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 |