feat(logging): enhance logging in GarageAdminService with detailed request information

Signed-off-by: Noooste <83548733+Noooste@users.noreply.github.com>

backend/internal/middleware/auth.go

@@ -4,60 +4,90 @@ import (
 	"Noooste/garage-ui/internal/auth"
 	"Noooste/garage-ui/internal/config"
 	"Noooste/garage-ui/internal/models"
+	logpkg "Noooste/garage-ui/pkg/logger"
 
 	"github.com/gofiber/fiber/v3"
 )
 
-// AuthMiddleware supports admin and OIDC authentication
+// AuthMiddleware supports admin and OIDC authentication. On success it
+// enriches the per-request logger (stored in c.Context() by the Logging
+// middleware) with user_id and auth_method so downstream service log lines
+// carry user identity. On failure it emits a warn log with the auth_method
+// tried and a reason — never the token value.
 func AuthMiddleware(cfg *config.AuthConfig, authService *auth.Service) fiber.Handler {
 	return func(c fiber.Ctx) error {
-		// If no auth is enabled, allow all requests
+		// If no auth is enabled, allow all requests.
 		if !cfg.Admin.Enabled && !cfg.OIDC.Enabled {
 			return c.Next()
 		}
 
-		// Get Authorization header
 		authHeader := c.Get("Authorization")
 
-		// Try admin auth if enabled and header is present
+		// Try admin auth if enabled and header is present.
 		if cfg.Admin.Enabled && authHeader != "" {
-			// Check if it's a Bearer token (JWT from admin login)
 			if len(authHeader) > 7 && authHeader[:7] == "Bearer " {
 				token := authHeader[7:]
-
-				// Validate JWT session token
 				userInfo, err := authService.ValidateSessionToken(token)
 				if err == nil {
-					// Valid admin token
 					c.Locals("userInfo", userInfo)
 					c.Locals("username", userInfo.Username)
 					if userInfo.Email != "" {
 						c.Locals("email", userInfo.Email)
 					}
+					enrichRequestLogger(c, userInfo.Username, "admin")
 					return c.Next()
 				}
 			}
 		}
 
-		// Try OIDC auth if enabled
+		// Try OIDC auth if enabled.
 		if cfg.OIDC.Enabled {
 			sessionCookie := c.Cookies(cfg.OIDC.CookieName)
 			if sessionCookie != "" {
-				// Validate JWT session token from cookie
 				userInfo, err := authService.ValidateSessionToken(sessionCookie)
 				if err == nil {
-					// Valid OIDC token
 					c.Locals("userInfo", userInfo)
 					c.Locals("username", userInfo.Username)
 					c.Locals("email", userInfo.Email)
+					enrichRequestLogger(c, userInfo.Username, "oidc")
 					return c.Next()
 				}
 			}
 		}
 
-		// No valid authentication found
+		// Auth failed — log at warn without exposing token material.
+		logpkg.FromCtx(c.Context()).Warn().
+			Str("auth_method", authMethodsEnabled(cfg)).
+			Str("reason", "no_valid_credentials").
+			Msg("authentication_failed")
+
 		return c.Status(fiber.StatusUnauthorized).JSON(
 			models.ErrorResponse(models.ErrCodeUnauthorized, "Authentication required"),
 		)
 	}
 }
+
+// enrichRequestLogger rebinds the per-request logger in c.Context() with
+// user_id and auth_method. Subsequent logpkg.FromCtx(c.Context()) calls
+// return the enriched logger.
+func enrichRequestLogger(c fiber.Ctx, userID, authMethod string) {
+	l := logpkg.FromCtx(c.Context()).With().
+		Str("user_id", userID).
+		Str("auth_method", authMethod).
+		Logger()
+	c.Locals(LoggerLocalsKey, l)
+	c.SetContext(logpkg.IntoCtx(c.Context(), l))
+}
+
+func authMethodsEnabled(cfg *config.AuthConfig) string {
+	switch {
+	case cfg.Admin.Enabled && cfg.OIDC.Enabled:
+		return "admin+oidc"
+	case cfg.Admin.Enabled:
+		return "admin"
+	case cfg.OIDC.Enabled:
+		return "oidc"
+	default:
+		return "none"
+	}
+}

backend/internal/services/admin.go

