Add test framework logging function. NFC (#25164)

Followup to #25081

Author: sbc100

test/common.py

@@ -155,6 +155,14 @@ def configure(data_dir):
 requires_network = unittest.skipIf(os.getenv('EMTEST_SKIP_NETWORK_TESTS'), 'This test requires network access')
 
 
+def errlog(*args):
+  """Shorthand for print with file=sys.stderr
+
+  Use this for all internal test framework logging..
+  """
+  print(*args, file=sys.stderr)
+
+
 def load_previous_test_run_results():
   try:
     return json.load(open(PREVIOUS_TEST_RUN_RESULTS_FILE))
@@ -1420,9 +1428,9 @@ def tearDown(self):
         left_over_files = set(temp_files_after_run) - set(self.temp_files_before_run)
         left_over_files = [f for f in left_over_files if not any(f.startswith(p) for p in ignorable_file_prefixes)]
         if len(left_over_files):
-          print('ERROR: After running test, there are ' + str(len(left_over_files)) + ' new temporary files/directories left behind:', file=sys.stderr)
+          errlog('ERROR: After running test, there are ' + str(len(left_over_files)) + ' new temporary files/directories left behind:')
           for f in left_over_files:
-            print('leaked file: ' + f, file=sys.stderr)
+            errlog('leaked file: ', f)
           self.fail('Test leaked ' + str(len(left_over_files)) + ' temporary files!')
 
   def get_setting(self, key, default=None):
@@ -1854,15 +1862,15 @@ def get_library(self, name, generated_libs, configure=['sh', './configure'],  #
     cache_name = ''.join([(c if c in valid_chars else '_') for c in cache_name])
 
     if not force_rebuild and self.library_cache.get(cache_name):
-      print('<load %s from cache> ' % cache_name, file=sys.stderr)
+      errlog('<load %s from cache> ' % cache_name)
       generated_libs = []
       for basename, contents in self.library_cache[cache_name]:
         bc_file = os.path.join(build_dir, cache_name + '_' + basename)
         write_binary(bc_file, contents)
         generated_libs.append(bc_file)
       return generated_libs
 
-    print(f'<building and saving {cache_name} into cache>', file=sys.stderr)
+    errlog(f'<building and saving {cache_name} into cache>')
     if configure and configure_args:
       # Make to copy to avoid mutating default param
       configure = list(configure)

test/parallel_testsuite.py

@@ -14,6 +14,7 @@
 from tools import utils
 
 import common
+from common import errlog
 
 from tools.shared import cap_max_workers_in_pool
 from tools.utils import WINDOWS
@@ -109,7 +110,7 @@ def run(self, result):
     tests = list(self if self.failing_and_slow_first else self.reversed_tests())
     contains_browser_test = any(test.is_browser_test() for test in tests)
     use_cores = cap_max_workers_in_pool(min(self.max_cores, len(tests), num_cores()), contains_browser_test)
-    print('Using %s parallel test processes' % use_cores, file=sys.stderr)
+    errlog(f'Using {use_cores} parallel test processes')
     with multiprocessing.Manager() as manager:
       # Give each worker a unique ID.
       worker_id_counter = manager.Value('i', 0) # 'i' for integer, starting at 0
@@ -124,7 +125,7 @@ def run(self, result):
           # or the progress bar.
           failfast_event = progress_counter = lock = None
           if self.failfast:
-            print('The version of python being used is not compatible with --failfast')
+            errlog('The version of python being used is not compatible with --failfast')
             sys.exit(1)
         else:
           failfast_event = manager.Event() if self.failfast else None
@@ -137,7 +138,7 @@ def run(self, result):
         num_tear_downs = sum([pool.apply(tear_down, ()) for i in range(use_cores)])
         # Assert the assumed behavior above hasn't changed.
         if num_tear_downs != use_cores:
-          print(f'Expected {use_cores} teardowns, got {num_tear_downs}')
+          errlog(f'Expected {use_cores} teardowns, got {num_tear_downs}')
 
     # Filter out the None results which can occur in failfast mode.
     if self.failfast:
@@ -181,9 +182,9 @@ def reversed_tests(self):
     return sorted(self, key=str, reverse=True)
 
   def combine_results(self, result, buffered_results):
-    print('', file=sys.stderr)
-    print('DONE: combining results on main thread', file=sys.stderr)
-    print('', file=sys.stderr)
+    errlog('')
+    errlog('DONE: combining results on main thread')
+    errlog('')
     # Sort the results back into alphabetical order. Running the tests in
     # parallel causes mis-orderings, this makes the results more readable.
     results = sorted(buffered_results, key=lambda res: str(res.test))
@@ -295,32 +296,32 @@ def compute_progress(self):
     return val
 
   def addSuccess(self, test):
-    print(f'{self.compute_progress()}{test} ... ok ({self.calculateElapsed():.2f}s)', file=sys.stderr)
+    errlog(f'{self.compute_progress()}{test} ... ok ({self.calculateElapsed():.2f}s)')
     self.buffered_result = BufferedTestSuccess(test)
     self.test_result = 'success'
 
   def addExpectedFailure(self, test, err):
-    print(f'{self.compute_progress()}{test} ... expected failure ({self.calculateElapsed():.2f}s)', file=sys.stderr)
+    errlog(f'{self.compute_progress()}{test} ... expected failure ({self.calculateElapsed():.2f}s)')
     self.buffered_result = BufferedTestExpectedFailure(test, err)
     self.test_result = 'expected failure'
 
   def addUnexpectedSuccess(self, test):
-    print(f'{self.compute_progress()}{test} ... unexpected success ({self.calculateElapsed():.2f}s)', file=sys.stderr)
+    errlog(f'{self.compute_progress()}{test} ... unexpected success ({self.calculateElapsed():.2f}s)')
     self.buffered_result = BufferedTestUnexpectedSuccess(test)
     self.test_result = 'unexpected success'
 
   def addSkip(self, test, reason):
-    print(f"{self.compute_progress()}{test} ... skipped '{reason}'", file=sys.stderr)
+    errlog(f"{self.compute_progress()}{test} ... skipped '{reason}'")
     self.buffered_result = BufferedTestSkip(test, reason)
     self.test_result = 'skipped'
 
   def addFailure(self, test, err):
-    print(f'{self.compute_progress()}{test} ... FAIL', file=sys.stderr)
+    errlog(f'{self.compute_progress()}{test} ... FAIL')
     self.buffered_result = BufferedTestFailure(test, err)
     self.test_result = 'failed'
 
   def addError(self, test, err):
-    print(f'{self.compute_progress()}{test} ... ERROR', file=sys.stderr)
+    errlog(f'{self.compute_progress()}{test} ... ERROR')
     self.buffered_result = BufferedTestError(test, err)
     self.test_result = 'errored'
 

test/runner.py

@@ -40,6 +40,7 @@
 import jsrun
 import parallel_testsuite
 import common
+from common import errlog
 from tools import shared, config, utils
 
 
@@ -108,11 +109,11 @@
 
 def check_js_engines():
   if not all(jsrun.check_engine(e) for e in config.JS_ENGINES):
-    print('Not all the JS engines in JS_ENGINES appears to work.')
+    errlog('Not all the JS engines in JS_ENGINES appears to work.')
     sys.exit(1)
 
   if common.EMTEST_ALL_ENGINES:
-    print('(using ALL js engines)')
+    errlog('(using ALL js engines)')
 
 
 def get_and_import_modules():
@@ -166,7 +167,7 @@ def tests_with_expanded_wildcards(args, all_tests):
     else:
       new_args += [arg]
   if not new_args and args:
-    print('No tests found to run in set: ' + str(args))
+    errlog('No tests found to run in set: ' + str(args))
     sys.exit(1)
   return new_args
 
@@ -189,7 +190,7 @@ def skip_requested_tests(args, modules):
     if arg.startswith('skip:'):
       which = arg.split('skip:')[1]
       os.environ['EMTEST_SKIP'] = os.environ['EMTEST_SKIP'] + ' ' + which
-      print('will skip "%s"' % which, file=sys.stderr)
+      errlog(f'will skip "{which}"')
       skip_test(which, modules)
       args[i] = None
   return [a for a in args if a is not None]
@@ -430,7 +431,7 @@ def run_tests(options, suites):
   total_core_time = 0
   run_start_time = time.perf_counter()
   for mod_name, suite in suites:
-    print('Running %s: (%s tests)' % (mod_name, suite.countTestCases()), file=sys.stderr)
+    errlog('Running %s: (%s tests)' % (mod_name, suite.countTestCases()))
     res = testRunner.run(suite)
     msg = ('%s: %s run, %s errors, %s failures, %s skipped' %
            (mod_name, res.testsRun, len(res.errors), len(res.failures), len(res.skipped)))
@@ -440,14 +441,14 @@ def run_tests(options, suites):
       total_core_time += res.core_time
   total_run_time = time.perf_counter() - run_start_time
   if total_core_time > 0:
-    print('Total core time: %.3fs. Wallclock time: %.3fs. Parallelization: %.2fx.' % (total_core_time, total_run_time, total_core_time / total_run_time), file=sys.stderr)
+    errlog('Total core time: %.3fs. Wallclock time: %.3fs. Parallelization: %.2fx.' % (total_core_time, total_run_time, total_core_time / total_run_time))
 
   if len(resultMessages) > 1:
-    print('====================')
-    print()
-    print('TEST SUMMARY')
+    errlog('====================')
+    errlog()
+    errlog('TEST SUMMARY')
     for msg in resultMessages:
-      print('    ' + msg)
+      errlog('    ' + msg)
 
   if options.bell:
     sys.stdout.write('\a')
@@ -518,12 +519,12 @@ def main():
   # Some options make sense being set in the environment, others not-so-much.
   # TODO(sbc): eventually just make these command-line only.
   if os.getenv('EMTEST_SAVE_DIR'):
-    print('ERROR: use --save-dir instead of EMTEST_SAVE_DIR=1, and --no-clean instead of EMTEST_SAVE_DIR=2')
+    errlog('ERROR: use --save-dir instead of EMTEST_SAVE_DIR=1, and --no-clean instead of EMTEST_SAVE_DIR=2')
     return 1
   if os.getenv('EMTEST_REBASELINE'):
-    print('Prefer --rebaseline over setting $EMTEST_REBASELINE')
+    errlog('Prefer --rebaseline over setting $EMTEST_REBASELINE')
   if os.getenv('EMTEST_VERBOSE'):
-    print('Prefer --verbose over setting $EMTEST_VERBOSE')
+    errlog('Prefer --verbose over setting $EMTEST_VERBOSE')
 
   # We set the environments variables here and then call configure,
   # to apply them.  This means the python's multiprocessing child
@@ -577,7 +578,7 @@ def prepend_default(arg):
     tests = args_for_random_tests(tests, modules)
 
   if not tests:
-    print('ERROR: no tests to run')
+    errlog('ERROR: no tests to run')
     return 1
 
   if not options.start_at and options._continue:
@@ -586,7 +587,7 @@ def prepend_default(arg):
 
   suites, unmatched_tests = load_test_suites(tests, modules, options)
   if unmatched_tests:
-    print('ERROR: could not find the following tests: ' + ' '.join(unmatched_tests))
+    errlog('ERROR: could not find the following tests: ' + ' '.join(unmatched_tests))
     return 1
 
   num_failures = run_tests(options, suites)