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

tools/auto_bisect/bisect_perf_regression.py

 #!/usr/bin/env python
 # Copyright (c) 2013 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.
 
 """Performance Test Bisect Tool
 
 This script bisects a series of changelists using binary search. It starts at
 a bad revision where a performance metric has regressed, and asks for a last
 known-good revision. It will then binary search across this revision range by
@@ skipping 17 matching lines @@
 ./tools/bisect_perf_regression.py -c\
   "out/Release/performance_ui_tests --gtest_filter=ShutdownTest.SimpleUserQuit"\
   -g 1f6e67861535121c5c819c16a666f2436c207e7b\
   -b b732f23b4f81c382db0b23b9035f3dadc7d925bb\
   -m shutdown/simple-user-quit
 """
 
 import copy
 import errno
 import hashlib
+import logging
 import optparse
 import os
 import re
 import shlex
 import shutil
 import StringIO
 import sys
 import time
 import zipfile
 
@@ skipping 137 matching lines @@
     bucket_name: Google Storage bucket name.
     source_path: Source file path.
     destination_path: Destination file path.
 
   Returns:
     Downloaded file path if exists, otherwise None.
   """
   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
 
 
 # This is copied from build/scripts/common/chromium_utils.py.
 def MaybeMakeDirectory(*path):
   """Creates an entire path, if it doesn't already exist."""
   file_path = os.path.join(*path)
   try:
@@ skipping 36 matching lines @@
     command = unzip_cmd + [filepath]
     result = bisect_utils.RunProcess(command)
     os.chdir(saved_dir)
     if result:
       raise IOError('unzip failed: %s => %s' % (str(command), result))
   else:
     assert bisect_utils.IsWindowsHost() or bisect_utils.IsMacHost()
     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.
         os.chmod(os.path.join(output_dir, name),
                  zf.getinfo(name).external_attr >> 16L)
 
 
 def WriteStringToFile(text, file_name):
   """Writes text to a file, raising an RuntimeError on failure."""
   try:
@@ skipping 93 matching lines @@
       # Note: Build is treated as PENDING if build number is not found
       # on the the try server.
       build_status, status_link = request_build.GetBuildStatus(
           build_num, bot_name, builder_host, builder_port)
       if build_status == request_build.FAILED:
         return (None, 'Failed to produce build, log: %s' % status_link)
     elapsed_time = time.time() - start_time
     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
     # while waiting for build.
     sys.stdout.flush()
 
 
 def _UpdateV8Branch(deps_content):
   """Updates V8 branch in DEPS file to process v8_bleeding_edge.
 
@@ skipping 50 matching lines @@
       new_data = re.sub(angle_rev_pattern, revision, deps_contents)
     else:
       # Check whether the depot and revision pattern in DEPS file deps
       # variable. e.g.,
       # "src/third_party/angle": Var("chromium_git") +
       # "/angle/angle.git@fa63e947cb3eccf463648d21a05d5002c9b8adfa",.
       angle_rev_pattern = re.compile(
           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
 
 
 def _TryParseHistogramValuesFromOutput(metric, text):
   """Attempts to parse a metric in the format HISTOGRAM <graph: <trace>.
 
   Args:
     metric: The metric as a list of [<trace>, <value>] strings.
     text: The text to parse the metric values from.
 
@@ skipping 287 matching lines @@
                '-n', bisect_job_name,
                '--svn_repo=%s' % SVN_REPO_URL,
                '--diff=%s' % patch_content
               ]
     # Execute try job to build revision.
     output, returncode = bisect_utils.RunGit(try_cmd)
 
     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:
       os.remove(BISECT_PATCH_FILE)
     except OSError as e:
       if e.errno != errno.ENOENT:
         raise
     # Checkout master branch and delete bisect-tryjob branch.
     bisect_utils.RunGit(['checkout', '-f', BISECT_MASTER_BRANCH])
     bisect_utils.RunGit(['branch', '-D', BISECT_TRYJOB_BRANCH])
