From fd91d28b610aad0520b58f317ee26659f2a2630d Mon Sep 17 00:00:00 2001 From: Tim Ross Date: Fri, 6 Dec 2024 16:54:01 -0500 Subject: [PATCH] Convert lib/srv to use slog This migrates the rest of the srv package to use slog for logging. Most sub-packages still however rely on logrus. --- lib/srv/ctx.go | 82 +++++++++++------------ lib/srv/ctx_test.go | 2 +- lib/srv/exec.go | 42 ++++++------ lib/srv/forward/sshserver.go | 26 ++++---- lib/srv/mock.go | 3 +- lib/srv/reexec.go | 38 ++++++----- lib/srv/regular/sftp.go | 2 +- lib/srv/regular/sshserver.go | 105 +++++++++++++++--------------- lib/srv/regular/sshserver_test.go | 14 +--- lib/srv/sess.go | 36 +++++----- lib/srv/sess_test.go | 2 +- lib/srv/term.go | 49 +++++++------- lib/srv/termhandlers.go | 6 +- lib/srv/usermgmt_linux.go | 10 +-- 14 files changed, 204 insertions(+), 213 deletions(-) diff --git a/lib/srv/ctx.go b/lib/srv/ctx.go index 60f9a0ae660c1..3318b3755f92c 100644 --- a/lib/srv/ctx.go +++ b/lib/srv/ctx.go @@ -34,7 +34,6 @@ import ( "github.com/gravitational/trace" "github.com/jonboulle/clockwork" "github.com/prometheus/client_golang/prometheus" - log "github.com/sirupsen/logrus" "golang.org/x/crypto/ssh" "github.com/gravitational/teleport" @@ -265,7 +264,7 @@ type ServerContext struct { // ConnectionContext is the parent context which manages connection-level // resources. *sshutils.ConnectionContext - *log.Entry + Logger *slog.Logger mu sync.RWMutex @@ -434,17 +433,14 @@ func NewServerContext(ctx context.Context, parent *sshutils.ConnectionContext, s ServerSubKind: srv.TargetMetadata().ServerSubKind, } - fields := log.Fields{ - "local": child.ServerConn.LocalAddr(), - "remote": child.ServerConn.RemoteAddr(), - "login": child.Identity.Login, - "teleportUser": child.Identity.TeleportUser, - "id": child.id, - } - child.Entry = log.WithFields(log.Fields{ - teleport.ComponentKey: child.srv.Component(), - teleport.ComponentFields: fields, - }) + child.Logger = slog.With( + teleport.ComponentKey, srv.Component(), + "local_addr", child.ServerConn.LocalAddr(), + "remote_addr", child.ServerConn.RemoteAddr(), + "login", child.Identity.Login, + "teleport_user", child.Identity.TeleportUser, + "id", child.id, + ) if identityContext.Login == teleport.SSHSessionJoinPrincipal { child.JoinOnly = true @@ -462,15 +458,11 @@ func NewServerContext(ctx context.Context, parent *sshutils.ConnectionContext, s // Update log entry fields. if !child.disconnectExpiredCert.IsZero() { - fields["cert"] = child.disconnectExpiredCert + child.Logger = child.Logger.With("cert", child.disconnectExpiredCert) } if child.clientIdleTimeout != 0 { - fields["idle"] = child.clientIdleTimeout + child.Logger = child.Logger.With("idle", child.clientIdleTimeout) } - child.Entry = log.WithFields(log.Fields{ - teleport.ComponentKey: srv.Component(), - teleport.ComponentFields: fields, - }) clusterName, err := srv.GetAccessPoint().GetClusterName() if err != nil { @@ -491,11 +483,9 @@ func NewServerContext(ctx context.Context, parent *sshutils.ConnectionContext, s TeleportUser: child.Identity.TeleportUser, Login: child.Identity.Login, ServerID: child.srv.ID(), - // TODO(tross) update this to use the child logger - // once ServerContext is converted to use a slog.Logger - Logger: slog.Default(), - Emitter: child.srv, - EmitterContext: ctx, + Logger: child.Logger, + Emitter: child.srv, + EmitterContext: ctx, } for _, opt := range monitorOpts { opt(&monitorConfig) @@ -573,7 +563,7 @@ func (c *ServerContext) GetServer() Server { // CreateOrJoinSession will look in the SessionRegistry for the session ID. If // no session is found, a new one is created. If one is found, it is returned. -func (c *ServerContext) CreateOrJoinSession(reg *SessionRegistry) error { +func (c *ServerContext) CreateOrJoinSession(ctx context.Context, reg *SessionRegistry) error { c.mu.Lock() defer c.mu.Unlock() // As SSH conversation progresses, at some point a session will be created and @@ -581,7 +571,7 @@ func (c *ServerContext) CreateOrJoinSession(reg *SessionRegistry) error { ssid, found := c.getEnvLocked(sshutils.SessionEnvVar) if !found { c.sessionID = rsession.NewID() - c.Logger.Debugf("Will create new session for SSH connection %v.", c.ServerConn.RemoteAddr()) + c.Logger.DebugContext(ctx, "Will create new session for SSH connection") return nil } @@ -595,7 +585,7 @@ func (c *ServerContext) CreateOrJoinSession(reg *SessionRegistry) error { if sess, found := reg.findSession(*id); found { c.sessionID = *id c.session = sess - c.Logger.Debugf("Will join session %v for SSH connection %v.", c.session.id, c.ServerConn.RemoteAddr()) + c.Logger.DebugContext(ctx, "Joining active SSH session", "session_id", c.session.id) } else { // TODO(capnspacehook): DELETE IN 17.0.0 - by then all supported // clients should only set TELEPORT_SESSION when they want to @@ -605,7 +595,7 @@ func (c *ServerContext) CreateOrJoinSession(reg *SessionRegistry) error { // to prevent the user from controlling the session ID, generate // a new one c.sessionID = rsession.NewID() - c.Logger.Debugf("Will create new session for SSH connection %v.", c.ServerConn.RemoteAddr()) + c.Logger.DebugContext(ctx, "Creating new SSH session") } return nil @@ -676,7 +666,7 @@ func (c *ServerContext) getEnvLocked(key string) (string, bool) { } // setSession sets the context's session -func (c *ServerContext) setSession(sess *session, ch ssh.Channel) { +func (c *ServerContext) setSession(ctx context.Context, sess *session, ch ssh.Channel) { c.mu.Lock() defer c.mu.Unlock() c.session = sess @@ -684,10 +674,10 @@ func (c *ServerContext) setSession(sess *session, ch ssh.Channel) { // inform the client of the session ID that is being used in a new // goroutine to reduce latency go func() { - c.Logger.Debug("Sending current session ID.") + c.Logger.DebugContext(ctx, "Sending current session ID") _, err := ch.SendRequest(teleport.CurrentSessionIDRequest, false, []byte(sess.ID())) if err != nil { - c.Logger.WithError(err).Debug("Failed to send the current session ID.") + c.Logger.DebugContext(ctx, "Failed to send the current session ID", "error", err) } }() } @@ -754,7 +744,7 @@ func (c *ServerContext) CheckSFTPAllowed(registry *SessionRegistry) error { } // OpenXServerListener opens a new XServer unix listener. -func (c *ServerContext) HandleX11Listener(l net.Listener, singleConnection bool) error { +func (c *ServerContext) HandleX11Listener(ctx context.Context, l net.Listener, singleConnection bool) error { display, err := x11.ParseDisplayFromUnixSocket(l.Addr().String()) if err != nil { return trace.Wrap(err) @@ -780,7 +770,7 @@ func (c *ServerContext) HandleX11Listener(l net.Listener, singleConnection bool) xconn, err := l.Accept() if err != nil { if !utils.IsOKNetworkError(err) { - c.Logger.WithError(err).Debug("Encountered error accepting XServer connection") + c.Logger.DebugContext(ctx, "Encountered error accepting XServer connection", "error", err) } return } @@ -790,7 +780,7 @@ func (c *ServerContext) HandleX11Listener(l net.Listener, singleConnection bool) xchan, sin, err := c.ServerConn.OpenChannel(x11.ChannelRequest, x11ChannelReqPayload) if err != nil { - c.Logger.WithError(err).Debug("Failed to open a new X11 channel") + c.Logger.DebugContext(ctx, "Failed to open a new X11 channel", "error", err) return } defer xchan.Close() @@ -802,12 +792,12 @@ func (c *ServerContext) HandleX11Listener(l net.Listener, singleConnection bool) go func() { err := sshutils.ForwardRequests(ctx, sin, c.RemoteSession) if err != nil { - c.Logger.WithError(err).Debug("Failed to forward ssh request from server during X11 forwarding") + c.Logger.DebugContext(ctx, "Failed to forward ssh request from server during X11 forwarding", "error", err) } }() if err := utils.ProxyConn(ctx, xconn, xchan); err != nil { - c.Logger.WithError(err).Debug("Encountered error during X11 forwarding") + c.Logger.DebugContext(ctx, "Encountered error during X11 forwarding", "error", err) } }() @@ -884,7 +874,7 @@ func (c *ServerContext) reportStats(conn utils.Stater) { sessionDataEvent.ConnectionMetadata.LocalAddr = c.ServerConn.LocalAddr().String() } if err := c.GetServer().EmitAuditEvent(c.GetServer().Context(), sessionDataEvent); err != nil { - c.WithError(err).Warn("Failed to emit session data event.") + c.Logger.WarnContext(c.GetServer().Context(), "Failed to emit session data event", "error", err) } // Emit TX and RX bytes to their respective Prometheus counters. @@ -926,21 +916,21 @@ func (c *ServerContext) CancelFunc() context.CancelFunc { // SendExecResult sends the result of execution of the "exec" command over the // ExecResultCh. -func (c *ServerContext) SendExecResult(r ExecResult) { +func (c *ServerContext) SendExecResult(ctx context.Context, r ExecResult) { select { case c.ExecResultCh <- r: default: - c.Infof("Blocked on sending exec result %v.", r) + c.Logger.InfoContext(ctx, "Blocked on sending exec result", "code", r.Code, "command", r.Command) } } // SendSubsystemResult sends the result of running the subsystem over the // SubsystemResultCh. -func (c *ServerContext) SendSubsystemResult(r SubsystemResult) { +func (c *ServerContext) SendSubsystemResult(ctx context.Context, r SubsystemResult) { select { case c.SubsystemResultCh <- r: default: - c.Info("Blocked on sending subsystem result.") + c.Logger.InfoContext(ctx, "Blocked on sending subsystem result") } } @@ -1005,7 +995,11 @@ func getPAMConfig(c *ServerContext) (*PAMConfig, error) { // If the trait isn't passed by the IdP due to misconfiguration // we fallback to setting a value which will indicate this. if trace.IsNotFound(err) { - c.Logger.WithError(err).Warnf("Attempted to interpolate custom PAM environment with external trait but received SAML response does not contain claim") + c.Logger.WarnContext( + c.CancelContext(), + "Attempted to interpolate custom PAM environment with external trait but received SAML response does not contain claim", + "error", err, + ) continue } @@ -1120,11 +1114,11 @@ func buildEnvironment(ctx *ServerContext) []string { // SSH_CONNECTION environment variables. remoteHost, remotePort, err := net.SplitHostPort(ctx.ServerConn.RemoteAddr().String()) if err != nil { - ctx.Logger.Debugf("Failed to split remote address: %v.", err) + ctx.Logger.DebugContext(ctx.CancelContext(), "Failed to split remote address", "error", err) } else { localHost, localPort, err := net.SplitHostPort(ctx.ServerConn.LocalAddr().String()) if err != nil { - ctx.Logger.Debugf("Failed to split local address: %v.", err) + ctx.Logger.DebugContext(ctx.CancelContext(), "Failed to split local address", "error", err) } else { env.AddTrusted("SSH_CLIENT", fmt.Sprintf("%s %s %s", remoteHost, remotePort, localPort)) env.AddTrusted("SSH_CONNECTION", fmt.Sprintf("%s %s %s %s", remoteHost, remotePort, localHost, localPort)) diff --git a/lib/srv/ctx_test.go b/lib/srv/ctx_test.go index 770f6e36e860e..f4c7554908646 100644 --- a/lib/srv/ctx_test.go +++ b/lib/srv/ctx_test.go @@ -366,7 +366,7 @@ func TestCreateOrJoinSession(t *testing.T) { ctx.SetEnv(sshutils.SessionEnvVar, tt.sessionID) } - err = ctx.CreateOrJoinSession(registry) + err = ctx.CreateOrJoinSession(context.Background(), registry) require.NoError(t, err) require.False(t, ctx.sessionID.IsZero()) if tt.wantSameSessionID { diff --git a/lib/srv/exec.go b/lib/srv/exec.go index 694bd6ddb1776..6728b27d5748b 100644 --- a/lib/srv/exec.go +++ b/lib/srv/exec.go @@ -24,6 +24,7 @@ import ( "errors" "fmt" "io" + "log/slog" "os" "os/exec" "path/filepath" @@ -34,7 +35,6 @@ import ( "time" "github.com/gravitational/trace" - log "github.com/sirupsen/logrus" "golang.org/x/crypto/ssh" "github.com/gravitational/teleport" @@ -147,6 +147,8 @@ func (e *localExec) SetCommand(command string) { // Start launches the given command returns (nil, nil) if successful. // ExecResult is only used to communicate an error while launching. func (e *localExec) Start(ctx context.Context, channel ssh.Channel) (*ExecResult, error) { + logger := e.Ctx.Logger.With("command", e.GetCommand()) + // Parse the command to see if it is scp. err := e.transformSecureCopy() if err != nil { @@ -172,7 +174,7 @@ func (e *localExec) Start(ctx context.Context, channel ssh.Channel) (*ExecResult // Start the command. err = e.Cmd.Start() if err != nil { - e.Ctx.Warningf("Local command %v failed to start: %v", e.GetCommand(), err) + logger.WarnContext(ctx, "Local command failed to start", "error", err) // Emit the result of execution to the audit log emitExecAuditEvent(e.Ctx, e.GetCommand(), err) @@ -185,18 +187,18 @@ func (e *localExec) Start(ctx context.Context, channel ssh.Channel) (*ExecResult // Close our half of the write pipe since it is only to be used by the child process. // Not closing prevents being signaled when the child closes its half. if err := e.Ctx.readyw.Close(); err != nil { - e.Ctx.Logger.WithError(err).Warn("Failed to close parent process ready signal write fd") + logger.WarnContext(ctx, "Failed to close parent process ready signal write fd", "error", err) } e.Ctx.readyw = nil go func() { if _, err := io.Copy(inputWriter, channel); err != nil { - e.Ctx.Warnf("Failed to forward data from SSH channel to local command %q stdin: %v", e.GetCommand(), err) + logger.WarnContext(ctx, "Failed to forward data from SSH channel to local command", "error", err) } inputWriter.Close() }() - e.Ctx.Infof("Started local command execution: %q", e.Command) + logger.InfoContext(ctx, "Started local command execution") return nil, nil } @@ -204,15 +206,15 @@ func (e *localExec) Start(ctx context.Context, channel ssh.Channel) (*ExecResult // Wait will block while the command executes. func (e *localExec) Wait() *ExecResult { if e.Cmd.Process == nil { - e.Ctx.Error("No process.") + e.Ctx.Logger.ErrorContext(e.Ctx.CancelContext(), "No process") } // Block until the command is finished executing. err := e.Cmd.Wait() if err != nil { - e.Ctx.Debugf("Local command failed: %v.", err) + e.Ctx.Logger.DebugContext(e.Ctx.CancelContext(), "Local command failed", "error", err) } else { - e.Ctx.Debugf("Local command successfully executed.") + e.Ctx.Logger.DebugContext(e.Ctx.CancelContext(), "Local command successfully executed") } // Emit the result of execution to the Audit Log. @@ -255,7 +257,7 @@ func (e *localExec) String() string { func (e *localExec) transformSecureCopy() error { isSCPCmd, err := checkSCPAllowed(e.Ctx, e.GetCommand()) if err != nil { - e.Ctx.GetServer().EmitAuditEvent(context.WithoutCancel(e.Ctx.Context), &apievents.SFTP{ + e.Ctx.GetServer().EmitAuditEvent(e.Ctx.CancelContext(), &apievents.SFTP{ Metadata: apievents.Metadata{ Code: events.SCPDisallowedCode, Type: events.SCPEvent, @@ -384,7 +386,7 @@ func (e *remoteExec) Start(ctx context.Context, ch ssh.Channel) (*ExecResult, er go func() { // copy from the channel (client) into stdin of the process if _, err := io.Copy(inputWriter, ch); err != nil { - e.ctx.Warnf("Failed copying data from SSH channel to remote command stdin: %v", err) + e.ctx.Logger.WarnContext(ctx, "Failed copying data from SSH channel to remote command stdin", "error", err) } inputWriter.Close() }() @@ -402,9 +404,9 @@ func (e *remoteExec) Wait() *ExecResult { // Block until the command is finished executing. err := e.session.Wait() if err != nil { - e.ctx.Debugf("Remote command failed: %v.", err) + e.ctx.Logger.DebugContext(e.ctx.CancelContext(), "Remote command failed", "error", err) } else { - e.ctx.Debugf("Remote command successfully executed.") + e.ctx.Logger.DebugContext(e.ctx.CancelContext(), "Remote command successfully executed") } // Emit the result of execution to the Audit Log. @@ -460,7 +462,7 @@ func emitExecAuditEvent(ctx *ServerContext, cmd string, execErr error) { // Parse the exec command to find out if it was SCP or not. path, action, isSCP, err := parseSecureCopy(cmd) if err != nil { - log.Warnf("Unable to emit audit event: %v.", err) + ctx.Logger.WarnContext(ctx.srv.Context(), "Unable to parse scp command", "error", err) return } @@ -495,7 +497,7 @@ func emitExecAuditEvent(ctx *ServerContext, cmd string, execErr error) { } } if err := ctx.session.emitAuditEvent(ctx.srv.Context(), scpEvent); err != nil { - log.WithError(err).Warn("Failed to emit scp event.") + ctx.Logger.WarnContext(ctx.srv.Context(), "Failed to emit scp event", "error", err) } } else { execEvent := &apievents.Exec{ @@ -515,7 +517,7 @@ func emitExecAuditEvent(ctx *ServerContext, cmd string, execErr error) { execEvent.Code = events.ExecCode } if err := ctx.session.emitAuditEvent(ctx.srv.Context(), execEvent); err != nil { - log.WithError(err).Warn("Failed to emit exec event.") + ctx.Logger.WarnContext(ctx.srv.Context(), "Failed to emit exec event", "error", err) } } } @@ -531,10 +533,10 @@ func getDefaultEnvPath(uid string, loginDefsPath string) string { f, err := utils.OpenFileAllowingUnsafeLinks(loginDefsPath) if err != nil { if uid == "0" { - log.Infof("Unable to open %q: %v: returning default su path: %q", loginDefsPath, err, defaultEnvRootPath) + slog.InfoContext(context.Background(), "Unable to open login.defs, returning default su path", "login_defs_path", loginDefsPath, "error", err, "default_path", defaultEnvRootPath) return defaultEnvRootPath } - log.Infof("Unable to open %q: %v: returning default path: %q", loginDefsPath, err, defaultEnvPath) + slog.InfoContext(context.Background(), "Unable to open login.defs, returning default path", "login_defs_path", loginDefsPath, "error", err, "default_path", defaultEnvPath) return defaultEnvPath } defer f.Close() @@ -565,10 +567,10 @@ func getDefaultEnvPath(uid string, loginDefsPath string) string { err = scanner.Err() if err != nil { if uid == "0" { - log.Warnf("Unable to open %q: %v: returning default su path: %q", loginDefsPath, err, defaultEnvRootPath) + slog.WarnContext(context.Background(), "Unable to read login.defs, returning default su path", "login_defs_path", loginDefsPath, "error", err, "default_path", defaultEnvRootPath) return defaultEnvRootPath } - log.Warnf("Unable to read %q: %v: returning default path: %q", loginDefsPath, err, defaultEnvPath) + slog.WarnContext(context.Background(), "Unable to read login.defs, returning default path", "login_defs_path", loginDefsPath, "error", err, "default_path", defaultEnvPath) return defaultEnvPath } @@ -634,7 +636,7 @@ func exitCode(err error) int { return sshExitErr.ExitStatus() // An error occurred, but the type is unknown, return a generic 255 code. default: - log.Debugf("Unknown error returned when executing command: %T: %v.", err, err) + slog.DebugContext(context.Background(), "Unknown error returned when executing command", "error", err) return teleport.RemoteCommandFailure } } diff --git a/lib/srv/forward/sshserver.go b/lib/srv/forward/sshserver.go index 53b432e0fea5e..574183f32c22c 100644 --- a/lib/srv/forward/sshserver.go +++ b/lib/srv/forward/sshserver.go @@ -1174,7 +1174,7 @@ func (s *Server) handleSessionChannel(ctx context.Context, nch ssh.NewChannel) { for { // Update the context with the session ID. - err := scx.CreateOrJoinSession(s.sessionRegistry) + err := scx.CreateOrJoinSession(ctx, s.sessionRegistry) if err != nil { s.logger.ErrorContext(ctx, "unable create or join session", "error", err) @@ -1243,7 +1243,7 @@ func (s *Server) handleSessionChannel(ctx context.Context, nch ssh.NewChannel) { } func (s *Server) dispatch(ctx context.Context, ch ssh.Channel, req *ssh.Request, scx *srv.ServerContext) error { - s.logger.DebugContext(ctx, "Handling request", "request_type", req.Type, "want_reply", req.WantReply) + scx.Logger.DebugContext(ctx, "Handling request", "request_type", req.Type, "want_reply", req.WantReply) // Certs with a join-only principal can only use a // subset of all the possible request types. @@ -1268,7 +1268,7 @@ func (s *Server) dispatch(ctx context.Context, ch ssh.Channel, req *ssh.Request, // processing requests. err := s.handleAgentForward(ch, req, scx) if err != nil { - s.logger.DebugContext(ctx, "failure forwarding agent", "error", err) + scx.Logger.DebugContext(ctx, "failure forwarding agent", "error", err) } return nil case sshutils.PuTTYWinadjRequest: @@ -1303,16 +1303,16 @@ func (s *Server) dispatch(ctx context.Context, ch ssh.Channel, req *ssh.Request, // processing requests. err := s.handleAgentForward(ch, req, scx) if err != nil { - s.logger.DebugContext(ctx, "failure forwarding agent", "error", err) + scx.Logger.DebugContext(ctx, "failure forwarding agent", "error", err) } return nil case sshutils.PuTTYWinadjRequest: return s.handlePuTTYWinadj(ctx, ch, req) default: - s.logger.WarnContext(ctx, "received unsupported SSH request", "request_type", req.Type) + scx.Logger.WarnContext(ctx, "received unsupported SSH request", "request_type", req.Type) if req.WantReply { if err := req.Reply(false, nil); err != nil { - s.logger.ErrorContext(ctx, "failed sending error reply on SSH channel", "error", err) + scx.Logger.ErrorContext(ctx, "failed sending error reply on SSH channel", "error", err) } } return nil @@ -1430,7 +1430,7 @@ func (s *Server) handleX11Forward(ctx context.Context, ch ssh.Channel, req *ssh. err = nil } if err := s.EmitAuditEvent(ctx, event); err != nil { - s.logger.WarnContext(ctx, "Failed to emit x11-forward event", "error", err) + scx.Logger.WarnContext(ctx, "Failed to emit x11-forward event", "error", err) } }() @@ -1477,7 +1477,7 @@ func (s *Server) handleSubsystem(ctx context.Context, ch ssh.Channel, req *ssh.R // start the requested subsystem, if it fails to start return result right away err = subsystem.Start(ctx, ch) if err != nil { - serverContext.SendSubsystemResult(srv.SubsystemResult{ + serverContext.SendSubsystemResult(ctx, srv.SubsystemResult{ Name: subsystem.subsystemName, Err: trace.Wrap(err), }) @@ -1487,7 +1487,7 @@ func (s *Server) handleSubsystem(ctx context.Context, ch ssh.Channel, req *ssh.R // wait for the subsystem to finish and return that result go func() { err := subsystem.Wait() - serverContext.SendSubsystemResult(srv.SubsystemResult{ + serverContext.SendSubsystemResult(ctx, srv.SubsystemResult{ Name: subsystem.subsystemName, Err: trace.Wrap(err), }) @@ -1499,7 +1499,7 @@ func (s *Server) handleSubsystem(ctx context.Context, ch ssh.Channel, req *ssh.R func (s *Server) handleEnv(ctx context.Context, ch ssh.Channel, req *ssh.Request, scx *srv.ServerContext) error { var e sshutils.EnvReqParams if err := ssh.Unmarshal(req.Payload, &e); err != nil { - s.logger.ErrorContext(ctx, "failed to parse env request", "error", err) + scx.Logger.ErrorContext(ctx, "failed to parse env request", "error", err) return trace.Wrap(err, "failed to parse env request") } @@ -1515,7 +1515,7 @@ func (s *Server) handleEnv(ctx context.Context, ch ssh.Channel, req *ssh.Request err := scx.RemoteSession.Setenv(ctx, e.Name, e.Value) if err != nil { - s.logger.DebugContext(ctx, "Unable to set environment variable", "key", e.Name, "value", e.Value, "error", err) + scx.Logger.DebugContext(ctx, "Unable to set environment variable", "key", e.Name, "value", e.Value, "error", err) } return nil @@ -1526,7 +1526,7 @@ func (s *Server) handleEnv(ctx context.Context, ch ssh.Channel, req *ssh.Request func (s *Server) handleEnvs(ctx context.Context, ch ssh.Channel, req *ssh.Request, scx *srv.ServerContext) error { var raw tracessh.EnvsReq if err := ssh.Unmarshal(req.Payload, &raw); err != nil { - s.logger.ErrorContext(ctx, "failed to parse envs request", "error", err) + scx.Logger.ErrorContext(ctx, "failed to parse envs request", "error", err) return trace.Wrap(err, "failed to parse envs request") } @@ -1548,7 +1548,7 @@ func (s *Server) handleEnvs(ctx context.Context, ch ssh.Channel, req *ssh.Reques } if err := scx.RemoteSession.SetEnvs(ctx, envs); err != nil { - s.logger.DebugContext(ctx, "Unable to set environment variables", "error", err) + scx.Logger.DebugContext(ctx, "Unable to set environment variables", "error", err) } return nil diff --git a/lib/srv/mock.go b/lib/srv/mock.go index 97b9a2f878600..548019d2928d6 100644 --- a/lib/srv/mock.go +++ b/lib/srv/mock.go @@ -29,7 +29,6 @@ import ( "github.com/gravitational/trace" "github.com/jonboulle/clockwork" - "github.com/sirupsen/logrus" "github.com/stretchr/testify/require" "golang.org/x/crypto/ssh" @@ -67,7 +66,7 @@ func newTestServerContext(t *testing.T, srv Server, roleSet services.RoleSet) *S clusterName := "localhost" _, connCtx := sshutils.NewConnectionContext(ctx, nil, &ssh.ServerConn{Conn: sshConn}) scx := &ServerContext{ - Entry: logrus.NewEntry(logrus.StandardLogger()), + Logger: utils.NewSlogLoggerForTests(), ConnectionContext: connCtx, env: make(map[string]string), SessionRecordingConfig: recConfig, diff --git a/lib/srv/reexec.go b/lib/srv/reexec.go index 26199e056b4f2..1cb4efec635d0 100644 --- a/lib/srv/reexec.go +++ b/lib/srv/reexec.go @@ -25,6 +25,7 @@ import ( "errors" "fmt" "io" + "log/slog" "net" "os" "os/exec" @@ -38,7 +39,6 @@ import ( "time" "github.com/gravitational/trace" - log "github.com/sirupsen/logrus" "golang.org/x/sys/unix" "github.com/gravitational/teleport" @@ -194,6 +194,8 @@ type UaccMetadata struct { // RunCommand reads in the command to run from the parent process (over a // pipe) then constructs and runs the command. func RunCommand() (errw io.Writer, code int, err error) { + ctx := context.Background() + // SIGQUIT is used by teleport to initiate graceful shutdown, waiting for // existing exec sessions to close before ending the process. For this to // work when closing the entire teleport process group, exec sessions must @@ -249,21 +251,21 @@ func RunCommand() (errw io.Writer, code int, err error) { if err := auditd.SendEvent(auditd.AuditUserLogin, auditd.Success, auditdMsg); err != nil { // Currently, this logs nothing. Related issue https://github.com/gravitational/teleport/issues/17318 - log.WithError(err).Debugf("failed to send user start event to auditd: %v", err) + slog.DebugContext(ctx, "failed to send user start event to auditd", "error", err) } defer func() { if err != nil { if errors.Is(err, user.UnknownUserError(c.Login)) { if err := auditd.SendEvent(auditd.AuditUserErr, auditd.Failed, auditdMsg); err != nil { - log.WithError(err).Debugf("failed to send UserErr event to auditd: %v", err) + slog.DebugContext(ctx, "failed to send UserErr event to auditd", "error", err) } return } } if err := auditd.SendEvent(auditd.AuditUserEnd, auditd.Success, auditdMsg); err != nil { - log.WithError(err).Debugf("failed to send UserEnd event to auditd: %v", err) + slog.DebugContext(ctx, "failed to send UserEnd event to auditd", "error", err) } }() @@ -335,7 +337,7 @@ func RunCommand() (errw io.Writer, code int, err error) { localUser, err := user.Lookup(c.Login) if err != nil { if uaccErr := uacc.LogFailedLogin(c.UaccMetadata.BtmpPath, c.Login, c.UaccMetadata.Hostname, c.UaccMetadata.RemoteAddr); uaccErr != nil { - log.WithError(uaccErr).Debug("uacc unsupported.") + slog.DebugContext(ctx, "uacc unsupported", "error", uaccErr) } return errorWriter, teleport.RemoteCommandFailure, trace.Wrap(err) } @@ -348,7 +350,7 @@ func RunCommand() (errw io.Writer, code int, err error) { if err == nil { uaccEnabled = true } else { - log.WithError(err).Debug("uacc unsupported.") + slog.DebugContext(ctx, "uacc unsupported", "error", err) } } @@ -384,7 +386,7 @@ func RunCommand() (errw io.Writer, code int, err error) { } if err := setNeutralOOMScore(); err != nil { - log.WithError(err).Warnf("failed to adjust OOM score") + slog.WarnContext(ctx, "failed to adjust OOM score", "error", err) } // Start the command. @@ -953,7 +955,7 @@ func buildCommand(c *ExecCommand, localUser *user.User, tty *os.File, pamEnviron // Get the login shell for the user (or fallback to the default). shellPath, err := shell.GetLoginShell(c.Login) if err != nil { - log.Debugf("Failed to get login shell for %v: %v.", c.Login, err) + slog.DebugContext(context.Background(), "Failed to get login shell", "login", c.Login, "error", err) } if c.IsTestStub { shellPath = "/bin/sh" @@ -1099,11 +1101,17 @@ func buildCommand(c *ExecCommand, localUser *user.User, tty *os.File, pamEnviron if os.Getuid() != int(credential.Uid) || os.Getgid() != int(credential.Gid) { cmd.SysProcAttr.Credential = credential - log.Debugf("Creating process with UID %v, GID: %v, and Groups: %v.", - credential.Uid, credential.Gid, credential.Groups) + slog.DebugContext(context.Background(), "Creating process", + "uid", credential.Uid, + "gid", credential.Gid, + "groups", credential.Groups, + ) } else { - log.Debugf("Creating process with ambient credentials UID %v, GID: %v, Groups: %v.", - credential.Uid, credential.Gid, credential.Groups) + slog.DebugContext(context.Background(), "Creating process with ambient credentials", + "uid", credential.Uid, + "gid", credential.Gid, + "groups", credential.Groups, + ) } // Perform OS-specific tweaks to the command. @@ -1197,7 +1205,7 @@ func copyCommand(ctx *ServerContext, cmdmsg *ExecCommand) { defer func() { err := ctx.cmdw.Close() if err != nil { - log.Errorf("Failed to close command pipe: %v.", err) + slog.ErrorContext(ctx.CancelContext(), "Failed to close command pipe", "error", err) } // Set to nil so the close in the context doesn't attempt to re-close. @@ -1207,7 +1215,7 @@ func copyCommand(ctx *ServerContext, cmdmsg *ExecCommand) { // Write command bytes to pipe. The child process will read the command // to execute from this pipe. if err := json.NewEncoder(ctx.cmdw).Encode(cmdmsg); err != nil { - log.Errorf("Failed to copy command over pipe: %v.", err) + slog.ErrorContext(ctx.CancelContext(), "Failed to copy command over pipe", "error", err) return } } @@ -1373,7 +1381,7 @@ func getCmdCredential(localUser *user.User) (*syscall.Credential, error) { for _, sgid := range userGroups { igid, err := strconv.ParseUint(sgid, 10, 32) if err != nil { - log.Warnf("Cannot interpret user group: '%v'", sgid) + slog.WarnContext(context.Background(), "Cannot interpret user group", "user_group", sgid) } else { groups = append(groups, uint32(igid)) } diff --git a/lib/srv/regular/sftp.go b/lib/srv/regular/sftp.go index 456c805b5ee51..c76d99380be83 100644 --- a/lib/srv/regular/sftp.go +++ b/lib/srv/regular/sftp.go @@ -229,7 +229,7 @@ func (s *sftpSubsys) Wait() error { waitErr := s.sftpCmd.Wait() s.logger.DebugContext(ctx, "SFTP process finished") - s.serverCtx.SendExecResult(srv.ExecResult{ + s.serverCtx.SendExecResult(ctx, srv.ExecResult{ Command: s.sftpCmd.String(), Code: s.sftpCmd.ProcessState.ExitCode(), }) diff --git a/lib/srv/regular/sshserver.go b/lib/srv/regular/sshserver.go index d80c143e96118..9b6ce88397248 100644 --- a/lib/srv/regular/sshserver.go +++ b/lib/srv/regular/sshserver.go @@ -1184,7 +1184,7 @@ func (s *Server) startNetworkingProcess(scx *srv.ServerContext) (*networking.Pro return nil, trace.Wrap(err) } - proc, err := networking.NewProcess(nsctx.Context, cmd) + proc, err := networking.NewProcess(nsctx.CancelContext(), cmd) return proc, trace.Wrap(err) } @@ -1470,27 +1470,27 @@ func (s *Server) handleDirectTCPIPRequest(ctx context.Context, ccx *sshutils.Con return } - scx.Debugf("Opening direct-tcpip channel from %v to %v.", scx.SrcAddr, scx.DstAddr) - defer scx.Debugf("Closing direct-tcpip channel from %v to %v.", scx.SrcAddr, scx.DstAddr) + scx.Logger.DebugContext(ctx, "Opening direct-tcpip channel", "source_addr", scx.SrcAddr, "dest_addr", scx.DstAddr) + defer scx.Logger.DebugContext(ctx, "Closing direct-tcpip channel", "source_addr", scx.SrcAddr, "dest_addr", scx.DstAddr) conn, err := s.dialTCPIP(scx, scx.DstAddr) if err != nil { if errors.Is(err, trace.NotFound(user.UnknownUserError(scx.Identity.Login).Error())) || errors.Is(err, trace.BadParameter("unknown user")) { // user does not exist for the provided login. Terminate the connection. - s.logger.WarnContext(ctx, "terminating direct-tcpip request because user does not exist", "user", scx.Identity.Login) + scx.Logger.WarnContext(ctx, "terminating direct-tcpip request because user does not exist", "user", scx.Identity.Login) if err := ccx.ServerConn.Close(); err != nil { - s.logger.WarnContext(ctx, "Unable to terminate connection", "error", err) + scx.Logger.WarnContext(ctx, "Unable to terminate connection", "error", err) } return } - s.logger.ErrorContext(ctx, "Forwarding data via direct-tcpip channel failed", "error", err) + scx.Logger.ErrorContext(ctx, "Forwarding data via direct-tcpip channel failed", "error", err) s.writeStderr(ctx, channel, err.Error()) return } if err := utils.ProxyConn(ctx, conn, channel); err != nil && !errors.Is(err, io.EOF) && !errors.Is(err, os.ErrClosed) { - s.logger.WarnContext(ctx, "Connection problem in direct-tcpip channel", "error", err) + scx.Logger.WarnContext(ctx, "Connection problem in direct-tcpip channel", "error", err) } if err := s.EmitAuditEvent(s.ctx, &apievents.PortForward{ @@ -1508,7 +1508,7 @@ func (s *Server) handleDirectTCPIPRequest(ctx context.Context, ccx *sshutils.Con Success: true, }, }); err != nil { - s.logger.WarnContext(ctx, "Failed to emit port forward event", "error", err) + scx.Logger.WarnContext(ctx, "Failed to emit port forward event", "error", err) } } @@ -1561,16 +1561,15 @@ func (s *Server) handleSessionRequests(ctx context.Context, ccx *sshutils.Connec for { // update scx with the session ID: if !s.proxyMode { - err := scx.CreateOrJoinSession(s.reg) + err := scx.CreateOrJoinSession(ctx, s.reg) if err != nil { - errorMessage := fmt.Sprintf("unable to update context: %v", err) - scx.Errorf("Unable to update context: %v.", errorMessage) + scx.Logger.ErrorContext(ctx, "Unable to update context", "error", err) // write the error to channel and close it - s.writeStderr(ctx, trackingChan, errorMessage) + s.writeStderr(ctx, trackingChan, fmt.Sprintf("unable to update context: %v", err)) _, err := trackingChan.SendRequest("exit-status", false, ssh.Marshal(struct{ C uint32 }{C: teleport.RemoteCommandFailure})) if err != nil { - scx.Errorf("Failed to send exit status %v.", errorMessage) + scx.Logger.ErrorContext(ctx, "Failed to send exit status", "error", err) } return } @@ -1579,12 +1578,12 @@ func (s *Server) handleSessionRequests(ctx context.Context, ccx *sshutils.Connec case creq := <-scx.SubsystemResultCh: // this means that subsystem has finished executing and // want us to close session and the channel - scx.Debugf("Close session request: %v.", creq.Err) + scx.Logger.DebugContext(ctx, "Close session request", "error", creq.Err) return case req := <-in: if req == nil { // this will happen when the client closes/drops the connection - scx.Debugf("Client %v disconnected.", scx.ServerConn.RemoteAddr()) + scx.Logger.DebugContext(ctx, "Client disconnected.", "client_addr", scx.ServerConn.RemoteAddr()) return } @@ -1609,23 +1608,23 @@ func (s *Server) handleSessionRequests(ctx context.Context, ccx *sshutils.Connec } if req.WantReply { if err := req.Reply(true, nil); err != nil { - s.logger.WarnContext(ctx, "Failed to reply to request", "request_type", req.Type, "error", err) + scx.Logger.WarnContext(ctx, "Failed to reply to request", "request_type", req.Type, "error", err) } } span.End() case result := <-scx.ExecResultCh: - scx.Debugf("Exec request (%q) complete: %v", result.Command, result.Code) + scx.Logger.DebugContext(ctx, "Exec request complete", "command", result.Command, "code", result.Code) // The exec process has finished and delivered the execution result, send // the result back to the client, and close the session and channel. _, err := trackingChan.SendRequest("exit-status", false, ssh.Marshal(struct{ C uint32 }{C: uint32(result.Code)})) if err != nil { - scx.Infof("Failed to send exit status for %v: %v", result.Command, err) + scx.Logger.InfoContext(ctx, "Failed to send exit status", "command", result.Command, "error", err) } return case <-ctx.Done(): - s.logger.DebugContext(ctx, "Closing session due to cancellation") + scx.Logger.DebugContext(ctx, "Closing session due to cancellation") return } } @@ -1634,7 +1633,7 @@ func (s *Server) handleSessionRequests(ctx context.Context, ccx *sshutils.Connec // dispatch receives an SSH request for a subsystem and dispatches the request to the // appropriate subsystem implementation func (s *Server) dispatch(ctx context.Context, ch ssh.Channel, req *ssh.Request, serverContext *srv.ServerContext) error { - serverContext.Debugf("Handling request %v, want reply %v.", req.Type, req.WantReply) + serverContext.Logger.DebugContext(ctx, "Handling session request", "request_type", req.Type, "want_reply", req.WantReply) // If this SSH server is configured to only proxy, we do not support anything // other than our own custom "subsystems" and environment manipulation. @@ -1643,15 +1642,15 @@ func (s *Server) dispatch(ctx context.Context, ch ssh.Channel, req *ssh.Request, case sshutils.SubsystemRequest: return s.handleSubsystem(ctx, ch, req, serverContext) case sshutils.EnvRequest: - return s.handleEnv(ch, req, serverContext) + return s.handleEnv(ctx, ch, req, serverContext) case tracessh.EnvsRequest: - return s.handleEnvs(ch, req, serverContext) + return s.handleEnvs(ctx, ch, req, serverContext) case sshutils.AgentForwardRequest: // process agent forwarding, but we will only forward agent to proxy in // recording proxy mode. err := s.handleAgentForwardProxy(req, serverContext) if err != nil { - s.logger.WarnContext(ctx, "Failure forwarding agent", "error", err) + serverContext.Logger.WarnContext(ctx, "Failure forwarding agent", "error", err) } return nil case sshutils.PuTTYSimpleRequest: @@ -1659,13 +1658,13 @@ func (s *Server) dispatch(ctx context.Context, ch ssh.Channel, req *ssh.Request, // as a proxy to indicate that it's in "simple" node and won't be requesting any other channels. // As we don't support this request, we ignore it. // https://the.earth.li/~sgtatham/putty/0.76/htmldoc/AppendixG.html#sshnames-channel - s.logger.DebugContext(ctx, "deliberately ignoring simple@putty.projects.tartarus.org request") + serverContext.Logger.DebugContext(ctx, "deliberately ignoring simple@putty.projects.tartarus.org request") return nil default: s.logger.WarnContext(ctx, "server doesn't support request type", "request_type", req.Type) if req.WantReply { if err := req.Reply(false, nil); err != nil { - s.logger.ErrorContext(ctx, "error sending reply on SSH channel", "error", err) + serverContext.Logger.ErrorContext(ctx, "error sending reply on SSH channel", "error", err) } } return nil @@ -1702,9 +1701,9 @@ func (s *Server) dispatch(ctx context.Context, ch ssh.Channel, req *ssh.Request, // to maintain interoperability with OpenSSH, agent forwarding requests // should never fail, all errors should be logged and we should continue // processing requests. - err := s.handleAgentForwardNode(req, serverContext) + err := s.handleAgentForwardNode(ctx, req, serverContext) if err != nil { - s.logger.WarnContext(ctx, "failure forwarding agent", "error", err) + serverContext.Logger.WarnContext(ctx, "failure forwarding agent", "error", err) } return nil case sshutils.PuTTYWinadjRequest: @@ -1729,9 +1728,9 @@ func (s *Server) dispatch(ctx context.Context, ch ssh.Channel, req *ssh.Request, case teleport.ForceTerminateRequest: return s.termHandlers.HandleForceTerminate(ch, req, serverContext) case sshutils.EnvRequest: - return s.handleEnv(ch, req, serverContext) + return s.handleEnv(ctx, ch, req, serverContext) case tracessh.EnvsRequest: - return s.handleEnvs(ch, req, serverContext) + return s.handleEnvs(ctx, ch, req, serverContext) case sshutils.SubsystemRequest: // subsystems are SSH subsystems defined in http://tools.ietf.org/html/rfc4254 6.6 // they are in essence SSH session extensions, allowing to implement new SSH commands @@ -1749,18 +1748,18 @@ func (s *Server) dispatch(ctx context.Context, ch ssh.Channel, req *ssh.Request, // to maintain interoperability with OpenSSH, agent forwarding requests // should never fail, all errors should be logged and we should continue // processing requests. - err := s.handleAgentForwardNode(req, serverContext) + err := s.handleAgentForwardNode(ctx, req, serverContext) if err != nil { - s.logger.WarnContext(ctx, "failure forwarding agent", "error", err) + serverContext.Logger.WarnContext(ctx, "failure forwarding agent", "error", err) } return nil case sshutils.PuTTYWinadjRequest: return s.handlePuTTYWinadj(ctx, req) default: - s.logger.WarnContext(ctx, "server doesn't support request type", "request_type", req.Type) + serverContext.Logger.WarnContext(ctx, "server doesn't support request type", "request_type", req.Type) if req.WantReply { if err := req.Reply(false, nil); err != nil { - s.logger.ErrorContext(ctx, "error sending reply on SSH channel", "error", err) + serverContext.Logger.ErrorContext(ctx, "error sending reply on SSH channel", "error", err) } } return nil @@ -1769,7 +1768,7 @@ func (s *Server) dispatch(ctx context.Context, ch ssh.Channel, req *ssh.Request, // handleAgentForwardNode will create a unix socket and serve the agent running // on the client on it. -func (s *Server) handleAgentForwardNode(_ *ssh.Request, scx *srv.ServerContext) error { +func (s *Server) handleAgentForwardNode(ctx context.Context, _ *ssh.Request, scx *srv.ServerContext) error { // check if the user's RBAC role allows agent forwarding err := s.authHandlers.CheckAgentForward(scx) if err != nil { @@ -1779,7 +1778,7 @@ func (s *Server) handleAgentForwardNode(_ *ssh.Request, scx *srv.ServerContext) // Enable agent forwarding for the broader connection-level // context. scx.Parent().SetForwardAgent(true) - if err := s.serveAgent(scx); err != nil { + if err := s.serveAgent(ctx, scx); err != nil { return trace.Wrap(err) } @@ -1787,7 +1786,7 @@ func (s *Server) handleAgentForwardNode(_ *ssh.Request, scx *srv.ServerContext) } // serveAgent will build the a sock path for this user and serve an SSH agent on unix socket. -func (s *Server) serveAgent(scx *srv.ServerContext) error { +func (s *Server) serveAgent(ctx context.Context, scx *srv.ServerContext) error { proc, err := s.getNetworkingProcess(scx) if err != nil { return trace.Wrap(err) @@ -1805,10 +1804,10 @@ func (s *Server) serveAgent(scx *srv.ServerContext) error { scx.Parent().AddCloser(agentServer) scx.Parent().SetEnv(teleport.SSHAuthSock, listener.Addr().String()) scx.Parent().SetEnv(teleport.SSHAgentPID, fmt.Sprintf("%v", os.Getpid())) - scx.Debugf("Starting agent server for Teleport user %v and socket %v.", scx.Identity.TeleportUser, agentServer.Path) + scx.Logger.DebugContext(ctx, "Starting agent server for user", "teleport_user", scx.Identity.TeleportUser, "socket", agentServer.Path) go func() { if err := agentServer.Serve(); err != nil { - scx.Errorf("agent server for user %q stopped: %v", scx.Identity.TeleportUser, err) + scx.Logger.ErrorContext(ctx, "agent server for user stopped", "teleport_user", scx.Identity.TeleportUser, "error", err) } }() @@ -1870,7 +1869,7 @@ func (s *Server) handleX11Forward(ctx context.Context, ch ssh.Channel, req *ssh. err = nil } if err := s.EmitAuditEvent(s.ctx, event); err != nil { - s.logger.WarnContext(s.ctx, "Failed to emit x11-forward event", "error", err) + scx.Logger.WarnContext(s.ctx, "Failed to emit x11-forward event", "error", err) } }() @@ -1894,7 +1893,7 @@ func (s *Server) handleX11Forward(ctx context.Context, ch ssh.Channel, req *ssh. return trace.Wrap(err) } - listener, err := proc.ListenX11(context.Background(), networking.X11Request{ + listener, err := proc.ListenX11(ctx, networking.X11Request{ ForwardRequestPayload: x11Req, DisplayOffset: s.x11.DisplayOffset, MaxDisplay: s.x11.MaxDisplay, @@ -1904,7 +1903,7 @@ func (s *Server) handleX11Forward(ctx context.Context, ch ssh.Channel, req *ssh. } scx.Parent().AddCloser(listener) - if err := scx.HandleX11Listener(listener, x11Req.SingleConnection); err != nil { + if err := scx.HandleX11Listener(ctx, listener, x11Req.SingleConnection); err != nil { if trace.IsLimitExceeded(err) { return trace.AccessDenied("The server cannot support any more X11 forwarding sessions at this time") } @@ -1917,43 +1916,43 @@ func (s *Server) handleX11Forward(ctx context.Context, ch ssh.Channel, req *ssh. func (s *Server) handleSubsystem(ctx context.Context, ch ssh.Channel, req *ssh.Request, serverContext *srv.ServerContext) error { sb, err := s.parseSubsystemRequest(ctx, req, serverContext) if err != nil { - serverContext.Warnf("Failed to parse subsystem request: %v: %v.", req, err) + serverContext.Logger.WarnContext(ctx, "Failed to parse subsystem request", "requres_type", req.Type, "error", err) return trace.Wrap(err) } - serverContext.Debugf("Subsystem request: %v.", sb) + serverContext.Logger.DebugContext(ctx, "Starting subsystem") // starting subsystem is blocking to the client, // while collecting its result and waiting is not blocking if err := sb.Start(ctx, serverContext.ServerConn, ch, req, serverContext); err != nil { - serverContext.Warnf("Subsystem request %v failed: %v.", sb, err) - serverContext.SendSubsystemResult(srv.SubsystemResult{Err: trace.Wrap(err)}) + serverContext.Logger.WarnContext(ctx, "Subsystem request failed", "error", err) + serverContext.SendSubsystemResult(ctx, srv.SubsystemResult{Err: trace.Wrap(err)}) return trace.Wrap(err) } go func() { err := sb.Wait() - s.logger.DebugContext(ctx, "Subsystem finished", "subsystem", sb, "error", err) - serverContext.SendSubsystemResult(srv.SubsystemResult{Err: trace.Wrap(err)}) + serverContext.Logger.DebugContext(ctx, "Subsystem finished", "subsystem", sb, "error", err) + serverContext.SendSubsystemResult(ctx, srv.SubsystemResult{Err: trace.Wrap(err)}) }() return nil } // handleEnv accepts an environment variable sent by the client and stores it // in connection context -func (s *Server) handleEnv(ch ssh.Channel, req *ssh.Request, ctx *srv.ServerContext) error { +func (s *Server) handleEnv(ctx context.Context, ch ssh.Channel, req *ssh.Request, scx *srv.ServerContext) error { var e sshutils.EnvReqParams if err := ssh.Unmarshal(req.Payload, &e); err != nil { - ctx.Error(err) + scx.Logger.ErrorContext(ctx, "failed to parse env request", "error", err) return trace.Wrap(err, "failed to parse env request") } - ctx.SetEnv(e.Name, e.Value) + scx.SetEnv(e.Name, e.Value) return nil } // handleEnvs accepts environment variables sent by the client and stores them // in connection context -func (s *Server) handleEnvs(ch ssh.Channel, req *ssh.Request, ctx *srv.ServerContext) error { +func (s *Server) handleEnvs(ctx context.Context, ch ssh.Channel, req *ssh.Request, scx *srv.ServerContext) error { var raw tracessh.EnvsReq if err := ssh.Unmarshal(req.Payload, &raw); err != nil { - ctx.Error(err) + scx.Logger.ErrorContext(ctx, "failed to parse envs request", "error", err) return trace.Wrap(err, "failed to parse envs request") } @@ -1963,7 +1962,7 @@ func (s *Server) handleEnvs(ch ssh.Channel, req *ssh.Request, ctx *srv.ServerCon } for k, v := range envs { - ctx.SetEnv(k, v) + scx.SetEnv(k, v) } return nil diff --git a/lib/srv/regular/sshserver_test.go b/lib/srv/regular/sshserver_test.go index 5e0b9a18bfec9..abf72512dae72 100644 --- a/lib/srv/regular/sshserver_test.go +++ b/lib/srv/regular/sshserver_test.go @@ -41,7 +41,6 @@ import ( "github.com/gravitational/trace" "github.com/jonboulle/clockwork" "github.com/moby/term" - "github.com/sirupsen/logrus" "github.com/stretchr/testify/assert" "github.com/stretchr/testify/require" "golang.org/x/crypto/ssh" @@ -1562,7 +1561,6 @@ func TestProxyRoundRobin(t *testing.T) { proxyClient, _ := newProxyClient(t, f.testSrv) nodeClient, _ := newNodeClient(t, f.testSrv) - logger := logrus.WithField("test", "TestProxyRoundRobin") listener, reverseTunnelAddress := mustListen(t) defer listener.Close() lockWatcher := newLockWatcher(ctx, t, proxyClient) @@ -1582,14 +1580,12 @@ func TestProxyRoundRobin(t *testing.T) { NewCachingAccessPoint: noCache, DataDir: t.TempDir(), Emitter: proxyClient, - Log: logger, LockWatcher: lockWatcher, NodeWatcher: nodeWatcher, CertAuthorityWatcher: caWatcher, CircuitBreakerConfig: breaker.NoopBreakerConfig(), }) require.NoError(t, err) - logger.WithField("tun-addr", reverseTunnelAddress.String()).Info("Created reverse tunnel server.") require.NoError(t, reverseTunnelServer.Start()) defer reverseTunnelServer.Close() @@ -1702,7 +1698,6 @@ func TestProxyDirectAccess(t *testing.T) { ctx := context.Background() listener, _ := mustListen(t) - logger := logrus.WithField("test", "TestProxyDirectAccess") proxyClient, _ := newProxyClient(t, f.testSrv) lockWatcher := newLockWatcher(ctx, t, proxyClient) nodeWatcher := newNodeWatcher(ctx, t, proxyClient) @@ -1721,7 +1716,6 @@ func TestProxyDirectAccess(t *testing.T) { NewCachingAccessPoint: noCache, DataDir: t.TempDir(), Emitter: proxyClient, - Log: logger, LockWatcher: lockWatcher, NodeWatcher: nodeWatcher, CertAuthorityWatcher: caWatcher, @@ -2409,7 +2403,6 @@ func TestParseSubsystemRequest(t *testing.T) { NewCachingAccessPoint: noCache, DataDir: t.TempDir(), Emitter: proxyClient, - Log: logrus.StandardLogger(), LockWatcher: lockWatcher, NodeWatcher: nodeWatcher, CertAuthorityWatcher: caWatcher, @@ -2654,7 +2647,6 @@ func TestIgnorePuTTYSimpleChannel(t *testing.T) { ctx := context.Background() listener, _ := mustListen(t) - logger := logrus.WithField("test", "TestIgnorePuTTYSimpleChannel") proxyClient, _ := newProxyClient(t, f.testSrv) lockWatcher := newLockWatcher(ctx, t, proxyClient) nodeWatcher := newNodeWatcher(ctx, t, proxyClient) @@ -2673,7 +2665,6 @@ func TestIgnorePuTTYSimpleChannel(t *testing.T) { NewCachingAccessPoint: noCache, DataDir: t.TempDir(), Emitter: proxyClient, - Log: logger, LockWatcher: lockWatcher, NodeWatcher: nodeWatcher, CertAuthorityWatcher: caWatcher, @@ -3076,8 +3067,7 @@ func TestHostUserCreationProxy(t *testing.T) { proxyClient, _ := newProxyClient(t, f.testSrv) nodeClient, _ := newNodeClient(t, f.testSrv) - logger := logrus.WithField("test", "TestHostUserCreationProxy") - listener, reverseTunnelAddress := mustListen(t) + listener, _ := mustListen(t) defer listener.Close() lockWatcher := newLockWatcher(ctx, t, proxyClient) nodeWatcher := newNodeWatcher(ctx, t, proxyClient) @@ -3096,14 +3086,12 @@ func TestHostUserCreationProxy(t *testing.T) { NewCachingAccessPoint: noCache, DataDir: t.TempDir(), Emitter: proxyClient, - Log: logger, LockWatcher: lockWatcher, NodeWatcher: nodeWatcher, CertAuthorityWatcher: caWatcher, CircuitBreakerConfig: breaker.NoopBreakerConfig(), }) require.NoError(t, err) - logger.WithField("tun-addr", reverseTunnelAddress.String()).Info("Created reverse tunnel server.") require.NoError(t, reverseTunnelServer.Start()) defer reverseTunnelServer.Close() diff --git a/lib/srv/sess.go b/lib/srv/sess.go index 9f0d967df055d..7942441592ee4 100644 --- a/lib/srv/sess.go +++ b/lib/srv/sess.go @@ -39,7 +39,6 @@ import ( "github.com/jonboulle/clockwork" "github.com/moby/term" "github.com/prometheus/client_golang/prometheus" - log "github.com/sirupsen/logrus" "go.opentelemetry.io/otel/attribute" oteltrace "go.opentelemetry.io/otel/trace" "golang.org/x/crypto/ssh" @@ -59,6 +58,7 @@ import ( rsession "github.com/gravitational/teleport/lib/session" "github.com/gravitational/teleport/lib/sshutils/sftp" "github.com/gravitational/teleport/lib/utils" + logutils "github.com/gravitational/teleport/lib/utils/log" ) const sessionRecorderID = "session-recorder" @@ -339,7 +339,7 @@ func (s *SessionRegistry) UpsertHostUser(identityContext IdentityContext) (bool, func (s *SessionRegistry) OpenSession(ctx context.Context, ch ssh.Channel, scx *ServerContext) error { session := scx.getSession() if session != nil && !session.isStopped() { - scx.Infof("Joining existing session %v.", session.id) + scx.Logger.InfoContext(ctx, "Joining existing session", "session_id", session.id) mode := types.SessionParticipantMode(scx.env[teleport.EnvSSHJoinMode]) if mode == "" { mode = types.SessionPeerMode @@ -374,9 +374,9 @@ func (s *SessionRegistry) OpenSession(ctx context.Context, ch ssh.Channel, scx * if err != nil { return trace.Wrap(err) } - scx.setSession(sess, ch) + scx.setSession(ctx, sess, ch) s.addSession(sess) - scx.Infof("Creating (interactive) session %v.", sid) + scx.Logger.InfoContext(ctx, "Creating interactive session", "session_id", sid) // Start an interactive session (TTY attached). Close the session if an error // occurs, otherwise it will be closed by the callee. @@ -393,11 +393,11 @@ func (s *SessionRegistry) OpenExecSession(ctx context.Context, channel ssh.Chann if sessionID.IsZero() { sessionID = rsession.NewID() - scx.Tracef("Session not found, creating a new session %s", sessionID) + scx.Logger.Log(ctx, logutils.TraceLevel, "Session not found, creating a new session", "sessin_id", sessionID) } else { // Use passed session ID. Assist uses this "feature" to record // the execution output. - scx.Tracef("Session found, reusing it %s", sessionID) + scx.Logger.Log(ctx, logutils.TraceLevel, "Session found, reusing it", "session_id", sessionID) } // This logic allows concurrent request to create a new session @@ -406,7 +406,7 @@ func (s *SessionRegistry) OpenExecSession(ctx context.Context, channel ssh.Chann if err != nil { return trace.Wrap(err) } - scx.Infof("Creating (exec) session %v.", sessionID) + scx.Logger.InfoContext(ctx, "Creating exec session", "session_id", sessionID) approved, err := s.isApprovedFileTransfer(scx) if err != nil { @@ -428,7 +428,7 @@ func (s *SessionRegistry) OpenExecSession(ctx context.Context, channel ssh.Chann // Start a non-interactive session (TTY attached). Close the session if an error // occurs, otherwise it will be closed by the callee. - scx.setSession(sess, channel) + scx.setSession(ctx, sess, channel) err = sess.startExec(ctx, channel, scx) if err != nil { @@ -1299,7 +1299,7 @@ func (s *session) launch() { _, err := io.Copy(s.io, s.term.PTY()) s.logger.DebugContext( - s.serverCtx, "Copying from PTY to writer completed with error.", + s.serverCtx, "Copying from PTY to writer completed", "error", err, ) }() @@ -1310,7 +1310,7 @@ func (s *session) launch() { _, err := io.Copy(s.term.PTY(), s.io) s.logger.DebugContext( - s.serverCtx, "Copying from reader to PTY completed with error.", + s.serverCtx, "Copying from reader to PTY completed", "error", err, ) }() @@ -1540,7 +1540,7 @@ func (s *session) startExec(ctx context.Context, channel ssh.Channel, scx *Serve "request", execRequest, "result", result, ) - scx.SendExecResult(*result) + scx.SendExecResult(ctx, *result) } // Open a BPF recording session. If BPF was not configured, not available, @@ -1585,7 +1585,7 @@ func (s *session) startExec(ctx context.Context, channel ssh.Channel, scx *Serve go func() { result = execRequest.Wait() if result != nil { - scx.SendExecResult(*result) + scx.SendExecResult(ctx, *result) } // Wait a little bit to let all events filter through before closing the @@ -2166,7 +2166,7 @@ func (s *session) getParties() (parties []*party) { type party struct { sync.Mutex - log *log.Entry + log *slog.Logger login string user string serverID string @@ -2182,10 +2182,12 @@ type party struct { } func newParty(s *session, mode types.SessionParticipantMode, ch ssh.Channel, ctx *ServerContext) *party { + pid := rsession.NewID() return &party{ - log: log.WithFields(log.Fields{ - teleport.ComponentKey: teleport.Component(teleport.ComponentSession, ctx.srv.Component()), - }), + log: slog.With( + teleport.ComponentKey, teleport.Component(teleport.ComponentSession, ctx.srv.Component()), + "party_id", pid, + ), user: ctx.Identity.TeleportUser, login: ctx.Identity.Login, serverID: s.registry.Srv.ID(), @@ -2237,7 +2239,7 @@ func (p *party) Close() error { func (p *party) closeUnderSessionLock() error { var err error p.closeOnce.Do(func() { - p.log.Infof("Closing party %v", p.id) + p.log.InfoContext(p.ctx.cancelContext, "Closing party") // Remove party from its session err = trace.NewAggregate(p.s.removePartyUnderLock(p), p.ch.Close()) }) diff --git a/lib/srv/sess_test.go b/lib/srv/sess_test.go index b6b0952c1a01a..28245d54a402d 100644 --- a/lib/srv/sess_test.go +++ b/lib/srv/sess_test.go @@ -825,7 +825,7 @@ func TestParties(t *testing.T) { func testJoinSession(t *testing.T, reg *SessionRegistry, sess *session) { scx := newTestServerContext(t, reg.Srv, nil) sshChanOpen := newMockSSHChannel() - scx.setSession(sess, sshChanOpen) + scx.setSession(context.Background(), sess, sshChanOpen) // Open a new session go func() { diff --git a/lib/srv/term.go b/lib/srv/term.go index 31b10c26d9011..37eaabf8bb692 100644 --- a/lib/srv/term.go +++ b/lib/srv/term.go @@ -22,6 +22,7 @@ import ( "context" "errors" "io" + "log/slog" "os" "os/exec" "os/user" @@ -33,7 +34,6 @@ import ( "github.com/creack/pty" "github.com/gravitational/trace" "github.com/moby/term" - log "github.com/sirupsen/logrus" "golang.org/x/crypto/ssh" "github.com/gravitational/teleport" @@ -131,7 +131,7 @@ type terminal struct { wg sync.WaitGroup mu sync.Mutex - log *log.Entry + log *slog.Logger cmd *exec.Cmd serverContext *ServerContext @@ -152,18 +152,17 @@ type terminal struct { // NewLocalTerminal creates and returns a local PTY. func newLocalTerminal(ctx *ServerContext) (*terminal, error) { + logger := ctx.Logger.With(teleport.ComponentKey, teleport.ComponentLocalTerm) // Open PTY and corresponding TTY. pty, tty, err := pty.Open() if err != nil { - log.Warnf("Could not start PTY: %v", err) + logger.WarnContext(ctx.CancelContext(), "Could not start PTY", "error", err) return nil, err } t := &terminal{ - log: log.WithFields(log.Fields{ - teleport.ComponentKey: teleport.ComponentLocalTerm, - }), + log: logger, serverContext: ctx, terminateFD: ctx.killShellw, pty: pty, @@ -175,7 +174,7 @@ func newLocalTerminal(ctx *ServerContext) (*terminal, error) { // on a read-only filesystem, but logging is useful for diagnostic purposes. err = t.setOwner() if err != nil { - log.Debugf("Unable to set TTY owner: %v.\n", err) + t.log.DebugContext(ctx.CancelContext(), "Unable to set TTY owner", "error", err) } return t, nil @@ -227,7 +226,7 @@ func (t *terminal) Run(ctx context.Context) error { // Close our half of the write pipe since it is only to be used by the child process. // Not closing prevents being signaled when the child closes its half. if err := t.serverContext.readyw.Close(); err != nil { - t.serverContext.Logger.WithError(err).Warn("Failed to close parent process ready signal write fd") + t.log.WarnContext(ctx, "Failed to close parent process ready signal write fd", "error", err) } t.serverContext.readyw = nil @@ -272,7 +271,7 @@ func (t *terminal) WaitForChild() error { // pre-processing routine (placed in a cgroup). func (t *terminal) Continue() { if err := t.serverContext.contw.Close(); err != nil { - t.log.Warnf("failed to close server context") + t.log.WarnContext(t.serverContext.CancelContext(), "failed to close server context") } } @@ -280,7 +279,7 @@ func (t *terminal) Continue() { func (t *terminal) KillUnderlyingShell(ctx context.Context) error { if err := t.terminateFD.Close(); err != nil { if !errors.Is(err, os.ErrClosed) { - t.log.WithError(err).Debug("Failed to close the shell file descriptor") + t.log.DebugContext(t.serverContext.CancelContext(), "Failed to close the shell file descriptor", "error", err) } } @@ -299,7 +298,7 @@ func (t *terminal) KillUnderlyingShell(ctx context.Context) error { } if err := proc.Signal(syscall.Signal(0)); errors.Is(err, os.ErrProcessDone) { - t.log.Debugf("Terminal child process has been stopped") + t.log.DebugContext(t.serverContext.CancelContext(), "Terminal child process has been stopped") return nil } @@ -351,24 +350,24 @@ func (t *terminal) closeTTY() error { defer t.mu.Unlock() if t.tty == nil { - t.log.Debug("TTY already closed") + t.log.DebugContext(t.serverContext.CancelContext(), "TTY already closed") return nil } - t.log.Debug("Closing TTY") - defer t.log.Debug("Closed TTY") + t.log.DebugContext(t.serverContext.CancelContext(), "Closing TTY") + defer t.log.DebugContext(t.serverContext.CancelContext(), "Closed TTY") err := t.tty.Close() t.tty = nil if err != nil { - t.log.Warnf("Failed to close TTY: %v", err) + t.log.WarnContext(t.serverContext.CancelContext(), "Failed to close TTY", "error", err) } return trace.Wrap(err) } func (t *terminal) closePTY() { - defer t.log.Debug("Closed PTY") + defer t.log.DebugContext(t.serverContext.CancelContext(), "Closed PTY") t.mu.Lock() defer t.mu.Unlock() @@ -381,7 +380,7 @@ func (t *terminal) closePTY() { } if err := t.pty.Close(); err != nil { - t.log.Warnf("Failed to close PTY: %v", err) + t.log.WarnContext(t.serverContext.CancelContext(), "Failed to close PTY", "error", err) } t.pty = nil } @@ -491,7 +490,7 @@ func (t *terminal) setOwner() error { return trace.Wrap(err) } - log.Debugf("Set permissions on %v to %v:%v with mode %v.", t.tty.Name(), uid, gid, mode) + t.log.DebugContext(t.serverContext.CancelContext(), "Set permissions on tty", "tty_name", t.tty.Name(), "uid", uid, "gid", gid, "mode", mode) return nil } @@ -500,7 +499,7 @@ type remoteTerminal struct { wg sync.WaitGroup mu sync.Mutex - log *log.Entry + log *slog.Logger ctx *ServerContext @@ -517,9 +516,7 @@ func newRemoteTerminal(ctx *ServerContext) (*remoteTerminal, error) { } t := &remoteTerminal{ - log: log.WithFields(log.Fields{ - teleport.ComponentKey: teleport.ComponentRemoteTerm, - }), + log: ctx.Logger.With(teleport.ComponentKey, teleport.ComponentRemoteTerm), ctx: ctx, session: ctx.RemoteSession, ptyBuffer: &ptyBuffer{}, @@ -577,7 +574,7 @@ func (t *remoteTerminal) Run(ctx context.Context) error { // we want to run a "exec" command within a pty if execRequest, err := t.ctx.GetExecRequest(); err == nil && execRequest.GetCommand() != "" { - t.log.Debugf("Running exec request within a PTY") + t.log.DebugContext(ctx, "Running exec request within a PTY") if err := t.session.Start(ctx, execRequest.GetCommand()); err != nil { return trace.Wrap(err) @@ -587,7 +584,7 @@ func (t *remoteTerminal) Run(ctx context.Context) error { } // we want an interactive shell - t.log.Debugf("Requesting an interactive terminal of type %v", t.termType) + t.log.DebugContext(ctx, "Requesting an interactive terminal", "term_type", t.termType) if err := t.session.Shell(ctx); err != nil { return trace.Wrap(err) } @@ -670,7 +667,7 @@ func (t *remoteTerminal) Close() error { // session. t.wg.Wait() - t.log.Debugf("Closed remote terminal and underlying SSH session") + t.log.DebugContext(t.ctx.CancelContext(), "Closed remote terminal and underlying SSH session") return nil } @@ -731,6 +728,6 @@ func (t *remoteTerminal) prepareRemoteSession(ctx context.Context, session *trac } if err := session.SetEnvs(ctx, envs); err != nil { - t.log.WithError(err).Debug("Unable to set environment variables") + t.log.DebugContext(ctx, "Unable to set environment variables", "error", err) } } diff --git a/lib/srv/termhandlers.go b/lib/srv/termhandlers.go index 6f1494b962911..6a7810d67ebe6 100644 --- a/lib/srv/termhandlers.go +++ b/lib/srv/termhandlers.go @@ -77,7 +77,7 @@ func (t *TermHandlers) HandlePTYReq(ctx context.Context, ch ssh.Channel, req *ss if err != nil { return trace.Wrap(err) } - scx.Debugf("Requested terminal %q of size %v", ptyRequest.Env, *params) + scx.Logger.DebugContext(ctx, "Terminal has been requested", "terminal", ptyRequest.Env, "width", params.W, "height", params.H) // get an existing terminal or create a new one term := scx.GetTerm() @@ -92,14 +92,14 @@ func (t *TermHandlers) HandlePTYReq(ctx context.Context, ch ssh.Channel, req *ss scx.ttyName = term.TTYName() } if err := term.SetWinSize(ctx, *params); err != nil { - scx.Errorf("Failed setting window size: %v", err) + scx.Logger.ErrorContext(ctx, "Failed setting window size", "error", err) } term.SetTermType(ptyRequest.Env) term.SetTerminalModes(termModes) // update the session if err := t.SessionRegistry.NotifyWinChange(ctx, *params, scx); err != nil { - scx.Errorf("Unable to update session: %v", err) + scx.Logger.ErrorContext(ctx, "Unable to update session", "error", err) } return nil diff --git a/lib/srv/usermgmt_linux.go b/lib/srv/usermgmt_linux.go index c6ba42ba35d8a..b1c6ed22c416c 100644 --- a/lib/srv/usermgmt_linux.go +++ b/lib/srv/usermgmt_linux.go @@ -20,8 +20,10 @@ package srv import ( "bufio" + "context" "errors" "fmt" + "log/slog" "os" "os/exec" "os/user" @@ -30,7 +32,6 @@ import ( "strings" "github.com/gravitational/trace" - log "github.com/sirupsen/logrus" "github.com/gravitational/teleport/lib/utils" "github.com/gravitational/teleport/lib/utils/host" @@ -186,9 +187,10 @@ func (u *HostSudoersProvisioningBackend) RemoveSudoersFile(username string) erro fileUsername := sanitizeSudoersName(username) sudoersFilePath := filepath.Join(u.SudoersPath, fmt.Sprintf("teleport-%s-%s", u.HostUUID, fileUsername)) if _, err := os.Stat(sudoersFilePath); os.IsNotExist(err) { - log.Debugf("User %q, did not have sudoers file as it did not exist at path %q", - username, - sudoersFilePath) + slog.DebugContext(context.Background(), "No sudoers file present to remove", + "user", username, + "sudoers_path", sudoersFilePath, + ) return nil } return trace.Wrap(os.Remove(sudoersFilePath))