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