From e191df70375c804b606c0507047c061fd2bd6fff Mon Sep 17 00:00:00 2001 From: Elad Namdar Date: Thu, 4 Feb 2021 16:28:26 +0200 Subject: [PATCH 1/5] contextvars: add test_parallel_binds to expose the bug in the contextvars impl --- tests/test_contextvars.py | 35 +++++++++++++++++++++++++++++++++++ 1 file changed, 35 insertions(+) diff --git a/tests/test_contextvars.py b/tests/test_contextvars.py index 538507f7..54257fca 100644 --- a/tests/test_contextvars.py +++ b/tests/test_contextvars.py @@ -2,6 +2,8 @@ # 2.0, and the MIT License. See the LICENSE file in the root of this # repository for complete details. +import asyncio + import pytest from structlog.contextvars import ( @@ -133,3 +135,36 @@ async def coro(): return merge_contextvars(None, None, {"b": 2}) assert {"b": 2} == await event_loop.create_task(coro()) + + async def test_parallel_binds(self, event_loop): + """ + Binding a variable causes it to be included in the result of + merge_contextvars. + """ + + coro1_bind = asyncio.Event() + coro2_bind = asyncio.Event() + + bind_contextvars(c=3) + + async def coro1(): + bind_contextvars(a=1) + + coro1_bind.set() + await coro2_bind.wait() + + return merge_contextvars(None, None, {"b": 2}) + + async def coro2(): + bind_contextvars(a=2) + + await coro1_bind.wait() + coro2_bind.set() + + return merge_contextvars(None, None, {"b": 2}) + + coro1_task = event_loop.create_task(coro1()) + coro2_task = event_loop.create_task(coro2()) + + assert {"a": 1, "b": 2, "c": 3} == await coro1_task + assert {"a": 2, "b": 2, "c": 3} == await coro2_task From fe3176fa5c9c6a72d645b373fbf655ca1b440826 Mon Sep 17 00:00:00 2001 From: Elad Namdar Date: Thu, 4 Feb 2021 16:28:40 +0200 Subject: [PATCH 2/5] Reimpl contextvars code The old impl was broken, since python contextvars impl use shallow copy to copy its context, and using a dict as a contextvar type ends up sharing the same dict among different contexts --- CHANGELOG.rst | 2 ++ src/structlog/contextvars.py | 53 ++++++++++++++++++++++-------------- src/structlog/stdlib.py | 8 +++--- 3 files changed, 38 insertions(+), 25 deletions(-) diff --git a/CHANGELOG.rst b/CHANGELOG.rst index c37aa4d4..a6d82a5f 100644 --- a/CHANGELOG.rst +++ b/CHANGELOG.rst @@ -27,6 +27,8 @@ Changes: - ``structlog.threadlocal.wrap_dict()`` now has a correct type annotation. `#290 `_ +- Fixed bug with ``structlog.contextvars`` impl + ---- diff --git a/src/structlog/contextvars.py b/src/structlog/contextvars.py index af58cd4d..bd3f6576 100644 --- a/src/structlog/contextvars.py +++ b/src/structlog/contextvars.py @@ -7,6 +7,8 @@ Python 3.7 as :mod:`contextvars`. .. versionadded:: 20.1.0 +.. versionchanged:: 14.0.0 + Reimplement code without dict See :doc:`contextvars`. """ @@ -15,12 +17,11 @@ from typing import Any, Dict -from .types import Context, EventDict, WrappedLogger +from .types import EventDict, WrappedLogger -_CONTEXT: contextvars.ContextVar[Dict[str, Any]] = contextvars.ContextVar( - "structlog_context" -) +STRUCTLOG_KEY_PREFIX = "structlog_" +_CONTEXT_VARS: Dict[str, contextvars.ContextVar[Any]] = {} def merge_contextvars( @@ -33,11 +34,15 @@ def merge_contextvars( context-local context is included in all log calls. .. versionadded:: 20.1.0 + .. versionchanged:: 20.2.0 See toplevel note """ - ctx = _get_context().copy() - ctx.update(event_dict) + ctx = contextvars.copy_context() - return ctx + for k in ctx: + if k.name.startswith(STRUCTLOG_KEY_PREFIX) and ctx[k] is not Ellipsis: + event_dict.setdefault(k.name[len(STRUCTLOG_KEY_PREFIX):], ctx[k]) # noqa + + return event_dict def clear_contextvars() -> None: @@ -48,9 +53,12 @@ def clear_contextvars() -> None: handling code. .. versionadded:: 20.1.0 + .. versionchanged:: 20.2.0 See toplevel note """ - ctx = _get_context() - ctx.clear() + ctx = contextvars.copy_context() + for k in ctx: + if k.name.startswith(STRUCTLOG_KEY_PREFIX): + k.set(Ellipsis) def bind_contextvars(**kw: Any) -> None: @@ -61,8 +69,17 @@ def bind_contextvars(**kw: Any) -> None: context to be global (context-local). .. versionadded:: 20.1.0 + .. versionchanged:: 20.2.0 See toplevel note """ - _get_context().update(kw) + for k, v in kw.items(): + structlog_k = f"{STRUCTLOG_KEY_PREFIX}{k}" + try: + var = _CONTEXT_VARS[structlog_k] + except KeyError: + var = contextvars.ContextVar(structlog_k, default=Ellipsis) + _CONTEXT_VARS[structlog_k] = var + + var.set(v) def unbind_contextvars(*keys: str) -> None: @@ -73,15 +90,9 @@ def unbind_contextvars(*keys: str) -> None: remove keys from a global (context-local) context. .. versionadded:: 20.1.0 + .. versionchanged:: 20.2.0 See toplevel note """ - ctx = _get_context() - for key in keys: - ctx.pop(key, None) - - -def _get_context() -> Context: - try: - return _CONTEXT.get() - except LookupError: - _CONTEXT.set({}) - return _CONTEXT.get() + for k in keys: + structlog_k = f"{STRUCTLOG_KEY_PREFIX}{k}" + if structlog_k in _CONTEXT_VARS: + _CONTEXT_VARS[structlog_k].set(Ellipsis) diff --git a/src/structlog/stdlib.py b/src/structlog/stdlib.py index 6aa7d17f..dbd5d83b 100644 --- a/src/structlog/stdlib.py +++ b/src/structlog/stdlib.py @@ -34,7 +34,7 @@ try: - from . import contextvars + import contextvars except ImportError: contextvars = None # type: ignore @@ -380,6 +380,7 @@ class AsyncBoundLogger: It is useful to be able to log synchronously occasionally. .. versionadded:: 20.2.0 + .. versionchanged:: 20.2.0 fix _dispatch_to_sync contextvars usage """ __slots__ = ["sync_bl", "_loop"] @@ -474,11 +475,10 @@ async def _dispatch_to_sync( """ Merge contextvars and log using the sync logger in a thread pool. """ - ctx = contextvars._get_context().copy() - ctx.update(kw) + ctx = contextvars.copy_context() await self._loop.run_in_executor( - self._executor, partial(meth, event, *args, **ctx) + self._executor, partial(ctx.run, partial(meth, event, *args, **kw)) ) async def debug(self, event: str, *args: Any, **kw: Any) -> None: From 827d96b086c474a4f79ba876f4acac2a6cfb4702 Mon Sep 17 00:00:00 2001 From: Elad Namdar Date: Thu, 4 Feb 2021 16:31:18 +0200 Subject: [PATCH 3/5] contextvars: fix broken test_nested_async_bind test --- tests/test_contextvars.py | 4 ++-- 1 file changed, 2 insertions(+), 2 deletions(-) diff --git a/tests/test_contextvars.py b/tests/test_contextvars.py index 54257fca..892f7056 100644 --- a/tests/test_contextvars.py +++ b/tests/test_contextvars.py @@ -56,11 +56,11 @@ async def test_nested_async_bind(self, event_loop): async def coro(): bind_contextvars(a=1) - await event_loop.create_task(nested_coro()) - return merge_contextvars(None, None, {"b": 2}) + return await event_loop.create_task(nested_coro()) async def nested_coro(): bind_contextvars(c=3) + return merge_contextvars(None, None, {"b": 2}) assert {"a": 1, "b": 2, "c": 3} == await event_loop.create_task(coro()) From 00bf80d6e2886e12f4223cfc869231b444c16364 Mon Sep 17 00:00:00 2001 From: Elad Namdar Date: Thu, 4 Feb 2021 17:17:08 +0200 Subject: [PATCH 4/5] Fix contextvars docs --- docs/contextvars.rst | 4 ++-- 1 file changed, 2 insertions(+), 2 deletions(-) diff --git a/docs/contextvars.rst b/docs/contextvars.rst index 70e1a3a1..6ed9e28b 100644 --- a/docs/contextvars.rst +++ b/docs/contextvars.rst @@ -50,11 +50,11 @@ The general flow is: >>> # Then use loggers as per normal >>> # (perhaps by using structlog.get_logger() to create them). >>> log.msg("hello") - a=1 b=2 event='hello' + event='hello' a=1 b=2 >>> # Use unbind_contextvars to remove a variable from the context >>> unbind_contextvars("b") >>> log.msg("world") - a=1 event='world' + event='world' a=1 >>> # And when we clear the threadlocal state again, it goes away. >>> clear_contextvars() >>> log.msg("hi there") From e9eed3bb5f4e2e28b1e3352a2ea3effffc781eaa Mon Sep 17 00:00:00 2001 From: "pre-commit-ci[bot]" <66853113+pre-commit-ci[bot]@users.noreply.github.com> Date: Thu, 4 Feb 2021 15:21:00 +0000 Subject: [PATCH 5/5] [pre-commit.ci] auto fixes from pre-commit.com hooks for more information, see https://pre-commit.ci --- src/structlog/contextvars.py | 4 +++- 1 file changed, 3 insertions(+), 1 deletion(-) diff --git a/src/structlog/contextvars.py b/src/structlog/contextvars.py index bd3f6576..6133560c 100644 --- a/src/structlog/contextvars.py +++ b/src/structlog/contextvars.py @@ -40,7 +40,9 @@ def merge_contextvars( for k in ctx: if k.name.startswith(STRUCTLOG_KEY_PREFIX) and ctx[k] is not Ellipsis: - event_dict.setdefault(k.name[len(STRUCTLOG_KEY_PREFIX):], ctx[k]) # noqa + event_dict.setdefault( + k.name[len(STRUCTLOG_KEY_PREFIX) :], ctx[k] + ) # noqa return event_dict