Make errors in called processes more evident and easier to debug.

Also trying to get unicode filenames right again.

Change-Id: I501c94921b92b8a8cd6a10441aff1595fc6d878e
Reviewed-on: https://pdfium-review.googlesource.com/10630
Commit-Queue: Henrique Nakashima <hnakashima@chromium.org>
Reviewed-by: Nicolás Peña <npm@chromium.org>
Reviewed-by: Ryan Harrison <rharrison@chromium.org>

6 files changed, 128 insertions, 72 deletions

diff --git a/testing/tools/common.py b/testing/tools/common.py
index 737169f8d3..fc16004210 100755
--- a/testing/tools/common.py
+++ b/testing/tools/common.py
@@ -3,6 +3,7 @@
 # Use of this source code is governed by a BSD-style license that can be
 # found in the LICENSE file.
 
+import datetime
 import glob
 import os
 import re
@@ -26,6 +27,38 @@ def RunCommand(cmd):
   except subprocess.CalledProcessError as e:
     return e
 
+
+def RunCommandPropagateErr(cmd, stdout_has_errors=False,
+                           exit_status_on_error=None):
+  """Run a command as a subprocess.
+
+  Errors in that subprocess are printed out if it returns an error exit code.
+
+  Args:
+    cmd: Command to run as a list of strings.
+    stdout_has_errors: Whether to print stdout instead of stderr on an error
+        exit.
+    exit_status_on_error: If specified, upon an error in the subprocess the
+        caller script exits immediately with the given status.
+  """
+  p = subprocess.Popen(cmd, stdout=subprocess.PIPE, stderr=subprocess.PIPE)
+  output, err = p.communicate()
+
+  if p.returncode:
+    PrintErr('\nError when invoking "%s"' % ' '.join(cmd))
+    if stdout_has_errors:
+      PrintErr(output)
+
+    PrintErr(err)
+
+    if exit_status_on_error is not None:
+      sys.exit(exit_status_on_error)
+
+    return None
+
+  return output
+
+
 # RunCommandExtractHashedFiles returns a tuple: (raised_exception, hashed_files)
 # It runs the given command. If it fails it will return an exception and None.
 # If it succeeds it will return None and the list of processed files extracted
@@ -110,3 +143,14 @@ def GetBooleanGnArg(arg_name, build_dir, verbose=False):
   if verbose:
     print >> sys.stderr, "Found '%s' for value of %s" % (arg_match_output, arg)
   return arg_match_output == 'true'
+
+
+def PrintWithTime(s):
+  """Prints s prepended by a timestamp."""
+  print '[%s] %s' % (datetime.datetime.now().strftime("%Y%m%d %H:%M:%S"),
+                     s)
+
+
+def PrintErr(s):
+  """Prints s to stderr."""
+  print >> sys.stderr, s
diff --git a/testing/tools/githelper.py b/testing/tools/githelper.py
index 021ed4e61e..2e94196e85 100644
--- a/testing/tools/githelper.py
+++ b/testing/tools/githelper.py
@@ -6,6 +6,8 @@
 
 import subprocess
 
+from common import RunCommandPropagateErr
+
 
 class GitHelper(object):
   """Issues git commands. Stateful."""
@@ -15,15 +17,17 @@ class GitHelper(object):
 
   def Checkout(self, branch):
     """Checks out a branch."""
-    subprocess.check_output(['git', 'checkout', branch])
+    RunCommandPropagateErr(['git', 'checkout', branch], exit_status_on_error=1)
 
   def FetchOriginMaster(self):
     """Fetches new changes on origin/master."""
-    subprocess.check_output(['git', 'fetch', 'origin', 'master'])
+    RunCommandPropagateErr(['git', 'fetch', 'origin', 'master'],
+                           exit_status_on_error=1)
 
   def StashPush(self):
     """Stashes uncommitted changes."""
-    output = subprocess.check_output(['git', 'stash', '--include-untracked'])
+    output = RunCommandPropagateErr(['git', 'stash', '--include-untracked'],
+                                    exit_status_on_error=1)
     if 'No local changes to save' in output:
       return False
 
@@ -33,30 +37,30 @@ class GitHelper(object):
   def StashPopAll(self):
     """Pops as many changes as this instance stashed."""
     while self.stashed > 0:
-      subprocess.check_output(['git', 'stash', 'pop'])
+      RunCommandPropagateErr(['git', 'stash', 'pop'], exit_status_on_error=1)
       self.stashed -= 1
 
   def GetCurrentBranchName(self):
     """Returns a string with the current branch name."""
-    return subprocess.check_output(
-        ['git', 'rev-parse', '--abbrev-ref', 'HEAD']).strip()
+    return RunCommandPropagateErr(
+        ['git', 'rev-parse', '--abbrev-ref', 'HEAD'],
+        exit_status_on_error=1).strip()
 
   def GetCurrentBranchHash(self):
