Merge pull request #6951 from donaldsharp/zebra_table

zebra: Add table id to debug output

3 files changed, 125 insertions, 79 deletions

diff --git a/zebra/redistribute.c b/zebra/redistribute.c
index 4d6346151a..0b97562424 100644
--- a/zebra/redistribute.c
+++ b/zebra/redistribute.c
@@ -200,8 +200,8 @@ void redistribute_update(const struct prefix *p, const struct prefix *src_p,
 
 	if (IS_ZEBRA_DEBUG_RIB) {
 		zlog_debug(
-			"%u:%s: Redist update re %p (%s), old %p (%s)",
-			re->vrf_id, prefix2str(p, buf, sizeof(buf)),
+			"(%u:%u):%s: Redist update re %p (%s), old %p (%s)",
+			re->vrf_id, re->table, prefix2str(p, buf, sizeof(buf)),
 			re, zebra_route_string(re->type), prev_re,
 			prev_re ? zebra_route_string(prev_re->type) : "None");
 	}
@@ -224,12 +224,12 @@ void redistribute_update(const struct prefix *p, const struct prefix *src_p,
 		if (zebra_redistribute_check(re, client, p, afi)) {
 			if (IS_ZEBRA_DEBUG_RIB) {
 				zlog_debug(
-					   "%s: client %s %s(%u), type=%d, distance=%d, metric=%d",
-					   __func__,
-					   zebra_route_string(client->proto),
-					   prefix2str(p, buf, sizeof(buf)),
-					   re->vrf_id, re->type,
-					   re->distance, re->metric);
+					"%s: client %s %s(%u:%u), type=%d, distance=%d, metric=%d",
+					__func__,
+					zebra_route_string(client->proto),
+					prefix2str(p, buf, sizeof(buf)),
+					re->vrf_id, re->table, re->type,
+					re->distance, re->metric);
 			}
 			zsend_redistribute_route(ZEBRA_REDISTRIBUTE_ROUTE_ADD,
 						 client, p, src_p, re);
diff --git a/zebra/zapi_msg.c b/zebra/zapi_msg.c
index 285f28ccec..2bcb3502d5 100644
--- a/zebra/zapi_msg.c
+++ b/zebra/zapi_msg.c
@@ -1588,16 +1588,17 @@ static void zread_route_add(ZAPI_HANDLER_ARGS)
 		return;
 	}
 
+	vrf_id = zvrf_id(zvrf);
+
 	if (IS_ZEBRA_DEBUG_RECV) {
 		char buf_prefix[PREFIX_STRLEN];
 
 		prefix2str(&api.prefix, buf_prefix, sizeof(buf_prefix));
-		zlog_debug("%s: p=%s, msg flags=0x%x, flags=0x%x",
-			   __func__, buf_prefix, (int)api.message, api.flags);
+		zlog_debug("%s: p=(%u:%u)%s, msg flags=0x%x, flags=0x%x",
+			   __func__, vrf_id, api.tableid, buf_prefix, (int)api.message, api.flags);
 	}
 
 	/* Allocate new route. */
-	vrf_id = zvrf_id(zvrf);
 	re = XCALLOC(MTYPE_RE, sizeof(struct route_entry));
 	re->type = api.type;
 	re->instance = api.instance;
@@ -1878,6 +1879,15 @@ static void zread_route_del(ZAPI_HANDLER_ARGS)
 	else
 		table_id = zvrf->table_id;
 
+	if (IS_ZEBRA_DEBUG_RECV) {
+		char buf_prefix[PREFIX_STRLEN];
+
+		prefix2str(&api.prefix, buf_prefix, sizeof(buf_prefix));
+		zlog_debug("%s: p=(%u:%u)%s, msg flags=0x%x, flags=0x%x",
+			   __func__, zvrf_id(zvrf), table_id, buf_prefix,
+			   (int)api.message, api.flags);
+	}
+
 	rib_delete(afi, api.safi, zvrf_id(zvrf), api.type, api.instance,
 		   api.flags, &api.prefix, src_p, NULL, 0, table_id, api.metric,
 		   api.distance, false);
diff --git a/zebra/zebra_rib.c b/zebra/zebra_rib.c
index d1d56f2cdb..abc3ba5f33 100644
--- a/zebra/zebra_rib.c
+++ b/zebra/zebra_rib.c
@@ -120,6 +120,7 @@ _rnode_zlog(const char *_func, vrf_id_t vrf_id, struct route_node *rn,
 	char buf[SRCDEST2STR_BUFFER + sizeof(" (MRIB)")];
 	char msgbuf[512];
 	va_list ap;
+	uint32_t table = 0;
 
 	va_start(ap, msgfmt);
 	vsnprintf(msgbuf, sizeof(msgbuf), msgfmt, ap);
@@ -127,15 +128,24 @@ _rnode_zlog(const char *_func, vrf_id_t vrf_id, struct route_node *rn,
 
 	if (rn) {
 		struct rib_table_info *info = srcdest_rnode_table_info(rn);
+		rib_dest_t *dest = NULL;
+		struct route_entry *re = NULL;
+
 		srcdest_rnode2str(rn, buf, sizeof(buf));
 
 		if (info->safi == SAFI_MULTICAST)
 			strlcat(buf, " (MRIB)", sizeof(buf));
+
+		dest = rib_dest_from_rnode(rn);
+		if (dest)
+			re = re_list_first(&dest->routes);
+		if (re)
+			table = re->table;
 	} else {
 		snprintf(buf, sizeof(buf), "{(route_node *) NULL}");
 	}
 
-	zlog(priority, "%s: %d:%s: %s", _func, vrf_id, buf, msgbuf);
+	zlog(priority, "%s: (%u:%u):%s: %s", _func, vrf_id, table, buf, msgbuf);
 }
 
 #define rnode_debug(node, vrf_id, ...)                                         \
@@ -758,9 +768,9 @@ 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("%s(%u):%s: Adding route rn %p, re %p (%s)",
-			   zvrf_name(zvrf), zvrf_id(zvrf), buf, rn, new,
-			   zebra_route_string(new->type));
+		zlog_debug("%s(%u:%u):%s: Adding route rn %p, re %p (%s)",
+			   zvrf_name(zvrf), zvrf_id(zvrf), new->table, buf, rn,
+			   new, zebra_route_string(new->type));
 	}
 
 	/* If labeled-unicast route, install transit LSP. */
@@ -781,9 +791,9 @@ 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("%s(%u):%s: Deleting route rn %p, re %p (%s)",
-			   zvrf_name(zvrf), zvrf_id(zvrf), buf, rn, old,
-			   zebra_route_string(old->type));
+		zlog_debug("%s(%u:%u):%s: Deleting route rn %p, re %p (%s)",
+			   zvrf_name(zvrf), zvrf_id(zvrf), old->table, buf, rn,
+			   old, zebra_route_string(old->type));
 	}
 
 	/* If labeled-unicast route, uninstall transit LSP. */
