1 /* 2 * Copyright (C) 2010 The Android Open Source Project 3 * 4 * Licensed under the Apache License, Version 2.0 (the "License"); 5 * you may not use this file except in compliance with the License. 6 * You may obtain a copy of the License at 7 * 8 * http://www.apache.org/licenses/LICENSE-2.0 9 * 10 * Unless required by applicable law or agreed to in writing, software 11 * distributed under the License is distributed on an "AS IS" BASIS, 12 * WITHOUT WARRANTIES OR CONDITIONS OF ANY KIND, either express or implied. 13 * See the License for the specific language governing permissions and 14 * limitations under the License. 15 */ 16 package com.android.tradefed.testtype; 17 18 import com.android.ddmlib.IShellOutputReceiver; 19 import com.android.ddmlib.MultiLineReceiver; 20 import com.android.tradefed.invoker.tracing.CloseableTraceScope; 21 import com.android.tradefed.log.LogUtil.CLog; 22 import com.android.tradefed.metrics.proto.MetricMeasurement.Metric; 23 import com.android.tradefed.result.FailureDescription; 24 import com.android.tradefed.result.ITestInvocationListener; 25 import com.android.tradefed.result.TestDescription; 26 import com.android.tradefed.result.error.ErrorIdentifier; 27 import com.android.tradefed.result.error.InfraErrorIdentifier; 28 import com.android.tradefed.result.proto.TestRecordProto.FailureStatus; 29 30 import java.util.ArrayList; 31 import java.util.Arrays; 32 import java.util.Collection; 33 import java.util.HashMap; 34 import java.util.LinkedHashSet; 35 import java.util.List; 36 import java.util.Map; 37 import java.util.Set; 38 import java.util.regex.Matcher; 39 import java.util.regex.Pattern; 40 41 /** 42 * Parses the 'raw output mode' results of native tests using GTest that run from shell, and informs 43 * a ITestInvocationListener of the results. 44 * 45 * <p>Sample format of output expected: 46 * 47 * <pre> 48 * [==========] Running 15 tests from 1 test case. 49 * [----------] Global test environment set-up. 50 * [----------] 15 tests from MessageTest 51 * [ RUN ] MessageTest.DefaultConstructor 52 * [ OK ] MessageTest.DefaultConstructor (1 ms) 53 * [ RUN ] MessageTest.CopyConstructor 54 * external/gtest/test/gtest-message_test.cc:67: Failure 55 * Value of: 5 56 * Expected: 2 57 * external/gtest/test/gtest-message_test.cc:68: Failure 58 * Value of: 1 == 1 59 * Actual: true 60 * Expected: false 61 * [ FAILED ] MessageTest.CopyConstructor (2 ms) 62 * ... 63 * [ RUN ] MessageTest.DoesNotTakeUpMuchStackSpace 64 * [ OK ] MessageTest.DoesNotTakeUpMuchStackSpace (0 ms) 65 * [----------] 15 tests from MessageTest (26 ms total) 66 * 67 * [----------] Global test environment tear-down 68 * [==========] 15 tests from 1 test case ran. (26 ms total) 69 * [ PASSED ] 6 tests. 70 * [ FAILED ] 9 tests, listed below: 71 * [ FAILED ] MessageTest.CopyConstructor 72 * [ FAILED ] MessageTest.ConstructsFromCString 73 * [ FAILED ] MessageTest.StreamsCString 74 * [ FAILED ] MessageTest.StreamsNullCString 75 * [ FAILED ] MessageTest.StreamsString 76 * [ FAILED ] MessageTest.StreamsStringWithEmbeddedNUL 77 * [ FAILED ] MessageTest.StreamsNULChar 78 * [ FAILED ] MessageTest.StreamsInt 79 * [ FAILED ] MessageTest.StreamsBasicIoManip 80 * 9 FAILED TESTS 81 * </pre> 82 * 83 * <p>where the following tags are used to signal certain events: 84 * 85 * <pre> 86 * [==========]: the first occurrence indicates a new run started, including the number of tests 87 * to be expected in this run 88 * [ RUN ]: indicates a new test has started to run; a series of zero or more lines may 89 * follow a test start, and will be captured in case of a test failure or error 90 * [ OK ]: the preceding test has completed successfully, optionally including the time it 91 * took to run (in ms) 92 * [ FAILED ]: the preceding test has failed, optionally including the time it took to run (in ms) 93 * [==========]: the preceding test run has completed, optionally including the time it took to run 94 * (in ms) 95 * </pre> 96 * 97 * All other lines are ignored. 98 */ 99 public class GTestResultParser extends MultiLineReceiver { 100 // Variables to keep track of state 101 private TestResult mCurrentTestResult = null; 102 private int mNumTestsRun = 0; 103 private int mNumTestsExpected = 0; 104 private long mTotalRunTime = 0; 105 private boolean mTestInProgress = false; 106 private CloseableTraceScope mMethodScope = null; 107 private boolean mTestRunInProgress = false; 108 private final String mTestRunName; 109 private final Collection<ITestInvocationListener> mTestListeners; 110 111 /** True if start of test has already been reported to listener. */ 112 private boolean mTestRunStartReported = false; 113 114 /** True if at least one testRunStart has been reported. */ 115 private boolean mSeenOneTestRunStart = false; 116 private boolean mFailureReported = false; 117 /** 118 * Track all the log lines before the testRunStart is made, it is helpful on an early failure to 119 * report those logs. 120 */ 121 private List<String> mTrackLogsBeforeRunStart = new ArrayList<>(); 122 123 /** True if current test run has been canceled by user. */ 124 private boolean mIsCancelled = false; 125 126 /** Whether or not to prepend filename to classname. */ 127 private boolean mPrependFileName = false; 128 129 /** Whether the test run was incomplete(test crashed or failed to parse test results). */ 130 private boolean mTestRunIncomplete = false; 131 132 /** List of tests that failed in the current run */ 133 private Set<String> mFailedTests = new LinkedHashSet<>(); 134 135 /** Whether current test run contained unexpected tests. Used for unit testing. */ 136 private boolean mUnexpectedTestFound = false; 137 138 /** The final status of the test. */ 139 enum TestStatus { 140 OK, 141 FAILED, 142 SKIPPED 143 } 144 setPrependFileName(boolean prepend)145 public void setPrependFileName(boolean prepend) { 146 mPrependFileName = prepend; 147 } 148 getPrependFileName()149 public boolean getPrependFileName() { 150 return mPrependFileName; 151 } 152 153 /** 154 * Test result data 155 */ 156 private static class TestResult { 157 private String mTestName = null; 158 private String mTestClass = null; 159 private StringBuilder mStackTrace = null; 160 private long mStartTimeMs; 161 private Long mRunTime = null; 162 163 /** Returns whether expected values have been parsed 164 * 165 * @return true if all expected values have been parsed 166 */ isComplete()167 boolean isComplete() { 168 return mTestName != null && mTestClass != null; 169 } 170 171 /** Returns whether there is currently a stack trace 172 * 173 * @return true if there is currently a stack trace, false otherwise 174 */ hasStackTrace()175 boolean hasStackTrace() { 176 return mStackTrace != null; 177 } 178 179 /** 180 * Returns the stack trace of the current test. 181 * 182 * @return a String representation of the current test's stack trace; if there is not 183 * a current stack trace, it returns an error string. Use {@link TestResult#hasStackTrace} 184 * if you need to know whether there is a stack trace. 185 */ getTrace()186 String getTrace() { 187 if (hasStackTrace()) { 188 return mStackTrace.toString(); 189 } else { 190 CLog.e("Could not find stack trace for failed test"); 191 return new Throwable("Unknown failure").toString(); 192 } 193 } 194 195 /** Provides a more user readable string for TestResult, if possible */ 196 @Override toString()197 public String toString() { 198 StringBuilder output = new StringBuilder(); 199 if (mTestClass != null ) { 200 output.append(mTestClass); 201 output.append('#'); 202 } 203 if (mTestName != null) { 204 output.append(mTestName); 205 } 206 if (output.length() > 0) { 207 return output.toString(); 208 } 209 return "unknown result"; 210 } 211 } 212 213 /** Internal helper struct to store parsed test info. */ 214 private static class ParsedTestInfo { 215 String mTestName = null; 216 String mTestClassName = null; 217 String mTestRunTime = null; 218 ParsedTestInfo(String testName, String testClassName, String testRunTime)219 public ParsedTestInfo(String testName, String testClassName, String testRunTime) { 220 mTestName = testName; 221 mTestClassName = testClassName; 222 mTestRunTime = testRunTime; 223 } 224 } 225 226 /** Prefixes used to demarcate and identify output. */ 227 private static class Prefixes { 228 @SuppressWarnings("unused") 229 private static final String INFORMATIONAL_MARKER = "[----------]"; 230 private static final String START_TEST_RUN_MARKER = "[==========] Running"; 231 private static final String TEST_RUN_MARKER = "[==========]"; 232 private static final String START_TEST_MARKER = "[ RUN ]"; // GTest format 233 private static final String OK_TEST_MARKER = "[ OK ]"; // GTest format 234 private static final String SKIPPED_TEST_MARKER = "[ SKIPPED ]"; // GTest format 235 private static final String FAILED_TEST_MARKER = "[ FAILED ]"; 236 // Alternative non GTest format can be generated from Google Test AOSP and respond to 237 // different needs (parallelism of tests) that the GTest format can't describe well. 238 private static final String ALT_OK_MARKER = "[ OK ]"; // Non GTest format 239 private static final String TIMEOUT_MARKER = "[ TIMEOUT ]"; // Non GTest format 240 } 241 242 /** 243 * Creates the GTestResultParser. 244 * 245 * @param testRunName the test run name to provide to {@link 246 * ITestInvocationListener#testRunStarted(String, int)} 247 * @param listeners informed of test results as the tests are executing 248 */ GTestResultParser(String testRunName, Collection<ITestInvocationListener> listeners)249 public GTestResultParser(String testRunName, Collection<ITestInvocationListener> listeners) { 250 mTestRunName = testRunName; 251 mTestListeners = new ArrayList<>(listeners); 252 setTrimLine(false); 253 } 254 255 /** 256 * Creates the GTestResultParser for a single listener. 257 * 258 * @param testRunName the test run name to provide to {@link 259 * ITestInvocationListener#testRunStarted(String, int)} 260 * @param listener informed of test results as the tests are executing 261 */ GTestResultParser(String testRunName, ITestInvocationListener listener)262 public GTestResultParser(String testRunName, ITestInvocationListener listener) { 263 this(testRunName, Arrays.asList(listener)); 264 } 265 266 /** 267 * Returns the current TestResult for test in progress, or a new default one. 268 * 269 * @return The TestResult for the current test run 270 */ getCurrentTestResult()271 private TestResult getCurrentTestResult() { 272 if (mCurrentTestResult == null) { 273 mCurrentTestResult = new TestResult(); 274 } 275 return mCurrentTestResult; 276 } 277 278 279 /** 280 * Clears out the current TestResult. 281 */ clearCurrentTestResult()282 private void clearCurrentTestResult() { 283 mCurrentTestResult = null; 284 } 285 286 /** 287 * {@inheritDoc} 288 */ 289 @Override processNewLines(String[] lines)290 public void processNewLines(String[] lines) { 291 if (!mSeenOneTestRunStart) { 292 mTrackLogsBeforeRunStart.addAll(Arrays.asList(lines)); 293 } 294 295 for (String line : lines) { 296 parse(line); 297 // in verbose mode, dump all adb output to log 298 CLog.v(line); 299 } 300 } 301 302 /** 303 * Parse an individual output line. 304 * 305 * @param line Text output line 306 */ parse(String line)307 private void parse(String line) { 308 String message = null; 309 310 if (mTestRunInProgress || line.startsWith(Prefixes.TEST_RUN_MARKER)) { 311 if (line.startsWith(Prefixes.START_TEST_MARKER)) { 312 // Individual test started 313 message = line.substring(Prefixes.START_TEST_MARKER.length()).trim(); 314 processTestStartedTag(message); 315 } else if (line.contains(Prefixes.SKIPPED_TEST_MARKER)) { 316 // Individual test was skipped. 317 // Logs from test could offset the SKIPPED marker 318 message = 319 line.substring( 320 line.indexOf(Prefixes.SKIPPED_TEST_MARKER) 321 + Prefixes.SKIPPED_TEST_MARKER.length()) 322 .trim(); 323 if (!testInProgress()) { 324 // Alternative format does not have a RUN tag, so we fake it. 325 fakeRunMarker(message); 326 } 327 processSkippedTag(message); 328 clearCurrentTestResult(); 329 } 330 else if (line.contains(Prefixes.OK_TEST_MARKER)) { 331 // Individual test completed successfully 332 // Logs from test could offset the OK marker 333 message = line.substring(line.indexOf(Prefixes.OK_TEST_MARKER) + 334 Prefixes.OK_TEST_MARKER.length()).trim(); 335 if (!testInProgress()) { 336 // If we are missing the RUN tag, skip it wrong format 337 CLog.e("Found %s without %s before, Ensure you are using GTest format", 338 line, Prefixes.START_TEST_MARKER); 339 return; 340 } 341 processOKTag(message); 342 clearCurrentTestResult(); 343 } 344 else if (line.contains(Prefixes.ALT_OK_MARKER)) { 345 message = line.substring(line.indexOf(Prefixes.ALT_OK_MARKER) + 346 Prefixes.ALT_OK_MARKER.length()).trim(); 347 // This alternative format does not have a RUN tag, so we fake it. 348 fakeRunMarker(message); 349 processOKTag(message); 350 clearCurrentTestResult(); 351 } 352 else if (line.contains(Prefixes.FAILED_TEST_MARKER)) { 353 // Individual test completed with failure 354 message = line.substring(line.indexOf(Prefixes.FAILED_TEST_MARKER) + 355 Prefixes.FAILED_TEST_MARKER.length()).trim(); 356 if (!testInProgress()) { 357 // If we are missing the RUN tag (ALT format) 358 fakeRunMarker(message); 359 } 360 processFailedTag(message); 361 clearCurrentTestResult(); 362 } 363 else if (line.contains(Prefixes.TIMEOUT_MARKER)) { 364 // Individual test timeout is considered a failure 365 message = line.substring(line.indexOf(Prefixes.TIMEOUT_MARKER) + 366 Prefixes.TIMEOUT_MARKER.length()).trim(); 367 fakeRunMarker(message); 368 processFailedTag(message); 369 clearCurrentTestResult(); 370 } 371 else if (line.startsWith(Prefixes.START_TEST_RUN_MARKER)) { 372 // Test run started 373 // Make sure to leave the "Running" in the string 374 message = line.substring(Prefixes.TEST_RUN_MARKER.length()).trim(); 375 processRunStartedTag(message); 376 } 377 else if (line.startsWith(Prefixes.TEST_RUN_MARKER)) { 378 // Test run ended 379 // This is for the end of the test suite run, so make sure this else-if is after the 380 // check for START_TEST_SUITE_MARKER 381 message = line.substring(Prefixes.TEST_RUN_MARKER.length()).trim(); 382 processRunCompletedTag(message); 383 } 384 else if (testInProgress()) { 385 // Note this does not handle the case of an error outside an actual test run 386 appendTestOutputLine(line); 387 } 388 } 389 } 390 391 /** 392 * Returns true if test run canceled. 393 * 394 * @see IShellOutputReceiver#isCancelled() 395 */ 396 @Override isCancelled()397 public boolean isCancelled() { 398 return mIsCancelled; 399 } 400 401 /** 402 * Create a fake run marker for alternative format that doesn't have it. 403 * @param message 404 */ fakeRunMarker(String message)405 private void fakeRunMarker(String message) { 406 // Remove everything after the test name. 407 String fakeRunMaker = message.split(" +")[0]; 408 // Do as if we had found a [RUN] tag. 409 processTestStartedTag(fakeRunMaker); 410 } 411 412 /** 413 * Requests cancellation of test run. 414 */ cancel()415 public void cancel() { 416 mIsCancelled = true; 417 } 418 419 /** 420 * Returns whether we're in the middle of running a test. 421 * 422 * @return True if a test was started, false otherwise 423 */ testInProgress()424 private boolean testInProgress() { 425 return mTestInProgress; 426 } 427 428 /** Set state to indicate we've started running a test. */ setTestStarted(TestDescription testId)429 private void setTestStarted(TestDescription testId) { 430 mTestInProgress = true; 431 mMethodScope = new CloseableTraceScope(testId.toString()); 432 } 433 434 /** 435 * Set state to indicate we've started running a test. 436 * 437 */ setTestEnded()438 private void setTestEnded() { 439 mTestInProgress = false; 440 if (mMethodScope != null) { 441 mMethodScope.close(); 442 mMethodScope = null; 443 } 444 } 445 446 /** 447 * Reports the start of a test run, and the total test count, if it has not been previously 448 * reported. 449 */ reportTestRunStarted()450 private void reportTestRunStarted() { 451 // if start test run not reported yet 452 if (!mTestRunStartReported) { 453 for (ITestInvocationListener listener : mTestListeners) { 454 listener.testRunStarted(mTestRunName, mNumTestsExpected); 455 } 456 mTestRunStartReported = true; 457 mSeenOneTestRunStart = true; 458 mTrackLogsBeforeRunStart.clear(); 459 // Reset test run completion flag for the new test run 460 mTestRunIncomplete = false; 461 // Clear failed tests list for new test run 462 mFailedTests = new LinkedHashSet<>(); 463 } 464 } 465 466 /** 467 * Reports the end of a test run, and resets that test 468 */ reportTestRunEnded()469 private void reportTestRunEnded() { 470 for (ITestInvocationListener listener : mTestListeners) { 471 listener.testRunEnded(mTotalRunTime, getRunMetrics()); 472 } 473 mTestRunStartReported = false; 474 mTestRunIncomplete = false; 475 } 476 477 /** 478 * Create the run metrics {@link Map} to report. 479 * 480 * @return a {@link Map} of run metrics data 481 */ getRunMetrics()482 private HashMap<String, Metric> getRunMetrics() { 483 HashMap<String, Metric> metricsMap = new HashMap<>(); 484 return metricsMap; 485 } 486 487 /** 488 * Parse the test identifier (class and test name), and optional time info. 489 * 490 * @param identifier Raw identifier of the form classname.testname, with an optional time 491 * element in the format of (XX ms) at the end 492 * @return A ParsedTestInfo representing the parsed info from the identifier string. 493 * 494 * If no time tag was detected, then the third element in the array (time_in_ms) will 495 * be null. If the line failed to parse properly (eg: could not determine name of 496 * test/class) then an "UNKNOWN" string value will be returned for the classname and 497 * testname. This method guarantees a string will always be returned for the class and 498 * test names (but not for the time value). 499 */ parseTestDescription(String identifier)500 private ParsedTestInfo parseTestDescription(String identifier) { 501 ParsedTestInfo returnInfo = new ParsedTestInfo("UNKNOWN_CLASS", "UNKNOWN_TEST", null); 502 503 Pattern timePattern = Pattern.compile(".*(\\((\\d+) ms\\))"); // eg: (XX ms) 504 Matcher time = timePattern.matcher(identifier); 505 506 // Try to find a time 507 if (time.find()) { 508 String timeString = time.group(2); // the "XX" in "(XX ms)" 509 String discardPortion = time.group(1); // everything after the test class/name 510 identifier = identifier.substring(0, identifier.lastIndexOf(discardPortion)).trim(); 511 returnInfo.mTestRunTime = timeString; 512 } 513 514 // filter out messages for parameterized tests: classname.testname, getParam() = (..) 515 Pattern parameterizedPattern = Pattern.compile("([a-zA-Z_0-9]+[\\S]*)(,\\s+.*)?$"); 516 Matcher parameterizedMsg = parameterizedPattern.matcher(identifier); 517 if (parameterizedMsg.find()) { 518 identifier = parameterizedMsg.group(1); 519 } 520 521 String[] testId = identifier.split("\\."); 522 if (testId.length < 2) { 523 CLog.e("Could not detect the test class and test name, received: %s", identifier); 524 returnInfo.mTestClassName = null; 525 returnInfo.mTestName = null; 526 } 527 else { 528 returnInfo.mTestClassName = testId[0]; 529 returnInfo.mTestName = testId[1]; 530 } 531 return returnInfo; 532 } 533 534 /** 535 * Parses and stores the test identifier (class and test name). 536 * 537 * @param identifier Raw identifier 538 */ processRunStartedTag(String identifier)539 private void processRunStartedTag(String identifier) { 540 // eg: (Running XX tests from 1 test case.) 541 Pattern numTestsPattern = Pattern.compile("Running (\\d+) test[s]? from .*"); 542 Matcher numTests = numTestsPattern.matcher(identifier); 543 544 // Try to find number of tests 545 if (numTests.find()) { 546 try { 547 mNumTestsExpected = Integer.parseInt(numTests.group(1)); 548 } 549 catch (NumberFormatException e) { 550 CLog.e( 551 "Unable to determine number of tests expected, received: %s", 552 numTests.group(1)); 553 } 554 } 555 if (mNumTestsExpected > 0) { 556 reportTestRunStarted(); 557 mNumTestsRun = 0; 558 mTestRunInProgress = true; 559 } else if (mNumTestsExpected == 0) { 560 reportTestRunStarted(); 561 } 562 } 563 564 /** 565 * Processes and informs listener when we encounter a tag indicating that a test suite is done. 566 * 567 * @param identifier Raw log output from the suite ended tag 568 */ processRunCompletedTag(String identifier)569 private void processRunCompletedTag(String identifier) { 570 Pattern timePattern = Pattern.compile(".*\\((\\d+) ms total\\)"); // eg: (XX ms total) 571 Matcher time = timePattern.matcher(identifier); 572 573 // Try to find the total run time 574 if (time.find()) { 575 try { 576 mTotalRunTime = Long.parseLong(time.group(1)); 577 } 578 catch (NumberFormatException e) { 579 CLog.e("Unable to determine the total running time, received: %s", time.group(1)); 580 } 581 } 582 reportTestRunEnded(); 583 mTestRunInProgress = false; 584 } 585 getTestClass(TestResult testResult)586 private String getTestClass(TestResult testResult) { 587 588 if (mPrependFileName) { 589 StringBuilder sb = new StringBuilder(); 590 sb.append(mTestRunName); 591 sb.append("."); 592 sb.append(testResult.mTestClass); 593 return sb.toString(); 594 } 595 return testResult.mTestClass; 596 } 597 598 /** 599 * Processes and informs listener when we encounter a tag indicating that a test has started. 600 * 601 * @param identifier Raw log output of the form classname.testname, with an optional time (x ms) 602 */ processTestStartedTag(String identifier)603 private void processTestStartedTag(String identifier) { 604 ParsedTestInfo parsedResults = parseTestDescription(identifier); 605 TestResult testResult = getCurrentTestResult(); 606 testResult.mTestClass = parsedResults.mTestClassName; 607 testResult.mTestName = parsedResults.mTestName; 608 testResult.mStartTimeMs = System.currentTimeMillis(); 609 TestDescription testId = null; 610 if (getTestClass(testResult) != null && testResult.mTestName != null) { 611 testId = new TestDescription(getTestClass(testResult), testResult.mTestName); 612 } else { 613 CLog.e("Error during parsing, className: %s and testName: %s, should both be not null", 614 getTestClass(testResult), testResult.mTestName); 615 return; 616 } 617 618 for (ITestInvocationListener listener : mTestListeners) { 619 listener.testStarted(testId, testResult.mStartTimeMs); 620 } 621 setTestStarted(testId); 622 } 623 624 /** 625 * Helper method to do the work necessary when a test has ended. 626 * 627 * @param identifier Raw log output of the form "classname.testname" with an optional (XX ms) at 628 * the end indicating the running time. 629 * @param testStatus Indicates the final test status. 630 */ doTestEnded(String identifier, TestStatus testStatus)631 private void doTestEnded(String identifier, TestStatus testStatus) { 632 ParsedTestInfo parsedResults = parseTestDescription(identifier); 633 TestResult testResult = getCurrentTestResult(); 634 TestDescription testId = null; 635 if (getTestClass(testResult) !=null && testResult.mTestName !=null) { 636 testId = new TestDescription(getTestClass(testResult), testResult.mTestName); 637 } else { 638 CLog.e("Error during parsing, className: %s and testName: %s, should both be not null", 639 getTestClass(testResult), testResult.mTestName); 640 return; 641 } 642 643 // Error - trying to end a test when one isn't in progress 644 if (!testInProgress()) { 645 CLog.e("Test currently not in progress when trying to end test: %s", identifier); 646 return; 647 } 648 649 // Save the run time for this test if one exists 650 if (parsedResults.mTestRunTime != null) { 651 try { 652 testResult.mRunTime = Long.valueOf(parsedResults.mTestRunTime); 653 } catch (NumberFormatException e) { 654 CLog.e("Test run time value is invalid, received: %s", parsedResults.mTestRunTime); 655 } 656 } else { 657 CLog.d("No runtime for %s, defaulting to 0ms.", testId); 658 testResult.mRunTime = 0L; 659 } 660 661 // Check that the test result is for the same test/class we're expecting it to be for 662 boolean encounteredUnexpectedTest = false; 663 if (!testResult.isComplete()) { 664 CLog.e("No test/class name is currently recorded as running!"); 665 } 666 else { 667 if (testResult.mTestClass.compareTo(parsedResults.mTestClassName) != 0) { 668 CLog.e( 669 "Name for current test class does not match class we started with, " 670 + "expected: %s but got:%s ", 671 testResult.mTestClass, parsedResults.mTestClassName); 672 encounteredUnexpectedTest = true; 673 } 674 if (testResult.mTestName.compareTo(parsedResults.mTestName) != 0) { 675 CLog.e( 676 "Name for current test does not match test we started with, expected: %s " 677 + " but got: %s", 678 testResult.mTestName, parsedResults.mTestName); 679 encounteredUnexpectedTest = true; 680 } 681 } 682 683 if (encounteredUnexpectedTest) { 684 // If the test name of the result changed from what we started with, report that 685 // the last known test failed, regardless of whether we received a pass or fail tag. 686 for (ITestInvocationListener listener : mTestListeners) { 687 listener.testFailed(testId, mCurrentTestResult.getTrace()); 688 } 689 mUnexpectedTestFound = true; 690 } else if (TestStatus.FAILED.equals(testStatus)) { // test failed 691 for (ITestInvocationListener listener : mTestListeners) { 692 listener.testFailed(testId, mCurrentTestResult.getTrace()); 693 } 694 mFailedTests.add(String.format("%s.%s", testId.getClassName(), testId.getTestName())); 695 } else if (TestStatus.SKIPPED.equals(testStatus)) { // test was skipped 696 for (ITestInvocationListener listener : mTestListeners) { 697 listener.testIgnored(testId); 698 } 699 } 700 701 // For all cases (pass or fail), we ultimately need to report test has ended 702 HashMap<String, Metric> emptyMap = new HashMap<>(); 703 long endTimeMs = testResult.mStartTimeMs + testResult.mRunTime; 704 for (ITestInvocationListener listener : mTestListeners) { 705 listener.testEnded(testId, endTimeMs, emptyMap); 706 } 707 708 setTestEnded(); 709 ++mNumTestsRun; 710 } 711 712 /** 713 * Processes and informs listener when we encounter the OK tag. 714 * 715 * @param identifier Raw log output of the form "classname.testname" with an optional (XX ms) 716 * at the end indicating the running time. 717 */ processOKTag(String identifier)718 private void processOKTag(String identifier) { 719 doTestEnded(identifier, TestStatus.OK); 720 } 721 722 /** 723 * Processes and informs listener when we encounter the FAILED tag. 724 * 725 * @param identifier Raw log output of the form "classname.testname" with an optional (XX ms) 726 * at the end indicating the running time. 727 */ processFailedTag(String identifier)728 private void processFailedTag(String identifier) { 729 doTestEnded(identifier, TestStatus.FAILED); 730 } 731 732 /** 733 * Processes and informs listener when we encounter the SKIPPED tag. 734 * 735 * @param identifier Raw log output of the form "classname.testname" with an optional (XX ms) at 736 * the end indicating the running time. 737 */ processSkippedTag(String identifier)738 private void processSkippedTag(String identifier) { 739 doTestEnded(identifier, TestStatus.SKIPPED); 740 } 741 742 743 /** 744 * Appends the test output to the current TestResult. 745 * 746 * @param line Raw test result line of output. 747 */ appendTestOutputLine(String line)748 private void appendTestOutputLine(String line) { 749 TestResult testResult = getCurrentTestResult(); 750 if (testResult.mStackTrace == null) { 751 testResult.mStackTrace = new StringBuilder(); 752 } 753 else { 754 testResult.mStackTrace.append("\r\n"); 755 } 756 testResult.mStackTrace.append(line); 757 } 758 759 /** 760 * Process an instrumentation run failure 761 * 762 * @param errorMsg The message to output about the nature of the error 763 */ handleTestRunFailed(String errorMsg, ErrorIdentifier errorId)764 private void handleTestRunFailed(String errorMsg, ErrorIdentifier errorId) { 765 errorMsg = (errorMsg == null ? "Unknown error" : errorMsg); 766 CLog.i("Test run failed: %s", errorMsg); 767 String testRunStackTrace = ""; 768 769 // Report that the last known test failed 770 if ((mCurrentTestResult != null) && mCurrentTestResult.isComplete()) { 771 // current test results are cleared out after every complete test run, 772 // if it's not null, assume the last test caused this and report as a test failure 773 TestDescription testId = 774 new TestDescription( 775 getTestClass(mCurrentTestResult), mCurrentTestResult.mTestName); 776 777 // If there was any stack trace during the test run, append it to the "test failed" 778 // error message so we have an idea of what caused the crash/failure. 779 HashMap<String, Metric> emptyMap = new HashMap<>(); 780 if (mCurrentTestResult.hasStackTrace()) { 781 testRunStackTrace = mCurrentTestResult.getTrace(); 782 } 783 FailureDescription testFailure = 784 FailureDescription.create("No test results.\r\n" + testRunStackTrace) 785 .setFailureStatus(FailureStatus.TEST_FAILURE); 786 for (ITestInvocationListener listener : mTestListeners) { 787 listener.testFailed(testId, testFailure); 788 listener.testEnded(testId, emptyMap); 789 } 790 if (mMethodScope != null) { 791 mMethodScope.close(); 792 mMethodScope = null; 793 } 794 clearCurrentTestResult(); 795 } 796 // Report the test run failed 797 FailureDescription error = 798 FailureDescription.create(errorMsg).setFailureStatus(FailureStatus.TEST_FAILURE); 799 if (errorId != null) { 800 error.setErrorIdentifier(errorId); 801 } 802 for (ITestInvocationListener listener : mTestListeners) { 803 listener.testRunFailed(error); 804 listener.testRunEnded(mTotalRunTime, getRunMetrics()); 805 } 806 } 807 808 /** 809 * Called by parent when adb session is complete. 810 */ 811 @Override done()812 public void done() { 813 super.done(); 814 if (mMethodScope != null) { 815 mMethodScope.close(); 816 mMethodScope = null; 817 } 818 // To make sure the test fail run will only be reported for this run. 819 if (mTestRunStartReported && (mNumTestsExpected > mNumTestsRun)) { 820 handleTestRunFailed( 821 String.format( 822 "Test run incomplete. Expected %d tests, received %d", 823 mNumTestsExpected, mNumTestsRun), 824 InfraErrorIdentifier.EXPECTED_TESTS_MISMATCH); 825 mTestRunIncomplete = true; 826 // Reset TestRunStart flag to prevent report twice in the same run. 827 mTestRunStartReported = false; 828 mTestRunInProgress = false; 829 } else if (mTestRunInProgress) { 830 // possible only when all tests were executed, but test run completed tag not reported 831 CLog.e( 832 "All tests were executed, but test run completion not reported." 833 + "Unable to determine the total run time."); 834 reportTestRunEnded(); 835 mTestRunInProgress = false; 836 } else if (!mSeenOneTestRunStart && !mFailureReported) { 837 for (ITestInvocationListener listener : mTestListeners) { 838 listener.testRunStarted(mTestRunName, 0); 839 listener.testRunFailed( 840 createFailure( 841 String.format( 842 "%s did not report any run:\n%s", 843 mTestRunName, 844 String.join("\n", mTrackLogsBeforeRunStart)))); 845 listener.testRunEnded(0L, new HashMap<String, Metric>()); 846 } 847 mFailureReported = true; 848 } 849 } 850 851 /** 852 * Whether the test run was incomplete or not. 853 * 854 * @return true, if the test run was incomplete due to parsing issues or crashes. 855 */ isTestRunIncomplete()856 public boolean isTestRunIncomplete() { 857 return mTestRunIncomplete; 858 } 859 860 /** Returns a list of tests that failed during the current test run. */ getFailedTests()861 public Set<String> getFailedTests() { 862 return mFailedTests; 863 } 864 createFailure(String message)865 private FailureDescription createFailure(String message) { 866 return FailureDescription.create(message, FailureStatus.TEST_FAILURE); 867 } 868 869 /** Exposed for unit testing. */ isUnexpectedTestFound()870 protected boolean isUnexpectedTestFound() { 871 return mUnexpectedTestFound; 872 } 873 } 874