From 0baf95d340389a2340af4988067b2781495d2b1d Mon Sep 17 00:00:00 2001 From: Steven Masley Date: Wed, 15 Nov 2023 14:29:16 -0600 Subject: [PATCH 1/4] chore: add uuid to ssh connection logs --- agent/agentssh/agentssh.go | 46 ++++++++++++++++++++++---------------- 1 file changed, 27 insertions(+), 19 deletions(-) diff --git a/agent/agentssh/agentssh.go b/agent/agentssh/agentssh.go index 9c7641643356a..799228117f9f2 100644 --- a/agent/agentssh/agentssh.go +++ b/agent/agentssh/agentssh.go @@ -19,6 +19,7 @@ import ( "time" "github.com/gliderlabs/ssh" + "github.com/google/uuid" "github.com/kballard/go-shellquote" "github.com/pkg/sftp" "github.com/prometheus/client_golang/prometheus" @@ -192,9 +193,16 @@ func (s *Server) ConnStats() ConnStats { } func (s *Server) sessionHandler(session ssh.Session) { - logger := s.logger.With(slog.F("remote_addr", session.RemoteAddr()), slog.F("local_addr", session.LocalAddr())) - logger.Info(session.Context(), "handling ssh session") ctx := session.Context() + logger := s.logger.With( + slog.F("remote_addr", session.RemoteAddr()), + slog.F("local_addr", session.LocalAddr()), + // Assigning a random uuid for each session is useful for tracking + // logs for the same ssh session in the logs. + slog.F("id", uuid.NewString()), + ) + logger.Info(ctx, "handling ssh session") + if !s.trackSession(session, true) { // See (*Server).Close() for why we call Close instead of Exit. _ = session.Close() @@ -218,7 +226,7 @@ func (s *Server) sessionHandler(session ssh.Session) { switch ss := session.Subsystem(); ss { case "": case "sftp": - s.sftpHandler(session) + s.sftpHandler(logger, session) return default: logger.Warn(ctx, "unsupported subsystem", slog.F("subsystem", ss)) @@ -226,7 +234,7 @@ func (s *Server) sessionHandler(session ssh.Session) { return } - err := s.sessionStart(session, extraEnv) + err := s.sessionStart(logger, session, extraEnv) var exitError *exec.ExitError if xerrors.As(err, &exitError) { logger.Info(ctx, "ssh session returned", slog.Error(exitError)) @@ -244,7 +252,7 @@ func (s *Server) sessionHandler(session ssh.Session) { _ = session.Exit(0) } -func (s *Server) sessionStart(session ssh.Session, extraEnv []string) (retErr error) { +func (s *Server) sessionStart(logger slog.Logger, session ssh.Session, extraEnv []string) (retErr error) { ctx := session.Context() env := append(session.Environ(), extraEnv...) var magicType string @@ -268,7 +276,7 @@ func (s *Server) sessionStart(session ssh.Session, extraEnv []string) (retErr er s.connCountSSHSession.Add(1) defer s.connCountSSHSession.Add(-1) default: - s.logger.Warn(ctx, "invalid magic ssh session type specified", slog.F("type", magicType)) + logger.Warn(ctx, "invalid magic ssh session type specified", slog.F("type", magicType)) } magicTypeLabel := magicTypeMetricLabel(magicType) @@ -342,7 +350,7 @@ type ptySession interface { RawCommand() string } -func (s *Server) startPTYSession(session ptySession, magicTypeLabel string, cmd *pty.Cmd, sshPty ssh.Pty, windowSize <-chan ssh.Window) (retErr error) { +func (s *Server) startPTYSession(logger slog.Logger, session ptySession, magicTypeLabel string, cmd *pty.Cmd, sshPty ssh.Pty, windowSize <-chan ssh.Window) (retErr error) { s.metrics.sessionsTotal.WithLabelValues(magicTypeLabel, "yes").Add(1) ctx := session.Context() @@ -355,7 +363,7 @@ func (s *Server) startPTYSession(session ptySession, magicTypeLabel string, cmd if serviceBanner != nil { err := showServiceBanner(session, serviceBanner) if err != nil { - s.logger.Error(ctx, "agent failed to show service banner", slog.Error(err)) + logger.Error(ctx, "agent failed to show service banner", slog.Error(err)) s.metrics.sessionErrors.WithLabelValues(magicTypeLabel, "yes", "service_banner").Add(1) } } @@ -366,11 +374,11 @@ func (s *Server) startPTYSession(session ptySession, magicTypeLabel string, cmd if manifest != nil { err := showMOTD(s.fs, session, manifest.MOTDFile) if err != nil { - s.logger.Error(ctx, "agent failed to show MOTD", slog.Error(err)) + logger.Error(ctx, "agent failed to show MOTD", slog.Error(err)) s.metrics.sessionErrors.WithLabelValues(magicTypeLabel, "yes", "motd").Add(1) } } else { - s.logger.Warn(ctx, "metadata lookup failed, unable to show MOTD") + logger.Warn(ctx, "metadata lookup failed, unable to show MOTD") } } @@ -379,7 +387,7 @@ func (s *Server) startPTYSession(session ptySession, magicTypeLabel string, cmd // The pty package sets `SSH_TTY` on supported platforms. ptty, process, err := pty.Start(cmd, pty.WithPTYOption( pty.WithSSHRequest(sshPty), - pty.WithLogger(slog.Stdlib(ctx, s.logger, slog.LevelInfo)), + pty.WithLogger(slog.Stdlib(ctx, logger, slog.LevelInfo)), )) if err != nil { s.metrics.sessionErrors.WithLabelValues(magicTypeLabel, "yes", "start_command").Add(1) @@ -388,7 +396,7 @@ func (s *Server) startPTYSession(session ptySession, magicTypeLabel string, cmd defer func() { closeErr := ptty.Close() if closeErr != nil { - s.logger.Warn(ctx, "failed to close tty", slog.Error(closeErr)) + logger.Warn(ctx, "failed to close tty", slog.Error(closeErr)) s.metrics.sessionErrors.WithLabelValues(magicTypeLabel, "yes", "close").Add(1) if retErr == nil { retErr = closeErr @@ -400,7 +408,7 @@ func (s *Server) startPTYSession(session ptySession, magicTypeLabel string, cmd resizeErr := ptty.Resize(uint16(win.Height), uint16(win.Width)) // If the pty is closed, then command has exited, no need to log. if resizeErr != nil && !errors.Is(resizeErr, pty.ErrClosed) { - s.logger.Warn(ctx, "failed to resize tty", slog.Error(resizeErr)) + logger.Warn(ctx, "failed to resize tty", slog.Error(resizeErr)) s.metrics.sessionErrors.WithLabelValues(magicTypeLabel, "yes", "resize").Add(1) } } @@ -422,7 +430,7 @@ func (s *Server) startPTYSession(session ptySession, magicTypeLabel string, cmd // 2. The client hangs up, which cancels the command's Context, and go will // kill the command's process. This then has the same effect as (1). n, err := io.Copy(session, ptty.OutputReader()) - s.logger.Debug(ctx, "copy output done", slog.F("bytes", n), slog.Error(err)) + logger.Debug(ctx, "copy output done", slog.F("bytes", n), slog.Error(err)) if err != nil { s.metrics.sessionErrors.WithLabelValues(magicTypeLabel, "yes", "output_io_copy").Add(1) return xerrors.Errorf("copy error: %w", err) @@ -435,7 +443,7 @@ func (s *Server) startPTYSession(session ptySession, magicTypeLabel string, cmd // ExitErrors just mean the command we run returned a non-zero exit code, which is normal // and not something to be concerned about. But, if it's something else, we should log it. if err != nil && !xerrors.As(err, &exitErr) { - s.logger.Warn(ctx, "process wait exited with error", slog.Error(err)) + logger.Warn(ctx, "process wait exited with error", slog.Error(err)) s.metrics.sessionErrors.WithLabelValues(magicTypeLabel, "yes", "wait").Add(1) } if err != nil { @@ -444,7 +452,7 @@ func (s *Server) startPTYSession(session ptySession, magicTypeLabel string, cmd return nil } -func (s *Server) sftpHandler(session ssh.Session) { +func (s *Server) sftpHandler(logger slog.Logger, session ssh.Session) { s.metrics.sftpConnectionsTotal.Add(1) ctx := session.Context() @@ -460,14 +468,14 @@ func (s *Server) sftpHandler(session ssh.Session) { // directory so that SFTP connections land there. homedir, err := userHomeDir() if err != nil { - s.logger.Warn(ctx, "get sftp working directory failed, unable to get home dir", slog.Error(err)) + logger.Warn(ctx, "get sftp working directory failed, unable to get home dir", slog.Error(err)) } else { opts = append(opts, sftp.WithServerWorkingDirectory(homedir)) } server, err := sftp.NewServer(session, opts...) if err != nil { - s.logger.Debug(ctx, "initialize sftp server", slog.Error(err)) + logger.Debug(ctx, "initialize sftp server", slog.Error(err)) return } defer server.Close() @@ -485,7 +493,7 @@ func (s *Server) sftpHandler(session ssh.Session) { _ = session.Exit(0) return } - s.logger.Warn(ctx, "sftp server closed with error", slog.Error(err)) + logger.Warn(ctx, "sftp server closed with error", slog.Error(err)) s.metrics.sftpServerErrors.Add(1) _ = session.Exit(1) } From 8f86f639cc23d36f4c19fa08ef5592a6ce117afa Mon Sep 17 00:00:00 2001 From: Steven Masley Date: Wed, 15 Nov 2023 14:30:02 -0600 Subject: [PATCH 2/4] fixup! chore: add uuid to ssh connection logs --- agent/agentssh/agentssh.go | 2 +- 1 file changed, 1 insertion(+), 1 deletion(-) diff --git a/agent/agentssh/agentssh.go b/agent/agentssh/agentssh.go index 799228117f9f2..43ae98270fb7d 100644 --- a/agent/agentssh/agentssh.go +++ b/agent/agentssh/agentssh.go @@ -309,7 +309,7 @@ func (s *Server) sessionStart(logger slog.Logger, session ssh.Session, extraEnv } if isPty { - return s.startPTYSession(session, magicTypeLabel, cmd, sshPty, windowSize) + return s.startPTYSession(logger, session, magicTypeLabel, cmd, sshPty, windowSize) } return s.startNonPTYSession(session, magicTypeLabel, cmd.AsExec()) } From e617cf26d17702618607751b7bff449ad25a6d61 Mon Sep 17 00:00:00 2001 From: Steven Masley Date: Wed, 15 Nov 2023 16:13:49 -0600 Subject: [PATCH 3/4] Add logger to test args --- agent/agentssh/agentssh_internal_test.go | 2 +- 1 file changed, 1 insertion(+), 1 deletion(-) diff --git a/agent/agentssh/agentssh_internal_test.go b/agent/agentssh/agentssh_internal_test.go index aa4cfe0236261..dd87be0503470 100644 --- a/agent/agentssh/agentssh_internal_test.go +++ b/agent/agentssh/agentssh_internal_test.go @@ -63,7 +63,7 @@ func Test_sessionStart_orphan(t *testing.T) { // we don't really care what the error is here. In the larger scenario, // the client has disconnected, so we can't return any error information // to them. - _ = s.startPTYSession(sess, "ssh", cmd, ptyInfo, windowSize) + _ = s.startPTYSession(logger, sess, "ssh", cmd, ptyInfo, windowSize) }() readDone := make(chan struct{}) From f74e4d3f907be1f0a6ea7d13189820e43c34f61b Mon Sep 17 00:00:00 2001 From: Steven Masley Date: Thu, 16 Nov 2023 13:57:30 -0600 Subject: [PATCH 4/4] Update agent/agentssh/agentssh.go Co-authored-by: Mathias Fredriksson --- agent/agentssh/agentssh.go | 2 +- 1 file changed, 1 insertion(+), 1 deletion(-) diff --git a/agent/agentssh/agentssh.go b/agent/agentssh/agentssh.go index 43ae98270fb7d..b0f9c11806235 100644 --- a/agent/agentssh/agentssh.go +++ b/agent/agentssh/agentssh.go @@ -198,7 +198,7 @@ func (s *Server) sessionHandler(session ssh.Session) { slog.F("remote_addr", session.RemoteAddr()), slog.F("local_addr", session.LocalAddr()), // Assigning a random uuid for each session is useful for tracking - // logs for the same ssh session in the logs. + // logs for the same ssh session. slog.F("id", uuid.NewString()), ) logger.Info(ctx, "handling ssh session")