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.invoker; 17 18 import com.android.ddmlib.Log.LogLevel; 19 import com.android.tradefed.build.BuildInfo; 20 import com.android.tradefed.build.BuildRetrievalError; 21 import com.android.tradefed.build.CommandLineBuildInfoBuilder; 22 import com.android.tradefed.build.IBuildInfo; 23 import com.android.tradefed.clearcut.ClearcutClient; 24 import com.android.tradefed.command.CommandRunner.ExitCode; 25 import com.android.tradefed.command.CommandScheduler; 26 import com.android.tradefed.command.ICommandOptions; 27 import com.android.tradefed.command.ICommandScheduler.IScheduledInvocationListener; 28 import com.android.tradefed.config.ArgsOptionParser; 29 import com.android.tradefed.config.ConfigurationException; 30 import com.android.tradefed.config.DynamicRemoteFileResolver; 31 import com.android.tradefed.config.GlobalConfiguration; 32 import com.android.tradefed.config.IConfiguration; 33 import com.android.tradefed.config.IDeviceConfiguration; 34 import com.android.tradefed.config.filter.OptionFetcher; 35 import com.android.tradefed.config.proxy.AutomatedReporters; 36 import com.android.tradefed.config.proxy.TradefedDelegator; 37 import com.android.tradefed.config.remote.ExtendedFile; 38 import com.android.tradefed.dependencies.ExternalDependency; 39 import com.android.tradefed.dependencies.IExternalDependency; 40 import com.android.tradefed.device.DeviceManager; 41 import com.android.tradefed.device.DeviceNotAvailableException; 42 import com.android.tradefed.device.DeviceUnresponsiveException; 43 import com.android.tradefed.device.FreeDeviceState; 44 import com.android.tradefed.device.ITestDevice; 45 import com.android.tradefed.device.ITestDevice.RecoveryMode; 46 import com.android.tradefed.device.NativeDevice; 47 import com.android.tradefed.device.RemoteAndroidDevice; 48 import com.android.tradefed.device.RemoteAvdIDevice; 49 import com.android.tradefed.device.SnapuserdWaitPhase; 50 import com.android.tradefed.device.StubDevice; 51 import com.android.tradefed.device.StubLocalAndroidVirtualDevice; 52 import com.android.tradefed.device.TestDeviceState; 53 import com.android.tradefed.device.cloud.ManagedRemoteDevice; 54 import com.android.tradefed.device.cloud.NestedRemoteDevice; 55 import com.android.tradefed.device.cloud.RemoteAndroidVirtualDevice; 56 import com.android.tradefed.device.internal.DeviceReleaseReporter; 57 import com.android.tradefed.error.HarnessException; 58 import com.android.tradefed.error.HarnessRuntimeException; 59 import com.android.tradefed.error.IHarnessException; 60 import com.android.tradefed.invoker.logger.CurrentInvocation; 61 import com.android.tradefed.invoker.logger.CurrentInvocation.InvocationInfo; 62 import com.android.tradefed.invoker.logger.InvocationMetricLogger; 63 import com.android.tradefed.invoker.logger.InvocationMetricLogger.InvocationMetricKey; 64 import com.android.tradefed.invoker.logger.TfObjectTracker; 65 import com.android.tradefed.invoker.sandbox.ParentSandboxInvocationExecution; 66 import com.android.tradefed.invoker.sandbox.SandboxedInvocationExecution; 67 import com.android.tradefed.invoker.shard.LastShardDetector; 68 import com.android.tradefed.invoker.shard.ShardHelper; 69 import com.android.tradefed.invoker.tracing.CloseableTraceScope; 70 import com.android.tradefed.log.BaseLeveledLogOutput; 71 import com.android.tradefed.log.ILeveledLogOutput; 72 import com.android.tradefed.log.ILogRegistry; 73 import com.android.tradefed.log.ITestLogger; 74 import com.android.tradefed.log.LogRegistry; 75 import com.android.tradefed.log.LogUtil.CLog; 76 import com.android.tradefed.log.StdoutLogger; 77 import com.android.tradefed.postprocessor.IPostProcessor; 78 import com.android.tradefed.result.ActionInProgress; 79 import com.android.tradefed.result.ByteArrayInputStreamSource; 80 import com.android.tradefed.result.EventsLoggerListener; 81 import com.android.tradefed.result.FailureDescription; 82 import com.android.tradefed.result.FileInputStreamSource; 83 import com.android.tradefed.result.ITestInvocationListener; 84 import com.android.tradefed.result.InputStreamSource; 85 import com.android.tradefed.result.LogDataType; 86 import com.android.tradefed.result.LogSaverResultForwarder; 87 import com.android.tradefed.result.ReportPassedTests; 88 import com.android.tradefed.result.ResultAndLogForwarder; 89 import com.android.tradefed.result.error.DeviceErrorIdentifier; 90 import com.android.tradefed.result.error.ErrorIdentifier; 91 import com.android.tradefed.result.error.InfraErrorIdentifier; 92 import com.android.tradefed.result.proto.TestRecordProto.FailureStatus; 93 import com.android.tradefed.result.skipped.SkipReason; 94 import com.android.tradefed.retry.IRetryDecision; 95 import com.android.tradefed.retry.ResultAggregator; 96 import com.android.tradefed.retry.RetryStrategy; 97 import com.android.tradefed.service.TradefedFeatureServer; 98 import com.android.tradefed.targetprep.BuildError; 99 import com.android.tradefed.targetprep.DeviceFailedToBootError; 100 import com.android.tradefed.targetprep.TargetSetupError; 101 import com.android.tradefed.testtype.ITestInformationReceiver; 102 import com.android.tradefed.testtype.SubprocessTfLauncher; 103 import com.android.tradefed.util.CommandResult; 104 import com.android.tradefed.util.FileUtil; 105 import com.android.tradefed.util.IDisableable; 106 import com.android.tradefed.util.IRunUtil; 107 import com.android.tradefed.util.PrettyPrintDelimiter; 108 import com.android.tradefed.util.QuotationAwareTokenizer; 109 import com.android.tradefed.util.RunInterruptedException; 110 import com.android.tradefed.util.RunUtil; 111 import com.android.tradefed.util.SystemUtil; 112 import com.android.tradefed.util.TimeUtil; 113 import com.android.tradefed.util.executor.ParallelDeviceExecutor; 114 115 import com.google.common.annotations.VisibleForTesting; 116 import com.google.common.base.Joiner; 117 118 import java.io.File; 119 import java.io.IOException; 120 import java.io.PrintWriter; 121 import java.io.StringWriter; 122 import java.util.ArrayList; 123 import java.util.Arrays; 124 import java.util.LinkedHashSet; 125 import java.util.List; 126 import java.util.Map; 127 import java.util.Map.Entry; 128 import java.util.Set; 129 import java.util.concurrent.Callable; 130 import java.util.concurrent.TimeUnit; 131 import java.util.stream.Collectors; 132 133 import javax.annotation.Nullable; 134 135 /** 136 * Default implementation of {@link ITestInvocation}. 137 * <p/> 138 * Loads major objects based on {@link IConfiguration} 139 * - retrieves build 140 * - prepares target 141 * - runs tests 142 * - reports results 143 */ 144 public class TestInvocation implements ITestInvocation { 145 146 /** Key of the command line args attributes */ 147 public static final String COMMAND_ARGS_KEY = "command_line_args"; 148 149 /** 150 * Format of the key in {@link IBuildInfo} to log the battery level for each step of the 151 * invocation. (Setup, test, tear down). 152 */ 153 private static final String BATTERY_ATTRIBUTE_FORMAT_KEY = "%s-battery-%s"; 154 155 public static final String TRADEFED_LOG_NAME = "host_log"; 156 public static final String TRADEFED_END_HOST_LOG = "end_host_log"; 157 public static final String TRADEFED_INVOC_COMPLETE_HOST_LOG = "invoc_complete_host_log"; 158 private static final String TRADEFED_DELEGATED_LOG_NAME = "delegated_parent_log"; 159 public static final String TRADEFED_CONFIG_NAME = "tradefed-expanded-config"; 160 /** Suffix used on host_log for the part before sharding occurs. */ 161 static final String BEFORE_SHARDING_SUFFIX = "_before_sharding"; 162 static final String DEVICE_LOG_NAME_PREFIX = "device_logcat_"; 163 static final String EMULATOR_LOG_NAME_PREFIX = "emulator_log_"; 164 static final String BUILD_ERROR_BUGREPORT_NAME = "build_error_bugreport"; 165 static final String DEVICE_UNRESPONSIVE_BUGREPORT_NAME = "device_unresponsive_bugreport"; 166 static final String INVOCATION_ENDED_BUGREPORT_NAME = "invocation_ended_bugreport"; 167 static final String TARGET_SETUP_ERROR_BUGREPORT_NAME = "target_setup_error_bugreport"; 168 static final String BATT_TAG = "[battery level]"; 169 static final String RECOVERY_LOG_DEVICE_PATH = "/tmp/recovery.log"; 170 public static final String INVOCATION_EXTERNAL_DEPENDENCIES = 171 "invocation-external-dependencies"; 172 public static final long AVAILABILITY_CHECK_TIMEOUT = 180000L; // 3 minutes 173 static final String GOOGLE_USB_VENDOR_ID = "0x18d1"; 174 175 public enum Stage { 176 ERROR("error"), 177 SETUP("setup"), 178 TEST("test"), 179 TEARDOWN("teardown"); 180 181 private final String mName; 182 Stage(String name)183 Stage(String name) { 184 mName = name; 185 } 186 getName()187 public String getName() { 188 return mName; 189 } 190 } 191 192 /** The different mode an invocation can run into. */ 193 public enum RunMode { 194 REGULAR, 195 PARENT_SANDBOX, 196 SANDBOX, 197 REMOTE_INVOCATION, 198 DELEGATED_INVOCATION 199 } 200 201 private String mStatus = "(not invoked)"; 202 private String mStopCause = null; 203 private ErrorIdentifier mStopErrorId = null; 204 private Long mStopRequestTime = null; 205 private Long mSoftStopRequestTime = null; 206 private boolean mShutdownBeforeTest = false; 207 private boolean mTestStarted = false; 208 private boolean mTestDone = false; 209 private boolean mForcedStopRequestedAfterTest = false; 210 private boolean mIsRemoteInvocation = false; 211 212 private boolean mInvocationFailed = false; 213 private boolean mDelegatedInvocation = false; 214 private List<IScheduledInvocationListener> mSchedulerListeners = new ArrayList<>(); 215 private DeviceUnavailableMonitor mUnavailableMonitor = new DeviceUnavailableMonitor(); 216 private ConditionFailureMonitor mConditionalFailureMonitor = new ConditionFailureMonitor(); 217 private ExitCode mExitCode = ExitCode.NO_ERROR; 218 private Throwable mExitStack = null; 219 private EventsLoggerListener mEventsLogger = null; 220 private ClearcutClient mClient = null; 221 222 private List<ExtendedFile> mParallelDynamicDownloads = new ArrayList<>(); 223 /** 224 * Display a log message informing the user of a invocation being started. 225 * 226 * @param context the {@link IInvocationContext} 227 * @param config the {@link IConfiguration} 228 */ logStartInvocation(IInvocationContext context, IConfiguration config)229 private void logStartInvocation(IInvocationContext context, IConfiguration config) { 230 String shardSuffix = ""; 231 if (config.getCommandOptions().getShardIndex() != null) { 232 shardSuffix = 233 String.format( 234 " (shard %d of %d)", 235 config.getCommandOptions().getShardIndex() + 1, 236 config.getCommandOptions().getShardCount()); 237 } 238 StringBuilder buildInfos = new StringBuilder(); 239 StringBuilder msg = new StringBuilder("Starting invocation for '"); 240 msg.append(context.getTestTag()); 241 msg.append("' with "); 242 for (Entry<ITestDevice, IBuildInfo> entry : context.getDeviceBuildMap().entrySet()) { 243 msg.append("'[ "); 244 msg.append(entry.getValue().toString()); 245 buildInfos.append(entry.getValue().toString()); 246 msg.append(" on device '"); 247 msg.append(entry.getKey().getSerialNumber()); 248 msg.append("'] "); 249 } 250 msg.append(shardSuffix); 251 CLog.logAndDisplay(LogLevel.INFO, msg.toString()); 252 mStatus = String.format("running %s on build(s) '%s'", context.getTestTag(), 253 buildInfos.toString()) + shardSuffix; 254 } 255 256 /** 257 * Performs the invocation 258 * 259 * @param config the {@link IConfiguration} 260 * @param testInfo the {@link TestInformation} to use for the invocation. 261 */ performInvocation( IConfiguration config, TestInformation testInfo, IInvocationExecution invocationPath, ITestInvocationListener listener, boolean devicePreSetupDone)262 private void performInvocation( 263 IConfiguration config, 264 TestInformation testInfo, 265 IInvocationExecution invocationPath, 266 ITestInvocationListener listener, 267 boolean devicePreSetupDone) 268 throws Throwable { 269 ReportHostLog reportThread = new ReportHostLog(listener, config); 270 Runtime.getRuntime().addShutdownHook(reportThread); 271 String bugreportName = null; 272 long startTime = System.currentTimeMillis(); 273 long elapsedTime = -1; 274 Throwable exception = null; 275 Throwable tearDownException = null; 276 ITestDevice badDevice = null; 277 IInvocationContext context = testInfo.getContext(); 278 279 // Ensure that no unexpected attributes are added afterward 280 ((InvocationContext) context).lockAttributes(); 281 try { 282 logDeviceBatteryLevel(context, "initial"); 283 // Run the preInvocationSetup on devices. 284 if (!devicePreSetupDone) { 285 invocationPath.runDevicePreInvocationSetup(context, config, listener); 286 } 287 // Then run the regular setup and run 288 prepareAndRun(config, testInfo, invocationPath, listener); 289 } catch (BuildError e) { 290 exception = e; 291 CLog.w("BuildError on device '%s'. Reason: %s", e.getDeviceSerial(), e.toString()); 292 bugreportName = BUILD_ERROR_BUGREPORT_NAME; 293 if (e.getDeviceSerial() != null) { 294 badDevice = context.getDeviceBySerial(e.getDeviceSerial()); 295 } 296 if (e instanceof DeviceFailedToBootError) { 297 if (badDevice == null) { 298 context.setRecoveryModeForAllDevices(RecoveryMode.NONE); 299 } else { 300 badDevice.setRecoveryMode(RecoveryMode.NONE); 301 } 302 } 303 reportFailure(createFailureFromException(e, FailureStatus.INFRA_FAILURE), listener); 304 } catch (TargetSetupError e) { 305 exception = e; 306 CLog.e("Caught exception while running invocation"); 307 CLog.e(e); 308 // We let parent process capture the bugreport 309 if (!isSubprocess(config)) { 310 bugreportName = TARGET_SETUP_ERROR_BUGREPORT_NAME; 311 } 312 if (e.getDeviceSerial() != null) { 313 badDevice = context.getDeviceBySerial(e.getDeviceSerial()); 314 } 315 reportFailure(createFailureFromException(e, FailureStatus.INFRA_FAILURE), listener); 316 } catch (DeviceNotAvailableException e) { 317 exception = e; 318 // log a warning here so its captured before reportLogs is called 319 CLog.w( 320 "Invocation did not complete due to device %s becoming not available. " 321 + "Reason: %s", 322 e.getSerial(), e.toString()); 323 badDevice = context.getDeviceBySerial(e.getSerial()); 324 if ((e instanceof DeviceUnresponsiveException) && badDevice != null 325 && TestDeviceState.ONLINE.equals(badDevice.getDeviceState())) { 326 // We let parent process capture the bugreport 327 if (!isSubprocess(config)) { 328 // under certain cases it might still be possible to grab a bugreport 329 bugreportName = DEVICE_UNRESPONSIVE_BUGREPORT_NAME; 330 } 331 } 332 reportFailure(createFailureFromException(e, FailureStatus.INFRA_FAILURE), listener); 333 // Upon reaching here after an exception, it is safe to assume that recovery 334 // has already been attempted so we disable it to avoid re-entry during clean up. 335 if (badDevice != null) { 336 badDevice.setRecoveryMode(RecoveryMode.NONE); 337 } 338 throw e; 339 } catch (RunInterruptedException e) { 340 exception = e; 341 CLog.w("Invocation interrupted"); 342 CLog.e(e); 343 // if a stop cause was set, the interruption is most likely due to the invocation being 344 // cancelled 345 if (mStopCause == null) { 346 reportFailure(createFailureFromException(e, FailureStatus.UNSET), listener); 347 } 348 } catch (AssertionError e) { 349 exception = e; 350 CLog.e("Caught AssertionError while running invocation: %s", e.toString()); 351 CLog.e(e); 352 reportFailure(createFailureFromException(e, FailureStatus.UNSET), listener); 353 } catch (Throwable t) { 354 exception = t; 355 // log a warning here so its captured before reportLogs is called 356 CLog.e("Unexpected exception when running invocation: %s", t.toString()); 357 CLog.e(t); 358 if (mStopCause == null) { 359 reportFailure(createFailureFromException(t, FailureStatus.UNSET), listener); 360 throw t; 361 } 362 } finally { 363 mTestDone = true; 364 long bugreportStartTime = System.currentTimeMillis(); 365 // Only capture logcat for TEST if we started the test phase. 366 if (mTestStarted) { 367 for (ITestDevice device : context.getDevices()) { 368 invocationPath.reportLogs(device, listener, Stage.TEST); 369 } 370 } 371 if (mConditionalFailureMonitor.hasRunFailures()) { 372 InvocationMetricLogger.addInvocationMetrics( 373 InvocationMetricKey.HAS_ANY_RUN_FAILURES, "true"); 374 } 375 CurrentInvocation.setActionInProgress(ActionInProgress.TEAR_DOWN); 376 getRunUtil().allowInterrupt(false); 377 if (!mDelegatedInvocation) { 378 if (config.getCommandOptions().takeBugreportOnInvocationEnded() 379 || config.getCommandOptions().takeBugreportzOnInvocationEnded()) { 380 if (bugreportName != null) { 381 CLog.i("Bugreport to be taken for failure instead of invocation ended."); 382 } else { 383 bugreportName = INVOCATION_ENDED_BUGREPORT_NAME; 384 } 385 } 386 if (exception == null && !SystemUtil.isLocalMode()) { 387 exception = mUnavailableMonitor.getUnavailableException(); 388 if (exception != null) { 389 CLog.e("Found a test level only device unavailable exception:"); 390 CLog.e(exception); 391 } 392 if (exception == null) { 393 try (CloseableTraceScope ignore = 394 new CloseableTraceScope("responsiveness_check")) { 395 exception = bareMinimumResponsiveness(context.getDevices()); 396 } 397 } 398 if (exception != null) { 399 bugreportName = null; 400 } 401 } 402 403 // reset bugreportName to null if shouldSkipBugreportError(exception) == true 404 bugreportName = shouldSkipBugreportError(exception) ? null : bugreportName; 405 if (bugreportName != null) { 406 try (CloseableTraceScope _ignore = 407 new CloseableTraceScope(InvocationMetricKey.bugreport.name())) { 408 if (context.getDevices().size() == 1 || badDevice != null) { 409 ITestDevice collectBugreport = badDevice; 410 if (collectBugreport == null) { 411 collectBugreport = context.getDevices().get(0); 412 } 413 // If we have identified a faulty device only take the bugreport on it. 414 takeBugreport( 415 collectBugreport, 416 listener, 417 config.getCommandOptions(), 418 bugreportName); 419 } else if (context.getDevices().size() > 1) { 420 ParallelDeviceExecutor<Boolean> executor = 421 new ParallelDeviceExecutor<>(context.getDevices().size()); 422 List<Callable<Boolean>> callableTasks = new ArrayList<>(); 423 final String reportName = bugreportName; 424 for (ITestDevice device : context.getDevices()) { 425 Callable<Boolean> callableTask = 426 () -> { 427 CLog.d( 428 "Start taking bugreport on '%s'", 429 device.getSerialNumber()); 430 takeBugreport( 431 device, 432 listener, 433 config.getCommandOptions(), 434 reportName); 435 return true; 436 }; 437 callableTasks.add(callableTask); 438 } 439 // Capture the bugreports best effort, ignore the results. 440 executor.invokeAll(callableTasks, 5, TimeUnit.MINUTES); 441 } 442 } 443 } 444 reportRecoveryLogs(context.getDevices(), listener); 445 } 446 try (CloseableTraceScope ignore = new CloseableTraceScope("logExecuteShellCommand")) { 447 // Save the device executeShellCommand logs 448 logExecuteShellCommand(context.getDevices(), listener); 449 } 450 try (CloseableTraceScope ignore = 451 new CloseableTraceScope(InvocationMetricKey.check_device_availability.name())) { 452 if (SystemUtil.isLocalMode()) { 453 CLog.d("Skipping check for device availability for local run."); 454 } else if (exception == null) { 455 CLog.d("Checking that devices are online."); 456 exception = checkDevicesAvailable(context.getDevices(), listener); 457 } else { 458 CLog.d("Skip online check as an exception was already reported: %s", exception); 459 } 460 // Report bugreport and various check as part of teardown 461 InvocationMetricLogger.addInvocationPairMetrics( 462 InvocationMetricKey.TEARDOWN_PAIR, 463 bugreportStartTime, 464 System.currentTimeMillis()); 465 mStatus = "tearing down"; 466 } 467 try (CloseableTraceScope ignore = 468 new CloseableTraceScope(InvocationMetricKey.test_teardown.name())) { 469 invocationPath.doTeardown(testInfo, config, listener, exception); 470 } catch (Throwable e) { 471 tearDownException = e; 472 CLog.e("Exception when tearing down invocation: %s", tearDownException.toString()); 473 CLog.e(tearDownException); 474 if (exception == null) { 475 // only report when the exception is new during tear down 476 reportFailure( 477 createFailureFromException( 478 tearDownException, FailureStatus.INFRA_FAILURE), 479 listener); 480 } 481 } 482 try (CloseableTraceScope ignore = 483 new CloseableTraceScope(InvocationMetricKey.log_and_release_device.name())) { 484 // Capture last logcat before releasing the device. 485 for (ITestDevice device : context.getDevices()) { 486 invocationPath.reportLogs(device, listener, Stage.TEARDOWN); 487 } 488 mStatus = "done running tests"; 489 CurrentInvocation.setActionInProgress(ActionInProgress.FREE_RESOURCES); 490 491 // Ensure we always deregister the logger 492 for (String deviceName : context.getDeviceConfigNames()) { 493 if (!(context.getDevice(deviceName).getIDevice() instanceof StubDevice)) { 494 context.getDevice(deviceName).stopLogcat(); 495 CLog.i( 496 "Done stopping logcat for %s", 497 context.getDevice(deviceName).getSerialNumber()); 498 } 499 } 500 501 if (config.getCommandOptions().earlyDeviceRelease()) { 502 Map<ITestDevice, FreeDeviceState> devicesStates = 503 handleAndLogReleaseState(context, exception, tearDownException); 504 context.markReleasedEarly(); 505 for (IScheduledInvocationListener scheduleListener : mSchedulerListeners) { 506 scheduleListener.releaseDevices(context, devicesStates); 507 } 508 } 509 // Log count of allocated devices for test accounting 510 addInvocationMetric( 511 InvocationMetricKey.DEVICE_COUNT, context.getNumDevicesAllocated()); 512 // Track the timestamp when we are done with devices 513 addInvocationMetric( 514 InvocationMetricKey.DEVICE_DONE_TIMESTAMP, System.currentTimeMillis()); 515 } 516 try (CloseableTraceScope ignore = 517 new CloseableTraceScope(InvocationMetricKey.test_cleanup.name())) { 518 // Clean up host. 519 invocationPath.doCleanUp(context, config, exception); 520 waitForSnapuserd(testInfo, config, SnapuserdWaitPhase.BLOCK_BEFORE_RELEASING); 521 if (mSoftStopRequestTime != null) { // soft stop occurred 522 long latency = System.currentTimeMillis() - mSoftStopRequestTime; 523 InvocationMetricLogger.addInvocationMetrics( 524 InvocationMetricKey.SHUTDOWN_LATENCY, latency); 525 InvocationMetricLogger.addInvocationMetrics( 526 InvocationMetricKey.SHUTDOWN_BEFORE_TEST, 527 Boolean.toString(mShutdownBeforeTest)); 528 if (mShutdownBeforeTest) { 529 String message = 530 String.format("Notified of soft shut down. Did not run tests"); 531 FailureDescription failure = 532 FailureDescription.create(message) 533 .setErrorIdentifier( 534 InfraErrorIdentifier 535 .TRADEFED_SKIPPED_TESTS_DURING_SHUTDOWN) 536 .setCause( 537 new HarnessRuntimeException( 538 message, 539 InfraErrorIdentifier 540 .TRADEFED_SKIPPED_TESTS_DURING_SHUTDOWN)); 541 // report failure so that command can be un-leased 542 reportFailure(failure, listener); 543 } 544 } 545 if (mStopCause != null) { // Forced stop occurred 546 if (mForcedStopRequestedAfterTest) { 547 InvocationMetricLogger.addInvocationMetrics( 548 InvocationMetricKey.SHUTDOWN_AFTER_TEST, "true"); 549 CLog.d( 550 "Forced shutdown occurred after test phase execution. It shouldn't" 551 + " have impact on test results."); 552 } else { 553 String message = 554 String.format( 555 "Invocation was interrupted due to: %s%s", 556 mStopCause, 557 mShutdownBeforeTest 558 ? ". Tests were not run." 559 : ", results will be affected"); 560 if (mStopErrorId == null) { 561 mStopErrorId = InfraErrorIdentifier.INVOCATION_CANCELLED; 562 } 563 // if invocation is stopped and tests were not run, report invocation 564 // failure with correct error identifier so that command can be 565 // un-leased 566 if (mShutdownBeforeTest) { 567 mStopErrorId = 568 InfraErrorIdentifier.TRADEFED_SKIPPED_TESTS_DURING_SHUTDOWN; 569 } 570 FailureDescription failure = 571 FailureDescription.create(message) 572 .setErrorIdentifier(mStopErrorId) 573 .setCause( 574 new HarnessRuntimeException(message, mStopErrorId)); 575 reportFailure(failure, listener); 576 PrettyPrintDelimiter.printStageDelimiter(message); 577 } 578 if (mStopRequestTime != null) { 579 // This is not 100% perfect since result reporting can still run a bit 580 // longer, but this is our last opportunity to report it. 581 long latency = System.currentTimeMillis() - mStopRequestTime; 582 InvocationMetricLogger.addInvocationMetrics( 583 InvocationMetricKey.SHUTDOWN_HARD_LATENCY, latency); 584 } 585 } 586 reportHostLog(listener, config); 587 // If host_log is reported, remove the hook 588 Runtime.getRuntime().removeShutdownHook(reportThread); 589 590 // Measure teardown disk usage before clean up 591 Long size = measureWorkFolderSize(config, testInfo); 592 if (size != null) { 593 InvocationMetricLogger.addInvocationMetrics( 594 InvocationMetricKey.TEAR_DOWN_DISK_USAGE, size); 595 } 596 elapsedTime = System.currentTimeMillis() - startTime; 597 reportInvocationEnded(config, context, listener, elapsedTime); 598 } 599 } 600 if (tearDownException != null) { 601 // this means a DNAE or RTE has happened during teardown, need to throw 602 // if there was a preceding RTE or DNAE stored in 'exception', it would have already 603 // been thrown before exiting the previous try...catch...finally block 604 throw tearDownException; 605 } 606 } 607 608 /** Do setup and run the tests */ prepareAndRun( IConfiguration config, TestInformation testInfo, IInvocationExecution invocationPath, ITestInvocationListener listener)609 private void prepareAndRun( 610 IConfiguration config, 611 TestInformation testInfo, 612 IInvocationExecution invocationPath, 613 ITestInvocationListener listener) 614 throws Throwable { 615 long startTimeNano = System.nanoTime(); 616 try { 617 getRunUtil().allowInterrupt(true); 618 logDeviceBatteryLevel(testInfo.getContext(), "initial -> setup"); 619 CurrentInvocation.setActionInProgress(ActionInProgress.SETUP); 620 invocationPath.doSetup(testInfo, config, listener); 621 // Don't run tests if notified of soft/forced shutdown 622 if (mSoftStopRequestTime != null || mStopRequestTime != null) { 623 // Throw an exception so that it can be reported as an invocation failure 624 // and command can be un-leased 625 throw new RunInterruptedException( 626 "Notified of shut down. Will not run tests", 627 InfraErrorIdentifier.TRADEFED_SKIPPED_TESTS_DURING_SHUTDOWN); 628 } 629 logDeviceBatteryLevel(testInfo.getContext(), "setup -> test"); 630 mTestStarted = true; 631 CurrentInvocation.setActionInProgress(ActionInProgress.TEST); 632 waitForSnapuserd(testInfo, config, SnapuserdWaitPhase.BLOCK_BEFORE_TEST); 633 invocationPath.runTests(testInfo, config, listener); 634 } finally { 635 if (mClient != null) { 636 mClient.notifyTestRunFinished(startTimeNano); 637 } 638 } 639 logDeviceBatteryLevel(testInfo.getContext(), "after test"); 640 CurrentInvocation.setActionInProgress(ActionInProgress.UNSET); 641 } 642 643 /** 644 * Starts the invocation. 645 * 646 * <p>Starts logging, and informs listeners that invocation has been started. 647 * 648 * @param config 649 * @param context 650 */ startInvocation( IConfiguration config, IInvocationContext context, ITestInvocationListener listener, RunMode mode, boolean parentShard)651 private void startInvocation( 652 IConfiguration config, 653 IInvocationContext context, 654 ITestInvocationListener listener, 655 RunMode mode, 656 boolean parentShard) { 657 logStartInvocation(context, config); 658 listener.invocationStarted(context); 659 logExpandedConfiguration(config, listener, mode, parentShard); 660 } 661 startInvocation( IConfiguration config, IInvocationContext context, ITestInvocationListener listener)662 private void startInvocation( 663 IConfiguration config, IInvocationContext context, ITestInvocationListener listener) { 664 startInvocation(config, context, listener, null, false); 665 } 666 667 /** Report the exception failure as an invocation failure. */ reportFailure(FailureDescription failure, ITestInvocationListener listener)668 private void reportFailure(FailureDescription failure, ITestInvocationListener listener) { 669 if (mInvocationFailed) { 670 CLog.e("An invocation failure was already reported, ignoring %s", failure); 671 return; 672 } 673 // Always report the failure 674 listener.invocationFailed(failure); 675 mInvocationFailed = true; 676 } 677 678 /** 679 * Create a {@link FailureDescription} from an invocation exception. 680 * 681 * @param exception The exception to convert 682 * @param defaultStatus The status to use by default if the exception is not a {@link 683 * IHarnessException}. 684 */ createFailureFromException( Throwable exception, FailureStatus defaultStatus)685 public static FailureDescription createFailureFromException( 686 Throwable exception, FailureStatus defaultStatus) { 687 ErrorIdentifier id = null; 688 if (exception instanceof IHarnessException) { 689 id = ((IHarnessException) exception).getErrorId(); 690 } 691 String message = exception.getMessage(); 692 if (message == null) { 693 message = "No error message"; 694 } 695 FailureDescription failure = 696 CurrentInvocation.createFailure(message, id).setCause(exception); 697 if (id == null) { 698 failure.setFailureStatus(defaultStatus); 699 } 700 return failure; 701 } 702 reportHostLog(ITestInvocationListener listener, IConfiguration config)703 private void reportHostLog(ITestInvocationListener listener, IConfiguration config) { 704 String name = TRADEFED_LOG_NAME; 705 if (mDelegatedInvocation) { 706 name = TRADEFED_DELEGATED_LOG_NAME; 707 } 708 reportHostLog(listener, config, name); 709 } 710 reportHostLog( ITestInvocationListener listener, IConfiguration config, String name)711 private void reportHostLog( 712 ITestInvocationListener listener, IConfiguration config, String name) { 713 ILeveledLogOutput logger = config.getLogOutput(); 714 try (InputStreamSource globalLogSource = logger.getLog()) { 715 if (globalLogSource != null) { 716 if (config.getCommandOptions().getHostLogSuffix() != null) { 717 name += config.getCommandOptions().getHostLogSuffix(); 718 } 719 listener.testLog(name, LogDataType.HOST_LOG, globalLogSource); 720 } else { 721 // Only print the non-logging if we are not a stdout logger 722 if (!(logger instanceof StdoutLogger)) { 723 CLog.i("Skip logging %s to a file with logger '%s'", name, logger); 724 } 725 } 726 } 727 // once tradefed log is reported, all further log calls for this invocation can get lost 728 // unregister logger so future log calls get directed to the tradefed global log 729 getLogRegistry().unregisterLogger(); 730 logger.closeLog(); 731 } 732 takeBugreport( ITestDevice device, ITestInvocationListener listener, ICommandOptions options, String bugreportName)733 private void takeBugreport( 734 ITestDevice device, 735 ITestInvocationListener listener, 736 ICommandOptions options, 737 String bugreportName) { 738 if (device == null) { 739 return; 740 } 741 if (device.getIDevice() instanceof StubDevice) { 742 return; 743 } 744 if (!TestDeviceState.ONLINE.equals(device.getDeviceState())) { 745 CLog.d("Skipping bugreportz on %s. Device is offline.", device.getSerialNumber()); 746 return; 747 } 748 // logBugreport will report a regular bugreport if bugreportz is not supported. 749 RecoveryMode recovery = device.getRecoveryMode(); 750 try { 751 device.setRecoveryMode(RecoveryMode.NONE); 752 if (!options.isConditionalBugreportDisabled() 753 && !mConditionalFailureMonitor.hasFailures()) { 754 device.logAnrs(listener); 755 } else { 756 boolean res = 757 device.logBugreport( 758 String.format("%s_%s", bugreportName, device.getSerialNumber()), 759 listener); 760 if (!res) { 761 CLog.w( 762 "Error when collecting bugreport for device '%s'", 763 device.getSerialNumber()); 764 } 765 } 766 } catch (DeviceNotAvailableException | RuntimeException e) { 767 CLog.e("Harness Exception while collecting bugreport"); 768 CLog.e(e); 769 } finally { 770 device.setRecoveryMode(recovery); 771 } 772 } 773 774 /** 775 * Gets the {@link ILogRegistry} to use. 776 * <p/> 777 * Exposed for unit testing. 778 */ getLogRegistry()779 ILogRegistry getLogRegistry() { 780 return LogRegistry.getLogRegistry(); 781 } 782 783 /** 784 * Utility method to fetch the default {@link IRunUtil} singleton 785 * <p /> 786 * Exposed for unit testing. 787 */ getRunUtil()788 IRunUtil getRunUtil() { 789 return RunUtil.getDefault(); 790 } 791 792 @Override toString()793 public String toString() { 794 return mStatus; 795 } 796 797 /** 798 * Log the battery level of each device in the invocation. 799 * 800 * @param context the {@link IInvocationContext} of the invocation. 801 * @param event a {@link String} describing the context of the logging (initial, setup, etc.). 802 */ 803 @VisibleForTesting logDeviceBatteryLevel(IInvocationContext context, String event)804 void logDeviceBatteryLevel(IInvocationContext context, String event) { 805 if (SystemUtil.isLocalMode()) { 806 CLog.d("Skipping battery level log for local invocation on event: %s.", event); 807 return; 808 } 809 for (ITestDevice testDevice : context.getDevices()) { 810 if (testDevice == null) { 811 continue; 812 } 813 if (testDevice.getIDevice() instanceof StubDevice) { 814 continue; 815 } 816 if (testDevice instanceof RemoteAndroidVirtualDevice 817 || testDevice instanceof NestedRemoteDevice) { 818 // Vritual devices have a fake battery there is no point in logging it. 819 continue; 820 } 821 try (CloseableTraceScope ignored = new CloseableTraceScope("log_battery")) { 822 Integer batteryLevel = testDevice.getBattery(); 823 if (batteryLevel == null) { 824 CLog.v("Failed to get battery level for %s", testDevice.getSerialNumber()); 825 continue; 826 } 827 CLog.v("%s - %s - %d%%", BATT_TAG, event, batteryLevel); 828 context.getBuildInfo(testDevice) 829 .addBuildAttribute( 830 String.format( 831 BATTERY_ATTRIBUTE_FORMAT_KEY, 832 testDevice.getSerialNumber(), 833 event), 834 batteryLevel.toString()); 835 } 836 } 837 } 838 839 /** 840 * Log the invocation configuration as one large XML detailing all settings in use. 841 * 842 * @param config the {@link IConfiguration} of this test run 843 * @param listener the {@link ITestLogger} with which to register the log 844 */ logExpandedConfiguration( IConfiguration config, ITestLogger listener, RunMode mode, boolean parentShard)845 private void logExpandedConfiguration( 846 IConfiguration config, ITestLogger listener, RunMode mode, boolean parentShard) { 847 boolean isShard = config.getConfigurationDescription().getShardIndex() != null; 848 if (isShard && !parentShard) { 849 // Bail out of logging the config if this is a local shard since it is problematic 850 // and redundant anyway. 851 CLog.d("Skipping expanded config log for shard."); 852 return; 853 } 854 try (StringWriter configXmlWriter = new StringWriter(); 855 PrintWriter wrapperWriter = new PrintWriter(configXmlWriter)) { 856 config.dumpXml(wrapperWriter, new ArrayList<String>(), true, false); 857 wrapperWriter.flush(); 858 // Specified UTF-8 encoding for an abundance of caution, but its possible we could want 859 // something else in the future 860 byte[] configXmlByteArray = configXmlWriter.toString().getBytes("UTF-8"); 861 try (InputStreamSource source = new ByteArrayInputStreamSource(configXmlByteArray)) { 862 String prefix = ""; 863 if (mode != null) { 864 switch (mode) { 865 case PARENT_SANDBOX: 866 prefix = "parent-sandbox-"; 867 break; 868 case SANDBOX: 869 prefix = "child-sandbox-"; 870 break; 871 case DELEGATED_INVOCATION: 872 prefix = "parent-delegate-"; 873 break; 874 case REMOTE_INVOCATION: 875 // Fallthrough 876 default: 877 prefix = ""; 878 } 879 } 880 String configOutputName = String.format("%s%s", prefix, TRADEFED_CONFIG_NAME); 881 listener.testLog(configOutputName, LogDataType.HARNESS_CONFIG, source); 882 } 883 } catch (IOException e) { 884 CLog.e(e); 885 } 886 } 887 888 /** 889 * Invoke {@link IInvocationExecution#fetchBuild(TestInformation, IConfiguration, IRescheduler, 890 * ITestInvocationListener)} and handles the output as well as failures. 891 * 892 * @param testInfo the {@link TestInformation} of the invocation. 893 * @param config the {@link IConfiguration} of this test run. 894 * @param rescheduler the {@link IRescheduler}, for rescheduling portions of the invocation for 895 * execution on another resource(s) 896 * @param listener the {@link ITestInvocation} to report build download failures. 897 * @param invocationPath the {@link IInvocationExecution} driving the invocation. 898 * @return True if we successfully downloaded the build, false otherwise. 899 */ invokeFetchBuild( TestInformation testInfo, IConfiguration config, IRescheduler rescheduler, ITestInvocationListener listener, IInvocationExecution invocationPath)900 private boolean invokeFetchBuild( 901 TestInformation testInfo, 902 IConfiguration config, 903 IRescheduler rescheduler, 904 ITestInvocationListener listener, 905 IInvocationExecution invocationPath) 906 throws Exception { 907 CurrentInvocation.setActionInProgress(ActionInProgress.FETCHING_ARTIFACTS); 908 Exception buildException = null; 909 boolean res = false; 910 try { 911 res = invocationPath.fetchBuild(testInfo, config, rescheduler, listener); 912 if (res) { 913 try (CloseableTraceScope ignored = 914 new CloseableTraceScope("wait_for_dynamic_download")) { 915 for (ExtendedFile file : mParallelDynamicDownloads) { 916 CLog.d("Wait for %s to finish downloading", file); 917 file.waitForDownload(); 918 } 919 } 920 // Successful fetch of build. 921 CurrentInvocation.setActionInProgress(ActionInProgress.UNSET); 922 return true; 923 } 924 // In case of build not found issues. 925 mStatus = "(no build to test)"; 926 // Set the exit code to error 927 buildException = 928 new BuildRetrievalError( 929 "No build found to test.", InfraErrorIdentifier.ARTIFACT_NOT_FOUND); 930 } catch (BuildRetrievalError | RuntimeException | DeviceNotAvailableException e) { 931 buildException = e; 932 } 933 for (ExtendedFile file : mParallelDynamicDownloads) { 934 file.cancelDownload(); 935 } 936 setExitCode(ExitCode.NO_BUILD, buildException); 937 // If somehow we don't have builds 938 if (testInfo.getContext().getBuildInfos().isEmpty()) { 939 InvocationMetricLogger.addInvocationMetrics( 940 InvocationMetricKey.BACKFILL_BUILD_INFO, "true"); 941 IBuildInfo info = backFillBuildInfoForReporting(config.getCommandLine()); 942 testInfo.getContext() 943 .addDeviceBuildInfo(testInfo.getContext().getDeviceConfigNames().get(0), info); 944 } 945 // Report an empty invocation, so this error is sent to listeners 946 startInvocation(config, testInfo.getContext(), listener); 947 reportFailure( 948 createFailureFromException(buildException, FailureStatus.INFRA_FAILURE), listener); 949 for (ITestDevice device : testInfo.getContext().getDevices()) { 950 invocationPath.reportLogs(device, listener, Stage.ERROR); 951 } 952 reportHostLog(listener, config); 953 reportInvocationEnded(config, testInfo.getContext(), listener, 0L); 954 CLog.e(buildException); 955 // We rethrow so it's caught in CommandScheduler and properly release 956 // the device 957 throw buildException; 958 } 959 960 /** 961 * Invoke {@link IConfiguration#resolveDynamicOptions(DynamicRemoteFileResolver)} to resolve the 962 * dynamic files. 963 * 964 * @param context the {@link IInvocationContext} of the invocation. 965 * @param config the {@link IConfiguration} of this test run. 966 * @param listener the {@link ITestInvocation} to report build download failures. 967 * @param invocationPath the {@link IInvocationExecution} driving the invocation. 968 * @param mode The current {@link RunMode} of the invocation. 969 * @return True if we successfully downloaded the build, false otherwise. 970 */ invokeRemoteDynamic( IInvocationContext context, IConfiguration config, ITestInvocationListener listener, IInvocationExecution invocationPath, RunMode mode)971 private boolean invokeRemoteDynamic( 972 IInvocationContext context, 973 IConfiguration config, 974 ITestInvocationListener listener, 975 IInvocationExecution invocationPath, 976 RunMode mode) 977 throws BuildRetrievalError, ConfigurationException { 978 DynamicRemoteFileResolver resolver = 979 new DynamicRemoteFileResolver(true /* allow parallelization */); 980 try { 981 // Don't resolve for remote invocation, wait until we are inside the remote. 982 if (RunMode.REMOTE_INVOCATION.equals(mode)) { 983 return true; 984 } 985 CurrentInvocation.setActionInProgress(ActionInProgress.FETCHING_ARTIFACTS); 986 resolver.setDevice(context.getDevices().get(0)); 987 resolver.addExtraArgs(config.getCommandOptions().getDynamicDownloadArgs()); 988 config.resolveDynamicOptions(resolver); 989 mParallelDynamicDownloads.addAll(resolver.getParallelDownloads()); 990 CurrentInvocation.setActionInProgress(ActionInProgress.UNSET); 991 return true; 992 } catch (RuntimeException | BuildRetrievalError | ConfigurationException e) { 993 // Cancel running downloads 994 for (ExtendedFile file : resolver.getParallelDownloads()) { 995 file.cancelDownload(); 996 } 997 // We don't have a reporting buildInfo at this point 998 IBuildInfo info = backFillBuildInfoForReporting(config.getCommandLine()); 999 1000 // In case of build not found issues. 1001 mStatus = "(failed dynamic download)"; 1002 // Set the exit code to error 1003 setExitCode(ExitCode.NO_BUILD, e); 1004 context.addDeviceBuildInfo(context.getDeviceConfigNames().get(0), info); 1005 1006 // Report an empty invocation, so this error is sent to listeners 1007 startInvocation(config, context, listener); 1008 reportFailure(createFailureFromException(e, FailureStatus.INFRA_FAILURE), listener); 1009 for (ITestDevice device : context.getDevices()) { 1010 invocationPath.reportLogs(device, listener, Stage.ERROR); 1011 } 1012 reportHostLog(listener, config); 1013 reportInvocationEnded(config, context, listener, 0L); 1014 // We rethrow so it's caught in CommandScheduler and properly release 1015 // the device 1016 throw e; 1017 } 1018 } 1019 1020 /** {@inheritDoc} */ 1021 @Override invoke( IInvocationContext context, IConfiguration config, IRescheduler rescheduler, ITestInvocationListener... extraListeners)1022 public void invoke( 1023 IInvocationContext context, 1024 IConfiguration config, 1025 IRescheduler rescheduler, 1026 ITestInvocationListener... extraListeners) 1027 throws DeviceNotAvailableException, Throwable { 1028 RunMode mode = RunMode.REGULAR; 1029 ITestInvocationListener listener = null; 1030 TestInformation info = null; 1031 ResultAggregator aggregator = null; 1032 CleanUpInvocationFiles cleanUpThread = null; 1033 try (CloseableTraceScope ignore = 1034 new CloseableTraceScope(InvocationMetricKey.invocation_warm_up.name())) { 1035 if (!config.getInopOptions().isEmpty()) { 1036 context.addInvocationAttribute( 1037 "inop-options", Joiner.on(",").join(config.getInopOptions())); 1038 } 1039 // Carry the reference of the server so it can be used within the same process. 1040 if (config.getConfigurationDescription() 1041 .getAllMetaData() 1042 .getUniqueMap() 1043 .containsKey(TradefedFeatureServer.SERVER_REFERENCE)) { 1044 InvocationMetricLogger.addInvocationMetrics( 1045 InvocationMetricKey.SERVER_REFERENCE, 1046 config.getConfigurationDescription() 1047 .getAllMetaData() 1048 .getUniqueMap() 1049 .get(TradefedFeatureServer.SERVER_REFERENCE)); 1050 } 1051 // Only log invocation_start in parent 1052 boolean isCurrentlySubprocess = isSubprocess(config); 1053 if (!isCurrentlySubprocess) { 1054 InvocationMetricLogger.addInvocationMetrics( 1055 InvocationMetricKey.INVOCATION_START, System.currentTimeMillis()); 1056 } else { 1057 CLog.d("Fetching options from parent."); 1058 // Get options from the parent process 1059 try (OptionFetcher fetchOptions = new OptionFetcher()) { 1060 fetchOptions.fetchParentOptions(config); 1061 } 1062 } 1063 // Handle the automated reporting 1064 applyAutomatedReporters(config); 1065 1066 if (config.getCommandOptions().delegatedEarlyDeviceRelease() 1067 && System.getenv(DelegatedInvocationExecution.DELEGATED_MODE_VAR) != null) { 1068 // If in a subprocess, add the early device release feature as a listener. 1069 mSchedulerListeners.add(new DeviceReleaseReporter()); 1070 } 1071 1072 for (ITestInvocationListener extra : extraListeners) { 1073 if (extra instanceof IScheduledInvocationListener) { 1074 mSchedulerListeners.add((IScheduledInvocationListener) extra); 1075 } 1076 } 1077 // Create the TestInformation for the invocation 1078 // TODO: Use invocation-id in the workfolder name 1079 Object sharedInfoObject = 1080 config.getConfigurationObject(ShardHelper.SHARED_TEST_INFORMATION); 1081 TestInformation sharedTestInfo = null; 1082 if (sharedInfoObject != null) { 1083 sharedTestInfo = (TestInformation) sharedInfoObject; 1084 // During sharding we share everything except the invocation context & properties 1085 info = TestInformation.createModuleTestInfo(sharedTestInfo, context); 1086 } 1087 if (info == null) { 1088 File mWorkFolder = FileUtil.createTempDir("tf-workfolder"); 1089 info = 1090 TestInformation.newBuilder() 1091 .setInvocationContext(context) 1092 .setDependenciesFolder(mWorkFolder) 1093 .build(); 1094 } 1095 // Register the test info to the configuration to be usable. 1096 config.setConfigurationObject(TradefedFeatureServer.TEST_INFORMATION_OBJECT, info); 1097 CurrentInvocation.addInvocationInfo( 1098 InvocationInfo.WORK_FOLDER, info.dependenciesFolder()); 1099 1100 cleanUpThread = new CleanUpInvocationFiles(info, config); 1101 Runtime.getRuntime().addShutdownHook(cleanUpThread); 1102 registerExecutionFiles(info.executionFiles()); 1103 1104 List<ITestInvocationListener> allListeners = new ArrayList<>(); 1105 // If it's not a subprocess, report the passed tests. 1106 ReportPassedTests reportPass = null; 1107 if (config.getConfigurationObject(TradefedDelegator.DELEGATE_OBJECT) == null 1108 && config.getCommandOptions().reportPassedTests() 1109 && !isSubprocess(config)) { 1110 reportPass = new ReportPassedTests(); 1111 reportPass.setConfiguration(config); 1112 allListeners.add(reportPass); 1113 } 1114 List<ITestInvocationListener> resultReporters = 1115 new ArrayList<ITestInvocationListener>(config.getTestInvocationListeners()); 1116 boolean disableReporter = 1117 resultReporters.removeIf( 1118 l -> ((l instanceof IDisableable) && ((IDisableable) l).isDisabled())); 1119 if (disableReporter) { 1120 CLog.d("Some reporters are disabled and won't be used."); 1121 } 1122 allListeners.addAll(resultReporters); 1123 allListeners.addAll(Arrays.asList(extraListeners)); 1124 allListeners.add(mUnavailableMonitor); 1125 allListeners.add(mConditionalFailureMonitor); 1126 1127 // Auto retry feature 1128 IRetryDecision decision = config.getRetryDecision(); 1129 decision.setInvocationContext(context); 1130 if (decision instanceof ITestInformationReceiver) { 1131 ((ITestInformationReceiver) decision).setTestInformation(info); 1132 } 1133 updateInvocationContext(context, config); 1134 CurrentInvocation.setInvocationContext(context); 1135 config.getLogSaver().init(context); 1136 // We don't need the aggregator in the subprocess because the parent will take care of 1137 // it. 1138 if (!config.getCommandOptions() 1139 .getInvocationData() 1140 .containsKey(SubprocessTfLauncher.SUBPROCESS_TAG_NAME)) { 1141 if (decision.isAutoRetryEnabled() 1142 && decision.getMaxRetryCount() > 1 1143 && !RetryStrategy.NO_RETRY.equals(decision.getRetryStrategy())) { 1144 CLog.d( 1145 "Auto-retry enabled, using the ResultAggregator to handle multiple" 1146 + " retries."); 1147 aggregator = new ResultAggregator(allListeners, decision.getRetryStrategy()); 1148 aggregator.setUpdatedReporting(decision.useUpdatedReporting()); 1149 allListeners = Arrays.asList(aggregator); 1150 } else { 1151 mEventsLogger = new EventsLoggerListener("all-events"); 1152 allListeners.add(mEventsLogger); 1153 } 1154 } 1155 1156 if (!config.getPostProcessors().isEmpty()) { 1157 ITestInvocationListener forwarder = new ResultAndLogForwarder(allListeners); 1158 // Post-processors are the first layer around the final reporters. 1159 for (IPostProcessor postProcessor : config.getPostProcessors()) { 1160 if (postProcessor.isDisabled()) { 1161 CLog.d("%s has been disabled. skipping.", postProcessor); 1162 } else { 1163 forwarder = postProcessor.init(forwarder); 1164 } 1165 } 1166 listener = 1167 new LogSaverResultForwarder(config.getLogSaver(), Arrays.asList(forwarder)); 1168 } else { 1169 listener = new LogSaverResultForwarder(config.getLogSaver(), allListeners); 1170 } 1171 if (reportPass != null) { 1172 reportPass.setLogger(listener); 1173 } 1174 1175 if (config.getConfigurationDescription().shouldUseSandbox()) { 1176 mode = RunMode.SANDBOX; 1177 } 1178 if (config.getCommandOptions().shouldUseSandboxing()) { 1179 mode = RunMode.PARENT_SANDBOX; 1180 } 1181 if (context.getDevices().get(0) instanceof ManagedRemoteDevice) { 1182 mode = RunMode.REMOTE_INVOCATION; 1183 } 1184 if (config.getConfigurationObject(TradefedDelegator.DELEGATE_OBJECT) != null) { 1185 mDelegatedInvocation = true; 1186 mode = RunMode.DELEGATED_INVOCATION; 1187 } 1188 } 1189 IInvocationExecution invocationPath = createInvocationExec(mode); 1190 1191 boolean sharding = false; 1192 try { 1193 ILeveledLogOutput leveledLogOutput = config.getLogOutput(); 1194 leveledLogOutput.init(); 1195 if (leveledLogOutput instanceof BaseLeveledLogOutput) { 1196 ((BaseLeveledLogOutput) leveledLogOutput).initFilters(config); 1197 } 1198 getLogRegistry().registerLogger(leveledLogOutput); 1199 1200 // Only in parent fetch demotion information 1201 config.getSkipManager().setup(config, context); 1202 1203 mStatus = "resolving dynamic options"; 1204 long startDynamic = System.currentTimeMillis(); 1205 boolean resolverSuccess = false; 1206 try (CloseableTraceScope ignored = 1207 new CloseableTraceScope(InvocationMetricKey.dynamic_download.name())) { 1208 resolverSuccess = 1209 invokeRemoteDynamic(context, config, listener, invocationPath, mode); 1210 } finally { 1211 // Do not report the pair for subprocess as it would be part 1212 // of a test specific setup instead. 1213 if (!isSubprocess(config)) { 1214 InvocationMetricLogger.addInvocationPairMetrics( 1215 InvocationMetricKey.DYNAMIC_FILE_RESOLVER_PAIR, 1216 startDynamic, 1217 System.currentTimeMillis()); 1218 } 1219 } 1220 if (!resolverSuccess) { 1221 return; 1222 } 1223 1224 mStatus = "fetching build"; 1225 String cmdLineArgs = config.getCommandLine(); 1226 if (cmdLineArgs != null) { 1227 CLog.i("Invocation was started with cmd: %s", cmdLineArgs); 1228 } 1229 1230 long start = System.currentTimeMillis(); 1231 InvocationMetricLogger.addInvocationMetrics( 1232 InvocationMetricKey.FETCH_BUILD_START, start); 1233 boolean providerSuccess = false; 1234 try (CloseableTraceScope ignored = 1235 new CloseableTraceScope(InvocationMetricKey.fetch_artifact.name())) { 1236 providerSuccess = 1237 invokeFetchBuild(info, config, rescheduler, listener, invocationPath); 1238 } finally { 1239 long end = System.currentTimeMillis(); 1240 InvocationMetricLogger.addInvocationMetrics( 1241 InvocationMetricKey.FETCH_BUILD_END, end); 1242 InvocationMetricLogger.addInvocationPairMetrics( 1243 InvocationMetricKey.FETCH_BUILD_PAIR, start, end); 1244 long fetchBuildDuration = end - start; 1245 InvocationMetricLogger.addInvocationMetrics( 1246 InvocationMetricKey.FETCH_BUILD, fetchBuildDuration); 1247 CLog.d("Fetch build duration: %s", TimeUtil.formatElapsedTime(fetchBuildDuration)); 1248 } 1249 if (!providerSuccess) { 1250 return; 1251 } 1252 // Skip invocation can only happen in the parent process and not in the parent 1253 // delegator. 1254 if (!config.getCommandOptions() 1255 .getInvocationData() 1256 .containsKey(SubprocessTfLauncher.SUBPROCESS_TAG_NAME) 1257 && !RunMode.DELEGATED_INVOCATION.equals(mode)) { 1258 if (config.getSkipManager().shouldSkipInvocation(info)) { 1259 CLog.d("Skipping invocation early."); 1260 startInvocation(config, info.getContext(), listener); 1261 // Backfill accounting metrics with zeros 1262 long timestamp = System.currentTimeMillis(); 1263 InvocationMetricLogger.addInvocationPairMetrics( 1264 InvocationMetricKey.TEST_SETUP_PAIR, timestamp, timestamp); 1265 InvocationMetricLogger.addInvocationMetrics(InvocationMetricKey.SETUP, 0); 1266 InvocationMetricLogger.addInvocationPairMetrics( 1267 InvocationMetricKey.SETUP_PAIR, timestamp, timestamp); 1268 InvocationMetricLogger.addInvocationMetrics( 1269 InvocationMetricKey.SETUP_START, timestamp); 1270 InvocationMetricLogger.addInvocationMetrics( 1271 InvocationMetricKey.SETUP_END, timestamp); 1272 InvocationMetricLogger.addInvocationPairMetrics( 1273 InvocationMetricKey.TEST_PAIR, timestamp, timestamp); 1274 InvocationMetricLogger.addInvocationPairMetrics( 1275 InvocationMetricKey.TEARDOWN_PAIR, timestamp, timestamp); 1276 InvocationMetricLogger.addInvocationPairMetrics( 1277 InvocationMetricKey.TEST_TEARDOWN_PAIR, timestamp, timestamp); 1278 listener.invocationSkipped( 1279 new SkipReason(config.getSkipManager().getInvocationSkipReason(), "")); 1280 reportHostLog(listener, config); 1281 reportInvocationEnded(config, info.getContext(), listener, 0L); 1282 return; 1283 } 1284 } 1285 try (CloseableTraceScope ignore = 1286 new CloseableTraceScope(InvocationMetricKey.start_logcat.name())) { 1287 for (String deviceName : context.getDeviceConfigNames()) { 1288 context.getDevice(deviceName).clearLastConnectedWifiNetwork(); 1289 // TODO: Report invocation error if setOptions() fails 1290 context.getDevice(deviceName) 1291 .setOptions( 1292 config.getDeviceConfigByName(deviceName).getDeviceOptions()); 1293 if (config.getDeviceConfigByName(deviceName) 1294 .getDeviceOptions() 1295 .isLogcatCaptureEnabled()) { 1296 if (!(context.getDevice(deviceName).getIDevice() instanceof StubDevice)) { 1297 context.getDevice(deviceName).startLogcat(); 1298 } 1299 } 1300 } 1301 } catch (RuntimeException e) { 1302 // Report an empty invocation, so this error is sent to listeners 1303 startInvocation(config, info.getContext(), listener); 1304 reportFailure(createFailureFromException(e, FailureStatus.INFRA_FAILURE), listener); 1305 for (ITestDevice device : info.getContext().getDevices()) { 1306 invocationPath.reportLogs(device, listener, Stage.ERROR); 1307 } 1308 reportHostLog(listener, config); 1309 reportInvocationEnded(config, info.getContext(), listener, 0L); 1310 return; 1311 } 1312 1313 // Apply global filters before sharding so they are taken into account. 1314 config.getGlobalFilters() 1315 .setUpFilters(config, config.getSkipManager().getDemotedTests().keySet()); 1316 boolean deviceInit = false; 1317 // If the top level invocation has --use-sandbox do not shard there. It will shard in 1318 // the child invocation. 1319 if (RunMode.REGULAR.equals(mode) || RunMode.SANDBOX.equals(mode)) { 1320 mStatus = "sharding"; 1321 1322 // TODO: Handle local sharding and special devices 1323 Integer shardCount = config.getCommandOptions().getShardCount(); 1324 Integer shardIndex = config.getCommandOptions().getShardIndex(); 1325 // Special Handling in case of sharding within the same invocation (in-place): Some 1326 // devices (Remote devices for example) require extra preparation step to be 1327 // available, but sharding requires the device to be available in some cases. So 1328 // we call the device setup early to meet all the requirements. 1329 boolean startInvocationCalled = false; 1330 if (shardCount != null && shardIndex != null) { 1331 try (CloseableTraceScope ignored = 1332 new CloseableTraceScope( 1333 InvocationMetricKey.pre_sharding_required_setup.name())) { 1334 deviceInit = true; 1335 startInvocation(config, context, listener); 1336 startInvocationCalled = true; 1337 invocationPath.runDevicePreInvocationSetup(context, config, listener); 1338 } catch (DeviceNotAvailableException | TargetSetupError e) { 1339 CLog.e(e); 1340 FailureDescription failure = FailureDescription.create(e.getMessage()); 1341 failure.setCause(e).setFailureStatus(FailureStatus.INFRA_FAILURE); 1342 if (e instanceof DeviceNotAvailableException) { 1343 setExitCode(ExitCode.DEVICE_UNAVAILABLE, e); 1344 } else { 1345 setExitCode(ExitCode.THROWABLE_EXCEPTION, e); 1346 } 1347 try { 1348 invocationPath.runDevicePostInvocationTearDown(context, config, e); 1349 } finally { 1350 reportFailure( 1351 createFailureFromException(e, FailureStatus.INFRA_FAILURE), 1352 listener); 1353 // Reports the logs 1354 for (ITestDevice device : context.getDevices()) { 1355 invocationPath.reportLogs(device, listener, Stage.ERROR); 1356 } 1357 reportHostLog(listener, config); 1358 reportInvocationEnded(config, context, listener, 0L); 1359 } 1360 return; 1361 } 1362 } 1363 1364 try (CloseableTraceScope ignored = 1365 new CloseableTraceScope(InvocationMetricKey.sharding.name())) { 1366 sharding = invocationPath.shardConfig(config, info, rescheduler, listener); 1367 } catch (RuntimeException unexpected) { 1368 CLog.e("Exception during sharding."); 1369 CLog.e(unexpected); 1370 if (deviceInit) { 1371 // If we did an early setup, do the tear down. 1372 invocationPath.runDevicePostInvocationTearDown(context, config, unexpected); 1373 } 1374 // Call the reporting to get debugging infos. 1375 if (!startInvocationCalled) { 1376 startInvocation(config, context, listener); 1377 } 1378 reportFailure( 1379 createFailureFromException(unexpected, FailureStatus.INFRA_FAILURE) 1380 .setActionInProgress(ActionInProgress.TEST), 1381 listener); 1382 reportHostLog(listener, config); 1383 listener.invocationEnded(0L); 1384 return; 1385 } 1386 if (sharding) { 1387 CLog.i( 1388 "Invocation for %s has been sharded, rescheduling", 1389 context.getSerials()); 1390 // Log the chunk of parent host_log before sharding 1391 reportHostLog(listener, config, TRADEFED_LOG_NAME + BEFORE_SHARDING_SUFFIX); 1392 logExpandedConfiguration(config, listener, mode, true); 1393 config.getLogSaver().invocationEnded(0L); 1394 if (aggregator != null) { 1395 // The host_log is not available yet to reporters that don't support 1396 // granular results, so forward it. 1397 aggregator.forwardAggregatedInvocationLogs(); 1398 aggregator.cleanEventsFiles(); 1399 } 1400 return; 1401 } 1402 } 1403 // Once we have all the information we can start the invocation. 1404 if (!deviceInit) { 1405 try (CloseableTraceScope s = new CloseableTraceScope("startInvocation")) { 1406 startInvocation(config, context, listener); 1407 } 1408 } 1409 if (!RunMode.DELEGATED_INVOCATION.equals(mode) 1410 && (config.getTests() == null || config.getTests().isEmpty())) { 1411 CLog.e("No tests to run"); 1412 if (deviceInit) { 1413 // If we did an early setup, do the tear down. 1414 invocationPath.runDevicePostInvocationTearDown(context, config, null); 1415 } 1416 if (mEventsLogger != null) { 1417 logEventsFile(mEventsLogger.getLoggedEvents(), listener); 1418 } 1419 listener.invocationEnded(0L); 1420 return; 1421 } 1422 1423 performInvocation(config, info, invocationPath, listener, deviceInit); 1424 setExitCode(ExitCode.NO_ERROR, null); 1425 } catch (IOException e) { 1426 CLog.e(e); 1427 } finally { 1428 TfObjectTracker.clearTracking(); 1429 CurrentInvocation.clearInvocationInfos(); 1430 config.getSkipManager().clearManager(); 1431 // Ensure build infos are always cleaned up at the end of invocation. 1432 CLog.i("Cleaning up builds"); 1433 invocationPath.cleanUpBuilds(context, config); 1434 if (!sharding) { 1435 // If we are the parent shard, we do not delete the test information 1436 deleteInvocationFiles(info, config); 1437 } 1438 1439 if (!config.getCommandOptions().reportInvocationComplete()) { 1440 // save remaining logs contents to global log 1441 getLogRegistry().dumpToGlobalLog(config.getLogOutput()); 1442 // Ensure log is unregistered and closed 1443 getLogRegistry().unregisterLogger(); 1444 config.getLogOutput().closeLog(); 1445 } 1446 1447 config.cleanConfigurationData(); 1448 if (cleanUpThread != null) { 1449 Runtime.getRuntime().removeShutdownHook(cleanUpThread); 1450 } 1451 } 1452 } 1453 1454 @VisibleForTesting registerExecutionFiles(ExecutionFiles executionFiles)1455 public void registerExecutionFiles(ExecutionFiles executionFiles) { 1456 CurrentInvocation.registerExecutionFiles(executionFiles); 1457 } 1458 1459 /** 1460 * Helper to set the exit code. Exposed for testing. 1461 */ setExitCode(ExitCode code, Throwable stack)1462 protected void setExitCode(ExitCode code, Throwable stack) { 1463 mExitCode = code; 1464 mExitStack = stack; 1465 } 1466 addInvocationMetric(InvocationMetricKey key, long value)1467 protected void addInvocationMetric(InvocationMetricKey key, long value) { 1468 InvocationMetricLogger.addInvocationMetrics(key, value); 1469 } 1470 addInvocationMetric(InvocationMetricKey key, String value)1471 protected void addInvocationMetric(InvocationMetricKey key, String value) { 1472 InvocationMetricLogger.addInvocationMetrics(key, value); 1473 } 1474 getDeviceLogName(Stage stage)1475 public static String getDeviceLogName(Stage stage) { 1476 return DEVICE_LOG_NAME_PREFIX + stage.getName(); 1477 } 1478 getEmulatorLogName(Stage stage)1479 public static String getEmulatorLogName(Stage stage) { 1480 return EMULATOR_LOG_NAME_PREFIX + stage.getName(); 1481 } 1482 1483 @Override notifyInvocationForceStopped(String message, ErrorIdentifier errorId)1484 public void notifyInvocationForceStopped(String message, ErrorIdentifier errorId) { 1485 mStopCause = message; 1486 mStopErrorId = errorId; 1487 if (mStopRequestTime == null) { 1488 mStopRequestTime = System.currentTimeMillis(); 1489 mForcedStopRequestedAfterTest = mTestDone; 1490 // If test isn't started yet, we know we can stop 1491 mShutdownBeforeTest = !mTestStarted; 1492 } 1493 } 1494 1495 @Override notifyInvocationStopped(String message)1496 public void notifyInvocationStopped(String message) { 1497 if (mSoftStopRequestTime == null) { 1498 mSoftStopRequestTime = System.currentTimeMillis(); 1499 // If test isn't started yet, we know we can stop 1500 mShutdownBeforeTest = !mTestStarted; 1501 } 1502 } 1503 1504 /** 1505 * Create the invocation path that should be followed. 1506 * 1507 * @param mode The mode we are currently running as. 1508 * @return The {@link IInvocationExecution} describing the invocation. 1509 */ createInvocationExec(RunMode mode)1510 public IInvocationExecution createInvocationExec(RunMode mode) { 1511 switch (mode) { 1512 case PARENT_SANDBOX: 1513 return new ParentSandboxInvocationExecution(); 1514 case SANDBOX: 1515 return new SandboxedInvocationExecution(); 1516 case REMOTE_INVOCATION: 1517 mIsRemoteInvocation = true; 1518 return new RemoteInvocationExecution(); 1519 case DELEGATED_INVOCATION: 1520 return new DelegatedInvocationExecution(); 1521 default: 1522 return new InvocationExecution(); 1523 } 1524 } 1525 1526 /** Prints a delimiter for a given Stage of the invocation. */ printStageDelimiter(Stage phase, boolean end)1527 public static void printStageDelimiter(Stage phase, boolean end) { 1528 String startEnd = end ? "ENDING" : "STARTING"; 1529 String message = String.format("===== %s PHASE %s =====", phase, startEnd); 1530 PrettyPrintDelimiter.printStageDelimiter(message); 1531 } 1532 1533 @VisibleForTesting applyAutomatedReporters(IConfiguration config)1534 protected void applyAutomatedReporters(IConfiguration config) { 1535 AutomatedReporters autoReport = new AutomatedReporters(); 1536 autoReport.applyAutomatedReporters(config); 1537 } 1538 logExecuteShellCommand(List<ITestDevice> devices, ITestLogger logger)1539 private void logExecuteShellCommand(List<ITestDevice> devices, ITestLogger logger) { 1540 for (ITestDevice device : devices) { 1541 if (device.getIDevice() instanceof StubDevice) { 1542 continue; 1543 } 1544 if (!(device instanceof NativeDevice)) { 1545 continue; 1546 } 1547 File log = ((NativeDevice) device).getExecuteShellCommandLog(); 1548 if (log == null || !log.exists()) { 1549 continue; 1550 } 1551 if (log.length() == 0) { 1552 CLog.d("executeShellCommandLog file was empty, skip logging."); 1553 continue; 1554 } 1555 try (InputStreamSource source = new FileInputStreamSource(log)) { 1556 logger.testLog( 1557 String.format("executeShellCommandLog_%s", device.getSerialNumber()), 1558 LogDataType.TEXT, 1559 source); 1560 } 1561 } 1562 } 1563 logEventsFile(File eventsLog, ITestLogger logger)1564 private void logEventsFile(File eventsLog, ITestLogger logger) { 1565 if (eventsLog != null && eventsLog.length() > 0) { 1566 try (FileInputStreamSource source = new FileInputStreamSource(eventsLog, true)) { 1567 logger.testLog("event-logs", LogDataType.TF_EVENTS, source); 1568 } 1569 } 1570 FileUtil.deleteFile(eventsLog); 1571 } 1572 1573 /** 1574 * Update the {@link IInvocationContext} with additional info from the {@link IConfiguration}. 1575 * 1576 * @param context the {@link IInvocationContext} 1577 * @param config the {@link IConfiguration} 1578 */ updateInvocationContext(IInvocationContext context, IConfiguration config)1579 private void updateInvocationContext(IInvocationContext context, IConfiguration config) { 1580 context.setTestTag(getTestTag(config)); 1581 if (config.getCommandOptions().getInvocationData().containsKey("subprocess")) { 1582 // Avoid relogging the properties in a subprocess 1583 return; 1584 } 1585 if (config.getCommandLine() != null) { 1586 context.addInvocationAttribute( 1587 TestInvocation.COMMAND_ARGS_KEY, config.getCommandLine()); 1588 } 1589 if (config.getCommandOptions().getShardCount() != null) { 1590 context.addInvocationAttribute( 1591 "shard_count", config.getCommandOptions().getShardCount().toString()); 1592 } 1593 if (config.getCommandOptions().getShardIndex() != null) { 1594 context.addInvocationAttribute( 1595 "shard_index", config.getCommandOptions().getShardIndex().toString()); 1596 } 1597 // add Invocation level external dependencies 1598 Set<ExternalDependency> externalDependencies = new LinkedHashSet<>(); 1599 for (IDeviceConfiguration deviceConfig : config.getDeviceConfig()) { 1600 for (Object obj : deviceConfig.getAllObjects()) { 1601 if (obj instanceof IExternalDependency) { 1602 externalDependencies.addAll(((IExternalDependency) obj).getDependencies()); 1603 } 1604 } 1605 } 1606 if (!externalDependencies.isEmpty()) { 1607 List<String> dependencyClassNames = 1608 externalDependencies.stream() 1609 .map(dependency -> dependency.getClass().getName()) 1610 .collect(Collectors.toList()); 1611 context.addInvocationAttribute( 1612 INVOCATION_EXTERNAL_DEPENDENCIES, String.join(", ", dependencyClassNames)); 1613 } 1614 } 1615 1616 /** Helper to create the test tag from the configuration. */ getTestTag(IConfiguration config)1617 private String getTestTag(IConfiguration config) { 1618 String testTag = config.getCommandOptions().getTestTag(); 1619 if (config.getCommandOptions().getTestTagSuffix() != null) { 1620 testTag = 1621 String.format("%s-%s", testTag, config.getCommandOptions().getTestTagSuffix()); 1622 } 1623 return testTag; 1624 } 1625 1626 /** 1627 * Delete the invocation files if this is the last shard for local sharding or if we are not in 1628 * a local sharding situation. 1629 */ deleteInvocationFiles(TestInformation testInfo, IConfiguration config)1630 private void deleteInvocationFiles(TestInformation testInfo, IConfiguration config) { 1631 Object obj = config.getConfigurationObject(ShardHelper.LAST_SHARD_DETECTOR); 1632 if (obj != null) { 1633 LastShardDetector lastShardDetector = (LastShardDetector) obj; 1634 if (!lastShardDetector.isLastShardDone()) { 1635 return; 1636 } 1637 } 1638 // Delete the invocation work directory at the end 1639 FileUtil.recursiveDelete(testInfo.dependenciesFolder()); 1640 // Delete all the execution files 1641 testInfo.executionFiles().clearFiles(); 1642 } 1643 handleAndLogReleaseState( IInvocationContext context, Throwable exception, Throwable tearDownException)1644 private Map<ITestDevice, FreeDeviceState> handleAndLogReleaseState( 1645 IInvocationContext context, Throwable exception, Throwable tearDownException) { 1646 if (exception == null && tearDownException != null) { 1647 exception = tearDownException; 1648 } else if (tearDownException instanceof DeviceNotAvailableException) { 1649 // Use what we consider a later & higher priority error 1650 exception = tearDownException; 1651 } 1652 // Capture the FreeDeviceState of the primary device 1653 Map<ITestDevice, FreeDeviceState> devicesStates = 1654 CommandScheduler.createReleaseMap(context, exception); 1655 if (devicesStates.size() >= 1) { 1656 addInvocationMetric( 1657 InvocationMetricKey.DEVICE_RELEASE_STATE, 1658 devicesStates.values().iterator().next().toString()); 1659 } 1660 int countPhysicalLost = 0; 1661 int countVirtualLost = 0; 1662 for (Entry<ITestDevice, FreeDeviceState> fds : devicesStates.entrySet()) { 1663 // TODO: Rely on the FailureStatus for lost devices instead 1664 if ((fds.getKey().getIDevice() instanceof RemoteAvdIDevice 1665 || fds.getKey().getIDevice() instanceof StubLocalAndroidVirtualDevice) 1666 && exception instanceof DeviceNotAvailableException) { 1667 countVirtualLost++; 1668 continue; 1669 } 1670 if (fds.getKey().getIDevice() instanceof StubDevice) { 1671 continue; 1672 } 1673 if (FreeDeviceState.UNAVAILABLE.equals(fds.getValue()) 1674 || FreeDeviceState.UNRESPONSIVE.equals(fds.getValue())) { 1675 // Remote devices are not seen as stub, but are still virtual devices 1676 if (fds.getKey() instanceof RemoteAndroidDevice 1677 || fds.getKey() instanceof NestedRemoteDevice) { 1678 countVirtualLost++; 1679 } else { 1680 countPhysicalLost++; 1681 } 1682 } 1683 } 1684 if (countPhysicalLost > 0) { 1685 addInvocationMetric(InvocationMetricKey.DEVICE_LOST_DETECTED, countPhysicalLost); 1686 if (GlobalConfiguration.getDeviceManagerInstance() instanceof DeviceManager) { 1687 String adbOutput = 1688 ((DeviceManager) GlobalConfiguration.getDeviceManagerInstance()) 1689 .executeGlobalAdbCommand("devices"); 1690 CLog.e("'adb devices' output:\n%s", adbOutput); 1691 1692 CommandResult fastbootResult = 1693 getRunUtil() 1694 .runTimedCmdSilently( 1695 60000L, 1696 GlobalConfiguration.getDeviceManagerInstance() 1697 .getFastbootPath(), 1698 "devices"); 1699 CLog.d("'fastboot devices' output:\n%s", fastbootResult.getStdout()); 1700 1701 CommandResult lsusbResult = 1702 getRunUtil() 1703 .runTimedCmdSilently( 1704 60000L, "lsusb", "-d", GOOGLE_USB_VENDOR_ID + ":"); 1705 CLog.d("'lsusb -d %s:' output:\n%s", GOOGLE_USB_VENDOR_ID, lsusbResult.getStdout()); 1706 } 1707 } else if (countVirtualLost > 0) { 1708 CLog.e("Counting as virtual_device_lost."); 1709 addInvocationMetric(InvocationMetricKey.VIRTUAL_DEVICE_LOST_DETECTED, countVirtualLost); 1710 } 1711 return devicesStates; 1712 } 1713 reportRecoveryLogs(List<ITestDevice> devices, ITestInvocationListener listener)1714 private void reportRecoveryLogs(List<ITestDevice> devices, ITestInvocationListener listener) { 1715 for (ITestDevice device : devices) { 1716 if (device == null) { 1717 continue; 1718 } 1719 if (device.getIDevice() instanceof StubDevice) { 1720 continue; 1721 } 1722 if (device.getDeviceState() != TestDeviceState.RECOVERY) { 1723 continue; 1724 } 1725 InvocationMetricLogger.addInvocationMetrics( 1726 InvocationMetricKey.ATTEMPT_RECOVERY_LOG_COUNT, 1); 1727 RecoveryMode mode = device.getRecoveryMode(); 1728 try { 1729 device.setRecoveryMode(RecoveryMode.NONE); 1730 // We need root to access the recovery logs so attempt to set it 1731 String output = device.executeAdbCommand("root"); 1732 CLog.d("adb recovery root output: %s", output); 1733 File recovery_log = device.pullFile(RECOVERY_LOG_DEVICE_PATH); 1734 if (recovery_log == null) { 1735 return; 1736 } 1737 try (FileInputStreamSource fis = new FileInputStreamSource(recovery_log)) { 1738 listener.testLog( 1739 String.format("recovery_log_%s.txt", device.getSerialNumber()), 1740 LogDataType.RECOVERY_MODE_LOG, 1741 fis); 1742 } 1743 } catch (DeviceNotAvailableException e) { 1744 CLog.i("Device unavailable, can't pull recovery.log"); 1745 } finally { 1746 device.setRecoveryMode(mode); 1747 } 1748 } 1749 } 1750 reportInvocationEnded( IConfiguration config, IInvocationContext context, ITestInvocationListener listener, long elapsedTime)1751 private void reportInvocationEnded( 1752 IConfiguration config, 1753 IInvocationContext context, 1754 ITestInvocationListener listener, 1755 long elapsedTime) { 1756 // Only log Invocation ended in parent 1757 if (mIsRemoteInvocation || !isSubprocess(config)) { 1758 InvocationMetricLogger.addInvocationMetrics( 1759 InvocationMetricKey.INVOCATION_END, System.currentTimeMillis()); 1760 } 1761 // Init a log for the end of the host_log. 1762 ILeveledLogOutput endHostLog = config.getLogOutput(); 1763 try { 1764 endHostLog.init(); 1765 getLogRegistry().registerLogger(endHostLog); 1766 } catch (IOException e) { 1767 CLog.e(e); 1768 endHostLog = null; 1769 } 1770 1771 PrettyPrintDelimiter.printStageDelimiter("===== Result Reporters ====="); 1772 try { 1773 // Copy the invocation metrics to the context 1774 ((InvocationContext) context).logInvocationMetrics(); 1775 if (mEventsLogger != null) { 1776 logEventsFile(mEventsLogger.getLoggedEvents(), listener); 1777 } 1778 listener.invocationEnded(elapsedTime); 1779 } finally { 1780 InvocationMetricLogger.clearInvocationMetrics(); 1781 if (endHostLog != null) { 1782 endHostLog.closeLog(); 1783 getLogRegistry().unregisterLogger(); 1784 } 1785 } 1786 if (!config.getCommandOptions().reportInvocationComplete()) { 1787 return; 1788 } 1789 if (config.getCommandOptions().getInvocationData().containsKey("subprocess")) { 1790 config.getCommandOptions().setReportInvocationComplete(false); 1791 return; 1792 } 1793 // Re-init for invocationComplete logs 1794 try { 1795 endHostLog.init(); 1796 getLogRegistry().registerLogger(endHostLog); 1797 } catch (IOException e) { 1798 CLog.e(e); 1799 config.getCommandOptions().setReportInvocationComplete(false); 1800 } 1801 } 1802 bareMinimumResponsiveness(List<ITestDevice> devices)1803 private DeviceNotAvailableException bareMinimumResponsiveness(List<ITestDevice> devices) { 1804 for (ITestDevice device : devices) { 1805 if (device == null) { 1806 continue; 1807 } 1808 if (device.getIDevice() instanceof StubDevice) { 1809 continue; 1810 } 1811 if (device.isStateBootloaderOrFastbootd()) { 1812 return null; 1813 } 1814 if (TestDeviceState.RECOVERY.equals(device.getDeviceState())) { 1815 return null; 1816 } 1817 RecoveryMode current = device.getRecoveryMode(); 1818 device.setRecoveryMode(RecoveryMode.NONE); 1819 CLog.d("Testing minimum responsiveness."); 1820 try { 1821 if (device instanceof NativeDevice) { 1822 ((NativeDevice) device).invalidatePropertyCache(); 1823 } 1824 device.waitForDeviceOnline(60000L); 1825 device.getApiLevel(); 1826 } catch (DeviceNotAvailableException e) { 1827 return e; 1828 } finally { 1829 device.setRecoveryMode(current); 1830 } 1831 } 1832 return null; 1833 } 1834 1835 /** 1836 * If no previous exception occurred, report if the device is not available anymore after tests 1837 * finish running. 1838 */ checkDevicesAvailable( List<ITestDevice> devices, ITestInvocationListener listener)1839 private DeviceNotAvailableException checkDevicesAvailable( 1840 List<ITestDevice> devices, ITestInvocationListener listener) { 1841 DeviceNotAvailableException dnae = null; 1842 for (ITestDevice device : devices) { 1843 if (device == null) { 1844 continue; 1845 } 1846 if (device.getIDevice() instanceof StubDevice) { 1847 continue; 1848 } 1849 if (device.isStateBootloaderOrFastbootd()) { 1850 dnae = 1851 new DeviceNotAvailableException( 1852 "Device was left in fastboot state after tests", 1853 device.getSerialNumber(), 1854 DeviceErrorIdentifier.DEVICE_UNAVAILABLE); 1855 reportFailure( 1856 createFailureFromException(dnae, FailureStatus.INFRA_FAILURE), listener); 1857 continue; 1858 } 1859 if (TestDeviceState.RECOVERY.equals(device.getDeviceState())) { 1860 dnae = 1861 new DeviceNotAvailableException( 1862 "Device was left in recovery state after tests", 1863 device.getSerialNumber(), 1864 DeviceErrorIdentifier.DEVICE_UNAVAILABLE); 1865 reportFailure( 1866 createFailureFromException(dnae, FailureStatus.INFRA_FAILURE), listener); 1867 continue; 1868 } 1869 RecoveryMode current = device.getRecoveryMode(); 1870 device.setRecoveryMode(RecoveryMode.NONE); 1871 try { 1872 // Cap availability check at 3 minutes instead of the device 1873 // configured one because this is not tied to a reboot, we just 1874 // need the device to be still online & reporting. 1875 boolean available = device.waitForDeviceAvailable(AVAILABILITY_CHECK_TIMEOUT); 1876 if (!available) { 1877 throw new DeviceNotAvailableException( 1878 String.format( 1879 "Device %s failed availability check after running tests.", 1880 device.getSerialNumber()), 1881 device.getSerialNumber(), 1882 DeviceErrorIdentifier.DEVICE_UNAVAILABLE); 1883 } 1884 } catch (DeviceNotAvailableException e) { 1885 String msg = 1886 String.format("Device was left offline after tests: %s", e.getMessage()); 1887 DeviceNotAvailableException wrap = 1888 new DeviceNotAvailableException(msg, e, e.getSerial(), e.getErrorId()); 1889 reportFailure( 1890 createFailureFromException(wrap, FailureStatus.INFRA_FAILURE), listener); 1891 dnae = e; 1892 } finally { 1893 device.setRecoveryMode(current); 1894 } 1895 } 1896 return dnae; 1897 } 1898 1899 /** 1900 * Helper that use the command line to backfill a {@link IBuildInfo} for reporting in case of 1901 * download failure. 1902 */ backFillBuildInfoForReporting(String commandLine)1903 public static IBuildInfo backFillBuildInfoForReporting(String commandLine) { 1904 IBuildInfo info = new BuildInfo(); 1905 CommandLineBuildInfoBuilder builder = new CommandLineBuildInfoBuilder(); 1906 try { 1907 List<String> command = 1908 new ArrayList<>( 1909 Arrays.asList( 1910 QuotationAwareTokenizer.tokenizeLine(commandLine, false))); 1911 command.remove(0); 1912 ArgsOptionParser parser = new ArgsOptionParser(builder); 1913 parser.parseBestEffort(command, true); 1914 info = builder.createBuild(); 1915 } catch (ConfigurationException ignore) { 1916 CLog.e(ignore); 1917 } 1918 return info; 1919 } 1920 1921 /** Helper Thread that ensures host_log is reported in case of killed JVM */ 1922 private class ReportHostLog extends Thread { 1923 1924 private ITestInvocationListener mListener; 1925 private IConfiguration mConfiguration; 1926 ReportHostLog(ITestInvocationListener listener, IConfiguration config)1927 public ReportHostLog(ITestInvocationListener listener, IConfiguration config) { 1928 mListener = listener; 1929 mConfiguration = config; 1930 } 1931 1932 @Override run()1933 public void run() { 1934 // Report all the logs that always be reported anyway. 1935 reportHostLog(mListener, mConfiguration); 1936 } 1937 } 1938 1939 /** Helper Thread to ensure invocation files are deleted in case of killed JVM */ 1940 private class CleanUpInvocationFiles extends Thread { 1941 1942 private TestInformation mTestInfo; 1943 private IConfiguration mConfig; 1944 CleanUpInvocationFiles(TestInformation currentInfo, IConfiguration config)1945 public CleanUpInvocationFiles(TestInformation currentInfo, IConfiguration config) { 1946 mTestInfo = currentInfo; 1947 mConfig = config; 1948 } 1949 1950 @Override run()1951 public void run() { 1952 deleteInvocationFiles(mTestInfo, mConfig); 1953 } 1954 } 1955 1956 /** Measure the size of the work folder. */ measureWorkFolderSize(IConfiguration config, TestInformation testInfo)1957 private Long measureWorkFolderSize(IConfiguration config, TestInformation testInfo) { 1958 if (testInfo == null) { 1959 return null; 1960 } 1961 File workFolder = testInfo.dependenciesFolder(); 1962 CLog.d("Measuring size of %s", workFolder); 1963 if (workFolder == null || !workFolder.exists()) { 1964 return null; 1965 } 1966 // Only measure in parent process 1967 if (isSubprocess(config)) { 1968 CLog.d("Skip measuring size since we are in subprocess"); 1969 return null; 1970 } 1971 1972 Object obj = config.getConfigurationObject(ShardHelper.LAST_SHARD_DETECTOR); 1973 if (obj != null) { 1974 LastShardDetector lastShardDetector = (LastShardDetector) obj; 1975 if (!lastShardDetector.isLastShardDone()) { 1976 return null; 1977 } 1978 } 1979 return FileUtil.sizeOfDirectory(workFolder); 1980 } 1981 1982 @Override getExitInfo()1983 public ExitInformation getExitInfo() { 1984 ExitInformation info = new ExitInformation(); 1985 info.mExitCode = this.mExitCode; 1986 info.mStack = this.mExitStack; 1987 return info; 1988 } 1989 1990 @Override setClearcutClient(ClearcutClient client)1991 public void setClearcutClient(ClearcutClient client) { 1992 mClient = client; 1993 } 1994 1995 /** Always complete snapuserd before proceeding into test. */ waitForSnapuserd( TestInformation testInfo, IConfiguration config, SnapuserdWaitPhase currentPhase)1996 private void waitForSnapuserd( 1997 TestInformation testInfo, IConfiguration config, SnapuserdWaitPhase currentPhase) 1998 throws DeviceNotAvailableException { 1999 for (ITestDevice device : testInfo.getDevices()) { 2000 if (device instanceof StubDevice) { 2001 continue; 2002 } 2003 device.waitForSnapuserd(currentPhase); // Should be inop if not waiting on any updates. 2004 } 2005 } 2006 2007 /** Returns true if the invocation is currently within a subprocess scope. */ isSubprocess(IConfiguration config)2008 public static boolean isSubprocess(IConfiguration config) { 2009 if (System.getenv(DelegatedInvocationExecution.DELEGATED_MODE_VAR) != null) { 2010 return true; 2011 } 2012 return config.getCommandOptions() 2013 .getInvocationData() 2014 .containsKey(SubprocessTfLauncher.SUBPROCESS_TAG_NAME); 2015 } 2016 2017 /** Helper method that identifies errors when the bugreport should be skipped */ shouldSkipBugreportError(@ullable Throwable t)2018 public static boolean shouldSkipBugreportError(@Nullable Throwable t) { 2019 if (t == null) { 2020 return false; 2021 } 2022 2023 if (!(t instanceof HarnessException)) { 2024 return false; 2025 } 2026 2027 HarnessException e = (HarnessException) t; 2028 2029 if (e.getErrorId() == null) { 2030 // Can't tell, better take a bugreport just in case. 2031 return false; 2032 } 2033 2034 long errorId = e.getErrorId().code(); 2035 2036 // Configuration Errors 2037 if (errorId >= 505_250 && errorId < 505_300) { 2038 return true; 2039 } 2040 2041 // Artifact Errors 2042 if (errorId >= 500_501 && errorId < 501_000) { 2043 return true; 2044 } 2045 2046 // Certain General Errors 2047 if (errorId == 500_501 2048 || errorId == 500_003 2049 || errorId == 500_008 2050 || errorId == 500_009 2051 || errorId == 500_010 2052 || errorId == 500_013 2053 || errorId == 500_014 2054 || errorId == 500_017) { 2055 return true; 2056 } 2057 2058 return false; 2059 } 2060 } 2061