wimglenn / pytest-structlog

Structured logging assertions
MIT License
54 stars 6 forks source link

Context Variables are not being captured by pytest-structlog #20

Closed zeerooth closed 1 year ago

zeerooth commented 1 year ago
import structlog
import pytest

logger = structlog.get_logger()

@pytest.fixture(autouse=True)
def configure_logs_for_tests():
    structlog.configure(
        processors=[
            structlog.contextvars.merge_contextvars,
            structlog.stdlib.filter_by_level,
            structlog.stdlib.ProcessorFormatter.wrap_for_formatter,
        ],
        wrapper_class=structlog.stdlib.BoundLogger,
        logger_factory=structlog.stdlib.LoggerFactory(),
        context_class=dict,
    )

def test_contextvar(log):
    structlog.contextvars.clear_contextvars()
    logger.info("log1", log1var="value")
    structlog.contextvars.bind_contextvars(contextvar="value")
    logger.info("log2", log2var="value")
    assert log.has("log2", log2var="value", contextvar="value")

Run pytest:

log = <pytest_structlog.StructuredLogCapture object at 0x7f38c191ce80>

    def test_contextvar(log):
        structlog.contextvars.clear_contextvars()
        logger.info("log1", log1var="value")
        structlog.contextvars.bind_contextvars(contextvar="value")
        logger.info("log2", log2var="value")
>       assert log.has("log2", log2var="value", contextvar="value")
E       AssertionError: assert False
E        +  where False = <bound method StructuredLogCapture.has of <pytest_structlog.StructuredLogCapture object at 0x7f38c191ce80>>('log2', log2var='value', contextvar='value')
E        +    where <bound method StructuredLogCapture.has of <pytest_structlog.StructuredLogCapture object at 0x7f38c191ce80>> = <pytest_structlog.StructuredLogCapture object at 0x7f38c191ce80>.has

tests/test_contextvar.py:27: AssertionError
---Captured structlog call ---
{'log1var': 'value', 'event': 'log1', 'level': 'info'}
{'log2var': 'value', 'event': 'log2', 'level': 'info'}

But when I change the test to no longer use the log fixture:

import structlog
import pytest

logger = structlog.get_logger()

@pytest.fixture(autouse=True)
def configure_logs_for_tests():
    structlog.configure(
        processors=[
            structlog.contextvars.merge_contextvars,
            structlog.stdlib.filter_by_level,
            structlog.stdlib.ProcessorFormatter.wrap_for_formatter,
        ],
        wrapper_class=structlog.stdlib.BoundLogger,
        logger_factory=structlog.stdlib.LoggerFactory(),
        context_class=dict,
    )

def test_contextvar():
    structlog.contextvars.clear_contextvars()
    logger.info("log1", log1var="value")
    structlog.contextvars.bind_contextvars(contextvar="value")
    logger.info("log2", log2var="value")
    assert False

And run the tests with pytest --log-cli-level=DEBUG, this is the output to stdout:

INFO     tests.test_contextvar:test_contextvar.py:24 {'log1var': 'value', 'event': 'log1'}
INFO     tests.test_contextvar:test_contextvar.py:26 {'log2var': 'value', 'event': 'log2', 'contextvar': 'value'}
wimglenn commented 1 year ago

@Zeerooth This should be fixed in v0.6. Thanks for the report

zeerooth commented 1 year ago

Yup, I confirm it works now!

Thank you @wimglenn for taking care of this and maintaining the repo :)