Bound time-to-first-byte so a first play actually plays

Playback failed in Jellyfin the day after deployment, for uncached videos
only. The handler blocked on the full download-and-mux before sending
anything at all -- not even response headers -- so a 46-minute upload sat
silent for 79 seconds and the client gave up. The proxy counted it a
success, which is why /healthz and doctor both looked fine.

Yesterday's "DirectPlay verified" only ever ran against videos already
pulled during testing, so the first-play path was never exercised.

The output is already a fragmented MP4, so it is readable while being
written; a finished file only buys a correct duration and working seeks.
Cap the wait at --first-byte-grace (12s, explicit in the unit) and stream
whatever has not muxed by then. Measured: 156s -> 12.0s TTFB on a
66-minute upload, with ranges on a complete file unchanged.

The cost is a first play with no seek bar when the grace is missed. Every
later play of that video is perfect.

Also fixes a hang found while testing this: the streaming loop waited on
"finished and good" rather than "finished", so a producer that died after
writing some bytes held the connection for the full 45s stall timeout and
then dropped it.

The stale yt-dlp warning pointed at youtube-automate's venv, the tree we
are decommissioning; it now names ytstream's. /healthz reports the serving
mode and grace. Eight new proxy tests, 353 passing.

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

deploy/ytstream-proxy.service

@@ -21,6 +21,12 @@ UMask=0002
 Environment=PATH=/var/lib/ytstream/venv/bin:/usr/local/sbin:/usr/local/bin:/usr/sbin:/usr/bin:/sbin:/bin
 Environment=PYTHONUNBUFFERED=1
 
+# --first-byte-grace is the difference between "plays" and "playback error".
+# Waiting for a complete mux costs ~3s to extract plus duration/50..110 to pull,
+# so a 46-minute upload blocked this socket for 79 silent seconds and Jellyfin
+# gave up long before. Do not raise this to --wait-timeout without re-reading
+# the module docstring: that restores the behaviour that broke first plays.
+
 WorkingDirectory=/opt/ytstream
 ExecStart=/var/lib/ytstream/venv/bin/python3 /opt/ytstream/proxy/ytstream_proxy.py \
     --host 127.0.0.1 --port 8099 \
@@ -28,7 +34,8 @@ ExecStart=/var/lib/ytstream/venv/bin/python3 /opt/ytstream/proxy/ytstream_proxy.
     --cache-gb 8 \
     --max-pipelines 2 \
     --max-retries 2 \
-    --max-starts 20 --starts-window 3600
+    --max-starts 20 --starts-window 3600 \
+    --first-byte-grace 12
 
 Restart=always
 RestartSec=5

plan.md

@@ -1053,3 +1053,87 @@ automatically after `materialise --all`.
 | Playback via Jellyfin `PlaybackInfo` | DirectPlay h264 720p + aac, 2049 s runtime |
 | Episodes with plot / aired after refresh | 251 / 251 |
 | `doctor` | all fatal checks pass |
