Authorization/services/authorize.go

package services

import (
	"authorization/models"
	"authorization/repository"
	"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 {
		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
}