capture_logs doesn't affect already initalized BoundLoggers

[fabianbuechler]

Hey, I found an issue with using structlog.testing.capture_logs that might be intentional, but tripped me up while testing.
I have a workaround / patch that I could submit as PR, but wanted to ask first to clarify whether the behavior is intentional.

When using capture_logs the processors of any existing, already initialized BoundLoggers aren't updated to use LogCapture and their logs are thus not captured.

I've written a bit of code to clarify what I mean:

from contextlib import contextmanager
from typing import Iterator, List

import structlog
from structlog.dev import ConsoleRenderer
from structlog.processors import add_log_level
from structlog.testing import capture_logs
from structlog.types import EventDict

processors = [add_log_level, ConsoleRenderer()]
structlog.configure(processors=processors)

# processors list is stored by reference
structlog.get_config()['processors'] is processors

logger = structlog.get_logger('log1')

# initialize BoundLogger by using the logger
logger = logger.bind(foo='bar')
logger.info("baz")

# for now, the logger's processors are _identical_ to the configuration's
assert logger._processors is processors

with capture_logs() as events:
    # the logger's processors are still _identical_ to the original processors list
    assert logger._processors is processors
    assert len(processors) == 2
    # while the configuration's list has been exchanged
    assert structlog.get_config()['processors'] is not processors
    assert len(structlog.get_config()['processors']) == 1

    # thus logs won't be captured
    logger.info("test")
    assert len(events) == 0


@contextmanager
def capture_logs_by_ref() -> Iterator[List[EventDict]]:
    """Modify `capture_logs` to keep reference to `processors` list intact,
    in order to also modify bound loggers which get the list assigned by reference.

    """
    cap = structlog.testing.LogCapture()
    # Modify `_Configuration.default_processors` set via `configure` but always keep
    # the list instance intact to not break references held by bound loggers.
    processors = structlog.get_config()["processors"]
    old_processors = processors[:]  # copy original processors
    try:
        processors.clear()  # clear processors list
        processors.append(cap)  # append the LogCapture processor for testing
        structlog.configure(processors=processors)
        yield cap.entries
    finally:
        processors.clear()  # remove LogCapture
        processors.extend(old_processors)  # restore original processors
        structlog.configure(processors=processors)


# let's try again
structlog.configure(processors=processors)
# processors list is stored by reference
structlog.get_config()['processors'] is processors

logger = structlog.get_logger('log2')

# initialize BoundLogger by using the logger
logger = logger.bind(foo='bar')
logger.info("baz")

# the logger's processors are still _identical_ to the configuration's
assert logger._processors is processors

with capture_logs_by_ref() as events:
    # the logger's processors are still _identical_ to the original processors list
    assert logger._processors is processors
    assert structlog.get_config()['processors'] is processors
    # but it contains only the LogCapture processor
    assert len(processors) == 1

    logger.info("test")
    assert events[0]['event'] == "test"

# and after exiting the capture_logs context, the original processors are restored
assert len(processors) == 2

That basically already contains my approach for a fix: keeping the _Configuration.processors list intact and only modify its contents so that the BoundLoggers which get the list passed by reference are affected by the changes.

Let me know if you agree that this change would be benefitial, then I can prepare a PR with tests.

And of course: thanks for building structlog - it's amazing!

[hynek]

May I ask how you ran into that problem? Because it's rather uncommon, I think, to much around with already bound loggers?

Your approach would certainly have thread-wide side-effects, but I suspect that would be even desired?

Thoughts @rgalanakis?

thanks for building structlog - it's amazing!

Thank you, I'm trying! 😅

[fabianbuechler]

Totally possible that I got a concept wrong.
What I have is a module with a module logger:

import structlog

logger = structlog.get_logger(__name__)

And in that module a class that binds a local logger on __init__ and logs something right away.

class Something:
    def __init__(self):
        self.logger = logger.bind(some="thing")

    def a_method(self):
        self.logger.info("doing something")

When I use capture_logs in a test of Something.a_method, it won't capture the logs as self.logger is already initialized.

@pytest.fixture
def something() -> Something:
    return Something()


def test_something_a_method(something: Something):
    with capture_logs() as events:
        something.a_method()

    assert events[0]['event'] == "doing something"  # fail

Is there a better way to do something like this?
Note: I am using contextvars to bind some global context already. The Something class however should add some more context only to its own log messages.

[fabianbuechler]

Your approach would certainly have thread-wide side-effects, but I suspect that would be even desired?

Well, yes. In my case that would be desired and imho I'd expect a testing utility like capture_logs to apply to all loggers that exist, bound or not. But I'm uncertain to whether that fits with the general philosophy of structlog - that's why I asked here instead of filing a PR.

[rgalanakis]

I would say that not capturing already-created loggers is an oversight in what I originally wrote. In similar logging libraries that I have used more extensively, in, say, Ruby, I expect it to capture all logs. In languages that are quite different and have no TLS (like Go) I would not expect global modifications. So I agree with @fabianbuechler here.

[hynek]

Oh I agree with the idea too, I just wonder if there’s a conscious reason why you didn’t choose the reference approach. If there’s some edge cases I can’t think of right now or if something broke in weird ways. :)

[rgalanakis]

Unfamiliarity with structlog's internal implementation I suppose.

[fabianbuechler]

@hynek thanks for agreeing to the approach - I've made this a PR #412 and would be happy about a review.

[hynek]

@rgalanakis thank you for coming back to us and thank you again so much for adding this to structlog. I use it in all my projects nowadays!