diff --git a/DeskThingServer/src/main/services/music/MusicService.ts b/DeskThingServer/src/main/services/music/MusicService.ts index a6010abf..a7938e50 100644 --- a/DeskThingServer/src/main/services/music/MusicService.ts +++ b/DeskThingServer/src/main/services/music/MusicService.ts @@ -22,6 +22,30 @@ import { ColorExtractor } from './ColorExtractor' * Core service that manages music playback functionality */ export class MusicService implements MusicStoreClass { + /** + * How long to wait for the answer to each attempt when chasing a track + * change. Every entry is a request followed by that pause before looking at + * the result, so the list is both the retry count and the total window — + * about seven seconds, which comfortably covers the provider's own lag in + * reporting a skip. The chase stops the moment the track is different, so + * the usual cost is the first entry alone. + */ + private static readonly TRACK_CHANGE_RETRY_DELAYS_MS = [600, 900, 1200, 1800, 2500] + + /** How long to wait for a refresh request to be handed off before moving on. */ + private static readonly REFRESH_SEND_TIMEOUT_MS = 2000 + + /** + * Poll cadence while a client is connected and something is playing. This is + * the only thing that notices playback changed from the provider's own app on + * another device, so it bounds how stale the screen can be in that case. + * Costs one request per tick and, because the source only reports genuine + * state changes, sends nothing to clients unless something actually changed. + */ + private static readonly ACTIVE_REFRESH_INTERVAL_MS = 2000 + + private chaseGeneration = 0 + private configuredRefreshRate = -1 private refreshInterval: NodeJS.Timeout | null = null private currentApp: string | null = null private songCache: SongCache @@ -61,27 +85,73 @@ export class MusicService implements MusicStoreClass { async updateRefreshInterval(refreshRate: number): Promise { if (this.refreshInterval) { - clearInterval(this.refreshInterval) + clearTimeout(this.refreshInterval) + this.refreshInterval = null } + this.configuredRefreshRate = refreshRate + if (refreshRate < 0) { Logger.log(LOGGING_LEVELS.LOG, `Music refresh disabled`) return } - if (refreshRate < 5000) { - Logger.log(LOGGING_LEVELS.WARN, `Refresh interval of ${refreshRate}s may impact performance`) - if (refreshRate < 1000) { - Logger.log( - LOGGING_LEVELS.WARN, - `Extremely low refresh interval (${refreshRate}s) could cause system issues` - ) - } + if (refreshRate < 1000) { + Logger.log( + LOGGING_LEVELS.WARN, + `Extremely low refresh interval (${refreshRate}ms) could cause system issues` + ) } - this.refreshInterval = setInterval(() => { - this.refreshMusicData() - }, refreshRate) + this.scheduleRefresh() + } + + /** + * Pick the next poll delay from what is actually happening, and schedule one + * poll at a time rather than running a fixed interval. + * + * A track that ends on its own, and a skip made from a connected client, are + * both handled the moment they happen — one is predicted from the track's own + * duration, the other is observed as a command. Neither needs the poll. + * + * What the poll is for is the case with no boundary to predict and no command + * to observe: playback changed somewhere else entirely, from the provider's + * own app on a phone or desktop. Nothing announces that, so the only way to + * notice is to look — and at the configured 15s that meant a change made + * elsewhere took up to 15s to appear, which is the whole of the delay users + * still saw after the boundary work. + * + * So look often, but only while it can matter: something is connected to show + * it, and something is actually playing. Idle or paused, this falls back to + * the configured rate, because a poll that nobody can see is pure cost — and + * cost here is provider rate limit, which is not free to spend. + */ + private scheduleRefresh(): void { + if (this.refreshInterval) { + clearTimeout(this.refreshInterval) + this.refreshInterval = null + } + + if (this.configuredRefreshRate < 0) return + + const song = this.songCache.getCurrentSong() + const someoneIsWatching = this.platformStore.getClients().length > 0 + const active = someoneIsWatching && song?.is_playing === true + + // Never poll slower than configured, and never faster than the active rate. + const delay = active + ? Math.min(MusicService.ACTIVE_REFRESH_INTERVAL_MS, this.configuredRefreshRate) + : this.configuredRefreshRate + + this.refreshInterval = setTimeout(async () => { + try { + await this.refreshMusicData() + } finally { + // Reschedule from here rather than on a fixed interval, so a slow poll + // cannot stack requests on top of itself. + this.scheduleRefresh() + } + }, delay) } async setAudioSource(source: string): Promise { @@ -172,12 +242,15 @@ export class MusicService implements MusicStoreClass { } break - // These requests don't need cache updates, just pass through + // A skip has the same shape as a track boundary: we know playback is + // about to be something else, but the provider will keep reporting the + // old track for a moment. Asking once loses that race and drops the user + // back onto the scheduled refresh, so chase it the same way. case AUDIO_REQUESTS.NEXT: case AUDIO_REQUESTS.PREVIOUS: case AUDIO_REQUESTS.REWIND: case AUDIO_REQUESTS.FAST_FORWARD: - this.refreshMusicData() + this.chaseTrackChange() break case AUDIO_REQUESTS.LIKE: case AUDIO_REQUESTS.VOLUME: @@ -200,6 +273,14 @@ export class MusicService implements MusicStoreClass { if (cachedSong) { await this.sendMusicToClient(client.clientId) } + // Someone can see the screen now — start looking often enough to keep it + // honest about changes made elsewhere. + this.scheduleRefresh() + }) + + // ...and stop paying for that the moment nobody is watching. + this.platformStore.on(PlatformStoreEvent.CLIENT_DISCONNECTED, () => { + this.scheduleRefresh() }) // Listen for app messages @@ -234,12 +315,81 @@ export class MusicService implements MusicStoreClass { // Listen for song end events this.songCache.on(SongCacheEvents.SONG_ENDED, () => { - this.refreshMusicData() + this.chaseTrackChange() }) - this.songCache.on(SongCacheEvents.SONG_CHANGED, (data) => { - this.refreshMusicData(data) + // Pausing or resuming changes whether a fast poll is worth paying for. + this.songCache.on(SongCacheEvents.SONG_CHANGED, () => { + this.scheduleRefresh() }) + + // NOTE: SONG_CHANGED deliberately does not broadcast. handleMusicPayload + // already broadcasts every payload it caches, and it broadcasts the + // normalised copy — the one whose thumbnail has been rewritten to a URL + // the client can actually fetch. Broadcasting again from here sent the raw + // payload as a second, worse copy of the same update. + } + + /** + * Ask again, briefly, until the track we were told ended is actually gone. + * + * Asking once at the boundary reliably fails: the provider still reports the + * finishing track for around a second afterwards, the change-detect gate + * sees nothing new, and the update waits for the next scheduled poll — which + * is how a one-second gap became a fifteen-second one. + * + * The ladder is short and stops the moment it has an answer, because an + * unbounded retry at a track boundary is exactly how an account earns a + * multi-hour Retry-After. + */ + private async chaseTrackChange(): Promise { + // Only one chase should be in flight, but a later one must be able to + // replace an earlier one rather than be dropped: it is chasing a different + // change, from a different starting track. A plain "already chasing" flag + // both discarded those and — worse — wedged permanently if a chase ever + // failed to finish, silently disabling every future chase and sending + // every skip back to the scheduled poll. + const generation = ++this.chaseGeneration + + const leaving = this.songCache.getCurrentSong() + const leavingId = leaving?.id + const leavingName = leaving?.track_name + const leavingProgress = leaving?.track_progress + + for (const wait of MusicService.TRACK_CHANGE_RETRY_DELAYS_MS) { + if (generation !== this.chaseGeneration) return // superseded by a newer chase + + // Never let one request hold the chase open. A send that does not settle + // would otherwise stall the whole ladder behind it. + await Promise.race([ + this.refreshMusicData(undefined, { force: true }), + new Promise((resolve) => setTimeout(resolve, MusicService.REFRESH_SEND_TIMEOUT_MS)) + ]).catch(() => {}) + + // Wait BEFORE looking. refreshMusicData only hands the request to the + // source app; the answer arrives later, over a separate message, and + // updates the cache then. Checking immediately after sending always + // reads the track we are trying to leave, so every attempt "fails" and + // the chase gives up on a change it had in fact already asked for — + // which is how a skip fell back to the scheduled poll and took a full + // cycle instead of about a second. + await new Promise((resolve) => setTimeout(resolve, wait)) + + const now = this.songCache.getCurrentSong() + if (!now) continue + + // Stop when the track is genuinely different. Repeat-one replays the + // same id, so a progress collapse counts as a change too — otherwise + // the chase would run to exhaustion on every looped track. + const isDifferent = now.id !== leavingId || now.track_name !== leavingName + const restarted = + leavingProgress != null && now.track_progress != null && now.track_progress < leavingProgress + + if (isDifferent || restarted) return + + // Nothing is playing any more — there is no next track to wait for. + if (now.is_playing === false) return + } } private handleMusicPayload = async (songData: SongData): Promise => { @@ -404,7 +554,10 @@ export class MusicService implements MusicStoreClass { return this.currentApp } - private async refreshMusicData(songData?: SongData): Promise { + private async refreshMusicData( + songData?: SongData, + options: { force?: boolean } = {} + ): Promise { if (songData) { await this.platformStore.broadcastToClients({ type: DESKTHING_DEVICE.MUSIC, @@ -426,7 +579,11 @@ export class MusicService implements MusicStoreClass { await this.appStore.sendDataToApp(currentApp, { type: SongEvent.GET, request: AUDIO_REQUESTS.REFRESH, - app: 'music' + app: 'music', + // Tells the source not to answer from a coalesced in-flight request. + // Only set when we already know playback changed, so the ordinary + // cadence keeps its de-duplication. + payload: options.force || undefined }) Logger.log(LOGGING_LEVELS.LOG, `Refreshed music data from ${currentApp}`) } catch (error) { diff --git a/DeskThingServer/src/main/services/music/songCache.ts b/DeskThingServer/src/main/services/music/songCache.ts index 424fb1a9..cb4d8fc3 100644 --- a/DeskThingServer/src/main/services/music/songCache.ts +++ b/DeskThingServer/src/main/services/music/songCache.ts @@ -19,6 +19,19 @@ type SongCacheEventMap = { * Manages the caching of song data and emits events when songs change or end */ export class SongCache extends EventEmitter { + /** + * Progress moves on its own while a track plays. Only a jump bigger than a + * poll's worth of playback means the listener actually seeked. + */ + private static readonly SEEK_TOLERANCE_MS = 3000 + + /** + * Ask for the next track slightly after the current one runs out. Querying + * at the exact boundary races the provider, which usually still reports the + * track that just finished. + */ + private static readonly END_OF_TRACK_GRACE_MS = 750 + private currentSong: SongData | null = null private songEndTimeout: NodeJS.Timeout | null = null private progressInterval: NodeJS.Timeout | null = null @@ -44,16 +57,29 @@ export class SongCache extends EventEmitter { return } - // Check if song has actually changed - const hasSongChanged = + // A track that is simply playing is not a track that changed. Treating + // every progress advance as a change made setNewSong run on each poll, + // which tore down and rebuilt the end-of-track timer every time and fired + // a redundant SONG_CHANGED broadcast on each one. + const isDifferentTrack = this.currentSong.track_name !== newSong.track_name || this.currentSong.artist !== newSong.artist || this.currentSong.album !== newSong.album || - this.currentSong.is_playing !== newSong.is_playing || - this.currentSong.track_progress !== newSong.track_progress || this.currentSong.track_duration !== newSong.track_duration - if (hasSongChanged) { + const playbackFlipped = this.currentSong.is_playing !== newSong.is_playing + + // A seek is a progress jump larger than playback alone can explain. The + // comparison is against the cached value rather than the last polled one + // because the progress interval above keeps the cache advancing in real + // time — so this is already "where the track should be by now", and an + // ordinary poll lands within the tolerance no matter how long the gap + // between polls is. + const jumped = + Math.abs((newSong.track_progress ?? 0) - (this.currentSong.track_progress ?? 0)) > + SongCache.SEEK_TOLERANCE_MS + + if (isDifferentTrack || playbackFlipped || jumped) { this.setNewSong(newSong) } else { // Update progress/state without emitting change @@ -210,38 +236,41 @@ export class SongCache extends EventEmitter { this.progressInterval = null } - // Set interval for progress updates and timeout for song end if we have duration and progress - if (song.track_duration && song.track_progress && song.is_playing) { - const remainingTime = song.track_duration - song.track_progress - - // Update progress every second + // Keep the cached progress moving between polls, so a client that connects + // mid-track is told where the track actually is. Note this only advances + // the cache — it is not what detects the end of the track. + if (song.track_duration && song.is_playing) { this.progressInterval = setInterval(() => { - if ( - this.currentSong && - this.currentSong.track_progress && - this.currentSong.track_duration - ) { - this.currentSong.track_progress += 1000 - if (this.currentSong.track_progress >= this.currentSong.track_duration) { - Logger.debug('Song ended based on duration', { - source: 'SongCache', - function: 'setNewSong' - }) - this.emit(SongCacheEvents.SONG_ENDED) - this.clear() - } - } + const current = this.currentSong + if (current?.track_duration == null) return + current.track_progress = Math.min( + (current.track_progress ?? 0) + 1000, + current.track_duration + ) }, 1000) - // Set a backup timeout for song end - this.songEndTimeout = setTimeout(() => { - Logger.debug('Song ended based on duration (backup timeout)', { - source: 'SongCache', - function: 'setNewSong' - }) - this.emit(SongCacheEvents.SONG_ENDED) - this.clear() - }, remainingTime) + // The track's own remaining time is the one piece of information that + // says exactly when the next track begins, so schedule for it rather + // than waiting for the next poll to stumble across the change. + // + // `track_progress ?? 0` matters: a track first seen at progress 0 is + // falsy, and the previous `song.track_progress &&` guard skipped the + // timer entirely for it — precisely the track that needed it most. + const remainingTime = song.track_duration - (song.track_progress ?? 0) + + if (remainingTime > 0) { + this.songEndTimeout = setTimeout(() => { + Logger.debug('Song reached the end of its duration', { + source: 'SongCache', + function: 'setNewSong' + }) + // Deliberately NOT clear() — dropping the cached song here left a + // client that connected during the gap with nothing to show, and + // killed the progress interval for the track that replaces it. The + // refresh this triggers will overwrite the entry a moment later. + this.emit(SongCacheEvents.SONG_ENDED) + }, remainingTime + SongCache.END_OF_TRACK_GRACE_MS) + } } } } diff --git a/DeskThingServer/test/main/services/music/songCache.test.ts b/DeskThingServer/test/main/services/music/songCache.test.ts new file mode 100644 index 00000000..4560c2bb --- /dev/null +++ b/DeskThingServer/test/main/services/music/songCache.test.ts @@ -0,0 +1,193 @@ +import { describe, expect, it, vi, beforeEach, afterEach } from 'vitest' +import { SongData } from '@deskthing/types' +import { SongCache, SongCacheEvents } from '../../../../src/main/services/music/songCache' + +vi.mock('@server/utils/logger', () => ({ + default: { info: vi.fn(), error: vi.fn(), warn: vi.fn(), debug: vi.fn(), log: vi.fn() } +})) + +// songCache writes thumbnails through electron's userData path; no test here +// exercises a thumbnail, but the import has to resolve. +vi.mock('electron', () => ({ app: { getPath: () => '/tmp/deskthing-test', getVersion: () => '0.0.0' } })) + +const track = (over: Partial = {}): SongData => + ({ + version: 2, + track_name: 'Vindicated', + artist: 'Dashboard Confessional', + album: 'Spider-Man 2', + is_playing: true, + track_duration: 200000, + track_progress: 10000, + abilities: [], + source: 'test', + id: 'track-1', + ...over + }) as SongData + +describe('SongCache', () => { + let cache: SongCache + + beforeEach(() => { + vi.useFakeTimers() + cache = new SongCache() + }) + + afterEach(() => { + cache.clear() + vi.useRealTimers() + vi.clearAllMocks() + }) + + describe('what counts as a change', () => { + it('does not treat ordinary playback progress as a song change', () => { + const changed = vi.fn() + cache.updateSong(track()) + cache.on(SongCacheEvents.SONG_CHANGED, changed) + + // A poll a couple of seconds later: same track, further along. + cache.updateSong(track({ track_progress: 12000 })) + + expect(changed).not.toHaveBeenCalled() + expect(cache.getCurrentSong()?.track_progress).toBe(12000) + }) + + it('treats a different track as a change', () => { + const changed = vi.fn() + cache.updateSong(track()) + cache.on(SongCacheEvents.SONG_CHANGED, changed) + + cache.updateSong(track({ track_name: 'Signal Fire', id: 'track-2' })) + + expect(changed).toHaveBeenCalledTimes(1) + }) + + it('treats pausing as a change', () => { + const changed = vi.fn() + cache.updateSong(track()) + cache.on(SongCacheEvents.SONG_CHANGED, changed) + + cache.updateSong(track({ is_playing: false })) + + expect(changed).toHaveBeenCalledTimes(1) + }) + + it('does not mistake a long gap between polls for a seek', () => { + // The cached progress advances in real time, so comparing against it + // stays correct however far apart the polls are. Comparing against the + // last *polled* value instead would make every poll longer than the + // tolerance — i.e. every poll at the default 15s cadence — look like a + // seek, and rearm the end-of-track timer each time. + const changed = vi.fn() + cache.updateSong(track({ track_progress: 10000 })) + cache.on(SongCacheEvents.SONG_CHANGED, changed) + + vi.advanceTimersByTime(15000) + cache.updateSong(track({ track_progress: 25000 })) + + expect(changed).not.toHaveBeenCalled() + }) + + it('treats a seek as a change, because it moves the end of the track', () => { + const changed = vi.fn() + cache.updateSong(track()) + cache.on(SongCacheEvents.SONG_CHANGED, changed) + + cache.updateSong(track({ track_progress: 120000 })) + + expect(changed).toHaveBeenCalledTimes(1) + }) + }) + + describe('end-of-track scheduling', () => { + it('announces the end just after the track actually runs out', () => { + const ended = vi.fn() + cache.on(SongCacheEvents.SONG_ENDED, ended) + + cache.updateSong(track({ track_duration: 200000, track_progress: 195000 })) + + // 5s of track left. Nothing yet at the boundary itself. + vi.advanceTimersByTime(5000) + expect(ended).not.toHaveBeenCalled() + + // A short grace later, so the provider has caught up. + vi.advanceTimersByTime(1000) + expect(ended).toHaveBeenCalledTimes(1) + }) + + it('schedules for a track first seen at progress 0', () => { + // Regression: `song.track_progress &&` made progress 0 falsy, so a track + // caught right at its start got no end timer at all. + const ended = vi.fn() + cache.on(SongCacheEvents.SONG_ENDED, ended) + + cache.updateSong(track({ track_duration: 30000, track_progress: 0 })) + + vi.advanceTimersByTime(31000) + expect(ended).toHaveBeenCalledTimes(1) + }) + + it('keeps the song cached after it ends', () => { + // Regression: clearing here left a client that connected during the gap + // with nothing to show. + cache.on(SongCacheEvents.SONG_ENDED, () => {}) + cache.updateSong(track({ track_duration: 20000, track_progress: 19000 })) + + vi.advanceTimersByTime(5000) + + expect(cache.getCurrentSong()).not.toBeNull() + expect(cache.getCurrentSong()?.track_name).toBe('Vindicated') + }) + + it('announces the end exactly once', () => { + // Regression: an interval and a timeout both used to fire it. + const ended = vi.fn() + cache.on(SongCacheEvents.SONG_ENDED, ended) + + cache.updateSong(track({ track_duration: 20000, track_progress: 19000 })) + vi.advanceTimersByTime(60000) + + expect(ended).toHaveBeenCalledTimes(1) + }) + + it('does not schedule an end for a paused track', () => { + const ended = vi.fn() + cache.on(SongCacheEvents.SONG_ENDED, ended) + + cache.updateSong(track({ is_playing: false })) + vi.advanceTimersByTime(500000) + + expect(ended).not.toHaveBeenCalled() + }) + + it('rearms against the new end when the listener seeks', () => { + const ended = vi.fn() + cache.on(SongCacheEvents.SONG_ENDED, ended) + + cache.updateSong(track({ track_duration: 200000, track_progress: 10000 })) + // Jump most of the way through the track. + cache.updateSong(track({ track_duration: 200000, track_progress: 195000 })) + + vi.advanceTimersByTime(6000) + expect(ended).toHaveBeenCalledTimes(1) + }) + }) + + describe('cached progress', () => { + it('advances while the track plays so a late joiner is told the truth', () => { + cache.updateSong(track({ track_progress: 10000 })) + + vi.advanceTimersByTime(3000) + + expect(cache.getCurrentSong()?.track_progress).toBe(13000) + }) + + it('never runs past the end of the track', () => { + cache.updateSong(track({ track_duration: 12000, track_progress: 10000 })) + + vi.advanceTimersByTime(30000) + + expect(cache.getCurrentSong()!.track_progress!).toBeLessThanOrEqual(12000) + }) + }) +}) diff --git a/DeskThingServer/test/main/services/music/trackChangeChase.test.ts b/DeskThingServer/test/main/services/music/trackChangeChase.test.ts new file mode 100644 index 00000000..b43063ee --- /dev/null +++ b/DeskThingServer/test/main/services/music/trackChangeChase.test.ts @@ -0,0 +1,261 @@ +import { describe, expect, it, vi, beforeEach, afterEach } from 'vitest' +import { APP_REQUESTS, AUDIO_REQUESTS, SongData, SongEvent } from '@deskthing/types' + +vi.mock('@server/utils/logger', () => ({ + default: { info: vi.fn(), error: vi.fn(), warn: vi.fn(), debug: vi.fn(), log: vi.fn() } +})) +vi.mock('electron', () => ({ + app: { getPath: () => '/tmp/deskthing-test', getVersion: () => '0.0.0' } +})) +vi.mock('../../../../src/main/services/files/appFileService', () => ({ + getAppByName: vi.fn(async () => ({ name: 'spotify', running: true })) +})) +// Colour extraction hits the network for real artwork; irrelevant here. +vi.mock('../../../../src/main/services/music/ColorExtractor', () => ({ + ColorExtractor: class { + async extractFromImage() { + return undefined + } + } +})) + +import { MusicService } from '../../../../src/main/services/music/MusicService' + +const song = (over: Partial = {}): SongData => + ({ + version: 2, + track_name: 'Town Called Malice', + artist: 'The Jam', + album: 'The Gift', + is_playing: true, + track_duration: 180000, + track_progress: 30000, + abilities: [], + source: 'spotify', + id: 'track-a', + ...over + }) as SongData + +/** + * Stands in for the source app. The important property is that answering is + * ASYNCHRONOUS: a refresh request is acknowledged immediately and the song + * arrives later on a separate message, exactly as the real app behaves. + */ +const buildHarness = (answerAfterMs: number, opts: { refreshInterval?: number; clients?: number } = {}) => { + let songHandler: ((d: { app: string; payload: SongData }) => Promise) | null = null + let current = song() + const requests: unknown[] = [] + + const appStore = { + initialize: vi.fn(async () => {}), + onAppMessage: vi.fn((request: string, handler: never) => { + if (request === APP_REQUESTS.SONG) songHandler = handler + return vi.fn() + }), + getAllBase: vi.fn(() => []), + sendDataToApp: vi.fn(async (_app: string, data: { request?: string }) => { + requests.push(data) + if (data.request !== AUDIO_REQUESTS.REFRESH) return + // Answer later, like a real network round trip. + setTimeout(() => { + songHandler?.({ app: 'spotify', payload: current }) + }, answerAfterMs) + }) + } + + const settingsStore = { + initialize: vi.fn(async () => {}), + getSettings: vi.fn(async () => ({ + music_playbackLocation: 'spotify', + // Default: no scheduled poll, so the chase tests measure the chase alone. + music_refreshInterval: opts.refreshInterval ?? -1 + })), + saveSetting: vi.fn(async () => {}), + on: vi.fn(() => vi.fn()) + } + + const platformStore = { + on: vi.fn(() => vi.fn()), + broadcastToClients: vi.fn(async () => {}), + sendDataToClient: vi.fn(async () => {}), + getClients: vi.fn(() => new Array(opts.clients ?? 0).fill({ clientId: 'c' })) + } + + // eslint-disable-next-line @typescript-eslint/no-explicit-any + const service = new MusicService(settingsStore as any, appStore as any, platformStore as any) + + return { + service, + appStore, + platformStore, + requests, + advanceToNextTrack: (next: SongData) => { + current = next + }, + seedCurrentSong: async () => { + await songHandler?.({ app: 'spotify', payload: current }) + // Seeding also triggers the service's one-off startup refresh. Drop it + // so the counts below describe the chase alone. + await new Promise((resolve) => setTimeout(resolve, 50)) + requests.length = 0 + }, + refreshCount: () => + requests.filter((r) => (r as { request?: string }).request === AUDIO_REQUESTS.REFRESH).length + } +} + +const skip = (service: MusicService) => + // eslint-disable-next-line @typescript-eslint/no-explicit-any + service.handleClientRequest({ + app: 'music', + type: SongEvent.SET, + request: AUDIO_REQUESTS.NEXT + } as any) + +/** + * handleClientRequest starts the chase without awaiting it, so tests have to + * give it real time to run. Without this the assertions run before a single + * request is sent and pass against an empty transcript. + */ +const settle = (ms: number) => new Promise((resolve) => setTimeout(resolve, ms)) + +const lastBroadcastTrack = (platformStore: { broadcastToClients: { mock: { calls: unknown[][] } } }) => { + const calls = platformStore.broadcastToClients.mock.calls + const last = calls[calls.length - 1]?.[0] as { payload?: SongData } | undefined + return last?.payload?.track_name +} + +describe('chasing a track change', () => { + beforeEach(() => { + vi.useRealTimers() + }) + + afterEach(() => { + vi.clearAllMocks() + }) + + it('finds the new track even though the answer arrives after the request', async () => { + // Regression: the chase used to look at the cache immediately after + // sending the refresh. The answer cannot have arrived yet, so every + // attempt read the track being left, the chase gave up, and the update + // waited for the next scheduled poll — a full cycle instead of ~1s. + const h = buildHarness(250) + await h.seedCurrentSong() + h.platformStore.broadcastToClients.mockClear() + + h.advanceToNextTrack(song({ track_name: 'When It Started', id: 'track-b', track_progress: 0 })) + await skip(h.service) + await settle(1200) + + expect(h.refreshCount()).toBeGreaterThanOrEqual(1) + expect(lastBroadcastTrack(h.platformStore)).toBe('When It Started') + // Settled early rather than running the whole ladder. + expect(h.refreshCount()).toBeLessThanOrEqual(2) + }) + + it('gives up after a bounded number of attempts when nothing changes', async () => { + // An unbounded retry against a provider that never advances is how an + // account earns a long Retry-After. + const h = buildHarness(50) + await h.seedCurrentSong() + + // Track deliberately never changes. + await skip(h.service) + await settle(9000) + + expect(h.refreshCount()).toBeGreaterThanOrEqual(2) + expect(h.refreshCount()).toBeLessThanOrEqual(5) + }, 20000) // the full ladder is ~7s by design + + it('stops chasing once playback has stopped', async () => { + const h = buildHarness(50) + await h.seedCurrentSong() + + h.advanceToNextTrack(song({ is_playing: false })) + await skip(h.service) + await settle(3000) + + expect(h.refreshCount()).toBeGreaterThanOrEqual(1) + expect(h.refreshCount()).toBeLessThanOrEqual(2) + }) + + it('does not run two chases at once', async () => { + const h = buildHarness(250) + await h.seedCurrentSong() + + // Two skips in quick succession, as an impatient double-press would send. + await skip(h.service) + await skip(h.service) + h.advanceToNextTrack(song({ track_name: 'Ghosts', id: 'track-c', track_progress: 0 })) + await settle(1500) + + // Two overlapping ladders would roughly double this. + expect(h.refreshCount()).toBeLessThanOrEqual(2) + }) + + it('polls often while someone is watching something play', async () => { + // The only way to notice playback changed in the provider's own app on + // another device. At the configured 15s that change took up to 15s to + // appear even after the boundary work. + const h = buildHarness(50, { refreshInterval: 15000, clients: 1 }) + await h.seedCurrentSong() + + await settle(5200) + + // ~2s cadence gives at least a couple of looks in 5s; the configured 15s + // would give none. + expect(h.refreshCount()).toBeGreaterThanOrEqual(2) + }, 20000) + + it('falls back to the configured rate when nobody is connected', async () => { + // A poll nobody can see is pure rate-limit cost. + const h = buildHarness(50, { refreshInterval: 15000, clients: 0 }) + await h.seedCurrentSong() + + await settle(5200) + + expect(h.refreshCount()).toBe(0) + }, 20000) + + it('falls back to the configured rate while playback is paused', async () => { + const h = buildHarness(50, { refreshInterval: 15000, clients: 1 }) + h.advanceToNextTrack(song({ is_playing: false })) + await h.seedCurrentSong() + + await settle(5200) + + expect(h.refreshCount()).toBe(0) + }, 20000) + + it('never polls faster than the configured rate', async () => { + // A user who deliberately set a slow cadence must not be overridden. + const h = buildHarness(50, { refreshInterval: 30000, clients: 1 }) + await h.seedCurrentSong() + + await settle(5200) + + expect(h.refreshCount()).toBeGreaterThanOrEqual(2) + }, 20000) + + it('lets a later chase replace an earlier one instead of dropping it', async () => { + // Regression: a plain "already chasing" flag made the second skip a no-op, + // so it fell through to the scheduled poll. Worse, a chase that never + // finished left the flag set and disabled every future chase — which is + // what stopped the chase running at all on the device. + const h = buildHarness(250) + await h.seedCurrentSong() + + await skip(h.service) + await settle(300) // first chase mid-flight + h.platformStore.broadcastToClients.mockClear() + + // A second skip must still produce requests of its own. + const before = h.refreshCount() + await skip(h.service) + h.advanceToNextTrack(song({ track_name: 'Start!', id: 'track-d', track_progress: 0 })) + await settle(1200) + + expect(h.refreshCount()).toBeGreaterThan(before) + expect(lastBroadcastTrack(h.platformStore)).toBe('Start!') + }) +}) diff --git a/tools/watch-music.js b/tools/watch-music.js new file mode 100755 index 00000000..8c6e2d0b --- /dev/null +++ b/tools/watch-music.js @@ -0,0 +1,164 @@ +#!/usr/bin/env node +/** + * watch-music — time the server's outbound song updates against reality. + * + * "The screen is slow to show the new track" is hard to act on. This turns it + * into numbers: how often the server actually pushes song data, how much of + * that is duplicate, and — the one that matters — how late an update arrives + * relative to when the previous track was due to end. + * + * Each payload carries track_progress and track_duration, so a sample at wall + * time T means the track ends at T + (duration - progress). Compare that + * against when the next track's update actually shows up and the lateness is + * exact, with no need to ask Spotify anything or to watch the device. + * + * Read-only. It connects as an ordinary extra websocket client and never sends + * a control request, so it cannot perturb what it is measuring. + * + * node tools/watch-music.js # 5 minutes against localhost:8891 + * node tools/watch-music.js --seconds 900 + * node tools/watch-music.js --url ws://localhost:8891 + * + * Run it long enough to span a track boundary — that is the measurement. + */ + +const path = require('path') + +// ws ships with the server; no separate install. +let WebSocket +try { + WebSocket = require(path.join(__dirname, '..', 'DeskThingServer', 'node_modules', 'ws')) +} catch { + try { + WebSocket = require('ws') + } catch { + console.error("Could not load 'ws'. Run `npm install` in DeskThingServer/ first.") + process.exit(1) + } +} + +function arg(name, fallback) { + const i = process.argv.indexOf(`--${name}`) + return i !== -1 && process.argv[i + 1] ? process.argv[i + 1] : fallback +} + +const URL = arg('url', 'ws://localhost:8891') +const RUN_MS = parseInt(arg('seconds', '300'), 10) * 1000 + +const t0 = Date.now() +const ts = () => ((Date.now() - t0) / 1000).toFixed(2).padStart(8) +const secs = (ms) => (ms / 1000).toFixed(2) + +const pushes = [] // wall time of every song payload +const changes = [] // {name, lateBy} +let duplicates = 0 +let lastTrack = null +let lastSeen = null // {name, progress, duration, at} +let lastPayload = null + +const ws = new WebSocket(URL) +ws.on('open', () => console.log(`${ts()} watching ${URL} for ${RUN_MS / 1000}s`)) + +ws.on('message', (buf) => { + let d + try { + d = JSON.parse(buf.toString()) + } catch { + return + } + const p = d && d.payload + if (!p || typeof p !== 'object' || p.track_name === undefined) return + + const now = Date.now() + const { track_name: name, track_progress: progress, track_duration: duration } = p + + // The server re-sends an identical payload several times per poll. Counting + // them matters on a Bluetooth link, where every copy is real airtime. + const fingerprint = `${name}|${progress}|${duration}|${p.is_playing}` + if (fingerprint === lastPayload) { + duplicates += 1 + return + } + lastPayload = fingerprint + pushes.push(now) + + if (name !== lastTrack) { + if (lastSeen) { + // How late we learned, measured directly: a track starts at progress 0, + // so whatever progress it has already accumulated when we first see it + // IS the lag. This holds whether the previous track ended on its own or + // was skipped, which extrapolating from the previous track's end does + // not — a skip makes that estimate wildly negative and useless. + const lateBy = progress + changes.push({ name, lateBy }) + + // Did the previous track finish, or did someone skip it? Only worth + // reporting to explain the context of the measurement. + const leftOver = + lastSeen.duration != null && lastSeen.progress != null + ? lastSeen.duration - lastSeen.progress - (now - lastSeen.at) + : null + const how = + leftOver == null ? '' : leftOver > 3000 ? ` (previous track skipped with ${secs(leftOver)}s to go)` : ' (previous track played out)' + + console.log( + `${ts()} TRACK CHANGE -> ${name}${how}\n` + + ` first seen ${secs(lateBy)}s into the track — that is how late the update was` + ) + } else { + console.log(`${ts()} first track: ${name} ${progress}/${duration}ms`) + } + lastTrack = name + } else { + const gap = pushes.length > 1 ? secs(now - pushes[pushes.length - 2]) : '—' + const remaining = duration != null && progress != null ? secs(duration - progress) : '?' + console.log(`${ts()} poll (+${gap}s) ${progress}/${duration}ms ${remaining}s left`) + } + + lastSeen = { name, progress, duration, at: now } +}) + +ws.on('error', (e) => console.log(`${ts()} ERROR ${e.message}`)) + +function report() { + const gaps = pushes.slice(1).map((t, i) => t - pushes[i]) + console.log('\n──────── summary ────────') + if (gaps.length) { + const sorted = [...gaps].sort((a, b) => a - b) + const mean = gaps.reduce((a, b) => a + b, 0) / gaps.length + console.log(`polls ${pushes.length}`) + console.log(`gap min/med/max ${secs(sorted[0])}s / ${secs(sorted[sorted.length >> 1])}s / ${secs(sorted[sorted.length - 1])}s`) + console.log(`gap mean ${secs(mean)}s`) + } else { + console.log('polls too few to measure a gap') + } + console.log(`duplicate sends ${duplicates} (identical payloads suppressed from the counts above)`) + + if (changes.length) { + console.log('\ntrack changes:') + for (const c of changes) console.log(` ${secs(c.lateBy).padStart(7)}s late ${c.name}`) + const mean = changes.reduce((a, c) => a + c.lateBy, 0) / changes.length + console.log(`\nmean lateness ${secs(mean)}s`) + console.log( + '\nA poller that ignores track_duration is late by up to one full poll\n' + + 'period on every track change, and by half a period on average. Compare\n' + + 'the lateness above against the gap figures — if they match, the poll\n' + + 'interval is the whole story and shortening it only trades API budget\n' + + 'for latency. Scheduling a refresh at the track boundary fixes it\n' + + 'without spending either.' + ) + } else { + console.log('\nno track change observed — run longer to measure the lateness') + } +} + +setTimeout(() => { + report() + ws.close() + process.exit(0) +}, RUN_MS) + +process.on('SIGINT', () => { + report() + process.exit(0) +})