The branch main has been updated by melifaro: URL: https://cgit.FreeBSD.org/src/commit/?id=6fa8ed43ee0ca43cf170f52b57fcad562f97baba
commit 6fa8ed43ee0ca43cf170f52b57fcad562f97baba Author: Alexander V. Chernikov <[email protected]> AuthorDate: 2022-06-25 19:53:31 +0000 Commit: Alexander V. Chernikov <[email protected]> CommitDate: 2022-06-25 19:53:31 +0000 routing: improve debugging. Use unified guidelines for the severity across the routing subsystem. Update severity for some of the already-used messages to adhere the guidelines. Convert rtsock logging to the new FIB_ reporting format. MFC after: 2 weeks --- sys/net/route/nhgrp.c | 2 +- sys/net/route/nhop_ctl.c | 11 +++++--- sys/net/route/route_ctl.c | 23 +++++++++++++---- sys/net/route/route_debug.h | 25 ++++++++++++++++++ sys/net/rtsock.c | 62 ++++++++++++++++++++++++++++++++------------- 5 files changed, 96 insertions(+), 27 deletions(-) diff --git a/sys/net/route/nhgrp.c b/sys/net/route/nhgrp.c index de53c792aea9..8f6c04b86395 100644 --- a/sys/net/route/nhgrp.c +++ b/sys/net/route/nhgrp.c @@ -168,7 +168,7 @@ link_nhgrp(struct nh_control *ctl, struct nhgrp_priv *grp_priv) if (bitmask_alloc_idx(&ctl->nh_idx_head, &idx) != 0) { NHOPS_WUNLOCK(ctl); - FIB_RH_LOG(LOG_INFO, ctl->ctl_rh, "Unable to allocate nhg index"); + FIB_RH_LOG(LOG_DEBUG, ctl->ctl_rh, "Unable to allocate nhg index"); consider_resize(ctl, new_num_buckets, new_num_items); return (0); } diff --git a/sys/net/route/nhop_ctl.c b/sys/net/route/nhop_ctl.c index be09d1a60772..0e9a6b8a0a77 100644 --- a/sys/net/route/nhop_ctl.c +++ b/sys/net/route/nhop_ctl.c @@ -229,7 +229,8 @@ set_nhop_gw_from_info(struct nhop_object *nh, struct rt_addrinfo *info) struct sockaddr_dl *sdl = (struct sockaddr_dl *)gw; struct ifnet *ifp = ifnet_byindex(sdl->sdl_index); if (ifp == NULL) { - FIB_NH_LOG(LOG_WARNING, nh, "invalid ifindex %d", sdl->sdl_index); + FIB_NH_LOG(LOG_DEBUG, nh, "error: invalid ifindex %d", + sdl->sdl_index); return (EINVAL); } fill_sdl_from_ifp(&nh->gwl_sa, ifp); @@ -247,9 +248,9 @@ set_nhop_gw_from_info(struct nhop_object *nh, struct rt_addrinfo *info) * happy. */ if (gw->sa_len > sizeof(struct sockaddr_in6)) { - FIB_NH_LOG(LOG_WARNING, nh, "nhop SA size too big: AF %d len %u", + FIB_NH_LOG(LOG_DEBUG, nh, "nhop SA size too big: AF %d len %u", gw->sa_family, gw->sa_len); - return (ENOMEM); + return (EINVAL); } memcpy(&nh->gw_sa, gw, gw->sa_len); } @@ -323,8 +324,10 @@ nhop_create_from_info(struct rib_head *rnh, struct rt_addrinfo *info, NET_EPOCH_ASSERT(); - if (info->rti_info[RTAX_GATEWAY] == NULL) + if (info->rti_info[RTAX_GATEWAY] == NULL) { + FIB_RH_LOG(LOG_DEBUG, rnh, "error: empty gateway"); return (EINVAL); + } nh_priv = alloc_nhop_structure(); diff --git a/sys/net/route/route_ctl.c b/sys/net/route/route_ctl.c index 80312b7c717c..fa0242f5bf7f 100644 --- a/sys/net/route/route_ctl.c +++ b/sys/net/route/route_ctl.c @@ -586,8 +586,10 @@ rib_add_route(uint32_t fibnum, struct rt_addrinfo *info, */ if (info->rti_flags & RTF_HOST) info->rti_info[RTAX_NETMASK] = NULL; - else if (info->rti_info[RTAX_NETMASK] == NULL) + else if (info->rti_info[RTAX_NETMASK] == NULL) { + FIB_RH_LOG(LOG_DEBUG, rnh, "error: no RTF_HOST and empty netmask"); return (EINVAL); + } bzero(rc, sizeof(struct rib_cmd_info)); rc->rc_cmd = RTM_ADD; @@ -642,13 +644,22 @@ create_rtentry(struct rib_head *rnh, struct rt_addrinfo *info, netmask = info->rti_info[RTAX_NETMASK]; flags = info->rti_flags; - if ((flags & RTF_GATEWAY) && !gateway) + if ((flags & RTF_GATEWAY) && !gateway) { + FIB_RH_LOG(LOG_DEBUG, rnh, "error: RTF_GATEWAY set with empty gw"); return (EINVAL); - if (dst && gateway && !check_gateway(rnh, dst, gateway)) + } + if (dst && gateway && !check_gateway(rnh, dst, gateway)) { + FIB_RH_LOG(LOG_DEBUG, rnh, + "error: invalid dst/gateway family combination (%d, %d)", + dst->sa_family, gateway->sa_family); return (EINVAL); + } - if (dst->sa_len > sizeof(((struct rtentry *)NULL)->rt_dstb)) + if (dst->sa_len > sizeof(((struct rtentry *)NULL)->rt_dstb)) { + FIB_RH_LOG(LOG_DEBUG, rnh, "error: dst->sa_len too large: %d", + dst->sa_len); return (EINVAL); + } if (info->rti_ifa == NULL) { error = rt_getifa_fib(info, rnh->rib_fibnum); @@ -798,8 +809,10 @@ rib_del_route(uint32_t fibnum, struct rt_addrinfo *info, struct rib_cmd_info *rc if (netmask != NULL) { /* Ensure @dst is always properly masked */ - if (dst_orig->sa_len > sizeof(mdst)) + if (dst_orig->sa_len > sizeof(mdst)) { + FIB_RH_LOG(LOG_DEBUG, rnh, "error: dst->sa_len too large"); return (EINVAL); + } rt_maskedcopy(dst_orig, (struct sockaddr *)&mdst, netmask); info->rti_info[RTAX_DST] = (struct sockaddr *)&mdst; } diff --git a/sys/net/route/route_debug.h b/sys/net/route/route_debug.h index 7bc98c43c0dc..ef14da4db81c 100644 --- a/sys/net/route/route_debug.h +++ b/sys/net/route/route_debug.h @@ -62,6 +62,31 @@ #define LOG_DEBUG3 9 #endif +/* + * Severity usage guidelines: + * + * LOG_WARNING - subsystem-global errors ("multipath init failed") + * + * LOG_INFO - subsystem non-transient errors ("Failed to unlink nexhop"). + * All logging <= LOG_INFO by default will be written to syslog. + * + * LOG_DEBUG - subsystem debug. Not-too often events (hash resizes, recoverable failures). + * These are compiled in by default on production. Turning it it should NOT notable affect + * performance + * LOG_DEBUG2 - more debug. Per-item level (nhg,nh,route) debug, up to multiple lines per item. + * This is NOT compiled in by default. Turning it on should NOT seriously impact performance + * LOG_DEBUG3 - last debug level. Per-item large debug outputs. + * This is NOT compiled in by default. All performance bets are off. + * + */ + + +#define LOG_WARNING 4 /* warning conditions */ +#define LOG_NOTICE 5 /* normal but significant condition */ +#define LOG_INFO 6 /* informational */ +#define LOG_DEBUG 7 /* debug-level messages */ + + #define _output printf #define _DEBUG_PASS_MSG(_l) (DEBUG_VAR_NAME >= (_l)) diff --git a/sys/net/rtsock.c b/sys/net/rtsock.c index 6775f09cfe50..995b78795eb4 100644 --- a/sys/net/rtsock.c +++ b/sys/net/rtsock.c @@ -80,6 +80,11 @@ #include <sys/mount.h> #include <compat/freebsd32/freebsd32.h> +#define DEBUG_MOD_NAME rtsock +#define DEBUG_MAX_LEVEL LOG_DEBUG +#include <net/route/route_debug.h> +_DECLARE_DEBUG(LOG_INFO); + struct if_msghdr32 { uint16_t ifm_msglen; uint8_t ifm_version; @@ -133,8 +138,7 @@ struct linear_buffer { }; #define SCRATCH_BUFFER_SIZE 1024 -#define RTS_PID_PRINTF(_fmt, ...) \ - printf("rtsock:%s(): PID %d: " _fmt "\n", __func__, curproc->p_pid, ## __VA_ARGS__) +#define RTS_PID_LOG(_l, _fmt, ...) RT_LOG_##_l(_l, "PID %d: " _fmt, curproc ? curproc->p_pid : 0, ## __VA_ARGS__) MALLOC_DEFINE(M_RTABLE, "routetbl", "routing tables"); @@ -581,7 +585,7 @@ fill_blackholeinfo(struct rt_addrinfo *info, union sockaddr_union *saun) sa_family_t saf; if (V_loif == NULL) { - RTS_PID_PRINTF("Unable to add blackhole/reject nhop without loopback"); + RTS_PID_LOG(LOG_INFO, "Unable to add blackhole/reject nhop without loopback"); return (ENOTSUP); } info->rti_ifp = V_loif; @@ -594,8 +598,10 @@ fill_blackholeinfo(struct rt_addrinfo *info, union sockaddr_union *saun) break; } } - if (info->rti_ifa == NULL) + if (info->rti_ifa == NULL) { + RTS_PID_LOG(LOG_INFO, "Unable to find ifa for blackhole/reject nhop"); return (ENOTSUP); + } bzero(saun, sizeof(union sockaddr_union)); switch (saf) { @@ -614,6 +620,7 @@ fill_blackholeinfo(struct rt_addrinfo *info, union sockaddr_union *saun) break; #endif default: + RTS_PID_LOG(LOG_INFO, "unsupported family: %d", saf); return (ENOTSUP); } info->rti_info[RTAX_GATEWAY] = &saun->sa; @@ -1100,8 +1107,10 @@ route_output(struct mbuf *m, struct socket *so, ...) if (blackhole_flags != 0) { if (blackhole_flags != (RTF_BLACKHOLE | RTF_REJECT)) error = fill_blackholeinfo(&info, &gw_saun); - else + else { + RTS_PID_LOG(LOG_DEBUG, "both BLACKHOLE and REJECT flags specifiied"); error = EINVAL; + } if (error != 0) senderr(error); } @@ -1110,8 +1119,10 @@ route_output(struct mbuf *m, struct socket *so, ...) case RTM_ADD: case RTM_CHANGE: if (rtm->rtm_type == RTM_ADD) { - if (info.rti_info[RTAX_GATEWAY] == NULL) + if (info.rti_info[RTAX_GATEWAY] == NULL) { + RTS_PID_LOG(LOG_DEBUG, "RTM_ADD w/o gateway"); senderr(EINVAL); + } } error = rib_action(fibnum, rtm->rtm_type, &info, &rc); if (error == 0) { @@ -1304,8 +1315,10 @@ rt_xaddrs(caddr_t cp, caddr_t cplim, struct rt_addrinfo *rtinfo) /* * It won't fit. */ - if (cp + sa->sa_len > cplim) + if (cp + sa->sa_len > cplim) { + RTS_PID_LOG(LOG_DEBUG, "sa_len too big for sa type %d", i); return (EINVAL); + } /* * there are no more.. quit now * If there are more bits, they are in error. @@ -1374,11 +1387,15 @@ cleanup_xaddrs_lladdr(struct rt_addrinfo *info) if (sdl->sdl_family != AF_LINK) return (EINVAL); - if (sdl->sdl_index == 0) + if (sdl->sdl_index == 0) { + RTS_PID_LOG(LOG_DEBUG, "AF_LINK gateway w/o ifindex"); return (EINVAL); + } - if (offsetof(struct sockaddr_dl, sdl_data) + sdl->sdl_nlen + sdl->sdl_alen > sdl->sdl_len) + if (offsetof(struct sockaddr_dl, sdl_data) + sdl->sdl_nlen + sdl->sdl_alen > sdl->sdl_len) { + RTS_PID_LOG(LOG_DEBUG, "AF_LINK gw: sdl_nlen/sdl_alen too large"); return (EINVAL); + } return (0); } @@ -1400,7 +1417,8 @@ cleanup_xaddrs_gateway(struct rt_addrinfo *info, struct linear_buffer *lb) /* Ensure reads do not go beyoud SA boundary */ if (SA_SIZE(gw) < offsetof(struct sockaddr_in, sin_zero)) { - RTS_PID_PRINTF("gateway sin_len too small: %d", gw->sa_len); + RTS_PID_LOG(LOG_DEBUG, "gateway sin_len too small: %d", + gw->sa_len); return (EINVAL); } sa = alloc_sockaddr_aligned(lb, sizeof(struct sockaddr_in)); @@ -1416,7 +1434,8 @@ cleanup_xaddrs_gateway(struct rt_addrinfo *info, struct linear_buffer *lb) { struct sockaddr_in6 *gw_sin6 = (struct sockaddr_in6 *)gw; if (gw_sin6->sin6_len < sizeof(struct sockaddr_in6)) { - RTS_PID_PRINTF("gateway sin6_len too small: %d", gw->sa_len); + RTS_PID_LOG(LOG_DEBUG, "gateway sin6_len too small: %d", + gw->sa_len); return (EINVAL); } fill_sockaddr_inet6(gw_sin6, &gw_sin6->sin6_addr, 0); @@ -1430,7 +1449,8 @@ cleanup_xaddrs_gateway(struct rt_addrinfo *info, struct linear_buffer *lb) size_t sdl_min_len = offsetof(struct sockaddr_dl, sdl_data); gw_sdl = (struct sockaddr_dl *)gw; if (gw_sdl->sdl_len < sdl_min_len) { - RTS_PID_PRINTF("gateway sdl_len too small: %d", gw_sdl->sdl_len); + RTS_PID_LOG(LOG_DEBUG, "gateway sdl_len too small: %d", + gw_sdl->sdl_len); return (EINVAL); } sa = alloc_sockaddr_aligned(lb, sizeof(struct sockaddr_dl_short)); @@ -1473,8 +1493,11 @@ cleanup_xaddrs_inet(struct rt_addrinfo *info, struct linear_buffer *lb) mask_sa = (struct sockaddr_in *)info->rti_info[RTAX_NETMASK]; /* Ensure reads do not go beyound the buffer size */ - if (SA_SIZE(dst_sa) < offsetof(struct sockaddr_in, sin_zero)) + if (SA_SIZE(dst_sa) < offsetof(struct sockaddr_in, sin_zero)) { + RTS_PID_LOG(LOG_DEBUG, "prefix dst sin_len too small: %d", + dst_sa->sin_len); return (EINVAL); + } if ((mask_sa != NULL) && mask_sa->sin_len < sizeof(struct sockaddr_in)) { /* @@ -1488,7 +1511,8 @@ cleanup_xaddrs_inet(struct rt_addrinfo *info, struct linear_buffer *lb) len = sizeof(struct in_addr); memcpy(&mask, &mask_sa->sin_addr, len); } else { - RTS_PID_PRINTF("prefix mask sin_len too small: %d", mask_sa->sin_len); + RTS_PID_LOG(LOG_DEBUG, "prefix mask sin_len too small: %d", + mask_sa->sin_len); return (EINVAL); } } else @@ -1533,7 +1557,8 @@ cleanup_xaddrs_inet6(struct rt_addrinfo *info, struct linear_buffer *lb) mask_sa = (struct sockaddr_in6 *)info->rti_info[RTAX_NETMASK]; if (dst_sa->sin6_len < sizeof(struct sockaddr_in6)) { - RTS_PID_PRINTF("prefix dst sin6_len too small: %d", dst_sa->sin6_len); + RTS_PID_LOG(LOG_DEBUG, "prefix dst sin6_len too small: %d", + dst_sa->sin6_len); return (EINVAL); } @@ -1549,7 +1574,8 @@ cleanup_xaddrs_inet6(struct rt_addrinfo *info, struct linear_buffer *lb) len = sizeof(struct in6_addr); memcpy(&mask, &mask_sa->sin6_addr, len); } else { - RTS_PID_PRINTF("rtsock: prefix mask sin6_len too small: %d", mask_sa->sin6_len); + RTS_PID_LOG(LOG_DEBUG, "rtsock: prefix mask sin6_len too small: %d", + mask_sa->sin6_len); return (EINVAL); } } else @@ -1585,8 +1611,10 @@ cleanup_xaddrs(struct rt_addrinfo *info, struct linear_buffer *lb) { int error = EAFNOSUPPORT; - if (info->rti_info[RTAX_DST] == NULL) + if (info->rti_info[RTAX_DST] == NULL) { + RTS_PID_LOG(LOG_DEBUG, "prefix dst is not set"); return (EINVAL); + } if (info->rti_flags & RTF_LLDATA) { /*
