diff --git a/src/music/spotify/controller.test.ts b/src/music/spotify/controller.test.ts index 1bf4efc..797ff7a 100644 --- a/src/music/spotify/controller.test.ts +++ b/src/music/spotify/controller.test.ts @@ -97,10 +97,14 @@ class FakeBackend extends EventEmitter implements SpotifyAudioBackend { ready = false; startShouldReject = false; playShouldReject = false; + /** When set, start() awaits this before resolving — lets a test interleave + * stop()/error DURING a mid-flight start (Bug I1). */ + startGate?: Promise; readonly pcm = Readable.from([Buffer.alloc(0)]); async start(): Promise { this.startCalls++; + if (this.startGate) await this.startGate; if (this.startShouldReject) throw new Error("start boom"); this.ready = true; } @@ -464,6 +468,40 @@ describe("SpotifyController.stop", () => { expect(() => ctrl.stop()).not.toThrow(); expect(be.stopCalls).toBe(0); }); + + it("Bug I1: stop() DURING a mid-flight start tears the sidecar down instead of resurrecting it", async () => { + // A Deferred the test resolves to complete backend.start() on demand. + let resolveStart!: () => void; + const startGate = new Promise((res) => { + resolveStart = res; + }); + const be = new FakeBackend(); + be.startGate = startGate; + const { ctrl } = makeCtrl({ backendFactory: () => be }); + + // Kick off ensureStarted but DO NOT await — start() is parked on the gate. + const startedP = ctrl.ensureStarted(); + // Let the ensureStarted IIFE run up to `await backend.start()`. + await Promise.resolve(); + await Promise.resolve(); + expect(be.startCalls).toBe(1); // start() was entered and is now pending + + // Caller tears the controller down while start() is still in flight + // (a user `!stop`/disconnect). Pre-fix this.backend is still null so this + // is a no-op and the spawned sidecar is orphaned. + ctrl.stop(); + + // Now let start() finally resolve. Pre-fix the IIFE would set this.backend + // and started=true, RESURRECTING the sidecar the caller already stopped. + resolveStart(); + const result = await startedP; + + // Post-fix: the mid-flight backend is torn down, not promoted. + expect(result).toBe(false); + expect(be.stopCalls).toBeGreaterThanOrEqual(1); // the fake WAS stopped + expect(be.listenerCount("trackEnded")).toBe(0); // listeners detached + expect(() => ctrl.getPcmStream()).toThrow(); // not resurrected + }); }); describe("SpotifyController per-bot ports (Fix 3)", () => { diff --git a/src/music/spotify/controller.ts b/src/music/spotify/controller.ts index 3b2f937..2fa2e0d 100644 --- a/src/music/spotify/controller.ts +++ b/src/music/spotify/controller.ts @@ -105,6 +105,12 @@ export class SpotifyController extends EventEmitter { private readonly connect: SpotifyConnectApi; private backend: SpotifyAudioBackend | null = null; + // The in-flight backend during a start() that has not yet completed. A + // stop()/handleBackendError() DURING start() clears (or replaces) this so the + // mid-start sidecar is torn down and a completing start is discarded by the + // ensureStarted post-await guard instead of resurrecting a backend the caller + // already tore down (Bug I1). + private pendingBackend: SpotifyAudioBackend | null = null; private started = false; private startPromise: Promise | null = null; @@ -218,30 +224,75 @@ export class SpotifyController extends EventEmitter { if (this.startPromise) return this.startPromise; this.startPromise = (async () => { + const backend = this.buildBackend(kind); + // Publish the in-flight backend BEFORE the (potentially ~20s) start() + // await so a concurrent stop()/handleBackendError() can reach and tear + // down this mid-start sidecar (Bug I1). + this.pendingBackend = backend; + backend.on("trackEnded", (e: SpotifyTrackEndedEvent) => + this.emit("trackEnded", e), + ); + backend.on("metadata", (m: SpotifyNowPlaying) => + this.emit("metadata", m), + ); + // C3: do NOT re-emit "error". Log and mark not-ready so the next + // ensureStarted() relaunches a fresh backend. + backend.on("error", (err?: unknown) => this.handleBackendError(err)); try { - const backend = this.buildBackend(kind); - backend.on("trackEnded", (e: SpotifyTrackEndedEvent) => - this.emit("trackEnded", e), - ); - backend.on("metadata", (m: SpotifyNowPlaying) => - this.emit("metadata", m), - ); - // C3: do NOT re-emit "error". Log and mark not-ready so the next - // ensureStarted() relaunches a fresh backend. - backend.on("error", (err?: unknown) => this.handleBackendError(err)); await backend.start(); - this.backend = backend; - this.started = true; - return true; } catch (err) { this.logger.error({ err }, "Spotify backend failed to start"); + if (this.pendingBackend === backend) this.pendingBackend = null; this.startPromise = null; return false; } + // Post-await guard (Bug I1): if teardown ran DURING start() — stop() or + // handleBackendError() cleared/replaced pendingBackend — do NOT promote + // this backend. Tear the just-started sidecar down so it is neither + // leaked nor resurrected, and report failure to the caller. + if (this.pendingBackend !== backend) { + this.teardownBackend( + backend, + "Spotify backend stop() threw tearing down a superseded start", + ); + return false; + } + this.pendingBackend = null; + this.backend = backend; + this.started = true; + return true; })(); return this.startPromise; } + /** + * Stop a backend and detach ALL its listeners, swallowing+logging any throw + * from stop() so teardown never propagates. Shared by the error/stop paths + * and the ensureStarted post-await guard. + */ + private teardownBackend(be: SpotifyAudioBackend, stopMsg: string): void { + try { + be.stop(); + } catch (stopErr) { + this.logger.error({ err: stopErr }, stopMsg); + } + (be as unknown as EventEmitter).removeAllListeners(); + } + + /** + * Tear down an in-flight (mid-start) backend so a start() still awaiting is + * discarded by ensureStarted's post-await guard rather than promoted, and its + * spawned sidecar is killed rather than orphaned (Bug I1). + */ + private teardownPendingBackend(): void { + if (!this.pendingBackend) return; + this.teardownBackend( + this.pendingBackend, + "Spotify backend stop() threw tearing down in-flight start", + ); + this.pendingBackend = null; + } + /** * C3 backend-error handler. Never re-emits "error" (an unhandled "error" on * an EventEmitter throws). Logs, tears the errored backend down, and marks @@ -249,16 +300,15 @@ export class SpotifyController extends EventEmitter { */ private handleBackendError(err: unknown): void { this.logger.error({ err }, "Spotify backend error; marking not-ready"); - try { - this.backend?.stop(); - } catch (stopErr) { - this.logger.error( - { err: stopErr }, + if (this.backend) { + this.teardownBackend( + this.backend, "Spotify backend stop() threw during error teardown", ); } - (this.backend as unknown as EventEmitter | null)?.removeAllListeners(); this.backend = null; + // Also kill an in-flight start so its post-await guard discards it. + this.teardownPendingBackend(); this.started = false; this.startPromise = null; } @@ -301,16 +351,16 @@ export class SpotifyController extends EventEmitter { * a fresh backend. */ stop(): void { - try { - this.backend?.stop(); - } catch (stopErr) { - this.logger.error( - { err: stopErr }, + if (this.backend) { + this.teardownBackend( + this.backend, "Spotify backend stop() threw during teardown", ); } - (this.backend as unknown as EventEmitter | null)?.removeAllListeners(); this.backend = null; + // Also kill an in-flight start so its post-await guard discards it rather + // than resurrecting the sidecar this stop() just tore down (Bug I1). + this.teardownPendingBackend(); this.started = false; this.startPromise = null; } diff --git a/src/music/spotify/rust-librespot.test.ts b/src/music/spotify/rust-librespot.test.ts index 2e539c7..64a8b7f 100644 --- a/src/music/spotify/rust-librespot.test.ts +++ b/src/music/spotify/rust-librespot.test.ts @@ -2,7 +2,7 @@ import { describe, it, expect, vi } from "vitest"; import { EventEmitter } from "node:events"; import { PassThrough } from "node:stream"; import pino from "pino"; -import { RustLibrespotBackend } from "./rust-librespot.js"; +import { RustLibrespotBackend, type RustLibrespotBackendDeps } from "./rust-librespot.js"; const log = pino({ level: "silent" }); @@ -36,7 +36,9 @@ function makeOAuth() { }; } -function makeHarness(over: { connect?: any; oauth?: any } = {}) { +function makeHarness( + over: { connect?: any; oauth?: any; deps?: Partial } = {}, +) { const calls: string[] = []; const librespotChild = makeFakeChild(); const ffmpegChild = makeFakeChild(); @@ -68,6 +70,7 @@ function makeHarness(over: { connect?: any; oauth?: any } = {}) { readyTimeoutMs: 100, // huge so the background setInterval never fires; tests drive pollState() directly. statePollIntervalMs: 10_000_000, + ...over.deps, }, }); @@ -280,6 +283,117 @@ describe("RustLibrespotBackend track-end poll loop", () => { }); }); +describe("RustLibrespotBackend playback-start watchdog (I4 degrade-to-skip)", () => { + /** A controllable timer seam matching the file's injected-deps style. */ + function makeFakeTimer() { + const pending: Array<{ cb: () => void; ms: number; handle: object }> = []; + const setTimer = vi.fn((cb: () => void, ms: number) => { + const handle = {}; + pending.push({ cb, ms, handle }); + return handle; + }); + const clearTimer = vi.fn((h: unknown) => { + const i = pending.findIndex((p) => p.handle === h); + if (i >= 0) pending.splice(i, 1); + }); + // "advance fake timers": run (and drain) every armed callback. + const advance = () => pending.splice(0).forEach((p) => p.cb()); + return { setTimer, clearTimer, advance, pending }; + } + + it("emits exactly ONE trackEnded{reason:'error'} when playback never starts", async () => { + const timer = makeFakeTimer(); + const h = makeHarness({ + deps: { + playbackStartTimeoutMs: 8000, + setTimeout: timer.setTimer as any, + clearTimeout: timer.clearTimer as any, + }, + }); + const ended = vi.fn(); + h.backend.on("trackEnded", ended); + + // The connect layer NEVER reports our track playing (204 / idle). + h.connect.getPlaybackState.mockResolvedValue(null); + await h.backend.playTrack("spotify:track:stuck"); + // Polls that never observe playback must NOT emit anything on their own. + await (h.backend as any).pollState(); + await (h.backend as any).pollState(); + expect(ended).not.toHaveBeenCalled(); + + // The watchdog is armed exactly once; advance past playbackStartTimeoutMs. + expect(timer.pending).toHaveLength(1); + expect(timer.pending[0].ms).toBe(8000); + timer.advance(); + + // Degraded-to-skip: one trackEnded with reason "error" for our uri. + expect(ended).toHaveBeenCalledTimes(1); + expect(ended).toHaveBeenCalledWith({ uri: "spotify:track:stuck", reason: "error" }); + + // A late idle poll after the watchdog fired does not double-emit. + await (h.backend as any).pollState(); + expect(ended).toHaveBeenCalledTimes(1); + h.backend.stop(); + }); + + it("does NOT fire the watchdog when the device actually starts playing", async () => { + const timer = makeFakeTimer(); + const h = makeHarness({ + deps: { + playbackStartTimeoutMs: 8000, + setTimeout: timer.setTimer as any, + clearTimeout: timer.clearTimer as any, + }, + }); + const ended = vi.fn(); + h.backend.on("trackEnded", ended); + + await h.backend.playTrack("spotify:track:ok"); + // Our device reports the track actually playing -> watchdog is disarmed. + h.connect.getPlaybackState.mockResolvedValue({ + isPlaying: true, + progressMs: 1000, + trackUri: "spotify:track:ok", + durationMs: 200000, + }); + await (h.backend as any).pollState(); + + // Real playback observed -> the watchdog was cleared, not left armed. + expect(timer.clearTimer).toHaveBeenCalled(); + expect(timer.pending).toHaveLength(0); + // Even if a stale timer somehow fired, no "error" end must be emitted. + timer.advance(); + expect(ended).not.toHaveBeenCalledWith( + expect.objectContaining({ reason: "error" }), + ); + h.backend.stop(); + }); + + it("a new playTrack() cancels the previous track's watchdog (at-most-one per track)", async () => { + const timer = makeFakeTimer(); + const h = makeHarness({ + deps: { + playbackStartTimeoutMs: 8000, + setTimeout: timer.setTimer as any, + clearTimeout: timer.clearTimer as any, + }, + }); + const ended = vi.fn(); + h.backend.on("trackEnded", ended); + h.connect.getPlaybackState.mockResolvedValue(null); + + await h.backend.playTrack("spotify:track:one"); + await h.backend.playTrack("spotify:track:two"); + // The first track's watchdog was cleared; only the second remains armed. + expect(timer.clearTimer).toHaveBeenCalled(); + expect(timer.pending).toHaveLength(1); + timer.advance(); + expect(ended).toHaveBeenCalledTimes(1); + expect(ended).toHaveBeenCalledWith({ uri: "spotify:track:two", reason: "error" }); + h.backend.stop(); + }); +}); + describe("RustLibrespotBackend.stop", () => { it("kills librespot + ffmpeg, clears ready, and is idempotent", async () => { const h = makeHarness(); diff --git a/src/music/spotify/rust-librespot.ts b/src/music/spotify/rust-librespot.ts index 7dc9f19..a2081fc 100644 --- a/src/music/spotify/rust-librespot.ts +++ b/src/music/spotify/rust-librespot.ts @@ -40,6 +40,15 @@ export interface RustLibrespotBackendDeps { readyPollIntervalMs?: number; readyTimeoutMs?: number; statePollIntervalMs?: number; + /** + * I4 (§13): bounded window after playTrack() within which our own track must + * be observed playing, else we degrade-to-skipped (emit trackEnded + * reason:"error"). Injectable timer seams (default real setTimeout, unref'd) + * let tests advance it deterministically. + */ + playbackStartTimeoutMs?: number; + setTimeout?: (cb: () => void, ms: number) => unknown; + clearTimeout?: (handle: unknown) => void; } const DEFAULT_READY_POLL_MS = 500; @@ -47,6 +56,13 @@ const DEFAULT_READY_TIMEOUT_MS = 20_000; const DEFAULT_STATE_POLL_MS = 2_000; /** How close to the end (ms) counts as "track finished" when polling player state. */ const END_OF_TRACK_WINDOW_MS = 1_500; +/** + * I4 (§13): if our own track has not been observed playing within this window + * after playTrack(), degrade-to-skipped so the queue advances instead of + * stalling on a persistently-failing play (403 non-Premium, 404 outliving + * retries). Bounded and injectable for tests. + */ +const DEFAULT_PLAYBACK_START_TIMEOUT_MS = 8_000; const defaultSleep = (ms: number) => new Promise((r) => setTimeout(r, ms)); @@ -60,6 +76,9 @@ export class RustLibrespotBackend extends EventEmitter implements SpotifyAudioBa private proc: ChildProcess | null = null; private ffmpeg: ChildProcess | null = null; private pollTimer: ReturnType | null = null; + // I4 (§13): "did our track actually start playing?" watchdog handle (opaque — + // produced by the injectable setTimeout seam). null when disarmed. + private watchdogTimer: unknown = null; private ready = false; private positionMs = 0; @@ -253,7 +272,11 @@ export class RustLibrespotBackend extends EventEmitter implements SpotifyAudioBa this.emit("metadata", np); } - if (state.isPlaying) this.hasPlayed = true; + if (state.isPlaying) { + this.hasPlayed = true; + // Real playback observed -> the I4 degrade-to-skip watchdog is moot. + this.clearPlaybackWatchdog(); + } if (!this.currentUri || this.endedForCurrent) return; // C3.4: EVERY end condition is gated on hasPlayed so no end can fire until @@ -289,6 +312,9 @@ export class RustLibrespotBackend extends EventEmitter implements SpotifyAudioBa // uri playing. currentUri is cleared so the next poll re-detects the track // (fresh metadata) rather than treating it as unchanged. Arming here is the // primary guarantee that no end/metadata can fire before the bot plays. + // Cancel the previous track's degrade-to-skip watchdog first (at-most-one + // trackEnded per track, I4). + this.clearPlaybackWatchdog(); this.currentUri = null; this.hasPlayed = false; this.endedForCurrent = false; @@ -298,6 +324,58 @@ export class RustLibrespotBackend extends EventEmitter implements SpotifyAudioBa // begin playback. await this.connect.transfer(deviceId, false); await this.connect.play(deviceId, uri); + // I4 (§13): arm the "did it actually start playing?" watchdog. If our own + // track is never seen playing within the window, degrade-to-skipped so the + // queue advances instead of hanging on a silent, persistently-failing play. + this.armPlaybackWatchdog(uri); + } + + /** + * I4 (§13) degrade-to-skip watchdog. Arms a bounded timer; if our own track + * has not been observed playing by the time it fires, emit a single + * trackEnded{reason:"error"} so the controller re-emits it and BotInstance + * advances the queue. Cleared when real playback is observed, on stop(), and + * at the start of a new playTrack(). + */ + private armPlaybackWatchdog(uri: string): void { + this.clearPlaybackWatchdog(); + const timeoutMs = this.deps.playbackStartTimeoutMs ?? DEFAULT_PLAYBACK_START_TIMEOUT_MS; + const setTimer = + this.deps.setTimeout ?? + ((cb: () => void, ms: number) => { + const t = setTimeout(cb, ms); + (t as { unref?: () => void }).unref?.(); + return t; + }); + this.watchdogTimer = setTimer(() => { + this.watchdogTimer = null; + this.onPlaybackStartTimeout(uri); + }, timeoutMs); + } + + private clearPlaybackWatchdog(): void { + if (this.watchdogTimer == null) return; + const clearTimer = + this.deps.clearTimeout ?? + ((h: unknown) => clearTimeout(h as ReturnType)); + clearTimer(this.watchdogTimer); + this.watchdogTimer = null; + } + + /** + * Fired when the playback-start window elapses with no observed playback. + * C3.6: never throws up the queue path. Guarded by the same endedForCurrent + * latch as normal end-detection so at most one trackEnded per track (no + * double-emit with the poll-loop end detection). + */ + private onPlaybackStartTimeout(uri: string): void { + // Real playback was seen (hasPlayed) or the track already ended -> moot. + if (this.hasPlayed || this.endedForCurrent) return; + this.endedForCurrent = true; // latch + this.currentUri = null; + this.positionMs = 0; + const e: SpotifyTrackEndedEvent = { uri, reason: "error" }; + this.emit("trackEnded", e); } async pause(): Promise { @@ -325,6 +403,8 @@ export class RustLibrespotBackend extends EventEmitter implements SpotifyAudioBa stop(): void { this.ready = false; + // Disarm the I4 degrade-to-skip watchdog so a stopped backend never emits. + this.clearPlaybackWatchdog(); // Clear the state poll interval FIRST so no poll fires mid-teardown. if (this.pollTimer) { clearInterval(this.pollTimer);