ospfd: Add vrf name to debug functions in ospf_zebra.c

This file had a bunch of debugs that were operating on
specific vrf's but not telling you which vrf this was
happening in.  Add code to allow operator debugging
to understand what vrf is being worked on.

Signed-off-by: Donald Sharp <sharpd@nvidia.com>

1 files changed, 102 insertions, 86 deletions

diff --git a/ospfd/ospf_zebra.c b/ospfd/ospf_zebra.c
index 2c518f2c9..c7cba1e20 100644
--- a/ospfd/ospf_zebra.c
+++ b/ospfd/ospf_zebra.c
@@ -119,8 +119,9 @@ static int ospf_interface_address_delete(ZAPI_CALLBACK_ARGS)
 		return 0;
 
 	if (IS_DEBUG_OSPF(zebra, ZEBRA_INTERFACE))
-		zlog_debug("Zebra: interface %s address delete %pFX",
-			   c->ifp->name, c->address);
+		zlog_debug("Zebra: interface %s address delete %pFX vrf %s id %u",
+			   c->ifp->name, c->address,
+			   ospf_vrf_id_to_name(vrf_id), vrf_id);
 
 	ifp = c->ifp;
 	p = *c->address;
@@ -261,9 +262,8 @@ void ospf_zebra_add(struct ospf *ospf, struct prefix_ipv4 *p,
 
 	if (ospf->gr_info.restart_in_progress) {
 		if (IS_DEBUG_OSPF_GR)
-			zlog_debug(
-				"Zebra: Graceful Restart in progress -- not installing %pFX",
-				p);
+			zlog_debug("Zebra: Graceful Restart in progress -- not installing %pFX(%s)",
+				   p, ospf_vrf_id_to_name(ospf->vrf_id));
 		return;
 	}
 
@@ -311,10 +311,10 @@ void ospf_zebra_add(struct ospf *ospf, struct prefix_ipv4 *p,
 
 			ifp = if_lookup_by_index(path->ifindex, ospf->vrf_id);
 
-			zlog_debug(
-				"Zebra: Route add %pFX nexthop %pI4, ifindex=%d %s",
-				p, &path->nexthop, path->ifindex,
-				ifp ? ifp->name : " ");
+			zlog_debug("Zebra: Route add %pFX(%s) nexthop %pI4, ifindex=%d %s",
+				   p, ospf_vrf_id_to_name(ospf->vrf_id),
+				   &path->nexthop, path->ifindex,
+				   ifp ? ifp->name : " ");
 		}
 	}
 
@@ -331,9 +331,8 @@ void ospf_zebra_delete(struct ospf *ospf, struct prefix_ipv4 *p,
 
 	if (ospf->gr_info.restart_in_progress) {
 		if (IS_DEBUG_OSPF_GR)
-			zlog_debug(
-				"Zebra: Graceful Restart in progress -- not uninstalling %pFX",
-				p);
+			zlog_debug("Zebra: Graceful Restart in progress -- not uninstalling %pFX(%s)",
+				   p, ospf_vrf_id_to_name(ospf->vrf_id));
 		return;
 	}
 
@@ -345,7 +344,8 @@ void ospf_zebra_delete(struct ospf *ospf, struct prefix_ipv4 *p,
 	memcpy(&api.prefix, p, sizeof(*p));
 
 	if (IS_DEBUG_OSPF(zebra, ZEBRA_REDISTRIBUTE))
-		zlog_debug("Zebra: Route delete %pFX", p);
+		zlog_debug("Zebra: Route delete %pFX(%s)", p,
+			   ospf_vrf_id_to_name(ospf->vrf_id));
 
 	zclient_route_send(ZEBRA_ROUTE_DELETE, zclient, &api);
 }
@@ -356,9 +356,8 @@ void ospf_zebra_add_discard(struct ospf *ospf, struct prefix_ipv4 *p)
 
 	if (ospf->gr_info.restart_in_progress) {
 		if (IS_DEBUG_OSPF_GR)
-			zlog_debug(
-				"Zebra: Graceful Restart in progress -- not installing %pFX",
-				p);
+			zlog_debug("Zebra: Graceful Restart in progress -- not installing %pFX(%s)",
+				   p, ospf_vrf_id_to_name(ospf->vrf_id));
 		return;
 	}
 
@@ -373,7 +372,8 @@ void ospf_zebra_add_discard(struct ospf *ospf, struct prefix_ipv4 *p)
 	zclient_route_send(ZEBRA_ROUTE_ADD, zclient, &api);
 
 	if (IS_DEBUG_OSPF(zebra, ZEBRA_REDISTRIBUTE))
-		zlog_debug("Zebra: Route add discard %pFX", p);
+		zlog_debug("Zebra: Route add discard %pFX(%s)", p,
+			   ospf_vrf_id_to_name(ospf->vrf_id));
 }
 
 void ospf_zebra_delete_discard(struct ospf *ospf, struct prefix_ipv4 *p)
