From e0437aba6d605a41c0471013746e3d9c791ccd20 Mon Sep 17 00:00:00 2001 From: Donald Sharp Date: Wed, 3 Jul 2024 10:29:21 -0400 Subject: [PATCH] zebra: Add more vrf name to debugs Trying to debug some cross vrf stuff in zebra and frankly it's hard to grep the file for the routes you are interested in. Let's clean this up some and get a bit better information for us developers Signed-off-by: Donald Sharp --- zebra/redistribute.c | 5 ++- zebra/zapi_msg.c | 16 ++++--- zebra/zebra_rib.c | 101 +++++++++++++++++++++++-------------------- zebra/zserv.c | 14 +++--- 4 files changed, 75 insertions(+), 61 deletions(-) diff --git a/zebra/redistribute.c b/zebra/redistribute.c index 11c13303987b..2de0917a7e43 100644 --- a/zebra/redistribute.c +++ b/zebra/redistribute.c @@ -290,6 +290,7 @@ void redistribute_delete(const struct route_node *rn, if (IS_ZEBRA_DEBUG_RIB) { uint8_t old_inst, new_inst; uint32_t table = 0; + struct vrf *vrf = vrf_lookup_by_id(vrfid); old_inst = new_inst = 0; @@ -302,8 +303,8 @@ void redistribute_delete(const struct route_node *rn, table = new_re->table; } - zlog_debug("(%u:%u):%pRN: Redist del: re %p (%u:%s), new re %p (%u:%s)", - vrfid, table, rn, old_re, old_inst, + zlog_debug("(%s:%u):%pRN: Redist del: re %p (%u:%s), new re %p (%u:%s)", + VRF_LOGNAME(vrf), table, rn, old_re, old_inst, old_re ? zebra_route_string(old_re->type) : "None", new_re, new_inst, new_re ? zebra_route_string(new_re->type) : "None"); diff --git a/zebra/zapi_msg.c b/zebra/zapi_msg.c index aecbba2ebc5f..c45c61a208ac 100644 --- a/zebra/zapi_msg.c +++ b/zebra/zapi_msg.c @@ -735,11 +735,13 @@ static int route_notify_internal(const struct route_node *rn, int type, client = zserv_find_client(type, instance); if (!client || !client->notify_owner) { - if (IS_ZEBRA_DEBUG_PACKET) - zlog_debug( - "Not Notifying Owner: %s about prefix %pRN(%u) %d vrf: %u", - zebra_route_string(type), rn, table_id, note, - vrf_id); + if (IS_ZEBRA_DEBUG_PACKET) { + struct vrf *vrf = vrf_lookup_by_id(vrf_id); + + zlog_debug("Not Notifying Owner: %s about prefix %pRN(%u) %d vrf: %s", + zebra_route_string(type), rn, table_id, note, + VRF_LOGNAME(vrf)); + } return 0; } @@ -2129,8 +2131,8 @@ static void zread_route_add(ZAPI_HANDLER_ARGS) vrf_id = zvrf_id(zvrf); if (IS_ZEBRA_DEBUG_RECV) - zlog_debug("%s: p=(%u:%u)%pFX, msg flags=0x%x, flags=0x%x", - __func__, vrf_id, api.tableid, &api.prefix, + zlog_debug("%s: p=(%s:%u)%pFX, msg flags=0x%x, flags=0x%x", + __func__, zvrf_name(zvrf), api.tableid, &api.prefix, (int)api.message, api.flags); /* Allocate new route. */ diff --git a/zebra/zebra_rib.c b/zebra/zebra_rib.c index 8bec32b85d7c..402a3104b941 100644 --- a/zebra/zebra_rib.c +++ b/zebra/zebra_rib.c @@ -316,12 +316,18 @@ static ssize_t printfrr_zebra_node(struct fbuf *buf, struct printfrr_eargs *ea, } #define rnode_debug(node, vrf_id, msg, ...) \ - zlog_debug("%s: (%u:%pZNt):%pZN: " msg, __func__, vrf_id, node, node, \ - ##__VA_ARGS__) + do { \ + struct vrf *vrf = vrf_lookup_by_id(vrf_id); \ + zlog_debug("%s: (%s:%pZNt):%pZN: " msg, __func__, \ + VRF_LOGNAME(vrf), node, node, ##__VA_ARGS__); \ + } while (0) #define rnode_info(node, vrf_id, msg, ...) \ - zlog_info("%s: (%u:%pZNt):%pZN: " msg, __func__, vrf_id, node, node, \ - ##__VA_ARGS__) + do { \ + struct vrf *vrf = vrf_lookup_by_id(vrf_id); \ + zlog_info("%s: (%s:%pZNt):%pZN: " msg, __func__, \ + VRF_LOGNAME(vrf), node, node, ##__VA_ARGS__); \ + } while (0) static char *_dump_re_status(const struct route_entry *re, char *buf, size_t len) @@ -4113,7 +4119,7 @@ void rib_delnode(struct route_node *rn, struct route_entry *re) * Helper that debugs a single nexthop within a route-entry */ static void _route_entry_dump_nh(const struct route_entry *re, - const char *straddr, + const char *straddr, const struct vrf *re_vrf, const struct nexthop *nexthop) { char nhname[PREFIX_STRLEN]; @@ -4168,35 +4174,32 @@ static void _route_entry_dump_nh(const struct route_entry *re, if (nexthop->weight) snprintf(wgt_str, sizeof(wgt_str), "wgt %d,", nexthop->weight); - zlog_debug("%s: %s %s[%u] %svrf %s(%u) %s%s with flags %s%s%s%s%s%s%s%s%s", - straddr, (nexthop->rparent ? " NH" : "NH"), nhname, - nexthop->ifindex, label_str, vrf ? vrf->name : "Unknown", - nexthop->vrf_id, + zlog_debug("%s(%s): %s %s[%u] %svrf %s(%u) %s%s with flags %s%s%s%s%s%s%s%s%s", + straddr, VRF_LOGNAME(re_vrf), + (nexthop->rparent ? " NH" : "NH"), nhname, nexthop->ifindex, + label_str, vrf ? vrf->name : "Unknown", nexthop->vrf_id, wgt_str, backup_str, - (CHECK_FLAG(nexthop->flags, NEXTHOP_FLAG_ACTIVE) - ? "ACTIVE " - : ""), - (CHECK_FLAG(re->status, ROUTE_ENTRY_INSTALLED) - ? "FIB " - : ""), + (CHECK_FLAG(nexthop->flags, NEXTHOP_FLAG_ACTIVE) ? "ACTIVE " + : ""), + (CHECK_FLAG(re->status, ROUTE_ENTRY_INSTALLED) ? "FIB " : ""), (CHECK_FLAG(nexthop->flags, NEXTHOP_FLAG_RECURSIVE) - ? "RECURSIVE " - : ""), - (CHECK_FLAG(nexthop->flags, NEXTHOP_FLAG_ONLINK) - ? "ONLINK " - : ""), + ? "RECURSIVE " + : ""), + (CHECK_FLAG(nexthop->flags, NEXTHOP_FLAG_ONLINK) ? "ONLINK " + : ""), (CHECK_FLAG(nexthop->flags, NEXTHOP_FLAG_DUPLICATE) - ? "DUPLICATE " - : ""), + ? "DUPLICATE " + : ""), (CHECK_FLAG(nexthop->flags, NEXTHOP_FLAG_RNH_FILTERED) - ? "FILTERED " : ""), + ? "FILTERED " + : ""), (CHECK_FLAG(nexthop->flags, NEXTHOP_FLAG_HAS_BACKUP) - ? "BACKUP " : ""), - (CHECK_FLAG(nexthop->flags, NEXTHOP_FLAG_SRTE) - ? "SRTE " : ""), - (CHECK_FLAG(nexthop->flags, NEXTHOP_FLAG_EVPN) - ? "EVPN " : "")); - + ? "BACKUP " + : ""), + (CHECK_FLAG(nexthop->flags, NEXTHOP_FLAG_SRTE) ? "SRTE " + : ""), + (CHECK_FLAG(nexthop->flags, NEXTHOP_FLAG_EVPN) ? "EVPN " + : "")); } /* This function dumps the contents of a given RE entry into @@ -4225,32 +4228,33 @@ void _route_entry_dump(const char *func, union prefixconstptr pp, is_srcdst ? prefix2str(src_pp, srcaddr, sizeof(srcaddr)) : "", VRF_LOGNAME(vrf), re->vrf_id); - zlog_debug("%s: uptime == %lu, type == %u, instance == %d, table == %d", - straddr, (unsigned long)re->uptime, re->type, re->instance, - re->table); - zlog_debug( - "%s: metric == %u, mtu == %u, distance == %u, flags == %sstatus == %s", - straddr, re->metric, re->mtu, re->distance, - zclient_dump_route_flags(re->flags, flags_buf, - sizeof(flags_buf)), - _dump_re_status(re, status_buf, sizeof(status_buf))); - zlog_debug("%s: tag == %u, nexthop_num == %u, nexthop_active_num == %u", - straddr, re->tag, nexthop_group_nexthop_num(&(re->nhe->nhg)), + zlog_debug("%s(%s): uptime == %lu, type == %u, instance == %d, table == %d", + straddr, VRF_LOGNAME(vrf), (unsigned long)re->uptime, + re->type, re->instance, re->table); + zlog_debug("%s(%s): metric == %u, mtu == %u, distance == %u, flags == %sstatus == %s", + straddr, VRF_LOGNAME(vrf), re->metric, re->mtu, re->distance, + zclient_dump_route_flags(re->flags, flags_buf, + sizeof(flags_buf)), + _dump_re_status(re, status_buf, sizeof(status_buf))); + zlog_debug("%s(%s): tag == %u, nexthop_num == %u, nexthop_active_num == %u", + straddr, VRF_LOGNAME(vrf), re->tag, + nexthop_group_nexthop_num(&(re->nhe->nhg)), nexthop_group_active_nexthop_num(&(re->nhe->nhg))); /* Dump nexthops */ for (ALL_NEXTHOPS(re->nhe->nhg, nexthop)) - _route_entry_dump_nh(re, straddr, nexthop); + _route_entry_dump_nh(re, straddr, vrf, nexthop); if (zebra_nhg_get_backup_nhg(re->nhe)) { - zlog_debug("%s: backup nexthops:", straddr); + zlog_debug("%s(%s): backup nexthops:", straddr, + VRF_LOGNAME(vrf)); nhg = zebra_nhg_get_backup_nhg(re->nhe); for (ALL_NEXTHOPS_PTR(nhg, nexthop)) - _route_entry_dump_nh(re, straddr, nexthop); + _route_entry_dump_nh(re, straddr, vrf, nexthop); } - zlog_debug("%s: dump complete", straddr); + zlog_debug("%s(%s): dump complete", straddr, VRF_LOGNAME(vrf)); } static int rib_meta_queue_gr_run_add(struct meta_queue *mq, void *data) @@ -4271,11 +4275,14 @@ static int rib_meta_queue_early_route_add(struct meta_queue *mq, void *data) listnode_add(mq->subq[META_QUEUE_EARLY_ROUTE], data); mq->size++; - if (IS_ZEBRA_DEBUG_RIB_DETAILED) - zlog_debug("Route %pFX(%u) (%s) queued for processing into sub-queue %s", - &ere->p, ere->re->vrf_id, + if (IS_ZEBRA_DEBUG_RIB_DETAILED) { + struct vrf *vrf = vrf_lookup_by_id(ere->re->vrf_id); + + zlog_debug("Route %pFX(%s) (%s) queued for processing into sub-queue %s", + &ere->p, VRF_LOGNAME(vrf), ere->deletion ? "delete" : "add", subqueue2str(META_QUEUE_EARLY_ROUTE)); + } return 0; } diff --git a/zebra/zserv.c b/zebra/zserv.c index a731f7f278fd..07e399664316 100644 --- a/zebra/zserv.c +++ b/zebra/zserv.c @@ -161,9 +161,11 @@ void zserv_log_message(const char *errmsg, struct stream *msg, if (errmsg) zlog_debug("%s", errmsg); if (hdr) { + struct vrf *vrf = vrf_lookup_by_id(hdr->vrf_id); + zlog_debug(" Length: %d", hdr->length); zlog_debug("Command: %s", zserv_command_string(hdr->command)); - zlog_debug(" VRF: %u", hdr->vrf_id); + zlog_debug(" VRF: %s(%u)", VRF_LOGNAME(vrf), hdr->vrf_id); } stream_hexdump(msg); } @@ -425,11 +427,13 @@ static void zserv_read(struct event *thread) } /* Debug packet information. */ - if (IS_ZEBRA_DEBUG_PACKET) - zlog_debug("zebra message[%s:%u:%u] comes from socket [%d]", + if (IS_ZEBRA_DEBUG_PACKET) { + struct vrf *vrf = vrf_lookup_by_id(hdr.vrf_id); + + zlog_debug("zebra message[%s:%s:%u] comes from socket [%d]", zserv_command_string(hdr.command), - hdr.vrf_id, hdr.length, - sock); + VRF_LOGNAME(vrf), hdr.length, sock); + } stream_set_getp(client->ibuf_work, 0); struct stream *msg = stream_dup(client->ibuf_work);