gh-92592: Allow logging filters to return a LogRecord. (GH-92591)

Doc/howto/logging-cookbook.rst

@@ -713,6 +713,32 @@ which, when run, produces something like:
     2010-09-06 22:38:15,301 d.e.f DEBUG    IP: 123.231.231.123 User: fred     A message at DEBUG level with 2 parameters
     2010-09-06 22:38:15,301 d.e.f INFO     IP: 123.231.231.123 User: fred     A message at INFO level with 2 parameters
 
+Imparting contextual information in handlers
+--------------------------------------------
+
+Each :class:`~Handler` has its own chain of filters.
+If you want to add contextual information to a :class:`LogRecord` without leaking
+it to other handlers, you can use a filter that returns
+a new :class:`~LogRecord` instead of modifying it in-place, as shown in the following script::
+
+    import copy
+    import logging
+
+    def filter(record: logging.LogRecord):
+        record = copy.copy(record)
+        record.user = 'jim'
+        return record
+
+    if __name__ == '__main__':
+        logger = logging.getLogger()
+        logger.setLevel(logging.INFO)
+        handler = logging.StreamHandler()
+        formatter = logging.Formatter('%(message)s from %(user)-8s')
+        handler.setFormatter(formatter)
+        handler.addFilter(filter)
+        logger.addHandler(handler)
+
+        logger.info('A log message')
 
 .. _multiple-processes:
 

Doc/library/logging.rst

@@ -662,9 +662,10 @@ empty string, all events are passed.
 
    .. method:: filter(record)
 
-      Is the specified record to be logged? Returns zero for no, nonzero for
-      yes. If deemed appropriate, the record may be modified in-place by this
-      method.
+      Is the specified record to be logged? Returns falsy for no, truthy for
+      yes. Filters can either modify log records in-place or return a completely
+      different record instance which will replace the original
+      log record in any future processing of the event.
 
 Note that filters attached to handlers are consulted before an event is
 emitted by the handler, whereas filters attached to loggers are consulted
@@ -686,6 +687,12 @@ which has a ``filter`` method with the same semantics.
    parameter. The returned value should conform to that returned by
    :meth:`~Filter.filter`.
 
+.. versionchanged:: 3.12
+   You can now return a :class:`LogRecord` instance from filters to replace
+   the log record rather than modifying it in place. This allows filters attached to
+   a :class:`Handler` to modify the log record before it is emitted, without
+   having side effects on other handlers.
+
 Although filters are used primarily to filter records based on more
 sophisticated criteria than levels, they get to see every record which is
 processed by the handler or logger they're attached to: this can be useful if

Lib/logging/__init__.py

@@ -817,23 +817,36 @@ def filter(self, record):
         Determine if a record is loggable by consulting all the filters.
 
         The default is to allow the record to be logged; any filter can veto
-        this and the record is then dropped. Returns a zero value if a record
-        is to be dropped, else non-zero.
+        this by returning a falsy value.
+        If a filter attached to a handler returns a log record instance,
+        then that instance is used in place of the original log record in
+        any further processing of the event by that handler.
+        If a filter returns any other truthy value, the original log record
+        is used in any further processing of the event by that handler.
+
+        If none of the filters return falsy values, this method returns
+        a log record.
+        If any of the filters return a falsy value, this method returns
+        a falsy value.
 
         .. versionchanged:: 3.2
 
            Allow filters to be just callables.
+
+        .. versionchanged:: 3.12
+           Allow filters to return a LogRecord instead of
+           modifying it in place.
         """
-        rv = True
         for f in self.filters:
             if hasattr(f, 'filter'):
                 result = f.filter(record)
             else:
                 result = f(record) # assume callable - will raise if not
             if not result:
-                rv = False
-                break
-        return rv
+                return False
+            if isinstance(result, LogRecord):
+                record = result
+        return record
 
 #---------------------------------------------------------------------------
 #   Handler classes and functions
@@ -968,10 +981,14 @@ def handle(self, 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.
+        the I/O thread lock.
+
+        Returns an instance of the log record that was emitted
+        if it passed all filters, otherwise a falsy value is returned.
         """
         rv = self.filter(record)
+        if isinstance(rv, LogRecord):
+            record = rv
         if rv:
             self.acquire()
             try:
@@ -1640,8 +1657,14 @@ def handle(self, record):
         This method is used for unpickled records received from a socket, as
         well as those created locally. Logger-level filtering is applied.
         """
-        if (not self.disabled) and self.filter(record):
-            self.callHandlers(record)
+        if self.disabled:
+            return
+        maybe_record = self.filter(record)
+        if not maybe_record:
+            return
+        if isinstance(maybe_record, LogRecord):
+            record = maybe_record
+        self.callHandlers(record)
 
     def addHandler(self, hdlr):
         """

Lib/test/test_logging.py

@@ -467,6 +467,51 @@ def log_at_all_levels(self, logger):
         for lvl in LEVEL_RANGE:
             logger.log(lvl, self.next_message())
 
+    def test_handler_filter_replaces_record(self):
+        def replace_message(record: logging.LogRecord):
+            record = copy.copy(record)
+            record.msg = "new message!"
+            return record
+
+        # Set up a logging hierarchy such that "child" and it's handler
+        # (and thus `replace_message()`) always get called before
+        # propagating up to "parent".
+        # Then we can confirm that `replace_message()` was able to
+        # replace the log record without having a side effect on
+        # other loggers or handlers.
+        parent = logging.getLogger("parent")
+        child = logging.getLogger("parent.child")
+        stream_1 = io.StringIO()
+        stream_2 = io.StringIO()
+        handler_1 = logging.StreamHandler(stream_1)
+        handler_2 = logging.StreamHandler(stream_2)
+        handler_2.addFilter(replace_message)
+        parent.addHandler(handler_1)
+        child.addHandler(handler_2)
+
+        child.info("original message")
+        handler_1.flush()
+        handler_2.flush()
+        self.assertEqual(stream_1.getvalue(), "original message\n")
+        self.assertEqual(stream_2.getvalue(), "new message!\n")
+
+    def test_logging_filter_replaces_record(self):
+        records = set()
+
+        class RecordingFilter(logging.Filter):
+            def filter(self, record: logging.LogRecord):
+                records.add(id(record))
+                return copy.copy(record)
+
+        logger = logging.getLogger("logger")
+        logger.setLevel(logging.INFO)
+        logger.addFilter(RecordingFilter())
+        logger.addFilter(RecordingFilter())
+
+        logger.info("msg")
+
+        self.assertEqual(2, len(records))
+
     def test_logger_filter(self):
         # Filter at logger level.
         self.root_logger.setLevel(VERBOSE)

Misc/NEWS.d/next/Library/2022-05-09-22-27-11.gh-issue-92591.V7RCk2.rst

@@ -0,0 +1,3 @@
+Allow :mod:`logging` filters to return a :class:`logging.LogRecord` instance
+so that filters attached to :class:`logging.Handler`\ s can enrich records without
+side effects on other handlers.