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