ospfd: Add/fix some debugs to handle vrf

This commit has:
The received packet path in ospf, had absolutely no debugs associated with
it.  This makes it extremely hard to know when we receive packets for
consumption.  Add some breadcrumbs to this end.

Large chunks of commands have no ability to debug what is happening
in what vrf.  With ip overlap X vrf this becomes a bit of a problem
Add some breadcrumbs here.

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

5 files changed, 69 insertions, 36 deletions

diff --git a/ospfd/ospf_asbr.c b/ospfd/ospf_asbr.c
index ea919017d..a60af3656 100644
--- a/ospfd/ospf_asbr.c
+++ b/ospfd/ospf_asbr.c
@@ -238,20 +238,23 @@ struct ospf_lsa *ospf_external_info_find_lsa(struct ospf *ospf,
 /* Update ASBR status. */
 void ospf_asbr_status_update(struct ospf *ospf, uint8_t status)
 {
-	zlog_info("ASBR[Status:%d]: Update", status);
+	zlog_info("ASBR[%s:Status:%d]: Update",
+		  ospf_get_name(ospf), status);
 
 	/* ASBR on. */
 	if (status) {
 		/* Already ASBR. */
 		if (IS_OSPF_ASBR(ospf)) {
-			zlog_info("ASBR[Status:%d]: Already ASBR", status);
+			zlog_info("ASBR[%s:Status:%d]: Already ASBR",
+				  ospf_get_name(ospf), status);
 			return;
 		}
 		SET_FLAG(ospf->flags, OSPF_FLAG_ASBR);
 	} else {
 		/* Already non ASBR. */
 		if (!IS_OSPF_ASBR(ospf)) {
-			zlog_info("ASBR[Status:%d]: Already non ASBR", status);
+			zlog_info("ASBR[%s:Status:%d]: Already non ASBR",
+				  ospf_get_name(ospf), status);
 			return;
 		}
 		UNSET_FLAG(ospf->flags, OSPF_FLAG_ASBR);
diff --git a/ospfd/ospf_flood.c b/ospfd/ospf_flood.c
index a72caa841..381fb6820 100644
--- a/ospfd/ospf_flood.c
+++ b/ospfd/ospf_flood.c
@@ -157,9 +157,9 @@ static void ospf_process_self_originated_lsa(struct ospf *ospf,
 
 	if (IS_DEBUG_OSPF_EVENT)
 		zlog_debug(
-			"LSA[Type%d:%s]: Process self-originated LSA seq 0x%x",
-			new->data->type, inet_ntoa(new->data->id),
-			ntohl(new->data->ls_seqnum));
+			"%s:LSA[Type%d:%s]: Process self-originated LSA seq 0x%x",
+			ospf_get_name(ospf), new->data->type,
+			inet_ntoa(new->data->id), ntohl(new->data->ls_seqnum));
 
 	/* If we're here, we installed a self-originated LSA that we received
 	   from a neighbor, i.e. it's more recent.  We must see whether we want
@@ -276,8 +276,8 @@ int ospf_flood(struct ospf *ospf, struct ospf_neighbor *nbr,
 
 	if (IS_DEBUG_OSPF_EVENT)
 		zlog_debug(
-			"LSA[Flooding]: start, NBR %s (%s), cur(%p), New-LSA[%s]",
-			inet_ntoa(nbr->router_id),
+			"%s:LSA[Flooding]: start, NBR %s (%s), cur(%p), New-LSA[%s]",
+			ospf_get_name(ospf), inet_ntoa(nbr->router_id),
 			lookup_msg(ospf_nsm_state_msg, nbr->state, NULL),
 			(void *)current, dump_lsa_key(new));
 
@@ -295,15 +295,16 @@ int ospf_flood(struct ospf *ospf, struct ospf_neighbor *nbr,
 				   == OSPF_INITIAL_SEQUENCE_NUMBER)) {
 			if (IS_DEBUG_OSPF_EVENT)
 				zlog_debug(
-					"LSA[Flooding]: Got a self-originated LSA, "
-					"while local one is initial instance.");
+					"%s:LSA[Flooding]: Got a self-originated LSA, while local one is initial instance.",
+					ospf_get_name(ospf));
 			; /* Accept this LSA for quick LSDB resynchronization.
 			     */
 		} else if (monotime_since(&current->tv_recv, NULL)
 			   < ospf->min_ls_arrival * 1000LL) {
 			if (IS_DEBUG_OSPF_EVENT)
 				zlog_debug(
-					"LSA[Flooding]: LSA is received recently.");
+					"%s:LSA[Flooding]: LSA is received recently.",
+					ospf_get_name(ospf));
 			return -1;
 		}
 	}
