package services import ( "authorization/models" "authorization/repository" "errors" "fmt" "log" "time" ) // Authorize performs RBAC + ABAC authorization check func Authorize(ctx *models.AuthorizationContext) (*models.AuthorizationResult, error) { startTime := time.Now() log.Printf("[AuthZ Step 0] Fetching user details for userID=%s", ctx.UsersID) user, err := repository.GetUserByID(ctx.UsersID) if err != nil { if errors.Is(err, repository.ErrUserDeleted) { log.Printf("✗ Deleted user attempted authorization for userID=%s", ctx.UsersID) return &models.AuthorizationResult{ Allowed: false, RedirectRoute: "/login", Message: "Account deleted", }, nil } log.Printf("✗ User not found for userID=%s: %v", ctx.UsersID, err) return &models.AuthorizationResult{ Allowed: false, Message: fmt.Sprintf("User not found: %v", err), }, nil } log.Printf("[AuthZ Step 0] User found: role_id=%d", user.RoleID) roleCandidates := getRoleCandidates(ctx) if len(roleCandidates) == 0 && user.RoleID != 0 { roleCandidates = []int{user.RoleID} } var permission *models.Permission permissionFound := false for _, roleID := range roleCandidates { log.Printf("[AuthZ Step 1] Checking if role_id=%d has permission for resource=%s, action=%s", roleID, ctx.Resource, ctx.Action) lookupPermission, lookupErr := repository.GetPermissionByResourceActionAndRole(ctx.Resource, ctx.Action, roleID) if lookupErr != nil { log.Printf("[AuthZ Step 1] Permission not granted for role_id=%d, trying next role: %v", roleID, lookupErr) continue } permission = lookupPermission ctx.RoleID = roleID permissionFound = true break } if !permissionFound { log.Printf("✗ Permission not found or not granted for role candidates=%v, resource=%s, action=%s", roleCandidates, ctx.Resource, ctx.Action) return &models.AuthorizationResult{ Allowed: false, Message: "Permission not granted to your role", }, nil } log.Printf("[AuthZ Step 1] Permission found: ID=%d, Name=%s", permission.ID, permission.PermissionName) // Step 2: Get user attributes log.Printf("[AuthZ Step 2] Fetching user attributes for userID=%s", ctx.UsersID) userAttrs, err := repository.GetUserAttributes(ctx.UsersID) if err != nil { log.Printf("✗ Failed to get user attributes for userID=%s: %v", ctx.UsersID, err) return &models.AuthorizationResult{ Allowed: false, Message: fmt.Sprintf("Failed to get user attributes: %v", err), }, err } ctx.UserAttributes = userAttrs fmt.Printf("[DEBUG] User attributes map: %+v\n", userAttrs) fmt.Println("[DEBUG] About to print user attributes") for k, v := range userAttrs { log.Printf("User Attribute - %s: %v", k, v) fmt.Printf("[DEBUG] User Attribute - %s: %v\n", k, v) } fmt.Println("[DEBUG] Finished printing user attributes") log.Printf("[AuthZ Step 2] User attributes retrieved: %d attributes", len(userAttrs)) // Step 3: Get policy attributes for the permission log.Printf("[AuthZ Step 3] Fetching policy attributes for permissionID=%d", permission.ID) policies, err := repository.GetPolicyAttributesByPermission(permission.ID) if err != nil { log.Printf("✗ Failed to get policies for permissionID=%d: %v", permission.ID, err) return &models.AuthorizationResult{ Allowed: false, Message: fmt.Sprintf("Failed to get policies: %v", err), }, err } log.Printf("[AuthZ Step 3] Policies retrieved: %d policies to evaluate", len(policies)) if len(policies) > 0 { for i, p := range policies { log.Printf("[DEBUG] Policy %d: AttributeType=%s, AttributeName=%s, Comparison=%s, AttributeValue=%s", i+1, p.AttributeType, p.AttributeName, p.Comparison, p.AttributeValue) } } else { log.Printf("[DEBUG] No policies loaded for permissionID=%d", permission.ID) } log.Printf("[AuthZ Step 4] Using RoleID: %d (from context or user record)", ctx.RoleID) allowed, reason := EvaluatePolicies(policies, ctx) result := &models.AuthorizationResult{ Allowed: allowed, } if allowed { result.RedirectRoute = "dashboard" result.Message = "Access granted" log.Printf("✓ Authorization GRANTED for user=%s, resource=%s, action=%s (evaluated in %v)", ctx.UsersID, ctx.Resource, ctx.Action, time.Since(startTime)) } else { log.Printf("✗ Authorization DENIED for user=%s, resource=%s, action=%s - Reason: %s (evaluated in %v)", ctx.UsersID, ctx.Resource, ctx.Action, reason, time.Since(startTime)) result.Message = reason } // Log evaluation time for performance monitoring evalTime := time.Since(startTime) if evalTime > 100*time.Millisecond { fmt.Printf("WARN: Slow authorization evaluation: %v for user=%s, resource=%s, action=%s\n", evalTime, ctx.UsersID, ctx.Resource, ctx.Action) } return result, nil }