fix(node): log a subtitle request before the cache answers it

A cached track replied without leaving a line, so the journal showed nothing
for a viewer who had asked for subtitles and been served instantly. That made
"no request in the log" look like evidence nobody had asked — which it was not
entitled to be, and which cost a wrong conclusion about whether a fix had been
exercised at all.

The request is logged on arrival now, before the cache is consulted, and a
cache hit says so with the size it served. Second time in this feature that a
silent success was read as an absence; the first was an attach-time state that
was correct while the screen stayed empty.

Co-Authored-By: Claude Opus 5 <noreply@anthropic.com>
Claude-Session: https://claude.ai/code/session_01UGY17EPph5LsLzePPXhUVc

1 files changed, 13 insertions, 5 deletions

diff --git a/packages/meshbay-node/src/meshbay_node/transport/webrtc_server.py b/packages/meshbay-node/src/meshbay_node/transport/webrtc_server.py
index 8ffcbed..180c891 100644
--- a/packages/meshbay-node/src/meshbay_node/transport/webrtc_server.py
+++ b/packages/meshbay-node/src/meshbay_node/transport/webrtc_server.py
@@ -4074,11 +4074,24 @@ class WebRTCPeerSession:
         except (TypeError, ValueError):
             ordinal = -1
 
+        # Logged before the cache is consulted, and that ordering is the point:
+        # a cached track used to answer without leaving a line, so the journal
+        # could not say whether a viewer had asked for subtitles at all. That
+        # turned "no request in the log" into evidence it was never entitled
+        # to be — the second time in this feature that a silent success was
+        # read as an absence.
+        log.info("subtitle: req file=%s track=%d size=%.1fMB slots_free=%s",
+                 file_id[:12], ordinal, entry.size / 1e6,
+                 getattr(self._ctx.get("_transcode_sem"), "_value", "?"))
+        t0 = time.monotonic()
+
         synthetic_id = f"subtitle:{entry.id}:{ordinal}"
         cached_hash = await media_cache.get_thumb_hash_by_file_id(synthetic_id)
         if cached_hash is not None:
             blob = await media_cache.get_thumb(cached_hash)
             if blob is not None:
+                log.info("subtitle: served file=%s track=%d from cache, %d bytes",
+                         file_id[:12], ordinal, len(blob))
                 self._send({"type": MNP.SUBTITLE_RESP, "v": MNP_VERSION,
                             "file_id": file_id, "track": ordinal,
                             "hash": cached_hash, "size": len(blob),
@@ -4087,11 +4100,6 @@ class WebRTCPeerSession:
             # Cached hash but the blob was pruned: fall through and extract
             # again, same as a cold cache.
 
-        log.info("subtitle: req file=%s track=%d size=%.1fMB slots_free=%s",
-                 file_id[:12], ordinal, entry.size / 1e6,
-                 getattr(self._ctx.get("_transcode_sem"), "_value", "?"))
-        t0 = time.monotonic()
-
         probe = await _probe_video(str(file_path))
         if not any(tr.ordinal == ordinal for tr in probe.subtitle_tracks):
             # Not a range check — see this method's docstring.