From nobody Fri Jan 13 21:24:45 2023 X-Original-To: dev-commits-src-branches@mlmmj.nyi.freebsd.org Received: from mx1.freebsd.org (mx1.freebsd.org [IPv6:2610:1c1:1:606c::19:1]) by mlmmj.nyi.freebsd.org (Postfix) with ESMTP id 4NtvZP5XmSz2qkXr; Fri, 13 Jan 2023 21:24:45 +0000 (UTC) (envelope-from git@FreeBSD.org) Received: from mxrelay.nyi.freebsd.org (mxrelay.nyi.freebsd.org [IPv6:2610:1c1:1:606c::19:3]) (using TLSv1.3 with cipher TLS_AES_256_GCM_SHA384 (256/256 bits) key-exchange X25519 server-signature RSA-PSS (4096 bits) server-digest SHA256 client-signature RSA-PSS (4096 bits) client-digest SHA256) (Client CN "mxrelay.nyi.freebsd.org", Issuer "R3" (verified OK)) by mx1.freebsd.org (Postfix) with ESMTPS id 4NtvZP4TDmz40Fg; Fri, 13 Jan 2023 21:24:45 +0000 (UTC) (envelope-from git@FreeBSD.org) DKIM-Signature: v=1; a=rsa-sha256; c=relaxed/relaxed; d=freebsd.org; s=dkim; t=1673645085; h=from:from:reply-to:subject:subject:date:date:message-id:message-id: to:to:cc:mime-version:mime-version:content-type:content-type: content-transfer-encoding:content-transfer-encoding; bh=AGCrdoDrX0mA4uCSm8Zf49jqK4xnhUs+G53I4QB0Y9E=; b=jYrucpc2+jQ6jtVkZ655aMBRP3oXEXDn6bHPG4CfIi5sg8YJyFpyfCQaQx2k0KsMPMC0xj IIe4Ql87mkMPIKRKCtkWCh01gQh5FJ6Dv/5+1vUDWAy8qzrwbQ1Swe1GGGsSsiQjM2bCem xMSSwB1DUWvVHKTy+SLLwqdwojuEd74jzvCFq9+0XI9ef9NbWD1O5C6YrBse6BqLIXY/lM wdXgyEUljuPkgxZ7vlWNM3gTPfJULZTT1yjXZfqJG6dxC9g/ykjfSTM7VCGAepHugj6amK eP54Bq2EuivgTik1ZcGOTAp/ZOO7uNcu8NQdGHVEkl8W/Zbnyjq31foHtlfrtg== ARC-Message-Signature: i=1; a=rsa-sha256; c=relaxed/relaxed; d=freebsd.org; s=dkim; t=1673645085; h=from:from:reply-to:subject:subject:date:date:message-id:message-id: to:to:cc:mime-version:mime-version:content-type:content-type: content-transfer-encoding:content-transfer-encoding; bh=AGCrdoDrX0mA4uCSm8Zf49jqK4xnhUs+G53I4QB0Y9E=; b=ga5k4pNULG+wke8/fO6dFaRtvbZuxztwj0o/m3IIIq+W8FNN0kcMJQInJnPUHhkT/JcdLa 58/OXnP0kXxMfqcAzak5LqzBMkFkpdPCm85y9tNRajZYQKPpuWbZO9JY8J1Ygm1iMlY68D f0T47fSoGgMvmyuugRfGw/KRCPqNApkE5ucraprMpynTq22TSLaGchQ9/Oevmjk8RShWUQ hjsQyBmWasTj8MqbXsS57kRo7DXJ/kT3WqpHGnCBSK6FdZv2RC9CtEZmQpLglcS6I7M8yX E7DXogPGg4m7gt4gzcbdW/bIEzQd7eXx9YXyHqac8kvrn9lCTIWPCXpJHqI5EA== ARC-Authentication-Results: i=1; mx1.freebsd.org; none ARC-Seal: i=1; s=dkim; d=freebsd.org; t=1673645085; a=rsa-sha256; cv=none; b=Qtc3uL1WkuYxIqP+hXEYrj7CknaMpI770qxmOIvaML6m+V2MmPzsx2K3fZhxSQu/U3IPLL eZsw20P36OZfKMjS0Rn6qNWZf5hkzOB6THKMTDMiTcHYdq15VLKieCDKtnCWtgA3qwynP/ ZkLOH6MUJdrlx7VJnDVwwjeVFeYI4fRgDRcF0Qo6rfOIp5iMJ1jx8HwH/c0e9/af9zS5n2 NtlY1a3sc51ECpZuALFzG/i1yCJqO7vt7KRT/CtXdfMhrdKVcqUrMGLFJlizNXsyk9erEj CbrW8KIJ2GPlhQ9pYtRT+4N8mjq9z6Dd0E4FW31wz26n6YKeUdrofZCy4Zk5IA== Received: from gitrepo.freebsd.org (gitrepo.freebsd.org [IPv6:2610:1c1:1:6068::e6a:5]) (using TLSv1.3 with cipher TLS_AES_256_GCM_SHA384 (256/256 bits) key-exchange X25519 server-signature RSA-PSS (4096 bits) server-digest SHA256) (Client did not present a certificate) by mxrelay.nyi.freebsd.org (Postfix) with ESMTPS id 4NtvZP36W1zMMq; Fri, 13 Jan 2023 21:24:45 +0000 (UTC) (envelope-from git@FreeBSD.org) Received: from gitrepo.freebsd.org ([127.0.1.44]) by gitrepo.freebsd.org (8.16.1/8.16.1) with ESMTP id 30DLOjaa040601; Fri, 13 Jan 2023 21:24:45 GMT (envelope-from git@gitrepo.freebsd.org) Received: (from git@localhost) by gitrepo.freebsd.org (8.16.1/8.16.1/Submit) id 30DLOjuu040600; Fri, 13 Jan 2023 21:24:45 GMT (envelope-from git) Date: Fri, 13 Jan 2023 21:24:45 GMT Message-Id: <202301132124.30DLOjuu040600@gitrepo.freebsd.org> To: src-committers@FreeBSD.org, dev-commits-src-all@FreeBSD.org, dev-commits-src-branches@FreeBSD.org From: "Alexander V. Chernikov" Subject: git: 6d7d5b869a4f - stable/13 - routing: improve debugging. List-Id: Commits to the stable branches of the FreeBSD src repository List-Archive: https://lists.freebsd.org/archives/dev-commits-src-branches List-Help: List-Post: List-Subscribe: List-Unsubscribe: Sender: owner-dev-commits-src-branches@freebsd.org X-BeenThere: dev-commits-src-branches@freebsd.org MIME-Version: 1.0 Content-Type: text/plain; charset=utf-8 Content-Transfer-Encoding: 8bit X-Git-Committer: melifaro X-Git-Repository: src X-Git-Refname: refs/heads/stable/13 X-Git-Reftype: branch X-Git-Commit: 6d7d5b869a4fa9ae4621cabc3fb13e7fb11730fd Auto-Submitted: auto-generated X-ThisMailContainsUnwantedMimeParts: N The branch stable/13 has been updated by melifaro: URL: https://cgit.FreeBSD.org/src/commit/?id=6d7d5b869a4fa9ae4621cabc3fb13e7fb11730fd commit 6d7d5b869a4fa9ae4621cabc3fb13e7fb11730fd Author: Alexander V. Chernikov AuthorDate: 2022-06-25 19:53:31 +0000 Commit: Alexander V. Chernikov CommitDate: 2023-01-13 21:18:25 +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 (cherry picked from commit 6fa8ed43ee0ca43cf170f52b57fcad562f97baba) --- 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 d35ad0213bb3..4bf7bfb1b416 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 8a61db449462..f8b6a6eb4cd0 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 7802c7d8da9e..5d9b4b7fa9f7 100644 --- a/sys/net/rtsock.c +++ b/sys/net/rtsock.c @@ -80,6 +80,11 @@ #include #include +#define DEBUG_MOD_NAME rtsock +#define DEBUG_MAX_LEVEL LOG_DEBUG +#include +_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; @@ -1101,8 +1108,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); } @@ -1111,8 +1120,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) { @@ -1303,8 +1314,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. @@ -1372,11 +1385,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); } @@ -1398,7 +1415,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)); @@ -1414,7 +1432,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); @@ -1428,7 +1447,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)); @@ -1470,8 +1490,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)) { /* @@ -1485,7 +1508,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 @@ -1530,7 +1554,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); } @@ -1546,7 +1571,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 @@ -1582,8 +1608,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) { /*