diff --git a/internal/admin/handler.go b/internal/admin/handler.go index afab61208..d1fadfd55 100644 --- a/internal/admin/handler.go +++ b/internal/admin/handler.go @@ -557,7 +557,7 @@ func handleError(c *echo.Context, err error) error { } fallback := &core.GatewayError{ - Type: "internal_error", + Type: core.ErrorTypeInternal, Message: "an unexpected error occurred", StatusCode: http.StatusInternalServerError, Err: err, diff --git a/internal/auditlog/enrich.go b/internal/auditlog/enrich.go index 2c8b87061..bfe532431 100644 --- a/internal/auditlog/enrich.go +++ b/internal/auditlog/enrich.go @@ -411,6 +411,14 @@ func EnrichEntryWithError(c *echo.Context, errorType, errorMessage string, error publishLiveAuditUpdate(c, entry) } +// HasRecordedError reports whether the request's audit entry already carries an +// error. Late failure paths consult it so a generic follow-up error cannot +// replace the original cause on the audit row. +func HasRecordedError(c *echo.Context) bool { + entry := entryFromContext(c) + return entry != nil && entry.ErrorType != "" +} + // EnrichEntryWithGatewayError records a gateway error on the log entry: // type, message and code as EnrichEntryWithError does, plus the upstream // provider the error originated from (empty for gateway-raised errors). diff --git a/internal/auditlog/enrich_test.go b/internal/auditlog/enrich_test.go index 304700db1..d642ca469 100644 --- a/internal/auditlog/enrich_test.go +++ b/internal/auditlog/enrich_test.go @@ -130,3 +130,30 @@ func TestEnrichEntryWithGatewayError(t *testing.T) { }) } } + +func TestHasRecordedError(t *testing.T) { + tests := []struct { + name string + entry *LogEntry + want bool + }{ + {name: "no entry on the context", entry: nil, want: false}, + {name: "entry without an error", entry: &LogEntry{Data: &LogData{}}, want: false}, + {name: "entry carrying an error", entry: &LogEntry{ErrorType: "not_found_error", Data: &LogData{}}, want: true}, + } + for _, tc := range tests { + t.Run(tc.name, func(t *testing.T) { + e := echo.New() + c := e.NewContext(httptest.NewRequest(http.MethodPost, "/v1/chat/completions", nil), httptest.NewRecorder()) + if tc.entry != nil { + c.Set(string(LogEntryKey), tc.entry) + } + if got := HasRecordedError(c); got != tc.want { + t.Fatalf("HasRecordedError() = %v, want %v", got, tc.want) + } + }) + } + if HasRecordedError(nil) { + t.Fatal("HasRecordedError(nil) = true, want false") + } +} diff --git a/internal/authkeys/store_sql.go b/internal/authkeys/store_sql.go index 17a733b0c..028050fd7 100644 --- a/internal/authkeys/store_sql.go +++ b/internal/authkeys/store_sql.go @@ -211,7 +211,7 @@ func scanSQLAuthKey(scanner authKeyScanner) (AuthKey, error) { } key.ExpiresAt = sqlutil.TimeFromUnixPtr(expiresAt) key.DeactivatedAt = sqlutil.TimeFromUnixPtr(deactivatedAt) - key.CreatedAt = time.Unix(createdAt, 0).UTC() - key.UpdatedAt = time.Unix(updatedAt, 0).UTC() + key.CreatedAt = sqlutil.TimeFromUnix(createdAt) + key.UpdatedAt = sqlutil.TimeFromUnix(updatedAt) return key, nil } diff --git a/internal/budget/store_sql.go b/internal/budget/store_sql.go index 532f7cc64..4d99bd522 100644 --- a/internal/budget/store_sql.go +++ b/internal/budget/store_sql.go @@ -410,7 +410,7 @@ func scanSQLBudget(scanner sqlx.Row) (Budget, error) { return Budget{}, fmt.Errorf("scan budget: %w", err) } budget.LastResetAt = sqlutil.TimeFromUnixPtr(lastResetAt) - budget.CreatedAt = time.Unix(createdAt, 0).UTC() - budget.UpdatedAt = time.Unix(updatedAt, 0).UTC() + budget.CreatedAt = sqlutil.TimeFromUnix(createdAt) + budget.UpdatedAt = sqlutil.TimeFromUnix(updatedAt) return budget, nil } diff --git a/internal/core/errors.go b/internal/core/errors.go index aed1ab43b..ea4c8aba2 100644 --- a/internal/core/errors.go +++ b/internal/core/errors.go @@ -30,6 +30,9 @@ const ( // ErrorTypePermission indicates an authenticated caller lacks the // permission for the operation (403) ErrorTypePermission ErrorType = "permission_error" + // ErrorTypeInternal indicates a failure inside the gateway itself (500), + // as opposed to one an upstream provider reported + ErrorTypeInternal ErrorType = "internal_error" ) // GatewayError is the base error type for all gateway errors diff --git a/internal/guardrails/store_sql.go b/internal/guardrails/store_sql.go index 6db18415d..79ebffb67 100644 --- a/internal/guardrails/store_sql.go +++ b/internal/guardrails/store_sql.go @@ -183,7 +183,7 @@ func scanSQLDefinition(scanner definitionScanner) (Definition, error) { } definition.UserPath = sqlutil.DerefTrimmed(userPath) definition.Config = configJSON - definition.CreatedAt = time.Unix(createdAtUnix, 0).UTC() - definition.UpdatedAt = time.Unix(updatedAtUnix, 0).UTC() + definition.CreatedAt = sqlutil.TimeFromUnix(createdAtUnix) + definition.UpdatedAt = sqlutil.TimeFromUnix(updatedAtUnix) return definition, nil } diff --git a/internal/mcpgateway/store_sql.go b/internal/mcpgateway/store_sql.go index a642ef3d3..cc1190439 100644 --- a/internal/mcpgateway/store_sql.go +++ b/internal/mcpgateway/store_sql.go @@ -5,8 +5,8 @@ import ( "errors" "fmt" "strings" - "time" + "github.com/enterpilot/gomodel/internal/storage/sqlutil" "github.com/enterpilot/gomodel/internal/storage/sqlx" ) @@ -210,7 +210,7 @@ func scanSQLMCPServer(scanner sqlx.Row) (ManagedServer, error) { if server.DisplayName == "" { server.DisplayName = server.Name } - server.CreatedAt = time.Unix(createdAt, 0).UTC() - server.UpdatedAt = time.Unix(updatedAt, 0).UTC() + server.CreatedAt = sqlutil.TimeFromUnix(createdAt) + server.UpdatedAt = sqlutil.TimeFromUnix(updatedAt) return server, nil } diff --git a/internal/pricingoverrides/store_sql.go b/internal/pricingoverrides/store_sql.go index ec852392c..78225a578 100644 --- a/internal/pricingoverrides/store_sql.go +++ b/internal/pricingoverrides/store_sql.go @@ -4,10 +4,10 @@ import ( "context" "fmt" "strings" - "time" "github.com/goccy/go-json" + "github.com/enterpilot/gomodel/internal/storage/sqlutil" "github.com/enterpilot/gomodel/internal/storage/sqlx" ) @@ -124,7 +124,7 @@ func scanSQLOverride(rows sqlx.Rows) (Override, error) { if err := json.Unmarshal(pricing, &override.Pricing); err != nil { return Override{}, fmt.Errorf("decode pricing: %w", err) } - override.CreatedAt = time.Unix(createdAt, 0).UTC() - override.UpdatedAt = time.Unix(updatedAt, 0).UTC() + override.CreatedAt = sqlutil.TimeFromUnix(createdAt) + override.UpdatedAt = sqlutil.TimeFromUnix(updatedAt) return override, nil } diff --git a/internal/providers/credentials_store_sql.go b/internal/providers/credentials_store_sql.go index 90e92106a..1263dcabd 100644 --- a/internal/providers/credentials_store_sql.go +++ b/internal/providers/credentials_store_sql.go @@ -4,8 +4,8 @@ import ( "context" "errors" "fmt" - "time" + "github.com/enterpilot/gomodel/internal/storage/sqlutil" "github.com/enterpilot/gomodel/internal/storage/sqlx" ) @@ -205,7 +205,7 @@ func scanSQLCredential(scanner sqlx.Row) (ManagedProviderCredential, error) { if cred.Models, err = decodeCredentialList(models); err != nil { return ManagedProviderCredential{}, err } - cred.CreatedAt = time.Unix(createdAt, 0).UTC() - cred.UpdatedAt = time.Unix(updatedAt, 0).UTC() + cred.CreatedAt = sqlutil.TimeFromUnix(createdAt) + cred.UpdatedAt = sqlutil.TimeFromUnix(updatedAt) return cred, nil } diff --git a/internal/ratelimit/store_sql.go b/internal/ratelimit/store_sql.go index 51f26e68f..5276ecf48 100644 --- a/internal/ratelimit/store_sql.go +++ b/internal/ratelimit/store_sql.go @@ -7,6 +7,7 @@ import ( "strings" "time" + "github.com/enterpilot/gomodel/internal/storage/sqlutil" "github.com/enterpilot/gomodel/internal/storage/sqlx" ) @@ -317,8 +318,8 @@ func scanSQLRule(scanner sqlx.Row) (Rule, error) { } rule.MaxRequests = maxRequests rule.MaxTokens = maxTokens - rule.CreatedAt = time.Unix(createdAt, 0).UTC() - rule.UpdatedAt = time.Unix(updatedAt, 0).UTC() + rule.CreatedAt = sqlutil.TimeFromUnix(createdAt) + rule.UpdatedAt = sqlutil.TimeFromUnix(updatedAt) return rule, nil } diff --git a/internal/server/error_support.go b/internal/server/error_support.go index 659316123..81a4e5c8b 100644 --- a/internal/server/error_support.go +++ b/internal/server/error_support.go @@ -6,6 +6,7 @@ import ( "net/http" "github.com/labstack/echo/v5" + "github.com/labstack/echo/v5/middleware" "github.com/enterpilot/gomodel/internal/anthropicapi" "github.com/enterpilot/gomodel/internal/auditlog" @@ -37,6 +38,85 @@ func writeGatewayError(c *echo.Context, gatewayErr *core.GatewayError) error { return c.JSON(gatewayErr.HTTPStatusCode(), gatewayErr.ToJSON()) } +// gatewayErrorHandler renders every error that escapes a handler — a recovered +// panic, a response body the JSON serializer could not encode, or an +// echo.HTTPError raised by middleware — in the caller's wire dialect, and logs +// it. Echo's default handler answers with a bare +// {"message": "Internal Server Error"} and logs nothing at all, so such a +// failure reaches the operator as a 500 naming neither the endpoint nor the +// cause, and reaches the client in an envelope no OpenAI SDK can parse. +func gatewayErrorHandler(c *echo.Context, err error) { + if err == nil { + return + } + gatewayErr := escapedGatewayError(err) + // Log before checking whether the response can still be changed: a panic + // after the first streamed chunk must still reach the operator. + logHandledError(c, gatewayErr) + // Finalize as handleError does, so an error that never passed through it — + // a panic, a rate-limit error returned rather than rendered — still lands + // on the audit row and keeps headers such as Retry-After. The audit half is + // skipped once an error is recorded: handleError returns its own response + // write failures here, and re-enriching would replace the real cause with + // this generic one. + if !auditlog.HasRecordedError(c) { + enrichAuditEntryWithProviderAttempts(c) + auditlog.EnrichEntryWithGatewayError(c, gatewayErr) + } + applyErrorResponseHeaders(c, err) + + // Once the status line and body are on the wire nothing can be changed; + // the response stands as the handler left it. + if response, unwrapErr := echo.UnwrapResponse(c.Response()); unwrapErr == nil && response.Committed { + return + } + if writeErr := writeGatewayError(c, gatewayErr); writeErr != nil { + slog.Error("failed to send error response", "error", writeErr) + } +} + +// escapedGatewayError classifies an error that reached the central handler. A +// gateway error is already shaped; an echo.HTTPError keeps its status; anything +// else is a failure inside the gateway and stays opaque to the client. +func escapedGatewayError(err error) *core.GatewayError { + if gatewayErr, ok := errors.AsType[*core.GatewayError](err); ok { + return gatewayErr + } + + // Echo carries the intended status on the error itself — BodyLimit's 413, + // the router's 405, any middleware's echo.NewHTTPError. An error without + // one is a failure inside the gateway. + status := echo.StatusCode(err) + if status <= 0 { + status = http.StatusInternalServerError + } + if status < http.StatusInternalServerError { + return core.NewInvalidRequestErrorWithStatus(status, echoErrorMessage(err, status), err) + } + // A 5xx message describes what broke inside the gateway and can quote an + // internal error verbatim (echo's own Decompress middleware answers with + // err.Error()), so the client gets the same opaque text every other + // gateway 500 uses. The cause travels in Err, which only the logs read. + return &core.GatewayError{ + Type: core.ErrorTypeInternal, + Message: "an unexpected error occurred", + StatusCode: status, + Err: err, + } +} + +// echoErrorMessage is the client-facing text of an echo error: its own message +// when it carries one, else the status text. +func echoErrorMessage(err error, status int) string { + if httpErr, ok := errors.AsType[*echo.HTTPError](err); ok && httpErr.Message != "" { + return httpErr.Message + } + if text := http.StatusText(status); text != "" { + return text + } + return "request failed" +} + // handleRouteNotFound renders unknown-route 404s in the caller's wire dialect // so SDK clients raise clean typed errors instead of parsing echo's default // {"message": "Not Found"} body. Anthropic SDK clients are recognized by the @@ -103,7 +183,12 @@ func logHandledError(c *echo.Context, gatewayErr *core.GatewayError) { if gatewayErr.Code != nil { attrs = append(attrs, "code", *gatewayErr.Code) } - if gatewayErr.Err != nil { + // A recovered panic arrives as echo's PanicStackError, whose message is + // the panic value followed by the whole stack; split them so the message + // stays readable and the stack lands in its own attribute. + if panicErr, ok := errors.AsType[*middleware.PanicStackError](gatewayErr.Err); ok { + attrs = append(attrs, "panic", panicErr.Err, "stack", string(panicErr.Stack)) + } else if gatewayErr.Err != nil { attrs = append(attrs, "error", gatewayErr.Err) } if c != nil && c.Request() != nil { diff --git a/internal/server/error_support_test.go b/internal/server/error_support_test.go index bdeec1da5..f3782cab4 100644 --- a/internal/server/error_support_test.go +++ b/internal/server/error_support_test.go @@ -9,8 +9,10 @@ import ( "net/http/httptest" "strings" "testing" + "time" "github.com/labstack/echo/v5" + "github.com/labstack/echo/v5/middleware" "github.com/enterpilot/gomodel/internal/auditlog" "github.com/enterpilot/gomodel/internal/core" @@ -268,3 +270,240 @@ func TestHandleError_RecordsUpstreamProviderOfError(t *testing.T) { t.Fatalf("gateway auth error body should omit provider: %s", rec.Body.String()) } } + +func TestGatewayErrorHandler_RendersCanonicalEnvelope(t *testing.T) { + tests := []struct { + name string + err error + wantStatus int + wantType string + wantMessage string + }{ + { + name: "recovered panic", + err: errors.New("runtime error: invalid memory address"), + wantStatus: http.StatusInternalServerError, + wantType: "internal_error", + }, + { + name: "unencodable response body", + err: &json.UnsupportedValueError{Str: "+Inf"}, + wantStatus: http.StatusInternalServerError, + wantType: "internal_error", + }, + { + name: "echo client error keeps its status", + err: echo.NewHTTPError(http.StatusMethodNotAllowed, "Method Not Allowed"), + wantStatus: http.StatusMethodNotAllowed, + wantType: "invalid_request_error", + }, + { + name: "middleware sentinel keeps its status", + err: echo.ErrStatusRequestEntityTooLarge, + wantStatus: http.StatusRequestEntityTooLarge, + wantType: "invalid_request_error", + }, + { + // echo's Decompress middleware answers 500 with err.Error(); a + // message describing gateway internals must not reach the client. + name: "echo server error stays opaque", + err: echo.NewHTTPError(http.StatusInternalServerError, "dial tcp 10.0.0.1:5432: connection refused"), + wantStatus: http.StatusInternalServerError, + wantType: "internal_error", + wantMessage: "an unexpected error occurred", + }, + { + name: "gateway error passes through", + err: core.NewNotFoundError("no such model"), + wantStatus: http.StatusNotFound, + wantType: "not_found_error", + }, + } + for _, tc := range tests { + t.Run(tc.name, func(t *testing.T) { + e := echo.New() + req := httptest.NewRequest(http.MethodGet, "/admin/virtual-models", nil) + rec := httptest.NewRecorder() + c := e.NewContext(req, rec) + + gatewayErrorHandler(c, tc.err) + + if rec.Code != tc.wantStatus { + t.Fatalf("status = %d, want %d", rec.Code, tc.wantStatus) + } + var body struct { + Error struct { + Type string `json:"type"` + Message string `json:"message"` + } `json:"error"` + } + if err := json.Unmarshal(rec.Body.Bytes(), &body); err != nil { + t.Fatalf("unmarshal %q: %v", rec.Body.String(), err) + } + if body.Error.Type != tc.wantType { + t.Errorf("error type = %q, want %q (body %s)", body.Error.Type, tc.wantType, rec.Body.String()) + } + if body.Error.Message == "" { + t.Errorf("error message is empty, body %s", rec.Body.String()) + } + if tc.wantMessage != "" && body.Error.Message != tc.wantMessage { + t.Errorf("error message = %q, want %q", body.Error.Message, tc.wantMessage) + } + }) + } +} + +func TestGatewayErrorHandler_LogsPanicWithStackAndRoute(t *testing.T) { + var buf bytes.Buffer + original := slog.Default() + slog.SetDefault(slog.New(slog.NewJSONHandler(&buf, &slog.HandlerOptions{Level: slog.LevelDebug}))) + t.Cleanup(func() { slog.SetDefault(original) }) + + e := echo.NewWithConfig(echo.Config{HTTPErrorHandler: gatewayErrorHandler}) + e.Use(middleware.Recover()) + e.GET("/admin/virtual-models", func(*echo.Context) error { + panic("listing blew up") + }) + + req := httptest.NewRequest(http.MethodGet, "/admin/virtual-models", nil) + req = req.WithContext(core.WithRequestID(req.Context(), "panic-req-1")) + rec := httptest.NewRecorder() + e.ServeHTTP(rec, req) + + if rec.Code != http.StatusInternalServerError { + t.Fatalf("status = %d, want 500", rec.Code) + } + if !strings.Contains(rec.Body.String(), `"type":"internal_error"`) { + t.Errorf("body = %s, want the canonical error envelope", rec.Body.String()) + } + + logOutput := buf.String() + for _, want := range []string{`"level":"ERROR"`, `"path":"/admin/virtual-models"`, `"request_id":"panic-req-1"`, `"panic":"listing blew up"`, `"stack":"goroutine `} { + if !strings.Contains(logOutput, want) { + t.Errorf("log missing %q, got %q", want, logOutput) + } + } + if strings.Contains(logOutput, "PANIC RECOVER") { + t.Errorf("panic value and stack should be separate attributes, not one error string: %q", logOutput) + } +} + +func TestGatewayErrorHandler_LeavesCommittedResponseAlone(t *testing.T) { + var buf bytes.Buffer + original := slog.Default() + slog.SetDefault(slog.New(slog.NewJSONHandler(&buf, nil))) + t.Cleanup(func() { slog.SetDefault(original) }) + + e := echo.New() + req := httptest.NewRequest(http.MethodGet, "/v1/chat/completions", nil) + rec := httptest.NewRecorder() + c := e.NewContext(req, rec) + + if err := c.String(http.StatusOK, "streamed"); err != nil { + t.Fatalf("String() error = %v", err) + } + gatewayErrorHandler(c, errors.New("failed after the first chunk")) + + if rec.Code != http.StatusOK { + t.Fatalf("status = %d, want 200 (response already committed)", rec.Code) + } + if rec.Body.String() != "streamed" { + t.Fatalf("body = %q, want the already-written body", rec.Body.String()) + } + // The response is untouchable, but the operator still needs to know. + if !strings.Contains(buf.String(), "failed after the first chunk") { + t.Fatalf("error after a committed response was not logged: %q", buf.String()) + } +} + +// The direct gatewayErrorHandler tests stub the error; this one drives the real +// server so the goccy serializer, echo's dispatch and the handler are all in +// the path — the shape that produced the opaque 500 in #881. +func TestGatewayErrorHandler_UnencodableResponseThroughRealServer(t *testing.T) { + logs := &bytes.Buffer{} + original := slog.Default() + slog.SetDefault(slog.New(slog.NewJSONHandler(logs, &slog.HandlerOptions{Level: slog.LevelDebug}))) + t.Cleanup(func() { slog.SetDefault(original) }) + + // A year beyond 9999 is what time.Time refuses to marshal, which is how one + // stored row turned a whole admin listing into a 500. + type row struct { + CreatedAt time.Time `json:"created_at"` + } + srv := New(&mockProvider{}, nil) + srv.echo.GET("/admin/rows", func(c *echo.Context) error { + return c.JSON(http.StatusOK, []row{{CreatedAt: time.Unix(1<<40, 0).UTC()}}) + }) + + rec := httptest.NewRecorder() + srv.ServeHTTP(rec, httptest.NewRequest(http.MethodGet, "/admin/rows", nil)) + + if rec.Code != http.StatusInternalServerError { + t.Fatalf("status = %d, want 500 (body %q)", rec.Code, rec.Body.String()) + } + var body struct { + Error struct { + Type string `json:"type"` + Message string `json:"message"` + } `json:"error"` + } + if err := json.Unmarshal(rec.Body.Bytes(), &body); err != nil { + t.Fatalf("body %q is not a gateway error envelope: %v", rec.Body.String(), err) + } + if body.Error.Type != "internal_error" || body.Error.Message != "an unexpected error occurred" { + t.Fatalf("error = %+v, want the canonical internal_error envelope", body.Error) + } + if strings.Contains(rec.Body.String(), "year outside") { + t.Errorf("serializer detail leaked to the client: %s", rec.Body.String()) + } + if !strings.Contains(logs.String(), "year outside of range") { + t.Errorf("log should name the serialization failure, got %q", logs.String()) + } +} + +func TestGatewayErrorHandler_FinalizesHeadersAndAudit(t *testing.T) { + e := echo.New() + req := httptest.NewRequest(http.MethodPost, "/v1/chat/completions", nil) + rec := httptest.NewRecorder() + c := e.NewContext(req, rec) + entry := &auditlog.LogEntry{Data: &auditlog.LogData{}} + c.Set(string(auditlog.LogEntryKey), entry) + + gatewayErrorHandler(c, &gatewayErrorWithResponseHeaders{ + GatewayError: core.NewRateLimitError("budget", "budget exceeded").WithCode("budget_exceeded"), + headers: http.Header{"Retry-After": []string{"30"}}, + }) + + if rec.Code != http.StatusTooManyRequests { + t.Fatalf("status = %d, want 429", rec.Code) + } + if got := rec.Header().Get("Retry-After"); got != "30" { + t.Errorf("Retry-After = %q, want 30", got) + } + if entry.ErrorType != string(core.ErrorTypeRateLimit) || entry.Data.ErrorCode != "budget_exceeded" { + t.Errorf("audit entry = %q/%q, want rate_limit_error/budget_exceeded", entry.ErrorType, entry.Data.ErrorCode) + } +} + +func TestGatewayErrorHandler_KeepsTheOriginalAuditedError(t *testing.T) { + e := echo.New() + req := httptest.NewRequest(http.MethodPost, "/v1/chat/completions", nil) + rec := httptest.NewRecorder() + c := e.NewContext(req, rec) + entry := &auditlog.LogEntry{Data: &auditlog.LogData{}} + c.Set(string(auditlog.LogEntryKey), entry) + + // handleError records the real cause and returns its own write failure, + // which then escapes here; that follow-up must not overwrite the cause. + if err := handleError(c, core.NewNotFoundError("no such model")); err != nil { + t.Fatalf("handleError() error = %v", err) + } + gatewayErrorHandler(c, errors.New("writing the error response failed")) + + if entry.ErrorType != string(core.ErrorTypeNotFound) { + t.Errorf("entry.ErrorType = %q, want not_found_error", entry.ErrorType) + } + if entry.Data.ErrorMessage != "no such model" { + t.Errorf("entry.Data.ErrorMessage = %q, want the original cause", entry.Data.ErrorMessage) + } +} diff --git a/internal/server/http.go b/internal/server/http.go index 37d582f8f..5733e6bd1 100644 --- a/internal/server/http.go +++ b/internal/server/http.go @@ -143,6 +143,10 @@ func New(provider core.RoutableProvider, cfg *Config) *Server { NotFoundHandler: handleRouteNotFound, }), JSONSerializer: goJSONSerializer{}, + // Errors no handler reported (recovered panics, responses the JSON + // serializer could not encode) get the canonical envelope and a log + // line instead of echo's silent, bare "Internal Server Error". + HTTPErrorHandler: gatewayErrorHandler, }) e.Logger = slog.Default() basePath := configuredBasePath(cfg) diff --git a/internal/storage/sqlutil/sqlutil.go b/internal/storage/sqlutil/sqlutil.go index 4abcea6dc..7de625884 100644 --- a/internal/storage/sqlutil/sqlutil.go +++ b/internal/storage/sqlutil/sqlutil.go @@ -64,12 +64,27 @@ func UnixOrNil(value *time.Time) any { return value.UTC().Unix() } +// TimeFromUnix converts a stored Unix-seconds column into a UTC time, +// mapping a value JSON cannot represent (time.Time marshals only years 0-9999) +// to the zero time. A single corrupt timestamp — a row written while the host +// clock was wrong, or hand-edited — would otherwise make every API response +// carrying that row unserializable, failing the whole listing instead of the +// one column. Same tolerance as StringsFromJSON, for the same reason. +func TimeFromUnix(value int64) time.Time { + t := time.Unix(value, 0).UTC() + if year := t.Year(); year < 0 || year > 9999 { + slog.Warn("dropping out-of-range stored timestamp", "unix_seconds", value) + return time.Time{} + } + return t +} + // TimeFromUnixPtr converts an optional Unix timestamp to a *time.Time. func TimeFromUnixPtr(value *int64) *time.Time { if value == nil { return nil } - t := time.Unix(*value, 0).UTC() + t := TimeFromUnix(*value) return &t } diff --git a/internal/storage/sqlutil/sqlutil_test.go b/internal/storage/sqlutil/sqlutil_test.go index f20a281c7..3d3e28547 100644 --- a/internal/storage/sqlutil/sqlutil_test.go +++ b/internal/storage/sqlutil/sqlutil_test.go @@ -1,8 +1,10 @@ package sqlutil import ( + "encoding/json" "reflect" "testing" + "time" ) func TestNullableJSONStrings(t *testing.T) { @@ -44,3 +46,45 @@ func TestStringsFromJSON(t *testing.T) { }) } } + +func TestTimeFromUnix(t *testing.T) { + tests := []struct { + name string + value int64 + want time.Time + }{ + {name: "epoch", value: 0, want: time.Unix(0, 0).UTC()}, + {name: "recent timestamp", value: 1788518356, want: time.Unix(1788518356, 0).UTC()}, + {name: "zero time round trip", value: time.Time{}.Unix(), want: time.Time{}}, + {name: "beyond year 9999 drops to zero time", value: 99999999999999, want: time.Time{}}, + {name: "before year 0 drops to zero time", value: -99999999999999, want: time.Time{}}, + } + for _, tt := range tests { + t.Run(tt.name, func(t *testing.T) { + got := TimeFromUnix(tt.value) + if !got.Equal(tt.want) { + t.Fatalf("TimeFromUnix(%d) = %s, want %s", tt.value, got, tt.want) + } + // Equal compares instants only; a stray location would change the + // offset every API response serializes. + if got.Location() != time.UTC { + t.Errorf("TimeFromUnix(%d) location = %s, want UTC", tt.value, got.Location()) + } + // The whole point of the clamp: the result must be encodable, or + // one bad row takes down every listing that includes it. + if _, err := json.Marshal(got); err != nil { + t.Fatalf("TimeFromUnix(%d) is not JSON-encodable: %v", tt.value, err) + } + }) + } +} + +func TestTimeFromUnixPtr(t *testing.T) { + if got := TimeFromUnixPtr(nil); got != nil { + t.Fatalf("TimeFromUnixPtr(nil) = %v, want nil", got) + } + out := int64(99999999999999) + if got := TimeFromUnixPtr(&out); got == nil || !got.IsZero() { + t.Fatalf("TimeFromUnixPtr(out-of-range) = %v, want zero time", got) + } +} diff --git a/internal/users/store_sql.go b/internal/users/store_sql.go index bfa205985..c978e2779 100644 --- a/internal/users/store_sql.go +++ b/internal/users/store_sql.go @@ -4,8 +4,8 @@ import ( "context" "encoding/json" "fmt" - "time" + "github.com/enterpilot/gomodel/internal/storage/sqlutil" "github.com/enterpilot/gomodel/internal/storage/sqlx" ) @@ -55,8 +55,8 @@ func (s *SQLStore) List(ctx context.Context) ([]User, error) { if user.AllowedModels, err = decodeAllowedModels(allowedJSON); err != nil { return nil, err } - user.CreatedAt = time.Unix(createdAt, 0).UTC() - user.UpdatedAt = time.Unix(updatedAt, 0).UTC() + user.CreatedAt = sqlutil.TimeFromUnix(createdAt) + user.UpdatedAt = sqlutil.TimeFromUnix(updatedAt) result = append(result, user) } if err := rows.Err(); err != nil { diff --git a/internal/virtualmodels/store_sql.go b/internal/virtualmodels/store_sql.go index caf385be2..0ec170914 100644 --- a/internal/virtualmodels/store_sql.go +++ b/internal/virtualmodels/store_sql.go @@ -5,8 +5,8 @@ import ( "errors" "fmt" "strings" - "time" + "github.com/enterpilot/gomodel/internal/storage/sqlutil" "github.com/enterpilot/gomodel/internal/storage/sqlx" ) @@ -201,8 +201,8 @@ func scanSQLVirtualModel(scanner sqlx.Row) (VirtualModel, error) { } vm.SessionAffinity = decodeTriStateBool(sessionAffinity) vm.Failover = decodeTriStateBool(failover) - vm.CreatedAt = time.Unix(createdAt, 0).UTC() - vm.UpdatedAt = time.Unix(updatedAt, 0).UTC() + vm.CreatedAt = sqlutil.TimeFromUnix(createdAt) + vm.UpdatedAt = sqlutil.TimeFromUnix(updatedAt) return vm, nil } diff --git a/internal/virtualmodels/store_test.go b/internal/virtualmodels/store_test.go index f4ba43118..ea3d0d6d1 100644 --- a/internal/virtualmodels/store_test.go +++ b/internal/virtualmodels/store_test.go @@ -2,6 +2,7 @@ package virtualmodels import ( "context" + "encoding/json" "errors" "strings" "testing" @@ -148,3 +149,46 @@ func TestSQLStore_ListSurfacesUndecodableRow(t *testing.T) { } }) } + +// A stored timestamp outside the range JSON can represent — a row written while +// the host clock was wrong, or hand-edited — must still list. The admin API +// serializes every row into one response, so a single unencodable column would +// otherwise fail the whole listing with an opaque 500 (issue #881). +func TestSQLStore_ListsRowWithOutOfRangeTimestamp(t *testing.T) { + ctx := context.Background() + db := sqlxtest.NewSQLite(t) + store, err := NewSQLStore(ctx, db) + if err != nil { + t.Fatalf("NewSQLStore: %v", err) + } + t.Cleanup(func() { _ = store.Close() }) + + vm := VirtualModel{ + Source: "fast", + Targets: []Target{{Provider: "openai", Model: "gpt-4o"}}, + Enabled: true, + } + if err := store.Upsert(ctx, vm); err != nil { + t.Fatalf("Upsert: %v", err) + } + const beyondYear9999 = int64(99999999999999) + if _, err := db.Exec(ctx, + "UPDATE virtual_models SET created_at = ?, updated_at = ? WHERE source = ?", + beyondYear9999, beyondYear9999, vm.Source); err != nil { + t.Fatalf("corrupt timestamps: %v", err) + } + + rows, err := store.List(ctx) + if err != nil { + t.Fatalf("List: %v", err) + } + if len(rows) != 1 { + t.Fatalf("len(List()) = %d, want 1", len(rows)) + } + if !rows[0].CreatedAt.IsZero() || !rows[0].UpdatedAt.IsZero() { + t.Errorf("timestamps = %s / %s, want the zero time", rows[0].CreatedAt, rows[0].UpdatedAt) + } + if _, err := json.Marshal(rows); err != nil { + t.Fatalf("listing is not JSON-encodable: %v", err) + } +} diff --git a/internal/workflows/store_sql.go b/internal/workflows/store_sql.go index 2d23aa5f0..23a6aaa29 100644 --- a/internal/workflows/store_sql.go +++ b/internal/workflows/store_sql.go @@ -320,7 +320,7 @@ func scanSQLVersion(scanner versionRowScanner) (Version, error) { Model: sqlutil.DerefTrimmed(scopeModel), UserPath: storedScopeUserPath(version.ScopeKey, sqlutil.DerefTrimmed(scopeUserPath)), } - version.CreatedAt = time.Unix(createdAtUnix, 0).UTC() + version.CreatedAt = sqlutil.TimeFromUnix(createdAtUnix) if err := json.Unmarshal(payloadJSON, &version.Payload); err != nil { return Version{}, fmt.Errorf("decode workflow payload %q: %w", version.ID, err) }