clean up NRWT logging/metering, be less verbose
[WebKit-https.git] / Tools / Scripts / webkitpy / layout_tests / views / printing.py
1 #!/usr/bin/env python
2 # Copyright (C) 2010, 2012 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 optparse
33
34 from webkitpy.common.net import resultsjsonparser
35 from webkitpy.layout_tests.models.test_expectations import TestExpectations
36 from webkitpy.layout_tests.views.metered_stream import MeteredStream
37
38 NUM_SLOW_TESTS_TO_LOG = 10
39
40 PRINT_DEFAULT = "misc,one-line-progress,one-line-summary,unexpected,unexpected-results,updates"
41 PRINT_EVERYTHING = "actual,config,expected,misc,one-line-progress,one-line-summary,slowest,timing,unexpected,unexpected-results,updates"
42
43 HELP_PRINTING = """
44 Output for run-webkit-tests is controlled by a comma-separated list of
45 values passed to --print.  Values either influence the overall output, or
46 the output at the beginning of the run, during the run, or at the end:
47
48 Overall options:
49     nothing             don't print anything. This overrides every other option
50     default             include the default options. This is useful for logging
51                         the default options plus additional settings.
52     everything          print (almost) everything (except the trace-* options,
53                         see below for the full list )
54     misc                print miscellaneous things like blank lines
55
56 At the beginning of the run:
57     config              print the test run configuration
58     expected            print a summary of what is expected to happen
59                         (# passes, # failures, etc.)
60
61 During the run:
62     one-line-progress   print a one-line progress message or bar
63     unexpected          print any unexpected results as they occur
64     updates             print updates on which stage is executing
65     trace-everything    print detailed info on every test's results
66                         (baselines, expectation, time it took to run). If
67                         this is specified it will override the '*-progress'
68                         options, the 'trace-unexpected' option, and the
69                         'unexpected' option.
70     trace-unexpected    like 'trace-everything', but only for tests with
71                         unexpected results. If this option is specified,
72                         it will override the 'unexpected' option.
73
74 At the end of the run:
75     actual              print a summary of the actual results
76     slowest             print %(slowest)d slowest tests and the time they took
77     timing              print timing statistics
78     unexpected-results  print a list of the tests with unexpected results
79     one-line-summary    print a one-line summary of the run
80
81 Notes:
82     - If 'nothing' is specified, it overrides all of the other options.
83     - Specifying --verbose is equivalent to --print everything plus it
84       changes the format of the log messages to add timestamps and other
85       information. If you specify --verbose and --print X, then X overrides
86       the --print everything implied by --verbose.
87
88 --print 'everything' is equivalent to --print '%(everything)s'.
89
90 The default (--print default) is equivalent to --print '%(default)s'.
91 """ % {'slowest': NUM_SLOW_TESTS_TO_LOG, 'everything': PRINT_EVERYTHING,
92        'default': PRINT_DEFAULT}
93
94
95 def print_options():
96     return [
97         # Note: We use print_options rather than just 'print' because print
98         # is a reserved word.
99         # Note: Also, we don't specify a default value so we can detect when
100         # no flag is specified on the command line and use different defaults
101         # based on whether or not --verbose is specified (since --print
102         # overrides --verbose).
103         optparse.make_option("--print", dest="print_options",
104             help=("controls print output of test run. "
105                   "Use --help-printing for more.")),
106         optparse.make_option("--help-printing", action="store_true",
107             help="show detailed help on controlling print output"),
108         optparse.make_option("-v", "--verbose", action="store_true",
109             default=False, help="include debug-level logging"),
110    ]
111
112
113 def parse_print_options(print_options, verbose):
114     """Parse the options provided to --print and dedup and rank them.
115
116     Returns
117         a set() of switches that govern how logging is done
118
119     """
120     if print_options:
121         switches = set(print_options.split(','))
122     elif verbose:
123         switches = set(PRINT_EVERYTHING.split(','))
124     else:
125         switches = set(PRINT_DEFAULT.split(','))
126
127     if 'nothing' in switches:
128         return set()
129
130     if 'everything' in switches:
131         switches.discard('everything')
132         switches.update(set(PRINT_EVERYTHING.split(',')))
133
134     if 'default' in switches:
135         switches.discard('default')
136         switches.update(set(PRINT_DEFAULT.split(',')))
137
138     if 'trace-everything' in switches:
139         switches.discard('one-line-progress')
140         switches.discard('trace-unexpected')
141         switches.discard('unexpected')
142
143     if 'trace-unexpected' in switches:
144         switches.discard('unexpected')
145
146     return switches
147
148
149 class Printer(object):
150     """Class handling all non-debug-logging printing done by run-webkit-tests.
151
152     Printing from run-webkit-tests falls into two buckets: general or
153     regular output that is read only by humans and can be changed at any
154     time, and output that is parsed by buildbots (and humans) and hence
155     must be changed more carefully and in coordination with the buildbot
156     parsing code (in chromium.org's buildbot/master.chromium/scripts/master/
157     log_parser/webkit_test_command.py script).
158
159     By default the buildbot-parsed code gets logged to stdout, and regular
160     output gets logged to stderr."""
161     def __init__(self, port, options, regular_output, buildbot_output, logger=None):
162         """
163         Args
164           port               interface to port-specific routines
165           options            OptionParser object with command line settings
166           regular_output     stream to which output intended only for humans
167                              should be written
168           buildbot_output    stream to which output intended to be read by
169                              the buildbots (and humans) should be written
170           logger             optional logger to integrate into the stream.
171         """
172         self._port = port
173         self._options = options
174         self._buildbot_stream = buildbot_output
175         self._meter = MeteredStream(regular_output, options.verbose, logger=logger)
176         self.switches = parse_print_options(options.print_options, options.verbose)
177
178     def cleanup(self):
179         self._meter.cleanup()
180
181     def __del__(self):
182         self.cleanup()
183
184     # These two routines just hide the implementation of the switches.
185     def disabled(self, option):
186         return not option in self.switches
187
188     def enabled(self, option):
189         return option in self.switches
190
191     def help_printing(self):
192         self._write(HELP_PRINTING)
193
194     def print_actual(self, msg):
195         if self.disabled('actual'):
196             return
197         self._buildbot_stream.write("%s\n" % msg)
198
199     def print_config(self, msg):
200         self.write(msg, 'config')
201
202     def print_expected(self, msg):
203         self.write(msg, 'expected')
204
205     def print_timing(self, msg):
206         self.write(msg, 'timing')
207
208     def print_one_line_summary(self, total, expected, unexpected):
209         """Print a one-line summary of the test run to stdout.
210
211         Args:
212           total: total number of tests run
213           expected: number of expected results
214           unexpected: number of unexpected results
215         """
216         if self.disabled('one-line-summary'):
217             return
218
219         incomplete = total - expected - unexpected
220         if incomplete:
221             self._write("")
222             incomplete_str = " (%d didn't run)" % incomplete
223             expected_str = str(expected)
224         else:
225             incomplete_str = ""
226             expected_str = "All %d" % expected
227
228         if unexpected == 0:
229             self._write("%s tests ran as expected%s." %
230                         (expected_str, incomplete_str))
231         elif expected == 1:
232             self._write("1 test ran as expected, %d didn't%s:" %
233                         (unexpected, incomplete_str))
234         else:
235             self._write("%d tests ran as expected, %d didn't%s:" %
236                         (expected, unexpected, incomplete_str))
237         self._write("")
238
239     def print_test_result(self, result, expected, exp_str, got_str):
240         """Print the result of the test as determined by --print.
241
242         This routine is used to print the details of each test as it completes.
243
244         Args:
245             result   - The actual TestResult object
246             expected - Whether the result we got was an expected result
247             exp_str  - What we expected to get (used for tracing)
248             got_str  - What we actually got (used for tracing)
249
250         Note that we need all of these arguments even though they seem
251         somewhat redundant, in order to keep this routine from having to
252         known anything about the set of expectations.
253         """
254         if (self.enabled('trace-everything') or
255             self.enabled('trace-unexpected') and not expected):
256             self._print_test_trace(result, exp_str, got_str)
257         elif not expected and self.enabled('unexpected'):
258             self._print_unexpected_test_result(result)
259
260     def _print_test_trace(self, result, exp_str, got_str):
261         """Print detailed results of a test (triggered by --print trace-*).
262         For each test, print:
263            - location of the expected baselines
264            - expected results
265            - actual result
266            - timing info
267         """
268         test_name = result.test_name
269         self._write('trace: %s' % test_name)
270
271         base = self._port.lookup_virtual_test_base(test_name)
272         if base:
273             args = ' '.join(self._port.lookup_virtual_test_args(test_name))
274             self._write(' base: %s' % base)
275             self._write(' args: %s' % args)
276
277         for extension in ('.txt', '.png', '.wav', '.webarchive'):
278             self._print_baseline(test_name, extension)
279
280         self._write('  exp: %s' % exp_str)
281         self._write('  got: %s' % got_str)
282         self._write(' took: %-.3f' % result.test_run_time)
283         self._write('')
284
285     def _print_baseline(self, test_name, extension):
286         baseline = self._port.expected_filename(test_name, extension)
287         if self._port._filesystem.exists(baseline):
288             relpath = self._port.relative_test_filename(baseline)
289         else:
290             relpath = '<none>'
291         self._write('  %s: %s' % (extension[1:], relpath))
292
293     def _print_unexpected_test_result(self, result):
294         """Prints one unexpected test result line."""
295         desc = TestExpectations.EXPECTATION_DESCRIPTIONS[result.type][0]
296         self.write("  %s -> unexpected %s" % (result.test_name, desc), "unexpected")
297
298     def print_progress(self, result_summary, retrying, test_list):
299         """Print progress through the tests as determined by --print."""
300         if self.disabled('one-line-progress'):
301             return
302
303         if result_summary.remaining == 0:
304             self._meter.write_update('')
305             return
306
307         percent_complete = 100 * (result_summary.expected +
308             result_summary.unexpected) / result_summary.total
309         action = "Testing"
310         if retrying:
311             action = "Retrying"
312
313         self._meter.write_throttled_update("%s (%d%%): %d ran as expected, %d didn't, %d left" %
314             (action, percent_complete, result_summary.expected,
315              result_summary.unexpected, result_summary.remaining))
316
317     def print_unexpected_results(self, unexpected_results):
318         """Prints a list of the unexpected results to the buildbot stream."""
319         if self.disabled('unexpected-results'):
320             return
321
322         passes = {}
323         flaky = {}
324         regressions = {}
325
326         def add_to_dict_of_lists(dict, key, value):
327             dict.setdefault(key, []).append(value)
328
329         def add_result(test, results, passes=passes, flaky=flaky, regressions=regressions):
330             actual = results['actual'].split(" ")
331             expected = results['expected'].split(" ")
332             if actual == ['PASS']:
333                 if 'CRASH' in expected:
334                     add_to_dict_of_lists(passes,
335                                          'Expected to crash, but passed',
336                                          test)
337                 elif 'TIMEOUT' in expected:
338                     add_to_dict_of_lists(passes,
339                                          'Expected to timeout, but passed',
340                                           test)
341                 else:
342                     add_to_dict_of_lists(passes,
343                                          'Expected to fail, but passed',
344                                          test)
345             elif len(actual) > 1:
346                 # We group flaky tests by the first actual result we got.
347                 add_to_dict_of_lists(flaky, actual[0], test)
348             else:
349                 add_to_dict_of_lists(regressions, results['actual'], test)
350
351         resultsjsonparser.for_each_test(unexpected_results['tests'], add_result)
352
353         if len(passes) or len(flaky) or len(regressions):
354             self._buildbot_stream.write("\n")
355
356         if len(passes):
357             for key, tests in passes.iteritems():
358                 self._buildbot_stream.write("%s: (%d)\n" % (key, len(tests)))
359                 tests.sort()
360                 for test in tests:
361                     self._buildbot_stream.write("  %s\n" % test)
362                 self._buildbot_stream.write("\n")
363             self._buildbot_stream.write("\n")
364
365         if len(flaky):
366             descriptions = TestExpectations.EXPECTATION_DESCRIPTIONS
367             for key, tests in flaky.iteritems():
368                 result = TestExpectations.EXPECTATIONS[key.lower()]
369                 self._buildbot_stream.write("Unexpected flakiness: %s (%d)\n"
370                     % (descriptions[result][1], len(tests)))
371                 tests.sort()
372
373                 for test in tests:
374                     result = resultsjsonparser.result_for_test(unexpected_results['tests'], test)
375                     actual = result['actual'].split(" ")
376                     expected = result['expected'].split(" ")
377                     result = TestExpectations.EXPECTATIONS[key.lower()]
378                     new_expectations_list = list(set(actual) | set(expected))
379                     self._buildbot_stream.write("  %s = %s\n" %
380                         (test, " ".join(new_expectations_list)))
381                 self._buildbot_stream.write("\n")
382             self._buildbot_stream.write("\n")
383
384         if len(regressions):
385             descriptions = TestExpectations.EXPECTATION_DESCRIPTIONS
386             for key, tests in regressions.iteritems():
387                 result = TestExpectations.EXPECTATIONS[key.lower()]
388                 self._buildbot_stream.write(
389                     "Regressions: Unexpected %s : (%d)\n" % (
390                     descriptions[result][1], len(tests)))
391                 tests.sort()
392                 for test in tests:
393                     self._buildbot_stream.write("  %s = %s\n" % (test, key))
394                 self._buildbot_stream.write("\n")
395             self._buildbot_stream.write("\n")
396
397         if len(unexpected_results['tests']) and self._options.verbose:
398             self._buildbot_stream.write("%s\n" % ("-" * 78))
399
400     def print_update(self, msg):
401         if self.disabled('updates'):
402             return
403         self._meter.write_update(msg)
404
405     def write(self, msg, option="misc"):
406         if self.disabled(option):
407             return
408         self._write(msg)
409
410     def _write(self, msg):
411         self._meter.writeln(msg)