From e76ba0ede9b31142f746d7bd6cf6a8ccf9982843 Mon Sep 17 00:00:00 2001 From: hkfires <10558748+hkfires@users.noreply.github.com> Date: Tue, 23 Dec 2025 21:41:18 +0800 Subject: [PATCH] feat(logging): implement request ID tracking and propagation --- internal/api/middleware/request_logging.go | 9 ++-- internal/api/middleware/response_writer.go | 14 +++-- internal/logging/gin_logger.go | 21 +++++--- internal/logging/global_logger.go | 20 +++++-- internal/logging/request_logger.go | 52 +++++++++++------- internal/logging/requestid.go | 61 ++++++++++++++++++++++ sdk/api/handlers/handlers.go | 31 ++++++++++- sdk/cliproxy/auth/manager.go | 39 +++++++++----- 8 files changed, 194 insertions(+), 53 deletions(-) create mode 100644 internal/logging/requestid.go diff --git a/internal/api/middleware/request_logging.go b/internal/api/middleware/request_logging.go index 8f29e1a1..49f28f52 100644 --- a/internal/api/middleware/request_logging.go +++ b/internal/api/middleware/request_logging.go @@ -98,10 +98,11 @@ func captureRequestInfo(c *gin.Context) (*RequestInfo, error) { } return &RequestInfo{ - URL: url, - Method: method, - Headers: headers, - Body: body, + URL: url, + Method: method, + Headers: headers, + Body: body, + RequestID: logging.GetGinRequestID(c), }, nil } diff --git a/internal/api/middleware/response_writer.go b/internal/api/middleware/response_writer.go index 8005df23..8029e50a 100644 --- a/internal/api/middleware/response_writer.go +++ b/internal/api/middleware/response_writer.go @@ -15,10 +15,11 @@ import ( // 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. + 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. } // ResponseWriterWrapper wraps the standard gin.ResponseWriter to intercept and log response data. @@ -149,6 +150,7 @@ func (w *ResponseWriterWrapper) WriteHeader(statusCode int) { w.requestInfo.Method, w.requestInfo.Headers, w.requestInfo.Body, + w.requestInfo.RequestID, ) if err == nil { w.streamWriter = streamWriter @@ -346,7 +348,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) error + LogRequestWithOptions(string, string, map[string][]string, []byte, int, map[string][]string, []byte, []byte, []byte, []*interfaces.ErrorMessage, bool, string) error }); ok { return loggerWithOptions.LogRequestWithOptions( w.requestInfo.URL, @@ -360,6 +362,7 @@ func (w *ResponseWriterWrapper) logRequest(statusCode int, headers map[string][] apiResponseBody, apiResponseErrors, forceLog, + w.requestInfo.RequestID, ) } @@ -374,5 +377,6 @@ func (w *ResponseWriterWrapper) logRequest(statusCode int, headers map[string][] apiRequestBody, apiResponseBody, apiResponseErrors, + w.requestInfo.RequestID, ) } diff --git a/internal/logging/gin_logger.go b/internal/logging/gin_logger.go index a4e020b1..f09ea879 100644 --- a/internal/logging/gin_logger.go +++ b/internal/logging/gin_logger.go @@ -18,12 +18,20 @@ const skipGinLogKey = "__gin_skip_request_logging__" // GinLogrusLogger returns a Gin middleware handler that logs HTTP requests and responses // using logrus. It captures request details including method, path, status code, latency, -// client IP, and any error messages, formatting them in a Gin-style log format. +// client IP, and any error messages, formatted with request ID for correlation. +// +// Output format: [2025-12-23 20:14:10] [info ] [a1b2c3d4] 200 | 23.559s | 144.34.236.116 | POST "/v1/messages?beta=true" // // Returns: // - gin.HandlerFunc: A middleware handler for request logging func GinLogrusLogger() gin.HandlerFunc { return func(c *gin.Context) { + requestID := GenerateRequestID() + SetGinRequestID(c, requestID) + + ctx := WithRequestID(c.Request.Context(), requestID) + c.Request = c.Request.WithContext(ctx) + start := time.Now() path := c.Request.URL.Path raw := util.MaskSensitiveQuery(c.Request.URL.RawQuery) @@ -49,19 +57,20 @@ func GinLogrusLogger() gin.HandlerFunc { clientIP := c.ClientIP() method := c.Request.Method errorMessage := c.Errors.ByType(gin.ErrorTypePrivate).String() - timestamp := time.Now().Format("2006/01/02 - 15:04:05") - logLine := fmt.Sprintf("[GIN] %s | %3d | %13v | %15s | %-7s \"%s\"", timestamp, statusCode, latency, clientIP, method, path) + + logLine := fmt.Sprintf("%3d | %13v | %15s | %-7s \"%s\"", statusCode, latency, clientIP, method, path) if errorMessage != "" { logLine = logLine + " | " + errorMessage } + entry := log.WithField("request_id", requestID) switch { case statusCode >= http.StatusInternalServerError: - log.Error(logLine) + entry.Error(logLine) case statusCode >= http.StatusBadRequest: - log.Warn(logLine) + entry.Warn(logLine) default: - log.Info(logLine) + entry.Info(logLine) } } } diff --git a/internal/logging/global_logger.go b/internal/logging/global_logger.go index e7d795fa..f27f726f 100644 --- a/internal/logging/global_logger.go +++ b/internal/logging/global_logger.go @@ -24,7 +24,8 @@ var ( ) // LogFormatter defines a custom log format for logrus. -// This formatter adds timestamp, level, and source location to each log entry. +// This formatter adds timestamp, level, request ID, and source location to each log entry. +// Format: [2025-12-23 20:14:04] [debug] [manager.go:524] | a1b2c3d4 | Use API key sk-9...0RHO for model gpt-5.2 type LogFormatter struct{} // Format renders a single log entry with custom formatting. @@ -39,11 +40,22 @@ func (m *LogFormatter) Format(entry *log.Entry) ([]byte, error) { timestamp := entry.Time.Format("2006-01-02 15:04:05") message := strings.TrimRight(entry.Message, "\r\n") + reqID := "" + if id, ok := entry.Data["request_id"].(string); ok && id != "" { + reqID = id + } + + levelStr := fmt.Sprintf("%-5s", entry.Level.String()) + var formatted string - if entry.Caller != nil { - formatted = fmt.Sprintf("[%s] [%s] [%s:%d] %s\n", timestamp, entry.Level, filepath.Base(entry.Caller.File), entry.Caller.Line, message) + if reqID != "" && entry.Caller != nil { + formatted = fmt.Sprintf("[%s] [%s] [%s:%d] | %s | %s\n", timestamp, levelStr, filepath.Base(entry.Caller.File), entry.Caller.Line, reqID, message) + } else if reqID != "" { + formatted = fmt.Sprintf("[%s] [%s] | %s | %s\n", timestamp, levelStr, reqID, message) + } else if entry.Caller != nil { + formatted = fmt.Sprintf("[%s] [%s] [%s:%d] %s\n", timestamp, levelStr, filepath.Base(entry.Caller.File), entry.Caller.Line, message) } else { - formatted = fmt.Sprintf("[%s] [%s] %s\n", timestamp, entry.Level, message) + formatted = fmt.Sprintf("[%s] [%s] %s\n", timestamp, levelStr, message) } buffer.WriteString(formatted) diff --git a/internal/logging/request_logger.go b/internal/logging/request_logger.go index 391f2869..397a4a08 100644 --- a/internal/logging/request_logger.go +++ b/internal/logging/request_logger.go @@ -43,10 +43,11 @@ type RequestLogger interface { // - response: The raw response data // - apiRequest: The API request data // - apiResponse: The API response data + // - requestID: Optional request ID for log file naming // // 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) 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) error // LogStreamingRequest initiates logging for a streaming request and returns a writer for chunks. // @@ -55,11 +56,12 @@ type RequestLogger interface { // - method: The HTTP method // - headers: The request headers // - body: The request body + // - requestID: Optional request ID for log file naming // // Returns: // - StreamingLogWriter: A writer for streaming response chunks // - error: An error if logging initialization fails, nil otherwise - LogStreamingRequest(url, method string, headers map[string][]string, body []byte) (StreamingLogWriter, error) + LogStreamingRequest(url, method string, headers map[string][]string, body []byte, requestID string) (StreamingLogWriter, error) // IsEnabled returns whether request logging is currently enabled. // @@ -177,20 +179,21 @@ func (l *FileRequestLogger) SetEnabled(enabled bool) { // - response: The raw response data // - apiRequest: The API request data // - apiResponse: The API response data +// - requestID: Optional request ID for log file naming // // 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) error { - return l.logRequest(url, method, requestHeaders, body, statusCode, responseHeaders, response, apiRequest, apiResponse, apiResponseErrors, false) +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) } // 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) error { - return l.logRequest(url, method, requestHeaders, body, statusCode, responseHeaders, response, apiRequest, apiResponse, apiResponseErrors, force) +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) 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) 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) error { if !l.enabled && !force { return nil } @@ -200,10 +203,10 @@ func (l *FileRequestLogger) logRequest(url, method string, requestHeaders map[st return fmt.Errorf("failed to create logs directory: %w", errEnsure) } - // Generate filename - filename := l.generateFilename(url) + // Generate filename with request ID + filename := l.generateFilename(url, requestID) if force && !l.enabled { - filename = l.generateErrorFilename(url) + filename = l.generateErrorFilename(url, requestID) } filePath := filepath.Join(l.logsDir, filename) @@ -271,11 +274,12 @@ func (l *FileRequestLogger) logRequest(url, method string, requestHeaders map[st // - method: The HTTP method // - headers: The request headers // - body: The request body +// - requestID: Optional request ID for log file naming // // Returns: // - StreamingLogWriter: A writer for streaming response chunks // - error: An error if logging initialization fails, nil otherwise -func (l *FileRequestLogger) LogStreamingRequest(url, method string, headers map[string][]string, body []byte) (StreamingLogWriter, error) { +func (l *FileRequestLogger) LogStreamingRequest(url, method string, headers map[string][]string, body []byte, requestID string) (StreamingLogWriter, error) { if !l.enabled { return &NoOpStreamingLogWriter{}, nil } @@ -285,8 +289,8 @@ func (l *FileRequestLogger) LogStreamingRequest(url, method string, headers map[ return nil, fmt.Errorf("failed to create logs directory: %w", err) } - // Generate filename - filename := l.generateFilename(url) + // Generate filename with request ID + filename := l.generateFilename(url, requestID) filePath := filepath.Join(l.logsDir, filename) requestHeaders := make(map[string][]string, len(headers)) @@ -330,8 +334,8 @@ func (l *FileRequestLogger) LogStreamingRequest(url, method string, headers map[ } // generateErrorFilename creates a filename with an error prefix to differentiate forced error logs. -func (l *FileRequestLogger) generateErrorFilename(url string) string { - return fmt.Sprintf("error-%s", l.generateFilename(url)) +func (l *FileRequestLogger) generateErrorFilename(url string, requestID ...string) string { + return fmt.Sprintf("error-%s", l.generateFilename(url, requestID...)) } // ensureLogsDir creates the logs directory if it doesn't exist. @@ -346,13 +350,15 @@ func (l *FileRequestLogger) ensureLogsDir() error { } // generateFilename creates a sanitized filename from the URL path and current timestamp. +// Format: v1-responses-2025-12-23T195811-a1b2c3d4.log // // Parameters: // - url: The request URL +// - requestID: Optional request ID to include in filename // // Returns: // - string: A sanitized filename for the log file -func (l *FileRequestLogger) generateFilename(url string) string { +func (l *FileRequestLogger) generateFilename(url string, requestID ...string) string { // Extract path from URL path := url if strings.Contains(url, "?") { @@ -368,12 +374,18 @@ func (l *FileRequestLogger) generateFilename(url string) string { sanitized := l.sanitizeForFilename(path) // Add timestamp - timestamp := time.Now().Format("2006-01-02T150405-.000000000") - timestamp = strings.Replace(timestamp, ".", "", -1) + timestamp := time.Now().Format("2006-01-02T150405") - id := requestLogID.Add(1) + // Use request ID if provided, otherwise use sequential ID + var idPart string + if len(requestID) > 0 && requestID[0] != "" { + idPart = requestID[0] + } else { + id := requestLogID.Add(1) + idPart = fmt.Sprintf("%d", id) + } - return fmt.Sprintf("%s-%s-%d.log", sanitized, timestamp, id) + return fmt.Sprintf("%s-%s-%s.log", sanitized, timestamp, idPart) } // sanitizeForFilename replaces characters that are not safe for filenames. diff --git a/internal/logging/requestid.go b/internal/logging/requestid.go new file mode 100644 index 00000000..8bd045d1 --- /dev/null +++ b/internal/logging/requestid.go @@ -0,0 +1,61 @@ +package logging + +import ( + "context" + "crypto/rand" + "encoding/hex" + + "github.com/gin-gonic/gin" +) + +// requestIDKey is the context key for storing/retrieving request IDs. +type requestIDKey struct{} + +// ginRequestIDKey is the Gin context key for request IDs. +const ginRequestIDKey = "__request_id__" + +// GenerateRequestID creates a new 8-character hex request ID. +func GenerateRequestID() string { + b := make([]byte, 4) + if _, err := rand.Read(b); err != nil { + return "00000000" + } + return hex.EncodeToString(b) +} + +// WithRequestID returns a new context with the request ID attached. +func WithRequestID(ctx context.Context, requestID string) context.Context { + return context.WithValue(ctx, requestIDKey{}, requestID) +} + +// GetRequestID retrieves the request ID from the context. +// Returns empty string if not found. +func GetRequestID(ctx context.Context) string { + if ctx == nil { + return "" + } + if id, ok := ctx.Value(requestIDKey{}).(string); ok { + return id + } + return "" +} + +// SetGinRequestID stores the request ID in the Gin context. +func SetGinRequestID(c *gin.Context, requestID string) { + if c != nil { + c.Set(ginRequestIDKey, requestID) + } +} + +// GetGinRequestID retrieves the request ID from the Gin context. +func GetGinRequestID(c *gin.Context) string { + if c == nil { + return "" + } + if id, exists := c.Get(ginRequestIDKey); exists { + if s, ok := id.(string); ok { + return s + } + } + return "" +} diff --git a/sdk/api/handlers/handlers.go b/sdk/api/handlers/handlers.go index 7857f736..a544ef0c 100644 --- a/sdk/api/handlers/handlers.go +++ b/sdk/api/handlers/handlers.go @@ -14,6 +14,7 @@ import ( "github.com/gin-gonic/gin" "github.com/google/uuid" "github.com/router-for-me/CLIProxyAPI/v6/internal/interfaces" + "github.com/router-for-me/CLIProxyAPI/v6/internal/logging" "github.com/router-for-me/CLIProxyAPI/v6/internal/util" coreauth "github.com/router-for-me/CLIProxyAPI/v6/sdk/cliproxy/auth" coreexecutor "github.com/router-for-me/CLIProxyAPI/v6/sdk/cliproxy/executor" @@ -216,13 +217,39 @@ func (h *BaseAPIHandler) GetAlt(c *gin.Context) string { // Parameters: // - handler: The API handler associated with the request. // - c: The Gin context of the current request. -// - ctx: The parent context. +// - ctx: The parent context (caller values/deadlines are preserved; request context adds cancellation and request ID). // // Returns: // - context.Context: The new context with cancellation and embedded values. // - APIHandlerCancelFunc: A function to cancel the context and log the response. func (h *BaseAPIHandler) GetContextWithCancel(handler interfaces.APIHandler, c *gin.Context, ctx context.Context) (context.Context, APIHandlerCancelFunc) { - newCtx, cancel := context.WithCancel(ctx) + parentCtx := ctx + if parentCtx == nil { + parentCtx = context.Background() + } + + var requestCtx context.Context + if c != nil && c.Request != nil { + requestCtx = c.Request.Context() + } + + if requestCtx != nil && logging.GetRequestID(parentCtx) == "" { + if requestID := logging.GetRequestID(requestCtx); requestID != "" { + parentCtx = logging.WithRequestID(parentCtx, requestID) + } else if requestID := logging.GetGinRequestID(c); requestID != "" { + parentCtx = logging.WithRequestID(parentCtx, requestID) + } + } + newCtx, cancel := context.WithCancel(parentCtx) + if requestCtx != nil && requestCtx != parentCtx { + go func() { + select { + case <-requestCtx.Done(): + cancel() + case <-newCtx.Done(): + } + }() + } newCtx = context.WithValue(newCtx, "gin", c) newCtx = context.WithValue(newCtx, "handler", handler) return newCtx, func(params ...interface{}) { diff --git a/sdk/cliproxy/auth/manager.go b/sdk/cliproxy/auth/manager.go index 38d4c0fa..0d648d81 100644 --- a/sdk/cliproxy/auth/manager.go +++ b/sdk/cliproxy/auth/manager.go @@ -12,6 +12,7 @@ import ( "time" "github.com/google/uuid" + "github.com/router-for-me/CLIProxyAPI/v6/internal/logging" "github.com/router-for-me/CLIProxyAPI/v6/internal/registry" "github.com/router-for-me/CLIProxyAPI/v6/internal/util" cliproxyexecutor "github.com/router-for-me/CLIProxyAPI/v6/sdk/cliproxy/executor" @@ -389,17 +390,18 @@ func (m *Manager) executeWithProvider(ctx context.Context, provider string, req accountType, accountInfo := auth.AccountInfo() proxyInfo := auth.ProxyInfo() + entry := logEntryWithRequestID(ctx) if accountType == "api_key" { if proxyInfo != "" { - log.Debugf("Use API key %s for model %s %s", util.HideAPIKey(accountInfo), req.Model, proxyInfo) + entry.Debugf("Use API key %s for model %s %s", util.HideAPIKey(accountInfo), req.Model, proxyInfo) } else { - log.Debugf("Use API key %s for model %s", util.HideAPIKey(accountInfo), req.Model) + entry.Debugf("Use API key %s for model %s", util.HideAPIKey(accountInfo), req.Model) } } else if accountType == "oauth" { if proxyInfo != "" { - log.Debugf("Use OAuth %s for model %s %s", accountInfo, req.Model, proxyInfo) + entry.Debugf("Use OAuth %s for model %s %s", accountInfo, req.Model, proxyInfo) } else { - log.Debugf("Use OAuth %s for model %s", accountInfo, req.Model) + entry.Debugf("Use OAuth %s for model %s", accountInfo, req.Model) } } @@ -449,17 +451,18 @@ func (m *Manager) executeCountWithProvider(ctx context.Context, provider string, accountType, accountInfo := auth.AccountInfo() proxyInfo := auth.ProxyInfo() + entry := logEntryWithRequestID(ctx) if accountType == "api_key" { if proxyInfo != "" { - log.Debugf("Use API key %s for model %s %s", util.HideAPIKey(accountInfo), req.Model, proxyInfo) + entry.Debugf("Use API key %s for model %s %s", util.HideAPIKey(accountInfo), req.Model, proxyInfo) } else { - log.Debugf("Use API key %s for model %s", util.HideAPIKey(accountInfo), req.Model) + entry.Debugf("Use API key %s for model %s", util.HideAPIKey(accountInfo), req.Model) } } else if accountType == "oauth" { if proxyInfo != "" { - log.Debugf("Use OAuth %s for model %s %s", accountInfo, req.Model, proxyInfo) + entry.Debugf("Use OAuth %s for model %s %s", accountInfo, req.Model, proxyInfo) } else { - log.Debugf("Use OAuth %s for model %s", accountInfo, req.Model) + entry.Debugf("Use OAuth %s for model %s", accountInfo, req.Model) } } @@ -509,17 +512,18 @@ func (m *Manager) executeStreamWithProvider(ctx context.Context, provider string accountType, accountInfo := auth.AccountInfo() proxyInfo := auth.ProxyInfo() + entry := logEntryWithRequestID(ctx) if accountType == "api_key" { if proxyInfo != "" { - log.Debugf("Use API key %s for model %s %s", util.HideAPIKey(accountInfo), req.Model, proxyInfo) + entry.Debugf("Use API key %s for model %s %s", util.HideAPIKey(accountInfo), req.Model, proxyInfo) } else { - log.Debugf("Use API key %s for model %s", util.HideAPIKey(accountInfo), req.Model) + entry.Debugf("Use API key %s for model %s", util.HideAPIKey(accountInfo), req.Model) } } else if accountType == "oauth" { if proxyInfo != "" { - log.Debugf("Use OAuth %s for model %s %s", accountInfo, req.Model, proxyInfo) + entry.Debugf("Use OAuth %s for model %s %s", accountInfo, req.Model, proxyInfo) } else { - log.Debugf("Use OAuth %s for model %s", accountInfo, req.Model) + entry.Debugf("Use OAuth %s for model %s", accountInfo, req.Model) } } @@ -1604,6 +1608,17 @@ type RequestPreparer interface { PrepareRequest(req *http.Request, auth *Auth) error } +// logEntryWithRequestID returns a logrus entry with request_id field if available in context. +func logEntryWithRequestID(ctx context.Context) *log.Entry { + if ctx == nil { + return log.NewEntry(log.StandardLogger()) + } + if reqID := logging.GetRequestID(ctx); reqID != "" { + return log.WithField("request_id", reqID) + } + return log.NewEntry(log.StandardLogger()) +} + // InjectCredentials delegates per-provider HTTP request preparation when supported. // If the registered executor for the auth provider implements RequestPreparer, // it will be invoked to modify the request (e.g., add headers).