Configure structlog once, so captured logs are the logs that fired - #590
Merged
Conversation
Three tests failed intermittently under the parallel suite and passed when run alone: two in test_agent_subscribers_registration.py and one in test_language_model_seed.py. They were not flaky in the scheduling sense. They were order-dependent, and the order that broke them was any contract test building a second app first. `build_kernel()` calls `configure_logging()` on every `create_app()`, and each call installed a new processor list. A logger already bound and cached against the first list keeps reading it. `structlog.testing.capture_logs()` works by swapping the live config's processors, so a cached logger never sees the swap: the capture comes back empty while the log line still prints. The failing assertion was `len(warnings) == 1` getting 0, with the warning plainly visible in the test's own captured stdout. Caching alone does not cause this; a probe confirmed capture_logs reaches a cached logger fine when the configuration is installed once. It is the second configure that strands the binding. So configure structlog once per process. The stdlib handler is still rebuilt on every call, so log level continues to follow the most recent caller, which is the only part any repeat caller actually wanted. Fixed at the source rather than with a test fixture: a process that builds two apps gets loggers bound to a dead processor list either way, and a fixture would have to be remembered at every new call site. The module's caching note claimed only the first call's level and handler take effect, which was half wrong, and said nothing about capture_logs; it now describes what is true and why the guard is there. Co-Authored-By: Claude Opus 5 <noreply@anthropic.com>
Coverage reportClick to see where and how coverage changed
This report was generated by python-coverage-comment-action |
||||||||||||||||||||||||
This file contains hidden or bidirectional Unicode text that may be interpreted or compiled differently than what appears below. To review, open the file in an editor that reveals hidden Unicode characters.
Learn more about bidirectional Unicode characters
Sign up for free
to join this conversation on GitHub.
Already have an account?
Sign in to comment
Add this suggestion to a batch that can be applied as a single commit.This suggestion is invalid because no changes were made to the code.Suggestions cannot be applied while the pull request is closed.Suggestions cannot be applied while viewing a subset of changes.Only one suggestion per line can be applied in a batch.Add this suggestion to a batch that can be applied as a single commit.Applying suggestions on deleted lines is not supported.You must change the existing code in this line in order to create a valid suggestion.Outdated suggestions cannot be applied.This suggestion has been applied or marked resolved.Suggestions cannot be applied from pending reviews.Suggestions cannot be applied on multi-line comments.Suggestions cannot be applied while the pull request is queued to merge.Suggestion cannot be applied right now. Please check back later.
Three tests failed intermittently under the parallel suite and passed when run alone:
test_agent_subscribers_registration.py(×2) andtest_language_model_seed.py. They were not flaky in the scheduling sense — they were order-dependent, and the order that broke them was any contract test building a second app first.Cause
build_kernel()callsconfigure_logging()on everycreate_app(), and each call installed a new processor list. A logger already bound and cached against the first list keeps reading it.structlog.testing.capture_logs()works by swapping the live config's processors, so a cached logger never sees the swap: the capture comes back empty while the log line still prints to stdout.The failing assertion was
len(squat_warnings) == 1getting0, with the warning plainly visible in the test's own "Captured stdout call" section. A log that fired and a capture that saw nothing.Caching on its own does not cause this. A probe confirmed
capture_logsreaches a cached logger fine when the configuration is installed once; it is the secondconfigure()that strands the binding.Fix
Configure structlog once per process. The stdlib handler is still rebuilt on every call, so log level continues to follow the most recent caller — the only part a repeat caller actually wanted.
Fixed at the source rather than with a test fixture, for two reasons: a process that builds two apps gets loggers bound to a dead processor list regardless of tests, and a fixture would have to be remembered at every new call site.
The module's caching note claimed "only the first call's level/handler take effect", which was half wrong — the stdlib handler was rebuilt every call — and said nothing about the
capture_logsconsequence. It now describes what is true and why the guard is there, so it does not get removed as redundant.Checks
The 18 tests in the combination that previously failed 3 now all pass. Unit tier 12,331 passed. Contract tier 3,350 passed. Architecture 29,732 passed. Ruff and pyright clean.
🤖 Generated with Claude Code