bfdd: add debug fine tuning capabilities

Move most of the log messages to debug guards so they only get activated
if the user configured the proper debug level.

Current debug levels:
- Peer events.
- Zebra events.
- Network layer debugs.

Signed-off-by: Rafael Zalamena <rzalamena@opensourcerouting.org>

5 files changed, 208 insertions, 68 deletions

diff --git a/bfdd/bfd.c b/bfdd/bfd.c
index e1c662941..80bfae632 100644
--- a/bfdd/bfd.c
+++ b/bfdd/bfd.c
@@ -169,7 +169,9 @@ int bfd_session_enable(struct bfd_session *bs)
 
 	/* Sanity check: don't leak open sockets. */
 	if (bs->sock != -1) {
-		zlog_debug("session-enable: previous socket open");
+		if (bglobal.debug_peer_event)
+			zlog_debug("session-enable: previous socket open");
+
 		close(bs->sock);
 		bs->sock = -1;
 	}
@@ -318,9 +320,10 @@ void ptm_bfd_sess_up(struct bfd_session *bfd)
 
 	if (old_state != bfd->ses_state) {
 		bfd->stats.session_up++;
-		zlog_debug("state-change: [%s] %s -> %s", bs_to_string(bfd),
-			   state_list[old_state].str,
-			   state_list[bfd->ses_state].str);
+		if (bglobal.debug_peer_event)
+			zlog_debug("state-change: [%s] %s -> %s",
+				   bs_to_string(bfd), state_list[old_state].str,
+				   state_list[bfd->ses_state].str);
 	}
 }
 
@@ -357,10 +360,11 @@ void ptm_bfd_sess_dn(struct bfd_session *bfd, uint8_t diag)
 
 	if (old_state != bfd->ses_state) {
 		bfd->stats.session_down++;
-		zlog_debug("state-change: [%s] %s -> %s reason:%s",
-			   bs_to_string(bfd), state_list[old_state].str,
-			   state_list[bfd->ses_state].str,
-			   get_diag_str(bfd->local_diag));
+		if (bglobal.debug_peer_event)
+			zlog_debug("state-change: [%s] %s -> %s reason:%s",
+				   bs_to_string(bfd), state_list[old_state].str,
+				   state_list[bfd->ses_state].str,
+				   get_diag_str(bfd->local_diag));
 	}
 }
 
@@ -758,7 +762,8 @@ struct bfd_session *bs_registrate(struct bfd_session *bfd)
 	if (bfd->key.ifname[0] || bfd->key.vrfname[0] || bfd->sock == -1)
 		bs_observer_add(bfd);
 
-	zlog_debug("session-new: %s", bs_to_string(bfd));
+	if (bglobal.debug_peer_event)
+		zlog_debug("session-new: %s", bs_to_string(bfd));
 
 	control_notify_config(BCM_NOTIFY_CONFIG_ADD, bfd);
 
@@ -782,7 +787,8 @@ int ptm_bfd_sess_del(struct bfd_peer_cfg *bpc)
 		return -1;
 	}
 
-	zlog_debug("session-delete: %s", bs_to_string(bs));
+	if (bglobal.debug_peer_event)
+		zlog_debug("session-delete: %s", bs_to_string(bs));
 
 	control_notify_config(BCM_NOTIFY_CONFIG_DELETE, bs);
 
@@ -849,8 +855,9 @@ static void bs_down_handler(struct bfd_session *bs, int nstate)
 		break;
 
 	default:
-		zlog_debug("state-change: unhandled neighbor state: %d",
-			   nstate);
+		if (bglobal.debug_peer_event)
+			zlog_debug("state-change: unhandled neighbor state: %d",
+				   nstate);
 		break;
 	}
 }
@@ -877,8 +884,9 @@ static void bs_init_handler(struct bfd_session *bs, int nstate)
 		break;
 
 	default:
-		zlog_debug("state-change: unhandled neighbor state: %d",
-			   nstate);
+		if (bglobal.debug_peer_event)
+			zlog_debug("state-change: unhandled neighbor state: %d",
+				   nstate);
 		break;
 	}
 }
