Fix subtitles still not showing: force Encode during negotiation, not just the URL

Follow-up to the previous language/subtitle fix - audio track selection
apparently started working, but subtitles specifically still didn't show.

Real gap found: applyPlaybackOverrides was only ever applied to the FINAL
stream URL, never to the PlaybackInfo NEGOTIATION call itself - so
SubtitleMethod=Encode never reached Emby until after it had already
decided, during negotiation, whether this session would be a full
re-encode or a plain remux. Burning a subtitle into the video is only
possible with a real re-encode; appending SubtitleMethod=Encode to a URL
for a session Emby already set up as a remux plausibly does nothing, no
matter how correct the URL looks. server/src/index.js now applies
applyPlaybackOverrides to the negotiation's own params too, so Emby is
asked to encode BEFORE it decides how the session will be handled, not
just told afterward.

Also added server/src/logger.js's streamLog ([watchparty:stream]) - two
rounds of blind, reasoned-but-unverified fixes for one bug is the point
where guessing stops being efficient. Every /master.m3u8 request now logs
its itemId and the resolved audio/subtitle/subtitleMethod/quality values,
so the next retest can confirm from docker logs/journalctl alone whether a
requested override actually reached Emby - without a devtools session on
whatever machine runs the server. Deliberately logs only those specific
values, never the full URL or params blob: Emby's own TranscodingUrl can
carry an api_key, which has no business ending up in a log file.

Verified as far as possible without real Emby access: the negotiation
call's params now measurably carry SubtitleMethod=Encode whenever a
subtitle is requested (same as the final URL always did); the new log line
correctly reports forced audio/subtitle values and reads "(none)" when
nothing was requested; and a test with a fake api_key embedded in the
source params confirms it never appears in the logged line.

If subtitles still don't show once this log line confirms
subtitleMethod=Encode really was sent, the fault is narrowed to Emby's own
handling of that parameter rather than anything before it in this app -
docs/architecture.md has the full writeup.

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

docs/architecture.md

@@ -405,6 +405,37 @@ What's **not** verified is the actual Emby round trip - whether
 produce a transcode that really carries the requested track. That needs a
 real retest.
 
