Bug 1325148 - Use "error" level in mozleak when logging leak failures, r?jgraham draft
authorAndrew Halberstadt <ahalberstadt@mozilla.com>
Wed, 21 Dec 2016 14:02:04 -0500
changeset 454183 7e419a4b565046050dd96b35f9ac910fd1f6eef4
parent 454127 d7b6af32811bddcec10a47d24bd455a1ec1836fc
child 454184 a70de09e4121feeacae4a884aa265ed4a5f4b74a
push id39859
push userahalberstadt@mozilla.com
push dateWed, 28 Dec 2016 14:22:54 +0000
reviewersjgraham
bugs1325148
milestone53.0a1
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
testing/mochitest/leaks.py
testing/mozbase/mozleak/mozleak/leaklog.py
--- 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)