From mboxrd@z Thu Jan 1 00:00:00 1970 Authentication-Results: passt.top; dmarc=none (p=none dis=none) header.from=gibson.dropbear.id.au Authentication-Results: passt.top; dkim=pass (2048-bit key; secure) header.d=gibson.dropbear.id.au header.i=@gibson.dropbear.id.au header.a=rsa-sha256 header.s=202606 header.b=UCK47YD/; dkim-atps=neutral Received: from mail.ozlabs.org (mail.ozlabs.org [IPv6:2404:9400:2221:ea00::3]) by passt.top (Postfix) with ESMTPS id DAF2F5A0262 for ; Tue, 09 Jun 2026 04:32:31 +0200 (CEST) DKIM-Signature: v=1; a=rsa-sha256; c=relaxed/relaxed; d=gibson.dropbear.id.au; s=202606; t=1780972349; bh=3nWaHYsXrxfYiPnJ2c5cydv8vbQ70J+/4ABCPERz/Bw=; h=From:To:Cc:Subject:Date:In-Reply-To:References:From; b=UCK47YD/mR5eG2ZeQV+oOWnspuMWUytEWFSP8F3YCyXUQomuuJCmPauyv4rH7h7nz DHQ39UGu/Nwwi34luMb9fWfawnEhQV42VBwAHMv1rTLEu8xSIQF3jXWPNiN4m16d3F b/oA3P/UQker+5NKB52C8juq9Ij4TeR+ExnkVqWHvPxnf5lng1TGjFfo+nbIG4wm2A lhYACC/9xA8VMeZR9f2NHmFS4VtvWuRwsvaUayZngv6oJKt5jPevgqky5m90g8dwLF 9M/BrTRDxejjZHzKEG40jC8uAPfBnlwASOcLLOtkKEY2aBHLbumojfM1r3107YSbyf lTlMbN3GhGtDA== Received: by gandalf.ozlabs.org (Postfix, from userid 1007) id 4gZCcF0qnDz4wSK; Tue, 09 Jun 2026 12:32:29 +1000 (AEST) From: David Gibson To: passt-dev@passt.top, Stefano Brivio Subject: [PATCH 1/4] flow: Regularise flow specific logging helpers Date: Tue, 9 Jun 2026 12:32:23 +1000 Message-ID: <20260609023226.86058-2-david@gibson.dropbear.id.au> X-Mailer: git-send-email 2.54.0 In-Reply-To: <20260609023226.86058-1-david@gibson.dropbear.id.au> References: <20260609023226.86058-1-david@gibson.dropbear.id.au> MIME-Version: 1.0 Content-Transfer-Encoding: 8bit Message-ID-Hash: YEZUVCL532U2IJENSRIP2PYWMV3ZNTJG X-Message-ID-Hash: YEZUVCL532U2IJENSRIP2PYWMV3ZNTJG X-MailFrom: dgibson@gandalf.ozlabs.org X-Mailman-Rule-Misses: dmarc-mitigation; no-senders; approved; emergency; loop; banned-address; member-moderation; nonmember-moderation; administrivia; implicit-dest; max-recipients; max-size; news-moderation; no-subject; digests; suspicious-header CC: David Gibson X-Mailman-Version: 3.3.8 Precedence: list List-Id: Development discussion and patches for passt Archived-At: Archived-At: List-Archive: List-Archive: List-Help: List-Owner: List-Post: List-Subscribe: List-Unsubscribe: flow.h has a collection of logging helpers that automatically include information about a specific flow. Which variants are present are a bit ad-hoc, based on what we happened to want use (e.g. there are no LOG_WARNING level versions, at present). There's also a rather awkward and only occasionally used flow_log_details_() helper to print additional log messages with more details of the flow (basically its addresses). It's particularly awkward to try to combine that with ratelimiting. Re-organise this to be based around a flow_log__() internal helper, which has bool parameters to include strerror() / perror information and/or the extra details. Add wrapper macros for all combinations of perror, ratelimiting and DEBUG/WARNING/ERR priorities. Be a little more consistent about parameter order between the various functions / macros / wrappers while we're at it. Signed-off-by: David Gibson --- flow.c | 89 ++++++++++++++++++++++++++++------------------------------ flow.h | 70 +++++++++++++++++++++++---------------------- tcp.c | 4 +-- udp.c | 6 ++-- 4 files changed, 85 insertions(+), 84 deletions(-) diff --git a/flow.c b/flow.c index 565ed2b2..6cf3905a 100644 --- a/flow.c +++ b/flow.c @@ -270,17 +270,20 @@ int flowside_connect(const struct ctx *c, int s, return connect(s, &sa.sa, socklen_inany(&sa)); } -/** flow_log_ - Log flow-related message +/** flow_log__ - Log flow-related message, internal helper * @f: flow the message is related to - * @newline: Append newline at the end of the message, if missing * @pri: Log priority + * @perror: Append strerror(errno) output + * @details: Add lines with flow addresses + * @state: State to display details for (used during state changes) * @fmt: Format string * @...: printf-arguments */ -void flow_log_(const struct flow_common *f, bool newline, int pri, - const char *fmt, ...) +void flow_log__(const struct flow_common *f, int pri, bool perror, bool details, + enum flow_state state, const char *fmt, ...) { const char *type_or_state; + int errno_ = errno; char msg[BUFSIZ]; va_list args; @@ -294,45 +297,41 @@ void flow_log_(const struct flow_common *f, bool newline, int pri, else type_or_state = FLOW_TYPE(f); - logmsg(newline, false, pri, + logmsg(!perror, false, pri, "Flow %u (%s): %s", flow_idx(f), type_or_state, msg); -} -/** flow_log_details_() - Log the details of a flow - * @f: flow to log - * @pri: Log priority - * @state: State to log details according to - * - * Logs the details of the flow: endpoints, interfaces, type etc. - */ -void flow_log_details_(const struct flow_common *f, int pri, - enum flow_state state) -{ - char estr0[INANY_ADDRSTRLEN], fstr0[INANY_ADDRSTRLEN]; - char estr1[INANY_ADDRSTRLEN], fstr1[INANY_ADDRSTRLEN]; - const struct flowside *ini = &f->side[INISIDE]; - const struct flowside *tgt = &f->side[TGTSIDE]; - - if (state >= FLOW_STATE_TGT) - flow_log_(f, true, pri, - "%s [%s]:%hu -> [%s]:%hu => %s [%s]:%hu -> [%s]:%hu", - pif_name(f->pif[INISIDE]), - inany_ntop(&ini->eaddr, estr0, sizeof(estr0)), - ini->eport, - inany_ntop(&ini->oaddr, fstr0, sizeof(fstr0)), - ini->oport, - pif_name(f->pif[TGTSIDE]), - inany_ntop(&tgt->oaddr, fstr1, sizeof(fstr1)), - tgt->oport, - inany_ntop(&tgt->eaddr, estr1, sizeof(estr1)), - tgt->eport); - else if (state >= FLOW_STATE_INI) - flow_log_(f, true, pri, "%s [%s]:%hu -> [%s]:%hu => ?", - pif_name(f->pif[INISIDE]), - inany_ntop(&ini->eaddr, estr0, sizeof(estr0)), - ini->eport, - inany_ntop(&ini->oaddr, fstr0, sizeof(fstr0)), - ini->oport); + if (perror) + logmsg(true, true, pri, ": %s", strerror_(errno_)); + + if (details) { + char estr0[INANY_ADDRSTRLEN], fstr0[INANY_ADDRSTRLEN]; + char estr1[INANY_ADDRSTRLEN], fstr1[INANY_ADDRSTRLEN]; + const struct flowside *ini = &f->side[INISIDE]; + const struct flowside *tgt = &f->side[TGTSIDE]; + + if (state >= FLOW_STATE_TGT) { + flow_log__(f, pri, false, false, state, +"%s [%s]:%hu -> [%s]:%hu => %s [%s]:%hu -> [%s]:%hu", + pif_name(f->pif[INISIDE]), + inany_ntop(&ini->eaddr, estr0, sizeof(estr0)), + ini->eport, + inany_ntop(&ini->oaddr, fstr0, sizeof(fstr0)), + ini->oport, + pif_name(f->pif[TGTSIDE]), + inany_ntop(&tgt->oaddr, fstr1, sizeof(fstr1)), + tgt->oport, + inany_ntop(&tgt->eaddr, estr1, sizeof(estr1)), + tgt->eport); + } else if (state >= FLOW_STATE_INI) { + flow_log__(f, pri, false, false, state, + "%s [%s]:%hu -> [%s]:%hu => ?", + pif_name(f->pif[INISIDE]), + inany_ntop(&ini->eaddr, estr0, sizeof(estr0)), + ini->eport, + inany_ntop(&ini->oaddr, fstr0, sizeof(fstr0)), + ini->oport); + } + } } /** @@ -348,10 +347,9 @@ static void flow_set_state(struct flow_common *f, enum flow_state state) assert(oldstate < FLOW_NUM_STATES); f->state = state; - flow_log_(f, true, LOG_DEBUG, "%s -> %s", flow_state_str[oldstate], + flow_log__(f, LOG_DEBUG, false, true, MAX(state, oldstate), + "%s -> %s", flow_state_str[oldstate], FLOW_STATE(f)); - - flow_log_details_(f, LOG_DEBUG, MAX(state, oldstate)); } /** @@ -552,8 +550,7 @@ norule: /* This shouldn't happen, because if there's no rule for it we should * have no listening socket that would let us get here */ - flow_dbg(flow, "Missing forward rule"); - flow_log_details_(f, LOG_DEBUG, f->state); + flow_log(flow, LOG_DEBUG, false, true, "Missing forward rule"); nofwd: flow_err(flow, "No rules to forward %s %s [%s]:%hu -> [%s]:%hu", diff --git a/flow.h b/flow.h index 6c6a9260..d168a35a 100644 --- a/flow.h +++ b/flow.h @@ -280,42 +280,46 @@ int flow_migrate_source(struct ctx *c, const struct migrate_stage *stage, int flow_migrate_target(struct ctx *c, const struct migrate_stage *stage, int fd); -void flow_log_(const struct flow_common *f, bool newline, int pri, - const char *fmt, ...) - __attribute__((format(printf, 4, 5))); - -#define flow_log(f_, pri, ...) flow_log_(&(f_)->f, true, (pri), __VA_ARGS__) -#define flow_dbg(f, ...) flow_log((f), LOG_DEBUG, __VA_ARGS__) -#define flow_err(f, ...) flow_log((f), LOG_ERR, __VA_ARGS__) - -#define flow_trace(f, ...) \ +void flow_log__(const struct flow_common *f, int pri, bool perror, bool details, + enum flow_state state, const char *fmt, ...); + +#define flow_log_(f_, pri_, perror_, details_, ...) \ + flow_log__((f_), (pri_), (perror_), (details_), (f_)->state, \ + __VA_ARGS__) + +#define flow_log(flow_, pri_, perror_, details_, ...) \ + flow_log_(&(flow_)->f, (pri_), (perror_), (details_), __VA_ARGS__) + +#define flow_dbg(flow_, ...) \ + flow_log((flow_), LOG_DEBUG, false, false, __VA_ARGS__) +#define flow_warn(flow_, ...) \ + flow_log((flow_), LOG_WARNING, false, false, __VA_ARGS__) +#define flow_err(flow_, ...) \ + flow_log((flow_), LOG_ERR, false, false, __VA_ARGS__) +#define flow_trace(flow_, ...) \ do { \ if (log_trace) \ - flow_dbg((f), __VA_ARGS__); \ - } while (0) - -#define flow_log_perror_(f, pri, ...) \ - do { \ - int errno_ = errno; \ - flow_log_((f), false, (pri), __VA_ARGS__); \ - logmsg(true, true, (pri), ": %s", strerror_(errno_)); \ + flow_dbg((flow_), __VA_ARGS__); \ } while (0) -#define flow_dbg_perror(f_, ...) flow_log_perror_(&(f_)->f, LOG_DEBUG, __VA_ARGS__) -#define flow_perror(f_, ...) flow_log_perror_(&(f_)->f, LOG_ERR, __VA_ARGS__) - -void flow_log_details_(const struct flow_common *f, int pri, - enum flow_state state); -#define flow_log_details(f_, pri) \ - flow_log_details_(&((f_)->f), (pri), (f_)->f.state) -#define flow_dbg_details(f_) flow_log_details((f_), LOG_DEBUG) -#define flow_err_details(f_) flow_log_details((f_), LOG_ERR) - -#define flow_dbg_ratelimit(f, now, ...) \ - logmsg_ratelimit(flow_dbg, debug, now, f, __VA_ARGS__) -#define flow_err_ratelimit(f, now, ...) \ - logmsg_ratelimit(flow_err, err, now, f, __VA_ARGS__) -#define flow_perror_ratelimit(f, now, ...) \ - logmsg_ratelimit(flow_perror, err, now, f, __VA_ARGS__) +#define flow_dbg_perror(flow_, ...) \ + flow_log((flow_), LOG_DEBUG, true, false, __VA_ARGS__) +#define flow_warn_perror(flow_, ...) \ + flow_log((flow_), LOG_WARNING, true, false, __VA_ARGS__) +#define flow_perror(flow_, ...) \ + flow_log((flow_), LOG_ERR, true, false, __VA_ARGS__) + +#define flow_dbg_ratelimit(flow_, now_, ...) \ + logmsg_ratelimit(flow_dbg, debug, (now_), (flow_), __VA_ARGS__) +#define flow_dbg_perror_ratelimit(flow_, now_, ...) \ + logmsg_ratelimit(flow_dbg_perror, debug, (now_), (flow_), __VA_ARGS__) +#define flow_warn_ratelimit(flow_, now_, ...) \ + logmsg_ratelimit(flow_warn, warn, (now_), (flow_), __VA_ARGS__) +#define flow_warn_perror_ratelimit(flow_, now_, ...) \ + logmsg_ratelimit(flow_warn_perror, warn, (now_), (flow_), __VA_ARGS__) +#define flow_err_ratelimit(flow_, now_, ...) \ + logmsg_ratelimit(flow_err, err, (now_), (flow_), __VA_ARGS__) +#define flow_perror_ratelimit(flow_, now_, ...) \ + logmsg_ratelimit(flow_perror, err, (now_), (flow_), __VA_ARGS__) #endif /* FLOW_H */ diff --git a/tcp.c b/tcp.c index c4000754..6fba865f 100644 --- a/tcp.c +++ b/tcp.c @@ -1404,8 +1404,8 @@ void tcp_linger0_(const struct flow_common *f, int s) */ if (setsockopt(s, SOL_SOCKET, SO_LINGER, &linger0, sizeof(linger0)) < 0) { - flow_log_perror_(f, LOG_DEBUG, - "SO_LINGER failed, may not send RST to peer"); + flow_log_(f, LOG_DEBUG, true, false, + "SO_LINGER failed, may not send RST to peer"); } } diff --git a/udp.c b/udp.c index c28d6ee2..f29ca3da 100644 --- a/udp.c +++ b/udp.c @@ -943,7 +943,8 @@ void udp_sock_handler(const struct ctx *c, union epoll_ref ref, if (events & EPOLLERR) { if (udp_sock_errs(c, ref.fd, ref.flowside, PIF_NONE, 0) < 0) { - flow_err(uflow, "Unrecoverable error on flow socket"); + flow_log(uflow, LOG_ERR, false, true, + "Unrecoverable error on flow socket"); goto fail; } } @@ -974,7 +975,7 @@ void udp_sock_handler(const struct ctx *c, union epoll_ref ref, udp_buf_sock_to_tap(c, s, n, tosidx); } } else { - flow_err(uflow, + flow_log(uflow, LOG_ERR, false, true, "No support for forwarding UDP from %s to %s", pif_name(pif_at_sidx(ref.flowside)), pif_name(topif)); @@ -984,7 +985,6 @@ void udp_sock_handler(const struct ctx *c, union epoll_ref ref, return; fail: - flow_err_details(uflow); udp_flow_close(c, uflow); } -- 2.54.0