dark/nether-voicebridge

Watch

Fork 1

e2e: audio_d2m_enc nightly-red since 08-08 — #25 reaper races the decrypting listener's LiveKit connect under compressed timing #133

New issue

Closed

opened 2026-08-15 16:36:27 +00:00 by robocub · 2 comments

robocub commented

2026-08-15 16:36:27 +00:00

Collaborator

Summary

audio_d2m_enc has failed 7 of the last 8 nightlies (every run 08-08 → 08-15 except 08-13; runs #306–#320). It is not an audio or E2EE bug: the #25 stale-membership reaper reaps the harness's decrypting listener mid-scenario, because under the compressed profile's 3 s reap_grace the listener's membership-post → LiveKit-connect latency now loses the race. Same class as the steal_release_repromotion fix in ad53ccd (#127 follow-up / #24), surfacing in a second scenario.

Evidence (bridge logs from the artifacts)

Run #320 (08-15):

08:47:55.681 call participants ["@nvbtest_listener:nether.im"]      ← membership posted
08:48:01.382 reaped phantom m.call.member sender=@nvbtest_listener  ← reap_grace 3s fires
08:48:01.755 LiveKit: remote participant connected @nvbtest_listener:...:Tkb6vgjs3   ← 373 ms late
08:48:01.542 membership gone — starting leave grace timer
08:48:03.544 call ended — disconnecting subscriber
08:48:06.579 capture-only anchor idle grace elapsed — leaving Discord voice

Run #315 (08-14): identical, margin 82 ms (reaped 08:46:59.148, listener LiveKit connect 08:46:59.230).

Once the anchor leaves Discord, the ghost's publish pump zero-fills — hence the oracle signature, a mid-stream hard cutoff, not degradation:

#315 d2m_enc_tap_b cycles ncc: [1.00 1.00 1.00 1.00 0.00 0.00 0.00 0.00]  good 4/8
#320 d2m_enc_tap_b cycles ncc: [1.00 1.00 1.00 0.11 0.00 0.00 0.00 0.00]  good 3/8

(Tap B is pre-encryption PCM — the exact audio the ghost feeds LiveKit's frame crypto — which is what rules out the E2EE path.)

fresh_store_rekey, which exercises the same d2m_enc_tap_b oracle, scored 8/8 perfect in the same failing runs — the D2M-enc pipeline itself is healthy.

Why only the encrypted variant, and why since 08-08

audio_d2m_unenc passes: its plain listener connects fast. MatrixListener::join_decrypting bootstraps Olm before connecting — precisely the extra seconds that lose the 3 s race.
The failure needs listener connect latency ≳ reap_grace. Something environmental pushed it past ~3–6 s around 08-08 (LiveKit lives on the resource-constrained nether-red VPS); 08-13 was simply a fast-connect day. Worth watching separately, but the harness must not be flaky against realistic connect latency either way.

Not the #124 recovery cluster

The recovery/displacement scenarios have not failed since v0.3.1 shipped — the 08-08→08-12 co-failures were a separate mgmt/link cluster (502-flap shaped) that cleared on its own after 08-12. The nightly's only standing red is this scenario.

Fix

Per-scenario [timing] override, exactly like the steal fix: start the bridge-under-test for audio_d2m_enc with reap_grace_ms = 300000 (past scenario runtime; every other key stays compressed). The reaper itself remains covered by reap_release under --profile real.

Bridge-side observation (not fixed here)

At 08:48:01.755 the listener's LiveKit participant connected 373 ms after its membership was reaped, and the bridge never reconsidered — a live media participant with no membership just rides the teardown cascade. In prod (45 s grace) this needs a >45 s connect straggler, and Element Call's delayed-events refresh would normally re-post the membership, so this is an edge case — noting it for the #41 refactor rather than fixing now.

## Summary `audio_d2m_enc` has failed **7 of the last 8 nightlies** (every run 08-08 → 08-15 except 08-13; runs #306–#320). It is not an audio or E2EE bug: the **#25 stale-membership reaper reaps the harness's decrypting listener mid-scenario**, because under the compressed profile's 3 s `reap_grace` the listener's membership-post → LiveKit-connect latency now loses the race. Same class as the `steal_release_repromotion` fix in `ad53ccd` (#127 follow-up / #24), surfacing in a second scenario. ## Evidence (bridge logs from the artifacts) **Run #320 (08-15):** ``` 08:47:55.681 call participants ["@nvbtest_listener:nether.im"] ← membership posted 08:48:01.382 reaped phantom m.call.member sender=@nvbtest_listener ← reap_grace 3s fires 08:48:01.755 LiveKit: remote participant connected @nvbtest_listener:...:Tkb6vgjs3 ← 373 ms late 08:48:01.542 membership gone — starting leave grace timer 08:48:03.544 call ended — disconnecting subscriber 08:48:06.579 capture-only anchor idle grace elapsed — leaving Discord voice ``` **Run #315 (08-14):** identical, margin **82 ms** (reaped 08:46:59.148, listener LiveKit connect 08:46:59.230). Once the anchor leaves Discord, the ghost's publish pump zero-fills — hence the oracle signature, a mid-stream hard cutoff, not degradation: ``` #315 d2m_enc_tap_b cycles ncc: [1.00 1.00 1.00 1.00 0.00 0.00 0.00 0.00] good 4/8 #320 d2m_enc_tap_b cycles ncc: [1.00 1.00 1.00 0.11 0.00 0.00 0.00 0.00] good 3/8 ``` (Tap B is **pre-encryption** PCM — the exact audio the ghost feeds LiveKit's frame crypto — which is what rules out the E2EE path.) `fresh_store_rekey`, which exercises the same `d2m_enc_tap_b` oracle, scored **8/8 perfect in the same failing runs** — the D2M-enc pipeline itself is healthy. ## Why only the encrypted variant, and why since 08-08 - `audio_d2m_unenc` passes: its plain listener connects fast. `MatrixListener::join_decrypting` bootstraps Olm before connecting — precisely the extra seconds that lose the 3 s race. - The failure needs listener connect latency ≳ reap_grace. Something environmental pushed it past ~3–6 s around 08-08 (LiveKit lives on the resource-constrained nether-red VPS); 08-13 was simply a fast-connect day. Worth watching separately, but the harness must not be flaky against realistic connect latency either way. ## Not the #124 recovery cluster The recovery/displacement scenarios have **not** failed since v0.3.1 shipped — the 08-08→08-12 co-failures were a separate mgmt/link cluster (502-flap shaped) that cleared on its own after 08-12. The nightly's only standing red is this scenario. ## Fix Per-scenario `[timing]` override, exactly like the steal fix: start the bridge-under-test for `audio_d2m_enc` with `reap_grace_ms = 300000` (past scenario runtime; every other key stays compressed). The reaper itself remains covered by `reap_release` under `--profile real`. ## Bridge-side observation (not fixed here) At 08:48:01.755 the listener's LiveKit participant connected 373 ms *after* its membership was reaped, and the bridge never reconsidered — a live media participant with no membership just rides the teardown cascade. In prod (45 s grace) this needs a >45 s connect straggler, and Element Call's delayed-events refresh would normally re-post the membership, so this is an edge case — noting it for the #41 refactor rather than fixing now.

robocub referenced this issue from a commit

2026-08-15 16:38:37 +00:00

fix(e2e): hold the reaper off audio_d2m_enc's decrypting listener (#133)

robocub referenced this issue from a commit

2026-08-15 16:55:20 +00:00

fix(e2e): thread [timing] overrides through EVERY real-config render arm (#133)

robocub commented

2026-08-15 17:05:47 +00:00

Author

Collaborator

Fixed on branch fix/133-d2m-enc-reaper-race — two commits, because the first fix was disproven live and exposed a second harness bug:

0e74e26 added the reap_grace_ms = 300000 per-scenario override (new full-pool start_with_timing). Verification run #322 still failed identically — and its bridge log showed resolved reap_grace_ms = 3000 while the redacted config artifact said 300000.
ada97ed — the real bug: start_inner's render match sent the full-pool non-management path through generate_config(cfg), silently dropping extra_timing from the real config while the redacted artifact copy always renders it. The steal scenario's #24 fix only ever worked because it takes the Some(pool_size) arm. The render choice is now a pure render_real_config threading the override for every non-management arm, with a unit test pinning real/redacted agreement.

Verification run #324: PASS. Bridge log shows resolved reap_grace_ms = 300000, zero reaped phantom events, d2m_enc_tap_b 8/8 (ncc 1.00 flat), decrypted-listener oracle 7/8 pass. Compare #322/#315/#320: [1.00 … 0.00 0.00] mid-stream cutoffs with the reap in the log every time.

Merging before tomorrow's 08:30 nightly keeps the signal clean — master still carries the red.

Fixed on branch `fix/133-d2m-enc-reaper-race` — **two commits, because the first fix was disproven live and exposed a second harness bug:** 1. `0e74e26` added the `reap_grace_ms = 300000` per-scenario override (new full-pool `start_with_timing`). Verification run **#322 still failed identically** — and its bridge log showed `resolved reap_grace_ms = 3000` while the redacted config artifact said 300000. 2. `ada97ed` — the real bug: `start_inner`'s render match sent the full-pool non-management path through `generate_config(cfg)`, **silently dropping `extra_timing` from the real config while the redacted artifact copy always renders it**. The steal scenario's #24 fix only ever worked because it takes the `Some(pool_size)` arm. The render choice is now a pure `render_real_config` threading the override for every non-management arm, with a unit test pinning real/redacted agreement. Verification run **#324: PASS.** Bridge log shows `resolved reap_grace_ms = 300000`, **zero** `reaped phantom` events, `d2m_enc_tap_b` 8/8 (ncc 1.00 flat), decrypted-listener oracle 7/8 pass. Compare #322/#315/#320: `[1.00 … 0.00 0.00]` mid-stream cutoffs with the reap in the log every time. Merging before tomorrow's 08:30 nightly keeps the signal clean — master still carries the red.

robocub commented

2026-08-15 17:23:21 +00:00

Author

Collaborator

Merged to master as 0e74e26 + ada97ed (fast-forward). Live-verified in run #324 (8/8, zero reaps, resolved reap_grace_ms=300000); tomorrow’s 08:30 nightly is the first scheduled run carrying the fix — the nvb-watch guardrail will post 🌙✅ when it goes green.

Merged to master as `0e74e26` + `ada97ed` (fast-forward). Live-verified in run #324 (8/8, zero reaps, resolved reap_grace_ms=300000); tomorrow’s 08:30 nightly is the first scheduled run carrying the fix — the nvb-watch guardrail will post 🌙✅ when it goes green.

robocub closed this issue

2026-08-15 17:23:22 +00:00

robocub referenced this issue

2026-08-20 02:09:55 +00:00

e2e/staging post-mortem: 4 red nightlies (apt-daily contention) + a stale-fingerprint frankenbuild that faked a d2m regression #123

robocub referenced this issue

2026-08-20 19:10:07 +00:00

e2e nightly RED 8 days — real multi-channel/encrypted/recovery audio failure cluster (NOT contention); env-vs-code TBD #124