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.IDevice; 19 import com.android.ddmlib.Log.LogLevel; 20 import com.android.tradefed.build.BuildRetrievalError; 21 import com.android.tradefed.build.IBuildInfo; 22 import com.android.tradefed.build.IBuildProvider; 23 import com.android.tradefed.build.IDeviceBuildProvider; 24 import com.android.tradefed.command.CommandRunner.ExitCode; 25 import com.android.tradefed.config.GlobalConfiguration; 26 import com.android.tradefed.config.IConfiguration; 27 import com.android.tradefed.config.IDeviceConfiguration; 28 import com.android.tradefed.device.DeviceNotAvailableException; 29 import com.android.tradefed.device.DeviceUnresponsiveException; 30 import com.android.tradefed.device.ITestDevice; 31 import com.android.tradefed.device.ITestDevice.RecoveryMode; 32 import com.android.tradefed.device.StubDevice; 33 import com.android.tradefed.device.TestDeviceState; 34 import com.android.tradefed.invoker.shard.IShardHelper; 35 import com.android.tradefed.invoker.shard.ShardBuildCloner; 36 import com.android.tradefed.log.ILeveledLogOutput; 37 import com.android.tradefed.log.ILogRegistry; 38 import com.android.tradefed.log.LogRegistry; 39 import com.android.tradefed.log.LogUtil.CLog; 40 import com.android.tradefed.result.AggregatingProfilerListener; 41 import com.android.tradefed.result.ITestInvocationListener; 42 import com.android.tradefed.result.ITestLoggerReceiver; 43 import com.android.tradefed.result.InputStreamSource; 44 import com.android.tradefed.result.LogDataType; 45 import com.android.tradefed.result.LogSaverResultForwarder; 46 import com.android.tradefed.result.ResultForwarder; 47 import com.android.tradefed.suite.checker.ISystemStatusCheckerReceiver; 48 import com.android.tradefed.targetprep.BuildError; 49 import com.android.tradefed.targetprep.DeviceFailedToBootError; 50 import com.android.tradefed.targetprep.IHostCleaner; 51 import com.android.tradefed.targetprep.ITargetCleaner; 52 import com.android.tradefed.targetprep.ITargetPreparer; 53 import com.android.tradefed.targetprep.TargetSetupError; 54 import com.android.tradefed.targetprep.multi.IMultiTargetPreparer; 55 import com.android.tradefed.testtype.IBuildReceiver; 56 import com.android.tradefed.testtype.IDeviceTest; 57 import com.android.tradefed.testtype.IInvocationContextReceiver; 58 import com.android.tradefed.testtype.IMultiDeviceTest; 59 import com.android.tradefed.testtype.IRemoteTest; 60 import com.android.tradefed.testtype.IResumableTest; 61 import com.android.tradefed.testtype.IRetriableTest; 62 import com.android.tradefed.util.IRunUtil; 63 import com.android.tradefed.util.RunInterruptedException; 64 import com.android.tradefed.util.RunUtil; 65 import com.android.tradefed.util.StreamUtil; 66 67 import com.google.common.annotations.VisibleForTesting; 68 69 import java.io.IOException; 70 import java.util.ArrayList; 71 import java.util.Arrays; 72 import java.util.List; 73 import java.util.ListIterator; 74 import java.util.Map.Entry; 75 import java.util.concurrent.ExecutionException; 76 import java.util.concurrent.TimeUnit; 77 78 /** 79 * Default implementation of {@link ITestInvocation}. 80 * <p/> 81 * Loads major objects based on {@link IConfiguration} 82 * - retrieves build 83 * - prepares target 84 * - runs tests 85 * - reports results 86 */ 87 public class TestInvocation implements ITestInvocation { 88 89 /** 90 * Format of the key in {@link IInvocationContext} to log the battery level for each step of the 91 * invocation. (Setup, test, tear down). 92 */ 93 private static final String BATTERY_ATTRIBUTE_FORMAT_KEY = "%s-battery-%s"; 94 95 static final String TRADEFED_LOG_NAME = "host_log"; 96 static final String DEVICE_LOG_NAME_PREFIX = "device_logcat_"; 97 static final String EMULATOR_LOG_NAME_PREFIX = "emulator_log_"; 98 static final String BUILD_ERROR_BUGREPORT_NAME = "build_error_bugreport"; 99 static final String DEVICE_UNRESPONSIVE_BUGREPORT_NAME = "device_unresponsive_bugreport"; 100 static final String INVOCATION_ENDED_BUGREPORT_NAME = "invocation_ended_bugreport"; 101 static final String TARGET_SETUP_ERROR_BUGREPORT_NAME = "target_setup_error_bugreport"; 102 static final String BATT_TAG = "[battery level]"; 103 104 public enum Stage { 105 ERROR("error"), 106 SETUP("setup"), 107 TEST("test"), 108 TEARDOWN("teardown"); 109 110 private final String mName; 111 112 Stage(String name) { 113 mName = name; 114 } 115 116 public String getName() { 117 return mName; 118 } 119 } 120 121 private String mStatus = "(not invoked)"; 122 private boolean mStopRequested = false; 123 124 /** 125 * A {@link ResultForwarder} for forwarding resumed invocations. 126 * <p/> 127 * It filters the invocationStarted event for the resumed invocation, and sums the invocation 128 * elapsed time 129 */ 130 private static class ResumeResultForwarder extends ResultForwarder { 131 132 long mCurrentElapsedTime; 133 134 /** 135 * @param listeners 136 */ 137 public ResumeResultForwarder(List<ITestInvocationListener> listeners, 138 long currentElapsedTime) { 139 super(listeners); 140 mCurrentElapsedTime = currentElapsedTime; 141 } 142 143 @Override 144 public void invocationStarted(IInvocationContext context) { 145 // ignore 146 } 147 148 @Override 149 public void invocationEnded(long newElapsedTime) { 150 super.invocationEnded(mCurrentElapsedTime + newElapsedTime); 151 } 152 } 153 154 /** 155 * Attempt to shard the configuration into sub-configurations, to be re-scheduled to run on 156 * multiple resources in parallel. 157 * 158 * <p>If a shard count is greater than 1, it will simply create configs for each shard by 159 * setting shard indices and reschedule them. If a shard count is not set,it would fallback to 160 * {@link IShardHelper#shardConfig}. 161 * 162 * @param config the current {@link IConfiguration}. 163 * @param context the {@link IInvocationContext} holding the info of the tests. 164 * @param rescheduler the {@link IRescheduler} 165 * @return true if test was sharded. Otherwise return <code>false</code> 166 */ 167 private boolean shardConfig( 168 IConfiguration config, IInvocationContext context, IRescheduler rescheduler) { 169 mStatus = "sharding"; 170 return createShardHelper().shardConfig(config, context, rescheduler); 171 } 172 173 /** Create an return the {@link IShardHelper} to be used. */ 174 @VisibleForTesting 175 protected IShardHelper createShardHelper() { 176 return GlobalConfiguration.getInstance().getShardingStrategy(); 177 } 178 179 /** 180 * Update the {@link IBuildInfo} with additional info from the {@link IConfiguration}. 181 * 182 * @param info the {@link IBuildInfo} 183 * @param config the {@link IConfiguration} 184 */ 185 private void updateBuild(IBuildInfo info, IConfiguration config) { 186 if (config.getCommandLine() != null) { 187 // TODO: obfuscate the password if any. 188 info.addBuildAttribute("command_line_args", config.getCommandLine()); 189 } 190 if (config.getCommandOptions().getShardCount() != null) { 191 info.addBuildAttribute("shard_count", 192 config.getCommandOptions().getShardCount().toString()); 193 } 194 if (config.getCommandOptions().getShardIndex() != null) { 195 info.addBuildAttribute("shard_index", 196 config.getCommandOptions().getShardIndex().toString()); 197 } 198 // TODO: update all the configs to only use test-tag from CommandOption and not build 199 // providers. 200 // When CommandOption is set, it overrides any test-tag from build_providers 201 if (!"stub".equals(config.getCommandOptions().getTestTag())) { 202 info.setTestTag(getTestTag(config)); 203 } else if (info.getTestTag() == null || info.getTestTag().isEmpty()) { 204 // We ensure that that a default test-tag is always available. 205 info.setTestTag("stub"); 206 } else { 207 CLog.w("Using the test-tag from the build_provider. Consider updating your config to" 208 + " have no alias/namespace in front of test-tag."); 209 } 210 } 211 212 /** 213 * Update the {@link IInvocationContext} with additional info from the {@link IConfiguration}. 214 * 215 * @param context the {@link IInvocationContext} 216 * @param config the {@link IConfiguration} 217 */ 218 private void updateInvocationContext(IInvocationContext context, IConfiguration config) { 219 // TODO: Once reporting on context is done, only set context attributes 220 if (config.getCommandLine() != null) { 221 // TODO: obfuscate the password if any. 222 context.addInvocationAttribute("command_line_args", config.getCommandLine()); 223 } 224 if (config.getCommandOptions().getShardCount() != null) { 225 context.addInvocationAttribute("shard_count", 226 config.getCommandOptions().getShardCount().toString()); 227 } 228 if (config.getCommandOptions().getShardIndex() != null) { 229 context.addInvocationAttribute("shard_index", 230 config.getCommandOptions().getShardIndex().toString()); 231 } 232 context.setTestTag(getTestTag(config)); 233 } 234 235 /** 236 * Helper to create the test tag from the configuration. 237 */ 238 private String getTestTag(IConfiguration config) { 239 String testTag = config.getCommandOptions().getTestTag(); 240 if (config.getCommandOptions().getTestTagSuffix() != null) { 241 testTag = String.format("%s-%s", testTag, 242 config.getCommandOptions().getTestTagSuffix()); 243 } 244 return testTag; 245 } 246 247 /** 248 * Display a log message informing the user of a invocation being started. 249 * 250 * @param context the {@link IInvocationContext} 251 * @param config the {@link IConfiguration} 252 */ 253 private void logStartInvocation(IInvocationContext context, IConfiguration config) { 254 String shardSuffix = ""; 255 if (config.getCommandOptions().getShardIndex() != null) { 256 shardSuffix = 257 String.format( 258 " (shard %d of %d)", 259 config.getCommandOptions().getShardIndex() + 1, 260 config.getCommandOptions().getShardCount()); 261 } 262 StringBuilder buildInfos = new StringBuilder(); 263 StringBuilder msg = new StringBuilder("Starting invocation for '"); 264 msg.append(context.getTestTag()); 265 msg.append("' with "); 266 for (Entry<ITestDevice, IBuildInfo> entry : context.getDeviceBuildMap().entrySet()) { 267 msg.append("'[ "); 268 msg.append(entry.getValue().toString()); 269 buildInfos.append(entry.getValue().toString()); 270 msg.append(" on device '"); 271 msg.append(entry.getKey().getSerialNumber()); 272 msg.append("'] "); 273 } 274 msg.append(shardSuffix); 275 CLog.logAndDisplay(LogLevel.INFO, msg.toString()); 276 mStatus = String.format("running %s on build(s) '%s'", context.getTestTag(), 277 buildInfos.toString()) + shardSuffix; 278 } 279 280 /** 281 * Performs the invocation 282 * 283 * @param config the {@link IConfiguration} 284 * @param context the {@link IInvocationContext} to use. 285 */ 286 private void performInvocation(IConfiguration config, IInvocationContext context, 287 IRescheduler rescheduler, ITestInvocationListener listener) throws Throwable { 288 289 boolean resumed = false; 290 String bugreportName = null; 291 long startTime = System.currentTimeMillis(); 292 long elapsedTime = -1; 293 Throwable exception = null; 294 Throwable tearDownException = null; 295 ITestDevice badDevice = null; 296 297 startInvocation(config, context, listener); 298 try { 299 logDeviceBatteryLevel(context, "initial"); 300 prepareAndRun(config, context, listener); 301 } catch (BuildError e) { 302 exception = e; 303 CLog.w("Build failed on device '%s'. Reason: %s", e.getDeviceDescriptor(), 304 e.toString()); 305 bugreportName = BUILD_ERROR_BUGREPORT_NAME; 306 badDevice = context.getDeviceBySerial(e.getDeviceDescriptor().getSerial()); 307 if (e instanceof DeviceFailedToBootError) { 308 if (badDevice == null) { 309 context.setRecoveryModeForAllDevices(RecoveryMode.NONE); 310 } else { 311 badDevice.setRecoveryMode(RecoveryMode.NONE); 312 } 313 } 314 reportFailure(e, listener, config, context, rescheduler); 315 } catch (TargetSetupError e) { 316 exception = e; 317 CLog.e("Caught exception while running invocation"); 318 CLog.e(e); 319 bugreportName = TARGET_SETUP_ERROR_BUGREPORT_NAME; 320 badDevice = context.getDeviceBySerial(e.getDeviceDescriptor().getSerial()); 321 reportFailure(e, listener, config, context, rescheduler); 322 } catch (DeviceNotAvailableException e) { 323 exception = e; 324 // log a warning here so its captured before reportLogs is called 325 CLog.w("Invocation did not complete due to device %s becoming not available. " + 326 "Reason: %s", e.getSerial(), e.getMessage()); 327 badDevice = context.getDeviceBySerial(e.getSerial()); 328 if ((e instanceof DeviceUnresponsiveException) && badDevice != null 329 && TestDeviceState.ONLINE.equals(badDevice.getDeviceState())) { 330 // under certain cases it might still be possible to grab a bugreport 331 bugreportName = DEVICE_UNRESPONSIVE_BUGREPORT_NAME; 332 } 333 resumed = resume(config, context, rescheduler, System.currentTimeMillis() - startTime); 334 if (!resumed) { 335 reportFailure(e, listener, config, context, rescheduler); 336 } else { 337 CLog.i("Rescheduled failed invocation for resume"); 338 } 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 CLog.w("Invocation interrupted"); 347 reportFailure(e, listener, config, context, rescheduler); 348 } catch (AssertionError e) { 349 exception = e; 350 CLog.e("Caught AssertionError while running invocation: %s", e.toString()); 351 CLog.e(e); 352 reportFailure(e, listener, config, context, rescheduler); 353 } catch (Throwable t) { 354 exception = t; 355 // log a warning here so its captured before reportLogs is called 356 CLog.e("Unexpected exception when running invocation: %s", t.toString()); 357 CLog.e(t); 358 reportFailure(t, listener, config, context, rescheduler); 359 throw t; 360 } finally { 361 for (ITestDevice device : context.getDevices()) { 362 reportLogs(device, listener, Stage.TEST); 363 } 364 getRunUtil().allowInterrupt(false); 365 if (config.getCommandOptions().takeBugreportOnInvocationEnded() || 366 config.getCommandOptions().takeBugreportzOnInvocationEnded()) { 367 if (bugreportName != null) { 368 CLog.i("Bugreport to be taken for failure instead of invocation ended."); 369 } else { 370 bugreportName = INVOCATION_ENDED_BUGREPORT_NAME; 371 } 372 } 373 if (bugreportName != null) { 374 if (badDevice == null) { 375 for (ITestDevice device : context.getDevices()) { 376 takeBugreport(device, listener, bugreportName, 377 config.getCommandOptions().takeBugreportzOnInvocationEnded()); 378 } 379 } else { 380 // If we have identified a faulty device only take the bugreport on it. 381 takeBugreport(badDevice, listener, bugreportName, 382 config.getCommandOptions().takeBugreportzOnInvocationEnded()); 383 } 384 } 385 mStatus = "tearing down"; 386 try { 387 doTeardown(config, context, exception); 388 } catch (Throwable e) { 389 tearDownException = e; 390 CLog.e("Exception when tearing down invocation: %s", tearDownException.toString()); 391 CLog.e(tearDownException); 392 if (exception == null) { 393 // only report when the exception is new during tear down 394 reportFailure(tearDownException, listener, config, context, rescheduler); 395 } 396 } 397 mStatus = "done running tests"; 398 try { 399 // Clean up host. 400 doCleanUp(config, context, exception); 401 if (config.getProfiler() != null) { 402 config.getProfiler().reportAllMetrics(listener); 403 } 404 for (ITestDevice device : context.getDevices()) { 405 reportLogs(device, listener, Stage.TEARDOWN); 406 } 407 if (mStopRequested) { 408 CLog.e( 409 "=====================================================================" 410 + "===="); 411 CLog.e( 412 "Invocation was interrupted due to TradeFed stop, results will be " 413 + "affected."); 414 CLog.e( 415 "=====================================================================" 416 + "===="); 417 } 418 reportHostLog(listener, config.getLogOutput()); 419 elapsedTime = System.currentTimeMillis() - startTime; 420 if (!resumed) { 421 listener.invocationEnded(elapsedTime); 422 } 423 } finally { 424 for (String deviceName : context.getDeviceConfigNames()) { 425 config.getDeviceConfigByName(deviceName).getBuildProvider() 426 .cleanUp(context.getBuildInfo(deviceName)); 427 } 428 } 429 } 430 if (tearDownException != null) { 431 // this means a DNAE or RTE has happened during teardown, need to throw 432 // if there was a preceding RTE or DNAE stored in 'exception', it would have already 433 // been thrown before exiting the previous try...catch...finally block 434 throw tearDownException; 435 } 436 } 437 438 /** Do setup and run the tests */ 439 private void prepareAndRun( 440 IConfiguration config, IInvocationContext context, ITestInvocationListener listener) 441 throws Throwable { 442 getRunUtil().allowInterrupt(true); 443 logDeviceBatteryLevel(context, "initial -> setup"); 444 doSetup(config, context, listener); 445 logDeviceBatteryLevel(context, "setup -> test"); 446 runTests(context, config, listener); 447 logDeviceBatteryLevel(context, "after test"); 448 } 449 450 @VisibleForTesting 451 void doSetup( 452 IConfiguration config, 453 IInvocationContext context, 454 final ITestInvocationListener listener) 455 throws TargetSetupError, BuildError, DeviceNotAvailableException { 456 // TODO: evaluate doing device setup in parallel 457 for (String deviceName : context.getDeviceConfigNames()) { 458 ITestDevice device = context.getDevice(deviceName); 459 CLog.d("Starting setup for device: '%s'", device.getSerialNumber()); 460 if (device instanceof ITestLoggerReceiver) { 461 ((ITestLoggerReceiver) context.getDevice(deviceName)) 462 .setTestLogger(listener); 463 } 464 if (!config.getCommandOptions().shouldSkipPreDeviceSetup()) { 465 device.preInvocationSetup(context.getBuildInfo(deviceName)); 466 } 467 for (ITargetPreparer preparer : config.getDeviceConfigByName(deviceName) 468 .getTargetPreparers()) { 469 if (preparer instanceof ITestLoggerReceiver) { 470 ((ITestLoggerReceiver) preparer).setTestLogger(listener); 471 } 472 CLog.d( 473 "starting preparer '%s' on device: '%s'", 474 preparer, device.getSerialNumber()); 475 preparer.setUp(device, context.getBuildInfo(deviceName)); 476 CLog.d( 477 "done with preparer '%s' on device: '%s'", 478 preparer, device.getSerialNumber()); 479 } 480 CLog.d("Done with setup of device: '%s'", device.getSerialNumber()); 481 } 482 // After all the individual setup, make the multi-devices setup 483 for (IMultiTargetPreparer multipreparer : config.getMultiTargetPreparers()) { 484 if (multipreparer instanceof ITestLoggerReceiver) { 485 ((ITestLoggerReceiver) multipreparer).setTestLogger(listener); 486 } 487 CLog.d("Starting multi target preparer '%s'", multipreparer); 488 multipreparer.setUp(context); 489 CLog.d("done with multi target preparer '%s'", multipreparer); 490 } 491 if (config.getProfiler() != null) { 492 config.getProfiler().setUp(context); 493 } 494 // Upload setup logcat after setup is complete 495 for (String deviceName : context.getDeviceConfigNames()) { 496 reportLogs(context.getDevice(deviceName), listener, Stage.SETUP); 497 } 498 } 499 500 private void doTeardown(IConfiguration config, IInvocationContext context, 501 Throwable exception) throws Throwable { 502 Throwable throwable = null; 503 504 List<IMultiTargetPreparer> multiPreparers = config.getMultiTargetPreparers(); 505 ListIterator<IMultiTargetPreparer> iterator = 506 multiPreparers.listIterator(multiPreparers.size()); 507 while (iterator.hasPrevious()) { 508 IMultiTargetPreparer multipreparer = iterator.previous(); 509 CLog.d("Starting multi target tearDown '%s'", multipreparer); 510 multipreparer.tearDown(context, throwable); 511 CLog.d("Done with multi target tearDown '%s'", multipreparer); 512 } 513 514 // Clear wifi settings, to prevent wifi errors from interfering with teardown process. 515 for (String deviceName : context.getDeviceConfigNames()) { 516 ITestDevice device = context.getDevice(deviceName); 517 device.clearLastConnectedWifiNetwork(); 518 List<ITargetPreparer> preparers = 519 config.getDeviceConfigByName(deviceName).getTargetPreparers(); 520 ListIterator<ITargetPreparer> itr = preparers.listIterator(preparers.size()); 521 while (itr.hasPrevious()) { 522 ITargetPreparer preparer = itr.previous(); 523 if(preparer instanceof ITargetCleaner) { 524 ITargetCleaner cleaner = (ITargetCleaner) preparer; 525 if (cleaner != null) { 526 try { 527 CLog.d("starting tearDown '%s' on device: '%s'", preparer, 528 device.getSerialNumber()); 529 cleaner.tearDown(device, context.getBuildInfo(deviceName), exception); 530 CLog.d("done with tearDown '%s' on device: '%s'", preparer, 531 device.getSerialNumber()); 532 } catch (Throwable e) { 533 // We catch it and rethrow later to allow each targetprep to be attempted. 534 // Only the last one will be thrown but all should be logged. 535 CLog.e("Deferring throw for: %s", e); 536 throwable = e; 537 } 538 } 539 } 540 } 541 // Extra tear down step for the device 542 device.postInvocationTearDown(); 543 } 544 545 if (throwable != null) { 546 throw throwable; 547 } 548 } 549 550 private void doCleanUp(IConfiguration config, IInvocationContext context, 551 Throwable exception) { 552 for (String deviceName : context.getDeviceConfigNames()) { 553 List<ITargetPreparer> preparers = 554 config.getDeviceConfigByName(deviceName).getTargetPreparers(); 555 ListIterator<ITargetPreparer> itr = preparers.listIterator(preparers.size()); 556 while (itr.hasPrevious()) { 557 ITargetPreparer preparer = itr.previous(); 558 if (preparer instanceof IHostCleaner) { 559 IHostCleaner cleaner = (IHostCleaner) preparer; 560 if (cleaner != null) { 561 cleaner.cleanUp(context.getBuildInfo(deviceName), exception); 562 } 563 } 564 } 565 } 566 } 567 568 /** 569 * Starts the invocation. 570 * <p/> 571 * Starts logging, and informs listeners that invocation has been started. 572 * 573 * @param config 574 * @param context 575 */ 576 private void startInvocation(IConfiguration config, IInvocationContext context, 577 ITestInvocationListener listener) { 578 logStartInvocation(context, config); 579 listener.invocationStarted(context); 580 } 581 582 /** 583 * Attempt to reschedule the failed invocation to resume where it left off. 584 * <p/> 585 * @see IResumableTest 586 * 587 * @param config 588 * @return <code>true</code> if invocation was resumed successfully 589 */ 590 private boolean resume(IConfiguration config, IInvocationContext context, 591 IRescheduler rescheduler, long elapsedTime) { 592 for (IRemoteTest test : config.getTests()) { 593 if (test instanceof IResumableTest) { 594 IResumableTest resumeTest = (IResumableTest)test; 595 if (resumeTest.isResumable()) { 596 // resume this config if any test is resumable 597 IConfiguration resumeConfig = config.clone(); 598 // reuse the same build for the resumed invocation 599 ShardBuildCloner.cloneBuildInfos(resumeConfig, resumeConfig, context); 600 601 // create a result forwarder, to prevent sending two invocationStarted events 602 resumeConfig.setTestInvocationListener(new ResumeResultForwarder( 603 config.getTestInvocationListeners(), elapsedTime)); 604 resumeConfig.setLogOutput(config.getLogOutput().clone()); 605 resumeConfig.setCommandOptions(config.getCommandOptions().clone()); 606 boolean canReschedule = rescheduler.scheduleConfig(resumeConfig); 607 if (!canReschedule) { 608 CLog.i("Cannot reschedule resumed config for build. Cleaning up build."); 609 for (String deviceName : context.getDeviceConfigNames()) { 610 resumeConfig.getDeviceConfigByName(deviceName).getBuildProvider() 611 .cleanUp(context.getBuildInfo(deviceName)); 612 } 613 } 614 // FIXME: is it a bug to return from here, when we may not have completed the 615 // FIXME: config.getTests iteration? 616 return canReschedule; 617 } 618 } 619 } 620 return false; 621 } 622 623 private void reportFailure(Throwable exception, ITestInvocationListener listener, 624 IConfiguration config, IInvocationContext context, IRescheduler rescheduler) { 625 listener.invocationFailed(exception); 626 if (!(exception instanceof BuildError) && !(exception.getCause() instanceof BuildError)) { 627 for (String deviceName : context.getDeviceConfigNames()) { 628 config.getDeviceConfigByName(deviceName) 629 .getBuildProvider() 630 .buildNotTested(context.getBuildInfo(deviceName)); 631 } 632 rescheduleTest(config, rescheduler); 633 } 634 } 635 636 private void rescheduleTest(IConfiguration config, IRescheduler rescheduler) { 637 for (IRemoteTest test : config.getTests()) { 638 if (!config.getCommandOptions().isLoopMode() && test instanceof IRetriableTest && 639 ((IRetriableTest) test).isRetriable()) { 640 rescheduler.rescheduleCommand(); 641 return; 642 } 643 } 644 } 645 646 private void reportLogs(ITestDevice device, ITestInvocationListener listener, Stage stage) { 647 InputStreamSource logcatSource = null; 648 InputStreamSource emulatorOutput = null; 649 try { 650 // only get logcat if we have an actual device available to avoid empty logs. 651 if (device != null && !(device.getIDevice() instanceof StubDevice)) { 652 logcatSource = device.getLogcat(); 653 device.clearLogcat(); 654 if (device.getIDevice() != null && device.getIDevice().isEmulator()) { 655 emulatorOutput = device.getEmulatorOutput(); 656 // TODO: Clear the emulator log 657 } 658 } 659 if (logcatSource != null) { 660 String name = getDeviceLogName(stage); 661 listener.testLog(name, LogDataType.LOGCAT, logcatSource); 662 } 663 if (emulatorOutput != null) { 664 String name = getEmulatorLogName(stage); 665 listener.testLog(name, LogDataType.TEXT, emulatorOutput); 666 } 667 } finally { 668 // Clean up after our ISSen 669 StreamUtil.cancel(logcatSource); 670 StreamUtil.cancel(emulatorOutput); 671 } 672 } 673 674 private void reportHostLog(ITestInvocationListener listener, ILeveledLogOutput logger) { 675 InputStreamSource globalLogSource = logger.getLog(); 676 listener.testLog(TRADEFED_LOG_NAME, LogDataType.TEXT, globalLogSource); 677 globalLogSource.cancel(); 678 // once tradefed log is reported, all further log calls for this invocation can get lost 679 // unregister logger so future log calls get directed to the tradefed global log 680 getLogRegistry().unregisterLogger(); 681 logger.closeLog(); 682 } 683 684 private void takeBugreport(ITestDevice device, ITestInvocationListener listener, 685 String bugreportName, boolean useBugreportz) { 686 if (device == null) { 687 return; 688 } 689 if (device.getIDevice() instanceof StubDevice) { 690 return; 691 } 692 if (useBugreportz) { 693 // logBugreport will report a regular bugreport if bugreportz is not supported. 694 device.logBugreport(String.format("%s_%s", bugreportName, device.getSerialNumber()), 695 listener); 696 } else { 697 InputStreamSource bugreport = device.getBugreport(); 698 try { 699 if (bugreport != null) { 700 listener.testLog(String.format("%s_%s", bugreportName, 701 device.getSerialNumber()), LogDataType.BUGREPORT, bugreport); 702 } else { 703 CLog.w("Error when collecting bugreport for device '%s'", 704 device.getSerialNumber()); 705 } 706 } finally { 707 StreamUtil.cancel(bugreport); 708 } 709 } 710 } 711 712 /** 713 * Gets the {@link ILogRegistry} to use. 714 * <p/> 715 * Exposed for unit testing. 716 */ 717 ILogRegistry getLogRegistry() { 718 return LogRegistry.getLogRegistry(); 719 } 720 721 /** 722 * Utility method to fetch the default {@link IRunUtil} singleton 723 * <p /> 724 * Exposed for unit testing. 725 */ 726 IRunUtil getRunUtil() { 727 return RunUtil.getDefault(); 728 } 729 730 /** 731 * Runs the test. 732 * 733 * @param context the {@link IInvocationContext} to run tests on 734 * @param config the {@link IConfiguration} to run 735 * @param listener the {@link ITestInvocationListener} of test results 736 * @throws DeviceNotAvailableException 737 */ 738 private void runTests(IInvocationContext context, IConfiguration config, 739 ITestInvocationListener listener) throws DeviceNotAvailableException { 740 for (IRemoteTest test : config.getTests()) { 741 // For compatibility of those receivers, they are assumed to be single device alloc. 742 if (test instanceof IDeviceTest) { 743 ((IDeviceTest)test).setDevice(context.getDevices().get(0)); 744 } 745 if (test instanceof IBuildReceiver) { 746 ((IBuildReceiver)test).setBuild(context.getBuildInfo( 747 context.getDevices().get(0))); 748 } 749 if (test instanceof ISystemStatusCheckerReceiver) { 750 ((ISystemStatusCheckerReceiver) test).setSystemStatusChecker( 751 config.getSystemStatusCheckers()); 752 } 753 754 // TODO: consider adding receivers for only the list of ITestDevice and IBuildInfo. 755 if (test instanceof IMultiDeviceTest) { 756 ((IMultiDeviceTest)test).setDeviceInfos(context.getDeviceBuildMap()); 757 } 758 if (test instanceof IInvocationContextReceiver) { 759 ((IInvocationContextReceiver)test).setInvocationContext(context); 760 } 761 test.run(listener); 762 } 763 } 764 765 @Override 766 public String toString() { 767 return mStatus; 768 } 769 770 /** 771 * Log the battery level of each device in the invocation. 772 * 773 * @param context the {@link IInvocationContext} of the invocation. 774 * @param event a {@link String} describing the context of the logging (initial, setup, etc.). 775 */ 776 @VisibleForTesting 777 void logDeviceBatteryLevel(IInvocationContext context, String event) { 778 for (ITestDevice testDevice : context.getDevices()) { 779 if (testDevice == null) { 780 continue; 781 } 782 IDevice device = testDevice.getIDevice(); 783 if (device == null || device instanceof StubDevice) { 784 continue; 785 } 786 try { 787 Integer batteryLevel = device.getBattery(500, TimeUnit.MILLISECONDS).get(); 788 CLog.v("%s - %s - %d%%", BATT_TAG, event, batteryLevel); 789 context.addInvocationAttribute( 790 String.format( 791 BATTERY_ATTRIBUTE_FORMAT_KEY, testDevice.getSerialNumber(), event), 792 batteryLevel.toString()); 793 continue; 794 } catch (InterruptedException | ExecutionException e) { 795 // fall through 796 } 797 798 CLog.v("Failed to get battery level for %s", testDevice.getSerialNumber()); 799 } 800 } 801 802 /** 803 * {@inheritDoc} 804 */ 805 @Override 806 public void invoke( 807 IInvocationContext context, IConfiguration config, IRescheduler rescheduler, 808 ITestInvocationListener... extraListeners) 809 throws DeviceNotAvailableException, Throwable { 810 List<ITestInvocationListener> allListeners = 811 new ArrayList<>(config.getTestInvocationListeners().size() + extraListeners.length); 812 allListeners.addAll(config.getTestInvocationListeners()); 813 allListeners.addAll(Arrays.asList(extraListeners)); 814 if (config.getProfiler() != null) { 815 allListeners.add(new AggregatingProfilerListener(config.getProfiler())); 816 } 817 ITestInvocationListener listener = new LogSaverResultForwarder(config.getLogSaver(), 818 allListeners); 819 String currentDeviceName = null; 820 try { 821 mStatus = "fetching build"; 822 config.getLogOutput().init(); 823 getLogRegistry().registerLogger(config.getLogOutput()); 824 for (String deviceName : context.getDeviceConfigNames()) { 825 context.getDevice(deviceName).clearLastConnectedWifiNetwork(); 826 context.getDevice(deviceName).setOptions( 827 config.getDeviceConfigByName(deviceName).getDeviceOptions()); 828 if (config.getDeviceConfigByName(deviceName).getDeviceOptions() 829 .isLogcatCaptureEnabled()) { 830 if (!(context.getDevice(deviceName).getIDevice() instanceof StubDevice)) { 831 context.getDevice(deviceName).startLogcat(); 832 } 833 } 834 } 835 836 String cmdLineArgs = config.getCommandLine(); 837 if (cmdLineArgs != null) { 838 CLog.i("Invocation was started with cmd: %s", cmdLineArgs); 839 } 840 updateInvocationContext(context, config); 841 // TODO: evaluate fetching build in parallel 842 for (String deviceName : context.getDeviceConfigNames()) { 843 currentDeviceName = deviceName; 844 IBuildInfo info = null; 845 ITestDevice device = context.getDevice(deviceName); 846 IDeviceConfiguration deviceConfig = config.getDeviceConfigByName(deviceName); 847 IBuildProvider provider = deviceConfig.getBuildProvider(); 848 // Set the provider test tag 849 if (provider instanceof IInvocationContextReceiver) { 850 ((IInvocationContextReceiver)provider).setInvocationContext(context); 851 } 852 // Get the build 853 if (provider instanceof IDeviceBuildProvider) { 854 info = ((IDeviceBuildProvider)provider).getBuild(device); 855 } else { 856 info = provider.getBuild(); 857 } 858 if (info != null) { 859 info.setDeviceSerial(device.getSerialNumber()); 860 context.addDeviceBuildInfo(deviceName, info); 861 device.setRecovery(deviceConfig.getDeviceRecovery()); 862 } else { 863 mStatus = "(no build to test)"; 864 CLog.logAndDisplay( 865 LogLevel.WARN, 866 "No build found to test for device: %s", 867 device.getSerialNumber()); 868 rescheduleTest(config, rescheduler); 869 // save current log contents to global log 870 getLogRegistry().dumpToGlobalLog(config.getLogOutput()); 871 // Set the exit code to error 872 setExitCode(ExitCode.NO_BUILD, 873 new BuildRetrievalError("No build found to test.")); 874 return; 875 } 876 // TODO: remove build update when reporting is done on context 877 updateBuild(info, config); 878 } 879 if (shardConfig(config, context, rescheduler)) { 880 CLog.i("Invocation for %s has been sharded, rescheduling", 881 context.getSerials().toString()); 882 } else { 883 if (config.getTests() == null || config.getTests().isEmpty()) { 884 CLog.e("No tests to run"); 885 } else { 886 performInvocation(config, context, rescheduler, listener); 887 setExitCode(ExitCode.NO_ERROR, null); 888 } 889 } 890 } catch (BuildRetrievalError e) { 891 CLog.e(e); 892 if (currentDeviceName != null) { 893 context.addDeviceBuildInfo(currentDeviceName, e.getBuildInfo()); 894 updateInvocationContext(context, config); 895 } 896 // report an empty invocation, so this error is sent to listeners 897 startInvocation(config, context, listener); 898 // don't want to use #reportFailure, since that will call buildNotTested 899 listener.invocationFailed(e); 900 for (ITestDevice device : context.getDevices()) { 901 reportLogs(device, listener, Stage.ERROR); 902 } 903 reportHostLog(listener, config.getLogOutput()); 904 listener.invocationEnded(0); 905 return; 906 } catch (IOException e) { 907 CLog.e(e); 908 } finally { 909 // ensure we always deregister the logger 910 for (String deviceName : context.getDeviceConfigNames()) { 911 if (!(context.getDevice(deviceName).getIDevice() instanceof StubDevice)) { 912 context.getDevice(deviceName).stopLogcat(); 913 } 914 } 915 // save remaining logs contents to global log 916 getLogRegistry().dumpToGlobalLog(config.getLogOutput()); 917 // Ensure log is unregistered and closed 918 getLogRegistry().unregisterLogger(); 919 config.getLogOutput().closeLog(); 920 } 921 } 922 923 /** 924 * Helper to set the exit code. Exposed for testing. 925 */ 926 protected void setExitCode(ExitCode code, Throwable stack) { 927 GlobalConfiguration.getInstance().getCommandScheduler() 928 .setLastInvocationExitCode(code, stack); 929 } 930 931 public static String getDeviceLogName(Stage stage) { 932 return DEVICE_LOG_NAME_PREFIX + stage.getName(); 933 } 934 935 public static String getEmulatorLogName(Stage stage) { 936 return EMULATOR_LOG_NAME_PREFIX + stage.getName(); 937 } 938 939 @Override 940 public void notifyInvocationStopped() { 941 mStopRequested = true; 942 } 943 } 944
