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

4 files changed, 75 insertions, 61 deletions

diff --git a/zebra/redistribute.c b/zebra/redistribute.c
index 11c1330398..2de0917a7e 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 aecbba2ebc..c45c61a208 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 8bec32b85d..402a3104b9 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 a731f7f278..07e3996643 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);