Skip to content

feat: add logging of ssh connections to agent #8096

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 3 commits into from
Jun 21, 2023
Merged

feat: add logging of ssh connections to agent #8096

Changes from all commits
Commits
Show all changes
3 commits
Select commit Hold shift + click to select a range
578a928
feat: adds logging of ssh connections to agent
spikecurtis Jun 20, 2023
0eb01c2
code review improvements
spikecurtis Jun 21, 2023
11da1e4
Merge branch 'main' of https://github.com/coder/coder into spike/7961…
spikecurtis Jun 21, 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
31 changes: 24 additions & 7 deletions agent/agentssh/agentssh.go
View file
Open in desktop
Original file line number Diff line number Diff line change
Expand Up @@ -180,21 +180,24 @@ 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()
if !s.trackSession(session, true) {
// See (*Server).Close() for why we call Close instead of Exit.
_ = session.Close()
logger.Info(ctx, "unable to accept new session, server is closing")
return
}
defer s.trackSession(session, false)

ctx := session.Context()

extraEnv := make([]string, 0)
x11, hasX11 := session.X11()
if hasX11 {
handled := s.x11Handler(session.Context(), x11)
if !handled {
_ = session.Exit(1)
logger.Error(ctx, "x11 handler failed")
return
}
extraEnv = append(extraEnv, fmt.Sprintf("DISPLAY=:%d.0", x11.ScreenNumber))
Expand All @@ -206,25 +209,26 @@ func (s *Server) sessionHandler(session ssh.Session) {
s.sftpHandler(session)
return
default:
s.logger.Debug(ctx, "unsupported subsystem", slog.F("subsystem", ss))
logger.Warn(ctx, "unsupported subsystem", slog.F("subsystem", ss))
_ = session.Exit(1)
return
}

err := s.sessionStart(session, extraEnv)
var exitError *exec.ExitError
if xerrors.As(err, &exitError) {
s.logger.Warn(ctx, "ssh session returned", slog.Error(exitError))
logger.Info(ctx, "ssh session returned", slog.Error(exitError))
_ = session.Exit(exitError.ExitCode())
return
}
if err != nil {
s.logger.Warn(ctx, "ssh session failed", slog.Error(err))
logger.Warn(ctx, "ssh session failed", slog.Error(err))
// This exit code is designed to be unlikely to be confused for a legit exit code
// from the process.
_ = session.Exit(MagicSessionErrorCode)
return
}
logger.Info(ctx, "normal ssh session exit")
_ = session.Exit(0)
}

Expand Down Expand Up @@ -565,7 +569,12 @@ func (s *Server) CreateCommand(ctx context.Context, script string, env []string)
return cmd, nil
}

func (s *Server) Serve(l net.Listener) error {
func (s *Server) Serve(l net.Listener) (retErr error) {
s.logger.Info(context.Background(), "started serving listener", slog.F("listen_addr", l.Addr()))
defer func() {
s.logger.Info(context.Background(), "stopped serving listener",
Copy link
Member

Choose a reason for hiding this comment

The reason will be displayed to describe this comment to others. Learn more.

nit: maybe we should also log the total serving time for debugging/support purposes?

Copy link
Contributor Author

Choose a reason for hiding this comment

The reason will be displayed to describe this comment to others. Learn more.

logs have timestamps, so I'm not generally worried about being able to tell how much time elapsed.

Listeners get restarted only on agent reconnections to coderd, which should be pretty obvious from the logs.

Copy link
Member

Choose a reason for hiding this comment

The reason will be displayed to describe this comment to others. Learn more.

Ok, I was thinking only about reducing the investigation time, even if the information is redundant. Feel free to leave it as is.

slog.F("listen_addr", l.Addr()), slog.Error(retErr))
}()
defer l.Close()

s.trackListener(l, true)
Expand All @@ -580,15 +589,23 @@ func (s *Server) Serve(l net.Listener) error {
}

func (s *Server) handleConn(l net.Listener, c net.Conn) {
logger := s.logger.With(
slog.F("remote_addr", c.RemoteAddr()),
slog.F("local_addr", c.LocalAddr()),
slog.F("listen_addr", l.Addr()))
defer c.Close()

if !s.trackConn(l, c, true) {
// Server is closed or we no longer want
// connections from this listener.
s.logger.Debug(context.Background(), "received connection after server closed")
logger.Info(context.Background(), "received connection after server closed")
return
}
defer s.trackConn(l, c, false)
logger.Info(context.Background(), "started serving connection")
defer func() {
logger.Info(context.Background(), "stopped serving connection")
}()

s.srv.HandleConn(c)
}
Expand Down