From b0cf6fb951ab69e84a694f3c46c569f1062566fd Mon Sep 17 00:00:00 2001 From: dev_agent Date: Mon, 5 Oct 2026 09:32:20 -0400 Subject: [PATCH 1/2] Record every harness run in ai_runs with redaction and purge harness.Run now writes one ai_runs row per run that reaches the provider, covering the repair turn: skill, version, provider, model, temperature, status (ok, repaired, bad_output, provider_error), latency, summed token counts when reported, error text and the per-turn request and response bodies. Every stored string is redacted first: the decrypted API key, Authorization and API-key header values, Google Chat webhook URLs and URLs with key-like query or fragment parameters or user info. JSON is decoded and its strings redacted, so escapes cannot hide a credential. A row that cannot be written fails the run. Purge deletes rows created before a cutoff (RunRetention is 30 days), clearing suggestion_batches and week_plans references in the same transaction. Migration 0006 rebuilds ai_runs with the new status CHECK and a created_at index; a pre-harness running or error row stops it. Maestro task 53e382d8-1db3-4555-a31d-e44cf55cc98d. Co-Authored-By: Claude Opus 5.5 --- docs/ARCHITECTURE.md | 9 +- internal/ai/harness/harness.go | 109 ++++++-- internal/ai/harness/harness_test.go | 40 ++- internal/ai/harness/prompt_test.go | 4 +- internal/ai/harness/redact.go | 139 ++++++++++ internal/ai/harness/runs.go | 194 +++++++++++++ internal/ai/harness/runs_test.go | 412 ++++++++++++++++++++++++++++ internal/db/ai_runs.sql.go | 107 ++++++++ internal/db/querier.go | 8 + internal/store/migrate_test.go | 79 +++++- internal/store/schema_test.go | 2 + migrations/0006_ai_runs_status.sql | 47 ++++ migrations/queries/ai_runs.sql | 28 ++ 13 files changed, 1141 insertions(+), 37 deletions(-) create mode 100644 internal/ai/harness/redact.go create mode 100644 internal/ai/harness/runs.go create mode 100644 internal/ai/harness/runs_test.go create mode 100644 internal/db/ai_runs.sql.go create mode 100644 migrations/0006_ai_runs_status.sql create mode 100644 migrations/queries/ai_runs.sql diff --git a/docs/ARCHITECTURE.md b/docs/ARCHITECTURE.md index 9fd67a4..a7c0857 100644 --- a/docs/ARCHITECTURE.md +++ b/docs/ARCHITECTURE.md @@ -150,7 +150,14 @@ automatic** (D-021). Anthropic and Ollama endpoints, called over plain HTTP — no vendor SDKs. - **Skill harness** (`ai/harness`): prompt layering, validation of the structured output, and **one repair retry**; if the repair also fails the - run fails — no silent fallback. Every call is recorded in `ai_runs`. + run fails — no silent fallback. Every run that reaches the provider writes + one `ai_runs` row when it ends, covering the repair turn too, with status + `ok`, `repaired`, `bad_output` or `provider_error`. Request and response + bodies are redacted before they are stored: the decrypted API key, + Authorization and API-key header values, Google Chat webhook URLs and URLs + with key-like query parameters are removed, inside JSON strings too. + `harness.Purge` deletes rows older than `harness.RunRetention` (30 days), + clearing the `suggestion_batches` and `week_plans` references first. - **Prompt layering** (D-007): each skill version's prompt is a `text/template` file embedded from `ai/skills/prompts/` (`.v.tmpl`). The system prompt is always, in order: diff --git a/internal/ai/harness/harness.go b/internal/ai/harness/harness.go index 6fa1312..fa52e9d 100644 --- a/internal/ai/harness/harness.go +++ b/internal/ai/harness/harness.go @@ -4,7 +4,8 @@ // for output matching the skill's schema, decodes and validates the reply, // and on failure sends exactly one repair turn quoting the problems. If the // repair fails too the run fails with llm.ErrBadOutput; there is no silent -// fallback (D-007). +// fallback (D-007). Every run that reaches the provider is recorded in +// ai_runs (see Run and Purge). package harness import ( @@ -17,6 +18,7 @@ import ( "strings" "code.cubecraftlabs.com/Maniacs_Mansion/Meal-Quest/internal/ai/llm" + "code.cubecraftlabs.com/Maniacs_Mansion/Meal-Quest/internal/store" ) // Skill is one versioned AI task with input In and structured output Out. @@ -50,6 +52,30 @@ type Config struct { // Temperature is the household's sampling temperature, sent with // every request. Temperature float64 + // ProviderName is ai_settings.provider and Model is ai_settings.model, + // both recorded in ai_runs. Neither may be empty. + ProviderName string + Model string + // APIKey is the decrypted API key Provider sends, or "" when it sends + // none. It is used only to remove the key from the ai_runs row. + APIKey string + // Store receives the run's ai_runs row. It must not be nil. + Store *store.Store +} + +// validate reports a Config missing what every run needs. +func (c Config) validate() error { + switch { + case c.Provider == nil: + return errors.New("config has no provider") + case c.ProviderName == "": + return errors.New("config has no provider name") + case c.Model == "": + return errors.New("config has no model") + case c.Store == nil: + return errors.New("config has no store") + } + return nil } // BadOutputError is a run whose reply and repair reply were both unusable. @@ -74,8 +100,17 @@ func (e *BadOutputError) Unwrap() error { return llm.ErrBadOutput } // Run runs skill s on in with cfg and returns its validated, post-processed // output. A provider error other than llm.ErrBadOutput is returned // unchanged and never repaired. +// +// Every run that sends a request writes one ai_runs row when it ends, +// covering both turns, with its RunStatus and the request and response +// bodies redacted (see redact). A Config or render error fails the run +// before any request, and writes no row. When the row cannot be written +// the run fails with that error too, even if its output was usable. func Run[In, Out any](ctx context.Context, cfg Config, s Skill[In, Out], in In) (Out, error) { var zero Out + if err := cfg.validate(); err != nil { + return zero, fmt.Errorf("harness: skill %s v%d: %w", s.Name(), s.Version(), err) + } prompt, err := Render(cfg.Persona, s, in) if err != nil { return zero, fmt.Errorf("harness: skill %s v%d: render: %w", s.Name(), s.Version(), err) @@ -89,33 +124,51 @@ func Run[In, Out any](ctx context.Context, cfg Config, s Skill[In, Out], in In) Schema: &schema, } - out, reply, first, err := attempt(ctx, cfg.Provider, s, req) + log := &runLog{start: store.Now()} + out, status, err := turns(ctx, cfg, s, req, log) + if saveErr := log.save(ctx, cfg, s.Name(), s.Version(), status, err); saveErr != nil { + return zero, errors.Join(err, fmt.Errorf("harness: skill %s v%d: record ai_runs row: %w", s.Name(), s.Version(), saveErr)) + } if err != nil { return zero, err } - if len(first) > 0 { - if reply != "" { - req.Messages = append(req.Messages, llm.Message{Role: llm.RoleAssistant, Content: reply}) - } - req.Messages = append(req.Messages, llm.Message{Role: llm.RoleUser, Content: repairMessage(schema.Name, first)}) - var second []string - out, _, second, err = attempt(ctx, cfg.Provider, s, req) - if err != nil { - return zero, err - } - if len(second) > 0 { - return zero, &BadOutputError{Skill: s.Name(), Version: s.Version(), First: first, Repair: second} - } - } return out, nil } -// attempt sends req once, then decodes, validates, post-processes and -// validates the reply again. It returns the reply for the repair turn and -// the problems found; err is set only for a provider or post-process -// failure, neither of which is repairable. -func attempt[In, Out any](ctx context.Context, p llm.Provider, s Skill[In, Out], req llm.Request) (out Out, reply string, problems []string, err error) { - resp, err := p.Generate(ctx, req) +// turns sends req and, when its reply is unusable, the repair turn, +// recording both in log. It returns the run's status alongside its result. +func turns[In, Out any](ctx context.Context, cfg Config, s Skill[In, Out], req llm.Request, log *runLog) (Out, RunStatus, error) { + var zero Out + out, reply, first, status, err := attempt(ctx, cfg, s, req, log) + if err != nil { + return zero, status, err + } + if len(first) == 0 { + return out, StatusOK, nil + } + log.problems = first + if reply != "" { + req.Messages = append(req.Messages, llm.Message{Role: llm.RoleAssistant, Content: reply}) + } + req.Messages = append(req.Messages, llm.Message{Role: llm.RoleUser, Content: repairMessage(req.Schema.Name, first)}) + out, _, second, status, err := attempt(ctx, cfg, s, req, log) + if err != nil { + return zero, status, err + } + if len(second) > 0 { + return zero, StatusBadOutput, &BadOutputError{Skill: s.Name(), Version: s.Version(), First: first, Repair: second} + } + return out, StatusRepaired, nil +} + +// attempt sends req once, records the turn in log, then decodes, +// validates, post-processes and validates the reply again. It returns the +// reply for the repair turn and the problems found; err is set only for a +// provider or post-process failure, neither of which is repairable, and +// status then says which. +func attempt[In, Out any](ctx context.Context, cfg Config, s Skill[In, Out], req llm.Request, log *runLog) (out Out, reply string, problems []string, status RunStatus, err error) { + resp, err := cfg.Provider.Generate(ctx, req) + log.add(cfg.APIKey, req, resp, err) // The repair turn must quote what failed: the structured output when // there is any, otherwise the text. reply = string(resp.JSON) @@ -124,21 +177,21 @@ func attempt[In, Out any](ctx context.Context, p llm.Provider, s Skill[In, Out], } if err != nil { if errors.Is(err, llm.ErrBadOutput) { - return out, reply, []string{err.Error()}, nil + return out, reply, []string{err.Error()}, "", nil } - return out, "", nil, err + return out, "", nil, StatusProviderError, err } if err := decode(resp.JSON, &out); err != nil { - return out, reply, []string{err.Error()}, nil + return out, reply, []string{err.Error()}, "", nil } if problems := s.Validate(out); len(problems) > 0 { - return out, reply, problems, nil + return out, reply, problems, "", nil } out, err = s.PostProcess(out) if err != nil { - return out, "", nil, fmt.Errorf("harness: skill %s v%d: post-process: %w", s.Name(), s.Version(), err) + return out, "", nil, StatusBadOutput, fmt.Errorf("harness: skill %s v%d: post-process: %w", s.Name(), s.Version(), err) } - return out, reply, s.Validate(out), nil + return out, reply, s.Validate(out), "", nil } // decode strictly decodes data into out: one JSON value, no unknown fields. diff --git a/internal/ai/harness/harness_test.go b/internal/ai/harness/harness_test.go index 042db2d..1c0ad9f 100644 --- a/internal/ai/harness/harness_test.go +++ b/internal/ai/harness/harness_test.go @@ -15,9 +15,15 @@ func reply(js string) llm.GenerateResult { return llm.GenerateResult{Response: llm.Response{Text: js, JSON: json.RawMessage(js)}} } +// testConfig returns a Config for f recording into a fresh migrated store. +func testConfig(t *testing.T, f *llm.Fake) Config { + t.Helper() + return Config{Provider: f, Temperature: 0.7, ProviderName: "anthropic", Model: "claude-test", Store: emptyHousehold(t)} +} + func run(t *testing.T, f *llm.Fake) (echoOutput, error) { t.Helper() - return Run(context.Background(), Config{Provider: f, Temperature: 0.7}, echoSkill{}, echoInput{Word: "taco"}) + return Run(context.Background(), testConfig(t, f), echoSkill{}, echoInput{Word: "taco"}) } func assertCalls(t *testing.T, f *llm.Fake, want int) []llm.Request { @@ -203,9 +209,37 @@ func TestRunProviderErrorOnRepairPassesThrough(t *testing.T) { func TestRunRenderError(t *testing.T) { var f llm.Fake - _, err := Run(context.Background(), Config{Provider: &f}, echoSkill{}, echoInput{}) - if err == nil || errors.Is(err, llm.ErrBadOutput) { + cfg := testConfig(t, &f) + _, err := Run(context.Background(), cfg, echoSkill{}, echoInput{}) + if err == nil || !strings.Contains(err.Error(), "render") { t.Fatalf("err = %v, want a render error", err) } assertCalls(t, &f, 0) + if rows := runRows(t, cfg.Store); len(rows) != 0 { + t.Fatalf("render error wrote %d ai_runs rows, want none", len(rows)) + } +} + +func TestRunConfigError(t *testing.T) { + var f llm.Fake + full := testConfig(t, &f) + for name, edit := range map[string]func(*Config){ + "provider": func(c *Config) { c.Provider = nil }, + "provider name": func(c *Config) { c.ProviderName = "" }, + "model": func(c *Config) { c.Model = "" }, + "store": func(c *Config) { c.Store = nil }, + } { + t.Run(name, func(t *testing.T) { + cfg := full + edit(&cfg) + _, err := Run(context.Background(), cfg, echoSkill{}, echoInput{Word: "taco"}) + if err == nil || !strings.Contains(err.Error(), "config has no "+name) { + t.Fatalf("err = %v, want missing %s", err, name) + } + }) + } + assertCalls(t, &f, 0) + if rows := runRows(t, full.Store); len(rows) != 0 { + t.Fatalf("config errors wrote %d ai_runs rows, want none", len(rows)) + } } diff --git a/internal/ai/harness/prompt_test.go b/internal/ai/harness/prompt_test.go index ebe7c7b..deda41e 100644 --- a/internal/ai/harness/prompt_test.go +++ b/internal/ai/harness/prompt_test.go @@ -117,7 +117,9 @@ func TestRunSendsLayeredPrompt(t *testing.T) { var f llm.Fake f.QueueGenerate(reply(`{"echo":"taco"}`)) in := echoInput{Word: "Taco", Context: tacoContext} - if _, err := Run(context.Background(), Config{Provider: &f, Persona: persona}, echoSkill{}, in); err != nil { + cfg := testConfig(t, &f) + cfg.Persona = persona + if _, err := Run(context.Background(), cfg, echoSkill{}, in); err != nil { t.Fatal(err) } req := assertCalls(t, &f, 1)[0] diff --git a/internal/ai/harness/redact.go b/internal/ai/harness/redact.go new file mode 100644 index 0000000..cd87c36 --- /dev/null +++ b/internal/ai/harness/redact.go @@ -0,0 +1,139 @@ +package harness + +import ( + "bytes" + "encoding/json" + "net/url" + "regexp" + "strings" + + "code.cubecraftlabs.com/Maniacs_Mansion/Meal-Quest/internal/ai/llm" +) + +// redactionMarker replaces each credential redact removes. +const redactionMarker = "[REDACTED]" + +var ( + // chatWebhookURL matches a Google Chat webhook URL, with or without + // its scheme. + chatWebhookURL = regexp.MustCompile(`(?i)(?:https?://)?chat\.googleapis\.com/[^\s"'<>]*`) + // schemeURL matches a URL with a scheme, up to whitespace, a quote or + // an angle bracket. + schemeURL = regexp.MustCompile(`(?i)[a-z][a-z0-9+.-]*://[^\s"'<>]+`) + // credentialHeader matches an Authorization or API-key header, or a + // field so named, and its value up to the end of the line or a quote. + // No word boundary is required before the name, so escaped text such + // as a JSON "\nAuthorization: …" matches too. + credentialHeader = regexp.MustCompile(`(?i)(` + credentialHeaderNames + `)(["']?[ \t]*[:=][ \t]*["']?)[^"'\r\n]*`) +) + +// credentialHeaderNames are the header names whose values are credentials. +const credentialHeaderNames = `proxy-authorization|authorization|x-goog-api-key|x-api-key|api-key` + +// credentialField matches a JSON object key naming a credential header. +var credentialField = regexp.MustCompile(`(?i)^(?:` + credentialHeaderNames + `)$`) + +// credentialParams are the substrings that make a URL query or fragment +// parameter name key-like, compared in lower case. +var credentialParams = []string{"key", "token", "secret", "sig", "pass", "auth", "credential"} + +// redact returns s with credentials removed: every occurrence of apiKey +// (the decrypted API key, or "" when there is none), Google Chat webhook +// URLs, URLs with a key-like query or fragment parameter or with user +// info, and the values of Authorization and API-key headers. Each becomes +// "[REDACTED]". +// +// When s is a JSON document its strings are redacted after decoding, so +// JSON escapes cannot hide a credential from the patterns, and it is +// encoded again. Any other s is redacted as text. +func redact(s, apiKey string) string { + var doc any + dec := json.NewDecoder(strings.NewReader(s)) + dec.UseNumber() + if strings.TrimSpace(s) != "" && json.Valid([]byte(s)) && dec.Decode(&doc) == nil { + var b bytes.Buffer + enc := json.NewEncoder(&b) + enc.SetEscapeHTML(false) + if err := enc.Encode(redactJSON(doc, apiKey)); err != nil { + // A decoded document always encodes; were it not to, it is + // still redacted, as text. + return redactText(s, apiKey) + } + // The encoding can join text into the key; Redact deletes it. + return llm.Redact(strings.TrimSuffix(b.String(), "\n"), apiKey) + } + return redactText(s, apiKey) +} + +// redactJSON returns the decoded JSON value v with every string and object +// key redacted, and the values of credential header fields replaced. +func redactJSON(v any, apiKey string) any { + switch v := v.(type) { + case string: + return redact(v, apiKey) + case []any: + for i, e := range v { + v[i] = redactJSON(e, apiKey) + } + return v + case map[string]any: + out := make(map[string]any, len(v)) + for k, e := range v { + if credentialField.MatchString(k) { + e = redactionMarker + } + out[redact(k, apiKey)] = redactJSON(e, apiKey) + } + return out + } + return v +} + +// redactText redacts s as plain text. +func redactText(s, apiKey string) string { + s = llm.Redact(s, apiKey) + s = chatWebhookURL.ReplaceAllLiteralString(s, redactionMarker) + s = schemeURL.ReplaceAllStringFunc(s, func(u string) string { + if hasCredential(u) { + return redactionMarker + } + return u + }) + s = credentialHeader.ReplaceAllString(s, "${1}${2}"+redactionMarker) + // A removal can join text either side into the key; Redact deletes + // it until none remains. + return llm.Redact(s, apiKey) +} + +// hasCredential reports whether URL u carries user info or a key-like +// query or fragment parameter. A parameter name that does not unescape +// counts as key-like, so it is never kept unexamined. +func hasCredential(u string) bool { + _, rest, _ := strings.Cut(u, "://") + authority := rest + if i := strings.IndexAny(rest, "/?#"); i >= 0 { + authority = rest[:i] + } + if strings.Contains(authority, "@") { + return true + } + i := strings.IndexAny(rest, "?#") + if i < 0 { + return false + } + params := strings.FieldsFunc(rest[i+1:], func(r rune) bool { return strings.ContainsRune("&;?#", r) }) + for _, p := range params { + name, _, _ := strings.Cut(p, "=") + name, err := url.QueryUnescape(name) + if err != nil { + return true + } + name = strings.ToLower(name) + for _, c := range credentialParams { + if strings.Contains(name, c) { + return true + } + } + } + return false +} diff --git a/internal/ai/harness/runs.go b/internal/ai/harness/runs.go new file mode 100644 index 0000000..9b13bd4 --- /dev/null +++ b/internal/ai/harness/runs.go @@ -0,0 +1,194 @@ +package harness + +import ( + "bytes" + "context" + "database/sql" + "encoding/json" + "errors" + "fmt" + "strconv" + "strings" + "time" + + "code.cubecraftlabs.com/Maniacs_Mansion/Meal-Quest/internal/ai/llm" + "code.cubecraftlabs.com/Maniacs_Mansion/Meal-Quest/internal/db" + "code.cubecraftlabs.com/Maniacs_Mansion/Meal-Quest/internal/store" +) + +// RunStatus is the outcome of a run, stored in ai_runs.status. +type RunStatus string + +// The run outcomes. +const ( + // StatusOK means the first reply was usable. + StatusOK RunStatus = "ok" + // StatusRepaired means the first reply was not usable and the reply to + // the repair turn was. + StatusRepaired RunStatus = "repaired" + // StatusBadOutput means neither reply was usable, or post-processing + // a valid reply failed. + StatusBadOutput RunStatus = "bad_output" + // StatusProviderError means the provider failed on either turn. + StatusProviderError RunStatus = "provider_error" +) + +// RunRetention is how long ai_runs rows are kept. The daily purge calls +// Purge with time.Now().Add(-RunRetention). +const RunRetention = 30 * 24 * time.Hour + +// Purge deletes the ai_runs rows created before olderThan and returns how +// many it deleted. The suggestion_batches and week_plans references to +// those rows are cleared first, in the same transaction. +func Purge(ctx context.Context, st *store.Store, olderThan time.Time) (int64, error) { + if olderThan.IsZero() { + return 0, errors.New("harness: purge ai_runs: zero cutoff") + } + cutoff := store.Timestamp{Time: olderThan.Truncate(time.Millisecond)}.String() + var deleted int64 + err := st.WithTx(ctx, func(tx *sql.Tx) error { + q := db.New(tx) + if _, err := q.ClearSuggestionBatchAIRunsBefore(ctx, cutoff); err != nil { + return err + } + if _, err := q.ClearWeekPlanAIRunsBefore(ctx, cutoff); err != nil { + return err + } + n, err := q.DeleteAIRunsBefore(ctx, cutoff) + deleted = n + return err + }) + if err != nil { + return 0, fmt.Errorf("harness: purge ai_runs: %w", err) + } + return deleted, nil +} + +// runLog collects one run's turns for its ai_runs row. +type runLog struct { + start store.Timestamp + requests []loggedRequest + responses []loggedResponse + tokensIn int64 + tokensOut int64 + // problems lists what was wrong with the first reply of a repaired + // run; it is the row's error text. + problems []string +} + +// loggedRequest is one turn's llm.Request as stored in +// ai_runs.request_redacted. +type loggedRequest struct { + System string `json:"system,omitempty"` + Messages []loggedMessage `json:"messages"` + Temperature *float64 `json:"temperature,omitempty"` + MaxTokens int `json:"max_tokens,omitempty"` + SchemaName string `json:"schema_name,omitempty"` + Schema string `json:"schema,omitempty"` +} + +type loggedMessage struct { + Role llm.Role `json:"role"` + Content string `json:"content"` +} + +// loggedResponse is one turn's llm.Response, or its error, as stored in +// ai_runs.response_redacted. +type loggedResponse struct { + Text string `json:"text,omitempty"` + JSON string `json:"json,omitempty"` + Model string `json:"model,omitempty"` + FinishReason string `json:"finish_reason,omitempty"` + InputTokens int `json:"input_tokens,omitempty"` + OutputTokens int `json:"output_tokens,omitempty"` + Error string `json:"error,omitempty"` +} + +// add records one turn: the request sent and the reply or error. Every +// string is redacted as it is recorded. +func (l *runLog) add(apiKey string, req llm.Request, resp llm.Response, err error) { + r := loggedRequest{ + System: redact(req.System, apiKey), + Temperature: req.Temperature, + MaxTokens: req.MaxTokens, + } + for _, m := range req.Messages { + r.Messages = append(r.Messages, loggedMessage{Role: m.Role, Content: redact(m.Content, apiKey)}) + } + if req.Schema != nil { + r.SchemaName = redact(req.Schema.Name, apiKey) + r.Schema = redact(string(req.Schema.Schema), apiKey) + } + l.requests = append(l.requests, r) + + lr := loggedResponse{ + Text: redact(resp.Text, apiKey), + JSON: redact(string(resp.JSON), apiKey), + Model: redact(resp.Model, apiKey), + FinishReason: redact(resp.FinishReason, apiKey), + InputTokens: resp.Usage.InputTokens, + OutputTokens: resp.Usage.OutputTokens, + } + if err != nil { + lr.Error = redact(err.Error(), apiKey) + } + l.responses = append(l.responses, lr) + l.tokensIn += int64(resp.Usage.InputTokens) + l.tokensOut += int64(resp.Usage.OutputTokens) +} + +// save writes the run's ai_runs row. It is written even when ctx is done, +// so a cancelled run is recorded too. +func (l *runLog) save(ctx context.Context, cfg Config, skill string, version int, status RunStatus, runErr error) error { + request, err := marshalRedacted(l.requests, cfg.APIKey) + if err != nil { + return err + } + response, err := marshalRedacted(l.responses, cfg.APIKey) + if err != nil { + return err + } + var errText sql.NullString + switch { + case runErr != nil: + errText = sql.NullString{String: redact(runErr.Error(), cfg.APIKey), Valid: true} + case len(l.problems) > 0: + errText = sql.NullString{String: redact("first reply: "+strings.Join(l.problems, "; "), cfg.APIKey), Valid: true} + } + now := store.Now() + return db.New(cfg.Store.Writer).CreateAIRun(context.WithoutCancel(ctx), db.CreateAIRunParams{ + ID: store.NewID(), + Skill: skill, + SkillVersion: strconv.Itoa(version), + Provider: cfg.ProviderName, + Model: cfg.Model, + Temperature: cfg.Temperature, + Status: string(status), + LatencyMs: sql.NullInt64{Int64: now.Sub(l.start.Time).Milliseconds(), Valid: true}, + TokensIn: reported(l.tokensIn), + TokensOut: reported(l.tokensOut), + Error: errText, + RequestRedacted: request, + ResponseRedacted: sql.NullString{String: response, Valid: true}, + CreatedAt: l.start.String(), + UpdatedAt: now.String(), + }) +} + +// reported is n as a column value, NULL when no turn reported a count. +func reported(n int64) sql.NullInt64 { + return sql.NullInt64{Int64: n, Valid: n > 0} +} + +// marshalRedacted encodes v as JSON without HTML escaping, so the stored +// text matches what was redacted, and redacts the result once more in case +// the encoding joined text into the key. +func marshalRedacted(v any, apiKey string) (string, error) { + var b bytes.Buffer + enc := json.NewEncoder(&b) + enc.SetEscapeHTML(false) + if err := enc.Encode(v); err != nil { + return "", fmt.Errorf("encode ai_runs body: %w", err) + } + return llm.Redact(string(bytes.TrimSuffix(b.Bytes(), []byte("\n"))), apiKey), nil +} diff --git a/internal/ai/harness/runs_test.go b/internal/ai/harness/runs_test.go new file mode 100644 index 0000000..182cc42 --- /dev/null +++ b/internal/ai/harness/runs_test.go @@ -0,0 +1,412 @@ +package harness + +import ( + "context" + "database/sql" + "encoding/json" + "errors" + "fmt" + "strings" + "testing" + "time" + + "code.cubecraftlabs.com/Maniacs_Mansion/Meal-Quest/internal/ai/llm" + "code.cubecraftlabs.com/Maniacs_Mansion/Meal-Quest/internal/db" + "code.cubecraftlabs.com/Maniacs_Mansion/Meal-Quest/internal/store" +) + +// runRow is one ai_runs row as stored. +type runRow struct { + ID, Skill, SkillVersion, Provider, Model, Status string + Temperature float64 + LatencyMs, TokensIn, TokensOut sql.NullInt64 + Error sql.NullString + Request string + Response sql.NullString + CreatedAt, UpdatedAt string +} + +// text is every column of r, for scanning for secrets. +func (r runRow) text() string { + return strings.Join([]string{r.ID, r.Skill, r.SkillVersion, r.Provider, r.Model, r.Status, + r.Error.String, r.Request, r.Response.String, r.CreatedAt, r.UpdatedAt}, "\n") +} + +// runRows returns every ai_runs row, oldest first. +func runRows(t *testing.T, st *store.Store) []runRow { + t.Helper() + rows, err := st.Reader.Query(`SELECT id, skill, skill_version, provider, model, temperature, status, latency_ms, + tokens_in, tokens_out, error, request_redacted, response_redacted, created_at, updated_at FROM ai_runs ORDER BY id`) + if err != nil { + t.Fatal(err) + } + defer rows.Close() + var out []runRow + for rows.Next() { + var r runRow + if err := rows.Scan(&r.ID, &r.Skill, &r.SkillVersion, &r.Provider, &r.Model, &r.Temperature, &r.Status, &r.LatencyMs, + &r.TokensIn, &r.TokensOut, &r.Error, &r.Request, &r.Response, &r.CreatedAt, &r.UpdatedAt); err != nil { + t.Fatal(err) + } + out = append(out, r) + } + if err := rows.Err(); err != nil { + t.Fatal(err) + } + return out +} + +// failingPostProcess is echoSkill whose PostProcess fails. +type failingPostProcess struct{ echoSkill } + +func (failingPostProcess) PostProcess(echoOutput) (echoOutput, error) { + return echoOutput{}, errors.New("cannot finish") +} + +func used(js string, in, out int) llm.GenerateResult { + r := reply(js) + r.Response.Usage = llm.Usage{InputTokens: in, OutputTokens: out} + return r +} + +func TestRunWritesOneRowWithStatus(t *testing.T) { + for _, tc := range []struct { + name string + skill Skill[echoInput, echoOutput] + script []llm.GenerateResult + status RunStatus + turns int + tokensIn sql.NullInt64 + tokensOut sql.NullInt64 + errText string + }{ + { + name: "ok", skill: echoSkill{}, + script: []llm.GenerateResult{used(`{"echo":"taco"}`, 100, 7)}, + status: StatusOK, turns: 1, + tokensIn: sql.NullInt64{Int64: 100, Valid: true}, tokensOut: sql.NullInt64{Int64: 7, Valid: true}, + }, + { + name: "repaired", skill: echoSkill{}, + script: []llm.GenerateResult{used(`{"echo":"TACO"}`, 100, 7), used(`{"echo":"taco"}`, 130, 6)}, + status: StatusRepaired, turns: 2, + tokensIn: sql.NullInt64{Int64: 230, Valid: true}, tokensOut: sql.NullInt64{Int64: 13, Valid: true}, + errText: "first reply: echo must be lower case", + }, + { + name: "bad output", skill: echoSkill{}, + script: []llm.GenerateResult{reply(`{"echo":"TACO"}`), reply(`{"echo":""}`)}, + status: StatusBadOutput, turns: 2, + errText: "echo must not be empty", + }, + { + name: "post-process failure", skill: failingPostProcess{}, + script: []llm.GenerateResult{used(`{"echo":"taco"}`, 100, 7)}, + status: StatusBadOutput, turns: 1, + tokensIn: sql.NullInt64{Int64: 100, Valid: true}, tokensOut: sql.NullInt64{Int64: 7, Valid: true}, + errText: "post-process: cannot finish", + }, + { + name: "provider error", skill: echoSkill{}, + script: []llm.GenerateResult{{Err: llm.ErrAuth}}, + status: StatusProviderError, turns: 1, + errText: llm.ErrAuth.Error(), + }, + { + name: "provider error on repair", skill: echoSkill{}, + script: []llm.GenerateResult{used(`{"echo":"TACO"}`, 100, 7), {Err: llm.ErrTimeout}}, + status: StatusProviderError, turns: 2, + tokensIn: sql.NullInt64{Int64: 100, Valid: true}, tokensOut: sql.NullInt64{Int64: 7, Valid: true}, + errText: llm.ErrTimeout.Error(), + }, + } { + t.Run(tc.name, func(t *testing.T) { + var f llm.Fake + f.QueueGenerate(tc.script...) + cfg := testConfig(t, &f) + before := store.Now() + _, runErr := Run(context.Background(), cfg, tc.skill, echoInput{Word: "taco"}) + if (runErr == nil) != (tc.status == StatusOK || tc.status == StatusRepaired) { + t.Fatalf("Run err = %v for status %s", runErr, tc.status) + } + assertCalls(t, &f, tc.turns) + + rows := runRows(t, cfg.Store) + if len(rows) != 1 { + t.Fatalf("%d ai_runs rows, want 1", len(rows)) + } + r := rows[0] + if r.Status != string(tc.status) || r.Skill != "echo" || r.SkillVersion != "1" || + r.Provider != "anthropic" || r.Model != "claude-test" || r.Temperature != 0.7 { + t.Fatalf("row = %+v", r) + } + if !r.LatencyMs.Valid || r.LatencyMs.Int64 < 0 { + t.Fatalf("latency_ms = %+v", r.LatencyMs) + } + if r.TokensIn != tc.tokensIn || r.TokensOut != tc.tokensOut { + t.Fatalf("tokens = %+v/%+v, want %+v/%+v", r.TokensIn, r.TokensOut, tc.tokensIn, tc.tokensOut) + } + if tc.errText == "" && r.Error.Valid { + t.Fatalf("error = %q, want NULL", r.Error.String) + } + if tc.errText != "" && !strings.Contains(r.Error.String, tc.errText) { + t.Fatalf("error = %q, want it to hold %q", r.Error.String, tc.errText) + } + var created store.Timestamp + if err := created.Scan(r.CreatedAt); err != nil || created.Before(before.Time) { + t.Fatalf("created_at = %q (%v), want at or after %s", r.CreatedAt, err, before) + } + + var reqs []loggedRequest + if err := json.Unmarshal([]byte(r.Request), &reqs); err != nil || len(reqs) != tc.turns { + t.Fatalf("request_redacted = %s (%v), want %d turns", r.Request, err, tc.turns) + } + if reqs[0].SchemaName != "echo" || reqs[0].Messages[0].Content != "Repeat: taco" || *reqs[0].Temperature != 0.7 { + t.Fatalf("first request = %+v", reqs[0]) + } + if tc.turns == 2 && (len(reqs[1].Messages) != 3 || !strings.Contains(reqs[1].Messages[2].Content, "not usable")) { + t.Fatalf("repair request = %+v", reqs[1]) + } + var resps []loggedResponse + if err := json.Unmarshal([]byte(r.Response.String), &resps); err != nil || len(resps) != tc.turns { + t.Fatalf("response_redacted = %s (%v), want %d turns", r.Response.String, err, tc.turns) + } + if tc.status == StatusProviderError && resps[tc.turns-1].Error != r.Error.String { + t.Fatalf("last response error = %q, want %q", resps[tc.turns-1].Error, r.Error.String) + } + }) + } +} + +func TestRunRowPerRun(t *testing.T) { + var f llm.Fake + cfg := testConfig(t, &f) + f.QueueGenerate(reply(`{"echo":"taco"}`), reply(`{"echo":"TACO"}`), reply(`{"echo":"taco"}`), llm.GenerateResult{Err: llm.ErrAuth}) + for range 3 { + _, _ = Run(context.Background(), cfg, echoSkill{}, echoInput{Word: "taco"}) + } + assertCalls(t, &f, 4) + var got []string + for _, r := range runRows(t, cfg.Store) { + got = append(got, r.Status) + } + if strings.Join(got, ",") != "ok,repaired,provider_error" { + t.Fatalf("statuses = %v, want ok,repaired,provider_error", got) + } +} + +func TestRunRecordsCancelledRun(t *testing.T) { + var f llm.Fake + cfg := testConfig(t, &f) + ctx, cancel := context.WithCancel(context.Background()) + cancel() + f.QueueGenerate(llm.GenerateResult{Err: context.Canceled}) + if _, err := Run(ctx, cfg, echoSkill{}, echoInput{Word: "taco"}); !errors.Is(err, context.Canceled) { + t.Fatalf("err = %v, want context.Canceled", err) + } + if rows := runRows(t, cfg.Store); len(rows) != 1 || rows[0].Status != string(StatusProviderError) { + t.Fatalf("rows = %+v, want one provider_error row", rows) + } +} + +func TestRunFailsWhenRowCannotBeWritten(t *testing.T) { + var f llm.Fake + cfg := testConfig(t, &f) + cfg.ProviderName = "gemini" // refused by the provider CHECK + f.QueueGenerate(reply(`{"echo":"taco"}`)) + _, err := Run(context.Background(), cfg, echoSkill{}, echoInput{Word: "taco"}) + if err == nil || !strings.Contains(err.Error(), "record ai_runs row") { + t.Fatalf("err = %v, want the row write failure", err) + } +} + +// The seeded secrets. The key and the webhook are what the household +// stores; the rest are credentials a reply or error may quote. +const ( + seededKey = "sk-seeded-0123456789abcdef" + seededWebhook = "https://chat.googleapis.com/v1/spaces/AAAAkitchen/messages?key=WEBHOOKKEY42&token=WEBHOOKTOKEN42" + seededBearer = "BEARERTOKEN42" + seededHeader = "HEADERKEY42" + seededURLKey = "URLKEY42" +) + +var seededSecrets = []string{seededKey, seededWebhook, "WEBHOOKKEY42", "WEBHOOKTOKEN42", "AAAAkitchen", seededBearer, seededHeader, seededURLKey} + +func TestRunRowsHoldNoSecrets(t *testing.T) { + // leaky quotes every seeded credential the way a model or vendor + // might, including the key inside a longer token. + leaky := "key " + seededKey + " webhook " + seededWebhook + + "\nAuthorization: Bearer " + seededBearer + + "\nx-api-key: " + seededHeader + + "\nsee https://maps.example.com/api?api_key=" + seededURLKey + "&q=tacos" + + " and xx" + seededKey + "yy" + leakyJSON, err := json.Marshal(map[string]string{"echo": leaky}) + if err != nil { + t.Fatal(err) + } + for name, script := range map[string][]llm.GenerateResult{ + "repaired": { + {Response: llm.Response{Text: leaky, JSON: leakyJSON, Model: seededKey}}, + reply(`{"echo":"taco"}`), + }, + "bad output": { + {Response: llm.Response{Text: leaky}, Err: fmt.Errorf("%w: %s", llm.ErrBadOutput, leaky)}, + {Response: llm.Response{Text: leaky, JSON: leakyJSON}}, + }, + "provider error": { + {Err: llm.NewProviderError(500, []byte(leaky), "")}, + }, + "provider error on repair": { + reply(`{"echo":"TACO"}`), + {Err: errors.New(leaky)}, + }, + } { + t.Run(name, func(t *testing.T) { + var f llm.Fake + f.QueueGenerate(script...) + cfg := testConfig(t, &f) + cfg.APIKey = seededKey + cfg.Persona = "Our kitchen. " + leaky + _, _ = Run(context.Background(), cfg, echoSkill{}, echoInput{Word: "tacos " + seededWebhook}) + assertCalls(t, &f, len(script)) + + rows := runRows(t, cfg.Store) + if len(rows) != 1 { + t.Fatalf("%d ai_runs rows, want 1", len(rows)) + } + text := rows[0].text() + for _, s := range seededSecrets { + if strings.Contains(text, s) { + t.Errorf("stored row holds %q:\n%s", s, text) + } + } + for _, kept := range []string{"Our kitchen.", "Repeat: tacos", redactionMarker} { + if !strings.Contains(text, kept) { + t.Errorf("stored row lacks %q:\n%s", kept, text) + } + } + }) + } +} + +func TestRedact(t *testing.T) { + const key = "sk-abc123" + for _, tc := range []struct{ in, want string }{ + {"key sk-abc123 here", "key [REDACTED] here"}, + {"Authorization: Bearer xyz.789\nnext", "Authorization: [REDACTED]\nnext"}, + {"proxy-authorization: Basic Zm9v", "proxy-authorization: [REDACTED]"}, + {`{"Authorization":"Bearer xyz","a":1}`, `{"Authorization":"[REDACTED]","a":1}`}, + {`{"x-api-key": "abc", "b": 2}`, `{"b":2,"x-api-key":"[REDACTED]"}`}, + {`{"X-Api-Key":{"v":"abc"},"n":1.50}`, `{"X-Api-Key":"[REDACTED]","n":1.50}`}, + {`{"m":"see https://chat.googleapis.com/v1/spaces/A?key=k\u0026token=t\nAuthorization: Bearer xyz"}`, `{"m":"see [REDACTED]\nAuthorization: [REDACTED]"}`}, + {`["sk-abc\u0031\u0032\u0033", "{\"Authorization\":\"Bearer xyz\"}"]`, `["[REDACTED]","{\"Authorization\":\"[REDACTED]\"}"]`}, + {"{\"a\":1} trailing \\u0026 Authorization: x", "{\"a\":1} trailing \\u0026 Authorization: [REDACTED]"}, + {"nAuthorization: Bearer xyz", "nAuthorization: [REDACTED]"}, + {"X-Goog-Api-Key=abc&x=1", "X-Goog-Api-Key=[REDACTED]"}, + {"authorization failed, try again", "authorization failed, try again"}, + {"post to https://chat.googleapis.com/v1/spaces/A/messages?key=k&token=t now", "post to [REDACTED] now"}, + {"chat.googleapis.com/v1/spaces/A/messages?key=k", "[REDACTED]"}, + {"", "<[REDACTED]>"}, + {"https://maps.example.com/api?api_key=abc&q=1", "[REDACTED]"}, + {"https://example.com/x?q=1&access_token=abc", "[REDACTED]"}, + {"https://example.com/x?%6Bey=abc", "[REDACTED]"}, + {"https://example.com/x?%zz=abc", "[REDACTED]"}, + {"https://example.com/cb#access_token=abc", "[REDACTED]"}, + {"https://example.com/x?sig=abc;q=1", "[REDACTED]"}, + {"https://user:pw@example.com/x", "[REDACTED]"}, + {"https://www.allrecipes.com/recipe/123/chili?servings=4#step-2", "https://www.allrecipes.com/recipe/123/chili?servings=4#step-2"}, + {"mailto-ish user@example.com is fine", "mailto-ish user@example.com is fine"}, + {"https://example.com/a@b", "https://example.com/a@b"}, + {"sk-abcsk-abc123123", ""}, + } { + got := redact(tc.in, key) + if strings.Contains(got, key) { + t.Errorf("redact(%q) = %q holds the key", tc.in, got) + } + if tc.want != "" && got != tc.want { + t.Errorf("redact(%q) = %q, want %q", tc.in, got, tc.want) + } + } + if got := redact("plain text", ""); got != "plain text" { + t.Errorf("redact with no key = %q", got) + } +} + +func TestPurgeRemovesOnlyOldRows(t *testing.T) { + ctx := context.Background() + st := emptyHousehold(t) + now := time.Now().UTC().Truncate(time.Millisecond) + cutoff := now.Add(-RunRetention) + q := db.New(st.Writer) + insert := func(id string, created time.Time) { + t.Helper() + ts := store.Timestamp{Time: created}.String() + if err := q.CreateAIRun(ctx, db.CreateAIRunParams{ + ID: id, Skill: "echo", SkillVersion: "1", Provider: "anthropic", Model: "m", Temperature: 0.7, + Status: string(StatusOK), RequestRedacted: "[]", CreatedAt: ts, UpdatedAt: ts, + }); err != nil { + t.Fatal(err) + } + } + insert("old-year", now.Add(-365*24*time.Hour)) + insert("old-31d", now.Add(-31*24*time.Hour)) + insert("old-just", cutoff.Add(-time.Millisecond)) + insert("at-cutoff", cutoff) + insert("new-29d", now.Add(-29*24*time.Hour)) + insert("new-now", now) + for _, stmt := range []string{ + `INSERT INTO suggestion_batches (id, trigger, status, ai_run_id, created_at, updated_at) VALUES ('batch-old', 'manual', 'done', 'old-31d', 'c', 'u')`, + `INSERT INTO suggestion_batches (id, trigger, status, ai_run_id, created_at, updated_at) VALUES ('batch-new', 'manual', 'done', 'new-29d', 'c', 'u')`, + `INSERT INTO week_plans (id, week_start, status, ai_run_id, created_at, updated_at) VALUES ('plan-old', '2026-08-30', 'draft', 'old-year', 'c', 'u')`, + `INSERT INTO week_plans (id, week_start, status, ai_run_id, created_at, updated_at) VALUES ('plan-new', '2026-10-04', 'draft', 'new-now', 'c', 'u')`, + } { + if _, err := st.Writer.Exec(stmt); err != nil { + t.Fatal(err) + } + } + + n, err := Purge(ctx, st, cutoff) + if err != nil { + t.Fatal(err) + } + if n != 3 { + t.Fatalf("Purge deleted %d rows, want 3", n) + } + var ids []string + for _, r := range runRows(t, st) { + ids = append(ids, r.ID) + } + if got := strings.Join(ids, ","); got != "at-cutoff,new-29d,new-now" { + t.Fatalf("rows left = %s, want at-cutoff,new-29d,new-now", got) + } + for table, want := range map[string]string{ + "suggestion_batches": "batch-new=new-29d,batch-old=NULL", + "week_plans": "plan-new=new-now,plan-old=NULL", + } { + var got []string + rows, err := st.Reader.Query(`SELECT id || '=' || coalesce(ai_run_id, 'NULL') FROM ` + table + ` ORDER BY id`) + if err != nil { + t.Fatal(err) + } + for rows.Next() { + var s string + if err := rows.Scan(&s); err != nil { + t.Fatal(err) + } + got = append(got, s) + } + if err := rows.Close(); err != nil { + t.Fatal(err) + } + if strings.Join(got, ",") != want { + t.Errorf("%s references = %v, want %s", table, got, want) + } + } + + if n, err := Purge(ctx, st, cutoff); err != nil || n != 0 { + t.Fatalf("second Purge = %d, %v; want 0, nil", n, err) + } + if _, err := Purge(ctx, st, time.Time{}); err == nil { + t.Fatal("Purge with a zero cutoff succeeded") + } +} diff --git a/internal/db/ai_runs.sql.go b/internal/db/ai_runs.sql.go new file mode 100644 index 0000000..4e8b56f --- /dev/null +++ b/internal/db/ai_runs.sql.go @@ -0,0 +1,107 @@ +// Code generated by sqlc. DO NOT EDIT. +// versions: +// sqlc v1.31.1 +// source: ai_runs.sql + +package db + +import ( + "context" + "database/sql" +) + +const clearSuggestionBatchAIRunsBefore = `-- name: ClearSuggestionBatchAIRunsBefore :execrows +UPDATE suggestion_batches +SET ai_run_id = NULL +WHERE ai_run_id IN (SELECT ai_runs.id FROM ai_runs WHERE ai_runs.created_at < ?1) +` + +// Drops references to the runs created before the cutoff, so the purge +// can delete them. +func (q *Queries) ClearSuggestionBatchAIRunsBefore(ctx context.Context, cutoff string) (int64, error) { + result, err := q.db.ExecContext(ctx, clearSuggestionBatchAIRunsBefore, cutoff) + if err != nil { + return 0, err + } + return result.RowsAffected() +} + +const clearWeekPlanAIRunsBefore = `-- name: ClearWeekPlanAIRunsBefore :execrows +UPDATE week_plans +SET ai_run_id = NULL +WHERE ai_run_id IN (SELECT ai_runs.id FROM ai_runs WHERE ai_runs.created_at < ?1) +` + +// Drops references to the runs created before the cutoff, so the purge +// can delete them. +func (q *Queries) ClearWeekPlanAIRunsBefore(ctx context.Context, cutoff string) (int64, error) { + result, err := q.db.ExecContext(ctx, clearWeekPlanAIRunsBefore, cutoff) + if err != nil { + return 0, err + } + return result.RowsAffected() +} + +const createAIRun = `-- name: CreateAIRun :exec +INSERT INTO ai_runs ( + id, skill, skill_version, provider, model, temperature, status, + latency_ms, tokens_in, tokens_out, error, request_redacted, + response_redacted, created_at, updated_at +) VALUES ( + ?, ?, ?, ?, ?, ?, ?, + ?, ?, ?, ?, ?, + ?, ?, ? +) +` + +type CreateAIRunParams struct { + ID string + Skill string + SkillVersion string + Provider string + Model string + Temperature float64 + Status string + LatencyMs sql.NullInt64 + TokensIn sql.NullInt64 + TokensOut sql.NullInt64 + Error sql.NullString + RequestRedacted string + ResponseRedacted sql.NullString + CreatedAt string + UpdatedAt string +} + +func (q *Queries) CreateAIRun(ctx context.Context, arg CreateAIRunParams) error { + _, err := q.db.ExecContext(ctx, createAIRun, + arg.ID, + arg.Skill, + arg.SkillVersion, + arg.Provider, + arg.Model, + arg.Temperature, + arg.Status, + arg.LatencyMs, + arg.TokensIn, + arg.TokensOut, + arg.Error, + arg.RequestRedacted, + arg.ResponseRedacted, + arg.CreatedAt, + arg.UpdatedAt, + ) + return err +} + +const deleteAIRunsBefore = `-- name: DeleteAIRunsBefore :execrows +DELETE FROM ai_runs +WHERE created_at < ?1 +` + +func (q *Queries) DeleteAIRunsBefore(ctx context.Context, cutoff string) (int64, error) { + result, err := q.db.ExecContext(ctx, deleteAIRunsBefore, cutoff) + if err != nil { + return 0, err + } + return result.RowsAffected() +} diff --git a/internal/db/querier.go b/internal/db/querier.go index c586bb2..825889c 100644 --- a/internal/db/querier.go +++ b/internal/db/querier.go @@ -15,11 +15,19 @@ type Querier interface { // Marks the oldest queued job running and returns it. Returns sql.ErrNoRows // when no job is queued. ClaimNextJob(ctx context.Context, now sql.NullString) (Job, error) + // Drops references to the runs created before the cutoff, so the purge + // can delete them. + ClearSuggestionBatchAIRunsBefore(ctx context.Context, cutoff string) (int64, error) + // Drops references to the runs created before the cutoff, so the purge + // can delete them. + ClearWeekPlanAIRunsBefore(ctx context.Context, cutoff string) (int64, error) + CreateAIRun(ctx context.Context, arg CreateAIRunParams) error CreateDinner(ctx context.Context, arg CreateDinnerParams) (Dinner, error) CreateJob(ctx context.Context, arg CreateJobParams) error CreatePhoto(ctx context.Context, arg CreatePhotoParams) (Photo, error) CreateRecipeIngredient(ctx context.Context, arg CreateRecipeIngredientParams) error CreateRecipeStep(ctx context.Context, arg CreateRecipeStepParams) error + DeleteAIRunsBefore(ctx context.Context, cutoff string) (int64, error) DeleteRecipeIngredients(ctx context.Context, recipeID string) error DeleteRecipeSteps(ctx context.Context, recipeID string) error FailJob(ctx context.Context, arg FailJobParams) (int64, error) diff --git a/internal/store/migrate_test.go b/internal/store/migrate_test.go index 624f17e..fa10f79 100644 --- a/internal/store/migrate_test.go +++ b/internal/store/migrate_test.go @@ -175,8 +175,8 @@ func TestMigrateEmbeddedMigrations(t *testing.T) { if err := Migrate(context.Background(), s.Writer, migrations.FS); err != nil { t.Fatal(err) } - if got := versions(migrationRows(t, s)); got != "0000_bootstrap,0001_init,0002_household_settings_updated_by,0003_jobs_status,0004_ai_provider_presets,0005_ai_provider_xai" { - t.Errorf("versions = %q, want 0000_bootstrap,0001_init,0002_household_settings_updated_by,0003_jobs_status,0004_ai_provider_presets,0005_ai_provider_xai", got) + if got := versions(migrationRows(t, s)); got != "0000_bootstrap,0001_init,0002_household_settings_updated_by,0003_jobs_status,0004_ai_provider_presets,0005_ai_provider_xai,0006_ai_runs_status" { + t.Errorf("versions = %q, want 0000_bootstrap,0001_init,0002_household_settings_updated_by,0003_jobs_status,0004_ai_provider_presets,0005_ai_provider_xai,0006_ai_runs_status", got) } } @@ -196,8 +196,8 @@ func TestMigrateBootstrapThenEmbeddedInitApplies(t *testing.T) { if err := Migrate(ctx, s.Writer, migrations.FS); err != nil { t.Fatal(err) } - if got := versions(migrationRows(t, s)); got != "0000_bootstrap,0001_init,0002_household_settings_updated_by,0003_jobs_status,0004_ai_provider_presets,0005_ai_provider_xai" { - t.Errorf("versions = %q, want 0000_bootstrap,0001_init,0002_household_settings_updated_by,0003_jobs_status,0004_ai_provider_presets,0005_ai_provider_xai", got) + if got := versions(migrationRows(t, s)); got != "0000_bootstrap,0001_init,0002_household_settings_updated_by,0003_jobs_status,0004_ai_provider_presets,0005_ai_provider_xai,0006_ai_runs_status" { + t.Errorf("versions = %q, want 0000_bootstrap,0001_init,0002_household_settings_updated_by,0003_jobs_status,0004_ai_provider_presets,0005_ai_provider_xai,0006_ai_runs_status", got) } if !tableExists(t, s, "dinners") { t.Error("table from 0001_init was not created") @@ -486,3 +486,74 @@ func TestMigrateAIProviderXAIKeepsRowsAndReferences(t *testing.T) { } } } + +// TestMigrateAIRunsStatus upgrades a database at 0005 and checks 0006 +// keeps an ok run and its references, accepts every harness outcome, and +// stops on a run with a pre-harness status rather than guess its outcome. +func TestMigrateAIRunsStatus(t *testing.T) { + ctx := context.Background() + before := fstest.MapFS{} + for _, name := range []string{"0000_bootstrap.sql", "0001_init.sql", "0002_household_settings_updated_by.sql", "0003_jobs_status.sql", "0004_ai_provider_presets.sql", "0005_ai_provider_xai.sql"} { + body, err := fs.ReadFile(migrations.FS, name) + if err != nil { + t.Fatal(err) + } + before[name] = &fstest.MapFile{Data: body} + } + seedRun := func(t *testing.T, s *Store, status string) { + t.Helper() + if err := Migrate(ctx, s.Writer, before); err != nil { + t.Fatal(err) + } + for _, stmt := range []string{ + `INSERT INTO ai_runs (id, skill, skill_version, provider, model, temperature, status, latency_ms, tokens_in, tokens_out, error, request_redacted, response_redacted, created_at, updated_at) + VALUES ('run-1', 'suggest', '1', 'xai', 'grok', 0.5, '` + status + `', 10, 20, 30, 'e', 'req', 'resp', 'c', 'u')`, + `INSERT INTO suggestion_batches (id, trigger, status, ai_run_id, created_at, updated_at) + VALUES ('batch-1', 'manual', 'done', 'run-1', 'c', 'u')`, + } { + if _, err := s.Writer.Exec(stmt); err != nil { + t.Fatalf("seed: %v", err) + } + } + } + + t.Run("ok row kept", func(t *testing.T) { + s := openTestStore(t) + seedRun(t, s, "ok") + if err := Migrate(ctx, s.Writer, migrations.FS); err != nil { + t.Fatal(err) + } + var status, request string + if err := s.Reader.QueryRow(`SELECT status, request_redacted FROM ai_runs WHERE id = 'run-1'`).Scan(&status, &request); err != nil { + t.Fatal(err) + } + if status != "ok" || request != "req" { + t.Errorf("ai_runs row = %s, %s; want ok, req", status, request) + } + if _, err := s.Writer.Exec(`DELETE FROM ai_runs WHERE id = 'run-1'`); err == nil || !strings.Contains(err.Error(), "FOREIGN KEY constraint failed") { + t.Errorf("deleting a referenced ai_run: error %v, want FOREIGN KEY constraint failure", err) + } + for _, status := range []string{"repaired", "bad_output", "provider_error", "ok"} { + if _, err := s.Writer.Exec(`UPDATE ai_runs SET status = ? WHERE id = 'run-1'`, status); err != nil { + t.Errorf("ai_runs.status %s rejected: %v", status, err) + } + } + if tableExists(t, s, "ai_runs_copy") { + t.Error("ai_runs_copy left behind") + } + }) + + for _, legacy := range []string{"running", "error"} { + t.Run(legacy+" row stops the migration", func(t *testing.T) { + s := openTestStore(t) + seedRun(t, s, legacy) + if err := Migrate(ctx, s.Writer, migrations.FS); err == nil || !strings.Contains(err.Error(), "CHECK constraint failed") { + t.Fatalf("Migrate error = %v, want a CHECK constraint failure", err) + } + var status string + if err := s.Reader.QueryRow(`SELECT status FROM ai_runs WHERE id = 'run-1'`).Scan(&status); err != nil || status != legacy { + t.Errorf("after the failed migration status = %q, %v; want %q kept", status, err, legacy) + } + }) + } +} diff --git a/internal/store/schema_test.go b/internal/store/schema_test.go index a5651bf..eb735b8 100644 --- a/internal/store/schema_test.go +++ b/internal/store/schema_test.go @@ -307,6 +307,8 @@ func TestSchemaEnumChecksRejectInvalidValues(t *testing.T) { {"household_settings", "chat_autosend_dow", 3.5}, {"ai_runs", "provider", "gemini"}, {"ai_runs", "status", "done"}, + {"ai_runs", "status", "running"}, + {"ai_runs", "status", "error"}, {"dinners", "status", "deck"}, {"dinners", "origin", "ai"}, {"dinners", "method", "microwave"}, diff --git a/migrations/0006_ai_runs_status.sql b/migrations/0006_ai_runs_status.sql new file mode 100644 index 0000000..fa325bd --- /dev/null +++ b/migrations/0006_ai_runs_status.sql @@ -0,0 +1,47 @@ +-- 0006_ai_runs_status: ai_runs.status becomes the harness run outcome: +-- ok the first reply was usable +-- repaired the first reply was not, the repair turn's was +-- bad_output neither reply was usable, or post-processing failed +-- provider_error the provider failed on either turn +-- A run's row is written once, when it ends, so there is no running state. +-- Nothing wrote ai_runs before the harness did, so no row holds the old +-- running or error values; if one does, the copy back fails the CHECK and +-- the migration stops rather than guess its outcome. created_at gains an +-- index for the 30-day purge. The rebuild is 0005's: copy the rows aside, +-- drop the table, create it again, copy the rows back and drop the copy. +-- +-- suggestion_batches.ai_run_id and week_plans.ai_run_id reference ai_runs, +-- so foreign keys are deferred until commit, after the ai_runs rows are +-- back. The pragma lasts only for this migration's transaction. + +PRAGMA defer_foreign_keys = ON; + +CREATE TABLE ai_runs_copy AS SELECT * FROM ai_runs; + +DROP TABLE ai_runs; + +CREATE TABLE ai_runs ( + id TEXT NOT NULL PRIMARY KEY, + skill TEXT NOT NULL, + skill_version TEXT NOT NULL, + provider TEXT NOT NULL CHECK (provider IN ('openai_compatible', 'anthropic', 'ollama', 'openai', 'openrouter', 'xai')), + model TEXT NOT NULL, + temperature REAL NOT NULL, + status TEXT NOT NULL CHECK (status IN ('ok', 'repaired', 'bad_output', 'provider_error')), + latency_ms INTEGER, + tokens_in INTEGER, + tokens_out INTEGER, + error TEXT, + request_redacted TEXT NOT NULL, + response_redacted TEXT, + created_at TEXT NOT NULL, + updated_at TEXT NOT NULL +); + +INSERT INTO ai_runs (id, skill, skill_version, provider, model, temperature, status, latency_ms, tokens_in, tokens_out, error, request_redacted, response_redacted, created_at, updated_at) +SELECT id, skill, skill_version, provider, model, temperature, status, latency_ms, tokens_in, tokens_out, error, request_redacted, response_redacted, created_at, updated_at +FROM ai_runs_copy; + +DROP TABLE ai_runs_copy; + +CREATE INDEX ai_runs_created_at ON ai_runs (created_at); diff --git a/migrations/queries/ai_runs.sql b/migrations/queries/ai_runs.sql new file mode 100644 index 0000000..d199e55 --- /dev/null +++ b/migrations/queries/ai_runs.sql @@ -0,0 +1,28 @@ +-- name: CreateAIRun :exec +INSERT INTO ai_runs ( + id, skill, skill_version, provider, model, temperature, status, + latency_ms, tokens_in, tokens_out, error, request_redacted, + response_redacted, created_at, updated_at +) VALUES ( + ?, ?, ?, ?, ?, ?, ?, + ?, ?, ?, ?, ?, + ?, ?, ? +); + +-- name: ClearSuggestionBatchAIRunsBefore :execrows +-- Drops references to the runs created before the cutoff, so the purge +-- can delete them. +UPDATE suggestion_batches +SET ai_run_id = NULL +WHERE ai_run_id IN (SELECT ai_runs.id FROM ai_runs WHERE ai_runs.created_at < sqlc.arg(cutoff)); + +-- name: ClearWeekPlanAIRunsBefore :execrows +-- Drops references to the runs created before the cutoff, so the purge +-- can delete them. +UPDATE week_plans +SET ai_run_id = NULL +WHERE ai_run_id IN (SELECT ai_runs.id FROM ai_runs WHERE ai_runs.created_at < sqlc.arg(cutoff)); + +-- name: DeleteAIRunsBefore :execrows +DELETE FROM ai_runs +WHERE created_at < sqlc.arg(cutoff); -- 2.55.0 From 6a7c040657dc25bc088193405bc37880f5742b7b Mon Sep 17 00:00:00 2001 From: dev_agent Date: Mon, 5 Oct 2026 09:43:24 -0400 Subject: [PATCH 2/2] Build the run's provider from the key it redacts; record render failures Review findings on b0cf6fb: 1. Config took a ready-made Provider and a separate, optional APIKey used only for redaction, so a provider holding a decrypted key could run with APIKey empty and a reply quoting that key unlabelled was stored. Config now holds the household's llm.Settings, the decrypted APIKey and a NewProvider constructor (presets.FromSettings in production). Run builds the provider from exactly that key and redacts the same key, so the two cannot differ. ProviderName, Model and Temperature come from Settings. A new test runs presets.FromSettings against a server that echoes the bearer key unlabelled in the reply text, reply JSON and model name, across a repair turn, and asserts the stored row never holds it; with redaction disabled the test fails. 2. A render failure wrote no ai_runs row. Every run with a valid Config now writes one: a render failure is bad_output and a provider that cannot be built is provider_error, each with the error text and empty request and response lists. TestRunRenderError now expects exactly one such row. A Config error (no store, provider name or model) still writes none, since the row cannot be written without them. Redaction rules, the four statuses for provider-reaching runs (one row, both turns) and Purge are unchanged. Maestro task 53e382d8-1db3-4555-a31d-e44cf55cc98d. Co-Authored-By: Claude Opus 5.5 --- docs/ARCHITECTURE.md | 10 ++- internal/ai/harness/harness.go | 101 ++++++++++++++++------------ internal/ai/harness/harness_test.go | 42 +++++++++--- internal/ai/harness/runs.go | 26 ++++--- internal/ai/harness/runs_test.go | 68 ++++++++++++++++++- 5 files changed, 184 insertions(+), 63 deletions(-) diff --git a/docs/ARCHITECTURE.md b/docs/ARCHITECTURE.md index a7c0857..8d3cc87 100644 --- a/docs/ARCHITECTURE.md +++ b/docs/ARCHITECTURE.md @@ -150,9 +150,13 @@ automatic** (D-021). Anthropic and Ollama endpoints, called over plain HTTP — no vendor SDKs. - **Skill harness** (`ai/harness`): prompt layering, validation of the structured output, and **one repair retry**; if the repair also fails the - run fails — no silent fallback. Every run that reaches the provider writes - one `ai_runs` row when it ends, covering the repair turn too, with status - `ok`, `repaired`, `bad_output` or `provider_error`. Request and response + run fails — no silent fallback. Every run writes one `ai_runs` row when it + ends, covering the repair turn too, with status `ok`, `repaired`, + `bad_output` or `provider_error`; a prompt that cannot be rendered is + `bad_output` and a provider that cannot be built is `provider_error`, both + with no turns. The harness builds the provider itself from the settings + and the decrypted API key (`presets.FromSettings`), so the key it redacts + is always the key the provider sends. Request and response bodies are redacted before they are stored: the decrypted API key, Authorization and API-key header values, Google Chat webhook URLs and URLs with key-like query parameters are removed, inside JSON strings too. diff --git a/internal/ai/harness/harness.go b/internal/ai/harness/harness.go index fa52e9d..5ad82d1 100644 --- a/internal/ai/harness/harness.go +++ b/internal/ai/harness/harness.go @@ -4,8 +4,7 @@ // for output matching the skill's schema, decodes and validates the reply, // and on failure sends exactly one repair turn quoting the problems. If the // repair fails too the run fails with llm.ErrBadOutput; there is no silent -// fallback (D-007). Every run that reaches the provider is recorded in -// ai_runs (see Run and Purge). +// fallback (D-007). Every run is recorded in ai_runs (see Run and Purge). package harness import ( @@ -42,23 +41,26 @@ type Skill[In, Out any] interface { PostProcess(out Out) (Out, error) } +// NewProvider builds the provider a run sends its requests to from the +// household's settings and decrypted API key. In production it is +// presets.FromSettings. +type NewProvider func(s llm.Settings, key string) (llm.Provider, error) + // Config is what a run needs from the household's AI settings. type Config struct { - // Provider answers the requests. - Provider llm.Provider + // Settings is the household's AI configuration. Settings.Provider and + // Settings.Model are recorded in ai_runs and may not be empty; + // Settings.Temperature is sent with every request. + Settings llm.Settings + // APIKey is the decrypted API key, or "" for a provider that takes + // none. It reaches the provider only through NewProvider, and every + // occurrence of it is removed from the ai_runs row. + APIKey string + // NewProvider builds the run's provider from Settings and APIKey. + NewProvider NewProvider // Persona is ai_settings.system_prompt, the first layer of every // system prompt; empty means none. Persona string - // Temperature is the household's sampling temperature, sent with - // every request. - Temperature float64 - // ProviderName is ai_settings.provider and Model is ai_settings.model, - // both recorded in ai_runs. Neither may be empty. - ProviderName string - Model string - // APIKey is the decrypted API key Provider sends, or "" when it sends - // none. It is used only to remove the key from the ai_runs row. - APIKey string // Store receives the run's ai_runs row. It must not be nil. Store *store.Store } @@ -66,11 +68,11 @@ type Config struct { // validate reports a Config missing what every run needs. func (c Config) validate() error { switch { - case c.Provider == nil: - return errors.New("config has no provider") - case c.ProviderName == "": + case c.NewProvider == nil: + return errors.New("config has no provider constructor") + case c.Settings.Provider == "": return errors.New("config has no provider name") - case c.Model == "": + case c.Settings.Model == "": return errors.New("config has no model") case c.Store == nil: return errors.New("config has no store") @@ -101,31 +103,21 @@ func (e *BadOutputError) Unwrap() error { return llm.ErrBadOutput } // output. A provider error other than llm.ErrBadOutput is returned // unchanged and never repaired. // -// Every run that sends a request writes one ai_runs row when it ends, +// Every run with a valid Config writes one ai_runs row when it ends, // covering both turns, with its RunStatus and the request and response -// bodies redacted (see redact). A Config or render error fails the run -// before any request, and writes no row. When the row cannot be written -// the run fails with that error too, even if its output was usable. +// bodies redacted (see redact). A render failure is recorded as +// StatusBadOutput and a provider that cannot be built as +// StatusProviderError, both with no turns. A Config error fails the run +// before anything else, and writes no row since the row cannot be +// written without one. When the row cannot be written the run fails with +// that error too, even if its output was usable. func Run[In, Out any](ctx context.Context, cfg Config, s Skill[In, Out], in In) (Out, error) { var zero Out if err := cfg.validate(); err != nil { return zero, fmt.Errorf("harness: skill %s v%d: %w", s.Name(), s.Version(), err) } - prompt, err := Render(cfg.Persona, s, in) - if err != nil { - return zero, fmt.Errorf("harness: skill %s v%d: render: %w", s.Name(), s.Version(), err) - } - schema := s.Schema() - temperature := cfg.Temperature - req := llm.Request{ - System: prompt.System, - Messages: []llm.Message{{Role: llm.RoleUser, Content: prompt.User}}, - Temperature: &temperature, - Schema: &schema, - } - log := &runLog{start: store.Now()} - out, status, err := turns(ctx, cfg, s, req, log) + out, status, err := execute(ctx, cfg, s, in, log) if saveErr := log.save(ctx, cfg, s.Name(), s.Version(), status, err); saveErr != nil { return zero, errors.Join(err, fmt.Errorf("harness: skill %s v%d: record ai_runs row: %w", s.Name(), s.Version(), saveErr)) } @@ -135,11 +127,34 @@ func Run[In, Out any](ctx context.Context, cfg Config, s Skill[In, Out], in In) return out, nil } +// execute renders the prompt, builds the provider and sends the turns, +// recording them in log. It returns the run's status alongside its result. +func execute[In, Out any](ctx context.Context, cfg Config, s Skill[In, Out], in In, log *runLog) (Out, RunStatus, error) { + var zero Out + prompt, err := Render(cfg.Persona, s, in) + if err != nil { + return zero, StatusBadOutput, fmt.Errorf("harness: skill %s v%d: render: %w", s.Name(), s.Version(), err) + } + provider, err := cfg.NewProvider(cfg.Settings, cfg.APIKey) + if err != nil { + return zero, StatusProviderError, fmt.Errorf("harness: skill %s v%d: provider: %w", s.Name(), s.Version(), err) + } + schema := s.Schema() + temperature := cfg.Settings.Temperature + req := llm.Request{ + System: prompt.System, + Messages: []llm.Message{{Role: llm.RoleUser, Content: prompt.User}}, + Temperature: &temperature, + Schema: &schema, + } + return turns(ctx, cfg.APIKey, provider, s, req, log) +} + // turns sends req and, when its reply is unusable, the repair turn, // recording both in log. It returns the run's status alongside its result. -func turns[In, Out any](ctx context.Context, cfg Config, s Skill[In, Out], req llm.Request, log *runLog) (Out, RunStatus, error) { +func turns[In, Out any](ctx context.Context, apiKey string, provider llm.Provider, s Skill[In, Out], req llm.Request, log *runLog) (Out, RunStatus, error) { var zero Out - out, reply, first, status, err := attempt(ctx, cfg, s, req, log) + out, reply, first, status, err := attempt(ctx, apiKey, provider, s, req, log) if err != nil { return zero, status, err } @@ -151,7 +166,7 @@ func turns[In, Out any](ctx context.Context, cfg Config, s Skill[In, Out], req l req.Messages = append(req.Messages, llm.Message{Role: llm.RoleAssistant, Content: reply}) } req.Messages = append(req.Messages, llm.Message{Role: llm.RoleUser, Content: repairMessage(req.Schema.Name, first)}) - out, _, second, status, err := attempt(ctx, cfg, s, req, log) + out, _, second, status, err := attempt(ctx, apiKey, provider, s, req, log) if err != nil { return zero, status, err } @@ -161,14 +176,14 @@ func turns[In, Out any](ctx context.Context, cfg Config, s Skill[In, Out], req l return out, StatusRepaired, nil } -// attempt sends req once, records the turn in log, then decodes, +// attempt sends req to provider once, records the turn in log, then decodes, // validates, post-processes and validates the reply again. It returns the // reply for the repair turn and the problems found; err is set only for a // provider or post-process failure, neither of which is repairable, and // status then says which. -func attempt[In, Out any](ctx context.Context, cfg Config, s Skill[In, Out], req llm.Request, log *runLog) (out Out, reply string, problems []string, status RunStatus, err error) { - resp, err := cfg.Provider.Generate(ctx, req) - log.add(cfg.APIKey, req, resp, err) +func attempt[In, Out any](ctx context.Context, apiKey string, provider llm.Provider, s Skill[In, Out], req llm.Request, log *runLog) (out Out, reply string, problems []string, status RunStatus, err error) { + resp, err := provider.Generate(ctx, req) + log.add(apiKey, req, resp, err) // The repair turn must quote what failed: the structured output when // there is any, otherwise the text. reply = string(resp.JSON) diff --git a/internal/ai/harness/harness_test.go b/internal/ai/harness/harness_test.go index 1c0ad9f..9e0470b 100644 --- a/internal/ai/harness/harness_test.go +++ b/internal/ai/harness/harness_test.go @@ -15,10 +15,15 @@ func reply(js string) llm.GenerateResult { return llm.GenerateResult{Response: llm.Response{Text: js, JSON: json.RawMessage(js)}} } -// testConfig returns a Config for f recording into a fresh migrated store. +// testConfig returns a Config whose provider is f, recording into a fresh +// migrated store. func testConfig(t *testing.T, f *llm.Fake) Config { t.Helper() - return Config{Provider: f, Temperature: 0.7, ProviderName: "anthropic", Model: "claude-test", Store: emptyHousehold(t)} + return Config{ + Settings: llm.Settings{Provider: "anthropic", Model: "claude-test", Temperature: 0.7}, + NewProvider: func(llm.Settings, string) (llm.Provider, error) { return f, nil }, + Store: emptyHousehold(t), + } } func run(t *testing.T, f *llm.Fake) (echoOutput, error) { @@ -215,8 +220,29 @@ func TestRunRenderError(t *testing.T) { t.Fatalf("err = %v, want a render error", err) } assertCalls(t, &f, 0) - if rows := runRows(t, cfg.Store); len(rows) != 0 { - t.Fatalf("render error wrote %d ai_runs rows, want none", len(rows)) + rows := runRows(t, cfg.Store) + if len(rows) != 1 { + t.Fatalf("render error wrote %d ai_runs rows, want 1", len(rows)) + } + r := rows[0] + if r.Status != string(StatusBadOutput) || r.Error.String != err.Error() || + r.Request != "[]" || r.Response.String != "[]" || r.TokensIn.Valid || r.TokensOut.Valid { + t.Fatalf("row = %+v, want bad_output with the render error and no turns", r) + } +} + +func TestRunProviderBuildError(t *testing.T) { + var f llm.Fake + cfg := testConfig(t, &f) + cfg.NewProvider = func(llm.Settings, string) (llm.Provider, error) { return nil, llm.ErrMissingKey } + _, err := Run(context.Background(), cfg, echoSkill{}, echoInput{Word: "taco"}) + if !errors.Is(err, llm.ErrMissingKey) { + t.Fatalf("err = %v, want ErrMissingKey", err) + } + rows := runRows(t, cfg.Store) + if len(rows) != 1 || rows[0].Status != string(StatusProviderError) || + rows[0].Error.String != err.Error() || rows[0].Request != "[]" { + t.Fatalf("rows = %+v, want one provider_error row with no turns", rows) } } @@ -224,10 +250,10 @@ func TestRunConfigError(t *testing.T) { var f llm.Fake full := testConfig(t, &f) for name, edit := range map[string]func(*Config){ - "provider": func(c *Config) { c.Provider = nil }, - "provider name": func(c *Config) { c.ProviderName = "" }, - "model": func(c *Config) { c.Model = "" }, - "store": func(c *Config) { c.Store = nil }, + "provider constructor": func(c *Config) { c.NewProvider = nil }, + "provider name": func(c *Config) { c.Settings.Provider = "" }, + "model": func(c *Config) { c.Settings.Model = "" }, + "store": func(c *Config) { c.Store = nil }, } { t.Run(name, func(t *testing.T) { cfg := full diff --git a/internal/ai/harness/runs.go b/internal/ai/harness/runs.go index 9b13bd4..fb12141 100644 --- a/internal/ai/harness/runs.go +++ b/internal/ai/harness/runs.go @@ -26,10 +26,11 @@ const ( // StatusRepaired means the first reply was not usable and the reply to // the repair turn was. StatusRepaired RunStatus = "repaired" - // StatusBadOutput means neither reply was usable, or post-processing - // a valid reply failed. + // StatusBadOutput means neither reply was usable, post-processing a + // valid reply failed, or the skill's prompt could not be rendered. StatusBadOutput RunStatus = "bad_output" - // StatusProviderError means the provider failed on either turn. + // StatusProviderError means the provider could not be built or failed + // on either turn. StatusProviderError RunStatus = "provider_error" ) @@ -140,11 +141,12 @@ func (l *runLog) add(apiKey string, req llm.Request, resp llm.Response, err erro // save writes the run's ai_runs row. It is written even when ctx is done, // so a cancelled run is recorded too. func (l *runLog) save(ctx context.Context, cfg Config, skill string, version int, status RunStatus, runErr error) error { - request, err := marshalRedacted(l.requests, cfg.APIKey) + // A run that failed before its first turn stores an empty list. + request, err := marshalRedacted(nonNil(l.requests), cfg.APIKey) if err != nil { return err } - response, err := marshalRedacted(l.responses, cfg.APIKey) + response, err := marshalRedacted(nonNil(l.responses), cfg.APIKey) if err != nil { return err } @@ -160,9 +162,9 @@ func (l *runLog) save(ctx context.Context, cfg Config, skill string, version int ID: store.NewID(), Skill: skill, SkillVersion: strconv.Itoa(version), - Provider: cfg.ProviderName, - Model: cfg.Model, - Temperature: cfg.Temperature, + Provider: cfg.Settings.Provider, + Model: cfg.Settings.Model, + Temperature: cfg.Settings.Temperature, Status: string(status), LatencyMs: sql.NullInt64{Int64: now.Sub(l.start.Time).Milliseconds(), Valid: true}, TokensIn: reported(l.tokensIn), @@ -175,6 +177,14 @@ func (l *runLog) save(ctx context.Context, cfg Config, skill string, version int }) } +// nonNil is s, or an empty slice when s is nil, so it encodes as []. +func nonNil[T any](s []T) []T { + if s == nil { + return []T{} + } + return s +} + // reported is n as a column value, NULL when no turn reported a count. func reported(n int64) sql.NullInt64 { return sql.NullInt64{Int64: n, Valid: n > 0} diff --git a/internal/ai/harness/runs_test.go b/internal/ai/harness/runs_test.go index 182cc42..339f40d 100644 --- a/internal/ai/harness/runs_test.go +++ b/internal/ai/harness/runs_test.go @@ -6,11 +6,14 @@ import ( "encoding/json" "errors" "fmt" + "net/http" + "net/http/httptest" "strings" "testing" "time" "code.cubecraftlabs.com/Maniacs_Mansion/Meal-Quest/internal/ai/llm" + "code.cubecraftlabs.com/Maniacs_Mansion/Meal-Quest/internal/ai/llm/presets" "code.cubecraftlabs.com/Maniacs_Mansion/Meal-Quest/internal/db" "code.cubecraftlabs.com/Maniacs_Mansion/Meal-Quest/internal/store" ) @@ -212,7 +215,7 @@ func TestRunRecordsCancelledRun(t *testing.T) { func TestRunFailsWhenRowCannotBeWritten(t *testing.T) { var f llm.Fake cfg := testConfig(t, &f) - cfg.ProviderName = "gemini" // refused by the provider CHECK + cfg.Settings.Provider = "gemini" // refused by the provider CHECK f.QueueGenerate(reply(`{"echo":"taco"}`)) _, err := Run(context.Background(), cfg, echoSkill{}, echoInput{Word: "taco"}) if err == nil || !strings.Contains(err.Error(), "record ai_runs row") { @@ -266,6 +269,12 @@ func TestRunRowsHoldNoSecrets(t *testing.T) { f.QueueGenerate(script...) cfg := testConfig(t, &f) cfg.APIKey = seededKey + cfg.NewProvider = func(_ llm.Settings, key string) (llm.Provider, error) { + if key != seededKey { + t.Errorf("provider built with key %q, want the seeded key", key) + } + return &f, nil + } cfg.Persona = "Our kitchen. " + leaky _, _ = Run(context.Background(), cfg, echoSkill{}, echoInput{Word: "tacos " + seededWebhook}) assertCalls(t, &f, len(script)) @@ -289,6 +298,63 @@ func TestRunRowsHoldNoSecrets(t *testing.T) { } } +// TestRunRowsHoldNoProviderKey builds the provider the production way, +// presets.FromSettings, against a server that quotes the bearer key it +// receives with no Authorization label: in the reply text, the reply JSON +// and the model name. The repair turn then sends the quoted key back. +func TestRunRowsHoldNoProviderKey(t *testing.T) { + turn := 0 + srv := httptest.NewServer(http.HandlerFunc(func(w http.ResponseWriter, r *http.Request) { + key, ok := strings.CutPrefix(r.Header.Get("Authorization"), "Bearer ") + if !ok || key == "" { + t.Errorf("Authorization = %q, want a bearer key", r.Header.Get("Authorization")) + } + turn++ + echo := key // lower case, so usable + if turn == 1 { + echo = "Your key is " + key // upper case, so repaired + } + content, err := json.Marshal(map[string]string{"echo": echo}) + if err != nil { + t.Error(err) + } + w.Header().Set("Content-Type", "application/json") + if err := json.NewEncoder(w).Encode(map[string]any{ + "model": "model-" + key, + "choices": []any{map[string]any{"finish_reason": "stop", "message": map[string]any{"role": "assistant", "content": string(content)}}}, + "usage": map[string]int{"prompt_tokens": 10, "completion_tokens": 5}, + }); err != nil { + t.Error(err) + } + })) + defer srv.Close() + + cfg := Config{ + Settings: llm.Settings{Provider: "openai_compatible", BaseURL: srv.URL, Model: "local-test", Temperature: 0.7}, + APIKey: seededKey, + NewProvider: presets.FromSettings, + Store: emptyHousehold(t), + } + out, err := Run(context.Background(), cfg, echoSkill{}, echoInput{Word: "taco"}) + if err != nil { + t.Fatal(err) + } + if out.Echo != seededKey || turn != 2 { + t.Fatalf("Echo = %q after %d turns, want the provider's key after 2", out.Echo, turn) + } + rows := runRows(t, cfg.Store) + if len(rows) != 1 || rows[0].Status != string(StatusRepaired) { + t.Fatalf("rows = %+v, want one repaired row", rows) + } + text := rows[0].text() + if strings.Contains(text, seededKey) { + t.Fatalf("stored row holds the provider's key:\n%s", text) + } + if !strings.Contains(text, "Your key is "+redactionMarker) || !strings.Contains(text, "model-"+redactionMarker) { + t.Fatalf("stored row lacks the redacted quotes:\n%s", text) + } +} + func TestRedact(t *testing.T) { const key = "sk-abc123" for _, tc := range []struct{ in, want string }{ -- 2.55.0