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