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 package com.android.tradefed.device;
17 
18 import com.android.ddmlib.AdbCommandRejectedException;
19 import com.android.ddmlib.IDevice;
20 import com.android.ddmlib.Log;
21 import com.android.ddmlib.TimeoutException;
22 import com.android.helper.aoa.UsbDevice;
23 import com.android.helper.aoa.UsbHelper;
24 import com.android.tradefed.config.Option;
25 import com.android.tradefed.invoker.logger.InvocationMetricLogger;
26 import com.android.tradefed.invoker.logger.InvocationMetricLogger.InvocationMetricKey;
27 import com.android.tradefed.log.LogUtil.CLog;
28 import com.android.tradefed.result.error.DeviceErrorIdentifier;
29 import com.android.tradefed.util.CommandResult;
30 import com.android.tradefed.util.CommandStatus;
31 import com.android.tradefed.util.IRunUtil;
32 import com.android.tradefed.util.RunUtil;
33 
34 import com.google.common.annotations.VisibleForTesting;
35 
36 import java.io.IOException;
37 import java.util.concurrent.ExecutionException;
38 
39 /**
40  * A simple implementation of a {@link IDeviceRecovery} that waits for device to be online and
41  * respond to simple commands.
42  */
43 public class WaitDeviceRecovery implements IDeviceRecovery {
44 
45     private static final String LOG_TAG = "WaitDeviceRecovery";
46 
47     /** the time in ms to wait before beginning recovery attempts */
48     protected static final long INITIAL_PAUSE_TIME = 5 * 1000;
49 
50     private static final long WAIT_FOR_DEVICE_OFFLINE = 20 * 1000;
51 
52     /**
53      * The number of attempts to check if device is in bootloader.
54      * <p/>
55      * Exposed for unit testing
56      */
57     public static final int BOOTLOADER_POLL_ATTEMPTS = 3;
58 
59     // TODO: add a separate configurable timeout per operation
60     @Option(name="online-wait-time",
61             description="maximum time in ms to wait for device to come online.")
62     protected long mOnlineWaitTime = 60 * 1000;
63     @Option(name="device-wait-time",
64             description="maximum time in ms to wait for a single device recovery command.")
65     protected long mWaitTime = 4 * 60 * 1000;
66 
67     @Option(name="bootloader-wait-time",
68             description="maximum time in ms to wait for device to be in fastboot.")
69     protected long mBootloaderWaitTime = 30 * 1000;
70 
71     @Option(name="shell-wait-time",
72             description="maximum time in ms to wait for device shell to be responsive.")
73     protected long mShellWaitTime = 30 * 1000;
74 
75     @Option(name="fastboot-wait-time",
76             description="maximum time in ms to wait for a fastboot command result.")
77     protected long mFastbootWaitTime = 30 * 1000;
78 
79     @Option(name = "min-battery-after-recovery",
80             description = "require a min battery level after successful recovery, " +
81                           "default to 0 for ignoring.")
82     protected int mRequiredMinBattery = 0;
83 
84     @Option(name = "disable-unresponsive-reboot",
85             description = "If this is set, we will not attempt to reboot an unresponsive device" +
86             "that is in userspace.  Note that this will have no effect if the device is in " +
87             "fastboot or is expected to be in fastboot.")
88     protected boolean mDisableUnresponsiveReboot = false;
89 
90     private String mFastbootPath = "fastboot";
91 
92     /**
93      * Get the {@link RunUtil} instance to use.
94      * <p/>
95      * Exposed for unit testing.
96      */
getRunUtil()97     protected IRunUtil getRunUtil() {
98         return RunUtil.getDefault();
99     }
100 
101     /**
102      * Sets the maximum time in ms to wait for a single device recovery command.
103      */
setWaitTime(long waitTime)104     void setWaitTime(long waitTime) {
105         mWaitTime = waitTime;
106     }
107 
108     /**
109      * {@inheritDoc}
110      */
111     @Override
setFastbootPath(String fastbootPath)112     public void setFastbootPath(String fastbootPath) {
113         mFastbootPath = fastbootPath;
114     }
115 
116     /**
117      * {@inheritDoc}
118      */
119     @Override
recoverDevice(IDeviceStateMonitor monitor, boolean recoverUntilOnline)120     public void recoverDevice(IDeviceStateMonitor monitor, boolean recoverUntilOnline)
121             throws DeviceNotAvailableException {
122         // device may have just gone offline
123         // sleep a small amount to give ddms state a chance to settle
124         // TODO - see if there is better way to handle this
125         Log.i(LOG_TAG, String.format("Pausing for %d for %s to recover",
126                 INITIAL_PAUSE_TIME, monitor.getSerialNumber()));
127         getRunUtil().sleep(INITIAL_PAUSE_TIME);
128 
129         // ensure bootloader state is updated
130         monitor.waitForDeviceBootloaderStateUpdate();
131 
132         TestDeviceState state = monitor.getDeviceState();
133         if (TestDeviceState.FASTBOOT.equals(state) || TestDeviceState.FASTBOOTD.equals(state)) {
134             Log.i(
135                     LOG_TAG,
136                     String.format(
137                             "Found device %s in %s but expected online. Rebooting...",
138                             monitor.getSerialNumber(), state));
139             // TODO: retry if failed
140             getRunUtil().runTimedCmd(mFastbootWaitTime, mFastbootPath, "-s",
141                     monitor.getSerialNumber(), "reboot");
142         }
143 
144         // wait for device online
145         IDevice device = monitor.waitForDeviceOnline(mOnlineWaitTime);
146         if (device == null) {
147             handleDeviceNotAvailable(monitor, recoverUntilOnline);
148             // function returning implies that recovery is successful, check battery level here
149             checkMinBatteryLevel(getDeviceAfterRecovery(monitor));
150             return;
151         }
152         // occasionally device is erroneously reported as online - double check that we can shell
153         // into device
154         if (!monitor.waitForDeviceShell(mShellWaitTime)) {
155             // treat this as a not available device
156             handleDeviceNotAvailable(monitor, recoverUntilOnline);
157             checkMinBatteryLevel(getDeviceAfterRecovery(monitor));
158             return;
159         }
160 
161         if (!recoverUntilOnline) {
162             if (monitor.waitForDeviceAvailable(mWaitTime) == null) {
163                 // device is online but not responsive
164                 handleDeviceUnresponsive(device, monitor);
165             }
166         }
167         // do a final check here when all previous if blocks are skipped or the last
168         // handleDeviceUnresponsive was successful
169         checkMinBatteryLevel(getDeviceAfterRecovery(monitor));
170     }
171 
getDeviceAfterRecovery(IDeviceStateMonitor monitor)172     private IDevice getDeviceAfterRecovery(IDeviceStateMonitor monitor)
173             throws DeviceNotAvailableException {
174         IDevice device = monitor.waitForDeviceOnline(mOnlineWaitTime);
175         if (device == null) {
176             throw new DeviceNotAvailableException(
177                     "Device still not online after successful recovery", monitor.getSerialNumber());
178         }
179         return device;
180     }
181 
182     /**
183      * Checks if device battery level meets min requirement
184      * @param device
185      * @throws DeviceNotAvailableException if battery level cannot be read or lower than min
186      */
checkMinBatteryLevel(IDevice device)187     protected void checkMinBatteryLevel(IDevice device) throws DeviceNotAvailableException {
188         if (mRequiredMinBattery <= 0) {
189             // don't do anything if check is not required
190             return;
191         }
192         try {
193             Integer level = device.getBattery().get();
194             if (level == null) {
195                 // can't read battery level but we are requiring a min, reject
196                 // device
197                 throw new DeviceNotAvailableException(
198                         "Cannot read battery level but a min is required",
199                         device.getSerialNumber(),
200                         DeviceErrorIdentifier.DEVICE_UNEXPECTED_RESPONSE);
201             } else if (level < mRequiredMinBattery) {
202                 throw new DeviceNotAvailableException(String.format(
203                         "After recovery, device battery level %d is lower than required minimum %d",
204                         level, mRequiredMinBattery), device.getSerialNumber());
205             }
206             return;
207         } catch (InterruptedException | ExecutionException e) {
208             throw new DeviceNotAvailableException("exception while reading battery level", e,
209                     device.getSerialNumber());
210         }
211     }
212 
213     /**
214      * Handle situation where device is online but unresponsive.
215      * @param monitor
216      * @throws DeviceNotAvailableException
217      */
handleDeviceUnresponsive(IDevice device, IDeviceStateMonitor monitor)218     protected void handleDeviceUnresponsive(IDevice device, IDeviceStateMonitor monitor)
219             throws DeviceNotAvailableException {
220         if (!mDisableUnresponsiveReboot) {
221             Log.i(LOG_TAG, String.format(
222                     "Device %s unresponsive. Rebooting...", monitor.getSerialNumber()));
223             rebootDevice(device, null);
224             IDevice newdevice = monitor.waitForDeviceOnline(mOnlineWaitTime);
225             if (newdevice == null) {
226                 handleDeviceNotAvailable(monitor, false);
227                 return;
228             }
229             if (monitor.waitForDeviceAvailable(mWaitTime) != null) {
230                 return;
231             }
232         }
233         // If no reboot was done, waitForDeviceAvailable has already been checked.
234         throw new DeviceUnresponsiveException(
235                 String.format("Device %s is online but unresponsive", monitor.getSerialNumber()),
236                 monitor.getSerialNumber(),
237                 DeviceErrorIdentifier.DEVICE_UNRESPONSIVE);
238     }
239 
240     /**
241      * Handle situation where device is not available.
242      *
243      * @param monitor the {@link IDeviceStateMonitor}
244      * @param recoverTillOnline if true this method should return if device is online, and not
245      * check for responsiveness
246      * @throws DeviceNotAvailableException
247      */
handleDeviceNotAvailable(IDeviceStateMonitor monitor, boolean recoverTillOnline)248     protected void handleDeviceNotAvailable(IDeviceStateMonitor monitor, boolean recoverTillOnline)
249             throws DeviceNotAvailableException {
250         if (attemptDeviceUnavailableRecovery(monitor, recoverTillOnline)) {
251             return;
252         }
253         String serial = monitor.getSerialNumber();
254         throw new DeviceNotAvailableException(
255                 String.format("Could not find device %s", serial),
256                 serial,
257                 DeviceErrorIdentifier.DEVICE_UNAVAILABLE);
258     }
259 
260     /**
261      * {@inheritDoc}
262      */
263     @Override
recoverDeviceBootloader(final IDeviceStateMonitor monitor)264     public void recoverDeviceBootloader(final IDeviceStateMonitor monitor)
265             throws DeviceNotAvailableException {
266         // device may have just gone offline
267         // wait a small amount to give device state a chance to settle
268         // TODO - see if there is better way to handle this
269         Log.i(LOG_TAG, String.format("Pausing for %d for %s to recover",
270                 INITIAL_PAUSE_TIME, monitor.getSerialNumber()));
271         getRunUtil().sleep(INITIAL_PAUSE_TIME);
272 
273         // poll and wait for device to return to valid state
274         long pollTime = mBootloaderWaitTime / BOOTLOADER_POLL_ATTEMPTS;
275         for (int i=0; i < BOOTLOADER_POLL_ATTEMPTS; i++) {
276             if (monitor.waitForDeviceBootloader(pollTime)) {
277                 handleDeviceBootloaderUnresponsive(monitor);
278                 // passed above check, abort
279                 return;
280             } else if (monitor.getDeviceState() == TestDeviceState.ONLINE) {
281                 handleDeviceOnlineExpectedBootloader(monitor);
282                 return;
283             }
284         }
285         handleDeviceBootloaderOrFastbootNotAvailable(monitor, "bootloader");
286     }
287 
288     /** {@inheritDoc} */
289     @Override
recoverDeviceFastbootd(IDeviceStateMonitor monitor)290     public void recoverDeviceFastbootd(IDeviceStateMonitor monitor)
291             throws DeviceNotAvailableException {
292         // device may have just gone offline
293         // wait a small amount to give device state a chance to settle
294         // TODO - see if there is better way to handle this
295         Log.i(
296                 LOG_TAG,
297                 String.format(
298                         "Pausing for %d for %s to recover",
299                         INITIAL_PAUSE_TIME, monitor.getSerialNumber()));
300         getRunUtil().sleep(INITIAL_PAUSE_TIME);
301 
302         // poll and wait for device to return to valid state
303         long pollTime = mBootloaderWaitTime / BOOTLOADER_POLL_ATTEMPTS;
304         for (int i = 0; i < BOOTLOADER_POLL_ATTEMPTS; i++) {
305             if (monitor.waitForDeviceFastbootd(mFastbootPath, pollTime)) {
306                 handleDeviceFastbootdUnresponsive(monitor);
307                 // passed above check, abort
308                 return;
309             } else if (monitor.getDeviceState() == TestDeviceState.ONLINE) {
310                 handleDeviceOnlineExpectedFasbootd(monitor);
311                 return;
312             }
313         }
314         handleDeviceBootloaderOrFastbootNotAvailable(monitor, "fastbootd");
315     }
316 
317     /**
318      * Handle condition where device is online, but should be in bootloader state.
319      *
320      * <p>If this method
321      *
322      * @param monitor
323      * @throws DeviceNotAvailableException
324      */
handleDeviceOnlineExpectedBootloader(final IDeviceStateMonitor monitor)325     private void handleDeviceOnlineExpectedBootloader(final IDeviceStateMonitor monitor)
326             throws DeviceNotAvailableException {
327         Log.i(
328                 LOG_TAG,
329                 String.format(
330                         "Found device %s online but expected bootloader.",
331                         monitor.getSerialNumber()));
332         // call waitForDeviceOnline to get handle to IDevice
333         IDevice device = monitor.waitForDeviceOnline(mOnlineWaitTime);
334         if (device == null) {
335             handleDeviceBootloaderOrFastbootNotAvailable(monitor, "bootloader");
336             return;
337         }
338         rebootDevice(device, "bootloader");
339         if (!monitor.waitForDeviceBootloader(mBootloaderWaitTime)) {
340             throw new DeviceNotAvailableException(String.format(
341                     "Device %s not in bootloader after reboot", monitor.getSerialNumber()),
342                     monitor.getSerialNumber());
343         }
344     }
345 
handleDeviceOnlineExpectedFasbootd(final IDeviceStateMonitor monitor)346     private void handleDeviceOnlineExpectedFasbootd(final IDeviceStateMonitor monitor)
347             throws DeviceNotAvailableException {
348         Log.i(
349                 LOG_TAG,
350                 String.format(
351                         "Found device %s online but expected fastbootd.",
352                         monitor.getSerialNumber()));
353         // call waitForDeviceOnline to get handle to IDevice
354         IDevice device = monitor.waitForDeviceOnline(mOnlineWaitTime);
355         if (device == null) {
356             handleDeviceBootloaderOrFastbootNotAvailable(monitor, "fastbootd");
357             return;
358         }
359         rebootDevice(device, "fastboot");
360         if (!monitor.waitForDeviceFastbootd(mFastbootPath, mBootloaderWaitTime)) {
361             throw new DeviceNotAvailableException(
362                     String.format(
363                             "Device %s not in fastbootd after reboot", monitor.getSerialNumber()),
364                     monitor.getSerialNumber());
365         }
366     }
367 
handleDeviceFastbootdUnresponsive(IDeviceStateMonitor monitor)368     private void handleDeviceFastbootdUnresponsive(IDeviceStateMonitor monitor)
369             throws DeviceNotAvailableException {
370         CLog.i(
371                 "Found device %s in fastbootd but potentially unresponsive.",
372                 monitor.getSerialNumber());
373         // TODO: retry reboot
374         getRunUtil()
375                 .runTimedCmd(
376                         mFastbootWaitTime,
377                         mFastbootPath,
378                         "-s",
379                         monitor.getSerialNumber(),
380                         "reboot",
381                         "fastboot");
382         // wait for device to reboot
383         monitor.waitForDeviceNotAvailable(WAIT_FOR_DEVICE_OFFLINE);
384         if (!monitor.waitForDeviceFastbootd(mFastbootPath, mBootloaderWaitTime)) {
385             throw new DeviceNotAvailableException(
386                     String.format(
387                             "Device %s not in fastbootd after reboot", monitor.getSerialNumber()),
388                     monitor.getSerialNumber());
389         }
390         // running a meaningless command just to see whether the device is responsive.
391         CommandResult result =
392                 getRunUtil()
393                         .runTimedCmd(
394                                 mFastbootWaitTime,
395                                 mFastbootPath,
396                                 "-s",
397                                 monitor.getSerialNumber(),
398                                 "getvar",
399                                 "product");
400         if (result.getStatus().equals(CommandStatus.TIMED_OUT)) {
401             throw new DeviceNotAvailableException(
402                     String.format(
403                             "Device %s is in fastbootd but unresponsive",
404                             monitor.getSerialNumber()),
405                     monitor.getSerialNumber());
406         }
407     }
408 
409     /**
410      * @param monitor
411      * @throws DeviceNotAvailableException
412      */
handleDeviceBootloaderUnresponsive(IDeviceStateMonitor monitor)413     private void handleDeviceBootloaderUnresponsive(IDeviceStateMonitor monitor)
414             throws DeviceNotAvailableException {
415         CLog.i("Found device %s in fastboot but potentially unresponsive.",
416                 monitor.getSerialNumber());
417         // TODO: retry reboot
418         getRunUtil().runTimedCmd(mFastbootWaitTime, mFastbootPath, "-s", monitor.getSerialNumber(),
419                 "reboot-bootloader");
420         // wait for device to reboot
421         monitor.waitForDeviceNotAvailable(20*1000);
422         if (!monitor.waitForDeviceBootloader(mBootloaderWaitTime)) {
423             throw new DeviceNotAvailableException(String.format(
424                     "Device %s not in bootloader after reboot", monitor.getSerialNumber()),
425                     monitor.getSerialNumber());
426         }
427         // running a meaningless command just to see whether the device is responsive.
428         CommandResult result = getRunUtil().runTimedCmd(mFastbootWaitTime, mFastbootPath, "-s",
429                 monitor.getSerialNumber(), "getvar", "product");
430         if (result.getStatus().equals(CommandStatus.TIMED_OUT)) {
431             throw new DeviceNotAvailableException(String.format(
432                     "Device %s is in fastboot but unresponsive", monitor.getSerialNumber()),
433                     monitor.getSerialNumber());
434         }
435     }
436 
437     /**
438      * Reboot device into given mode.
439      *
440      * @param device the {@link IDevice} to reboot.
441      * @param mode The mode into which to reboot the device. null being regular reboot.
442      */
rebootDevice(IDevice device, String mode)443     private void rebootDevice(IDevice device, String mode) {
444         try {
445             device.reboot(mode);
446         } catch (IOException e) {
447             Log.w(LOG_TAG, String.format("failed to reboot %s: %s", device.getSerialNumber(),
448                     e.getMessage()));
449         } catch (TimeoutException e) {
450             Log.w(LOG_TAG, String.format("failed to reboot %s: timeout", device.getSerialNumber()));
451         } catch (AdbCommandRejectedException e) {
452             Log.w(LOG_TAG, String.format("failed to reboot %s: %s", device.getSerialNumber(),
453                     e.getMessage()));
454         }
455     }
456 
457     /**
458      * Handle situation where device is not available when expected to be in bootloader.
459      *
460      * @param monitor the {@link IDeviceStateMonitor}
461      * @throws DeviceNotAvailableException
462      */
handleDeviceBootloaderOrFastbootNotAvailable( final IDeviceStateMonitor monitor, String mode)463     private void handleDeviceBootloaderOrFastbootNotAvailable(
464             final IDeviceStateMonitor monitor, String mode) throws DeviceNotAvailableException {
465         throw new DeviceNotAvailableException(
466                 String.format("Could not find device %s in %s", monitor.getSerialNumber(), mode),
467                 monitor.getSerialNumber(),
468                 DeviceErrorIdentifier.DEVICE_UNAVAILABLE);
469     }
470 
471     /**
472      * {@inheritDoc}
473      */
474     @Override
recoverDeviceRecovery(IDeviceStateMonitor monitor)475     public void recoverDeviceRecovery(IDeviceStateMonitor monitor)
476             throws DeviceNotAvailableException {
477         throw new DeviceNotAvailableException("device recovery not implemented",
478                 monitor.getSerialNumber());
479     }
480 
481     /** Recovery routine for device unavailable errors. */
attemptDeviceUnavailableRecovery( IDeviceStateMonitor monitor, boolean recoverTillOnline)482     private boolean attemptDeviceUnavailableRecovery(
483             IDeviceStateMonitor monitor, boolean recoverTillOnline) {
484         TestDeviceState state = monitor.getDeviceState();
485         if (TestDeviceState.FASTBOOT.equals(state) || TestDeviceState.FASTBOOTD.equals(state)) {
486             CLog.d("Device is in '%s' state skipping USB reset attempt.", state);
487             return false;
488         }
489         String serial = monitor.getSerialNumber();
490         boolean recoveryAttempted = false;
491         // First try to do a USB reset to get the device back
492         try (UsbHelper usb = getUsbHelper()) {
493             try (UsbDevice usbDevice = usb.getDevice(serial)) {
494                 if (usbDevice != null) {
495                     CLog.d("Resetting USB port for device '%s'", serial);
496                     usbDevice.reset();
497                     recoveryAttempted = true;
498                     if (waitForDevice(monitor, recoverTillOnline)) {
499                         // Success
500                         CLog.d("Device recovered from USB reset and is online.");
501                         InvocationMetricLogger.addInvocationMetrics(
502                                 InvocationMetricKey.DEVICE_RECOVERY, 1);
503                         return true;
504                     }
505                 }
506             }
507         }
508         if (recoveryAttempted) {
509             // Sometimes device come back visible but in recovery
510             if (TestDeviceState.RECOVERY.equals(monitor.getDeviceState())) {
511                 IDevice device = monitor.waitForDeviceInRecovery();
512                 if (device != null) {
513                     CLog.d("Device came back in 'RECOVERY' mode when we expected 'ONLINE'");
514                     rebootDevice(
515                             device, null
516                             /** regular mode */
517                             );
518                     if (waitForDevice(monitor, recoverTillOnline)) {
519                         // Success
520                         CLog.d("Device recovered from recovery mode and is online.");
521                         InvocationMetricLogger.addInvocationMetrics(
522                                 InvocationMetricKey.DEVICE_RECOVERY, 1);
523                         // Individually track this too
524                         InvocationMetricLogger.addInvocationMetrics(
525                                 InvocationMetricKey.DEVICE_RECOVERY_FROM_RECOVERY, 1);
526                         return true;
527                     }
528                 }
529             }
530             // Track the failure
531             InvocationMetricLogger.addInvocationMetrics(
532                     InvocationMetricKey.DEVICE_RECOVERY_FAIL, 1);
533             CLog.w("USB reset recovery was unsuccessful");
534         }
535         return false;
536     }
537 
waitForDevice(IDeviceStateMonitor monitor, boolean recoverTillOnline)538     private boolean waitForDevice(IDeviceStateMonitor monitor, boolean recoverTillOnline) {
539         if (recoverTillOnline) {
540             if (monitor.waitForDeviceOnline() != null) {
541                 // Success
542                 return true;
543             }
544         } else if (monitor.waitForDeviceAvailable() != null) {
545             // Success
546             return true;
547         }
548         return false;
549     }
550 
551     @VisibleForTesting
getUsbHelper()552     UsbHelper getUsbHelper() {
553         return new UsbHelper();
554     }
555 }
556