Log Emby's real status + response body on any proxied call failure

Every attempt to see Emby's actual error message by hand failed the same
way: hls.js's own error reporting only ever exposes the generic HTTP
reason phrase, never the real response body, and Emby's own live log
view didn't reliably surface the exception's headline message either -
across several different items and failure modes this session. Emby's
own access log confirmed a real, several-KB text body really was being
sent every time (Content-Type: text/plain, Content-Length: 5190) - it
just never survived being reported back through either of those paths.

Fixed at the root: EmbyClient.fetch - the one function every Emby call in
this app goes through (fetchJson's JSON API calls and proxyResponse's
streaming/image proxy alike) - now logs Emby's status and full response
body itself straight to docker logs whenever a call fails.

- server/src/emby/EmbyClient.ts: new private logErrorResponse, called
  from fetch() only when !res.ok. Reads the body via .clone() so the real
  caller still gets an untouched, fully readable response (a body can
  only be consumed once, and this had to not break either of the two very
  different ways this app's callers read one - fetchJson's .json(),
  proxyResponse's .text()/pipe). pathAndQuery is logged with api_key
  redacted - this can be called with Emby's own TranscodingUrl verbatim,
  which can carry one (same concern as CatalogService's logStreamRequest).
- server/src/Logger.ts: new emby() method, same shape as party()/stream().
- server/test/embyClient.test.ts (new): body/status logged and readable
  by the real caller afterward, api_key redaction, and silence on a
  successful response (only failures are worth logging, same discipline
  as this app's existing logging).

Co-Authored-By: Claude Sonnet 5 <noreply@anthropic.com>

docs/architecture.md

@@ -566,6 +566,45 @@ needing another round of server-log archaeology, and prevents anyone
 from picking a subtitle that's guaranteed to break playback the same way
 again, for any item, without needing to know any of this history.
 
+**Round 6: a third item, same failure, `supportsBurnIn` said it should
+have worked - and finally, why chasing the message by hand kept failing.**
+A YouTube-downloaded video (AV1 video, `mov_text` subtitle - genuinely
+text, `supportsBurnIn` would report `true`) hit the exact same 500. Not
+PGS this time - a third distinct cause. What finally moved this forward
+wasn't the exception message (still never successfully captured by hand,
+across several attempts at pointing at the right log line or the
+browser's Network tab) but a detail that surfaced almost by accident:
+Emby's own access log recorded the failing response as `Content-Type=
+text/plain, Content-Length=5190` - a real, several-KB error body really
+was being sent every time, it just never survived being reported back
+here. `hls.js`'s own error object only ever exposes the generic HTTP
+reason phrase (`"Internal Server Error"`), never the actual response
+text; Emby's live log view apparently doesn't reliably surface the
+exception's headline message either, at least not in whatever's easy to
+copy from it. Both dead ends, independently, on every attempt.
+
+Fixed at the root instead of trying a fourth way to ask for the same
+missing text by hand: `EmbyClient.fetch` - the one function every single
+Emby call in this app goes through, `fetchJson`'s JSON API calls and
+`proxyResponse`'s streaming/image proxy alike - now logs Emby's status
+and full response body itself, straight to `docker logs`, whenever a call
+fails. Reads the body via `.clone()` specifically so the real caller
+(whichever one it is) still gets an untouched, fully readable response of
+its own - a `Response` body can only be consumed once, and this had to
+not break either of the two very different ways this app's callers read
+one. `pathAndQuery` is logged with `api_key` redacted, matching
+`logStreamRequest`'s existing concern - this can be called with Emby's
+own `TranscodingUrl` verbatim, which can carry one. Only failures get
+logged at all - a deliberate choice consistent with how the rest of this
+app's logging already works (`Logger.party`/`Logger.stream` also skip
+routine/unchanged traffic) - so this adds real, previously-invisible
+detail on exactly the calls worth seeing, and silence on the thousands
+that don't need it.
+
+The next 500 on this or any future item gets its real cause into
+`docker logs` directly, without another round of trying to hand-copy it
+out of a browser or Emby's own log viewer.
+
 ## Assumptions to verify
 
 **Confirmed against the real server** (not a guess — actually exercised,

server/package.json

@@ -9,7 +9,7 @@
     "start": "node dist/index.js",
     "dev": "tsx watch src/index.ts",
     "typecheck": "tsc -p tsconfig.test.json",
-    "test": "tsx --test test/catalogService.test.ts test/musicQueueService.test.ts test/partyService.test.ts test/socketGateway.test.ts"
+    "test": "tsx --test test/catalogService.test.ts test/embyClient.test.ts test/musicQueueService.test.ts test/partyService.test.ts test/socketGateway.test.ts"
   },
   "engines": {
     "node": ">=18"

server/src/Logger.ts

@@ -41,4 +41,17 @@ export class Logger {
   static who(userId: string, userName: string): string {
     return `${userName}(${userId})`;
   }
+
+  /**
+   * Emby answering anything but success, to any proxied call - see
+   * EmbyClient.fetch, the one place every Emby request goes through.
+   * Added after several rounds of chasing a real error message through
+   * browser devtools and Emby's own live log view (see docs/architecture.md's
+   * player-track-selection section): Emby often sends back a real,
+   * detailed text body on a failure, which neither of those reliably
+   * surfaced - this puts it directly in `docker logs` instead, from now on.
+   */
+  static emby(message: string): void {
+    console.log(`[watchparty:emby] ${new Date().toISOString()} ${message}`);
+  }
 }

server/src/emby/EmbyClient.ts

@@ -3,6 +3,7 @@
 import type { Request, Response } from 'express';
 import { Readable } from 'stream';
 import { EMBY_SERVER_URL } from '../config';
+import { Logger } from '../Logger';
 
 /**
  * Low-level HTTP plumbing for talking to Emby and proxying its responses
@@ -13,12 +14,45 @@ import { EMBY_SERVER_URL } from '../config';
  */
 export class EmbyClient {
   /** Fetches a path from Emby with the given user's token, forwarding
-   *  Range (needed for direct-play video seeking) when the browser sent one. */
+   *  Range (needed for direct-play video seeking) when the browser sent one.
+   *  Every Emby call in this app goes through here - see logErrorResponse
+   *  below for what happens when Emby answers with anything but success. */
   static async fetch(pathAndQuery: string, token: string, options: { range?: string } = {}): Promise<globalThis.Response> {
     const url = pathAndQuery.startsWith('http') ? pathAndQuery : `${EMBY_SERVER_URL}${pathAndQuery}`;
     const headers: Record<string, string> = { 'X-Emby-Token': token };
     if (options.range) headers.Range = options.range;
-    return fetch(url, { headers });
+    const res = await fetch(url, { headers });
+    if (!res.ok) await EmbyClient.logErrorResponse(res, pathAndQuery);
+    return res;
+  }
+
+  /**
+   * Logs Emby's own status + response body whenever a call fails - added
+   * after several rounds of chasing a real error message through browser
+   * devtools (hls.js's own error reporting never surfaces the actual
+   * response body, just the generic HTTP reason phrase) and Emby's own
+   * live log view (the exception's headline message routinely scrolled
+   * past what got copied) - see docs/architecture.md's player-track-
+   * selection section. Emby often sends a real, detailed text body on a
+   * failure (confirmed directly: a real 500 here carried 5190 bytes of
+   * plain text, not an empty response) - this puts it straight into
+   * `docker logs` instead, every time, going forward.
+   *
+   * Reads via `.clone()` specifically so this never consumes the body the
+   * real caller still needs (`fetchJson`'s `.json()`, `proxyResponse`'s
+   * `.text()`/pipe) - a Response's body stream can only be read once, and
+   * every single Emby call (JSON API calls and the streaming/image proxy
+   * alike) passes through this same `fetch`, so getting this wrong would
+   * have broken all of them, not just the error path.
+   *
+   * `pathAndQuery` is logged with `api_key` redacted - this can be called
+   * with Emby's own `TranscodingUrl` verbatim, which can carry one (same
+   * concern as CatalogService's `logStreamRequest`).
+   */
+  private static async logErrorResponse(res: globalThis.Response, pathAndQuery: string): Promise<void> {
+    const safePathAndQuery = pathAndQuery.replace(/([?&]api_key=)[^&]*/i, '$1REDACTED');
+    const body = await res.clone().text().catch(() => '(corps illisible)');
+    Logger.emby(`${res.status} ${safePathAndQuery} - ${body.slice(0, 2000)}`);
   }
 
   static isPlaylistPath(path: string): boolean {

server/test/embyClient.test.ts

@@ -0,0 +1,52 @@
+// EmbyClient.fetch itself (not mocked away, unlike catalogService.test.ts,
+// which replaces it wholesale to isolate CatalogService) - specifically
+// the error-logging path added after several rounds of not being able to
+// see what Emby actually said on a failure (see docs/architecture.md's
+// player-track-selection section). Mocks the GLOBAL fetch, since that's
+// what EmbyClient.fetch itself calls.
+import { describe, it } from 'node:test';
+import assert from 'node:assert/strict';
+import { EmbyClient } from '../src/emby/EmbyClient';
+
+describe('EmbyClient.fetch', () => {
+  it('logs Emby\'s status and response body on a failure, without consuming the body the real caller still needs', async (t) => {
+    const logged: string[] = [];
+    t.mock.method(console, 'log', (line: string) => { logged.push(line); });
+    t.mock.method(globalThis, 'fetch', async () => new Response('Server.MediaEncoding.Api boom', { status: 500 }));
+
+    const res = await EmbyClient.fetch('/Videos/91988/hls1/main/0.ts?PlaySessionId=abc', 'tok');
+
+    const embyLines = logged.filter((l) => l.includes('[watchparty:emby]'));
+    assert.equal(embyLines.length, 1);
+    assert.ok(embyLines[0]!.includes('500'));
+    assert.ok(embyLines[0]!.includes('Server.MediaEncoding.Api boom'), 'the real body text should make it into the log line');
+    assert.ok(embyLines[0]!.includes('/Videos/91988/hls1/main/0.ts'));
+
+    // The caller (proxyResponse/fetchJson) still needs to read this same
+    // response's body itself - logErrorResponse must read a *clone*, not
+    // the original, or this would come back empty/throw.
+    assert.equal(await res.text(), 'Server.MediaEncoding.Api boom');
+  });
+
+  it('redacts api_key from the logged path - Emby\'s own TranscodingUrl can carry one', async (t) => {
+    const logged: string[] = [];
+    t.mock.method(console, 'log', (line: string) => { logged.push(line); });
+    t.mock.method(globalThis, 'fetch', async () => new Response('nope', { status: 502 }));
+
+    await EmbyClient.fetch('/Videos/1/master.m3u8?api_key=super-secret&MediaSourceId=x', 'tok');
+
+    const line = logged.find((l) => l.includes('[watchparty:emby]'))!;
+    assert.ok(!line.includes('super-secret'), 'the real key must never reach the log');
+    assert.ok(line.includes('api_key=REDACTED'));
+  });
+
+  it('logs nothing extra on a successful response - only failures are interesting', async (t) => {
+    const logged: string[] = [];
+    t.mock.method(console, 'log', (line: string) => { logged.push(line); });
+    t.mock.method(globalThis, 'fetch', async () => new Response('{}', { status: 200 }));
+
+    await EmbyClient.fetch('/Users/u1/Views', 'tok');
+
+    assert.equal(logged.filter((l) => l.includes('[watchparty:emby]')).length, 0);
+  });
+});