tor-browser

The Tor Browser
git clone https://git.dasho.dev/tor-browser.git
Log | Files | Refs | README | LICENSE

leaks.py (15571B)

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