]> git.puffer.fish Git - matthieu/frr.git/commitdiff
bfdd: improve logging messages
authorRafael Zalamena <rzalamena@opensourcerouting.org>
Wed, 25 Jul 2018 03:03:47 +0000 (00:03 -0300)
committerRafael Zalamena <rzalamena@opensourcerouting.org>
Wed, 8 Aug 2018 21:25:08 +0000 (18:25 -0300)
Show a little more details, remove some duplicated calls and remove the
macro compatibility with old debugging functions.

Signed-off-by: Rafael Zalamena <rzalamena@opensourcerouting.org>
bfdd/bfd.c
bfdd/bfd.h
bfdd/bfd_packet.c
bfdd/bsd.c
bfdd/linux.c

index 09499ad2c4c97c583d763c0d1ed787ab6f69e006..ff62cd356badda00f2f99cc5cec62a127afebf38 100644 (file)
@@ -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.
  */
index 8f7dd1b8c8c7c956c0c27658b5138382073f1375..40aecaa67bf2095e573fa0349b50e4d233f4ec7a 100644 (file)
@@ -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);
index 17c2486196cab1c887eb714dc4aad12da2ae1831..177d6307e4e2032a71be1e799f64132b15f407d8 100644 (file)
@@ -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;
                }
index 3d196dfb9fef6ffa2a4d1e505674482e466653d1..34a3a1a801e22268954488f14553221ae44d6ac7 100644 (file)
@@ -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;
index 8a68511d533a1e2df58272e2d47924f6c2a71783..5f24ef4d19cc573e122806f2c860e055760322a9 100644 (file)
@@ -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;
        }