From 72339000686d5e266952850789ae35e6ac9983f6 Mon Sep 17 00:00:00 2001 From: "Jakub A. W" Date: Fri, 4 Sep 2026 12:57:00 +0200 Subject: [PATCH 1/5] fix(admin): keep one corrupt timestamp from failing a whole listing Every SQL store decoded created_at/updated_at with time.Unix, which accepts any int64 but produces a time JSON cannot encode outside years 0-9999. Admin listings serialize all rows into one response, so a single row written while the host clock was wrong (or hand-edited) made GET /admin/virtual-models and GET /admin/provider-credentials fail entirely with HTTP 500. Route the decodes through sqlutil.TimeFromUnix, which maps an unrepresentable value to the zero time and warns, the same tolerance StringsFromJSON already applies to malformed JSON columns. Fixes #881 Co-Authored-By: Claude Opus 5 (1M context) Claude-Session: https://claude.ai/code/session_01GbZfUSK3BnzEE8c6vaCb9c --- internal/authkeys/store_sql.go | 4 +- internal/budget/store_sql.go | 4 +- internal/guardrails/store_sql.go | 4 +- internal/mcpgateway/store_sql.go | 6 +-- internal/pricingoverrides/store_sql.go | 6 +-- internal/providers/credentials_store_sql.go | 6 +-- internal/ratelimit/store_sql.go | 5 ++- internal/storage/sqlutil/sqlutil.go | 17 +++++++- internal/storage/sqlutil/sqlutil_test.go | 39 ++++++++++++++++++ internal/users/store_sql.go | 6 +-- internal/virtualmodels/store_sql.go | 6 +-- internal/virtualmodels/store_test.go | 44 +++++++++++++++++++++ internal/workflows/store_sql.go | 2 +- 13 files changed, 124 insertions(+), 25 deletions(-) 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/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/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..4e9f69d33 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,40 @@ 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) + } + // 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) } From 1ac9cc57b5defc40145e0f487677b2a4425bc946 Mon Sep 17 00:00:00 2001 From: "Jakub A. W" Date: Fri, 4 Sep 2026 12:58:24 +0200 Subject: [PATCH 2/5] fix(server): render and log the errors that escape a handler A recovered panic, or a response body the JSON serializer could not encode, reached echo's default error handler, which answers with a bare {"message":"Internal Server Error"} and logs nothing at all. The operator who reported #881 therefore had a 500 that named neither the endpoint nor the cause, and clients got an envelope no OpenAI SDK can parse. Install a central handler that renders these in the caller's wire dialect (the canonical envelope handleError already uses) and logs them, keeping the status echo attached to errors such as BodyLimit's 413. A recovered panic's stack rides along in the logged error. Co-Authored-By: Claude Opus 5 (1M context) Claude-Session: https://claude.ai/code/session_01GbZfUSK3BnzEE8c6vaCb9c --- internal/admin/handler.go | 2 +- internal/core/errors.go | 3 + internal/server/error_support.go | 64 ++++++++++++++ internal/server/error_support_test.go | 121 ++++++++++++++++++++++++++ internal/server/http.go | 4 + 5 files changed, 193 insertions(+), 1 deletion(-) 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/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/server/error_support.go b/internal/server/error_support.go index 659316123..6999d2cca 100644 --- a/internal/server/error_support.go +++ b/internal/server/error_support.go @@ -37,6 +37,70 @@ 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 + } + // 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 + } + + gatewayErr := escapedGatewayError(err) + // gatewayErr.Err carries the original error, which for a recovered panic is + // echo's PanicStackError: its message is the panic value plus the stack. + logHandledError(c, gatewayErr) + 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, message := http.StatusInternalServerError, "an unexpected error occurred" + if code := echo.StatusCode(err); code > 0 { + status, message = code, echoErrorMessage(err, code) + } + if status < http.StatusInternalServerError { + return core.NewInvalidRequestErrorWithStatus(status, message, err) + } + return &core.GatewayError{ + Type: core.ErrorTypeInternal, + Message: message, + 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 diff --git a/internal/server/error_support_test.go b/internal/server/error_support_test.go index bdeec1da5..1257b241b 100644 --- a/internal/server/error_support_test.go +++ b/internal/server/error_support_test.go @@ -11,6 +11,7 @@ import ( "testing" "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 +269,123 @@ 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 + }{ + { + 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", + }, + { + 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()) + } + }) + } +} + +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"`, "listing blew up", "PANIC RECOVER"} { + if !strings.Contains(logOutput, want) { + t.Errorf("log missing %q, got %q", want, logOutput) + } + } +} + +func TestGatewayErrorHandler_LeavesCommittedResponseAlone(t *testing.T) { + 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()) + } +} 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) From f008eff7449612bd2bb3fb4e40fda77077b54999 Mon Sep 17 00:00:00 2001 From: "Jakub A. W" Date: Fri, 4 Sep 2026 13:15:34 +0200 Subject: [PATCH 3/5] fix(server): log escaped errors before the committed check and split panic stacks A panic after the first streamed chunk was never logged because the handler returned on a committed response before logging. The recovered panic's value and stack now land in separate `panic` and `stack` attributes instead of one error string. Co-Authored-By: Claude Fable 5.1 Claude-Session: https://claude.ai/code/session_01NEgRAh914CS85pUNh92RBh --- internal/server/error_support.go | 18 ++++++++++++------ internal/server/error_support_test.go | 14 +++++++++++++- 2 files changed, 25 insertions(+), 7 deletions(-) diff --git a/internal/server/error_support.go b/internal/server/error_support.go index 6999d2cca..21aea81f1 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" @@ -48,16 +49,16 @@ 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) + // 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 } - - gatewayErr := escapedGatewayError(err) - // gatewayErr.Err carries the original error, which for a recovered panic is - // echo's PanicStackError: its message is the panic value plus the stack. - logHandledError(c, gatewayErr) if writeErr := writeGatewayError(c, gatewayErr); writeErr != nil { slog.Error("failed to send error response", "error", writeErr) } @@ -167,7 +168,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 1257b241b..ce06b6c2f 100644 --- a/internal/server/error_support_test.go +++ b/internal/server/error_support_test.go @@ -364,14 +364,22 @@ func TestGatewayErrorHandler_LogsPanicWithStackAndRoute(t *testing.T) { } logOutput := buf.String() - for _, want := range []string{`"level":"ERROR"`, `"path":"/admin/virtual-models"`, `"request_id":"panic-req-1"`, "listing blew up", "PANIC RECOVER"} { + 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() @@ -388,4 +396,8 @@ func TestGatewayErrorHandler_LeavesCommittedResponseAlone(t *testing.T) { 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()) + } } From a1ba99f1510aebabb35f01411ca36fc5e004da6b Mon Sep 17 00:00:00 2001 From: "Jakub A. W" Date: Fri, 4 Sep 2026 13:33:26 +0200 Subject: [PATCH 4/5] fix(server): finalize escaped errors the way handleError does MIME-Version: 1.0 Content-Type: text/plain; charset=UTF-8 Content-Transfer-Encoding: 8bit An error that reached the central handler without passing through handleError — a recovered panic, or a rate-limit error returned rather than rendered — skipped audit enrichment and response headers, so its audit row recorded no error and a Retry-After could be dropped. Run the same finalization before writing. The audit half is skipped once an error is recorded: handleError returns its own response write failures to this handler, and re-enriching there would replace the real cause with the generic one. Also drive the serializer failure end to end through the real server, so the goccy serializer and echo's dispatch are in the tested path, and assert TimeFromUnix keeps its UTC location. Co-Authored-By: Claude Opus 5 (1M context) Claude-Session: https://claude.ai/code/session_01GbZfUSK3BnzEE8c6vaCb9c --- internal/auditlog/enrich.go | 8 ++ internal/auditlog/enrich_test.go | 27 +++++++ internal/server/error_support.go | 11 +++ internal/server/error_support_test.go | 93 ++++++++++++++++++++++++ internal/storage/sqlutil/sqlutil_test.go | 5 ++ 5 files changed, 144 insertions(+) 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/server/error_support.go b/internal/server/error_support.go index 21aea81f1..6d5b63c06 100644 --- a/internal/server/error_support.go +++ b/internal/server/error_support.go @@ -53,6 +53,17 @@ func gatewayErrorHandler(c *echo.Context, err error) { // 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. diff --git a/internal/server/error_support_test.go b/internal/server/error_support_test.go index ce06b6c2f..e20cc21dc 100644 --- a/internal/server/error_support_test.go +++ b/internal/server/error_support_test.go @@ -9,6 +9,7 @@ import ( "net/http/httptest" "strings" "testing" + "time" "github.com/labstack/echo/v5" "github.com/labstack/echo/v5/middleware" @@ -401,3 +402,95 @@ func TestGatewayErrorHandler_LeavesCommittedResponseAlone(t *testing.T) { 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/storage/sqlutil/sqlutil_test.go b/internal/storage/sqlutil/sqlutil_test.go index 4e9f69d33..3d3e28547 100644 --- a/internal/storage/sqlutil/sqlutil_test.go +++ b/internal/storage/sqlutil/sqlutil_test.go @@ -65,6 +65,11 @@ func TestTimeFromUnix(t *testing.T) { 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 { From 273cd18ddb2bc28bb31b4e22888c9af3a8d577ff Mon Sep 17 00:00:00 2001 From: "Jakub A. W" Date: Fri, 4 Sep 2026 13:50:01 +0200 Subject: [PATCH 5/5] fix(server): keep escaped 5xx messages opaque to the client MIME-Version: 1.0 Content-Type: text/plain; charset=UTF-8 Content-Transfer-Encoding: 8bit echo answers some server errors with the underlying error text — its Decompress middleware passes err.Error() straight into the response — and escapedGatewayError forwarded that message verbatim, so a failure inside the gateway could describe its internals to the caller. 5xx now carries the same opaque text every other gateway 500 uses; the cause stays in Err, which only the logs read. Client errors keep echo's message, which names the rule the request broke (413, 405). Co-Authored-By: Claude Opus 5 (1M context) Claude-Session: https://claude.ai/code/session_01GbZfUSK3BnzEE8c6vaCb9c --- internal/server/error_support.go | 14 +++++++++----- internal/server/error_support_test.go | 21 +++++++++++++++++---- 2 files changed, 26 insertions(+), 9 deletions(-) diff --git a/internal/server/error_support.go b/internal/server/error_support.go index 6d5b63c06..81a4e5c8b 100644 --- a/internal/server/error_support.go +++ b/internal/server/error_support.go @@ -86,16 +86,20 @@ func escapedGatewayError(err error) *core.GatewayError { // 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, message := http.StatusInternalServerError, "an unexpected error occurred" - if code := echo.StatusCode(err); code > 0 { - status, message = code, echoErrorMessage(err, code) + status := echo.StatusCode(err) + if status <= 0 { + status = http.StatusInternalServerError } if status < http.StatusInternalServerError { - return core.NewInvalidRequestErrorWithStatus(status, message, err) + 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: message, + Message: "an unexpected error occurred", StatusCode: status, Err: err, } diff --git a/internal/server/error_support_test.go b/internal/server/error_support_test.go index e20cc21dc..f3782cab4 100644 --- a/internal/server/error_support_test.go +++ b/internal/server/error_support_test.go @@ -273,10 +273,11 @@ func TestHandleError_RecordsUpstreamProviderOfError(t *testing.T) { func TestGatewayErrorHandler_RendersCanonicalEnvelope(t *testing.T) { tests := []struct { - name string - err error - wantStatus int - wantType string + name string + err error + wantStatus int + wantType string + wantMessage string }{ { name: "recovered panic", @@ -302,6 +303,15 @@ func TestGatewayErrorHandler_RendersCanonicalEnvelope(t *testing.T) { 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"), @@ -336,6 +346,9 @@ func TestGatewayErrorHandler_RendersCanonicalEnvelope(t *testing.T) { 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) + } }) } }