From ce8bbf9e336ae81e24a3d9901a2616a5ebc9929c Mon Sep 17 00:00:00 2001 From: Edward Rosado Date: Wed, 5 Aug 2026 19:38:19 -0400 Subject: [PATCH 1/5] Show the next track when it starts, not at the next poll MIME-Version: 1.0 Content-Type: text/plain; charset=UTF-8 Content-Transfer-Encoding: 8bit A track change took a median of ~11s to reach the screen, with a worst case of 17.8s across 25 measured transitions. The distribution is the signature of a free-running 15s poll, and the poll was indeed doing nearly all the detecting — but not because nothing else tried. songCache already armed a timer for the end of each track and MusicService already refreshed on it. That path was structurally unable to succeed: - it fired at the exact boundary, a beat before the provider reports the new track, so the answer was the track that just finished; - it then called clear(), dropping the cached song and cancelling every timer, so nothing retried and a client connecting in the gap had nothing to show; - `song.track_progress &&` treated progress 0 as absent, so a track first seen at its start — the one that most needed the timer — never got one; - and an interval fired the same event a second time. So the timer either lost the race or never existed, and the poll picked up the pieces one cycle later. The end-of-track event now fires once, shortly after the track actually runs out, and leaves the cache intact. MusicService chases the change with a short bounded ladder (immediate, +1.2s, +2.5s) that stops as soon as the track is genuinely different, and treats a progress collapse as a change too so repeat-one does not run it to exhaustion. A skip takes the same path, since it loses the same race. A track that is merely playing is no longer treated as a track that changed. Progress advancing rebuilt the end-of-track timer on every poll and fired a redundant SONG_CHANGED broadcast each time — which also sent the raw payload as a second, worse copy of an update handleMusicPayload had already broadcast with its thumbnail rewritten. Only a different track, a play/pause flip, or a seek counts now. The poll interval is deliberately unchanged. Once the boundary is scheduled properly the poll only has to catch changes with no predictable boundary — a pause, a seek, or a skip from another device — and shortening it would multiply traffic against an account this branch already exists to keep under a rate limit. tools/watch-music.js measures this from the server's own websocket: poll cadence, duplicate sends, and how far into a track the update announcing it arrives. 12 tests cover the change detection and the boundary scheduling, including each regression above. Co-Authored-By: Claude Opus 5 --- .../src/main/services/music/MusicService.ts | 79 +++++++- .../src/main/services/music/songCache.ts | 94 ++++++---- .../main/services/music/songCache.test.ts | 177 ++++++++++++++++++ tools/watch-music.js | 164 ++++++++++++++++ 4 files changed, 472 insertions(+), 42 deletions(-) create mode 100644 DeskThingServer/test/main/services/music/songCache.test.ts create mode 100755 tools/watch-music.js diff --git a/DeskThingServer/src/main/services/music/MusicService.ts b/DeskThingServer/src/main/services/music/MusicService.ts index a6010abf..1e67383a 100644 --- a/DeskThingServer/src/main/services/music/MusicService.ts +++ b/DeskThingServer/src/main/services/music/MusicService.ts @@ -22,6 +22,14 @@ import { ColorExtractor } from './ColorExtractor' * Core service that manages music playback functionality */ export class MusicService implements MusicStoreClass { + /** + * When to ask after playback is expected to have changed. The first attempt + * is immediate; the rest cover the provider's own lag in reporting the new + * track, which is around a second in practice. Three attempts, then give up + * and let the scheduled refresh handle it. + */ + private static readonly TRACK_CHANGE_RETRY_DELAYS_MS = [0, 1200, 2500] + private refreshInterval: NodeJS.Timeout | null = null private currentApp: string | null = null private songCache: SongCache @@ -172,12 +180,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: @@ -234,12 +245,57 @@ 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) - }) + // 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 { + const leaving = this.songCache.getCurrentSong() + const leavingId = leaving?.id + const leavingName = leaving?.track_name + + for (const delay of MusicService.TRACK_CHANGE_RETRY_DELAYS_MS) { + if (delay > 0) { + await new Promise((resolve) => setTimeout(resolve, delay)) + } + + await this.refreshMusicData(undefined, { force: true }) + + 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 + // ladder would run to exhaustion on every looped track. + const isDifferent = now.id !== leavingId || now.track_name !== leavingName + const restarted = + leaving?.track_progress != null && + now.track_progress != null && + now.track_progress < leaving.track_progress + + 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 +460,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 +485,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..bb671729 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,26 @@ 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 elapsed playback can explain. It + // matters because it moves the end of the track, so the timer must be + // rearmed — an ordinary tick must not be. + 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 +233,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..897717b6 --- /dev/null +++ b/DeskThingServer/test/main/services/music/songCache.test.ts @@ -0,0 +1,177 @@ +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('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/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) +}) From 8a981fc68f685cb555c9745e6c664b332f682467 Mon Sep 17 00:00:00 2001 From: Edward Rosado Date: Wed, 5 Aug 2026 19:46:43 -0400 Subject: [PATCH 2/5] Pin down why seek detection compares against the cached progress MIME-Version: 1.0 Content-Type: text/plain; charset=UTF-8 Content-Transfer-Encoding: 8bit The comparison looks wrong at a glance: an ordinary poll advances progress by a whole poll period, which is far more than the seek tolerance, so it reads as though every poll would be treated as a seek. It isn't, because the progress interval advances the cached value in real time — the cached number is already "where the track should be by now", not "where it was at the last poll". Comparing against the last polled value instead would double-count the elapsed time and rearm the end-of-track timer on every single poll. Test added for a 15s gap between polls, which fails under that mistake. Co-Authored-By: Claude Opus 5 --- .../src/main/services/music/songCache.ts | 9 ++++++--- .../test/main/services/music/songCache.test.ts | 16 ++++++++++++++++ 2 files changed, 22 insertions(+), 3 deletions(-) diff --git a/DeskThingServer/src/main/services/music/songCache.ts b/DeskThingServer/src/main/services/music/songCache.ts index bb671729..cb4d8fc3 100644 --- a/DeskThingServer/src/main/services/music/songCache.ts +++ b/DeskThingServer/src/main/services/music/songCache.ts @@ -69,9 +69,12 @@ export class SongCache extends EventEmitter { const playbackFlipped = this.currentSong.is_playing !== newSong.is_playing - // A seek is a progress jump larger than elapsed playback can explain. It - // matters because it moves the end of the track, so the timer must be - // rearmed — an ordinary tick must not be. + // 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 diff --git a/DeskThingServer/test/main/services/music/songCache.test.ts b/DeskThingServer/test/main/services/music/songCache.test.ts index 897717b6..4560c2bb 100644 --- a/DeskThingServer/test/main/services/music/songCache.test.ts +++ b/DeskThingServer/test/main/services/music/songCache.test.ts @@ -72,6 +72,22 @@ describe('SongCache', () => { 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()) From cf9c70e57cffe20b9e32e09337a3a8532c61fd11 Mon Sep 17 00:00:00 2001 From: Edward Rosado Date: Wed, 5 Aug 2026 19:54:38 -0400 Subject: [PATCH 3/5] Wait for the answer before deciding the chase has failed MIME-Version: 1.0 Content-Type: text/plain; charset=UTF-8 Content-Transfer-Encoding: 8bit refreshMusicData only hands a request to the source app. The song comes back later, on a separate message, and updates the cache then. The chase checked the cache immediately after sending, so it read the track it was trying to leave every time, concluded nothing had changed, and gave up — leaving the update to the next scheduled poll. Measured against the running build: a skip took 1.38s when the timing happened to work out and 14.73s when it didn't, which matches the ~13s reported from the device. The variance was the tell. Each attempt now waits for its answer before looking, and the delays are the wait after each request rather than the pause before it: 600/900/ 1200/1800/2500ms, about a seven second window. The chase still stops the moment the track is different, so the usual cost is one request. Concurrent chases are collapsed. A double-press used to start a second ladder on top of the first and double the requests for one answer. 4 tests, driven through a source app that answers asynchronously like the real one — the arrangement the old code got wrong. They assert the new track actually reaches the broadcast, that the ladder stays bounded when the provider never advances, and that two skips do not stack. Co-Authored-By: Claude Opus 5 --- .../src/main/services/music/MusicService.ts | 76 ++++--- .../services/music/trackChangeChase.test.ts | 193 ++++++++++++++++++ 2 files changed, 239 insertions(+), 30 deletions(-) create mode 100644 DeskThingServer/test/main/services/music/trackChangeChase.test.ts diff --git a/DeskThingServer/src/main/services/music/MusicService.ts b/DeskThingServer/src/main/services/music/MusicService.ts index 1e67383a..1a75f43b 100644 --- a/DeskThingServer/src/main/services/music/MusicService.ts +++ b/DeskThingServer/src/main/services/music/MusicService.ts @@ -23,13 +23,16 @@ import { ColorExtractor } from './ColorExtractor' */ export class MusicService implements MusicStoreClass { /** - * When to ask after playback is expected to have changed. The first attempt - * is immediate; the rest cover the provider's own lag in reporting the new - * track, which is around a second in practice. Three attempts, then give up - * and let the scheduled refresh handle it. + * 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 = [0, 1200, 2500] + private static readonly TRACK_CHANGE_RETRY_DELAYS_MS = [600, 900, 1200, 1800, 2500] + private chasing = false private refreshInterval: NodeJS.Timeout | null = null private currentApp: string | null = null private songCache: SongCache @@ -268,33 +271,46 @@ export class MusicService implements MusicStoreClass { * multi-hour Retry-After. */ private async chaseTrackChange(): Promise { - const leaving = this.songCache.getCurrentSong() - const leavingId = leaving?.id - const leavingName = leaving?.track_name + // One chase at a time. A skip lands while the previous chase may still be + // running, and letting them overlap multiplies requests for one answer. + if (this.chasing) return + this.chasing = true - for (const delay of MusicService.TRACK_CHANGE_RETRY_DELAYS_MS) { - if (delay > 0) { - await new Promise((resolve) => setTimeout(resolve, delay)) + try { + 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) { + await this.refreshMusicData(undefined, { force: true }) + + // 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 } - - await this.refreshMusicData(undefined, { force: true }) - - 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 - // ladder would run to exhaustion on every looped track. - const isDifferent = now.id !== leavingId || now.track_name !== leavingName - const restarted = - leaving?.track_progress != null && - now.track_progress != null && - now.track_progress < leaving.track_progress - - if (isDifferent || restarted) return - - // Nothing is playing any more — there is no next track to wait for. - if (now.is_playing === false) return + } finally { + this.chasing = false } } 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..68420efd --- /dev/null +++ b/DeskThingServer/test/main/services/music/trackChangeChase.test.ts @@ -0,0 +1,193 @@ +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) => { + 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', + music_refreshInterval: -1 // no scheduled poll; isolate the chase + })), + saveSetting: vi.fn(async () => {}), + on: vi.fn(() => vi.fn()) + } + + const platformStore = { + on: vi.fn(() => vi.fn()), + broadcastToClients: vi.fn(async () => {}), + sendDataToClient: vi.fn(async () => {}) + } + + // 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) + }) +}) From b2ba3810cf8c373cf9172f5f82c2e2c69c8169fa Mon Sep 17 00:00:00 2001 From: Edward Rosado Date: Wed, 5 Aug 2026 20:05:09 -0400 Subject: [PATCH 4/5] Stop one stalled chase from disabling every chase after it MIME-Version: 1.0 Content-Type: text/plain; charset=UTF-8 Content-Transfer-Encoding: 8bit Guarding the chase with an "already chasing" flag was wrong in two ways. A second skip arriving mid-chase was discarded, even though it is chasing a different change from a different starting track — so it fell through to the scheduled poll. And if a chase ever failed to finish, the flag stayed set and silently disabled every future chase for the life of the process. The second failure is what showed on the device: after a while the log contains no chase requests at all, only the scheduled polls exactly 15s apart, and every skip costs a full cycle no matter how the retry timings are tuned. A generation counter replaces it. A newer chase supersedes an older one at its next checkpoint, there is no state to get stuck in, and each refresh is raced against a timeout so one unsettled send cannot stall the ladder behind it. Co-Authored-By: Claude Opus 5 --- .../src/main/services/music/MusicService.ts | 91 ++++++++++--------- .../services/music/trackChangeChase.test.ts | 22 +++++ 2 files changed, 72 insertions(+), 41 deletions(-) diff --git a/DeskThingServer/src/main/services/music/MusicService.ts b/DeskThingServer/src/main/services/music/MusicService.ts index 1a75f43b..2c543046 100644 --- a/DeskThingServer/src/main/services/music/MusicService.ts +++ b/DeskThingServer/src/main/services/music/MusicService.ts @@ -32,7 +32,10 @@ export class MusicService implements MusicStoreClass { */ private static readonly TRACK_CHANGE_RETRY_DELAYS_MS = [600, 900, 1200, 1800, 2500] - private chasing = false + /** How long to wait for a refresh request to be handed off before moving on. */ + private static readonly REFRESH_SEND_TIMEOUT_MS = 2000 + + private chaseGeneration = 0 private refreshInterval: NodeJS.Timeout | null = null private currentApp: string | null = null private songCache: SongCache @@ -271,46 +274,52 @@ export class MusicService implements MusicStoreClass { * multi-hour Retry-After. */ private async chaseTrackChange(): Promise { - // One chase at a time. A skip lands while the previous chase may still be - // running, and letting them overlap multiplies requests for one answer. - if (this.chasing) return - this.chasing = true - - try { - 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) { - await this.refreshMusicData(undefined, { force: true }) - - // 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 - } - } finally { - this.chasing = false + // 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 } } diff --git a/DeskThingServer/test/main/services/music/trackChangeChase.test.ts b/DeskThingServer/test/main/services/music/trackChangeChase.test.ts index 68420efd..3f7aea0c 100644 --- a/DeskThingServer/test/main/services/music/trackChangeChase.test.ts +++ b/DeskThingServer/test/main/services/music/trackChangeChase.test.ts @@ -190,4 +190,26 @@ describe('chasing a track change', () => { // Two overlapping ladders would roughly double this. expect(h.refreshCount()).toBeLessThanOrEqual(2) }) + + 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!') + }) }) From b471a0a6ac0935f8cfd18cbf1987facbfd06279e Mon Sep 17 00:00:00 2001 From: Edward Rosado Date: Wed, 5 Aug 2026 22:12:27 -0400 Subject: [PATCH 5/5] Notice playback that changed somewhere else MIME-Version: 1.0 Content-Type: text/plain; charset=UTF-8 Content-Transfer-Encoding: 8bit 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. That leaves the case with no boundary to predict and no command to observe — playback changed in the provider's own app, on a phone or a desktop. Nothing announces it, so the only way to notice is to look, and at the configured 15s a change made elsewhere still took up to 15s to reach the screen. After the boundary work this was the entire remaining delay, and it is the one users are most likely to hit. The poll now schedules itself one tick at a time and picks the delay from what is actually happening: about 2s while a client is connected and something is playing, the configured rate otherwise. Idle or paused it costs exactly what it did before, because a poll nobody can see buys nothing and the currency here is a provider rate limit. It never polls faster than the configured rate, so someone who deliberately set a slow cadence still gets it. Client traffic does not increase. The source only reports genuine state changes, and at a 2s cadence an ordinary progress advance falls inside its own tolerance — so a faster poll sends *fewer* redundant updates over the link, not more. Scheduling one tick at a time also means a slow poll can no longer stack requests on top of itself, which a fixed interval allowed. 4 tests: fast while watched and playing, configured rate when nothing is connected, configured rate while paused, and never faster than configured. Co-Authored-By: Claude Opus 5 --- .../src/main/services/music/MusicService.ts | 93 ++++++++++++++++--- .../services/music/trackChangeChase.test.ts | 52 ++++++++++- 2 files changed, 130 insertions(+), 15 deletions(-) diff --git a/DeskThingServer/src/main/services/music/MusicService.ts b/DeskThingServer/src/main/services/music/MusicService.ts index 2c543046..a7938e50 100644 --- a/DeskThingServer/src/main/services/music/MusicService.ts +++ b/DeskThingServer/src/main/services/music/MusicService.ts @@ -35,7 +35,17 @@ export class MusicService implements MusicStoreClass { /** 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 @@ -75,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.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 } - this.refreshInterval = setInterval(() => { - this.refreshMusicData() - }, refreshRate) + 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 { @@ -217,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 @@ -254,6 +318,11 @@ export class MusicService implements MusicStoreClass { this.chaseTrackChange() }) + // 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 diff --git a/DeskThingServer/test/main/services/music/trackChangeChase.test.ts b/DeskThingServer/test/main/services/music/trackChangeChase.test.ts index 3f7aea0c..b43063ee 100644 --- a/DeskThingServer/test/main/services/music/trackChangeChase.test.ts +++ b/DeskThingServer/test/main/services/music/trackChangeChase.test.ts @@ -41,7 +41,7 @@ const song = (over: Partial = {}): SongData => * 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) => { +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[] = [] @@ -67,7 +67,8 @@ const buildHarness = (answerAfterMs: number) => { initialize: vi.fn(async () => {}), getSettings: vi.fn(async () => ({ music_playbackLocation: 'spotify', - music_refreshInterval: -1 // no scheduled poll; isolate the chase + // 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()) @@ -76,7 +77,8 @@ const buildHarness = (answerAfterMs: number) => { const platformStore = { on: vi.fn(() => vi.fn()), broadcastToClients: vi.fn(async () => {}), - sendDataToClient: 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 @@ -191,6 +193,50 @@ describe('chasing a track change', () => { 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