Unreviewed, rolling out r112014.
[WebKit-https.git] / Tools / Scripts / webkitpy / layout_tests / views / printing.py
1 #!/usr/bin/env python
2 # Copyright (C) 2010 Google Inc. All rights reserved.
3 #
4 # Redistribution and use in source and binary forms, with or without
5 # modification, are permitted provided that the following conditions are
6 # met:
7 #
8 #     * Redistributions of source code must retain the above copyright
9 # notice, this list of conditions and the following disclaimer.
10 #     * Redistributions in binary form must reproduce the above
11 # copyright notice, this list of conditions and the following disclaimer
12 # in the documentation and/or other materials provided with the
13 # distribution.
14 #     * Neither the name of Google Inc. nor the names of its
15 # contributors may be used to endorse or promote products derived from
16 # this software without specific prior written permission.
17 #
18 # THIS SOFTWARE IS PROVIDED BY THE COPYRIGHT HOLDERS AND CONTRIBUTORS
19 # "AS IS" AND ANY EXPRESS OR IMPLIED WARRANTIES, INCLUDING, BUT NOT
20 # LIMITED TO, THE IMPLIED WARRANTIES OF MERCHANTABILITY AND FITNESS FOR
21 # A PARTICULAR PURPOSE ARE DISCLAIMED. IN NO EVENT SHALL THE COPYRIGHT
22 # OWNER OR CONTRIBUTORS BE LIABLE FOR ANY DIRECT, INDIRECT, INCIDENTAL,
23 # SPECIAL, EXEMPLARY, OR CONSEQUENTIAL DAMAGES (INCLUDING, BUT NOT
24 # LIMITED TO, PROCUREMENT OF SUBSTITUTE GOODS OR SERVICES; LOSS OF USE,
25 # DATA, OR PROFITS; OR BUSINESS INTERRUPTION) HOWEVER CAUSED AND ON ANY
26 # THEORY OF LIABILITY, WHETHER IN CONTRACT, STRICT LIABILITY, OR TORT
27 # (INCLUDING NEGLIGENCE OR OTHERWISE) ARISING IN ANY WAY OUT OF THE USE
28 # OF THIS SOFTWARE, EVEN IF ADVISED OF THE POSSIBILITY OF SUCH DAMAGE.
29
30 """Package that handles non-debug, non-file output for run-webkit-tests."""
31
32 import logging
33 import optparse
34 import time
35
36 from webkitpy.common.net import resultsjsonparser
37 from webkitpy.layout_tests.views.metered_stream import MeteredStream
38 from webkitpy.layout_tests.models.test_expectations import TestExpectations
39
40
41 _log = logging.getLogger(__name__)
42
43
44 NUM_SLOW_TESTS_TO_LOG = 10
45 FAST_UPDATES_SECONDS = 0.03
46 SLOW_UPDATES_SECONDS = 10.0
47
48 PRINT_DEFAULT = "misc,one-line-progress,one-line-summary,unexpected,unexpected-results,updates"
49 PRINT_EVERYTHING = "actual,config,expected,misc,one-line-progress,one-line-summary,slowest,timing,unexpected,unexpected-results,updates"
50
51 HELP_PRINTING = """
52 Output for run-webkit-tests is controlled by a comma-separated list of
53 values passed to --print.  Values either influence the overall output, or
54 the output at the beginning of the run, during the run, or at the end:
55
56 Overall options:
57     nothing             don't print anything. This overrides every other option
58     default             include the default options. This is useful for logging
59                         the default options plus additional settings.
60     everything          print (almost) everything (except the trace-* options,
61                         see below for the full list )
62     misc                print miscellaneous things like blank lines
63
64 At the beginning of the run:
65     config              print the test run configuration
66     expected            print a summary of what is expected to happen
67                         (# passes, # failures, etc.)
68
69 During the run:
70     one-line-progress   print a one-line progress message or bar
71     unexpected          print any unexpected results as they occur
72     updates             print updates on which stage is executing
73     trace-everything    print detailed info on every test's results
74                         (baselines, expectation, time it took to run). If
75                         this is specified it will override the '*-progress'
76                         options, the 'trace-unexpected' option, and the
77                         'unexpected' option.
78     trace-unexpected    like 'trace-everything', but only for tests with
79                         unexpected results. If this option is specified,
80                         it will override the 'unexpected' option.
81
82 At the end of the run:
83     actual              print a summary of the actual results
84     slowest             print %(slowest)d slowest tests and the time they took
85     timing              print timing statistics
86     unexpected-results  print a list of the tests with unexpected results
87     one-line-summary    print a one-line summary of the run
88
89 Notes:
90     - If 'nothing' is specified, it overrides all of the other options.
91     - Specifying --verbose is equivalent to --print everything plus it
92       changes the format of the log messages to add timestamps and other
93       information. If you specify --verbose and --print X, then X overrides
94       the --print everything implied by --verbose.
95
96 --print 'everything' is equivalent to --print '%(everything)s'.
97
98 The default (--print default) is equivalent to --print '%(default)s'.
99 """ % {'slowest': NUM_SLOW_TESTS_TO_LOG, 'everything': PRINT_EVERYTHING,
100        'default': PRINT_DEFAULT}
101
102
103 def print_options():
104     return [
105         # Note: We use print_options rather than just 'print' because print
106         # is a reserved word.
107         # Note: Also, we don't specify a default value so we can detect when
108         # no flag is specified on the command line and use different defaults
109         # based on whether or not --verbose is specified (since --print
110         # overrides --verbose).
111         optparse.make_option("--print", dest="print_options",
112             help=("controls print output of test run. "
113                   "Use --help-printing for more.")),
114         optparse.make_option("--help-printing", action="store_true",
115             help="show detailed help on controlling print output"),
116         optparse.make_option("-v", "--verbose", action="store_true",
117             default=False, help="include debug-level logging"),
118    ]
119
120
121 def parse_print_options(print_options, verbose):
122     """Parse the options provided to --print and dedup and rank them.
123
124     Returns
125         a set() of switches that govern how logging is done
126
127     """
128     if print_options:
129         switches = set(print_options.split(','))
130     elif verbose:
131         switches = set(PRINT_EVERYTHING.split(','))
132     else:
133         switches = set(PRINT_DEFAULT.split(','))
134
135     if 'nothing' in switches:
136         return set()
137
138     if 'everything' in switches:
139         switches.discard('everything')
140         switches.update(set(PRINT_EVERYTHING.split(',')))
141
142     if 'default' in switches:
143         switches.discard('default')
144         switches.update(set(PRINT_DEFAULT.split(',')))
145
146     if 'trace-everything' in switches:
147         switches.discard('one-line-progress')
148         switches.discard('trace-unexpected')
149         switches.discard('unexpected')
150
151     if 'trace-unexpected' in switches:
152         switches.discard('unexpected')
153
154     return switches
155
156
157 def _configure_logging(stream, verbose):
158     log_fmt = '%(message)s'
159     log_datefmt = '%y%m%d %H:%M:%S'
160     log_level = logging.INFO
161     if verbose:
162         log_fmt = '%(asctime)s %(process)d %(filename)s:%(lineno)d %(levelname)s %(message)s'
163         log_level = logging.DEBUG
164
165     root = logging.getLogger()
166     handler = logging.StreamHandler(stream)
167     handler.setFormatter(logging.Formatter(log_fmt, None))
168     root.addHandler(handler)
169     root.setLevel(log_level)
170     return handler
171
172
173 def _restore_logging(handler_to_remove):
174     root = logging.getLogger()
175     root.handlers.remove(handler_to_remove)
176
177
178 class Printer(object):
179     """Class handling all non-debug-logging printing done by run-webkit-tests.
180
181     Printing from run-webkit-tests falls into two buckets: general or
182     regular output that is read only by humans and can be changed at any
183     time, and output that is parsed by buildbots (and humans) and hence
184     must be changed more carefully and in coordination with the buildbot
185     parsing code (in chromium.org's buildbot/master.chromium/scripts/master/
186     log_parser/webkit_test_command.py script).
187
188     By default the buildbot-parsed code gets logged to stdout, and regular
189     output gets logged to stderr."""
190     def __init__(self, port, options, regular_output, buildbot_output, configure_logging):
191         """
192         Args
193           port               interface to port-specific routines
194           options            OptionParser object with command line settings
195           regular_output     stream to which output intended only for humans
196                              should be written
197           buildbot_output    stream to which output intended to be read by
198                              the buildbots (and humans) should be written
199           configure_loggign  Whether a logging handler should be registered
200
201         """
202         self._port = port
203         self._options = options
204         self._stream = regular_output
205         self._buildbot_stream = buildbot_output
206         self._meter = None
207
208         # These are used for --print one-line-progress
209         self._last_remaining = None
210         self._last_update_time = None
211
212         self.switches = parse_print_options(options.print_options, options.verbose)
213
214         self._logging_handler = None
215         if self._stream.isatty() and not options.verbose:
216             self._update_interval_seconds = FAST_UPDATES_SECONDS
217             self._meter = MeteredStream(self._stream)
218             if configure_logging:
219                 self._logging_handler = _configure_logging(self._meter, options.verbose)
220         else:
221             self._update_interval_seconds = SLOW_UPDATES_SECONDS
222             if configure_logging:
223                 self._logging_handler = _configure_logging(self._stream, options.verbose)
224
225     def cleanup(self):
226         """Restore logging configuration to its initial settings."""
227         if self._logging_handler:
228             _restore_logging(self._logging_handler)
229             self._logging_handler = None
230
231     def __del__(self):
232         self.cleanup()
233
234     # These two routines just hide the implementation of the switches.
235     def disabled(self, option):
236         return not option in self.switches
237
238     def enabled(self, option):
239         return option in self.switches
240
241     def help_printing(self):
242         self._write(HELP_PRINTING)
243
244     def print_actual(self, msg):
245         if self.disabled('actual'):
246             return
247         self._buildbot_stream.write("%s\n" % msg)
248
249     def print_config(self, msg):
250         self.write(msg, 'config')
251
252     def print_expected(self, msg):
253         self.write(msg, 'expected')
254
255     def print_timing(self, msg):
256         self.write(msg, 'timing')
257
258     def print_one_line_summary(self, total, expected, unexpected):
259         """Print a one-line summary of the test run to stdout.
260
261         Args:
262           total: total number of tests run
263           expected: number of expected results
264           unexpected: number of unexpected results
265         """
266         if self.disabled('one-line-summary'):
267             return
268
269         incomplete = total - expected - unexpected
270         if incomplete:
271             self._write("")
272             incomplete_str = " (%d didn't run)" % incomplete
273             expected_str = str(expected)
274         else:
275             incomplete_str = ""
276             expected_str = "All %d" % expected
277
278         if unexpected == 0:
279             self._write("%s tests ran as expected%s." %
280                         (expected_str, incomplete_str))
281         elif expected == 1:
282             self._write("1 test ran as expected, %d didn't%s:" %
283                         (unexpected, incomplete_str))
284         else:
285             self._write("%d tests ran as expected, %d didn't%s:" %
286                         (expected, unexpected, incomplete_str))
287         self._write("")
288
289     def print_test_result(self, result, expected, exp_str, got_str):
290         """Print the result of the test as determined by --print.
291
292         This routine is used to print the details of each test as it completes.
293
294         Args:
295             result   - The actual TestResult object
296             expected - Whether the result we got was an expected result
297             exp_str  - What we expected to get (used for tracing)
298             got_str  - What we actually got (used for tracing)
299
300         Note that we need all of these arguments even though they seem
301         somewhat redundant, in order to keep this routine from having to
302         known anything about the set of expectations.
303         """
304         if (self.enabled('trace-everything') or
305             self.enabled('trace-unexpected') and not expected):
306             self._print_test_trace(result, exp_str, got_str)
307         elif not expected and self.enabled('unexpected'):
308             self._print_unexpected_test_result(result)
309
310     def _print_test_trace(self, result, exp_str, got_str):
311         """Print detailed results of a test (triggered by --print trace-*).
312         For each test, print:
313            - location of the expected baselines
314            - expected results
315            - actual result
316            - timing info
317         """
318         test_name = result.test_name
319         self._write('trace: %s' % test_name)
320
321         base = self._port.lookup_virtual_test_base(test_name)
322         if base:
323             args = ' '.join(self._port.lookup_virtual_test_args(test_name))
324             self._write(' base: %s' % base)
325             self._write(' args: %s' % args)
326
327         for extension in ('.txt', '.png', '.wav', '.webarchive'):
328             self._print_baseline(test_name, extension)
329
330         self._write('  exp: %s' % exp_str)
331         self._write('  got: %s' % got_str)
332         self._write(' took: %-.3f' % result.test_run_time)
333         self._write('')
334
335     def _print_baseline(self, test_name, extension):
336         baseline = self._port.expected_filename(test_name, extension)
337         if self._port._filesystem.exists(baseline):
338             relpath = self._port.relative_test_filename(baseline)
339         else:
340             relpath = '<none>'
341         self._write('  %s: %s' % (extension[1:], relpath))
342
343     def _print_unexpected_test_result(self, result):
344         """Prints one unexpected test result line."""
345         desc = TestExpectations.EXPECTATION_DESCRIPTIONS[result.type][0]
346         self.write("  %s -> unexpected %s" % (result.test_name, desc), "unexpected")
347
348     def print_progress(self, result_summary, retrying, test_list):
349         """Print progress through the tests as determined by --print."""
350         if self.disabled('one-line-progress'):
351             return
352
353         now = time.time()
354         if self._last_update_time is None:
355             self._last_update_time = now
356
357         time_since_last_update = now - self._last_update_time
358         if time_since_last_update <= self._update_interval_seconds:
359             return
360
361         self._last_update_time = now
362
363         percent_complete = 100 * (result_summary.expected +
364             result_summary.unexpected) / result_summary.total
365         action = "Testing"
366         if retrying:
367             action = "Retrying"
368         self._update("%s (%d%%): %d ran as expected, %d didn't, %d left" %
369                      (action, percent_complete, result_summary.expected,
370                       result_summary.unexpected, result_summary.remaining))
371
372         if result_summary.remaining == 0:
373             self._update('')
374
375     def print_unexpected_results(self, unexpected_results):
376         """Prints a list of the unexpected results to the buildbot stream."""
377         if self.disabled('unexpected-results'):
378             return
379
380         passes = {}
381         flaky = {}
382         regressions = {}
383
384         def add_to_dict_of_lists(dict, key, value):
385             dict.setdefault(key, []).append(value)
386
387         def add_result(test, results, passes=passes, flaky=flaky, regressions=regressions):
388             actual = results['actual'].split(" ")
389             expected = results['expected'].split(" ")
390             if actual == ['PASS']:
391                 if 'CRASH' in expected:
392                     add_to_dict_of_lists(passes,
393                                          'Expected to crash, but passed',
394                                          test)
395                 elif 'TIMEOUT' in expected:
396                     add_to_dict_of_lists(passes,
397                                          'Expected to timeout, but passed',
398                                           test)
399                 else:
400                     add_to_dict_of_lists(passes,
401                                          'Expected to fail, but passed',
402                                          test)
403             elif len(actual) > 1:
404                 # We group flaky tests by the first actual result we got.
405                 add_to_dict_of_lists(flaky, actual[0], test)
406             else:
407                 add_to_dict_of_lists(regressions, results['actual'], test)
408
409         resultsjsonparser.for_each_test(unexpected_results['tests'], add_result)
410
411         if len(passes) or len(flaky) or len(regressions):
412             self._buildbot_stream.write("\n")
413
414         if len(passes):
415             for key, tests in passes.iteritems():
416                 self._buildbot_stream.write("%s: (%d)\n" % (key, len(tests)))
417                 tests.sort()
418                 for test in tests:
419                     self._buildbot_stream.write("  %s\n" % test)
420                 self._buildbot_stream.write("\n")
421             self._buildbot_stream.write("\n")
422
423         if len(flaky):
424             descriptions = TestExpectations.EXPECTATION_DESCRIPTIONS
425             for key, tests in flaky.iteritems():
426                 result = TestExpectations.EXPECTATIONS[key.lower()]
427                 self._buildbot_stream.write("Unexpected flakiness: %s (%d)\n"
428                     % (descriptions[result][1], len(tests)))
429                 tests.sort()
430
431                 for test in tests:
432                     result = resultsjsonparser.result_for_test(unexpected_results['tests'], test)
433                     actual = result['actual'].split(" ")
434                     expected = result['expected'].split(" ")
435                     result = TestExpectations.EXPECTATIONS[key.lower()]
436                     new_expectations_list = list(set(actual) | set(expected))
437                     self._buildbot_stream.write("  %s = %s\n" %
438                         (test, " ".join(new_expectations_list)))
439                 self._buildbot_stream.write("\n")
440             self._buildbot_stream.write("\n")
441
442         if len(regressions):
443             descriptions = TestExpectations.EXPECTATION_DESCRIPTIONS
444             for key, tests in regressions.iteritems():
445                 result = TestExpectations.EXPECTATIONS[key.lower()]
446                 self._buildbot_stream.write(
447                     "Regressions: Unexpected %s : (%d)\n" % (
448                     descriptions[result][1], len(tests)))
449                 tests.sort()
450                 for test in tests:
451                     self._buildbot_stream.write("  %s = %s\n" % (test, key))
452                 self._buildbot_stream.write("\n")
453             self._buildbot_stream.write("\n")
454
455         if len(unexpected_results['tests']) and self._options.verbose:
456             self._buildbot_stream.write("%s\n" % ("-" * 78))
457
458     def print_update(self, msg):
459         if self.disabled('updates'):
460             return
461         self._update(msg)
462
463     def write(self, msg, option="misc"):
464         if self.disabled(option):
465             return
466         self._write(msg)
467
468     def _write(self, msg):
469         _log.info(msg)
470
471     def _update(self, msg):
472         if self._meter:
473             self._meter.update(msg)
474         else:
475             self._write(msg)