plumbing: transport/ssh, Add trace support for SSH handshake

Historically go-git lacked ways for users to debug the SSH handshake process. These changes enable the use of the trace package to log information around the SSH handshake. Users are now also able to enable/disable traces via environment variables GIT_TRACE=true, GIT_TRACE_PACKET=true and GIT_TRACE_SSH=true. Signed-off-by: Paulo Gomes <[email protected]>
pjbgf · Aug 20, 2024 · 89a2aa8 · 89a2aa8
1 parent 97dd764
commit 89a2aa8
Show file tree

Hide file tree

Showing 10 changed files with 1,419 additions and 23 deletions.
diff --git a/go.mod b/go.mod
@@ -1,7 +1,9 @@
 module github.com/go-git/go-git/v5
 
 // go-git supports the last 3 stable Go versions.
-go 1.20
+go 1.21
+
+toolchain go1.22.6
 
 // Use the v6-exp branch across go-git dependencies (gcfg and go-billy).
 replace (
@@ -11,6 +13,7 @@ replace (
 
 require (
 	dario.cat/mergo v1.0.0
+	github.com/Microsoft/go-winio v0.6.1
 	github.com/ProtonMail/go-crypto v1.0.0
 	github.com/armon/go-socks5 v0.0.0-20160902184237-e75332964ef5
 	github.com/elazarl/goproxy v0.0.0-20240618083138-03be62527ccb
@@ -24,9 +27,7 @@ require (
 	github.com/kevinburke/ssh_config v1.2.0
 	github.com/pjbgf/sha1cd v0.3.0
 	github.com/sergi/go-diff v1.3.2-0.20230802210424-5b0b94c5c0d3
-	github.com/skeema/knownhosts v1.3.0
 	github.com/stretchr/testify v1.9.0
-	github.com/xanzy/ssh-agent v0.3.3
 	golang.org/x/crypto v0.26.0
 	golang.org/x/net v0.28.0
 	golang.org/x/sys v0.24.0
@@ -35,7 +36,6 @@ require (
 )
 
 require (
-	github.com/Microsoft/go-winio v0.6.1 // indirect
 	github.com/anmitsu/go-shlex v0.0.0-20200514113438-38f4b401e2be // indirect
 	github.com/cloudflare/circl v1.3.7 // indirect
 	github.com/cyphar/filepath-securejoin v0.2.4 // indirect

diff --git a/go.sum b/go.sum
@@ -1,6 +1,5 @@
 dario.cat/mergo v1.0.0 h1:AGCNq9Evsj31mOgNPcLyXc+4PNABt905YmuqPYYpBWk=
 dario.cat/mergo v1.0.0/go.mod h1:uNxQE+84aUszobStD9th8a29P2fMDhsBdgRYvZOxGmk=
-github.com/Microsoft/go-winio v0.5.2/go.mod h1:WpS1mjBmmwHBEWmogvA2mj8546UReBk4v8QkMxJ6pZY=
 github.com/Microsoft/go-winio v0.6.1 h1:9/kr64B9VUZrLm5YYwbGtUJnMgqWVOdUAXu6Migciow=
 github.com/Microsoft/go-winio v0.6.1/go.mod h1:LRdKpFKfdobln8UmuiYcKPot9D2v6svN5+sAH+4kjUM=
 github.com/ProtonMail/go-crypto v1.0.0 h1:LRuvITjQWX+WIfr930YHG2HNfjR1uOfyf5vE0kC2U78=
@@ -58,20 +57,13 @@ github.com/rogpeppe/go-internal v1.11.0 h1:cWPaGQEPrBb5/AsnsZesgZZ9yb1OQ+GOISoDN
 github.com/rogpeppe/go-internal v1.11.0/go.mod h1:ddIwULY96R17DhadqLgMfk9H9tvdUzkipdSkR5nkCZA=
 github.com/sergi/go-diff v1.3.2-0.20230802210424-5b0b94c5c0d3 h1:n661drycOFuPLCN3Uc8sB6B/s6Z4t2xvBgU1htSHuq8=
 github.com/sergi/go-diff v1.3.2-0.20230802210424-5b0b94c5c0d3/go.mod h1:A0bzQcvG0E7Rwjx0REVgAGH58e96+X0MeOfepqsbeW4=
-github.com/sirupsen/logrus v1.7.0/go.mod h1:yWOB1SBYBC5VeMP7gHvWumXLIWorT60ONWic61uBYv0=
-github.com/skeema/knownhosts v1.3.0 h1:AM+y0rI04VksttfwjkSTNQorvGqmwATnvnAHpSgc0LY=
-github.com/skeema/knownhosts v1.3.0/go.mod h1:sPINvnADmT/qYH1kfv+ePMmOBTH6Tbl7b5LvTDjFK7M=
 github.com/stretchr/objx v0.1.0/go.mod h1:HFkY916IF+rwdDfMAkV7OtwuqBVzrE8GR6GFx+wExME=
-github.com/stretchr/testify v1.2.2/go.mod h1:a8OnRcib4nhh0OaRAV+Yts87kKdq0PP7pXfy6kDkUVs=
 github.com/stretchr/testify v1.4.0/go.mod h1:j7eGeouHqKxXV5pUuKE4zz7dFj8WfuZ+81PSLYec5m4=
 github.com/stretchr/testify v1.9.0 h1:HtqpIVDClZ4nwg75+f6Lvsy/wHu+3BoSGCbBAcpTsTg=
 github.com/stretchr/testify v1.9.0/go.mod h1:r2ic/lqez/lEtzL7wO/rwa5dbSLXVDPFyf8C91i36aY=
-github.com/xanzy/ssh-agent v0.3.3 h1:+/15pJfg/RsTxqYcX6fHqOXZwwMP+2VyYWJeWM2qQFM=
-github.com/xanzy/ssh-agent v0.3.3/go.mod h1:6dzNDKs0J9rVPHPhaGCukekBHKqfl+L3KghI1Bc68Uw=
 github.com/yuin/goldmark v1.4.13/go.mod h1:6yULJ656Px+3vBD8DxQVa3kxgyrAnzto9xy5taEt/CY=
 golang.org/x/crypto v0.0.0-20190308221718-c2843e01d9a2/go.mod h1:djNgcEr1/C05ACkg1iLfiJU5Ep61QUkGW8qpdssI0+w=
 golang.org/x/crypto v0.0.0-20210921155107-089bfa567519/go.mod h1:GvvjBRRGRdwPK5ydBHafDWAxML/pGHZbMvKqRZ5+Abc=
-golang.org/x/crypto v0.0.0-20220622213112-05595931fe9d/go.mod h1:IxCIyHEi3zRg3s0A5j5BB6A9Jmi73HwBIUl50j+osU4=
 golang.org/x/crypto v0.3.1-0.20221117191849-2c476679df9a/go.mod h1:hebNnKkNXi2UzZN1eVRvBB7co0a+JxK6XbPiWVs/3J4=
 golang.org/x/crypto v0.7.0/go.mod h1:pYwdfH91IfpZVANVyUOhSIPZaFoJGxTFbZhFTx+dXZU=
 golang.org/x/crypto v0.26.0 h1:RrRspgV4mU+YwB4FYnuBoKsUapNIL5cohGAmSH3azsw=
@@ -82,7 +74,6 @@ golang.org/x/mod v0.17.0 h1:zY54UmvipHiNd+pm+m0x9KhZ9hl1/7QNMyxXbc6ICqA=
 golang.org/x/mod v0.17.0/go.mod h1:hTbmBsO62+eylJbnUtE2MGJUyE7QWk4xUqPFrRgJ+7c=
 golang.org/x/net v0.0.0-20190620200207-3b0461eec859/go.mod h1:z5CRVTTTmAJ677TzLLGU+0bjPO0LkuOLi4/5GtJWs/s=
 golang.org/x/net v0.0.0-20210226172049-e18ecbb05110/go.mod h1:m0MpNAwzfU5UDzcl9v0D8zg8gWTRqZa9RBIspLL5mdg=
-golang.org/x/net v0.0.0-20211112202133-69e39bad7dc2/go.mod h1:9nx3DQGgdP8bBQD5qxJ1jj9UTztislL4KSBs9R2vV5Y=
 golang.org/x/net v0.0.0-20220722155237-a158d28d115b/go.mod h1:XRhObCWvk6IyKnWLug+ECip1KBveYUHfp+8e9klMJ9c=
 golang.org/x/net v0.2.0/go.mod h1:KqCZLdyyvdV855qA2rE3GC2aiw5xGR5TEjj8smXukLY=
 golang.org/x/net v0.6.0/go.mod h1:2Tu9+aMcznHK/AK1HMvgo6xiTLG5rD5rZLDS+rp2Bjs=
@@ -95,13 +86,9 @@ golang.org/x/sync v0.1.0/go.mod h1:RxMgew5VJxzue5/jJTE5uejpjVlOe/izrB70Jof72aM=
 golang.org/x/sync v0.8.0 h1:3NFvSEYkUoMifnESzZl15y791HH1qU2xm6eCJU5ZPXQ=
 golang.org/x/sync v0.8.0/go.mod h1:Czt+wKu1gCyEFDUtn0jG5QVvpJ6rzVqr5aXyt9drQfk=
 golang.org/x/sys v0.0.0-20190215142949-d0b11bdaac8a/go.mod h1:STP8DvDyc/dI5b8T5hshtkjS+E42TnysNCUPdjciGhY=
-golang.org/x/sys v0.0.0-20191026070338-33540a1f6037/go.mod h1:h1NjWce9XRLGQEsW7wpKNCjG9DtNlClVuFLEZdDNbEs=
 golang.org/x/sys v0.0.0-20201119102817-f84b799fce68/go.mod h1:h1NjWce9XRLGQEsW7wpKNCjG9DtNlClVuFLEZdDNbEs=
-golang.org/x/sys v0.0.0-20210124154548-22da62e12c0c/go.mod h1:h1NjWce9XRLGQEsW7wpKNCjG9DtNlClVuFLEZdDNbEs=
-golang.org/x/sys v0.0.0-20210423082822-04245dca01da/go.mod h1:h1NjWce9XRLGQEsW7wpKNCjG9DtNlClVuFLEZdDNbEs=
 golang.org/x/sys v0.0.0-20210615035016-665e8c7367d1/go.mod h1:oPkhp1MJrh7nUepCBck5+mAzfO9JrbApNNgaTdGDITg=
 golang.org/x/sys v0.0.0-20220520151302-bc2c85ada10a/go.mod h1:oPkhp1MJrh7nUepCBck5+mAzfO9JrbApNNgaTdGDITg=
-golang.org/x/sys v0.0.0-20220715151400-c0bba94af5f8/go.mod h1:oPkhp1MJrh7nUepCBck5+mAzfO9JrbApNNgaTdGDITg=
 golang.org/x/sys v0.0.0-20220722155257-8c9f86f7a55f/go.mod h1:oPkhp1MJrh7nUepCBck5+mAzfO9JrbApNNgaTdGDITg=
 golang.org/x/sys v0.2.0/go.mod h1:oPkhp1MJrh7nUepCBck5+mAzfO9JrbApNNgaTdGDITg=
 golang.org/x/sys v0.3.0/go.mod h1:oPkhp1MJrh7nUepCBck5+mAzfO9JrbApNNgaTdGDITg=
@@ -118,7 +105,6 @@ golang.org/x/term v0.23.0 h1:F6D4vR+EHoL9/sWAWgAR1H2DcHr4PareCbAaCo1RpuU=
 golang.org/x/term v0.23.0/go.mod h1:DgV24QBUrK6jhZXl+20l6UWznPlwAHm1Q1mGHtydmSk=
 golang.org/x/text v0.3.0/go.mod h1:NqM8EUOU14njkJ3fqMW+pc6Ldnwhi/IjpwHt7yyuwOQ=
 golang.org/x/text v0.3.3/go.mod h1:5Zoc/QRtKVWzQhOtBMvqHzDpF6irO9z98xDceosuGiQ=
-golang.org/x/text v0.3.6/go.mod h1:5Zoc/QRtKVWzQhOtBMvqHzDpF6irO9z98xDceosuGiQ=
 golang.org/x/text v0.3.7/go.mod h1:u+2+/6zg+i71rQMx5EYifcz6MCKuco9NR6JIITiCfzQ=
 golang.org/x/text v0.4.0/go.mod h1:mrYo+phRRbMaCq/xk9113O4dZlRixOauAjOtrjsXDZ8=
 golang.org/x/text v0.7.0/go.mod h1:mrYo+phRRbMaCq/xk9113O4dZlRixOauAjOtrjsXDZ8=

diff --git a/plumbing/transport/ssh/auth_method.go b/plumbing/transport/ssh/auth_method.go
@@ -3,14 +3,16 @@ package ssh
 import (
 	"errors"
 	"fmt"
+	"net"
 	"os"
 	"os/user"
 	"path/filepath"
 
 	"github.com/go-git/go-git/v5/plumbing/transport"
+	"github.com/go-git/go-git/v5/plumbing/transport/ssh/knownhosts"
+	"github.com/go-git/go-git/v5/plumbing/transport/ssh/sshagent"
+	"github.com/go-git/go-git/v5/utils/trace"
 
-	"github.com/skeema/knownhosts"
-	sshagent "github.com/xanzy/ssh-agent"
 	"golang.org/x/crypto/ssh"
 )
 
@@ -54,6 +56,7 @@ func (a *KeyboardInteractive) String() string {
 }
 
 func (a *KeyboardInteractive) ClientConfig() (*ssh.ClientConfig, error) {
+	trace.SSH.Printf("ssh: %s user=%s", KeyboardInteractiveName, a.User)
 	return a.SetHostKeyCallback(&ssh.ClientConfig{
 		User: a.User,
 		Auth: []ssh.AuthMethod{
@@ -78,6 +81,7 @@ func (a *Password) String() string {
 }
 
 func (a *Password) ClientConfig() (*ssh.ClientConfig, error) {
+	trace.SSH.Printf("ssh: %s user=%s", PasswordName, a.User)
 	return a.SetHostKeyCallback(&ssh.ClientConfig{
 		User: a.User,
 		Auth: []ssh.AuthMethod{ssh.Password(a.Password)},
@@ -101,6 +105,7 @@ func (a *PasswordCallback) String() string {
 }
 
 func (a *PasswordCallback) ClientConfig() (*ssh.ClientConfig, error) {
+	trace.SSH.Printf("ssh: %s user=%s", PasswordCallbackName, a.User)
 	return a.SetHostKeyCallback(&ssh.ClientConfig{
 		User: a.User,
 		Auth: []ssh.AuthMethod{ssh.PasswordCallback(a.Callback)},
@@ -150,6 +155,9 @@ func (a *PublicKeys) String() string {
 }
 
 func (a *PublicKeys) ClientConfig() (*ssh.ClientConfig, error) {
+	trace.SSH.Printf("ssh: %s user=%s signer=\"%s %s\"", PublicKeysName, a.User,
+		a.Signer.PublicKey().Type(),
+		ssh.FingerprintSHA256(a.Signer.PublicKey()))
 	return a.SetHostKeyCallback(&ssh.ClientConfig{
 		User: a.User,
 		Auth: []ssh.AuthMethod{ssh.PublicKeys(a.Signer)},
@@ -160,8 +168,10 @@ func username() (string, error) {
 	var username string
 	if user, err := user.Current(); err == nil {
 		username = user.Username
+		trace.SSH.Printf("ssh: Falling back to current user name %q", username)
 	} else {
 		username = os.Getenv("USER")
+		trace.SSH.Printf("ssh: Falling back to environment variable USER %q", username)
 	}
 
 	if username == "" {
@@ -211,9 +221,10 @@ func (a *PublicKeysCallback) String() string {
 }
 
 func (a *PublicKeysCallback) ClientConfig() (*ssh.ClientConfig, error) {
+	trace.SSH.Printf("ssh: %s user=%s", PublicKeysCallbackName, a.User)
 	return a.SetHostKeyCallback(&ssh.ClientConfig{
 		User: a.User,
-		Auth: []ssh.AuthMethod{ssh.PublicKeysCallback(a.Callback)},
+		Auth: []ssh.AuthMethod{tracePublicKeysCallback(a.Callback)},
 	})
 }
 
@@ -236,23 +247,25 @@ func NewKnownHostsCallback(files ...string) (ssh.HostKeyCallback, error) {
 
 func newKnownHostsDb(files ...string) (*knownhosts.HostKeyDB, error) {
 	var err error
-
 	if len(files) == 0 {
 		if files, err = getDefaultKnownHostsFiles(); err != nil {
 			return nil, err
 		}
 	}
+	trace.SSH.Printf("ssh: known_hosts sources %s", files)
 
 	if files, err = filterKnownHostsFiles(files...); err != nil {
 		return nil, err
 	}
+	trace.SSH.Printf("ssh: filtered known_hosts sources %s", files)
 
 	return knownhosts.NewDB(files...)
 }
 
 func getDefaultKnownHostsFiles() ([]string, error) {
 	files := filepath.SplitList(os.Getenv("SSH_KNOWN_HOSTS"))
 	if len(files) != 0 {
+		trace.SSH.Printf("ssh: loading known_hosts from SSH_KNOWN_HOSTS")
 		return files, nil
 	}
 
@@ -309,6 +322,32 @@ func (m *HostKeyCallbackHelper) SetHostKeyCallback(cfg *ssh.ClientConfig) (*ssh.
 		m.HostKeyCallback = db.HostKeyCallback()
 	}
 
-	cfg.HostKeyCallback = m.HostKeyCallback
+	cfg.HostKeyCallback = m.traceHostKeyCallback
 	return cfg, nil
 }
+
+func (m *HostKeyCallbackHelper) traceHostKeyCallback(hostname string, remote net.Addr, key ssh.PublicKey) error {
+	trace.SSH.Printf(
+		`ssh: hostkey callback hostname=%s remote=%s pubkey="%s %s"`,
+		hostname, remote, key.Type(), ssh.FingerprintSHA256(key))
+	return m.HostKeyCallback(hostname, remote, key)
+}
+
+func tracePublicKeysCallback(getSigners func() ([]ssh.Signer, error)) ssh.AuthMethod {
+	signers, err := getSigners()
+	if err != nil {
+		trace.SSH.Printf("ssh: error calling getSigners: %v", err)
+	}
+	if len(signers) == 0 {
+		trace.SSH.Printf("ssh: no signers found")
+	}
+	for _, s := range signers {
+		trace.SSH.Printf("ssh: found key: %s %s", s.PublicKey().Type(),
+			ssh.FingerprintSHA256(s.PublicKey()))
+	}
+
+	cb := func() ([]ssh.Signer, error) {
+		return signers, err
+	}
+	return ssh.PublicKeysCallback(cb)
+}
diff --git a/plumbing/transport/ssh/common.go b/plumbing/transport/ssh/common.go
@@ -10,6 +10,7 @@ import (
 	"strings"
 
 	"github.com/go-git/go-git/v5/plumbing/transport"
+	"github.com/go-git/go-git/v5/utils/trace"
 
 	"github.com/kevinburke/ssh_config"
 	"golang.org/x/crypto/ssh"
@@ -39,6 +40,7 @@ func NewClient(config *ssh.ClientConfig) transport.Transport {
 // DefaultAuthBuilder is the function used to create a default AuthMethod, when
 // the user doesn't provide any.
 var DefaultAuthBuilder = func(user string) (AuthMethod, error) {
+	trace.SSH.Printf("ssh: Using default auth builder (user: %s)", user)
 	return NewSSHAgentAuth(user)
 }
 
@@ -150,6 +152,8 @@ func (c *command) connect() error {
 		config.HostKeyAlgorithms = db.HostKeyAlgorithms(hostWithPort)
 	}
 
+	trace.SSH.Printf("ssh: host key algorithms %s", config.HostKeyAlgorithms)
+
 	overrideConfig(c.config, config)
 
 	c.client, err = dial("tcp", hostWithPort, c.endpoint.Proxy, config)
@@ -187,6 +191,8 @@ func dial(network, addr string, proxyOpts transport.ProxyOptions, config *ssh.Cl
 		if err != nil {
 			return nil, err
 		}
+
+		trace.SSH.Printf("ssh: using proxyURL=%s", proxyUrl)
 		dialer, err := proxy.FromURL(proxyUrl, proxy.Direct)
 		if err != nil {
 			return nil, err