marvin8/dujiangyan

Watch

Fork 0

Flaky test: startup log-redaction test fails intermittently depending on worker test order #110

New issue

Closed

opened 2026-09-08 03:02:08 +00:00 by agent-pi · 2 comments

agent-pi commented

2026-09-08 03:02:08 +00:00

Collaborator

Symptom

tests/test_startup.py — LogStartupInfo::does_not_log_db_password ("DB password must be redacted in debug startup log output") fails intermittently in full-suite runs. The failure shows the captured log output as empty: expected contains '***' — received '', while the first assertion ("not contain secret") passes trivially because there is no output at all.

Reproduction / frequency

Never fails when the file runs alone (5/5 solo passes).
Fails roughly 1 in ~6 full-suite runs, including on a clean checkout with no local changes (verified while working on PRs #107/#109).
Tryke distributes tests across a worker pool, so which tests share a worker — and in what order — varies between runs, which matches the non-determinism.

Impact

Random red CI runs and noisy local verification. The production behaviour under test (credential redaction) is fine; the test's capture setup is order-dependent.

## Symptom `tests/test_startup.py` — `LogStartupInfo::does_not_log_db_password` ("DB password must be redacted in debug startup log output") fails intermittently in full-suite runs. The failure shows the captured log output as **empty**: `expected contains '***' — received ''`, while the first assertion ("not contain secret") passes trivially because there is no output at all. ## Reproduction / frequency - Never fails when the file runs alone (5/5 solo passes). - Fails roughly 1 in ~6 full-suite runs, including on a clean checkout with no local changes (verified while working on PRs #107/#109). - Tryke distributes tests across a worker pool, so which tests share a worker — and in what order — varies between runs, which matches the non-determinism. ## Impact Random red CI runs and noisy local verification. The production behaviour under test (credential redaction) is fine; the test's capture setup is order-dependent.

agent-pi commented

2026-09-08 03:02:22 +00:00

Author

Collaborator

Findings from chasing this during PR #109 (where the same root cause also produced a real CI failure for new tests):

The test attaches a StreamHandler to logging.getLogger("fenliu.__main__") and calls log_startup_info, saving/restoring the logger level around the call. Whether records are emitted, however, depends on the logger's effective level, which inherits process-global logging state mutated by whichever tests ran earlier on the same tryke worker. When a previous test leaves the effective level above DEBUG/INFO, the handler receives zero records and the assertion on captured output fails.
Proof from the same session: new log-capture tests in tests/test_ai_classification.py (added for #106) failed in CI on the 3.13 and 3.14 workers only, with zero records collected — and passed deterministically once the tests pinned the logger's own level (setLevel(WARNING) + restore in finally) for the capture window.
Likely state-mutators: tests that run fenliu.logging.setup_logging or otherwise reconfigure root/package loggers (startup / main / entrypoint test areas).

Plan of attack (sketch)

Add a small hermetic helper (or tryke fixture) for log-capture tests: pin the target logger's level, attach the handler, and restore both level and handler set in finally.
Apply it to test_startup.py and audit the other log-capture sites (test_main._capture_log users, test_entrypoint) for the same hole.
Verify: run the full suite ~10 times (varying worker counts if possible) and confirm zero flakes.

Findings from chasing this during PR #109 (where the same root cause also produced a real CI failure for new tests): - The test attaches a `StreamHandler` to `logging.getLogger("fenliu.__main__")` and calls `log_startup_info`, saving/restoring the logger level around the call. Whether records are emitted, however, depends on the logger's **effective** level, which inherits process-global logging state mutated by whichever tests ran earlier on the same tryke worker. When a previous test leaves the effective level above DEBUG/INFO, the handler receives zero records and the assertion on captured output fails. - Proof from the same session: new log-capture tests in `tests/test_ai_classification.py` (added for #106) failed in CI on the 3.13 and 3.14 workers only, with zero records collected — and passed deterministically once the tests pinned the logger's own level (`setLevel(WARNING)` + restore in `finally`) for the capture window. - Likely state-mutators: tests that run `fenliu.logging.setup_logging` or otherwise reconfigure root/package loggers (startup / main / entrypoint test areas). ## Plan of attack (sketch) 1. Add a small hermetic helper (or tryke fixture) for log-capture tests: pin the target logger's level, attach the handler, and restore both level and handler set in `finally`. 2. Apply it to `test_startup.py` and audit the other log-capture sites (`test_main._capture_log` users, `test_entrypoint`) for the same hole. 3. Verify: run the full suite ~10 times (varying worker counts if possible) and confirm zero flakes.

agent-pi referenced this issue from a commit

2026-09-08 04:23:40 +00:00

:bug: (fenliu) stop alembic fileConfig disabling existing loggers

agent-pi referenced this issue from a pull request that will close it,

2026-09-08 04:23:56 +00:00

Follow redirects when downloading AI vision images #107

agent-pi commented

2026-09-08 04:24:12 +00:00

Author

Collaborator

Root cause found and fixed on PR #107 (commit ea42a15).

Mechanism: alembic/env.py called fileConfig(config.config_file_name) with the stdlib default disable_existing_loggers=True. test_database.py runs real migrations via alembic.command.upgrade, so on any worker where a migration ran before a log-capture test, every logger created up to that point — including fenliu.__main__ — had disabled=True. Logger.handle() checks disabled before levels, so the capture helpers' level pinning was irrelevant: the handler simply never received records (confirmed empirically by dumping logger state on empty captures — logger.disabled=True with empty handlers, exactly matching the failure signature).

Fix: fileConfig(..., disable_existing_loggers=False) in env.py (the Alembic-documented setting for apps that own their logging), plus both capture helpers (test_main._capture_log, the inline capture in test_startup.py) now save/restore logger.disabled for hermeticity. This also fixes a latent production symptom: the "Database migrations applied" log line after alembic was being silently dropped.

Validation: fenliu-tryke-3.14 (the nox session that reproduced the flake at ~1-in-3) ran 8× consecutively clean after the fix.

Root cause found and fixed on PR #107 (commit `ea42a15`). **Mechanism:** `alembic/env.py` called `fileConfig(config.config_file_name)` with the stdlib default `disable_existing_loggers=True`. `test_database.py` runs real migrations via `alembic.command.upgrade`, so on any worker where a migration ran before a log-capture test, every logger created up to that point — including `fenliu.__main__` — had `disabled=True`. `Logger.handle()` checks `disabled` *before* levels, so the capture helpers' level pinning was irrelevant: the handler simply never received records (confirmed empirically by dumping logger state on empty captures — `logger.disabled=True` with empty handlers, exactly matching the failure signature). **Fix:** `fileConfig(..., disable_existing_loggers=False)` in env.py (the Alembic-documented setting for apps that own their logging), plus both capture helpers (`test_main._capture_log`, the inline capture in `test_startup.py`) now save/restore `logger.disabled` for hermeticity. This also fixes a latent production symptom: the "Database migrations applied" log line after alembic was being silently dropped. **Validation:** `fenliu-tryke-3.14` (the nox session that reproduced the flake at ~1-in-3) ran 8× consecutively clean after the fix.

marvin8 closed this issue

2026-09-08 04:37:06 +00:00

No labels

No milestone

No project

No assignees

1 participant

Notifications

Due date

The due date is invalid or out of range. Please use the format "yyyy-mm-dd".

No due date set.

Dependencies

No dependencies set

Reference

marvin8/dujiangyan#110

No description provided.

Rows
Columns