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