added logging

services/cached_authorization.go

@@ -227,32 +227,42 @@ func NewCachedAuthorizationService() *models.CachedAuthorizationService {
 func AuthorizeWithCache(s *models.CachedAuthorizationService, ctx *models.AuthorizationContext) (*models.AuthorizationResult, error) {
 	startTime := time.Now()
 
+	log.Printf("[AuthZ Cached] Starting authorization check for user=%s, resource=%s, action=%s", ctx.UserID, ctx.Resource, ctx.Action)
+
 	// Step 1: Get permission from distributed cache
 	cacheKey := ctx.Resource + ":" + ctx.Action
+	log.Printf("[AuthZ Step 1] Looking up permission in cache: %s", cacheKey)
 	permission, exists := getPermissionFromCache(s, cacheKey)
 
-	log.Print("Cached authorization lookup for user=", ctx.UserID, ", resource=", ctx.Resource, ", action=", ctx.Action)
 	if !exists {
+		log.Printf("✗ Permission not found in cache for resource=%s, action=%s", ctx.Resource, ctx.Action)
 		return &models.AuthorizationResult{
 			Allowed: false,
 			Message: "Permission not found",
 		}, nil
 	}
+	log.Printf("[AuthZ Step 1] Permission found in cache: ID=%d, Name=%s", permission.ID, permission.PermissionName)
 
 	// Step 2: Get user attributes (with distributed cache)
+	log.Printf("[AuthZ Step 2] Fetching user attributes for userID=%s", ctx.UserID)
 	userAttrs, err := getCachedUserAttributes(s, ctx.UserID)
 	if err != nil {
+		log.Printf("✗ Failed to get user attributes for userID=%s: %v", ctx.UserID, err)
 		return &models.AuthorizationResult{
 			Allowed: false,
 			Message: "Failed to get user attributes",
 		}, err
 	}
 	ctx.UserAttributes = userAttrs
+	log.Printf("[AuthZ Step 2] User attributes retrieved: %d attributes", len(userAttrs))
 
 	// Step 3: Get policies from distributed cache
+	log.Printf("[AuthZ Step 3] Fetching policies for permissionID=%d", permission.ID)
 	policies := getPoliciesFromCache(s, permission.ID)
+	log.Printf("[AuthZ Step 3] Policies retrieved: %d policies to evaluate", len(policies))
 
 	// Step 4: Evaluate policies
+	log.Printf("[AuthZ Step 4] Evaluating ABAC policies")
 	allowed, reason := EvaluatePolicies(policies, ctx)
 
 	result := &models.AuthorizationResult{
@@ -261,8 +271,12 @@ func AuthorizeWithCache(s *models.CachedAuthorizationService, ctx *models.Author
 
 	if allowed {
 		result.Message = "Access granted"
+		log.Printf("✓ Authorization GRANTED for user=%s, resource=%s, action=%s (evaluated in %v)",
+			ctx.UserID, ctx.Resource, ctx.Action, time.Since(startTime))
 	} else {
 		result.Message = reason
+		log.Printf("✗ Authorization DENIED for user=%s, resource=%s, action=%s - Reason: %s (evaluated in %v)",
+			ctx.UserID, ctx.Resource, ctx.Action, reason, time.Since(startTime))
 	}
 
 	// Performance monitoring