5 files changed, 225 insertions, 182 deletions

diff --git a/bfdd/bfd.c b/bfdd/bfd.c
index 09499ad2c4..ff62cd356b 100644
--- a/bfdd/bfd.c
+++ b/bfdd/bfd.c
@@ -167,6 +167,8 @@ void ptm_bfd_echo_start(struct bfd_session *bfd)
 
 void ptm_bfd_ses_up(struct bfd_session *bfd)
 {
+	int old_state = bfd->ses_state;
+
 	bfd->local_diag = 0;
 	bfd->ses_state = PTM_BFD_UP;
 	bfd->polling = 1;
@@ -183,8 +185,10 @@ void ptm_bfd_ses_up(struct bfd_session *bfd)
 
 	control_notify(bfd);
 
-	INFOLOG("Session 0x%x up peer %s", bfd->discrs.my_discr,
-		satostr(&bfd->shop.peer));
+	if (old_state != bfd->ses_state)
+		log_info("state-change: [%s] %s -> %s", bs_to_string(bfd),
+			 state_list[old_state].str,
+			 state_list[bfd->ses_state].str);
 }
 
 void ptm_bfd_ses_dn(struct bfd_session *bfd, uint8_t diag)
@@ -204,13 +208,15 @@ void ptm_bfd_ses_dn(struct bfd_session *bfd, uint8_t diag)
 	if (old_state == PTM_BFD_UP)
 		control_notify(bfd);
 
-	INFOLOG("Session 0x%x down peer %s Rsn %s prev st %s",
-		bfd->discrs.my_discr, satostr(&bfd->shop.peer),
-		get_diag_str(bfd->local_diag), state_list[old_state].str);
-
 	/* Stop echo packet transmission if they are active */
 	if (BFD_CHECK_FLAG(bfd->flags, BFD_SESS_FLAG_ECHO_ACTIVE))
 		ptm_bfd_echo_stop(bfd, 0);
+
+	if (old_state != bfd->ses_state)
+		log_info("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));
 }
 
 static int ptm_bfd_get_vrf_name(char *port_name, char *vrf_name)
@@ -282,7 +288,8 @@ struct bfd_session *ptm_bfd_sess_find(struct bfd_pkt *cp, char *port_name,
 		} else if (port_name && port_name[0]) {
 			memset(vrf_buf, 0, sizeof(vrf_buf));
 			if (ptm_bfd_get_vrf_name(port_name, vrf_buf) != -1)
-				strlcpy(mhop.vrf_name, vrf_buf, sizeof(mhop.vrf_name));
+				strlcpy(mhop.vrf_name, vrf_buf,
+					sizeof(mhop.vrf_name));
 		}
 
 		l_bfd = bfd_mhop_lookup(mhop);
@@ -290,7 +297,8 @@ struct bfd_session *ptm_bfd_sess_find(struct bfd_pkt *cp, char *port_name,
 		memset(&shop, 0, sizeof(shop));
 		shop.peer = *peer;
 		if (port_name && port_name[0])
-			strlcpy(shop.port_name, port_name, sizeof(shop.port_name));
+			strlcpy(shop.port_name, port_name,
+				sizeof(shop.port_name));
 
 		l_bfd = bfd_shop_lookup(shop);
 	}
@@ -348,17 +356,11 @@ int bfd_echo_xmt_cb(struct thread *t)
 int bfd_recvtimer_cb(struct thread *t)
 {
 	struct bfd_session *bs = THREAD_ARG(t);
-	uint8_t old_state;
-
-	old_state = bs->ses_state;
 
 	switch (bs->ses_state) {
 	case PTM_BFD_INIT:
 	case PTM_BFD_UP:
 		ptm_bfd_ses_dn(bs, BFD_DIAGDETECTTIME);
-		INFOLOG("%s Detect timeout on session 0x%x with peer %s, in state %d",
-			__func__, bs->discrs.my_discr, satostr(&bs->shop.peer),
-			bs->ses_state);
 		bfd_recvtimer_update(bs);
 		break;
 
@@ -370,12 +372,6 @@ int bfd_recvtimer_cb(struct thread *t)
 		break;
 	}
 
-	if (old_state != bs->ses_state) {
-		DLOG("BFD Sess %d [%s] Old State [%s] : New State [%s]",
-		     bs->discrs.my_discr, satostr(&bs->shop.peer),
-		     state_list[old_state].str, state_list[bs->ses_state].str);
-	}
-
 	return 0;
 }
 
@@ -383,26 +379,14 @@ int bfd_recvtimer_cb(struct thread *t)
 int bfd_echo_recvtimer_cb(struct thread *t)
 {
 	struct bfd_session *bs = THREAD_ARG(t);
-	uint8_t old_state;
-
-	old_state = bs->ses_state;
 
 	switch (bs->ses_state) {
 	case PTM_BFD_INIT:
 	case PTM_BFD_UP:
 		ptm_bfd_ses_dn(bs, BFD_DIAGDETECTTIME);
-		INFOLOG("%s Detect timeout on session 0x%x with peer %s, in state %d",
-			__func__, bs->discrs.my_discr, satostr(&bs->shop.peer),
-			bs->ses_state);
 		break;
 	}
 
-	if (old_state != bs->ses_state) {
-		DLOG("BFD Sess %d [%s] Old State [%s] : New State [%s]",
-		     bs->discrs.my_discr, satostr(&bs->shop.peer),
-		     state_list[old_state].str, state_list[bs->ses_state].str);
-	}
-
 	return 0;
 }
 
