Index: Tools/AutoSheriff/gtest_utils.py |
diff --git a/Tools/AutoSheriff/gtest_utils.py b/Tools/AutoSheriff/gtest_utils.py |
new file mode 100755 |
index 0000000000000000000000000000000000000000..0e1c17059687f8a903036f6d14227de7e0973144 |
--- /dev/null |
+++ b/Tools/AutoSheriff/gtest_utils.py |
@@ -0,0 +1,520 @@ |
+#!/usr/bin/env python |
+# Copyright (c) 2012 The Chromium Authors. All rights reserved. |
+# Use of this source code is governed by a BSD-style license that can be |
+# found in the LICENSE file. |
+ |
+import json |
+import os |
+import re |
+import tempfile |
+ |
+ |
+def CompressList(lines, max_length, middle_replacement): |
+ """Ensures that |lines| is no longer than |max_length|. If |lines| need to |
+ be compressed then the middle items are replaced by |middle_replacement|. |
+ """ |
+ if len(lines) <= max_length: |
+ return lines |
+ remove_from_start = max_length / 2 |
+ return (lines[:remove_from_start] + |
+ [middle_replacement] + |
+ lines[len(lines) - (max_length - remove_from_start):]) |
+ |
+ |
+class GTestLogParser(object): |
+ """This helper class process GTest test output.""" |
+ |
+ def __init__(self): |
+ # State tracking for log parsing |
+ self.completed = False |
+ self._current_test = '' |
+ self._failure_description = [] |
+ self._current_suppression_hash = '' |
+ self._current_suppression = [] |
+ self._parsing_failures = False |
+ |
+ # Line number currently being processed. |
+ self._line_number = 0 |
+ |
+ # List of parsing errors, as human-readable strings. |
+ self._internal_error_lines = [] |
+ |
+ # Tests are stored here as 'test.name': (status, [description]). |
+ # The status should be one of ('started', 'OK', 'failed', 'timeout', |
+ # 'warning'). Warning indicates that a test did not pass when run in |
+ # parallel with other tests but passed when run alone. The description is |
+ # a list of lines detailing the test's error, as reported in the log. |
+ self._test_status = {} |
+ |
+ # Suppressions are stored here as 'hash': [suppression]. |
+ self._suppressions = {} |
+ |
+ # This may be either text or a number. It will be used in the phrase |
+ # '%s disabled' or '%s flaky' on the waterfall display. |
+ self._disabled_tests = 0 |
+ self._flaky_tests = 0 |
+ |
+ # Regular expressions for parsing GTest logs. Test names look like |
+ # SomeTestCase.SomeTest |
+ # SomeName/SomeTestCase.SomeTest/1 |
+ # This regexp also matches SomeName.SomeTest/1, which should be harmless. |
+ test_name_regexp = r'((\w+/)?\w+\.\w+(/\d+)?)' |
+ |
+ self._master_name_re = re.compile('\[Running for master: "([^"]*)"') |
+ self.master_name = '' |
+ |
+ self._test_name = re.compile(test_name_regexp) |
+ self._test_start = re.compile('\[\s+RUN\s+\] ' + test_name_regexp) |
+ self._test_ok = re.compile('\[\s+OK\s+\] ' + test_name_regexp) |
+ self._test_fail = re.compile('\[\s+FAILED\s+\] ' + test_name_regexp) |
+ self._test_passed = re.compile('\[\s+PASSED\s+\] \d+ tests?.') |
+ self._run_test_cases_line = re.compile( |
+ '\[\s*\d+\/\d+\]\s+[0-9\.]+s ' + test_name_regexp + ' .+') |
+ self._test_timeout = re.compile( |
+ 'Test timeout \([0-9]+ ms\) exceeded for ' + test_name_regexp) |
+ self._disabled = re.compile('\s*YOU HAVE (\d+) DISABLED TEST') |
+ self._flaky = re.compile('\s*YOU HAVE (\d+) FLAKY TEST') |
+ |
+ self._suppression_start = re.compile( |
+ 'Suppression \(error hash=#([0-9A-F]+)#\):') |
+ self._suppression_end = re.compile('^}\s*$') |
+ |
+ self._retry_message = re.compile('RETRYING FAILED TESTS:') |
+ self.retrying_failed = False |
+ |
+ def GetCurrentTest(self): |
+ return self._current_test |
+ |
+ def _StatusOfTest(self, test): |
+ """Returns the status code for the given test, or 'not known'.""" |
+ test_status = self._test_status.get(test, ('not known', [])) |
+ return test_status[0] |
+ |
+ def _TestsByStatus(self, status, include_fails, include_flaky): |
+ """Returns list of tests with the given status. |
+ |
+ Args: |
+ include_fails: If False, tests containing 'FAILS_' anywhere in their |
+ names will be excluded from the list. |
+ include_flaky: If False, tests containing 'FLAKY_' anywhere in their |
+ names will be excluded from the list. |
+ """ |
+ test_list = [x[0] for x in self._test_status.items() |
+ if self._StatusOfTest(x[0]) == status] |
+ |
+ if not include_fails: |
+ test_list = [x for x in test_list if x.find('FAILS_') == -1] |
+ if not include_flaky: |
+ test_list = [x for x in test_list if x.find('FLAKY_') == -1] |
+ |
+ return test_list |
+ |
+ def _RecordError(self, line, reason): |
+ """Record a log line that produced a parsing error. |
+ |
+ Args: |
+ line: text of the line at which the error occurred |
+ reason: a string describing the error |
+ """ |
+ self._internal_error_lines.append('%s: %s [%s]' % |
+ (self._line_number, line.strip(), reason)) |
+ |
+ def RunningTests(self): |
+ """Returns list of tests that appear to be currently running.""" |
+ return self._TestsByStatus('started', True, True) |
+ |
+ def ParsingErrors(self): |
+ """Returns a list of lines that have caused parsing errors.""" |
+ return self._internal_error_lines |
+ |
+ def ClearParsingErrors(self): |
+ """Clears the currently stored parsing errors.""" |
+ self._internal_error_lines = ['Cleared.'] |
+ |
+ def PassedTests(self): |
+ """Returns list of tests that passed.""" |
+ return self._TestsByStatus('OK', False, False) |
+ |
+ def FailedTests(self, include_fails=False, include_flaky=False): |
+ """Returns list of tests that failed, timed out, or didn't finish |
+ (crashed). |
+ |
+ This list will be incorrect until the complete log has been processed, |
+ because it will show currently running tests as having failed. |
+ |
+ Args: |
+ include_fails: If true, all failing tests with FAILS_ in their names will |
+ be included. Otherwise, they will only be included if they crashed or |
+ timed out. |
+ include_flaky: If true, all failing tests with FLAKY_ in their names will |
+ be included. Otherwise, they will only be included if they crashed or |
+ timed out. |
+ |
+ """ |
+ return (self._TestsByStatus('failed', include_fails, include_flaky) + |
+ self._TestsByStatus('timeout', True, True) + |
+ self._TestsByStatus('warning', include_fails, include_flaky) + |
+ self.RunningTests()) |
+ |
+ def DisabledTests(self): |
+ """Returns the name of the disabled test (if there is only 1) or the number |
+ of disabled tests. |
+ """ |
+ return self._disabled_tests |
+ |
+ def FlakyTests(self): |
+ """Returns the name of the flaky test (if there is only 1) or the number |
+ of flaky tests. |
+ """ |
+ return self._flaky_tests |
+ |
+ def FailureDescription(self, test): |
+ """Returns a list containing the failure description for the given test. |
+ |
+ If the test didn't fail or timeout, returns []. |
+ """ |
+ test_status = self._test_status.get(test, ('', [])) |
+ return ['%s: ' % test] + test_status[1] |
+ |
+ def SuppressionHashes(self): |
+ """Returns list of suppression hashes found in the log.""" |
+ return self._suppressions.keys() |
+ |
+ def Suppression(self, suppression_hash): |
+ """Returns a list containing the suppression for a given hash. |
+ |
+ If the suppression hash doesn't exist, returns []. |
+ """ |
+ return self._suppressions.get(suppression_hash, []) |
+ |
+ def CompletedWithoutFailure(self): |
+ """Returns True if all tests completed and no tests failed unexpectedly.""" |
+ return self.completed and not self.FailedTests() |
+ |
+ def ProcessLine(self, line): |
+ """This is called once with each line of the test log.""" |
+ |
+ # Track line number for error messages. |
+ self._line_number += 1 |
+ |
+ # Some tests (net_unittests in particular) run subprocesses which can write |
+ # stuff to shared stdout buffer. Sometimes such output appears between new |
+ # line and gtest directives ('[ RUN ]', etc) which breaks the parser. |
+ # Code below tries to detect such cases and recognize a mixed line as two |
+ # separate lines. |
+ |
+ # List of regexps that parses expects to find at the start of a line but |
+ # which can be somewhere in the middle. |
+ gtest_regexps = [ |
+ self._test_start, |
+ self._test_ok, |
+ self._test_fail, |
+ self._test_passed, |
+ ] |
+ |
+ for regexp in gtest_regexps: |
+ match = regexp.search(line) |
+ if match: |
+ break |
+ |
+ if not match or match.start() == 0: |
+ self._ProcessLine(line) |
+ else: |
+ self._ProcessLine(line[:match.start()]) |
+ self._ProcessLine(line[match.start():]) |
+ |
+ def _ProcessLine(self, line): |
+ """Parses the line and changes the state of parsed tests accordingly. |
+ |
+ Will recognize newly started tests, OK or FAILED statuses, timeouts, etc. |
+ """ |
+ |
+ # Note: When sharding, the number of disabled and flaky tests will be read |
+ # multiple times, so this will only show the most recent values (but they |
+ # should all be the same anyway). |
+ |
+ # Is it a line listing the master name? |
+ if not self.master_name: |
+ results = self._master_name_re.match(line) |
+ if results: |
+ self.master_name = results.group(1) |
+ |
+ results = self._run_test_cases_line.match(line) |
+ if results: |
+ # A run_test_cases.py output. |
+ if self._current_test: |
+ if self._test_status[self._current_test][0] == 'started': |
+ self._test_status[self._current_test] = ( |
+ 'timeout', self._failure_description) |
+ self._current_test = '' |
+ self._failure_description = [] |
+ return |
+ |
+ # Is it a line declaring all tests passed? |
+ results = self._test_passed.match(line) |
+ if results: |
+ self.completed = True |
+ self._current_test = '' |
+ return |
+ |
+ # Is it a line reporting disabled tests? |
+ results = self._disabled.match(line) |
+ if results: |
+ try: |
+ disabled = int(results.group(1)) |
+ except ValueError: |
+ disabled = 0 |
+ if disabled > 0 and isinstance(self._disabled_tests, int): |
+ self._disabled_tests = disabled |
+ else: |
+ # If we can't parse the line, at least give a heads-up. This is a |
+ # safety net for a case that shouldn't happen but isn't a fatal error. |
+ self._disabled_tests = 'some' |
+ return |
+ |
+ # Is it a line reporting flaky tests? |
+ results = self._flaky.match(line) |
+ if results: |
+ try: |
+ flaky = int(results.group(1)) |
+ except ValueError: |
+ flaky = 0 |
+ if flaky > 0 and isinstance(self._flaky_tests, int): |
+ self._flaky_tests = flaky |
+ else: |
+ # If we can't parse the line, at least give a heads-up. This is a |
+ # safety net for a case that shouldn't happen but isn't a fatal error. |
+ self._flaky_tests = 'some' |
+ return |
+ |
+ # Is it the start of a test? |
+ results = self._test_start.match(line) |
+ if results: |
+ if self._current_test: |
+ if self._test_status[self._current_test][0] == 'started': |
+ self._test_status[self._current_test] = ( |
+ 'timeout', self._failure_description) |
+ test_name = results.group(1) |
+ self._test_status[test_name] = ('started', ['Did not complete.']) |
+ self._current_test = test_name |
+ if self.retrying_failed: |
+ self._failure_description = self._test_status[test_name][1] |
+ self._failure_description.extend(['', 'RETRY OUTPUT:', '']) |
+ else: |
+ self._failure_description = [] |
+ return |
+ |
+ # Is it a test success line? |
+ results = self._test_ok.match(line) |
+ if results: |
+ test_name = results.group(1) |
+ status = self._StatusOfTest(test_name) |
+ if status != 'started': |
+ self._RecordError(line, 'success while in status %s' % status) |
+ if self.retrying_failed: |
+ self._test_status[test_name] = ('warning', self._failure_description) |
+ else: |
+ self._test_status[test_name] = ('OK', []) |
+ self._failure_description = [] |
+ self._current_test = '' |
+ return |
+ |
+ # Is it a test failure line? |
+ results = self._test_fail.match(line) |
+ if results: |
+ test_name = results.group(1) |
+ status = self._StatusOfTest(test_name) |
+ if status not in ('started', 'failed', 'timeout'): |
+ self._RecordError(line, 'failure while in status %s' % status) |
+ # Don't overwrite the failure description when a failing test is listed a |
+ # second time in the summary, or if it was already recorded as timing |
+ # out. |
+ if status not in ('failed', 'timeout'): |
+ self._test_status[test_name] = ('failed', self._failure_description) |
+ self._failure_description = [] |
+ self._current_test = '' |
+ return |
+ |
+ # Is it a test timeout line? |
+ results = self._test_timeout.search(line) |
+ if results: |
+ test_name = results.group(1) |
+ status = self._StatusOfTest(test_name) |
+ if status not in ('started', 'failed'): |
+ self._RecordError(line, 'timeout while in status %s' % status) |
+ self._test_status[test_name] = ( |
+ 'timeout', self._failure_description + ['Killed (timed out).']) |
+ self._failure_description = [] |
+ self._current_test = '' |
+ return |
+ |
+ # Is it the start of a new valgrind suppression? |
+ results = self._suppression_start.match(line) |
+ if results: |
+ suppression_hash = results.group(1) |
+ if suppression_hash in self._suppressions: |
+ self._RecordError(line, 'suppression reported more than once') |
+ self._suppressions[suppression_hash] = [] |
+ self._current_suppression_hash = suppression_hash |
+ self._current_suppression = [line] |
+ return |
+ |
+ # Is it the end of a valgrind suppression? |
+ results = self._suppression_end.match(line) |
+ if results and self._current_suppression_hash: |
+ self._current_suppression.append(line) |
+ self._suppressions[self._current_suppression_hash] = ( |
+ self._current_suppression) |
+ self._current_suppression_hash = '' |
+ self._current_suppression = [] |
+ return |
+ |
+ # Is it the start of the retry tests? |
+ results = self._retry_message.match(line) |
+ if results: |
+ self.retrying_failed = True |
+ return |
+ |
+ # Random line: if we're in a suppression, collect it. Suppressions are |
+ # generated after all tests are finished, so this should always belong to |
+ # the current suppression hash. |
+ if self._current_suppression_hash: |
+ self._current_suppression.append(line) |
+ return |
+ |
+ # Random line: if we're in a test, collect it for the failure description. |
+ # Tests may run simultaneously, so this might be off, but it's worth a try. |
+ # This also won't work if a test times out before it begins running. |
+ if self._current_test: |
+ self._failure_description.append(line) |
+ |
+ # Parse the "Failing tests:" list at the end of the output, and add any |
+ # additional failed tests to the list. For example, this includes tests |
+ # that crash after the OK line. |
+ if self._parsing_failures: |
+ results = self._test_name.match(line) |
+ if results: |
+ test_name = results.group(1) |
+ status = self._StatusOfTest(test_name) |
+ if status in ('not known', 'OK'): |
+ self._test_status[test_name] = ( |
+ 'failed', ['Unknown error, see stdio log.']) |
+ else: |
+ self._parsing_failures = False |
+ elif line.startswith('Failing tests:'): |
+ self._parsing_failures = True |
+ |
+ |
+class GTestJSONParser(object): |
+ # Limit of output snippet lines. Avoids flooding the logs with amount |
+ # of output that gums up the infrastructure. |
+ OUTPUT_SNIPPET_LINES_LIMIT = 5000 |
+ |
+ def __init__(self): |
+ self.json_file_path = None |
+ self.delete_json_file = False |
+ |
+ self.disabled_tests = set() |
+ self.passed_tests = set() |
+ self.failed_tests = set() |
+ self.flaky_tests = set() |
+ self.test_logs = {} |
+ |
+ self.parsing_errors = [] |
+ |
+ self.master_name = None |
+ |
+ def ProcessLine(self, line): |
+ # Deliberately do nothing - we parse out-of-band JSON summary |
+ # instead of in-band stdout. |
+ pass |
+ |
+ def PassedTests(self): |
+ return sorted(self.passed_tests) |
+ |
+ def FailedTests(self, include_fails=False, include_flaky=False): |
+ return sorted(self.failed_tests) |
+ |
+ def FailureDescription(self, test): |
+ return self.test_logs.get(test, []) |
+ |
+ @staticmethod |
+ def SuppressionHashes(): |
+ return [] |
+ |
+ def ParsingErrors(self): |
+ return self.parsing_errors |
+ |
+ def ClearParsingErrors(self): |
+ self.parsing_errors = ['Cleared.'] |
+ |
+ def DisabledTests(self): |
+ return len(self.disabled_tests) |
+ |
+ def FlakyTests(self): |
+ return len(self.flaky_tests) |
+ |
+ @staticmethod |
+ def RunningTests(): |
+ return [] |
+ |
+ def PrepareJSONFile(self, cmdline_path): |
+ if cmdline_path: |
+ self.json_file_path = cmdline_path |
+ # If the caller requested JSON summary, do not delete it. |
+ self.delete_json_file = False |
+ else: |
+ fd, self.json_file_path = tempfile.mkstemp() |
+ os.close(fd) |
+ # When we create the file ourselves, delete it to avoid littering. |
+ self.delete_json_file = True |
+ return self.json_file_path |
+ |
+ def ProcessJSONFile(self): |
+ if not self.json_file_path: |
+ return |
+ |
+ with open(self.json_file_path) as json_file: |
+ try: |
+ json_output = json_file.read() |
+ json_data = json.loads(json_output) |
+ except ValueError: |
+ # Only signal parsing error if the file is non-empty. Empty file |
+ # most likely means the binary doesn't support JSON output. |
+ if json_output: |
+ self.parsing_errors = json_output.split('\n') |
+ else: |
+ self.ProcessJSONData(json_data) |
+ |
+ if self.delete_json_file: |
+ os.remove(self.json_file_path) |
+ |
+ def ProcessJSONData(self, json_data): |
+ # TODO(phajdan.jr): Require disabled_tests to be present (May 2014). |
+ self.disabled_tests.update(json_data.get('disabled_tests', [])) |
+ |
+ for iteration_data in json_data['per_iteration_data']: |
+ for test_name, test_runs in iteration_data.iteritems(): |
+ if test_runs[-1]['status'] == 'SUCCESS': |
+ self.passed_tests.add(test_name) |
+ else: |
+ self.failed_tests.add(test_name) |
+ |
+ if len(test_runs) > 1: |
+ self.flaky_tests.add(test_name) |
+ |
+ self.test_logs.setdefault(test_name, []) |
+ for run_index, run_data in enumerate(test_runs, start=1): |
+ run_lines = ['%s (run #%d):' % (test_name, run_index)] |
+ # Make sure the annotations are ASCII to avoid character set related |
+ # errors. They are mostly informational anyway, and more detailed |
+ # info can be obtained from the original JSON output. |
+ ascii_lines = run_data['output_snippet'].encode('ascii', |
+ errors='replace') |
+ decoded_lines = CompressList( |
+ ascii_lines.decode('string_escape').split('\n'), |
+ self.OUTPUT_SNIPPET_LINES_LIMIT, |
+ '<truncated, full output is in gzipped JSON ' |
+ 'output at end of step>') |
+ run_lines.extend(decoded_lines) |
+ self.test_logs[test_name].extend(run_lines) |