AI 145968: am: CL 145727 CTS: Fixes and improvements for device reboots
  Recently, we see a new behavior where the device indicates that the boot
  is complete, but then the adb connection drops shortly after, while the
  CTS is trying to install a package. This means the CTS never sees a result
  for the package installation and keeps waiting forever. As a workaround,
  add a delay after the device indicates that the boot is complete, so that
  the connection is fully restored by the time the CTS resumes. Create a bugreport on the device if the connection drops during the time we wait after reboot.
  Also fix a problem in the disconnect notification.
  Original author: phillipd
  Merged from: //branches/cupcake/...

Automated import of CL 145968
diff --git a/tools/host/src/com/android/cts/DeviceManager.java b/tools/host/src/com/android/cts/DeviceManager.java
index 4e84058..85b88db 100644
--- a/tools/host/src/com/android/cts/DeviceManager.java
+++ b/tools/host/src/com/android/cts/DeviceManager.java
@@ -32,6 +32,11 @@
 
     private static final int SHORT_DELAY = 1000 * 15; // 15 seconds
     private static final int LONG_DELAY = 1000 * 60 * 10; // 10 minutes
+    /** Time to wait after issuing reboot command through ddmlib. */
+    private static final int DDMLIB_REBOOT_DELAY = 5000; // 5 seconds
+    /** Time to wait after device reports that boot is complete. */
+    private static final int POST_BOOT_DELAY = 1000 * 60; // 1 minute
+    /** Maximal number of attempts to restart ADB connection. */
     private static final int MAX_ADB_RESTART_ATTEMPTS = 10;
     ArrayList<TestDevice> mDevices;
     /** This is used during device restart for blocking until the device has been reconnected. */
@@ -288,8 +293,11 @@
         String deviceSerialNumber = ts.getDeviceId();
         if (!deviceSerialNumber.toLowerCase().startsWith("emulator")) {
             try {
+                // send reboot command through ddmlib
                 Device dev = searchTestDevice(deviceSerialNumber).getDevice();
                 dev.executeShellCommand("reboot", new NullOutputReceiver());
+                // wait to make sure the reboot gets through before we tear down the connection
+                Thread.sleep(DDMLIB_REBOOT_DELAY);
             } catch (Exception e) {
                 Log.d("Could not issue reboot command through ddmlib: " + e);
                 // try to reboot the device using the command line adb
@@ -319,6 +327,27 @@
                         ts.setTestDevice(device);
                         deviceFound = true;
                         deviceConnected = device.waitForBootComplete();
+                        // After boot is complete, the ADB connection sometimes drops
+                        // for a short time. Wait for things to stabilize.
+                        try {
+                            Thread.sleep(POST_BOOT_DELAY);
+                        } catch (InterruptedException ignored) {
+                            // ignore
+                        }
+                        // If the connection dropped during the sleep above, the TestDevice
+                        // instance is no longer valid.
+                        TestDevice newDevice = searchTestDevice(deviceSerialNumber);
+                        if (newDevice != null) {
+                            ts.setTestDevice(newDevice);
+                            if (newDevice != device) {
+                                // the connection was dropped or a second reboot occurred
+                                executeCommand("adb -s " + deviceSerialNumber + " shell " +
+                                        "bugreport -o /sdcard/bugreports/doubleReboot");
+                            }
+                        } else {
+                            // connection dropped and has not come back up
+                            deviceFound = false; // go wait for next semaphore permit
+                        }
                     }
                 }
                 attempts += 1;
diff --git a/tools/host/src/com/android/cts/Log.java b/tools/host/src/com/android/cts/Log.java
index 4365dc1..9ee99c8 100644
--- a/tools/host/src/com/android/cts/Log.java
+++ b/tools/host/src/com/android/cts/Log.java
@@ -90,7 +90,7 @@
      * @param msg The message to be added to the debugging stream.
      */
     public static void d(final String msg) {
-        log(DEBUG_PREFIX + msg);
+        log(DEBUG_PREFIX + System.currentTimeMillis() + " " + msg);
 
         if (HostConfig.DEBUG) {
             mOut.println(DEBUG_PREFIX + msg);
diff --git a/tools/host/src/com/android/cts/Test.java b/tools/host/src/com/android/cts/Test.java
index 1e5c841..ecfa501 100644
--- a/tools/host/src/com/android/cts/Test.java
+++ b/tools/host/src/com/android/cts/Test.java
@@ -370,12 +370,15 @@
     public void notifyResult(CtsTestResult result) {
 
         Log.d("Test.notifyResult() is called. (Test.getFullName()=" + getFullName());
-        synchronized (mTimeOutTimer) {
-            mResult = result;
-
-            Log.d("notifyUpdateResult() detects that it needs to cancel mTimeOutTimer");
-            if (mTimeOutTimer != null) {
-                mTimeOutTimer.sendNotify();
+        mResult = result;
+        if (mTimeOutTimer != null) {
+            synchronized (mTimeOutTimer) {
+                // set result again in case timeout just happened
+                mResult = result;
+                Log.d("notifyUpdateResult() detects that it needs to cancel mTimeOutTimer");
+                if (mTimeOutTimer != null) {
+                    mTimeOutTimer.sendNotify();
+                }
             }
         }
     }
@@ -403,9 +406,11 @@
             mProgressObserver.stop();
         }
 
-        synchronized (mTimeOutTimer) {
-            mTimeOutTimer.cancel(false);
-            mTimeOutTimer.sendNotify();
+        if (mTimeOutTimer != null) {
+            synchronized (mTimeOutTimer) {
+                mTimeOutTimer.cancel(false);
+                mTimeOutTimer.sendNotify();
+            }
         }
     }
 }
diff --git a/tools/host/src/com/android/cts/TestDevice.java b/tools/host/src/com/android/cts/TestDevice.java
index 51b8322..bc5c82e 100644
--- a/tools/host/src/com/android/cts/TestDevice.java
+++ b/tools/host/src/com/android/cts/TestDevice.java
@@ -1505,7 +1505,6 @@
      */
     public void disconnected() {
         CUIOutputStream.println("Device(" + getSerialNumber() + ") disconnected");
-        mStatus = STATUS_OFFLINE;
         mDevice = null;
         mSyncService = null;
 
@@ -1515,12 +1514,14 @@
         }
 
         if (mStatus == STATUS_BUSY) {
+            Log.d("TestDevice.disconnected calls notifyTestingDeviceDisconnected");
             mDeviceObserver.notifyTestingDeviceDisconnected();
         } else {
             if (!TestSession.isADBServerRestartedMode()) {
                 CUIOutputStream.printPrompt();
             }
         }
+        mStatus = STATUS_OFFLINE;
     }
 
     /**
diff --git a/tools/host/src/com/android/cts/TestPackage.java b/tools/host/src/com/android/cts/TestPackage.java
index 463a91f..a8d97c2 100644
--- a/tools/host/src/com/android/cts/TestPackage.java
+++ b/tools/host/src/com/android/cts/TestPackage.java
@@ -600,7 +600,7 @@
         cleanUp();
 
         try {
-            CUIOutputStream.println("Test stoped.");
+            CUIOutputStream.println("Test stopped.");
             mTestThread.join();
         } catch (InterruptedException e) {
             Log.e("", e);