@@ -598,25 +582,18 @@ struct bfd_session *ptm_bfd_sess_new(struct bfd_peer_cfg *bpc)
 	 */
 	if (bpc->bpc_ipv4) {
 		psock = bp_peer_socket(bpc);
-		if (psock == -1) {
-			ERRLOG("Can't get socket for new session: %s",
-			       strerror(errno));
+		if (psock == -1)
 			return NULL;
-		}
 	} else {
 		psock = bp_peer_socketv6(bpc);
-		if (psock == -1) {
-			ERRLOG("Can't get IPv6 socket for new session: %s",
-			       strerror(errno));
+		if (psock == -1)
 			return NULL;
-		}
 	}
 
 	/* Get memory */
 	bfd = bfd_session_new(psock);
 	if (bfd == NULL) {
-		ERRLOG("Can't malloc memory for new session: %s",
-		       strerror(errno));
+		log_error("session-new: allocation failed");
 		return NULL;
 	}
 
@@ -691,16 +668,7 @@ struct bfd_session *ptm_bfd_sess_new(struct bfd_peer_cfg *bpc)
 
 	ptm_bfd_xmt_TO(bfd, 0);
 
-	if (bpc->bpc_mhop) {
-		INFOLOG("Created new session 0x%x with vrf %s peer %s local %s",
-			bfd->discrs.my_discr,
-			(bpc->bpc_has_vrfname) ? bfd->mhop.vrf_name : "N/A",
-			satostr(&bfd->mhop.peer), satostr(&bfd->mhop.local));
-	} else {
-		INFOLOG("Created new session 0x%x with peer %s port %s",
-			bfd->discrs.my_discr, satostr(&bfd->shop.peer),
-			bfd->shop.port_name[0] ? bfd->shop.port_name : "N/A");
-	}
+	log_info("session-new: %s", bs_to_string(bfd));
 
 	control_notify_config(BCM_NOTIFY_CONFIG_ADD, bfd);
 
@@ -718,22 +686,13 @@ int ptm_bfd_ses_del(struct bfd_peer_cfg *bpc)
 
 	/* This pointer is being referenced, don't let it be deleted. */
 	if (bs->refcount > 0) {
-		zlog_debug("%s: trying to free in-use session: %" PRIu64
-			   " references",
-			   __func__, bs->refcount);
+		log_error("session-delete: refcount failure: %" PRIu64
+			  " references",
+			  bs->refcount);
 		return -1;
 	}
 
-	if (BFD_CHECK_FLAG(bs->flags, BFD_SESS_FLAG_MH)) {
-		INFOLOG("Deleting session 0x%x with vrf %s peer %s local %s",
-			bs->discrs.my_discr,
-			bpc->bpc_has_vrfname ? bpc->bpc_vrfname : "N/A",
-			satostr(&bs->mhop.peer), satostr(&bs->mhop.local));
-	} else {
-		INFOLOG("Deleting session 0x%x with peer %s port %s",
-			bs->discrs.my_discr, satostr(&bs->shop.peer),
-			bs->shop.port_name);
-	}
+	log_info("session-delete: %s", bs_to_string(bs));
 
 	control_notify_config(BCM_NOTIFY_CONFIG_DELETE, bs);
 
@@ -895,6 +854,38 @@ void integer2timestr(uint64_t time, char *buf, size_t buflen)
 	snprintf(buf, buflen, "%u second(s)", second);
 }
 
+const char *bs_to_string(struct bfd_session *bs)
+{
+	static char buf[256];
+	int pos;
+	bool is_mhop = BFD_CHECK_FLAG(bs->flags, BFD_SESS_FLAG_MH);
+
+	pos = snprintf(buf, sizeof(buf), "mhop:%s", is_mhop ? "yes" : "no");
+	if (BFD_CHECK_FLAG(bs->flags, BFD_SESS_FLAG_MH)) {
+		pos += snprintf(buf + pos, sizeof(buf) - pos,
+				" peer:%s local:%s", satostr(&bs->mhop.peer),
+				satostr(&bs->mhop.local));
+
+		if (bs->mhop.vrf_name[0])
+			snprintf(buf + pos, sizeof(buf) - pos, " vrf:%s",
+				 bs->mhop.vrf_name);
+	} else {
+		pos += snprintf(buf + pos, sizeof(buf) - pos, " peer:%s",
+				satostr(&bs->shop.peer));
+
+		if (bs->local_address.sa_sin.sin_family)
+			pos += snprintf(buf + pos, sizeof(buf) - pos,
+					" local:%s",
+					satostr(&bs->local_address));
+
+		if (bs->shop.port_name[0])
+			snprintf(buf + pos, sizeof(buf) - pos, " interface:%s",
+				 bs->shop.port_name);
+	}
+
+	return buf;
+}
+
 
 /*
  * BFD hash data structures to find sessions.
@@ -1051,7 +1042,6 @@ static int _iface_key(struct bfd_iface *iface, const char *ifname)
 	return 0;
 }
 
-
 /*
  * Hash public interface / exported functions.
  */
