From 868a0861d2619ee4681132ece26349ea1ddd2d43 Mon Sep 17 00:00:00 2001 From: Donald Sharp Date: Wed, 6 Nov 2019 19:49:06 -0500 Subject: [PATCH] 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 --- ospfd/ospf_asbr.c | 9 +++++--- ospfd/ospf_flood.c | 47 ++++++++++++++++++++++++++---------------- ospfd/ospf_interface.c | 4 ++-- ospfd/ospf_nsm.c | 32 +++++++++++++++++----------- ospfd/ospf_packet.c | 13 +++++++++++- 5 files changed, 69 insertions(+), 36 deletions(-) diff --git a/ospfd/ospf_asbr.c b/ospfd/ospf_asbr.c index ea919017d3..a60af36564 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 a72caa8415..381fb6820f 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(¤t->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 5459e3b87c..7ddffbcdbd 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 00174b638e..110738802c 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 6c7531a362..a9067e0119 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. */ -- 2.39.5