From 965201b2b9396980276fcb71dc3ca33be6adb823 Mon Sep 17 00:00:00 2001 From: Denis Savran Date: Thu, 7 Nov 2024 17:42:50 +0300 Subject: [PATCH] Add 'structlog.stdlib.render_to_log_args_and_kwargs' processor --- CHANGELOG.md | 7 ++ docs/api.rst | 4 +- docs/standard-library.md | 21 +++-- src/structlog/stdlib.py | 46 +++++++++-- tests/test_stdlib.py | 167 ++++++++++++++++++++++++++++++++++++++- tests/typing/api.py | 8 ++ 6 files changed, 238 insertions(+), 15 deletions(-) diff --git a/CHANGELOG.md b/CHANGELOG.md index 9267b458..365585e0 100644 --- a/CHANGELOG.md +++ b/CHANGELOG.md @@ -15,6 +15,13 @@ You can find our backwards-compatibility policy [here](https://github.com/hynek/ ## [Unreleased](https://github.com/hynek/structlog/compare/24.4.0...HEAD) +### Added + +- Add `structlog.stdlib.render_to_log_args_and_kwargs` processor. + Same as `structlog.stdlib.render_to_log_kwargs`, but also allows to pass positional arguments to `logging`. + With it, you do not need to add `structlog.stdlib.PositionalArgumentsFormatter` processor to format positional arguments from *structlog* loggers. + [#668](https://github.com/hynek/structlog/pull/668) + ## Changed - `structlog.typing.BindableLogger` protocol now returns `Self` instead of `BindableLogger`. diff --git a/docs/api.rst b/docs/api.rst index 6879f1e0..9eaf1fcc 100644 --- a/docs/api.rst +++ b/docs/api.rst @@ -303,6 +303,8 @@ API Reference .. autoclass:: LoggerFactory :members: __call__ +.. autofunction:: render_to_log_args_and_kwargs + .. autofunction:: render_to_log_kwargs .. autofunction:: filter_by_level @@ -313,7 +315,7 @@ API Reference .. autofunction:: add_logger_name -.. autofunction:: ExtraAdder +.. autoclass:: ExtraAdder .. autoclass:: PositionalArgumentsFormatter diff --git a/docs/standard-library.md b/docs/standard-library.md index 3b307541..410d00da 100644 --- a/docs/standard-library.md +++ b/docs/standard-library.md @@ -77,11 +77,16 @@ To use it, {doc}`configure ` *structlog* to use `AsyncBoundLogger *structlog* comes with a few standard library-specific processors: -{func}`~structlog.stdlib.render_to_log_kwargs`: +{func}`~structlog.stdlib.render_to_log_args_and_kwargs`: -: Renders the event dictionary into keyword arguments for `logging.log` that attaches everything except the `event` field to the *extra* argument. +: Renders the event dictionary into positional and keyword arguments for `logging.Logger` logging methods. This is useful if you want to render your log entries entirely within `logging`. +{func}`~structlog.stdlib.render_to_log_kwargs`: + +: Same as above, but does not support passing positional arguments from *structlog* loggers to `logging.Logger` logging methods as positional arguments. + *structlog* positional arguments are still passed to `logging` under `positional_args` key of `extra` keyword argument. + {func}`~structlog.stdlib.filter_by_level`: : Checks the log entry's log level against the configuration of standard library's logging. @@ -92,12 +97,6 @@ To use it, {doc}`configure ` *structlog* to use `AsyncBoundLogger : Adds the name of the logger to the event dictionary under the key `logger`. -{func}`~structlog.stdlib.ExtraAdder`: - -: Add extra attributes of `logging.LogRecord` objects to the event dictionary. - - This processor can be used for adding data passed in the `extra` parameter of the `logging` module's log methods to the event dictionary. - {func}`~structlog.stdlib.add_log_level`: : Adds the log level to the event dictionary under the key `level`. @@ -117,6 +116,12 @@ To use it, {doc}`configure ` *structlog* to use `AsyncBoundLogger The mapping of names to numbers is in `structlog.stdlib._NAME_TO_LEVEL`. +{func}`~structlog.stdlib.ExtraAdder`: + +: Add extra attributes of `logging.LogRecord` objects to the event dictionary. + +This processor can be used for adding data passed in the `extra` parameter of the `logging` module's log methods to the event dictionary. + {func}`~structlog.stdlib.PositionalArgumentsFormatter`: : This processes and formats positional arguments (if any) passed to log methods in the same way the `logging` module would do, for example, `logger.info("Hello, %s", name)`. diff --git a/src/structlog/stdlib.py b/src/structlog/stdlib.py index 166578be..239b8c0e 100644 --- a/src/structlog/stdlib.py +++ b/src/structlog/stdlib.py @@ -50,6 +50,7 @@ "PositionalArgumentsFormatter", "ProcessorFormatter", "recreate_defaults", + "render_to_log_args_and_kwargs", "render_to_log_kwargs", ] @@ -885,15 +886,50 @@ def _copy_allowed( event_dict[key] = record.__dict__[key] +LOG_KWARG_NAMES = ("exc_info", "stack_info", "stacklevel") + + +def render_to_log_args_and_kwargs( + _: logging.Logger, __: str, event_dict: EventDict +) -> tuple[tuple[Any, ...], dict[str, Any]]: + """ + Render ``event_dict`` into positional and keyword arguments for + `logging.Logger` logging methods. + See `logging.Logger.debug` method for keyword arguments reference. + + The ``event`` field is passed in the first positional argument, positional + arguments from ``positional_args`` field are passed in subsequent positional + arguments, keyword arguments are extracted from the *event_dict* and the + rest of the *event_dict* is added as ``extra``. + + This allows you to defer formatting to `logging`. + + .. versionadded:: 24.4.0 + """ + args = (event_dict.pop("event"), *event_dict.pop("positional_args", ())) + + kwargs = { + kwarg_name: event_dict.pop(kwarg_name) + for kwarg_name in LOG_KWARG_NAMES + if kwarg_name in event_dict + } + if event_dict: + kwargs["extra"] = event_dict + + return args, kwargs + + def render_to_log_kwargs( _: logging.Logger, __: str, event_dict: EventDict ) -> EventDict: """ - Render ``event_dict`` into keyword arguments for `logging.log`. - See `logging.Logger`'s ``_log`` method for kwargs reference. + Render ``event_dict`` into keyword arguments for `logging.Logger` logging + methods. + See `logging.Logger.debug` method for keyword arguments reference. - The ``event`` field is translated into ``msg`` and the rest of the - *event_dict* is added as ``extra``. + The ``event`` field is translated into ``msg``, keyword arguments are + extracted from the *event_dict* and the rest of the *event_dict* is added as + ``extra``. This allows you to defer formatting to `logging`. @@ -909,7 +945,7 @@ def render_to_log_kwargs( "extra": event_dict, **{ kw: event_dict.pop(kw) - for kw in ("exc_info", "stack_info", "stacklevel") + for kw in LOG_KWARG_NAMES if kw in event_dict }, } diff --git a/tests/test_stdlib.py b/tests/test_stdlib.py index 9bba39f9..383e60dd 100644 --- a/tests/test_stdlib.py +++ b/tests/test_stdlib.py @@ -46,6 +46,7 @@ filter_by_level, get_logger, recreate_defaults, + render_to_log_args_and_kwargs, render_to_log_kwargs, ) from structlog.testing import CapturedCall @@ -706,7 +707,171 @@ def _stdlib_logger(): logging.basicConfig() -class TestRenderToLogKW: +class TestRenderToLogArgsAndKwargs: + def test_default(self, stdlib_logger: logging.Logger): + """ + Passes `event` key from `event_dict` in the first positional argument + and handles otherwise empty `event_dict`. + """ + method_name = "debug" + event = "message" + args, kwargs = render_to_log_args_and_kwargs( + stdlib_logger, method_name, {"event": event} + ) + + assert (event,) == args + assert {} == kwargs + + with patch.object(stdlib_logger, "_log") as mock_log: + getattr(stdlib_logger, method_name)(*args, **kwargs) + + mock_log.assert_called_once_with(logging.DEBUG, event, ()) + + def test_pass_remaining_event_dict_as_extra( + self, stdlib_logger: logging.Logger, event_dict: dict[str, Any] + ): + """ + Passes remaining `event_dict` as `extra`. + """ + expected_extra = event_dict.copy() + + method_name = "info" + event = "message" + event_dict["event"] = event + + args, kwargs = render_to_log_args_and_kwargs( + stdlib_logger, method_name, event_dict + ) + + assert (event,) == args + assert {"extra": expected_extra} == kwargs + + with patch.object(stdlib_logger, "_log") as mock_log: + getattr(stdlib_logger, method_name)(*args, **kwargs) + + mock_log.assert_called_once_with( + logging.INFO, event, (), extra=expected_extra + ) + + def test_pass_positional_args_from_event_dict_as_args( + self, stdlib_logger: logging.Logger, event_dict: dict[str, Any] + ): + """ + Passes items from "positional_args" key from `event_dict` as positional + arguments. + """ + expected_extra = event_dict.copy() + + method_name = "warning" + event = "message: a = %s, b = %d" + positional_args = ("foo", 123) + event_dict["event"] = event + event_dict["positional_args"] = positional_args + + args, kwargs = render_to_log_args_and_kwargs( + stdlib_logger, method_name, event_dict + ) + + assert (event, *(positional_args)) == args + assert {"extra": expected_extra} == kwargs + + with patch.object(stdlib_logger, "_log") as mock_log: + getattr(stdlib_logger, method_name)(*args, **kwargs) + + mock_log.assert_called_once_with( + logging.WARNING, event, positional_args, extra=expected_extra + ) + + def test_pass_kwargs_from_event_dict_as_kwargs( + self, stdlib_logger: logging.Logger, event_dict: dict[str, Any] + ): + """ + Passes "exc_info", "stack_info", and "stacklevel" keys from `event_dict` + as keyword arguments. + """ + expected_extra = event_dict.copy() + + method_name = "info" + event = "message" + exc_info = True + stack_info = False + stacklevel = 2 + event_dict["event"] = event + event_dict["exc_info"] = exc_info + event_dict["stack_info"] = stack_info + event_dict["stacklevel"] = stacklevel + + args, kwargs = render_to_log_args_and_kwargs( + stdlib_logger, method_name, event_dict + ) + + assert (event,) == args + assert { + "exc_info": exc_info, + "stack_info": stack_info, + "stacklevel": stacklevel, + "extra": expected_extra, + } == kwargs + + with patch.object(stdlib_logger, "_log") as mock_log: + getattr(stdlib_logger, method_name)(*args, **kwargs) + + mock_log.assert_called_once_with( + logging.INFO, + event, + (), + exc_info=exc_info, + stack_info=stack_info, + stacklevel=stacklevel, + extra=expected_extra, + ) + + def test_integration( + self, stdlib_logger: logging.Logger, event_dict: dict[str, Any] + ): + """ + `render_to_log_args_and_kwargs` with a wrapped logger calls the stdlib + logger correctly. + + Reserved stdlib keyword arguments are in `logging.Logger._log`. + https://github.com/python/cpython/blob/60403a5409ff2c3f3b07dd2ca91a7a3e096839c7/Lib/logging/__init__.py#L1640 + """ + event = "message: a = %s, b = %d" + arg_1 = "foo" + arg_2 = 123 + exc_info = False + stack_info = True + stacklevel = 3 + + struct_logger = wrap_logger( + stdlib_logger, + processors=[render_to_log_args_and_kwargs], + wrapper_class=BoundLogger, + ) + + with patch.object(stdlib_logger, "_log") as mock_log: + struct_logger.info( + event, + arg_1, + arg_2, + exc_info=exc_info, + stack_info=stack_info, + stacklevel=stacklevel, + **event_dict, + ) + + mock_log.assert_called_once_with( + logging.INFO, + event, + (arg_1, arg_2), + exc_info=exc_info, + stack_info=stack_info, + stacklevel=stacklevel, + extra=event_dict, + ) + + +class TestRenderToLogKwargs: def test_default(self, stdlib_logger): """ Translates `event` to `msg` and handles otherwise empty `event_dict`s. diff --git a/tests/typing/api.py b/tests/typing/api.py index d4e1afe6..dd93350d 100644 --- a/tests/typing/api.py +++ b/tests/typing/api.py @@ -43,6 +43,14 @@ def bytes_dumps( processors=[structlog.processors.JSONRenderer(serializer=bytes_dumps)] ) +structlog.configure( + processors=[ + structlog.stdlib.render_to_log_args_and_kwargs, + ], + logger_factory=structlog.stdlib.LoggerFactory(), + wrapper_class=structlog.stdlib.BoundLogger, + cache_logger_on_first_use=True, +) structlog.configure( processors=[