libgit2: improve 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 a correlation ID 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>

controllers/suite_test.go

@@ -40,7 +40,6 @@ import (
 	feathelper "github.com/fluxcd/pkg/runtime/features"
 	"github.com/fluxcd/pkg/runtime/testenv"
 	"github.com/fluxcd/pkg/testserver"
-	"github.com/go-logr/logr"
 	"github.com/phayes/freeport"
 
 	"github.com/distribution/distribution/v3/configuration"
@@ -209,7 +208,7 @@ func TestMain(m *testing.M) {
 
 	fg := feathelper.FeatureGates{}
 	fg.SupportedFeatures(features.FeatureGates())
-	managed.InitManagedTransport(logr.Discard())
+	managed.InitManagedTransport()
 
 	if err := (&GitRepositoryReconciler{
 		Client:        testEnv,

main.go

@@ -311,7 +311,7 @@ func main() {
 	}()
 
 	if enabled, _ := features.Enabled(features.GitManagedTransport); enabled {
-		managed.InitManagedTransport(ctrl.Log.WithName("managed-transport"))
+		managed.InitManagedTransport()
 	} else {
 		if optimize, _ := feathelper.Enabled(features.OptimizedGitClones); optimize {
 			features.Disable(features.OptimizedGitClones)

pkg/git/libgit2/managed/http.go

@@ -45,6 +45,7 @@ package managed
 
 import (
 	"bytes"
+	"context"
 	"crypto/tls"
 	"crypto/x509"
 	"errors"
@@ -55,8 +56,11 @@ import (
 	"strings"
 	"sync"
 
+	"github.com/fluxcd/pkg/runtime/logger"
 	pool "github.com/fluxcd/source-controller/internal/transport"
 	"github.com/fluxcd/source-controller/pkg/git"
+	"github.com/go-logr/logr"
+	"github.com/google/uuid"
 	git2go "github.com/libgit2/git2go/v33"
 )
 
@@ -81,10 +85,11 @@ func registerManagedHTTP() error {
 }
 
 func httpSmartSubtransportFactory(remote *git2go.Remote, transport *git2go.Transport) (git2go.SmartSubtransport, error) {
-	traceLog.Info("[http]: httpSmartSubtransportFactory")
 	sst := &httpSmartSubtransport{
 		transport:     transport,
 		httpTransport: pool.NewOrIdle(nil),
+		ctx:           context.Background(),
+		logger:        logr.Discard(),
 	}
 
 	return sst, nil
@@ -93,6 +98,21 @@ func httpSmartSubtransportFactory(remote *git2go.Remote, transport *git2go.Trans
 type httpSmartSubtransport struct {
 	transport     *git2go.Transport
 	httpTransport *http.Transport
+
+	// once is used to ensure that logger and context is set only once,
+	// on the initial (or only) Action call. Without this a mutex must
+	// be applied to ensure that ctx won't be changed, as this would be
+	// prone to race conditions in the stdout processing goroutine.
+	once sync.Once
+	// ctx defines the context to be used across long-running or
+	// cancellable operations.
+	// Defaults to context.Background().
+	ctx context.Context
+	// logger keeps a logger instance for logging. This was preferred
+	// due to the need to have a correlation ID and URL set and
+	// reused across all log calls.
+	// If context is not set, this defaults to logr.Discard().
+	logger logr.Logger
 }
 
 func (t *httpSmartSubtransport) Action(transportOptionsURL string, action git2go.SmartServiceAction) (git2go.SmartSubtransportStream, error) {
@@ -133,6 +153,17 @@ func (t *httpSmartSubtransport) Action(transportOptionsURL string, action git2go
 	}
 	t.httpTransport.DisableCompression = false
 
+	t.once.Do(func() {
+		if opts.Context != nil {
+			t.ctx = opts.Context
+			t.logger = logr.FromContextOrDiscard(t.ctx).
+				WithValues("transportType", "http").
+				WithValues("url", opts.TargetURL).
+				// Sets a correlation ID for all transport level logs.
+				WithValues("cid", uuid.New())
+		}
+	})
+
 	client, req, err := createClientRequest(targetURL, action, t.httpTransport, opts.AuthOpts)
 	if err != nil {
 		return nil, err
@@ -176,8 +207,10 @@ func (t *httpSmartSubtransport) Action(transportOptionsURL string, action git2go
 					opts.TargetURL = trimActionSuffix(newURL.String())
 					AddTransportOptions(transportOptionsURL, *opts)
 
-					debugLog.Info("[http]: server responded with redirect",
-						"newURL", opts.TargetURL, "StatusCode", req.Response.StatusCode)
+					// show as info, as this should be visible regardless of the
+					// chosen log-level.
+					t.logger.Info("server responded with redirect",
+						"newUrl", opts.TargetURL, "StatusCode", req.Response.StatusCode)
 				}
 			}
 		}
@@ -270,15 +303,16 @@ func createClientRequest(targetURL string, action git2go.SmartServiceAction,
 }
 
 func (t *httpSmartSubtransport) Close() error {
-	traceLog.Info("[http]: httpSmartSubtransport.Close()")
+	t.logger.V(logger.TraceLevel).Info("httpSmartSubtransport.Close()")
 	return nil
 }
 
 func (t *httpSmartSubtransport) Free() {
-	traceLog.Info("[http]: httpSmartSubtransport.Free()")
+	t.logger.V(logger.TraceLevel).Info("httpSmartSubtransport.Free()")
 
 	if t.httpTransport != nil {
-		traceLog.Info("[http]: release http transport back to pool")
+		t.logger.V(logger.TraceLevel).Info("release http transport back to pool")
+
 		pool.Release(t.httpTransport)
 		t.httpTransport = nil
 	}
@@ -345,18 +379,18 @@ func (self *httpSmartSubtransportStream) Write(buf []byte) (int, error) {
 
 func (self *httpSmartSubtransportStream) Free() {
 	if self.resp != nil {
-		traceLog.Info("[http]: httpSmartSubtransportStream.Free()")
+		self.owner.logger.V(logger.TraceLevel).Info("httpSmartSubtransportStream.Free()")
 
 		if self.resp.Body != nil {
 			// ensure body is fully processed and closed
 			// for increased likelihood of transport reuse in HTTP/1.x.
 			// it should not be a problem to do this more than once.
 			if _, err := io.Copy(io.Discard, self.resp.Body); err != nil {
-				traceLog.Error(err, "[http]: cannot discard response body")
+				self.owner.logger.V(logger.TraceLevel).Error(err, "cannot discard response body")
 			}
 
 			if err := self.resp.Body.Close(); err != nil {
-				traceLog.Error(err, "[http]: cannot close response body")
+				self.owner.logger.V(logger.TraceLevel).Error(err, "cannot close response body")
 			}
 		}
 	}
@@ -399,7 +433,7 @@ func (self *httpSmartSubtransportStream) sendRequest() error {
 			req.ContentLength = -1
 		}
 
-		traceLog.Info("[http]: new request", "method", req.Method, "URL", req.URL)
+		self.owner.logger.V(logger.TraceLevel).Info("new request", "method", req.Method, "postUrl", req.URL)
 		resp, err = self.client.Do(req)
 		if err != nil {
 			return err

pkg/git/libgit2/managed/http_test.go

@@ -25,7 +25,6 @@ import (
 
 	"github.com/fluxcd/pkg/gittestserver"
 	"github.com/fluxcd/source-controller/pkg/git"
-	"github.com/go-logr/logr"
 	. "github.com/onsi/gomega"
 
 	git2go "github.com/libgit2/git2go/v33"
@@ -170,7 +169,7 @@ func TestHTTPManagedTransport_E2E(t *testing.T) {
 	defer server.StopHTTP()
 
 	// Force managed transport to be enabled
-	InitManagedTransport(logr.Discard())
+	InitManagedTransport()
 
 	repoPath := "test.git"
 	err = server.InitRepo("../../testdata/git/repo", git.DefaultBranch, repoPath)
@@ -253,7 +252,7 @@ func TestHTTPManagedTransport_HandleRedirect(t *testing.T) {
 	}
 
 	// Force managed transport to be enabled
-	InitManagedTransport(logr.Discard())
+	InitManagedTransport()
 
 	for _, tt := range tests {
 		t.Run(tt.name, func(t *testing.T) {

pkg/git/libgit2/managed/init.go

@@ -19,9 +19,6 @@ package managed
 import (
 	"sync"
 	"time"
-
-	"github.com/fluxcd/pkg/runtime/logger"
-	"github.com/go-logr/logr"
 )
 
 var (
@@ -38,9 +35,7 @@ var (
 	// handshake, put/get).
 	fullHttpClientTimeOut time.Duration = 10 * time.Minute
 
-	debugLog logr.Logger
-	traceLog logr.Logger
-	enabled  bool
+	enabled bool
 )
 
 // Enabled defines whether the use of Managed Transport is enabled which
@@ -63,14 +58,10 @@ func Enabled() bool {
 //
 // This function will only register managed transports once, subsequent calls
 // leads to no-op.
-func InitManagedTransport(log logr.Logger) error {
+func InitManagedTransport() error {
 	var err error
 
 	once.Do(func() {
-		log.Info("Initializing managed transport")
-		debugLog = log.V(logger.DebugLevel)
-		traceLog = log.V(logger.TraceLevel)
-
 		if err = registerManagedHTTP(); err != nil {
 			return
 		}

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,17 +82,32 @@ func registerManagedSSH() error {
 func sshSmartSubtransportFactory(remote *git2go.Remote, transport *git2go.Transport) (git2go.SmartSubtransport, error) {
 	return &sshSmartSubtransport{
 		transport: transport,
+		logger:    logr.Discard(),
+		ctx:       context.Background(),
 	}, nil
 }
 
 type sshSmartSubtransport struct {
 	transport *git2go.Transport
 
+	// once is used to ensure that logger and context is set only once,
+	// on the initial (or only) Action call. Without this a mutex must
+	// be applied to ensure that ctx won't be changed, as this would be
+	// prone to race conditions in the stdout processing goroutine.
+	once sync.Once
+	// ctx defines the context to be used across long-running or
+	// cancellable operations.
+	// Defaults to context.Background().
+	ctx context.Context
+	// logger keeps a logger instance for logging. This was preferred
+	// due to the need to have a correlation ID and Address set and
+	// reused across all log calls.
+	// If context is not set, this defaults to logr.Discard().
+	logger logr.Logger
+
 	lastAction git2go.SmartServiceAction
 	stdin      io.WriteCloser
 	stdout     io.Reader
-	addr       string
-	ctx        context.Context
 
 	con connection
 }
@@ -111,8 +129,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 +174,18 @@ 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)
+
+	once.Do(func() {
+		if opts.Context != nil {
+			t.ctx = opts.Context
+			t.logger = logr.FromContextOrDiscard(t.ctx).
+				WithValues("transportType", "ssh").
+				WithValues("addr", addr).
+				// Sets a correlation ID for all transport level logs.
+				WithValues("cid", uuid.New())
+		}
+	})
 
 	sshConfig, err := createClientConfig(opts.AuthOpts)
 	if err != nil {
@@ -191,12 +218,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("creating new ssh session")
 	if t.con.session, err = t.con.client.NewSession(); err != nil {
 		return nil, err
 	}
@@ -222,8 +249,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)),
+					"recovered from libgit2 ssh smart subtransport panic")
 			}
 		}()
 
@@ -259,7 +286,7 @@ func (t *sshSmartSubtransport) Action(transportOptionsURL string, action git2go.
 		}
 	}()
 
-	traceLog.Info("[ssh]: run on remote", "cmd", cmd)
+	t.logger.V(logger.TraceLevel).Info("run on remote", "cmd", cmd)
 	if err := t.con.session.Start(cmd); err != nil {
 		return nil, err
 	}
@@ -276,6 +303,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,23 +331,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)
+	t.logger.V(logger.TraceLevel).Info("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()
 	}
 	t.stdin = nil
 
 	if t.con.session != nil {
-		traceLog.Info("[ssh]: session.Close()", "server", t.addr)
+		t.logger.V(logger.TraceLevel).Info("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 +373,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) {

pkg/git/libgit2/managed/ssh_test.go

@@ -23,7 +23,6 @@ import (
 
 	"github.com/fluxcd/pkg/ssh"
 	"github.com/fluxcd/source-controller/pkg/git"
-	"github.com/go-logr/logr"
 	. "github.com/onsi/gomega"
 
 	"github.com/fluxcd/pkg/gittestserver"
@@ -89,7 +88,7 @@ func TestSSHManagedTransport_E2E(t *testing.T) {
 		server.StartSSH()
 	}()
 	defer server.StopSSH()
-	InitManagedTransport(logr.Discard())
+	InitManagedTransport()
 
 	kp, err := ssh.NewEd25519Generator().Generate()
 	g.Expect(err).ToNot(HaveOccurred())