zebra: Add some debugs to neighbor entry processing

When we get a neighbor entry in zebra we start processing it.
Let's add some additional debugs to the processing so that when
it bails out and we don't use the data, we know the reason.
This should help in debugging the problems from why bgp does
not appear to have data associated with a neighbor entry
in the kernel.

Signed-off-by: Donald Sharp <sharpd@cumulusnetworks.com>

2 files changed, 91 insertions, 34 deletions

diff --git a/zebra/rt_netlink.c b/zebra/rt_netlink.c
index 32dc8791b..2a297409f 100644
--- a/zebra/rt_netlink.c
+++ b/zebra/rt_netlink.c
@@ -1965,23 +1965,38 @@ static int netlink_macfdb_change(struct nlmsghdr *h, int len, ns_id_t ns_id)
 	/* The interface should exist. */
 	ifp = if_lookup_by_index_per_ns(zebra_ns_lookup(ns_id),
 					ndm->ndm_ifindex);
-	if (!ifp || !ifp->info)
+	if (!ifp || !ifp->info) {
+		if (IS_ZEBRA_DEBUG_KERNEL)
+			zlog_debug("\t%s without associated interface: %u",
+				   __PRETTY_FUNCTION__, ndm->ndm_ifindex);
 		return 0;
+	}
 
 	/* The interface should be something we're interested in. */
-	if (!IS_ZEBRA_IF_BRIDGE_SLAVE(ifp))
+	if (!IS_ZEBRA_IF_BRIDGE_SLAVE(ifp)) {
+		if (IS_ZEBRA_DEBUG_KERNEL)
+			zlog_debug("\t%s Not interested in %s, not a slave",
+				   __PRETTY_FUNCTION__, ifp->name);
 		return 0;
+	}
 
 	/* Drop "permanent" entries. */
-	if (ndm->ndm_state & NUD_PERMANENT)
+	if (ndm->ndm_state & NUD_PERMANENT) {
+		if (IS_ZEBRA_DEBUG_KERNEL)
+			zlog_debug("\t%s Entry is PERMANENT, dropping",
+				   __PRETTY_FUNCTION__);
 		return 0;
+	}
 
 	zif = (struct zebra_if *)ifp->info;
 	if ((br_if = zif->brslave_info.br_if) == NULL) {
-		zlog_debug("%s family %s IF %s(%u) brIF %u - no bridge master",
-			   nl_msg_type_to_str(h->nlmsg_type),
-			   nl_family_to_str(ndm->ndm_family), ifp->name,
-			   ndm->ndm_ifindex, zif->brslave_info.bridge_ifindex);
+		if (IS_ZEBRA_DEBUG_KERNEL)
+			zlog_debug(
+				"%s family %s IF %s(%u) brIF %u - no bridge master",
+				nl_msg_type_to_str(h->nlmsg_type),
+				nl_family_to_str(ndm->ndm_family), ifp->name,
+				ndm->ndm_ifindex,
+				zif->brslave_info.bridge_ifindex);
 		return 0;
 	}
 
@@ -1990,20 +2005,24 @@ static int netlink_macfdb_change(struct nlmsghdr *h, int len, ns_id_t ns_id)
 	netlink_parse_rtattr(tb, NDA_MAX, NDA_RTA(ndm), len);
 
 	if (!tb[NDA_LLADDR]) {
-		zlog_debug("%s family %s IF %s(%u) brIF %u - no LLADDR",
-			   nl_msg_type_to_str(h->nlmsg_type),
-			   nl_family_to_str(ndm->ndm_family), ifp->name,
-			   ndm->ndm_ifindex, zif->brslave_info.bridge_ifindex);
+		if (IS_ZEBRA_DEBUG_KERNEL)
+			zlog_debug("%s family %s IF %s(%u) brIF %u - no LLADDR",
+				   nl_msg_type_to_str(h->nlmsg_type),
+				   nl_family_to_str(ndm->ndm_family), ifp->name,
+				   ndm->ndm_ifindex,
+				   zif->brslave_info.bridge_ifindex);
 		return 0;
 	}
 
 	if (RTA_PAYLOAD(tb[NDA_LLADDR]) != ETH_ALEN) {
-		zlog_debug(
-			"%s family %s IF %s(%u) brIF %u - LLADDR is not MAC, len %lu",
-			nl_msg_type_to_str(h->nlmsg_type),
-			nl_family_to_str(ndm->ndm_family), ifp->name,
-			ndm->ndm_ifindex, zif->brslave_info.bridge_ifindex,
-			(unsigned long)RTA_PAYLOAD(tb[NDA_LLADDR]));
+		if (IS_ZEBRA_DEBUG_KERNEL)
+			zlog_debug(
+				"%s family %s IF %s(%u) brIF %u - LLADDR is not MAC, len %lu",
+				nl_msg_type_to_str(h->nlmsg_type),
+				nl_family_to_str(ndm->ndm_family), ifp->name,
+				ndm->ndm_ifindex,
+				zif->brslave_info.bridge_ifindex,
+				(unsigned long)RTA_PAYLOAD(tb[NDA_LLADDR]));
 		return 0;
 	}
 