-    return subprocess.check_output(
-        ['git', 'rev-parse', 'HEAD']).strip()
+    return RunCommandPropagateErr(
+        ['git', 'rev-parse', 'HEAD'], exit_status_on_error=1).strip()
 
   def IsCurrentBranchClean(self):
-    output = subprocess.check_output(['git', 'status', '--porcelain'])
+    output = RunCommandPropagateErr(['git', 'status', '--porcelain'],
+                                    exit_status_on_error=1)
     return not output
 
   def BranchExists(self, branch_name):
     """Return whether a branch with the given name exists."""
-    try:
-      subprocess.check_output(['git', 'rev-parse', '--verify',
-                               branch_name])
-      return True
-    except subprocess.CalledProcessError:
-      return False
+    output = RunCommandPropagateErr(['git', 'rev-parse', '--verify',
+                                     branch_name])
+    return output is not None
 
   def CloneLocal(self, source_repo, new_repo):
-    subprocess.check_call(['git', 'clone', source_repo, new_repo])
+    RunCommandPropagateErr(['git', 'clone', source_repo, new_repo],
+                           exit_status_on_error=1)
diff --git a/testing/tools/safetynet_compare.py b/testing/tools/safetynet_compare.py
index 028dd02232..d583312bab 100755
--- a/testing/tools/safetynet_compare.py
+++ b/testing/tools/safetynet_compare.py
@@ -17,6 +17,8 @@ import sys
 import tempfile
 
 from common import GetBooleanGnArg
+from common import PrintErr
+from common import RunCommandPropagateErr
 from githelper import GitHelper
 from safetynet_conclusions import ComparisonConclusions
 from safetynet_conclusions import PrintConclusionsDictHumanReadable
@@ -24,11 +26,6 @@ from safetynet_conclusions import RATING_IMPROVEMENT
 from safetynet_conclusions import RATING_REGRESSION
 
 
-def PrintErr(s):
-  """Prints s to stderr."""
-  print >> sys.stderr, s
-
-
 def RunSingleTestCaseParallel(this, run_label, build_dir, test_case):
   result = this.RunSingleTestCase(run_label, build_dir, test_case)
   return (test_case, result)
@@ -44,11 +41,13 @@ class CompareRun(object):
 
   def _InitPaths(self):
     if self.args.this_repo:
-      measure_script_path = os.path.join(self.args.build_dir,
-                                         'safetynet_measure_current.py')
+      self.safe_script_dir = self.args.build_dir
     else:
-      measure_script_path = 'testing/tools/safetynet_measure.py'
-    self.safe_measure_script_path = os.path.abspath(measure_script_path)
+      self.safe_script_dir = os.path.join('testing', 'tools')
+
+    self.safe_measure_script_path = os.path.abspath(
+        os.path.join(self.safe_script_dir,
+                     'safetynet_measure.py'))
 
     input_file_re = re.compile('^.+[.]pdf$')
     self.test_cases = []
@@ -115,8 +114,12 @@ class CompareRun(object):
     This is needed to make sure we are comparing the pdfium library changes and
     not script changes that may happen between the two branches.
     """
-    subprocess.check_output(['cp', 'testing/tools/safetynet_measure.py',
-                             self.safe_measure_script_path])
+    self.__FreezeFile(os.path.join('testing', 'tools', 'safetynet_measure.py'))
+    self.__FreezeFile(os.path.join('testing', 'tools', 'common.py'))
+
+  def __FreezeFile(self, file):
+    RunCommandPropagateErr(['cp', file, self.safe_script_dir],
+                           exit_status_on_error=1)
 
   def _ProfileTwoOtherBranchesInThisRepo(self, before_branch, after_branch):
     """Profiles two branches that are not the current branch.
@@ -334,9 +337,10 @@ class CompareRun(object):
            'https://pdfium.googlesource.com/pdfium.git']
     if self.args.cache_dir:
       cmd.append('--cache-dir=%s' % self.args.cache_dir)
-    subprocess.check_output(cmd)
+    RunCommandPropagateErr(cmd, exit_status_on_error=1)
+
+    RunCommandPropagateErr(['gclient', 'sync'], exit_status_on_error=1)
 
-    subprocess.check_output(['gclient', 'sync'])
     PrintErr('Done.')
 
     build_dir = os.path.join(src_dir, relative_build_dir)
@@ -347,7 +351,8 @@ class CompareRun(object):
     dest_gn_args = os.path.join(build_dir, 'args.gn')
     shutil.copy(source_gn_args, dest_gn_args)
 
-    subprocess.check_output(['gn', 'gen', relative_build_dir])
+    RunCommandPropagateErr(['gn', 'gen', relative_build_dir],
+                           exit_status_on_error=1)
 
     os.chdir(cwd)
 
