← Commit history

v1.9.43 — FIX: a newly-arrived clip was killed on arrival by the PREVIOUS clip's telemetry. The page moved curClipId synchronously while <audio> still held the old clip during blob download, so done/position from clip A were attributed to clip B (cut off ~3s in, falsely reported ok). Page now tracks loadedClipId + sends loaded=0 with zeroed telemetry while downloading and resets the element synchronously; drainer ignores telemetry unless loaded=1. ralph-test T10 reproduces the race (11/11).

John Lauer ·6474941bc6 ·2mo ago ·parent 2a1e619
9 files changed +113−36
Cargo.lock+1−1
@@ -4,7 +4,7 @@ version = 4  [[package]] name = "adom-tts"-version = "1.9.42"+version = "1.9.43" dependencies = [  "anyhow",  "base64",
Cargo.toml+1−1
@@ -1,6 +1,6 @@ [package] name = "adom-tts"-version = "1.9.42"+version = "1.9.43" edition = "2021" license = "AGPL-3.0-or-later" repository = "https://github.com/adom-inc/adom-tts"
VERSION+1−1
@@ -1 +1 @@-1.9.42+1.9.43
dev-skills/adom-tts-dev/SKILL.md+14
@@ -129,6 +129,20 @@ manually — deploy a new version and let supersede do the handoff. If you must   keeps the flash: audio is still owed. - **Run `tools/ralph-test.sh` before every release** — see the adom-tts-test   skill for the full matrix and the incident behind each test.+- **TELEMETRY MUST BE VOUCHED FOR (`loaded=1`).** The page's `/poll` carries+  `t`/`dur`/`done` read off the `<audio>` element, but `curClipId` moves the+  INSTANT a new clip arrives while the element still holds the PREVIOUS clip+  until its blob finishes downloading. That window reported the new id with the+  old clip's `ended`/position, so the drainer marked the new clip done on+  arrival, advanced, and cut it off ~3s in — while telling its sender "ok"+  (field: two threads sent clips back to back; clip two died at 2.8s and 3.3s+  carrying clip one's exact `reached`). FIX, both sides: the page tracks+  `loadedClipId` (the id the element ACTUALLY holds), sends `loaded=0` with+  zeroed numbers while downloading, and resets the element synchronously in+  `applyClip`; the drainer ignores all telemetry unless `loaded=1`. Any future+  "second clip got cut off" or "verdict ok but it barely played" → suspect this+  first, and note the tell: the victim's `reached_s` EQUALS the previous clip's.+  ralph-test T10 reproduces the exact race (`stale-done` fake-page mode). - **NEVER auto-replay audio the human already heard.** Retry is for TRULY-SILENT   clips only: `verdict == "no-playback"` (reached==0) AND `i_own_lock()`. A clip   that produced ANY audio (`partial`) is NEVER re-queued — it goes to History,
dev-skills/adom-tts-test/SKILL.md+8
@@ -39,6 +39,7 @@ and the incident behind each: | T7 hash metadata recovery | "what is this garbage in the header": bare snapshot replays must recover name/thread/desc | | T8 orphan → interrupted History | a killed drainer's clip is never silently destroyed (the human may have paused it) | | T9 port stability | "the port differs on every invocation": a page must reconnect to the same port |+| T10 second clip survives the swap | "two threads sent clips and you stopped the playing one": stale telemetry from clip A killed clip B on arrival (falsely "ok"). The `stale-done` fake-page mode replays the blob-download window; B must live >4s and never inherit A's `reached` |  Extending: add a `say "TN ..."` block copying an existing test. Trigger the behavior via the real CLI, assert via events.jsonl (`ev <kind>`) or the queue@@ -84,6 +85,13 @@ paths were "fine". Drive the real page for:   must be `window.x` or function declarations; read live ids from `/poll`, not   from `window.curClipId`. - **pup eval responses put the value in `.result`** (not `.output`).+- **A clip's `reached_s` equal to the PREVIOUS clip's is the tell** for stale+  telemetry being attributed across a clip swap. Cross-check wall-clock+  (clip_end.ts - clip_start.ts) against `reached_s`: a clip that "reached 111s"+  in 3 seconds of wall time did not play, whatever its verdict says.+- **Synthetic clips need DISTINCT durations.** Giving every fake clip the same+  duration made an inheritance assertion pass/fail by coincidence; T10 derives+  `dur` from the clip id so consecutive clips always differ.  ## 4. Release gate 
page.json−21
@@ -12,7 +12,6 @@     "audio",     "demo",     "accessibility",-    "cli",     "open-source",     "mit"   ],@@ -65,25 +64,5 @@   ],   "install": {     "binary_name": "adom-tts"-  },-  "description": "Adom's shared text-to-speech CLI + Playground. Reads your AI answers back to you while driving, and renders perfectly-timed voiceover tracks for demo videos.",-  "dependencies": {},-  "scripts": {-    "install": "./install.sh",-    "uninstall": "./uninstall.sh"-  },-  "needs_sudo": false,-  "files": [-    "package.json",-    "install.sh",-    "uninstall.sh",-    "bin/adom-tts",-    "skills/**",-    "completions/**"-  ],-  "org": "adom",-  "author": {-    "name": "John Lauer",-    "email": "[email protected]"   } }\ No newline at end of file
src/play.rs+11−1
@@ -1799,7 +1799,17 @@ fn handle_player_request(request: tiny_http::Request, method: &Method, route: &s         // can't turn a fully-heard clip into a false "partial"/"no-playback".         (Method::Get, "/poll" | "poll") => {             shared.last_poll_ms.store(now_ms(), Ordering::SeqCst);-            if id_matches(query, shared) && qnum(query, "id").map(|n| n as u64).unwrap_or(0) != 0 {+            // TELEMETRY MUST BE VOUCHED FOR BY THE PAGE. `loaded=1` means the+            // <audio> element actually holds the clip named by `id`; while a new+            // clip is still downloading the page sends loaded=0 and zeroed+            // numbers. Without this, the moments after a clip swap carried the+            // PREVIOUS clip's `ended`/position under the NEW clip's id, so the+            // new clip was marked done on arrival and the drainer advanced —+            // the human heard the second clip cut off seconds in while its+            // sender was told it played fine. (Absent param = a page served by+            // an older drainer; trust it as before rather than going deaf.)+            let vouched = qnum(query, "loaded").map(|x| x >= 1.0).unwrap_or(true);+            if vouched && id_matches(query, shared) && qnum(query, "id").map(|n| n as u64).unwrap_or(0) != 0 {                 if let Some(t) = qnum(query, "t") {                     let ms = (t * 1000.0) as u64;                     if ms > 0 {
src/player.html+25−5
@@ -361,7 +361,9 @@   let lastErr = "", seeking = false;    // ---- current clip state -----  let curClipId = 0;       // id of the clip <audio> is currently bound to+  let curClipId = 0;       // id of the clip the page INTENDS to play (set on arrival)+  let loadedClipId = 0;    // id whose audio the <audio> element ACTUALLY holds.+                           // Telemetry is only valid when these agree — see applyClip.   let wantPlay = false;    // we just swapped src and intend to auto-play it   let metaBase = "";       // clip meta line before we append duration @@ -502,6 +504,17 @@   })();   function applyClip(c){     curClipId = c.id;+    // TELEMETRY MUST NEVER DESCRIBE THE PREVIOUS CLIP. `curClipId` moves the+    // instant a new clip arrives, but the <audio> element keeps the OLD clip's+    // `ended`/`currentTime` until the new blob finishes downloading. Polling in+    // that window reported the NEW id with the OLD state (done=1, t=83.1), so+    // the drainer marked the new clip finished on arrival and advanced — the+    // human heard clip two get cut off ~3s in while its sender was told "ok".+    // Two guards: clear `loadedClipId` so telemetry is withheld until the audio+    // element truly holds THIS clip, and reset the element synchronously so+    // stale ended/currentTime cannot leak through any other path.+    loadedClipId = 0;+    try { a.pause(); a.removeAttribute('src'); a.load(); } catch (e) {}     // Subject = WHO is speaking (AI thread) + WHAT the clip says (--desc).     // The mp3 filename means nothing to a human — it lives in the tooltip only.     subjectName.textContent = c.label || c.title || 'audio clip';@@ -534,6 +547,7 @@         ev('blobready', '&bytes=' + b.size);         a.src = blobUrl;         try { a.load(); } catch(e) {}+        loadedClipId = id;   // NOW the element's state describes THIS clip         tryPlay();       })       .catch(() => {@@ -648,11 +662,17 @@     // Telemetry rides ON the poll: after a hotspot gap the first poll through     // carries the true position/done state, so lost beacons can't produce a     // false "partial/no-playback" verdict for a clip that actually played.+    // `loaded` tells the drainer whether the element's numbers describe the+    // clip named by `id`. While a new clip is still downloading it is 0 and we+    // send zeroed telemetry, so the previous clip's ended/position can never be+    // attributed to the new clip (which used to kill it on arrival).+    const loaded = (loadedClipId !== 0 && loadedClipId === curClipId) ? 1 : 0;     const q = 'poll?id=' + curClipId-      + '&t=' + (a.currentTime || 0).toFixed(1)-      + '&dur=' + (isFinite(a.duration) ? a.duration.toFixed(1) : '0')-      + '&done=' + (a.ended ? 1 : 0)-      + '&paused=' + ((curClipId && a.paused && !a.ended) ? 1 : 0);+      + '&loaded=' + loaded+      + '&t=' + (loaded ? (a.currentTime || 0).toFixed(1) : '0')+      + '&dur=' + (loaded && isFinite(a.duration) ? a.duration.toFixed(1) : '0')+      + '&done=' + ((loaded && a.ended) ? 1 : 0)+      + '&paused=' + ((loaded && curClipId && a.paused && !a.ended) ? 1 : 0);     fetch(q, { cache: 'no-store' }).then(r => r.json()).then(j => {       lastPing = Date.now();       if (!j) return;
tools/ralph-test.sh+52−6
@@ -49,22 +49,36 @@ port,mode=sys.argv[1],sys.argv[2] base=f"http://127.0.0.1:{port}" def get(p):     with urllib.request.urlopen(base+p,timeout=3) as r: return r.read()-cur=0; t=0.0; dur=12.0; started=time.time()-while time.time()-started < 40:-    q=f"/poll?id={cur}&t={t:.1f}&dur={dur}&done=0&paused=0"-    if mode=="pause-mid" and t>=3: q=f"/poll?id={cur}&t={t:.1f}&dur={dur}&done=0&paused=1"+cur=0; t=0.0; dur=12.0; clipno=0; started=time.time()+while time.time()-started < 150:+    q=f"/poll?id={cur}&loaded=1&t={t:.1f}&dur={dur}&done=0&paused=0"+    if mode=="pause-mid" and t>=3: q=f"/poll?id={cur}&loaded=1&t={t:.1f}&dur={dur}&done=0&paused=1"     try: j=json.loads(get(q))     except Exception: time.sleep(.4); continue     if j.get("id") and j["id"]!=cur:+        prev_t=t         cur=j["id"]; t=0.0+        clipno+=1+        # duration derived from the clip id, so CONSECUTIVE clips always differ:+        # then 'B reports A's reached' can only mean inheritance, never coincidence+        dur = 12.0 + (cur % 5) * 2.0+        if mode=="stale-done":+            # THE REGRESSION: a real page sets curClipId synchronously but the+            # <audio> element still holds the previous clip while the new blob+            # downloads. Replay that window: new id, previous clip's ended+pos.+            # A correct drainer must ignore this (page sends loaded=0).+            for _ in range(3):+                try: get(f"/poll?id={cur}&loaded=0&t={prev_t:.1f}&dur={dur}&done=1&paused=0")+                except Exception: pass+                time.sleep(.4)         try: get(f"/audio?id={cur}")         except Exception: pass-    if cur and mode in ("play","pause-mid"):+    if cur and mode in ("play","pause-mid","stale-done"):         if mode=="pause-mid" and t>=3:             time.sleep(.5); continue    # hold paused forever (pause is sacred)         t+=1.5         if t>=dur:-            get(f"/poll?id={cur}&t={dur}&dur={dur}&done=1&paused=0")+            get(f"/poll?id={cur}&loaded=1&t={dur}&dur={dur}&done=1&paused=0")             print(f"page: clip {cur} done"); cur=0; t=0.0     time.sleep(.5) PY@@ -185,6 +199,38 @@ say "T9 port stability across drainer death" NEWPORT=$(port) [ "$NEWPORT" = "$LIVEPORT" ] && ok "port $LIVEPORT reused after kill" || bad "port changed $LIVEPORT → $NEWPORT" +say "T10 second clip must NOT be killed by the previous clip's telemetry"+# THE FIELD REPORT: two AI threads send clips back to back; the moment clip two+# arrives, clip one's stale ended/position gets attributed to it, so it is+# marked done on arrival and cut off seconds in (falsely reported "ok").+mkmp3 $T/t10a.mp3 seed-t10a 4000+mkmp3 $T/t10b.mp3 seed-t10b 4000+rig play $T/t10a.mp3 >/dev/null 2>&1+rig play $T/t10b.mp3 >/dev/null 2>&1+fakepage $(port) stale-done >/dev/null 2>&1 & FP=$!+for i in $(seq 1 60); do ev clip_end | grep -q '"t10b.mp3"' && break; sleep 1; done+kill $FP 2>/dev/null+# assert clip B lived longer than a swap-window blip (>4s wall) and did not+# inherit clip A's reached value+python3 -c "+import json,sys+ev=[json.loads(l) for l in open('$T/.adom/tts/events.jsonl')]+st={ }; res={}+for v in ev:+    if v.get('kind')=='clip_start': st[v.get('clip')]=v['ts_ms']+    if v.get('kind')=='clip_end' and v.get('clip') in st:+        res[v['clip']]=((v['ts_ms']-st[v['clip']])/1000.0, v.get('reached_s',0), v.get('verdict'))+b=res.get('t10b.mp3')+a=res.get('t10a.mp3')+if not b: print('NOSTART'); sys.exit(1)+wall,reached,verdict=b+if wall < 4: print('KILLED wall=%.1fs reached=%s verdict=%s' % (wall,reached,verdict)); sys.exit(1)+if a and abs(reached-a[1])<0.01 and reached>0: print('INHERITED reached=%s from clip A' % reached); sys.exit(1)+print('OK wall=%.1fs reached=%s verdict=%s' % (wall,reached,verdict))+" > $T/t10.out 2>&1+if grep -q '^OK' $T/t10.out; then ok "second clip played through ($(cat $T/t10.out))"+else bad "second clip cut off by stale telemetry: $(cat $T/t10.out)"; fi+ # teardown DP=$(python3 -c "print(open('$T/.adom/tts/drainer.lock').read().split()[0])" 2>/dev/null) [ -n "${DP:-}" ] && kill -9 $DP 2>/dev/null