From 2a7fc3983b48e5b8ce2c2f6bfb25194fd7465858 Mon Sep 17 00:00:00 2001 From: Karl Persson Date: Fri, 24 Feb 2023 11:26:55 +0100 Subject: [PATCH] AuthN: cleanup logs (#63652) * AuthN: clean up logs Co-authored-by: Ieva --- pkg/services/authn/authnimpl/service.go | 18 +++++----- .../authn/authnimpl/sync/oauth_token_sync.go | 6 ++-- pkg/services/authn/authnimpl/sync/org_sync.go | 35 +++++++++---------- .../authn/authnimpl/sync/user_sync.go | 32 ++++++----------- pkg/services/authn/clients/anonymous.go | 2 +- pkg/services/authn/clients/jwt.go | 6 ++-- pkg/services/authn/clients/password.go | 4 +-- pkg/services/authn/clients/proxy.go | 8 ++--- pkg/services/authn/clients/render.go | 4 +-- pkg/services/authn/clients/render_test.go | 2 +- pkg/services/authn/clients/session.go | 9 ++--- 11 files changed, 57 insertions(+), 69 deletions(-) diff --git a/pkg/services/authn/authnimpl/service.go b/pkg/services/authn/authnimpl/service.go index c0fa3c1bc12..67a26a0937a 100644 --- a/pkg/services/authn/authnimpl/service.go +++ b/pkg/services/authn/authnimpl/service.go @@ -115,7 +115,7 @@ func ProvideService( if s.cfg.AuthProxyEnabled && len(proxyClients) > 0 { proxy, err := clients.ProvideProxy(cfg, cache, userService, proxyClients...) if err != nil { - s.log.Error("failed to configure auth proxy", "err", err) + s.log.Error("Failed to configure auth proxy", "err", err) } else { s.RegisterClient(proxy) } @@ -133,10 +133,10 @@ func ProvideService( connector, errConnector := socialService.GetConnector(name) httpClient, errHTTPClient := socialService.GetOAuthHttpClient(name) if errConnector != nil || errHTTPClient != nil { - s.log.Error("failed to configure oauth client", "client", clientName, "err", multierror.Append(errConnector, errHTTPClient)) + s.log.Error("Failed to configure oauth client", "client", clientName, "err", multierror.Append(errConnector, errHTTPClient)) + } else { + s.RegisterClient(clients.ProvideOAuth(clientName, cfg, oauthCfg, connector, httpClient)) } - - s.RegisterClient(clients.ProvideOAuth(clientName, cfg, oauthCfg, connector, httpClient)) } } @@ -204,13 +204,13 @@ func (s *Service) authenticate(ctx context.Context, c authn.Client, r *authn.Req r.OrgID = orgIDFromRequest(r) identity, err := c.Authenticate(ctx, r) if err != nil { - s.log.FromContext(ctx).Warn("auth client could not authenticate request", "client", c.Name(), "error", err) + s.log.FromContext(ctx).Warn("Failed to authenticate request", "client", c.Name(), "error", err) return nil, err } for _, hook := range s.postAuthHooks.items { if err := hook.v(ctx, identity, r); err != nil { - s.log.FromContext(ctx).Warn("post auth hook failed", "error", err, "client", c.Name(), "id", identity.ID) + s.log.FromContext(ctx).Warn("Failed to run post auth hook", "client", c.Name(), "id", identity.ID, "error", err) return nil, err } } @@ -221,7 +221,7 @@ func (s *Service) authenticate(ctx context.Context, c authn.Client, r *authn.Req if hc, ok := c.(authn.HookClient); ok { if err := hc.Hook(ctx, identity, r); err != nil { - s.log.FromContext(ctx).Warn("post client auth hook failed", "error", err, "client", c.Name(), "id", identity.ID) + s.log.FromContext(ctx).Warn("Failed to run post client auth hook", "client", c.Name(), "id", identity.ID, "error", err) return nil, err } } @@ -260,12 +260,12 @@ func (s *Service) Login(ctx context.Context, client string, r *authn.Request) (i addr := web.RemoteAddr(r.HTTPRequest) ip, err := network.GetIPFromAddress(addr) if err != nil { - s.log.Debug("failed to parse ip from address", "addr", addr) + s.log.FromContext(ctx).Debug("Failed to parse ip from address", "client", c.Name(), "id", identity.ID, "addr", addr, "error", err) } sessionToken, err := s.sessionService.CreateToken(ctx, &user.User{ID: id}, ip, r.HTTPRequest.UserAgent()) if err != nil { - s.log.FromContext(ctx).Error("failed to create session", "client", client, "userId", id, "err", err) + s.log.FromContext(ctx).Error("Failed to create session", "client", client, "id", identity.ID, "err", err) return nil, err } diff --git a/pkg/services/authn/authnimpl/sync/oauth_token_sync.go b/pkg/services/authn/authnimpl/sync/oauth_token_sync.go index 6f98c258cf5..f12c1d21719 100644 --- a/pkg/services/authn/authnimpl/sync/oauth_token_sync.go +++ b/pkg/services/authn/authnimpl/sync/oauth_token_sync.go @@ -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) diff --git a/pkg/services/authn/authnimpl/sync/org_sync.go b/pkg/services/authn/authnimpl/sync/org_sync.go index 364167db3da..a2203411385 100644 --- a/pkg/services/authn/authnimpl/sync/org_sync.go +++ b/pkg/services/authn/authnimpl/sync/org_sync.go @@ -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) } } diff --git a/pkg/services/authn/authnimpl/sync/user_sync.go b/pkg/services/authn/authnimpl/sync/user_sync.go index e8b1a5e7a53..1210274ac1b 100644 --- a/pkg/services/authn/authnimpl/sync/user_sync.go +++ b/pkg/services/authn/authnimpl/sync/user_sync.go @@ -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 diff --git a/pkg/services/authn/clients/anonymous.go b/pkg/services/authn/clients/anonymous.go index 3ca4083d6c3..2d5d919954e 100644 --- a/pkg/services/authn/clients/anonymous.go +++ b/pkg/services/authn/clients/anonymous.go @@ -47,7 +47,7 @@ func (a *Anonymous) Authenticate(ctx context.Context, r *authn.Request) (*authn. } }() if err := a.anonSessionService.TagSession(context.Background(), r.HTTPRequest); err != nil { - a.log.Warn("Failed to tag anonymous session", "error", err) + a.log.Warn("failed to tag anonymous session", "error", err) } }() diff --git a/pkg/services/authn/clients/jwt.go b/pkg/services/authn/clients/jwt.go index 8aa2c759367..fa0a2ebab5e 100644 --- a/pkg/services/authn/clients/jwt.go +++ b/pkg/services/authn/clients/jwt.go @@ -53,13 +53,13 @@ func (s *JWT) Authenticate(ctx context.Context, r *authn.Request) (*authn.Identi claims, err := s.jwtService.Verify(ctx, jwtToken) if err != nil { - s.log.Debug("Failed to verify JWT", "error", err) + s.log.FromContext(ctx).Debug("Failed to verify JWT", "error", err) return nil, errJWTInvalid.Errorf("failed to verify JWT: %w", err) } sub, _ := claims["sub"].(string) if sub == "" { - s.log.Warn("Got a JWT without the mandatory 'sub' claim", "error", err) + s.log.FromContext(ctx).Warn("Got a JWT without the mandatory 'sub' claim", "error", err) return nil, errJWTMissingClaim.Errorf("missing mandatory 'sub' claim in JWT") } @@ -112,7 +112,7 @@ func (s *JWT) Authenticate(ctx context.Context, r *authn.Request) (*authn.Identi id.IsGrafanaAdmin = isGrafanaAdmin if id.Login == "" && id.Email == "" { - s.log.Debug("Failed to get an authentication claim from JWT", + s.log.FromContext(ctx).Debug("Failed to get an authentication claim from JWT", "login", id.Login, "email", id.Email) return nil, errJWTMissingClaim.Errorf("missing login and email claim in JWT") } diff --git a/pkg/services/authn/clients/password.go b/pkg/services/authn/clients/password.go index 226cfdaaac5..d5c90b80ffa 100644 --- a/pkg/services/authn/clients/password.go +++ b/pkg/services/authn/clients/password.go @@ -51,9 +51,9 @@ func (c *Password) AuthenticatePassword(ctx context.Context, r *authn.Request, u for _, pwClient := range c.clients { identity, clientErr := pwClient.AuthenticatePassword(ctx, r, username, password) clientErrs = multierror.Append(clientErrs, clientErr) - // for invalid password or if the identity is not found by a client continue to next one + // we always try next client on any error if clientErr != nil { - c.log.Warn("failed to authenticate password identity", "client", pwClient, "error", clientErr) + c.log.FromContext(ctx).Debug("Failed to authenticate password identity", "client", pwClient, "error", clientErr) continue } diff --git a/pkg/services/authn/clients/proxy.go b/pkg/services/authn/clients/proxy.go index 99ac48e4c16..dc1554c0c73 100644 --- a/pkg/services/authn/clients/proxy.go +++ b/pkg/services/authn/clients/proxy.go @@ -89,13 +89,13 @@ func (c *Proxy) Authenticate(ctx context.Context, r *authn.Request) (*authn.Iden }) if err != nil { - c.log.Warn("could not resolved cached user", "error", err, "userId", entry.(int64)) + c.log.FromContext(ctx).Warn("Could not resolved cached user", "error", err, "userId", entry.(int64)) } // if we for some reason cannot find the user we proceed with the normal flow, authenticate with ProxyClient // and perform syncs if usr != nil { - c.log.Debug("user was loaded from cache, skip syncs", "userId", usr.UserID) + c.log.FromContext(ctx).Debug("User was loaded from cache, skip syncs", "userId", usr.UserID) return authn.IdentityFromSignedInUser(authn.NamespacedID(authn.NamespaceUser, usr.UserID), usr, authn.ClientParams{}), nil } } @@ -132,9 +132,9 @@ func (c *Proxy) Hook(ctx context.Context, identity *authn.Identity, r *authn.Req return nil } - c.log.Debug("cache proxy user", "userId", id) + c.log.FromContext(ctx).Debug("Cache proxy user", "userId", id) if err := c.cache.Set(ctx, identity.ClientParams.CacheAuthProxyKey, id, time.Duration(c.cfg.AuthProxySyncTTL)*time.Minute); err != nil { - c.log.Warn("failed to cache proxy user", "error", err, "userId", id) + c.log.FromContext(ctx).Warn("Failed to cache proxy user", "error", err, "userId", id) } return nil diff --git a/pkg/services/authn/clients/render.go b/pkg/services/authn/clients/render.go index 44df3ecc4ed..52e39b1a981 100644 --- a/pkg/services/authn/clients/render.go +++ b/pkg/services/authn/clients/render.go @@ -13,7 +13,7 @@ import ( ) var ( - ErrInvalidRenderKey = errutil.NewBase(errutil.StatusUnauthorized, "render-auth.invalid-key", errutil.WithPublicMessage("Invalid Render Key")) + errInvalidRenderKey = errutil.NewBase(errutil.StatusUnauthorized, "render-auth.invalid-key", errutil.WithPublicMessage("Invalid Render Key")) ) const ( @@ -39,7 +39,7 @@ func (c *Render) Authenticate(ctx context.Context, r *authn.Request) (*authn.Ide key := getRenderKey(r) renderUsr, ok := c.renderService.GetRenderUser(ctx, key) if !ok { - return nil, ErrInvalidRenderKey.Errorf("found no render user for key: %s", key) + return nil, errInvalidRenderKey.Errorf("found no render user for key: %s", key) } var identity *authn.Identity diff --git a/pkg/services/authn/clients/render_test.go b/pkg/services/authn/clients/render_test.go index 5a69914b05b..d38e2421634 100644 --- a/pkg/services/authn/clients/render_test.go +++ b/pkg/services/authn/clients/render_test.go @@ -84,7 +84,7 @@ func TestRender_Authenticate(t *testing.T) { Header: map[string][]string{"Cookie": {"renderKey=123"}}, }, }, - expectedErr: ErrInvalidRenderKey, + expectedErr: errInvalidRenderKey, }, } diff --git a/pkg/services/authn/clients/session.go b/pkg/services/authn/clients/session.go index 8a54a27eabf..39cc1fc74ac 100644 --- a/pkg/services/authn/clients/session.go +++ b/pkg/services/authn/clients/session.go @@ -54,14 +54,15 @@ func (s *Session) Authenticate(ctx context.Context, r *authn.Request) (*authn.Id token, err := s.sessionService.LookupToken(ctx, rawSessionToken) if err != nil { - s.log.Warn("failed to look up session from cookie", "error", err) + s.log.FromContext(ctx).Warn("Failed to look up session from cookie", "error", err) return nil, err } - signedInUser, err := s.userService.GetSignedInUserWithCacheCtx(ctx, - &user.GetSignedInUserQuery{UserID: token.UserId, OrgID: r.OrgID}) + signedInUser, err := s.userService.GetSignedInUserWithCacheCtx( + ctx, &user.GetSignedInUserQuery{UserID: token.UserId, OrgID: r.OrgID}, + ) if err != nil { - s.log.Error("failed to get user with id", "userId", token.UserId, "error", err) + s.log.FromContext(ctx).Error("Failed to get user with id", "userId", token.UserId, "error", err) return nil, err }