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