diff --git a/handshake_manager.go b/handshake_manager.go index ff80693c..b68c0c38 100644 --- a/handshake_manager.go +++ b/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", diff --git a/handshake_manager_test.go b/handshake_manager_test.go index acf13539..fb988718 100644 --- a/handshake_manager_test.go +++ b/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.