Bug 1354232 - Add support for LSAN to mozlog, r=ahal, mccr8 draft
authorJames Graham <james@hoppipolla.co.uk>
Mon, 21 May 2018 11:37:35 +0100
changeset 805833 38ceb6f6da4d168b80fc903c29c1970ed756332a
parent 805832 9dcdbbccb1fcd680e94a5fcbbd9ca74e555aa479
child 805834 43408d37349ce2f9cbce7a257dff63b565a264d7
push id112776
push userbmo:james@hoppipolla.co.uk
push dateFri, 08 Jun 2018 15:53:57 +0000
reviewersahal, mccr8
bugs1354232
milestone62.0a1
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
@@ -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