Merge branch 'eladnam-fix-context-vars'

CHANGELOG.rst

@@ -26,6 +26,8 @@ Changes:
 
 - ``structlog.threadlocal.wrap_dict()`` now has a correct type annotation.
   `#290 <https://github.com/hynek/structlog/pull/290>`_
+- Fix isolation in ``structlog.contextvars``.
+  `#302 <https://github.com/hynek/structlog/pull/302>`_
 
 
 ----

docs/contextvars.rst

@@ -46,15 +46,16 @@ The general flow is:
    >>> # middleware), clear the threadlocal context and bind some common
    >>> # values:
    >>> clear_contextvars()
-   >>> bind_contextvars(a=1, b=2)
+   >>> bind_contextvars(a=1)
+   >>> bind_contextvars(b=2)
    >>> # 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")

src/structlog/contextvars.py

@@ -7,6 +7,9 @@
 Python 3.7 as :mod:`contextvars`.
 
 .. versionadded:: 20.1.0
+.. versionchanged:: 21.1.0
+   Reimplemented without using a single dict as context carrier for improved
+   isolation. Every key-value pair is a separate `contextvars.ContextVar` now.
 
 See :doc:`contextvars`.
 """
@@ -15,12 +18,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 +35,17 @@ def merge_contextvars(
     context-local context is included in all log calls.
 
     .. versionadded:: 20.1.0
+    .. versionchanged:: 21.1.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 +56,12 @@ def clear_contextvars() -> None:
     handling code.
 
     .. versionadded:: 20.1.0
+    .. versionchanged:: 21.1.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 +72,17 @@ def bind_contextvars(**kw: Any) -> None:
     context to be global (context-local).
 
     .. versionadded:: 20.1.0
+    .. versionchanged:: 21.1.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 +93,9 @@ def unbind_contextvars(*keys: str) -> None:
     remove keys from a global (context-local) context.
 
     .. versionadded:: 20.1.0
+    .. versionchanged:: 21.1.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)

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:

tests/test_contextvars.py

@@ -2,6 +2,9 @@
 # 2.0, and the MIT License.  See the LICENSE file in the root of this
 # repository for complete details.
 
+import asyncio
+import secrets
+
 import pytest
 
 from structlog.contextvars import (
@@ -54,11 +57,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())
 
@@ -110,7 +113,7 @@ async def coro():
 
         assert {} == await event_loop.create_task(coro())
 
-    async def test_undbind(self, event_loop):
+    async def test_unbind(self, event_loop):
         """
         Unbinding a previously bound variable causes it to be removed from the
         result of merge_contextvars.
@@ -123,13 +126,49 @@ async def coro():
 
         assert {"b": 2} == await event_loop.create_task(coro())
 
-    async def test_undbind_not_bound(self, event_loop):
+    async def test_unbind_not_bound(self, event_loop):
         """
         Unbinding a not bound variable causes doesn't raise an exception.
         """
 
         async def coro():
-            unbind_contextvars("a")
+            # Since unbinding means "setting to Ellipsis", we have to make
+            # some effort to ensure that the ContextVar never existed.
+            unbind_contextvars("a" + secrets.token_hex())
+
             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

tox.ini

@@ -1,3 +1,6 @@
+[flake8]
+ignore = E203,W503,W504
+
 # Keep docs in sync with docs env and .readthedocs.yml.
 [gh-actions]
 python =