From 68be5ea2be69fa89d66e86ab7ec1aa7fbd13d4c8 Mon Sep 17 00:00:00 2001 From: Noooste <83548733+Noooste@users.noreply.github.com> Date: Sun, 19 Apr 2026 13:59:27 +0200 Subject: [PATCH] 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 | 54 +++++++++--- backend/internal/services/admin.go | 130 ++++++++++++++++++++++++---- backend/pkg/utils/retry.go | 10 +++ 3 files changed, 167 insertions(+), 27 deletions(-) diff --git a/backend/internal/middleware/auth.go b/backend/internal/middleware/auth.go index 989d917..7259cb5 100644 --- a/backend/internal/middleware/auth.go +++ b/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" + } +} diff --git a/backend/internal/services/admin.go b/backend/internal/services/admin.go index c9cd46d..97e12fd 100644 --- a/backend/internal/services/admin.go +++ b/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) diff --git a/backend/pkg/utils/retry.go b/backend/pkg/utils/retry.go index bb632ca..027d61a 100644 --- a/backend/pkg/utils/retry.go +++ b/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 }