@@ -834,17 +844,17 @@ static void rib_process_update_fib(struct zebra_vrf *zvrf,
 				srcdest_rnode2str(rn, buf, sizeof(buf));
 				if (new != old)
 					zlog_debug(
-						"%s(%u):%s: Updating route rn %p, re %p (%s) old %p (%s)",
+						"%s(%u:%u):%s: Updating route rn %p, re %p (%s) old %p (%s)",
 						zvrf_name(zvrf), zvrf_id(zvrf),
-						buf, rn, new,
+						new->table, buf, rn, new,
 						zebra_route_string(new->type),
 						old,
 						zebra_route_string(old->type));
 				else
 					zlog_debug(
-						"%s(%u):%s: Updating route rn %p, re %p (%s)",
+						"%s(%u:%u):%s: Updating route rn %p, re %p (%s)",
 						zvrf_name(zvrf), zvrf_id(zvrf),
-						buf, rn, new,
+						new->table, buf, rn, new,
 						zebra_route_string(new->type));
 			}
 
@@ -874,17 +884,17 @@ static void rib_process_update_fib(struct zebra_vrf *zvrf,
 				srcdest_rnode2str(rn, buf, sizeof(buf));
 				if (new != old)
 					zlog_debug(
-						"%s(%u):%s: Deleting route rn %p, re %p (%s) old %p (%s) - nexthop inactive",
+						"%s(%u:%u):%s: Deleting route rn %p, re %p (%s) old %p (%s) - nexthop inactive",
 						zvrf_name(zvrf), zvrf_id(zvrf),
-						buf, rn, new,
+						new->table, buf, rn, new,
 						zebra_route_string(new->type),
 						old,
 						zebra_route_string(old->type));
 				else
 					zlog_debug(
-						"%s(%u):%s: Deleting route rn %p, re %p (%s) - nexthop inactive",
+						"%s(%u:%u):%s: Deleting route rn %p, re %p (%s) - nexthop inactive",
 						zvrf_name(zvrf), zvrf_id(zvrf),
-						buf, rn, new,
+						new->table, buf, rn, new,
 						zebra_route_string(new->type));
 			}
 
