From: vivek Date: Fri, 20 Nov 2015 16:48:32 +0000 (-0800) Subject: Zebra: Cleanup RIB debugs X-Git-Tag: frr-2.0-rc1~1192 X-Git-Url: https://git.puffer.fish/?a=commitdiff_plain;h=41ec92223a7dfc14eb8cb0b84c73ad09943213eb;p=matthieu%2Ffrr.git Zebra: Cleanup RIB debugs Some of the changes include: - ensuring IPv6 addresses are printed correctly - say 'updating' or 'deleting' etc. only when that is actually done - say 'queuing' or 'dequeuing' only when that is actually done - print useful info for 'detailed' debug - that now subsumes 'rib queue' - delete various useless logs - VRF-specific - print VRF id in RIB debugs prior to prefix (e.g., 4:37.1.1.0/28) Ticket: CM-8110 Reviewed By: CCR-3765 Testing Done: Manual testing (2.5-br) --- diff --git a/zebra/connected.c b/zebra/connected.c index b6dbad39bd..98e0bb84af 100644 --- a/zebra/connected.c +++ b/zebra/connected.c @@ -214,7 +214,7 @@ connected_up_ipv4 (struct interface *ifp, struct connected *ifc) rib_add_ipv4 (ZEBRA_ROUTE_CONNECT, 0, 0, &p, NULL, NULL, ifp->ifindex, ifp->vrf_id, RT_TABLE_MAIN, ifp->metric, 0, SAFI_MULTICAST); - if (IS_ZEBRA_DEBUG_RIB) + if (IS_ZEBRA_DEBUG_RIB_DETAILED) zlog_debug ("%s: calling rib_update", __func__); rib_update (ifp->vrf_id); @@ -333,7 +333,7 @@ connected_down_ipv4 (struct interface *ifp, struct connected *ifc) rib_delete_ipv4 (ZEBRA_ROUTE_CONNECT, 0, 0, &p, NULL, ifp->ifindex, ifp->vrf_id, 0, SAFI_MULTICAST); - if (IS_ZEBRA_DEBUG_RIB) + if (IS_ZEBRA_DEBUG_RIB_DETAILED) zlog_debug ("%s: calling rib_update_static", __func__); rib_update_static (ifp->vrf_id); @@ -396,7 +396,7 @@ connected_delete_ipv4 (struct interface *ifp, int flags, struct in_addr *addr, connected_withdraw (ifc); - if (IS_ZEBRA_DEBUG_RIB) + if (IS_ZEBRA_DEBUG_RIB_DETAILED) zlog_debug ("%s: calling rib_update_static", __func__); rib_update_static(ifp->vrf_id); @@ -425,7 +425,7 @@ connected_up_ipv6 (struct interface *ifp, struct connected *ifc) rib_add_ipv6 (ZEBRA_ROUTE_CONNECT, 0, 0, &p, NULL, ifp->ifindex, ifp->vrf_id, RT_TABLE_MAIN, ifp->metric, 0, SAFI_UNICAST); - if (IS_ZEBRA_DEBUG_RIB) + if (IS_ZEBRA_DEBUG_RIB_DETAILED) zlog_debug ("%s: calling rib_update", __func__); rib_update (ifp->vrf_id); @@ -514,7 +514,7 @@ connected_down_ipv6 (struct interface *ifp, struct connected *ifc) rib_delete_ipv6 (ZEBRA_ROUTE_CONNECT, 0, 0, &p, NULL, ifp->ifindex, ifp->vrf_id, 0, SAFI_UNICAST); - if (IS_ZEBRA_DEBUG_RIB) + if (IS_ZEBRA_DEBUG_RIB_DETAILED) zlog_debug ("%s: calling rib_update_static", __func__); rib_update_static (ifp->vrf_id); @@ -538,7 +538,7 @@ connected_delete_ipv6 (struct interface *ifp, struct in6_addr *address, connected_withdraw (ifc); - if (IS_ZEBRA_DEBUG_RIB) + if (IS_ZEBRA_DEBUG_RIB_DETAILED) zlog_debug ("%s: calling rib_update_static", __func__); rib_update_static(ifp->vrf_id); diff --git a/zebra/debug.c b/zebra/debug.c index 10aba2d556..906d13d7eb 100644 --- a/zebra/debug.c +++ b/zebra/debug.c @@ -68,10 +68,11 @@ DEFUN (show_debugging_zebra, if (IS_ZEBRA_DEBUG_KERNEL) vty_out (vty, " Zebra kernel debugging is on%s", VTY_NEWLINE); - if (IS_ZEBRA_DEBUG_RIB) + /* Check here using flags as the 'macro' does an OR */ + if (CHECK_FLAG (zebra_debug_rib, ZEBRA_DEBUG_RIB)) vty_out (vty, " Zebra RIB debugging is on%s", VTY_NEWLINE); - if (IS_ZEBRA_DEBUG_RIB_Q) - vty_out (vty, " Zebra RIB queue debugging is on%s", VTY_NEWLINE); + if (CHECK_FLAG (zebra_debug_rib, ZEBRA_DEBUG_RIB_DETAILED)) + vty_out (vty, " Zebra RIB detailed debugging is on%s", VTY_NEWLINE); if (IS_ZEBRA_DEBUG_FPM) vty_out (vty, " Zebra FPM debugging is on%s", VTY_NEWLINE); @@ -175,15 +176,15 @@ DEFUN (debug_zebra_rib, return CMD_SUCCESS; } -DEFUN (debug_zebra_rib_q, - debug_zebra_rib_q_cmd, - "debug zebra rib queue", +DEFUN (debug_zebra_rib_detailed, + debug_zebra_rib_detailed_cmd, + "debug zebra rib detailed", DEBUG_STR "Zebra configuration\n" "Debug RIB events\n" - "Debug RIB queueing\n") + "Detailed debugs\n") { - SET_FLAG (zebra_debug_rib, ZEBRA_DEBUG_RIB_Q); + SET_FLAG (zebra_debug_rib, ZEBRA_DEBUG_RIB_DETAILED); return CMD_SUCCESS; } @@ -275,16 +276,16 @@ DEFUN (no_debug_zebra_rib, return CMD_SUCCESS; } -DEFUN (no_debug_zebra_rib_q, - no_debug_zebra_rib_q_cmd, - "no debug zebra rib queue", +DEFUN (no_debug_zebra_rib_detailed, + no_debug_zebra_rib_detailed_cmd, + "no debug zebra rib detailed", NO_STR DEBUG_STR "Zebra configuration\n" "Debug zebra RIB\n" - "Debug RIB queueing\n") + "Detailed debugs\n") { - UNSET_FLAG (zebra_debug_rib, ZEBRA_DEBUG_RIB_Q); + UNSET_FLAG (zebra_debug_rib, ZEBRA_DEBUG_RIB_DETAILED); return CMD_SUCCESS; } @@ -345,14 +346,15 @@ config_write_debug (struct vty *vty) vty_out (vty, "debug zebra kernel%s", VTY_NEWLINE); write++; } - if (IS_ZEBRA_DEBUG_RIB) + /* Check here using flags as the 'macro' does an OR */ + if (CHECK_FLAG (zebra_debug_rib, ZEBRA_DEBUG_RIB)) { vty_out (vty, "debug zebra rib%s", VTY_NEWLINE); write++; } - if (IS_ZEBRA_DEBUG_RIB_Q) + if (CHECK_FLAG (zebra_debug_rib, ZEBRA_DEBUG_RIB_DETAILED)) { - vty_out (vty, "debug zebra rib queue%s", VTY_NEWLINE); + vty_out (vty, "debug zebra rib detailed%s", VTY_NEWLINE); write++; } if (IS_ZEBRA_DEBUG_FPM) @@ -384,14 +386,14 @@ zebra_debug_init (void) install_element (ENABLE_NODE, &debug_zebra_packet_detail_cmd); install_element (ENABLE_NODE, &debug_zebra_kernel_cmd); install_element (ENABLE_NODE, &debug_zebra_rib_cmd); - install_element (ENABLE_NODE, &debug_zebra_rib_q_cmd); + install_element (ENABLE_NODE, &debug_zebra_rib_detailed_cmd); install_element (ENABLE_NODE, &debug_zebra_fpm_cmd); install_element (ENABLE_NODE, &no_debug_zebra_events_cmd); install_element (ENABLE_NODE, &no_debug_zebra_nht_cmd); install_element (ENABLE_NODE, &no_debug_zebra_packet_cmd); install_element (ENABLE_NODE, &no_debug_zebra_kernel_cmd); install_element (ENABLE_NODE, &no_debug_zebra_rib_cmd); - install_element (ENABLE_NODE, &no_debug_zebra_rib_q_cmd); + install_element (ENABLE_NODE, &no_debug_zebra_rib_detailed_cmd); install_element (ENABLE_NODE, &no_debug_zebra_fpm_cmd); install_element (CONFIG_NODE, &debug_zebra_events_cmd); @@ -401,13 +403,13 @@ zebra_debug_init (void) install_element (CONFIG_NODE, &debug_zebra_packet_detail_cmd); install_element (CONFIG_NODE, &debug_zebra_kernel_cmd); install_element (CONFIG_NODE, &debug_zebra_rib_cmd); - install_element (CONFIG_NODE, &debug_zebra_rib_q_cmd); + install_element (CONFIG_NODE, &debug_zebra_rib_detailed_cmd); install_element (CONFIG_NODE, &debug_zebra_fpm_cmd); install_element (CONFIG_NODE, &no_debug_zebra_events_cmd); install_element (CONFIG_NODE, &no_debug_zebra_nht_cmd); install_element (CONFIG_NODE, &no_debug_zebra_packet_cmd); install_element (CONFIG_NODE, &no_debug_zebra_kernel_cmd); install_element (CONFIG_NODE, &no_debug_zebra_rib_cmd); - install_element (CONFIG_NODE, &no_debug_zebra_rib_q_cmd); + install_element (CONFIG_NODE, &no_debug_zebra_rib_detailed_cmd); install_element (CONFIG_NODE, &no_debug_zebra_fpm_cmd); } diff --git a/zebra/debug.h b/zebra/debug.h index 0fb4dd9fee..42af53f0d8 100644 --- a/zebra/debug.h +++ b/zebra/debug.h @@ -34,7 +34,7 @@ #define ZEBRA_DEBUG_KERNEL 0x01 #define ZEBRA_DEBUG_RIB 0x01 -#define ZEBRA_DEBUG_RIB_Q 0x02 +#define ZEBRA_DEBUG_RIB_DETAILED 0x02 #define ZEBRA_DEBUG_FPM 0x01 #define ZEBRA_DEBUG_NHT 0x01 @@ -49,8 +49,9 @@ #define IS_ZEBRA_DEBUG_KERNEL (zebra_debug_kernel & ZEBRA_DEBUG_KERNEL) -#define IS_ZEBRA_DEBUG_RIB (zebra_debug_rib & ZEBRA_DEBUG_RIB) -#define IS_ZEBRA_DEBUG_RIB_Q (zebra_debug_rib & ZEBRA_DEBUG_RIB_Q) +#define IS_ZEBRA_DEBUG_RIB \ + (zebra_debug_rib & (ZEBRA_DEBUG_RIB | ZEBRA_DEBUG_RIB_DETAILED)) +#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) diff --git a/zebra/interface.c b/zebra/interface.c index a3d297d327..8d081c0597 100644 --- a/zebra/interface.c +++ b/zebra/interface.c @@ -639,7 +639,7 @@ if_up (struct interface *ifp) } } - if (IS_ZEBRA_DEBUG_RIB) + if (IS_ZEBRA_DEBUG_RIB_DETAILED) zlog_debug ("%s: calling rib_update on interface %s up", __func__, ifp->name); @@ -677,7 +677,7 @@ if_down (struct interface *ifp) } /* Examine all static routes which direct to the interface. */ - if (IS_ZEBRA_DEBUG_RIB) + if (IS_ZEBRA_DEBUG_RIB_DETAILED) zlog_debug ("%s: calling rib_update_static on interface %s down", __func__, ifp->name); diff --git a/zebra/redistribute.c b/zebra/redistribute.c index a17b9a8c09..ba7945ad23 100644 --- a/zebra/redistribute.c +++ b/zebra/redistribute.c @@ -181,6 +181,15 @@ redistribute_update (struct prefix *p, struct rib *rib, struct rib *prev_rib) struct zserv *client; int send_redistribute; int afi; + char buf[INET6_ADDRSTRLEN]; + + if (IS_ZEBRA_DEBUG_RIB) + { + inet_ntop (p->family, &p->u.prefix, buf, INET6_ADDRSTRLEN); + zlog_debug ("%u:%s/%d: Redist update rib %p (type %d), old %p (type %d)", + rib->vrf_id, buf, p->prefixlen, rib, rib->type, + prev_rib, prev_rib ? prev_rib->type : -1); + } afi = family2afi(p->family); if (!afi) @@ -254,6 +263,14 @@ redistribute_delete (struct prefix *p, struct rib *rib) { struct listnode *node, *nnode; struct zserv *client; + char buf[INET6_ADDRSTRLEN]; + + if (IS_ZEBRA_DEBUG_RIB) + { + inet_ntop (p->family, &p->u.prefix, buf, INET6_ADDRSTRLEN); + zlog_debug ("%u:%s/%d: Redist delete rib %p (type %d)", + rib->vrf_id, buf, p->prefixlen, rib, rib->type); + } /* Add DISTANCE_INFINITY check. */ if (rib->distance == DISTANCE_INFINITY) diff --git a/zebra/zebra_rib.c b/zebra/zebra_rib.c index 300c2143cb..d1f679361a 100644 --- a/zebra/zebra_rib.c +++ b/zebra/zebra_rib.c @@ -1203,8 +1203,8 @@ nexthop_active_check (struct route_node *rn, struct rib *rib, if (IS_ZEBRA_DEBUG_RIB) { inet_ntop (rn->p.family, &rn->p.u.prefix, buf, sizeof (buf)); - zlog_debug("%s: Filtering out %s with NH out %s due to route map", - __FUNCTION__, buf, nexthop->ifname); + zlog_debug("%u:%s/%d: Filtering out with NH out %s due to route map", + rib->vrf_id, buf, rn->p.prefixlen, nexthop->ifname); } UNSET_FLAG (nexthop->flags, NEXTHOP_FLAG_ACTIVE); } @@ -1391,6 +1391,7 @@ rib_gc_dest (struct route_node *rn) { rib_dest_t *dest; char buf[INET6_ADDRSTRLEN]; + struct zebra_vrf *zvrf; dest = rib_dest_from_rnode (rn); if (!dest) @@ -1399,11 +1400,12 @@ rib_gc_dest (struct route_node *rn) if (!rib_can_delete_dest (dest)) return 0; - if (IS_ZEBRA_DEBUG_RIB) + zvrf = rib_dest_vrf (dest); + if (IS_ZEBRA_DEBUG_RIB_DETAILED) { inet_ntop (rn->p.family, &rn->p.u.prefix, buf, sizeof (buf)); - zlog_debug ("%s: %s/%d: removing dest from table", __func__, - buf, rn->p.prefixlen); + zlog_debug ("%u:%s/%d: rn %p removing dest", + zvrf->vrf_id, buf, rn->p.prefixlen, rn); } dest->rnode = NULL; @@ -1430,14 +1432,33 @@ rib_process (struct route_node *rn) struct nexthop *nexthop = NULL, *tnexthop; int recursing; char buf[INET6_ADDRSTRLEN]; - + rib_dest_t *dest; + struct zebra_vrf *zvrf = NULL; + vrf_id_t vrf_id = 0; + assert (rn); - if (IS_ZEBRA_DEBUG_RIB || IS_ZEBRA_DEBUG_RIB_Q) + dest = rib_dest_from_rnode (rn); + if (dest) + { + zvrf = rib_dest_vrf (dest); + vrf_id = zvrf->vrf_id; + } + + if (IS_ZEBRA_DEBUG_RIB) inet_ntop (rn->p.family, &rn->p.u.prefix, buf, INET6_ADDRSTRLEN); + if (IS_ZEBRA_DEBUG_RIB_DETAILED) + zlog_debug ("%u:%s/%d: Processing rn %p", vrf_id, buf, rn->p.prefixlen, rn); + RNODE_FOREACH_RIB_SAFE (rn, rib, next) { + if (IS_ZEBRA_DEBUG_RIB_DETAILED) + zlog_debug ("%u:%s/%d: Examine rib %p (type %d) status %x flags %x " + "dist %d metric %d", + vrf_id, buf, rn->p.prefixlen, rib, rib->type, rib->status, + rib->flags, rib->distance, rib->metric); + UNSET_FLAG(rib->status, RIB_ENTRY_NEXTHOPS_CHANGED); /* Currently installed rib. */ @@ -1455,8 +1476,8 @@ rib_process (struct route_node *rn) if (rib != fib) { if (IS_ZEBRA_DEBUG_RIB) - zlog_debug ("%s: %s/%d: rn %p, removing rib %p", __func__, - buf, rn->p.prefixlen, rn, rib); + zlog_debug ("%u:%s/%d: Freeing route rn %p, rib %p (type %d)", + vrf_id, buf, rn->p.prefixlen, rn, rib, rib->type); rib_unlink (rn, rib); } else @@ -1551,13 +1572,13 @@ rib_process (struct route_node *rn) * del --- equal to fib, if fib is queued for deletion, NULL otherwise * rib --- NULL */ + if (IS_ZEBRA_DEBUG_RIB_DETAILED) + zlog_debug ("%u:%s/%d: After processing: select %p fib %p del %p", + vrf_id, buf, rn->p.prefixlen, select, fib, del); /* Same RIB entry is selected. Update FIB and finish. */ if (select && select == fib) { - if (IS_ZEBRA_DEBUG_RIB) - zlog_debug ("%s: %s/%d: Updating existing route, select %p, fib %p", - __func__, buf, rn->p.prefixlen, select, fib); if (CHECK_FLAG (select->flags, ZEBRA_FLAG_CHANGED)) { zfpm_trigger_update (rn, "updating existing route"); @@ -1568,6 +1589,9 @@ rib_process (struct route_node *rn) */ if (nexthop_active_update (rn, select, 1)) { + if (IS_ZEBRA_DEBUG_RIB) + zlog_debug ("%u:%s/%d: Updating route rn %p, rib %p (type %d)", + vrf_id, buf, rn->p.prefixlen, rn, select, select->type); if (! RIB_SYSTEM_ROUTE (select)) { /* Clear FIB flag if performing a replace, will get set again @@ -1583,6 +1607,11 @@ rib_process (struct route_node *rn) } else { + if (IS_ZEBRA_DEBUG_RIB) + zlog_debug ("%u:%s/%d: Deleting route rn %p, rib %p (type %d) " + "- nexthop inactive", + vrf_id, buf, rn->p.prefixlen, rn, select, select->type); + /* Withdraw unreachable redistribute route */ redistribute_delete(&rn->p, select); @@ -1620,10 +1649,6 @@ rib_process (struct route_node *rn) */ if (fib) { - if (IS_ZEBRA_DEBUG_RIB) - zlog_debug ("%s: %s/%d: Removing existing route, fib %p", __func__, - buf, rn->p.prefixlen, fib); - zfpm_trigger_update (rn, "removing existing route"); /* If there's no route to replace this with, withdraw redistribute and @@ -1631,6 +1656,10 @@ rib_process (struct route_node *rn) */ if (!select) { + if (IS_ZEBRA_DEBUG_RIB) + zlog_debug ("%u:%s/%d: Deleting route rn %p, rib %p (type %d)", + vrf_id, buf, rn->p.prefixlen, rn, fib, fib->type); + redistribute_delete(&rn->p, fib); if (! RIB_SYSTEM_ROUTE (fib)) rib_uninstall_kernel (rn, fib); @@ -1649,15 +1678,22 @@ rib_process (struct route_node *rn) */ if (select) { - if (IS_ZEBRA_DEBUG_RIB) - zlog_debug ("%s: %s/%d: Adding route, select %p", __func__, buf, - rn->p.prefixlen, select); - zfpm_trigger_update (rn, "new route selected"); /* Set real nexthop. */ if (nexthop_active_update (rn, select, 1)) { + if (IS_ZEBRA_DEBUG_RIB) + { + if (fib) + zlog_debug ("%u:%s/%d: Updating route rn %p, rib %p (type %d) " + "old %p (type %d)", vrf_id, buf, rn->p.prefixlen, rn, + select, select->type, fib, fib->type); + else + zlog_debug ("%u:%s/%d: Adding route rn %p, rib %p (type %d)", + vrf_id, buf, rn->p.prefixlen, rn, select, select->type); + } + if (! RIB_SYSTEM_ROUTE (select)) { /* Clear FIB flag if performing a replace, will get set again @@ -1686,12 +1722,18 @@ rib_process (struct route_node *rn) } else { - /* Uninstall prior route here, if needed. */ - if (fib && !RIB_SYSTEM_ROUTE (fib)) - rib_uninstall_kernel (rn, fib); - /* if "select", the earlier redist delete wouldn't have happened */ + /* Uninstall prior route here and do redist delete, if needed. */ if (fib) - redistribute_delete(&rn->p, fib); + { + if (IS_ZEBRA_DEBUG_RIB) + zlog_debug ("%u:%s/%d: Deleting route rn %p, rib %p (type %d) " + "- nexthop inactive", + vrf_id, buf, rn->p.prefixlen, rn, fib, fib->type); + + if (!RIB_SYSTEM_ROUTE (fib)) + rib_uninstall_kernel (rn, fib); + redistribute_delete(&rn->p, fib); + } } UNSET_FLAG(select->flags, ZEBRA_FLAG_CHANGED); } @@ -1700,15 +1742,12 @@ rib_process (struct route_node *rn) if (del) { if (IS_ZEBRA_DEBUG_RIB) - zlog_debug ("%s: %s/%d: Deleting fib %p, rn %p", __func__, buf, - rn->p.prefixlen, del, rn); + zlog_debug ("%u:%s/%d: Freeing route rn %p, rib %p (type %d)", + vrf_id, buf, rn->p.prefixlen, rn, del, del->type); rib_unlink (rn, del); } end: - if (IS_ZEBRA_DEBUG_RIB_Q) - zlog_debug ("%s: %s/%d: rn %p dequeued", __func__, buf, rn->p.prefixlen, rn); - /* * Check if the dest can be deleted now. */ @@ -1724,13 +1763,27 @@ process_subq (struct list * subq, u_char qindex) { struct listnode *lnode = listhead (subq); struct route_node *rnode; + char buf[INET6_ADDRSTRLEN]; + rib_dest_t *dest; + struct zebra_vrf *zvrf = NULL; if (!lnode) return 0; rnode = listgetdata (lnode); + dest = rib_dest_from_rnode (rnode); + if (dest) + zvrf = rib_dest_vrf (dest); + rib_process (rnode); + if (IS_ZEBRA_DEBUG_RIB_DETAILED) + { + inet_ntop (rnode->p.family, &rnode->p.u.prefix, buf, INET6_ADDRSTRLEN); + zlog_debug ("%u:%s/%d: rn %p dequeued from sub-queue %u", + zvrf ? zvrf->vrf_id : 0, buf, rnode->p.prefixlen, rnode, qindex); + } + if (rnode->info) UNSET_FLAG (rib_dest_from_rnode (rnode)->flags, RIB_ROUTE_QUEUED (qindex)); @@ -1806,7 +1859,7 @@ rib_meta_queue_add (struct meta_queue *mq, struct route_node *rn) struct rib *rib; char buf[INET6_ADDRSTRLEN]; - if (IS_ZEBRA_DEBUG_RIB_Q) + if (IS_ZEBRA_DEBUG_RIB_DETAILED) inet_ntop (rn->p.family, &rn->p.u.prefix, buf, INET6_ADDRSTRLEN); RNODE_FOREACH_RIB (rn, rib) @@ -1816,21 +1869,16 @@ rib_meta_queue_add (struct meta_queue *mq, struct route_node *rn) /* Invariant: at this point we always have rn->info set. */ if (CHECK_FLAG (rib_dest_from_rnode (rn)->flags, RIB_ROUTE_QUEUED (qindex))) - { - if (IS_ZEBRA_DEBUG_RIB_Q) - zlog_debug ("%s: %s/%d: rn %p is already queued in sub-queue %u", - __func__, buf, rn->p.prefixlen, rn, qindex); - continue; - } + continue; SET_FLAG (rib_dest_from_rnode (rn)->flags, RIB_ROUTE_QUEUED (qindex)); listnode_add (mq->subq[qindex], rn); route_lock_node (rn); mq->size++; - if (IS_ZEBRA_DEBUG_RIB_Q) - zlog_debug ("%s: %s/%d: queued rn %p into sub-queue %u", - __func__, buf, rn->p.prefixlen, rn, qindex); + if (IS_ZEBRA_DEBUG_RIB_DETAILED) + zlog_debug ("%u:%s/%d: rn %p queued into sub-queue %u", + rib->vrf_id, buf, rn->p.prefixlen, rn, qindex); } } @@ -1838,12 +1886,8 @@ rib_meta_queue_add (struct meta_queue *mq, struct route_node *rn) void rib_queue_add (struct zebra_t *zebra, struct route_node *rn) { - char buf[INET_ADDRSTRLEN]; assert (zebra && rn); - if (IS_ZEBRA_DEBUG_RIB_Q) - inet_ntop (AF_INET, &rn->p.u.prefix, buf, INET_ADDRSTRLEN); - /* Pointless to queue a route_node with no RIB entries to add or remove */ if (!rnode_to_ribs (rn)) { @@ -1853,9 +1897,6 @@ rib_queue_add (struct zebra_t *zebra, struct route_node *rn) return; } - if (IS_ZEBRA_DEBUG_RIB_Q) - zlog_info ("%s: %s/%d: work queue added", __func__, buf, rn->p.prefixlen); - assert (zebra); if (zebra->ribq == NULL) @@ -1877,9 +1918,6 @@ rib_queue_add (struct zebra_t *zebra, struct route_node *rn) rib_meta_queue_add (zebra->mq, rn); - if (IS_ZEBRA_DEBUG_RIB_Q) - zlog_debug ("%s: %s/%d: rn %p queued", __func__, buf, rn->p.prefixlen, rn); - return; } @@ -1981,20 +2019,14 @@ rib_link (struct route_node *rn, struct rib *rib) assert (rib && rn); - if (IS_ZEBRA_DEBUG_RIB) - { - inet_ntop (rn->p.family, &rn->p.u.prefix, buf, INET6_ADDRSTRLEN); - zlog_debug ("%s: %s/%d: rn %p, rib %p", __func__, - buf, rn->p.prefixlen, rn, rib); - } - dest = rib_dest_from_rnode (rn); if (!dest) { - if (IS_ZEBRA_DEBUG_RIB) + if (IS_ZEBRA_DEBUG_RIB_DETAILED) { - zlog_debug ("%s: %s/%d: adding dest to table", __func__, - buf, rn->p.prefixlen); + inet_ntop (rn->p.family, &rn->p.u.prefix, buf, INET6_ADDRSTRLEN); + zlog_debug ("%u:%s/%d: rn %p adding dest", + rib->vrf_id, buf, rn->p.prefixlen, rn); } dest = XCALLOC (MTYPE_RIB_DEST, sizeof (rib_dest_t)); @@ -2016,11 +2048,6 @@ rib_link (struct route_node *rn, struct rib *rib) rib_queue_add (&zebrad, rn); else { - if (IS_ZEBRA_DEBUG_RIB) - { - zlog_debug ("%s: %s/%d: Skipping further RIB processing of non-main table", - __func__, buf, rn->p.prefixlen); - } afi = (rn->p.family == AF_INET) ? AFI_IP : (rn->p.family == AF_INET6) ? AFI_IP6 : AFI_MAX; if (is_zebra_import_table_enabled (afi, rib->table)) @@ -2036,13 +2063,6 @@ rib_addnode (struct route_node *rn, struct rib *rib) */ if (CHECK_FLAG (rib->status, RIB_ENTRY_REMOVED)) { - if (IS_ZEBRA_DEBUG_RIB) - { - char buf[INET6_ADDRSTRLEN]; - inet_ntop (rn->p.family, &rn->p.u.prefix, buf, INET6_ADDRSTRLEN); - zlog_debug ("%s: %s/%d: rn %p, un-removed rib %p", - __func__, buf, rn->p.prefixlen, rn, rib); - } UNSET_FLAG (rib->status, RIB_ENTRY_REMOVED); return; } @@ -2061,18 +2081,10 @@ rib_addnode (struct route_node *rn, struct rib *rib) static void rib_unlink (struct route_node *rn, struct rib *rib) { - char buf[INET6_ADDRSTRLEN]; rib_dest_t *dest; assert (rn && rib); - if (IS_ZEBRA_DEBUG_RIB) - { - inet_ntop (rn->p.family, &rn->p.u.prefix, buf, INET6_ADDRSTRLEN); - zlog_debug ("%s: %s/%d: rn %p, rib %p", - __func__, buf, rn->p.prefixlen, rn, rib); - } - dest = rib_dest_from_rnode (rn); if (rib->next) @@ -2096,13 +2108,6 @@ rib_delnode (struct route_node *rn, struct rib *rib) { afi_t afi; - if (IS_ZEBRA_DEBUG_RIB) - { - char buf[INET6_ADDRSTRLEN]; - inet_ntop (rn->p.family, &rn->p.u.prefix, buf, INET6_ADDRSTRLEN); - zlog_debug ("%s: %s/%d: rn %p, rib %p, removing", __func__, - buf, rn->p.prefixlen, rn, rib); - } SET_FLAG (rib->status, RIB_ENTRY_REMOVED); if ((rib->table == RT_TABLE_MAIN) || (rib->table == zebrad.rtm_table_default)) @@ -2114,6 +2119,17 @@ rib_delnode (struct route_node *rn, struct rib *rib) if (is_zebra_import_table_enabled (afi, rib->table)) zebra_del_import_table_entry(rn, rib); /* Just clean up if non main table */ + if (IS_ZEBRA_DEBUG_RIB) + { + char buf[INET6_ADDRSTRLEN]; + if (IS_ZEBRA_DEBUG_RIB) + { + inet_ntop (rn->p.family, &rn->p.u.prefix, buf, INET6_ADDRSTRLEN); + zlog_debug ("%u:%s/%d: Freeing route rn %p, rib %p (type %d)", + rib->vrf_id, buf, rn->p.prefixlen, rn, rib, rib->type); + } + } + rib_unlink(rn, rib); } } @@ -2219,20 +2235,24 @@ rib_add_ipv4 (int type, u_short instance, int flags, struct prefix_ipv4 *p, /* Link new rib to node.*/ if (IS_ZEBRA_DEBUG_RIB) - { - zlog_debug ("%s: called rib_addnode (%p, %p) on new RIB entry", - __func__, rn, rib); - rib_dump ((struct prefix *)p, rib); - } + { + char buf[INET6_ADDRSTRLEN]; + if (IS_ZEBRA_DEBUG_RIB) + { + inet_ntop (p->family, &p->prefix, buf, INET6_ADDRSTRLEN); + zlog_debug ("%u:%s/%d: Inserting route rn %p, rib %p (type %d) " + "existing %p", + vrf_id, buf, p->prefixlen, rn, rib, rib->type, same); + } + + if (IS_ZEBRA_DEBUG_RIB_DETAILED) + rib_dump ((struct prefix *)p, rib); + } rib_addnode (rn, rib); /* Free implicit route.*/ if (same) - { - if (IS_ZEBRA_DEBUG_RIB) - zlog_debug ("%s: calling rib_delnode (%p, %p)", __func__, rn, rib); rib_delnode (rn, same); - } route_unlock_node (rn); return 0; @@ -2389,7 +2409,8 @@ void rib_lookup_and_pushup (struct prefix_ipv4 * p) { char buf[INET_ADDRSTRLEN]; inet_ntop (rn->p.family, &p->prefix, buf, INET_ADDRSTRLEN); - zlog_debug ("%s: freeing way for connected prefix %s/%d", __func__, buf, p->prefixlen); + zlog_debug ("%u:%s/%d: freeing way for connected prefix", + rib->vrf_id, buf, p->prefixlen); rib_dump (&rn->p, rib); } rib_uninstall (rn, rib); @@ -2456,27 +2477,29 @@ rib_add_ipv4_multipath (struct prefix_ipv4 *p, struct rib *rib, safi_t safi) SET_FLAG (nexthop->flags, NEXTHOP_FLAG_FIB); /* Link new rib to node.*/ + if (IS_ZEBRA_DEBUG_RIB) + { + char buf[INET6_ADDRSTRLEN]; + if (IS_ZEBRA_DEBUG_RIB) + { + inet_ntop (p->family, &p->prefix, buf, INET6_ADDRSTRLEN); + zlog_debug ("%u:%s/%d: Inserting route rn %p, rib %p (type %d) " + "existing %p", + rib->vrf_id, buf, p->prefixlen, rn, rib, rib->type, same); + } + + if (IS_ZEBRA_DEBUG_RIB_DETAILED) + rib_dump ((struct prefix *)p, rib); + } rib_addnode (rn, rib); ret = 1; - if (IS_ZEBRA_DEBUG_RIB) - { - zlog_debug ("%s: called rib_addnode (%p, %p) on new RIB entry", - __func__, rn, rib); - rib_dump (p, rib); - } /* Free implicit route.*/ if (same) - { - if (IS_ZEBRA_DEBUG_RIB) { - zlog_debug ("%s: calling rib_delnode (%p, %p) on existing RIB entry", - __func__, rn, same); - rib_dump (p, same); + rib_delnode (rn, same); + ret = -1; } - rib_delnode (rn, same); - ret = -1; - } route_unlock_node (rn); return ret; @@ -2495,8 +2518,8 @@ rib_delete_ipv4 (int type, u_short instance, int flags, struct prefix_ipv4 *p, struct rib *same = NULL; struct nexthop *nexthop, *tnexthop; int recursing; - char buf1[INET_ADDRSTRLEN]; - char buf2[INET_ADDRSTRLEN]; + char buf1[INET6_ADDRSTRLEN]; + char buf2[INET6_ADDRSTRLEN]; /* Lookup table. */ if ((table_id == RT_TABLE_MAIN) || (table_id == zebrad.rtm_table_default)) @@ -2513,35 +2536,14 @@ rib_delete_ipv4 (int type, u_short instance, int flags, struct prefix_ipv4 *p, /* Apply mask. */ apply_mask_ipv4 (p); - if (IS_ZEBRA_DEBUG_KERNEL) - { - if (gate) - zlog_debug ("rib_delete_ipv4(): route delete %s vrf %u via %s ifindex %d", - prefix2str (p, buf1, sizeof(buf1)), vrf_id, - inet_ntoa (*gate), - ifindex); - else - zlog_debug ("rib_delete_ipv4(): route delete %s vrf %u ifindex %d", - prefix2str (p, buf1, sizeof(buf1)), vrf_id, - ifindex); - } - /* Lookup route node. */ rn = route_node_lookup (table, (struct prefix *) p); if (! rn) { - if (IS_ZEBRA_DEBUG_KERNEL) - { - if (gate) - zlog_debug ("route %s vrf %u via %s ifindex %d doesn't exist in rib", - prefix2str (p, buf1, sizeof(buf1)), vrf_id, - inet_ntop (AF_INET, gate, buf2, INET_ADDRSTRLEN), - ifindex); - else - zlog_debug ("route %s vrf %u ifindex %d doesn't exist in rib", - prefix2str (p, buf1, sizeof(buf1)), vrf_id, - ifindex); - } + if (IS_ZEBRA_DEBUG_RIB) + zlog_debug ("%u:%s/%d: doesn't exist in rib", + vrf_id, inet_ntop (p->family, &p->prefix, buf1, INET6_ADDRSTRLEN), + p->prefixlen); return ZEBRA_ERR_RTNOEXIST; } @@ -2598,11 +2600,12 @@ rib_delete_ipv4 (int type, u_short instance, int flags, struct prefix_ipv4 *p, if (fib && type == ZEBRA_ROUTE_KERNEL && CHECK_FLAG(flags, ZEBRA_FLAG_SELFROUTE)) { - if (IS_ZEBRA_DEBUG_KERNEL) + if (IS_ZEBRA_DEBUG_RIB) { - zlog_debug ("Zebra route %s/%d was deleted by others from kernel", - inet_ntop (AF_INET, &p->prefix, buf1, INET_ADDRSTRLEN), - p->prefixlen); + zlog_debug ("%u:%s/%d: rn %p, rib %p (type %d) was deleted " + "from kernel, adding", + vrf_id, inet_ntop (p->family, &p->prefix, buf1, INET6_ADDRSTRLEN), + p->prefixlen, rn, fib, fib->type); } if (allow_delete) { @@ -2621,18 +2624,18 @@ rib_delete_ipv4 (int type, u_short instance, int flags, struct prefix_ipv4 *p, } else { - if (IS_ZEBRA_DEBUG_KERNEL) + if (IS_ZEBRA_DEBUG_RIB) { if (gate) - zlog_debug ("route %s vrf %u via %s ifindex %d type %d " + zlog_debug ("%u:%s: via %s ifindex %d type %d " "doesn't exist in rib", - prefix2str (p, buf1, sizeof(buf1)), vrf_id, + vrf_id, prefix2str (p, buf1, sizeof(buf1)), inet_ntop (AF_INET, gate, buf2, INET_ADDRSTRLEN), ifindex, type); else - zlog_debug ("route %s vrf %u ifindex %d type %d doesn't exist in rib", - prefix2str (p, buf1, sizeof(buf1)), vrf_id, + zlog_debug ("%u:%s: ifindex %d type %d doesn't exist in rib", + vrf_id, prefix2str (p, buf1, sizeof(buf1)), ifindex, type); } @@ -2711,6 +2714,17 @@ static_install_route (afi_t afi, safi_t safi, struct prefix *p, struct static_ro nexthop_ipv6_ifname_add (rib, &si->addr.ipv6, si->ifname); break; } + + if (IS_ZEBRA_DEBUG_RIB) + { + char buf[INET6_ADDRSTRLEN]; + if (IS_ZEBRA_DEBUG_RIB) + { + inet_ntop (p->family, &p->u.prefix, buf, INET6_ADDRSTRLEN); + zlog_debug ("%u:%s/%d: Modifying route rn %p, rib %p (type %d)", + si->vrf_id, buf, p->prefixlen, rn, rib, rib->type); + } + } rib_queue_add (&zebrad, rn); } else @@ -2761,6 +2775,16 @@ static_install_route (afi_t afi, safi_t safi, struct prefix *p, struct static_ro rib->flags = si->flags; /* Link this rib to the tree. */ + if (IS_ZEBRA_DEBUG_RIB) + { + char buf[INET6_ADDRSTRLEN]; + if (IS_ZEBRA_DEBUG_RIB) + { + inet_ntop (p->family, &p->u.prefix, buf, INET6_ADDRSTRLEN); + zlog_debug ("%u:%s/%d: Inserting route rn %p, rib %p (type %d)", + si->vrf_id, buf, p->prefixlen, rn, rib, rib->type); + } + } rib_addnode (rn, rib); } } @@ -2852,6 +2876,16 @@ static_uninstall_route (afi_t afi, safi_t safi, struct prefix *p, struct static_ * the nexthop. There is no need to re-evaluate the route for this * scenario. */ + if (IS_ZEBRA_DEBUG_RIB) + { + char buf[INET6_ADDRSTRLEN]; + if (IS_ZEBRA_DEBUG_RIB) + { + inet_ntop (p->family, &p->u.prefix, buf, INET6_ADDRSTRLEN); + zlog_debug ("%u:%s/%d: Modifying route rn %p, rib %p (type %d)", + si->vrf_id, buf, p->prefixlen, rn, rib, rib->type); + } + } UNSET_FLAG(nexthop->flags, NEXTHOP_FLAG_ACTIVE); if (CHECK_FLAG (nexthop->flags, NEXTHOP_FLAG_FIB)) { @@ -3142,25 +3176,25 @@ rib_add_ipv6 (int type, u_short instance, int flags, struct prefix_ipv6 *p, SET_FLAG (nexthop->flags, NEXTHOP_FLAG_FIB); /* Link new rib to node.*/ - rib_addnode (rn, rib); if (IS_ZEBRA_DEBUG_RIB) - { - zlog_debug ("%s: called rib_addnode (%p, %p) on new RIB entry", - __func__, rn, rib); - rib_dump (p, rib); - } + { + char buf[INET6_ADDRSTRLEN]; + if (IS_ZEBRA_DEBUG_RIB) + { + inet_ntop (p->family, &p->prefix, buf, INET6_ADDRSTRLEN); + zlog_debug ("%u:%s/%d: Inserting route rn %p, rib %p (type %d) " + "existing %p", + vrf_id, buf, p->prefixlen, rn, rib, rib->type, same); + } + + if (IS_ZEBRA_DEBUG_RIB_DETAILED) + rib_dump ((struct prefix *)p, rib); + } + rib_addnode (rn, rib); /* Free implicit route.*/ if (same) - { - if (IS_ZEBRA_DEBUG_RIB) - { - zlog_debug ("%s: calling rib_delnode (%p, %p) on existing RIB entry", - __func__, rn, same); - rib_dump (p, same); - } rib_delnode (rn, same); - } route_unlock_node (rn); return 0; @@ -3263,20 +3297,29 @@ rib_add_ipv6_multipath (struct prefix *p, struct rib *rib, safi_t safi, } /* Link new rib to node.*/ + if (IS_ZEBRA_DEBUG_RIB) + { + char buf[INET6_ADDRSTRLEN]; + if (IS_ZEBRA_DEBUG_RIB) + { + inet_ntop (p->family, &p->u.prefix, buf, INET6_ADDRSTRLEN); + zlog_debug ("%u:%s/%d: Inserting route rn %p, rib %p (type %d) " + "existing %p", + rib->vrf_id, buf, p->prefixlen, rn, rib, rib->type, same); + } + + if (IS_ZEBRA_DEBUG_RIB_DETAILED) + rib_dump ((struct prefix *)p, rib); + } rib_addnode (rn, rib); ret = 1; + /* Free implicit route.*/ if (same) - { - if (IS_ZEBRA_DEBUG_RIB) { - zlog_debug ("%s: calling rib_delnode (%p, %p) on existing RIB entry", - __func__, rn, same); - rib_dump ((struct prefix *)p, same); + rib_delnode (rn, same); + ret = -1; } - rib_delnode (rn, same); - ret = -1; - } route_unlock_node (rn); return ret; @@ -3317,18 +3360,10 @@ rib_delete_ipv6 (int type, u_short instance, int flags, struct prefix_ipv6 *p, rn = route_node_lookup (table, (struct prefix *) p); if (! rn) { - if (IS_ZEBRA_DEBUG_KERNEL) - { - if (gate) - zlog_debug ("route %s vrf %u via %s ifindex %d doesn't exist in rib", - prefix2str (p, buf1, sizeof(buf1)), vrf_id, - inet_ntop (AF_INET6, gate, buf2, INET6_ADDRSTRLEN), - ifindex); - else - zlog_debug ("route %s vrf %u ifindex %d doesn't exist in rib", - prefix2str (p, buf1, sizeof(buf1)), vrf_id, - ifindex); - } + if (IS_ZEBRA_DEBUG_RIB) + zlog_debug ("%u:%s/%d: doesn't exist in rib", + vrf_id, inet_ntop (p->family, &p->prefix, buf1, INET6_ADDRSTRLEN), + p->prefixlen); return ZEBRA_ERR_RTNOEXIST; } @@ -3386,12 +3421,11 @@ rib_delete_ipv6 (int type, u_short instance, int flags, struct prefix_ipv6 *p, if (fib && type == ZEBRA_ROUTE_KERNEL && CHECK_FLAG(flags, ZEBRA_FLAG_SELFROUTE)) { - if (IS_ZEBRA_DEBUG_KERNEL) - { - zlog_debug ("Zebra route %s/%d was deleted by others from kernel", - inet_ntop (AF_INET6, &p->prefix, buf1, INET6_ADDRSTRLEN), - p->prefixlen); - } + if (IS_ZEBRA_DEBUG_RIB) + zlog_debug ("%u:%s/%d: rn %p, rib %p (type %d) was deleted " + "from kernel, adding", + vrf_id, inet_ntop (p->family, &p->prefix, buf1, INET6_ADDRSTRLEN), + p->prefixlen, rn, fib, fib->type); if (allow_delete) { /* Unset flags. */ @@ -3412,14 +3446,14 @@ rib_delete_ipv6 (int type, u_short instance, int flags, struct prefix_ipv6 *p, if (IS_ZEBRA_DEBUG_KERNEL) { if (gate) - zlog_debug ("route %s vrf %u via %s ifindex %d type %d " + zlog_debug ("%s: vrf %u via %s ifindex %d type %d " "doesn't exist in rib", prefix2str (p, buf1, sizeof(buf1)), vrf_id, inet_ntop (AF_INET6, gate, buf2, INET6_ADDRSTRLEN), ifindex, type); else - zlog_debug ("route %s vrf %u ifindex %d type %d doesn't exist in rib", + zlog_debug ("%s: vrf %u ifindex %d type %d doesn't exist in rib", prefix2str (p, buf1, sizeof(buf1)), vrf_id, ifindex, type); diff --git a/zebra/zebra_routemap.c b/zebra/zebra_routemap.c index 64d6fda24d..20ac1d0352 100644 --- a/zebra/zebra_routemap.c +++ b/zebra/zebra_routemap.c @@ -775,7 +775,7 @@ DEFUN (ip_protocol, } proto_rm[AFI_IP][i] = XSTRDUP (MTYPE_ROUTE_MAP_NAME, argv[1]); - if (IS_ZEBRA_DEBUG_RIB) + if (IS_ZEBRA_DEBUG_RIB_DETAILED) zlog_debug ("%s: calling rib_update", __func__); rib_update(VRF_DEFAULT); @@ -812,7 +812,7 @@ DEFUN (no_ip_protocol, XFREE (MTYPE_ROUTE_MAP_NAME, proto_rm[AFI_IP][i]); proto_rm[AFI_IP][i] = NULL; - if (IS_ZEBRA_DEBUG_RIB) + if (IS_ZEBRA_DEBUG_RIB_DETAILED) zlog_debug ("%s: calling rib_update", __func__); rib_update(VRF_DEFAULT); @@ -887,7 +887,7 @@ DEFUN (ipv6_protocol, } proto_rm[AFI_IP6][i] = XSTRDUP (MTYPE_ROUTE_MAP_NAME, argv[1]); - if (IS_ZEBRA_DEBUG_RIB) + if (IS_ZEBRA_DEBUG_RIB_DETAILED) zlog_debug ("%s: calling rib_update", __func__); rib_update(VRF_DEFAULT); @@ -924,7 +924,7 @@ DEFUN (no_ipv6_protocol, XFREE (MTYPE_ROUTE_MAP_NAME, proto_rm[AFI_IP6][i]); proto_rm[AFI_IP6][i] = NULL; - if (IS_ZEBRA_DEBUG_RIB) + if (IS_ZEBRA_DEBUG_RIB_DETAILED) zlog_debug ("%s: calling rib_update", __func__); rib_update(VRF_DEFAULT); @@ -1598,7 +1598,7 @@ zebra_route_map_update_timer (struct thread *thread) if (IS_ZEBRA_DEBUG_EVENT) zlog_debug("Event driven route-map update triggered"); - if (IS_ZEBRA_DEBUG_RIB) + if (IS_ZEBRA_DEBUG_RIB_DETAILED) zlog_debug ("%s: calling rib_update", __func__); rib_update(VRF_DEFAULT);