1 # Copyright (c) 2017 The Chromium OS 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 """Utility class to parse the output of a gtest suite run.""" 6 7 import re 8 9 10 class gtest_parser(object): 11 """This class knows how to understand GTest test output. 12 13 The code was borrowed with minor changes from chrome utility gtest_command. 14 http://src.chromium.org/viewvc/chrome/trunk/tools/build/scripts/master/ 15 log_parser/gtest_command.py?view=markup 16 """ 17 18 def __init__(self): 19 # State tracking for log parsing 20 self._current_test = '' 21 self._failure_description = [] 22 self._current_suppression_hash = '' 23 self._current_suppression = [] 24 25 # Line number currently being processed. 26 self._line_number = 0 27 28 # List of parsing errors, as human-readable strings. 29 self.internal_error_lines = [] 30 31 # Tests are stored here as 'test.name': (status, [description]). 32 # The status should be one of ('started', 'OK', 'failed', 'timeout'). 33 # The description is a list of lines detailing the test's error, as 34 # reported in the log. 35 self._test_status = {} 36 37 # Suppressions are stored here as 'hash': [suppression]. 38 self._suppressions = {} 39 40 # This may be either text or a number. It will be used in the phrase 41 # '%s disabled' or '%s flaky' on the waterfall display. 42 self.disabled_tests = 0 43 self.flaky_tests = 0 44 45 # Regular expressions for parsing GTest logs. Test names look like 46 # SomeTestCase.SomeTest 47 # SomeName/SomeTestCase.SomeTest/1 48 # This regexp also matches SomeName.SomeTest/1, which should be 49 # harmless. 50 test_name_regexp = r'((\w+/)?\w+\.\w+(\.\w+)?(/\d+)?)' 51 self._test_start = re.compile('\[\s+RUN\s+\] ' + test_name_regexp) 52 self._test_ok = re.compile('\[\s+OK\s+\] ' + test_name_regexp) 53 self._test_fail = re.compile('\[\s+FAILED\s+\] ' + test_name_regexp) 54 self._test_timeout = re.compile( 55 'Test timeout \([0-9]+ ms\) exceeded for ' + test_name_regexp) 56 self._disabled = re.compile(' YOU HAVE (\d+) DISABLED TEST') 57 self._flaky = re.compile(' YOU HAVE (\d+) FLAKY TEST') 58 59 self._suppression_start = re.compile( 60 'Suppression \(error hash=#([0-9A-F]+)#\):') 61 self._suppression_end = re.compile('^}\s*$') 62 63 self._master_name_re = re.compile('\[Running for master: "([^"]*)"') 64 self.master_name = '' 65 66 self._error_logging_start_re = re.compile('=' * 70) 67 self._error_logging_test_name_re = re.compile( 68 '[FAIL|ERROR]: ' + test_name_regexp) 69 self._error_logging_end_re = re.compile('-' * 70) 70 self._error_logging_first_dash_found = False 71 72 def _TestsByStatus(self, status, include_fails, include_flaky): 73 """Returns list of tests with the given status. 74 75 Args: 76 status: test results status to search for. 77 include_fails: If False, tests containing 'FAILS_' anywhere in 78 their names will be excluded from the list. 79 include_flaky: If False, tests containing 'FLAKY_' anywhere in 80 their names will be excluded from the list. 81 Returns: 82 List of tests with the status. 83 """ 84 test_list = [x[0] for x in self._test_status.items() 85 if self._StatusOfTest(x[0]) == status] 86 87 if not include_fails: 88 test_list = [x for x in test_list if x.find('FAILS_') == -1] 89 if not include_flaky: 90 test_list = [x for x in test_list if x.find('FLAKY_') == -1] 91 92 return test_list 93 94 def _StatusOfTest(self, test): 95 """Returns the status code for the given test, or 'not known'.""" 96 test_status = self._test_status.get(test, ('not known', [])) 97 return test_status[0] 98 99 def _RecordError(self, line, reason): 100 """Record a log line that produced a parsing error. 101 102 Args: 103 line: text of the line at which the error occurred. 104 reason: a string describing the error. 105 """ 106 self.internal_error_lines.append("%s: %s [%s]" % (self._line_number, 107 line.strip(), 108 reason)) 109 110 def TotalTests(self): 111 """Returns the number of parsed tests.""" 112 return len(self._test_status) 113 114 def PassedTests(self): 115 """Returns list of tests that passed.""" 116 return self._TestsByStatus('OK', False, False) 117 118 def FailedTests(self, include_fails=False, include_flaky=False): 119 """Returns list of tests that failed, timed out, or didn't finish. 120 121 This list will be incorrect until the complete log has been processed, 122 because it will show currently running tests as having failed. 123 124 Args: 125 include_fails: If true, all failing tests with FAILS_ in their 126 names will be included. Otherwise, they will only be included 127 if they crashed. 128 include_flaky: If true, all failing tests with FLAKY_ in their 129 names will be included. Otherwise, they will only be included 130 if they crashed. 131 Returns: 132 List of failed tests. 133 """ 134 return (self._TestsByStatus('failed', include_fails, include_flaky) + 135 self._TestsByStatus('timeout', include_fails, include_flaky) + 136 self._TestsByStatus('started', include_fails, include_flaky)) 137 138 def FailureDescription(self, test): 139 """Returns a list containing the failure description for the given test. 140 141 If the test didn't fail or timeout, returns []. 142 Args: 143 test: Name to test to find failure reason. 144 Returns: 145 List of test name, and failure string. 146 """ 147 test_status = self._test_status.get(test, ('', [])) 148 return test_status[1] 149 150 def SuppressionHashes(self): 151 """Returns list of suppression hashes found in the log.""" 152 return self._suppressions.keys() 153 154 def Suppression(self, suppression_hash): 155 """Returns a list containing the suppression for a given hash. 156 157 If the suppression hash doesn't exist, returns []. 158 159 Args: 160 suppression_hash: name of hash. 161 Returns: 162 List of suppression for the hash. 163 """ 164 return self._suppressions.get(suppression_hash, []) 165 166 def ProcessLogLine(self, line): 167 """This is called once with each line of the test log.""" 168 169 # Track line number for error messages. 170 self._line_number += 1 171 172 if not self.master_name: 173 results = self._master_name_re.search(line) 174 if results: 175 self.master_name = results.group(1) 176 177 # Is it a line reporting disabled tests? 178 results = self._disabled.search(line) 179 if results: 180 try: 181 disabled = int(results.group(1)) 182 except ValueError: 183 disabled = 0 184 if disabled > 0 and isinstance(self.disabled_tests, int): 185 self.disabled_tests += disabled 186 else: 187 # If we can't parse the line, at least give a heads-up. This is 188 # a safety net for a case that shouldn't happen but isn't a 189 # fatal error. 190 self.disabled_tests = 'some' 191 return 192 193 # Is it a line reporting flaky tests? 194 results = self._flaky.search(line) 195 if results: 196 try: 197 flaky = int(results.group(1)) 198 except ValueError: 199 flaky = 0 200 if flaky > 0 and isinstance(self.flaky_tests, int): 201 self.flaky_tests = flaky 202 else: 203 # If we can't parse the line, at least give a heads-up. This is 204 # a safety net for a case that shouldn't happen but isn't a 205 # fatal error. 206 self.flaky_tests = 'some' 207 return 208 209 # Is it the start of a test? 210 results = self._test_start.search(line) 211 if results: 212 test_name = results.group(1) 213 if test_name in self._test_status: 214 self._RecordError(line, 'test started more than once') 215 return 216 if self._current_test: 217 status = self._StatusOfTest(self._current_test) 218 if status in ('OK', 'failed', 'timeout'): 219 self._RecordError(line, 'start while in status %s' % status) 220 return 221 if status not in ('failed', 'timeout'): 222 self._test_status[self._current_test] = ( 223 'failed', self._failure_description) 224 self._test_status[test_name] = ('started', ['Did not complete.']) 225 self._current_test = test_name 226 self._failure_description = [] 227 return 228 229 # Is it a test success line? 230 results = self._test_ok.search(line) 231 if results: 232 test_name = results.group(1) 233 status = self._StatusOfTest(test_name) 234 if status != 'started': 235 self._RecordError(line, 'success while in status %s' % status) 236 return 237 self._test_status[test_name] = ('OK', []) 238 self._failure_description = [] 239 self._current_test = '' 240 return 241 242 # Is it a test failure line? 243 results = self._test_fail.search(line) 244 if results: 245 test_name = results.group(1) 246 status = self._StatusOfTest(test_name) 247 if status not in ('started', 'failed', 'timeout'): 248 self._RecordError(line, 'failure while in status %s' % status) 249 return 250 # Don't overwrite the failure description when a failing test is 251 # listed a second time in the summary, or if it was already 252 # recorded as timing out. 253 if status not in ('failed', 'timeout'): 254 self._test_status[test_name] = ('failed', 255 self._failure_description) 256 self._failure_description = [] 257 self._current_test = '' 258 return 259 260 # Is it a test timeout line? 261 results = self._test_timeout.search(line) 262 if results: 263 test_name = results.group(1) 264 status = self._StatusOfTest(test_name) 265 if status not in ('started', 'failed'): 266 self._RecordError(line, 'timeout while in status %s' % status) 267 return 268 self._test_status[test_name] = ( 269 'timeout', self._failure_description + ['Killed (timed out).']) 270 self._failure_description = [] 271 self._current_test = '' 272 return 273 274 # Is it the start of a new valgrind suppression? 275 results = self._suppression_start.search(line) 276 if results: 277 suppression_hash = results.group(1) 278 if suppression_hash in self._suppressions: 279 self._RecordError(line, 'suppression reported more than once') 280 return 281 self._suppressions[suppression_hash] = [] 282 self._current_suppression_hash = suppression_hash 283 self._current_suppression = [line] 284 return 285 286 # Is it the end of a valgrind suppression? 287 results = self._suppression_end.search(line) 288 if results and self._current_suppression_hash: 289 self._current_suppression.append(line) 290 self._suppressions[self._current_suppression_hash] = ( 291 self._current_suppression) 292 self._current_suppression_hash = '' 293 self._current_suppression = [] 294 return 295 296 # Is it the start of a test summary error message? 297 results = self._error_logging_test_name_re.search(line) 298 if results: 299 test_name = results.group(1) 300 self._test_status[test_name] = ('failed', ['Output not found.']) 301 self._current_test = test_name 302 self._failure_description = [] 303 self._error_logging_first_dash_found = False 304 return 305 306 # Is it the start of the next test summary signaling the end 307 # of the previous message? 308 results = self._error_logging_start_re.search(line) 309 if results and self._current_test: 310 self._test_status[self._current_test] = ('failed', 311 self._failure_description) 312 self._failure_description = [] 313 self._current_test = '' 314 return 315 316 # Is it the end of the extra test failure summaries? 317 results = self._error_logging_end_re.search(line) 318 if results and self._current_test: 319 if self._error_logging_first_dash_found: 320 self._test_status[self._current_test] = ( 321 'failed', self._failure_description) 322 self._failure_description = [] 323 self._current_test = '' 324 self._error_logging_first_dash_found = True 325 return 326 327 # Random line: if we're in a suppression, collect it. Suppressions are 328 # generated after all tests are finished, so this should always belong 329 # to the current suppression hash. 330 if self._current_suppression_hash: 331 self._current_suppression.append(line) 332 return 333 334 # Random line: if we're in a test, collect it for the failure 335 # description. Tests may run simultaneously, so this might be off, but 336 # it's worth a try. 337 if self._current_test: 338 self._failure_description.append(line) 339
