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