diff options
| author | John Reck <jreck@google.com> | 2016-10-19 08:18:32 -0700 |
|---|---|---|
| committer | John Reck <jreck@google.com> | 2016-10-20 15:39:28 -0700 |
| commit | eeb03f366d148f92337cfd7577087ade44ab9285 (patch) | |
| tree | b6ffda675a47b15a69daf9da1ebf7108f48a5836 /catapult/devil | |
| parent | 61575af334bf03f270cf3b3b7a79c978159861eb (diff) | |
| download | chromium-trace-eeb03f366d148f92337cfd7577087ade44ab9285.tar.gz | |
Update catapult and how we update catapult
Test: manual, ran systrace.py
Change-Id: Ifda344fd8ff744b8dd0151f748c35c620a628016
Diffstat (limited to 'catapult/devil')
35 files changed, 1024 insertions, 372 deletions
diff --git a/catapult/devil/devil/android/battery_utils.py b/catapult/devil/devil/android/battery_utils.py index 7a735f35..3b225aa1 100644 --- a/catapult/devil/devil/android/battery_utils.py +++ b/catapult/devil/devil/android/battery_utils.py @@ -17,14 +17,15 @@ from devil.android import device_utils from devil.android.sdk import version_codes from devil.utils import timeout_retry +logger = logging.getLogger(__name__) + _DEFAULT_TIMEOUT = 30 _DEFAULT_RETRIES = 3 _DEVICE_PROFILES = [ { - 'name': 'Nexus 4', - 'witness_file': '/sys/module/pm8921_charger/parameters/disabled', + 'name': ['Nexus 4'], 'enable_command': ( 'echo 0 > /sys/module/pm8921_charger/parameters/disabled && ' 'dumpsys battery reset'), @@ -36,12 +37,11 @@ _DEVICE_PROFILES = [ 'current': None, }, { - 'name': 'Nexus 5', + 'name': ['Nexus 5'], # Nexus 5 # Setting the HIZ bit of the bq24192 causes the charger to actually ignore # energy coming from USB. Setting the power_supply offline just updates the # Android system to reflect that. - 'witness_file': '/sys/kernel/debug/bq24192/INPUT_SRC_CONT', 'enable_command': ( 'echo 0x4A > /sys/kernel/debug/bq24192/INPUT_SRC_CONT && ' 'chmod 644 /sys/class/power_supply/usb/online && ' @@ -57,8 +57,7 @@ _DEVICE_PROFILES = [ 'current': None, }, { - 'name': 'Nexus 6', - 'witness_file': None, + 'name': ['Nexus 6'], 'enable_command': ( 'echo 1 > /sys/class/power_supply/battery/charging_enabled && ' 'dumpsys battery reset'), @@ -71,8 +70,7 @@ _DEVICE_PROFILES = [ 'current': '/sys/class/power_supply/max170xx_battery/current_now', }, { - 'name': 'Nexus 9', - 'witness_file': None, + 'name': ['Nexus 9'], 'enable_command': ( 'echo Disconnected > ' '/sys/bus/i2c/drivers/bq2419x/0-006b/input_cable_state && ' @@ -86,8 +84,7 @@ _DEVICE_PROFILES = [ 'current': '/sys/class/power_supply/battery/current_now', }, { - 'name': 'Nexus 10', - 'witness_file': None, + 'name': ['Nexus 10'], 'enable_command': None, 'disable_command': None, 'charge_counter': None, @@ -96,8 +93,7 @@ _DEVICE_PROFILES = [ }, { - 'name': 'Nexus 5X', - 'witness_file': None, + 'name': ['Nexus 5X'], 'enable_command': ( 'echo 1 > /sys/class/power_supply/battery/charging_enabled && ' 'dumpsys battery reset'), @@ -108,6 +104,42 @@ _DEVICE_PROFILES = [ 'voltage': None, 'current': None, }, + { # Galaxy s5 + 'name': ['SM-G900H'], + 'enable_command': ( + 'chmod 644 /sys/class/power_supply/battery/test_mode && ' + 'chmod 644 /sys/class/power_supply/sec-charger/current_now && ' + 'echo 0 > /sys/class/power_supply/battery/test_mode && ' + 'echo 9999 > /sys/class/power_supply/sec-charger/current_now &&' + 'dumpsys battery reset'), + 'disable_command': ( + 'chmod 644 /sys/class/power_supply/battery/test_mode && ' + 'chmod 644 /sys/class/power_supply/sec-charger/current_now && ' + 'echo 1 > /sys/class/power_supply/battery/test_mode && ' + 'echo 0 > /sys/class/power_supply/sec-charger/current_now && ' + 'dumpsys battery set ac 0 && dumpsys battery set usb 0'), + 'charge_counter': None, + 'voltage': '/sys/class/power_supply/sec-fuelgauge/voltage_now', + 'current': '/sys/class/power_supply/sec-charger/current_now', + }, + { # Galaxy s6, Galaxy s6, Galaxy s6 edge + 'name': ['SM-G920F', 'SM-G920V', 'SM-G925V'], + 'enable_command': ( + 'chmod 644 /sys/class/power_supply/battery/test_mode && ' + 'chmod 644 /sys/class/power_supply/max77843-charger/current_now && ' + 'echo 0 > /sys/class/power_supply/battery/test_mode && ' + 'echo 9999 > /sys/class/power_supply/max77843-charger/current_now &&' + 'dumpsys battery reset'), + 'disable_command': ( + 'chmod 644 /sys/class/power_supply/battery/test_mode && ' + 'chmod 644 /sys/class/power_supply/max77843-charger/current_now && ' + 'echo 1 > /sys/class/power_supply/battery/test_mode && ' + 'echo 0 > /sys/class/power_supply/max77843-charger/current_now && ' + 'dumpsys battery set ac 0 && dumpsys battery set usb 0'), + 'charge_counter': None, + 'voltage': '/sys/class/power_supply/max77843-fuelgauge/voltage_now', + 'current': '/sys/class/power_supply/max77843-charger/current_now', + }, ] # The list of useful dumpsys columns. @@ -214,8 +246,8 @@ class BatteryUtils(object): if package not in self._cache['uids']: self.GetPowerData() if package not in self._cache['uids']: - logging.warning('No UID found for %s. Can\'t get network data.', - package) + logger.warning('No UID found for %s. Can\'t get network data.', + package) return None network_data_path = '/proc/uid_stat/%s/' % self._cache['uids'][package] @@ -224,12 +256,12 @@ class BatteryUtils(object): # If ReadFile throws exception, it means no network data usage file for # package has been recorded. Return 0 sent and 0 received. except device_errors.AdbShellCommandFailedError: - logging.warning('No sent data found for package %s', package) + logger.warning('No sent data found for package %s', package) send_data = 0 try: recv_data = int(self._device.ReadFile(network_data_path + 'tcp_rcv')) except device_errors.AdbShellCommandFailedError: - logging.warning('No received data found for package %s', package) + logger.warning('No received data found for package %s', package) recv_data = 0 return (send_data, recv_data) @@ -311,10 +343,10 @@ class BatteryUtils(object): ['dumpsys', 'battery'], check_return=True)[1:]: # If usb charging has been disabled, an extra line of header exists. if 'UPDATES STOPPED' in line: - logging.warning('Dumpsys battery not receiving updates. ' - 'Run dumpsys battery reset if this is in error.') + logger.warning('Dumpsys battery not receiving updates. ' + 'Run dumpsys battery reset if this is in error.') elif ':' not in line: - logging.warning('Unknown line found in dumpsys battery: "%s"', line) + logger.warning('Unknown line found in dumpsys battery: "%s"', line) else: k, v = line.split(':', 1) result[k.strip()] = v.strip() @@ -428,12 +460,12 @@ class BatteryUtils(object): raise ValueError('Discharge amount(%s) must be between 1 and 99' % percent) if battery_level is None: - logging.warning('Unable to find current battery level. Cannot discharge.') + logger.warning('Unable to find current battery level. Cannot discharge.') return # Do not discharge if it would make battery level too low. if percent >= battery_level - 10: - logging.warning('Battery is too low or discharge amount requested is too ' - 'high. Cannot discharge phone %s percent.', percent) + logger.warning('Battery is too low or discharge amount requested is too ' + 'high. Cannot discharge phone %s percent.', percent) return self._HardwareSetCharging(False) @@ -441,7 +473,7 @@ class BatteryUtils(object): def device_discharged(): self._HardwareSetCharging(True) current_level = int(self.GetBatteryInfo().get('level')) - logging.info('current battery level: %s', current_level) + logger.info('current battery level: %s', current_level) if battery_level - current_level >= percent: return True self._HardwareSetCharging(False) @@ -466,10 +498,10 @@ class BatteryUtils(object): def device_charged(): battery_level = self.GetBatteryInfo().get('level') if battery_level is None: - logging.warning('Unable to find current battery level.') + logger.warning('Unable to find current battery level.') battery_level = 100 else: - logging.info('current battery level: %s', battery_level) + logger.info('current battery level: %s', battery_level) battery_level = int(battery_level) # Use > so that it will not reset if charge is going down. @@ -497,21 +529,21 @@ class BatteryUtils(object): def cool_device(): temp = self.GetBatteryInfo().get('temperature') if temp is None: - logging.warning('Unable to find current battery temperature.') + logger.warning('Unable to find current battery temperature.') temp = 0 else: - logging.info('Current battery temperature: %s', temp) + logger.info('Current battery temperature: %s', temp) if int(temp) <= target_temp: return True else: - if self._cache['profile']['name'] == 'Nexus 5': + if 'Nexus 5' in self._cache['profile']['name']: self._DischargeDevice(1) return False self._DiscoverDeviceProfile() self.EnableBatteryUpdates() - logging.info('Waiting for the device to cool down to %s (0.1 C)', - target_temp) + logger.info('Waiting for the device to cool down to %s (0.1 C)', + target_temp) timeout_retry.WaitFor(cool_device, wait_period=wait_period) @decorators.WithTimeoutAndRetriesFromInstance() @@ -525,7 +557,7 @@ class BatteryUtils(object): retries: number of retries """ if self.GetCharging() == enabled: - logging.warning('Device charging already in expected state: %s', enabled) + logger.warning('Device charging already in expected state: %s', enabled) return self._DiscoverDeviceProfile() @@ -533,15 +565,15 @@ class BatteryUtils(object): if self._cache['profile']['enable_command']: self._HardwareSetCharging(enabled) else: - logging.info('Unable to enable charging via hardware. ' - 'Falling back to software enabling.') + logger.info('Unable to enable charging via hardware. ' + 'Falling back to software enabling.') self.EnableBatteryUpdates() else: if self._cache['profile']['enable_command']: self._ClearPowerData() self._HardwareSetCharging(enabled) else: - logging.info('Unable to disable charging via hardware. ' + logger.info('Unable to disable charging via hardware. ' 'Falling back to software disabling.') self.DisableBatteryUpdates() @@ -613,8 +645,8 @@ class BatteryUtils(object): but fails. """ if self._device.build_version_sdk < version_codes.LOLLIPOP: - logging.warning('Dumpsys power data only available on 5.0 and above. ' - 'Cannot clear power data.') + logger.warning('Dumpsys power data only available on 5.0 and above. ' + 'Cannot clear power data.') return False self._device.RunShellCommand( @@ -653,12 +685,11 @@ class BatteryUtils(object): if 'profile' in self._cache: return True for profile in _DEVICE_PROFILES: - if self._device.product_model == profile['name']: + if self._device.product_model in profile['name']: self._cache['profile'] = profile return True self._cache['profile'] = { - 'name': None, - 'witness_file': None, + 'name': [], 'enable_command': None, 'disable_command': None, 'charge_counter': None, diff --git a/catapult/devil/devil/android/battery_utils_test.py b/catapult/devil/devil/android/battery_utils_test.py index 9fbd1276..beaba3b0 100755 --- a/catapult/devil/devil/android/battery_utils_test.py +++ b/catapult/devil/devil/android/battery_utils_test.py @@ -616,13 +616,13 @@ class BatteryUtilsDiscoverDeviceProfile(BatteryUtilsTest): with self.patch_call(self.call.device.product_model, return_value='Nexus 4'): self.battery._DiscoverDeviceProfile() - self.assertEqual(self.battery._cache['profile']['name'], "Nexus 4") + self.assertListEqual(self.battery._cache['profile']['name'], ["Nexus 4"]) def testDiscoverDeviceProfile_unknown(self): with self.patch_call(self.call.device.product_model, return_value='Other'): self.battery._DiscoverDeviceProfile() - self.assertEqual(self.battery._cache['profile']['name'], None) + self.assertListEqual(self.battery._cache['profile']['name'], []) class BatteryUtilsClearPowerData(BatteryUtilsTest): diff --git a/catapult/devil/devil/android/device_blacklist.py b/catapult/devil/devil/android/device_blacklist.py index e8055a77..010e9965 100644 --- a/catapult/devil/devil/android/device_blacklist.py +++ b/catapult/devil/devil/android/device_blacklist.py @@ -8,6 +8,8 @@ import os import threading import time +logger = logging.getLogger(__name__) + class Blacklist(object): @@ -30,11 +32,11 @@ class Blacklist(object): with open(self._path, 'r') as f: blacklist = json.load(f) except (IOError, ValueError) as e: - logging.warning('Unable to read blacklist: %s', str(e)) + logger.warning('Unable to read blacklist: %s', str(e)) os.remove(self._path) if not isinstance(blacklist, dict): - logging.warning('Ignoring %s: %s (a dict was expected instead)', + logger.warning('Ignoring %s: %s (a dict was expected instead)', self._path, blacklist) blacklist = dict() @@ -63,7 +65,7 @@ class Blacklist(object): 'reason': reason, } device_dicts = {device: event_info for device in devices} - logging.info('Adding %s to blacklist %s for reason: %s', + logger.info('Adding %s to blacklist %s for reason: %s', ','.join(devices), self._path, reason) with self._blacklist_lock: blacklist = self.Read() @@ -72,7 +74,7 @@ class Blacklist(object): def Reset(self): """Erases the blacklist file if it exists.""" - logging.info('Resetting blacklist %s', self._path) + logger.info('Resetting blacklist %s', self._path) with self._blacklist_lock: if os.path.exists(self._path): os.remove(self._path) diff --git a/catapult/devil/devil/android/device_list.py b/catapult/devil/devil/android/device_list.py index 36a03b16..0fbb0f15 100644 --- a/catapult/devil/devil/android/device_list.py +++ b/catapult/devil/devil/android/device_list.py @@ -8,6 +8,8 @@ import json import logging import os +logger = logging.getLogger(__name__) + def GetPersistentDeviceList(file_name): """Returns a list of devices. @@ -18,7 +20,7 @@ def GetPersistentDeviceList(file_name): Returns: List of device serial numbers that were on the bot. """ if not os.path.isfile(file_name): - logging.warning('Device file %s doesn\'t exist.', file_name) + logger.warning("Device file %s doesn't exist.", file_name) return [] try: @@ -26,11 +28,11 @@ def GetPersistentDeviceList(file_name): devices = json.load(f) if not isinstance(devices, list) or not all(isinstance(d, basestring) for d in devices): - logging.warning('Unrecognized device file format: %s', devices) + logger.warning('Unrecognized device file format: %s', devices) return [] return [d for d in devices if d != '(error)'] except ValueError: - logging.exception( + logger.exception( 'Error reading device file %s. Falling back to old format.', file_name) # TODO(bpastene) Remove support for old unstructured file format. diff --git a/catapult/devil/devil/android/device_utils.py b/catapult/devil/devil/android/device_utils.py index 1a996500..0d16b81e 100644 --- a/catapult/devil/devil/android/device_utils.py +++ b/catapult/devil/devil/android/device_utils.py @@ -49,6 +49,8 @@ from devil.utils import reraiser_thread from devil.utils import timeout_retry from devil.utils import zip_utils +logger = logging.getLogger(__name__) + _DEFAULT_TIMEOUT = 30 _DEFAULT_RETRIES = 3 @@ -184,7 +186,7 @@ def RestartServer(): adb_wrapper.AdbWrapper.KillServer() if not timeout_retry.WaitFor(adb_killed, wait_period=1, max_tries=5): # TODO(perezju): raise an exception after fixng http://crbug.com/442319 - logging.warning('Failed to kill adb server') + logger.warning('Failed to kill adb server') adb_wrapper.AdbWrapper.StartServer() if not timeout_retry.WaitFor(adb_started, wait_period=1, max_tries=5): raise device_errors.CommandFailedError('Failed to start adb server') @@ -293,6 +295,11 @@ class DeviceUtils(object): self._ClearCache() + @property + def serial(self): + """Returns the device serial.""" + return self.adb.GetDeviceSerial() + def __eq__(self, other): """Checks whether |other| refers to the same device as |self|. @@ -302,7 +309,7 @@ class DeviceUtils(object): Returns: Whether |other| refers to the same device as |self|. """ - return self.adb.GetDeviceSerial() == str(other) + return self.serial == str(other) def __lt__(self, other): """Compares two instances of DeviceUtils. @@ -314,11 +321,11 @@ class DeviceUtils(object): Returns: Whether |self| is less than |other|. """ - return self.adb.GetDeviceSerial() < other.adb.GetDeviceSerial() + return self.serial < other.serial def __str__(self): """Returns the device serial.""" - return self.adb.GetDeviceSerial() + return self.serial @decorators.WithTimeoutAndRetriesFromInstance() def IsOnline(self, timeout=None, retries=None): @@ -337,7 +344,7 @@ class DeviceUtils(object): try: return self.adb.GetState() == 'device' except base_error.BaseError as exc: - logging.info('Failed to get state: %s', exc) + logger.info('Failed to get state: %s', exc) return False @decorators.WithTimeoutAndRetriesFromInstance() @@ -542,7 +549,7 @@ class DeviceUtils(object): if dataDir: return dataDir except device_errors.CommandFailedError: - logging.exception('Could not find data directory for %s', package) + logger.exception('Could not find data directory for %s', package) return None @decorators.WithTimeoutAndRetriesFromInstance() @@ -693,7 +700,7 @@ class DeviceUtils(object): all_apks += split_select.SelectSplits( self, base_apk.path, split_apks, allow_cached_props=allow_cached_props) if len(all_apks) == 1: - logging.warning('split-select did not select any from %s', split_apks) + logger.warning('split-select did not select any from %s', split_apks) package_name = base_apk.GetPackageName() device_apk_paths = self._GetApplicationPathsInternal(package_name) @@ -703,11 +710,11 @@ class DeviceUtils(object): if not device_apk_paths: apks_to_install = all_apks elif len(device_apk_paths) > 1 and not split_apks: - logging.warning( + logger.warning( 'Installing non-split APK when split APK was previously installed') apks_to_install = all_apks elif len(device_apk_paths) == 1 and split_apks: - logging.warning( + logger.warning( 'Installing split APK when non-split APK was previously installed') apks_to_install = all_apks else: @@ -715,7 +722,7 @@ class DeviceUtils(object): apks_to_install, host_checksums = ( self._ComputeStaleApks(package_name, all_apks)) except EnvironmentError as e: - logging.warning('Error calculating md5: %s', e) + logger.warning('Error calculating md5: %s', e) apks_to_install, host_checksums = all_apks, None if apks_to_install and not reinstall: self.Uninstall(package_name) @@ -783,7 +790,7 @@ class DeviceUtils(object): raise device_errors.DeviceVersionError( ('Requires SDK level %s, device is SDK level %s' % (required_sdk_level, self.build_version_sdk)), - device_serial=self.adb.GetDeviceSerial()) + device_serial=self.serial) @decorators.WithTimeoutAndRetriesFromInstance() def RunShellCommand(self, cmd, check_return=False, cwd=None, env=None, @@ -865,16 +872,16 @@ class DeviceUtils(object): else: with device_temp_file.DeviceTempFile(self.adb, suffix='.sh') as script: self._WriteFileWithPush(script.name, cmd) - logging.info('Large shell command will be run from file: %s ...', - cmd[:self._MAX_ADB_COMMAND_LENGTH]) + logger.info('Large shell command will be run from file: %s ...', + cmd[:self._MAX_ADB_COMMAND_LENGTH]) return handle_check_return('sh %s' % script.name_quoted) def handle_large_output(cmd, large_output_mode): if large_output_mode: with device_temp_file.DeviceTempFile(self.adb) as large_output_file: cmd = '( %s )>%s' % (cmd, large_output_file.name) - logging.debug('Large output mode enabled. Will write output to ' - 'device and read results from file.') + logger.debug('Large output mode enabled. Will write output to ' + 'device and read results from file.') handle_large_command(cmd) return self.ReadFile(large_output_file.name, force_pull=True) else: @@ -882,10 +889,10 @@ class DeviceUtils(object): return handle_large_command(cmd) except device_errors.AdbCommandFailedError as exc: if exc.status is None: - logging.error(_FormatPartialOutputError(exc.output)) - logging.warning('Attempting to run in large_output mode.') - logging.warning('Use RunShellCommand(..., large_output=True) for ' - 'shell commands that expect a lot of output.') + logger.error(_FormatPartialOutputError(exc.output)) + logger.warning('Attempting to run in large_output mode.') + logger.warning('Use RunShellCommand(..., large_output=True) for ' + 'shell commands that expect a lot of output.') return handle_large_output(cmd, True) else: raise @@ -927,10 +934,10 @@ class DeviceUtils(object): pipestatus_line = output[-1] if not pipestatus_line.startswith(PIPESTATUS_LEADER): - logging.error('Pipe exit statuses of shell script missing.') + logger.error('Pipe exit statuses of shell script missing.') raise device_errors.AdbShellCommandFailedError( script, output, status=None, - device_serial=self.adb.GetDeviceSerial()) + device_serial=self.serial) output = output[:-1] statuses = [ @@ -938,7 +945,7 @@ class DeviceUtils(object): if any(statuses): raise device_errors.AdbShellCommandFailedError( script, output, status=statuses, - device_serial=self.adb.GetDeviceSerial()) + device_serial=self.serial) return output @decorators.WithTimeoutAndRetriesFromInstance() @@ -982,11 +989,11 @@ class DeviceUtils(object): raise device_errors.CommandFailedError( 'No process "%s"' % process_name, str(self)) - logging.info( + logger.info( 'KillAll(%r, ...) attempting to kill the following:', process_name) for name, ids in procs_pids.iteritems(): for i in ids: - logging.info(' %05s %s', str(i), name) + logger.info(' %05s %s', str(i), name) cmd = ['kill', '-%d' % signum] + sorted(pids) self.RunShellCommand(cmd, as_root=as_root, check_return=True) @@ -1203,6 +1210,7 @@ class DeviceUtils(object): cache_commit_funcs = [] for h, d in host_device_tuples: assert os.path.isabs(h) and posixpath.isabs(d) + h = os.path.realpath(h) changed_files, up_to_date_files, stale_files, cache_commit_func = ( self._GetChangedAndStaleFiles(h, d, delete_device_stale)) all_changed_files += changed_files @@ -1273,7 +1281,7 @@ class DeviceUtils(object): calculate_host_checksums, calculate_device_checksums)) except EnvironmentError as e: - logging.warning('Error calculating md5: %s', e) + logger.warning('Error calculating md5: %s', e) return ([(host_path, device_path)], [], [], lambda: 0) to_push = [] @@ -1369,7 +1377,7 @@ class DeviceUtils(object): install_commands.InstallCommands(self) self._commands_installed = True except device_errors.CommandFailedError as e: - logging.warning('unzip not available: %s', str(e)) + logger.warning('unzip not available: %s', str(e)) self._commands_installed = False return self._commands_installed @@ -1625,7 +1633,7 @@ class DeviceUtils(object): if m.group('filename') not in ['.', '..']: entries.append(m.groupdict()) else: - logging.info('Skipping: %s', line) + logger.info('Skipping: %s', line) return entries @@ -2105,7 +2113,7 @@ class DeviceUtils(object): """ if not host_path: host_path = os.path.abspath('screenshot-%s-%s.png' % ( - self.adb.GetDeviceSerial(), _GetTimeStamp())) + self.serial, _GetTimeStamp())) with device_temp_file.DeviceTempFile(self.adb, suffix='.png') as device_tmp: self.RunShellCommand(['/system/bin/screencap', '-p', device_tmp.name], check_return=True) @@ -2134,12 +2142,12 @@ class DeviceUtils(object): try: result.update(self._GetMemoryUsageForPidFromSmaps(pid)) except device_errors.CommandFailedError: - logging.exception('Error getting memory usage from smaps') + logger.exception('Error getting memory usage from smaps') try: result.update(self._GetMemoryUsageForPidFromStatus(pid)) except device_errors.CommandFailedError: - logging.exception('Error getting memory usage from status') + logger.exception('Error getting memory usage from status') return result @@ -2166,13 +2174,13 @@ class DeviceUtils(object): if not match: return None package = match.group(2) - logging.warning('Trying to dismiss %s dialog for %s', *match.groups()) + logger.warning('Trying to dismiss %s dialog for %s', *match.groups()) self.SendKeyEvent(keyevent.KEYCODE_DPAD_RIGHT) self.SendKeyEvent(keyevent.KEYCODE_DPAD_RIGHT) self.SendKeyEvent(keyevent.KEYCODE_ENTER) match = _FindFocusedWindow() if match: - logging.error('Still showing a %s dialog for %s', *match.groups()) + logger.error('Still showing a %s dialog for %s', *match.groups()) return package def _GetMemoryUsageForPidFromSmaps(self, pid): @@ -2257,7 +2265,7 @@ class DeviceUtils(object): self._EnsureCacheInitialized() given_token = obj.get('token') if not given_token or self._cache['prev_token'] != given_token: - logging.warning('Stale cache detected. Not using it.') + logger.warning('Stale cache detected. Not using it.') return False self._cache['package_apk_paths'] = obj.get('package_apk_paths', {}) @@ -2370,7 +2378,7 @@ class DeviceUtils(object): def blacklisted(serial): if serial in blacklisted_devices: - logging.warning('Device %s is blacklisted.', serial) + logger.warning('Device %s is blacklisted.', serial) return True return False @@ -2390,7 +2398,7 @@ class DeviceUtils(object): @decorators.WithTimeoutAndRetriesFromInstance() def RestartAdbd(self, timeout=None, retries=None): - logging.info('Restarting adbd on device.') + logger.info('Restarting adbd on device.') with device_temp_file.DeviceTempFile(self.adb, suffix='.sh') as script: self.WriteFile(script.name, _RESTART_ADBD_SCRIPT) self.RunShellCommand(['source', script.name], as_root=True) @@ -2402,7 +2410,7 @@ class DeviceUtils(object): # the permission model. if not permissions or self.build_version_sdk < version_codes.MARSHMALLOW: return - logging.info('Setting permissions for %s.', package) + logger.info('Setting permissions for %s.', package) permissions = [p for p in permissions if p not in _PERMISSIONS_BLACKLIST] if ('android.permission.WRITE_EXTERNAL_STORAGE' in permissions and 'android.permission.READ_EXTERNAL_STORAGE' not in permissions): @@ -2411,10 +2419,10 @@ class DeviceUtils(object): if cmd: output = self.RunShellCommand(cmd, check_return=True) if output: - logging.warning('Possible problem when granting permissions. Blacklist ' - 'may need to be updated.') + logger.warning('Possible problem when granting permissions. Blacklist ' + 'may need to be updated.') for line in output: - logging.warning(' %s', line) + logger.warning(' %s', line) @decorators.WithTimeoutAndRetriesFromInstance() def IsScreenOn(self, timeout=None, retries=None): @@ -2460,7 +2468,7 @@ class DeviceUtils(object): return self.IsScreenOn() == on if screen_test(): - logging.info('Screen already in expected state.') + logger.info('Screen already in expected state.') return self.RunShellCommand('input keyevent 26') timeout_retry.WaitFor(screen_test, wait_period=1) diff --git a/catapult/devil/devil/android/fastboot_utils.py b/catapult/devil/devil/android/fastboot_utils.py index c5e8a498..3bd3ee8b 100644 --- a/catapult/devil/devil/android/fastboot_utils.py +++ b/catapult/devil/devil/android/fastboot_utils.py @@ -17,6 +17,8 @@ from devil.android import device_errors from devil.android.sdk import fastboot from devil.utils import timeout_retry +logger = logging.getLogger(__name__) + _DEFAULT_TIMEOUT = 30 _DEFAULT_RETRIES = 3 _FASTBOOT_REBOOT_TIMEOUT = 10 * _DEFAULT_TIMEOUT @@ -163,11 +165,11 @@ class FastbootUtils(object): elif board_name: return False else: - logging.warning('No board type found in %s.', - self._BOARD_VERIFICATION_FILE) + logger.warning('No board type found in %s.', + self._BOARD_VERIFICATION_FILE) else: - logging.warning('%s not found. Unable to use it to verify device.', - self._BOARD_VERIFICATION_FILE) + logger.warning('%s not found. Unable to use it to verify device.', + self._BOARD_VERIFICATION_FILE) zip_regex = re.compile(r'.*%s.*\.zip' % re.escape(self._board)) for f in files: @@ -192,9 +194,9 @@ class FastbootUtils(object): """ if not self._VerifyBoard(directory): if force: - logging.warning('Could not verify build is meant to be installed on ' - 'the current device type, but force flag is set. ' - 'Flashing device. Possibly dangerous operation.') + logger.warning('Could not verify build is meant to be installed on ' + 'the current device type, but force flag is set. ' + 'Flashing device. Possibly dangerous operation.') else: raise device_errors.CommandFailedError( 'Could not verify build is meant to be installed on the current ' @@ -205,10 +207,10 @@ class FastbootUtils(object): partitions = flash_image_files.keys() for partition in partitions: if _KNOWN_PARTITIONS[partition].get('wipe_only') and not wipe: - logging.info( + logger.info( 'Not flashing in wipe mode. Skipping partition %s.', partition) else: - logging.info( + logger.info( 'Flashing %s with %s', partition, flash_image_files[partition]) self.fastboot.Flash(partition, flash_image_files[partition]) if _KNOWN_PARTITIONS[partition].get('restart', False): diff --git a/catapult/devil/devil/android/flag_changer.py b/catapult/devil/devil/android/flag_changer.py index 4267f117..5de54eaa 100644 --- a/catapult/devil/devil/android/flag_changer.py +++ b/catapult/devil/devil/android/flag_changer.py @@ -6,6 +6,8 @@ import logging from devil.android import device_errors +logger = logging.getLogger(__name__) + class FlagChanger(object): """Changes the flags Chrome runs with. @@ -113,7 +115,7 @@ class FlagChanger(object): def _UpdateCommandLineFile(self): """Writes out the command line to the file, or removes it if empty.""" current_flags = list(self._state_stack[-1]) - logging.info('Current flags: %s', current_flags) + logger.info('Current flags: %s', current_flags) # Root is not required to write to /data/local/tmp/. use_root = '/data/local/tmp/' not in self._cmdline_file if current_flags: @@ -174,7 +176,7 @@ class FlagChanger(object): # Tack on the last flag. if not current_flag: if within_quotations: - logging.warn('Unterminated quoted argument: ' + line) + logger.warn('Unterminated quoted argument: ' + line) else: tokenized_flags.append(current_flag) diff --git a/catapult/devil/devil/android/forwarder.py b/catapult/devil/devil/android/forwarder.py index 99e8343b..a85d5f65 100644 --- a/catapult/devil/devil/android/forwarder.py +++ b/catapult/devil/devil/android/forwarder.py @@ -16,11 +16,46 @@ from devil.android.constants import file_system from devil.android.valgrind_tools import base_tool from devil.utils import cmd_helper +logger = logging.getLogger(__name__) + def _GetProcessStartTime(pid): return psutil.Process(pid).create_time +def _LogMapFailureDiagnostics(device): + # The host forwarder daemon logs to /tmp/host_forwarder_log, so print the end + # of that. + try: + with open('/tmp/host_forwarder_log') as host_forwarder_log: + logger.info('Last 50 lines of the host forwarder daemon log:') + for line in host_forwarder_log.read().splitlines()[-50:]: + logger.info(' %s', line) + except Exception: # pylint: disable=broad-except + # Grabbing the host forwarder log is best-effort. Ignore all errors. + logger.warning('Failed to get the contents of host_forwarder_log.') + + # The device forwarder daemon logs to the logcat, so print the end of that. + try: + logger.info('Last 50 lines of logcat:') + for logcat_line in device.adb.Logcat(dump=True)[-50:]: + logger.info(' %s', logcat_line) + except device_errors.CommandFailedError: + # Grabbing the device forwarder log is also best-effort. Ignore all errors. + logger.warning('Failed to get the contents of the logcat.') + + # Log alive device forwarders. + try: + ps_out = device.RunShellCommand(['ps'], check_return=True) + logger.info('Currently running device_forwarders:') + for line in ps_out: + if 'device_forwarder' in line: + logger.info(' %s', line) + except device_errors.CommandFailedError: + logger.warning('Failed to list currently running device_forwarder ' + 'instances.') + + class _FileLock(object): """With statement-aware implementation of a file lock. @@ -61,6 +96,8 @@ class Forwarder(object): # Defined in host_forwarder_main.cc _HOST_FORWARDER_LOG = '/tmp/host_forwarder_log' + _TIMEOUT = 60 # seconds + _instance = None @staticmethod @@ -87,17 +124,21 @@ class Forwarder(object): instance._InitDeviceLocked(device, tool) device_serial = str(device) - redirection_commands = [ + map_arg_lists = [ ['--adb=' + devil_env.config.FetchPath('adb'), '--serial-id=' + device_serial, '--map', str(device_port), str(host_port)] for device_port, host_port in port_pairs] - logging.info('Forwarding using commands: %s', redirection_commands) + logger.info('Forwarding using commands: %s', map_arg_lists) - for redirection_command in redirection_commands: + for map_arg_list in map_arg_lists: try: - (exit_code, output) = cmd_helper.GetCmdStatusAndOutput( - [instance._host_forwarder_path] + redirection_command) + map_cmd = [instance._host_forwarder_path] + map_arg_list + (exit_code, output) = cmd_helper.GetCmdStatusAndOutputWithTimeout( + map_cmd, Forwarder._TIMEOUT) + except cmd_helper.TimeoutError as e: + raise HostForwarderError( + '`%s` timed out:\n%s' % (' '.join(map_cmd), e.output)) except OSError as e: if e.errno == 2: raise HostForwarderError( @@ -105,16 +146,20 @@ class Forwarder(object): 'Make sure you have built host_forwarder.') else: raise if exit_code != 0: - Forwarder._KillDeviceLocked(device, tool) - # Log alive forwarders - ps_out = device.RunShellCommand(['ps']) - logging.info('Currently running device_forwarders:') - for line in ps_out: - if 'device_forwarder' in line: - logging.info(' %s', line) + try: + instance._KillDeviceLocked(device, tool) + except device_errors.CommandFailedError: + # We don't want the failure to kill the device forwarder to + # supersede the original failure to map. + logging.warning( + 'Failed to kill the device forwarder after map failure: %s', + str(e)) + _LogMapFailureDiagnostics(device) raise HostForwarderError( - '%s exited with %d:\n%s' % (instance._host_forwarder_path, - exit_code, '\n'.join(output))) + '`%s` exited with %d:\n%s' % ( + ' '.join(map_cmd), + exit_code, + '\n'.join(output))) tokens = output.split(':') if len(tokens) != 2: raise HostForwarderError( @@ -125,8 +170,8 @@ class Forwarder(object): serial_with_port = (device_serial, device_port) instance._device_to_host_port_map[serial_with_port] = host_port instance._host_to_device_port_map[host_port] = serial_with_port - logging.info('Forwarding device port: %d to host port: %d.', - device_port, host_port) + logger.info('Forwarding device port: %d to host port: %d.', + device_port, host_port) @staticmethod def UnmapDevicePort(device_port, device): @@ -148,19 +193,37 @@ class Forwarder(object): port_pairs: A list of tuples (device_port, host_port) to unmap. """ with _FileLock(Forwarder._LOCK_PATH): - if not Forwarder._instance: - return - adb_serial = str(device) - if adb_serial not in Forwarder._instance._initialized_devices: - return - port_map = Forwarder._GetInstanceLocked( - None)._device_to_host_port_map - for (device_serial, device_port) in port_map.keys(): - if adb_serial == device_serial: - Forwarder._UnmapDevicePortLocked(device_port, device) - # There are no more ports mapped, kill the device_forwarder. + instance = Forwarder._GetInstanceLocked(None) + unmap_all_cmd = [ + instance._host_forwarder_path, + '--adb=%s' % devil_env.config.FetchPath('adb'), + '--serial-id=%s' % device.serial, + '--unmap-all' + ] + try: + exit_code, output = cmd_helper.GetCmdStatusAndOutputWithTimeout( + unmap_all_cmd, Forwarder._TIMEOUT) + except cmd_helper.TimeoutError as e: + raise HostForwarderError( + '`%s` timed out:\n%s' % (' '.join(unmap_all_cmd), e.output)) + if exit_code != 0: + error_msg = [ + '`%s` exited with %d' % (' '.join(unmap_all_cmd), exit_code)] + error_msg += output + raise HostForwarderError('\n'.join(error_msg)) + + # Clean out any entries from the device & host map. + device_map = instance._device_to_host_port_map + host_map = instance._host_to_device_port_map + for device_serial_and_port, host_port in device_map.items(): + device_serial = device_serial_and_port[0] + if device_serial == device.serial: + del device_map[device_serial_and_port] + del host_map[host_port] + + # Kill the device forwarder. tool = base_tool.BaseTool() - Forwarder._KillDeviceLocked(device, tool) + instance._KillDeviceLocked(device, tool) @staticmethod def DevicePortForHostPort(host_port): @@ -225,22 +288,32 @@ class Forwarder(object): serial = str(device) serial_with_port = (serial, device_port) if not serial_with_port in instance._device_to_host_port_map: - logging.error('Trying to unmap non-forwarded port %d', device_port) + logger.error('Trying to unmap non-forwarded port %d', device_port) return - redirection_command = ['--adb=' + devil_env.config.FetchPath('adb'), - '--serial-id=' + serial, - '--unmap', str(device_port)] - logging.info('Undo forwarding using command: %s', redirection_command) - (exit_code, output) = cmd_helper.GetCmdStatusAndOutput( - [instance._host_forwarder_path] + redirection_command) - if exit_code != 0: - logging.error( - '%s exited with %d:\n%s', - instance._host_forwarder_path, exit_code, '\n'.join(output)) + host_port = instance._device_to_host_port_map[serial_with_port] del instance._device_to_host_port_map[serial_with_port] del instance._host_to_device_port_map[host_port] + unmap_cmd = [ + instance._host_forwarder_path, + '--adb=%s' % devil_env.config.FetchPath('adb'), + '--serial-id=%s' % serial, + '--unmap', str(device_port) + ] + try: + (exit_code, output) = cmd_helper.GetCmdStatusAndOutputWithTimeout( + unmap_cmd, Forwarder._TIMEOUT) + except cmd_helper.TimeoutError as e: + raise HostForwarderError( + '`%s` timed out:\n%s' % (' '.join(unmap_cmd), e.output)) + if exit_code != 0: + logger.error( + '`%s` exited with %d:\n%s', + ' '.join(unmap_cmd), + exit_code, + '\n'.join(output)) + @staticmethod def _GetPidForLock(): """Returns the PID used for host_forwarder initialization. @@ -290,9 +363,9 @@ class Forwarder(object): if device_serial in self._initialized_devices: return try: - Forwarder._KillDeviceLocked(device, tool) + self._KillDeviceLocked(device, tool) except device_errors.CommandFailedError: - logging.warning('Failed to kill device forwarder. Rebooting.') + logger.warning('Failed to kill device forwarder. Rebooting.') device.Reboot() forwarder_device_path_on_host = devil_env.config.FetchPath( 'forwarder_device', device=device) @@ -310,24 +383,48 @@ class Forwarder(object): check_return=True) self._initialized_devices.add(device_serial) + @staticmethod + def KillHost(): + """Kills the forwarder process running on the host.""" + with _FileLock(Forwarder._LOCK_PATH): + Forwarder._GetInstanceLocked(None)._KillHostLocked() + def _KillHostLocked(self): """Kills the forwarder process running on the host. Note that the global lock must be acquired before calling this method. """ - logging.info('Killing host_forwarder.') - (exit_code, output) = cmd_helper.GetCmdStatusAndOutput( - [self._host_forwarder_path, '--kill-server']) - if exit_code != 0: - (exit_code, output) = cmd_helper.GetCmdStatusAndOutput( - ['pkill', '-9', 'host_forwarder']) + logger.info('Killing host_forwarder.') + try: + kill_cmd = [self._host_forwarder_path, '--kill-server'] + (exit_code, _o) = cmd_helper.GetCmdStatusAndOutputWithTimeout( + kill_cmd, Forwarder._TIMEOUT) if exit_code != 0: - raise HostForwarderError( - '%s exited with %d:\n%s' % (self._host_forwarder_path, exit_code, - '\n'.join(output))) + kill_cmd = ['pkill', '-9', 'host_forwarder'] + (exit_code, output) = cmd_helper.GetCmdStatusAndOutputWithTimeout( + kill_cmd, Forwarder._TIMEOUT) + if exit_code != 0: + raise HostForwarderError( + '%s exited with %d:\n%s' % (self._host_forwarder_path, exit_code, + '\n'.join(output))) + except cmd_helper.TimeoutError as e: + raise HostForwarderError( + '`%s` timed out:\n%s' % (' '.join(kill_cmd), e.output)) @staticmethod - def _KillDeviceLocked(device, tool): + def KillDevice(device, tool=None): + """Kills the forwarder process running on the device. + + Args: + device: Instance of DeviceUtils for talking to the device. + tool: Wrapper tool (e.g. valgrind) that can be used to execute the device + forwarder (see valgrind_tools.py). + """ + with _FileLock(Forwarder._LOCK_PATH): + Forwarder._GetInstanceLocked(None)._KillDeviceLocked( + device, tool or base_tool.BaseTool()) + + def _KillDeviceLocked(self, device, tool): """Kills the forwarder process running on the device. Note that the global lock must be acquired before calling this method. @@ -337,8 +434,8 @@ class Forwarder(object): tool: Wrapper tool (e.g. valgrind) that can be used to execute the device forwarder (see valgrind_tools.py). """ - logging.info('Killing device_forwarder.') - Forwarder._instance._initialized_devices.discard(str(device)) + logger.info('Killing device_forwarder.') + self._initialized_devices.discard(device.serial) if not device.FileExists(Forwarder._DEVICE_FORWARDER_PATH): return diff --git a/catapult/devil/devil/android/logcat_monitor.py b/catapult/devil/devil/android/logcat_monitor.py index bf30d409..c99fda9f 100644 --- a/catapult/devil/devil/android/logcat_monitor.py +++ b/catapult/devil/devil/android/logcat_monitor.py @@ -18,6 +18,8 @@ from devil.android import device_errors from devil.android.sdk import adb_wrapper from devil.utils import reraiser_thread +logger = logging.getLogger(__name__) + class LogcatMonitor(object): @@ -89,7 +91,7 @@ class LogcatMonitor(object): if isinstance(failure_regex, basestring): failure_regex = re.compile(failure_regex) - logging.debug('Waiting %d seconds for "%s"', timeout, success_regex.pattern) + logger.debug('Waiting %d seconds for "%s"', timeout, success_regex.pattern) # NOTE This will continue looping until: # - success_regex matches a line, in which case the match object is @@ -232,7 +234,7 @@ class LogcatMonitor(object): """Closes logcat recording file in case |Close| was never called.""" with self._record_file_lock: if self._record_file: - logging.warning( + logger.warning( 'Need to call |Close| on the logcat monitor when done!') self._record_file.close() diff --git a/catapult/devil/devil/android/perf/perf_control.py b/catapult/devil/devil/android/perf/perf_control.py index 383b4fb2..225b7c95 100644 --- a/catapult/devil/devil/android/perf/perf_control.py +++ b/catapult/devil/devil/android/perf/perf_control.py @@ -8,6 +8,8 @@ import re from devil.android import device_errors +logger = logging.getLogger(__name__) + class PerfControl(object): """Provides methods for setting the performance mode of a device.""" @@ -23,7 +25,7 @@ class PerfControl(object): if self._CPU_FILE_PATTERN.match(filename)] assert self._cpu_files, 'Failed to detect CPUs.' self._cpu_file_list = ' '.join(self._cpu_files) - logging.info('CPUs found: %s', self._cpu_file_list) + logger.info('CPUs found: %s', self._cpu_file_list) self._have_mpdecision = self._device.FileExists('/system/bin/mpdecision') def SetHighPerfMode(self): @@ -32,10 +34,10 @@ class PerfControl(object): self._device.EnableRoot() except device_errors.CommandFailedError: message = 'Need root for performance mode. Results may be NOISY!!' - logging.warning(message) + logger.warning(message) # Add an additional warning at exit, such that it's clear that any results # may be different/noisy (due to the lack of intended performance mode). - atexit.register(logging.warning, message) + atexit.register(logger.warning, message) return product_model = self._device.product_model @@ -43,12 +45,12 @@ class PerfControl(object): if 'Nexus 4' == product_model: self._ForceAllCpusOnline(True) if not self._AllCpusAreOnline(): - logging.warning('Failed to force CPUs online. Results may be NOISY!') + logger.warning('Failed to force CPUs online. Results may be NOISY!') self._SetScalingGovernorInternal('performance') elif 'Nexus 5' == product_model: self._ForceAllCpusOnline(True) if not self._AllCpusAreOnline(): - logging.warning('Failed to force CPUs online. Results may be NOISY!') + logger.warning('Failed to force CPUs online. Results may be NOISY!') self._SetScalingGovernorInternal('performance') self._SetScalingMaxFreq(1190400) self._SetMaxGpuClock(200000000) @@ -111,9 +113,9 @@ class PerfControl(object): path=path, value=value)) cpus = ' '.join(cpu for (cpu, _, status) in results if status == 0) if cpus: - logging.info('Successfully set %s to %r on: %s', path, value, cpus) + logger.info('Successfully set %s to %r on: %s', path, value, cpus) else: - logging.warning('Failed to set %s to %r on any cpus', path, value) + logger.warning('Failed to set %s to %r on any cpus', path, value) def _SetScalingGovernorInternal(self, value): self._WriteEachCpuFile('cpufreq/scaling_governor', value) @@ -153,7 +155,7 @@ class PerfControl(object): self._device.RunShellCommand(cmd, check_return=True, as_root=True) if not self._have_mpdecision and not self._AllCpusAreOnline(): - logging.warning('Unexpected cpu hot plugging detected.') + logger.warning('Unexpected cpu hot plugging detected.') if force_online: self._ForEachCpu('echo 1 > "$CPU/online"') diff --git a/catapult/devil/devil/android/perf/thermal_throttle.py b/catapult/devil/devil/android/perf/thermal_throttle.py index 362a9d44..5a0454ec 100644 --- a/catapult/devil/devil/android/perf/thermal_throttle.py +++ b/catapult/devil/devil/android/perf/thermal_throttle.py @@ -4,6 +4,8 @@ import logging +logger = logging.getLogger(__name__) + class OmapThrottlingDetector(object): """Class to detect and track thermal throttling on an OMAP 4.""" @@ -101,32 +103,32 @@ class ThermalThrottle(object): for line in log: if self._detector.BecameThrottled(line): if not self._throttled: - logging.warning('>>> Device %s thermally throttled', serial_number) + logger.warning('>>> Device %s thermally throttled', serial_number) self._throttled = True has_been_throttled = True elif self._detector.BecameUnthrottled(line): if self._throttled: - logging.warning('>>> Device %s thermally unthrottled', serial_number) + logger.warning('>>> Device %s thermally unthrottled', serial_number) self._throttled = False has_been_throttled = True temperature = self._detector.GetThrottlingTemperature(line) if temperature is not None: - logging.info(u'Device %s thermally throttled at %3.1f%sC', - serial_number, temperature, degree_symbol) + logger.info(u'Device %s thermally throttled at %3.1f%sC', + serial_number, temperature, degree_symbol) - if logging.getLogger().isEnabledFor(logging.DEBUG): + if logger.isEnabledFor(logging.DEBUG): # Print current temperature of CPU SoC. temperature = self._detector.GetCurrentTemperature() if temperature is not None: - logging.debug(u'Current SoC temperature of %s = %3.1f%sC', - serial_number, temperature, degree_symbol) + logger.debug(u'Current SoC temperature of %s = %3.1f%sC', + serial_number, temperature, degree_symbol) # Print temperature of battery, to give a system temperature dumpsys_log = self._device.RunShellCommand('dumpsys battery') for line in dumpsys_log: if 'temperature' in line: btemp = float([s for s in line.split() if s.isdigit()][0]) / 10.0 - logging.debug(u'Current battery temperature of %s = %3.1f%sC', - serial_number, btemp, degree_symbol) + logger.debug(u'Current battery temperature of %s = %3.1f%sC', + serial_number, btemp, degree_symbol) return has_been_throttled diff --git a/catapult/devil/devil/android/ports.py b/catapult/devil/devil/android/ports.py index 6384d74b..1d4e5f21 100644 --- a/catapult/devil/devil/android/ports.py +++ b/catapult/devil/devil/android/ports.py @@ -12,6 +12,8 @@ import os import socket import traceback +logger = logging.getLogger(__name__) + # The net test server is started from port 10201. _TEST_SERVER_PORT_FIRST = 10201 _TEST_SERVER_PORT_LAST = 30000 @@ -36,7 +38,7 @@ def ResetTestServerPortAllocation(): fp.write('%d' % _TEST_SERVER_PORT_FIRST) return True except Exception: # pylint: disable=broad-except - logging.exception('Error while resetting port allocation') + logger.exception('Error while resetting port allocation') return False @@ -68,16 +70,16 @@ def AllocateTestServerPort(): fp.seek(0, os.SEEK_SET) fp.write('%d' % (port + 1)) except Exception: # pylint: disable=broad-except - logging.exception('Error while allocating port') + logger.exception('Error while allocating port') finally: if fp_lock: fcntl.flock(fp_lock, fcntl.LOCK_UN) fp_lock.close() if port: - logging.info('Allocate port %d for test server.', port) + logger.info('Allocate port %d for test server.', port) else: - logging.error('Could not allocate port for test server. ' - 'List of ports tried: %s', str(ports_tried)) + logger.error('Could not allocate port for test server. ' + 'List of ports tried: %s', str(ports_tried)) return port diff --git a/catapult/devil/devil/android/sdk/adb_wrapper.py b/catapult/devil/devil/android/sdk/adb_wrapper.py index cbc5ed5c..924aaa64 100644 --- a/catapult/devil/devil/android/sdk/adb_wrapper.py +++ b/catapult/devil/devil/android/sdk/adb_wrapper.py @@ -27,6 +27,8 @@ from devil.utils import timeout_retry with devil_env.SysPath(devil_env.DEPENDENCY_MANAGER_PATH): import dependency_manager # pylint: disable=import-error +logger = logging.getLogger(__name__) + ADB_KEYS_FILE = '/data/misc/adb/adb_keys' @@ -319,7 +321,7 @@ class AdbWrapper(object): def IsServerOnline(cls): status, output = cmd_helper.GetCmdStatusAndOutput(['pgrep', 'adb']) output = [int(x) for x in output.split()] - logging.info('PIDs for adb found: %r', output) + logger.info('PIDs for adb found: %r', output) return status == 0 # pylint: enable=unused-argument @@ -485,7 +487,7 @@ class AdbWrapper(object): try: status = int(output[output_end + 1:]) except ValueError: - logging.warning('exit status of shell command %r missing.', command) + logger.warning('exit status of shell command %r missing.', command) raise device_errors.AdbShellCommandFailedError( command, output, status=None, device_serial=self._device_serial) output = output[:output_end] diff --git a/catapult/devil/devil/android/sdk/gce_adb_wrapper.py b/catapult/devil/devil/android/sdk/gce_adb_wrapper.py index a85d2bd2..71600f40 100644 --- a/catapult/devil/devil/android/sdk/gce_adb_wrapper.py +++ b/catapult/devil/devil/android/sdk/gce_adb_wrapper.py @@ -18,6 +18,8 @@ from devil.android import device_errors from devil.android.sdk import adb_wrapper from devil.utils import cmd_helper +logger = logging.getLogger(__name__) + class GceAdbWrapper(adb_wrapper.AdbWrapper): @@ -113,7 +115,7 @@ class GceAdbWrapper(adb_wrapper.AdbWrapper): try: adb_wrapper.VerifyLocalFileExists(local) except (subprocess.CalledProcessError, IOError): - logging.exception('Error when pulling files from android instance.') + logger.exception('Error when pulling files from android instance.') raise device_errors.AdbCommandFailedError( cmd, 'File not reachable on host: %s' % local, device_serial=str(self)) diff --git a/catapult/devil/devil/android/sdk/shared_prefs.py b/catapult/devil/devil/android/sdk/shared_prefs.py index 50ff5c62..58370bc0 100644 --- a/catapult/devil/devil/android/sdk/shared_prefs.py +++ b/catapult/devil/devil/android/sdk/shared_prefs.py @@ -13,6 +13,8 @@ import posixpath from xml.etree import ElementTree +logger = logging.getLogger(__name__) + _XML_DECLARATION = "<?xml version='1.0' encoding='utf-8' standalone='yes' ?>\n" @@ -388,4 +390,4 @@ class SharedPrefs(object): if old_value != value: pref.set(value) self._changed = True - logging.info('Setting property: %s', pref) + logger.info('Setting property: %s', pref) diff --git a/catapult/devil/devil/android/sdk/version_codes.py b/catapult/devil/devil/android/sdk/version_codes.py index 410379b9..095b59cc 100644 --- a/catapult/devil/devil/android/sdk/version_codes.py +++ b/catapult/devil/devil/android/sdk/version_codes.py @@ -15,4 +15,5 @@ KITKAT_WATCH = 20 LOLLIPOP = 21 LOLLIPOP_MR1 = 22 MARSHMALLOW = 23 +NOUGAT = 24 diff --git a/catapult/devil/devil/android/settings.py b/catapult/devil/devil/android/settings.py index 2249c2a5..427592f2 100644 --- a/catapult/devil/devil/android/settings.py +++ b/catapult/devil/devil/android/settings.py @@ -4,6 +4,8 @@ import logging +logger = logging.getLogger(__name__) + _LOCK_SCREEN_SETTINGS_PATH = '/data/system/locksettings.db' _ALTERNATE_LOCK_SCREEN_SETTINGS_PATH = ( '/data/data/com.android.providers.settings/databases/settings.db') @@ -205,9 +207,9 @@ def ConfigureContentSettings(device, desired_settings): settings = ContentSettings(table, device) for key, value in key_value: settings[key] = value - logging.info('\n%s %s', table, (80 - len(table)) * '-') + logger.info('\n%s %s', table, (80 - len(table)) * '-') for key, value in sorted(settings.iteritems()): - logging.info('\t%s: %s', key, value) + logger.info('\t%s: %s', key, value) def SetLockScreenSettings(device): @@ -230,8 +232,8 @@ def SetLockScreenSettings(device): Exception if the setting was not properly set. """ if device.build_type not in _COMPATIBLE_BUILD_TYPES: - logging.warning('Unable to disable lockscreen on %s builds.', - device.build_type) + logger.warning('Unable to disable lockscreen on %s builds.', + device.build_type) return def get_lock_settings(table): @@ -251,7 +253,7 @@ def SetLockScreenSettings(device): columns = ['name', 'value'] generate_values = lambda k, v: [k, v] else: - logging.warning('Unable to find database file to set lock screen settings.') + logger.warning('Unable to find database file to set lock screen settings.') return for table, key, value in locksettings: @@ -271,5 +273,5 @@ commit transaction;""" % { output_msg = device.RunShellCommand('sqlite3 %s "%s"' % (db, cmd), as_root=True) if output_msg: - logging.info(' '.join(output_msg)) + logger.info(' '.join(output_msg)) diff --git a/catapult/devil/devil/android/tools/device_monitor.py b/catapult/devil/devil/android/tools/device_monitor.py new file mode 100755 index 00000000..86a84dd7 --- /dev/null +++ b/catapult/devil/devil/android/tools/device_monitor.py @@ -0,0 +1,206 @@ +#!/usr/bin/env python +# Copyright 2015 The Chromium Authors. All rights reserved. +# Use of this source code is governed by a BSD-style license that can be +# found in the LICENSE file. + +"""Launches a daemon to monitor android device temperatures & status. + +This script will repeatedly poll the given devices for their temperatures and +status every 60 seconds and dump the stats to file on the host. +""" + +import argparse +import collections +import json +import logging +import os +import re +import sys +import time + +if __name__ == '__main__': + sys.path.append( + os.path.abspath(os.path.join(os.path.dirname(__file__), + '..', '..', '..'))) + +from devil import devil_env +from devil.android import battery_utils +from devil.android import device_blacklist +from devil.android import device_errors +from devil.android import device_utils + + +# Various names of sensors used to measure cpu temp +CPU_TEMP_SENSORS = [ + # most nexus devices + 'tsens_tz_sensor0', + # android one + 'mtktscpu', + # nexus 9 + 'CPU-therm', +] + +DEVICE_FILE_VERSION = 1 +DEVICE_FILE = os.path.join(os.path.expanduser('~'), + 'android_device_status.json') + +MEM_INFO_REGEX = re.compile(r'.*?\:\s*(\d+)\s*kB') # ex: 'MemTotal: 185735 kB' + + +def get_device_status(device): + """Polls the given device for various info. + + Returns: A dict of the following format: + { + 'battery': { + 'level': 100, + 'temperature': 123 + }, + 'build': { + 'build.id': 'ABC12D', + 'product.device': 'chickenofthesea' + }, + 'mem': { + 'avail': 1000000, + 'total': 1234567, + }, + 'processes': 123, + 'state': 'good', + 'temp': { + 'some_sensor': 30 + }, + 'uptime': 1234.56, + } + """ + status = collections.defaultdict(dict) + + # Battery + battery = battery_utils.BatteryUtils(device) + battery_info = battery.GetBatteryInfo() + try: + level = int(battery_info.get('level')) + except (KeyError, TypeError, ValueError): + level = None + if level and level >= 0 and level <= 100: + status['battery']['level'] = level + try: + temperature = int(battery_info.get('temperature')) + except (KeyError, TypeError, ValueError): + temperature = None + if temperature: + status['battery']['temperature'] = temperature + + # Build + status['build']['build.id'] = device.build_id + status['build']['product.device'] = device.build_product + + # Memory + mem_info = '' + try: + mem_info = device.ReadFile('/proc/meminfo') + except device_errors.AdbShellCommandFailedError: + logging.exception('Unable to read /proc/meminfo') + for line in mem_info.splitlines(): + match = MEM_INFO_REGEX.match(line) + if match: + try: + value = int(match.group(1)) + except ValueError: + continue + key = line.split(':')[0].strip() + if 'MemTotal' == key: + status['mem']['total'] = value + elif 'MemFree' == key: + status['mem']['free'] = value + + # Process + try: + lines = device.RunShellCommand('ps', check_return=True) + status['processes'] = len(lines) - 1 # Ignore the header row. + except device_errors.AdbShellCommandFailedError: + logging.exception('Unable to count process list.') + + # CPU Temps + # Find a thermal sensor that matches one in CPU_TEMP_SENSORS and read its + # temperature. + files = [] + try: + files = device.RunShellCommand( + 'grep -lE "%s" /sys/class/thermal/thermal_zone*/type' % '|'.join( + CPU_TEMP_SENSORS), check_return=True) + except device_errors.AdbShellCommandFailedError: + logging.exception('Unable to list thermal sensors.') + for f in files: + try: + sensor_name = device.ReadFile(f).strip() + temp = device.ReadFile(f[:-4] + 'temp').strip() # s/type^/temp + status['temp'][sensor_name] = temp + except device_errors.AdbShellCommandFailedError: + logging.exception('Unable to read thermal sensor %s', f) + + # Uptime + try: + uptimes = device.ReadFile('/proc/uptime').split() + status['uptime'] = float(uptimes[0]) # Take the first field (actual uptime) + except (device_errors.AdbShellCommandFailedError, ValueError): + logging.exception('Unable to read /proc/uptime') + + status['state'] = 'available' + return status + + +def get_all_status(blacklist): + status_dict = { + 'version': DEVICE_FILE_VERSION, + 'devices': {}, + } + + healthy_devices = device_utils.DeviceUtils.HealthyDevices(blacklist) + parallel_devices = device_utils.DeviceUtils.parallel(healthy_devices) + results = parallel_devices.pMap(get_device_status).pGet(None) + + status_dict['devices'] = { + device.serial: result for device, result in zip(healthy_devices, results) + } + + if blacklist: + for device, reason in blacklist.Read().iteritems(): + status_dict['devices'][device] = { + 'state': reason.get('reason', 'blacklisted')} + + status_dict['timestamp'] = time.time() + return status_dict + + +def main(argv): + """Launches the device monitor. + + Polls the devices for their battery and cpu temperatures and scans the + blacklist file every 60 seconds and dumps the data to DEVICE_FILE. + """ + + parser = argparse.ArgumentParser( + description='Launches the device monitor.') + parser.add_argument('--adb-path', help='Path to adb binary.') + parser.add_argument('--blacklist-file', help='Path to device blacklist file.') + args = parser.parse_args(argv) + + devil_dynamic_config = devil_env.EmptyConfig() + if args.adb_path: + devil_dynamic_config['dependencies'].update( + devil_env.LocalConfigItem( + 'adb', devil_env.GetPlatform(), args.adb_path)) + + devil_env.config.Initialize(configs=[devil_dynamic_config]) + + blacklist = (device_blacklist.Blacklist(args.blacklist_file) + if args.blacklist_file else None) + while True: + status_dict = get_all_status(blacklist) + with open(DEVICE_FILE, 'wb') as f: + json.dump(status_dict, f, indent=2, sort_keys=True) + time.sleep(60) + + +if __name__ == '__main__': + sys.exit(main(sys.argv[1:])) diff --git a/catapult/devil/devil/android/tools/device_monitor_test.py b/catapult/devil/devil/android/tools/device_monitor_test.py new file mode 100755 index 00000000..7079cf64 --- /dev/null +++ b/catapult/devil/devil/android/tools/device_monitor_test.py @@ -0,0 +1,163 @@ +#!/usr/bin/env python +# Copyright 2015 The Chromium Authors. All rights reserved. +# Use of this source code is governed by a BSD-style license that can be +# found in the LICENSE file. + +import os +import sys +import unittest + +if __name__ == '__main__': + sys.path.append( + os.path.abspath(os.path.join(os.path.dirname(__file__), + '..', '..', '..'))) + +from devil import devil_env +from devil.android import device_errors +from devil.android import device_utils +from devil.android.tools import device_monitor + +with devil_env.SysPath(devil_env.PYMOCK_PATH): + import mock # pylint: disable=import-error + + +class DeviceMonitorTest(unittest.TestCase): + + def setUp(self): + self.device = mock.Mock(spec=device_utils.DeviceUtils, + serial='device_cereal', build_id='abc123', build_product='clownfish') + self.file_contents = { + '/proc/meminfo': """ + MemTotal: 1234567 kB + MemFree: 1000000 kB + MemUsed: 234567 kB + """, + '/sys/class/thermal/thermal_zone0/type': 'CPU-therm', + '/sys/class/thermal/thermal_zone0/temp': '30', + '/proc/uptime': '12345 99999', + } + self.device.ReadFile = mock.MagicMock( + side_effect=lambda file_name: self.file_contents[file_name]) + + self.cmd_outputs = { + 'ps': ['headers', 'p1', 'p2', 'p3', 'p4', 'p5'], + 'grep': ['/sys/class/thermal/thermal_zone0/type'], + } + self.device.RunShellCommand = mock.MagicMock( + side_effect=lambda cmd, **kwargs: self.cmd_outputs[cmd.split()[0]]) + + self.battery = mock.Mock() + self.battery.GetBatteryInfo = mock.MagicMock( + return_value={'level': '80', 'temperature': '123'}) + + self.expected_status = { + 'device_cereal': { + 'processes': 5, + 'temp': { + 'CPU-therm': '30' + }, + 'battery': { + 'temperature': 123, + 'level': 80 + }, + 'uptime': 12345.0, + 'mem': { + 'total': 1234567, + 'free': 1000000 + }, + 'build': { + 'build.id': 'abc123', + 'product.device': 'clownfish', + }, + 'state': 'available', + } + } + + @mock.patch('devil.android.battery_utils.BatteryUtils') + @mock.patch('devil.android.device_utils.DeviceUtils.HealthyDevices') + def test_getStats(self, get_devices, get_battery): + get_devices.return_value = [self.device] + get_battery.return_value = self.battery + + status = device_monitor.get_all_status(None) + self.assertEquals(self.expected_status, status['devices']) + + @mock.patch('devil.android.battery_utils.BatteryUtils') + @mock.patch('devil.android.device_utils.DeviceUtils.HealthyDevices') + def test_getStatsNoBattery(self, get_devices, get_battery): + get_devices.return_value = [self.device] + get_battery.return_value = self.battery + broken_battery_info = mock.Mock() + broken_battery_info.GetBatteryInfo = mock.MagicMock( + return_value={'level': '-1', 'temperature': 'not_a_number'}) + get_battery.return_value = broken_battery_info + + # Should be same status dict but without battery stats. + expected_status_no_battery = self.expected_status.copy() + expected_status_no_battery['device_cereal'].pop('battery') + + status = device_monitor.get_all_status(None) + self.assertEquals(expected_status_no_battery, status['devices']) + + @mock.patch('devil.android.battery_utils.BatteryUtils') + @mock.patch('devil.android.device_utils.DeviceUtils.HealthyDevices') + def test_getStatsNoPs(self, get_devices, get_battery): + get_devices.return_value = [self.device] + get_battery.return_value = self.battery + def _throw_on_ps(cmd): + if cmd == 'ps': + raise device_errors.AdbShellCommandFailedError(cmd, None, None) + else: + return [] + self.device.RunShellCommand = mock.MagicMock( + side_effect=lambda cmd, **kwargs: + _throw_on_ps(cmd) + self.cmd_outputs[cmd.split()[0]]) + + # Should be same status dict but without process stats. + expected_status_no_ps = self.expected_status.copy() + expected_status_no_ps['device_cereal'].pop('processes') + + status = device_monitor.get_all_status(None) + self.assertEquals(expected_status_no_ps, status['devices']) + + @mock.patch('devil.android.battery_utils.BatteryUtils') + @mock.patch('devil.android.device_utils.DeviceUtils.HealthyDevices') + def test_getStatsNoSensors(self, get_devices, get_battery): + get_devices.return_value = [self.device] + get_battery.return_value = self.battery + def _throw_on_grep(cmd): + if cmd.startswith('grep'): + raise device_errors.AdbShellCommandFailedError(cmd, None, None) + else: + return [] + self.device.RunShellCommand = mock.MagicMock( + side_effect=lambda cmd, **kwargs: + _throw_on_grep(cmd) + self.cmd_outputs[cmd.split()[0]]) + + # Should be same status dict but without temp stats. + expected_status_no_temp = self.expected_status.copy() + expected_status_no_temp['device_cereal'].pop('temp') + + status = device_monitor.get_all_status(None) + self.assertEquals(expected_status_no_temp, status['devices']) + + @mock.patch('devil.android.battery_utils.BatteryUtils') + @mock.patch('devil.android.device_utils.DeviceUtils.HealthyDevices') + def test_getStatsWithBlacklist(self, get_devices, get_battery): + get_devices.return_value = [self.device] + get_battery.return_value = self.battery + blacklist = mock.Mock() + blacklist.Read = mock.MagicMock( + return_value={'bad_device': {'reason': 'offline'}}) + + # Should be same status dict but with extra blacklisted device. + expected_status = self.expected_status.copy() + expected_status['bad_device'] = {'state': 'offline'} + + status = device_monitor.get_all_status(blacklist) + self.assertEquals(expected_status, status['devices']) + + +if __name__ == '__main__': + sys.exit(unittest.main()) + diff --git a/catapult/devil/devil/android/tools/device_recovery.py b/catapult/devil/devil/android/tools/device_recovery.py index a7844e26..a7d53338 100755 --- a/catapult/devil/devil/android/tools/device_recovery.py +++ b/catapult/devil/devil/android/tools/device_recovery.py @@ -26,6 +26,8 @@ from devil.utils import lsusb from devil.utils import reset_usb # pylint: disable=unused-import from devil.utils import run_tests_helper +logger = logging.getLogger(__name__) + def KillAllAdb(): def get_all_adb(): @@ -39,15 +41,15 @@ def KillAllAdb(): for sig in [signal.SIGTERM, signal.SIGQUIT, signal.SIGKILL]: for p in get_all_adb(): try: - logging.info('kill %d %d (%s [%s])', sig, p.pid, p.name, - ' '.join(p.cmdline)) + logger.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 get_all_adb(): try: - logging.error('Unable to kill %d (%s [%s])', p.pid, p.name, - ' '.join(p.cmdline)) + logger.error('Unable to kill %d (%s [%s])', p.pid, p.name, + ' '.join(p.cmdline)) except (psutil.NoSuchProcess, psutil.AccessDenied): pass @@ -55,7 +57,7 @@ def KillAllAdb(): def RecoverDevice(device, blacklist, should_reboot=lambda device: True): if device_status.IsBlacklisted(device.adb.GetDeviceSerial(), blacklist): - logging.debug('%s is blacklisted, skipping recovery.', str(device)) + logger.debug('%s is blacklisted, skipping recovery.', str(device)) return if should_reboot(device): @@ -63,26 +65,26 @@ def RecoverDevice(device, blacklist, should_reboot=lambda device: True): device.WaitUntilFullyBooted(retries=0) except (device_errors.CommandTimeoutError, device_errors.CommandFailedError): - logging.exception('Failure while waiting for %s. ' - 'Attempting to recover.', str(device)) + logger.exception('Failure while waiting for %s. ' + 'Attempting to recover.', str(device)) try: try: device.Reboot(block=False, timeout=5, retries=0) except device_errors.CommandTimeoutError: - logging.warning('Timed out while attempting to reboot %s normally.' - 'Attempting alternative reboot.', str(device)) + logger.warning('Timed out while attempting to reboot %s normally.' + 'Attempting alternative reboot.', str(device)) # The device drops offline before we can grab the exit code, so # we don't check for status. device.adb.Root() device.adb.Shell('echo b > /proc/sysrq-trigger', expect_status=None, timeout=5, retries=0) except device_errors.CommandFailedError: - logging.exception('Failed to reboot %s.', str(device)) + logger.exception('Failed to reboot %s.', str(device)) if blacklist: blacklist.Extend([device.adb.GetDeviceSerial()], reason='reboot_failure') except device_errors.CommandTimeoutError: - logging.exception('Timed out while rebooting %s.', str(device)) + logger.exception('Timed out while rebooting %s.', str(device)) if blacklist: blacklist.Extend([device.adb.GetDeviceSerial()], reason='reboot_timeout') @@ -91,12 +93,12 @@ def RecoverDevice(device, blacklist, should_reboot=lambda device: True): device.WaitUntilFullyBooted( retries=0, timeout=device.REBOOT_DEFAULT_TIMEOUT) except device_errors.CommandFailedError: - logging.exception('Failure while waiting for %s.', str(device)) + logger.exception('Failure while waiting for %s.', str(device)) if blacklist: blacklist.Extend([device.adb.GetDeviceSerial()], reason='reboot_failure') except device_errors.CommandTimeoutError: - logging.exception('Timed out while waiting for %s.', str(device)) + logger.exception('Timed out while waiting for %s.', str(device)) if blacklist: blacklist.Extend([device.adb.GetDeviceSerial()], reason='reboot_timeout') @@ -124,15 +126,15 @@ def RecoverDevices(devices, blacklist, enable_usb_reset=False): status['serial'] for status in statuses if status['blacklisted'])) - logging.debug('Should restart USB for:') + logger.debug('Should restart USB for:') for d in should_restart_usb: - logging.debug(' %s', d) - logging.debug('Should restart ADB for:') + logger.debug(' %s', d) + logger.debug('Should restart ADB for:') for d in should_restart_adb: - logging.debug(' %s', d) - logging.debug('Should reboot:') + logger.debug(' %s', d) + logger.debug('Should reboot:') for d in should_reboot_device: - logging.debug(' %s', d) + logger.debug(' %s', d) if blacklist: blacklist.Reset() @@ -146,14 +148,14 @@ def RecoverDevices(devices, blacklist, enable_usb_reset=False): if enable_usb_reset: reset_usb.reset_android_usb(serial) else: - logging.warning('USB reset disabled for %s (crbug.com/642914)', - serial) + logger.warning('USB reset disabled for %s (crbug.com/642914)', + serial) except IOError: - logging.exception('Unable to reset USB for %s.', serial) + logger.exception('Unable to reset USB for %s.', serial) if blacklist: blacklist.Extend([serial], reason='USB failure') except device_errors.DeviceUnreachableError: - logging.exception('Unable to reset USB for %s.', serial) + logger.exception('Unable to reset USB for %s.', serial) if blacklist: blacklist.Extend([serial], reason='offline') diff --git a/catapult/devil/devil/android/tools/device_status.py b/catapult/devil/devil/android/tools/device_status.py index dbfccb6e..167d66c4 100755 --- a/catapult/devil/devil/android/tools/device_status.py +++ b/catapult/devil/devil/android/tools/device_status.py @@ -27,6 +27,8 @@ from devil.constants import exit_codes from devil.utils import lsusb from devil.utils import run_tests_helper +logger = logging.getLogger(__name__) + _RE_DEVICE_ID = re.compile(r'Device ID = (\d+)') @@ -42,7 +44,7 @@ def _BatteryStatus(device, blacklist): battery_level = int(battery_info.get('level', 100)) if battery_level < 15: - logging.error('Critically low battery level (%d)', battery_level) + logger.error('Critically low battery level (%d)', battery_level) battery = battery_utils.BatteryUtils(device) if not battery.GetCharging(): battery.SetCharging(True) @@ -50,8 +52,8 @@ def _BatteryStatus(device, blacklist): blacklist.Extend([device.adb.GetDeviceSerial()], reason='low_battery') except device_errors.CommandFailedError: - logging.exception('Failed to get battery information for %s', - str(device)) + logger.exception('Failed to get battery information for %s', + str(device)) return battery_info @@ -65,7 +67,7 @@ def _IMEISlice(device): if m: imei_slice = m.group(1)[-6:] except device_errors.CommandFailedError: - logging.exception('Failed to get IMEI slice for %s', str(device)) + logger.exception('Failed to get IMEI slice for %s', str(device)) return imei_slice @@ -129,7 +131,7 @@ def DeviceStatus(devices, blacklist): if (device.product_name == 'mantaray' and battery_info.get('AC powered', None) != 'true'): - logging.error('Mantaray device not connected to AC power.') + logger.error('Mantaray device not connected to AC power.') device_status.update({ 'ro.build.product': build_product, @@ -142,14 +144,14 @@ def DeviceStatus(devices, blacklist): }) except device_errors.CommandFailedError: - logging.exception('Failure while getting device status for %s.', - str(device)) + logger.exception('Failure while getting device status for %s.', + str(device)) if blacklist: blacklist.Extend([serial], reason='status_check_failure') except device_errors.CommandTimeoutError: - logging.exception('Timeout while getting device status for %s.', - str(device)) + logger.exception('Timeout while getting device status for %s.', + str(device)) if blacklist: blacklist.Extend([serial], reason='status_check_timeout') @@ -169,23 +171,23 @@ def DeviceStatus(devices, blacklist): def _LogStatuses(statuses): # Log the state of all devices. for status in statuses: - logging.info(status['serial']) + logger.info(status['serial']) adb_status = status.get('adb_status') blacklisted = status.get('blacklisted') - logging.info(' USB status: %s', - 'online' if status.get('usb_status') else 'offline') - logging.info(' ADB status: %s', adb_status) - logging.info(' Blacklisted: %s', str(blacklisted)) + logger.info(' USB status: %s', + 'online' if status.get('usb_status') else 'offline') + logger.info(' ADB status: %s', adb_status) + logger.info(' Blacklisted: %s', str(blacklisted)) if adb_status == 'device' and not blacklisted: - logging.info(' Device type: %s', status.get('ro.build.product')) - logging.info(' OS build: %s', status.get('ro.build.id')) - logging.info(' OS build fingerprint: %s', - status.get('ro.build.fingerprint')) - logging.info(' Battery state:') + logger.info(' Device type: %s', status.get('ro.build.product')) + logger.info(' OS build: %s', status.get('ro.build.id')) + logger.info(' OS build fingerprint: %s', + status.get('ro.build.fingerprint')) + logger.info(' Battery state:') for k, v in status.get('battery', {}).iteritems(): - logging.info(' %s: %s', k, v) - logging.info(' IMEI slice: %s', status.get('imei_slice')) - logging.info(' WiFi IP: %s', status.get('wifi_ip')) + logger.info(' %s: %s', k, v) + logger.info(' IMEI slice: %s', status.get('imei_slice')) + logger.info(' WiFi IP: %s', status.get('wifi_ip')) def _WriteBuildbotFile(file_path, statuses): @@ -224,13 +226,13 @@ def GetExpectedDevices(known_devices_files): if os.path.exists(path): expected_devices.update(device_list.GetPersistentDeviceList(path)) else: - logging.warning('Could not find known devices file: %s', path) + logger.warning('Could not find known devices file: %s', path) except IOError: - logging.warning('Problem reading %s, skipping.', path) + logger.warning('Problem reading %s, skipping.', path) - logging.info('Expected devices:') + logger.info('Expected devices:') for device in expected_devices: - logging.info(' %s', device) + logger.info(' %s', device) return expected_devices @@ -303,7 +305,7 @@ def main(): # If all devices failed, or if there are no devices, it's an infra error. if not live_devices: - logging.error('No available devices.') + logger.error('No available devices.') return 0 if live_devices else exit_codes.INFRA diff --git a/catapult/devil/devil/android/tools/flash_device.py b/catapult/devil/devil/android/tools/flash_device.py index 50ed6961..d13c1df7 100755 --- a/catapult/devil/devil/android/tools/flash_device.py +++ b/catapult/devil/devil/android/tools/flash_device.py @@ -18,6 +18,8 @@ from devil.android.tools import script_common from devil.constants import exit_codes from devil.utils import run_tests_helper +logger = logging.getLogger(__name__) + def main(): parser = argparse.ArgumentParser() @@ -35,9 +37,9 @@ def main(): if args.blacklist_file: blacklist = device_blacklist.Blacklist(args.blacklist_file).Read() if blacklist: - logging.critical('Device(s) in blacklist, not flashing devices:') + logger.critical('Device(s) in blacklist, not flashing devices:') for key in blacklist: - logging.critical(' %s', key) + logger.critical(' %s', key) return exit_codes.INFRA flashed_devices = [] @@ -49,18 +51,18 @@ def main(): fastboot.FlashDevice(args.build_path, wipe=args.wipe) flashed_devices.append(device) except Exception: # pylint: disable=broad-except - logging.exception('Device %s failed to flash.', str(device)) + logger.exception('Device %s failed to flash.', str(device)) failed_devices.append(device) devices = script_common.GetDevices(args.devices, args.blacklist_file) device_utils.DeviceUtils.parallel(devices).pMap(flash) if flashed_devices: - logging.info('The following devices were flashed:') - logging.info(' %s', ' '.join(str(d) for d in flashed_devices)) + logger.info('The following devices were flashed:') + logger.info(' %s', ' '.join(str(d) for d in flashed_devices)) if failed_devices: - logging.critical('The following devices failed to flash:') - logging.critical(' %s', ' '.join(str(d) for d in failed_devices)) + logger.critical('The following devices failed to flash:') + logger.critical(' %s', ' '.join(str(d) for d in failed_devices)) return exit_codes.INFRA return 0 diff --git a/catapult/devil/devil/android/tools/provision_devices.py b/catapult/devil/devil/android/tools/provision_devices.py index d9bff5dc..2c4406f0 100755 --- a/catapult/devil/devil/android/tools/provision_devices.py +++ b/catapult/devil/devil/android/tools/provision_devices.py @@ -46,6 +46,8 @@ from devil.constants import exit_codes from devil.utils import run_tests_helper from devil.utils import timeout_retry +logger = logging.getLogger(__name__) + _SYSTEM_WEBVIEW_PATHS = ['/system/app/webview', '/system/app/WebViewGoogle'] _CHROME_PACKAGE_REGEX = re.compile('.*chrom.*') _TOMBSTONE_REGEX = re.compile('tombstone.*') @@ -141,7 +143,7 @@ def ProvisionDevice(device, steps, blacklist, reboot_timeout=None): try: device.WaitUntilFullyBooted(timeout=reboot_timeout, retries=0) except device_errors.CommandTimeoutError: - logging.error('Device did not finish booting. Will try to reboot.') + logger.error('Device did not finish booting. Will try to reboot.') device.Reboot(timeout=reboot_timeout) step.cmd(device) if step.reboot: @@ -149,14 +151,14 @@ def ProvisionDevice(device, steps, blacklist, reboot_timeout=None): device.adb.WaitForDevice() except device_errors.CommandTimeoutError: - logging.exception('Timed out waiting for device %s. Adding to blacklist.', - str(device)) + logger.exception('Timed out waiting for device %s. Adding to blacklist.', + str(device)) if blacklist: blacklist.Extend([str(device)], reason='provision_timeout') except device_errors.CommandFailedError: - logging.exception('Failed to provision device %s. Adding to blacklist.', - str(device)) + logger.exception('Failed to provision device %s. Adding to blacklist.', + str(device)) if blacklist: blacklist.Extend([str(device)], reason='provision_failure') @@ -168,7 +170,7 @@ def Wipe(device, adb_key_files=None): package = "com.google.android.gms" version_name = device.GetApplicationVersion(package) - logging.info("Version name for %s is %s", package, version_name) + logger.info("Version name for %s is %s", package, version_name) else: WipeDevice(device, adb_key_files) @@ -211,8 +213,8 @@ def WipeChromeData(device): device.RunShellCommand('rm -rf %s/*' % device.GetExternalStoragePath(), check_return=True) except device_errors.CommandFailedError: - logging.exception('Possible failure while wiping the device. ' - 'Attempting to continue.') + logger.exception('Possible failure while wiping the device. ' + 'Attempting to continue.') def _UninstallIfMatch(device, pattern, app_to_keep): @@ -268,11 +270,11 @@ def WipeDevice(device, adb_key_files): adb_public_keys = f.readlines() adb_keys_set.update(adb_public_keys) except IOError: - logging.warning('Unable to find adb keys file %s.', adb_key_file) + logger.warning('Unable to find adb keys file %s.', adb_key_file) _WriteAdbKeysFile(device, '\n'.join(adb_keys_set)) except device_errors.CommandFailedError: - logging.exception('Possible failure while wiping the device. ' - 'Attempting to continue.') + logger.exception('Possible failure while wiping the device. ' + 'Attempting to continue.') def _WriteAdbKeysFile(device, adb_keys_string): @@ -291,12 +293,12 @@ def SetProperties(device, enable_java_debug, disable_location, try: device.EnableRoot() except device_errors.CommandFailedError as e: - logging.warning(str(e)) + logger.warning(str(e)) if not device.IsUserBuild(): _ConfigureLocalProperties(device, enable_java_debug) else: - logging.warning('Cannot configure properties in user builds.') + logger.warning('Cannot configure properties in user builds.') settings.ConfigureContentSettings( device, settings.DETERMINISTIC_DEVICE_SETTINGS) if disable_location: @@ -336,7 +338,7 @@ def DisableSystemChrome(device): def RemoveSystemWebView(device): if any(device.PathExists(p) for p in _SYSTEM_WEBVIEW_PATHS): - logging.info('System WebView exists and needs to be removed') + logger.info('System WebView exists and needs to be removed') if device.HasRoot(): # Disabled Marshmallow's Verity security feature if device.build_version_sdk >= version_codes.MARSHMALLOW: @@ -352,9 +354,9 @@ def RemoveSystemWebView(device): check_return=True) device.RunShellCommand(['start'], check_return=True) else: - logging.warning('Cannot remove system webview from a non-rooted device') + logger.warning('Cannot remove system webview from a non-rooted device') else: - logging.info('System WebView already removed') + logger.info('System WebView already removed') @@ -380,7 +382,7 @@ def _ConfigureLocalProperties(device, java_debug=True): ['chmod', '644', device.LOCAL_PROPERTIES_PATH], as_root=True, check_return=True) except device_errors.CommandFailedError: - logging.exception('Failed to configure local properties.') + logger.exception('Failed to configure local properties.') def FinishProvisioning(device): @@ -404,7 +406,7 @@ def WaitForTemperature(device, max_battery_temp): battery = battery_utils.BatteryUtils(device) battery.LetBatteryCoolToTemperature(max_battery_temp) except device_errors.CommandFailedError: - logging.exception('Unable to let battery cool to specified temperature.') + logger.exception('Unable to let battery cool to specified temperature.') def SetDate(device): @@ -431,11 +433,11 @@ def SetDate(device): correct_time = datetime.datetime.strptime(strgmtime, date_format) tdelta = (correct_time - device_time).seconds if tdelta <= 1: - logging.info('Date/time successfully set on %s', device) + logger.info('Date/time successfully set on %s', device) return True else: - logging.error('Date mismatch. Device: %s Correct: %s', - device_time.isoformat(), correct_time.isoformat()) + logger.error('Date mismatch. Device: %s Correct: %s', + device_time.isoformat(), correct_time.isoformat()) return False # Sometimes the date is not set correctly on the devices. Retry on failure. @@ -452,7 +454,7 @@ def SetDate(device): def LogDeviceProperties(device): props = device.RunShellCommand('getprop', check_return=True) for prop in props: - logging.info(' %s', prop) + logger.info(' %s', prop) def CheckExternalStorage(device): @@ -466,7 +468,7 @@ def CheckExternalStorage(device): device.adb, suffix='.sh', dir=device.GetExternalStoragePath()) as f: device.WriteFile(f.name, 'test') except device_errors.CommandFailedError: - logging.info('External storage not writable. Remounting / as RW') + logger.info('External storage not writable. Remounting / as RW') device.RunShellCommand(['mount', '-o', 'remount,rw', '/'], check_return=True, as_root=True) device.EnableRoot() diff --git a/catapult/devil/devil/android/tools/screenshot.py b/catapult/devil/devil/android/tools/screenshot.py index 326bb162..a264c4f3 100755 --- a/catapult/devil/devil/android/tools/screenshot.py +++ b/catapult/devil/devil/android/tools/screenshot.py @@ -16,6 +16,8 @@ if __name__ == '__main__': from devil.android import device_utils from devil.android.tools import script_common +logger = logging.getLogger(__name__) + def main(): # Parse options. diff --git a/catapult/devil/devil/android/tools/video_recorder.py b/catapult/devil/devil/android/tools/video_recorder.py index bcc9a75e..28def21a 100755 --- a/catapult/devil/devil/android/tools/video_recorder.py +++ b/catapult/devil/devil/android/tools/video_recorder.py @@ -22,6 +22,8 @@ from devil.utils import cmd_helper from devil.utils import reraiser_thread from devil.utils import timeout_retry +logger = logging.getLogger(__name__) + class VideoRecorder(object): """Records a screen capture video from an Android Device (KitKat or newer).""" @@ -85,7 +87,7 @@ class VideoRecorder(object): """Stop recording video.""" if not self._device.KillAll('screenrecord', signum=device_signal.SIGINT, quiet=True): - logging.warning('Nothing to kill: screenrecord was not running') + logger.warning('Nothing to kill: screenrecord was not running') self._recorder_thread.join() def Pull(self, host_file=None): diff --git a/catapult/devil/devil/devil_dependencies.json b/catapult/devil/devil/devil_dependencies.json index d16e792b..5c2b8711 100644 --- a/catapult/devil/devil/devil_dependencies.json +++ b/catapult/devil/devil/devil_dependencies.json @@ -2,8 +2,8 @@ "config_type": "BaseConfig", "dependencies": { "aapt": { - "cloud_storage_bucket": "chromium-telemetry", "cloud_storage_base_folder": "binary_dependencies", + "cloud_storage_bucket": "chromium-telemetry", "file_info": { "linux2_x86_64": { "cloud_storage_hash": "16ba3180141a2489d7ec99b39fd6e3434a9a373f", @@ -12,8 +12,8 @@ } }, "adb": { - "cloud_storage_bucket": "chromium-telemetry", "cloud_storage_base_folder": "binary_dependencies", + "cloud_storage_bucket": "chromium-telemetry", "file_info": { "linux2_x86_64": { "cloud_storage_hash": "8bd43e3930f6eec643d5dc64cab9e5bb4ddf4909", @@ -22,8 +22,8 @@ } }, "android_build_tools_libc++": { - "cloud_storage_bucket": "chromium-telemetry", "cloud_storage_base_folder": "binary_dependencies", + "cloud_storage_bucket": "chromium-telemetry", "file_info": { "linux2_x86_64": { "cloud_storage_hash": "91cdce1e3bd81b2ac1fd380013896d0e2cdb40a0", @@ -32,8 +32,8 @@ } }, "chromium_commands": { - "cloud_storage_bucket": "chromium-telemetry", "cloud_storage_base_folder": "binary_dependencies", + "cloud_storage_bucket": "chromium-telemetry", "file_info": { "linux2_x86_64": { "cloud_storage_hash": "4e22f641e4757309510e8d9f933f5aa504574ab6", @@ -42,8 +42,8 @@ } }, "dexdump": { - "cloud_storage_bucket": "chromium-telemetry", "cloud_storage_base_folder": "binary_dependencies", + "cloud_storage_bucket": "chromium-telemetry", "file_info": { "linux2_x86_64": { "cloud_storage_hash": "acfb10f7a868baf9bcf446a2d9f8ed6b5d52c3c6", @@ -52,8 +52,8 @@ } }, "fastboot": { - "cloud_storage_bucket": "chromium-telemetry", "cloud_storage_base_folder": "binary_dependencies", + "cloud_storage_bucket": "chromium-telemetry", "file_info": { "linux2_x86_64": { "cloud_storage_hash": "db9728166f182800eb9d09e9f036d56e105e8235", @@ -62,41 +62,41 @@ } }, "forwarder_device": { - "cloud_storage_bucket": "chromium-telemetry", "cloud_storage_base_folder": "binary_dependencies", + "cloud_storage_bucket": "chromium-telemetry", "file_info": { - "android_armeabi-v7a": { - "cloud_storage_hash": "de54e23327cc04ef7009fe697227617c7eeb1b2e", - "download_path": "../bin/deps/android/armeabi-v7a/bin/forwarder_device" - }, "android_arm64-v8a": { - "cloud_storage_hash": "67b496f6d3ec6371393c2a8f4f403fdb27f5d091", + "cloud_storage_hash": "90cc60cefb497512d95d774045146754c477b433", "download_path": "../bin/deps/android/arm64-v8a/bin/forwarder_device" + }, + "android_armeabi-v7a": { + "cloud_storage_hash": "3a5ade8fbaffea3b0670bffaa845288db5e4d567", + "download_path": "../bin/deps/android/armeabi-v7a/bin/forwarder_device" } } }, "forwarder_host": { - "cloud_storage_bucket": "chromium-telemetry", "cloud_storage_base_folder": "binary_dependencies", + "cloud_storage_bucket": "chromium-telemetry", "file_info": { "linux2_x86_64": { - "cloud_storage_hash": "02a1854adc15cc9e438f4ecfad2af058bd44fa7e", + "cloud_storage_hash": "63653293098d7fe17aa115b147c8d9aa253b0912", "download_path": "../bin/deps/linux2/x86_64/forwarder_host" } } }, "md5sum_device": { - "cloud_storage_bucket": "chromium-telemetry", "cloud_storage_base_folder": "binary_dependencies", + "cloud_storage_bucket": "chromium-telemetry", "file_info": { - "android_armeabi-v7a": { - "cloud_storage_hash": "39fd90af0f8828202b687f7128393759181c5e2e", - "download_path": "../bin/deps/android/armeabi-v7a/bin/md5sum_device" - }, "android_arm64-v8a": { "cloud_storage_hash": "4e7d2dedd9c6321fdc152b06869e09a3c5817904", "download_path": "../bin/deps/andorid/arm64-v8a/bin/md5sum_device" }, + "android_armeabi-v7a": { + "cloud_storage_hash": "39fd90af0f8828202b687f7128393759181c5e2e", + "download_path": "../bin/deps/android/armeabi-v7a/bin/md5sum_device" + }, "android_x86": { "cloud_storage_hash": "d5cf42ab5986a69c31c0177b0df499d6bf708df6", "download_path": "../bin/deps/android/x86/bin/md5sum_device" @@ -104,8 +104,8 @@ } }, "md5sum_host": { - "cloud_storage_bucket": "chromium-telemetry", "cloud_storage_base_folder": "binary_dependencies", + "cloud_storage_bucket": "chromium-telemetry", "file_info": { "linux2_x86_64": { "cloud_storage_hash": "4db5bd5e9bea8880d8bf2caa59d0efb0acc19f74", @@ -114,8 +114,8 @@ } }, "split-select": { - "cloud_storage_bucket": "chromium-telemetry", "cloud_storage_base_folder": "binary_dependencies", + "cloud_storage_bucket": "chromium-telemetry", "file_info": { "linux2_x86_64": { "cloud_storage_hash": "abb9753a8d3efeea4144e328933931729e01571c", @@ -124,4 +124,4 @@ } } } -} +}
\ No newline at end of file diff --git a/catapult/devil/devil/devil_env.py b/catapult/devil/devil/devil_env.py index 6b647666..aa4fe1ee 100644 --- a/catapult/devil/devil/devil_env.py +++ b/catapult/devil/devil/devil_env.py @@ -4,6 +4,7 @@ import contextlib import json +import logging import os import platform import sys @@ -85,6 +86,8 @@ class _Environment(object): def __init__(self): self._dm_init_lock = threading.Lock() self._dm = None + self._logging_init_lock = threading.Lock() + self._logging_initialized = False def Initialize(self, configs=None, config_files=None): """Initialize devil's environment from configuration files. @@ -138,6 +141,32 @@ class _Environment(object): self._dm = dependency_manager.DependencyManager( [dependency_manager.BaseConfig(c) for c in config_files]) + def InitializeLogging(self, log_level, formatter=None, handler=None): + if self._logging_initialized: + return + + with self._logging_init_lock: + if self._logging_initialized: + return + + formatter = formatter or logging.Formatter( + '%(threadName)-4s %(message)s') + handler = handler or logging.StreamHandler(sys.stdout) + handler.setFormatter(formatter) + + devil_logger = logging.getLogger('devil') + devil_logger.setLevel(log_level) + devil_logger.propagate = False + devil_logger.addHandler(handler) + + import py_utils.cloud_storage + lock_logger = py_utils.cloud_storage.logger + lock_logger.setLevel(log_level) + lock_logger.propagate = False + lock_logger.addHandler(handler) + + self._logging_initialized = True + def FetchPath(self, dependency, arch=None, device=None): if self._dm is None: self.Initialize() @@ -150,9 +179,13 @@ class _Environment(object): self.Initialize() return self._dm.LocalPath(dependency, GetPlatform(arch, device)) + def PrefetchPaths(self, dependencies=None, arch=None, device=None): + return self._dm.PrefetchPaths( + GetPlatform(arch, device), dependencies=dependencies) + def GetPlatform(arch=None, device=None): - if device: + if arch or device: return 'android_%s' % (arch or device.product_cpu_abi) return '%s_%s' % (sys.platform, platform.machine()) diff --git a/catapult/devil/devil/utils/battor_device_mapping.py b/catapult/devil/devil/utils/battor_device_mapping.py index 5624036c..8cabb830 100755 --- a/catapult/devil/devil/utils/battor_device_mapping.py +++ b/catapult/devil/devil/utils/battor_device_mapping.py @@ -61,7 +61,7 @@ If the user wanted to specify a custom mapping, the user could instead create the JSON file manually. (In this case, hubs would not be necessary and the physical ports connected would be irrelevant.) -Step (2) is conducted through the function GetBattorPathFromPhoneSerial, +Step (2) is conducted through the function GetBattOrPathFromPhoneSerial, which takes a serial number mapping generated via step (1) and a phone serial number, then gets the corresponding BattOr serial number from the map and determines its BattOr path (e.g. /dev/ttyUSB0). Since BattOr paths @@ -70,7 +70,7 @@ or disconnected via the same port) this function should be called to determine the BattOr path every time before connecting to the BattOr. Note that if there is only one BattOr connected to the system, then -GetBattorPathFromPhoneSerial will always return that BattOr and will ignore +GetBattOrPathFromPhoneSerial will always return that BattOr and will ignore the mapping file. Thus, if the user never has more than one BattOr connected to the system, the user will not need to generate mapping files. ''' @@ -84,20 +84,20 @@ from devil.utils import find_usb_devices from devil.utils import usb_hubs -def GetBattorList(device_tree_map): +def GetBattOrList(device_tree_map): return [x for x in find_usb_devices.GetTTYList() - if IsBattor(x, device_tree_map)] + if IsBattOr(x, device_tree_map)] -def IsBattor(tty_string, device_tree_map): +def IsBattOr(tty_string, device_tree_map): (bus, device) = find_usb_devices.GetBusDeviceFromTTY(tty_string) node = device_tree_map[bus].FindDeviceNumber(device) return '0403:6001' in node.desc -def GetBattorSerialNumbers(device_tree_map): +def GetBattOrSerialNumbers(device_tree_map): for x in find_usb_devices.GetTTYList(): - if IsBattor(x, device_tree_map): + if IsBattOr(x, device_tree_map): (bus, device) = find_usb_devices.GetBusDeviceFromTTY(x) devnode = device_tree_map[bus].FindDeviceNumber(device) yield devnode.serial @@ -169,7 +169,7 @@ def GenerateSerialMap(hub_types=None): devtree = find_usb_devices.GetBusNumberToDeviceTreeMap() # List of serial numbers in the system that represent BattOrs. - battor_serials = list(GetBattorSerialNumbers(devtree)) + battor_serials = list(GetBattOrSerialNumbers(devtree)) # If there's only one BattOr in the system, then a serial number ma # is not necessary. @@ -198,12 +198,12 @@ def GenerateSerialMap(hub_types=None): for (port, serial) in hub.iteritems(): if serial in battor_serials: if port_to_devices[port].battor is not None: - raise battor_error.BattorError('Multiple BattOrs on same port number') + raise battor_error.BattOrError('Multiple BattOrs on same port number') else: port_to_devices[port].battor = serial else: if port_to_devices[port].phone is not None: - raise battor_error.BattorError('Multiple phones on same port number') + raise battor_error.BattOrError('Multiple phones on same port number') else: port_to_devices[port].phone = serial @@ -214,7 +214,7 @@ def GenerateSerialMap(hub_types=None): if pair.phone is None: continue if pair.battor is None: - raise battor_error.BattorError( + raise battor_error.BattOrError( 'Phone detected with no corresponding BattOr') result[pair.phone] = pair.battor return result @@ -228,7 +228,7 @@ def _PhoneToPathMap(serial, serial_map, devtree): try: battor_serial = serial_map[serial] except KeyError: - raise battor_error.BattorError('Serial number not found in serial map.') + raise battor_error.BattOrError('Serial number not found in serial map.') for tree in devtree.values(): for node in tree.AllNodes(): if isinstance(node, find_usb_devices.USBDeviceNode): @@ -238,12 +238,12 @@ def _PhoneToPathMap(serial, serial_map, devtree): try: return bus_device_to_tty[bus_device] except KeyError: - raise battor_error.BattorError( + raise battor_error.BattOrError( 'Device with given serial number not a BattOr ' '(does not have TTY path)') -def GetBattorPathFromPhoneSerial(serial, serial_map=None, +def GetBattOrPathFromPhoneSerial(serial, serial_map=None, serial_map_file=None): """Gets the TTY path (e.g. '/dev/ttyUSB0') to communicate with the BattOr. @@ -273,17 +273,17 @@ def GetBattorPathFromPhoneSerial(serial, serial_map=None, Raises: ValueError: If serial number is not given. - BattorError: If BattOr not found or unexpected USB topology. + BattOrError: If BattOr not found or unexpected USB topology. """ # If there's only one BattOr connected to the system, just use that one. # This allows for use on, e.g., a developer's workstation with no hubs. devtree = find_usb_devices.GetBusNumberToDeviceTreeMap() - all_battors = GetBattorList(devtree) + all_battors = GetBattOrList(devtree) if len(all_battors) == 1: return '/dev/' + all_battors[0] if not serial: - raise battor_error.BattorError( + raise battor_error.BattOrError( 'Two or more BattOrs connected, no serial provided') if serial_map and serial_map_file: @@ -295,13 +295,13 @@ def GetBattorPathFromPhoneSerial(serial, serial_map=None, tty_string = _PhoneToPathMap(serial, serial_map, devtree) if not tty_string: - raise battor_error.BattorError( + raise battor_error.BattOrError( 'No device with given serial number detected.') - if IsBattor(tty_string, devtree): + if IsBattOr(tty_string, devtree): return '/dev/' + tty_string else: - raise battor_error.BattorError( + raise battor_error.BattOrError( 'Device with given serial number is not a BattOr.') if __name__ == '__main__': diff --git a/catapult/devil/devil/utils/cmd_helper.py b/catapult/devil/devil/utils/cmd_helper.py index c2200522..36fd87be 100644 --- a/catapult/devil/devil/utils/cmd_helper.py +++ b/catapult/devil/devil/utils/cmd_helper.py @@ -20,6 +20,8 @@ try: except ImportError: fcntl = None +logger = logging.getLogger(__name__) + _SafeShellChars = frozenset(string.ascii_letters + string.digits + '@%_-+=:,./') @@ -116,7 +118,7 @@ def RunCmd(args, cwd=None): Returns: Return code from the command execution. """ - logging.info(str(args) + ' ' + (cwd or '')) + logger.info(str(args) + ' ' + (cwd or '')) return Call(args, cwd=cwd) @@ -150,7 +152,7 @@ def _ValidateAndLogCommand(args, cwd, shell): cwd = '' else: cwd = ':' + cwd - logging.info('[host]%s> %s', cwd, args) + logger.info('[host]%s> %s', cwd, args) return args @@ -172,9 +174,9 @@ def GetCmdStatusAndOutput(args, cwd=None, shell=False): args, cwd=cwd, shell=shell) if stderr: - logging.critical('STDERR: %s', stderr) - logging.debug('STDOUT: %s%s', stdout[:4096].rstrip(), - '<truncated>' if len(stdout) > 4096 else '') + logger.critical('STDERR: %s', stderr) + logger.debug('STDOUT: %s%s', stdout[:4096].rstrip(), + '<truncated>' if len(stdout) > 4096 else '') return (status, stdout) @@ -259,6 +261,8 @@ def GetCmdStatusAndOutputWithTimeout(args, timeout, cwd=None, shell=False, Returns: The 2-tuple (exit code, output). + Raises: + TimeoutError on timeout. """ _ValidateAndLogCommand(args, cwd, shell) output = StringIO.StringIO() @@ -273,8 +277,8 @@ def GetCmdStatusAndOutputWithTimeout(args, timeout, cwd=None, shell=False, raise TimeoutError(output.getvalue()) str_output = output.getvalue() - logging.debug('STDOUT+STDERR: %s%s', str_output[:4096].rstrip(), - '<truncated>' if len(str_output) > 4096 else '') + logger.debug('STDOUT+STDERR: %s%s', str_output[:4096].rstrip(), + '<truncated>' if len(str_output) > 4096 else '') return process.returncode, str_output diff --git a/catapult/devil/devil/utils/find_usb_devices_test.py b/catapult/devil/devil/utils/find_usb_devices_test.py index c99e7165..e8b00c85 100755 --- a/catapult/devil/devil/utils/find_usb_devices_test.py +++ b/catapult/devil/devil/utils/find_usb_devices_test.py @@ -82,14 +82,14 @@ T: Bus=02 Lev=00 Prnt=00 Port=00 Cnt=00 Dev#= 11 Spd=000 MxCh=00 T: Bus=02 Lev=00 Prnt=00 Port=01 Cnt=00 Dev#= 20 Spd=000 MxCh=00 T: Bus=02 Lev=00 Prnt=20 Port=00 Cnt=00 Dev#= 21 Spd=000 MxCh=00 -S: SerialNumber=Battor0 +S: SerialNumber=BattOr0 T: Bus=02 Lev=00 Prnt=20 Port=02 Cnt=00 Dev#= 22 Spd=000 MxCh=00 -S: SerialNumber=Battor1 +S: SerialNumber=BattOr1 T: Bus=02 Lev=00 Prnt=20 Port=03 Cnt=00 Dev#= 23 Spd=000 MxCh=00 T: Bus=02 Lev=00 Prnt=23 Port=01 Cnt=00 Dev#= 24 Spd=000 MxCh=00 -S: SerialNumber=Battor2 +S: SerialNumber=BattOr2 T: Bus=02 Lev=00 Prnt=23 Port=03 Cnt=00 Dev#= 25 Spd=000 MxCh=00 -S: SerialNumber=Battor3 +S: SerialNumber=BattOr3 T: Bus=02 Lev=00 Prnt=23 Port=02 Cnt=00 Dev#= 26 Spd=000 MxCh=00 T: Bus=02 Lev=00 Prnt=00 Port=02 Cnt=00 Dev#=100 Spd=000 MxCh=00 @@ -213,14 +213,14 @@ class USBScriptTest(unittest.TestCase): lsusb.raw_lsusb = mock.Mock( return_value=RAW_LSUSB_OUTPUT) - def testIsBattor(self): + def testIsBattOr(self): bd = find_usb_devices.GetBusNumberToDeviceTreeMap() - self.assertTrue(battor_device_mapping.IsBattor('ttyUSB3', bd)) - self.assertFalse(battor_device_mapping.IsBattor('ttyUSB5', bd)) + self.assertTrue(battor_device_mapping.IsBattOr('ttyUSB3', bd)) + self.assertFalse(battor_device_mapping.IsBattOr('ttyUSB5', bd)) - def testGetBattors(self): + def testGetBattOrs(self): bd = find_usb_devices.GetBusNumberToDeviceTreeMap() - self.assertEquals(battor_device_mapping.GetBattorList(bd), + self.assertEquals(battor_device_mapping.GetBattOrList(bd), ['ttyUSB0', 'ttyUSB1', 'ttyUSB2', 'ttyUSB3', 'ttyUSB4']) @@ -247,10 +247,10 @@ class USBScriptTest(unittest.TestCase): def testGetSerialMapping(self): pp = find_usb_devices.GetAllPhysicalPortToSerialMaps([TEST_HUB]) result = list(pp) - self.assertEquals(result[0], {7:'Battor0', - 5:'Battor1', - 3:'Battor2', - 1:'Battor3'}) + self.assertEquals(result[0], {7:'BattOr0', + 5:'BattOr1', + 3:'BattOr2', + 1:'BattOr3'}) self.assertEquals(result[1], {}) def testFastDeviceDescriptions(self): @@ -289,31 +289,31 @@ class USBScriptTest(unittest.TestCase): dev_battor_p7_h1_t0 = bd[2].FindDeviceNumber(21) self.assertEquals(dev_foo.serial, 'FooSerial') self.assertEquals(dev_bar.serial, 'BarSerial') - self.assertEquals(dev_battor_p7_h1_t0.serial, 'Battor0') + self.assertEquals(dev_battor_p7_h1_t0.serial, 'BattOr0') - def testBattorDictMapping(self): - map_dict = {'Phone1':'Battor1', 'Phone2':'Battor2', 'Phone3':'Battor3'} - a1 = battor_device_mapping.GetBattorPathFromPhoneSerial( + def testBattOrDictMapping(self): + map_dict = {'Phone1':'BattOr1', 'Phone2':'BattOr2', 'Phone3':'BattOr3'} + a1 = battor_device_mapping.GetBattOrPathFromPhoneSerial( 'Phone1', serial_map=map_dict) - a2 = battor_device_mapping.GetBattorPathFromPhoneSerial( + a2 = battor_device_mapping.GetBattOrPathFromPhoneSerial( 'Phone2', serial_map=map_dict) - a3 = battor_device_mapping.GetBattorPathFromPhoneSerial( + a3 = battor_device_mapping.GetBattOrPathFromPhoneSerial( 'Phone3', serial_map=map_dict) self.assertEquals(a1, '/dev/ttyUSB1') self.assertEquals(a2, '/dev/ttyUSB2') self.assertEquals(a3, '/dev/ttyUSB3') - def testBattorDictFromFileMapping(self): + def testBattOrDictFromFileMapping(self): try: - map_dict = {'Phone1':'Battor1', 'Phone2':'Battor2', 'Phone3':'Battor3'} + map_dict = {'Phone1':'BattOr1', 'Phone2':'BattOr2', 'Phone3':'BattOr3'} curr_dir = os.path.dirname(os.path.realpath(__file__)) filename = os.path.join(curr_dir, 'test', 'data', 'test_write_map.json') battor_device_mapping.WriteSerialMapFile(filename, map_dict) - a1 = battor_device_mapping.GetBattorPathFromPhoneSerial( + a1 = battor_device_mapping.GetBattOrPathFromPhoneSerial( 'Phone1', serial_map_file=filename) - a2 = battor_device_mapping.GetBattorPathFromPhoneSerial( + a2 = battor_device_mapping.GetBattOrPathFromPhoneSerial( 'Phone2', serial_map_file=filename) - a3 = battor_device_mapping.GetBattorPathFromPhoneSerial( + a3 = battor_device_mapping.GetBattOrPathFromPhoneSerial( 'Phone3', serial_map_file=filename) finally: os.remove(filename) @@ -326,16 +326,16 @@ class USBScriptTest(unittest.TestCase): map_dict = battor_device_mapping.ReadSerialMapFile( os.path.join(curr_dir, 'test', 'data', 'test_serial_map.json')) self.assertEquals(len(map_dict.keys()), 3) - self.assertEquals(map_dict['Phone1'], 'Battor1') - self.assertEquals(map_dict['Phone2'], 'Battor2') - self.assertEquals(map_dict['Phone3'], 'Battor3') + self.assertEquals(map_dict['Phone1'], 'BattOr1') + self.assertEquals(map_dict['Phone2'], 'BattOr2') + self.assertEquals(map_dict['Phone3'], 'BattOr3') original_PPTSM = find_usb_devices.GetAllPhysicalPortToSerialMaps original_PPTTM = find_usb_devices.GetAllPhysicalPortToTTYMaps -original_GBL = battor_device_mapping.GetBattorList +original_GBL = battor_device_mapping.GetBattOrList original_GBNDM = find_usb_devices.GetBusNumberToDeviceTreeMap -original_IB = battor_device_mapping.IsBattor -original_GBSM = battor_device_mapping.GetBattorSerialNumbers +original_IB = battor_device_mapping.IsBattOr +original_GBSM = battor_device_mapping.GetBattOrSerialNumbers def setup_battor_test(serial, tty, battor, bser=None): serial_mapper = mock.Mock(return_value=serial) @@ -346,19 +346,19 @@ def setup_battor_test(serial, tty, battor, bser=None): battor_serials = mock.Mock(return_value=bser) find_usb_devices.GetAllPhysicalPortToSerialMaps = serial_mapper find_usb_devices.GetAllPhysicalPortToTTYMaps = tty_mapper - battor_device_mapping.GetBattorList = battor_lister + battor_device_mapping.GetBattOrList = battor_lister find_usb_devices.GetBusNumberToDeviceTreeMap = devtree - battor_device_mapping.IsBattor = is_battor - battor_device_mapping.GetBattorSerialNumbers = battor_serials + battor_device_mapping.IsBattOr = is_battor + battor_device_mapping.GetBattOrSerialNumbers = battor_serials -class BattorMappingTest(unittest.TestCase): +class BattOrMappingTest(unittest.TestCase): def tearDown(self): find_usb_devices.GetAllPhysicalPortToSerialMaps = original_PPTSM find_usb_devices.GetAllPhysicalPortToTTYMaps = original_PPTTM - battor_device_mapping.GetBattorList = original_GBL + battor_device_mapping.GetBattOrList = original_GBL find_usb_devices.GetBusNumberToDeviceTreeMap = original_GBNDM - battor_device_mapping.IsBattor = original_IB - battor_device_mapping.GetBattorSerialNumbers = original_GBSM + battor_device_mapping.IsBattOr = original_IB + battor_device_mapping.GetBattOrSerialNumbers = original_GBSM def test_generate_serial_map(self): setup_battor_test([{1:'Phn1', 2:'Phn2', 3:'Phn3'}, diff --git a/catapult/devil/devil/utils/lsusb.py b/catapult/devil/devil/utils/lsusb.py index d6306dfd..6cbf2567 100644 --- a/catapult/devil/devil/utils/lsusb.py +++ b/catapult/devil/devil/utils/lsusb.py @@ -7,6 +7,8 @@ import re from devil.utils import cmd_helper +logger = logging.getLogger(__name__) + _COULDNT_OPEN_ERROR_RE = re.compile(r'Couldn\'t open device.*') _INDENTATION_RE = re.compile(r'^( *)') _LSUSB_BUS_DEVICE_RE = re.compile(r'^Bus (\d{3}) Device (\d{3}): (.*)') @@ -22,7 +24,56 @@ def _lsusbv_on_device(bus_id, dev_id): device = {'bus': bus_id, 'device': dev_id} depth_stack = [device] - # TODO(jbudorick): Add documentation for parsing. + # This builds a nested dict -- a tree, basically -- that corresponds + # to the lsusb output. It looks first for a line containing + # + # "Bus <bus number> Device <device number>: ..." + # + # and uses that to create the root node. It then parses all remaining + # lines as a tree, with the indentation level determining the + # depth of the new node. + # + # This expects two kinds of lines: + # - "groups", which take the form + # "<Group name>:" + # and typically have children, and + # - "entries", which take the form + # "<entry name> <entry value> <possible entry description>" + # and typically do not have children (but can). + # + # This maintains a stack containing all current ancestor nodes in + # order to add new nodes to the proper place in the tree. + # The stack is added to when a new node is parsed. Nodes are removed + # from the stack when they are either at the same indentation level as + # or a deeper indentation level than the current line. + # + # e.g. the following lsusb output: + # + # Bus 123 Device 456: School bus + # Device Descriptor: + # bDeviceClass 5 Actual School Bus + # Configuration Descriptor: + # bLength 20 Rows + # + # would produce the following dict: + # + # { + # 'bus': 123, + # 'device': 456, + # 'desc': 'School bus', + # 'Device Descriptor': { + # 'bDeviceClass': { + # '_value': '5', + # '_desc': 'Actual School Bus', + # }, + # 'Configuration Descriptor': { + # 'bLength': { + # '_value': '20', + # '_desc': 'Rows', + # }, + # }, + # } + # } for line in raw_output.splitlines(): # Ignore blank lines. if not line: @@ -34,24 +85,29 @@ def _lsusbv_on_device(bus_id, dev_id): m = _LSUSB_BUS_DEVICE_RE.match(line) if m: if m.group(1) != bus_id: - logging.warning( + logger.warning( 'Expected bus_id value: %r, seen %r', bus_id, m.group(1)) if m.group(2) != dev_id: - logging.warning( + logger.warning( 'Expected dev_id value: %r, seen %r', dev_id, m.group(2)) device['desc'] = m.group(3) continue + # Skip any lines that aren't indented, as they're not part of the + # device descriptor. indent_match = _INDENTATION_RE.match(line) if not indent_match: continue + # Determine the indentation depth. depth = 1 + len(indent_match.group(1)) / 2 if depth > len(depth_stack): - logging.error( + logger.error( 'lsusb parsing error: unexpected indentation: "%s"', line) continue + # Pop everything off the depth stack that isn't a parent of + # this element. while depth < len(depth_stack): depth_stack.pop() @@ -74,7 +130,7 @@ def _lsusbv_on_device(bus_id, dev_id): depth_stack.append(new_entry) continue - logging.error('lsusb parsing error: unrecognized line: "%s"', line) + logger.error('lsusb parsing error: unrecognized line: "%s"', line) return device @@ -92,7 +148,7 @@ def lsusb(): devices.append(_lsusbv_on_device(bus_num, dev_num)) except cmd_helper.TimeoutError: # Will be blacklisted if it is in expected device file, but times out. - logging.info('lsusb -v %s:%s timed out.', bus_num, dev_num) + logger.info('lsusb -v %s:%s timed out.', bus_num, dev_num) return devices def raw_lsusb(): @@ -104,6 +160,15 @@ def get_lsusb_serial(device): except KeyError: return None +def _is_android_device(device): + try: + # Hubs are not android devices. + if device['Device Descriptor']['bDeviceClass']['_value'] == '9': + return False + except KeyError: + pass + return get_lsusb_serial(device) is not None + def get_android_devices(): - return [serial for serial in (get_lsusb_serial(d) for d in lsusb()) - if serial] + android_devices = (d for d in lsusb() if _is_android_device(d)) + return [get_lsusb_serial(d) for d in android_devices] diff --git a/catapult/devil/devil/utils/reset_usb.py b/catapult/devil/devil/utils/reset_usb.py index 3f3b30ac..947c8e29 100755 --- a/catapult/devil/devil/utils/reset_usb.py +++ b/catapult/devil/devil/utils/reset_usb.py @@ -13,6 +13,8 @@ from devil.android import device_errors from devil.utils import lsusb from devil.utils import run_tests_helper +logger = logging.getLogger(__name__) + _INDENTATION_RE = re.compile(r'^( *)') _LSUSB_BUS_DEVICE_RE = re.compile(r'^Bus (\d{3}) Device (\d{3}):') _LSUSB_ENTRY_RE = re.compile(r'^ *([^ ]+) +([^ ]+) *([^ ].*)?$') @@ -25,7 +27,7 @@ def reset_usb(bus, device): """Reset the USB device with the given bus and device.""" usb_file_path = '/dev/bus/usb/%03d/%03d' % (bus, device) with open(usb_file_path, 'w') as usb_file: - logging.debug('fcntl.ioctl(%s, %d)', usb_file_path, _USBDEVFS_RESET) + logger.debug('fcntl.ioctl(%s, %d)', usb_file_path, _USBDEVFS_RESET) fcntl.ioctl(usb_file, _USBDEVFS_RESET) @@ -63,13 +65,15 @@ def _reset_all_matching(condition): reset_usb(bus, device) serial = lsusb.get_lsusb_serial(device_info) if serial: - logging.info('Reset USB device (bus: %03d, device: %03d, serial: %s)', + logger.info( + 'Reset USB device (bus: %03d, device: %03d, serial: %s)', bus, device, serial) else: - logging.info('Reset USB device (bus: %03d, device: %03d)', + logger.info( + 'Reset USB device (bus: %03d, device: %03d)', bus, device) except IOError: - logging.error( + logger.error( 'Failed to reset USB device (bus: %03d, device: %03d)', bus, device) diff --git a/catapult/devil/devil/utils/test/data/test_serial_map.json b/catapult/devil/devil/utils/test/data/test_serial_map.json index 452df3f2..f0682816 100644 --- a/catapult/devil/devil/utils/test/data/test_serial_map.json +++ b/catapult/devil/devil/utils/test/data/test_serial_map.json @@ -1 +1 @@ -[{"phone": "Phone1", "battor": "Battor1"}, {"phone": "Phone2", "battor": "Battor2"}, {"phone": "Phone3", "battor": "Battor3"}] +[{"phone": "Phone1", "battor": "BattOr1"}, {"phone": "Phone2", "battor": "BattOr2"}, {"phone": "Phone3", "battor": "BattOr3"}] diff --git a/catapult/devil/devil/utils/timeout_retry.py b/catapult/devil/devil/utils/timeout_retry.py index e4b5ff8c..d2304629 100644 --- a/catapult/devil/devil/utils/timeout_retry.py +++ b/catapult/devil/devil/utils/timeout_retry.py @@ -12,6 +12,8 @@ import time from devil.utils import reraiser_thread from devil.utils import watchdog_timer +logger = logging.getLogger(__name__) + class TimeoutRetryThreadGroup(reraiser_thread.ReraiserThreadGroup): @@ -102,7 +104,7 @@ def WaitFor(condition, wait_period=5, max_tries=None): if timeout_thread_group: # pylint: disable=no-member msg.append('(%.1fs)' % timeout_thread_group.GetElapsedTime()) - logging.info(' '.join(msg)) + logger.info(' '.join(msg)) if result: return result if timeout_thread_group: @@ -156,7 +158,7 @@ def Run(func, timeout, retries, args=None, kwargs=None, desc=None, thread_group.JoinAll(watcher=thread_group.GetWatcher(), timeout=60, error_log_func=error_log_func) if thread_group.IsAlive(): - logging.info('Still working on %s', desc) + logger.info('Still working on %s', desc) else: return thread_group.GetAllReturnValues()[0] except reraiser_thread.TimeoutError as e: diff --git a/catapult/devil/devil/utils/zip_utils.py b/catapult/devil/devil/utils/zip_utils.py index d799463f..eaa6a2df 100644 --- a/catapult/devil/devil/utils/zip_utils.py +++ b/catapult/devil/devil/utils/zip_utils.py @@ -6,6 +6,8 @@ import logging import os import zipfile +logger = logging.getLogger(__name__) + def WriteToZipFile(zip_file, path, arc_path): """Recursively write |path| to |zip_file| as |arc_path|. @@ -18,14 +20,14 @@ def WriteToZipFile(zip_file, path, arc_path): if os.path.isdir(path): for dir_path, _, file_names in os.walk(path): dir_arc_path = os.path.join(arc_path, os.path.relpath(dir_path, path)) - logging.debug('dir: %s -> %s', dir_path, dir_arc_path) + logger.debug('dir: %s -> %s', dir_path, dir_arc_path) zip_file.write(dir_path, dir_arc_path, zipfile.ZIP_STORED) for f in file_names: file_path = os.path.join(dir_path, f) file_arc_path = os.path.join(dir_arc_path, f) - logging.debug('file: %s -> %s', file_path, file_arc_path) + logger.debug('file: %s -> %s', file_path, file_arc_path) zip_file.write(file_path, file_arc_path, zipfile.ZIP_DEFLATED) else: - logging.debug('file: %s -> %s', path, arc_path) + logger.debug('file: %s -> %s', path, arc_path) zip_file.write(path, arc_path, zipfile.ZIP_DEFLATED) |