@@ -908,11 +916,11 @@ static void bs_neighbour_admin_down_handler(struct bfd_session *bfd,
 
 	if (old_state != bfd->ses_state) {
 		bfd->stats.session_down++;
-
-		zlog_debug("state-change: [%s] %s -> %s reason:%s",
-			   bs_to_string(bfd), state_list[old_state].str,
-			   state_list[bfd->ses_state].str,
-			   get_diag_str(bfd->local_diag));
+		if (bglobal.debug_peer_event)
+			zlog_debug("state-change: [%s] %s -> %s reason:%s",
+				   bs_to_string(bfd), state_list[old_state].str,
+				   state_list[bfd->ses_state].str,
+				   get_diag_str(bfd->local_diag));
 	}
 }
 
@@ -934,8 +942,9 @@ static void bs_up_handler(struct bfd_session *bs, int nstate)
 		break;
 
 	default:
-		zlog_debug("state-change: unhandled neighbor state: %d",
-			   nstate);
+		if (bglobal.debug_peer_event)
+			zlog_debug("state-change: unhandled neighbor state: %d",
+				   nstate);
 		break;
 	}
 }
@@ -957,8 +966,9 @@ void bs_state_handler(struct bfd_session *bs, int nstate)
 		break;
 
 	default:
-		zlog_debug("state-change: [%s] is in invalid state: %d",
-			   bs_to_string(bs), nstate);
+		if (bglobal.debug_peer_event)
+			zlog_debug("state-change: [%s] is in invalid state: %d",
+				   bs_to_string(bs), nstate);
 		break;
 	}
 }
@@ -1433,12 +1443,14 @@ struct bfd_session *bfd_key_lookup(struct bfd_key key)
 		memset(&bs.key.local, 0, sizeof(bs.key.local));
 		bsp = hash_lookup(bfd_key_hash, &bs);
 		if (bsp) {
-			char addr_buf[INET6_ADDRSTRLEN];
-
-			inet_ntop(bs.key.family, &key.local, addr_buf,
-				  sizeof(addr_buf));
-			zlog_debug(" peer %s found, but loc-addr %s ignored",
-				   peer_buf, addr_buf);
+			if (bglobal.debug_peer_event) {
+				char addr_buf[INET6_ADDRSTRLEN];
+				inet_ntop(bs.key.family, &key.local, addr_buf,
+					  sizeof(addr_buf));
+				zlog_debug(
+					" peer %s found, but loc-addr %s ignored",
+					peer_buf, addr_buf);
+			}
 			return bsp;
 		}
 	}
@@ -1449,8 +1461,9 @@ struct bfd_session *bfd_key_lookup(struct bfd_key key)
 		memset(bs.key.ifname, 0, sizeof(bs.key.ifname));
 		bsp = hash_lookup(bfd_key_hash, &bs);
 		if (bsp) {
-			zlog_debug(" peer %s found, but ifp %s ignored",
-				   peer_buf, key.ifname);
+			if (bglobal.debug_peer_event)
+				zlog_debug(" peer %s found, but ifp %s ignored",
+					   peer_buf, key.ifname);
 			return bsp;
 		}
 	}
@@ -1460,14 +1473,15 @@ struct bfd_session *bfd_key_lookup(struct bfd_key key)
 		memset(&bs.key.local, 0, sizeof(bs.key.local));
 		bsp = hash_lookup(bfd_key_hash, &bs);
 		if (bsp) {
-			char addr_buf[INET6_ADDRSTRLEN];
-
-			inet_ntop(bs.key.family, &bs.key.local, addr_buf,
-				  sizeof(addr_buf));
-			zlog_debug(
-				" peer %s found, but ifp %s"
-				" and loc-addr %s ignored",
-				peer_buf, key.ifname, addr_buf);
+			if (bglobal.debug_peer_event) {
+				char addr_buf[INET6_ADDRSTRLEN];
+				inet_ntop(bs.key.family, &bs.key.local,
+					  addr_buf, sizeof(addr_buf));
+				zlog_debug(
+					" peer %s found, but ifp %s"
+					" and loc-addr %s ignored",
+					peer_buf, key.ifname, addr_buf);
+			}
 			return bsp;
 		}
 	}
