Better instrumentation for filter, and filter bug fixes.

node/Network.cpp

@@ -37,6 +37,36 @@
 
 namespace ZeroTier {
 
+#ifdef ZT_TRACE
+static const char *_rtn(const ZT_VirtualNetworkRuleType rt)
+{
+	switch(rt) {
+		case ZT_NETWORK_RULE_ACTION_DROP: return "ACTION_DROP";
+		case ZT_NETWORK_RULE_ACTION_ACCEPT: return "ACTION_ACCEPT";
+		case ZT_NETWORK_RULE_ACTION_TEE: return "ACTION_TEE";
+		case ZT_NETWORK_RULE_ACTION_REDIRECT: return "ACTION_REDIRECT";
+		case ZT_NETWORK_RULE_MATCH_SOURCE_ZEROTIER_ADDRESS: return "MATCH_SOURCE_ZEROTIER_ADDRESS";
+		case ZT_NETWORK_RULE_MATCH_DEST_ZEROTIER_ADDRESS: return "MATCH_DEST_ZEROTIER_ADDRESS";
+		case ZT_NETWORK_RULE_MATCH_VLAN_ID: return "MATCH_VLAN_ID";
+		case ZT_NETWORK_RULE_MATCH_VLAN_PCP: return "MATCH_VLAN_PCP";
+		case ZT_NETWORK_RULE_MATCH_VLAN_DEI: return "MATCH_VLAN_DEI";
+		case ZT_NETWORK_RULE_MATCH_ETHERTYPE: return "MATCH_ETHERTYPE";
+		case ZT_NETWORK_RULE_MATCH_MAC_SOURCE: return "MATCH_MAC_SOURCE";
+		case ZT_NETWORK_RULE_MATCH_MAC_DEST: return "MATCH_MAC_DEST";
+		case ZT_NETWORK_RULE_MATCH_IPV4_SOURCE: return "MATCH_IPV4_SOURCE";
+		case ZT_NETWORK_RULE_MATCH_IPV4_DEST: return "MATCH_IPV4_DEST";
+		case ZT_NETWORK_RULE_MATCH_IPV6_SOURCE: return "MATCH_IPV6_SOURCE";
+		case ZT_NETWORK_RULE_MATCH_IPV6_DEST: return "MATCH_IPV6_DEST";
+		case ZT_NETWORK_RULE_MATCH_IP_TOS: return "MATCH_IP_TOS";
+		case ZT_NETWORK_RULE_MATCH_IP_PROTOCOL: return "MATCH_IP_PROTOCOL";
+		case ZT_NETWORK_RULE_MATCH_IP_SOURCE_PORT_RANGE: return "MATCH_IP_SOURCE_PORT_RANGE";
+		case ZT_NETWORK_RULE_MATCH_IP_DEST_PORT_RANGE: return "MATCH_IP_DEST_PORT_RANGE";
+		case ZT_NETWORK_RULE_MATCH_CHARACTERISTICS: return "MATCH_CHARACTERISTICS";
+		default: return "BAD_RULE_TYPE";
+	}
+}
+#endif // ZT_TRACE
+
 // Returns true if packet appears valid; pos and proto will be set
 static bool _ipv6GetPayload(const uint8_t *frameData,unsigned int frameLen,unsigned int &pos,unsigned int &proto)
 {
@@ -66,6 +96,9 @@ static bool _ipv6GetPayload(const uint8_t *frameData,unsigned int frameLen,unsig
 	return false; // overflow == invalid
 }
 
+//#define FILTER_TRACE TRACE
+#define FILTER_TRACE(f,...) {}
+
 // 0 == no match, -1 == match/drop, 1 == match/accept
 static int _doZtFilter(
 	const RuntimeEnvironment *RR,
@@ -107,6 +140,7 @@ static int _doZtFilter(
 				if (thisSetMatches) {
 					return -1; // match, drop packet
 				} else {
+					thisRuleMatches = 1;
 					thisSetMatches = 1; // no match, evaluate next set
 				}
 				break;
@@ -114,6 +148,7 @@ static int _doZtFilter(
 				if (thisSetMatches) {
 					return 1; // match, accept packet
 				} else {
+					thisRuleMatches = 1;
 					thisSetMatches = 1; // no match, evaluate next set
 				}
 				break;
@@ -132,6 +167,7 @@ static int _doZtFilter(
 				if (rt == ZT_NETWORK_RULE_ACTION_REDIRECT) {
 					return -1; // match, drop packet (we redirected it)
 				} else {
+					thisRuleMatches = 1;
 					thisSetMatches = 1; // TEE does not terminate evaluation
 				}
 			}	break;
@@ -141,32 +177,41 @@ static int _doZtFilter(
 			// thisSetMatches is the binary AND of the result of all rules in a set
 
 			case ZT_NETWORK_RULE_MATCH_SOURCE_ZEROTIER_ADDRESS:
+				FILTER_TRACE("FILTER[%u] %s param0=%.10llx",rn,_rtn(rt),rules[rn].v.zt);
 				thisRuleMatches = (uint8_t)(rules[rn].v.zt == ztSource.toInt());
 				break;
 			case ZT_NETWORK_RULE_MATCH_DEST_ZEROTIER_ADDRESS:
+				FILTER_TRACE("FILTER[%u] %s param0=%.10llx",rn,_rtn(rt),rules[rn].v.zt);
 				thisRuleMatches = (uint8_t)(rules[rn].v.zt == ztDest.toInt());
 				break;
 			case ZT_NETWORK_RULE_MATCH_VLAN_ID:
+				FILTER_TRACE("FILTER[%u] %s param0=%u",rn,_rtn(rt),(unsigned int)rules[rn].v.vlanId);
 				thisRuleMatches = (uint8_t)(rules[rn].v.vlanId == (uint16_t)vlanId);
 				break;
 			case ZT_NETWORK_RULE_MATCH_VLAN_PCP:
 				// NOT SUPPORTED YET
+				FILTER_TRACE("FILTER[%u] %s param0=%u",rn,_rtn(rt),(unsigned int)rules[rn].v.vlanPcp);
 				thisRuleMatches = (uint8_t)(rules[rn].v.vlanPcp == 0);
 				break;
 			case ZT_NETWORK_RULE_MATCH_VLAN_DEI:
 				// NOT SUPPORTED YET
+				FILTER_TRACE("FILTER[%u] %s param0=%u",rn,_rtn(rt),(unsigned int)rules[rn].v.vlanDei);
 				thisRuleMatches = (uint8_t)(rules[rn].v.vlanDei == 0);
 				break;
 			case ZT_NETWORK_RULE_MATCH_ETHERTYPE:
+				FILTER_TRACE("FILTER[%u] %s param0=%u etherType=%u",rn,_rtn(rt),(unsigned int)rules[rn].v.etherType,etherType);
 				thisRuleMatches = (uint8_t)(rules[rn].v.etherType == (uint16_t)etherType);
 				break;
 			case ZT_NETWORK_RULE_MATCH_MAC_SOURCE:
+				FILTER_TRACE("FILTER[%u] %s param0=%.12llx",rn,_rtn(rt),rules[rn].v.mac);
 				thisRuleMatches = (uint8_t)(MAC(rules[rn].v.mac,6) == macSource);
 				break;
 			case ZT_NETWORK_RULE_MATCH_MAC_DEST:
+				FILTER_TRACE("FILTER[%u] %s param0=%.12llx",rn,_rtn(rt),rules[rn].v.mac);
 				thisRuleMatches = (uint8_t)(MAC(rules[rn].v.mac,6) == macDest);
 				break;
 			case ZT_NETWORK_RULE_MATCH_IPV4_SOURCE:
+				FILTER_TRACE("FILTER[%u] %s param0=%s",rn,_rtn(rt),InetAddress((const void *)&(rules[rn].v.ipv4.ip),4,rules[rn].v.ipv4.mask).toString().c_str());
 				if ((etherType == ZT_ETHERTYPE_IPV4)&&(frameLen >= 20)) {
 					thisRuleMatches = (uint8_t)(InetAddress((const void *)&(rules[rn].v.ipv4.ip),4,rules[rn].v.ipv4.mask).containsAddress(InetAddress((const void *)(frameData + 12),4,0)));
 				} else {
@@ -174,6 +219,7 @@ static int _doZtFilter(
 				}
 				break;
 			case ZT_NETWORK_RULE_MATCH_IPV4_DEST:
+				FILTER_TRACE("FILTER[%u] %s param0=%s",rn,_rtn(rt),InetAddress((const void *)&(rules[rn].v.ipv4.ip),4,rules[rn].v.ipv4.mask).toString().c_str());
 				if ((etherType == ZT_ETHERTYPE_IPV4)&&(frameLen >= 20)) {
 					thisRuleMatches = (uint8_t)(InetAddress((const void *)&(rules[rn].v.ipv4.ip),4,rules[rn].v.ipv4.mask).containsAddress(InetAddress((const void *)(frameData + 16),4,0)));
 				} else {
@@ -181,6 +227,7 @@ static int _doZtFilter(
 				}
 				break;
 			case ZT_NETWORK_RULE_MATCH_IPV6_SOURCE:
+				FILTER_TRACE("FILTER[%u] %s param0=%s",rn,_rtn(rt),InetAddress((const void *)rules[rn].v.ipv6.ip,16,rules[rn].v.ipv6.mask).toString().c_str());
 				if ((etherType == ZT_ETHERTYPE_IPV6)&&(frameLen >= 40)) {
 					thisRuleMatches = (uint8_t)(InetAddress((const void *)rules[rn].v.ipv6.ip,16,rules[rn].v.ipv6.mask).containsAddress(InetAddress((const void *)(frameData + 8),16,0)));
 				} else {
@@ -188,6 +235,7 @@ static int _doZtFilter(
 				}
 				break;
 			case ZT_NETWORK_RULE_MATCH_IPV6_DEST:
+				FILTER_TRACE("FILTER[%u] %s param0=%s",rn,_rtn(rt),InetAddress((const void *)rules[rn].v.ipv6.ip,16,rules[rn].v.ipv6.mask).toString().c_str());
 				if ((etherType == ZT_ETHERTYPE_IPV6)&&(frameLen >= 40)) {
 					thisRuleMatches = (uint8_t)(InetAddress((const void *)rules[rn].v.ipv6.ip,16,rules[rn].v.ipv6.mask).containsAddress(InetAddress((const void *)(frameData + 24),16,0)));
 				} else {
@@ -195,6 +243,7 @@ static int _doZtFilter(
 				}
 				break;
 			case ZT_NETWORK_RULE_MATCH_IP_TOS:
+				FILTER_TRACE("FILTER[%u] %s param0=%u",rn,_rtn(rt),(unsigned int)rules[rn].v.ipTos);
 				if ((etherType == ZT_ETHERTYPE_IPV4)&&(frameLen >= 20)) {
 					thisRuleMatches = (uint8_t)(rules[rn].v.ipTos == ((frameData[1] & 0xfc) >> 2));
 				} else if ((etherType == ZT_ETHERTYPE_IPV6)&&(frameLen >= 40)) {
@@ -205,6 +254,7 @@ static int _doZtFilter(
 				}
 				break;
 			case ZT_NETWORK_RULE_MATCH_IP_PROTOCOL:
+				FILTER_TRACE("FILTER[%u] %s param0=%u",rn,_rtn(rt),(unsigned int)rules[rn].v.ipProtocol);
 				if ((etherType == ZT_ETHERTYPE_IPV4)&&(frameLen >= 20)) {
 					thisRuleMatches = (uint8_t)(rules[rn].v.ipProtocol == frameData[9]);
 				} else if (etherType == ZT_ETHERTYPE_IPV6) {
@@ -236,6 +286,7 @@ static int _doZtFilter(
 							}
 							break;
 					}
+					FILTER_TRACE("FILTER[%u] %s param0=%u param1=%u port==%u proto==%u etherType=%u (IPv4)",rn,_rtn(rt),(unsigned int)rules[rn].v.port[0],(unsigned int)rules[rn].v.port[1],p,(unsigned int)frameData[9],etherType);
 					thisRuleMatches = (p > 0) ? (uint8_t)((p >= (int)rules[rn].v.port[0])&&(p <= (int)rules[rn].v.port[1])) : (uint8_t)0;
 				} else if (etherType == ZT_ETHERTYPE_IPV6) {
 					unsigned int pos = 0,proto = 0;
@@ -254,11 +305,14 @@ static int _doZtFilter(
 								}
 								break;
 						}
+						FILTER_TRACE("FILTER[%u] %s param0=%u param1=%u port==%u proto=%u etherType=%u (IPv6)",rn,_rtn(rt),(unsigned int)rules[rn].v.port[0],(unsigned int)rules[rn].v.port[1],p,proto,etherType);
 						thisRuleMatches = (p > 0) ? (uint8_t)((p >= (int)rules[rn].v.port[0])&&(p <= (int)rules[rn].v.port[1])) : (uint8_t)0;
 					} else {
+						FILTER_TRACE("FILTER[%u] %s param0=%u param1=%u port=0 proto=0 etherType=%u (IPv6 parse failed)",rn,_rtn(rt),(unsigned int)rules[rn].v.port[0],(unsigned int)rules[rn].v.port[1],etherType);
 						thisRuleMatches = 0;
 					}
 				} else {
+					FILTER_TRACE("FILTER[%u] %s param0=%u param1=%u port=0 proto=0 etherType=%u (not IPv4 or IPv6)",rn,_rtn(rt),(unsigned int)rules[rn].v.port[0],(unsigned int)rules[rn].v.port[1],etherType);
 					thisRuleMatches = 0;
 				}
 				break;
@@ -277,15 +331,18 @@ static int _doZtFilter(
 						}
 					}
 				}
+				FILTER_TRACE("FILTER[%u] %s param0=%.16llx param1=%.16llx actual=%.16llx",rn,_rtn(rt),rules[rn].v.characteristics[0],rules[rn].v.characteristics[1],cf);
 				thisRuleMatches = (uint8_t)((cf & rules[rn].v.characteristics[0]) == rules[rn].v.characteristics[1]);
 			}	break;
 			case ZT_NETWORK_RULE_MATCH_FRAME_SIZE_RANGE:
+				FILTER_TRACE("FILTER[%u] %s param0=%u param1=%u",rn,_rtn(rt),(unsigned int)rules[rn].v.frameSize[0],(unsigned int)rules[rn].v.frameSize[1]);
 				thisRuleMatches = (uint8_t)((frameLen >= (unsigned int)rules[rn].v.frameSize[0])&&(frameLen <= (unsigned int)rules[rn].v.frameSize[1]));
 				break;
 			case ZT_NETWORK_RULE_MATCH_TAGS_SAMENESS:
 			case ZT_NETWORK_RULE_MATCH_TAGS_BITWISE_AND:
 			case ZT_NETWORK_RULE_MATCH_TAGS_BITWISE_OR:
 			case ZT_NETWORK_RULE_MATCH_TAGS_BITWISE_XOR: {
+				FILTER_TRACE("FILTER[%u] %s param0=%u",rn,_rtn(rt),(unsigned int)rules[rn].v.tag.value);
 				const Tag *lt = (const Tag *)0;
 				for(unsigned int i=0;i<localTagCount;++i) {
 					if (rules[rn].v.tag.id == localTags[i].id()) {
@@ -329,7 +386,7 @@ static int _doZtFilter(
 		// thisSetMatches remains true if the current rule matched (or did NOT match if NOT bit is set)
 		thisSetMatches &= (thisRuleMatches ^ ((rules[rn].t & 0x80) >> 7));
 
-		//TRACE("[%u] %u result==%u set==%u",rn,(unsigned int)rt,(unsigned int)thisRuleMatches,(unsigned int)thisSetMatches);
+		FILTER_TRACE("FILTER[%u] %s/%u thisRuleMatches==%u thisSetMatches==%u",rn,_rtn(rt),(unsigned int)rt,(unsigned int)thisRuleMatches,(unsigned int)thisSetMatches);
 	}
 
 	return 0;