From nobody Fri Jan 13 21:24:39 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 4NtvZJ13nsz2qkmW; Fri, 13 Jan 2023 21:24:40 +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 4NtvZH6rJyz3ynP; Fri, 13 Jan 2023 21:24:39 +0000 (UTC) (envelope-from git@FreeBSD.org) DKIM-Signature: v=1; a=rsa-sha256; c=relaxed/relaxed; d=freebsd.org; s=dkim; t=1673645080; 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=dyNVBJZbyGPCC7QRL/IpZtOqvD67xq0qckX49ZZWE1E=; b=vxpcJCC1WQkZPYh/e4Du867x6bqtuGVi9qL0MpulWyua4pIl7t0J4RpUWtqybDnBMvDLB6 YBBqeUrZDeymmUfvzNxew+0ynMS6vRQVT1p01ZtmZJxAWUacFq6cF1goQc4oJhv1o50rxu 7A787hbvWniiOAQ5CVX6hHrQXTA4F/WraXuRR2q+mRKX5hhGzHpMbjCqppzpWgDVk1TkeW mEStu1nFNHho9f2jOaIvYgFiwRFnzxKv6ylxdhh+muzUxP7QGxHs4tAZBwMfUoKMAFnM8g koh7zjCUmgUKORigwWm622mKIuI63yit128hrRoL94nPgKJKoY6xZGC1jL79Zg== ARC-Message-Signature: i=1; a=rsa-sha256; c=relaxed/relaxed; d=freebsd.org; s=dkim; t=1673645080; 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=dyNVBJZbyGPCC7QRL/IpZtOqvD67xq0qckX49ZZWE1E=; b=nlt5UuTw3MQS4gAxyfXuRdxpncHjSzC+VMCA4j3Ff28Z9H/FtJ7gkFtToBf6309n5U8iRg wPh6YNLeI9uWfcYx8XR5yYm2OcimkGPcdN03COnsMENUDDkQJ2ug4VseTAKDeU2nIQZfLG kv1EFiXDpPTgvRXXKNblgiNhg2Q9VtmGhnR498AF7dVgvV4Ajvvhap6JutzG871MELIs1+ QrzmJZfSPnez8lzbdpfzXZMM3vWuwgQoGCYZRIWKMD4BsTTltb/SrHsBjtEYPMtUUCsQZA NXVv5zGBSl7Qiq+etuaScveoUJqZZWNVc9p3nURt8vtnWyLFjrd4yunU7+qZCQ== ARC-Authentication-Results: i=1; mx1.freebsd.org; none ARC-Seal: i=1; s=dkim; d=freebsd.org; t=1673645080; a=rsa-sha256; cv=none; b=YBChCYvmTdwc18Z4pi1qE5sECESudbmhfYOAmPJX+4hTU0CslTwcay9yQ8XGb0CgKLa1EW PiXu0HSof/nW0wNvgm5adn6tILcjT1S+3Xg9VRKZ8vztFk5tefmfpcshK0q9uKgD1TBkP9 sYUq20SFTPgm51AjzR8PXMW/uym6vtuxmjGB2z7r09zjLeIJZ8qr7BGaAbEvmhuRUk93+c Phkp6KoSFqX8oNhe18V/vHari9qyZ9/V29yhG3hNfVzx4x2dySKS6phwM7v5SncSQ69K0J Hehn5qWuPJ3Ysecu8uvpnKbVAt7rejijwicEVZHyAUW+beXv2xWI2ZCawFJoDQ== 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 4NtvZH5fF8zMrR; Fri, 13 Jan 2023 21:24:39 +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 30DLOdIt040316; Fri, 13 Jan 2023 21:24:39 GMT (envelope-from git@gitrepo.freebsd.org) Received: (from git@localhost) by gitrepo.freebsd.org (8.16.1/8.16.1/Submit) id 30DLOdjc040315; Fri, 13 Jan 2023 21:24:39 GMT (envelope-from git) Date: Fri, 13 Jan 2023 21:24:39 GMT Message-Id: <202301132124.30DLOdjc040315@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: cda085d1ccef - stable/13 - routing: improve debug logging 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: cda085d1ccefb338e3c828fe9e08d13aee9a40ae Auto-Submitted: auto-generated X-ThisMailContainsUnwantedMimeParts: N The branch stable/13 has been updated by melifaro: URL: https://cgit.FreeBSD.org/src/commit/?id=cda085d1ccefb338e3c828fe9e08d13aee9a40ae commit cda085d1ccefb338e3c828fe9e08d13aee9a40ae Author: Alexander V. Chernikov AuthorDate: 2022-06-22 15:04:17 +0000 Commit: Alexander V. Chernikov CommitDate: 2023-01-13 21:18:25 +0000 routing: improve debug logging Use standard logging (FIB_XX_LOG) across nhg code instead of using old-style DPRINTFs. Add debug object printer for nhgs (`nhgrp_print_buf`). Example: ``` Jun 19 20:17:09 devel2 kernel: [nhgrp] inet.0 nhgrp_ctl_alloc_default: multipath init done Jun 19 20:17:09 devel2 kernel: [nhg_ctl] inet.0 alloc_nhgrp: num_nhops: 2, compiled_nhop: 2 Jun 19 20:17:26 devel2 kernel: [nhg_ctl] inet.0 alloc_nhgrp: num_nhops: 3, compiled_nhop: 3 Jun 19 20:17:26 devel2 kernel: [nhg_ctl] inet.0 destroy_nhgrp: destroying nhg#0/sz=2:[#6:1,#5:1] ``` Differential Revision: https://reviews.freebsd.org/D35525 MFC after: 2 weeks (cherry picked from commit 5d6894bd66e15bb7cf7c6ee2337ce86dfd0b2f7e) --- sys/net/route/nhgrp.c | 23 +++++++++++----- sys/net/route/nhgrp_ctl.c | 66 ++++++++++++++++++++++++++++++++++++++------- sys/net/route/nhop_ctl.c | 19 ++++++++++--- sys/net/route/route_debug.h | 8 +++++- 4 files changed, 94 insertions(+), 22 deletions(-) diff --git a/sys/net/route/nhgrp.c b/sys/net/route/nhgrp.c index 07abdf480101..d93fd5053c30 100644 --- a/sys/net/route/nhgrp.c +++ b/sys/net/route/nhgrp.c @@ -60,6 +60,11 @@ #include #include +#define DEBUG_MOD_NAME nhgrp +#define DEBUG_MAX_LEVEL LOG_DEBUG +#include +_DECLARE_DEBUG(LOG_INFO); + /* * This file contains data structures management logic for the nexthop * groups ("nhgrp") route subsystem. @@ -163,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); - DPRINTF("Unable to allocate mpath index"); + FIB_RH_LOG(LOG_INFO, ctl->ctl_rh, "Unable to allocate nhg index"); consider_resize(ctl, new_num_buckets, new_num_items); return (0); } @@ -190,7 +195,7 @@ unlink_nhgrp(struct nh_control *ctl, struct nhgrp_priv *key) CHT_SLIST_REMOVE(&ctl->gr_head, mpath, key, nhg_priv_ret); if (nhg_priv_ret == NULL) { - DPRINTF("Unable to find nhop group!"); + FIB_RH_LOG(LOG_DEBUG, ctl->ctl_rh, "Unable to find nhg"); NHOPS_WUNLOCK(ctl); return (NULL); } @@ -233,7 +238,8 @@ consider_resize(struct nh_control *ctl, uint32_t new_gr_bucket, uint32_t new_idx return; } - DPRINTF("mp: going to resize: gr:[ptr:%p sz:%u] idx:[ptr:%p sz:%u]", + FIB_RH_LOG(LOG_DEBUG, ctl->ctl_rh, + "going to resize nhg hash: [ptr:%p sz:%u] idx:[ptr:%p sz:%u]", gr_ptr, new_gr_bucket, gr_idx_ptr, new_idx_items); old_idx_ptr = NULL; @@ -271,7 +277,7 @@ nhgrp_ctl_alloc_default(struct nh_control *ctl, int malloc_flags) cht_ptr = malloc(alloc_size, M_NHOP, malloc_flags); if (cht_ptr == NULL) { - DPRINTF("mpath init failed"); + FIB_RH_LOG(LOG_WARNING, ctl->ctl_rh, "multipath init failed"); return (false); } @@ -287,8 +293,7 @@ nhgrp_ctl_alloc_default(struct nh_control *ctl, int malloc_flags) free(cht_ptr, M_NHOP); } - DPRINTF("mpath init done for fib/af %d/%d", ctl->rh->rib_fibnum, - ctl->rh->rib_family); + FIB_RH_LOG(LOG_DEBUG, ctl->ctl_rh, "multipath init done"); return (true); } @@ -320,7 +325,11 @@ nhgrp_ctl_unlink_all(struct nh_control *ctl) NHOPS_WLOCK_ASSERT(ctl); CHT_SLIST_FOREACH(&ctl->gr_head, mpath, nhg_priv) { - DPRINTF("Marking nhgrp %u unlinked", nhg_priv->nhg_idx); +#if DEBUG_MAX_LEVEL >= LOG_DEBUG + char nhgbuf[NHOP_PRINT_BUFSIZE]; + FIB_RH_LOG(LOG_DEBUG, ctl->ctl_rh, "marking %s unlinked", + nhgrp_print_buf(nhg_priv->nhg, nhgbuf, sizeof(nhgbuf))); +#endif refcount_release(&nhg_priv->nhg_linked); } CHT_SLIST_FOREACH_END; } diff --git a/sys/net/route/nhgrp_ctl.c b/sys/net/route/nhgrp_ctl.c index 6a3f853e073d..91ce5b3f4174 100644 --- a/sys/net/route/nhgrp_ctl.c +++ b/sys/net/route/nhgrp_ctl.c @@ -58,6 +58,11 @@ #include #include +#define DEBUG_MOD_NAME nhgrp_ctl +#define DEBUG_MAX_LEVEL LOG_DEBUG +#include +_DECLARE_DEBUG(LOG_INFO); + /* * This file contains the supporting functions for creating multipath groups * and compiling their dataplane parts. @@ -222,7 +227,8 @@ compile_nhgrp(struct nhgrp_priv *dst_priv, const struct weightened_nhop *x, for (i = 0; i < dst_priv->nhg_nh_count; i++) remaining_sum += x[i].weight; remaining_slots = num_slots; - DPRINTF("O: %u/%u", (uint32_t)remaining_sum, remaining_slots); + FIB_NH_LOG(LOG_DEBUG3, x[0].nh, "sum: %lu, slots: %d", + remaining_sum, remaining_slots); for (i = 0; i < dst_priv->nhg_nh_count; i++) { /* Calculate number of slots for the current nexthop */ if (remaining_sum > 0) { @@ -234,9 +240,9 @@ compile_nhgrp(struct nhgrp_priv *dst_priv, const struct weightened_nhop *x, remaining_sum -= x[i].weight; remaining_slots -= nh_slots; - DPRINTF(" OO[%d]: %u/%u curr=%d slot_idx=%d", i, - (uint32_t)remaining_sum, remaining_slots, - (int)nh_slots, slot_idx); + FIB_NH_LOG(LOG_DEBUG3, x[0].nh, + " rem_sum: %lu, rem_slots: %d nh_slots: %d, slot_idx: %d", + remaining_sum, remaining_slots, (int)nh_slots, slot_idx); KASSERT((slot_idx + nh_slots <= num_slots), ("index overflow during nhg compilation")); @@ -267,12 +273,14 @@ alloc_nhgrp(struct weightened_nhop *wn, int num_nhops) size_t sz = get_nhgrp_alloc_size(nhgrp_size, num_nhops); nhg = malloc(sz, M_NHOP, M_NOWAIT | M_ZERO); if (nhg == NULL) { + FIB_NH_LOG(LOG_INFO, wn[0].nh, + "unable to allocate group with num_nhops %d (compiled %u)", + num_nhops, nhgrp_size); return (NULL); } /* Has to be the first to make NHGRP_PRIV() work */ nhg->nhg_size = nhgrp_size; - DPRINTF("new mpath group: num_nhops: %u", (uint32_t)nhgrp_size); nhg->nhg_flags = MPF_MULTIPATH; nhg_priv = NHGRP_PRIV(nhg); @@ -286,6 +294,9 @@ alloc_nhgrp(struct weightened_nhop *wn, int num_nhops) memcpy(&nhg_priv->nhg_nh_weights[0], wn, num_nhops * sizeof(struct weightened_nhop)); + FIB_NH_LOG(LOG_DEBUG, wn[0].nh, "num_nhops: %d, compiled_nhop: %u", + num_nhops, nhgrp_size); + compile_nhgrp(nhg_priv, wn, nhg->nhg_size); return (nhg_priv); @@ -345,7 +356,8 @@ nhgrp_free(struct nhgrp_object *nhg) ctl = nhg_priv->nh_control; if (unlink_nhgrp(ctl, nhg_priv) == NULL) { /* Do not try to reclaim */ - DPRINTF("Failed to unlink nexhop group %p", nhg_priv); + RT_LOG(LOG_INFO, "Failed to unlink nexhop group %p", + nhg_priv); NET_EPOCH_EXIT(et); return; } @@ -371,13 +383,16 @@ destroy_nhgrp(struct nhgrp_priv *nhg_priv) { KASSERT((nhg_priv->nhg_refcount == 0), ("nhg_refcount != 0")); - - DPRINTF("DEL MPATH %p", nhg_priv); - KASSERT((nhg_priv->nhg_idx == 0), ("gr_idx != 0")); - free_nhgrp_nhops(nhg_priv); +#if DEBUG_MAX_LEVEL >= LOG_DEBUG + char nhgbuf[NHOP_PRINT_BUFSIZE]; + FIB_NH_LOG(LOG_DEBUG, nhg_priv->nhg_nh_weights[0].nh, + "destroying %s", nhgrp_print_buf(nhg_priv->nhg, + nhgbuf, sizeof(nhgbuf))); +#endif + free_nhgrp_nhops(nhg_priv); destroy_nhgrp_int(nhg_priv); } @@ -695,6 +710,37 @@ nhgrp_get_nhops(struct nhgrp_object *nhg, uint32_t *pnum_nhops) return (nhg_priv->nhg_nh_weights); } +/* + * Prints nexhop group @nhg data in the provided @buf. + * Example: nhg#33/sz=3:[#1:100,#2:100,#3:100] + * Example: nhg#33/sz=5:[#1:100,#2:100,..] + */ +char * +nhgrp_print_buf(const struct nhgrp_object *nhg, char *buf, size_t bufsize) +{ + const struct nhgrp_priv *nhg_priv = NHGRP_PRIV_CONST(nhg); + + int off = snprintf(buf, bufsize, "nhg#%u/sz=%u:[", nhg_priv->nhg_idx, + nhg_priv->nhg_nh_count); + + for (int i = 0; i < nhg_priv->nhg_nh_count; i++) { + const struct weightened_nhop *wn = &nhg_priv->nhg_nh_weights[i]; + int len = snprintf(&buf[off], bufsize - off, "#%u:%u,", + wn->nh->nh_priv->nh_idx, wn->weight); + if (len + off + 3 >= bufsize) { + int len = snprintf(&buf[off], bufsize - off, "..."); + off += len; + break; + } + off += len; + } + if (off > 0) + off--; // remove last "," + if (off + 1 < bufsize) + snprintf(&buf[off], bufsize - off, "]"); + return buf; +} + __noinline static int dump_nhgrp_entry(struct rib_head *rh, const struct nhgrp_priv *nhg_priv, char *buffer, size_t buffer_size, struct sysctl_req *w) diff --git a/sys/net/route/nhop_ctl.c b/sys/net/route/nhop_ctl.c index b0f31f400bd3..eadb053c0f42 100644 --- a/sys/net/route/nhop_ctl.c +++ b/sys/net/route/nhop_ctl.c @@ -584,7 +584,7 @@ finalize_nhop(struct nh_control *ctl, struct rt_addrinfo *info, * the epoch end, as nexthop is not used * and return. */ - char nhbuf[48]; + char nhbuf[NHOP_PRINT_BUFSIZE]; FIB_NH_LOG(LOG_WARNING, nh, "failed to link %s", nhop_print_buf(nh, nhbuf, sizeof(nhbuf))); destroy_nhop(nh_priv); @@ -593,7 +593,7 @@ finalize_nhop(struct nh_control *ctl, struct rt_addrinfo *info, } #if DEBUG_MAX_LEVEL >= LOG_DEBUG - char nhbuf[48]; + char nhbuf[NHOP_PRINT_BUFSIZE]; FIB_NH_LOG(LOG_DEBUG, nh, "finalized: %s", nhop_print_buf(nh, nhbuf, sizeof(nhbuf))); #endif @@ -655,7 +655,7 @@ nhop_free(struct nhop_object *nh) return; #if DEBUG_MAX_LEVEL >= LOG_DEBUG - char nhbuf[48]; + char nhbuf[NHOP_PRINT_BUFSIZE]; FIB_NH_LOG(LOG_DEBUG, nh, "deleting %s", nhop_print_buf(nh, nhbuf, sizeof(nhbuf))); #endif @@ -683,7 +683,7 @@ nhop_free(struct nhop_object *nh) ctl = nh_priv->nh_control; if (unlink_nhop(ctl, nh_priv) == NULL) { /* Do not try to reclaim */ - char nhbuf[48]; + char nhbuf[NHOP_PRINT_BUFSIZE]; FIB_NH_LOG(LOG_WARNING, nh, "failed to unlink %s", nhop_print_buf(nh, nhbuf, sizeof(nhbuf))); NET_EPOCH_EXIT(et); @@ -864,6 +864,17 @@ nhop_print_buf(const struct nhop_object *nh, char *buf, size_t bufsize) return (buf); } +char * +nhop_print_buf_any(const struct nhop_object *nh, char *buf, size_t bufsize) +{ +#ifdef ROUTE_MPATH + if (NH_IS_NHGRP(nh)) + return (nhgrp_print_buf((const struct nhgrp_object *)nh, buf, bufsize)); + else +#endif + return (nhop_print_buf(nh, buf, bufsize)); +} + /* * Dumps a single entry to sysctl buffer. * diff --git a/sys/net/route/route_debug.h b/sys/net/route/route_debug.h index b0741f3409d4..7bc98c43c0dc 100644 --- a/sys/net/route/route_debug.h +++ b/sys/net/route/route_debug.h @@ -76,6 +76,8 @@ /* 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__) +/* Same as FIB_LOG, but uses rib_head to get fib and family */ +#define FIB_RH_LOG(_l, _rh, _fmt, ...) FIB_LOG_##_l(_l, (_rh)->rib_fibnum, (_rh)->rib_family, _fmt, ## __VA_ARGS__) /* * Generic logging for routing subsystem @@ -90,7 +92,7 @@ /* * Wrapper logic to avoid compiling high levels of debugging messages for production systems. */ -#if DEBUG_MAX_LEVEL>=LOG_DEBUG2 +#if DEBUG_MAX_LEVEL>=LOG_DEBUG3 #define FIB_LOG_LOG_DEBUG3 _FIB_LOG #define RT_LOG_LOG_DEBUG3 _RT_LOG #else @@ -129,10 +131,14 @@ /* Helpers for fancy-printing various objects */ struct nhop_object; +struct nhgrp_object; struct llentry; struct nhop_neigh; +#define NHOP_PRINT_BUFSIZE 48 char *nhop_print_buf(const struct nhop_object *nh, char *buf, size_t bufsize); +char *nhop_print_buf_any(const struct nhop_object *nh, char *buf, size_t bufsize); +char *nhgrp_print_buf(const struct nhgrp_object *nhg, 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);