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
3# file, You can obtain one at http://mozilla.org/MPL/2.0/
4
5# The content of this file comes orginally from automationutils.py
6# and *should* be revised.
7
8from __future__ import absolute_import, division
9
10import re
11from operator import itemgetter
12
13RE_DOCSHELL = re.compile("I\/DocShellAndDOMWindowLeak ([+\-]{2})DOCSHELL")
14RE_DOMWINDOW = re.compile("I\/DocShellAndDOMWindowLeak ([+\-]{2})DOMWINDOW")
15
16
17class ShutdownLeaks(object):
18
19    """
20    Parses the mochitest run log when running a debug build, assigns all leaked
21    DOM windows (that are still around after test suite shutdown, despite running
22    the GC) to the tests that created them and prints leak statistics.
23    """
24
25    def __init__(self, logger):
26        self.logger = logger
27        self.tests = []
28        self.leakedWindows = {}
29        self.hiddenWindowsCount = 0
30        self.leakedDocShells = set()
31        self.hiddenDocShellsCount = 0
32        self.numDocShellCreatedLogsSeen = 0
33        self.numDocShellDestroyedLogsSeen = 0
34        self.numDomWindowCreatedLogsSeen = 0
35        self.numDomWindowDestroyedLogsSeen = 0
36        self.currentTest = None
37        self.seenShutdown = set()
38
39    def log(self, message):
40        action = message["action"]
41
42        # Remove 'log' when clipboard is gone and/or structured.
43        if action in ("log", "process_output"):
44            line = message["message"] if action == "log" else message["data"]
45
46            m = RE_DOMWINDOW.search(line)
47            if m:
48                self._logWindow(line, m.group(1) == "++")
49                return
50
51            m = RE_DOCSHELL.search(line)
52            if m:
53                self._logDocShell(line, m.group(1) == "++")
54                return
55
56            if line.startswith("Completed ShutdownLeaks collections in process"):
57                pid = int(line.split()[-1])
58                self.seenShutdown.add(pid)
59        elif action == "test_start":
60            fileName = message["test"].replace(
61                "chrome://mochitests/content/browser/", ""
62            )
63            self.currentTest = {
64                "fileName": fileName,
65                "windows": set(),
66                "docShells": set(),
67            }
68        elif action == "test_end":
69            # don't track a test if no windows or docShells leaked
70            if self.currentTest and (
71                self.currentTest["windows"] or self.currentTest["docShells"]
72            ):
73                self.tests.append(self.currentTest)
74            self.currentTest = None
75
76    def process(self):
77        failures = 0
78
79        if not self.seenShutdown:
80            self.logger.error(
81                "TEST-UNEXPECTED-FAIL | ShutdownLeaks | process() called before end of test suite"
82            )
83            failures += 1
84
85        if (
86            self.numDocShellCreatedLogsSeen == 0
87            or self.numDocShellDestroyedLogsSeen == 0
88        ):
89            self.logger.error(
90                "TEST-UNEXPECTED-FAIL | did not see DOCSHELL log strings."
91                " this occurs if the DOCSHELL logging gets disabled by"
92                " something. %d created seen %d destroyed seen"
93                % (self.numDocShellCreatedLogsSeen, self.numDocShellDestroyedLogsSeen)
94            )
95            failures += 1
96        else:
97            self.logger.info(
98                "TEST-INFO | Confirming we saw %d DOCSHELL created and %d destroyed log"
99                " strings."
100                % (self.numDocShellCreatedLogsSeen, self.numDocShellDestroyedLogsSeen)
101            )
102
103        if (
104            self.numDomWindowCreatedLogsSeen == 0
105            or self.numDomWindowDestroyedLogsSeen == 0
106        ):
107            self.logger.error(
108                "TEST-UNEXPECTED-FAIL | did not see DOMWINDOW log strings."
109                " this occurs if the DOMWINDOW logging gets disabled by"
110                " something%d created seen %d destroyed seen"
111                % (self.numDomWindowCreatedLogsSeen, self.numDomWindowDestroyedLogsSeen)
112            )
113            failures += 1
114        else:
115            self.logger.info(
116                "TEST-INFO | Confirming we saw %d DOMWINDOW created and %d destroyed log"
117                " strings."
118                % (self.numDomWindowCreatedLogsSeen, self.numDomWindowDestroyedLogsSeen)
119            )
120
121        for test in self._parseLeakingTests():
122            for url, count in self._zipLeakedWindows(test["leakedWindows"]):
123                self.logger.error(
124                    "TEST-UNEXPECTED-FAIL | %s | leaked %d window(s) until shutdown "
125                    "[url = %s]" % (test["fileName"], count, url)
126                )
127                failures += 1
128
129            if test["leakedWindowsString"]:
130                self.logger.info(
131                    "TEST-INFO | %s | windows(s) leaked: %s"
132                    % (test["fileName"], test["leakedWindowsString"])
133                )
134
135            if test["leakedDocShells"]:
136                self.logger.error(
137                    "TEST-UNEXPECTED-FAIL | %s | leaked %d docShell(s) until "
138                    "shutdown" % (test["fileName"], len(test["leakedDocShells"]))
139                )
140                failures += 1
141                self.logger.info(
142                    "TEST-INFO | %s | docShell(s) leaked: %s"
143                    % (
144                        test["fileName"],
145                        ", ".join(
146                            [
147                                "[pid = %s] [id = %s]" % x
148                                for x in test["leakedDocShells"]
149                            ]
150                        ),
151                    )
152                )
153
154            if test["hiddenWindowsCount"] > 0:
155                # Note: to figure out how many hidden windows were created, we divide
156                # this number by 2, because 1 hidden window creation implies in
157                # 1 outer window + 1 inner window.
158                # pylint --py3k W1619
159                self.logger.info(
160                    "TEST-INFO | %s | This test created %d hidden window(s)"
161                    % (test["fileName"], test["hiddenWindowsCount"] / 2)
162                )
163
164            if test["hiddenDocShellsCount"] > 0:
165                self.logger.info(
166                    "TEST-INFO | %s | This test created %d hidden docshell(s)"
167                    % (test["fileName"], test["hiddenDocShellsCount"])
168                )
169
170        return failures
171
172    def _logWindow(self, line, created):
173        pid = self._parseValue(line, "pid")
174        serial = self._parseValue(line, "serial")
175        self.numDomWindowCreatedLogsSeen += 1 if created else 0
176        self.numDomWindowDestroyedLogsSeen += 0 if created else 1
177
178        # log line has invalid format
179        if not pid or not serial:
180            self.logger.error(
181                "TEST-UNEXPECTED-FAIL | ShutdownLeaks | failed to parse line <%s>"
182                % line
183            )
184            return
185
186        key = (pid, serial)
187
188        if self.currentTest:
189            windows = self.currentTest["windows"]
190            if created:
191                windows.add(key)
192            else:
193                windows.discard(key)
194        elif int(pid) in self.seenShutdown and not created:
195            url = self._parseValue(line, "url")
196            if not self._isHiddenWindowURL(url):
197                self.leakedWindows[key] = url
198            else:
199                self.hiddenWindowsCount += 1
200
201    def _logDocShell(self, line, created):
202        pid = self._parseValue(line, "pid")
203        id = self._parseValue(line, "id")
204        self.numDocShellCreatedLogsSeen += 1 if created else 0
205        self.numDocShellDestroyedLogsSeen += 0 if created else 1
206
207        # log line has invalid format
208        if not pid or not id:
209            self.logger.error(
210                "TEST-UNEXPECTED-FAIL | ShutdownLeaks | failed to parse line <%s>"
211                % line
212            )
213            return
214
215        key = (pid, id)
216
217        if self.currentTest:
218            docShells = self.currentTest["docShells"]
219            if created:
220                docShells.add(key)
221            else:
222                docShells.discard(key)
223        elif int(pid) in self.seenShutdown and not created:
224            url = self._parseValue(line, "url")
225            if not self._isHiddenWindowURL(url):
226                self.leakedDocShells.add(key)
227            else:
228                self.hiddenDocShellsCount += 1
229
230    def _parseValue(self, line, name):
231        match = re.search("\[%s = (.+?)\]" % name, line)
232        if match:
233            return match.group(1)
234        return None
235
236    def _parseLeakingTests(self):
237        leakingTests = []
238
239        for test in self.tests:
240            leakedWindows = [id for id in test["windows"] if id in self.leakedWindows]
241            test["leakedWindows"] = [self.leakedWindows[id] for id in leakedWindows]
242            test["hiddenWindowsCount"] = self.hiddenWindowsCount
243            test["leakedWindowsString"] = ", ".join(
244                ["[pid = %s] [serial = %s]" % x for x in leakedWindows]
245            )
246            test["leakedDocShells"] = [
247                id for id in test["docShells"] if id in self.leakedDocShells
248            ]
249            test["hiddenDocShellsCount"] = self.hiddenDocShellsCount
250            test["leakCount"] = len(test["leakedWindows"]) + len(
251                test["leakedDocShells"]
252            )
253
254            if (
255                test["leakCount"]
256                or test["hiddenWindowsCount"]
257                or test["hiddenDocShellsCount"]
258            ):
259                leakingTests.append(test)
260
261        return sorted(leakingTests, key=itemgetter("leakCount"), reverse=True)
262
263    def _zipLeakedWindows(self, leakedWindows):
264        counts = []
265        counted = set()
266
267        for url in leakedWindows:
268            if url not in counted:
269                counts.append((url, leakedWindows.count(url)))
270                counted.add(url)
271
272        return sorted(counts, key=itemgetter(1), reverse=True)
273
274    def _isHiddenWindowURL(self, url):
275        return (
276            url == "resource://gre-resources/hiddenWindow.html"
277            or url == "chrome://browser/content/hiddenWindowMac.xhtml"  # Win / Linux
278        )  # Mac
279
280
281class LSANLeaks(object):
282
283    """
284    Parses the log when running an LSAN build, looking for interesting stack frames
285    in allocation stacks, and prints out reports.
286    """
287
288    def __init__(self, logger):
289        self.logger = logger
290        self.inReport = False
291        self.fatalError = False
292        self.symbolizerError = False
293        self.foundFrames = set([])
294        self.recordMoreFrames = None
295        self.currStack = None
296        self.maxNumRecordedFrames = 4
297
298        # Don't various allocation-related stack frames, as they do not help much to
299        # distinguish different leaks.
300        unescapedSkipList = [
301            "malloc",
302            "js_malloc",
303            "js_arena_malloc",
304            "malloc_",
305            "__interceptor_malloc",
306            "moz_xmalloc",
307            "calloc",
308            "js_calloc",
309            "js_arena_calloc",
310            "calloc_",
311            "__interceptor_calloc",
312            "moz_xcalloc",
313            "realloc",
314            "js_realloc",
315            "js_arena_realloc",
316            "realloc_",
317            "__interceptor_realloc",
318            "moz_xrealloc",
319            "new",
320            "js::MallocProvider",
321        ]
322        self.skipListRegExp = re.compile(
323            "^" + "|".join([re.escape(f) for f in unescapedSkipList]) + "$"
324        )
325
326        self.startRegExp = re.compile(
327            "==\d+==ERROR: LeakSanitizer: detected memory leaks"
328        )
329        self.fatalErrorRegExp = re.compile(
330            "==\d+==LeakSanitizer has encountered a fatal error."
331        )
332        self.symbolizerOomRegExp = re.compile(
333            "LLVMSymbolizer: error reading file: Cannot allocate memory"
334        )
335        self.stackFrameRegExp = re.compile("    #\d+ 0x[0-9a-f]+ in ([^(</]+)")
336        self.sysLibStackFrameRegExp = re.compile(
337            "    #\d+ 0x[0-9a-f]+ \(([^+]+)\+0x[0-9a-f]+\)"
338        )
339
340    def log(self, line):
341        if re.match(self.startRegExp, line):
342            self.inReport = True
343            return
344
345        if re.match(self.fatalErrorRegExp, line):
346            self.fatalError = True
347            return
348
349        if re.match(self.symbolizerOomRegExp, line):
350            self.symbolizerError = True
351            return
352
353        if not self.inReport:
354            return
355
356        if line.startswith("Direct leak") or line.startswith("Indirect leak"):
357            self._finishStack()
358            self.recordMoreFrames = True
359            self.currStack = []
360            return
361
362        if line.startswith("SUMMARY: AddressSanitizer"):
363            self._finishStack()
364            self.inReport = False
365            return
366
367        if not self.recordMoreFrames:
368            return
369
370        stackFrame = re.match(self.stackFrameRegExp, line)
371        if stackFrame:
372            # Split the frame to remove any return types.
373            frame = stackFrame.group(1).split()[-1]
374            if not re.match(self.skipListRegExp, frame):
375                self._recordFrame(frame)
376            return
377
378        sysLibStackFrame = re.match(self.sysLibStackFrameRegExp, line)
379        if sysLibStackFrame:
380            # System library stack frames will never match the skip list,
381            # so don't bother checking if they do.
382            self._recordFrame(sysLibStackFrame.group(1))
383
384        # If we don't match either of these, just ignore the frame.
385        # We'll end up with "unknown stack" if everything is ignored.
386
387    def process(self):
388        failures = 0
389
390        if self.fatalError:
391            self.logger.error(
392                "TEST-UNEXPECTED-FAIL | LeakSanitizer | LeakSanitizer "
393                "has encountered a fatal error."
394            )
395            failures += 1
396
397        if self.symbolizerError:
398            self.logger.error(
399                "TEST-UNEXPECTED-FAIL | LeakSanitizer | LLVMSymbolizer "
400                "was unable to allocate memory."
401            )
402            failures += 1
403            self.logger.info(
404                "TEST-INFO | LeakSanitizer | This will cause leaks that "
405                "should be ignored to instead be reported as an error"
406            )
407
408        if self.foundFrames:
409            self.logger.info(
410                "TEST-INFO | LeakSanitizer | To show the "
411                "addresses of leaked objects add report_objects=1 to LSAN_OPTIONS"
412            )
413            self.logger.info(
414                "TEST-INFO | LeakSanitizer | This can be done "
415                "in testing/mozbase/mozrunner/mozrunner/utils.py"
416            )
417
418        for f in self.foundFrames:
419            self.logger.error("TEST-UNEXPECTED-FAIL | LeakSanitizer | leak at " + f)
420            failures += 1
421
422        return failures
423
424    def _finishStack(self):
425        if self.recordMoreFrames and len(self.currStack) == 0:
426            self.currStack = ["unknown stack"]
427        if self.currStack:
428            self.foundFrames.add(", ".join(self.currStack))
429            self.currStack = None
430        self.recordMoreFrames = False
431        self.numRecordedFrames = 0
432
433    def _recordFrame(self, frame):
434        self.currStack.append(frame)
435        self.numRecordedFrames += 1
436        if self.numRecordedFrames >= self.maxNumRecordedFrames:
437            self.recordMoreFrames = False
438