81cdc9b67ba555302023965389f4f0bab48a0aad
[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 def configure_logging(options, meter):
130     """Configures the logging system."""
131     log_fmt = '%(message)s'
132     log_datefmt = '%y%m%d %H:%M:%S'
133     log_level = logging.INFO
134     if options.verbose:
135         log_fmt = ('%(asctime)s %(filename)s:%(lineno)-4d %(levelname)s '
136                    '%(message)s')
137         log_level = logging.DEBUG
138
139     logging.basicConfig(level=log_level, format=log_fmt,
140                         datefmt=log_datefmt, stream=meter)
141
142
143 def parse_print_options(print_options, verbose, child_processes,
144                         is_fully_parallel):
145     """Parse the options provided to --print and dedup and rank them.
146
147     Returns
148         a set() of switches that govern how logging is done
149
150     """
151     if print_options:
152         switches = set(print_options.split(','))
153     elif verbose:
154         switches = set(PRINT_EVERYTHING.split(','))
155     else:
156         switches = set(PRINT_DEFAULT.split(','))
157
158     if 'nothing' in switches:
159         return set()
160
161     if (child_processes != 1 and not is_fully_parallel and
162         'detailed-progress' in switches):
163         _log.warn("Can only print 'detailed-progress' if running "
164                   "with --child-processes=1 or "
165                   "with --experimental-fully-parallel. "
166                   "Using 'one-line-progress' instead.")
167         switches.discard('detailed-progress')
168         switches.add('one-line-progress')
169
170     if 'everything' in switches:
171         switches.discard('everything')
172         switches.update(set(PRINT_EVERYTHING.split(',')))
173
174     if 'default' in switches:
175         switches.discard('default')
176         switches.update(set(PRINT_DEFAULT.split(',')))
177
178     if 'detailed-progress' in switches:
179         switches.discard('one-line-progress')
180
181     if 'trace-everything' in switches:
182         switches.discard('detailed-progress')
183         switches.discard('one-line-progress')
184         switches.discard('trace-unexpected')
185         switches.discard('unexpected')
186
187     if 'trace-unexpected' in switches:
188         switches.discard('unexpected')
189
190     return switches
191
192
193 class Printer(object):
194     """Class handling all non-debug-logging printing done by run-webkit-tests.
195
196     Printing from run-webkit-tests falls into two buckets: general or
197     regular output that is read only by humans and can be changed at any
198     time, and output that is parsed by buildbots (and humans) and hence
199     must be changed more carefully and in coordination with the buildbot
200     parsing code (in chromium.org's buildbot/master.chromium/scripts/master/
201     log_parser/webkit_test_command.py script).
202
203     By default the buildbot-parsed code gets logged to stdout, and regular
204     output gets logged to stderr."""
205     def __init__(self, port, options, regular_output, buildbot_output,
206                  child_processes, is_fully_parallel):
207         """
208         Args
209           port               interface to port-specific routines
210           options            OptionParser object with command line settings
211           regular_output     stream to which output intended only for humans
212                              should be written
213           buildbot_output    stream to which output intended to be read by
214                              the buildbots (and humans) should be written
215           child_processes    number of parallel threads running (usually
216                              controlled by --child-processes)
217           is_fully_parallel  are the tests running in a single queue, or
218                              in shards (usually controlled by
219                              --experimental-fully-parallel)
220
221         Note that the last two args are separate rather than bundled into
222         the options structure so that this object does not assume any flags
223         set in options that weren't returned from logging_options(), above.
224         The two are used to determine whether or not we can sensibly use
225         the 'detailed-progress' option, or can only use 'one-line-progress'.
226         """
227         self._buildbot_stream = buildbot_output
228         self._options = options
229         self._port = port
230         self._stream = regular_output
231
232         # These are used for --print detailed-progress to track status by
233         # directory.
234         self._current_dir = None
235         self._current_progress_str = ""
236         self._current_test_number = 0
237
238         self._meter = metered_stream.MeteredStream(options.verbose,
239                                                    regular_output)
240         configure_logging(self._options, self._meter)
241
242         self.switches = parse_print_options(options.print_options,
243             options.verbose, child_processes, is_fully_parallel)
244
245     # These two routines just hide the implmentation of the switches.
246     def disabled(self, option):
247         return not option in self.switches
248
249     def enabled(self, option):
250         return option in self.switches
251
252     def help_printing(self):
253         self._write(HELP_PRINTING)
254
255     def print_actual(self, msg):
256         if self.disabled('actual'):
257             return
258         self._buildbot_stream.write("%s\n" % msg)
259
260     def print_config(self, msg):
261         self.write(msg, 'config')
262
263     def print_expected(self, msg):
264         self.write(msg, 'expected')
265
266     def print_timing(self, msg):
267         self.write(msg, 'timing')
268
269     def print_one_line_summary(self, total, expected, unexpected):
270         """Print a one-line summary of the test run to stdout.
271
272         Args:
273           total: total number of tests run
274           expected: number of expected results
275           unexpected: number of unexpected results
276         """
277         if self.disabled('one-line-summary'):
278             return
279
280         incomplete = total - expected - unexpected
281         if incomplete:
282             self._write("")
283             incomplete_str = " (%d didn't run)" % incomplete
284             expected_str = str(expected)
285         else:
286             incomplete_str = ""
287             expected_str = "All %d" % expected
288
289         if unexpected == 0:
290             self._write("%s tests ran as expected%s." %
291                         (expected_str, incomplete_str))
292         elif expected == 1:
293             self._write("1 test ran as expected, %d didn't%s:" %
294                         (unexpected, incomplete_str))
295         else:
296             self._write("%d tests ran as expected, %d didn't%s:" %
297                         (expected, unexpected, incomplete_str))
298         self._write("")
299
300     def print_test_result(self, result, expected, exp_str, got_str):
301         """Print the result of the test as determined by --print."""
302         if (self.enabled('trace-everything') or
303             self.enabled('trace-unexpected') and not expected):
304             self._print_test_trace(result, exp_str, got_str)
305         elif (not expected and self.enabled('unexpected') and
306               self.disabled('detailed-progress')):
307             # Note: 'detailed-progress' handles unexpected results internally,
308             # so we skip it here.
309             self._print_unexpected_test_result(result)
310
311     def _print_test_trace(self, result, exp_str, got_str):
312         """Print detailed results of a test (triggered by --print trace-*).
313         For each test, print:
314            - location of the expected baselines
315            - expected results
316            - actual result
317            - timing info
318         """
319         filename = result.filename
320         test_name = self._port.relative_test_filename(filename)
321         self._write('trace: %s' % test_name)
322         self._write('  txt: %s' %
323                   self._port.relative_test_filename(
324                        self._port.expected_filename(filename, '.txt')))
325         png_file = self._port.expected_filename(filename, '.png')
326         if os.path.exists(png_file):
327             self._write('  png: %s' %
328                         self._port.relative_test_filename(png_file))
329         else:
330             self._write('  png: <none>')
331         self._write('  exp: %s' % exp_str)
332         self._write('  got: %s' % got_str)
333         self._write(' took: %-.3f' % result.test_run_time)
334         self._write('')
335
336     def _print_unexpected_test_result(self, result):
337         """Prints one unexpected test result line."""
338         desc = TestExpectationsFile.EXPECTATION_DESCRIPTIONS[result.type][0]
339         self.write("  %s -> unexpected %s" %
340                    (self._port.relative_test_filename(result.filename),
341                     desc), "unexpected")
342
343     def print_progress(self, result_summary, retrying, test_list):
344         """Print progress through the tests as determined by --print."""
345         if self.enabled('detailed-progress'):
346             self._print_detailed_progress(result_summary, test_list)
347         elif self.enabled('one-line-progress'):
348             self._print_one_line_progress(result_summary, retrying)
349         else:
350             return
351
352         if result_summary.remaining == 0:
353             self._meter.update('')
354
355     def _print_one_line_progress(self, result_summary, retrying):
356         """Displays the progress through the test run."""
357         percent_complete = 100 * (result_summary.expected +
358             result_summary.unexpected) / result_summary.total
359         action = "Testing"
360         if retrying:
361             action = "Retrying"
362         self._meter.progress("%s (%d%%): %d ran as expected, %d didn't,"
363             " %d left" % (action, percent_complete, result_summary.expected,
364              result_summary.unexpected, result_summary.remaining))
365
366     def _print_detailed_progress(self, result_summary, test_list):
367         """Display detailed progress output where we print the directory name
368         and one dot for each completed test. This is triggered by
369         "--log detailed-progress"."""
370         if self._current_test_number == len(test_list):
371             return
372
373         next_test = test_list[self._current_test_number]
374         next_dir = os.path.dirname(
375             self._port.relative_test_filename(next_test))
376         if self._current_progress_str == "":
377             self._current_progress_str = "%s: " % (next_dir)
378             self._current_dir = next_dir
379
380         while next_test in result_summary.results:
381             if next_dir != self._current_dir:
382                 self._meter.write("%s\n" % (self._current_progress_str))
383                 self._current_progress_str = "%s: ." % (next_dir)
384                 self._current_dir = next_dir
385             else:
386                 self._current_progress_str += "."
387
388             if (next_test in result_summary.unexpected_results and
389                 self.enabled('unexpected')):
390                 self._meter.write("%s\n" % self._current_progress_str)
391                 test_result = result_summary.results[next_test]
392                 self._print_unexpected_test_result(test_result)
393                 self._current_progress_str = "%s: " % self._current_dir
394
395             self._current_test_number += 1
396             if self._current_test_number == len(test_list):
397                 break
398
399             next_test = test_list[self._current_test_number]
400             next_dir = os.path.dirname(
401                 self._port.relative_test_filename(next_test))
402
403         if result_summary.remaining:
404             remain_str = " (%d)" % (result_summary.remaining)
405             self._meter.progress("%s%s" % (self._current_progress_str,
406                                            remain_str))
407         else:
408             self._meter.progress("%s" % (self._current_progress_str))
409
410     def print_unexpected_results(self, unexpected_results):
411         """Prints a list of the unexpected results to the buildbot stream."""
412         if self.disabled('unexpected-results'):
413             return
414
415         passes = {}
416         flaky = {}
417         regressions = {}
418
419         for test, results in unexpected_results['tests'].iteritems():
420             actual = results['actual'].split(" ")
421             expected = results['expected'].split(" ")
422             if actual == ['PASS']:
423                 if 'CRASH' in expected:
424                     _add_to_dict_of_lists(passes,
425                                           'Expected to crash, but passed',
426                                           test)
427                 elif 'TIMEOUT' in expected:
428                     _add_to_dict_of_lists(passes,
429                                           'Expected to timeout, but passed',
430                                            test)
431                 else:
432                     _add_to_dict_of_lists(passes,
433                                           'Expected to fail, but passed',
434                                           test)
435             elif len(actual) > 1:
436                 # We group flaky tests by the first actual result we got.
437                 _add_to_dict_of_lists(flaky, actual[0], test)
438             else:
439                 _add_to_dict_of_lists(regressions, results['actual'], test)
440
441         if len(passes) or len(flaky) or len(regressions):
442             self._buildbot_stream.write("\n")
443
444         if len(passes):
445             for key, tests in passes.iteritems():
446                 self._buildbot_stream.write("%s: (%d)\n" % (key, len(tests)))
447                 tests.sort()
448                 for test in tests:
449                     self._buildbot_stream.write("  %s\n" % test)
450                 self._buildbot_stream.write("\n")
451             self._buildbot_stream.write("\n")
452
453         if len(flaky):
454             descriptions = TestExpectationsFile.EXPECTATION_DESCRIPTIONS
455             for key, tests in flaky.iteritems():
456                 result = TestExpectationsFile.EXPECTATIONS[key.lower()]
457                 self._buildbot_stream.write("Unexpected flakiness: %s (%d)\n"
458                     % (descriptions[result][1], len(tests)))
459                 tests.sort()
460
461                 for test in tests:
462                     result = unexpected_results['tests'][test]
463                     actual = result['actual'].split(" ")
464                     expected = result['expected'].split(" ")
465                     result = TestExpectationsFile.EXPECTATIONS[key.lower()]
466                     new_expectations_list = list(set(actual) | set(expected))
467                     self._buildbot_stream.write("  %s = %s\n" %
468                         (test, " ".join(new_expectations_list)))
469                 self._buildbot_stream.write("\n")
470             self._buildbot_stream.write("\n")
471
472         if len(regressions):
473             descriptions = TestExpectationsFile.EXPECTATION_DESCRIPTIONS
474             for key, tests in regressions.iteritems():
475                 result = TestExpectationsFile.EXPECTATIONS[key.lower()]
476                 self._buildbot_stream.write(
477                     "Regressions: Unexpected %s : (%d)\n" % (
478                     descriptions[result][1], len(tests)))
479                 tests.sort()
480                 for test in tests:
481                     self._buildbot_stream.write("  %s = %s\n" % (test, key))
482                 self._buildbot_stream.write("\n")
483             self._buildbot_stream.write("\n")
484
485         if len(unexpected_results['tests']) and self._options.verbose:
486             self._buildbot_stream.write("%s\n" % ("-" * 78))
487
488     def print_update(self, msg):
489         if self.disabled('updates'):
490             return
491         self._meter.update(msg)
492
493     def write(self, msg, option="misc"):
494         if self.disabled(option):
495             return
496         self._write(msg)
497
498     def _write(self, msg):
499         # FIXME: we could probably get away with calling _log.info() all of
500         # the time, but there doesn't seem to be a good way to test the output
501         # from the logger :(.
502         if self._options.verbose:
503             _log.info(msg)
504         else:
505             self._meter.write("%s\n" % msg)
506
507 #
508 # Utility routines used by the Controller class
509 #
510
511
512 def _add_to_dict_of_lists(dict, key, value):
513     dict.setdefault(key, []).append(value)