From 664bf65a5ba279a7d28439969e9e7583c4f3dd89 Mon Sep 17 00:00:00 2001 From: "Jakub A. W" Date: Sat, 25 Jul 2026 16:11:45 +0200 Subject: [PATCH 01/12] refactor(config): separate loading, decoding and validation of failover rules loadFailoverConfig did env expansion, file IO, strict JSON decoding, a three-way merge and validation in one body, with the decode-then-merge step written out once per source. Each source is now a named function that returns nil when unconfigured, so the loader reads as four steps. The hand-rolled JSON decoder is split into decodeStrictJSONObject, whose doc comment states what it rejects that a plain Unmarshal accepts and why that needs the token stream. Behaviour is unchanged, including that an unset FAILOVER_RULES_JSON is no rules while an empty rules *file* stays a parse error. Co-Authored-By: Claude Opus 5 (1M context) --- config/failover.go | 228 ++++++++++++++++++++++++++++----------------- 1 file changed, 140 insertions(+), 88 deletions(-) diff --git a/config/failover.go b/config/failover.go index d1e6ff291..03b238ef4 100644 --- a/config/failover.go +++ b/config/failover.go @@ -90,67 +90,109 @@ func loadFailoverConfig(cfg *FailoverConfig) error { slog.Warn("failover.overrides was removed and is ignored; use failover.disabled_models instead") cfg.Overrides = nil } - cfg.DefaultMode = ResolveFailoverDefaultMode(cfg.DefaultMode) - manual := make(map[string][]string) - if err := mergeFailoverRules(manual, cfg.Rules, "failover.rules"); err != nil { + manual, err := failoverManualRules(cfg) + if err != nil { return err } + cfg.Manual = manual - path := strings.TrimSpace(cfg.ManualRulesPath) - if path != "" { - raw, err := os.ReadFile(path) - if err != nil { - return fmt.Errorf("failover.manual_rules_path: failed to read %q: %w", path, err) - } - decoded, err := decodeFailoverRuleJSON(string(raw), fmt.Sprintf("failover.manual_rules_path: failed to parse %q", path)) - if err != nil { - return err - } - if err := mergeFailoverRules(manual, decoded, "failover.manual_rules_path"); err != nil { - return err - } + disabled, err := failoverDisabledModels(cfg) + if err != nil { + return err + } + cfg.Disabled = disabled + return nil +} + +// failoverManualRules merges the three sources of manual rules, later sources +// overwriting a key an earlier one set: inline YAML, then the rules file, then +// the env JSON. It returns nil rather than an empty map when no source +// contributes, because callers treat a nil map as "no manual rules". +func failoverManualRules(cfg *FailoverConfig) (map[string][]string, error) { + merged := make(map[string][]string) + + if err := mergeFailoverRules(merged, cfg.Rules, "failover.rules"); err != nil { + return nil, err + } + + fromFile, err := failoverRulesFromFile(cfg.ManualRulesPath) + if err != nil { + return nil, err + } + if err := mergeFailoverRules(merged, fromFile, "failover.manual_rules_path"); err != nil { + return nil, err } - if inline := strings.TrimSpace(cfg.RulesJSON); inline != "" { - decoded, err := decodeFailoverRuleJSON(inline, "failover.rules_json") + // An unset env var is simply no rules; an empty *file*, by contrast, stays + // a parse error, since configuring a path to nothing is a mistake. + if strings.TrimSpace(cfg.RulesJSON) != "" { + fromEnv, err := failoverRulesFromJSON(cfg.RulesJSON, "failover.rules_json") if err != nil { - return err + return nil, err } - if err := mergeFailoverRules(manual, decoded, "failover.rules_json"); err != nil { - return err + if err := mergeFailoverRules(merged, fromEnv, "failover.rules_json"); err != nil { + return nil, err } } - cfg.Manual = nil - if len(manual) > 0 { - cfg.Manual = manual + if len(merged) == 0 { + return nil, nil } + return merged, nil +} - disabled, err := failoverDisabledModels(cfg) +// failoverRulesFromFile reads manual rules from a JSON file, or returns nil +// when no path is configured. +func failoverRulesFromFile(path string) (map[string][]string, error) { + path = strings.TrimSpace(path) + if path == "" { + return nil, nil + } + raw, err := os.ReadFile(path) if err != nil { - return err + return nil, fmt.Errorf("failover.manual_rules_path: failed to read %q: %w", path, err) } - cfg.Disabled = disabled - return nil + return failoverRulesFromJSON(string(raw), + fmt.Sprintf("failover.manual_rules_path: failed to parse %q", path)) } -func decodeFailoverRuleJSON(raw, label string) (map[string][]string, error) { - expanded := expandString(raw) - decoded := make(map[string][]string) - decoder := json.NewDecoder(strings.NewReader(expanded)) - - token, err := decoder.Token() +// failoverRulesFromJSON decodes a JSON object mapping a source model to its +// ordered failover models. +func failoverRulesFromJSON(raw, label string) (map[string][]string, error) { + entries, err := decodeStrictJSONObject(raw, label) if err != nil { - return nil, fmt.Errorf("%s: %w", label, err) + return nil, err + } + rules := make(map[string][]string, len(entries)) + for key, rawModels := range entries { + if bytes.Equal(bytes.TrimSpace(rawModels), []byte("null")) { + return nil, fmt.Errorf("%s: null not allowed for %q", label, key) + } + var models []string + if err := json.Unmarshal(rawModels, &models); err != nil { + return nil, fmt.Errorf("%s: %w", label, err) + } + rules[key] = models } - delim, ok := token.(json.Delim) - if !ok || delim != '{' { - return nil, fmt.Errorf("%s: top-level JSON value must be an object", label) + return rules, nil +} + +// decodeStrictJSONObject decodes a JSON object into its raw values, rejecting +// what a plain json.Unmarshal into a map would silently accept: a non-object +// top level, a repeated key (the last would win, quietly discarding a rule an +// operator wrote), and trailing content after the object (usually a truncated +// or concatenated file). Detecting those needs the token stream, which is why +// this is hand-rolled rather than an Unmarshal. +func decodeStrictJSONObject(raw, label string) (map[string]json.RawMessage, error) { + decoder := json.NewDecoder(strings.NewReader(expandString(raw))) + + if err := expectJSONDelim(decoder, '{', label); err != nil { + return nil, err } - seenKeys := make(map[string]struct{}) + entries := make(map[string]json.RawMessage) for decoder.More() { token, err := decoder.Token() if err != nil { @@ -160,32 +202,19 @@ func decodeFailoverRuleJSON(raw, label string) (map[string][]string, error) { if !ok { return nil, fmt.Errorf("%s: object key must be a string", label) } - if _, exists := seenKeys[key]; exists { + if _, exists := entries[key]; exists { return nil, fmt.Errorf("%s: duplicate JSON key %q", label, key) } - seenKeys[key] = struct{}{} - var rawModels json.RawMessage - if err := decoder.Decode(&rawModels); err != nil { + var value json.RawMessage + if err := decoder.Decode(&value); err != nil { return nil, fmt.Errorf("%s: %w", label, err) } - if bytes.Equal(bytes.TrimSpace(rawModels), []byte("null")) { - return nil, fmt.Errorf("%s: null not allowed for %q", label, key) - } - var models []string - if err := json.Unmarshal(rawModels, &models); err != nil { - return nil, fmt.Errorf("%s: %w", label, err) - } - decoded[key] = models + entries[key] = value } - token, err = decoder.Token() - if err != nil { - return nil, fmt.Errorf("%s: %w", label, err) - } - delim, ok = token.(json.Delim) - if !ok || delim != '}' { - return nil, fmt.Errorf("%s: top-level JSON value must be an object", label) + if err := expectJSONDelim(decoder, '}', label); err != nil { + return nil, err } var trailing json.RawMessage @@ -195,7 +224,18 @@ func decodeFailoverRuleJSON(raw, label string) (map[string][]string, error) { } return nil, fmt.Errorf("%s: unexpected trailing JSON content", label) } - return decoded, nil + return entries, nil +} + +func expectJSONDelim(decoder *json.Decoder, want json.Delim, label string) error { + token, err := decoder.Token() + if err != nil { + return fmt.Errorf("%s: %w", label, err) + } + if delim, ok := token.(json.Delim); !ok || delim != want { + return fmt.Errorf("%s: top-level JSON value must be an object", label) + } + return nil } func mergeFailoverRules(dst map[string][]string, src map[string][]string, label string) error { @@ -224,39 +264,51 @@ func mergeFailoverRules(dst map[string][]string, src map[string][]string, label func failoverDisabledModels(cfg *FailoverConfig) (map[string]bool, error) { disabled := make(map[string]bool) - for _, model := range cfg.DisabledModels { - model = strings.TrimSpace(model) - if model != "" { - disabled[model] = true - } + addDisabledModel(disabled, cfg.DisabledModels...) + + raw := strings.TrimSpace(cfg.DisabledModelsJSON) + if raw == "" { + return nilIfEmpty(disabled), nil } - if raw := strings.TrimSpace(cfg.DisabledModelsJSON); raw != "" { - expanded := expandString(raw) - if strings.TrimSpace(expanded) == "null" { - return nil, fmt.Errorf("disabled models JSON: null not allowed; expected an array or object") - } - var list []string - if err := json.Unmarshal([]byte(expanded), &list); err == nil { - for _, model := range list { - model = strings.TrimSpace(model) - if model != "" { - disabled[model] = true - } - } - return nilIfEmpty(disabled), nil - } - var keyed map[string]bool - if err := json.Unmarshal([]byte(expanded), &keyed); err != nil { - return nil, fmt.Errorf("failover.disabled_models_json: must be a JSON array or boolean object: %w", err) + if err := addDisabledModelsFromJSON(disabled, raw); err != nil { + return nil, err + } + return nilIfEmpty(disabled), nil +} + +// addDisabledModelsFromJSON accepts either spelling operators use: a plain +// array of selectors, or an object mapping a selector to a boolean so a single +// entry can be turned off without deleting it. +func addDisabledModelsFromJSON(disabled map[string]bool, raw string) error { + expanded := expandString(raw) + if strings.TrimSpace(expanded) == "null" { + return fmt.Errorf("disabled models JSON: null not allowed; expected an array or object") + } + + var list []string + if err := json.Unmarshal([]byte(expanded), &list); err == nil { + addDisabledModel(disabled, list...) + return nil + } + + var keyed map[string]bool + if err := json.Unmarshal([]byte(expanded), &keyed); err != nil { + return fmt.Errorf("failover.disabled_models_json: must be a JSON array or boolean object: %w", err) + } + for model, isDisabled := range keyed { + if isDisabled { + addDisabledModel(disabled, model) } - for key, value := range keyed { - key = strings.TrimSpace(key) - if key != "" && value { - disabled[key] = true - } + } + return nil +} + +func addDisabledModel(disabled map[string]bool, models ...string) { + for _, model := range models { + if model = strings.TrimSpace(model); model != "" { + disabled[model] = true } } - return nilIfEmpty(disabled), nil } func nilIfEmpty(m map[string]bool) map[string]bool { From d14aa938e7bf8ecd29d2643635558d55e96645e7 Mon Sep 17 00:00:00 2001 From: "Jakub A. W" Date: Sat, 25 Jul 2026 16:11:45 +0200 Subject: [PATCH 02/12] refactor(failover): compute a request's match keys once per resolve MIME-Version: 1.0 Content-Type: text/plain; charset=UTF-8 Content-Transfer-Encoding: 8bit The resolver built the same key list twice on every request — once for the disabled check, once for the manual-rule lookup — and each build allocates a map and two slices. A requestIdentity value now carries the source model, its canonical key and the match keys, computed once. BenchmarkResolveFailovers: 330 -> 237 ns/op, 312 -> 216 B/op, 8 -> 6 allocs/op. Co-Authored-By: Claude Opus 5 (1M context) --- internal/failover/resolver.go | 58 ++++++++++++++---------- internal/failover/resolver_bench_test.go | 36 +++++++++++++++ 2 files changed, 71 insertions(+), 23 deletions(-) create mode 100644 internal/failover/resolver_bench_test.go diff --git a/internal/failover/resolver.go b/internal/failover/resolver.go index c0cd2eebe..e38baee39 100644 --- a/internal/failover/resolver.go +++ b/internal/failover/resolver.go @@ -89,15 +89,33 @@ func (r *Resolver) ResolveFailovers(resolution *core.RequestModelResolution, op return nil } - source := r.sourceModelInfo(resolution) - if r.disabledFor(resolution, source) { + identity := r.identify(resolution) + if r.disabledFor(identity) { return nil } + return r.manualSelectorsFor(identity, make(map[string]struct{})) +} - sourceKey := r.sourceKey(resolution, source) - seen := make(map[string]struct{}) +// requestIdentity is the set of names one resolution answers to: the source +// model it resolved to, that model's canonical key, and every key a failover +// rule may be written against. +// +// It exists so matchKeys runs once per request. Both the disabled check and +// the manual-rule lookup need the same list, and building it allocates a map +// and two slices — on the resolve path of every translated request. +type requestIdentity struct { + source *providers.ModelInfo + sourceKey string + matchKeys []string +} - return r.manualSelectorsFor(resolution, source, sourceKey, seen) +func (r *Resolver) identify(resolution *core.RequestModelResolution) requestIdentity { + source := r.sourceModelInfo(resolution) + return requestIdentity{ + source: source, + sourceKey: r.sourceKey(resolution, source), + matchKeys: r.matchKeys(resolution, source), + } } func (r *Resolver) sourceModelInfo(resolution *core.RequestModelResolution) *providers.ModelInfo { @@ -123,9 +141,9 @@ func (r *Resolver) sourceModelInfo(resolution *core.RequestModelResolution) *pro return nil } -func (r *Resolver) disabledFor(resolution *core.RequestModelResolution, source *providers.ModelInfo) bool { +func (r *Resolver) disabledFor(identity requestIdentity) bool { disabled := r.effectiveDisabled() - for _, key := range r.matchKeys(resolution, source) { + for _, key := range identity.matchKeys { if disabled[key] { return true } @@ -133,14 +151,9 @@ func (r *Resolver) disabledFor(resolution *core.RequestModelResolution, source * return false } -func (r *Resolver) manualSelectorsFor( - resolution *core.RequestModelResolution, - source *providers.ModelInfo, - sourceKey string, - seen map[string]struct{}, -) []core.ModelSelector { +func (r *Resolver) manualSelectorsFor(identity requestIdentity, seen map[string]struct{}) []core.ModelSelector { manual := r.effectiveManualRules() - for _, key := range r.matchKeys(resolution, source) { + for _, key := range identity.matchKeys { models, ok := manual[key] if !ok { continue @@ -148,7 +161,7 @@ func (r *Resolver) manualSelectorsFor( result := make([]core.ModelSelector, 0, len(models)) for _, model := range models { selector, candidateKey, ok := r.resolveSelector(model) - if !ok || candidateKey == sourceKey { + if !ok || candidateKey == identity.sourceKey { continue } if _, exists := seen[candidateKey]; exists { @@ -172,16 +185,15 @@ func (r *Resolver) SuggestFailovers(resolution *core.RequestModelResolution, op if requiredCategory == core.CategoryEmbedding { return nil } - source := r.sourceModelInfo(resolution) - if r.disabledFor(resolution, source) { + identity := r.identify(resolution) + if r.disabledFor(identity) { return nil } - sourceKey := r.sourceKey(resolution, source) seen := make(map[string]struct{}) - for _, selector := range r.manualSelectorsFor(resolution, source, sourceKey, seen) { + for _, selector := range r.manualSelectorsFor(identity, seen) { seen[selector.QualifiedModel()] = struct{}{} } - return r.autoSelectorsFor(source, sourceKey, requiredCategory, seen) + return r.autoSelectorsFor(identity, requiredCategory, seen) } func (r *Resolver) effectiveManualRules() map[string][]string { @@ -225,11 +237,11 @@ func (r *Resolver) effectiveDisabled() map[string]bool { } func (r *Resolver) autoSelectorsFor( - source *providers.ModelInfo, - sourceKey string, + identity requestIdentity, requiredCategory core.ModelCategory, seen map[string]struct{}, ) []core.ModelSelector { + source := identity.source if source == nil || source.Model.Metadata == nil { return nil } @@ -255,7 +267,7 @@ func (r *Resolver) autoSelectorsFor( candidates := make([]scoredCandidate, 0) for _, candidate := range r.registry.ListModelsWithProvider() { key := strings.TrimSpace(candidate.Selector) - if key == "" || key == sourceKey { + if key == "" || key == identity.sourceKey { continue } if _, exists := seen[key]; exists { diff --git a/internal/failover/resolver_bench_test.go b/internal/failover/resolver_bench_test.go new file mode 100644 index 000000000..2884ef743 --- /dev/null +++ b/internal/failover/resolver_bench_test.go @@ -0,0 +1,36 @@ +package failover + +import ( + "testing" + + "github.com/enterpilot/gomodel/config" + "github.com/enterpilot/gomodel/internal/core" +) + +// BenchmarkResolveFailovers covers the path every translated request takes +// when failover rules exist. It exists because the resolver used to compute +// the request's match keys twice — once for the disabled check, once for the +// rule lookup — which this measures at 8 allocs/op against 6 today. +func BenchmarkResolveFailovers(b *testing.B) { + registry := newFakeRegistry( + modelInfo("gpt-4o", "openai", "openai", 1287, "gpt-4o"), + modelInfo("gpt-4o", "azure", "azure", 1287, "gpt-4o"), + modelInfo("gemini-2.5-pro", "gemini", "gemini", 1290, "gemini-2.5-pro"), + ) + resolver := NewResolver(config.FailoverConfig{ + Enabled: true, + Manual: map[string][]string{"gpt-4o": {"azure/gpt-4o", "gemini/gemini-2.5-pro"}}, + }, registry) + + resolution := &core.RequestModelResolution{ + Requested: core.NewRequestedModelSelector("gpt-4o", ""), + ResolvedSelector: core.ModelSelector{Model: "gpt-4o"}, + ProviderType: "openai", + } + + b.ReportAllocs() + b.ResetTimer() + for range b.N { + _ = resolver.ResolveFailovers(resolution, core.OperationChatCompletions) + } +} From bcd23a8a34a7cb22f7a16ea0dd0613abfdce03a5 Mon Sep 17 00:00:00 2001 From: "Jakub A. W" Date: Sat, 25 Jul 2026 16:21:29 +0200 Subject: [PATCH 03/12] refactor(auditlog): serve both SQL backends from one reader MIME-Version: 1.0 Content-Type: text/plain; charset=UTF-8 Content-Transfer-Encoding: 8bit reader_sqlite.go (497) and reader_postgresql.go (395) were the same reader written twice, down to a duplicated latency predicate and a scan body the SQLite half repeated inline as well as in its own helper. One SQLReader now serves both, with a readerDialect value holding the six spellings that genuinely differ — ILIKE, the id casts a pre-unification PostgreSQL database still needs, the JSON path operators, the date-range boundary and the hour-bucketing expression — each carrying why. sqlx.Timestamp is the read side of TimestampArg: PostgreSQL returns a time.Time, SQLite the RFC3339 text that was written. It leaves an unparseable value invalid rather than failing the scan, so one bad row does not fail a page of results, as before. Two PostgreSQL JSON lookups now use the `#>>` spelling the indexes in jsonPathIndexes are built on. `data->'response_body'->>'id'` is a different expression to the planner, so those indexes could not be used. Coverage: the store tests paired with the reader ran on SQLite only. They now run through sqlxtest on both engines — auditlog goes from 0 to 19 PostgreSQL subtests. reader_postgresql_test.go, 205 lines of reflection-based fake pgx rows asserting NULL handling, is deleted: the same behaviour is now asserted against a real database. Co-Authored-By: Claude Opus 5 (1M context) --- internal/auditlog/reader_factory.go | 10 +- internal/auditlog/reader_postgresql.go | 395 ---------- internal/auditlog/reader_postgresql_test.go | 205 ------ internal/auditlog/reader_sql.go | 409 +++++++++++ internal/auditlog/reader_sql_boundary_test.go | 192 +++++ internal/auditlog/reader_sqlite.go | 497 ------------- .../auditlog/reader_sqlite_boundary_test.go | 189 ----- internal/auditlog/roundtrip_sql_test.go | 666 +++++++++++++++++ internal/auditlog/stats_postgresql.go | 61 -- internal/auditlog/stats_sql.go | 106 +++ internal/auditlog/stats_sqlite.go | 63 -- internal/auditlog/stats_test.go | 161 +++-- internal/auditlog/store_sqlite_test.go | 682 ------------------ internal/storage/sqlx/timestamp.go | 61 ++ 14 files changed, 1521 insertions(+), 2176 deletions(-) delete mode 100644 internal/auditlog/reader_postgresql.go delete mode 100644 internal/auditlog/reader_postgresql_test.go create mode 100644 internal/auditlog/reader_sql.go create mode 100644 internal/auditlog/reader_sql_boundary_test.go delete mode 100644 internal/auditlog/reader_sqlite.go delete mode 100644 internal/auditlog/reader_sqlite_boundary_test.go create mode 100644 internal/auditlog/roundtrip_sql_test.go delete mode 100644 internal/auditlog/stats_postgresql.go create mode 100644 internal/auditlog/stats_sql.go delete mode 100644 internal/auditlog/stats_sqlite.go delete mode 100644 internal/auditlog/store_sqlite_test.go create mode 100644 internal/storage/sqlx/timestamp.go diff --git a/internal/auditlog/reader_factory.go b/internal/auditlog/reader_factory.go index 516989a21..9247a9817 100644 --- a/internal/auditlog/reader_factory.go +++ b/internal/auditlog/reader_factory.go @@ -1,12 +1,12 @@ package auditlog import ( - "database/sql" + "context" - "github.com/jackc/pgx/v5/pgxpool" "go.mongodb.org/mongo-driver/v2/mongo" "github.com/enterpilot/gomodel/internal/storage" + "github.com/enterpilot/gomodel/internal/storage/sqlx" ) // NewReader creates an audit log Reader from a storage backend. @@ -16,10 +16,10 @@ func NewReader(store storage.Storage) (Reader, error) { return nil, nil } - return storage.ResolveBackend[Reader]( + return storage.ResolveSQLBackend[Reader]( + context.Background(), store, - func(db *sql.DB) (Reader, error) { return NewSQLiteReader(db) }, - func(pool *pgxpool.Pool) (Reader, error) { return NewPostgreSQLReader(pool) }, + func(db sqlx.DB) (Reader, error) { return NewSQLReader(db) }, func(db *mongo.Database) (Reader, error) { return NewMongoDBReader(db) }, ) } diff --git a/internal/auditlog/reader_postgresql.go b/internal/auditlog/reader_postgresql.go deleted file mode 100644 index d1370df0f..000000000 --- a/internal/auditlog/reader_postgresql.go +++ /dev/null @@ -1,395 +0,0 @@ -package auditlog - -import ( - "github.com/enterpilot/gomodel/internal/storage/sqlutil" - - "context" - "fmt" - "log/slog" - "time" - - "github.com/goccy/go-json" - - "github.com/jackc/pgx/v5" - "github.com/jackc/pgx/v5/pgxpool" -) - -type postgreSQLQueryer interface { - Query(ctx context.Context, sql string, args ...any) (pgx.Rows, error) - QueryRow(ctx context.Context, sql string, args ...any) pgx.Row -} - -// PostgreSQLReader implements Reader for PostgreSQL databases. -type PostgreSQLReader struct { - pool postgreSQLQueryer -} - -// NewPostgreSQLReader creates a new PostgreSQL audit log reader. -func NewPostgreSQLReader(pool *pgxpool.Pool) (*PostgreSQLReader, error) { - if pool == nil { - return nil, fmt.Errorf("connection pool is required") - } - return &PostgreSQLReader{pool: pool}, nil -} - -// GetLogs returns a paginated list of audit log entries. -func (r *PostgreSQLReader) GetLogs(ctx context.Context, params LogQueryParams) (*LogListResult, error) { - limit, offset := clampLimitOffset(params.Limit, params.Offset) - - conditions, args, argIdx := pgDateRangeConditions(params.QueryParams, 1) - userPath, err := normalizeAuditUserPathFilter(params.UserPath) - if err != nil { - return nil, err - } - - if params.RequestedModel != "" { - conditions = append(conditions, fmt.Sprintf("requested_model ILIKE $%d ESCAPE '\\'", argIdx)) - args = append(args, "%"+sqlutil.EscapeLikeWildcards(params.RequestedModel)+"%") - argIdx++ - } - if params.Provider != "" { - conditions = append(conditions, fmt.Sprintf("(provider ILIKE $%d ESCAPE '\\' OR provider_name ILIKE $%d ESCAPE '\\')", argIdx, argIdx+1)) - args = append(args, "%"+sqlutil.EscapeLikeWildcards(params.Provider)+"%", "%"+sqlutil.EscapeLikeWildcards(params.Provider)+"%") - argIdx += 2 - } - if params.Method != "" { - conditions = append(conditions, fmt.Sprintf("method = $%d", argIdx)) - args = append(args, params.Method) - argIdx++ - } - if params.Path != "" { - conditions = append(conditions, fmt.Sprintf("path ILIKE $%d ESCAPE '\\'", argIdx)) - args = append(args, "%"+sqlutil.EscapeLikeWildcards(params.Path)+"%") - argIdx++ - } - if userPath != "" { - conditions = append(conditions, auditUserPathSQLPredicate( - userPath, - fmt.Sprintf("user_path = $%d", argIdx), - fmt.Sprintf("user_path LIKE $%d ESCAPE '\\'", argIdx+1), - )) - args = append(args, userPath, auditUserPathSubtreePattern(userPath)) - argIdx += 2 - } - if params.ErrorType != "" { - conditions = append(conditions, fmt.Sprintf("error_type ILIKE $%d ESCAPE '\\'", argIdx)) - args = append(args, "%"+sqlutil.EscapeLikeWildcards(params.ErrorType)+"%") - argIdx++ - } - if params.StatusCode != nil { - conditions = append(conditions, fmt.Sprintf("status_code = $%d", argIdx)) - args = append(args, *params.StatusCode) - argIdx++ - } - if params.Stream != nil { - conditions = append(conditions, fmt.Sprintf("stream = $%d", argIdx)) - args = append(args, *params.Stream) - argIdx++ - } - if params.Search != "" { - s := "%" + sqlutil.EscapeLikeWildcards(params.Search) + "%" - conditions = append(conditions, fmt.Sprintf("(request_id ILIKE $%d ESCAPE '\\' OR auth_key_id ILIKE $%d ESCAPE '\\' OR requested_model ILIKE $%d ESCAPE '\\' OR provider ILIKE $%d ESCAPE '\\' OR provider_name ILIKE $%d ESCAPE '\\' OR method ILIKE $%d ESCAPE '\\' OR path ILIKE $%d ESCAPE '\\' OR user_path ILIKE $%d ESCAPE '\\' OR error_type ILIKE $%d ESCAPE '\\' OR data->>'error_message' ILIKE $%d ESCAPE '\\')", argIdx, argIdx, argIdx, argIdx, argIdx, argIdx, argIdx, argIdx, argIdx, argIdx)) - args = append(args, s) - argIdx++ - } - - where := sqlutil.BuildWhereClause(conditions) - - var total int - countQuery := `SELECT COUNT(*) FROM audit_logs` + where - if err := r.pool.QueryRow(ctx, countQuery, args...).Scan(&total); err != nil { - return nil, fmt.Errorf("failed to count audit log entries: %w", err) - } - - dataQuery := fmt.Sprintf(`SELECT id, timestamp, duration_ns, requested_model, resolved_model, provider, provider_name, alias_used, workflow_version_id, cache_type, status_code, request_id, auth_key_id, auth_method, - client_ip, method, path, user_path, stream, error_type, data - FROM audit_logs%s ORDER BY timestamp DESC LIMIT $%d OFFSET $%d`, where, argIdx, argIdx+1) - dataArgs := append(append([]any(nil), args...), limit, offset) - - rows, err := r.pool.Query(ctx, dataQuery, dataArgs...) - if err != nil { - return nil, fmt.Errorf("failed to query audit logs: %w", err) - } - defer rows.Close() - - entries := make([]LogEntry, 0) - for rows.Next() { - var e LogEntry - var dataJSON *string - var providerName *string - var workflowVersionID *string - var cacheType *string - var authKeyID *string - var authMethod *string - var userPath *string - var errorType *string - - if err := rows.Scan(&e.ID, &e.Timestamp, &e.DurationNs, &e.RequestedModel, &e.ResolvedModel, &e.Provider, &providerName, &e.AliasUsed, &workflowVersionID, &cacheType, &e.StatusCode, - &e.RequestID, &authKeyID, &authMethod, &e.ClientIP, &e.Method, &e.Path, &userPath, &e.Stream, &errorType, &dataJSON); err != nil { - return nil, fmt.Errorf("failed to scan audit log row: %w", err) - } - if workflowVersionID != nil { - e.WorkflowVersionID = *workflowVersionID - } - if authKeyID != nil { - e.AuthKeyID = *authKeyID - } - if authMethod != nil { - e.AuthMethod = *authMethod - } - if cacheType != nil { - e.CacheType = normalizeCacheType(*cacheType) - } - if providerName != nil { - e.ProviderName = displayAuditProviderName(*providerName, e.Provider) - } else { - e.ProviderName = displayAuditProviderName("", e.Provider) - } - if userPath != nil { - e.UserPath = *userPath - } - if errorType != nil { - e.ErrorType = *errorType - } - - if dataJSON != nil && *dataJSON != "" { - var data LogData - if err := json.Unmarshal([]byte(*dataJSON), &data); err != nil { - slog.Warn("failed to unmarshal audit data JSON", "id", e.ID, "error", err) - } else { - e.Data = &data - } - } - - entries = append(entries, e) - } - - if err := rows.Err(); err != nil { - return nil, fmt.Errorf("error iterating audit log rows: %w", err) - } - rows.Close() - if err := r.loadAttempts(ctx, entries); err != nil { - return nil, err - } - - return &LogListResult{ - Entries: entries, - Total: total, - Limit: limit, - Offset: offset, - }, nil -} - -// queryLogEntryWithAttempts runs a single-row audit log query, scans the entry, -// and hydrates its provider attempts. Returns (nil, nil) when no row matches. -func (r *PostgreSQLReader) queryLogEntryWithAttempts(ctx context.Context, query, arg string) (*LogEntry, error) { - rows, err := r.pool.Query(ctx, query, arg) - if err != nil { - return nil, fmt.Errorf("failed to query audit log: %w", err) - } - defer rows.Close() - if !rows.Next() { - if err := rows.Err(); err != nil { - return nil, fmt.Errorf("failed to read audit log row: %w", err) - } - return nil, nil - } - entry, err := scanPostgreSQLLogEntry(rows) - if err != nil { - return nil, err - } - rows.Close() - hydrated := []LogEntry{*entry} - if err := r.loadAttempts(ctx, hydrated); err != nil { - return nil, err - } - *entry = hydrated[0] - return entry, nil -} - -// GetLogByID returns a single audit log entry by ID. -func (r *PostgreSQLReader) GetLogByID(ctx context.Context, id string) (*LogEntry, error) { - return r.queryLogEntryWithAttempts(ctx, `SELECT id, timestamp, duration_ns, requested_model, resolved_model, provider, provider_name, alias_used, workflow_version_id, cache_type, status_code, request_id, auth_key_id, auth_method, - client_ip, method, path, user_path, stream, error_type, data - FROM audit_logs WHERE id::text = $1 LIMIT 1`, id) -} - -// GetConversation returns a linear conversation thread around a seed log entry. -func (r *PostgreSQLReader) GetConversation(ctx context.Context, logID string, limit int) (*ConversationResult, error) { - return buildConversationThread(ctx, logID, limit, r.GetLogByID, r.findByResponseID, r.findByPreviousResponseID) -} - -func pgDateRangeConditions(params QueryParams, argIdx int) (conditions []string, args []any, nextIdx int) { - nextIdx = argIdx - if !params.StartDate.IsZero() { - conditions = append(conditions, fmt.Sprintf("timestamp >= $%d", nextIdx)) - args = append(args, params.StartDate.UTC()) - nextIdx++ - } - if !params.EndDate.IsZero() { - conditions = append(conditions, fmt.Sprintf("timestamp < $%d", nextIdx)) - args = append(args, params.EndDate.AddDate(0, 0, 1).UTC()) - nextIdx++ - } - return conditions, args, nextIdx -} - -func (r *PostgreSQLReader) findByResponseID(ctx context.Context, responseID string) (*LogEntry, error) { - return r.queryLogEntryWithAttempts(ctx, `SELECT id, timestamp, duration_ns, requested_model, resolved_model, provider, provider_name, alias_used, workflow_version_id, cache_type, status_code, request_id, auth_key_id, auth_method, - client_ip, method, path, user_path, stream, error_type, data - FROM audit_logs - WHERE data->'response_body'->>'id' = $1 - ORDER BY timestamp ASC - LIMIT 1`, responseID) -} - -func (r *PostgreSQLReader) findByPreviousResponseID(ctx context.Context, previousResponseID string) (*LogEntry, error) { - return r.queryLogEntryWithAttempts(ctx, `SELECT id, timestamp, duration_ns, requested_model, resolved_model, provider, provider_name, alias_used, workflow_version_id, cache_type, status_code, request_id, auth_key_id, auth_method, - client_ip, method, path, user_path, stream, error_type, data - FROM audit_logs - WHERE data->'request_body'->>'previous_response_id' = $1 - ORDER BY timestamp ASC - LIMIT 1`, previousResponseID) -} - -func (r *PostgreSQLReader) loadAttempts(ctx context.Context, entries []LogEntry) error { - if len(entries) == 0 { - return nil - } - - // Batch all entries into a single query keyed by audit_log_id to avoid an - // N+1 read (one query per returned log) when hydrating a page of entries. - ids := make([]string, len(entries)) - index := make(map[string]int, len(entries)) - for i := range entries { - ids[i] = entries[i].ID - index[entries[i].ID] = i - } - rows, err := r.pool.Query(ctx, ` - SELECT audit_log_id::text, seq, kind, provider_type, provider_name, model, status_code, success, - error_type, error_code, error_message, response_body, response_headers, started_at, duration_ns - FROM audit_log_attempts - WHERE audit_log_id::text = ANY($1) - ORDER BY audit_log_id ASC, seq ASC - `, ids) - if err != nil { - return fmt.Errorf("failed to query audit log attempts: %w", err) - } - defer rows.Close() - - grouped := make(map[string][]AttemptSnapshot, len(entries)) - for rows.Next() { - var auditLogID string - var attempt AttemptSnapshot - var providerType, providerName, model *string - var errorType, errorCode, errorMessage *string - var responseBody, responseHeaders *string - var startedAt *time.Time - if err := rows.Scan( - &auditLogID, - &attempt.Seq, - &attempt.Kind, - &providerType, - &providerName, - &model, - &attempt.StatusCode, - &attempt.Success, - &errorType, - &errorCode, - &errorMessage, - &responseBody, - &responseHeaders, - &startedAt, - &attempt.DurationNs, - ); err != nil { - return fmt.Errorf("failed to scan audit log attempt: %w", err) - } - attempt.ResponseBody = unmarshalAttemptBody(responseBody) - attempt.ResponseHeaders = unmarshalAttemptHeaders(responseHeaders) - if providerType != nil { - attempt.ProviderType = *providerType - } - if providerName != nil { - attempt.ProviderName = *providerName - } - if model != nil { - attempt.Model = *model - } - if errorType != nil { - attempt.ErrorType = *errorType - } - if errorCode != nil { - attempt.ErrorCode = *errorCode - } - if errorMessage != nil { - attempt.ErrorMessage = *errorMessage - } - if startedAt != nil { - attempt.StartedAt = *startedAt - } - grouped[auditLogID] = append(grouped[auditLogID], attempt) - } - if err := rows.Err(); err != nil { - return fmt.Errorf("error iterating audit log attempts: %w", err) - } - - for id, attempts := range grouped { - if i, ok := index[id]; ok && len(attempts) > 0 { - ensureLogData(&entries[i]).Attempts = normalizeAttemptSnapshots(attempts) - } - } - return nil -} - -func scanPostgreSQLLogEntry(rows interface { - Scan(dest ...any) error -}) (*LogEntry, error) { - var e LogEntry - var dataJSON *string - var providerName *string - var workflowVersionID *string - var cacheType *string - var authKeyID *string - var authMethod *string - var userPath *string - var errorType *string - - if err := rows.Scan(&e.ID, &e.Timestamp, &e.DurationNs, &e.RequestedModel, &e.ResolvedModel, &e.Provider, &providerName, &e.AliasUsed, &workflowVersionID, &cacheType, &e.StatusCode, - &e.RequestID, &authKeyID, &authMethod, &e.ClientIP, &e.Method, &e.Path, &userPath, &e.Stream, &errorType, &dataJSON); err != nil { - return nil, fmt.Errorf("failed to scan audit log row: %w", err) - } - if workflowVersionID != nil { - e.WorkflowVersionID = *workflowVersionID - } - if authKeyID != nil { - e.AuthKeyID = *authKeyID - } - if authMethod != nil { - e.AuthMethod = *authMethod - } - if cacheType != nil { - e.CacheType = normalizeCacheType(*cacheType) - } - if providerName != nil { - e.ProviderName = displayAuditProviderName(*providerName, e.Provider) - } else { - e.ProviderName = displayAuditProviderName("", e.Provider) - } - if userPath != nil { - e.UserPath = *userPath - } - if errorType != nil { - e.ErrorType = *errorType - } - - if dataJSON != nil && *dataJSON != "" { - var data LogData - if err := json.Unmarshal([]byte(*dataJSON), &data); err != nil { - slog.Warn("failed to unmarshal audit data JSON", "id", e.ID, "error", err) - } else { - e.Data = &data - } - } - - return &e, nil -} diff --git a/internal/auditlog/reader_postgresql_test.go b/internal/auditlog/reader_postgresql_test.go deleted file mode 100644 index bc0e718d1..000000000 --- a/internal/auditlog/reader_postgresql_test.go +++ /dev/null @@ -1,205 +0,0 @@ -package auditlog - -import ( - "context" - "fmt" - "reflect" - "strings" - "testing" - "time" - - "github.com/jackc/pgx/v5" - "github.com/jackc/pgx/v5/pgconn" -) - -type fakePostgreSQLRow struct { - values []any -} - -func (r fakePostgreSQLRow) Scan(dest ...any) error { - if len(dest) != len(r.values) { - return fmt.Errorf("scan destination count = %d, want %d", len(dest), len(r.values)) - } - for i, value := range r.values { - target := reflect.ValueOf(dest[i]) - if target.Kind() != reflect.Pointer || target.IsNil() { - return fmt.Errorf("scan destination %d is not a non-nil pointer", i) - } - elem := target.Elem() - if value == nil { - elem.Set(reflect.Zero(elem.Type())) - continue - } - if elem.Kind() == reflect.Pointer { - pointerValue := reflect.New(elem.Type().Elem()) - if err := assignScannedValue(pointerValue.Elem(), value); err != nil { - return fmt.Errorf("scan destination %d: %w", i, err) - } - elem.Set(pointerValue) - continue - } - if err := assignScannedValue(elem, value); err != nil { - return fmt.Errorf("scan destination %d: %w", i, err) - } - } - return nil -} - -func assignScannedValue(target reflect.Value, value any) error { - source := reflect.ValueOf(value) - if source.Type().AssignableTo(target.Type()) { - target.Set(source) - return nil - } - if source.Type().ConvertibleTo(target.Type()) { - target.Set(source.Convert(target.Type())) - return nil - } - return fmt.Errorf("cannot assign %T to %s", value, target.Type()) -} - -type fakePostgreSQLQueryer struct { - count int - rows pgx.Rows -} - -func (q fakePostgreSQLQueryer) QueryRow(_ context.Context, _ string, _ ...any) pgx.Row { - return fakePostgreSQLRow{values: []any{q.count}} -} - -func (q fakePostgreSQLQueryer) Query(_ context.Context, sql string, _ ...any) (pgx.Rows, error) { - if strings.Contains(sql, "FROM audit_log_attempts") { - return &fakePostgreSQLRows{read: true}, nil - } - if !strings.Contains(sql, "FROM audit_logs") { - return nil, fmt.Errorf("unexpected query: %s", sql) - } - return q.rows, nil -} - -type fakePostgreSQLRows struct { - values []any - read bool - closed bool - err error -} - -func (r *fakePostgreSQLRows) Close() { - r.closed = true -} - -func (r *fakePostgreSQLRows) Err() error { - return r.err -} - -func (r *fakePostgreSQLRows) CommandTag() pgconn.CommandTag { - return pgconn.CommandTag{} -} - -func (r *fakePostgreSQLRows) FieldDescriptions() []pgconn.FieldDescription { - return nil -} - -func (r *fakePostgreSQLRows) Next() bool { - if r.read { - r.Close() - return false - } - r.read = true - return true -} - -func (r *fakePostgreSQLRows) Scan(dest ...any) error { - return fakePostgreSQLRow{values: r.values}.Scan(dest...) -} - -func (r *fakePostgreSQLRows) Values() ([]any, error) { - return r.values, nil -} - -func (r *fakePostgreSQLRows) RawValues() [][]byte { - return nil -} - -func (r *fakePostgreSQLRows) Conn() *pgx.Conn { - return nil -} - -func postgreSQLAuditLogRowValues(errorType any) []any { - return []any{ - "entry-null-error-type", - time.Unix(1700000000, 0).UTC(), - int64(1234), - "gpt-4o-mini", - "gpt-4o-mini", - "openai", - "primary-openai", - false, - nil, - nil, - 200, - "req-1", - nil, - "master_key", - "127.0.0.1", - "POST", - "/v1/chat/completions", - "/", - false, - errorType, - `{"user_agent":"test-agent"}`, - } -} - -func TestPostgreSQLReaderGetLogsAllowsNullErrorType(t *testing.T) { - rows := &fakePostgreSQLRows{values: postgreSQLAuditLogRowValues(nil)} - reader := &PostgreSQLReader{ - pool: fakePostgreSQLQueryer{ - count: 1, - rows: rows, - }, - } - - result, err := reader.GetLogs(context.Background(), LogQueryParams{Limit: 10}) - if err != nil { - t.Fatalf("GetLogs failed: %v", err) - } - if result.Total != 1 { - t.Fatalf("Total = %d, want 1", result.Total) - } - if len(result.Entries) != 1 { - t.Fatalf("len(Entries) = %d, want 1", len(result.Entries)) - } - entry := result.Entries[0] - if entry.ErrorType != "" { - t.Fatalf("ErrorType = %q, want empty", entry.ErrorType) - } - if entry.ProviderName != "primary-openai" { - t.Fatalf("ProviderName = %q, want primary-openai", entry.ProviderName) - } - if entry.Data == nil || entry.Data.UserAgent != "test-agent" { - t.Fatalf("Data = %#v, want user_agent", entry.Data) - } - if !rows.closed { - t.Fatal("rows were not closed") - } -} - -func TestScanPostgreSQLLogEntryAllowsNullErrorType(t *testing.T) { - entry, err := scanPostgreSQLLogEntry(fakePostgreSQLRow{values: postgreSQLAuditLogRowValues(nil)}) - if err != nil { - t.Fatalf("scanPostgreSQLLogEntry failed: %v", err) - } - if entry.ErrorType != "" { - t.Fatalf("ErrorType = %q, want empty", entry.ErrorType) - } - if entry.ProviderName != "primary-openai" { - t.Fatalf("ProviderName = %q, want primary-openai", entry.ProviderName) - } - if entry.AuthMethod != "master_key" { - t.Fatalf("AuthMethod = %q, want master_key", entry.AuthMethod) - } - if entry.Data == nil || entry.Data.UserAgent != "test-agent" { - t.Fatalf("Data = %#v, want user_agent", entry.Data) - } -} diff --git a/internal/auditlog/reader_sql.go b/internal/auditlog/reader_sql.go new file mode 100644 index 000000000..ab81529f8 --- /dev/null +++ b/internal/auditlog/reader_sql.go @@ -0,0 +1,409 @@ +package auditlog + +import ( + "context" + "fmt" + "log/slog" + "strings" + "time" + + "github.com/goccy/go-json" + + "github.com/enterpilot/gomodel/internal/storage/sqlutil" + "github.com/enterpilot/gomodel/internal/storage/sqlx" +) + +// SQLReader implements Reader for SQL databases. +type SQLReader struct { + db sqlx.DB + dialect readerDialect +} + +// NewSQLReader creates an audit log reader over a SQL database. +func NewSQLReader(db sqlx.DB) (*SQLReader, error) { + if db == nil { + return nil, fmt.Errorf("database connection is required") + } + return &SQLReader{db: db, dialect: readerDialectFor(db.Dialect())}, nil +} + +// readerDialect holds the handful of spellings the two engines genuinely +// disagree on. Everything else in this reader is one query for both. +type readerDialect struct { + // like is the case-insensitive match operator. SQLite's LIKE already + // ignores case for ASCII; PostgreSQL's does not, and needs ILIKE. + like string + + // idColumn and attemptIDColumn reference the primary key. A PostgreSQL + // database created before the stores were unified still has UUID columns + // there — CREATE TABLE IF NOT EXISTS did not reshape it — so both are cast + // to text before comparing with a string. + idColumn string + attemptIDColumn string + + // errorMessage, responseID and previousResponseID extract JSON fields. + // The PostgreSQL spellings match the expressions jsonPathIndexes creates, + // which is what lets the planner use those indexes. + errorMessage string + responseID string + previousResponseID string + + // timestampBound converts a date-range boundary. SQLite compares the + // column as text, so the boundary must be a prefix of the stored RFC3339 + // form: a full RFC3339 boundary would sort *after* a fractional-second + // timestamp in the same second and pull the next day's first rows in. + timestampBound func(time.Time) any + + // statsHour buckets a row into its UTC hour. SQLite's strftime also + // normalises the stored timestamp variants (space separator, fractional + // seconds, offsets) that its text column may hold. + statsHour string +} + +func readerDialectFor(dialect sqlx.Dialect) readerDialect { + if dialect == sqlx.PostgreSQL { + return readerDialect{ + like: "ILIKE", + idColumn: "id::text", + attemptIDColumn: "audit_log_id::text", + errorMessage: `data->>'error_message'`, + responseID: `data #>> '{response_body,id}'`, + previousResponseID: `data #>> '{request_body,previous_response_id}'`, + timestampBound: func(t time.Time) any { return t.UTC() }, + statsHour: `date_trunc('hour', timestamp AT TIME ZONE 'UTC')`, + } + } + return readerDialect{ + like: "LIKE", + idColumn: "id", + attemptIDColumn: "audit_log_id", + errorMessage: `json_extract(data, '$.error_message')`, + responseID: `json_extract(data, '$.response_body.id')`, + previousResponseID: `json_extract(data, '$.request_body.previous_response_id')`, + timestampBound: func(t time.Time) any { return t.UTC().Format(sqliteTimestampBoundaryLayout) }, + statsHour: `strftime('%Y-%m-%dT%H', REPLACE(timestamp, ' ', 'T'))`, + } +} + +const sqliteTimestampBoundaryLayout = "2006-01-02T15:04:05" + +const selectLogColumns = `SELECT id, timestamp, duration_ns, requested_model, resolved_model, + provider, provider_name, alias_used, workflow_version_id, cache_type, status_code, + request_id, auth_key_id, auth_method, client_ip, method, path, user_path, stream, + error_type, data + FROM audit_logs` + +// GetLogs returns a paginated list of audit log entries. +func (r *SQLReader) GetLogs(ctx context.Context, params LogQueryParams) (*LogListResult, error) { + limit, offset := clampLimitOffset(params.Limit, params.Offset) + + conditions, args, err := r.logFilters(params) + if err != nil { + return nil, err + } + where := sqlutil.BuildWhereClause(conditions) + + var total int + if err := r.db.QueryRow(ctx, "SELECT COUNT(*) FROM audit_logs"+where, args...).Scan(&total); err != nil { + return nil, fmt.Errorf("failed to count audit log entries: %w", err) + } + + rows, err := r.db.Query(ctx, + selectLogColumns+where+" ORDER BY timestamp DESC LIMIT ? OFFSET ?", + append(append([]any(nil), args...), limit, offset)...) + if err != nil { + return nil, fmt.Errorf("failed to query audit logs: %w", err) + } + defer rows.Close() + + entries := make([]LogEntry, 0) + for rows.Next() { + entry, err := scanSQLLogEntry(rows) + if err != nil { + return nil, err + } + entries = append(entries, *entry) + } + if err := rows.Err(); err != nil { + return nil, fmt.Errorf("error iterating audit log rows: %w", err) + } + rows.Close() + + if err := r.loadAttempts(ctx, entries); err != nil { + return nil, err + } + return &LogListResult{Entries: entries, Total: total, Limit: limit, Offset: offset}, nil +} + +// logFilters builds the WHERE conditions for a log query. Placeholders are +// written as `?` throughout; the adapter renumbers them for PostgreSQL. +func (r *SQLReader) logFilters(params LogQueryParams) ([]string, []any, error) { + userPath, err := normalizeAuditUserPathFilter(params.UserPath) + if err != nil { + return nil, nil, err + } + + var conditions []string + var args []any + add := func(condition string, values ...any) { + conditions = append(conditions, condition) + args = append(args, values...) + } + contains := func(value string) string { + return "%" + sqlutil.EscapeLikeWildcards(value) + "%" + } + + if !params.StartDate.IsZero() { + add("timestamp >= ?", r.dialect.timestampBound(params.StartDate)) + } + if !params.EndDate.IsZero() { + add("timestamp < ?", r.dialect.timestampBound(params.EndDate.AddDate(0, 0, 1))) + } + if params.RequestedModel != "" { + add(r.likeClause("requested_model"), contains(params.RequestedModel)) + } + if params.Provider != "" { + add("("+r.likeClause("provider")+" OR "+r.likeClause("provider_name")+")", + contains(params.Provider), contains(params.Provider)) + } + if params.Method != "" { + add("method = ?", params.Method) + } + if params.Path != "" { + add(r.likeClause("path"), contains(params.Path)) + } + if userPath != "" { + add(auditUserPathSQLPredicate(userPath, "user_path = ?", r.likeClause("user_path")), + userPath, auditUserPathSubtreePattern(userPath)) + } + if params.ErrorType != "" { + add(r.likeClause("error_type"), contains(params.ErrorType)) + } + if params.StatusCode != nil { + add("status_code = ?", *params.StatusCode) + } + if params.Stream != nil { + add("stream = ?", *params.Stream) + } + if params.Search != "" { + searchColumns := []string{ + "request_id", "auth_key_id", "requested_model", "provider", "provider_name", + "method", "path", "user_path", "error_type", r.dialect.errorMessage, + } + clauses := make([]string, 0, len(searchColumns)) + values := make([]any, 0, len(searchColumns)) + for _, column := range searchColumns { + clauses = append(clauses, r.likeClause(column)) + values = append(values, contains(params.Search)) + } + add("("+strings.Join(clauses, " OR ")+")", values...) + } + return conditions, args, nil +} + +func (r *SQLReader) likeClause(column string) string { + return column + " " + r.dialect.like + ` ? ESCAPE '\'` +} + +// GetLogByID returns a single audit log entry by ID. +func (r *SQLReader) GetLogByID(ctx context.Context, id string) (*LogEntry, error) { + return r.queryLogEntryWithAttempts(ctx, + selectLogColumns+" WHERE "+r.dialect.idColumn+" = ? LIMIT 1", id) +} + +// GetConversation returns a linear conversation thread around a seed log entry. +func (r *SQLReader) GetConversation(ctx context.Context, logID string, limit int) (*ConversationResult, error) { + return buildConversationThread(ctx, logID, limit, r.GetLogByID, r.findByResponseID, r.findByPreviousResponseID) +} + +func (r *SQLReader) findByResponseID(ctx context.Context, responseID string) (*LogEntry, error) { + return r.queryLogEntryWithAttempts(ctx, + selectLogColumns+" WHERE "+r.dialect.responseID+" = ? ORDER BY timestamp ASC LIMIT 1", responseID) +} + +func (r *SQLReader) findByPreviousResponseID(ctx context.Context, previousResponseID string) (*LogEntry, error) { + return r.queryLogEntryWithAttempts(ctx, + selectLogColumns+" WHERE "+r.dialect.previousResponseID+" = ? ORDER BY timestamp ASC LIMIT 1", previousResponseID) +} + +// queryLogEntryWithAttempts runs a single-row audit log query, scans the entry, +// and hydrates its provider attempts. Returns (nil, nil) when no row matches. +func (r *SQLReader) queryLogEntryWithAttempts(ctx context.Context, query, arg string) (*LogEntry, error) { + rows, err := r.db.Query(ctx, query, arg) + if err != nil { + return nil, fmt.Errorf("failed to query audit log: %w", err) + } + defer rows.Close() + + if !rows.Next() { + if err := rows.Err(); err != nil { + return nil, fmt.Errorf("failed to read audit log row: %w", err) + } + return nil, nil + } + entry, err := scanSQLLogEntry(rows) + if err != nil { + return nil, err + } + rows.Close() + + hydrated := []LogEntry{*entry} + if err := r.loadAttempts(ctx, hydrated); err != nil { + return nil, err + } + *entry = hydrated[0] + return entry, nil +} + +func (r *SQLReader) loadAttempts(ctx context.Context, entries []LogEntry) error { + if len(entries) == 0 { + return nil + } + + // Batch all entries into a single query keyed by audit_log_id to avoid an + // N+1 read (one query per returned log) when hydrating a page of entries. + // A page is capped at 100 rows, well inside SQLite's parameter limit. + ids := make([]any, len(entries)) + index := make(map[string]int, len(entries)) + for i := range entries { + ids[i] = entries[i].ID + index[entries[i].ID] = i + } + placeholders := strings.TrimSuffix(strings.Repeat("?,", len(ids)), ",") + + rows, err := r.db.Query(ctx, fmt.Sprintf(` + SELECT %s, seq, kind, provider_type, provider_name, model, status_code, success, + error_type, error_code, error_message, response_body, response_headers, started_at, duration_ns + FROM audit_log_attempts + WHERE %s IN (%s) + ORDER BY audit_log_id ASC, seq ASC + `, r.dialect.attemptIDColumn, r.dialect.attemptIDColumn, placeholders), ids...) + if err != nil { + // A database written before attempts existed has no such table; its + // logs simply carry no attempts. + if isMissingAuditAttemptsTable(err) { + return nil + } + return fmt.Errorf("failed to query audit log attempts: %w", err) + } + defer rows.Close() + + grouped := make(map[string][]AttemptSnapshot, len(entries)) + for rows.Next() { + auditLogID, attempt, err := scanSQLAttempt(rows) + if err != nil { + return err + } + grouped[auditLogID] = append(grouped[auditLogID], attempt) + } + if err := rows.Err(); err != nil { + return fmt.Errorf("error iterating audit log attempts: %w", err) + } + + for id, attempts := range grouped { + if i, ok := index[id]; ok && len(attempts) > 0 { + ensureLogData(&entries[i]).Attempts = normalizeAttemptSnapshots(attempts) + } + } + return nil +} + +func scanSQLLogEntry(scanner sqlx.Row) (*LogEntry, error) { + var ( + entry LogEntry + timestamp sqlx.Timestamp + providerName *string + workflowVersionID *string + cacheType *string + authKeyID *string + authMethod *string + userPath *string + errorType *string + dataJSON *string + ) + + if err := scanner.Scan( + &entry.ID, ×tamp, &entry.DurationNs, &entry.RequestedModel, &entry.ResolvedModel, + &entry.Provider, &providerName, &entry.AliasUsed, &workflowVersionID, &cacheType, + &entry.StatusCode, &entry.RequestID, &authKeyID, &authMethod, &entry.ClientIP, + &entry.Method, &entry.Path, &userPath, &entry.Stream, &errorType, &dataJSON, + ); err != nil { + return nil, fmt.Errorf("failed to scan audit log row: %w", err) + } + + if !timestamp.Valid && timestamp.Raw != "" { + slog.Warn("failed to parse audit timestamp", "id", entry.ID, "raw_timestamp", timestamp.Raw) + } + entry.Timestamp = timestamp.Time + entry.WorkflowVersionID = sqlutil.DerefTrimmed(workflowVersionID) + entry.AuthKeyID = derefString(authKeyID) + entry.AuthMethod = derefString(authMethod) + entry.UserPath = derefString(userPath) + entry.ErrorType = derefString(errorType) + entry.CacheType = normalizeCacheType(derefString(cacheType)) + entry.ProviderName = displayAuditProviderName(derefString(providerName), entry.Provider) + + if dataJSON != nil && *dataJSON != "" { + var data LogData + if err := json.Unmarshal([]byte(*dataJSON), &data); err != nil { + slog.Warn("failed to unmarshal audit data JSON", "id", entry.ID, "error", err) + } else { + entry.Data = &data + } + } + return &entry, nil +} + +func scanSQLAttempt(scanner sqlx.Row) (string, AttemptSnapshot, error) { + var ( + auditLogID string + attempt AttemptSnapshot + providerType *string + providerName *string + model *string + errorType *string + errorCode *string + errorMessage *string + responseBody *string + responseHeaders *string + startedAt sqlx.Timestamp + ) + + if err := scanner.Scan( + &auditLogID, &attempt.Seq, &attempt.Kind, &providerType, &providerName, &model, + &attempt.StatusCode, &attempt.Success, &errorType, &errorCode, &errorMessage, + &responseBody, &responseHeaders, &startedAt, &attempt.DurationNs, + ); err != nil { + return "", AttemptSnapshot{}, fmt.Errorf("failed to scan audit log attempt: %w", err) + } + + attempt.ProviderType = derefString(providerType) + attempt.ProviderName = derefString(providerName) + attempt.Model = derefString(model) + attempt.ErrorType = derefString(errorType) + attempt.ErrorCode = derefString(errorCode) + attempt.ErrorMessage = derefString(errorMessage) + attempt.ResponseBody = unmarshalAttemptBody(responseBody) + attempt.ResponseHeaders = unmarshalAttemptHeaders(responseHeaders) + if !startedAt.Valid && startedAt.Raw != "" { + slog.Warn("failed to parse audit attempt timestamp", "id", auditLogID, "raw_timestamp", startedAt.Raw) + } + attempt.StartedAt = startedAt.Time + return auditLogID, attempt, nil +} + +func derefString(value *string) string { + if value == nil { + return "" + } + return *value +} + +func isMissingAuditAttemptsTable(err error) bool { + if err == nil { + return false + } + message := strings.ToLower(err.Error()) + return strings.Contains(message, "audit_log_attempts") && + (strings.Contains(message, "no such table") || strings.Contains(message, "does not exist")) +} diff --git a/internal/auditlog/reader_sql_boundary_test.go b/internal/auditlog/reader_sql_boundary_test.go new file mode 100644 index 000000000..88aae66ec --- /dev/null +++ b/internal/auditlog/reader_sql_boundary_test.go @@ -0,0 +1,192 @@ +package auditlog + +import ( + "context" + "testing" + "time" + + "github.com/enterpilot/gomodel/internal/storage/sqlx" + "github.com/enterpilot/gomodel/internal/storage/sqlx/sqlxtest" +) + +func TestSQLReaderGetLogs_IncludesFractionalStartBoundaryAndExcludesFractionalEndBoundary(t *testing.T) { + sqlxtest.Run(t, func(t *testing.T, db sqlx.DB) { + + store, err := newSQLStoreForTest(t, db, 0) + if err != nil { + t.Fatalf("failed to create store: %v", err) + } + + ctx := context.Background() + err = store.WriteBatch(ctx, []*LogEntry{ + { + ID: "start-boundary", + Timestamp: time.Date(2026, 1, 15, 23, 0, 0, 123_000_000, time.UTC), + RequestedModel: "gpt-5", + Provider: "openai", + }, + { + ID: "inside-range", + Timestamp: time.Date(2026, 1, 16, 12, 0, 0, 0, time.UTC), + RequestedModel: "gpt-5", + Provider: "openai", + }, + { + ID: "after-end-boundary", + Timestamp: time.Date(2026, 1, 16, 23, 0, 0, 123_000_000, time.UTC), + RequestedModel: "gpt-5", + Provider: "openai", + }, + }) + if err != nil { + t.Fatalf("failed to seed audit logs: %v", err) + } + + reader, err := NewSQLReader(db) + if err != nil { + t.Fatalf("failed to create reader: %v", err) + } + + location, err := time.LoadLocation("Europe/Warsaw") + if err != nil { + t.Fatalf("failed to load location: %v", err) + } + + result, err := reader.GetLogs(ctx, LogQueryParams{ + QueryParams: QueryParams{ + StartDate: time.Date(2026, 1, 16, 0, 0, 0, 0, location), + EndDate: time.Date(2026, 1, 16, 0, 0, 0, 0, location), + }, + Limit: 10, + Offset: 0, + }) + if err != nil { + t.Fatalf("GetLogs returned error: %v", err) + } + + if result.Total != 2 { + t.Fatalf("expected 2 logs in range, got %d", result.Total) + } + if len(result.Entries) != 2 { + t.Fatalf("expected 2 returned entries, got %d", len(result.Entries)) + } + if result.Entries[0].ID != "inside-range" { + t.Fatalf("expected latest in-range entry %q, got %q", "inside-range", result.Entries[0].ID) + } + if result.Entries[1].ID != "start-boundary" { + t.Fatalf("expected boundary entry %q, got %q", "start-boundary", result.Entries[1].ID) + } + }) +} + +func TestSQLReaderGetLogs_SearchMatchesUserPath(t *testing.T) { + sqlxtest.Run(t, func(t *testing.T, db sqlx.DB) { + + store, err := newSQLStoreForTest(t, db, 0) + if err != nil { + t.Fatalf("failed to create store: %v", err) + } + + ctx := context.Background() + if err := store.WriteBatch(ctx, []*LogEntry{ + { + ID: "team-match", + Timestamp: time.Date(2026, 1, 16, 12, 0, 0, 0, time.UTC), + RequestedModel: "gpt-5", + Provider: "openai", + UserPath: "/team/alpha", + }, + { + ID: "other-team", + Timestamp: time.Date(2026, 1, 16, 11, 0, 0, 0, time.UTC), + RequestedModel: "gpt-5", + Provider: "openai", + UserPath: "/org/beta", + }, + }); err != nil { + t.Fatalf("failed to seed audit logs: %v", err) + } + + reader, err := NewSQLReader(db) + if err != nil { + t.Fatalf("failed to create reader: %v", err) + } + + result, err := reader.GetLogs(ctx, LogQueryParams{ + Search: "team/alpha", + Limit: 10, + }) + if err != nil { + t.Fatalf("GetLogs returned error: %v", err) + } + + if result.Total != 1 { + t.Fatalf("expected 1 log in search result, got %d", result.Total) + } + if len(result.Entries) != 1 { + t.Fatalf("expected 1 returned entry, got %d", len(result.Entries)) + } + if result.Entries[0].ID != "team-match" { + t.Fatalf("expected matching entry %q, got %q", "team-match", result.Entries[0].ID) + } + }) +} + +func TestSQLReaderGetLogs_SearchMatchesErrorMessage(t *testing.T) { + sqlxtest.Run(t, func(t *testing.T, db sqlx.DB) { + + store, err := newSQLStoreForTest(t, db, 0) + if err != nil { + t.Fatalf("failed to create store: %v", err) + } + + ctx := context.Background() + if err := store.WriteBatch(ctx, []*LogEntry{ + { + ID: "timeout-match", + Timestamp: time.Date(2026, 1, 16, 12, 0, 0, 0, time.UTC), + RequestedModel: "gpt-5", + Provider: "openai", + ErrorType: "provider_error", + Data: &LogData{ + ErrorMessage: `failed to send request: Post "https://api.openai.com/v1/chat/completions": http2: timeout awaiting response headers`, + }, + }, + { + ID: "other-error", + Timestamp: time.Date(2026, 1, 16, 11, 0, 0, 0, time.UTC), + RequestedModel: "gpt-5", + Provider: "openai", + ErrorType: "provider_error", + Data: &LogData{ + ErrorMessage: "upstream refused connection", + }, + }, + }); err != nil { + t.Fatalf("failed to seed audit logs: %v", err) + } + + reader, err := NewSQLReader(db) + if err != nil { + t.Fatalf("failed to create sqlite reader: %v", err) + } + + result, err := reader.GetLogs(ctx, LogQueryParams{ + Search: "timeout awaiting response headers", + Limit: 10, + }) + if err != nil { + t.Fatalf("GetLogs returned error: %v", err) + } + + if result.Total != 1 { + t.Fatalf("expected 1 log in search result, got %d", result.Total) + } + if len(result.Entries) != 1 { + t.Fatalf("expected 1 returned entry, got %d", len(result.Entries)) + } + if result.Entries[0].ID != "timeout-match" { + t.Fatalf("expected matching entry %q, got %q", "timeout-match", result.Entries[0].ID) + } + }) +} diff --git a/internal/auditlog/reader_sqlite.go b/internal/auditlog/reader_sqlite.go deleted file mode 100644 index 1fae5cf29..000000000 --- a/internal/auditlog/reader_sqlite.go +++ /dev/null @@ -1,497 +0,0 @@ -package auditlog - -import ( - "github.com/enterpilot/gomodel/internal/storage/sqlutil" - - "context" - "database/sql" - "fmt" - "log/slog" - "sort" - "strings" - "time" - - "github.com/goccy/go-json" -) - -const sqliteTimestampBoundaryLayout = "2006-01-02T15:04:05" - -// SQLiteReader implements Reader for SQLite databases. -type SQLiteReader struct { - db *sql.DB -} - -// NewSQLiteReader creates a new SQLite audit log reader. -func NewSQLiteReader(db *sql.DB) (*SQLiteReader, error) { - if db == nil { - return nil, fmt.Errorf("database connection is required") - } - return &SQLiteReader{db: db}, nil -} - -// GetLogs returns a paginated list of audit log entries. -func (r *SQLiteReader) GetLogs(ctx context.Context, params LogQueryParams) (*LogListResult, error) { - limit, offset := clampLimitOffset(params.Limit, params.Offset) - - conditions, args := sqliteDateRangeConditions(params.QueryParams) - userPath, err := normalizeAuditUserPathFilter(params.UserPath) - if err != nil { - return nil, err - } - - if params.RequestedModel != "" { - conditions = append(conditions, "requested_model LIKE ? ESCAPE '\\'") - args = append(args, "%"+sqlutil.EscapeLikeWildcards(params.RequestedModel)+"%") - } - if params.Provider != "" { - conditions = append(conditions, "(provider LIKE ? ESCAPE '\\' OR provider_name LIKE ? ESCAPE '\\')") - args = append(args, "%"+sqlutil.EscapeLikeWildcards(params.Provider)+"%", "%"+sqlutil.EscapeLikeWildcards(params.Provider)+"%") - } - if params.Method != "" { - conditions = append(conditions, "method = ?") - args = append(args, params.Method) - } - if params.Path != "" { - conditions = append(conditions, "path LIKE ? ESCAPE '\\'") - args = append(args, "%"+sqlutil.EscapeLikeWildcards(params.Path)+"%") - } - if userPath != "" { - conditions = append(conditions, auditUserPathSQLPredicate(userPath, "user_path = ?", "user_path LIKE ? ESCAPE '\\'")) - args = append(args, userPath, auditUserPathSubtreePattern(userPath)) - } - if params.ErrorType != "" { - conditions = append(conditions, "error_type LIKE ? ESCAPE '\\'") - args = append(args, "%"+sqlutil.EscapeLikeWildcards(params.ErrorType)+"%") - } - if params.StatusCode != nil { - conditions = append(conditions, "status_code = ?") - args = append(args, *params.StatusCode) - } - if params.Stream != nil { - conditions = append(conditions, "stream = ?") - if *params.Stream { - args = append(args, 1) - } else { - args = append(args, 0) - } - } - if params.Search != "" { - s := "%" + sqlutil.EscapeLikeWildcards(params.Search) + "%" - conditions = append(conditions, `(request_id LIKE ? ESCAPE '\' OR auth_key_id LIKE ? ESCAPE '\' OR requested_model LIKE ? ESCAPE '\' OR provider LIKE ? ESCAPE '\' OR provider_name LIKE ? ESCAPE '\' OR method LIKE ? ESCAPE '\' OR path LIKE ? ESCAPE '\' OR user_path LIKE ? ESCAPE '\' OR error_type LIKE ? ESCAPE '\' OR json_extract(data, '$.error_message') LIKE ? ESCAPE '\')`) - args = append(args, s, s, s, s, s, s, s, s, s, s) - } - - where := sqlutil.BuildWhereClause(conditions) - - // Count total - var total int - countQuery := "SELECT COUNT(*) FROM audit_logs" + where - if err := r.db.QueryRowContext(ctx, countQuery, args...).Scan(&total); err != nil { - return nil, fmt.Errorf("failed to count audit log entries: %w", err) - } - - dataQuery := `SELECT id, timestamp, duration_ns, requested_model, resolved_model, provider, provider_name, alias_used, workflow_version_id, cache_type, status_code, request_id, auth_key_id, auth_method, - client_ip, method, path, user_path, stream, error_type, data - FROM audit_logs` + where + ` ORDER BY timestamp DESC LIMIT ? OFFSET ?` - dataArgs := append(append([]any(nil), args...), limit, offset) - - rows, err := r.db.QueryContext(ctx, dataQuery, dataArgs...) - if err != nil { - return nil, fmt.Errorf("failed to query audit logs: %w", err) - } - defer rows.Close() - - entries := make([]LogEntry, 0) - for rows.Next() { - var e LogEntry - var ts string - var providerName sql.NullString - var aliasUsedInt int - var streamInt int - var dataJSON *string - var workflowVersionID sql.NullString - var cacheType sql.NullString - var authKeyID sql.NullString - var authMethod sql.NullString - var userPath sql.NullString - var errorType sql.NullString - - if err := rows.Scan(&e.ID, &ts, &e.DurationNs, &e.RequestedModel, &e.ResolvedModel, &e.Provider, &providerName, &aliasUsedInt, &workflowVersionID, &cacheType, &e.StatusCode, - &e.RequestID, &authKeyID, &authMethod, &e.ClientIP, &e.Method, &e.Path, &userPath, &streamInt, &errorType, &dataJSON); err != nil { - return nil, fmt.Errorf("failed to scan audit log row: %w", err) - } - - e.AliasUsed = aliasUsedInt == 1 - e.Stream = streamInt == 1 - e.Timestamp = parseSQLTimestamp(ts, e.ID) - if workflowVersionID.Valid { - e.WorkflowVersionID = workflowVersionID.String - } - if authKeyID.Valid { - e.AuthKeyID = authKeyID.String - } - if authMethod.Valid { - e.AuthMethod = authMethod.String - } - if cacheType.Valid { - e.CacheType = normalizeCacheType(cacheType.String) - } - if providerName.Valid { - e.ProviderName = displayAuditProviderName(providerName.String, e.Provider) - } else { - e.ProviderName = displayAuditProviderName("", e.Provider) - } - if userPath.Valid { - e.UserPath = userPath.String - } - if errorType.Valid { - e.ErrorType = errorType.String - } - - if dataJSON != nil && *dataJSON != "" { - var data LogData - if err := json.Unmarshal([]byte(*dataJSON), &data); err != nil { - slog.Warn("failed to unmarshal audit data JSON", "id", e.ID, "error", err) - } else { - e.Data = &data - } - } - - entries = append(entries, e) - } - - if err := rows.Err(); err != nil { - return nil, fmt.Errorf("error iterating audit log rows: %w", err) - } - if err := rows.Close(); err != nil { - return nil, fmt.Errorf("failed to close audit log rows: %w", err) - } - if err := r.loadAttempts(ctx, entries); err != nil { - return nil, err - } - - return &LogListResult{ - Entries: entries, - Total: total, - Limit: limit, - Offset: offset, - }, nil -} - -// queryLogEntryWithAttempts runs a single-row audit log query, scans the entry, -// and hydrates its provider attempts. Returns (nil, nil) when no row matches. -func (r *SQLiteReader) queryLogEntryWithAttempts(ctx context.Context, query, arg string) (*LogEntry, error) { - rows, err := r.db.QueryContext(ctx, query, arg) - if err != nil { - return nil, fmt.Errorf("failed to query audit log: %w", err) - } - defer rows.Close() - if !rows.Next() { - if err := rows.Err(); err != nil { - return nil, fmt.Errorf("failed to read audit log row: %w", err) - } - return nil, nil - } - entry, err := scanSQLiteLogEntry(rows) - if err != nil { - return nil, err - } - if err := rows.Close(); err != nil { - return nil, fmt.Errorf("failed to close audit log row: %w", err) - } - hydrated := []LogEntry{*entry} - if err := r.loadAttempts(ctx, hydrated); err != nil { - return nil, err - } - *entry = hydrated[0] - return entry, nil -} - -// GetLogByID returns a single audit log entry by ID. -func (r *SQLiteReader) GetLogByID(ctx context.Context, id string) (*LogEntry, error) { - return r.queryLogEntryWithAttempts(ctx, `SELECT id, timestamp, duration_ns, requested_model, resolved_model, provider, provider_name, alias_used, workflow_version_id, cache_type, status_code, request_id, auth_key_id, auth_method, - client_ip, method, path, user_path, stream, error_type, data - FROM audit_logs WHERE id = ? LIMIT 1`, id) -} - -// GetConversation returns a linear conversation thread around a seed log entry. -func (r *SQLiteReader) GetConversation(ctx context.Context, logID string, limit int) (*ConversationResult, error) { - limit = clampConversationLimit(limit) - - anchor, err := r.GetLogByID(ctx, logID) - if err != nil { - return nil, err - } - if anchor == nil { - return &ConversationResult{ - AnchorID: logID, - Entries: []LogEntry{}, - }, nil - } - - thread := []*LogEntry{anchor} - seen := map[string]struct{}{anchor.ID: {}} - - // Walk backwards through previous_response_id links. - current := anchor - for len(thread) < limit { - prevID := extractPreviousResponseID(current) - if prevID == "" { - break - } - parent, err := r.findByResponseID(ctx, prevID) - if err != nil { - return nil, err - } - if parent == nil { - break - } - if _, ok := seen[parent.ID]; ok { - break - } - thread = append(thread, parent) - seen[parent.ID] = struct{}{} - current = parent - } - - // Walk forwards via entries whose previous_response_id points to current response id. - current = anchor - for len(thread) < limit { - respID := extractResponseID(current) - if respID == "" { - break - } - child, err := r.findByPreviousResponseID(ctx, respID) - if err != nil { - return nil, err - } - if child == nil { - break - } - if _, ok := seen[child.ID]; ok { - break - } - thread = append(thread, child) - seen[child.ID] = struct{}{} - current = child - } - - sort.Slice(thread, func(i, j int) bool { - return thread[i].Timestamp.Before(thread[j].Timestamp) - }) - - entries := make([]LogEntry, 0, len(thread)) - for _, entry := range thread { - if entry != nil { - entries = append(entries, *entry) - } - } - - return &ConversationResult{ - AnchorID: anchor.ID, - Entries: entries, - }, nil -} - -func sqliteDateRangeConditions(params QueryParams) (conditions []string, args []any) { - if !params.StartDate.IsZero() { - conditions = append(conditions, "timestamp >= ?") - args = append(args, sqliteTimestampBoundary(params.StartDate)) - } - if !params.EndDate.IsZero() { - conditions = append(conditions, "timestamp < ?") - args = append(args, sqliteTimestampBoundary(params.EndDate.AddDate(0, 0, 1))) - } - return conditions, args -} - -func sqliteTimestampBoundary(t time.Time) string { - return t.UTC().Format(sqliteTimestampBoundaryLayout) -} - -func parseSQLTimestamp(ts string, entryID string) time.Time { - t, ok := sqlutil.ParseSQLiteTimestamp(ts) - if !ok { - slog.Warn("failed to parse audit timestamp", "id", entryID, "raw_timestamp", ts) - } - return t -} - -func (r *SQLiteReader) findByResponseID(ctx context.Context, responseID string) (*LogEntry, error) { - return r.queryLogEntryWithAttempts(ctx, `SELECT id, timestamp, duration_ns, requested_model, resolved_model, provider, provider_name, alias_used, workflow_version_id, cache_type, status_code, request_id, auth_key_id, auth_method, - client_ip, method, path, user_path, stream, error_type, data - FROM audit_logs - WHERE json_extract(data, '$.response_body.id') = ? - ORDER BY timestamp ASC - LIMIT 1`, responseID) -} - -func (r *SQLiteReader) findByPreviousResponseID(ctx context.Context, previousResponseID string) (*LogEntry, error) { - return r.queryLogEntryWithAttempts(ctx, `SELECT id, timestamp, duration_ns, requested_model, resolved_model, provider, provider_name, alias_used, workflow_version_id, cache_type, status_code, request_id, auth_key_id, auth_method, - client_ip, method, path, user_path, stream, error_type, data - FROM audit_logs - WHERE json_extract(data, '$.request_body.previous_response_id') = ? - ORDER BY timestamp ASC - LIMIT 1`, previousResponseID) -} - -func (r *SQLiteReader) loadAttempts(ctx context.Context, entries []LogEntry) error { - if len(entries) == 0 { - return nil - } - - // Batch all entries into a single query keyed by audit_log_id to avoid an - // N+1 read (one query per returned log) when hydrating a page of entries. - ids := make([]any, len(entries)) - index := make(map[string]int, len(entries)) - for i := range entries { - ids[i] = entries[i].ID - index[entries[i].ID] = i - } - placeholders := strings.TrimSuffix(strings.Repeat("?,", len(ids)), ",") - rows, err := r.db.QueryContext(ctx, fmt.Sprintf(` - SELECT audit_log_id, seq, kind, provider_type, provider_name, model, status_code, success, - error_type, error_code, error_message, response_body, response_headers, started_at, duration_ns - FROM audit_log_attempts - WHERE audit_log_id IN (%s) - ORDER BY audit_log_id ASC, seq ASC - `, placeholders), ids...) - if err != nil { - if isMissingSQLiteAuditAttemptsTable(err) { - return nil - } - return fmt.Errorf("failed to query audit log attempts: %w", err) - } - defer rows.Close() - - grouped := make(map[string][]AttemptSnapshot, len(entries)) - for rows.Next() { - var auditLogID string - var attempt AttemptSnapshot - var providerType, providerName, model sql.NullString - var errorType, errorCode, errorMessage sql.NullString - var responseBody, responseHeaders sql.NullString - var startedAt sql.NullString - var successInt int - if err := rows.Scan( - &auditLogID, - &attempt.Seq, - &attempt.Kind, - &providerType, - &providerName, - &model, - &attempt.StatusCode, - &successInt, - &errorType, - &errorCode, - &errorMessage, - &responseBody, - &responseHeaders, - &startedAt, - &attempt.DurationNs, - ); err != nil { - return fmt.Errorf("failed to scan audit log attempt: %w", err) - } - attempt.Success = successInt == 1 - if responseBody.Valid { - attempt.ResponseBody = unmarshalAttemptBody(&responseBody.String) - } - if responseHeaders.Valid { - attempt.ResponseHeaders = unmarshalAttemptHeaders(&responseHeaders.String) - } - if providerType.Valid { - attempt.ProviderType = providerType.String - } - if providerName.Valid { - attempt.ProviderName = providerName.String - } - if model.Valid { - attempt.Model = model.String - } - if errorType.Valid { - attempt.ErrorType = errorType.String - } - if errorCode.Valid { - attempt.ErrorCode = errorCode.String - } - if errorMessage.Valid { - attempt.ErrorMessage = errorMessage.String - } - if startedAt.Valid { - attempt.StartedAt = parseSQLTimestamp(startedAt.String, auditLogID) - } - grouped[auditLogID] = append(grouped[auditLogID], attempt) - } - if err := rows.Err(); err != nil { - return fmt.Errorf("error iterating audit log attempts: %w", err) - } - - for id, attempts := range grouped { - if i, ok := index[id]; ok && len(attempts) > 0 { - ensureLogData(&entries[i]).Attempts = normalizeAttemptSnapshots(attempts) - } - } - return nil -} - -func scanSQLiteLogEntry(rows *sql.Rows) (*LogEntry, error) { - var e LogEntry - var ts string - var providerName sql.NullString - var aliasUsedInt int - var streamInt int - var dataJSON *string - var workflowVersionID sql.NullString - var cacheType sql.NullString - var authKeyID sql.NullString - var authMethod sql.NullString - var userPath sql.NullString - var errorType sql.NullString - - if err := rows.Scan(&e.ID, &ts, &e.DurationNs, &e.RequestedModel, &e.ResolvedModel, &e.Provider, &providerName, &aliasUsedInt, &workflowVersionID, &cacheType, &e.StatusCode, - &e.RequestID, &authKeyID, &authMethod, &e.ClientIP, &e.Method, &e.Path, &userPath, &streamInt, &errorType, &dataJSON); err != nil { - return nil, fmt.Errorf("failed to scan audit log row: %w", err) - } - - e.AliasUsed = aliasUsedInt == 1 - e.Stream = streamInt == 1 - e.Timestamp = parseSQLTimestamp(ts, e.ID) - if workflowVersionID.Valid { - e.WorkflowVersionID = workflowVersionID.String - } - if authKeyID.Valid { - e.AuthKeyID = authKeyID.String - } - if authMethod.Valid { - e.AuthMethod = authMethod.String - } - if cacheType.Valid { - e.CacheType = normalizeCacheType(cacheType.String) - } - if providerName.Valid { - e.ProviderName = displayAuditProviderName(providerName.String, e.Provider) - } else { - e.ProviderName = displayAuditProviderName("", e.Provider) - } - if userPath.Valid { - e.UserPath = userPath.String - } - if errorType.Valid { - e.ErrorType = errorType.String - } - - if dataJSON != nil && *dataJSON != "" { - var data LogData - if err := json.Unmarshal([]byte(*dataJSON), &data); err != nil { - slog.Warn("failed to unmarshal audit data JSON", "id", e.ID, "error", err) - } else { - e.Data = &data - } - } - - return &e, nil -} - -func isMissingSQLiteAuditAttemptsTable(err error) bool { - return err != nil && strings.Contains(strings.ToLower(err.Error()), "no such table: audit_log_attempts") -} diff --git a/internal/auditlog/reader_sqlite_boundary_test.go b/internal/auditlog/reader_sqlite_boundary_test.go deleted file mode 100644 index 7fabaa182..000000000 --- a/internal/auditlog/reader_sqlite_boundary_test.go +++ /dev/null @@ -1,189 +0,0 @@ -package auditlog - -import ( - "context" - "testing" - "time" -) - -func TestSQLiteReaderGetLogs_IncludesFractionalStartBoundaryAndExcludesFractionalEndBoundary(t *testing.T) { - db := createTestDB(t) - defer db.Close() - - store, err := newSQLiteStore(t, db, 0) - if err != nil { - t.Fatalf("failed to create store: %v", err) - } - - ctx := context.Background() - err = store.WriteBatch(ctx, []*LogEntry{ - { - ID: "start-boundary", - Timestamp: time.Date(2026, 1, 15, 23, 0, 0, 123_000_000, time.UTC), - RequestedModel: "gpt-5", - Provider: "openai", - }, - { - ID: "inside-range", - Timestamp: time.Date(2026, 1, 16, 12, 0, 0, 0, time.UTC), - RequestedModel: "gpt-5", - Provider: "openai", - }, - { - ID: "after-end-boundary", - Timestamp: time.Date(2026, 1, 16, 23, 0, 0, 123_000_000, time.UTC), - RequestedModel: "gpt-5", - Provider: "openai", - }, - }) - if err != nil { - t.Fatalf("failed to seed audit logs: %v", err) - } - - reader, err := NewSQLiteReader(db) - if err != nil { - t.Fatalf("failed to create reader: %v", err) - } - - location, err := time.LoadLocation("Europe/Warsaw") - if err != nil { - t.Fatalf("failed to load location: %v", err) - } - - result, err := reader.GetLogs(ctx, LogQueryParams{ - QueryParams: QueryParams{ - StartDate: time.Date(2026, 1, 16, 0, 0, 0, 0, location), - EndDate: time.Date(2026, 1, 16, 0, 0, 0, 0, location), - }, - Limit: 10, - Offset: 0, - }) - if err != nil { - t.Fatalf("GetLogs returned error: %v", err) - } - - if result.Total != 2 { - t.Fatalf("expected 2 logs in range, got %d", result.Total) - } - if len(result.Entries) != 2 { - t.Fatalf("expected 2 returned entries, got %d", len(result.Entries)) - } - if result.Entries[0].ID != "inside-range" { - t.Fatalf("expected latest in-range entry %q, got %q", "inside-range", result.Entries[0].ID) - } - if result.Entries[1].ID != "start-boundary" { - t.Fatalf("expected boundary entry %q, got %q", "start-boundary", result.Entries[1].ID) - } -} - -func TestSQLiteReaderGetLogs_SearchMatchesUserPath(t *testing.T) { - db := createTestDB(t) - defer db.Close() - - store, err := newSQLiteStore(t, db, 0) - if err != nil { - t.Fatalf("failed to create store: %v", err) - } - - ctx := context.Background() - if err := store.WriteBatch(ctx, []*LogEntry{ - { - ID: "team-match", - Timestamp: time.Date(2026, 1, 16, 12, 0, 0, 0, time.UTC), - RequestedModel: "gpt-5", - Provider: "openai", - UserPath: "/team/alpha", - }, - { - ID: "other-team", - Timestamp: time.Date(2026, 1, 16, 11, 0, 0, 0, time.UTC), - RequestedModel: "gpt-5", - Provider: "openai", - UserPath: "/org/beta", - }, - }); err != nil { - t.Fatalf("failed to seed audit logs: %v", err) - } - - reader, err := NewSQLiteReader(db) - if err != nil { - t.Fatalf("failed to create reader: %v", err) - } - - result, err := reader.GetLogs(ctx, LogQueryParams{ - Search: "team/alpha", - Limit: 10, - }) - if err != nil { - t.Fatalf("GetLogs returned error: %v", err) - } - - if result.Total != 1 { - t.Fatalf("expected 1 log in search result, got %d", result.Total) - } - if len(result.Entries) != 1 { - t.Fatalf("expected 1 returned entry, got %d", len(result.Entries)) - } - if result.Entries[0].ID != "team-match" { - t.Fatalf("expected matching entry %q, got %q", "team-match", result.Entries[0].ID) - } -} - -func TestSQLiteReaderGetLogs_SearchMatchesErrorMessage(t *testing.T) { - db := createTestDB(t) - defer db.Close() - - store, err := newSQLiteStore(t, db, 0) - if err != nil { - t.Fatalf("failed to create store: %v", err) - } - - ctx := context.Background() - if err := store.WriteBatch(ctx, []*LogEntry{ - { - ID: "timeout-match", - Timestamp: time.Date(2026, 1, 16, 12, 0, 0, 0, time.UTC), - RequestedModel: "gpt-5", - Provider: "openai", - ErrorType: "provider_error", - Data: &LogData{ - ErrorMessage: `failed to send request: Post "https://api.openai.com/v1/chat/completions": http2: timeout awaiting response headers`, - }, - }, - { - ID: "other-error", - Timestamp: time.Date(2026, 1, 16, 11, 0, 0, 0, time.UTC), - RequestedModel: "gpt-5", - Provider: "openai", - ErrorType: "provider_error", - Data: &LogData{ - ErrorMessage: "upstream refused connection", - }, - }, - }); err != nil { - t.Fatalf("failed to seed audit logs: %v", err) - } - - reader, err := NewSQLiteReader(db) - if err != nil { - t.Fatalf("failed to create sqlite reader: %v", err) - } - - result, err := reader.GetLogs(ctx, LogQueryParams{ - Search: "timeout awaiting response headers", - Limit: 10, - }) - if err != nil { - t.Fatalf("GetLogs returned error: %v", err) - } - - if result.Total != 1 { - t.Fatalf("expected 1 log in search result, got %d", result.Total) - } - if len(result.Entries) != 1 { - t.Fatalf("expected 1 returned entry, got %d", len(result.Entries)) - } - if result.Entries[0].ID != "timeout-match" { - t.Fatalf("expected matching entry %q, got %q", "timeout-match", result.Entries[0].ID) - } -} diff --git a/internal/auditlog/roundtrip_sql_test.go b/internal/auditlog/roundtrip_sql_test.go new file mode 100644 index 000000000..46a6e2710 --- /dev/null +++ b/internal/auditlog/roundtrip_sql_test.go @@ -0,0 +1,666 @@ +package auditlog + +import ( + "context" + "fmt" + "testing" + "time" + + "github.com/enterpilot/gomodel/internal/storage/sqlx" + "github.com/enterpilot/gomodel/internal/storage/sqlx/sqlxtest" +) + +func newSQLStoreForTest(t *testing.T, db sqlx.DB, retentionDays int) (*SQLStore, error) { + t.Helper() + return NewSQLStore(context.Background(), db, retentionDays) +} + +func TestSQLStore_WriteBatch_NullDataPreservation(t *testing.T) { + sqlxtest.Run(t, func(t *testing.T, db sqlx.DB) { + + store, err := newSQLStoreForTest(t, db, 0) + if err != nil { + t.Fatalf("failed to create store: %v", err) + } + defer store.Close() + + ctx := context.Background() + + // Create entries - one with nil Data, one with Data + entries := []*LogEntry{ + { + ID: "entry-nil-data", + Timestamp: time.Now(), + RequestedModel: "gpt-4", + Provider: "openai", + Data: nil, // This should become SQL NULL + }, + { + ID: "entry-with-data", + Timestamp: time.Now(), + RequestedModel: "gpt-4", + Provider: "openai", + Data: &LogData{ + UserAgent: "test-agent", + }, + }, + } + + // Write entries + if err := store.WriteBatch(ctx, entries); err != nil { + t.Fatalf("WriteBatch failed: %v", err) + } + + // Query to check NULL vs non-NULL + rows, err := db.Query(ctx, "SELECT id, data, data IS NULL as is_null FROM audit_logs ORDER BY id") + if err != nil { + t.Fatalf("query failed: %v", err) + } + defer rows.Close() + + results := make(map[string]bool) // id -> isNull + for rows.Next() { + var id string + var data *string + var isNull bool + if err := rows.Scan(&id, &data, &isNull); err != nil { + t.Fatalf("scan failed: %v", err) + } + results[id] = isNull + } + + // Verify entry with nil Data has NULL in database + if !results["entry-nil-data"] { + t.Error("entry with nil Data should have NULL in database, got non-NULL") + } + + // Verify entry with Data has non-NULL in database + if results["entry-with-data"] { + t.Error("entry with Data should have non-NULL in database, got NULL") + } + }) +} + +func TestSQLStore_WriteBatch_Chunking(t *testing.T) { + sqlxtest.Run(t, func(t *testing.T, db sqlx.DB) { + + store, err := newSQLStoreForTest(t, db, 0) + if err != nil { + t.Fatalf("failed to create store: %v", err) + } + defer store.Close() + + ctx := context.Background() + + // Create more entries than can fit in a single batch (>62 entries) + // Using 150 entries to ensure we need at least 3 batches + numEntries := 150 + entries := make([]*LogEntry, numEntries) + for i := range numEntries { + entries[i] = &LogEntry{ + ID: fmt.Sprintf("entry-%03d", i), + Timestamp: time.Now(), + RequestedModel: "gpt-4", + Provider: "openai", + StatusCode: 200, + } + } + + // Write all entries - this should internally chunk into multiple batches + if err := store.WriteBatch(ctx, entries); err != nil { + t.Fatalf("WriteBatch failed: %v", err) + } + + // Verify all entries were persisted + var count int + if err := db.QueryRow(ctx, "SELECT COUNT(*) FROM audit_logs").Scan(&count); err != nil { + t.Fatalf("count query failed: %v", err) + } + + if count != numEntries { + t.Errorf("expected %d entries, got %d", numEntries, count) + } + + // Verify entries are actually in the database by sampling a few + for _, id := range []string{"entry-000", "entry-062", "entry-124", "entry-149"} { + var found int + err := db.QueryRow(ctx, "SELECT COUNT(*) FROM audit_logs WHERE id = ?", id).Scan(&found) + if err != nil { + t.Fatalf("query for %s failed: %v", id, err) + } + if found != 1 { + t.Errorf("entry %s not found in database", id) + } + } + }) +} + +func TestSQLStore_WriteBatch_EmptyEntries(t *testing.T) { + sqlxtest.Run(t, func(t *testing.T, db sqlx.DB) { + + store, err := newSQLStoreForTest(t, db, 0) + if err != nil { + t.Fatalf("failed to create store: %v", err) + } + defer store.Close() + + ctx := context.Background() + + // Empty slice should not error + if err := store.WriteBatch(ctx, []*LogEntry{}); err != nil { + t.Fatalf("WriteBatch with empty entries failed: %v", err) + } + + // Verify no entries in database + var count int + if err := db.QueryRow(ctx, "SELECT COUNT(*) FROM audit_logs").Scan(&count); err != nil { + t.Fatalf("count query failed: %v", err) + } + if count != 0 { + t.Errorf("expected 0 entries, got %d", count) + } + }) +} + +func TestSQLStore_WriteBatch_ExactBatchBoundary(t *testing.T) { + sqlxtest.Run(t, func(t *testing.T, db sqlx.DB) { + + store, err := newSQLStoreForTest(t, db, 0) + if err != nil { + t.Fatalf("failed to create store: %v", err) + } + defer store.Close() + + ctx := context.Background() + + // Test with exactly maxEntriesPerBatch entries + numEntries := maxEntriesPerBatch + entries := make([]*LogEntry, numEntries) + for i := range numEntries { + entries[i] = &LogEntry{ + ID: fmt.Sprintf("exact-%03d", i), + Timestamp: time.Now(), + RequestedModel: "gpt-4", + } + } + + if err := store.WriteBatch(ctx, entries); err != nil { + t.Fatalf("WriteBatch failed: %v", err) + } + + var count int + if err := db.QueryRow(ctx, "SELECT COUNT(*) FROM audit_logs").Scan(&count); err != nil { + t.Fatalf("count query failed: %v", err) + } + if count != numEntries { + t.Errorf("expected %d entries, got %d", numEntries, count) + } + + // Test with maxEntriesPerBatch + 1 entries - should require 2 batches + entries = make([]*LogEntry, maxEntriesPerBatch+1) + for i := 0; i <= maxEntriesPerBatch; i++ { + entries[i] = &LogEntry{ + ID: fmt.Sprintf("boundary-%03d", i), + Timestamp: time.Now(), + RequestedModel: "gpt-4", + } + } + + if err := store.WriteBatch(ctx, entries); err != nil { + t.Fatalf("WriteBatch failed at boundary: %v", err) + } + + if err := db.QueryRow(ctx, "SELECT COUNT(*) FROM audit_logs").Scan(&count); err != nil { + t.Fatalf("count query failed: %v", err) + } + expectedTotal := numEntries + maxEntriesPerBatch + 1 + if count != expectedTotal { + t.Errorf("expected %d entries, got %d", expectedTotal, count) + } + }) +} + +func TestSQLStore_WriteBatch_PersistsAliasFields(t *testing.T) { + sqlxtest.Run(t, func(t *testing.T, db sqlx.DB) { + + store, err := newSQLStoreForTest(t, db, 0) + if err != nil { + t.Fatalf("failed to create store: %v", err) + } + defer store.Close() + + ctx := context.Background() + entry := &LogEntry{ + ID: "alias-entry", + Timestamp: time.Now(), + RequestedModel: "anthropic/claude-opus-4-6", + ResolvedModel: "openai/gpt-5-nano", + Provider: "openai", + AliasUsed: true, + StatusCode: 200, + } + + if err := store.WriteBatch(ctx, []*LogEntry{entry}); err != nil { + t.Fatalf("WriteBatch failed: %v", err) + } + + reader, err := NewSQLReader(db) + if err != nil { + t.Fatalf("failed to create reader: %v", err) + } + + logEntry, err := reader.GetLogByID(ctx, entry.ID) + if err != nil { + t.Fatalf("GetLogByID failed: %v", err) + } + if logEntry == nil { + t.Fatal("expected log entry, got nil") + return + } + if logEntry.RequestedModel != entry.RequestedModel { + t.Fatalf("RequestedModel = %q, want %q", logEntry.RequestedModel, entry.RequestedModel) + } + if logEntry.ResolvedModel != entry.ResolvedModel { + t.Fatalf("ResolvedModel = %q, want %q", logEntry.ResolvedModel, entry.ResolvedModel) + } + if logEntry.Provider != entry.Provider { + t.Fatalf("Provider = %q, want %q", logEntry.Provider, entry.Provider) + } + if !logEntry.AliasUsed { + t.Fatal("AliasUsed = false, want true") + } + if logEntry.UserPath != "/" { + t.Fatalf("UserPath = %q, want /", logEntry.UserPath) + } + }) +} + +func TestSQLStore_WriteBatch_PersistsProviderAttempts(t *testing.T) { + sqlxtest.Run(t, func(t *testing.T, db sqlx.DB) { + + store, err := newSQLStoreForTest(t, db, 0) + if err != nil { + t.Fatalf("failed to create store: %v", err) + } + defer store.Close() + + ctx := context.Background() + entry := &LogEntry{ + ID: "attempt-entry", + Timestamp: time.Now(), + RequestedModel: "anthropic/claude-fable-5", + ResolvedModel: "openai/gpt-5.5", + Provider: "openai", + StatusCode: 200, + Data: &LogData{ + Failover: &FailoverSnapshot{TargetModel: "openai/gpt-5.5"}, + Attempts: []AttemptSnapshot{ + { + Seq: 1, + Kind: AttemptKindPrimary, + ProviderType: "anthropic", + Model: "anthropic/claude-fable-5", + StatusCode: 404, + ErrorType: "not_found_error", + ErrorCode: "model_not_found", + ErrorMessage: "model is not available", + ResponseBody: map[string]any{ + "error": map[string]any{"message": "model is not available", "code": "model_not_found"}, + }, + ResponseHeaders: map[string]string{"X-Request-Id": "req-123", "Retry-After": "30"}, + }, + { + Seq: 2, + Kind: AttemptKindFailover, + ProviderType: "openai", + Model: "openai/gpt-5.5", + StatusCode: 200, + Success: true, + }, + }, + }, + } + + if err := store.WriteBatch(ctx, []*LogEntry{entry}); err != nil { + t.Fatalf("WriteBatch failed: %v", err) + } + + var attemptRows int + if err := db.QueryRow(ctx, "SELECT COUNT(*) FROM audit_log_attempts WHERE audit_log_id = ?", entry.ID).Scan(&attemptRows); err != nil { + t.Fatalf("count audit_log_attempts failed: %v", err) + } + if attemptRows != 2 { + t.Fatalf("attempt rows = %d, want 2", attemptRows) + } + + reader, err := NewSQLReader(db) + if err != nil { + t.Fatalf("failed to create reader: %v", err) + } + got, err := reader.GetLogByID(ctx, entry.ID) + if err != nil { + t.Fatalf("GetLogByID failed: %v", err) + } + if got == nil || got.Data == nil { + t.Fatalf("entry data = %#v, want populated", got) + } + if len(got.Data.Attempts) != 2 { + t.Fatalf("hydrated attempts = %#v, want 2", got.Data.Attempts) + } + if got.Data.Attempts[0].Kind != AttemptKindPrimary || got.Data.Attempts[0].StatusCode != 404 { + t.Fatalf("primary attempt = %#v, want failed 404 primary", got.Data.Attempts[0]) + } + if got.Data.Attempts[1].Kind != AttemptKindFailover || !got.Data.Attempts[1].Success { + t.Fatalf("failover attempt = %#v, want successful failover", got.Data.Attempts[1]) + } + + primary := got.Data.Attempts[0] + body, ok := primary.ResponseBody.(map[string]any) + if !ok { + t.Fatalf("primary response body type = %T, want map", primary.ResponseBody) + } + errObj, ok := body["error"].(map[string]any) + if !ok || errObj["code"] != "model_not_found" { + t.Fatalf("primary response body = %#v, want nested provider error", primary.ResponseBody) + } + if primary.ResponseHeaders["X-Request-Id"] != "req-123" || primary.ResponseHeaders["Retry-After"] != "30" { + t.Fatalf("primary response headers = %#v, want captured upstream headers", primary.ResponseHeaders) + } + if got.Data.Attempts[1].ResponseBody != nil || got.Data.Attempts[1].ResponseHeaders != nil { + t.Fatalf("successful attempt should not carry a captured error body/headers: %#v", got.Data.Attempts[1]) + } + }) +} + +func TestSQLReader_AllowsNullWorkflowVersionIDAndErrorType(t *testing.T) { + sqlxtest.Run(t, func(t *testing.T, db sqlx.DB) { + ctx := context.Background() + + store, err := newSQLStoreForTest(t, db, 0) + if err != nil { + t.Fatalf("failed to create store: %v", err) + } + defer store.Close() + + now := db.Dialect().TimestampArg(time.Now()) + if _, err := db.Exec(ctx, ` + INSERT INTO audit_logs ( + id, timestamp, duration_ns, requested_model, resolved_model, provider, alias_used, workflow_version_id, + status_code, request_id, client_ip, method, path, stream, error_type, data + ) VALUES (?, ?, ?, ?, ?, ?, ?, ?, ?, ?, ?, ?, ?, ?, ?, ?) + `, + "null-workflow-version", + now, + 0, + "gpt-4", + "", + "openai", + false, + nil, + 200, + "req-1", + "127.0.0.1", + "POST", + "/v1/chat/completions", + false, + nil, + nil, + ); err != nil { + t.Fatalf("failed to insert audit log row: %v", err) + } + + reader, err := NewSQLReader(db) + if err != nil { + t.Fatalf("failed to create reader: %v", err) + } + + entry, err := reader.GetLogByID(context.Background(), "null-workflow-version") + if err != nil { + t.Fatalf("GetLogByID failed: %v", err) + } + if entry == nil { + t.Fatal("expected log entry, got nil") + return + } + if entry.WorkflowVersionID != "" { + t.Fatalf("WorkflowVersionID = %q, want empty", entry.WorkflowVersionID) + } + if entry.ErrorType != "" { + t.Fatalf("ErrorType = %q, want empty", entry.ErrorType) + } + + logs, err := reader.GetLogs(context.Background(), LogQueryParams{Limit: 10}) + if err != nil { + t.Fatalf("GetLogs failed: %v", err) + } + if len(logs.Entries) != 1 { + t.Fatalf("len(entries) = %d, want 1", len(logs.Entries)) + } + if logs.Entries[0].WorkflowVersionID != "" { + t.Fatalf("list WorkflowVersionID = %q, want empty", logs.Entries[0].WorkflowVersionID) + } + if logs.Entries[0].ErrorType != "" { + t.Fatalf("list ErrorType = %q, want empty", logs.Entries[0].ErrorType) + } + }) +} + +func TestSQLReader_GetLogsFiltersByUserPathSubtree(t *testing.T) { + sqlxtest.Run(t, func(t *testing.T, db sqlx.DB) { + ctx := context.Background() + + store, err := newSQLStoreForTest(t, db, 0) + if err != nil { + t.Fatalf("failed to create store: %v", err) + } + defer store.Close() + + now := db.Dialect().TimestampArg(time.Now()) + _, err = db.Exec(ctx, ` + INSERT INTO audit_logs ( + id, timestamp, duration_ns, requested_model, resolved_model, provider, alias_used, workflow_version_id, + status_code, request_id, client_ip, method, path, user_path, stream, error_type, data + ) VALUES + (?, ?, ?, ?, ?, ?, ?, ?, ?, ?, ?, ?, ?, ?, ?, ?, ?), + (?, ?, ?, ?, ?, ?, ?, ?, ?, ?, ?, ?, ?, ?, ?, ?, ?) + `, + "match-team", + now, + 0, + "gpt-4", + "", + "openai", + false, + nil, + 200, + "req-1", + "127.0.0.1", + "POST", + "/v1/chat/completions", + "/team/a", + false, + "", + nil, + "miss-other", + now, + 0, + "gpt-4", + "", + "openai", + false, + nil, + 200, + "req-2", + "127.0.0.1", + "POST", + "/v1/chat/completions", + "/other", + false, + "", + nil, + ) + if err != nil { + t.Fatalf("failed to insert audit log rows: %v", err) + } + + reader, err := NewSQLReader(db) + if err != nil { + t.Fatalf("failed to create reader: %v", err) + } + + logs, err := reader.GetLogs(context.Background(), LogQueryParams{UserPath: "/team", Limit: 10}) + if err != nil { + t.Fatalf("GetLogs failed: %v", err) + } + if len(logs.Entries) != 1 { + t.Fatalf("len(entries) = %d, want 1", len(logs.Entries)) + } + if logs.Entries[0].ID != "match-team" { + t.Fatalf("entry id = %q, want match-team", logs.Entries[0].ID) + } + if logs.Entries[0].UserPath != "/team/a" { + t.Fatalf("entry user_path = %q, want /team/a", logs.Entries[0].UserPath) + } + }) +} + +func TestSQLReader_GetLogsRootUserPathIncludesLegacyNullRows(t *testing.T) { + sqlxtest.Run(t, func(t *testing.T, db sqlx.DB) { + ctx := context.Background() + + store, err := newSQLStoreForTest(t, db, 0) + if err != nil { + t.Fatalf("failed to create store: %v", err) + } + defer store.Close() + + now := db.Dialect().TimestampArg(time.Now()) + _, err = db.Exec(ctx, ` + INSERT INTO audit_logs ( + id, timestamp, duration_ns, requested_model, resolved_model, provider, alias_used, workflow_version_id, + status_code, request_id, client_ip, method, path, user_path, stream, error_type, data + ) VALUES + (?, ?, ?, ?, ?, ?, ?, ?, ?, ?, ?, ?, ?, ?, ?, ?, ?), + (?, ?, ?, ?, ?, ?, ?, ?, ?, ?, ?, ?, ?, ?, ?, ?, ?) + `, + "legacy-null", + now, + 0, + "gpt-4", + "", + "openai", + false, + nil, + 200, + "req-legacy", + "127.0.0.1", + "POST", + "/v1/chat/completions", + nil, + false, + "", + nil, + "root-explicit", + now, + 0, + "gpt-4", + "", + "openai", + false, + nil, + 200, + "req-root", + "127.0.0.1", + "POST", + "/v1/chat/completions", + "/", + false, + "", + nil, + ) + if err != nil { + t.Fatalf("failed to insert audit log rows: %v", err) + } + + reader, err := NewSQLReader(db) + if err != nil { + t.Fatalf("failed to create reader: %v", err) + } + + logs, err := reader.GetLogs(context.Background(), LogQueryParams{UserPath: "/", Limit: 10}) + if err != nil { + t.Fatalf("GetLogs failed: %v", err) + } + if len(logs.Entries) != 2 { + t.Fatalf("len(entries) = %d, want 2", len(logs.Entries)) + } + }) +} + +func TestSQLStoreAndReader_PreserveCacheType(t *testing.T) { + sqlxtest.Run(t, func(t *testing.T, db sqlx.DB) { + + store, err := newSQLStoreForTest(t, db, 0) + if err != nil { + t.Fatalf("failed to create store: %v", err) + } + defer store.Close() + + ctx := context.Background() + now := time.Now() + if err := store.WriteBatch(ctx, []*LogEntry{ + { + ID: "cache-exact", + Timestamp: now, + RequestedModel: "gpt-4", + Provider: "openai", + CacheType: CacheTypeExact, + }, + { + ID: "cache-none", + Timestamp: now.Add(time.Second), + RequestedModel: "gpt-4", + Provider: "openai", + }, + }); err != nil { + t.Fatalf("WriteBatch failed: %v", err) + } + + var exactCacheType *string + if err := db.QueryRow(ctx, "SELECT cache_type FROM audit_logs WHERE id = ?", "cache-exact").Scan(&exactCacheType); err != nil { + t.Fatalf("query exact cache_type failed: %v", err) + } + if exactCacheType == nil || *exactCacheType != CacheTypeExact { + t.Fatalf("exact cache_type = %v, want %q", exactCacheType, CacheTypeExact) + } + + var noneCacheType *string + if err := db.QueryRow(ctx, "SELECT cache_type FROM audit_logs WHERE id = ?", "cache-none").Scan(&noneCacheType); err != nil { + t.Fatalf("query nil cache_type failed: %v", err) + } + if noneCacheType != nil { + t.Fatalf("nil cache_type = %q, want SQL NULL", *noneCacheType) + } + + reader, err := NewSQLReader(db) + if err != nil { + t.Fatalf("failed to create reader: %v", err) + } + + exactEntry, err := reader.GetLogByID(ctx, "cache-exact") + if err != nil { + t.Fatalf("GetLogByID(exact) failed: %v", err) + } + if exactEntry == nil || exactEntry.CacheType != CacheTypeExact { + t.Fatalf("exact entry cache_type = %#v, want %q", exactEntry, CacheTypeExact) + } + + noneEntry, err := reader.GetLogByID(ctx, "cache-none") + if err != nil { + t.Fatalf("GetLogByID(none) failed: %v", err) + } + if noneEntry == nil || noneEntry.CacheType != "" { + t.Fatalf("none entry cache_type = %#v, want empty", noneEntry) + } + }) +} diff --git a/internal/auditlog/stats_postgresql.go b/internal/auditlog/stats_postgresql.go deleted file mode 100644 index 53e0e325a..000000000 --- a/internal/auditlog/stats_postgresql.go +++ /dev/null @@ -1,61 +0,0 @@ -package auditlog - -import ( - "context" - "fmt" - "time" - - "github.com/enterpilot/gomodel/internal/storage/sqlutil" -) - -// GetRequestStats returns time-bucketed status-class counts and per-provider -// latency aggregates for the dashboard charts. -func (r *PostgreSQLReader) GetRequestStats(ctx context.Context, params RequestStatsParams) (*RequestStats, error) { - conditions, args, _ := pgDateRangeConditions(params.QueryParams, 1) - where := sqlutil.BuildWhereClause(conditions) - - // Group by UTC hour and provider; foldRequestStats folds hours into the - // requested bucket granularity. - query := `SELECT - date_trunc('hour', timestamp AT TIME ZONE 'UTC') AS hour, - COALESCE(NULLIF(TRIM(provider_name), ''), TRIM(provider), '') AS prov, - COUNT(*), - SUM(CASE WHEN status_code BETWEEN 200 AND 299 THEN 1 ELSE 0 END), - SUM(CASE WHEN status_code BETWEEN 400 AND 499 THEN 1 ELSE 0 END), - SUM(CASE WHEN status_code >= 500 THEN 1 ELSE 0 END), - COALESCE(SUM(CASE WHEN ` + postgresStatsLatencyPredicate + ` THEN duration_ns ELSE 0 END), 0), - COALESCE(SUM(CASE WHEN ` + postgresStatsLatencyPredicate + ` THEN 1 ELSE 0 END), 0) - FROM audit_logs` + where + ` - GROUP BY hour, prov` - - rows, err := r.pool.Query(ctx, query, args...) - if err != nil { - return nil, fmt.Errorf("failed to query audit request stats: %w", err) - } - defer rows.Close() - - stats := make([]statsRow, 0) - for rows.Next() { - var row statsRow - var hour time.Time - if err := rows.Scan(&hour, &row.Provider, &row.Requests, &row.Status2xx, &row.Status4xx, &row.Status5xx, &row.DurationNsSum, &row.DurationCount); err != nil { - return nil, fmt.Errorf("failed to scan audit request stats row: %w", err) - } - // date_trunc over "AT TIME ZONE 'UTC'" yields a timestamp without - // time zone holding UTC wall-clock values; pin the location so the - // fold buckets it correctly regardless of driver defaults. - row.HourUTC = time.Date(hour.Year(), hour.Month(), hour.Day(), hour.Hour(), 0, 0, 0, time.UTC) - stats = append(stats, row) - } - if err := rows.Err(); err != nil { - return nil, fmt.Errorf("error iterating audit request stats rows: %w", err) - } - - return foldRequestStats(stats, params), nil -} - -// Latency covers successful requests with a recorded duration that actually -// reached a provider (local response-cache hits complete in microseconds and -// would drag averages toward zero). -const postgresStatsLatencyPredicate = `status_code BETWEEN 200 AND 299 AND duration_ns > 0 - AND (cache_type IS NULL OR cache_type = '')` diff --git a/internal/auditlog/stats_sql.go b/internal/auditlog/stats_sql.go new file mode 100644 index 000000000..614cb541c --- /dev/null +++ b/internal/auditlog/stats_sql.go @@ -0,0 +1,106 @@ +package auditlog + +import ( + "context" + "fmt" + "time" + + "github.com/enterpilot/gomodel/internal/storage/sqlutil" +) + +// GetRequestStats returns time-bucketed status-class counts and per-provider +// latency aggregates for the dashboard charts. +func (r *SQLReader) GetRequestStats(ctx context.Context, params RequestStatsParams) (*RequestStats, error) { + var conditions []string + var args []any + if !params.StartDate.IsZero() { + conditions = append(conditions, "timestamp >= ?") + args = append(args, r.dialect.timestampBound(params.StartDate)) + } + if !params.EndDate.IsZero() { + conditions = append(conditions, "timestamp < ?") + args = append(args, r.dialect.timestampBound(params.EndDate.AddDate(0, 0, 1))) + } + + // Group by UTC hour and provider; foldRequestStats folds hours into the + // requested bucket granularity. + // + // Latency covers successful requests with a recorded duration that + // actually reached a provider: local response-cache hits complete in + // microseconds and would drag averages toward zero. + const latencyPredicate = `status_code BETWEEN 200 AND 299 AND duration_ns > 0 + AND (cache_type IS NULL OR cache_type = '')` + + query := `SELECT + ` + r.dialect.statsHour + ` AS hour, + COALESCE(NULLIF(TRIM(provider_name), ''), TRIM(provider), '') AS prov, + COUNT(*), + SUM(CASE WHEN status_code BETWEEN 200 AND 299 THEN 1 ELSE 0 END), + SUM(CASE WHEN status_code BETWEEN 400 AND 499 THEN 1 ELSE 0 END), + SUM(CASE WHEN status_code >= 500 THEN 1 ELSE 0 END), + COALESCE(SUM(CASE WHEN ` + latencyPredicate + ` THEN duration_ns ELSE 0 END), 0), + COALESCE(SUM(CASE WHEN ` + latencyPredicate + ` THEN 1 ELSE 0 END), 0) + FROM audit_logs` + sqlutil.BuildWhereClause(conditions) + ` + GROUP BY hour, prov` + + rows, err := r.db.Query(ctx, query, args...) + if err != nil { + return nil, fmt.Errorf("failed to query audit request stats: %w", err) + } + defer rows.Close() + + stats := make([]statsRow, 0) + for rows.Next() { + var row statsRow + var hour statsHour + if err := rows.Scan(&hour, &row.Provider, &row.Requests, &row.Status2xx, + &row.Status4xx, &row.Status5xx, &row.DurationNsSum, &row.DurationCount); err != nil { + return nil, fmt.Errorf("failed to scan audit request stats row: %w", err) + } + if !hour.valid { + return nil, fmt.Errorf("failed to parse audit request stats hour %q", hour.raw) + } + row.HourUTC = hour.Time + stats = append(stats, row) + } + if err := rows.Err(); err != nil { + return nil, fmt.Errorf("error iterating audit request stats rows: %w", err) + } + + return foldRequestStats(stats, params), nil +} + +// statsHour scans the hour a stats row groups under. SQLite formats it as text +// with strftime; PostgreSQL's date_trunc over "AT TIME ZONE 'UTC'" yields a +// timestamp *without* time zone holding UTC wall-clock values, so the location +// is pinned rather than trusted from the driver. +type statsHour struct { + time.Time + valid bool + raw string +} + +func (h *statsHour) Scan(src any) error { + switch value := src.(type) { + case time.Time: + h.Time = time.Date(value.Year(), value.Month(), value.Day(), value.Hour(), 0, 0, 0, time.UTC) + h.valid = true + return nil + case string: + return h.parse(value) + case []byte: + return h.parse(string(value)) + default: + return fmt.Errorf("cannot scan %T into a stats hour", src) + } +} + +func (h *statsHour) parse(raw string) error { + h.raw = raw + parsed, err := time.ParseInLocation(statsHourLayout, raw, time.UTC) + if err != nil { + return nil // reported by the caller, which has the row context + } + h.Time, h.valid = parsed, true + return nil +} diff --git a/internal/auditlog/stats_sqlite.go b/internal/auditlog/stats_sqlite.go deleted file mode 100644 index 8ef5fbccd..000000000 --- a/internal/auditlog/stats_sqlite.go +++ /dev/null @@ -1,63 +0,0 @@ -package auditlog - -import ( - "context" - "fmt" - "time" - - "github.com/enterpilot/gomodel/internal/storage/sqlutil" -) - -// GetRequestStats returns time-bucketed status-class counts and per-provider -// latency aggregates for the dashboard charts. -func (r *SQLiteReader) GetRequestStats(ctx context.Context, params RequestStatsParams) (*RequestStats, error) { - conditions, args := sqliteDateRangeConditions(params.QueryParams) - where := sqlutil.BuildWhereClause(conditions) - - // Group by UTC hour and provider; foldRequestStats folds hours into the - // requested bucket granularity. strftime normalizes stored timestamp - // variants (space separator, fractional seconds, offsets) to UTC. - query := `SELECT - strftime('%Y-%m-%dT%H', REPLACE(timestamp, ' ', 'T')) AS hour, - COALESCE(NULLIF(TRIM(provider_name), ''), TRIM(provider), '') AS prov, - COUNT(*), - SUM(CASE WHEN status_code BETWEEN 200 AND 299 THEN 1 ELSE 0 END), - SUM(CASE WHEN status_code BETWEEN 400 AND 499 THEN 1 ELSE 0 END), - SUM(CASE WHEN status_code >= 500 THEN 1 ELSE 0 END), - COALESCE(SUM(CASE WHEN ` + sqliteStatsLatencyPredicate + ` THEN duration_ns ELSE 0 END), 0), - COALESCE(SUM(CASE WHEN ` + sqliteStatsLatencyPredicate + ` THEN 1 ELSE 0 END), 0) - FROM audit_logs` + where + ` - GROUP BY hour, prov` - - rows, err := r.db.QueryContext(ctx, query, args...) - if err != nil { - return nil, fmt.Errorf("failed to query audit request stats: %w", err) - } - defer rows.Close() - - stats := make([]statsRow, 0) - for rows.Next() { - var row statsRow - var hour string - if err := rows.Scan(&hour, &row.Provider, &row.Requests, &row.Status2xx, &row.Status4xx, &row.Status5xx, &row.DurationNsSum, &row.DurationCount); err != nil { - return nil, fmt.Errorf("failed to scan audit request stats row: %w", err) - } - parsed, err := time.ParseInLocation(statsHourLayout, hour, time.UTC) - if err != nil { - return nil, fmt.Errorf("failed to parse audit request stats hour %q: %w", hour, err) - } - row.HourUTC = parsed - stats = append(stats, row) - } - if err := rows.Err(); err != nil { - return nil, fmt.Errorf("error iterating audit request stats rows: %w", err) - } - - return foldRequestStats(stats, params), nil -} - -// Latency covers successful requests with a recorded duration that actually -// reached a provider (local response-cache hits complete in microseconds and -// would drag averages toward zero). -const sqliteStatsLatencyPredicate = `status_code BETWEEN 200 AND 299 AND duration_ns > 0 - AND (cache_type IS NULL OR cache_type = '')` diff --git a/internal/auditlog/stats_test.go b/internal/auditlog/stats_test.go index 8bf530cdb..ac3ab2476 100644 --- a/internal/auditlog/stats_test.go +++ b/internal/auditlog/stats_test.go @@ -5,6 +5,9 @@ import ( "math" "testing" "time" + + "github.com/enterpilot/gomodel/internal/storage/sqlx" + "github.com/enterpilot/gomodel/internal/storage/sqlx/sqlxtest" ) func hourRow(hour time.Time, provider string, mutate func(*statsRow)) statsRow { @@ -169,84 +172,84 @@ func TestFoldRequestStats_ZeroFillStopsAtNow(t *testing.T) { } } -func TestSQLiteReaderGetRequestStats(t *testing.T) { - db := createTestDB(t) - defer db.Close() - - store, err := newSQLiteStore(t, db, 0) - if err != nil { - t.Fatalf("failed to create store: %v", err) - } - - day := time.Date(2026, 1, 16, 0, 0, 0, 0, time.UTC) - entries := []*LogEntry{ - {ID: "ok-1", Timestamp: day.Add(10*time.Hour + 15*time.Minute), Provider: "openai", ProviderName: "openai-prod", StatusCode: 200, DurationNs: 100e6}, - {ID: "ok-2", Timestamp: day.Add(10*time.Hour + 45*time.Minute), Provider: "openai", ProviderName: "openai-prod", StatusCode: 201, DurationNs: 300e6}, - {ID: "client-err", Timestamp: day.Add(10*time.Hour + 50*time.Minute), Provider: "openai", ProviderName: "openai-prod", StatusCode: 429, DurationNs: 5e6}, - {ID: "server-err", Timestamp: day.Add(11*time.Hour + 5*time.Minute), Provider: "openai", ProviderName: "openai-prod", StatusCode: 502, DurationNs: 2e9}, - // Local cache hit: counted as 2xx but excluded from latency. - {ID: "cache-hit", Timestamp: day.Add(11*time.Hour + 10*time.Minute), Provider: "openai", ProviderName: "openai-prod", StatusCode: 200, DurationNs: 1e6, CacheType: CacheTypeExact}, - // Empty provider name falls back to the provider type. - {ID: "fallback-name", Timestamp: day.Add(11*time.Hour + 20*time.Minute), Provider: "anthropic", StatusCode: 200, DurationNs: 700e6}, - // Outside the queried range. - {ID: "next-day", Timestamp: day.Add(30 * time.Hour), Provider: "openai", ProviderName: "openai-prod", StatusCode: 200, DurationNs: 100e6}, - } - if err := store.WriteBatch(context.Background(), entries); err != nil { - t.Fatalf("failed to seed audit logs: %v", err) - } - - reader, err := NewSQLiteReader(db) - if err != nil { - t.Fatalf("failed to create reader: %v", err) - } - - stats, err := reader.GetRequestStats(context.Background(), RequestStatsParams{ - QueryParams: QueryParams{StartDate: day, EndDate: day}, - Interval: StatsIntervalHour, - Location: time.UTC, - Now: day.Add(23 * time.Hour), +func TestSQLReaderGetRequestStats(t *testing.T) { + sqlxtest.Run(t, func(t *testing.T, db sqlx.DB) { + + store, err := newSQLStoreForTest(t, db, 0) + if err != nil { + t.Fatalf("failed to create store: %v", err) + } + + day := time.Date(2026, 1, 16, 0, 0, 0, 0, time.UTC) + entries := []*LogEntry{ + {ID: "ok-1", Timestamp: day.Add(10*time.Hour + 15*time.Minute), Provider: "openai", ProviderName: "openai-prod", StatusCode: 200, DurationNs: 100e6}, + {ID: "ok-2", Timestamp: day.Add(10*time.Hour + 45*time.Minute), Provider: "openai", ProviderName: "openai-prod", StatusCode: 201, DurationNs: 300e6}, + {ID: "client-err", Timestamp: day.Add(10*time.Hour + 50*time.Minute), Provider: "openai", ProviderName: "openai-prod", StatusCode: 429, DurationNs: 5e6}, + {ID: "server-err", Timestamp: day.Add(11*time.Hour + 5*time.Minute), Provider: "openai", ProviderName: "openai-prod", StatusCode: 502, DurationNs: 2e9}, + // Local cache hit: counted as 2xx but excluded from latency. + {ID: "cache-hit", Timestamp: day.Add(11*time.Hour + 10*time.Minute), Provider: "openai", ProviderName: "openai-prod", StatusCode: 200, DurationNs: 1e6, CacheType: CacheTypeExact}, + // Empty provider name falls back to the provider type. + {ID: "fallback-name", Timestamp: day.Add(11*time.Hour + 20*time.Minute), Provider: "anthropic", StatusCode: 200, DurationNs: 700e6}, + // Outside the queried range. + {ID: "next-day", Timestamp: day.Add(30 * time.Hour), Provider: "openai", ProviderName: "openai-prod", StatusCode: 200, DurationNs: 100e6}, + } + if err := store.WriteBatch(context.Background(), entries); err != nil { + t.Fatalf("failed to seed audit logs: %v", err) + } + + reader, err := NewSQLReader(db) + if err != nil { + t.Fatalf("failed to create reader: %v", err) + } + + stats, err := reader.GetRequestStats(context.Background(), RequestStatsParams{ + QueryParams: QueryParams{StartDate: day, EndDate: day}, + Interval: StatsIntervalHour, + Location: time.UTC, + Now: day.Add(23 * time.Hour), + }) + if err != nil { + t.Fatalf("GetRequestStats failed: %v", err) + } + + if stats.Summary.Requests != 6 { + t.Fatalf("summary requests = %d, want 6", stats.Summary.Requests) + } + if stats.Summary.Status2xx != 4 || stats.Summary.Status4xx != 1 || stats.Summary.Status5xx != 1 || stats.Summary.StatusOther != 0 { + t.Fatalf("summary = %+v", stats.Summary) + } + + byStart := map[int]RequestStatsBucket{} + for _, b := range stats.Buckets { + byStart[b.Start.UTC().Hour()] = b + } + if b := byStart[10]; b.Requests != 3 || b.Status2xx != 2 || b.Status4xx != 1 { + t.Fatalf("10:00 bucket = %+v", b) + } + if b := byStart[11]; b.Requests != 3 || b.Status2xx != 2 || b.Status5xx != 1 { + t.Fatalf("11:00 bucket = %+v", b) + } + + if len(stats.ProviderLatency) != 2 { + t.Fatalf("provider series = %d, want 2", len(stats.ProviderLatency)) + } + if stats.ProviderLatency[0].Provider != "openai-prod" { + t.Fatalf("first provider = %q, want openai-prod", stats.ProviderLatency[0].Provider) + } + openai := stats.ProviderLatency[0] + if openai.AvgDurationMs[10] == nil || *openai.AvgDurationMs[10] != 200 { + t.Fatalf("openai 10:00 avg = %v, want 200 (2xx only)", openai.AvgDurationMs[10]) + } + // The 11:00 openai bucket only saw a 502 and a cache hit -> gap. + if openai.AvgDurationMs[11] != nil { + t.Fatalf("openai 11:00 avg = %v, want nil", openai.AvgDurationMs[11]) + } + anthropic := stats.ProviderLatency[1] + if anthropic.Provider != "anthropic" { + t.Fatalf("second provider = %q, want anthropic", anthropic.Provider) + } + if anthropic.AvgDurationMs[11] == nil || *anthropic.AvgDurationMs[11] != 700 { + t.Fatalf("anthropic 11:00 avg = %v, want 700", anthropic.AvgDurationMs[11]) + } }) - if err != nil { - t.Fatalf("GetRequestStats failed: %v", err) - } - - if stats.Summary.Requests != 6 { - t.Fatalf("summary requests = %d, want 6", stats.Summary.Requests) - } - if stats.Summary.Status2xx != 4 || stats.Summary.Status4xx != 1 || stats.Summary.Status5xx != 1 || stats.Summary.StatusOther != 0 { - t.Fatalf("summary = %+v", stats.Summary) - } - - byStart := map[int]RequestStatsBucket{} - for _, b := range stats.Buckets { - byStart[b.Start.UTC().Hour()] = b - } - if b := byStart[10]; b.Requests != 3 || b.Status2xx != 2 || b.Status4xx != 1 { - t.Fatalf("10:00 bucket = %+v", b) - } - if b := byStart[11]; b.Requests != 3 || b.Status2xx != 2 || b.Status5xx != 1 { - t.Fatalf("11:00 bucket = %+v", b) - } - - if len(stats.ProviderLatency) != 2 { - t.Fatalf("provider series = %d, want 2", len(stats.ProviderLatency)) - } - if stats.ProviderLatency[0].Provider != "openai-prod" { - t.Fatalf("first provider = %q, want openai-prod", stats.ProviderLatency[0].Provider) - } - openai := stats.ProviderLatency[0] - if openai.AvgDurationMs[10] == nil || *openai.AvgDurationMs[10] != 200 { - t.Fatalf("openai 10:00 avg = %v, want 200 (2xx only)", openai.AvgDurationMs[10]) - } - // The 11:00 openai bucket only saw a 502 and a cache hit -> gap. - if openai.AvgDurationMs[11] != nil { - t.Fatalf("openai 11:00 avg = %v, want nil", openai.AvgDurationMs[11]) - } - anthropic := stats.ProviderLatency[1] - if anthropic.Provider != "anthropic" { - t.Fatalf("second provider = %q, want anthropic", anthropic.Provider) - } - if anthropic.AvgDurationMs[11] == nil || *anthropic.AvgDurationMs[11] != 700 { - t.Fatalf("anthropic 11:00 avg = %v, want 700", anthropic.AvgDurationMs[11]) - } } diff --git a/internal/auditlog/store_sqlite_test.go b/internal/auditlog/store_sqlite_test.go deleted file mode 100644 index cacaaf2e7..000000000 --- a/internal/auditlog/store_sqlite_test.go +++ /dev/null @@ -1,682 +0,0 @@ -package auditlog - -import ( - "context" - "database/sql" - "fmt" - "testing" - "time" - - _ "modernc.org/sqlite" - - "github.com/enterpilot/gomodel/internal/storage/sqlx" -) - -// createTestDB creates an in-memory SQLite database for testing. -func createTestDB(t *testing.T) *sql.DB { - t.Helper() - db, err := sql.Open("sqlite", ":memory:") - if err != nil { - t.Fatalf("failed to open test database: %v", err) - } - return db -} - -// newSQLiteStore builds the store over an existing SQLite handle. These tests -// pair the store with the SQLite reader, which is still dialect-specific, so -// they stay on one engine rather than running through sqlxtest. -func newSQLiteStore(t *testing.T, db *sql.DB, retentionDays int) (*SQLStore, error) { - t.Helper() - wrapped, err := sqlx.NewSQLite(db) - if err != nil { - t.Fatalf("sqlx.NewSQLite: %v", err) - } - return NewSQLStore(context.Background(), wrapped, retentionDays) -} - -func TestSQLiteStore_WriteBatch_NullDataPreservation(t *testing.T) { - db := createTestDB(t) - defer db.Close() - - store, err := newSQLiteStore(t, db, 0) - if err != nil { - t.Fatalf("failed to create store: %v", err) - } - defer store.Close() - - ctx := context.Background() - - // Create entries - one with nil Data, one with Data - entries := []*LogEntry{ - { - ID: "entry-nil-data", - Timestamp: time.Now(), - RequestedModel: "gpt-4", - Provider: "openai", - Data: nil, // This should become SQL NULL - }, - { - ID: "entry-with-data", - Timestamp: time.Now(), - RequestedModel: "gpt-4", - Provider: "openai", - Data: &LogData{ - UserAgent: "test-agent", - }, - }, - } - - // Write entries - if err := store.WriteBatch(ctx, entries); err != nil { - t.Fatalf("WriteBatch failed: %v", err) - } - - // Query to check NULL vs non-NULL - rows, err := db.Query("SELECT id, data, data IS NULL as is_null FROM audit_logs ORDER BY id") - if err != nil { - t.Fatalf("query failed: %v", err) - } - defer rows.Close() - - results := make(map[string]bool) // id -> isNull - for rows.Next() { - var id string - var data sql.NullString - var isNull bool - if err := rows.Scan(&id, &data, &isNull); err != nil { - t.Fatalf("scan failed: %v", err) - } - results[id] = isNull - } - - // Verify entry with nil Data has NULL in database - if !results["entry-nil-data"] { - t.Error("entry with nil Data should have NULL in database, got non-NULL") - } - - // Verify entry with Data has non-NULL in database - if results["entry-with-data"] { - t.Error("entry with Data should have non-NULL in database, got NULL") - } -} - -func TestSQLiteStore_WriteBatch_Chunking(t *testing.T) { - db := createTestDB(t) - defer db.Close() - - store, err := newSQLiteStore(t, db, 0) - if err != nil { - t.Fatalf("failed to create store: %v", err) - } - defer store.Close() - - ctx := context.Background() - - // Create more entries than can fit in a single batch (>62 entries) - // Using 150 entries to ensure we need at least 3 batches - numEntries := 150 - entries := make([]*LogEntry, numEntries) - for i := range numEntries { - entries[i] = &LogEntry{ - ID: fmt.Sprintf("entry-%03d", i), - Timestamp: time.Now(), - RequestedModel: "gpt-4", - Provider: "openai", - StatusCode: 200, - } - } - - // Write all entries - this should internally chunk into multiple batches - if err := store.WriteBatch(ctx, entries); err != nil { - t.Fatalf("WriteBatch failed: %v", err) - } - - // Verify all entries were persisted - var count int - if err := db.QueryRow("SELECT COUNT(*) FROM audit_logs").Scan(&count); err != nil { - t.Fatalf("count query failed: %v", err) - } - - if count != numEntries { - t.Errorf("expected %d entries, got %d", numEntries, count) - } - - // Verify entries are actually in the database by sampling a few - for _, id := range []string{"entry-000", "entry-062", "entry-124", "entry-149"} { - var exists bool - err := db.QueryRow("SELECT 1 FROM audit_logs WHERE id = ?", id).Scan(&exists) - if err == sql.ErrNoRows { - t.Errorf("entry %s not found in database", id) - } else if err != nil { - t.Fatalf("query for %s failed: %v", id, err) - } - } -} - -func TestSQLiteStore_WriteBatch_EmptyEntries(t *testing.T) { - db := createTestDB(t) - defer db.Close() - - store, err := newSQLiteStore(t, db, 0) - if err != nil { - t.Fatalf("failed to create store: %v", err) - } - defer store.Close() - - ctx := context.Background() - - // Empty slice should not error - if err := store.WriteBatch(ctx, []*LogEntry{}); err != nil { - t.Fatalf("WriteBatch with empty entries failed: %v", err) - } - - // Verify no entries in database - var count int - if err := db.QueryRow("SELECT COUNT(*) FROM audit_logs").Scan(&count); err != nil { - t.Fatalf("count query failed: %v", err) - } - if count != 0 { - t.Errorf("expected 0 entries, got %d", count) - } -} - -func TestSQLiteStore_WriteBatch_ExactBatchBoundary(t *testing.T) { - db := createTestDB(t) - defer db.Close() - - store, err := newSQLiteStore(t, db, 0) - if err != nil { - t.Fatalf("failed to create store: %v", err) - } - defer store.Close() - - ctx := context.Background() - - // Test with exactly maxEntriesPerBatch entries - numEntries := maxEntriesPerBatch - entries := make([]*LogEntry, numEntries) - for i := range numEntries { - entries[i] = &LogEntry{ - ID: fmt.Sprintf("exact-%03d", i), - Timestamp: time.Now(), - RequestedModel: "gpt-4", - } - } - - if err := store.WriteBatch(ctx, entries); err != nil { - t.Fatalf("WriteBatch failed: %v", err) - } - - var count int - if err := db.QueryRow("SELECT COUNT(*) FROM audit_logs").Scan(&count); err != nil { - t.Fatalf("count query failed: %v", err) - } - if count != numEntries { - t.Errorf("expected %d entries, got %d", numEntries, count) - } - - // Test with maxEntriesPerBatch + 1 entries - should require 2 batches - entries = make([]*LogEntry, maxEntriesPerBatch+1) - for i := 0; i <= maxEntriesPerBatch; i++ { - entries[i] = &LogEntry{ - ID: fmt.Sprintf("boundary-%03d", i), - Timestamp: time.Now(), - RequestedModel: "gpt-4", - } - } - - if err := store.WriteBatch(ctx, entries); err != nil { - t.Fatalf("WriteBatch failed at boundary: %v", err) - } - - if err := db.QueryRow("SELECT COUNT(*) FROM audit_logs").Scan(&count); err != nil { - t.Fatalf("count query failed: %v", err) - } - expectedTotal := numEntries + maxEntriesPerBatch + 1 - if count != expectedTotal { - t.Errorf("expected %d entries, got %d", expectedTotal, count) - } -} - -func TestSQLiteStore_WriteBatch_PersistsAliasFields(t *testing.T) { - db := createTestDB(t) - defer db.Close() - - store, err := newSQLiteStore(t, db, 0) - if err != nil { - t.Fatalf("failed to create store: %v", err) - } - defer store.Close() - - ctx := context.Background() - entry := &LogEntry{ - ID: "alias-entry", - Timestamp: time.Now(), - RequestedModel: "anthropic/claude-opus-4-6", - ResolvedModel: "openai/gpt-5-nano", - Provider: "openai", - AliasUsed: true, - StatusCode: 200, - } - - if err := store.WriteBatch(ctx, []*LogEntry{entry}); err != nil { - t.Fatalf("WriteBatch failed: %v", err) - } - - reader, err := NewSQLiteReader(db) - if err != nil { - t.Fatalf("failed to create reader: %v", err) - } - - logEntry, err := reader.GetLogByID(ctx, entry.ID) - if err != nil { - t.Fatalf("GetLogByID failed: %v", err) - } - if logEntry == nil { - t.Fatal("expected log entry, got nil") - return - } - if logEntry.RequestedModel != entry.RequestedModel { - t.Fatalf("RequestedModel = %q, want %q", logEntry.RequestedModel, entry.RequestedModel) - } - if logEntry.ResolvedModel != entry.ResolvedModel { - t.Fatalf("ResolvedModel = %q, want %q", logEntry.ResolvedModel, entry.ResolvedModel) - } - if logEntry.Provider != entry.Provider { - t.Fatalf("Provider = %q, want %q", logEntry.Provider, entry.Provider) - } - if !logEntry.AliasUsed { - t.Fatal("AliasUsed = false, want true") - } - if logEntry.UserPath != "/" { - t.Fatalf("UserPath = %q, want /", logEntry.UserPath) - } -} - -func TestSQLiteStore_WriteBatch_PersistsProviderAttempts(t *testing.T) { - db := createTestDB(t) - db.SetMaxOpenConns(1) - defer db.Close() - - store, err := newSQLiteStore(t, db, 0) - if err != nil { - t.Fatalf("failed to create store: %v", err) - } - defer store.Close() - - ctx := context.Background() - entry := &LogEntry{ - ID: "attempt-entry", - Timestamp: time.Now(), - RequestedModel: "anthropic/claude-fable-5", - ResolvedModel: "openai/gpt-5.5", - Provider: "openai", - StatusCode: 200, - Data: &LogData{ - Failover: &FailoverSnapshot{TargetModel: "openai/gpt-5.5"}, - Attempts: []AttemptSnapshot{ - { - Seq: 1, - Kind: AttemptKindPrimary, - ProviderType: "anthropic", - Model: "anthropic/claude-fable-5", - StatusCode: 404, - ErrorType: "not_found_error", - ErrorCode: "model_not_found", - ErrorMessage: "model is not available", - ResponseBody: map[string]any{ - "error": map[string]any{"message": "model is not available", "code": "model_not_found"}, - }, - ResponseHeaders: map[string]string{"X-Request-Id": "req-123", "Retry-After": "30"}, - }, - { - Seq: 2, - Kind: AttemptKindFailover, - ProviderType: "openai", - Model: "openai/gpt-5.5", - StatusCode: 200, - Success: true, - }, - }, - }, - } - - if err := store.WriteBatch(ctx, []*LogEntry{entry}); err != nil { - t.Fatalf("WriteBatch failed: %v", err) - } - - var attemptRows int - if err := db.QueryRow("SELECT COUNT(*) FROM audit_log_attempts WHERE audit_log_id = ?", entry.ID).Scan(&attemptRows); err != nil { - t.Fatalf("count audit_log_attempts failed: %v", err) - } - if attemptRows != 2 { - t.Fatalf("attempt rows = %d, want 2", attemptRows) - } - - reader, err := NewSQLiteReader(db) - if err != nil { - t.Fatalf("failed to create reader: %v", err) - } - got, err := reader.GetLogByID(ctx, entry.ID) - if err != nil { - t.Fatalf("GetLogByID failed: %v", err) - } - if got == nil || got.Data == nil { - t.Fatalf("entry data = %#v, want populated", got) - } - if len(got.Data.Attempts) != 2 { - t.Fatalf("hydrated attempts = %#v, want 2", got.Data.Attempts) - } - if got.Data.Attempts[0].Kind != AttemptKindPrimary || got.Data.Attempts[0].StatusCode != 404 { - t.Fatalf("primary attempt = %#v, want failed 404 primary", got.Data.Attempts[0]) - } - if got.Data.Attempts[1].Kind != AttemptKindFailover || !got.Data.Attempts[1].Success { - t.Fatalf("failover attempt = %#v, want successful failover", got.Data.Attempts[1]) - } - - primary := got.Data.Attempts[0] - body, ok := primary.ResponseBody.(map[string]any) - if !ok { - t.Fatalf("primary response body type = %T, want map", primary.ResponseBody) - } - errObj, ok := body["error"].(map[string]any) - if !ok || errObj["code"] != "model_not_found" { - t.Fatalf("primary response body = %#v, want nested provider error", primary.ResponseBody) - } - if primary.ResponseHeaders["X-Request-Id"] != "req-123" || primary.ResponseHeaders["Retry-After"] != "30" { - t.Fatalf("primary response headers = %#v, want captured upstream headers", primary.ResponseHeaders) - } - if got.Data.Attempts[1].ResponseBody != nil || got.Data.Attempts[1].ResponseHeaders != nil { - t.Fatalf("successful attempt should not carry a captured error body/headers: %#v", got.Data.Attempts[1]) - } -} - -func TestSQLiteReader_AllowsNullWorkflowVersionIDAndErrorType(t *testing.T) { - db := createTestDB(t) - defer db.Close() - - store, err := newSQLiteStore(t, db, 0) - if err != nil { - t.Fatalf("failed to create store: %v", err) - } - defer store.Close() - - now := time.Now().UTC().Format(time.RFC3339Nano) - if _, err := db.Exec(` - INSERT INTO audit_logs ( - id, timestamp, duration_ns, requested_model, resolved_model, provider, alias_used, workflow_version_id, - status_code, request_id, client_ip, method, path, stream, error_type, data - ) VALUES (?, ?, ?, ?, ?, ?, ?, ?, ?, ?, ?, ?, ?, ?, ?, ?) - `, - "null-workflow-version", - now, - 0, - "gpt-4", - "", - "openai", - 0, - nil, - 200, - "req-1", - "127.0.0.1", - "POST", - "/v1/chat/completions", - 0, - nil, - nil, - ); err != nil { - t.Fatalf("failed to insert audit log row: %v", err) - } - - reader, err := NewSQLiteReader(db) - if err != nil { - t.Fatalf("failed to create reader: %v", err) - } - - entry, err := reader.GetLogByID(context.Background(), "null-workflow-version") - if err != nil { - t.Fatalf("GetLogByID failed: %v", err) - } - if entry == nil { - t.Fatal("expected log entry, got nil") - return - } - if entry.WorkflowVersionID != "" { - t.Fatalf("WorkflowVersionID = %q, want empty", entry.WorkflowVersionID) - } - if entry.ErrorType != "" { - t.Fatalf("ErrorType = %q, want empty", entry.ErrorType) - } - - logs, err := reader.GetLogs(context.Background(), LogQueryParams{Limit: 10}) - if err != nil { - t.Fatalf("GetLogs failed: %v", err) - } - if len(logs.Entries) != 1 { - t.Fatalf("len(entries) = %d, want 1", len(logs.Entries)) - } - if logs.Entries[0].WorkflowVersionID != "" { - t.Fatalf("list WorkflowVersionID = %q, want empty", logs.Entries[0].WorkflowVersionID) - } - if logs.Entries[0].ErrorType != "" { - t.Fatalf("list ErrorType = %q, want empty", logs.Entries[0].ErrorType) - } -} - -func TestSQLiteReader_GetLogsFiltersByUserPathSubtree(t *testing.T) { - db := createTestDB(t) - defer db.Close() - - store, err := newSQLiteStore(t, db, 0) - if err != nil { - t.Fatalf("failed to create store: %v", err) - } - defer store.Close() - - now := time.Now().UTC().Format(time.RFC3339Nano) - _, err = db.Exec(` - INSERT INTO audit_logs ( - id, timestamp, duration_ns, requested_model, resolved_model, provider, alias_used, workflow_version_id, - status_code, request_id, client_ip, method, path, user_path, stream, error_type, data - ) VALUES - (?, ?, ?, ?, ?, ?, ?, ?, ?, ?, ?, ?, ?, ?, ?, ?, ?), - (?, ?, ?, ?, ?, ?, ?, ?, ?, ?, ?, ?, ?, ?, ?, ?, ?) - `, - "match-team", - now, - 0, - "gpt-4", - "", - "openai", - 0, - nil, - 200, - "req-1", - "127.0.0.1", - "POST", - "/v1/chat/completions", - "/team/a", - 0, - "", - nil, - "miss-other", - now, - 0, - "gpt-4", - "", - "openai", - 0, - nil, - 200, - "req-2", - "127.0.0.1", - "POST", - "/v1/chat/completions", - "/other", - 0, - "", - nil, - ) - if err != nil { - t.Fatalf("failed to insert audit log rows: %v", err) - } - - reader, err := NewSQLiteReader(db) - if err != nil { - t.Fatalf("failed to create reader: %v", err) - } - - logs, err := reader.GetLogs(context.Background(), LogQueryParams{UserPath: "/team", Limit: 10}) - if err != nil { - t.Fatalf("GetLogs failed: %v", err) - } - if len(logs.Entries) != 1 { - t.Fatalf("len(entries) = %d, want 1", len(logs.Entries)) - } - if logs.Entries[0].ID != "match-team" { - t.Fatalf("entry id = %q, want match-team", logs.Entries[0].ID) - } - if logs.Entries[0].UserPath != "/team/a" { - t.Fatalf("entry user_path = %q, want /team/a", logs.Entries[0].UserPath) - } -} - -func TestSQLiteReader_GetLogsRootUserPathIncludesLegacyNullRows(t *testing.T) { - db := createTestDB(t) - defer db.Close() - - store, err := newSQLiteStore(t, db, 0) - if err != nil { - t.Fatalf("failed to create store: %v", err) - } - defer store.Close() - - now := time.Now().UTC().Format(time.RFC3339Nano) - _, err = db.Exec(` - INSERT INTO audit_logs ( - id, timestamp, duration_ns, requested_model, resolved_model, provider, alias_used, workflow_version_id, - status_code, request_id, client_ip, method, path, user_path, stream, error_type, data - ) VALUES - (?, ?, ?, ?, ?, ?, ?, ?, ?, ?, ?, ?, ?, ?, ?, ?, ?), - (?, ?, ?, ?, ?, ?, ?, ?, ?, ?, ?, ?, ?, ?, ?, ?, ?) - `, - "legacy-null", - now, - 0, - "gpt-4", - "", - "openai", - 0, - nil, - 200, - "req-legacy", - "127.0.0.1", - "POST", - "/v1/chat/completions", - nil, - 0, - "", - nil, - "root-explicit", - now, - 0, - "gpt-4", - "", - "openai", - 0, - nil, - 200, - "req-root", - "127.0.0.1", - "POST", - "/v1/chat/completions", - "/", - 0, - "", - nil, - ) - if err != nil { - t.Fatalf("failed to insert audit log rows: %v", err) - } - - reader, err := NewSQLiteReader(db) - if err != nil { - t.Fatalf("failed to create reader: %v", err) - } - - logs, err := reader.GetLogs(context.Background(), LogQueryParams{UserPath: "/", Limit: 10}) - if err != nil { - t.Fatalf("GetLogs failed: %v", err) - } - if len(logs.Entries) != 2 { - t.Fatalf("len(entries) = %d, want 2", len(logs.Entries)) - } -} - -func TestSQLiteStoreAndReader_PreserveCacheType(t *testing.T) { - db := createTestDB(t) - defer db.Close() - - store, err := newSQLiteStore(t, db, 0) - if err != nil { - t.Fatalf("failed to create store: %v", err) - } - defer store.Close() - - ctx := context.Background() - now := time.Now() - if err := store.WriteBatch(ctx, []*LogEntry{ - { - ID: "cache-exact", - Timestamp: now, - RequestedModel: "gpt-4", - Provider: "openai", - CacheType: CacheTypeExact, - }, - { - ID: "cache-none", - Timestamp: now.Add(time.Second), - RequestedModel: "gpt-4", - Provider: "openai", - }, - }); err != nil { - t.Fatalf("WriteBatch failed: %v", err) - } - - var exactCacheType sql.NullString - if err := db.QueryRow("SELECT cache_type FROM audit_logs WHERE id = ?", "cache-exact").Scan(&exactCacheType); err != nil { - t.Fatalf("query exact cache_type failed: %v", err) - } - if !exactCacheType.Valid || exactCacheType.String != CacheTypeExact { - t.Fatalf("exact cache_type = %#v, want %q", exactCacheType, CacheTypeExact) - } - - var noneCacheType sql.NullString - if err := db.QueryRow("SELECT cache_type FROM audit_logs WHERE id = ?", "cache-none").Scan(&noneCacheType); err != nil { - t.Fatalf("query nil cache_type failed: %v", err) - } - if noneCacheType.Valid { - t.Fatalf("nil cache_type = %#v, want SQL NULL", noneCacheType) - } - - reader, err := NewSQLiteReader(db) - if err != nil { - t.Fatalf("failed to create reader: %v", err) - } - - exactEntry, err := reader.GetLogByID(ctx, "cache-exact") - if err != nil { - t.Fatalf("GetLogByID(exact) failed: %v", err) - } - if exactEntry == nil || exactEntry.CacheType != CacheTypeExact { - t.Fatalf("exact entry cache_type = %#v, want %q", exactEntry, CacheTypeExact) - } - - noneEntry, err := reader.GetLogByID(ctx, "cache-none") - if err != nil { - t.Fatalf("GetLogByID(none) failed: %v", err) - } - if noneEntry == nil || noneEntry.CacheType != "" { - t.Fatalf("none entry cache_type = %#v, want empty", noneEntry) - } -} diff --git a/internal/storage/sqlx/timestamp.go b/internal/storage/sqlx/timestamp.go new file mode 100644 index 000000000..b06aaf875 --- /dev/null +++ b/internal/storage/sqlx/timestamp.go @@ -0,0 +1,61 @@ +package sqlx + +import ( + "fmt" + "time" +) + +// Timestamp scans a TypeTimestamp column from either engine. It is the read +// side of TimestampArg: PostgreSQL hands back a time.Time, SQLite the RFC3339 +// text that was written. +// +// Text it cannot parse leaves Time zero and Valid false rather than failing +// the scan. A reader returning a page of rows should not fail the whole page +// because one row holds an unreadable timestamp; callers that care report Raw. +type Timestamp struct { + Time time.Time + Valid bool + Raw string +} + +// Scan implements sql.Scanner, which both drivers honour. +func (t *Timestamp) Scan(src any) error { + *t = Timestamp{} + switch value := src.(type) { + case nil: + return nil + case time.Time: + // Deliberately not normalised to UTC: each driver's own zone is what + // callers already render, and changing it would move every timestamp + // the admin API returns. + t.Time, t.Valid = value, true + return nil + case string: + t.parseText(value) + return nil + case []byte: + t.parseText(string(value)) + return nil + default: + return fmt.Errorf("cannot scan %T into a timestamp", src) + } +} + +// timestampLayouts are the spellings a TypeTimestamp column has held. The +// first is what TimestampArg writes; the rest are older rows and values +// written by SQLite's own date functions. +var timestampLayouts = []string{ + time.RFC3339Nano, + "2006-01-02 15:04:05.999999999-07:00", + "2006-01-02T15:04:05Z", +} + +func (t *Timestamp) parseText(raw string) { + t.Raw = raw + for _, layout := range timestampLayouts { + if parsed, err := time.Parse(layout, raw); err == nil { + t.Time, t.Valid = parsed, true + return + } + } +} From 2ab70cc5d7bef225ac71f251c5535ae7006e4653 Mon Sep 17 00:00:00 2001 From: "Jakub A. W" Date: Sat, 25 Jul 2026 16:27:27 +0200 Subject: [PATCH 04/12] refactor(usage): let GetCacheOverview own its cached-only scope The admin handler set params.CacheMode = CacheModeCached before calling GetCacheOverview, which every implementation then overrides anyway. The duplication made the guarantee look like the caller's job, and the only thing asserting it was three admin tests reading it back off a stub reader that cannot enforce anything. The handler no longer sets it, the interface documents that the method overrides rather than honours CacheMode, and a new usage test asserts the real behaviour: passing "all" or "uncached" still returns cached rows only. Co-Authored-By: Claude Opus 5 (1M context) --- internal/admin/handler_test.go | 9 ---- internal/admin/handler_usage.go | 1 - internal/usage/reader.go | 3 ++ internal/usage/reader_cache_mode_test.go | 69 ++++++++++++++++++++++++ 4 files changed, 72 insertions(+), 10 deletions(-) create mode 100644 internal/usage/reader_cache_mode_test.go diff --git a/internal/admin/handler_test.go b/internal/admin/handler_test.go index 72fdf8d48..0ddcb34f9 100644 --- a/internal/admin/handler_test.go +++ b/internal/admin/handler_test.go @@ -2503,9 +2503,6 @@ func TestCacheOverview_ReturnsPayloadWhenEnabled(t *testing.T) { if len(body.Daily) != 1 || body.Daily[0].ExactHits != 3 { t.Fatalf("unexpected daily payload: %+v", body.Daily) } - if reader.lastCacheOverview.CacheMode != usage.CacheModeCached { - t.Fatalf("CacheMode = %q, want %q", reader.lastCacheOverview.CacheMode, usage.CacheModeCached) - } if reader.lastCacheOverview.UserPath != "/team" { t.Fatalf("UserPath = %q, want %q", reader.lastCacheOverview.UserPath, "/team") } @@ -2547,9 +2544,6 @@ func TestCacheOverview_ReturnsErrorWhenReaderFails(t *testing.T) { if _, ok := errorBody["code"]; !ok { t.Fatalf("error.code missing from payload: %v", errorBody) } - if reader.lastCacheOverview.CacheMode != usage.CacheModeCached { - t.Fatalf("CacheMode = %q, want %q", reader.lastCacheOverview.CacheMode, usage.CacheModeCached) - } } func TestCacheOverview_ReturnsClientClosedWhenRequestIsCanceled(t *testing.T) { @@ -2583,9 +2577,6 @@ func TestCacheOverview_ReturnsClientClosedWhenRequestIsCanceled(t *testing.T) { if got, ok := errorBody["code"].(string); !ok || got != "request_canceled" { t.Fatalf("error.code = %#v, want request_canceled", errorBody["code"]) } - if reader.lastCacheOverview.CacheMode != usage.CacheModeCached { - t.Fatalf("CacheMode = %q, want %q", reader.lastCacheOverview.CacheMode, usage.CacheModeCached) - } } func TestCacheOverview_ReturnsGatewayTimeoutWhenRequestDeadlineExceeded(t *testing.T) { diff --git a/internal/admin/handler_usage.go b/internal/admin/handler_usage.go index b8e81f850..0b748eb5f 100644 --- a/internal/admin/handler_usage.go +++ b/internal/admin/handler_usage.go @@ -371,7 +371,6 @@ func (h *Handler) CacheOverview(c *echo.Context) error { if err != nil { return handleError(c, err) } - params.CacheMode = usage.CacheModeCached if h.usageReader == nil { return c.JSON(http.StatusOK, usage.CacheOverview{ diff --git a/internal/usage/reader.go b/internal/usage/reader.go index d49672e74..d261bba1d 100644 --- a/internal/usage/reader.go +++ b/internal/usage/reader.go @@ -419,6 +419,9 @@ type UsageReader interface { GetUsageByRequestIDs(ctx context.Context, requestIDs []string) (map[string][]UsageLogEntry, error) // GetCacheOverview returns cached-only aggregates for the admin dashboard. + // The cached-only scope is this method's contract, not the caller's to + // arrange: an implementation overrides params.CacheMode rather than + // honouring it, so callers pass the params they parsed and no more. GetCacheOverview(ctx context.Context, params UsageQueryParams) (*CacheOverview, error) // GetTokenThroughput returns a fixed-width window of token-volume buckets diff --git a/internal/usage/reader_cache_mode_test.go b/internal/usage/reader_cache_mode_test.go new file mode 100644 index 000000000..a43cc4d41 --- /dev/null +++ b/internal/usage/reader_cache_mode_test.go @@ -0,0 +1,69 @@ +package usage + +import ( + "context" + "database/sql" + "testing" + "time" + + _ "modernc.org/sqlite" +) + +// TestGetCacheOverviewIgnoresRequestedCacheMode pins the contract documented on +// the UsageReader interface: cached-only scope belongs to GetCacheOverview, not +// to its caller. The admin handler used to set CacheMode itself, which made the +// guarantee look like the caller's job and left it asserted only through a stub +// reader that could not enforce it. +func TestGetCacheOverviewIgnoresRequestedCacheMode(t *testing.T) { + db, err := sql.Open("sqlite", ":memory:") + if err != nil { + t.Fatalf("open sqlite: %v", err) + } + defer db.Close() + + store, err := NewSQLiteStore(db, 0) + if err != nil { + t.Fatalf("NewSQLiteStore: %v", err) + } + defer store.Close() + + day := time.Date(2026, 6, 16, 12, 0, 0, 0, time.UTC) + ctx := context.Background() + if err := store.WriteBatch(ctx, []*UsageEntry{ + { + ID: "cached-hit", RequestID: "r1", ProviderID: "p1", Timestamp: day, + Model: "gpt-5", Provider: "openai", Endpoint: "/v1/chat/completions", + CacheType: CacheTypeExact, InputTokens: 100, OutputTokens: 20, TotalTokens: 120, + }, + { + ID: "uncached-miss", RequestID: "r2", ProviderID: "p1", Timestamp: day, + Model: "gpt-5", Provider: "openai", Endpoint: "/v1/chat/completions", + InputTokens: 200, OutputTokens: 40, TotalTokens: 240, + }, + }); err != nil { + t.Fatalf("WriteBatch: %v", err) + } + + reader, err := NewSQLiteReader(db) + if err != nil { + t.Fatalf("NewSQLiteReader: %v", err) + } + + // Every mode a caller could pass, including the one that would otherwise + // widen the result to uncached rows. + for _, mode := range []string{"", CacheModeAll, CacheModeUncached, CacheModeCached} { + t.Run("mode="+mode, func(t *testing.T) { + overview, err := reader.GetCacheOverview(ctx, UsageQueryParams{ + StartDate: day, + EndDate: day, + CacheMode: mode, + }) + if err != nil { + t.Fatalf("GetCacheOverview: %v", err) + } + if overview.Summary.TotalHits != 1 { + t.Fatalf("total_hits = %d, want 1 (the cached row only)", overview.Summary.TotalHits) + } + }) + } +} From 2e9a5978c8676926b8d962ed2fbbe91ed73ecc09 Mon Sep 17 00:00:00 2001 From: "Jakub A. W" Date: Sat, 25 Jul 2026 16:32:25 +0200 Subject: [PATCH 05/12] test(storage): run store suites against MongoDB MIME-Version: 1.0 Content-Type: text/plain; charset=UTF-8 Content-Transfer-Encoding: 8bit MongoDB stays hand-written rather than sharing an implementation with the SQL backends, which makes it the one place a behaviour can drift unnoticed — and 12 of its 16 stores had no test that touched a database. mongotest mirrors sqlxtest: it hands a suite an empty database and drops it afterwards, skipping unless MONGO_TEST_DSN names a reachable server. Names are bounded to MongoDB's 64-byte limit and stripped of the characters it rejects, which a nested subtest name would otherwise overrun. Six domains — virtualmodels, failover, pricingoverrides, mcpgateway, batch, responsestore — now run their store round-trips through a suite written against the domain's Store interface, so the same assertions cover SQLite, PostgreSQL and MongoDB. Tests that reach past the interface for a raw handle stay SQL-only. Co-Authored-By: Claude Opus 5 (1M context) --- internal/batch/store_sql_test.go | 27 ++++- internal/failover/store_sql_test.go | 22 +++- internal/mcpgateway/store_sql_test.go | 18 +++- internal/pricingoverrides/store_sql_test.go | 35 +++++-- internal/responsestore/store_sql_test.go | 27 ++++- internal/storage/mongotest/mongotest.go | 109 ++++++++++++++++++++ internal/virtualmodels/helpers_test.go | 23 +++++ internal/virtualmodels/store_test.go | 8 +- 8 files changed, 247 insertions(+), 22 deletions(-) create mode 100644 internal/storage/mongotest/mongotest.go diff --git a/internal/batch/store_sql_test.go b/internal/batch/store_sql_test.go index a741c5816..c38da0ebe 100644 --- a/internal/batch/store_sql_test.go +++ b/internal/batch/store_sql_test.go @@ -6,6 +6,9 @@ import ( "testing" "github.com/enterpilot/gomodel/internal/core" + "go.mongodb.org/mongo-driver/v2/mongo" + + "github.com/enterpilot/gomodel/internal/storage/mongotest" "github.com/enterpilot/gomodel/internal/storage/sqlx" "github.com/enterpilot/gomodel/internal/storage/sqlx/sqlxtest" ) @@ -21,6 +24,26 @@ func runSQLStoreTest(t *testing.T, body func(t *testing.T, store *SQLStore)) { }) } +// runStoreSuite exercises behaviour every Store implementation owes its +// callers, against each backend available in this environment. +func runStoreSuite(t *testing.T, body func(t *testing.T, store Store)) { + t.Helper() + sqlxtest.Run(t, func(t *testing.T, db sqlx.DB) { + store, err := NewSQLStore(context.Background(), db) + if err != nil { + t.Fatalf("NewSQLStore: %v", err) + } + body(t, store) + }) + mongotest.Run(t, func(t *testing.T, db *mongo.Database) { + store, err := NewMongoDBStore(db) + if err != nil { + t.Fatalf("NewMongoDBStore: %v", err) + } + body(t, store) + }) +} + func TestSQLStoreLifecycle(t *testing.T) { runSQLStoreTest(t, func(t *testing.T, store *SQLStore) { ctx := context.Background() @@ -79,8 +102,8 @@ func TestSQLStoreLifecycle(t *testing.T) { }) } -func TestSQLStoreDelete(t *testing.T) { - runSQLStoreTest(t, func(t *testing.T, store *SQLStore) { +func TestStoreDelete(t *testing.T) { + runStoreSuite(t, func(t *testing.T, store Store) { ctx := context.Background() if err := store.Delete(ctx, "missing"); !errors.Is(err, ErrNotFound) { t.Fatalf("delete missing = %v, want ErrNotFound", err) diff --git a/internal/failover/store_sql_test.go b/internal/failover/store_sql_test.go index 1b9929319..0cd7503e6 100644 --- a/internal/failover/store_sql_test.go +++ b/internal/failover/store_sql_test.go @@ -7,11 +7,16 @@ import ( "testing" "time" + "go.mongodb.org/mongo-driver/v2/mongo" + + "github.com/enterpilot/gomodel/internal/storage/mongotest" "github.com/enterpilot/gomodel/internal/storage/sqlx" "github.com/enterpilot/gomodel/internal/storage/sqlx/sqlxtest" ) -func runSQLStoreTest(t *testing.T, body func(t *testing.T, store *SQLStore)) { +// runStoreSuite exercises behaviour every Store implementation owes its +// callers, against each backend available in this environment. +func runStoreSuite(t *testing.T, body func(t *testing.T, store Store)) { t.Helper() sqlxtest.Run(t, func(t *testing.T, db sqlx.DB) { store, err := NewSQLStore(context.Background(), db) @@ -20,10 +25,17 @@ func runSQLStoreTest(t *testing.T, body func(t *testing.T, store *SQLStore)) { } body(t, store) }) + mongotest.Run(t, func(t *testing.T, db *mongo.Database) { + store, err := NewMongoDBStore(db) + if err != nil { + t.Fatalf("NewMongoDBStore: %v", err) + } + body(t, store) + }) } -func TestSQLStoreCRUDRoundTrip(t *testing.T) { - runSQLStoreTest(t, func(t *testing.T, store *SQLStore) { +func TestStoreCRUDRoundTrip(t *testing.T) { + runStoreSuite(t, func(t *testing.T, store Store) { ctx := context.Background() // Insert: untrimmed source is trimmed; targets and metadata round-trip. @@ -126,8 +138,8 @@ func TestSQLStoreCRUDRoundTrip(t *testing.T) { }) } -func TestSQLStoreUpsertNilTargetsRoundTrip(t *testing.T) { - runSQLStoreTest(t, func(t *testing.T, store *SQLStore) { +func TestStoreUpsertNilTargetsRoundTrip(t *testing.T) { + runStoreSuite(t, func(t *testing.T, store Store) { ctx := context.Background() // A rule with no targets must persist as an empty list and read back as nil diff --git a/internal/mcpgateway/store_sql_test.go b/internal/mcpgateway/store_sql_test.go index af16ed4cf..ca68bedcd 100644 --- a/internal/mcpgateway/store_sql_test.go +++ b/internal/mcpgateway/store_sql_test.go @@ -5,11 +5,16 @@ import ( "errors" "testing" + "go.mongodb.org/mongo-driver/v2/mongo" + + "github.com/enterpilot/gomodel/internal/storage/mongotest" "github.com/enterpilot/gomodel/internal/storage/sqlx" "github.com/enterpilot/gomodel/internal/storage/sqlx/sqlxtest" ) -func runSQLStoreTest(t *testing.T, body func(t *testing.T, store *SQLStore)) { +// runStoreSuite exercises behaviour every Store implementation owes its +// callers, against each backend available in this environment. +func runStoreSuite(t *testing.T, body func(t *testing.T, store Store)) { t.Helper() sqlxtest.Run(t, func(t *testing.T, db sqlx.DB) { store, err := NewSQLStore(context.Background(), db) @@ -18,10 +23,17 @@ func runSQLStoreTest(t *testing.T, body func(t *testing.T, store *SQLStore)) { } body(t, store) }) + mongotest.Run(t, func(t *testing.T, db *mongo.Database) { + store, err := NewMongoDBStore(db) + if err != nil { + t.Fatalf("NewMongoDBStore: %v", err) + } + body(t, store) + }) } -func TestSQLStoreRoundTrip(t *testing.T) { - runSQLStoreTest(t, func(t *testing.T, store *SQLStore) { +func TestStoreRoundTrip(t *testing.T) { + runStoreSuite(t, func(t *testing.T, store Store) { ctx := context.Background() server := ManagedServer{ diff --git a/internal/pricingoverrides/store_sql_test.go b/internal/pricingoverrides/store_sql_test.go index 3b719c7c9..225769bb2 100644 --- a/internal/pricingoverrides/store_sql_test.go +++ b/internal/pricingoverrides/store_sql_test.go @@ -6,6 +6,9 @@ import ( "strings" "testing" + "go.mongodb.org/mongo-driver/v2/mongo" + + "github.com/enterpilot/gomodel/internal/storage/mongotest" "github.com/enterpilot/gomodel/internal/storage/sqlx" "github.com/enterpilot/gomodel/internal/storage/sqlx/sqlxtest" ) @@ -21,6 +24,26 @@ func runSQLStoreTest(t *testing.T, body func(t *testing.T, store *SQLStore, db s }) } +// runStoreSuite exercises behaviour every Store implementation owes its +// callers, against each backend available in this environment. +func runStoreSuite(t *testing.T, body func(t *testing.T, store Store)) { + t.Helper() + sqlxtest.Run(t, func(t *testing.T, db sqlx.DB) { + store, err := NewSQLStore(context.Background(), db) + if err != nil { + t.Fatalf("NewSQLStore: %v", err) + } + body(t, store) + }) + mongotest.Run(t, func(t *testing.T, db *mongo.Database) { + store, err := NewMongoDBStore(db) + if err != nil { + t.Fatalf("NewMongoDBStore: %v", err) + } + body(t, store) + }) +} + func TestSQLStoreStoresPricingWithoutCurrency(t *testing.T) { runSQLStoreTest(t, func(t *testing.T, store *SQLStore, db sqlx.DB) { ctx := context.Background() @@ -59,8 +82,8 @@ func TestSQLStoreStoresPricingWithoutCurrency(t *testing.T) { }) } -func TestSQLStoreUpsertReplacesPricing(t *testing.T) { - runSQLStoreTest(t, func(t *testing.T, store *SQLStore, _ sqlx.DB) { +func TestStoreUpsertReplacesPricing(t *testing.T) { + runStoreSuite(t, func(t *testing.T, store Store) { ctx := context.Background() if err := store.Upsert(ctx, Override{ @@ -120,8 +143,8 @@ func TestSQLStoreListIsOrderedBySelector(t *testing.T) { }) } -func TestSQLStoreDeleteMissingReturnsNotFound(t *testing.T) { - runSQLStoreTest(t, func(t *testing.T, store *SQLStore, _ sqlx.DB) { +func TestStoreDeleteMissingReturnsNotFound(t *testing.T) { + runStoreSuite(t, func(t *testing.T, store Store) { err := store.Delete(context.Background(), "absent/model") if !errors.Is(err, ErrNotFound) { t.Fatalf("Delete error = %v, want ErrNotFound", err) @@ -129,8 +152,8 @@ func TestSQLStoreDeleteMissingReturnsNotFound(t *testing.T) { }) } -func TestSQLStoreDeleteRemovesOverride(t *testing.T) { - runSQLStoreTest(t, func(t *testing.T, store *SQLStore, _ sqlx.DB) { +func TestStoreDeleteRemovesOverride(t *testing.T) { + runStoreSuite(t, func(t *testing.T, store Store) { ctx := context.Background() if err := store.Upsert(ctx, Override{ diff --git a/internal/responsestore/store_sql_test.go b/internal/responsestore/store_sql_test.go index 97811076a..82a4b0078 100644 --- a/internal/responsestore/store_sql_test.go +++ b/internal/responsestore/store_sql_test.go @@ -10,6 +10,9 @@ import ( "github.com/goccy/go-json" "github.com/enterpilot/gomodel/internal/core" + "go.mongodb.org/mongo-driver/v2/mongo" + + "github.com/enterpilot/gomodel/internal/storage/mongotest" "github.com/enterpilot/gomodel/internal/storage/sqlx" "github.com/enterpilot/gomodel/internal/storage/sqlx/sqlxtest" ) @@ -26,6 +29,26 @@ func runSQLStoreTest(t *testing.T, body func(t *testing.T, store *SQLStore)) { }) } +// runStoreSuite exercises behaviour every Store implementation owes its +// callers, against each backend available in this environment. +func runStoreSuite(t *testing.T, body func(t *testing.T, store Store)) { + t.Helper() + sqlxtest.Run(t, func(t *testing.T, db sqlx.DB) { + store, err := NewSQLStore(context.Background(), db) + if err != nil { + t.Fatalf("NewSQLStore: %v", err) + } + body(t, store) + }) + mongotest.Run(t, func(t *testing.T, db *mongo.Database) { + store, err := NewMongoDBStore(db) + if err != nil { + t.Fatalf("NewMongoDBStore: %v", err) + } + body(t, store) + }) +} + func testStoredResponse(id string) *StoredResponse { return &StoredResponse{ Response: &core.ResponsesResponse{ @@ -156,8 +179,8 @@ func TestSQLStoreUpdateMissingReturnsNotFound(t *testing.T) { }) } -func TestSQLStoreDelete(t *testing.T) { - runSQLStoreTest(t, func(t *testing.T, store *SQLStore) { +func TestStoreDelete(t *testing.T) { + runStoreSuite(t, func(t *testing.T, store Store) { ctx := context.Background() if err := store.Create(ctx, testStoredResponse("resp-1")); err != nil { diff --git a/internal/storage/mongotest/mongotest.go b/internal/storage/mongotest/mongotest.go new file mode 100644 index 000000000..b69a78cd3 --- /dev/null +++ b/internal/storage/mongotest/mongotest.go @@ -0,0 +1,109 @@ +// Package mongotest runs a store's test suite against MongoDB. +// +// It is the document-store counterpart to sqlxtest. MongoDB stays hand-written +// rather than sharing an implementation with the SQL backends, which makes it +// the one place where a behaviour can drift unnoticed: most domains ship a +// MongoDB store with no test that touches a database. A suite written against +// the domain's Store interface can run on every backend, so a domain's +// behaviour is asserted once and checked everywhere. +// +// MongoDB runs only when MONGO_TEST_DSN names a reachable server; otherwise +// the subtest skips. The variable is deliberately not MONGODB_URL — a suite +// that creates and drops databases should take a separate, explicit opt-in. +package mongotest + +import ( + "context" + "os" + "strconv" + "strings" + "sync/atomic" + "testing" + + "go.mongodb.org/mongo-driver/v2/mongo" + "go.mongodb.org/mongo-driver/v2/mongo/options" +) + +// DSNEnv names the environment variable holding the test MongoDB connection +// string. +const DSNEnv = "MONGO_TEST_DSN" + +// databaseCounter keeps concurrently running subtests in separate databases. +// Tests must not depend on wall-clock time or randomness for naming. +var databaseCounter atomic.Uint64 + +// Run executes fn against an empty MongoDB database that is dropped +// afterwards, as a subtest named "mongodb". It skips when no server is +// configured. +func Run(t *testing.T, fn func(t *testing.T, db *mongo.Database)) { + t.Helper() + + t.Run("mongodb", func(t *testing.T) { + db := New(t) + if db == nil { + return // New already skipped + } + fn(t, db) + }) +} + +// New returns an empty MongoDB database for one test, or nil after skipping +// when no test server is configured. +func New(t *testing.T) *mongo.Database { + t.Helper() + + dsn := strings.TrimSpace(os.Getenv(DSNEnv)) + if dsn == "" { + t.Skipf("%s not set", DSNEnv) + return nil + } + + ctx := context.Background() + client, err := mongo.Connect(options.Client().ApplyURI(dsn)) + if err != nil { + t.Skipf("connect to %s: %v", DSNEnv, err) + return nil + } + if err := client.Ping(ctx, nil); err != nil { + _ = client.Disconnect(ctx) + t.Skipf("ping %s: %v", DSNEnv, err) + return nil + } + + db := client.Database(DatabaseName(t.Name(), databaseCounter.Add(1))) + t.Cleanup(func() { + _ = db.Drop(context.Background()) + _ = client.Disconnect(context.Background()) + }) + return db +} + +// DatabaseName builds a unique database name for a test. MongoDB rejects names +// of 64 bytes or more, so the test name is bounded rather than concatenated +// whole — a nested subtest name easily runs past the limit on its own. +func DatabaseName(testName string, counter uint64) string { + const prefix = "gomodel_test_" + + suffix := "_" + strconv.FormatUint(counter, 10) + sanitized := sanitize(testName) + if budget := 63 - len(prefix) - len(suffix); len(sanitized) > budget { + sanitized = sanitized[:budget] + } + return prefix + sanitized + suffix +} + +// sanitize reduces a test name to characters MongoDB accepts in a database +// name: it rejects / \ . " $ and null bytes, and Go test names routinely carry +// slashes. +func sanitize(name string) string { + var b strings.Builder + for _, r := range strings.ToLower(name) { + switch { + case r >= 'a' && r <= 'z', r >= '0' && r <= '9': + b.WriteRune(r) + default: + b.WriteByte('_') + } + } + return b.String() +} diff --git a/internal/virtualmodels/helpers_test.go b/internal/virtualmodels/helpers_test.go index 607fb0aa8..94d54b967 100644 --- a/internal/virtualmodels/helpers_test.go +++ b/internal/virtualmodels/helpers_test.go @@ -5,6 +5,9 @@ import ( "testing" "github.com/enterpilot/gomodel/internal/core" + "go.mongodb.org/mongo-driver/v2/mongo" + + "github.com/enterpilot/gomodel/internal/storage/mongotest" "github.com/enterpilot/gomodel/internal/storage/sqlx" "github.com/enterpilot/gomodel/internal/storage/sqlx/sqlxtest" ) @@ -20,6 +23,26 @@ func runSQLStoreTest(t *testing.T, body func(t *testing.T, store *SQLStore)) { }) } +// runStoreSuite exercises behaviour every Store implementation owes its +// callers, against each backend available in this environment. +func runStoreSuite(t *testing.T, body func(t *testing.T, store Store)) { + t.Helper() + sqlxtest.Run(t, func(t *testing.T, db sqlx.DB) { + store, err := NewSQLStore(context.Background(), db) + if err != nil { + t.Fatalf("NewSQLStore: %v", err) + } + body(t, store) + }) + mongotest.Run(t, func(t *testing.T, db *mongo.Database) { + store, err := NewMongoDBStore(db) + if err != nil { + t.Fatalf("NewMongoDBStore: %v", err) + } + body(t, store) + }) +} + // newSQLVMStore returns a store on a fresh in-memory SQLite database, for // tests that exercise logic above the store rather than the store itself. func newSQLVMStore(t *testing.T) *SQLStore { diff --git a/internal/virtualmodels/store_test.go b/internal/virtualmodels/store_test.go index 5195e5660..d891a1f47 100644 --- a/internal/virtualmodels/store_test.go +++ b/internal/virtualmodels/store_test.go @@ -7,8 +7,8 @@ import ( "testing" ) -func TestSQLStore_RoundTripRedirectAndPolicy(t *testing.T) { - runSQLStoreTest(t, func(t *testing.T, store *SQLStore) { +func TestStore_RoundTripRedirectAndPolicy(t *testing.T) { + runStoreSuite(t, func(t *testing.T, store Store) { ctx := context.Background() redirect := VirtualModel{ @@ -63,8 +63,8 @@ func TestSQLStore_RoundTripRedirectAndPolicy(t *testing.T) { }) } -func TestSQLStore_GetMissingAndDelete(t *testing.T) { - runSQLStoreTest(t, func(t *testing.T, store *SQLStore) { +func TestStore_GetMissingAndDelete(t *testing.T) { + runStoreSuite(t, func(t *testing.T, store Store) { ctx := context.Background() if _, err := store.Get(ctx, "nope"); !errors.Is(err, ErrNotFound) { From 4eca0520bbda5eea1571703397fe68aa05591e68 Mon Sep 17 00:00:00 2001 From: "Jakub A. W" Date: Sat, 25 Jul 2026 16:55:17 +0200 Subject: [PATCH 06/12] test(storage): address review findings on the MongoDB harness MIME-Version: 1.0 Content-Type: text/plain; charset=UTF-8 Content-Transfer-Encoding: 8bit - mongotest database names now carry the pid. The counter only separates subtests inside one process, and `go test ./...` runs packages in parallel — batch and responsestore both define TestStoreDelete, so two processes could create *and drop* the same database. A new test pins the naming rules: under 64 bytes, no character MongoDB rejects, pid and counter present. - Every mongotest server call is bounded, so an unreachable DSN skips promptly instead of stalling every opted-in suite, and cleanup cannot hang the test binary. - runStoreSuite closes the store it built. responsestore's SQL store runs a retention goroutine that the SQL-only helper stopped and the shared one did not. - The cache-mode test asserts token totals, not just hit counts: only one fixture row is a cache hit either way, so a mode that wrongly widened to both rows still counted 1. Verified it now fails without the reader's override. - The request-stats hour parse error is carried to the caller instead of being dropped, so the failure names the reason. Co-Authored-By: Claude Opus 5 (1M context) --- internal/auditlog/stats_sql.go | 9 +++- internal/batch/store_sql_test.go | 2 + internal/failover/store_sql_test.go | 2 + internal/mcpgateway/store_sql_test.go | 2 + internal/pricingoverrides/store_sql_test.go | 2 + internal/responsestore/store_sql_test.go | 2 + internal/storage/mongotest/mongotest.go | 43 +++++++++++---- internal/storage/mongotest/mongotest_test.go | 57 ++++++++++++++++++++ internal/usage/reader_cache_mode_test.go | 8 +++ internal/virtualmodels/helpers_test.go | 2 + 10 files changed, 118 insertions(+), 11 deletions(-) create mode 100644 internal/storage/mongotest/mongotest_test.go diff --git a/internal/auditlog/stats_sql.go b/internal/auditlog/stats_sql.go index 614cb541c..58f64d331 100644 --- a/internal/auditlog/stats_sql.go +++ b/internal/auditlog/stats_sql.go @@ -58,7 +58,7 @@ func (r *SQLReader) GetRequestStats(ctx context.Context, params RequestStatsPara return nil, fmt.Errorf("failed to scan audit request stats row: %w", err) } if !hour.valid { - return nil, fmt.Errorf("failed to parse audit request stats hour %q", hour.raw) + return nil, fmt.Errorf("failed to parse audit request stats hour %q: %w", hour.raw, hour.err) } row.HourUTC = hour.Time stats = append(stats, row) @@ -78,6 +78,7 @@ type statsHour struct { time.Time valid bool raw string + err error } func (h *statsHour) Scan(src any) error { @@ -95,11 +96,15 @@ func (h *statsHour) Scan(src any) error { } } +// parse keeps a failure on the value rather than returning it, so the caller +// can report it with the row context. The reason is carried along, not +// discarded. func (h *statsHour) parse(raw string) error { h.raw = raw parsed, err := time.ParseInLocation(statsHourLayout, raw, time.UTC) if err != nil { - return nil // reported by the caller, which has the row context + h.err = err + return nil } h.Time, h.valid = parsed, true return nil diff --git a/internal/batch/store_sql_test.go b/internal/batch/store_sql_test.go index c38da0ebe..c688e8759 100644 --- a/internal/batch/store_sql_test.go +++ b/internal/batch/store_sql_test.go @@ -33,6 +33,7 @@ func runStoreSuite(t *testing.T, body func(t *testing.T, store Store)) { if err != nil { t.Fatalf("NewSQLStore: %v", err) } + t.Cleanup(func() { _ = store.Close() }) body(t, store) }) mongotest.Run(t, func(t *testing.T, db *mongo.Database) { @@ -40,6 +41,7 @@ func runStoreSuite(t *testing.T, body func(t *testing.T, store Store)) { if err != nil { t.Fatalf("NewMongoDBStore: %v", err) } + t.Cleanup(func() { _ = store.Close() }) body(t, store) }) } diff --git a/internal/failover/store_sql_test.go b/internal/failover/store_sql_test.go index 0cd7503e6..c4f26d909 100644 --- a/internal/failover/store_sql_test.go +++ b/internal/failover/store_sql_test.go @@ -23,6 +23,7 @@ func runStoreSuite(t *testing.T, body func(t *testing.T, store Store)) { if err != nil { t.Fatalf("NewSQLStore: %v", err) } + t.Cleanup(func() { _ = store.Close() }) body(t, store) }) mongotest.Run(t, func(t *testing.T, db *mongo.Database) { @@ -30,6 +31,7 @@ func runStoreSuite(t *testing.T, body func(t *testing.T, store Store)) { if err != nil { t.Fatalf("NewMongoDBStore: %v", err) } + t.Cleanup(func() { _ = store.Close() }) body(t, store) }) } diff --git a/internal/mcpgateway/store_sql_test.go b/internal/mcpgateway/store_sql_test.go index ca68bedcd..d70b221fb 100644 --- a/internal/mcpgateway/store_sql_test.go +++ b/internal/mcpgateway/store_sql_test.go @@ -21,6 +21,7 @@ func runStoreSuite(t *testing.T, body func(t *testing.T, store Store)) { if err != nil { t.Fatalf("NewSQLStore: %v", err) } + t.Cleanup(func() { _ = store.Close() }) body(t, store) }) mongotest.Run(t, func(t *testing.T, db *mongo.Database) { @@ -28,6 +29,7 @@ func runStoreSuite(t *testing.T, body func(t *testing.T, store Store)) { if err != nil { t.Fatalf("NewMongoDBStore: %v", err) } + t.Cleanup(func() { _ = store.Close() }) body(t, store) }) } diff --git a/internal/pricingoverrides/store_sql_test.go b/internal/pricingoverrides/store_sql_test.go index 225769bb2..2b7c5510f 100644 --- a/internal/pricingoverrides/store_sql_test.go +++ b/internal/pricingoverrides/store_sql_test.go @@ -33,6 +33,7 @@ func runStoreSuite(t *testing.T, body func(t *testing.T, store Store)) { if err != nil { t.Fatalf("NewSQLStore: %v", err) } + t.Cleanup(func() { _ = store.Close() }) body(t, store) }) mongotest.Run(t, func(t *testing.T, db *mongo.Database) { @@ -40,6 +41,7 @@ func runStoreSuite(t *testing.T, body func(t *testing.T, store Store)) { if err != nil { t.Fatalf("NewMongoDBStore: %v", err) } + t.Cleanup(func() { _ = store.Close() }) body(t, store) }) } diff --git a/internal/responsestore/store_sql_test.go b/internal/responsestore/store_sql_test.go index 82a4b0078..5f76dfeab 100644 --- a/internal/responsestore/store_sql_test.go +++ b/internal/responsestore/store_sql_test.go @@ -38,6 +38,7 @@ func runStoreSuite(t *testing.T, body func(t *testing.T, store Store)) { if err != nil { t.Fatalf("NewSQLStore: %v", err) } + t.Cleanup(func() { _ = store.Close() }) body(t, store) }) mongotest.Run(t, func(t *testing.T, db *mongo.Database) { @@ -45,6 +46,7 @@ func runStoreSuite(t *testing.T, body func(t *testing.T, store Store)) { if err != nil { t.Fatalf("NewMongoDBStore: %v", err) } + t.Cleanup(func() { _ = store.Close() }) body(t, store) }) } diff --git a/internal/storage/mongotest/mongotest.go b/internal/storage/mongotest/mongotest.go index b69a78cd3..17d4c4bf0 100644 --- a/internal/storage/mongotest/mongotest.go +++ b/internal/storage/mongotest/mongotest.go @@ -19,6 +19,7 @@ import ( "strings" "sync/atomic" "testing" + "time" "go.mongodb.org/mongo-driver/v2/mongo" "go.mongodb.org/mongo-driver/v2/mongo/options" @@ -58,36 +59,60 @@ func New(t *testing.T) *mongo.Database { return nil } - ctx := context.Background() + // Every server call is bounded: an unreachable DSN should skip promptly + // rather than stall every opted-in suite, and cleanup must not be able to + // hang the test binary. + ctx, cancel := context.WithTimeout(context.Background(), connectTimeout) + defer cancel() + client, err := mongo.Connect(options.Client().ApplyURI(dsn)) if err != nil { t.Skipf("connect to %s: %v", DSNEnv, err) return nil } if err := client.Ping(ctx, nil); err != nil { - _ = client.Disconnect(ctx) + disconnect(client) t.Skipf("ping %s: %v", DSNEnv, err) return nil } db := client.Database(DatabaseName(t.Name(), databaseCounter.Add(1))) t.Cleanup(func() { - _ = db.Drop(context.Background()) - _ = client.Disconnect(context.Background()) + dropCtx, cancelDrop := context.WithTimeout(context.Background(), cleanupTimeout) + defer cancelDrop() + _ = db.Drop(dropCtx) + disconnect(client) }) return db } -// DatabaseName builds a unique database name for a test. MongoDB rejects names -// of 64 bytes or more, so the test name is bounded rather than concatenated -// whole — a nested subtest name easily runs past the limit on its own. +const ( + connectTimeout = 5 * time.Second + cleanupTimeout = 10 * time.Second +) + +func disconnect(client *mongo.Client) { + ctx, cancel := context.WithTimeout(context.Background(), cleanupTimeout) + defer cancel() + _ = client.Disconnect(ctx) +} + +// DatabaseName builds a unique database name for a test. +// +// The counter only separates subtests inside one process, and `go test ./...` +// runs packages in parallel — two packages that happen to share a test name +// would otherwise create *and drop* the same database. The pid separates them. +// +// MongoDB rejects names of 64 bytes or more, so the test name is bounded +// rather than concatenated whole: a nested subtest name easily runs past the +// limit on its own. func DatabaseName(testName string, counter uint64) string { const prefix = "gomodel_test_" - suffix := "_" + strconv.FormatUint(counter, 10) + suffix := "_" + strconv.Itoa(os.Getpid()) + "_" + strconv.FormatUint(counter, 10) sanitized := sanitize(testName) if budget := 63 - len(prefix) - len(suffix); len(sanitized) > budget { - sanitized = sanitized[:budget] + sanitized = sanitized[:max(budget, 0)] } return prefix + sanitized + suffix } diff --git a/internal/storage/mongotest/mongotest_test.go b/internal/storage/mongotest/mongotest_test.go new file mode 100644 index 000000000..10c86c52e --- /dev/null +++ b/internal/storage/mongotest/mongotest_test.go @@ -0,0 +1,57 @@ +package mongotest + +import ( + "os" + "strconv" + "strings" + "testing" +) + +func TestDatabaseName(t *testing.T) { + pid := strconv.Itoa(os.Getpid()) + + tests := []struct { + name string + testName string + counter uint64 + }{ + {"plain", "TestStoreDelete", 1}, + {"subtest path", "TestStoreDelete/mongodb", 2}, + {"deeply nested", strings.Repeat("TestSomethingWithAVeryLongName/", 8), 3}, + {"forbidden characters", `Test$Store."weird"\name`, 4}, + {"empty", "", 5}, + } + + for _, tc := range tests { + t.Run(tc.name, func(t *testing.T) { + got := DatabaseName(tc.testName, tc.counter) + + if len(got) >= 64 { + t.Errorf("len(%q) = %d, want < 64", got, len(got)) + } + // MongoDB rejects these outright. + if strings.ContainsAny(got, `/\. "$`+"\x00") { + t.Errorf("name %q holds a character MongoDB rejects", got) + } + // The pid keeps parallel package processes apart; the counter keeps + // subtests within one process apart. + if !strings.HasSuffix(got, "_"+pid+"_"+strconv.FormatUint(tc.counter, 10)) { + t.Errorf("name %q does not end in the pid and counter", got) + } + }) + } +} + +// TestDatabaseNameSeparatesProcessesAndSubtests is the property that matters: +// two packages running the same test name concurrently must not create — and +// then drop — the same database. +func TestDatabaseNameSeparatesProcessesAndSubtests(t *testing.T) { + first := DatabaseName("TestStoreDelete/mongodb", 1) + second := DatabaseName("TestStoreDelete/mongodb", 2) + if first == second { + t.Fatalf("counter did not separate subtests: both %q", first) + } + if !strings.Contains(first, strconv.Itoa(os.Getpid())) { + t.Fatalf("name %q carries no pid, so another test process could collide", first) + } +} diff --git a/internal/usage/reader_cache_mode_test.go b/internal/usage/reader_cache_mode_test.go index a43cc4d41..7d98250bb 100644 --- a/internal/usage/reader_cache_mode_test.go +++ b/internal/usage/reader_cache_mode_test.go @@ -64,6 +64,14 @@ func TestGetCacheOverviewIgnoresRequestedCacheMode(t *testing.T) { if overview.Summary.TotalHits != 1 { t.Fatalf("total_hits = %d, want 1 (the cached row only)", overview.Summary.TotalHits) } + // Hit counts alone cannot catch a leak: only one row is a cache + // hit either way, so a mode that wrongly widened to both rows + // would still count 1. The token totals differ between the two + // rows, so they do catch it. + if overview.Summary.TotalInput != 100 || overview.Summary.TotalTokens != 120 { + t.Fatalf("tokens = in %d / total %d, want 100 / 120 — the uncached row leaked in", + overview.Summary.TotalInput, overview.Summary.TotalTokens) + } }) } } diff --git a/internal/virtualmodels/helpers_test.go b/internal/virtualmodels/helpers_test.go index 94d54b967..de55f0b0a 100644 --- a/internal/virtualmodels/helpers_test.go +++ b/internal/virtualmodels/helpers_test.go @@ -32,6 +32,7 @@ func runStoreSuite(t *testing.T, body func(t *testing.T, store Store)) { if err != nil { t.Fatalf("NewSQLStore: %v", err) } + t.Cleanup(func() { _ = store.Close() }) body(t, store) }) mongotest.Run(t, func(t *testing.T, db *mongo.Database) { @@ -39,6 +40,7 @@ func runStoreSuite(t *testing.T, body func(t *testing.T, store Store)) { if err != nil { t.Fatalf("NewMongoDBStore: %v", err) } + t.Cleanup(func() { _ = store.Close() }) body(t, store) }) } From fc975451879310bf38ae7f965acc1a3807303299 Mon Sep 17 00:00:00 2001 From: "Jakub A. W" Date: Sat, 25 Jul 2026 17:03:47 +0200 Subject: [PATCH 07/12] test(auditlog): pin that timestamps are stored in UTC on both engines sqlx.Timestamp deliberately does not normalise on read, so the guarantee has to hold on the way in. This asserts it against the column itself, not the reader's interpretation: a caller writing 14:30+02:00 must leave 12:30 with a UTC marker in the row, on SQLite text and PostgreSQL timestamptz alike, and the instant must survive the round trip for both the entry and its attempts. Without it, a write that bypassed Dialect.TimestampArg would store a local-offset string on SQLite that sorts wrongly against every other row, and the date-range filters would quietly return the wrong day. Co-Authored-By: Claude Opus 5 (1M context) --- internal/auditlog/timestamp_utc_test.go | 84 +++++++++++++++++++++++++ 1 file changed, 84 insertions(+) create mode 100644 internal/auditlog/timestamp_utc_test.go diff --git a/internal/auditlog/timestamp_utc_test.go b/internal/auditlog/timestamp_utc_test.go new file mode 100644 index 000000000..1bef47414 --- /dev/null +++ b/internal/auditlog/timestamp_utc_test.go @@ -0,0 +1,84 @@ +package auditlog + +import ( + "context" + "strings" + "testing" + "time" + + "github.com/enterpilot/gomodel/internal/storage/sqlx" + "github.com/enterpilot/gomodel/internal/storage/sqlx/sqlxtest" +) + +// TestStoreWritesTimestampsInUTC pins the invariant the whole audit schema +// rests on: whatever zone a caller hands in, the column holds UTC. +// +// It matters because sqlx.Timestamp deliberately does *not* normalise on read +// — each driver's own zone is what callers already render — so the guarantee +// has to be established on the way in. If a write ever bypassed +// Dialect.TimestampArg, SQLite would store a local-offset string that sorts +// wrongly against every other row, and the date-range filters would quietly +// return the wrong day. +func TestStoreWritesTimestampsInUTC(t *testing.T) { + sqlxtest.Run(t, func(t *testing.T, db sqlx.DB) { + warsaw, err := time.LoadLocation("Europe/Warsaw") + if err != nil { + t.Fatalf("load location: %v", err) + } + // 14:30+02:00 is 12:30 UTC. A local-zone write would store 14:30. + written := time.Date(2026, 7, 25, 14, 30, 0, 123456000, warsaw) + + store, err := NewSQLStore(context.Background(), db, 0) + if err != nil { + t.Fatalf("NewSQLStore: %v", err) + } + defer store.Close() + + ctx := context.Background() + if err := store.WriteBatch(ctx, []*LogEntry{{ + ID: "utc-entry", Timestamp: written, Provider: "openai", StatusCode: 200, + Data: &LogData{Attempts: []AttemptSnapshot{{Seq: 1, Kind: "primary", StartedAt: written}}}, + }}); err != nil { + t.Fatalf("WriteBatch: %v", err) + } + + // The column itself, not the reader's interpretation of it. + timestampExpr := "timestamp" + if db.Dialect() == sqlx.PostgreSQL { + timestampExpr = "timestamp::text" + } + var stored string + if err := db.QueryRow(ctx, + "SELECT "+timestampExpr+" FROM audit_logs WHERE id = ?", "utc-entry").Scan(&stored); err != nil { + t.Fatalf("read stored timestamp: %v", err) + } + if !strings.Contains(stored, "12:30:00") { + t.Errorf("stored timestamp = %q, want the 12:30 UTC wall clock, not the caller's 14:30", stored) + } + // SQLite writes RFC3339 text ending in Z; PostgreSQL renders a +00 offset. + if !strings.HasSuffix(stored, "Z") && !strings.Contains(stored, "+00") { + t.Errorf("stored timestamp = %q, want a UTC zone marker", stored) + } + + // And the instant survives the round trip. PostgreSQL's TIMESTAMPTZ + // holds microseconds, so the fixture stays inside that precision. + reader, err := NewSQLReader(db) + if err != nil { + t.Fatalf("NewSQLReader: %v", err) + } + entry, err := reader.GetLogByID(ctx, "utc-entry") + if err != nil { + t.Fatalf("GetLogByID: %v", err) + } + if !entry.Timestamp.Equal(written) { + t.Errorf("round-tripped timestamp = %s, want the same instant as %s", entry.Timestamp, written) + } + if entry.Data == nil || len(entry.Data.Attempts) != 1 { + t.Fatalf("attempts = %+v, want one hydrated attempt", entry.Data) + } + if !entry.Data.Attempts[0].StartedAt.Equal(written) { + t.Errorf("attempt started_at = %s, want the same instant as %s", + entry.Data.Attempts[0].StartedAt, written) + } + }) +} From 977fc719f64c8160d123b6bba1808c62d56211ff Mon Sep 17 00:00:00 2001 From: "Jakub A. W" Date: Sat, 25 Jul 2026 17:06:02 +0200 Subject: [PATCH 08/12] docs(dev): record the per-backend timestamp rendering as deferred MIME-Version: 1.0 Content-Type: text/plain; charset=UTF-8 Content-Transfer-Encoding: 8bit Writes are UTC on every backend and now have a test asserting it against the stored column. Reads are not normalised, so the same entry serialises with a Z on SQLite and a server-local offset on PostgreSQL. Pre-existing, same instant either way, and normalising would change the timestamp string in every PostgreSQL deployment's admin API responses — so it is a separate decision rather than part of a refactor. Co-Authored-By: Claude Opus 5 (1M context) --- docs/dev/2026-07-25_backend-refactor-survey.md | 13 +++++++++++++ 1 file changed, 13 insertions(+) diff --git a/docs/dev/2026-07-25_backend-refactor-survey.md b/docs/dev/2026-07-25_backend-refactor-survey.md index bb27179bb..ad9045872 100644 --- a/docs/dev/2026-07-25_backend-refactor-survey.md +++ b/docs/dev/2026-07-25_backend-refactor-survey.md @@ -205,6 +205,19 @@ several now do (`guardrails`, `mcpgateway`, `failover`, `ratelimit`, - **F6 (b)–(e)**: cache-type vocabulary spread over four packages (import-cycle risk), `failover/resolver.go` recomputing selector identity per request, `config.loadFailoverConfig` mixing validation with a bespoke JSON loader. +- **Timestamps render in a different zone per backend.** Writes are UTC + everywhere — `Dialect.TimestampArg` normalises on both engines, and + `auditlog.TestStoreWritesTimestampsInUTC` asserts it against the stored + column rather than the reader. Reads are *not* normalised: SQLite returns the + `Z` text it stored, while pgx materialises a `TIMESTAMPTZ` in the server's + local zone, so the same entry serialises as `…T12:30:00Z` or + `…T14:30:00+02:00` depending on the backend, with an offset that also shifts + with DST. Same instant, and any client parsing RFC 3339 correctly is + unaffected. This is pre-existing — neither hand-written reader normalised + either — and `sqlx.Timestamp` preserves it deliberately. Normalising is one + line in `Scan`, but it changes the timestamp string in every PostgreSQL + deployment's admin API responses, so it was left as a separate decision + rather than folded into a refactor. `docs/dev/possible-refactoring.md` items 2, 6, 7 and 10 are **stale** — the dashboard JS they reference was replaced by the Svelte app, and the failover From 14d104b64e009253fcd5272de82af969072429b2 Mon Sep 17 00:00:00 2001 From: "Jakub A. W" Date: Sat, 25 Jul 2026 17:08:56 +0200 Subject: [PATCH 09/12] docs(dev): trim the storage refactor note to lessons and open work Three of its deferred items were done in #587 and its MongoDB coverage numbers were stale, so the one section anyone reads was actively wrong. Removed what had a better home or no longer applied: a baseline snapshot of a commit two releases back, line-count tables git already holds, a paragraph on sqlxtest duplicating that package's own doc comment, the driver binding facts now stated on the type tokens, and a reconciliation against a file deleted in #586. 261 lines to 112, and renamed, since it stopped being a survey the moment the survey was acted on. Also fixes the dangling pointer to that deleted file in the 2026-07-04 architecture review. Co-Authored-By: Claude Opus 5 (1M context) --- docs/dev/2026-07-04_architecture-review.md | 5 +- .../dev/2026-07-25_backend-refactor-survey.md | 261 ------------------ docs/dev/2026-07-25_storage-refactor.md | 112 ++++++++ 3 files changed, 115 insertions(+), 263 deletions(-) delete mode 100644 docs/dev/2026-07-25_backend-refactor-survey.md create mode 100644 docs/dev/2026-07-25_storage-refactor.md diff --git a/docs/dev/2026-07-04_architecture-review.md b/docs/dev/2026-07-04_architecture-review.md index baca8eff4..f619f845d 100644 --- a/docs/dev/2026-07-04_architecture-review.md +++ b/docs/dev/2026-07-04_architecture-review.md @@ -1,8 +1,9 @@ # Architecture Review — 2026-07-04 Scope: whole repo on `chore/architecture` (HEAD `87d78d2c`). Evidence is cited as -`file:line`. Items already tracked in `docs/dev/possible-refactoring.md` are marked -**(known #N)** rather than re-explained. +`file:line`. Items marked **(known #N)** were already tracked in a +`docs/dev/possible-refactoring.md` list that has since been retired; its live +entries were carried into `docs/dev/2026-07-25_storage-refactor.md`. Legend: **[COUPLING]** dependency/blast-radius problem · **[SMELL]** design debt · **[BUG]** incorrect behavior · **[REMOVE]** dead or redundant code · diff --git a/docs/dev/2026-07-25_backend-refactor-survey.md b/docs/dev/2026-07-25_backend-refactor-survey.md deleted file mode 100644 index ad9045872..000000000 --- a/docs/dev/2026-07-25_backend-refactor-survey.md +++ /dev/null @@ -1,261 +0,0 @@ -# Backend Refactor — Survey and Outcome, 2026-07-25 - -Branch: `refactor/rework2` (surveyed at `7b74d973`). - -Part 1 is the survey that scoped the work. Part 2 records what was executed, -what it cost, what it broke, and what is deliberately left. - ---- - -# Part 1 — Survey - -## 1. Baseline - -| Metric | Value | -|---|---| -| Backend Go, non-test | 117,407 lines | -| — of which generated (`cmd/gomodel/docs/docs.go`) | 11,013 | -| — hand-written | **106,394** | -| Backend Go, test | 124,908 | -| Packages under `internal/` | 30 | -| `golangci-lint run` (errcheck, govet, ineffassign, staticcheck, unused, **dupl@100**) | **0 issues** | -| `deadcode -test ./...` | **4 findings**, all documented deliberate keeps | - -## 2. What was already clean — no effort spent there - -- **Dead code.** Three prior sweeps exhausted it. `deadcode -test ./...` returns - 4 symbols, all deliberate (`ext/registry.go`, the documented embedder API). -- **Lint and token-level duplication.** `dupl` runs at threshold 100 and the - tree is green. All remaining duplication was *structural* — same shape, - different API calls — which is precisely why a token-based detector never - saw it. -- **Provider adapters.** `internal/providers/*/` is already well factored: - small providers embed `openai.ChatCompatible` and are ~50 lines of real - configuration each. -- **Admin handlers**, **`config/`**, and the **`internal/core` JSON layer**: - all appropriately factored for what they do. - -## 3. The finding - -Every persisted domain shipped three near-identical store implementations plus -a factory: **18,259 lines, 15.5% of the hand-written backend**, over 17 -domains, plus 6,374 lines of backend-specific store tests. - -Normalising placeholders and type names, the SQLite and PostgreSQL halves were -50–83% textually identical. Reading the full `responsestore` diff, the *entire* -difference was six mechanical things: the driver handle type, `?` vs `$n`, the -no-rows sentinel, the `RowsAffected` signature, `Exec` arity, and DDL column -type names. - -**The coverage asymmetry mattered more than the line count:** - -| Backend | store test files | implementations | untested | -|---|---:|---:|---:| -| SQLite | 22 | 22 | 0 | -| PostgreSQL | **4** | 22 | **18** | -| MongoDB | 9 | 22 | 13 | - -and the four PostgreSQL "tests" that existed only asserted generated SQL -strings — **no PostgreSQL store code executed against a database anywhere in -the suite.** Predictably it had drifted: `failover` normalised padded primary -keys through two independently written migrations, only one of them verified. - ---- - -# Part 2 — Outcome - -## 4. What was executed - -| Phase | Work | Status | -|---|---|---| -| 1 | `internal/storage/sqlx` adapter + conformance suite | done | -| 2 | Migrate stores to one implementation | **16 of 17 domains** | -| 3 | Single storage connection; delete the duplicate constructors | done | -| 4 | `Shutdown` → ordered closer list | done | -| 5 | Small cleanups | partly; see §7 | - -Net across the branch: **130 files changed, +8,460 / −10,470**. - -| | before | after | -|---|---:|---:| -| SQLite store code | 5,570 | 1,705 | -| PostgreSQL store code | 5,015 | 1,448 | -| Unified `store_sql*.go` | — | 3,948 | -| `internal/storage/sqlx` | — | 820 | -| Factories | 2,232 | 1,762 | - -**PostgreSQL subtests executing against a real database: 0 → 91.** - -## 5. The adapter - -`internal/storage/sqlx` absorbs exactly the five mechanical differences and -nothing else. Two things it deliberately does *not* abstract, both settled by -probing the drivers rather than assuming: - -- **Value binding and scanning.** Both drivers already agree. A Go `bool` binds - to SQLite `INTEGER` and PostgreSQL `BOOLEAN`; an `INTEGER` scans into - `*bool`; `TEXT`/`JSON`/`JSONB` all scan into `[]byte`; nullable columns scan - into `*string`/`*int64` on both. The `boolToSQLite` helpers and the - `sql.NullString`-vs-`*string` split in the old stores were accidental - divergence, not dialect requirements. -- **Genuinely dialect-specific SQL.** Kept behind a `Dialect()` check and - labelled, rather than forced into a false abstraction. Three places qualify: - - `conversationstore`'s JSON mutations — SQLite JSON1 functions vs PostgreSQL - jsonb operators. These must mutate JSON server-side in a single `UPDATE` or - concurrent Responses turns overwrite each other; there is no portable - spelling. - - `failover` and `ratelimit` legacy migrations — column rename in place vs - table rebuild, and `PRAGMA` vs `information_schema` introspection. - - `budget.SumUsageCost` — SQLite stores the usage timestamp as text and must - convert it; PostgreSQL compares a real timestamp and must quote `"usage"`. - -`sqlxtest.Run` executes a suite against every available dialect: SQLite always, -PostgreSQL when `GOMODEL_TEST_POSTGRES_URL` is set. The variable is -deliberately *not* `POSTGRES_URL` — a suite that creates and drops schemas -should not point at a configured application database by accident. - -## 6. Three things this got wrong, and how they surfaced - -Recording these because each marks a real gap, not just a fixed bug. - -1. **`InTx` was documented as serializing read-then-write. It does not.** - Writing the conformance test disproved the claim: SQLite's `BEGIN IMMEDIATE` - makes concurrent transactions queue, but PostgreSQL's default READ COMMITTED - lets both read the same `MAX` and the second fail on the unique index. This - difference is pre-existing — the two workflow stores already behaved this - way. The suite now asserts atomicity, which does hold on both, and the - isolation difference is documented on `InTx` rather than hidden. - -2. **A schema break for existing PostgreSQL deployments.** `workflow_versions` - was the one table where the backends disagreed on representation: SQLite - stored `created_at` as INTEGER unix seconds, PostgreSQL as `TIMESTAMPTZ`. - Unifying on unix seconds — which every other table already used on both - engines — left existing PostgreSQL databases unreadable. **The unit suite - could not catch this: `sqlxtest` builds each case a fresh schema, so it never - meets a table created by an earlier release.** A smoke test against a real - PostgreSQL database that already had the table did. Fixed with an in-place - `EXTRACT(EPOCH FROM ...)` conversion in `NewSQLStore`, plus a test starting - from the legacy shape. - - **Two consequences operators need to know.** The conversion keeps the - instant but not the representation: a workflow's `created_at` in - `GET /admin/workflows` is floored to whole seconds and renders as UTC - (`2026-07-25T14:04:29.08001+02:00` becomes `2026-07-25T12:04:29Z`). It - floors rather than casts because `EXTRACT(EPOCH FROM ...)::bigint` *rounds* - — a `.6`-second row would land a second in the future and disagree with the - truncation `time.Unix` performs on every row written afterwards. Nothing - depends on the lost precision — `active` is enforced by a unique partial - index, so the one `ORDER BY created_at DESC ... LIMIT 1` query cannot tie — - and this is the granularity SQLite always had. And the conversion is - **one-way**: once the new binary has started against a PostgreSQL database, - an older binary rolled back onto it fails at startup with `cannot scan int8 - (OID 20) in binary format into *time.Time`. Roll back by restoring a dump - taken before the upgrade, not by swapping the binary. - -3. **A nil-handling bug in the new shutdown ordering.** `closerOf` initially - handled typed-nil `*Result` but not a nil `storage.Storage` interface, which - reflect reports as *invalid* rather than as a nil pointer. An existing - narrow test caught it; nothing covered `app.New` → `Shutdown` end to end, - which is why a lifecycle test now exists. - -The general lesson: **a conformance suite over fresh schemas proves the dialects -agree, but says nothing about upgrading a database written by an older -release.** Migration paths need tests that start from the old table shape — -several now do (`guardrails`, `mcpgateway`, `failover`, `ratelimit`, -`workflows`). - -## 7. What is deliberately not done - -- **The `usage` store, and both analytics readers.** - - The readers (`usage` 1,376 lines, `auditlog` 892) are the one place where the - divergence is real analytics SQL — 7 SQLite date-function sites versus 6 - PostgreSQL ones for bucketing and grouping — not mechanical duplication. They - deserve a deliberate decision about whether a shared query builder beats two - honest implementations. - - The **`usage` store** was scoped as mechanical and is not, which is worth - recording because the estimate came from counting dialect-specific constructs - in the store file alone and that missed two couplings: - - 1. `RecalculatePricing` is a store method whose row queries are built by the - *reader's* `sqliteUsageConditions` / `pgUsageConditions`. Unifying the - store without the reader means keeping a dialect switch that reaches into - reader internals. - 2. The two implementations differ **semantically, not syntactically**: SQLite - paginates by `id > lastID` in batches of 500, while PostgreSQL selects - every matching row in one statement with `FOR UPDATE` row locking. Those - are different memory and locking profiles, and picking one would change - behaviour on the other engine. - - So `usage` should follow its reader rather than lead it. `auditlog`'s store, - which had no such coupling, was migrated. -- **`CacheModeCached` set in four places** (F6a). Removing the handler's copy - in favour of reader ownership breaks three admin tests that assert it through - a *stub* reader; with the readers still split and not uniformly tested, that - would weaken coverage to force a cleanup through. It belongs with the reader - unification, when there is exactly one owner. -- **F5, the config-shadows-store precedence.** Nine subsystems implement it - three different ways (shadow at read, replace at startup, upsert at startup), - so removing an entry from `config.yaml` and restarting behaves differently - per subsystem. This is a product-behaviour decision, not a refactor, and was - explicitly deferred. -- **MongoDB.** Stays hand-written by decision: document semantics are not a SQL - dialect. 13 of its 22 implementations remain untested. -- **F6 (b)–(e)**: cache-type vocabulary spread over four packages (import-cycle - risk), `failover/resolver.go` recomputing selector identity per request, - `config.loadFailoverConfig` mixing validation with a bespoke JSON loader. -- **Timestamps render in a different zone per backend.** Writes are UTC - everywhere — `Dialect.TimestampArg` normalises on both engines, and - `auditlog.TestStoreWritesTimestampsInUTC` asserts it against the stored - column rather than the reader. Reads are *not* normalised: SQLite returns the - `Z` text it stored, while pgx materialises a `TIMESTAMPTZ` in the server's - local zone, so the same entry serialises as `…T12:30:00Z` or - `…T14:30:00+02:00` depending on the backend, with an offset that also shifts - with DST. Same instant, and any client parsing RFC 3339 correctly is - unaffected. This is pre-existing — neither hand-written reader normalised - either — and `sqlx.Timestamp` preserves it deliberately. Normalising is one - line in `Scan`, but it changes the timestamp string in every PostgreSQL - deployment's admin API responses, so it was left as a separate decision - rather than folded into a refactor. - -`docs/dev/possible-refactoring.md` items 2, 6, 7 and 10 are **stale** — the -dashboard JS they reference was replaced by the Svelte app, and the failover -helpers they name no longer exist. Items 3, 5, 8, 9 remain live and are carried -into §7 above. - -## 8. Verification - -Every commit passed the full pre-commit gate: `make test-race`, `make lint` -and `make fix-check` across all build tags -(`swagger,e2e,integration,contract`). Beyond that: - -- CI runs a `postgres:18-alpine` service and sets - `GOMODEL_TEST_POSTGRES_URL`, so all 91 PostgreSQL subtests execute there - rather than skip. -- The built binary was smoke-tested on both backends: boot, `/health`, an - auth-gated `/v1/models`, and graceful shutdown. This is what caught the - `workflow_versions` schema break, which no unit test could have. -- The full release matrix (`tests/e2e/release-e2e-scenarios.md`, 196 scenarios - over six gateways and real provider upstreams) passed with no failures and no - skips, as did `tests/e2e/test-iac-virtualmodels.sh` (19 checks) and the - dashboard suite (331 tests). -- **An upgrade harness** (`tests/e2e/upgrade-compat.sh`) boots the `main` binary against an empty database, - writes a row through every store domain, restarts it so the snapshot comes - from storage rather than from the caches the writes populated, then boots - this branch on the same database. All 17 domain reads come back identical and - every domain still accepts writes, on SQLite, PostgreSQL and MongoDB. This is - what established the `created_at` representation change and the one-way - migration in §6.2 — a fresh-schema conformance suite sees neither. - -**To run the PostgreSQL half locally:** - -```bash -make infra # brings up postgres on :5432 -GOMODEL_TEST_POSTGRES_URL="postgres://gomodel:gomodel@localhost:5432/gomodel" \ - go test ./internal/... -``` - -Without the variable the PostgreSQL subtests skip and SQLite still covers every -store, so CI stays green either way — but the variable should be set in CI, or -the coverage this work bought is left on the floor. diff --git a/docs/dev/2026-07-25_storage-refactor.md b/docs/dev/2026-07-25_storage-refactor.md new file mode 100644 index 000000000..5e2d74b01 --- /dev/null +++ b/docs/dev/2026-07-25_storage-refactor.md @@ -0,0 +1,112 @@ +# Storage Refactor — Lessons and Remaining Work + +Started 2026-07-25 on `refactor/rework2` (#586), continued on `refactor/rework3` +(#587). + +Every persisted domain used to ship three near-identical store implementations +plus a factory — 18,259 lines, 15.5% of the hand-written backend, over 17 +domains. Normalising placeholders and type names, the SQLite and PostgreSQL +halves were 50–83% textually identical, and the entire difference came down to +six mechanical things: the driver handle type, `?` vs `$n`, the no-rows +sentinel, the `RowsAffected` signature, `Exec` arity, and DDL column type names. + +`internal/storage/sqlx` absorbs exactly those. What it deliberately does *not* +abstract, and why, is documented at the code: the type tokens in `dialect.go`, +the isolation difference on `InTx`, the read/write timestamp pair on +`TimestampArg` and `sqlx.Timestamp`, and the opt-in rationale on the `sqlxtest` +and `mongotest` packages. Genuinely dialect-specific SQL is kept behind a +labelled `Dialect()` check at each site rather than forced into a false +abstraction. + +This file keeps the two things that outlive the pull requests: what the work got +wrong, and what is left. + +## What this got wrong, and how it surfaced + +Each marks a real gap, not just a fixed bug. + +1. **`InTx` was documented as serializing read-then-write. It does not.** + Writing the conformance test disproved the claim: SQLite's `BEGIN IMMEDIATE` + makes concurrent transactions queue, but PostgreSQL's default READ COMMITTED + lets both read the same `MAX` and the second fail on the unique index. The + difference is pre-existing — the two workflow stores already behaved this + way. The suite now asserts atomicity, which does hold on both, and the + isolation difference is documented on `InTx` rather than hidden. Code + allocating a key from a `MAX` must handle the conflict. + +2. **A schema break for existing PostgreSQL deployments.** `workflow_versions` + was the one table where the backends disagreed on representation: SQLite + stored `created_at` as INTEGER unix seconds, PostgreSQL as `TIMESTAMPTZ`. + Unifying on unix seconds left existing PostgreSQL databases unreadable. + **The unit suite could not catch it: `sqlxtest` builds each case a fresh + schema, so it never meets a table created by an earlier release.** A smoke + test against a real PostgreSQL database that already had the table did. + + The conversion floors rather than casts, because `EXTRACT(EPOCH FROM + ...)::bigint` *rounds* — a `.6`-second row would land a second in the future + and disagree with the truncation `time.Unix` performs on every row written + afterwards. It is also one-way. Operator-facing consequences are in + `docs/advanced/configuration.mdx`. + +3. **A nil-handling bug in the new shutdown ordering.** `closerOf` initially + handled typed-nil `*Result` but not a nil `storage.Storage` interface, which + reflect reports as *invalid* rather than as a nil pointer. An existing narrow + test caught it; nothing covered `app.New` → `Shutdown` end to end, which is + why a lifecycle test now exists. + +**The general lesson: a conformance suite over fresh schemas proves the dialects +agree, but says nothing about upgrading a database written by an older release.** +Migration paths need tests that start from the old table shape — several now do +(`guardrails`, `mcpgateway`, `failover`, `ratelimit`, `workflows`) — and +`tests/e2e/upgrade-compat.sh` runs the previous release's binary against an +empty database, then this one against the result, across all three backends. + +## What is left + +- **The `usage` store and its reader.** The reader is the one place where the + divergence is real analytics SQL — timezone-aware bucketing and grouping, and + on SQLite a generated `CASE` over DST segments that PostgreSQL does natively + with `AT TIME ZONE` — not mechanical duplication. + + The store cannot move without it. `RecalculatePricing` is a *store* method + whose row filter is built by the *reader's* `sqliteUsageConditions` / + `pgUsageConditions`, and those emit different placeholder styles, so a + unified store cannot borrow either one. Attempted during #587 and reverted: + it is ~2,100 lines of implementation plus ~1,500 of tests and wants its own + pass. + + The two implementations also differ *semantically*: SQLite paginates + `RecalculatePricing` by `id > lastID` in batches of 500, while PostgreSQL + selects every matching row in one statement with `FOR UPDATE`. Those are + different memory and locking profiles. **Decision taken:** keep both paths + behind a labelled `Dialect()` check so neither engine's behaviour changes. + +- **F5, the config-shadows-store precedence.** Nine subsystems implement it + three different ways (shadow at read, replace at startup, upsert at startup), + so removing an entry from `config.yaml` and restarting behaves differently per + subsystem. A product-behaviour decision, not a refactor. + +- **MongoDB stays hand-written** by decision: document semantics are not a SQL + dialect. `internal/storage/mongotest` now lets a domain's suite run against + it, and seven domains do: batch, failover, filestore, mcpgateway, + pricingoverrides, responsestore, virtualmodels. Nine still have no test that + touches a database: auditlog, authkeys, budget, conversationstore, guardrails, + ratelimit, tagging, usage, workflows. The pattern to copy is a + `runStoreSuite` written against the domain's `Store` interface that calls both + `sqlxtest.Run` and `mongotest.Run`. + +- **Timestamps render in a different zone per backend.** Writes are UTC + everywhere: `Dialect.TimestampArg` normalises on both engines, and + `auditlog.TestStoreWritesTimestampsInUTC` asserts it against the stored column + rather than the reader. Reads are not normalised — SQLite returns the `Z` text + it stored, pgx materialises a `TIMESTAMPTZ` in the server's local zone — so + the same entry serialises as `…T12:30:00Z` or `…T14:30:00+02:00` depending on + the backend, with an offset that shifts with DST. Same instant, and any client + parsing RFC 3339 correctly is unaffected. Pre-existing: neither hand-written + reader normalised either. Normalising is one line in `Scan`, but it changes + the timestamp string in every PostgreSQL deployment's admin API responses, so + it was left as a separate decision rather than folded into a refactor. + +- **Cache-type vocabulary is spread over seven packages** (`admin`, `auditlog`, + `live`, `ratelimit`, `responsecache`, `server`, `usage`), with an import-cycle + risk in consolidating it. Best done once the usage reader has one owner. From 7127370768a5b9090b7c80ca4b5707ee167b1c5c Mon Sep 17 00:00:00 2001 From: "Jakub A. W" Date: Sat, 25 Jul 2026 17:11:56 +0200 Subject: [PATCH 10/12] docs(dev): point the metrics notes at where hooks are actually wired The implementation notes told contributors to look in cmd/gomodel/main.go for the SetHooks call, twice. It moved to run/providers.go (defaultProviderFactory). A link check would not catch it: the file still exists, it just no longer contains what the doc says it does. Co-Authored-By: Claude Opus 5 (1M context) --- docs/dev/prometheus-metrics.md | 4 ++-- 1 file changed, 2 insertions(+), 2 deletions(-) diff --git a/docs/dev/prometheus-metrics.md b/docs/dev/prometheus-metrics.md index 50b62a0e7..dc66ff731 100644 --- a/docs/dev/prometheus-metrics.md +++ b/docs/dev/prometheus-metrics.md @@ -13,7 +13,7 @@ provider implementations themselves are not aware of metrics. ## Wiring ```text -cmd/gomodel/main.go +run/providers.go (defaultProviderFactory) └─ if cfg.Metrics.Enabled: factory.SetHooks(observability.NewPrometheusHooks()) @@ -170,7 +170,7 @@ curl -s http://localhost:8080/metrics | grep gomodel_requests_total The hooks API is provider-agnostic. To add another backend, return a different `llmclient.Hooks` value from a constructor in -`internal/observability` and wire it in `cmd/gomodel/main.go`: +`internal/observability` and wire it in `run/providers.go`: ```go // example sketch — combineHooks does not exist today From 7bf96e4ef697c671db48d4bf8223dd455c2bbc9e Mon Sep 17 00:00:00 2001 From: "Jakub A. W" Date: Sat, 25 Jul 2026 17:14:21 +0200 Subject: [PATCH 11/12] docs(dev): drop two docs that had drifted past being useful api-examples.md cited five retired models, so a chunk of it failed on paste. tests/e2e/release-e2e-scenarios.md covers the same ground executably and is verified every release, so the hand-maintained copy could only fall further behind it. 2026-03-16_ARCHITECTURE_SNAPSHOT.md predated the MCP gateway, rate limiting, provider credentials and the storage refactor. The 2026-07-04 architecture review had already flagged both dated snapshots as looking authoritative while stale; this executes that for the one in docs/dev and records that its sibling in docs/ still has the problem. Co-Authored-By: Claude Opus 5 (1M context) --- docs/dev/2026-03-16_ARCHITECTURE_SNAPSHOT.md | 474 ------------------- docs/dev/2026-07-04_architecture-review.md | 6 +- docs/dev/api-examples.md | 403 ---------------- 3 files changed, 4 insertions(+), 879 deletions(-) delete mode 100644 docs/dev/2026-03-16_ARCHITECTURE_SNAPSHOT.md delete mode 100644 docs/dev/api-examples.md diff --git a/docs/dev/2026-03-16_ARCHITECTURE_SNAPSHOT.md b/docs/dev/2026-03-16_ARCHITECTURE_SNAPSHOT.md deleted file mode 100644 index db1491ee2..000000000 --- a/docs/dev/2026-03-16_ARCHITECTURE_SNAPSHOT.md +++ /dev/null @@ -1,474 +0,0 @@ -# GoModel Architecture Snapshot - -This document is a point-in-time architecture snapshot based on the code and runtime wiring present on March 16, 2026. - -It is not a statement of the intended architectural direction. It is a snapshot of how the system is structured as of that date. - -It focuses on: - -- what is instantiated at boot -- how requests move through the gateway -- what data objects are passed between layers -- where `RequestSnapshot`, `WhiteBoxPrompt`, and `Workflow` are created and consumed - -## 1. Boot And Dependency Wiring - -```mermaid -flowchart TB - Main["cmd/gomodel/main.go -- config.Load() -- register provider constructors -- optional Prometheus hooks -- app.New() -- app.Start()"] - - Cfg["config.LoadResult -- Config -- RawProviders"] - - Factory["providers.ProviderFactory -constructors: -- openai -- anthropic -- gemini -- groq -- xai -- ollama -also exposes passthrough enrichers"] - - App["internal/app.New(...)"] - - Main --> Cfg - Main --> Factory - Cfg --> App - Factory --> App - - subgraph ProviderSubsystem["Provider subsystem: providers.Init(...)"] - Resolve["resolveProviders(...) -merge YAML, env, resilience config"] - - ProviderInstances["Provider instances"] - - ModelCache["modelcache.Cache -local file or Redis"] - - Registry["providers.ModelRegistry -- configured providers -- in-memory model map -- provider type map -- cache-backed warm start -- background refresh"] - - ModelList["modeldata.Fetch(...) -optional model list URL -background metadata enrichment"] - - Router["providers.Router -implements: -- translated routing -- passthrough routing -- native batch routing -- native file routing"] - - Resolve --> ProviderInstances - Factory --> ProviderInstances - ProviderInstances -->|"RegisterProviderWithNameAndType"| Registry - ModelCache <-->|"LoadFromCache / SaveToCache"| Registry - ModelList -->|"SetModelList + EnrichModels"| Registry - Registry --> Router - end - - subgraph StorageSubsystem["Storage-backed subsystems"] - Audit["auditlog.New(...) --> Logger --> optional Storage"] - - Usage["usage.New(...) or -usage.NewWithSharedStorage(...) --> Logger --> optional Storage"] - - Batch["batch.New(...) or -batch.NewWithSharedStorage(...) --> Batch Store"] - - Aliases["aliases.New(...) or -aliases.NewWithSharedStorage(...) --> aliases.Service"] - - Audit -->|"shared storage when available"| Usage - Audit -->|"shared storage when available"| Batch - Audit -->|"shared storage when available"| Aliases - Usage -->|"fallback shared storage"| Batch - Usage -->|"fallback shared storage"| Aliases - Batch -->|"fallback shared storage"| Aliases - end - - Registry -->|"catalog for alias validation -and provider-type lookup"| Aliases - - subgraph PolicySubsystem["Optional policy layer"] - Guardrails["guardrails.Pipeline"] - RequestPatcher["guardrails.RequestPatcher -translated request patcher"] - BatchPreparers["ComposeBatchRequestPreparers(...) -- aliases batch rewrite -- optional guardrails batch rewrite"] - - Guardrails --> RequestPatcher - Guardrails --> BatchPreparers - Aliases --> BatchPreparers - end - - subgraph AdminSubsystem["Optional admin layer"] - AdminHandler["admin.Handler -usage, audit, models, aliases"] - Dashboard["dashboard.Handler"] - AdminHandler --> Dashboard - end - - Router -->|"core.RoutableProvider"| Server["server.New(...) -Echo + Handler"] - Audit -->|"AuditLogger"| Server - Usage -->|"UsageLogger"| Server - Registry -->|"PricingResolver"| Server - Aliases -->|"ModelResolver -+ ExposedModelLister"| Server - RequestPatcher --> Server - BatchPreparers --> Server - Factory -->|"PassthroughSemanticEnrichers"| Server - Batch -->|"BatchStore"| Server - AdminHandler --> Server - Dashboard --> Server - - Server --> HTTP["HTTP surface -- /v1/* -- /p/* -- /admin/* -- /admin/dashboard -- /metrics -- /health -- /swagger/*"] -``` - -## 2. Request-Scoped Data Objects - -| Object | Created by | Contains | Consumed by | -| ----------------- | ------------------------------------------------------------------------------- | --------------------------------------------------------------------------------------------------------------------------------------------------------------------- | ---------------------------------------------------------------------------------------------------------------------- | -| `RequestSnapshot` | `RequestSnapshotCapture()` | Immutable ingress transport data: method, path, route params, query params, headers, content type, captured body bytes, `BodyNotCaptured`, request id, trace metadata | `DeriveWhiteBoxPrompt`, audit logging, passthrough semantic enrichers, any later logic that needs raw ingress fidelity | -| `WhiteBoxPrompt` | `core.DeriveWhiteBoxPrompt(snapshot)` | Best-effort semantics: route type, operation type, route hints, stream intent, JSON parsed flag, cached typed request objects, cached route metadata | workflow resolution, canonical request decoding, passthrough/file/batch helpers | -| `Workflow` | `WorkflowResolutionWithResolver(...)` or `ensureTranslatedRequestWorkflow(...)` | Control-plane decision: endpoint descriptor, execution mode, capabilities, provider type, resolved model selector, passthrough info | response cache, translated handlers, passthrough handlers, audit-log enrichment | - -Important constraints: - -- `RequestSnapshot` is transport-first and must not be mutated. -- `WhiteBoxPrompt` is best-effort and may be partial or absent. -- `Workflow` is request-scoped control-plane state, not raw transport state. -- Streaming response frames are not part of `RequestSnapshot`. - -## 3. Model-Facing Request Lifecycle - -This pipeline applies to ingress-managed model routes such as: - -- `/v1/chat/completions` -- `/v1/responses` -- `/v1/embeddings` -- `/v1/batches*` -- `/v1/files*` -- `/p/:provider/*` - -It does not apply to `/health`, `/metrics`, `/swagger/*`, admin UI assets, or `GET /v1/models`. - -```mermaid -flowchart TB - Client["Client -HTTP request"] - - subgraph EchoPipeline["Echo middleware order"] - M0["RequestLogger -Recover -BodyLimit"] - - M1["Request ID middleware -ensure X-Request-ID -store request id in context -echo request id in response header"] - - M2["RequestSnapshotCapture"] - - M3["auditlog.Middleware -create LogEntry"] - - M4["AuthMiddleware -skips public paths"] - - M5["PassthroughSemanticEnrichment -provider-owned enrichers for /p/*"] - - M6["WorkflowResolutionWithResolver"] - - M7["ResponseCacheMiddleware -only POST: -- /v1/chat/completions -- /v1/responses -- /v1/embeddings"] - - H["Route handler"] - end - - Client -->|"HTTP request"| M0 --> M1 --> M2 --> M3 --> M4 --> M5 --> M6 --> M7 --> H - - M2 -->|"construct"| Snapshot["core.RequestSnapshot -method -path -route params -query params -headers -content type -captured body bytes -BodyNotCaptured -request id -trace metadata"] - - Snapshot -->|"core.DeriveWhiteBoxPrompt(snapshot)"| WBP["core.WhiteBoxPrompt -RouteType -OperationType -RouteHints: model, provider, endpoint -StreamRequested -JSONBodyParsed -cache: -- ChatRequest -- ResponsesRequest -- EmbeddingRequest -- BatchRequest -- BatchRouteInfo -- FileRouteInfo -- PassthroughRouteInfo"] - - Snapshot -.->|"stored in request context"| M3 - Snapshot -.->|"stored in request context"| M5 - WBP -.->|"stored in request context"| M5 - WBP -.->|"selector hints / cached canonical request"| M6 - - M5 -->|"enrich cached PassthroughRouteInfo -using RequestSnapshot + WhiteBoxPrompt"| WBP - - M6 -->|"build"| Plan["core.Workflow -RequestID -EndpointDescriptor -Mode: -- translated -- passthrough -- native_batch -- native_file -CapabilitySet -ProviderType -RequestModelResolution or PassthroughRouteInfo"] - - Plan -.->|"stored in request context"| M7 - Plan -.->|"used by audit-log enrichment"| M3 - Plan -.->|"consumed by handlers"| H - - M7 -->|"cache key: -path + raw body + plan.mode -+ plan.providerType + plan.resolvedModel"| CacheStore["Redis response cache -optional"] -``` - -## 4. Execution Branches After Routing - -```mermaid -flowchart TB - H["Resolved route handler"] - - H --> TStart["Translated endpoints -/v1/chat/completions -/v1/responses -/v1/embeddings"] - - H --> FStart["Native file endpoints -/v1/files*"] - - H --> BStart["Native batch endpoints -/v1/batches*"] - - H --> PStart["Provider passthrough -/p/:provider/*"] - - subgraph Translated["Translated OpenAI-compatible execution"] - T1["canonicalJSONRequestFromSemantics -RequestSnapshot body + WhiteBoxPrompt --> ChatRequest or ResponsesRequest or EmbeddingRequest"] - - T2["ensureTranslatedRequestWorkflow -selector hints from WhiteBoxPrompt --> RequestModelResolution -requested selector -> resolved selector"] - - T3["TranslatedRequestPatcher -optional guardrails patching -typed request -> patched typed request"] - - T4["providers.Router -resolveProvider(...) -forward*Request(...) -rewrite model to concrete upstream model -clear provider field before upstream call"] - - T5["Concrete provider adapter -OpenAI -Anthropic -Gemini -Groq -xAI -Ollama"] - - T6["Synchronous OpenAI-compatible JSON response -provider field stamped on response"] - - T7["Streaming response -io.ReadCloser"] - - T8["auditlog.WrapStreamForLogging"] - - T9["usage.WrapStreamForUsage"] - end - - TStart --> T1 --> T2 --> T3 --> T4 --> T5 - T5 -->|"non-stream"| T6 - T5 -->|"SSE stream"| T7 --> T8 --> T9 - - subgraph Files["Native file execution"] - F1["fileRouteInfoFromSemantics --> FileRouteInfo -provider, purpose, file id, limit, filename"] - - F2["nativeFileService -choose provider from: -- ?provider query -- single configured file provider -- multi-provider inventory scan"] - - F3["core.NativeFileRoutableProvider"] - - F4["Provider file API -create -list -get -delete -content"] - end - - FStart --> F1 --> F2 --> F3 --> F4 - - subgraph Batches["Native batch execution"] - B1["DecodeBatchRequest -+ BatchRouteInfo"] - - B2["determineBatchProviderType -from request endpoint, model, aliases"] - - B3["BatchRequestPreparer chain -- aliases batch rewrite -- optional guardrails batch rewrite"] - - B4["core.NativeBatchRoutableProvider"] - - B5["BatchStore persistence -gateway batch id -provider batch id -request endpoint hints -rewritten input file ids -request id"] - - B6["Batch results usage extraction -when results are fetched"] - end - - BStart --> B1 --> B2 --> B3 --> B4 --> B5 --> B6 - - subgraph Passthrough["Opaque provider passthrough execution"] - P1["passthroughExecutionTarget --> provider type --> normalized endpoint --> PassthroughRouteInfo"] - - P2["core.PassthroughRequest -Method -Endpoint -Body -Headers -request id propagated"] - - P3["providers.Router.resolvePassthroughProvider"] - - P4["Provider adapter.Passthrough(...)"] - - P5["Opaque upstream response -JSON or binary or SSE -upstream status code preserved"] - end - - PStart --> P1 --> P2 --> P3 --> P4 --> P5 - - T6 --> Client["Client response"] - T9 --> Client - F4 --> Client - B6 --> Client - P5 --> Client -``` - -## 5. What Is Passed Where - -Translated request path: - -1. HTTP ingress data becomes `RequestSnapshot`. -2. `RequestSnapshot` becomes `WhiteBoxPrompt`. -3. `WhiteBoxPrompt` plus request body decoding becomes a typed request such as `*core.ChatRequest`. -4. `WhiteBoxPrompt` selector hints plus alias resolution become `RequestModelResolution`. -5. `RequestModelResolution` becomes part of `Workflow`. -6. `Workflow` drives: - - response-cache keying - - provider selection - - audit-log enrichment - - usage attribution -7. `providers.Router` rewrites the outgoing request to the concrete upstream model and clears the provider field before invoking the provider adapter. -8. The provider adapter returns either: - - a typed OpenAI-compatible response object - - an `io.ReadCloser` SSE stream - -Passthrough request path: - -1. HTTP ingress data becomes `RequestSnapshot`. -2. `RequestSnapshot` becomes `WhiteBoxPrompt`. -3. Provider-owned passthrough enrichment can add `PassthroughRouteInfo` such as normalized endpoint, semantic operation, or model hints. -4. `Workflow` is created in `passthrough` mode with `ProviderType` and `PassthroughRouteInfo`. -5. The handler converts the live request into `*core.PassthroughRequest`: - - `Method` - - normalized `Endpoint` - - live `Body` - - forwarded `Headers` -6. The selected provider adapter executes the opaque upstream request and the gateway proxies the upstream response back to the client. - -Batch request path: - -1. The request body is decoded into `*core.BatchRequest`. -2. Batch provider type is determined from request semantics plus alias policy. -3. The batch preparer chain can rewrite input files or per-item request payloads. -4. The native batch router sends the prepared request to the selected provider. -5. The gateway persists its own batch id plus provider ids and request-endpoint hints in `BatchStore`. - -File request path: - -1. Transport and multipart/query/path data become `FileRouteInfo`. -2. `nativeFileService` resolves the provider from query parameters or provider inventory. -3. The native file router forwards to the selected provider file API. - -## 6. Side Paths Outside The Main Ingress Pipeline - -- `GET /v1/models`: `Handler.ListModels` calls `providers.Router.ListModels()` and then merges alias-exposed models from `aliases.Service`. -- `/admin/*`: reads usage and audit storage, model registry, and alias service through `admin.Handler`. -- `/admin/dashboard`: dashboard UI handler over the same underlying readers. -- `/metrics`: Prometheus endpoint when enabled. -- `/health`: simple health check. -- `/swagger/*`: Swagger UI when enabled. diff --git a/docs/dev/2026-07-04_architecture-review.md b/docs/dev/2026-07-04_architecture-review.md index f619f845d..f10b7cfc6 100644 --- a/docs/dev/2026-07-04_architecture-review.md +++ b/docs/dev/2026-07-04_architecture-review.md @@ -487,8 +487,10 @@ guardrails error). (`make swagger && git diff --exit-code`) so PRs stop hand-carrying them. - **[REMOVE]** `gateway/refactor_findings_test.go` — legitimate regression tests named after the review session that produced them; rename to describe behavior. -- **[SMELL]** Dated snapshot docs (`docs/dev/2026-03-16_ARCHITECTURE_SNAPSHOT.md`, - `docs/2026-04-09_CODEBASE_SNAPSHOT.md`) look authoritative while 3+ months stale. +- **[SMELL]** Dated snapshot docs look authoritative while months stale. + `docs/dev/2026-03-16_ARCHITECTURE_SNAPSHOT.md` was deleted on 2026-07-25 for + this reason; `docs/2026-04-09_CODEBASE_SNAPSHOT.md` (1,368 lines) remains and + has the same problem. - **[GOOD]** Test culture: test LOC ≈ source LOC in most packages (`internal/server`: 15.8k test vs 8k source), plus e2e/integration/contract suites and dashboard JS tests. `internal/streaming`'s cross-chunk boundary logic diff --git a/docs/dev/api-examples.md b/docs/dev/api-examples.md deleted file mode 100644 index 29fd89dce..000000000 --- a/docs/dev/api-examples.md +++ /dev/null @@ -1,403 +0,0 @@ -# API Examples - -Reference curl examples for the OpenAI-compatible endpoints exposed by GoModel. -The user-facing quickstart lives at -[`docs/getting-started/quickstart.mdx`](../getting-started/quickstart.mdx); this -file is a longer collection useful when manually exercising providers. - -All examples assume: - -- GoModel is reachable at `http://localhost:8080` -- The relevant provider credential is configured server-side -- If `GOMODEL_MASTER_KEY` is set, add `-H "Authorization: Bearer $GOMODEL_MASTER_KEY"` - to every request - -Streaming responses are SSE: chunks are flushed incrementally and the stream -terminates with `data: [DONE]`. - -## OpenAI - -### Basic Chat Completion - -```bash -curl http://localhost:8080/v1/chat/completions \ - -H "Content-Type: application/json" \ - -d '{ - "model": "gpt-4o-mini", - "messages": [ - {"role": "user", "content": "What is the capital of France?"} - ] - }' -``` - -### Chat Completion with Parameters - -```bash -curl http://localhost:8080/v1/chat/completions \ - -H "Content-Type: application/json" \ - -d '{ - "model": "gpt-4o", - "messages": [ - {"role": "system", "content": "You are a helpful assistant."}, - {"role": "user", "content": "Write a haiku about programming."} - ], - "temperature": 0.7, - "max_tokens": 100 - }' -``` - -### Chat Completion with Function Calling - -```bash -curl http://localhost:8080/v1/chat/completions \ - -H "Content-Type: application/json" \ - -d '{ - "model": "gpt-4o-mini", - "messages": [ - {"role": "user", "content": "What is the weather in Warsaw?"} - ], - "tools": [ - { - "type": "function", - "function": { - "name": "lookup_weather", - "description": "Get the weather for a city.", - "parameters": { - "type": "object", - "properties": { - "city": {"type": "string"} - }, - "required": ["city"] - } - } - } - ], - "tool_choice": { - "type": "function", - "function": {"name": "lookup_weather"} - } - }' -``` - -### Streaming Response - -```bash -curl http://localhost:8080/v1/chat/completions \ - -H "Content-Type: application/json" \ - -N \ - -d '{ - "model": "gpt-4o-mini", - "messages": [ - {"role": "user", "content": "Tell me a short story."} - ], - "stream": true - }' -``` - -## Anthropic - -### Basic Chat Completion - -```bash -curl http://localhost:8080/v1/chat/completions \ - -H "Content-Type: application/json" \ - -d '{ - "model": "claude-3-5-sonnet-20241022", - "messages": [ - {"role": "user", "content": "What is the capital of France?"} - ] - }' -``` - -### Chat Completion with System Message - -```bash -curl http://localhost:8080/v1/chat/completions \ - -H "Content-Type: application/json" \ - -d '{ - "model": "claude-3-5-sonnet-20241022", - "messages": [ - {"role": "system", "content": "You are a creative writing assistant."}, - {"role": "user", "content": "Write a haiku about the ocean."} - ], - "temperature": 0.8, - "max_tokens": 200 - }' -``` - -### Streaming Response - -```bash -curl http://localhost:8080/v1/chat/completions \ - -H "Content-Type: application/json" \ - -N \ - -d '{ - "model": "claude-3-5-haiku-20241022", - "messages": [ - {"role": "user", "content": "Explain quantum computing in simple terms."} - ], - "stream": true - }' -``` - -### Using Claude Opus - -```bash -curl http://localhost:8080/v1/chat/completions \ - -H "Content-Type: application/json" \ - -d '{ - "model": "claude-3-opus-20240229", - "messages": [ - {"role": "user", "content": "Analyze the pros and cons of renewable energy."} - ], - "max_tokens": 1000 - }' -``` - -## Google Gemini - -### Basic Chat Completion - -```bash -curl http://localhost:8080/v1/chat/completions \ - -H "Content-Type: application/json" \ - -d '{ - "model": "gemini-3-flash-preview", - "messages": [ - {"role": "user", "content": "What is the capital of France?"} - ] - }' -``` - -### Chat Completion with Parameters - -```bash -curl http://localhost:8080/v1/chat/completions \ - -H "Content-Type: application/json" \ - -d '{ - "model": "gemini-1.5-pro", - "messages": [ - {"role": "system", "content": "You are a knowledgeable science educator."}, - {"role": "user", "content": "Explain photosynthesis in simple terms."} - ], - "temperature": 0.7, - "max_tokens": 500 - }' -``` - -### Streaming Response - -```bash -curl http://localhost:8080/v1/chat/completions \ - -H "Content-Type: application/json" \ - -N \ - -d '{ - "model": "gemini-2.0-flash", - "messages": [ - {"role": "user", "content": "Write a short poem about AI."} - ], - "stream": true - }' -``` - -## xAI (Responses API) - -### Basic Responses Request - -```bash -curl http://localhost:8080/v1/responses \ - -H "Content-Type: application/json" \ - -d '{ - "model": "grok-4-1-fast-non-reasoning", - "input": "What is the capital of France?" - }' -``` - -### Responses Request with Instructions - -```bash -curl http://localhost:8080/v1/responses \ - -H "Content-Type: application/json" \ - -d '{ - "model": "grok-4-1-fast-non-reasoning", - "input": "Write a haiku about programming.", - "instructions": "You are a creative AI assistant who specializes in writing poetry.", - "temperature": 0.8, - "max_output_tokens": 200 - }' -``` - -### Streaming Responses - -```bash -curl http://localhost:8080/v1/responses \ - -H "Content-Type: application/json" \ - -N \ - -d '{ - "model": "grok-4-1-fast-non-reasoning", - "input": "Tell me a short story about AI.", - "stream": true - }' -``` - -## Embeddings - -Supported by: OpenAI, Gemini, Groq, Z.ai, xAI, Ollama. Anthropic does not -support embeddings natively. - -### Basic Embedding - -```bash -curl http://localhost:8080/v1/embeddings \ - -H "Content-Type: application/json" \ - -d '{ - "model": "text-embedding-3-small", - "input": "The quick brown fox jumps over the lazy dog." - }' -``` - -### Batch Embedding - -```bash -curl http://localhost:8080/v1/embeddings \ - -H "Content-Type: application/json" \ - -d '{ - "model": "text-embedding-3-small", - "input": ["First sentence", "Second sentence", "Third sentence"] - }' -``` - -### Custom Dimensions - -```bash -curl http://localhost:8080/v1/embeddings \ - -H "Content-Type: application/json" \ - -d '{ - "model": "text-embedding-3-large", - "input": "Hello world", - "dimensions": 512 - }' -``` - -## List Available Models - -```bash -curl http://localhost:8080/v1/models -``` - -Example response: - -```json -{ - "object": "list", - "data": [ - { - "id": "gpt-4o", - "object": "model", - "owned_by": "openai", - "created": 1234567890 - }, - { - "id": "claude-3-5-sonnet-20241022", - "object": "model", - "owned_by": "anthropic", - "created": 1234567890 - } - ] -} -``` - -## Health Check - -```bash -curl http://localhost:8080/health -gomodel --health -gomodel --version -``` - -## Client Library Examples - -GoModel exposes an OpenAI-compatible API, so the official OpenAI SDKs work -unchanged — just point them at the gateway. The model name selects the -upstream provider; routing is automatic. - -### Python - -```python -import os - -from openai import OpenAI - -client = OpenAI( - base_url="http://localhost:8080/v1", - api_key=os.getenv("GOMODEL_MASTER_KEY") or "not-needed", -) - -# Use OpenAI models -response = client.chat.completions.create( - model="gpt-4o-mini", - messages=[{"role": "user", "content": "Hello!"}] -) -print(response.choices[0].message.content) - -# Or use Anthropic models with the same interface -response = client.chat.completions.create( - model="claude-3-5-sonnet-20241022", - messages=[{"role": "user", "content": "Hello!"}] -) -print(response.choices[0].message.content) - -# Streaming works too -stream = client.chat.completions.create( - model="claude-3-5-haiku-20241022", - messages=[{"role": "user", "content": "Tell me a story"}], - stream=True -) -for chunk in stream: - if chunk.choices[0].delta.content: - print(chunk.choices[0].delta.content, end="") - -# Embeddings -embedding = client.embeddings.create( - model="text-embedding-3-small", - input="Hello world" -) -print(embedding.data[0].embedding[:5]) # first 5 dimensions -``` - -### Node.js - -```javascript -import OpenAI from "openai"; - -const client = new OpenAI({ - baseURL: "http://localhost:8080/v1", - apiKey: process.env.GOMODEL_MASTER_KEY || "not-needed", -}); - -// Use any supported model - routing is automatic -const response = await client.chat.completions.create({ - model: "gemini-2.0-flash", - messages: [{ role: "user", content: "Hello!" }], -}); -console.log(response.choices[0].message.content); - -// Streaming -const stream = await client.chat.completions.create({ - model: "claude-3-5-haiku-20241022", - messages: [{ role: "user", content: "Tell me a story" }], - stream: true, -}); -for await (const chunk of stream) { - if (chunk.choices[0]?.delta?.content) { - process.stdout.write(chunk.choices[0].delta.content); - } -} - -// Embeddings -const embedding = await client.embeddings.create({ - model: "text-embedding-3-small", - input: "Hello world", -}); -console.log(embedding.data[0].embedding.slice(0, 5)); // first 5 dimensions -``` From 6bbce9e9f25d395170441e5e82235dbe7019324c Mon Sep 17 00:00:00 2001 From: "Jakub A. W" Date: Sat, 25 Jul 2026 17:17:13 +0200 Subject: [PATCH 12/12] test(auditlog): make the UTC assertion independent of the server's time zone MIME-Version: 1.0 Content-Type: text/plain; charset=UTF-8 Content-Transfer-Encoding: 8bit The check read timestamp::text, and PostgreSQL renders TIMESTAMPTZ in the *session* time zone — so it asserted the UTC wall clock only because this container happens to default to UTC. Against a server on Europe/Warsaw it failed on perfectly correct data: stored timestamp = "2026-07-25 14:30:00.123456+02", want the 12:30 UTC wall clock Both verified: the previous assertion fails under PGTZ=Europe/Warsaw, the projection through AT TIME ZONE 'UTC' passes under both. Also covers audit_log_attempts.started_at, which was only checked through the hydrated instant, and makes the cases table-driven across UTC, a summer +02:00 offset and a winter +01:00 one, so the contract is exercised either side of a DST change rather than at a single offset. Co-Authored-By: Claude Opus 5 (1M context) --- internal/auditlog/timestamp_utc_test.go | 198 ++++++++++++++++-------- 1 file changed, 133 insertions(+), 65 deletions(-) diff --git a/internal/auditlog/timestamp_utc_test.go b/internal/auditlog/timestamp_utc_test.go index 1bef47414..9543bd4ce 100644 --- a/internal/auditlog/timestamp_utc_test.go +++ b/internal/auditlog/timestamp_utc_test.go @@ -10,75 +10,143 @@ import ( "github.com/enterpilot/gomodel/internal/storage/sqlx/sqlxtest" ) -// TestStoreWritesTimestampsInUTC pins the invariant the whole audit schema -// rests on: whatever zone a caller hands in, the column holds UTC. +// TestStoreWritesTimestampsInUTC pins the invariant the audit schema rests on: +// whatever zone a caller hands in, the column holds UTC. // -// It matters because sqlx.Timestamp deliberately does *not* normalise on read -// — each driver's own zone is what callers already render — so the guarantee -// has to be established on the way in. If a write ever bypassed -// Dialect.TimestampArg, SQLite would store a local-offset string that sorts -// wrongly against every other row, and the date-range filters would quietly -// return the wrong day. +// It matters because sqlx.Timestamp deliberately does *not* normalise on read — +// each driver's own zone is what callers already render — so the guarantee has +// to be established on the way in. +// +// The stakes differ per engine, which is why both are asserted. PostgreSQL's +// TIMESTAMPTZ stores an absolute instant, so a non-UTC time.Time still lands +// correctly and the check mostly guards against the column type changing. +// SQLite formats the value to text: dropping the UTC conversion there would +// write "2026-07-25T14:30:00+02:00", which sorts wrongly against every "…Z" +// row and would quietly break the date-range filters, since those compare the +// column as a string. func TestStoreWritesTimestampsInUTC(t *testing.T) { - sqlxtest.Run(t, func(t *testing.T, db sqlx.DB) { - warsaw, err := time.LoadLocation("Europe/Warsaw") - if err != nil { - t.Fatalf("load location: %v", err) - } - // 14:30+02:00 is 12:30 UTC. A local-zone write would store 14:30. - written := time.Date(2026, 7, 25, 14, 30, 0, 123456000, warsaw) + warsaw, err := time.LoadLocation("Europe/Warsaw") + if err != nil { + t.Fatalf("load location: %v", err) + } + + tests := []struct { + name string + // written is the same instant expressed in different zones, except for + // the winter case, which exists to cover the other side of a DST change. + written time.Time + wantUTCClock string + notLocalT string + }{ + { + name: "already UTC", + written: time.Date(2026, 7, 25, 12, 30, 0, 123456000, time.UTC), + wantUTCClock: "12:30:00", + }, + { + name: "summer offset +02:00", + written: time.Date(2026, 7, 25, 14, 30, 0, 123456000, warsaw), + wantUTCClock: "12:30:00", + notLocalT: "14:30:00", + }, + { + name: "winter offset +01:00", + written: time.Date(2026, 1, 15, 13, 30, 0, 123456000, warsaw), + wantUTCClock: "12:30:00", + notLocalT: "13:30:00", + }, + } - store, err := NewSQLStore(context.Background(), db, 0) - if err != nil { - t.Fatalf("NewSQLStore: %v", err) - } - defer store.Close() + for _, tc := range tests { + t.Run(tc.name, func(t *testing.T) { + sqlxtest.Run(t, func(t *testing.T, db sqlx.DB) { + store, err := NewSQLStore(context.Background(), db, 0) + if err != nil { + t.Fatalf("NewSQLStore: %v", err) + } + defer store.Close() - ctx := context.Background() - if err := store.WriteBatch(ctx, []*LogEntry{{ - ID: "utc-entry", Timestamp: written, Provider: "openai", StatusCode: 200, - Data: &LogData{Attempts: []AttemptSnapshot{{Seq: 1, Kind: "primary", StartedAt: written}}}, - }}); err != nil { - t.Fatalf("WriteBatch: %v", err) - } + ctx := context.Background() + if err := store.WriteBatch(ctx, []*LogEntry{{ + ID: "utc-entry", Timestamp: tc.written, Provider: "openai", StatusCode: 200, + Data: &LogData{Attempts: []AttemptSnapshot{ + {Seq: 1, Kind: "primary", StartedAt: tc.written}, + }}, + }}); err != nil { + t.Fatalf("WriteBatch: %v", err) + } - // The column itself, not the reader's interpretation of it. - timestampExpr := "timestamp" - if db.Dialect() == sqlx.PostgreSQL { - timestampExpr = "timestamp::text" - } - var stored string - if err := db.QueryRow(ctx, - "SELECT "+timestampExpr+" FROM audit_logs WHERE id = ?", "utc-entry").Scan(&stored); err != nil { - t.Fatalf("read stored timestamp: %v", err) - } - if !strings.Contains(stored, "12:30:00") { - t.Errorf("stored timestamp = %q, want the 12:30 UTC wall clock, not the caller's 14:30", stored) - } - // SQLite writes RFC3339 text ending in Z; PostgreSQL renders a +00 offset. - if !strings.HasSuffix(stored, "Z") && !strings.Contains(stored, "+00") { - t.Errorf("stored timestamp = %q, want a UTC zone marker", stored) - } + // Both columns, read as stored rather than as the reader + // interprets them. + var entryStored, attemptStored string + if err := db.QueryRow(ctx, + "SELECT "+utcProjection(db, "timestamp")+" FROM audit_logs WHERE id = ?", + "utc-entry").Scan(&entryStored); err != nil { + t.Fatalf("read stored timestamp: %v", err) + } + if err := db.QueryRow(ctx, + "SELECT "+utcProjection(db, "started_at")+" FROM audit_log_attempts WHERE audit_log_id = ?", + "utc-entry").Scan(&attemptStored); err != nil { + t.Fatalf("read stored started_at: %v", err) + } - // And the instant survives the round trip. PostgreSQL's TIMESTAMPTZ - // holds microseconds, so the fixture stays inside that precision. - reader, err := NewSQLReader(db) - if err != nil { - t.Fatalf("NewSQLReader: %v", err) - } - entry, err := reader.GetLogByID(ctx, "utc-entry") - if err != nil { - t.Fatalf("GetLogByID: %v", err) - } - if !entry.Timestamp.Equal(written) { - t.Errorf("round-tripped timestamp = %s, want the same instant as %s", entry.Timestamp, written) - } - if entry.Data == nil || len(entry.Data.Attempts) != 1 { - t.Fatalf("attempts = %+v, want one hydrated attempt", entry.Data) - } - if !entry.Data.Attempts[0].StartedAt.Equal(written) { - t.Errorf("attempt started_at = %s, want the same instant as %s", - entry.Data.Attempts[0].StartedAt, written) - } - }) + for column, stored := range map[string]string{ + "audit_logs.timestamp": entryStored, + "audit_log_attempts.started_at": attemptStored, + } { + if !strings.Contains(stored, tc.wantUTCClock) { + t.Errorf("%s = %q, want the %s UTC wall clock", column, stored, tc.wantUTCClock) + } + if tc.notLocalT != "" && strings.Contains(stored, tc.notLocalT) { + t.Errorf("%s = %q, holds the caller's local wall clock %s", column, stored, tc.notLocalT) + } + // SQLite's text form must also carry the zone marker, or it + // sorts wrongly against rows written in another zone. + if db.Dialect() == sqlx.SQLite && !strings.HasSuffix(stored, "Z") { + t.Errorf("%s = %q, want RFC3339 UTC text ending in Z", column, stored) + } + } + + // And the instant survives the round trip. PostgreSQL's + // TIMESTAMPTZ holds microseconds, so the fixture stays inside + // that precision. + reader, err := NewSQLReader(db) + if err != nil { + t.Fatalf("NewSQLReader: %v", err) + } + entry, err := reader.GetLogByID(ctx, "utc-entry") + if err != nil { + t.Fatalf("GetLogByID: %v", err) + } + if !entry.Timestamp.Equal(tc.written) { + t.Errorf("round-tripped timestamp = %s, want the same instant as %s", + entry.Timestamp, tc.written) + } + if entry.Data == nil || len(entry.Data.Attempts) != 1 { + t.Fatalf("attempts = %+v, want one hydrated attempt", entry.Data) + } + if !entry.Data.Attempts[0].StartedAt.Equal(tc.written) { + t.Errorf("attempt started_at = %s, want the same instant as %s", + entry.Data.Attempts[0].StartedAt, tc.written) + } + }) + }) + } +} + +// utcProjection renders a timestamp column as its UTC wall clock. +// +// PostgreSQL formats TIMESTAMPTZ in the *session* time zone, so a plain ::text +// on a server that is not on UTC returns the local rendering of a correctly +// stored instant — which would fail this test on good data. SQLite already +// holds the UTC text that was written. +// +// The column name is a literal chosen here, never caller input, so building the +// statement around it is not a parameterisation this could use anyway: a column +// expression cannot be a bind parameter. +func utcProjection(db sqlx.DB, column string) string { + if db.Dialect() == sqlx.PostgreSQL { + return "(" + column + " AT TIME ZONE 'UTC')::text" + } + return column }