diff --git a/lib/srv/ctx.go b/lib/srv/ctx.go index 342566dee7a54..60f9a0ae660c1 100644 --- a/lib/srv/ctx.go +++ b/lib/srv/ctx.go @@ -407,14 +407,14 @@ type ServerContext struct { // the ServerContext is closed. The ctx parameter should be a child of the ctx // associated with the scope of the parent ConnectionContext to ensure that // cancellation of the ConnectionContext propagates to the ServerContext. -func NewServerContext(ctx context.Context, parent *sshutils.ConnectionContext, srv Server, identityContext IdentityContext, monitorOpts ...func(*MonitorConfig)) (context.Context, *ServerContext, error) { +func NewServerContext(ctx context.Context, parent *sshutils.ConnectionContext, srv Server, identityContext IdentityContext, monitorOpts ...func(*MonitorConfig)) (*ServerContext, error) { netConfig, err := srv.GetAccessPoint().GetClusterNetworkingConfig(ctx) if err != nil { - return nil, nil, trace.Wrap(err) + return nil, trace.Wrap(err) } recConfig, err := srv.GetAccessPoint().GetSessionRecordingConfig(ctx) if err != nil { - return nil, nil, trace.Wrap(err) + return nil, trace.Wrap(err) } cancelContext, cancel := context.WithCancel(ctx) @@ -453,7 +453,7 @@ func NewServerContext(ctx context.Context, parent *sshutils.ConnectionContext, s authPref, err := srv.GetAccessPoint().GetAuthPreference(ctx) if err != nil { childErr := child.Close() - return nil, nil, trace.NewAggregate(err, childErr) + return nil, trace.NewAggregate(err, childErr) } child.disconnectExpiredCert = getDisconnectExpiredCertFromIdentityContext( @@ -475,7 +475,7 @@ func NewServerContext(ctx context.Context, parent *sshutils.ConnectionContext, s clusterName, err := srv.GetAccessPoint().GetClusterName() if err != nil { childErr := child.Close() - return nil, nil, trace.NewAggregate(err, childErr) + return nil, trace.NewAggregate(err, childErr) } monitorConfig := MonitorConfig{ @@ -503,14 +503,14 @@ func NewServerContext(ctx context.Context, parent *sshutils.ConnectionContext, s err = StartMonitor(monitorConfig) if err != nil { childErr := child.Close() - return nil, nil, trace.NewAggregate(err, childErr) + return nil, trace.NewAggregate(err, childErr) } // Create pipe used to send command to child process. child.cmdr, child.cmdw, err = os.Pipe() if err != nil { childErr := child.Close() - return nil, nil, trace.NewAggregate(err, childErr) + return nil, trace.NewAggregate(err, childErr) } child.AddCloser(child.cmdr) child.AddCloser(child.cmdw) @@ -519,7 +519,7 @@ func NewServerContext(ctx context.Context, parent *sshutils.ConnectionContext, s child.contr, child.contw, err = os.Pipe() if err != nil { childErr := child.Close() - return nil, nil, trace.NewAggregate(err, childErr) + return nil, trace.NewAggregate(err, childErr) } child.AddCloser(child.contr) child.AddCloser(child.contw) @@ -528,7 +528,7 @@ func NewServerContext(ctx context.Context, parent *sshutils.ConnectionContext, s child.readyr, child.readyw, err = os.Pipe() if err != nil { childErr := child.Close() - return nil, nil, trace.NewAggregate(err, childErr) + return nil, trace.NewAggregate(err, childErr) } child.AddCloser(child.readyr) child.AddCloser(child.readyw) @@ -536,12 +536,12 @@ func NewServerContext(ctx context.Context, parent *sshutils.ConnectionContext, s child.killShellr, child.killShellw, err = os.Pipe() if err != nil { childErr := child.Close() - return nil, nil, trace.NewAggregate(err, childErr) + return nil, trace.NewAggregate(err, childErr) } child.AddCloser(child.killShellr) child.AddCloser(child.killShellw) - return ctx, child, nil + return child, nil } // Parent grants access to the connection-level context of which this @@ -948,6 +948,15 @@ func (c *ServerContext) String() string { return fmt.Sprintf("ServerContext(%v->%v, user=%v, id=%v)", c.ServerConn.RemoteAddr(), c.ServerConn.LocalAddr(), c.ServerConn.User(), c.id) } +func (c *ServerContext) LogValue() slog.Value { + return slog.GroupValue( + slog.String("remote_addr", c.ServerConn.RemoteAddr().String()), + slog.String("local_addr", c.ServerConn.LocalAddr().String()), + slog.String("user", c.ServerConn.User()), + slog.Int("id", c.id), + ) +} + func getPAMConfig(c *ServerContext) (*PAMConfig, error) { // PAM should be disabled. if c.srv.Component() != teleport.ComponentNode { diff --git a/lib/srv/forward/sshserver.go b/lib/srv/forward/sshserver.go index 978be8c89ea32..1691c1377f954 100644 --- a/lib/srv/forward/sshserver.go +++ b/lib/srv/forward/sshserver.go @@ -909,7 +909,7 @@ func (s *Server) handleForwardedTCPIPRequest(ctx context.Context, nch ssh.NewCha // Create context for this channel. This context will be closed when // forwarding is complete. - ctx, scx, err := srv.NewServerContext(ctx, s.connectionContext, s, s.identityContext) + scx, err := srv.NewServerContext(ctx, s.connectionContext, s, s.identityContext) if err != nil { if err := nch.Reject(ssh.ConnectionFailed, "failed to open server context"); err != nil { s.log.WithError(err).Errorf("Error rejecting %s channel.", teleport.ChanForwardedTCPIP) @@ -1070,7 +1070,7 @@ func (s *Server) handleChannel(ctx context.Context, nch ssh.NewChannel) { func (s *Server) handleDirectTCPIPRequest(ctx context.Context, ch ssh.Channel, req *sshutils.DirectTCPIPReq) { // Create context for this channel. This context will be closed when // forwarding is complete. - ctx, scx, err := srv.NewServerContext(ctx, s.connectionContext, s, s.identityContext) + scx, err := srv.NewServerContext(ctx, s.connectionContext, s, s.identityContext) if err != nil { s.log.Errorf("Unable to create connection context: %v.", err) s.stderrWrite(ch, "Unable to create connection context.") @@ -1121,7 +1121,7 @@ func (s *Server) handleSessionChannel(ctx context.Context, nch ssh.NewChannel) { // There is no need for the forwarding server to initiate disconnects, // based on teleport business logic, because this logic is already // done on the server's terminating side. - ctx, scx, err := srv.NewServerContext(ctx, s.connectionContext, s, s.identityContext) + scx, err := srv.NewServerContext(ctx, s.connectionContext, s, s.identityContext) if err != nil { s.log.Warnf("Server context setup failed: %v", err) if err := nch.Reject(ssh.ConnectionFailed, fmt.Sprintf("server context setup failed: %v", err)); err != nil { diff --git a/lib/srv/regular/fuzz_test.go b/lib/srv/regular/fuzz_test.go index 892e95fce25a9..c1ab280ac0f39 100644 --- a/lib/srv/regular/fuzz_test.go +++ b/lib/srv/regular/fuzz_test.go @@ -19,11 +19,14 @@ package regular import ( + "context" + "log/slog" "testing" "github.com/stretchr/testify/require" "github.com/gravitational/teleport/lib/srv" + logutils "github.com/gravitational/teleport/lib/utils/log" ) func FuzzParseProxySubsys(f *testing.F) { @@ -40,12 +43,13 @@ func FuzzParseProxySubsys(f *testing.F) { server := &Server{ hostname: "redhorse", proxyMode: true, + logger: slog.New(logutils.DiscardHandler{}), } ctx := &srv.ServerContext{} require.NotPanics(t, func() { - parseProxySubsys(request, server, ctx) + server.parseProxySubsys(context.Background(), request, ctx) }) }) } diff --git a/lib/srv/regular/proxy.go b/lib/srv/regular/proxy.go index c55e05b3ea787..1e421d54748a8 100644 --- a/lib/srv/regular/proxy.go +++ b/lib/srv/regular/proxy.go @@ -21,11 +21,11 @@ package regular import ( "context" "fmt" + "log/slog" "net" "strings" "github.com/gravitational/trace" - "github.com/sirupsen/logrus" "golang.org/x/crypto/ssh" "github.com/gravitational/teleport" @@ -53,7 +53,7 @@ type proxySubsys struct { proxySubsysRequest router *proxy.Router ctx *srv.ServerContext - log *logrus.Entry + logger *slog.Logger closeC chan error proxySigner PROXYHeaderSigner localCluster string @@ -68,8 +68,8 @@ type proxySubsys struct { // "proxy:@clustername" - Teleport request to connect to an auth server for cluster with name 'clustername' // "proxy:host:22@clustername" - Teleport request to connect to host:22 on cluster 'clustername' // "proxy:host:22@namespace@clustername" -func parseProxySubsysRequest(request string) (proxySubsysRequest, error) { - log.Debugf("parse_proxy_subsys(%q)", request) +func (s *Server) parseProxySubsysRequest(ctx context.Context, request string) (proxySubsysRequest, error) { + s.logger.DebugContext(ctx, "parsing proxy subsystem request", "request", request) var ( clusterName string targetHost string @@ -124,12 +124,12 @@ func parseProxySubsysRequest(request string) (proxySubsysRequest, error) { // parseProxySubsys decodes a proxy subsystem request and sets up a proxy subsystem instance. // See parseProxySubsysRequest for details on the request format. -func parseProxySubsys(request string, srv *Server, ctx *srv.ServerContext) (*proxySubsys, error) { - req, err := parseProxySubsysRequest(request) +func (s *Server) parseProxySubsys(ctx context.Context, request string, serverContext *srv.ServerContext) (*proxySubsys, error) { + req, err := s.parseProxySubsysRequest(ctx, request) if err != nil { return nil, trace.Wrap(err) } - subsys, err := newProxySubsys(ctx, srv, req) + subsys, err := newProxySubsys(ctx, serverContext, s, req) if err != nil { return nil, trace.Wrap(err) } @@ -163,16 +163,17 @@ func (p *proxySubsysRequest) SetDefaults() { // newProxySubsys is a helper that creates a proxy subsystem from // a port forwarding request, used to implement ProxyJump feature in proxy // and reuse the code -func newProxySubsys(ctx *srv.ServerContext, srv *Server, req proxySubsysRequest) (*proxySubsys, error) { +func newProxySubsys(ctx context.Context, serverContext *srv.ServerContext, srv *Server, req proxySubsysRequest) (*proxySubsys, error) { req.SetDefaults() - if req.clusterName == "" && ctx.Identity.RouteToCluster != "" { - log.Debugf("Proxy subsystem: routing user %q to cluster %q based on the route to cluster extension.", - ctx.Identity.TeleportUser, ctx.Identity.RouteToCluster, + if req.clusterName == "" && serverContext.Identity.RouteToCluster != "" { + srv.logger.DebugContext(ctx, "Proxy subsystem: routing user to cluster based on the route to cluster extension", + "user", serverContext.Identity.TeleportUser, + "cluster", serverContext.Identity.RouteToCluster, ) - req.clusterName = ctx.Identity.RouteToCluster + req.clusterName = serverContext.Identity.RouteToCluster } if req.clusterName != "" && srv.proxyTun != nil { - checker, err := srv.tunnelWithAccessChecker(ctx) + checker, err := srv.tunnelWithAccessChecker(serverContext) if err != nil { return nil, trace.Wrap(err) } @@ -181,18 +182,15 @@ func newProxySubsys(ctx *srv.ServerContext, srv *Server, req proxySubsysRequest) return nil, trace.BadParameter("invalid format for proxy request: unknown cluster %q", req.clusterName) } } - log.Debugf("newProxySubsys(%v).", req) + srv.logger.DebugContext(ctx, "successfully created proxy subsystem request", "request", &req) return &proxySubsys{ proxySubsysRequest: req, - ctx: ctx, - log: logrus.WithFields(logrus.Fields{ - teleport.ComponentKey: teleport.ComponentSubsystemProxy, - teleport.ComponentFields: map[string]string{}, - }), - closeC: make(chan error), - router: srv.router, - proxySigner: srv.proxySigner, - localCluster: ctx.ClusterName, + ctx: serverContext, + logger: slog.With(teleport.ComponentKey, teleport.ComponentSubsystemProxy), + closeC: make(chan error), + router: srv.router, + proxySigner: srv.proxySigner, + localCluster: serverContext.ClusterName, }, nil } @@ -205,15 +203,12 @@ func (t *proxySubsys) String() string { // a mapping connection between a client & remote node we're proxying to) func (t *proxySubsys) Start(ctx context.Context, sconn *ssh.ServerConn, ch ssh.Channel, req *ssh.Request, serverContext *srv.ServerContext) error { // once we start the connection, update logger to include component fields - t.log = logrus.WithFields(logrus.Fields{ - teleport.ComponentKey: teleport.ComponentSubsystemProxy, - teleport.ComponentFields: map[string]string{ - "src": sconn.RemoteAddr().String(), - "dst": sconn.LocalAddr().String(), - "subsystem": t.String(), - }, - }) - t.log.Debugf("Starting subsystem") + t.logger = t.logger.With( + "src", sconn.RemoteAddr().String(), + "dst", sconn.LocalAddr().String(), + "subsystem", t.String(), + ) + t.logger.DebugContext(ctx, "Starting subsystem") clientAddr := sconn.RemoteAddr() @@ -229,13 +224,13 @@ func (t *proxySubsys) Start(ctx context.Context, sconn *ssh.ServerConn, ch ssh.C // proxyToSite establishes a proxy connection from the connected SSH client to the // auth server of the requested remote site func (t *proxySubsys) proxyToSite(ctx context.Context, ch ssh.Channel, clusterName string, clientSrcAddr, clientDstAddr net.Addr) error { - t.log.Debugf("Connecting from cluster %q to site: %q", t.localCluster, clusterName) + t.logger.DebugContext(ctx, "attempting to proxy connection to auth server", "local_cluster", t.localCluster, "proxied_cluster", clusterName) conn, err := t.router.DialSite(ctx, clusterName, clientSrcAddr, clientDstAddr) if err != nil { return trace.Wrap(err) } - t.log.Infof("Connected to cluster %v at %v", clusterName, conn.RemoteAddr()) + t.logger.InfoContext(ctx, "Connected to cluster", "cluster", clusterName, "address", conn.RemoteAddr()) go func() { t.close(utils.ProxyConn(ctx, ch, conn)) @@ -246,7 +241,7 @@ func (t *proxySubsys) proxyToSite(ctx context.Context, ch ssh.Channel, clusterNa // proxyToHost establishes a proxy connection from the connected SSH client to the // requested remote node (t.host:t.port) via the given site func (t *proxySubsys) proxyToHost(ctx context.Context, ch ssh.Channel, clientSrcAddr, clientDstAddr net.Addr) error { - t.log.Debugf("proxy connecting to host=%v port=%v, exact port=%v", t.host, t.port, t.SpecifiedPort()) + t.logger.DebugContext(ctx, "proxying connection to target host", "host", t.host, "port", t.port, "exact_port", t.SpecifiedPort()) authClient, err := t.router.GetSiteClient(ctx, t.localCluster) if err != nil { diff --git a/lib/srv/regular/proxy_test.go b/lib/srv/regular/proxy_test.go index 3333d2f79de75..178fedccdcae9 100644 --- a/lib/srv/regular/proxy_test.go +++ b/lib/srv/regular/proxy_test.go @@ -19,12 +19,15 @@ package regular import ( + "context" + "log/slog" "testing" "github.com/stretchr/testify/require" apidefaults "github.com/gravitational/teleport/api/defaults" "github.com/gravitational/teleport/lib/srv" + logutils "github.com/gravitational/teleport/lib/utils/log" ) func TestParseProxyRequest(t *testing.T) { @@ -86,6 +89,12 @@ func TestParseProxyRequest(t *testing.T) { }, } + server := &Server{ + hostname: "redhorse", + proxyMode: true, + logger: slog.New(logutils.DiscardHandler{}), + } + for i, tt := range testCases { t.Run(tt.desc, func(t *testing.T) { if tt.expected.namespace == "" { @@ -94,7 +103,7 @@ func TestParseProxyRequest(t *testing.T) { // never actually be empty. tt.expected.namespace = apidefaults.Namespace } - req, err := parseProxySubsysRequest(tt.req) + req, err := server.parseProxySubsysRequest(context.Background(), tt.req) require.NoError(t, err, "Test case %d: req=%s, expected=%+v", i, tt.req, tt.expected) require.Equal(t, tt.expected, req, "Test case %d: req=%s, expected=%+v", i, tt.req, tt.expected) }) @@ -107,6 +116,7 @@ func TestParseBadRequests(t *testing.T) { server := &Server{ hostname: "redhorse", proxyMode: true, + logger: slog.New(logutils.DiscardHandler{}), } ctx := &srv.ServerContext{} @@ -122,7 +132,7 @@ func TestParseBadRequests(t *testing.T) { } for _, tt := range testCases { t.Run(tt.desc, func(t *testing.T) { - subsystem, err := parseProxySubsys(tt.input, server, ctx) + subsystem, err := server.parseProxySubsys(context.Background(), tt.input, ctx) require.Error(t, err, "test case: %q", tt.input) require.Nil(t, subsystem, "test case: %q", tt.input) }) diff --git a/lib/srv/regular/sftp.go b/lib/srv/regular/sftp.go index f3f194ab16ae0..456c805b5ee51 100644 --- a/lib/srv/regular/sftp.go +++ b/lib/srv/regular/sftp.go @@ -24,13 +24,13 @@ import ( "encoding/json" "errors" "io" + "log/slog" "os" "os/exec" "time" "github.com/gogo/protobuf/jsonpb" "github.com/gravitational/trace" - "github.com/sirupsen/logrus" "golang.org/x/crypto/ssh" "github.com/gravitational/teleport" @@ -45,7 +45,7 @@ import ( const copyingGoroutines = 2 type sftpSubsys struct { - log *logrus.Entry + logger *slog.Logger fileTransferReq *srv.FileTransferRequest sftpCmd *exec.Cmd @@ -55,9 +55,7 @@ type sftpSubsys struct { func newSFTPSubsys(fileTransferReq *srv.FileTransferRequest) (*sftpSubsys, error) { return &sftpSubsys{ - log: logrus.WithFields(logrus.Fields{ - teleport.ComponentKey: teleport.ComponentSubsystemSFTP, - }), + logger: slog.With(teleport.ComponentKey, teleport.ComponentSubsystemSFTP), fileTransferReq: fileTransferReq, }, nil } @@ -125,7 +123,7 @@ func (s *sftpSubsys) Start(ctx context.Context, s.sftpCmd.Stdout = os.Stdout s.sftpCmd.Stderr = os.Stderr - s.log.Debug("starting SFTP process") + s.logger.DebugContext(ctx, "starting SFTP process") err = s.sftpCmd.Start() if err != nil { return trace.Wrap(err) @@ -184,7 +182,7 @@ func (s *sftpSubsys) Start(ctx context.Context, eventStr, err := r.ReadString(0x0) if err != nil { if !errors.Is(err, io.EOF) { - s.log.WithError(err).Warn("Failed to read SFTP event.") + s.logger.WarnContext(ctx, "Failed to read SFTP event", "error", err) } return } @@ -192,12 +190,12 @@ func (s *sftpSubsys) Start(ctx context.Context, var oneOfEvent apievents.OneOf err = jsonpb.UnmarshalString(eventStr[:len(eventStr)-1], &oneOfEvent) if err != nil { - s.log.WithError(err).Warn("Failed to unmarshal SFTP event.") + s.logger.WarnContext(ctx, "Failed to unmarshal SFTP event", "error", err) continue } event, err := apievents.FromOneOf(oneOfEvent) if err != nil { - s.log.WithError(err).Warn("Failed to convert SFTP event from OneOf.") + s.logger.WarnContext(ctx, "Failed to convert SFTP event from OneOf", "error", err) continue } @@ -214,11 +212,11 @@ func (s *sftpSubsys) Start(ctx context.Context, e.UserMetadata = userMeta e.ConnectionMetadata = connectionMeta default: - s.log.WithError(err).Warnf("Unknown event type received from SFTP server process: %q", event.GetType()) + s.logger.WarnContext(ctx, "Unknown event type received from SFTP server process", "error", err, "event_type", event.GetType()) } if err := serverCtx.GetServer().EmitAuditEvent(ctx, event); err != nil { - log.WithError(err).Warn("Failed to emit SFTP event.") + s.logger.WarnContext(ctx, "Failed to emit SFTP event", "error", err) } } }() @@ -227,8 +225,9 @@ func (s *sftpSubsys) Start(ctx context.Context, } func (s *sftpSubsys) Wait() error { + ctx := context.Background() waitErr := s.sftpCmd.Wait() - s.log.Debug("SFTP process finished") + s.logger.DebugContext(ctx, "SFTP process finished") s.serverCtx.SendExecResult(srv.ExecResult{ Command: s.sftpCmd.String(), @@ -239,7 +238,7 @@ func (s *sftpSubsys) Wait() error { for i := 0; i < copyingGoroutines; i++ { err := <-s.errCh if err != nil && !utils.IsOKNetworkError(err) { - s.log.WithError(err).Warn("Connection problem.") + s.logger.WarnContext(ctx, "Connection problem", "error", err) errs = append(errs, err) } } diff --git a/lib/srv/regular/sites.go b/lib/srv/regular/sites.go index 5e80844365eb5..029ca982af845 100644 --- a/lib/srv/regular/sites.go +++ b/lib/srv/regular/sites.go @@ -53,7 +53,7 @@ func (t *proxySitesSubsys) Wait() error { // Start serves a request for "proxysites" custom SSH subsystem. It builds an array of // service.Site structures, and writes it serialized as JSON back to the SSH client func (t *proxySitesSubsys) Start(ctx context.Context, sconn *ssh.ServerConn, ch ssh.Channel, req *ssh.Request, serverContext *srv.ServerContext) error { - log.Debugf("proxysites.start(%v)", serverContext) + t.srv.logger.DebugContext(ctx, "starting proxysites subsystem", "server_context", serverContext) checker, err := t.srv.tunnelWithAccessChecker(serverContext) if err != nil { return trace.Wrap(err) diff --git a/lib/srv/regular/sshserver.go b/lib/srv/regular/sshserver.go index a4bbd56a552df..d80c143e96118 100644 --- a/lib/srv/regular/sshserver.go +++ b/lib/srv/regular/sshserver.go @@ -38,7 +38,6 @@ import ( "github.com/gravitational/trace" "github.com/jonboulle/clockwork" - "github.com/sirupsen/logrus" semconv "go.opentelemetry.io/otel/semconv/v1.10.0" oteltrace "go.opentelemetry.io/otel/trace" "golang.org/x/crypto/ssh" @@ -74,16 +73,12 @@ import ( "github.com/gravitational/teleport/lib/utils/hostid" ) -var log = logrus.WithFields(logrus.Fields{ - teleport.ComponentKey: teleport.ComponentNode, -}) - // Server implements SSH server that uses configuration backend and // certificate-based authentication type Server struct { sync.Mutex - *logrus.Entry + logger *slog.Logger namespace string addr utils.NetAddr @@ -333,7 +328,7 @@ func (s *Server) close() { s.reg.Close() if s.heartbeat != nil { if err := s.heartbeat.Close(); err != nil { - s.Warningf("Failed to close heartbeat: %v", err) + s.logger.WarnContext(s.ctx, "Failed to close heartbeat", "error", err) } } if s.dynamicLabels != nil { @@ -368,7 +363,7 @@ func (s *Server) Shutdown(ctx context.Context) error { // from making the server appear alive and well. if s.heartbeat != nil { if err := s.heartbeat.Close(); err != nil { - s.Warningf("Failed to close heartbeat: %v", err) + s.logger.WarnContext(ctx, "Failed to close heartbeat", "error", err) } } @@ -792,10 +787,7 @@ func New( component = teleport.ComponentNode } - s.Entry = logrus.WithFields(logrus.Fields{ - teleport.ComponentKey: component, - teleport.ComponentFields: logrus.Fields{}, - }) + s.logger = slog.With(teleport.ComponentKey, component) if s.GetCreateHostUser() { s.users = srv.NewHostUsers(ctx, s.storage, s.ID()) @@ -858,7 +850,7 @@ func New( if !s.proxyMode { if err := s.startAuthorizedKeysManager(ctx, auth); err != nil { - log.WithError(err).Infof("Failed to start authorized keys manager.") + s.logger.InfoContext(ctx, "Failed to start authorized keys manager", "error", err) } } @@ -871,14 +863,14 @@ func New( var heartbeat srv.HeartbeatI if heartbeatMode == srv.HeartbeatModeNode && s.inventoryHandle != nil { - s.Logger.Debug("starting control-stream based heartbeat.") + s.logger.DebugContext(ctx, "starting control-stream based heartbeat") heartbeat, err = srv.NewSSHServerHeartbeat(srv.HeartbeatV2Config[*types.ServerV2]{ InventoryHandle: s.inventoryHandle, GetResource: s.getServerInfo, OnHeartbeat: s.onHeartbeat, }) } else { - s.Logger.Debug("starting legacy heartbeat.") + s.logger.DebugContext(ctx, "starting legacy heartbeat") heartbeat, err = srv.NewHeartbeat(srv.HeartbeatConfig{ Mode: heartbeatMode, Context: ctx, @@ -935,7 +927,7 @@ func (s *Server) startAuthorizedKeysManager(ctx context.Context, auth authclient go func() { if err := authorizedKeysWatcher.Run(ctx); err != nil { - s.Warningf("Failed to start authorized keys watcher: %v", err) + s.logger.WarnContext(ctx, "Failed to start authorized keys watcher", "error", err) } }() return nil @@ -1005,7 +997,7 @@ func (s *Server) AdvertiseAddr() string { _, port, _ := net.SplitHostPort(listenAddr) ahost, aport, err := utils.ParseAdvertiseAddr(advertiseAddr.String()) if err != nil { - s.Logger.Warningf("Failed to parse advertise address %q, %v, using default value %q.", advertiseAddr, err, listenAddr) + s.logger.WarnContext(s.ctx, "Failed to parse advertise address, using default value", "advertise_addr", advertiseAddr, "error", err, "default_addr", listenAddr) return listenAddr } if aport == "" { @@ -1094,13 +1086,13 @@ func (s *Server) getBasicInfo() *types.ServerV2 { return srv } -func (s *Server) getServerInfo(context.Context) (*types.ServerV2, error) { +func (s *Server) getServerInfo(ctx context.Context) (*types.ServerV2, error) { server := s.getBasicInfo() if s.getRotation != nil { rotation, err := s.getRotation(s.getRole()) if err != nil { if !trace.IsNotFound(err) { - s.Logger.Warningf("Failed to get rotation state: %v", err) + s.logger.WarnContext(ctx, "Failed to get rotation state", "error", err) } } else { server.SetRotation(*rotation) @@ -1176,7 +1168,7 @@ func (s *Server) getNetworkingProcess(scx *srv.ServerContext) (*networking.Proce // the server connection is closed. func (s *Server) startNetworkingProcess(scx *srv.ServerContext) (*networking.Process, error) { // Create context for the networking process. - _, nsctx, err := srv.NewServerContext(context.Background(), scx.ConnectionContext, s, scx.Identity) + nsctx, err := srv.NewServerContext(context.Background(), scx.ConnectionContext, s, scx.Identity) if err != nil { return nil, trace.Wrap(err) } @@ -1210,44 +1202,44 @@ func (s *Server) HandleRequest(ctx context.Context, ccx *sshutils.ConnectionCont case teleport.ClusterDetailsReqType: s.handleClusterDetails(ctx, r) case teleport.VersionRequest: - s.handleVersionRequest(r) + s.handleVersionRequest(ctx, r) case teleport.TerminalSizeRequest: if err := s.termHandlers.HandleTerminalSize(r); err != nil { - s.Logger.WithError(err).Warn("failed to handle terminal size request") + s.logger.WarnContext(ctx, "failed to handle terminal size request", "error", err) if r.WantReply { if err := r.Reply(false, nil); err != nil { - s.Logger.Warnf("Failed to reply to %q request: %v", r.Type, err) + s.logger.WarnContext(ctx, "Failed to reply to terminal size request", "error", err) } } } case teleport.TCPIPForwardRequest: if err := s.handleTCPIPForwardRequest(ctx, ccx, r); err != nil { - s.Logger.WithError(err).Warn("failed to handle tcpip forward request") + s.logger.WarnContext(ctx, "failed to handle tcpip forward request", "error", err) if err := r.Reply(false, nil); err != nil { - s.Logger.Warnf("Failed to reply to %q request: %v", r.Type, err) + s.logger.WarnContext(ctx, "Failed to reply to tcpip forward request", "error", err) } } case teleport.CancelTCPIPForwardRequest: if err := s.handleCancelTCPIPForwardRequest(ctx, ccx, r); err != nil { - s.Logger.WithError(err).Warn("failed to handle cancel tcpip forward request") + s.logger.WarnContext(ctx, "failed to handle cancel tcpip forward request", "error", err) if err := r.Reply(false, nil); err != nil { - s.Logger.Warnf("Failed to reply to %q request: %v", r.Type, err) + s.logger.WarnContext(ctx, "Failed to reply to tcpip forward request", "error", err) } } case teleport.SessionIDQueryRequest: // Reply true to session ID query requests, we will set new // session IDs for new sessions if err := r.Reply(true, nil); err != nil { - s.Logger.WithError(err).Warnf("Failed to reply to session ID query request") + s.logger.WarnContext(ctx, "Failed to reply to session ID query request", "error", err) } return default: if r.WantReply { if err := r.Reply(false, nil); err != nil { - s.Logger.Warnf("Failed to reply to %q request: %v", r.Type, err) + s.logger.WarnContext(ctx, "Failed to reply to ssh request", "request_type", r.Type, "error", err) } } - s.Logger.Debugf("Discarding %q global request: %+v", r.Type, r) + s.logger.DebugContext(ctx, "Discarding global request", "request_type", r.Type) } } @@ -1268,7 +1260,7 @@ func (s *Server) HandleNewConn(ctx context.Context, ccx *sshutils.ConnectionCont // Create host user. created, userCloser, err := s.termHandlers.SessionRegistry.UpsertHostUser(identityContext) if err != nil { - log.Warnf("error while creating host users: %s", err) + s.logger.WarnContext(ctx, "error while creating host users", "error", err) } // Indicate that the user was created by Teleport. @@ -1279,7 +1271,7 @@ func (s *Server) HandleNewConn(ctx context.Context, ccx *sshutils.ConnectionCont sudoersCloser, err := s.termHandlers.SessionRegistry.WriteSudoersFile(identityContext) if err != nil { - log.Warnf("error while writing sudoers: %s", err) + s.logger.WarnContext(ctx, "error while writing sudoers", "error", err) } if sudoersCloser != nil { @@ -1293,7 +1285,7 @@ func (s *Server) HandleNewConn(ctx context.Context, ccx *sshutils.ConnectionCont func (s *Server) HandleNewChan(ctx context.Context, ccx *sshutils.ConnectionContext, nch ssh.NewChannel) { identityContext, err := s.authHandlers.CreateIdentityContext(ccx.ServerConn) if err != nil { - rejectChannel(nch, ssh.Prohibited, fmt.Sprintf("Unable to create identity from connection: %v", err)) + s.rejectChannel(ctx, nch, ssh.Prohibited, fmt.Sprintf("Unable to create identity from connection: %v", err)) return } @@ -1305,14 +1297,14 @@ func (s *Server) HandleNewChan(ctx context.Context, ccx *sshutils.ConnectionCont case teleport.ChanDirectTCPIP: req, err := sshutils.ParseDirectTCPIPReq(nch.ExtraData()) if err != nil { - s.Logger.Errorf("Failed to parse request data: %v, err: %v.", string(nch.ExtraData()), err) - rejectChannel(nch, ssh.UnknownChannelType, "failed to parse direct-tcpip request") + s.logger.ErrorContext(ctx, "Failed to parse request data", "data", string(nch.ExtraData()), "error", err) + s.rejectChannel(ctx, nch, ssh.UnknownChannelType, "failed to parse direct-tcpip request") return } ch, reqC, err := nch.Accept() if err != nil { - s.Logger.Warnf("Unable to accept channel: %v.", err) - rejectChannel(nch, ssh.ConnectionFailed, fmt.Sprintf("unable to accept channel: %v", err)) + s.logger.WarnContext(ctx, "Unable to accept channel", "error", err) + s.rejectChannel(ctx, nch, ssh.ConnectionFailed, fmt.Sprintf("unable to accept channel: %v", err)) return } go ssh.DiscardRequests(reqC) @@ -1324,14 +1316,14 @@ func (s *Server) HandleNewChan(ctx context.Context, ccx *sshutils.ConnectionCont case teleport.ChanSession: ch, requests, err := nch.Accept() if err != nil { - s.Logger.Warnf("Unable to accept channel: %v.", err) - rejectChannel(nch, ssh.ConnectionFailed, fmt.Sprintf("unable to accept channel: %v", err)) + s.logger.WarnContext(ctx, "Unable to accept channel", "error", err) + s.rejectChannel(ctx, nch, ssh.ConnectionFailed, fmt.Sprintf("unable to accept channel: %v", err)) return } go s.handleSessionRequests(ctx, ccx, identityContext, ch, requests) return default: - rejectChannel(nch, ssh.UnknownChannelType, fmt.Sprintf("unknown channel type: %v", channelType)) + s.rejectChannel(ctx, nch, ssh.UnknownChannelType, fmt.Sprintf("unknown channel type: %v", channelType)) return } } @@ -1364,17 +1356,17 @@ func (s *Server) HandleNewChan(ctx context.Context, ccx *sshutils.ConnectionCont Reason: events.SessionRejectedReasonMaxSessions, Maximum: max, }); err != nil { - s.Logger.WithError(err).Warn("Failed to emit session reject event.") + s.logger.WarnContext(ctx, "Failed to emit session reject event", "error", err) } - rejectChannel(nch, ssh.Prohibited, fmt.Sprintf("too many session channels for user %q (max=%d)", identityContext.TeleportUser, max)) + s.rejectChannel(ctx, nch, ssh.Prohibited, fmt.Sprintf("too many session channels for user %q (max=%d)", identityContext.TeleportUser, max)) return } decr = d } ch, requests, err := nch.Accept() if err != nil { - s.Logger.Warnf("Unable to accept channel: %v.", err) - rejectChannel(nch, ssh.ConnectionFailed, fmt.Sprintf("unable to accept channel: %v", err)) + s.logger.WarnContext(ctx, "Unable to accept channel", "error", err) + s.rejectChannel(ctx, nch, ssh.ConnectionFailed, fmt.Sprintf("unable to accept channel: %v", err)) if decr != nil { decr() } @@ -1392,28 +1384,29 @@ func (s *Server) HandleNewChan(ctx context.Context, ccx *sshutils.ConnectionCont // SessionJoinPrincipal should be rejected, otherwise it's possible // to use the "-teleport-internal-join" user to bypass RBAC. if identityContext.Login == teleport.SSHSessionJoinPrincipal { - s.Logger.Error("Connection rejected, direct-tcpip with SessionJoinPrincipal in regular node must be blocked") - rejectChannel( + s.logger.ErrorContext(ctx, "Connection rejected, direct-tcpip with SessionJoinPrincipal in regular node must be blocked") + s.rejectChannel( + ctx, nch, ssh.Prohibited, fmt.Sprintf("attempted %v channel open in join-only mode", channelType)) return } req, err := sshutils.ParseDirectTCPIPReq(nch.ExtraData()) if err != nil { - s.Logger.Errorf("Failed to parse request data: %v, err: %v.", string(nch.ExtraData()), err) - rejectChannel(nch, ssh.UnknownChannelType, "failed to parse direct-tcpip request") + s.logger.ErrorContext(ctx, "Failed to parse request data", "data", string(nch.ExtraData()), "error", err) + s.rejectChannel(ctx, nch, ssh.UnknownChannelType, "failed to parse direct-tcpip request") return } ch, reqC, err := nch.Accept() if err != nil { - s.Logger.Warnf("Unable to accept channel: %v.", err) - rejectChannel(nch, ssh.ConnectionFailed, fmt.Sprintf("unable to accept channel: %v", err)) + s.logger.WarnContext(ctx, "Unable to accept channel", "error", err) + s.rejectChannel(ctx, nch, ssh.ConnectionFailed, fmt.Sprintf("unable to accept channel: %v", err)) return } go ssh.DiscardRequests(reqC) go s.handleDirectTCPIPRequest(ctx, ccx, identityContext, ch, req) default: - rejectChannel(nch, ssh.UnknownChannelType, fmt.Sprintf("unknown channel type: %v", channelType)) + s.rejectChannel(ctx, nch, ssh.UnknownChannelType, fmt.Sprintf("unknown channel type: %v", channelType)) } } @@ -1438,11 +1431,11 @@ func (s *Server) canPortForward(scx *srv.ServerContext) error { // stderrWriter wraps an ssh.Channel in an implementation of io.StringWriter // that sends anything written back the client over its stderr stream type stderrWriter struct { - channel ssh.Channel + writer func(s string) } func (w *stderrWriter) WriteString(s string) (int, error) { - writeStderr(w.channel, s) + w.writer(s) return len(s), nil } @@ -1450,12 +1443,12 @@ func (w *stderrWriter) WriteString(s string) (int, error) { func (s *Server) handleDirectTCPIPRequest(ctx context.Context, ccx *sshutils.ConnectionContext, identityContext srv.IdentityContext, channel ssh.Channel, req *sshutils.DirectTCPIPReq) { // Create context for this channel. This context will be closed when // forwarding is complete. - ctx, scx, err := srv.NewServerContext(ctx, ccx, s, identityContext) + scx, err := srv.NewServerContext(ctx, ccx, s, identityContext) if err != nil { - s.Logger.WithError(err).Error("Unable to create connection context.") - writeStderr(channel, "Unable to create connection context.") + s.logger.ErrorContext(ctx, "Unable to create connection context", "error", err) + s.writeStderr(ctx, channel, "Unable to create connection context.") if err := channel.Close(); err != nil { - s.Logger.WithError(err).Warn("Failed to close channel.") + s.logger.WarnContext(ctx, "Failed to close channel", "error", err) } return } @@ -1473,7 +1466,7 @@ func (s *Server) handleDirectTCPIPRequest(ctx context.Context, ccx *sshutils.Con // Bail out now if TCP port forwarding is not allowed for this node/user/role // combo if err = s.canPortForward(scx); err != nil { - writeStderr(channel, err.Error()) + s.writeStderr(ctx, channel, err.Error()) return } @@ -1484,20 +1477,20 @@ func (s *Server) handleDirectTCPIPRequest(ctx context.Context, ccx *sshutils.Con 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.Warnf("Forwarding data via direct-tcpip channel failed. Terminating connection because user %q does not exist", scx.Identity.Login) + s.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.Warnf("Unable to terminate connection: %v", err) + s.logger.WarnContext(ctx, "Unable to terminate connection", "error", err) } return } - s.Logger.WithError(err).Error("Forwarding data via direct-tcpip channel failed") - writeStderr(channel, err.Error()) + s.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.Warnf("Connection problem in direct-tcpip channel: %v %T.", trace.DebugReport(err), err) + s.logger.WarnContext(ctx, "Connection problem in direct-tcpip channel", "error", err) } if err := s.EmitAuditEvent(s.ctx, &apievents.PortForward{ @@ -1515,7 +1508,7 @@ func (s *Server) handleDirectTCPIPRequest(ctx context.Context, ccx *sshutils.Con Success: true, }, }); err != nil { - s.Logger.WithError(err).Warn("Failed to emit port forward event.") + s.logger.WarnContext(ctx, "Failed to emit port forward event", "error", err) } } @@ -1525,22 +1518,22 @@ func (s *Server) handleDirectTCPIPRequest(ctx context.Context, ccx *sshutils.Con func (s *Server) handleSessionRequests(ctx context.Context, ccx *sshutils.ConnectionContext, identityContext srv.IdentityContext, ch ssh.Channel, in <-chan *ssh.Request) { netConfig, err := s.GetAccessPoint().GetClusterNetworkingConfig(ctx) if err != nil { - s.Logger.Errorf("Unable to fetch cluster networking config: %v.", err) - writeStderr(ch, "Unable to fetch cluster networking configuration.") + s.logger.ErrorContext(ctx, "Unable to fetch cluster networking config", "error", err) + s.writeStderr(ctx, ch, "Unable to fetch cluster networking configuration.") return } // Create context for this channel. This context will be closed when the // session request is complete. - ctx, scx, err := srv.NewServerContext(ctx, ccx, s, identityContext, func(cfg *srv.MonitorConfig) { + scx, err := srv.NewServerContext(ctx, ccx, s, identityContext, func(cfg *srv.MonitorConfig) { cfg.IdleTimeoutMessage = netConfig.GetClientIdleTimeoutMessage() - cfg.MessageWriter = &stderrWriter{channel: ch} + cfg.MessageWriter = &stderrWriter{writer: func(msg string) { s.writeStderr(ctx, ch, msg) }} }) if err != nil { - s.Logger.WithError(err).Error("Unable to create connection context.") - writeStderr(ch, "Unable to create connection context.") + s.logger.ErrorContext(ctx, "Unable to create connection context", "error", err) + s.writeStderr(ctx, ch, "Unable to create connection context.") if err := ch.Close(); err != nil { - s.Logger.WithError(err).Warn("Failed to close channel.") + s.logger.WarnContext(ctx, "Failed to close channel", "error", err) } return } @@ -1550,7 +1543,7 @@ func (s *Server) handleSessionRequests(ctx context.Context, ccx *sshutils.Connec scx.SetAllowFileCopying(s.allowFileCopying) defer scx.Close() - ch = scx.TrackActivity(ch) + trackingChan := scx.TrackActivity(ch) // The keep-alive loop will keep pinging the remote server and after it has // missed a certain number of keep-alive requests it will cancel the @@ -1574,8 +1567,8 @@ func (s *Server) handleSessionRequests(ctx context.Context, ccx *sshutils.Connec scx.Errorf("Unable to update context: %v.", errorMessage) // write the error to channel and close it - writeStderr(ch, errorMessage) - _, err := ch.SendRequest("exit-status", false, ssh.Marshal(struct{ C uint32 }{C: teleport.RemoteCommandFailure})) + s.writeStderr(ctx, trackingChan, errorMessage) + _, 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) } @@ -1609,14 +1602,14 @@ func (s *Server) handleSessionRequests(ctx context.Context, ccx *sshutils.Connec // some functions called inside dispatch() may handle replies to SSH channel requests internally, // rather than leaving the reply to be handled inside this loop. in that case, those functions must // set req.WantReply to false so that two replies are not sent. - if err := s.dispatch(ctx, ch, req, scx); err != nil { - s.replyError(ch, req, err) + if err := s.dispatch(ctx, trackingChan, req, scx); err != nil { + s.replyError(ctx, trackingChan, req, err) span.End() return } if req.WantReply { if err := req.Reply(true, nil); err != nil { - s.Logger.Warnf("Failed to reply to %q request: %v", req.Type, err) + s.logger.WarnContext(ctx, "Failed to reply to request", "request_type", req.Type, "error", err) } } span.End() @@ -1625,14 +1618,14 @@ func (s *Server) handleSessionRequests(ctx context.Context, ccx *sshutils.Connec // The exec process has finished and delivered the execution result, send // the result back to the client, and close the session and channel. - _, err := ch.SendRequest("exit-status", false, ssh.Marshal(struct{ C uint32 }{C: uint32(result.Code)})) + _, 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) } return case <-ctx.Done(): - s.Logger.Debugf("Closing session due to cancellation.") + s.logger.DebugContext(ctx, "Closing session due to cancellation") return } } @@ -1658,7 +1651,7 @@ func (s *Server) dispatch(ctx context.Context, ch ssh.Channel, req *ssh.Request, // recording proxy mode. err := s.handleAgentForwardProxy(req, serverContext) if err != nil { - s.Logger.Warn(err) + s.logger.WarnContext(ctx, "Failure forwarding agent", "error", err) } return nil case sshutils.PuTTYSimpleRequest: @@ -1666,13 +1659,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.Debugf("%v: deliberately ignoring request for '%v' channel", s.Component(), sshutils.PuTTYSimpleRequest) + s.logger.DebugContext(ctx, "deliberately ignoring simple@putty.projects.tartarus.org request") return nil default: - s.Logger.Warnf("(%v) proxy doesn't support request type '%v'", s.Component(), req.Type) + 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.Errorf("sending error reply on SSH channel: %v", err) + s.logger.ErrorContext(ctx, "error sending reply on SSH channel", "error", err) } } return nil @@ -1711,11 +1704,11 @@ func (s *Server) dispatch(ctx context.Context, ch ssh.Channel, req *ssh.Request, // processing requests. err := s.handleAgentForwardNode(req, serverContext) if err != nil { - s.Logger.Warn(err) + s.logger.WarnContext(ctx, "failure forwarding agent", "error", err) } return nil case sshutils.PuTTYWinadjRequest: - return s.handlePuTTYWinadj(ch, req) + return s.handlePuTTYWinadj(ctx, req) default: return trace.AccessDenied("attempted %v request in join-only mode", req.Type) } @@ -1744,7 +1737,7 @@ func (s *Server) dispatch(ctx context.Context, ch ssh.Channel, req *ssh.Request, // they are in essence SSH session extensions, allowing to implement new SSH commands return s.handleSubsystem(ctx, ch, req, serverContext) case x11.ForwardRequest: - return s.handleX11Forward(ch, req, serverContext) + return s.handleX11Forward(ctx, ch, req, serverContext) case sshutils.AgentForwardRequest: // This happens when SSH client has agent forwarding enabled, in this case // client sends a special request, in return SSH server opens new channel @@ -1758,16 +1751,16 @@ func (s *Server) dispatch(ctx context.Context, ch ssh.Channel, req *ssh.Request, // processing requests. err := s.handleAgentForwardNode(req, serverContext) if err != nil { - s.Logger.Warn(err) + s.logger.WarnContext(ctx, "failure forwarding agent", "error", err) } return nil case sshutils.PuTTYWinadjRequest: - return s.handlePuTTYWinadj(ch, req) + return s.handlePuTTYWinadj(ctx, req) default: - s.Logger.Warnf("%v doesn't support request type '%v'", s.Component(), req.Type) + 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.Errorf("sending error reply on SSH channel: %v", err) + s.logger.ErrorContext(ctx, "error sending reply on SSH channel", "error", err) } } return nil @@ -1848,7 +1841,7 @@ func (s *Server) handleAgentForwardProxy(_ *ssh.Request, ctx *srv.ServerContext) } // handleX11Forward handles an X11 forwarding request from the client. -func (s *Server) handleX11Forward(ch ssh.Channel, req *ssh.Request, scx *srv.ServerContext) (err error) { +func (s *Server) handleX11Forward(ctx context.Context, ch ssh.Channel, req *ssh.Request, scx *srv.ServerContext) (err error) { event := &apievents.X11Forward{ Metadata: apievents.Metadata{ Type: events.X11ForwardEvent, @@ -1873,11 +1866,11 @@ func (s *Server) handleX11Forward(ch ssh.Channel, req *ssh.Request, scx *srv.Ser if trace.IsAccessDenied(err) { // denied X11 requests are ok from a protocol perspective so we // don't return them, just reply over ssh and emit the audit s.Logger. - s.replyError(ch, req, err) + s.replyError(ctx, ch, req, err) err = nil } if err := s.EmitAuditEvent(s.ctx, event); err != nil { - s.Logger.WithError(err).Warn("Failed to emit x11-forward event.") + s.logger.WarnContext(s.ctx, "Failed to emit x11-forward event", "error", err) } }() @@ -1922,7 +1915,7 @@ func (s *Server) handleX11Forward(ch ssh.Channel, req *ssh.Request, scx *srv.Ser } func (s *Server) handleSubsystem(ctx context.Context, ch ssh.Channel, req *ssh.Request, serverContext *srv.ServerContext) error { - sb, err := s.parseSubsystemRequest(req, serverContext) + sb, err := s.parseSubsystemRequest(ctx, req, serverContext) if err != nil { serverContext.Warnf("Failed to parse subsystem request: %v: %v.", req, err) return trace.Wrap(err) @@ -1937,7 +1930,7 @@ func (s *Server) handleSubsystem(ctx context.Context, ch ssh.Channel, req *ssh.R } go func() { err := sb.Wait() - s.Logger.Debugf("Subsystem %v finished with result: %v.", sb, err) + s.logger.DebugContext(ctx, "Subsystem finished", "subsystem", sb, "error", err) serverContext.SendSubsystemResult(srv.SubsystemResult{Err: trace.Wrap(err)}) }() return nil @@ -1984,16 +1977,16 @@ func (s *Server) handleKeepAlive(req *ssh.Request) { } if err := req.Reply(true, nil); err != nil { - s.Logger.Warnf("Unable to reply to %q request: %v", req.Type, err) + s.logger.WarnContext(s.ctx, "Unable to reply to request", "request_type", req.Type, "error", err) return } - s.Logger.Debugf("Replied to %q", req.Type) + s.logger.DebugContext(s.ctx, "successfully replied to request", "request_type", req.Type) } // handleClusterDetails responds to global out-of-band with details about the cluster. func (s *Server) handleClusterDetails(ctx context.Context, req *ssh.Request) { - s.Logger.Debugf("Global request (%v, %v) received", req.Type, req.WantReply) + s.logger.DebugContext(ctx, "cluster details request received") if !req.WantReply { return @@ -2002,7 +1995,7 @@ func (s *Server) handleClusterDetails(ctx context.Context, req *ssh.Request) { recConfig, err := s.authService.GetSessionRecordingConfig(ctx) if err != nil { if err := req.Reply(false, nil); err != nil { - s.Logger.Warnf("Unable to respond to global request (%v, %v): %v", req.Type, req.WantReply, err) + s.logger.WarnContext(ctx, "Unable to respond to cluster details request", "error", err) } return } @@ -2013,18 +2006,18 @@ func (s *Server) handleClusterDetails(ctx context.Context, req *ssh.Request) { } if err = req.Reply(true, ssh.Marshal(details)); err != nil { - s.Logger.Warnf("Unable to respond to global request (%v, %v): %v: %v", req.Type, req.WantReply, details, err) + s.logger.WarnContext(ctx, "Unable to respond to cluster details request", "error", err) return } - s.Logger.Debugf("Replied to global request (%v, %v): %v", req.Type, req.WantReply, details) + s.logger.DebugContext(ctx, "Replied to cluster details request") } // handleVersionRequest replies with the Teleport version of the server. -func (s *Server) handleVersionRequest(req *ssh.Request) { +func (s *Server) handleVersionRequest(ctx context.Context, req *ssh.Request) { err := req.Reply(true, []byte(teleport.Version)) if err != nil { - s.Logger.Debugf("Failed to reply to version request: %v.", err) + s.logger.DebugContext(ctx, "Failed to reply to version request", "error", err) } } @@ -2032,12 +2025,12 @@ func (s *Server) handleVersionRequest(req *ssh.Request) { func (s *Server) handleProxyJump(ctx context.Context, ccx *sshutils.ConnectionContext, identityContext srv.IdentityContext, ch ssh.Channel, req sshutils.DirectTCPIPReq) { // Create context for this channel. This context will be closed when the // session request is complete. - ctx, scx, err := srv.NewServerContext(ctx, ccx, s, identityContext) + scx, err := srv.NewServerContext(ctx, ccx, s, identityContext) if err != nil { - s.Logger.WithError(err).Error("Unable to create connection context.") - writeStderr(ch, "Unable to create connection context.") + s.logger.ErrorContext(ctx, "Unable to create connection context", "error", err) + s.writeStderr(ctx, ch, "Unable to create connection context.") if err := ch.Close(); err != nil { - s.Logger.WithError(err).Warn("Failed to close channel.") + s.logger.WarnContext(ctx, "Failed to close channel", "error", err) } return } @@ -2050,8 +2043,8 @@ func (s *Server) handleProxyJump(ctx context.Context, ccx *sshutils.ConnectionCo recConfig, err := s.GetAccessPoint().GetSessionRecordingConfig(ctx) if err != nil { - s.Logger.Errorf("Unable to fetch session recording config: %v.", err) - writeStderr(ch, "Unable to fetch session recording configuration.") + s.logger.ErrorContext(ctx, "Unable to fetch session recording config", "error", err) + s.writeStderr(ctx, ch, "Unable to fetch session recording configuration.") return } @@ -2083,16 +2076,16 @@ func (s *Server) handleProxyJump(ctx context.Context, ccx *sshutils.ConnectionCo if services.IsRecordAtProxy(recConfig.GetMode()) { err = s.handleAgentForwardProxy(&ssh.Request{}, scx) if err != nil { - s.Logger.Warningf("Failed to request agent in recording mode: %v", err) - writeStderr(ch, "Failed to request agent") + s.logger.WarnContext(ctx, "Failed to request agent in recording mode", "error", err) + s.writeStderr(ctx, ch, "Failed to request agent") return } } netConfig, err := s.GetAccessPoint().GetClusterNetworkingConfig(ctx) if err != nil { - s.Logger.Errorf("Unable to fetch cluster networking config: %v.", err) - writeStderr(ch, "Unable to fetch cluster networking configuration.") + s.logger.ErrorContext(ctx, "Unable to fetch cluster networking config", "error", err) + s.writeStderr(ctx, ch, "Unable to fetch cluster networking configuration.") return } @@ -2109,19 +2102,19 @@ func (s *Server) handleProxyJump(ctx context.Context, ccx *sshutils.ConnectionCo CloseCancel: scx.CancelFunc(), }) - subsys, err := newProxySubsys(scx, s, proxySubsysRequest{ + subsys, err := newProxySubsys(ctx, scx, s, proxySubsysRequest{ host: req.Host, port: fmt.Sprintf("%v", req.Port), }) if err != nil { - s.Logger.Errorf("Unable instantiate proxy subsystem: %v.", err) - writeStderr(ch, "Unable to instantiate proxy subsystem.") + s.logger.ErrorContext(ctx, "Unable instantiate proxy subsystem", "error", err) + s.writeStderr(ctx, ch, "Unable to instantiate proxy subsystem.") return } if err := subsys.Start(ctx, scx.ServerConn, ch, &ssh.Request{}, scx); err != nil { - s.Logger.Errorf("Unable to start proxy subsystem: %v.", err) - writeStderr(ch, "Unable to start proxy subsystem.") + s.logger.ErrorContext(ctx, "Unable to start proxy subsystem", "error", err) + s.writeStderr(ctx, ch, "Unable to start proxy subsystem.") return } @@ -2129,8 +2122,8 @@ func (s *Server) handleProxyJump(ctx context.Context, ccx *sshutils.ConnectionCo go func() { defer close(wch) if err := subsys.Wait(); err != nil { - s.Logger.Errorf("Proxy subsystem failed: %v.", err) - writeStderr(ch, "Proxy subsystem failed.") + s.logger.ErrorContext(ctx, "Proxy subsystem failed", "error", err) + s.writeStderr(ctx, ch, "Proxy subsystem failed.") } }() select { @@ -2155,10 +2148,10 @@ func (s *Server) createForwardingContext(ctx context.Context, ccx *sshutils.Conn // SessionJoinPrincipal should be rejected, otherwise it's possible to use // the "-teleport-internal-join" user to bypass RBAC. if identityContext.Login == teleport.SSHSessionJoinPrincipal { - log.Errorf("Request rejected, %q with SessionJoinPrincipal in forward node must be blocked", r.Type) + s.logger.ErrorContext(ctx, "Request with SessionJoinPrincipal rejected", "request_type", r.Type) err := trace.AccessDenied("attempted %q request in join-only mode", r.Type) if replyErr := r.Reply(false, []byte(utils.FormatErrorWithNewline(err))); replyErr != nil { - s.Logger.Warnf("Failed to reply to %q request: %v", r.Type, err) + s.logger.WarnContext(ctx, "Failed to reply to request", "request_type", r.Type, "error", err) } // Disable default reply by caller, we already handled it. r.WantReply = false @@ -2166,7 +2159,7 @@ func (s *Server) createForwardingContext(ctx context.Context, ccx *sshutils.Conn } // Create context for this request. - ctx, scx, err := srv.NewServerContext(ctx, ccx, s, identityContext) + scx, err := srv.NewServerContext(ctx, ccx, s, identityContext) if err != nil { return nil, nil, trace.Wrap(err) } @@ -2211,7 +2204,7 @@ func (s *Server) handleTCPIPForwardRequest(ctx context.Context, ccx *sshutils.Co event := scx.GetPortForwardEvent() if err := s.EmitAuditEvent(ctx, &event); err != nil { - s.Logger.WithError(err).Warn("Failed to emit audit event.") + s.logger.WarnContext(ctx, "Failed to emit audit event", "error", err) } if err := sshutils.StartRemoteListener(ctx, scx.ConnectionContext.ServerConn, scx.SrcAddr, listener); err != nil { return trace.Wrap(err) @@ -2231,7 +2224,7 @@ func (s *Server) handleTCPIPForwardRequest(ctx context.Context, ccx *sshutils.Co } if err := r.Reply(true, payload); err != nil { - s.Logger.Warnf("Failed to reply to %q request: %v", r.Type, err) + s.logger.WarnContext(ctx, "Failed to reply to request", "request_type", r.Type, "error", err) } } @@ -2264,27 +2257,27 @@ func (s *Server) handleCancelTCPIPForwardRequest(ctx context.Context, ccx *sshut return trace.NotFound("no remote forwarding listener at %v", scx.SrcAddr) } if err := r.Reply(true, nil); err != nil { - s.Logger.Warnf("Failed to reply to %q request: %v", r.Type, err) + s.logger.WarnContext(ctx, "Failed to reply to request", "request_type", r.Type, "error", err) } return trace.Wrap(listener.Close()) } -func (s *Server) replyError(ch ssh.Channel, req *ssh.Request, err error) { - s.Logger.WithError(err).Errorf("failure handling SSH %q request", req.Type) +func (s *Server) replyError(ctx context.Context, ch ssh.Channel, req *ssh.Request, err error) { + s.logger.ErrorContext(ctx, "failure handling SSH request", "request_type", req.Type, "error", err) // Terminate the error with a newline when writing to remote channel's // stderr so the output does not mix with the rest of the output if the remote // side is not doing additional formatting for extended data. // See github.com/gravitational/teleport/issues/4542 message := utils.FormatErrorWithNewline(err) - writeStderr(ch, message) + s.writeStderr(ctx, ch, message) if req.WantReply { if err := req.Reply(false, []byte(message)); err != nil { - s.Logger.Warnf("Failed to reply to %q request: %v", req.Type, err) + s.logger.WarnContext(ctx, "Failed to reply with error to request", "request_type", req.Type, "error", err) } } } -func (s *Server) parseSubsystemRequest(req *ssh.Request, ctx *srv.ServerContext) (srv.Subsystem, error) { +func (s *Server) parseSubsystemRequest(ctx context.Context, req *ssh.Request, serverContext *srv.ServerContext) (srv.Subsystem, error) { var r sshutils.SubsystemReq if err := ssh.Unmarshal(req.Payload, &r); err != nil { return nil, trace.BadParameter("failed to parse subsystem request: %v", err) @@ -2293,7 +2286,7 @@ func (s *Server) parseSubsystemRequest(req *ssh.Request, ctx *srv.ServerContext) if s.proxyMode { switch { case strings.HasPrefix(r.Name, "proxy:"): - return parseProxySubsys(r.Name, s, ctx) + return s.parseProxySubsys(ctx, r.Name, serverContext) case strings.HasPrefix(r.Name, "proxysites"): return parseProxySitesSubsys(r.Name, s) default: @@ -2306,7 +2299,7 @@ func (s *Server) parseSubsystemRequest(req *ssh.Request, ctx *srv.ServerContext) case r.Name == teleport.GetHomeDirSubsystem: return newHomeDirSubsys(), nil case r.Name == teleport.SFTPSubsystem: - err := ctx.CheckSFTPAllowed(s.reg) + err := serverContext.CheckSFTPAllowed(s.reg) if err != nil { s.EmitAuditEvent(context.Background(), &apievents.SFTP{ Metadata: apievents.Metadata{ @@ -2314,28 +2307,28 @@ func (s *Server) parseSubsystemRequest(req *ssh.Request, ctx *srv.ServerContext) Type: events.SFTPEvent, Time: time.Now(), }, - UserMetadata: ctx.Identity.GetUserMetadata(), - ServerMetadata: ctx.GetServer().TargetMetadata(), + UserMetadata: serverContext.Identity.GetUserMetadata(), + ServerMetadata: serverContext.GetServer().TargetMetadata(), Error: err.Error(), }) return nil, trace.Wrap(err) } - return newSFTPSubsys(ctx.ConsumeApprovedFileTransferRequest()) + return newSFTPSubsys(serverContext.ConsumeApprovedFileTransferRequest()) default: return nil, trace.BadParameter("unrecognized subsystem: %v", r.Name) } } -func writeStderr(ch ssh.Channel, msg string) { +func (s *Server) writeStderr(ctx context.Context, ch ssh.Channel, msg string) { if _, err := io.WriteString(ch.Stderr(), msg); err != nil { - log.Warnf("Failed writing to ssh.Channel.Stderr(): %v", err) + s.logger.WarnContext(ctx, "Failed writing to stderr of SSH channel", "error", err) } } -func rejectChannel(ch ssh.NewChannel, reason ssh.RejectionReason, msg string) { +func (s *Server) rejectChannel(ctx context.Context, ch ssh.NewChannel, reason ssh.RejectionReason, msg string) { if err := ch.Reject(reason, msg); err != nil { - log.Warnf("Failed to reject new ssh.Channel: %v", err) + s.logger.WarnContext(ctx, "Failed to reject new SSH channel", "error", err) } } @@ -2345,9 +2338,9 @@ func rejectChannel(ch ssh.NewChannel, reason ssh.RejectionReason, msg string) { // tuning. It can be sent on any type of channel. There is no message-specific data. Servers MUST treat it // as an unrecognized request and respond with SSH_MSG_CHANNEL_FAILURE. // https://the.earth.li/~sgtatham/putty/0.76/htmldoc/AppendixG.html#sshnames-channel -func (s *Server) handlePuTTYWinadj(ch ssh.Channel, req *ssh.Request) error { +func (s *Server) handlePuTTYWinadj(ctx context.Context, req *ssh.Request) error { if err := req.Reply(false, nil); err != nil { - s.Logger.Warnf("Failed to reply to %q request: %v", req.Type, err) + s.logger.WarnContext(ctx, "Failed to reply to PuTTY winadj request", "error", err) return err } // the reply has been handled inside this function (rather than relying on the standard behavior diff --git a/lib/srv/regular/sshserver_test.go b/lib/srv/regular/sshserver_test.go index c2f5990339255..5e0b9a18bfec9 100644 --- a/lib/srv/regular/sshserver_test.go +++ b/lib/srv/regular/sshserver_test.go @@ -1227,10 +1227,7 @@ func x11EchoSession(ctx context.Context, t *testing.T, clt *tracessh.Client) x11 defer clientConn.Close() go func() { - err := sshutils.ForwardRequests(ctx, sin, se) - if err != nil { - log.WithError(err).Debug("Failed to forward ssh request from server during X11 forwarding") - } + _ = sshutils.ForwardRequests(ctx, sin, se) }() err = utils.ProxyConn(ctx, clientXConn, sch) @@ -2278,13 +2275,11 @@ func x11Handler(ctx context.Context, conn *ssh.ServerConn, chs <-chan ssh.NewCha // echo all bytes back across the X11 channel _, err = io.Copy(xch, xch) - if err == nil { - xch.CloseWrite() - } else { - log.Errorf("X11 channel error: %v", err) + if err != nil { + return trace.Wrap(err) } - return nil + return trace.Wrap(xch.CloseWrite()) } // startX11EchoServer starts a fake node which, for each incoming SSH connection, accepts an @@ -2298,7 +2293,6 @@ func startX11EchoServer(ctx context.Context, t *testing.T, authSrv *auth.Server) for { conn, chs, _, err := node.accept() if err != nil { - log.Warnf("X11 echo server closing: %v", err) return } go func() { diff --git a/lib/utils/log/slog_handler.go b/lib/utils/log/slog_handler.go index b69b83d2a1adb..14363bca8584e 100644 --- a/lib/utils/log/slog_handler.go +++ b/lib/utils/log/slog_handler.go @@ -44,6 +44,17 @@ const TraceLevel = slog.LevelDebug - 1 // TraceLevelText is the text representation of Trace verbosity. const TraceLevelText = "TRACE" +// DiscardHandler is a [slog.Handler] that discards all messages. It +// is more efficient than a [slog.Handler] which outputs to [io.Discard] since +// it performs zero formatting. +// TODO(tross): Use slog.DiscardHandler once upgraded to Go 1.24. +type DiscardHandler struct{} + +func (dh DiscardHandler) Enabled(context.Context, slog.Level) bool { return false } +func (dh DiscardHandler) Handle(context.Context, slog.Record) error { return nil } +func (dh DiscardHandler) WithAttrs(attrs []slog.Attr) slog.Handler { return dh } +func (dh DiscardHandler) WithGroup(name string) slog.Handler { return dh } + // SlogTextHandler is a [slog.Handler] that outputs messages in a textual // manner as configured by the Teleport configuration. type SlogTextHandler struct {