diff --git a/backend/internal/api/middleware/recovery.go b/backend/internal/api/middleware/recovery.go index cc333725..badbb378 100644 --- a/backend/internal/api/middleware/recovery.go +++ b/backend/internal/api/middleware/recovery.go @@ -1,7 +1,6 @@ package middleware import ( - "log" "net/http" "runtime/debug" @@ -14,10 +13,16 @@ func Recovery(verbose bool) gin.HandlerFunc { return func(c *gin.Context) { defer func() { if r := recover(); r != nil { + // Try to get a request-scoped logger; fall back to global logger + entry := GetRequestLogger(c) if verbose { - log.Printf("PANIC: %v\nRequest: %s %s\nHeaders: %v\nStacktrace:\n%s", r, c.Request.Method, c.Request.URL.String(), c.Request.Header, debug.Stack()) + entry.WithFields(map[string]interface{}{ + "method": c.Request.Method, + "path": c.Request.URL.Path, + "headers": c.Request.Header, + }).Errorf("PANIC: %v\nStacktrace:\n%s", r, debug.Stack()) } else { - log.Printf("PANIC: %v", r) + entry.Errorf("PANIC: %v", r) } c.AbortWithStatusJSON(http.StatusInternalServerError, gin.H{"error": "internal server error"}) } diff --git a/backend/internal/api/middleware/recovery_test.go b/backend/internal/api/middleware/recovery_test.go index 20a88a49..b2122931 100644 --- a/backend/internal/api/middleware/recovery_test.go +++ b/backend/internal/api/middleware/recovery_test.go @@ -8,6 +8,7 @@ import ( "strings" "testing" + "github.com/Wikid82/charon/backend/internal/logger" "github.com/gin-gonic/gin" ) @@ -16,8 +17,11 @@ func TestRecoveryLogsStacktraceVerbose(t *testing.T) { buf := &bytes.Buffer{} log.SetOutput(buf) defer log.SetOutput(old) + // Ensure structured logger writes to the same buffer and enable debug + logger.Init(true, buf) router := gin.New() + router.Use(RequestID()) router.Use(Recovery(true)) router.GET("/panic", func(c *gin.Context) { panic("test panic") @@ -38,6 +42,9 @@ func TestRecoveryLogsStacktraceVerbose(t *testing.T) { if !strings.Contains(out, "Stacktrace:") { t.Fatalf("verbose log did not include stack trace: %s", out) } + if !strings.Contains(out, "request_id") { + t.Fatalf("verbose log did not include request_id: %s", out) + } } func TestRecoveryLogsBriefWhenNotVerbose(t *testing.T) { @@ -46,7 +53,10 @@ func TestRecoveryLogsBriefWhenNotVerbose(t *testing.T) { log.SetOutput(buf) defer log.SetOutput(old) + // Ensure structured logger writes to the same buffer and keep debug off + logger.Init(false, buf) router := gin.New() + router.Use(RequestID()) router.Use(Recovery(false)) router.GET("/panic", func(c *gin.Context) { panic("brief panic") diff --git a/backend/internal/api/middleware/request_id.go b/backend/internal/api/middleware/request_id.go new file mode 100644 index 00000000..120c311d --- /dev/null +++ b/backend/internal/api/middleware/request_id.go @@ -0,0 +1,35 @@ +package middleware + +import ( + "github.com/Wikid82/charon/backend/internal/logger" + "github.com/gin-gonic/gin" + "github.com/google/uuid" + "github.com/sirupsen/logrus" +) + +const RequestIDKey = "requestID" +const RequestIDHeader = "X-Request-ID" + +// RequestID generates a uuid per request and places it in context and header. +func RequestID() gin.HandlerFunc { + return func(c *gin.Context) { + rid := uuid.New().String() + c.Set(RequestIDKey, rid) + c.Writer.Header().Set(RequestIDHeader, rid) + // Add to logger fields for this request + entry := logger.WithFields(map[string]interface{}{"request_id": rid}) + c.Set("logger", entry) + c.Next() + } +} + +// GetRequestLogger retrieves the request-scoped logger from context or the global logger +func GetRequestLogger(c *gin.Context) *logrus.Entry { + if v, ok := c.Get("logger"); ok { + if entry, ok := v.(*logrus.Entry); ok { + return entry + } + } + // fallback + return logger.Log() +} diff --git a/backend/internal/api/middleware/request_id_test.go b/backend/internal/api/middleware/request_id_test.go new file mode 100644 index 00000000..1813e922 --- /dev/null +++ b/backend/internal/api/middleware/request_id_test.go @@ -0,0 +1,37 @@ +package middleware + +import ( + "bytes" + "net/http" + "net/http/httptest" + "testing" + + "github.com/Wikid82/charon/backend/internal/logger" + "github.com/gin-gonic/gin" +) + +func TestRequestIDAddsHeaderAndLogger(t *testing.T) { + buf := &bytes.Buffer{} + logger.Init(true, buf) + + router := gin.New() + router.Use(RequestID()) + router.GET("/test", func(c *gin.Context) { + // Ensure logger exists in context and header is present + if _, ok := c.Get("logger"); !ok { + t.Fatalf("expected request-scoped logger in context") + } + c.String(200, "ok") + }) + + req := httptest.NewRequest(http.MethodGet, "/test", nil) + w := httptest.NewRecorder() + router.ServeHTTP(w, req) + + if w.Code != http.StatusOK { + t.Fatalf("expected status 200, got %d", w.Code) + } + if w.Header().Get(RequestIDHeader) == "" { + t.Fatalf("expected response to include X-Request-ID header") + } +} diff --git a/backend/internal/api/middleware/request_logger.go b/backend/internal/api/middleware/request_logger.go new file mode 100644 index 00000000..2bf5b9c4 --- /dev/null +++ b/backend/internal/api/middleware/request_logger.go @@ -0,0 +1,24 @@ +package middleware + +import ( + "time" + + "github.com/gin-gonic/gin" +) + +// RequestLogger logs basic request information along with the request_id. +func RequestLogger() gin.HandlerFunc { + return func(c *gin.Context) { + start := time.Now() + c.Next() + latency := time.Since(start) + entry := GetRequestLogger(c) + entry.WithFields(map[string]interface{}{ + "status": c.Writer.Status(), + "method": c.Request.Method, + "path": c.Request.URL.Path, + "latency": latency.String(), + "client": c.ClientIP(), + }).Info("handled request") + } +} diff --git a/backend/internal/api/middleware/request_logger_test.go b/backend/internal/api/middleware/request_logger_test.go new file mode 100644 index 00000000..15c58b67 --- /dev/null +++ b/backend/internal/api/middleware/request_logger_test.go @@ -0,0 +1,36 @@ +package middleware + +import ( + "bytes" + "net/http" + "net/http/httptest" + "strings" + "testing" + + "github.com/Wikid82/charon/backend/internal/logger" + "github.com/gin-gonic/gin" +) + +func TestRequestLoggerIncludesRequestID(t *testing.T) { + buf := &bytes.Buffer{} + logger.Init(true, buf) + + router := gin.New() + router.Use(RequestID()) + router.Use(RequestLogger()) + router.GET("/ok", func(c *gin.Context) { c.String(200, "ok") }) + + req := httptest.NewRequest(http.MethodGet, "/ok", nil) + w := httptest.NewRecorder() + router.ServeHTTP(w, req) + if w.Code != http.StatusOK { + t.Fatalf("unexpected status code: %d", w.Code) + } + out := buf.String() + if !strings.Contains(out, "request_id") { + t.Fatalf("expected log output to include request_id: %s", out) + } + if !strings.Contains(out, "handled request") { + t.Fatalf("expected log output to indicate handled request: %s", out) + } +}