Skip to content

chore: add uuid's to ssh sessions for logging #10721

New issue

Have a question about this project? Sign up for a free GitHub account to open an issue and contact its maintainers and the community.

Sign up for GitHub

By clicking “Sign up for GitHub”, you agree to our terms of service and privacy statement. We’ll occasionally send you account related emails.

Already on GitHub? Sign in to your account

Merged
merged 4 commits into from
Nov 17, 2023
Merged

chore: add uuid's to ssh sessions for logging #10721

Show file tree
Hide file tree
Changes from all commits
Commits
Show all changes
4 commits
Select commit Hold shift + click to select a range
0baf95d
chore: add uuid to ssh connection logs
Emyrk Nov 15, 2023
8f86f63
fixup! chore: add uuid to ssh connection logs
Emyrk Nov 15, 2023
e617cf2
Add logger to test args
Emyrk Nov 15, 2023
f74e4d3
Update agent/agentssh/agentssh.go
Emyrk Nov 16, 2023
File filter

Filter by extension

Filter by extension
Conversations
Failed to load comments.
Loading
Jump to
Jump to file
Failed to load files.
Loading
Diff view
Diff view
48 changes: 28 additions & 20 deletions agent/agentssh/agentssh.go
View file
Open in desktop
Original file line number Diff line number Diff line change
Expand Up @@ -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"
Expand Down Expand Up @@ -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.
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()
Expand All @@ -218,15 +226,15 @@ 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))
_ = session.Exit(1)
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))
Expand All @@ -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
Expand All @@ -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)
Expand Down Expand Up @@ -301,7 +309,7 @@ func (s *Server) sessionStart(session ssh.Session, extraEnv []string) (retErr er
}

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())
}
Expand Down Expand Up @@ -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()
Expand All @@ -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)
}
}
Expand All @@ -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")
}
}

Expand All @@ -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)
Expand All @@ -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
Expand All @@ -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)
}
}
Expand All @@ -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)
Expand All @@ -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 {
Expand All @@ -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()
Expand All @@ -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()
Expand All @@ -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)
}
Expand Down
2 changes: 1 addition & 1 deletion agent/agentssh/agentssh_internal_test.go
View file
Open in desktop
Original file line number Diff line number Diff line change
Expand Up @@ -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{})
Expand Down