diff --git a/CLAUDE.md b/CLAUDE.md index 6dffd06..666e431 100644 --- a/CLAUDE.md +++ b/CLAUDE.md @@ -47,6 +47,9 @@ Machine split: workers run on **workpc** (RX 7900 GRE, ROCm). MinIO and the orch shape means reconciling the orchestrator in the same session. Neither repo's self-checks can catch a contract break, because each asserts its own side. 8. **`ponytail:` comments mark deliberate simplifications** and name the upgrade path. Respect them. +9. **Nothing that positions an ffmpeg filter may use `format=duration`.** It reports `max(video, audio)`. + It hides A/V drift, and it walks xfade offsets past the end of their input. ffmpeg then discards clips + and still exits 0 (`decisions/chapter-assembly.md#offsets-from-min-stream`). ## Working rules diff --git a/JOURNAL.md b/JOURNAL.md index 0f380a1..286cbff 100644 --- a/JOURNAL.md +++ b/JOURNAL.md @@ -228,3 +228,44 @@ people who have none, and at least one nameless row is a real recurring person w The "26 of 113 detected people carry an identity" figure that framed the roadmap counted mostly background extras. It should not be quoted again. + +## 2026-08-12, chapter assembly, root cause and fix + +Reproduced the A/V collapse offline with 49 synthetic clips at `ASSEMBLE_BATCH=8` and six `fade_black` +boundaries. It came out worse than the shipped run: **two round-0 groups of 8 fresh clips collapsed on +their own**, so the single-item passthrough theory from yesterday is dead +(`decisions/chapter-assembly.md#passthrough-innocent`). + +Bisected one collapsing group by truncating the chain stage by stage: + +``` +k=7 out= 52.52 correct +k=8 out= 52.52 the last xfade contributed nothing + [v6][n7]xfade=duration=0.050:offset=52.500 <- [v6] is 52.52s long, 0.02s of margin +``` + +`_xfade_chain` took its durations from `_audio_dur`, which is `format=duration`, which is +`max(video, audio)`. Each clip's audio outlasts its video by about a frame, so the offset accumulator +crept ahead of the picture. Once the creep passed the transition width, xfade emitted the transition and +threw away the second input and every clip after it, at `rc 0` with nothing on stderr. + +Fix: offsets come from `min(_stream_dur(v), _stream_dur(a))`, every input is floored to a whole frame +count and `trim`/`atrim`ed on both streams, and `_check_assembled` now verifies each encode against the +predicted timeline instead of trusting the exit code +(`decisions/chapter-assembly.md#offsets-from-min-stream`, `#check-assembled`). + +Verified on the 49 real clips of chapter `7c944dd4`, re-downloaded from MinIO: + +``` +before r1 n=7 XFADE in v=359.29 a=359.60 -> out v= 99.96 a=358.79 +after r1 n=7 XFADE in v=359.61 a=359.62 -> out v=358.76 a=358.76 +chapter v=358.76 a=358.76 gap=+0.00 (shipped: v=436.39 a=363.67 gap=+72.72) +``` + +`worker_render.py` `__main__` passes. Two checks were added there, because the existing 4-clip A/V assert +passed all the way through the broken build. One asserts the frame-exact `trim` on both streams, one +assembles three clips whose audio outlasts their video by 0.4s. Mutation-tested by putting `_audio_dur` +back: the new check fires with `video=1.80 audio=3.56 expected=3.56`. + +Not done: `s3://video/.../chapter.mp4` is still the broken 436s file. Rebuilding it means clearing the +`assemble` stage and resuming, which is CPU-only and was not run. diff --git a/NEXT.md b/NEXT.md index 4ef352b..f9ae0d6 100644 --- a/NEXT.md +++ b/NEXT.md @@ -5,6 +5,7 @@ Updated 2026-08-12. What this session did is in `HANDOFF.md`. ## State The chapter runs end to end and the output is **not watchable**. That is now measured, not guessed. +Assembly is fixed and verified offline. The shipped `chapter.mp4` has not been rebuilt yet. Job `778297bc-e7ce-439d-91b5-8a027060d17f`, chapter `7c944dd4-e972-42c7-ba60-9f6939548e80`, 116 panels, `status=completed`, finished 2026-08-11T20:08:16Z. `s3://video/` holds 49 clips and a 50MiB @@ -12,23 +13,25 @@ Job `778297bc-e7ce-439d-91b5-8a027060d17f`, chapter `7c944dd4-e972-42c7-ba60-9f6 Two numbers set the agenda: -- `chapter.mp4` is video 436.39s over audio 363.67s. The narration finishes 72.7s before the picture. +- The shipped `chapter.mp4` is video 436.39s over audio 363.67s. Cause found and fixed, see below. - Panel 7 checked against the art has **zero correct identity bindings** out of two, and the one character who matters is unbound. `HANDOFF.md#panel-7-walked-against-the-art` has the table. -Uncommitted work sits in the tree: `worker_render.py` has an `FPS = 25` constant, fps normalization in -the xfade branch, a new `_stream_dur`, and a self-check that compares video against audio. The -self-check passes. It does **not** yet fix the chapter. Details and one dead end in `HANDOFF.md`. - ## Next -1. **Fix chapter assembly.** `_assemble_batched` turns 359s of video into 100s while the audio survives. - It reproduces offline in two minutes, no GPU. Round 0 is correct and round 1 collapses. Round 1 is - the only round holding a raw clip that skipped encoding, so suspect the single-item passthrough - first. The recommended shape is one path, not three: normalize every input, then xfade every - boundary, treating `cut` as a 0.05s fade. `acrossfade` and `xfade` shorten audio and video equally, - so the streams stay locked. `HANDOFF.md` holds the per-round table, the filtergraph, and the repro - commands. Nothing downstream is worth judging until this lands. +1. **Rebuild `chapter.mp4`.** Assembly is fixed in `worker_render.py`. Verified over the 49 real clips of + this chapter: video 358.76s against audio 358.76s, agreeing to the frame. The cause was `_xfade_chain` + taking offsets from `format=duration`, which is `max(video, audio)`. The accumulator drifted past the + end of its input, and ffmpeg silently discarded whole clips at `rc 0` + (`decisions/chapter-assembly.md#offsets-from-min-stream`). The single-item passthrough was innocent + and the one-path rewrite is not needed (`decisions/chapter-assembly.md#passthrough-innocent`). + + What is left is to clear the `assemble` stage and resume, then watch the result. That is CPU-only + ffmpeg, no GPU, but it needs the user's go-ahead. + + Smaller follow-on: nine other `_audio_dur` calls in `worker_render.py` measure finished clips with + `format=duration`. So the durations reported to the orchestrator are blind to per-clip drift. + They position no filter, so invariant 9 does not cover them. Worth converting to `_stream_dur`. 2. **Fix identity, in this order.** Panel 7 is the worked example and `HANDOFF.md#panel-7-walked-against-the-art` carries the evidence. Do not start at the registry. diff --git a/decisions/CLAUDE.md b/decisions/CLAUDE.md index f695ef6..021bc8a 100644 --- a/decisions/CLAUDE.md +++ b/decisions/CLAUDE.md @@ -36,3 +36,6 @@ still live belongs in `caveats/`. | [An interjection is not a name and not a misquote](speaker-attribution.md#interjection-false-positive) | closed | | [Cast names enter the verifier tokenized](speaker-attribution.md#multiword-cast-names) | closed | | [Clearing a stage strips the vision blob it wrote](storage-layout.md#clear-vision-blob) | closed | +| [xfade offsets come from `min(video, audio)`, never `format=duration`](chapter-assembly.md#offsets-from-min-stream) | closed | +| [Assembly verifies its own output instead of trusting ffmpeg's exit code](chapter-assembly.md#check-assembled) | closed | +| [The single-item passthrough is not the assembly bug](chapter-assembly.md#passthrough-innocent) | void | diff --git a/decisions/chapter-assembly.md b/decisions/chapter-assembly.md new file mode 100644 index 0000000..d0d81a9 --- /dev/null +++ b/decisions/chapter-assembly.md @@ -0,0 +1,77 @@ +# chapter-assembly + +Settled questions about `_assemble_batched` / `_assemble_once` / `_xfade_chain` in `worker_render.py`. + +## xfade offsets are computed from `min(video, audio)`, never `format=duration` {#offsets-from-min-stream} + +**Closed, 2026-08-12.** + +`_xfade_chain` accumulates `cum += dur[i] - td` and hands each boundary `offset=cum-td`. That offset is +an assertion about where input `i-1` still has frames. It fed on `_audio_dur`, which probes +`format=duration`, which is `max(video, audio)`. A rendered clip's audio outlasts its video by about a +frame. So every boundary pushed the accumulator further ahead of the picture. + +Once the accumulated overshoot exceeds the transition width, the xfade window starts after the last frame +of input `i-1`. ffmpeg emits the transition and then **silently discards input `i` and every clip +downstream of it**. `rc 0`, no warning on stderr, output file present and playable. Measured on a group of +8 real clips, chain truncated at each stage: + +``` +k=7 out= 52.52 correct +k=8 out= 52.52 the last xfade contributed nothing + [v6][n7]xfade=duration=0.050:offset=52.500 <- [v6] is only 52.52s long, so 0.02s of margin +``` + +This is the whole cause of the shipped chapter being video 436.39s over audio 363.67s. It reproduces with +synthetic clips in about four minutes and needs no GPU. + +Two changes hold it closed: + +* `_assemble_once` probes `min(_stream_dur(p, "v"), _stream_dur(p, "a"))`. The minimum, because either + stream running long breaks a different half of the graph. +* `_xfade_chain` floors every input to a whole frame count. It applies `trim` and `atrim` to both streams, + so the accumulator tracks the real timeline instead of estimating it. Transition widths are quantized to + frames for the same reason. + +Verified over the 49 real clips of chapter `7c944dd4`. The round that previously turned 359s of video into +100s now loses 0.85s. The chapter comes out video 358.76s against audio 358.76s, agreeing to the frame. + +Forbidden from here: `_audio_dur` in anything that positions a filter. It is fine for "how long is this +clip roughly", nothing else. + +## Assembly verifies its own output instead of trusting ffmpeg's exit code {#check-assembled} + +**Closed, 2026-08-12.** + +Both assembly branches drop stream time without failing. xfade discards inputs as above. The concat +demuxer with `-vsync cfr` drops video frames to force a constant rate. Neither is an error to ffmpeg. + +So `_assemble_once` calls `_check_assembled(out, expect)` after every encode. It compares the output's +video stream against the predicted timeline and against its own audio stream. It raises when either is off +by more than `ASSEMBLE_TOL_S`, which is 0.5s. That tolerance covers frame boundaries and aac padding. A +dropped input is off by whole seconds. + +Without this the failure stays invisible until somebody watches the video. That is how a 50MiB chapter +with 72.7s of silent picture reached the bucket while every stage counter read success. + +## The single-item passthrough is not the bug {#passthrough-innocent} + +**Void, 2026-08-12.** Cited in `HANDOFF.md` for 2026-08-11 as the prime suspect and must not be cited +again. + +With 49 clips and `ASSEMBLE_BATCH=8`, round 0 makes six groups of 8 plus a leftover group of 1, which +`_assemble_batched` carries forward un-encoded. The theory was that mixing that raw clip with six encoded +intermediates broke round 1. The instrumented run disproves it: **two round-0 groups of 8 fresh clips +collapse on their own**, before any passthrough exists. + +``` +n=8 XFADE in v= 63.52 a= 63.60 -> out v= 52.52 a= 62.77 lost_v= +11.00 +n=8 XFADE in v= 58.12 a= 58.20 -> out v= 12.04 a= 56.83 lost_v= +46.08 +``` + +Round 1's 259s loss was the cascade. Its inputs already held 309s of video against 364s of audio, and +`durs` read the audio. + +Consequence for the plan: collapsing `concat`, `xfade` and the passthrough into one path was the +recommended fix in `NEXT.md` and is **not needed**. Three paths are fine once each one positions filters +on a real timeline. The tree keeps the bounded memory it was built for. diff --git a/worker_render.py b/worker_render.py index 4a15687..5875124 100644 --- a/worker_render.py +++ b/worker_render.py @@ -686,31 +686,57 @@ FFMPEG_THREADS = max(1, int(os.environ.get("FFMPEG_THREADS", "2"))) def _xfade_chain(durs: list, trans: list): """build a filter_complex that xfades N clips with per-boundary transitions, keeping audio in sync via matching acrossfade. trans[i] is the transition OUT of clip i (boundary i->i+1). - returns (filtergraph, video_label, audio_label). offsets accumulate as clips overlap.""" + returns (filtergraph, video_label, audio_label, expected_duration). offsets accumulate as clips + overlap. `durs[i]` MUST be min(video, audio) of input i, not `format=duration`.""" # A clip whose duration probed as 0/unreadable must not poison the chain: with dur=0 the offset # accumulator would run BACKWARDS (cum += dur - td), swallowing every later clip into a frozen # overlap near the middle. Floor to a small positive length so the timeline stays monotonic. durs = [d if (d and d > 0.1) else 0.1 for d in durs] + # The offset accumulator is only as good as `durs`: an offset that lands even one frame past the end + # of input i-1 makes xfade emit the transition and then SILENTLY DROP input i and the whole rest of + # the chain -- rc 0, no warning, a chapter minutes short with the audio intact. So truncate every + # input to a whole number of frames it certainly has (floor, and min(v,a) from the caller) and trim + # both streams to exactly that. Then cum is the real timeline, not an estimate of it. + durs = [max(1, int(d * FPS)) / FPS for d in durs] # Normalize every input to FPS/SAR before it reaches xfade, exactly as the concat branch does. Both # branches feed the same tree, so an un-normalized xfade input is what stretched the chapter 1.2x. - parts = [f"[{i}:v]setsar=1,fps={FPS}[n{i}]" for i in range(len(durs))] - vlast, alast, cum = "[n0]", "[0:a]", durs[0] + parts = [] + for i, d in enumerate(durs): + parts.append(f"[{i}:v]setsar=1,fps={FPS},trim=end={d:.3f},setpts=PTS-STARTPTS[n{i}]") + parts.append(f"[{i}:a]atrim=end={d:.3f},asetpts=PTS-STARTPTS[m{i}]") + vlast, alast, cum = "[n0]", "[m0]", durs[0] for i in range(1, len(durs)): name, td = XFADE.get(trans[i - 1] if i - 1 < len(trans) else "cut", XFADE["cut"]) td = max(0.05, min(td, durs[i - 1] - 0.05, durs[i] - 0.05)) # overlap fits in both clips + td = max(1, int(td * FPS)) / FPS # ...on a frame boundary off = max(cum - td, 0) parts.append(f"{vlast}[n{i}]xfade=transition={name}:duration={td:.3f}:offset={off:.3f}[v{i}]") - parts.append(f"{alast}[{i}:a]acrossfade=d={td:.3f}[a{i}]") + parts.append(f"{alast}[m{i}]acrossfade=d={td:.3f}[a{i}]") vlast, alast, cum = f"[v{i}]", f"[a{i}]", cum + durs[i] - td - return ";".join(parts), vlast, alast + return ";".join(parts), vlast, alast, cum + + +ASSEMBLE_TOL_S = 0.5 # frame-boundary + aac-padding slack; a dropped input is off by whole seconds + + +def _check_assembled(out: str, expect: float): + """ffmpeg drops xfade inputs and re-times concat segments without ever failing, so verify the + result instead of trusting rc 0. Both streams, because a video-only loss is the failure mode that + shipped a 436s picture over 364s of narration.""" + v, a = _stream_dur(out, "v"), _stream_dur(out, "a") + if abs(v - expect) > ASSEMBLE_TOL_S or abs(v - a) > ASSEMBLE_TOL_S: + raise RuntimeError(f"assembly lost stream time in {os.path.basename(out)}: " + f"video={v:.2f} audio={a:.2f} expected={expect:.2f}") def _assemble_once(inputs: list[str], trans: list[str], out: str): """Assemble one bounded batch. `trans[i]` is the transition out of inputs[i].""" + # min(video, audio), never `format=duration`: that is max(video, audio), and feeding it to + # _xfade_chain puts the offset accumulator ahead of the real video timeline. + durs = [min(_stream_dur(p, "v"), _stream_dur(p, "a")) for p in inputs] fancy = len(inputs) >= 2 and any(t not in ("", "cut") for t in trans[:len(inputs) - 1]) if fancy: - durs = [_audio_dur(p) for p in inputs] - fg, vmap, amap = _xfade_chain(durs, trans) + fg, vmap, amap, expect = _xfade_chain(durs, trans) cmd = ["ffmpeg", "-y", "-filter_complex_threads", str(FFMPEG_THREADS)] # Input-side -threads limits each decoder; otherwise ffmpeg may create a decoder thread pool # for every input in the batch in addition to the filter and libx264 pools. @@ -720,6 +746,7 @@ def _assemble_once(inputs: list[str], trans: list[str], out: str): "-c:v", "libx264", "-threads", str(FFMPEG_THREADS), "-pix_fmt", "yuv420p", "-c:a", "aac", "-b:a", "192k", out] subprocess.run(cmd, check=True, capture_output=True) + _check_assembled(out, expect) return # A cut-only batch is concatenated with the concat FILTER, not -c copy or the concat demuxer. @@ -738,6 +765,7 @@ def _assemble_once(inputs: list[str], trans: list[str], out: str): "-c:v", "libx264", "-preset", "veryfast", "-crf", "20", "-pix_fmt", "yuv420p", "-threads", str(FFMPEG_THREADS), "-c:a", "aac", "-b:a", "192k", out] subprocess.run(cmd, check=True, capture_output=True) + _check_assembled(out, sum(durs)) def _assemble_batched(inputs: list[str], transitions: list[str], out: str, tag: str, @@ -952,8 +980,14 @@ if __name__ == "__main__": for p in (img, bed, *cl): if os.path.exists(p): os.remove(p) # #6 transitions: two real clips xfade into one chapter; graph offsets/labels well-formed. - fg, vmap, amap = _xfade_chain([1.0, 1.0], ["fade_white"]) + fg, vmap, amap, exp = _xfade_chain([1.0, 1.0], ["fade_white"]) assert "xfade=transition=fadewhite" in fg and vmap == "[v1]" and amap == "[a1]" + # Both streams of every input trimmed to a whole frame count. That is what keeps the offset + # accumulator ON the real timeline: an offset one frame past the end of input i-1 makes xfade + # emit the transition and then silently drop input i and everything after it, rc 0, no warning. + assert fg.count(",trim=end=") == 2 and fg.count("]atrim=end=") == 2, fg + _td = max(1, int(XFADE["fade_white"][1] * FPS)) / FPS + assert abs(exp - (2.0 - _td)) < 0.001, (exp, _td) img = f"{SHM}/t.png" subprocess.run(["ffmpeg", "-y", "-f", "lavfi", "-i", "color=c=black:s=400x600", "-frames:v", "1", img], check=True, capture_output=True) @@ -986,8 +1020,33 @@ if __name__ == "__main__": if os.path.exists(p): os.remove(p) vd, ad = _stream_dur(out, "v"), _stream_dur(out, "a") assert abs(vd - ad) < 0.25, f"A/V drift: video {vd:.2f}s vs audio {ad:.2f}s" + # ...and the guard that catches it in production must actually fire. `assemble` reports success + # off ffmpeg's rc, which is 0 even when a whole batch of inputs is thrown away. + try: + _check_assembled(out, vd + 5.0) + raise AssertionError("_check_assembled did not fire on a 5s loss") + except RuntimeError: + pass for p in (img, c0, c1, c2, c3): os.remove(p) + # The offset creep itself, reproduced small. A real clip's audio outlasts its video slightly, and + # `format=duration` reports the audio, so the accumulator walked ahead of the picture until one + # xfade window ran past the end of its first input -- at which point ffmpeg emitted the + # transition, threw away the second input and everything downstream, and exited 0. Clips with + # audio 0.4s longer than the video exaggerate one clip's worth of that creep. + cs = [] + for i in range(3): + c = f"{SHM}/creep{i}.mp4"; cs.append(c) + subprocess.run(["ffmpeg", "-y", "-f", "lavfi", "-i", "testsrc2=s=160x120:r=25:d=1.0", + "-f", "lavfi", "-i", f"sine=f={300 + i * 40}:d=1.4", + "-c:v", "libx264", "-preset", "ultrafast", "-pix_fmt", "yuv420p", + "-c:a", "aac", c], check=True, capture_output=True) + _assemble_once(cs, ["fade_black", "cut", "cut"], out) # raises if an input was dropped + vd, ad = _stream_dur(out, "v"), _stream_dur(out, "a") + assert vd > 2.2, f"xfade dropped inputs: {vd:.2f}s from 3 clips of 1.0s" + assert abs(vd - ad) < 0.1, f"A/V drift: video {vd:.2f}s vs audio {ad:.2f}s" + for p in cs: + os.remove(p) # #6 composite: 2 panels + 2 audios -> one stacked clip; duration = sum, subs timed per row. a2 = f"{SHM}/a2.wav" subprocess.run(["ffmpeg", "-y", "-f", "lavfi", "-i", "anullsrc=r=16000:cl=mono", "-t", "1.5", a2],