@@ -1485,10 +1499,11 @@ struct bfd_session *bfd_key_lookup(struct bfd_key key)
 	/* change key */
 	if (ctx.result) {
 		bsp = ctx.result;
-		zlog_debug(
-			" peer %s found, but ifp"
-			" and/or loc-addr params ignored",
-			peer_buf);
+		if (bglobal.debug_peer_event)
+			zlog_debug(
+				" peer %s found, but ifp"
+				" and/or loc-addr params ignored",
+				peer_buf);
 	}
 	return bsp;
 }
@@ -1676,13 +1691,17 @@ void bfd_sessions_remove_manual(void)
  */
 static int bfd_vrf_new(struct vrf *vrf)
 {
-	zlog_debug("VRF Created: %s(%u)", vrf->name, vrf->vrf_id);
+	if (bglobal.debug_zebra)
+		zlog_debug("VRF Created: %s(%u)", vrf->name, vrf->vrf_id);
+
 	return 0;
 }
 
 static int bfd_vrf_delete(struct vrf *vrf)
 {
-	zlog_debug("VRF Deletion: %s(%u)", vrf->name, vrf->vrf_id);
+	if (bglobal.debug_zebra)
+		zlog_debug("VRF Deletion: %s(%u)", vrf->name, vrf->vrf_id);
+
 	return 0;
 }
 
@@ -1690,7 +1709,10 @@ static int bfd_vrf_update(struct vrf *vrf)
 {
 	if (!vrf_is_enabled(vrf))
 		return 0;
-	zlog_debug("VRF update: %s(%u)", vrf->name, vrf->vrf_id);
+
+	if (bglobal.debug_zebra)
+		zlog_debug("VRF update: %s(%u)", vrf->name, vrf->vrf_id);
+
 	/* a different name is given; update bfd list */
 	bfdd_sessions_enable_vrf(vrf);
 	return 0;
@@ -1707,7 +1729,10 @@ static int bfd_vrf_enable(struct vrf *vrf)
 		vrf->info = (void *)bvrf;
 	} else
 		bvrf = vrf->info;
-	zlog_debug("VRF enable add %s id %u", vrf->name, vrf->vrf_id);
+
+	if (bglobal.debug_zebra)
+		zlog_debug("VRF enable add %s id %u", vrf->name, vrf->vrf_id);
+
 	if (vrf->vrf_id == VRF_DEFAULT ||
 	    vrf_get_backend() == VRF_BACKEND_NETNS) {
 		if (!bvrf->bg_shop)
@@ -1763,7 +1788,8 @@ static int bfd_vrf_disable(struct vrf *vrf)
 		bfdd_zclient_unregister(vrf->vrf_id);
 	}
 
-	zlog_debug("VRF disable %s id %d", vrf->name, vrf->vrf_id);
+	if (bglobal.debug_zebra)
+		zlog_debug("VRF disable %s id %d", vrf->name, vrf->vrf_id);
 
 	/* Disable read/write poll triggering. */
 	THREAD_OFF(bvrf->bg_ev[0]);
diff --git a/bfdd/bfd.h b/bfdd/bfd.h
index a786bb71b..1cc9ddb47 100644
--- a/bfdd/bfd.h
+++ b/bfdd/bfd.h
@@ -393,7 +393,26 @@ struct bfd_global {
 	struct obslist bg_obslist;
 
 	struct zebra_privs_t bfdd_privs;
+
+	/* Debug options. */
+	/* Show all peer state changes events. */
+	bool debug_peer_event;
+	/*
+	 * Show zebra message exchanges:
+	 * - Interface add/delete.
+	 * - Local address add/delete.
+	 * - VRF add/delete.
+	 */
+	bool debug_zebra;
+	/*
+	 * Show network level debug information:
+	 * - Echo packets without session.
+	 * - Unavailable peer sessions.
+	 * - Network system call failures.
+	 */
+	bool debug_network;
 };
