routing: Add unified level-based logging support for the routing subsystem.

Summary: MFC after:	2 weeks
Differential Revision: https://reviews.freebsd.org/D33664
This commit is contained in:
Alexander V. Chernikov 2021-12-26 18:42:12 +00:00
parent 823a08d740
commit 63f7f3921b
6 changed files with 292 additions and 51 deletions

View File

@ -59,6 +59,7 @@ __FBSDID("$FreeBSD$");
#include <net/if_var.h>
#include <net/route.h>
#include <net/route/route_ctl.h>
#include <net/route/route_debug.h>
#include <net/vnet.h>
#include <netinet/if_ether.h>
#include <netinet6/in6_var.h>
@ -418,6 +419,67 @@ llentry_lookup_family(struct llentry *lle, int family)
return (NULL);
}
/*
* Retrieves upper protocol family for the llentry.
* By default, all "normal" (e.g. upper_family == transport_family)
* llentries have r_family set to 0.
* Thus, use @default_family in that regard, otherwise use r_family.
*
* Returns upper protocol family
*/
int
llentry_get_upper_family(const struct llentry *lle, int default_family)
{
return (lle->r_family == 0 ? default_family : lle->r_family);
}
/*
* Prints llentry @lle data into provided buffer.
* Example: lle/inet/valid/em0/1.2.3.4
*
* Returns @buf.
*/
char *
llentry_print_buf(const struct llentry *lle, struct ifnet *ifp, int family,
char *buf, size_t bufsize)
{
char abuf[INET6_ADDRSTRLEN];
const char *valid = (lle->r_flags & RLLE_VALID) ? "valid" : "no_l2";
const char *upper_str = rib_print_family(llentry_get_upper_family(lle, family));
switch (family) {
#ifdef INET
case AF_INET:
inet_ntop(AF_INET, &lle->r_l3addr.addr4, abuf, sizeof(abuf));
snprintf(buf, bufsize, "lle/%s/%s/%s/%s", upper_str,
valid, if_name(ifp), abuf);
break;
#endif
#ifdef INET6
case AF_INET6:
inet_ntop(AF_INET6, &lle->r_l3addr.addr6, abuf, sizeof(abuf));
snprintf(buf, bufsize, "lle/%s/%s/%s/%s", upper_str,
valid, if_name(ifp), abuf);
break;
#endif
default:
snprintf(buf, bufsize, "lle/%s/%s/%s/????", upper_str,
valid, if_name(ifp));
break;
}
return (buf);
}
char *
llentry_print_buf_lltable(const struct llentry *lle, char *buf, size_t bufsize)
{
struct lltable *tbl = lle->lle_tbl;
return (llentry_print_buf(lle, lltable_get_ifp(tbl), lltable_get_af(tbl), buf, bufsize));
}
/*
* Requests feedback from the datapath.
* First packet using @lle should result in

View File

@ -268,6 +268,7 @@ lla_lookup(struct lltable *llt, u_int flags, const struct sockaddr *l3addr)
void llentry_request_feedback(struct llentry *lle);
void llentry_mark_used(struct llentry *lle);
time_t llentry_get_hittime(struct llentry *lle);
int llentry_get_upper_family(const struct llentry *lle, int default_family);
/*
* Notify the LLE code that the entry was used by datapath.

View File

@ -448,6 +448,7 @@ void rib_free_info(struct rt_addrinfo *info);
void rib_flush_routes_family(int family);
struct nhop_object *rib_lookup(uint32_t fibnum, const struct sockaddr *dst,
uint32_t flags, uint32_t flowid);
const char *rib_print_family(int family);
#endif
#endif

View File

@ -52,6 +52,11 @@ __FBSDID("$FreeBSD$");
#include <net/route/nhop_var.h>
#include <net/vnet.h>
#define DEBUG_MOD_NAME nhop_ctl
#define DEBUG_MAX_LEVEL LOG_DEBUG
#include <net/route/route_debug.h>
_DECLARE_DEBUG(LOG_INFO);
/*
* This file contains core functionality for the nexthop ("nhop") route subsystem.
* The business logic needed to create nexhop objects is implemented here.
@ -91,8 +96,6 @@ static void fill_sdl_from_ifp(struct sockaddr_dl_short *sdl, const struct ifnet
static void destroy_nhop_epoch(epoch_context_t ctx);
static void destroy_nhop(struct nhop_priv *nh_priv);
static void print_nhop(const char *prefix, const struct nhop_object *nh);
_Static_assert(__offsetof(struct nhop_object, nh_ifp) == 32,
"nhop_object: wrong nh_ifp offset");
_Static_assert(sizeof(struct nhop_object) <= 128,
@ -139,7 +142,7 @@ get_aifp(const struct nhop_object *nh)
nh->gw_sa.sa_family == AF_LINK) {
aifp = ifnet_byindex(nh->gwl_sa.sdl_index);
if (aifp == NULL) {
DPRINTF("unable to get aifp for %s index %d",
FIB_NH_LOG(LOG_WARNING, nh, "unable to get aifp for %s index %d",
if_name(nh->nh_ifp), nh->gwl_sa.sdl_index);
}
}
@ -226,7 +229,7 @@ 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) {
DPRINTF("invalid ifindex %d", sdl->sdl_index);
FIB_NH_LOG(LOG_WARNING, nh, "invalid ifindex %d", sdl->sdl_index);
return (EINVAL);
}
fill_sdl_from_ifp(&nh->gwl_sa, ifp);
@ -244,7 +247,7 @@ set_nhop_gw_from_info(struct nhop_object *nh, struct rt_addrinfo *info)
* happy.
*/
if (gw->sa_len > sizeof(struct sockaddr_in6)) {
DPRINTF("nhop SA size too big: AF %d len %u",
FIB_NH_LOG(LOG_WARNING, nh, "nhop SA size too big: AF %d len %u",
gw->sa_family, gw->sa_len);
return (ENOMEM);
}
@ -525,7 +528,7 @@ reference_nhop_deps(struct nhop_object *nh)
ifa_free(nh->nh_ifa);
return (false);
}
DPRINTF("AIFP: %p nh_ifp %p", nh->nh_aifp, nh->nh_ifp);
FIB_NH_LOG(LOG_DEBUG, nh, "AIFP: %p nh_ifp %p", nh->nh_aifp, nh->nh_ifp);
if (!if_try_ref(nh->nh_ifp)) {
ifa_free(nh->nh_ifa);
if_rele(nh->nh_aifp);
@ -552,7 +555,7 @@ finalize_nhop(struct nh_control *ctl, struct rt_addrinfo *info,
if (nh->nh_pksent == NULL) {
uma_zfree(nhops_zone, nh);
RTSTAT_INC(rts_nh_alloc_failure);
DPRINTF("nh_alloc_finalize failed");
FIB_NH_LOG(LOG_WARNING, nh, "counter_u64_alloc() failed");
return (ENOMEM);
}
@ -560,7 +563,7 @@ finalize_nhop(struct nh_control *ctl, struct rt_addrinfo *info,
counter_u64_free(nh->nh_pksent);
uma_zfree(nhops_zone, nh);
RTSTAT_INC(rts_nh_alloc_failure);
DPRINTF("nh_alloc_finalize failed - reference failure");
FIB_NH_LOG(LOG_WARNING, nh, "interface reference failed");
return (EAGAIN);
}
@ -574,8 +577,6 @@ finalize_nhop(struct nh_control *ctl, struct rt_addrinfo *info,
nh_priv->nh_fibnum = ctl->ctl_rh->rib_fibnum;
print_nhop("FINALIZE", nh);
if (link_nhop(ctl, nh_priv) == 0) {
/*
* Adding nexthop to the datastructures
@ -583,49 +584,22 @@ finalize_nhop(struct nh_control *ctl, struct rt_addrinfo *info,
* the epoch end, as nexthop is not used
* and return.
*/
DPRINTF("link_nhop failed!");
char nhbuf[48];
FIB_NH_LOG(LOG_WARNING, nh, "failed to link %s",
nhop_print_buf(nh, nhbuf, sizeof(nhbuf)));
destroy_nhop(nh_priv);
return (ENOBUFS);
}
#if DEBUG_MAX_LEVEL >= LOG_DEBUG
char nhbuf[48];
FIB_NH_LOG(LOG_DEBUG, nh, "finalized: %s", nhop_print_buf(nh, nhbuf, sizeof(nhbuf)));
#endif
return (0);
}
static void
print_nhop_sa(char *buf, size_t buflen, const struct sockaddr *sa)
{
if (sa->sa_family == AF_INET) {
const struct sockaddr_in *sin4;
sin4 = (const struct sockaddr_in *)sa;
inet_ntop(AF_INET, &sin4->sin_addr, buf, buflen);
} else if (sa->sa_family == AF_INET6) {
const struct sockaddr_in6 *sin6;
sin6 = (const struct sockaddr_in6 *)sa;
inet_ntop(AF_INET6, &sin6->sin6_addr, buf, buflen);
} else if (sa->sa_family == AF_LINK) {
const struct sockaddr_dl *sdl;
sdl = (const struct sockaddr_dl *)sa;
snprintf(buf, buflen, "if#%d", sdl->sdl_index);
} else
snprintf(buf, buflen, "af:%d", sa->sa_family);
}
static void
print_nhop(const char *prefix, const struct nhop_object *nh)
{
char src_buf[INET6_ADDRSTRLEN], addr_buf[INET6_ADDRSTRLEN];
print_nhop_sa(src_buf, sizeof(src_buf), nh->nh_ifa->ifa_addr);
print_nhop_sa(addr_buf, sizeof(addr_buf), &nh->gw_sa);
DPRINTF("%s nhop priv %p: AF %d ifp %p %s addr %s src %p %s aifp %p %s mtu %d nh_flags %X",
prefix, nh->nh_priv, nh->nh_priv->nh_upper_family, nh->nh_ifp,
if_name(nh->nh_ifp), addr_buf, nh->nh_ifa, src_buf, nh->nh_aifp,
if_name(nh->nh_aifp), nh->nh_mtu, nh->nh_flags);
}
static void
destroy_nhop(struct nhop_priv *nh_priv)
{
@ -633,8 +607,6 @@ destroy_nhop(struct nhop_priv *nh_priv)
nh = nh_priv->nh;
print_nhop("DEL", nh);
if_rele(nh->nh_ifp);
if_rele(nh->nh_aifp);
ifa_free(nh->nh_ifa);
@ -682,6 +654,11 @@ nhop_free(struct nhop_object *nh)
if (!refcount_release(&nh_priv->nh_refcnt))
return;
#if DEBUG_MAX_LEVEL >= LOG_DEBUG
char nhbuf[48];
FIB_NH_LOG(LOG_DEBUG, nh, "deleting %s", nhop_print_buf(nh, nhbuf, sizeof(nhbuf)));
#endif
/*
* There are only 2 places, where nh_linked can be decreased:
* rib destroy (nhops_destroy_rib) and this function.
@ -706,7 +683,9 @@ nhop_free(struct nhop_object *nh)
ctl = nh_priv->nh_control;
if (unlink_nhop(ctl, nh_priv) == NULL) {
/* Do not try to reclaim */
DPRINTF("Failed to unlink nexhop %p", nh_priv);
char nhbuf[48];
FIB_NH_LOG(LOG_WARNING, nh, "failed to unlink %s",
nhop_print_buf(nh, nhbuf, sizeof(nhbuf)));
NET_EPOCH_EXIT(et);
return;
}
@ -844,6 +823,45 @@ nhops_update_ifmtu(struct rib_head *rh, struct ifnet *ifp, uint32_t mtu)
}
/*
* Prints nexthop @nh data in the provided @buf.
* Example: nh#33/inet/em0/192.168.0.1
*/
char *
nhop_print_buf(const struct nhop_object *nh, char *buf, size_t bufsize)
{
char abuf[INET6_ADDRSTRLEN];
struct nhop_priv *nh_priv = nh->nh_priv;
const char *upper_str = rib_print_family(nh->nh_priv->nh_upper_family);
switch (nh->gw_sa.sa_family) {
#ifdef INET
case AF_INET:
inet_ntop(AF_INET, &nh->gw4_sa.sin_addr, abuf, sizeof(abuf));
snprintf(buf, bufsize, "nh#%d/%s/%s/%s", nh_priv->nh_idx, upper_str,
if_name(nh->nh_ifp), abuf);
break;
#endif
#ifdef INET6
case AF_INET6:
inet_ntop(AF_INET6, &nh->gw6_sa.sin6_addr, abuf, sizeof(abuf));
snprintf(buf, bufsize, "nh#%d/%s/%s/%s", nh_priv->nh_idx, upper_str,
if_name(nh->nh_ifp), abuf);
break;
#endif
case AF_LINK:
snprintf(buf, bufsize, "nh#%d/%s/%s/resolve", nh_priv->nh_idx, upper_str,
if_name(nh->nh_ifp));
break;
default:
snprintf(buf, bufsize, "nh#%d/%s/%s/????", nh_priv->nh_idx, upper_str,
if_name(nh->nh_ifp));
break;
}
return (buf);
}
/*
* Dumps a single entry to sysctl buffer.
*
@ -866,8 +884,6 @@ dump_nhop_entry(struct rib_head *rh, struct nhop_object *nh, struct sysctl_req *
size_t addrs_len;
int error;
//DPRINTF("Dumping: head %p nh %p flags %X req %p\n", rh, nh, nh->nh_flags, w);
memset(&arpc, 0, sizeof(arpc));
arpc.rtm.rtm_msglen = sizeof(arpc);
@ -949,7 +965,10 @@ nhops_dump_sysctl(struct rib_head *rh, struct sysctl_req *w)
ctl = rh->nh_control;
NHOPS_RLOCK(ctl);
DPRINTF("NHDUMP: count=%u", ctl->nh_head.items_count);
#if DEBUG_MAX_LEVEL >= LOG_DEBUG
FIB_LOG(LOG_DEBUG, rh->rib_fibnum, rh->rib_family, "dump %u items",
ctl->nh_head.items_count);
#endif
CHT_SLIST_FOREACH(&ctl->nh_head, nhops, nh_priv) {
error = dump_nhop_entry(rh, nh_priv->nh, w);
if (error != 0) {

View File

@ -118,6 +118,9 @@ SYSCTL_UINT(_net_route, OID_AUTO, ipv6_nexthop, CTLFLAG_RW | CTLFLAG_VNET,
VNET_DEFINE_STATIC(uma_zone_t, rtzone);
#define V_rtzone VNET(rtzone)
/* Debug bits */
SYSCTL_NODE(_net_route, OID_AUTO, debug, CTLFLAG_RD | CTLFLAG_MPSAFE, 0, "");
void
vnet_rtzone_init()
{
@ -1430,6 +1433,20 @@ rib_flush_routes_family(int family)
}
}
const char *
rib_print_family(int family)
{
switch (family) {
case AF_INET:
return ("inet");
case AF_INET6:
return ("inet6");
case AF_LINK:
return ("link");
}
return ("unknown");
}
static void
rib_notify(struct rib_head *rnh, enum rib_subscription_type type,
struct rib_cmd_info *rc)

