Merge branch 'id-session-duration' into 'main'

Improve establish session duration metrics

See merge request gitlab-org/gitlab-shell!651

3 files changed, 20 insertions, 19 deletions

diff --git a/internal/sshd/connection.go b/internal/sshd/connection.go
index 5600260..3c20788 100644
--- a/internal/sshd/connection.go
+++ b/internal/sshd/connection.go
@@ -25,13 +25,11 @@ const KeepAliveMsg = "keepalive@openssh.com"
 var EOFTimeout = 10 * time.Second
 
 type connection struct {
-	cfg                      *config.Config
-	concurrentSessions       *semaphore.Weighted
-	nconn                    net.Conn
-	maxSessions              int64
-	remoteAddr               string
-	started                  time.Time
-	establishSessionDuration float64
+	cfg                *config.Config
+	concurrentSessions *semaphore.Weighted
+	nconn              net.Conn
+	maxSessions        int64
+	remoteAddr         string
 }
 
 type channelHandler func(*ssh.ServerConn, ssh.Channel, <-chan *ssh.Request) error
@@ -45,7 +43,6 @@ func newConnection(cfg *config.Config, nconn net.Conn) *connection {
 		concurrentSessions: semaphore.NewWeighted(maxSessions),
 		nconn:              nconn,
 		remoteAddr:         nconn.RemoteAddr().String(),
-		started:            time.Now(),
 	}
 }
 
@@ -64,11 +61,7 @@ func (c *connection) handle(ctx context.Context, srvCfg *ssh.ServerConfig, handl
 	c.handleRequests(ctx, sconn, chans, handler)
 
 	reason := sconn.Wait()
-	log.WithContextFields(ctx, log.Fields{
-		"duration_s":                   time.Since(c.started).Seconds(),
-		"establish_session_duration_s": c.establishSessionDuration,
-		"reason":                       reason,
-	}).Info("server: handleConn: done")
+	log.WithContextFields(ctx, log.Fields{"reason": reason}).Info("server: handleConn: done")
 }
 
 func (c *connection) initServerConn(ctx context.Context, srvCfg *ssh.ServerConfig) (*ssh.ServerConn, <-chan ssh.NewChannel, error) {
@@ -120,10 +113,10 @@ func (c *connection) handleRequests(ctx context.Context, sconn *ssh.ServerConn,
 
 		go func() {
 			defer func(started time.Time) {
-				metrics.SshdSessionDuration.Observe(time.Since(started).Seconds())
+				duration := time.Since(started).Seconds()
+				metrics.SshdSessionDuration.Observe(duration)
+				ctxlog.WithFields(log.Fields{"duration_s": duration}).Info("connection: handleRequests: done")
 			}(time.Now())
-			c.establishSessionDuration = time.Since(c.started).Seconds()
-			metrics.SshdSessionEstablishedDuration.Observe(c.establishSessionDuration)
 
 			defer c.concurrentSessions.Release(1)
 
@@ -139,8 +132,6 @@ func (c *connection) handleRequests(ctx context.Context, sconn *ssh.ServerConn,
 			if err != nil {
 				c.trackError(ctxlog, err)
 			}
-
-			ctxlog.Info("connection: handleRequests: done")
 		}()
 	}
 
diff --git a/internal/sshd/session.go b/internal/sshd/session.go
index ac079dc..7aa6d5d 100644
--- a/internal/sshd/session.go
+++ b/internal/sshd/session.go
@@ -5,6 +5,7 @@ import (
 	"errors"
 	"fmt"
 	"reflect"
+	"time"
 
 	"gitlab.com/gitlab-org/labkit/log"
 	"golang.org/x/crypto/ssh"
@@ -16,6 +17,7 @@ import (
 	"gitlab.com/gitlab-org/gitlab-shell/internal/command/shared/disallowedcommand"
 	"gitlab.com/gitlab-org/gitlab-shell/internal/config"
 	"gitlab.com/gitlab-org/gitlab-shell/internal/console"
+	"gitlab.com/gitlab-org/gitlab-shell/internal/metrics"
 	"gitlab.com/gitlab-org/gitlab-shell/internal/sshenv"
 )
 
@@ -29,6 +31,7 @@ type session struct {
 	// State managed by the session
 	execCmd            string
 	gitProtocolVersion string
+	started            time.Time
 }
 
 type execRequest struct {
@@ -171,7 +174,12 @@ func (s *session) handleShell(ctx context.Context, req *ssh.Request) (uint32, er
 	}
 
 	cmdName := reflect.TypeOf(cmd).String()
-	ctxlog.WithFields(log.Fields{"env": env, "command": cmdName}).Info("session: handleShell: executing command")
+
+	establishSessionDuration := time.Since(s.started).Seconds()
+	ctxlog.WithFields(log.Fields{
+		"env": env, "command": cmdName, "established_session_duration_s": establishSessionDuration,
+	}).Info("session: handleShell: executing command")
+	metrics.SshdSessionEstablishedDuration.Observe(establishSessionDuration)
 
 	if err := cmd.Execute(ctx); err != nil {
 		grpcStatus := grpcstatus.Convert(err)
diff --git a/internal/sshd/sshd.go b/internal/sshd/sshd.go
index d927268..a0c4d0e 100644
--- a/internal/sshd/sshd.go
+++ b/internal/sshd/sshd.go
@@ -171,6 +171,7 @@ func (s *Server) handleConn(ctx context.Context, nconn net.Conn) {
 		}
 	}()
 
+	started := time.Now()
 	conn := newConnection(s.Config, nconn)
 	conn.handle(ctx, s.serverConfig.get(ctx), func(sconn *ssh.ServerConn, channel ssh.Channel, requests <-chan *ssh.Request) error {
 		session := &session{
@@ -178,6 +179,7 @@ func (s *Server) handleConn(ctx context.Context, nconn net.Conn) {
 			channel:     channel,
 			gitlabKeyId: sconn.Permissions.Extensions["key-id"],
 			remoteAddr:  remoteAddr,
+			started:     started,
 		}
 
 		return session.handle(ctx, requests)