diff --git a/lib/client/alpn.go b/lib/client/alpn.go index db58eb374701f..9f88c69f1bdb1 100644 --- a/lib/client/alpn.go +++ b/lib/client/alpn.go @@ -129,7 +129,7 @@ func RunALPNAuthTunnel(ctx context.Context, cfg ALPNAuthTunnelConfig) error { go func() { defer cfg.Listener.Close() if err := lp.Start(ctx); err != nil { - log.WithError(err).Info("ALPN proxy stopped.") + log.InfoContext(ctx, "ALPN proxy stopped", "error", err) } }() diff --git a/lib/client/api.go b/lib/client/api.go index 9dd82e6af631a..35b28544978b2 100644 --- a/lib/client/api.go +++ b/lib/client/api.go @@ -40,7 +40,6 @@ import ( "unicode/utf8" "github.com/gravitational/trace" - "github.com/sirupsen/logrus" "go.opentelemetry.io/otel/attribute" oteltrace "go.opentelemetry.io/otel/trace" "golang.org/x/crypto/ssh" @@ -130,9 +129,7 @@ const ( const remoteForwardUnsupportedMessage = "ssh: tcpip-forward request denied by peer" -var log = logrus.WithFields(logrus.Fields{ - teleport.ComponentKey: teleport.ComponentClient, -}) +var log = logutils.NewPackageLogger(teleport.ComponentKey, teleport.ComponentClient) // ForwardedPort specifies local tunnel to remote // destination managed by the client, is equivalent @@ -659,7 +656,7 @@ func RetryWithRelogin(ctx context.Context, tc *TeleportClient, fn func() error, for _, o := range opts { o(opt) } - log.Debugf("Activating relogin on error=%q (type=%T)", fnErr, trace.Unwrap(fnErr)) + log.DebugContext(ctx, "Activating relogin on error", "error", fnErr, "error_type", logutils.TypeAttr(trace.Unwrap(fnErr))) if keys.IsPrivateKeyPolicyError(fnErr) { privateKeyPolicy, err := keys.ParsePrivateKeyPolicyError(fnErr) @@ -680,7 +677,7 @@ func RetryWithRelogin(ctx context.Context, tc *TeleportClient, fn func() error, key, err := tc.Login(ctx) if err != nil { if errors.Is(err, prompt.ErrNotTerminal) { - log.WithError(err).Debugf("Relogin is not available in this environment") + log.DebugContext(ctx, "Relogin is not available in this environment", "error", err) return trace.Wrap(fnErr) } if trace.IsTrustError(err) { @@ -705,7 +702,7 @@ func RetryWithRelogin(ctx context.Context, tc *TeleportClient, fn func() error, // Save profile to record proxy credentials if err := tc.SaveProfile(opt.makeCurrentProfile); err != nil { - log.Warningf("Failed to save profile: %v", err) + log.WarnContext(ctx, "Failed to save profile", "error", err) return trace.Wrap(err) } @@ -906,13 +903,16 @@ func (c *Config) LoadProfile(ps ProfileStore, proxyAddr string) error { c.DynamicForwardedPorts, err = ParseDynamicPortForwardSpec(profile.DynamicForwardedPorts) if err != nil { - log.Warnf("Unable to parse dynamic port forwarding in user profile: %v.", err) + log.WarnContext(context.Background(), "Unable to parse dynamic port forwarding in user profile", "error", err) } if required, ok := client.OverwriteALPNConnUpgradeRequirementByEnv(c.WebProxyAddr); ok { c.TLSRoutingConnUpgradeRequired = required } - log.Infof("ALPN connection upgrade required for %q: %v.", c.WebProxyAddr, c.TLSRoutingConnUpgradeRequired) + log.InfoContext(context.Background(), "ALPN connection upgrade required", + "web_proxy_addr", c.WebProxyAddr, + "upgrade_required", c.TLSRoutingConnUpgradeRequired, + ) return nil } @@ -1247,7 +1247,7 @@ func NewClient(c *Config) (tc *TeleportClient, err error) { if err != nil { return nil, trace.Wrap(err) } - log.Infof("No teleport login given. defaulting to %s", c.Username) + log.InfoContext(context.Background(), "No teleport login given, using default", "default_login", c.Username) } if c.WebProxyAddr == "" { return nil, trace.BadParameter("No proxy address specified, missed --proxy flag?") @@ -1257,7 +1257,7 @@ func NewClient(c *Config) (tc *TeleportClient, err error) { if err != nil { return nil, trace.Wrap(err) } - log.Infof("no host login given. defaulting to %s", c.HostLogin) + log.InfoContext(context.Background(), "no host login given, using default", "default_host_login", c.HostLogin) } c.Namespace = types.ProcessNamespace(c.Namespace) @@ -1426,7 +1426,10 @@ func (tc *TeleportClient) SignersForClusterWithReissue(ctx context.Context, clus signers, err = tc.localAgent.signersForCluster(clusterName) if err != nil { - log.WithError(err).Warnf("Failed to load/reissue certificates for cluster %q.", clusterName) + log.WarnContext(ctx, "Failed to load/reissue certificates for cluster", + "error", err, + "cluster", clusterName, + ) return nil, trace.Wrap(err) } return signers, nil @@ -1505,7 +1508,11 @@ func (tc *TeleportClient) GetTargetNodes(ctx context.Context, clt client.ListUni // Query for nodes if labels, fuzzy search, or predicate expressions were provided. if len(tc.Labels) > 0 || len(tc.SearchKeywords) > 0 || tc.PredicateExpression != "" { - log.Debugf("Attempting to resolve matching hosts from labels=%v|search=%v|predicate=%v", tc.Labels, tc.SearchKeywords, tc.PredicateExpression) + log.DebugContext(ctx, "Attempting to resolve matching hosts", + "labels", tc.Labels, + "search", tc.SearchKeywords, + "predicate", tc.PredicateExpression, + ) nodes, err := client.GetAllUnifiedResources(ctx, clt, &proto.ListUnifiedResourcesRequest{ Kinds: []string{types.KindNode}, SortBy: types.SortBy{Field: types.ResourceMetadataName}, @@ -1535,7 +1542,7 @@ func (tc *TeleportClient) GetTargetNodes(ctx context.Context, clt client.ListUni return retval, nil } - log.Debugf("Using provided host %s", tc.Host) + log.DebugContext(ctx, "Using provided host", "host", tc.Host) // detect the common error when users use host:port address format _, port, err := net.SplitHostPort(tc.Host) @@ -1572,7 +1579,7 @@ func (tc *TeleportClient) GetTargetNode(ctx context.Context, clt authclient.Clie } if len(tc.Labels) == 0 && len(tc.SearchKeywords) == 0 && tc.PredicateExpression == "" { - log.Debugf("Using provided host %s", tc.Host) + log.DebugContext(ctx, "Using provided host", "host", tc.Host) // detect the common error when users use host:port address format _, port, err := net.SplitHostPort(tc.Host) @@ -1589,7 +1596,11 @@ func (tc *TeleportClient) GetTargetNode(ctx context.Context, clt authclient.Clie } // Query for nodes if labels, fuzzy search, or predicate expressions were provided. - log.Debugf("Attempting to resolve matching host from labels=%v|search=%v|predicate=%v", tc.Labels, tc.SearchKeywords, tc.PredicateExpression) + log.DebugContext(ctx, "Attempting to resolve matching host", + "labels", tc.Labels, + "search", tc.SearchKeywords, + "predicate", tc.PredicateExpression, + ) resp, err := clt.ResolveSSHTarget(ctx, &proto.ResolveSSHTargetRequest{ PredicateExpression: tc.PredicateExpression, SearchKeywords: tc.SearchKeywords, @@ -2175,7 +2186,7 @@ func (tc *TeleportClient) runShellOrCommandOnSingleNode(ctx context.Context, clt go func() { connClosed <- nodeClient.Client.Wait() }() - log.Debugf("Connected to node, no remote command execution was requested, blocking indefinitely.") + log.DebugContext(ctx, "Connected to node, no remote command execution was requested, blocking indefinitely") select { case <-ctx.Done(): // Only return an error if the context was canceled by something other than SIGINT. @@ -2259,11 +2270,11 @@ func (tc *TeleportClient) startPortForwarding(ctx context.Context, nodeClient *N // We log the error here instead of returning it to be consistent with // the other port forwarding methods, which don't stop the session // if forwarding fails. - message := fmt.Sprintf("Failed to bind on remote host to %v: %v.", addr, err) if strings.Contains(err.Error(), remoteForwardUnsupportedMessage) { - message = "Node does not support remote port forwarding (-R)." + log.ErrorContext(ctx, "Node does not support remote port forwarding (-R)") + } else { + log.ErrorContext(ctx, "Failed to bind on remote host", "addr", addr, "error", err) } - log.Error(message) } else { go nodeClient.remoteListenAndForward(ctx, socket, net.JoinHostPort(fp.DestHost, strconv.Itoa(fp.DestPort)), addr) } @@ -2650,7 +2661,7 @@ func (tc *TeleportClient) ListNodesWithFilters(ctx context.Context) ([]types.Ser for _, r := range page { srv, ok := r.ResourceWithLabels.(types.Server) if !ok { - log.Warnf("expected types.Server but received unexpected type %T", r) + log.WarnContext(ctx, "expected types.Server but received unexpected type", "resource_type", logutils.TypeAttr(r)) continue } @@ -3046,7 +3057,7 @@ func (tc *TeleportClient) getProxySSHPrincipal() string { proxyPrincipal := tc.Config.HostLogin if len(tc.JumpHosts) > 0 && tc.JumpHosts[0].Username != "" { - log.Debugf("Setting proxy login to jump host's parameter user %q", tc.JumpHosts[0].Username) + log.DebugContext(context.Background(), "Setting proxy login to jump host's parameter user", "user", tc.JumpHosts[0].Username) proxyPrincipal = tc.JumpHosts[0].Username } return proxyPrincipal @@ -3178,7 +3189,7 @@ func (tc *TeleportClient) generateClientConfig(ctx context.Context) (*clientConf authMethods := append([]ssh.AuthMethod{}, tc.Config.AuthMethods...) clusterName := func() string { return tc.SiteName } if len(tc.JumpHosts) > 0 { - log.Debugf("Overriding SSH proxy to JumpHosts's address %q", tc.JumpHosts[0].Addr.String()) + log.DebugContext(ctx, "Overriding SSH proxy to JumpHosts's address", "addr", logutils.StringerAttr(&tc.JumpHosts[0].Addr)) proxyAddr = tc.JumpHosts[0].Addr.Addr if tc.localAgent != nil { @@ -3299,7 +3310,9 @@ func (g *proxyClusterGuesser) hostKeyCallback(hostname string, remote net.Addr, } if clusterName == "" { - log.Debugf("Target SSH server %q does not have a cluster name embedded in their certificate; will use all available client certificates to authenticate", hostname) + log.DebugContext(context.Background(), "Target SSH server does not have a cluster name embedded in their certificate; will use all available client certificates to authenticate", + "target_server", hostname, + ) } if g.nextHostKeyCallback != nil { @@ -3548,7 +3561,7 @@ func (tc *TeleportClient) AttemptDeviceLogin(ctx context.Context, keyRing *KeyRi } if !tc.dtAttemptLoginIgnorePing && pingResp.Auth.DeviceTrust.Disabled { - log.Debug("Device Trust: skipping device authentication, device trust disabled") + log.DebugContext(ctx, "Device Trust: skipping device authentication, device trust disabled") return nil } @@ -3563,20 +3576,20 @@ func (tc *TeleportClient) AttemptDeviceLogin(ctx context.Context, keyRing *KeyRi }) switch { case errors.Is(err, devicetrust.ErrDeviceKeyNotFound): - log.Debug("Device Trust: Skipping device authentication, device key not found") + log.DebugContext(ctx, "Device Trust: Skipping device authentication, device key not found") return nil // err swallowed on purpose case errors.Is(err, devicetrust.ErrPlatformNotSupported): - log.Debug("Device Trust: Skipping device authentication, platform not supported") + log.DebugContext(ctx, "Device Trust: Skipping device authentication, platform not supported") return nil // err swallowed on purpose case trace.IsNotImplemented(err): - log.Debug("Device Trust: Skipping device authentication, not supported by server") + log.DebugContext(ctx, "Device Trust: Skipping device authentication, not supported by server") return nil // err swallowed on purpose case err != nil: - log.WithError(err).Debug("Device Trust: device authentication failed") + log.DebugContext(ctx, "Device Trust: device authentication failed", "error", err) return nil // err swallowed on purpose } - log.Debug("Device Trust: acquired augmented user certificates") + log.DebugContext(ctx, "Device Trust: acquired augmented user certificates") cp := *keyRing cp.Cert = newCerts.SshAuthorizedKey cp.TLSCert = pem.EncodeToMemory(&pem.Block{ @@ -3636,7 +3649,7 @@ func (tc *TeleportClient) DeviceLogin(ctx context.Context, params *dtauthntypes. // Is auto-enroll enabled? pingResp, err := tc.Ping(ctx) if err != nil { - log.WithError(err).Debug("Device Trust: swallowing Ping error for previous Login error") + log.DebugContext(ctx, "Device Trust: swallowing Ping error for previous Login error", "error", err) return nil, trace.Wrap(loginErr) // err swallowed for loginErr } if !tc.dtAutoEnrollIgnorePing && !pingResp.Auth.DeviceTrust.AutoEnroll { @@ -3650,7 +3663,7 @@ func (tc *TeleportClient) DeviceLogin(ctx context.Context, params *dtauthntypes. // Auto-enroll and Login again. if _, err := autoEnroll(ctx, params.DevicesClient); err != nil { - log.WithError(err).Debug("Device Trust: device auto-enroll failed") + log.DebugContext(ctx, "Device Trust: device auto-enroll failed", "error", err) return nil, trace.Wrap(loginErr) // err swallowed for loginErr } newCerts, err = runCeremony(ctx, params) @@ -3690,7 +3703,7 @@ func (tc *TeleportClient) getSSHLoginFunc(pr *webclient.PingResponse) (SSHLoginF // registered, we can try to go with passwordless login even though // auth=local was selected. if tc.canDefaultToPasswordless(pr) { - log.Debug("Trying passwordless login because credentials were found") + log.DebugContext(context.Background(), "Trying passwordless login because credentials were found") return tc.pwdlessLogin, nil } @@ -3732,7 +3745,7 @@ func (tc *TeleportClient) getWebLoginFunc(pr *webclient.PingResponse) (WebLoginF // registered, we can try to go with passwordless login even though // auth=local was selected. if tc.canDefaultToPasswordless(pr) { - log.Debug("Trying passwordless login because credentials were found") + log.DebugContext(context.Background(), "Trying passwordless login because credentials were found") return tc.pwdlessLoginWeb, nil } @@ -3984,9 +3997,9 @@ func (tc *TeleportClient) GetNewLoginKeyRing(ctx context.Context) (keyRing *KeyR defer span.End() if tc.PrivateKeyPolicy.IsHardwareKeyPolicy() { - log.Debugf("Attempting to login with YubiKey private key.") + log.DebugContext(ctx, "Attempting to login with YubiKey private key") if tc.PIVSlot != "" { - log.Debugf("Using PIV slot %q specified by client or server settings.", tc.PIVSlot) + log.DebugContext(ctx, "Using PIV slot specified by client or server settings", "piv_slot", tc.PIVSlot) } priv, err := keys.GetYubiKeyPrivateKey(ctx, tc.PrivateKeyPolicy, tc.PIVSlot, tc.CustomHardwareKeyPrompt) if err != nil { @@ -3998,7 +4011,7 @@ func (tc *TeleportClient) GetNewLoginKeyRing(ctx context.Context) (keyRing *KeyR var sshKey, tlsKey crypto.Signer if tc.GenerateUnifiedKey { - log.Debugf("Attempting to login with a new software private key.") + log.DebugContext(ctx, "Attempting to login with a new software private key") // Using the UserTLS key algorithm for both keys because SSH generally // supports all TLS keys algorithms (RSA2048, ECDSAP256), but TLS does // not support Ed25519 which may be used for SSH. @@ -4008,7 +4021,7 @@ func (tc *TeleportClient) GetNewLoginKeyRing(ctx context.Context) (keyRing *KeyR } sshKey = tlsKey } else { - log.Debugf("Attempting to login with new software private keys.") + log.DebugContext(ctx, "Attempting to login with new software private keys") var err error sshKey, tlsKey, err = cryptosuites.GenerateUserSSHAndTLSKey(ctx, tc.GetCurrentSignatureAlgorithmSuite) if err != nil { @@ -4745,23 +4758,26 @@ func (tc *TeleportClient) EventsChannel() <-chan events.EventFields { // loopbackPool reads trusted CAs if it finds it in a predefined location // and will work only if target proxy address is loopback func loopbackPool(proxyAddr string) *x509.CertPool { + ctx := context.Background() + if !apiutils.IsLoopback(proxyAddr) { - log.Debugf("not using loopback pool for remote proxy addr: %v", proxyAddr) + log.DebugContext(ctx, "not using loopback pool for remote proxy addr", "proxy_addr", proxyAddr) return nil } - log.Debugf("attempting to use loopback pool for local proxy addr: %v", proxyAddr) + log.DebugContext(ctx, "attempting to use loopback pool for local proxy addr", "proxy_addr", proxyAddr) certPool, err := x509.SystemCertPool() if err != nil { - log.Debugf("could not open system cert pool, using empty cert pool instead: %v", err) + log.DebugContext(ctx, "could not open system cert pool, using empty cert pool instead", "error", err) certPool = x509.NewCertPool() } certPath := filepath.Join(defaults.DataDir, defaults.SelfSignedCertPath) - log.Debugf("reading self-signed certs from: %v", certPath) + logger := log.With("cert_path", certPath) + logger.DebugContext(ctx, "reading self-signed certs") pemByte, err := os.ReadFile(certPath) if err != nil { - log.Debugf("could not open any path in: %v", certPath) + logger.DebugContext(ctx, "could not open any path in") return nil } @@ -4773,25 +4789,31 @@ func loopbackPool(proxyAddr string) *x509.CertPool { } cert, err := x509.ParseCertificate(block.Bytes) if err != nil { - log.Debugf("could not parse cert in: %v, err: %v", certPath, err) + logger.DebugContext(ctx, "could not parse cert", "error", err) return nil } certPool.AddCert(cert) } - log.Debugf("using local pool for loopback proxy: %v, err: %v", certPath, err) + logger.DebugContext(ctx, "using local pool for loopback proxy", "error", err) return certPool } // connectToSSHAgent connects to the system SSH agent and returns an agent.Agent. func connectToSSHAgent() agent.ExtendedAgent { + ctx := context.Background() + logger := log.With(teleport.ComponentKey, "KEYAGENT") + socketPath := os.Getenv(teleport.SSHAuthSock) conn, err := agentconn.Dial(socketPath) if err != nil { - log.Warnf("[KEY AGENT] Unable to connect to SSH agent on socket %q: %v", socketPath, err) + logger.WarnContext(ctx, "Unable to connect to SSH agent on socket", + "socket_path", socketPath, + "error", err, + ) return nil } - log.Infof("[KEY AGENT] Connected to the system agent: %q", socketPath) + logger.InfoContext(ctx, "Connected to the system agent", "socket_path", socketPath) return agent.NewClient(conn) } diff --git a/lib/client/api_login_test.go b/lib/client/api_login_test.go index cd39dd3acf0c1..e06e73c6ce648 100644 --- a/lib/client/api_login_test.go +++ b/lib/client/api_login_test.go @@ -36,7 +36,6 @@ import ( "github.com/google/uuid" "github.com/jonboulle/clockwork" "github.com/pquerna/otp/totp" - log "github.com/sirupsen/logrus" "github.com/stretchr/testify/assert" "github.com/stretchr/testify/require" @@ -64,8 +63,6 @@ import ( func TestTeleportClient_Login_local(t *testing.T) { t.Parallel() - silenceLogger(t) - type webauthnFunc func(ctx context.Context, origin string, assertion *wantypes.CredentialAssertion, prompt wancli.LoginPrompt) (*proto.MFAAuthenticateResponse, error) waitForCancelFn := func(ctx context.Context) (string, error) { @@ -324,8 +321,6 @@ func TestTeleportClient_Login_local(t *testing.T) { } func TestTeleportClient_DeviceLogin(t *testing.T) { - silenceLogger(t) - clock := clockwork.NewFakeClockAt(time.Now()) sa := newStandaloneTeleport(t, clock) username := sa.Username @@ -521,10 +516,6 @@ type standaloneBundle struct { func newStandaloneTeleport(t *testing.T, clock clockwork.Clock) *standaloneBundle { randomAddr := utils.NetAddr{AddrNetwork: "tcp", Addr: "127.0.0.1:0"} - // Silent logger and console. - logger := utils.NewLoggerForTests() - logger.SetLevel(log.PanicLevel) - logger.SetOutput(io.Discard) console := io.Discard staticToken := uuid.New().String() @@ -559,7 +550,7 @@ func newStandaloneTeleport(t *testing.T, clock clockwork.Clock) *standaloneBundl cfg.Hostname = "localhost" cfg.Clock = clock cfg.Console = console - cfg.Log = logger + cfg.Logger = utils.NewSlogLoggerForTests() cfg.SetAuthServerAddress(randomAddr) // must be present cfg.Auth.Preference, err = types.NewAuthPreferenceFromConfigFile(types.AuthPreferenceSpecV2{ Type: constants.Local, @@ -643,7 +634,7 @@ func newStandaloneTeleport(t *testing.T, clock clockwork.Clock) *standaloneBundl cfg.SetToken(staticToken) cfg.Clock = clock cfg.Console = console - cfg.Log = logger + cfg.Logger = utils.NewSlogLoggerForTests() cfg.SetAuthServerAddress(*authAddr) cfg.Auth.Enabled = false cfg.Proxy.Enabled = true @@ -683,17 +674,6 @@ func startAndWait(t *testing.T, cfg *servicecfg.Config, eventName string) *servi return instance } -// silenceLogger silences logger during testing. -func silenceLogger(t *testing.T) { - lvl := log.GetLevel() - t.Cleanup(func() { - log.SetOutput(os.Stderr) - log.SetLevel(lvl) - }) - log.SetOutput(io.Discard) - log.SetLevel(log.PanicLevel) -} - func TestRetryWithRelogin(t *testing.T) { clock := clockwork.NewFakeClockAt(time.Now()) sa := newStandaloneTeleport(t, clock) diff --git a/lib/client/client.go b/lib/client/client.go index f14a5a2df476d..ffa41d5fcbc5f 100644 --- a/lib/client/client.go +++ b/lib/client/client.go @@ -54,6 +54,7 @@ import ( "github.com/gravitational/teleport/lib/events" "github.com/gravitational/teleport/lib/sshutils/sftp" "github.com/gravitational/teleport/lib/utils" + logutils "github.com/gravitational/teleport/lib/utils/log" "github.com/gravitational/teleport/lib/utils/socks" ) @@ -217,7 +218,7 @@ func makeDatabaseClientPEM(proto string, cert []byte, pk *keys.PrivateKey) ([]by } else if !trace.IsBadParameter(err) { return nil, trace.Wrap(err) } - log.WithError(err).Warn("MongoDB integration is not supported when logging in with a hardware private key.") + log.WarnContext(context.Background(), "MongoDB integration is not supported when logging in with a hardware private key", "error", err) } return cert, nil } @@ -333,7 +334,11 @@ func NewNodeClient(ctx context.Context, sshConfig *ssh.ClientConfig, conn net.Co // TODO(codingllama): Improve error message below for device trust. // An alternative we have here is querying the cluster to check if device // trust is required, a check similar to `IsMFARequired`. - log.Infof("Access denied to %v connecting to %v: %v", sshConfig.User, nodeName, err) + log.InfoContext(ctx, "Access denied connecting to host", + "login", sshConfig.User, + "target_host", nodeName, + "error", err, + ) return nil, trace.AccessDenied(`access denied to %v connecting to %v`, sshConfig.User, nodeName) } return nil, trace.Wrap(err) @@ -640,7 +645,7 @@ func (c *NodeClient) handleGlobalRequests(ctx context.Context, requestCh <-chan switch r.Type { case teleport.MFAPresenceRequest: if c.OnMFA == nil { - log.Warn("Received MFA presence request, but no callback was provided.") + log.WarnContext(ctx, "Received MFA presence request, but no callback was provided") continue } @@ -651,21 +656,21 @@ func (c *NodeClient) handleGlobalRequests(ctx context.Context, requestCh <-chan var e events.EventFields err := json.Unmarshal(r.Payload, &e) if err != nil { - log.Warnf("Unable to parse event: %v: %v.", string(r.Payload), err) + log.WarnContext(ctx, "Unable to parse event", "event", string(r.Payload), "error", err) continue } // Send event to event channel. err = c.TC.SendEvent(ctx, e) if err != nil { - log.Warnf("Unable to send event %v: %v.", string(r.Payload), err) + log.WarnContext(ctx, "Unable to send event", "event", string(r.Payload), "error", err) continue } default: // This handles keep-alive messages and matches the behavior of OpenSSH. err := r.Reply(false, nil) if err != nil { - log.Warnf("Unable to reply to %v request.", r.Type) + log.WarnContext(ctx, "Unable to reply to request", "request_type", r.Type, "error", err) continue } } @@ -707,7 +712,7 @@ func newClientConn( case <-ctx.Done(): errClose := conn.Close() if errClose != nil { - log.Error(errClose) + log.ErrorContext(ctx, "Failed closing connection", "error", errClose) } // drain the channel resp := <-respCh @@ -732,11 +737,16 @@ type netDialer interface { } func proxyConnection(ctx context.Context, conn net.Conn, remoteAddr string, dialer netDialer) error { + logger := log.With( + "source_addr", logutils.StringerAttr(conn.RemoteAddr()), + "target_addr", remoteAddr, + ) + defer conn.Close() - defer log.Debugf("Finished proxy from %v to %v.", conn.RemoteAddr(), remoteAddr) + defer logger.DebugContext(ctx, "Finished proxy connection") var remoteConn net.Conn - log.Debugf("Attempting to connect proxy from %v to %v.", conn.RemoteAddr(), remoteAddr) + logger.DebugContext(ctx, "Attempting to proxy connection") retry, err := retryutils.NewLinear(retryutils.LinearConfig{ First: 100 * time.Millisecond, @@ -756,7 +766,7 @@ func proxyConnection(ctx context.Context, conn net.Conn, remoteAddr string, dial break } - log.Debugf("Proxy connection attempt %v: %v.", attempt, err) + logger.DebugContext(ctx, "Proxy connection attempt", "attempt", attempt, "error", err) // Wait and attempt to connect again, if the context has closed, exit // right away. select { @@ -806,16 +816,19 @@ func acceptWithContext(ctx context.Context, l net.Listener) (net.Conn, error) { func (c *NodeClient) listenAndForward(ctx context.Context, ln net.Listener, localAddr string, remoteAddr string) { defer ln.Close() - log := log.WithField("localAddr", localAddr).WithField("remoteAddr", remoteAddr) + log := log.With( + "local_addr", localAddr, + "remote_addr", remoteAddr, + ) - log.Infof("Starting port forwarding") + log.InfoContext(ctx, "Starting port forwarding") for ctx.Err() == nil { // Accept connections from the client. conn, err := acceptWithContext(ctx, ln) if err != nil { if ctx.Err() == nil { - log.WithError(err).Errorf("Port forwarding failed.") + log.ErrorContext(ctx, "Port forwarding failed", "error", err) } continue } @@ -824,12 +837,12 @@ func (c *NodeClient) listenAndForward(ctx context.Context, ln net.Listener, loca go func() { // `err` must be a fresh variable, hence `:=` instead of `=`. if err := proxyConnection(ctx, conn, remoteAddr, c.Client); err != nil { - log.WithError(err).Warnf("Failed to proxy connection.") + log.WarnContext(ctx, "Failed to proxy connection", "error", err) } }() } - log.WithError(ctx.Err()).Infof("Shutting down port forwarding.") + log.InfoContext(ctx, "Shutting down port forwarding", "error", ctx.Err()) } // dynamicListenAndForward listens for connections, performs a SOCKS5 @@ -837,9 +850,11 @@ func (c *NodeClient) listenAndForward(ctx context.Context, ln net.Listener, loca func (c *NodeClient) dynamicListenAndForward(ctx context.Context, ln net.Listener, localAddr string) { defer ln.Close() - log := log.WithField("localAddr", localAddr) + log := log.With( + "local_addr", localAddr, + ) - log.Infof("Starting dynamic port forwarding.") + log.InfoContext(ctx, "Starting dynamic port forwarding") for ctx.Err() == nil { // Accept connection from the client. Here the client is typically @@ -847,7 +862,7 @@ func (c *NodeClient) dynamicListenAndForward(ctx context.Context, ln net.Listene conn, err := acceptWithContext(ctx, ln) if err != nil { if ctx.Err() == nil { - log.WithError(err).Errorf("Dynamic port forwarding (SOCKS5) failed.") + log.ErrorContext(ctx, "Dynamic port forwarding (SOCKS5) failed", "error", err) } continue } @@ -856,52 +871,55 @@ func (c *NodeClient) dynamicListenAndForward(ctx context.Context, ln net.Listene // address to proxy. remoteAddr, err := socks.Handshake(conn) if err != nil { - log.WithError(err).Errorf("SOCKS5 handshake failed.") + log.ErrorContext(ctx, "SOCKS5 handshake failed", "error", err) if err = conn.Close(); err != nil { - log.WithError(err).Errorf("Error closing failed proxy connection.") + log.ErrorContext(ctx, "Error closing failed proxy connection", "error", err) } continue } - log.Debugf("SOCKS5 proxy forwarding requests to %v.", remoteAddr) + log.DebugContext(ctx, "SOCKS5 proxy forwarding requests", "remote_addr", remoteAddr) // Proxy the connection to the remote address. go func() { // `err` must be a fresh variable, hence `:=` instead of `=`. if err := proxyConnection(ctx, conn, remoteAddr, c.Client); err != nil { - log.WithError(err).Warnf("Failed to proxy connection.") + log.WarnContext(ctx, "Failed to proxy connection", "error", err) if err = conn.Close(); err != nil { - log.WithError(err).Errorf("Error closing failed proxy connection.") + log.ErrorContext(ctx, "Error closing failed proxy connection", "error", err) } } }() } - log.WithError(ctx.Err()).Infof("Shutting down dynamic port forwarding.") + log.InfoContext(ctx, "Shutting down dynamic port forwarding", "error", ctx.Err()) } // remoteListenAndForward requests a listening socket and forwards all incoming // commands to the local address through the SSH tunnel. func (c *NodeClient) remoteListenAndForward(ctx context.Context, ln net.Listener, localAddr, remoteAddr string) { defer ln.Close() - log := log.WithField("localAddr", localAddr).WithField("remoteAddr", remoteAddr) - log.Infof("Starting remote port forwarding") + log := log.With( + "local_addr", localAddr, + "remote_addr", remoteAddr, + ) + log.InfoContext(ctx, "Starting remote port forwarding") for ctx.Err() == nil { conn, err := acceptWithContext(ctx, ln) if err != nil { if ctx.Err() == nil { - log.WithError(err).Errorf("Remote port forwarding failed.") + log.ErrorContext(ctx, "Remote port forwarding failed", "error", err) } continue } go func() { if err := proxyConnection(ctx, conn, localAddr, &net.Dialer{}); err != nil { - log.WithError(err).Warnf("Failed to proxy connection") + log.WarnContext(ctx, "Failed to proxy connection", "error", err) } }() } - log.WithError(ctx.Err()).Infof("Shutting down remote port forwarding.") + log.InfoContext(ctx, "Shutting down remote port forwarding", "error", ctx.Err()) } // GetRemoteTerminalSize fetches the terminal size of a given SSH session. diff --git a/lib/client/client_store.go b/lib/client/client_store.go index d10b1b47a7b4b..5762f9d7ec8ee 100644 --- a/lib/client/client_store.go +++ b/lib/client/client_store.go @@ -19,13 +19,14 @@ package client import ( + "context" "errors" "fmt" + "log/slog" "net/url" "time" "github.com/gravitational/trace" - "github.com/sirupsen/logrus" "golang.org/x/crypto/ssh" "github.com/gravitational/teleport" @@ -42,7 +43,7 @@ import ( // when using `tsh --add-keys-to-agent=only`, Store will be made up of an in-memory // key store and an FS (~/.tsh) profile and trusted certs store. type Store struct { - log *logrus.Entry + log *slog.Logger KeyStore TrustedCertsStore @@ -53,7 +54,7 @@ type Store struct { func NewFSClientStore(dirPath string) *Store { dirPath = profile.FullProfilePath(dirPath) return &Store{ - log: logrus.WithField(teleport.ComponentKey, teleport.ComponentKeyStore), + log: slog.With(teleport.ComponentKey, teleport.ComponentKeyStore), KeyStore: NewFSKeyStore(dirPath), TrustedCertsStore: NewFSTrustedCertsStore(dirPath), ProfileStore: NewFSProfileStore(dirPath), @@ -63,7 +64,7 @@ func NewFSClientStore(dirPath string) *Store { // NewMemClientStore initializes a new in-memory client store. func NewMemClientStore() *Store { return &Store{ - log: logrus.WithField(teleport.ComponentKey, teleport.ComponentKeyStore), + log: slog.With(teleport.ComponentKey, teleport.ComponentKeyStore), KeyStore: NewMemKeyStore(), TrustedCertsStore: NewMemTrustedCertsStore(), ProfileStore: NewMemProfileStore(), @@ -261,7 +262,10 @@ func (s *Store) FullProfileStatus() (*ProfileStatus, []*ProfileStatus, error) { } status, err := s.ReadProfileStatus(profileName) if err != nil { - s.log.WithError(err).Warnf("skipping profile %q due to error", profileName) + s.log.WarnContext(context.Background(), "skipping profile due to error", + "profile_name", profileName, + "error", err, + ) continue } profiles = append(profiles, status) diff --git a/lib/client/cluster_client.go b/lib/client/cluster_client.go index ce0a7d6485a6e..729f8f602863d 100644 --- a/lib/client/cluster_client.go +++ b/lib/client/cluster_client.go @@ -311,7 +311,7 @@ func (c *ClusterClient) SessionSSHConfig(ctx context.Context, user string, targe defer authClient.Close() } - log.Debug("Attempting to issue a single-use user certificate with an MFA check.") + log.DebugContext(ctx, "Attempting to issue a single-use user certificate with an MFA check") keyRing, err = c.performSessionMFACeremony(ctx, mfaClt, ReissueParams{ @@ -325,7 +325,7 @@ func (c *ClusterClient) SessionSSHConfig(ctx context.Context, user string, targe return nil, trace.Wrap(err) } - log.Debug("Issued single-use user certificate after an MFA check.") + log.DebugContext(ctx, "Issued single-use user certificate after an MFA check") am, err := keyRing.AsAuthMethod() if err != nil { return nil, trace.Wrap(ceremonyFailedErr{err}) @@ -561,7 +561,7 @@ func (c *ClusterClient) IssueUserCertsWithMFA(ctx context.Context, params Reissu // MFA is not required, but the user requires a new certificate with the // target included in it for routing. if !mfaRequired { - log.Debug("MFA not required for access.") + log.DebugContext(ctx, "MFA not required for access") keyRing, err := certClient.generateUserCerts(ctx, CertCacheKeep, params) return keyRing, proto.MFARequired_MFA_REQUIRED_NO, trace.Wrap(err) } @@ -572,7 +572,7 @@ func (c *ClusterClient) IssueUserCertsWithMFA(ctx context.Context, params Reissu return nil, proto.MFARequired_MFA_REQUIRED_YES, trace.Wrap(err) } - log.Debug("Issued single-use user certificate after an MFA check.") + log.DebugContext(ctx, "Issued single-use user certificate after an MFA check") return keyRing, proto.MFARequired_MFA_REQUIRED_YES, nil } @@ -648,7 +648,7 @@ func PerformSessionMFACeremony(ctx context.Context, params PerformSessionMFACere // that MFA was not required instead of the error received from the root cluster. if mfaRequiredReq != nil && !params.MFAAgainstRoot { mfaRequiredResp, err := currentClient.IsMFARequired(ctx, mfaRequiredReq) - log.Debugf("MFA requirement acquired from leaf, MFARequired=%s", mfaRequiredResp.GetMFARequired()) + log.DebugContext(ctx, "MFA requirement acquired from leaf", "mfa_required", mfaRequiredResp.GetMFARequired()) switch { case err != nil: return nil, nil, trace.Wrap(MFARequiredUnknown(err)) @@ -686,7 +686,7 @@ func PerformSessionMFACeremony(ctx context.Context, params PerformSessionMFACere certsReq := params.CertsReq certsReq.MFAResponse = mfaResp certsReq.Purpose = proto.UserCertsRequest_CERT_PURPOSE_SINGLE_USE_CERTS - log.Debug("Issuing single-use certificate from unary GenerateUserCerts") + log.DebugContext(ctx, "Issuing single-use certificate from unary GenerateUserCerts") newCerts, err := rootClient.GenerateUserCerts(ctx, *certsReq) if err != nil { return nil, nil, trace.Wrap(err) diff --git a/lib/client/conntest/database/mysql.go b/lib/client/conntest/database/mysql.go index 1c2a7ca2e561b..39d07a811fa17 100644 --- a/lib/client/conntest/database/mysql.go +++ b/lib/client/conntest/database/mysql.go @@ -22,13 +22,13 @@ import ( "context" "errors" "fmt" + "log/slog" "net" "strings" "github.com/go-mysql-org/go-mysql/client" "github.com/go-mysql-org/go-mysql/mysql" "github.com/gravitational/trace" - "github.com/sirupsen/logrus" "github.com/gravitational/teleport/lib/defaults" ) @@ -73,7 +73,7 @@ func (p *MySQLPinger) Ping(ctx context.Context, params PingParams) error { defer func() { if err := conn.Quit(); err != nil { - logrus.WithError(err).Info("Failed to close connection in MySQLPinger.Ping") + slog.InfoContext(context.Background(), "Failed to close connection in MySQLPinger.Ping", "error", err) } }() diff --git a/lib/client/conntest/database/postgres.go b/lib/client/conntest/database/postgres.go index 6a574c56ce156..a048376aadc8a 100644 --- a/lib/client/conntest/database/postgres.go +++ b/lib/client/conntest/database/postgres.go @@ -22,12 +22,12 @@ import ( "context" "errors" "fmt" + "log/slog" "strings" "github.com/gravitational/trace" "github.com/jackc/pgconn" "github.com/jackc/pgerrcode" - "github.com/sirupsen/logrus" "github.com/gravitational/teleport/lib/defaults" ) @@ -65,7 +65,7 @@ func (p *PostgresPinger) Ping(ctx context.Context, params PingParams) error { defer func() { if err := conn.Close(ctx); err != nil { - logrus.WithError(err).Info("failed to close connection in PostgresPinger.Ping") + slog.InfoContext(context.Background(), "failed to close connection in PostgresPinger.Ping", "error", err) } }() diff --git a/lib/client/https_client.go b/lib/client/https_client.go index db980450238b0..66293120843b2 100644 --- a/lib/client/https_client.go +++ b/lib/client/https_client.go @@ -84,7 +84,7 @@ type WebClient struct { // and a the HTTPS failure will be considered final. func (w *WebClient) PostJSONWithFallback(ctx context.Context, endpoint string, val interface{}, allowHTTPFallback bool) (*roundtrip.Response, error) { // First try HTTPS and see how that goes - log.Debugf("Attempting %s", endpoint) + log.DebugContext(ctx, "Attempting request", "endpoint", endpoint) resp, httpsErr := w.Client.PostJSON(ctx, endpoint, val) if httpsErr == nil { // If all went well, then we don't need to do anything else - just return @@ -116,7 +116,7 @@ func (w *WebClient) PostJSONWithFallback(ctx context.Context, endpoint string, v // re-write the endpoint to try HTTP u.Scheme = "http" endpoint = u.String() - log.Warnf("Request for %s/%s falling back to PLAIN HTTP", u.Host, u.Path) + log.WarnContext(ctx, "Request for falling back to PLAIN HTTP", "endpoint", endpoint) return httplib.ConvertResponse(w.Client.PostJSON(ctx, endpoint, val)) } diff --git a/lib/client/interfaces.go b/lib/client/interfaces.go index 23502cb4f561c..b755a98de5970 100644 --- a/lib/client/interfaces.go +++ b/lib/client/interfaces.go @@ -28,6 +28,7 @@ import ( "crypto/tls" "crypto/x509" "fmt" + "log/slog" "strings" "time" @@ -81,6 +82,14 @@ func (idx KeyRingIndex) Match(matchKeyRing KeyRingIndex) bool { (matchKeyRing.Username == "" || matchKeyRing.Username == idx.Username) } +func (idx KeyRingIndex) LogValue() slog.Value { + return slog.GroupValue( + slog.String("proxy", idx.ProxyHost), + slog.String("cluster", idx.ClusterName), + slog.String("username", idx.Username), + ) +} + // TLSCredential holds a signed TLS certificate and matching private key. type TLSCredential struct { // PrivateKey is the private key of the credential. diff --git a/lib/client/keyagent.go b/lib/client/keyagent.go index 741c1f5b989ec..85e095f14a3c1 100644 --- a/lib/client/keyagent.go +++ b/lib/client/keyagent.go @@ -23,6 +23,7 @@ import ( "crypto/x509" "fmt" "io" + "log/slog" "net" "os" "runtime" @@ -30,7 +31,6 @@ import ( "strings" "github.com/gravitational/trace" - "github.com/sirupsen/logrus" "golang.org/x/crypto/ssh" "golang.org/x/crypto/ssh/agent" @@ -40,12 +40,13 @@ import ( "github.com/gravitational/teleport/api/utils/sshutils" "github.com/gravitational/teleport/lib/auth/authclient" "github.com/gravitational/teleport/lib/tlsca" + logutils "github.com/gravitational/teleport/lib/utils/log" ) // LocalKeyAgent holds Teleport certificates for a user connected to a cluster. type LocalKeyAgent struct { // log holds the structured logger. - log *logrus.Entry + log *slog.Logger // ExtendedAgent is the teleport agent agent.ExtendedAgent @@ -120,9 +121,7 @@ func NewLocalAgent(conf LocalAgentConfig) (a *LocalKeyAgent, err error) { conf.Agent = keyring } a = &LocalKeyAgent{ - log: logrus.WithFields(logrus.Fields{ - teleport.ComponentKey: teleport.ComponentKeyAgent, - }), + log: slog.With(teleport.ComponentKey, teleport.ComponentKeyAgent), ExtendedAgent: conf.Agent, clientStore: conf.ClientStore, noHosts: make(map[string]bool), @@ -136,10 +135,10 @@ func NewLocalAgent(conf LocalAgentConfig) (a *LocalKeyAgent, err error) { if shouldAddKeysToAgent(conf.KeysOption) { a.systemAgent = connectToSSHAgent() } else { - log.Debug("Skipping connection to the local ssh-agent.") + log.DebugContext(context.Background(), "Skipping connection to the local ssh-agent.") if !agentSupportsSSHCertificates() && agentIsPresent() { - log.Warn(`Certificate was not loaded into agent because the agent at SSH_AUTH_SOCK does not appear + log.WarnContext(context.Background(), `Certificate was not loaded into agent because the agent at SSH_AUTH_SOCK does not appear to support SSH certificates. To force load the certificate into the running agent, use the --add-keys-to-agent=yes flag.`) } @@ -195,13 +194,15 @@ func (a *LocalKeyAgent) LoadKeyRing(keyRing KeyRing) error { return trace.Wrap(err) } - a.log.Infof("Loading SSH key for user %q and cluster %q.", a.username, keyRing.ClusterName) + a.log.InfoContext(context.Background(), "Loading SSH key", "user", a.username, "cluster", keyRing.ClusterName) agents := []agent.ExtendedAgent{a.ExtendedAgent} if a.systemAgent != nil { if canAddToSystemAgent(agentKey) { agents = append(agents, a.systemAgent) } else { - a.log.Infof("Skipping adding key to SSH system agent for non-standard key type %T", agentKey.PrivateKey) + a.log.InfoContext(context.Background(), "Skipping adding key to SSH system agent for non-standard key type", + "key_type", logutils.TypeAttr(agentKey.PrivateKey), + ) } } @@ -249,14 +250,14 @@ func (a *LocalKeyAgent) UnloadKeyRing(keyRing KeyRingIndex) error { // get a list of all keys in the agent keyList, err := agent.List() if err != nil { - a.log.Warnf("Unable to communicate with agent and list keys: %v", err) + a.log.WarnContext(context.Background(), "Unable to communicate with agent and list keys", "error", err) } // remove any teleport keys we currently have loaded in the agent for this user and proxy for _, agentKey := range keyList { if agentKeyIdx, ok := parseTeleportAgentKeyComment(agentKey.Comment); ok && agentKeyIdx.Match(keyRing) { if err = agent.Remove(agentKey); err != nil { - a.log.Warnf("Unable to communicate with agent and remove key: %v", err) + a.log.WarnContext(context.Background(), "Unable to communicate with agent and remove key", "error", err) } } } @@ -278,14 +279,14 @@ func (a *LocalKeyAgent) UnloadKeys() error { // get a list of all keys in the agent keyList, err := agent.List() if err != nil { - a.log.Warnf("Unable to communicate with agent and list keys: %v", err) + a.log.WarnContext(context.Background(), "Unable to communicate with agent and list keys", "error", err) } // remove any teleport keys we currently have loaded in the agent for _, key := range keyList { if isTeleportAgentKey(key) { if err = agent.Remove(key); err != nil { - a.log.Warnf("Unable to communicate with agent and remove key: %v", err) + a.log.WarnContext(context.Background(), "Unable to communicate with agent and remove key", "error", err) } } } @@ -362,13 +363,15 @@ func (a *LocalKeyAgent) HostKeyCallback(addr string, remote net.Addr, hostKey ss }, FIPS: isFIPS(), } - a.log.Debugf("Checking key: %s.", ssh.MarshalAuthorizedKey(hostKey)) + + ctx := context.Background() + a.log.DebugContext(ctx, "Checking key", "host_key", string(ssh.MarshalAuthorizedKey(hostKey))) err = certChecker.CheckHostKey(addr, remote, hostKey) if err != nil { - a.log.Debugf("Host validation failed: %v.", err) + a.log.DebugContext(ctx, "Host validation failed", "error", err) return trace.Wrap(err) } - a.log.Debugf("Validated host %v.", addr) + a.log.DebugContext(ctx, "Validated host", "host_addr", addr) return nil } @@ -377,12 +380,14 @@ func (a *LocalKeyAgent) HostKeyCallback(addr string, remote net.Addr, hostKey ss // reject the server key. func (a *LocalKeyAgent) checkHostCertificateForClusters(clusters ...string) func(key ssh.PublicKey, addr string) bool { return func(key ssh.PublicKey, addr string) bool { + ctx := context.Background() + // Check the local cache (where all Teleport CAs are placed upon login) to // see if any of them match. var keys []ssh.PublicKey trustedCerts, err := a.clientStore.GetTrustedCerts(a.proxyHost) if err != nil { - a.log.Errorf("Failed to get trusted certs: %v.", err) + a.log.ErrorContext(ctx, "Failed to get trusted certs", "error", err) return false } @@ -395,7 +400,7 @@ func (a *LocalKeyAgent) checkHostCertificateForClusters(clusters ...string) func } key, err := sshutils.ParseAuthorizedKeys(cert.AuthorizedKeys) if err != nil { - a.log.Errorf("Failed to parse authorized keys: %v.", err) + a.log.ErrorContext(ctx, "Failed to parse authorized keys", "error", err) return false } keys = append(keys, key...) @@ -418,25 +423,26 @@ func (a *LocalKeyAgent) checkHostCertificateForClusters(clusters ...string) func // ~/.tsh/known_hosts cache and if not found, prompts the user to accept // or reject. func (a *LocalKeyAgent) checkHostKey(addr string, remote net.Addr, key ssh.PublicKey) error { - var err error + ctx := context.Background() + logger := a.log.With("host_addr", addr) // Unless --insecure flag was given, prohibit public keys or host certs // not signed by Teleport. if !a.insecure { - a.log.Debugf("Host %s presented a public key not signed by Teleport. Rejecting due to insecure mode being OFF.", addr) + logger.DebugContext(ctx, "Host presented a public key not signed by Teleport - Rejecting due to insecure mode being OFF") return trace.BadParameter("host %s presented a public key not signed by Teleport", addr) } - a.log.Warnf("Host %s presented a public key not signed by Teleport. Proceeding due to insecure mode being ON.", addr) + logger.WarnContext(ctx, "Host presented a public key not signed by Teleport - Proceeding due to insecure mode being ON") // Check if this exact host is in the local cache. keys, err := a.clientStore.GetTrustedHostKeys(addr) if err != nil { - a.log.WithError(err).Debugf("Failed to retrieve client's trusted host keys.") + logger.DebugContext(ctx, "Failed to retrieve client's trusted host keys", "error", err) } else { for _, trustedHostKey := range keys { if sshutils.KeysEqual(key, trustedHostKey) { - a.log.Debugf("Verified host %s.", addr) + logger.DebugContext(ctx, "Verified host") return nil } } @@ -456,7 +462,7 @@ func (a *LocalKeyAgent) checkHostKey(addr string, remote net.Addr, key ssh.Publi // If the user trusts the key, store the key in the client trusted certs store. err = a.clientStore.AddTrustedHostKeys(a.proxyHost, addr, key) if err != nil { - a.log.Warnf("Failed to save the host key: %v.", err) + logger.WarnContext(ctx, "Failed to save the host key", "error", err) return trace.Wrap(err) } return nil @@ -547,7 +553,7 @@ func (a *LocalKeyAgent) addKeyRing(keyRing *KeyRing) error { } } else { if !keyRing.EqualPrivateKey(storedKeyRing) { - a.log.Debugf("Deleting obsolete stored keyring with index %+v.", storedKeyRing.KeyRingIndex) + a.log.DebugContext(context.Background(), "Deleting obsolete stored keyring", "keyring_index", storedKeyRing.KeyRingIndex) if err := a.clientStore.DeleteKeyRing(storedKeyRing.KeyRingIndex); err != nil { return trace.Wrap(err) } diff --git a/lib/client/keyagent_test.go b/lib/client/keyagent_test.go index bbd2ae2677dc7..4c0c078e82293 100644 --- a/lib/client/keyagent_test.go +++ b/lib/client/keyagent_test.go @@ -812,7 +812,7 @@ func startDebugAgent(t *testing.T) error { conn, err := listener.Accept() if err != nil { if !utils.IsUseOfClosedNetworkError(err) { - log.Warnf("Unexpected response from listener.Accept: %v", err) + log.WarnContext(context.Background(), "Unexpected response from listener.Accept", "error", err) } return } diff --git a/lib/client/keystore.go b/lib/client/keystore.go index 2cba0d5810825..9215922f5c33b 100644 --- a/lib/client/keystore.go +++ b/lib/client/keystore.go @@ -24,6 +24,7 @@ import ( "errors" "fmt" iofs "io/fs" + "log/slog" "os" "path/filepath" "runtime" @@ -31,7 +32,6 @@ import ( "time" "github.com/gravitational/trace" - "github.com/sirupsen/logrus" "golang.org/x/crypto/ssh" "github.com/gravitational/teleport" @@ -95,7 +95,7 @@ type KeyStore interface { // The FS store uses the file layout outlined in `api/utils/keypaths.go`. type FSKeyStore struct { // log holds the structured logger. - log logrus.FieldLogger + log *slog.Logger // KeyDir is the directory where all keys are stored. KeyDir string @@ -111,7 +111,7 @@ type FSKeyStore struct { func NewFSKeyStore(dirPath string) *FSKeyStore { dirPath = profile.FullProfilePath(dirPath) return &FSKeyStore{ - log: logrus.WithField(teleport.ComponentKey, teleport.ComponentKeyStore), + log: slog.With(teleport.ComponentKey, teleport.ComponentKeyStore), KeyDir: dirPath, } } @@ -225,7 +225,7 @@ func (fs *FSKeyStore) AddKeyRing(keyRing *KeyRing) error { if runtime.GOOS == constants.WindowsOS { ppkFile, err := keyRing.SSHPrivateKey.PPKFile() if err != nil { - fs.log.Debugf("Cannot convert private key to PPK-formatted keypair: %v", err) + fs.log.DebugContext(context.Background(), "Cannot convert private key to PPK-formatted keypair", "error", err) } else { if err := fs.writeBytes(ppkFile, fs.ppkFilePath(keyRing.KeyRingIndex)); err != nil { return trace.Wrap(err) @@ -353,7 +353,10 @@ func tryLockFile(ctx context.Context, path string, lockFn func(string) (func() e case err == nil: return func() { if err := unlock(); err != nil { - log.Errorf("failed to unlock TLS credential at %s: %s", path, err) + log.ErrorContext(ctx, "failed to unlock TLS credential", + "credential_path", path, + "error", err, + ) } }, nil case errors.Is(err, utils.ErrUnsuccessfulLockTry): @@ -447,7 +450,7 @@ func (fs *FSKeyStore) DeleteKeyRing(idx KeyRingIndex) error { // And try to delete kube credentials lockfile in case it exists err := utils.RemoveSecure(fs.kubeCredLockfilePath(idx)) if err != nil && !errors.Is(err, iofs.ErrNotExist) { - log.Debugf("Could not remove kube credentials file: %v", err) + log.DebugContext(context.Background(), "Could not remove kube credentials file", "error", err) } // Clear ClusterName to delete the user certs stored for all clusters. diff --git a/lib/client/known_hosts_migrate.go b/lib/client/known_hosts_migrate.go index bd331dd3c8fb4..26fd22a667d2b 100644 --- a/lib/client/known_hosts_migrate.go +++ b/lib/client/known_hosts_migrate.go @@ -20,9 +20,10 @@ package client import ( "bytes" + "context" + "log/slog" "github.com/gravitational/trace" - "github.com/sirupsen/logrus" "golang.org/x/crypto/ssh" "github.com/gravitational/teleport" @@ -117,7 +118,7 @@ func canPruneOldHostsEntry(oldEntry *knownHostEntry, newEntries []*knownHostEntr // duplicate entry exists. This may modify order of host keys, but will not // change their content. func pruneOldHostKeys(output []string) []string { - log := logrus.WithField(teleport.ComponentKey, teleport.ComponentMigrate) + log := slog.With(teleport.ComponentKey, teleport.ComponentMigrate) var ( oldEntries = make([]*knownHostEntry, 0) @@ -130,7 +131,10 @@ func pruneOldHostKeys(output []string) []string { parsed, err := parseKnownHost(line) if err != nil { // If the line isn't parseable, pass it through. - log.WithError(err).Debugf("Unable to parse known host on line %d, skipping", i+1) + log.DebugContext(context.Background(), "Unable to parse known host, skipping", + "invalid_line_number", i+1, + "error", err, + ) prunedOutput = append(prunedOutput, line) continue } @@ -153,7 +157,7 @@ func pruneOldHostKeys(output []string) []string { // exists. If not, pass it through. for _, entry := range oldEntries { if canPruneOldHostsEntry(entry, newEntries) { - log.Debugf("Pruning old known_hosts entry for %s.", entry.hosts[0]) + log.DebugContext(context.Background(), "Pruning old known_hosts entry for host", "host", entry.hosts[0]) } else { prunedOutput = append(prunedOutput, entry.raw) } diff --git a/lib/client/kube/kube.go b/lib/client/kube/kube.go index dd26866d0938a..85980291f5d25 100644 --- a/lib/client/kube/kube.go +++ b/lib/client/kube/kube.go @@ -17,17 +17,17 @@ package kube import ( + "context" + "github.com/gravitational/trace" - "github.com/sirupsen/logrus" "github.com/gravitational/teleport" "github.com/gravitational/teleport/lib/client" "github.com/gravitational/teleport/lib/tlsca" + logutils "github.com/gravitational/teleport/lib/utils/log" ) -var log = logrus.WithFields(logrus.Fields{ - teleport.ComponentKey: teleport.ComponentKubeClient, -}) +var log = logutils.NewPackageLogger(teleport.ComponentKey, teleport.ComponentKubeClient) // CheckIfCertsAreAllowedToAccessCluster evaluates if the new cert created by the user // to access kubeCluster has at least one kubernetes_user or kubernetes_group @@ -43,7 +43,7 @@ func CheckIfCertsAreAllowedToAccessCluster(k *client.KeyRing, rootCluster, telep return nil } if cred, ok := k.KubeTLSCredentials[kubeCluster]; ok { - log.Debugf("Got TLS cert for Kubernetes cluster %q", kubeCluster) + log.DebugContext(context.Background(), "Got TLS cert for Kubernetes cluster", "kubernetes_cluster", kubeCluster) exist, err := checkIfCertHasKubeGroupsAndUsers(cred.Cert) if err != nil { return trace.Wrap(err) diff --git a/lib/client/kubesession.go b/lib/client/kubesession.go index 5390555369c19..39681989a1abd 100644 --- a/lib/client/kubesession.go +++ b/lib/client/kubesession.go @@ -227,7 +227,7 @@ func (s *KubeSession) pipeInOut(stdout io.Writer, enableEscapeSequences bool, mo handleNonPeerControls(mode, s.term, func() { err := s.stream.ForceTerminate() if err != nil { - log.Debugf("Error sending force termination request: %v", err) + log.DebugContext(context.Background(), "Error sending force termination request", "error", err) fmt.Print("\n\rError while sending force termination request\n\r") } }) diff --git a/lib/client/local_proxy_middleware.go b/lib/client/local_proxy_middleware.go index 781e1ce4fa95b..20b8b9f3e7822 100644 --- a/lib/client/local_proxy_middleware.go +++ b/lib/client/local_proxy_middleware.go @@ -161,7 +161,10 @@ func (c *CertChecker) GetOrIssueCert(ctx context.Context) (tls.Certificate, erro } certTTL := cert.Leaf.NotAfter.Sub(c.clock.Now()).Round(time.Minute) - log.Debugf("Certificate renewed: valid until %s [valid for %v]", cert.Leaf.NotAfter.Format(time.RFC3339), certTTL) + log.DebugContext(ctx, "Certificate renewed", + "valud_until", cert.Leaf.NotAfter.Format(time.RFC3339), + "cert_ttl", certTTL, + ) c.cert = cert return c.cert, nil @@ -209,7 +212,7 @@ func (c *DBCertIssuer) CheckCert(cert *x509.Certificate) error { func (c *DBCertIssuer) IssueCert(ctx context.Context) (tls.Certificate, error) { var accessRequests []string if profile, err := c.Client.ProfileStatus(); err != nil { - log.WithError(err).Warn("unable to load profile, requesting database certs without access requests") + log.WarnContext(ctx, "unable to load profile, requesting database certs without access requests", "error", err) } else { accessRequests = profile.ActiveRequests.AccessRequests } @@ -281,7 +284,7 @@ func (c *AppCertIssuer) CheckCert(cert *x509.Certificate) error { func (c *AppCertIssuer) IssueCert(ctx context.Context) (tls.Certificate, error) { var accessRequests []string if profile, err := c.Client.ProfileStatus(); err != nil { - log.WithError(err).Warn("unable to load profile, requesting app certs without access requests") + log.WarnContext(ctx, "unable to load profile, requesting app certs without access requests", "error", err) } else { accessRequests = profile.ActiveRequests.AccessRequests } @@ -446,7 +449,10 @@ func (r *LocalCertGenerator) ensureValidCA(ctx context.Context) error { } certTTL := time.Until(caTLSCert.Leaf.NotAfter).Round(time.Minute) - log.Debugf("Local CA renewed: valid until %s [valid for %v]", caTLSCert.Leaf.NotAfter.Format(time.RFC3339), certTTL) + log.DebugContext(ctx, "Local CA renewed", + "valid_until", caTLSCert.Leaf.NotAfter.Format(time.RFC3339), + "cert_ttl", certTTL, + ) // Clear cert cache and use CA for hostnames in the CA. r.certsByHost = make(map[string]*tls.Certificate) diff --git a/lib/client/mfa/prompt.go b/lib/client/mfa/prompt.go index c96935c897f18..8adb56a3b262d 100644 --- a/lib/client/mfa/prompt.go +++ b/lib/client/mfa/prompt.go @@ -21,11 +21,11 @@ package mfa import ( "context" "errors" + "log/slog" "strings" "sync" "github.com/gravitational/trace" - log "github.com/sirupsen/logrus" "github.com/gravitational/teleport/api/client/proto" "github.com/gravitational/teleport/api/mfa" @@ -115,9 +115,7 @@ func HandleMFAPromptGoroutines(ctx context.Context, startGoroutines func(context // Surface error immediately. return nil, trace.Wrap(resp.Err) case err != nil: - log. - WithError(err). - Debug("MFA goroutine failed, continuing so other goroutines have a chance to succeed") + slog.DebugContext(ctx, "MFA goroutine failed, continuing so other goroutines have a chance to succeed", "error", err) errs = append(errs, err) // Continue to give the other authn goroutine a chance to succeed. // If both have failed, this will exit the loop. diff --git a/lib/client/profile.go b/lib/client/profile.go index 985266ee3bc75..10e2754c82354 100644 --- a/lib/client/profile.go +++ b/lib/client/profile.go @@ -19,6 +19,7 @@ package client import ( + "context" "net/url" "os" "path/filepath" @@ -27,7 +28,6 @@ import ( "time" "github.com/gravitational/trace" - "github.com/sirupsen/logrus" "github.com/gravitational/teleport" "github.com/gravitational/teleport/api/profile" @@ -109,9 +109,6 @@ func (ms *MemProfileStore) SaveProfile(profile *profile.Profile, makecurrent boo // // The FS store uses the file layout outlined in `api/utils/keypaths.go`. type FSProfileStore struct { - // log holds the structured logger. - log logrus.FieldLogger - // Dir is the directory where all keys are stored. Dir string } @@ -120,7 +117,6 @@ type FSProfileStore struct { func NewFSProfileStore(dirPath string) *FSProfileStore { dirPath = profile.FullProfilePath(dirPath) return &FSProfileStore{ - log: logrus.WithField(teleport.ComponentKey, teleport.ComponentKeyStore), Dir: dirPath, } } @@ -434,14 +430,17 @@ func (p *ProfileStatus) virtualPathFromEnv(kind VirtualPathKind, params VirtualP // If we can't resolve any env vars, this will return garbage which we // should at least warn about. As ugly as this is, arguably making every // profile path lookup fallible is even uglier. - log.Debugf("Could not resolve path to virtual profile entry of type %s "+ - "with parameters %+v.", kind, params) + log.DebugContext(context.Background(), "Could not resolve path to virtual profile entry", + "entry_type", kind, + "parameters", params, + ) virtualPathWarnOnce.Do(func() { - log.Errorf("A virtual profile is in use due to an identity file " + + const msg = "A virtual profile is in use due to an identity file " + "(`-i ...`) but this functionality requires additional files on " + "disk and may fail. Consider using a compatible wrapper " + - "application (e.g. Machine ID) for this command.") + "application (e.g. Machine ID) for this command." + log.ErrorContext(context.Background(), msg) }) return "", false diff --git a/lib/client/session.go b/lib/client/session.go index 1c6cc9bea41e3..8d40ee5ba5675 100644 --- a/lib/client/session.go +++ b/lib/client/session.go @@ -151,7 +151,7 @@ func newSession(ctx context.Context, if ns.terminal.IsAttached() { err = ns.terminal.Resize(int16(terminalSize.Width), int16(terminalSize.Height)) if err != nil { - log.Error(err) + log.ErrorContext(ctx, "Failed to resize terminal", "error", err) } } @@ -179,7 +179,7 @@ func newSession(ctx context.Context, if ns.shouldClearOnExit { if err := ns.terminal.Clear(); err != nil { - log.Warnf("Failed to clear screen: %v.", err) + log.WarnContext(ctx, "Failed to clear screen", "error", err) } } ns.terminal.Close() @@ -247,7 +247,7 @@ func (ns *NodeSession) createServerSession(ctx context.Context, chanReqCallback } if err := sess.SetEnvs(ctx, envs); err != nil { - log.Warn(err) + log.WarnContext(ctx, "Failed to set environment variabls", "error", err) } // if agent forwarding was requested (and we have a agent to forward), @@ -256,7 +256,7 @@ func (ns *NodeSession) createServerSession(ctx context.Context, chanReqCallback targetAgent := selectKeyAgent(tc) if targetAgent != nil { - log.Debugf("Forwarding Selected Key Agent") + log.DebugContext(ctx, "Forwarding Selected Key Agent") err = agent.ForwardToAgent(ns.nodeClient.Client.Client, targetAgent) if err != nil { return nil, trace.Wrap(err) @@ -275,13 +275,13 @@ func (ns *NodeSession) createServerSession(ctx context.Context, chanReqCallback func selectKeyAgent(tc *TeleportClient) agent.ExtendedAgent { switch tc.ForwardAgent { case ForwardAgentYes: - log.Debugf("Selecting system key agent.") + log.DebugContext(context.Background(), "Selecting system key agent") return connectToSSHAgent() case ForwardAgentLocal: - log.Debugf("Selecting local Teleport key agent.") + log.DebugContext(context.Background(), "Selecting local Teleport key agent") return tc.localAgent.ExtendedAgent default: - log.Debugf("No Key Agent selected.") + log.DebugContext(context.Background(), "No Key Agent selected") return nil } } @@ -355,7 +355,7 @@ func (ns *NodeSession) allocateTerminal(ctx context.Context, termType string, s if ns.terminal.IsAttached() { realWidth, realHeight, err := ns.terminal.Size() if err != nil { - log.Error(err) + log.ErrorContext(ctx, "Unable to determine terminal size", "error", err) } else { width = int(realWidth) height = int(realHeight) @@ -390,7 +390,7 @@ func (ns *NodeSession) allocateTerminal(ctx context.Context, termType string, s } go func() { if _, err := io.Copy(ns.nodeClient.TC.Stderr, stderr); err != nil { - log.Debugf("Error reading remote STDERR: %v", err) + log.DebugContext(ctx, "Error reading remote STDERR", "error", err) } }() return utils.NewPipeNetConn( @@ -407,7 +407,7 @@ func (ns *NodeSession) updateTerminalSize(ctx context.Context, s *tracessh.Sessi lastWidth, lastHeight, err := ns.terminal.Size() if err != nil { - log.Errorf("Unable to get window size: %v", err) + log.ErrorContext(ctx, "Unable to get window size", "error", err) return } @@ -432,7 +432,7 @@ func (ns *NodeSession) updateTerminalSize(ctx context.Context, s *tracessh.Sessi currWidth, currHeight, err := ns.terminal.Size() if err != nil { - log.Warnf("Unable to get window size: %v.", err) + log.WarnContext(ctx, "Unable to get window size", "error", err) continue } @@ -443,11 +443,16 @@ func (ns *NodeSession) updateTerminalSize(ctx context.Context, s *tracessh.Sessi // Send the "window-change" request over the channel. if err = s.WindowChange(ctx, int(currHeight), int(currWidth)); err != nil { - log.Warnf("Unable to send %v request: %v.", sshutils.WindowChangeRequest, err) + log.WarnContext(ctx, "Unable to send window change request", "error", err) continue } - log.Debugf("Updated window size from (%d, %d) to (%d, %d) due to SIGWINCH.", lastWidth, lastHeight, currWidth, currHeight) + log.DebugContext(ctx, "Updated window size from due to SIGWINCH.", + "original_width", lastWidth, + "original_height", lastHeight, + "current_width", currWidth, + "current_height", currHeight, + ) lastWidth, lastHeight = currWidth, currHeight @@ -460,14 +465,18 @@ func (ns *NodeSession) updateTerminalSize(ctx context.Context, s *tracessh.Sessi terminalParams, err := session.UnmarshalTerminalParams(event.GetString(events.TerminalSize)) if err != nil { - log.Warnf("Unable to unmarshal terminal parameters: %v.", err) + log.WarnContext(ctx, "Unable to unmarshal terminal parameters", "error", err) continue } lastSize := terminalParams.Winsize() lastWidth = int16(lastSize.Width) lastHeight = int16(lastSize.Height) - log.Debugf("Received window size %v from node in session %v.", lastSize, event.GetString(events.SessionEventID)) + log.DebugContext(ctx, "Received window size from node in session", + "width", lastSize.Width, + "height", lastSize.Height, + "session_id", event.GetString(events.SessionEventID), + ) // Update size of local terminal with the last size received from remote server. case <-tickerCh.C: @@ -475,7 +484,7 @@ func (ns *NodeSession) updateTerminalSize(ctx context.Context, s *tracessh.Sessi // received. currWidth, currHeight, err := ns.terminal.Size() if err != nil { - log.Warnf("Unable to get current terminal size: %v.", err) + log.WarnContext(ctx, "Unable to get current terminal size", "error", err) continue } @@ -488,11 +497,16 @@ func (ns *NodeSession) updateTerminalSize(ctx context.Context, s *tracessh.Sessi // the window. err = ns.terminal.Resize(lastWidth, lastHeight) if err != nil { - log.Warnf("Unable to update terminal size: %v.", err) + log.WarnContext(ctx, "Unable to update terminal size", "error", err) continue } - log.Debugf("Updated window size from (%d, %d) to (%d, %d) due to remote window change.", currWidth, currHeight, lastWidth, lastHeight) + log.DebugContext(ctx, "Updated window size due to remote window change", + "original_width", lastWidth, + "original_height", lastHeight, + "current_width", currWidth, + "current_height", currHeight, + ) case <-ns.closer.C: return } @@ -602,10 +616,10 @@ func (ns *NodeSession) runCommand(ctx context.Context, mode types.SessionPartici // Ctrl-C. case <-ctx.Done(): if err := s.Close(); err != nil { - log.Debugf("Unable to close SSH channel: %v", err) + log.DebugContext(ctx, "Unable to close SSH channel", "error", err) } if err := ns.NodeClient().Client.Close(); err != nil { - log.Debugf("Unable to close SSH client: %v", err) + log.DebugContext(ctx, "Unable to close SSH client", "error", err) } return trace.ConnectionProblem(ctx.Err(), "connection canceled") } @@ -640,7 +654,7 @@ func (ns *NodeSession) watchSignals(shell io.Writer) { case <-ctrlCSignal: _, err := shell.Write([]byte{ctrlCharC}) if err != nil { - log.Error(err.Error()) + log.ErrorContext(context.Background(), "Failed to forward ctrl+c", "error", err) } case <-ns.closer.C: return @@ -656,7 +670,7 @@ func (ns *NodeSession) watchSignals(shell io.Writer) { if _, ok := event.(terminal.StopEvent); ok { _, err := shell.Write([]byte{ctrlCharZ}) if err != nil { - log.Error(err.Error()) + log.ErrorContext(context.Background(), "Failed to forward ctrl+z", "error", err) } } } @@ -698,7 +712,7 @@ func handlePeerControls(term *terminal.Terminal, enableEscapeSequences bool, rem // by tsh. These can be used to force a client disconnect since CTRL-C is merely passed // to the other end and not interpreted as an exit request locally stdin = escape.NewReader(stdin, term.Stderr(), func(err error) { - log.Debugf("escape.NewReader error: %v", err) + log.DebugContext(context.Background(), "escape.NewReader error", "error", err) switch { case errors.Is(err, escape.ErrDisconnect): @@ -713,7 +727,7 @@ func handlePeerControls(term *terminal.Terminal, enableEscapeSequences bool, rem _, err := io.Copy(remoteStdin, stdin) if err != nil { - log.Debugf("Error copying data to remote peer: %v", err) + log.DebugContext(context.Background(), "Error copying data to remote peer", "error", err) fmt.Fprint(term.Stderr(), "\r\nError copying data to remote peer\r\n") forceDisconnect = true } @@ -728,8 +742,8 @@ func (ns *NodeSession) pipeInOut(ctx context.Context, shell io.ReadWriteCloser, go func() { defer ns.closer.Close() _, err := io.Copy(ns.terminal.Stdout(), shell) - if err != nil { - log.Error(err.Error()) + if err != nil && !utils.IsOKNetworkError(err) { + log.ErrorContext(ctx, "Failed copying data to session", "error", err) } }() diff --git a/lib/client/terminal/terminal_common.go b/lib/client/terminal/terminal_common.go index fe51fdc7f6f2b..11e9f00e66b20 100644 --- a/lib/client/terminal/terminal_common.go +++ b/lib/client/terminal/terminal_common.go @@ -23,14 +23,12 @@ import ( "sync" "github.com/gravitational/trace" - "github.com/sirupsen/logrus" "github.com/gravitational/teleport" + logutils "github.com/gravitational/teleport/lib/utils/log" ) -var log = logrus.WithFields(logrus.Fields{ - teleport.ComponentKey: teleport.ComponentClient, -}) +var log = logutils.NewPackageLogger(teleport.ComponentKey, teleport.ComponentClient) // ResizeEvent is emitted when a terminal window is resized. type ResizeEvent struct{} diff --git a/lib/client/terminal/terminal_unix.go b/lib/client/terminal/terminal_unix.go index 479ddfcfc492d..98da0332a4205 100644 --- a/lib/client/terminal/terminal_unix.go +++ b/lib/client/terminal/terminal_unix.go @@ -22,9 +22,10 @@ package terminal import ( - "bytes" + "context" "fmt" "io" + "log/slog" "os" "os/signal" "sync" @@ -32,9 +33,9 @@ import ( "github.com/gravitational/trace" "github.com/moby/term" - "github.com/sirupsen/logrus" "github.com/gravitational/teleport/lib/utils" + logutils "github.com/gravitational/teleport/lib/utils/log" ) // Terminal is used to configure raw input and output modes for an attached @@ -80,26 +81,6 @@ func New(stdin io.Reader, stdout, stderr io.Writer) (*Terminal, error) { return &term, nil } -// addCRFormatter is a formatter which adds carriage return (CR) to the output of a base formatter. -// This is needed in case the logger output is fed into terminal in raw mode. -type addCRFormatter struct { - BaseFmt logrus.Formatter -} - -func (r addCRFormatter) Format(entry *logrus.Entry) ([]byte, error) { - out, err := r.BaseFmt.Format(entry) - if err != nil { - return nil, err - } - - replaced := bytes.ReplaceAll(out, []byte("\n"), []byte("\r\n")) - return replaced, nil -} - -func newCRFormatter(baseFmt logrus.Formatter) *addCRFormatter { - return &addCRFormatter{BaseFmt: baseFmt} -} - // InitRaw puts the terminal into raw mode. On Unix, no special input handling // is required beyond simply reading from stdin, so `input` has no effect. // Note that some implementations may replace one or more streams (particularly @@ -107,17 +88,18 @@ func newCRFormatter(baseFmt logrus.Formatter) *addCRFormatter { func (t *Terminal) InitRaw(input bool) error { // Put the terminal into raw mode. ts, err := term.SetRawTerminal(0) - fmtNew := newCRFormatter(logrus.StandardLogger().Formatter) - logrus.StandardLogger().Formatter = fmtNew + + originalHandler := slog.Default().Handler() + slog.SetDefault(slog.New(logutils.DiscardHandler{})) if err != nil { - log.Warnf("Could not put terminal into raw mode: %v", err) + log.WarnContext(context.Background(), "Could not put terminal into raw mode", "error", err) } else { // Ensure the terminal is reset on exit. t.closeWait.Add(1) go func() { <-t.closer.C term.RestoreTerminal(0, ts) - logrus.StandardLogger().Formatter = fmtNew.BaseFmt + slog.SetDefault(slog.New(originalHandler)) t.closeWait.Done() }() } diff --git a/lib/client/terminal/terminal_unix_test.go b/lib/client/terminal/terminal_unix_test.go deleted file mode 100644 index fe0fc2d586b3e..0000000000000 --- a/lib/client/terminal/terminal_unix_test.go +++ /dev/null @@ -1,86 +0,0 @@ -/* - * Teleport - * Copyright (C) 2023 Gravitational, Inc. - * - * This program is free software: you can redistribute it and/or modify - * it under the terms of the GNU Affero General Public License as published by - * the Free Software Foundation, either version 3 of the License, or - * (at your option) any later version. - * - * This program is distributed in the hope that it will be useful, - * but WITHOUT ANY WARRANTY; without even the implied warranty of - * MERCHANTABILITY or FITNESS FOR A PARTICULAR PURPOSE. See the - * GNU Affero General Public License for more details. - * - * You should have received a copy of the GNU Affero General Public License - * along with this program. If not, see . - */ - -package terminal - -import ( - "fmt" - "testing" - - "github.com/sirupsen/logrus" - "github.com/stretchr/testify/require" -) - -// fixedDummyFmt is dummy formatter which ignores entry argument in Format() call and returns the same value, always. -type fixedDummyFmt struct { - bytes []byte - err error -} - -func (r fixedDummyFmt) Format(entry *logrus.Entry) ([]byte, error) { - return r.bytes, r.err -} - -func Test_addCRFormatter(t *testing.T) { - tests := []struct { - name string - input string - output string - wantErr bool - }{ - { - name: "no newlines", - input: "foo bar baz", - output: "foo bar baz", - }, - { - name: "single newline", - input: "foo bar baz\n", - output: "foo bar baz\r\n", - }, - { - name: "multiple newlines", - input: "foo\nbar\nbaz\n", - output: "foo\r\nbar\r\nbaz\r\n", - }, - { - name: "propagate error", - wantErr: true, - }, - } - - for _, tt := range tests { - t.Run(tt.name, func(t *testing.T) { - baseFmt := fixedDummyFmt{bytes: []byte(tt.input)} - if tt.wantErr { - baseFmt.err = fmt.Errorf("dummy") - } - - r := newCRFormatter(baseFmt) - actual, err := r.Format(nil) - - if tt.wantErr { - require.Error(t, err) - } else { - require.NoError(t, err) - require.Equal(t, tt.output, string(actual)) - } - - }) - } -} diff --git a/lib/client/terminal/terminal_windows.go b/lib/client/terminal/terminal_windows.go index 9a9f71051310a..3c9e51ab9e229 100644 --- a/lib/client/terminal/terminal_windows.go +++ b/lib/client/terminal/terminal_windows.go @@ -19,6 +19,7 @@ package terminal import ( + "context" "fmt" "io" "os" @@ -76,7 +77,10 @@ func initTerminal(input bool) (func(), error) { // Attempt to reset the stdout mode before returning. err = winterm.SetConsoleMode(uintptr(stdoutFd), oldOutMode) if err != nil { - log.Errorf("Failed to reset terminal output mode to %d: %v\n", oldOutMode, err) + log.ErrorContext(context.Background(), "Failed to reset terminal output mode", + "original_output_mode", oldOutMode, + "error", err, + ) } return func() {}, fmt.Errorf("failed to set stdin mode: %w", err) @@ -86,13 +90,19 @@ func initTerminal(input bool) (func(), error) { return func() { err := winterm.SetConsoleMode(uintptr(stdoutFd), oldOutMode) if err != nil { - log.Errorf("Failed to reset terminal output mode to %d: %v\n", oldOutMode, err) + log.ErrorContext(context.Background(), "Failed to reset terminal output mode", + "original_output_mode", oldOutMode, + "error", err, + ) } if input { err = winterm.SetConsoleMode(uintptr(stdinFd), oldInMode) if err != nil { - log.Errorf("Failed to reset terminal input mode to %d: %v\n", oldInMode, err) + log.ErrorContext(context.Background(), "Failed to reset terminal input mode", + "original_input_mode", oldInMode, + "error", err, + ) } } }, nil diff --git a/lib/client/trusted_certs_store.go b/lib/client/trusted_certs_store.go index bb270e5ea1aa3..24dede0c3a9c3 100644 --- a/lib/client/trusted_certs_store.go +++ b/lib/client/trusted_certs_store.go @@ -25,13 +25,13 @@ import ( "encoding/pem" "fmt" iofs "io/fs" + "log/slog" "os" "path/filepath" "strings" "time" "github.com/gravitational/trace" - "github.com/sirupsen/logrus" "golang.org/x/crypto/ssh" "github.com/gravitational/teleport" @@ -161,7 +161,7 @@ func (ms *MemTrustedCertsStore) GetTrustedHostKeys(hostnames ...string) ([]ssh.P // The FS store uses the file layout outlined in `api/utils/keypaths.go`. type FSTrustedCertsStore struct { // log holds the structured logger. - log logrus.FieldLogger + log *slog.Logger // Dir is the directory where all keys are stored. Dir string @@ -171,7 +171,7 @@ type FSTrustedCertsStore struct { func NewFSTrustedCertsStore(dirPath string) *FSTrustedCertsStore { dirPath = profile.FullProfilePath(dirPath) return &FSTrustedCertsStore{ - log: logrus.WithField(teleport.ComponentKey, teleport.ComponentKeyStore), + log: slog.With(teleport.ComponentKey, teleport.ComponentKeyStore), Dir: dirPath, } } @@ -296,7 +296,7 @@ func (fs *FSTrustedCertsStore) saveTrustedCertsInCASDir(proxyHost string, cas [] } // check if cluster name is safe and doesn't contain miscellaneous characters. if strings.Contains(ca.ClusterName, "..") { - fs.log.Warnf("Skipped unsafe cluster name: %q", ca.ClusterName) + fs.log.WarnContext(context.Background(), "Skipped unsafe cluster name", "cluster_name", ca.ClusterName) continue } // Create CA files in cas dir for each cluster. @@ -392,7 +392,10 @@ func (fs *FSTrustedCertsStore) addKnownHosts(proxyHost string, cas []authclient. // add every host key to the list of entries for _, ca := range cas { for _, hostKey := range ca.AuthorizedKeys { - fs.log.Debugf("Adding known host %s with proxy %s", ca.ClusterName, proxyHost) + fs.log.DebugContext(context.Background(), "Adding known host entry", + "cluster_name", ca.ClusterName, + "proxy", proxyHost, + ) // Write keys in an OpenSSH-compatible format. A previous format was not // quite OpenSSH-compatible, so we may write a duplicate entry here. Any @@ -467,7 +470,10 @@ func (fs *FSTrustedCertsStore) GetTrustedCertsPEM(proxyHost string) ([][]byte, e break } if block.Type != "CERTIFICATE" || len(block.Headers) != 0 { - fs.log.Debugf("Skipping PEM block type=%v headers=%v.", block.Type, block.Headers) + fs.log.DebugContext(context.Background(), "Skipping PEM block", + "type", block.Type, + "headers", block.Headers, + ) data = rest continue } diff --git a/lib/client/weblogin.go b/lib/client/weblogin.go index c3415e340417d..668f22b45a903 100644 --- a/lib/client/weblogin.go +++ b/lib/client/weblogin.go @@ -27,6 +27,7 @@ import ( "encoding/json" "fmt" "io" + "log/slog" "net" "net/http" "net/http/cookiejar" @@ -37,7 +38,6 @@ import ( "github.com/go-webauthn/webauthn/protocol" "github.com/gravitational/roundtrip" "github.com/gravitational/trace" - "github.com/sirupsen/logrus" "github.com/gravitational/teleport" "github.com/gravitational/teleport/api/client/proto" @@ -547,16 +547,18 @@ type TOTPRegisterChallenge struct { // initClient creates a new client to the HTTPS web proxy. func initClient(proxyAddr string, insecure bool, pool *x509.CertPool, extraHeaders map[string]string, opts ...roundtrip.ClientParam) (*WebClient, *url.URL, error) { - log := logrus.WithFields(logrus.Fields{ - teleport.ComponentKey: teleport.ComponentClient, - }) - log.Debugf("HTTPS client init(proxyAddr=%v, insecure=%v, extraHeaders=%v)", proxyAddr, insecure, extraHeaders) + log := slog.With(teleport.ComponentKey, teleport.ComponentClient) + log.DebugContext(context.Background(), "Initializing proxy HTTPS client", + "proxy_addr", proxyAddr, + "insecure", insecure, + "extra_headers", extraHeaders, + ) // validate proxy address host, port, err := net.SplitHostPort(proxyAddr) if err != nil || host == "" || port == "" { if err != nil { - log.Error(err) + log.ErrorContext(context.Background(), "invalid proxy address", "error", err) } return nil, nil, trace.BadParameter("'%v' is not a valid proxy address", proxyAddr) } diff --git a/lib/client/weblogin_test.go b/lib/client/weblogin_test.go index 39722c78c2efe..cca05b892fe2b 100644 --- a/lib/client/weblogin_test.go +++ b/lib/client/weblogin_test.go @@ -121,7 +121,6 @@ func newServer(handler http.HandlerFunc, loopback bool) (*httptest.Server, error func TestSSHAgentPasswordlessLogin(t *testing.T) { t.Parallel() - silenceLogger(t) clock := clockwork.NewFakeClockAt(time.Now()) sa := newStandaloneTeleport(t, clock)