Add ProcessorFormatter (#105)

Based on the work of @fabianbuechler, @insolite, and @if-fi.

Fixes #79, #9

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 <http://www.structlog.org/en/stable/standard-library.html>`_ 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 <http://www.structlog.org/en/stable/standard-library.html>`_ on how to use it!
+  This allows you to use ``logging``-based formatters to take care of rendering your entries.
   `#98 <https://github.com/hynek/structlog/issues/98>`_
+- Added ``structlog.stdlib.ProcessorFormatter`` which does the opposite:
+  This allows you to run ``structlog`` processors on arbitrary ``logging.LogRecords``.
+  `#79 <https://github.com/hynek/structlog/issues/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).

docs/api.rst

@@ -188,6 +188,9 @@ API Reference
 
 .. autoclass:: PositionalArgumentsFormatter
 
+.. autoclass:: ProcessorFormatter
+   :members: wrap_for_formatter
+
 
 :mod:`twisted` Module
 ---------------------

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``
 ^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^
 

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}}

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())