diff --git a/internal/trace/llm_call.go b/internal/trace/llm_call.go new file mode 100644 index 0000000..4375883 --- /dev/null +++ b/internal/trace/llm_call.go @@ -0,0 +1,129 @@ +package trace + +import ( + "encoding/json" + "fmt" + "os" + "path/filepath" + "time" +) + +// LLMCallFileName is the run-directory file model-call records are appended to, +// one JSON object per line, in step order. +// +// These records live beside trace.jsonl rather than inside it because the two +// have different readers. Every trace line already carries a full accessibility +// hierarchy, and both the replay server and the campaign summarizer scan every +// line of it; folding prompts, candidate lists and raw responses in would grow +// the lines those readers parse by several KB each for data neither one reads. +// The join is by Step, which is the step field of the trace line whose +// next_action the call produced. +const LLMCallFileName = "llm-calls.jsonl" + +// Outcomes of one step's action selection. Exactly one is recorded per step of +// a model-driven run, so a step the guard threw away is never confused with one +// where the picker legitimately had nothing to do. +const ( + // LLMOutcomeSelected: the model picked a candidate and the action ran. + LLMOutcomeSelected = "selected" + // LLMOutcomeSetupAction: the spec's setup generator drove the step, so the + // model was not consulted. + LLMOutcomeSetupAction = "setup_action" + // LLMOutcomeSetupFailed: the setup generator itself errored, which aborts + // the run. + LLMOutcomeSetupFailed = "setup_failed" + // LLMOutcomeNoCandidates: the action tree yielded nothing on this screen, so + // no call was made. + LLMOutcomeNoCandidates = "no_candidates" + // LLMOutcomeRequestFailed: the provider call failed (transport, timeout, + // non-2xx). + LLMOutcomeRequestFailed = "request_failed" + // LLMOutcomeNoChoices: a 2xx response carrying an empty choices array. + LLMOutcomeNoChoices = "no_choices" + // LLMOutcomeUnparsableResponse: the content was empty, not JSON, or carried + // no choice. + LLMOutcomeUnparsableResponse = "unparsable_response" + // LLMOutcomeChoiceOutOfRange: the number picked is not in 1..len(candidates). + LLMOutcomeChoiceOutOfRange = "choice_out_of_range" + // LLMOutcomeEchoMismatch: the echoed chosen_action disagrees with the + // numbered entry, so the pick is discarded. + LLMOutcomeEchoMismatch = "echo_mismatch" + // LLMOutcomeActionBuildFailed: the chosen candidate could not be turned into + // an executable action (e.g. the input sampler was unavailable). + LLMOutcomeActionBuildFailed = "action_build_failed" +) + +// LLMCall is one step's action-selection record: what was sent, what came back, +// what it cost, and how the step ended. +type LLMCall struct { + // Step joins this record to the trace line of the same step index. + Step int `json:"step"` + Timestamp time.Time `json:"timestamp"` + Outcome string `json:"outcome"` + // Model is the requested model id; ServedModel is the one the provider + // reported serving, which a router may vary per call. + Model string `json:"model,omitempty"` + ServedModel string `json:"served_model,omitempty"` + // SystemPrompt and UserPrompt are the text parts as sent, not the templates + // they were assembled from. + SystemPrompt string `json:"system_prompt,omitempty"` + UserPrompt string `json:"user_prompt,omitempty"` + // Candidates is the numbered list the prompt rendered, so an experiment that + // varies candidate labelling can recover the labels this call actually saw. + Candidates []LLMCandidate `json:"candidates,omitempty"` + // Screenshot is the run-relative path of the image sent with the call. It + // names the step the image was captured at, which lags Step when the runner + // skipped a transitional observation. + Screenshot string `json:"screenshot,omitempty"` + // RawResponse is the assistant content before parsing. + RawResponse string `json:"raw_response,omitempty"` + PromptTokens int `json:"prompt_tokens,omitempty"` + CompletionTokens int `json:"completion_tokens,omitempty"` + TotalTokens int `json:"total_tokens,omitempty"` + LatencyMillis int64 `json:"latency_millis,omitempty"` + // Choice, EchoedAction and Reasoning are the parsed output, recorded + // whenever parsing succeeded and so present on the outcomes that then + // discarded the pick. EchoedAction is verbatim, including the weight + // annotation models copy along with the line; on an echo_mismatch it is what + // disagreed with Candidates[Choice-1]. + Choice int `json:"choice,omitempty"` + EchoedAction string `json:"echoed_action,omitempty"` + Reasoning string `json:"reasoning,omitempty"` + Error string `json:"error,omitempty"` +} + +// LLMCandidate is one numbered line of the candidate list as the model saw it. +type LLMCandidate struct { + Index int `json:"index"` + Kind string `json:"kind,omitempty"` + // Description is the rendered line the model echoes back; Label is the + // target's visible text the description was built from. + Description string `json:"description"` + Label string `json:"label,omitempty"` + // Weight is the percentage annotation shown on the line, 0 when the spec's + // action tree declared no weights and none was shown. + Weight int `json:"weight,omitempty"` +} + +// WriteLLMCall appends one record to llm-calls.jsonl, creating the file on the +// first call. +func (w *Writer) WriteLLMCall(call LLMCall) error { + w.mutex.Lock() + defer w.mutex.Unlock() + if w.file == nil { + return fmt.Errorf("trace: writer is closed") + } + if w.llmCallEncoder == nil { + file, err := os.OpenFile( + filepath.Join(w.directory, LLMCallFileName), + os.O_CREATE|os.O_WRONLY|os.O_APPEND, + 0o644, + ) + if err != nil { + return fmt.Errorf("open %s: %w", LLMCallFileName, err) + } + w.llmCallFile = file + w.llmCallEncoder = json.NewEncoder(file) + } + return w.llmCallEncoder.Encode(call) +} diff --git a/internal/trace/llm_call_test.go b/internal/trace/llm_call_test.go new file mode 100644 index 0000000..6b24533 --- /dev/null +++ b/internal/trace/llm_call_test.go @@ -0,0 +1,131 @@ +package trace + +import ( + "encoding/json" + "os" + "path/filepath" + "reflect" + "strings" + "testing" + "time" +) + +func TestWriteLLMCall_RoundTrip(t *testing.T) { + directory := t.TempDir() + writer, err := NewWriter(directory) + if err != nil { + t.Fatal(err) + } + + call := LLMCall{ + Step: 4, + Timestamp: time.Date(2026, 8, 12, 9, 30, 0, 0, time.UTC), + Outcome: LLMOutcomeSelected, + Model: "vendor/model", + ServedModel: "vendor/model-2026-05", + SystemPrompt: "You are exercising a UI to find bugs.\n\n" + + "hunt for double submits", + UserPrompt: "Actions available on the current screen:\n1. Tap \"Submit\" (w60)\n", + Candidates: []LLMCandidate{ + {Index: 1, Kind: "tap", Description: `Tap "Submit"`, Label: "Submit", Weight: 60}, + {Index: 2, Kind: "inputText", Description: `Type into "Name"`, Label: "Name", Weight: 40}, + }, + Screenshot: ScreenshotReference(4), + RawResponse: `{"reasoning":"submit twice","choice":1,"chosen_action":"Tap \"Submit\"","text":""}`, + PromptTokens: 1200, + CompletionTokens: 34, + TotalTokens: 1234, + LatencyMillis: 812, + Choice: 1, + EchoedAction: `Tap "Submit"`, + Reasoning: "submit twice", + } + if err := writer.WriteLLMCall(call); err != nil { + t.Fatal(err) + } + if err := writer.WriteLLMCall(LLMCall{ + Step: 5, + Timestamp: call.Timestamp.Add(time.Second), + Outcome: LLMOutcomeNoCandidates, + }); err != nil { + t.Fatal(err) + } + if err := writer.Close(); err != nil { + t.Fatal(err) + } + + body, err := os.ReadFile(filepath.Join(directory, LLMCallFileName)) + if err != nil { + t.Fatal(err) + } + lines := strings.Split(strings.TrimSpace(string(body)), "\n") + if len(lines) != 2 { + t.Fatalf("wrote %d lines, want 2", len(lines)) + } + var got LLMCall + if err := json.Unmarshal([]byte(lines[0]), &got); err != nil { + t.Fatalf("%s line 1 is not valid JSON: %v", LLMCallFileName, err) + } + if !reflect.DeepEqual(got, call) { + t.Errorf("round-trip mismatch:\n got: %+v\nwant: %+v", got, call) + } + + var declined LLMCall + if err := json.Unmarshal([]byte(lines[1]), &declined); err != nil { + t.Fatal(err) + } + if declined.Step != 5 || declined.Outcome != LLMOutcomeNoCandidates { + t.Errorf("second record = %+v, want step 5 with outcome %q", declined, LLMOutcomeNoCandidates) + } +} + +// TestWriteLLMCall_FileAbsentWithoutCalls keeps a seeded run's directory free of +// model-call output, so its presence alone identifies a model-driven run. +func TestWriteLLMCall_FileAbsentWithoutCalls(t *testing.T) { + directory := t.TempDir() + writer, err := NewWriter(directory) + if err != nil { + t.Fatal(err) + } + if err := writer.WriteStep(Step{Index: 1, Timestamp: time.Now()}); err != nil { + t.Fatal(err) + } + if err := writer.Close(); err != nil { + t.Fatal(err) + } + if _, err := os.Stat(filepath.Join(directory, LLMCallFileName)); !os.IsNotExist(err) { + t.Errorf("stat %s = %v, want the file never to be created", LLMCallFileName, err) + } +} + +// TestScreenshotReferenceMatchesWrittenFile pins the reference records point at +// to the path WriteScreenshot actually writes. +func TestScreenshotReferenceMatchesWrittenFile(t *testing.T) { + directory := t.TempDir() + writer, err := NewWriter(directory) + if err != nil { + t.Fatal(err) + } + defer writer.Close() + + if err := writer.WriteScreenshot(12, []byte("not really a png")); err != nil { + t.Fatal(err) + } + if _, err := os.Stat(filepath.Join(directory, ScreenshotReference(12))); err != nil { + t.Errorf("stat %s: %v", ScreenshotReference(12), err) + } +} + +func TestWriteLLMCall_AfterCloseErrors(t *testing.T) { + directory := t.TempDir() + writer, err := NewWriter(directory) + if err != nil { + t.Fatal(err) + } + if err := writer.Close(); err != nil { + t.Fatal(err) + } + if err := writer.WriteLLMCall(LLMCall{Step: 1}); err == nil { + t.Error("expected an error writing to a closed writer") + } +} diff --git a/internal/trace/writer.go b/internal/trace/writer.go index 52f9809..30e6ce2 100644 --- a/internal/trace/writer.go +++ b/internal/trace/writer.go @@ -31,6 +31,10 @@ type Step struct { // retry budget. The verifier is skipped for these steps so transient // state does not poison the previous/current extractor advance. Transitional bool `json:"transitional,omitempty"` + // ActionSkipped names why NextAction was chosen but never dispatched, so a + // count of executed actions cannot be inflated by steps whose action the + // runner threw away. Empty when the action ran (or when none was chosen). + ActionSkipped string `json:"action_skipped,omitempty"` // SkippedVerification is set true exactly when the verifier was skipped // for this step, so downstream tooling can tell a deliberately-skipped // step from one that was verified and came back clean. @@ -151,6 +155,10 @@ type Writer struct { mutex sync.Mutex file io.WriteCloser encoder *json.Encoder + // llmCallFile is opened on the first WriteLLMCall, so a run whose picker + // never called a model leaves no llm-calls.jsonl behind at all. + llmCallFile io.WriteCloser + llmCallEncoder *json.Encoder } // NewWriter ensures `directory` exists and opens trace.jsonl for append. @@ -194,14 +202,27 @@ func (w *Writer) WriteStep(step Step) error { // file via os.WriteFile and touches no field of Writer, so concurrent calls // never contend. func (w *Writer) WriteScreenshot(stepIndex int, png []byte) error { - return w.writePNG(fmt.Sprintf("step-%05d.png", stepIndex), png) + return w.writePNG(screenshotName(stepIndex), png) } +func screenshotName(stepIndex int) string { + return fmt.Sprintf("step-%05d.png", stepIndex) +} + +// ScreenshotReference is the run-relative path WriteScreenshot puts a step's +// screenshot at. Records that describe an image point at it instead of copying +// the bytes. +func ScreenshotReference(stepIndex int) string { + return screenshotDirectory + "/" + screenshotName(stepIndex) +} + +const screenshotDirectory = "screenshots" + func (w *Writer) writePNG(name string, png []byte) error { if len(png) == 0 { return nil } - directory := filepath.Join(w.directory, "screenshots") + directory := filepath.Join(w.directory, screenshotDirectory) if err := os.MkdirAll(directory, 0o755); err != nil { return fmt.Errorf("mkdir screenshots: %w", err) } @@ -211,10 +232,18 @@ func (w *Writer) writePNG(name string, png []byte) error { func (w *Writer) Close() error { w.mutex.Lock() defer w.mutex.Unlock() + var err error + if w.llmCallFile != nil { + err = w.llmCallFile.Close() + w.llmCallFile = nil + w.llmCallEncoder = nil + } if w.file == nil { - return nil + return err + } + if closeErr := w.file.Close(); closeErr != nil { + err = closeErr } - err := w.file.Close() w.file = nil return err }