diff --git a/.abcd/work/DECISIONS.md b/.abcd/work/DECISIONS.md index 5d16153..bdb1c3a 100644 --- a/.abcd/work/DECISIONS.md +++ b/.abcd/work/DECISIONS.md @@ -850,3 +850,37 @@ Architecture-shaping decisions graduate to an ADR under new regression test. Both reviewers' verdicts were BLOCK, so per the loop's merge gate the PR (#48) stays open for the human rather than auto-merging, even with the fix pushed and CI green. +- 2026-08-07 — Bug-hunt round 33: one confirmed substantive defect and four + confirmed nitpicks. `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. + Nitpicks: `AGENTS.md`/`CLAUDE.md` (a symlink to it) claimed `go test + ./...` as a CI gate distinct from `go test -race ./...`, but CI and + `release.yml` run only the race-enabled line; `session-directory.md`'s + `words` row omitted that empty/whitespace/invisible-only text is also + dropped (re-examined for present-day accuracy independent of origin — + round 31 split-discarded a similarly framed finding on whether round 30 + introduced fresh staleness, a different question, and this round's two + refuters both confirmed the row itself is incomplete regardless); 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; and 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` — restored the opening words so they + agree again. 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 and re-marshals, + so `WriteJSONL`'s encoder choice never reaches it); 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/AGENTS.md b/AGENTS.md index 45c0f83..c93eaba 100644 --- a/AGENTS.md +++ b/AGENTS.md @@ -70,7 +70,7 @@ Run from the repo root. Requires Go (version per `go.mod`). go build -o testimony ./cmd/testimony # build the CLI gofmt -l . # format gate: any output needs gofmt -w go vet ./... # static checks -go test ./... # unit tests +go test ./... # unit tests (local; CI runs only the race-enabled line below) go test -race ./... # race-enabled go test -run TestEventsNearWindow ./internal/timeline/ # a single test ./testimony merge -session examples/sample-session # pipeline smoke: @@ -78,9 +78,10 @@ go test -run TestEventsNearWindow ./internal/timeline/ # a single test sh -n install.sh && bash -n install.sh # installer syntax ``` -CI (`.github/workflows/ci.yml`) runs every gate above (the single-test example -line is illustrative, not a gate) on every push and pull request, plus checks -with no local command above: installer flag-handling +CI (`.github/workflows/ci.yml`) runs every gate above except the plain +`go test ./...` line, which the race-enabled run subsumes (both lines run the +same tests; the single-test example line is illustrative, not a gate) on +every push and pull request, plus checks with no local command above: installer flag-handling tests (`--help`/`--dir`/`--version`/`--bogus`), a compile-only cross-check for the other release platforms, a version-stamp ldflags check, a full-history `gitleaks` secret scan, and a `zizmor` workflow-security audit. diff --git a/docs/reference/session-directory.md b/docs/reference/session-directory.md index dd612aa..1fc5e5c 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 (`ReadEntries` refuses 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.0},{"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..3f936ca 100644 --- a/internal/analyze/validate.go +++ b/internal/analyze/validate.go @@ -1,7 +1,6 @@ package analyze import ( - "errors" "fmt" "strings" @@ -243,17 +242,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..e1d738e 100644 --- a/internal/record/record_test.go +++ b/internal/record/record_test.go @@ -592,6 +592,97 @@ 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() + if !strings.Contains(out, "capture stopped unexpectedly") && !strings.Contains(out, "capture failed to start") { + t.Fatalf("the operator was never told the recorder exited on its own: %q", out) + } + 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