@@ -4,11 +4,13 @@ import (
 	"Noooste/garage-ui/internal/config"
 	"Noooste/garage-ui/internal/models"
 	"Noooste/garage-ui/pkg/utils"
+	logpkg "Noooste/garage-ui/pkg/logger"
 	"context"
 	"encoding/json"
 	"fmt"
 	"io"
 	"net/http"
+	"time"
 
 	"github.com/Noooste/azuretls-client"
 )
@@ -177,100 +179,177 @@ func (s *GarageAdminService) ImportKey(ctx context.Context, req models.ImportKey
 	return &result, nil
 }
 
-// ListBuckets returns all buckets in the cluster
+// ListBuckets returns all buckets in the cluster.
 func (s *GarageAdminService) ListBuckets(ctx context.Context) ([]models.ListBucketsResponseItem, error) {
+	log := logpkg.FromCtx(ctx).With().
+		Str("component", "admin").
+		Str("operation", "list_buckets").
+		Logger()
+
+	log.Debug().Msg("listing buckets")
+	start := time.Now()
+
 	resp, err := s.doRequest(ctx, http.MethodGet, "/v2/ListBuckets", nil)
 	if err != nil {
+		log.Error().Err(err).
+			Float64("duration_ms", msSince(start)).
+			Str("outcome", "failure").
+			Msg("garage list_buckets request failed")
 		return nil, fmt.Errorf("request failed: %w", err)
 	}
 
 	var result []models.ListBucketsResponseItem
 	if err := decodeResponse(resp, &result); err != nil {
+		log.Error().Err(err).
+			Float64("duration_ms", msSince(start)).
+			Str("outcome", "failure").
+			Msg("garage list_buckets decode failed")
 		return nil, fmt.Errorf("failed to decode response: %w", err)
 	}
 
+	log.Debug().
+		Float64("duration_ms", msSince(start)).
+		Str("outcome", "success").
+		Int("count", len(result)).
+		Msg("listed buckets")
 	return result, nil
 }
 
-// GetBucketInfo returns detailed information about a bucket by ID
+// GetBucketInfo returns detailed information about a bucket by ID.
 func (s *GarageAdminService) GetBucketInfo(ctx context.Context, bucketID string) (*models.GarageBucketInfo, error) {
-	path := fmt.Sprintf("/v2/GetBucketInfo?id=%s", bucketID)
+	log := logpkg.FromCtx(ctx).With().
+		Str("component", "admin").
+		Str("operation", "get_bucket_info").
+		Str("bucket_id", bucketID).
+		Logger()
 
-	resp, err := s.doRequest(ctx, http.MethodGet, path, nil)
+	log.Debug().Msg("getting bucket info")
+	start := time.Now()
+
+	resp, err := s.doRequest(ctx, http.MethodGet, fmt.Sprintf("/v2/GetBucketInfo?id=%s", bucketID), nil)
 	if err != nil {
+		log.Error().Err(err).Float64("duration_ms", msSince(start)).Str("outcome", "failure").Msg("garage get_bucket_info request failed")
 		return nil, fmt.Errorf("request failed: %w", err)
 	}
 
 	var result models.GarageBucketInfo
 	if err := decodeResponse(resp, &result); err != nil {
+		log.Error().Err(err).Float64("duration_ms", msSince(start)).Str("outcome", "failure").Msg("garage get_bucket_info decode failed")
 		return nil, fmt.Errorf("failed to decode response: %w", err)
 	}
 
+	log.Debug().Float64("duration_ms", msSince(start)).Str("outcome", "success").Msg("got bucket info")
 	return &result, nil
 }
 
