merge_contextvars raises a KeyError #591
Description
During a recent update of structlog from version 20.2.0 to 21.1.0 in a large Flask + Gunicorn web app, we encountered a new error coming from contextvars.merge_contextvars:
builtins.KeyError: <ContextVar name='structlog_http.x-real-ip' default=Ellipsis at 0x7fe6b387c3b0>
Traceback (most recent call last):
...
File "/api/app.py", line 148, in response_after_request
log.debug("api_hit", **{"http.status_code": response.status_code})
File "/usr/local/lib/python3.8/site-packages/structlog/stdlib.py", line 142, in debug
return self._proxy_to_logger("debug", event, *args, **kw)
File "/usr/local/lib/python3.8/site-packages/structlog/stdlib.py", line 213, in _proxy_to_logger
return super()._proxy_to_logger(method_name, event=event, **event_kw)
File "/usr/local/lib/python3.8/site-packages/structlog/_base.py", line 203, in _proxy_to_logger
args, kw = self._process_event(method_name, event, event_kw)
File "/usr/local/lib/python3.8/site-packages/structlog/_base.py", line 160, in _process_event
event_dict = proc(self._logger, method_name, event_dict)
File "/usr/local/lib/python3.8/site-packages/structlog/contextvars.py", line 81, in merge_contextvars
if k.name.startswith(STRUCTLOG_KEY_PREFIX) and ctx[k] is not Ellipsis:
KeyError: <ContextVar name='structlog_http.x-real-ip' default=Ellipsis at 0x7fe6b387c3b0>
The same KeyError can be observed in our application for contextvars with different names beyond structlog_http.x-real-ip.
Updating to the latest version of structlog, v23.3.0 does not seem to have resolved the issue.
Further inspection suggests that #302 may have introduced a race condition to the merge_contextvars function when the implementation changed:
def merge_contextvars(
logger: WrappedLogger, method_name: str, event_dict: Dict[str, Any]
) -> Context:
"""
A processor that merges in a global (context-local) context.
Use this as your first processor in :func:`structlog.configure` to ensure
context-local context is included in all log calls.
.. versionadded:: 20.1.0
"""
ctx = _get_context().copy()
ctx.update(event_dict)
return ctxdef merge_contextvars(
logger: WrappedLogger, method_name: str, event_dict: EventDict
) -> EventDict:
"""
A processor that merges in a global (context-local) context.
Use this as your first processor in :func:`structlog.configure` to ensure
context-local context is included in all log calls.
.. versionadded:: 20.1.0
.. versionchanged:: 21.1.0 See toplevel note.
"""
ctx = contextvars.copy_context()
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])
return event_dictIt appears possible for ctx[k] to raise a KeyError despite the fact that k is defined as for k in ctx:
We have temporarily reverted the structlog update, but would love to help develop a fix for this issue upstream. Please let us know if/how we can help with further investigation.