Merge pull request #6214 from opensourcerouting/bfdd-debug

bfdd: code/logging/debug improvements

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) {
+		if (bglobal.debug_peer_event)
 			zlog_debug("session-enable: previous socket open");
+
 		close(bs->sock);
 		bs->sock = -1;
 	}
@@ -318,8 +320,9 @@ 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),
+		if (bglobal.debug_peer_event)
-			   state_list[old_state].str,
+			zlog_debug("state-change: [%s] %s -> %s",
+				   bs_to_string(bfd), state_list[old_state].str,
 				   state_list[bfd->ses_state].str);
 	}
 }
@@ -357,6 +360,7 @@ void ptm_bfd_sess_dn(struct bfd_session *bfd, uint8_t diag)
 
 	if (old_state != bfd->ses_state) {
 		bfd->stats.session_down++;
+		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,
@@ -522,8 +526,7 @@ int bfd_session_update_label(struct bfd_session *bs, const char *nlabel)
 			return -1;
 		}
 
-		if (pl_new(nlabel, bs) == NULL)
+		pl_new(nlabel, bs);
-			return -1;
 
 		return 0;
 	}
@@ -681,10 +684,6 @@ struct bfd_session *ptm_bfd_sess_new(struct bfd_peer_cfg *bpc)
 
 	/* Get BFD session storage with its defaults. */
 	bfd = bfd_session_new();
