From e6d71f2e373eb20896683280cbb456d8eb34c88b Mon Sep 17 00:00:00 2001 From: Nicolas Date: Mon, 14 Sep 2026 22:42:49 +0200 Subject: [PATCH] Log the playstate sweep's own requests, not just its failures Follow-up to the last fix (wrong Progress param shape): now that the request shape is corrected, the obvious next question is "is it actually being sent right, and is Emby accepting it" - answered from the logs alone, without cross-referencing anything else. PlaystateService.reportProgress now logs the exact outgoing request right before sending it (method, path, query string - everything actually sent) and its outcome right after (the real HTTP status and whether it was ok, or that the call threw), all under [watchparty:playstate]. EmbyClient's own generic [watchparty:emby] failure log still fires too, independently, with the fuller error body - this is a second, feature-scoped log so `docker logs | grep watchparty:playstate` alone shows the whole story for this specific sweep. Deliberately safe to log the full path: the query string here is only ever MediaSourceId/PositionTicks/IsPaused, never a token - the real embyToken travels as a header, not the URL - unlike Logger.stream's own request logging, which stays partial specifically because Emby's own TranscodingUrl can carry an api_key. Tests: request logging (path/params present, token absent), and outcome logging for a success, a non-ok status, and a thrown error each producing a distinct line. Full typecheck/test/build green (96/96 tests). docs/architecture.md updated. Co-Authored-By: Claude Sonnet 5 --- docs/architecture.md | 22 +++++++++- server/src/Logger.ts | 11 ++++- server/src/services/PlaystateService.ts | 24 +++++++---- server/test/playstateService.test.ts | 56 +++++++++++++++++++++++++ 4 files changed, 103 insertions(+), 10 deletions(-) diff --git a/docs/architecture.md b/docs/architecture.md index 36ac952..93c015f 100644 --- a/docs/architecture.md +++ b/docs/architecture.md @@ -2010,12 +2010,32 @@ against the same real spec - both match with no missing required parameter, consistent with them already having been tried for real successfully. +**Made the sweep's own traffic visible, not just its failures** - asked +for directly, once fixing the request shape raised the obvious +follow-up question ("is it actually being sent correctly now?"). +`reportProgress` now logs the exact outgoing request (`-> POST +/Users/{userId}/PlayingItems/{itemId}/Progress?MediaSourceId=...&...`) +right before sending it, and its outcome right after (`<- 200 ok` / +`<- 400 FAILED` / `<- threw ...`), all under the same +`[watchparty:playstate]` prefix - so `docker logs | grep +watchparty:playstate` answers "what did this send, and did Emby accept +it" on its own, without cross-referencing `EmbyClient`'s own generic +`[watchparty:emby]` failure log (which still fires too, independently, +with the fuller error body). Safe to log the full path here, unlike +`Logger.stream`'s own deliberately-partial logging - this query string +is only ever `MediaSourceId`/`PositionTicks`/`IsPaused`, never a token; +the real `embyToken` travels as a header, never in the URL, and the +tests confirm it never ends up in these lines either. + Verified: full typecheck/test/build on both projects. Unit tests cover `getCurrentPlaybackState` (video reads the host, music reads the shared queue, both branches, plus the empty-queue null case), `setMemberEmbyToken`, `PlaystateService.reportProgress`'s corrected query-string request shape (and that a thrown failure never -propagates), and `PartyStreamService.getCachedMediaSourceId`'s +propagates), its own request/outcome logging (success, a non-ok +status, and a thrown error each produce a distinct, greppable line, +and the token itself never appears in one), and +`PartyStreamService.getCachedMediaSourceId`'s cache-hit/cache-miss/dropped-on-failure behavior. `EmbyClient.fetch`'s optional body-encoding capability stays generic plumbing (its own test no longer claims PlaystateService as the reason it exists) - no diff --git a/server/src/Logger.ts b/server/src/Logger.ts index b88db7a..61ac1c2 100644 --- a/server/src/Logger.ts +++ b/server/src/Logger.ts @@ -67,8 +67,15 @@ export class Logger { } /** The periodic Emby-playstate sweep (index.ts / PlaystateService) - - * best-effort background sync, so this is where a failed report ends - * up instead of ever propagating - see PlaystateService's own comment. */ + * logs every outgoing Progress request (method + path + query - see + * PlaystateService.reportProgress) and its outcome, not just + * failures: this is a best-effort background sync with nothing else + * watching it, so `docker logs | grep watchparty:playstate` needs to + * be enough on its own to see exactly what was sent and whether Emby + * accepted it, without cross-referencing `emby` above. Safe to log + * the full path here (unlike `stream` above) - the query string is + * only ever MediaSourceId/PositionTicks/IsPaused, never a token; the + * real embyToken travels as a header, not a URL. */ static playstate(message: string): void { console.log(`[watchparty:playstate] ${new Date().toISOString()} ${message}`); } diff --git a/server/src/services/PlaystateService.ts b/server/src/services/PlaystateService.ts index 5cd540b..51e5673 100644 --- a/server/src/services/PlaystateService.ts +++ b/server/src/services/PlaystateService.ts @@ -38,17 +38,27 @@ class PlaystateServiceClass { * fresh one here would mean an extra PlaybackInfo round trip on every * tick, for a value the party's already-negotiated stream already * produced for free. + * + * Every call logs the exact outgoing request (method, path, query - + * everything actually sent, minus the token itself, which travels as + * a header, never in this) and its outcome - see Logger.playstate's + * own comment for why this needs to be enough on its own, greppable, + * to answer "is this actually reaching Emby, and with what" without + * digging through EmbyClient's own generic failure log. */ async reportProgress(embyToken: string, userId: string, itemId: string, mediaSourceId: string, positionTicks: number, isPaused: boolean): Promise { + const params = new URLSearchParams({ + MediaSourceId: mediaSourceId, + PositionTicks: String(Math.round(positionTicks)), + IsPaused: String(isPaused) + }); + const path = `/Users/${userId}/PlayingItems/${itemId}/Progress?${params}`; + Logger.playstate(`-> POST ${path}`); try { - const params = new URLSearchParams({ - MediaSourceId: mediaSourceId, - PositionTicks: String(Math.round(positionTicks)), - IsPaused: String(isPaused) - }); - await EmbyClient.fetch(`/Users/${userId}/PlayingItems/${itemId}/Progress?${params}`, embyToken, { method: 'POST' }); + const res = await EmbyClient.fetch(path, embyToken, { method: 'POST' }); + Logger.playstate(`<- ${res.status} ${res.ok ? 'ok' : 'FAILED'} userId=${userId} itemId=${itemId}`); } catch (err) { - Logger.playstate(`progress report failed userId=${userId} itemId=${itemId}: ${(err as Error).message}`); + Logger.playstate(`<- threw userId=${userId} itemId=${itemId}: ${(err as Error).message}`); } } } diff --git a/server/test/playstateService.test.ts b/server/test/playstateService.test.ts index 6c52b70..a2f404f 100644 --- a/server/test/playstateService.test.ts +++ b/server/test/playstateService.test.ts @@ -52,4 +52,60 @@ describe('PlaystateService.reportProgress', () => { await assert.doesNotReject(() => PlaystateService.reportProgress('tok', 'u1', 'item1', 'src1', 0, false)); }); + + // Logging: the whole point is being able to answer "what did this + // actually send, and did Emby accept it" from `docker logs` alone - + // see Logger.playstate's own comment. + it('logs the exact outgoing request, never the token itself', async (t) => { + const logged: string[] = []; + t.mock.method(console, 'log', (line: string) => { logged.push(line); }); + t.mock.method(EmbyClient, 'fetch', async () => new Response('{}', { status: 200 })); + + await PlaystateService.reportProgress('super-secret-token', 'u-alice', 'item1', 'src1', 12_345_678, false); + + const requestLine = logged.find((l) => l.includes('[watchparty:playstate]') && l.includes('POST')); + assert.ok(requestLine, 'the request itself must be logged'); + assert.ok(requestLine!.includes('/Users/u-alice/PlayingItems/item1/Progress')); + assert.ok(requestLine!.includes('MediaSourceId=src1')); + assert.ok(requestLine!.includes('PositionTicks=12345678')); + assert.ok(requestLine!.includes('IsPaused=false')); + assert.ok(!requestLine!.includes('super-secret-token'), 'the token travels as a header, never logged into the request line'); + }); + + it('logs a successful response as ok, with its real HTTP status', async (t) => { + const logged: string[] = []; + t.mock.method(console, 'log', (line: string) => { logged.push(line); }); + t.mock.method(EmbyClient, 'fetch', async () => new Response(null, { status: 204 })); // 204 is a null-body status - a non-null body here would throw + + await PlaystateService.reportProgress('tok', 'u1', 'item1', 'src1', 0, false); + + const outcomeLine = logged.find((l) => l.includes('[watchparty:playstate]') && l.includes('204')); + assert.ok(outcomeLine, 'the real status code must be logged'); + assert.ok(outcomeLine!.includes('ok')); + assert.ok(!outcomeLine!.includes('FAILED')); + }); + + it('logs a non-ok response as FAILED, with its real HTTP status - the exact case the original wrong request shape would have hit', async (t) => { + const logged: string[] = []; + t.mock.method(console, 'log', (line: string) => { logged.push(line); }); + t.mock.method(EmbyClient, 'fetch', async () => new Response('bad request', { status: 400 })); + + await PlaystateService.reportProgress('tok', 'u1', 'item1', 'src1', 0, false); + + const outcomeLine = logged.find((l) => l.includes('[watchparty:playstate]') && l.includes('400')); + assert.ok(outcomeLine, 'the real status code must be logged'); + assert.ok(outcomeLine!.includes('FAILED')); + }); + + it('logs a thrown error (Emby unreachable) distinctly from a non-ok HTTP response', async (t) => { + const logged: string[] = []; + t.mock.method(console, 'log', (line: string) => { logged.push(line); }); + t.mock.method(EmbyClient, 'fetch', async () => { throw new Error('Emby unreachable'); }); + + await PlaystateService.reportProgress('tok', 'u1', 'item1', 'src1', 0, false); + + const outcomeLine = logged.find((l) => l.includes('[watchparty:playstate]') && l.includes('threw')); + assert.ok(outcomeLine, 'a thrown error must still be logged, not just swallowed silently'); + assert.ok(outcomeLine!.includes('Emby unreachable')); + }); });