synced/coder
1
0
Fork 0
mirror of https://github.com/coder/coder.git synced 2025-07-15 22:20:27 +00:00
Code Issues Packages Projects Releases Wiki Activity

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

Browse Source 
* chore: add uuid to ssh connection logs
This commit is contained in:
Steven Masley
2023-11-17 10:04:23 -06:00
committed by GitHub
parent befb42b6fd
commit e448c10122
2 changed files with 29 additions and 21 deletions
Download Patch File Download Diff File Expand all files Collapse all files

48
agent/agentssh/agentssh.go
View File

@ -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.
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)
@ -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())
}
@ -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)
}

2
agent/agentssh/agentssh_internal_test.go
View File

@ -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{})