fix(test): install one global capture subscriber; delete schema migrations #411

2026-08-12T17:33:30Z

KofTwentyTwo commented

2026-08-12 17:33:30 +00:00

(Migrated from github.com)

dev CI has been red on every run since ~2026-08-01, with a different test failing each time. Root-caused, reproduced, fixed, and verified. Closes #375.

Root cause

tracing resolves each callsite's Interest once for the whole process and caches it — that cache is what makes a disabled log statement nearly free. tracing::subscriber::set_default / with_default installs a subscriber on the current thread only.

Under cargo test's parallel harness those collide: a callsite first executed by a thread with no subscriber caches Interest::never(), and the macro then short-circuits before consulting any thread-local subscriber a later test installs. Whichever thread reaches a callsite first decides, for the rest of the process, whether any other test can capture it.

Confirmed by direct instrumentation rather than inference. On a failing run:

PROBE test-thread=ThreadId(116) name="migrate_logs_when_an_additive_column_migration_actually_runs"
PROBE alter-branch thread=ThreadId(110) name="migrate_backfills_smtp_columns_..."  is_noop_dispatch=true
PROBE alter-branch thread=ThreadId(116) name="migrate_logs_when_an_additive_..."   is_noop_dispatch=false

Thread 116 had its subscriber correctly installed (is_noop_dispatch=false) and executed the logging branch — and still captured nothing, because thread 110 had already registered that callsite with no subscriber. The captured buffer was not empty either; it held an unrelated INFO line from vault, whose callsite happened to register while a subscriber was active. Empty-vs-partial is the tell.

Why it only ever failed in CI

It reproduces at --test-threads=2, which is what GitHub runners give us. At this machine's default 18 threads it is invisible:

`--test-threads`	runs with a failure
1	0/6
2	3/6
3	0/6
4	1/6
8, 16	0/6

--test-threads=1 passing is itself diagnostic: with no dispatcher ever set at registration time, the interest cache gets rebuilt when the first subscriber appears.

The fix

Install the capture layer once as the global default and route events to a per-thread recorder slot. Every callsite then registers against a real subscriber, so interest is always enabled; per-thread routing keeps concurrent tests from reading each other's telemetry. rebuild_interest_cache() is called once at install, never per test — the per-test variant was previously measured as making things worse, and that finding still stands.

Applied to all five crates that captured logs thread-locally: nunciod, nuncio-cal, nuncio-contacts, nuncio-filter, nuncio-store. nuncio-mail already used a global subscriber and is untouched.

No assertion was weakened. The structured Recorder is preserved, so tests that assert on a level or a field name still do. tracing-test was deliberately not adopted: its logs_contain is a substring match that would have lost those assertions.

Deleting migrations instead of fixing one of them

One flaky test covered an additive schema migration. Rather than stabilise it, the migration machinery is gone — nothing is released, and every store is a local development database.

migrate() called four ALTER TABLE … ADD COLUMN helpers (smtp columns, TLS-mode columns, DAV collection_url, messages identity columns). Every column they add is already declared in the CREATE TABLE IF NOT EXISTS in the same function, so on any database this engine creates they were unconditional no-ops. Deleted, along with the three tests that existed only to exercise them. Databases are created, never migrated.

backfill_message_fts stays, and its doc no longer claims the legacy justification. It has a live reason: SqliteRecoveryEngine::salvage restores rows straight into messages, bypassing save_email's index write, so a recovered database really does hold content the trigram index has never seen.

Net: −495 lines, and that flake ceases to exist rather than being managed.

Verification

The reproduction, before and after:

	before	after
`RUST_TEST_THREADS=2 cargo test-all`	3/3 red	0/8 red
`nunciod` @ 2 threads	~90% red	0/12
`nuncio-store` @ 2 threads	8/70 red	0 (remaining failures were the now-deleted test)
`nuncio-cal` / `-contacts` / `-filter` @ 2 threads	not reproducible	0/12 each

Full gate: fmt clean, check-all 0 errors, test-all green.

Honest caveat: nuncio-cal, nuncio-contacts and nuncio-filter could not be made to fail at baseline even at 100 runs each — they are structurally smaller, so collision probability is lower. Their fix rests on the proven mechanism and on those crates using the identical broken helper, not on an observed before/after delta.

Two CI failures NOT addressed

Both appeared once each across four CI runs and are not this root cause:

recovery::tests::test_stage_2_backup_creation_and_stage_3_table_salvage — 0/40 failures locally at 2 threads under artificial CPU contention
a_timed_out_item_does_not_block_a_later_item_in_a_subsequent_pass — 0/30 under the same conditions

Neither reproduced, so neither was diagnosed, and nothing was changed speculatively to make them "look" fixed. If CI stays red on either after this merges, they need their own investigation with a real reproduction first. The second is a timeout test and the likely shape is condition-based waiting rather than a fixed duration, but that is a hypothesis, not a finding.

