1 /* 2 * Copyright (C) 2008 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 17 package com.android.ddmlib.testrunner; 18 19 import com.android.ddmlib.IShellOutputReceiver; 20 import com.android.ddmlib.Log; 21 import com.android.ddmlib.MultiLineReceiver; 22 23 import java.util.ArrayList; 24 import java.util.Collection; 25 import java.util.HashMap; 26 import java.util.HashSet; 27 import java.util.Map; 28 import java.util.Set; 29 import java.util.regex.Matcher; 30 import java.util.regex.Pattern; 31 32 /** 33 * Parses the 'raw output mode' results of an instrumentation test run from shell and informs a 34 * ITestRunListener of the results. 35 * 36 * <p>Expects the following output: 37 * 38 * <p>If fatal error occurred when attempted to run the tests: 39 * <pre> 40 * INSTRUMENTATION_STATUS: Error=error Message 41 * INSTRUMENTATION_FAILED: 42 * </pre> 43 * <p>or 44 * <pre> 45 * INSTRUMENTATION_RESULT: shortMsg=error Message 46 * </pre> 47 * 48 * <p>Otherwise, expect a series of test results, each one containing a set of status key/value 49 * pairs, delimited by a start(1)/pass(0)/fail(-2)/error(-1) status code result. At end of test 50 * run, expects that the elapsed test time in seconds will be displayed 51 * 52 * <p>For example: 53 * <pre> 54 * INSTRUMENTATION_STATUS_CODE: 1 55 * INSTRUMENTATION_STATUS: class=com.foo.FooTest 56 * INSTRUMENTATION_STATUS: test=testFoo 57 * INSTRUMENTATION_STATUS: numtests=2 58 * INSTRUMENTATION_STATUS: stack=com.foo.FooTest#testFoo:312 59 * com.foo.X 60 * INSTRUMENTATION_STATUS_CODE: -2 61 * ... 62 * 63 * Time: X 64 * </pre> 65 * <p>Note that the "value" portion of the key-value pair may wrap over several text lines 66 */ 67 public class InstrumentationResultParser extends MultiLineReceiver { 68 69 /** Relevant test status keys. */ 70 private static class StatusKeys { 71 private static final String TEST = "test"; 72 private static final String CLASS = "class"; 73 private static final String STACK = "stack"; 74 private static final String NUMTESTS = "numtests"; 75 private static final String ERROR = "Error"; 76 private static final String SHORTMSG = "shortMsg"; 77 } 78 79 /** The set of expected status keys. Used to filter which keys should be stored as metrics */ 80 private static final Set<String> KNOWN_KEYS = new HashSet<String>(); 81 static { 82 KNOWN_KEYS.add(StatusKeys.TEST); 83 KNOWN_KEYS.add(StatusKeys.CLASS); 84 KNOWN_KEYS.add(StatusKeys.STACK); 85 KNOWN_KEYS.add(StatusKeys.NUMTESTS); 86 KNOWN_KEYS.add(StatusKeys.ERROR); 87 KNOWN_KEYS.add(StatusKeys.SHORTMSG); 88 // unused, but regularly occurring status keys. 89 KNOWN_KEYS.add("stream"); 90 KNOWN_KEYS.add("id"); 91 KNOWN_KEYS.add("current"); 92 } 93 94 /** Test result status codes. */ 95 private static class StatusCodes { 96 private static final int FAILURE = -2; 97 private static final int START = 1; 98 private static final int ERROR = -1; 99 private static final int OK = 0; 100 private static final int IN_PROGRESS = 2; 101 } 102 103 /** Prefixes used to identify output. */ 104 private static class Prefixes { 105 private static final String STATUS = "INSTRUMENTATION_STATUS: "; 106 private static final String STATUS_CODE = "INSTRUMENTATION_STATUS_CODE: "; 107 private static final String STATUS_FAILED = "INSTRUMENTATION_FAILED: "; 108 private static final String CODE = "INSTRUMENTATION_CODE: "; 109 private static final String RESULT = "INSTRUMENTATION_RESULT: "; 110 private static final String TIME_REPORT = "Time: "; 111 } 112 113 private final Collection<ITestRunListener> mTestListeners; 114 115 /** 116 * Test result data 117 */ 118 private static class TestResult { 119 private Integer mCode = null; 120 private String mTestName = null; 121 private String mTestClass = null; 122 private String mStackTrace = null; 123 private Integer mNumTests = null; 124 125 /** Returns true if all expected values have been parsed */ 126 boolean isComplete() { 127 return mCode != null && mTestName != null && mTestClass != null; 128 } 129 130 /** Provides a more user readable string for TestResult, if possible */ 131 @Override 132 public String toString() { 133 StringBuilder output = new StringBuilder(); 134 if (mTestClass != null ) { 135 output.append(mTestClass); 136 output.append('#'); 137 } 138 if (mTestName != null) { 139 output.append(mTestName); 140 } 141 if (output.length() > 0) { 142 return output.toString(); 143 } 144 return "unknown result"; 145 } 146 } 147 148 /** the name to provide to {@link ITestRunListener#testRunStarted(String, int)} */ 149 private final String mTestRunName; 150 151 /** Stores the status values for the test result currently being parsed */ 152 private TestResult mCurrentTestResult = null; 153 154 /** Stores the status values for the test result last parsed */ 155 private TestResult mLastTestResult = null; 156 157 /** Stores the current "key" portion of the status key-value being parsed. */ 158 private String mCurrentKey = null; 159 160 /** Stores the current "value" portion of the status key-value being parsed. */ 161 private StringBuilder mCurrentValue = null; 162 163 /** True if start of test has already been reported to listener. */ 164 private boolean mTestStartReported = false; 165 166 /** True if the completion of the test run has been detected. */ 167 private boolean mTestRunFinished = false; 168 169 /** True if test run failure has already been reported to listener. */ 170 private boolean mTestRunFailReported = false; 171 172 /** The elapsed time of the test run, in milliseconds. */ 173 private long mTestTime = 0; 174 175 /** True if current test run has been canceled by user. */ 176 private boolean mIsCancelled = false; 177 178 /** The number of tests currently run */ 179 private int mNumTestsRun = 0; 180 181 /** The number of tests expected to run */ 182 private int mNumTestsExpected = 0; 183 184 /** True if the parser is parsing a line beginning with "INSTRUMENTATION_RESULT" */ 185 private boolean mInInstrumentationResultKey = false; 186 187 /** 188 * Stores key-value pairs under INSTRUMENTATION_RESULT header, these are printed at the 189 * end of a test run, if applicable 190 */ 191 private Map<String, String> mInstrumentationResultBundle = new HashMap<String, String>(); 192 193 /** 194 * Stores key-value pairs of metrics emitted during the execution of each test case. Note that 195 * standard keys that are stored in the TestResults class are filtered out of this Map. 196 */ 197 private Map<String, String> mTestMetrics = new HashMap<String, String>(); 198 199 private static final String LOG_TAG = "InstrumentationResultParser"; 200 201 /** Error message supplied when no parseable test results are received from test run. */ 202 static final String NO_TEST_RESULTS_MSG = "No test results"; 203 204 /** Error message supplied when a test start bundle is parsed, but not the test end bundle. */ 205 static final String INCOMPLETE_TEST_ERR_MSG_PREFIX = "Test failed to run to completion"; 206 static final String INCOMPLETE_TEST_ERR_MSG_POSTFIX = "Check device logcat for details"; 207 208 /** Error message supplied when the test run is incomplete. */ 209 static final String INCOMPLETE_RUN_ERR_MSG_PREFIX = "Test run failed to complete"; 210 211 /** 212 * Creates the InstrumentationResultParser. 213 * 214 * @param runName the test run name to provide to 215 * {@link ITestRunListener#testRunStarted(String, int)} 216 * @param listeners informed of test results as the tests are executing 217 */ 218 public InstrumentationResultParser(String runName, Collection<ITestRunListener> listeners) { 219 mTestRunName = runName; 220 mTestListeners = new ArrayList<ITestRunListener>(listeners); 221 } 222 223 /** 224 * Creates the InstrumentationResultParser for a single listener. 225 * 226 * @param runName the test run name to provide to 227 * {@link ITestRunListener#testRunStarted(String, int)} 228 * @param listener informed of test results as the tests are executing 229 */ 230 public InstrumentationResultParser(String runName, ITestRunListener listener) { 231 mTestRunName = runName; 232 mTestListeners = new ArrayList<ITestRunListener>(1); 233 mTestListeners.add(listener); 234 } 235 236 /** 237 * Processes the instrumentation test output from shell. 238 * 239 * @see MultiLineReceiver#processNewLines 240 */ 241 @Override 242 public void processNewLines(String[] lines) { 243 for (String line : lines) { 244 parse(line); 245 // in verbose mode, dump all adb output to log 246 Log.v(LOG_TAG, line); 247 } 248 } 249 250 /** 251 * Parse an individual output line. Expects a line that is one of: 252 * <ul> 253 * <li> 254 * The start of a new status line (starts with Prefixes.STATUS or Prefixes.STATUS_CODE), 255 * and thus there is a new key=value pair to parse, and the previous key-value pair is 256 * finished. 257 * </li> 258 * <li> 259 * A continuation of the previous status (the "value" portion of the key has wrapped 260 * to the next line). 261 * </li> 262 * <li> A line reporting a fatal error in the test run (Prefixes.STATUS_FAILED) </li> 263 * <li> A line reporting the total elapsed time of the test run. (Prefixes.TIME_REPORT) </li> 264 * </ul> 265 * 266 * @param line Text output line 267 */ 268 private void parse(String line) { 269 if (line.startsWith(Prefixes.STATUS_CODE)) { 270 // Previous status key-value has been collected. Store it. 271 submitCurrentKeyValue(); 272 mInInstrumentationResultKey = false; 273 parseStatusCode(line); 274 } else if (line.startsWith(Prefixes.STATUS)) { 275 // Previous status key-value has been collected. Store it. 276 submitCurrentKeyValue(); 277 mInInstrumentationResultKey = false; 278 parseKey(line, Prefixes.STATUS.length()); 279 } else if (line.startsWith(Prefixes.RESULT)) { 280 // Previous status key-value has been collected. Store it. 281 submitCurrentKeyValue(); 282 mInInstrumentationResultKey = true; 283 parseKey(line, Prefixes.RESULT.length()); 284 } else if (line.startsWith(Prefixes.STATUS_FAILED) || 285 line.startsWith(Prefixes.CODE)) { 286 // Previous status key-value has been collected. Store it. 287 submitCurrentKeyValue(); 288 mInInstrumentationResultKey = false; 289 // these codes signal the end of the instrumentation run 290 mTestRunFinished = true; 291 // just ignore the remaining data on this line 292 } else if (line.startsWith(Prefixes.TIME_REPORT)) { 293 parseTime(line); 294 } else { 295 if (mCurrentValue != null) { 296 // this is a value that has wrapped to next line. 297 mCurrentValue.append("\r\n"); 298 mCurrentValue.append(line); 299 } else if (line.trim().length() > 0){ 300 Log.d(LOG_TAG, "unrecognized line " + line); 301 } 302 } 303 } 304 305 /** 306 * Stores the currently parsed key-value pair in the appropriate place. 307 */ 308 private void submitCurrentKeyValue() { 309 if (mCurrentKey != null && mCurrentValue != null) { 310 String statusValue = mCurrentValue.toString(); 311 if (mInInstrumentationResultKey) { 312 if (!KNOWN_KEYS.contains(mCurrentKey)) { 313 mInstrumentationResultBundle.put(mCurrentKey, statusValue); 314 } else if (mCurrentKey.equals(StatusKeys.SHORTMSG)) { 315 // test run must have failed 316 handleTestRunFailed(String.format("Instrumentation run failed due to '%1$s'", 317 statusValue)); 318 } 319 } else { 320 TestResult testInfo = getCurrentTestInfo(); 321 322 if (mCurrentKey.equals(StatusKeys.CLASS)) { 323 testInfo.mTestClass = statusValue.trim(); 324 } else if (mCurrentKey.equals(StatusKeys.TEST)) { 325 testInfo.mTestName = statusValue.trim(); 326 } else if (mCurrentKey.equals(StatusKeys.NUMTESTS)) { 327 try { 328 testInfo.mNumTests = Integer.parseInt(statusValue); 329 } catch (NumberFormatException e) { 330 Log.w(LOG_TAG, "Unexpected integer number of tests, received " 331 + statusValue); 332 } 333 } else if (mCurrentKey.equals(StatusKeys.ERROR)) { 334 // test run must have failed 335 handleTestRunFailed(statusValue); 336 } else if (mCurrentKey.equals(StatusKeys.STACK)) { 337 testInfo.mStackTrace = statusValue; 338 } else if (!KNOWN_KEYS.contains(mCurrentKey)) { 339 // Not one of the recognized key/value pairs, so dump it in mTestMetrics 340 mTestMetrics.put(mCurrentKey, statusValue); 341 } 342 } 343 344 mCurrentKey = null; 345 mCurrentValue = null; 346 } 347 } 348 349 /** 350 * A utility method to return the test metrics from the current test case execution and get 351 * ready for the next one. 352 */ 353 private Map<String, String> getAndResetTestMetrics() { 354 Map<String, String> retVal = mTestMetrics; 355 mTestMetrics = new HashMap<String, String>(); 356 return retVal; 357 } 358 359 private TestResult getCurrentTestInfo() { 360 if (mCurrentTestResult == null) { 361 mCurrentTestResult = new TestResult(); 362 } 363 return mCurrentTestResult; 364 } 365 366 private void clearCurrentTestInfo() { 367 mLastTestResult = mCurrentTestResult; 368 mCurrentTestResult = null; 369 } 370 371 /** 372 * Parses the key from the current line. 373 * Expects format of "key=value". 374 * 375 * @param line full line of text to parse 376 * @param keyStartPos the starting position of the key in the given line 377 */ 378 private void parseKey(String line, int keyStartPos) { 379 int endKeyPos = line.indexOf('=', keyStartPos); 380 if (endKeyPos != -1) { 381 mCurrentKey = line.substring(keyStartPos, endKeyPos).trim(); 382 parseValue(line, endKeyPos + 1); 383 } 384 } 385 386 /** 387 * Parses the start of a key=value pair. 388 * 389 * @param line - full line of text to parse 390 * @param valueStartPos - the starting position of the value in the given line 391 */ 392 private void parseValue(String line, int valueStartPos) { 393 mCurrentValue = new StringBuilder(); 394 mCurrentValue.append(line.substring(valueStartPos)); 395 } 396 397 /** 398 * Parses out a status code result. 399 */ 400 private void parseStatusCode(String line) { 401 String value = line.substring(Prefixes.STATUS_CODE.length()).trim(); 402 TestResult testInfo = getCurrentTestInfo(); 403 testInfo.mCode = StatusCodes.ERROR; 404 try { 405 testInfo.mCode = Integer.parseInt(value); 406 } catch (NumberFormatException e) { 407 Log.w(LOG_TAG, "Expected integer status code, received: " + value); 408 testInfo.mCode = StatusCodes.ERROR; 409 } 410 if (testInfo.mCode != StatusCodes.IN_PROGRESS) { 411 // this means we're done with current test result bundle 412 reportResult(testInfo); 413 clearCurrentTestInfo(); 414 } 415 } 416 417 /** 418 * Returns true if test run canceled. 419 * 420 * @see IShellOutputReceiver#isCancelled() 421 */ 422 @Override 423 public boolean isCancelled() { 424 return mIsCancelled; 425 } 426 427 /** 428 * Requests cancellation of test run. 429 */ 430 public void cancel() { 431 mIsCancelled = true; 432 } 433 434 /** 435 * Reports a test result to the test run listener. Must be called when a individual test 436 * result has been fully parsed. 437 * 438 * @param statusMap key-value status pairs of test result 439 */ 440 private void reportResult(TestResult testInfo) { 441 if (!testInfo.isComplete()) { 442 Log.w(LOG_TAG, "invalid instrumentation status bundle " + testInfo.toString()); 443 return; 444 } 445 reportTestRunStarted(testInfo); 446 TestIdentifier testId = new TestIdentifier(testInfo.mTestClass, testInfo.mTestName); 447 Map<String, String> metrics; 448 449 switch (testInfo.mCode) { 450 case StatusCodes.START: 451 for (ITestRunListener listener : mTestListeners) { 452 listener.testStarted(testId); 453 } 454 break; 455 case StatusCodes.FAILURE: 456 metrics = getAndResetTestMetrics(); 457 for (ITestRunListener listener : mTestListeners) { 458 listener.testFailed(ITestRunListener.TestFailure.FAILURE, testId, 459 getTrace(testInfo)); 460 461 listener.testEnded(testId, metrics); 462 } 463 mNumTestsRun++; 464 break; 465 case StatusCodes.ERROR: 466 metrics = getAndResetTestMetrics(); 467 for (ITestRunListener listener : mTestListeners) { 468 listener.testFailed(ITestRunListener.TestFailure.ERROR, testId, 469 getTrace(testInfo)); 470 listener.testEnded(testId, metrics); 471 } 472 mNumTestsRun++; 473 break; 474 case StatusCodes.OK: 475 metrics = getAndResetTestMetrics(); 476 for (ITestRunListener listener : mTestListeners) { 477 listener.testEnded(testId, metrics); 478 } 479 mNumTestsRun++; 480 break; 481 default: 482 metrics = getAndResetTestMetrics(); 483 Log.e(LOG_TAG, "Unknown status code received: " + testInfo.mCode); 484 for (ITestRunListener listener : mTestListeners) { 485 listener.testEnded(testId, metrics); 486 } 487 mNumTestsRun++; 488 break; 489 } 490 491 } 492 493 /** 494 * Reports the start of a test run, and the total test count, if it has not been previously 495 * reported. 496 * 497 * @param testInfo current test status values 498 */ 499 private void reportTestRunStarted(TestResult testInfo) { 500 // if start test run not reported yet 501 if (!mTestStartReported && testInfo.mNumTests != null) { 502 for (ITestRunListener listener : mTestListeners) { 503 listener.testRunStarted(mTestRunName, testInfo.mNumTests); 504 } 505 mNumTestsExpected = testInfo.mNumTests; 506 mTestStartReported = true; 507 } 508 } 509 510 /** 511 * Returns the stack trace of the current failed test, from the provided testInfo. 512 */ 513 private String getTrace(TestResult testInfo) { 514 if (testInfo.mStackTrace != null) { 515 return testInfo.mStackTrace; 516 } else { 517 Log.e(LOG_TAG, "Could not find stack trace for failed test "); 518 return new Throwable("Unknown failure").toString(); 519 } 520 } 521 522 /** 523 * Parses out and store the elapsed time. 524 */ 525 private void parseTime(String line) { 526 final Pattern timePattern = Pattern.compile(String.format("%s\\s*([\\d\\.]+)", 527 Prefixes.TIME_REPORT)); 528 Matcher timeMatcher = timePattern.matcher(line); 529 if (timeMatcher.find()) { 530 String timeString = timeMatcher.group(1); 531 try { 532 float timeSeconds = Float.parseFloat(timeString); 533 mTestTime = (long) (timeSeconds * 1000); 534 } catch (NumberFormatException e) { 535 Log.w(LOG_TAG, String.format("Unexpected time format %1$s", line)); 536 } 537 } else { 538 Log.w(LOG_TAG, String.format("Unexpected time format %1$s", line)); 539 } 540 } 541 542 /** 543 * Inform the parser of a instrumentation run failure. Should be called when the adb command 544 * used to run the test fails. 545 */ 546 public void handleTestRunFailed(String errorMsg) { 547 errorMsg = (errorMsg == null ? "Unknown error" : errorMsg); 548 Log.i(LOG_TAG, String.format("test run failed: '%1$s'", errorMsg)); 549 if (mLastTestResult != null && 550 mLastTestResult.isComplete() && 551 StatusCodes.START == mLastTestResult.mCode) { 552 553 // received test start msg, but not test complete 554 // assume test caused this, report as test failure 555 TestIdentifier testId = new TestIdentifier(mLastTestResult.mTestClass, 556 mLastTestResult.mTestName); 557 for (ITestRunListener listener : mTestListeners) { 558 listener.testFailed(ITestRunListener.TestFailure.ERROR, testId, 559 String.format("%1$s. Reason: '%2$s'. %3$s", INCOMPLETE_TEST_ERR_MSG_PREFIX, 560 errorMsg, INCOMPLETE_TEST_ERR_MSG_POSTFIX)); 561 listener.testEnded(testId, getAndResetTestMetrics()); 562 } 563 } 564 for (ITestRunListener listener : mTestListeners) { 565 if (!mTestStartReported) { 566 // test run wasn't started - must have crashed before it started 567 listener.testRunStarted(mTestRunName, 0); 568 } 569 listener.testRunFailed(errorMsg); 570 listener.testRunEnded(mTestTime, mInstrumentationResultBundle); 571 } 572 mTestStartReported = true; 573 mTestRunFailReported = true; 574 } 575 576 /** 577 * Called by parent when adb session is complete. 578 */ 579 @Override 580 public void done() { 581 super.done(); 582 if (!mTestRunFailReported) { 583 handleOutputDone(); 584 } 585 } 586 587 /** 588 * Handles the end of the adb session when a test run failure has not been reported yet 589 */ 590 private void handleOutputDone() { 591 if (!mTestStartReported && !mTestRunFinished) { 592 // no results 593 handleTestRunFailed(NO_TEST_RESULTS_MSG); 594 } else if (mNumTestsExpected > mNumTestsRun) { 595 final String message = 596 String.format("%1$s. Expected %2$d tests, received %3$d", 597 INCOMPLETE_RUN_ERR_MSG_PREFIX, mNumTestsExpected, mNumTestsRun); 598 handleTestRunFailed(message); 599 } else { 600 for (ITestRunListener listener : mTestListeners) { 601 if (!mTestStartReported) { 602 // test run wasn't started, but it finished successfully. Must be a run with 603 // no tests 604 listener.testRunStarted(mTestRunName, 0); 605 } 606 listener.testRunEnded(mTestTime, mInstrumentationResultBundle); 607 } 608 } 609 } 610 } 611