@@ -2036,8 +2055,12 @@ static int netlink_macfdb_change(struct nlmsghdr *h, int len, ns_id_t ns_id)
 			   prefix_mac2str(&mac, buf, sizeof(buf)),
 			   dst_present ? dst_buf : "");
 
-	if (filter_vlan && vid != filter_vlan)
+	if (filter_vlan && vid != filter_vlan) {
+		if (IS_ZEBRA_DEBUG_KERNEL)
+			zlog_debug("\tFiltered due to filter vlan: %d",
+				   filter_vlan);
 		return 0;
+	}
 
 	/* If add or update, do accordingly if learnt on a "local" interface; if
 	 * the notification is over VxLAN, this has to be related to
@@ -2061,8 +2084,11 @@ static int netlink_macfdb_change(struct nlmsghdr *h, int len, ns_id_t ns_id)
 	 * Ignore the notification from VxLan driver as it is also generated
 	 * when mac moves from remote to local.
 	 */
-	if (dst_present)
+	if (dst_present) {
+		if (IS_ZEBRA_DEBUG_KERNEL)
+			zlog_debug("\tNo Destination Present");
 		return 0;
+	}
 
 	if (IS_ZEBRA_IF_VXLAN(ifp))
 		return zebra_vxlan_check_readd_remote_mac(ifp, br_if, &mac,
@@ -2375,6 +2401,9 @@ static int netlink_ipneigh_change(struct nlmsghdr *h, int len, ns_id_t ns_id)
 	/* if kernel deletes our rfc5549 neighbor entry, re-install it */
 	if (h->nlmsg_type == RTM_DELNEIGH && (ndm->ndm_state & NUD_PERMANENT)) {
 		netlink_handle_5549(ndm, zif, ifp, &ip);
+		if (IS_ZEBRA_DEBUG_KERNEL)
+			zlog_debug(
+				"\tNeighbor Entry Received is a 5549 entry, finished");
 		return 0;
 	}
 
@@ -2400,20 +2429,27 @@ static int netlink_ipneigh_change(struct nlmsghdr *h, int len, ns_id_t ns_id)
 			return 0;
 	} else if (IS_ZEBRA_IF_BRIDGE(ifp))
 		link_if = ifp;
