diff --git a/Doc/howto/logging-cookbook.rst b/Doc/howto/logging-cookbook.rst index 704279240b357b..7e45d25ceb48ff 100644 --- a/Doc/howto/logging-cookbook.rst +++ b/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: diff --git a/Doc/library/logging.rst b/Doc/library/logging.rst index b82b90b47dd160..c148da08f57b17 100644 --- a/Doc/library/logging.rst +++ b/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 diff --git a/Lib/logging/__init__.py b/Lib/logging/__init__.py index 79e4b7d09bfa43..af42a4477e734f 100644 --- a/Lib/logging/__init__.py +++ b/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): """ diff --git a/Lib/test/test_logging.py b/Lib/test/test_logging.py index e69afae484aa77..46cf55c20339e9 100644 --- a/Lib/test/test_logging.py +++ b/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) diff --git a/Misc/NEWS.d/next/Library/2022-05-09-22-27-11.gh-issue-92591.V7RCk2.rst b/Misc/NEWS.d/next/Library/2022-05-09-22-27-11.gh-issue-92591.V7RCk2.rst new file mode 100644 index 00000000000000..cd9b598d1dbca1 --- /dev/null +++ b/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.