-	if (bfd == NULL) {
-		zlog_err("session-new: allocation failed");
-		return NULL;
-	}
 
 	/*
 	 * Store interface/VRF name in case we need to delay session
@@ -758,6 +757,7 @@ 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);
 
+	if (bglobal.debug_peer_event)
 		zlog_debug("session-new: %s", bs_to_string(bfd));
 
 	control_notify_config(BCM_NOTIFY_CONFIG_ADD, bfd);
@@ -782,6 +782,7 @@ int ptm_bfd_sess_del(struct bfd_peer_cfg *bpc)
 		return -1;
 	}
 
+	if (bglobal.debug_peer_event)
 		zlog_debug("session-delete: %s", bs_to_string(bs));
 
 	control_notify_config(BCM_NOTIFY_CONFIG_DELETE, bs);
@@ -849,6 +850,7 @@ static void bs_down_handler(struct bfd_session *bs, int nstate)
 		break;
 
 	default:
+		if (bglobal.debug_peer_event)
 			zlog_debug("state-change: unhandled neighbor state: %d",
 				   nstate);
 		break;
@@ -877,6 +879,7 @@ static void bs_init_handler(struct bfd_session *bs, int nstate)
 		break;
 
 	default:
+		if (bglobal.debug_peer_event)
 			zlog_debug("state-change: unhandled neighbor state: %d",
 				   nstate);
 		break;
@@ -908,7 +911,7 @@ static void bs_neighbour_admin_down_handler(struct bfd_session *bfd,
 
 	if (old_state != bfd->ses_state) {
 		bfd->stats.session_down++;
-
+		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,
@@ -934,6 +937,7 @@ static void bs_up_handler(struct bfd_session *bs, int nstate)
 		break;
 
 	default:
+		if (bglobal.debug_peer_event)
 			zlog_debug("state-change: unhandled neighbor state: %d",
 				   nstate);
 		break;
@@ -957,6 +961,7 @@ void bs_state_handler(struct bfd_session *bs, int nstate)
 		break;
 
 	default:
+		if (bglobal.debug_peer_event)
 			zlog_debug("state-change: [%s] is in invalid state: %d",
 				   bs_to_string(bs), nstate);
 		break;
@@ -1106,13 +1111,13 @@ static const char *get_diag_str(int diag)
 	return "N/A";
 }
 
-const char *satostr(struct sockaddr_any *sa)
+const char *satostr(const struct sockaddr_any *sa)
 {
 #define INETSTR_BUFCOUNT 8
 	static char buf[INETSTR_BUFCOUNT][INET6_ADDRSTRLEN];
 	static int bufidx;
-	struct sockaddr_in *sin = &sa->sa_sin;
+	const struct sockaddr_in *sin = &sa->sa_sin;
-	struct sockaddr_in6 *sin6 = &sa->sa_sin6;
+	const struct sockaddr_in6 *sin6 = &sa->sa_sin6;
 
 	bufidx += (bufidx + 1) % INETSTR_BUFCOUNT;
 	buf[bufidx][0] = 0;
@@ -1433,12 +1438,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) {
+			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",
+				zlog_debug(
+					" peer %s found, but loc-addr %s ignored",
 					peer_buf, addr_buf);
+			}
 			return bsp;
 		}
 	}
@@ -1449,6 +1456,7 @@ 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) {
+			if (bglobal.debug_peer_event)
 				zlog_debug(" peer %s found, but ifp %s ignored",
 					   peer_buf, key.ifname);
 			return bsp;
@@ -1460,14 +1468,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) {
+			if (bglobal.debug_peer_event) {
 				char addr_buf[INET6_ADDRSTRLEN];
-
+				inet_ntop(bs.key.family, &bs.key.local,
-			inet_ntop(bs.key.family, &bs.key.local, addr_buf,
+					  addr_buf, sizeof(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,6 +1494,7 @@ struct bfd_session *bfd_key_lookup(struct bfd_key key)
 	/* change key */
 	if (ctx.result) {
 		bsp = ctx.result;
+		if (bglobal.debug_peer_event)
 			zlog_debug(
 				" peer %s found, but ifp"
 				" and/or loc-addr params ignored",
@@ -1676,13 +1686,17 @@ void bfd_sessions_remove_manual(void)
  */
 static int bfd_vrf_new(struct vrf *vrf)
 {
+	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)
 {
+	if (bglobal.debug_zebra)
 		zlog_debug("VRF Deletion: %s(%u)", vrf->name, vrf->vrf_id);
+
 	return 0;
 }
 
@@ -1690,7 +1704,10 @@ static int bfd_vrf_update(struct vrf *vrf)
 {
 	if (!vrf_is_enabled(vrf))
 		return 0;
+
+	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 +1724,10 @@ static int bfd_vrf_enable(struct vrf *vrf)
 		vrf->info = (void *)bvrf;
 	} else
 		bvrf = vrf->info;
+
+	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,6 +1783,7 @@ static int bfd_vrf_disable(struct vrf *vrf)
 		bfdd_zclient_unregister(vrf->vrf_id);
 	}
 
+	if (bglobal.debug_zebra)
 		zlog_debug("VRF disable %s id %d", vrf->name, vrf->vrf_id);
 
 	/* Disable read/write poll triggering. */

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[];
@@ -510,7 +529,7 @@ void bs_state_handler(struct bfd_session *bs, int nstate);
 void bs_echo_timer_handler(struct bfd_session *bs);
 void bs_final_handler(struct bfd_session *bs);
 void bs_set_slow_timers(struct bfd_session *bs);
-const char *satostr(struct sockaddr_any *sa);
+const char *satostr(const struct sockaddr_any *sa);
 const char *diag2str(uint8_t diag);
 int strtosa(const char *addr, struct sockaddr_any *sa);
 void integer2timestr(uint64_t time, char *buf, size_t buflen);

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)
+	if (rv < (ssize_t)datalen) {
-		zlog_debug("packet-send: send partial: %s", strerror(errno));
+		if (bglobal.debug_network)
+			zlog_debug("packet-send: send partial: %s",
+				   strerror(errno));
+	}
 
 	return 0;
 }
@@ -190,12 +195,14 @@ 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) {
+		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)) {
+		if (bglobal.debug_network)
 			zlog_debug("echo-packet: echo disabled [%s] (id:%u)",
 				   bs_to_string(bfd), my_discr);
 		return -1;
@@ -313,6 +320,7 @@ 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) {
+				if (bglobal.debug_network)
 					zlog_debug("ipv4-recv: invalid TTL: %u",
 						   ttlval);
 				return -1;
@@ -420,6 +428,7 @@ 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) {
+				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) {
+		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,
+		if (bglobal.debug_network)
-			   datalen);
+			zlog_debug("udp-send: partial send: %zd expected %zu",
+				   wlen, datalen);
 		return -1;
 	}
 