@@ -1018,9 +1028,12 @@ static void rib_process(struct route_node *rn)
 	if (IS_ZEBRA_DEBUG_RIB)
 		srcdest_rnode2str(rn, buf, sizeof(buf));
 
-	if (IS_ZEBRA_DEBUG_RIB_DETAILED)
-		zlog_debug("%s(%u):%s: Processing rn %p", VRF_LOGNAME(vrf),
-			   vrf_id, buf, rn);
+	if (IS_ZEBRA_DEBUG_RIB_DETAILED) {
+		struct route_entry *re = re_list_first(&dest->routes);
+
+		zlog_debug("%s(%u:%u):%s: Processing rn %p", VRF_LOGNAME(vrf),
+			   vrf_id, re->table, buf, rn);
+	}
 
 	/*
 	 * we can have rn's that have a NULL info pointer
@@ -1034,8 +1047,8 @@ static void rib_process(struct route_node *rn)
 	RNODE_FOREACH_RE_SAFE (rn, re, next) {
 		if (IS_ZEBRA_DEBUG_RIB_DETAILED)
 			zlog_debug(
-				"%s(%u):%s: Examine re %p (%s) status %x flags %x dist %d metric %d",
-				VRF_LOGNAME(vrf), vrf_id, buf, re,
+				"%s(%u:%u):%s: Examine re %p (%s) status %x flags %x dist %d metric %d",
+				VRF_LOGNAME(vrf), vrf_id, re->table, buf, re,
 				zebra_route_string(re->type), re->status,
 				re->flags, re->distance, re->metric);
 
@@ -1131,10 +1144,20 @@ static void rib_process(struct route_node *rn)
 	 */
 
 	if (IS_ZEBRA_DEBUG_RIB_DETAILED) {
+		struct route_entry *entry;
+
+		entry = old_selected
+				? old_selected
+				: new_selected
+					  ? new_selected
+					  : old_fib ? old_fib
+						    : new_fib ? new_fib : NULL;
+
 		zlog_debug(
-			"%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);
+			"%s(%u:%u):%s: After processing: old_selected %p new_selected %p old_fib %p new_fib %p",
+			VRF_LOGNAME(vrf), vrf_id, entry ? entry->table : 0, buf,
+			(void *)old_selected, (void *)new_selected,
+			(void *)old_fib, (void *)new_fib);
 	}
 
 	/* Buffer ROUTE_ENTRY_CHANGED here, because it will get cleared if
@@ -1456,8 +1479,8 @@ 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: %s(%u):%s: %sSELECTED, re %p",
-			   VRF_LOGNAME(vrf), re->vrf_id, dest_str,
+		zlog_debug("update_from_ctx: %s(%u:%u):%s: %sSELECTED, re %p",
+			   VRF_LOGNAME(vrf), re->vrf_id, re->table, dest_str,
 			   (is_selected ? "" : "NOT "), re);
 
 	/* Update zebra's nexthop FIB flag for each nexthop that was installed.
@@ -1483,8 +1506,9 @@ static bool rib_update_re_from_ctx(struct route_entry *re,
 	if (matched) {
 		if (IS_ZEBRA_DEBUG_RIB)
 			zlog_debug(
-				"%s(%u):%s update_from_ctx(): existing fib nhg, no change",
-				VRF_LOGNAME(vrf), re->vrf_id, dest_str);
+				"%s(%u:%u):%s update_from_ctx(): existing fib nhg, no change",
+				VRF_LOGNAME(vrf), re->vrf_id, re->table,
+				dest_str);
 		goto check_backups;
 
 	} else if (CHECK_FLAG(re->status, ROUTE_ENTRY_USE_FIB_NHG)) {
@@ -1493,8 +1517,9 @@ static bool rib_update_re_from_ctx(struct route_entry *re,
 		 */
 		if (IS_ZEBRA_DEBUG_RIB)
 			zlog_debug(
-				"%s(%u):%s update_from_ctx(): replacing fib nhg",
-				VRF_LOGNAME(vrf), re->vrf_id, dest_str);
+				"%s(%u:%u):%s update_from_ctx(): replacing fib nhg",
+				VRF_LOGNAME(vrf), re->vrf_id, re->table,
+				dest_str);
 		nexthops_free(re->fib_ng.nexthop);
 		re->fib_ng.nexthop = NULL;
 
