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>

diff --git a/ospfd/ospf_asbr.c b/ospfd/ospf_asbr.c
index ea919017d36c91394fee8e9614c12f6c719b9598..a60af36564f6974ff5c9bb756ab398f069f0e439 100644 (file)
--- 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 a72caa8415bbaa46dd61139a2dd26680c89cdb62..381fb6820fbe311ef3c465a412b39835ce5d385f 100644 (file)
--- 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 5459e3b87c5d4ed87b298eed2cd2398b5fae42a6..7ddffbcdbdc36d289b076f7a8ac27cd2d762cae1 100644 (file)
--- 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 00174b638eaff8c5fe317a6b32b9922f1a1401f4..110738802c5db15fe3f7587feb8922a02b96479f 100644 (file)
--- 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 6c7531a3626e452f18c79dad89e067450c0fd653..a9067e011958871b82cfc1f143576035a528273f 100644 (file)
--- 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. */