AuthN: cleanup logs (#63652)

* AuthN: clean up logs
Co-authored-by: Ieva <ieva.vasiljeva@grafana.com>
This commit is contained in:
Karl Persson
2023-02-24 11:26:55 +01:00
committed by GitHub
co-authored by Ieva
parent 9cae3f43ed
commit 2a7fc3983b
11 changed files with 57 additions and 69 deletions
@@ -74,15 +74,15 @@ func (s *OAuthTokenSync) SyncOauthTokenHook(ctx context.Context, identity *authn
if err := s.service.TryTokenRefresh(ctx, token); err != nil {
if !errors.Is(err, oauthtoken.ErrNoRefreshTokenFound) {
s.log.FromContext(ctx).Error("could not refresh oauth access token for user", "userId", id, "err", err)
s.log.FromContext(ctx).Error("Failed to refresh OAuth access token", "id", identity.ID, "error", err)
}
if err := s.service.InvalidateOAuthTokens(ctx, token); err != nil {
s.log.FromContext(ctx).Error("could not invalidate OAuth tokens", "userId", id, "err", err)
s.log.FromContext(ctx).Error("Failed invalidate OAuth tokens", "id", identity.ID, "error", err)
}
if err := s.sessionService.RevokeToken(ctx, identity.SessionToken, false); err != nil {
s.log.FromContext(ctx).Error("could not revoke token", "userId", id, "tokenId", identity.SessionToken.Id, "err", err)
s.log.FromContext(ctx).Error("Failed to revoke session token", "id", identity.ID, "tokenId", identity.SessionToken.Id, "error", err)
}
return errExpiredAccessToken.Errorf("oauth access token could not be refreshed: %w", auth.ErrInvalidSessionToken)
+17 -18
View File
@@ -29,23 +29,25 @@ func (s *OrgSync) SyncOrgRolesHook(ctx context.Context, id *authn.Identity, _ *a
return nil
}
ctxLogger := s.log.FromContext(ctx)
namespace, userID := id.NamespacedID()
if namespace != authn.NamespaceUser || userID <= 0 {
s.log.Warn("invalid namespace %q for user ID %q", namespace, userID)
ctxLogger.Warn("Failed to sync org role, invalid namespace for identity", "id", id.ID, "namespace", namespace)
return nil
}
s.log.Debug("syncing organization roles", "id", userID, "extOrgRoles", id.OrgRoles)
ctxLogger.Debug("Syncing organization roles", "id", id.ID, "extOrgRoles", id.OrgRoles)
// don't sync org roles if none is specified
if len(id.OrgRoles) == 0 {
s.log.Debug("not syncing organization roles since external user doesn't have any")
ctxLogger.Debug("Not syncing organization roles since external user doesn't have any", "id", id.ID)
return nil
}
orgsQuery := &org.GetUserOrgListQuery{UserID: userID}
result, err := s.orgService.GetUserOrgList(ctx, orgsQuery)
if err != nil {
s.log.Error("failed to get user's organizations", "userId", userID, "error", err)
ctxLogger.Error("Failed to get user's organizations", "id", id.ID, "error", err)
return nil
}
@@ -63,8 +65,8 @@ func (s *OrgSync) SyncOrgRolesHook(ctx context.Context, id *authn.Identity, _ *a
// update role
cmd := &org.UpdateOrgUserCommand{OrgID: orga.OrgID, UserID: userID, Role: extRole}
if err := s.orgService.UpdateOrgUser(ctx, cmd); err != nil {
s.log.Error("failed to update active org user", "userId", userID, "error", err)
return nil
s.log.FromContext(ctx).Error("Failed to update active org user", "id", id.ID, "error", err)
return err
}
}
}
@@ -81,29 +83,26 @@ func (s *OrgSync) SyncOrgRolesHook(ctx context.Context, id *authn.Identity, _ *a
cmd := &org.AddOrgUserCommand{UserID: userID, Role: orgRole, OrgID: orgId}
err := s.orgService.AddOrgUser(ctx, cmd)
if err != nil && !errors.Is(err, org.ErrOrgNotFound) {
s.log.Error("failed to update active org user", "userId", userID, "error", err)
return nil
s.log.FromContext(ctx).Error("Failed to update active org for user", "id", id.ID, "error", err)
return err
}
}
// delete any removed org roles
for _, orgId := range deleteOrgIds {
s.log.Debug("Removing user's organization membership as part of syncing with OAuth login",
"userId", userID, "orgId", orgId)
cmd := &org.RemoveOrgUserCommand{OrgID: orgId, UserID: userID}
for _, orgID := range deleteOrgIds {
ctxLogger.Debug("Removing user's organization membership as part of syncing with OAuth login", "id", id.ID, "orgId", orgID)
cmd := &org.RemoveOrgUserCommand{OrgID: orgID, UserID: userID}
if err := s.orgService.RemoveOrgUser(ctx, cmd); err != nil {
s.log.FromContext(ctx).Error("Failed to remove user from org", "id", id.ID, "orgId", orgID, "error", err)
if errors.Is(err, org.ErrLastOrgAdmin) {
s.log.Error(err.Error(), "userId", cmd.UserID, "orgId", cmd.OrgID)
continue
}
s.log.Error("failed to delete user org membership", "userId", userID, "error", err)
return nil
return err
}
if err := s.accessControl.DeleteUserPermissions(ctx, orgId, cmd.UserID); err != nil {
s.log.Error("failed to delete permissions for user", "error", err, "userID", cmd.UserID, "orgID", orgId)
return nil
if err := s.accessControl.DeleteUserPermissions(ctx, orgID, cmd.UserID); err != nil {
ctxLogger.Error("Failed to delete permissions for user", "id", id.ID, "orgId", orgID, "error", err)
}
}
+10 -22
View File
@@ -3,7 +3,6 @@ package sync
import (
"context"
"errors"
"fmt"
"time"
"github.com/grafana/grafana/pkg/infra/log"
@@ -67,17 +66,13 @@ func (s *UserSync) SyncUserHook(ctx context.Context, id *authn.Identity, _ *auth
// Does user exist in the database?
usr, userAuth, errUserInDB := s.getUser(ctx, id)
if errUserInDB != nil && !errors.Is(errUserInDB, user.ErrUserNotFound) {
s.log.Error("error retrieving user", "error", errUserInDB,
"auth_module", id.AuthModule, "auth_id", id.AuthID,
"lookup_params", id.ClientParams.LookUpParams,
)
s.log.FromContext(ctx).Error("Failed to fetch user", "error", errUserInDB, "auth_module", id.AuthModule, "auth_id", id.AuthID)
return errSyncUserInternal.Errorf("unable to retrieve user")
}
if errors.Is(errUserInDB, user.ErrUserNotFound) {
if !id.ClientParams.AllowSignUp {
s.log.Warn("not allowing login, user not found in internal user database and allow signup = false",
"auth_module", id.AuthModule)
s.log.FromContext(ctx).Warn("Failed to create user, signup is not allowed for module", "auth_module", id.AuthModule, "auth_id", id.AuthID)
return errSyncUserForbidden.Errorf("%w", login.ErrSignupNotAllowed)
}
@@ -85,10 +80,7 @@ func (s *UserSync) SyncUserHook(ctx context.Context, id *authn.Identity, _ *auth
var errCreate error
usr, errCreate = s.createUser(ctx, id)
if errCreate != nil {
s.log.Error("error creating user", "error", errCreate,
"auth_module", id.AuthModule, "auth_id", id.AuthID,
"id_login", id.Login, "id_email", id.Email,
)
s.log.FromContext(ctx).Error("Failed to create user", "error", errCreate, "auth_module", id.AuthModule, "auth_id", id.AuthID)
return errSyncUserInternal.Errorf("unable to create user")
}
}
@@ -99,11 +91,7 @@ func (s *UserSync) SyncUserHook(ctx context.Context, id *authn.Identity, _ *auth
// update user
if errUpdate := s.updateUserAttributes(ctx, usr, id, userAuth); errUpdate != nil {
s.log.Error("error updating user", "error", errUpdate,
"auth_module", id.AuthModule, "auth_id", id.AuthID,
"login", usr.Login, "email", usr.Email,
"id_login", id.Login, "id_email", id.Email,
)
s.log.FromContext(ctx).Error("Failed to update user", "error", errUpdate, "auth_module", id.AuthModule, "auth_id", id.AuthID)
return errSyncUserInternal.Errorf("unable to update user")
}
@@ -147,12 +135,12 @@ func (s *UserSync) SyncLastSeenHook(ctx context.Context, identity *authn.Identit
go func(userID int64) {
defer func() {
if err := recover(); err != nil {
s.log.Error("panic during user last seen sync", "err", err)
s.log.Error("Panic during user last seen sync", "err", err)
}
}()
if err := s.userService.UpdateLastSeenAt(context.Background(), &user.UpdateUserLastSeenAtCommand{UserID: userID}); err != nil {
s.log.Error("failed to update last_seen_at", "err", err, "userId", userID)
s.log.Error("Failed to update last_seen_at", "err", err, "userId", userID)
}
}(id)
@@ -193,7 +181,7 @@ func (s *UserSync) upsertAuthConnection(ctx context.Context, userID int64, ident
})
}
s.log.Debug("Updating user_auth info", "user_id", userID)
s.log.FromContext(ctx).Debug("Updating auth connection for user", "id", identity.ID)
return s.authInfoService.UpdateAuthInfo(ctx, &login.UpdateAuthInfoCommand{
UserId: userID,
AuthId: identity.AuthID,
@@ -228,7 +216,7 @@ func (s *UserSync) updateUserAttributes(ctx context.Context, usr *user.User, id
}
if needsUpdate {
s.log.Debug("Syncing user info", "id", usr.ID, "update", updateCmd)
s.log.FromContext(ctx).Debug("Syncing user info", "id", id.ID, "update", updateCmd)
if err := s.userService.Update(ctx, updateCmd); err != nil {
return err
}
@@ -252,7 +240,7 @@ func (s *UserSync) createUser(ctx context.Context, id *authn.Identity) (*user.Us
for _, srv := range []string{user.QuotaTargetSrv, org.QuotaTargetSrv} {
limitReached, errLimit := s.quotaService.CheckQuotaReached(ctx, quota.TargetSrv(srv), nil)
if errLimit != nil {
s.log.Error("error getting user quota", "error", errLimit)
s.log.FromContext(ctx).Error("Failed to check quota", "error", errLimit)
return nil, errSyncUserInternal.Errorf("%w", login.ErrGettingUserQuota)
}
if limitReached {
@@ -364,7 +352,7 @@ func (s *UserSync) lookupByOneOf(ctx context.Context, params login.UserLookupPar
// syncUserToIdentity syncs a user to an identity.
// This is used to update the identity with the latest user information.
func syncUserToIdentity(usr *user.User, id *authn.Identity) {
id.ID = fmt.Sprintf("user:%d", usr.ID)
id.ID = authn.NamespacedID(authn.NamespaceUser, usr.ID)
id.Login = usr.Login
id.Email = usr.Email
id.Name = usr.Name