Refactoring the output of bisect script. Switching from plain printing to a combination of:

tools/auto_bisect/bisect_perf_regression.py

Index: tools/auto_bisect/bisect_perf_regression.py
diff --git a/tools/auto_bisect/bisect_perf_regression.py b/tools/auto_bisect/bisect_perf_regression.py
index 01b4fabc46dcaf47ad6d3d380b40a05d19c3b22d..e529c11c8e483597d767146ffc2befdc7df12310 100755
--- a/tools/auto_bisect/bisect_perf_regression.py
+++ b/tools/auto_bisect/bisect_perf_regression.py
@@ -36,6 +36,7 @@ import copy
 import datetime
 import errno
 import hashlib
+import logging
 import optparse
 import os
 import re
@@ -58,6 +59,7 @@ import request_build
 import source_control
 from telemetry.util import cloud_storage
 
+

[qyearsley, 2014/10/20 18:26:00]

I think this blank line isn't necessary according to the style guide; the style
just says something like "two blank lines between top level functions or
classes".

[RobertoCN, 2014/10/20 21:01:03]

Done.

 # Below is the map of "depot" names to information about each depot. Each depot
 # is a repository, and in the process of bisecting, revision ranges in these
 # repositories may also be bisected.
@@ -344,15 +346,16 @@ def FetchFromCloudStorage(bucket_name, source_path, destination_path):
   target_file = os.path.join(destination_path, os.path.basename(source_path))
   try:
     if cloud_storage.Exists(bucket_name, source_path):
-      print 'Fetching file from gs//%s/%s ...' % (bucket_name, source_path)
+      logging.info('Fetching file from gs//%s/%s ...',
+                   bucket_name, source_path)
       cloud_storage.Get(bucket_name, source_path, destination_path)
       if os.path.exists(target_file):
         return target_file
     else:
-      print ('File gs://%s/%s not found in cloud storage.' % (
-          bucket_name, source_path))
+      logging.info('File gs://%s/%s not found in cloud storage.',
+                    bucket_name, source_path)
   except Exception as e:
-    print 'Something went wrong while fetching file from cloud: %s' % e
+    logging.warn('Something went wrong while fetching file from cloud: %s', e)
     if os.path.exists(target_file):
       os.remove(target_file)
   return None
@@ -409,7 +412,7 @@ def ExtractZip(filename, output_dir, verbose=True):
     zf = zipfile.ZipFile(filename)
     for name in zf.namelist():
       if verbose:
-        print 'Extracting %s' % name
+        logging.info('Extracting %s', name)
       zf.extract(name, output_dir)
       if bisect_utils.IsMacHost():
         # Restore permission bits.
@@ -523,7 +526,7 @@ def _WaitUntilBuildIsReady(
     if elapsed_time > max_timeout:
       return (None, 'Timed out: %ss without build' % max_timeout)
 
-    print 'Time elapsed: %ss without build.' % elapsed_time
+    logging.info('Time elapsed: %ss without build.', elapsed_time)
     time.sleep(poll_interval)
     # For some reason, mac bisect bots were not flushing stdout periodically.
     # As a result buildbot command is timed-out. Flush stdout on all platforms
@@ -594,14 +597,14 @@ def _UpdateDEPSForAngle(revision, depot, deps_file):
           r'(?<=angle\.git@)([a-fA-F0-9]{40})(?=")', re.MULTILINE)
       match = re.search(angle_rev_pattern, deps_contents)
       if not match:
-        print 'Could not find angle revision information in DEPS file.'
+        logging.info('Could not find angle revision information in DEPS file.')
         return False
       new_data = re.sub(angle_rev_pattern, revision, deps_contents)
     # Write changes to DEPS file
     WriteStringToFile(new_data, deps_file)
     return True
   except IOError, e:
-    print 'Something went wrong while updating DEPS file, %s' % e
+    logging.warn('Something went wrong while updating DEPS file, %s', e)
   return False
 
 
@@ -940,8 +943,8 @@ def _BuilderTryjob(git_revision, bot_name, bisect_job_name, patch=None):
     if returncode:
       raise RunGitError('Could not execute tryjob: %s.\n Error: %s' % (
                          'git %s' % ' '.join(try_cmd), output))
-    print ('Try job successfully submitted.\n TryJob Details: %s\n%s' % (
-           'git %s' % ' '.join(try_cmd), output))
+    logging.info('Try job successfully submitted.\n TryJob Details: %s\n%s',
+           'git %s' % ' '.join(try_cmd), output)
   finally:
     # Delete patch file if exists
     try:
@@ -1157,7 +1160,7 @@ class BisectPerformanceMetrics(object):
       results = {}
       for depot_name, depot_revision in parse_results.iteritems():
         depot_revision = depot_revision.strip('@')
-        print depot_name, depot_revision
+        logging.warn(depot_name, depot_revision)
         for current_name, current_data in DEPOT_DEPS_NAME.iteritems():
           if (current_data.has_key('deps_var') and
               current_data['deps_var'] == depot_name):
@@ -1350,12 +1353,12 @@ class BisectPerformanceMetrics(object):
         else:
           raise IOError('Missing extracted folder %s ' % output_dir)
 
-      print 'Moving build from %s to %s' % (
-          output_dir, target_build_output_dir)
+      logging.info('Moving build from %s to %s',
+                   output_dir, target_build_output_dir)
       shutil.move(output_dir, target_build_output_dir)
       return True
     except Exception as e:
