diff --git a/docs/architecture.md b/docs/architecture.md index 96d91d5..d1a0191 100644 --- a/docs/architecture.md +++ b/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, diff --git a/server/package.json b/server/package.json index c92861b..ee3d5a9 100644 --- a/server/package.json +++ b/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" diff --git a/server/src/Logger.ts b/server/src/Logger.ts index 51d9549..6eff759 100644 --- a/server/src/Logger.ts +++ b/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}`); + } } diff --git a/server/src/emby/EmbyClient.ts b/server/src/emby/EmbyClient.ts index a93c1e5..3331017 100644 --- a/server/src/emby/EmbyClient.ts +++ b/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 { const url = pathAndQuery.startsWith('http') ? pathAndQuery : `${EMBY_SERVER_URL}${pathAndQuery}`; const headers: Record = { '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 { + 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 { diff --git a/server/test/embyClient.test.ts b/server/test/embyClient.test.ts new file mode 100644 index 0000000..835f88a --- /dev/null +++ b/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); + }); +});