dark/nether-voicebridge

Fork 1

fix(discord): external displacement during puppet media-startup breaks recovery — rejoin succeeds but playback stays silent (deterministic; was masked by voice-state lag) #127

New issue

Closed

opened 2026-07-26 02:33:15 +00:00 by robocub · 2 comments

robocub commented

2026-07-26 02:33:15 +00:00

Collaborator

Symptom

If an external displacement (moderator voice-kick, force-move, or a steal/release cycle) hits a puppet during its media-startup window (observed: kick landing ~300 ms after playback: first frame from LiveKit, ~1.5 s after the voice join), the #46 recovery path completes on paper but the bridge is broken afterwards:

external_disconnect_recovery / recovery_no_spare shape: RECOVERING → RECOVERED both log, the same bot rejoins voice — but from then on the puppet transmits pure digital silence (captured audio: peak=1, 0.0 % nonzero, continuous full-window coverage). Matrix→Discord audio is dead until the bridge cycles.
force_move_recovery shape: the bridge never notices the displacement at all (#62 probe never fires).
steal_release_repromotion shape: the post-steal re-promotion never lands (0 puppets back in the original channel).

All four fail deterministically — the #125 one-retry pass fails both attempts, so this is not the transient-infra class that retry was built for.

Why this went unnoticed (and what unmasked it)

The live harness performs the displacement as soon as its listener's gateway cache shows the puppet in voice — so the effective timing of the adversarial event tracks Discord's voice-state propagation speed:

In a passing run (2026-07-19, same binary, same host), propagation was laggy and the kick landed 15 s after playback: first frame — the puppet had long stabilized. Everything recovered.
In failing runs (nightlies since ~07-22, and a clean-tree quiet-host --all on 07-26), propagation is fast and the kick lands ~0.3 s after first frame. Recovery breaks as above, every time.

Same binary on both dates ⇒ a latent race in the recovery path, gated by environment timing. This also corrects part of the #124 triage: the recovery-cluster nightly failures were attributed to infra flakiness, but they are this bug — deterministic once the timing window is hit. (The 502-shaped failures from that triage remain infra; those scenarios pass now.)

Evidence trail (from the 07-26 clean-tree run)

Captured WAV post-recovery is digital zeros with continuous coverage. The harness recorder zero-fills only on songbird's explicit silent set and never fills loss gaps — continuous coverage therefore means the puppet's frames were arriving and decrypting fine and the puppet was genuinely transmitting silence (playback underrun), not that the listener failed to receive/decrypt. DAVE handshake lines on the bridge side are identical between the passing and failing runs.
After the rejoin, no playback consumer started / first frame recur — but the 07-19 passing run shows the same absence, so that alone isn't the defect; the rejoin path (rejoin_puppet → puppet_join) does call.play_input(PlaybackSource::new(mixer)) on the new Call and respawns the speaking gate.
The "gateway leave echo race — retrying" join retry is ruled out as the discriminator (present in a 07-19 passing recovery_no_spare run).

Suspected mechanism (unconfirmed — needs instrumented repro)

The killed connection's speaking-gate task survives the displacement by design ("play/pause errors are ignored: after a leave the track is gone"). Post-rejoin there are then two gate tasks sampling the shared PlaybackMixer loud-frame activity — the stale one can consume the speech-onset signal and the new track (paused by its gate after the initial hangover) never resumes. Alternatives: mixer/consumer wedge, or the new track's gate never observing loud frames at all. The force-move and steal shapes suggest the displacement detection latches also misbehave when the event lands this early.

Repro

Live harness, compressed profile, quiet host: nvb-e2e run --scenario external_disconnect_recovery fails ~every time while Discord voice-state propagation is fast (current behavior). For a guaranteed repro independent of Discord's mood, the harness kick should be delayed-gated: kick at a fixed short offset after the puppet joins (e.g. 1 s) rather than on cache visibility — that would also make these four scenarios timing-deterministic in both directions.

Production impact

Narrow but real: a moderator kicking or dragging a bridge puppet right as it joins leaves that channel's Matrix→Discord audio silent until the bridge is cycled. No crash, no error logs — a silent wedge (the worst kind).

Suggested fix shape

Root-cause with an instrumented single-scenario repro (debug logging on the playback/gate path), then fix the actual race — likely: cancel the old speaking-gate task on rejoin (tie gate lifetime to the join epoch), and audit the displacement-detection latches for early-event windows.
Harden the harness: fixed-offset displacement (see Repro) so the scenarios pin BOTH the fast and slow timing, not whichever Discord serves that night.

## Symptom If an external displacement (moderator voice-kick, force-move, or a steal/release cycle) hits a puppet **during its media-startup window** (observed: kick landing ~300 ms after `playback: first frame from LiveKit`, ~1.5 s after the voice join), the #46 recovery path completes on paper but the bridge is broken afterwards: - `external_disconnect_recovery` / `recovery_no_spare` shape: RECOVERING → RECOVERED both log, the **same** bot rejoins voice — but from then on the puppet transmits **pure digital silence** (captured audio: peak=1, 0.0 % nonzero, continuous full-window coverage). Matrix→Discord audio is dead until the bridge cycles. - `force_move_recovery` shape: the bridge **never notices** the displacement at all (#62 probe never fires). - `steal_release_repromotion` shape: the post-steal re-promotion never lands (0 puppets back in the original channel). All four fail **deterministically** — the #125 one-retry pass fails both attempts, so this is not the transient-infra class that retry was built for. ## Why this went unnoticed (and what unmasked it) The live harness performs the displacement as soon as its listener's gateway cache shows the puppet in voice — so the *effective* timing of the adversarial event tracks Discord's voice-state propagation speed: - In a passing run (2026-07-19, same binary, same host), propagation was laggy and the kick landed **15 s** after `playback: first frame` — the puppet had long stabilized. Everything recovered. - In failing runs (nightlies since ~07-22, and a clean-tree quiet-host `--all` on 07-26), propagation is fast and the kick lands **~0.3 s** after first frame. Recovery breaks as above, every time. Same binary on both dates ⇒ a latent race in the recovery path, gated by environment timing. This also corrects part of the #124 triage: the recovery-cluster nightly failures were attributed to infra flakiness, but they are this bug — deterministic once the timing window is hit. (The 502-shaped failures from that triage remain infra; those scenarios pass now.) ## Evidence trail (from the 07-26 clean-tree run) - Captured WAV post-recovery is digital zeros with **continuous** coverage. The harness recorder zero-fills only on songbird's explicit `silent` set and never fills loss gaps — continuous coverage therefore means the puppet's frames were arriving and decrypting fine and the puppet was genuinely **transmitting silence** (playback underrun), not that the listener failed to receive/decrypt. DAVE handshake lines on the bridge side are identical between the passing and failing runs. - After the rejoin, no `playback consumer started` / `first frame` recur — but the 07-19 **passing** run shows the same absence, so that alone isn't the defect; the rejoin path (`rejoin_puppet` → `puppet_join`) does `call.play_input(PlaybackSource::new(mixer))` on the new Call and respawns the speaking gate. - The "gateway leave echo race — retrying" join retry is ruled out as the discriminator (present in a 07-19 *passing* `recovery_no_spare` run). ## Suspected mechanism (unconfirmed — needs instrumented repro) The killed connection's speaking-gate task survives the displacement by design ("play/pause errors are ignored: after a leave the track is gone"). Post-rejoin there are then **two** gate tasks sampling the shared `PlaybackMixer` loud-frame activity — the stale one can consume the speech-onset signal and the new track (paused by its gate after the initial hangover) never resumes. Alternatives: mixer/consumer wedge, or the new track's gate never observing loud frames at all. The force-move and steal shapes suggest the displacement *detection* latches also misbehave when the event lands this early. ## Repro Live harness, compressed profile, quiet host: `nvb-e2e run --scenario external_disconnect_recovery` fails ~every time while Discord voice-state propagation is fast (current behavior). For a guaranteed repro independent of Discord's mood, the harness kick should be delayed-gated: kick at a **fixed short offset** after the puppet joins (e.g. 1 s) rather than on cache visibility — that would also make these four scenarios timing-deterministic in both directions. ## Production impact Narrow but real: a moderator kicking or dragging a bridge puppet right as it joins leaves that channel's Matrix→Discord audio silent until the bridge is cycled. No crash, no error logs — a silent wedge (the worst kind). ## Suggested fix shape 1. Root-cause with an instrumented single-scenario repro (debug logging on the playback/gate path), then fix the actual race — likely: cancel the old speaking-gate task on rejoin (tie gate lifetime to the join epoch), and audit the displacement-detection latches for early-event windows. 2. Harden the harness: fixed-offset displacement (see Repro) so the scenarios pin BOTH the fast and slow timing, not whichever Discord serves that night.

robocub referenced this issue from a commit

2026-07-26 03:34:53 +00:00

fix(vendor/songbird): cancel disconnect tombstone on re-speak — fast leave+rejoin permanently deafened the receive side (#127)

robocub commented

2026-07-26 03:53:20 +00:00

Author

Collaborator

Root-caused and fixed — landed on master as a4a94b4 (direct push after clean-tree verification). Two stacked bugs, plus the DAVE-layer observability that made the hunt possible. Details below.

Bug 1 — songbird SSRC tombstone race (the production bug)

The vendored songbird tracks voice-gateway ClientDisconnects with a lazy tombstone (SsrcTracker::disconnected_users) consumed by a cleanup sweep in udp_rx that runs every 5 s. The sweep removes user_ssrc_map[user] → whatever SSRC that holds at sweep time.

If a user leaves and rejoins within one sweep interval (a mod voice-kick + the #46 same-bot recovery ≈ 1–3 s, a quick channel hop, a gateway blip), their re-speak has already overwritten the mapping with the new SSRC — so the sweep deletes the live mapping. Every subsequent DAVE-encrypted packet from the new SSRC then hits the unmapped-SSRC branch and is silently discarded (no log line existed on any of the three drop branches): the receiving client is permanently deaf to that user until the connection cycles.

In production this is the capture anchor going deaf to a human speaker (Discord→Matrix one-way silence); in the harness it was the listener, which is how the e2e suite caught it.

Fix (vendor/songbird, upstreamable): a Speaking event cancels the user's pending tombstone — a re-speaking user is not disconnected — and eagerly retires their previous SSRC's reverse mapping. The cancel logs at debug, so a defused race is positively visible in artifacts.

Why #124 called this "infra" (and why the retry couldn't fix it)

The race depends on the kick→re-speak gap vs the sweep phase. During the 07-19 triage week Discord's voice-state propagation was laggy (documented in that triage), stretching the gap past the sweep — always-safe ordering, so every clean-tree repro passed and the failures looked environmental. When propagation sped up (~07-22) the race hit ~60 % of attempts; both retry attempts roll the same dice, so nightlies stayed red through #125. Measured on a quiet runner: baseline 3/5 fail (silence signature: ncc≈0.00x, glitches=0, captures are pure digital zeros), post-fix the silence signature is gone entirely.

Bug 2 — e2e recorder double-write (unmasked by bug 1's fix)

With the mapping race fixed, a fast-rejoining target is briefly reachable through two mapped SSRCs: the dead one lingers in songbird's silent set (decoder state persists to decode_state_timeout) while the live one carries audio in speaking. ListenerTick wrote 20 ms of audio plus 20 ms of zero-fill per tick for the same user — captures stretched to ~2× wall clock as half-rate chop (signature: ncc 0.05–0.10, glitches ≈200, envelope twice the probe length). Pre-fix this was masked because the same sweep that caused bug 1 also pruned the stale decoder entry.

Fix: per-user-per-tick dedupe — real audio wins; zero-fill only applies to a target with no write in that tick.

Observability added

debug! on every vendored DAVE gateway arm: prepare_epoch (including the previously-invisible ignored epoch != 1 case), prepare/execute transition, external sender, proposals (op + whether we commit), commit, welcome, session reinit.
debug! on all three silent packet-drop branches in the receive path (unmapped SSRC / session not ready / no decryptor).
Throttled warn! in the mixer when frames leave a DAVE-negotiated connection without frame encryption — the send-side state a mandatory-DAVE SFU punishes with silent non-delivery. (Fires transiently during every normal handshake; sustained repeats are the alarm.)
songbird=debug added to the harness bridge env and the nightly workflow RUST_LOG (32 debug sites total, none per-packet in steady state), so artifacts capture all of the above.

Verification (quiet runner; live scenarios against the standing environment)

Stage	Result
Baseline (master `522a5bd`)	`external_disconnect_recovery` 2 pass / 3 fail, all fails silence-signature
+ bug 1 fix	silence signature eliminated; remaining fails all recorder-chop
+ bug 2 fix	`external_disconnect_recovery` 5/5 pass
Cluster	`recovery_no_spare` 2/2, `force_move_recovery` 2/2
Clean tree (fresh clone of `a4a94b4`)	202/202 hermetic tests; live: smoke + 4 audio + 3 recovery scenarios = 7/8 pass — `external_disconnect_recovery` 0.986 8/8, `recovery_no_spare` 0.981 8/8, `force_move_recovery` pass. The single fail (`audio_d2m_enc`) is the documented pre-existing homeserver-502 flake: 2× `502 Bad Gateway` + call membership dropping 1→0 mid-scenario in its bridge log, and it passes 8/8 on the same binary minutes later.

Remaining (this issue stays open)

steal_release_repromotion still fails, but with an allocator-level shape (post-steal cross-channel re-promotion leaves the overflow speaker stranded — the #24 regression guard firing, no audio involved). Different subsystem, separate investigation; tracked on #127.

Upstream: the tombstone race + fix will be reported to serenity-rs/songbird (also the eventual home of the #36 trailer fix in this vendor tree).

🤖 Generated with Claude Code

**Root-caused and fixed** — landed on master as `a4a94b4` (direct push after clean-tree verification). Two stacked bugs, plus the DAVE-layer observability that made the hunt possible. Details below. ## Bug 1 — songbird SSRC tombstone race (the production bug) The vendored songbird tracks voice-gateway `ClientDisconnect`s with a lazy tombstone (`SsrcTracker::disconnected_users`) consumed by a cleanup sweep in `udp_rx` that runs **every 5 s**. The sweep removes `user_ssrc_map[user]` → whatever SSRC that holds *at sweep time*. If a user leaves **and rejoins within one sweep interval** (a mod voice-kick + the #46 same-bot recovery ≈ 1–3 s, a quick channel hop, a gateway blip), their re-speak has already overwritten the mapping with the **new** SSRC — so the sweep deletes the *live* mapping. Every subsequent DAVE-encrypted packet from the new SSRC then hits the unmapped-SSRC branch and is **silently discarded** (no log line existed on any of the three drop branches): the receiving client is permanently deaf to that user until the connection cycles. In production this is the capture **anchor going deaf to a human speaker** (Discord→Matrix one-way silence); in the harness it was the listener, which is how the e2e suite caught it. **Fix (`vendor/songbird`, upstreamable):** a `Speaking` event cancels the user's pending tombstone — a re-speaking user is not disconnected — and eagerly retires their previous SSRC's reverse mapping. The cancel logs at `debug`, so a defused race is *positively visible* in artifacts. ### Why #124 called this "infra" (and why the retry couldn't fix it) The race depends on the kick→re-speak gap vs the sweep phase. During the 07-19 triage week Discord's voice-state propagation was laggy (documented in that triage), stretching the gap past the sweep — always-safe ordering, so every clean-tree repro passed and the failures looked environmental. When propagation sped up (~07-22) the race hit ~60 % of attempts; both retry attempts roll the same dice, so nightlies stayed red through #125. Measured on a quiet runner: baseline 3/5 fail (silence signature: ncc≈0.00x, glitches=0, captures are pure digital zeros), post-fix the silence signature is gone entirely. ## Bug 2 — e2e recorder double-write (unmasked by bug 1's fix) With the mapping race fixed, a fast-rejoining target is briefly reachable through **two** mapped SSRCs: the dead one lingers in songbird's `silent` set (decoder state persists to `decode_state_timeout`) while the live one carries audio in `speaking`. `ListenerTick` wrote 20 ms of audio **plus** 20 ms of zero-fill per tick for the same user — captures stretched to ~2× wall clock as half-rate chop (signature: ncc 0.05–0.10, glitches ≈200, envelope twice the probe length). Pre-fix this was masked because the same sweep that caused bug 1 also pruned the stale decoder entry. **Fix:** per-user-per-tick dedupe — real audio wins; zero-fill only applies to a target with no write in that tick. ## Observability added - `debug!` on every vendored DAVE gateway arm: prepare_epoch (including the previously-invisible **ignored `epoch != 1`** case), prepare/execute transition, external sender, proposals (op + whether we commit), commit, welcome, session reinit. - `debug!` on all three silent packet-drop branches in the receive path (unmapped SSRC / session not ready / no decryptor). - Throttled `warn!` in the mixer when frames leave a DAVE-negotiated connection **without frame encryption** — the send-side state a mandatory-DAVE SFU punishes with silent non-delivery. (Fires transiently during every normal handshake; sustained repeats are the alarm.) - `songbird=debug` added to the harness bridge env and the nightly workflow `RUST_LOG` (32 debug sites total, none per-packet in steady state), so artifacts capture all of the above. ## Verification (quiet runner; live scenarios against the standing environment) | Stage | Result | |---|---| | Baseline (master `522a5bd`) | `external_disconnect_recovery` 2 pass / 3 fail, all fails silence-signature | | + bug 1 fix | silence signature eliminated; remaining fails all recorder-chop | | + bug 2 fix | `external_disconnect_recovery` **5/5 pass** | | Cluster | `recovery_no_spare` **2/2**, `force_move_recovery` **2/2** | | Clean tree (fresh clone of `a4a94b4`) | 202/202 hermetic tests; live: smoke + 4 audio + 3 recovery scenarios = 7/8 pass — `external_disconnect_recovery` 0.986 8/8, `recovery_no_spare` 0.981 8/8, `force_move_recovery` pass. The single fail (`audio_d2m_enc`) is the documented pre-existing homeserver-502 flake: 2× `502 Bad Gateway` + call membership dropping 1→0 mid-scenario in its bridge log, and it passes 8/8 on the same binary minutes later. | ## Remaining (this issue stays open) `steal_release_repromotion` still fails, but with an **allocator-level** shape (post-steal cross-channel re-promotion leaves the overflow speaker stranded — the #24 regression guard firing, no audio involved). Different subsystem, separate investigation; tracked on #127. Upstream: the tombstone race + fix will be reported to serenity-rs/songbird (also the eventual home of the #36 trailer fix in this vendor tree). 🤖 Generated with [Claude Code](https://claude.com/claude-code)

robocub referenced this issue

2026-07-26 04:29:39 +00:00

chore(vendor): report the #127 SSRC-tombstone race (and the #36 trailer fix) upstream to serenity-rs/songbird, then unwind the vendor #128

robocub referenced this issue from a commit

2026-07-26 04:38:07 +00:00

release: 0.3.1 — one-way-deafness fix; e2e: hold the reaper off the steal scenario's phantoms (#127, #24)

robocub commented

2026-07-26 04:38:55 +00:00

Author

Collaborator

The steal_release_repromotion residual is resolved too — and the allocator was innocent (ad53ccd, in v0.3.1).

The scenario's membership-only phantoms are, to the #25 stale-membership reaper, exactly what it exists to retract: an m.call.member with no LiveKit participant. Under the compressed 3 s reap_grace, the reaper emptied Alice's and Bob's memberships ~4 s after the subscriber connected — racing the steal→release→re-promotion choreography (~5-10 s). Lose the race early and Bob is gone from overflow before the thief channel frees its bot (re-promotion times out); lose it late and the cascading releases empty the donor channel under the final assert. Both #124-era failure shapes, one mechanism — and the 07-19 "memberships vanish ~3 s after join" observation previously pinned on homeserver 502s was this reaper (reaped phantom m.call.member in the bridge logs).

Fix: a per-scenario [timing]-override hook in the harness config generator; the scenario's bridge-under-test now runs with reap_grace_ms beyond its runtime (the reaper's own behavior stays covered by reap_release under --profile real). Verified 4/5 standalone (from 0/4 attempts); the single miss was the pre-existing Discord channel-hop propagation flake, which has its own quarantine/failover machinery.

With that, everything this issue tracked is fixed and shipped: tombstone race + recorder double-write (a4a94b4, deployed to the public bridge), steal-scenario reaper race (ad53ccd), DAVE observability throughout. Upstream reporting is tracked in #128. Closing.

**The `steal_release_repromotion` residual is resolved too — and the allocator was innocent** (`ad53ccd`, in v0.3.1). The scenario's membership-only phantoms are, to the #25 stale-membership reaper, exactly what it exists to retract: an `m.call.member` with no LiveKit participant. Under the compressed 3 s `reap_grace`, the reaper emptied Alice's and Bob's memberships ~4 s after the subscriber connected — racing the steal→release→re-promotion choreography (~5-10 s). Lose the race early and Bob is gone from overflow before the thief channel frees its bot (re-promotion times out); lose it late and the cascading releases empty the donor channel under the final assert. Both #124-era failure shapes, one mechanism — and the 07-19 \"memberships vanish ~3 s after join\" observation previously pinned on homeserver 502s was this reaper (`reaped phantom m.call.member` in the bridge logs). Fix: a per-scenario `[timing]`-override hook in the harness config generator; the scenario's bridge-under-test now runs with `reap_grace_ms` beyond its runtime (the reaper's own behavior stays covered by `reap_release` under `--profile real`). Verified 4/5 standalone (from 0/4 attempts); the single miss was the pre-existing Discord channel-hop propagation flake, which has its own quarantine/failover machinery. With that, everything this issue tracked is fixed and shipped: tombstone race + recorder double-write (`a4a94b4`, deployed to the public bridge), steal-scenario reaper race (`ad53ccd`), DAVE observability throughout. Upstream reporting is tracked in #128. Closing.

robocub closed this issue

2026-07-26 04:38:55 +00:00