[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

@@ -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:

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.

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)

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)
 
 

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,

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:

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'):