From b52939e2c251bbda2f0206af0d6c6f6f5f737e6c Mon Sep 17 00:00:00 2001
From: Paulo Gomes <paulo.gomes@weave.works>
Date: Thu, 9 Jun 2022 09:37:45 +0100
Subject: [PATCH] libgit2: improve SSH subtransport logging Debugging
 connection issues can be extremely difficult, even more so at scale or when
 concurrent connections are required to trigger specific issues.

The changes create an unique identifier for each
SubTransport instance, which allows for greater traceability
when going through all the steps throughout the transport
lifecicle.

Signed-off-by: Paulo Gomes <paulo.gomes@weave.works>
---
 pkg/git/libgit2/managed/ssh.go | 35 ++++++++++++++++++++++------------
 1 file changed, 23 insertions(+), 12 deletions(-)

diff --git a/pkg/git/libgit2/managed/ssh.go b/pkg/git/libgit2/managed/ssh.go
index b990dd0af..9f0dece7a 100644
--- a/pkg/git/libgit2/managed/ssh.go
+++ b/pkg/git/libgit2/managed/ssh.go
@@ -59,7 +59,10 @@ import (
 	"golang.org/x/crypto/ssh"
 	"golang.org/x/net/proxy"
 
+	"github.com/fluxcd/pkg/runtime/logger"
 	"github.com/fluxcd/source-controller/pkg/git"
+	"github.com/go-logr/logr"
+	"github.com/google/uuid"
 	git2go "github.com/libgit2/git2go/v33"
 )
 
@@ -79,16 +82,17 @@ func registerManagedSSH() error {
 func sshSmartSubtransportFactory(remote *git2go.Remote, transport *git2go.Transport) (git2go.SmartSubtransport, error) {
 	return &sshSmartSubtransport{
 		transport: transport,
+		logger:    logr.Discard(),
 	}, nil
 }
 
 type sshSmartSubtransport struct {
 	transport *git2go.Transport
+	logger    logr.Logger
 
 	lastAction git2go.SmartServiceAction
 	stdin      io.WriteCloser
 	stdout     io.Reader
-	addr       string
 	ctx        context.Context
 
 	con connection
@@ -111,8 +115,6 @@ func (t *sshSmartSubtransport) Action(transportOptionsURL string, action git2go.
 		return nil, fmt.Errorf("could not find transport options for object: %s", transportOptionsURL)
 	}
 
-	t.ctx = opts.Context
-
 	u, err := url.Parse(opts.TargetURL)
 	if err != nil {
 		return nil, err
@@ -158,7 +160,14 @@ func (t *sshSmartSubtransport) Action(transportOptionsURL string, action git2go.
 	if u.Port() != "" {
 		port = u.Port()
 	}
-	t.addr = net.JoinHostPort(u.Hostname(), port)
+	addr := net.JoinHostPort(u.Hostname(), port)
+
+	if t.ctx == nil {
+		t.ctx = opts.Context
+		t.logger = logr.FromContextOrDiscard(t.ctx).
+			WithValues("TransportID", uuid.New()).
+			WithValues("addr", addr)
+	}
 
 	sshConfig, err := createClientConfig(opts.AuthOpts)
 	if err != nil {
@@ -191,12 +200,12 @@ func (t *sshSmartSubtransport) Action(transportOptionsURL string, action git2go.
 	}
 	t.con.m.RUnlock()
 
-	err = t.createConn(t.addr, sshConfig)
+	err = t.createConn(addr, sshConfig)
 	if err != nil {
 		return nil, err
 	}
 
-	traceLog.Info("[ssh]: creating new ssh session")
+	t.logger.V(logger.TraceLevel).Info("[ssh]: creating new ssh session")
 	if t.con.session, err = t.con.client.NewSession(); err != nil {
 		return nil, err
 	}
@@ -222,8 +231,8 @@ func (t *sshSmartSubtransport) Action(transportOptionsURL string, action git2go.
 
 			// In case this goroutine panics, handle recovery.
 			if r := recover(); r != nil {
-				traceLog.Error(errors.New(r.(string)),
-					"[ssh]: recovered from libgit2 ssh smart subtransport panic", "address", t.addr)
+				t.logger.V(logger.TraceLevel).Error(errors.New(r.(string)),
+					"[ssh]: recovered from libgit2 ssh smart subtransport panic")
 			}
 		}()
 
@@ -259,7 +268,7 @@ func (t *sshSmartSubtransport) Action(transportOptionsURL string, action git2go.
 		}
 	}()
 
-	traceLog.Info("[ssh]: run on remote", "cmd", cmd)
+	t.logger.V(logger.TraceLevel).Info("[ssh]: run on remote", "cmd", cmd)
 	if err := t.con.session.Start(cmd); err != nil {
 		return nil, err
 	}
@@ -276,6 +285,7 @@ func (t *sshSmartSubtransport) createConn(addr string, sshConfig *ssh.ClientConf
 	ctx, cancel := context.WithTimeout(context.TODO(), sshConnectionTimeOut)
 	defer cancel()
 
+	t.logger.V(logger.TraceLevel).Info("[ssh] dial connection")
 	conn, err := proxy.Dial(ctx, "tcp", addr)
 	if err != nil {
 		return err
@@ -303,9 +313,10 @@ func (t *sshSmartSubtransport) createConn(addr string, sshConfig *ssh.ClientConf
 // may impair the transport to have successful actions on a new
 // SmartSubTransport (i.e. unreleased resources, staled connections).
 func (t *sshSmartSubtransport) Close() error {
-	traceLog.Info("[ssh]: sshSmartSubtransport.Close()", "server", t.addr)
+	t.logger.V(logger.TraceLevel).Info("[ssh]: sshSmartSubtransport.Close()")
 	t.con.m.Lock()
 	defer t.con.m.Unlock()
+
 	t.con.currentStream = nil
 	if t.con.client != nil && t.stdin != nil {
 		_ = t.stdin.Close()
@@ -313,13 +324,14 @@ func (t *sshSmartSubtransport) Close() error {
 	t.stdin = nil
 
 	if t.con.session != nil {
-		traceLog.Info("[ssh]: session.Close()", "server", t.addr)
+		t.logger.V(logger.TraceLevel).Info("[ssh]: session.Close()")
 		_ = t.con.session.Close()
 	}
 	t.con.session = nil
 
 	if t.con.client != nil {
 		_ = t.con.client.Close()
+		t.logger.V(logger.TraceLevel).Info("[ssh] close client")
 	}
 
 	t.con.connected = false
@@ -343,7 +355,6 @@ func (stream *sshSmartSubtransportStream) Write(buf []byte) (int, error) {
 }
 
 func (stream *sshSmartSubtransportStream) Free() {
-	traceLog.Info("[ssh]: sshSmartSubtransportStream.Free()")
 }
 
 func createClientConfig(authOpts *git.AuthOptions) (*ssh.ClientConfig, error) {