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