From 0da39e6b62fe7dc0f40d5242325b3b2d5b2c9d96 Mon Sep 17 00:00:00 2001 From: Henrique Nakashima Date: Tue, 15 Aug 2017 14:37:58 -0400 Subject: Make errors in called processes more evident and easier to debug. MIME-Version: 1.0 Content-Type: text/plain; charset=UTF-8 Content-Transfer-Encoding: 8bit Also trying to get unicode filenames right again. Change-Id: I501c94921b92b8a8cd6a10441aff1595fc6d878e Reviewed-on: https://pdfium-review.googlesource.com/10630 Commit-Queue: Henrique Nakashima Reviewed-by: Nicolás Peña Reviewed-by: Ryan Harrison --- testing/tools/common.py | 44 ++++++++++++++++++++++++++++ testing/tools/githelper.py | 36 +++++++++++++---------- testing/tools/safetynet_compare.py | 53 +++++++++++++++++----------------- testing/tools/safetynet_conclusions.py | 11 +++---- testing/tools/safetynet_job.py | 41 ++++++++++++++------------ testing/tools/safetynet_measure.py | 15 ++++++---- 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) -- cgit v1.2.3