@@ -1504,8 +1529,9 @@ static bool rib_update_re_from_ctx(struct route_entry *re,
 		changed_p = true;
 	} else {
 		if (IS_ZEBRA_DEBUG_RIB)
-			zlog_debug("%s(%u):%s update_from_ctx(): no fib nhg",
-				   VRF_LOGNAME(vrf), re->vrf_id, dest_str);
+			zlog_debug("%s(%u:%u):%s update_from_ctx(): no fib nhg",
+				   VRF_LOGNAME(vrf), re->vrf_id, re->table,
+				   dest_str);
 	}
 
 	/*
@@ -1532,9 +1558,9 @@ static bool rib_update_re_from_ctx(struct route_entry *re,
 	if (matched) {
 		if (IS_ZEBRA_DEBUG_RIB)
 			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"));
+				"%s(%u:%u):%s update_from_ctx(): rib nhg matched, changed '%s'",
+				VRF_LOGNAME(vrf), re->vrf_id, re->table,
+				dest_str, (changed_p ? "true" : "false"));
 		goto check_backups;
 	}
 
@@ -1545,8 +1571,8 @@ no_nexthops:
 	 */
 	if (IS_ZEBRA_DEBUG_RIB)
 		zlog_debug(
-			"%s(%u):%s update_from_ctx(): changed %s, adding new fib nhg%s",
-			VRF_LOGNAME(vrf), re->vrf_id, dest_str,
+			"%s(%u:%u):%s update_from_ctx(): changed %s, adding new fib nhg%s",
+			VRF_LOGNAME(vrf), re->vrf_id, re->table, dest_str,
 			(changed_p ? "true" : "false"),
 			ctxnhg->nexthop != NULL ? "" : " (empty)");
 
@@ -1722,9 +1748,10 @@ static void rib_process_result(struct zebra_dplane_ctx *ctx)
 
 	if (IS_ZEBRA_DEBUG_DPLANE_DETAIL)
 		zlog_debug(
-			"%s(%u):%s Processing dplane result ctx %p, op %s result %s",
-			VRF_LOGNAME(vrf), dplane_ctx_get_vrf(ctx), dest_str,
-			ctx, dplane_op2str(op), dplane_res2str(status));
+			"%s(%u:%u):%s Processing dplane result ctx %p, op %s result %s",
+			VRF_LOGNAME(vrf), dplane_ctx_get_vrf(ctx),
+			dplane_ctx_get_table(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
@@ -1774,10 +1801,10 @@ static void rib_process_result(struct zebra_dplane_ctx *ctx)
 		if (old_re->dplane_sequence != dplane_ctx_get_old_seq(ctx)) {
 			if (IS_ZEBRA_DEBUG_DPLANE_DETAIL)
 				zlog_debug(
-					"%s(%u):%s Stale dplane result for old_re %p",
+					"%s(%u:%u):%s Stale dplane result for old_re %p",
 					VRF_LOGNAME(vrf),
-					dplane_ctx_get_vrf(ctx), dest_str,
-					old_re);
+					dplane_ctx_get_vrf(ctx), old_re->table,
+					dest_str, old_re);
 		} else
 			UNSET_FLAG(old_re->status, ROUTE_ENTRY_QUEUED);
 	}
