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

@@ -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,23 +307,25 @@ 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()
 	}
 	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) {