@@ -373,16 +378,14 @@ class CompareRun(object):
       build_dir: String with path to build directory
     """
     PrintErr('Syncing...')
-    subprocess.check_output(['gclient', 'sync'])
+    RunCommandPropagateErr(['gclient', 'sync'], exit_status_on_error=1)
     PrintErr('Done.')
 
+    PrintErr('Building...')
     cmd = ['ninja', '-C', build_dir, 'pdfium_test']
-
     if GetBooleanGnArg('use_goma', build_dir):
       cmd.extend(['-j', '250'])
-
-    PrintErr('Building...')
-    subprocess.check_output(cmd)
+    RunCommandPropagateErr(cmd, stdout_has_errors=True, exit_status_on_error=1)
     PrintErr('Done.')
 
   def _MeasureCurrentBranch(self, run_label, build_dir):
@@ -480,13 +483,9 @@ class CompareRun(object):
     if profile_file_path:
       command.append('--output-path=%s' % profile_file_path)
 
-    try:
-      output = subprocess.check_output(command)
-    except subprocess.CalledProcessError as e:
-      PrintErr(e)
-      PrintErr(35 * '=' + '  Output:  ' + 34 * '=')
-      PrintErr(e.output)
-      PrintErr(80 * '=')
+    output = RunCommandPropagateErr(command)
+
+    if output is None:
       return None
 
     # Get the time number as output, making sure it's just a number
@@ -539,7 +538,7 @@ class CompareRun(object):
           ComparisonConclusions.GetOutputDict().
     """
     if self.args.machine_readable:
-      print json.dumps(conclusions_dict, ensure_ascii=False)
+      print json.dumps(conclusions_dict)
     else:
       PrintConclusionsDictHumanReadable(
           conclusions_dict, colored=True, key=self.args.case_order)
diff --git a/testing/tools/safetynet_conclusions.py b/testing/tools/safetynet_conclusions.py
index 112274e669..5764ede0c5 100644
--- a/testing/tools/safetynet_conclusions.py
+++ b/testing/tools/safetynet_conclusions.py
@@ -179,7 +179,7 @@ class ComparisonConclusions(object):
     output_dict['params'] = {'threshold': self.threshold_significant}
     output_dict['summary'] = self.summary.GetOutputDict()
     output_dict['comparison_by_case'] = {
-        cr.case_name: cr.GetOutputDict()
+        cr.case_name.decode('utf-8'): cr.GetOutputDict()
         for cr in self.GetCaseResults().values()
     }
     return output_dict
@@ -264,17 +264,18 @@ def PrintConclusionsDictHumanReadable(conclusions_dict, colored, key=None):
 
   for case_name, case_dict in case_pairs:
     if case_dict['rating'] == RATING_FAILURE:
-      print '%s to measure time for %s' % (
-          RATING_TO_COLOR[RATING_FAILURE].format('Failed'), case_name)
+      print u'{} to measure time for {}'.format(
+          RATING_TO_COLOR[RATING_FAILURE].format('Failed'),
+          case_name).encode('utf-8')
       continue
 
     if colored:
       color = RATING_TO_COLOR[case_dict['rating']]
 
-    print '{0} {1:15,d}  {2}' .format(
+    print u'{0} {1:15,d}  {2}' .format(
         color.format('{:+11.4%}'.format(case_dict['ratio'])),
         case_dict['after'],
-        case_name)
+        case_name).encode('utf-8')
 
   # Print totals
   totals = conclusions_dict['summary']
diff --git a/testing/tools/safetynet_job.py b/testing/tools/safetynet_job.py
index 09e6b75097..5cb926aec9 100755
--- a/testing/tools/safetynet_job.py
+++ b/testing/tools/safetynet_job.py
@@ -17,6 +17,9 @@ import os
 import subprocess
 import sys
 
+from common import PrintErr
+from common import PrintWithTime
+from common import RunCommandPropagateErr
 from githelper import GitHelper
 from safetynet_conclusions import PrintConclusionsDictHumanReadable
 
@@ -66,16 +69,15 @@ class JobRun(object):
         os.path.pardir)
     os.chdir(pdfium_src_dir)
 
-    if not self.git.IsCurrentBranchClean():
-      print 'Current branch is not clean, aborting'
+    if not self.git.IsCurrentBranchClean() and not self.args.no_checkout:
+      PrintWithTime('Current branch is not clean, aborting')
       return 1
 
     branch_to_restore = self.git.GetCurrentBranchName()
 
-    if not self.args.no_fetch:
+    if not self.args.no_checkout:
       self.git.FetchOriginMaster()
