[test] Add verbose output of flaky tests

The verbose output shown on bots didn't print the first failing result
of a flaky test before. Now the result line shows all results and
the details in the end show the output of the first failure.

Previously it was confusing as it seemed that the json results and
the test runner output differed.

We now print PASS in all caps like the other statuses. A test for
this case already existed and the output is now updated.

Bug: v8:8434
Change-Id: I473ec392e0028bf64b3da53d4b37446ffcd17277
Reviewed-on: https://chromium-review.googlesource.com/c/v8/v8/+/2919670
Commit-Queue: Liviu Rau <liviurau@chromium.org>
Auto-Submit: Michael Achenbach <machenbach@chromium.org>
Reviewed-by: Liviu Rau <liviurau@chromium.org>
Cr-Commit-Position: refs/heads/master@{#74792}

tools/testrunner/testproc/progress.py

@@ -17,15 +17,13 @@ from . import base
 from . import util
 
 
-def print_failure_header(test):
+def print_failure_header(test, is_flaky=False):
+  text = [str(test)]
   if test.output_proc.negative:
-    negative_marker = '[negative] '
-  else:
-    negative_marker = ''
-  print("=== %(label)s %(negative)s===" % {
-    'label': test,
-    'negative': negative_marker,
-  })
+    text.append('[negative]')
+  if is_flaky:
+    text.append('(flaky)')
+  print('=== %s ===' % ' '.join(text))
 
 
 class ResultsTracker(base.TestProcObserver):
@@ -74,13 +72,18 @@ class SimpleProgressIndicator(ProgressIndicator):
   def _on_result_for(self, test, result):
     # TODO(majeski): Support for dummy/grouped results
     if result.has_unexpected_output:
-      self._failed.append((test, result))
+      self._failed.append((test, result, False))
+    elif result.is_rerun:
+      # Print only the first result of a flaky failure that was rerun.
+      self._failed.append((test, result.results[0], True))
 
   def finished(self):
     crashed = 0
+    flaky = 0
     print()
-    for test, result in self._failed:
-      print_failure_header(test)
+    for test, result, is_flaky in self._failed:
+      flaky += int(is_flaky)
+      print_failure_header(test, is_flaky=is_flaky)
       if result.output.stderr:
         print("--- stderr ---")
         print(result.output.stderr.strip())
@@ -101,9 +104,11 @@ class SimpleProgressIndicator(ProgressIndicator):
     else:
       print()
       print("===")
-      print("=== %i tests failed" % len(self._failed))
+      print("=== %d tests failed" % len(self._failed))
+      if flaky > 0:
+        print("=== %d tests were flaky" % flaky)
       if crashed > 0:
-        print("=== %i tests CRASHED" % crashed)
+        print("=== %d tests CRASHED" % crashed)
       print("===")
 
 
@@ -129,6 +134,17 @@ class StreamProgressIndicator(ProgressIndicator):
     print('%s: %ss' % (prefix, test))
     sys.stdout.flush()
 
+
+def format_result_status(result):
+  if result.has_unexpected_output:
+    if result.output.HasCrashed():
+      return 'CRASH'
+    else:
+      return 'FAIL'
+  else:
+    return 'PASS'
+
+
 class VerboseProgressIndicator(SimpleProgressIndicator):
   def __init__(self):
     super(VerboseProgressIndicator, self).__init__()
@@ -141,13 +157,10 @@ class VerboseProgressIndicator(SimpleProgressIndicator):
 
   def _message(self, test, result):
     # TODO(majeski): Support for dummy/grouped results
-    if result.has_unexpected_output:
-      if result.output.HasCrashed():
-        outcome = 'CRASH'
-      else:
-        outcome = 'FAIL'
+    if result.is_rerun:
+      outcome = ' '.join(format_result_status(r) for r in result.results)
     else:
-      outcome = 'pass'
+      outcome = format_result_status(result)
     return '%s %s: %s' % (
       test, test.variant or 'default', outcome)
 

tools/unittests/run_tests_test.py

@@ -177,7 +177,7 @@ class SystemTest(unittest.TestCase):
           'sweet/bananas',
           'sweet/raspberries',
       )
-      self.assertIn('sweet/bananas default: pass', result.stdout, result)
+      self.assertIn('sweet/bananas default: PASS', result.stdout, result)
       # TODO(majeski): Implement for test processors
       # self.assertIn('Total time:', result.stderr, result)
       # self.assertIn('sweet/bananas', result.stderr, result)
@@ -328,8 +328,10 @@ class SystemTest(unittest.TestCase):
           'sweet',
           infra_staging=False,
       )
-      self.assertIn('sweet/bananaflakes default: pass', result.stdout, result)
-      self.assertIn('All tests succeeded', result.stdout, result)
+      self.assertIn('sweet/bananaflakes default: FAIL PASS', result.stdout, result)
+      self.assertIn('=== sweet/bananaflakes (flaky) ===', result.stdout, result)
+      self.assertIn('1 tests failed', result.stdout, result)
+      self.assertIn('1 tests were flaky', result.stdout, result)
       self.assertEqual(0, result.returncode, result)
       self.maxDiff = None
       self.check_cleaned_json_output(
@@ -631,7 +633,7 @@ class SystemTest(unittest.TestCase):
           'sweet/blackberries',  # FAIL
           'sweet/raspberries',   # should not run
       )
-      self.assertIn('sweet/mangoes default: pass', result.stdout, result)
+      self.assertIn('sweet/mangoes default: PASS', result.stdout, result)
       self.assertIn('sweet/strawberries default: FAIL', result.stdout, result)
       self.assertIn('Too many failures, exiting...', result.stdout, result)
       self.assertIn('sweet/blackberries default: FAIL', result.stdout, result)