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

Doc/howto/logging-cookbook.rst

@@ -713,6 +713,41 @@ 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 in Handlers
+---------------------------------
+
+Each :class:`~Handler` has it's own chain of Filters.
+If you want to add contextual information to a :class:`LogRecord` without leaking
+this contextual information to other handlers, you can use a filter that returns
+a new :class:`~LogRecord` instead of modifying it in-place:
+
+script::
+
+ import logging
+
+ def filter(record: logging.LogRecord):
+ record = logging.LogRecord(
+ name=record.name,
+ level=record.levelno,
+ pathname=record.pathname,
+ lineno=record.lineno,
+ msg=record.msg,
+ exc_info=record.exc_info,
+ args=(),
+ )
+ 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

@@ -663,8 +663,9 @@ 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.
+ yes. Filters can also modify log records in-place or return a completely
+ different record instance which will replace the original
+ log record without modifying it.
 
 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 without modifying it in place. This allows filters installed
+ on 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,34 @@ 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 and the record is then dropped and
+ this method returns a falsy value.
+ Filters can return a log record, which case that log record
+ is used to call the next filter.
+ If filters return a truthy value that is not a log record the
+ next filter is called with the existing log record.
+
+ If none of the filters return falsy values, this method returns
+ a log record.
 
  .. 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 +979,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 +1655,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,65 @@ 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):
+ return logging.LogRecord(
+ name=record.name,
+ level=record.levelno,
+ pathname=record.pathname,
+ lineno=record.lineno,
+ msg="new message!",
+ exc_info=record.exc_info,
+ args=(),
+ )
+
+ # 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 logging.LogRecord(
+ name=record.name,
+ level=record.levelno,
+ pathname=record.pathname,
+ lineno=record.lineno,
+ msg=record.msg,
+ exc_info=record.exc_info,
+ args=(),
+ )
+
+ 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 @@
+Let :mod:`logging` Filters to return a :class:`logging.LogRecord` instance
+so that :class:`logging.Handler`\ s can enrich records without side effects on
+other Handlers.