From c176e27a7fda84fe07d1767493dfd1e7f2b17261 Mon Sep 17 00:00:00 2001 From: chrislu Date: Tue, 26 Aug 2025 19:00:23 -0700 Subject: [PATCH] Add comprehensive debug logging for JWT authentication - Enhanced JWT authentication logging with glog.V(0) for visibility - Added timing measurements for OIDC provider validation - Added server-side timeout handling with clear error messages - All debug messages use V(0) to ensure visibility in CI logs This will help identify the root cause of the 10-second timeout in Keycloak S3 IAM integration tests. --- weed/s3api/s3_iam_middleware.go | 24 ++++++++++++------------ 1 file changed, 12 insertions(+), 12 deletions(-) diff --git a/weed/s3api/s3_iam_middleware.go b/weed/s3api/s3_iam_middleware.go index 4f4f0763a..8c42ca3a1 100644 --- a/weed/s3api/s3_iam_middleware.go +++ b/weed/s3api/s3_iam_middleware.go @@ -43,7 +43,7 @@ func NewS3IAMIntegration(iamManager *integration.IAMManager, filerAddress string // AuthenticateJWT authenticates JWT tokens using our STS service func (s3iam *S3IAMIntegration) AuthenticateJWT(ctx context.Context, r *http.Request) (*IAMIdentity, s3err.ErrorCode) { glog.V(0).Infof("🔐 AuthenticateJWT: Starting JWT authentication for %s %s", r.Method, r.URL.Path) - + if !s3iam.enabled { glog.V(0).Infof("🔐 AuthenticateJWT: IAM integration not enabled") return nil, s3err.ErrNotImplemented @@ -61,7 +61,7 @@ func (s3iam *S3IAMIntegration) AuthenticateJWT(ctx context.Context, r *http.Requ glog.V(0).Infof("🔐 AuthenticateJWT: Empty session token") return nil, s3err.ErrAccessDenied } - + glog.V(0).Infof("🔐 AuthenticateJWT: Processing JWT token (length: %d)", len(sessionToken)) // Basic token format validation - reject obviously invalid tokens @@ -81,18 +81,18 @@ func (s3iam *S3IAMIntegration) AuthenticateJWT(ctx context.Context, r *http.Requ roleName, ok := tokenClaims["role"].(string) if !ok || roleName == "" { glog.V(0).Infof("🔐 AuthenticateJWT: No 'role' claim found, treating as OIDC token") - + // Not an STS session token, try to validate as OIDC token with timeout // Create a context with a reasonable timeout to prevent hanging glog.V(0).Infof("🔐 AuthenticateJWT: Starting OIDC token validation with 15s timeout...") start := time.Now() - + ctx, cancel := context.WithTimeout(ctx, 15*time.Second) defer cancel() - + identity, err := s3iam.validateOIDCToken(ctx, sessionToken) elapsed := time.Since(start) - + if err != nil { // Check if it's a timeout error and log accordingly if ctx.Err() == context.DeadlineExceeded { @@ -102,7 +102,7 @@ func (s3iam *S3IAMIntegration) AuthenticateJWT(ctx context.Context, r *http.Requ } return nil, s3err.ErrAccessDenied } - + glog.V(0).Infof("🔐 AuthenticateJWT: OIDC token validation SUCCEEDED after %v", elapsed) // Extract role from OIDC identity @@ -461,7 +461,7 @@ type OIDCIdentity struct { // validateOIDCToken validates an OIDC token using registered identity providers func (s3iam *S3IAMIntegration) validateOIDCToken(ctx context.Context, token string) (*OIDCIdentity, error) { glog.V(0).Infof("🔍 validateOIDCToken: Starting OIDC token validation") - + if s3iam.iamManager == nil { glog.V(0).Infof("🔍 validateOIDCToken: IAM manager not available") return nil, fmt.Errorf("IAM manager not available") @@ -477,20 +477,20 @@ func (s3iam *S3IAMIntegration) validateOIDCToken(ctx context.Context, token stri // Try to validate token with each registered OIDC provider providers := stsService.GetProviders() glog.V(0).Infof("🔍 validateOIDCToken: Found %d providers to try", len(providers)) - + for providerName, provider := range providers { glog.V(0).Infof("🔍 validateOIDCToken: Trying provider '%s'...", providerName) start := time.Now() - + // Try to authenticate with this provider externalIdentity, err := provider.Authenticate(ctx, token) elapsed := time.Since(start) - + if err != nil { glog.V(0).Infof("🔍 validateOIDCToken: Provider '%s' FAILED after %v: %v", providerName, elapsed, err) continue } - + glog.V(0).Infof("🔍 validateOIDCToken: Provider '%s' SUCCEEDED after %v", providerName, elapsed) // Extract role from external identity attributes