ai_runs logging, redaction and retention (#60)
CI / ci (push) Successful in 1m34s

Co-authored-by: dev_agent <dev_agent@cubecraftlabs.com>
This commit was merged in pull request #60.
This commit is contained in:
2026-10-05 09:55:06 -04:00
committed by approver_agent
parent 5d5404b3cb
commit 87316d8b70
13 changed files with 1274 additions and 49 deletions
+108 -40
View File
@@ -4,7 +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).
// fallback (D-007). Every run is recorded in ai_runs (see Run and Purge).
package harness
import (
@@ -17,6 +17,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.
@@ -40,16 +41,43 @@ 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
// 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.NewProvider == nil:
return errors.New("config has no provider constructor")
case c.Settings.Provider == "":
return errors.New("config has no provider name")
case c.Settings.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,48 +102,88 @@ 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 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 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)
}
log := &runLog{start: store.Now()}
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))
}
if err != nil {
return zero, err
}
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, fmt.Errorf("harness: skill %s v%d: render: %w", s.Name(), s.Version(), err)
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.Temperature
temperature := cfg.Settings.Temperature
req := llm.Request{
System: prompt.System,
Messages: []llm.Message{{Role: llm.RoleUser, Content: prompt.User}},
Temperature: &temperature,
Schema: &schema,
}
out, reply, first, err := attempt(ctx, cfg.Provider, s, req)
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
return turns(ctx, cfg.APIKey, provider, s, req, log)
}
// 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, 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, apiKey, provider, 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, apiKey, provider, 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 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, 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)
@@ -124,21 +192,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.
+63 -3
View File
@@ -15,9 +15,20 @@ func reply(js string) llm.GenerateResult {
return llm.GenerateResult{Response: llm.Response{Text: js, JSON: json.RawMessage(js)}}
}
// 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{
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) {
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 +214,58 @@ 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)
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)
}
}
func TestRunConfigError(t *testing.T) {
var f llm.Fake
full := testConfig(t, &f)
for name, edit := range map[string]func(*Config){
"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
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))
}
}
+3 -1
View File
@@ -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]
+139
View File
@@ -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
}
+204
View File
@@ -0,0 +1,204 @@
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, post-processing a
// valid reply failed, or the skill's prompt could not be rendered.
StatusBadOutput RunStatus = "bad_output"
// StatusProviderError means the provider could not be built or 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 {
// 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(nonNil(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.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),
TokensOut: reported(l.tokensOut),
Error: errText,
RequestRedacted: request,
ResponseRedacted: sql.NullString{String: response, Valid: true},
CreatedAt: l.start.String(),
UpdatedAt: now.String(),
})
}
// 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}
}
// 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
}
+478
View File
@@ -0,0 +1,478 @@
package harness
import (
"context"
"database/sql"
"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"
)
// 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.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") {
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.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))
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)
}
}
})
}
}
// 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 }{
{"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]"},
{"<https://chat.googleapis.com/v1/spaces/A/messages>", "<[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")
}
}