1 /* 2 * Copyright (C) 2011 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.cts.tradefed.testtype; 17 18 import com.android.ddmlib.IShellOutputReceiver; 19 import com.android.ddmlib.Log; 20 import com.android.ddmlib.MultiLineReceiver; 21 import com.android.ddmlib.testrunner.ITestRunListener; 22 import com.android.ddmlib.testrunner.TestIdentifier; 23 import com.android.tradefed.testtype.testdefs.XmlDefsTest; 24 25 import java.util.ArrayList; 26 import java.util.Collection; 27 import java.util.Collections; 28 import java.util.HashMap; 29 import java.util.Map; 30 import java.util.regex.Matcher; 31 import java.util.regex.Pattern; 32 33 /** 34 * TODO: Merge change to add package prefix to tradefed's GTestResultParser. 35 * Otherwise this file should be the same as TradeFed's version. 36 * 37 * Parses the 'raw output mode' results of native tests using GTest that run from shell, and informs 38 * a ITestRunListener of the results. 39 * <p>Sample format of output expected: 40 * 41 * <pre> 42 * [==========] Running 15 tests from 1 test case. 43 * [----------] Global test environment set-up. 44 * [----------] 15 tests from MessageTest 45 * [ RUN ] MessageTest.DefaultConstructor 46 * [ OK ] MessageTest.DefaultConstructor (1 ms) 47 * [ RUN ] MessageTest.CopyConstructor 48 * external/gtest/test/gtest-message_test.cc:67: Failure 49 * Value of: 5 50 * Expected: 2 51 * external/gtest/test/gtest-message_test.cc:68: Failure 52 * Value of: 1 == 1 53 * Actual: true 54 * Expected: false 55 * [ FAILED ] MessageTest.CopyConstructor (2 ms) 56 * ... 57 * [ RUN ] MessageTest.DoesNotTakeUpMuchStackSpace 58 * [ OK ] MessageTest.DoesNotTakeUpMuchStackSpace (0 ms) 59 * [----------] 15 tests from MessageTest (26 ms total) 60 * 61 * [----------] Global test environment tear-down 62 * [==========] 15 tests from 1 test case ran. (26 ms total) 63 * [ PASSED ] 6 tests. 64 * [ FAILED ] 9 tests, listed below: 65 * [ FAILED ] MessageTest.CopyConstructor 66 * [ FAILED ] MessageTest.ConstructsFromCString 67 * [ FAILED ] MessageTest.StreamsCString 68 * [ FAILED ] MessageTest.StreamsNullCString 69 * [ FAILED ] MessageTest.StreamsString 70 * [ FAILED ] MessageTest.StreamsStringWithEmbeddedNUL 71 * [ FAILED ] MessageTest.StreamsNULChar 72 * [ FAILED ] MessageTest.StreamsInt 73 * [ FAILED ] MessageTest.StreamsBasicIoManip 74 * 9 FAILED TESTS 75 * </pre> 76 * 77 * <p>where the following tags are used to signal certain events: 78 * <pre> 79 * [==========]: the first occurrence indicates a new run started, including the number of tests 80 * to be expected in this run 81 * [ RUN ]: indicates a new test has started to run; a series of zero or more lines may 82 * follow a test start, and will be captured in case of a test failure or error 83 * [ OK ]: the preceding test has completed successfully, optionally including the time it 84 * took to run (in ms) 85 * [ FAILED ]: the preceding test has failed, optionally including the time it took to run (in ms) 86 * [==========]: the preceding test run has completed, optionally including the time it took to run 87 * (in ms) 88 * </pre> 89 * 90 * All other lines are ignored. 91 */ 92 public class GeeTestResultParser extends MultiLineReceiver { 93 private static final String LOG_TAG = "GTestResultParser"; 94 95 // Variables to keep track of state 96 private TestResult mCurrentTestResult = null; 97 private int mNumTestsRun = 0; 98 private int mNumTestsExpected = 0; 99 private long mTotalRunTime = 0; 100 private boolean mTestInProgress = false; 101 private boolean mTestRunInProgress = false; 102 private final String mTestRunId; 103 private final Collection<ITestRunListener> mTestListeners; 104 105 /** Fake adding a package prefix if the test listener needs it. */ 106 private String mFakePackagePrefix = ""; 107 108 /** True if start of test has already been reported to listener. */ 109 private boolean mTestRunStartReported = false; 110 111 /** True if current test run has been canceled by user. */ 112 private boolean mIsCancelled = false; 113 114 private String mCoverageTarget = null; 115 116 /** 117 * Test result data 118 */ 119 private static class TestResult { 120 private String mTestName = null; 121 private String mTestClass = null; 122 private StringBuilder mStackTrace = null; 123 @SuppressWarnings("unused") 124 private Long mRunTime = null; 125 126 /** Returns whether expected values have been parsed 127 * 128 * @return true if all expected values have been parsed 129 */ 130 boolean isComplete() { 131 return mTestName != null && mTestClass != null; 132 } 133 134 /** Returns whether there is currently a stack trace 135 * 136 * @return true if there is currently a stack trace, false otherwise 137 */ 138 boolean hasStackTrace() { 139 return mStackTrace != null; 140 } 141 142 /** 143 * Returns the stack trace of the current test. 144 * 145 * @return a String representation of the current test's stack trace; if there is not 146 * a current stack trace, it returns an error string. Use {@link TestResult#hasStackTrace} 147 * if you need to know whether there is a stack trace. 148 */ 149 String getTrace() { 150 if (hasStackTrace()) { 151 return mStackTrace.toString(); 152 } else { 153 Log.e(LOG_TAG, "Could not find stack trace for failed test"); 154 return new Throwable("Unknown failure").toString(); 155 } 156 } 157 158 /** Provides a more user readable string for TestResult, if possible */ 159 @Override 160 public String toString() { 161 StringBuilder output = new StringBuilder(); 162 if (mTestClass != null ) { 163 output.append(mTestClass); 164 output.append('#'); 165 } 166 if (mTestName != null) { 167 output.append(mTestName); 168 } 169 if (output.length() > 0) { 170 return output.toString(); 171 } 172 return "unknown result"; 173 } 174 } 175 176 /** Internal helper struct to store parsed test info. */ 177 private static class ParsedTestInfo { 178 String mTestName = null; 179 String mTestClassName = null; 180 String mTestRunTime = null; 181 182 public ParsedTestInfo(String testName, String testClassName, String testRunTime) { 183 mTestName = testName; 184 mTestClassName = testClassName; 185 mTestRunTime = testRunTime; 186 } 187 } 188 189 /** Prefixes used to demarcate and identify output. */ 190 private static class Prefixes { 191 @SuppressWarnings("unused") 192 private static final String INFORMATIONAL_MARKER = "[----------]"; 193 private static final String START_TEST_RUN_MARKER = "[==========] Running"; 194 private static final String TEST_RUN_MARKER = "[==========]"; 195 private static final String START_TEST_MARKER = "[ RUN ]"; 196 private static final String OK_TEST_MARKER = "[ OK ]"; 197 private static final String FAILED_TEST_MARKER = "[ FAILED ]"; 198 } 199 200 /** 201 * Creates the GTestResultParser. 202 * 203 * @param testRunId the test run id to provide to 204 * {@link ITestRunListener#testRunStarted(String, int)} 205 * @param listeners informed of test results as the tests are executing 206 */ 207 public GeeTestResultParser(String testRunId, Collection<ITestRunListener> listeners) { 208 mTestRunId = testRunId; 209 mTestListeners = new ArrayList<ITestRunListener>(listeners); 210 } 211 212 /** 213 * Creates the GTestResultParser for a single listener. 214 * 215 * @param testRunId the test run id to provide to 216 * {@link ITestRunListener#testRunStarted(String, int)} 217 * @param listener informed of test results as the tests are executing 218 */ 219 public GeeTestResultParser(String testRunId, ITestRunListener listener) { 220 mTestRunId = testRunId; 221 mTestListeners = new ArrayList<ITestRunListener>(1); 222 mTestListeners.add(listener); 223 } 224 225 /** 226 * Package prefix to be added to test names when they are reported like 227 * "android.nativemedia." You may need to add the dot if you need it. 228 */ 229 public void setFakePackagePrefix(String prefix) { 230 mFakePackagePrefix = prefix; 231 } 232 233 /** 234 * Returns the current TestResult for test in progress, or a new default one. 235 * 236 * @return The TestResult for the current test run 237 */ 238 private TestResult getCurrentTestResult() { 239 if (mCurrentTestResult == null) { 240 mCurrentTestResult = new TestResult(); 241 } 242 return mCurrentTestResult; 243 } 244 245 246 /** 247 * Clears out the current TestResult. 248 */ 249 private void clearCurrentTestResult() { 250 mCurrentTestResult = null; 251 } 252 253 /** 254 * {@inheritDoc} 255 */ 256 @Override 257 public void processNewLines(String[] lines) { 258 for (String line : lines) { 259 parse(line); 260 } 261 } 262 263 /** 264 * Parse an individual output line. 265 * 266 * @param line Text output line 267 */ 268 private void parse(String line) { 269 String message = null; 270 271 if (mTestRunInProgress || line.startsWith(Prefixes.TEST_RUN_MARKER)) { 272 if (line.startsWith(Prefixes.START_TEST_MARKER)) { 273 // Individual test started 274 message = line.substring(Prefixes.START_TEST_MARKER.length()).trim(); 275 processTestStartedTag(message); 276 } 277 else if (line.startsWith(Prefixes.OK_TEST_MARKER)) { 278 // Individual test completed successfully 279 message = line.substring(Prefixes.OK_TEST_MARKER.length()).trim(); 280 processOKTag(message); 281 clearCurrentTestResult(); 282 } 283 else if (line.startsWith(Prefixes.FAILED_TEST_MARKER)) { 284 // Individual test completed with failure 285 message = line.substring(Prefixes.FAILED_TEST_MARKER.length()).trim(); 286 processFailedTag(message); 287 clearCurrentTestResult(); 288 } 289 else if (line.startsWith(Prefixes.START_TEST_RUN_MARKER)) { 290 // Test run started 291 // Make sure to leave the "Running" in the string 292 message = line.substring(Prefixes.TEST_RUN_MARKER.length()).trim(); 293 processRunStartedTag(message); 294 } 295 else if (line.startsWith(Prefixes.TEST_RUN_MARKER)) { 296 // Test run ended 297 // This is for the end of the test suite run, so make sure this else-if is after the 298 // check for START_TEST_SUITE_MARKER 299 message = line.substring(Prefixes.TEST_RUN_MARKER.length()).trim(); 300 processRunCompletedTag(message); 301 } 302 else if (testInProgress()) { 303 // Note this does not handle the case of an error outside an actual test run 304 appendTestOutputLine(line); 305 } 306 } 307 } 308 309 /** 310 * Returns true if test run canceled. 311 * 312 * @see IShellOutputReceiver#isCancelled() 313 */ 314 @Override 315 public boolean isCancelled() { 316 return mIsCancelled; 317 } 318 319 /** 320 * Requests cancellation of test run. 321 */ 322 public void cancel() { 323 mIsCancelled = true; 324 } 325 326 /** 327 * Returns whether we're in the middle of running a test. 328 * 329 * @return True if a test was started, false otherwise 330 */ 331 private boolean testInProgress() { 332 return mTestInProgress; 333 } 334 335 /** 336 * Set state to indicate we've started running a test. 337 * 338 */ 339 private void setTestStarted() { 340 mTestInProgress = true; 341 } 342 343 /** 344 * Set state to indicate we've started running a test. 345 * 346 */ 347 private void setTestEnded() { 348 mTestInProgress = false; 349 } 350 351 /** 352 * Reports the start of a test run, and the total test count, if it has not been previously 353 * reported. 354 */ 355 private void reportTestRunStarted() { 356 // if start test run not reported yet 357 if (!mTestRunStartReported) { 358 for (ITestRunListener listener : mTestListeners) { 359 listener.testRunStarted(mTestRunId, mNumTestsExpected); 360 } 361 mTestRunStartReported = true; 362 } 363 } 364 365 /** 366 * Reports the end of a test run, and resets that test 367 */ 368 private void reportTestRunEnded() { 369 for (ITestRunListener listener : mTestListeners) { 370 listener.testRunEnded(mTotalRunTime, getRunMetrics()); 371 } 372 mTestRunStartReported = false; 373 } 374 375 /** 376 * Create the run metrics {@link Map} to report. 377 * 378 * @return a {@link Map} of run metrics data 379 */ 380 private Map<String, String> getRunMetrics() { 381 Map<String, String> metricsMap = new HashMap<String, String>(); 382 if (mCoverageTarget != null) { 383 metricsMap.put(XmlDefsTest.COVERAGE_TARGET_KEY, mCoverageTarget); 384 } 385 return metricsMap; 386 } 387 388 /** 389 * Parse the test identifier (class and test name), and optional time info. 390 * 391 * @param identifier Raw identifier of the form classname.testname, with an optional time 392 * element in the format of (XX ms) at the end 393 * @return A ParsedTestInfo representing the parsed info from the identifier string. 394 * 395 * If no time tag was detected, then the third element in the array (time_in_ms) will 396 * be null. If the line failed to parse properly (eg: could not determine name of 397 * test/class) then an "UNKNOWN" string value will be returned for the classname and 398 * testname. This method guarantees a string will always be returned for the class and 399 * test names (but not for the time value). 400 */ 401 private ParsedTestInfo parseTestIdentifier(String identifier) { 402 ParsedTestInfo returnInfo = new ParsedTestInfo("UNKNOWN_CLASS", "UNKNOWN_TEST", null); 403 404 Pattern timePattern = Pattern.compile(".*(\\((\\d+) ms\\))"); // eg: (XX ms) 405 Matcher time = timePattern.matcher(identifier); 406 407 // Try to find a time 408 if (time.find()) { 409 String timeString = time.group(2); // the "XX" in "(XX ms)" 410 String discardPortion = time.group(1); // everything after the test class/name 411 identifier = identifier.substring(0, identifier.lastIndexOf(discardPortion)).trim(); 412 returnInfo.mTestRunTime = timeString; 413 } 414 415 String[] testId = identifier.split("\\."); 416 if (testId.length < 2) { 417 Log.e(LOG_TAG, "Could not detect the test class and test name, received: " + 418 identifier); 419 } 420 else { 421 returnInfo.mTestClassName = testId[0]; 422 returnInfo.mTestName = testId[1]; 423 } 424 return returnInfo; 425 } 426 427 /** 428 * Parses and stores the test identifier (class and test name). 429 * 430 * @param identifier Raw identifier 431 */ 432 private void processRunStartedTag(String identifier) { 433 // eg: (Running XX tests from 1 test case.) 434 Pattern numTestsPattern = Pattern.compile("Running (\\d+) test[s]? from .*"); 435 Matcher numTests = numTestsPattern.matcher(identifier); 436 437 // Try to find number of tests 438 if (numTests.find()) { 439 try { 440 mNumTestsExpected = Integer.parseInt(numTests.group(1)); 441 } 442 catch (NumberFormatException e) { 443 Log.e(LOG_TAG, "Unable to determine number of tests expected, received: " + 444 numTests.group(1)); 445 } 446 } 447 if (mNumTestsExpected > 0) { 448 reportTestRunStarted(); 449 mNumTestsRun = 0; 450 mTestRunInProgress = true; 451 } 452 } 453 454 /** 455 * Processes and informs listener when we encounter a tag indicating that a test suite is done. 456 * 457 * @param identifier Raw log output from the suite ended tag 458 */ 459 private void processRunCompletedTag(String identifier) { 460 Pattern timePattern = Pattern.compile(".*\\((\\d+) ms total\\)"); // eg: (XX ms total) 461 Matcher time = timePattern.matcher(identifier); 462 463 // Try to find the total run time 464 if (time.find()) { 465 try { 466 mTotalRunTime = Long.parseLong(time.group(1)); 467 } 468 catch (NumberFormatException e) { 469 Log.e(LOG_TAG, "Unable to determine the total running time, received: " + 470 time.group(1)); 471 } 472 } 473 reportTestRunEnded(); 474 mTestRunInProgress = false; 475 } 476 477 /** 478 * Processes and informs listener when we encounter a tag indicating that a test has started. 479 * 480 * @param identifier Raw log output of the form classname.testname, with an optional time (x ms) 481 */ 482 private void processTestStartedTag(String identifier) { 483 ParsedTestInfo parsedResults = parseTestIdentifier(identifier); 484 TestResult testResult = getCurrentTestResult(); 485 testResult.mTestClass = parsedResults.mTestClassName; 486 testResult.mTestName = parsedResults.mTestName; 487 488 TestIdentifier testId = new TestIdentifier(mFakePackagePrefix + testResult.mTestClass, 489 testResult.mTestName); 490 491 for (ITestRunListener listener : mTestListeners) { 492 listener.testStarted(testId); 493 } 494 setTestStarted(); 495 } 496 497 /** 498 * Helper method to do the work necessary when a test has ended. 499 * 500 * @param identifier Raw log output of the form "classname.testname" with an optional (XX ms) 501 * at the end indicating the running time. 502 * @param testPassed Indicates whether the test passed or failed (set to true if passed, false 503 * if failed) 504 */ 505 private void doTestEnded(String identifier, boolean testPassed) { 506 ParsedTestInfo parsedResults = parseTestIdentifier(identifier); 507 TestResult testResult = getCurrentTestResult(); 508 TestIdentifier testId = new TestIdentifier(mFakePackagePrefix + testResult.mTestClass, 509 testResult.mTestName); 510 511 // Error - trying to end a test when one isn't in progress 512 if (!testInProgress()) { 513 Log.e(LOG_TAG, "Test currently not in progress when trying to end test: " + identifier); 514 return; 515 } 516 517 // Save the run time for this test if one exists 518 if (parsedResults.mTestRunTime != null) { 519 try { 520 testResult.mRunTime = new Long(parsedResults.mTestRunTime); 521 } 522 catch (NumberFormatException e) { 523 Log.e(LOG_TAG, "Test run time value is invalid, received: " + 524 parsedResults.mTestRunTime); 525 } 526 } 527 528 // Check that the test result is for the same test/class we're expecting it to be for 529 boolean encounteredUnexpectedTest = false; 530 if (!testResult.isComplete()) { 531 Log.e(LOG_TAG, "No test/class name is currently recorded as running!"); 532 } 533 else { 534 if (testResult.mTestClass.compareTo(parsedResults.mTestClassName) != 0) { 535 Log.e(LOG_TAG, "Name for current test class does not match class we started " + 536 "with, expected: " + testResult.mTestClass + " but got: " + 537 parsedResults.mTestClassName); 538 encounteredUnexpectedTest = true; 539 } 540 if (testResult.mTestName.compareTo(parsedResults.mTestName) != 0) { 541 Log.e(LOG_TAG, "Name for current test does not match test we started with," + 542 "expected: " + testResult.mTestName + " bug got: " + 543 parsedResults.mTestName); 544 encounteredUnexpectedTest = true; 545 } 546 } 547 548 if (encounteredUnexpectedTest) { 549 // If the test name of the result changed from what we started with, report that 550 // the last known test failed, regardless of whether we received a pass or fail tag. 551 for (ITestRunListener listener : mTestListeners) { 552 listener.testFailed(testId, mCurrentTestResult.getTrace()); 553 } 554 } 555 else if (!testPassed) { // test failed 556 for (ITestRunListener listener : mTestListeners) { 557 listener.testFailed(testId, mCurrentTestResult.getTrace()); 558 } 559 } 560 // For all cases (pass or fail), we ultimately need to report test has ended 561 Map <String, String> emptyMap = Collections.emptyMap(); 562 for (ITestRunListener listener : mTestListeners) { 563 // @TODO: Add reporting of test run time to ITestRunListener 564 listener.testEnded(testId, emptyMap); 565 } 566 567 setTestEnded(); 568 ++mNumTestsRun; 569 } 570 571 /** 572 * Processes and informs listener when we encounter the OK tag. 573 * 574 * @param identifier Raw log output of the form "classname.testname" with an optional (XX ms) 575 * at the end indicating the running time. 576 */ 577 private void processOKTag(String identifier) { 578 doTestEnded(identifier, true); 579 } 580 581 /** 582 * Processes and informs listener when we encounter the FAILED tag. 583 * 584 * @param identifier Raw log output of the form "classname.testname" with an optional (XX ms) 585 * at the end indicating the running time. 586 */ 587 private void processFailedTag(String identifier) { 588 doTestEnded(identifier, false); 589 } 590 591 /** 592 * Appends the test output to the current TestResult. 593 * 594 * @param line Raw test result line of output. 595 */ 596 private void appendTestOutputLine(String line) { 597 TestResult testResult = getCurrentTestResult(); 598 if (testResult.mStackTrace == null) { 599 testResult.mStackTrace = new StringBuilder(); 600 } 601 else { 602 testResult.mStackTrace.append("\r\n"); 603 } 604 testResult.mStackTrace.append(line); 605 } 606 607 /** 608 * Process an instrumentation run failure 609 * 610 * @param errorMsg The message to output about the nature of the error 611 */ 612 private void handleTestRunFailed(String errorMsg) { 613 errorMsg = (errorMsg == null ? "Unknown error" : errorMsg); 614 Log.i(LOG_TAG, String.format("Test run failed: %s", errorMsg)); 615 String testRunStackTrace = ""; 616 617 // Report that the last known test failed 618 if ((mCurrentTestResult != null) && (mCurrentTestResult.isComplete())) { 619 // current test results are cleared out after every complete test run, 620 // if it's not null, assume the last test caused this and report as a test failure 621 TestIdentifier testId = new TestIdentifier(mCurrentTestResult.mTestClass, 622 mCurrentTestResult.mTestName); 623 624 // If there was any stack trace during the test run, append it to the "test failed" 625 // error message so we have an idea of what caused the crash/failure. 626 Map<String, String> emptyMap = Collections.emptyMap(); 627 if (mCurrentTestResult.hasStackTrace()) { 628 testRunStackTrace = mCurrentTestResult.getTrace(); 629 } 630 for (ITestRunListener listener : mTestListeners) { 631 listener.testFailed(testId, "No test results.\r\n" + testRunStackTrace); 632 listener.testEnded(testId, emptyMap); 633 } 634 clearCurrentTestResult(); 635 } 636 // Report the test run failed 637 for (ITestRunListener listener : mTestListeners) { 638 listener.testRunFailed(errorMsg); 639 listener.testRunEnded(mTotalRunTime, getRunMetrics()); 640 } 641 } 642 643 /** 644 * Called by parent when adb session is complete. 645 */ 646 @Override 647 public void done() { 648 super.done(); 649 if (mNumTestsExpected > mNumTestsRun) { 650 handleTestRunFailed(String.format("Test run incomplete. Expected %d tests, received %d", 651 mNumTestsExpected, mNumTestsRun)); 652 } 653 else if (mTestRunInProgress) { 654 handleTestRunFailed("No test results"); 655 } 656 } 657 658 /** 659 * Sets the coverage target for this test. 660 * <p/> 661 * Will be sent as a metric to test listeners. 662 * 663 * @param coverageTarget the coverage target 664 */ 665 public void setCoverageTarget(String coverageTarget) { 666 mCoverageTarget = coverageTarget; 667 } 668 } 669
