results.py (17486B)
1 import json 2 import re 3 import shlex 4 5 from .progressbar import NullProgressBar, ProgressBar 6 from .structuredlog import TestLogger 7 8 # subprocess.list2cmdline does not properly escape for sh-like shells 9 10 11 def escape_cmdline(args): 12 return " ".join([shlex.quote(a) for a in args]) 13 14 15 class TestOutput: 16 """Output from a test run.""" 17 18 def __init__(self, test, cmd, out, err, rc, dt, timed_out, extra=None): 19 self.test = test # Test 20 self.cmd = cmd # str: command line of test 21 self.out = out # str: stdout 22 self.err = err # str: stderr 23 self.rc = rc # int: return code 24 self.dt = dt # float: run time 25 self.timed_out = timed_out # bool: did the test time out 26 self.extra = extra # includes the pid on some platforms 27 28 def describe_failure(self): 29 if self.timed_out: 30 return "Timeout" 31 lines = self.err.splitlines() 32 for line in lines: 33 # Skip the asm.js compilation success message. 34 if "Successfully compiled asm.js code" not in line: 35 return line 36 return "Unknown" 37 38 39 class NullTestOutput: 40 """Variant of TestOutput that indicates a test was not run.""" 41 42 def __init__(self, test): 43 self.test = test 44 self.cmd = "" 45 self.out = "" 46 self.err = "" 47 self.rc = 0 48 self.dt = 0.0 49 self.timed_out = False 50 51 52 class TestResult: 53 PASS = "PASS" 54 FAIL = "FAIL" 55 CRASH = "CRASH" 56 57 """Classified result from a test run.""" 58 59 def __init__(self, test, result, results, wpt_results=None): 60 self.test = test 61 self.result = result 62 self.results = results 63 self.wpt_results = wpt_results # Only used for wpt tests. 64 65 @classmethod 66 def from_wpt_output(cls, output): 67 """Parse the output from a web-platform test that uses testharness.js. 68 (The output is written to stdout in js/src/tests/testharnessreport.js.) 69 """ 70 from wptrunner.executors.base import testharness_result_converter 71 72 rc = output.rc 73 stdout = output.out.split("\n") 74 if rc != 0: 75 if rc == 3: 76 harness_status = "ERROR" 77 harness_message = "Exit code reported exception" 78 else: 79 harness_status = "CRASH" 80 harness_message = "Exit code reported crash" 81 tests = [] 82 else: 83 for idx, line in enumerate(stdout): 84 if line.startswith("WPT OUTPUT: "): 85 msg = line[len("WPT OUTPUT: ") :] 86 data = [output.test.wpt.url] + json.loads(msg) 87 harness_status_obj, tests = testharness_result_converter( 88 output.test.wpt, data 89 ) 90 harness_status = harness_status_obj.status 91 harness_message = "Reported by harness: %s" % ( 92 harness_status_obj.message, 93 ) 94 del stdout[idx] 95 break 96 else: 97 harness_status = "ERROR" 98 harness_message = "No harness output found" 99 tests = [] 100 stdout.append("Harness status: %s (%s)" % (harness_status, harness_message)) 101 102 result = cls.PASS 103 results = [] 104 subtests = [] 105 expected_harness_status = output.test.wpt.expected() 106 if harness_status != expected_harness_status: 107 if harness_status == "CRASH": 108 result = cls.CRASH 109 else: 110 result = cls.FAIL 111 else: 112 for test in tests: 113 test_output = 'Subtest "%s": ' % (test.name,) 114 expected = output.test.wpt.expected(test.name) 115 if test.status == expected: 116 test_result = (cls.PASS, "") 117 test_output += "as expected: %s" % (test.status,) 118 else: 119 test_result = (cls.FAIL, test.message) 120 result = cls.FAIL 121 test_output += "expected %s, found %s" % (expected, test.status) 122 if test.message: 123 test_output += ' (with message: "%s")' % (test.message,) 124 subtests.append({ 125 "test": output.test.wpt.id, 126 "subtest": test.name, 127 "status": test.status, 128 "expected": expected, 129 }) 130 results.append(test_result) 131 stdout.append(test_output) 132 133 output.out = "\n".join(stdout) + "\n" 134 135 wpt_results = { 136 "name": output.test.wpt.id, 137 "status": harness_status, 138 "expected": expected_harness_status, 139 "subtests": subtests, 140 } 141 142 return cls(output.test, result, results, wpt_results) 143 144 @classmethod 145 def from_output(cls, output): 146 test = output.test 147 result = None # str: overall result, see class-level variables 148 results = [] # (str,str) list: subtest results (pass/fail, message) 149 150 if test.wpt: 151 return cls.from_wpt_output(output) 152 153 out, err, rc = output.out, output.err, output.rc 154 155 failures = 0 156 passes = 0 157 158 expected_rcs = [] 159 if test.path.endswith("-n.js"): 160 expected_rcs.append(3) 161 162 for line in out.split("\n"): 163 if line.startswith(" FAILED!"): 164 failures += 1 165 msg = line[len(" FAILED! ") :] 166 results.append((cls.FAIL, msg)) 167 elif line.startswith(" PASSED!"): 168 passes += 1 169 msg = line[len(" PASSED! ") :] 170 results.append((cls.PASS, msg)) 171 else: 172 m = re.match( 173 "--- NOTE: IN THIS TESTCASE, WE EXPECT EXIT CODE ((?:-|\\d)+) ---", 174 line, 175 ) 176 if m: 177 expected_rcs.append(int(m.group(1))) 178 179 if test.error is not None: 180 expected_rcs.append(3) 181 if test.error not in err: 182 failures += 1 183 results.append((cls.FAIL, f"Expected uncaught error: {test.error}")) 184 185 if rc and rc not in expected_rcs: 186 if rc == 3: 187 result = cls.FAIL 188 else: 189 result = cls.CRASH 190 elif (rc or passes > 0) and failures == 0: 191 result = cls.PASS 192 else: 193 result = cls.FAIL 194 195 return cls(test, result, results) 196 197 198 class TestDuration: 199 def __init__(self, test, duration): 200 self.test = test 201 self.duration = duration 202 203 204 class ResultsSink: 205 def __init__(self, testsuite, options, testcount): 206 self.options = options 207 self.fp = options.output_fp 208 if self.options.format == "automation": 209 self.slog = TestLogger(testsuite) 210 self.slog.suite_start() 211 212 self.wptreport = None 213 if self.options.wptreport: 214 try: 215 from .wptreport import WptreportHandler 216 217 self.wptreport = WptreportHandler(self.options.wptreport) 218 self.wptreport.suite_start() 219 except ImportError: 220 pass 221 222 self.groups = {} 223 self.output_dict = {} 224 self.counts = {"PASS": 0, "FAIL": 0, "TIMEOUT": 0, "SKIP": 0} 225 self.slow_tests = [] 226 self.n = 0 227 228 if options.hide_progress: 229 self.pb = NullProgressBar() 230 else: 231 fmt = [ 232 {"value": "PASS", "color": "green"}, 233 {"value": "FAIL", "color": "red"}, 234 {"value": "TIMEOUT", "color": "blue"}, 235 {"value": "SKIP", "color": "brightgray"}, 236 ] 237 self.pb = ProgressBar(testcount, fmt) 238 239 def push(self, output): 240 if self.options.show_slow and output.dt >= self.options.slow_test_threshold: 241 self.slow_tests.append(TestDuration(output.test, output.dt)) 242 if output.timed_out: 243 self.counts["TIMEOUT"] += 1 244 if isinstance(output, NullTestOutput): 245 if self.options.format == "automation": 246 self.print_automation_result( 247 "TEST-KNOWN-FAIL", output.test, time=output.dt, skip=True 248 ) 249 self.counts["SKIP"] += 1 250 self.n += 1 251 else: 252 result = TestResult.from_output(output) 253 254 if self.wptreport is not None and result.wpt_results: 255 self.wptreport.test(result.wpt_results, output.dt) 256 257 tup = (result.result, result.test.expect, result.test.random) 258 dev_label = self.LABELS[tup][1] 259 260 if self.options.check_output: 261 if output.test.path in self.output_dict.keys(): 262 if self.output_dict[output.test.path] != output: 263 self.counts["FAIL"] += 1 264 self.print_automation_result( 265 "TEST-UNEXPECTED-FAIL", 266 result.test, 267 time=output.dt, 268 message="Same test with different flag producing different output", 269 ) 270 else: 271 self.output_dict[output.test.path] = output 272 273 if output.timed_out: 274 dev_label = "TIMEOUTS" 275 self.groups.setdefault(dev_label, []).append(result) 276 277 if dev_label == "REGRESSIONS": 278 show_output = ( 279 self.options.show_output or not self.options.no_show_failed 280 ) 281 elif dev_label == "TIMEOUTS": 282 show_output = self.options.show_output 283 else: 284 show_output = self.options.show_output and not self.options.failed_only 285 286 if dev_label in ("REGRESSIONS", "TIMEOUTS"): 287 show_cmd = self.options.show_cmd 288 else: 289 show_cmd = self.options.show_cmd and not self.options.failed_only 290 291 if show_output or show_cmd: 292 self.pb.beginline() 293 294 if show_output: 295 print( 296 f"## {output.test.path}: rc = {output.rc:d}, run time = {output.dt}", 297 file=self.fp, 298 ) 299 300 if show_cmd: 301 print(escape_cmdline(output.cmd), file=self.fp) 302 303 if show_output: 304 305 def write_with_fallback(fp, data): 306 try: 307 fp.write(data) 308 except UnicodeEncodeError as e: 309 # In case the data contains something not directly 310 # encodable, use \uXXXX. 311 fp.write(f"WARNING: Falling back from exception: {e}\n") 312 fp.write("WARNING: The following output is escaped, ") 313 fp.write("and may be different than original one.\n") 314 fp.write( 315 data.encode("ascii", "namereplace").decode("ascii") 316 ) 317 318 write_with_fallback(self.fp, output.out) 319 write_with_fallback(self.fp, output.err) 320 321 self.n += 1 322 323 if result.result == TestResult.PASS and not result.test.random: 324 self.counts["PASS"] += 1 325 elif result.test.expect and not result.test.random: 326 self.counts["FAIL"] += 1 327 else: 328 self.counts["SKIP"] += 1 329 330 if self.options.format == "automation": 331 if result.result != TestResult.PASS and len(result.results) > 1: 332 for sub_ok, msg in result.results: 333 tup = (sub_ok, result.test.expect, result.test.random) 334 label = self.LABELS[tup][0] 335 if label == "TEST-UNEXPECTED-PASS": 336 label = "TEST-PASS (EXPECTED RANDOM)" 337 self.print_automation_result( 338 label, result.test, time=output.dt, message=msg 339 ) 340 tup = (result.result, result.test.expect, result.test.random) 341 self.print_automation_result( 342 self.LABELS[tup][0], 343 result.test, 344 time=output.dt, 345 extra=getattr(output, "extra", None), 346 ) 347 return 348 349 if dev_label: 350 351 def singular(label): 352 return "FIXED" if label == "FIXES" else label[:-1] 353 354 self.pb.message(f"{singular(dev_label)} - {output.test.path}") 355 356 self.pb.update(self.n, self.counts) 357 358 def finish(self, completed): 359 self.pb.finish(completed) 360 if self.options.format == "automation": 361 self.slog.suite_end() 362 else: 363 self.list(completed) 364 365 if self.n != 0 and self.options.show_slow: 366 self.show_slow_tests() 367 368 if self.wptreport is not None: 369 self.wptreport.suite_end() 370 371 # Conceptually, this maps (test result x test expectation) to text labels. 372 # key is (result, expect, random) 373 # value is (automation label, dev test category) 374 LABELS = { 375 (TestResult.CRASH, False, False): ("TEST-UNEXPECTED-FAIL", "REGRESSIONS"), 376 (TestResult.CRASH, False, True): ("TEST-UNEXPECTED-FAIL", "REGRESSIONS"), 377 (TestResult.CRASH, True, False): ("TEST-UNEXPECTED-FAIL", "REGRESSIONS"), 378 (TestResult.CRASH, True, True): ("TEST-UNEXPECTED-FAIL", "REGRESSIONS"), 379 (TestResult.FAIL, False, False): ("TEST-KNOWN-FAIL", ""), 380 (TestResult.FAIL, False, True): ("TEST-KNOWN-FAIL (EXPECTED RANDOM)", ""), 381 (TestResult.FAIL, True, False): ("TEST-UNEXPECTED-FAIL", "REGRESSIONS"), 382 (TestResult.FAIL, True, True): ("TEST-KNOWN-FAIL (EXPECTED RANDOM)", ""), 383 (TestResult.PASS, False, False): ("TEST-UNEXPECTED-PASS", "FIXES"), 384 (TestResult.PASS, False, True): ("TEST-PASS (EXPECTED RANDOM)", ""), 385 (TestResult.PASS, True, False): ("TEST-PASS", ""), 386 (TestResult.PASS, True, True): ("TEST-PASS (EXPECTED RANDOM)", ""), 387 } 388 389 def list(self, completed): 390 for label, results in sorted(self.groups.items()): 391 if label == "": 392 continue 393 394 print(label) 395 for result in results: 396 print( 397 " {}".format( 398 " ".join( 399 result.test.jitflags 400 + result.test.options 401 + [result.test.path] 402 ) 403 ) 404 ) 405 406 if self.options.failure_file: 407 failure_file = open(self.options.failure_file, "w") 408 if not self.all_passed(): 409 if "REGRESSIONS" in self.groups: 410 for result in self.groups["REGRESSIONS"]: 411 print(result.test.path, file=failure_file) 412 if "TIMEOUTS" in self.groups: 413 for result in self.groups["TIMEOUTS"]: 414 print(result.test.path, file=failure_file) 415 failure_file.close() 416 417 suffix = "" if completed else " (partial run -- interrupted by user)" 418 if self.all_passed(): 419 print("PASS" + suffix) 420 else: 421 print("FAIL" + suffix) 422 423 def show_slow_tests(self): 424 threshold = self.options.slow_test_threshold 425 fraction_fast = 1 - len(self.slow_tests) / self.n 426 self.log_info(f"{fraction_fast * 100:5.2f}% of tests ran in under {threshold}s") 427 428 self.log_info(f"Slowest tests that took longer than {threshold}s:") 429 slow_tests = sorted(self.slow_tests, key=lambda x: x.duration, reverse=True) 430 any = False 431 for i in range(min(len(slow_tests), 20)): 432 test = slow_tests[i] 433 self.log_info(f" {test.duration:6.2f} {test.test}") 434 any = True 435 if not any: 436 self.log_info("None") 437 438 def log_info(self, message): 439 if self.options.format == "automation": 440 self.slog.log_info(message) 441 else: 442 print(message) 443 444 def all_passed(self): 445 return "REGRESSIONS" not in self.groups and "TIMEOUTS" not in self.groups 446 447 def print_automation_result( 448 self, label, test, message=None, skip=False, time=None, extra=None 449 ): 450 result = label 451 result += " | " + test.path 452 args = [] 453 if self.options.shell_args: 454 args.extend(self.options.shell_args) 455 args += test.jitflags 456 result += ' | (args: "{}")'.format(" ".join(args)) 457 if message: 458 result += " | " + message 459 if skip: 460 result += " | (SKIP)" 461 if time > self.options.timeout: 462 result += " | (TIMEOUT)" 463 result += f" [{time:.1f} s]" 464 print(result) 465 466 details = {"extra": extra.copy() if extra else {}} 467 if self.options.shell_args: 468 details["extra"]["shell_args"] = shlex.join(self.options.shell_args) 469 details["extra"]["jitflags"] = test.jitflags 470 if message: 471 details["message"] = message 472 status = "FAIL" if "TEST-UNEXPECTED" in label else "PASS" 473 474 self.slog.test(test.path, status, time or 0, **details)