a9e015fceecb3c9ccb6f8e8c7f9e58b2d6d0988c
[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
303         This routine is used to print the details of each test as it completes.
304
305         Args:
306             result   - The actual TestResult object
307             expected - Whether the result we got was an expected result
308             exp_str  - What we expected to get (used for tracing)
309             got_str  - What we actually got (used for tracing)
310
311         Note that we need all of these arguments even though they seem
312         somewhat redundant, in order to keep this routine from having to
313         known anything about the set of expectations.
314         """
315         if (self.enabled('trace-everything') or
316             self.enabled('trace-unexpected') and not expected):
317             self._print_test_trace(result, exp_str, got_str)
318         elif (not expected and self.enabled('unexpected') and
319               self.disabled('detailed-progress')):
320             # Note: 'detailed-progress' handles unexpected results internally,
321             # so we skip it here.
322             self._print_unexpected_test_result(result)
323
324     def _print_test_trace(self, result, exp_str, got_str):
325         """Print detailed results of a test (triggered by --print trace-*).
326         For each test, print:
327            - location of the expected baselines
328            - expected results
329            - actual result
330            - timing info
331         """
332         filename = result.filename
333         test_name = self._port.relative_test_filename(filename)
334         self._write('trace: %s' % test_name)
335         self._write('  txt: %s' %
336                   self._port.relative_test_filename(
337                        self._port.expected_filename(filename, '.txt')))
338         png_file = self._port.expected_filename(filename, '.png')
339         if os.path.exists(png_file):
340             self._write('  png: %s' %
341                         self._port.relative_test_filename(png_file))
342         else:
343             self._write('  png: <none>')
344         self._write('  exp: %s' % exp_str)
345         self._write('  got: %s' % got_str)
346         self._write(' took: %-.3f' % result.test_run_time)
347         self._write('')
348
349     def _print_unexpected_test_result(self, result):
350         """Prints one unexpected test result line."""
351         desc = TestExpectationsFile.EXPECTATION_DESCRIPTIONS[result.type][0]
352         self.write("  %s -> unexpected %s" %
353                    (self._port.relative_test_filename(result.filename),
354                     desc), "unexpected")
355
356     def print_progress(self, result_summary, retrying, test_list):
357         """Print progress through the tests as determined by --print."""
358         if self.enabled('detailed-progress'):
359             self._print_detailed_progress(result_summary, test_list)
360         elif self.enabled('one-line-progress'):
361             self._print_one_line_progress(result_summary, retrying)
362         else:
363             return
364
365         if result_summary.remaining == 0:
366             self._meter.update('')
367
368     def _print_one_line_progress(self, result_summary, retrying):
369         """Displays the progress through the test run."""
370         percent_complete = 100 * (result_summary.expected +
371             result_summary.unexpected) / result_summary.total
372         action = "Testing"
373         if retrying:
374             action = "Retrying"
375         self._meter.progress("%s (%d%%): %d ran as expected, %d didn't,"
376             " %d left" % (action, percent_complete, result_summary.expected,
377              result_summary.unexpected, result_summary.remaining))
378
379     def _print_detailed_progress(self, result_summary, test_list):
380         """Display detailed progress output where we print the directory name
381         and one dot for each completed test. This is triggered by
382         "--log detailed-progress"."""
383         if self._current_test_number == len(test_list):
384             return
385
386         next_test = test_list[self._current_test_number]
387         next_dir = os.path.dirname(
388             self._port.relative_test_filename(next_test))
389         if self._current_progress_str == "":
390             self._current_progress_str = "%s: " % (next_dir)
391             self._current_dir = next_dir
392
393         while next_test in result_summary.results:
394             if next_dir != self._current_dir:
395                 self._meter.write("%s\n" % (self._current_progress_str))
396                 self._current_progress_str = "%s: ." % (next_dir)
397                 self._current_dir = next_dir
398             else:
399                 self._current_progress_str += "."
400
401             if (next_test in result_summary.unexpected_results and
402                 self.enabled('unexpected')):
403                 self._meter.write("%s\n" % self._current_progress_str)
404                 test_result = result_summary.results[next_test]
405                 self._print_unexpected_test_result(test_result)
406                 self._current_progress_str = "%s: " % self._current_dir
407
408             self._current_test_number += 1
409             if self._current_test_number == len(test_list):
410                 break
411
412             next_test = test_list[self._current_test_number]
413             next_dir = os.path.dirname(
414                 self._port.relative_test_filename(next_test))
415
416         if result_summary.remaining:
417             remain_str = " (%d)" % (result_summary.remaining)
418             self._meter.progress("%s%s" % (self._current_progress_str,
419                                            remain_str))
420         else:
421             self._meter.progress("%s" % (self._current_progress_str))
422
423     def print_unexpected_results(self, unexpected_results):
424         """Prints a list of the unexpected results to the buildbot stream."""
425         if self.disabled('unexpected-results'):
426             return
427
428         passes = {}
429         flaky = {}
430         regressions = {}
431
432         for test, results in unexpected_results['tests'].iteritems():
433             actual = results['actual'].split(" ")
434             expected = results['expected'].split(" ")
435             if actual == ['PASS']:
436                 if 'CRASH' in expected:
437                     _add_to_dict_of_lists(passes,
438                                           'Expected to crash, but passed',
439                                           test)
440                 elif 'TIMEOUT' in expected:
441                     _add_to_dict_of_lists(passes,
442                                           'Expected to timeout, but passed',
443                                            test)
444                 else:
445                     _add_to_dict_of_lists(passes,
446                                           'Expected to fail, but passed',
447                                           test)
448             elif len(actual) > 1:
449                 # We group flaky tests by the first actual result we got.
450                 _add_to_dict_of_lists(flaky, actual[0], test)
451             else:
452                 _add_to_dict_of_lists(regressions, results['actual'], test)
453
454         if len(passes) or len(flaky) or len(regressions):
455             self._buildbot_stream.write("\n")
456
457         if len(passes):
458             for key, tests in passes.iteritems():
459                 self._buildbot_stream.write("%s: (%d)\n" % (key, len(tests)))
460                 tests.sort()
461                 for test in tests:
462                     self._buildbot_stream.write("  %s\n" % test)
463                 self._buildbot_stream.write("\n")
464             self._buildbot_stream.write("\n")
465
466         if len(flaky):
467             descriptions = TestExpectationsFile.EXPECTATION_DESCRIPTIONS
468             for key, tests in flaky.iteritems():
469                 result = TestExpectationsFile.EXPECTATIONS[key.lower()]
470                 self._buildbot_stream.write("Unexpected flakiness: %s (%d)\n"
471                     % (descriptions[result][1], len(tests)))
472                 tests.sort()
473
474                 for test in tests:
475                     result = unexpected_results['tests'][test]
476                     actual = result['actual'].split(" ")
477                     expected = result['expected'].split(" ")
478                     result = TestExpectationsFile.EXPECTATIONS[key.lower()]
479                     new_expectations_list = list(set(actual) | set(expected))
480                     self._buildbot_stream.write("  %s = %s\n" %
481                         (test, " ".join(new_expectations_list)))
482                 self._buildbot_stream.write("\n")
483             self._buildbot_stream.write("\n")
484
485         if len(regressions):
486             descriptions = TestExpectationsFile.EXPECTATION_DESCRIPTIONS
487             for key, tests in regressions.iteritems():
488                 result = TestExpectationsFile.EXPECTATIONS[key.lower()]
489                 self._buildbot_stream.write(
490                     "Regressions: Unexpected %s : (%d)\n" % (
491                     descriptions[result][1], len(tests)))
492                 tests.sort()
493                 for test in tests:
494                     self._buildbot_stream.write("  %s = %s\n" % (test, key))
495                 self._buildbot_stream.write("\n")
496             self._buildbot_stream.write("\n")
497
498         if len(unexpected_results['tests']) and self._options.verbose:
499             self._buildbot_stream.write("%s\n" % ("-" * 78))
500
501     def print_update(self, msg):
502         if self.disabled('updates'):
503             return
504         self._meter.update(msg)
505
506     def write(self, msg, option="misc"):
507         if self.disabled(option):
508             return
509         self._write(msg)
510
511     def _write(self, msg):
512         # FIXME: we could probably get away with calling _log.info() all of
513         # the time, but there doesn't seem to be a good way to test the output
514         # from the logger :(.
515         if self._options.verbose:
516             _log.info(msg)
517         else:
518             self._meter.write("%s\n" % msg)
519
520 #
521 # Utility routines used by the Controller class
522 #
523
524
525 def _add_to_dict_of_lists(dict, key, value):
526     dict.setdefault(key, []).append(value)