From afc4da7491fbd81057f4217a331face3be41303e Mon Sep 17 00:00:00 2001 From: Noooste <83548733+Noooste@users.noreply.github.com> Date: Sun, 19 Apr 2026 13:59:08 +0200 Subject: [PATCH] feat(logging): implement per-request logging middleware with access log Signed-off-by: Noooste <83548733+Noooste@users.noreply.github.com> --- backend/internal/middleware/logging.go | 82 ++++++++++++++++++++++++++ backend/main.go | 56 ++++++++++++------ backend/pkg/logger/ctx.go | 9 +-- backend/pkg/logger/redact.go | 22 +++++++ 4 files changed, 147 insertions(+), 22 deletions(-) create mode 100644 backend/internal/middleware/logging.go create mode 100644 backend/pkg/logger/redact.go diff --git a/backend/internal/middleware/logging.go b/backend/internal/middleware/logging.go new file mode 100644 index 0000000..3f604f5 --- /dev/null +++ b/backend/internal/middleware/logging.go @@ -0,0 +1,82 @@ +package middleware + +import ( + "time" + + logpkg "Noooste/garage-ui/pkg/logger" + + "github.com/gofiber/fiber/v3" + "github.com/rs/zerolog" +) + +// LoggerLocalsKey is the fiber.Ctx.Locals key carrying the per-request logger. +const LoggerLocalsKey = "logger" + +// Logging returns middleware that (1) builds a per-request zerolog.Logger +// bound with request_id/method/path/remote_ip/user_agent, (2) injects it into +// c.Context() so service layers can retrieve it via logger.FromCtx, and +// (3) emits a single access-log line after the handler runs. +// +// The base logger is the one to derive from — typically the global zerolog +// logger configured at startup. Tests pass a buffer-backed logger here. +// +// Access-log line fields: request_id, method, path, remote_ip, user_agent, +// status, duration_ms, bytes_out. Skipped for /health and OPTIONS. +// Level is chosen from status: >=500 error, >=400 warn, else info. +func Logging(base zerolog.Logger) fiber.Handler { + return func(c fiber.Ctx) error { + requestID, _ := c.Locals(RequestIDLocalsKey).(string) + + reqLogger := base.With(). + Str("request_id", requestID). + Str("method", c.Method()). + Str("path", c.Path()). + Str("remote_ip", c.IP()). + Str("user_agent", c.Get("User-Agent")). + Logger() + + c.Locals(LoggerLocalsKey, reqLogger) + c.SetContext(logpkg.IntoCtx(c.Context(), reqLogger)) + + start := time.Now() + err := c.Next() + duration := time.Since(start) + + if skipAccessLog(c) { + return err + } + + status := c.Response().StatusCode() + bytesOut := len(c.Response().Body()) + + evt := eventForStatus(&reqLogger, status) + evt. + Int("status", status). + Float64("duration_ms", float64(duration.Microseconds())/1000.0). + Int("bytes_out", bytesOut). + Msg("http_request") + + return err + } +} + +func skipAccessLog(c fiber.Ctx) bool { + if c.Method() == fiber.MethodOptions { + return true + } + if c.Path() == "/health" { + return true + } + return false +} + +func eventForStatus(l *zerolog.Logger, status int) *zerolog.Event { + switch { + case status >= 500: + return l.Error() + case status >= 400: + return l.Warn() + default: + return l.Info() + } +} diff --git a/backend/main.go b/backend/main.go index 177473c..d2a7f77 100644 --- a/backend/main.go +++ b/backend/main.go @@ -5,17 +5,22 @@ import ( "fmt" "os" "os/signal" + "runtime" + "runtime/debug" "syscall" + "time" "Noooste/garage-ui/internal/auth" "Noooste/garage-ui/internal/config" "Noooste/garage-ui/internal/handlers" + appmw "Noooste/garage-ui/internal/middleware" "Noooste/garage-ui/internal/routes" "Noooste/garage-ui/internal/services" "Noooste/garage-ui/pkg/logger" "github.com/gofiber/fiber/v3" "github.com/gofiber/fiber/v3/middleware/recover" + "github.com/rs/zerolog/log" ) // @title Garage UI API @@ -78,6 +83,7 @@ func main() { logger.Info(). Str("config_path", *configPath). Str("version", version). + Str("go_version", runtime.Version()). Str("environment", cfg.Server.Environment). Msg("Starting Garage UI Backend") @@ -147,8 +153,22 @@ func main() { ErrorHandler: customErrorHandler, }) - // Apply global middleware - app.Use(recover.New()) // Panic recovery + // Apply global middleware (order matters): + // 1. recover — must be outermost so panics become 500s. + // 2. RequestID — mints/reads X-Request-ID before any logger needs it. + // 3. Logging — builds per-request zerolog logger + emits access log. + // Auth middleware is installed per-route inside routes.SetupRoutes. + app.Use(recover.New(recover.Config{ + EnableStackTrace: true, + StackTraceHandler: func(c fiber.Ctx, e interface{}) { + logger.FromCtx(c.Context()).Error(). + Interface("panic", e). + Bytes("stack", debug.Stack()). + Msg("panic_recovered") + }, + })) + app.Use(appmw.RequestID()) + app.Use(appmw.Logging(log.Logger)) // Setup routes logger.Info().Msg("Setting up routes") @@ -178,38 +198,38 @@ func main() { } }() - // Wait for interrupt signal to gracefully shutdown the server + // Wait for interrupt signal to gracefully shutdown the server. quit := make(chan os.Signal, 1) signal.Notify(quit, os.Interrupt, syscall.SIGTERM) - <-quit + sig := <-quit - logger.Info().Msg("Shutting down server") + logger.Info().Str("signal", sig.String()).Msg("Shutting down server") + shutdownStart := time.Now() if err := app.Shutdown(); err != nil { logger.Fatal().Err(err).Msg("Server shutdown failed") } - logger.Info().Msg("Server stopped gracefully") + logger.Info(). + Dur("shutdown_duration", time.Since(shutdownStart)). + Msg("Server stopped gracefully") } -// customErrorHandler handles errors globally +// customErrorHandler handles errors globally. It uses the per-request logger +// from c.Context() so request_id / user_id attach automatically, and it +// demotes expected 4xx responses to warn (5xx stays at error). func customErrorHandler(c fiber.Ctx, err error) error { - // Default to 500 Internal Server Error code := fiber.StatusInternalServerError - - // Check if it's a Fiber error if e, ok := err.(*fiber.Error); ok { code = e.Code } - // Log the error - logger.Error(). - Err(err). - Int("status_code", code). - Str("method", c.Method()). - Str("path", c.Path()). - Msg("Request error") + l := logger.FromCtx(c.Context()) + evt := l.Error() + if code >= 400 && code < 500 { + evt = l.Warn() + } + evt.Err(err).Int("status_code", code).Msg("request_error") - // Return JSON error response return c.Status(code).JSON(fiber.Map{ "success": false, "error": fiber.Map{ diff --git a/backend/pkg/logger/ctx.go b/backend/pkg/logger/ctx.go index 70f2ace..9a643e3 100644 --- a/backend/pkg/logger/ctx.go +++ b/backend/pkg/logger/ctx.go @@ -18,12 +18,13 @@ func IntoCtx(ctx context.Context, l zerolog.Logger) context.Context { // FromCtx returns the logger bound to ctx. If no logger is bound (e.g. the // call is outside any middleware, or ctx is nil), it returns the global -// logger. Never returns a zero-value zerolog.Logger. -func FromCtx(ctx context.Context) zerolog.Logger { +// logger. Never returns nil. +func FromCtx(ctx context.Context) *zerolog.Logger { if ctx != nil { if l, ok := ctx.Value(ctxKey{}).(zerolog.Logger); ok { - return l + return &l } } - return Get().Logger + l := Get().Logger + return &l } diff --git a/backend/pkg/logger/redact.go b/backend/pkg/logger/redact.go new file mode 100644 index 0000000..56e0380 --- /dev/null +++ b/backend/pkg/logger/redact.go @@ -0,0 +1,22 @@ +package logger + +// redactThreshold is the minimum length at which partial visibility is shown. +// Below this, the entire value is replaced with "***" because first-4/last-4 +// would leak too much of short strings. +const redactThreshold = 12 + +// RedactKey returns a partially-visible form of a non-secret identifier +// (access key ID, user ID, etc.) showing first 4 and last 4 characters. +// Shorter values are fully redacted to avoid over-exposure. +func RedactKey(s string) string { + if len(s) < redactThreshold { + return "***" + } + return s[:4] + "…" + s[len(s)-4:] +} + +// RedactToken returns "***" for any secret (passwords, bearer tokens, JWT, +// client secrets). Secrets must never be partially visible in logs. +func RedactToken(s string) string { + return "***" +}