Add async log methods to filtering bound logger (#457)

* Add async log methods to filtering bound logger

* Add changelog entry

* Save the tmp var

* Add docstrings and complete protocol

* Add to getting started

* Clarify around AsyncBoundLogger

* Typo

.pre-commit-config.yaml

@@ -38,6 +38,7 @@ repos:
     rev: v2.2.1
     hooks:
       - id: codespell
+        args: [-L, alog]
 
   - repo: https://github.com/pre-commit/pre-commit-hooks
     rev: v4.3.0

CHANGELOG.md

@@ -33,6 +33,13 @@ You can find out backwards-compatibility policy [here](https://github.com/hynek/
 
   [#454](https://github.com/hynek/structlog/pull/454)
 
+- `FilteringBoundLogger` now also has support for *asyncio*-based logging.
+  Instead of a wrapper class like `structlog.stdlib.AsyncBoundLogger`, async equivalents have been added for all logging methods.
+  So instead of `log.info("hello")` you can also write `await log.ainfo("hello")` in async functions and methods.
+
+  This seems like the better approach and if it's liked by the community, `structlog.stdlib.BoundLogger` will get those methods too.
+  [#457](https://github.com/hynek/structlog/pull/457)
+
 
 ### Changed
 

docs/getting-started.md

@@ -231,6 +231,28 @@ To make this common case as simple as possible, *structlog* comes with [some too
 As noted before, the fastest way to transform *structlog* into a `logging`-friendly package is calling {func}`structlog.stdlib.recreate_defaults()`.
 
 
+## 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:
+
+```pycon
+>>> import asyncio
+>>> logger = structlog.get_logger()
+>>> async def f():
+...     await logger.ainfo("hi!")
+...
+>>> asyncio.run(f())
+2022-10-18 13:23:37 [info     ] 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?
 
 Now you're all set for the rest of the user's guide and can start reading about [bound loggers](bound-loggers.md) -- the heart of *structlog*.

src/structlog/_log_levels.py

@@ -9,6 +9,8 @@
 
 from __future__ import annotations
 
+import asyncio
+import contextvars
 import logging
 
 from typing import Any, Callable
@@ -73,19 +75,38 @@ def _nop(self: Any, event: str, **kw: Any) -> Any:
     return None
 
 
+async def _anop(self: Any, event: str, **kw: Any) -> Any:
+    return None
+
+
 def exception(self: FilteringBoundLogger, event: str, **kw: Any) -> Any:
     kw.setdefault("exc_info", True)
 
     return self.error(event, **kw)
 
 
+async def aexception(self: FilteringBoundLogger, event: str, **kw: Any) -> Any:
+    kw.setdefault("exc_info", True)
+
+    return await asyncio.get_running_loop().run_in_executor(
+        None,
+        lambda: contextvars.copy_context().run(
+            lambda: self.error(event, **kw)
+        ),
+    )
+
+
 def make_filtering_bound_logger(min_level: int) -> type[FilteringBoundLogger]:
     """
     Create a new `FilteringBoundLogger` that only logs *min_level* or higher.
 
     The logger is optimized such that log levels below *min_level* only consist
     of a ``return None``.
 
+    All familiar log methods are present, with async variants of each that are
+    prefixed by an ``a``. Therefore, the async version of ``log.info("hello")``
+    is ``await log.ainfo("hello")``.
+
     Additionally it has a ``log(self, level: int, **kw: Any)`` method to mirror
     `logging.Logger.log` and `structlog.stdlib.BoundLogger.log`.
 
@@ -109,6 +130,8 @@ def make_filtering_bound_logger(min_level: int) -> type[FilteringBoundLogger]:
     .. versionadded:: 20.2.0
     .. versionchanged:: 21.1.0 The returned loggers are now pickleable.
     .. versionadded:: 20.1.0 The ``log()`` method.
+    .. versionadded:: 22.2.0
+       Async variants ``alog()``, ``adebug()``, ``ainfo()``, and so forth.
     """
 
     return _LEVEL_TO_FILTERING_LOGGER[min_level]
@@ -122,33 +145,63 @@ def _make_filtering_bound_logger(min_level: int) -> type[FilteringBoundLogger]:
     of a ``return None``.
     """
 
-    def make_method(level: int) -> Callable[..., Any]:
+    def make_method(
+        level: int,
+    ) -> tuple[Callable[..., Any], Callable[..., Any]]:
         if level < min_level:
-            return _nop
+            return _nop, _anop
 
         name = _LEVEL_TO_NAME[level]
 
         def meth(self: Any, event: str, *args: Any, **kw: Any) -> Any:
             return self._proxy_to_logger(name, event % args, **kw)
 
+        async def ameth(self: Any, event: str, *args: Any, **kw: Any) -> Any:
+            await asyncio.get_running_loop().run_in_executor(
+                None,
+                lambda: contextvars.copy_context().run(
+                    lambda: self._proxy_to_logger(name, event % args, **kw)
+                ),
+            )
+
         meth.__name__ = name
+        ameth.__name__ = f"a{name}"
+
+        return meth, ameth
+
+    def log(self: Any, level: int, event: str, *args: Any, **kw: Any) -> Any:
+        if level < min_level:
+            return None
+        name = _LEVEL_TO_NAME[level]
 
-        return meth
+        return self._proxy_to_logger(name, event % args, **kw)
 
-    def log(self: Any, level: int, event: str, **kw: Any) -> Any:
+    async def alog(
+        self: Any, level: int, event: str, *args: Any, **kw: Any
+    ) -> Any:
         if level < min_level:
             return None
         name = _LEVEL_TO_NAME[level]
-        return self._proxy_to_logger(name, event, **kw)
 
-    meths: dict[str, Callable[..., Any]] = {"log": log}
+        return await asyncio.get_running_loop().run_in_executor(
+            None,
+            lambda: contextvars.copy_context().run(
+                lambda: self._proxy_to_logger(name, event % args, **kw)
+            ),
+        )
+
+    meths: dict[str, Callable[..., Any]] = {"log": log, "alog": alog}
     for lvl, name in _LEVEL_TO_NAME.items():
-        meths[name] = make_method(lvl)
+        meths[name], meths[f"a{name}"] = make_method(lvl)
 
     meths["exception"] = exception
+    meths["aexception"] = aexception
     meths["fatal"] = meths["error"]
+    meths["afatal"] = meths["aerror"]
     meths["warn"] = meths["warning"]
+    meths["awarn"] = meths["awarning"]
     meths["msg"] = meths["info"]
+    meths["amsg"] = meths["ainfo"]
 
     return type(
         "BoundLoggerFilteringAt%s"

src/structlog/typing.py

@@ -153,6 +153,8 @@ class FilteringBoundLogger(BindableLogger, Protocol):
     .. versionadded:: 20.2.0
     .. versionadded:: 22.2.0
        String interpolation using positional arguments.
+    .. versionadded:: 22.2.0
+       Async variants ``alog()``, ``adebug()``, ``ainfo()``, and so forth.
     """
 
     def bind(self, **new_values: Any) -> FilteringBoundLogger:
@@ -188,26 +190,61 @@ def debug(self, event: str, *args: Any, **kw: Any) -> Any:
         Log ``event % args`` with **kw** at **debug** level.
         """
 
+    async def adebug(self, event: str, *args: Any, **kw: Any) -> Any:
+        """
+        Log ``event % args`` with **kw** at **debug** level.
+
+        ..versionadded:: 22.2.0
+        """
+
     def info(self, event: str, *args: Any, **kw: Any) -> Any:
         """
         Log ``event % args`` with **kw** at **info** level.
         """
 
+    async def ainfo(self, event: str, *args: Any, **kw: Any) -> Any:
+        """
+        Log ``event % args`` with **kw** at **info** level.
+
+        ..versionadded:: 22.2.0
+        """
+
     def warning(self, event: str, *args: Any, **kw: Any) -> Any:
         """
         Log ``event % args`` with **kw** at **warn** level.
         """
 
+    async def awarning(self, event: str, *args: Any, **kw: Any) -> Any:
+        """
+        Log ``event % args`` with **kw** at **warn** level.
+
+        ..versionadded:: 22.2.0
+        """
+
     def warn(self, event: str, *args: Any, **kw: Any) -> Any:
         """
         Log ``event % args`` with **kw** at **warn** level.
         """
 
+    async def awarn(self, event: str, *args: Any, **kw: Any) -> Any:
+        """
+        Log ``event % args`` with **kw** at **warn** level.
+
+        ..versionadded:: 22.2.0
+        """
+
     def error(self, event: str, *args: Any, **kw: Any) -> Any:
         """
         Log ``event % args`` with **kw** at **error** level.
         """
 
+    async def aerror(self, event: str, *args: Any, **kw: Any) -> Any:
+        """
+        Log ``event % args`` with **kw** at **error** level.
+
+        ..versionadded:: 22.2.0
+        """
+
     def err(self, event: str, *args: Any, **kw: Any) -> Any:
         """
         Log ``event % args`` with **kw** at **error** level.
@@ -218,17 +255,39 @@ def fatal(self, event: str, *args: Any, **kw: Any) -> Any:
         Log ``event % args`` with **kw** at **critical** level.
         """
 
+    async def afatal(self, event: str, *args: Any, **kw: Any) -> Any:
+        """
+        Log ``event % args`` with **kw** at **critical** level.
+
+        ..versionadded:: 22.2.0
+        """
+
     def exception(self, event: str, *args: Any, **kw: Any) -> Any:
         """
         Log ``event % args`` with **kw** at **error** level and ensure that
         ``exc_info`` is set in the event dictionary.
         """
 
+    async def aexception(self, event: str, *args: Any, **kw: Any) -> Any:
+        """
+        Log ``event % args`` with **kw** at **error** level and ensure that
+        ``exc_info`` is set in the event dictionary.
+
+        ..versionadded:: 22.2.0
+        """
+
     def critical(self, event: str, *args: Any, **kw: Any) -> Any:
         """
         Log ``event % args`` with **kw** at **critical** level.
         """
 
+    async def acritical(self, event: str, *args: Any, **kw: Any) -> Any:
+        """
+        Log ``event % args`` with **kw** at **critical** level.
+
+        ..versionadded:: 22.2.0
+        """
+
     def msg(self, event: str, *args: Any, **kw: Any) -> Any:
         """
         Log ``event % args`` with **kw** at **info** level.