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

@@ -1,3 +1,8 @@
+# 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
 
 
@@ -5,19 +10,22 @@ 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.allowedMatch = None
         self.maxNumRecordedFrames = 4
+        self.summaryData = None
+        self.scope = scope
+        self.allowedMatch = None
+        self.sawError = False
 
         # Don't various allocation-related stack frames, as they do not help much to
         # distinguish different leaks.
@@ -40,36 +48,53 @@ class LSANLeaks(object):
         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:
@@ -77,7 +102,7 @@ class LSANLeaks(object):
             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:
@@ -87,45 +112,59 @@ class LSANLeaks(object):
 
         # 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:

testing/mozbase/mozlog/mozlog/formatters/machformatter.py

@@ -224,6 +224,26 @@ class MachFormatter(base.BaseFormatter):
 
         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:

testing/mozbase/mozlog/mozlog/formatters/tbplformatter.py

@@ -277,6 +277,21 @@ class TbplFormatter(BaseFormatter):
         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']

testing/mozbase/mozlog/mozlog/logtypes.py

@@ -245,6 +245,12 @@ class Any(DataType):
         return data
 
 
+class Boolean(DataType):
+
+    def convert(self, data):
+        return bool(data)
+
+
 class Tuple(ContainerType):
 
     def _format_item_type(self, item_type):

testing/mozbase/mozlog/mozlog/structuredlog.py

@@ -11,7 +11,8 @@ 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
 
@@ -53,6 +54,18 @@ Allowed actions, and subfields:
       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
@@ -464,6 +477,18 @@ class StructuredLogger(object):
         """
         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.