2010-11-22 Dirk Pranke <dpranke@chromium.org>
[WebKit.git] / WebKitTools / Scripts / webkitpy / layout_tests / layout_package / 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 os
35 import pdb
36
37 from webkitpy.layout_tests.layout_package import metered_stream
38 from webkitpy.layout_tests.layout_package import test_expectations
39
40 _log = logging.getLogger("webkitpy.layout_tests.printer")
41
42 TestExpectationsFile = test_expectations.TestExpectationsFile
43
44 NUM_SLOW_TESTS_TO_LOG = 10
45
46 PRINT_DEFAULT = ("misc,one-line-progress,one-line-summary,unexpected,"
47                  "unexpected-results,updates")
48 PRINT_EVERYTHING = ("actual,config,expected,misc,one-line-progress,"
49                     "one-line-summary,slowest,timing,unexpected,"
50                     "unexpected-results,updates")
51
52 HELP_PRINTING = """
53 Output for run-webkit-tests is controlled by a comma-separated list of
54 values passed to --print.  Values either influence the overall output, or
55 the output at the beginning of the run, during the run, or at the end:
56
57 Overall options:
58     nothing             don't print anything. This overrides every other option
59     default             include the default options. This is useful for logging
60                         the default options plus additional settings.
61     everything          print everything (except the trace-* options and the
62                         detailed-progress option, see below for the full list )
63     misc                print miscellaneous things like blank lines
64
65 At the beginning of the run:
66     config              print the test run configuration
67     expected            print a summary of what is expected to happen
68                         (# passes, # failures, etc.)
69
70 During the run:
71     detailed-progress   print one dot per test completed
72     one-line-progress   print a one-line progress bar
73     unexpected          print any unexpected results as they occur
74     updates             print updates on which stage is executing
75     trace-everything    print detailed info on every test's results
76                         (baselines, expectation, time it took to run). If
77                         this is specified it will override the '*-progress'
78                         options, the 'trace-unexpected' option, and the
79                         'unexpected' option.
80     trace-unexpected    like 'trace-everything', but only for tests with
81                         unexpected results. If this option is specified,
82                         it will override the 'unexpected' option.
83
84 At the end of the run:
85     actual              print a summary of the actual results
86     slowest             print %(slowest)d slowest tests and the time they took
87     timing              print timing statistics
88     unexpected-results  print a list of the tests with unexpected results
89     one-line-summary    print a one-line summary of the run
90
91 Notes:
92     - 'detailed-progress' can only be used if running in a single thread
93       (using --child-processes=1) or a single queue of tests (using
94        --experimental-fully-parallel). If these conditions aren't true,
95       'one-line-progress' will be used instead.
96     - If both 'detailed-progress' and 'one-line-progress' are specified (and
97       both are possible), 'detailed-progress' will be used.
98     - If 'nothing' is specified, it overrides all of the other options.
99     - Specifying --verbose is equivalent to --print everything plus it
100       changes the format of the log messages to add timestamps and other
101       information. If you specify --verbose and --print X, then X overrides
102       the --print everything implied by --verbose.
103
104 --print 'everything' is equivalent to --print '%(everything)s'.
105
106 The default (--print default) is equivalent to --print '%(default)s'.
107 """ % {'slowest': NUM_SLOW_TESTS_TO_LOG, 'everything': PRINT_EVERYTHING,
108        'default': PRINT_DEFAULT}
109
110
111 def print_options():
112     return [
113         # Note: We use print_options rather than just 'print' because print
114         # is a reserved word.
115         # Note: Also, we don't specify a default value so we can detect when
116         # no flag is specified on the command line and use different defaults
117         # based on whether or not --verbose is specified (since --print
118         # overrides --verbose).
119         optparse.make_option("--print", dest="print_options",
120             help=("controls print output of test run. "
121                   "Use --help-printing for more.")),
122         optparse.make_option("--help-printing", action="store_true",
123             help="show detailed help on controlling print output"),
124         optparse.make_option("-v", "--verbose", action="store_true",
125             default=False, help="include debug-level logging"),
126     ]
127
128
129
130 def parse_print_options(print_options, verbose, child_processes,
131                         is_fully_parallel):
132     """Parse the options provided to --print and dedup and rank them.
133
134     Returns
135         a set() of switches that govern how logging is done
136
137     """
138     if print_options:
139         switches = set(print_options.split(','))
140     elif verbose:
141         switches = set(PRINT_EVERYTHING.split(','))
142     else:
143         switches = set(PRINT_DEFAULT.split(','))
144
145     if 'nothing' in switches:
146         return set()
147
148     if (child_processes != 1 and not is_fully_parallel and
149         'detailed-progress' in switches):
150         _log.warn("Can only print 'detailed-progress' if running "
151                   "with --child-processes=1 or "
152                   "with --experimental-fully-parallel. "
153                   "Using 'one-line-progress' instead.")
154         switches.discard('detailed-progress')
155         switches.add('one-line-progress')
156
157     if 'everything' in switches:
158         switches.discard('everything')
159         switches.update(set(PRINT_EVERYTHING.split(',')))
160
161     if 'default' in switches:
162         switches.discard('default')
163         switches.update(set(PRINT_DEFAULT.split(',')))
164
165     if 'detailed-progress' in switches:
166         switches.discard('one-line-progress')
167
168     if 'trace-everything' in switches:
169         switches.discard('detailed-progress')
170         switches.discard('one-line-progress')
171         switches.discard('trace-unexpected')
172         switches.discard('unexpected')
173
174     if 'trace-unexpected' in switches:
175         switches.discard('unexpected')
176
177     return switches
178
179
180 def _configure_logging(stream, verbose):
181     log_fmt = '%(message)s'
182     log_datefmt = '%y%m%d %H:%M:%S'
183     log_level = logging.INFO
184     if verbose:
185         log_fmt = ('%(asctime)s %(process)d %(filename)s:%(lineno)d '
186                    '%(levelname)s %(message)s')
187         log_level = logging.DEBUG
188
189     root = logging.getLogger()
190     handler = logging.StreamHandler(stream)
191     handler.setFormatter(logging.Formatter(log_fmt, None))
192     root.addHandler(handler)
193     root.setLevel(log_level)
194     return handler
195
196
197 def _restore_logging(handler_to_remove):
198     root = logging.getLogger()
199     root.handlers.remove(handler_to_remove)
200
201
202 class Printer(object):
203     """Class handling all non-debug-logging printing done by run-webkit-tests.
204
205     Printing from run-webkit-tests falls into two buckets: general or
206     regular output that is read only by humans and can be changed at any
207     time, and output that is parsed by buildbots (and humans) and hence
208     must be changed more carefully and in coordination with the buildbot
209     parsing code (in chromium.org's buildbot/master.chromium/scripts/master/
210     log_parser/webkit_test_command.py script).
211
212     By default the buildbot-parsed code gets logged to stdout, and regular
213     output gets logged to stderr."""
214     def __init__(self, port, options, regular_output, buildbot_output,
215                  child_processes, is_fully_parallel):
216         """
217         Args
218           port               interface to port-specific routines
219           options            OptionParser object with command line settings
220           regular_output     stream to which output intended only for humans
221                              should be written
222           buildbot_output    stream to which output intended to be read by
223                              the buildbots (and humans) should be written
224           child_processes    number of parallel threads running (usually
225                              controlled by --child-processes)
226           is_fully_parallel  are the tests running in a single queue, or
227                              in shards (usually controlled by
228                              --experimental-fully-parallel)
229
230         Note that the last two args are separate rather than bundled into
231         the options structure so that this object does not assume any flags
232         set in options that weren't returned from logging_options(), above.
233         The two are used to determine whether or not we can sensibly use
234         the 'detailed-progress' option, or can only use 'one-line-progress'.
235         """
236         self._buildbot_stream = buildbot_output
237         self._options = options
238         self._port = port
239         self._stream = regular_output
240
241         # These are used for --print detailed-progress to track status by
242         # directory.
243         self._current_dir = None
244         self._current_progress_str = ""
245         self._current_test_number = 0
246
247         self._meter = metered_stream.MeteredStream(options.verbose,
248                                                    regular_output)
249         self._logging_handler = _configure_logging(self._meter,
250             options.verbose)
251
252         self.switches = parse_print_options(options.print_options,
253             options.verbose, child_processes, is_fully_parallel)
254
255     def cleanup(self):
256         """Restore logging configuration to its initial settings."""
257         if self._logging_handler:
258             _restore_logging(self._logging_handler)
259             self._logging_handler = None
260
261     def __del__(self):
262         self.cleanup()
263
264     # These two routines just hide the implementation of the switches.
265     def disabled(self, option):
266         return not option in self.switches
267
268     def enabled(self, option):
269         return option in self.switches
270
271     def help_printing(self):
272         self._write(HELP_PRINTING)
273
274     def print_actual(self, msg):
275         if self.disabled('actual'):
276             return
277         self._buildbot_stream.write("%s\n" % msg)
278
279     def print_config(self, msg):
280         self.write(msg, 'config')
281
282     def print_expected(self, msg):
283         self.write(msg, 'expected')
284
285     def print_timing(self, msg):
286         self.write(msg, 'timing')
287
288     def print_one_line_summary(self, total, expected, unexpected):
289         """Print a one-line summary of the test run to stdout.
290
291         Args:
292           total: total number of tests run
293           expected: number of expected results
294           unexpected: number of unexpected results
295         """
296         if self.disabled('one-line-summary'):
297             return
298
299         incomplete = total - expected - unexpected
300         if incomplete:
301             self._write("")
302             incomplete_str = " (%d didn't run)" % incomplete
303             expected_str = str(expected)
304         else:
305             incomplete_str = ""
306             expected_str = "All %d" % expected
307
308         if unexpected == 0:
309             self._write("%s tests ran as expected%s." %
310                         (expected_str, incomplete_str))
311         elif expected == 1:
312             self._write("1 test ran as expected, %d didn't%s:" %
313                         (unexpected, incomplete_str))
314         else:
315             self._write("%d tests ran as expected, %d didn't%s:" %
316                         (expected, unexpected, incomplete_str))
317         self._write("")
318
319     def print_test_result(self, result, expected, exp_str, got_str):
320         """Print the result of the test as determined by --print.
321
322         This routine is used to print the details of each test as it completes.
323
324         Args:
325             result   - The actual TestResult object
326             expected - Whether the result we got was an expected result
327             exp_str  - What we expected to get (used for tracing)
328             got_str  - What we actually got (used for tracing)
329
330         Note that we need all of these arguments even though they seem
331         somewhat redundant, in order to keep this routine from having to
332         known anything about the set of expectations.
333         """
334         if (self.enabled('trace-everything') or
335             self.enabled('trace-unexpected') and not expected):
336             self._print_test_trace(result, exp_str, got_str)
337         elif (not expected and self.enabled('unexpected') and
338               self.disabled('detailed-progress')):
339             # Note: 'detailed-progress' handles unexpected results internally,
340             # so we skip it here.
341             self._print_unexpected_test_result(result)
342
343     def _print_test_trace(self, result, exp_str, got_str):
344         """Print detailed results of a test (triggered by --print trace-*).
345         For each test, print:
346            - location of the expected baselines
347            - expected results
348            - actual result
349            - timing info
350         """
351         filename = result.filename
352         test_name = self._port.relative_test_filename(filename)
353         self._write('trace: %s' % test_name)
354         txt_file = self._port.expected_filename(filename, '.txt')
355         if self._port.path_exists(txt_file):
356             self._write('  txt: %s' %
357                         self._port.relative_test_filename(txt_file))
358         else:
359             self._write('  txt: <none>')
360         checksum_file = self._port.expected_filename(filename, '.checksum')
361         if self._port.path_exists(checksum_file):
362             self._write('  sum: %s' %
363                         self._port.relative_test_filename(checksum_file))
364         else:
365             self._write('  sum: <none>')
366         png_file = self._port.expected_filename(filename, '.png')
367         if self._port.path_exists(png_file):
368             self._write('  png: %s' %
369                         self._port.relative_test_filename(png_file))
370         else:
371             self._write('  png: <none>')
372         self._write('  exp: %s' % exp_str)
373         self._write('  got: %s' % got_str)
374         self._write(' took: %-.3f' % result.test_run_time)
375         self._write('')
376
377     def _print_unexpected_test_result(self, result):
378         """Prints one unexpected test result line."""
379         desc = TestExpectationsFile.EXPECTATION_DESCRIPTIONS[result.type][0]
380         self.write("  %s -> unexpected %s" %
381                    (self._port.relative_test_filename(result.filename),
382                     desc), "unexpected")
383
384     def print_progress(self, result_summary, retrying, test_list):
385         """Print progress through the tests as determined by --print."""
386         if self.enabled('detailed-progress'):
387             self._print_detailed_progress(result_summary, test_list)
388         elif self.enabled('one-line-progress'):
389             self._print_one_line_progress(result_summary, retrying)
390         else:
391             return
392
393         if result_summary.remaining == 0:
394             self._meter.update('')
395
396     def _print_one_line_progress(self, result_summary, retrying):
397         """Displays the progress through the test run."""
398         percent_complete = 100 * (result_summary.expected +
399             result_summary.unexpected) / result_summary.total
400         action = "Testing"
401         if retrying:
402             action = "Retrying"
403         self._meter.progress("%s (%d%%): %d ran as expected, %d didn't,"
404             " %d left" % (action, percent_complete, result_summary.expected,
405              result_summary.unexpected, result_summary.remaining))
406
407     def _print_detailed_progress(self, result_summary, test_list):
408         """Display detailed progress output where we print the directory name
409         and one dot for each completed test. This is triggered by
410         "--log detailed-progress"."""
411         if self._current_test_number == len(test_list):
412             return
413
414         next_test = test_list[self._current_test_number]
415         next_dir = os.path.dirname(
416             self._port.relative_test_filename(next_test))
417         if self._current_progress_str == "":
418             self._current_progress_str = "%s: " % (next_dir)
419             self._current_dir = next_dir
420
421         while next_test in result_summary.results:
422             if next_dir != self._current_dir:
423                 self._meter.write("%s\n" % (self._current_progress_str))
424                 self._current_progress_str = "%s: ." % (next_dir)
425                 self._current_dir = next_dir
426             else:
427                 self._current_progress_str += "."
428
429             if (next_test in result_summary.unexpected_results and
430                 self.enabled('unexpected')):
431                 self._meter.write("%s\n" % self._current_progress_str)
432                 test_result = result_summary.results[next_test]
433                 self._print_unexpected_test_result(test_result)
434                 self._current_progress_str = "%s: " % self._current_dir
435
436             self._current_test_number += 1
437             if self._current_test_number == len(test_list):
438                 break
439
440             next_test = test_list[self._current_test_number]
441             next_dir = os.path.dirname(
442                 self._port.relative_test_filename(next_test))
443
444         if result_summary.remaining:
445             remain_str = " (%d)" % (result_summary.remaining)
446             self._meter.progress("%s%s" % (self._current_progress_str,
447                                            remain_str))
448         else:
449             self._meter.progress("%s" % (self._current_progress_str))
450
451     def print_unexpected_results(self, unexpected_results):
452         """Prints a list of the unexpected results to the buildbot stream."""
453         if self.disabled('unexpected-results'):
454             return
455
456         passes = {}
457         flaky = {}
458         regressions = {}
459
460         for test, results in unexpected_results['tests'].iteritems():
461             actual = results['actual'].split(" ")
462             expected = results['expected'].split(" ")
463             if actual == ['PASS']:
464                 if 'CRASH' in expected:
465                     _add_to_dict_of_lists(passes,
466                                           'Expected to crash, but passed',
467                                           test)
468                 elif 'TIMEOUT' in expected:
469                     _add_to_dict_of_lists(passes,
470                                           'Expected to timeout, but passed',
471                                            test)
472                 else:
473                     _add_to_dict_of_lists(passes,
474                                           'Expected to fail, but passed',
475                                           test)
476             elif len(actual) > 1:
477                 # We group flaky tests by the first actual result we got.
478                 _add_to_dict_of_lists(flaky, actual[0], test)
479             else:
480                 _add_to_dict_of_lists(regressions, results['actual'], test)
481
482         if len(passes) or len(flaky) or len(regressions):
483             self._buildbot_stream.write("\n")
484
485         if len(passes):
486             for key, tests in passes.iteritems():
487                 self._buildbot_stream.write("%s: (%d)\n" % (key, len(tests)))
488                 tests.sort()
489                 for test in tests:
490                     self._buildbot_stream.write("  %s\n" % test)
491                 self._buildbot_stream.write("\n")
492             self._buildbot_stream.write("\n")
493
494         if len(flaky):
495             descriptions = TestExpectationsFile.EXPECTATION_DESCRIPTIONS
496             for key, tests in flaky.iteritems():
497                 result = TestExpectationsFile.EXPECTATIONS[key.lower()]
498                 self._buildbot_stream.write("Unexpected flakiness: %s (%d)\n"
499                     % (descriptions[result][1], len(tests)))
500                 tests.sort()
501
502                 for test in tests:
503                     result = unexpected_results['tests'][test]
504                     actual = result['actual'].split(" ")
505                     expected = result['expected'].split(" ")
506                     result = TestExpectationsFile.EXPECTATIONS[key.lower()]
507                     new_expectations_list = list(set(actual) | set(expected))
508                     self._buildbot_stream.write("  %s = %s\n" %
509                         (test, " ".join(new_expectations_list)))
510                 self._buildbot_stream.write("\n")
511             self._buildbot_stream.write("\n")
512
513         if len(regressions):
514             descriptions = TestExpectationsFile.EXPECTATION_DESCRIPTIONS
515             for key, tests in regressions.iteritems():
516                 result = TestExpectationsFile.EXPECTATIONS[key.lower()]
517                 self._buildbot_stream.write(
518                     "Regressions: Unexpected %s : (%d)\n" % (
519                     descriptions[result][1], len(tests)))
520                 tests.sort()
521                 for test in tests:
522                     self._buildbot_stream.write("  %s = %s\n" % (test, key))
523                 self._buildbot_stream.write("\n")
524             self._buildbot_stream.write("\n")
525
526         if len(unexpected_results['tests']) and self._options.verbose:
527             self._buildbot_stream.write("%s\n" % ("-" * 78))
528
529     def print_update(self, msg):
530         if self.disabled('updates'):
531             return
532         self._meter.update(msg)
533
534     def write(self, msg, option="misc"):
535         if self.disabled(option):
536             return
537         self._write(msg)
538
539     def _write(self, msg):
540         # FIXME: we could probably get away with calling _log.info() all of
541         # the time, but there doesn't seem to be a good way to test the output
542         # from the logger :(.
543         if self._options.verbose:
544             _log.info(msg)
545         else:
546             self._meter.write("%s\n" % msg)
547
548 #
549 # Utility routines used by the Controller class
550 #
551
552
553 def _add_to_dict_of_lists(dict, key, value):
554     dict.setdefault(key, []).append(value)