+**Round 2, after a retest: subtitles specifically still didn't show.**
+Found a real gap in the fix above: `applyPlaybackOverrides` was only ever
+applied to the *final* stream URL, not to the `PlaybackInfo` **negotiation**
+call itself - so `SubtitleMethod=Encode` never reached Emby until after it
+had already decided, during negotiation, whether this playback session
+would be a full re-encode or a plain remux. Burning a subtitle into the
+video is only possible with a real re-encode - appending
+`SubtitleMethod=Encode` to a URL for a session Emby had already set up as a
+remux plausibly does nothing, regardless of how correct the URL looks.
+Fixed by applying `applyPlaybackOverrides` to the negotiation's own params
+too (`server/src/index.js`), so Emby is asked to encode *before* it decides
+how the session will actually be handled, not just told afterward.
+Unit-tested (see session history): the negotiation call now measurably
+carries `SubtitleMethod=Encode` whenever a subtitle is requested, same as
+the final URL always did.
+
+Also added `server/src/logger.js`'s `streamLog` (`[watchparty:stream]`,
+alongside the party-lifecycle `partyLog` added separately - see "Server-side
+logging" below) specifically because two rounds of blind, reasoned-but-
+unverified fixes for this one bug is the point where guessing stops being
+efficient: one `master.m3u8` request now logs its `itemId` and the
+resolved `audio`/`subtitle`/`subtitleMethod`/`quality` values (never the
+full URL or params blob - Emby's own `TranscodingUrl` can carry an
+`api_key`, confirmed kept out of the log line by a dedicated test case),
+so the next retest can confirm from `docker logs`/journalctl alone whether
+a requested override actually reached Emby, without needing a devtools
+session on whatever machine runs the server. If subtitles still don't show
+once this log line confirms `subtitleMethod=Encode` really was sent, the
+fault has been narrowed to Emby's own handling of that parameter rather
+than anything before it in this app.
+
 ## Assumptions to verify
 
 **Confirmed against the real server** (not a guess — actually exercised,
@@ -605,10 +636,13 @@ return. Right now it just shows an honest placeholder.
 Requested once the app was running for real on the user's own server:
 visibility into what's actually happening, from `docker logs`/journalctl,
 without needing to reproduce a bug through the UI first. `server/src/logger.js`
-is a deliberately tiny `partyLog(message)` (plain `console.log`, prefixed
-`[watchparty:party]`, ISO timestamp) plus a `who(userId, userName)` formatter
-shared by every call site - no logging library, consistent with this app's
-general bias against dependencies it doesn't need.
+is deliberately tiny - `partyLog(message)` (`[watchparty:party]`) and
+`streamLog(message)` (`[watchparty:stream]`, added a bit later for the
+streaming route specifically - see "Player track selection" above), both
+plain `console.log` with an ISO timestamp, plus a `who(userId, userName)`
+formatter shared by every party-lifecycle call site - no logging library,
+consistent with this app's general bias against dependencies it doesn't
+need.
 
 Covers the party's business lifecycle end to end, called from wherever the
 state actually changes so every caller is covered without repeating the

server/src/index.js

@@ -18,6 +18,7 @@ const {
 const { embyFetch, proxyEmbyResponse } = require('./embyProxy');
 const { PartyManager } = require('./partyManager');
 const { attachSocketServer, broadcastLobby, applyLeave } = require('./socketHandler');
+const { streamLog } = require('./logger');
 
 const app = express();
 app.set('trust proxy', 1); // behind openresty/nginx - needed for req.secure to reflect the real scheme
@@ -245,19 +246,23 @@ app.get('/api/catalog/stream/:itemId/master.m3u8', async (req, res) => {
   // PlaybackInfo returns a MediaSource with its own ready-to-use
   // TranscodingUrl carrying whatever Emby actually needs.
   //
-  // AudioStreamIndex/SubtitleStreamIndex/MaxStreamingBitrate come from the
-  // player's language/subtitle/quality pickers, forwarded into the
-  // negotiation on the off chance Emby's GET-based PlaybackInfo honors them -
-  // but NOT trusted to have taken effect (this app never sends the
+  // AudioStreamIndex/SubtitleStreamIndex/MaxStreamingBitrate (and
+  // SubtitleMethod=Encode, forced by applyPlaybackOverrides whenever a
+  // subtitle is requested - see its own comment below) come from the
+  // player's language/subtitle/quality pickers, applied to the negotiation
+  // itself, not just the final URL. That distinction matters here: whether
+  // to actually re-encode the video (required to burn in a subtitle) is a
+  // decision Emby makes *during* PlaybackInfo, not something a later
+  // query-string tweak on the resulting URL can retroactively change if
+  // Emby already set up a plain remux. Still not trusted to have taken
+  // effect on its own, though (this app never sends the
   // POST-with-DeviceProfile body real Emby web clients use for that
-  // negotiation, so there's no guarantee a plain GET applies them the same
-  // way). applyPlaybackOverrides below forces our selection onto whatever
-  // URL we end up with, Emby-negotiated or hand-built, so a track pick
-  // can't silently no-op regardless of which path Emby's response takes.
+  // negotiation, so there's no guarantee a plain GET applies it the same
+  // way) - applyPlaybackOverrides is applied a second time below, to
+  // whatever URL we end up with, so a track pick can't silently no-op
+  // regardless of which path Emby's response takes.
   const infoParams = new URLSearchParams({ UserId: session.userId });
-  for (const key of ['AudioStreamIndex', 'SubtitleStreamIndex', 'MaxStreamingBitrate']) {
-    if (req.query[key]) infoParams.set(key, req.query[key]);
-  }
+  applyPlaybackOverrides(infoParams, req.query);
   const infoRes = await embyFetch(`/Items/${itemId}/PlaybackInfo?${infoParams}`, session.embyToken);
   if (!infoRes.ok) {
     res.status(502).json({ error: 'Impossible de préparer la lecture de ce titre.' });
@@ -281,6 +286,7 @@ app.get('/api/catalog/stream/:itemId/master.m3u8', async (req, res) => {
     const params = new URLSearchParams(urlQuery || '');
     applyPlaybackOverrides(params, req.query);
     target = `${urlPath}?${params}`;
+    logStreamRequest(itemId, 'negotiated', params);
   } else {
     const params = new URLSearchParams({
       UserId: session.userId,
@@ -291,11 +297,29 @@ app.get('/api/catalog/stream/:itemId/master.m3u8', async (req, res) => {
     });
     applyPlaybackOverrides(params, req.query);
     target = `/Videos/${itemId}/master.m3u8?${params}`;
+    logStreamRequest(itemId, 'fallback', params);
   }
 
   await proxyEmbyResponse(req, res, target, session.embyToken, itemId);
 });
 
+// Deliberately logs only these specific override values, never the full
+// resolved URL/params blob - Emby's own TranscodingUrl can carry an
+// api_key, and that has no business ending up in a log file. Added
+// alongside the language/subtitle fix above so it's actually possible to
+// confirm from docker logs/journalctl whether a requested override made it
+// into the request Emby received, without a devtools session on whatever
+// machine is running the server.
+function logStreamRequest(itemId, source, params) {
+  streamLog(
+    `master.m3u8 itemId=${itemId} source=${source} ` +
+    `audio=${params.get('AudioStreamIndex') || '(default)'} ` +
+    `subtitle=${params.get('SubtitleStreamIndex') || '(none)'} ` +
+    `subtitleMethod=${params.get('SubtitleMethod') || '(none)'} ` +
+    `quality=${params.get('MaxStreamingBitrate') || '(auto)'}`
+  );
+}
+
 /**
  * Forces this app's own audio/subtitle/quality selection onto a transcode
  * URL, whether that URL came from Emby's own PlaybackInfo negotiation or

server/src/logger.js

@@ -18,9 +18,22 @@ function partyLog(message) {
   console.log(`[watchparty:party] ${new Date().toISOString()} ${message}`);
 }
 
+// Separate prefix/function for the streaming route (index.js's
+// /master.m3u8 handler) - a different concern from the party lifecycle
+// above (it's about one HTTP request, not party state), added specifically
+// to make the language/subtitle/quality override actually debuggable from
+// docker logs/journalctl without needing a browser devtools session on the
+// machine running the server. Deliberately logs only the individual
+// override values it cares about, never the full resolved URL or params
+// blob - Emby's own TranscodingUrl can carry an api_key, and that has no
+// business ending up in a log file.
+function streamLog(message) {
+  console.log(`[watchparty:stream] ${new Date().toISOString()} ${message}`);
+}
+
 /** `"name(id)"` - the same shape in every party lifecycle log line. */
 function who(userId, userName) {
   return `${userName}(${userId})`;
 }
 
-module.exports = { partyLog, who };
+module.exports = { partyLog, streamLog, who };