@@ -376,9 +377,8 @@ static int ospf_flood_through_interface(struct ospf_interface *oi,
 
 	if (IS_DEBUG_OSPF_EVENT)
 		zlog_debug(
-			"ospf_flood_through_interface(): "
-			"considering int %s, INBR(%s), LSA[%s] AGE %u",
-			IF_NAME(oi), inbr ? inet_ntoa(inbr->router_id) : "NULL",
+			"%s:ospf_flood_through_interface(): considering int %s, INBR(%s), LSA[%s] AGE %u",
+			ospf_get_name(oi->ospf), IF_NAME(oi), inbr ? inet_ntoa(inbr->router_id) : "NULL",
 			dump_lsa_key(lsa), ntohs(lsa->data->ls_age));
 
 	if (!ospf_if_is_enable(oi))
@@ -399,8 +399,9 @@ static int ospf_flood_through_interface(struct ospf_interface *oi,
 		onbr = rn->info;
 		if (IS_DEBUG_OSPF_EVENT)
 			zlog_debug(
-				"ospf_flood_through_interface(): considering nbr %s (%s)",
+				"ospf_flood_through_interface(): considering nbr %s(%s) (%s)",
 				inet_ntoa(onbr->router_id),
+				ospf_get_name(oi->ospf),
 				lookup_msg(ospf_nsm_state_msg, onbr->state,
 					   NULL));
 
@@ -737,9 +738,10 @@ void ospf_ls_request_add(struct ospf_neighbor *nbr, struct ospf_lsa *lsa)
 	 * the common function "ospf_lsdb_add()" -- endo.
 	 */
 	if (IS_DEBUG_OSPF(lsa, LSA_FLOODING))
-		zlog_debug("RqstL(%lu)++, NBR(%s), LSA[%s]",
+		zlog_debug("RqstL(%lu)++, NBR(%s(%s)), LSA[%s]",
 			   ospf_ls_request_count(nbr),
-			   inet_ntoa(nbr->router_id), dump_lsa_key(lsa));
+			   inet_ntoa(nbr->router_id),
+			   ospf_get_name(nbr->oi->ospf), dump_lsa_key(lsa));
 
 	ospf_lsdb_add(&nbr->ls_req, lsa);
 }
@@ -763,9 +765,10 @@ void ospf_ls_request_delete(struct ospf_neighbor *nbr, struct ospf_lsa *lsa)
 	}
 
 	if (IS_DEBUG_OSPF(lsa, LSA_FLOODING)) /* -- endo. */
-		zlog_debug("RqstL(%lu)--, NBR(%s), LSA[%s]",
+		zlog_debug("RqstL(%lu)--, NBR(%s(%s)), LSA[%s]",
 			   ospf_ls_request_count(nbr),
-			   inet_ntoa(nbr->router_id), dump_lsa_key(lsa));
+			   inet_ntoa(nbr->router_id),
+			   ospf_get_name(nbr->oi->ospf), dump_lsa_key(lsa));
 
 	ospf_lsdb_delete(&nbr->ls_req, lsa);
 }
