1 /*
2  * Copyright (C) 2020 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.tradefed.device.DeviceNotAvailableException;
19 import com.android.tradefed.device.ITestDevice;
20 import com.android.tradefed.device.TestDeviceState;
21 import com.android.tradefed.invoker.tracing.CloseableTraceScope;
22 import com.android.tradefed.log.LogUtil.CLog;
23 import com.android.tradefed.metrics.proto.MetricMeasurement.Metric;
24 import com.android.tradefed.result.FailureDescription;
25 import com.android.tradefed.result.ITestInvocationListener;
26 import com.android.tradefed.result.LogcatCrashResultForwarder;
27 import com.android.tradefed.result.TestDescription;
28 import com.android.tradefed.result.error.DeviceErrorIdentifier;
29 import com.android.tradefed.result.error.InfraErrorIdentifier;
30 import com.android.tradefed.result.error.TestErrorIdentifier;
31 import com.android.tradefed.result.proto.TestRecordProto.FailureStatus;
32 import com.android.tradefed.result.skipped.SkipReason;
33 import com.android.tradefed.util.ProcessInfo;
34 
35 import java.util.ArrayList;
36 import java.util.Collection;
37 import java.util.HashMap;
38 import java.util.HashSet;
39 import java.util.LinkedHashSet;
40 import java.util.List;
41 import java.util.Set;
42 
43 /**
44  * Internal listener to Trade Federation for {@link InstrumentationTest}. It allows to collect extra
45  * information needed for easier debugging.
46  */
47 final class InstrumentationListener extends LogcatCrashResultForwarder {
48 
49     // Message from ddmlib InstrumentationResultParser for interrupted instrumentation.
50     private static final String DDMLIB_INSTRU_FAILURE_MSG = "Test run failed to complete";
51     // Message from ddmlib for ShellCommandUnresponsiveException
52     private static final String DDMLIB_SHELL_UNRESPONSIVE =
53             "Failed to receive adb shell test output within";
54     private static final String JUNIT4_TIMEOUT =
55             "org.junit.runners.model.TestTimedOutException: test timed out";
56     // Message from ddmlib when there is a mismatch of test cases count
57     private static final String DDMLIB_UNEXPECTED_COUNT = "Instrumentation reported numtests=";
58 
59     private Set<TestDescription> mTests = new HashSet<>();
60     private Set<TestDescription> mDuplicateTests = new HashSet<>();
61     private final Collection<TestDescription> mExpectedTests;
62     private boolean mDisableDuplicateCheck = false;
63     private boolean mReportUnexecutedTests = false;
64     private ProcessInfo mSystemServerProcess = null;
65     private String runLevelError = null;
66     private TestDescription mLastTest = null;
67     private TestDescription mLastStartedTest = null;
68 
69     private CloseableTraceScope mMethodScope = null;
70 
71     /**
72      * @param device
73      * @param listeners
74      */
InstrumentationListener( ITestDevice device, Collection<TestDescription> expectedTests, ITestInvocationListener... listeners)75     public InstrumentationListener(
76             ITestDevice device,
77             Collection<TestDescription> expectedTests,
78             ITestInvocationListener... listeners) {
79         super(device, listeners);
80         mExpectedTests = expectedTests;
81     }
82 
addListener(ITestInvocationListener listener)83     public void addListener(ITestInvocationListener listener) {
84         List<ITestInvocationListener> listeners = new ArrayList<>();
85         listeners.addAll(getListeners());
86         listeners.add(listener);
87         setListeners(listeners);
88     }
89 
90     /** Whether or not to disable the duplicate test method check. */
setDisableDuplicateCheck(boolean disable)91     public void setDisableDuplicateCheck(boolean disable) {
92         mDisableDuplicateCheck = disable;
93     }
94 
setOriginalSystemServer(ProcessInfo info)95     public void setOriginalSystemServer(ProcessInfo info) {
96         mSystemServerProcess = info;
97     }
98 
setReportUnexecutedTests(boolean enable)99     public void setReportUnexecutedTests(boolean enable) {
100         mReportUnexecutedTests = enable;
101     }
102 
103     @Override
testRunStarted(String runName, int testCount)104     public void testRunStarted(String runName, int testCount) {
105         runLevelError = null;
106         // In case of crash, run will attempt to report with 0
107         if (testCount == 0 && mExpectedTests != null && !mExpectedTests.isEmpty()) {
108             CLog.e("Run reported 0 tests while we collected %s", mExpectedTests.size());
109             super.testRunStarted(runName, mExpectedTests.size());
110         } else {
111             super.testRunStarted(runName, testCount);
112         }
113     }
114 
115     @Override
testStarted(TestDescription test, long startTime)116     public void testStarted(TestDescription test, long startTime) {
117         mMethodScope = new CloseableTraceScope(test.toString());
118         super.testStarted(test, startTime);
119         if (!mTests.add(test)) {
120             mDuplicateTests.add(test);
121         }
122         mLastStartedTest = test;
123     }
124 
125     @Override
testFailed(TestDescription test, FailureDescription failure)126     public void testFailed(TestDescription test, FailureDescription failure) {
127         String message = failure.getErrorMessage();
128         if (message.startsWith(JUNIT4_TIMEOUT) || message.contains(DDMLIB_SHELL_UNRESPONSIVE)) {
129             failure.setErrorIdentifier(TestErrorIdentifier.TEST_TIMEOUT).setRetriable(false);
130         }
131         super.testFailed(test, failure);
132     }
133 
134     @Override
testEnded(TestDescription test, long endTime, HashMap<String, Metric> testMetrics)135     public void testEnded(TestDescription test, long endTime, HashMap<String, Metric> testMetrics) {
136         mLastTest = test;
137         mLastStartedTest = null;
138         super.testEnded(test, endTime, testMetrics);
139         if (mMethodScope != null) {
140             mMethodScope.close();
141             mMethodScope = null;
142         }
143     }
144 
145     @Override
testRunFailed(FailureDescription error)146     public void testRunFailed(FailureDescription error) {
147         if (error.getErrorMessage().startsWith(DDMLIB_INSTRU_FAILURE_MSG)) {
148             if (mExpectedTests != null) {
149                 Set<TestDescription> expected = new LinkedHashSet<>(mExpectedTests);
150                 expected.removeAll(mTests);
151                 String helpMessage = String.format("The following tests didn't run: %s", expected);
152                 error.setDebugHelpMessage(helpMessage);
153             }
154             error.setFailureStatus(FailureStatus.TEST_FAILURE);
155             String wrapMessage = error.getErrorMessage();
156             boolean restarted = false;
157             if (mSystemServerProcess != null) {
158                 try {
159                     restarted = getDevice().deviceSoftRestarted(mSystemServerProcess);
160                 } catch (DeviceNotAvailableException e) {
161                     // Ignore
162                 }
163                 if (restarted) {
164                     error.setFailureStatus(FailureStatus.SYSTEM_UNDER_TEST_CRASHED);
165                     error.setErrorIdentifier(DeviceErrorIdentifier.DEVICE_CRASHED);
166                     wrapMessage =
167                             String.format(
168                                     "Detected system_server restart causing instrumentation error:"
169                                             + " %s",
170                                     error.getErrorMessage());
171                 }
172             }
173             if (!restarted && !TestDeviceState.ONLINE.equals(getDevice().getDeviceState())) {
174                 error.setErrorIdentifier(DeviceErrorIdentifier.ADB_DISCONNECT);
175                 wrapMessage =
176                         String.format(
177                                 "Detected device offline causing instrumentation error: %s",
178                                 error.getErrorMessage());
179             }
180             error.setErrorMessage(wrapMessage);
181         } else if (error.getErrorMessage().startsWith(DDMLIB_SHELL_UNRESPONSIVE)) {
182             String wrapMessage = "Instrumentation ran for longer than the configured timeout.";
183             if (mLastStartedTest != null) {
184                 wrapMessage += String.format(" The last started but unfinished test was: %s.",
185                     mLastStartedTest.toString());
186             }
187             CLog.w("ddmlib reported error: %s.", error.getErrorMessage());
188             error.setErrorMessage(wrapMessage);
189             error.setFailureStatus(FailureStatus.TIMED_OUT);
190             error.setErrorIdentifier(TestErrorIdentifier.INSTRUMENTATION_TIMED_OUT);
191         } else if (error.getErrorMessage().startsWith(DDMLIB_UNEXPECTED_COUNT)) {
192             error.setFailureStatus(FailureStatus.TEST_FAILURE);
193             error.setErrorIdentifier(InfraErrorIdentifier.EXPECTED_TESTS_MISMATCH);
194         }
195         // Use error before injecting the crashes
196         runLevelError = error.getErrorMessage();
197         super.testRunFailed(error);
198     }
199 
200     @Override
testRunEnded(long elapsedTime, HashMap<String, Metric> runMetrics)201     public void testRunEnded(long elapsedTime, HashMap<String, Metric> runMetrics) {
202         if (!mDuplicateTests.isEmpty() && !mDisableDuplicateCheck) {
203             FailureDescription error =
204                     FailureDescription.create(
205                             String.format(
206                                     "The following tests ran more than once: %s. Check "
207                                             + "your run configuration, you might be "
208                                             + "including the same test class several "
209                                             + "times.",
210                                     mDuplicateTests));
211             error.setFailureStatus(FailureStatus.TEST_FAILURE)
212                     .setRetriable(false); // Don't retry duplicate tests.
213             super.testRunFailed(error);
214         } else if (mReportUnexecutedTests
215                 && mExpectedTests != null
216                 && mExpectedTests.size() > mTests.size()) {
217             Set<TestDescription> missingTests = new LinkedHashSet<>(mExpectedTests);
218             missingTests.removeAll(mTests);
219 
220             TestDescription lastTest = mLastTest;
221             String lastExecutedLog = "";
222             if (lastTest != null) {
223                 lastExecutedLog = "Last executed test was " + lastTest.toString() + ".";
224             }
225             if (runLevelError == null) {
226                 runLevelError = "Method was expected to run but didn't.";
227             } else {
228                 runLevelError =
229                         String.format("Run level error reported reason: '%s", runLevelError);
230             }
231             for (TestDescription miss : missingTests) {
232                 super.testStarted(miss);
233                 SkipReason reason =
234                         new SkipReason(
235                                 String.format(
236                                         "Test did not run due to instrumentation issue. %s %s",
237                                         lastExecutedLog, runLevelError),
238                                 "INSTRUMENTATION_ERROR");
239                 super.testSkipped(miss, reason);
240                 super.testEnded(miss, new HashMap<String, Metric>());
241             }
242         }
243         runLevelError = null;
244         super.testRunEnded(elapsedTime, runMetrics);
245     }
246 }
247