From 03e7f0888166850122c81dce68683d9fb7edd751 Mon Sep 17 00:00:00 2001 From: Rafael Zalamena Date: Wed, 25 Jul 2018 00:03:47 -0300 Subject: [PATCH] bfdd: improve logging messages Show a little more details, remove some duplicated calls and remove the macro compatibility with old debugging functions. Signed-off-by: Rafael Zalamena --- bfdd/bfd.c | 122 +++++++++++------------- bfdd/bfd.h | 6 +- bfdd/bfd_packet.c | 230 ++++++++++++++++++++++++++++------------------ bfdd/bsd.c | 8 +- bfdd/linux.c | 41 +++++---- 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; } -- 2.39.5