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