@@ skipping 195 matching lines @@
                 self.warnings.append(warning_text)
           else:
             results[depot_name] = None
       return results
     except ImportError:
       deps_file_contents = ReadStringFromFile(deps_file)
       parse_results = _ParseRevisionsFromDEPSFileManually(deps_file_contents)
       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 cur_name, cur_data in bisect_utils.DEPOT_DEPS_NAME.iteritems():
           if (cur_data.has_key('deps_var') and
               cur_data['deps_var'] == depot_name):
             src_name = cur_name
             results[src_name] = depot_revision
             break
       return results
 
   def _Get3rdPartyRevisions(self, depot):
     """Parses the DEPS file to determine WebKit/v8/etc... versions.
@@ skipping 172 matching lines @@
       target_build_output_dir = os.path.join(abs_build_dir, build_type)
       ExtractZip(downloaded_file, abs_build_dir)
       if not os.path.exists(output_dir):
         # Due to recipe changes, the builds extract folder contains
         # out/Release instead of full-build-<platform>/Release.
         if os.path.exists(os.path.join(abs_build_dir, 'out', build_type)):
           output_dir = os.path.join(abs_build_dir, 'out', build_type)
         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):
         RemoveDirectoryTree(output_dir)
     finally:
       # Delete downloaded archive
       if os.path.exists(downloaded_file):
         os.remove(downloaded_file)
     return False
 
@@ skipping 28 matching lines @@
     bot_name = self._GetBuilderName(self.opts.target_platform)
     build_timeout = self._GetBuilderBuildTime()
     target_file = None
     try:
       # Execute try job request to build revision with patch.
       _BuilderTryjob(git_revision, bot_name, build_request_id, patch)
       target_file, error_msg = _WaitUntilBuildIsReady(
           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
 
   @staticmethod
   def _GetBuilderName(target_platform):
     """Gets builder bot name and build time in seconds based on platform."""
     if bisect_utils.IsWindowsHost():
       return 'win_perf_bisect_builder'
     if bisect_utils.IsLinuxHost():
       if target_platform == 'android':
@@ skipping 37 matching lines @@
     """
     # Check whether the depot and revision pattern in DEPS file vars
     # e.g. for webkit the format is "webkit_revision": "12345".
     deps_revision = re.compile(r'(?<="%s": ")([0-9]+)(?=")' % deps_key,
                                re.MULTILINE)
     new_data = None
     if re.search(deps_revision, deps_contents):
       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)
     else:
       # Check whether the depot and revision pattern in DEPS file vars
       # e.g. for webkit the format is "webkit_revision": "559a6d4ab7a84c539..".
       deps_revision = re.compile(
           r'(?<=["\']%s["\']: ["\'])([a-fA-F0-9]{40})(?=["\'])' % deps_key,
           re.MULTILINE)
       if re.search(deps_revision, deps_contents):
@@ skipping 21 matching lines @@
 
     Returns:
       True if DEPS file is modified successfully, otherwise False.
     """
     if not os.path.exists(deps_file):
       return False
 
     deps_var = bisect_utils.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
     # contains "angle_revision" key that holds git hash instead of SVN revision.
     # And sometime "angle_revision" key is not specified in "vars" variable.
     # In such cases check, "deps" dictionary variable that matches
     # angle.git@[a-fA-F0-9]{40}$ and replace git hash.
     if depot == 'angle':
       return _UpdateDEPSForAngle(revision, depot, deps_file)
 
     try:
       deps_contents = ReadStringFromFile(deps_file)
       updated_deps_content = self.UpdateDepsContents(
           deps_contents, depot, revision, deps_var)
       # Write changes to DEPS file
       if updated_deps_content:
         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):
     """Modifies DEPS and returns diff as text.
 
     Args:
       depot: Current depot being bisected.
       revision: A git hash revision of the dependency repository.
 
     Returns:
@@ skipping 906 matching lines @@
         if metric_increased:
           message += "and the metric appears to have increased. "
         else:
           message += "and the metric appears to have decreased. "
         if ((higher_is_better and metric_increased) or
             (not higher_is_better and not metric_increased)):
           error = (message + 'Then, the test results for the ends of the given '
                    '\'good\' - \'bad\' range of revisions represent an '
                    'improvement (and not a regression).')
           return BisectResults(error=error)
-        print message, "Therefore we continue to bisect."
+        logging.info(message + "Therefore we continue to bisect.")
 
       bisect_state = BisectState(target_depot, revision_list)
       revision_states = bisect_state.GetRevisionStates()
 
       min_revision = 0
       max_revision = len(revision_states) - 1
       # Check how likely it is that the good and bad results are different
       # beyond chance-induced variation.
       if not self.opts.debug_ignore_regression_confidence:
         error = _CheckRegressionConfidenceError(good_revision,
@@ skipping 478 matching lines @@
       opts.metric = metric_values
 
     opts.repeat_test_count = min(max(opts.repeat_test_count, 1), 100)
     opts.max_time_minutes = min(max(opts.max_time_minutes, 1), 60)
     opts.truncate_percent = min(max(opts.truncate_percent, 0), 25)
     opts.truncate_percent = opts.truncate_percent / 100.0
 
     return opts
 
 
+def _ConfigureLogging():
+  """Trivial logging config.
+
+  Configures logging to output any messages at or above INFO to standard out,
+  without any additional formatting.
+  """
+  logging_format = '%(message)s'
+  logging.basicConfig(
+      stream=logging.sys.stdout, level=logging.INFO, format=logging_format)
+
+
 def main():
-
+  _ConfigureLogging()
   try:
     opts = BisectOptions()
     opts.ParseCommandLine()
 
     if opts.extra_src:
       extra_src = bisect_utils.LoadExtraSrc(opts.extra_src)
       if not extra_src:
         raise RuntimeError('Invalid or missing --extra_src.')
       bisect_utils.AddAdditionalDepotInfo(extra_src.GetAdditionalDepotInfo())
 
@@ skipping 29 matching lines @@
         raise RuntimeError(results.error)
       bisect_printer.FormatAndPrintResults(results)
       return 0
     finally:
       bisect_test.PerformCleanup()
   except RuntimeError, e:
     if opts.output_buildbot_annotations:
       # 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
+    print 'Error: ', e.message
+    logging.warn('A RuntimeError was caught: %s', e.message)
     if opts.output_buildbot_annotations:
       bisect_utils.OutputAnnotationStepClosed()
   return 1
 
 
 if __name__ == '__main__':
   sys.exit(main())