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..50fa1c69 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,22 +21,24 @@ 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. // 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. @@ -73,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 @@ -117,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: @@ -280,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 { @@ -297,7 +310,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 +350,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 +372,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 +387,8 @@ func (w *ResponseWriterWrapper) logRequest(statusCode int, headers map[string][] apiResponseErrors, forceLog, w.requestInfo.RequestID, + w.requestInfo.Timestamp, + apiResponseTimestamp, ) } @@ -378,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 397a4a08..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,20 +188,22 @@ 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) +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. // 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 +257,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 +511,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 +600,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 +618,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 +996,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). @@ -1053,6 +1078,12 @@ func (w *FileStreamingLogWriter) WriteAPIResponse(apiResponse []byte) error { 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) @@ -1140,10 +1171,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 } @@ -1220,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 ea78657d..917902e7 100644 --- a/sdk/api/handlers/gemini/gemini-cli_handlers.go +++ b/sdk/api/handlers/gemini/gemini-cli_handlers.go @@ -124,6 +124,7 @@ func (h *GeminiCLIAPIHandler) CLIHandler(c *gin.Context) { log.Errorf("Failed to read response body: %v", err) return } + c.Set("API_RESPONSE_TIMESTAMP", time.Now()) _, _ = c.Writer.Write(output) 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)