bfdd/bfdd_nb_config.c

@@ -107,8 +107,6 @@ static int bfd_session_create(enum nb_event event, const struct lyd_node *dnode,
 		}
 
 		bs = bfd_session_new();
-		if (bs == NULL)
-			return NB_ERR_RESOURCE;
 
 		/* Fill the session key. */
 		bfd_session_get_key(mhop, dnode, &bs->key);

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);

bfdd/control.c

@@ -168,8 +168,7 @@ int control_accept(struct thread *t)
 		return 0;
 	}
 
-	if (control_new(csock) == NULL)
+	control_new(csock);
-		close(csock);
 
 	bglobal.bg_csockev = NULL;
 	thread_add_read(master, control_accept, NULL, sd, &bglobal.bg_csockev);
@@ -334,8 +333,6 @@ static int control_queue_enqueue(struct bfd_control_socket *bcs,
 	struct bfd_control_buffer *bcb;
 
 	bcq = control_queue_new(bcs);
-	if (bcq == NULL)
-		return -1;
 
 	bcb = &bcq->bcq_bcb;
 	bcb->bcb_left = sizeof(struct bfd_control_msg) + ntohl(bcm->bcm_length);
@@ -656,8 +653,7 @@ static int notify_add_cb(struct bfd_peer_cfg *bpc, void *arg)
 	if (bs == NULL)
 		return -1;
 
-	if (control_notifypeer_new(bcs, bs) == NULL)
+	control_notifypeer_new(bcs, bs);
-		return -1;
 
 	/* Notify peer status. */
 	_control_notify(bcs, bs);

bfdd/event.c

@@ -48,10 +48,6 @@ void bfd_recvtimer_update(struct bfd_session *bs)
 		return;
 
 	tv_normalize(&tv);
-#ifdef BFD_EVENT_DEBUG
-	zlog_debug("%s: sec = %ld, usec = %ld", __func__, tv.tv_sec,
-		   tv.tv_usec);
-#endif /* BFD_EVENT_DEBUG */
 
 	thread_add_timer_tv(master, bfd_recvtimer_cb, bs, &tv,
 			    &bs->recvtimer_ev);
@@ -70,10 +66,6 @@ void bfd_echo_recvtimer_update(struct bfd_session *bs)
 		return;
 
 	tv_normalize(&tv);
-#ifdef BFD_EVENT_DEBUG
-	zlog_debug("%s: sec = %ld, usec = %ld", __func__, tv.tv_sec,
-		   tv.tv_usec);
-#endif /* BFD_EVENT_DEBUG */
 
 	thread_add_timer_tv(master, bfd_echo_recvtimer_cb, bs, &tv,
 			    &bs->echo_recvtimer_ev);
@@ -92,10 +84,6 @@ void bfd_xmttimer_update(struct bfd_session *bs, uint64_t jitter)
 		return;
 
 	tv_normalize(&tv);
-#ifdef BFD_EVENT_DEBUG
-	zlog_debug("%s: sec = %ld, usec = %ld", __func__, tv.tv_sec,
-		   tv.tv_usec);
-#endif /* BFD_EVENT_DEBUG */
 
 	thread_add_timer_tv(master, bfd_xmt_cb, bs, &tv, &bs->xmttimer_ev);
 }
@@ -113,10 +101,6 @@ void bfd_echo_xmttimer_update(struct bfd_session *bs, uint64_t jitter)
 		return;
 
 	tv_normalize(&tv);
-#ifdef BFD_EVENT_DEBUG
-	zlog_debug("%s: sec = %ld, usec = %ld", __func__, tv.tv_sec,
-		   tv.tv_usec);
-#endif /* BFD_EVENT_DEBUG */
 
 	thread_add_timer_tv(master, bfd_echo_xmt_cb, bs, &tv,
 			    &bs->echo_xmttimer_ev);

