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

@@ -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()
+	}
+}

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{

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
 }

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 "***"
+}