1# Copyright (c) 2011 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 classes used to run and parse a gest suite in autotest. 6 7gtest_runner: runs a gtest suite parsing individual tests. 8 9gtest_parser: understands the output of a gtest run. 10""" 11 12 13import logging, os, re 14from autotest_lib.server import autotest, hosts, host_attributes 15from autotest_lib.server import site_server_job_utils 16 17 18class gtest_runner(object): 19 """Run a gtest test suite and evaluate the individual tests.""" 20 21 def __init__(self): 22 """Creates an instance of gtest_runner to run tests on a remote host.""" 23 self._results_dir = '' 24 self._gtest = None 25 self._host = None 26 27 def run(self, gtest_entry, machine, work_dir='.'): 28 """Run the gtest suite on a remote host, then parse the results. 29 30 Like machine_worker, gtest_runner honors include/exclude attributes on 31 the test item and will only run the test if the supplied host meets the 32 test requirements. 33 34 Note: This method takes a test and a machine as arguments, not a list 35 of tests and a list of machines like the parallel and distribute 36 methods do. 37 38 Args: 39 gtest_entry: Test tuple from control file. See documentation in 40 site_server_job_utils.test_item class. 41 machine: Name (IP) if remote host to run tests on. 42 work_dir: Local directory to run tests in. 43 44 """ 45 self._gtest = site_server_job_utils.test_item(*gtest_entry) 46 self._host = hosts.create_host(machine) 47 self._results_dir = work_dir 48 49 client_autotest = autotest.Autotest(self._host) 50 client_attributes = host_attributes.host_attributes(machine) 51 attribute_set = set(client_attributes.get_attributes()) 52 53 if self._gtest.validate(attribute_set): 54 logging.info('%s %s Running %s', self._host, 55 [a for a in attribute_set], self._gtest) 56 try: 57 self._gtest.run_test(client_autotest, self._results_dir) 58 finally: 59 self.parse() 60 else: 61 self.record_failed_test(self._gtest.test_name, 62 'No machines found for: ' + self._gtest) 63 64 def parse(self): 65 """Parse the gtest output recording individual test results. 66 67 Uses gtest_parser to pull the test results out of the gtest log file. 68 Then creates entries in status.log file for each test. 69 """ 70 # Find gtest log files from the autotest client run. 71 log_path = os.path.join( 72 self._results_dir, self._gtest.tagged_test_name, 73 'debug', self._gtest.tagged_test_name + '.DEBUG') 74 if not os.path.exists(log_path): 75 logging.error('gtest log file "%s" is missing.', log_path) 76 return 77 78 parser = gtest_parser() 79 80 # Read the log file line-by-line, passing each line into the parser. 81 with open(log_path, 'r') as log_file: 82 for log_line in log_file: 83 parser.ProcessLogLine(log_line) 84 85 logging.info('gtest_runner found %d tests.', parser.TotalTests()) 86 87 # Record each failed test. 88 for failed in parser.FailedTests(): 89 fail_description = parser.FailureDescription(failed) 90 if fail_description: 91 self.record_failed_test(failed, fail_description[0].strip(), 92 ''.join(fail_description)) 93 else: 94 self.record_failed_test(failed, 'NO ERROR LINES FOUND.') 95 96 # Finally record each successful test. 97 for passed in parser.PassedTests(): 98 self.record_passed_test(passed) 99 100 def record_failed_test(self, failed_test, message, error_lines=None): 101 """Insert a failure record into status.log for this test. 102 103 Args: 104 failed_test: Name of test that failed. 105 message: Reason test failed, will be put in status.log file. 106 error_lines: Additional failure info, will be put in ERROR log. 107 """ 108 # Create a test name subdirectory to hold the test status.log file. 109 test_dir = os.path.join(self._results_dir, failed_test) 110 if not os.path.exists(test_dir): 111 try: 112 os.makedirs(test_dir) 113 except OSError: 114 logging.exception('Failed to created test directory: %s', 115 test_dir) 116 117 # Record failure into the global job and test specific status files. 118 self._host.record('START', failed_test, failed_test) 119 self._host.record('INFO', failed_test, 'FAILED: ' + failed_test) 120 self._host.record('END FAIL', failed_test, failed_test, message) 121 122 # If we have additional information on the failure, create an error log 123 # file for this test in the location a normal autotest would have left 124 # it so the frontend knows where to find it. 125 if error_lines is not None: 126 fail_log_dir = os.path.join(test_dir, 'debug') 127 fail_log_path = os.path.join(fail_log_dir, failed_test + '.ERROR') 128 129 if not os.path.exists(fail_log_dir): 130 try: 131 os.makedirs(fail_log_dir) 132 except OSError: 133 logging.exception('Failed to created log directory: %s', 134 fail_log_dir) 135 return 136 try: 137 with open(fail_log_path, 'w') as fail_log: 138 fail_log.write(error_lines) 139 except IOError: 140 logging.exception('Failed to open log file: %s', fail_log_path) 141 142 def record_passed_test(self, passed_test): 143 """Insert a failure record into status.log for this test. 144 145 Args: 146 passed_test: Name of test that passed. 147 """ 148 self._host.record('START', None, passed_test) 149 self._host.record('INFO', None, 'PASSED: ' + passed_test) 150 self._host.record('END GOOD', None, passed_test) 151 152 153class gtest_parser(object): 154 """This class knows how to understand GTest test output. 155 156 The code was borrowed with minor changes from chrome utility gtest_command. 157 http://src.chromium.org/viewvc/chrome/trunk/tools/build/scripts/master/ 158 log_parser/gtest_command.py?view=markup 159 """ 160 161 def __init__(self): 162 # State tracking for log parsing 163 self._current_test = '' 164 self._failure_description = [] 165 self._current_suppression_hash = '' 166 self._current_suppression = [] 167 168 # Line number currently being processed. 169 self._line_number = 0 170 171 # List of parsing errors, as human-readable strings. 172 self.internal_error_lines = [] 173 174 # Tests are stored here as 'test.name': (status, [description]). 175 # The status should be one of ('started', 'OK', 'failed', 'timeout'). 176 # The description is a list of lines detailing the test's error, as 177 # reported in the log. 178 self._test_status = {} 179 180 # Suppressions are stored here as 'hash': [suppression]. 181 self._suppressions = {} 182 183 # This may be either text or a number. It will be used in the phrase 184 # '%s disabled' or '%s flaky' on the waterfall display. 185 self.disabled_tests = 0 186 self.flaky_tests = 0 187 188 # Regular expressions for parsing GTest logs. Test names look like 189 # SomeTestCase.SomeTest 190 # SomeName/SomeTestCase.SomeTest/1 191 # This regexp also matches SomeName.SomeTest/1, which should be 192 # harmless. 193 test_name_regexp = r'((\w+/)?\w+\.\w+(\.\w+)?(/\d+)?)' 194 self._test_start = re.compile('\[\s+RUN\s+\] ' + test_name_regexp) 195 self._test_ok = re.compile('\[\s+OK\s+\] ' + test_name_regexp) 196 self._test_fail = re.compile('\[\s+FAILED\s+\] ' + test_name_regexp) 197 self._test_timeout = re.compile( 198 'Test timeout \([0-9]+ ms\) exceeded for ' + test_name_regexp) 199 self._disabled = re.compile(' YOU HAVE (\d+) DISABLED TEST') 200 self._flaky = re.compile(' YOU HAVE (\d+) FLAKY TEST') 201 202 self._suppression_start = re.compile( 203 'Suppression \(error hash=#([0-9A-F]+)#\):') 204 self._suppression_end = re.compile('^}\s*$') 205 206 self._master_name_re = re.compile('\[Running for master: "([^"]*)"') 207 self.master_name = '' 208 209 self._error_logging_start_re = re.compile('=' * 70) 210 self._error_logging_test_name_re = re.compile( 211 '[FAIL|ERROR]: ' + test_name_regexp) 212 self._error_logging_end_re = re.compile('-' * 70) 213 self._error_logging_first_dash_found = False 214 215 def _TestsByStatus(self, status, include_fails, include_flaky): 216 """Returns list of tests with the given status. 217 218 Args: 219 status: test results status to search for. 220 include_fails: If False, tests containing 'FAILS_' anywhere in 221 their names will be excluded from the list. 222 include_flaky: If False, tests containing 'FLAKY_' anywhere in 223 their names will be excluded from the list. 224 Returns: 225 List of tests with the status. 226 """ 227 test_list = [x[0] for x in self._test_status.items() 228 if self._StatusOfTest(x[0]) == status] 229 230 if not include_fails: 231 test_list = [x for x in test_list if x.find('FAILS_') == -1] 232 if not include_flaky: 233 test_list = [x for x in test_list if x.find('FLAKY_') == -1] 234 235 return test_list 236 237 def _StatusOfTest(self, test): 238 """Returns the status code for the given test, or 'not known'.""" 239 test_status = self._test_status.get(test, ('not known', [])) 240 return test_status[0] 241 242 def _RecordError(self, line, reason): 243 """Record a log line that produced a parsing error. 244 245 Args: 246 line: text of the line at which the error occurred. 247 reason: a string describing the error. 248 """ 249 self.internal_error_lines.append("%s: %s [%s]" % (self._line_number, 250 line.strip(), 251 reason)) 252 253 def TotalTests(self): 254 """Returns the number of parsed tests.""" 255 return len(self._test_status) 256 257 def PassedTests(self): 258 """Returns list of tests that passed.""" 259 return self._TestsByStatus('OK', False, False) 260 261 def FailedTests(self, include_fails=False, include_flaky=False): 262 """Returns list of tests that failed, timed out, or didn't finish. 263 264 This list will be incorrect until the complete log has been processed, 265 because it will show currently running tests as having failed. 266 267 Args: 268 include_fails: If true, all failing tests with FAILS_ in their 269 names will be included. Otherwise, they will only be included 270 if they crashed. 271 include_flaky: If true, all failing tests with FLAKY_ in their 272 names will be included. Otherwise, they will only be included 273 if they crashed. 274 Returns: 275 List of failed tests. 276 """ 277 return (self._TestsByStatus('failed', include_fails, include_flaky) + 278 self._TestsByStatus('timeout', include_fails, include_flaky)) 279 280 def FailureDescription(self, test): 281 """Returns a list containing the failure description for the given test. 282 283 If the test didn't fail or timeout, returns []. 284 Args: 285 test: Name to test to find failure reason. 286 Returns: 287 List of test name, and failure string. 288 """ 289 test_status = self._test_status.get(test, ('', [])) 290 return test_status[1] 291 292 def SuppressionHashes(self): 293 """Returns list of suppression hashes found in the log.""" 294 return self._suppressions.keys() 295 296 def Suppression(self, suppression_hash): 297 """Returns a list containing the suppression for a given hash. 298 299 If the suppression hash doesn't exist, returns []. 300 301 Args: 302 suppression_hash: name of hash. 303 Returns: 304 List of suppression for the hash. 305 """ 306 return self._suppressions.get(suppression_hash, []) 307 308 def ProcessLogLine(self, line): 309 """This is called once with each line of the test log.""" 310 311 # Track line number for error messages. 312 self._line_number += 1 313 314 if not self.master_name: 315 results = self._master_name_re.search(line) 316 if results: 317 self.master_name = results.group(1) 318 319 # Is it a line reporting disabled tests? 320 results = self._disabled.search(line) 321 if results: 322 try: 323 disabled = int(results.group(1)) 324 except ValueError: 325 disabled = 0 326 if disabled > 0 and isinstance(self.disabled_tests, int): 327 self.disabled_tests += disabled 328 else: 329 # If we can't parse the line, at least give a heads-up. This is 330 # a safety net for a case that shouldn't happen but isn't a 331 # fatal error. 332 self.disabled_tests = 'some' 333 return 334 335 # Is it a line reporting flaky tests? 336 results = self._flaky.search(line) 337 if results: 338 try: 339 flaky = int(results.group(1)) 340 except ValueError: 341 flaky = 0 342 if flaky > 0 and isinstance(self.flaky_tests, int): 343 self.flaky_tests = flaky 344 else: 345 # If we can't parse the line, at least give a heads-up. This is 346 # a safety net for a case that shouldn't happen but isn't a 347 # fatal error. 348 self.flaky_tests = 'some' 349 return 350 351 # Is it the start of a test? 352 results = self._test_start.search(line) 353 if results: 354 test_name = results.group(1) 355 if test_name in self._test_status: 356 self._RecordError(line, 'test started more than once') 357 return 358 if self._current_test: 359 status = self._StatusOfTest(self._current_test) 360 if status in ('OK', 'failed', 'timeout'): 361 self._RecordError(line, 'start while in status %s' % status) 362 return 363 if status not in ('failed', 'timeout'): 364 self._test_status[self._current_test] = ( 365 'failed', self._failure_description) 366 self._test_status[test_name] = ('started', ['Did not complete.']) 367 self._current_test = test_name 368 self._failure_description = [] 369 return 370 371 # Is it a test success line? 372 results = self._test_ok.search(line) 373 if results: 374 test_name = results.group(1) 375 status = self._StatusOfTest(test_name) 376 if status != 'started': 377 self._RecordError(line, 'success while in status %s' % status) 378 return 379 self._test_status[test_name] = ('OK', []) 380 self._failure_description = [] 381 self._current_test = '' 382 return 383 384 # Is it a test failure line? 385 results = self._test_fail.search(line) 386 if results: 387 test_name = results.group(1) 388 status = self._StatusOfTest(test_name) 389 if status not in ('started', 'failed', 'timeout'): 390 self._RecordError(line, 'failure while in status %s' % status) 391 return 392 # Don't overwrite the failure description when a failing test is 393 # listed a second time in the summary, or if it was already 394 # recorded as timing out. 395 if status not in ('failed', 'timeout'): 396 self._test_status[test_name] = ('failed', 397 self._failure_description) 398 self._failure_description = [] 399 self._current_test = '' 400 return 401 402 # Is it a test timeout line? 403 results = self._test_timeout.search(line) 404 if results: 405 test_name = results.group(1) 406 status = self._StatusOfTest(test_name) 407 if status not in ('started', 'failed'): 408 self._RecordError(line, 'timeout while in status %s' % status) 409 return 410 self._test_status[test_name] = ( 411 'timeout', self._failure_description + ['Killed (timed out).']) 412 self._failure_description = [] 413 self._current_test = '' 414 return 415 416 # Is it the start of a new valgrind suppression? 417 results = self._suppression_start.search(line) 418 if results: 419 suppression_hash = results.group(1) 420 if suppression_hash in self._suppressions: 421 self._RecordError(line, 'suppression reported more than once') 422 return 423 self._suppressions[suppression_hash] = [] 424 self._current_suppression_hash = suppression_hash 425 self._current_suppression = [line] 426 return 427 428 # Is it the end of a valgrind suppression? 429 results = self._suppression_end.search(line) 430 if results and self._current_suppression_hash: 431 self._current_suppression.append(line) 432 self._suppressions[self._current_suppression_hash] = ( 433 self._current_suppression) 434 self._current_suppression_hash = '' 435 self._current_suppression = [] 436 return 437 438 # Is it the start of a test summary error message? 439 results = self._error_logging_test_name_re.search(line) 440 if results: 441 test_name = results.group(1) 442 self._test_status[test_name] = ('failed', ['Output not found.']) 443 self._current_test = test_name 444 self._failure_description = [] 445 self._error_logging_first_dash_found = False 446 return 447 448 # Is it the start of the next test summary signaling the end 449 # of the previous message? 450 results = self._error_logging_start_re.search(line) 451 if results and self._current_test: 452 self._test_status[self._current_test] = ('failed', 453 self._failure_description) 454 self._failure_description = [] 455 self._current_test = '' 456 return 457 458 # Is it the end of the extra test failure summaries? 459 results = self._error_logging_end_re.search(line) 460 if results and self._current_test: 461 if self._error_logging_first_dash_found: 462 self._test_status[self._current_test] = ( 463 'failed', self._failure_description) 464 self._failure_description = [] 465 self._current_test = '' 466 self._error_logging_first_dash_found = True 467 return 468 469 # Random line: if we're in a suppression, collect it. Suppressions are 470 # generated after all tests are finished, so this should always belong 471 # to the current suppression hash. 472 if self._current_suppression_hash: 473 self._current_suppression.append(line) 474 return 475 476 # Random line: if we're in a test, collect it for the failure 477 # description. Tests may run simultaneously, so this might be off, but 478 # it's worth a try. 479 if self._current_test: 480 self._failure_description.append(line) 481