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.BuildRetrievalError; 20 import com.android.tradefed.build.IBuildInfo; 21 import com.android.tradefed.command.CommandRunner.ExitCode; 22 import com.android.tradefed.config.GlobalConfiguration; 23 import com.android.tradefed.config.IConfiguration; 24 import com.android.tradefed.device.DeviceNotAvailableException; 25 import com.android.tradefed.device.DeviceUnresponsiveException; 26 import com.android.tradefed.device.ITestDevice; 27 import com.android.tradefed.device.ITestDevice.RecoveryMode; 28 import com.android.tradefed.device.NativeDevice; 29 import com.android.tradefed.device.StubDevice; 30 import com.android.tradefed.device.TestDeviceState; 31 import com.android.tradefed.device.cloud.ManagedRemoteDevice; 32 import com.android.tradefed.device.cloud.NestedRemoteDevice; 33 import com.android.tradefed.device.cloud.RemoteAndroidVirtualDevice; 34 import com.android.tradefed.guice.InvocationScope; 35 import com.android.tradefed.invoker.sandbox.ParentSandboxInvocationExecution; 36 import com.android.tradefed.invoker.sandbox.SandboxedInvocationExecution; 37 import com.android.tradefed.invoker.shard.ShardBuildCloner; 38 import com.android.tradefed.log.BaseLeveledLogOutput; 39 import com.android.tradefed.log.ILeveledLogOutput; 40 import com.android.tradefed.log.ILogRegistry; 41 import com.android.tradefed.log.ITestLogger; 42 import com.android.tradefed.log.LogRegistry; 43 import com.android.tradefed.log.LogUtil.CLog; 44 import com.android.tradefed.postprocessor.IPostProcessor; 45 import com.android.tradefed.result.FileInputStreamSource; 46 import com.android.tradefed.result.ITestInvocationListener; 47 import com.android.tradefed.result.InputStreamSource; 48 import com.android.tradefed.result.LogDataType; 49 import com.android.tradefed.result.LogSaverResultForwarder; 50 import com.android.tradefed.result.ResultAndLogForwarder; 51 import com.android.tradefed.result.ResultForwarder; 52 import com.android.tradefed.targetprep.BuildError; 53 import com.android.tradefed.targetprep.DeviceFailedToBootError; 54 import com.android.tradefed.targetprep.TargetSetupError; 55 import com.android.tradefed.testtype.IRemoteTest; 56 import com.android.tradefed.testtype.IResumableTest; 57 import com.android.tradefed.testtype.IRetriableTest; 58 import com.android.tradefed.util.FileUtil; 59 import com.android.tradefed.util.IRunUtil; 60 import com.android.tradefed.util.PrettyPrintDelimiter; 61 import com.android.tradefed.util.RunInterruptedException; 62 import com.android.tradefed.util.RunUtil; 63 import com.android.tradefed.util.TimeUtil; 64 65 import com.google.common.annotations.VisibleForTesting; 66 67 import java.io.File; 68 import java.io.IOException; 69 import java.util.ArrayList; 70 import java.util.Arrays; 71 import java.util.List; 72 import java.util.Map.Entry; 73 74 /** 75 * Default implementation of {@link ITestInvocation}. 76 * <p/> 77 * Loads major objects based on {@link IConfiguration} 78 * - retrieves build 79 * - prepares target 80 * - runs tests 81 * - reports results 82 */ 83 public class TestInvocation implements ITestInvocation { 84 85 /** Key of the command line args attributes */ 86 public static final String COMMAND_ARGS_KEY = "command_line_args"; 87 88 /** 89 * Format of the key in {@link IBuildInfo} to log the battery level for each step of the 90 * invocation. (Setup, test, tear down). 91 */ 92 private static final String BATTERY_ATTRIBUTE_FORMAT_KEY = "%s-battery-%s"; 93 94 static final String TRADEFED_LOG_NAME = "host_log"; 95 /** Suffix used on host_log for the part before sharding occurs. */ 96 static final String BEFORE_SHARDING_SUFFIX = "_before_sharding"; 97 static final String DEVICE_LOG_NAME_PREFIX = "device_logcat_"; 98 static final String EMULATOR_LOG_NAME_PREFIX = "emulator_log_"; 99 static final String BUILD_ERROR_BUGREPORT_NAME = "build_error_bugreport"; 100 static final String DEVICE_UNRESPONSIVE_BUGREPORT_NAME = "device_unresponsive_bugreport"; 101 static final String INVOCATION_ENDED_BUGREPORT_NAME = "invocation_ended_bugreport"; 102 static final String TARGET_SETUP_ERROR_BUGREPORT_NAME = "target_setup_error_bugreport"; 103 static final String BATT_TAG = "[battery level]"; 104 105 public enum Stage { 106 ERROR("error"), 107 SETUP("setup"), 108 TEST("test"), 109 TEARDOWN("teardown"); 110 111 private final String mName; 112 Stage(String name)113 Stage(String name) { 114 mName = name; 115 } 116 getName()117 public String getName() { 118 return mName; 119 } 120 } 121 122 /** The different mode an invocation can run into. */ 123 public enum RunMode { 124 REGULAR, 125 PARENT_SANDBOX, 126 SANDBOX, 127 REMOTE_INVOCATION, 128 } 129 130 private String mStatus = "(not invoked)"; 131 private boolean mStopRequested = false; 132 133 /** 134 * A {@link ResultForwarder} for forwarding resumed invocations. 135 * <p/> 136 * It filters the invocationStarted event for the resumed invocation, and sums the invocation 137 * elapsed time 138 */ 139 private static class ResumeResultForwarder extends ResultForwarder { 140 141 long mCurrentElapsedTime; 142 143 /** 144 * @param listeners 145 */ ResumeResultForwarder(List<ITestInvocationListener> listeners, long currentElapsedTime)146 public ResumeResultForwarder(List<ITestInvocationListener> listeners, 147 long currentElapsedTime) { 148 super(listeners); 149 mCurrentElapsedTime = currentElapsedTime; 150 } 151 152 @Override invocationStarted(IInvocationContext context)153 public void invocationStarted(IInvocationContext context) { 154 // ignore 155 } 156 157 @Override invocationEnded(long newElapsedTime)158 public void invocationEnded(long newElapsedTime) { 159 super.invocationEnded(mCurrentElapsedTime + newElapsedTime); 160 } 161 } 162 163 /** 164 * Display a log message informing the user of a invocation being started. 165 * 166 * @param context the {@link IInvocationContext} 167 * @param config the {@link IConfiguration} 168 */ logStartInvocation(IInvocationContext context, IConfiguration config)169 private void logStartInvocation(IInvocationContext context, IConfiguration config) { 170 String shardSuffix = ""; 171 if (config.getCommandOptions().getShardIndex() != null) { 172 shardSuffix = 173 String.format( 174 " (shard %d of %d)", 175 config.getCommandOptions().getShardIndex() + 1, 176 config.getCommandOptions().getShardCount()); 177 } 178 StringBuilder buildInfos = new StringBuilder(); 179 StringBuilder msg = new StringBuilder("Starting invocation for '"); 180 msg.append(context.getTestTag()); 181 msg.append("' with "); 182 for (Entry<ITestDevice, IBuildInfo> entry : context.getDeviceBuildMap().entrySet()) { 183 msg.append("'[ "); 184 msg.append(entry.getValue().toString()); 185 buildInfos.append(entry.getValue().toString()); 186 msg.append(" on device '"); 187 msg.append(entry.getKey().getSerialNumber()); 188 msg.append("'] "); 189 } 190 msg.append(shardSuffix); 191 CLog.logAndDisplay(LogLevel.INFO, msg.toString()); 192 mStatus = String.format("running %s on build(s) '%s'", context.getTestTag(), 193 buildInfos.toString()) + shardSuffix; 194 } 195 196 /** 197 * Performs the invocation 198 * 199 * @param config the {@link IConfiguration} 200 * @param context the {@link IInvocationContext} to use. 201 */ performInvocation( IConfiguration config, IInvocationContext context, IInvocationExecution invocationPath, IRescheduler rescheduler, ITestInvocationListener listener, boolean devicePreSetupDone)202 private void performInvocation( 203 IConfiguration config, 204 IInvocationContext context, 205 IInvocationExecution invocationPath, 206 IRescheduler rescheduler, 207 ITestInvocationListener listener, 208 boolean devicePreSetupDone) 209 throws Throwable { 210 211 boolean resumed = false; 212 String bugreportName = null; 213 long startTime = System.currentTimeMillis(); 214 long elapsedTime = -1; 215 Throwable exception = null; 216 Throwable tearDownException = null; 217 ITestDevice badDevice = null; 218 219 // Ensure that no unexpected attributes are added afterward 220 ((InvocationContext) context).lockAttributes(); 221 try { 222 logDeviceBatteryLevel(context, "initial"); 223 // Run the preInvocationSetup on devices. 224 if (!devicePreSetupDone) { 225 if (!config.getCommandOptions().shouldUseSandboxing()) { 226 invocationPath.runDevicePreInvocationSetup(context, config, listener); 227 } 228 } 229 // Then run the regular setup and run 230 prepareAndRun(config, context, invocationPath, listener); 231 } catch (BuildError e) { 232 exception = e; 233 CLog.w("Build failed on device '%s'. Reason: %s", e.getDeviceDescriptor(), 234 e.toString()); 235 bugreportName = BUILD_ERROR_BUGREPORT_NAME; 236 badDevice = context.getDeviceBySerial(e.getDeviceDescriptor().getSerial()); 237 if (e instanceof DeviceFailedToBootError) { 238 if (badDevice == null) { 239 context.setRecoveryModeForAllDevices(RecoveryMode.NONE); 240 } else { 241 badDevice.setRecoveryMode(RecoveryMode.NONE); 242 } 243 } 244 reportFailure(e, listener, config, context, rescheduler, invocationPath); 245 } catch (TargetSetupError e) { 246 exception = e; 247 CLog.e("Caught exception while running invocation"); 248 CLog.e(e); 249 bugreportName = TARGET_SETUP_ERROR_BUGREPORT_NAME; 250 badDevice = context.getDeviceBySerial(e.getDeviceDescriptor().getSerial()); 251 reportFailure(e, listener, config, context, rescheduler, invocationPath); 252 } catch (DeviceNotAvailableException e) { 253 exception = e; 254 // log a warning here so its captured before reportLogs is called 255 CLog.w("Invocation did not complete due to device %s becoming not available. " + 256 "Reason: %s", e.getSerial(), e.getMessage()); 257 badDevice = context.getDeviceBySerial(e.getSerial()); 258 if ((e instanceof DeviceUnresponsiveException) && badDevice != null 259 && TestDeviceState.ONLINE.equals(badDevice.getDeviceState())) { 260 // under certain cases it might still be possible to grab a bugreport 261 bugreportName = DEVICE_UNRESPONSIVE_BUGREPORT_NAME; 262 } 263 resumed = resume(config, context, rescheduler, System.currentTimeMillis() - startTime); 264 if (!resumed) { 265 reportFailure(e, listener, config, context, rescheduler, invocationPath); 266 } else { 267 CLog.i("Rescheduled failed invocation for resume"); 268 } 269 // Upon reaching here after an exception, it is safe to assume that recovery 270 // has already been attempted so we disable it to avoid re-entry during clean up. 271 if (badDevice != null) { 272 badDevice.setRecoveryMode(RecoveryMode.NONE); 273 } 274 throw e; 275 } catch (RunInterruptedException e) { 276 CLog.w("Invocation interrupted"); 277 reportFailure(e, listener, config, context, rescheduler, invocationPath); 278 } catch (AssertionError e) { 279 exception = e; 280 CLog.e("Caught AssertionError while running invocation: %s", e.toString()); 281 CLog.e(e); 282 reportFailure(e, listener, config, context, rescheduler, invocationPath); 283 } catch (Throwable t) { 284 exception = t; 285 // log a warning here so its captured before reportLogs is called 286 CLog.e("Unexpected exception when running invocation: %s", t.toString()); 287 CLog.e(t); 288 reportFailure(t, listener, config, context, rescheduler, invocationPath); 289 throw t; 290 } finally { 291 for (ITestDevice device : context.getDevices()) { 292 invocationPath.reportLogs(device, listener, Stage.TEST); 293 } 294 getRunUtil().allowInterrupt(false); 295 if (config.getCommandOptions().takeBugreportOnInvocationEnded() || 296 config.getCommandOptions().takeBugreportzOnInvocationEnded()) { 297 if (bugreportName != null) { 298 CLog.i("Bugreport to be taken for failure instead of invocation ended."); 299 } else { 300 bugreportName = INVOCATION_ENDED_BUGREPORT_NAME; 301 } 302 } 303 if (bugreportName != null) { 304 if (badDevice == null) { 305 for (ITestDevice device : context.getDevices()) { 306 takeBugreport(device, listener, bugreportName); 307 } 308 } else { 309 // If we have identified a faulty device only take the bugreport on it. 310 takeBugreport(badDevice, listener, bugreportName); 311 } 312 } 313 // Save the device executeShellCommand logs 314 logExecuteShellCommand(context.getDevices(), listener); 315 316 mStatus = "tearing down"; 317 try { 318 invocationPath.doTeardown(context, config, listener, exception); 319 } catch (Throwable e) { 320 tearDownException = e; 321 CLog.e("Exception when tearing down invocation: %s", tearDownException.toString()); 322 CLog.e(tearDownException); 323 if (exception == null) { 324 // only report when the exception is new during tear down 325 reportFailure( 326 tearDownException, 327 listener, 328 config, 329 context, 330 rescheduler, 331 invocationPath); 332 } 333 } 334 mStatus = "done running tests"; 335 try { 336 // Clean up host. 337 invocationPath.doCleanUp(context, config, exception); 338 for (ITestDevice device : context.getDevices()) { 339 invocationPath.reportLogs(device, listener, Stage.TEARDOWN); 340 } 341 if (mStopRequested) { 342 CLog.e( 343 "=====================================================================" 344 + "===="); 345 CLog.e( 346 "Invocation was interrupted due to TradeFed stop, results will be " 347 + "affected."); 348 CLog.e( 349 "=====================================================================" 350 + "===="); 351 } 352 reportHostLog(listener, config); 353 elapsedTime = System.currentTimeMillis() - startTime; 354 if (!resumed) { 355 listener.invocationEnded(elapsedTime); 356 } 357 } finally { 358 invocationPath.cleanUpBuilds(context, config); 359 } 360 } 361 if (tearDownException != null) { 362 // this means a DNAE or RTE has happened during teardown, need to throw 363 // if there was a preceding RTE or DNAE stored in 'exception', it would have already 364 // been thrown before exiting the previous try...catch...finally block 365 throw tearDownException; 366 } 367 } 368 369 /** Do setup and run the tests */ prepareAndRun( IConfiguration config, IInvocationContext context, IInvocationExecution invocationPath, ITestInvocationListener listener)370 private void prepareAndRun( 371 IConfiguration config, 372 IInvocationContext context, 373 IInvocationExecution invocationPath, 374 ITestInvocationListener listener) 375 throws Throwable { 376 getRunUtil().allowInterrupt(true); 377 logDeviceBatteryLevel(context, "initial -> setup"); 378 invocationPath.doSetup(context, config, listener); 379 logDeviceBatteryLevel(context, "setup -> test"); 380 invocationPath.runTests(context, config, listener); 381 logDeviceBatteryLevel(context, "after test"); 382 } 383 384 /** 385 * Starts the invocation. 386 * <p/> 387 * Starts logging, and informs listeners that invocation has been started. 388 * 389 * @param config 390 * @param context 391 */ startInvocation(IConfiguration config, IInvocationContext context, ITestInvocationListener listener)392 private void startInvocation(IConfiguration config, IInvocationContext context, 393 ITestInvocationListener listener) { 394 logStartInvocation(context, config); 395 listener.invocationStarted(context); 396 } 397 398 /** 399 * Attempt to reschedule the failed invocation to resume where it left off. 400 * <p/> 401 * @see IResumableTest 402 * 403 * @param config 404 * @return <code>true</code> if invocation was resumed successfully 405 */ resume(IConfiguration config, IInvocationContext context, IRescheduler rescheduler, long elapsedTime)406 private boolean resume(IConfiguration config, IInvocationContext context, 407 IRescheduler rescheduler, long elapsedTime) { 408 for (IRemoteTest test : config.getTests()) { 409 if (test instanceof IResumableTest) { 410 IResumableTest resumeTest = (IResumableTest)test; 411 if (resumeTest.isResumable()) { 412 // resume this config if any test is resumable 413 IConfiguration resumeConfig = config.clone(); 414 // reuse the same build for the resumed invocation 415 ShardBuildCloner.cloneBuildInfos(resumeConfig, resumeConfig, context); 416 417 // create a result forwarder, to prevent sending two invocationStarted events 418 resumeConfig.setTestInvocationListener(new ResumeResultForwarder( 419 config.getTestInvocationListeners(), elapsedTime)); 420 resumeConfig.setLogOutput(config.getLogOutput().clone()); 421 resumeConfig.setCommandOptions(config.getCommandOptions().clone()); 422 boolean canReschedule = rescheduler.scheduleConfig(resumeConfig); 423 if (!canReschedule) { 424 CLog.i("Cannot reschedule resumed config for build. Cleaning up build."); 425 for (String deviceName : context.getDeviceConfigNames()) { 426 resumeConfig.getDeviceConfigByName(deviceName).getBuildProvider() 427 .cleanUp(context.getBuildInfo(deviceName)); 428 } 429 } 430 // FIXME: is it a bug to return from here, when we may not have completed the 431 // FIXME: config.getTests iteration? 432 return canReschedule; 433 } 434 } 435 } 436 return false; 437 } 438 reportFailure( Throwable exception, ITestInvocationListener listener, IConfiguration config, IInvocationContext context, IRescheduler rescheduler, IInvocationExecution invocationPath)439 private void reportFailure( 440 Throwable exception, 441 ITestInvocationListener listener, 442 IConfiguration config, 443 IInvocationContext context, 444 IRescheduler rescheduler, 445 IInvocationExecution invocationPath) { 446 // Always report the failure 447 listener.invocationFailed(exception); 448 // Reset the build (if necessary) and decide if we should reschedule the configuration. 449 boolean shouldReschedule = 450 invocationPath.resetBuildAndReschedule(exception, listener, config, context); 451 if (shouldReschedule) { 452 rescheduleTest(config, rescheduler); 453 } 454 } 455 rescheduleTest(IConfiguration config, IRescheduler rescheduler)456 private void rescheduleTest(IConfiguration config, IRescheduler rescheduler) { 457 for (IRemoteTest test : config.getTests()) { 458 if (!config.getCommandOptions().isLoopMode() && test instanceof IRetriableTest && 459 ((IRetriableTest) test).isRetriable()) { 460 rescheduler.rescheduleCommand(); 461 return; 462 } 463 } 464 } 465 reportHostLog(ITestInvocationListener listener, IConfiguration config)466 private void reportHostLog(ITestInvocationListener listener, IConfiguration config) { 467 reportHostLog(listener, config, TRADEFED_LOG_NAME); 468 } 469 reportHostLog( ITestInvocationListener listener, IConfiguration config, String name)470 private void reportHostLog( 471 ITestInvocationListener listener, IConfiguration config, String name) { 472 ILeveledLogOutput logger = config.getLogOutput(); 473 try (InputStreamSource globalLogSource = logger.getLog()) { 474 if (config.getCommandOptions().getHostLogSuffix() != null) { 475 name += config.getCommandOptions().getHostLogSuffix(); 476 } 477 listener.testLog(name, LogDataType.TEXT, globalLogSource); 478 } 479 // once tradefed log is reported, all further log calls for this invocation can get lost 480 // unregister logger so future log calls get directed to the tradefed global log 481 getLogRegistry().unregisterLogger(); 482 logger.closeLog(); 483 } 484 takeBugreport( ITestDevice device, ITestInvocationListener listener, String bugreportName)485 private void takeBugreport( 486 ITestDevice device, ITestInvocationListener listener, String bugreportName) { 487 if (device == null) { 488 return; 489 } 490 if (device.getIDevice() instanceof StubDevice) { 491 return; 492 } 493 // logBugreport will report a regular bugreport if bugreportz is not supported. 494 boolean res = 495 device.logBugreport( 496 String.format("%s_%s", bugreportName, device.getSerialNumber()), listener); 497 if (!res) { 498 CLog.w("Error when collecting bugreport for device '%s'", device.getSerialNumber()); 499 } 500 } 501 502 /** 503 * Gets the {@link ILogRegistry} to use. 504 * <p/> 505 * Exposed for unit testing. 506 */ getLogRegistry()507 ILogRegistry getLogRegistry() { 508 return LogRegistry.getLogRegistry(); 509 } 510 511 /** 512 * Utility method to fetch the default {@link IRunUtil} singleton 513 * <p /> 514 * Exposed for unit testing. 515 */ getRunUtil()516 IRunUtil getRunUtil() { 517 return RunUtil.getDefault(); 518 } 519 520 @Override toString()521 public String toString() { 522 return mStatus; 523 } 524 525 /** 526 * Log the battery level of each device in the invocation. 527 * 528 * @param context the {@link IInvocationContext} of the invocation. 529 * @param event a {@link String} describing the context of the logging (initial, setup, etc.). 530 */ 531 @VisibleForTesting logDeviceBatteryLevel(IInvocationContext context, String event)532 void logDeviceBatteryLevel(IInvocationContext context, String event) { 533 for (ITestDevice testDevice : context.getDevices()) { 534 if (testDevice == null) { 535 continue; 536 } 537 if (testDevice.getIDevice() instanceof StubDevice) { 538 continue; 539 } 540 if (testDevice instanceof RemoteAndroidVirtualDevice 541 || testDevice instanceof NestedRemoteDevice) { 542 // Vritual devices have a fake battery there is no point in logging it. 543 continue; 544 } 545 Integer batteryLevel = testDevice.getBattery(); 546 if (batteryLevel == null) { 547 CLog.v("Failed to get battery level for %s", testDevice.getSerialNumber()); 548 continue; 549 } 550 CLog.v("%s - %s - %d%%", BATT_TAG, event, batteryLevel); 551 context.getBuildInfo(testDevice) 552 .addBuildAttribute( 553 String.format( 554 BATTERY_ATTRIBUTE_FORMAT_KEY, 555 testDevice.getSerialNumber(), 556 event), 557 batteryLevel.toString()); 558 } 559 } 560 561 /** 562 * Invoke {@link IInvocationExecution#fetchBuild(IInvocationContext, IConfiguration, 563 * IRescheduler, ITestInvocationListener)} and handles the output as well as failures. 564 * 565 * @param context the {@link IInvocationContext} of the invocation. 566 * @param config the {@link IConfiguration} of this test run. 567 * @param rescheduler the {@link IRescheduler}, for rescheduling portions of the invocation for 568 * execution on another resource(s) 569 * @param listener the {@link ITestInvocation} to report build download failures. 570 * @param invocationPath the {@link IInvocationExecution} driving the invocation. 571 * @return True if we successfully downloaded the build, false otherwise. 572 * @throws DeviceNotAvailableException 573 */ invokeFetchBuild( IInvocationContext context, IConfiguration config, IRescheduler rescheduler, ITestInvocationListener listener, IInvocationExecution invocationPath)574 private boolean invokeFetchBuild( 575 IInvocationContext context, 576 IConfiguration config, 577 IRescheduler rescheduler, 578 ITestInvocationListener listener, 579 IInvocationExecution invocationPath) 580 throws DeviceNotAvailableException { 581 Exception buildException = null; 582 boolean res = false; 583 try { 584 res = invocationPath.fetchBuild(context, config, rescheduler, listener); 585 if (res) { 586 // Successful fetch of build. 587 return true; 588 } 589 // In case of build not found issues. 590 mStatus = "(no build to test)"; 591 rescheduleTest(config, rescheduler); 592 // Set the exit code to error 593 buildException = new BuildRetrievalError("No build found to test."); 594 setExitCode(ExitCode.NO_BUILD, buildException); 595 } catch (BuildRetrievalError e) { 596 buildException = e; 597 } 598 // Report an empty invocation, so this error is sent to listeners 599 startInvocation(config, context, listener); 600 // Don't want to use #reportFailure, since that will call buildNotTested 601 listener.invocationFailed(buildException); 602 for (ITestDevice device : context.getDevices()) { 603 invocationPath.reportLogs(device, listener, Stage.ERROR); 604 } 605 reportHostLog(listener, config); 606 listener.invocationEnded(0L); 607 return false; 608 } 609 610 /** {@inheritDoc} */ 611 @Override invoke( IInvocationContext context, IConfiguration config, IRescheduler rescheduler, ITestInvocationListener... extraListeners)612 public void invoke( 613 IInvocationContext context, 614 IConfiguration config, 615 IRescheduler rescheduler, 616 ITestInvocationListener... extraListeners) 617 throws DeviceNotAvailableException, Throwable { 618 List<ITestInvocationListener> allListeners = 619 new ArrayList<>(config.getTestInvocationListeners().size() + extraListeners.length); 620 allListeners.addAll(config.getTestInvocationListeners()); 621 allListeners.addAll(Arrays.asList(extraListeners)); 622 ITestInvocationListener listener = null; 623 if (!config.getPostProcessors().isEmpty()) { 624 ITestInvocationListener forwarder = new ResultAndLogForwarder(allListeners); 625 // Post-processors are the first layer around the final reporters. 626 for (IPostProcessor postProcessor : config.getPostProcessors()) { 627 if (postProcessor.isDisabled()) { 628 CLog.d("%s has been disabled. skipping.", postProcessor); 629 } else { 630 forwarder = postProcessor.init(forwarder); 631 } 632 } 633 listener = new LogSaverResultForwarder(config.getLogSaver(), Arrays.asList(forwarder)); 634 } else { 635 listener = new LogSaverResultForwarder(config.getLogSaver(), allListeners); 636 } 637 638 RunMode mode = RunMode.REGULAR; 639 if (config.getConfigurationDescription().shouldUseSandbox()) { 640 mode = RunMode.SANDBOX; 641 } 642 if (config.getCommandOptions().shouldUseSandboxing()) { 643 mode = RunMode.PARENT_SANDBOX; 644 } 645 if (context.getDevices().get(0) instanceof ManagedRemoteDevice) { 646 mode = RunMode.REMOTE_INVOCATION; 647 } 648 IInvocationExecution invocationPath = createInvocationExec(mode); 649 650 // Create the Guice scope 651 InvocationScope scope = getInvocationScope(); 652 scope.enter(); 653 // Seed our TF objects to the Guice scope 654 scope.seed(IRescheduler.class, rescheduler); 655 scope.seedConfiguration(config); 656 try { 657 mStatus = "fetching build"; 658 ILeveledLogOutput leveledLogOutput = config.getLogOutput(); 659 leveledLogOutput.init(); 660 if (leveledLogOutput instanceof BaseLeveledLogOutput) { 661 ((BaseLeveledLogOutput) leveledLogOutput).initFilters(config); 662 } 663 getLogRegistry().registerLogger(config.getLogOutput()); 664 for (String deviceName : context.getDeviceConfigNames()) { 665 context.getDevice(deviceName).clearLastConnectedWifiNetwork(); 666 context.getDevice(deviceName) 667 .setOptions(config.getDeviceConfigByName(deviceName).getDeviceOptions()); 668 if (config.getDeviceConfigByName(deviceName) 669 .getDeviceOptions() 670 .isLogcatCaptureEnabled()) { 671 if (!(context.getDevice(deviceName).getIDevice() instanceof StubDevice)) { 672 context.getDevice(deviceName).startLogcat(); 673 } 674 } 675 } 676 677 String cmdLineArgs = config.getCommandLine(); 678 if (cmdLineArgs != null) { 679 CLog.i("Invocation was started with cmd: %s", cmdLineArgs); 680 } 681 682 long start = System.currentTimeMillis(); 683 boolean providerSuccess = 684 invokeFetchBuild(context, config, rescheduler, listener, invocationPath); 685 long fetchBuildDuration = System.currentTimeMillis() - start; 686 context.addInvocationTimingMetric(IInvocationContext.TimingEvent.FETCH_BUILD, 687 fetchBuildDuration); 688 CLog.d("Fetch build duration: %s", TimeUtil.formatElapsedTime(fetchBuildDuration)); 689 if (!providerSuccess) { 690 return; 691 } 692 693 boolean deviceInit = false; 694 // If the top level invocation has --use-sandbox do not shard there. It will shard in 695 // the child invocation. 696 if (RunMode.REGULAR.equals(mode) || RunMode.SANDBOX.equals(mode)) { 697 mStatus = "sharding"; 698 699 // TODO: Handle local sharding and special devices 700 Integer shardCount = config.getCommandOptions().getShardCount(); 701 Integer shardIndex = config.getCommandOptions().getShardIndex(); 702 // Special Handling in case of sharding within the same invocation (in-place): Some 703 // devices (Remote devices for example) require extra preparation step to be 704 // available, but sharding requires the device to be available in some cases. So 705 // we call the device setup early to meet all the requirements. 706 if (shardCount != null && shardIndex != null) { 707 deviceInit = true; 708 startInvocation(config, context, listener); 709 try { 710 invocationPath.runDevicePreInvocationSetup(context, config, listener); 711 } catch (DeviceNotAvailableException | TargetSetupError e) { 712 CLog.e(e); 713 setExitCode(ExitCode.THROWABLE_EXCEPTION, e); 714 try { 715 invocationPath.runDevicePostInvocationTearDown(context, config); 716 } finally { 717 listener.invocationFailed(e); 718 // Reports the logs 719 for (ITestDevice device : context.getDevices()) { 720 invocationPath.reportLogs(device, listener, Stage.ERROR); 721 } 722 reportHostLog(listener, config); 723 listener.invocationEnded(0L); 724 } 725 return; 726 } 727 } 728 729 boolean sharding = invocationPath.shardConfig(config, context, rescheduler); 730 if (sharding) { 731 CLog.i( 732 "Invocation for %s has been sharded, rescheduling", 733 context.getSerials()); 734 // Log the chunk of parent host_log before sharding 735 reportHostLog(listener, config, TRADEFED_LOG_NAME + BEFORE_SHARDING_SUFFIX); 736 config.getLogSaver().invocationEnded(0L); 737 return; 738 } 739 } 740 // Once we have all the information we can start the invocation. 741 if (!deviceInit) { 742 startInvocation(config, context, listener); 743 } 744 if (config.getTests() == null || config.getTests().isEmpty()) { 745 CLog.e("No tests to run"); 746 if (deviceInit) { 747 // If we did an early setup, do the tear down. 748 invocationPath.runDevicePostInvocationTearDown(context, config); 749 } 750 listener.invocationEnded(0L); 751 return; 752 } 753 754 performInvocation(config, context, invocationPath, rescheduler, listener, deviceInit); 755 setExitCode(ExitCode.NO_ERROR, null); 756 } catch (IOException e) { 757 CLog.e(e); 758 } finally { 759 scope.exit(); 760 // Ensure build infos are always cleaned up at the end of invocation. 761 invocationPath.cleanUpBuilds(context, config); 762 763 // ensure we always deregister the logger 764 for (String deviceName : context.getDeviceConfigNames()) { 765 if (!(context.getDevice(deviceName).getIDevice() instanceof StubDevice)) { 766 context.getDevice(deviceName).stopLogcat(); 767 } 768 } 769 // save remaining logs contents to global log 770 getLogRegistry().dumpToGlobalLog(config.getLogOutput()); 771 // Ensure log is unregistered and closed 772 getLogRegistry().unregisterLogger(); 773 config.getLogOutput().closeLog(); 774 config.cleanDynamicOptionFiles(); 775 } 776 } 777 778 /** Returns the current {@link InvocationScope}. */ 779 @VisibleForTesting getInvocationScope()780 InvocationScope getInvocationScope() { 781 return InvocationScope.getDefault(); 782 } 783 784 /** 785 * Helper to set the exit code. Exposed for testing. 786 */ setExitCode(ExitCode code, Throwable stack)787 protected void setExitCode(ExitCode code, Throwable stack) { 788 GlobalConfiguration.getInstance().getCommandScheduler() 789 .setLastInvocationExitCode(code, stack); 790 } 791 getDeviceLogName(Stage stage)792 public static String getDeviceLogName(Stage stage) { 793 return DEVICE_LOG_NAME_PREFIX + stage.getName(); 794 } 795 getEmulatorLogName(Stage stage)796 public static String getEmulatorLogName(Stage stage) { 797 return EMULATOR_LOG_NAME_PREFIX + stage.getName(); 798 } 799 800 @Override notifyInvocationStopped()801 public void notifyInvocationStopped() { 802 mStopRequested = true; 803 } 804 805 /** 806 * Create the invocation path that should be followed. 807 * 808 * @param mode The mode we are currently running as. 809 * @return The {@link IInvocationExecution} describing the invocation. 810 */ createInvocationExec(RunMode mode)811 public IInvocationExecution createInvocationExec(RunMode mode) { 812 switch (mode) { 813 case PARENT_SANDBOX: 814 return new ParentSandboxInvocationExecution(); 815 case SANDBOX: 816 return new SandboxedInvocationExecution(); 817 case REMOTE_INVOCATION: 818 return new RemoteInvocationExecution(); 819 default: 820 return new InvocationExecution(); 821 } 822 } 823 824 /** Prints a delimiter for a given Stage of the invocation. */ printStageDelimiter(Stage phase, boolean end)825 public static void printStageDelimiter(Stage phase, boolean end) { 826 String startEnd = end ? "ENDING" : "STARTING"; 827 String message = String.format("===== %s PHASE %s =====", phase, startEnd); 828 PrettyPrintDelimiter.printStageDelimiter(message); 829 } 830 logExecuteShellCommand(List<ITestDevice> devices, ITestLogger logger)831 private void logExecuteShellCommand(List<ITestDevice> devices, ITestLogger logger) { 832 for (ITestDevice device : devices) { 833 if (!(device instanceof NativeDevice)) { 834 return; 835 } 836 File log = ((NativeDevice) device).getExecuteShellCommandLog(); 837 if (log == null || !log.exists()) { 838 return; 839 } 840 try { 841 if (log != null && !FileUtil.readStringFromFile(log).isEmpty()) { 842 try (InputStreamSource source = new FileInputStreamSource(log)) { 843 logger.testLog( 844 String.format( 845 "executeShellCommandLog_%s", device.getSerialNumber()), 846 LogDataType.TEXT, 847 source); 848 } 849 } 850 } catch (IOException e) { 851 // Ignored 852 CLog.e(e); 853 } 854 } 855 } 856 } 857