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 17 package com.android.tradefed.command; 18 19 import com.android.ddmlib.DdmPreferences; 20 import com.android.ddmlib.Log; 21 import com.android.ddmlib.Log.LogLevel; 22 import com.android.tradefed.clearcut.ClearcutClient; 23 import com.android.tradefed.command.CommandFileParser.CommandLine; 24 import com.android.tradefed.command.CommandFileWatcher.ICommandFileListener; 25 import com.android.tradefed.command.CommandRunner.ExitCode; 26 import com.android.tradefed.command.remote.DeviceDescriptor; 27 import com.android.tradefed.command.remote.IRemoteClient; 28 import com.android.tradefed.command.remote.RemoteClient; 29 import com.android.tradefed.command.remote.RemoteException; 30 import com.android.tradefed.command.remote.RemoteManager; 31 import com.android.tradefed.config.ConfigurationDescriptor; 32 import com.android.tradefed.config.ConfigurationException; 33 import com.android.tradefed.config.ConfigurationFactory; 34 import com.android.tradefed.config.GlobalConfiguration; 35 import com.android.tradefed.config.IConfiguration; 36 import com.android.tradefed.config.IConfigurationFactory; 37 import com.android.tradefed.config.IDeviceConfiguration; 38 import com.android.tradefed.config.IGlobalConfiguration; 39 import com.android.tradefed.config.Option; 40 import com.android.tradefed.config.RetryConfigurationFactory; 41 import com.android.tradefed.config.SandboxConfigurationFactory; 42 import com.android.tradefed.device.DeviceAllocationState; 43 import com.android.tradefed.device.DeviceManager; 44 import com.android.tradefed.device.DeviceNotAvailableException; 45 import com.android.tradefed.device.DeviceUnresponsiveException; 46 import com.android.tradefed.device.FreeDeviceState; 47 import com.android.tradefed.device.IDeviceManager; 48 import com.android.tradefed.device.IDeviceMonitor; 49 import com.android.tradefed.device.IManagedTestDevice; 50 import com.android.tradefed.device.ITestDevice; 51 import com.android.tradefed.device.ITestDevice.RecoveryMode; 52 import com.android.tradefed.device.NoDeviceException; 53 import com.android.tradefed.device.StubDevice; 54 import com.android.tradefed.device.TestDeviceState; 55 import com.android.tradefed.invoker.IInvocationContext; 56 import com.android.tradefed.invoker.IRescheduler; 57 import com.android.tradefed.invoker.ITestInvocation; 58 import com.android.tradefed.invoker.InvocationContext; 59 import com.android.tradefed.invoker.TestInvocation; 60 import com.android.tradefed.log.ILogRegistry.EventType; 61 import com.android.tradefed.log.LogRegistry; 62 import com.android.tradefed.log.LogUtil.CLog; 63 import com.android.tradefed.result.ITestInvocationListener; 64 import com.android.tradefed.result.ResultForwarder; 65 import com.android.tradefed.sandbox.ISandbox; 66 import com.android.tradefed.sandbox.TradefedSandbox; 67 import com.android.tradefed.testtype.IRemoteTest; 68 import com.android.tradefed.testtype.suite.retry.RetryRescheduler; 69 import com.android.tradefed.util.ArrayUtil; 70 import com.android.tradefed.util.FileUtil; 71 import com.android.tradefed.util.QuotationAwareTokenizer; 72 import com.android.tradefed.util.RunUtil; 73 import com.android.tradefed.util.StreamUtil; 74 import com.android.tradefed.util.TableFormatter; 75 import com.android.tradefed.util.TimeUtil; 76 import com.android.tradefed.util.hostmetric.IHostMonitor; 77 import com.android.tradefed.util.hostmetric.IHostMonitor.HostDataPoint; 78 import com.android.tradefed.util.hostmetric.IHostMonitor.HostMetricType; 79 import com.android.tradefed.util.keystore.IKeyStoreClient; 80 import com.android.tradefed.util.keystore.IKeyStoreFactory; 81 import com.android.tradefed.util.keystore.KeyStoreException; 82 83 import com.google.common.annotations.VisibleForTesting; 84 85 import org.json.JSONException; 86 87 import java.io.File; 88 import java.io.IOException; 89 import java.io.PrintWriter; 90 import java.util.ArrayList; 91 import java.util.Arrays; 92 import java.util.Collections; 93 import java.util.Comparator; 94 import java.util.HashMap; 95 import java.util.HashSet; 96 import java.util.Iterator; 97 import java.util.LinkedHashMap; 98 import java.util.LinkedHashSet; 99 import java.util.LinkedList; 100 import java.util.List; 101 import java.util.Map; 102 import java.util.Set; 103 import java.util.Timer; 104 import java.util.TimerTask; 105 import java.util.concurrent.CountDownLatch; 106 import java.util.concurrent.ScheduledThreadPoolExecutor; 107 import java.util.concurrent.TimeUnit; 108 import java.util.regex.Pattern; 109 110 /** 111 * A scheduler for running TradeFederation commands across all available devices. 112 * <p/> 113 * Will attempt to prioritize commands to run based on a total running count of their execution 114 * time. e.g. infrequent or fast running commands will get prioritized over long running commands. 115 * <p/> 116 * Runs forever in background until shutdown. 117 */ 118 public class CommandScheduler extends Thread implements ICommandScheduler, ICommandFileListener { 119 120 /** the queue of commands ready to be executed. */ 121 private List<ExecutableCommand> mReadyCommands; 122 private Set<ExecutableCommand> mUnscheduledWarning; 123 124 /** the queue of commands sleeping. */ 125 private Set<ExecutableCommand> mSleepingCommands; 126 127 /** the queue of commands current executing. */ 128 private Set<ExecutableCommand> mExecutingCommands; 129 130 /** map of device to active invocation threads */ 131 private Map<IInvocationContext, InvocationThread> mInvocationThreadMap; 132 133 /** timer for scheduling commands to be re-queued for execution */ 134 private ScheduledThreadPoolExecutor mCommandTimer; 135 136 private IRemoteClient mRemoteClient = null; 137 private RemoteManager mRemoteManager = null; 138 139 private CommandFileWatcher mCommandFileWatcher = null; 140 141 /** latch used to notify other threads that this thread is running */ 142 private final CountDownLatch mRunLatch; 143 144 /** maximum time to wait for handover initiation to complete */ 145 private static final long MAX_HANDOVER_INIT_TIME = 2 * 60 * 1000; 146 147 /** Maximum time to wait for adb to initialize and get the physical devices discovered */ 148 private static final long ADB_INIT_TIME_MS = 500; 149 150 /** used to assign unique ids to each CommandTracker created */ 151 private int mCurrentCommandId = 0; 152 153 /** flag for instructing scheduler to exit when no commands are present */ 154 private boolean mShutdownOnEmpty = false; 155 156 private boolean mStarted = false; 157 158 // flag to indicate this scheduler is currently handing over control to another remote TF 159 private boolean mPerformingHandover = false; 160 161 private WaitObj mHandoverHandshake = new WaitObj(); 162 163 private WaitObj mCommandProcessWait = new WaitObj(); 164 165 /** The last {@link InvocationThread} that ran error code and error stack*/ 166 private ExitCode mLastInvocationExitCode = ExitCode.NO_ERROR; 167 private Throwable mLastInvocationThrowable = null; 168 169 /** Client to report metric data of the harness. */ 170 private ClearcutClient mClient = null; 171 172 @Option(name = "reload-cmdfiles", description = 173 "Whether to enable the command file autoreload mechanism") 174 // FIXME: enable this to be enabled or disabled on a per-cmdfile basis 175 private boolean mReloadCmdfiles = false; 176 177 @Option( 178 name = "max-poll-time", 179 description = "ms between forced command scheduler execution time" 180 ) 181 private long mPollTime = 30 * 1000; // 30 seconds 182 183 @Option(name = "shutdown-on-cmdfile-error", description = 184 "terminate TF session if a configuration exception on command file occurs") 185 private boolean mShutdownOnCmdfileError = false; 186 187 @Option(name = "shutdown-delay", description = 188 "maximum time to wait before allowing final interruption of scheduler to terminate" 189 + " TF session. If value is zero, interruption will only be triggered" 190 + " when Invocation become interruptible. (Default behavior).", isTimeVal = true) 191 private long mShutdownTimeout = 0; 192 193 private HostState mHostState = HostState.UNKNOWN; 194 195 private enum CommandState { 196 WAITING_FOR_DEVICE("Wait_for_device"), 197 EXECUTING("Executing"), 198 SLEEPING("Sleeping"); 199 200 private final String mDisplayName; 201 CommandState(String displayName)202 CommandState(String displayName) { 203 mDisplayName = displayName; 204 } 205 getDisplayName()206 public String getDisplayName() { 207 return mDisplayName; 208 } 209 } 210 211 /** Enums of different status of host */ 212 public enum HostState { 213 UNKNOWN, 214 RUNNING, 215 QUITTING, 216 KILLING; 217 } 218 setHostState(HostState state)219 private void setHostState(HostState state) { 220 mHostState = state; 221 } 222 getHostState()223 public HostState getHostState() { 224 return mHostState; 225 } 226 227 /** 228 * Represents one active command added to the scheduler. Will track total execution time of all 229 * instances of this command 230 */ 231 static class CommandTracker { 232 private final int mId; 233 private final String[] mArgs; 234 private final String mCommandFilePath; 235 236 /** the total amount of time this command was executing. Used to prioritize */ 237 private long mTotalExecTime = 0; 238 CommandTracker(int id, String[] args, String commandFilePath)239 CommandTracker(int id, String[] args, String commandFilePath) { 240 mId = id; 241 mArgs = args; 242 mCommandFilePath = commandFilePath; 243 } 244 incrementExecTime(long execTime)245 synchronized void incrementExecTime(long execTime) { 246 mTotalExecTime += execTime; 247 } 248 249 /** 250 * @return the total amount of execution time for this command. 251 */ getTotalExecTime()252 synchronized long getTotalExecTime() { 253 return mTotalExecTime; 254 } 255 256 /** 257 * Get the full list of config arguments associated with this command. 258 */ getArgs()259 String[] getArgs() { 260 return mArgs; 261 } 262 getId()263 int getId() { 264 return mId; 265 } 266 267 /** 268 * Return the path of the file this command is associated with. null if not applicable 269 */ getCommandFilePath()270 String getCommandFilePath() { 271 return mCommandFilePath; 272 } 273 } 274 275 /** 276 * Represents one instance of a command to be executed. 277 */ 278 private class ExecutableCommand { 279 private final CommandTracker mCmdTracker; 280 private final IConfiguration mConfig; 281 private final boolean mRescheduled; 282 private final long mCreationTime; 283 private Long mSleepTime; 284 ExecutableCommand(CommandTracker tracker, IConfiguration config, boolean rescheduled)285 private ExecutableCommand(CommandTracker tracker, IConfiguration config, 286 boolean rescheduled) { 287 mConfig = config; 288 mCmdTracker = tracker; 289 mRescheduled = rescheduled; 290 mCreationTime = System.currentTimeMillis(); 291 } 292 293 /** 294 * Gets the {@link IConfiguration} for this command instance 295 */ getConfiguration()296 public IConfiguration getConfiguration() { 297 return mConfig; 298 } 299 300 /** 301 * Gets the associated {@link CommandTracker}. 302 */ getCommandTracker()303 CommandTracker getCommandTracker() { 304 return mCmdTracker; 305 } 306 307 /** 308 * Callback to inform listener that command has started execution. 309 */ commandStarted()310 void commandStarted() { 311 mSleepTime = null; 312 } 313 commandFinished(long elapsedTime)314 public void commandFinished(long elapsedTime) { 315 getCommandTracker().incrementExecTime(elapsedTime); 316 CLog.d("removing exec command for id %d", getCommandTracker().getId()); 317 synchronized (CommandScheduler.this) { 318 mExecutingCommands.remove(this); 319 } 320 if (isShuttingDown()) { 321 mCommandProcessWait.signalEventReceived(); 322 } 323 } 324 isRescheduled()325 public boolean isRescheduled() { 326 return mRescheduled; 327 } 328 getCreationTime()329 public long getCreationTime() { 330 return mCreationTime; 331 } 332 isLoopMode()333 public boolean isLoopMode() { 334 return mConfig.getCommandOptions().isLoopMode(); 335 } 336 getSleepTime()337 public Long getSleepTime() { 338 return mSleepTime; 339 } 340 getCommandFilePath()341 public String getCommandFilePath() { 342 return mCmdTracker.getCommandFilePath(); 343 } 344 } 345 346 /** 347 * struct for a command and its state 348 */ 349 private static class ExecutableCommandState { 350 final ExecutableCommand cmd; 351 final CommandState state; 352 ExecutableCommandState(ExecutableCommand cmd, CommandState state)353 ExecutableCommandState(ExecutableCommand cmd, CommandState state) { 354 this.cmd = cmd; 355 this.state = state; 356 } 357 } 358 359 /** 360 * A {@link IRescheduler} that will add a command back to the queue. 361 */ 362 private class Rescheduler implements IRescheduler { 363 364 private CommandTracker mCmdTracker; 365 Rescheduler(CommandTracker cmdTracker)366 Rescheduler(CommandTracker cmdTracker) { 367 mCmdTracker = cmdTracker; 368 } 369 370 /** 371 * {@inheritDoc} 372 */ 373 @Override scheduleConfig(IConfiguration config)374 public boolean scheduleConfig(IConfiguration config) { 375 // force loop mode to off, otherwise each rescheduled config will be treated as 376 // a new command and added back to queue 377 config.getCommandOptions().setLoopMode(false); 378 ExecutableCommand rescheduledCmd = createExecutableCommand(mCmdTracker, config, true); 379 return addExecCommandToQueue(rescheduledCmd, 0); 380 } 381 382 /** 383 * {@inheritDoc} 384 */ 385 @Override rescheduleCommand()386 public boolean rescheduleCommand() { 387 try { 388 CLog.d("rescheduling for command %d", mCmdTracker.getId()); 389 IConfiguration config = getConfigFactory().createConfigurationFromArgs( 390 mCmdTracker.getArgs()); 391 ExecutableCommand execCmd = createExecutableCommand(mCmdTracker, config, true); 392 return addExecCommandToQueue(execCmd, config.getCommandOptions().getLoopTime()); 393 } catch (ConfigurationException e) { 394 // FIXME: do this with jline somehow for ANSI support 395 // note: make sure not to log (aka record) this line, as (args) may contain 396 // passwords. 397 System.out.println(String.format("Error while processing args: %s", 398 Arrays.toString(mCmdTracker.getArgs()))); 399 System.out.println(e.getMessage()); 400 System.out.println(); 401 return false; 402 } 403 } 404 } 405 406 /** 407 * Comparator for {@link ExecutableCommand}. 408 * <p/> 409 * Delegates to {@link CommandTrackerTimeComparator}. 410 */ 411 private static class ExecutableCommandComparator implements Comparator<ExecutableCommand> { 412 CommandTrackerTimeComparator mTrackerComparator = new CommandTrackerTimeComparator(); 413 414 /** 415 * {@inheritDoc} 416 */ 417 @Override compare(ExecutableCommand c1, ExecutableCommand c2)418 public int compare(ExecutableCommand c1, ExecutableCommand c2) { 419 return mTrackerComparator.compare(c1.getCommandTracker(), c2.getCommandTracker()); 420 } 421 } 422 423 /** 424 * Comparator for {@link CommandTracker}. 425 * <p/> 426 * Compares by mTotalExecTime, prioritizing configs with lower execution time 427 */ 428 private static class CommandTrackerTimeComparator implements Comparator<CommandTracker> { 429 430 @Override compare(CommandTracker c1, CommandTracker c2)431 public int compare(CommandTracker c1, CommandTracker c2) { 432 if (c1.getTotalExecTime() == c2.getTotalExecTime()) { 433 return 0; 434 } else if (c1.getTotalExecTime() < c2.getTotalExecTime()) { 435 return -1; 436 } else { 437 return 1; 438 } 439 } 440 } 441 442 /** 443 * Comparator for {@link CommandTracker}. 444 * <p/> 445 * Compares by id. 446 */ 447 static class CommandTrackerIdComparator implements Comparator<CommandTracker> { 448 449 @Override compare(CommandTracker c1, CommandTracker c2)450 public int compare(CommandTracker c1, CommandTracker c2) { 451 if (c1.getId() == c2.getId()) { 452 return 0; 453 } else if (c1.getId() < c2.getId()) { 454 return -1; 455 } else { 456 return 1; 457 } 458 } 459 } 460 461 /** 462 * An {@link com.android.tradefed.command.ICommandScheduler.IScheduledInvocationListener} 463 * for locally scheduled commands added via addCommand. 464 * <p/> 465 * Returns device to device manager and remote handover server if applicable. 466 */ 467 private class FreeDeviceHandler extends ResultForwarder implements 468 IScheduledInvocationListener { 469 470 private final IDeviceManager mDeviceManager; 471 FreeDeviceHandler(IDeviceManager deviceManager, IScheduledInvocationListener... listeners)472 FreeDeviceHandler(IDeviceManager deviceManager, 473 IScheduledInvocationListener... listeners) { 474 super(listeners); 475 mDeviceManager = deviceManager; 476 } 477 478 @Override invocationComplete(IInvocationContext context, Map<ITestDevice, FreeDeviceState> devicesStates)479 public void invocationComplete(IInvocationContext context, 480 Map<ITestDevice, FreeDeviceState> devicesStates) { 481 for (ITestInvocationListener listener : getListeners()) { 482 ((IScheduledInvocationListener) listener).invocationComplete(context, devicesStates); 483 } 484 485 for (ITestDevice device : context.getDevices()) { 486 mDeviceManager.freeDevice(device, devicesStates.get(device)); 487 remoteFreeDevice(device); 488 if (device instanceof IManagedTestDevice) { 489 // This quite an important setting so we do make sure it's reset. 490 ((IManagedTestDevice)device).setFastbootPath(mDeviceManager.getFastbootPath()); 491 } 492 } 493 } 494 } 495 496 /** 497 * Monitor Class for {@link InvocationThread} to make sure it does not run for too long. 498 */ 499 private class InvocationThreadMonitor extends TimerTask { 500 501 private InvocationThread mInvocationThread = null; 502 private boolean mTriggered = false; 503 InvocationThreadMonitor(InvocationThread toMonitor)504 public InvocationThreadMonitor(InvocationThread toMonitor) { 505 mInvocationThread = toMonitor; 506 } 507 508 @Override run()509 public void run() { 510 if (mInvocationThread != null) { 511 mTriggered = true; 512 mInvocationThread.stopInvocation("Invocation Timeout Reached."); 513 } 514 } 515 isTriggered()516 public boolean isTriggered() { 517 return mTriggered; 518 } 519 } 520 521 private class InvocationThread extends Thread { 522 /** 523 * time to wait for device adb shell responsive connection before declaring it unavailable 524 * for the next iteration of testing. 525 */ 526 private static final long CHECK_WAIT_DEVICE_AVAIL_MS = 30 * 1000; 527 private static final int EXPECTED_THREAD_COUNT = 1; 528 private static final String INVOC_END_EVENT_ID_KEY = "id"; 529 private static final String INVOC_END_EVENT_ELAPSED_KEY = "elapsed-time"; 530 private static final String INVOC_END_EVENT_TAG_KEY = "test-tag"; 531 532 private final IScheduledInvocationListener[] mListeners; 533 private final IInvocationContext mInvocationContext; 534 private final ExecutableCommand mCmd; 535 private final ITestInvocation mInvocation; 536 private final InvocationThreadMonitor mInvocationThreadMonitor; 537 private final Timer mExecutionTimer; 538 private long mStartTime = -1; 539 InvocationThread(String name, IInvocationContext invocationContext, ExecutableCommand command, IScheduledInvocationListener... listeners)540 public InvocationThread(String name, IInvocationContext invocationContext, 541 ExecutableCommand command, IScheduledInvocationListener... listeners) { 542 // create a thread group so LoggerRegistry can identify this as an invocationThread 543 super(new ThreadGroup(name), name); 544 mListeners = listeners; 545 mInvocationContext = invocationContext; 546 mCmd = command; 547 mInvocation = createRunInstance(); 548 549 // Daemon timer 550 mExecutionTimer = new Timer(true); 551 mInvocationThreadMonitor = new InvocationThreadMonitor(this); 552 } 553 getStartTime()554 public long getStartTime() { 555 return mStartTime; 556 } 557 558 @Override run()559 public void run() { 560 Map<ITestDevice, FreeDeviceState> deviceStates = new HashMap<>(); 561 for (ITestDevice device : mInvocationContext.getDevices()) { 562 deviceStates.put(device, FreeDeviceState.AVAILABLE); 563 } 564 mStartTime = System.currentTimeMillis(); 565 ITestInvocation instance = getInvocation(); 566 IConfiguration config = mCmd.getConfiguration(); 567 568 for (final IScheduledInvocationListener listener : mListeners) { 569 try { 570 listener.invocationInitiated(mInvocationContext); 571 } catch (Throwable anyException) { 572 CLog.e("Exception caught while calling invocationInitiated:"); 573 CLog.e(anyException); 574 } 575 } 576 577 try { 578 // Copy the command options invocation attributes to the invocation if it has not 579 // been already done. 580 if (!config.getConfigurationDescription().shouldUseSandbox() 581 && !config.getCommandOptions().getInvocationData().isEmpty()) { 582 mInvocationContext.addInvocationAttributes( 583 config.getCommandOptions().getInvocationData()); 584 } 585 mCmd.commandStarted(); 586 long invocTimeout = config.getCommandOptions().getInvocationTimeout(); 587 if (invocTimeout > 0) { 588 CLog.i("Setting a timer for the invocation in %sms", invocTimeout); 589 mExecutionTimer.schedule(mInvocationThreadMonitor, invocTimeout); 590 } 591 instance.invoke(mInvocationContext, config, 592 new Rescheduler(mCmd.getCommandTracker()), mListeners); 593 } catch (DeviceUnresponsiveException e) { 594 CLog.w("Device %s is unresponsive. Reason: %s", e.getSerial(), e.getMessage()); 595 ITestDevice badDevice = mInvocationContext.getDeviceBySerial(e.getSerial()); 596 if (badDevice != null) { 597 deviceStates.put(badDevice, FreeDeviceState.UNRESPONSIVE); 598 } 599 setLastInvocationExitCode(ExitCode.DEVICE_UNRESPONSIVE, e); 600 } catch (DeviceNotAvailableException e) { 601 CLog.w("Device %s is not available. Reason: %s", e.getSerial(), e.getMessage()); 602 ITestDevice badDevice = mInvocationContext.getDeviceBySerial(e.getSerial()); 603 if (badDevice != null) { 604 deviceStates.put(badDevice, FreeDeviceState.UNAVAILABLE); 605 } 606 setLastInvocationExitCode(ExitCode.DEVICE_UNAVAILABLE, e); 607 } catch (FatalHostError e) { 608 CLog.wtf(String.format("Fatal error occurred: %s, shutting down", e.getMessage()), 609 e); 610 setLastInvocationExitCode(ExitCode.FATAL_HOST_ERROR, e); 611 shutdown(); 612 } catch (Throwable e) { 613 setLastInvocationExitCode(ExitCode.THROWABLE_EXCEPTION, e); 614 CLog.e(e); 615 } finally { 616 mExecutionTimer.cancel(); 617 if (mInvocationThreadMonitor.isTriggered()) { 618 CLog.e("Invocation reached its timeout. Cleaning up."); 619 } 620 long elapsedTime = System.currentTimeMillis() - mStartTime; 621 CLog.i("Updating command %d with elapsed time %d ms", 622 mCmd.getCommandTracker().getId(), elapsedTime); 623 // remove invocation thread first so another invocation can be started on device 624 // when freed 625 removeInvocationThread(this); 626 for (ITestDevice device : mInvocationContext.getDevices()) { 627 if (device.getIDevice() instanceof StubDevice) { 628 // Never release stub and Tcp devices, otherwise they will disappear 629 // during deallocation since they are only placeholder. 630 deviceStates.put(device, FreeDeviceState.AVAILABLE); 631 } else if (!TestDeviceState.ONLINE.equals(device.getDeviceState())) { 632 // If the device is offline at the end of the test 633 deviceStates.put(device, FreeDeviceState.UNAVAILABLE); 634 } else if (!isDeviceResponsive(device)) { 635 // If device cannot pass basic shell responsiveness test. 636 deviceStates.put(device, FreeDeviceState.UNAVAILABLE); 637 } 638 // Reset the recovery mode at the end of the invocation. 639 device.setRecoveryMode(RecoveryMode.AVAILABLE); 640 } 641 642 checkStrayThreads(); 643 644 for (final IScheduledInvocationListener listener : mListeners) { 645 try { 646 listener.invocationComplete(mInvocationContext, deviceStates); 647 } catch (Throwable anyException) { 648 CLog.e("Exception caught while calling invocationComplete:"); 649 CLog.e(anyException); 650 } 651 } 652 mCmd.commandFinished(elapsedTime); 653 logInvocationEndedEvent( 654 mCmd.getCommandTracker().getId(), elapsedTime, mInvocationContext); 655 } 656 } 657 658 /** Check the number of thread in the ThreadGroup, only one should exists (itself). */ checkStrayThreads()659 private void checkStrayThreads() { 660 int numThread = this.getThreadGroup().activeCount(); 661 if (numThread == EXPECTED_THREAD_COUNT) { 662 // No stray thread detected at the end of invocation 663 return; 664 } 665 List<String> cmd = Arrays.asList(mCmd.getCommandTracker().getArgs()); 666 CLog.e( 667 "Stray thread detected for command %d, %s. %d threads instead of %d", 668 mCmd.getCommandTracker().getId(), cmd, numThread, EXPECTED_THREAD_COUNT); 669 // This is the best we have for debug, it prints to std out. 670 Thread[] listThreads = new Thread[numThread]; 671 this.getThreadGroup().enumerate(listThreads); 672 CLog.e("List of remaining threads: %s", Arrays.asList(listThreads)); 673 List<IHostMonitor> hostMonitors = GlobalConfiguration.getHostMonitorInstances(); 674 if (hostMonitors != null) { 675 for (IHostMonitor hm : hostMonitors) { 676 HostDataPoint data = new HostDataPoint("numThread", numThread, cmd.toString()); 677 hm.addHostEvent(HostMetricType.INVOCATION_STRAY_THREAD, data); 678 } 679 } 680 // printing to stderr will help to catch them. 681 System.err.println( 682 String.format( 683 "We have %s threads instead of 1: %s. Check the logs for list of " 684 + "threads.", 685 numThread, Arrays.asList(listThreads))); 686 } 687 688 /** Helper to log an invocation ended event. */ logInvocationEndedEvent( int invocId, long elapsedTime, final IInvocationContext context)689 private void logInvocationEndedEvent( 690 int invocId, long elapsedTime, final IInvocationContext context) { 691 Map<String, String> args = new HashMap<>(); 692 args.put(INVOC_END_EVENT_ID_KEY, Integer.toString(invocId)); 693 args.put(INVOC_END_EVENT_ELAPSED_KEY, TimeUtil.formatElapsedTime(elapsedTime)); 694 args.put(INVOC_END_EVENT_TAG_KEY, context.getTestTag()); 695 // Add all the invocation attributes to the final event logging. 696 // UniqueMultiMap cannot be easily converted to Map so we just iterate. 697 for (String key : context.getAttributes().keySet()) { 698 args.put(key, context.getAttributes().get(key).get(0)); 699 } 700 logEvent(EventType.INVOCATION_END, args); 701 } 702 703 /** Basic responsiveness check at the end of an invocation. */ isDeviceResponsive(ITestDevice device)704 private boolean isDeviceResponsive(ITestDevice device) { 705 return device.waitForDeviceShell(CHECK_WAIT_DEVICE_AVAIL_MS); 706 } 707 getInvocation()708 ITestInvocation getInvocation() { 709 return mInvocation; 710 } 711 getInvocationContext()712 IInvocationContext getInvocationContext() { 713 return mInvocationContext; 714 } 715 716 /** 717 * Stops a running invocation. {@link CommandScheduler#shutdownHard()} will stop all running 718 * invocations. 719 */ stopInvocation(String message)720 public void stopInvocation(String message) { 721 getInvocation().notifyInvocationStopped(); 722 for (ITestDevice device : mInvocationContext.getDevices()) { 723 if (TestDeviceState.ONLINE.equals(device.getDeviceState())) { 724 // Kill all running processes on device. 725 if (!(device.getIDevice() instanceof StubDevice)) { 726 try { 727 device.executeShellCommand("am kill-all"); 728 } catch (DeviceNotAvailableException e) { 729 CLog.e("failed to kill process on device %s", device.getSerialNumber()); 730 CLog.e(e); 731 } 732 } 733 } 734 // Finish with device tear down: We try to ensure that regardless of the invocation 735 // state during the interruption we at least do minimal tear down of devices with 736 // their built-in clean up. 737 CLog.d("Attempting postInvocationTearDown in stopInvocation"); 738 device.postInvocationTearDown(); 739 } 740 // If invocation is not currently in an interruptible state we provide a timer 741 // after which it will become interruptible. 742 // If timeout is 0, we do not enforce future interruption. 743 if (getShutdownTimeout() != 0) { 744 RunUtil.getDefault().setInterruptibleInFuture(this, getShutdownTimeout()); 745 } 746 RunUtil.getDefault().interrupt(this, message); 747 } 748 749 /** 750 * Disable the reporting from reporters that implements a non-default 751 * {@link ITestInvocationListener#invocationInterrupted()}. 752 * Should be called on shutdown. 753 */ disableReporters()754 public void disableReporters() { 755 for (ITestInvocationListener listener : 756 mCmd.getConfiguration().getTestInvocationListeners()) { 757 listener.invocationInterrupted(); 758 } 759 } 760 761 /** 762 * Checks whether the device battery level is above the required value to keep running the 763 * invocation. 764 */ checkDeviceBatteryLevel()765 public void checkDeviceBatteryLevel() { 766 for (String deviceName : mInvocationContext.getDeviceConfigNames()) { 767 if (mCmd.getConfiguration().getDeviceConfigByName(deviceName) 768 .getDeviceOptions() == null) { 769 CLog.d("No deviceOptions in the configuration, cannot do Battery level check"); 770 return; 771 } 772 final Integer cutoffBattery = mCmd.getConfiguration() 773 .getDeviceConfigByName(deviceName).getDeviceOptions().getCutoffBattery(); 774 775 if (mInvocationContext.getDevice(deviceName) != null && cutoffBattery != null) { 776 final ITestDevice device = mInvocationContext.getDevice(deviceName); 777 Integer batteryLevel = device.getBattery(); 778 if (batteryLevel == null) { 779 return; 780 } 781 CLog.d("device %s: battery level=%d%%", device.getSerialNumber(), batteryLevel); 782 // This logic is based on the assumption that batterLevel will be 0 or -1 if TF 783 // fails to fetch a valid battery level or the device is not using a battery. 784 // So batteryLevel=0 will not trigger a stop. 785 if (0 < batteryLevel && batteryLevel < cutoffBattery) { 786 if (RunUtil.getDefault().isInterruptAllowed()) { 787 CLog.i("Stopping %s: battery too low (%d%% < %d%%)", 788 getName(), batteryLevel, cutoffBattery); 789 stopInvocation( 790 String.format( 791 "battery too low (%d%% < %d%%)", 792 batteryLevel, cutoffBattery)); 793 } else { 794 // In this case, the battery is check periodically by CommandScheduler 795 // so there will be more opportunity to terminate the invocation when 796 // it's interruptible. 797 CLog.w("device: %s has a low battery but is in uninterruptible state.", 798 device.getSerialNumber()); 799 } 800 } 801 } 802 } 803 } 804 } 805 806 /** 807 * A {@link IDeviceMonitor} that signals scheduler to process commands when an available device 808 * is added. 809 */ 810 private class AvailDeviceMonitor implements IDeviceMonitor { 811 812 @Override run()813 public void run() { 814 // ignore 815 } 816 817 @Override stop()818 public void stop() { 819 // ignore 820 } 821 822 @Override setDeviceLister(DeviceLister lister)823 public void setDeviceLister(DeviceLister lister) { 824 // ignore 825 } 826 827 @Override notifyDeviceStateChange(String serial, DeviceAllocationState oldState, DeviceAllocationState newState)828 public void notifyDeviceStateChange(String serial, DeviceAllocationState oldState, 829 DeviceAllocationState newState) { 830 if (newState.equals(DeviceAllocationState.Available)) { 831 // new avail device was added, wake up scheduler 832 mCommandProcessWait.signalEventReceived(); 833 } 834 } 835 } 836 837 /** 838 * Creates a {@link CommandScheduler}. 839 * <p /> 840 * Note: start must be called before use. 841 */ CommandScheduler()842 public CommandScheduler() { 843 super("CommandScheduler"); // set the thread name 844 mReadyCommands = new LinkedList<>(); 845 mUnscheduledWarning = new HashSet<>(); 846 mSleepingCommands = new HashSet<>(); 847 mExecutingCommands = new HashSet<>(); 848 mInvocationThreadMap = new HashMap<IInvocationContext, InvocationThread>(); 849 // use a ScheduledThreadPoolExecutorTimer as a single-threaded timer. This class 850 // is used instead of a java.util.Timer because it offers advanced shutdown options 851 mCommandTimer = new ScheduledThreadPoolExecutor(1); 852 mRunLatch = new CountDownLatch(1); 853 } 854 855 /** 856 * Starts the scheduler including setting up of logging, init of {@link DeviceManager} etc 857 */ 858 @Override start()859 public void start() { 860 synchronized (this) { 861 if (mStarted) { 862 throw new IllegalStateException("scheduler has already been started"); 863 } 864 initLogging(); 865 866 initDeviceManager(); 867 868 mStarted = true; 869 } 870 super.start(); 871 setHostState(HostState.RUNNING); 872 } 873 874 /** 875 * {@inheritDoc} 876 */ 877 @Override getCommandFileWatcher()878 public synchronized CommandFileWatcher getCommandFileWatcher() { 879 assertStarted(); 880 if (mCommandFileWatcher == null) { 881 mCommandFileWatcher = new CommandFileWatcher(this); 882 mCommandFileWatcher.start(); 883 } 884 return mCommandFileWatcher; 885 } 886 887 /** 888 * Initialize the device manager, optionally using a global device filter if specified. 889 */ initDeviceManager()890 void initDeviceManager() { 891 getDeviceManager().init(); 892 if (getDeviceManager().waitForFirstDeviceAdded(ADB_INIT_TIME_MS)) { 893 // If a first device is added we wait a short extra time to allow more devices to be 894 // discovered. 895 RunUtil.getDefault().sleep(ADB_INIT_TIME_MS); 896 } 897 } 898 899 /** 900 * Factory method for creating a {@link TestInvocation}. 901 * 902 * @return the {@link ITestInvocation} to use 903 */ createRunInstance()904 ITestInvocation createRunInstance() { 905 return new TestInvocation(); 906 } 907 908 /** 909 * Factory method for getting a reference to the {@link IDeviceManager} 910 * 911 * @return the {@link IDeviceManager} to use 912 */ getDeviceManager()913 protected IDeviceManager getDeviceManager() { 914 return GlobalConfiguration.getDeviceManagerInstance(); 915 } 916 917 /** 918 * Factory method for getting a reference to the {@link IHostMonitor} 919 * 920 * @return the {@link IHostMonitor} to use 921 */ getHostMonitor()922 List<IHostMonitor> getHostMonitor() { 923 return GlobalConfiguration.getHostMonitorInstances(); 924 } 925 926 /** 927 * Factory method for getting a reference to the {@link IConfigurationFactory} 928 * 929 * @return the {@link IConfigurationFactory} to use 930 */ getConfigFactory()931 protected IConfigurationFactory getConfigFactory() { 932 return ConfigurationFactory.getInstance(); 933 } 934 935 /** 936 * Fetches a {@link IKeyStoreClient} using the {@link IKeyStoreFactory} 937 * declared in {@link IGlobalConfiguration} or null if none is defined. 938 * @return IKeyStoreClient 939 */ getKeyStoreClient()940 protected IKeyStoreClient getKeyStoreClient() { 941 try { 942 IKeyStoreFactory f = GlobalConfiguration.getInstance().getKeyStoreFactory(); 943 if (f != null) { 944 try { 945 return f.createKeyStoreClient(); 946 } catch (KeyStoreException e) { 947 CLog.e("Failed to create key store client"); 948 CLog.e(e); 949 } 950 } 951 } catch (IllegalStateException e) { 952 CLog.w("Global configuration has not been created, failed to get keystore"); 953 CLog.e(e); 954 } 955 return null; 956 } 957 958 /** 959 * The main execution block of this thread. 960 */ 961 @Override run()962 public void run() { 963 assertStarted(); 964 try { 965 IDeviceManager manager = getDeviceManager(); 966 967 startRemoteManager(); 968 969 // Notify other threads that we're running. 970 mRunLatch.countDown(); 971 972 // add a listener that will wake up scheduler when a new avail device is added 973 manager.addDeviceMonitor(new AvailDeviceMonitor()); 974 975 while (!isShutdown()) { 976 // wait until processing is required again 977 mCommandProcessWait.waitAndReset(mPollTime); 978 checkInvocations(); 979 try { 980 processReadyCommands(manager); 981 postProcessReadyCommands(); 982 } catch (RuntimeException e) { 983 CLog.e(e); 984 Map<String, String> information = new HashMap<>(); 985 information.put("Exception", "CommandScheduler"); 986 information.put("stack", StreamUtil.getStackTrace(e)); 987 logEvent(EventType.UNEXPECTED_EXCEPTION, information); 988 } 989 } 990 mCommandTimer.shutdown(); 991 // We signal the device manager to stop device recovery threads because it could 992 // potentially create more invocations. 993 manager.terminateDeviceRecovery(); 994 manager.terminateDeviceMonitor(); 995 CLog.i("Waiting for invocation threads to complete"); 996 waitForAllInvocationThreads(); 997 closeRemoteClient(); 998 if (mRemoteManager != null) { 999 mRemoteManager.cancelAndWait(); 1000 } 1001 exit(manager); 1002 cleanUp(); 1003 CLog.logAndDisplay(LogLevel.INFO, "All done"); 1004 if (mClient != null) { 1005 mClient.stop(); 1006 } 1007 } finally { 1008 // Make sure that we don't quit with messages still in the buffers 1009 System.err.flush(); 1010 System.out.flush(); 1011 } 1012 } 1013 1014 /** 1015 * Placeholder method within the scheduler main loop, called after {@link 1016 * #processReadyCommands(IDeviceManager)}. Default implementation is empty and does not provide 1017 * any extra actions. 1018 */ postProcessReadyCommands()1019 protected void postProcessReadyCommands() {} 1020 checkInvocations()1021 void checkInvocations() { 1022 CLog.d("Checking invocations..."); 1023 final List<InvocationThread> copy; 1024 synchronized(this) { 1025 copy = new ArrayList<InvocationThread>(mInvocationThreadMap.values()); 1026 } 1027 for (InvocationThread thread : copy) { 1028 thread.checkDeviceBatteryLevel(); 1029 } 1030 } 1031 processReadyCommands(IDeviceManager manager)1032 protected void processReadyCommands(IDeviceManager manager) { 1033 CLog.d("processReadyCommands..."); 1034 Map<ExecutableCommand, IInvocationContext> scheduledCommandMap = new HashMap<>(); 1035 // minimize length of synchronized block by just matching commands with device first, 1036 // then scheduling invocations/adding looping commands back to queue 1037 synchronized (this) { 1038 // sort ready commands by priority, so high priority commands are matched first 1039 Collections.sort(mReadyCommands, new ExecutableCommandComparator()); 1040 Iterator<ExecutableCommand> cmdIter = mReadyCommands.iterator(); 1041 while (cmdIter.hasNext()) { 1042 ExecutableCommand cmd = cmdIter.next(); 1043 IConfiguration config = cmd.getConfiguration(); 1044 IInvocationContext context = new InvocationContext(); 1045 context.setConfigurationDescriptor(config.getConfigurationDescription()); 1046 Map<String, ITestDevice> devices = allocateDevices(config, manager); 1047 if (!devices.isEmpty()) { 1048 cmdIter.remove(); 1049 mExecutingCommands.add(cmd); 1050 context.addAllocatedDevice(devices); 1051 1052 // track command matched with device 1053 scheduledCommandMap.put(cmd, context); 1054 // clean warned list to avoid piling over time. 1055 mUnscheduledWarning.remove(cmd); 1056 } else { 1057 if (!mUnscheduledWarning.contains(cmd)) { 1058 CLog.logAndDisplay(LogLevel.DEBUG, "No available device matching all the " 1059 + "config's requirements for cmd id %d.", 1060 cmd.getCommandTracker().getId()); 1061 // make sure not to record since it may contains password 1062 System.out.println( 1063 String.format( 1064 "The command %s will be rescheduled.", 1065 Arrays.toString(cmd.getCommandTracker().getArgs()))); 1066 mUnscheduledWarning.add(cmd); 1067 } 1068 } 1069 } 1070 } 1071 1072 // now actually execute the commands 1073 for (Map.Entry<ExecutableCommand, IInvocationContext> cmdDeviceEntry : scheduledCommandMap 1074 .entrySet()) { 1075 ExecutableCommand cmd = cmdDeviceEntry.getKey(); 1076 startInvocation(cmdDeviceEntry.getValue(), cmd, 1077 new FreeDeviceHandler(getDeviceManager())); 1078 if (cmd.isLoopMode()) { 1079 addNewExecCommandToQueue(cmd.getCommandTracker()); 1080 } 1081 } 1082 CLog.d("done processReadyCommands..."); 1083 } 1084 1085 /** 1086 * {@inheritDoc} 1087 */ 1088 @Override await()1089 public void await() throws InterruptedException { 1090 while (mRunLatch.getCount() > 0) { 1091 mRunLatch.await(); 1092 } 1093 } 1094 closeRemoteClient()1095 private void closeRemoteClient() { 1096 if (mRemoteClient != null) { 1097 try { 1098 mRemoteClient.sendHandoverComplete(); 1099 mRemoteClient.close(); 1100 } catch (RemoteException e) { 1101 CLog.e(e); 1102 } 1103 } 1104 } 1105 waitForThread(Thread thread)1106 private void waitForThread(Thread thread) { 1107 try { 1108 thread.join(); 1109 } catch (InterruptedException e) { 1110 // ignore 1111 waitForThread(thread); 1112 } 1113 } 1114 1115 /** Wait until all invocation threads complete. */ waitForAllInvocationThreads()1116 protected void waitForAllInvocationThreads() { 1117 List<InvocationThread> threadListCopy; 1118 synchronized (this) { 1119 threadListCopy = new ArrayList<InvocationThread>(mInvocationThreadMap.size()); 1120 threadListCopy.addAll(mInvocationThreadMap.values()); 1121 } 1122 for (Thread thread : threadListCopy) { 1123 waitForThread(thread); 1124 } 1125 } 1126 exit(IDeviceManager manager)1127 private void exit(IDeviceManager manager) { 1128 if (manager != null) { 1129 manager.terminate(); 1130 } 1131 } 1132 1133 /** 1134 * {@inheritDoc} 1135 */ 1136 @Override addCommand(String[] args)1137 public boolean addCommand(String[] args) throws ConfigurationException { 1138 return addCommand(args, 0); 1139 } 1140 1141 /** 1142 * {@inheritDoc} 1143 */ 1144 @Override addCommand(String[] args, long totalExecTime)1145 public boolean addCommand(String[] args, long totalExecTime) throws ConfigurationException { 1146 return internalAddCommand(args, totalExecTime, null); 1147 } 1148 1149 /** Returns true if {@link CommandOptions#USE_SANDBOX} is part of the command line. */ isCommandSandboxed(String[] args)1150 private boolean isCommandSandboxed(String[] args) { 1151 boolean foundSandbox = false; 1152 // Since the order is important, mark the found sandbox when we find it, and unset it if 1153 // we find the negation. 1154 for (String arg : args) { 1155 if (("--" + CommandOptions.USE_SANDBOX).equals(arg)) { 1156 foundSandbox = true; 1157 } else if (("--no-" + CommandOptions.USE_SANDBOX).equals(arg)) { 1158 foundSandbox = false; 1159 } 1160 } 1161 return foundSandbox; 1162 } 1163 1164 /** Returns true if the configuration used is a retry one. */ isRetryCommand(IConfiguration config)1165 private boolean isRetryCommand(IConfiguration config) { 1166 // If a configuration is made of the RetryRunner only, it is meant to run as a retry. 1167 if (config.getTests().size() != 1) { 1168 return false; 1169 } 1170 IRemoteTest rerunner = config.getTests().get(0); 1171 if (rerunner instanceof RetryRescheduler) { 1172 return true; 1173 } 1174 return false; 1175 } 1176 1177 /** Create a {@link ISandbox} that the invocation will use to run. */ createSandbox()1178 public ISandbox createSandbox() { 1179 return new TradefedSandbox(); 1180 } 1181 createConfiguration(String[] args)1182 private IConfiguration createConfiguration(String[] args) throws ConfigurationException { 1183 // check if the command should be sandboxed 1184 if (isCommandSandboxed(args)) { 1185 // Create an sandboxed configuration based on the sandbox of the scheduler. 1186 ISandbox sandbox = createSandbox(); 1187 return SandboxConfigurationFactory.getInstance() 1188 .createConfigurationFromArgs(args, getKeyStoreClient(), sandbox, new RunUtil()); 1189 } 1190 IConfiguration config = 1191 getConfigFactory().createConfigurationFromArgs(args, null, getKeyStoreClient()); 1192 if (isRetryCommand(config)) { 1193 return RetryConfigurationFactory.getInstance().createRetryConfiguration(config); 1194 } 1195 return config; 1196 } 1197 internalAddCommand(String[] args, long totalExecTime, String cmdFilePath)1198 private boolean internalAddCommand(String[] args, long totalExecTime, String cmdFilePath) 1199 throws ConfigurationException { 1200 assertStarted(); 1201 IConfiguration config = createConfiguration(args); 1202 if (config.getCommandOptions().isHelpMode()) { 1203 getConfigFactory().printHelpForConfig(args, true, System.out); 1204 } else if (config.getCommandOptions().isFullHelpMode()) { 1205 getConfigFactory().printHelpForConfig(args, false, System.out); 1206 } else if (config.getCommandOptions().isJsonHelpMode()) { 1207 try { 1208 // Convert the JSON usage to a string (with 4 space indentation) and print to stdout 1209 System.out.println(config.getJsonCommandUsage().toString(4)); 1210 } catch (JSONException e) { 1211 CLog.logAndDisplay(LogLevel.ERROR, "Failed to get json command usage: %s", e); 1212 } 1213 } else if (config.getCommandOptions().isDryRunMode()) { 1214 config.validateOptions(false); 1215 String cmdLine = QuotationAwareTokenizer.combineTokens(args); 1216 CLog.d("Dry run mode; skipping adding command: %s", cmdLine); 1217 if (config.getCommandOptions().isNoisyDryRunMode()) { 1218 System.out.println(cmdLine.replace("--noisy-dry-run", "")); 1219 System.out.println(""); 1220 } 1221 } else { 1222 config.validateOptions(); 1223 1224 if (config.getCommandOptions().runOnAllDevices()) { 1225 addCommandForAllDevices(totalExecTime, args, cmdFilePath); 1226 } else { 1227 CommandTracker cmdTracker = createCommandTracker(args, cmdFilePath); 1228 cmdTracker.incrementExecTime(totalExecTime); 1229 ExecutableCommand cmdInstance = createExecutableCommand(cmdTracker, config, false); 1230 addExecCommandToQueue(cmdInstance, 0); 1231 } 1232 return true; 1233 } 1234 return false; 1235 } 1236 1237 /** 1238 * {@inheritDoc} 1239 */ 1240 @Override addCommandFile(String cmdFilePath, List<String> extraArgs)1241 public void addCommandFile(String cmdFilePath, List<String> extraArgs) 1242 throws ConfigurationException { 1243 // verify we aren't already watching this command file, don't want to add it twice! 1244 File cmdFile = new File(cmdFilePath); 1245 if (mReloadCmdfiles && getCommandFileWatcher().isFileWatched(cmdFile)) { 1246 CLog.logAndDisplay(LogLevel.INFO, 1247 "cmd file %s is already running and being watched for changes. Reloading", 1248 cmdFilePath); 1249 removeCommandsFromFile(cmdFile); 1250 } 1251 internalAddCommandFile(cmdFile, extraArgs); 1252 } 1253 1254 /** 1255 * Adds a command file without verifying if its already being watched 1256 */ internalAddCommandFile(File cmdFile, List<String> extraArgs)1257 private void internalAddCommandFile(File cmdFile, List<String> extraArgs) 1258 throws ConfigurationException { 1259 try { 1260 CommandFileParser parser = createCommandFileParser(); 1261 1262 List<CommandLine> commands = parser.parseFile(cmdFile); 1263 if (mReloadCmdfiles) { 1264 // note always should re-register for command file, even if already listening, 1265 // since the dependent file list might have changed 1266 getCommandFileWatcher().addCmdFile(cmdFile, extraArgs, parser.getIncludedFiles()); 1267 } 1268 for (CommandLine command : commands) { 1269 command.addAll(extraArgs); 1270 String[] arrayCommand = command.asArray(); 1271 final String prettyCmdLine = QuotationAwareTokenizer.combineTokens(arrayCommand); 1272 CLog.d("Adding command %s", prettyCmdLine); 1273 1274 try { 1275 internalAddCommand(arrayCommand, 0, cmdFile.getAbsolutePath()); 1276 } catch (ConfigurationException e) { 1277 throw new ConfigurationException(String.format( 1278 "Failed to add command '%s': %s", prettyCmdLine, e.getMessage()), e); 1279 } 1280 } 1281 } catch (IOException e) { 1282 throw new ConfigurationException("Failed to read file " + cmdFile.getAbsolutePath(), e); 1283 } 1284 } 1285 1286 /** 1287 * Factory method for creating a {@link CommandFileParser}. 1288 * 1289 * <p>Exposed for unit testing. 1290 */ createCommandFileParser()1291 CommandFileParser createCommandFileParser() { 1292 return new CommandFileParser(); 1293 } 1294 1295 /** 1296 * Creates a new command for each connected device, and adds each to the queue. 1297 * <p/> 1298 * Note this won't have the desired effect if user has specified other 1299 * conflicting {@link IConfiguration#getDeviceRequirements()}in the command. 1300 */ addCommandForAllDevices(long totalExecTime, String[] args, String cmdFilePath)1301 private void addCommandForAllDevices(long totalExecTime, String[] args, String cmdFilePath) 1302 throws ConfigurationException { 1303 List<DeviceDescriptor> deviceDescs = getDeviceManager().listAllDevices(); 1304 1305 for (DeviceDescriptor deviceDesc : deviceDescs) { 1306 if (!deviceDesc.isStubDevice()) { 1307 String device = deviceDesc.getSerial(); 1308 String[] argsWithDevice = Arrays.copyOf(args, args.length + 2); 1309 argsWithDevice[argsWithDevice.length - 2] = "-s"; 1310 argsWithDevice[argsWithDevice.length - 1] = device; 1311 CommandTracker cmdTracker = createCommandTracker(argsWithDevice, cmdFilePath); 1312 cmdTracker.incrementExecTime(totalExecTime); 1313 IConfiguration config = getConfigFactory().createConfigurationFromArgs( 1314 cmdTracker.getArgs(), null, getKeyStoreClient()); 1315 CLog.logAndDisplay(LogLevel.INFO, "Scheduling '%s' on '%s'", 1316 cmdTracker.getArgs()[0], device); 1317 config.getDeviceRequirements().setSerial(device); 1318 ExecutableCommand execCmd = createExecutableCommand(cmdTracker, config, false); 1319 addExecCommandToQueue(execCmd, 0); 1320 } 1321 } 1322 } 1323 1324 /** 1325 * Creates a new {@link CommandTracker} with a unique id. 1326 */ createCommandTracker(String[] args, String commandFilePath)1327 private synchronized CommandTracker createCommandTracker(String[] args, 1328 String commandFilePath) { 1329 mCurrentCommandId++; 1330 CLog.d("Creating command tracker id %d for command args: '%s'", mCurrentCommandId, 1331 ArrayUtil.join(" ", (Object[])args)); 1332 return new CommandTracker(mCurrentCommandId, args, commandFilePath); 1333 } 1334 1335 /** 1336 * Creates a new {@link ExecutableCommand}. 1337 */ createExecutableCommand(CommandTracker cmdTracker, IConfiguration config, boolean rescheduled)1338 private ExecutableCommand createExecutableCommand(CommandTracker cmdTracker, 1339 IConfiguration config, boolean rescheduled) { 1340 ExecutableCommand cmd = new ExecutableCommand(cmdTracker, config, rescheduled); 1341 CLog.d("creating exec command for id %d", cmdTracker.getId()); 1342 return cmd; 1343 } 1344 1345 /** 1346 * Creates a new {@link ExecutableCommand}, and adds it to queue 1347 * 1348 * @param commandTracker 1349 */ addNewExecCommandToQueue(CommandTracker commandTracker)1350 private void addNewExecCommandToQueue(CommandTracker commandTracker) { 1351 try { 1352 IConfiguration config = createConfiguration(commandTracker.getArgs()); 1353 ExecutableCommand execCmd = createExecutableCommand(commandTracker, config, false); 1354 addExecCommandToQueue(execCmd, config.getCommandOptions().getLoopTime()); 1355 } catch (ConfigurationException e) { 1356 CLog.e(e); 1357 } 1358 } 1359 1360 /** 1361 * Adds executable command instance to queue, with optional delay. 1362 * 1363 * @param cmd the {@link ExecutableCommand} to return to queue 1364 * @param delayTime the time in ms to delay before adding command to queue 1365 * @return <code>true</code> if command will be added to queue, <code>false</code> otherwise 1366 */ addExecCommandToQueue(final ExecutableCommand cmd, long delayTime)1367 private synchronized boolean addExecCommandToQueue(final ExecutableCommand cmd, 1368 long delayTime) { 1369 // If the command is local sharding one being rescheduled, do not apply the shutdown yet 1370 // This allows commandAndExit to still works with local sharding. 1371 if (isShutdown()) { 1372 if (cmd.getConfiguration() 1373 .getConfigurationDescription() 1374 .getMetaData(ConfigurationDescriptor.LOCAL_SHARDED_KEY) 1375 == null) { 1376 return false; 1377 } 1378 } 1379 if (delayTime > 0) { 1380 mSleepingCommands.add(cmd); 1381 // delay before making command active 1382 Runnable delayCommand = new Runnable() { 1383 @Override 1384 public void run() { 1385 synchronized (CommandScheduler.this) { 1386 if (mSleepingCommands.remove(cmd)) { 1387 mReadyCommands.add(cmd); 1388 mCommandProcessWait.signalEventReceived(); 1389 } 1390 } 1391 } 1392 }; 1393 mCommandTimer.schedule(delayCommand, delayTime, TimeUnit.MILLISECONDS); 1394 } else { 1395 mReadyCommands.add(cmd); 1396 mCommandProcessWait.signalEventReceived(); 1397 } 1398 return true; 1399 } 1400 1401 /** 1402 * Helper method to return an array of {@link String} elements as a readable {@link String} 1403 * 1404 * @param args the {@link String}[] to use 1405 * @return a display friendly {@link String} of args contents 1406 */ getArgString(String[] args)1407 private String getArgString(String[] args) { 1408 return ArrayUtil.join(" ", (Object[])args); 1409 } 1410 1411 /** {@inheritDoc} */ 1412 @Override execCommand( IInvocationContext context, IScheduledInvocationListener listener, String[] args)1413 public void execCommand( 1414 IInvocationContext context, IScheduledInvocationListener listener, String[] args) 1415 throws ConfigurationException, NoDeviceException { 1416 assertStarted(); 1417 IDeviceManager manager = getDeviceManager(); 1418 CommandTracker cmdTracker = createCommandTracker(args, null); 1419 IConfiguration config = createConfiguration(cmdTracker.getArgs()); 1420 config.validateOptions(); 1421 1422 ExecutableCommand execCmd = createExecutableCommand(cmdTracker, config, false); 1423 context.setConfigurationDescriptor(config.getConfigurationDescription()); 1424 Map<String, ITestDevice> devices = allocateDevices(config, manager); 1425 if (!devices.isEmpty()) { 1426 context.addAllocatedDevice(devices); 1427 synchronized (this) { 1428 mExecutingCommands.add(execCmd); 1429 } 1430 CLog.d("Executing '%s' on '%s'", cmdTracker.getArgs()[0], devices); 1431 startInvocation(context, execCmd, listener, new FreeDeviceHandler(manager)); 1432 } else { 1433 throw new NoDeviceException( 1434 "no devices is available for command: " + Arrays.asList(args)); 1435 } 1436 } 1437 1438 /** {@inheritDoc} */ 1439 @Override execCommand(IScheduledInvocationListener listener, String[] args)1440 public void execCommand(IScheduledInvocationListener listener, String[] args) 1441 throws ConfigurationException, NoDeviceException { 1442 execCommand(new InvocationContext(), listener, args); 1443 } 1444 1445 /** 1446 * Allocate devices for a config. 1447 * @param config a {@link IConfiguration} has device requirements. 1448 * @param manager a {@link IDeviceManager} 1449 * @return allocated devices 1450 */ allocateDevices(IConfiguration config, IDeviceManager manager)1451 Map<String, ITestDevice> allocateDevices(IConfiguration config, IDeviceManager manager) { 1452 Map<String, ITestDevice> devices = new LinkedHashMap<String, ITestDevice>(); 1453 ITestDevice device = null; 1454 synchronized(this) { 1455 if (!config.getDeviceConfig().isEmpty()) { 1456 for (IDeviceConfiguration deviceConfig : config.getDeviceConfig()) { 1457 device = 1458 manager.allocateDevice( 1459 deviceConfig.getDeviceRequirements(), deviceConfig.isFake()); 1460 if (device != null) { 1461 devices.put(deviceConfig.getDeviceName(), device); 1462 } else { 1463 // If one of the several device cannot be allocated, we de-allocate 1464 // all the previous one. 1465 for (ITestDevice allocatedDevice : devices.values()) { 1466 FreeDeviceState deviceState = FreeDeviceState.AVAILABLE; 1467 if (allocatedDevice.getIDevice() instanceof StubDevice) { 1468 deviceState = FreeDeviceState.AVAILABLE; 1469 } else if (!TestDeviceState.ONLINE.equals( 1470 allocatedDevice.getDeviceState())) { 1471 // If the device is offline at the end of the test 1472 deviceState = FreeDeviceState.UNAVAILABLE; 1473 } 1474 manager.freeDevice(allocatedDevice, deviceState); 1475 } 1476 // Could not allocate all devices 1477 devices.clear(); 1478 break; 1479 } 1480 } 1481 } 1482 return devices; 1483 } 1484 } 1485 1486 /** 1487 * {@inheritDoc} 1488 */ 1489 @Override execCommand(IScheduledInvocationListener listener, ITestDevice device, String[] args)1490 public void execCommand(IScheduledInvocationListener listener, ITestDevice device, 1491 String[] args) throws ConfigurationException { 1492 // TODO: add support for execCommand multi-device allocation 1493 assertStarted(); 1494 CommandTracker cmdTracker = createCommandTracker(args, null); 1495 IConfiguration config = getConfigFactory().createConfigurationFromArgs( 1496 cmdTracker.getArgs(), null, getKeyStoreClient()); 1497 config.validateOptions(); 1498 CLog.i("Executing '%s' on '%s'", cmdTracker.getArgs()[0], device.getSerialNumber()); 1499 ExecutableCommand execCmd = createExecutableCommand(cmdTracker, config, false); 1500 if (config.getDeviceConfig().size() > 1) { 1501 throw new RuntimeException("execCommand assume single device invocation."); 1502 } 1503 1504 synchronized(this) { 1505 mExecutingCommands.add(execCmd); 1506 } 1507 IInvocationContext context = createInvocationContext(); 1508 context.setConfigurationDescriptor(config.getConfigurationDescription()); 1509 context.addAllocatedDevice(config.getDeviceConfig().get(0).getDeviceName(), device); 1510 startInvocation(context, execCmd, listener); 1511 } 1512 1513 @VisibleForTesting createInvocationContext()1514 protected IInvocationContext createInvocationContext() { 1515 return new InvocationContext(); 1516 } 1517 1518 /** Optional initialization step before test invocation starts */ initInvocation()1519 protected void initInvocation() {} 1520 1521 /** 1522 * Spawns off thread to run invocation for given device. 1523 * 1524 * @param context the {@link IInvocationContext} 1525 * @param cmd the {@link ExecutableCommand} to execute 1526 * @param listeners the {@link 1527 * com.android.tradefed.command.ICommandScheduler.IScheduledInvocationListener}s to invoke 1528 * when complete 1529 */ startInvocation( IInvocationContext context, ExecutableCommand cmd, IScheduledInvocationListener... listeners)1530 private void startInvocation( 1531 IInvocationContext context, 1532 ExecutableCommand cmd, 1533 IScheduledInvocationListener... listeners) { 1534 initInvocation(); 1535 1536 // Check if device is not used in another invocation. 1537 throwIfDeviceInInvocationThread(context.getDevices()); 1538 1539 int invocationId = cmd.getCommandTracker().getId(); 1540 CLog.d("starting invocation for command id %d", invocationId); 1541 // Name invocation with first device serial 1542 final String invocationName = String.format("Invocation-%s", 1543 context.getSerials().get(0)); 1544 InvocationThread invocationThread = new InvocationThread(invocationName, context, cmd, 1545 listeners); 1546 // Link context and command 1547 context.addInvocationAttribute( 1548 IInvocationContext.INVOCATION_ID, Integer.toString(invocationId)); 1549 logInvocationStartedEvent(cmd.getCommandTracker(), context); 1550 invocationThread.start(); 1551 addInvocationThread(invocationThread); 1552 } 1553 1554 /** Helper to log an invocation started event. */ logInvocationStartedEvent(CommandTracker tracker, IInvocationContext context)1555 private void logInvocationStartedEvent(CommandTracker tracker, IInvocationContext context) { 1556 Map<String, String> args = new HashMap<>(); 1557 args.put("id", Integer.toString(tracker.getId())); 1558 int i = 0; 1559 for (String serial : context.getSerials()) { 1560 args.put("serial" + i, serial); 1561 i++; 1562 } 1563 args.put("args", ArrayUtil.join(" ", Arrays.asList(tracker.getArgs()))); 1564 logEvent(EventType.INVOCATION_START, args); 1565 } 1566 1567 /** Removes a {@link InvocationThread} from the active list. */ removeInvocationThread(InvocationThread invThread)1568 private synchronized void removeInvocationThread(InvocationThread invThread) { 1569 mInvocationThreadMap.remove(invThread.getInvocationContext()); 1570 } 1571 throwIfDeviceInInvocationThread(List<ITestDevice> devices)1572 private synchronized void throwIfDeviceInInvocationThread(List<ITestDevice> devices) { 1573 for (ITestDevice device : devices) { 1574 for (IInvocationContext context : mInvocationThreadMap.keySet()) { 1575 if (context.getDevices().contains(device)) { 1576 throw new IllegalStateException( 1577 String.format( 1578 "Attempting invocation on device %s when one is already " 1579 + "running", 1580 device.getSerialNumber())); 1581 } 1582 } 1583 } 1584 } 1585 1586 /** 1587 * Adds a {@link InvocationThread} to the active list. 1588 */ addInvocationThread(InvocationThread invThread)1589 private synchronized void addInvocationThread(InvocationThread invThread) { 1590 mInvocationThreadMap.put(invThread.getInvocationContext(), invThread); 1591 } 1592 isShutdown()1593 protected synchronized boolean isShutdown() { 1594 return mCommandTimer.isShutdown() || (mShutdownOnEmpty && getAllCommandsSize() == 0); 1595 } 1596 isShuttingDown()1597 protected synchronized boolean isShuttingDown() { 1598 return mCommandTimer.isShutdown() || mShutdownOnEmpty; 1599 } 1600 1601 /** 1602 * {@inheritDoc} 1603 */ 1604 @Override shutdown()1605 public synchronized void shutdown() { 1606 setHostState(HostState.QUITTING); 1607 doShutdown(); 1608 } 1609 doShutdown()1610 private synchronized void doShutdown() { 1611 assertStarted(); 1612 if (!isShuttingDown()) { 1613 CLog.d("initiating shutdown"); 1614 removeAllCommands(); 1615 if (mCommandFileWatcher != null) { 1616 mCommandFileWatcher.cancel(); 1617 } 1618 if (mCommandTimer != null) { 1619 mCommandTimer.shutdownNow(); 1620 } 1621 mCommandProcessWait.signalEventReceived(); 1622 } 1623 } 1624 1625 /** 1626 * {@inheritDoc} 1627 */ 1628 @Override shutdownOnEmpty()1629 public synchronized void shutdownOnEmpty() { 1630 assertStarted(); 1631 setHostState(HostState.QUITTING); 1632 if (!isShuttingDown()) { 1633 CLog.d("initiating shutdown on empty"); 1634 mShutdownOnEmpty = true; 1635 mCommandProcessWait.signalEventReceived(); 1636 } 1637 } 1638 1639 /** 1640 * {@inheritDoc} 1641 */ 1642 @Override removeAllCommands()1643 public synchronized void removeAllCommands() { 1644 assertStarted(); 1645 CLog.d("removing all commands"); 1646 if (mReloadCmdfiles) { 1647 getCommandFileWatcher().removeAllFiles(); 1648 } 1649 if (mCommandTimer != null) { 1650 for (Runnable task : mCommandTimer.getQueue()) { 1651 mCommandTimer.remove(task); 1652 } 1653 } 1654 mReadyCommands.clear(); 1655 mSleepingCommands.clear(); 1656 if (isShuttingDown()) { 1657 mCommandProcessWait.signalEventReceived(); 1658 } 1659 } 1660 1661 /** 1662 * Remove commands originally added via the given command file 1663 * @param cmdFile 1664 */ removeCommandsFromFile(File cmdFile)1665 private synchronized void removeCommandsFromFile(File cmdFile) { 1666 Iterator<ExecutableCommand> cmdIter = mReadyCommands.iterator(); 1667 while (cmdIter.hasNext()) { 1668 ExecutableCommand cmd = cmdIter.next(); 1669 String path = cmd.getCommandFilePath(); 1670 if (path != null && 1671 path.equals(cmdFile.getAbsolutePath())) { 1672 cmdIter.remove(); 1673 } 1674 } 1675 cmdIter = mSleepingCommands.iterator(); 1676 while (cmdIter.hasNext()) { 1677 ExecutableCommand cmd = cmdIter.next(); 1678 String path = cmd.getCommandFilePath(); 1679 if (path != null && 1680 path.equals(cmdFile.getAbsolutePath())) { 1681 cmdIter.remove(); 1682 } 1683 } 1684 if (isShuttingDown()) { 1685 mCommandProcessWait.signalEventReceived(); 1686 } 1687 } 1688 1689 /** 1690 * {@inheritDoc} 1691 */ 1692 @Override handoverShutdown(int handoverPort)1693 public synchronized boolean handoverShutdown(int handoverPort) { 1694 assertStarted(); 1695 if (mRemoteClient != null || mPerformingHandover) { 1696 CLog.e("A handover has already been initiated"); 1697 return false; 1698 } 1699 mPerformingHandover = true; 1700 try { 1701 mRemoteClient = RemoteClient.connect(handoverPort); 1702 CLog.d("Connected to remote manager at %d", handoverPort); 1703 handoverDevices(mRemoteClient); 1704 CLog.i("Done with device handover."); 1705 mRemoteClient.sendHandoverInitComplete(); 1706 shutdown(); 1707 return true; 1708 } catch (RemoteException e) { 1709 CLog.e(e); 1710 // TODO: reset state and recover 1711 } 1712 return false; 1713 } 1714 1715 /** Informs remote manager of the physical devices we are still using. */ handoverDevices(IRemoteClient client)1716 private void handoverDevices(IRemoteClient client) throws RemoteException { 1717 for (DeviceDescriptor deviceDesc : getDeviceManager().listAllDevices()) { 1718 if (DeviceAllocationState.Allocated.equals(deviceDesc.getState()) 1719 && !deviceDesc.isStubDevice()) { 1720 client.sendAllocateDevice(deviceDesc.getSerial()); 1721 CLog.d("Sent filter device %s command", deviceDesc.getSerial()); 1722 } 1723 } 1724 } 1725 1726 /** 1727 * @return the list of active {@link CommandTracker}. 'Active' here means all commands added 1728 * to the scheduler that are either executing, waiting for a device to execute on, or looping. 1729 */ getCommandTrackers()1730 List<CommandTracker> getCommandTrackers() { 1731 List<ExecutableCommandState> cmdCopy = getAllCommands(); 1732 Set<CommandTracker> cmdTrackers = new LinkedHashSet<CommandTracker>(); 1733 for (ExecutableCommandState cmdState : cmdCopy) { 1734 cmdTrackers.add(cmdState.cmd.getCommandTracker()); 1735 } 1736 return new ArrayList<CommandTracker>(cmdTrackers); 1737 } 1738 1739 /** 1740 * Inform the remote listener of the freed device. Has no effect if there is no remote listener. 1741 * 1742 * @param device the freed {@link ITestDevice} 1743 */ remoteFreeDevice(ITestDevice device)1744 private void remoteFreeDevice(ITestDevice device) { 1745 // TODO: send freed device state too 1746 if (mPerformingHandover && mRemoteClient != null) { 1747 try { 1748 mRemoteClient.sendFreeDevice(device.getSerialNumber()); 1749 } catch (RemoteException e) { 1750 CLog.e("Failed to send unfilter device %s to remote manager", 1751 device.getSerialNumber()); 1752 CLog.e(e); 1753 // TODO: send handover failed op? 1754 } 1755 } 1756 } 1757 1758 /** 1759 * {@inheritDoc} 1760 */ 1761 @Override shutdownHard()1762 public synchronized void shutdownHard() { 1763 setHostState(HostState.KILLING); 1764 doShutdown(); 1765 CLog.logAndDisplay(LogLevel.WARN, "Stopping invocation threads..."); 1766 for (InvocationThread thread : mInvocationThreadMap.values()) { 1767 thread.disableReporters(); 1768 // TODO(b/118891716): Improve tear down 1769 thread.stopInvocation("TF is shutting down"); 1770 } 1771 getDeviceManager().terminateHard(); 1772 } 1773 1774 /** 1775 * Initializes the ddmlib log. 1776 * 1777 * <p>Exposed so unit tests can mock. 1778 */ 1779 @SuppressWarnings("deprecation") initLogging()1780 protected void initLogging() { 1781 DdmPreferences.setLogLevel(LogLevel.VERBOSE.getStringValue()); 1782 Log.setLogOutput(LogRegistry.getLogRegistry()); 1783 } 1784 1785 /** 1786 * Closes the logs and does any other necessary cleanup before we quit. 1787 * 1788 * <p>Exposed so unit tests can mock. 1789 */ cleanUp()1790 protected void cleanUp() { 1791 LogRegistry.getLogRegistry().closeAndRemoveAllLogs(); 1792 } 1793 1794 /** log an event to the registry history logger. */ 1795 @VisibleForTesting logEvent(EventType event, Map<String, String> args)1796 void logEvent(EventType event, Map<String, String> args) { 1797 LogRegistry.getLogRegistry().logEvent(LogLevel.DEBUG, event, args); 1798 } 1799 1800 /** {@inheritDoc} */ 1801 @Override displayInvocationsInfo(PrintWriter printWriter)1802 public void displayInvocationsInfo(PrintWriter printWriter) { 1803 assertStarted(); 1804 if (mInvocationThreadMap == null || mInvocationThreadMap.size() == 0) { 1805 return; 1806 } 1807 List<InvocationThread> copy = new ArrayList<InvocationThread>(); 1808 synchronized(this) { 1809 copy.addAll(mInvocationThreadMap.values()); 1810 } 1811 ArrayList<List<String>> displayRows = new ArrayList<List<String>>(); 1812 displayRows.add(Arrays.asList("Command Id", "Exec Time", "Device", "State")); 1813 long curTime = System.currentTimeMillis(); 1814 1815 for (InvocationThread invThread : copy) { 1816 displayRows.add(Arrays.asList( 1817 Integer.toString(invThread.mCmd.getCommandTracker().getId()), 1818 getTimeString(curTime - invThread.getStartTime()), 1819 invThread.getInvocationContext().getSerials().toString(), 1820 invThread.getInvocation().toString())); 1821 } 1822 new TableFormatter().displayTable(displayRows, printWriter); 1823 } 1824 getTimeString(long elapsedTime)1825 private String getTimeString(long elapsedTime) { 1826 long duration = elapsedTime / 1000; 1827 long secs = duration % 60; 1828 long mins = (duration / 60) % 60; 1829 long hrs = duration / (60 * 60); 1830 String time = "unknown"; 1831 if (hrs > 0) { 1832 time = String.format("%dh:%02d:%02d", hrs, mins, secs); 1833 } else { 1834 time = String.format("%dm:%02d", mins, secs); 1835 } 1836 return time; 1837 } 1838 1839 /** 1840 * {@inheritDoc} 1841 */ 1842 @Override stopInvocation(ITestInvocation invocation)1843 public synchronized boolean stopInvocation(ITestInvocation invocation) { 1844 for (InvocationThread thread : mInvocationThreadMap.values()) { 1845 if (thread.getInvocation() == invocation) { 1846 thread.interrupt(); 1847 return true; 1848 } 1849 } 1850 return false; 1851 } 1852 1853 /** 1854 * {@inheritDoc} 1855 */ 1856 @Override stopInvocation(int invocationId)1857 public synchronized boolean stopInvocation(int invocationId) { 1858 // TODO: make invocationID part of InvocationContext 1859 for (InvocationThread thread : mInvocationThreadMap.values()) { 1860 if (thread.mCmd.getCommandTracker().mId == invocationId) { 1861 thread.stopInvocation("User requested stopping invocation " + invocationId); 1862 return true; 1863 } 1864 } 1865 CLog.w("No invocation found matching the id: %s", invocationId); 1866 return false; 1867 } 1868 1869 /** 1870 * {@inheritDoc} 1871 */ 1872 @Override getInvocationInfo(int invocationId)1873 public synchronized String getInvocationInfo(int invocationId) { 1874 for (InvocationThread thread : mInvocationThreadMap.values()) { 1875 if (thread.mCmd.getCommandTracker().mId == invocationId) { 1876 String info = Arrays.toString(thread.mCmd.getCommandTracker().getArgs()); 1877 return info; 1878 } 1879 } 1880 CLog.w("No invocation found matching the id: %s", invocationId); 1881 return null; 1882 } 1883 1884 /** 1885 * {@inheritDoc} 1886 */ 1887 @Override displayCommandsInfo(PrintWriter printWriter, String regex)1888 public void displayCommandsInfo(PrintWriter printWriter, String regex) { 1889 assertStarted(); 1890 Pattern regexPattern = null; 1891 if (regex != null) { 1892 regexPattern = Pattern.compile(regex); 1893 } 1894 1895 List<CommandTracker> cmds = getCommandTrackers(); 1896 Collections.sort(cmds, new CommandTrackerIdComparator()); 1897 for (CommandTracker cmd : cmds) { 1898 String argString = getArgString(cmd.getArgs()); 1899 if (regexPattern == null || regexPattern.matcher(argString).find()) { 1900 String cmdDesc = String.format("Command %d: [%s] %s", cmd.getId(), 1901 getTimeString(cmd.getTotalExecTime()), argString); 1902 printWriter.println(cmdDesc); 1903 } 1904 } 1905 } 1906 1907 /** 1908 * {@inheritDoc} 1909 */ 1910 @Override dumpCommandsXml(PrintWriter printWriter, String regex)1911 public void dumpCommandsXml(PrintWriter printWriter, String regex) { 1912 assertStarted(); 1913 Pattern regexPattern = null; 1914 if (regex != null) { 1915 regexPattern = Pattern.compile(regex); 1916 } 1917 1918 List<ExecutableCommandState> cmdCopy = getAllCommands(); 1919 for (ExecutableCommandState cmd : cmdCopy) { 1920 String[] args = cmd.cmd.getCommandTracker().getArgs(); 1921 String argString = getArgString(args); 1922 if (regexPattern == null || regexPattern.matcher(argString).find()) { 1923 // Use the config name prefixed by config__ for the file path 1924 String xmlPrefix = "config__" + args[0].replace("/", "__") + "__"; 1925 1926 // If the command line contains --template:map test config, use that config for the 1927 // file path. This is because in the template system, many tests will have same 1928 // base config and the distinguishing feature is the test included. 1929 boolean templateIncludeFound = false; 1930 boolean testFound = false; 1931 for (String arg : args) { 1932 if ("--template:map".equals(arg)) { 1933 templateIncludeFound = true; 1934 } else if (templateIncludeFound && "test".equals(arg)) { 1935 testFound = true; 1936 } else { 1937 if (templateIncludeFound && testFound) { 1938 xmlPrefix = "config__" + arg.replace("/", "__") + "__"; 1939 } 1940 templateIncludeFound = false; 1941 testFound = false; 1942 } 1943 } 1944 1945 try { 1946 File xmlFile = FileUtil.createTempFile(xmlPrefix, ".xml"); 1947 PrintWriter writer = new PrintWriter(xmlFile); 1948 cmd.cmd.getConfiguration().dumpXml(writer); 1949 printWriter.println(String.format("Saved command dump to %s", 1950 xmlFile.getAbsolutePath())); 1951 } catch (IOException e) { 1952 // Log exception and continue 1953 CLog.e("Could not dump config xml"); 1954 CLog.e(e); 1955 } 1956 } 1957 } 1958 } 1959 1960 /** 1961 * {@inheritDoc} 1962 */ 1963 @Override displayCommandQueue(PrintWriter printWriter)1964 public void displayCommandQueue(PrintWriter printWriter) { 1965 assertStarted(); 1966 List<ExecutableCommandState> cmdCopy = getAllCommands(); 1967 if (cmdCopy.size() == 0) { 1968 return; 1969 } 1970 ArrayList<List<String>> displayRows = new ArrayList<List<String>>(); 1971 displayRows.add(Arrays.asList("Id", "Config", "Created", "Exec time", "State", "Sleep time", 1972 "Rescheduled", "Loop")); 1973 long curTime = System.currentTimeMillis(); 1974 for (ExecutableCommandState cmd : cmdCopy) { 1975 dumpCommand(curTime, cmd, displayRows); 1976 } 1977 new TableFormatter().displayTable(displayRows, printWriter); 1978 } 1979 dumpCommand(long curTime, ExecutableCommandState cmdAndState, ArrayList<List<String>> displayRows)1980 private void dumpCommand(long curTime, ExecutableCommandState cmdAndState, 1981 ArrayList<List<String>> displayRows) { 1982 ExecutableCommand cmd = cmdAndState.cmd; 1983 String sleepTime = cmd.getSleepTime() == null ? "N/A" : getTimeString(cmd.getSleepTime()); 1984 displayRows.add(Arrays.asList( 1985 Integer.toString(cmd.getCommandTracker().getId()), 1986 cmd.getCommandTracker().getArgs()[0], 1987 getTimeString(curTime - cmd.getCreationTime()), 1988 getTimeString(cmd.mCmdTracker.getTotalExecTime()), 1989 cmdAndState.state.getDisplayName(), 1990 sleepTime, 1991 Boolean.toString(cmd.isRescheduled()), 1992 Boolean.toString(cmd.isLoopMode()))); 1993 } 1994 1995 /** 1996 * Starts remote manager to listen to remote commands. 1997 * 1998 * <p>TODO: refactor to throw exception on failure 1999 */ startRemoteManager()2000 private void startRemoteManager() { 2001 if (mRemoteManager != null && !mRemoteManager.isCanceled()) { 2002 String error = String.format("A remote manager is already running at port %d", 2003 mRemoteManager.getPort()); 2004 throw new IllegalStateException(error); 2005 } 2006 mRemoteManager = new RemoteManager(getDeviceManager(), this); 2007 // Read the args that were set by the global config. 2008 boolean startRmtMgrOnBoot = mRemoteManager.getStartRemoteMgrOnBoot(); 2009 int defaultRmtMgrPort = mRemoteManager.getRemoteManagerPort(); 2010 boolean autoHandover = mRemoteManager.getAutoHandover(); 2011 2012 if (!startRmtMgrOnBoot) { 2013 mRemoteManager = null; 2014 return; 2015 } 2016 if (mRemoteManager.connect()) { 2017 mRemoteManager.start(); 2018 CLog.logAndDisplay(LogLevel.INFO, "Started remote manager at port %d", 2019 mRemoteManager.getPort()); 2020 return; 2021 } 2022 CLog.logAndDisplay(LogLevel.INFO, "Failed to start remote manager at port %d", 2023 defaultRmtMgrPort); 2024 if (!autoHandover) { 2025 if (mRemoteManager.connectAnyPort()) { 2026 mRemoteManager.start(); 2027 CLog.logAndDisplay(LogLevel.INFO, 2028 "Started remote manager at port %d with no handover", 2029 mRemoteManager.getPort()); 2030 return; 2031 } else { 2032 CLog.logAndDisplay(LogLevel.ERROR, "Failed to auto start a remote manager on boot."); 2033 return; 2034 } 2035 } 2036 try { 2037 CLog.logAndDisplay(LogLevel.INFO, "Initiating handover with remote TF instance!"); 2038 mHandoverHandshake.reset(); 2039 initiateHandover(defaultRmtMgrPort); 2040 waitForHandoverHandshake(); 2041 CLog.logAndDisplay(LogLevel.INFO, "Handover initiation complete."); 2042 } catch (RemoteException e) { 2043 CLog.e(e); 2044 } 2045 } 2046 waitForHandoverHandshake()2047 private void waitForHandoverHandshake() { 2048 // block and wait to receive all the commands and 'device still in use' messages from remote 2049 mHandoverHandshake.waitForEvent(MAX_HANDOVER_INIT_TIME); 2050 // TODO: throw exception if not received 2051 } 2052 2053 /** 2054 * Helper object for allowing multiple threads to synchronize on an event. 2055 * 2056 * <p>Basically a modest wrapper around Object's wait and notify methods, that supports 2057 * remembering if a notify call was made. 2058 */ 2059 private static class WaitObj { 2060 boolean mEventReceived = false; 2061 2062 /** 2063 * Wait for signal for a max of given ms. 2064 * @return true if event received before time elapsed, false otherwise 2065 */ waitForEvent(long maxWaitTime)2066 public synchronized boolean waitForEvent(long maxWaitTime) { 2067 if (maxWaitTime == 0) { 2068 return waitForEvent(); 2069 } 2070 long startTime = System.currentTimeMillis(); 2071 long remainingTime = maxWaitTime; 2072 while (!mEventReceived && remainingTime > 0) { 2073 try { 2074 wait(remainingTime); 2075 } catch (InterruptedException e) { 2076 CLog.w("interrupted"); 2077 } 2078 remainingTime = maxWaitTime - (System.currentTimeMillis() - startTime); 2079 } 2080 return mEventReceived; 2081 } 2082 2083 /** 2084 * Wait for signal indefinitely or until interrupted. 2085 * @return true if event received, false otherwise 2086 */ waitForEvent()2087 public synchronized boolean waitForEvent() { 2088 if (!mEventReceived) { 2089 try { 2090 wait(); 2091 } catch (InterruptedException e) { 2092 CLog.w("interrupted"); 2093 } 2094 } 2095 return mEventReceived; 2096 } 2097 2098 /** 2099 * Reset the event received flag. 2100 */ reset()2101 public synchronized void reset() { 2102 mEventReceived = false; 2103 } 2104 2105 /** 2106 * Wait for given ms for event to be received, and reset state back to 'no event received' 2107 * upon completion. 2108 */ waitAndReset(long maxWaitTime)2109 public synchronized void waitAndReset(long maxWaitTime) { 2110 waitForEvent(maxWaitTime); 2111 reset(); 2112 } 2113 2114 /** 2115 * Notify listeners that event was received. 2116 */ signalEventReceived()2117 public synchronized void signalEventReceived() { 2118 mEventReceived = true; 2119 notifyAll(); 2120 } 2121 } 2122 2123 @Override handoverInitiationComplete()2124 public void handoverInitiationComplete() { 2125 mHandoverHandshake.signalEventReceived(); 2126 } 2127 2128 @Override completeHandover()2129 public void completeHandover() { 2130 CLog.logAndDisplay(LogLevel.INFO, "Completing handover."); 2131 if (mRemoteClient != null) { 2132 mRemoteClient.close(); 2133 mRemoteClient = null; 2134 } else { 2135 CLog.e("invalid state: received handover complete when remote client is null"); 2136 } 2137 2138 if (mRemoteManager != null) { 2139 mRemoteManager.cancelAndWait(); 2140 mRemoteManager = null; 2141 } else { 2142 CLog.e("invalid state: received handover complete when remote manager is null"); 2143 } 2144 2145 // Start a new remote manager and attempt to capture the original default port. 2146 mRemoteManager = new RemoteManager(getDeviceManager(), this); 2147 boolean success = false; 2148 for (int i=0; i < 10 && !success; i++) { 2149 try { 2150 sleep(2000); 2151 } catch (InterruptedException e) { 2152 CLog.e(e); 2153 return; 2154 } 2155 success = mRemoteManager.connect(); 2156 } 2157 if (!success) { 2158 CLog.e("failed to connect to default remote manager port"); 2159 return; 2160 } 2161 2162 mRemoteManager.start(); 2163 CLog.logAndDisplay(LogLevel.INFO, 2164 "Successfully started remote manager after handover on port %d", 2165 mRemoteManager.getPort()); 2166 } 2167 initiateHandover(int port)2168 private void initiateHandover(int port) throws RemoteException { 2169 mRemoteClient = RemoteClient.connect(port); 2170 CLog.i("Connecting local client with existing remote TF at %d - Attempting takeover", port); 2171 // Start up a temporary local remote manager for handover. 2172 if (mRemoteManager.connectAnyPort()) { 2173 mRemoteManager.start(); 2174 CLog.logAndDisplay(LogLevel.INFO, 2175 "Started local tmp remote manager for handover at port %d", 2176 mRemoteManager.getPort()); 2177 mRemoteClient.sendStartHandover(mRemoteManager.getPort()); 2178 } 2179 } 2180 assertStarted()2181 private synchronized void assertStarted() { 2182 if(!mStarted) { 2183 throw new IllegalStateException("start() must be called before this method"); 2184 } 2185 } 2186 2187 @Override notifyFileChanged(File cmdFile, List<String> extraArgs)2188 public void notifyFileChanged(File cmdFile, List<String> extraArgs) { 2189 CLog.logAndDisplay(LogLevel.INFO, "Detected update for cmdfile '%s'. Reloading", 2190 cmdFile.getAbsolutePath()); 2191 removeCommandsFromFile(cmdFile); 2192 try { 2193 // just add the file again, including re-registering for command file watcher 2194 // don't want to remove the registration here in case file fails to load 2195 internalAddCommandFile(cmdFile, extraArgs); 2196 } catch (ConfigurationException e) { 2197 CLog.wtf(String.format("Failed to automatically reload cmdfile %s", 2198 cmdFile.getAbsolutePath()), e); 2199 } 2200 } 2201 2202 /** 2203 * Set the command file reloading flag. 2204 */ 2205 @VisibleForTesting setCommandFileReload(boolean b)2206 void setCommandFileReload(boolean b) { 2207 mReloadCmdfiles = b; 2208 } 2209 getAllCommandsSize()2210 synchronized int getAllCommandsSize() { 2211 return mReadyCommands.size() + mExecutingCommands.size() + mSleepingCommands.size(); 2212 } 2213 getAllCommands()2214 synchronized List<ExecutableCommandState> getAllCommands() { 2215 List<ExecutableCommandState> cmds = new ArrayList<>(getAllCommandsSize()); 2216 for (ExecutableCommand cmd : mExecutingCommands) { 2217 cmds.add(new ExecutableCommandState(cmd, CommandState.EXECUTING)); 2218 } 2219 for (ExecutableCommand cmd : mReadyCommands) { 2220 cmds.add(new ExecutableCommandState(cmd, CommandState.WAITING_FOR_DEVICE)); 2221 } 2222 for (ExecutableCommand cmd : mSleepingCommands) { 2223 cmds.add(new ExecutableCommandState(cmd, CommandState.SLEEPING)); 2224 } 2225 return cmds; 2226 } 2227 2228 @Override shouldShutdownOnCmdfileError()2229 public boolean shouldShutdownOnCmdfileError() { 2230 return mShutdownOnCmdfileError; 2231 } 2232 getShutdownTimeout()2233 public long getShutdownTimeout() { 2234 return mShutdownTimeout; 2235 } 2236 2237 @Override getLastInvocationExitCode()2238 public ExitCode getLastInvocationExitCode() { 2239 return mLastInvocationExitCode; 2240 } 2241 2242 @Override getLastInvocationThrowable()2243 public Throwable getLastInvocationThrowable() { 2244 return mLastInvocationThrowable; 2245 } 2246 2247 @Override setLastInvocationExitCode(ExitCode code, Throwable throwable)2248 public void setLastInvocationExitCode(ExitCode code, Throwable throwable) { 2249 mLastInvocationExitCode = code; 2250 mLastInvocationThrowable = throwable; 2251 } 2252 2253 @Override getReadyCommandCount()2254 public synchronized int getReadyCommandCount() { 2255 return mReadyCommands.size(); 2256 } 2257 2258 @Override setClearcutClient(ClearcutClient client)2259 public void setClearcutClient(ClearcutClient client) { 2260 mClient = client; 2261 } 2262 } 2263