Update from https://crrev.com/327068

build/android/buildbot/bb_device_status_check.py

Index: build/android/buildbot/bb_device_status_check.py
diff --git a/build/android/buildbot/bb_device_status_check.py b/build/android/buildbot/bb_device_status_check.py
index 8561c0104b4724168cc20eda531e95f7849a6edb..8690a60a71409f3df38a6ce6a6a9ad384b9d2498 100755
--- a/build/android/buildbot/bb_device_status_check.py
+++ b/build/android/buildbot/bb_device_status_check.py
@@ -30,9 +30,14 @@ sys.path.append(os.path.join(os.path.dirname(__file__), '..'))
 from pylib import android_commands
 from pylib import constants
 from pylib.cmd_helper import GetCmdOutput
+from pylib.device import battery_utils
 from pylib.device import device_blacklist
+from pylib.device import device_errors
 from pylib.device import device_list
 from pylib.device import device_utils
+from pylib.utils import run_tests_helper
+
+_RE_DEVICE_ID = re.compile('Device ID = (\d+)')
 
 def DeviceInfo(serial, options):
   """Gathers info on a device via various adb calls.
@@ -44,73 +49,62 @@ def DeviceInfo(serial, options):
     Tuple of device type, build id, report as a string, error messages, and
     boolean indicating whether or not device can be used for testing.
   """
+  device = device_utils.DeviceUtils(serial)
+  battery = battery_utils.BatteryUtils(device)
 
-  device_adb = device_utils.DeviceUtils(serial)
-  device_type = device_adb.build_product
-  device_build = device_adb.build_id
-  device_build_type = device_adb.build_type
-  device_product_name = device_adb.product_name
-
-  try:
-    battery_info = device_adb.old_interface.GetBatteryInfo()
-  except Exception as e:
-    battery_info = {}
-    logging.error('Unable to obtain battery info for %s, %s', serial, e)
-
-  def _GetData(re_expression, line, lambda_function=lambda x: x):
-    if not line:
-      return 'Unknown'
-    found = re.findall(re_expression, line)
-    if found and len(found):
-      return lambda_function(found[0])
-    return 'Unknown'
-
-  battery_level = int(battery_info.get('level', 100))
-  imei_slice = _GetData(r'Device ID = (\d+)',
-                        device_adb.old_interface.GetSubscriberInfo(),
-                        lambda x: x[-6:])
+  battery_info = {}
+  battery_level = 100
+  errors = []
+  dev_good = True
   json_data = {
     'serial': serial,
-    'type': device_type,
-    'build': device_build,
-    'build_detail': device_adb.GetProp('ro.build.fingerprint'),
-    'battery': battery_info,
-    'imei_slice': imei_slice,
-    'wifi_ip': device_adb.GetProp('dhcp.wlan0.ipaddress'),
+    'type': device.build_product,
+    'build': device.build_id,
+    'build_detail': device.GetProp('ro.build.fingerprint'),
+    'battery': {},
+    'imei_slice': 'Unknown',
+    'wifi_ip': device.GetProp('dhcp.wlan0.ipaddress'),
   }
-  report = ['Device %s (%s)' % (serial, device_type),
-            '  Build: %s (%s)' %
-              (device_build, json_data['build_detail']),
-            '  Current Battery Service state: ',
-            '\n'.join(['    %s: %s' % (k, v)
-                       for k, v in battery_info.iteritems()]),
-            '  IMEI slice: %s' % imei_slice,
-            '  Wifi IP: %s' % json_data['wifi_ip'],
-            '']
 
-  errors = []
-  dev_good = True
-  if battery_level < 15:
-    errors += ['Device critically low in battery. Will add to blacklist.']
-    dev_good = False
-    if not device_adb.old_interface.IsDeviceCharging():
-      if device_adb.old_interface.CanControlUsbCharging():
-        device_adb.old_interface.EnableUsbCharging()
-      else:
-        logging.error('Device %s is not charging' % serial)
-  if not options.no_provisioning_check:
-    setup_wizard_disabled = (
-        device_adb.GetProp('ro.setupwizard.mode') == 'DISABLED')
-    if not setup_wizard_disabled and device_build_type != 'user':
-      errors += ['Setup wizard not disabled. Was it provisioned correctly?']
-  if (device_product_name == 'mantaray' and
-      battery_info.get('AC powered', None) != 'true'):
-    errors += ['Mantaray device not connected to AC power.']
+  try:
+    try:
+      battery_info = battery.GetBatteryInfo(timeout=5)
+      battery_level = int(battery_info.get('level', battery_level))
+      json_data['battery'] = battery_info
+    except device_errors.CommandFailedError:
+      logging.exception('Failed to get battery information for %s', serial)
 
