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