From c41ce77eea6e368fecdd9c47ffa27efb43b959f9 Mon Sep 17 00:00:00 2001 From: sususu98 Date: Tue, 27 Jan 2026 21:30:17 +0800 Subject: [PATCH 1/2] fix(logging): add API response timestamp and fix request timestamp timing Previously: - REQUEST INFO timestamp was captured at log write time (not request arrival) - API RESPONSE had NO timestamp at all This fix: - Captures REQUEST INFO timestamp when request first arrives - Adds API RESPONSE timestamp when upstream response arrives Changes: - Add Timestamp field to RequestInfo, set at middleware initialization - Set API_RESPONSE_TIMESTAMP in appendAPIResponse() and gemini handler - Pass timestamps through logging chain to writeNonStreamingLog() - Add timestamp output to API RESPONSE section This enables accurate measurement of backend response latency in error logs. --- internal/api/middleware/request_logging.go | 2 ++ internal/api/middleware/response_writer.go | 21 +++++++++-- internal/logging/request_logger.go | 36 +++++++++++++------ .../handlers/gemini/gemini-cli_handlers.go | 1 + sdk/api/handlers/handlers.go | 5 +++ 5 files changed, 52 insertions(+), 13 deletions(-) diff --git a/internal/api/middleware/request_logging.go b/internal/api/middleware/request_logging.go index 49f28f52..2c9fdbdd 100644 --- a/internal/api/middleware/request_logging.go +++ b/internal/api/middleware/request_logging.go @@ -8,6 +8,7 @@ import ( "io" "net/http" "strings" + "time" "github.com/gin-gonic/gin" "github.com/router-for-me/CLIProxyAPI/v6/internal/logging" @@ -103,6 +104,7 @@ func captureRequestInfo(c *gin.Context) (*RequestInfo, error) { Headers: headers, Body: body, RequestID: logging.GetGinRequestID(c), + Timestamp: time.Now(), }, nil } diff --git a/internal/api/middleware/response_writer.go b/internal/api/middleware/response_writer.go index 8029e50a..8272c868 100644 --- a/internal/api/middleware/response_writer.go +++ b/internal/api/middleware/response_writer.go @@ -7,6 +7,7 @@ import ( "bytes" "net/http" "strings" + "time" "github.com/gin-gonic/gin" "github.com/router-for-me/CLIProxyAPI/v6/internal/interfaces" @@ -20,6 +21,7 @@ type RequestInfo struct { 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. @@ -297,7 +299,7 @@ func (w *ResponseWriterWrapper) Finalize(c *gin.Context) error { return nil } - return w.logRequest(finalStatusCode, w.cloneHeaders(), w.body.Bytes(), w.extractAPIRequest(c), w.extractAPIResponse(c), slicesAPIResponseError, forceLog) + return w.logRequest(finalStatusCode, w.cloneHeaders(), w.body.Bytes(), w.extractAPIRequest(c), w.extractAPIResponse(c), w.extractAPIResponseTimestamp(c), slicesAPIResponseError, forceLog) } func (w *ResponseWriterWrapper) cloneHeaders() map[string][]string { @@ -337,7 +339,18 @@ func (w *ResponseWriterWrapper) extractAPIResponse(c *gin.Context) []byte { return data } -func (w *ResponseWriterWrapper) logRequest(statusCode int, headers map[string][]string, body []byte, apiRequestBody, apiResponseBody []byte, apiResponseErrors []*interfaces.ErrorMessage, forceLog bool) error { +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) logRequest(statusCode int, headers map[string][]string, body []byte, apiRequestBody, apiResponseBody []byte, apiResponseTimestamp time.Time, apiResponseErrors []*interfaces.ErrorMessage, forceLog bool) error { if w.requestInfo == nil { return nil } @@ -348,7 +361,7 @@ func (w *ResponseWriterWrapper) logRequest(statusCode int, headers map[string][] } if loggerWithOptions, ok := w.logger.(interface { - LogRequestWithOptions(string, string, map[string][]string, []byte, int, map[string][]string, []byte, []byte, []byte, []*interfaces.ErrorMessage, bool, string) error + LogRequestWithOptions(string, string, map[string][]string, []byte, int, map[string][]string, []byte, []byte, []byte, []*interfaces.ErrorMessage, bool, string, time.Time, time.Time) error }); ok { return loggerWithOptions.LogRequestWithOptions( w.requestInfo.URL, @@ -363,6 +376,8 @@ func (w *ResponseWriterWrapper) logRequest(statusCode int, headers map[string][] apiResponseErrors, forceLog, w.requestInfo.RequestID, + w.requestInfo.Timestamp, + apiResponseTimestamp, ) } diff --git a/internal/logging/request_logger.go b/internal/logging/request_logger.go index 397a4a08..44df43d3 100644 --- a/internal/logging/request_logger.go +++ b/internal/logging/request_logger.go @@ -184,16 +184,16 @@ func (l *FileRequestLogger) SetEnabled(enabled bool) { // Returns: // - error: An error if logging fails, nil otherwise func (l *FileRequestLogger) LogRequest(url, method string, requestHeaders map[string][]string, body []byte, statusCode int, responseHeaders map[string][]string, response, apiRequest, apiResponse []byte, apiResponseErrors []*interfaces.ErrorMessage, requestID string) error { - return l.logRequest(url, method, requestHeaders, body, statusCode, responseHeaders, response, apiRequest, apiResponse, apiResponseErrors, false, requestID) + return l.logRequest(url, method, requestHeaders, body, statusCode, responseHeaders, response, apiRequest, apiResponse, apiResponseErrors, false, requestID, time.Time{}, time.Time{}) } // LogRequestWithOptions logs a request with optional forced logging behavior. // The force flag allows writing error logs even when regular request logging is disabled. -func (l *FileRequestLogger) LogRequestWithOptions(url, method string, requestHeaders map[string][]string, body []byte, statusCode int, responseHeaders map[string][]string, response, apiRequest, apiResponse []byte, apiResponseErrors []*interfaces.ErrorMessage, force bool, requestID string) error { - return l.logRequest(url, method, requestHeaders, body, statusCode, responseHeaders, response, apiRequest, apiResponse, apiResponseErrors, force, requestID) +func (l *FileRequestLogger) LogRequestWithOptions(url, method string, requestHeaders map[string][]string, body []byte, statusCode int, responseHeaders map[string][]string, response, apiRequest, apiResponse []byte, apiResponseErrors []*interfaces.ErrorMessage, force bool, requestID string, requestTimestamp, apiResponseTimestamp time.Time) error { + return l.logRequest(url, method, requestHeaders, body, statusCode, responseHeaders, response, apiRequest, apiResponse, apiResponseErrors, force, requestID, requestTimestamp, apiResponseTimestamp) } -func (l *FileRequestLogger) logRequest(url, method string, requestHeaders map[string][]string, body []byte, statusCode int, responseHeaders map[string][]string, response, apiRequest, apiResponse []byte, apiResponseErrors []*interfaces.ErrorMessage, force bool, requestID string) error { +func (l *FileRequestLogger) logRequest(url, method string, requestHeaders map[string][]string, body []byte, statusCode int, responseHeaders map[string][]string, response, apiRequest, apiResponse []byte, apiResponseErrors []*interfaces.ErrorMessage, force bool, requestID string, requestTimestamp, apiResponseTimestamp time.Time) error { if !l.enabled && !force { return nil } @@ -247,6 +247,8 @@ func (l *FileRequestLogger) logRequest(url, method string, requestHeaders map[st responseHeaders, responseToWrite, decompressErr, + requestTimestamp, + apiResponseTimestamp, ) if errClose := logFile.Close(); errClose != nil { log.WithError(errClose).Warn("failed to close request log file") @@ -499,17 +501,22 @@ func (l *FileRequestLogger) writeNonStreamingLog( responseHeaders map[string][]string, response []byte, decompressErr error, + requestTimestamp time.Time, + apiResponseTimestamp time.Time, ) error { - if errWrite := writeRequestInfoWithBody(w, url, method, requestHeaders, requestBody, requestBodyPath, time.Now()); errWrite != nil { + if requestTimestamp.IsZero() { + requestTimestamp = time.Now() + } + if errWrite := writeRequestInfoWithBody(w, url, method, requestHeaders, requestBody, requestBodyPath, requestTimestamp); errWrite != nil { return errWrite } - if errWrite := writeAPISection(w, "=== API REQUEST ===\n", "=== API REQUEST", apiRequest); errWrite != nil { + if errWrite := writeAPISection(w, "=== API REQUEST ===\n", "=== API REQUEST", apiRequest, time.Time{}); errWrite != nil { return errWrite } if errWrite := writeAPIErrorResponses(w, apiResponseErrors); errWrite != nil { return errWrite } - if errWrite := writeAPISection(w, "=== API RESPONSE ===\n", "=== API RESPONSE", apiResponse); errWrite != nil { + if errWrite := writeAPISection(w, "=== API RESPONSE ===\n", "=== API RESPONSE", apiResponse, apiResponseTimestamp); errWrite != nil { return errWrite } return writeResponseSection(w, statusCode, true, responseHeaders, bytes.NewReader(response), decompressErr, true) @@ -583,7 +590,7 @@ func writeRequestInfoWithBody( return nil } -func writeAPISection(w io.Writer, sectionHeader string, sectionPrefix string, payload []byte) error { +func writeAPISection(w io.Writer, sectionHeader string, sectionPrefix string, payload []byte, timestamp time.Time) error { if len(payload) == 0 { return nil } @@ -601,6 +608,11 @@ func writeAPISection(w io.Writer, sectionHeader string, sectionPrefix string, pa if _, errWrite := io.WriteString(w, sectionHeader); errWrite != nil { return errWrite } + if !timestamp.IsZero() { + if _, errWrite := io.WriteString(w, fmt.Sprintf("Timestamp: %s\n", timestamp.Format(time.RFC3339Nano))); errWrite != nil { + return errWrite + } + } if _, errWrite := w.Write(payload); errWrite != nil { return errWrite } @@ -974,6 +986,9 @@ type FileStreamingLogWriter struct { // apiResponse stores the upstream API response data. apiResponse []byte + + // apiResponseTimestamp captures when the API response was received. + apiResponseTimestamp time.Time } // WriteChunkAsync writes a response chunk asynchronously (non-blocking). @@ -1050,6 +1065,7 @@ func (w *FileStreamingLogWriter) WriteAPIResponse(apiResponse []byte) error { return nil } w.apiResponse = bytes.Clone(apiResponse) + w.apiResponseTimestamp = time.Now() return nil } @@ -1140,10 +1156,10 @@ func (w *FileStreamingLogWriter) writeFinalLog(logFile *os.File) error { if errWrite := writeRequestInfoWithBody(logFile, w.url, w.method, w.requestHeaders, nil, w.requestBodyPath, w.timestamp); errWrite != nil { return errWrite } - if errWrite := writeAPISection(logFile, "=== API REQUEST ===\n", "=== API REQUEST", w.apiRequest); errWrite != nil { + if errWrite := writeAPISection(logFile, "=== API REQUEST ===\n", "=== API REQUEST", w.apiRequest, time.Time{}); errWrite != nil { return errWrite } - if errWrite := writeAPISection(logFile, "=== API RESPONSE ===\n", "=== API RESPONSE", w.apiResponse); errWrite != nil { + if errWrite := writeAPISection(logFile, "=== API RESPONSE ===\n", "=== API RESPONSE", w.apiResponse, w.apiResponseTimestamp); errWrite != nil { return errWrite } diff --git a/sdk/api/handlers/gemini/gemini-cli_handlers.go b/sdk/api/handlers/gemini/gemini-cli_handlers.go index ea78657d..8c85b39c 100644 --- a/sdk/api/handlers/gemini/gemini-cli_handlers.go +++ b/sdk/api/handlers/gemini/gemini-cli_handlers.go @@ -125,6 +125,7 @@ func (h *GeminiCLIAPIHandler) CLIHandler(c *gin.Context) { return } _, _ = c.Writer.Write(output) + c.Set("API_RESPONSE_TIMESTAMP", time.Now()) c.Set("API_RESPONSE", output) } } diff --git a/sdk/api/handlers/handlers.go b/sdk/api/handlers/handlers.go index b1da9664..85657e12 100644 --- a/sdk/api/handlers/handlers.go +++ b/sdk/api/handlers/handlers.go @@ -361,6 +361,11 @@ func appendAPIResponse(c *gin.Context, data []byte) { return } + // Capture timestamp on first API response + if _, exists := c.Get("API_RESPONSE_TIMESTAMP"); !exists { + c.Set("API_RESPONSE_TIMESTAMP", time.Now()) + } + if existing, exists := c.Get("API_RESPONSE"); exists { if existingBytes, ok := existing.([]byte); ok && len(existingBytes) > 0 { combined := make([]byte, 0, len(existingBytes)+len(data)+1) From 295f34d7f0cd466ee17715026cba641253de1de8 Mon Sep 17 00:00:00 2001 From: sususu98 Date: Thu, 29 Jan 2026 22:22:09 +0800 Subject: [PATCH 2/2] fix(logging): capture streaming TTFB on first chunk and make timestamps required - Add firstChunkTimestamp field to ResponseWriterWrapper for sync capture - Capture TTFB in Write() and WriteString() before async channel send - Add SetFirstChunkTimestamp() to StreamingLogWriter interface - Make requestTimestamp/apiResponseTimestamp required in LogRequest() - Remove timestamp capture from WriteAPIResponse() (now via setter) - Fix Gemini handler to set API_RESPONSE_TIMESTAMP before writing response This ensures accurate TTFB measurement for all streaming API formats (OpenAI, Gemini, Claude) by capturing timestamp synchronously when the first response chunk arrives, not when the stream finalizes. --- internal/api/middleware/response_writer.go | 33 +++++++++++++------ internal/logging/request_logger.go | 25 +++++++++++--- .../handlers/gemini/gemini-cli_handlers.go | 2 +- 3 files changed, 45 insertions(+), 15 deletions(-) diff --git a/internal/api/middleware/response_writer.go b/internal/api/middleware/response_writer.go index 8272c868..50fa1c69 100644 --- a/internal/api/middleware/response_writer.go +++ b/internal/api/middleware/response_writer.go @@ -28,16 +28,17 @@ type RequestInfo struct { // 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. + 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. @@ -75,6 +76,10 @@ func (w *ResponseWriterWrapper) Write(data []byte) (int, error) { // 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 @@ -119,6 +124,10 @@ func (w *ResponseWriterWrapper) WriteString(data string) (int, error) { // 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: @@ -282,6 +291,8 @@ func (w *ResponseWriterWrapper) Finalize(c *gin.Context) error { w.streamDone = nil } + w.streamWriter.SetFirstChunkTimestamp(w.firstChunkTimestamp) + // Write API Request and Response to the streaming log before closing apiRequest := w.extractAPIRequest(c) if len(apiRequest) > 0 { @@ -393,5 +404,7 @@ func (w *ResponseWriterWrapper) logRequest(statusCode int, headers map[string][] apiResponseBody, apiResponseErrors, w.requestInfo.RequestID, + w.requestInfo.Timestamp, + apiResponseTimestamp, ) } diff --git a/internal/logging/request_logger.go b/internal/logging/request_logger.go index 44df43d3..cf9b4d5c 100644 --- a/internal/logging/request_logger.go +++ b/internal/logging/request_logger.go @@ -44,10 +44,12 @@ type RequestLogger interface { // - apiRequest: The API request data // - apiResponse: The API response data // - requestID: Optional request ID for log file naming + // - requestTimestamp: When the request was received + // - apiResponseTimestamp: When the API response was received // // Returns: // - error: An error if logging fails, nil otherwise - LogRequest(url, method string, requestHeaders map[string][]string, body []byte, statusCode int, responseHeaders map[string][]string, response, apiRequest, apiResponse []byte, apiResponseErrors []*interfaces.ErrorMessage, requestID string) error + LogRequest(url, method string, requestHeaders map[string][]string, body []byte, statusCode int, responseHeaders map[string][]string, response, apiRequest, apiResponse []byte, apiResponseErrors []*interfaces.ErrorMessage, requestID string, requestTimestamp, apiResponseTimestamp time.Time) error // LogStreamingRequest initiates logging for a streaming request and returns a writer for chunks. // @@ -109,6 +111,12 @@ type StreamingLogWriter interface { // - error: An error if writing fails, nil otherwise WriteAPIResponse(apiResponse []byte) error + // SetFirstChunkTimestamp sets the TTFB timestamp captured when first chunk was received. + // + // Parameters: + // - timestamp: The time when first response chunk was received + SetFirstChunkTimestamp(timestamp time.Time) + // Close finalizes the log file and cleans up resources. // // Returns: @@ -180,11 +188,13 @@ func (l *FileRequestLogger) SetEnabled(enabled bool) { // - apiRequest: The API request data // - apiResponse: The API response data // - requestID: Optional request ID for log file naming +// - requestTimestamp: When the request was received +// - apiResponseTimestamp: When the API response was received // // Returns: // - error: An error if logging fails, nil otherwise -func (l *FileRequestLogger) LogRequest(url, method string, requestHeaders map[string][]string, body []byte, statusCode int, responseHeaders map[string][]string, response, apiRequest, apiResponse []byte, apiResponseErrors []*interfaces.ErrorMessage, requestID string) error { - return l.logRequest(url, method, requestHeaders, body, statusCode, responseHeaders, response, apiRequest, apiResponse, apiResponseErrors, false, requestID, time.Time{}, time.Time{}) +func (l *FileRequestLogger) LogRequest(url, method string, requestHeaders map[string][]string, body []byte, statusCode int, responseHeaders map[string][]string, response, apiRequest, apiResponse []byte, apiResponseErrors []*interfaces.ErrorMessage, requestID string, requestTimestamp, apiResponseTimestamp time.Time) error { + return l.logRequest(url, method, requestHeaders, body, statusCode, responseHeaders, response, apiRequest, apiResponse, apiResponseErrors, false, requestID, requestTimestamp, apiResponseTimestamp) } // LogRequestWithOptions logs a request with optional forced logging behavior. @@ -1065,10 +1075,15 @@ func (w *FileStreamingLogWriter) WriteAPIResponse(apiResponse []byte) error { return nil } w.apiResponse = bytes.Clone(apiResponse) - w.apiResponseTimestamp = time.Now() return nil } +func (w *FileStreamingLogWriter) SetFirstChunkTimestamp(timestamp time.Time) { + if !timestamp.IsZero() { + w.apiResponseTimestamp = timestamp + } +} + // Close finalizes the log file and cleans up resources. // It writes all buffered data to the file in the correct order: // API REQUEST -> API RESPONSE -> RESPONSE (status, headers, body chunks) @@ -1236,6 +1251,8 @@ func (w *NoOpStreamingLogWriter) WriteAPIResponse(_ []byte) error { return nil } +func (w *NoOpStreamingLogWriter) SetFirstChunkTimestamp(_ time.Time) {} + // Close is a no-op implementation that does nothing and always returns nil. // // Returns: diff --git a/sdk/api/handlers/gemini/gemini-cli_handlers.go b/sdk/api/handlers/gemini/gemini-cli_handlers.go index 8c85b39c..917902e7 100644 --- a/sdk/api/handlers/gemini/gemini-cli_handlers.go +++ b/sdk/api/handlers/gemini/gemini-cli_handlers.go @@ -124,8 +124,8 @@ func (h *GeminiCLIAPIHandler) CLIHandler(c *gin.Context) { log.Errorf("Failed to read response body: %v", err) return } - _, _ = c.Writer.Write(output) c.Set("API_RESPONSE_TIMESTAMP", time.Now()) + _, _ = c.Writer.Write(output) c.Set("API_RESPONSE", output) } }