From 6581cc7d40b18f1b207a0ced1483058005a49460 Mon Sep 17 00:00:00 2001 From: "frankf@chromium.org" Date: Wed, 10 Apr 2013 22:38:59 +0000 Subject: [PATCH] [Android] Reduce test logging verbosity to INFO on buildbots. Also, the output of host commands are now at DEBUG level. BUG=160320 Review URL: https://codereview.chromium.org/13799010 git-svn-id: http://src.chromium.org/svn/trunk/src/build@193479 4ff67af0-8c30-449e-8e8b-ad334ec8d88c --- android/buildbot/bb_device_steps.py | 4 ++-- android/pylib/android_commands.py | 25 +++++++++++++++++++------ android/pylib/base/shard.py | 12 ++++++------ android/pylib/cmd_helper.py | 20 ++++++++++++++++++-- android/pylib/flag_changer.py | 3 ++- android/pylib/gtest/test_package_apk.py | 3 ++- android/pylib/utils/report_results.py | 8 ++++++-- 7 files changed, 55 insertions(+), 20 deletions(-) diff --git a/android/buildbot/bb_device_steps.py b/android/buildbot/bb_device_steps.py index 04d49c2b1..c77782cea 100755 --- a/android/buildbot/bb_device_steps.py +++ b/android/buildbot/bb_device_steps.py @@ -188,8 +188,8 @@ def RunInstrumentationSuite(options, test): buildbot_report.PrintNamedStep('%s_instrumentation_tests' % test.name.lower()) InstallApk(options, test) - args = ['--test-apk', test.test_apk, '--test_data', test.test_data, '-vvv', - '-I'] + args = ['--test-apk', test.test_apk, '--test_data', test.test_data, + '--verbose', '-I'] if options.target == 'Release': args.append('--release') if options.asan: diff --git a/android/pylib/android_commands.py b/android/pylib/android_commands.py index f370efee1..1d80642d6 100644 --- a/android/pylib/android_commands.py +++ b/android/pylib/android_commands.py @@ -109,9 +109,11 @@ def GetAttachedDevices(): devices.insert(0, preferred_device) return devices + def IsDeviceAttached(device): return device in GetAttachedDevices() + def _GetFilesFromRecursiveLsOutput(path, ls_output, re_file, utc_offset=None): """Gets a list of files from `ls` command output. @@ -164,10 +166,12 @@ def _GetFilesFromRecursiveLsOutput(path, ls_output, re_file, utc_offset=None): files[filename] = (int(file_match.group('size')), lastmod) return files + def _ComputeFileListHash(md5sum_output): """Returns a list of MD5 strings from the provided md5sum output.""" return [line.split(' ')[0] for line in md5sum_output] + def _HasAdbPushSucceeded(command_output): """Returns whether adb push has succeeded from the provided output.""" if not command_output: @@ -179,6 +183,7 @@ def _HasAdbPushSucceeded(command_output): return False return True + def GetLogTimestamp(log_line, year): """Returns the timestamp of the given |log_line| in the given year.""" try: @@ -211,6 +216,14 @@ class AndroidCommands(object): self._external_storage = '' self._util_wrapper = '' + def _LogShell(self, cmd): + """Logs the adb shell command.""" + if self._device: + device_repr = self._device[-4:] + else: + device_repr = '????' + logging.info('[%s]> %s', device_repr, cmd) + def Adb(self): """Returns our AdbInterface to avoid us wrapping all its methods.""" return self._adb @@ -317,7 +330,7 @@ class AndroidCommands(object): """ uninstall_command = 'uninstall %s' % package - logging.info('>>> $' + uninstall_command) + self._LogShell(uninstall_command) return self._adb.SendCommand(uninstall_command, timeout_time=60) def Install(self, package_file_path, reinstall=False): @@ -341,7 +354,7 @@ class AndroidCommands(object): install_cmd.append(package_file_path) install_cmd = ' '.join(install_cmd) - logging.info('>>> $' + install_cmd) + self._LogShell(install_cmd) return self._adb.SendCommand(install_cmd, timeout_time=2 * 60, retry_count=0) @@ -472,14 +485,14 @@ class AndroidCommands(object): Returns: list containing the lines of output received from running the command """ - logging.info('>>> $' + command) + self._LogShell(command) if "'" in command: logging.warning(command + " contains ' quotes") result = self._adb.SendShellCommand( "'%s'" % command, timeout_time).splitlines() if ['error: device not found'] == result: raise errors.DeviceUnresponsiveError('device not found') if log_result: - logging.info('\n>>> '.join(result)) + self._LogShell('\n'.join(result)) return result def GetShellCommandStatusAndOutput(self, command, timeout_time=20, @@ -697,7 +710,7 @@ class AndroidCommands(object): # NOTE: We can't use adb_interface.Push() because it hardcodes a timeout of # 60 seconds which isn't sufficient for a lot of users of this method. push_command = 'push %s %s' % (local_path, device_path) - logging.info('>>> $' + push_command) + self._LogShell(push_command) output = self._adb.SendCommand(push_command, timeout_time=30 * 60) assert _HasAdbPushSucceeded(output) @@ -1253,7 +1266,7 @@ class AndroidCommands(object): An instance of am_instrument_parser.TestResult object. """ cmd = 'uiautomator runtest %s -e class %s' % (test_package, test) - logging.info('>>> $' + cmd) + self._LogShell(cmd) output = self._adb.SendShellCommand(cmd, timeout_time=timeout) # uiautomator doesn't fully conform to the instrumenation test runner # convention and doesn't terminate with INSTRUMENTATION_CODE. diff --git a/android/pylib/base/shard.py b/android/pylib/base/shard.py index c9fc838d1..03c72ef91 100644 --- a/android/pylib/base/shard.py +++ b/android/pylib/base/shard.py @@ -143,7 +143,7 @@ def _RunTestsFromQueue(runner, test_collection, out_results, watcher): pass_results = base_test_result.TestRunResults() pass_results.AddResults(result.GetPass()) out_results.append(pass_results) - logging.warning('****Will retry test, try #%s.' % test.tries) + logging.warning('Will retry test, try #%s.' % test.tries) test_collection.add(_Test(test=retry, tries=test.tries)) else: # All tests passed or retry limit reached. Either way, record results. @@ -179,12 +179,12 @@ def _SetUp(runner_factory, device, out_runners, threadsafe_counter): """ try: index = threadsafe_counter.GetAndIncrement() - logging.warning('*****Creating shard %s for device %s.', index, device) + logging.warning('Creating shard %s for device %s.', index, device) runner = runner_factory(device, index) runner.SetUp() out_runners.append(runner) except android_commands.errors.DeviceUnresponsiveError as e: - logging.warning('****Failed to create shard for %s: [%s]', device, e) + logging.warning('Failed to create shard for %s: [%s]', device, e) def _RunAllTests(runners, tests, timeout=None): @@ -198,7 +198,7 @@ def _RunAllTests(runners, tests, timeout=None): Returns: A TestRunResults object. """ - logging.warning('****Running %s tests with %s test runners.' % + logging.warning('Running %s tests with %s test runners.' % (len(tests), len(runners))) tests_collection = _TestCollection([_Test(t) for t in tests]) results = [] @@ -231,7 +231,7 @@ def _CreateRunners(runner_factory, devices, timeout=None): Returns: A list of TestRunner objects. """ - logging.warning('****Creating %s test runners.' % len(devices)) + logging.warning('Creating %s test runners.' % len(devices)) runners = [] counter = _ThreadSafeCounter() threads = reraiser_thread.ReraiserThreadGroup( @@ -284,6 +284,6 @@ def ShardAndRunTests(runner_factory, devices, tests, build_type='Debug', try: _TearDownRunners(runners, setup_timeout) except android_commands.errors.DeviceUnresponsiveError as e: - logging.warning('****Device unresponsive during TearDown: [%s]', e) + logging.warning('Device unresponsive during TearDown: [%s]', e) finally: forwarder.Forwarder.KillHost(build_type) diff --git a/android/pylib/cmd_helper.py b/android/pylib/cmd_helper.py index e9102411a..daa4c71e7 100644 --- a/android/pylib/cmd_helper.py +++ b/android/pylib/cmd_helper.py @@ -6,6 +6,7 @@ import os import logging +import pipes import signal import subprocess import tempfile @@ -67,7 +68,20 @@ def GetCmdStatusAndOutput(args, cwd=None, shell=False): Returns: The tuple (exit code, output). """ - logging.info(str(args) + ' ' + (cwd or '')) + if isinstance(args, basestring): + args_repr = args + if not shell: + raise Exception('string args must be run with shell=True') + elif shell: + raise Exception('array args must be run with shell=False') + else: + args_repr = ' '.join(map(pipes.quote, args)) + + s = '[host]' + if cwd: + s += ':' + cwd + s += '> ' + args_repr + logging.info(s) tmpout = tempfile.TemporaryFile(bufsize=0) tmperr = tempfile.TemporaryFile(bufsize=0) exit_code = _Call(args, cwd=cwd, stdout=tmpout, stderr=tmperr, shell=shell) @@ -79,7 +93,9 @@ def GetCmdStatusAndOutput(args, cwd=None, shell=False): tmpout.seek(0) stdout = tmpout.read() tmpout.close() - logging.info(stdout[:4096]) # Truncate output longer than 4k. + if len(stdout) > 4096: + logging.debug('Truncated output:') + logging.debug(stdout[:4096]) return (exit_code, stdout) diff --git a/android/pylib/flag_changer.py b/android/pylib/flag_changer.py index d497ef6fd..6eb9f0b3c 100644 --- a/android/pylib/flag_changer.py +++ b/android/pylib/flag_changer.py @@ -3,6 +3,7 @@ # found in the LICENSE file. import constants +import logging import traceback import warnings @@ -86,7 +87,7 @@ class FlagChanger(object): def _UpdateCommandLineFile(self): """Writes out the command line to the file, or removes it if empty.""" - print "Current flags: ", self._current_flags + logging.info('Current flags: %s', self._current_flags) if self._current_flags: self._android_cmd.SetProtectedFileContents(CHROME_COMMAND_FILE, diff --git a/android/pylib/gtest/test_package_apk.py b/android/pylib/gtest/test_package_apk.py index f18d87cd4..64e233e76 100644 --- a/android/pylib/gtest/test_package_apk.py +++ b/android/pylib/gtest/test_package_apk.py @@ -3,6 +3,7 @@ # found in the LICENSE file. +import logging import os import shlex import sys @@ -63,7 +64,7 @@ class TestPackageApk(TestPackage): def _WatchFifo(self, timeout, logfile=None): for i in range(10): if self.adb.FileExistsOnDevice(self._GetFifo()): - print 'Fifo created...' + logging.info('Fifo created.') break time.sleep(i) else: diff --git a/android/pylib/utils/report_results.py b/android/pylib/utils/report_results.py index 9ac2620b3..34bae526c 100644 --- a/android/pylib/utils/report_results.py +++ b/android/pylib/utils/report_results.py @@ -88,10 +88,14 @@ def LogFull(results, test_type, test_package, annotation=None, if not results.DidRunPass(): logging.critical('*' * 80) logging.critical('Detailed Logs') - logging.critical('%s\n%s' % ('*' * 80, results.GetLogs())) + logging.critical('*' * 80) + for line in results.GetLogs().splitlines(): + logging.critical(line) logging.critical('*' * 80) logging.critical('Summary') - logging.critical('%s\n%s' % ('*' * 80, results)) + logging.critical('*' * 80) + for line in results.GetLongForm().splitlines(): + logging.critical(line) logging.critical('*' * 80) if os.environ.get('BUILDBOT_BUILDERNAME'):