History

Merge pull request #549 from router-for-me/log

Improve Request Logging Efficiency and Standardize Error Responses

Luis Pater committed 11 months ago

Commit 88b101e2 parents d9a6574 97ab6232 files · +127 −57Browse files

Unified · Split

2 files
  1. internal/api/middleware/response_writer.go +71 −53
  2. sdk/api/handlers/handlers.go +56 −4
internal/api/middleware/response_writer.go+71−53
@@ -71,22 +71,64 @@ func (w *ResponseWriterWrapper) Write(data []byte) (int, error) { · 70 unmodified lines
71 n, err := w.ResponseWriter.Write(data)71 n, err := w.ResponseWriter.Write(data)
72 72
73 // THEN: Handle logging based on response type73 // THEN: Handle logging based on response type
74 if w.isStreaming {74 if w.isStreaming && w.chunkChannel != nil {
75 // For streaming responses: Send to async logging channel (non-blocking)75 // For streaming responses: Send to async logging channel (non-blocking)
76 if w.chunkChannel != nil {76 select {
77 select {77 case w.chunkChannel <- append([]byte(nil), data...): // Non-blocking send with copy
78 case w.chunkChannel <- append([]byte(nil), data...): // Non-blocking send with copy78 default: // Channel full, skip logging to avoid blocking
79 default: // Channel full, skip logging to avoid blocking
80 }
81 }79 }
82 } else {80 return n, err
83 // For non-streaming responses: Buffer complete response81 }
82
83 if w.shouldBufferResponseBody() {
84 w.body.Write(data)84 w.body.Write(data)
85 }85 }
86 86
87 return n, err87 return n, err
88}88}
89 89
90func (w *ResponseWriterWrapper) shouldBufferResponseBody() bool {
91 if w.logger != nil && w.logger.IsEnabled() {
92 return true
93 }
94 if !w.logOnErrorOnly {
95 return false
96 }
97 status := w.statusCode
98 if status == 0 {
99 if statusWriter, ok := w.ResponseWriter.(interface{ Status() int }); ok && statusWriter != nil {
100 status = statusWriter.Status()
101 } else {
102 status = http.StatusOK
103 }
104 }
105 return status >= http.StatusBadRequest
106}
107
108// WriteString wraps the underlying ResponseWriter's WriteString method to capture response data.
109// Some handlers (and fmt/io helpers) write via io.StringWriter; without this override, those writes
110// bypass Write() and would be missing from request logs.
111func (w *ResponseWriterWrapper) WriteString(data string) (int, error) {
112 w.ensureHeadersCaptured()
113
114 // CRITICAL: Write to client first (zero latency)
115 n, err := w.ResponseWriter.WriteString(data)
116
117 // THEN: Capture for logging
118 if w.isStreaming && w.chunkChannel != nil {
119 select {
120 case w.chunkChannel <- []byte(data):
121 default:
122 }
123 return n, err
124 }
125
126 if w.shouldBufferResponseBody() {
127 w.body.WriteString(data)
128 }
129 return n, err
130}
131
90// WriteHeader wraps the underlying ResponseWriter's WriteHeader method.132// WriteHeader wraps the underlying ResponseWriter's WriteHeader method.
91// It captures the status code, detects if the response is streaming based on the Content-Type header,133// It captures the status code, detects if the response is streaming based on the Content-Type header,
92// and initializes the appropriate logging mechanism (standard or streaming).134// and initializes the appropriate logging mechanism (standard or streaming).
@@ -160,12 +202,16 @@ func (w *ResponseWriterWrapper) detectStreaming(contentType string) bool { · 67 unmodified lines
160 return true202 return true
161 }203 }
162 204
163 // Check request body for streaming indicators205 // If a concrete Content-Type is already set (e.g., application/json for error responses),
164 if w.requestInfo.Body != nil {206 // treat it as non-streaming instead of inferring from the request payload.
207 if strings.TrimSpace(contentType) != "" {
208 return false
209 }
210
211 // Only fall back to request payload hints when Content-Type is not set yet.
212 if w.requestInfo != nil && len(w.requestInfo.Body) > 0 {
165 bodyStr := string(w.requestInfo.Body)213 bodyStr := string(w.requestInfo.Body)
166 if strings.Contains(bodyStr, `"stream": true`) || strings.Contains(bodyStr, `"stream":true`) {214 return strings.Contains(bodyStr, `"stream": true`) || strings.Contains(bodyStr, `"stream":true`)
167 return true
168 }
169 }215 }
170 216
171 return false217 return false
@@ -221,7 +267,7 @@ func (w *ResponseWriterWrapper) Finalize(c *gin.Context) error { · 49 unmodified lines
221 return nil267 return nil
222 }268 }
223 269
224 if w.isStreaming {270 if w.isStreaming && w.streamWriter != nil {
225 if w.chunkChannel != nil {271 if w.chunkChannel != nil {
226 close(w.chunkChannel)272 close(w.chunkChannel)
227 w.chunkChannel = nil273 w.chunkChannel = nil
@@ -233,24 +279,19 @@ func (w *ResponseWriterWrapper) Finalize(c *gin.Context) error { · 5 unmodified lines
233 }279 }
234 280
235 // Write API Request and Response to the streaming log before closing281 // Write API Request and Response to the streaming log before closing
236 if w.streamWriter != nil {282 apiRequest := w.extractAPIRequest(c)
237 apiRequest := w.extractAPIRequest(c)283 if len(apiRequest) > 0 {
238 if len(apiRequest) > 0 {284 _ = w.streamWriter.WriteAPIRequest(apiRequest)
239 _ = w.streamWriter.WriteAPIRequest(apiRequest)285 }
240 }286 apiResponse := w.extractAPIResponse(c)
241 apiResponse := w.extractAPIResponse(c)287 if len(apiResponse) > 0 {
242 if len(apiResponse) > 0 {288 _ = w.streamWriter.WriteAPIResponse(apiResponse)
243 _ = w.streamWriter.WriteAPIResponse(apiResponse)
244 }
245 if err := w.streamWriter.Close(); err != nil {
246 w.streamWriter = nil
247 return err
248 }
249 w.streamWriter = nil
250 }289 }
251 if forceLog {290 if err := w.streamWriter.Close(); err != nil {
252 return w.logRequest(finalStatusCode, w.cloneHeaders(), w.body.Bytes(), w.extractAPIRequest(c), w.extractAPIResponse(c), slicesAPIResponseError, forceLog)291 w.streamWriter = nil
292 return err
253 }293 }
294 w.streamWriter = nil
254 return nil295 return nil
255 }296 }
256 297
@@ -335,26 +376,3 @@ func (w *ResponseWriterWrapper) logRequest(statusCode int, headers map[string][] · 78 unmodified lines
335 apiResponseErrors,376 apiResponseErrors,
336 )377 )
337}378}
338
339// Status returns the HTTP response status code captured by the wrapper.
340// It defaults to 200 if WriteHeader has not been called.
341func (w *ResponseWriterWrapper) Status() int {
342 if w.statusCode == 0 {
343 return 200 // Default status code
344 }
345 return w.statusCode
346}
347
348// Size returns the size of the response body in bytes for non-streaming responses.
349// For streaming responses, it returns -1, as the total size is unknown.
350func (w *ResponseWriterWrapper) Size() int {
351 if w.isStreaming {
352 return -1 // Unknown size for streaming responses
353 }
354 return w.body.Len()
355}
356
357// Written returns true if the response header has been written (i.e., a status code has been set).
358func (w *ResponseWriterWrapper) Written() bool {
359 return w.statusCode != 0
360}
sdk/api/handlers/handlers.go+56−4
@@ -5,6 +5,7 @@ package handlers · 4 unmodified lines
5 5
6import (6import (
7 "bytes"7 "bytes"
8 "encoding/json"
8 "fmt"9 "fmt"
9 "net/http"10 "net/http"
10 "strings"11 "strings"
@@ -117,6 +118,16 @@ func (h *BaseAPIHandler) GetContextWithCancel(handler interfaces.APIHandler, c * · 106 unmodified lines
117 newCtx = context.WithValue(newCtx, "handler", handler)118 newCtx = context.WithValue(newCtx, "handler", handler)
118 return newCtx, func(params ...interface{}) {119 return newCtx, func(params ...interface{}) {
119 if h.Cfg.RequestLog && len(params) == 1 {120 if h.Cfg.RequestLog && len(params) == 1 {
121 if existing, exists := c.Get("API_RESPONSE"); exists {
122 if existingBytes, ok := existing.([]byte); ok && len(bytes.TrimSpace(existingBytes)) > 0 {
123 switch params[0].(type) {
124 case error, string:
125 cancel()
126 return
127 }
128 }
129 }
130
120 var payload []byte131 var payload []byte
121 switch data := params[0].(type) {132 switch data := params[0].(type) {
122 case []byte:133 case []byte:
@@ -437,12 +448,53 @@ func (h *BaseAPIHandler) WriteErrorResponse(c *gin.Context, msg *interfaces.Erro · 314 unmodified lines
437 }448 }
438 }449 }
439 }450 }
440 c.Status(status)451
452 errText := http.StatusText(status)
441 if msg != nil && msg.Error != nil {453 if msg != nil && msg.Error != nil {
442 _, _ = c.Writer.Write([]byte(msg.Error.Error()))454 if v := strings.TrimSpace(msg.Error.Error()); v != "" {
443 } else {455 errText = v
444 _, _ = c.Writer.Write([]byte(http.StatusText(status)))456 }
457 }
458
459 // Prefer preserving upstream JSON error bodies when possible.
460 buildJSONBody := func() []byte {
461 trimmed := strings.TrimSpace(errText)
462 if trimmed != "" && json.Valid([]byte(trimmed)) {
463 return []byte(trimmed)
464 }
465 errType := "invalid_request_error"
466 switch status {
467 case http.StatusUnauthorized:
468 errType = "authentication_error"
469 case http.StatusForbidden:
470 errType = "permission_error"
471 case http.StatusTooManyRequests:
472 errType = "rate_limit_error"
473 default:
474 if status >= http.StatusInternalServerError {
475 errType = "server_error"
476 }
477 }
478 payload, err := json.Marshal(ErrorResponse{
479 Error: ErrorDetail{
480 Message: errText,
481 Type: errType,
482 },
483 })
484 if err != nil {
485 return []byte(fmt.Sprintf(`{"error":{"message":%q,"type":"server_error"}}`, errText))
486 }
487 return payload
445 }488 }
489
490 body := buildJSONBody()
491 c.Set("API_RESPONSE", bytes.Clone(body))
492
493 if !c.Writer.Written() {
494 c.Writer.Header().Set("Content-Type", "application/json")
495 }
496 c.Status(status)
497 _, _ = c.Writer.Write(body)
446}498}
447 499
448func (h *BaseAPIHandler) LoggingAPIResponseError(ctx context.Context, err *interfaces.ErrorMessage) {500func (h *BaseAPIHandler) LoggingAPIResponseError(ctx context.Context, err *interfaces.ErrorMessage) {