fix(node): a subtitle request that is cancelled must still answer

Two faults, both found while a hang could not be diagnosed from the node's
own journal.

`except Exception` does not catch `CancelledError`, which derives from
BaseException. A cancelled extraction therefore sent no reply and logged
nothing at all, leaving the client waiting on something nothing would ever
answer — the one shape that cannot be reported by whoever hits it. It now
answers, logs, and re-raises so the cancellation still propagates.

And the handler logged nothing on any path, so the journal could not even say
whether a request had arrived. It now names the file, the track, the file size
and the free slot count on entry, the moment the transcode slot is taken, and
the duration and byte count on the way out — the size and duration because the
extraction is a whole-file demux and its cost is set by the file, not by the
subtitle.

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

1 files changed, 24 insertions, 4 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 f858a53..1e85f29 100644
--- a/packages/meshbay-node/src/meshbay_node/transport/webrtc_server.py
+++ b/packages/meshbay-node/src/meshbay_node/transport/webrtc_server.py
@@ -4081,28 +4081,48 @@ 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.
+            log.warning("subtitle: file=%s has no text track %d", file_id[:12], ordinal)
             self._send({"type": "error", "detail": "No such subtitle track"})
             return
 
         sem = self._transcode_semaphore()
         if sem.locked() and sem._value <= 0:
+            log.info("subtitle: refused, no transcode slot free")
             self._send({"type": "error", "detail": "Server busy, retry shortly"})
             return
         async with sem:
+            log.info("subtitle: extracting file=%s track=%d (slot taken)",
+                     file_id[:12], ordinal)
             try:
                 blob = await _extract_subtitle_to_webvtt(file_path, ordinal)
-            except Exception as e:
-                log.warning("Subtitle extract failed for %s track %d: %s",
-                            entry.id[:12], ordinal, e)
-                self._send({"type": "error", "detail": f"Subtitle extraction failed: {e}"})
+            # BaseException, not Exception: a cancelled task — the peer went
+            # away, the session is being torn down — raises CancelledError,
+            # which is not an Exception and would otherwise leave this handler
+            # with no reply sent and no line in the log. The client is then
+            # waiting on something nothing will ever answer, which is exactly
+            # the shape that is impossible to report.
+            except BaseException as e:
+                log.warning("subtitle: extract failed file=%s track=%d after %.1fs: %r",
+                            file_id[:12], ordinal, time.monotonic() - t0, e)
+                self._send({"type": "error",
+                            "detail": f"Subtitle extraction failed: {e}"})
+                if isinstance(e, asyncio.CancelledError):
+                    raise
                 return
 
         subtitle_hash = blake3.blake3(blob).hexdigest()
         await media_cache.put_thumb(subtitle_hash, synthetic_id, blob)
         self._audit("subtitle_extract", f"{entry.name} [{ordinal}]")
+        log.info("subtitle: extracted file=%s track=%d in %.1fs, %d bytes",
+                 file_id[:12], ordinal, time.monotonic() - t0, len(blob))
         self._send({"type": MNP.SUBTITLE_RESP, "v": MNP_VERSION,
                     "file_id": file_id, "track": ordinal,
                     "hash": subtitle_hash, "size": len(blob),