Disable Logger Caching

[ghickman]

structlog.configure() sets cache_logger_on_first_use=True by default.

With structlog==20.1.0 and pyest-structlog==0.2 I have multiple tests calling the same function and only the first one sees any logs in the event list. I think this can be fixed with configure(…, cache_logger_on_first_use=False) when constructing the log fixture.

[wimglenn]

Hi @ghickman , can you make a reproducible example please? I've tried with structlog==20.1.0 and pytest-structlog==0.2 on Linux and can not reproduce this issue.

[b0g3r]

First of all: thank you for your awesome work, now I have a very convenient way to test my log system 🚀

But I faced up with same problem about cache_logger_on_first_use=True

[b0g3r]

Example: https://github.com/b0g3r/pytest-structlog-issue-example

with cache_logger_on_first_use:

without cache_logger_on_first_use

[b0g3r]

@ghickman Possible workaround:

@pytest.fixture(autouse=True)
def turn_off_structlog_caching():
    structlog.configure(cache_logger_on_first_use=False)

[ghickman]

Thanks @b0g3r! That's effectively what I ended up doing too:

def log_output():
    return LogCapture()

@pytest.fixture(autouse=True)
def fixture_configure_structlog(log_output):
    structlog.configure(processors=[log_output], cache_logger_on_first_use=False)

@wimglenn – apologies for not supplying a reproducible example yet, @b0g3r's example is very close to mine. I'll try to get you one next week (deadlines!) to confirm my issue is the same.

[wimglenn]

OK, I think I understand the issue now. It's a combination of two things, configuring logging at import time and enabling structlog's caching. That aspect of the global cache is actually mentioned in structlog docs https://www.structlog.org/en/stable/performance.html

This has the only drawback is that later calls on configure() don’t have any effect on already cached loggers – that shouldn’t matter outside of testing though.

Maybe it should also be mentioned that configuring the logging at import time in module global scope is somewhat an anti-pattern (see the note at the bottom of where to configure), it's usually better to configure after entering the main entry point in order for imports not to cause side-effects.

However, since there is no disadvantage for pytest-structlog to also handle that case, I've released v0.3 which should cover this - please let me know if upgrading fixes the problem.

Cheers!

[skoot]

Version 0.3 breaks our tests. We use django and configure structlog in our settings.py file.

structlog.configure(
    processors=[
        structlog.stdlib.filter_by_level,
        structlog.processors.TimeStamper(),
        structlog.stdlib.add_logger_name,
        structlog.stdlib.add_log_level,
        structlog.stdlib.PositionalArgumentsFormatter(),
        structlog.processors.StackInfoRenderer(),
        structlog.processors.format_exc_info,
        structlog.processors.UnicodeDecoder(),
        structlog.processors.ExceptionPrettyPrinter(),
        structlog.stdlib.ProcessorFormatter.wrap_for_formatter,
    ],
    context_class=structlog.threadlocal.wrap_dict(dict),
    logger_factory=structlog.stdlib.LoggerFactory(),
    wrapper_class=structlog.stdlib.BoundLogger,
    cache_logger_on_first_use=True,
)

When we run the tests we now get this error:

logger = <PrintLogger(file=<_io.TextIOWrapper name="<_io.FileIO name=8 mode='rb+' closefd=True>" mode='r+' encoding='utf-8'>)>
name = 'error'
event_dict = {'client': 'test_client', 'duration': 0.051772, 'event': 'campaign-list.create', 'headers': {'Authorization': '***', 'Content-Length': '185', 'Content-Type': 'application/json; charset=None', 'Cookie': ''}, ...}

    def filter_by_level(logger, name, event_dict):
        """
        Check whether logging is configured to accept messages from this log level.

        Should be the first processor if stdlib's filtering by level is used so
        possibly expensive processors like exception formatters are avoided in the
        first place.

        >>> import logging
        >>> from structlog.stdlib import filter_by_level
        >>> logging.basicConfig(level=logging.WARN)
        >>> logger = logging.getLogger()
        >>> filter_by_level(logger, 'warn', {})
        {}
        >>> filter_by_level(logger, 'debug', {})
        Traceback (most recent call last):
        ...
        DropEvent
        """
>       if logger.isEnabledFor(_NAME_TO_LEVEL[name]):
E       AttributeError: 'PrintLogger' object has no attribute 'isEnabledFor'