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