diff --git a/.abcd/work/DECISIONS.md b/.abcd/work/DECISIONS.md index 1525c0a..76bc118 100644 --- a/.abcd/work/DECISIONS.md +++ b/.abcd/work/DECISIONS.md @@ -886,3 +886,61 @@ Architecture-shaping decisions graduate to an ADR under discarded); a dangling-link nitpick in `AGENTS.md`'s abcd-managed fence (split verdict on whether `.abcd/rules.json` gives an indirect fix path; discarded as out of scope). +- 2026-08-07 — Bug-hunt round 34: one confirmed substantive defect and four + confirmed nitpicks. This round's hunt ran concurrently with another + session's round 33 (above, PR #49) and picked the same next number before + either merged; renumbered to 34 on rebase, and its independent AGENTS.md + finding (below) dropped as a duplicate of round 33's own fix once that + overlap became visible. `record`'s `<-ctx.Done()` shutdown branch sampled + no early-exit state before `stopAll`, unlike the sibling `anyExit` branch + (round 32's fix): a recorder whose `done` channel closed in the + sub-millisecond window before the interrupt reached the select fell + through to `finaliseOutputs` unconditionally, either misdiagnosed via + `classifyMissingOutput`'s "stayed blocked on the permission prompt" + narrative when it captured nothing, or silently exited 0 with a + truncated recording presented as a clean session when it left partial + data. Fixed by factoring the pre-`stopAll` sampling both branches need + into a shared `sampleEarlyExits` helper, with two new regression tests; + `CHANGELOG.md` gains the matching `[Unreleased]` entry, the sibling of + round 32's for the recorder-exit path. A post-hoc adversarial review of + the round's own PR caught that one of the two new tests made both + `select` cases ready by construction, so it asserted on `opts.Log` alone + when Go's non-deterministic case choice can route the diagnosis to the + returned error instead — fixed to check both. The same review caught that + removing `analyze.Validate` (below) orphaned its sole caller-side helper, + `atPositions`; removed that too, along with its stale comment naming + `Validate`. Nitpicks: `session-directory.md`'s `words` row omitted that + empty/whitespace/invisible-only text is also dropped — round 31 + split-discarded the identical finding (one refuter called the drop rule + pre-existing with no staleness fresh from round 30, the other found it + survives on the row's own precedent of documenting the equivalent + `text`-row cause); this round's two independent refuters, examining it + fresh, both reached the surviving refuter's conclusion. The same page's + `timeline.jsonl` table had no `Required` column and did not state `t`'s + (or a speech payload's `t1`'s) ±1e9-second bound — corrected using + `report`/`analyze`'s user-facing names rather than the internal + `ReadEntries` that first enforces it, matching the rest of the page. Its + `utt-003` example trimmed the utterance text to start mid-sentence while + keeping the untrimmed fixture's `t0` and word times, leaving the first + shown word 1.6s after its own `t0`: round 30 refuted a claim about this + same example's abbreviated text against the fuller fixture sentence (the + page's examples are established illustrative reductions, and no + `findings.jsonl` quote cites `utt-003`), but that reasoning doesn't reach + this narrower defect — the abbreviation itself is fine, the self- + contradiction between the shown `t0` and the shown first word's time is + the actual gap — so restored the opening words to agree with `t0` again, + matching real `merge` output's integer formatting (`"t":16`, not + `"t":16.0`) rather than transcript.jsonl's rounded literal. Also removed + `analyze.Validate`, an exported function with zero callers anywhere in + the module. Refuted: a claimed round-32 regression desynchronising + `timeline.jsonl` from `analyze`'s emitted request via HTML-escaping (one + refuter proved `EmitRequest`'s output byte-identical before and after + round 32 — it re-decodes the timeline and re-marshals, so `WriteJSONL`'s + encoder choice, round 32's actual change, never reaches the request an + operator or model is shown, even though round 32 did newly desynchronise + the two artefacts' own on-disk/in-source encoding on this axis); an + inverted transcription segment span, a CI cross-compile comment's + CGO-flag mismatch, `cli.md`'s "ingest reads timeline.jsonl only" + phrasing, and the `manifest.json` example's field trimming (all four on + split or unanimous refuter verdicts, with no misleading or behavioural + consequence found). diff --git a/CHANGELOG.md b/CHANGELOG.md index 30351cd..2a684fb 100644 --- a/CHANGELOG.md +++ b/CHANGELOG.md @@ -540,6 +540,15 @@ Capture integrity: through `classifyMissingOutput`'s "stayed blocked on the permission prompt" narrative — disproved by its own exit — with its real exit status never surfaced. +- **Behaviour:** `record`'s Ctrl+C shutdown path now diagnoses a recorder + that exited on its own moments before the interrupt arrived, the sibling + case to the one above for the interrupt path rather than the recorder-exit + path: it used to fall through to the same missing-output sweep as a + normally-stopped recorder, either printing `classifyMissingOutput`'s + "stayed blocked on the permission prompt" narrative for a recorder that + had already exited and captured nothing, or — for a recorder that left a + partial artefact — exiting 0 with no word that capture had ended early, + presenting a truncated recording as a clean session. ## [0.4.0] - 2026-07-24 diff --git a/docs/reference/session-directory.md b/docs/reference/session-directory.md index dd612aa..875a96e 100644 --- a/docs/reference/session-directory.md +++ b/docs/reference/session-directory.md @@ -70,10 +70,10 @@ One utterance per line. Times are session-relative seconds (audio time plus the | `t1` | number | yes | utterance end, session-relative seconds; defaults to `t0` when absent or earlier than `t0`, and otherwise must not exceed 1e9 seconds in magnitude (`merge` refuses) | | `speaker` | string | no | speaker label; `"P1"` when the engine supplies no diarisation | | `text` | string | yes | utterance text, whitespace-trimmed (segments that are empty, whitespace-only, or invisible-only Unicode are dropped) | -| `words` | array | no | word-level alignment (WhisperX only); each element is `{"w": , "t": }` — words the aligner could not time, or whose time is implausible (non-finite, or beyond ±1e9 seconds) either as engine-reported (before the session offset is added) or after adding the offset, are omitted | +| `words` | array | no | word-level alignment (WhisperX only); each element is `{"w": , "t": }` — a word is omitted if the aligner could not time it, if its time is implausible (non-finite, or beyond ±1e9 seconds) either as engine-reported (before the session offset is added) or after adding the offset, or if its text is empty, whitespace-only, or invisible-only Unicode | ```json -{"id":"utt-003","t0":16.0,"t1":21.0,"speaker":"P1","text":"Now I expect this save button to confirm somehow.","words":[{"w":"Now","t":17.6},{"w":"I","t":17.92}]} +{"id":"utt-003","t0":16.0,"t1":21.0,"speaker":"P1","text":"Typing feels fine. Now I expect this save button to confirm somehow.","words":[{"w":"Typing","t":16.0},{"w":"feels","t":16.42}]} ``` ## `audio.offset.json` @@ -93,19 +93,19 @@ One raw [rrweb](https://github.com/rrweb-io/rrweb) event per line, exactly as em The merged record — one entry per line, speech and interface events on the shared session-relative clock, stably sorted by `t`. This is the single artefact the report (and any later analysis) consumes. -| Field | Type | Meaning | -|---|---|---| -| `t` | number | entry time, session-relative seconds | -| `src` | string | `"speech"` or `"event"` (a closed set: `report` and `analyze` refuse any other value); entry ids must be unique for `analyze`, which resolves cited evidence by id | -| `id` | string | `utt-NNN` (from the transcript) or `ev-NNN` (assigned at merge, in input order) | -| `payload` | object | source-dependent, see below | +| Field | Type | Required | Meaning | +|---|---|---|---| +| `t` | number | yes | entry time, session-relative seconds; must not exceed 1e9 seconds in magnitude (`report` and `analyze` refuse otherwise; `merge` never writes past this bound) | +| `src` | string | yes | `"speech"` or `"event"` (a closed set: `report` and `analyze` refuse any other value); entry ids must be unique for `analyze`, which resolves cited evidence by id | +| `id` | string | yes | `utt-NNN` (from the transcript) or `ev-NNN` (assigned at merge, in input order) | +| `payload` | object | yes | source-dependent, see below | -Speech payload (`src: "speech"`; `t` is the utterance's `t0`): `t1`, `speaker`, `text`, and `words` when present in the transcript. +Speech payload (`src: "speech"`; `t` is the utterance's `t0`): `t1` (also bounded to ±1e9 seconds in magnitude), `speaker`, `text`, and `words` when present in the transcript. Event payload (`src: "event"`): `kind`, plus `selector`, `text`, `value`, and `route` — each only when non-empty in the interaction. ```json -{"t":16,"src":"speech","id":"utt-003","payload":{"speaker":"P1","t1":21,"text":"Now I expect this save button to confirm somehow.","words":[{"w":"Now","t":17.6},{"w":"I","t":17.92}]}} +{"t":16,"src":"speech","id":"utt-003","payload":{"speaker":"P1","t1":21,"text":"Typing feels fine. Now I expect this save button to confirm somehow.","words":[{"w":"Typing","t":16},{"w":"feels","t":16.42}]}} {"t":19.2,"src":"event","id":"ev-003","payload":{"kind":"click","route":"#general","selector":"[data-testid=save-btn]","text":"Save"}} ``` diff --git a/internal/analyze/validate.go b/internal/analyze/validate.go index 1d01bd0..5065a04 100644 --- a/internal/analyze/validate.go +++ b/internal/analyze/validate.go @@ -1,7 +1,6 @@ package analyze import ( - "errors" "fmt" "strings" @@ -113,17 +112,6 @@ type positioned struct { at int } -// atPositions pairs each finding with its own ordinal, for callers (Validate) -// whose findings did not come from a partially-decoded answer and so are -// already in answer order. -func atPositions(findings []Finding) []positioned { - out := make([]positioned, len(findings)) - for i, f := range findings { - out[i] = positioned{finding: f, at: i + 1} - } - return out -} - // findingLabel names a finding in an error message: its own id when that id is // well-formed, and otherwise its position in the answer, which is the only // handle the operator has on a finding whose id is unusable. Both the schema @@ -243,17 +231,6 @@ func validate(findings []positioned, idx timelineIndex) []error { return errs } -// Validate reports all schema violations across the findings as one joined -// error (nil when clean). The findings are validated against the merged -// timeline in dir. -func Validate(dir string, findings []Finding) error { - entries, err := loadTimeline(dir) - if err != nil { - return err - } - return errors.Join(validate(atPositions(findings), indexTimeline(entries))...) -} - func containsAny(texts []string, sub string) bool { for _, t := range texts { if strings.Contains(t, sub) { diff --git a/internal/record/record.go b/internal/record/record.go index 82030e4..17d7bba 100644 --- a/internal/record/record.go +++ b/internal/record/record.go @@ -226,9 +226,20 @@ func Run(opts Options) error { return nil } + var ctxEarly, ctxAtStartupOf map[*liveChild]bool select { case <-ctx.Done(): fmt.Fprintln(opts.Log, "\nstopping — finalising capture files…") + // A recorder may have exited on its own in the instant before the + // signal arrived: sample that now, before stopAll's SIGINT reaches the + // survivors and makes a live recorder's own clean shutdown + // indistinguishable from a self-exit moments earlier — the same + // ordering constraint the other case observes below. Without this, an + // already-dead recorder fell through to finaliseOutputs exactly like a + // normally-stopped one: misdiagnosed as still blocked on its + // permission prompt when it produced nothing, or silently accepted as + // a clean session when it left a partial artefact. + ctxEarly, ctxAtStartupOf = sampleEarlyExits(children) case dead := <-anyExit(children): // A recorder exited before we asked it to stop. Within the startup // window this is most often a TCC denial; a later exit is an unexpected @@ -242,31 +253,18 @@ func Run(opts Options) error { // genuine TCC denial that failed in the first second was reported as an // unexpected mid-session stop and the operator was sent looking for a // device fault instead of the permission they had never granted. - atStartup := time.Since(dead.started) < startupWindow - // Other children may have exited on their own at the same moment as - // dead: anyExit's channel is buffered to len(children), so a second + // + // Every child's exit state is sampled via sampleEarlyExits, not just + // dead's: anyExit's channel is buffered to len(children), so a second // self-exit sent before this select fired is already sitting there, // unread, the instant this case runs. Both the exit itself and its - // start-up-window classification are sampled now, before stopAll's - // SIGINT reaches them: after that, a live recorder's own clean + // start-up-window classification must be sampled now, before stopAll's + // SIGINT reaches the survivors: after that, a live recorder's own clean // shutdown becomes indistinguishable from a dead one's self-exit, and - // stopAll's own wait — up to stopGrace per remaining child, which - // alone equals startupWindow — would charge the shutdown against a - // second early exit's classification exactly as it would have - // against dead's, the mistake atStartup above exists to avoid. - early := map[*liveChild]bool{dead: true} - atStartupOf := map[*liveChild]bool{dead: atStartup} - for _, c := range children { - if c == dead { - continue - } - select { - case <-c.done: - early[c] = true - atStartupOf[c] = time.Since(c.started) < startupWindow - default: - } - } + // stopAll's own wait — up to stopGrace per remaining child, which alone + // equals startupWindow — would charge the shutdown against a second + // early exit's classification exactly as it would have against dead's. + early, atStartupOf := sampleEarlyExits(children) stopAll(children) stopDemo(srv) // An early exit is reported the same way as a recorder that produced @@ -317,7 +315,7 @@ func Run(opts Options) error { fmt.Fprintf(opts.Log, "\n%s\n", classifyRecorderExit(c.stream, c.err, c.stderr.tail(), atStartupOf[c])) } fmt.Fprintf(opts.Log, "\n%s\n", nextCommands(dir, audioReady, capturePossible)) - return errors.New(classifyRecorderExit(dead.stream, dead.err, dead.stderr.tail(), atStartup)) + return errors.New(classifyRecorderExit(dead.stream, dead.err, dead.stderr.tail(), atStartupOf[dead])) } stopAll(children) @@ -327,7 +325,36 @@ func Run(opts Options) error { // A recorder blocked on its TCC prompt for the whole session finalises no // container on SIGINT — audio.wav (or screen.mp4) is absent or empty — and // this is the only place that catches it, since it never exited on its own. - audioReady, problems := finaliseOutputs(dir, children) + // + // A recorder sampled as an early exit above (ctxEarly) is excluded here and + // diagnosed through classifyRecorderExit instead, the same treatment the + // anyExit case gives a self-exited recorder: classifyMissingOutput's + // stayed-blocked-on-the-prompt narrative would be disproved by the very + // exit that brought it here, and a partial artefact from an early exit + // would otherwise pass finaliseOutputs's size check and be presented as a + // clean stop rather than a capture that ended early. + others := children + if len(ctxEarly) > 0 { + others = make([]*liveChild, 0, len(children)) + for _, c := range children { + if !ctxEarly[c] { + others = append(others, c) + } + } + } + audioReady, problems := finaliseOutputs(dir, others) + for c := range ctxEarly { + if c.stream == streamMicrophone { + if fi, err := os.Stat(expectedOutput(dir, c.stream)); err == nil && fi.Size() > 0 { + audioReady = true + } + } + } + for _, c := range children { + if ctxEarly[c] { + problems = append(problems, classifyRecorderExit(c.stream, c.err, c.stderr.tail(), ctxAtStartupOf[c])) + } + } for _, p := range problems { fmt.Fprintf(opts.Log, "\n%s\n", p) } @@ -494,6 +521,29 @@ func anyExit(children []*liveChild) <-chan *liveChild { return ch } +// sampleEarlyExits reports which children have already exited — their done +// channel already closed — at the moment this is called, and whether each +// such exit fell inside startupWindow. It must run before stopAll signals the +// survivors: once a live recorder receives SIGINT, its own clean shutdown +// becomes indistinguishable from a self-exit that happened moments earlier, +// so this is the last point at which the two can still be told apart. Both of +// Run's select cases call this before stopAll for that reason — a recorder +// that exits on its own gets the same diagnosis regardless of which case +// happened to observe the exit. +func sampleEarlyExits(children []*liveChild) (early map[*liveChild]bool, atStartupOf map[*liveChild]bool) { + early = map[*liveChild]bool{} + atStartupOf = map[*liveChild]bool{} + for _, c := range children { + select { + case <-c.done: + early[c] = true + atStartupOf[c] = time.Since(c.started) < startupWindow + default: + } + } + return early, atStartupOf +} + // onlyManifest reports whether dir contains nothing but manifest.json — i.e. // no recorder ever wrote output to it. It fails safe: any error reading the // directory (permissions, a concurrent removal) is treated as "not empty" so diff --git a/internal/record/record_test.go b/internal/record/record_test.go index 43d6c10..38fab09 100644 --- a/internal/record/record_test.go +++ b/internal/record/record_test.go @@ -592,6 +592,104 @@ func TestEarlyRecorderExitDoesNotDoubleDiagnoseWithTwoRecorders(t *testing.T) { } } +// TestCtrlCDiagnosesRecorderThatSelfExitedWithNoOutput is the ctx.Done() +// sibling of TestEarlyRecorderExitDoesNotDoubleDiagnose: a recorder that +// exits on its own an instant before the interrupt signal arrives must get +// the same classifyRecorderExit diagnosis a self-exit gets when anyExit's +// select observes it directly, not classifyMissingOutput's "stayed blocked +// on the permission prompt" narrative — disproved by the very exit that left +// no output — and Run must still exit non-zero. Pre-fix, the ctx.Done() +// branch sampled no early-exit state at all, so a recorder already reaped by +// the time the interrupt arrived fell straight through to finaliseOutputs and +// was misdiagnosed exactly as if it had stayed blocked on the prompt for the +// whole session. +func TestCtrlCDiagnosesRecorderThatSelfExitedWithNoOutput(t *testing.T) { + origNotify, origStart := notifyContext, startRecordersFn + t.Cleanup(func() { notifyContext, startRecordersFn = origNotify, origStart }) + + var cancel context.CancelFunc + notifyContext = func() (context.Context, context.CancelFunc) { + ctx, c := context.WithCancel(context.Background()) + cancel = c + return ctx, c + } + startRecordersFn = func(dir string, streams []string, _ io.Writer) ([]*liveChild, error) { + // The recorder dies on its own having captured nothing — a TCC denial — + // and is fully reaped before the interrupt arrives. + mic := newLiveChild(streamMicrophone, newFakeProc(syscall.SIGINT), &lockedBuffer{}) + _ = mic.p.Signal(syscall.SIGINT) + <-mic.done + // The interrupt fires only once the recorder has already exited, so + // Run's select sees both cases ready — the scenario under test. + cancel() + return []*liveChild{mic}, nil + } + + var log bytes.Buffer + err := Run(Options{Out: t.TempDir(), GOOS: "darwin", Log: &log}) + if err == nil { + t.Fatal("a recorder that self-exited before the interrupt must still make Run exit non-zero") + } + out := log.String() + if strings.Contains(out, "stayed blocked on the permission prompt") { + t.Fatalf("the self-exited recorder was diagnosed through classifyMissingOutput, contradicting its own exit: %q", out) + } + if !strings.Contains(out, "Next:") { + t.Fatalf("the next-command block must still print: %q", out) + } +} + +// TestCtrlCDiagnosesRecorderThatSelfExitedWithPartialOutput is the ctx.Done() +// sibling of TestEarlyRecorderExitStillFinalisesAndPrintsNext: a recorder that +// self-exits leaving a usable partial audio.wav (a mid-session device loss) +// an instant before the interrupt arrives must still make Run exit non-zero +// and print the recorder's own diagnosis, offering the partial audio for +// transcription. Pre-fix, the ctx.Done() branch's finaliseOutputs saw the +// file, set audioReady, appended no problem, and Run returned nil — a +// truncated recording presented as a clean session with no word that capture +// ended early. +func TestCtrlCDiagnosesRecorderThatSelfExitedWithPartialOutput(t *testing.T) { + origNotify, origStart := notifyContext, startRecordersFn + t.Cleanup(func() { notifyContext, startRecordersFn = origNotify, origStart }) + + var cancel context.CancelFunc + notifyContext = func() (context.Context, context.CancelFunc) { + ctx, c := context.WithCancel(context.Background()) + cancel = c + return ctx, c + } + startRecordersFn = func(dir string, streams []string, _ io.Writer) ([]*liveChild, error) { + if err := os.WriteFile(filepath.Join(dir, session.AudioFile), []byte("RIFF...."), 0o644); err != nil { + t.Fatal(err) + } + mic := newLiveChild(streamMicrophone, newFakeProc(syscall.SIGINT), &lockedBuffer{}) + _ = mic.p.Signal(syscall.SIGINT) + <-mic.done + cancel() + return []*liveChild{mic}, nil + } + + var log bytes.Buffer + err := Run(Options{Out: t.TempDir(), GOOS: "darwin", Log: &log}) + if err == nil { + t.Fatal("a recorder that self-exited mid-session before the interrupt must still make Run exit non-zero, not present a truncated recording as a clean session") + } + out := log.String() + // Cancelling inside startRecordersFn, after the child is already reaped, + // makes both select cases ready at once: Go's select picks between them + // uniformly at random, not deterministically. When anyExit wins, dead's + // diagnosis is returned as the error rather than written to opts.Log (the + // ctxEarly loop that would print it never runs), so the diagnosis must be + // looked for in whichever of the two actually carries it. + combined := out + "\n" + err.Error() + if !strings.Contains(combined, "capture stopped unexpectedly") && !strings.Contains(combined, "capture failed to start") { + t.Fatalf("the operator was never told the recorder exited on its own: log=%q err=%q", out, err) + } + if !strings.Contains(out, "testimony transcribe") { + t.Fatalf("the partial audio.wav was not offered for transcription: %q", out) + } +} + // TestEarlyRecorderExitTwoRecordersClassifiesStartupExitDespiteSlowDemoStop is // the two-recorder sibling of TestRunClassifiesStartupExitDespiteSlowStop: // dead's own start-up classification is sampled before stopAll/stopDemo run