testing/mochitest/leaks.py

   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 from __future__ import absolute_import, division
   9
  10 import re
  11 from operator import itemgetter
  12
  13 RE_DOCSHELL = re.compile("I\/DocShellAndDOMWindowLeak ([+\-]{2})DOCSHELL")
  14 RE_DOMWINDOW = re.compile("I\/DocShellAndDOMWindowLeak ([+\-]{2})DOMWINDOW")
  15
  16
  17 class 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
 281 class 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