test: stop the webhook traceback fixture from reconfiguring logging process-wide - #10322
Conversation
github-actions
Bot
added
the
group/backend
…rocess-wide The configured_logging fixture called configure_logging(production=False, log_level="DEBUG"). That routine is application startup code: it sets the root log level, replaces the root handler and reconfigures structlog, and undoes none of it. Called per test it left the root logger at DEBUG for the rest of the xdist worker, overriding the WARNING level pytest_configure pins, so every later test in that worker logged a line per Bolt message from the Neo4j driver. Install only what the assertions need instead: extract the filter installation from configure_logging as install_traceback_suppression_filter, call that from the fixture and remove the filter after the yield. The fixture is renamed traceback_suppression_installed to say what it now does. Also record the general rule in the backend testing guidelines and the Python testing agent rules: leave process-global state as you found it, and never call an application startup routine from a test. Co-Authored-By: Claude Opus 5 (1M context) <noreply@anthropic.com>
![cubic-dev-ai[bot]](https://avatars.githubusercontent.com/in/1082092?s=60&v=4){kind=small}
There was a problem hiding this comment.
1 issue found across 5 files
Confidence score: 5/5
backend/tests/component/webhook/test_traceback_suppression.pyno longer covers theconfigure_logging -> install_traceback_suppression_filterwiring path, so an integration regression could go unnoticed even though suppression behavior remains tested; retain or add a focused wiring test.
Prompt for AI agents (unresolved issues)
Check if these issues are valid — if so, understand the root cause of each and fix them. If appropriate, use sub-agents to investigate and fix each issue separately.
<file name="backend/tests/component/webhook/test_traceback_suppression.py">
<violation number="1" location="backend/tests/component/webhook/test_traceback_suppression.py:63">
P3: After this change, no test exercises the `configure_logging -> install_traceback_suppression_filter` wiring path; the fixture now calls the extracted function directly. Traceback suppression behavior is still verified, but a regression that drops the install call from `configure_logging` (log.py:106) would pass the suite silently. Consider adding a small assertion test that calls `configure_logging` and checks a `TracebackSuppressionFilter` is present on the `PREFECT_RUN_LOGGERS`, to keep the production wiring covered.</violation>
</file>
Shadow auto-approve: would not auto-approve because issues were found.
Re-trigger cubic
fa51698 to
d5a093b
Compare
…logging state The three suppression tests pass whether the fixture installs only the filter or calls configure_logging, since that routine installs the same filter — nothing committed distinguished them, so the leak could come back unnoticed. Extract the fixture body into a _traceback_suppression context manager and assert its contract directly: the Prefect run loggers carry exactly the filter it installed while it is open, and both their filter lists and the root log level are back to their previous values once it closes. Driving the context manager rather than probing state from a later test module keeps the guard hermetic — no dependence on collection order or on which xdist worker picks the file up. Co-Authored-By: Claude Opus 5 (1M context) <noreply@anthropic.com>
…n loggers Extracting install_traceback_suppression_filter left the configure_logging call site uncovered: dropping it would keep every traceback suppression test passing, since they install the filter themselves. Assert instead on what importing infrahub.log already did — its module-level configure_logging call is the production wiring — so the call site is covered without a test reconfiguring logging for the rest of the worker. Co-Authored-By: Claude Opus 5 (1M context) <noreply@anthropic.com>
There was a problem hiding this comment.
0 issues found across 1 file (changes from recent commits).
Confidence score: 5/5
- Automated review surfaced no issues in the provided summaries.
- No files require special attention.
Shadow auto-approve: would not auto-approve. Auto-approval blocked by 1 unresolved issue from previous reviews.
Re-trigger cubic
| return {name: list(logging.getLogger(name).filters) for name in PREFECT_RUN_LOGGERS} | ||
|
|
||
|
|
||
| def test_traceback_suppression_leaves_logging_state_unchanged() -> None: |
There was a problem hiding this comment.
this looks like a unit test to me
There was a problem hiding this comment.
Agreed — it needs no database, no Prefect flow run and none of the component fixtures, so it was paying component-suite cost for a pure logging-state assertion.
Moved to backend/tests/unit/test_log.py in 32323eb, next to the other infrahub.log tests. The install/remove cycle it drives moved with it, to backend/tests/helpers/log.py as traceback_suppression(), so the webhook fixture and the guard still share one implementation across the two suites — and any future fixture that installs the filter inherits the guard rather than each suite growing its own copy.
Still bites where it matters, re-verified after the move: revert the cycle to configure_logging and the guard fails on the extra filter that routine leaves behind; drop install_traceback_suppression_filter() from configure_logging and test_startup_installs_the_filter_on_the_prefect_run_loggers fails with [] == ['prefect.flow_runs', 'prefect.task_runs'].
One thing the move does not carry over, worth stating plainly: the guard now asserts the contract of the shared helper, not of the fixture literally. If someone rewrote the fixture to stop using the helper and call configure_logging directly, the guard would keep passing — the written-down rule in dev/guidelines/backend/testing.md is what covers that case, not a test.
| def _traceback_suppression() -> Iterator[TracebackSuppressionFilter]: | ||
| """Register the traceback filter on the Prefect run loggers, as production startup does, then remove it. | ||
|
|
||
| Only the filter is installed, not the whole of configure_logging: that startup routine also raises |
There was a problem hiding this comment.
I don't think docstrings should describe what they are NOT doing. I think you can remove all or almost all of this docstring under the first line
There was a problem hiding this comment.
Fair — and it applied to two docstrings, not one.
That whole paragraph is gone: the context manager moved to backend/tests/helpers/log.py in 32323eb keeping only its first line ("Register the traceback filter on the Prefect run loggers, as production startup does, then remove it"), and the fixture that wraps it now needs no docstring at all. The rationale it was carrying — why install the filter alone instead of calling configure_logging — belongs in dev/guidelines/backend/testing.md, which is where this PR puts it; the guideline now points at the helper as the example.
Applied the same cut in 8ca9a21 to test_startup_installs_the_filter_on_the_prefect_run_loggers, which had the same shape: its second paragraph explained why it doesn't call configure_logging. First line kept, since that one says what the test asserts.
A docstring should say what the test asserts, not what it deliberately does not do. The paragraph explaining why the test reads the state left by the import rather than calling configure_logging again is a note on a choice already made; the rule it follows is written down in the backend testing guidelines. The first line still explains why asserting on import-time state is the wiring assertion, which is the part a reader needs. Co-Authored-By: Claude Opus 5 (1M context) <noreply@anthropic.com>
test_traceback_suppression_leaves_logging_state_unchanged drives a context manager and reads logging state — it needs no database, no Prefect flow run and none of the component suite's fixtures, so it belongs next to the other infrahub.log tests in the unit suite. Move the install/remove cycle it drives to tests/helpers/log.py as traceback_suppression, so the webhook fixture and the guard share one implementation across suites and any future fixture that installs the filter inherits the guard. Its docstring keeps the line that says what it does; the paragraph on why it installs the filter alone rather than calling configure_logging is the rule the testing guidelines now carry, which the guidelines point at the helper for. Co-Authored-By: Claude Opus 5 (1M context) <noreply@anthropic.com>
d579fb9 to
32323eb
Compare
3 participants
Why
backend/tests/component/webhook/test_traceback_suppression.pyinstalled its Prefect traceback filter by calling application startup code:configure_loggingowns the process when it runs — it sets the root log level, swaps the root handler and reconfigures structlog — and, being startup code, undoes none of it. Called from a fixture it left the root logger atDEBUGfor the rest of the xdist worker, overriding theWARNINGlevelpytest_configurepins. Every test that ran after it in that worker then logged one line per Bolt message from the Neo4j driver.The enterprise CI job that surfaced it (infrahub-private run 32120976740) produced 185,123 of 193,263 log lines as
neo4j.io/neo4j.poolDEBUG output, starting at the first test of this file and continuing on that worker for the next 37 minutes. The three tests that failed — allFailed: Timeout >300.0s, all ongw1, the poisoned worker — ran the suite past its 1800s session timeout.Goal: the fixture leaves logging exactly as it found it, and the rule is written down so the next fixture doesn't repeat it.
Non-goals: no change to production logging behaviour, and no attempt to pin
neo4j*/httpcorelevels inconfigure_logging(see below).Targets
stable. The three Python files this touches are byte-identical onstableanddevelop,backend/tests/helpers/log.pyis new on both, and the two docs additions land outside the one region where those files differ between the branches — so the change applies unchanged wherever it flows next.What changed
backend/tests/helpers/log.py(new) —traceback_suppression(), a context manager that installs the filter on the Prefect run loggers and removes it again. One implementation shared by the webhook fixture and the regression guard below, so a future fixture that installs the filter inherits the guard.backend/tests/component/webhook/test_traceback_suppression.py— the fixture now wraps that context manager instead of callingconfigure_logging. Renamedconfigured_logging→traceback_suppression_installed, since that is what it does now.backend/infrahub/log.py— the filter installation is extracted fromconfigure_loggingintoinstall_traceback_suppression_filter(), so production startup and the test share one implementation and the test still exercises the real registry (suppress_traceback_in_logsopt-in) rather than a hand-built set. Pure extraction — same operations, same order, same call site.backend/tests/unit/test_log.py— two guards:test_traceback_suppression_leaves_logging_state_unchanged(the install/remove cycle restores the run loggers' filters and the root level) andtest_startup_installs_the_filter_on_the_prefect_run_loggers(startup wiring is still in place).dev/guidelines/backend/testing.md— new section "Leave process-global state as you found it": what counts as global state, and never call an application startup routine from a test..agents/rules/testing-python.md— the same rule in short form for coding agents.What stayed the same:
configure_logging's behaviour, the three suppression tests' assertions, and the traceback suppression contract.How to review
Start with the test file — the fixture is the fix. Then
log.pyto confirm the extraction is behaviour-preserving.The judgement call worth scrutiny: the fixture no longer calls
configure_logging, so that wiring is covered by the startup assertion intest_log.pyinstead. The alternative — keep callingconfigure_loggingand unwind it in teardown — is worse: restoringroot.handlerswholesale re-attaches pytest's own capture handler (LogCaptureHandlersubclassesStreamHandler, soconfigure_loggingremoves it too), which would leak records into a stale handler for the rest of the session.How to test
Two committed guards, both hermetic — no dependence on collection order or on which xdist worker takes the file, and both live in the unit suite because neither needs a database or a Prefect flow run:
test_traceback_suppression_leaves_logging_state_unchangeddrives thetraceback_suppression()context manager the fixture wraps: while it is open the Prefect run loggers carry exactly the filter it installed; once it closes their filter lists and the root log level are back to their previous values. Fails if that cycle reverts toconfigure_logging(verified: the assertion reports the extra filter that routine leaves behind).test_startup_installs_the_filter_on_the_prefect_run_loggersasserts the wiringconfigure_loggingperforms at import, so dropping itsinstall_traceback_suppression_filter()call fails a test (verified:[] == ['prefect.flow_runs', 'prefect.task_runs']). Nothing is reconfigured to check it.Before/after on the original leak, measured with a throwaway probe module collected after the suppression tests in the same worker:
neo4j.ioDEBUG recordDEBUG[4, 4]WARNING[1, 1]Also run:
backend/tests/unit/log_forwarding(4 passed),ruff format --check backend/,ruff check backend/tests/,mypyon the three changed test files,invoke docs.lint(0 errors).Impact & rollout
configure_logging's public behaviour is unchanged.Follow-up, not in this PR
configure_loggingmuteshttpxexplicitly but leavesneo4j,neo4j.io,neo4j.poolandhttpcoreat the root level, which is why a single leakedDEBUGwas this loud. Worth deciding separately whether those should be pinned. Two smaller things noticed nearby: the handler-removal loop inconfigure_loggingmutatesroot_logger.handlerswhile iterating it (so it can skip a handler), and the enterprisepyproject.toml's[tool.pytest_env]omitsINFRAHUB_PRODUCTION = false, which community sets — that is why the enterprise job renders JSON logs where community renders console.Checklist
🤖 Generated with Claude Code