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