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 18 matching lines @@
   "out/Release/performance_ui_tests --gtest_filter=ShutdownTest.SimpleUserQuit"\
   -g 1f6e67861535121c5c819c16a666f2436c207e7b\
   -b b732f23b4f81c382db0b23b9035f3dadc7d925bb\
   -m shutdown/simple-user-quit
 """
 
 import copy
 import datetime
 import errno
 import hashlib
+import logging
 import optparse
 import os
 import re
 import shlex
 import shutil
 import StringIO
 import sys
 import time
 import zipfile
 
 sys.path.append(os.path.join(
     os.path.dirname(__file__), os.path.pardir, 'telemetry'))
 
 from bisect_results import BisectResults
 from bisect_results import ConfidenceScore
 import bisect_utils
 import builder
 import math_utils
 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.
 #
 # Each depot information dictionary may contain:
 #   src: Path to the working directory.
 #   recurse: True if this repository will get bisected.
 #   depends: A list of other repositories that are actually part of the same
 #       repository in svn. If the repository has any dependent repositories
 #       (e.g. skia/src needs skia/include and skia/gyp to be updated), then
@@ skipping 266 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 318 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 current_name, current_data in DEPOT_DEPS_NAME.iteritems():
           if (current_data.has_key('deps_var') and
               current_data['deps_var'] == depot_name):
             src_name = current_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 44 matching lines @@
     bot_name, build_timeout = GetBuilderNameAndBuildTime(
        self.opts.target_platform, self.opts.target_arch)
     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
 
   def IsDownloadable(self, depot):
     """Checks if build can be downloaded based on target platform and depot."""
     if (self.opts.target_platform in ['chromium', 'android'] and
         self.opts.gs_bucket):
       return (depot == 'chromium' or
               'chromium' in DEPOT_DEPS_NAME[depot]['from'] or
               'v8' in DEPOT_DEPS_NAME[depot]['from'])
@@ skipping 13 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 = 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 933 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)):
           results.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 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.
       if not self.opts.debug_ignore_regression_confidence:
         regression_confidence = ConfidenceScore(known_bad_value['values'],
                                                 known_good_value['values'])
         if regression_confidence < REGRESSION_CONFIDENCE:
           results.error = ('We could not reproduce the regression with this '
                            'test/metric/platform combination with enough '
                            'confidence. There\'s still a chance that this is '
@@ skipping 701 matching lines @@
         if not cloud_storage.List(opts.gs_bucket):
           raise RuntimeError('Invalid Google Storage: gs://%s' % opts.gs_bucket)
         if not opts.builder_host:
           raise RuntimeError('Must specify try server host name using '
                              '--builder_host when gs_bucket is used.')
         if not opts.builder_port:
           raise RuntimeError('Must specify try server port number using '
                              '--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:
           raise RuntimeError('missing required parameter: --cros_board')
 
         if not opts.cros_remote_ip:
           raise RuntimeError('missing required parameter: --cros_remote_ip')
 
         if not opts.working_directory:
           raise RuntimeError('missing required parameter: --working_directory')
@@ skipping 41 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.
+  """
+  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()
 
     if opts.extra_src:
       extra_src = bisect_utils.LoadExtraSrc(opts.extra_src)
       if not extra_src:
         raise RuntimeError('Invalid or missing --extra_src.')
       _AddAdditionalDepotInfo(extra_src.GetAdditionalDepotInfo())
 
@@ skipping 30 matching lines @@
         raise RuntimeError(bisect_results.error)
       bisect_test.FormatAndPrintResults(bisect_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
+    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
 
 
 if __name__ == '__main__':
   sys.exit(main())