e2e nightly: shutdown_drain + external_disconnect_recovery + force_move_recovery fail in CI (first scheduled run) #81

New issue

Closed

opened 2026-07-11 06:40:44 +00:00 by robocub · 2 comments

robocub commented

2026-07-11 06:40:44 +00:00

Collaborator

The first scheduled nightly of the e2e workflow (run 256, master 44386f3, 2026-07-11 06:00 UTC) came back 12 pass / 3 fail on the full compressed suite. The failures look environmental/harness rather than regressions — none of the three touch code changed by #77/#78 (and mgmt_self_serve_link passed in the same run), but they need triage before the nightly is a trustworthy signal:

shutdown_drain — fail in 32.5s: "bridge exited 0 after SIGTERM but never logged 'all bridges drained cleanly'". Exit code was clean; the assertion is on the log line.
external_disconnect_recovery — fail in 68.6s: "puppet never recovered from the external disconnect (#46 rejoin): timed out waiting for log event".
force_move_recovery — fail in 70.0s: "bridge never noticed the force-move displacement (#62 probe): timed out waiting for log event".

Context/suspects:

This is the first-ever schedule run of e2e.yml in the CI container on the shared runner — a different environment from the staging host where these scenarios have previously passed live.
Host-load contention on cubuntu is a known garbler of timing-sensitive scenarios (see #38 notes); the nightly runs everything back-to-back.
The two recovery scenarios depend on manipulating the puppet's voice connection — the CI container may lack a capability the staging host has (e.g. the disconnect injection path), or the timeouts may simply be too tight under contention.

Suggested triage: re-run the three via workflow_dispatch in isolation; if they pass solo, it's contention → stagger or loosen timeouts; if they fail solo, diff the CI environment against the staging host for the injection prerequisites.

Log source: run 256 (actions_log on the Forgejo host). Scenario summary preserved in this issue for when the log rotates.

The first scheduled nightly of the e2e workflow (run 256, master `44386f3`, 2026-07-11 06:00 UTC) came back **12 pass / 3 fail** on the full compressed suite. The failures look environmental/harness rather than regressions — none of the three touch code changed by #77/#78 (and `mgmt_self_serve_link` passed in the same run), but they need triage before the nightly is a trustworthy signal: - **`shutdown_drain`** — fail in 32.5s: "bridge exited 0 after SIGTERM but never logged 'all bridges drained cleanly'". Exit code was clean; the assertion is on the log line. - **`external_disconnect_recovery`** — fail in 68.6s: "puppet never recovered from the external disconnect (#46 rejoin): timed out waiting for log event". - **`force_move_recovery`** — fail in 70.0s: "bridge never noticed the force-move displacement (#62 probe): timed out waiting for log event". Context/suspects: - This is the first-ever `schedule` run of e2e.yml in the CI container on the shared runner — a different environment from the staging host where these scenarios have previously passed live. - Host-load contention on cubuntu is a known garbler of timing-sensitive scenarios (see #38 notes); the nightly runs everything back-to-back. - The two recovery scenarios depend on manipulating the puppet's voice connection — the CI container may lack a capability the staging host has (e.g. the disconnect injection path), or the timeouts may simply be too tight under contention. Suggested triage: re-run the three via workflow_dispatch in isolation; if they pass solo, it's contention → stagger or loosen timeouts; if they fail solo, diff the CI environment against the staging host for the injection prerequisites. Log source: run 256 (`actions_log` on the Forgejo host). Scenario summary preserved in this issue for when the log rotates.

robocub referenced this issue from a commit

2026-07-11 16:11:28 +00:00

fix(discord): retry puppet rejoin on JoinError::Dropped (recovery race)

robocub commented

2026-07-11 16:11:51 +00:00

Author

Collaborator

Triaged live (staging + bridge logs). The 3 failures split into two causes:

Recovery scenarios (external_disconnect_recovery + force_move_recovery) — root-caused + FIXED (6a3ac86, master).
The same-bot rejoin lost the manager.remove()→manager.join() race and got JoinError::Dropped ("request was cancelled/dropped"): songbird remove = leave + drop, and leave sends a gateway leave op even for a mod-KICKED connection, whose confirmation echo cancels the immediate rejoin. The bot was then needlessly quarantined → failover; force_move failed as a cascade (the prior SIGKILLed scenario left a zombie bot in the channel that force_move's probe then targeted instead of the real puppet). Fix: retry puppet_join up to 3× on JoinError::Dropped. Live-verified — both PASS (33.3s / 13.4s), the retry fires and same-bot recovery succeeds (~1.2s), no quarantine/failover. Note: production channel recovery still worked via failover; the real gap was the no-spare case (one bot in the guild) where Dropped = no recovery.

shutdown_drain — CI-container contention, folded into #74.
Passes on staging (123.6s). The 10s TEARDOWN_TIMEOUT is exceeded under CI load so the drain logs the timeout branch instead of "all bridges drained cleanly" (clean exit-0 regardless). This is the #74 voice-leave-flush symptom; fixing #74 resolves it. Keeping this issue open until the #74 fix lands.

Triaged live (staging + bridge logs). The 3 failures split into two causes: **Recovery scenarios (`external_disconnect_recovery` + `force_move_recovery`) — root-caused + FIXED (`6a3ac86`, master).** The same-bot rejoin lost the `manager.remove()`→`manager.join()` race and got `JoinError::Dropped` ("request was cancelled/dropped"): songbird `remove` = `leave` + drop, and `leave` sends a gateway leave op even for a mod-KICKED connection, whose confirmation echo cancels the immediate rejoin. The bot was then needlessly quarantined → failover; `force_move` failed as a **cascade** (the prior SIGKILLed scenario left a zombie bot in the channel that force_move's probe then targeted instead of the real puppet). Fix: retry `puppet_join` up to 3× on `JoinError::Dropped`. Live-verified — both PASS (33.3s / 13.4s), the retry fires and same-bot recovery succeeds (~1.2s), no quarantine/failover. Note: production channel recovery still worked via failover; the real gap was the no-spare case (one bot in the guild) where `Dropped` = no recovery. **`shutdown_drain` — CI-container contention, folded into #74.** Passes on staging (123.6s). The 10s `TEARDOWN_TIMEOUT` is exceeded under CI load so the drain logs the timeout branch instead of "all bridges drained cleanly" (clean exit-0 regardless). This is the #74 voice-leave-flush symptom; fixing #74 resolves it. Keeping this issue open until the #74 fix lands.

robocub referenced this issue from a commit

2026-07-11 17:06:23 +00:00

fix(discord): flush puppet voice-leave on shutdown before dropping clients (#74)

robocub commented

2026-07-11 17:07:14 +00:00

Author

Collaborator

All three triaged and fixed:

external_disconnect_recovery + force_move_recovery — JoinError::Dropped same-bot rejoin race (force_move failed as a cascade off it). Fixed by retry-on-Dropped in 6a3ac86 (shipped in alpha.18). Live PASS 33.3s / 13.4s; log confirms the retry fires and same-bot recovery succeeds.
shutdown_drain — CI-container contention on the drain (the #74 voice-leave-flush symptom). Fixed by #74 (cf82850): the drain now flushes the leave before dropping the clients, and the scenario baseline window tightened 150s→30s. Live PASS 26.6s (even under host load 13).

All three verified individually on staging against master. The next scheduled nightly (--all) should confirm 16/16 green — reopen if any of these regress there. Closing.

All three triaged and fixed: - **`external_disconnect_recovery` + `force_move_recovery`** — `JoinError::Dropped` same-bot rejoin race (force_move failed as a cascade off it). Fixed by retry-on-Dropped in `6a3ac86` (**shipped in alpha.18**). Live PASS 33.3s / 13.4s; log confirms the retry fires and same-bot recovery succeeds. - **`shutdown_drain`** — CI-container contention on the drain (the #74 voice-leave-flush symptom). Fixed by #74 (`cf82850`): the drain now flushes the leave before dropping the clients, and the scenario baseline window tightened 150s→30s. Live PASS 26.6s (even under host load 13). All three verified individually on staging against master. The next scheduled nightly (`--all`) should confirm 16/16 green — reopen if any of these regress there. Closing.

robocub closed this issue

2026-07-11 17:07:14 +00:00

robocub referenced this issue

2026-07-11 20:04:55 +00:00

LiveKit ICE candidate lottery: connections intermittently establish with ZERO media (affects prod audio) #91

robocub referenced this issue from a commit

2026-07-11 21:26:53 +00:00

test(e2e): add recovery_no_spare scenario (#81 rejoin-race severe case)

robocub referenced this issue

2026-07-11 22:33:36 +00:00

Automatic Testing #38