From af519688d20912d09b627a70fc57a5ac3f87a4c1 Mon Sep 17 00:00:00 2001 From: Hynek Schlawack Date: Sat, 8 Feb 2020 11:35:18 +0100 Subject: [PATCH 1/9] Start the async revolution --- CHANGELOG.rst | 4 +- docs/api.rst | 3 ++ setup.py | 2 +- src/structlog/stdlib.py | 72 ++++++++++++++++++++++++++ tests/test_stdlib.py | 111 ++++++++++++++++++++++++++++++++++++++++ 5 files changed, 190 insertions(+), 2 deletions(-) diff --git a/CHANGELOG.rst b/CHANGELOG.rst index aae565a8..e25957e9 100644 --- a/CHANGELOG.rst +++ b/CHANGELOG.rst @@ -53,7 +53,9 @@ Changes: `#266 `_, - ``structlog.PrintLogger`` now supports ``copy.deepcopy()``. `#268 `_ -- Added ``structlog.testing.CapturingLogger`` for more unittesting goodness. +- Added ``structlog.testing.CapturingLogger`` for more unit testing goodness. +- Added ``structlog.stdlib.AsyncBoundLogger`` that executes logging calls in a thread executor and therefore doesn't block. + `#245 `_ ---- diff --git a/docs/api.rst b/docs/api.rst index 9220eb46..1330f88b 100644 --- a/docs/api.rst +++ b/docs/api.rst @@ -237,6 +237,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__ diff --git a/setup.py b/setup.py index d644162f..18a5d453 100644 --- a/setup.py +++ b/setup.py @@ -47,7 +47,7 @@ "coverage[toml]", "freezegun>=0.2.8", "pretend", - "pytest-asyncio; python_version>='3.7'", + "pytest-asyncio", "pytest-randomly", "pytest>=6.0", "simplejson", diff --git a/src/structlog/stdlib.py b/src/structlog/stdlib.py index 7bb1f027..622dc842 100644 --- a/src/structlog/stdlib.py +++ b/src/structlog/stdlib.py @@ -8,8 +8,11 @@ See also :doc:`structlog's standard library support `. """ + +import asyncio import logging +from functools import partial from typing import Any, Dict, List, Optional, Sequence, Tuple from ._base import BoundLoggerBase @@ -337,6 +340,75 @@ def get_logger(*args: Any, **initial_values: Any) -> BoundLogger: return _generic_get_logger(*args, **initial_values) +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. diff --git a/tests/test_stdlib.py b/tests/test_stdlib.py index ac9c1914..3218e8c2 100644 --- a/tests/test_stdlib.py +++ b/tests/test_stdlib.py @@ -3,6 +3,8 @@ # repository for complete details. +import collections +import json import logging import logging.config import os @@ -14,10 +16,25 @@ from structlog import ReturnLogger, configure, get_context, reset_defaults from structlog._log_levels import _NAME_TO_LEVEL, CRITICAL, WARN +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, + _NAME_TO_LEVEL, + CRITICAL, + WARN, + AsyncBoundLogger, BoundLogger, LoggerFactory, PositionalArgumentsFormatter, @@ -822,3 +839,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() From 020a3a5dc803689fe9c24e11985eb04f01cdfd91 Mon Sep 17 00:00:00 2001 From: Hynek Schlawack Date: Sun, 9 Feb 2020 13:37:52 +0100 Subject: [PATCH 2/9] Keep stuff private for now --- src/structlog/stdlib.py | 23 +++++++++++++---------- 1 file changed, 13 insertions(+), 10 deletions(-) diff --git a/src/structlog/stdlib.py b/src/structlog/stdlib.py index 622dc842..75f57f73 100644 --- a/src/structlog/stdlib.py +++ b/src/structlog/stdlib.py @@ -346,15 +346,17 @@ class AsyncBoundLogger: a thread executor. Only available for Python 3.7 and later. + + .. versionadded:: 20.2 """ __slots__ = ["sync_bl", "_loop"] - executor = None - bound_logger_factory = BoundLogger + _executor = None + _bound_logger_factory = BoundLogger def __init__(self, *args, **kw): - self.sync_bl = self.bound_logger_factory(*args, **kw) + self.sync_bl = self._bound_logger_factory(*args, **kw) self._loop = asyncio.get_running_loop() def bind(self, **new_values) -> "AsyncBoundLogger": @@ -371,41 +373,42 @@ def unbind(self, *keys) -> "AsyncBoundLogger": async def debug(self, event, *args, **kw): return await self._loop.run_in_executor( - self.executor, partial(self.sync_bl.debug, event, *args, **kw) + 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) + 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) + 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) + 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) + 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) + 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) + self._executor, + partial(self.sync_bl.log, level, event, *args, **kw), ) From bbd64853a73c0efb1e9e6504d0c930bfdbbe80b8 Mon Sep 17 00:00:00 2001 From: Hynek Schlawack Date: Sun, 9 Feb 2020 15:21:06 +0100 Subject: [PATCH 3/9] Point out that running async means more overhead --- src/structlog/stdlib.py | 11 ++++++++--- 1 file changed, 8 insertions(+), 3 deletions(-) diff --git a/src/structlog/stdlib.py b/src/structlog/stdlib.py index 75f57f73..a089fca4 100644 --- a/src/structlog/stdlib.py +++ b/src/structlog/stdlib.py @@ -342,12 +342,17 @@ def get_logger(*args: Any, **initial_values: Any) -> BoundLogger: class AsyncBoundLogger: """ - Wraps a `BoundLogger` and runs its logging methods asynchronously in - a thread executor. + Wrap a `BoundLogger` and run its logging methods asynchronously in a thread + executor. + + .. note:: + This means more computational overhead per log call. But it also means + that the processor chain (e.g. JSON serialization) and I/O won't block + your whole application. Only available for Python 3.7 and later. - .. versionadded:: 20.2 + .. versionadded:: 20.2.0 """ __slots__ = ["sync_bl", "_loop"] From ccbd341d5dfe07a0e56636f76b994c35420efc1f Mon Sep 17 00:00:00 2001 From: Hynek Schlawack Date: Tue, 25 Feb 2020 13:33:46 +0100 Subject: [PATCH 4/9] Add types --- docs/standard-library.rst | 11 +++++++ src/structlog/stdlib.py | 64 ++++++++++++++++++++++++--------------- 2 files changed, 51 insertions(+), 24 deletions(-) diff --git a/docs/standard-library.rst b/docs/standard-library.rst index 69f16f33..5945bbe3 100644 --- a/docs/standard-library.rst +++ b/docs/standard-library.rst @@ -48,6 +48,17 @@ Please note though, that it will neither configure nor verify your configuration It will call `structlog.get_logger()` just like if you would've called it -- the only difference are the type hints. +``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 `structlog.stdlib.AsyncBoundLogger` that will do all processing in a thread pool executor. + +This means an increased computational cost per log entry but your application will never block because of logging. + +To use it, simply replace all instances of `structlog.stdlib.BoundLogger` with `AsyncBoundLogger` in all calls to `structlog.configure`. + + Processors ---------- diff --git a/src/structlog/stdlib.py b/src/structlog/stdlib.py index a089fca4..74837de0 100644 --- a/src/structlog/stdlib.py +++ b/src/structlog/stdlib.py @@ -11,9 +11,11 @@ import asyncio import logging +import sys from functools import partial from typing import Any, Dict, List, Optional, Sequence, Tuple +from typing import Any, Callable, List, Mapping, Sequence from ._base import BoundLoggerBase from ._config import get_logger as _generic_get_logger @@ -343,12 +345,12 @@ def get_logger(*args: Any, **initial_values: Any) -> BoundLogger: class AsyncBoundLogger: """ Wrap a `BoundLogger` and run its logging methods asynchronously in a thread - executor. + pool executor. .. note:: - This means more computational overhead per log call. But it also means - that the processor chain (e.g. JSON serialization) and I/O won't block - your whole application. + This means more computational overhead per log call. But it also means + that the processor chain (e.g. JSON serialization) and I/O won't block + your whole application. Only available for Python 3.7 and later. @@ -360,58 +362,72 @@ class AsyncBoundLogger: _executor = None _bound_logger_factory = BoundLogger - def __init__(self, *args, **kw): - self.sync_bl = self._bound_logger_factory(*args, **kw) + def __init__( + self, + logger: logging.Logger, + processors: List[Callable], + context: Mapping, + ): + self.sync_bl = self._bound_logger_factory( + logger=logger, processors=processors, context=context + ) self._loop = asyncio.get_running_loop() - def bind(self, **new_values) -> "AsyncBoundLogger": + def bind(self, **new_values: Any) -> "AsyncBoundLogger": self.sync_bl = self.sync_bl.bind(**new_values) return self - def new(self, **new_values) -> "AsyncBoundLogger": + def new(self, **new_values: Any) -> "AsyncBoundLogger": self.sync_bl = self.sync_bl.new(**new_values) return self - def unbind(self, *keys) -> "AsyncBoundLogger": + def unbind(self, *keys: Sequence[str]) -> "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( + async def debug(self, event: str, *args: Any, **kw: Any) -> None: + 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( + async def info(self, event: str, *args: Any, **kw: Any) -> None: + 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( + async def warning(self, event: str, *args: Any, **kw: Any) -> None: + 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( + async def error(self, event: str, *args: Any, **kw: Any) -> None: + 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( + async def critical(self, event: str, *args: Any, **kw: Any) -> None: + 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 exception(self, event: str, *args: Any, **kw: Any) -> None: + # To make `log.exception("foo") work, we have to check if the user + # passed an explicit exc_info and if not, supply our own. + ei = kw.pop("exc_info", None) + if ei is None and kw.get("exception") is None: + ei = sys.exc_info() + + await self._loop.run_in_executor( + self._executor, + partial(self.sync_bl.exception, event, *args, exc_info=ei, **kw), ) - async def log(self, level, event, *args, **kw): - return await self._loop.run_in_executor( + async def log(self, level: Any, event: str, *args: Any, **kw: Any) -> None: + await self._loop.run_in_executor( self._executor, partial(self.sync_bl.log, level, event, *args, **kw), ) From f2a78954aee096dd40756465e1d3f2aae15364a5 Mon Sep 17 00:00:00 2001 From: Hynek Schlawack Date: Wed, 5 Aug 2020 09:59:13 +0200 Subject: [PATCH 5/9] Update from prod --- src/structlog/stdlib.py | 65 +++++++++++++++++++++++++---------------- 1 file changed, 40 insertions(+), 25 deletions(-) diff --git a/src/structlog/stdlib.py b/src/structlog/stdlib.py index 74837de0..5810b14d 100644 --- a/src/structlog/stdlib.py +++ b/src/structlog/stdlib.py @@ -16,6 +16,8 @@ from functools import partial from typing import Any, Dict, List, Optional, Sequence, Tuple from typing import Any, Callable, List, Mapping, Sequence +from typing import Any, Callable, List, Mapping, Sequence +from typing import Any, Callable, Dict, List, Mapping, Sequence, Tuple from ._base import BoundLoggerBase from ._config import get_logger as _generic_get_logger @@ -347,13 +349,23 @@ class AsyncBoundLogger: Wrap a `BoundLogger` and run its logging methods asynchronously in a thread pool executor. - .. note:: - This means more computational overhead per log call. But it also means - that the processor chain (e.g. JSON serialization) and I/O won't block - your whole application. + This means more computational overhead per log call. But it also means that + the processor chain (e.g. JSON serialization) and I/O won't block your + whole application. + + .. warning: + Since the processor pipeline runs in a separate thread, + `structlog.contextvars.merge_contextvars` does **nothing** and should + be removed from you processor chain. + + Instead it's merged within **this logger** before handing off log + processing to the thread. Only available for Python 3.7 and later. + :ivar sync_bl: The wrapped synchronous logger. It is useful to be able to + log synchronously occasionally. + .. versionadded:: 20.2.0 """ @@ -385,32 +397,38 @@ def unbind(self, *keys: Sequence[str]) -> "AsyncBoundLogger": self.sync_bl = self.sync_bl.try_unbind(*keys) return self - async def debug(self, event: str, *args: Any, **kw: Any) -> None: + async def _dispatch_to_sync( + self, + meth: Callable, + event: str, + args: Tuple[Any, ...], + kw: Dict[str, Any], + ) -> None: + """ + Merge contextvars and log using the sync logger in a thread pool. + """ + ctx = contextvars._get_context().copy() + ctx.update(kw) await self._loop.run_in_executor( - self._executor, partial(self.sync_bl.debug, event, *args, **kw) + self._executor, partial(meth, event, *args, **ctx) ) + async def debug(self, event: str, *args: Any, **kw: Any) -> None: + await self._dispatch_to_sync(self.sync_bl.debug, event, args, kw) + async def info(self, event: str, *args: Any, **kw: Any) -> None: - await self._loop.run_in_executor( - self._executor, partial(self.sync_bl.info, event, *args, **kw) - ) + await self._dispatch_to_sync(self.sync_bl.info, event, args, kw) async def warning(self, event: str, *args: Any, **kw: Any) -> None: - await self._loop.run_in_executor( - self._executor, partial(self.sync_bl.warning, event, *args, **kw) - ) + await self._dispatch_to_sync(self.sync_bl.warning, event, args, kw) warn = warning async def error(self, event: str, *args: Any, **kw: Any) -> None: - await self._loop.run_in_executor( - self._executor, partial(self.sync_bl.error, event, *args, **kw) - ) + await self._dispatch_to_sync(self.sync_bl.error, event, args, kw) async def critical(self, event: str, *args: Any, **kw: Any) -> None: - await self._loop.run_in_executor( - self._executor, partial(self.sync_bl.critical, event, *args, **kw) - ) + await self._dispatch_to_sync(self.sync_bl.critical, event, args, kw) fatal = critical @@ -420,16 +438,13 @@ async def exception(self, event: str, *args: Any, **kw: Any) -> None: ei = kw.pop("exc_info", None) if ei is None and kw.get("exception") is None: ei = sys.exc_info() + kw["exc_info"] = ei - await self._loop.run_in_executor( - self._executor, - partial(self.sync_bl.exception, event, *args, exc_info=ei, **kw), - ) + await self._dispatch_to_sync(self.sync_bl.exception, event, args, kw) async def log(self, level: Any, event: str, *args: Any, **kw: Any) -> None: - await self._loop.run_in_executor( - self._executor, - partial(self.sync_bl.log, level, event, *args, **kw), + await self._dispatch_to_sync( + partial(self.sync_bl.log, level), event, args, kw ) From fa8ba7f66708f0415f0ea3468e2b22cdd90766aa Mon Sep 17 00:00:00 2001 From: Hynek Schlawack Date: Wed, 16 Dec 2020 11:18:52 +0100 Subject: [PATCH 6/9] Fix tests --- .pre-commit-config.yaml | 2 +- conftest.py | 29 +++++++++-- docs/api.rst | 3 +- docs/conf.py | 1 + src/structlog/stdlib.py | 111 +++++++++++++++++++++++++++++++--------- tests/test_loggers.py | 14 ++--- tests/test_stdlib.py | 86 +++++++++++++++---------------- tests/test_twisted.py | 9 ++-- 8 files changed, 164 insertions(+), 91 deletions(-) diff --git a/.pre-commit-config.yaml b/.pre-commit-config.yaml index 1ce19f5c..6d407190 100644 --- a/.pre-commit-config.yaml +++ b/.pre-commit-config.yaml @@ -21,7 +21,7 @@ repos: exclude: docs/code_examples - repo: https://github.com/pre-commit/pre-commit-hooks - rev: v3.3.0 + rev: v3.4.0 hooks: - id: trailing-whitespace - id: end-of-file-fixer diff --git a/conftest.py b/conftest.py index ca862f95..31dbb9d8 100644 --- a/conftest.py +++ b/conftest.py @@ -3,6 +3,7 @@ # repository for complete details. +import logging import sys from io import StringIO @@ -10,6 +11,7 @@ import pytest from structlog._log_levels import _NAME_TO_LEVEL +from structlog.testing import CapturingLogger try: @@ -17,11 +19,25 @@ except ImportError: twisted = None +LOGGER = logging.getLogger() -@pytest.fixture -def sio(): + +@pytest.fixture(autouse=True) +def _ensure_logging_framework_not_altered(): + """ + Prevents 'ValueError: I/O operation on closed file.' errors. + """ + before_handlers = list(LOGGER.handlers) + + yield + + LOGGER.handlers = before_handlers + + +@pytest.fixture(name="sio") +def _sio(): """ - A StringIO instance. + A new StringIO instance. """ return StringIO() @@ -43,10 +59,15 @@ def __repr__(self): name="stdlib_log_method", params=[m for m in _NAME_TO_LEVEL if m != "notset"], ) -def fixture_stdlib_log_methods(request): +def _stdlib_log_methods(request): return request.param +@pytest.fixture(name="cl") +def _cl(): + return CapturingLogger() + + collect_ignore = [] if sys.version_info[:2] < (3, 7): collect_ignore.append("tests/test_contextvars.py") diff --git a/docs/api.rst b/docs/api.rst index 1330f88b..08ca999a 100644 --- a/docs/api.rst +++ b/docs/api.rst @@ -235,10 +235,9 @@ API Reference .. autofunction:: get_logger .. autoclass:: BoundLogger - :members: bind, unbind, new, debug, info, warning, warn, error, critical, exception, log + :members: bind, unbind, try_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__ diff --git a/docs/conf.py b/docs/conf.py index 74281a47..63a0dbf6 100644 --- a/docs/conf.py +++ b/docs/conf.py @@ -74,6 +74,7 @@ def find_version(*file_paths): ("py:class", "TextIO"), ("py:class", "structlog._base.BoundLoggerBase"), ("py:class", "structlog.dev._Styles"), + ("py:obj", "sync_bl"), ] # If true, '()' will be appended to :func: etc. cross-reference text. diff --git a/src/structlog/stdlib.py b/src/structlog/stdlib.py index 5810b14d..0a69e27c 100644 --- a/src/structlog/stdlib.py +++ b/src/structlog/stdlib.py @@ -14,30 +14,42 @@ import sys from functools import partial -from typing import Any, Dict, List, Optional, Sequence, Tuple -from typing import Any, Callable, List, Mapping, Sequence -from typing import Any, Callable, List, Mapping, Sequence -from typing import Any, Callable, Dict, List, Mapping, Sequence, Tuple +from typing import ( + Any, + Callable, + Dict, + Iterable, + List, + Optional, + Sequence, + Tuple, +) from ._base import BoundLoggerBase from ._config import get_logger as _generic_get_logger from ._frames import _find_first_app_frame_and_name, _format_stack from ._log_levels import _LEVEL_TO_NAME, _NAME_TO_LEVEL, add_log_level from .exceptions import DropEvent -from .types import EventDict, ExcInfo, Processor, WrappedLogger +from .types import Context, EventDict, ExcInfo, Processor, WrappedLogger + + +try: + from . import contextvars +except ImportError: + contextvars = None # type: ignore __all__ = [ + "add_log_level_number", + "add_log_level", + "add_logger_name", "BoundLogger", + "filter_by_level", "get_logger", "LoggerFactory", "PositionalArgumentsFormatter", - "filter_by_level", - "add_log_level_number", - "add_log_level", - "add_logger_name", - "render_to_log_kwargs", "ProcessorFormatter", + "render_to_log_kwargs", ] @@ -346,15 +358,16 @@ def get_logger(*args: Any, **initial_values: Any) -> BoundLogger: class AsyncBoundLogger: """ - Wrap a `BoundLogger` and run its logging methods asynchronously in a thread + Wraps a `BoundLogger` & exposes its logging methods as ``async`` versions. + + Instead of blocking the program, they are run asynchronously in a thread pool executor. This means more computational overhead per log call. But it also means that the processor chain (e.g. JSON serialization) and I/O won't block your whole application. - .. warning: - Since the processor pipeline runs in a separate thread, + .. warning: Since the processor pipeline runs in a separate thread, `structlog.contextvars.merge_contextvars` does **nothing** and should be removed from you processor chain. @@ -363,43 +376,89 @@ class AsyncBoundLogger: Only available for Python 3.7 and later. - :ivar sync_bl: The wrapped synchronous logger. It is useful to be able to - log synchronously occasionally. + :ivar structlog.stdlib.BoundLogger sync_bl: The wrapped synchronous logger. + It is useful to be able to log synchronously occasionally. .. versionadded:: 20.2.0 """ __slots__ = ["sync_bl", "_loop"] + sync_bl: BoundLogger + _executor = None _bound_logger_factory = BoundLogger def __init__( self, logger: logging.Logger, - processors: List[Callable], - context: Mapping, + processors: Iterable[Processor], + context: Context, + *, + # Only as an optimization for binding! + _sync_bl: Any = None, # *vroom vroom* over purity. + _loop: Any = None, ): + if _sync_bl: + self.sync_bl = _sync_bl + self._loop = _loop + + return + self.sync_bl = self._bound_logger_factory( logger=logger, processors=processors, context=context ) self._loop = asyncio.get_running_loop() + @property + def _context(self) -> Context: + return self.sync_bl._context + def bind(self, **new_values: Any) -> "AsyncBoundLogger": - self.sync_bl = self.sync_bl.bind(**new_values) - return self + return AsyncBoundLogger( + # logger, processors and context are within sync_bl. These + # arguments are ignored if _sync_bl is passsed. *vroom vroom* over + # purity. + logger=None, # type: ignore + processors=(), + context={}, + _sync_bl=self.sync_bl.bind(**new_values), + _loop=self._loop, + ) def new(self, **new_values: Any) -> "AsyncBoundLogger": - self.sync_bl = self.sync_bl.new(**new_values) - return self + return AsyncBoundLogger( + # c.f. comment in bind + logger=None, # type: ignore + processors=(), + context={}, + _sync_bl=self.sync_bl.new(**new_values), + _loop=self._loop, + ) + + def unbind(self, *keys: str) -> "AsyncBoundLogger": + return AsyncBoundLogger( + # c.f. comment in bind + logger=None, # type: ignore + processors=(), + context={}, + _sync_bl=self.sync_bl.unbind(*keys), + _loop=self._loop, + ) - def unbind(self, *keys: Sequence[str]) -> "AsyncBoundLogger": - self.sync_bl = self.sync_bl.try_unbind(*keys) - return self + def try_unbind(self, *keys: str) -> "AsyncBoundLogger": + return AsyncBoundLogger( + # c.f. comment in bind + logger=None, # type: ignore + processors=(), + context={}, + _sync_bl=self.sync_bl.try_unbind(*keys), + _loop=self._loop, + ) async def _dispatch_to_sync( self, - meth: Callable, + meth: Callable[..., Any], event: str, args: Tuple[Any, ...], kw: Dict[str, Any], @@ -409,6 +468,7 @@ async def _dispatch_to_sync( """ ctx = contextvars._get_context().copy() ctx.update(kw) + await self._loop.run_in_executor( self._executor, partial(meth, event, *args, **ctx) ) @@ -438,6 +498,7 @@ async def exception(self, event: str, *args: Any, **kw: Any) -> None: ei = kw.pop("exc_info", None) if ei is None and kw.get("exception") is None: ei = sys.exc_info() + kw["exc_info"] = ei await self._dispatch_to_sync(self.sync_bl.exception, event, args, kw) diff --git a/tests/test_loggers.py b/tests/test_loggers.py index 8d7f5625..7d9ed09e 100644 --- a/tests/test_loggers.py +++ b/tests/test_loggers.py @@ -7,7 +7,7 @@ import pickle import sys -from io import BytesIO, StringIO +from io import BytesIO import pytest @@ -53,12 +53,10 @@ def test_repr(self): """ assert repr(PrintLogger()).startswith(" Date: Wed, 16 Dec 2020 11:41:26 +0100 Subject: [PATCH 7/9] Refactor fixture --- tests/test_stdlib.py | 56 ++++++++++++++++++++++++++++++++++---------- 1 file changed, 43 insertions(+), 13 deletions(-) diff --git a/tests/test_stdlib.py b/tests/test_stdlib.py index 51591312..81393992 100644 --- a/tests/test_stdlib.py +++ b/tests/test_stdlib.py @@ -832,27 +832,29 @@ def test_foreign_pre_chain_filter_by_level(self, configure_for_pf, capsys): ) == capsys.readouterr() +@pytest.fixture(name="abl") +async def _abl(cl): + return AsyncBoundLogger(cl, context={}, processors=[]) + + @pytest.mark.skipif( sys.version_info[:2] < (3, 7), reason="AsyncBoundLogger is only for Python 3.7 and later.", ) class TestAsyncBoundLogger: @pytest.mark.asyncio - async def test_protocol(self): + async def test_protocol(self, abl): """ AsyncBoundLogger is a proper BindableLogger. """ - assert isinstance(AsyncBoundLogger(None, {}, []), BindableLogger) + assert isinstance(abl, BindableLogger) @pytest.mark.asyncio - async def test_correct_levels(self, cl, stdlib_log_method): + async def test_correct_levels(self, abl, cl, stdlib_log_method): """ The proxy methods call the correct upstream methods. """ - await getattr( - AsyncBoundLogger(cl, context={}, processors=[]).bind(foo="bar"), - stdlib_log_method, - )("42") + await getattr(abl.bind(foo="bar"), stdlib_log_method)("42") aliases = {"exception": "error", "warn": "warning"} @@ -865,18 +867,46 @@ async def test_correct_levels(self, cl, stdlib_log_method): assert expect == cl.calls[0].method_name @pytest.mark.asyncio - async def test_log_method(self, cl): + async def test_log_method(self, abl, cl): """ The `log` method is proxied too. """ - await ( - AsyncBoundLogger(cl, context={}, processors=[]) - .bind(foo="bar") - .log(logging.ERROR, "42") - ) + await abl.bind(foo="bar").log(logging.ERROR, "42") assert "error" == cl.calls[0].method_name + @pytest.mark.asyncio + async def test_exception(self, abl, cl): + """ + `exception` makes sure 'exc_info" is set, if it's not set already. + """ + try: + raise ValueError("omg") + except ValueError: + await abl.exception("oops") + + ei = cl.calls[0].kwargs["exc_info"] + + assert ValueError is ei[0] + assert ("omg",) == ei[1].args + + @pytest.mark.asyncio + async def test_exception_do_not_overwrite(self, abl, cl): + """ + `exception` leaves exc_info be, if it's set. + """ + o1 = object() + o2 = object() + o3 = object() + + try: + raise ValueError("omg") + except ValueError: + await abl.exception("oops", exc_info=(o1, o2, o3)) + + ei = cl.calls[0].kwargs["exc_info"] + assert (o1, o2, o3) == ei + @pytest.mark.asyncio async def test_bind_unbind(self, cl): """ From 95a1233552dd4e4fea1da17e78c6d6f8f0f2e55e Mon Sep 17 00:00:00 2001 From: Hynek Schlawack Date: Wed, 16 Dec 2020 11:59:53 +0100 Subject: [PATCH 8/9] More helpful phrasing --- docs/standard-library.rst | 2 +- 1 file changed, 1 insertion(+), 1 deletion(-) diff --git a/docs/standard-library.rst b/docs/standard-library.rst index 5945bbe3..6ac1d868 100644 --- a/docs/standard-library.rst +++ b/docs/standard-library.rst @@ -56,7 +56,7 @@ For that use case ``structlog`` comes with `structlog.stdlib.AsyncBoundLogger` t This means an increased computational cost per log entry but your application will never block because of logging. -To use it, simply replace all instances of `structlog.stdlib.BoundLogger` with `AsyncBoundLogger` in all calls to `structlog.configure`. +To use it, :doc:`configure ` structlog to use `AsyncBoundLogger` as ``wrapper_class``. Processors From ba0c239003cea3f4adefe237f517230f143810a1 Mon Sep 17 00:00:00 2001 From: Hynek Schlawack Date: Wed, 16 Dec 2020 12:00:57 +0100 Subject: [PATCH 9/9] braaand --- docs/standard-library.rst | 2 +- 1 file changed, 1 insertion(+), 1 deletion(-) diff --git a/docs/standard-library.rst b/docs/standard-library.rst index 6ac1d868..596a1ca2 100644 --- a/docs/standard-library.rst +++ b/docs/standard-library.rst @@ -56,7 +56,7 @@ For that use case ``structlog`` comes with `structlog.stdlib.AsyncBoundLogger` t This means an increased computational cost per log entry but your application will never block because of logging. -To use it, :doc:`configure ` structlog to use `AsyncBoundLogger` as ``wrapper_class``. +To use it, :doc:`configure ` ``structlog`` to use `AsyncBoundLogger` as ``wrapper_class``. Processors