diff --git a/lib/auth/accountrecovery.go b/lib/auth/accountrecovery.go index c7aa11c403f5a..7f133e4f3f3d1 100644 --- a/lib/auth/accountrecovery.go +++ b/lib/auth/accountrecovery.go @@ -210,7 +210,7 @@ func (a *Server) VerifyAccountRecovery(ctx context.Context, req *proto.VerifyAcc return nil, trace.AccessDenied(verifyRecoveryBadAuthnErrMsg) } - if err := a.verifyUserToken(startToken, authclient.UserTokenTypeRecoveryStart); err != nil { + if err := a.verifyUserToken(ctx, startToken, authclient.UserTokenTypeRecoveryStart); err != nil { return nil, trace.Wrap(err) } @@ -304,7 +304,7 @@ func (a *Server) CompleteAccountRecovery(ctx context.Context, req *proto.Complet return trace.AccessDenied(completeRecoveryGenericErrMsg) } - if err := a.verifyUserToken(approvedToken, authclient.UserTokenTypeRecoveryApproved); err != nil { + if err := a.verifyUserToken(ctx, approvedToken, authclient.UserTokenTypeRecoveryApproved); err != nil { return trace.Wrap(err) } @@ -403,7 +403,7 @@ func (a *Server) CreateAccountRecoveryCodes(ctx context.Context, req *proto.Crea return nil, trace.AccessDenied("only local users may create recovery codes") } - if err := a.verifyUserToken(token, authclient.UserTokenTypeRecoveryApproved, authclient.UserTokenTypePrivilege); err != nil { + if err := a.verifyUserToken(ctx, token, authclient.UserTokenTypeRecoveryApproved, authclient.UserTokenTypePrivilege); err != nil { return nil, trace.Wrap(err) } @@ -428,7 +428,7 @@ func (a *Server) GetAccountRecoveryToken(ctx context.Context, req *proto.GetAcco return nil, trace.AccessDenied("access denied") } - if err := a.verifyUserToken(token, authclient.UserTokenTypeRecoveryStart, authclient.UserTokenTypeRecoveryApproved); err != nil { + if err := a.verifyUserToken(ctx, token, authclient.UserTokenTypeRecoveryStart, authclient.UserTokenTypeRecoveryApproved); err != nil { return nil, trace.Wrap(err) } diff --git a/lib/auth/auth.go b/lib/auth/auth.go index 7d15e272af2c2..067cea661c7e1 100644 --- a/lib/auth/auth.go +++ b/lib/auth/auth.go @@ -123,6 +123,7 @@ import ( usagereporter "github.com/gravitational/teleport/lib/usagereporter/teleport" "github.com/gravitational/teleport/lib/utils" "github.com/gravitational/teleport/lib/utils/interval" + logutils "github.com/gravitational/teleport/lib/utils/log" vc "github.com/gravitational/teleport/lib/versioncontrol" "github.com/gravitational/teleport/lib/versioncontrol/github" uw "github.com/gravitational/teleport/lib/versioncontrol/upgradewindow" @@ -538,14 +539,14 @@ func NewServer(cfg *InitConfig, opts ...ServerOption) (*Server, error) { if g, ok := connectedResourceGauges[s]; ok { g.Inc() } else { - log.Warnf("missing connected resources gauge for keep alive %s (this is a bug)", s) + as.logger.WarnContext(closeCtx, "missing connected resources gauge for keep alive (this is a bug)", "keep_alive_type", s) } }), inventory.WithOnDisconnect(func(s string, c int) { if g, ok := connectedResourceGauges[s]; ok { g.Sub(float64(c)) } else { - log.Warnf("missing connected resources gauge for keep alive %s (this is a bug)", s) + as.logger.WarnContext(closeCtx, "missing connected resources gauge for keep alive (this is a bug)", "keep_alive_type", s) } }), ) @@ -666,7 +667,7 @@ func NewServer(cfg *InitConfig, opts ...ServerOption) (*Server, error) { as.RegisterLoginHook(as.ulsGenerator.LoginHook(services.UserLoginStates)) if _, ok := as.getCache(); !ok { - log.Warn("Auth server starting without cache (may have negative performance implications).") + as.logger.WarnContext(closeCtx, "Auth server starting without cache (may have negative performance implications)") } return &as, nil @@ -1444,7 +1445,7 @@ func (a *Server) runPeriodicOperations() { Jitter: retryutils.HalfJitter, }) } else if err := a.DeleteClusterAlert(a.closeCtx, OSSDesktopsAlertID); err != nil && !trace.IsNotFound(err) { - log.Warnf("Can't delete OSS non-AD desktops limit alert: %v", err) + a.logger.WarnContext(a.closeCtx, "Can't delete OSS non-AD desktops limit alert", "error", err) } // isolate the schedule of potentially long-running refreshRemoteClusters() from other tasks @@ -1487,9 +1488,9 @@ func (a *Server) runPeriodicOperations() { go func() { if err := a.AutoRotateCertAuthorities(a.closeCtx); err != nil { if trace.IsCompareFailed(err) { - log.Debugf("Cert authority has been updated concurrently: %v.", err) + a.logger.DebugContext(a.closeCtx, "Cert authority has been updated concurrently", "error", err) } else { - log.Errorf("Failed to perform cert rotation check: %v.", err) + a.logger.ErrorContext(a.closeCtx, "Failed to perform cert rotation check", "error", err) } } }() @@ -1535,7 +1536,7 @@ func (a *Server) runPeriodicOperations() { return false, nil } if _, err := a.Services.UpdateNode(a.closeCtx, srv); err != nil && !trace.IsCompareFailed(err) { - log.Warnf("Failed to update node hostname: %v", err) + logger.WarnContext(a.closeCtx, "Failed to update node hostname", "error", err) } } @@ -1544,7 +1545,7 @@ func (a *Server) runPeriodicOperations() { req, ) if err != nil { - log.Errorf("Failed to load nodes for heartbeat metric calculation: %v", err) + a.logger.ErrorContext(a.closeCtx, "Failed to load nodes for heartbeat metric calculation", "error", err) return } @@ -1662,7 +1663,7 @@ func (a *Server) doInstancePeriodics(ctx context.Context) { } if err := instances.Done(); err != nil { - log.Warnf("Failed stream instances for periodics: %v", err) + a.logger.WarnContext(ctx, "Failed stream instances for periodics", "error", err) return } @@ -1680,7 +1681,7 @@ func (a *Server) handleUpgradeEnrollPrompt(ctx context.Context, msg string, shou if !shouldPrompt { if err := a.DeleteClusterAlert(ctx, upgradeEnrollAlertID); err != nil && !trace.IsNotFound(err) { - log.Warnf("Failed to delete %s alert: %v", upgradeEnrollAlertID, err) + a.logger.WarnContext(ctx, "Failed to delete auto-upgrade-enroll alert", "error", err) } return } @@ -1698,11 +1699,11 @@ func (a *Server) handleUpgradeEnrollPrompt(ctx context.Context, msg string, shou types.WithAlertExpires(a.clock.Now().Add(alertTTL)), ) if err != nil { - log.Warnf("Failed to build %s alert: %v (this is a bug)", upgradeEnrollAlertID, err) + a.logger.WarnContext(ctx, "Failed to build auto-upgrade-enroll alert (this is a bug)", "error", err) return } if err := a.UpsertClusterAlert(ctx, alert); err != nil { - log.Warnf("Failed to set %s alert: %v", upgradeEnrollAlertID, err) + a.logger.WarnContext(ctx, "Failed to set auto-upgrade-enroll alert", "error", err) return } } @@ -1717,7 +1718,7 @@ const ( // is true it pulls the latest release info from GitHub. Otherwise, it loads the versions used // for the most recent alerts and re-syncs with latest cluster state. func (a *Server) syncReleaseAlerts(ctx context.Context, checkRemote bool) { - log.Debug("Checking for new teleport releases via github api.") + a.logger.DebugContext(ctx, "Checking for new teleport releases via github api") // NOTE: essentially everything in this function is going to be // scrapped/replaced once the inventory and version-control systems @@ -1746,12 +1747,12 @@ func (a *Server) syncReleaseAlerts(ctx context.Context, checkRemote bool) { if checkRemote { // scrape the github releases API with our visitor if err := github.Visit(&visitor); err != nil { - log.Warnf("Failed to load github releases: %v (this will not impact teleport functionality)", err) + a.logger.WarnContext(ctx, "Failed to load github releases (this will not impact teleport functionality)", "error", err) loadFailed = true } } else { if err := a.visitCachedAlertVersions(ctx, &visitor); err != nil { - log.Warnf("Failed to load release alert into: %v (this will not impact teleport functionality)", err) + a.logger.WarnContext(ctx, "Failed to load release alert info (this will not impact teleport functionality)", "error", err) loadFailed = true } } @@ -1816,7 +1817,10 @@ func (a *Server) doReleaseAlertSync(ctx context.Context, current vc.Target, visi if sp := visitor.NewestSecurityPatch(); sp.Ok() && sp.NewerThan(current) && !sp.SecurityPatchAltOf(current) { // explicit security patch alerts have a more limited audience, so we generate // them as their own separate alert. - log.Warnf("A newer security patch has been detected. current=%s, patch=%s", current.Version(), sp.Version()) + a.logger.WarnContext(ctx, "A newer security patch has been detected", + "current_version", current.Version(), + "patch_version", sp.Version(), + ) secMsg := fmt.Sprintf("A security patch is available for Teleport. Please upgrade your Cluster to %s or newer.", sp.Version()) alert, err := types.NewClusterAlert( @@ -1835,18 +1839,18 @@ func (a *Server) doReleaseAlertSync(ctx context.Context, current vc.Target, visi types.WithAlertExpires(a.clock.Now().Add(alertTTL)), ) if err != nil { - log.Warnf("Failed to build %s alert: %v (this is a bug)", secAlertID, err) + a.logger.WarnContext(ctx, "Failed to build security-patch-available alert (this is a bug)", "error", err) return } if err := a.UpsertClusterAlert(ctx, alert); err != nil { - log.Warnf("Failed to set %s alert: %v", secAlertID, err) + a.logger.WarnContext(ctx, "Failed to set security-patch-available alert", "error", err) return } } else if cleanup { err := a.DeleteClusterAlert(ctx, secAlertID) if err != nil && !trace.IsNotFound(err) { - log.Warnf("Failed to delete %s alert: %v", secAlertID, err) + a.logger.WarnContext(ctx, "Failed to delete security-patch-available alert", "error", err) } } } @@ -1900,13 +1904,13 @@ var ( func (a *Server) refreshRemoteClusters(ctx context.Context) { remoteClusters, err := a.Services.GetRemoteClusters(ctx) if err != nil { - log.WithError(err).Error("Failed to load remote clusters for status refresh") + a.logger.ErrorContext(ctx, "Failed to load remote clusters for status refresh", "error", err) return } netConfig, err := a.GetClusterNetworkingConfig(ctx) if err != nil { - log.WithError(err).Error("Failed to load networking config for remote cluster status refresh") + a.logger.ErrorContext(ctx, "Failed to load networking config for remote cluster status refresh", "error", err) return } @@ -1926,7 +1930,7 @@ func (a *Server) refreshRemoteClusters(ctx context.Context) { var updateCount int for _, remoteCluster := range remoteClusters { if updated, err := a.updateRemoteClusterStatus(ctx, netConfig, remoteCluster); err != nil { - log.WithError(err).Error("Failed to perform remote cluster status refresh") + a.logger.ErrorContext(ctx, "Failed to perform remote cluster status refresh", "error", err) } else if updated { updateCount++ } @@ -3483,7 +3487,9 @@ func (a *Server) attestHardwareKey(ctx context.Context, params *attestHardwareKe // a serial number in the user's traits, if any are set. registeredSerialNumbers, ok := params.userTraits[serialNumberTraitName] if !ok || len(registeredSerialNumbers) == 0 { - log.Debugf("user %q tried to sign in with hardware key support, but has no known hardware keys. A user's known hardware key serial numbers should be set \"in user.traits.%v\"", params.userName, serialNumberTraitName) + a.logger.DebugContext(ctx, "A user tried to sign in with hardware key support, but has no known hardware keys set in their traits", + "user", params.userName, + "expected_trait", "user.traits."+serialNumberTraitName) return attestedKeyPolicy, trace.BadParameter("cannot generate certs for user with no known hardware keys") } @@ -3493,7 +3499,10 @@ func (a *Server) attestHardwareKey(ctx context.Context, params *attestHardwareKe if !slices.ContainsFunc(registeredSerialNumbers, func(s string) bool { return slices.Contains(strings.Split(s, ","), attestedSerialNumber) }) { - log.Debugf("user %q tried to sign in with hardware key support with an unknown hardware key and was denied: YubiKey serial number %q", params.userName, attestedSerialNumber) + a.logger.DebugContext(ctx, "A user tried to sign in with hardware key support with an unknown hardware key and was denied", + "user", params.userName, + "yubikey_serial_number", attestedSerialNumber, + ) return attestedKeyPolicy, trace.BadParameter("cannot generate certs for user with unknown hardware key: YubiKey serial number %q", attestedSerialNumber) } } @@ -3585,7 +3594,7 @@ func (a *Server) emitCertCreateEvent(ctx context.Context, identity *tlsca.Identi UserAgent: trimUserAgent(metadata.UserAgentFromContext(ctx)), }, }); err != nil { - log.WithError(err).Warn("Failed to emit certificate create event.") + a.logger.WarnContext(ctx, "Failed to emit certificate create event", "error", err) } } @@ -3610,8 +3619,11 @@ func (a *Server) WithUserLock(ctx context.Context, username string, authenticate status := user.GetStatus() if status.IsLocked { if status.LockExpires.After(a.clock.Now().UTC()) { - log.Debugf("%v exceeds %v failed login attempts, locked until %v", - user.GetName(), defaults.MaxLoginAttempts, apiutils.HumanTimeFormat(status.LockExpires)) + a.logger.DebugContext(ctx, "Locking user that exceeded the failed login attempt limit", + "user", user.GetName(), + "failed_attempt_limit", defaults.MaxLoginAttempts, + "locked_until", apiutils.HumanTimeFormat(status.LockExpires), + ) err := trace.AccessDenied(MaxFailedAttemptsErrMsg) return trace.WithField(err, ErrFieldKeyUserMaxedAttempts, true) @@ -3635,25 +3647,31 @@ func (a *Server) WithUserLock(ctx context.Context, username string, authenticate attempt := services.LoginAttempt{Time: a.clock.Now().UTC(), Success: false} err = a.AddUserLoginAttempt(username, attempt, defaults.AttemptTTL) if err != nil { - log.Error(trace.DebugReport(err)) + a.logger.ErrorContext(ctx, "unable to persist failed login attempt", "error", err) return trace.Wrap(fnErr) } loginAttempts, err := a.GetUserLoginAttempts(username) if err != nil { - log.Error(trace.DebugReport(err)) + a.logger.ErrorContext(ctx, "unable to retrieve user login attempts", "error", err) return trace.Wrap(fnErr) } if !services.LastFailed(defaults.MaxLoginAttempts, loginAttempts) { - log.Debugf("%v user has less than %v failed login attempts", username, defaults.MaxLoginAttempts) + a.logger.DebugContext(ctx, "user has less than the failed login attempt limit", + "user", username, + "failed_attempt_limit", defaults.MaxLoginAttempts, + ) return trace.Wrap(fnErr) } lockUntil := a.clock.Now().UTC().Add(defaults.AccountLockInterval) - log.Debug(fmt.Sprintf("%v exceeds %v failed login attempts, locked until %v", - username, defaults.MaxLoginAttempts, apiutils.HumanTimeFormat(lockUntil))) + a.logger.DebugContext(ctx, "Locking user that exceeded the failed login attempt limit", + "user", username, + "failed_attempt_limit", defaults.MaxLoginAttempts, + "locked_until", apiutils.HumanTimeFormat(lockUntil), + ) user.SetLocked(lockUntil, "user has exceeded maximum failed login attempts") _, err = a.UpsertUser(ctx, user) if err != nil { - log.Error(trace.DebugReport(err)) + a.logger.ErrorContext(ctx, "failed to persist user record", "error", err) return trace.Wrap(fnErr) } @@ -3695,7 +3713,7 @@ func (a *Server) CreateAuthenticateChallenge(ctx context.Context, req *proto.Cre username: username, authErr: err, }); err != nil { - log.WithError(err).Warn("Failed to emit login event") + a.logger.WarnContext(ctx, "Failed to emit login event", "error", err) // err swallowed on purpose. } return nil, trace.Wrap(err) @@ -3708,11 +3726,11 @@ func (a *Server) CreateAuthenticateChallenge(ctx context.Context, req *proto.Cre case *proto.CreateAuthenticateChallengeRequest_RecoveryStartTokenID: token, err := a.GetUserToken(ctx, req.GetRecoveryStartTokenID()) if err != nil { - log.Error(trace.DebugReport(err)) + a.logger.ErrorContext(ctx, "failed to get user token", "error", err) return nil, trace.AccessDenied("invalid token") } - if err := a.verifyUserToken(token, authclient.UserTokenTypeRecoveryStart); err != nil { + if err := a.verifyUserToken(ctx, token, authclient.UserTokenTypeRecoveryStart); err != nil { return nil, trace.Wrap(err) } @@ -3747,7 +3765,7 @@ func (a *Server) CreateAuthenticateChallenge(ctx context.Context, req *proto.Cre return nil, trace.Wrap(err) } - log.Error(trace.DebugReport(err)) + a.logger.ErrorContext(ctx, "failed to create MFA challenge", "error", err) return nil, trace.AccessDenied("unable to create MFA challenges") } @@ -3763,7 +3781,7 @@ func (a *Server) CreateRegisterChallenge(ctx context.Context, req *proto.CreateR var err error token, err = a.GetUserToken(ctx, req.GetTokenID()) if err != nil { - log.Error(trace.DebugReport(err)) + a.logger.ErrorContext(ctx, "failed to retrieve user token", "error", err) return nil, trace.AccessDenied("invalid token") } @@ -3774,7 +3792,7 @@ func (a *Server) CreateRegisterChallenge(ctx context.Context, req *proto.CreateR authclient.UserTokenTypeResetPasswordInvite, authclient.UserTokenTypeRecoveryApproved, } - if err := a.verifyUserToken(token, allowedTokenTypes...); err != nil { + if err := a.verifyUserToken(ctx, token, allowedTokenTypes...); err != nil { return nil, trace.AccessDenied("invalid token") } username = token.GetUser() @@ -3930,11 +3948,11 @@ func (a *Server) GetMFADevices(ctx context.Context, req *proto.GetMFADevicesRequ if req.GetTokenID() != "" { token, err := a.GetUserToken(ctx, req.GetTokenID()) if err != nil { - log.Error(trace.DebugReport(err)) + a.logger.ErrorContext(ctx, "failed to retrieve user token", "error", err) return nil, trace.AccessDenied("invalid token") } - if err := a.verifyUserToken(token, authclient.UserTokenTypeRecoveryApproved); err != nil { + if err := a.verifyUserToken(ctx, token, authclient.UserTokenTypeRecoveryApproved); err != nil { return nil, trace.Wrap(err) } @@ -3966,12 +3984,12 @@ func (a *Server) DeleteMFADeviceSync(ctx context.Context, req *proto.DeleteMFADe case req.TokenID != "": token, err := a.GetUserToken(ctx, req.TokenID) if err != nil { - log.Error(trace.DebugReport(err)) + a.logger.ErrorContext(ctx, "failed to retrieve user token", "error", err) return trace.AccessDenied("invalid token") } user = token.GetUser() - if err := a.verifyUserToken(token, authclient.UserTokenTypeRecoveryApproved, authclient.UserTokenTypePrivilege); err != nil { + if err := a.verifyUserToken(ctx, token, authclient.UserTokenTypeRecoveryApproved, authclient.UserTokenTypePrivilege); err != nil { return trace.Wrap(err) } @@ -4045,7 +4063,7 @@ func (a *Server) deleteMFADeviceSafely(ctx context.Context, user, deviceName str case *types.MFADevice_Sso: remainingDevices[types.SecondFactorType_SECOND_FACTOR_TYPE_SSO]++ default: - log.Warnf("Ignoring unknown device with type %T in deletion.", d.Device) + a.logger.WarnContext(ctx, "Ignoring unknown device type in deletion", "device_type", logutils.TypeAttr(d.Device)) continue } @@ -4123,11 +4141,12 @@ func (a *Server) AddMFADeviceSync(ctx context.Context, req *proto.AddMFADeviceSy case token != "": privilegeToken, err := a.GetUserToken(ctx, token) if err != nil { - log.Error(trace.DebugReport(err)) + a.logger.ErrorContext(ctx, "failed to retrieve user token", "error", err) return nil, trace.AccessDenied("invalid token") } if err := a.verifyUserToken( + ctx, privilegeToken, authclient.UserTokenTypePrivilege, authclient.UserTokenTypePrivilegeException, @@ -4221,7 +4240,7 @@ func (a *Server) verifyMFARespAndAddDevice(ctx context.Context, req *newMFADevic MFADeviceMetadata: mfaDeviceEventMetadata(dev), ConnectionMetadata: authz.ConnectionMetadata(ctx), }); err != nil { - log.WithError(err).Warn("Failed to emit add mfa device event.") + a.logger.WarnContext(ctx, "Failed to emit add mfa device event", "error", err) } return dev, nil @@ -4590,7 +4609,11 @@ func (a *Server) GenerateHostCerts(ctx context.Context, req *proto.HostCertsRequ if err := a.limiter.AcquireConnection(req.Role.String()); err != nil { generateThrottledRequestsCount.Inc() - log.Debugf("Node %q [%v] is rate limited: %v.", req.NodeName, req.HostID, req.Role) + a.logger.DebugContext(ctx, "Rejecting request to generate host certs because host is rate limited", + "name", req.NodeName, + "host_id", req.HostID, + "role", req.Role, + ) return nil, trace.Wrap(err) } defer a.limiter.ReleaseConnection(req.Role.String()) @@ -4648,7 +4671,10 @@ func (a *Server) GenerateHostCerts(ctx context.Context, req *proto.HostCertsRequ // cache is out of sync, this will result in higher read rate // to the backend, which is a fine tradeoff if !req.NoCache && !req.Rotation.IsZero() && !req.Rotation.Matches(ca.GetRotation()) { - log.Debugf("Client sent rotation state %v, cache state is %v, using state from the DB.", req.Rotation, ca.GetRotation()) + a.logger.DebugContext(ctx, "Client sent rotation state and cache state mismatch, retrieving state from the DB", + "client_state", req.Rotation, + "cache_state", ca.GetRotation(), + ) ca, err = a.Services.GetCertAuthority(ctx, types.CertAuthID{ Type: types.HostCA, DomainName: clusterName.GetClusterName(), @@ -4956,7 +4982,7 @@ func (a *Server) checkTokenTTL(tok types.ProvisionToken) bool { defer cancel() if err := a.DeleteToken(ctx, tok.GetName()); err != nil { if !trace.IsNotFound(err) { - log.Warnf("Unable to delete token from backend: %v.", err) + a.logger.WarnContext(ctx, "Unable to delete token from backend", "error", err) } } }() @@ -5160,7 +5186,10 @@ func (a *Server) CreateAccessRequestV2(ctx context.Context, req types.AccessRequ return nil, trace.Wrap(err) } - log.Debugf("Creating Access Request %v with expiry %v.", req.GetName(), req.Expiry()) + a.logger.DebugContext(ctx, "Creating Access Request", + "request_name", req.GetName(), + "request_expiry", req.Expiry(), + ) if _, err := a.Services.CreateAccessRequestV2(ctx, req); err != nil { return nil, trace.Wrap(err) @@ -5171,7 +5200,7 @@ func (a *Server) CreateAccessRequestV2(ctx context.Context, req types.AccessRequ var err error annotations, err = apievents.EncodeMapStrings(sa) if err != nil { - log.WithError(err).Debug("Failed to encode access request annotations.") + a.logger.DebugContext(ctx, "Failed to encode access request annotations", "error", err) } } @@ -5193,7 +5222,7 @@ func (a *Server) CreateAccessRequestV2(ctx context.Context, req types.AccessRequ Annotations: annotations, }) if err != nil { - log.WithError(err).Warn("Failed to emit access request create event.") + a.logger.WarnContext(ctx, "Failed to emit access request create event", "error", err) } // Create a notification. @@ -5238,7 +5267,7 @@ func (a *Server) CreateAccessRequestV2(ctx context.Context, req types.AccessRequ }, }) if err != nil { - log.WithError(err).Warn("Failed to create access request notification") + a.logger.WarnContext(ctx, "Failed to create access request notification", "error", err) } // calculate the promotions @@ -5247,7 +5276,7 @@ func (a *Server) CreateAccessRequestV2(ctx context.Context, req types.AccessRequ // Create the promotion entry even if the allowed promotion is empty. Otherwise, we won't // be able to distinguish between an allowed empty set and generation failure. if err := a.Services.CreateAccessRequestAllowedPromotions(ctx, reqCopy, promotions); err != nil { - log.WithError(err).Warn("Failed to update access request with promotions.") + a.logger.WarnContext(ctx, "Failed to update access request with promotions", "error", err) } } @@ -5328,7 +5357,7 @@ func (a *Server) generateAccessRequestPromotions(ctx context.Context, req types. if err != nil { // Do not fail the request if the promotions failed to generate. // The request promotion will be blocked, but the request can still be approved. - log.WithError(err).Warn("Failed to generate access list promotions.") + a.logger.WarnContext(ctx, "Failed to generate access list promotions", "error", err) } return reqCopy, promotions } @@ -5347,7 +5376,7 @@ func updateAccessRequestWithAdditionalReviewers(ctx context.Context, req types.A for _, promotion := range promotions.Promotions { allOwners, err := accessLists.GetAccessListOwners(ctx, promotion.AccessListName) if err != nil { - log.WithError(err).Warnf("Failed to get nested access list owners for %v, skipping additional reviewers", promotion.AccessListName) + logger.WarnContext(ctx, "Failed to get nested access list owners, skipping additional reviewers", "error", err, "access_list", promotion.AccessListName) break } @@ -5374,7 +5403,7 @@ func (a *Server) DeleteAccessRequest(ctx context.Context, name string) error { UserMetadata: authz.ClientUserMetadata(ctx), RequestID: name, }); err != nil { - log.WithError(err).Warn("Failed to emit access request delete event.") + a.logger.WarnContext(ctx, "Failed to emit access request delete event", "error", err) } return nil } @@ -5403,7 +5432,7 @@ func (a *Server) SetAccessRequestState(ctx context.Context, params types.AccessR var err error event.Annotations, err = apievents.EncodeMapStrings(sa) if err != nil { - log.WithError(err).Debug("Failed to encode access request annotations.") + a.logger.DebugContext(ctx, "Failed to encode access request annotations", "error", err) } } @@ -5414,14 +5443,14 @@ func (a *Server) SetAccessRequestState(ctx context.Context, params types.AccessR if len(params.Annotations) > 0 { annotations, err := apievents.EncodeMapStrings(params.Annotations) if err != nil { - log.WithError(err).Debugf("Failed to encode access request annotations.") + a.logger.DebugContext(ctx, "Failed to encode access request annotations", "error", err) } else { event.Annotations = annotations } } err = a.emitter.EmitAuditEvent(a.closeCtx, event) if err != nil { - log.WithError(err).Warn("Failed to emit access request update event.") + a.logger.WarnContext(ctx, "Failed to emit access request update event", "error", err) } return trace.Wrap(err) } @@ -5498,20 +5527,20 @@ func (a *Server) submitAccessReview( if !req.GetState().IsPending() { _, err = a.Services.CreateUserNotification(ctx, generateAccessRequestReviewedNotification(req, params)) if err != nil { - log.WithError(err).Debugf("Failed to emit access request reviewed notification.") + a.logger.DebugContext(ctx, "Failed to emit access request reviewed notification", "error", err) } } if len(params.Review.Annotations) > 0 { annotations, err := apievents.EncodeMapStrings(params.Review.Annotations) if err != nil { - log.WithError(err).Debugf("Failed to encode access request annotations.") + a.logger.DebugContext(ctx, "Failed to encode access request annotations", "error", err) } else { event.Annotations = annotations } } if err := a.emitter.EmitAuditEvent(a.closeCtx, event); err != nil { - log.WithError(err).Warn("Failed to emit access request update event.") + a.logger.WarnContext(ctx, "Failed to emit access request update event", "error", err) } return req, nil @@ -5836,7 +5865,7 @@ func (a *Server) DeleteWindowsDesktop(ctx context.Context, hostID, name string) return trace.Wrap(err) } if _, err := a.desktopsLimitExceeded(ctx); err != nil { - log.Warnf("Can't check OSS non-AD desktops limit: %v", err) + a.logger.WarnContext(ctx, "Can't check OSS non-AD desktops limit", "error", err) } return nil } @@ -5911,7 +5940,7 @@ func (a *Server) streamWindowsDesktops(ctx context.Context, startKey string) str func (a *Server) syncDesktopsLimitAlert(ctx context.Context) { exceeded, err := a.desktopsLimitExceeded(ctx) if err != nil { - log.Warnf("Can't check OSS non-AD desktops limit: %v", err) + a.logger.WarnContext(ctx, "Can't check OSS non-AD desktops limit", "error", err) } if !exceeded { return @@ -5924,10 +5953,10 @@ func (a *Server) syncDesktopsLimitAlert(ctx context.Context) { types.WithAlertLabel(types.AlertLinkText, OSSDesktopsAlertLinkText), types.WithAlertExpires(time.Now().Add(OSSDesktopsCheckPeriod))) if err != nil { - log.Warnf("Can't create OSS non-AD desktops limit alert: %v", err) + a.logger.WarnContext(ctx, "Can't create OSS non-AD desktops limit alert", "error", err) } if err := a.UpsertClusterAlert(ctx, alert); err != nil { - log.Warnf("Can't upsert OSS non-AD desktops limit alert: %v", err) + a.logger.WarnContext(ctx, "Can't upsert OSS non-AD desktops limit alert", "error", err) } } @@ -5957,7 +5986,7 @@ func (a *Server) desktopsLimitExceeded(ctx context.Context) (bool, error) { func (a *Server) syncDynamicLabelsAlert(ctx context.Context) { roles, err := a.GetRoles(ctx) if err != nil { - log.Warnf("Can't get roles: %v", err) + a.logger.WarnContext(ctx, "Can't get roles", "error", err) } var rolesWithDynamicDenyLabels bool for _, role := range roles { @@ -5967,7 +5996,10 @@ func (a *Server) syncDynamicLabelsAlert(ctx context.Context) { break } if err != nil { - log.Warnf("Error checking labels in role %s: %v", role.GetName(), err) + a.logger.WarnContext(ctx, "Error checking labels in role", + "role", role.GetName(), + "error", err, + ) continue } } @@ -5981,10 +6013,10 @@ func (a *Server) syncDynamicLabelsAlert(ctx context.Context) { types.WithAlertLabel(types.AlertVerbPermit, fmt.Sprintf("%s:%s", types.KindRole, types.VerbRead)), ) if err != nil { - log.Warnf("Failed to build %s alert: %v (this is a bug)", dynamicLabelAlertID, err) + a.logger.WarnContext(ctx, "Failed to build dynamic-labels-in-deny-rules alert(this is a bug)", "error", err) } if err := a.UpsertClusterAlert(ctx, alert); err != nil { - log.Warnf("Failed to set %s alert: %v", dynamicLabelAlertID, err) + a.logger.WarnContext(ctx, "Failed to set dynamic-labels-in-deny-rules alert", "error", err) } } @@ -6002,7 +6034,7 @@ func (a *Server) CleanupNotifications(ctx context.Context) { } response, nextKey, err := a.Cache.ListUserNotifications(ctx, 20, userNotificationsPageKey) if err != nil { - slog.WarnContext(ctx, "failed to list user notifications for periodic cleanup", "error", err) + a.logger.WarnContext(ctx, "failed to list user notifications for periodic cleanup", "error", err) } userNotifications = append(userNotifications, response...) if nextKey == "" { @@ -6023,7 +6055,7 @@ func (a *Server) CleanupNotifications(ctx context.Context) { } response, nextKey, err := a.Cache.ListGlobalNotifications(ctx, 20, globalNotificationsPageKey) if err != nil { - slog.WarnContext(ctx, "failed to list global notifications for periodic cleanup", "error", err) + a.logger.WarnContext(ctx, "failed to list global notifications for periodic cleanup", "error", err) } globalNotifications = append(globalNotifications, response...) if nextKey == "" { @@ -6050,7 +6082,7 @@ func (a *Server) CleanupNotifications(ctx context.Context) { return } if err := a.DeleteGlobalNotification(ctx, notificationID); err != nil && !trace.IsNotFound(err) { - slog.WarnContext(ctx, "encountered error attempting to cleanup global notification", "error", err, "notification_id", notificationID) + a.logger.WarnContext(ctx, "encountered error attempting to cleanup global notification", "error", err, "notification_id", notificationID) } } else { nonExpiredGlobalNotificationsByID[notificationID] = gn @@ -6071,7 +6103,7 @@ func (a *Server) CleanupNotifications(ctx context.Context) { return } if err := a.DeleteUserNotification(ctx, user, notificationID); err != nil && !trace.IsNotFound(err) { - slog.WarnContext(ctx, "encountered error attempting to cleanup user notification", "error", err, "notification_id", notificationID, "target_user", user) + a.logger.WarnContext(ctx, "encountered error attempting to cleanup user notification", "error", err, "notification_id", notificationID, "target_user", user) } } else { nonExpiredUserNotificationsByID[notificationID] = un @@ -6090,7 +6122,7 @@ func (a *Server) CleanupNotifications(ctx context.Context) { } response, nextKey, err := a.ListNotificationStatesForAllUsers(ctx, 20, userNotificationStatesPageKey) if err != nil { - slog.WarnContext(ctx, "encountered error attempting to list notification states for cleanup", "error", err) + a.logger.WarnContext(ctx, "encountered error attempting to list notification states for cleanup", "error", err) } userNotificationStates = append(userNotificationStates, response...) if nextKey == "" { @@ -6112,7 +6144,7 @@ func (a *Server) CleanupNotifications(ctx context.Context) { return } if err := a.DeleteUserNotificationState(ctx, username, id); err != nil { - slog.WarnContext(ctx, "encountered error attempting to cleanup notification state", "error", err, "user", username, "id", id) + a.logger.WarnContext(ctx, "encountered error attempting to cleanup notification state", "error", err, "user", username, "id", id) } } } @@ -6219,7 +6251,7 @@ func (a *Server) CreateApp(ctx context.Context, app types.Application) error { AppLabels: app.GetStaticLabels(), }, }); err != nil { - log.WithError(err).Warn("Failed to emit app create event.") + a.logger.WarnContext(ctx, "Failed to emit app create event", "error", err) } return nil } @@ -6245,7 +6277,7 @@ func (a *Server) UpdateApp(ctx context.Context, app types.Application) error { AppLabels: app.GetStaticLabels(), }, }); err != nil { - log.WithError(err).Warn("Failed to emit app update event.") + a.logger.WarnContext(ctx, "Failed to emit app update event", "error", err) } return nil } @@ -6265,7 +6297,7 @@ func (a *Server) DeleteApp(ctx context.Context, name string) error { Name: name, }, }); err != nil { - log.WithError(err).Warn("Failed to emit app delete event.") + a.logger.WarnContext(ctx, "Failed to emit app delete event", "error", err) } return nil } @@ -6309,7 +6341,7 @@ func (a *Server) CreateDatabase(ctx context.Context, database types.Database) er DatabaseGCPInstanceID: database.GetGCP().InstanceID, }, }); err != nil { - log.WithError(err).Warn("Failed to emit database create event.") + a.logger.WarnContext(ctx, "Failed to emit database create event", "error", err) } return nil } @@ -6339,7 +6371,7 @@ func (a *Server) UpdateDatabase(ctx context.Context, database types.Database) er DatabaseGCPInstanceID: database.GetGCP().InstanceID, }, }); err != nil { - log.WithError(err).Warn("Failed to emit database update event.") + a.logger.WarnContext(ctx, "Failed to emit database update event", "error", err) } return nil } @@ -6359,7 +6391,7 @@ func (a *Server) DeleteDatabase(ctx context.Context, name string) error { Name: name, }, }); err != nil { - log.WithError(err).Warn("Failed to emit database delete event.") + a.logger.WarnContext(ctx, "Failed to emit database delete event", "error", err) } return nil } @@ -6427,7 +6459,7 @@ func (a *Server) CreateKubernetesCluster(ctx context.Context, kubeCluster types. KubeLabels: kubeCluster.GetStaticLabels(), }, }); err != nil { - log.WithError(err).Warn("Failed to emit kube cluster create event.") + a.logger.WarnContext(ctx, "Failed to emit kube cluster create event", "error", err) } return nil } @@ -6454,7 +6486,7 @@ func (a *Server) UpdateKubernetesCluster(ctx context.Context, kubeCluster types. KubeLabels: kubeCluster.GetStaticLabels(), }, }); err != nil { - log.WithError(err).Warn("Failed to emit kube cluster update event.") + a.logger.WarnContext(ctx, "Failed to emit kube cluster update event", "error", err) } return nil } @@ -6474,7 +6506,7 @@ func (a *Server) DeleteKubernetesCluster(ctx context.Context, name string) error Name: name, }, }); err != nil { - log.WithError(err).Warn("Failed to emit kube cluster delete event.") + a.logger.WarnContext(ctx, "Failed to emit kube cluster delete event", "error", err) } return nil } @@ -6573,12 +6605,12 @@ func (a *Server) exportUpgradeWindowsCached(ctx context.Context) (proto.ExportUp rsp.KubeControllerSchedule, err = uw.EncodeKubeControllerSchedule(sched) if err != nil { - log.Warnf("Failed to encode kube controller maintenance schedule: %v", err) + a.logger.WarnContext(ctx, "Failed to encode kube controller maintenance schedule", "error", err) } rsp.SystemdUnitSchedule, err = uw.EncodeSystemdUnitSchedule(sched) if err != nil { - log.Warnf("Failed to encode systemd unit maintenance schedule: %v", err) + a.logger.WarnContext(ctx, "Failed to encode systemd unit maintenance schedule", "error", err) } return rsp, nil @@ -6837,7 +6869,7 @@ func (a *Server) isMFARequired(ctx context.Context, checker services.AccessCheck // most likely access denied. if !errors.Is(noMFAAccessErr, services.ErrSessionMFARequired) { if !trace.IsAccessDenied(noMFAAccessErr) { - log.WithError(noMFAAccessErr).Warn("Could not determine MFA access") + a.logger.WarnContext(ctx, "Could not determine MFA access", "error", noMFAAccessErr) } // Mask the access denied errors by returning false to prevent resource @@ -6921,7 +6953,7 @@ func (a *Server) mfaAuthChallenge(ctx context.Context, user string, ssoClientRed ChallengeScope: challengeExtensions.Scope.String(), ChallengeAllowReuse: challengeExtensions.AllowReuse == mfav1.ChallengeAllowReuse_CHALLENGE_ALLOW_REUSE_YES, }); err != nil { - log.WithError(err).Warn("Failed to emit CreateMFAAuthChallenge event.") + a.logger.WarnContext(ctx, "Failed to emit CreateMFAAuthChallenge event", "error", err) } return &proto.MFAAuthenticateChallenge{ @@ -6983,7 +7015,7 @@ func (a *Server) mfaAuthChallenge(ctx context.Context, user string, ssoClientRed ChallengeScope: challengeExtensions.Scope.String(), ChallengeAllowReuse: challengeExtensions.AllowReuse == mfav1.ChallengeAllowReuse_CHALLENGE_ALLOW_REUSE_YES, }); err != nil { - log.WithError(err).Warn("Failed to emit CreateMFAAuthChallenge event.") + a.logger.WarnContext(ctx, "Failed to emit CreateMFAAuthChallenge event", "error", err) } return challenge, nil @@ -7008,7 +7040,7 @@ func groupByDeviceType(devs []*types.MFADevice) devicesByType { case *types.MFADevice_Sso: res.SSO = dev default: - log.Warningf("Skipping MFA device of unknown type %T.", dev.Device) + logger.WarnContext(context.Background(), "Skipping MFA device with unknown type", "device_type", logutils.TypeAttr(dev.Device)) } } return res @@ -7080,7 +7112,7 @@ func (a *Server) ValidateMFAAuthResponse( // Read ClusterName for audit. var clusterName string if cn, err := a.GetClusterName(); err != nil { - log.WithError(err).Warn("Failed to read cluster name") + a.logger.WarnContext(ctx, "Failed to read cluster name", "error", err) // err swallowed on purpose. } else { clusterName = cn.GetClusterName() @@ -7114,7 +7146,7 @@ func (a *Server) ValidateMFAAuthResponse( auditEvent.ChallengeAllowReuse = authData.AllowReuse == mfav1.ChallengeAllowReuse_CHALLENGE_ALLOW_REUSE_YES } if err := a.emitter.EmitAuditEvent(ctx, auditEvent); err != nil { - log.WithError(err).Warn("Failed to emit ValidateMFAAuthResponse event") + a.logger.WarnContext(ctx, "Failed to emit ValidateMFAAuthResponse event", "error", err) // err swallowed on purpose. } @@ -7196,7 +7228,7 @@ func (a *Server) validateMFAAuthResponseInternal( }, nil case *proto.MFAAuthenticateResponse_TOTP: - dev, err := a.checkOTP(user, res.TOTP.Code) + dev, err := a.checkOTP(ctx, user, res.TOTP.Code) if err != nil { return nil, trace.Wrap(err) } @@ -7365,7 +7397,7 @@ func (a *Server) ensureLocalAdditionalKeys(ctx context.Context, ca types.CertAut if err != nil { return trace.Wrap(err) } - log.Infof("Successfully added locally usable additional trusted keys to %s CA.", ca.GetType()) + a.logger.InfoContext(ctx, "Successfully added locally usable additional trusted keys to CA", "ca_type", ca.GetType()) return nil } @@ -7458,7 +7490,11 @@ func (a *Server) getProxyPublicAddr() string { continue } if _, err := utils.ParseAddr(addr); err != nil { - log.Warningf("Invalid public address on the proxy %q: %q: %v.", p.GetName(), addr, err) + a.logger.WarnContext(a.closeCtx, "Invalid public address found in proxy", + "proxy", p.GetName(), + "public_addr", addr, + "error", err, + ) continue } return addr diff --git a/lib/auth/auth_with_roles.go b/lib/auth/auth_with_roles.go index 40e94526e472a..85cc6fe6237b1 100644 --- a/lib/auth/auth_with_roles.go +++ b/lib/auth/auth_with_roles.go @@ -30,7 +30,6 @@ import ( "github.com/google/uuid" "github.com/gravitational/trace" - "github.com/sirupsen/logrus" collectortracev1 "go.opentelemetry.io/proto/otlp/collector/trace/v1" otlpcommonv1 "go.opentelemetry.io/proto/otlp/common/v1" @@ -65,6 +64,7 @@ import ( "github.com/gravitational/teleport/lib/services/local" "github.com/gravitational/teleport/lib/session" "github.com/gravitational/teleport/lib/tlsca" + logutils "github.com/gravitational/teleport/lib/utils/log" ) // ServerWithRoles is a wrapper around auth service @@ -163,14 +163,17 @@ func (a *ServerWithRoles) identityCenterAction(namespace string, resource string // actionForListWithCondition extracts a restrictive filter condition to be // added to a list query after a simple resource check fails. -func (a *ServerWithRoles) actionForListWithCondition(resource, identifier string) (*types.WhereExpr, error) { +func (a *ServerWithRoles) actionForListWithCondition(ctx context.Context, resource, identifier string) (*types.WhereExpr, error) { origErr := a.action(resource, types.VerbList) if origErr == nil || !trace.IsAccessDenied(origErr) { return nil, trace.Wrap(origErr) } cond, err := a.context.Checker.ExtractConditionForIdentifier(&services.Context{User: a.context.User}, apidefaults.Namespace, resource, types.VerbList, identifier) if trace.IsAccessDenied(err) { - log.WithError(err).Infof("Access to %v %v in namespace %v denied to %v.", types.VerbList, resource, apidefaults.Namespace, a.context.Checker) + a.authServer.logger.InfoContext(ctx, "Access to list resource denied", + "error", err, + "resource", resource, + ) // Return the original AccessDenied to avoid leaking information. return nil, trace.Wrap(origErr) } @@ -179,14 +182,14 @@ func (a *ServerWithRoles) actionForListWithCondition(resource, identifier string // actionWithExtendedContext performs an additional RBAC check with extended // rule context after a simple resource check fails. -func (a *ServerWithRoles) actionWithExtendedContext(kind, verb string, extendContext func(*services.Context) error) error { +func (a *ServerWithRoles) actionWithExtendedContext(ctx context.Context, kind, verb string, extendContext func(*services.Context) error) error { ruleCtx := &services.Context{User: a.context.User} origErr := a.context.Checker.CheckAccessToRule(ruleCtx, apidefaults.Namespace, kind, verb) if origErr == nil || !trace.IsAccessDenied(origErr) { return trace.Wrap(origErr) } if err := extendContext(ruleCtx); err != nil { - log.WithError(err).Warning("Failed to extend context for second RBAC check.") + a.authServer.logger.WarnContext(ctx, "Failed to extend context for second RBAC check", "error", err) // Return the original AccessDenied to avoid leaking information. return trace.Wrap(origErr) } @@ -203,7 +206,7 @@ func (a *ServerWithRoles) actionForKindSession(ctx context.Context, sid session. return trace.Wrap(err) } - return trace.Wrap(a.actionWithExtendedContext(types.KindSession, types.VerbRead, extendContext)) + return trace.Wrap(a.actionWithExtendedContext(ctx, types.KindSession, types.VerbRead, extendContext)) } // localServerAction returns an access denied error if the role is not one of the builtin server roles. @@ -596,17 +599,17 @@ func (a *ServerWithRoles) RegisterUsingToken(ctx context.Context, req *types.Reg // service). They will be derived from the client certificate otherwise. if !isProxy { if req.BotInstanceID != "" { - log.WithFields(logrus.Fields{ - "bot_instance_id": req.BotInstanceID, - }).Warnf("Untrusted client attempted to provide a bot instance ID, this will be ignored") + a.authServer.logger.WarnContext(ctx, "Untrusted client attempted to provide a bot instance ID, this will be ignored", + "bot_instance_id", req.BotInstanceID, + ) req.BotInstanceID = "" } if req.BotGeneration > 0 { - log.WithFields(logrus.Fields{ - "bot_generation": req.BotGeneration, - }).Warnf("Untrusted client attempted to provide a bot generation, this will be ignored") + a.authServer.logger.WarnContext(ctx, "Untrusted client attempted to provide a bot generation, this will be ignored", + "bot_generation", req.BotGeneration, + ) req.BotGeneration = 0 } @@ -684,7 +687,11 @@ func (a *ServerWithRoles) checkAdditionalSystemRoles(ctx context.Context, req *p if err != nil { // include this error in the logs, since it might be indicative of a bug if it occurs outside of the context // of a general backend outage. - log.Warnf("Failed to load system role assertion set %q for instance %q: %v", req.SystemRoleAssertionID, req.HostID, err) + a.authServer.logger.WarnContext(ctx, "Failed to load system role assertion set for instance", + "system_role_assertion", req.SystemRoleAssertionID, + "instance", req.HostID, + "error", err, + ) return trace.AccessDenied("failed to load system role assertion set with ID %q", req.SystemRoleAssertionID) } } @@ -773,7 +780,10 @@ func (a *ServerWithRoles) RegisterInventoryControlStream(ics client.UpstreamInve var filteredServices []types.SystemRole for _, service := range hello.Services { if !a.hasBuiltinRole(service) { - log.Warnf("Omitting service %q for control stream of instance %q (unknown or unauthorized).", service, role.GetServerID()) + a.authServer.logger.WarnContext(a.CloseContext(), "Omitting unknown or unauthorized service for instance control stream", + "omitted_service", service, + "instance", role.GetServerID(), + ) continue } filteredServices = append(filteredServices, service) @@ -845,7 +855,7 @@ func (a *ServerWithRoles) GetClusterAlerts(ctx context.Context, query types.GetC if err != nil { // we don't fail here since users are allowed to see acknowledged alerts, acks // are intended only as a tool for reducing noise. - log.Warnf("Failed to load alert acks: %v", err) + a.authServer.logger.WarnContext(ctx, "Failed to load alert acks", "error", err) } } @@ -1245,12 +1255,11 @@ func (c *resourceAccess) checkAccess(resource types.ResourceWithLabels, filter s // Filter first and only check RBAC if there is a match to improve perf. match, err := services.MatchResourceByFilters(resource, filter, nil) if err != nil { - log.WithFields(logrus.Fields{ - "resource_name": resource.GetName(), - "resource_kind": resourceKind, - "error": err, - }). - Warn("Unable to determine access to resource, matching with filter failed") + logger.WarnContext(context.Background(), "Unable to determine access to resource, matching with filter failed", + "resource_name", resource.GetName(), + "resource_kind", resourceKind, + "error", err, + ) return false, nil } @@ -1448,14 +1457,20 @@ func (a *ServerWithRoles) ListUnifiedResources(ctx context.Context, req *proto.L if n := r.GetNode(); n != nil { logins, err := checker.GetAllowedLoginsForResource(n) if err != nil { - log.WithError(err).WithField("resource", n.GetName()).Warn("Unable to determine logins for node") + a.authServer.logger.WarnContext(ctx, "Unable to determine logins for node", + "error", err, + "resource", n.GetName(), + ) continue } r.Logins = logins } else if d := r.GetWindowsDesktop(); d != nil { logins, err := checker.GetAllowedLoginsForResource(d) if err != nil { - log.WithError(err).WithField("resource", d.GetName()).Warn("Unable to determine logins for desktop") + a.authServer.logger.WarnContext(ctx, "Unable to determine logins for desktop", + "error", err, + "resource", d.GetName(), + ) continue } r.Logins = logins @@ -1466,13 +1481,19 @@ func (a *ServerWithRoles) ListUnifiedResources(ctx context.Context, req *proto.L // no access and treat the whole app as requiring an access request if _any_ of the contained // permission sets require one. if err := a.filterICPermissionSets(r, d.GetApp(), resourceAccess); err != nil { - log.WithError(err).WithField("resource", d.GetApp().GetName()).Warn("Unable to filter ") + a.authServer.logger.WarnContext(ctx, "Unable to filter", + "error", err, + "resource", d.GetApp().GetName(), + ) continue } logins, err := checker.GetAllowedLoginsForResource(d.GetApp()) if err != nil { - log.WithError(err).WithField("resource", d.GetApp().GetName()).Warn("Unable to determine logins for app") + a.authServer.logger.WarnContext(ctx, "Unable to determine logins for app", + "error", err, + "resource", d.GetApp().GetName(), + ) continue } r.Logins = logins @@ -1565,13 +1586,14 @@ func (a *ServerWithRoles) GetNodes(ctx context.Context, namespace string) ([]typ } elapsedFilter := time.Since(startFilter) - log.WithFields(logrus.Fields{ - "user": a.context.User.GetName(), - "elapsed_fetch": elapsedFetch, - "elapsed_filter": elapsedFilter, - }).Debugf( - "GetServers(%v->%v) in %v.", - len(nodes), len(filteredNodes), elapsedFetch+elapsedFilter) + a.authServer.logger.DebugContext(ctx, "Retrieved servers", + "node_count", len(nodes), + "filtered_node_count", len(filteredNodes), + "user", a.context.User.GetName(), + "elapsed_fetch", elapsedFetch, + "elapsed_filter", elapsedFilter, + "elapsed_total", elapsedFetch+elapsedFilter, + ) return filteredNodes, nil } @@ -1649,7 +1671,9 @@ func (a *ServerWithRoles) GetSSHTargets(ctx context.Context, req *proto.GetSSHTa for _, rsc := range lrsp.Resources { srv := rsc.GetNode() if srv == nil { - log.Warnf("Unexpected resource type %T, expected *types.ServerV2 (skipping)", rsc) + a.authServer.logger.WarnContext(ctx, "Skipping unexpected resource type, expected *types.ServerV2", + "resource_type", logutils.TypeAttr(rsc), + ) continue } @@ -1716,7 +1740,9 @@ func (a *ServerWithRoles) ResolveSSHTarget(ctx context.Context, req *proto.Resol for _, rsc := range lrsp.Resources { srv := rsc.GetNode() if srv == nil { - log.Warnf("Unexpected resource type %T, expected *types.ServerV2 (skipping)", rsc) + a.authServer.logger.WarnContext(ctx, "Skipping unexpected resource type, expected *types.ServerV2", + "resource_type", logutils.TypeAttr(rsc), + ) continue } @@ -1897,7 +1923,10 @@ func (a *ServerWithRoles) ListResources(ctx context.Context, req proto.ListResou logins, err := resourceChecker.GetAllowedLoginsForResource(checkableResource) if err != nil { - log.WithError(err).WithField("resource", resource.GetName()).Warn("Unable to determine logins for resource") + a.authServer.logger.WarnContext(ctx, "Unable to determine logins for resource", + "error", err, + "resource", resource.GetName(), + ) } resource = &types.EnrichedResource{ @@ -2179,7 +2208,10 @@ func (a *ServerWithRoles) listResourcesWithSort(ctx context.Context, req proto.L logins, err := resourceChecker.GetAllowedLoginsForResource(checkableResource) if err != nil { - log.WithError(err).WithField("resource", r.GetName()).Warn("Unable to determine logins for resource") + a.authServer.logger.WarnContext(ctx, "Unable to determine logins for resource", + "error", err, + "resource", r.GetName(), + ) } return &types.EnrichedResource{ResourceWithLabels: r, Logins: logins}, nil @@ -2379,7 +2411,7 @@ func emitTokenEvent(ctx context.Context, e apievents.Emitter, token types.Provis Roles: token.GetRoles(), JoinMethod: token.GetJoinMethod(), }); err != nil { - log.WithError(err).Warn("Failed to emit join token create event.") + logger.WarnContext(ctx, "Failed to emit join token create event", "error", err) } } @@ -2692,7 +2724,11 @@ func (a *ServerWithRoles) ListAccessRequests(ctx context.Context, req *proto.Lis canReview, err := checker.CanReviewRequest(accessRequest) if err != nil { - log.Warnf("Failed to evaluate review permissions for user %q against request %q: %v", a.context.User.GetName(), accessRequest.GetName(), err) + a.authServer.logger.WarnContext(ctx, "Failed to evaluate review permissions for user against access request", + "user", a.context.User.GetName(), + "access_request", accessRequest.GetName(), + "error", err, + ) return false } @@ -2720,7 +2756,10 @@ func (a *ServerWithRoles) CreateAccessRequestV2(ctx context.Context, req types.A return nil, trace.AccessDenied("cannot create access requests in non-pending state while using an access request") } - log.Warnf("Use of resource-level access request 'create' permission by user %q to create non-pending access request for user %q. Creation of non-pending requests will be deprecated in future version of teleport. Consider migrating to a workflow with a separate approval step.", a.context.User.GetName(), req.GetUser()) + a.authServer.logger.WarnContext(ctx, "Use of resource-level access request 'create' permission by user to create non-pending access request for user. Creation of non-pending requests will be deprecated in future version of teleport. Consider migrating to a workflow with a separate approval step.", + "user", a.context.User.GetName(), + "request_user", req.GetUser(), + ) } if !authz.IsCurrentUser(a.context, req.GetUser()) { @@ -2923,22 +2962,25 @@ func (a *ServerWithRoles) GetCurrentUserRoles(ctx context.Context) ([]types.Role func (a *ServerWithRoles) desiredAccessInfo(ctx context.Context, req *proto.UserCertsRequest, user types.User) (*services.AccessInfo, error) { if req.Username != a.context.User.GetName() { if isRoleImpersonation(*req) { - err := trace.AccessDenied("User %v tried to issue a cert for %v and added role requests. This is not supported.", a.context.User.GetName(), req.Username) - log.WithError(err).Warn() - return nil, err + a.authServer.logger.WarnContext(ctx, "User tried to issue a cert for another user wjile adding role requests", + "user", a.context.User.GetName(), + "requested_user", req.Username, + ) + return nil, trace.AccessDenied("User %v tried to issue a cert for %v and added role requests. This is not supported.", a.context.User.GetName(), req.Username) } if len(req.AccessRequests) > 0 { - err := trace.AccessDenied("User %v tried to issue a cert for %v and added access requests. This is not supported.", a.context.User.GetName(), req.Username) - log.WithError(err).Warn() - return nil, err + a.authServer.logger.WarnContext(ctx, "User tried to issue a cert for another user wihile adding access requests", + "user", a.context.User.GetName(), + "requested_user", req.Username, + ) + return nil, trace.AccessDenied("User %v tried to issue a cert for %v and added access requests. This is not supported.", a.context.User.GetName(), req.Username) } return a.desiredAccessInfoForImpersonation(user) } if isRoleImpersonation(*req) { if len(req.AccessRequests) > 0 { - err := trace.AccessDenied("User %v tried to issue a cert with both role and access requests. This is not supported.", a.context.User.GetName()) - log.WithError(err).Warn() - return nil, err + a.authServer.logger.WarnContext(ctx, "User tried to issue a cert with both role and access requests", "user", a.context.User.GetName()) + return nil, trace.AccessDenied("User %v tried to issue a cert with both role and access requests. This is not supported.", a.context.User.GetName()) } return a.desiredAccessInfoForRoleRequest(req, user.GetTraits()) } @@ -3153,13 +3195,19 @@ func (a *ServerWithRoles) generateUserCerts(ctx context.Context, req proto.UserC // permissions to read user data. user, err := a.authServer.GetUser(ctx, req.Username, false) if err != nil { - log.WithError(err).Debugf("Could not impersonate user %v. The user could not be fetched from local store.", req.Username) + a.authServer.logger.DebugContext(ctx, "Could not impersonate user, the user could not be fetched from local store", + "error", err, + "user", req.Username, + ) return nil, trace.AccessDenied("access denied") } // Do not allow SSO users to be impersonated. if req.Username != a.context.User.GetName() && user.GetUserType() == types.UserTypeSSO { - log.Warningf("User %v tried to issue a cert for externally managed user %v, this is not supported.", a.context.User.GetName(), req.Username) + a.authServer.logger.WarnContext(ctx, "User tried to issue a cert for externally managed user", + "user", a.context.User.GetName(), + "external_user", req.Username, + ) return nil, trace.AccessDenied("access denied") } @@ -3169,7 +3217,9 @@ func (a *ServerWithRoles) generateUserCerts(ctx context.Context, req proto.UserC identity := a.context.Identity.GetIdentity() sessionExpires := identity.Expires if sessionExpires.IsZero() { - log.Warningf("Encountered identity with no expiry: %v and denied request. Must be internal logic error.", a.context.Identity) + a.authServer.logger.WarnContext(ctx, "Denied cert issuance for identity with no expiry", + "identity", identity.Username, + ) return nil, trace.AccessDenied("access denied") } if req.Expires.Before(a.authServer.GetClock().Now()) { @@ -3257,7 +3307,10 @@ func (a *ServerWithRoles) generateUserCerts(ctx context.Context, req proto.UserC // certificates with alternate RoleRequests. err = a.context.Checker.CheckImpersonateRoles(a.context.User, parsedRoles) if err != nil { - log.Warning(err) + a.authServer.logger.WarnContext(ctx, "user request for role impersonation denied", + "user", a.context.User.GetName(), + "error", err, + ) err := trace.AccessDenied("user %q has requested role impersonation for %q", a.context.User.GetName(), accessInfo.Roles) if err := a.authServer.emitter.EmitAuditEvent(a.CloseContext(), &apievents.UserLogin{ Metadata: apievents.Metadata{ @@ -3271,7 +3324,7 @@ func (a *ServerWithRoles) generateUserCerts(ctx context.Context, req proto.UserC UserMessage: err.Error(), }, }); err != nil { - log.WithError(err).Warn("Failed to emit local login failure event.") + a.authServer.logger.WarnContext(ctx, "Failed to emit local login failure event", "error", err) } return nil, trace.Wrap(err) } @@ -3284,7 +3337,10 @@ func (a *ServerWithRoles) generateUserCerts(ctx context.Context, req proto.UserC ttl = checker.AdjustSessionTTL(ttl) req.Expires = a.authServer.GetClock().Now().Add(ttl) if err != nil { - log.Warning(err) + a.authServer.logger.WarnContext(ctx, "user request for user impersonation denied", + "user", a.context.User.GetName(), + "error", err, + ) err := trace.AccessDenied("user %q has requested to generate certs for %q.", a.context.User.GetName(), accessInfo.Roles) if err := a.authServer.emitter.EmitAuditEvent(a.CloseContext(), &apievents.UserLogin{ Metadata: apievents.Metadata{ @@ -3298,7 +3354,7 @@ func (a *ServerWithRoles) generateUserCerts(ctx context.Context, req proto.UserC UserMessage: err.Error(), }, }); err != nil { - log.WithError(err).Warn("Failed to emit local login failure event.") + a.authServer.logger.WarnContext(ctx, "Failed to emit local login failure event", "error", err) } return nil, trace.Wrap(err) } @@ -3534,7 +3590,7 @@ func (a *ServerWithRoles) ChangeUserAuthentication(ctx context.Context, req *pro isPasswordless := req.NewMFARegisterResponse != nil && len(req.NewPassword) == 0 if isPasswordless && modules.GetModules().Features().Cloud { if err := a.trySettingConnectorNameToPasswordless(ctx); err != nil { - log.WithError(err).Error("Failed to set passwordless as connector name.") + a.authServer.logger.ErrorContext(ctx, "Failed to set passwordless as connector name", "error", err) } } @@ -4163,9 +4219,13 @@ func (a *ServerWithRoles) EmitAuditEvent(ctx context.Context, event apievents.Au if err != nil { // TODO: this should be a proper audit event // notifying about access violation - log.Warningf("Rejecting audit event %v(%q) from %q: %v. The client is attempting to "+ - "submit events for an identity other than the one on its x509 certificate.", - event.GetType(), event.GetID(), role.GetServerID(), err) + const msg = "Rejecting audit event, the client is attempting to " + + "submit events for an identity other than the one on its x509 certificate." + a.authServer.logger.WarnContext(ctx, msg, + "event_type", event.GetType(), + "event_id", event.GetID(), + "server_id", role.GetServerID(), + "error", err) // this message is sparse on purpose to avoid conveying extra data to an attacker return trace.AccessDenied("failed to validate event metadata") } @@ -4247,9 +4307,14 @@ func (s *streamWithRoles) RecordEvent(ctx context.Context, pe apievents.Prepared if err != nil { // TODO: this should be a proper audit event // notifying about access violation - log.Warningf("Rejecting audit event %v from %v: %v. A node is attempting to "+ - "submit events for an identity other than the one on its x509 certificate.", - event.GetID(), s.serverID, err) + const msg = "Rejecting audit event, a node is attempting to " + + "submit events for an identity other than the one on its x509 certificate." + s.a.authServer.logger.WarnContext(ctx, msg, + "event_id", event.GetID(), + "event_type", event.GetType(), + "server_id", s.serverID, + "error", err, + ) // this message is sparse on purpose to avoid conveying extra data to an attacker return trace.AccessDenied("failed to validate event metadata") } @@ -4735,7 +4800,7 @@ func (a *ServerWithRoles) SetAuthPreference(ctx context.Context, newAuthPref typ }, AdminActionsMFA: clusterconfigv1.GetAdminActionsMFAStatus(storedAuthPref, newAuthPref), }); auditErr != nil { - log.WithError(auditErr).Warn("Failed to emit auth preference update event event.") + a.authServer.logger.WarnContext(ctx, "Failed to emit auth preference update event event", "error", auditErr) } return trace.Wrap(err) @@ -4785,7 +4850,7 @@ func (a *ServerWithRoles) ResetAuthPreference(ctx context.Context) error { }, AdminActionsMFA: clusterconfigv1.GetAdminActionsMFAStatus(storedAuthPref, defaultAuthPref), }); auditErr != nil { - log.WithError(auditErr).Warn("Failed to emit auth preference update event event.") + a.authServer.logger.WarnContext(ctx, "Failed to emit auth preference update event event", "error", auditErr) } return trace.Wrap(err) @@ -4869,7 +4934,7 @@ func (a *ServerWithRoles) SetClusterNetworkingConfig(ctx context.Context, newNet UserMessage: msg, }, }); auditErr != nil { - log.WithError(auditErr).Warn("Failed to emit cluster networking config update event event.") + a.authServer.logger.WarnContext(ctx, "Failed to emit cluster networking config update event event", "error", auditErr) } return trace.Wrap(err) } @@ -4921,7 +4986,7 @@ func (a *ServerWithRoles) ResetClusterNetworkingConfig(ctx context.Context) erro UserMessage: msg, }, }); auditErr != nil { - log.WithError(auditErr).Warn("Failed to emit cluster networking config update event event.") + a.authServer.logger.WarnContext(ctx, "Failed to emit cluster networking config update event event", "error", auditErr) } return trace.Wrap(err) @@ -4974,7 +5039,7 @@ func (a *ServerWithRoles) SetSessionRecordingConfig(ctx context.Context, newRecC UserMessage: msg, }, }); auditErr != nil { - log.WithError(auditErr).Warn("Failed to emit session recording config update event event.") + a.authServer.logger.WarnContext(ctx, "Failed to emit session recording config update event event", "error", auditErr) } return trace.Wrap(err) @@ -5019,7 +5084,7 @@ func (a *ServerWithRoles) ResetSessionRecordingConfig(ctx context.Context) error UserMessage: msg, }, }); auditErr != nil { - log.WithError(auditErr).Warn("Failed to emit session recording config update event event.") + a.authServer.logger.WarnContext(ctx, "Failed to emit session recording config update event event", "error", auditErr) } return trace.Wrap(err) @@ -5231,12 +5296,10 @@ func (a *ServerWithRoles) ProcessKubeCSR(req authclient.KubeCSR) (*authclient.Ku if proxyClusterName != "" && proxyClusterName != clusterName.GetClusterName() && proxyClusterName != identityClusterName { - log.WithFields( - logrus.Fields{ - "proxy_cluster_name": proxyClusterName, - "identity_cluster_name": identityClusterName, - }, - ).Warn("KubeCSR request denied because the proxy and identity clusters didn't match") + a.authServer.logger.WarnContext(a.CloseContext(), "KubeCSR request denied because the proxy and identity clusters didn't match", + "proxy_cluster_name", proxyClusterName, + "identity_cluster_name", identityClusterName, + ) return nil, trace.AccessDenied("can not sign certs for users via a different cluster proxy") } return a.authServer.ProcessKubeCSR(req) @@ -5380,8 +5443,12 @@ func (a *ServerWithRoles) checkAccessToGenerateDatabaseCert(resourceKind string) // user that is allowed to impersonate database service. if !a.hasBuiltinRole(types.RoleDatabase, types.RoleAdmin) { if err := a.canImpersonateBuiltinRole(types.RoleDatabase); err != nil { - log.WithError(err).Warnf("User %v tried to generate database certificate but does not have '%s' permission for '%s' kind, nor is allowed to impersonate %q system role", - a.context.User.GetName(), verb, resourceKind, types.RoleDatabase) + a.authServer.logger.WarnContext(a.CloseContext(), "User tried to generate database certificate but does not have permissions, nor is allowed to impersonate database system role", + "user", a.context.User.GetName(), + "verb", verb, + "resource_kind", resourceKind, + "error", err, + ) return trace.AccessDenied("access denied. User must have '%s' permission for '%s' kind to generate the certificate ", verb, resourceKind) } @@ -5396,8 +5463,10 @@ func (a *ServerWithRoles) GenerateSnowflakeJWT(ctx context.Context, req *proto.S // user that is allowed to impersonate database service. if !a.hasBuiltinRole(types.RoleDatabase, types.RoleAdmin) { if err := a.canImpersonateBuiltinRole(types.RoleDatabase); err != nil { - log.WithError(err).Warnf("User %v tried to generate database certificate but is not allowed to impersonate %q system role.", - a.context.User.GetName(), types.RoleDatabase) + a.authServer.logger.WarnContext(ctx, "User tried to generate database certificate but is not allowed to impersonate Database system role.", + "user", a.context.User.GetName(), + "error", err, + ) return nil, trace.AccessDenied(`access denied. The user must be able to impersonate the builtin role and user "Db" in order to generate database certificates, for more info see https://goteleport.com/docs/database-access/reference/cli/#tctl-auth-sign.`) } } @@ -6014,7 +6083,7 @@ func (a *ServerWithRoles) SearchSessionEvents(ctx context.Context, req events.Se return nil, "", trace.BadParameter("cond is an internal parameter, should not be set by client") } - cond, err := a.actionForListWithCondition(types.KindSession, services.SessionIdentifier) + cond, err := a.actionForListWithCondition(ctx, types.KindSession, services.SessionIdentifier) if err != nil { return nil, "", trace.Wrap(err) } @@ -6134,7 +6203,7 @@ func (a *ServerWithRoles) StreamSessionEvents(ctx context.Context, sessionID ses SessionType: string(sessionTypeFromStartEvent(evt)), Format: metadata.SessionRecordingFormatFromContext(ctx), }); err != nil { - log.WithError(err).Errorf("Failed to emit stream session event audit event") + a.authServer.logger.ErrorContext(ctx, "Failed to emit stream session event audit event", "error", err) } } @@ -7055,7 +7124,7 @@ func (a *ServerWithRoles) CreateSAMLIdPServiceProvider(ctx context.Context, sp t AttributeMapping: typesAttrMapToEventAttrMap(sp.GetAttributeMapping()), }, }); emitErr != nil { - log.WithError(trace.NewAggregate(emitErr, err)).Warn("Failed to emit SAML IdP service provider created event.") + a.authServer.logger.WarnContext(ctx, "Failed to emit SAML IdP service provider created event", "error", emitErr) } }() @@ -7108,7 +7177,7 @@ func (a *ServerWithRoles) UpdateSAMLIdPServiceProvider(ctx context.Context, sp t AttributeMapping: typesAttrMapToEventAttrMap(sp.GetAttributeMapping()), }, }); emitErr != nil { - log.WithError(trace.NewAggregate(emitErr, err)).Warn("Failed to emit SAML IdP service provider updated event.") + a.authServer.logger.WarnContext(ctx, "Failed to emit SAML IdP service provider updated event", "error", emitErr) } }() @@ -7174,7 +7243,7 @@ func (a *ServerWithRoles) DeleteSAMLIdPServiceProvider(ctx context.Context, name ServiceProviderEntityID: entityID, }, }); emitErr != nil { - log.WithError(trace.NewAggregate(emitErr, err)).Warn("Failed to emit SAML IdP service provider deleted event.") + a.authServer.logger.WarnContext(ctx, "Failed to emit SAML IdP service provider deleted event", "error", emitErr) } }() @@ -7222,7 +7291,7 @@ func (a *ServerWithRoles) DeleteAllSAMLIdPServiceProviders(ctx context.Context) UpdatedBy: authz.ClientUsername(ctx), }, }); emitErr != nil { - log.WithError(trace.NewAggregate(emitErr, err)).Warn("Failed to emit SAML IdP service provider deleted all event.") + a.authServer.logger.WarnContext(ctx, "Failed to emit SAML IdP service provider deleted all event", "error", emitErr) } }() @@ -7645,7 +7714,7 @@ func emitHeadlessLoginEvent(ctx context.Context, code string, emitter apievents. } if emitErr := emitter.EmitAuditEvent(ctx, &event); emitErr != nil { - log.WithError(err).Warnf("Failed to emit %q login event, code %q: %v", events.LoginMethodHeadless, code, emitErr) + logger.WarnContext(ctx, "Failed to emit headless login event", "event_code", code, "error", emitErr) } } @@ -7669,7 +7738,11 @@ func emitSSOLoginFailureEvent(ctx context.Context, emitter apievents.Emitter, me }) if emitErr != nil { - log.WithError(err).Warnf("Failed to emit %v login failure event: %v", method, emitErr) + logger.WarnContext(ctx, "Failed to emit sso login event", + "sso_method", method, + "event_code", code, + "error", emitErr, + ) } } diff --git a/lib/auth/auth_with_roles_test.go b/lib/auth/auth_with_roles_test.go index f6ad5315cd6fb..923e74f46f4e7 100644 --- a/lib/auth/auth_with_roles_test.go +++ b/lib/auth/auth_with_roles_test.go @@ -24,7 +24,6 @@ import ( "crypto/tls" "crypto/x509/pkix" "fmt" - "io" "net/url" "slices" "strconv" @@ -38,7 +37,6 @@ import ( "github.com/gravitational/trace" "github.com/jonboulle/clockwork" "github.com/pquerna/otp/totp" - "github.com/sirupsen/logrus" "github.com/stretchr/testify/assert" "github.com/stretchr/testify/require" "golang.org/x/crypto/ssh" @@ -77,7 +75,6 @@ import ( "github.com/gravitational/teleport/lib/session" "github.com/gravitational/teleport/lib/srv/discovery/common" "github.com/gravitational/teleport/lib/tlsca" - logutils "github.com/gravitational/teleport/lib/utils/log" "github.com/gravitational/teleport/lib/utils/pagination" ) @@ -1824,12 +1821,6 @@ func BenchmarkListNodes(b *testing.B) { const nodeCount = 50_000 const roleCount = 32 - logger := logrus.StandardLogger() - logger.ReplaceHooks(make(logrus.LevelHooks)) - logrus.SetFormatter(logutils.NewTestJSONFormatter()) - logger.SetLevel(logrus.DebugLevel) - logger.SetOutput(io.Discard) - ctx := context.Background() srv := newTestTLSServer(b) @@ -6124,12 +6115,6 @@ func BenchmarkListUnifiedResourcesFilter(b *testing.B) { const nodeCount = 150_000 const roleCount = 32 - logger := logrus.StandardLogger() - logger.ReplaceHooks(make(logrus.LevelHooks)) - logrus.SetFormatter(logutils.NewTestJSONFormatter()) - logger.SetLevel(logrus.PanicLevel) - logger.SetOutput(io.Discard) - ctx := context.Background() srv := newTestTLSServer(b) @@ -6257,12 +6242,6 @@ func BenchmarkListUnifiedResources(b *testing.B) { const nodeCount = 150_000 const roleCount = 32 - logger := logrus.StandardLogger() - logger.ReplaceHooks(make(logrus.LevelHooks)) - logrus.SetFormatter(logutils.NewTestJSONFormatter()) - logger.SetLevel(logrus.DebugLevel) - logger.SetOutput(io.Discard) - ctx := context.Background() srv := newTestTLSServer(b) diff --git a/lib/auth/db.go b/lib/auth/db.go index 33f2b1fb71d0c..ce7080b7ba3f6 100644 --- a/lib/auth/db.go +++ b/lib/auth/db.go @@ -216,7 +216,7 @@ func (a *Server) SignDatabaseCSR(ctx context.Context, req *proto.DatabaseCSRRequ "this Teleport cluster is not licensed for database access, please contact the cluster administrator") } - log.Debugf("Signing database CSR for cluster %v.", req.ClusterName) + a.logger.DebugContext(ctx, "Signing database CSR for cluster", "cluster", req.ClusterName) clusterName, err := a.GetClusterName() if err != nil { @@ -348,7 +348,7 @@ func (a *Server) GenerateSnowflakeJWT(ctx context.Context, req *proto.SnowflakeJ return nil, trace.Wrap(err) } - subject, issuer := getSnowflakeJWTParams(req.AccountName, req.UserName, pubKey) + subject, issuer := getSnowflakeJWTParams(ctx, req.AccountName, req.UserName, pubKey) _, signer, err := a.GetKeyStore().GetTLSCertAndSigner(ctx, ca) if err != nil { @@ -371,7 +371,7 @@ func (a *Server) GenerateSnowflakeJWT(ctx context.Context, req *proto.SnowflakeJ }, nil } -func getSnowflakeJWTParams(accountName, userName string, publicKey []byte) (string, string) { +func getSnowflakeJWTParams(ctx context.Context, accountName, userName string, publicKey []byte) (string, string) { // Use only the first part of the account name to generate JWT // Based on: // https://github.com/snowflakedb/snowflake-connector-python/blob/f2f7e6f35a162484328399c8a50a5015825a5573/src/snowflake/connector/auth_keypair.py#L83 @@ -383,7 +383,10 @@ func getSnowflakeJWTParams(accountName, userName string, publicKey []byte) (stri accnToken, _, _ := strings.Cut(accountName, accNameSeparator) accnTokenCap := strings.ToUpper(accnToken) userNameCap := strings.ToUpper(userName) - log.Debugf("Signing database JWT token for %s %s", accnTokenCap, userNameCap) + logger.DebugContext(ctx, "Signing database JWT token", + "account_name", accnTokenCap, + "user_name", userNameCap, + ) subject := fmt.Sprintf("%s.%s", accnTokenCap, userNameCap) diff --git a/lib/auth/db_test.go b/lib/auth/db_test.go index 2565f168a1905..2ce873a09eae2 100644 --- a/lib/auth/db_test.go +++ b/lib/auth/db_test.go @@ -90,7 +90,7 @@ func Test_getSnowflakeJWTParams(t *testing.T) { for _, tt := range tests { t.Run(tt.name, func(t *testing.T) { - subject, issuer := getSnowflakeJWTParams(tt.args.accountName, tt.args.userName, tt.args.publicKey) + subject, issuer := getSnowflakeJWTParams(context.Background(), tt.args.accountName, tt.args.userName, tt.args.publicKey) require.Equal(t, tt.wantSubject, subject) require.Equal(t, tt.wantIssuer, issuer) diff --git a/lib/auth/github.go b/lib/auth/github.go index 64a147f584a7a..a122352d99e5b 100644 --- a/lib/auth/github.go +++ b/lib/auth/github.go @@ -33,7 +33,6 @@ import ( "time" "github.com/gravitational/trace" - "github.com/sirupsen/logrus" "golang.org/x/oauth2" "github.com/gravitational/teleport" @@ -349,7 +348,7 @@ func orgUsesExternalSSO(ctx context.Context, endpointURL, org string, client htt if resp != nil { io.Copy(io.Discard, resp.Body) if bodyErr := resp.Body.Close(); bodyErr != nil { - logrus.WithError(bodyErr).Error("Error closing response body.") + logger.ErrorContext(ctx, "Error closing response body", "error", bodyErr) } } // Handle makeHTTPGetReq errors. diff --git a/lib/auth/init.go b/lib/auth/init.go index 3e0c0fbe1a970..ab7e2f5a025df 100644 --- a/lib/auth/init.go +++ b/lib/auth/init.go @@ -35,7 +35,6 @@ import ( "github.com/coreos/go-semver/semver" "github.com/gravitational/trace" "github.com/jonboulle/clockwork" - "github.com/sirupsen/logrus" "go.opentelemetry.io/otel/attribute" "go.opentelemetry.io/otel/exporters/otlp/otlptrace" oteltrace "go.opentelemetry.io/otel/trace" @@ -75,7 +74,6 @@ import ( ) var ( - log = logrus.WithField(teleport.ComponentKey, teleport.ComponentAuth) logger = logutils.NewPackageLogger(teleport.ComponentKey, teleport.ComponentAuth) ) diff --git a/lib/auth/join_ec2.go b/lib/auth/join_ec2.go index 0b5cf51252cef..ee4ee567b7434 100644 --- a/lib/auth/join_ec2.go +++ b/lib/auth/join_ec2.go @@ -338,8 +338,12 @@ func (a *Server) tryToDetectIdentityReuse(ctx context.Context, req *types.Regist return trace.Wrap(err) } if instanceExists { - log.Warnf("Server with ID %q and role %q is attempting to join the cluster with a Simplified Node Joining request, but"+ - " a server with this ID is already present in the cluster.", req.HostID, req.Role) + const msg = "Server is attempting to join the cluster with a Simplified Node Joining request, but" + + " a server with this ID is already present in the cluster" + a.logger.WarnContext(ctx, msg, + "host_id", req.HostID, + "role", req.Role, + ) return trace.AccessDenied("server with host ID %q and role %q already exists", req.HostID, req.Role) } return nil @@ -363,7 +367,7 @@ func (a *Server) checkEC2JoinRequest(ctx context.Context, req *types.RegisterUsi return trace.Wrap(err) } - log.Debugf("Received Simplified Node Joining request for host %q", req.HostID) + a.logger.DebugContext(ctx, "Received Simplified Node Joining request", "host_id", req.HostID) if len(req.EC2IdentityDocument) == 0 { return trace.AccessDenied("this token is only valid for the EC2 join " + diff --git a/lib/auth/join_iam.go b/lib/auth/join_iam.go index 5ca3f4af1877d..7b284733bee1c 100644 --- a/lib/auth/join_iam.go +++ b/lib/auth/join_iam.go @@ -109,7 +109,7 @@ func validateSTSIdentityRequest(req *http.Request, challenge string, cfg *iamReg // invalid sts:GetCallerIdentity request, it's either going to be caused // by a node in a unknown region or an attacker. if err != nil { - log.WithError(err).Warn("Detected an invalid sts:GetCallerIdentity used by a client attempting to use the IAM join method.") + logger.WarnContext(req.Context(), "Detected an invalid sts:GetCallerIdentity used by a client attempting to use the IAM join method", "error", err) } }() diff --git a/lib/auth/kube.go b/lib/auth/kube.go index 4d9eaf4b2c864..bcacbd0e6bf1f 100644 --- a/lib/auth/kube.go +++ b/lib/auth/kube.go @@ -52,7 +52,7 @@ func (a *Server) ProcessKubeCSR(req authclient.KubeCSR) (*authclient.KubeCSRResp // Certificate for remote cluster is a user certificate // with special provisions. - log.Debugf("Generating certificate to access remote Kubernetes clusters.") + a.logger.DebugContext(ctx, "Generating certificate to access remote Kubernetes clusters") hostCA, err := a.GetCertAuthority(ctx, types.CertAuthID{ Type: types.HostCA, diff --git a/lib/auth/methods.go b/lib/auth/methods.go index 0e7682370490f..ab485dfa96f9d 100644 --- a/lib/auth/methods.go +++ b/lib/auth/methods.go @@ -22,7 +22,6 @@ import ( "bytes" "context" "errors" - "log/slog" "net" "time" @@ -71,16 +70,19 @@ func (a *Server) authenticateUserLogin(ctx context.Context, req authclient.Authe clientMetadata: req.ClientMetadata, authErr: err, }); err != nil { - log.WithError(err).Warn("Failed to emit login event") + a.logger.WarnContext(ctx, "Failed to emit login event", "error", err) } return nil, nil, trace.Wrap(err) } switch { case username != "" && actualUsername != "" && username != actualUsername: - log.Warnf("Authenticate user mismatch (%q vs %q). Using request user (%q)", username, actualUsername, username) + a.logger.WarnContext(ctx, "Authenticate user mismatch, using request user", + "username", username, + "request_user", actualUsername, + ) case username == "" && actualUsername != "": - log.Debugf("User %q authenticated via passwordless", actualUsername) + a.logger.DebugContext(ctx, "User authenticated via passwordless", "username", actualUsername) username = actualUsername } @@ -123,7 +125,7 @@ func (a *Server) authenticateUserLogin(ctx context.Context, req authclient.Authe checker: checker, authErr: err, }); err != nil { - log.WithError(err).Warn("Failed to emit login event") + a.logger.WarnContext(ctx, "Failed to emit login event", "error", err) } return nil, nil, trace.Wrap(err) } @@ -135,7 +137,7 @@ func (a *Server) authenticateUserLogin(ctx context.Context, req authclient.Authe mfaDevice: mfaDev, checker: checker, }); err != nil { - log.WithError(err).Warn("Failed to emit login event") + a.logger.WarnContext(ctx, "Failed to emit login event", "error", err) } return userState, checker, trace.Wrap(err) @@ -303,7 +305,7 @@ func (a *Server) authenticateUserInternal( if req.HeadlessAuthenticationID != "" { mfaDev, err = a.authenticateHeadless(ctx, req) if err != nil { - slog.DebugContext(ctx, "Headless authenticate failed while waiting for approval", + a.logger.DebugContext(ctx, "Headless authenticate failed while waiting for approval", "user", user, "error", err, ) @@ -330,7 +332,7 @@ func (a *Server) authenticateUserInternal( case err != nil: return nil, "", trace.Wrap(err) case u.GetUserType() != types.UserTypeLocal: - slog.WarnContext(ctx, "Non-local user attempted local authentication", + a.logger.WarnContext(ctx, "Non-local user attempted local authentication", "user", user, "user_type", u.GetUserType(), ) @@ -381,7 +383,7 @@ func (a *Server) authenticateUserInternal( }) switch { case err != nil: - slog.DebugContext(ctx, "User failed to authenticate.", + a.logger.DebugContext(ctx, "User failed to authenticate", "user", user, "error", err, ) @@ -391,7 +393,7 @@ func (a *Server) authenticateUserInternal( return nil, "", trace.Wrap(authErr) case mfaDev == nil: - slog.DebugContext(ctx, "MFA authentication returned nil device.", + a.logger.DebugContext(ctx, "MFA authentication returned nil device", "webauthn", req.Webauthn != nil, "totp", req.OTP != nil, "headless", req.HeadlessAuthenticationID != "", @@ -420,7 +422,7 @@ func (a *Server) authenticateUserInternal( // Some form of MFA is required but none provided. Either client is // buggy (didn't send MFA response) or someone is trying to bypass // MFA. - slog.WarnContext(ctx, "MFA bypass attempt, access denied.", "user", user) + a.logger.WarnContext(ctx, "MFA bypass attempt, access denied", "user", user) return nil, "", trace.AccessDenied("missing second factor") case authPreference.IsSecondFactorEnabled(): // 2FA is optional. Make sure that a user does not have MFA devices @@ -430,7 +432,7 @@ func (a *Server) authenticateUserInternal( return nil, "", trace.Wrap(err) } if len(devs) != 0 { - slog.WarnContext(ctx, "MFA bypass attempt, access denied.", "user", user) + a.logger.WarnContext(ctx, "MFA bypass attempt, access denied", "user", user) return nil, "", trace.AccessDenied("missing second factor authentication") } default: @@ -444,7 +446,7 @@ func (a *Server) authenticateUserInternal( } // provide obscure message on purpose, while logging the real // error server side - slog.DebugContext(ctx, "User failed to authenticate.", + a.logger.DebugContext(ctx, "User failed to authenticate", "user", user, "error", err, ) @@ -467,7 +469,7 @@ func (a *Server) authenticatePasswordless(ctx context.Context, req authclient.Au case errors.Is(err, types.ErrPassswordlessLoginBySSOUser): return nil, "", trace.Wrap(err) case err != nil: - log.Debugf("Passwordless authentication failed: %v", err) + a.logger.DebugContext(ctx, "Passwordless authentication failed", "error", err) return nil, "", trace.Wrap(authenticateWebauthnError) } @@ -475,7 +477,10 @@ func (a *Server) authenticatePasswordless(ctx context.Context, req authclient.Au // acquire the user lock beforehand (or at all on failures!) // We do grab it here so successful logins go through the regular process. if err := a.WithUserLock(ctx, mfaData.User, func() error { return nil }); err != nil { - log.Debugf("WithUserLock for user %q failed during passwordless authentication: %v", mfaData.User, err) + a.logger.DebugContext(ctx, "WithUserLock failed during passwordless authentication", + "user", mfaData.User, + "error", err, + ) return nil, mfaData.User, trace.Wrap(authenticateWebauthnError) } @@ -487,7 +492,7 @@ func (a *Server) authenticateHeadless(ctx context.Context, req authclient.Authen defer func() { if err != nil { if err := a.DeleteHeadlessAuthentication(a.CloseContext(), req.Username, req.HeadlessAuthenticationID); err != nil && !trace.IsNotFound(err) { - log.Debugf("Failed to delete headless authentication: %v", err) + a.logger.DebugContext(ctx, "Failed to delete headless authentication", "error", err) } } }() @@ -773,7 +778,7 @@ func (a *Server) emitNoLocalAuthEvent(username string) { Error: noLocalAuth, }, }); err != nil { - log.WithError(err).Warn("Failed to emit no local auth event.") + a.logger.WarnContext(a.closeCtx, "Failed to emit no local auth event", "error", err) } } @@ -794,7 +799,7 @@ func getErrorByTraceField(err error) error { ok := errors.As(err, &traceErr) switch { case !ok: - log.WithError(err).Warn("Unexpected error type, wanted TraceError") + logger.WarnContext(context.Background(), "Unexpected error type, wanted TraceError", "error", err) return trace.AccessDenied("an error has occurred") case traceErr.GetFields()[ErrFieldKeyUserMaxedAttempts] != nil: return trace.AccessDenied(MaxFailedAttemptsErrMsg) diff --git a/lib/auth/oidc.go b/lib/auth/oidc.go index fd138373f2540..00557fddd545c 100644 --- a/lib/auth/oidc.go +++ b/lib/auth/oidc.go @@ -55,7 +55,7 @@ func (a *Server) UpsertOIDCConnector(ctx context.Context, connector types.OIDCCo Name: connector.GetName(), }, }); err != nil { - log.WithError(err).Warn("Failed to emit OIDC connector create event.") + a.logger.WarnContext(ctx, "Failed to emit OIDC connector create event", "error", err) } return upserted, nil @@ -77,7 +77,7 @@ func (a *Server) UpdateOIDCConnector(ctx context.Context, connector types.OIDCCo Name: connector.GetName(), }, }); err != nil { - log.WithError(err).Warn("Failed to emit OIDC connector update event.") + a.logger.WarnContext(ctx, "Failed to emit OIDC connector update event", "error", err) } return updated, nil @@ -99,7 +99,7 @@ func (a *Server) CreateOIDCConnector(ctx context.Context, connector types.OIDCCo Name: connector.GetName(), }, }); err != nil { - log.WithError(err).Warn("Failed to emit OIDC connector create event.") + a.logger.WarnContext(ctx, "Failed to emit OIDC connector create event", "error", err) } return created, nil @@ -120,7 +120,7 @@ func (a *Server) DeleteOIDCConnector(ctx context.Context, connectorName string) Name: connectorName, }, }); err != nil { - log.WithError(err).Warn("Failed to emit OIDC connector delete event.") + a.logger.WarnContext(ctx, "Failed to emit OIDC connector delete event", "error", err) } return nil } diff --git a/lib/auth/password.go b/lib/auth/password.go index f2045ddd2ef0c..02523ce941d28 100644 --- a/lib/auth/password.go +++ b/lib/auth/password.go @@ -40,6 +40,7 @@ import ( "github.com/gravitational/teleport/lib/authz" "github.com/gravitational/teleport/lib/events" "github.com/gravitational/teleport/lib/services" + logutils "github.com/gravitational/teleport/lib/utils/log" ) // This is bcrypt hash for password "barbaz". @@ -164,7 +165,7 @@ func (a *Server) ChangePassword(ctx context.Context, req *proto.ChangePasswordRe UserMetadata: authz.ClientUserMetadataWithUser(ctx, user), ConnectionMetadata: authz.ConnectionMetadata(ctx), }); err != nil { - log.WithError(err).Warn("Failed to emit password change event.") + a.logger.WarnContext(ctx, "Failed to emit password change event", "error", err) } return nil } @@ -182,12 +183,12 @@ func (a *Server) checkPasswordWOToken(ctx context.Context, user string, password userFound := true if trace.IsNotFound(err) { userFound = false - log.Debugf("Password for username %q not found, using fake hash to mitigate timing attacks.", user) + a.logger.DebugContext(ctx, "Password for username not found, using fake hash to mitigate timing attacks", "user", user) hash = fakePasswordHash } if err = bcrypt.CompareHashAndPassword(hash, password); err != nil { - log.Debugf("Password for %q does not match", user) + a.logger.DebugContext(ctx, "Password for user does not match", "user", user) return trace.BadParameter(errMsg) } @@ -210,10 +211,10 @@ func (a *Server) checkPasswordWOToken(ctx context.Context, user string, password }) if err != nil { // Don't let the password state flag change fail the entire operation. - log. - WithError(err). - WithField("user", user). - Warn("Failed to set password state") + a.logger.WarnContext(ctx, "Failed to set password state", + "error", err, + "user", user, + ) } return nil @@ -230,7 +231,7 @@ func (a *Server) checkPassword(ctx context.Context, user string, password []byte return nil, trace.Wrap(err) } - mfaDev, err := a.checkOTP(user, otpToken) + mfaDev, err := a.checkOTP(ctx, user, otpToken) if err != nil { return nil, trace.Wrap(err) } @@ -238,7 +239,7 @@ func (a *Server) checkPassword(ctx context.Context, user string, password []byte } // checkOTP checks if the OTP token is valid. -func (a *Server) checkOTP(user string, otpToken string) (*types.MFADevice, error) { +func (a *Server) checkOTP(ctx context.Context, user string, otpToken string) (*types.MFADevice, error) { // get the previously used token to mitigate token replay attacks usedToken, err := a.GetUsedTOTPToken(user) if err != nil { @@ -249,7 +250,6 @@ func (a *Server) checkOTP(user string, otpToken string) (*types.MFADevice, error return nil, trace.BadParameter("previously used totp token") } - ctx := context.TODO() devs, err := a.Services.GetMFADevices(ctx, user, true) if err != nil { return nil, trace.Wrap(err) @@ -262,10 +262,10 @@ func (a *Server) checkOTP(user string, otpToken string) (*types.MFADevice, error } if err := a.checkTOTP(ctx, user, otpToken, dev); err != nil { - log. - WithError(err). - WithField("device", dev.GetName()). - Debug("TOTP device failed verification. This is expected if the user has multiple TOTP devices.") + a.logger.DebugContext(ctx, "TOTP device failed verification, this is expected if the user has multiple TOTP devices", + "error", err, + "device", dev.GetName(), + ) continue } return dev, nil @@ -414,7 +414,9 @@ func (a *Server) changeUserSecondFactor(ctx context.Context, req *proto.ChangeUs // Fallback to something reasonable while letting verifyMFARespAndAddDevice // worry about the "unknown" response type. deviceName = "mfa" - log.Warnf("Unexpected MFA register response type, setting device name to %q: %T", deviceName, req.GetNewMFARegisterResponse().Response) + a.logger.WarnContext(ctx, "Unexpected MFA register response type, setting device name to mfa", + "response_type", logutils.TypeAttr(req.GetNewMFARegisterResponse().Response), + ) } } diff --git a/lib/auth/rotate.go b/lib/auth/rotate.go index 5f7d708f71551..7418cff56b780 100644 --- a/lib/auth/rotate.go +++ b/lib/auth/rotate.go @@ -27,7 +27,6 @@ import ( "github.com/google/uuid" "github.com/gravitational/trace" "github.com/jonboulle/clockwork" - "github.com/sirupsen/logrus" "golang.org/x/crypto/ssh" "github.com/gravitational/teleport/api/types" @@ -227,7 +226,7 @@ func (a *Server) autoRotate(ctx context.Context, ca types.CertAuthority) error { if rotation.State != types.RotationStateInProgress { return nil } - logger := log.WithFields(logrus.Fields{"type": ca.GetType()}) + logger := a.logger.With("type", ca.GetType()) var req *rotationReq switch rotation.Phase { case types.RotationPhaseInit: @@ -269,7 +268,7 @@ func (a *Server) autoRotate(ctx context.Context, ca types.CertAuthority) error { default: return trace.BadParameter("phase is not supported: %q", rotation.Phase) } - logger.Infof("Setting rotation phase to %q", req.targetPhase) + logger.InfoContext(ctx, "Updating rotation phase", "target_phase", req.targetPhase) rotated, err := a.processRotationRequest(ctx, *req) if err != nil { return trace.Wrap(err) @@ -277,7 +276,7 @@ func (a *Server) autoRotate(ctx context.Context, ca types.CertAuthority) error { if _, err := a.UpdateCertAuthority(ctx, rotated); err != nil { return trace.Wrap(err) } - logger.Infof("Cert authority rotation request is completed") + logger.InfoContext(ctx, "Cert authority rotation request is completed") return nil } @@ -377,7 +376,7 @@ func (a *Server) startNewRotation(ctx context.Context, req rotationReq, ca types // generate keys and certificates: if len(req.privateKey) != 0 { - log.Infof("Generating CA, using pregenerated test private key.") + a.logger.InfoContext(ctx, "Generating CA, using pregenerated test private key") signer, err := keys.ParsePrivateKey(req.privateKey) if err != nil { diff --git a/lib/auth/saml.go b/lib/auth/saml.go index 4c11479967156..cf2dfe40ae039 100644 --- a/lib/auth/saml.go +++ b/lib/auth/saml.go @@ -87,7 +87,7 @@ func (a *Server) UpsertSAMLConnector(ctx context.Context, connector types.SAMLCo }, Connector: upsertedConnector, }); err != nil { - log.WithError(err).Warn("Failed to emit SAML connector create event.") + a.logger.WarnContext(ctx, "Failed to emit SAML connector create event", "error", err) } return upserted, nil @@ -133,7 +133,7 @@ func (a *Server) UpdateSAMLConnector(ctx context.Context, connector types.SAMLCo }, Connector: updatedConnector, }); err != nil { - log.WithError(err).Warn("Failed to emit SAML connector update event.") + a.logger.WarnContext(ctx, "Failed to emit SAML connector update event", "error", err) } return updated, nil @@ -175,7 +175,7 @@ func (a *Server) CreateSAMLConnector(ctx context.Context, connector types.SAMLCo }, Connector: newConnector, }); err != nil { - log.WithError(err).Warn("Failed to emit SAML connector create event.") + a.logger.WarnContext(ctx, "Failed to emit SAML connector create event", "error", err) } return created, nil @@ -196,7 +196,7 @@ func (a *Server) DeleteSAMLConnector(ctx context.Context, connectorID string) er Name: connectorID, }, }); err != nil { - log.WithError(err).Warn("Failed to emit SAML connector delete event.") + a.logger.WarnContext(ctx, "Failed to emit SAML connector delete event", "error", err) } return nil diff --git a/lib/auth/sso_diag_context.go b/lib/auth/sso_diag_context.go index a2699886ec70f..4db3d77d32efa 100644 --- a/lib/auth/sso_diag_context.go +++ b/lib/auth/sso_diag_context.go @@ -56,7 +56,10 @@ func (c *SSODiagContext) WriteToBackend(ctx context.Context) { if c.Info.TestFlow { err := c.DiagService.CreateSSODiagnosticInfo(ctx, c.AuthKind, c.RequestID, c.Info) if err != nil { - log.WithError(err).WithField("requestID", c.RequestID).Warn("failed to write SSO diag info data") + logger.WarnContext(ctx, "failed to write SSO diag info data", + "error", err, + "request_id", c.RequestID, + ) } } } diff --git a/lib/auth/transport_credentials.go b/lib/auth/transport_credentials.go index 1e0e87904637e..9eb499a5368c4 100644 --- a/lib/auth/transport_credentials.go +++ b/lib/auth/transport_credentials.go @@ -185,7 +185,7 @@ func newTimeoutConn(conn net.Conn, clock clockwork.Clock, expires time.Time) (ne return &timeoutConn{ Conn: conn, timer: clock.AfterFunc(expires.Sub(clock.Now()), func() { - log.Debug("Closing gRPC connection due to certificate expiry") + logger.DebugContext(context.Background(), "Closing gRPC connection due to certificate expiry") conn.Close() }), }, nil diff --git a/lib/auth/trustedcluster.go b/lib/auth/trustedcluster.go index e86008679d31e..443cb6579013e 100644 --- a/lib/auth/trustedcluster.go +++ b/lib/auth/trustedcluster.go @@ -343,7 +343,7 @@ func (a *Server) DeleteTrustedCluster(ctx context.Context, name string) error { }, ConnectionMetadata: authz.ConnectionMetadata(ctx), }); err != nil { - log.WithError(err).Warn("Failed to emit trusted cluster delete event.") + a.logger.WarnContext(ctx, "Failed to emit trusted cluster delete event", "error", err) } return nil @@ -384,12 +384,15 @@ func (a *Server) establishTrust(ctx context.Context, trustedCluster types.Truste } // log the local certificate authorities that we are sending - log.Infof("Sending validate request; token=%s, CAs=%v", backend.MaskKeyName(validateRequest.Token), validateRequest.CAs) + a.logger.InfoContext(ctx, "Sending validate request", + "token", backend.MaskKeyName(validateRequest.Token), + "cas", validateRequest.CAs, + ) // send the request to the remote auth server via the proxy - validateResponse, err := a.sendValidateRequestToProxy(trustedCluster.GetProxyAddress(), &validateRequest) + validateResponse, err := a.sendValidateRequestToProxy(ctx, trustedCluster.GetProxyAddress(), &validateRequest) if err != nil { - log.Error(err) + a.logger.ErrorContext(ctx, "failed to send validation request", "error", err) if strings.Contains(err.Error(), "x509") { return nil, trace.AccessDenied("the trusted cluster uses misconfigured HTTP/TLS certificate.") } @@ -397,7 +400,7 @@ func (a *Server) establishTrust(ctx context.Context, trustedCluster types.Truste } // log the remote certificate authorities we are adding - log.Infof("Received validate response; CAs=%v", validateResponse.CAs) + a.logger.InfoContext(ctx, "Received validate response", "cas", validateResponse.CAs) for _, ca := range validateResponse.CAs { for _, keyPair := range ca.GetActiveKeys().TLS { @@ -533,11 +536,14 @@ func (a *Server) GetRemoteClusters(ctx context.Context) ([]types.RemoteCluster, func (a *Server) validateTrustedCluster(ctx context.Context, validateRequest *authclient.ValidateTrustedClusterRequest) (resp *authclient.ValidateTrustedClusterResponse, err error) { defer func() { if err != nil { - log.WithError(err).Info("Trusted cluster validation failed") + a.logger.InfoContext(ctx, "Trusted cluster validation failed", "error", err) } }() - log.Debugf("Received validate request: token=%s, CAs=%v", backend.MaskKeyName(validateRequest.Token), validateRequest.CAs) + a.logger.DebugContext(ctx, "Received validate request", + "token", backend.MaskKeyName(validateRequest.Token), + "cas", validateRequest.CAs, + ) domainName, err := a.GetDomainName() if err != nil { @@ -604,7 +610,7 @@ func (a *Server) validateTrustedCluster(ctx context.Context, validateRequest *au } // log the local certificate authorities we are sending - log.Debugf("Sending validate response: CAs=%v", validateResponse.CAs) + a.logger.DebugContext(ctx, "Sending validate response", "cas", validateResponse.CAs) return &validateResponse, nil } @@ -641,7 +647,7 @@ func (a *Server) validateTrustedClusterToken(ctx context.Context, tokenName stri return provisionToken.GetMetadata().Labels, nil } -func (a *Server) sendValidateRequestToProxy(host string, validateRequest *authclient.ValidateTrustedClusterRequest) (*authclient.ValidateTrustedClusterResponse, error) { +func (a *Server) sendValidateRequestToProxy(ctx context.Context, host string, validateRequest *authclient.ValidateTrustedClusterRequest) (*authclient.ValidateTrustedClusterResponse, error) { proxyAddr := url.URL{ Scheme: "https", Host: host, @@ -652,7 +658,7 @@ func (a *Server) sendValidateRequestToProxy(host string, validateRequest *authcl } if lib.IsInsecureDevMode() { - log.Warn("The setting insecureSkipVerify is used to communicate with proxy. Make sure you intend to run Teleport in insecure mode!") + a.logger.WarnContext(ctx, "The setting insecureSkipVerify is used to communicate with proxy. Make sure you intend to run Teleport in insecure mode!") // Get the default transport, this allows picking up proxy from the // environment. @@ -682,7 +688,7 @@ func (a *Server) sendValidateRequestToProxy(host string, validateRequest *authcl return nil, trace.Wrap(err) } - out, err := httplib.ConvertResponse(clt.PostJSON(context.TODO(), clt.Endpoint("webapi", "trustedclusters", "validate"), validateRequestRaw)) + out, err := httplib.ConvertResponse(clt.PostJSON(ctx, clt.Endpoint("webapi", "trustedclusters", "validate"), validateRequestRaw)) if err != nil { return nil, trace.Wrap(err) } diff --git a/lib/auth/user.go b/lib/auth/user.go index fc8ed983930eb..5e51332e04071 100644 --- a/lib/auth/user.go +++ b/lib/auth/user.go @@ -65,7 +65,7 @@ func (a *Server) CompareAndSwapUser(ctx context.Context, new, existing types.Use Connector: connectorName, Roles: new.GetRoles(), }); err != nil { - log.WithError(err).Warn("Failed to emit user update event.") + a.logger.WarnContext(ctx, "Failed to emit user update event", "error", err) } usagereporter.EmitEditorChangeEvent(new.GetName(), existing.GetRoles(), new.GetRoles(), a.AnonymizeAndSubmit) diff --git a/lib/auth/usertoken.go b/lib/auth/usertoken.go index 5959f223cb491..2fceb89c64bb3 100644 --- a/lib/auth/usertoken.go +++ b/lib/auth/usertoken.go @@ -103,7 +103,7 @@ func (a *Server) CreateResetPasswordToken(ctx context.Context, req authclient.Cr Expires: a.GetClock().Now().UTC().Add(req.TTL), }, }); err != nil { - log.WithError(err).Warn("Failed to emit create reset password token event.") + a.logger.WarnContext(ctx, "Failed to emit create reset password token event", "error", err) } return a.GetUserToken(ctx, token.GetName()) @@ -150,7 +150,7 @@ func formatAccountName(s proxyDomainGetter, username string, authHostname string if len(proxies) == 0 { proxyHost, err = s.GetDomainName() if err != nil { - log.Errorf("Failed to retrieve cluster name, falling back to hostname: %v.", err) + logger.ErrorContext(context.TODO(), "Failed to retrieve cluster name, falling back to hostname", "error", err) proxyHost = authHostname } } else { @@ -363,7 +363,7 @@ func (a *Server) createRecoveryToken(ctx context.Context, username, tokenType st Expires: a.GetClock().Now().UTC().Add(req.TTL), }, }); err != nil { - log.WithError(err).Warn("Failed to emit create recovery token event.") + a.logger.WarnContext(ctx, "Failed to emit create recovery token event", "error", err) } return newToken, nil @@ -442,7 +442,7 @@ func (a *Server) createPrivilegeToken(ctx context.Context, username, tokenKind s Expires: a.GetClock().Now().UTC().Add(req.TTL), }, }); err != nil { - log.WithError(err).Warn("Failed to emit create privilege token event.") + a.logger.WarnContext(ctx, "Failed to emit create privilege token event", "error", err) } convertedToken, ok := token.(*types.UserTokenV3) @@ -454,10 +454,13 @@ func (a *Server) createPrivilegeToken(ctx context.Context, username, tokenKind s } // verifyUserToken verifies that the token is not expired and is of the allowed kinds. -func (a *Server) verifyUserToken(token types.UserToken, allowedKinds ...string) error { +func (a *Server) verifyUserToken(ctx context.Context, token types.UserToken, allowedKinds ...string) error { if token.Expiry().Before(a.clock.Now().UTC()) { // Provide obscure message on purpose, while logging the real error server side. - log.Debugf("Expired token(%s) type(%s)", token.GetName(), token.GetSubKind()) + a.logger.DebugContext(ctx, "Expired token", + "token", token.GetName(), + "token_type", token.GetSubKind(), + ) return trace.AccessDenied("invalid token") } @@ -467,6 +470,10 @@ func (a *Server) verifyUserToken(token types.UserToken, allowedKinds ...string) } } - log.Debugf("Invalid token(%s) type(%s), expected type: %v", token.GetName(), token.GetSubKind(), allowedKinds) + a.logger.DebugContext(ctx, "Invalid token", + "token", token.GetName(), + "token_type", token.GetSubKind(), + "expected_type", allowedKinds, + ) return trace.AccessDenied("invalid token") }