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("I\/DocShellAndDOMWindowLeak ([+\-]{2})DOCSHELL")
  12 RE_DOMWINDOW = re.compile("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         for test in self._parseLeakingTests():
 120             for url, count in self._zipLeakedWindows(test["leakedWindows"]):
 121                 self.logger.error(
 122                     "TEST-UNEXPECTED-FAIL | %s | leaked %d window(s) until shutdown "
 123                     "[url = %s]" % (test["fileName"], count, url)
 124                 )
 125                 failures += 1
 126
 127             if test["leakedWindowsString"]:
 128                 self.logger.info(
 129                     "TEST-INFO | %s | windows(s) leaked: %s"
 130                     % (test["fileName"], test["leakedWindowsString"])
 131                 )
 132
 133             if test["leakedDocShells"]:
 134                 self.logger.error(
 135                     "TEST-UNEXPECTED-FAIL | %s | leaked %d docShell(s) until "
 136                     "shutdown" % (test["fileName"], len(test["leakedDocShells"]))
 137                 )
 138                 failures += 1
 139                 self.logger.info(
 140                     "TEST-INFO | %s | docShell(s) leaked: %s"
 141                     % (
 142                         test["fileName"],
 143                         ", ".join(
 144                             [
 145                                 "[pid = %s] [id = %s]" % x
 146                                 for x in test["leakedDocShells"]
 147                             ]
 148                         ),
 149                     )
 150                 )
 151
 152             if test["hiddenWindowsCount"] > 0:
 153                 # Note: to figure out how many hidden windows were created, we divide
 154                 # this number by 2, because 1 hidden window creation implies in
 155                 # 1 outer window + 1 inner window.
 156                 # pylint --py3k W1619
 157                 self.logger.info(
 158                     "TEST-INFO | %s | This test created %d hidden window(s)"
 159                     % (test["fileName"], test["hiddenWindowsCount"] / 2)
 160                 )
 161
 162             if test["hiddenDocShellsCount"] > 0:
 163                 self.logger.info(
 164                     "TEST-INFO | %s | This test created %d hidden docshell(s)"
 165                     % (test["fileName"], test["hiddenDocShellsCount"])
 166                 )
 167
 168         return failures
 169
 170     def _logWindow(self, line, created):
 171         pid = self._parseValue(line, "pid")
 172         serial = self._parseValue(line, "serial")
 173         self.numDomWindowCreatedLogsSeen += 1 if created else 0
 174         self.numDomWindowDestroyedLogsSeen += 0 if created else 1
 175
 176         # log line has invalid format
 177         if not pid or not serial:
 178             self.logger.error(
 179                 "TEST-UNEXPECTED-FAIL | ShutdownLeaks | failed to parse line"
 180             )
 181             self.logger.error("TEST-INFO | ShutdownLeaks | Unparsable line <%s>" % line)
 182             return
 183
 184         key = (pid, serial)
 185
 186         if self.currentTest:
 187             windows = self.currentTest["windows"]
 188             if created:
 189                 windows.add(key)
 190             else:
 191                 windows.discard(key)
 192         elif int(pid) in self.seenShutdown and not created:
 193             url = self._parseValue(line, "url")
 194             if not self._isHiddenWindowURL(url):
 195                 self.leakedWindows[key] = url
 196             else:
 197                 self.hiddenWindowsCount += 1
 198
 199     def _logDocShell(self, line, created):
 200         pid = self._parseValue(line, "pid")
 201         id = self._parseValue(line, "id")
 202         self.numDocShellCreatedLogsSeen += 1 if created else 0
 203         self.numDocShellDestroyedLogsSeen += 0 if created else 1
 204
 205         # log line has invalid format
 206         if not pid or not id:
 207             self.logger.error(
 208                 "TEST-UNEXPECTED-FAIL | ShutdownLeaks | failed to parse line"
 209             )
 210             self.logger.error("TEST-INFO | ShutdownLeaks | Unparsable line <%s>" % line)
 211             return
 212
 213         key = (pid, id)
 214
 215         if self.currentTest:
 216             docShells = self.currentTest["docShells"]
 217             if created:
 218                 docShells.add(key)
 219             else:
 220                 docShells.discard(key)
 221         elif int(pid) in self.seenShutdown and not created:
 222             url = self._parseValue(line, "url")
 223             if not self._isHiddenWindowURL(url):
 224                 self.leakedDocShells.add(key)
 225             else:
 226                 self.hiddenDocShellsCount += 1
 227
 228     def _parseValue(self, line, name):
 229         match = re.search("\[%s = (.+?)\]" % name, line)
 230         if match:
 231             return match.group(1)
 232         return None
 233
 234     def _parseLeakingTests(self):
 235         leakingTests = []
 236
 237         for test in self.tests:
 238             leakedWindows = [id for id in test["windows"] if id in self.leakedWindows]
 239             test["leakedWindows"] = [self.leakedWindows[id] for id in leakedWindows]
 240             test["hiddenWindowsCount"] = self.hiddenWindowsCount
 241             test["leakedWindowsString"] = ", ".join(
 242                 ["[pid = %s] [serial = %s]" % x for x in leakedWindows]
 243             )
 244             test["leakedDocShells"] = [
 245                 id for id in test["docShells"] if id in self.leakedDocShells
 246             ]
 247             test["hiddenDocShellsCount"] = self.hiddenDocShellsCount
 248             test["leakCount"] = len(test["leakedWindows"]) + len(
 249                 test["leakedDocShells"]
 250             )
 251
 252             if (
 253                 test["leakCount"]
 254                 or test["hiddenWindowsCount"]
 255                 or test["hiddenDocShellsCount"]
 256             ):
 257                 leakingTests.append(test)
 258
 259         return sorted(leakingTests, key=itemgetter("leakCount"), reverse=True)
 260
 261     def _zipLeakedWindows(self, leakedWindows):
 262         counts = []
 263         counted = set()
 264
 265         for url in leakedWindows:
 266             if url not in counted:
 267                 counts.append((url, leakedWindows.count(url)))
 268                 counted.add(url)
 269
 270         return sorted(counts, key=itemgetter(1), reverse=True)
 271
 272     def _isHiddenWindowURL(self, url):
 273         return (
 274             url == "resource://gre-resources/hiddenWindow.html"
 275             or url == "chrome://browser/content/hiddenWindowMac.xhtml"  # Win / Linux
 276         )  # Mac
 277
 278
 279 class LSANLeaks(object):
 280
 281     """
 282     Parses the log when running an LSAN build, looking for interesting stack frames
 283     in allocation stacks, and prints out reports.
 284     """
 285
 286     def __init__(self, logger):
 287         self.logger = logger
 288         self.inReport = False
 289         self.fatalError = False
 290         self.symbolizerError = False
 291         self.foundFrames = set([])
 292         self.recordMoreFrames = None
 293         self.currStack = None
 294         self.maxNumRecordedFrames = 4
 295
 296         # Don't various allocation-related stack frames, as they do not help much to
 297         # distinguish different leaks.
 298         unescapedSkipList = [
 299             "malloc",
 300             "js_malloc",
 301             "js_arena_malloc",
 302             "malloc_",
 303             "__interceptor_malloc",
 304             "moz_xmalloc",
 305             "calloc",
 306             "js_calloc",
 307             "js_arena_calloc",
 308             "calloc_",
 309             "__interceptor_calloc",
 310             "moz_xcalloc",
 311             "realloc",
 312             "js_realloc",
 313             "js_arena_realloc",
 314             "realloc_",
 315             "__interceptor_realloc",
 316             "moz_xrealloc",
 317             "new",
 318             "js::MallocProvider",
 319         ]
 320         self.skipListRegExp = re.compile(
 321             "^" + "|".join([re.escape(f) for f in unescapedSkipList]) + "$"
 322         )
 323
 324         self.startRegExp = re.compile(
 325             "==\d+==ERROR: LeakSanitizer: detected memory leaks"
 326         )
 327         self.fatalErrorRegExp = re.compile(
 328             "==\d+==LeakSanitizer has encountered a fatal error."
 329         )
 330         self.symbolizerOomRegExp = re.compile(
 331             "LLVMSymbolizer: error reading file: Cannot allocate memory"
 332         )
 333         self.stackFrameRegExp = re.compile("    #\d+ 0x[0-9a-f]+ in ([^(</]+)")
 334         self.sysLibStackFrameRegExp = re.compile(
 335             "    #\d+ 0x[0-9a-f]+ \(([^+]+)\+0x[0-9a-f]+\)"
 336         )
 337
 338     def log(self, line):
 339         if re.match(self.startRegExp, line):
 340             self.inReport = True
 341             return
 342
 343         if re.match(self.fatalErrorRegExp, line):
 344             self.fatalError = True
 345             return
 346
 347         if re.match(self.symbolizerOomRegExp, line):
 348             self.symbolizerError = True
 349             return
 350
 351         if not self.inReport:
 352             return
 353
 354         if line.startswith("Direct leak") or line.startswith("Indirect leak"):
 355             self._finishStack()
 356             self.recordMoreFrames = True
 357             self.currStack = []
 358             return
 359
 360         if line.startswith("SUMMARY: AddressSanitizer"):
 361             self._finishStack()
 362             self.inReport = False
 363             return
 364
 365         if not self.recordMoreFrames:
 366             return
 367
 368         stackFrame = re.match(self.stackFrameRegExp, line)
 369         if stackFrame:
 370             # Split the frame to remove any return types.
 371             frame = stackFrame.group(1).split()[-1]
 372             if not re.match(self.skipListRegExp, frame):
 373                 self._recordFrame(frame)
 374             return
 375
 376         sysLibStackFrame = re.match(self.sysLibStackFrameRegExp, line)
 377         if sysLibStackFrame:
 378             # System library stack frames will never match the skip list,
 379             # so don't bother checking if they do.
 380             self._recordFrame(sysLibStackFrame.group(1))
 381
 382         # If we don't match either of these, just ignore the frame.
 383         # We'll end up with "unknown stack" if everything is ignored.
 384
 385     def process(self):
 386         failures = 0
 387
 388         if self.fatalError:
 389             self.logger.error(
 390                 "TEST-UNEXPECTED-FAIL | LeakSanitizer | LeakSanitizer "
 391                 "has encountered a fatal error."
 392             )
 393             failures += 1
 394
 395         if self.symbolizerError:
 396             self.logger.error(
 397                 "TEST-UNEXPECTED-FAIL | LeakSanitizer | LLVMSymbolizer "
 398                 "was unable to allocate memory."
 399             )
 400             failures += 1
 401             self.logger.info(
 402                 "TEST-INFO | LeakSanitizer | This will cause leaks that "
 403                 "should be ignored to instead be reported as an error"
 404             )
 405
 406         if self.foundFrames:
 407             self.logger.info(
 408                 "TEST-INFO | LeakSanitizer | To show the "
 409                 "addresses of leaked objects add report_objects=1 to LSAN_OPTIONS"
 410             )
 411             self.logger.info(
 412                 "TEST-INFO | LeakSanitizer | This can be done "
 413                 "in testing/mozbase/mozrunner/mozrunner/utils.py"
 414             )
 415
 416         for f in self.foundFrames:
 417             self.logger.error("TEST-UNEXPECTED-FAIL | LeakSanitizer | leak at " + f)
 418             failures += 1
 419
 420         return failures
 421
 422     def _finishStack(self):
 423         if self.recordMoreFrames and len(self.currStack) == 0:
 424             self.currStack = ["unknown stack"]
 425         if self.currStack:
 426             self.foundFrames.add(", ".join(self.currStack))
 427             self.currStack = None
 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