1 /*
2  * Copyright (C) 2016 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 package com.android.tradefed.device;
17 
18 import com.android.ddmlib.AdbCommandRejectedException;
19 import com.android.ddmlib.CollectingOutputReceiver;
20 import com.android.ddmlib.IDevice;
21 import com.android.ddmlib.ShellCommandUnresponsiveException;
22 import com.android.ddmlib.TimeoutException;
23 import com.android.tradefed.device.IDeviceManager.IFastbootListener;
24 import com.android.tradefed.log.LogUtil.CLog;
25 import com.android.tradefed.util.IRunUtil;
26 import com.android.tradefed.util.RunInterruptedException;
27 import com.android.tradefed.util.RunUtil;
28 
29 import java.io.IOException;
30 import java.util.ArrayList;
31 import java.util.Collection;
32 import java.util.List;
33 import java.util.concurrent.ExecutionException;
34 import java.util.concurrent.TimeUnit;
35 
36 /**
37  * Helper class for monitoring the state of a {@link IDevice} with no framework support.
38  */
39 public class NativeDeviceStateMonitor implements IDeviceStateMonitor {
40 
41     static final String BOOTCOMPLETE_PROP = "dev.bootcomplete";
42 
43     private IDevice mDevice;
44     private TestDeviceState mDeviceState;
45 
46     /** the time in ms to wait between 'poll for responsiveness' attempts */
47     private static final long CHECK_POLL_TIME = 3 * 1000;
48     protected static final long MAX_CHECK_POLL_TIME = 30 * 1000;
49     /** the maximum operation time in ms for a 'poll for responsiveness' command */
50     protected static final int MAX_OP_TIME = 10 * 1000;
51 
52     /** The  time in ms to wait for a device to be online. */
53     private long mDefaultOnlineTimeout = 1 * 60 * 1000;
54 
55     /** The  time in ms to wait for a device to available. */
56     private long mDefaultAvailableTimeout = 6 * 60 * 1000;
57 
58     private List<DeviceStateListener> mStateListeners;
59     private IDeviceManager mMgr;
60     private final boolean mFastbootEnabled;
61 
62     protected static final String PERM_DENIED_ERROR_PATTERN = "Permission denied";
63 
NativeDeviceStateMonitor(IDeviceManager mgr, IDevice device, boolean fastbootEnabled)64     public NativeDeviceStateMonitor(IDeviceManager mgr, IDevice device,
65             boolean fastbootEnabled) {
66         mMgr = mgr;
67         mDevice = device;
68         mStateListeners = new ArrayList<DeviceStateListener>();
69         mDeviceState = TestDeviceState.getStateByDdms(device.getState());
70         mFastbootEnabled = fastbootEnabled;
71     }
72 
73     /**
74      * Get the {@link RunUtil} instance to use.
75      * <p/>
76      * Exposed for unit testing.
77      */
getRunUtil()78     IRunUtil getRunUtil() {
79         return RunUtil.getDefault();
80     }
81 
82     /**
83      * Set the time in ms to wait for a device to be online in {@link #waitForDeviceOnline()}.
84      */
85     @Override
setDefaultOnlineTimeout(long timeoutMs)86     public void setDefaultOnlineTimeout(long timeoutMs) {
87         mDefaultOnlineTimeout = timeoutMs;
88     }
89 
90     /**
91      * Set the time in ms to wait for a device to be available in {@link #waitForDeviceAvailable()}.
92      */
93     @Override
setDefaultAvailableTimeout(long timeoutMs)94     public void setDefaultAvailableTimeout(long timeoutMs) {
95         mDefaultAvailableTimeout = timeoutMs;
96     }
97 
98     /**
99      * {@inheritDoc}
100      */
101     @Override
waitForDeviceOnline(long waitTime)102     public IDevice waitForDeviceOnline(long waitTime) {
103         if (waitForDeviceState(TestDeviceState.ONLINE, waitTime)) {
104             return getIDevice();
105         }
106         return null;
107     }
108 
109     @Override
waitForDeviceInRecovery()110     public IDevice waitForDeviceInRecovery() {
111         if (waitForDeviceState(TestDeviceState.RECOVERY, mDefaultOnlineTimeout)) {
112             return getIDevice();
113         }
114         return null;
115     }
116 
117     /**
118      * @return {@link IDevice} associate with the state monitor
119      */
getIDevice()120     protected IDevice getIDevice() {
121         synchronized (mDevice) {
122             return mDevice;
123         }
124     }
125 
126     /**
127      * {@inheritDoc}
128      */
129     @Override
getSerialNumber()130     public String getSerialNumber() {
131         return getIDevice().getSerialNumber();
132     }
133 
134     /**
135      * {@inheritDoc}
136      */
137     @Override
waitForDeviceOnline()138     public IDevice waitForDeviceOnline() {
139         return waitForDeviceOnline(mDefaultOnlineTimeout);
140     }
141 
142     /**
143      * {@inheritDoc}
144      */
145     @Override
waitForDeviceNotAvailable(long waitTime)146     public boolean waitForDeviceNotAvailable(long waitTime) {
147         IFastbootListener listener = new StubFastbootListener();
148         if (mFastbootEnabled) {
149             mMgr.addFastbootListener(listener);
150         }
151         boolean result = waitForDeviceState(TestDeviceState.NOT_AVAILABLE, waitTime);
152         if (mFastbootEnabled) {
153             mMgr.removeFastbootListener(listener);
154         }
155         return result;
156     }
157 
158     /**
159      * {@inheritDoc}
160      */
161     @Override
waitForDeviceInRecovery(long waitTime)162     public boolean waitForDeviceInRecovery(long waitTime) {
163         return waitForDeviceState(TestDeviceState.RECOVERY, waitTime);
164     }
165 
166     /** {@inheritDoc} */
167     @Override
waitForDeviceInSideload(long waitTime)168     public boolean waitForDeviceInSideload(long waitTime) {
169         return waitForDeviceState(TestDeviceState.SIDELOAD, waitTime);
170     }
171 
172     /**
173      * {@inheritDoc}
174      */
175     @Override
waitForDeviceShell(final long waitTime)176     public boolean waitForDeviceShell(final long waitTime) {
177         CLog.i("Waiting %d ms for device %s shell to be responsive", waitTime,
178                 getSerialNumber());
179         long startTime = System.currentTimeMillis();
180         int counter = 1;
181         while (System.currentTimeMillis() - startTime < waitTime) {
182             final CollectingOutputReceiver receiver = createOutputReceiver();
183             final String cmd = "ls /system/bin/adb";
184             try {
185                 getIDevice().executeShellCommand(cmd, receiver, MAX_OP_TIME, TimeUnit.MILLISECONDS);
186                 String output = receiver.getOutput();
187                 if (output.contains("/system/bin/adb")) {
188                     return true;
189                 }
190             } catch (IOException | AdbCommandRejectedException |
191                     ShellCommandUnresponsiveException e) {
192                 CLog.e("%s failed on: %s", cmd, getSerialNumber());
193                 CLog.e(e);
194             } catch (TimeoutException e) {
195                 CLog.e("%s failed on %s: timeout", cmd, getSerialNumber());
196                 CLog.e(e);
197             }
198             getRunUtil().sleep(Math.min(getCheckPollTime() * counter, MAX_CHECK_POLL_TIME));
199             counter++;
200         }
201         CLog.w("Device %s shell is unresponsive", getSerialNumber());
202         return false;
203     }
204 
205     /**
206      * {@inheritDoc}
207      */
208     @Override
waitForDeviceAvailable(final long waitTime)209     public IDevice waitForDeviceAvailable(final long waitTime) {
210         // A device is currently considered "available" if and only if four events are true:
211         // 1. Device is online aka visible via DDMS/adb
212         // 2. Device has dev.bootcomplete flag set
213         // 3. Device's package manager is responsive (may be inop)
214         // 4. Device's external storage is mounted
215         //
216         // The current implementation waits for each event to occur in sequence.
217         //
218         // it will track the currently elapsed time and fail if it is
219         // greater than waitTime
220 
221         long startTime = System.currentTimeMillis();
222         IDevice device = waitForDeviceOnline(waitTime);
223         if (device == null) {
224             return null;
225         }
226         long elapsedTime = System.currentTimeMillis() - startTime;
227         if (!waitForBootComplete(waitTime - elapsedTime)) {
228             return null;
229         }
230         elapsedTime = System.currentTimeMillis() - startTime;
231         if (!postOnlineCheck(waitTime - elapsedTime)) {
232             return null;
233         }
234         return device;
235     }
236 
237     /**
238      * {@inheritDoc}
239      */
240     @Override
waitForDeviceAvailable()241     public IDevice waitForDeviceAvailable() {
242         return waitForDeviceAvailable(mDefaultAvailableTimeout);
243     }
244 
245     /**
246      * {@inheritDoc}
247      */
248     @Override
waitForBootComplete(final long waitTime)249     public boolean waitForBootComplete(final long waitTime) {
250         CLog.i("Waiting %d ms for device %s boot complete", waitTime, getSerialNumber());
251         int counter = 1;
252         long startTime = System.currentTimeMillis();
253         final String cmd = "getprop " + BOOTCOMPLETE_PROP;
254         while ((System.currentTimeMillis() - startTime) < waitTime) {
255             try {
256                 String bootFlag = getIDevice().getSystemProperty("dev.bootcomplete").get();
257                 if ("1".equals(bootFlag)) {
258                     return true;
259                 }
260             } catch (InterruptedException e) {
261                 CLog.i("%s on device %s failed: %s", cmd, getSerialNumber(), e.getMessage());
262                 // exit the loop for InterruptedException
263                 break;
264             } catch (ExecutionException e) {
265                 CLog.i("%s on device %s failed: %s", cmd, getSerialNumber(), e.getMessage());
266             }
267             getRunUtil().sleep(Math.min(getCheckPollTime() * counter, MAX_CHECK_POLL_TIME));
268             counter++;
269         }
270         CLog.w("Device %s did not boot after %d ms", getSerialNumber(), waitTime);
271         return false;
272     }
273 
274     /**
275      * Additional checks to be done on an Online device
276      *
277      * @param waitTime time in ms to wait before giving up
278      * @return <code>true</code> if checks are successful before waitTime expires.
279      * <code>false</code> otherwise
280      */
postOnlineCheck(final long waitTime)281     protected boolean postOnlineCheck(final long waitTime) {
282         return waitForStoreMount(waitTime);
283     }
284 
285     /**
286      * Waits for the device's external store to be mounted.
287      *
288      * @param waitTime time in ms to wait before giving up
289      * @return <code>true</code> if external store is mounted before waitTime expires.
290      * <code>false</code> otherwise
291      */
waitForStoreMount(final long waitTime)292     protected boolean waitForStoreMount(final long waitTime) {
293         CLog.i("Waiting %d ms for device %s external store", waitTime, getSerialNumber());
294         long startTime = System.currentTimeMillis();
295         int counter = 1;
296         // TODO(b/151119210): Remove this 'retryOnPermissionDenied' workaround when we figure out
297         // what causes "Permission denied" to be returned incorrectly.
298         int retryOnPermissionDenied = 1;
299         while (System.currentTimeMillis() - startTime < waitTime) {
300             final CollectingOutputReceiver receiver = createOutputReceiver();
301             final CollectingOutputReceiver bitBucket = new CollectingOutputReceiver();
302             final long number = getCurrentTime();
303             final String externalStore = getMountPoint(IDevice.MNT_EXTERNAL_STORAGE);
304 
305             final String testFile = String.format("'%s/%d'", externalStore, number);
306             final String testString = String.format("number %d one", number);
307             final String writeCmd = String.format("echo '%s' > %s", testString, testFile);
308             final String checkCmd = String.format("cat %s", testFile);
309             final String cleanupCmd = String.format("rm %s", testFile);
310             String cmd = null;
311             if (externalStore != null) {
312                 try {
313                     cmd = writeCmd;
314                     getIDevice().executeShellCommand(writeCmd, bitBucket,
315                             MAX_OP_TIME, TimeUnit.MILLISECONDS);
316                     cmd = checkCmd;
317                     getIDevice().executeShellCommand(checkCmd, receiver,
318                             MAX_OP_TIME, TimeUnit.MILLISECONDS);
319                     cmd = cleanupCmd;
320                     getIDevice().executeShellCommand(cleanupCmd, bitBucket,
321                             MAX_OP_TIME, TimeUnit.MILLISECONDS);
322 
323                     String output = receiver.getOutput();
324                     CLog.v("%s returned %s", checkCmd, output);
325                     if (output.contains(testString)) {
326                         return true;
327                     } else if (output.contains(PERM_DENIED_ERROR_PATTERN)
328                             && --retryOnPermissionDenied < 0) {
329                         CLog.w("Device %s mount check returned Permision Denied, "
330                                 + "issue with mounting.", getSerialNumber());
331                         return false;
332                     }
333                 } catch (IOException | AdbCommandRejectedException |
334                         ShellCommandUnresponsiveException e) {
335                     CLog.i("%s on device %s failed:", cmd, getSerialNumber());
336                     CLog.e(e);
337                 } catch (TimeoutException e) {
338                     CLog.i("%s on device %s failed: timeout", cmd, getSerialNumber());
339                     CLog.e(e);
340                 }
341             } else {
342                 CLog.w("Failed to get external store mount point for %s", getSerialNumber());
343             }
344             getRunUtil().sleep(Math.min(getCheckPollTime() * counter, MAX_CHECK_POLL_TIME));
345             counter++;
346         }
347         CLog.w("Device %s external storage is not mounted after %d ms",
348                 getSerialNumber(), waitTime);
349         return false;
350     }
351 
352     /**
353      * {@inheritDoc}
354      */
355     @Override
getMountPoint(String mountName)356     public String getMountPoint(String mountName) {
357         String mountPoint = getIDevice().getMountPoint(mountName);
358         if (mountPoint != null) {
359             return mountPoint;
360         }
361         // cached mount point is null - try querying directly
362         CollectingOutputReceiver receiver = createOutputReceiver();
363         try {
364             getIDevice().executeShellCommand("echo $" + mountName, receiver);
365             return receiver.getOutput().trim();
366         } catch (IOException e) {
367             return null;
368         } catch (TimeoutException e) {
369             return null;
370         } catch (AdbCommandRejectedException e) {
371             return null;
372         } catch (ShellCommandUnresponsiveException e) {
373             return null;
374         }
375     }
376 
377     /**
378      * {@inheritDoc}
379      */
380     @Override
getDeviceState()381     public TestDeviceState getDeviceState() {
382         return mDeviceState;
383     }
384 
385     /**
386      * {@inheritDoc}
387      */
388     @Override
waitForDeviceBootloader(long time)389     public boolean waitForDeviceBootloader(long time) {
390         return waitForDeviceBootloaderOrFastbootd(time, false);
391     }
392 
393     /** {@inheritDoc} */
394     @Override
waitForDeviceFastbootd(String fastbootPath, long time)395     public boolean waitForDeviceFastbootd(String fastbootPath, long time) {
396         return waitForDeviceBootloaderOrFastbootd(time, true);
397     }
398 
waitForDeviceBootloaderOrFastbootd(long time, boolean fastbootd)399     private boolean waitForDeviceBootloaderOrFastbootd(long time, boolean fastbootd) {
400         if (!mFastbootEnabled) {
401             return false;
402         }
403         long startTime = System.currentTimeMillis();
404         // ensure fastboot state is updated at least once
405         waitForDeviceBootloaderStateUpdate();
406         long elapsedTime = System.currentTimeMillis() - startTime;
407         IFastbootListener listener = new StubFastbootListener();
408         mMgr.addFastbootListener(listener);
409         long waitTime = time - elapsedTime;
410         if (waitTime < 0) {
411             // wait at least 200ms
412             waitTime = 200;
413         }
414         TestDeviceState mode = TestDeviceState.FASTBOOT;
415         if (fastbootd) {
416             mode = TestDeviceState.FASTBOOTD;
417         }
418         boolean result = waitForDeviceState(mode, waitTime);
419         mMgr.removeFastbootListener(listener);
420         return result;
421     }
422 
423     @Override
waitForDeviceBootloaderStateUpdate()424     public void waitForDeviceBootloaderStateUpdate() {
425         if (!mFastbootEnabled) {
426             return;
427         }
428         IFastbootListener listener = new NotifyFastbootListener();
429         synchronized (listener) {
430             mMgr.addFastbootListener(listener);
431             try {
432                 listener.wait();
433             } catch (InterruptedException e) {
434                 CLog.w("wait for device bootloader state update interrupted");
435                 CLog.w(e);
436                 throw new RunInterruptedException(e);
437             } finally {
438                 mMgr.removeFastbootListener(listener);
439             }
440         }
441     }
442 
waitForDeviceState(TestDeviceState state, long time)443     private boolean waitForDeviceState(TestDeviceState state, long time) {
444         String deviceSerial = getSerialNumber();
445         if (getDeviceState() == state) {
446             CLog.i("Device %s is already %s", deviceSerial, state);
447             return true;
448         }
449         CLog.i("Waiting for device %s to be %s; it is currently %s...", deviceSerial,
450                 state, getDeviceState());
451         DeviceStateListener listener = new DeviceStateListener(state);
452         addDeviceStateListener(listener);
453         synchronized (listener) {
454             try {
455                 listener.wait(time);
456             } catch (InterruptedException e) {
457                 CLog.w("wait for device state interrupted");
458                 CLog.w(e);
459                 throw new RunInterruptedException(e);
460             } finally {
461                 removeDeviceStateListener(listener);
462             }
463         }
464         return getDeviceState().equals(state);
465     }
466 
467     /**
468      * @param listener
469      */
removeDeviceStateListener(DeviceStateListener listener)470     private void removeDeviceStateListener(DeviceStateListener listener) {
471         synchronized (mStateListeners) {
472             mStateListeners.remove(listener);
473         }
474     }
475 
476     /**
477      * @param listener
478      */
addDeviceStateListener(DeviceStateListener listener)479     private void addDeviceStateListener(DeviceStateListener listener) {
480         synchronized (mStateListeners) {
481             mStateListeners.add(listener);
482         }
483     }
484 
485     /**
486      * {@inheritDoc}
487      */
488     @Override
setState(TestDeviceState deviceState)489     public void setState(TestDeviceState deviceState) {
490         mDeviceState = deviceState;
491         // create a copy of listeners to prevent holding mStateListeners lock when notifying
492         // and to protect from list modification when iterating
493         Collection<DeviceStateListener> listenerCopy = new ArrayList<DeviceStateListener>(
494                 mStateListeners.size());
495         synchronized (mStateListeners) {
496             listenerCopy.addAll(mStateListeners);
497         }
498         for (DeviceStateListener listener: listenerCopy) {
499             listener.stateChanged(deviceState);
500         }
501     }
502 
503     @Override
setIDevice(IDevice newDevice)504     public void setIDevice(IDevice newDevice) {
505         IDevice currentDevice = mDevice;
506         if (!getIDevice().equals(newDevice)) {
507             synchronized (currentDevice) {
508                 mDevice = newDevice;
509             }
510         }
511     }
512 
513     private static class DeviceStateListener {
514         private final TestDeviceState mExpectedState;
515 
DeviceStateListener(TestDeviceState expectedState)516         public DeviceStateListener(TestDeviceState expectedState) {
517             mExpectedState = expectedState;
518         }
519 
stateChanged(TestDeviceState newState)520         public void stateChanged(TestDeviceState newState) {
521             if (mExpectedState.equals(newState)) {
522                 synchronized (this) {
523                     notify();
524                 }
525             }
526         }
527     }
528 
529     /**
530      * An empty implementation of {@link IFastbootListener}
531      */
532     private static class StubFastbootListener implements IFastbootListener {
533         @Override
stateUpdated()534         public void stateUpdated() {
535             // ignore
536         }
537     }
538 
539     /**
540      * A {@link IFastbootListener} that notifies when a status update has been received.
541      */
542     private static class NotifyFastbootListener implements IFastbootListener {
543         @Override
stateUpdated()544         public void stateUpdated() {
545             synchronized (this) {
546                 notify();
547             }
548         }
549     }
550 
551     /**
552      * {@inheritDoc}
553      */
554     @Override
isAdbTcp()555     public boolean isAdbTcp() {
556         return mDevice.getSerialNumber().contains(":");
557     }
558 
559     /**
560      * Exposed for testing
561      * @return {@link CollectingOutputReceiver}
562      */
createOutputReceiver()563     protected CollectingOutputReceiver createOutputReceiver() {
564         return new CollectingOutputReceiver();
565     }
566 
567     /**
568      * Exposed for testing
569      */
getCheckPollTime()570     protected long getCheckPollTime() {
571         return CHECK_POLL_TIME;
572     }
573 
574     /**
575      * Exposed for testing
576      */
getCurrentTime()577     protected long getCurrentTime() {
578         return System.currentTimeMillis();
579     }
580 }
581