`dev` CI has been red on every run since ~2026-08-01, with a *different* test failing each time. Root-caused, reproduced, fixed, and verified. Closes #375. ## Root cause `tracing` resolves each callsite's `Interest` **once for the whole process** and caches it — that cache is what makes a disabled log statement nearly free. `tracing::subscriber::set_default` / `with_default` installs a subscriber on the **current thread only**. Under `cargo test`'s parallel harness those collide: a callsite first executed by a thread with no subscriber caches `Interest::never()`, and the macro then short-circuits **before consulting** any thread-local subscriber a later test installs. Whichever thread reaches a callsite first decides, for the rest of the process, whether any other test can capture it. Confirmed by direct instrumentation rather than inference. On a failing run: ``` PROBE test-thread=ThreadId(116) name="migrate_logs_when_an_additive_column_migration_actually_runs" PROBE alter-branch thread=ThreadId(110) name="migrate_backfills_smtp_columns_..." is_noop_dispatch=true PROBE alter-branch thread=ThreadId(116) name="migrate_logs_when_an_additive_..." is_noop_dispatch=false ``` Thread 116 had its subscriber correctly installed (`is_noop_dispatch=false`) and executed the logging branch — and still captured nothing, because thread 110 had already registered that callsite with no subscriber. The captured buffer was not empty either; it held an unrelated INFO line from `vault`, whose callsite happened to register while a subscriber was active. Empty-vs-partial is the tell. ## Why it only ever failed in CI It reproduces at **`--test-threads=2`**, which is what GitHub runners give us. At this machine's default 18 threads it is invisible: | `--test-threads` | runs with a failure | |---|---| | 1 | 0/6 | | **2** | **3/6** | | 3 | 0/6 | | 4 | 1/6 | | 8, 16 | 0/6 | `--test-threads=1` passing is itself diagnostic: with no dispatcher ever set at registration time, the interest cache gets rebuilt when the first subscriber appears. ## The fix Install the capture layer **once as the global default** and route events to a **per-thread** recorder slot. Every callsite then registers against a real subscriber, so interest is always enabled; per-thread routing keeps concurrent tests from reading each other's telemetry. `rebuild_interest_cache()` is called once at install, never per test — the per-test variant was previously measured as making things *worse*, and that finding still stands. Applied to all five crates that captured logs thread-locally: `nunciod`, `nuncio-cal`, `nuncio-contacts`, `nuncio-filter`, `nuncio-store`. `nuncio-mail` already used a global subscriber and is untouched. **No assertion was weakened.** The structured `Recorder` is preserved, so tests that assert on a level or a field name still do. `tracing-test` was deliberately *not* adopted: its `logs_contain` is a substring match that would have lost those assertions. ## Deleting migrations instead of fixing one of them One flaky test covered an additive schema migration. Rather than stabilise it, the migration machinery is gone — nothing is released, and every store is a local development database. `migrate()` called four `ALTER TABLE … ADD COLUMN` helpers (smtp columns, TLS-mode columns, DAV `collection_url`, messages identity columns). Every column they add is **already declared in the `CREATE TABLE IF NOT EXISTS` in the same function**, so on any database this engine creates they were unconditional no-ops. Deleted, along with the three tests that existed only to exercise them. Databases are created, never migrated. `backfill_message_fts` **stays**, and its doc no longer claims the legacy justification. It has a live reason: `SqliteRecoveryEngine::salvage` restores rows straight into `messages`, bypassing `save_email`'s index write, so a recovered database really does hold content the trigram index has never seen. Net: −495 lines, and that flake ceases to exist rather than being managed. ## Verification The reproduction, before and after: | | before | after | |---|---|---| | `RUST_TEST_THREADS=2 cargo test-all` | **3/3 red** | **0/8 red** | | `nunciod` @ 2 threads | ~90% red | 0/12 | | `nuncio-store` @ 2 threads | 8/70 red | 0 (remaining failures were the now-deleted test) | | `nuncio-cal` / `-contacts` / `-filter` @ 2 threads | not reproducible | 0/12 each | Full gate: `fmt` clean, `check-all` 0 errors, `test-all` green. Honest caveat: `nuncio-cal`, `nuncio-contacts` and `nuncio-filter` could not be made to fail at baseline even at 100 runs each — they are structurally smaller, so collision probability is lower. Their fix rests on the proven mechanism and on those crates using the identical broken helper, not on an observed before/after delta. ## Two CI failures NOT addressed Both appeared once each across four CI runs and are **not** this root cause: - `recovery::tests::test_stage_2_backup_creation_and_stage_3_table_salvage` — 0/40 failures locally at 2 threads under artificial CPU contention - `a_timed_out_item_does_not_block_a_later_item_in_a_subsequent_pass` — 0/30 under the same conditions Neither reproduced, so neither was diagnosed, and nothing was changed speculatively to make them "look" fixed. If CI stays red on either after this merges, they need their own investigation with a real reproduction first. The second is a timeout test and the likely shape is condition-based waiting rather than a fixed duration, but that is a hypothesis, not a finding.

Sign in to join this conversation.

1 Participants

Notifications

Due Date

No due date set.

Dependencies

No dependencies set.

Reference: KofTwentyTwo/nuncio#411