+
 extern struct bfd_global bglobal;
 extern const struct bfd_diag_str_list diag_list[];
 extern const struct bfd_state_str_list state_list[];
diff --git a/bfdd/bfd_packet.c b/bfdd/bfd_packet.c
index 79971fb3e..68bdd89bb 100644
--- a/bfdd/bfd_packet.c
+++ b/bfdd/bfd_packet.c
@@ -112,11 +112,16 @@ int _ptm_bfd_send(struct bfd_session *bs, uint16_t *port, const void *data,
 #endif /* HAVE_STRUCT_SOCKADDR_SA_LEN */
 	rv = sendto(sd, data, datalen, 0, sa, slen);
 	if (rv <= 0) {
-		zlog_debug("packet-send: send failure: %s", strerror(errno));
+		if (bglobal.debug_network)
+			zlog_debug("packet-send: send failure: %s",
+				   strerror(errno));
 		return -1;
 	}
-	if (rv < (ssize_t)datalen)
-		zlog_debug("packet-send: send partial: %s", strerror(errno));
+	if (rv < (ssize_t)datalen) {
+		if (bglobal.debug_network)
+			zlog_debug("packet-send: send partial: %s",
+				   strerror(errno));
+	}
 
 	return 0;
 }
@@ -190,14 +195,16 @@ static int ptm_bfd_process_echo_pkt(struct bfd_vrf_global *bvrf, int s)
 	/* Your discriminator not zero - use it to find session */
 	bfd = bfd_id_lookup(my_discr);
 	if (bfd == NULL) {
-		zlog_debug("echo-packet: no matching session (id:%u)",
-			   my_discr);
+		if (bglobal.debug_network)
+			zlog_debug("echo-packet: no matching session (id:%u)",
+				   my_discr);
 		return -1;
 	}
 
 	if (!CHECK_FLAG(bfd->flags, BFD_SESS_FLAG_ECHO_ACTIVE)) {
-		zlog_debug("echo-packet: echo disabled [%s] (id:%u)",
-			   bs_to_string(bfd), my_discr);
+		if (bglobal.debug_network)
+			zlog_debug("echo-packet: echo disabled [%s] (id:%u)",
+				   bs_to_string(bfd), my_discr);
 		return -1;
 	}
 
