chore: import upstream snapshot with attribution

This commit is contained in:
wehub-resource-sync
2026-07-13 12:35:43 +08:00
commit 0e2cc6b102
927 changed files with 260929 additions and 0 deletions
+245
View File
@@ -0,0 +1,245 @@
// Package middleware provides HTTP middleware components for the CLI Proxy API server.
// This file contains the request logging middleware that captures comprehensive
// request and response data when enabled through configuration.
package middleware
import (
"bytes"
"fmt"
"io"
"net/http"
"strings"
"time"
"github.com/gin-gonic/gin"
"github.com/klauspost/compress/zstd"
"github.com/router-for-me/CLIProxyAPI/v7/internal/logging"
"github.com/router-for-me/CLIProxyAPI/v7/internal/util"
)
const maxErrorOnlyCapturedRequestBodyBytes int64 = 1 << 20 // 1 MiB
// RequestLoggingMiddleware creates a Gin middleware that logs HTTP requests and responses.
// It captures detailed information about the request and response, including headers and body,
// and uses the provided RequestLogger to record this data. When full request logging is disabled,
// body capture is limited to small known-size payloads to avoid large per-request memory spikes.
func RequestLoggingMiddleware(logger logging.RequestLogger) gin.HandlerFunc {
return func(c *gin.Context) {
if logger == nil {
c.Next()
return
}
if shouldSkipMethodForRequestLogging(c.Request) {
c.Next()
return
}
path := c.Request.URL.Path
if !shouldLogRequest(path) {
c.Next()
return
}
loggerEnabled := logger.IsEnabled()
// Capture request information
requestInfo, err := captureRequestInfo(c, shouldCaptureRequestBody(loggerEnabled, c.Request))
if err != nil {
// Log error but continue processing
// In a real implementation, you might want to use a proper logger here
c.Next()
return
}
// Create response writer wrapper
wrapper := NewResponseWriterWrapper(c.Writer, logger, requestInfo)
if !loggerEnabled {
wrapper.logOnErrorOnly = true
}
c.Writer = wrapper
attachRequestLogSources(c, logger, loggerEnabled)
// Process the request
c.Next()
// Finalize logging after request processing
if err = wrapper.Finalize(c); err != nil {
// Log error but don't interrupt the response
// In a real implementation, you might want to use a proper logger here
}
}
}
type fileBodySourceFactory interface {
NewFileBodySource(prefix string) (*logging.FileBodySource, error)
}
func attachRequestLogSources(c *gin.Context, logger logging.RequestLogger, loggerEnabled bool) {
if c == nil || !loggerEnabled {
return
}
factory, ok := logger.(fileBodySourceFactory)
if !ok || factory == nil {
return
}
if source, errSource := factory.NewFileBodySource("api-request"); errSource == nil {
c.Set(logging.APIRequestSourceContextKey, source)
}
if source, errSource := factory.NewFileBodySource("api-response"); errSource == nil {
c.Set(logging.APIResponseSourceContextKey, source)
}
if !isResponsesWebsocketUpgrade(c.Request) {
return
}
if source, errSource := factory.NewFileBodySource("websocket-timeline"); errSource == nil {
c.Set(logging.WebsocketTimelineSourceContextKey, source)
}
if source, errSource := factory.NewFileBodySource("api-websocket-timeline"); errSource == nil {
c.Set(logging.APIWebsocketTimelineSourceContextKey, source)
}
}
func shouldSkipMethodForRequestLogging(req *http.Request) bool {
if req == nil {
return true
}
if req.Method != http.MethodGet {
return false
}
return !isResponsesWebsocketUpgrade(req)
}
func isResponsesWebsocketUpgrade(req *http.Request) bool {
if req == nil || req.URL == nil {
return false
}
if req.URL.Path != "/v1/responses" && req.URL.Path != "/backend-api/codex/responses" {
return false
}
return strings.EqualFold(strings.TrimSpace(req.Header.Get("Upgrade")), "websocket")
}
func shouldCaptureRequestBody(loggerEnabled bool, req *http.Request) bool {
if loggerEnabled {
return true
}
if req == nil || req.Body == nil {
return false
}
contentType := strings.ToLower(strings.TrimSpace(req.Header.Get("Content-Type")))
if strings.HasPrefix(contentType, "multipart/form-data") {
return false
}
if req.ContentLength <= 0 {
return false
}
return req.ContentLength <= maxErrorOnlyCapturedRequestBodyBytes
}
// captureRequestInfo extracts relevant information from the incoming HTTP request.
// It captures the URL, method, headers, and body. The request body is read and then
// restored so that it can be processed by subsequent handlers.
func captureRequestInfo(c *gin.Context, captureBody bool) (*RequestInfo, error) {
// Capture URL with sensitive query parameters masked
maskedQuery := util.MaskSensitiveQuery(c.Request.URL.RawQuery)
url := c.Request.URL.Path
if maskedQuery != "" {
url += "?" + maskedQuery
}
// Capture method
method := c.Request.Method
// Capture headers
headers := make(map[string][]string)
for key, values := range c.Request.Header {
headers[key] = values
}
// Capture request body
var body []byte
if captureBody && c.Request.Body != nil {
// Read the body
bodyBytes, err := io.ReadAll(c.Request.Body)
if err != nil {
return nil, err
}
// Restore the body for the actual request processing
c.Request.Body = io.NopCloser(bytes.NewBuffer(bodyBytes))
body = decodeCapturedRequestBodyForLog(bodyBytes, c.Request.Header.Get("Content-Encoding"))
}
return &RequestInfo{
URL: url,
Method: method,
Headers: headers,
Body: body,
RequestID: logging.GetGinRequestID(c),
Timestamp: time.Now(),
}, nil
}
func decodeCapturedRequestBodyForLog(raw []byte, encoding string) []byte {
if len(raw) == 0 {
return raw
}
decoded, errDecode := decodeCapturedRequestBody(raw, encoding)
if errDecode != nil {
return raw
}
return decoded
}
func decodeCapturedRequestBody(raw []byte, encoding string) ([]byte, error) {
encoding = strings.TrimSpace(encoding)
if encoding == "" || strings.EqualFold(encoding, "identity") {
return raw, nil
}
parts := strings.Split(encoding, ",")
body := raw
for i := len(parts) - 1; i >= 0; i-- {
enc := strings.ToLower(strings.TrimSpace(parts[i]))
switch enc {
case "", "identity":
continue
case "zstd":
decoded, errDecode := decodeCapturedZstdRequestBody(body)
if errDecode != nil {
return nil, errDecode
}
body = decoded
default:
return nil, fmt.Errorf("unsupported request content encoding: %s", enc)
}
}
return body, nil
}
func decodeCapturedZstdRequestBody(raw []byte) ([]byte, error) {
decoder, errNewReader := zstd.NewReader(bytes.NewReader(raw))
if errNewReader != nil {
return nil, fmt.Errorf("failed to create zstd request decoder: %w", errNewReader)
}
defer decoder.Close()
decoded, errRead := io.ReadAll(decoder)
if errRead != nil {
return nil, fmt.Errorf("failed to decode zstd request body: %w", errRead)
}
return decoded, nil
}
// shouldLogRequest determines whether the request should be logged.
// It skips management endpoints to avoid leaking secrets but allows
// all other routes, including module-provided ones, to honor request-log.
func shouldLogRequest(path string) bool {
if strings.HasPrefix(path, "/v0/management") || strings.HasPrefix(path, "/management") {
return false
}
return true
}
@@ -0,0 +1,251 @@
package middleware
import (
"bytes"
"io"
"net/http"
"net/http/httptest"
"net/url"
"os"
"strings"
"testing"
"github.com/gin-gonic/gin"
"github.com/klauspost/compress/zstd"
"github.com/router-for-me/CLIProxyAPI/v7/internal/logging"
)
func TestShouldSkipMethodForRequestLogging(t *testing.T) {
tests := []struct {
name string
req *http.Request
skip bool
}{
{
name: "nil request",
req: nil,
skip: true,
},
{
name: "post request should not skip",
req: &http.Request{
Method: http.MethodPost,
URL: &url.URL{Path: "/v1/responses"},
},
skip: false,
},
{
name: "plain get should skip",
req: &http.Request{
Method: http.MethodGet,
URL: &url.URL{Path: "/v1/models"},
Header: http.Header{},
},
skip: true,
},
{
name: "responses websocket upgrade should not skip",
req: &http.Request{
Method: http.MethodGet,
URL: &url.URL{Path: "/v1/responses"},
Header: http.Header{"Upgrade": []string{"websocket"}},
},
skip: false,
},
{
name: "codex responses websocket upgrade should not skip",
req: &http.Request{
Method: http.MethodGet,
URL: &url.URL{Path: "/backend-api/codex/responses"},
Header: http.Header{"Upgrade": []string{"websocket"}},
},
skip: false,
},
{
name: "responses get without upgrade should skip",
req: &http.Request{
Method: http.MethodGet,
URL: &url.URL{Path: "/v1/responses"},
Header: http.Header{},
},
skip: true,
},
}
for i := range tests {
got := shouldSkipMethodForRequestLogging(tests[i].req)
if got != tests[i].skip {
t.Fatalf("%s: got skip=%t, want %t", tests[i].name, got, tests[i].skip)
}
}
}
func TestShouldCaptureRequestBody(t *testing.T) {
tests := []struct {
name string
loggerEnabled bool
req *http.Request
want bool
}{
{
name: "logger enabled always captures",
loggerEnabled: true,
req: &http.Request{
Body: io.NopCloser(strings.NewReader("{}")),
ContentLength: -1,
Header: http.Header{"Content-Type": []string{"application/json"}},
},
want: true,
},
{
name: "nil request",
loggerEnabled: false,
req: nil,
want: false,
},
{
name: "small known size json in error-only mode",
loggerEnabled: false,
req: &http.Request{
Body: io.NopCloser(strings.NewReader("{}")),
ContentLength: 2,
Header: http.Header{"Content-Type": []string{"application/json"}},
},
want: true,
},
{
name: "large known size skipped in error-only mode",
loggerEnabled: false,
req: &http.Request{
Body: io.NopCloser(strings.NewReader("x")),
ContentLength: maxErrorOnlyCapturedRequestBodyBytes + 1,
Header: http.Header{"Content-Type": []string{"application/json"}},
},
want: false,
},
{
name: "unknown size skipped in error-only mode",
loggerEnabled: false,
req: &http.Request{
Body: io.NopCloser(strings.NewReader("x")),
ContentLength: -1,
Header: http.Header{"Content-Type": []string{"application/json"}},
},
want: false,
},
{
name: "multipart skipped in error-only mode",
loggerEnabled: false,
req: &http.Request{
Body: io.NopCloser(strings.NewReader("x")),
ContentLength: 1,
Header: http.Header{"Content-Type": []string{"multipart/form-data; boundary=abc"}},
},
want: false,
},
}
for i := range tests {
got := shouldCaptureRequestBody(tests[i].loggerEnabled, tests[i].req)
if got != tests[i].want {
t.Fatalf("%s: got %t, want %t", tests[i].name, got, tests[i].want)
}
}
}
func TestAttachRequestLogSourcesUsesLoggerLogsDir(t *testing.T) {
gin.SetMode(gin.TestMode)
logsDir := t.TempDir()
logger := logging.NewFileRequestLogger(true, logsDir, "", 0)
recorder := httptest.NewRecorder()
c, _ := gin.CreateTestContext(recorder)
c.Request = httptest.NewRequest(http.MethodGet, "/backend-api/codex/responses", nil)
c.Request.Header.Set("Upgrade", "websocket")
attachRequestLogSources(c, logger, true)
defer cleanupFileBodySourcesFromContext(c)
for _, key := range []string{
logging.WebsocketTimelineSourceContextKey,
logging.APIWebsocketTimelineSourceContextKey,
} {
value, exists := c.Get(key)
if !exists {
t.Fatalf("expected %s source to be attached", key)
}
source, ok := value.(*logging.FileBodySource)
if !ok || source == nil {
t.Fatalf("%s source type = %T", key, value)
}
file, errPart := source.CreatePart("probe")
if errPart != nil {
t.Fatalf("CreatePart(%s): %v", key, errPart)
}
path := file.Name()
if errClose := file.Close(); errClose != nil {
t.Fatalf("close part: %v", errClose)
}
if !strings.HasPrefix(path, logsDir+string(os.PathSeparator)) {
t.Fatalf("%s part path %s is not under logs dir %s", key, path, logsDir)
}
}
}
func cleanupFileBodySourcesFromContext(c *gin.Context) {
if c == nil {
return
}
for _, key := range []string{
logging.WebsocketTimelineSourceContextKey,
logging.APIWebsocketTimelineSourceContextKey,
} {
value, exists := c.Get(key)
if !exists {
continue
}
if source, ok := value.(*logging.FileBodySource); ok && source != nil {
_ = source.Cleanup()
}
}
}
func TestCaptureRequestInfoDecodesZstdRequestBodyForLog(t *testing.T) {
gin.SetMode(gin.TestMode)
payload := []byte(`{"model":"test-model","stream":true}`)
var compressed bytes.Buffer
encoder, errNewWriter := zstd.NewWriter(&compressed)
if errNewWriter != nil {
t.Fatalf("zstd.NewWriter: %v", errNewWriter)
}
if _, errWrite := encoder.Write(payload); errWrite != nil {
t.Fatalf("zstd write: %v", errWrite)
}
if errClose := encoder.Close(); errClose != nil {
t.Fatalf("zstd close: %v", errClose)
}
compressedBytes := compressed.Bytes()
recorder := httptest.NewRecorder()
c, _ := gin.CreateTestContext(recorder)
req := httptest.NewRequest(http.MethodPost, "/v1/responses", bytes.NewReader(compressedBytes))
req.Header.Set("Content-Encoding", "zstd")
c.Request = req
info, errCapture := captureRequestInfo(c, true)
if errCapture != nil {
t.Fatalf("captureRequestInfo: %v", errCapture)
}
if !bytes.Equal(info.Body, payload) {
t.Fatalf("logged request body = %q, want %q", string(info.Body), string(payload))
}
restoredBody, errRead := io.ReadAll(c.Request.Body)
if errRead != nil {
t.Fatalf("read restored request body: %v", errRead)
}
if !bytes.Equal(restoredBody, compressedBytes) {
t.Fatal("request body was not restored with the original compressed bytes")
}
}
+666
View File
@@ -0,0 +1,666 @@
// Package middleware provides Gin HTTP middleware for the CLI Proxy API server.
// It includes a sophisticated response writer wrapper designed to capture and log request and response data,
// including support for streaming responses, without impacting latency.
package middleware
import (
"bytes"
"net/http"
"strings"
"time"
"github.com/gin-gonic/gin"
"github.com/router-for-me/CLIProxyAPI/v7/internal/interfaces"
"github.com/router-for-me/CLIProxyAPI/v7/internal/logging"
log "github.com/sirupsen/logrus"
)
const requestBodyOverrideContextKey = "REQUEST_BODY_OVERRIDE"
const responseBodyOverrideContextKey = "RESPONSE_BODY_OVERRIDE"
const websocketTimelineOverrideContextKey = "WEBSOCKET_TIMELINE_OVERRIDE"
// RequestInfo holds essential details of an incoming HTTP request for logging purposes.
type RequestInfo struct {
URL string // URL is the request URL.
Method string // Method is the HTTP method (e.g., GET, POST).
Headers map[string][]string // Headers contains the request headers.
Body []byte // Body is the raw request body.
RequestID string // RequestID is the unique identifier for the request.
Timestamp time.Time // Timestamp is when the request was received.
}
// ResponseWriterWrapper wraps the standard gin.ResponseWriter to intercept and log response data.
// It is designed to handle both standard and streaming responses, ensuring that logging operations do not block the client response.
type ResponseWriterWrapper struct {
gin.ResponseWriter
body *bytes.Buffer // body is a buffer to store the response body for non-streaming responses.
isStreaming bool // isStreaming indicates whether the response is a streaming type (e.g., text/event-stream).
streamWriter logging.StreamingLogWriter // streamWriter is a writer for handling streaming log entries.
chunkChannel chan []byte // chunkChannel is a channel for asynchronously passing response chunks to the logger.
streamDone chan struct{} // streamDone signals when the streaming goroutine completes.
logger logging.RequestLogger // logger is the instance of the request logger service.
requestInfo *RequestInfo // requestInfo holds the details of the original request.
statusCode int // statusCode stores the HTTP status code of the response.
headers map[string][]string // headers stores the response headers.
logOnErrorOnly bool // logOnErrorOnly enables logging only when an error response is detected.
firstChunkTimestamp time.Time // firstChunkTimestamp captures TTFB for streaming responses.
}
// NewResponseWriterWrapper creates and initializes a new ResponseWriterWrapper.
// It takes the original gin.ResponseWriter, a logger instance, and request information.
//
// Parameters:
// - w: The original gin.ResponseWriter to wrap.
// - logger: The logging service to use for recording requests.
// - requestInfo: The pre-captured information about the incoming request.
//
// Returns:
// - A pointer to a new ResponseWriterWrapper.
func NewResponseWriterWrapper(w gin.ResponseWriter, logger logging.RequestLogger, requestInfo *RequestInfo) *ResponseWriterWrapper {
return &ResponseWriterWrapper{
ResponseWriter: w,
body: &bytes.Buffer{},
logger: logger,
requestInfo: requestInfo,
headers: make(map[string][]string),
}
}
// Write wraps the underlying ResponseWriter's Write method to capture response data.
// For non-streaming responses, it writes to an internal buffer. For streaming responses,
// it sends data chunks to a non-blocking channel for asynchronous logging.
// CRITICAL: This method prioritizes writing to the client to ensure zero latency,
// handling logging operations subsequently.
func (w *ResponseWriterWrapper) Write(data []byte) (int, error) {
// Ensure headers are captured before first write
// This is critical because Write() may trigger WriteHeader() internally
w.ensureHeadersCaptured()
// CRITICAL: Write to client first (zero latency)
n, err := w.ResponseWriter.Write(data)
// THEN: Handle logging based on response type
if w.isStreaming && w.chunkChannel != nil {
// Capture TTFB on first chunk (synchronous, before async channel send)
if w.firstChunkTimestamp.IsZero() {
w.firstChunkTimestamp = time.Now()
}
// For streaming responses: Send to async logging channel (non-blocking)
select {
case w.chunkChannel <- append([]byte(nil), data...): // Non-blocking send with copy
default: // Channel full, skip logging to avoid blocking
}
return n, err
}
if w.shouldBufferResponseBody() {
w.body.Write(data)
}
return n, err
}
func (w *ResponseWriterWrapper) shouldBufferResponseBody() bool {
if w.logger != nil && w.logger.IsEnabled() {
return true
}
if !w.logOnErrorOnly {
return false
}
status := w.statusCode
if status == 0 {
if statusWriter, ok := w.ResponseWriter.(interface{ Status() int }); ok && statusWriter != nil {
status = statusWriter.Status()
} else {
status = http.StatusOK
}
}
return status >= http.StatusBadRequest
}
// WriteString wraps the underlying ResponseWriter's WriteString method to capture response data.
// Some handlers (and fmt/io helpers) write via io.StringWriter; without this override, those writes
// bypass Write() and would be missing from request logs.
func (w *ResponseWriterWrapper) WriteString(data string) (int, error) {
w.ensureHeadersCaptured()
// CRITICAL: Write to client first (zero latency)
n, err := w.ResponseWriter.WriteString(data)
// THEN: Capture for logging
if w.isStreaming && w.chunkChannel != nil {
// Capture TTFB on first chunk (synchronous, before async channel send)
if w.firstChunkTimestamp.IsZero() {
w.firstChunkTimestamp = time.Now()
}
select {
case w.chunkChannel <- []byte(data):
default:
}
return n, err
}
if w.shouldBufferResponseBody() {
w.body.WriteString(data)
}
return n, err
}
// WriteHeader wraps the underlying ResponseWriter's WriteHeader method.
// It captures the status code, detects if the response is streaming based on the Content-Type header,
// and initializes the appropriate logging mechanism (standard or streaming).
func (w *ResponseWriterWrapper) WriteHeader(statusCode int) {
w.statusCode = statusCode
// Capture response headers using the new method
w.captureCurrentHeaders()
// Detect streaming based on Content-Type
contentType := w.ResponseWriter.Header().Get("Content-Type")
w.isStreaming = w.detectStreaming(contentType)
// If streaming, initialize streaming log writer
if w.isStreaming && w.logger.IsEnabled() {
streamWriter, err := w.logger.LogStreamingRequest(
w.requestInfo.URL,
w.requestInfo.Method,
w.requestInfo.Headers,
w.requestInfo.Body,
w.requestInfo.RequestID,
)
if err == nil {
w.streamWriter = streamWriter
w.chunkChannel = make(chan []byte, 100) // Buffered channel for async writes
doneChan := make(chan struct{})
w.streamDone = doneChan
// Start async chunk processor
go w.processStreamingChunks(doneChan)
// Write status immediately
_ = streamWriter.WriteStatus(statusCode, w.headers)
}
}
// Call original WriteHeader
w.ResponseWriter.WriteHeader(statusCode)
}
// ensureHeadersCaptured is a helper function to make sure response headers are captured.
// It is safe to call this method multiple times; it will always refresh the headers
// with the latest state from the underlying ResponseWriter.
func (w *ResponseWriterWrapper) ensureHeadersCaptured() {
// Always capture the current headers to ensure we have the latest state
w.captureCurrentHeaders()
}
// captureCurrentHeaders reads all headers from the underlying ResponseWriter and stores them
// in the wrapper's headers map. It creates copies of the header values to prevent race conditions.
func (w *ResponseWriterWrapper) captureCurrentHeaders() {
// Initialize headers map if needed
if w.headers == nil {
w.headers = make(map[string][]string)
}
// Capture all current headers from the underlying ResponseWriter
for key, values := range w.ResponseWriter.Header() {
// Make a copy of the values slice to avoid reference issues
headerValues := make([]string, len(values))
copy(headerValues, values)
w.headers[key] = headerValues
}
}
// detectStreaming determines if a response should be treated as a streaming response.
// It checks for a "text/event-stream" Content-Type or a '"stream": true'
// field in the original request body.
func (w *ResponseWriterWrapper) detectStreaming(contentType string) bool {
// Check Content-Type for Server-Sent Events
if strings.Contains(contentType, "text/event-stream") {
return true
}
// If a concrete Content-Type is already set (e.g., application/json for error responses),
// treat it as non-streaming instead of inferring from the request payload.
if strings.TrimSpace(contentType) != "" {
return false
}
// Only fall back to request payload hints when Content-Type is not set yet.
if w.requestInfo != nil && len(w.requestInfo.Body) > 0 {
return bytes.Contains(w.requestInfo.Body, []byte(`"stream": true`)) ||
bytes.Contains(w.requestInfo.Body, []byte(`"stream":true`))
}
return false
}
// processStreamingChunks runs in a separate goroutine to process response chunks from the chunkChannel.
// It asynchronously writes each chunk to the streaming log writer.
func (w *ResponseWriterWrapper) processStreamingChunks(done chan struct{}) {
if done == nil {
return
}
defer close(done)
if w.streamWriter == nil || w.chunkChannel == nil {
return
}
for chunk := range w.chunkChannel {
w.streamWriter.WriteChunkAsync(chunk)
}
}
// Finalize completes the logging process for the request and response.
// For streaming responses, it closes the chunk channel and the stream writer.
// For non-streaming responses, it logs the complete request and response details,
// including any API-specific request/response data stored in the Gin context.
func (w *ResponseWriterWrapper) Finalize(c *gin.Context) error {
if w.logger == nil {
return nil
}
finalStatusCode := w.statusCode
if finalStatusCode == 0 {
if statusWriter, ok := w.ResponseWriter.(interface{ Status() int }); ok {
finalStatusCode = statusWriter.Status()
} else {
finalStatusCode = 200
}
}
var slicesAPIResponseError []*interfaces.ErrorMessage
apiResponseError, isExist := c.Get("API_RESPONSE_ERROR")
if isExist {
if apiErrors, ok := apiResponseError.([]*interfaces.ErrorMessage); ok {
slicesAPIResponseError = apiErrors
}
}
hasAPIError := len(slicesAPIResponseError) > 0 || finalStatusCode >= http.StatusBadRequest
forceLog := w.logOnErrorOnly && hasAPIError && !w.logger.IsEnabled()
websocketTimelineSource := w.extractWebsocketTimelineSource(c)
apiRequestSource := w.extractAPIRequestSource(c)
apiResponseSource := w.extractAPIResponseSource(c)
apiWebsocketTimelineSource := w.extractAPIWebsocketTimelineSource(c)
if !w.logger.IsEnabled() && !forceLog {
cleanupFileBodySources(websocketTimelineSource, apiRequestSource, apiResponseSource, apiWebsocketTimelineSource)
return nil
}
if w.isStreaming && w.streamWriter != nil {
if w.chunkChannel != nil {
close(w.chunkChannel)
w.chunkChannel = nil
}
if w.streamDone != nil {
<-w.streamDone
w.streamDone = nil
}
w.streamWriter.SetFirstChunkTimestamp(w.firstChunkTimestamp)
// Write API Request and Response to the streaming log before closing
apiRequest := w.extractAPIRequest(c)
apiResponse := w.extractAPIResponse(c)
if sourceWriter, ok := w.streamWriter.(interface {
WriteAPIRequestSource(*logging.FileBodySource) error
WriteAPIResponseSource(*logging.FileBodySource) error
}); ok {
if len(apiRequest) > 0 {
_ = w.streamWriter.WriteAPIRequest(apiRequest)
}
if apiRequestSource != nil && apiRequestSource.HasPayload() {
_ = sourceWriter.WriteAPIRequestSource(apiRequestSource)
}
if len(apiResponse) > 0 {
_ = w.streamWriter.WriteAPIResponse(apiResponse)
}
if apiResponseSource != nil && apiResponseSource.HasPayload() {
_ = sourceWriter.WriteAPIResponseSource(apiResponseSource)
}
} else {
var errMerge error
apiRequest, errMerge = mergeFileBodySource(apiRequest, apiRequestSource)
if errMerge != nil {
cleanupFileBodySources(websocketTimelineSource, apiResponseSource, apiWebsocketTimelineSource)
return errMerge
}
apiResponse, errMerge = mergeFileBodySource(apiResponse, apiResponseSource)
if errMerge != nil {
cleanupFileBodySources(websocketTimelineSource, apiWebsocketTimelineSource)
return errMerge
}
if len(apiRequest) > 0 {
_ = w.streamWriter.WriteAPIRequest(apiRequest)
}
if len(apiResponse) > 0 {
_ = w.streamWriter.WriteAPIResponse(apiResponse)
}
}
apiWebsocketTimeline := w.extractAPIWebsocketTimeline(c)
var errMerge error
apiWebsocketTimeline, errMerge = mergeFileBodySource(apiWebsocketTimeline, apiWebsocketTimelineSource)
if errMerge != nil {
cleanupFileBodySources(websocketTimelineSource, apiRequestSource, apiResponseSource)
return errMerge
}
if len(apiWebsocketTimeline) > 0 {
_ = w.streamWriter.WriteAPIWebsocketTimeline(apiWebsocketTimeline)
}
if err := w.streamWriter.Close(); err != nil {
w.streamWriter = nil
cleanupFileBodySources(websocketTimelineSource, apiRequestSource, apiResponseSource)
return err
}
w.streamWriter = nil
cleanupFileBodySources(websocketTimelineSource, apiRequestSource, apiResponseSource)
return nil
}
return w.logRequest(w.extractRequestBody(c), finalStatusCode, w.cloneHeaders(), w.extractResponseBody(c), w.extractWebsocketTimeline(c), websocketTimelineSource, w.extractAPIRequest(c), apiRequestSource, w.extractAPIResponse(c), apiResponseSource, w.extractAPIWebsocketTimeline(c), apiWebsocketTimelineSource, w.extractAPIResponseTimestamp(c), slicesAPIResponseError, forceLog)
}
func (w *ResponseWriterWrapper) cloneHeaders() map[string][]string {
w.ensureHeadersCaptured()
finalHeaders := make(map[string][]string, len(w.headers))
for key, values := range w.headers {
headerValues := make([]string, len(values))
copy(headerValues, values)
finalHeaders[key] = headerValues
}
return finalHeaders
}
func (w *ResponseWriterWrapper) extractAPIRequest(c *gin.Context) []byte {
apiRequest, isExist := c.Get("API_REQUEST")
if !isExist {
return nil
}
data, ok := apiRequest.([]byte)
if !ok || len(data) == 0 {
return nil
}
return data
}
func (w *ResponseWriterWrapper) extractAPIResponse(c *gin.Context) []byte {
apiResponse, isExist := c.Get("API_RESPONSE")
if !isExist {
return nil
}
data, ok := apiResponse.([]byte)
if !ok || len(data) == 0 {
return nil
}
return data
}
func (w *ResponseWriterWrapper) extractAPIRequestSource(c *gin.Context) *logging.FileBodySource {
return extractFileBodySource(c, logging.APIRequestSourceContextKey)
}
func (w *ResponseWriterWrapper) extractAPIResponseSource(c *gin.Context) *logging.FileBodySource {
return extractFileBodySource(c, logging.APIResponseSourceContextKey)
}
func (w *ResponseWriterWrapper) extractAPIWebsocketTimeline(c *gin.Context) []byte {
apiTimeline, isExist := c.Get("API_WEBSOCKET_TIMELINE")
if !isExist {
return nil
}
data, ok := apiTimeline.([]byte)
if !ok || len(data) == 0 {
return nil
}
return bytes.Clone(data)
}
func (w *ResponseWriterWrapper) extractAPIWebsocketTimelineSource(c *gin.Context) *logging.FileBodySource {
return extractFileBodySource(c, logging.APIWebsocketTimelineSourceContextKey)
}
func (w *ResponseWriterWrapper) extractAPIResponseTimestamp(c *gin.Context) time.Time {
ts, isExist := c.Get("API_RESPONSE_TIMESTAMP")
if !isExist {
return time.Time{}
}
if t, ok := ts.(time.Time); ok {
return t
}
return time.Time{}
}
func (w *ResponseWriterWrapper) extractRequestBody(c *gin.Context) []byte {
if body := extractBodyOverride(c, requestBodyOverrideContextKey); len(body) > 0 {
return body
}
if w.requestInfo != nil && len(w.requestInfo.Body) > 0 {
return w.requestInfo.Body
}
return nil
}
func (w *ResponseWriterWrapper) extractResponseBody(c *gin.Context) []byte {
if body := extractBodyOverride(c, responseBodyOverrideContextKey); len(body) > 0 {
return body
}
if w.body == nil || w.body.Len() == 0 {
return nil
}
return bytes.Clone(w.body.Bytes())
}
func (w *ResponseWriterWrapper) extractWebsocketTimeline(c *gin.Context) []byte {
return extractBodyOverride(c, websocketTimelineOverrideContextKey)
}
func (w *ResponseWriterWrapper) extractWebsocketTimelineSource(c *gin.Context) *logging.FileBodySource {
return extractFileBodySource(c, logging.WebsocketTimelineSourceContextKey)
}
func extractFileBodySource(c *gin.Context, key string) *logging.FileBodySource {
if c == nil {
return nil
}
value, exists := c.Get(key)
if !exists {
return nil
}
source, ok := value.(*logging.FileBodySource)
if !ok || source == nil {
return nil
}
return source
}
func extractBodyOverride(c *gin.Context, key string) []byte {
if c == nil {
return nil
}
bodyOverride, isExist := c.Get(key)
if !isExist {
return nil
}
switch value := bodyOverride.(type) {
case []byte:
if len(value) > 0 {
return bytes.Clone(value)
}
case string:
if strings.TrimSpace(value) != "" {
return []byte(value)
}
}
return nil
}
func (w *ResponseWriterWrapper) logRequest(requestBody []byte, statusCode int, headers map[string][]string, body, websocketTimeline []byte, websocketTimelineSource *logging.FileBodySource, apiRequestBody []byte, apiRequestSource *logging.FileBodySource, apiResponseBody []byte, apiResponseSource *logging.FileBodySource, apiWebsocketTimeline []byte, apiWebsocketTimelineSource *logging.FileBodySource, apiResponseTimestamp time.Time, apiResponseErrors []*interfaces.ErrorMessage, forceLog bool) error {
if w.requestInfo == nil {
cleanupFileBodySources(websocketTimelineSource, apiRequestSource, apiResponseSource, apiWebsocketTimelineSource)
return nil
}
if loggerWithAllSources, ok := w.logger.(interface {
LogRequestWithOptionsAndAllSources(string, string, map[string][]string, []byte, int, map[string][]string, []byte, []byte, *logging.FileBodySource, []byte, *logging.FileBodySource, []byte, *logging.FileBodySource, []byte, *logging.FileBodySource, []*interfaces.ErrorMessage, bool, string, time.Time, time.Time) error
}); ok {
return loggerWithAllSources.LogRequestWithOptionsAndAllSources(
w.requestInfo.URL,
w.requestInfo.Method,
w.requestInfo.Headers,
requestBody,
statusCode,
headers,
body,
websocketTimeline,
websocketTimelineSource,
apiRequestBody,
apiRequestSource,
apiResponseBody,
apiResponseSource,
apiWebsocketTimeline,
apiWebsocketTimelineSource,
apiResponseErrors,
forceLog,
w.requestInfo.RequestID,
w.requestInfo.Timestamp,
apiResponseTimestamp,
)
}
if loggerWithSources, ok := w.logger.(interface {
LogRequestWithOptionsAndSources(string, string, map[string][]string, []byte, int, map[string][]string, []byte, []byte, *logging.FileBodySource, []byte, []byte, []byte, *logging.FileBodySource, []*interfaces.ErrorMessage, bool, string, time.Time, time.Time) error
}); ok {
var errMerge error
apiRequestBody, errMerge = mergeFileBodySource(apiRequestBody, apiRequestSource)
if errMerge != nil {
cleanupFileBodySources(websocketTimelineSource, apiResponseSource, apiWebsocketTimelineSource)
return errMerge
}
apiResponseBody, errMerge = mergeFileBodySource(apiResponseBody, apiResponseSource)
if errMerge != nil {
cleanupFileBodySources(websocketTimelineSource, apiWebsocketTimelineSource)
return errMerge
}
return loggerWithSources.LogRequestWithOptionsAndSources(
w.requestInfo.URL,
w.requestInfo.Method,
w.requestInfo.Headers,
requestBody,
statusCode,
headers,
body,
websocketTimeline,
websocketTimelineSource,
apiRequestBody,
apiResponseBody,
apiWebsocketTimeline,
apiWebsocketTimelineSource,
apiResponseErrors,
forceLog,
w.requestInfo.RequestID,
w.requestInfo.Timestamp,
apiResponseTimestamp,
)
}
var errMerge error
websocketTimeline, errMerge = mergeFileBodySource(websocketTimeline, websocketTimelineSource)
if errMerge != nil {
cleanupFileBodySources(apiRequestSource, apiResponseSource, apiWebsocketTimelineSource)
return errMerge
}
apiRequestBody, errMerge = mergeFileBodySource(apiRequestBody, apiRequestSource)
if errMerge != nil {
cleanupFileBodySources(apiResponseSource, apiWebsocketTimelineSource)
return errMerge
}
apiResponseBody, errMerge = mergeFileBodySource(apiResponseBody, apiResponseSource)
if errMerge != nil {
cleanupFileBodySources(apiWebsocketTimelineSource)
return errMerge
}
apiWebsocketTimeline, errMerge = mergeFileBodySource(apiWebsocketTimeline, apiWebsocketTimelineSource)
if errMerge != nil {
return errMerge
}
if loggerWithOptions, ok := w.logger.(interface {
LogRequestWithOptions(string, string, map[string][]string, []byte, int, map[string][]string, []byte, []byte, []byte, []byte, []byte, []*interfaces.ErrorMessage, bool, string, time.Time, time.Time) error
}); ok {
return loggerWithOptions.LogRequestWithOptions(
w.requestInfo.URL,
w.requestInfo.Method,
w.requestInfo.Headers,
requestBody,
statusCode,
headers,
body,
websocketTimeline,
apiRequestBody,
apiResponseBody,
apiWebsocketTimeline,
apiResponseErrors,
forceLog,
w.requestInfo.RequestID,
w.requestInfo.Timestamp,
apiResponseTimestamp,
)
}
return w.logger.LogRequest(
w.requestInfo.URL,
w.requestInfo.Method,
w.requestInfo.Headers,
requestBody,
statusCode,
headers,
body,
websocketTimeline,
apiRequestBody,
apiResponseBody,
apiWebsocketTimeline,
apiResponseErrors,
w.requestInfo.RequestID,
w.requestInfo.Timestamp,
apiResponseTimestamp,
)
}
func mergeFileBodySource(payload []byte, source *logging.FileBodySource) ([]byte, error) {
if source == nil {
return payload, nil
}
defer cleanupFileBodySources(source)
if !source.HasPayload() {
return payload, nil
}
var buf bytes.Buffer
if len(payload) > 0 {
buf.Write(payload)
if !bytes.HasSuffix(payload, []byte("\n")) {
buf.WriteByte('\n')
}
buf.WriteByte('\n')
}
if errWrite := source.WriteTo(&buf); errWrite != nil {
return nil, errWrite
}
return buf.Bytes(), nil
}
func cleanupFileBodySources(sources ...*logging.FileBodySource) {
for _, source := range sources {
if source == nil {
continue
}
if errCleanup := source.Cleanup(); errCleanup != nil {
log.WithError(errCleanup).Warn("failed to clean up log part files")
}
}
}
@@ -0,0 +1,202 @@
package middleware
import (
"bytes"
"net/http/httptest"
"testing"
"time"
"github.com/gin-gonic/gin"
"github.com/router-for-me/CLIProxyAPI/v7/internal/interfaces"
"github.com/router-for-me/CLIProxyAPI/v7/internal/logging"
)
func TestExtractRequestBodyPrefersOverride(t *testing.T) {
gin.SetMode(gin.TestMode)
recorder := httptest.NewRecorder()
c, _ := gin.CreateTestContext(recorder)
wrapper := &ResponseWriterWrapper{
requestInfo: &RequestInfo{Body: []byte("original-body")},
}
body := wrapper.extractRequestBody(c)
if string(body) != "original-body" {
t.Fatalf("request body = %q, want %q", string(body), "original-body")
}
c.Set(requestBodyOverrideContextKey, []byte("override-body"))
body = wrapper.extractRequestBody(c)
if string(body) != "override-body" {
t.Fatalf("request body = %q, want %q", string(body), "override-body")
}
}
func TestExtractRequestBodySupportsStringOverride(t *testing.T) {
gin.SetMode(gin.TestMode)
recorder := httptest.NewRecorder()
c, _ := gin.CreateTestContext(recorder)
wrapper := &ResponseWriterWrapper{body: &bytes.Buffer{}}
c.Set(requestBodyOverrideContextKey, "override-as-string")
body := wrapper.extractRequestBody(c)
if string(body) != "override-as-string" {
t.Fatalf("request body = %q, want %q", string(body), "override-as-string")
}
}
func TestExtractResponseBodyPrefersOverride(t *testing.T) {
gin.SetMode(gin.TestMode)
recorder := httptest.NewRecorder()
c, _ := gin.CreateTestContext(recorder)
wrapper := &ResponseWriterWrapper{body: &bytes.Buffer{}}
wrapper.body.WriteString("original-response")
body := wrapper.extractResponseBody(c)
if string(body) != "original-response" {
t.Fatalf("response body = %q, want %q", string(body), "original-response")
}
c.Set(responseBodyOverrideContextKey, []byte("override-response"))
body = wrapper.extractResponseBody(c)
if string(body) != "override-response" {
t.Fatalf("response body = %q, want %q", string(body), "override-response")
}
body[0] = 'X'
if got := wrapper.extractResponseBody(c); string(got) != "override-response" {
t.Fatalf("response override should be cloned, got %q", string(got))
}
}
func TestExtractResponseBodySupportsStringOverride(t *testing.T) {
gin.SetMode(gin.TestMode)
recorder := httptest.NewRecorder()
c, _ := gin.CreateTestContext(recorder)
wrapper := &ResponseWriterWrapper{}
c.Set(responseBodyOverrideContextKey, "override-response-as-string")
body := wrapper.extractResponseBody(c)
if string(body) != "override-response-as-string" {
t.Fatalf("response body = %q, want %q", string(body), "override-response-as-string")
}
}
func TestExtractBodyOverrideClonesBytes(t *testing.T) {
gin.SetMode(gin.TestMode)
recorder := httptest.NewRecorder()
c, _ := gin.CreateTestContext(recorder)
override := []byte("body-override")
c.Set(requestBodyOverrideContextKey, override)
body := extractBodyOverride(c, requestBodyOverrideContextKey)
if !bytes.Equal(body, override) {
t.Fatalf("body override = %q, want %q", string(body), string(override))
}
body[0] = 'X'
if !bytes.Equal(override, []byte("body-override")) {
t.Fatalf("override mutated: %q", string(override))
}
}
func TestExtractWebsocketTimelineUsesOverride(t *testing.T) {
gin.SetMode(gin.TestMode)
recorder := httptest.NewRecorder()
c, _ := gin.CreateTestContext(recorder)
wrapper := &ResponseWriterWrapper{}
if got := wrapper.extractWebsocketTimeline(c); got != nil {
t.Fatalf("expected nil websocket timeline, got %q", string(got))
}
c.Set(websocketTimelineOverrideContextKey, []byte("timeline"))
body := wrapper.extractWebsocketTimeline(c)
if string(body) != "timeline" {
t.Fatalf("websocket timeline = %q, want %q", string(body), "timeline")
}
}
func TestFinalizeStreamingWritesAPIWebsocketTimeline(t *testing.T) {
gin.SetMode(gin.TestMode)
recorder := httptest.NewRecorder()
c, _ := gin.CreateTestContext(recorder)
streamWriter := &testStreamingLogWriter{}
wrapper := &ResponseWriterWrapper{
ResponseWriter: c.Writer,
logger: &testRequestLogger{enabled: true},
requestInfo: &RequestInfo{
URL: "/v1/responses",
Method: "POST",
Headers: map[string][]string{"Content-Type": {"application/json"}},
RequestID: "req-1",
Timestamp: time.Date(2026, time.April, 1, 12, 0, 0, 0, time.UTC),
},
isStreaming: true,
streamWriter: streamWriter,
}
c.Set("API_WEBSOCKET_TIMELINE", []byte("Timestamp: 2026-04-01T12:00:00Z\nEvent: api.websocket.request\n{}"))
if err := wrapper.Finalize(c); err != nil {
t.Fatalf("Finalize error: %v", err)
}
if string(streamWriter.apiWebsocketTimeline) != "Timestamp: 2026-04-01T12:00:00Z\nEvent: api.websocket.request\n{}" {
t.Fatalf("stream writer websocket timeline = %q", string(streamWriter.apiWebsocketTimeline))
}
if !streamWriter.closed {
t.Fatal("expected stream writer to be closed")
}
}
type testRequestLogger struct {
enabled bool
}
func (l *testRequestLogger) LogRequest(string, string, map[string][]string, []byte, int, map[string][]string, []byte, []byte, []byte, []byte, []byte, []*interfaces.ErrorMessage, string, time.Time, time.Time) error {
return nil
}
func (l *testRequestLogger) LogStreamingRequest(string, string, map[string][]string, []byte, string) (logging.StreamingLogWriter, error) {
return &testStreamingLogWriter{}, nil
}
func (l *testRequestLogger) IsEnabled() bool {
return l.enabled
}
type testStreamingLogWriter struct {
apiWebsocketTimeline []byte
closed bool
}
func (w *testStreamingLogWriter) WriteChunkAsync([]byte) {}
func (w *testStreamingLogWriter) WriteStatus(int, map[string][]string) error {
return nil
}
func (w *testStreamingLogWriter) WriteAPIRequest([]byte) error {
return nil
}
func (w *testStreamingLogWriter) WriteAPIResponse([]byte) error {
return nil
}
func (w *testStreamingLogWriter) WriteAPIWebsocketTimeline(apiWebsocketTimeline []byte) error {
w.apiWebsocketTimeline = bytes.Clone(apiWebsocketTimeline)
return nil
}
func (w *testStreamingLogWriter) SetFirstChunkTimestamp(time.Time) {}
func (w *testStreamingLogWriter) Close() error {
w.closed = true
return nil
}