Add gitlab-sshd connection logging

2 files changed, 18 insertions, 6 deletions

diff --git a/internal/sshd/connection.go b/internal/sshd/connection.go
index 1d91a6c..c8f5c00 100644
--- a/internal/sshd/connection.go
+++ b/internal/sshd/connection.go
@@ -29,21 +29,26 @@ func newConnection(maxSessions int64, remoteAddr string) *connection {
 }
 
 func (c *connection) handle(ctx context.Context, chans <-chan ssh.NewChannel, handler channelHandler) {
+	ctxlog := log.WithContextFields(ctx, log.Fields{"remote_addr": c.remoteAddr})
+
 	defer metrics.SshdConnectionDuration.Observe(time.Since(c.begin).Seconds())
 
 	for newChannel := range chans {
+		ctxlog.WithField("channel_type", newChannel.ChannelType).Info("connection: handle: new channel requested")
 		if newChannel.ChannelType() != "session" {
+			ctxlog.Info("connection: handle: unknown channel type")
 			newChannel.Reject(ssh.UnknownChannelType, "unknown channel type")
 			continue
 		}
 		if !c.concurrentSessions.TryAcquire(1) {
+			ctxlog.Info("connection: handle: too many concurrent sessions")
 			newChannel.Reject(ssh.ResourceShortage, "too many concurrent sessions")
 			metrics.SshdHitMaxSessions.Inc()
 			continue
 		}
 		channel, requests, err := newChannel.Accept()
 		if err != nil {
-			log.WithError(err).Info("could not accept channel")
+			ctxlog.WithError(err).Error("connection: handle: accepting channel failed")
 			c.concurrentSessions.Release(1)
 			continue
 		}
@@ -54,11 +59,12 @@ func (c *connection) handle(ctx context.Context, chans <-chan ssh.NewChannel, ha
 			// Prevent a panic in a single session from taking out the whole server
 			defer func() {
 				if err := recover(); err != nil {
-					log.WithContextFields(ctx, log.Fields{"recovered_error": err, "address": c.remoteAddr}).Warn("panic handling session")
+					ctxlog.WithField("recovered_error", err).Warn("panic handling session")
 				}
 			}()
 
 			handler(ctx, channel, requests)
+			ctxlog.Info("connection: handle: done")
 		}()
 	}
 }
diff --git a/internal/sshd/sshd.go b/internal/sshd/sshd.go
index 92a9c2b..19fa661 100644
--- a/internal/sshd/sshd.go
+++ b/internal/sshd/sshd.go
@@ -149,19 +149,23 @@ func (s *Server) handleConn(ctx context.Context, nconn net.Conn) {
 	defer s.wg.Done()
 	defer nconn.Close()
 
+	ctx, cancel := context.WithCancel(correlation.ContextWithCorrelation(ctx, correlation.SafeRandomID()))
+	defer cancel()
+
+	ctxlog := log.WithContextFields(ctx, log.Fields{"remote_addr": remoteAddr})
+
 	// Prevent a panic in a single connection from taking out the whole server
 	defer func() {
 		if err := recover(); err != nil {
-			log.WithContextFields(ctx, log.Fields{"recovered_error": err, "address": remoteAddr}).Warn("panic handling session")
+			ctxlog.Warn("panic handling session")
 		}
 	}()
 
-	ctx, cancel := context.WithCancel(correlation.ContextWithCorrelation(ctx, correlation.SafeRandomID()))
-	defer cancel()
+	ctxlog.Info("server: handleConn: start")
 
 	sconn, chans, reqs, err := ssh.NewServerConn(nconn, s.serverConfig.get(ctx))
 	if err != nil {
-		log.ContextLogger(ctx).WithError(err).Info("Failed to initialize SSH connection")
+		ctxlog.WithError(err).Error("server: handleConn: failed to initialize SSH connection")
 		return
 	}
 
@@ -178,4 +182,6 @@ func (s *Server) handleConn(ctx context.Context, nconn net.Conn) {
 
 		session.handle(ctx, requests)
 	})
+
+	ctxlog.Info("server: handleConn: done")
 }