Merged PR 631: [feature] properly filter log records when they're modified by a logging.filter

When you modify a LogRecord inside a filter, whether it should be emitted or not based on the current level is determined by the handler before it applies the filter in the base class. This just reverses the order of the evaluation to make sure we evaluate the filter before the level. It also includes pieces getting a named logger rather than the implicit root logger.

Author: Matthew Carlson

MuPythonLibrary/MuAnsiHandler.py

@@ -276,6 +276,24 @@ def __init__(self, stream=None, strip=None, convert=None):
             self._default_back = self._back
             self._default_style = self._style
 
+    def handle(self, record):
+        """
+        Conditionally emit the specified logging record.
+        Emission depends on filters which may have been added to the handler.
+        Wrap the actual emission of the record with acquisition/release of
+        the I/O thread lock. Returns whether the filter passed the record for
+        emission.
+        """
+
+        rv = self.filter(record)
+        if rv and record.levelno >= self.level:
+            self.acquire()
+            try:
+                self.emit(record)
+            finally:
+                self.release()
+        return rv
+
     def get_win32_calls(self):
         if self.convert:
             return {

MuPythonLibrary/MuFileHandler.py

@@ -0,0 +1,50 @@
+# @file MuAnsiHandler.py
+# Handle basic logging outputting to files
+##
+# Copyright (c) 2018, Microsoft Corporation
+#
+# All rights reserved.
+# Redistribution and use in source and binary forms, with or without
+# modification, are permitted provided that the following conditions are met:
+# 1. Redistributions of source code must retain the above copyright notice,
+# this list of conditions and the following disclaimer.
+# 2. Redistributions in binary form must reproduce the above copyright notice,
+# this list of conditions and the following disclaimer in the documentation
+# and/or other materials provided with the distribution.
+#
+# THIS SOFTWARE IS PROVIDED BY THE COPYRIGHT HOLDERS AND CONTRIBUTORS "AS IS"
+# AND ANY EXPRESS OR IMPLIED WARRANTIES, INCLUDING, BUT NOT LIMITED TO, THE
+# IMPLIED WARRANTIES OF MERCHANTABILITY AND FITNESS FOR A PARTICULAR PURPOSE
+# ARE DISCLAIMED. IN NO EVENT SHALL THE COPYRIGHT HOLDER OR CONTRIBUTORS BE
+# LIABLE FOR ANY DIRECT, INDIRECT, INCIDENTAL, SPECIAL, EXEMPLARY, OR
+# CONSEQUENTIAL DAMAGES (INCLUDING, BUT NOT LIMITED TO, PROCUREMENT OF
+# SUBSTITUTE GOODS OR SERVICES; LOSS OF USE,DATA, OR PROFITS; OR BUSINESS
+# INTERRUPTION) HOWEVER CAUSED AND ON ANY THEORY OF LIABILITY, WHETHER IN
+# CONTRACT, STRICT LIABILITY, OR TORT (INCLUDING NEGLIGENCEOR OTHERWISE)
+# ARISING IN ANY WAY OUT OF THE USE OF THIS SOFTWARE, EVEN IF ADVISED OF THE
+# POSSIBILITY OF SUCH DAMAGE.
+##
+import logging
+
+
+class FileHandler(logging.FileHandler):
+    def __init__(self, filename, mode='w+'):
+        logging.FileHandler.__init__(self, filename, mode=mode)
+
+    def handle(self, record):
+        """
+        Conditionally emit the specified logging record.
+        Emission depends on filters which may have been added to the handler.
+        Wrap the actual emission of the record with acquisition/release of
+        the I/O thread lock. Returns whether the filter passed the record for
+        emission.
+        """
+
+        rv = self.filter(record)
+        if rv and record.levelno >= self.level:
+            self.acquire()
+            try:
+                self.emit(record)
+            finally:
+                self.release()
+        return rv

MuPythonLibrary/MuMarkdownHandler.py

@@ -66,6 +66,24 @@ def emit(self, record):
 
             # self.flush()
 
+    def handle(self, record):
+        """
+        Conditionally emit the specified logging record.
+        Emission depends on filters which may have been added to the handler.
+        Wrap the actual emission of the record with acquisition/release of
+        the I/O thread lock. Returns whether the filter passed the record for
+        emission.
+        """
+
+        rv = self.filter(record)
+        if rv and record.levelno >= self.level:
+            self.acquire()
+            try:
+                self.emit(record)
+            finally:
+                self.release()
+        return rv
+
     @staticmethod
     def __convert_to_markdownlink(text):
         # Using info from here https://stackoverflow.com/a/38507669

MuPythonLibrary/MuStringHandler.py

@@ -38,9 +38,23 @@ def __init__(self):
         logging.Handler.__init__(self)
         self.stream = StringIO()
 
-    # just returns the message indefinitely
-    def format(self, record):
-        return record.message
+    def handle(self, record):
+        """
+        Conditionally emit the specified logging record.
+        Emission depends on filters which may have been added to the handler.
+        Wrap the actual emission of the record with acquisition/release of
+        the I/O thread lock. Returns whether the filter passed the record for
+        emission.
+        """
+
+        rv = self.filter(record)
+        if rv and record.levelno >= self.level:
+            self.acquire()
+            try:
+                self.emit(record)
+            finally:
+                self.release()
+        return rv
 
     def readlines(self, hint=-1):
         return self.stream.readlines(hint)

MuPythonLibrary/Uefi/EdkII/PathUtilities.py

@@ -42,11 +42,12 @@ class Edk2Path(object):
     #
     def __init__(self, ws, packagepathlist):
         self.WorkspacePath = ws
+        self.logger = logging.getLogger("Edk2Path")
         if(not os.path.isabs(ws)):
             self.WorkspacePath = os.path.abspath(os.path.join(os.getcwd(), ws))
 
         if(not os.path.isdir(self.WorkspacePath)):
-            logging.error("Workspace path invalid.  {0}".format(ws))
+            self.logger.error("Workspace path invalid.  {0}".format(ws))
             raise Exception("Workspace path invalid.  {0}".format(ws))
 
         # Set PackagePath
@@ -66,7 +67,7 @@ def __init__(self, ws, packagepathlist):
         error = False
         for a in self.PackagePathList:
             if(not os.path.isdir(a)):
-                logging.error("Invalid package path entry {0}".format(a))
+                self.logger.error("Invalid package path entry {0}".format(a))
                 error = True
 
         # report error
@@ -84,8 +85,8 @@ def GetEdk2RelativePathFromAbsolutePath(self, abspath):
                 # found our path...now lets correct for case
                 relpath = abspath[len(a):]
                 found = True
-                logging.debug("Successfully converted AbsPath to Edk2Relative Path using PackagePath")
-                logging.debug("AbsolutePath: %s found in PackagePath: %s" % (abspath, a))
+                self.logger.debug("Successfully converted AbsPath to Edk2Relative Path using PackagePath")
+                self.logger.debug("AbsolutePath: %s found in PackagePath: %s" % (abspath, a))
                 break
 
         if(not found):
@@ -95,16 +96,16 @@ def GetEdk2RelativePathFromAbsolutePath(self, abspath):
                 # found our path...now lets correct for case
                 relpath = abspath[len(self.WorkspacePath):]
                 found = True
-                logging.debug("Successfully converted AbsPath to Edk2Relative Path using WorkspacePath")
-                logging.debug("AbsolutePath: %s found in Workspace: %s" % (abspath, self.WorkspacePath))
+                self.logger.debug("Successfully converted AbsPath to Edk2Relative Path using WorkspacePath")
+                self.logger.debug("AbsolutePath: %s found in Workspace: %s" % (abspath, self.WorkspacePath))
 
         if(found):
             relpath = relpath.replace(os.sep, "/")
             return relpath.lstrip("/")
 
         # didn't find the path for conversion.
-        logging.error("Failed to convert AbsPath to Edk2Relative Path")
-        logging.error("AbsolutePath: %s" % abspath)
+        self.logger.error("Failed to convert AbsPath to Edk2Relative Path")
+        self.logger.error("AbsolutePath: %s" % abspath)
         return None
 
     def GetAbsolutePathOnThisSytemFromEdk2RelativePath(self, relpath):
@@ -117,8 +118,8 @@ def GetAbsolutePathOnThisSytemFromEdk2RelativePath(self, relpath):
             abspath = os.path.join(a, relpath)
             if(os.path.exists(abspath)):
                 return abspath
-        logging.error("Failed to convert Edk2Relative Path to an Absolute Path on this system.")
-        logging.error("Relative Path: %s" % relpath)
+        self.logger.error("Failed to convert Edk2Relative Path to an Absolute Path on this system.")
+        self.logger.error("Relative Path: %s" % relpath)
 
         return None
 
@@ -130,7 +131,7 @@ def GetAbsolutePathOnThisSytemFromEdk2RelativePath(self, relpath):
     #
     # @ret Name of Package that the module is in.
     def GetContainingPackage(self, InputPath):
-        logging.debug("GetContainingPackage: %s" % InputPath)
+        self.logger.debug("GetContainingPackage: %s" % InputPath)
 
         dirpathprevious = os.path.dirname(InputPath)
         dirpath = os.path.dirname(InputPath)
@@ -141,15 +142,15 @@ def GetContainingPackage(self, InputPath):
             #
             if(dirpath in self.PackagePathList):
                 a = os.path.basename(dirpathprevious)
-                logging.debug("Reached Package Path.  Using previous directory: %s" % a)
+                self.logger.debug("Reached Package Path.  Using previous directory: %s" % a)
                 return a
             #
             # if at the root of the workspace return the previous dir.
             # this catches cases where a package has no DEC
             #
             if(dirpath == self.WorkspacePath):
                 a = os.path.basename(dirpathprevious)
-                logging.debug("Reached Workspace Path.  Using previous directory: %s" % a)
+                self.logger.debug("Reached Workspace Path.  Using previous directory: %s" % a)
                 return a
             #
             # Check for a DEC file in this folder
@@ -158,13 +159,13 @@ def GetContainingPackage(self, InputPath):
             for f in os.listdir(dirpath):
                 if fnmatch.fnmatch(f, '*.dec'):
                     a = os.path.basename(dirpath)
-                    logging.debug("Found DEC file at %s.  Pkg is: %s", dirpath, a)
+                    self.logger.debug("Found DEC file at %s.  Pkg is: %s", dirpath, a)
                     return a
 
             dirpathprevious = dirpath
             dirpath = os.path.dirname(dirpath)
 
-        logging.error("Failed to find containing package for %s" % InputPath)
-        logging.info("PackagePath is: %s" % os.pathsep.join(self.PackagePathList))
-        logging.info("Workspace path is : %s" % self.WorkspacePath)
+        self.logger.error("Failed to find containing package for %s" % InputPath)
+        self.logger.info("PackagePath is: %s" % os.pathsep.join(self.PackagePathList))
+        self.logger.info("Workspace path is : %s" % self.WorkspacePath)
         return None