-      print 'Something went wrong while extracting archive file: %s' % e
+      logging.info('Something went wrong while extracting archive file: %s', e)
       self.BackupOrRestoreOutputDirectory(restore=True)
       # Cleanup any leftovers from unzipping.
       if os.path.exists(output_dir):
@@ -1420,10 +1423,10 @@ class BisectPerformanceMetrics(object):
           fetch_build, bot_name, self.opts.builder_host,
           self.opts.builder_port, build_request_id, build_timeout)
       if not target_file:
-        print '%s [revision: %s]' % (error_msg, git_revision)
+        logging.warn('%s [revision: %s]', error_msg, git_revision)
     except RunGitError as e:
-      print ('Failed to post builder try job for revision: [%s].\n'
-             'Error: %s' % (git_revision, e))
+      logging.warn('Failed to post builder try job for revision: [%s].\n'
+             'Error: %s', git_revision, e)
 
     return target_file
 
@@ -1457,7 +1460,7 @@ class BisectPerformanceMetrics(object):
       commit_position = source_control.GetCommitPosition(
           git_revision, self.depot_registry.GetDepotDir(depot))
       if not commit_position:
-        print 'Could not determine commit position for %s' % git_revision
+        logging.warn('Could not determine commit position for %s', git_revision)
         return None
       # Update the revision information for the given depot
       new_data = re.sub(deps_revision, str(commit_position), deps_contents)
@@ -1499,7 +1502,7 @@ class BisectPerformanceMetrics(object):
     deps_var = DEPOT_DEPS_NAME[depot]['deps_var']
     # Don't update DEPS file if deps_var is not set in DEPOT_DEPS_NAME.
     if not deps_var:
-      print 'DEPS update not supported for Depot: %s', depot
+      logging.warn('DEPS update not supported for Depot: %s', depot)
       return False
 
     # Hack for Angle repository. In the DEPS file, "vars" dictionary variable
@@ -1519,7 +1522,7 @@ class BisectPerformanceMetrics(object):
         WriteStringToFile(updated_deps_content, deps_file)
         return True
     except IOError, e:
-      print 'Something went wrong while updating DEPS file. [%s]' % e
+      logging.warn('Something went wrong while updating DEPS file. [%s]', e)
     return False
 
   def CreateDEPSPatch(self, depot, revision):
@@ -2473,7 +2476,7 @@ class BisectPerformanceMetrics(object):
                            'the given \'good\' - \'bad\' range of revisions '
                            'represent an improvement (and not a regression).')
           return results
-        print message, "Therefore we continue to bisect."
+        logging.info(message + "Therefore we continue to bisect.")
 
       # Check how likely it is that the good and bad results are different
       # beyond chance-induced variation.
@@ -3195,8 +3198,8 @@ class BisectOptions(object):
                              '--builder_port when gs_bucket is used.')
       if opts.target_platform == 'cros':
         # Run sudo up front to make sure credentials are cached for later.
-        print 'Sudo is required to build cros:'
-        print
+        logging.info('Sudo is required to build cros:')
+        logging.info('')

[qyearsley, 2014/10/20 18:26:00]

This one I'm not really sure about, maybe it should be a print. Here, we're
expecting that the user is running the bisect script locally and they set
target_platform to "cros". We're expecting this message to be printed to the
console, followed by the sudo password prompt.

Note: In the past year, virtually nobody has done this. Everything CrOS related
is basically untested.

[RobertoCN, 2014/10/20 21:01:03]

Done.

         bisect_utils.RunProcess(['sudo', 'true'])
 
         if not opts.cros_board:
@@ -3258,8 +3261,19 @@ class BisectOptions(object):
     return opts
 
 
-def main():
+def _ConfigureLogging():
+  """Trivial logging config.
+
+  Configures logging to output any messages at or above INFO to standard out,
+  without any additional formatting.
+  """
+  loggingFormat = '%(message)s'

[qyearsley, 2014/10/20 18:26:00]

"logging_format" is probably better here, even though camelCase is used inside
the logging module.

[RobertoCN, 2014/10/20 21:01:03]

Done.

+  logging.basicConfig(
+      stream=logging.sys.stdout, level=logging.INFO, format=loggingFormat)
+
 
+def main():
+  _ConfigureLogging()
   try:
     opts = BisectOptions()
     opts.ParseCommandLine()
@@ -3310,7 +3324,7 @@ def main():
       # The perf dashboard scrapes the "results" step in order to comment on
       # bugs. If you change this, please update the perf dashboard as well.
       bisect_utils.OutputAnnotationStepStart('Results')
-    print 'Error: %s' % e.message
+    logging.warn('Error: %s', e.message)

[qyearsley, 2014/10/20 18:26:00]

We definitely want to make sure that this gets printed to stdout, because what's
printed here is part of the Results.

(RuntimeError is thrown for fatal errors, and whenever it's thrown, we skip to
the Results step and print an error message.)

[RobertoCN, 2014/10/20 21:01:03]

How about we print it and also log it?
Also how is this instead of using the % op?
  print 'Error: ', e.message

[qyearsley, 2014/10/21 21:51:27]

Printing as well as logging would probably be fine, although we want to be sure
that only one copy goes to stdout and thus into the Results step text.

     if opts.output_buildbot_annotations:
       bisect_utils.OutputAnnotationStepClosed()
   return 1