log the reason for fw drops (#220)

* log the reason for fw drops

* only prepare log if we will end up sending it

firewall.go

@@ -347,27 +347,33 @@ func AddFirewallRulesFromConfig(inbound bool, config *Config, fw FirewallInterfa
 	return nil
 }
 
-func (f *Firewall) Drop(packet []byte, fp FirewallPacket, incoming bool, h *HostInfo, caPool *cert.NebulaCAPool) bool {
+var ErrInvalidRemoteIP = errors.New("remote IP is not in remote certificate subnets")
+var ErrInvalidLocalIP = errors.New("local IP is not in list of handled local IPs")
+var ErrNoMatchingRule = errors.New("no matching rule in firewall table")
+
+// Drop returns an error if the packet should be dropped, explaining why. It
+// returns nil if the packet should not be dropped.
+func (f *Firewall) Drop(packet []byte, fp FirewallPacket, incoming bool, h *HostInfo, caPool *cert.NebulaCAPool) error {
 	// Check if we spoke to this tuple, if we did then allow this packet
 	if f.inConns(packet, fp, incoming) {
-		return false
+		return nil
 	}
 
 	// Make sure remote address matches nebula certificate
 	if remoteCidr := h.remoteCidr; remoteCidr != nil {
 		if remoteCidr.Contains(fp.RemoteIP) == nil {
-			return true
+			return ErrInvalidRemoteIP
 		}
 	} else {
 		// Simple case: Certificate has one IP and no subnets
 		if fp.RemoteIP != h.hostId {
-			return true
+			return ErrInvalidRemoteIP
 		}
 	}
 
 	// Make sure we are supposed to be handling this local ip address
 	if f.localIps.Contains(fp.LocalIP) == nil {
-		return true
+		return ErrInvalidLocalIP
 	}
 
 	table := f.OutRules
@@ -377,13 +383,13 @@ func (f *Firewall) Drop(packet []byte, fp FirewallPacket, incoming bool, h *Host
 
 	// We now know which firewall table to check against
 	if !table.match(fp, incoming, h.ConnectionState.peerCert, caPool) {
-		return true
+		return ErrNoMatchingRule
 	}
 
 	// We always want to conntrack since it is a faster operation
 	f.addConn(packet, fp, incoming)
 
-	return false
+	return nil
 }
 
 // Destroy cleans up any known cyclical references so the object can be free'd my GC. This should be called if a new

firewall_test.go

@@ -180,44 +180,44 @@ func TestFirewall_Drop(t *testing.T) {
 	cp := cert.NewCAPool()
 
 	// Drop outbound
-	assert.True(t, fw.Drop([]byte{}, p, false, &h, cp))
+	assert.Equal(t, fw.Drop([]byte{}, p, false, &h, cp), ErrNoMatchingRule)
 	// Allow inbound
 	resetConntrack(fw)
-	assert.False(t, fw.Drop([]byte{}, p, true, &h, cp))
+	assert.NoError(t, fw.Drop([]byte{}, p, true, &h, cp))
 	// Allow outbound because conntrack
-	assert.False(t, fw.Drop([]byte{}, p, false, &h, cp))
+	assert.NoError(t, fw.Drop([]byte{}, p, false, &h, cp))
 
 	// test remote mismatch
 	oldRemote := p.RemoteIP
 	p.RemoteIP = ip2int(net.IPv4(1, 2, 3, 10))
-	assert.True(t, fw.Drop([]byte{}, p, false, &h, cp))
+	assert.Equal(t, fw.Drop([]byte{}, p, false, &h, cp), ErrInvalidRemoteIP)
 	p.RemoteIP = oldRemote
 
 	// ensure signer doesn't get in the way of group checks
 	fw = NewFirewall(time.Second, time.Minute, time.Hour, &c)
 	assert.Nil(t, fw.AddRule(true, fwProtoAny, 0, 0, []string{"nope"}, "", nil, "", "signer-shasum"))
 	assert.Nil(t, fw.AddRule(true, fwProtoAny, 0, 0, []string{"default-group"}, "", nil, "", "signer-shasum-bad"))
-	assert.True(t, fw.Drop([]byte{}, p, true, &h, cp))
+	assert.Equal(t, fw.Drop([]byte{}, p, true, &h, cp), ErrNoMatchingRule)
 
 	// test caSha doesn't drop on match
 	fw = NewFirewall(time.Second, time.Minute, time.Hour, &c)
 	assert.Nil(t, fw.AddRule(true, fwProtoAny, 0, 0, []string{"nope"}, "", nil, "", "signer-shasum-bad"))
 	assert.Nil(t, fw.AddRule(true, fwProtoAny, 0, 0, []string{"default-group"}, "", nil, "", "signer-shasum"))
-	assert.False(t, fw.Drop([]byte{}, p, true, &h, cp))
+	assert.NoError(t, fw.Drop([]byte{}, p, true, &h, cp))
 
 	// ensure ca name doesn't get in the way of group checks
 	cp.CAs["signer-shasum"] = &cert.NebulaCertificate{Details: cert.NebulaCertificateDetails{Name: "ca-good"}}
 	fw = NewFirewall(time.Second, time.Minute, time.Hour, &c)
 	assert.Nil(t, fw.AddRule(true, fwProtoAny, 0, 0, []string{"nope"}, "", nil, "ca-good", ""))
 	assert.Nil(t, fw.AddRule(true, fwProtoAny, 0, 0, []string{"default-group"}, "", nil, "ca-good-bad", ""))
-	assert.True(t, fw.Drop([]byte{}, p, true, &h, cp))
+	assert.Equal(t, fw.Drop([]byte{}, p, true, &h, cp), ErrNoMatchingRule)
 
 	// test caName doesn't drop on match
 	cp.CAs["signer-shasum"] = &cert.NebulaCertificate{Details: cert.NebulaCertificateDetails{Name: "ca-good"}}
 	fw = NewFirewall(time.Second, time.Minute, time.Hour, &c)
 	assert.Nil(t, fw.AddRule(true, fwProtoAny, 0, 0, []string{"nope"}, "", nil, "ca-good-bad", ""))
 	assert.Nil(t, fw.AddRule(true, fwProtoAny, 0, 0, []string{"default-group"}, "", nil, "ca-good", ""))
-	assert.False(t, fw.Drop([]byte{}, p, true, &h, cp))
+	assert.NoError(t, fw.Drop([]byte{}, p, true, &h, cp))
 }
 
 func BenchmarkFirewallTable_match(b *testing.B) {
@@ -368,10 +368,10 @@ func TestFirewall_Drop2(t *testing.T) {
 	cp := cert.NewCAPool()
 
 	// h1/c1 lacks the proper groups
-	assert.True(t, fw.Drop([]byte{}, p, true, &h1, cp))
+	assert.Error(t, fw.Drop([]byte{}, p, true, &h1, cp), ErrNoMatchingRule)
 	// c has the proper groups
 	resetConntrack(fw)
-	assert.False(t, fw.Drop([]byte{}, p, true, &h, cp))
+	assert.NoError(t, fw.Drop([]byte{}, p, true, &h, cp))
 }
 
 func TestFirewall_Drop3(t *testing.T) {
@@ -452,13 +452,13 @@ func TestFirewall_Drop3(t *testing.T) {
 	cp := cert.NewCAPool()
 
 	// c1 should pass because host match
-	assert.False(t, fw.Drop([]byte{}, p, true, &h1, cp))
+	assert.NoError(t, fw.Drop([]byte{}, p, true, &h1, cp))
 	// c2 should pass because ca sha match
 	resetConntrack(fw)
-	assert.False(t, fw.Drop([]byte{}, p, true, &h2, cp))
+	assert.NoError(t, fw.Drop([]byte{}, p, true, &h2, cp))
 	// c3 should fail because no match
 	resetConntrack(fw)
-	assert.True(t, fw.Drop([]byte{}, p, true, &h3, cp))
+	assert.Equal(t, fw.Drop([]byte{}, p, true, &h3, cp), ErrNoMatchingRule)
 }
 
 func BenchmarkLookup(b *testing.B) {

inside.go

@@ -44,14 +44,17 @@ func (f *Interface) consumeInsidePacket(packet []byte, fwPacket *FirewallPacket,
 		ci.queueLock.Unlock()
 	}
 
-	if !f.firewall.Drop(packet, *fwPacket, false, hostinfo, trustedCAs) {
+	dropReason := f.firewall.Drop(packet, *fwPacket, false, hostinfo, trustedCAs)
+	if dropReason == nil {
 		f.send(message, 0, ci, hostinfo, hostinfo.remote, packet, nb, out)
 		if f.lightHouse != nil && *ci.messageCounter%5000 == 0 {
 			f.lightHouse.Query(fwPacket.RemoteIP, f)
 		}
 
 	} else if l.Level >= logrus.DebugLevel {
-		hostinfo.logger().WithField("fwPacket", fwPacket).
+		hostinfo.logger().
+			WithField("fwPacket", fwPacket).
+			WithField("reason", dropReason).
 			Debugln("dropping outbound packet")
 	}
 }
@@ -105,8 +108,11 @@ func (f *Interface) sendMessageNow(t NebulaMessageType, st NebulaMessageSubType,
 	}
 
 	// check if packet is in outbound fw rules
-	if f.firewall.Drop(p, *fp, false, hostInfo, trustedCAs) {
+	dropReason := f.firewall.Drop(p, *fp, false, hostInfo, trustedCAs)
-		l.WithField("fwPacket", fp).Debugln("dropping cached packet")
+	if dropReason != nil && l.Level >= logrus.DebugLevel {
+		l.WithField("fwPacket", fp).
+			WithField("reason", dropReason).
+			Debugln("dropping cached packet")
 		return
 	}
 

outside.go

@@ -280,8 +280,10 @@ func (f *Interface) decryptToTun(hostinfo *HostInfo, messageCounter uint64, out
 		return
 	}
 
-	if f.firewall.Drop(out, *fwPacket, true, hostinfo, trustedCAs) {
+	dropReason := f.firewall.Drop(out, *fwPacket, true, hostinfo, trustedCAs)
+	if dropReason != nil && l.Level >= logrus.DebugLevel {
 		hostinfo.logger().WithField("fwPacket", fwPacket).
+			WithField("reason", dropReason).
 			Debugln("dropping inbound packet")
 		return
 	}