@@ -823,6 +826,12 @@ void ospf_ls_retransmit_add(struct ospf_neighbor *nbr, struct ospf_lsa *lsa)
 	if (ospf_lsa_more_recent(old, lsa) < 0) {
 		if (old) {
 			old->retransmit_counter--;
+			if (IS_DEBUG_OSPF(lsa, LSA_FLOODING))
+				zlog_debug("RXmtL(%lu)--, NBR(%s(%s)), LSA[%s]",
+					   ospf_ls_retransmit_count(nbr),
+					   inet_ntoa(nbr->router_id),
+					   ospf_get_name(nbr->oi->ospf),
+					   dump_lsa_key(old));
 			ospf_lsdb_delete(&nbr->ls_rxmt, old);
 		}
 		lsa->retransmit_counter++;
@@ -835,9 +844,10 @@ void ospf_ls_retransmit_add(struct ospf_neighbor *nbr, struct ospf_lsa *lsa)
 		 * the common function "ospf_lsdb_add()" -- endo.
 		 */
 		if (IS_DEBUG_OSPF(lsa, LSA_FLOODING))
-			zlog_debug("RXmtL(%lu)++, NBR(%s), LSA[%s]",
+			zlog_debug("RXmtL(%lu)++, NBR(%s(%s)), LSA[%s]",
 				   ospf_ls_retransmit_count(nbr),
 				   inet_ntoa(nbr->router_id),
+				   ospf_get_name(nbr->oi->ospf),
 				   dump_lsa_key(lsa));
 		ospf_lsdb_add(&nbr->ls_rxmt, lsa);
 	}
@@ -849,9 +859,10 @@ void ospf_ls_retransmit_delete(struct ospf_neighbor *nbr, struct ospf_lsa *lsa)
 	if (ospf_ls_retransmit_lookup(nbr, lsa)) {
 		lsa->retransmit_counter--;
 		if (IS_DEBUG_OSPF(lsa, LSA_FLOODING)) /* -- endo. */
-			zlog_debug("RXmtL(%lu)--, NBR(%s), LSA[%s]",
+			zlog_debug("RXmtL(%lu)--, NBR(%s(%s)), LSA[%s]",
 				   ospf_ls_retransmit_count(nbr),
 				   inet_ntoa(nbr->router_id),
+				   ospf_get_name(nbr->oi->ospf),
 				   dump_lsa_key(lsa));
 		ospf_lsdb_delete(&nbr->ls_rxmt, lsa);
 	}
diff --git a/ospfd/ospf_interface.c b/ospfd/ospf_interface.c
index 5459e3b87..7ddffbcdb 100644
--- a/ospfd/ospf_interface.c
+++ b/ospfd/ospf_interface.c
@@ -273,7 +273,7 @@ struct ospf_interface *ospf_if_new(struct ospf *ospf, struct interface *ifp,
 	if (IS_DEBUG_OSPF_EVENT)
 		zlog_debug("%s: ospf interface %s vrf %s id %u created",
 			   __PRETTY_FUNCTION__, ifp->name,
-			   ospf_vrf_id_to_name(ospf->vrf_id), ospf->vrf_id);
+			   ospf_get_name(ospf), ospf->vrf_id);
 
 	return oi;
 }
@@ -832,7 +832,7 @@ struct ospf_interface *ospf_vl_new(struct ospf *ospf,
 	struct prefix_ipv4 *p;
 
 	if (IS_DEBUG_OSPF_EVENT)
-		zlog_debug("ospf_vl_new(): Start");
+		zlog_debug("ospf_vl_new()(%s): Start", ospf_get_name(ospf));
 	if (vlink_count == OSPF_VL_MAX_COUNT) {
 		if (IS_DEBUG_OSPF_EVENT)
 			zlog_debug(
diff --git a/ospfd/ospf_nsm.c b/ospfd/ospf_nsm.c
index 00174b638..110738802 100644
--- a/ospfd/ospf_nsm.c
+++ b/ospfd/ospf_nsm.c
@@ -65,8 +65,9 @@ static int ospf_inactivity_timer(struct thread *thread)
 	nbr->t_inactivity = NULL;
 
 	if (IS_DEBUG_OSPF(nsm, NSM_TIMERS))
-		zlog_debug("NSM[%s:%s]: Timer (Inactivity timer expire)",
-			   IF_NAME(nbr->oi), inet_ntoa(nbr->router_id));
+		zlog_debug("NSM[%s:%s:%s]: Timer (Inactivity timer expire)",
+			   IF_NAME(nbr->oi), inet_ntoa(nbr->router_id),
+			   ospf_get_name(nbr->oi->ospf));
 
 	OSPF_NSM_EVENT_SCHEDULE(nbr, NSM_InactivityTimer);
 
@@ -81,8 +82,9 @@ static int ospf_db_desc_timer(struct thread *thread)
 	nbr->t_db_desc = NULL;
 
 	if (IS_DEBUG_OSPF(nsm, NSM_TIMERS))
-		zlog_debug("NSM[%s:%s]: Timer (DD Retransmit timer expire)",
-			   IF_NAME(nbr->oi), inet_ntoa(nbr->src));
+		zlog_debug("NSM[%s:%s:%s]: Timer (DD Retransmit timer expire)",
+			   IF_NAME(nbr->oi), inet_ntoa(nbr->src),
+			   ospf_get_name(nbr->oi->ospf));
 
 	/* resent last send DD packet. */
 	assert(nbr->last_send);
@@ -387,9 +389,10 @@ static int nsm_kill_nbr(struct ospf_neighbor *nbr)
 
 		if (IS_DEBUG_OSPF(nsm, NSM_EVENTS))
 			zlog_debug(
-				"NSM[%s:%s]: Down (PollIntervalTimer scheduled)",
+				"NSM[%s:%s:%s]: Down (PollIntervalTimer scheduled)",
 				IF_NAME(nbr->oi),
-				inet_ntoa(nbr->address.u.prefix4));
+				inet_ntoa(nbr->address.u.prefix4),
+				ospf_get_name(nbr->oi->ospf));
 	}
 
 	return 0;
@@ -585,8 +588,9 @@ static void nsm_notice_state_change(struct ospf_neighbor *nbr, int next_state,
 {
 	/* Logging change of status. */
 	if (IS_DEBUG_OSPF(nsm, NSM_STATUS))
-		zlog_debug("NSM[%s:%s]: State change %s -> %s (%s)",
+		zlog_debug("NSM[%s:%s:%s]: State change %s -> %s (%s)",
 			   IF_NAME(nbr->oi), inet_ntoa(nbr->router_id),
+			   ospf_get_name(nbr->oi->ospf),
 			   lookup_msg(ospf_nsm_state_msg, nbr->state, NULL),
 			   lookup_msg(ospf_nsm_state_msg, next_state, NULL),
 			   ospf_nsm_event_str[event]);
@@ -595,8 +599,9 @@ static void nsm_notice_state_change(struct ospf_neighbor *nbr, int next_state,
 	if (CHECK_FLAG(nbr->oi->ospf->config, OSPF_LOG_ADJACENCY_CHANGES)
 	    && (CHECK_FLAG(nbr->oi->ospf->config, OSPF_LOG_ADJACENCY_DETAIL)
 		|| (next_state == NSM_Full) || (next_state < nbr->state)))
-		zlog_notice("AdjChg: Nbr %s on %s: %s -> %s (%s)",
-			    inet_ntoa(nbr->router_id), IF_NAME(nbr->oi),
+		zlog_notice("AdjChg: Nbr %s(%s) on %s: %s -> %s (%s)",
+			    inet_ntoa(nbr->router_id),
+			    ospf_get_name(nbr->oi->ospf), IF_NAME(nbr->oi),
 			    lookup_msg(ospf_nsm_state_msg, nbr->state, NULL),
 			    lookup_msg(ospf_nsm_state_msg, next_state, NULL),
 			    ospf_nsm_event_str[event]);
@@ -677,9 +682,10 @@ static void nsm_change_state(struct ospf_neighbor *nbr, int state)
 
 		if (CHECK_FLAG(oi->ospf->config, OSPF_LOG_ADJACENCY_DETAIL))
 			zlog_info(
-				"%s:(%s, %s -> %s): "
+				"%s:[%s:%s], %s -> %s): "
 				"scheduling new router-LSA origination",
 				__PRETTY_FUNCTION__, inet_ntoa(nbr->router_id),
+				ospf_get_name(oi->ospf),
 				lookup_msg(ospf_nsm_state_msg, old_state, NULL),
 				lookup_msg(ospf_nsm_state_msg, state, NULL));
 
@@ -753,8 +759,9 @@ int ospf_nsm_event(struct thread *thread)
 	event = THREAD_VAL(thread);
 
 	if (IS_DEBUG_OSPF(nsm, NSM_EVENTS))
-		zlog_debug("NSM[%s:%s]: %s (%s)", IF_NAME(nbr->oi),
+		zlog_debug("NSM[%s:%s:%s]: %s (%s)", IF_NAME(nbr->oi),
 			   inet_ntoa(nbr->router_id),
+			   ospf_get_name(nbr->oi->ospf),
 			   lookup_msg(ospf_nsm_state_msg, nbr->state, NULL),
 			   ospf_nsm_event_str[event]);
 
@@ -777,9 +784,10 @@ int ospf_nsm_event(struct thread *thread)
 			 */
 			flog_err(
 				EC_OSPF_FSM_INVALID_STATE,
-				"NSM[%s:%s]: %s (%s): "
+				"NSM[%s:%s:%s]: %s (%s): "
 				"Warning: action tried to change next_state to %s",
 				IF_NAME(nbr->oi), inet_ntoa(nbr->router_id),
+				ospf_get_name(nbr->oi->ospf),
 				lookup_msg(ospf_nsm_state_msg, nbr->state,
 					   NULL),
 				ospf_nsm_event_str[event],
diff --git a/ospfd/ospf_packet.c b/ospfd/ospf_packet.c
index 6c7531a36..a9067e011 100644
--- a/ospfd/ospf_packet.c
+++ b/ospfd/ospf_packet.c
@@ -2381,6 +2381,10 @@ static struct stream *ospf_recv_packet(struct ospf *ospf, int fd,
 		return NULL;
 	}
 
+	if (IS_DEBUG_OSPF_PACKET(0, RECV))
+		zlog_debug("%s: fd %d(%s) on interface %d(%s)",
+			   __PRETTY_FUNCTION__, fd, ospf_get_name(ospf),
+			   ifindex, *ifp ? (*ifp)->name : "Unknown");
 	return ibuf;
 }
 
@@ -2981,8 +2985,15 @@ int ospf_read(struct thread *thread)
 				      ospf->vrf_id);
 		if (c)
 			ifp = c->ifp;
-		if (ifp == NULL)
+		if (ifp == NULL) {
+			if (IS_DEBUG_OSPF_PACKET(0, RECV))
+				zlog_debug(
+					"%s: Unable to determine incoming interface from: %s(%s)",
+					__PRETTY_FUNCTION__,
+					inet_ntoa(iph->ip_src),
+					ospf_get_name(ospf));
 			return 0;
+		}
 	}
 
 	/* IP Header dump. */