141
sys/net/route/route_debug.h Normal file
View File

@ -0,0 +1,141 @@
/*-
* Copyright (c) 2021
* Alexander V. Chernikov <melifaro@FreeBSD.org>
*
* Redistribution and use in source and binary forms, with or without
* modification, are permitted provided that the following conditions
* are met:
* 1. Redistributions of source code must retain the above copyright
* notice, this list of conditions and the following disclaimer.
* 2. Redistributions in binary form must reproduce the above copyright
* notice, this list of conditions and the following disclaimer in the
* documentation and/or other materials provided with the distribution.
* 3. Neither the name of the University nor the names of its contributors
* may be used to endorse or promote products derived from this software
* without specific prior written permission.
*
* THIS SOFTWARE IS PROVIDED BY THE REGENTS AND CONTRIBUTORS ``AS IS'' AND
* ANY EXPRESS OR IMPLIED WARRANTIES, INCLUDING, BUT NOT LIMITED TO, THE
* IMPLIED WARRANTIES OF MERCHANTABILITY AND FITNESS FOR A PARTICULAR PURPOSE
* ARE DISCLAIMED. IN NO EVENT SHALL THE REGENTS OR CONTRIBUTORS BE LIABLE
* FOR ANY DIRECT, INDIRECT, INCIDENTAL, SPECIAL, EXEMPLARY, OR CONSEQUENTIAL
* DAMAGES (INCLUDING, BUT NOT LIMITED TO, PROCUREMENT OF SUBSTITUTE GOODS
* OR SERVICES; LOSS OF USE, DATA, OR PROFITS; OR BUSINESS INTERRUPTION)
* HOWEVER CAUSED AND ON ANY THEORY OF LIABILITY, WHETHER IN CONTRACT, STRICT
* LIABILITY, OR TORT (INCLUDING NEGLIGENCE OR OTHERWISE) ARISING IN ANY WAY
* OUT OF THE USE OF THIS SOFTWARE, EVEN IF ADVISED OF THE POSSIBILITY OF
* SUCH DAMAGE.
*
* $FreeBSD$
*/
#ifndef _NET_ROUTE_DEBUG_H_
#define _NET_ROUTE_DEBUG_H_
#include <sys/sysctl.h>
#include <sys/syslog.h>
/* DEBUG logic */
#if defined(DEBUG_MOD_NAME) && defined(DEBUG_MAX_LEVEL)
#define DEBUG_VAR_NAME _DEBUG_VAR_NAME(DEBUG_MOD_NAME)
#define _DEBUG_VAR_NAME(a) _DEBUG_VAR_NAME_INDIRECT(a)
#define _DEBUG_VAR_NAME_INDIRECT(prefix) prefix##_debug_level
#define DEBUG_PREFIX_NAME _DEBUG_PREFIX_NAME(DEBUG_MOD_NAME)
#define _DEBUG_PREFIX_NAME(n) __DEBUG_PREFIX_NAME(n)
#define __DEBUG_PREFIX_NAME(n) #n
#define _DECLARE_DEBUG(_default_level) \
SYSCTL_DECL(_net_route_debug); \
static int DEBUG_VAR_NAME = _default_level; \
SYSCTL_INT(_net_route_debug, OID_AUTO, DEBUG_VAR_NAME, \
CTLFLAG_RW | CTLFLAG_RWTUN, \
&(DEBUG_VAR_NAME), 0, "debuglevel")
/* Additional tracing levels not defined by log.h */
#ifndef LOG_DEBUG2
#define LOG_DEBUG2 8
#endif
#ifndef LOG_DEBUG3
#define LOG_DEBUG3 9
#endif
#define _output printf
#define _DEBUG_PASS_MSG(_l) (DEBUG_VAR_NAME >= (_l))
/*
* Logging for events specific for particular family and fib
* Example: [nhop_neigh] inet.0 find_lle: nhop nh#4/inet/vtnet0/10.0.0.1: mapped to lle NULL
*/
#define FIB_LOG(_l, _fib, _fam, _fmt, ...) FIB_LOG_##_l(_l, _fib, _fam, _fmt, ## __VA_ARGS__)
#define _FIB_LOG(_l, _fib, _fam, _fmt, ...) if (_DEBUG_PASS_MSG(_l)) { \
_output("[" DEBUG_PREFIX_NAME "] %s.%u %s: " _fmt "\n", rib_print_family(_fam), _fib, __func__, ##__VA_ARGS__); \
}
/* Same as FIB_LOG, but uses nhop to get fib and family */
#define FIB_NH_LOG(_l, _nh, _fmt, ...) FIB_LOG_##_l(_l, nhop_get_fibnum(_nh), nhop_get_upper_family(_nh), _fmt, ## __VA_ARGS__)
/*
* Generic logging for routing subsystem
* Example: [nhop_neigh] nhops_update_neigh: L2 prepend update from lle/inet/valid/vtnet0/10.0.0.157
*/
#define RT_LOG(_l, _fmt, ...) RT_LOG_##_l(_l, _fmt, ## __VA_ARGS__)
#define _RT_LOG(_l, _fmt, ...) if (_DEBUG_PASS_MSG(_l)) { \
_output("[" DEBUG_PREFIX_NAME "] %s: " _fmt "\n", __func__, ##__VA_ARGS__); \
}
/*
* Wrapper logic to avoid compiling high levels of debugging messages for production systems.
*/
#if DEBUG_MAX_LEVEL>=LOG_DEBUG2
#define FIB_LOG_LOG_DEBUG3 _FIB_LOG
#define RT_LOG_LOG_DEBUG3 _RT_LOG
#else
#define FIB_LOG_LOG_DEBUG3(_l, _fib, _fam, _fmt, ...)
#define RT_LOG_LOG_DEBUG3(_l, _fmt, ...)
#endif
#if DEBUG_MAX_LEVEL>=LOG_DEBUG2
#define FIB_LOG_LOG_DEBUG2 _FIB_LOG
#define RT_LOG_LOG_DEBUG2 _RT_LOG
#else
#define FIB_LOG_LOG_DEBUG2(_l, _fib, _fam, _fmt, ...)
#define RT_LOG_LOG_DEBUG2(_l, _fmt, ...)
#endif
#if DEBUG_MAX_LEVEL>=LOG_DEBUG
#define FIB_LOG_LOG_DEBUG _FIB_LOG
#define RT_LOG_LOG_DEBUG _RT_LOG
#else
#define FIB_LOG_LOG_DEBUG(_l, _fib, _fam, _fmt, ...)
#define RT_LOG_LOG_DEBUG(_l, _fmt, ...)
#endif
#if DEBUG_MAX_LEVEL>=LOG_INFO
#define FIB_LOG_LOG_INFO _FIB_LOG
#define RT_LOG_LOG_INFO _RT_LOG
#else
#define FIB_LOG_LOG_INFO(_l, _fib, _fam, _fmt, ...)
#define RT_LOG_LOG_INFO(_l, _fmt, ...)
#endif
#define FIB_LOG_LOG_NOTICE _FIB_LOG
#define FIB_LOG_LOG_ERR _FIB_LOG
#define FIB_LOG_LOG_WARNING _FIB_LOG
#define RT_LOG_LOG_NOTICE _RT_LOG
#define RT_LOG_LOG_ERR _RT_LOG
#define RT_LOG_LOG_WARNING _RT_LOG
#endif
/* Helpers for fancy-printing various objects */
struct nhop_object;
struct llentry;
struct nhop_neigh;
char *nhop_print_buf(const struct nhop_object *nh, char *buf, size_t bufsize);
char *llentry_print_buf(const struct llentry *lle, struct ifnet *ifp, int family, char *buf,
size_t bufsize);
char *llentry_print_buf_lltable(const struct llentry *lle, char *buf, size_t bufsize);
char *neigh_print_buf(const struct nhop_neigh *nn, char *buf, size_t bufsize);
#endif