-  full_report = '\n'.join(report)
+    try:
+      for l in device.RunShellCommand(['dumpsys', 'iphonesubinfo'],
+                                      check_return=True, timeout=5):
+        m = _RE_DEVICE_ID.match(l)
+        if m:
+          json_data['imei_slice'] = m.group(1)[-6:]
+    except device_errors.CommandFailedError:
+      logging.exception('Failed to get IMEI slice for %s', serial)
+
+    if battery_level < 15:
+      errors += ['Device critically low in battery.']
+      dev_good = False
+      if not battery.GetCharging():
+        battery.SetCharging(True)
+    if not options.no_provisioning_check:
+      setup_wizard_disabled = (
+          device.GetProp('ro.setupwizard.mode') == 'DISABLED')
+      if not setup_wizard_disabled and device.build_type != 'user':
+        errors += ['Setup wizard not disabled. Was it provisioned correctly?']
+    if (device.product_name == 'mantaray' and
+        battery_info.get('AC powered', None) != 'true'):
+      errors += ['Mantaray device not connected to AC power.']
+  except device_errors.CommandFailedError:
+    logging.exception('Failure while getting device status.')
+    dev_good = False
+  except device_errors.CommandTimeoutError:
+    logging.exception('Timeout while getting device status.')
+    dev_good = False
 
-  return (device_type, device_build, battery_level, full_report, errors,
-    dev_good, json_data)
+  return (device.build_product, device.build_id, battery_level, errors,
+          dev_good, json_data)
 
 
 def CheckForMissingDevices(options, adb_online_devs):