diff --git a/bfdd/bfd.h b/bfdd/bfd.h
index 8f7dd1b8c8..40aecaa67b 100644
--- a/bfdd/bfd.h
+++ b/bfdd/bfd.h
@@ -464,11 +464,6 @@ void log_warning(const char *fmt, ...);
 void log_error(const char *fmt, ...);
 void log_fatal(const char *fmt, ...);
 
-/* Compatibility code: code to avoid touching ported code debug messages. */
-#define DLOG(fmt, args...) log_debug(fmt, ##args)
-#define INFOLOG(fmt, args...) log_info(fmt, ##args)
-#define ERRLOG(fmt, args...) log_error(fmt, ##args)
-#define CRITLOG(fmt, args...) log_fatal(fmt, ##args)
 
 /*
  * bfd_packet.c
@@ -545,6 +540,7 @@ const char *satostr(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);
+const char *bs_to_string(struct bfd_session *bs);
 
 /* BFD hash data structures interface */
 void bfd_initialize(void);
diff --git a/bfdd/bfd_packet.c b/bfdd/bfd_packet.c
index 17c2486196..177d6307e4 100644
--- a/bfdd/bfd_packet.c
+++ b/bfdd/bfd_packet.c
@@ -186,7 +186,7 @@ static int _ptm_bfd_send(struct bfd_session *bs, bool use_layer2,
 		 * TODO: implement layer 2 send for *BSDs. This is
 		 * needed for VxLAN.
 		 */
-		log_warning("%s: not implemented");
+		log_warning("packet-send: not implemented");
 		return -1;
 #endif
 	} else if (BFD_CHECK_FLAG(bs->flags, BFD_SESS_FLAG_IPV6)) {
@@ -222,14 +222,11 @@ static int _ptm_bfd_send(struct bfd_session *bs, bool use_layer2,
 #endif /* HAVE_STRUCT_SOCKADDR_SA_LEN */
 	rv = sendto(sd, data, datalen, 0, sa, slen);
 	if (rv <= 0) {
-		log_debug("%s:%d: sendto: (%d) %s", __func__, __LINE__, errno,
-			  strerror(errno));
+		log_debug("packet-send: send failure: %s", strerror(errno));
 		return -1;
 	}
-	if (rv < (ssize_t)datalen) {
-		log_debug("%s:%d: sendto: sent partial data", __func__,
-			  __LINE__);
-	}
+	if (rv < (ssize_t)datalen)
+		log_debug("packet-send: send partial", strerror(errno));
 
 	return 0;
 }
@@ -349,7 +346,7 @@ void ptm_bfd_echo_snd(struct bfd_session *bfd)
 	}
 
 	if (_ptm_bfd_send(bfd, use_layer2, &port, pkt, pktlen) != 0) {
-		ERRLOG("%s: _ptm_bfd_send: %s", __func__, strerror(errno));
+		log_debug("echo-packet: send failure: %s", strerror(errno));
 		return;
 	}
 
@@ -408,7 +405,7 @@ static int ptm_bfd_echo_loopback(uint8_t *pkt, int pkt_len, struct sockaddr *ss,
 #endif /* BFD_BSD_FILTER */
 
 	if (sendto(bglobal.bg_echo, pkt, pkt_len, 0, ss, sslen) < 0) {
-		ERRLOG("%s: sendto: %s", __func__, strerror(errno));
+		log_debug("echo-loopback: send failure: %s", strerror(errno));
 		return -1;
 	}
 
@@ -515,13 +512,16 @@ static int ptm_bfd_process_echo_pkt(int s)
 			   (struct sockaddr *)&ss, &sslen);
 	if (pkt_len <= 0) {
 		if (errno != EAGAIN)
-			ERRLOG("%s: recvfrom: %s", __func__, strerror(errno));
+			log_error("echo-packet: read failure: %s",
+				  strerror(errno));
+
 		return -1;
 	}
 
 	/* Check if we have at least the basic headers to send back. */
-	if (pkt_len < HEADERS_MIN_LEN) {
-		INFOLOG("Received short echo packet");
+	if (pkt_len < BFD_ECHO_PKT_TOT_LEN) {
+		log_debug("echo-packet: too short (got %ld, expected %d)",
+			  pkt_len, BFD_ECHO_PKT_TOT_LEN);
 		return -1;
 	}
 
@@ -534,16 +534,9 @@ static int ptm_bfd_process_echo_pkt(int s)
 					     (struct sockaddr *)&ss,
 					     sizeof(struct sockaddr_ll));
 
