Skip to content

Commit e448c10

Browse files
EmyrkEmyrk
authored
chore: add uuid's to ssh sessions for logging (#10721)
* chore: add uuid to ssh connection logs
1 parent befb42b commit e448c10

File tree

2 files changed

+29
-21
lines changed

2 files changed

+29
-21
lines changed

‎agent/agentssh/agentssh.go

Lines changed: 28 additions & 20 deletions
Original file line numberDiff line numberDiff line change
@@ -19,6 +19,7 @@ import (
1919
"time"
2020

2121
"github.com/gliderlabs/ssh"
22+
"github.com/google/uuid"
2223
"github.com/kballard/go-shellquote"
2324
"github.com/pkg/sftp"
2425
"github.com/prometheus/client_golang/prometheus"
@@ -192,9 +193,16 @@ func (s *Server) ConnStats() ConnStats {
192193
}
193194

194195
func (s *Server) sessionHandler(session ssh.Session) {
195-
logger := s.logger.With(slog.F("remote_addr", session.RemoteAddr()), slog.F("local_addr", session.LocalAddr()))
196-
logger.Info(session.Context(), "handling ssh session")
197196
ctx := session.Context()
197+
logger := s.logger.With(
198+
slog.F("remote_addr", session.RemoteAddr()),
199+
slog.F("local_addr", session.LocalAddr()),
200+
// Assigning a random uuid for each session is useful for tracking
201+
// logs for the same ssh session.
202+
slog.F("id", uuid.NewString()),
203+
)
204+
logger.Info(ctx, "handling ssh session")
205+
198206
if !s.trackSession(session, true) {
199207
// See (*Server).Close() for why we call Close instead of Exit.
200208
_ = session.Close()
@@ -218,15 +226,15 @@ func (s *Server) sessionHandler(session ssh.Session) {
218226
switch ss := session.Subsystem(); ss {
219227
case "":
220228
case "sftp":
221-
s.sftpHandler(session)
229+
s.sftpHandler(logger, session)
222230
return
223231
default:
224232
logger.Warn(ctx, "unsupported subsystem", slog.F("subsystem", ss))
225233
_ = session.Exit(1)
226234
return
227235
}
228236

229-
err := s.sessionStart(session, extraEnv)
237+
err := s.sessionStart(logger, session, extraEnv)
230238
var exitError *exec.ExitError
231239
if xerrors.As(err, &exitError) {
232240
logger.Info(ctx, "ssh session returned", slog.Error(exitError))
@@ -244,7 +252,7 @@ func (s *Server) sessionHandler(session ssh.Session) {
244252
_ = session.Exit(0)
245253
}
246254

247-
func (s *Server) sessionStart(session ssh.Session, extraEnv []string) (retErr error) {
255+
func (s *Server) sessionStart(logger slog.Logger, session ssh.Session, extraEnv []string) (retErr error) {
248256
ctx := session.Context()
249257
env := append(session.Environ(), extraEnv...)
250258
var magicType string
@@ -268,7 +276,7 @@ func (s *Server) sessionStart(session ssh.Session, extraEnv []string) (retErr er
268276
s.connCountSSHSession.Add(1)
269277
defer s.connCountSSHSession.Add(-1)
270278
default:
271-
s.logger.Warn(ctx, "invalid magic ssh session type specified", slog.F("type", magicType))
279+
logger.Warn(ctx, "invalid magic ssh session type specified", slog.F("type", magicType))
272280
}
273281

274282
magicTypeLabel := magicTypeMetricLabel(magicType)
@@ -301,7 +309,7 @@ func (s *Server) sessionStart(session ssh.Session, extraEnv []string) (retErr er
301309
}
302310

303311
if isPty {
304-
return s.startPTYSession(session, magicTypeLabel, cmd, sshPty, windowSize)
312+
return s.startPTYSession(logger, session, magicTypeLabel, cmd, sshPty, windowSize)
305313
}
306314
return s.startNonPTYSession(session, magicTypeLabel, cmd.AsExec())
307315
}
@@ -342,7 +350,7 @@ type ptySession interface {
342350
RawCommand() string
343351
}
344352

345-
func (s *Server) startPTYSession(session ptySession, magicTypeLabel string, cmd *pty.Cmd, sshPty ssh.Pty, windowSize <-chan ssh.Window) (retErr error) {
353+
func (s *Server) startPTYSession(logger slog.Logger, session ptySession, magicTypeLabel string, cmd *pty.Cmd, sshPty ssh.Pty, windowSize <-chan ssh.Window) (retErr error) {
346354
s.metrics.sessionsTotal.WithLabelValues(magicTypeLabel, "yes").Add(1)
347355

348356
ctx := session.Context()
@@ -355,7 +363,7 @@ func (s *Server) startPTYSession(session ptySession, magicTypeLabel string, cmd
355363
if serviceBanner != nil {
356364
err := showServiceBanner(session, serviceBanner)
357365
if err != nil {
358-
s.logger.Error(ctx, "agent failed to show service banner", slog.Error(err))
366+
logger.Error(ctx, "agent failed to show service banner", slog.Error(err))
359367
s.metrics.sessionErrors.WithLabelValues(magicTypeLabel, "yes", "service_banner").Add(1)
360368
}
361369
}
@@ -366,11 +374,11 @@ func (s *Server) startPTYSession(session ptySession, magicTypeLabel string, cmd
366374
if manifest != nil {
367375
err := showMOTD(s.fs, session, manifest.MOTDFile)
368376
if err != nil {
369-
s.logger.Error(ctx, "agent failed to show MOTD", slog.Error(err))
377+
logger.Error(ctx, "agent failed to show MOTD", slog.Error(err))
370378
s.metrics.sessionErrors.WithLabelValues(magicTypeLabel, "yes", "motd").Add(1)
371379
}
372380
} else {
373-
s.logger.Warn(ctx, "metadata lookup failed, unable to show MOTD")
381+
logger.Warn(ctx, "metadata lookup failed, unable to show MOTD")
374382
}
375383
}
376384

@@ -379,7 +387,7 @@ func (s *Server) startPTYSession(session ptySession, magicTypeLabel string, cmd
379387
// The pty package sets `SSH_TTY` on supported platforms.
380388
ptty, process, err := pty.Start(cmd, pty.WithPTYOption(
381389
pty.WithSSHRequest(sshPty),
382-
pty.WithLogger(slog.Stdlib(ctx, s.logger, slog.LevelInfo)),
390+
pty.WithLogger(slog.Stdlib(ctx, logger, slog.LevelInfo)),
383391
))
384392
if err != nil {
385393
s.metrics.sessionErrors.WithLabelValues(magicTypeLabel, "yes", "start_command").Add(1)
@@ -388,7 +396,7 @@ func (s *Server) startPTYSession(session ptySession, magicTypeLabel string, cmd
388396
defer func() {
389397
closeErr := ptty.Close()
390398
if closeErr != nil {
391-
s.logger.Warn(ctx, "failed to close tty", slog.Error(closeErr))
399+
logger.Warn(ctx, "failed to close tty", slog.Error(closeErr))
392400
s.metrics.sessionErrors.WithLabelValues(magicTypeLabel, "yes", "close").Add(1)
393401
if retErr == nil {
394402
retErr = closeErr
@@ -400,7 +408,7 @@ func (s *Server) startPTYSession(session ptySession, magicTypeLabel string, cmd
400408
resizeErr := ptty.Resize(uint16(win.Height), uint16(win.Width))
401409
// If the pty is closed, then command has exited, no need to log.
402410
if resizeErr != nil && !errors.Is(resizeErr, pty.ErrClosed) {
403-
s.logger.Warn(ctx, "failed to resize tty", slog.Error(resizeErr))
411+
logger.Warn(ctx, "failed to resize tty", slog.Error(resizeErr))
404412
s.metrics.sessionErrors.WithLabelValues(magicTypeLabel, "yes", "resize").Add(1)
405413
}
406414
}
@@ -422,7 +430,7 @@ func (s *Server) startPTYSession(session ptySession, magicTypeLabel string, cmd
422430
// 2. The client hangs up, which cancels the command's Context, and go will
423431
// kill the command's process. This then has the same effect as (1).
424432
n, err := io.Copy(session, ptty.OutputReader())
425-
s.logger.Debug(ctx, "copy output done", slog.F("bytes", n), slog.Error(err))
433+
logger.Debug(ctx, "copy output done", slog.F("bytes", n), slog.Error(err))
426434
if err != nil {
427435
s.metrics.sessionErrors.WithLabelValues(magicTypeLabel, "yes", "output_io_copy").Add(1)
428436
return xerrors.Errorf("copy error: %w", err)
@@ -435,7 +443,7 @@ func (s *Server) startPTYSession(session ptySession, magicTypeLabel string, cmd
435443
// ExitErrors just mean the command we run returned a non-zero exit code, which is normal
436444
// and not something to be concerned about. But, if it's something else, we should log it.
437445
if err != nil && !xerrors.As(err, &exitErr) {
438-
s.logger.Warn(ctx, "process wait exited with error", slog.Error(err))
446+
logger.Warn(ctx, "process wait exited with error", slog.Error(err))
439447
s.metrics.sessionErrors.WithLabelValues(magicTypeLabel, "yes", "wait").Add(1)
440448
}
441449
if err != nil {
@@ -444,7 +452,7 @@ func (s *Server) startPTYSession(session ptySession, magicTypeLabel string, cmd
444452
return nil
445453
}
446454

447-
func (s *Server) sftpHandler(session ssh.Session) {
455+
func (s *Server) sftpHandler(logger slog.Logger, session ssh.Session) {
448456
s.metrics.sftpConnectionsTotal.Add(1)
449457

450458
ctx := session.Context()
@@ -460,14 +468,14 @@ func (s *Server) sftpHandler(session ssh.Session) {
460468
// directory so that SFTP connections land there.
461469
homedir, err := userHomeDir()
462470
if err != nil {
463-
s.logger.Warn(ctx, "get sftp working directory failed, unable to get home dir", slog.Error(err))
471+
logger.Warn(ctx, "get sftp working directory failed, unable to get home dir", slog.Error(err))
464472
} else {
465473
opts = append(opts, sftp.WithServerWorkingDirectory(homedir))
466474
}
467475

468476
server, err := sftp.NewServer(session, opts...)
469477
if err != nil {
470-
s.logger.Debug(ctx, "initialize sftp server", slog.Error(err))
478+
logger.Debug(ctx, "initialize sftp server", slog.Error(err))
471479
return
472480
}
473481
defer server.Close()
@@ -485,7 +493,7 @@ func (s *Server) sftpHandler(session ssh.Session) {
485493
_ = session.Exit(0)
486494
return
487495
}
488-
s.logger.Warn(ctx, "sftp server closed with error", slog.Error(err))
496+
logger.Warn(ctx, "sftp server closed with error", slog.Error(err))
489497
s.metrics.sftpServerErrors.Add(1)
490498
_ = session.Exit(1)
491499
}

‎agent/agentssh/agentssh_internal_test.go

Lines changed: 1 addition & 1 deletion
Original file line numberDiff line numberDiff line change
@@ -63,7 +63,7 @@ func Test_sessionStart_orphan(t *testing.T) {
6363
// we don't really care what the error is here. In the larger scenario,
6464
// the client has disconnected, so we can't return any error information
6565
// to them.
66-
_ = s.startPTYSession(sess, "ssh", cmd, ptyInfo, windowSize)
66+
_ = s.startPTYSession(logger, sess, "ssh", cmd, ptyInfo, windowSize)
6767
}()
6868

6969
readDone := make(chan struct{})

0 commit comments

Comments
 (0)