-// GetBucketInfoByAlias returns detailed information about a bucket by its global alias
+// GetBucketInfoByAlias returns detailed information about a bucket by its global alias.
 func (s *GarageAdminService) GetBucketInfoByAlias(ctx context.Context, globalAlias string) (*models.GarageBucketInfo, error) {
-	path := fmt.Sprintf("/v2/GetBucketInfo?globalAlias=%s", globalAlias)
+	log := logpkg.FromCtx(ctx).With().
+		Str("component", "admin").
+		Str("operation", "get_bucket_info_by_alias").
+		Str("bucket", globalAlias).
+		Logger()
 
-	resp, err := s.doRequest(ctx, http.MethodGet, path, nil)
+	log.Debug().Msg("getting bucket info by alias")
+	start := time.Now()
+
+	resp, err := s.doRequest(ctx, http.MethodGet, fmt.Sprintf("/v2/GetBucketInfo?globalAlias=%s", globalAlias), nil)
 	if err != nil {
+		log.Error().Err(err).Float64("duration_ms", msSince(start)).Str("outcome", "failure").Msg("garage get_bucket_info_by_alias request failed")
 		return nil, fmt.Errorf("request failed: %w", err)
 	}
 
 	var result models.GarageBucketInfo
 	if err = decodeResponse(resp, &result); err != nil {
+		log.Error().Err(err).Float64("duration_ms", msSince(start)).Str("outcome", "failure").Msg("garage get_bucket_info_by_alias decode failed")
 		return nil, fmt.Errorf("failed to decode response: %w", err)
 	}
 
+	log.Debug().Float64("duration_ms", msSince(start)).Str("outcome", "success").Str("bucket_id", result.ID).Msg("got bucket info by alias")
 	return &result, nil
 }
 
-// CreateBucket creates a new bucket via the Admin API
+// CreateBucket creates a new bucket via the Admin API.
 func (s *GarageAdminService) CreateBucket(ctx context.Context, req models.CreateBucketAdminRequest) (*models.GarageBucketInfo, error) {
+	var alias string
+	if req.GlobalAlias != nil {
+		alias = *req.GlobalAlias
+	}
+	log := logpkg.FromCtx(ctx).With().
+		Str("component", "admin").
+		Str("operation", "create_bucket").
+		Str("bucket", alias).
+		Logger()
+
+	log.Info().Msg("creating bucket")
+	start := time.Now()
+
 	resp, err := s.doRequest(ctx, http.MethodPost, "/v2/CreateBucket", req)
 	if err != nil {
+		log.Error().Err(err).Float64("duration_ms", msSince(start)).Str("outcome", "failure").Msg("garage create_bucket request failed")
 		return nil, fmt.Errorf("request failed: %w", err)
 	}
 
 	var result models.GarageBucketInfo
 	if err := decodeResponse(resp, &result); err != nil {
+		log.Error().Err(err).Float64("duration_ms", msSince(start)).Str("outcome", "failure").Msg("garage create_bucket decode failed")
 		return nil, fmt.Errorf("failed to decode response: %w", err)
 	}
 
+	log.Info().Float64("duration_ms", msSince(start)).Str("outcome", "success").Str("bucket_id", result.ID).Msg("bucket created")
 	return &result, nil
 }
 
-// UpdateBucket updates bucket settings
+// UpdateBucket updates bucket settings.
 func (s *GarageAdminService) UpdateBucket(ctx context.Context, bucketID string, req models.UpdateBucketRequest) (*models.GarageBucketInfo, error) {
-	path := fmt.Sprintf("/v2/UpdateBucket?id=%s", bucketID)
+	log := logpkg.FromCtx(ctx).With().
+		Str("component", "admin").
+		Str("operation", "update_bucket").
+		Str("bucket_id", bucketID).
+		Logger()
 
-	resp, err := s.doRequest(ctx, http.MethodPost, path, req)
+	log.Info().Msg("updating bucket")
+	start := time.Now()
+
+	resp, err := s.doRequest(ctx, http.MethodPost, fmt.Sprintf("/v2/UpdateBucket?id=%s", bucketID), req)
 	if err != nil {
+		log.Error().Err(err).Float64("duration_ms", msSince(start)).Str("outcome", "failure").Msg("garage update_bucket request failed")
 		return nil, fmt.Errorf("request failed: %w", err)
 	}
 
 	var result models.GarageBucketInfo
 	if err := decodeResponse(resp, &result); err != nil {
+		log.Error().Err(err).Float64("duration_ms", msSince(start)).Str("outcome", "failure").Msg("garage update_bucket decode failed")
 		return nil, fmt.Errorf("failed to decode response: %w", err)
 	}
 
+	log.Info().Float64("duration_ms", msSince(start)).Str("outcome", "success").Msg("bucket updated")
 	return &result, nil
 }
 