bfdd/ptm_adapter.c

@@ -80,19 +80,17 @@ static void bfdd_client_deregister(struct stream *msg);
 /*
  * Functions
  */
-#ifdef BFD_DEBUG
+static void debug_printbpc(const struct bfd_peer_cfg *bpc, const char *fmt, ...)
-static void debug_printbpc(const char *func, unsigned int line,
-			   struct bfd_peer_cfg *bpc);
-
-static void debug_printbpc(const char *func, unsigned int line,
-			   struct bfd_peer_cfg *bpc)
 {
-	char addr[3][128];
+	char timers[3][128] = {};
-	char timers[3][128];
+	char addr[3][128] = {};
-	char cbit_str[10];
+	char cbit_str[32];
+	char msgbuf[256];
+	va_list vl;
 
-	addr[0][0] = addr[1][0] = addr[2][0] = timers[0][0] = timers[1][0] =
+	/* Avoid debug calculations if it's disabled. */
-		timers[2][0] = 0;
+	if (bglobal.debug_zebra == false)
+		return;
 
 	snprintf(addr[0], sizeof(addr[0]), "peer:%s", satostr(&bpc->bpc_peer));
 	if (bpc->bpc_local.sa_sin.sin_family)
@@ -107,29 +105,28 @@ static void debug_printbpc(const char *func, unsigned int line,
 		snprintf(addr[2], sizeof(addr[2]), " vrf:%s", bpc->bpc_vrfname);
 
 	if (bpc->bpc_has_recvinterval)
-		snprintf(timers[0], sizeof(timers[0]), " rx:%lu",
+		snprintf(timers[0], sizeof(timers[0]), " rx:%" PRIu64,
 			 bpc->bpc_recvinterval);
 
 	if (bpc->bpc_has_txinterval)
-		snprintf(timers[1], sizeof(timers[1]), " tx:%lu",
+		snprintf(timers[1], sizeof(timers[1]), " tx:%" PRIu64,
 			 bpc->bpc_recvinterval);
 
 	if (bpc->bpc_has_detectmultiplier)
 		snprintf(timers[2], sizeof(timers[2]), " detect-multiplier:%d",
 			 bpc->bpc_detectmultiplier);
 
-	sprintf(cbit_str, "CB %x", bpc->bpc_cbit);
+	snprintf(cbit_str, sizeof(cbit_str), " cbit:0x%02x", bpc->bpc_cbit);
 
-	zlog_debug("%s:%d: %s %s%s%s%s%s%s %s", func, line,
+	va_start(vl, fmt);
-		   bpc->bpc_mhop ? "multi-hop" : "single-hop", addr[0], addr[1],
+	vsnprintf(msgbuf, sizeof(msgbuf), fmt, vl);
-		   addr[2], timers[0], timers[1], timers[2], cbit_str);
+	va_end(vl);
+
+	zlog_debug("%s [mhop:%s %s%s%s%s%s%s%s]", msgbuf,
+		   bpc->bpc_mhop ? "yes" : "no", addr[0], addr[1], addr[2],
+		   timers[0], timers[1], timers[2], cbit_str);
 }
 
-#define DEBUG_PRINTBPC(bpc) debug_printbpc(__FILE__, __LINE__, (bpc))
-#else
-#define DEBUG_PRINTBPC(bpc)
-#endif /* BFD_DEBUG */
-
 static int _ptm_msg_address(struct stream *msg, int family, const void *addr)
 {
 	stream_putc(msg, family);
@@ -315,10 +312,6 @@ static int _ptm_msg_read(struct stream *msg, int command, vrf_id_t vrf_id,
 	STREAM_GETL(msg, pid);
 
 	*pc = pc_new(pid);
-	if (*pc == NULL) {
-		zlog_debug("ptm-read: failed to allocate memory");
-		return -1;
-	}
 
 	/* Register/update peer information. */
 	_ptm_msg_read_address(msg, &bpc->bpc_peer);
@@ -404,7 +397,6 @@ stream_failure:
 static void bfdd_dest_register(struct stream *msg, vrf_id_t vrf_id)
 {
 	struct ptm_client *pc;
-	struct ptm_client_notification *pcn;
 	struct bfd_session *bs;
 	struct bfd_peer_cfg bpc;
 
@@ -412,13 +404,14 @@ static void bfdd_dest_register(struct stream *msg, vrf_id_t vrf_id)
 	if (_ptm_msg_read(msg, ZEBRA_BFD_DEST_REGISTER, vrf_id, &bpc, &pc) == -1)
 		return;
 
-	DEBUG_PRINTBPC(&bpc);
+	debug_printbpc(&bpc, "ptm-add-dest: register peer");
 
 	/* Find or start new BFD session. */
 	bs = bs_peer_find(&bpc);
 	if (bs == NULL) {
 		bs = ptm_bfd_sess_new(&bpc);
 		if (bs == NULL) {
+			if (bglobal.debug_zebra)
 				zlog_debug(
 					"ptm-add-dest: failed to create BFD session");
 			return;
@@ -431,11 +424,7 @@ static void bfdd_dest_register(struct stream *msg, vrf_id_t vrf_id)
 	}
 
 	/* Create client peer notification register. */
-	pcn = pcn_new(pc, bs);
+	pcn_new(pc, bs);
-	if (pcn == NULL) {
-		zlog_err("ptm-add-dest: failed to registrate notifications");
-		return;
-	}
 
 	ptm_bfd_notify(bs, bs->ses_state);
 }
@@ -451,11 +440,12 @@ static void bfdd_dest_deregister(struct stream *msg, vrf_id_t vrf_id)
 	if (_ptm_msg_read(msg, ZEBRA_BFD_DEST_DEREGISTER, vrf_id, &bpc, &pc) == -1)
 		return;
 
-	DEBUG_PRINTBPC(&bpc);
+	debug_printbpc(&bpc, "ptm-del-dest: deregister peer");
 
 	/* Find or start new BFD session. */
 	bs = bs_peer_find(&bpc);
 	if (bs == NULL) {
+		if (bglobal.debug_zebra)
 			zlog_debug("ptm-del-dest: failed to find BFD session");
 		return;
 	}
@@ -479,17 +469,12 @@ static void bfdd_dest_deregister(struct stream *msg, vrf_id_t vrf_id)
  */
 static void bfdd_client_register(struct stream *msg)
 {
-	struct ptm_client *pc;
 	uint32_t pid;
 
 	/* Find or allocate process context data. */
 	STREAM_GETL(msg, pid);
 
-	pc = pc_new(pid);
+	pc_new(pid);
-	if (pc == NULL) {
-		zlog_err("ptm-add-client: failed to register client: %u", pid);
-		return;
-	}
 
 	return;
 
@@ -511,7 +496,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,6 +533,7 @@ static int bfdd_replay(ZAPI_CALLBACK_ARGS)
 		break;
 
 	default:
+		if (bglobal.debug_zebra)
 			zlog_debug("ptm-replay: invalid message type %u", rcmd);
 		return -1;
 	}
@@ -674,6 +662,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 +710,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 +729,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;

doc/user/bfd.rst

@@ -476,13 +476,36 @@ You can also clear packet counters per session with the following commands, only
                 Session down events: 0
                 Zebra notifications: 4
 
-Logging / debugging
+Debugging
-===================
+=========
 
-There are no fine grained debug controls for bfdd. Just enable debug logs.
+By default only informational, warning and errors messages are going to be
+displayed. If you want to get debug messages and other diagnostics then make
+sure you have `debugging` level enabled:
 
 ::
 
    config
    log file /var/log/frr/frr.log debugging
    log syslog debugging
+
+You may also fine tune the debug messages by selecting one or more of the
+debug levels:
+
+.. index:: [no] debug bfd network
+.. clicmd:: [no] debug bfd network
+
+   Toggle network events: show messages about socket failures and unexpected
+   BFD messages that may not belong to registered peers.
+
+.. index:: [no] debug bfd peer
+.. clicmd:: [no] debug bfd peer
+
+   Toggle peer event log messages: show messages about peer creation/removal
+   and state changes.
+
+.. index:: [no] debug bfd zebra
+.. clicmd:: [no] debug bfd zebra
+
+   Toggle zebra message events: show messages about interfaces, local
+   addresses, VRF and daemon peer registrations.

tests/topotests/bfd-bgp-cbit-topo3/r1/bfdd.conf

@@ -0,0 +1,5 @@
+!
+debug bfd network
+debug bfd peer
+debug bfd zebra
+!

tests/topotests/bfd-bgp-cbit-topo3/r3/bfdd.conf

@@ -0,0 +1,5 @@
+!
+debug bfd network
+debug bfd peer
+debug bfd zebra
+!

tests/topotests/bfd-topo1/r1/bfdd.conf

@@ -1,3 +1,8 @@
+!
+debug bfd network
+debug bfd peer
+debug bfd zebra
+!
 bfd
  peer 192.168.0.2
   echo-mode

tests/topotests/bfd-topo1/r2/bfdd.conf

@@ -1,3 +1,8 @@
+!
+debug bfd network
+debug bfd peer
+debug bfd zebra
+!
 bfd
  peer 192.168.0.1
   receive-interval 1000

tests/topotests/bfd-topo1/r3/bfdd.conf

@@ -1,3 +1,8 @@
+!
+debug bfd network
+debug bfd peer
+debug bfd zebra
+!
 bfd
  peer 192.168.1.2
   echo-interval 100

tests/topotests/bfd-topo1/r4/bfdd.conf

@@ -1,3 +1,8 @@
+!
+debug bfd network
+debug bfd peer
+debug bfd zebra
+!
 bfd
  peer 192.168.2.2
   transmit-interval 2000

tests/topotests/bfd-topo2/r1/bfdd.conf

@@ -1,3 +1,8 @@
+!
+debug bfd network
+debug bfd peer
+debug bfd zebra
+!
 bfd
  peer 2001:db8:4::1 multihop local-address 2001:db8:1::1
   no shutdown

tests/topotests/bfd-topo2/r2/bfdd.conf

@@ -0,0 +1,5 @@
+!
+debug bfd network
+debug bfd peer
+debug bfd zebra
+!

tests/topotests/bfd-topo2/r3/bfdd.conf

@@ -0,0 +1,5 @@
+!
+debug bfd network
+debug bfd peer
+debug bfd zebra
+!

tests/topotests/bfd-topo2/r4/bfdd.conf

@@ -1,3 +1,8 @@
+!
+debug bfd network
+debug bfd peer
+debug bfd zebra
+!
 bfd
  peer 2001:db8:1::1 multihop local-address 2001:db8:4::1
   no shutdown

tests/topotests/bfd-vrf-topo1/r1/bfdd.conf

@@ -1,3 +1,8 @@
+!
+debug bfd network
+debug bfd peer
+debug bfd zebra
+!
 bfd
  peer 192.168.0.2 vrf r1-cust1
   echo-mode

tests/topotests/bfd-vrf-topo1/r2/bfdd.conf

@@ -1,3 +1,8 @@
+!
+debug bfd network
+debug bfd peer
+debug bfd zebra
+!
 bfd
  peer 192.168.0.1 vrf r2-cust1
   receive-interval 1000

tests/topotests/bfd-vrf-topo1/r3/bfdd.conf

@@ -1,3 +1,8 @@
+!
+debug bfd network
+debug bfd peer
+debug bfd zebra
+!
 bfd
  peer 192.168.1.2 vrf r3-cust1
   echo-interval 100

tests/topotests/bfd-vrf-topo1/r4/bfdd.conf

@@ -1,3 +1,8 @@
+!
+debug bfd network
+debug bfd peer
+debug bfd zebra
+!
 bfd
  peer 192.168.2.2 vrf r4-cust1
   transmit-interval 2000