Fix context vars

[eladnam]

Pull Request Check List

This is just a friendly reminder about the most common mistakes. Please make sure that you tick all boxes. But please read our contribution guide at least once, it will save you unnecessary review cycles!

If an item doesn't apply to your pull request, check it anyway to make it apparent that there's nothing left to do.

• Added tests for changed code.
• Updated documentation for changed code.
  • New functions/classes have to be added to docs/api.rst by hand.
  • Changed/added classes/methods/functions have appropriate versionadded, versionchanged, or deprecated directives. Find the appropriate next version in our __init__.py file.
• Documentation in .rst files is written using semantic newlines.
• Changes (and possible deprecations) are documented in the changelog.

If you have any questions to any of the points above, just submit and ask! This checklist is here to help you, not to deter you from contributing!

[eladnam]

PyCQA/pycodestyle#373
:(

[hynek]

Hi Elad, would you mind elaborating what you're doing here? 😇

[eladnam]

Hi Elad, would you mind elaborating what you're doing here?

Of course, as I've explained in the commit message, there was a bug with old usage of contextvars. i've added a test to expose this bug in e191df7.

i think that the source of the bug is saving a dict in the contextvar, while contextvar only doing a shallow copy of its var. (so we actually shared the same dict across different contexts ).

[hynek]

Thanks! Until I have the time to review this, please add a

[flake8]
ignore = E203

to the top of tox.ini. That should fix the linter if its the only error.

[csernazs]

Hi,

My code is also affected by this bug. In my case the root cause of the problem was that when the the first log message was logged, it happened from outside asyncio. In such case, merge_contextvars creates the context var implicitly (via get_context), so the contextvar is bound to thread-local, not to async-local. Later on, when the async tasks are started, they structlog re-uses this contextvar but as it is bound to thread and not to the task itself there will be a crosstalk between the tasks as these are running in the same thread.

When I removed all "before async" logging, which means that the first log message was logged from an async task, the issue disappeared.

I made a pretty simple example (not as good as the test in the PR but can be used as a standalone proof if it helps):

import structlog
import structlog.contextvars

import asyncio

structlog.configure(
    processors=[
        structlog.contextvars.merge_contextvars,
        structlog.dev.ConsoleRenderer()
    ]
)

logger = structlog.get_logger("foo")


async def bind_and_log(value, sleeptime):
    logger.info("before bind", task=asyncio.current_task().get_name())
    structlog.contextvars.bind_contextvars(a=value)
    logger.info("after bind", task=asyncio.current_task().get_name())
    await asyncio.sleep(sleeptime)
    logger.info("before unbind", task=asyncio.current_task().get_name())
    structlog.contextvars.unbind_contextvars("a")


async def async_main():
    tasks = (bind_and_log(1, 1), bind_and_log(2, 2))
    await asyncio.gather(*tasks)


def main():
    # if the following line is commented out or removed
    # it works as expected
    logger.info("Start")
    asyncio.run(async_main())


if __name__ == "__main__":
    main()

When logging the "Start" message, the contextvar is created outside async and there is a crosstalk between the tasks. If this line is removed, the code will work as expected, each task will have its own separated value.

[hynek]

Does the PR fix it for you?

[csernazs]

Yes, I confirm that this PR fixes my issue.

[hynek]

Thank you so much to both of you! This was a very subtle bug and it would've probably taken me forever to debug & fix!

[romulocollopy]

Hello, I'm new using the library and got stuck in a use case in my fastapi application that I am not sure if is intended behaviour o a bug. Could you clarify if calling the merge_contextvars should ignore he binds happening in the async functions?

ex: https://github.com/hynek/structlog/pull/595/files

[hynek]

The is explained in the warning block at the beginning of https://www.structlog.org/en/stable/contextvars.html – sadly there's no way for us to merge both because we don't have access to both.

[romulocollopy]

Got it, thanks! What caught my attention is that the current implementation creates the contextvar inside a function, while python's documentation states that:

Important: Context Variables should be created at the top module level and never in closures. Context objects hold strong references to context variables which prevents context variables from being properly garbage collected.
https://docs.python.org/3/library/contextvars.html#contextvars.ContextVar