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