+
+## 19. First play was broken, and how — 2026-08-13
+
+The day after deployment, playback failed in Jellyfin. The service was healthy the
+whole time: both units active, `doctor` green, `/healthz` reporting `failed: 0`.
+
+**Cached videos played; uncached ones did not.** Yesterday's "DirectPlay verified"
+was measured only on videos already pulled during testing, so the first-play path
+had never actually been exercised end to end. That is the hole in §18's evidence.
+
+### The mechanism
+
+In wait-for-complete mode the handler blocked on `sess.final.wait(wait_timeout)`
+before sending anything — not the body, not even response headers. The wait is the
+whole download and mux:
+
+| upload | cold time to first byte |
+|---|---|
+| 8 min | ~10 s |
+| 6.8 min *(one transient failure + retry)* | >12 s |
+| 22 min | 47 s |
+| 46 min | **79 s** ← what the user hit |
+| 66 min | 156 s |
+
+No player waits that long, so the socket sat silent until the client gave up. The
+proxy counted it a success, which is why nothing looked wrong from inside.
+
+### The fix: bound the wait, then stream
+
+The output is already a fragmented MP4 (`frag_keyframe+empty_moov`), so it is
+readable while being written. The only thing a *finished* file buys is a correct
+duration and working seeks — ffmpeg patches the real duration into the moov on
+close, and ignores both `mvhd.duration` and an injected `mehd` before then
+(confirmed: a growing file probes 197 s → 1185 s → 2378 s → 4127 s against a true
+4128 s).
+
+So the wait is now capped by `--first-byte-grace` (default 12 s, explicit in the
+unit). Whatever has not muxed by then is streamed as it is written.
+
+| | before | after |
+|---|---|---|
+| TTFB, 66-min upload cold | 156 s (silent) | **12.0 s** |
+| TTFB, same video cached | ~0 | ~0 |
+| Range request on a complete file | 206 + `Content-Range` | unchanged, 1.7 ms |
+
+`--first-byte-grace` is a **cap, not a prediction**. Completion time ranged 10–156 s
+and does not track duration closely: YouTube's per-format throttling varies, and one
+transient failure plus a retry costs ~5 s of extraction before any byte is pulled.
+Raising it to `--wait-timeout` restores the old finished-file-or-504 behaviour, which
+is the bug. The unit carries a comment saying so.
+
+### Cost, stated plainly
+
+A first play that misses the grace has **no seek bar and no duration** for that
+watch. The stream is chunked with no `Content-Length`, so the client cannot seek
+even after the mux lands mid-play; it has to re-request, which happens on the next
+play. Every subsequent play of that video is perfect and instant. This is a real
+regression against a *hypothetical* fast first play, and a large improvement over
+an error.
+
+### A second bug found while fixing the first
+
+The streaming loop waited on `sess.complete` (finished **and** good) rather than
+`sess.final` (finished). A producer that died after writing some bytes therefore
+never satisfied the wait: the loop sat in `_wait_for_bytes` for the full 45 s
+`STALL_TIMEOUT` and then dropped the connection. Now split into `finished` for every
+wait and `sess.complete` only for the ranges decision. Caught by a new test, not by
+inspection.
+
+### Also corrected
+
+The too-old-yt-dlp warning pointed at `/var/lib/youtube-automate/venv/bin` — the tree
+§12 decommissions. It now names ytstream's venv, and says the unit pins PATH so a
+manual run has to as well. That warning is what a future debugger reads at 2am.
+
+The `/healthz` payload gained `mode` (`wait-then-stream` / `growing`) and
+`first_byte_grace_s`, because the difference between "plays" and "playback error" was
+invisible without reading the unit file.
+
+Eight new tests in `test_proxy.py` cover: a slow mux streaming instead of blocking, a
+fast mux keeping ranges and seeking, `--first-byte-grace` at `--wait-timeout`
+restoring strict mode, a failed producer with bytes being served but 502 in strict
+mode, a failed producer with no bytes always 502, `--growing` meaning no wait, and
+`/healthz` reporting the mode. 353 pass.

proxy/ytstream_proxy.py

@@ -26,15 +26,25 @@ Safety rails, because a Jellyfin library scan can ask for every episode at once:
                     hour; a refresh storm hits the cap in seconds.
   --cache-gb        tmpfs budget; least-recently-used complete files are evicted.
 
-Two serving modes, as in the PoC:
+Serving modes. The output is a fragmented MP4, so it is readable while it is
+still being written; the only thing a finished file buys is a correct duration
+and working seeks, because ffmpeg patches the real duration into the moov on
+close and ignores both mvhd.duration and an injected mehd box before then.
 