-	/* Packet is too small for us to process */
-	if (pkt_len < BFD_ECHO_PKT_TOT_LEN) {
-		INFOLOG("Received short echo packet");
-		return -1;
-	}
-
 	my_discr = ntohl(ep->data.my_discr);
 	if (ep->data.my_discr == 0) {
-		INFOLOG("My discriminator is zero in echo pkt from 0x%x",
-			ntohl(ep->ip.saddr));
+		log_debug("echo-packet: 'my discriminator' is zero");
 		return -1;
 	}
 #endif /* BFD_LINUX */
@@ -568,12 +561,13 @@ static int ptm_bfd_process_echo_pkt(int s)
 	/* Your discriminator not zero - use it to find session */
 	bfd = bfd_id_lookup(my_discr);
 	if (bfd == NULL) {
-		INFOLOG("Failed to extract session from echo packet");
+		log_debug("echo-packet: no matching session (id:%u)", my_discr);
 		return -1;
 	}
 
 	if (!BFD_CHECK_FLAG(bfd->flags, BFD_SESS_FLAG_ECHO_ACTIVE)) {
-		INFOLOG("BFD echo not active - ignore echo packet");
+		log_debug("echo-packet: echo disabled [%s]", my_discr,
+			  bs_to_string(bfd));
 		return -1;
 	}
 
@@ -623,10 +617,8 @@ void ptm_bfd_snd(struct bfd_session *bfd, int fbit)
 	}
 	cp.timers.required_min_echo = htonl(bfd->timers.required_min_echo);
 
-	if (_ptm_bfd_send(bfd, false, NULL, &cp, BFD_PKT_LEN) != 0) {
-		ERRLOG("Error sending control pkt: %s", strerror(errno));
+	if (_ptm_bfd_send(bfd, false, NULL, &cp, BFD_PKT_LEN) != 0)
 		return;
-	}
 
 	bfd->stats.tx_ctrl_pkt++;
 }
