Bug 1325148 - Use "error" level in mozleak when logging leak failures, r?jgraham
This fixes a regression when switching to the StructuredOutputParser in mozharness.
Previously, mozleak was relying on the string "TEST-UNEXPECTED-FAIL" to turn the jobs
orange, but it was doing so at the "warning" level. The StructuredOutputParser requires
the "error" level to set the appropriate tbpl_status.
MozReview-Commit-ID: 9u9mwqrkA6E
--- a/testing/mochitest/leaks.py
+++ b/testing/mochitest/leaks.py
@@ -43,46 +43,46 @@ class ShutdownLeaks(object):
elif message['action'] == 'test_end':
# don't track a test if no windows or docShells leaked
if self.currentTest and (self.currentTest["windows"] or self.currentTest["docShells"]):
self.tests.append(self.currentTest)
self.currentTest = None
def process(self):
if not self.seenShutdown:
- self.logger.warning(
+ self.logger.error(
"TEST-UNEXPECTED-FAIL | ShutdownLeaks | process() called before end of test suite")
for test in self._parseLeakingTests():
for url, count in self._zipLeakedWindows(test["leakedWindows"]):
- self.logger.warning(
+ self.logger.error(
"TEST-UNEXPECTED-FAIL | %s | leaked %d window(s) until shutdown "
"[url = %s]" % (test["fileName"], count, url))
if test["leakedWindowsString"]:
self.logger.info("TEST-INFO | %s | windows(s) leaked: %s" %
(test["fileName"], test["leakedWindowsString"]))
if test["leakedDocShells"]:
- self.logger.warning("TEST-UNEXPECTED-FAIL | %s | leaked %d docShell(s) until "
- "shutdown" %
- (test["fileName"], len(test["leakedDocShells"])))
+ self.logger.error("TEST-UNEXPECTED-FAIL | %s | leaked %d docShell(s) until "
+ "shutdown" %
+ (test["fileName"], len(test["leakedDocShells"])))
self.logger.info("TEST-INFO | %s | docShell(s) leaked: %s" %
(test["fileName"], ', '.join(["[pid = %s] [id = %s]" %
x for x in test["leakedDocShells"]]
)))
def _logWindow(self, line):
created = line[:2] == "++"
pid = self._parseValue(line, "pid")
serial = self._parseValue(line, "serial")
# log line has invalid format
if not pid or not serial:
- self.logger.warning(
+ self.logger.error(
"TEST-UNEXPECTED-FAIL | ShutdownLeaks | failed to parse line <%s>" % line)
return
key = (pid, serial)
if self.currentTest:
windows = self.currentTest["windows"]
if created:
@@ -94,17 +94,17 @@ class ShutdownLeaks(object):
def _logDocShell(self, line):
created = line[:2] == "++"
pid = self._parseValue(line, "pid")
id = self._parseValue(line, "id")
# log line has invalid format
if not pid or not id:
- self.logger.warning(
+ self.logger.error(
"TEST-UNEXPECTED-FAIL | ShutdownLeaks | failed to parse line <%s>" % line)
return
key = (pid, id)
if self.currentTest:
docShells = self.currentTest["docShells"]
if created:
@@ -228,27 +228,27 @@ class LSANLeaks(object):
# so don't bother checking if they do.
self._recordFrame(sysLibStackFrame.group(1))
# If we don't match either of these, just ignore the frame.
# We'll end up with "unknown stack" if everything is ignored.
def process(self):
if self.fatalError:
- self.logger.warning("TEST-UNEXPECTED-FAIL | LeakSanitizer | LeakSanitizer "
- "has encountered a fatal error.")
+ self.logger.error("TEST-UNEXPECTED-FAIL | LeakSanitizer | LeakSanitizer "
+ "has encountered a fatal error.")
if self.foundFrames:
self.logger.info("TEST-INFO | LeakSanitizer | To show the "
"addresses of leaked objects add report_objects=1 to LSAN_OPTIONS")
self.logger.info("TEST-INFO | LeakSanitizer | This can be done "
"in testing/mozbase/mozrunner/mozrunner/utils.py")
for f in self.foundFrames:
- self.logger.warning(
+ self.logger.error(
"TEST-UNEXPECTED-FAIL | LeakSanitizer | leak at " + f)
def _finishStack(self):
if self.recordMoreFrames and len(self.currStack) == 0:
self.currStack = ["unknown stack"]
if self.currStack:
self.foundFrames.add(", ".join(self.currStack))
self.currStack = None
--- a/testing/mozbase/mozleak/mozleak/leaklog.py
+++ b/testing/mozbase/mozleak/mozleak/leaklog.py
@@ -33,18 +33,16 @@ def process_single_leak_file(leakLogFile
r"\s*-?\d+\s+(?P<numLeaked>-?\d+)")
# The class name can contain spaces. We remove trailing whitespace later.
log = log or _get_default_logger()
processString = "%s process:" % processType
crashedOnPurpose = False
totalBytesLeaked = None
- logAsWarning = False
- leakAnalysis = []
leakedObjectAnalysis = []
leakedObjectNames = []
recordLeakedObjects = False
with open(leakLogFileName, "r") as leaks:
for line in leaks:
if line.find("purposefully crash") > -1:
crashedOnPurpose = True
matches = lineRe.match(line)
@@ -63,90 +61,78 @@ def process_single_leak_file(leakLogFile
log.info(line.rstrip())
# Analyse the leak log, but output later or it will interrupt the
# leak table
if name == "TOTAL":
# Multiple default processes can end up writing their bloat views into a single
# log, particularly on B2G. Eventually, these should be split into multiple
# logs (bug 1068869), but for now, we report the largest leak.
if totalBytesLeaked is not None:
- leakAnalysis.append("WARNING | leakcheck | %s "
- "multiple BloatView byte totals found"
- % processString)
+ log.warning("leakcheck | %s "
+ "multiple BloatView byte totals found"
+ % processString)
else:
totalBytesLeaked = 0
if bytesLeaked > totalBytesLeaked:
totalBytesLeaked = bytesLeaked
# Throw out the information we had about the previous bloat
# view.
leakedObjectNames = []
leakedObjectAnalysis = []
recordLeakedObjects = True
else:
recordLeakedObjects = False
if size < 0 or bytesLeaked < 0 or numLeaked < 0:
- leakAnalysis.append("TEST-UNEXPECTED-FAIL | leakcheck | %s negative leaks caught!"
- % processString)
- logAsWarning = True
+ log.error("TEST-UNEXPECTED-FAIL | leakcheck | %s negative leaks caught!"
+ % processString)
continue
if name != "TOTAL" and numLeaked != 0 and recordLeakedObjects:
leakedObjectNames.append(name)
leakedObjectAnalysis.append("TEST-INFO | leakcheck | %s leaked %d %s"
% (processString, numLeaked, name))
- leakAnalysis.extend(leakedObjectAnalysis)
- if logAsWarning:
- log.warning('\n'.join(leakAnalysis))
- else:
- log.info('\n'.join(leakAnalysis))
-
- logAsWarning = False
+ log.info('\n'.join(leakedObjectAnalysis))
if totalBytesLeaked is None:
# We didn't see a line with name 'TOTAL'
if crashedOnPurpose:
log.info("TEST-INFO | leakcheck | %s deliberate crash and thus no leak log"
% processString)
elif ignoreMissingLeaks:
log.info("TEST-INFO | leakcheck | %s ignoring missing output line for total leaks"
% processString)
else:
- log.info("TEST-UNEXPECTED-FAIL | leakcheck | %s missing output line for total leaks!"
- % processString)
+ log.error("TEST-UNEXPECTED-FAIL | leakcheck | %s missing output line for total leaks!"
+ % processString)
log.info("TEST-INFO | leakcheck | missing output line from log file %s"
% leakLogFileName)
return
if totalBytesLeaked == 0:
log.info("TEST-PASS | leakcheck | %s no leaks detected!" %
processString)
return
- if totalBytesLeaked > leakThreshold:
- logAsWarning = True
- # Fail the run if we're over the threshold (which defaults to 0)
- prefix = "TEST-UNEXPECTED-FAIL"
- else:
- prefix = "WARNING"
# Create a comma delimited string of the first N leaked objects found,
# to aid with bug summary matching in TBPL. Note: The order of the objects
# had no significance (they're sorted alphabetically).
maxSummaryObjects = 5
leakedObjectSummary = ', '.join(leakedObjectNames[:maxSummaryObjects])
if len(leakedObjectNames) > maxSummaryObjects:
leakedObjectSummary += ', ...'
+ message = "leakcheck | %s %d bytes leaked (%s)" % (
+ processString, totalBytesLeaked, leakedObjectSummary)
+
# totalBytesLeaked will include any expected leaks, so it can be off
# by a few thousand bytes.
- if logAsWarning:
- log.warning("%s | leakcheck | %s %d bytes leaked (%s)"
- % (prefix, processString, totalBytesLeaked, leakedObjectSummary))
+ if totalBytesLeaked > leakThreshold:
+ log.error("TEST-UNEXPECTED-FAIL | %s" % message)
else:
- log.info("%s | leakcheck | %s %d bytes leaked (%s)"
- % (prefix, processString, totalBytesLeaked, leakedObjectSummary))
+ log.warning(message)
def process_leak_log(leak_log_file, leak_thresholds=None,
ignore_missing_leaks=None, log=None,
stack_fixer=None):
"""Process the leak log, including separate leak logs created
by child processes.
@@ -170,35 +156,35 @@ def process_leak_log(leak_log_file, leak
creates a leak log without a TOTAL, then we report an error if it isn't
in the list ignore_missing_leaks.
"""
log = log or _get_default_logger()
leakLogFile = leak_log_file
if not os.path.exists(leakLogFile):
- log.info(
- "WARNING | leakcheck | refcount logging is off, so leaks can't be detected!")
+ log.warning(
+ "leakcheck | refcount logging is off, so leaks can't be detected!")
return
leakThresholds = leak_thresholds or {}
ignoreMissingLeaks = ignore_missing_leaks or []
# This list is based on kGeckoProcessTypeString. ipdlunittest processes likely
# are not going to produce leak logs we will ever see.
knownProcessTypes = ["default", "plugin", "tab", "geckomediaplugin", "gpu"]
for processType in knownProcessTypes:
log.info("TEST-INFO | leakcheck | %s process: leak threshold set at %d bytes"
% (processType, leakThresholds.get(processType, 0)))
for processType in leakThresholds:
if processType not in knownProcessTypes:
- log.info("TEST-UNEXPECTED-FAIL | leakcheck | Unknown process type %s in leakThresholds"
- % processType)
+ log.error("TEST-UNEXPECTED-FAIL | leakcheck | "
+ "Unknown process type %s in leakThresholds" % processType)
(leakLogFileDir, leakFileBase) = os.path.split(leakLogFile)
if leakFileBase[-4:] == ".log":
leakFileBase = leakFileBase[:-4]
fileNameRegExp = re.compile(r"_([a-z]*)_pid\d*.log$")
else:
fileNameRegExp = re.compile(r"_([a-z]*)_pid\d*$")
@@ -206,14 +192,14 @@ def process_leak_log(leak_log_file, leak
if fileName.find(leakFileBase) != -1:
thisFile = os.path.join(leakLogFileDir, fileName)
m = fileNameRegExp.search(fileName)
if m:
processType = m.group(1)
else:
processType = "default"
if processType not in knownProcessTypes:
- log.info("TEST-UNEXPECTED-FAIL | leakcheck | Leak log with unknown process type %s"
- % processType)
+ log.error("TEST-UNEXPECTED-FAIL | leakcheck | "
+ "Leak log with unknown process type %s" % processType)
leakThreshold = leakThresholds.get(processType, 0)
process_single_leak_file(thisFile, processType, leakThreshold,
processType in ignoreMissingLeaks,
log=log, stackFixer=stack_fixer)