From f337da8e57b82682de52031eecadfb5d7ddae172 Mon Sep 17 00:00:00 2001 From: Misi Date: Fri, 5 Jul 2024 09:37:36 +0200 Subject: [PATCH] Chore: Add more context to logs of OAuthToken and OAuthTokenSync (#90071) Chore: Add more context to oauth token sync --- .../authn/authnimpl/sync/oauth_token_sync.go | 12 ++--- pkg/services/oauthtoken/oauth_token.go | 45 +++++++++++-------- 2 files changed, 34 insertions(+), 23 deletions(-) diff --git a/pkg/services/authn/authnimpl/sync/oauth_token_sync.go b/pkg/services/authn/authnimpl/sync/oauth_token_sync.go index 2b4220fdfd0..1a3891570ab 100644 --- a/pkg/services/authn/authnimpl/sync/oauth_token_sync.go +++ b/pkg/services/authn/authnimpl/sync/oauth_token_sync.go @@ -55,8 +55,10 @@ func (s *OAuthTokenSync) SyncOauthTokenHook(ctx context.Context, identity *authn return nil } + ctxLogger := s.log.FromContext(ctx).New("userID", identity.ID.ID()) + _, err, _ := s.singleflightGroup.Do(identity.ID.String(), func() (interface{}, error) { - s.log.Debug("Singleflight request for OAuth token sync", "key", identity.ID.String()) + ctxLogger.Debug("Singleflight request for OAuth token sync") // FIXME: Consider using context.WithoutCancel instead of context.Background after Go 1.21 update updateCtx, cancel := context.WithTimeout(context.Background(), 15*time.Second) @@ -69,7 +71,7 @@ func (s *OAuthTokenSync) SyncOauthTokenHook(ctx context.Context, identity *authn token, _, err := s.service.HasOAuthEntry(ctx, identity) if err != nil { - s.log.Error("Failed to get OAuth entry for verifying if token has already been refreshed", "id", identity.ID, "error", err) + ctxLogger.Error("Failed to get OAuth entry for verifying if token has already been refreshed", "id", identity.ID, "error", err) return nil, err } @@ -79,14 +81,14 @@ func (s *OAuthTokenSync) SyncOauthTokenHook(ctx context.Context, identity *authn return nil, nil } - s.log.Error("Failed to refresh OAuth access token", "id", identity.ID, "error", refreshErr) + ctxLogger.Error("Failed to refresh OAuth access token", "id", identity.ID, "error", refreshErr) if err := s.service.InvalidateOAuthTokens(ctx, token); err != nil { - s.log.Warn("Failed to invalidate OAuth tokens", "id", identity.ID, "error", err) + ctxLogger.Warn("Failed to invalidate OAuth tokens", "id", identity.ID, "error", err) } if err := s.sessionService.RevokeToken(ctx, identity.SessionToken, false); err != nil { - s.log.Warn("Failed to revoke session token", "id", identity.ID, "tokenId", identity.SessionToken.Id, "error", err) + ctxLogger.Warn("Failed to revoke session token", "id", identity.ID, "tokenId", identity.SessionToken.Id, "error", err) } return nil, refreshErr diff --git a/pkg/services/oauthtoken/oauth_token.go b/pkg/services/oauthtoken/oauth_token.go index fffc81e9547..79820f391ff 100644 --- a/pkg/services/oauthtoken/oauth_token.go +++ b/pkg/services/oauthtoken/oauth_token.go @@ -100,21 +100,25 @@ func (o *Service) HasOAuthEntry(ctx context.Context, usr identity.Requester) (*l return nil, false, nil } + ctxLogger := logger.FromContext(ctx) + userID, err := identity.IntIdentifier(namespace, id) if err != nil { - logger.Error("Failed to convert user id to int", "namespace", namespace, "userId", id, "error", err) + ctxLogger.Error("Failed to convert user id to int", "namespace", namespace, "userID", id, "error", err) return nil, false, err } + ctxLogger = ctxLogger.New("userID", userID) + authInfoQuery := &login.GetAuthInfoQuery{UserId: userID} authInfo, err := o.AuthInfoService.GetAuthInfo(ctx, authInfoQuery) if err != nil { if errors.Is(err, user.ErrUserNotFound) { // Not necessarily an error. User may be logged in another way. - logger.Debug("No oauth token found for user", "userId", userID, "username", usr.GetLogin()) + ctxLogger.Debug("No oauth token found for user", "username", usr.GetLogin()) return nil, false, nil } - logger.Error("Failed to fetch oauth token for user", "userId", userID, "username", usr.GetLogin(), "error", err) + ctxLogger.Error("Failed to fetch oauth token for user", "username", usr.GetLogin(), "error", err) return nil, false, err } if !strings.Contains(authInfo.AuthModule, "oauth") { @@ -139,24 +143,28 @@ func (o *Service) TryTokenRefresh(ctx context.Context, usr identity.Requester) e return nil } + ctxLogger := logger.FromContext(ctx) + userID, err := identity.IntIdentifier(namespace, id) if err != nil { - logger.Warn("Failed to convert user id to int", "namespace", namespace, "userId", id, "error", err) + ctxLogger.Warn("Failed to convert user id to int", "namespace", namespace, "userId", id, "error", err) return nil } + ctxLogger = ctxLogger.New("userID", userID) + lockKey := fmt.Sprintf("oauth-refresh-token-%d", userID) if _, ok := o.cache.Get(lockKey); ok { - logger.Debug("Expiration check has been cached, no need to refresh", "userID", userID) + ctxLogger.Debug("Expiration check has been cached, no need to refresh") return nil } _, err, _ = o.singleFlightGroup.Do(lockKey, func() (any, error) { - logger.Debug("Singleflight request for getting a new access token", "key", lockKey) + ctxLogger.Debug("Singleflight request for getting a new access token", "key", lockKey) authInfo, exists, err := o.HasOAuthEntry(ctx, usr) if !exists { if err != nil { - logger.Debug("Failed to fetch oauth entry", "id", userID, "error", err) + ctxLogger.Debug("Failed to fetch oauth entry", "error", err) } else { // User is not logged in via OAuth no need to check o.cache.Set(lockKey, struct{}{}, maxOAuthTokenCacheTTL) @@ -174,13 +182,13 @@ func (o *Service) TryTokenRefresh(ctx context.Context, usr identity.Requester) e provider := strings.TrimPrefix(authInfo.AuthModule, "oauth_") currentOAuthInfo := o.SocialService.GetOAuthInfoProvider(provider) if currentOAuthInfo == nil { - logger.Warn("OAuth provider not found", "provider", provider) + ctxLogger.Warn("OAuth provider not found", "provider", provider) return nil, nil } // if refresh token handling is disabled for this provider, we can skip the refresh if !currentOAuthInfo.UseRefreshToken { - logger.Debug("Skipping token refresh", "provider", provider) + ctxLogger.Debug("Skipping token refresh", "provider", provider) return nil, nil } @@ -240,9 +248,11 @@ func (o *Service) InvalidateOAuthTokens(ctx context.Context, usr *login.UserAuth } func (o *Service) tryGetOrRefreshOAuthToken(ctx context.Context, usr *login.UserAuth) (*oauth2.Token, error) { + ctxLogger := logger.FromContext(ctx).New("userID", usr.UserId) + key := getCheckCacheKey(usr.UserId) if _, ok := o.cache.Get(key); ok { - logger.Debug("Expiration check has been cached", "userID", usr.UserId) + ctxLogger.Debug("Expiration check has been cached", "userID", usr.UserId) return buildOAuthTokenFromAuthInfo(usr), nil } @@ -259,13 +269,13 @@ func (o *Service) tryGetOrRefreshOAuthToken(ctx context.Context, usr *login.User authProvider := usr.AuthModule connect, err := o.SocialService.GetConnector(authProvider) if err != nil { - logger.Error("Failed to get oauth connector", "provider", authProvider, "error", err) + ctxLogger.Error("Failed to get oauth connector", "provider", authProvider, "error", err) return nil, err } client, err := o.SocialService.GetOAuthHttpClient(authProvider) if err != nil { - logger.Error("Failed to get oauth http client", "provider", authProvider, "error", err) + ctxLogger.Error("Failed to get oauth http client", "provider", authProvider, "error", err) return nil, err } ctx = context.WithValue(ctx, oauth2.HTTPClient, client) @@ -277,7 +287,7 @@ func (o *Service) tryGetOrRefreshOAuthToken(ctx context.Context, usr *login.User o.tokenRefreshDuration.WithLabelValues(authProvider, fmt.Sprintf("%t", err == nil)).Observe(duration.Seconds()) if err != nil { - logger.Error("Failed to retrieve oauth access token", + ctxLogger.Error("Failed to retrieve oauth access token", "provider", usr.AuthModule, "userId", usr.UserId, "error", err) return nil, err } @@ -292,8 +302,7 @@ func (o *Service) tryGetOrRefreshOAuthToken(ctx context.Context, usr *login.User } if o.Cfg.Env == setting.Dev { - logger.Debug("Oauth got token", - "user", usr.UserId, + ctxLogger.Debug("Oauth got token", "auth_module", usr.AuthModule, "expiry", fmt.Sprintf("%v", token.Expiry), "access_token", fmt.Sprintf("%v", token.AccessToken), @@ -302,10 +311,10 @@ func (o *Service) tryGetOrRefreshOAuthToken(ctx context.Context, usr *login.User } if err := o.AuthInfoService.UpdateAuthInfo(ctx, updateAuthCommand); err != nil { - logger.Error("Failed to update auth info during token refresh", "userId", usr.UserId, "error", err) + ctxLogger.Error("Failed to update auth info during token refresh", "userId", usr.UserId, "error", err) return nil, err } - logger.Debug("Updated oauth info for user", "userId", usr.UserId) + ctxLogger.Debug("Updated oauth info for user") } return token, nil @@ -359,7 +368,7 @@ func needTokenRefresh(usr *login.UserAuth) (*oauth2.Token, bool, time.Duration) idTokenExpires, hasIdTokenExpired = getExpiryWithSkew(idTokenExp) } if !hasAccessTokenExpired && !hasIdTokenExpired { - logger.Debug("Neither access nor id token have expired yet", "id", usr.Id) + logger.Debug("Neither access nor id token have expired yet", "userID", usr.UserId) return persistedToken, false, getOAuthTokenCacheTTL(accessTokenExpires, idTokenExpires) } if hasIdTokenExpired {