1# ***** BEGIN LICENSE BLOCK ***** 2# This Source Code Form is subject to the terms of the Mozilla Public 3# License, v. 2.0. If a copy of the MPL was not distributed with this file, 4# You can obtain one at http://mozilla.org/MPL/2.0/. 5# ***** END LICENSE BLOCK ***** 6from __future__ import absolute_import 7import json 8 9from mozharness.base import log 10from mozharness.base.log import OutputParser, WARNING, INFO, ERROR 11from mozharness.mozilla.automation import TBPL_WARNING, TBPL_FAILURE 12from mozharness.mozilla.automation import TBPL_SUCCESS, TBPL_WORST_LEVEL_TUPLE 13from mozharness.mozilla.automation import TBPL_RETRY 14from mozharness.mozilla.testing.errors import TinderBoxPrintRe 15from mozharness.mozilla.testing.unittest import tbox_print_summary 16 17from collections import ( 18 defaultdict, 19 namedtuple, 20) 21 22 23class StructuredOutputParser(OutputParser): 24 # The script class using this must inherit the MozbaseMixin to ensure 25 # that mozlog is available. 26 def __init__(self, **kwargs): 27 """Object that tracks the overall status of the test run""" 28 # The 'strict' argument dictates whether the presence of output 29 # from the harness process other than line-delimited json indicates 30 # failure. If it does not, the errors_list parameter may be used 31 # to detect additional failure output from the harness process. 32 if "strict" in kwargs: 33 self.strict = kwargs.pop("strict") 34 else: 35 self.strict = True 36 37 self.suite_category = kwargs.pop("suite_category", None) 38 39 tbpl_compact = kwargs.pop("log_compact", False) 40 super(StructuredOutputParser, self).__init__(**kwargs) 41 self.allow_crashes = kwargs.pop("allow_crashes", False) 42 43 mozlog = self._get_mozlog_module() 44 self.formatter = mozlog.formatters.TbplFormatter(compact=tbpl_compact) 45 self.handler = mozlog.handlers.StatusHandler() 46 self.log_actions = mozlog.structuredlog.log_actions() 47 48 self.worst_log_level = INFO 49 self.tbpl_status = TBPL_SUCCESS 50 self.harness_retry_re = TinderBoxPrintRe["harness_error"]["retry_regex"] 51 self.prev_was_unstructured = False 52 53 def _get_mozlog_module(self): 54 try: 55 import mozlog 56 except ImportError: 57 self.fatal( 58 "A script class using structured logging must inherit " 59 "from the MozbaseMixin to ensure that mozlog is available." 60 ) 61 return mozlog 62 63 def _handle_unstructured_output(self, line, log_output=True): 64 self.log_output = log_output 65 return super(StructuredOutputParser, self).parse_single_line(line) 66 67 def parse_single_line(self, line): 68 """Parses a line of log output from the child process and passes 69 it to mozlog to update the overall status of the run. 70 Re-emits the logged line in human-readable format. 71 """ 72 level = INFO 73 tbpl_level = TBPL_SUCCESS 74 75 data = None 76 try: 77 candidate_data = json.loads(line) 78 if ( 79 isinstance(candidate_data, dict) 80 and "action" in candidate_data 81 and candidate_data["action"] in self.log_actions 82 ): 83 data = candidate_data 84 except ValueError: 85 pass 86 87 if data is None: 88 if self.strict: 89 if not self.prev_was_unstructured: 90 self.critical( 91 ( 92 "Test harness output was not a valid structured log message: " 93 "\n%s" 94 ) 95 % line 96 ) 97 else: 98 self.critical(line) 99 self.update_levels(TBPL_FAILURE, log.CRITICAL) 100 self.prev_was_unstructured = True 101 else: 102 self._handle_unstructured_output(line) 103 return 104 105 self.prev_was_unstructured = False 106 107 self.handler(data) 108 109 action = data["action"] 110 if action in ("log", "process_output"): 111 if action == "log": 112 message = data["message"] 113 level = getattr(log, data["level"].upper()) 114 else: 115 message = data["data"] 116 117 # Run log and process_output actions through the error lists, but make sure 118 # the super parser doesn't print them to stdout (they should go through the 119 # log formatter). 120 error_level = self._handle_unstructured_output(message, log_output=False) 121 if error_level is not None: 122 level = self.worst_level(error_level, level) 123 124 if self.harness_retry_re.search(message): 125 self.update_levels(TBPL_RETRY, log.CRITICAL) 126 tbpl_level = TBPL_RETRY 127 level = log.CRITICAL 128 129 log_data = self.formatter(data) 130 if log_data is not None: 131 self.log(log_data, level=level) 132 self.update_levels(tbpl_level, level) 133 134 def _subtract_tuples(self, old, new): 135 items = set(list(old.keys()) + list(new.keys())) 136 merged = defaultdict(int) 137 for item in items: 138 merged[item] = new.get(item, 0) - old.get(item, 0) 139 if merged[item] <= 0: 140 del merged[item] 141 return merged 142 143 def evaluate_parser(self, return_code, success_codes=None, previous_summary=None): 144 success_codes = success_codes or [0] 145 summary = self.handler.summarize() 146 147 """ 148 We can run evaluate_parser multiple times, it will duplicate failures 149 and status which can mean that future tests will fail if a previous test fails. 150 When we have a previous summary, we want to do 2 things: 151 1) Remove previous data from the new summary to only look at new data 152 2) Build a joined summary to include the previous + new data 153 """ 154 RunSummary = namedtuple( 155 "RunSummary", 156 ( 157 "unexpected_statuses", 158 "expected_statuses", 159 "known_intermittent_statuses", 160 "log_level_counts", 161 "action_counts", 162 ), 163 ) 164 if previous_summary == {}: 165 previous_summary = RunSummary( 166 defaultdict(int), 167 defaultdict(int), 168 defaultdict(int), 169 defaultdict(int), 170 defaultdict(int), 171 ) 172 if previous_summary: 173 # Always preserve retry status: if any failure triggers retry, the script 174 # must exit with TBPL_RETRY to trigger task retry. 175 if self.tbpl_status != TBPL_RETRY: 176 self.tbpl_status = TBPL_SUCCESS 177 joined_summary = summary 178 179 # Remove previously known status messages 180 if "ERROR" in summary.log_level_counts: 181 summary.log_level_counts["ERROR"] -= self.handler.no_tests_run_count 182 183 summary = RunSummary( 184 self._subtract_tuples( 185 previous_summary.unexpected_statuses, summary.unexpected_statuses 186 ), 187 self._subtract_tuples( 188 previous_summary.expected_statuses, summary.expected_statuses 189 ), 190 self._subtract_tuples( 191 previous_summary.known_intermittent_statuses, 192 summary.known_intermittent_statuses, 193 ), 194 self._subtract_tuples( 195 previous_summary.log_level_counts, summary.log_level_counts 196 ), 197 summary.action_counts, 198 ) 199 200 # If we have previous data to ignore, 201 # cache it so we don't parse the log multiple times 202 self.summary = summary 203 else: 204 joined_summary = summary 205 206 fail_pair = TBPL_WARNING, WARNING 207 error_pair = TBPL_FAILURE, ERROR 208 209 # These are warning/orange statuses. 210 failure_conditions = [ 211 (sum(summary.unexpected_statuses.values()), 0, "statuses", False), 212 ( 213 summary.action_counts.get("crash", 0), 214 summary.expected_statuses.get("CRASH", 0), 215 "crashes", 216 self.allow_crashes, 217 ), 218 ( 219 summary.action_counts.get("valgrind_error", 0), 220 0, 221 "valgrind errors", 222 False, 223 ), 224 ] 225 for value, limit, type_name, allow in failure_conditions: 226 if value > limit: 227 msg = "%d unexpected %s" % (value, type_name) 228 if limit != 0: 229 msg += " expected at most %d" % (limit) 230 if not allow: 231 self.update_levels(*fail_pair) 232 msg = "Got " + msg 233 self.error(msg) 234 else: 235 msg = "Ignored " + msg 236 self.warning(msg) 237 238 # These are error/red statuses. A message is output here every time something 239 # wouldn't otherwise be highlighted in the UI. 240 required_actions = { 241 "suite_end": "No suite end message was emitted by this harness.", 242 "test_end": "No checks run.", 243 } 244 for action, diagnostic_message in required_actions.items(): 245 if action not in summary.action_counts: 246 self.log(diagnostic_message, ERROR) 247 self.update_levels(*error_pair) 248 249 failure_log_levels = ["ERROR", "CRITICAL"] 250 for level in failure_log_levels: 251 if level in summary.log_level_counts: 252 self.update_levels(*error_pair) 253 254 # If a superclass was used to detect errors with a regex based output parser, 255 # this will be reflected in the status here. 256 if self.num_errors: 257 self.update_levels(*error_pair) 258 259 # Harnesses typically return non-zero on test failure, so don't promote 260 # to error if we already have a failing status. 261 if return_code not in success_codes and self.tbpl_status == TBPL_SUCCESS: 262 self.update_levels(*error_pair) 263 264 return self.tbpl_status, self.worst_log_level, joined_summary 265 266 def update_levels(self, tbpl_level, log_level): 267 self.worst_log_level = self.worst_level(log_level, self.worst_log_level) 268 self.tbpl_status = self.worst_level( 269 tbpl_level, self.tbpl_status, levels=TBPL_WORST_LEVEL_TUPLE 270 ) 271 272 def print_summary(self, suite_name): 273 # Summary text provided for compatibility. Counts are currently 274 # in the format <pass count>/<fail count>/<todo count>, 275 # <expected count>/<unexpected count>/<expected fail count> will yield the 276 # expected info from a structured log (fail count from the prior implementation 277 # includes unexpected passes from "todo" assertions). 278 try: 279 summary = self.summary 280 except AttributeError: 281 summary = self.handler.summarize() 282 283 unexpected_count = sum(summary.unexpected_statuses.values()) 284 expected_count = sum(summary.expected_statuses.values()) 285 expected_failures = summary.expected_statuses.get("FAIL", 0) 286 287 if unexpected_count: 288 fail_text = '<em class="testfail">%s</em>' % unexpected_count 289 else: 290 fail_text = "0" 291 292 text_summary = "%s/%s/%s" % (expected_count, fail_text, expected_failures) 293 self.info("TinderboxPrint: %s<br/>%s\n" % (suite_name, text_summary)) 294 295 def append_tinderboxprint_line(self, suite_name): 296 try: 297 summary = self.summary 298 except AttributeError: 299 summary = self.handler.summarize() 300 301 unexpected_count = sum(summary.unexpected_statuses.values()) 302 expected_count = sum(summary.expected_statuses.values()) 303 expected_failures = summary.expected_statuses.get("FAIL", 0) 304 crashed = 0 305 if "crash" in summary.action_counts: 306 crashed = summary.action_counts["crash"] 307 text_summary = tbox_print_summary( 308 expected_count, unexpected_count, expected_failures, crashed > 0, False 309 ) 310 self.info("TinderboxPrint: %s<br/>%s\n" % (suite_name, text_summary)) 311