@@ -1815,9 +1842,11 @@ static void rib_process_result(struct zebra_dplane_ctx *ctx)
 				if (!fib_changed) {
 					if (IS_ZEBRA_DEBUG_DPLANE_DETAIL)
 						zlog_debug(
-							"%s(%u):%s no fib change for re",
+							"%s(%u:%u):%s no fib change for re",
 							VRF_LOGNAME(vrf),
 							dplane_ctx_get_vrf(ctx),
+							dplane_ctx_get_table(
+								ctx),
 							dest_str);
 				}
 
@@ -1854,8 +1883,9 @@ static void rib_process_result(struct zebra_dplane_ctx *ctx)
 				zsend_route_notify_owner(re, dest_pfx,
 							 ZAPI_ROUTE_FAIL_INSTALL);
 
-			zlog_warn("%s(%u):%s: Route install failed",
+			zlog_warn("%s(%u:%u):%s: Route install failed",
 				  VRF_LOGNAME(vrf), dplane_ctx_get_vrf(ctx),
+				  dplane_ctx_get_table(ctx),
 				  prefix2str(dest_pfx, dest_str,
 					     sizeof(dest_str)));
 		}
@@ -1883,8 +1913,9 @@ static void rib_process_result(struct zebra_dplane_ctx *ctx)
 			zsend_route_notify_owner_ctx(ctx,
 						     ZAPI_ROUTE_REMOVE_FAIL);
 
-			zlog_warn("%s(%u):%s: Route Deletion failure",
+			zlog_warn("%s(%u:%u):%s: Route Deletion failure",
 				  VRF_LOGNAME(vrf), dplane_ctx_get_vrf(ctx),
+				  dplane_ctx_get_table(ctx),
 				  prefix2str(dest_pfx, dest_str,
 					     sizeof(dest_str)));
 		}
@@ -1981,9 +2012,9 @@ static void rib_process_dplane_notify(struct zebra_dplane_ctx *ctx)
 	if (rn == NULL) {
 		if (debug_p) {
 			zlog_debug(
-				"Failed to process dplane notification: no routes for %s(%u):%s",
+				"Failed to process dplane notification: no routes for %s(%u:%u):%s",
 				VRF_LOGNAME(vrf), dplane_ctx_get_vrf(ctx),
-				dest_str);
+				dplane_ctx_get_table(ctx), dest_str);
 		}
 		goto done;
 	}
@@ -1992,9 +2023,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("%s(%u):%s Processing dplane notif ctx %p",
-			   VRF_LOGNAME(vrf), dplane_ctx_get_vrf(ctx), dest_str,
-			   ctx);
+		zlog_debug("%s(%u:%u):%s Processing dplane notif ctx %p",
+			   VRF_LOGNAME(vrf), dplane_ctx_get_vrf(ctx),
+			   dplane_ctx_get_table(ctx), dest_str, ctx);
 
 	/*
 	 * Take a pass through the routes, look for matches with the context
@@ -2009,9 +2040,9 @@ static void rib_process_dplane_notify(struct zebra_dplane_ctx *ctx)
 	if (re == NULL) {
 		if (debug_p)
 			zlog_debug(
-				"%s(%u):%s Unable to process dplane notification: no entry for type %s",
+				"%s(%u:%u):%s Unable to process dplane notification: no entry for type %s",
 				VRF_LOGNAME(vrf), dplane_ctx_get_vrf(ctx),
-				dest_str,
+				dplane_ctx_get_table(ctx), dest_str,
 				zebra_route_string(dplane_ctx_get_type(ctx)));
 
 		goto done;
@@ -2043,18 +2074,20 @@ static void rib_process_dplane_notify(struct zebra_dplane_ctx *ctx)
 				UNSET_FLAG(re->status, ROUTE_ENTRY_INSTALLED);
 			if (debug_p)
 				zlog_debug(
-					"%s(%u):%s dplane notif, uninstalled type %s route",
+					"%s(%u:%u):%s dplane notif, uninstalled type %s route",
 					VRF_LOGNAME(vrf),
-					dplane_ctx_get_vrf(ctx), dest_str,
+					dplane_ctx_get_vrf(ctx),
+					dplane_ctx_get_table(ctx), dest_str,
 					zebra_route_string(
 						dplane_ctx_get_type(ctx)));
 		} else {
 			/* At least report on the event. */
 			if (debug_p)
 				zlog_debug(
-					"%s(%u):%s dplane notif, but type %s not selected_fib",
+					"%s(%u:%u):%s dplane notif, but type %s not selected_fib",
 					VRF_LOGNAME(vrf),
-					dplane_ctx_get_vrf(ctx), dest_str,
+					dplane_ctx_get_vrf(ctx),
+					dplane_ctx_get_table(ctx), dest_str,
 					zebra_route_string(
 						dplane_ctx_get_type(ctx)));
 		}
