From 065b69aaba436ec704c4b19eef733af78043e3f1 Mon Sep 17 00:00:00 2001 From: Hynek Schlawack Date: Mon, 24 Apr 2017 12:13:54 +0200 Subject: [PATCH] Add ProcessorFormatter (#105) Based on the work of @fabianbuechler, @insolite, and @if-fi. Fixes #79, #9 --- CHANGELOG.rst | 11 +++- docs/api.rst | 3 + docs/standard-library.rst | 100 ++++++++++++++++++++++++++++++- src/structlog/stdlib.py | 73 +++++++++++++++++++++++ tests/test_base.py | 10 +++- tests/test_stdlib.py | 122 +++++++++++++++++++++++++++++++++++++- 6 files changed, 308 insertions(+), 11 deletions(-) diff --git a/CHANGELOG.rst b/CHANGELOG.rst index 96ad21d6..de3caade 100644 --- a/CHANGELOG.rst +++ b/CHANGELOG.rst @@ -8,6 +8,10 @@ The third digit is only for regressions. 17.1.0 (UNRELEASED) ------------------- +The main features of this release are multiple improvements in standard library's ``logging`` integration. +Have a look at the updated `standard library chapter `_ on how to use them! + + Backward-incompatible changes: ^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^ @@ -20,10 +24,11 @@ Changes: ^^^^^^^^ - Added ``structlog.stdlib.render_to_log_kwargs()``. - This allows to let standard library's ``logging`` do all formatting. - It gives you much more consistently formatted logs if you have mixed ``structlog`` and ``logging`` output. - Have a look at the updated `standard library chapter `_ on how to use it! + This allows you to use ``logging``-based formatters to take care of rendering your entries. `#98 `_ +- Added ``structlog.stdlib.ProcessorFormatter`` which does the opposite: + This allows you to run ``structlog`` processors on arbitrary ``logging.LogRecords``. + `#79 `_ - UNIX epoch timestamps from ``structlog.processors.TimeStamper`` are more precise now. - Add *repr_native_str* to ``structlog.processors.KeyValueRenderer`` and ``structlog.dev.ConsoleRenderer``. This allows for human-readable non-ASCII output on Python 2 (``repr()`` on Python 2 haves like ``ascii()`` on Python 3 in that regard). diff --git a/docs/api.rst b/docs/api.rst index c64dc11c..b8f3cba7 100644 --- a/docs/api.rst +++ b/docs/api.rst @@ -188,6 +188,9 @@ API Reference .. autoclass:: PositionalArgumentsFormatter +.. autoclass:: ProcessorFormatter + :members: wrap_for_formatter + :mod:`twisted` Module --------------------- diff --git a/docs/standard-library.rst b/docs/standard-library.rst index 3a08eb81..7925c731 100644 --- a/docs/standard-library.rst +++ b/docs/standard-library.rst @@ -43,16 +43,19 @@ Processors This processes and formats positional arguments (if any) passed to log methods in the same way the ``logging`` module would do, e.g. ``logger.info("Hello, %s", name)``. +``structlog`` also comes with :class:`~structlog.stdlib.ProcessorFormatter` which is a :class:`logging.Formatter` that enables you to format non-``structlog`` log entries using ``structlog`` renderers *and* multiplex ``structlog``’s output with different renderers (see below for an example). + + .. _stdlib-config: Suggested Configurations ------------------------ -Depending where you'd like to do your formatting, you can take one of two approaches: +Depending *where* you'd like to do your formatting, you can take one of three approaches: -Rendering Within :mod:`logging` -^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^ +Rendering Using :mod:`logging`-based Formatters +^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^ .. code-block:: python @@ -101,6 +104,97 @@ Now both ``structlog`` and ``logging`` will emit JSON logs: {"message": "hello"} +Rendering Using ``structlog``-based Formatters Within :mod:`logging` +^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^ + +You can leave rendering for later and yet use ``structlog``’s renderers for it: + +.. code-block:: python + + import logging.config + import structlog + + timestamper = structlog.processors.TimeStamper(fmt="%Y-%m-%d %H:%M:%S") + pre_chain = [ + # Add the log level and a timestamp to the event_dict if the log entry + # is not from structlog. + structlog.stdlib.add_log_level, + timestamper, + ] + + logging.config.dictConfig({ + "version": 1, + "disable_existing_loggers": False, + "formatters": { + "plain": { + "()": structlog.stdlib.ProcessorFormatter, + "processor": structlog.dev.ConsoleRenderer(colors=False), + "foreign_pre_chain": pre_chain, + }, + "colored": { + "()": structlog.stdlib.ProcessorFormatter, + "processor": structlog.dev.ConsoleRenderer(colors=True), + "foreign_pre_chain": pre_chain, + }, + }, + "handlers": { + "default": { + "level": "DEBUG", + "class": "logging.StreamHandler", + "formatter": "colored", + }, + "file": { + "level": "DEBUG", + "class": "logging.handlers.WatchedFileHandler", + "filename": "test.log", + "formatter": "plain", + }, + }, + "loggers": { + "": { + "handlers": ["default", "file"], + "level": "DEBUG", + "propagate": True, + }, + } + }) + structlog.configure( + processors=[ + structlog.stdlib.add_log_level, + structlog.stdlib.PositionalArgumentsFormatter(), + timestamper, + structlog.processors.StackInfoRenderer(), + structlog.processors.format_exc_info, + structlog.stdlib.ProcessorFormatter.wrap_for_formatter, + ], + context_class=dict, + logger_factory=structlog.stdlib.LoggerFactory(), + wrapper_class=structlog.stdlib.BoundLogger, + cache_logger_on_first_use=True, + ) + +This defines two formatters: one plain and one colored. +Both are run for each log entry. +Log entries that do not originate from ``structlog``, are additionally pre-processed using a cached ``timestamper`` and :func:`~structlog.stdlib.add_log_level`. + +.. code-block:: pycon + + >>> logging.getLogger().warning("bar") + 2017-03-06 11:49:27 [warning ] bar + + >>> structlog.get_logger("structlog").warning("foo", x=42) + 2017-03-06 11:49:32 [warning ] foo x=42 + + >>> print(open("test.log").read()) + 2017-03-06 11:49:27 [warning ] bar + 2017-03-06 11:49:32 [warning ] foo x=42 + +(sadly, you have to imagine the colors in the first two outputs) + +If you leave ``foreign_pre_chain`` `None`, formatting will be left to :mod:`logging`. +Meaning: you can define a ``format`` for :class:`~structlog.stdlib.ProcessorFormatter` too! + + Rendering Within ``structlog`` ^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^ diff --git a/src/structlog/stdlib.py b/src/structlog/stdlib.py index 281137e3..3dec78dd 100644 --- a/src/structlog/stdlib.py +++ b/src/structlog/stdlib.py @@ -365,3 +365,76 @@ def render_to_log_kwargs(wrapped_logger, method_name, event_dict): "msg": event_dict.pop("event"), "extra": event_dict, } + + +class ProcessorFormatter(logging.Formatter): + """ + Call ``structlog`` processors on :mod:`logging.LogRecord`\ s. + + This :class:`logging.Formatter` allows to configure :mod:`logging` to call + *processor* on ``structlog``-borne log entries (origin is determined solely + on the fact whether the ``msg`` field on the :class:`logging.LogRecord` is + a dict or not). + + This allows for two interesting use cases: + + #. You can format non-``structlog`` log entries. + #. You can multiplex log records into multiple :class:`logging.Handler`\ s. + + Please refer to :doc:`standard-library` for examples. + + :param callable processor: A ``structlog`` processor. + :param foreign_pre_chain: + If not `None`, it is used as an iterable of processors that is applied + to non-``structlog`` log entries before *processor*. If `None`, + formatting is left to :mod:`logging`. (default: `None`) + + :rtype: str + + .. versionadded:: 17.1.0 + """ + def __init__(self, processor, foreign_pre_chain=None, *args, **kwargs): + fmt = kwargs.pop("fmt", "%(message)s") + super(ProcessorFormatter, self).__init__(*args, fmt=fmt, **kwargs) + self.processor = processor + self.foreign_pre_chain = foreign_pre_chain + + def format(self, record): + """ + Extract ``structlog``'s `event_dict` from ``record.msg`` and format it. + """ + if isinstance(record.msg, dict): + # Both attached by wrap_for_formatter + logger = record._logger + meth_name = record._name + + # We need to copy because it's possible that the same record gets + # processed by multiple logging formatters. LogRecord.getMessage + # would transform our dict into a str. + ed = record.msg.copy() + else: + logger = None + meth_name = record.levelname.lower() + ed = {"event": record.getMessage()} + + # Non-structlog allows to run through a chain to prepare it for the + # final processor (e.g. adding timestamps and log levels). + for proc in self.foreign_pre_chain or (): + ed = proc(None, meth_name, ed) + + record.msg = self.processor(logger, meth_name, ed) + return super(ProcessorFormatter, self).format(record) + + @staticmethod + def wrap_for_formatter(logger, name, event_dict): + """ + Wrap *logger*, *name*, and *event_dict*. + + The result is later unpacked by :class:`ProcessorFormatter` when + formatting log entries. + + Use this static method as the renderer (i.e. final processor) if you + want to use :class:`ProcessorFormatter` in your :mod:`logging` + configuration. + """ + return (event_dict,), {"extra": {"_logger": logger, "_name": name}} diff --git a/tests/test_base.py b/tests/test_base.py index d51ff557..cde18cf0 100644 --- a/tests/test_base.py +++ b/tests/test_base.py @@ -119,7 +119,7 @@ def test_last_processor_returns_tuple(self): def test_last_processor_returns_dict(self): """ - If the final processor returns a dict, ``(), the_dict`` is returnend. + If the final processor returns a dict, ``(), the_dict`` is returned. """ logger = stub(msg=lambda *args, **kw: (args, kw)) b = build_bl(logger, processors=[lambda *_: {'event': 'foo'}]) @@ -145,6 +145,10 @@ def test_last_processor_returns_unknown_value(self): class TestProxying(object): def test_processor_raising_DropEvent_silently_aborts_chain(self, capsys): + """ + If a processor raises DropEvent, the chain is aborted and nothing is + proxied to the logger. + """ b = build_bl(processors=[raiser(DropEvent), raiser(ValueError)]) - b._proxy_to_logger('', None, x=5) - assert (('', '') == capsys.readouterr()) + b._proxy_to_logger("", None, x=5) + assert (("", "") == capsys.readouterr()) diff --git a/tests/test_stdlib.py b/tests/test_stdlib.py index 7ed84015..2d901cce 100644 --- a/tests/test_stdlib.py +++ b/tests/test_stdlib.py @@ -7,23 +7,27 @@ import os import logging +import logging.config import pytest + from pretend import call_recorder -from structlog._loggers import ReturnLogger +from structlog import reset_defaults, configure, ReturnLogger, get_logger +from structlog.dev import ConsoleRenderer from structlog.exceptions import DropEvent from structlog.stdlib import ( BoundLogger, CRITICAL, LoggerFactory, PositionalArgumentsFormatter, + ProcessorFormatter, WARN, _FixedFindCallerLogger, add_log_level, add_logger_name, - render_to_log_kwargs, filter_by_level, + render_to_log_kwargs, ) from .additional_frame import additional_frame @@ -307,3 +311,117 @@ def test_add_extra_event_dict(self, event_dict): d = render_to_log_kwargs(None, None, event_dict) assert {"msg": "message", "extra": event_dict} == d + + +@pytest.fixture +def configure_for_pf(): + """ + Configure structlog to use ProcessorFormatter. + + Reset both structlog and logging setting after the test. + """ + configure( + processors=[ + add_log_level, + ProcessorFormatter.wrap_for_formatter, + ], + logger_factory=LoggerFactory(), + wrapper_class=BoundLogger, + ) + + yield + + logging.basicConfig() + reset_defaults() + + +def configure_logging(pre_chain): + """ + Configure logging to use ProcessorFormatter. + """ + return logging.config.dictConfig({ + "version": 1, + "disable_existing_loggers": False, + "formatters": { + "plain": { + "()": ProcessorFormatter, + "processor": ConsoleRenderer(colors=False), + "foreign_pre_chain": pre_chain, + "format": "%(message)s [in %(funcName)s]" + } + }, + "handlers": { + "default": { + "level": "DEBUG", + "class": "logging.StreamHandler", + "formatter": "plain", + }, + }, + "loggers": { + "": { + "handlers": ["default"], + "level": "DEBUG", + "propagate": True, + }, + } + }) + + +class TestProcessorFormatter(object): + """ + These are all integration tests because they're all about integration. + """ + def test_foreign_delegate(self, configure_for_pf, capsys): + """ + If foreign_pre_chain is None, non-structlog log entries are delegated + to logging. + """ + configure_logging(None) + configure( + processors=[ + ProcessorFormatter.wrap_for_formatter, + ], + logger_factory=LoggerFactory(), + wrapper_class=BoundLogger, + ) + + logging.getLogger().warning("foo") + + assert ( + "", + "foo [in test_foreign_delegate]\n", + ) == capsys.readouterr() + + def test_foreign_pre_chain(self, configure_for_pf, capsys): + """ + If foreign_pre_chain is an iterable, it's used to pre-process + non-structlog log entries. + """ + configure_logging((add_log_level,)) + configure( + processors=[ + ProcessorFormatter.wrap_for_formatter, + ], + logger_factory=LoggerFactory(), + wrapper_class=BoundLogger, + ) + + logging.getLogger().warning("foo") + + assert ( + "", + "[warning ] foo [in test_foreign_pre_chain]\n", + ) == capsys.readouterr() + + def test_native(self, configure_for_pf, capsys): + """ + If the log entry comes from structlog, it's unpackaged and processed. + """ + configure_logging(None) + + get_logger().warning("foo") + + assert ( + "", + "[warning ] foo [in test_native]\n", + ) == capsys.readouterr()