-// DeleteBucket deletes a bucket
+// DeleteBucket deletes a bucket.
 func (s *GarageAdminService) DeleteBucket(ctx context.Context, bucketID string) error {
-	path := fmt.Sprintf("/v2/DeleteBucket?id=%s", bucketID)
+	log := logpkg.FromCtx(ctx).With().
+		Str("component", "admin").
+		Str("operation", "delete_bucket").
+		Str("bucket_id", bucketID).
+		Logger()
 
-	resp, err := s.doRequest(ctx, http.MethodPost, path, nil)
+	log.Info().Msg("deleting bucket")
+	start := time.Now()
+
+	resp, err := s.doRequest(ctx, http.MethodPost, fmt.Sprintf("/v2/DeleteBucket?id=%s", bucketID), nil)
 	if err != nil {
+		log.Error().Err(err).Float64("duration_ms", msSince(start)).Str("outcome", "failure").Msg("garage delete_bucket request failed")
 		return fmt.Errorf("request failed: %w", err)
 	}
 
 	if err := decodeResponse(resp, nil); err != nil {
+		log.Error().Err(err).Float64("duration_ms", msSince(start)).Str("outcome", "failure").Msg("garage delete_bucket decode failed")
 		return fmt.Errorf("failed to process response: %w", err)
 	}
 
+	log.Info().Float64("duration_ms", msSince(start)).Str("outcome", "success").Msg("bucket deleted")
 	return nil
 }
 
@@ -304,18 +383,34 @@ func (s *GarageAdminService) RemoveBucketAlias(ctx context.Context, req models.R
 	return &result, nil
 }
 
-// AllowBucketKey grants permissions for a key on a bucket
+// AllowBucketKey grants permissions for a key on a bucket.
 func (s *GarageAdminService) AllowBucketKey(ctx context.Context, req models.BucketKeyPermRequest) (*models.GarageBucketInfo, error) {
+	log := logpkg.FromCtx(ctx).With().
+		Str("component", "admin").
+		Str("operation", "allow_bucket_key").
+		Str("bucket_id", req.BucketID).
+		Str("access_key_id", logpkg.RedactKey(req.AccessKeyID)).
+		Bool("perm_read", req.Permissions.Read).
+		Bool("perm_write", req.Permissions.Write).
+		Bool("perm_owner", req.Permissions.Owner).
+		Logger()
+
+	log.Info().Msg("granting bucket key permissions")
+	start := time.Now()
+
 	resp, err := s.doRequest(ctx, http.MethodPost, "/v2/AllowBucketKey", req)
 	if err != nil {
+		log.Error().Err(err).Float64("duration_ms", msSince(start)).Str("outcome", "failure").Msg("garage allow_bucket_key request failed")
 		return nil, fmt.Errorf("request failed: %w", err)
 	}
 
 	var result models.GarageBucketInfo
 	if err := decodeResponse(resp, &result); err != nil {
+		log.Error().Err(err).Float64("duration_ms", msSince(start)).Str("outcome", "failure").Msg("garage allow_bucket_key decode failed")
 		return nil, fmt.Errorf("failed to decode response: %w", err)
 	}
 
+	log.Info().Float64("duration_ms", msSince(start)).Str("outcome", "success").Msg("bucket key permissions granted")
 	return &result, nil
 }
 
@@ -427,6 +522,11 @@ func (s *GarageAdminService) HealthCheck(ctx context.Context) error {
 	return nil
 }
 
+// msSince returns duration since t in milliseconds as a float64.
+func msSince(t time.Time) float64 {
+	return float64(time.Since(t).Microseconds()) / 1000.0
+}
+
 // GetMetrics returns Prometheus metrics from the Admin API
 func (s *GarageAdminService) GetMetrics(ctx context.Context) (string, error) {
 	resp, err := s.doRequest(ctx, http.MethodGet, "/metrics", nil)

backend/pkg/utils/retry.go

@@ -5,6 +5,7 @@ import (
 	"errors"
 	"fmt"
 	"net"
+	"strings"
 	"syscall"
 	"time"
 )
@@ -50,6 +51,15 @@ func IsConnectionRefused(err error) bool {
 		return true
 	}
 
+	// Some HTTP clients (e.g. azuretls) collapse the syscall error into a
+	// plain string before returning. Fall back to substring matching so the
+	// retry path still triggers for those wrappers. "connectex" is the
+	// Windows variant emitted by the Go runtime.
+	msg := err.Error()
+	if strings.Contains(msg, "connection refused") || strings.Contains(msg, "actively refused") {
+		return true
+	}
+
 	return false
 }