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 <noreply@anthropic.com>

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

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
+   *  logs every outgoing Progress request (method + path + query - see
-   *  up instead of ever propagating - see PlaystateService's own comment. */
+   *  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}`);
   }

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<void> {
+    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({
+      const res = await EmbyClient.fetch(path, embyToken, { method: 'POST' });
-        MediaSourceId: mediaSourceId,
+      Logger.playstate(`<- ${res.status} ${res.ok ? 'ok' : 'FAILED'} userId=${userId} itemId=${itemId}`);
-        PositionTicks: String(Math.round(positionTicks)),
-        IsPaused: String(isPaused)
-      });
-      await EmbyClient.fetch(`/Users/${userId}/PlayingItems/${itemId}/Progress?${params}`, embyToken, { method: 'POST' });
     } 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}`);
     }
   }
 }

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'));
+  });
 });