xctest_utils.py 12 KB

123456789101112131415161718192021222324252627282930313233343536373839404142434445464748495051525354555657585960616263646566676869707172737475767778798081828384858687888990919293949596979899100101102103104105106107108109110111112113114115116117118119120121122123124125126127128129130131132133134135136137138139140141142143144145146147148149150151152153154155156157158159160161162163164165166167168169170171172173174175176177178179180181182183184185186187188189190191192193194195196197198199200201202203204205206207208209210211212213214215216217218219220221222223224225226227228229230231232233234235236237238239240241242243244245246247248249250251252253254255256257258259260261262263264265266267268269270271272273274275276277278279280281282283284285286287288289290291292293294295296297298299300301302303304305306307308309310311312313314315316317318319320321322323324325326327328329330
  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 re
  5. from test_result_util import ResultCollection, TestResult, TestStatus
  6. # These labels should match the ones output by gtest's JSON.
  7. TEST_UNKNOWN_LABEL = 'UNKNOWN'
  8. TEST_SUCCESS_LABEL = 'SUCCESS'
  9. TEST_FAILURE_LABEL = 'FAILURE'
  10. TEST_CRASH_LABEL = 'CRASH'
  11. TEST_TIMEOUT_LABEL = 'TIMEOUT'
  12. TEST_WARNING_LABEL = 'WARNING'
  13. class XCTestLogParser(object):
  14. """This helper class process XCTest test output."""
  15. def __init__(self):
  16. # Test results from the parser.
  17. self._result_collection = ResultCollection()
  18. # State tracking for log parsing
  19. self.completed = False
  20. self._current_test = ''
  21. self._failure_description = []
  22. self._current_report_hash = ''
  23. self._current_report = []
  24. self._parsing_failures = False
  25. # Line number currently being processed.
  26. self._line_number = 0
  27. # List of parsing errors, as human-readable strings.
  28. self._internal_error_lines = []
  29. # Tests are stored here as 'test.name': (status, [description]).
  30. # The status should be one of ('started', 'OK', 'failed', 'timeout',
  31. # 'warning'). Warning indicates that a test did not pass when run in
  32. # parallel with other tests but passed when run alone. The description is
  33. # a list of lines detailing the test's error, as reported in the log.
  34. self._test_status = {}
  35. # This may be either text or a number. It will be used in the phrase
  36. # '%s disabled' or '%s flaky' on the waterfall display.
  37. self._disabled_tests = 0
  38. self._flaky_tests = 0
  39. test_name_regexp = r'\-\[(\w+)\s(\w+)\]'
  40. self._test_name = re.compile(test_name_regexp)
  41. self._test_start = re.compile(
  42. r'Test Case \'' + test_name_regexp + '\' started\.')
  43. self._test_ok = re.compile(
  44. r'Test Case \'' + test_name_regexp +
  45. '\' passed\s+\(\d+\.\d+\s+seconds\)?.')
  46. self._test_fail = re.compile(
  47. r'Test Case \'' + test_name_regexp +
  48. '\' failed\s+\(\d+\.\d+\s+seconds\)?.')
  49. self._test_execute_succeeded = re.compile(
  50. r'\*\*\s+TEST\s+EXECUTE\s+SUCCEEDED\s+\*\*')
  51. self._test_execute_failed = re.compile(
  52. r'\*\*\s+TEST\s+EXECUTE\s+FAILED\s+\*\*')
  53. self._retry_message = re.compile('RETRYING FAILED TESTS:')
  54. self.retrying_failed = False
  55. self._system_alert_present_message = re.compile(
  56. r'\bSystem alert view is present, so skipping all tests\b')
  57. self.system_alert_present = False
  58. self.TEST_STATUS_MAP = {
  59. 'OK': TEST_SUCCESS_LABEL,
  60. 'failed': TEST_FAILURE_LABEL,
  61. 'timeout': TEST_TIMEOUT_LABEL,
  62. 'warning': TEST_WARNING_LABEL
  63. }
  64. def Finalize(self):
  65. """Finalize for |self._result_collection|.
  66. Called at the end to add unfinished tests and crash status for
  67. self._result_collection.
  68. """
  69. for test in self.RunningTests():
  70. self._result_collection.add_test_result(
  71. TestResult(test[0], TestStatus.CRASH, test_log='Did not complete.'))
  72. if not self.completed:
  73. self._result_collection.crashed = True
  74. def GetResultCollection(self):
  75. return self._result_collection
  76. def GetCurrentTest(self):
  77. return self._current_test
  78. def _StatusOfTest(self, test):
  79. """Returns the status code for the given test, or 'not known'."""
  80. test_status = self._test_status.get(test, ('not known', []))
  81. return test_status[0]
  82. def _TestsByStatus(self, status, include_fails, include_flaky):
  83. """Returns list of tests with the given status.
  84. Args:
  85. include_fails: If False, tests containing 'FAILS_' anywhere in their
  86. names will be excluded from the list.
  87. include_flaky: If False, tests containing 'FLAKY_' anywhere in their
  88. names will be excluded from the list.
  89. """
  90. test_list = [x[0] for x in self._test_status.items()
  91. if self._StatusOfTest(x[0]) == status]
  92. if not include_fails:
  93. test_list = [x for x in test_list if x.find('FAILS_') == -1]
  94. if not include_flaky:
  95. test_list = [x for x in test_list if x.find('FLAKY_') == -1]
  96. return test_list
  97. def _RecordError(self, line, reason):
  98. """Record a log line that produced a parsing error.
  99. Args:
  100. line: text of the line at which the error occurred
  101. reason: a string describing the error
  102. """
  103. self._internal_error_lines.append('%s: %s [%s]' %
  104. (self._line_number, line.strip(), reason))
  105. def RunningTests(self):
  106. """Returns list of tests that appear to be currently running."""
  107. return self._TestsByStatus('started', True, True)
  108. def ParsingErrors(self):
  109. """Returns a list of lines that have caused parsing errors."""
  110. return self._internal_error_lines
  111. def ClearParsingErrors(self):
  112. """Clears the currently stored parsing errors."""
  113. self._internal_error_lines = ['Cleared.']
  114. def PassedTests(self, include_fails=False, include_flaky=False):
  115. """Returns list of tests that passed."""
  116. return self._TestsByStatus('OK', include_fails, include_flaky)
  117. def FailedTests(self, include_fails=False, include_flaky=False):
  118. """Returns list of tests that failed, timed out, or didn't finish
  119. (crashed).
  120. This list will be incorrect until the complete log has been processed,
  121. because it will show currently running tests as having failed.
  122. Args:
  123. include_fails: If true, all failing tests with FAILS_ in their names will
  124. be included. Otherwise, they will only be included if they crashed or
  125. timed out.
  126. include_flaky: If true, all failing tests with FLAKY_ in their names will
  127. be included. Otherwise, they will only be included if they crashed or
  128. timed out.
  129. """
  130. return (self._TestsByStatus('failed', include_fails, include_flaky) +
  131. self._TestsByStatus('timeout', True, True) +
  132. self._TestsByStatus('warning', include_fails, include_flaky) +
  133. self.RunningTests())
  134. def TriesForTest(self, test):
  135. """Returns a list containing the state for all tries of the given test.
  136. This parser doesn't support retries so a single result is returned."""
  137. return [self.TEST_STATUS_MAP.get(self._StatusOfTest(test),
  138. TEST_UNKNOWN_LABEL)]
  139. def FailureDescription(self, test):
  140. """Returns a list containing the failure description for the given test.
  141. If the test didn't fail or timeout, returns [].
  142. """
  143. test_status = self._test_status.get(test, ('', []))
  144. return ['%s: ' % test] + test_status[1]
  145. def CompletedWithoutFailure(self):
  146. """Returns True if all tests completed and no tests failed unexpectedly."""
  147. return self.completed and not self.FailedTests()
  148. def SystemAlertPresent(self):
  149. """Returns a bool indicating whether a system alert is shown on device."""
  150. return self.system_alert_present
  151. def ProcessLine(self, line):
  152. """This is called once with each line of the test log."""
  153. # Track line number for error messages.
  154. self._line_number += 1
  155. # Some tests (net_unittests in particular) run subprocesses which can write
  156. # stuff to shared stdout buffer. Sometimes such output appears between new
  157. # line and gtest directives ('[ RUN ]', etc) which breaks the parser.
  158. # Code below tries to detect such cases and recognize a mixed line as two
  159. # separate lines.
  160. # List of regexps that parses expects to find at the start of a line but
  161. # which can be somewhere in the middle.
  162. gtest_regexps = [
  163. self._test_start,
  164. self._test_ok,
  165. self._test_fail,
  166. self._test_execute_failed,
  167. self._test_execute_succeeded,
  168. ]
  169. for regexp in gtest_regexps:
  170. match = regexp.search(line)
  171. if match:
  172. break
  173. if not match or match.start() == 0:
  174. self._ProcessLine(line)
  175. else:
  176. self._ProcessLine(line[:match.start()])
  177. self._ProcessLine(line[match.start():])
  178. def _ProcessLine(self, line):
  179. """Parses the line and changes the state of parsed tests accordingly.
  180. Will recognize newly started tests, OK or FAILED statuses, timeouts, etc.
  181. """
  182. # Is it a line declaring end of all tests?
  183. succeeded = self._test_execute_succeeded.match(line)
  184. failed = self._test_execute_failed.match(line)
  185. if succeeded or failed:
  186. self.completed = True
  187. self._current_test = ''
  188. return
  189. # Is it a line declaring a system alert is shown on the device?
  190. results = self._system_alert_present_message.search(line)
  191. if results:
  192. self.system_alert_present = True
  193. self._current_test = ''
  194. return
  195. # Is it the start of a test?
  196. results = self._test_start.match(line)
  197. if results:
  198. if self._current_test:
  199. if self._test_status[self._current_test][0] == 'started':
  200. self._test_status[self._current_test] = (
  201. 'timeout', self._failure_description)
  202. self._result_collection.add_test_result(
  203. TestResult(
  204. self._current_test,
  205. TestStatus.ABORT,
  206. test_log='\n'.join(self._failure_description)))
  207. test_name = '%s/%s' % (results.group(1), results.group(2))
  208. self._test_status[test_name] = ('started', ['Did not complete.'])
  209. self._current_test = test_name
  210. if self.retrying_failed:
  211. self._failure_description = self._test_status[test_name][1]
  212. self._failure_description.extend(['', 'RETRY OUTPUT:', ''])
  213. else:
  214. self._failure_description = []
  215. return
  216. # Is it a test success line?
  217. results = self._test_ok.match(line)
  218. if results:
  219. test_name = '%s/%s' % (results.group(1), results.group(2))
  220. status = self._StatusOfTest(test_name)
  221. if status != 'started':
  222. self._RecordError(line, 'success while in status %s' % status)
  223. if self.retrying_failed:
  224. self._test_status[test_name] = ('warning', self._failure_description)
  225. # This is a passed result. Previous failures were reported in separate
  226. # TestResult objects.
  227. self._result_collection.add_test_result(
  228. TestResult(
  229. test_name,
  230. TestStatus.PASS,
  231. test_log='\n'.join(self._failure_description)))
  232. else:
  233. self._test_status[test_name] = ('OK', [])
  234. self._result_collection.add_test_result(
  235. TestResult(test_name, TestStatus.PASS))
  236. self._failure_description = []
  237. self._current_test = ''
  238. return
  239. # Is it a test failure line?
  240. results = self._test_fail.match(line)
  241. if results:
  242. test_name = '%s/%s' % (results.group(1), results.group(2))
  243. status = self._StatusOfTest(test_name)
  244. if status not in ('started', 'failed', 'timeout'):
  245. self._RecordError(line, 'failure while in status %s' % status)
  246. if self._current_test != test_name:
  247. if self._current_test:
  248. self._RecordError(
  249. line,
  250. '%s failure while in test %s' % (test_name, self._current_test))
  251. return
  252. # Don't overwrite the failure description when a failing test is listed a
  253. # second time in the summary, or if it was already recorded as timing
  254. # out.
  255. if status not in ('failed', 'timeout'):
  256. self._test_status[test_name] = ('failed', self._failure_description)
  257. # Add to |test_results| regardless whether the test ran before.
  258. self._result_collection.add_test_result(
  259. TestResult(
  260. test_name,
  261. TestStatus.FAIL,
  262. test_log='\n'.join(self._failure_description)))
  263. self._failure_description = []
  264. self._current_test = ''
  265. return
  266. # Is it the start of the retry tests?
  267. results = self._retry_message.match(line)
  268. if results:
  269. self.retrying_failed = True
  270. return
  271. # Random line: if we're in a test, collect it for the failure description.
  272. # Tests may run simultaneously, so this might be off, but it's worth a try.
  273. # This also won't work if a test times out before it begins running.
  274. if self._current_test:
  275. self._failure_description.append(line)