@@ -313,8 +320,9 @@ ssize_t bfd_recv_ipv4(int sd, uint8_t *msgbuf, size_t msgbuflen, uint8_t *ttl,
 
 			memcpy(&ttlval, CMSG_DATA(cm), sizeof(ttlval));
 			if (ttlval > 255) {
-				zlog_debug("ipv4-recv: invalid TTL: %u",
-					   ttlval);
+				if (bglobal.debug_network)
+					zlog_debug("ipv4-recv: invalid TTL: %u",
+						   ttlval);
 				return -1;
 			}
 			*ttl = ttlval;
@@ -420,8 +428,9 @@ ssize_t bfd_recv_ipv6(int sd, uint8_t *msgbuf, size_t msgbuflen, uint8_t *ttl,
 		if (cm->cmsg_type == IPV6_HOPLIMIT) {
 			memcpy(&ttlval, CMSG_DATA(cm), sizeof(ttlval));
 			if (ttlval > 255) {
-				zlog_debug("ipv6-recv: invalid TTL: %u",
-					   ttlval);
+				if (bglobal.debug_network)
+					zlog_debug("ipv6-recv: invalid TTL: %u",
+						   ttlval);
 				return -1;
 			}
 
@@ -487,6 +496,10 @@ static void cp_debug(bool mhop, struct sockaddr_any *peer,
 	char buf[512], peerstr[128], localstr[128], portstr[64], vrfstr[64];
 	va_list vl;
 
+	/* Don't to any processing if debug is disabled. */
+	if (bglobal.debug_network == false)
+		return;
+
 	if (peer->sa_sin.sin_family)
 		snprintf(peerstr, sizeof(peerstr), " peer:%s", satostr(peer));
 	else
@@ -797,12 +810,14 @@ int bp_udp_send(int sd, uint8_t ttl, uint8_t *data, size_t datalen,
 	/* Send echo back. */
 	wlen = sendmsg(sd, &msg, 0);
 	if (wlen <= 0) {
-		zlog_debug("udp-send: loopback failure: (%d) %s", errno,
-			   strerror(errno));
+		if (bglobal.debug_network)
+			zlog_debug("udp-send: loopback failure: (%d) %s", errno,
+				   strerror(errno));
 		return -1;
 	} else if (wlen < (ssize_t)datalen) {
-		zlog_debug("udp-send: partial send: %zd expected %zu", wlen,
-			   datalen);
+		if (bglobal.debug_network)
+			zlog_debug("udp-send: partial send: %zd expected %zu",
+				   wlen, datalen);
 		return -1;
 	}
 
diff --git a/bfdd/bfdd_vty.c b/bfdd/bfdd_vty.c
index 74ffd6d62..f539c6d27 100644
--- a/bfdd/bfdd_vty.c
+++ b/bfdd/bfdd_vty.c
@@ -738,6 +738,42 @@ DEFPY(bfd_show_peers_brief, bfd_show_peers_brief_cmd,
 	return CMD_SUCCESS;
 }
 
+DEFPY(
+	bfd_debug_peer, bfd_debug_peer_cmd,
+	"[no] debug bfd peer",
+	NO_STR
+	DEBUG_STR
+	"Bidirection Forwarding Detection\n"
+	"Peer events debugging\n")
+{
+	bglobal.debug_peer_event = !no;
+	return CMD_SUCCESS;
+}
+
+DEFPY(
+	bfd_debug_zebra, bfd_debug_zebra_cmd,
+	"[no] debug bfd zebra",
+	NO_STR
+	DEBUG_STR
+	"Bidirection Forwarding Detection\n"
+	"Zebra events debugging\n")
+{
+	bglobal.debug_zebra = !no;
+	return CMD_SUCCESS;
+}
+
+DEFPY(
+	bfd_debug_network, bfd_debug_network_cmd,
+	"[no] debug bfd network",
+	NO_STR
+	DEBUG_STR
+	"Bidirection Forwarding Detection\n"
+	"Network layer debugging\n")
+{
+	bglobal.debug_network = !no;
+	return CMD_SUCCESS;
+}
+
 /*
  * Function definitions.
  */
@@ -842,6 +878,9 @@ DEFUN_NOSH(show_debugging_bfd,
 	   "BFD daemon\n")
 {
 	vty_out(vty, "BFD debugging status:\n");
+	vty_out(vty, "  Peer events debugging.\n");
+	vty_out(vty, "  Zebra events debugging.\n");
+	vty_out(vty, "  Network layer debugging.\n");
 
 	return CMD_SUCCESS;
 }
@@ -863,6 +902,21 @@ static int bfdd_write_config(struct vty *vty)
 	struct lyd_node *dnode;
 	int written = 0;
 
+	if (bglobal.debug_peer_event) {
+		vty_out(vty, "debug bfd peer\n");
+		written = 1;
+	}
+
+	if (bglobal.debug_zebra) {
+		vty_out(vty, "debug bfd zebra\n");
+		written = 1;
+	}
+
+	if (bglobal.debug_network) {
+		vty_out(vty, "debug bfd network\n");
+		written = 1;
+	}
+
 	dnode = yang_dnode_get(running_config->dnode, "/frr-bfdd:bfdd");
 	if (dnode) {
 		nb_cli_show_dnode_cmds(vty, dnode, false);
@@ -882,6 +936,14 @@ void bfdd_vty_init(void)
 	install_element(ENABLE_NODE, &bfd_show_peers_brief_cmd);
 	install_element(ENABLE_NODE, &show_debugging_bfd_cmd);
 
+	install_element(ENABLE_NODE, &bfd_debug_peer_cmd);
+	install_element(ENABLE_NODE, &bfd_debug_zebra_cmd);
+	install_element(ENABLE_NODE, &bfd_debug_network_cmd);
+
+	install_element(CONFIG_NODE, &bfd_debug_peer_cmd);
+	install_element(CONFIG_NODE, &bfd_debug_zebra_cmd);
+	install_element(CONFIG_NODE, &bfd_debug_network_cmd);
+
 	/* Install BFD node and commands. */
 	install_node(&bfd_node, bfdd_write_config);
 	install_default(BFD_NODE);
diff --git a/bfdd/ptm_adapter.c b/bfdd/ptm_adapter.c
index eae2158ac..0f1c4d06c 100644
--- a/bfdd/ptm_adapter.c
+++ b/bfdd/ptm_adapter.c
@@ -419,8 +419,9 @@ static void bfdd_dest_register(struct stream *msg, vrf_id_t vrf_id)
 	if (bs == NULL) {
 		bs = ptm_bfd_sess_new(&bpc);
 		if (bs == NULL) {
-			zlog_debug(
-				"ptm-add-dest: failed to create BFD session");
+			if (bglobal.debug_zebra)
+				zlog_debug(
+					"ptm-add-dest: failed to create BFD session");
 			return;
 		}
 	} else {
@@ -456,7 +457,8 @@ static void bfdd_dest_deregister(struct stream *msg, vrf_id_t vrf_id)
 	/* Find or start new BFD session. */
 	bs = bs_peer_find(&bpc);
 	if (bs == NULL) {
-		zlog_debug("ptm-del-dest: failed to find BFD session");
+		if (bglobal.debug_zebra)
+			zlog_debug("ptm-del-dest: failed to find BFD session");
 		return;
 	}
 
@@ -511,7 +513,9 @@ static void bfdd_client_deregister(struct stream *msg)
 
 	pc = pc_lookup(pid);
 	if (pc == NULL) {
-		zlog_debug("ptm-del-client: failed to find client: %u", pid);
+		if (bglobal.debug_zebra)
+			zlog_debug("ptm-del-client: failed to find client: %u",
+				   pid);
 		return;
 	}
 
@@ -546,7 +550,8 @@ static int bfdd_replay(ZAPI_CALLBACK_ARGS)
 		break;
 
 	default:
-		zlog_debug("ptm-replay: invalid message type %u", rcmd);
+		if (bglobal.debug_zebra)
+			zlog_debug("ptm-replay: invalid message type %u", rcmd);
 		return -1;
 	}
 
@@ -674,6 +679,9 @@ void bfdd_sessions_disable_vrf(struct vrf *vrf)
 
 static int bfd_ifp_destroy(struct interface *ifp)
 {
+	if (bglobal.debug_zebra)
+		zlog_debug("zclient: delete interface %s", ifp->name);
+
 	bfdd_sessions_disable_interface(ifp);
 
 	return 0;
@@ -719,11 +727,18 @@ static void bfdd_sessions_enable_address(struct connected *ifc)
 static int bfdd_interface_address_update(ZAPI_CALLBACK_ARGS)
 {
 	struct connected *ifc;
+	char buf[64];
 
 	ifc = zebra_interface_address_read(cmd, zclient->ibuf, vrf_id);
 	if (ifc == NULL)
 		return 0;
 
+	if (bglobal.debug_zebra)
+		zlog_debug("zclient: %s local address %s",
+			   cmd == ZEBRA_INTERFACE_ADDRESS_ADD ? "add"
+							      : "delete",
+			   prefix2str(ifc->address, buf, sizeof(buf)));
+
 	bfdd_sessions_enable_address(ifc);
 
 	return 0;
@@ -731,6 +746,9 @@ static int bfdd_interface_address_update(ZAPI_CALLBACK_ARGS)
 
 static int bfd_ifp_create(struct interface *ifp)
 {
+	if (bglobal.debug_zebra)
+		zlog_debug("zclient: add interface %s", ifp->name);
+
 	bfdd_sessions_enable_interface(ifp);
 
 	return 0;