diff --git a/CHANGELOG.md b/CHANGELOG.md index cee51a9d..b8f59ab7 100644 --- a/CHANGELOG.md +++ b/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. diff --git a/docs/api.rst b/docs/api.rst index d968dbe3..9b6670b0 100644 --- a/docs/api.rst +++ b/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 diff --git a/docs/getting-started.md b/docs/getting-started.md index 935b3a35..7f770a99 100644 --- a/docs/getting-started.md +++ b/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? diff --git a/docs/standard-library.md b/docs/standard-library.md index e51267db..6339db8d 100644 --- a/docs/standard-library.md +++ b/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 ` *structlog* to use `AsyncBoundLogger` as `wrapper_class`. +```{versionadded} 20.2.0 +``` + + ## Processors diff --git a/src/structlog/stdlib.py b/src/structlog/stdlib.py index 9213fbbd..0e336692 100644 --- a/src/structlog/stdlib.py +++ b/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: """ diff --git a/tests/test_log_levels.py b/tests/test_log_levels.py index 727b4a9f..8faa576d 100644 --- a/tests/test_log_levels.py +++ b/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 """ diff --git a/tests/test_stdlib.py b/tests/test_stdlib.py index e09ee30a..d479438e 100644 --- a/tests/test_stdlib.py +++ b/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): diff --git a/tox.ini b/tox.ini index 04d72d1e..e84d268f 100644 --- a/tox.ini +++ b/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] diff --git a/typing_examples.py b/typing_examples.py index c47d1bfd..ab10880f 100644 --- a/typing_examples.py +++ b/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