From 59c964c907a2a7bfd5cd794d3e6faa875e26c76e Mon Sep 17 00:00:00 2001
From: Paulo Gomes <paulo.gomes@weave.works>
Date: Wed, 8 Jun 2022 19:52:03 +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 | 17 +++++++++++------
 1 file changed, 11 insertions(+), 6 deletions(-)

diff --git a/pkg/git/libgit2/managed/ssh.go b/pkg/git/libgit2/managed/ssh.go
index b990dd0af..9f3fd11cb 100644
--- a/pkg/git/libgit2/managed/ssh.go
+++ b/pkg/git/libgit2/managed/ssh.go
@@ -59,6 +59,7 @@ import (
 	"golang.org/x/crypto/ssh"
 	"golang.org/x/net/proxy"
 
+	"github.com/distribution/distribution/v3/uuid"
 	"github.com/fluxcd/source-controller/pkg/git"
 	git2go "github.com/libgit2/git2go/v33"
 )
@@ -79,11 +80,13 @@ func registerManagedSSH() error {
 func sshSmartSubtransportFactory(remote *git2go.Remote, transport *git2go.Transport) (git2go.SmartSubtransport, error) {
 	return &sshSmartSubtransport{
 		transport: transport,
+		uuid:      uuid.Generate(),
 	}, nil
 }
 
 type sshSmartSubtransport struct {
 	transport *git2go.Transport
+	uuid      uuid.UUID
 
 	lastAction git2go.SmartServiceAction
 	stdin      io.WriteCloser
@@ -196,7 +199,7 @@ func (t *sshSmartSubtransport) Action(transportOptionsURL string, action git2go.
 		return nil, err
 	}
 
-	traceLog.Info("[ssh]: creating new ssh session")
+	traceLog.Info("[ssh]: creating new ssh session", "server", t.addr, "TransportID", t.uuid)
 	if t.con.session, err = t.con.client.NewSession(); err != nil {
 		return nil, err
 	}
@@ -223,7 +226,7 @@ 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)
+					"[ssh]: recovered from libgit2 ssh smart subtransport panic", "server", t.addr, "TransportID", t.uuid)
 			}
 		}()
 
@@ -259,7 +262,7 @@ func (t *sshSmartSubtransport) Action(transportOptionsURL string, action git2go.
 		}
 	}()
 
-	traceLog.Info("[ssh]: run on remote", "cmd", cmd)
+	traceLog.Info("[ssh]: run on remote", "cmd", cmd, "server", t.addr, "TransportID", t.uuid)
 	if err := t.con.session.Start(cmd); err != nil {
 		return nil, err
 	}
@@ -276,6 +279,7 @@ func (t *sshSmartSubtransport) createConn(addr string, sshConfig *ssh.ClientConf
 	ctx, cancel := context.WithTimeout(context.TODO(), sshConnectionTimeOut)
 	defer cancel()
 
+	traceLog.Info("[ssh] dial connection", "server", t.addr, "TransportID", t.uuid)
 	conn, err := proxy.Dial(ctx, "tcp", addr)
 	if err != nil {
 		return err
@@ -303,9 +307,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)
+	traceLog.Info("[ssh]: sshSmartSubtransport.Close()", "server", t.addr, "TransportID", t.uuid)
 	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 +318,14 @@ func (t *sshSmartSubtransport) Close() error {
 	t.stdin = nil
 
 	if t.con.session != nil {
-		traceLog.Info("[ssh]: session.Close()", "server", t.addr)
+		traceLog.Info("[ssh]: session.Close()", "server", t.addr, "TransportID", t.uuid)
 		_ = t.con.session.Close()
 	}
 	t.con.session = nil
 
 	if t.con.client != nil {
 		_ = t.con.client.Close()
+		traceLog.Info("[ssh] close client", "server", t.addr, "TransportID", t.uuid)
 	}
 
 	t.con.connected = false
@@ -343,7 +349,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) {