@@ -686,27 +678,27 @@ ptm_bfd_validate_vxlan_pkt(struct bfd_session *bfd,
 			   struct bfd_session_vxlan_info *vxlan_info)
 {
 	if (bfd->vxlan_info.check_tnl_key && (vxlan_info->vnid != 0)) {
-		ERRLOG("Error Rx BFD Vxlan pkt with non-zero vnid %d",
-		       vxlan_info->vnid);
+		log_error("vxlan-packet: vnid not zero: %d", vxlan_info->vnid);
 		return false;
 	}
 
 	if (bfd->vxlan_info.local_dst_ip.s_addr
 	    != vxlan_info->local_dst_ip.s_addr) {
-		ERRLOG("Error Rx BFD Vxlan pkt with wrong inner dst IP %s",
-		       inet_ntoa(vxlan_info->local_dst_ip));
+		log_error("vxlan-packet: wrong inner destination",
+			  inet_ntoa(vxlan_info->local_dst_ip));
 		return false;
 	}
 
 	if (memcmp(bfd->vxlan_info.local_dst_mac, vxlan_info->local_dst_mac,
 		   ETHERNET_ADDRESS_LENGTH)) {
-		ERRLOG("Error Rx BFD Vxlan pkt with wrong inner dst MAC %02x:%02x:%02x:%02x:%02x:%02x",
-		       vxlan_info->local_dst_mac[0],
-		       vxlan_info->local_dst_mac[1],
-		       vxlan_info->local_dst_mac[2],
-		       vxlan_info->local_dst_mac[3],
-		       vxlan_info->local_dst_mac[4],
-		       vxlan_info->local_dst_mac[5]);
+		log_error(
+			"vxlan-packet: wrong inner mac: %02x:%02x:%02x:%02x:%02x:%02x",
+			vxlan_info->local_dst_mac[0],
+			vxlan_info->local_dst_mac[1],
+			vxlan_info->local_dst_mac[2],
+			vxlan_info->local_dst_mac[3],
+			vxlan_info->local_dst_mac[4],
+			vxlan_info->local_dst_mac[5]);
 		return false;
 	}
 
@@ -729,10 +721,10 @@ static ssize_t bfd_recv_ipv4(int sd, bool is_mhop, char *port, size_t portlen,
 
 	mlen = recvmsg(sd, &msghdr, MSG_DONTWAIT);
 	if (mlen == -1) {
-		if (errno != EAGAIN) {
-			ERRLOG("Error receiving from BFD socket: %s",
-			       strerror(errno));
-		}
+		if (errno != EAGAIN)
+			log_error("ipv4-recv: recv failed: %s",
+				  strerror(errno));
+
 		return -1;
 	}
 
@@ -752,8 +744,10 @@ static ssize_t bfd_recv_ipv4(int sd, bool is_mhop, char *port, size_t portlen,
 
 			memcpy(&ttl, CMSG_DATA(cm), sizeof(ttl));
 			if ((is_mhop == false) && (ttl != BFD_TTL_VAL)) {
-				INFOLOG("Received pkt with invalid TTL %u from %s flags: %d",
-					ttl, satostr(peer), msghdr.msg_flags);
+				log_debug(
+					"ipv4-recv: invalid TTL from %s (expected %d, got %d flags %d)",
+					satostr(peer), ttl, BFD_TTL_VAL,
+					msghdr.msg_flags);
 				return -1;
 			}
 			break;
@@ -779,8 +773,10 @@ static ssize_t bfd_recv_ipv4(int sd, bool is_mhop, char *port, size_t portlen,
 
 			memcpy(&ttl, CMSG_DATA(cm), sizeof(ttl));
 			if ((is_mhop == false) && (ttl != BFD_TTL_VAL)) {
-				INFOLOG("Received pkt with invalid TTL %u from %s flags: %d",
-					ttl, satostr(peer), msghdr.msg_flags);
+				log_debug(
+					"ipv4-recv: invalid TTL from %s (expected %d, got %d flags %d)",
+					satostr(peer), ttl, BFD_TTL_VAL,
+					msghdr.msg_flags);
 				return -1;
 			}
 			break;
@@ -832,10 +828,10 @@ ssize_t bfd_recv_ipv6(int sd, bool is_mhop, char *port, size_t portlen,
 
 	mlen = recvmsg(sd, &msghdr6, MSG_DONTWAIT);
 	if (mlen == -1) {
-		if (errno != EAGAIN) {
-			ERRLOG("Error receiving from BFD socket: %s",
-			       strerror(errno));
-		}
+		if (errno != EAGAIN)
+			log_error("ipv4-recv: recv failed: %s",
+				  strerror(errno));
+
 		return -1;
 	}
 
@@ -851,8 +847,9 @@ ssize_t bfd_recv_ipv6(int sd, bool is_mhop, char *port, size_t portlen,
 		if (cm->cmsg_type == IPV6_HOPLIMIT) {
 			memcpy(&ttlval, CMSG_DATA(cm), 4);
 			if ((is_mhop == false) && (ttlval != BFD_TTL_VAL)) {
-				INFOLOG("Received pkt with invalid TTL %u from %s flags: %d",
-					ttlval, satostr(peer),
+				log_debug(
+					"ipv6-recv: invalid TTL from %s (expected %d, got %d flags %d)",
+					satostr(peer), ttlval, BFD_TTL_VAL,
 					msghdr.msg_flags);
 				return -1;
 			}
@@ -899,6 +896,42 @@ static void bfd_sd_reschedule(int sd)
 	}
 }
 
+static void cp_debug(bool mhop, struct sockaddr_any *peer,
+		     struct sockaddr_any *local, const char *port,
+		     const char *vrf, const char *fmt, ...)
+{
+	char buf[512], peerstr[128], localstr[128], portstr[64], vrfstr[64];
+	va_list vl;
+
+	if (peer->sa_sin.sin_family)
+		snprintf(peerstr, sizeof(peerstr), " peer:%s", satostr(peer));
+	else
+		peerstr[0] = 0;
+
+	if (local->sa_sin.sin_family)
+		snprintf(localstr, sizeof(localstr), " local:%s",
+			 satostr(local));
+	else
+		localstr[0] = 0;
+
+	if (port[0])
+		snprintf(portstr, sizeof(portstr), " port:%s", port);
+	else
+		portstr[0] = 0;
+
+	if (vrf[0])
+		snprintf(vrfstr, sizeof(vrfstr), " vrf:%s", port);
+	else
+		vrfstr[0] = 0;
+
+	va_start(vl, fmt);
+	vsnprintf(buf, sizeof(buf), fmt, vl);
+	va_end(vl);
+
+	log_debug("control-packet: %s [mhop:%s%s%s%s%s]", buf,
+		  mhop ? "yes" : "no", peerstr, localstr, portstr, vrfstr);
+}
+
 int bfd_recv_cb(struct thread *t)
 {
 	int sd = THREAD_FD(t);
@@ -906,7 +939,6 @@ int bfd_recv_cb(struct thread *t)
 	struct bfd_pkt *cp;
 	bool is_mhop, is_vxlan;
 	ssize_t mlen = 0;
-	uint8_t old_state;
 	uint32_t oldEchoXmt_TO, oldXmtTime;
 	struct sockaddr_any local, peer;
 	char port[MAXNAMELEN + 1], vrfname[MAXNAMELEN + 1];
@@ -915,11 +947,13 @@ int bfd_recv_cb(struct thread *t)
 	/* Schedule next read. */
 	bfd_sd_reschedule(sd);
 
+	/* Handle echo packets. */
 	if (sd == bglobal.bg_echo) {
 		ptm_bfd_process_echo_pkt(sd);
 		return 0;
 	}
 
+	/* Handle control packets. */
 	is_mhop = is_vxlan = false;
 	if (sd == bglobal.bg_shop || sd == bglobal.bg_mhop) {
 		is_mhop = sd == bglobal.bg_mhop;
@@ -945,48 +979,65 @@ int bfd_recv_cb(struct thread *t)
 
 	/* Implement RFC 5880 6.8.6 */
 	if (mlen < BFD_PKT_LEN) {
-		INFOLOG("Received short packet from %s", satostr(&peer));
+		cp_debug(is_mhop, &peer, &local, port, vrfname,
+			 "too small (%ld bytes)", mlen);
 		return 0;
 	}
 
+	/*
+	 * Parse the control header for inconsistencies:
+	 * - Invalid version;
+	 * - Bad multiplier configuration;
+	 * - Short packets;
+	 * - Invalid discriminator;
+	 */
 	cp = (struct bfd_pkt *)(msghdr.msg_iov->iov_base);
 	if (BFD_GETVER(cp->diag) != BFD_VERSION) {
-		INFOLOG("Received bad version %d from %s", BFD_GETVER(cp->diag),
-			satostr(&peer));
+		cp_debug(is_mhop, &peer, &local, port, vrfname,
+			 "bad version %d", BFD_GETVER(cp->diag));
 		return 0;
 	}
 
 	if (cp->detect_mult == 0) {
-		INFOLOG("Detect Mult is zero in pkt from %s", satostr(&peer));
+		cp_debug(is_mhop, &peer, &local, port, vrfname,
+			 "detect multiplier set to zero");
 		return 0;
 	}
 
 	if ((cp->len < BFD_PKT_LEN) || (cp->len > mlen)) {
-		INFOLOG("Invalid length %d in control pkt from %s", cp->len,
-			satostr(&peer));
+		cp_debug(is_mhop, &peer, &local, port, vrfname, "too small");
 		return 0;
 	}
 
 	if (cp->discrs.my_discr == 0) {
-		INFOLOG("My discriminator is zero in pkt from %s",
-			satostr(&peer));
+		cp_debug(is_mhop, &peer, &local, port, vrfname,
+			 "'my discriminator' is zero");
 		return 0;
 	}
 
+	/* Find the session that this packet belongs. */
 	bfd = ptm_bfd_sess_find(cp, port, &peer, &local, vrfname, is_mhop);
 	if (bfd == NULL) {
-		DLOG("Failed to generate session from remote packet");
+		cp_debug(is_mhop, &peer, &local, port, vrfname,
+			 "no session found");
 		return 0;
 	}
 
+	/* Handle VxLAN cases. */
 	if (is_vxlan && !ptm_bfd_validate_vxlan_pkt(bfd, &vxlan_info))
 		return 0;
 
 	bfd->stats.rx_ctrl_pkt++;
+
+	/*
+	 * Multi hop: validate packet TTL.
+	 * Single hop: set local address that received the packet.
+	 */
 	if (is_mhop) {
 		if ((BFD_TTL_VAL - bfd->mh_ttl) > ttlval) {
-			DLOG("Exceeded max hop count of %d, dropped pkt from %s with TTL %d",
-			     bfd->mh_ttl, satostr(&peer), ttlval);
+			cp_debug(is_mhop, &peer, &local, port, vrfname,
+				 "exceeded max hop count (expected %d, got %d)",
+				 bfd->mh_ttl, ttlval);
 			return 0;
 		}
 	} else if (bfd->local_ip.sa_sin.sin_family == AF_UNSPEC) {
@@ -1000,12 +1051,12 @@ int bfd_recv_cb(struct thread *t)
 	if (bfd->ifindex == 0)
 		bfd->ifindex = ptm_bfd_fetch_ifindex(port);
 
+	/* Log remote discriminator changes. */
 	if ((bfd->discrs.remote_discr != 0)
-	    && (bfd->discrs.remote_discr != ntohl(cp->discrs.my_discr))) {
-		DLOG("My Discriminator mismatch in pkt from %s, Expected %d Got %d",
-		     satostr(&peer), bfd->discrs.remote_discr,
-		     ntohl(cp->discrs.my_discr));
-	}
+	    && (bfd->discrs.remote_discr != ntohl(cp->discrs.my_discr)))
+		cp_debug(is_mhop, &peer, &local, port, vrfname,
+			 "remote discriminator mismatch (expected %d, got %d)",
+			 bfd->discrs.remote_discr, ntohl(cp->discrs.my_discr));
 
 	bfd->discrs.remote_discr = ntohl(cp->discrs.my_discr);
 
@@ -1026,15 +1077,14 @@ int bfd_recv_cb(struct thread *t)
 					    ? bfd->timers.required_min_rx
 					    : ntohl(cp->timers.desired_min_tx));
 		bfd->remote_detect_mult = cp->detect_mult;
-	} else {
-		ERRLOG("Unsupport BFD mode detected");
-	}
+	} else
+		cp_debug(is_mhop, &peer, &local, port, vrfname,
+			 "unsupported demand mode");
 
 	/* Save remote diagnostics before state switch. */
 	bfd->remote_diag = cp->diag & BFD_DIAGMASK;
 
 	/* State switch from section 6.8.6 */
-	old_state = bfd->ses_state;
 	if (BFD_GETSTATE(cp->flags) == PTM_BFD_ADM_DOWN) {
 		if (bfd->ses_state != PTM_BFD_DOWN)
 			ptm_bfd_ses_dn(bfd, BFD_DIAGNEIGHDOWN);
@@ -1058,12 +1108,13 @@ int bfd_recv_cb(struct thread *t)
 		}
 	}
 
-	if (old_state != bfd->ses_state) {
-		DLOG("BFD Sess %d [%s] Old State [%s] : New State [%s]",
-		     bfd->discrs.my_discr, satostr(&peer),
-		     state_list[old_state].str, state_list[bfd->ses_state].str);
-	}
-
+	/*
+	 * Handle echo packet status:
+	 * - Start echo packets if configured and permitted
+	 *   (required_min_echo > 0);
+	 * - Stop echo packets if not allowed (required_min_echo == 0);
+	 * - Recalculate echo packet interval;
+	 */
 	if (BFD_CHECK_FLAG(bfd->flags, BFD_SESS_FLAG_ECHO)) {
 		if (BFD_CHECK_FLAG(bfd->flags, BFD_SESS_FLAG_ECHO_ACTIVE)) {
 			if (!ntohl(cp->timers.required_min_echo)) {
@@ -1112,12 +1163,9 @@ int bfd_recv_cb(struct thread *t)
 		ptm_bfd_start_xmt_timer(bfd, false);
 	}
 
-	if (!bfd->demand_mode) {
-		/* Restart detection timer (packet received) */
+	/* Restart detection timer (packet received) */
+	if (!bfd->demand_mode)
 		bfd_recvtimer_update(bfd);
-	} else {
-		ERRLOG("Unsupport BFD mode detected");
-	}
 
 	/*
 	 * Save the timers and state sent by the remote end
@@ -1248,8 +1296,11 @@ int bp_peer_socket(struct bfd_peer_cfg *bpc)
 	static int srcPort = BFD_SRCPORTINIT;
 
 	sd = socket(AF_INET, SOCK_DGRAM, PF_UNSPEC);
-	if (sd == -1)
+	if (sd == -1) {
+		log_error("ipv4-new: failed to create socket: %s",
+			  strerror(errno));
 		return -1;
+	}
 
 	if (!bpc->bpc_has_vxlan) {
 		/* Set TTL to 255 for all transmitted packets */
@@ -1294,8 +1345,8 @@ int bp_peer_socket(struct bfd_peer_cfg *bpc)
 	do {
 		if ((++pcount) > (BFD_SRCPORTMAX - BFD_SRCPORTINIT)) {
 			/* Searched all ports, none available */
-			ERRLOG("Can't find source port for new session: %s",
-			       strerror(errno));
+			log_error("ipv4-new: failed to bind port: %s",
+				  strerror(errno));
 			close(sd);
 			return -1;
 		}
@@ -1319,8 +1370,11 @@ int bp_peer_socketv6(struct bfd_peer_cfg *bpc)
 	static int srcPort = BFD_SRCPORTINIT;
 
 	sd = socket(AF_INET6, SOCK_DGRAM, PF_UNSPEC);
-	if (sd == -1)
+	if (sd == -1) {
+		log_error("ipv6-new: failed to create socket: %s",
+			  strerror(errno));
 		return -1;
+	}
 
 	if (!bpc->bpc_has_vxlan) {
 		/* Set TTL to 255 for all transmitted packets */
@@ -1370,8 +1424,8 @@ int bp_peer_socketv6(struct bfd_peer_cfg *bpc)
 	do {
 		if ((++pcount) > (BFD_SRCPORTMAX - BFD_SRCPORTINIT)) {
 			/* Searched all ports, none available */
-			ERRLOG("Can't find source port for new session: %s",
-			       strerror(errno));
+			log_error("ipv6-new: failed to bind port: %s",
+				  strerror(errno));
 			close(sd);
 			return -1;
 		}
diff --git a/bfdd/bsd.c b/bfdd/bsd.c
index 3d196dfb9f..34a3a1a801 100644
--- a/bfdd/bsd.c
+++ b/bfdd/bsd.c
@@ -136,7 +136,7 @@ int ptm_bfd_echo_sock_init(void)
 
 	s = socket(AF_INET, SOCK_DGRAM, PF_UNSPEC);
 	if (s == -1) {
-		ERRLOG("%s: socket: %s", __func__, strerror(errno));
+		log_error("echo-socket: creation failed: %s", strerror(errno));
 		return -1;
 	}
 
@@ -148,13 +148,13 @@ int ptm_bfd_echo_sock_init(void)
 	sin.sin_family = AF_INET;
 	sin.sin_port = htons(3785);
 	if (bind(s, (struct sockaddr *)&sin, sizeof(sin)) == -1) {
-		log_error("%s: bind: %s", __func__, strerror(errno));
+		log_error("echo-socket: bind failure: %s", strerror(errno));
 		close(s);
 		return -1;
 	}
 
 	if (setsockopt(s, IPPROTO_IP, IP_RECVTTL, &yes, sizeof(yes)) == -1) {
-		log_error("%s: setsockopt(IP_RECVTTL): %s", __func__,
+		log_error("echo-socket: setsockopt(IP_RECVTTL): %s",
 			  strerror(errno));
 		close(s);
 		return -1;
@@ -162,7 +162,7 @@ int ptm_bfd_echo_sock_init(void)
 
 	ttl = BFD_TTL_VAL;
 	if (setsockopt(s, IPPROTO_IP, IP_TTL, &ttl, sizeof(ttl)) == -1) {
-		log_error("%s: setsockopt(IP_TTL): %s", __func__,
+		log_error("echo-socket: setsockopt(IP_TTL): %s",
 			  strerror(errno));
 		close(s);
 		return -1;
diff --git a/bfdd/linux.c b/bfdd/linux.c
index 8a68511d53..5f24ef4d19 100644
--- a/bfdd/linux.c
+++ b/bfdd/linux.c
@@ -75,13 +75,13 @@ int ptm_bfd_fetch_ifindex(const char *ifname)
 	struct ifreq ifr;
 
 	if (strlcpy(ifr.ifr_name, ifname, sizeof(ifr.ifr_name))
-	    > sizeof(ifr.ifr_name)) {
-		CRITLOG("Interface name %s truncated", ifr.ifr_name);
-	}
+	    > sizeof(ifr.ifr_name))
+		log_error("interface-to-index: name truncated ('%s' -> '%s')",
+			  ifr.ifr_name, ifname);
 
 	if (ioctl(bglobal.bg_shop, SIOCGIFINDEX, &ifr) == -1) {
-		CRITLOG("Getting ifindex for %s failed: %s", ifname,
-			strerror(errno));
+		log_error("interface-to-index: %s translation failed: %s",
+			  ifname, strerror(errno));
 		return -1;
 	}
 
@@ -93,13 +93,13 @@ void ptm_bfd_fetch_local_mac(const char *ifname, uint8_t *mac)
 	struct ifreq ifr;
 
 	if (strlcpy(ifr.ifr_name, ifname, sizeof(ifr.ifr_name))
-	    > sizeof(ifr.ifr_name)) {
-		CRITLOG("Interface name %s truncated", ifr.ifr_name);
-	}
+	    > sizeof(ifr.ifr_name))
+		log_error("interface-mac: name truncated ('%s' -> '%s')",
+			  ifr.ifr_name, ifname);
 
 	if (ioctl(bglobal.bg_shop, SIOCGIFHWADDR, &ifr) == -1) {
-		CRITLOG("Getting mac address for %s failed: %s", ifname,
-			strerror(errno));
+		log_error("interface-mac: %s MAC retrieval failed: %s", ifname,
+			  strerror(errno));
 		return;
 	}
 
@@ -118,12 +118,14 @@ void fetch_portname_from_ifindex(int ifindex, char *ifname, size_t ifnamelen)
 	ifr.ifr_ifindex = ifindex;
 
 	if (ioctl(bglobal.bg_shop, SIOCGIFNAME, &ifr) == -1) {
-		CRITLOG("Getting ifname for ifindex %d failed: %s", ifindex,
-			strerror(errno));
+		log_error("index-to-interface: index %d failure: %s", ifindex,
+			  strerror(errno));
 		return;
 	}
 
-	strlcpy(ifname, ifr.ifr_name, ifnamelen);
+	if (strlcpy(ifname, ifr.ifr_name, ifnamelen) >= ifnamelen)
+		log_debug("index-to-interface: name truncated '%s' -> '%s'",
+			  ifr.ifr_name, ifname);
 }
 
 int ptm_bfd_echo_sock_init(void)
@@ -135,14 +137,14 @@ int ptm_bfd_echo_sock_init(void)
 
 	s = socket(PF_PACKET, SOCK_RAW, htons(ETH_P_IP));
 	if (s == -1) {
-		ERRLOG("%s: socket: %s", __func__, strerror(errno));
+		log_error("echo-socket: creation failure: %s", strerror(errno));
 		return -1;
 	}
 
 	if (setsockopt(s, SOL_SOCKET, SO_ATTACH_FILTER, &bpf, sizeof(bpf))
 	    == -1) {
-		ERRLOG("%s: setsockopt(SO_ATTACH_FILTER): %s", __func__,
-		       strerror(errno));
+		log_error("echo-socket: setsockopt(SO_ATTACH_FILTER): %s",
+			  strerror(errno));
 		close(s);
 		return -1;
 	}
@@ -159,14 +161,15 @@ int ptm_bfd_vxlan_sock_init(void)
 
 	s = socket(PF_PACKET, SOCK_RAW, htons(ETH_P_IP));
 	if (s == -1) {
-		ERRLOG("%s: socket: %s", __func__, strerror(errno));
+		log_error("vxlan-socket: creation failure: %s",
+			  strerror(errno));
 		return -1;
 	}
 
 	if (setsockopt(s, SOL_SOCKET, SO_ATTACH_FILTER, &bpf, sizeof(bpf))
 	    == -1) {
-		ERRLOG("%s: setsockopt(SO_ATTACH_FILTER): %s", __func__,
-		       strerror(errno));
+		log_error("vxlan-socket: setsockopt(SO_ATTACH_FILTER): %s",
+			  strerror(errno));
 		close(s);
 		return -1;
 	}