From c80bdf8153a0631244f292fd01c054503d48933e Mon Sep 17 00:00:00 2001 From: rosstimothy <39066650+rosstimothy@users.noreply.github.com> Date: Tue, 10 Dec 2024 12:54:36 -0500 Subject: [PATCH] Convert lib/sshutils to use slog (#49829) In addition to the conversion, the reverstunnel server now has a slog.Logger provided so that it can be passed into the sshutils.Server, is not used otherwise. A similar migration will be performed in the future for the reversetunnel package. --- lib/reversetunnel/srv.go | 20 ++++++--- lib/service/service.go | 1 + lib/sshutils/scp/scp.go | 54 ++++++++++++------------ lib/sshutils/scp/scp_test.go | 39 ++++++++--------- lib/sshutils/server.go | 82 ++++++++++++++++++------------------ lib/sshutils/sftp/sftp.go | 28 ++++++------ lib/sshutils/tcpip.go | 22 +++++----- 7 files changed, 126 insertions(+), 120 deletions(-) diff --git a/lib/reversetunnel/srv.go b/lib/reversetunnel/srv.go index cd36109a0b72f..10591e2042bdd 100644 --- a/lib/reversetunnel/srv.go +++ b/lib/reversetunnel/srv.go @@ -22,6 +22,7 @@ import ( "context" "fmt" "io" + "log/slog" "net" "strings" "sync" @@ -186,8 +187,12 @@ type Config struct { Component string // Log specifies the logger + // TODO(tross): remove this once Logger is used everywhere Log log.FieldLogger + // Logger specifies the logger + Logger *slog.Logger + // FIPS means Teleport was started in a FedRAMP/FIPS 140-2 compliant // configuration. FIPS bool @@ -260,13 +265,16 @@ func (cfg *Config) CheckAndSetDefaults() error { if cfg.Component == "" { cfg.Component = teleport.Component(teleport.ComponentProxy, teleport.ComponentServer) } - logger := cfg.Log if cfg.Log == nil { - logger = log.StandardLogger() + cfg.Log = log.StandardLogger() } - cfg.Log = logger.WithFields(log.Fields{ - teleport.ComponentKey: cfg.Component, - }) + cfg.Log = cfg.Log.WithField(teleport.ComponentKey, cfg.Component) + + if cfg.Logger == nil { + cfg.Logger = slog.Default() + } + cfg.Logger = cfg.Logger.With(teleport.ComponentKey, cfg.Component) + if cfg.LockWatcher == nil { return trace.BadParameter("missing parameter LockWatcher") } @@ -345,7 +353,7 @@ func NewServer(cfg Config) (reversetunnelclient.Server, error) { sshutils.AuthMethods{ PublicKey: srv.keyAuth, }, - sshutils.SetLogger(cfg.Log), + sshutils.SetLogger(cfg.Logger), sshutils.SetLimiter(cfg.Limiter), sshutils.SetCiphers(cfg.Ciphers), sshutils.SetKEXAlgorithms(cfg.KEXAlgorithms), diff --git a/lib/service/service.go b/lib/service/service.go index 16276a69827fa..b321badeef084 100644 --- a/lib/service/service.go +++ b/lib/service/service.go @@ -4408,6 +4408,7 @@ func (process *TeleportProcess) initProxyEndpoint(conn *Connector) error { FIPS: cfg.FIPS, Emitter: streamEmitter, Log: process.log, + Logger: process.logger, LockWatcher: lockWatcher, PeerClient: peerClient, NodeWatcher: nodeWatcher, diff --git a/lib/sshutils/scp/scp.go b/lib/sshutils/scp/scp.go index f3df1993fe390..ebaa842b9b42c 100644 --- a/lib/sshutils/scp/scp.go +++ b/lib/sshutils/scp/scp.go @@ -26,9 +26,11 @@ package scp import ( "bufio" + "context" "errors" "fmt" "io" + "log/slog" "os" "path/filepath" "strconv" @@ -36,7 +38,6 @@ import ( "time" "github.com/gravitational/trace" - log "github.com/sirupsen/logrus" "github.com/gravitational/teleport" "github.com/gravitational/teleport/lib/events" @@ -94,7 +95,7 @@ type Config struct { // this command will be run on the server RunOnServer bool // Log optionally specifies the logger - Log log.FieldLogger + Log *slog.Logger } // Command is an API that describes command operations @@ -174,20 +175,18 @@ func CreateUploadCommand(cfg Config) (Command, error) { func (c *Config) CheckAndSetDefaults() error { logger := c.Log if logger == nil { - logger = log.StandardLogger() - } - c.Log = logger.WithFields(log.Fields{ - teleport.ComponentKey: "SCP", - teleport.ComponentFields: log.Fields{ - "LocalAddr": c.Flags.LocalAddr, - "RemoteAddr": c.Flags.RemoteAddr, - "Target": c.Flags.Target, - "PreserveAttrs": c.Flags.PreserveAttrs, - "User": c.User, - "RunOnServer": c.RunOnServer, - "RemoteLocation": c.RemoteLocation, - }, - }) + logger = slog.Default() + } + c.Log = logger.With( + teleport.ComponentKey, "SCP", + "local_addr", c.Flags.LocalAddr, + "remote_addr", c.Flags.RemoteAddr, + "target", c.Flags.Target, + "preserve_attrs", c.Flags.PreserveAttrs, + "user", c.User, + "run_on_server", c.RunOnServer, + "remote_location", c.RemoteLocation, + ) if c.FileSystem == nil { c.FileSystem = &localFileSystem{} } @@ -216,7 +215,7 @@ func CreateCommand(cfg Config) (Command, error) { // to teleport can pretend it launches real SCP behind the scenes type command struct { Config - log log.FieldLogger + log *slog.Logger } // Execute implements SSH file copy (SCP). It is called on both tsh (client) @@ -301,7 +300,7 @@ func (cmd *command) serveSource(ch io.ReadWriter) (retErr error) { } } - cmd.log.Debug("Send completed.") + cmd.log.DebugContext(context.Background(), "Send completed") return nil } @@ -315,7 +314,7 @@ func (cmd *command) sendDir(r *reader, ch io.ReadWriter, fileInfo FileInfo) erro return trace.Wrap(err) } - cmd.log.Debug("sendDir got OK") + cmd.log.DebugContext(context.Background(), "sendDir got OK") fileInfos, err := fileInfo.ReadDir() if err != nil { @@ -381,7 +380,7 @@ func (cmd *command) sendFile(r *reader, ch io.ReadWriter, fileInfo FileInfo) err func (cmd *command) sendErr(ch io.Writer, err error) { out := fmt.Sprintf("%c%s\n", byte(ErrByte), err) if _, err := ch.Write([]byte(out)); err != nil { - cmd.log.Debugf("Failed sending SCP error message to the remote side: %v.", err) + cmd.log.DebugContext(context.Background(), "Failed sending SCP error message to the remote side", "error", err) } } @@ -447,7 +446,7 @@ func (cmd *command) serveSink(ch io.ReadWriter) error { } func (cmd *command) processCommand(ch io.ReadWriter, st *state, b byte, line string) error { - cmd.log.Debugf("<- %v %v", string(b), line) + cmd.log.DebugContext(context.Background(), "processing command", "b", string(b), "line", line) switch b { case WarnByte, ErrByte: return trace.Errorf("error from sender: %q", line) @@ -487,7 +486,8 @@ func (cmd *command) processCommand(ch io.ReadWriter, st *state, b byte, line str } func (cmd *command) receiveFile(st *state, fc newFileCmd, ch io.ReadWriter) error { - cmd.log.Debugf("scp.receiveFile(%v): %v", cmd.Flags.Target, fc.Name) + ctx := context.Background() + cmd.log.DebugContext(ctx, "processing file copy request", "targets", cmd.Flags.Target, "file_name", fc.Name) // Unless target specifies a file, use the file name from the command path := cmd.Flags.Target[0] @@ -534,12 +534,12 @@ func (cmd *command) receiveFile(st *state, fc newFileCmd, ch io.ReadWriter) erro } } - cmd.log.Debugf("File %v(%v) copied to %v.", fc.Name, fc.Length, path) + cmd.log.DebugContext(ctx, "File successfully copied", "file", fc.Name, "size", fc.Length, "destination", path) return nil } func (cmd *command) receiveDir(st *state, fc newFileCmd, ch io.ReadWriter) error { - cmd.log.Debugf("scp.receiveDir(%v): %v", cmd.Flags.Target, fc.Name) + cmd.log.DebugContext(context.Background(), "processing directory copy request", "targets", cmd.Flags.Target, "name", fc.Name) if cmd.FileSystem.IsDir(cmd.Flags.Target[0]) { // Copying into an existing directory? append to it: @@ -561,7 +561,7 @@ func (cmd *command) receiveDir(st *state, fc newFileCmd, ch io.ReadWriter) error func (cmd *command) sendDirMode(r *reader, ch io.Writer, fileInfo FileInfo) error { out := fmt.Sprintf("D%04o 0 %s\n", fileInfo.GetModePerm(), fileInfo.GetName()) - cmd.log.WithField("cmd", out).Debug("Send directory mode.") + cmd.log.DebugContext(context.Background(), "Sending directory mode", "cmd", out) _, err := io.WriteString(ch, out) if err != nil { return trace.Wrap(err) @@ -582,7 +582,7 @@ func (cmd *command) sendFileTimes(r *reader, ch io.Writer, fileInfo FileInfo) er fileInfo.GetModTime().Unix(), fileInfo.GetAccessTime().Unix(), ) - cmd.log.WithField("cmd", out).Debug("Send file times.") + cmd.log.DebugContext(context.Background(), "Sending file times", "cmd", out) _, err := io.WriteString(ch, out) if err != nil { return trace.Wrap(err) @@ -596,7 +596,7 @@ func (cmd *command) sendFileMode(r *reader, ch io.Writer, fileInfo FileInfo) err fileInfo.GetSize(), fileInfo.GetName(), ) - cmd.log.WithField("cmd", out).Debug("Send file mode.") + cmd.log.DebugContext(context.Background(), "Sending file mode", "cmd", out) _, err := io.WriteString(ch, out) if err != nil { return trace.Wrap(err) diff --git a/lib/sshutils/scp/scp_test.go b/lib/sshutils/scp/scp_test.go index 9eec0bed1b9b3..820b6807df41b 100644 --- a/lib/sshutils/scp/scp_test.go +++ b/lib/sshutils/scp/scp_test.go @@ -20,8 +20,10 @@ package scp import ( "bytes" + "context" "fmt" "io" + "log/slog" "os" "os/exec" "path/filepath" @@ -30,7 +32,6 @@ import ( "github.com/google/go-cmp/cmp" "github.com/gravitational/trace" - "github.com/sirupsen/logrus" "github.com/stretchr/testify/require" "github.com/gravitational/teleport" @@ -48,7 +49,7 @@ func TestSend(t *testing.T) { atime := testNow.Add(1 * time.Second) dirModtime := testNow.Add(2 * time.Second) dirAtime := testNow.Add(3 * time.Second) - logger := logrus.WithField(teleport.ComponentKey, "t:send") + logger := utils.NewSlogLoggerForTests().With(teleport.ComponentKey, "send") testCases := []struct { desc string config Config @@ -112,7 +113,7 @@ func TestReceive(t *testing.T) { atime := testNow.Add(1 * time.Second) dirModtime := testNow.Add(2 * time.Second) dirAtime := testNow.Add(3 * time.Second) - logger := logrus.WithField(teleport.ComponentKey, "t:recv") + logger := utils.NewSlogLoggerForTests().With(teleport.ComponentKey, "recv") testCases := []struct { desc string config Config @@ -172,7 +173,7 @@ func TestReceive(t *testing.T) { for _, tt := range testCases { tt := tt t.Run(tt.desc, func(t *testing.T) { - logger := logger.WithField("test", tt.desc) + logger := logger.With("test", tt.desc) t.Parallel() sourceDir := t.TempDir() @@ -235,7 +236,7 @@ func TestSCPFailsIfNoSource(t *testing.T) { // // See https://github.com/gravitational/teleport/issues/5497 func TestReceiveIntoExistingDirectory(t *testing.T) { - logger := logrus.WithField("test", t.Name()) + logger := utils.NewSlogLoggerForTests().With("test", t.Name()) config := newTargetConfigWithFS("dir", Flags{PreserveAttrs: true, Recursive: true}, newTestFS(logger, newDir("dir")), @@ -278,7 +279,7 @@ func TestReceiveIntoExistingDirectory(t *testing.T) { // // See https://github.com/gravitational/teleport/issues/5695 func TestReceiveIntoNonExistingDirectoryFailsWithCorrectMessage(t *testing.T) { - logger := logrus.WithField("test", t.Name()) + logger := utils.NewSlogLoggerForTests().With("test", t.Name()) // Target configuration with no existing directory root := t.TempDir() config := newTargetConfigWithFS(filepath.Join(root, "dir"), @@ -306,7 +307,7 @@ func TestReceiveIntoNonExistingDirectoryFailsWithCorrectMessage(t *testing.T) { // TestCopyIntoNestedNonExistingDirectoriesDoesNotCreateIntermediateDirectories validates that copying a directory // into a remote '/path/to/remote' where '/path/to' does not exist causes an error. func TestCopyIntoNestedNonExistingDirectoriesDoesNotCreateIntermediateDirectories(t *testing.T) { - logger := logrus.WithField("test", t.Name()) + logger := utils.NewSlogLoggerForTests().With("test", t.Name()) config := newTargetConfig("non-existing/remote_dir", Flags{Recursive: true}) sourceFS := newTestFS(logger, newDir("dir")) @@ -631,14 +632,14 @@ func newCmd(name string, args ...string) (cmd *exec.Cmd, stdin io.WriteCloser, s // newTestFS creates a new test FileSystem using the specified logger // and the set of top-level files -func newTestFS(logger logrus.FieldLogger, files ...*testFileInfo) *testFS { +func newTestFS(logger *slog.Logger, files ...*testFileInfo) *testFS { fs := newEmptyTestFS(logger) addFiles(fs.fs, files...) return fs } // newEmptyTestFS creates a new test FileSystem without content -func newEmptyTestFS(logger logrus.FieldLogger) *testFS { +func newEmptyTestFS(logger *slog.Logger) *testFS { return &testFS{ fs: make(map[string]*testFileInfo), l: logger, @@ -646,7 +647,7 @@ func newEmptyTestFS(logger logrus.FieldLogger) *testFS { } func (r *testFS) IsDir(path string) bool { - r.l.WithField("path", path).Debug("IsDir.") + r.l.DebugContext(context.Background(), "IsDir", "path", path) if fi, exists := r.fs[path]; exists { return fi.IsDir() } @@ -654,7 +655,7 @@ func (r *testFS) IsDir(path string) bool { } func (r *testFS) GetFileInfo(path string) (FileInfo, error) { - r.l.WithField("path", path).Debug("GetFileInfo.") + r.l.DebugContext(context.Background(), "GetFileInfo", "path", path) fi, exists := r.fs[path] if !exists { return nil, newErrMissingFile(path) @@ -663,7 +664,7 @@ func (r *testFS) GetFileInfo(path string) (FileInfo, error) { } func (r *testFS) MkDir(path string, mode int) error { - r.l.WithFields(logrus.Fields{"path": path, "mode": mode}).Debug("MkDir.") + r.l.DebugContext(context.Background(), "MkDir", "path", path, "mode", mode) _, exists := r.fs[path] if exists { return trace.AlreadyExists("directory %v already exists", path) @@ -677,7 +678,7 @@ func (r *testFS) MkDir(path string, mode int) error { } func (r *testFS) OpenFile(path string) (io.ReadCloser, error) { - r.l.WithField("path", path).Debug("OpenFile.") + r.l.DebugContext(context.Background(), "OpenFile", "path", path) fi, exists := r.fs[path] if !exists { return nil, newErrMissingFile(path) @@ -687,7 +688,7 @@ func (r *testFS) OpenFile(path string) (io.ReadCloser, error) { } func (r *testFS) CreateFile(path string, length uint64) (io.WriteCloser, error) { - r.l.WithFields(logrus.Fields{"path": path, "len": length}).Debug("CreateFile.") + r.l.DebugContext(context.Background(), "CreateFile", "path", path, "len", length) baseDir := filepath.Dir(path) if _, exists := r.fs[baseDir]; baseDir != "." && !exists { return nil, newErrMissingFile(baseDir) @@ -704,7 +705,7 @@ func (r *testFS) CreateFile(path string, length uint64) (io.WriteCloser, error) } func (r *testFS) Chmod(path string, mode int) error { - r.l.WithFields(logrus.Fields{"path": path, "mode": mode}).Debug("Chmod.") + r.l.DebugContext(context.Background(), "Chmod", "path", path, "mode", mode) fi, exists := r.fs[path] if !exists { return newErrMissingFile(path) @@ -714,11 +715,7 @@ func (r *testFS) Chmod(path string, mode int) error { } func (r *testFS) Chtimes(path string, atime, mtime time.Time) error { - r.l.WithFields(logrus.Fields{ - "path": path, - "atime": atime, - "mtime": mtime, - }).Debug("Chtimes.") + r.l.DebugContext(context.Background(), "Chtimes", "path", path, "atime", atime, "mtime", mtime) fi, exists := r.fs[path] if !exists { return newErrMissingFile(path) @@ -730,7 +727,7 @@ func (r *testFS) Chtimes(path string, atime, mtime time.Time) error { // testFS implements a fake FileSystem type testFS struct { - l logrus.FieldLogger + l *slog.Logger fs map[string]*testFileInfo } diff --git a/lib/sshutils/server.go b/lib/sshutils/server.go index fb1a431105aa6..7020c302342c6 100644 --- a/lib/sshutils/server.go +++ b/lib/sshutils/server.go @@ -25,6 +25,7 @@ import ( "errors" "fmt" "io" + "log/slog" "net" "sync" "sync/atomic" @@ -33,7 +34,6 @@ import ( "github.com/gravitational/trace" "github.com/jonboulle/clockwork" "github.com/prometheus/client_golang/prometheus" - "github.com/sirupsen/logrus" semconv "go.opentelemetry.io/otel/semconv/v1.10.0" oteltrace "go.opentelemetry.io/otel/trace" "golang.org/x/crypto/ssh" @@ -61,7 +61,7 @@ var proxyConnectionLimitHitCount = prometheus.NewCounter( type Server struct { sync.RWMutex - log logrus.FieldLogger + logger *slog.Logger // component is a name of the facility which uses this server, // used for logging/debugging. typically it's "proxy" or "auth api", etc component string @@ -136,9 +136,9 @@ func SetIngressReporter(service string, r *ingress.Reporter) ServerOption { } // SetLogger sets the logger for the server -func SetLogger(logger logrus.FieldLogger) ServerOption { +func SetLogger(logger *slog.Logger) ServerOption { return func(s *Server) error { - s.log = logger.WithField(teleport.ComponentKey, "ssh:"+s.component) + s.logger = logger.With(teleport.ComponentKey, teleport.Component("ssh", s.component)) return nil } } @@ -205,9 +205,7 @@ func NewServer( closeContext, cancel := context.WithCancel(context.TODO()) s := &Server{ - log: logrus.WithFields(logrus.Fields{ - teleport.ComponentKey: "ssh:" + component, - }), + logger: slog.With(teleport.ComponentKey, teleport.Component("ssh", component)), addr: a, newChanHandler: h, getHostSigners: getHostSigners, @@ -276,7 +274,7 @@ func SetNewConnHandler(handler NewConnHandler) ServerOption { func SetCiphers(ciphers []string) ServerOption { return func(s *Server) error { - s.log.Debugf("Supported ciphers: %q.", ciphers) + s.logger.DebugContext(context.Background(), "Supported ciphers updated", "ciphers", ciphers) if ciphers != nil { s.cfg.Ciphers = ciphers } @@ -286,7 +284,7 @@ func SetCiphers(ciphers []string) ServerOption { func SetKEXAlgorithms(kexAlgorithms []string) ServerOption { return func(s *Server) error { - s.log.Debugf("Supported KEX algorithms: %q.", kexAlgorithms) + s.logger.DebugContext(context.Background(), "Supported KEX algorithms updated", "kex_algorithms", kexAlgorithms) if kexAlgorithms != nil { s.cfg.KeyExchanges = kexAlgorithms } @@ -296,7 +294,7 @@ func SetKEXAlgorithms(kexAlgorithms []string) ServerOption { func SetMACAlgorithms(macAlgorithms []string) ServerOption { return func(s *Server) error { - s.log.Debugf("Supported MAC algorithms: %q.", macAlgorithms) + s.logger.DebugContext(context.Background(), "Supported MAC algorithms updated", "mac_algorithms", macAlgorithms) if macAlgorithms != nil { s.cfg.MACs = macAlgorithms } @@ -344,7 +342,7 @@ func (s *Server) Start() error { return trace.Wrap(err) } } - s.log.WithField("addr", s.listener.Addr().String()).Debug("Server start.") + s.logger.DebugContext(s.closeContext, "Starting server", "addr", s.listener.Addr().String()) go s.acceptConnections() return nil } @@ -380,7 +378,7 @@ func (s *Server) Shutdown(ctx context.Context) error { } minReportInterval := 10 * s.shutdownPollPeriod maxReportInterval := 600 * s.shutdownPollPeriod - s.log.Infof("Shutdown: waiting for %v connections to finish.", activeConnections) + s.logger.InfoContext(ctx, "Shutdown: waiting for active connections to finish", "active_connections", activeConnections) reportedConnections := activeConnections lastReport := time.Now() reportInterval := minReportInterval @@ -394,7 +392,7 @@ func (s *Server) Shutdown(ctx context.Context) error { return err } if activeConnections != reportedConnections || now.Sub(lastReport) > reportInterval { - s.log.Infof("Shutdown: waiting for %v connections to finish.", activeConnections) + s.logger.InfoContext(ctx, "Shutdown: waiting for active connections to finish", "active_connections", activeConnections) lastReport = now if activeConnections == reportedConnections { reportInterval = min(reportInterval*2, maxReportInterval) @@ -404,7 +402,7 @@ func (s *Server) Shutdown(ctx context.Context) error { } } case <-ctx.Done(): - s.log.Infof("Context canceled wait, returning.") + s.logger.InfoContext(ctx, "Context canceled wait, returning") return trace.ConnectionProblem(err, "context canceled") } } @@ -429,27 +427,27 @@ func (s *Server) Close() error { func (s *Server) acceptConnections() { defer s.closeFunc() - addr := s.Addr() - s.log.Debugf("Listening on %v.", addr) + logger := s.logger.With("listen_addr", s.Addr()) + logger.DebugContext(s.closeContext, "Listening for connections") for { conn, err := s.listener.Accept() if err != nil { if trace.IsLimitExceeded(err) { proxyConnectionLimitHitCount.Inc() - s.log.Error(err.Error()) + logger.ErrorContext(s.closeContext, "connection limit exceeded", "error", err) continue } if utils.IsUseOfClosedNetworkError(err) { - s.log.Debugf("Server %v has closed.", addr) + logger.DebugContext(s.closeContext, "Server has closed") return } select { case <-s.closeContext.Done(): - s.log.Debugf("Server %v has closed.", addr) + logger.DebugContext(s.closeContext, "Server has closed") return case <-time.After(5 * time.Second): - s.log.Debugf("Backoff on network error: %v.", err) + logger.DebugContext(s.closeContext, "Applying backoff in response to network error", "error", err) } } else { go s.HandleConnection(conn) @@ -492,10 +490,10 @@ func (s *Server) HandleConnection(conn net.Conn) { hostSigners := s.getHostSigners() if err := s.validateHostSigners(hostSigners); err != nil { - s.log. - WithError(err). - WithField("remote_addr", conn.RemoteAddr()). - Error("Error during server setup for a new SSH connection (this is a bug).") + s.logger.ErrorContext(s.closeContext, "Error during server setup for a new SSH connection (this is a bug)", + "error", err, + "remote_addr", conn.RemoteAddr(), + ) conn.Close() return } @@ -518,10 +516,10 @@ func (s *Server) HandleConnection(conn net.Conn) { if err != nil { // Ignore EOF as these are triggered by loadbalancer health checks if !errors.Is(err, io.EOF) { - s.log. - WithError(err). - WithField("remote_addr", conn.RemoteAddr()). - Warn("Error occurred in handshake for new SSH conn") + s.logger.WarnContext(s.closeContext, "Error occurred in handshake for new SSH conn", + "error", err, + "remote_addr", conn.RemoteAddr(), + ) } conn.Close() return @@ -544,18 +542,22 @@ func (s *Server) HandleConnection(conn net.Conn) { user := sconn.User() if err := s.limiter.RegisterRequest(user); err != nil { - s.log.Errorf(err.Error()) + s.logger.ErrorContext(s.closeContext, "user connection rate limit exceeded", "user", user, "error", err) sconn.Close() conn.Close() return } // Connection successfully initiated - s.log.Debugf("Incoming connection %v -> %v version: %v, certtype: %q", - sconn.RemoteAddr(), sconn.LocalAddr(), string(sconn.ClientVersion()), certType) + s.logger.DebugContext(s.closeContext, "handling incoming connection", + "remote_addr", sconn.RemoteAddr(), + "local_addr", sconn.LocalAddr(), + "version", string(sconn.ClientVersion()), + "cert_type", certType, + ) // will be called when the connection is closed connClosed := func() { - s.log.Debugf("Closed connection %v.", sconn.RemoteAddr()) + s.logger.DebugContext(s.closeContext, "Closed connection", "remote_addr", sconn.RemoteAddr()) } // The keepalive ticket will ensure that SSH keepalive requests are being sent @@ -577,7 +579,7 @@ func (s *Server) HandleConnection(conn net.Conn) { // from a NewConnHandler are rejections. ctx, err = s.newConnHandler.HandleNewConn(ctx, ccx) if err != nil { - s.log.Warnf("Dropping inbound ssh connection due to error: %v", err) + s.logger.WarnContext(ctx, "Dropping inbound ssh connection due to error", "error", err) // Immediately dropping the ssh connection results in an // EOF error for the client. We therefore wait briefly // to see if the client opens a channel or sends any global @@ -598,7 +600,7 @@ func (s *Server) HandleConnection(conn net.Conn) { } if err := req.Reply(false, []byte(err.Error())); err != nil { - s.log.WithError(err).Warnf("failed to reply to request %s", req.Type) + s.logger.WarnContext(ctx, "failed to reply to request", "request_type", req.Type, "error", err) } case firstChan := <-chans: // channel was closed, terminate the connection @@ -607,7 +609,7 @@ func (s *Server) HandleConnection(conn net.Conn) { } if err := firstChan.Reject(ssh.Prohibited, err.Error()); err != nil { - s.log.WithError(err).Warnf("failed to reject channel %s", firstChan.ChannelType()) + s.logger.WarnContext(ctx, "failed to reject channel", "channel_type", firstChan.ChannelType(), "error", err) } case <-waitCtx.Done(): } @@ -616,10 +618,10 @@ func (s *Server) HandleConnection(conn net.Conn) { } if err := sconn.Close(); err != nil && !utils.IsOKNetworkError(err) { - s.log.WithError(err).Warn("failed to close ssh server connection") + s.logger.WarnContext(ctx, "failed to close ssh server connection", "error", err) } if err := conn.Close(); err != nil && !utils.IsOKNetworkError(err) { - s.log.WithError(err).Warn("failed to close ssh client connection") + s.logger.WarnContext(ctx, "failed to close ssh client connection", "error", err) } return } @@ -633,7 +635,7 @@ func (s *Server) HandleConnection(conn net.Conn) { connClosed() return } - s.log.Debugf("Received out-of-band request: %+v.", req) + s.logger.DebugContext(ctx, "Received out-of-band request", "request_type", req.Type) reqCtx := tracessh.ContextFromRequest(req) ctx, span := s.tracerProvider.Tracer("ssh").Start( @@ -683,10 +685,10 @@ func (s *Server) HandleConnection(conn net.Conn) { const wantReply = true _, _, err = sconn.SendRequest(teleport.KeepAliveReqType, wantReply, keepAlivePayload[:]) if err != nil { - s.log.Errorf("Failed sending keepalive request: %v", err) + s.logger.ErrorContext(ctx, "Failed sending keepalive request", "error", err) } case <-ctx.Done(): - s.log.Debugf("Connection context canceled: %v -> %v", conn.RemoteAddr(), conn.LocalAddr()) + s.logger.DebugContext(ctx, "Connection context canceled", "remote_addr", conn.RemoteAddr(), "local_addr", conn.LocalAddr()) return } } diff --git a/lib/sshutils/sftp/sftp.go b/lib/sshutils/sftp/sftp.go index 77bd23f3cda5a..b16eb656a3557 100644 --- a/lib/sshutils/sftp/sftp.go +++ b/lib/sshutils/sftp/sftp.go @@ -26,6 +26,7 @@ import ( "fmt" "io" "io/fs" + "log/slog" "net/http" "os" "path" // SFTP requires UNIX-style path separators @@ -37,7 +38,6 @@ import ( "github.com/gravitational/trace" "github.com/pkg/sftp" "github.com/schollz/progressbar/v3" - log "github.com/sirupsen/logrus" "golang.org/x/crypto/ssh" "github.com/gravitational/teleport" @@ -70,7 +70,7 @@ type Config struct { // (used only on the client) ProgressStream func(fileInfo os.FileInfo) io.ReadWriter // Log optionally specifies the logger - Log log.FieldLogger + Log *slog.Logger } // FileSystem describes file operations to be done either locally or over SFTP @@ -222,17 +222,15 @@ func (h HTTPTransferRequest) checkDefaults() error { func (c *Config) setDefaults() { logger := c.Log if logger == nil { - logger = log.StandardLogger() - } - c.Log = logger.WithFields(log.Fields{ - teleport.ComponentKey: "SFTP", - teleport.ComponentFields: log.Fields{ - "SrcPaths": c.srcPaths, - "DstPath": c.dstPath, - "Recursive": c.opts.Recursive, - "PreserveAttrs": c.opts.PreserveAttrs, - }, - }) + logger = slog.Default() + } + c.Log = logger.With( + teleport.ComponentKey, "SFTP", + "src_paths", c.srcPaths, + "dst_path", c.dstPath, + "recursive", c.opts.Recursive, + "preserve_attrs", c.opts.PreserveAttrs, + ) if !c.opts.Quiet { c.ProgressStream = func(fileInfo os.FileInfo) io.ReadWriter { @@ -488,7 +486,7 @@ func (c *Config) transfer(ctx context.Context) error { // transferDir transfers a directory func (c *Config) transferDir(ctx context.Context, dstPath, srcPath string, srcFileInfo os.FileInfo) error { - c.Log.Debugf("copying %s dir %q to %s dir %q", c.srcFS.Type(), srcPath, c.dstFS.Type(), dstPath) + c.Log.DebugContext(ctx, "transferring contents of directory", "source_fs", c.srcFS.Type(), "source_path", srcPath, "dest_fs", c.dstFS.Type(), "dest_path", dstPath) err := c.dstFS.Mkdir(ctx, dstPath) if err != nil && !errors.Is(err, os.ErrExist) { @@ -532,7 +530,7 @@ func (c *Config) transferDir(ctx context.Context, dstPath, srcPath string, srcFi // transferFile transfers a file func (c *Config) transferFile(ctx context.Context, dstPath, srcPath string, srcFileInfo os.FileInfo) error { - c.Log.Debugf("copying %s file %q to %s file %q", c.srcFS.Type(), srcPath, c.dstFS.Type(), dstPath) + c.Log.DebugContext(ctx, "transferring file", "source_fs", c.srcFS.Type(), "source_file", srcPath, "dest_fs", c.dstFS.Type(), "dest_file", dstPath) srcFile, err := c.srcFS.Open(ctx, srcPath) if err != nil { diff --git a/lib/sshutils/tcpip.go b/lib/sshutils/tcpip.go index 55ac4ea981cf3..a7308f010db7c 100644 --- a/lib/sshutils/tcpip.go +++ b/lib/sshutils/tcpip.go @@ -21,10 +21,10 @@ package sshutils import ( "context" "io" + "log/slog" "net" "github.com/gravitational/trace" - log "github.com/sirupsen/logrus" "golang.org/x/crypto/ssh" "github.com/gravitational/teleport" @@ -48,7 +48,7 @@ type DirectTCPIPReq struct { func ParseDirectTCPIPReq(data []byte) (*DirectTCPIPReq, error) { var r DirectTCPIPReq if err := ssh.Unmarshal(data, &r); err != nil { - log.Infof("failed to parse Direct TCP IP request: %v", err) + slog.InfoContext(context.Background(), "failed to parse Direct TCP IP request", "error", err) return nil, trace.Wrap(err) } return &r, nil @@ -67,7 +67,7 @@ type TCPIPForwardReq struct { func ParseTCPIPForwardReq(data []byte) (*TCPIPForwardReq, error) { var r TCPIPForwardReq if err := ssh.Unmarshal(data, &r); err != nil { - log.Infof("failed to parse TCP IP Forward request: %v", err) + slog.InfoContext(context.Background(), "failed to parse TCP IP Forward request", "error", err) return nil, trace.Wrap(err) } return &r, nil @@ -90,19 +90,19 @@ func StartRemoteListener(ctx context.Context, sshConn channelOpener, srcAddr str conn, err := listener.Accept() if err != nil { if !utils.IsOKNetworkError(err) { - log.WithError(err).Warn("failed to accept connection") + slog.WarnContext(ctx, "failed to accept connection", "error", err) } return } - logger := log.WithFields(log.Fields{ - "srcAddr": srcAddr, - "remoteAddr": conn.RemoteAddr().String(), - }) + logger := slog.With( + "src_addr", srcAddr, + "remote_addr", conn.RemoteAddr().String(), + ) dstHost, dstPort, err := SplitHostPort(conn.RemoteAddr().String()) if err != nil { conn.Close() - logger.WithError(err).Warn("failed to parse addr") + logger.WarnContext(ctx, "failed to parse addr", "error", err) return } @@ -114,7 +114,7 @@ func StartRemoteListener(ctx context.Context, sshConn channelOpener, srcAddr str } if err := req.CheckAndSetDefaults(); err != nil { conn.Close() - logger.WithError(err).Warn("failed to create forwarded tcpip request") + logger.WarnContext(ctx, "failed to create forwarded tcpip request", "error", err) return } reqBytes := ssh.Marshal(req) @@ -122,7 +122,7 @@ func StartRemoteListener(ctx context.Context, sshConn channelOpener, srcAddr str ch, rch, err := sshConn.OpenChannel(teleport.ChanForwardedTCPIP, reqBytes) if err != nil { conn.Close() - logger.WithError(err).Warn("failed to open channel") + logger.WarnContext(ctx, "failed to open channel", "error", err) continue } go ssh.DiscardRequests(rch)