diff --git a/middleware/logging.go b/middleware/logging.go index 6d8b09d..4c7a348 100644 --- a/middleware/logging.go +++ b/middleware/logging.go @@ -255,12 +255,69 @@ func WithHTTPLogging(opts ...LogMiddlewareOption) fiber.Handler { } info.FinishRequestInfo(&rw) - logger.Log(c.UserContext(), obslog.LevelInfo, info.CLFString()) + + accessLogger := logger.With(obslog.String("http_client_ip", info.RemoteAddress)) + if body := errorBodyForLog(c, statusCode, mid.ObfuscationDisabled); body != "" { + accessLogger = accessLogger.With(obslog.String("http_error", body)) + } + + accessLogger.Log(c.UserContext(), obslog.LevelInfo, info.CLFString()) return err } } +// maxErrorBodyLogLen caps the http_error field so a large error response body +// cannot bloat the access log entry. 2 KiB comfortably covers structured API +// error payloads while bounding log volume. +const maxErrorBodyLogLen = 2048 + +// errorBodyForLog returns a sanitized, length-capped copy of the response body +// suitable for the http_error log field, or "" when it should not be logged. +// +// Bodies are only logged for error responses (status >= 400). The body is +// obfuscated with the same content-type-aware redaction pipeline used for +// request bodies (unless obfuscation is disabled), so sensitive fields are not +// leaked, and is then truncated to maxErrorBodyLogLen bytes on a UTF-8 rune +// boundary. +func errorBodyForLog(c *fiber.Ctx, statusCode int, obfuscationDisabled bool) string { + if c == nil || statusCode < fiber.StatusBadRequest { + return "" + } + + bodyBytes := c.Response().Body() + if len(bodyBytes) == 0 { + return "" + } + + body := string(bodyBytes) + if !obfuscationDisabled { + body = getResponseBodyObfuscatedString(c, bodyBytes) + } + + return truncateLogBody(body) +} + +// truncateLogBody caps body at maxErrorBodyLogLen bytes, cutting on a rune +// boundary so the stored value is always valid UTF-8. +func truncateLogBody(body string) string { + if len(body) <= maxErrorBodyLogLen { + return body + } + + lastFit := 0 + + for i := range body { + if i > maxErrorBodyLogLen { + return body[:lastFit] + } + + lastFit = i + } + + return body[:lastFit] +} + func httpStatusCode(c *fiber.Ctx, err error) int { statusCode := c.Response().StatusCode() if err == nil { diff --git a/middleware/logging_obfuscation.go b/middleware/logging_obfuscation.go index 5095190..b1569ab 100644 --- a/middleware/logging_obfuscation.go +++ b/middleware/logging_obfuscation.go @@ -26,6 +26,21 @@ func getBodyObfuscatedString(c *fiber.Ctx, bodyBytes []byte) string { } } +// getResponseBodyObfuscatedString obfuscates a response body for logging, +// keying off the response Content-Type (not the request header). JSON error +// payloads are passed through the same key-based redaction as request bodies so +// sensitive fields are never written to the http_error log field; any other +// content type is reduced to the [REDACTED] placeholder. +func getResponseBodyObfuscatedString(c *fiber.Ctx, bodyBytes []byte) string { + contentType := strings.ToLower(string(c.Response().Header.ContentType())) + + if strings.Contains(contentType, "application/json") { + return handleJSONBody(bodyBytes) + } + + return redactedBody +} + func obfuscateMapRecursively(data map[string]any, depth int) { if depth >= maxObfuscationDepth { return diff --git a/middleware/logging_test.go b/middleware/logging_test.go index 68ceda4..bbf0128 100644 --- a/middleware/logging_test.go +++ b/middleware/logging_test.go @@ -250,6 +250,93 @@ func TestWithHTTPLoggingLogsErrorStatus(t *testing.T) { assert.Contains(t, messages[0], " 500 ") } +func TestWithHTTPLoggingAddsClientIPField(t *testing.T) { + logger := &captureLogger{} + app := fiber.New() + app.Use(WithHTTPLogging(WithCustomLogger(logger))) + app.Get("/ok", func(c *fiber.Ctx) error { + return c.SendString("ok") + }) + + req := httptest.NewRequest(http.MethodGet, "/ok", nil) + resp, err := app.Test(req) + require.NoError(t, err) + defer func() { require.NoError(t, resp.Body.Close()) }() + + _, fields := logger.snapshot() + + var clientIPFound bool + + for _, f := range fields { + if f.Key != "http_client_ip" { + continue + } + + clientIPFound = true + + ip, ok := f.Value.(string) + require.True(t, ok, "http_client_ip should be a string") + assert.NotEmpty(t, ip) + } + + assert.True(t, clientIPFound, "expected http_client_ip field on access log entry") +} + +func TestWithHTTPLoggingLogsSanitizedErrorBody(t *testing.T) { + logger := &captureLogger{} + app := fiber.New() + app.Use(WithHTTPLogging(WithCustomLogger(logger))) + app.Get("/fail", func(c *fiber.Ctx) error { + c.Set(headerContentType, "application/json") + + return c.Status(http.StatusBadRequest). + SendString(`{"error":"invalid request","password":"secret"}`) + }) + + req := httptest.NewRequest(http.MethodGet, "/fail", nil) + resp, err := app.Test(req) + require.NoError(t, err) + defer func() { require.NoError(t, resp.Body.Close()) }() + + _, fields := logger.snapshot() + + var errorBody string + + for _, f := range fields { + if f.Key == "http_error" { + if s, ok := f.Value.(string); ok { + errorBody = s + } + } + } + + require.NotEmpty(t, errorBody, "expected http_error field for 4xx response") + assert.Contains(t, errorBody, "invalid request") + assert.NotContains(t, errorBody, "secret") +} + +func TestWithHTTPLoggingOmitsErrorBodyForSuccess(t *testing.T) { + logger := &captureLogger{} + app := fiber.New() + app.Use(WithHTTPLogging(WithCustomLogger(logger))) + app.Get("/ok", func(c *fiber.Ctx) error { + c.Set(headerContentType, "application/json") + + return c.SendString(`{"status":"ok"}`) + }) + + req := httptest.NewRequest(http.MethodGet, "/ok", nil) + resp, err := app.Test(req) + require.NoError(t, err) + defer func() { require.NoError(t, resp.Body.Close()) }() + + _, fields := logger.snapshot() + + for _, f := range fields { + assert.NotEqual(t, "http_error", f.Key, "http_error must not be logged for 2xx responses") + } +} + func TestWithGrpcLoggingUsesBodyRequestIDAndLogsResult(t *testing.T) { logger := &captureLogger{} bodyRequestID := "4fbf011b-bb11-4c73-9f7c-4f8e19ca8402"