@@ -2078,9 +2111,9 @@ static void rib_process_dplane_notify(struct zebra_dplane_ctx *ctx)
 	if (!fib_changed) {
 		if (debug_p)
 			zlog_debug(
-				"%s(%u):%s dplane notification: rib_update returns FALSE",
+				"%s(%u:%u):%s dplane notification: rib_update returns FALSE",
 				VRF_LOGNAME(vrf), dplane_ctx_get_vrf(ctx),
-				dest_str);
+				dplane_ctx_get_table(ctx), dest_str);
 	}
 
 	/*
@@ -2095,9 +2128,9 @@ static void rib_process_dplane_notify(struct zebra_dplane_ctx *ctx)
 	if (start_count > 0 && end_count > 0) {
 		if (debug_p)
 			zlog_debug(
-				"%s(%u):%s applied nexthop changes from dplane notification",
+				"%s(%u:%u):%s applied nexthop changes from dplane notification",
 				VRF_LOGNAME(vrf), dplane_ctx_get_vrf(ctx),
-				dest_str);
+				dplane_ctx_get_table(ctx), dest_str);
 
 		/* Changed nexthops - update kernel/others */
 		dplane_route_notif_update(rn, re,
@@ -2106,9 +2139,9 @@ static void rib_process_dplane_notify(struct zebra_dplane_ctx *ctx)
 	} else if (start_count == 0 && end_count > 0) {
 		if (debug_p)
 			zlog_debug(
-				"%s(%u):%s installed transition from dplane notification",
+				"%s(%u:%u):%s installed transition from dplane notification",
 				VRF_LOGNAME(vrf), dplane_ctx_get_vrf(ctx),
-				dest_str);
+				dplane_ctx_get_table(ctx), dest_str);
 
 		/* We expect this to be the selected route, so we want
 		 * to tell others about this transition.
@@ -2124,9 +2157,9 @@ static void rib_process_dplane_notify(struct zebra_dplane_ctx *ctx)
 	} else if (start_count > 0 && end_count == 0) {
 		if (debug_p)
 			zlog_debug(
-				"%s(%u):%s un-installed transition from dplane notification",
+				"%s(%u:%u):%s un-installed transition from dplane notification",
 				VRF_LOGNAME(vrf), dplane_ctx_get_vrf(ctx),
-				dest_str);
+				dplane_ctx_get_table(ctx), dest_str);
 
 		/* Transition from _something_ installed to _nothing_
 		 * installed.
@@ -2182,17 +2215,20 @@ static void process_subq_route(struct listnode *lnode, uint8_t qindex)
 
 	rnode = listgetdata(lnode);
 	dest = rib_dest_from_rnode(rnode);
-	if (dest)
-		zvrf = rib_dest_vrf(dest);
+	assert(dest);
+
+	zvrf = rib_dest_vrf(dest);
 
 	rib_process(rnode);
 
 	if (IS_ZEBRA_DEBUG_RIB_DETAILED) {
+		struct route_entry *re = re_list_first(&dest->routes);
 		char buf[SRCDEST2STR_BUFFER];
 
 		srcdest_rnode2str(rnode, buf, sizeof(buf));
-		zlog_debug("%s(%u):%s: rn %p dequeued from sub-queue %u",
-			   zvrf_name(zvrf), zvrf_id(zvrf), buf, rnode, qindex);
+		zlog_debug("%s(%u:%u):%s: rn %p dequeued from sub-queue %u",
+			   zvrf_name(zvrf), zvrf_id(zvrf), re ? re->table : 0, buf,
+			   rnode, qindex);
 	}
 
 	if (rnode->info)