From 0f69f09a70b0493e7bfee2fae47d9c3c3f5d4665 Mon Sep 17 00:00:00 2001 From: sususu Date: Sun, 16 Aug 2026 08:31:09 +0800 Subject: [PATCH] fix(logging): exclude HTTP 499 and client cancellations from forced error logs --- .../api/middleware/request_logging_test.go | 125 ++++++++++++ internal/api/middleware/response_writer.go | 44 ++++- .../api/middleware/response_writer_test.go | 178 ++++++++++++++++++ internal/clienterror/client_error.go | 25 +++ internal/clienterror/client_error_test.go | 30 +++ .../runtime/executor/helps/usage_helpers.go | 13 ++ .../executor/helps/usage_helpers_test.go | 21 +++ 7 files changed, 434 insertions(+), 2 deletions(-) diff --git a/internal/api/middleware/request_logging_test.go b/internal/api/middleware/request_logging_test.go index 48ce4f6cc..ab0094fc6 100644 --- a/internal/api/middleware/request_logging_test.go +++ b/internal/api/middleware/request_logging_test.go @@ -13,6 +13,7 @@ import ( "github.com/gin-gonic/gin" "github.com/klauspost/compress/zstd" + "github.com/router-for-me/CLIProxyAPI/v7/internal/clienterror" "github.com/router-for-me/CLIProxyAPI/v7/internal/config" "github.com/router-for-me/CLIProxyAPI/v7/internal/logging" "github.com/router-for-me/CLIProxyAPI/v7/internal/runtime/executor/helps" @@ -380,3 +381,127 @@ func TestCaptureRequestInfoDecodesZstdRequestBodyForLog(t *testing.T) { t.Fatal("request body was not restored with the original compressed bytes") } } + +func TestRequestLoggingMiddleware_ClientCancellationExclusion(t *testing.T) { + gin.SetMode(gin.TestMode) + + t.Run("499 status does not create error log when request-log is false", func(t *testing.T) { + logsDir := t.TempDir() + logger := logging.NewFileRequestLogger(false, logsDir, "", 10) + + router := gin.New() + router.Use(RequestLoggingMiddleware(logger)) + router.POST("/v1/responses", func(c *gin.Context) { + c.AbortWithStatus(clienterror.StatusClientClosedRequest) + }) + + req := httptest.NewRequest(http.MethodPost, "/v1/responses", strings.NewReader(`{"model":"gpt-4"}`)) + req.Header.Set("Content-Type", "application/json") + resp := httptest.NewRecorder() + router.ServeHTTP(resp, req) + + if resp.Code != clienterror.StatusClientClosedRequest { + t.Fatalf("status = %d, want %d", resp.Code, clienterror.StatusClientClosedRequest) + } + + entries, errRead := os.ReadDir(logsDir) + if errRead != nil { + t.Fatalf("read logs dir: %v", errRead) + } + if len(entries) != 0 { + t.Fatalf("expected 0 log files for 499 cancellation in error-only mode, got %d files", len(entries)) + } + }) + + t.Run("context canceled does not create error log when request-log is false", func(t *testing.T) { + logsDir := t.TempDir() + logger := logging.NewFileRequestLogger(false, logsDir, "", 10) + + router := gin.New() + router.Use(RequestLoggingMiddleware(logger)) + router.POST("/v1/responses", func(c *gin.Context) { + // Simulate client closing connection mid-flight + ctx, cancel := context.WithCancel(c.Request.Context()) + cancel() + c.Request = c.Request.WithContext(ctx) + c.Status(http.StatusOK) + }) + + req := httptest.NewRequest(http.MethodPost, "/v1/responses", strings.NewReader(`{"model":"gpt-4"}`)) + req.Header.Set("Content-Type", "application/json") + resp := httptest.NewRecorder() + router.ServeHTTP(resp, req) + + entries, errRead := os.ReadDir(logsDir) + if errRead != nil { + t.Fatalf("read logs dir: %v", errRead) + } + if len(entries) != 0 { + t.Fatalf("expected 0 log files for canceled context in error-only mode, got %d files", len(entries)) + } + }) + + t.Run("400 bad request creates error log when request-log is false", func(t *testing.T) { + logsDir := t.TempDir() + logger := logging.NewFileRequestLogger(false, logsDir, "", 10) + + router := gin.New() + router.Use(RequestLoggingMiddleware(logger)) + router.POST("/v1/responses", func(c *gin.Context) { + c.JSON(http.StatusBadRequest, gin.H{"error": "invalid parameter"}) + }) + + req := httptest.NewRequest(http.MethodPost, "/v1/responses", strings.NewReader(`{"bad":"param"}`)) + req.Header.Set("Content-Type", "application/json") + resp := httptest.NewRecorder() + router.ServeHTTP(resp, req) + + if resp.Code != http.StatusBadRequest { + t.Fatalf("status = %d, want %d", resp.Code, http.StatusBadRequest) + } + + entries, errRead := os.ReadDir(logsDir) + if errRead != nil { + t.Fatalf("read logs dir: %v", errRead) + } + var errorLogCount int + for _, entry := range entries { + if strings.HasPrefix(entry.Name(), "error-") && strings.HasSuffix(entry.Name(), ".log") { + errorLogCount++ + } + } + if errorLogCount != 1 { + t.Fatalf("expected 1 error log file for 400 Bad Request, got %d", errorLogCount) + } + }) + + t.Run("499 status logs standard request when request-log is true", func(t *testing.T) { + logsDir := t.TempDir() + logger := logging.NewFileRequestLogger(true, logsDir, "", 10) + + router := gin.New() + router.Use(RequestLoggingMiddleware(logger)) + router.POST("/v1/responses", func(c *gin.Context) { + c.AbortWithStatus(clienterror.StatusClientClosedRequest) + }) + + req := httptest.NewRequest(http.MethodPost, "/v1/responses", strings.NewReader(`{"model":"gpt-4"}`)) + req.Header.Set("Content-Type", "application/json") + resp := httptest.NewRecorder() + router.ServeHTTP(resp, req) + + entries, errRead := os.ReadDir(logsDir) + if errRead != nil { + t.Fatalf("read logs dir: %v", errRead) + } + var standardLogCount int + for _, entry := range entries { + if !strings.HasPrefix(entry.Name(), "error-") && strings.HasSuffix(entry.Name(), ".log") { + standardLogCount++ + } + } + if standardLogCount != 1 { + t.Fatalf("expected 1 standard request log file when request-log=true, got %d", standardLogCount) + } + }) +} diff --git a/internal/api/middleware/response_writer.go b/internal/api/middleware/response_writer.go index 31c655412..75d586d56 100644 --- a/internal/api/middleware/response_writer.go +++ b/internal/api/middleware/response_writer.go @@ -5,11 +5,14 @@ package middleware import ( "bytes" + "context" + "errors" "net/http" "strings" "time" "github.com/gin-gonic/gin" + "github.com/router-for-me/CLIProxyAPI/v7/internal/clienterror" "github.com/router-for-me/CLIProxyAPI/v7/internal/interfaces" "github.com/router-for-me/CLIProxyAPI/v7/internal/logging" log "github.com/sirupsen/logrus" @@ -116,7 +119,7 @@ func (w *ResponseWriterWrapper) shouldBufferResponseBody() bool { status = http.StatusOK } } - return status >= http.StatusBadRequest + return status >= http.StatusBadRequest && status != clienterror.StatusClientClosedRequest } // WriteString wraps the underlying ResponseWriter's WriteString method to capture response data. @@ -283,7 +286,7 @@ func (w *ResponseWriterWrapper) Finalize(c *gin.Context) error { } } - hasAPIError := len(slicesAPIResponseError) > 0 || finalStatusCode >= http.StatusBadRequest + hasAPIError := hasActionableError(c, finalStatusCode, slicesAPIResponseError) forceLog := w.logOnErrorOnly && hasAPIError && !w.logger.IsEnabled() websocketTimelineSource := w.extractWebsocketTimelineSource(c) apiRequestSource := w.extractAPIRequestSource(c) @@ -719,3 +722,40 @@ func cleanupFileBodySources(sources ...*logging.FileBodySource) { } } } + +func isClientCancellationErrorMessage(errMsg *interfaces.ErrorMessage) bool { + if errMsg == nil { + return true + } + return clienterror.IsClientCancellation(errMsg.StatusCode, errMsg.Error) +} + +func hasActionableAPIResponseErrors(apiErrors []*interfaces.ErrorMessage) bool { + for _, err := range apiErrors { + if !isClientCancellationErrorMessage(err) { + return true + } + } + return false +} + +func isContextCanceled(c *gin.Context) bool { + if c == nil || c.Request == nil { + return false + } + ctx := c.Request.Context() + return ctx != nil && errors.Is(ctx.Err(), context.Canceled) +} + +func hasActionableError(c *gin.Context, statusCode int, apiErrors []*interfaces.ErrorMessage) bool { + if hasActionableAPIResponseErrors(apiErrors) { + return true + } + if statusCode == clienterror.StatusClientClosedRequest { + return false + } + if isContextCanceled(c) && statusCode < http.StatusBadRequest { + return false + } + return statusCode >= http.StatusBadRequest +} diff --git a/internal/api/middleware/response_writer_test.go b/internal/api/middleware/response_writer_test.go index fa0bd5485..b00417512 100644 --- a/internal/api/middleware/response_writer_test.go +++ b/internal/api/middleware/response_writer_test.go @@ -2,11 +2,16 @@ package middleware import ( "bytes" + "context" + "errors" + "fmt" + "net/http" "net/http/httptest" "testing" "time" "github.com/gin-gonic/gin" + "github.com/router-for-me/CLIProxyAPI/v7/internal/clienterror" "github.com/router-for-me/CLIProxyAPI/v7/internal/interfaces" "github.com/router-for-me/CLIProxyAPI/v7/internal/logging" ) @@ -200,3 +205,176 @@ func (w *testStreamingLogWriter) Close() error { w.closed = true return nil } + +func TestHasActionableError(t *testing.T) { + canceledCtx, cancel := context.WithCancel(context.Background()) + cancel() + + tests := []struct { + name string + statusCode int + ctx context.Context + apiErrors []*interfaces.ErrorMessage + want bool + }{ + { + name: "200 ok without errors", + statusCode: http.StatusOK, + want: false, + }, + { + name: "499 client closed request", + statusCode: clienterror.StatusClientClosedRequest, + want: false, + }, + { + name: "499 with context canceled api error", + statusCode: clienterror.StatusClientClosedRequest, + apiErrors: []*interfaces.ErrorMessage{{StatusCode: clienterror.StatusClientClosedRequest, Error: context.Canceled}}, + want: false, + }, + { + name: "200 with canceled context", + statusCode: http.StatusOK, + ctx: canceledCtx, + want: false, + }, + { + name: "0 with canceled context", + statusCode: 0, + ctx: canceledCtx, + want: false, + }, + { + name: "400 bad request", + statusCode: http.StatusBadRequest, + want: true, + }, + { + name: "429 rate limit", + statusCode: http.StatusTooManyRequests, + want: true, + }, + { + name: "500 internal server error", + statusCode: http.StatusInternalServerError, + want: true, + }, + { + name: "503 with canceled context", + statusCode: http.StatusServiceUnavailable, + ctx: canceledCtx, + want: true, + }, + { + name: "200 with actionable upstream api error", + statusCode: http.StatusOK, + apiErrors: []*interfaces.ErrorMessage{{StatusCode: http.StatusBadGateway, Error: errors.New("upstream failed")}}, + want: true, + }, + { + name: "200 with non-actionable cancellation api error", + statusCode: http.StatusOK, + apiErrors: []*interfaces.ErrorMessage{{StatusCode: 0, Error: fmt.Errorf("read: %w", context.Canceled)}}, + want: false, + }, + } + + for _, tc := range tests { + t.Run(tc.name, func(t *testing.T) { + recorder := httptest.NewRecorder() + c, _ := gin.CreateTestContext(recorder) + req := httptest.NewRequest(http.MethodPost, "/v1/responses", nil) + if tc.ctx != nil { + req = req.WithContext(tc.ctx) + } + c.Request = req + + got := hasActionableError(c, tc.statusCode, tc.apiErrors) + if got != tc.want { + t.Fatalf("hasActionableError(status=%d, errors=%v) = %t, want %t", tc.statusCode, tc.apiErrors, got, tc.want) + } + }) + } +} + +type recordingRequestLogger struct { + loggedCalls []int + enabled bool +} + +func (l *recordingRequestLogger) LogRequest(url, method string, requestHeaders map[string][]string, body []byte, statusCode int, responseHeaders map[string][]string, response, websocketTimeline, apiRequest, apiResponse, apiWebsocketTimeline []byte, apiResponseErrors []*interfaces.ErrorMessage, requestID string, requestTimestamp, apiResponseTimestamp time.Time) error { + l.loggedCalls = append(l.loggedCalls, statusCode) + return nil +} + +func (l *recordingRequestLogger) LogStreamingRequest(string, string, map[string][]string, []byte, string) (logging.StreamingLogWriter, error) { + return &testStreamingLogWriter{}, nil +} + +func (l *recordingRequestLogger) IsEnabled() bool { + return l.enabled +} + +func (l *recordingRequestLogger) LogRequestWithOptions(url, method string, requestHeaders map[string][]string, body []byte, statusCode int, responseHeaders map[string][]string, response, websocketTimeline, apiRequest, apiResponse, apiWebsocketTimeline []byte, apiResponseErrors []*interfaces.ErrorMessage, force bool, requestID string, requestTimestamp, apiResponseTimestamp time.Time) error { + if force || l.enabled { + l.loggedCalls = append(l.loggedCalls, statusCode) + } + return nil +} + +func TestFinalizeExcludes499FromForceLog(t *testing.T) { + gin.SetMode(gin.TestMode) + recorder := httptest.NewRecorder() + c, _ := gin.CreateTestContext(recorder) + c.Request = httptest.NewRequest(http.MethodPost, "/v1/responses", nil) + + logger := &recordingRequestLogger{enabled: false} + wrapper := &ResponseWriterWrapper{ + ResponseWriter: c.Writer, + logger: logger, + logOnErrorOnly: true, + statusCode: clienterror.StatusClientClosedRequest, + requestInfo: &RequestInfo{ + URL: "/v1/responses", + Method: "POST", + RequestID: "req-499", + Timestamp: time.Now(), + }, + } + + if err := wrapper.Finalize(c); err != nil { + t.Fatalf("Finalize error: %v", err) + } + if len(logger.loggedCalls) != 0 { + t.Fatalf("expected 0 logged calls for 499 cancellation, got %d: %v", len(logger.loggedCalls), logger.loggedCalls) + } +} + +func TestFinalizeIncludes500InForceLog(t *testing.T) { + gin.SetMode(gin.TestMode) + recorder := httptest.NewRecorder() + c, _ := gin.CreateTestContext(recorder) + c.Request = httptest.NewRequest(http.MethodPost, "/v1/responses", nil) + + logger := &recordingRequestLogger{enabled: false} + wrapper := &ResponseWriterWrapper{ + ResponseWriter: c.Writer, + logger: logger, + logOnErrorOnly: true, + statusCode: http.StatusInternalServerError, + requestInfo: &RequestInfo{ + URL: "/v1/responses", + Method: "POST", + RequestID: "req-500", + Timestamp: time.Now(), + }, + } + + if err := wrapper.Finalize(c); err != nil { + t.Fatalf("Finalize error: %v", err) + } + if len(logger.loggedCalls) != 1 || logger.loggedCalls[0] != http.StatusInternalServerError { + t.Fatalf("expected 1 logged call for 500 status, got: %v", logger.loggedCalls) + } +} diff --git a/internal/clienterror/client_error.go b/internal/clienterror/client_error.go index 36a0e61c8..51db164a3 100644 --- a/internal/clienterror/client_error.go +++ b/internal/clienterror/client_error.go @@ -162,3 +162,28 @@ func hasRequestFaultBody(err error) bool { } return false } + +// IsClientCancellation reports whether an HTTP status code or error represents +// a client-initiated cancellation (HTTP 499 StatusClientClosedRequest or context.Canceled). +func IsClientCancellation(status int, err error) bool { + if status == StatusClientClosedRequest { + return true + } + if err != nil { + if errors.Is(err, context.Canceled) { + return true + } + type statusCoder interface { + StatusCode() int + } + var sc statusCoder + if errors.As(err, &sc) && sc != nil && sc.StatusCode() == StatusClientClosedRequest { + return true + } + lower := strings.ToLower(err.Error()) + if strings.Contains(lower, "context canceled") || strings.Contains(lower, "client closed request") { + return true + } + } + return false +} diff --git a/internal/clienterror/client_error_test.go b/internal/clienterror/client_error_test.go index d1b0343bc..758efda55 100644 --- a/internal/clienterror/client_error_test.go +++ b/internal/clienterror/client_error_test.go @@ -223,3 +223,33 @@ func TestIsRequestFault(t *testing.T) { }) } } + +func TestIsClientCancellation(t *testing.T) { + tests := []struct { + name string + status int + err error + want bool + }{ + {name: "status 499", status: StatusClientClosedRequest, want: true}, + {name: "context canceled error", status: 0, err: context.Canceled, want: true}, + {name: "fmt wrapped context canceled", status: 0, err: fmt.Errorf("read: %w", context.Canceled), want: true}, + {name: "context canceled string in error", status: 0, err: errors.New("upstream failed: context canceled"), want: true}, + {name: "client closed request string in error", status: 0, err: errors.New("client closed request"), want: true}, + {name: "statusCoder with 499", status: 0, err: statusError{status: StatusClientClosedRequest, body: "aborted"}, want: true}, + {name: "status 200 without error", status: http.StatusOK, err: nil, want: false}, + {name: "status 400 bad request", status: http.StatusBadRequest, err: errors.New("bad request"), want: false}, + {name: "status 429 rate limit", status: http.StatusTooManyRequests, err: errors.New("rate limited"), want: false}, + {name: "status 500 internal error", status: http.StatusInternalServerError, err: errors.New("internal error"), want: false}, + {name: "plain unrelated error", status: 0, err: errors.New("connection reset by peer"), want: false}, + {name: "nil error and 0 status", status: 0, err: nil, want: false}, + } + + for _, tc := range tests { + t.Run(tc.name, func(t *testing.T) { + if got := IsClientCancellation(tc.status, tc.err); got != tc.want { + t.Fatalf("IsClientCancellation(%d, %v) = %t, want %t", tc.status, tc.err, got, tc.want) + } + }) + } +} diff --git a/internal/runtime/executor/helps/usage_helpers.go b/internal/runtime/executor/helps/usage_helpers.go index 04faf7898..7313fb339 100644 --- a/internal/runtime/executor/helps/usage_helpers.go +++ b/internal/runtime/executor/helps/usage_helpers.go @@ -210,6 +210,10 @@ func (r *UsageReporter) PublishFailure(ctx context.Context, errs ...error) { r.publishWithOutcome(ctx, usage.Detail{}, true, failFromErrors(errs...)) } +func (r *UsageReporter) PublishFailureWithDetail(ctx context.Context, detail usage.Detail, errs ...error) { + r.publishWithOutcome(ctx, detail, true, failFromErrors(errs...)) +} + func (r *UsageReporter) TrackFailure(ctx context.Context, errPtr *error) { if r == nil || errPtr == nil { return @@ -525,6 +529,15 @@ func (b *StreamUsageBuffer) Publish(ctx context.Context, reporter *UsageReporter return true } +// PublishFailure emits the latest observed usage detail together with failure details. +func (b *StreamUsageBuffer) PublishFailure(ctx context.Context, reporter *UsageReporter, errs ...error) bool { + if b == nil || reporter == nil { + return false + } + reporter.PublishFailureWithDetail(ctx, b.detail, errs...) + return true +} + // Detail returns the latest observed usage detail. func (b *StreamUsageBuffer) Detail() (usage.Detail, bool) { if b == nil || !b.ok { diff --git a/internal/runtime/executor/helps/usage_helpers_test.go b/internal/runtime/executor/helps/usage_helpers_test.go index dc0785ca2..3fc772956 100644 --- a/internal/runtime/executor/helps/usage_helpers_test.go +++ b/internal/runtime/executor/helps/usage_helpers_test.go @@ -719,6 +719,27 @@ func TestFailFromErrorsMapsContextStatuses(t *testing.T) { } } +func TestStreamUsageBufferPublishFailure(t *testing.T) { + var buffer StreamUsageBuffer + buffer.Observe(usage.Detail{InputTokens: 10, OutputTokens: 5, TotalTokens: 15}, true) + + reporter := &UsageReporter{ + provider: "openai", + model: "gpt-5.4", + } + + record := reporter.buildRecord(buffer.detail, true, failFromErrors(context.Canceled)) + if !record.Failed { + t.Fatal("expected record to be marked failed") + } + if record.Fail.StatusCode != clienterror.StatusClientClosedRequest { + t.Fatalf("Fail.StatusCode = %d, want %d", record.Fail.StatusCode, clienterror.StatusClientClosedRequest) + } + if record.Detail.TotalTokens != 15 { + t.Fatalf("Detail.TotalTokens = %d, want 15", record.Detail.TotalTokens) + } +} + type roundTripFunc func(*http.Request) (*http.Response, error) func (f roundTripFunc) RoundTrip(req *http.Request) (*http.Response, error) {