Add async log variants to structlog.stdlib.BoundLogger (#502)

CHANGELOG.md

@@ -15,6 +15,11 @@ You can find out backwards-compatibility policy [here](https://github.com/hynek/
 
 ## [Unreleased](https://github.com/hynek/structlog/compare/22.3.0...HEAD)
 
+### Added
+
+- `structlog.stdlib.BoundLogger` now has, analogously to our native logger, a full set of async log methods prefixed with an `a`: `await log.ainfo("event!")`
+
+
 ### Fixed
 
 - ConsoleRenderer now reuses the `_figure_out_exc_info` to process the `exc_info` argument like `ExceptionRenderer` does.

docs/api.rst

@@ -277,7 +277,7 @@ API Reference
 .. autofunction:: get_logger
 
 .. autoclass:: BoundLogger
-   :members: bind, unbind, try_unbind, new, debug, info, warning, warn, error, critical, exception, log
+   :members: bind, unbind, try_unbind, new, debug, info, warning, warn, error, critical, exception, log, adebug, ainfo, awarning, aerror, acritical, aexception, alog
 
 .. autoclass:: AsyncBoundLogger
 

docs/getting-started.md

@@ -225,25 +225,22 @@ As noted before, the fastest way to transform *structlog* into a `logging`-frien
 
 ## asyncio
 
-*structlog* comes with two approaches to support asynchronous logging.
-
-The default *bound logger* that you get back from {func}`structlog.get_logger()` doesn't have just the familiar log methods like `debug()` or `info()`, but also their async cousins, that simply prefix the name with an a:
+The default *bound logger* that you get back from {func}`structlog.get_logger()` and standard library's {class}`structlog.stdlib.BoundLogger` don't have just the familiar log methods like `debug()` or `info()`, but also their async cousins, that simply prefix the name with an a:
 
 ```pycon
 >>> import asyncio
 >>> logger = structlog.get_logger()
 >>> async def f():
-...     await logger.ainfo("hi!")
+...     await logger.ainfo("async hi!")
 ...
+>>> logger.info("Loop isn't running yet, but we can log!")
+2023-04-06 07:25:48 [info     ] Loop isn't running yet, but we can log!
 >>> asyncio.run(f())
-2022-10-18 13:23:37 [info     ] hi!
+2023-04-06 07:26:08 [info     ] async hi!
 ```
 
 You can use the sync and async logging methods interchangeably within the same application.
 
----
-
-The standard library integration on the other hand offers an asynchronous wrapper class {class}`structlog.stdlib.AsyncBoundLogger`.
 
 ## Liked what you saw?
 

docs/standard-library.md

@@ -48,13 +48,29 @@ See also {doc}`typing`.
 
 ### `asyncio`
 
-For `asyncio` applications, you may not want your whole application to block while your processor chain is formatting your log entries.
-For that use case *structlog* comes with {class}`structlog.stdlib.AsyncBoundLogger` that will do all processing in a thread pool executor.
+For `asyncio` applications, you may not want your whole application to block while the processor chain is formatting your log entries.
 
-This means an increased computational cost per log entry but your application will never block because of logging.
+For that use case *structlog* comes with a set of non-standard methods that will do all processing in a thread pool executor.
+They have the same names as the regular methods, except they are prefixed by an `a`.
+So instead of `logger.info("event!")` you write `await logger.ainfo("event!)`.
+No extra configuration is necessary and you can mix-and-match both types of methods within the same application.
+
+This means an increased computational cost per log entry, but your application will not block because of logging.
+
+```{versionadded} 23.1.0
+```
+
+---
+
+
+*structlog* also comes with {class}`structlog.stdlib.AsyncBoundLogger` that blankly makes all logging methods asynchronous (i.e. `await log.info()`).
 
 To use it, {doc}`configure <configuration>` *structlog* to use `AsyncBoundLogger` as `wrapper_class`.
 
+```{versionadded} 20.2.0
+```
+
+
 
 ## Processors
 

src/structlog/stdlib.py

@@ -137,6 +137,9 @@ class BoundLogger(BoundLoggerBase):
 
     It also contains a bunch of properties that pass-through to the wrapped
     `logging.Logger` which should make it work as a drop-in replacement.
+
+    .. versionadded:: 23.1.0
+       Async variants `alog()`, `adebug()`, `ainfo()`, and so forth.
     """
 
     _logger: logging.Logger
@@ -375,6 +378,89 @@ def getChild(self, suffix: str) -> logging.Logger:
         """
         return self._logger.getChild(suffix)
 
+    # Non-Standard Async
+    async def _dispatch_to_sync(
+        self,
+        meth: Callable[..., Any],
+        event: str,
+        args: tuple[Any, ...],
+        kw: dict[str, Any],
+    ) -> None:
+        """
+        Merge contextvars and log using the sync logger in a thread pool.
+        """
+        ctx = contextvars.copy_context()
+
+        await asyncio.get_running_loop().run_in_executor(
+            None,
+            lambda: ctx.run(lambda: meth(event, *args, **kw)),
+        )
+
+    async def adebug(self, event: str, *args: Any, **kw: Any) -> None:
+        """
+        Log using `debug()`, but asynchronously in a separate thread.
+
+        .. versionadded:: 23.1.0
+        """
+        await self._dispatch_to_sync(self.debug, event, args, kw)
+
+    async def ainfo(self, event: str, *args: Any, **kw: Any) -> None:
+        """
+        Log using `info()`, but asynchronously in a separate thread.
+
+        .. versionadded:: 23.1.0
+        """
+        await self._dispatch_to_sync(self.info, event, args, kw)
+
+    async def awarning(self, event: str, *args: Any, **kw: Any) -> None:
+        """
+        Log using `warning()`, but asynchronously in a separate thread.
+
+        .. versionadded:: 23.1.0
+        """
+        await self._dispatch_to_sync(self.warning, event, args, kw)
+
+    async def aerror(self, event: str, *args: Any, **kw: Any) -> None:
+        """
+        Log using `error()`, but asynchronously in a separate thread.
+
+        .. versionadded:: 23.1.0
+        """
+        await self._dispatch_to_sync(self.error, event, args, kw)
+
+    async def acritical(self, event: str, *args: Any, **kw: Any) -> None:
+        """
+        Log using `critical()`, but asynchronously in a separate thread.
+
+        .. versionadded:: 23.1.0
+        """
+        await self._dispatch_to_sync(self.critical, event, args, kw)
+
+    afatal = acritical
+
+    async def aexception(self, event: str, *args: Any, **kw: Any) -> None:
+        """
+        Log using `exception()`, but asynchronously in a separate thread.
+
+        .. versionadded:: 23.1.0
+        """
+        # To make `log.exception("foo") work, we have to check if the user
+        # passed an explicit exc_info and if not, supply our own.
+        if kw.get("exc_info", True) is True and kw.get("exception") is None:
+            kw["exc_info"] = sys.exc_info()
+
+        await self._dispatch_to_sync(self.exception, event, args, kw)
+
+    async def alog(
+        self, level: Any, event: str, *args: Any, **kw: Any
+    ) -> None:
+        """
+        Log using `log()`, but asynchronously in a separate thread.
+
+        .. versionadded:: 23.1.0
+        """
+        await self._dispatch_to_sync(partial(self.log, level), event, args, kw)
+
 
 def get_logger(*args: Any, **initial_values: Any) -> BoundLogger:
     """

tests/test_log_levels.py

@@ -15,16 +15,10 @@
     clear_contextvars,
     merge_contextvars,
 )
-from structlog.testing import CapturingLogger
-
-
-@pytest.fixture(name="cl")
-def fixture_cl():
-    return CapturingLogger()
 
 
 @pytest.fixture(name="bl")
-def fixture_bl(cl):
+def _bl(cl):
     return make_filtering_bound_logger(logging.INFO)(cl, [], {})
 
 
@@ -79,7 +73,7 @@ async def test_async_filtered_interp(self, bl, cl):
 
     def test_no_args(self, bl, cl):
         """
-        If no args are passed, don't attempt intepolation.
+        If no args are passed, don't attempt interpolation.
 
         See also #473
         """
@@ -89,7 +83,7 @@ def test_no_args(self, bl, cl):
 
     async def test_async_no_args(self, bl, cl):
         """
-        If no args are passed, don't attempt intepolation.
+        If no args are passed, don't attempt interpolation.
 
         See also #473
         """

tests/test_stdlib.py

@@ -340,6 +340,66 @@ def test_proxies_try_unbind(self):
 
         assert {} == get_context(bl)
 
+    @pytest.mark.parametrize(
+        "meth", ["debug", "info", "warning", "error", "critical"]
+    )
+    async def test_async_log_methods(self, meth, cl):
+        """
+        Async methods log async.
+        """
+        bl = build_bl(cl, processors=[])
+
+        await getattr(bl, f"a{meth}")("Async!")
+
+        assert [
+            CapturedCall(method_name=meth, args=(), kwargs={"event": "Async!"})
+        ] == cl.calls
+
+    async def test_alog(self, cl):
+        """
+        Alog logs async at the correct level.
+        """
+        bl = build_bl(cl, processors=[])
+
+        await bl.alog(logging.INFO, "foo %s", "bar")
+
+        assert [
+            CapturedCall(
+                method_name="info",
+                args=(),
+                kwargs={"positional_args": ("bar",), "event": "foo %s"},
+            )
+        ] == cl.calls
+
+    async def test_aexception_exc_info_true(self, cl):
+        """
+        aexception passes current exc_info into dispatch.
+        """
+        bl = build_bl(cl, processors=[])
+
+        try:
+            raise ValueError(42)
+        except ValueError as e:
+            await bl.aexception("oops")
+            exc = e
+
+        (cc,) = cl.calls
+
+        assert isinstance(cc[2]["exc_info"], tuple)
+        assert exc == cc[2]["exc_info"][1]
+
+    async def test_aexception_exc_info_explicit(self, cl):
+        """
+        In aexception, if exc_info isn't missing or True, leave it be.
+        """
+        bl = build_bl(cl, processors=[])
+
+        obj = object()
+
+        await bl.aexception("ooops", exc_info=obj)
+
+        assert obj is cl.calls[0].kwargs["exc_info"]
+
 
 class TestPositionalArgumentsFormatter:
     def test_formats_tuple(self):

tox.ini

@@ -25,7 +25,7 @@ commands =
 [testenv:pre-commit]
 skip_install = true
 deps = pre-commit
-commands = pre-commit run --all-files --show-diff-on-failure
+commands = pre-commit run --all-files
 
 
 [testenv:mypy]

typing_examples.py

@@ -309,6 +309,18 @@ async def typecheck_filtering_return_async() -> None:
     await fblogger.alog(logging.CRITICAL, "async log")
 
 
+async def typecheck_stdlib_async() -> None:
+    logger: structlog.stdlib.BoundLogger = structlog.get_logger(__name__)
+    await logger.adebug("async debug")
+    await logger.ainfo("async info")
+    await logger.awarning("async warning")
+    await logger.aerror("async error")
+    await logger.afatal("fatal error")
+    await logger.aexception("async exception")
+    await logger.acritical("async critical")
+    await logger.alog(logging.CRITICAL, "async log")
+
+
 # Structured tracebacks and ExceptionRenderer with ExceptionDictTransformer
 struct_tb: structlog.tracebacks.Trace = structlog.tracebacks.extract(
     ValueError, ValueError("onoes"), None