Bug 1354232 - Add support for LSAN to mozlog, r=ahal, mccr8
authorJames Graham <james@hoppipolla.co.uk>
Mon, 21 May 2018 11:37:35 +0100
changeset 482440 6eda80370f59eb70e4f3d64f8552d894e0313f13
parent 482439 05441f0a29b3e1de138727c3e41b00b01bf3d0e5
child 482441 6d28db898070e56ac198dfa94553f83facd96ab7
push id9719
push userffxbld-merge
push dateFri, 24 Aug 2018 17:49:46 +0000
treeherdermozilla-beta@719ec98fba77 [default view] [failures only]
perfherder[talos] [build metrics] [platform microbench] (compared to previous push)
reviewersahal, mccr8
bugs1354232
milestone63.0a1
first release with
nightly linux32
nightly linux64
nightly mac
nightly win32
nightly win64
last release without
nightly linux32
nightly linux64
nightly mac
nightly win32
nightly win64
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
testing/mozbase/mozleak/mozleak/lsan.py
testing/mozbase/mozlog/mozlog/formatters/machformatter.py
testing/mozbase/mozlog/mozlog/formatters/tbplformatter.py
testing/mozbase/mozlog/mozlog/logtypes.py
testing/mozbase/mozlog/mozlog/structuredlog.py
--- 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
@@ -219,16 +219,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
@@ -272,16 +272,31 @@ 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):
+        level = "INFO" if data.get("allowed", False) else "ERROR"
+        return ("%s | LeakSanitizer | "
+                "SUMMARY: AddressSanitizer: %d byte(s) leaked in %d allocation(s)." %
+                (level, data["bytes"], data["allocations"]))
+
     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
@@ -240,16 +240,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
 import six
 
 """Structured Logging for recording test results.
 
 Allowed actions, and subfields:
   suite_start
       tests  - List of test names
@@ -48,16 +49,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
@@ -459,16 +472,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