-	else
+	else {
+		if (IS_ZEBRA_DEBUG_KERNEL)
+			zlog_debug(
+				"\tNeighbor Entry received is not on a VLAN or a BRIDGE, ignoring");
 		return 0;
+	}
 
 	memset(&mac, 0, sizeof(struct ethaddr));
 	if (h->nlmsg_type == RTM_NEWNEIGH) {
 		if (tb[NDA_LLADDR]) {
 			if (RTA_PAYLOAD(tb[NDA_LLADDR]) != ETH_ALEN) {
-				zlog_debug(
-					"%s family %s IF %s(%u) - LLADDR is not MAC, len %lu",
-					nl_msg_type_to_str(h->nlmsg_type),
-					nl_family_to_str(ndm->ndm_family),
-					ifp->name, ndm->ndm_ifindex,
-					(unsigned long)RTA_PAYLOAD(
-						tb[NDA_LLADDR]));
+				if (IS_ZEBRA_DEBUG_KERNEL)
+					zlog_debug(
+						"%s family %s IF %s(%u) - LLADDR is not MAC, len %lu",
+						nl_msg_type_to_str(
+							h->nlmsg_type),
+						nl_family_to_str(
+							ndm->ndm_family),
+						ifp->name, ndm->ndm_ifindex,
+						(unsigned long)RTA_PAYLOAD(
+							tb[NDA_LLADDR]));
 				return 0;
 			}
 
diff --git a/zebra/zebra_vxlan.c b/zebra/zebra_vxlan.c
index 9a7d20bc4..00fc23085 100644
--- a/zebra/zebra_vxlan.c
+++ b/zebra/zebra_vxlan.c
@@ -2986,8 +2986,12 @@ static int zvni_local_neigh_update(zebra_vni_t *zvni,
 	}
 
 	zvrf = vrf_info_lookup(zvni->vxlan_if->vrf_id);
-	if (!zvrf)
+	if (!zvrf) {
+		if (IS_ZEBRA_DEBUG_VXLAN)
+			zlog_debug("\tUnable to find vrf for: %d",
+				   zvni->vxlan_if->vrf_id);
 		return -1;
+	}
 
 	/* Check if the neighbor exists. */
 	n = zvni_neigh_lookup(zvni, ip);
@@ -3017,6 +3021,9 @@ static int zvni_local_neigh_update(zebra_vni_t *zvni,
 			cur_is_router = !!CHECK_FLAG(n->flags,
 						     ZEBRA_NEIGH_ROUTER_FLAG);
 			if (!mac_different && is_router == cur_is_router) {
+				if (IS_ZEBRA_DEBUG_VXLAN)
+					zlog_debug(
+						"\tIgnoring entry mac is the same and is_router == cur_is_router");
 				n->ifindex = ifp->ifindex;
 				return 0;
 			}
@@ -3045,6 +3052,11 @@ static int zvni_local_neigh_update(zebra_vni_t *zvni,
 					return zvni_neigh_send_add_to_client(
 							zvni->vni, ip, macaddr,
 							n->flags, n->loc_seq);
+				else {
+					if (IS_ZEBRA_DEBUG_VXLAN)
+						zlog_debug(
+							"\tNeighbor active and frozen");
+				}
 				return 0;
 			}
 
@@ -3185,6 +3197,10 @@ static int zvni_local_neigh_update(zebra_vni_t *zvni,
 	if (!neigh_on_hold)
 		return zvni_neigh_send_add_to_client(zvni->vni, ip, macaddr,
 					     n->flags, n->loc_seq);
+	else {
+		if (IS_ZEBRA_DEBUG_VXLAN)
+			zlog_debug("\tNeighbor on hold not sending");
+	}
 	return 0;
 }
 
@@ -7579,7 +7595,7 @@ int zebra_vxlan_local_mac_add_update(struct interface *ifp,
 	if (!zvni) {
 		if (IS_ZEBRA_DEBUG_VXLAN)
 			zlog_debug(
-				"Add/Update %sMAC %s intf %s(%u) VID %u, could not find VNI",
+				"\tAdd/Update %sMAC %s intf %s(%u) VID %u, could not find VNI",
 				sticky ? "sticky " : "",
 				prefix_mac2str(macaddr, buf, sizeof(buf)),
 				ifp->name, ifp->ifindex, vid);
@@ -7587,15 +7603,20 @@ int zebra_vxlan_local_mac_add_update(struct interface *ifp,
 	}
 
 	if (!zvni->vxlan_if) {
-		zlog_debug(
-			"VNI %u hash %p doesn't have intf upon local MAC ADD",
-			zvni->vni, zvni);
+		if (IS_ZEBRA_DEBUG_VXLAN)
+			zlog_debug(
+				"\tVNI %u hash %p doesn't have intf upon local MAC ADD",
+				zvni->vni, zvni);
 		return -1;
 	}
 
 	zvrf = vrf_info_lookup(zvni->vxlan_if->vrf_id);
-	if (!zvrf)
+	if (!zvrf) {
+		if (IS_ZEBRA_DEBUG_VXLAN)
+			zlog_debug("\tNo Vrf found for vrf_id: %d",
+				   zvni->vxlan_if->vrf_id);
 		return -1;
+	}
 
 	/* Check if we need to create or update or it is a NO-OP. */
 	mac = zvni_mac_lookup(zvni, macaddr);
@@ -7645,7 +7666,7 @@ int zebra_vxlan_local_mac_add_update(struct interface *ifp,
 			    && mac->fwd_info.local.vid == vid) {
 				if (IS_ZEBRA_DEBUG_VXLAN)
 					zlog_debug(
-						"Add/Update %sMAC %s intf %s(%u) VID %u -> VNI %u, "
+						"\tAdd/Update %sMAC %s intf %s(%u) VID %u -> VNI %u, "
 						"entry exists and has not changed ",
 						sticky ? "sticky " : "",
 						prefix_mac2str(macaddr, buf,