Start the async revolution

CHANGELOG.rst

@@ -26,7 +26,8 @@ Deprecations:
 Changes:
 ^^^^^^^^
 
-*none*
+- Added ``structlog.stdlib.AsyncBoundLogger`` that executes logging calls in a thread executor and therefore doesn't block.
+  `#245 <https://github.com/hynek/structlog/pull/245>`_
 
 
 ----

docs/api.rst

@@ -209,6 +209,9 @@ API Reference
 .. autoclass:: BoundLogger
    :members: bind, unbind, new, debug, info, warning, warn, error, critical, exception, log
 
+.. autoclass:: AsyncBoundLogger
+   :members: bind, unbind, new, debug, info, warning, warn, error, critical, exception, log
+
 .. autoclass:: LoggerFactory
    :members: __call__
 

setup.py

@@ -37,7 +37,7 @@
         "freezegun>=0.2.8",
         "pretend",
         "pytest>=3.3.0",
-        "pytest-asyncio; python_version>='3.7'",
+        "pytest-asyncio",
         "python-rapidjson",
         "simplejson",
     ],

src/structlog/stdlib.py

@@ -9,8 +9,11 @@
 See also :doc:`structlog's standard library support <standard-library>`.
 """
 
+import asyncio
 import logging
 
+from functools import partial
+
 from structlog._base import BoundLoggerBase
 from structlog._frames import _find_first_app_frame_and_name, _format_stack
 from structlog.exceptions import DropEvent
@@ -236,6 +239,75 @@ def getChild(self, suffix):
         return self._logger.getChild(suffix)
 
 
+class AsyncBoundLogger:
+    """
+    Wraps a `BoundLogger` and runs its logging methods asynchronously in
+    a thread executor.
+
+    Only available for Python 3.7 and later.
+    """
+
+    __slots__ = ["sync_bl", "_loop"]
+
+    executor = None
+    bound_logger_factory = BoundLogger
+
+    def __init__(self, *args, **kw):
+        self.sync_bl = self.bound_logger_factory(*args, **kw)
+        self._loop = asyncio.get_running_loop()
+
+    def bind(self, **new_values) -> "AsyncBoundLogger":
+        self.sync_bl = self.sync_bl.bind(**new_values)
+        return self
+
+    def new(self, **new_values) -> "AsyncBoundLogger":
+        self.sync_bl = self.sync_bl.new(**new_values)
+        return self
+
+    def unbind(self, *keys) -> "AsyncBoundLogger":
+        self.sync_bl = self.sync_bl.try_unbind(*keys)
+        return self
+
+    async def debug(self, event, *args, **kw):
+        return await self._loop.run_in_executor(
+            self.executor, partial(self.sync_bl.debug, event, *args, **kw)
+        )
+
+    async def info(self, event, *args, **kw):
+        return await self._loop.run_in_executor(
+            self.executor, partial(self.sync_bl.info, event, *args, **kw)
+        )
+
+    async def warning(self, event, *args, **kw):
+        return await self._loop.run_in_executor(
+            self.executor, partial(self.sync_bl.warning, event, *args, **kw)
+        )
+
+    warn = warning
+
+    async def error(self, event, *args, **kw):
+        return await self._loop.run_in_executor(
+            self.executor, partial(self.sync_bl.error, event, *args, **kw)
+        )
+
+    async def critical(self, event, *args, **kw):
+        return await self._loop.run_in_executor(
+            self.executor, partial(self.sync_bl.critical, event, *args, **kw)
+        )
+
+    fatal = critical
+
+    async def exception(self, event, *args, **kw):
+        return await self._loop.run_in_executor(
+            self.executor, partial(self.sync_bl.exception, event, *args, **kw)
+        )
+
+    async def log(self, level, event, *args, **kw):
+        return await self._loop.run_in_executor(
+            self.executor, partial(self.sync_bl.log, level, event, *args, **kw)
+        )
+
+
 class LoggerFactory:
     """
     Build a standard library logger when an *instance* is called.

tests/test_stdlib.py

@@ -4,22 +4,31 @@
 
 
 import collections
+import json
 import logging
 import logging.config
 import os
+import sys
 
 import pytest
 
 from pretend import call_recorder
 
-from structlog import ReturnLogger, configure, get_logger, reset_defaults
+from structlog import (
+    PrintLogger,
+    ReturnLogger,
+    configure,
+    get_logger,
+    reset_defaults,
+)
 from structlog.dev import ConsoleRenderer
 from structlog.exceptions import DropEvent
 from structlog.processors import JSONRenderer
 from structlog.stdlib import (
     _NAME_TO_LEVEL,
     CRITICAL,
     WARN,
+    AsyncBoundLogger,
     BoundLogger,
     LoggerFactory,
     PositionalArgumentsFormatter,
@@ -770,3 +779,97 @@ def test_foreign_pre_chain_filter_by_level(self, configure_for_pf, capsys):
             "",
             "foo [in test_foreign_pre_chain_filter_by_level]\n",
         ) == capsys.readouterr()
+
+
+@pytest.mark.skipif(
+    sys.version_info[:2] < (3, 7),
+    reason="AsyncBoundLogger is only for Python 3.7 and later.",
+)
+class TestAsyncBoundLogger:
+    @pytest.mark.parametrize(
+        "level_name",
+        ["debug", "info", "warning", "error", "critical", "exception"],
+    )
+    @pytest.mark.asyncio
+    async def test_correct_levels(self, level_name):
+        """
+        The proxy methods call the correct upstream methods.
+        """
+        _, ed = await getattr(
+            AsyncBoundLogger(
+                ReturnLogger(), context={}, processors=[add_log_level]
+            ).bind(foo="bar"),
+            level_name,
+        )("42")
+
+        if level_name == "exception":
+            expect = "error"
+        else:
+            expect = level_name
+
+        assert expect == ed["level"]
+
+    @pytest.mark.asyncio
+    async def test_log_method(self):
+        """
+        The `log` method is proxied too.
+        """
+        _, ed = (
+            await AsyncBoundLogger(
+                ReturnLogger(), context={}, processors=[add_log_level]
+            )
+            .bind(foo="bar")
+            .log(logging.ERROR, "42")
+        )
+
+        assert "error" == ed["level"]
+
+    @pytest.mark.asyncio
+    async def test_bind_unbind(self):
+        """
+        new/bind/unbind are correctly propagated.
+
+        Unbind is actually try_unbind and therefore ignores extra keys.
+        """
+        l1 = AsyncBoundLogger(ReturnLogger(), context={}, processors=[])
+
+        l2 = l1.bind(x=42)
+
+        assert {"x": 42} == l1.sync_bl._context
+
+        l3 = l2.new(y=23)
+
+        assert {"y": 23} == l1.sync_bl._context
+
+        # N.B. x isn't bound anymore.
+        l4 = l3.unbind("x", "y")
+
+        assert {} == l1.sync_bl._context
+
+        assert l1 is l2 is l3 is l4
+
+    @pytest.mark.asyncio
+    async def test_integration(self, capsys):
+        """
+        Configure and log an actual entry.
+        """
+
+        configure(
+            processors=[add_log_level, JSONRenderer()],
+            logger_factory=PrintLogger,
+            wrapper_class=AsyncBoundLogger,
+            cache_logger_on_first_use=True,
+        )
+
+        logger = get_logger()
+
+        await logger.bind(foo="bar").info("baz", x="42")
+
+        assert {
+            "foo": "bar",
+            "x": "42",
+            "event": "baz",
+            "level": "info",
+        } == json.loads(capsys.readouterr().out)
+
+        reset_defaults()