From: Donald Sharp Date: Fri, 8 Feb 2019 14:11:47 +0000 (-0500) Subject: zebra: Add detailed debugging command for NHT tracking X-Git-Tag: 7.1_pulled~129^2~4 X-Git-Url: https://git.puffer.fish/?a=commitdiff_plain;h=50872b0804870e2f2ffaf5db8d3052af4003dc89;p=matthieu%2Ffrr.git zebra: Add detailed debugging command for NHT tracking Add a detailed debugging command for NHT tracking and add the detailed output to the log about why we make some decisions that we are. I tried to model this like the rib processing detailed debugs that we added a few months back. Signed-off-by: Donald Sharp --- diff --git a/zebra/debug.c b/zebra/debug.c index 87999a1bbc..8e5fb0ea10 100644 --- a/zebra/debug.c +++ b/zebra/debug.c @@ -87,7 +87,9 @@ DEFUN_NOSH (show_debugging_zebra, if (IS_ZEBRA_DEBUG_FPM) vty_out(vty, " Zebra FPM debugging is on\n"); - if (IS_ZEBRA_DEBUG_NHT) + if (IS_ZEBRA_DEBUG_NHT_DETAILED) + vty_out(vty, " Zebra detailed next-hop tracking debugging is on\n"); + else if (IS_ZEBRA_DEBUG_NHT) vty_out(vty, " Zebra next-hop tracking debugging is on\n"); if (IS_ZEBRA_DEBUG_MPLS) vty_out(vty, " Zebra MPLS debugging is on\n"); @@ -119,12 +121,19 @@ DEFUN (debug_zebra_events, DEFUN (debug_zebra_nht, debug_zebra_nht_cmd, - "debug zebra nht", + "debug zebra nht [detailed]", DEBUG_STR "Zebra configuration\n" - "Debug option set for zebra next hop tracking\n") + "Debug option set for zebra next hop tracking\n" + "Debug option set for detailed info\n") { + int idx = 0; + zebra_debug_nht = ZEBRA_DEBUG_NHT; + + if (argv_find(argv, argc, "detailed", &idx)) + zebra_debug_nht |= ZEBRA_DEBUG_NHT_DETAILED; + return CMD_SUCCESS; } @@ -320,11 +329,12 @@ DEFUN (no_debug_zebra_events, DEFUN (no_debug_zebra_nht, no_debug_zebra_nht_cmd, - "no debug zebra nht", + "no debug zebra nht [detailed]", NO_STR DEBUG_STR "Zebra configuration\n" - "Debug option set for zebra next hop tracking\n") + "Debug option set for zebra next hop tracking\n" + "Debug option set for detailed info\n") { zebra_debug_nht = 0; return CMD_SUCCESS; @@ -490,10 +500,15 @@ static int config_write_debug(struct vty *vty) vty_out(vty, "debug zebra fpm\n"); write++; } - if (IS_ZEBRA_DEBUG_NHT) { + + if (IS_ZEBRA_DEBUG_NHT_DETAILED) { + vty_out(vty, "debug zebra nht detailed\n"); + write++; + } else if (IS_ZEBRA_DEBUG_NHT) { vty_out(vty, "debug zebra nht\n"); write++; } + if (IS_ZEBRA_DEBUG_MPLS) { vty_out(vty, "debug zebra mpls\n"); write++; @@ -530,6 +545,7 @@ void zebra_debug_init(void) zebra_debug_pw = 0; zebra_debug_dplane = 0; zebra_debug_mlag = 0; + zebra_debug_nht = 0; install_node(&debug_node, config_write_debug); diff --git a/zebra/debug.h b/zebra/debug.h index 944ad6d68b..176226f7ae 100644 --- a/zebra/debug.h +++ b/zebra/debug.h @@ -44,7 +44,9 @@ extern "C" { #define ZEBRA_DEBUG_RIB_DETAILED 0x02 #define ZEBRA_DEBUG_FPM 0x01 -#define ZEBRA_DEBUG_NHT 0x01 + +#define ZEBRA_DEBUG_NHT 0x01 +#define ZEBRA_DEBUG_NHT_DETAILED 0x02 #define ZEBRA_DEBUG_MPLS 0x01 @@ -76,7 +78,10 @@ extern "C" { #define IS_ZEBRA_DEBUG_RIB_DETAILED (zebra_debug_rib & ZEBRA_DEBUG_RIB_DETAILED) #define IS_ZEBRA_DEBUG_FPM (zebra_debug_fpm & ZEBRA_DEBUG_FPM) + #define IS_ZEBRA_DEBUG_NHT (zebra_debug_nht & ZEBRA_DEBUG_NHT) +#define IS_ZEBRA_DEBUG_NHT_DETAILED (zebra_debug_nht & ZEBRA_DEBUG_NHT_DETAILED) + #define IS_ZEBRA_DEBUG_MPLS (zebra_debug_mpls & ZEBRA_DEBUG_MPLS) #define IS_ZEBRA_DEBUG_VXLAN (zebra_debug_vxlan & ZEBRA_DEBUG_VXLAN) #define IS_ZEBRA_DEBUG_PW (zebra_debug_pw & ZEBRA_DEBUG_PW) diff --git a/zebra/zebra_rib.c b/zebra/zebra_rib.c index be9a6af1fa..adf2f3928e 100644 --- a/zebra/zebra_rib.c +++ b/zebra/zebra_rib.c @@ -1232,7 +1232,7 @@ void zebra_rib_evaluate_rn_nexthops(struct route_node *rn, uint32_t seq) struct rnh *rnh; /* - * We are storing the rnh's associated with + * We are storing the rnh's associated withb * the tracked nexthop as a list of the rn's. * Unresolved rnh's are placed at the top * of the tree list.( 0.0.0.0/0 for v4 and 0::0/0 for v6 ) @@ -1241,6 +1241,13 @@ void zebra_rib_evaluate_rn_nexthops(struct route_node *rn, uint32_t seq) * would match a more specific route */ while (rn) { + if (IS_ZEBRA_DEBUG_NHT_DETAILED) { + char buf[PREFIX_STRLEN]; + + zlog_debug("%s: %s Being examined for Nexthop Tracking", + __PRETTY_FUNCTION__, + srcdest_rnode2str(rn, buf, sizeof(buf))); + } if (!dest) { rn = rn->parent; if (rn) @@ -1258,13 +1265,13 @@ void zebra_rib_evaluate_rn_nexthops(struct route_node *rn, uint32_t seq) zebra_vrf_lookup_by_id(rnh->vrf_id); struct prefix *p = &rnh->node->p; - if (IS_ZEBRA_DEBUG_NHT) { + if (IS_ZEBRA_DEBUG_NHT_DETAILED) { char buf1[PREFIX_STRLEN]; char buf2[PREFIX_STRLEN]; zlog_debug("%u:%s has Nexthop(%s) depending on it, evaluating %u:%u", zvrf->vrf->vrf_id, - prefix2str(&rn->p, buf1, + srcdest_rnode2str(rn, buf1, sizeof(buf1)), prefix2str(p, buf2, sizeof(buf2)), seq, rnh->seqno); @@ -1282,8 +1289,12 @@ void zebra_rib_evaluate_rn_nexthops(struct route_node *rn, uint32_t seq) * we were originally as such we know that * that sequence number is ok to respect. */ - if (rnh->seqno == seq) + if (rnh->seqno == seq) { + if (IS_ZEBRA_DEBUG_NHT_DETAILED) + zlog_debug( + "\tNode processed and moved already"); continue; + } rnh->seqno = seq; zebra_evaluate_rnh(zvrf, family2afi(p->family), 0, diff --git a/zebra/zebra_rnh.c b/zebra/zebra_rnh.c index 32da05afb6..d57087d462 100644 --- a/zebra/zebra_rnh.c +++ b/zebra/zebra_rnh.c @@ -108,6 +108,16 @@ static void zebra_rnh_remove_from_routing_table(struct rnh *rnh) if (!rn) return; + if (IS_ZEBRA_DEBUG_NHT_DETAILED) { + char buf[PREFIX_STRLEN]; + char buf1[PREFIX_STRLEN]; + + zlog_debug("%s: %u:%s removed from tracking on %s", + __PRETTY_FUNCTION__, rnh->vrf_id, + prefix2str(&rnh->node->p, buf, sizeof(buf)), + srcdest_rnode2str(rn, buf1, sizeof(buf))); + } + dest = rib_dest_from_rnode(rn); listnode_delete(dest->nht, rnh); route_unlock_node(rn); @@ -124,6 +134,16 @@ static void zebra_rnh_store_in_routing_table(struct rnh *rnh) if (!rn) return; + if (IS_ZEBRA_DEBUG_NHT_DETAILED) { + char buf[PREFIX_STRLEN]; + char buf1[PREFIX_STRLEN]; + + zlog_debug("%s: %u:%s added for tracking on %s", + __PRETTY_FUNCTION__, rnh->vrf_id, + prefix2str(&rnh->node->p, buf, sizeof(buf)), + srcdest_rnode2str(rn, buf1, sizeof(buf))); + } + dest = rib_dest_from_rnode(rn); listnode_add(dest->nht, rnh); route_unlock_node(rn); @@ -414,6 +434,16 @@ zebra_rnh_resolve_import_entry(struct zebra_vrf *zvrf, afi_t afi, && !prefix_same(&nrn->p, &rn->p)) return NULL; + if (IS_ZEBRA_DEBUG_NHT_DETAILED) { + char buf[PREFIX_STRLEN]; + char buf1[PREFIX_STRLEN]; + + zlog_debug("%s: %u:%s Resolved Import Entry to %s", + __PRETTY_FUNCTION__, rnh->vrf_id, + prefix2str(&rnh->node->p, buf, sizeof(buf)), + srcdest_rnode2str(rn, buf1, sizeof(buf))); + } + /* Identify appropriate route entry. */ RNODE_FOREACH_RE (rn, re) { if (!CHECK_FLAG(re->status, ROUTE_ENTRY_REMOVED) @@ -424,6 +454,10 @@ zebra_rnh_resolve_import_entry(struct zebra_vrf *zvrf, afi_t afi, if (re) *prn = rn; + + if (!re && IS_ZEBRA_DEBUG_NHT_DETAILED) + zlog_debug("\tRejected due to removed or is a bgp route"); + return re; } @@ -497,7 +531,7 @@ static void zebra_rnh_notify_protocol_clients(struct zebra_vrf *zvrf, afi_t afi, if (IS_ZEBRA_DEBUG_NHT) { prefix2str(&nrn->p, bufn, INET6_ADDRSTRLEN); if (prn && re) { - prefix2str(&prn->p, bufp, INET6_ADDRSTRLEN); + srcdest_rnode2str(prn, bufp, INET6_ADDRSTRLEN); zlog_debug("%u:%s: NH resolved over route %s", zvrf->vrf->vrf_id, bufn, bufp); } else @@ -630,19 +664,43 @@ zebra_rnh_resolve_nexthop_entry(struct zebra_vrf *zvrf, afi_t afi, * most-specific match. Do similar logic as in zebra_rib.c */ while (rn) { + if (IS_ZEBRA_DEBUG_NHT_DETAILED) { + char buf[PREFIX_STRLEN]; + char buf1[PREFIX_STRLEN]; + + zlog_debug("%s: %u:%s Possible Match to %s", + __PRETTY_FUNCTION__, rnh->vrf_id, + prefix2str(&rnh->node->p, buf, sizeof(buf)), + srcdest_rnode2str(rn, buf1, sizeof(buf))); + } + /* Do not resolve over default route unless allowed && * match route to be exact if so specified */ if (is_default_prefix(&rn->p) - && !rnh_resolve_via_default(rn->p.family)) + && !rnh_resolve_via_default(rn->p.family)) { + if (IS_ZEBRA_DEBUG_NHT_DETAILED) + zlog_debug( + "\tNot allowed to resolve through default prefix"); return NULL; + } /* Identify appropriate route entry. */ RNODE_FOREACH_RE (rn, re) { - if (CHECK_FLAG(re->status, ROUTE_ENTRY_REMOVED)) + if (CHECK_FLAG(re->status, ROUTE_ENTRY_REMOVED)) { + if (IS_ZEBRA_DEBUG_NHT_DETAILED) + zlog_debug( + "\tRoute Entry %s removed", + zebra_route_string(re->type)); continue; - if (!CHECK_FLAG(re->flags, ZEBRA_FLAG_SELECTED)) + } + if (!CHECK_FLAG(re->flags, ZEBRA_FLAG_SELECTED)) { + if (IS_ZEBRA_DEBUG_NHT_DETAILED) + zlog_debug( + "\tRoute Entry %s !selected", + zebra_route_string(re->type)); continue; + } /* Just being SELECTED isn't quite enough - must * have an installed nexthop to be useful. @@ -652,8 +710,13 @@ zebra_rnh_resolve_nexthop_entry(struct zebra_vrf *zvrf, afi_t afi, break; } - if (nexthop == NULL) + if (nexthop == NULL) { + if (IS_ZEBRA_DEBUG_NHT_DETAILED) + zlog_debug( + "\tRoute Entry %s no nexthops", + zebra_route_string(re->type)); continue; + } if (CHECK_FLAG(rnh->flags, ZEBRA_NHT_CONNECTED)) { if ((re->type == ZEBRA_ROUTE_CONNECT) @@ -681,8 +744,12 @@ zebra_rnh_resolve_nexthop_entry(struct zebra_vrf *zvrf, afi_t afi, if (!CHECK_FLAG(rnh->flags, ZEBRA_NHT_CONNECTED)) rn = rn->parent; - else + else { + if (IS_ZEBRA_DEBUG_NHT_DETAILED) + zlog_debug( + "\tNexthop must be connected, cannot recurse up"); return NULL; + } } return NULL;