feat: add logging to agent stats and JetBrains tracking (#11364)

spikecurtis · web-flow · commit 4071f1713bb8 · 2024-01-02T13:34:49.000+04:00
Adds logging so we can hope to diagnose #11363
diff --git a/agent/agent.go b/agent/agent.go
@@ -1188,6 +1188,7 @@ func (a *agent) handleReconnectingPTY(ctx context.Context, logger slog.Logger, m
 // startReportingConnectionStats runs the connection stats reporting goroutine.
 func (a *agent) startReportingConnectionStats(ctx context.Context) {
 	reportStats := func(networkStats map[netlogtype.Connection]netlogtype.Counts) {
+		a.logger.Debug(ctx, "computing stats report")
 		stats := &agentsdk.Stats{
 			ConnectionCount:    int64(len(networkStats)),
 			ConnectionsByProto: map[string]int64{},
@@ -1209,6 +1210,7 @@ func (a *agent) startReportingConnectionStats(ctx context.Context) {
 		stats.SessionCountReconnectingPTY = a.connCountReconnectingPTY.Load()
 
 		// Compute the median connection latency!
+		a.logger.Debug(ctx, "starting peer latency measurement for stats")
 		var wg sync.WaitGroup
 		var mu sync.Mutex
 		status := a.network.Status()
@@ -1257,13 +1259,17 @@ func (a *agent) startReportingConnectionStats(ctx context.Context) {
 
 		metricsCtx, cancelFunc := context.WithTimeout(ctx, 5*time.Second)
 		defer cancelFunc()
+		a.logger.Debug(ctx, "collecting agent metrics for stats")
 		stats.Metrics = a.collectMetrics(metricsCtx)
 
 		a.latestStat.Store(stats)
 
+		a.logger.Debug(ctx, "about to send stats")
 		select {
 		case a.connStatsChan <- stats:
+			a.logger.Debug(ctx, "successfully sent stats")
 		case <-a.closed:
+			a.logger.Debug(ctx, "didn't send stats because we are closed")
 		}
 	}
 
diff --git a/agent/agentssh/jetbrainstrack.go b/agent/agentssh/jetbrainstrack.go
@@ -1,6 +1,7 @@
 package agentssh
 
 import (
+	"context"
 	"strings"
 	"sync"
 
@@ -26,6 +27,7 @@ type localForwardChannelData struct {
 type JetbrainsChannelWatcher struct {
 	gossh.NewChannel
 	jetbrainsCounter *atomic.Int64
+	logger           slog.Logger
 }
 
 func NewJetbrainsChannelWatcher(ctx ssh.Context, logger slog.Logger, newChannel gossh.NewChannel, counter *atomic.Int64) gossh.NewChannel {
@@ -58,6 +60,7 @@ func NewJetbrainsChannelWatcher(ctx ssh.Context, logger slog.Logger, newChannel
 	return &JetbrainsChannelWatcher{
 		NewChannel:       newChannel,
 		jetbrainsCounter: counter,
+		logger:           logger.With(slog.F("destination_port", d.DestPort)),
 	}
 }
 
@@ -67,11 +70,15 @@ func (w *JetbrainsChannelWatcher) Accept() (gossh.Channel, <-chan *gossh.Request
 		return c, r, err
 	}
 	w.jetbrainsCounter.Add(1)
+	// nolint: gocritic // JetBrains is a proper noun and should be capitalized
+	w.logger.Debug(context.Background(), "JetBrains watcher accepted channel")
 
 	return &ChannelOnClose{
 		Channel: c,
 		done: func() {
 			w.jetbrainsCounter.Add(-1)
+			// nolint: gocritic // JetBrains is a proper noun and should be capitalized
+			w.logger.Debug(context.Background(), "JetBrains watcher channel closed")
 		},
 	}, r, err
 }
