| OLD | NEW |
| 1 #!/usr/bin/env python | |
| 2 # Copyright (c) 2016 The Chromium Authors. All rights reserved. | 1 # Copyright (c) 2016 The Chromium Authors. All rights reserved. |
| 3 # Use of this source code is governed by a BSD-style license that can be | 2 # Use of this source code is governed by a BSD-style license that can be |
| 4 # found in the LICENSE file. | 3 # found in the LICENSE file. |
| 5 | 4 |
| 6 import collections | 5 import json |
| 7 import copy | 6 import os |
| 8 import re | 7 import re |
| 8 import tempfile |
| 9 | 9 |
| 10 | 10 |
| 11 # These labels should match the ones output by gtest's JSON. | 11 # These labels should match the ones output by gtest's JSON. |
| 12 TEST_UNKNOWN_LABEL = 'UNKNOWN' | 12 TEST_UNKNOWN_LABEL = 'UNKNOWN' |
| 13 TEST_SUCCESS_LABEL = 'SUCCESS' | 13 TEST_SUCCESS_LABEL = 'SUCCESS' |
| 14 TEST_FAILURE_LABEL = 'FAILURE' | 14 TEST_FAILURE_LABEL = 'FAILURE' |
| 15 TEST_CRASH_LABEL = 'CRASH' |
| 15 TEST_TIMEOUT_LABEL = 'TIMEOUT' | 16 TEST_TIMEOUT_LABEL = 'TIMEOUT' |
| 16 TEST_WARNING_LABEL = 'WARNING' | 17 TEST_WARNING_LABEL = 'WARNING' |
| 17 | 18 |
| 18 | 19 |
| 19 class GTestResult(object): | 20 class XCTestLogParser(object): |
| 20 """A result of gtest. | 21 """This helper class process XCTest test output.""" |
| 21 | |
| 22 Properties: | |
| 23 command: The command argv. | |
| 24 crashed: Whether or not the test crashed. | |
| 25 crashed_test: The name of the test during which execution crashed, or | |
| 26 None if a particular test didn't crash. | |
| 27 failed_tests: A dict mapping the names of failed tests to a list of | |
| 28 lines of output from those tests. | |
| 29 flaked_tests: A dict mapping the names of failed flaky tests to a list | |
| 30 of lines of output from those tests. | |
| 31 passed_tests: A list of passed tests. | |
| 32 perf_links: A dict mapping the names of perf data points collected | |
| 33 to links to view those graphs. | |
| 34 return_code: The return code of the command. | |
| 35 success: Whether or not this run of the command was considered a | |
| 36 successful GTest execution. | |
| 37 """ | |
| 38 @property | |
| 39 def crashed(self): | |
| 40 return self._crashed | |
| 41 | |
| 42 @property | |
| 43 def crashed_test(self): | |
| 44 return self._crashed_test | |
| 45 | |
| 46 @property | |
| 47 def command(self): | |
| 48 return self._command | |
| 49 | |
| 50 @property | |
| 51 def failed_tests(self): | |
| 52 if self.__finalized: | |
| 53 return copy.deepcopy(self._failed_tests) | |
| 54 return self._failed_tests | |
| 55 | |
| 56 @property | |
| 57 def flaked_tests(self): | |
| 58 if self.__finalized: | |
| 59 return copy.deepcopy(self._flaked_tests) | |
| 60 return self._flaked_tests | |
| 61 | |
| 62 @property | |
| 63 def passed_tests(self): | |
| 64 if self.__finalized: | |
| 65 return copy.deepcopy(self._passed_tests) | |
| 66 return self._passed_tests | |
| 67 | |
| 68 @property | |
| 69 def perf_links(self): | |
| 70 if self.__finalized: | |
| 71 return copy.deepcopy(self._perf_links) | |
| 72 return self._perf_links | |
| 73 | |
| 74 @property | |
| 75 def return_code(self): | |
| 76 return self._return_code | |
| 77 | |
| 78 @property | |
| 79 def success(self): | |
| 80 return self._success | |
| 81 | |
| 82 def __init__(self, command): | |
| 83 if not isinstance(command, collections.Iterable): | |
| 84 raise ValueError('Expected an iterable of command arguments.', command) | |
| 85 | |
| 86 if not command: | |
| 87 raise ValueError('Expected a non-empty command.', command) | |
| 88 | |
| 89 self._command = tuple(command) | |
| 90 self._crashed = False | |
| 91 self._crashed_test = None | |
| 92 self._failed_tests = collections.OrderedDict() | |
| 93 self._flaked_tests = collections.OrderedDict() | |
| 94 self._passed_tests = [] | |
| 95 self._perf_links = collections.OrderedDict() | |
| 96 self._return_code = None | |
| 97 self._success = None | |
| 98 self.__finalized = False | |
| 99 | |
| 100 def finalize(self, return_code, success): | |
| 101 self._return_code = return_code | |
| 102 self._success = success | |
| 103 | |
| 104 # If the test was not considered to be a GTest success, but had no | |
| 105 # failing tests, conclude that it must have crashed. | |
| 106 if not self._success and not self._failed_tests and not self._flaked_tests: | |
| 107 self._crashed = True | |
| 108 | |
| 109 # At most one test can crash the entire app in a given parsing. | |
| 110 for test, log_lines in self._failed_tests.iteritems(): | |
| 111 # A test with no output would have crashed. No output is replaced | |
| 112 # by the GTestLogParser by a sentence indicating non-completion. | |
| 113 if 'Did not complete.' in log_lines: | |
| 114 self._crashed = True | |
| 115 self._crashed_test = test | |
| 116 | |
| 117 # A test marked as flaky may also have crashed the app. | |
| 118 for test, log_lines in self._flaked_tests.iteritems(): | |
| 119 if 'Did not complete.' in log_lines: | |
| 120 self._crashed = True | |
| 121 self._crashed_test = test | |
| 122 | |
| 123 self.__finalized = True | |
| 124 | |
| 125 | |
| 126 class GTestLogParser(object): | |
| 127 """This helper class process GTest test output.""" | |
| 128 | 22 |
| 129 def __init__(self): | 23 def __init__(self): |
| 130 # State tracking for log parsing | 24 # State tracking for log parsing |
| 131 self.completed = False | 25 self.completed = False |
| 132 self._current_test = '' | 26 self._current_test = '' |
| 133 self._failure_description = [] | 27 self._failure_description = [] |
| 28 self._current_report_hash = '' |
| 29 self._current_report = [] |
| 134 self._parsing_failures = False | 30 self._parsing_failures = False |
| 135 | 31 |
| 136 # Line number currently being processed. | 32 # Line number currently being processed. |
| 137 self._line_number = 0 | 33 self._line_number = 0 |
| 138 | 34 |
| 139 # List of parsing errors, as human-readable strings. | 35 # List of parsing errors, as human-readable strings. |
| 140 self._internal_error_lines = [] | 36 self._internal_error_lines = [] |
| 141 | 37 |
| 142 # Tests are stored here as 'test.name': (status, [description]). | 38 # Tests are stored here as 'test.name': (status, [description]). |
| 143 # The status should be one of ('started', 'OK', 'failed', 'timeout', | 39 # The status should be one of ('started', 'OK', 'failed', 'timeout', |
| 144 # 'warning'). Warning indicates that a test did not pass when run in | 40 # 'warning'). Warning indicates that a test did not pass when run in |
| 145 # parallel with other tests but passed when run alone. The description is | 41 # parallel with other tests but passed when run alone. The description is |
| 146 # a list of lines detailing the test's error, as reported in the log. | 42 # a list of lines detailing the test's error, as reported in the log. |
| 147 self._test_status = {} | 43 self._test_status = {} |
| 148 | 44 |
| 149 # This may be either text or a number. It will be used in the phrase | 45 # This may be either text or a number. It will be used in the phrase |
| 150 # '%s disabled' or '%s flaky' on the waterfall display. | 46 # '%s disabled' or '%s flaky' on the waterfall display. |
| 151 self._disabled_tests = 0 | 47 self._disabled_tests = 0 |
| 152 self._flaky_tests = 0 | 48 self._flaky_tests = 0 |
| 153 | 49 |
| 154 # Regular expressions for parsing GTest logs. Test names look like | 50 test_name_regexp = r'\-\[(\w+)\s(\w+)\]' |
| 155 # "x.y", with 0 or more "w/" prefixes and 0 or more "/z" suffixes. | |
| 156 # e.g.: | |
| 157 # SomeName/SomeTestCase.SomeTest/1 | |
| 158 # SomeName/SomeTestCase/1.SomeTest | |
| 159 # SomeName/SomeTestCase/1.SomeTest/SomeModifider | |
| 160 test_name_regexp = r'((\w+/)*\w+\.\w+(/\w+)*)' | |
| 161 | |
| 162 self._master_name_re = re.compile(r'\[Running for master: "([^"]*)"') | |
| 163 self.master_name = '' | |
| 164 | |
| 165 self._test_name = re.compile(test_name_regexp) | 51 self._test_name = re.compile(test_name_regexp) |
| 166 self._test_start = re.compile(r'\[\s+RUN\s+\] ' + test_name_regexp) | 52 self._test_start = re.compile( |
| 167 self._test_ok = re.compile(r'\[\s+OK\s+\] ' + test_name_regexp) | 53 r'Test Case \'' + test_name_regexp + '\' started\.') |
| 168 self._test_fail = re.compile(r'\[\s+FAILED\s+\] ' + test_name_regexp) | 54 self._test_ok = re.compile( |
| 169 self._test_passed = re.compile(r'\[\s+PASSED\s+\] \d+ tests?.') | 55 r'Test Case \'' + test_name_regexp + |
| 170 self._run_test_cases_line = re.compile( | 56 '\' passed\s+\(\d+\.\d+\s+seconds\)?.') |
| 171 r'\[\s*\d+\/\d+\]\s+[0-9\.]+s ' + test_name_regexp + ' .+') | 57 self._test_fail = re.compile( |
| 172 self._test_timeout = re.compile( | 58 r'Test Case \'' + test_name_regexp + |
| 173 r'Test timeout \([0-9]+ ms\) exceeded for ' + test_name_regexp) | 59 '\' failed\s+\(\d+\.\d+\s+seconds\)?.') |
| 174 self._disabled = re.compile(r'\s*YOU HAVE (\d+) DISABLED TEST') | 60 self._test_passed = re.compile(r'\*\*\s+TEST\s+EXECUTE\s+SUCCEEDED\s+\*\*') |
| 175 self._flaky = re.compile(r'\s*YOU HAVE (\d+) FLAKY TEST') | |
| 176 | |
| 177 self._retry_message = re.compile('RETRYING FAILED TESTS:') | 61 self._retry_message = re.compile('RETRYING FAILED TESTS:') |
| 178 self.retrying_failed = False | 62 self.retrying_failed = False |
| 179 | 63 |
| 180 self.TEST_STATUS_MAP = { | 64 self.TEST_STATUS_MAP = { |
| 181 'OK': TEST_SUCCESS_LABEL, | 65 'OK': TEST_SUCCESS_LABEL, |
| 182 'failed': TEST_FAILURE_LABEL, | 66 'failed': TEST_FAILURE_LABEL, |
| 183 'timeout': TEST_TIMEOUT_LABEL, | 67 'timeout': TEST_TIMEOUT_LABEL, |
| 184 'warning': TEST_WARNING_LABEL | 68 'warning': TEST_WARNING_LABEL |
| 185 } | 69 } |
| 186 | 70 |
| (...skipping 70 matching lines...) Expand 10 before | Expand all | Expand 10 after Loading... |
| 257 self._TestsByStatus('timeout', True, True) + | 141 self._TestsByStatus('timeout', True, True) + |
| 258 self._TestsByStatus('warning', include_fails, include_flaky) + | 142 self._TestsByStatus('warning', include_fails, include_flaky) + |
| 259 self.RunningTests()) | 143 self.RunningTests()) |
| 260 | 144 |
| 261 def TriesForTest(self, test): | 145 def TriesForTest(self, test): |
| 262 """Returns a list containing the state for all tries of the given test. | 146 """Returns a list containing the state for all tries of the given test. |
| 263 This parser doesn't support retries so a single result is returned.""" | 147 This parser doesn't support retries so a single result is returned.""" |
| 264 return [self.TEST_STATUS_MAP.get(self._StatusOfTest(test), | 148 return [self.TEST_STATUS_MAP.get(self._StatusOfTest(test), |
| 265 TEST_UNKNOWN_LABEL)] | 149 TEST_UNKNOWN_LABEL)] |
| 266 | 150 |
| 267 def DisabledTests(self): | |
| 268 """Returns the name of the disabled test (if there is only 1) or the number | |
| 269 of disabled tests. | |
| 270 """ | |
| 271 return self._disabled_tests | |
| 272 | |
| 273 def FlakyTests(self): | |
| 274 """Returns the name of the flaky test (if there is only 1) or the number | |
| 275 of flaky tests. | |
| 276 """ | |
| 277 return self._flaky_tests | |
| 278 | |
| 279 def FailureDescription(self, test): | 151 def FailureDescription(self, test): |
| 280 """Returns a list containing the failure description for the given test. | 152 """Returns a list containing the failure description for the given test. |
| 281 | 153 |
| 282 If the test didn't fail or timeout, returns []. | 154 If the test didn't fail or timeout, returns []. |
| 283 """ | 155 """ |
| 284 test_status = self._test_status.get(test, ('', [])) | 156 test_status = self._test_status.get(test, ('', [])) |
| 285 return ['%s: ' % test] + test_status[1] | 157 return ['%s: ' % test] + test_status[1] |
| 286 | 158 |
| 287 def CompletedWithoutFailure(self): | 159 def CompletedWithoutFailure(self): |
| 288 """Returns True if all tests completed and no tests failed unexpectedly.""" | 160 """Returns True if all tests completed and no tests failed unexpectedly.""" |
| 289 return self.completed and not self.FailedTests() | 161 return self.completed |
| 290 | 162 |
| 291 def ProcessLine(self, line): | 163 def ProcessLine(self, line): |
| 292 """This is called once with each line of the test log.""" | 164 """This is called once with each line of the test log.""" |
| 293 | 165 |
| 294 # Track line number for error messages. | 166 # Track line number for error messages. |
| 295 self._line_number += 1 | 167 self._line_number += 1 |
| 296 | 168 |
| 297 # Some tests (net_unittests in particular) run subprocesses which can write | 169 # Some tests (net_unittests in particular) run subprocesses which can write |
| 298 # stuff to shared stdout buffer. Sometimes such output appears between new | 170 # stuff to shared stdout buffer. Sometimes such output appears between new |
| 299 # line and gtest directives ('[ RUN ]', etc) which breaks the parser. | 171 # line and gtest directives ('[ RUN ]', etc) which breaks the parser. |
| (...skipping 19 matching lines...) Expand all Loading... |
| 319 else: | 191 else: |
| 320 self._ProcessLine(line[:match.start()]) | 192 self._ProcessLine(line[:match.start()]) |
| 321 self._ProcessLine(line[match.start():]) | 193 self._ProcessLine(line[match.start():]) |
| 322 | 194 |
| 323 def _ProcessLine(self, line): | 195 def _ProcessLine(self, line): |
| 324 """Parses the line and changes the state of parsed tests accordingly. | 196 """Parses the line and changes the state of parsed tests accordingly. |
| 325 | 197 |
| 326 Will recognize newly started tests, OK or FAILED statuses, timeouts, etc. | 198 Will recognize newly started tests, OK or FAILED statuses, timeouts, etc. |
| 327 """ | 199 """ |
| 328 | 200 |
| 329 # Note: When sharding, the number of disabled and flaky tests will be read | |
| 330 # multiple times, so this will only show the most recent values (but they | |
| 331 # should all be the same anyway). | |
| 332 | |
| 333 # Is it a line listing the master name? | |
| 334 if not self.master_name: | |
| 335 results = self._master_name_re.match(line) | |
| 336 if results: | |
| 337 self.master_name = results.group(1) | |
| 338 | |
| 339 results = self._run_test_cases_line.match(line) | |
| 340 if results: | |
| 341 # A run_test_cases.py output. | |
| 342 if self._current_test: | |
| 343 if self._test_status[self._current_test][0] == 'started': | |
| 344 self._test_status[self._current_test] = ( | |
| 345 'timeout', self._failure_description) | |
| 346 self._current_test = '' | |
| 347 self._failure_description = [] | |
| 348 return | |
| 349 | |
| 350 # Is it a line declaring all tests passed? | 201 # Is it a line declaring all tests passed? |
| 351 results = self._test_passed.match(line) | 202 results = self._test_passed.match(line) |
| 352 if results: | 203 if results: |
| 353 self.completed = True | 204 self.completed = True |
| 354 self._current_test = '' | 205 self._current_test = '' |
| 355 return | 206 return |
| 356 | 207 |
| 357 # Is it a line reporting disabled tests? | |
| 358 results = self._disabled.match(line) | |
| 359 if results: | |
| 360 try: | |
| 361 disabled = int(results.group(1)) | |
| 362 except ValueError: | |
| 363 disabled = 0 | |
| 364 if disabled > 0 and isinstance(self._disabled_tests, int): | |
| 365 self._disabled_tests = disabled | |
| 366 else: | |
| 367 # If we can't parse the line, at least give a heads-up. This is a | |
| 368 # safety net for a case that shouldn't happen but isn't a fatal error. | |
| 369 self._disabled_tests = 'some' | |
| 370 return | |
| 371 | |
| 372 # Is it a line reporting flaky tests? | |
| 373 results = self._flaky.match(line) | |
| 374 if results: | |
| 375 try: | |
| 376 flaky = int(results.group(1)) | |
| 377 except ValueError: | |
| 378 flaky = 0 | |
| 379 if flaky > 0 and isinstance(self._flaky_tests, int): | |
| 380 self._flaky_tests = flaky | |
| 381 else: | |
| 382 # If we can't parse the line, at least give a heads-up. This is a | |
| 383 # safety net for a case that shouldn't happen but isn't a fatal error. | |
| 384 self._flaky_tests = 'some' | |
| 385 return | |
| 386 | |
| 387 # Is it the start of a test? | 208 # Is it the start of a test? |
| 388 results = self._test_start.match(line) | 209 results = self._test_start.match(line) |
| 389 if results: | 210 if results: |
| 390 if self._current_test: | 211 if self._current_test: |
| 391 if self._test_status[self._current_test][0] == 'started': | 212 if self._test_status[self._current_test][0] == 'started': |
| 392 self._test_status[self._current_test] = ( | 213 self._test_status[self._current_test] = ( |
| 393 'timeout', self._failure_description) | 214 'timeout', self._failure_description) |
| 394 test_name = results.group(1) | 215 test_name = '%s.%s' % (results.group(1), results.group(2)) |
| 395 self._test_status[test_name] = ('started', ['Did not complete.']) | 216 self._test_status[test_name] = ('started', ['Did not complete.']) |
| 396 self._current_test = test_name | 217 self._current_test = test_name |
| 397 if self.retrying_failed: | 218 if self.retrying_failed: |
| 398 self._failure_description = self._test_status[test_name][1] | 219 self._failure_description = self._test_status[test_name][1] |
| 399 self._failure_description.extend(['', 'RETRY OUTPUT:', '']) | 220 self._failure_description.extend(['', 'RETRY OUTPUT:', '']) |
| 400 else: | 221 else: |
| 401 self._failure_description = [] | 222 self._failure_description = [] |
| 402 return | 223 return |
| 403 | 224 |
| 404 # Is it a test success line? | 225 # Is it a test success line? |
| 405 results = self._test_ok.match(line) | 226 results = self._test_ok.match(line) |
| 406 if results: | 227 if results: |
| 407 test_name = results.group(1) | 228 test_name = '%s.%s' % (results.group(1), results.group(2)) |
| 408 status = self._StatusOfTest(test_name) | 229 status = self._StatusOfTest(test_name) |
| 409 if status != 'started': | 230 if status != 'started': |
| 410 self._RecordError(line, 'success while in status %s' % status) | 231 self._RecordError(line, 'success while in status %s' % status) |
| 411 if self.retrying_failed: | 232 if self.retrying_failed: |
| 412 self._test_status[test_name] = ('warning', self._failure_description) | 233 self._test_status[test_name] = ('warning', self._failure_description) |
| 413 else: | 234 else: |
| 414 self._test_status[test_name] = ('OK', []) | 235 self._test_status[test_name] = ('OK', []) |
| 415 self._failure_description = [] | 236 self._failure_description = [] |
| 416 self._current_test = '' | 237 self._current_test = '' |
| 417 return | 238 return |
| 418 | 239 |
| 419 # Is it a test failure line? | 240 # Is it a test failure line? |
| 420 results = self._test_fail.match(line) | 241 results = self._test_fail.match(line) |
| 421 if results: | 242 if results: |
| 422 test_name = results.group(1) | 243 test_name = '%s.%s' % (results.group(1), results.group(2)) |
| 423 status = self._StatusOfTest(test_name) | 244 status = self._StatusOfTest(test_name) |
| 424 if status not in ('started', 'failed', 'timeout'): | 245 if status not in ('started', 'failed', 'timeout'): |
| 425 self._RecordError(line, 'failure while in status %s' % status) | 246 self._RecordError(line, 'failure while in status %s' % status) |
| 426 # Don't overwrite the failure description when a failing test is listed a | 247 # Don't overwrite the failure description when a failing test is listed a |
| 427 # second time in the summary, or if it was already recorded as timing | 248 # second time in the summary, or if it was already recorded as timing |
| 428 # out. | 249 # out. |
| 429 if status not in ('failed', 'timeout'): | 250 if status not in ('failed', 'timeout'): |
| 430 self._test_status[test_name] = ('failed', self._failure_description) | 251 self._test_status[test_name] = ('failed', self._failure_description) |
| 431 self._failure_description = [] | 252 self._failure_description = [] |
| 432 self._current_test = '' | 253 self._current_test = '' |
| 433 return | 254 return |
| 434 | 255 |
| 435 # Is it a test timeout line? | |
| 436 results = self._test_timeout.search(line) | |
| 437 if results: | |
| 438 test_name = results.group(1) | |
| 439 status = self._StatusOfTest(test_name) | |
| 440 if status not in ('started', 'failed'): | |
| 441 self._RecordError(line, 'timeout while in status %s' % status) | |
| 442 self._test_status[test_name] = ( | |
| 443 'timeout', self._failure_description + ['Killed (timed out).']) | |
| 444 self._failure_description = [] | |
| 445 self._current_test = '' | |
| 446 return | |
| 447 | |
| 448 # Is it the start of the retry tests? | 256 # Is it the start of the retry tests? |
| 449 results = self._retry_message.match(line) | 257 results = self._retry_message.match(line) |
| 450 if results: | 258 if results: |
| 451 self.retrying_failed = True | 259 self.retrying_failed = True |
| 452 return | 260 return |
| 453 | 261 |
| 454 # Random line: if we're in a test, collect it for the failure description. | 262 # Random line: if we're in a test, collect it for the failure description. |
| 455 # Tests may run simultaneously, so this might be off, but it's worth a try. | 263 # Tests may run simultaneously, so this might be off, but it's worth a try. |
| 456 # This also won't work if a test times out before it begins running. | 264 # This also won't work if a test times out before it begins running. |
| 457 if self._current_test: | 265 if self._current_test: |
| 458 self._failure_description.append(line) | 266 self._failure_description.append(line) |
| 459 | |
| 460 # Parse the "Failing tests:" list at the end of the output, and add any | |
| 461 # additional failed tests to the list. For example, this includes tests | |
| 462 # that crash after the OK line. | |
| 463 if self._parsing_failures: | |
| 464 results = self._test_name.match(line) | |
| 465 if results: | |
| 466 test_name = results.group(1) | |
| 467 status = self._StatusOfTest(test_name) | |
| 468 if status in ('not known', 'OK'): | |
| 469 self._test_status[test_name] = ( | |
| 470 'failed', ['Unknown error, see stdio log.']) | |
| 471 else: | |
| 472 self._parsing_failures = False | |
| 473 elif line.startswith('Failing tests:'): | |
| 474 self._parsing_failures = True | |
| OLD | NEW |