-  default     wait for the mux to finish, then serve. Correct duration, ranges
+  default            wait for the mux, but only for --first-byte-grace seconds,
-              and seeking. Costs time-to-first-byte (~60x realtime pull, so a
+                     then serve what exists. Short videos finish inside the
-              46-minute video is ready in about 50s).
+                     grace and keep the exact duration and ranges; long ones
-  --growing   serve while writing. Low TTFB, but a probe of a partially written
+                     start immediately and regain both when the mux lands.
-              fragmented MP4 reports only the duration written so far. ffmpeg
+  --first-byte-grace raise it above --wait-timeout for the old strict behaviour
-              ignores both mvhd.duration and an injected mehd box, so this
+                     (finished file or 504), which is only safe for a client
-              cannot be fixed in the container.
+                     that will wait minutes for its first byte.
+  --growing          grace of zero: serve as soon as any byte exists.
+
+Why the grace exists at all, measured 2026-08-13 on this machine: the wait is
+~3s to extract plus roughly duration/50..110 to pull and mux, so a 46-minute
+upload took 79 seconds during which the handler sent nothing -- not even
+response headers. Jellyfin reported "playback error" on the first play of every
+long video while already-cached ones played perfectly.
 """
 
 import argparse
@@ -63,6 +73,15 @@ POT_ARGS = "youtubepot-bgutilhttp:base_url=http://127.0.0.1:4416"
 CLIENT_ARGS = "youtube:player_client=default"
 MAX_HEIGHT = 720
 STALL_TIMEOUT = 45.0
+# How long a request may block waiting for a *complete* mux before it gives up and
+# streams the partial file instead. This is a cap on time-to-first-byte, not a
+# prediction: measured cold on 2026-08-13, completion ran from 10s (8-minute
+# upload) to 156s (66-minute upload), and it does not follow the duration closely
+# because YouTube's per-format throttling varies and one transient failure plus a
+# retry costs ~5s of extraction before any byte is pulled. So do not tune this
+# expecting to cover "videos up to N minutes" -- it catches the quick cases,
+# absorbs a single retry, and bounds the bad case at something a player tolerates.
+FIRST_BYTE_GRACE = 12.0
 VIDEO_ID_RE = re.compile(r"^[A-Za-z0-9_-]{11}$")
 
 _log_lock = threading.Lock()
@@ -308,6 +327,9 @@ class Manager:
         self.cache_bytes = cache_bytes
         self.no_fetch = no_fetch
         self.growing = growing
+        # Reported by /healthz so the serving mode is visible without reading the
+        # unit file. Set by main(); the handler holds the value it actually uses.
+        self.first_byte_grace = 0.0 if growing else FIRST_BYTE_GRACE
         self.lock = threading.Lock()
         self.sessions = {}
         self.counters = {"requests": 0, "started": 0, "reused": 0,
@@ -438,7 +460,8 @@ class Manager:
     def status(self):
         with self.lock:
             return {
-                "mode": "growing" if self.growing else "wait-for-complete",
+                "mode": "growing" if self.growing else "wait-then-stream",
+                "first_byte_grace_s": self.first_byte_grace,
                 "no_fetch": self.no_fetch,
                 "max_pipelines": self.max_pipelines,
                 "max_starts": self.max_starts,
@@ -465,7 +488,7 @@ class Manager:
 # HTTP
 # --------------------------------------------------------------------------
 
-def make_handler(mgr, wait_timeout):
+def make_handler(mgr, wait_timeout, first_byte_grace=FIRST_BYTE_GRACE):
 
     class Handler(BaseHTTPRequestHandler):
         protocol_version = "HTTP/1.1"
@@ -478,11 +501,18 @@ def make_handler(mgr, wait_timeout):
         def _size(self, path):
             return os.path.getsize(path) if os.path.exists(path) else 0
 
-        def _wait_for_bytes(self, path, offset, complete):
+        def _wait_for_bytes(self, path, offset, finished):
+            """Block until the file grows past `offset`, or nothing more is coming.
+
+            `finished` must mean "the producer has stopped", not "the producer
+            succeeded" -- a run that died after writing some bytes never grows
+            again, and waiting on success would hang here for STALL_TIMEOUT and
+            then drop the connection.
+            """
             deadline = time.monotonic() + STALL_TIMEOUT
             while True:
                 size = self._size(path)
-                if size > offset or complete():
+                if size > offset or finished():
                     return size
                 if time.monotonic() > deadline:
                     raise TimeoutError
@@ -551,27 +581,39 @@ def make_handler(mgr, wait_timeout):
                 self._fail(503, refusal, retry_after=30)
                 return
 
-            if not mgr.growing:
+            # A finished file is worth a short wait -- it is the only way to get a
-                # Correct duration and working seeks require a finished file.
+            # correct duration and working seeks -- but the wait is proportional
+            # to the video's length, and until it ends this handler sends nothing
+            # at all, not even response headers. Bound it. Whatever has not muxed
+            # inside the grace gets served while it is still being written, which
+            # is possible because the container is fragmented.
+            grace = 0.0 if mgr.growing else min(first_byte_grace, wait_timeout)
+            strict = grace >= wait_timeout
+            if grace > 0 and not sess.final.is_set():
+                access(f"  -> waiting up to {grace:.0f}s for {video_id} to mux")
+                sess.final.wait(grace)
+
             if not sess.final.is_set():
-                    access(f"  -> waiting for {video_id} to finish muxing")
+                if strict:
-                    if not sess.final.wait(wait_timeout):
                     self._fail(504, "mux did not finish in time")
                     return
-                if sess.failed:
+                # Serving a partial file still needs its first bytes to exist: a
-                    access(f"  -> 502 producer failed: {sess.failed[:120]}")
+                # retry underneath can leave the size at 0 for a while, so wait
-                    self._fail(502, f"producer failed: {sess.failed[:200]}")
+                # on both the size and the terminal signal.
-                    return
+                access(f"  -> serving {video_id} while it is still muxing")
-            else:
-                # Growing mode still needs the first bytes to exist. Retries
-                # happen underneath while size is still 0, so wait on both.
                 deadline = time.monotonic() + STALL_TIMEOUT
                 while sess.size() == 0 and not sess.final.is_set():
                     if time.monotonic() > deadline:
                         self._fail(504, "producer wrote nothing")
                         return
                     time.sleep(0.1)
-                if sess.failed and sess.size() == 0:
+
+            # `failed` is only ever set together with `final`, so this covers both
+            # paths. Strict callers asked for a good file and get an error
+            # instead; otherwise a partial file is better than nothing, and a
+            # failure with no bytes at all is still an error.
+            if sess.failed and (strict or sess.size() == 0):
+                access(f"  -> 502 producer failed: {sess.failed[:120]}")
                 self._fail(502, f"producer failed: {sess.failed[:200]}")
                 return
 
@@ -602,12 +644,16 @@ def make_handler(mgr, wait_timeout):
 
         def _serve(self, sess, head_only):
             path = sess.out_path
-            complete = lambda: sess.complete            # noqa: E731
+            # Two different questions, and conflating them hangs the connection:
+            # `finished` is "no more bytes are coming", which is what every wait
+            # below must test; `sess.complete` additionally means the file is
+            # good, which is what ranges require.
+            finished = lambda: sess.final.is_set()      # noqa: E731
 
             # Ranges are only honoured once the file is complete; while it is
             # still growing there is no reliable time-to-byte mapping into a
             # fragmented MP4, so we present a non-seekable stream instead.
-            chunked = not complete()
+            chunked = not sess.complete
             start, end, is_range = 0, None, False
             if not chunked:
                 spec = self._parse_range(self.headers.get("Range"),
@@ -624,7 +670,7 @@ def make_handler(mgr, wait_timeout):
                     is_range = True
 
             try:
-                self._wait_for_bytes(path, start, complete)
+                self._wait_for_bytes(path, start, finished)
             except TimeoutError:
                 self._fail(504, "producer stalled")
                 return
@@ -672,10 +718,10 @@ def make_handler(mgr, wait_timeout):
                             if remaining is not None:
                                 remaining -= len(buf)
                             continue
-                        if complete() and sent >= self._size(path):
+                        if finished() and sent >= self._size(path):
                             break
                         try:
-                            self._wait_for_bytes(path, sent, complete)
+                            self._wait_for_bytes(path, sent, finished)
                         except TimeoutError:
                             break
                 if chunked:
@@ -698,7 +744,12 @@ def main():
     ap.add_argument("--cache-gb", type=float, default=8.0)
     ap.add_argument("--max-pipelines", type=int, default=2)
     ap.add_argument("--wait-timeout", type=float, default=300.0,
-                    help="how long a request may block waiting for the mux")
+                    help="hard cap on blocking for the mux; only reachable when "
+                         "--first-byte-grace is raised to meet it")
+    ap.add_argument("--first-byte-grace", type=float, default=FIRST_BYTE_GRACE,
+                    help=f"seconds to wait for a complete mux before streaming "
+                         f"the partial file instead (default {FIRST_BYTE_GRACE:g}). "
+                         f"Raise to --wait-timeout for finished-file-or-504")
     ap.add_argument("--max-starts", type=int, default=20,
                     help="max cold starts per window; bounds a runaway library "
                          "refresh (default 20)")
@@ -711,7 +762,8 @@ def main():
                     help="never start a pipeline; log and 503. Use for a first "
                          "library scan to detect probing with no YouTube traffic")
     ap.add_argument("--growing", action="store_true",
-                    help="serve while still writing (low TTFB, wrong duration)")
+                    help="never wait: serve as soon as a byte exists, which is "
+                         "--first-byte-grace 0")
     ap.add_argument("--access-log", default=None)
     args = ap.parse_args()
 
@@ -722,8 +774,8 @@ def main():
     version = ver.stdout.strip()
     if version < "2025":
         log(f"WARNING: yt-dlp {version} looks far too old, and a POT plugin is "
-            f"required. Expected the automation venv "
+            f"required. Expected ytstream's venv (/var/lib/ytstream/venv/bin) "
-            f"(/var/lib/youtube-automate/venv/bin) on PATH.")
+            f"first on PATH -- the unit pins it, a manual run must too.")
     else:
         log(f"yt-dlp {version}")
 
@@ -735,14 +787,24 @@ def main():
                   int(args.cache_gb * 2**30), args.no_fetch, args.growing,
                   args.max_retries, args.max_starts, args.starts_window)
 
+    grace = 0.0 if args.growing else min(args.first_byte_grace, args.wait_timeout)
+    mgr.first_byte_grace = grace
+
     if args.no_fetch:
         log("NO-FETCH MODE: every /watch request will be logged and refused. "
             "No YouTube traffic will be generated.")
-    if args.growing:
+    if grace <= 0:
-        log("growing mode: probes will see a partial duration")
+        log("growing mode: a first play seeks badly and shows no duration until "
+            "the mux lands")
+    elif grace >= args.wait_timeout:
+        log(f"strict mode: a request blocks up to {grace:g}s for a complete mux "
+            f"and 504s otherwise -- long videos will fail to start")
+    else:
+        log(f"waiting up to {grace:g}s for a complete mux, then streaming the "
+            f"partial file")
 
     srv = ThreadingHTTPServer((args.host, args.port),
-                              make_handler(mgr, args.wait_timeout))
+                              make_handler(mgr, args.wait_timeout, grace))
     log(f"listening on http://{args.host}:{args.port}  "
         f"(/watch/<video_id>, /healthz)")
     try:

tests/test_proxy.py

@@ -105,8 +105,9 @@ def growing_server(tmp_path):
     yield from _serve(manager)
 
 
-def _serve(manager):
+def _serve(manager, wait_timeout=30, grace=proxy.FIRST_BYTE_GRACE):
-    server = ThreadingHTTPServer(("127.0.0.1", 0), proxy.make_handler(manager, 30))
+    server = ThreadingHTTPServer(
+        ("127.0.0.1", 0), proxy.make_handler(manager, wait_timeout, grace))
     threading.Thread(target=server.serve_forever, daemon=True).start()
     try:
         yield server.server_address[1]
@@ -214,6 +215,145 @@ def test_growing_file_is_chunked_and_tracks_to_eof(growing_server):
     assert body == BODY
 
 
+# ------------------------------------------------- time-to-first-byte grace
+#
+# Waiting for a complete mux is the only way to get a correct duration and
+# working seeks, but the wait grows with the video's length and sends nothing at
+# all -- not even headers -- while it lasts. A 46-minute upload blocked for 79s
+# and Jellyfin reported a playback error on every first play of a long video.
+# These tests pin the compromise: wait, but only for a bounded grace.
+
+
+def _partial(tmp_path, *, finishes_after):
+    """A half-written file that completes after `finishes_after` seconds."""
+    path = tmp_path / "out.mp4"
+    path.write_bytes(BODY[:1000])
+    session = StubSession(path, finished=False)
+
+    def finish():
+        time.sleep(finishes_after)
+        with open(path, "ab") as handle:
+            handle.write(BODY[1000:])
+        session.final.set()
+
+    threading.Thread(target=finish, daemon=True).start()
+    return session
+
+
+def test_a_slow_mux_streams_instead_of_blocking(tmp_path):
+    """The bug: this used to block for --wait-timeout with the socket silent."""
+    session = _partial(tmp_path, finishes_after=1.0)
+    server = _serve(StubManager(session), wait_timeout=30, grace=0.2)
+    port = next(server)
+    try:
+        started = time.monotonic()
+        status, head, body = request(port, {"Range": "bytes=0-"})
+        elapsed = time.monotonic() - started
+
+        assert status == 200
+        assert head.get("Transfer-Encoding") == "chunked"
+        assert body == BODY
+        # The whole point: it returned on the mux's schedule, not the timeout's.
+        assert elapsed < 10, f"blocked {elapsed:.1f}s -- grace not applied"
+    finally:
+        server.close()
+
+
+def test_a_mux_that_lands_inside_the_grace_keeps_ranges_and_seeking(tmp_path):
+    """The fast path must survive: a short video still gets a real 206."""
+    session = _partial(tmp_path, finishes_after=0.2)
+    server = _serve(StubManager(session), wait_timeout=30, grace=10)
+    port = next(server)
+    try:
+        status, head, body = request(port, {"Range": "bytes=100-199"})
+
+        assert status == 206
+        assert head["Content-Range"] == f"bytes 100-199/{TOTAL}"
+        assert head.get("Transfer-Encoding") is None
+        assert body == BODY[100:200]
+    finally:
+        server.close()
+
+
+def test_grace_at_the_wait_timeout_restores_strict_finished_file_only(tmp_path):
+    """The old behaviour stays reachable, for a caller that really wants it."""
+    session = _partial(tmp_path, finishes_after=60)
+    server = _serve(StubManager(session), wait_timeout=0.3, grace=0.3)
+    port = next(server)
+    try:
+        status, _, _ = request(port)
+        assert status == 504
+    finally:
+        server.close()
+
+
+def test_a_failed_producer_with_bytes_is_served_rather_than_erroring(tmp_path):
+    """Most of a video beats none of it -- except in strict mode, where the
+    caller asked for a good file and must be told it cannot have one."""
+    path = tmp_path / "out.mp4"
+    path.write_bytes(BODY)
+    session = StubSession(path, finished=True)
+    session.failed = "ffmpeg exited 1"
+
+    lenient = _serve(StubManager(session), wait_timeout=30, grace=1)
+    port = next(lenient)
+    try:
+        assert request(port)[0] == 200
+    finally:
+        lenient.close()
+
+    strict = _serve(StubManager(session), wait_timeout=1, grace=1)
+    port = next(strict)
+    try:
+        assert request(port)[0] == 502
+    finally:
+        strict.close()
+
+
+def test_a_failed_producer_with_no_bytes_is_always_502(tmp_path):
+    path = tmp_path / "out.mp4"
+    path.write_bytes(b"")
+    session = StubSession(path, finished=True)
+    session.failed = "yt-dlp[video] exited 1"
+
+    server = _serve(StubManager(session), wait_timeout=30, grace=1)
+    port = next(server)
+    try:
+        assert request(port)[0] == 502
+    finally:
+        server.close()
+
+
+def test_growing_flag_means_no_wait_at_all(tmp_path):
+    """--growing is a grace of zero, and must not be overridden by the default."""
+    session = _partial(tmp_path, finishes_after=0.5)
+    manager = StubManager(session, growing=True)
+    server = _serve(manager, wait_timeout=30, grace=proxy.FIRST_BYTE_GRACE)
+    port = next(server)
+    try:
+        started = time.monotonic()
+        status, head, _ = request(port)
+        assert status == 200
+        assert head.get("Transfer-Encoding") == "chunked"
+        # Would have waited the full 12s default grace if growing were ignored.
+        assert time.monotonic() - started < 5
+    finally:
+        server.close()
+
+
+def test_status_reports_the_serving_mode_and_grace(manager_factory):
+    """/healthz has to show this: it is the difference between 'plays' and
+    'playback error', and it is otherwise invisible without the unit file."""
+    manager = manager_factory()
+    status = manager.status()
+    assert status["mode"] == "wait-then-stream"
+    assert status["first_byte_grace_s"] == proxy.FIRST_BYTE_GRACE
+
+    growing = manager_factory(growing=True)
+    assert growing.status()["mode"] == "growing"
+    assert growing.status()["first_byte_grace_s"] == 0.0
+
+
 # ------------------------------------------------------------------- routing