-
-    self.git.Checkout('origin/master')
+      self.git.Checkout('origin/master')
 
     # Make sure results dir exists
     if not os.path.exists(self.context.results_dir):
@@ -99,11 +101,12 @@ class JobRun(object):
     """
     current = self.git.GetCurrentBranchHash()
 
-    print 'Initial run, current is %s' % current
+    PrintWithTime('Initial run, current is %s' % current)
 
     self._WriteCheckpoint(current)
 
-    print 'All set up, next runs will be incremental and perform comparisons'
+    PrintWithTime('All set up, next runs will be incremental and perform '
+                  'comparisons')
     return 0
 
   def _IncrementalRun(self, last_revision_covered):
@@ -117,11 +120,11 @@ class JobRun(object):
     """
     current = self.git.GetCurrentBranchHash()
 
-    print ('Incremental run, current is %s, last is %s'
-           % (current, last_revision_covered))
+    PrintWithTime('Incremental run, current is %s, last is %s'
+                  % (current, last_revision_covered))
 
     if current == last_revision_covered:
-      print 'No changes seen, finishing job'
+      PrintWithTime('No changes seen, finishing job')
       return 0
 
     # Run compare
@@ -134,8 +137,10 @@ class JobRun(object):
            '--output-dir=%s' % self.context.run_output_dir]
     cmd.extend(self.args.input_paths)
 
-    p = subprocess.Popen(cmd, stdout=subprocess.PIPE)
-    json_output, _ = p.communicate()
+    json_output = RunCommandPropagateErr(cmd)
+
+    if json_output is None:
+      return 1
 
     output_info = json.loads(json_output)
     PrintConclusionsDictHumanReadable(output_info,
@@ -145,15 +150,15 @@ class JobRun(object):
     status = 0
 
     if output_info['summary']['improvement']:
-      print 'Improvement detected.'
+      PrintWithTime('Improvement detected.')
       status = 3
 
     if output_info['summary']['regression']:
-      print 'Regression detected.'
+      PrintWithTime('Regression detected.')
       status = 2
 
     if status == 0:
-      print 'Nothing detected.'
+      PrintWithTime('Nothing detected.')
 
     self._WriteCheckpoint(current)
 
@@ -172,9 +177,9 @@ def main():
   parser.add_argument('input_paths', nargs='+',
                       help='pdf files or directories to search for pdf files '
                            'to run as test cases')
-  parser.add_argument('--no-fetch', action='store_true',
-                      help='whether to skip the git fetch. Use for script '
-                      'debugging.')
+  parser.add_argument('--no-checkout', action='store_true',
+                      help='whether to skip checking out origin/master. Use '
+                           'for script debugging.')
   parser.add_argument('--no-checkpoint', action='store_true',
                       help='whether to skip writing the new checkpoint. Use '
                            'for script debugging.')
diff --git a/testing/tools/safetynet_measure.py b/testing/tools/safetynet_measure.py
index 67c07349e3..7b5bd5fe9d 100755
--- a/testing/tools/safetynet_measure.py
+++ b/testing/tools/safetynet_measure.py
@@ -14,6 +14,8 @@ import re
 import subprocess
 import sys
 
+from common import PrintErr
+
 
 CALLGRIND_PROFILER = 'callgrind'
 PERFSTAT_PROFILER = 'perfstat'
@@ -30,12 +32,13 @@ class PerformanceRun(object):
   def _CheckTools(self):
     """Returns whether the tool file paths are sane."""
     if not os.path.exists(self.pdfium_test_path):
-      print "FAILURE: Can't find test executable '%s'" % self.pdfium_test_path
-      print 'Use --build-dir to specify its location.'
+      PrintErr("FAILURE: Can't find test executable '%s'"
+               % self.pdfium_test_path)
+      PrintErr('Use --build-dir to specify its location.')
       return False
     if not os.access(self.pdfium_test_path, os.X_OK):
-      print ("FAILURE: Test executable '%s' lacks execution permissions"
-             % self.pdfium_test_path)
+      PrintErr("FAILURE: Test executable '%s' lacks execution permissions"
+               % self.pdfium_test_path)
       return False
     return True
 
@@ -53,7 +56,7 @@ class PerformanceRun(object):
     elif self.args.profiler == PERFSTAT_PROFILER:
       time = self._RunPerfStat()
     else:
-      print 'profiler=%s not supported, aborting' % self.args.profiler
+      PrintErr('profiler=%s not supported, aborting' % self.args.profiler)
       return 1
 
     if time is None:
@@ -142,7 +145,7 @@ def main():
   args = parser.parse_args()
 
   if args.interesting_section and args.profiler != CALLGRIND_PROFILER:
-    print '--interesting-section requires profiler to be callgrind.'
+    PrintErr('--interesting-section requires profiler to be callgrind.')
     return 1
 
   run = PerformanceRun(args)