• Home
  • Line#
  • Scopes#
  • Navigate#
  • Raw
  • Download
1# Copyright 2018 the V8 project authors. All rights reserved.
2# Use of this source code is governed by a BSD-style license that can be
3# found in the LICENSE file.
4
5import datetime
6import json
7import os
8import platform
9import sys
10import time
11
12from . import base
13from . import util
14from ..local import junit_output
15
16
17def print_failure_header(test, is_flaky=False):
18  text = [str(test)]
19  if test.output_proc.negative:
20    text.append('[negative]')
21  if is_flaky:
22    text.append('(flaky)')
23  output = '=== %s ===' % ' '.join(text)
24  encoding = sys.stdout.encoding or 'utf-8'
25  print(output.encode(encoding, errors='replace').decode(encoding))
26
27
28class ResultsTracker(base.TestProcObserver):
29  """Tracks number of results and stops to run tests if max_failures reached."""
30  def __init__(self, max_failures):
31    super(ResultsTracker, self).__init__()
32    self._requirement = base.DROP_OUTPUT
33
34    self.failed = 0
35    self.remaining = 0
36    self.total = 0
37    self.max_failures = max_failures
38
39  def _on_next_test(self, test):
40    self.total += 1
41    self.remaining += 1
42
43  def _on_result_for(self, test, result):
44    self.remaining -= 1
45    if result.has_unexpected_output:
46      self.failed += 1
47      if self.max_failures and self.failed >= self.max_failures:
48        print('>>> Too many failures, exiting...')
49        self.stop()
50
51
52class ProgressIndicator(base.TestProcObserver):
53  def __init__(self):
54    super(base.TestProcObserver, self).__init__()
55    self.options = None
56
57  def finished(self):
58    pass
59
60  def configure(self, options):
61    self.options = options
62
63
64class SimpleProgressIndicator(ProgressIndicator):
65  def __init__(self):
66    super(SimpleProgressIndicator, self).__init__()
67    self._requirement = base.DROP_PASS_OUTPUT
68
69    self._failed = []
70
71  def _on_result_for(self, test, result):
72    # TODO(majeski): Support for dummy/grouped results
73    if result.has_unexpected_output:
74      self._failed.append((test, result, False))
75    elif result.is_rerun:
76      # Print only the first result of a flaky failure that was rerun.
77      self._failed.append((test, result.results[0], True))
78
79  def finished(self):
80    crashed = 0
81    flaky = 0
82    print()
83    for test, result, is_flaky in self._failed:
84      flaky += int(is_flaky)
85      print_failure_header(test, is_flaky=is_flaky)
86      if result.output.stderr:
87        print("--- stderr ---")
88        print(result.output.stderr.strip())
89      if result.output.stdout:
90        print("--- stdout ---")
91        print(result.output.stdout.strip())
92      print("Command: %s" % result.cmd.to_string())
93      if result.output.HasCrashed():
94        print("exit code: %s" % result.output.exit_code_string)
95        print("--- CRASHED ---")
96        crashed += 1
97      if result.output.HasTimedOut():
98        print("--- TIMEOUT ---")
99    if len(self._failed) == 0:
100      print("===")
101      print("=== All tests succeeded")
102      print("===")
103    else:
104      print()
105      print("===")
106      print("=== %d tests failed" % len(self._failed))
107      if flaky > 0:
108        print("=== %d tests were flaky" % flaky)
109      if crashed > 0:
110        print("=== %d tests CRASHED" % crashed)
111      print("===")
112
113
114class StreamProgressIndicator(ProgressIndicator):
115  def __init__(self):
116    super(StreamProgressIndicator, self).__init__()
117    self._requirement = base.DROP_PASS_OUTPUT
118
119  def _on_result_for(self, test, result):
120    if not result.has_unexpected_output:
121      self.print('PASS', test)
122    elif result.output.HasCrashed():
123      self.print("CRASH", test)
124    elif result.output.HasTimedOut():
125      self.print("TIMEOUT", test)
126    else:
127      if test.is_fail:
128        self.print("UNEXPECTED PASS", test)
129      else:
130        self.print("FAIL", test)
131
132  def print(self, prefix, test):
133    print('%s: %ss' % (prefix, test))
134    sys.stdout.flush()
135
136
137def format_result_status(result):
138  if result.has_unexpected_output:
139    if result.output.HasCrashed():
140      return 'CRASH'
141    else:
142      return 'FAIL'
143  else:
144    return 'PASS'
145
146
147class VerboseProgressIndicator(SimpleProgressIndicator):
148  def __init__(self):
149    super(VerboseProgressIndicator, self).__init__()
150    self._last_printed_time = time.time()
151
152  def _print(self, text):
153    encoding = sys.stdout.encoding or 'utf-8'
154    print(text.encode(encoding, errors='replace').decode(encoding))
155    sys.stdout.flush()
156    self._last_printed_time = time.time()
157
158  def _message(self, test, result):
159    # TODO(majeski): Support for dummy/grouped results
160    if result.is_rerun:
161      outcome = ' '.join(format_result_status(r) for r in result.results)
162    else:
163      outcome = format_result_status(result)
164    return '%s %s: %s' % (
165      test, test.variant or 'default', outcome)
166
167  def _on_result_for(self, test, result):
168    super(VerboseProgressIndicator, self)._on_result_for(test, result)
169    self._print(self._message(test, result))
170
171  # TODO(machenbach): Remove this platform specific hack and implement a proper
172  # feedback channel from the workers, providing which tests are currently run.
173  def _print_processes_linux(self):
174    if platform.system() == 'Linux':
175      self._print('List of processes:')
176      for pid, cmd in util.list_processes_linux():
177        # Show command with pid, but other process info cut off.
178        self._print('pid: %d cmd: %s' % (pid, cmd))
179
180  def _ensure_delay(self, delay):
181    return time.time() - self._last_printed_time > delay
182
183  def _on_heartbeat(self):
184    if self._ensure_delay(30):
185      # Print something every 30 seconds to not get killed by an output
186      # timeout.
187      self._print('Still working...')
188      self._print_processes_linux()
189
190  def _on_event(self, event):
191    self._print(event)
192    self._print_processes_linux()
193
194
195class CIProgressIndicator(VerboseProgressIndicator):
196  def _on_result_for(self, test, result):
197    super(VerboseProgressIndicator, self)._on_result_for(test, result)
198    if self.options.ci_test_completion:
199      with open(self.options.ci_test_completion, "a") as f:
200        f.write(self._message(test, result) + "\n")
201    self._output_feedback()
202
203  def _output_feedback(self):
204    """Reduced the verbosity leads to getting killed by an ouput timeout.
205    We ensure output every minute.
206    """
207    if self._ensure_delay(60):
208      dt = time.time()
209      st = datetime.datetime.fromtimestamp(dt).strftime('%Y-%m-%d %H:%M:%S')
210      self._print(st)
211
212
213class DotsProgressIndicator(SimpleProgressIndicator):
214  def __init__(self):
215    super(DotsProgressIndicator, self).__init__()
216    self._count = 0
217
218  def _on_result_for(self, test, result):
219    super(DotsProgressIndicator, self)._on_result_for(test, result)
220    # TODO(majeski): Support for dummy/grouped results
221    self._count += 1
222    if self._count > 1 and self._count % 50 == 1:
223      sys.stdout.write('\n')
224    if result.has_unexpected_output:
225      if result.output.HasCrashed():
226        sys.stdout.write('C')
227        sys.stdout.flush()
228      elif result.output.HasTimedOut():
229        sys.stdout.write('T')
230        sys.stdout.flush()
231      else:
232        sys.stdout.write('F')
233        sys.stdout.flush()
234    else:
235      sys.stdout.write('.')
236      sys.stdout.flush()
237
238
239class CompactProgressIndicator(ProgressIndicator):
240  def __init__(self, templates):
241    super(CompactProgressIndicator, self).__init__()
242    self._requirement = base.DROP_PASS_OUTPUT
243
244    self._templates = templates
245    self._last_status_length = 0
246    self._start_time = time.time()
247
248    self._passed = 0
249    self._failed = 0
250
251  def set_test_count(self, test_count):
252    self._total = test_count
253
254  def _on_result_for(self, test, result):
255    # TODO(majeski): Support for dummy/grouped results
256    if result.has_unexpected_output:
257      self._failed += 1
258    else:
259      self._passed += 1
260
261    self._print_progress(str(test))
262    if result.has_unexpected_output:
263      output = result.output
264      stdout = output.stdout.strip()
265      stderr = output.stderr.strip()
266
267      self._clear_line(self._last_status_length)
268      print_failure_header(test)
269      if len(stdout):
270        self.printFormatted('stdout', stdout)
271      if len(stderr):
272        self.printFormatted('stderr', stderr)
273      self.printFormatted(
274          'command', "Command: %s" % result.cmd.to_string(relative=True))
275      if output.HasCrashed():
276        self.printFormatted(
277            'failure', "exit code: %s" % output.exit_code_string)
278        self.printFormatted('failure', "--- CRASHED ---")
279      elif output.HasTimedOut():
280        self.printFormatted('failure', "--- TIMEOUT ---")
281      else:
282        if test.is_fail:
283          self.printFormatted('failure', "--- UNEXPECTED PASS ---")
284          if test.expected_failure_reason != None:
285            self.printFormatted('failure', test.expected_failure_reason)
286        else:
287          self.printFormatted('failure', "--- FAILED ---")
288
289  def finished(self):
290    self._print_progress('Done')
291    print()
292
293  def _print_progress(self, name):
294    self._clear_line(self._last_status_length)
295    elapsed = time.time() - self._start_time
296    if self._total:
297      progress = (self._passed + self._failed) * 100 // self._total
298    else:
299      progress = 0
300    status = self._templates['status_line'] % {
301      'passed': self._passed,
302      'progress': progress,
303      'failed': self._failed,
304      'test': name,
305      'mins': int(elapsed) // 60,
306      'secs': int(elapsed) % 60
307    }
308    status = self._truncateStatusLine(status, 78)
309    self._last_status_length = len(status)
310    print(status, end='')
311    sys.stdout.flush()
312
313  def _truncateStatusLine(self, string, length):
314    if length and len(string) > (length - 3):
315      return string[:(length - 3)] + "..."
316    else:
317      return string
318
319  def _clear_line(self, last_length):
320    raise NotImplementedError()
321
322
323class ColorProgressIndicator(CompactProgressIndicator):
324  def __init__(self):
325    templates = {
326      'status_line': ("[%(mins)02i:%(secs)02i|"
327                      "\033[34m%%%(progress) 4d\033[0m|"
328                      "\033[32m+%(passed) 4d\033[0m|"
329                      "\033[31m-%(failed) 4d\033[0m]: %(test)s"),
330      'stdout': "\033[1m%s\033[0m",
331      'stderr': "\033[31m%s\033[0m",
332      'failure': "\033[1;31m%s\033[0m",
333      'command': "\033[33m%s\033[0m",
334    }
335    super(ColorProgressIndicator, self).__init__(templates)
336
337  def printFormatted(self, format, string):
338    print(self._templates[format] % string)
339
340  def _truncateStatusLine(self, string, length):
341    # Add some slack for the color control chars
342    return super(ColorProgressIndicator, self)._truncateStatusLine(
343        string, length + 3*9)
344
345  def _clear_line(self, last_length):
346    print("\033[1K\r", end='')
347
348
349class MonochromeProgressIndicator(CompactProgressIndicator):
350  def __init__(self):
351    templates = {
352        'status_line': ("[%(mins)02i:%(secs)02i|%%%(progress) 4d|"
353                        "+%(passed) 4d|-%(failed) 4d]: %(test)s"),
354    }
355    super(MonochromeProgressIndicator, self).__init__(templates)
356
357  def printFormatted(self, format, string):
358    print(string)
359
360  def _clear_line(self, last_length):
361    print(("\r" + (" " * last_length) + "\r"), end='')
362
363
364class JUnitTestProgressIndicator(ProgressIndicator):
365  def __init__(self, junitout, junittestsuite):
366    super(JUnitTestProgressIndicator, self).__init__()
367    self._requirement = base.DROP_PASS_STDOUT
368
369    self.outputter = junit_output.JUnitTestOutput(junittestsuite)
370    if junitout:
371      self.outfile = open(junitout, "wb")
372    else:
373      self.outfile = sys.stdout
374
375  def _on_result_for(self, test, result):
376    # TODO(majeski): Support for dummy/grouped results
377    fail_text = ""
378    output = result.output
379    if result.has_unexpected_output:
380      stdout = output.stdout.strip()
381      if len(stdout):
382        fail_text += "stdout:\n%s\n" % stdout
383      stderr = output.stderr.strip()
384      if len(stderr):
385        fail_text += "stderr:\n%s\n" % stderr
386      fail_text += "Command: %s" % result.cmd.to_string()
387      if output.HasCrashed():
388        fail_text += "exit code: %d\n--- CRASHED ---" % output.exit_code
389      if output.HasTimedOut():
390        fail_text += "--- TIMEOUT ---"
391    self.outputter.HasRunTest(
392        test_name=str(test),
393        test_cmd=result.cmd.to_string(relative=True),
394        test_duration=output.duration,
395        test_failure=fail_text)
396
397  def finished(self):
398    self.outputter.FinishAndWrite(self.outfile)
399    if self.outfile != sys.stdout:
400      self.outfile.close()
401
402
403class JsonTestProgressIndicator(ProgressIndicator):
404  def __init__(self, framework_name):
405    super(JsonTestProgressIndicator, self).__init__()
406    # We want to drop stdout/err for all passed tests on the first try, but we
407    # need to get outputs for all runs after the first one. To accommodate that,
408    # reruns are set to keep the result no matter what requirement says, i.e.
409    # keep_output set to True in the RerunProc.
410    self._requirement = base.DROP_PASS_STDOUT
411
412    self.framework_name = framework_name
413    self.results = []
414    self.duration_sum = 0
415    self.test_count = 0
416
417  def configure(self, options):
418    super(JsonTestProgressIndicator, self).configure(options)
419    self.tests = util.FixedSizeTopList(
420        self.options.slow_tests_cutoff,
421        key=lambda rec: rec['duration'])
422
423  def _on_result_for(self, test, result):
424    if result.is_rerun:
425      self.process_results(test, result.results)
426    else:
427      self.process_results(test, [result])
428
429  def process_results(self, test, results):
430    for run, result in enumerate(results):
431      # TODO(majeski): Support for dummy/grouped results
432      output = result.output
433
434      self._buffer_slow_tests(test, result, output, run)
435
436      # Omit tests that run as expected on the first try.
437      # Everything that happens after the first run is included in the output
438      # even if it flakily passes.
439      if not result.has_unexpected_output and run == 0:
440        continue
441
442      record = self._test_record(test, result, output, run)
443      record.update({
444          "result": test.output_proc.get_outcome(output),
445          "stdout": output.stdout,
446          "stderr": output.stderr,
447        })
448      self.results.append(record)
449
450  def _buffer_slow_tests(self, test, result, output, run):
451    def result_value(test, result, output):
452      if not result.has_unexpected_output:
453        return ""
454      return test.output_proc.get_outcome(output)
455
456    record = self._test_record(test, result, output, run)
457    record.update({
458        "result": result_value(test, result, output),
459        "marked_slow": test.is_slow,
460      })
461    self.tests.add(record)
462    self.duration_sum += record['duration']
463    self.test_count += 1
464
465  def _test_record(self, test, result, output, run):
466    return {
467        "name": str(test),
468        "flags": result.cmd.args,
469        "command": result.cmd.to_string(relative=True),
470        "run": run + 1,
471        "exit_code": output.exit_code,
472        "expected": test.expected_outcomes,
473        "duration": output.duration,
474        "random_seed": test.random_seed,
475        "target_name": test.get_shell(),
476        "variant": test.variant,
477        "variant_flags": test.variant_flags,
478        "framework_name": self.framework_name,
479      }
480
481  def finished(self):
482    duration_mean = None
483    if self.test_count:
484      duration_mean = self.duration_sum / self.test_count
485
486    result = {
487      "results": self.results,
488      "slowest_tests": self.tests.as_list(),
489      "duration_mean": duration_mean,
490      "test_total": self.test_count,
491    }
492
493    with open(self.options.json_test_results, "w") as f:
494      json.dump(result, f)
495