From 0b70dd1659a4c8c6625b089fdd6bd956395df676 Mon Sep 17 00:00:00 2001 From: PJ Date: Wed, 12 Aug 2026 22:57:06 +0530 Subject: [PATCH] fix(runner): a guard-skipped step is no longer a silent log line The strict echo-skip left only a logger.Warn, so a step the guard discarded was indistinguishable in the trace from a picker that legitimately declined. Any yield or actions-per-hour figure computed from model traces mixed the two. Every path that ends a step without a model-chosen action now records its own outcome. Claude-Session: https://claude.ai/code/session_01A5KmftdEJ49A9z5mF5ESrX --- internal/runner/llm_source.go | 151 ++++++++++++-- internal/runner/llm_source_test.go | 324 ++++++++++++++++++++++++++++- internal/runner/source.go | 15 +- 3 files changed, 457 insertions(+), 33 deletions(-) diff --git a/internal/runner/llm_source.go b/internal/runner/llm_source.go index 368722b..6f9f306 100644 --- a/internal/runner/llm_source.go +++ b/internal/runner/llm_source.go @@ -13,6 +13,7 @@ import ( "log/slog" "regexp" "strings" + "time" "github.com/priyanshujain/sanderling/internal/llmclient" "github.com/priyanshujain/sanderling/internal/trace" @@ -51,6 +52,9 @@ type llmSource struct { instructions string logger *slog.Logger history *actionHistory + // recorder persists one record per step: what was sent, what came back, and + // how the step ended. Nil only in unit tests that never select. + recorder llmCallRecorder // lastSource/lastReasoning describe the most recent NextAction so the runner // can stamp the trace. lastSource is "llm" only when the LLM (not setup) @@ -71,10 +75,18 @@ type llmSelection struct { chosenAction string } +// llmCallRecorder persists one selection record per step. *trace.Writer +// implements it. +type llmCallRecorder interface { + WriteLLMCall(call trace.LLMCall) error +} + // NextAction returns the step's action. Setup precedence is preserved by // running the JS path first (the llm marker is inert there, so a null result -// means setup yielded nothing); the LLM selection then takes over. -func (s *llmSource) NextAction(ctx context.Context) (verifier.Action, error) { +// means setup yielded nothing); the LLM selection then takes over. Every way a +// step can end lands one record keyed to stepIndex, so a step the guards threw +// away is never confused with one the picker declined. +func (s *llmSource) NextAction(ctx context.Context, stepIndex int) (verifier.Action, error) { s.lastSource = "" s.lastReasoning = "" s.lastChoice = 0 @@ -85,17 +97,20 @@ func (s *llmSource) NextAction(ctx context.Context) (verifier.Action, error) { // setup (e.g. login) first but never the weighted picker. action, err := s.verifier.SetupAction() if err == nil { + s.record(stepIndex, trace.LLMCall{Outcome: trace.LLMOutcomeSetupAction}) s.history.add(describeAction(action)) return action, nil } if !errors.Is(err, verifier.ErrNoAction) { + s.record(stepIndex, trace.LLMCall{Outcome: trace.LLMOutcomeSetupFailed, Error: err.Error()}) return verifier.Action{}, err } - selection, ok := s.selectViaLLM(ctx) - if !ok { - // Any failure (HTTP error, unusable output, invalid choice, echo - // mismatch) skips the step; the next step re-observes and tries again. + selection, call := s.selectViaLLM(ctx) + s.record(stepIndex, call) + if call.Outcome != trace.LLMOutcomeSelected { + // Every other outcome skips the step; the next step re-observes and + // tries again. The record says which one it was. return verifier.Action{}, verifier.ErrNoAction } s.lastSource = "llm" @@ -107,33 +122,57 @@ func (s *llmSource) NextAction(ctx context.Context) (verifier.Action, error) { } // selectViaLLM runs one multimodal call and maps the chosen number to an action. -// It returns ok=false on any error/empty/invalid output, logging the cause; the -// caller turns that into a skipped step. -func (s *llmSource) selectViaLLM(ctx context.Context) (llmSelection, bool) { +// The returned record is complete whichever way the selection ended: its +// Outcome is trace.LLMOutcomeSelected exactly when the returned selection is +// usable. +func (s *llmSource) selectViaLLM(ctx context.Context) (llmSelection, trace.LLMCall) { + call := trace.LLMCall{Timestamp: time.Now(), Model: s.model} candidates := s.verifier.Candidates() if len(candidates) == 0 { - return llmSelection{}, false + call.Outcome = trace.LLMOutcomeNoCandidates + return llmSelection{}, call } + call.Candidates = recordCandidates(candidates) - response, err := s.client.ChatCompletion(ctx, s.buildRequest(candidates)) + request, screenshotReference := s.buildRequest(candidates) + call.Screenshot = screenshotReference + call.SystemPrompt, call.UserPrompt = promptTexts(request) + + requestStart := time.Now() + response, err := s.client.ChatCompletion(ctx, request) + call.LatencyMillis = time.Since(requestStart).Milliseconds() if err != nil { s.logger.Warn("llm action selection failed", "err", err) - return llmSelection{}, false + call.Outcome = trace.LLMOutcomeRequestFailed + call.Error = err.Error() + return llmSelection{}, call } + call.ServedModel = response.Model + call.PromptTokens = response.Usage.PromptTokens + call.CompletionTokens = response.Usage.CompletionTokens + call.TotalTokens = response.Usage.TotalTokens if len(response.Choices) == 0 { s.logger.Warn("llm returned no choices") - return llmSelection{}, false + call.Outcome = trace.LLMOutcomeNoChoices + return llmSelection{}, call } + call.RawResponse = response.Choices[0].Message.Content - output, err := parseChoice(response.Choices[0].Message.Content) + output, err := parseChoice(call.RawResponse) if err != nil { s.logger.Warn("llm output unusable", "err", err) - return llmSelection{}, false + call.Outcome = trace.LLMOutcomeUnparsableResponse + call.Error = err.Error() + return llmSelection{}, call } + call.Choice = output.Choice + call.EchoedAction = output.ChosenAction + call.Reasoning = output.Reasoning // choice is 1-based into the numbered list. if output.Choice < 1 || output.Choice > len(candidates) { s.logger.Warn("llm choice out of range", "choice", output.Choice, "candidates", len(candidates)) - return llmSelection{}, false + call.Outcome = trace.LLMOutcomeChoiceOutOfRange + return llmSelection{}, call } candidate := candidates[output.Choice-1] // Strict skip: the echoed action must match the numbered entry, so a model @@ -143,19 +182,79 @@ func (s *llmSource) selectViaLLM(ctx context.Context) (llmSelection, bool) { if stripWeightSuffix(output.ChosenAction) != candidate.Description { s.logger.Warn("llm chosen_action mismatch; skipping", "choice", output.Choice, "echoed", output.ChosenAction, "candidate", candidate.Description) - return llmSelection{}, false + call.Outcome = trace.LLMOutcomeEchoMismatch + return llmSelection{}, call } action, err := s.actionForCandidate(candidate, output.Text) if err != nil { s.logger.Warn("building action from candidate failed", "choice", output.Choice, "err", err) - return llmSelection{}, false + call.Outcome = trace.LLMOutcomeActionBuildFailed + call.Error = err.Error() + return llmSelection{}, call } + call.Outcome = trace.LLMOutcomeSelected return llmSelection{ action: action, reasoning: output.Reasoning, choice: output.Choice, chosenAction: candidate.Description, - }, true + }, call +} + +// record stamps the step this selection belongs to and appends the record. A +// write failure must not kill the run, but it does mean the step is +// unattributable, so it is logged. +func (s *llmSource) record(stepIndex int, call trace.LLMCall) { + if s.recorder == nil { + return + } + call.Step = stepIndex + if call.Timestamp.IsZero() { + call.Timestamp = time.Now() + } + if err := s.recorder.WriteLLMCall(call); err != nil { + s.logger.Warn("llm call record failed", "step", stepIndex, "err", err) + } +} + +// recordCandidates snapshots the numbered list as the prompt rendered it, so a +// campaign that varies candidate labelling can recover the labels each call saw. +func recordCandidates(candidates []verifier.ActionCandidate) []trace.LLMCandidate { + recorded := make([]trace.LLMCandidate, 0, len(candidates)) + for _, candidate := range candidates { + entry := trace.LLMCandidate{ + Index: candidate.Index, + Kind: string(candidate.Kind), + Description: candidate.Description, + Label: candidate.Label, + } + if candidate.Weighted { + entry.Weight = candidate.Weight + } + recorded = append(recorded, entry) + } + return recorded +} + +// promptTexts reads the text parts back off the built request, so the record is +// what went on the wire rather than a second rendering of the same templates. +func promptTexts(request llmclient.Request) (systemPrompt, userPrompt string) { + for _, message := range request.Messages { + var parts []string + for _, part := range message.Content { + if part.Type == "text" { + parts = append(parts, part.Text) + } + } + text := strings.Join(parts, "\n") + switch message.Role { + case "system": + systemPrompt = text + case "user": + userPrompt = text + } + } + return systemPrompt, userPrompt } // actionForCandidate turns a chosen candidate into the executable action. The @@ -182,14 +281,23 @@ func (s *llmSource) actionForCandidate(candidate verifier.ActionCandidate, text // buildRequest assembles the one-shot multimodal request: a system frame, the // numbered candidate list plus recent-action memory, and the downscaled // screenshot. The strict json_schema response format pins the ranked output. -func (s *llmSource) buildRequest(candidates []verifier.ActionCandidate) llmclient.Request { +// +// The second return is the run-relative path of the screenshot attached, empty +// when none was, so a record can never claim an image the call did not carry. +// It names the step the image was captured at, which is the last observed step +// rather than the current one whenever an observation was skipped. +func (s *llmSource) buildRequest(candidates []verifier.ActionCandidate) (llmclient.Request, string) { userParts := []llmclient.ContentPart{llmclient.TextPart(s.userPrompt(candidates))} + screenshotReference := "" if screenshot := s.verifier.Screenshot(); len(screenshot) > 0 { if dataURL, ok := screenshotDataURL(screenshot, llmMaxImageEdge); ok { userParts = append(userParts, llmclient.ImagePart(dataURL)) + if step := s.verifier.SnapshotStep(); step > 0 { + screenshotReference = trace.ScreenshotReference(step) + } } } - return llmclient.Request{ + request := llmclient.Request{ Model: s.model, Messages: []llmclient.Message{ {Role: "system", Content: []llmclient.ContentPart{llmclient.TextPart(s.systemPrompt())}}, @@ -197,6 +305,7 @@ func (s *llmSource) buildRequest(candidates []verifier.ActionCandidate) llmclien }, ResponseFormat: choiceResponseFormat(len(candidates)), } + return request, screenshotReference } // systemPrompt is the base framing plus any spec-level instructions, appended as diff --git a/internal/runner/llm_source_test.go b/internal/runner/llm_source_test.go index a1e8bb1..c69b942 100644 --- a/internal/runner/llm_source_test.go +++ b/internal/runner/llm_source_test.go @@ -5,21 +5,27 @@ import ( "context" "encoding/json" "errors" + "fmt" "image" "image/png" "io" "log/slog" "net/http" "net/http/httptest" + "os" + "path/filepath" + "regexp" "slices" "strconv" "strings" "testing" + "time" "github.com/priyanshujain/sanderling/internal/driver" mockdriver "github.com/priyanshujain/sanderling/internal/driver/mock" "github.com/priyanshujain/sanderling/internal/hierarchy" "github.com/priyanshujain/sanderling/internal/llmclient" + "github.com/priyanshujain/sanderling/internal/trace" "github.com/priyanshujain/sanderling/internal/verifier" ) @@ -168,6 +174,9 @@ type fakeOpenRouter struct { chosenAction string text string reasoning string + usage llmclient.Usage + servedModel string + delay time.Duration lastRequest map[string]any } @@ -184,8 +193,11 @@ func newFakeOpenRouter(t *testing.T) *fakeOpenRouter { "text": fake.text, }) response, _ := json.Marshal(llmclient.Response{ + Model: fake.servedModel, Choices: []llmclient.Choice{{Message: llmclient.ResponseMessage{Content: string(content)}}}, + Usage: fake.usage, }) + time.Sleep(fake.delay) w.Header().Set("Content-Type", "application/json") _, _ = w.Write(response) })) @@ -193,7 +205,41 @@ func newFakeOpenRouter(t *testing.T) *fakeOpenRouter { return fake } +// fakeCallRecorder keeps the per-step selection records in memory so a test can +// assert on them without opening the run directory. +type fakeCallRecorder struct { + calls []trace.LLMCall +} + +func (r *fakeCallRecorder) WriteLLMCall(call trace.LLMCall) error { + r.calls = append(r.calls, call) + return nil +} + +func recordedCalls(t *testing.T, source *llmSource) []trace.LLMCall { + t.Helper() + recorder, ok := source.recorder.(*fakeCallRecorder) + if !ok { + t.Fatalf("recorder = %T, want *fakeCallRecorder", source.recorder) + } + return recorder.calls +} + +func lastCall(t *testing.T, source *llmSource) trace.LLMCall { + t.Helper() + calls := recordedCalls(t, source) + if len(calls) == 0 { + t.Fatal("no selection record written") + } + return calls[len(calls)-1] +} + func newLLMSource(t *testing.T, fake *fakeOpenRouter) (*llmSource, *verifier.Verifier) { + t.Helper() + return newLLMSourceWithSpec(t, fake, llmFixtureSpec) +} + +func newLLMSourceWithSpec(t *testing.T, fake *fakeOpenRouter, spec string) (*llmSource, *verifier.Verifier) { t.Helper() t.Setenv("OPENROUTER_API_KEY", "test-key") t.Setenv("OPENROUTER_BASE_URL", fake.server.URL) @@ -206,7 +252,7 @@ func newLLMSource(t *testing.T, fake *fakeOpenRouter) (*llmSource, *verifier.Ver if err != nil { t.Fatal(err) } - if err := verifierInstance.Load(bundleSpec(t, llmFixtureSpec)); err != nil { + if err := verifierInstance.Load(bundleSpec(t, spec)); err != nil { t.Fatal(err) } if _, ok := verifierInstance.LLMConfig(); !ok { @@ -219,21 +265,48 @@ func newLLMSource(t *testing.T, fake *fakeOpenRouter) (*llmSource, *verifier.Ver model: "test/model", logger: slog.New(slog.NewTextHandler(io.Discard, nil)), history: newActionHistory(llmHistorySize), + recorder: &fakeCallRecorder{}, } return source, verifierInstance } func pushLLMSnapshot(t *testing.T, v *verifier.Verifier) { + t.Helper() + pushLLMSnapshotAtStep(t, v, 0) +} + +func pushLLMSnapshotAtStep(t *testing.T, v *verifier.Verifier, stepIndex int) { t.Helper() tree, err := hierarchy.Parse(llmTreeJSON) if err != nil { t.Fatal(err) } - if err := v.PushSnapshot(verifier.SnapshotInput{Tree: tree, ScreenshotPNG: tinyPNG(t)}); err != nil { + if err := v.PushSnapshot(verifier.SnapshotInput{ + Tree: tree, + ScreenshotPNG: tinyPNG(t), + StepIndex: stepIndex, + }); err != nil { t.Fatalf("PushSnapshot: %v", err) } } +func readLLMCalls(t *testing.T, directory string) []trace.LLMCall { + t.Helper() + body, err := os.ReadFile(filepath.Join(directory, trace.LLMCallFileName)) + if err != nil { + t.Fatalf("read %s: %v", trace.LLMCallFileName, err) + } + var calls []trace.LLMCall + for _, line := range strings.Split(strings.TrimSpace(string(body)), "\n") { + var call trace.LLMCall + if err := json.Unmarshal([]byte(line), &call); err != nil { + t.Fatalf("decode record %q: %v", line, err) + } + calls = append(calls, call) + } + return calls +} + func candidateByKind(t *testing.T, candidates []verifier.ActionCandidate, kind verifier.ActionKind) verifier.ActionCandidate { t.Helper() for _, candidate := range candidates { @@ -385,7 +458,7 @@ func TestLLMSourceDrivesExecutedActions(t *testing.T) { fake.chosenAction = tap.Description fake.reasoning = "tap submit" fake.text = "" - action, err := source.NextAction(context.Background()) + action, err := source.NextAction(context.Background(), 1) if err != nil { t.Fatalf("NextAction: %v", err) } @@ -411,7 +484,7 @@ func TestLLMSourceDrivesExecutedActions(t *testing.T) { fake.chosenAction = typing.Description fake.reasoning = "type a name" fake.text = "Priya" - action, err = source.NextAction(context.Background()) + action, err = source.NextAction(context.Background(), 1) if err != nil { t.Fatalf("NextAction: %v", err) } @@ -440,7 +513,7 @@ func TestLLMSourceSkipsOnOutOfRangeChoice(t *testing.T) { fake.choice = 9999 fake.chosenAction = "whatever" - _, err := source.NextAction(context.Background()) + _, err := source.NextAction(context.Background(), 1) if !errors.Is(err, verifier.ErrNoAction) { t.Fatalf("NextAction err = %v, want ErrNoAction for an out-of-range choice", err) } @@ -460,7 +533,7 @@ func TestLLMSourceAcceptsEchoWithWeightSuffix(t *testing.T) { tap := candidateByKind(t, candidates, verifier.ActionKindTap) fake.choice = tap.Index fake.chosenAction = tap.Description + " (w" + strconv.Itoa(tap.Weight) + ")" - action, err := source.NextAction(context.Background()) + action, err := source.NextAction(context.Background(), 1) if err != nil { t.Fatalf("NextAction: %v", err) } @@ -497,7 +570,7 @@ func TestLLMSourceStrictSkipsOnEchoMismatch(t *testing.T) { tap := candidateByKind(t, candidates, verifier.ActionKindTap) fake.choice = tap.Index fake.chosenAction = "Tap \"Something Else\"" - _, err := source.NextAction(context.Background()) + _, err := source.NextAction(context.Background(), 1) if !errors.Is(err, verifier.ErrNoAction) { t.Fatalf("NextAction err = %v, want ErrNoAction on chosen_action mismatch", err) } @@ -516,12 +589,247 @@ func TestLLMSourceSkipsOnHTTPError(t *testing.T) { pushLLMSnapshot(t, verifierInstance) fake.choice = 1 - _, err := source.NextAction(context.Background()) + _, err := source.NextAction(context.Background(), 1) if !errors.Is(err, verifier.ErrNoAction) { t.Fatalf("NextAction err = %v, want ErrNoAction on HTTP failure", err) } } +// llmSetupFixtureSpec drives the first action from setup, so the model is never +// consulted for that step. +const llmSetupFixtureSpec = ` +import { llm, always, actions, taps, typing, weighted, Tap } from "@sanderling/spec"; +globalThis.properties = { ok: always(() => true) }; +globalThis.setup = actions(() => [Tap({ on: "id:Submit" })]); +globalThis.actions = weighted([1, taps], [1, typing]); +globalThis.generator = llm({ model: "test/model" }); +` + +// TestLLMCallRecordSeparatesGuardSkipFromDecline pins the reason these records +// exist. A step the echo guard threw away and a step where the picker had +// nothing to choose both used to leave nothing behind but a log line, so any +// defect-yield or actions-per-hour figure computed from a model run silently +// mixed the two with each other and with steps that acted. +func TestLLMCallRecordSeparatesGuardSkipFromDecline(t *testing.T) { + const stepIndex = 7 + + guardSkipped := func(t *testing.T) trace.LLMCall { + fake := newFakeOpenRouter(t) + source, verifierInstance := newLLMSource(t, fake) + pushLLMSnapshot(t, verifierInstance) + tap := candidateByKind(t, verifierInstance.Candidates(), verifier.ActionKindTap) + fake.choice = tap.Index + fake.chosenAction = `Tap "Something Else"` + if _, err := source.NextAction(context.Background(), stepIndex); !errors.Is(err, verifier.ErrNoAction) { + t.Fatalf("NextAction err = %v, want ErrNoAction on echo mismatch", err) + } + return lastCall(t, source) + } + declined := func(t *testing.T) trace.LLMCall { + fake := newFakeOpenRouter(t) + // No snapshot pushed, so the action tree yields nothing to pick from. + source, _ := newLLMSource(t, fake) + if _, err := source.NextAction(context.Background(), stepIndex); !errors.Is(err, verifier.ErrNoAction) { + t.Fatalf("NextAction err = %v, want ErrNoAction with no candidates", err) + } + return lastCall(t, source) + } + acted := func(t *testing.T) trace.LLMCall { + fake := newFakeOpenRouter(t) + source, verifierInstance := newLLMSource(t, fake) + pushLLMSnapshot(t, verifierInstance) + tap := candidateByKind(t, verifierInstance.Candidates(), verifier.ActionKindTap) + fake.choice = tap.Index + fake.chosenAction = tap.Description + if _, err := source.NextAction(context.Background(), stepIndex); err != nil { + t.Fatalf("NextAction: %v", err) + } + return lastCall(t, source) + } + + skip, decline, pick := guardSkipped(t), declined(t), acted(t) + if skip.Outcome != trace.LLMOutcomeEchoMismatch { + t.Errorf("guard-skipped outcome = %q, want %q", skip.Outcome, trace.LLMOutcomeEchoMismatch) + } + if decline.Outcome != trace.LLMOutcomeNoCandidates { + t.Errorf("declined outcome = %q, want %q", decline.Outcome, trace.LLMOutcomeNoCandidates) + } + if pick.Outcome != trace.LLMOutcomeSelected { + t.Errorf("executed outcome = %q, want %q", pick.Outcome, trace.LLMOutcomeSelected) + } + for _, call := range []trace.LLMCall{skip, decline, pick} { + if call.Step != stepIndex { + t.Errorf("record step = %d, want %d so it joins its trace line", call.Step, stepIndex) + } + if call.Timestamp.IsZero() { + t.Error("record carries no timestamp") + } + } + // The guard skip must carry what only the dropped log line used to hold. + if skip.Choice == 0 || skip.EchoedAction != `Tap "Something Else"` || skip.RawResponse == "" { + t.Errorf("guard-skip record = %+v, want the choice, the echo, and the raw response", skip) + } + if len(skip.Candidates) == 0 { + t.Error("guard-skip record must keep the candidate list the mismatch is judged against") + } + // A decline never reached the provider, so it must not look like a call. + if decline.RawResponse != "" || decline.UserPrompt != "" || len(decline.Candidates) != 0 { + t.Errorf("decline record = %+v, want no prompt, candidates, or response", decline) + } +} + +// TestLLMCallRecordsCandidateListAsShown covers the companion experiment that +// varies how candidates are labelled: the labels are an independent variable, so +// each call must be recoverable with the exact numbered list it saw. +func TestLLMCallRecordsCandidateListAsShown(t *testing.T) { + fake := newFakeOpenRouter(t) + source, verifierInstance := newLLMSource(t, fake) + source.instructions = "hunt for double submits" + pushLLMSnapshot(t, verifierInstance) + tap := candidateByKind(t, verifierInstance.Candidates(), verifier.ActionKindTap) + fake.choice = tap.Index + fake.chosenAction = tap.Description + if _, err := source.NextAction(context.Background(), 1); err != nil { + t.Fatalf("NextAction: %v", err) + } + + call := lastCall(t, source) + if len(call.Candidates) == 0 { + t.Fatal("no candidate list recorded") + } + for _, candidate := range call.Candidates { + line := fmt.Sprintf("%d. %s", candidate.Index, candidate.Description) + if !strings.Contains(call.UserPrompt, line) { + t.Errorf("recorded candidate %q is not a line of the prompt:\n%s", line, call.UserPrompt) + } + if candidate.Weight > 0 && !strings.Contains(call.UserPrompt, fmt.Sprintf("%s (w%d)", candidate.Description, candidate.Weight)) { + t.Errorf("recorded weight %d for %q is not the weight the prompt showed:\n%s", + candidate.Weight, candidate.Description, call.UserPrompt) + } + } + numberedLine := regexp.MustCompile(`(?m)^\d+\. `) + if shown := len(numberedLine.FindAllString(call.UserPrompt, -1)); shown != len(call.Candidates) { + t.Errorf("prompt showed %d numbered lines but %d candidates were recorded", shown, len(call.Candidates)) + } + if got := candidateLabels(call.Candidates); !slices.Contains(got, tap.Label) { + t.Errorf("recorded labels = %v, want the target label %q among them", got, tap.Label) + } + // The system prompt is assembled from a constant plus spec instructions, so + // the record has to be the assembled text, not the constant. + if call.SystemPrompt != source.systemPrompt() { + t.Errorf("recorded system prompt = %q, want the assembled prompt", call.SystemPrompt) + } + if !strings.Contains(call.SystemPrompt, "hunt for double submits") { + t.Error("recorded system prompt dropped the spec instructions") + } + if call.Model != "test/model" { + t.Errorf("recorded model = %q, want test/model", call.Model) + } +} + +func candidateLabels(candidates []trace.LLMCandidate) []string { + labels := make([]string, 0, len(candidates)) + for _, candidate := range candidates { + labels = append(labels, candidate.Label) + } + return labels +} + +func TestLLMCallRecordsSetupDrivenStep(t *testing.T) { + fake := newFakeOpenRouter(t) + source, verifierInstance := newLLMSourceWithSpec(t, fake, llmSetupFixtureSpec) + pushLLMSnapshot(t, verifierInstance) + + action, err := source.NextAction(context.Background(), 2) + if err != nil { + t.Fatalf("NextAction: %v", err) + } + if action.On != "id:Submit" { + t.Fatalf("action = %+v, want the setup tap on id:Submit", action) + } + call := lastCall(t, source) + if call.Outcome != trace.LLMOutcomeSetupAction { + t.Errorf("outcome = %q, want %q", call.Outcome, trace.LLMOutcomeSetupAction) + } + if call.UserPrompt != "" || call.RawResponse != "" || call.TotalTokens != 0 { + t.Errorf("setup-driven step = %+v, want no model call recorded", call) + } + if source.lastSource != "" { + t.Errorf("lastSource = %q, want empty: setup chose the action, not the model", source.lastSource) + } +} + +func TestLLMCallFileRecordsUsageLatencyAndScreenshot(t *testing.T) { + fake := newFakeOpenRouter(t) + fake.usage = llmclient.Usage{PromptTokens: 1200, CompletionTokens: 34, TotalTokens: 1234} + fake.servedModel = "vendor/model-2026-05" + fake.delay = 15 * time.Millisecond + source, verifierInstance := newLLMSource(t, fake) + + directory := t.TempDir() + writer, err := trace.NewWriter(directory) + if err != nil { + t.Fatal(err) + } + source.recorder = writer + + pushLLMSnapshotAtStep(t, verifierInstance, 4) + tap := candidateByKind(t, verifierInstance.Candidates(), verifier.ActionKindTap) + fake.choice = tap.Index + fake.chosenAction = tap.Description + if _, err := source.NextAction(context.Background(), 4); err != nil { + t.Fatalf("NextAction: %v", err) + } + if err := writer.Close(); err != nil { + t.Fatal(err) + } + + calls := readLLMCalls(t, directory) + if len(calls) != 1 { + t.Fatalf("recorded %d calls, want 1", len(calls)) + } + call := calls[0] + if call.PromptTokens != 1200 || call.CompletionTokens != 34 || call.TotalTokens != 1234 { + t.Errorf("tokens = %d/%d/%d, want 1200/34/1234", + call.PromptTokens, call.CompletionTokens, call.TotalTokens) + } + if call.LatencyMillis < 15 { + t.Errorf("latency = %dms, want at least the server's 15ms", call.LatencyMillis) + } + if call.ServedModel != "vendor/model-2026-05" { + t.Errorf("served model = %q, want the id the provider reported", call.ServedModel) + } + if want := trace.ScreenshotReference(4); call.Screenshot != want { + t.Errorf("screenshot = %q, want %q", call.Screenshot, want) + } + if call.Reasoning == "" || call.EchoedAction != tap.Description { + t.Errorf("record = %+v, want the parsed reasoning and echo", call) + } +} + +// TestLLMCallScreenshotNamesObservedStep guards the one case where the image +// sent is not the current step's: the runner skips PushSnapshot on a +// transitional observation, so the model still sees the last observed screen. +func TestLLMCallScreenshotNamesObservedStep(t *testing.T) { + fake := newFakeOpenRouter(t) + source, verifierInstance := newLLMSource(t, fake) + pushLLMSnapshotAtStep(t, verifierInstance, 4) + tap := candidateByKind(t, verifierInstance.Candidates(), verifier.ActionKindTap) + fake.choice = tap.Index + fake.chosenAction = tap.Description + if _, err := source.NextAction(context.Background(), 6); err != nil { + t.Fatalf("NextAction: %v", err) + } + + call := lastCall(t, source) + if call.Step != 6 { + t.Errorf("record step = %d, want the current step 6", call.Step) + } + if want := trace.ScreenshotReference(4); call.Screenshot != want { + t.Errorf("screenshot = %q, want %q: the image sent was step 4's", call.Screenshot, want) + } +} + func TestDownscalePNGShrinksLongEdge(t *testing.T) { large := image.NewRGBA(image.Rect(0, 0, 2048, 1024)) var buffer bytes.Buffer diff --git a/internal/runner/source.go b/internal/runner/source.go index 486904c..44a3c75 100644 --- a/internal/runner/source.go +++ b/internal/runner/source.go @@ -15,9 +15,11 @@ import ( // ActionSource resolves the next action for a step. Both runtimes (the goja // picker and the web/V8 picker) implement it so the runner loop has one path // and no per-step driver type assertion. NextAction returns verifier.ErrNoAction -// when the picker declined to act this tick. +// when the picker declined to act this tick. stepIndex is the trace line the +// decision belongs to, so a source that keeps its own records can key them to it +// rather than counting steps a second time. type ActionSource interface { - NextAction(ctx context.Context) (verifier.Action, error) + NextAction(ctx context.Context, stepIndex int) (verifier.Action, error) } // ExtractorSource yields per-step extractor overrides the runner applies after @@ -34,7 +36,7 @@ type gojaSource struct { verifier *verifier.Verifier } -func (s gojaSource) NextAction(context.Context) (verifier.Action, error) { +func (s gojaSource) NextAction(context.Context, int) (verifier.Action, error) { return s.verifier.NextAction() } @@ -49,7 +51,7 @@ type webSource struct { web driver.WebDriver } -func (s webSource) NextAction(ctx context.Context) (verifier.Action, error) { +func (s webSource) NextAction(ctx context.Context, _ int) (verifier.Action, error) { raw, err := s.web.NextActionFromV8(ctx) if err != nil { return verifier.Action{}, fmt.Errorf("v8 next action: %w", err) @@ -108,5 +110,10 @@ func pickSources(options Options) (ActionSource, ExtractorSource, error) { logger: logger, history: newActionHistory(llmHistorySize), } + // Assigned only when present so the interface field stays nil rather than + // holding a typed nil pointer that would panic on the first record. + if options.TraceWriter != nil { + action.recorder = options.TraceWriter + } return action, extractor, nil }