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 <sharpd@cumulusnetworks.com>

diff --git a/zebra/debug.c b/zebra/debug.c
index 87999a1bbce03e66976b66e967959e8ee7d42d11..8e5fb0ea103b8e4474a242753204b8665b6e2406 100644 (file)
--- 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 944ad6d68b44f4b3588b5c9d75a3424287074756..176226f7ae402b5ff0d10645ddc1a6d5b1dd8688 100644 (file)
--- 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 be9a6af1fa10da90d84944541477a316fcf6e2c1..adf2f3928ebe5baf379535b6c261679431338376 100644 (file)
--- 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 32da05afb631f35941254e1e1e578aa4ae818e51..d57087d462e1fb8cc6e2ac5116f71e560ac6e9e4 100644 (file)
--- 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;