@@ -382,9 +382,8 @@ void ospf_zebra_delete_discard(struct ospf *ospf, struct prefix_ipv4 *p)
 
 	if (ospf->gr_info.restart_in_progress) {
 		if (IS_DEBUG_OSPF_GR)
-			zlog_debug(
-				"Zebra: Graceful Restart in progress -- not uninstalling %pFX",
-				p);
+			zlog_debug("Zebra: Graceful Restart in progress -- not uninstalling %pFX(%s)",
+				   p, ospf_vrf_id_to_name(ospf->vrf_id));
 		return;
 	}
 
@@ -399,7 +398,8 @@ void ospf_zebra_delete_discard(struct ospf *ospf, struct prefix_ipv4 *p)
 	zclient_route_send(ZEBRA_ROUTE_DELETE, zclient, &api);
 
 	if (IS_DEBUG_OSPF(zebra, ZEBRA_REDISTRIBUTE))
-		zlog_debug("Zebra: Route delete discard %pFX", p);
+		zlog_debug("Zebra: Route delete discard %pFX(%s)", p,
+			   ospf_vrf_id_to_name(ospf->vrf_id));
 }
 
 struct ospf_external *ospf_external_lookup(struct ospf *ospf, uint8_t type,
@@ -475,8 +475,9 @@ bool ospf_external_default_routemap_apply_walk(struct ospf *ospf,
 
 	if (ret && ei) {
 		if (IS_DEBUG_OSPF_DEFAULT_INFO)
-			zlog_debug("Default originate routemap permit ei: %pI4",
-				   &ei->p.prefix);
+			zlog_debug("Default originate routemap permit ei: %pI4(%s)",
+				   &ei->p.prefix,
+				   ospf_vrf_id_to_name(ospf->vrf_id));
 		return true;
 	}
 
@@ -507,7 +508,8 @@ static void ospf_external_lsa_default_routemap_timer(struct event *thread)
 	if (!default_ei) {
 		/* Nothing to be done here. */
 		if (IS_DEBUG_OSPF_DEFAULT_INFO)
-			zlog_debug("Default originate info not present");
+			zlog_debug("Default originate info not present(%s)",
+				   ospf_vrf_id_to_name(ospf->vrf_id));
 		return;
 	}
 
@@ -821,11 +823,11 @@ int ospf_redistribute_update(struct ospf *ospf, struct ospf_redist *red,
 	ospf_external_lsa_refresh_type(ospf, type, instance, force);
 
 	if (IS_DEBUG_OSPF(zebra, ZEBRA_REDISTRIBUTE))
-		zlog_debug(
-			"Redistribute[%s][%d]: Refresh  Type[%d], Metric[%d]",
-			ospf_redist_string(type), instance,
-			metric_type(ospf, type, instance),
-			metric_value(ospf, type, instance));
+		zlog_debug("Redistribute[%s][%d][%s]: Refresh  Type[%d], Metric[%d]",
+			   ospf_redist_string(type), instance,
+			   ospf_vrf_id_to_name(ospf->vrf_id),
+			   metric_type(ospf, type, instance),
+			   metric_value(ospf, type, instance));
 
 	return CMD_SUCCESS;
 }
@@ -842,11 +844,11 @@ int ospf_redistribute_set(struct ospf *ospf, struct ospf_redist *red, int type,
 			     instance, ospf->vrf_id);
 
 	if (IS_DEBUG_OSPF(zebra, ZEBRA_REDISTRIBUTE))
-		zlog_debug(
-			"Redistribute[%s][%d] vrf id %u: Start  Type[%d], Metric[%d]",
-			ospf_redist_string(type), instance, ospf->vrf_id,
-			metric_type(ospf, type, instance),
-			metric_value(ospf, type, instance));
+		zlog_debug("Redistribute[%s][%d][%s]: Start  Type[%d], Metric[%d]",
+			   ospf_redist_string(type), instance,
+			   ospf_vrf_id_to_name(ospf->vrf_id),
+			   metric_type(ospf, type, instance),
+			   metric_value(ospf, type, instance));
 
 	ospf_asbr_status_update(ospf, ++ospf->redistribute);
 
@@ -863,8 +865,9 @@ int ospf_redistribute_unset(struct ospf *ospf, int type,
 			     instance, ospf->vrf_id);
 
 	if (IS_DEBUG_OSPF(zebra, ZEBRA_REDISTRIBUTE))
-		zlog_debug("Redistribute[%s][%d] vrf id %u: Stop",
-			   ospf_redist_string(type), instance, ospf->vrf_id);
+		zlog_debug("Redistribute[%s][%d][%s]: Stop",
+			   ospf_redist_string(type), instance,
+			   ospf_vrf_id_to_name(ospf->vrf_id));
 
 	/* Remove the routes from OSPF table. */
 	ospf_redistribute_withdraw(ospf, type, instance);
@@ -894,11 +897,11 @@ int ospf_redistribute_default_set(struct ospf *ospf, int originate, int mtype,
 	if (cur_originate == originate) {
 		/* Refresh the lsa since metric might different */
 		if (IS_DEBUG_OSPF(zebra, ZEBRA_REDISTRIBUTE))
-			zlog_debug(
-				"Redistribute[%s]: Refresh  Type[%d], Metric[%d]",
-				ospf_redist_string(DEFAULT_ROUTE),
-				metric_type(ospf, DEFAULT_ROUTE, 0),
-				metric_value(ospf, DEFAULT_ROUTE, 0));
+			zlog_debug("Redistribute[%s][%s]: Refresh  Type[%d], Metric[%d]",
+				   ospf_redist_string(DEFAULT_ROUTE),
+				   ospf_vrf_id_to_name(ospf->vrf_id),
+				   metric_type(ospf, DEFAULT_ROUTE, 0),
+				   metric_value(ospf, DEFAULT_ROUTE, 0));
 
 		ospf_external_lsa_refresh_default(ospf);
 		return CMD_SUCCESS;
@@ -939,10 +942,10 @@ int ospf_redistribute_default_set(struct ospf *ospf, int originate, int mtype,
 	}
 
 	if (IS_DEBUG_OSPF(zebra, ZEBRA_REDISTRIBUTE))
-		zlog_debug("Redistribute[DEFAULT]: %s Type[%d], Metric[%d]",
-		type_str,
-		metric_type(ospf, DEFAULT_ROUTE, 0),
-		metric_value(ospf, DEFAULT_ROUTE, 0));
+		zlog_debug("Redistribute[DEFAULT][%s]: %s Type[%d], Metric[%d]",
+			   ospf_vrf_id_to_name(ospf->vrf_id), type_str,
+			   metric_type(ospf, DEFAULT_ROUTE, 0),
+			   metric_value(ospf, DEFAULT_ROUTE, 0));
 
 	ospf_external_lsa_refresh_default(ospf);
 	ospf_asbr_status_update(ospf, ospf->redistribute);
@@ -1047,16 +1050,18 @@ static bool ospf_external_lsa_default_routemap_apply(struct ospf *ospf,
 	}
 
 	if (IS_DEBUG_OSPF_DEFAULT_INFO)
-		zlog_debug("Apply default originate routemap on ei: %pI4 cmd: %d",
-			   &ei->p.prefix, cmd);
+		zlog_debug("Apply default originate routemap on ei: %pI4(%s) cmd: %d",
+			   &ei->p.prefix, ospf_vrf_id_to_name(ospf->vrf_id),
+			   cmd);
 
 	ret = ospf_external_info_apply_default_routemap(ospf, ei, default_ei);
 
 	/* If deny then nothing to be done both in add and del case. */
 	if (!ret) {
 		if (IS_DEBUG_OSPF_DEFAULT_INFO)
-			zlog_debug("Default originte routemap deny for ei: %pI4",
-				   &ei->p.prefix);
+			zlog_debug("Default originte routemap deny for ei: %pI4(%s)",
+				   &ei->p.prefix,
+				   ospf_vrf_id_to_name(ospf->vrf_id));
 		return false;
 	}
 
@@ -1068,12 +1073,14 @@ static bool ospf_external_lsa_default_routemap_apply(struct ospf *ospf,
 		/* If permit and default already advertise then return. */
 		if (lsa && !IS_LSA_MAXAGE(lsa)) {
 			if (IS_DEBUG_OSPF_DEFAULT_INFO)
-				zlog_debug("Default lsa already originated");
+				zlog_debug("Default lsa already originated(%s)",
+					   ospf_vrf_id_to_name(ospf->vrf_id));
 			return true;
 		}
 
 		if (IS_DEBUG_OSPF_DEFAULT_INFO)
-			zlog_debug("Originating/Refreshing default lsa");
+			zlog_debug("Originating/Refreshing default lsa(%s)",
+				   ospf_vrf_id_to_name(ospf->vrf_id));
 
 		if (lsa && IS_LSA_MAXAGE(lsa))
 			/* Refresh lsa.*/
@@ -1088,15 +1095,15 @@ static bool ospf_external_lsa_default_routemap_apply(struct ospf *ospf,
 		/* If deny and lsa is not originated then nothing to be done.*/
 		if (!lsa) {
 			if (IS_DEBUG_OSPF_DEFAULT_INFO)
-				zlog_debug(
-					"Default lsa not originated, not flushing");
+				zlog_debug("Default lsa not originated, not flushing(%s)",
+					   ospf_vrf_id_to_name(ospf->vrf_id));
 			return true;
 		}
 
 		if (IS_DEBUG_OSPF_DEFAULT_INFO)
-			zlog_debug(
-				"Running default route-map again as ei: %pI4 deleted",
-				&ei->p.prefix);
+			zlog_debug("Running default route-map again as ei: %pI4(%s) deleted",
+				   &ei->p.prefix,
+				   ospf_vrf_id_to_name(ospf->vrf_id));
 		/*
 		 * if this route delete was permitted then we need to check
 		 * there are any other external info which can still trigger
@@ -1142,9 +1149,10 @@ int ospf_redistribute_check(struct ospf *ospf, struct external_info *ei,
 			if (access_list_apply(DISTRIBUTE_LIST(ospf, type), p)
 			    == FILTER_DENY) {
 				if (IS_DEBUG_OSPF(zebra, ZEBRA_REDISTRIBUTE))
-					zlog_debug(
-						"Redistribute[%s]: %pFX filtered by distribute-list.",
-						ospf_redist_string(type), p);
+					zlog_debug("Redistribute[%s]: %pFX(%s) filtered by distribute-list.",
+						   ospf_redist_string(type), p,
+						   ospf_vrf_id_to_name(
+							   ospf->vrf_id));
 				return 0;
 			}
 
@@ -1165,9 +1173,9 @@ int ospf_redistribute_check(struct ospf *ospf, struct external_info *ei,
 		if (ret == RMAP_DENYMATCH) {
 			ei->route_map_set = save_values;
 			if (IS_DEBUG_OSPF(zebra, ZEBRA_REDISTRIBUTE))
-				zlog_debug(
-					"Redistribute[%s]: %pFX filtered by route-map.",
-					ospf_redist_string(type), p);
+				zlog_debug("Redistribute[%s]: %pFX(%s) filtered by route-map.",
+					   ospf_redist_string(type), p,
+					   ospf_vrf_id_to_name(ospf->vrf_id));
 			return 0;
 		}
 
@@ -1230,7 +1238,8 @@ static int ospf_zebra_gr_update(struct ospf *ospf, int command,
 int ospf_zebra_gr_enable(struct ospf *ospf, uint32_t stale_time)
 {
 	if (IS_DEBUG_OSPF_GR)
-		zlog_debug("Zebra enable GR [stale time %u]", stale_time);
+		zlog_debug("Zebra enable GR [stale time %u] vrf %s", stale_time,
+			   ospf_vrf_id_to_name(ospf->vrf_id));
 
 	return ospf_zebra_gr_update(ospf, ZEBRA_CLIENT_GR_CAPABILITIES,
 				    stale_time);
@@ -1239,7 +1248,8 @@ int ospf_zebra_gr_enable(struct ospf *ospf, uint32_t stale_time)
 int ospf_zebra_gr_disable(struct ospf *ospf)
 {
 	if (IS_DEBUG_OSPF_GR)
-		zlog_debug("Zebra disable GR");
+		zlog_debug("Zebra disable GR vrf: %s",
+			   ospf_vrf_id_to_name(ospf->vrf_id));
 
 	return ospf_zebra_gr_update(ospf, ZEBRA_CLIENT_GR_DISABLE, 0);
 }
@@ -1286,11 +1296,11 @@ static int ospf_zebra_read_route(ZAPI_CALLBACK_ARGS)
 		rt_type = DEFAULT_ROUTE;
 
 	if (IS_DEBUG_OSPF(zebra, ZEBRA_REDISTRIBUTE))
-		zlog_debug(
-			"%s: cmd %s from client %s: vrf_id %d, p %pFX, metric %d",
-			__func__, zserv_command_string(cmd),
-			zebra_route_string(api.type), vrf_id, &api.prefix,
-			api.metric);
+		zlog_debug("%s: cmd %s from client %s: vrf %s(%u), p %pFX, metric %d",
+			   __func__, zserv_command_string(cmd),
+			   zebra_route_string(api.type),
+			   ospf_vrf_id_to_name(vrf_id), vrf_id, &api.prefix,
+			   api.metric);
 
 	if (cmd == ZEBRA_REDISTRIBUTE_ROUTE_ADD) {
 		/* XXX|HACK|TODO|FIXME:
@@ -1343,11 +1353,12 @@ static int ospf_zebra_read_route(ZAPI_CALLBACK_ARGS)
 						return 0;
 
 					if (IS_DEBUG_OSPF(lsa, EXTNL_LSA_AGGR))
-						zlog_debug(
-							"%s: Send Aggreate LSA (%pI4/%d)",
-							__func__,
-							&aggr->p.prefix,
-							aggr->p.prefixlen);
+						zlog_debug("%s: Send Aggreate LSA (%pI4/%d)(%s)",
+							   __func__,
+							   &aggr->p.prefix,
+							   aggr->p.prefixlen,
+							   ospf_vrf_id_to_name(
+								   ospf->vrf_id));
 
 					ospf_originate_summary_lsa(ospf, aggr,
 								   ei);
@@ -1402,10 +1413,11 @@ static int ospf_zebra_read_route(ZAPI_CALLBACK_ARGS)
 						if (IS_DEBUG_OSPF(
 							    zebra,
 							    ZEBRA_REDISTRIBUTE))
-							zlog_debug(
-								"%s: %pI4 refreshing LSA",
-								__func__,
-								&p.prefix);
+							zlog_debug("%s: %pI4(%s) refreshing LSA",
+								   __func__,
+								   &p.prefix,
+								   ospf_vrf_id_to_name(
+									   ospf->vrf_id));
 						ospf_external_lsa_refresh(
 							ospf, current, ei,
 							LSA_REFRESH_FORCE,
@@ -1464,7 +1476,8 @@ void ospf_zebra_import_default_route(struct ospf *ospf, bool unreg)
 
 	if (zclient->sock < 0) {
 		if (IS_DEBUG_OSPF(zebra, ZEBRA))
-			zlog_debug("  Not connected to Zebra");
+			zlog_debug("  Not connected to Zebra vrf: %s",
+				   ospf_vrf_id_to_name(ospf->vrf_id));
 		return;
 	}
 
@@ -1477,14 +1490,14 @@ void ospf_zebra_import_default_route(struct ospf *ospf, bool unreg)
 		command = ZEBRA_NEXTHOP_REGISTER;
 
 	if (IS_DEBUG_OSPF(zebra, ZEBRA))
-		zlog_debug("%s: sending cmd %s for %pFX (vrf %u)", __func__,
+		zlog_debug("%s: sending cmd %s for %pFX(%s)", __func__,
 			   zserv_command_string(command), &prefix,
-			   ospf->vrf_id);
+			   ospf_vrf_id_to_name(ospf->vrf_id));
 
 	if (zclient_send_rnh(zclient, command, &prefix, SAFI_UNICAST, false,
 			     true, ospf->vrf_id) == ZCLIENT_SEND_FAILURE)
-		flog_err(EC_LIB_ZAPI_SOCKET, "%s: zclient_send_rnh() failed",
-			 __func__);
+		flog_err(EC_LIB_ZAPI_SOCKET, "%s(%s): zclient_send_rnh() failed",
+			 __func__, ospf_vrf_id_to_name(ospf->vrf_id));
 }
 
 static void ospf_zebra_import_check_update(struct vrf *vrf, struct prefix *match,
@@ -1556,7 +1569,8 @@ static void ospf_distribute_list_update_timer(struct event *thread)
 
 	ospf->t_distribute_update = NULL;
 
-	zlog_info("Zebra[Redistribute]: distribute-list update timer fired!");
+	zlog_info("Zebra[Redistribute]: vrf: %s distribute-list update timer fired!",
+		  ospf_vrf_id_to_name(ospf->vrf_id));
 
 	if (IS_DEBUG_OSPF_EVENT) {
 		zlog_debug("%s: ospf distribute-list update vrf %s id %d",
@@ -1607,10 +1621,12 @@ static void ospf_distribute_list_update_timer(struct event *thread)
 							    lsa,
 							    EXTNL_LSA_AGGR))
 							zlog_debug(
-								"%s: Send Aggregate LSA (%pI4/%d)",
+								"%s: Send Aggregate LSA (%pI4/%d)(%s)",
 								__func__,
 								&aggr->p.prefix,
-								aggr->p.prefixlen);
+								aggr->p.prefixlen,
+								ospf_vrf_id_to_name(
+									ospf->vrf_id));
 
 						/* Originate Aggregate
 						 * LSA