gtest_utils.py 23 KB

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