Skip to content

Configure structlog once, so captured logs are the logs that fired - #590

Merged
xmap merged 1 commit into
mainfrom
claude/structlog-configure-once
Jul 29, 2026
Merged

Configure structlog once, so captured logs are the logs that fired#590
xmap merged 1 commit into
mainfrom
claude/structlog-configure-once

Conversation

@xmap

@xmap xmap commented Jul 29, 2026

Copy link
Copy Markdown
Owner

Three tests failed intermittently under the parallel suite and passed when run alone: test_agent_subscribers_registration.py (×2) and 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.

Cause

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 to stdout.

The failing assertion was len(squat_warnings) == 1 getting 0, 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_logs reaches a cached logger fine when the configuration is installed once; it is the second configure() 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_logs consequence. 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

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>
@github-actions

Copy link
Copy Markdown

Coverage report

Click to see where and how coverage changed

FileStatementsMissingCoverageCoverage
(new stmts)
Lines missing
  apps/api/src/cora/infrastructure
  logging.py
Project Total  

This report was generated by python-coverage-comment-action

@xmap
xmap merged commit 57ad541 into main Jul 29, 2026
16 checks passed
@xmap
xmap deleted the claude/structlog-configure-once branch July 29, 2026 15:37
Sign up for free to join this conversation on GitHub. Already have an account? Sign in to comment

Labels

None yet

Projects

None yet

Development

Successfully merging this pull request may close these issues.

1 participant