mirror of
https://github.com/ZHANGTIANYAO1/teamspeak-music-bot.git
synced 2026-10-02 04:52:50 +08:00
fix(spotify): tear down in-flight backend on stop + degrade-to-skip on persistent play failure [whole-branch I1,I4]
Co-Authored-By: Claude Opus 4.8 (1M context) <noreply@anthropic.com>
This commit is contained in:
1 parent
dc763ec689
commit
b4c3cc0539
4 files changed
+301
-19
No files matched your search
@@ -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<void>;
|
||||
readonly pcm = Readable.from([Buffer.alloc(0)]);
|
||||
|
||||
async start(): Promise<void> {
|
||||
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<void>((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)", () => {
|
||||
|
||||
@@ -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<boolean> | null = null;
|
||||
|
||||
@@ -218,8 +224,11 @@ export class SpotifyController extends EventEmitter {
|
||||
if (this.startPromise) return this.startPromise;
|
||||
|
||||
this.startPromise = (async () => {
|
||||
try {
|
||||
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),
|
||||
);
|
||||
@@ -229,19 +238,61 @@ export class SpotifyController extends EventEmitter {
|
||||
// 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 {
|
||||
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;
|
||||
}
|
||||
|
||||
@@ -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<RustLibrespotBackendDeps> } = {},
|
||||
) {
|
||||
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();
|
||||
|
||||
@@ -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<void>((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<typeof setInterval> | 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<typeof setTimeout>));
|
||||
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<void> {
|
||||
@@ -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);
|
||||
|
||||
Reference in new issue
Block a user