From: Jakub Urbańczyk Date: Sun, 15 Mar 2020 18:42:30 +0000 (+0100) Subject: zebra: Add vrf name and id to debugs X-Git-Tag: base_7.4~97^2 X-Git-Url: https://git.puffer.fish/?a=commitdiff_plain;h=refs%2Fpull%2F5988%2Fhead;p=mirror%2Ffrr.git zebra: Add vrf name and id to debugs In some places we log the interface but not the vfr the interface is in. In others we only output the vrf id, which can be difficult for human to read. This commit makes zebra debugs more vrf aware. Signed-off-by: Jakub Urbańczyk --- diff --git a/lib/vrf.c b/lib/vrf.c index 31ea2d6c4c..9bc0db0b58 100644 --- a/lib/vrf.c +++ b/lib/vrf.c @@ -324,10 +324,7 @@ const char *vrf_id_to_name(vrf_id_t vrf_id) struct vrf *vrf; vrf = vrf_lookup_by_id(vrf_id); - if (vrf) - return vrf->name; - - return "n/a"; + return VRF_LOGNAME(vrf); } vrf_id_t vrf_name_to_id(const char *name) diff --git a/zebra/rt_netlink.c b/zebra/rt_netlink.c index f29a7fa305..b6224b3da9 100644 --- a/zebra/rt_netlink.c +++ b/zebra/rt_netlink.c @@ -718,14 +718,15 @@ static int netlink_route_change_read_unicast(struct nlmsghdr *h, ns_id_t ns_id, if (IS_ZEBRA_DEBUG_KERNEL) { char buf[PREFIX_STRLEN]; char buf2[PREFIX_STRLEN]; - zlog_debug("%s %s%s%s vrf %u(%u) metric: %d Admin Distance: %d", - nl_msg_type_to_str(h->nlmsg_type), - prefix2str(&p, buf, sizeof(buf)), - src_p.prefixlen ? " from " : "", - src_p.prefixlen - ? prefix2str(&src_p, buf2, sizeof(buf2)) - : "", - vrf_id, table, metric, distance); + zlog_debug( + "%s %s%s%s vrf %s(%u) table_id: %u metric: %d Admin Distance: %d", + nl_msg_type_to_str(h->nlmsg_type), + prefix2str(&p, buf, sizeof(buf)), + src_p.prefixlen ? " from " : "", + src_p.prefixlen ? prefix2str(&src_p, buf2, sizeof(buf2)) + : "", + vrf_id_to_name(vrf_id), vrf_id, table, metric, + distance); } afi_t afi = AFI_IP; @@ -911,9 +912,8 @@ static int netlink_route_change_read_multicast(struct nlmsghdr *h, ifp = if_lookup_by_index(iif, vrf); zlog_debug( "MCAST VRF: %s(%d) %s (%s,%s) IIF: %s(%d) OIF: %s jiffies: %lld", - (zvrf ? zvrf->vrf->name : "Unknown"), vrf, - nl_msg_type_to_str(h->nlmsg_type), sbuf, gbuf, - ifp ? ifp->name : "Unknown", iif, oif_list, + zvrf_name(zvrf), vrf, nl_msg_type_to_str(h->nlmsg_type), + sbuf, gbuf, ifp ? ifp->name : "Unknown", iif, oif_list, m->lastused); } return 0; @@ -1122,9 +1122,12 @@ static void _netlink_route_build_singlepath(const struct prefix *p, mpls_lse_t out_lse[MPLS_MAX_LABELS]; char label_buf[256]; int num_labels = 0; + struct vrf *vrf; assert(nexthop); + vrf = vrf_lookup_by_id(nexthop->vrf_id); + /* * label_buf is *only* currently used within debugging. * As such when we assign it we are guarding it inside @@ -1177,9 +1180,10 @@ static void _netlink_route_build_singlepath(const struct prefix *p, if (IS_ZEBRA_DEBUG_KERNEL) zlog_debug( - " 5549: _netlink_route_build_singlepath() (%s): %pFX nexthop via %s %s if %u(%u)", + " 5549: _netlink_route_build_singlepath() (%s): %pFX nexthop via %s %s if %u vrf %s(%u)", routedesc, p, ipv4_ll_buf, label_buf, - nexthop->ifindex, nexthop->vrf_id); + nexthop->ifindex, VRF_LOGNAME(vrf), + nexthop->vrf_id); return; } @@ -1202,9 +1206,10 @@ static void _netlink_route_build_singlepath(const struct prefix *p, if (IS_ZEBRA_DEBUG_KERNEL) zlog_debug( - "netlink_route_multipath() (%s): %pFX nexthop via %s %s if %u(%u)", + "netlink_route_multipath() (%s): %pFX nexthop via %s %s if %u vrf %s(%u)", routedesc, p, inet_ntoa(nexthop->gate.ipv4), - label_buf, nexthop->ifindex, nexthop->vrf_id); + label_buf, nexthop->ifindex, VRF_LOGNAME(vrf), + nexthop->vrf_id); } if (nexthop->type == NEXTHOP_TYPE_IPV6 @@ -1224,9 +1229,10 @@ static void _netlink_route_build_singlepath(const struct prefix *p, if (IS_ZEBRA_DEBUG_KERNEL) zlog_debug( - "netlink_route_multipath() (%s): %pFX nexthop via %s %s if %u(%u)", + "netlink_route_multipath() (%s): %pFX nexthop via %s %s if %u vrf %s(%u)", routedesc, p, inet6_ntoa(nexthop->gate.ipv6), - label_buf, nexthop->ifindex, nexthop->vrf_id); + label_buf, nexthop->ifindex, VRF_LOGNAME(vrf), + nexthop->vrf_id); } /* @@ -1249,9 +1255,9 @@ static void _netlink_route_build_singlepath(const struct prefix *p, if (IS_ZEBRA_DEBUG_KERNEL) zlog_debug( - "netlink_route_multipath() (%s): %pFX nexthop via if %u(%u)", + "netlink_route_multipath() (%s): %pFX nexthop via if %u vrf %s(%u)", routedesc, p, nexthop->ifindex, - nexthop->vrf_id); + VRF_LOGNAME(vrf), nexthop->vrf_id); } } @@ -1280,6 +1286,7 @@ _netlink_route_build_multipath(const struct prefix *p, const char *routedesc, mpls_lse_t out_lse[MPLS_MAX_LABELS]; char label_buf[256]; int num_labels = 0; + struct vrf *vrf; rtnh->rtnh_len = sizeof(*rtnh); rtnh->rtnh_flags = 0; @@ -1288,6 +1295,8 @@ _netlink_route_build_multipath(const struct prefix *p, const char *routedesc, assert(nexthop); + vrf = vrf_lookup_by_id(nexthop->vrf_id); + /* * label_buf is *only* currently used within debugging. * As such when we assign it we are guarding it inside @@ -1347,9 +1356,10 @@ _netlink_route_build_multipath(const struct prefix *p, const char *routedesc, if (IS_ZEBRA_DEBUG_KERNEL) zlog_debug( - " 5549: netlink_route_build_multipath() (%s): %pFX nexthop via %s %s if %u", + " 5549: netlink_route_build_multipath() (%s): %pFX nexthop via %s %s if %u vrf %s(%u)", routedesc, p, ipv4_ll_buf, label_buf, - nexthop->ifindex); + nexthop->ifindex, VRF_LOGNAME(vrf), + nexthop->vrf_id); return; } @@ -1365,9 +1375,10 @@ _netlink_route_build_multipath(const struct prefix *p, const char *routedesc, if (IS_ZEBRA_DEBUG_KERNEL) zlog_debug( - "netlink_route_multipath() (%s): %pFX nexthop via %s %s if %u", + "netlink_route_multipath() (%s): %pFX nexthop via %s %s if %u vrf %s(%u)", routedesc, p, inet_ntoa(nexthop->gate.ipv4), - label_buf, nexthop->ifindex); + label_buf, nexthop->ifindex, VRF_LOGNAME(vrf), + nexthop->vrf_id); } if (nexthop->type == NEXTHOP_TYPE_IPV6 || nexthop->type == NEXTHOP_TYPE_IPV6_IFINDEX) { @@ -1382,9 +1393,10 @@ _netlink_route_build_multipath(const struct prefix *p, const char *routedesc, if (IS_ZEBRA_DEBUG_KERNEL) zlog_debug( - "netlink_route_multipath() (%s): %pFX nexthop via %s %s if %u", + "netlink_route_multipath() (%s): %pFX nexthop via %s %s if %u vrf %s(%u)", routedesc, p, inet6_ntoa(nexthop->gate.ipv6), - label_buf, nexthop->ifindex); + label_buf, nexthop->ifindex, VRF_LOGNAME(vrf), + nexthop->vrf_id); } /* @@ -1404,8 +1416,9 @@ _netlink_route_build_multipath(const struct prefix *p, const char *routedesc, if (IS_ZEBRA_DEBUG_KERNEL) zlog_debug( - "netlink_route_multipath() (%s): %pFX nexthop via if %u", - routedesc, p, nexthop->ifindex); + "netlink_route_multipath() (%s): %pFX nexthop via if %u vrf %s(%u)", + routedesc, p, nexthop->ifindex, + VRF_LOGNAME(vrf), nexthop->vrf_id); } if (nexthop->weight) @@ -1461,9 +1474,9 @@ static void _netlink_route_debug(int cmd, const struct prefix *p, if (IS_ZEBRA_DEBUG_KERNEL) { char buf[PREFIX_STRLEN]; zlog_debug( - "netlink_route_multipath(): %s %s vrf %u(%u)", + "netlink_route_multipath(): %s %s vrf %s(%u) table_id: %u", nl_msg_type_to_str(cmd), - prefix2str(p, buf, sizeof(buf)), + prefix2str(p, buf, sizeof(buf)), vrf_id_to_name(vrfid), vrfid, tableid); } } @@ -2077,10 +2090,10 @@ static int netlink_nexthop(int cmd, struct zebra_dplane_ctx *ctx) nexthop_done: if (IS_ZEBRA_DEBUG_KERNEL) - zlog_debug("%s: ID (%u): %pNHv (%u) %s ", - __func__, id, nh, nh->vrf_id, - label_buf); - + zlog_debug("%s: ID (%u): %pNHv vrf %s(%u) %s ", + __func__, id, nh, + vrf_id_to_name(nh->vrf_id), + nh->vrf_id, label_buf); } req.nhm.nh_protocol = zebra2proto(dplane_ctx_get_nhe_type(ctx)); @@ -2881,10 +2894,12 @@ static int netlink_request_specific_mac_in_bridge(struct zebra_ns *zns, addattr32(&req.n, sizeof(req), NDA_MASTER, br_if->ifindex); if (IS_ZEBRA_DEBUG_KERNEL) - zlog_debug("%s: Tx family %s IF %s(%u) MAC %s vid %u", __func__, - nl_family_to_str(req.ndm.ndm_family), br_if->name, - br_if->ifindex, - prefix_mac2str(mac, buf, sizeof(buf)), vid); + zlog_debug( + "%s: Tx family %s IF %s(%u) vrf %s(%u) MAC %s vid %u", + __func__, nl_family_to_str(req.ndm.ndm_family), + br_if->name, br_if->ifindex, + vrf_id_to_name(br_if->vrf_id), br_if->vrf_id, + prefix_mac2str(mac, buf, sizeof(buf)), vid); return netlink_request(&zns->netlink_cmd, &req.n); } @@ -3000,6 +3015,7 @@ static int netlink_ipneigh_change(struct nlmsghdr *h, int len, ns_id_t ns_id) struct interface *link_if; struct ethaddr mac; struct ipaddr ip; + struct vrf *vrf; char buf[ETHER_ADDR_STRLEN]; char buf2[INET6_ADDRSTRLEN]; int mac_present = 0; @@ -3014,6 +3030,7 @@ static int netlink_ipneigh_change(struct nlmsghdr *h, int len, ns_id_t ns_id) if (!ifp || !ifp->info) return 0; + vrf = vrf_lookup_by_id(ifp->vrf_id); zif = (struct zebra_if *)ifp->info; /* Parse attributes and extract fields of interest. */ @@ -3021,10 +3038,10 @@ static int netlink_ipneigh_change(struct nlmsghdr *h, int len, ns_id_t ns_id) netlink_parse_rtattr(tb, NDA_MAX, NDA_RTA(ndm), len); if (!tb[NDA_DST]) { - zlog_debug("%s family %s IF %s(%u) - no DST", + zlog_debug("%s family %s IF %s(%u) vrf %s(%u) - no DST", nl_msg_type_to_str(h->nlmsg_type), nl_family_to_str(ndm->ndm_family), ifp->name, - ndm->ndm_ifindex); + ndm->ndm_ifindex, VRF_LOGNAME(vrf), ifp->vrf_id); return 0; } @@ -3076,12 +3093,13 @@ static int netlink_ipneigh_change(struct nlmsghdr *h, int len, ns_id_t ns_id) if (RTA_PAYLOAD(tb[NDA_LLADDR]) != ETH_ALEN) { if (IS_ZEBRA_DEBUG_KERNEL) zlog_debug( - "%s family %s IF %s(%u) - LLADDR is not MAC, len %lu", + "%s family %s IF %s(%u) vrf %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, + VRF_LOGNAME(vrf), ifp->vrf_id, (unsigned long)RTA_PAYLOAD( tb[NDA_LLADDR])); return 0; @@ -3096,10 +3114,10 @@ static int netlink_ipneigh_change(struct nlmsghdr *h, int len, ns_id_t ns_id) if (IS_ZEBRA_DEBUG_KERNEL) zlog_debug( - "Rx %s family %s IF %s(%u) IP %s MAC %s state 0x%x flags 0x%x", + "Rx %s family %s IF %s(%u) vrf %s(%u) IP %s MAC %s state 0x%x flags 0x%x", nl_msg_type_to_str(h->nlmsg_type), nl_family_to_str(ndm->ndm_family), ifp->name, - ndm->ndm_ifindex, + ndm->ndm_ifindex, VRF_LOGNAME(vrf), ifp->vrf_id, ipaddr2str(&ip, buf2, sizeof(buf2)), mac_present ? prefix_mac2str(&mac, buf, sizeof(buf)) @@ -3121,10 +3139,10 @@ static int netlink_ipneigh_change(struct nlmsghdr *h, int len, ns_id_t ns_id) } if (IS_ZEBRA_DEBUG_KERNEL) - zlog_debug("Rx %s family %s IF %s(%u) IP %s", + zlog_debug("Rx %s family %s IF %s(%u) vrf %s(%u) IP %s", nl_msg_type_to_str(h->nlmsg_type), nl_family_to_str(ndm->ndm_family), ifp->name, - ndm->ndm_ifindex, + ndm->ndm_ifindex, VRF_LOGNAME(vrf), ifp->vrf_id, ipaddr2str(&ip, buf2, sizeof(buf2))); /* Process the delete - it may result in re-adding the neighbor if it is @@ -3278,9 +3296,10 @@ int netlink_neigh_read_specific_ip(struct ipaddr *ip, zebra_dplane_info_from_zns(&dp_info, zns, true /*is_cmd*/); if (IS_ZEBRA_DEBUG_KERNEL) - zlog_debug("%s: neigh request IF %s(%u) IP %s vrf_id %u", + zlog_debug("%s: neigh request IF %s(%u) IP %s vrf %s(%u)", __func__, vlan_if->name, vlan_if->ifindex, - ipaddr2str(ip, buf, sizeof(buf)), vlan_if->vrf_id); + ipaddr2str(ip, buf, sizeof(buf)), + vrf_id_to_name(vlan_if->vrf_id), vlan_if->vrf_id); ret = netlink_request_specific_neigh_in_vlan(zns, RTM_GETNEIGH, ip, vlan_if->ifindex); diff --git a/zebra/zebra_rib.c b/zebra/zebra_rib.c index 80116fca18..2dbe907751 100644 --- a/zebra/zebra_rib.c +++ b/zebra/zebra_rib.c @@ -348,8 +348,8 @@ struct route_entry *rib_match_ipv4_multicast(vrf_id_t vrf_id, char buf[BUFSIZ]; inet_ntop(AF_INET, &addr, buf, BUFSIZ); - zlog_debug("%s: %s: vrf: %u found %s, using %s", - __func__, buf, vrf_id, + zlog_debug("%s: %s: vrf: %s(%u) found %s, using %s", __func__, + buf, vrf_id_to_name(vrf_id), vrf_id, mre ? (ure ? "MRIB+URIB" : "MRIB") : ure ? "URIB" : "nothing", re == ure ? "URIB" : re == mre ? "MRIB" : "none"); @@ -659,13 +659,14 @@ void zebra_rib_evaluate_rn_nexthops(struct route_node *rn, uint32_t seq) char buf1[PREFIX_STRLEN]; char buf2[PREFIX_STRLEN]; - zlog_debug("%u:%s has Nexthop(%s) Type: %s depending on it, evaluating %u:%u", - zvrf->vrf->vrf_id, - srcdest_rnode2str(rn, buf1, - sizeof(buf1)), - prefix2str(p, buf2, sizeof(buf2)), - rnh_type2str(rnh->type), - seq, rnh->seqno); + zlog_debug( + "%s(%u):%s has Nexthop(%s) Type: %s depending on it, evaluating %u:%u", + zvrf_name(zvrf), zvrf_id(zvrf), + srcdest_rnode2str(rn, buf1, + sizeof(buf1)), + prefix2str(p, buf2, sizeof(buf2)), + rnh_type2str(rnh->type), seq, + rnh->seqno); } /* @@ -753,8 +754,8 @@ static void rib_process_add_fib(struct zebra_vrf *zvrf, struct route_node *rn, if (IS_ZEBRA_DEBUG_RIB) { char buf[SRCDEST2STR_BUFFER]; srcdest_rnode2str(rn, buf, sizeof(buf)); - zlog_debug("%u:%s: Adding route rn %p, re %p (%s)", - zvrf_id(zvrf), buf, rn, new, + zlog_debug("%s(%u):%s: Adding route rn %p, re %p (%s)", + zvrf_name(zvrf), zvrf_id(zvrf), buf, rn, new, zebra_route_string(new->type)); } @@ -776,8 +777,8 @@ static void rib_process_del_fib(struct zebra_vrf *zvrf, struct route_node *rn, if (IS_ZEBRA_DEBUG_RIB) { char buf[SRCDEST2STR_BUFFER]; srcdest_rnode2str(rn, buf, sizeof(buf)); - zlog_debug("%u:%s: Deleting route rn %p, re %p (%s)", - zvrf_id(zvrf), buf, rn, old, + zlog_debug("%s(%u):%s: Deleting route rn %p, re %p (%s)", + zvrf_name(zvrf), zvrf_id(zvrf), buf, rn, old, zebra_route_string(old->type)); } @@ -829,15 +830,17 @@ static void rib_process_update_fib(struct zebra_vrf *zvrf, srcdest_rnode2str(rn, buf, sizeof(buf)); if (new != old) zlog_debug( - "%u:%s: Updating route rn %p, re %p (%s) old %p (%s)", - zvrf_id(zvrf), buf, rn, new, + "%s(%u):%s: Updating route rn %p, re %p (%s) old %p (%s)", + zvrf_name(zvrf), zvrf_id(zvrf), + buf, rn, new, zebra_route_string(new->type), old, zebra_route_string(old->type)); else zlog_debug( - "%u:%s: Updating route rn %p, re %p (%s)", - zvrf_id(zvrf), buf, rn, new, + "%s(%u):%s: Updating route rn %p, re %p (%s)", + zvrf_name(zvrf), zvrf_id(zvrf), + buf, rn, new, zebra_route_string(new->type)); } @@ -867,15 +870,17 @@ static void rib_process_update_fib(struct zebra_vrf *zvrf, srcdest_rnode2str(rn, buf, sizeof(buf)); if (new != old) zlog_debug( - "%u:%s: Deleting route rn %p, re %p (%s) old %p (%s) - nexthop inactive", - zvrf_id(zvrf), buf, rn, new, + "%s(%u):%s: Deleting route rn %p, re %p (%s) old %p (%s) - nexthop inactive", + zvrf_name(zvrf), zvrf_id(zvrf), + buf, rn, new, zebra_route_string(new->type), old, zebra_route_string(old->type)); else zlog_debug( - "%u:%s: Deleting route rn %p, re %p (%s) - nexthop inactive", - zvrf_id(zvrf), buf, rn, new, + "%s(%u):%s: Deleting route rn %p, re %p (%s) - nexthop inactive", + zvrf_name(zvrf), zvrf_id(zvrf), + buf, rn, new, zebra_route_string(new->type)); } @@ -990,6 +995,7 @@ static void rib_process(struct route_node *rn) char buf[SRCDEST2STR_BUFFER]; rib_dest_t *dest; struct zebra_vrf *zvrf = NULL; + struct vrf *vrf; const struct prefix *p, *src_p; srcdest_rnode_prefixes(rn, &p, &src_p); @@ -1003,11 +1009,14 @@ static void rib_process(struct route_node *rn) vrf_id = zvrf_id(zvrf); } + vrf = vrf_lookup_by_id(vrf_id); + if (IS_ZEBRA_DEBUG_RIB) srcdest_rnode2str(rn, buf, sizeof(buf)); if (IS_ZEBRA_DEBUG_RIB_DETAILED) - zlog_debug("%u:%s: Processing rn %p", vrf_id, buf, rn); + zlog_debug("%s(%u):%s: Processing rn %p", VRF_LOGNAME(vrf), + vrf_id, buf, rn); /* * we can have rn's that have a NULL info pointer @@ -1021,10 +1030,10 @@ static void rib_process(struct route_node *rn) RNODE_FOREACH_RE_SAFE (rn, re, next) { if (IS_ZEBRA_DEBUG_RIB_DETAILED) zlog_debug( - "%u:%s: Examine re %p (%s) status %x flags %x dist %d metric %d", - vrf_id, buf, re, zebra_route_string(re->type), - re->status, re->flags, re->distance, - re->metric); + "%s(%u):%s: Examine re %p (%s) status %x flags %x dist %d metric %d", + VRF_LOGNAME(vrf), vrf_id, buf, re, + zebra_route_string(re->type), re->status, + re->flags, re->distance, re->metric); /* Currently selected re. */ if (CHECK_FLAG(re->flags, ZEBRA_FLAG_SELECTED)) { @@ -1065,9 +1074,11 @@ static void rib_process(struct route_node *rn) if (re != old_selected) { if (IS_ZEBRA_DEBUG_RIB) zlog_debug( - "%s: %u:%s: imported via import-table but denied " + "%s: %s(%u):%s: imported via import-table but denied " "by the ip protocol table route-map", - __func__, vrf_id, buf); + __func__, + VRF_LOGNAME(vrf), + vrf_id, buf); rib_unlink(rn, re); } else SET_FLAG(re->status, @@ -1118,9 +1129,9 @@ static void rib_process(struct route_node *rn) if (IS_ZEBRA_DEBUG_RIB_DETAILED) { zlog_debug( - "%u:%s: After processing: old_selected %p new_selected %p old_fib %p new_fib %p", - vrf_id, buf, (void *)old_selected, (void *)new_selected, - (void *)old_fib, (void *)new_fib); + "%s(%u):%s: After processing: old_selected %p new_selected %p old_fib %p new_fib %p", + VRF_LOGNAME(vrf), vrf_id, buf, (void *)old_selected, + (void *)new_selected, (void *)old_fib, (void *)new_fib); } /* Buffer ROUTE_ENTRY_CHANGED here, because it will get cleared if @@ -1191,8 +1202,8 @@ static void zebra_rib_evaluate_mpls(struct route_node *rn) if (CHECK_FLAG(dest->flags, RIB_DEST_UPDATE_LSPS)) { if (IS_ZEBRA_DEBUG_MPLS) zlog_debug( - "%u: Scheduling all LSPs upon RIB completion", - zvrf_id(zvrf)); + "%s(%u): Scheduling all LSPs upon RIB completion", + zvrf_name(zvrf), zvrf_id(zvrf)); zebra_mpls_lsp_schedule(zvrf); mpls_unmark_lsps_for_processing(rn); } @@ -1299,6 +1310,9 @@ static bool rib_update_re_from_ctx(struct route_entry *re, bool is_selected = false; /* Is 're' currently the selected re? */ bool changed_p = false; /* Change to nexthops? */ rib_dest_t *dest; + struct vrf *vrf; + + vrf = vrf_lookup_by_id(re->vrf_id); /* Note well: only capturing the prefix string if debug is enabled here; * unconditional log messages will have to generate the string. @@ -1311,8 +1325,9 @@ static bool rib_update_re_from_ctx(struct route_entry *re, is_selected = (re == dest->selected_fib); if (IS_ZEBRA_DEBUG_RIB_DETAILED) - zlog_debug("update_from_ctx: %u:%s: %sSELECTED", - re->vrf_id, dest_str, (is_selected ? "" : "NOT ")); + zlog_debug("update_from_ctx: %s(%u):%s: %sSELECTED", + VRF_LOGNAME(vrf), re->vrf_id, dest_str, + (is_selected ? "" : "NOT ")); /* Update zebra's nexthop FIB flag for each nexthop that was installed. * If the installed set differs from the set requested by the rib/owner, @@ -1325,11 +1340,10 @@ static bool rib_update_re_from_ctx(struct route_entry *re, * Let's assume the nexthops are ordered here to save time. */ if (nexthop_group_equal(&re->fib_ng, dplane_ctx_get_ng(ctx)) == false) { - if (IS_ZEBRA_DEBUG_RIB_DETAILED) { + if (IS_ZEBRA_DEBUG_RIB_DETAILED) zlog_debug( - "%u:%s update_from_ctx: notif nh and fib nh mismatch", - re->vrf_id, dest_str); - } + "%s(%u):%s update_from_ctx: notif nh and fib nh mismatch", + VRF_LOGNAME(vrf), re->vrf_id, dest_str); matched = false; } else @@ -1338,8 +1352,9 @@ static bool rib_update_re_from_ctx(struct route_entry *re, /* If the new FIB set matches the existing FIB set, we're done. */ if (matched) { if (IS_ZEBRA_DEBUG_RIB) - zlog_debug("%u:%s update_from_ctx(): existing fib nhg, no change", - re->vrf_id, dest_str); + zlog_debug( + "%s(%u):%s update_from_ctx(): existing fib nhg, no change", + VRF_LOGNAME(vrf), re->vrf_id, dest_str); goto done; } else if (re->fib_ng.nexthop) { @@ -1347,8 +1362,9 @@ static bool rib_update_re_from_ctx(struct route_entry *re, * Free stale fib list and move on to check the rib nhg. */ if (IS_ZEBRA_DEBUG_RIB) - zlog_debug("%u:%s update_from_ctx(): replacing fib nhg", - re->vrf_id, dest_str); + zlog_debug( + "%s(%u):%s update_from_ctx(): replacing fib nhg", + VRF_LOGNAME(vrf), re->vrf_id, dest_str); nexthops_free(re->fib_ng.nexthop); re->fib_ng.nexthop = NULL; @@ -1356,8 +1372,8 @@ static bool rib_update_re_from_ctx(struct route_entry *re, changed_p = true; } else { if (IS_ZEBRA_DEBUG_RIB) - zlog_debug("%u:%s update_from_ctx(): no fib nhg", - re->vrf_id, dest_str); + zlog_debug("%s(%u):%s update_from_ctx(): no fib nhg", + VRF_LOGNAME(vrf), re->vrf_id, dest_str); } /* @@ -1437,9 +1453,10 @@ static bool rib_update_re_from_ctx(struct route_entry *re, /* If all nexthops were processed, we're done */ if (matched) { if (IS_ZEBRA_DEBUG_RIB) - zlog_debug("%u:%s update_from_ctx(): rib nhg matched, changed '%s'", - re->vrf_id, dest_str, - (changed_p ? "true" : "false")); + zlog_debug( + "%s(%u):%s update_from_ctx(): rib nhg matched, changed '%s'", + VRF_LOGNAME(vrf), re->vrf_id, dest_str, + (changed_p ? "true" : "false")); goto done; } @@ -1449,9 +1466,10 @@ no_nexthops: * create a fib-specific nexthop-group */ if (IS_ZEBRA_DEBUG_RIB) - zlog_debug("%u:%s update_from_ctx(): changed %s, adding new fib nhg", - re->vrf_id, dest_str, - (changed_p ? "true" : "false")); + zlog_debug( + "%s(%u):%s update_from_ctx(): changed %s, adding new fib nhg", + VRF_LOGNAME(vrf), re->vrf_id, dest_str, + (changed_p ? "true" : "false")); ctxnhg = dplane_ctx_get_ng(ctx); @@ -1489,10 +1507,12 @@ rib_find_rn_from_ctx(const struct zebra_dplane_ctx *ctx) dplane_ctx_get_vrf(ctx), dplane_ctx_get_table(ctx)); if (table == NULL) { if (IS_ZEBRA_DEBUG_DPLANE) { - zlog_debug("Failed to find route for ctx: no table for afi %d, safi %d, vrf %u", - dplane_ctx_get_afi(ctx), - dplane_ctx_get_safi(ctx), - dplane_ctx_get_vrf(ctx)); + zlog_debug( + "Failed to find route for ctx: no table for afi %d, safi %d, vrf %s(%u)", + dplane_ctx_get_afi(ctx), + dplane_ctx_get_safi(ctx), + vrf_id_to_name(dplane_ctx_get_vrf(ctx)), + dplane_ctx_get_vrf(ctx)); } goto done; } @@ -1515,6 +1535,7 @@ done: static void rib_process_result(struct zebra_dplane_ctx *ctx) { struct zebra_vrf *zvrf = NULL; + struct vrf *vrf; struct route_node *rn = NULL; struct route_entry *re = NULL, *old_re = NULL, *rib; bool is_update = false; @@ -1526,6 +1547,7 @@ static void rib_process_result(struct zebra_dplane_ctx *ctx) bool fib_changed = false; zvrf = vrf_info_lookup(dplane_ctx_get_vrf(ctx)); + vrf = vrf_lookup_by_id(dplane_ctx_get_vrf(ctx)); dest_pfx = dplane_ctx_get_dest(ctx); /* Note well: only capturing the prefix string if debug is enabled here; @@ -1538,8 +1560,10 @@ static void rib_process_result(struct zebra_dplane_ctx *ctx) rn = rib_find_rn_from_ctx(ctx); if (rn == NULL) { if (IS_ZEBRA_DEBUG_DPLANE) { - zlog_debug("Failed to process dplane results: no route for %u:%s", - dplane_ctx_get_vrf(ctx), dest_str); + zlog_debug( + "Failed to process dplane results: no route for %s(%u):%s", + VRF_LOGNAME(vrf), dplane_ctx_get_vrf(ctx), + dest_str); } goto done; } @@ -1550,9 +1574,10 @@ static void rib_process_result(struct zebra_dplane_ctx *ctx) status = dplane_ctx_get_status(ctx); if (IS_ZEBRA_DEBUG_DPLANE_DETAIL) - zlog_debug("%u:%s Processing dplane ctx %p, op %s result %s", - dplane_ctx_get_vrf(ctx), dest_str, ctx, - dplane_op2str(op), dplane_res2str(status)); + zlog_debug( + "%s(%u):%s Processing dplane ctx %p, op %s result %s", + VRF_LOGNAME(vrf), dplane_ctx_get_vrf(ctx), dest_str, + ctx, dplane_op2str(op), dplane_res2str(status)); /* * Update is a bit of a special case, where we may have both old and new @@ -1590,9 +1615,10 @@ static void rib_process_result(struct zebra_dplane_ctx *ctx) if (re) { if (re->dplane_sequence != seq) { if (IS_ZEBRA_DEBUG_DPLANE_DETAIL) - zlog_debug("%u:%s Stale dplane result for re %p", - dplane_ctx_get_vrf(ctx), - dest_str, re); + zlog_debug( + "%s(%u):%s Stale dplane result for re %p", + VRF_LOGNAME(vrf), + dplane_ctx_get_vrf(ctx), dest_str, re); } else UNSET_FLAG(re->status, ROUTE_ENTRY_QUEUED); } @@ -1600,9 +1626,11 @@ static void rib_process_result(struct zebra_dplane_ctx *ctx) if (old_re) { if (old_re->dplane_sequence != dplane_ctx_get_old_seq(ctx)) { if (IS_ZEBRA_DEBUG_DPLANE_DETAIL) - zlog_debug("%u:%s Stale dplane result for old_re %p", - dplane_ctx_get_vrf(ctx), - dest_str, old_re); + zlog_debug( + "%s(%u):%s Stale dplane result for old_re %p", + VRF_LOGNAME(vrf), + dplane_ctx_get_vrf(ctx), dest_str, + old_re); } else UNSET_FLAG(old_re->status, ROUTE_ENTRY_QUEUED); } @@ -1639,10 +1667,11 @@ static void rib_process_result(struct zebra_dplane_ctx *ctx) if (!fib_changed) { if (IS_ZEBRA_DEBUG_DPLANE_DETAIL) - zlog_debug("%u:%s no fib change for re", - dplane_ctx_get_vrf( - ctx), - dest_str); + zlog_debug( + "%s(%u):%s no fib change for re", + VRF_LOGNAME(vrf), + dplane_ctx_get_vrf(ctx), + dest_str); } /* Redistribute */ @@ -1677,10 +1706,10 @@ static void rib_process_result(struct zebra_dplane_ctx *ctx) zsend_route_notify_owner(re, dest_pfx, ZAPI_ROUTE_FAIL_INSTALL); - zlog_warn("%u:%s: Route install failed", - dplane_ctx_get_vrf(ctx), - prefix2str(dest_pfx, - dest_str, sizeof(dest_str))); + zlog_warn("%s(%u):%s: Route install failed", + VRF_LOGNAME(vrf), dplane_ctx_get_vrf(ctx), + prefix2str(dest_pfx, dest_str, + sizeof(dest_str))); } break; case DPLANE_OP_ROUTE_DELETE: @@ -1706,10 +1735,10 @@ static void rib_process_result(struct zebra_dplane_ctx *ctx) zsend_route_notify_owner_ctx(ctx, ZAPI_ROUTE_REMOVE_FAIL); - zlog_warn("%u:%s: Route Deletion failure", - dplane_ctx_get_vrf(ctx), - prefix2str(dest_pfx, - dest_str, sizeof(dest_str))); + zlog_warn("%s(%u):%s: Route Deletion failure", + VRF_LOGNAME(vrf), dplane_ctx_get_vrf(ctx), + prefix2str(dest_pfx, dest_str, + sizeof(dest_str))); } /* @@ -1747,6 +1776,7 @@ static void rib_process_dplane_notify(struct zebra_dplane_ctx *ctx) { struct route_node *rn = NULL; struct route_entry *re = NULL; + struct vrf *vrf; struct nexthop *nexthop; char dest_str[PREFIX_STRLEN] = ""; const struct prefix *dest_pfx, *src_pfx; @@ -1755,6 +1785,7 @@ static void rib_process_dplane_notify(struct zebra_dplane_ctx *ctx) bool debug_p = IS_ZEBRA_DEBUG_DPLANE | IS_ZEBRA_DEBUG_RIB; int start_count, end_count; dest_pfx = dplane_ctx_get_dest(ctx); + vrf = vrf_lookup_by_id(dplane_ctx_get_vrf(ctx)); /* Note well: only capturing the prefix string if debug is enabled here; * unconditional log messages will have to generate the string. @@ -1766,8 +1797,10 @@ static void rib_process_dplane_notify(struct zebra_dplane_ctx *ctx) rn = rib_find_rn_from_ctx(ctx); if (rn == NULL) { if (debug_p) { - zlog_debug("Failed to process dplane notification: no routes for %u:%s", - dplane_ctx_get_vrf(ctx), dest_str); + zlog_debug( + "Failed to process dplane notification: no routes for %s(%u):%s", + VRF_LOGNAME(vrf), dplane_ctx_get_vrf(ctx), + dest_str); } goto done; } @@ -1776,8 +1809,9 @@ static void rib_process_dplane_notify(struct zebra_dplane_ctx *ctx) srcdest_rnode_prefixes(rn, &dest_pfx, &src_pfx); if (debug_p) - zlog_debug("%u:%s Processing dplane notif ctx %p", - dplane_ctx_get_vrf(ctx), dest_str, ctx); + zlog_debug("%s(%u):%s Processing dplane notif ctx %p", + VRF_LOGNAME(vrf), dplane_ctx_get_vrf(ctx), dest_str, + ctx); /* * Take a pass through the routes, look for matches with the context @@ -1791,10 +1825,11 @@ static void rib_process_dplane_notify(struct zebra_dplane_ctx *ctx) /* No match? Nothing we can do */ if (re == NULL) { if (debug_p) - zlog_debug("%u:%s Unable to process dplane notification: no entry for type %s", - dplane_ctx_get_vrf(ctx), dest_str, - zebra_route_string( - dplane_ctx_get_type(ctx))); + zlog_debug( + "%s(%u):%s Unable to process dplane notification: no entry for type %s", + VRF_LOGNAME(vrf), dplane_ctx_get_vrf(ctx), + dest_str, + zebra_route_string(dplane_ctx_get_type(ctx))); goto done; } @@ -1824,17 +1859,21 @@ static void rib_process_dplane_notify(struct zebra_dplane_ctx *ctx) if (CHECK_FLAG(re->status, ROUTE_ENTRY_INSTALLED)) UNSET_FLAG(re->status, ROUTE_ENTRY_INSTALLED); if (debug_p) - zlog_debug("%u:%s dplane notif, uninstalled type %s route", - dplane_ctx_get_vrf(ctx), dest_str, - zebra_route_string( - dplane_ctx_get_type(ctx))); + zlog_debug( + "%s(%u):%s dplane notif, uninstalled type %s route", + VRF_LOGNAME(vrf), + dplane_ctx_get_vrf(ctx), dest_str, + zebra_route_string( + dplane_ctx_get_type(ctx))); } else { /* At least report on the event. */ if (debug_p) - zlog_debug("%u:%s dplane notif, but type %s not selected_fib", - dplane_ctx_get_vrf(ctx), dest_str, - zebra_route_string( - dplane_ctx_get_type(ctx))); + zlog_debug( + "%s(%u):%s dplane notif, but type %s not selected_fib", + VRF_LOGNAME(vrf), + dplane_ctx_get_vrf(ctx), dest_str, + zebra_route_string( + dplane_ctx_get_type(ctx))); } goto done; } @@ -1859,8 +1898,10 @@ static void rib_process_dplane_notify(struct zebra_dplane_ctx *ctx) if (!fib_changed) { if (debug_p) - zlog_debug("%u:%s dplane notification: rib_update returns FALSE", - dplane_ctx_get_vrf(ctx), dest_str); + zlog_debug( + "%s(%u):%s dplane notification: rib_update returns FALSE", + VRF_LOGNAME(vrf), dplane_ctx_get_vrf(ctx), + dest_str); } /* @@ -1879,8 +1920,10 @@ static void rib_process_dplane_notify(struct zebra_dplane_ctx *ctx) */ if (start_count > 0 && end_count > 0) { if (debug_p) - zlog_debug("%u:%s applied nexthop changes from dplane notification", - dplane_ctx_get_vrf(ctx), dest_str); + zlog_debug( + "%s(%u):%s applied nexthop changes from dplane notification", + VRF_LOGNAME(vrf), dplane_ctx_get_vrf(ctx), + dest_str); /* Changed nexthops - update kernel/others */ dplane_route_notif_update(rn, re, @@ -1888,8 +1931,10 @@ static void rib_process_dplane_notify(struct zebra_dplane_ctx *ctx) } else if (start_count == 0 && end_count > 0) { if (debug_p) - zlog_debug("%u:%s installed transition from dplane notification", - dplane_ctx_get_vrf(ctx), dest_str); + zlog_debug( + "%s(%u):%s installed transition from dplane notification", + VRF_LOGNAME(vrf), dplane_ctx_get_vrf(ctx), + dest_str); /* We expect this to be the selected route, so we want * to tell others about this transition. @@ -1904,8 +1949,10 @@ static void rib_process_dplane_notify(struct zebra_dplane_ctx *ctx) } else if (start_count > 0 && end_count == 0) { if (debug_p) - zlog_debug("%u:%s un-installed transition from dplane notification", - dplane_ctx_get_vrf(ctx), dest_str); + zlog_debug( + "%s(%u):%s un-installed transition from dplane notification", + VRF_LOGNAME(vrf), dplane_ctx_get_vrf(ctx), + dest_str); /* Transition from _something_ installed to _nothing_ * installed. @@ -1970,8 +2017,8 @@ static void process_subq_route(struct listnode *lnode, uint8_t qindex) char buf[SRCDEST2STR_BUFFER]; srcdest_rnode2str(rnode, buf, sizeof(buf)); - zlog_debug("%u:%s: rn %p dequeued from sub-queue %u", - zvrf ? zvrf_id(zvrf) : 0, buf, rnode, qindex); + zlog_debug("%s(%u):%s: rn %p dequeued from sub-queue %u", + zvrf_name(zvrf), zvrf_id(zvrf), buf, rnode, qindex); } if (rnode->info) @@ -2383,9 +2430,9 @@ void rib_delnode(struct route_node *rn, struct route_entry *re) if (IS_ZEBRA_DEBUG_RIB) { char buf[SRCDEST2STR_BUFFER]; srcdest_rnode2str(rn, buf, sizeof(buf)); - zlog_debug("%u:%s: Freeing route rn %p, re %p (%s)", - re->vrf_id, buf, rn, re, - zebra_route_string(re->type)); + zlog_debug("%s(%u):%s: Freeing route rn %p, re %p (%s)", + vrf_id_to_name(re->vrf_id), re->vrf_id, buf, + rn, re, zebra_route_string(re->type)); } rib_unlink(rn, re); @@ -2515,14 +2562,17 @@ void rib_lookup_and_dump(struct prefix_ipv4 *p, vrf_id_t vrf_id) struct route_table *table; struct route_node *rn; struct route_entry *re; + struct vrf *vrf; char prefix_buf[INET_ADDRSTRLEN]; + vrf = vrf_lookup_by_id(vrf_id); + /* Lookup table. */ table = zebra_vrf_table(AFI_IP, SAFI_UNICAST, vrf_id); if (!table) { flog_err(EC_ZEBRA_TABLE_LOOKUP_FAILED, - "%s:%u zebra_vrf_table() returned NULL", __func__, - vrf_id); + "%s:%s(%u) zebra_vrf_table() returned NULL", __func__, + VRF_LOGNAME(vrf), vrf_id); return; } @@ -2531,7 +2581,8 @@ void rib_lookup_and_dump(struct prefix_ipv4 *p, vrf_id_t vrf_id) /* No route for this prefix. */ if (!rn) { - zlog_debug("%s:%u lookup failed for %s", __func__, vrf_id, + zlog_debug("%s:%s(%u) lookup failed for %s", __func__, + VRF_LOGNAME(vrf), vrf_id, prefix2str((struct prefix *)p, prefix_buf, sizeof(prefix_buf))); return; @@ -2542,9 +2593,8 @@ void rib_lookup_and_dump(struct prefix_ipv4 *p, vrf_id_t vrf_id) /* let's go */ RNODE_FOREACH_RE (rn, re) { - zlog_debug("%s:%u rn %p, re %p: %s, %s", - __func__, vrf_id, - (void *)rn, (void *)re, + zlog_debug("%s:%s(%u) rn %p, re %p: %s, %s", __func__, + VRF_LOGNAME(vrf), vrf_id, (void *)rn, (void *)re, (CHECK_FLAG(re->status, ROUTE_ENTRY_REMOVED) ? "removed" : "NOT removed"), @@ -2567,9 +2617,11 @@ void rib_lookup_and_pushup(struct prefix_ipv4 *p, vrf_id_t vrf_id) rib_dest_t *dest; if (NULL == (table = zebra_vrf_table(AFI_IP, SAFI_UNICAST, vrf_id))) { + struct vrf *vrf = vrf_lookup_by_id(vrf_id); + flog_err(EC_ZEBRA_TABLE_LOOKUP_FAILED, - "%s:%u zebra_vrf_table() returned NULL", __func__, - vrf_id); + "%s:%s(%u) zebra_vrf_table() returned NULL", __func__, + VRF_LOGNAME(vrf), vrf_id); return; } @@ -2592,10 +2644,13 @@ void rib_lookup_and_pushup(struct prefix_ipv4 *p, vrf_id_t vrf_id) if (dest->selected_fib) { if (IS_ZEBRA_DEBUG_RIB) { char buf[PREFIX_STRLEN]; + struct vrf *vrf = + vrf_lookup_by_id(dest->selected_fib->vrf_id); - zlog_debug("%u:%s: freeing way for connected prefix", - dest->selected_fib->vrf_id, - prefix2str(&rn->p, buf, sizeof(buf))); + zlog_debug( + "%s(%u):%s: freeing way for connected prefix", + VRF_LOGNAME(vrf), dest->selected_fib->vrf_id, + prefix2str(&rn->p, buf, sizeof(buf))); route_entry_dump(&rn->p, NULL, dest->selected_fib); } rib_uninstall(rn, dest->selected_fib); @@ -3091,8 +3146,7 @@ void rib_update_table(struct route_table *table, rib_update_event_t event) table->info ? afi2str( ((rib_table_info_t *)table->info)->afi) : "Unknown", - vrf ? vrf->name : "Unknown", - zvrf ? zvrf->table_id : 0, + VRF_LOGNAME(vrf), zvrf ? zvrf->table_id : 0, rib_update_event2str(event)); } diff --git a/zebra/zebra_vrf.h b/zebra/zebra_vrf.h index 5448e17073..268ee12a65 100644 --- a/zebra/zebra_vrf.h +++ b/zebra/zebra_vrf.h @@ -193,7 +193,7 @@ struct zebra_vrf { static inline vrf_id_t zvrf_id(struct zebra_vrf *zvrf) { if (!zvrf || !zvrf->vrf) - return VRF_UNKNOWN; + return VRF_DEFAULT; return zvrf->vrf->vrf_id; } @@ -206,6 +206,8 @@ static inline const char *zvrf_ns_name(struct zebra_vrf *zvrf) static inline const char *zvrf_name(struct zebra_vrf *zvrf) { + if (!zvrf || !zvrf->vrf) + return "Unknown"; return zvrf->vrf->name; }