Bug 1354232 - Add support for LSAN to mozlog, r=ahal, mccr8
This adds two new actions to mozlog, one for reporting an LSAN
failure, and one for reporting the summary.
MozReview-Commit-ID: D7ep27SrI1n
--- a/testing/mozbase/mozleak/mozleak/lsan.py
+++ b/testing/mozbase/mozleak/mozleak/lsan.py
@@ -1,28 +1,36 @@
+# This Source Code Form is subject to the terms of the Mozilla Public
+# License, v. 2.0. If a copy of the MPL was not distributed with this
+# file, You can obtain one at http://mozilla.org/MPL/2.0/.
+
+from __future__ import absolute_import
import re
class LSANLeaks(object):
"""
Parses the log when running an LSAN build, looking for interesting stack frames
- in allocation stacks, and prints out reports.
+ in allocation stacks
"""
- def __init__(self, logger):
+ def __init__(self, logger, scope=None, allowed=None):
self.logger = logger
self.inReport = False
self.fatalError = False
self.symbolizerError = False
- self.foundFrames = set([])
+ self.foundFrames = set()
self.recordMoreFrames = None
self.currStack = None
+ self.maxNumRecordedFrames = 4
+ self.summaryData = None
+ self.scope = scope
self.allowedMatch = None
- self.maxNumRecordedFrames = 4
+ self.sawError = False
# Don't various allocation-related stack frames, as they do not help much to
# distinguish different leaks.
unescapedSkipList = [
"malloc", "js_malloc", "malloc_", "__interceptor_malloc", "moz_xmalloc",
"calloc", "js_calloc", "calloc_", "__interceptor_calloc", "moz_xcalloc",
"realloc", "js_realloc", "realloc_", "__interceptor_realloc", "moz_xrealloc",
"new",
@@ -35,98 +43,129 @@ class LSANLeaks(object):
"==\d+==ERROR: LeakSanitizer: detected memory leaks")
self.fatalErrorRegExp = re.compile(
"==\d+==LeakSanitizer has encountered a fatal error.")
self.symbolizerOomRegExp = re.compile(
"LLVMSymbolizer: error reading file: Cannot allocate memory")
self.stackFrameRegExp = re.compile(" #\d+ 0x[0-9a-f]+ in ([^(</]+)")
self.sysLibStackFrameRegExp = re.compile(
" #\d+ 0x[0-9a-f]+ \(([^+]+)\+0x[0-9a-f]+\)")
+ self.summaryRegexp = re.compile(
+ "SUMMARY: AddressSanitizer: (\d+) byte\(s\) leaked in (\d+) allocation\(s\).")
+ self.setAllowed(allowed)
+
+ def setAllowed(self, allowedLines):
+ if not allowedLines:
+ self.allowedRegexp = None
+ else:
+ self.allowedRegexp = re.compile(
+ "^" + "|".join([re.escape(f) for f in allowedLines]))
def log(self, line):
if re.match(self.startRegExp, line):
self.inReport = True
- return
+ # Downgrade this from an ERROR
+ self.sawError = True
+ return "LeakSanitizer: detected memory leaks"
if re.match(self.fatalErrorRegExp, line):
self.fatalError = True
- return
+ return line
if re.match(self.symbolizerOomRegExp, line):
self.symbolizerError = True
- return
+ return line
if not self.inReport:
- return
+ return line
if line.startswith("Direct leak") or line.startswith("Indirect leak"):
self._finishStack()
self.recordMoreFrames = True
self.currStack = []
- return
+ return line
- if line.startswith("SUMMARY: AddressSanitizer"):
+ summaryData = self.summaryRegexp.match(line)
+ if summaryData:
+ assert self.summaryData is None
self._finishStack()
self.inReport = False
+ self.summaryData = (int(item) for item in summaryData.groups())
+ # We don't return the line here because we want to control whether the
+ # leak is seen as an expected failure later
return
if not self.recordMoreFrames:
- return
+ return line
stackFrame = re.match(self.stackFrameRegExp, line)
if stackFrame:
# Split the frame to remove any return types.
frame = stackFrame.group(1).split()[-1]
if not re.match(self.skipListRegExp, frame):
self._recordFrame(frame)
- return
+ return line
sysLibStackFrame = re.match(self.sysLibStackFrameRegExp, line)
if sysLibStackFrame:
# System library stack frames will never match the skip list,
# 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.
+ return line
def process(self):
failures = 0
+ if self.summaryData:
+ allowed = all(allowed for _, allowed in self.foundFrames)
+ self.logger.lsan_summary(*self.summaryData, allowed=allowed)
+ self.summaryData = None
+
if self.fatalError:
- self.logger.error("TEST-UNEXPECTED-FAIL | LeakSanitizer | LeakSanitizer "
- "has encountered a fatal error.")
+ self.logger.error("LeakSanitizer | LeakSanitizer has encountered a fatal error.")
failures += 1
if self.symbolizerError:
- self.logger.error("TEST-UNEXPECTED-FAIL | LeakSanitizer | LLVMSymbolizer "
- "was unable to allocate memory.")
+ self.logger.error("LeakSanitizer | LLVMSymbolizer was unable to allocate memory.\n"
+ "This will cause leaks that "
+ "should be ignored to instead be reported as an error")
failures += 1
- self.logger.info("TEST-INFO | LeakSanitizer | This will cause leaks that "
- "should be ignored to instead be reported as an 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")
+ self.logger.info("LeakSanitizer | To show the "
+ "addresses of leaked objects add report_objects=1 to LSAN_OPTIONS\n"
+ "This can be done in testing/mozbase/mozrunner/mozrunner/utils.py")
- for f in self.foundFrames:
- self.logger.error(
- "TEST-UNEXPECTED-FAIL | LeakSanitizer | leak at " + f)
- failures += 1
+ for frames, allowed in self.foundFrames:
+ self.logger.lsan_leak(frames, scope=self.scope, allowed_match=allowed)
+ if not allowed:
+ failures += 1
+
+ if self.sawError and not (self.summaryData or
+ self.foundFrames or
+ self.fatalError or
+ self.symbolizerError):
+ self.logger.error("LeakSanitizer | Memory leaks detected but no leak report generated")
+
+ self.sawError = False
return failures
def _finishStack(self):
if self.recordMoreFrames and len(self.currStack) == 0:
- self.currStack = ["unknown stack"]
+ self.currStack = {"unknown stack"}
if self.currStack:
- self.foundFrames.add(", ".join(self.currStack))
+ self.foundFrames.add((tuple(self.currStack), self.allowedMatch))
self.currStack = None
+ self.allowedMatch = None
self.recordMoreFrames = False
self.numRecordedFrames = 0
def _recordFrame(self, frame):
+ if self.allowedMatch is None and self.allowedRegexp is not None:
+ self.allowedMatch = frame if self.allowedRegexp.match(frame) else None
self.currStack.append(frame)
self.numRecordedFrames += 1
if self.numRecordedFrames >= self.maxNumRecordedFrames:
self.recordMoreFrames = False
--- a/testing/mozbase/mozlog/mozlog/formatters/machformatter.py
+++ b/testing/mozbase/mozlog/mozlog/formatters/machformatter.py
@@ -217,16 +217,36 @@ class MachFormatter(base.BaseFormatter):
def valgrind_error(self, data):
rv = " " + data['primary'] + "\n"
for line in data['secondary']:
rv = rv + line + "\n"
return rv
+ def lsan_leak(self, data):
+ allowed = data.get("allowed_match")
+ if allowed:
+ prefix = self.term.yellow("FAIL")
+ else:
+ prefix = self.term.red("UNEXPECTED-FAIL")
+
+ return "%s LeakSanitizer: leak at %s" % (prefix, ", ".join(data["frames"]))
+
+ def lsan_summary(self, data):
+ allowed = data.get("allowed", False)
+ if allowed:
+ prefix = self.term.yellow("WARNING")
+ else:
+ prefix = self.term.red("ERROR")
+
+ return ("%s | LeakSanitizer | "
+ "SUMMARY: AddressSanitizer: %d byte(s) leaked in %d allocation(s)." %
+ (prefix, data["bytes"], data["allocations"]))
+
def test_status(self, data):
test = self._get_test_id(data)
if test not in self.status_buffer:
self.status_buffer[test] = {"count": 0, "unexpected": 0, "pass": 0}
self.status_buffer[test]["count"] += 1
if data["status"] == "PASS":
self.status_buffer[test]["pass"] += 1
--- a/testing/mozbase/mozlog/mozlog/formatters/tbplformatter.py
+++ b/testing/mozbase/mozlog/mozlog/formatters/tbplformatter.py
@@ -270,16 +270,33 @@ class TbplFormatter(BaseFormatter):
return rv
def lint(self, data):
fmt = "TEST-UNEXPECTED-{level} | {path}:{lineno}{column} | {message} ({rule})"
data["column"] = ":%s" % data["column"] if data["column"] else ""
data['rule'] = data['rule'] or data['linter'] or ""
return fmt.append(fmt.format(**data))
+ def lsan_leak(self, data):
+ frames = data.get("frames")
+ allowed_match = data.get("allowed_match")
+ frame_list = ", ".join(frames)
+ prefix = "TEST-UNEXPECTED-FAIL" if not allowed_match else "TEST-FAIL"
+ suffix = ("" if not allowed_match
+ else "INFO | LeakSanitizer | Frame %s matched a expected leak\n" % allowed_match)
+ return "%s | LeakSanitizer | leak at %s\n%s" % (prefix, frame_list, suffix)
+
+ def lsan_summary(self, data):
+ if not data.get("allowed", False):
+ return ("ERROR | LeakSanitizer | "
+ "SUMMARY: AddressSanitizer: %d byte(s) leaked in %d allocation(s)." %
+ (data["bytes"], data["allocations"]))
+ return ("INFO | LeakSanitizer | "
+ "SUMMARY: (expected) AddressSanitizer: %d byte(s) leaked in %d allocation(s).")
+
def _format_suite_summary(self, suite, summary):
counts = summary['counts']
logs = summary['unexpected_logs']
total = sum(self.summary.aggregate('count', counts).values())
expected = sum(self.summary.aggregate('expected', counts).values())
status_str = "{}/{}".format(expected, total)
rv = ["{}: {}".format(suite, status_str)]
--- a/testing/mozbase/mozlog/mozlog/logtypes.py
+++ b/testing/mozbase/mozlog/mozlog/logtypes.py
@@ -237,16 +237,22 @@ class Int(DataType):
class Any(DataType):
def convert(self, data):
return data
+class Boolean(DataType):
+
+ def convert(self, data):
+ return bool(data)
+
+
class Tuple(ContainerType):
def _format_item_type(self, item_type):
superfmt = super(Tuple, self)._format_item_type
if isinstance(item_type, (tuple, list)):
return [superfmt(t) for t in item_type]
return (superfmt(item_type),)
--- a/testing/mozbase/mozlog/mozlog/structuredlog.py
+++ b/testing/mozbase/mozlog/mozlog/structuredlog.py
@@ -6,17 +6,18 @@ from __future__ import absolute_import,
from multiprocessing import current_process
from threading import current_thread, Lock
import json
import sys
import time
import traceback
-from .logtypes import Unicode, TestId, TestList, Status, SubStatus, Dict, List, Int, Any, Tuple
+from .logtypes import (Unicode, TestId, TestList, Status, SubStatus, Dict, List, Int, Any, Tuple,
+ Boolean)
from .logtypes import log_action, convertor_registry
"""Structured Logging for recording test results.
Allowed actions, and subfields:
suite_start
tests - List of test names
name - Name for the suite
@@ -47,16 +48,28 @@ Allowed actions, and subfields:
command - Command line of the process
data - Output data from the process
assertion_count
count - Number of assertions produced
min_expected - Minimum expected number of assertions
max_expected - Maximum expected number of assertions
+ lsan_leak
+ frames - List of stack frames from the leak report
+ scope - An identifier for the set of tests run during the browser session
+ (e.g. a directory name)
+ allowed_match - A stack frame in the list that matched a rule meaning the
+ leak is expected
+
+ lsan_summary
+ bytes - Number of bytes leaked
+ allocations - Number of allocations
+ allowed - Boolean indicating whether all detected leaks matched allow rules
+
log
level [CRITICAL | ERROR | WARNING |
INFO | DEBUG] - level of the logging message
message - Message to log
Subfields for all messages:
action - the action type of the current message
time - the timestamp in ms since the epoch of the log message
@@ -458,16 +471,28 @@ class StructuredLogger(object):
"""Log count of assertions produced when running a test.
:param count: - Number of assertions produced
:param min_expected: - Minimum expected number of assertions
:param max_expected: - Maximum expected number of assertions
"""
self._log_data("assertion_count", data)
+ @log_action(List(Unicode, "frames"),
+ Unicode("scope", optional=True, default=None),
+ Unicode("allowed_match", optional=True, default=None))
+ def lsan_leak(self, data):
+ self._log_data("lsan_leak", data)
+
+ @log_action(Int("bytes"),
+ Int("allocations"),
+ Boolean("allowed", optional=True, default=False))
+ def lsan_summary(self, data):
+ self._log_data("lsan_summary", data)
+
@log_action()
def shutdown(self, data):
"""Shutdown the logger.
This logs a 'shutdown' action after which any further attempts to use
the logger will raise a :exc:`LoggerShutdownError`.
This is also called implicitly from the destructor or