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 self._TestsByStatus('started', include_fails, include_flaky)) 280 281 def FailureDescription(self, test): 282 """Returns a list containing the failure description for the given test. 283 284 If the test didn't fail or timeout, returns []. 285 Args: 286 test: Name to test to find failure reason. 287 Returns: 288 List of test name, and failure string. 289 """ 290 test_status = self._test_status.get(test, ('', [])) 291 return test_status[1] 292 293 def SuppressionHashes(self): 294 """Returns list of suppression hashes found in the log.""" 295 return self._suppressions.keys() 296 297 def Suppression(self, suppression_hash): 298 """Returns a list containing the suppression for a given hash. 299 300 If the suppression hash doesn't exist, returns []. 301 302 Args: 303 suppression_hash: name of hash. 304 Returns: 305 List of suppression for the hash. 306 """ 307 return self._suppressions.get(suppression_hash, []) 308 309 def ProcessLogLine(self, line): 310 """This is called once with each line of the test log.""" 311 312 # Track line number for error messages. 313 self._line_number += 1 314 315 if not self.master_name: 316 results = self._master_name_re.search(line) 317 if results: 318 self.master_name = results.group(1) 319 320 # Is it a line reporting disabled tests? 321 results = self._disabled.search(line) 322 if results: 323 try: 324 disabled = int(results.group(1)) 325 except ValueError: 326 disabled = 0 327 if disabled > 0 and isinstance(self.disabled_tests, int): 328 self.disabled_tests += disabled 329 else: 330 # If we can't parse the line, at least give a heads-up. This is 331 # a safety net for a case that shouldn't happen but isn't a 332 # fatal error. 333 self.disabled_tests = 'some' 334 return 335 336 # Is it a line reporting flaky tests? 337 results = self._flaky.search(line) 338 if results: 339 try: 340 flaky = int(results.group(1)) 341 except ValueError: 342 flaky = 0 343 if flaky > 0 and isinstance(self.flaky_tests, int): 344 self.flaky_tests = flaky 345 else: 346 # If we can't parse the line, at least give a heads-up. This is 347 # a safety net for a case that shouldn't happen but isn't a 348 # fatal error. 349 self.flaky_tests = 'some' 350 return 351 352 # Is it the start of a test? 353 results = self._test_start.search(line) 354 if results: 355 test_name = results.group(1) 356 if test_name in self._test_status: 357 self._RecordError(line, 'test started more than once') 358 return 359 if self._current_test: 360 status = self._StatusOfTest(self._current_test) 361 if status in ('OK', 'failed', 'timeout'): 362 self._RecordError(line, 'start while in status %s' % status) 363 return 364 if status not in ('failed', 'timeout'): 365 self._test_status[self._current_test] = ( 366 'failed', self._failure_description) 367 self._test_status[test_name] = ('started', ['Did not complete.']) 368 self._current_test = test_name 369 self._failure_description = [] 370 return 371 372 # Is it a test success line? 373 results = self._test_ok.search(line) 374 if results: 375 test_name = results.group(1) 376 status = self._StatusOfTest(test_name) 377 if status != 'started': 378 self._RecordError(line, 'success while in status %s' % status) 379 return 380 self._test_status[test_name] = ('OK', []) 381 self._failure_description = [] 382 self._current_test = '' 383 return 384 385 # Is it a test failure line? 386 results = self._test_fail.search(line) 387 if results: 388 test_name = results.group(1) 389 status = self._StatusOfTest(test_name) 390 if status not in ('started', 'failed', 'timeout'): 391 self._RecordError(line, 'failure while in status %s' % status) 392 return 393 # Don't overwrite the failure description when a failing test is 394 # listed a second time in the summary, or if it was already 395 # recorded as timing out. 396 if status not in ('failed', 'timeout'): 397 self._test_status[test_name] = ('failed', 398 self._failure_description) 399 self._failure_description = [] 400 self._current_test = '' 401 return 402 403 # Is it a test timeout line? 404 results = self._test_timeout.search(line) 405 if results: 406 test_name = results.group(1) 407 status = self._StatusOfTest(test_name) 408 if status not in ('started', 'failed'): 409 self._RecordError(line, 'timeout while in status %s' % status) 410 return 411 self._test_status[test_name] = ( 412 'timeout', self._failure_description + ['Killed (timed out).']) 413 self._failure_description = [] 414 self._current_test = '' 415 return 416 417 # Is it the start of a new valgrind suppression? 418 results = self._suppression_start.search(line) 419 if results: 420 suppression_hash = results.group(1) 421 if suppression_hash in self._suppressions: 422 self._RecordError(line, 'suppression reported more than once') 423 return 424 self._suppressions[suppression_hash] = [] 425 self._current_suppression_hash = suppression_hash 426 self._current_suppression = [line] 427 return 428 429 # Is it the end of a valgrind suppression? 430 results = self._suppression_end.search(line) 431 if results and self._current_suppression_hash: 432 self._current_suppression.append(line) 433 self._suppressions[self._current_suppression_hash] = ( 434 self._current_suppression) 435 self._current_suppression_hash = '' 436 self._current_suppression = [] 437 return 438 439 # Is it the start of a test summary error message? 440 results = self._error_logging_test_name_re.search(line) 441 if results: 442 test_name = results.group(1) 443 self._test_status[test_name] = ('failed', ['Output not found.']) 444 self._current_test = test_name 445 self._failure_description = [] 446 self._error_logging_first_dash_found = False 447 return 448 449 # Is it the start of the next test summary signaling the end 450 # of the previous message? 451 results = self._error_logging_start_re.search(line) 452 if results and self._current_test: 453 self._test_status[self._current_test] = ('failed', 454 self._failure_description) 455 self._failure_description = [] 456 self._current_test = '' 457 return 458 459 # Is it the end of the extra test failure summaries? 460 results = self._error_logging_end_re.search(line) 461 if results and self._current_test: 462 if self._error_logging_first_dash_found: 463 self._test_status[self._current_test] = ( 464 'failed', self._failure_description) 465 self._failure_description = [] 466 self._current_test = '' 467 self._error_logging_first_dash_found = True 468 return 469 470 # Random line: if we're in a suppression, collect it. Suppressions are 471 # generated after all tests are finished, so this should always belong 472 # to the current suppression hash. 473 if self._current_suppression_hash: 474 self._current_suppression.append(line) 475 return 476 477 # Random line: if we're in a test, collect it for the failure 478 # description. Tests may run simultaneously, so this might be off, but 479 # it's worth a try. 480 if self._current_test: 481 self._failure_description.append(line) 482