2 # This Source Code Form is subject to the terms of the Mozilla Public
3 # License, v. 2.0. If a copy of the MPL was not distributed with this
4 # file, You can obtain one at http://mozilla.org/MPL/2.0/.
6 from __future__
import with_statement
8 from operator
import itemgetter
28 log
= logging
.getLogger()
31 log
.removeHandler(log
.handlers
[0])
32 handler
= logging
.StreamHandler(sys
.stdout
)
33 log
.setLevel(logging
.INFO
)
34 log
.addHandler(handler
)
37 def setAutomationLog(alt_logger
):
41 # Python does not provide strsignal() even in the very latest 3.x.
42 # This is a reasonable fake.
44 # Signal numbers run 0 through NSIG-1; an array with NSIG members
45 # has exactly that many slots
46 _sigtbl
= [None]*signal
.NSIG
48 if k
.startswith("SIG") and not k
.startswith("SIG_") and k
!= "SIGCLD" and k
!= "SIGPOLL":
49 _sigtbl
[getattr(signal
, k
)] = k
50 # Realtime signals mostly have no names
51 if hasattr(signal
, "SIGRTMIN") and hasattr(signal
, "SIGRTMAX"):
52 for r
in range(signal
.SIGRTMIN
+1, signal
.SIGRTMAX
+1):
53 _sigtbl
[r
] = "SIGRTMIN+" + str(r
- signal
.SIGRTMIN
)
54 # Fill in any remaining gaps
55 for i
in range(signal
.NSIG
):
56 if _sigtbl
[i
] is None:
57 _sigtbl
[i
] = "unrecognized signal, number " + str(i
)
58 if n
< 0 or n
>= signal
.NSIG
:
59 return "out-of-range signal, number "+str(n
)
62 def printstatus(status
, name
= ""):
63 # 'status' is the exit status
64 if os
.name
!= 'posix':
65 # Windows error codes are easier to look up if printed in hexadecimal
68 print "TEST-INFO | %s: exit status %x\n" % (name
, status
)
69 elif os
.WIFEXITED(status
):
70 print "TEST-INFO | %s: exit %d\n" % (name
, os
.WEXITSTATUS(status
))
71 elif os
.WIFSIGNALED(status
):
72 # The python stdlib doesn't appear to have strsignal(), alas
73 print "TEST-INFO | {}: killed by {}".format(name
,strsig(os
.WTERMSIG(status
)))
75 # This is probably a can't-happen condition on Unix, but let's be defensive
76 print "TEST-INFO | %s: undecodable exit status %04x\n" % (name
, status
)
78 def dumpLeakLog(leakLogFile
, filter = False):
79 """Process the leak log, without parsing it.
81 Use this function if you want the raw log only.
82 Use it preferably with the |XPCOM_MEM_LEAK_LOG| environment variable.
85 # Don't warn (nor "info") if the log file is not there.
86 if not os
.path
.exists(leakLogFile
):
89 with
open(leakLogFile
, "r") as leaks
:
90 leakReport
= leaks
.read()
92 # Only |XPCOM_MEM_LEAK_LOG| reports can be actually filtered out.
93 # Only check whether an actual leak was reported.
94 if filter and not "0 TOTAL " in leakReport
:
97 # Simply copy the log.
98 log
.info(leakReport
.rstrip("\n"))
100 def processSingleLeakFile(leakLogFileName
, processType
, leakThreshold
, ignoreMissingLeaks
):
101 """Process a single leak log.
104 # Per-Inst Leaked Total Rem ...
105 # 0 TOTAL 17 192 419115886 2 ...
106 # 833 nsTimerImpl 60 120 24726 2 ...
107 lineRe
= re
.compile(r
"^\s*\d+\s+(?P<name>\S+)\s+"
108 r
"(?P<size>-?\d+)\s+(?P<bytesLeaked>-?\d+)\s+"
109 r
"-?\d+\s+(?P<numLeaked>-?\d+)")
111 processString
= "%s process:" % processType
112 crashedOnPurpose
= False
113 totalBytesLeaked
= None
116 leakedObjectAnalysis
= []
117 leakedObjectNames
= []
118 recordLeakedObjects
= False
119 with
open(leakLogFileName
, "r") as leaks
:
121 if line
.find("purposefully crash") > -1:
122 crashedOnPurpose
= True
123 matches
= lineRe
.match(line
)
125 # eg: the leak table header row
126 log
.info(line
.rstrip())
128 name
= matches
.group("name")
129 size
= int(matches
.group("size"))
130 bytesLeaked
= int(matches
.group("bytesLeaked"))
131 numLeaked
= int(matches
.group("numLeaked"))
132 # Output the raw line from the leak log table if it is the TOTAL row,
133 # or is for an object row that has been leaked.
134 if numLeaked
!= 0 or name
== "TOTAL":
135 log
.info(line
.rstrip())
136 # Analyse the leak log, but output later or it will interrupt the leak table
138 # Multiple default processes can end up writing their bloat views into a single
139 # log, particularly on B2G. Eventually, these should be split into multiple
140 # logs (bug 1068869), but for now, we report the largest leak.
141 if totalBytesLeaked
!= None:
142 leakAnalysis
.append("WARNING | leakcheck | %s multiple BloatView byte totals found"
146 if bytesLeaked
> totalBytesLeaked
:
147 totalBytesLeaked
= bytesLeaked
148 # Throw out the information we had about the previous bloat view.
149 leakedObjectNames
= []
150 leakedObjectAnalysis
= []
151 recordLeakedObjects
= True
153 recordLeakedObjects
= False
154 if size
< 0 or bytesLeaked
< 0 or numLeaked
< 0:
155 leakAnalysis
.append("TEST-UNEXPECTED-FAIL | leakcheck | %s negative leaks caught!"
159 if name
!= "TOTAL" and numLeaked
!= 0 and recordLeakedObjects
:
160 leakedObjectNames
.append(name
)
161 leakedObjectAnalysis
.append("TEST-INFO | leakcheck | %s leaked %d %s (%s bytes)"
162 % (processString
, numLeaked
, name
, bytesLeaked
))
164 leakAnalysis
.extend(leakedObjectAnalysis
)
166 log
.warning('\n'.join(leakAnalysis
))
168 log
.info('\n'.join(leakAnalysis
))
172 if totalBytesLeaked
is None:
173 # We didn't see a line with name 'TOTAL'
175 log
.info("TEST-INFO | leakcheck | %s deliberate crash and thus no leak log"
177 elif ignoreMissingLeaks
:
178 log
.info("TEST-INFO | leakcheck | %s ignoring missing output line for total leaks"
181 log
.info("TEST-UNEXPECTED-FAIL | leakcheck | %s missing output line for total leaks!"
183 log
.info("TEST-INFO | leakcheck | missing output line from log file %s"
187 if totalBytesLeaked
== 0:
188 log
.info("TEST-PASS | leakcheck | %s no leaks detected!" % processString
)
191 # totalBytesLeaked was seen and is non-zero.
192 if totalBytesLeaked
> leakThreshold
:
194 # Fail the run if we're over the threshold (which defaults to 0)
195 prefix
= "TEST-UNEXPECTED-FAIL"
198 # Create a comma delimited string of the first N leaked objects found,
199 # to aid with bug summary matching in TBPL. Note: The order of the objects
200 # had no significance (they're sorted alphabetically).
201 maxSummaryObjects
= 5
202 leakedObjectSummary
= ', '.join(leakedObjectNames
[:maxSummaryObjects
])
203 if len(leakedObjectNames
) > maxSummaryObjects
:
204 leakedObjectSummary
+= ', ...'
207 log
.warning("%s | leakcheck | %s %d bytes leaked (%s)"
208 % (prefix
, processString
, totalBytesLeaked
, leakedObjectSummary
))
210 log
.info("%s | leakcheck | %s %d bytes leaked (%s)"
211 % (prefix
, processString
, totalBytesLeaked
, leakedObjectSummary
))
213 def processLeakLog(leakLogFile
, options
):
214 """Process the leak log, including separate leak logs created
217 Use this function if you want an additional PASS/FAIL summary.
218 It must be used with the |XPCOM_MEM_BLOAT_LOG| environment variable.
220 The base of leakLogFile for a non-default process needs to end with
221 _proctype_pid12345.log
222 "proctype" is a string denoting the type of the process, which should
223 be the result of calling XRE_ChildProcessTypeToString(). 12345 is
224 a series of digits that is the pid for the process. The .log is
227 All other file names are treated as being for default processes.
229 The options argument is checked for two optional attributes,
230 leakThresholds and ignoreMissingLeaks.
232 leakThresholds should be a dict mapping process types to leak thresholds,
233 in bytes. If a process type is not present in the dict the threshold
236 ignoreMissingLeaks should be a list of process types. If a process
237 creates a leak log without a TOTAL, then we report an error if it isn't
238 in the list ignoreMissingLeaks.
241 if not os
.path
.exists(leakLogFile
):
242 log
.info("WARNING | leakcheck | refcount logging is off, so leaks can't be detected!")
245 leakThresholds
= getattr(options
, 'leakThresholds', {})
246 ignoreMissingLeaks
= getattr(options
, 'ignoreMissingLeaks', [])
248 # This list is based on kGeckoProcessTypeString. ipdlunittest processes likely
249 # are not going to produce leak logs we will ever see.
250 knownProcessTypes
= ["default", "plugin", "tab", "geckomediaplugin"]
252 for processType
in knownProcessTypes
:
253 log
.info("TEST-INFO | leakcheck | %s process: leak threshold set at %d bytes"
254 % (processType
, leakThresholds
.get(processType
, 0)))
256 for processType
in leakThresholds
:
257 if not processType
in knownProcessTypes
:
258 log
.info("TEST-UNEXPECTED-FAIL | leakcheck | Unknown process type %s in leakThresholds"
261 (leakLogFileDir
, leakFileBase
) = os
.path
.split(leakLogFile
)
262 if leakFileBase
[-4:] == ".log":
263 leakFileBase
= leakFileBase
[:-4]
264 fileNameRegExp
= re
.compile(r
"_([a-z]*)_pid\d*.log$")
266 fileNameRegExp
= re
.compile(r
"_([a-z]*)_pid\d*$")
268 for fileName
in os
.listdir(leakLogFileDir
):
269 if fileName
.find(leakFileBase
) != -1:
270 thisFile
= os
.path
.join(leakLogFileDir
, fileName
)
271 m
= fileNameRegExp
.search(fileName
)
273 processType
= m
.group(1)
275 processType
= "default"
276 if not processType
in knownProcessTypes
:
277 log
.info("TEST-UNEXPECTED-FAIL | leakcheck | Leak log with unknown process type %s"
279 leakThreshold
= leakThresholds
.get(processType
, 0)
280 processSingleLeakFile(thisFile
, processType
, leakThreshold
,
281 processType
in ignoreMissingLeaks
)
285 Returns total system memory in kilobytes.
286 Works only on unix-like platforms where `free` is in the path.
288 return int(os
.popen("free").readlines()[1].split()[1])
290 def environment(xrePath
, env
=None, crashreporter
=True, debugger
=False, dmdPath
=None, lsanPath
=None):
291 """populate OS environment variables for mochitest"""
293 env
= os
.environ
.copy() if env
is None else env
295 assert os
.path
.isabs(xrePath
)
298 ldLibraryPath
= os
.path
.join(os
.path
.dirname(xrePath
), "MacOS")
300 ldLibraryPath
= xrePath
305 if 'toolkit' in mozinfo
.info
and mozinfo
.info
['toolkit'] == "gonk":
306 # Skip all of this, it's only valid for the host.
309 envVar
= "LD_LIBRARY_PATH"
310 env
['MOZILLA_FIVE_HOME'] = xrePath
311 dmdLibrary
= "libdmd.so"
312 preloadEnvVar
= "LD_PRELOAD"
314 envVar
= "DYLD_LIBRARY_PATH"
315 dmdLibrary
= "libdmd.dylib"
316 preloadEnvVar
= "DYLD_INSERT_LIBRARIES"
319 dmdLibrary
= "dmd.dll"
320 preloadEnvVar
= "MOZ_REPLACE_MALLOC_LIB"
322 envValue
= ((env
.get(envVar
), str(ldLibraryPath
))
324 else (ldLibraryPath
, dmdPath
, env
.get(envVar
)))
325 env
[envVar
] = os
.path
.pathsep
.join([path
for path
in envValue
if path
])
327 if dmdPath
and dmdLibrary
and preloadEnvVar
:
328 env
[preloadEnvVar
] = os
.path
.join(dmdPath
, dmdLibrary
)
331 env
['GNOME_DISABLE_CRASH_DIALOG'] = '1'
332 env
['XRE_NO_WINDOWS_CRASH_DIALOG'] = '1'
334 if crashreporter
and not debugger
:
335 env
['MOZ_CRASHREPORTER_NO_REPORT'] = '1'
336 env
['MOZ_CRASHREPORTER'] = '1'
338 env
['MOZ_CRASHREPORTER_DISABLE'] = '1'
340 # Crash on non-local network connections by default.
341 # MOZ_DISABLE_NONLOCAL_CONNECTIONS can be set to "0" to temporarily
342 # enable non-local connections for the purposes of local testing. Don't
343 # override the user's choice here. See bug 1049688.
344 env
.setdefault('MOZ_DISABLE_NONLOCAL_CONNECTIONS', '1')
346 # Set WebRTC logging in case it is not set yet
347 env
.setdefault('NSPR_LOG_MODULES', 'signaling:5,mtransport:5,datachannel:5,jsep:5,MediaPipelineFactory:5')
348 env
.setdefault('R_LOG_LEVEL', '6')
349 env
.setdefault('R_LOG_DESTINATION', 'stderr')
350 env
.setdefault('R_LOG_VERBOSE', '1')
352 # ASan specific environment stuff
353 asan
= bool(mozinfo
.info
.get("asan"))
354 if asan
and (mozinfo
.isLinux
or mozinfo
.isMac
):
357 llvmsym
= os
.path
.join(xrePath
, "llvm-symbolizer")
358 if os
.path
.isfile(llvmsym
):
359 env
["ASAN_SYMBOLIZER_PATH"] = llvmsym
360 log
.info("INFO | runtests.py | ASan using symbolizer at %s" % llvmsym
)
362 log
.info("TEST-UNEXPECTED-FAIL | runtests.py | Failed to find ASan symbolizer at %s" % llvmsym
)
364 totalMemory
= systemMemory()
366 # Only 4 GB RAM or less available? Use custom ASan options to reduce
367 # the amount of resources required to do the tests. Standard options
368 # will otherwise lead to OOM conditions on the current test slaves.
369 message
= "INFO | runtests.py | ASan running in %s configuration"
371 if totalMemory
<= 1024 * 1024 * 4:
372 message
= message
% 'low-memory'
373 asanOptions
= ['quarantine_size=50331648', 'malloc_context_size=5']
375 message
= message
% 'default memory'
378 log
.info("LSan enabled.")
379 asanOptions
.append('detect_leaks=1')
380 lsanOptions
= ["exitcode=0"]
381 suppressionsFile
= os
.path
.join(lsanPath
, 'lsan_suppressions.txt')
382 if os
.path
.exists(suppressionsFile
):
383 log
.info("LSan using suppression file " + suppressionsFile
)
384 lsanOptions
.append("suppressions=" + suppressionsFile
)
386 log
.info("WARNING | runtests.py | LSan suppressions file does not exist! " + suppressionsFile
)
387 env
["LSAN_OPTIONS"] = ':'.join(lsanOptions
)
388 # Run shutdown GCs and CCs to avoid spurious leaks.
389 env
['MOZ_CC_RUN_DURING_SHUTDOWN'] = '1'
392 env
['ASAN_OPTIONS'] = ':'.join(asanOptions
)
395 log
.info("Failed determine available memory, disabling ASan low-memory configuration: %s" % err
.strerror
)
397 log
.info("Failed determine available memory, disabling ASan low-memory configuration")
403 def dumpScreen(utilityPath
):
404 """dumps a screenshot of the entire screen to a directory specified by
405 the MOZ_UPLOAD_DIR environment variable"""
407 # Need to figure out which OS-dependent tool to use
409 utility
= [os
.path
.join(utilityPath
, "screentopng")]
410 utilityname
= "screentopng"
412 utility
= ['/usr/sbin/screencapture', '-C', '-x', '-t', 'png']
413 utilityname
= "screencapture"
415 utility
= [os
.path
.join(utilityPath
, "screenshot.exe")]
416 utilityname
= "screenshot"
418 # Get dir where to write the screenshot file
419 parent_dir
= os
.environ
.get('MOZ_UPLOAD_DIR', None)
421 log
.info('Failed to retrieve MOZ_UPLOAD_DIR env var')
426 tmpfd
, imgfilename
= tempfile
.mkstemp(prefix
='mozilla-test-fail-screenshot_', suffix
='.png', dir=parent_dir
)
428 returncode
= subprocess
.call(utility
+ [imgfilename
])
429 printstatus(returncode
, utilityname
)
431 log
.info("Failed to start %s for screenshot: %s" %
432 utility
[0], err
.strerror
)
435 class ShutdownLeaks(object):
437 Parses the mochitest run log when running a debug build, assigns all leaked
438 DOM windows (that are still around after test suite shutdown, despite running
439 the GC) to the tests that created them and prints leak statistics.
442 def __init__(self
, logger
):
445 self
.leakedWindows
= {}
446 self
.leakedDocShells
= set()
447 self
.currentTest
= None
448 self
.seenShutdown
= False
450 def log(self
, message
):
451 if message
['action'] == 'log':
452 line
= message
['message']
453 if line
[2:11] == "DOMWINDOW":
454 self
._logWindow
(line
)
455 elif line
[2:10] == "DOCSHELL":
456 self
._logDocShell
(line
)
457 elif line
.startswith("TEST-START | Shutdown"):
458 self
.seenShutdown
= True
459 elif message
['action'] == 'test_start':
460 fileName
= message
['test'].replace("chrome://mochitests/content/browser/", "")
461 self
.currentTest
= {"fileName": fileName
, "windows": set(), "docShells": set()}
462 elif message
['action'] == 'test_end':
463 # don't track a test if no windows or docShells leaked
464 if self
.currentTest
and (self
.currentTest
["windows"] or self
.currentTest
["docShells"]):
465 self
.tests
.append(self
.currentTest
)
466 self
.currentTest
= None
469 if not self
.seenShutdown
:
470 self
.logger
.warning("TEST-UNEXPECTED-FAIL | ShutdownLeaks | process() called before end of test suite")
472 for test
in self
._parseLeakingTests
():
473 for url
, count
in self
._zipLeakedWindows
(test
["leakedWindows"]):
474 self
.logger
.warning("TEST-UNEXPECTED-FAIL | %s | leaked %d window(s) until shutdown [url = %s]" % (test
["fileName"], count
, url
))
476 if test
["leakedDocShells"]:
477 self
.logger
.warning("TEST-UNEXPECTED-FAIL | %s | leaked %d docShell(s) until shutdown" % (test
["fileName"], len(test
["leakedDocShells"])))
479 def _logWindow(self
, line
):
480 created
= line
[:2] == "++"
481 pid
= self
._parseValue
(line
, "pid")
482 serial
= self
._parseValue
(line
, "serial")
484 # log line has invalid format
485 if not pid
or not serial
:
486 self
.logger
.warning("TEST-UNEXPECTED-FAIL | ShutdownLeaks | failed to parse line <%s>" % line
)
489 key
= pid
+ "." + serial
492 windows
= self
.currentTest
["windows"]
497 elif self
.seenShutdown
and not created
:
498 self
.leakedWindows
[key
] = self
._parseValue
(line
, "url")
500 def _logDocShell(self
, line
):
501 created
= line
[:2] == "++"
502 pid
= self
._parseValue
(line
, "pid")
503 id = self
._parseValue
(line
, "id")
505 # log line has invalid format
506 if not pid
or not id:
507 self
.logger
.warning("TEST-UNEXPECTED-FAIL | ShutdownLeaks | failed to parse line <%s>" % line
)
513 docShells
= self
.currentTest
["docShells"]
517 docShells
.discard(key
)
518 elif self
.seenShutdown
and not created
:
519 self
.leakedDocShells
.add(key
)
521 def _parseValue(self
, line
, name
):
522 match
= re
.search("\[%s = (.+?)\]" % name
, line
)
524 return match
.group(1)
527 def _parseLeakingTests(self
):
530 for test
in self
.tests
:
531 test
["leakedWindows"] = [self
.leakedWindows
[id] for id in test
["windows"] if id in self
.leakedWindows
]
532 test
["leakedDocShells"] = [id for id in test
["docShells"] if id in self
.leakedDocShells
]
533 test
["leakCount"] = len(test
["leakedWindows"]) + len(test
["leakedDocShells"])
535 if test
["leakCount"]:
536 leakingTests
.append(test
)
538 return sorted(leakingTests
, key
=itemgetter("leakCount"), reverse
=True)
540 def _zipLeakedWindows(self
, leakedWindows
):
544 for url
in leakedWindows
:
545 if not url
in counted
:
546 counts
.append((url
, leakedWindows
.count(url
)))
549 return sorted(counts
, key
=itemgetter(1), reverse
=True)
552 class LSANLeaks(object):
554 Parses the log when running an LSAN build, looking for interesting stack frames
555 in allocation stacks, and prints out reports.
558 def __init__(self
, logger
):
560 self
.inReport
= False
561 self
.foundFrames
= set([])
562 self
.recordMoreFrames
= None
563 self
.currStack
= None
564 self
.maxNumRecordedFrames
= 4
566 # Don't various allocation-related stack frames, as they do not help much to
567 # distinguish different leaks.
568 unescapedSkipList
= [
569 "malloc", "js_malloc", "malloc_", "__interceptor_malloc", "moz_malloc", "moz_xmalloc",
570 "calloc", "js_calloc", "calloc_", "__interceptor_calloc", "moz_calloc", "moz_xcalloc",
571 "realloc","js_realloc", "realloc_", "__interceptor_realloc", "moz_realloc", "moz_xrealloc",
573 "js::MallocProvider",
575 self
.skipListRegExp
= re
.compile("^" + "|".join([re
.escape(f
) for f
in unescapedSkipList
]) + "$")
577 self
.startRegExp
= re
.compile("==\d+==ERROR: LeakSanitizer: detected memory leaks")
578 self
.stackFrameRegExp
= re
.compile(" #\d+ 0x[0-9a-f]+ in ([^(</]+)")
579 self
.sysLibStackFrameRegExp
= re
.compile(" #\d+ 0x[0-9a-f]+ \(([^+]+)\+0x[0-9a-f]+\)")
583 if re
.match(self
.startRegExp
, line
):
587 if not self
.inReport
:
590 if line
.startswith("Direct leak"):
592 self
.recordMoreFrames
= True
596 if line
.startswith("Indirect leak"):
598 # Only report direct leaks, in the hope that they are less flaky.
599 self
.recordMoreFrames
= False
602 if line
.startswith("SUMMARY: AddressSanitizer"):
604 self
.inReport
= False
607 if not self
.recordMoreFrames
:
610 stackFrame
= re
.match(self
.stackFrameRegExp
, line
)
612 # Split the frame to remove any return types.
613 frame
= stackFrame
.group(1).split()[-1]
614 if not re
.match(self
.skipListRegExp
, frame
):
615 self
._recordFrame
(frame
)
618 sysLibStackFrame
= re
.match(self
.sysLibStackFrameRegExp
, line
)
620 # System library stack frames will never match the skip list,
621 # so don't bother checking if they do.
622 self
._recordFrame
(sysLibStackFrame
.group(1))
624 # If we don't match either of these, just ignore the frame.
625 # We'll end up with "unknown stack" if everything is ignored.
628 for f
in self
.foundFrames
:
629 self
.logger
.warning("TEST-UNEXPECTED-FAIL | LeakSanitizer | leak at " + f
)
631 def _finishStack(self
):
632 if self
.recordMoreFrames
and len(self
.currStack
) == 0:
633 self
.currStack
= ["unknown stack"]
635 self
.foundFrames
.add(", ".join(self
.currStack
))
636 self
.currStack
= None
637 self
.recordMoreFrames
= False
638 self
.numRecordedFrames
= 0
640 def _recordFrame(self
, frame
):
641 self
.currStack
.append(frame
)
642 self
.numRecordedFrames
+= 1
643 if self
.numRecordedFrames
>= self
.maxNumRecordedFrames
:
644 self
.recordMoreFrames
= False