IntenseWebs/grafana
3
0
Fork 0
mirror of https://github.com/grafana/grafana.git synced 2025-02-25 18:55:37 -06:00
Code Issues Packages Projects Releases Wiki Activity

Chore: Add more context to logs of OAuthToken and OAuthTokenSync (#90071)

Browse Source 
Chore: Add more context to oauth token sync
This commit is contained in:
Misi 2024-07-05 09:37:36 +02:00 committed by GitHub
parent 315e068190
commit f337da8e57
No known key found for this signature in database
GPG Key ID: B5690EEEBB952194
2 changed files with 34 additions and 23 deletions
Show Stats Download Patch File Download Diff File Expand all files Collapse all files

12
pkg/services/authn/authnimpl/sync/oauth_token_sync.go
View File

@ -55,8 +55,10 @@ func (s *OAuthTokenSync) SyncOauthTokenHook(ctx context.Context, identity *authn
return nil return nil
} }
ctxLogger := s.log.FromContext(ctx).New("userID", identity.ID.ID())
_, err, _ := s.singleflightGroup.Do(identity.ID.String(), func() (interface{}, error) { _, 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 // FIXME: Consider using context.WithoutCancel instead of context.Background after Go 1.21 update
updateCtx, cancel := context.WithTimeout(context.Background(), 15*time.Second) 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) token, _, err := s.service.HasOAuthEntry(ctx, identity)
if err != nil { 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 return nil, err
} }
@ -79,14 +81,14 @@ func (s *OAuthTokenSync) SyncOauthTokenHook(ctx context.Context, identity *authn
return nil, nil 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 { 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 { 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 return nil, refreshErr

45
pkg/services/oauthtoken/oauth_token.go
View File

@ -100,21 +100,25 @@ func (o *Service) HasOAuthEntry(ctx context.Context, usr identity.Requester) (*l
return nil, false, nil return nil, false, nil
} }
ctxLogger := logger.FromContext(ctx)
userID, err := identity.IntIdentifier(namespace, id) userID, err := identity.IntIdentifier(namespace, id)
if err != nil { 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 return nil, false, err
} }
ctxLogger = ctxLogger.New("userID", userID)
authInfoQuery := &login.GetAuthInfoQuery{UserId: userID} authInfoQuery := &login.GetAuthInfoQuery{UserId: userID}
authInfo, err := o.AuthInfoService.GetAuthInfo(ctx, authInfoQuery) authInfo, err := o.AuthInfoService.GetAuthInfo(ctx, authInfoQuery)
if err != nil { if err != nil {
if errors.Is(err, user.ErrUserNotFound) { if errors.Is(err, user.ErrUserNotFound) {
// Not necessarily an error. User may be logged in another way. // 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 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 return nil, false, err
} }
if !strings.Contains(authInfo.AuthModule, "oauth") { if !strings.Contains(authInfo.AuthModule, "oauth") {
@ -139,24 +143,28 @@ func (o *Service) TryTokenRefresh(ctx context.Context, usr identity.Requester) e
return nil return nil
} }
ctxLogger := logger.FromContext(ctx)
userID, err := identity.IntIdentifier(namespace, id) userID, err := identity.IntIdentifier(namespace, id)
if err != nil { 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 return nil
} }
ctxLogger = ctxLogger.New("userID", userID)
lockKey := fmt.Sprintf("oauth-refresh-token-%d", userID) lockKey := fmt.Sprintf("oauth-refresh-token-%d", userID)
if _, ok := o.cache.Get(lockKey); ok { 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 return nil
} }
_, err, _ = o.singleFlightGroup.Do(lockKey, func() (any, error) { _, 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) authInfo, exists, err := o.HasOAuthEntry(ctx, usr)
if !exists { if !exists {
if err != nil { if err != nil {
logger.Debug("Failed to fetch oauth entry", "id", userID, "error", err) ctxLogger.Debug("Failed to fetch oauth entry", "error", err)
} else { } else {
// User is not logged in via OAuth no need to check // User is not logged in via OAuth no need to check
o.cache.Set(lockKey, struct{}{}, maxOAuthTokenCacheTTL) 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_") provider := strings.TrimPrefix(authInfo.AuthModule, "oauth_")
currentOAuthInfo := o.SocialService.GetOAuthInfoProvider(provider) currentOAuthInfo := o.SocialService.GetOAuthInfoProvider(provider)
if currentOAuthInfo == nil { if currentOAuthInfo == nil {
logger.Warn("OAuth provider not found", "provider", provider) ctxLogger.Warn("OAuth provider not found", "provider", provider)
return nil, nil return nil, nil
} }
// if refresh token handling is disabled for this provider, we can skip the refresh // if refresh token handling is disabled for this provider, we can skip the refresh
if !currentOAuthInfo.UseRefreshToken { if !currentOAuthInfo.UseRefreshToken {
logger.Debug("Skipping token refresh", "provider", provider) ctxLogger.Debug("Skipping token refresh", "provider", provider)
return nil, nil 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) { 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) key := getCheckCacheKey(usr.UserId)
if _, ok := o.cache.Get(key); ok { 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 return buildOAuthTokenFromAuthInfo(usr), nil
} }
@ -259,13 +269,13 @@ func (o *Service) tryGetOrRefreshOAuthToken(ctx context.Context, usr *login.User
authProvider := usr.AuthModule authProvider := usr.AuthModule
connect, err := o.SocialService.GetConnector(authProvider) connect, err := o.SocialService.GetConnector(authProvider)
if err != nil { 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 return nil, err
} }
client, err := o.SocialService.GetOAuthHttpClient(authProvider) client, err := o.SocialService.GetOAuthHttpClient(authProvider)
if err != nil { 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 return nil, err
} }
ctx = context.WithValue(ctx, oauth2.HTTPClient, client) 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()) o.tokenRefreshDuration.WithLabelValues(authProvider, fmt.Sprintf("%t", err == nil)).Observe(duration.Seconds())
if err != nil { 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) "provider", usr.AuthModule, "userId", usr.UserId, "error", err)
return nil, err return nil, err
} }
@ -292,8 +302,7 @@ func (o *Service) tryGetOrRefreshOAuthToken(ctx context.Context, usr *login.User
} }
if o.Cfg.Env == setting.Dev { if o.Cfg.Env == setting.Dev {
logger.Debug("Oauth got token", ctxLogger.Debug("Oauth got token",
"user", usr.UserId,
"auth_module", usr.AuthModule, "auth_module", usr.AuthModule,
"expiry", fmt.Sprintf("%v", token.Expiry), "expiry", fmt.Sprintf("%v", token.Expiry),
"access_token", fmt.Sprintf("%v", token.AccessToken), "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 { 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 return nil, err
} }
logger.Debug("Updated oauth info for user", "userId", usr.UserId) ctxLogger.Debug("Updated oauth info for user")
} }
return token, nil return token, nil
@ -359,7 +368,7 @@ func needTokenRefresh(usr *login.UserAuth) (*oauth2.Token, bool, time.Duration)
idTokenExpires, hasIdTokenExpired = getExpiryWithSkew(idTokenExp) idTokenExpires, hasIdTokenExpired = getExpiryWithSkew(idTokenExp)
} }
if !hasAccessTokenExpired && !hasIdTokenExpired { 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) return persistedToken, false, getOAuthTokenCacheTTL(accessTokenExpires, idTokenExpires)
} }
if hasIdTokenExpired { if hasIdTokenExpired {