@@ -122,11 +116,6 @@ def CheckForMissingDevices(options, adb_online_devs):
     adb_online_devs: A list of serial numbers of the currently visible
                      and online attached devices.
   """
-  # TODO(navabi): remove this once the bug that causes different number
-  # of devices to be detected between calls is fixed.
-  logger = logging.getLogger()
-  logger.setLevel(logging.INFO)
-
   out_dir = os.path.abspath(options.out_dir)
 
   # last_devices denotes all known devices prior to this run
@@ -189,10 +178,10 @@ def CheckForMissingDevices(options, adb_online_devs):
                                  os.environ.get('BUILDBOT_SLAVENAME'),
                                  os.environ.get('BUILDBOT_BUILDNUMBER')))))
     return ['Current online devices: %s' % adb_online_devs,
-            '%s are no longer visible. Were they removed?\n' % missing_devs,
-            'SHERIFF:\n',
-            '@@@STEP_LINK@Click here to file a bug@%s@@@\n' % crbug_link,
-            'Cache file: %s\n\n' % last_devices_path,
+            '%s are no longer visible. Were they removed?' % missing_devs,
+            'SHERIFF:',
+            '@@@STEP_LINK@Click here to file a bug@%s@@@' % crbug_link,
+            'Cache file: %s' % last_devices_path,
             'adb devices: %s' % GetCmdOutput(['adb', 'devices']),
             'adb devices(GetAttachedDevices): %s' % adb_online_devs]
   else:
@@ -201,8 +190,9 @@ def CheckForMissingDevices(options, adb_online_devs):
       bb_annotations.PrintWarning()
       bb_annotations.PrintSummaryText(
           '%d new devices detected' % len(new_devs))
-      print ('New devices detected %s. And now back to your '
-             'regularly scheduled program.' % list(new_devs))
+      logging.info('New devices detected:')
+      for d in new_devs:
+        logging.info('  %s', d)
 
 
 def SendEmail(from_address, to_addresses, cc_addresses, subject, msg):
@@ -214,20 +204,20 @@ def SendEmail(from_address, to_addresses, cc_addresses, subject, msg):
     server = smtplib.SMTP('localhost')
     server.sendmail(from_address, to_addresses, msg_body)
     server.quit()
-  except Exception as e:
-    print 'Failed to send alert email. Error: %s' % e
+  except Exception:
+    logging.exception('Failed to send alert email.')
 
 
 def RestartUsb():
   if not os.path.isfile('/usr/bin/restart_usb'):
-    print ('ERROR: Could not restart usb. /usr/bin/restart_usb not installed '
-           'on host (see BUG=305769).')
+    logging.error('Could not restart usb. ''/usr/bin/restart_usb not '
+                  'installed on host (see BUG=305769).')
     return False
 
   lsusb_proc = bb_utils.SpawnCmd(['lsusb'], stdout=subprocess.PIPE)
   lsusb_output, _ = lsusb_proc.communicate()
   if lsusb_proc.returncode:
-    print 'Error: Could not get list of USB ports (i.e. lsusb).'
+    logging.error('Could not get list of USB ports (i.e. lsusb).')
     return lsusb_proc.returncode
 
   usb_devices = [re.findall(r'Bus (\d\d\d) Device (\d\d\d)', lsusb_line)[0]
@@ -243,10 +233,11 @@ def RestartUsb():
     if dev != '001':
       return_code = bb_utils.RunCmd(['/usr/bin/restart_usb', bus, dev])
       if return_code:
-        print 'Error restarting USB device /dev/bus/usb/%s/%s' % (bus, dev)
+        logging.error('Error restarting USB device /dev/bus/usb/%s/%s',
+                      bus, dev)
         all_restarted = False
       else:
-        print 'Restarted USB device /dev/bus/usb/%s/%s' % (bus, dev)
+        logging.info('Restarted USB device /dev/bus/usb/%s/%s', bus, dev)
 
   return all_restarted
 
@@ -263,14 +254,15 @@ def KillAllAdb():
   for sig in [signal.SIGTERM, signal.SIGQUIT, signal.SIGKILL]:
     for p in GetAllAdb():
       try:
-        print 'kill %d %d (%s [%s])' % (sig, p.pid, p.name,
-            ' '.join(p.cmdline))
+        logging.info('kill %d %d (%s [%s])', sig, p.pid, p.name,
+                     ' '.join(p.cmdline))
         p.send_signal(sig)
       except (psutil.NoSuchProcess, psutil.AccessDenied):
         pass
   for p in GetAllAdb():
     try:
-      print 'Unable to kill %d (%s [%s])' % (p.pid, p.name, ' '.join(p.cmdline))
+      logging.error('Unable to kill %d (%s [%s])', p.pid, p.name,
+                    ' '.join(p.cmdline))
     except (psutil.NoSuchProcess, psutil.AccessDenied):
       pass
 
@@ -288,11 +280,15 @@ def main():
                     help='Restart USB ports before running device check.')
   parser.add_option('--json-output',
                     help='Output JSON information into a specified file.')
+  parser.add_option('-v', '--verbose', action='count', default=1,
+                    help='Log more information.')
 
   options, args = parser.parse_args()
   if args:
     parser.error('Unknown options %s' % args)
 
+  run_tests_helper.SetLogLevel(options.verbose)
+
   # Remove the last build's "bad devices" before checking device statuses.
   device_blacklist.ResetBlacklist()
 
@@ -304,7 +300,8 @@ def main():
   devices = android_commands.GetAttachedDevices()
   # Only restart usb if devices are missing.
   if set(expected_devices) != set(devices):
-    print 'expected_devices: %s, devices: %s' % (expected_devices, devices)
+    logging.warning('expected_devices: %s', expected_devices)
+    logging.warning('devices: %s', devices)
     KillAllAdb()
     retries = 5
     usb_restarted = True
@@ -312,9 +309,10 @@ def main():
       if not RestartUsb():
         usb_restarted = False
         bb_annotations.PrintWarning()
-        print 'USB reset stage failed, wait for any device to come back.'
+        logging.error('USB reset stage failed, '
+                      'wait for any device to come back.')
     while retries:
-      print 'retry adb devices...'
+      logging.info('retry adb devices...')
       time.sleep(1)
       devices = android_commands.GetAttachedDevices()
       if set(expected_devices) == set(devices):
@@ -330,10 +328,10 @@ def main():
   offline_devices = android_commands.GetAttachedDevices(
       hardware=False, emulator=False, offline=True)
 
-  types, builds, batteries, reports, errors, json_data = [], [], [], [], [], []
-  fail_step_lst = []
+  types, builds, batteries, errors, devices_ok, json_data = (
+      [], [], [], [], [], [])
   if devices:
-    types, builds, batteries, reports, errors, fail_step_lst, json_data = (
+    types, builds, batteries, errors, devices_ok, json_data = (
         zip(*[DeviceInfo(dev, options) for dev in devices]))
 
   # Write device info to file for buildbot info display.
@@ -354,7 +352,16 @@ def main():
 
   bb_annotations.PrintMsg('Online devices: %d. Device types %s, builds %s'
                            % (len(devices), unique_types, unique_builds))
-  print '\n'.join(reports)
+
+  for j in json_data:
+    logging.info('Device %s (%s)', j.get('serial'), j.get('type'))
+    logging.info('  Build: %s (%s)', j.get('build'), j.get('build_detail'))
+    logging.info('  Current Battery Service state:')
+    for k, v in j.get('battery', {}).iteritems():
+      logging.info('    %s: %s', k, v)
+    logging.info('  IMEI slice: %s', j.get('imei_slice'))
+    logging.info('  WiFi IP: %s', j.get('wifi_ip'))
+
 
   for serial, dev_errors in zip(devices, errors):
     if dev_errors:
@@ -363,14 +370,14 @@ def main():
 
   if err_msg:
     bb_annotations.PrintWarning()
-    msg = '\n'.join(err_msg)
-    print msg
+    for e in err_msg:
+      logging.error(e)
     from_address = 'buildbot@chromium.org'
     to_addresses = ['chromium-android-device-alerts@google.com']
     bot_name = os.environ.get('BUILDBOT_BUILDERNAME')
     slave_name = os.environ.get('BUILDBOT_SLAVENAME')
     subject = 'Device status check errors on %s, %s.' % (slave_name, bot_name)
-    SendEmail(from_address, to_addresses, [], subject, msg)
+    SendEmail(from_address, to_addresses, [], subject, '\n'.join(err_msg))
 
   if options.device_status_dashboard:
     perf_tests_results_helper.PrintPerfResult('BotDevices', 'OnlineDevices',
@@ -388,8 +395,9 @@ def main():
       f.write(json.dumps(json_data, indent=4))
 
   num_failed_devs = 0
-  for fail_status, device in zip(fail_step_lst, devices):
-    if not fail_status:
+  for device_ok, device in zip(devices_ok, devices):
+    if not device_ok:
+      logging.warning('Blacklisting %s', str(device))
       device_blacklist.ExtendBlacklist([str(device)])
       num_failed_devs += 1