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