handshake: lower log level for blocklisted certificates (#1969)

handshake_manager.go

@@ -61,16 +61,17 @@ type HandshakeManager struct {
 	vpnIps  map[netip.Addr]*HandshakeHostInfo
 	indexes map[uint32]*HandshakeHostInfo
 
-	mainHostMap            *HostMap
-	lightHouse             *LightHouse
-	outside                udp.Conn
-	config                 HandshakeConfig
-	OutboundHandshakeTimer *LockingTimerWheel[netip.Addr]
-	messageMetrics         *MessageMetrics
-	metricInitiated        metrics.Counter
-	metricTimedOut         metrics.Counter
-	f                      *Interface
-	l                      *slog.Logger
+	mainHostMap               *HostMap
+	lightHouse                *LightHouse
+	outside                   udp.Conn
+	config                    HandshakeConfig
+	OutboundHandshakeTimer    *LockingTimerWheel[netip.Addr]
+	messageMetrics            *MessageMetrics
+	metricInitiated           metrics.Counter
+	metricTimedOut            metrics.Counter
+	metricRejectedBlocklisted metrics.Counter
+	f                         *Interface
+	l                         *slog.Logger
 
 	// can be used to trigger outbound handshake for the given vpnIp
 	trigger chan netip.Addr
@@ -118,18 +119,19 @@ func (hh *HandshakeHostInfo) cachePacket(l *slog.Logger, t header.MessageType, s
 
 func NewHandshakeManager(l *slog.Logger, mainHostMap *HostMap, lightHouse *LightHouse, outside udp.Conn, config HandshakeConfig) *HandshakeManager {
 	return &HandshakeManager{
-		vpnIps:                 map[netip.Addr]*HandshakeHostInfo{},
-		indexes:                map[uint32]*HandshakeHostInfo{},
-		mainHostMap:            mainHostMap,
-		lightHouse:             lightHouse,
-		outside:                outside,
-		config:                 config,
-		trigger:                make(chan netip.Addr, config.triggerBuffer),
-		OutboundHandshakeTimer: NewLockingTimerWheel[netip.Addr](config.tryInterval, hsTimeout(config.retries, config.tryInterval)),
-		messageMetrics:         config.messageMetrics,
-		metricInitiated:        metrics.GetOrRegisterCounter("handshake_manager.initiated", nil),
-		metricTimedOut:         metrics.GetOrRegisterCounter("handshake_manager.timed_out", nil),
-		l:                      l,
+		vpnIps:                    map[netip.Addr]*HandshakeHostInfo{},
+		indexes:                   map[uint32]*HandshakeHostInfo{},
+		mainHostMap:               mainHostMap,
+		lightHouse:                lightHouse,
+		outside:                   outside,
+		config:                    config,
+		trigger:                   make(chan netip.Addr, config.triggerBuffer),
+		OutboundHandshakeTimer:    NewLockingTimerWheel[netip.Addr](config.tryInterval, hsTimeout(config.retries, config.tryInterval)),
+		messageMetrics:            config.messageMetrics,
+		metricInitiated:           metrics.GetOrRegisterCounter("handshake_manager.initiated", nil),
+		metricTimedOut:            metrics.GetOrRegisterCounter("handshake_manager.timed_out", nil),
+		metricRejectedBlocklisted: metrics.GetOrRegisterCounter("handshake_manager.rejected.blocklisted", nil),
+		l:                         l,
 	}
 }
 
@@ -717,7 +719,12 @@ func (hm *HandshakeManager) beginHandshake(via ViaSender, packet []byte, h *head
 
 	response, result, err := machine.ProcessPacket(nil, packet)
 	if err != nil {
-		f.l.Error("Failed to process handshake packet", "from", via, "error", err)
+		level := slog.LevelError
+		if errors.Is(err, cert.ErrBlockListed) {
+			level = slog.LevelDebug
+			hm.metricRejectedBlocklisted.Inc(1)
+		}
+		f.l.Log(context.Background(), level, "Failed to process handshake packet", "from", via, "error", err)
 		return
 	}
 
@@ -849,6 +856,9 @@ func (hm *HandshakeManager) continueHandshake(via ViaSender, hh *HandshakeHostIn
 
 	response, result, err := machine.ProcessPacket(nil, packet)
 	if err != nil {
+		if errors.Is(err, cert.ErrBlockListed) {
+			hm.metricRejectedBlocklisted.Inc(1)
+		}
 		// Recoverable errors are routine noise, log at Debug. Fatal errors get a Warn.
 		if machine.Failed() {
 			f.l.Warn("Failed to process handshake packet, abandoning",

handshake_manager_test.go

@@ -1,12 +1,17 @@
 package nebula
 
 import (
+	"log/slog"
 	"net/netip"
 	"testing"
 	"time"
 
+	"github.com/flynn/noise"
 	"github.com/gaissmai/bart"
+	"github.com/rcrowley/go-metrics"
 	"github.com/slackhq/nebula/cert"
+	ct "github.com/slackhq/nebula/cert_test"
+	"github.com/slackhq/nebula/handshake"
 	"github.com/slackhq/nebula/header"
 	"github.com/slackhq/nebula/test"
 	"github.com/slackhq/nebula/udp"
@@ -235,6 +240,89 @@ func TestHandleIncomingDispatch(t *testing.T) {
 	})
 }
 
+func TestBlocklistedHandshakeLogLevelAndCounter(t *testing.T) {
+	ca, _, caKey, _ := ct.NewTestCaCert(cert.Version2, cert.Curve_CURVE25519, time.Time{}, time.Time{}, nil, nil, nil)
+	pool := ct.NewTestCAPool(ca)
+
+	newCredential := func(name, network string) (cert.Certificate, *handshake.Credential) {
+		c, _, rawKey, _ := ct.NewTestCert(cert.Version2, cert.Curve_CURVE25519, ca, caKey,
+			name, ca.NotBefore(), ca.NotAfter(), []netip.Prefix{netip.MustParsePrefix(network)}, nil, nil)
+		privateKey, _, _, err := cert.UnmarshalPrivateKeyFromPEM(rawKey)
+		require.NoError(t, err)
+		certBytes, err := c.MarshalForHandshakes()
+		require.NoError(t, err)
+		cipherSuite := noise.NewCipherSuite(noise.DH25519, noise.CipherChaChaPoly, noise.HashSHA256)
+		return c, handshake.NewCredential(c, certBytes, privateKey, cipherSuite)
+	}
+
+	initiatorCert, initiatorCredential := newCredential("initiator", "10.0.0.1/24")
+	responderCert, responderCredential := newCredential("responder", "10.0.0.2/24")
+	fingerprint, err := initiatorCert.Fingerprint()
+	require.NoError(t, err)
+	pool.BlocklistFingerprint(fingerprint)
+
+	initiator, err := handshake.NewMachine(cert.Version2,
+		func(cert.Version) *handshake.Credential { return initiatorCredential },
+		func(c cert.Certificate) (*cert.CachedCertificate, error) {
+			return pool.VerifyCertificate(time.Now(), c)
+		},
+		func() (uint32, error) { return 1, nil }, true, header.HandshakeIXPSK0)
+	require.NoError(t, err)
+	packet, err := initiator.Initiate(nil)
+	require.NoError(t, err)
+
+	handler := &capturingHandler{}
+	logger := slog.New(handler)
+	pki := &PKI{}
+	pki.cs.Store(&CertState{initiatingVersion: cert.Version2, v2Credential: responderCredential})
+	pki.caPool.Store(pool)
+	hm := NewHandshakeManager(logger, nil, nil, nil, defaultHandshakeConfig)
+	hm.metricRejectedBlocklisted = metrics.NewCounter()
+	hm.f = &Interface{pki: pki, l: logger}
+	via := ViaSender{UdpAddr: netip.MustParseAddrPort("198.51.100.7:4242")}
+
+	hm.beginHandshake(via, packet, nil)
+	entry := findEntry(t, handler.entries, "Failed to process handshake packet")
+	assert.Equal(t, slog.LevelDebug, entry.Level)
+	require.ErrorIs(t, entry.Attrs["error"].(error), cert.ErrBlockListed)
+	assert.Equal(t, int64(1), hm.metricRejectedBlocklisted.Count())
+
+	handler.entries = nil
+	hm.beginHandshake(via, nil, nil)
+	entry = findEntry(t, handler.entries, "Failed to process handshake packet")
+	assert.Equal(t, slog.LevelError, entry.Level)
+	assert.Equal(t, int64(1), hm.metricRejectedBlocklisted.Count())
+
+	// The initiator sees the same rejection in continueHandshake, after a
+	// responder has accepted its first packet and sent a valid reply.
+	cleanPool := ct.NewTestCAPool(ca)
+	responder, err := handshake.NewMachine(cert.Version2,
+		func(cert.Version) *handshake.Credential { return responderCredential },
+		func(c cert.Certificate) (*cert.CachedCertificate, error) {
+			return cleanPool.VerifyCertificate(time.Now(), c)
+		},
+		func() (uint32, error) { return 2, nil }, false, header.HandshakeIXPSK0)
+	require.NoError(t, err)
+	response, _, err := responder.ProcessPacket(nil, packet)
+	require.NoError(t, err)
+
+	responderFingerprint, err := responderCert.Fingerprint()
+	require.NoError(t, err)
+	pool.BlocklistFingerprint(responderFingerprint)
+
+	initiatingHM := NewHandshakeManager(logger, nil, nil, nil, defaultHandshakeConfig)
+	initiatingHM.metricRejectedBlocklisted = metrics.NewCounter()
+	initiatingHM.f = &Interface{l: logger}
+	hh := &HandshakeHostInfo{
+		machine:  initiator,
+		hostinfo: &HostInfo{localIndexId: 1, vpnAddrs: []netip.Addr{netip.MustParseAddr("10.0.0.2")}},
+	}
+	initiatingHM.indexes[1] = hh
+	via.IsRelayed = true // skip the remote allow list before certificate validation
+	initiatingHM.continueHandshake(via, hh, response)
+	assert.Equal(t, int64(1), initiatingHM.metricRejectedBlocklisted.Count())
+}
+
 // Test_PendingHandshakeHasRemotes covers create-tunnel -address: a pending hostinfo must already
 // carry its RemoteList when StartHandshake runs its callback, so SetRemote there, before the
 // handshake loop has run, is safe and the address becomes one the handshake is sent to.