From 21d1e85db584a5707e8323307df7044017356c10 Mon Sep 17 00:00:00 2001 From: Rafael Zalamena Date: Thu, 26 May 2022 09:54:27 -0300 Subject: [PATCH 1/3] pimd,yang: log MSDP neighbor events Move MSDP neighbor events global debug to per PIM instance. Signed-off-by: Rafael Zalamena --- pimd/pim_cmd.c | 16 +++++++ pimd/pim_instance.c | 5 ++ pimd/pim_instance.h | 7 +++ pimd/pim_msdp.c | 106 ++++++++++++++++++------------------------- pimd/pim_msdp.h | 1 + pimd/pim_nb.c | 6 +++ pimd/pim_nb.h | 1 + pimd/pim_nb_config.c | 30 ++++++++++++ yang/frr-pim.yang | 7 +++ 9 files changed, 117 insertions(+), 62 deletions(-) diff --git a/pimd/pim_cmd.c b/pimd/pim_cmd.c index 934da2d53e67..e23492ca3b4f 100644 --- a/pimd/pim_cmd.c +++ b/pimd/pim_cmd.c @@ -8267,6 +8267,21 @@ DEFUN (show_ip_msdp_sa_sg_vrf_all, return CMD_SUCCESS; } +DEFPY(msdp_log_neighbor_changes, msdp_log_neighbor_changes_cmd, + "[no] msdp log neighbor-events", + NO_STR + MSDP_STR + "MSDP log messages\n" + "MSDP log neighbor event messages\n") +{ + char xpath_value[XPATH_MAXLEN + 32]; + + snprintf(xpath_value, sizeof(xpath_value), "%s/msdp/log-neighbor-events", VTY_CURR_XPATH); + nb_cli_enqueue_change(vty, xpath_value, no ? NB_OP_DESTROY : NB_OP_MODIFY, "true"); + + return nb_cli_apply_changes(vty, NULL); +} + struct pim_sg_cache_walk_data { struct vty *vty; json_object *json; @@ -8898,6 +8913,7 @@ void pim_cmd_init(void) install_element(PIM_NODE, &pim_msdp_mesh_group_source_cmd); install_element(PIM_NODE, &no_pim_msdp_mesh_group_source_cmd); install_element(PIM_NODE, &no_pim_msdp_mesh_group_cmd); + install_element(PIM_NODE, &msdp_log_neighbor_changes_cmd); install_element(PIM_NODE, &pim_bsr_candidate_rp_cmd); install_element(PIM_NODE, &pim_bsr_candidate_rp_group_cmd); diff --git a/pimd/pim_instance.c b/pimd/pim_instance.c index e18ae97d6fcc..bec6e49e1896 100644 --- a/pimd/pim_instance.c +++ b/pimd/pim_instance.c @@ -272,3 +272,8 @@ void pim_vrf_terminate(void) vrf_terminate(); } + +bool pim_msdp_log_neighbor_events(const struct pim_instance *pim) +{ + return (pim->log_flags & PIM_MSDP_LOG_NEIGHBOR_EVENTS); +} diff --git a/pimd/pim_instance.h b/pimd/pim_instance.h index 1b7815d86c51..a4e550c9d00b 100644 --- a/pimd/pim_instance.h +++ b/pimd/pim_instance.h @@ -192,6 +192,11 @@ struct pim_instance { uint64_t gm_rx_drop_sys; + /** Log information flags. */ + uint32_t log_flags; +/** Log neighbor event messages. */ +#define PIM_MSDP_LOG_NEIGHBOR_EVENTS 0x01 + bool stopping; #if PIM_IPV == 6 @@ -218,4 +223,6 @@ extern struct pim_router *router; struct pim_instance *pim_get_pim_instance(vrf_id_t vrf_id); +extern bool pim_msdp_log_neighbor_events(const struct pim_instance *pim); + #endif diff --git a/pimd/pim_msdp.c b/pimd/pim_msdp.c index 0c87b3f48548..fc07d9239d1e 100644 --- a/pimd/pim_msdp.c +++ b/pimd/pim_msdp.c @@ -744,7 +744,7 @@ static void pim_msdp_peer_state_chg_log(struct pim_msdp_peer *mp) char state_str[PIM_MSDP_STATE_STRLEN]; pim_msdp_state_dump(mp->state, state_str, sizeof(state_str)); - zlog_debug("MSDP peer %s state chg to %s", mp->key_str, state_str); + zlog_info("MSDP peer %s state changed to %s", mp->key_str, state_str); } /* MSDP Connection State Machine actions (defined in RFC-3618:Sec-11.2) */ @@ -753,9 +753,8 @@ static void pim_msdp_peer_state_chg_log(struct pim_msdp_peer *mp) static void pim_msdp_peer_connect(struct pim_msdp_peer *mp) { mp->state = PIM_MSDP_CONNECTING; - if (PIM_DEBUG_MSDP_EVENTS) { + if (pim_msdp_log_neighbor_events(mp->pim)) pim_msdp_peer_state_chg_log(mp); - } pim_msdp_peer_cr_timer_setup(mp, true /* start */); } @@ -764,9 +763,8 @@ static void pim_msdp_peer_connect(struct pim_msdp_peer *mp) static void pim_msdp_peer_listen(struct pim_msdp_peer *mp) { mp->state = PIM_MSDP_LISTEN; - if (PIM_DEBUG_MSDP_EVENTS) { + if (pim_msdp_log_neighbor_events(mp->pim)) pim_msdp_peer_state_chg_log(mp); - } /* this is interntionally asymmetric i.e. we set up listen-socket when * the @@ -790,9 +788,8 @@ void pim_msdp_peer_established(struct pim_msdp_peer *mp) mp->state = PIM_MSDP_ESTABLISHED; mp->uptime = pim_time_monotonic_sec(); - if (PIM_DEBUG_MSDP_EVENTS) { + if (pim_msdp_log_neighbor_events(mp->pim)) pim_msdp_peer_state_chg_log(mp); - } /* stop retry timer on active peers */ pim_msdp_peer_cr_timer_setup(mp, false /* start */); @@ -816,9 +813,9 @@ void pim_msdp_peer_stop_tcp_conn(struct pim_msdp_peer *mp, bool chg_state) ++mp->est_flaps; } mp->state = PIM_MSDP_INACTIVE; - if (PIM_DEBUG_MSDP_EVENTS) { + + if (pim_msdp_log_neighbor_events(mp->pim)) pim_msdp_peer_state_chg_log(mp); - } } if (PIM_DEBUG_MSDP_INTERNAL) { @@ -851,10 +848,10 @@ void pim_msdp_peer_stop_tcp_conn(struct pim_msdp_peer *mp, bool chg_state) /* RFC-3618:Sec-5.6 - stop the peer tcp connection and startover */ void pim_msdp_peer_reset_tcp_conn(struct pim_msdp_peer *mp, const char *rc_str) { - if (PIM_DEBUG_EVENTS) { - zlog_debug("MSDP peer %s tcp reset %s", mp->key_str, rc_str); - snprintf(mp->last_reset, sizeof(mp->last_reset), "%s", rc_str); - } + if (pim_msdp_log_neighbor_events(mp->pim)) + zlog_info("MSDP peer %s tcp reset %s", mp->key_str, rc_str); + + snprintf(mp->last_reset, sizeof(mp->last_reset), "%s", rc_str); /* close the connection and transition to listening or connecting */ pim_msdp_peer_stop_tcp_conn(mp, true /* chg_state */); @@ -865,12 +862,6 @@ void pim_msdp_peer_reset_tcp_conn(struct pim_msdp_peer *mp, const char *rc_str) } } -static void pim_msdp_peer_timer_expiry_log(struct pim_msdp_peer *mp, - const char *timer_str) -{ - zlog_debug("MSDP peer %s %s timer expired", mp->key_str, timer_str); -} - /* RFC-3618:Sec-5.4 - peer hold timer */ static void pim_msdp_peer_hold_timer_cb(struct event *t) { @@ -878,17 +869,16 @@ static void pim_msdp_peer_hold_timer_cb(struct event *t) mp = EVENT_ARG(t); - if (PIM_DEBUG_MSDP_EVENTS) { - pim_msdp_peer_timer_expiry_log(mp, "hold"); - } + if (pim_msdp_log_neighbor_events(mp->pim)) + zlog_info("MSDP peer %s hold timer expired", mp->key_str); if (mp->state != PIM_MSDP_ESTABLISHED) { return; } - if (PIM_DEBUG_MSDP_EVENTS) { + if (pim_msdp_log_neighbor_events(mp->pim)) pim_msdp_peer_state_chg_log(mp); - } + pim_msdp_peer_reset_tcp_conn(mp, "ht-expired"); } @@ -910,9 +900,8 @@ static void pim_msdp_peer_ka_timer_cb(struct event *t) mp = EVENT_ARG(t); - if (PIM_DEBUG_MSDP_EVENTS) { - pim_msdp_peer_timer_expiry_log(mp, "ka"); - } + if (pim_msdp_log_neighbor_events(mp->pim)) + zlog_info("MSDP peer %s keep alive timer expired", mp->key_str); pim_msdp_pkt_ka_tx(mp); pim_msdp_peer_ka_timer_setup(mp, true /* start */); @@ -970,9 +959,8 @@ static void pim_msdp_peer_cr_timer_cb(struct event *t) mp = EVENT_ARG(t); - if (PIM_DEBUG_MSDP_EVENTS) { - pim_msdp_peer_timer_expiry_log(mp, "connect-retry"); - } + if (pim_msdp_log_neighbor_events(mp->pim)) + zlog_info("MSDP peer %s connection retry timer expired", mp->key_str); if (mp->state != PIM_MSDP_CONNECTING || PIM_MSDP_PEER_IS_LISTENER(mp)) { return; @@ -1051,8 +1039,8 @@ struct pim_msdp_peer *pim_msdp_peer_add(struct pim_instance *pim, mp = hash_get(pim->msdp.peer_hash, mp, hash_alloc_intern); listnode_add_sort(pim->msdp.peer_list, mp); - if (PIM_DEBUG_MSDP_EVENTS) { - zlog_debug("MSDP peer %s created", mp->key_str); + if (pim_msdp_log_neighbor_events(pim)) { + zlog_info("MSDP peer %s created", mp->key_str); pim_msdp_peer_state_chg_log(mp); } @@ -1116,9 +1104,8 @@ void pim_msdp_peer_del(struct pim_msdp_peer **mp) listnode_delete((*mp)->pim->msdp.peer_list, *mp); hash_release((*mp)->pim->msdp.peer_hash, *mp); - if (PIM_DEBUG_MSDP_EVENTS) { - zlog_debug("MSDP peer %s deleted", (*mp)->key_str); - } + if (pim_msdp_log_neighbor_events((*mp)->pim)) + zlog_info("MSDP peer %s deleted", (*mp)->key_str); /* free up any associated memory */ pim_msdp_peer_free(*mp); @@ -1193,10 +1180,8 @@ void pim_msdp_mg_free(struct pim_instance *pim, struct pim_msdp_mg **mgp) for (ALL_LIST_ELEMENTS((*mgp)->mbr_list, n, nn, mbr)) pim_msdp_mg_mbr_del((*mgp), mbr); - if (PIM_DEBUG_MSDP_EVENTS) { - zlog_debug("MSDP mesh-group %s deleted", - (*mgp)->mesh_group_name); - } + if (pim_msdp_log_neighbor_events(pim)) + zlog_info("MSDP mesh-group %s deleted", (*mgp)->mesh_group_name); XFREE(MTYPE_PIM_MSDP_MG_NAME, (*mgp)->mesh_group_name); @@ -1213,15 +1198,14 @@ struct pim_msdp_mg *pim_msdp_mg_new(struct pim_instance *pim, struct pim_msdp_mg *mg; mg = XCALLOC(MTYPE_PIM_MSDP_MG, sizeof(*mg)); - + mg->pim = pim; mg->mesh_group_name = XSTRDUP(MTYPE_PIM_MSDP_MG_NAME, mesh_group_name); mg->mbr_list = list_new(); mg->mbr_list->del = (void (*)(void *))pim_msdp_mg_mbr_free; mg->mbr_list->cmp = (int (*)(void *, void *))pim_msdp_mg_mbr_comp; - if (PIM_DEBUG_MSDP_EVENTS) { - zlog_debug("MSDP mesh-group %s created", mg->mesh_group_name); - } + if (pim_msdp_log_neighbor_events(pim)) + zlog_info("MSDP mesh-group %s created", mg->mesh_group_name); SLIST_INSERT_HEAD(&pim->msdp.mglist, mg, mg_entry); @@ -1255,12 +1239,10 @@ void pim_msdp_mg_mbr_del(struct pim_msdp_mg *mg, struct pim_msdp_mg_mbr *mbr) } listnode_delete(mg->mbr_list, mbr); - if (PIM_DEBUG_MSDP_EVENTS) { - char ip_str[INET_ADDRSTRLEN]; - pim_inet4_dump("", mbr->mbr_ip, ip_str, sizeof(ip_str)); - zlog_debug("MSDP mesh-group %s mbr %s deleted", - mg->mesh_group_name, ip_str); - } + if (pim_msdp_log_neighbor_events(mg->pim)) + zlog_info("MSDP mesh-group %s neighbor %pI4 deleted", mg->mesh_group_name, + &mbr->mbr_ip); + pim_msdp_mg_mbr_free(mbr); if (mg->mbr_cnt) { --mg->mbr_cnt; @@ -1277,10 +1259,9 @@ static void pim_msdp_src_del(struct pim_msdp_mg *mg) if (mbr->mp) pim_msdp_peer_del(&mbr->mp); } - if (PIM_DEBUG_MSDP_EVENTS) { - zlog_debug("MSDP mesh-group %s src cleared", - mg->mesh_group_name); - } + + if (pim_msdp_log_neighbor_events(mg->pim)) + zlog_info("MSDP mesh-group %s source cleared", mg->mesh_group_name); } /*********************** MSDP feature APIs *********************************/ @@ -1292,6 +1273,9 @@ int pim_msdp_config_write(struct pim_instance *pim, struct vty *vty) char src_str[INET_ADDRSTRLEN]; int count = 0; + if (pim_msdp_log_neighbor_events(pim)) + vty_out(vty, " msdp log neighbor-events\n"); + if (SLIST_EMPTY(&pim->msdp.mglist)) return count; @@ -1426,9 +1410,8 @@ void pim_msdp_mg_src_add(struct pim_instance *pim, struct pim_msdp_mg *mg, /* No new address, disable everyone. */ if (ai->s_addr == INADDR_ANY) { - if (PIM_DEBUG_MSDP_EVENTS) - zlog_debug("MSDP mesh-group %s src unset", - mg->mesh_group_name); + if (pim_msdp_log_neighbor_events(pim)) + zlog_info("MSDP mesh-group %s source unset", mg->mesh_group_name); return; } @@ -1437,9 +1420,8 @@ void pim_msdp_mg_src_add(struct pim_instance *pim, struct pim_msdp_mg *mg, mbr->mp = pim_msdp_peer_add(pim, &mbr->mbr_ip, &mg->src_ip, mg->mesh_group_name); - if (PIM_DEBUG_MSDP_EVENTS) - zlog_debug("MSDP mesh-group %s src %pI4 set", - mg->mesh_group_name, &mg->src_ip); + if (pim_msdp_log_neighbor_events(pim)) + zlog_info("MSDP mesh-group %s source %pI4 set", mg->mesh_group_name, &mg->src_ip); } struct pim_msdp_mg_mbr *pim_msdp_mg_mbr_add(struct pim_instance *pim, @@ -1457,9 +1439,9 @@ struct pim_msdp_mg_mbr *pim_msdp_mg_mbr_add(struct pim_instance *pim, mbr->mp = pim_msdp_peer_add(pim, &mbr->mbr_ip, &mg->src_ip, mg->mesh_group_name); - if (PIM_DEBUG_MSDP_EVENTS) - zlog_debug("MSDP mesh-group %s mbr %pI4 created", - mg->mesh_group_name, &mbr->mbr_ip); + if (pim_msdp_log_neighbor_events(pim)) + zlog_info("MSDP mesh-group %s neighbor %pI4 created", mg->mesh_group_name, + &mbr->mbr_ip); ++mg->mbr_cnt; diff --git a/pimd/pim_msdp.h b/pimd/pim_msdp.h index cd1f6647f69f..0a7c74e438e7 100644 --- a/pimd/pim_msdp.h +++ b/pimd/pim_msdp.h @@ -165,6 +165,7 @@ struct pim_msdp_mg { struct in_addr src_ip; uint32_t mbr_cnt; struct list *mbr_list; + struct pim_instance *pim; /** Belongs to PIM instance list. */ SLIST_ENTRY(pim_msdp_mg) mg_entry; diff --git a/pimd/pim_nb.c b/pimd/pim_nb.c index 1dc66be82d7d..29e8f9a782ce 100644 --- a/pimd/pim_nb.c +++ b/pimd/pim_nb.c @@ -129,6 +129,12 @@ const struct frr_yang_module_info frr_pim_info = { .modify = pim_msdp_connection_retry_modify, } }, + { + .xpath = "/frr-routing:routing/control-plane-protocols/control-plane-protocol/frr-pim:pim/address-family/msdp/log-neighbor-events", + .cbs = { + .modify = pim_msdp_log_neighbor_events_modify, + } + }, { .xpath = "/frr-routing:routing/control-plane-protocols/control-plane-protocol/frr-pim:pim/address-family/msdp-mesh-groups", .cbs = { diff --git a/pimd/pim_nb.h b/pimd/pim_nb.h index b45af3d589da..48dc6574a8ec 100644 --- a/pimd/pim_nb.h +++ b/pimd/pim_nb.h @@ -54,6 +54,7 @@ int routing_control_plane_protocols_control_plane_protocol_pim_address_family_ss int pim_msdp_hold_time_modify(struct nb_cb_modify_args *args); int pim_msdp_keep_alive_modify(struct nb_cb_modify_args *args); int pim_msdp_connection_retry_modify(struct nb_cb_modify_args *args); +int pim_msdp_log_neighbor_events_modify(struct nb_cb_modify_args *args); int pim_msdp_mesh_group_create(struct nb_cb_create_args *args); int pim_msdp_mesh_group_destroy(struct nb_cb_destroy_args *args); int pim_msdp_mesh_group_members_create(struct nb_cb_create_args *args); diff --git a/pimd/pim_nb_config.c b/pimd/pim_nb_config.c index 87338f37c0ea..fa1c744cfcd3 100644 --- a/pimd/pim_nb_config.c +++ b/pimd/pim_nb_config.c @@ -1064,8 +1064,38 @@ pim6_msdp_err(routing_control_plane_protocols_control_plane_protocol_pim_address pim6_msdp_err(pim_msdp_peer_authentication_type_modify, nb_cb_modify_args); pim6_msdp_err(pim_msdp_peer_authentication_key_modify, nb_cb_modify_args); pim6_msdp_err(pim_msdp_peer_authentication_key_destroy, nb_cb_destroy_args); +pim6_msdp_err(pim_msdp_log_neighbor_events_modify, nb_cb_modify_args); #if PIM_IPV != 6 +/* + * XPath: + * /frr-routing:routing/control-plane-protocols/control-plane-protocol/frr-pim:pim/address-family/msdp/log-neighbor-events + */ +int pim_msdp_log_neighbor_events_modify(struct nb_cb_modify_args *args) +{ + struct pim_instance *pim; + struct vrf *vrf; + + switch (args->event) { + case NB_EV_VALIDATE: + case NB_EV_PREPARE: + case NB_EV_ABORT: + /* NOTHING */ + break; + + case NB_EV_APPLY: + vrf = nb_running_get_entry(args->dnode, NULL, true); + pim = vrf->info; + if (yang_dnode_get_bool(args->dnode, NULL)) + SET_FLAG(pim->log_flags, PIM_MSDP_LOG_NEIGHBOR_EVENTS); + else + UNSET_FLAG(pim->log_flags, PIM_MSDP_LOG_NEIGHBOR_EVENTS); + break; + } + + return NB_OK; +} + /* * XPath: * /frr-routing:routing/control-plane-protocols/control-plane-protocol/frr-pim:pim/address-family/msdp-mesh-groups diff --git a/yang/frr-pim.yang b/yang/frr-pim.yang index 6a6c52185ddb..d1e95cef2e8b 100644 --- a/yang/frr-pim.yang +++ b/yang/frr-pim.yang @@ -250,6 +250,13 @@ module frr-pim { container msdp { description "Global MSDP configuration."; uses msdp-timers; + + leaf log-neighbor-events { + type boolean; + default false; + description + "Log all MSDP neighbor related events."; + } } list msdp-mesh-groups { From fc39bfaa0a2f3556d3986a01828e0647cb47d747 Mon Sep 17 00:00:00 2001 From: Rafael Zalamena Date: Thu, 26 May 2022 11:22:27 -0300 Subject: [PATCH 2/3] pimd,yang: log MSDP SA events Add new command to log all SA events. Signed-off-by: Rafael Zalamena --- pimd/pim_cmd.c | 17 +++++++++ pimd/pim_instance.c | 5 +++ pimd/pim_instance.h | 3 ++ pimd/pim_msdp.c | 80 +++++++++++++++++------------------------- pimd/pim_msdp_packet.c | 27 +++++++------- pimd/pim_nb.c | 6 ++++ pimd/pim_nb.h | 1 + pimd/pim_nb_config.c | 30 ++++++++++++++++ yang/frr-pim.yang | 7 ++++ 9 files changed, 114 insertions(+), 62 deletions(-) diff --git a/pimd/pim_cmd.c b/pimd/pim_cmd.c index e23492ca3b4f..bd79ddadf442 100644 --- a/pimd/pim_cmd.c +++ b/pimd/pim_cmd.c @@ -8282,6 +8282,22 @@ DEFPY(msdp_log_neighbor_changes, msdp_log_neighbor_changes_cmd, return nb_cli_apply_changes(vty, NULL); } +DEFPY(msdp_log_sa_changes, msdp_log_sa_changes_cmd, + "[no] msdp log sa-events", + NO_STR + MSDP_STR + "MSDP log messages\n" + "MSDP log SA event messages\n") +{ + char xpath_value[XPATH_MAXLEN + 32]; + + snprintf(xpath_value, sizeof(xpath_value), "%s/msdp/log-sa-events", VTY_CURR_XPATH); + nb_cli_enqueue_change(vty, xpath_value, no ? NB_OP_DESTROY : NB_OP_MODIFY, "true"); + + return nb_cli_apply_changes(vty, NULL); +} + + struct pim_sg_cache_walk_data { struct vty *vty; json_object *json; @@ -8914,6 +8930,7 @@ void pim_cmd_init(void) install_element(PIM_NODE, &no_pim_msdp_mesh_group_source_cmd); install_element(PIM_NODE, &no_pim_msdp_mesh_group_cmd); install_element(PIM_NODE, &msdp_log_neighbor_changes_cmd); + install_element(PIM_NODE, &msdp_log_sa_changes_cmd); install_element(PIM_NODE, &pim_bsr_candidate_rp_cmd); install_element(PIM_NODE, &pim_bsr_candidate_rp_group_cmd); diff --git a/pimd/pim_instance.c b/pimd/pim_instance.c index bec6e49e1896..4e4e5a6ce8f9 100644 --- a/pimd/pim_instance.c +++ b/pimd/pim_instance.c @@ -277,3 +277,8 @@ bool pim_msdp_log_neighbor_events(const struct pim_instance *pim) { return (pim->log_flags & PIM_MSDP_LOG_NEIGHBOR_EVENTS); } + +bool pim_msdp_log_sa_events(const struct pim_instance *pim) +{ + return (pim->log_flags & PIM_MSDP_LOG_SA_EVENTS); +} diff --git a/pimd/pim_instance.h b/pimd/pim_instance.h index a4e550c9d00b..dab7ed269828 100644 --- a/pimd/pim_instance.h +++ b/pimd/pim_instance.h @@ -196,6 +196,8 @@ struct pim_instance { uint32_t log_flags; /** Log neighbor event messages. */ #define PIM_MSDP_LOG_NEIGHBOR_EVENTS 0x01 +/** Log SA event messages. */ +#define PIM_MSDP_LOG_SA_EVENTS 0x02 bool stopping; @@ -224,5 +226,6 @@ extern struct pim_router *router; struct pim_instance *pim_get_pim_instance(vrf_id_t vrf_id); extern bool pim_msdp_log_neighbor_events(const struct pim_instance *pim); +extern bool pim_msdp_log_sa_events(const struct pim_instance *pim); #endif diff --git a/pimd/pim_msdp.c b/pimd/pim_msdp.c index fc07d9239d1e..a536ab6fe031 100644 --- a/pimd/pim_msdp.c +++ b/pimd/pim_msdp.c @@ -47,20 +47,13 @@ static int pim_msdp_mg_mbr_comp(const void *p1, const void *p2); static void pim_msdp_mg_mbr_free(struct pim_msdp_mg_mbr *mbr); /************************ SA cache management ******************************/ -static void pim_msdp_sa_timer_expiry_log(struct pim_msdp_sa *sa, - const char *timer_str) -{ - zlog_debug("MSDP SA %s %s timer expired", sa->sg_str, timer_str); -} - /* RFC-3618:Sec-5.1 - global active source advertisement timer */ static void pim_msdp_sa_adv_timer_cb(struct event *t) { struct pim_instance *pim = EVENT_ARG(t); - if (PIM_DEBUG_MSDP_EVENTS) { - zlog_debug("MSDP SA advertisement timer expired"); - } + if (pim_msdp_log_sa_events(pim)) + zlog_info("MSDP SA advertisement timer expired"); pim_msdp_sa_adv_timer_setup(pim, true /* start */); pim_msdp_pkt_sa_tx(pim); @@ -83,9 +76,8 @@ static void pim_msdp_sa_state_timer_cb(struct event *t) sa = EVENT_ARG(t); - if (PIM_DEBUG_MSDP_EVENTS) { - pim_msdp_sa_timer_expiry_log(sa, "state"); - } + if (pim_msdp_log_sa_events(sa->pim)) + zlog_info("MSDP SA %s state timer expired", sa->sg_str); pim_msdp_sa_deref(sa, PIM_MSDP_SAF_PEER); } @@ -120,9 +112,8 @@ static void pim_msdp_sa_upstream_del(struct pim_msdp_sa *sa) sa->flags &= ~PIM_MSDP_SAF_UP_DEL_IN_PROG; } - if (PIM_DEBUG_MSDP_EVENTS) { - zlog_debug("MSDP SA %s de-referenced SPT", sa->sg_str); - } + if (pim_msdp_log_sa_events(sa->pim)) + zlog_info("MSDP SA %s de-referenced SPT", sa->sg_str); } static bool pim_msdp_sa_upstream_add_ok(struct pim_msdp_sa *sa, @@ -185,10 +176,8 @@ static void pim_msdp_sa_upstream_update(struct pim_msdp_sa *sa, if (up && (PIM_UPSTREAM_FLAG_TEST_SRC_MSDP(up->flags))) { /* somehow we lost track of the upstream ptr? best log it */ sa->up = up; - if (PIM_DEBUG_MSDP_EVENTS) { - zlog_debug("MSDP SA %s SPT reference missing", - sa->sg_str); - } + if (pim_msdp_log_sa_events(sa->pim)) + zlog_info("MSDP SA %s SPT reference missing", sa->sg_str); return; } @@ -204,14 +193,11 @@ static void pim_msdp_sa_upstream_update(struct pim_msdp_sa *sa, /* should we also start the kat in parallel? we will need it * when the * SA ages out */ - if (PIM_DEBUG_MSDP_EVENTS) { - zlog_debug("MSDP SA %s referenced SPT", sa->sg_str); - } + if (pim_msdp_log_sa_events(sa->pim)) + zlog_info("MSDP SA %s referenced SPT", sa->sg_str); } else { - if (PIM_DEBUG_MSDP_EVENTS) { - zlog_debug("MSDP SA %s SPT reference failed", - sa->sg_str); - } + if (pim_msdp_log_sa_events(sa->pim)) + zlog_info("MSDP SA %s SPT reference failed", sa->sg_str); } } @@ -240,9 +226,8 @@ static struct pim_msdp_sa *pim_msdp_sa_new(struct pim_instance *pim, sa = hash_get(pim->msdp.sa_hash, sa, hash_alloc_intern); listnode_add_sort(pim->msdp.sa_list, sa); - if (PIM_DEBUG_MSDP_EVENTS) { - zlog_debug("MSDP SA %s created", sa->sg_str); - } + if (pim_msdp_log_sa_events(pim)) + zlog_info("MSDP SA %s created", sa->sg_str); return sa; } @@ -282,9 +267,8 @@ static void pim_msdp_sa_del(struct pim_msdp_sa *sa) listnode_delete(sa->pim->msdp.sa_list, sa); hash_release(sa->pim->msdp.sa_hash, sa); - if (PIM_DEBUG_MSDP_EVENTS) { - zlog_debug("MSDP SA %s deleted", sa->sg_str); - } + if (pim_msdp_log_sa_events(sa->pim)) + zlog_info("MSDP SA %s deleted", sa->sg_str); /* free up any associated memory */ pim_msdp_sa_free(sa); @@ -333,10 +317,9 @@ static void pim_msdp_sa_deref(struct pim_msdp_sa *sa, if ((sa->flags & PIM_MSDP_SAF_LOCAL)) { if (flags & PIM_MSDP_SAF_LOCAL) { - if (PIM_DEBUG_MSDP_EVENTS) { - zlog_debug("MSDP SA %s local reference removed", - sa->sg_str); - } + if (pim_msdp_log_sa_events(sa->pim)) + zlog_info("MSDP SA %s local reference removed", sa->sg_str); + if (sa->pim->msdp.local_cnt) --sa->pim->msdp.local_cnt; } @@ -346,10 +329,9 @@ static void pim_msdp_sa_deref(struct pim_msdp_sa *sa, if (flags & PIM_MSDP_SAF_PEER) { struct in_addr rp; - if (PIM_DEBUG_MSDP_EVENTS) { - zlog_debug("MSDP SA %s peer reference removed", - sa->sg_str); - } + if (pim_msdp_log_sa_events(sa->pim)) + zlog_info("MSDP SA %s peer reference removed", sa->sg_str); + pim_msdp_sa_state_timer_setup(sa, false /* start */); rp.s_addr = INADDR_ANY; pim_msdp_sa_peer_ip_set(sa, NULL /* mp */, rp); @@ -386,10 +368,8 @@ void pim_msdp_sa_ref(struct pim_instance *pim, struct pim_msdp_peer *mp, if (mp) { if (!(sa->flags & PIM_MSDP_SAF_PEER)) { sa->flags |= PIM_MSDP_SAF_PEER; - if (PIM_DEBUG_MSDP_EVENTS) { - zlog_debug("MSDP SA %s added by peer", - sa->sg_str); - } + if (pim_msdp_log_sa_events(pim)) + zlog_info("MSDP SA %s added by peer", sa->sg_str); } pim_msdp_sa_peer_ip_set(sa, mp, rp); /* start/re-start the state timer to prevent cache expiry */ @@ -403,10 +383,9 @@ void pim_msdp_sa_ref(struct pim_instance *pim, struct pim_msdp_peer *mp, if (!(sa->flags & PIM_MSDP_SAF_LOCAL)) { sa->flags |= PIM_MSDP_SAF_LOCAL; ++sa->pim->msdp.local_cnt; - if (PIM_DEBUG_MSDP_EVENTS) { - zlog_debug("MSDP SA %s added locally", - sa->sg_str); - } + if (pim_msdp_log_sa_events(pim)) + zlog_info("MSDP SA %s added locally", sa->sg_str); + /* send an immediate SA update to peers */ pim_addr_to_prefix(&grp, sa->sg.grp); rp_info = pim_rp_find_match_group(pim, &grp); @@ -710,6 +689,9 @@ bool pim_msdp_peer_rpf_check(struct pim_msdp_peer *mp, struct in_addr rp) return true; } + if (pim_msdp_log_sa_events(mp->pim)) + zlog_info("MSDP peer %pI4 RPF failure for %pI4", &mp->peer, &rp); + return false; } @@ -1275,6 +1257,8 @@ int pim_msdp_config_write(struct pim_instance *pim, struct vty *vty) if (pim_msdp_log_neighbor_events(pim)) vty_out(vty, " msdp log neighbor-events\n"); + if (pim_msdp_log_sa_events(pim)) + vty_out(vty, " msdp log sa-events\n"); if (SLIST_EMPTY(&pim->msdp.mglist)) return count; diff --git a/pimd/pim_msdp_packet.c b/pimd/pim_msdp_packet.c index 27f4966a1cc3..f66a941ee312 100644 --- a/pimd/pim_msdp_packet.c +++ b/pimd/pim_msdp_packet.c @@ -487,9 +487,8 @@ static void pim_msdp_pkt_sa_gen(struct pim_instance *pim, } if (msdp_peer_sa_filter(mp, sa)) { - if (PIM_DEBUG_MSDP_EVENTS) - zlog_debug("MSDP peer %pI4 filter SA out %s", - &mp->peer, sa->sg_str); + if (pim_msdp_log_sa_events(pim)) + zlog_info("MSDP peer %pI4 filter SA out %s", &mp->peer, sa->sg_str); continue; } @@ -551,9 +550,9 @@ void pim_msdp_pkt_sa_tx_one(struct pim_msdp_sa *sa) pim_msdp_pkt_sa_fill_one(sa); for (ALL_LIST_ELEMENTS_RO(sa->pim->msdp.peer_list, node, mp)) { if (msdp_peer_sa_filter(mp, sa)) { - if (PIM_DEBUG_MSDP_EVENTS) - zlog_debug("MSDP peer %pI4 filter SA out %s", - &mp->peer, sa->sg_str); + if (pim_msdp_log_sa_events(sa->pim)) + zlog_info("MSDP peer %pI4 filter SA out %s", &mp->peer, sa->sg_str); + continue; } @@ -583,9 +582,10 @@ void pim_msdp_pkt_sa_tx_one_to_one_peer(struct pim_msdp_peer *mp, /* Don't push it if filtered. */ if (msdp_peer_sa_filter(mp, &sa)) { - if (PIM_DEBUG_MSDP_EVENTS) - zlog_debug("MSDP peer %pI4 filter SA out (%pI4, %pI4)", - &mp->peer, &sa.sg.src, &sa.sg.grp); + if (pim_msdp_log_sa_events(mp->pim)) + zlog_info("MSDP peer %pI4 filter SA out (%pI4, %pI4)", &mp->peer, + &sa.sg.src, &sa.sg.grp); + return; } @@ -641,11 +641,10 @@ static void pim_msdp_pkt_sa_rx_one(struct pim_msdp_peer *mp, struct in_addr rp) /* Filter incoming SA with configured access list. */ if (mp->acl_in) { acl = access_list_lookup(AFI_IP, mp->acl_in); - if (msdp_access_list_apply(acl, &sg.src, &sg.grp) == - FILTER_DENY) { - if (PIM_DEBUG_MSDP_EVENTS) - zlog_debug("MSDP peer %pI4 filter SA in (%pI4, %pI4)", - &mp->peer, &sg.src, &sg.grp); + if (msdp_access_list_apply(acl, &sg.src, &sg.grp) == FILTER_DENY) { + if (pim_msdp_log_sa_events(mp->pim)) + zlog_info("MSDP peer %pI4 filter SA in (%pI4, %pI4)", &mp->peer, + &sg.src, &sg.grp); return; } } diff --git a/pimd/pim_nb.c b/pimd/pim_nb.c index 29e8f9a782ce..e9221125243e 100644 --- a/pimd/pim_nb.c +++ b/pimd/pim_nb.c @@ -135,6 +135,12 @@ const struct frr_yang_module_info frr_pim_info = { .modify = pim_msdp_log_neighbor_events_modify, } }, + { + .xpath = "/frr-routing:routing/control-plane-protocols/control-plane-protocol/frr-pim:pim/address-family/msdp/log-sa-events", + .cbs = { + .modify = pim_msdp_log_sa_events_modify, + } + }, { .xpath = "/frr-routing:routing/control-plane-protocols/control-plane-protocol/frr-pim:pim/address-family/msdp-mesh-groups", .cbs = { diff --git a/pimd/pim_nb.h b/pimd/pim_nb.h index 48dc6574a8ec..61cc9c162811 100644 --- a/pimd/pim_nb.h +++ b/pimd/pim_nb.h @@ -55,6 +55,7 @@ int pim_msdp_hold_time_modify(struct nb_cb_modify_args *args); int pim_msdp_keep_alive_modify(struct nb_cb_modify_args *args); int pim_msdp_connection_retry_modify(struct nb_cb_modify_args *args); int pim_msdp_log_neighbor_events_modify(struct nb_cb_modify_args *args); +int pim_msdp_log_sa_events_modify(struct nb_cb_modify_args *args); int pim_msdp_mesh_group_create(struct nb_cb_create_args *args); int pim_msdp_mesh_group_destroy(struct nb_cb_destroy_args *args); int pim_msdp_mesh_group_members_create(struct nb_cb_create_args *args); diff --git a/pimd/pim_nb_config.c b/pimd/pim_nb_config.c index fa1c744cfcd3..659b110307ed 100644 --- a/pimd/pim_nb_config.c +++ b/pimd/pim_nb_config.c @@ -1065,6 +1065,7 @@ pim6_msdp_err(pim_msdp_peer_authentication_type_modify, nb_cb_modify_args); pim6_msdp_err(pim_msdp_peer_authentication_key_modify, nb_cb_modify_args); pim6_msdp_err(pim_msdp_peer_authentication_key_destroy, nb_cb_destroy_args); pim6_msdp_err(pim_msdp_log_neighbor_events_modify, nb_cb_modify_args); +pim6_msdp_err(pim_msdp_log_sa_events_modify, nb_cb_modify_args); #if PIM_IPV != 6 /* @@ -1096,6 +1097,35 @@ int pim_msdp_log_neighbor_events_modify(struct nb_cb_modify_args *args) return NB_OK; } +/* + * XPath: + * /frr-routing:routing/control-plane-protocols/control-plane-protocol/frr-pim:pim/address-family/msdp/log-sa-events + */ +int pim_msdp_log_sa_events_modify(struct nb_cb_modify_args *args) +{ + struct pim_instance *pim; + struct vrf *vrf; + + switch (args->event) { + case NB_EV_VALIDATE: + case NB_EV_PREPARE: + case NB_EV_ABORT: + /* NOTHING */ + break; + + case NB_EV_APPLY: + vrf = nb_running_get_entry(args->dnode, NULL, true); + pim = vrf->info; + if (yang_dnode_get_bool(args->dnode, NULL)) + SET_FLAG(pim->log_flags, PIM_MSDP_LOG_SA_EVENTS); + else + UNSET_FLAG(pim->log_flags, PIM_MSDP_LOG_SA_EVENTS); + break; + } + + return NB_OK; +} + /* * XPath: * /frr-routing:routing/control-plane-protocols/control-plane-protocol/frr-pim:pim/address-family/msdp-mesh-groups diff --git a/yang/frr-pim.yang b/yang/frr-pim.yang index d1e95cef2e8b..c3c953b76b42 100644 --- a/yang/frr-pim.yang +++ b/yang/frr-pim.yang @@ -257,6 +257,13 @@ module frr-pim { description "Log all MSDP neighbor related events."; } + + leaf log-sa-events { + type boolean; + default false; + description + "Log all MSDP SA related events."; + } } list msdp-mesh-groups { From 0b0648f15c0ced171dc29961ea374f11dd6a66cc Mon Sep 17 00:00:00 2001 From: Rafael Zalamena Date: Thu, 21 Nov 2024 10:23:37 -0300 Subject: [PATCH 3/3] topotests: test new log toggle Test MSDP new log toggle: the MSDP peer connection state and SA events should be logged. Signed-off-by: Rafael Zalamena --- tests/topotests/msdp_topo1/r1/pimd.conf | 2 ++ tests/topotests/msdp_topo1/test_msdp_topo1.py | 20 +++++++++++++++++++ 2 files changed, 22 insertions(+) diff --git a/tests/topotests/msdp_topo1/r1/pimd.conf b/tests/topotests/msdp_topo1/r1/pimd.conf index 3c116a003bea..1548aed05e18 100644 --- a/tests/topotests/msdp_topo1/r1/pimd.conf +++ b/tests/topotests/msdp_topo1/r1/pimd.conf @@ -22,5 +22,7 @@ ip pim rp 10.254.254.1 ip pim join-prune-interval 5 ! router pim + msdp log neighbor-events + msdp log sa-events msdp peer 192.168.0.2 password 1234 ! diff --git a/tests/topotests/msdp_topo1/test_msdp_topo1.py b/tests/topotests/msdp_topo1/test_msdp_topo1.py index ff80052d2665..1c97f7cb1e47 100755 --- a/tests/topotests/msdp_topo1/test_msdp_topo1.py +++ b/tests/topotests/msdp_topo1/test_msdp_topo1.py @@ -17,6 +17,7 @@ import sys import json from functools import partial +import re import pytest # Save the Current Working Directory to find configuration files. @@ -510,6 +511,25 @@ def test_msdp_sa_filter(): assert val is None, "multicast route convergence failure" +def test_msdp_log_events(): + "Test that the enabled logs are working as expected." + + tgen = get_topogen() + if tgen.routers_have_failure(): + pytest.skip(tgen.errors) + + r1_log = tgen.gears["r1"].net.getLog("log", "pimd") + + # Look up for informational messages that should have been enabled. + match = re.search( + "MSDP peer 192.168.1.2 state changed to established", r1_log) + assert match is not None + + match = re.search( + r"MSDP SA \(192.168.10.100\,229.1.2.3\) created", r1_log) + assert match is not None + + def test_memory_leak(): "Run the memory leak test and report results." tgen = get_topogen()