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=nHlrhjr9; dkim-atps=neutral Received: from mail.ozlabs.org (gandalf.ozlabs.org [150.107.74.76]) by passt.top (Postfix) with ESMTPS id 4DC035A0271 for ; Wed, 17 Jun 2026 05:11:28 +0200 (CEST) DKIM-Signature: v=1; a=rsa-sha256; c=relaxed/relaxed; d=gibson.dropbear.id.au; s=202606; t=1781665884; bh=mF+bzP3pceMBs+J/iUiD81DCNyv4Am/1nSOr0wPva5Y=; h=From:To:Cc:Subject:Date:In-Reply-To:References:From; b=nHlrhjr9EF4E6H7NnkFapRkK3ESHdIbOKvwKD0nQLtoWDE34ztTXFmRqNq4iRZbvM G0CZy7CkaJdZr2ZGLxDL52DQ9dINmdtjule6ONzhHME9tI0y0uRXUiLEoCIEFkypO2 IKhkJ+otxFxkgWHYpk6jv0RJEhxgYq8cUG19AedS9uXVeYtNg3uGT3A242SYVNy5dC ueBVIhvWrm8mcwKhGTNbwsEQ8nKUdYn55FbBEYjSMfn/5mzU2FwF5Q31DaAU4cVpxQ 7Oa4qQiRpbq9u46UfembyZiXS9lAT4ejzNX9pmR6H/T9O8BCGXlv+QwXcKiHChbvoO zkclqMT3FEWMw== Received: by gandalf.ozlabs.org (Postfix, from userid 1007) id 4gg85S70SXz58nx; Wed, 17 Jun 2026 13:11:24 +1000 (AEST) From: David Gibson To: passt-dev@passt.top, Stefano Brivio Subject: [PATCH v2 1/6] flow: Regularise flow specific logging helpers Date: Wed, 17 Jun 2026 13:11:17 +1000 Message-ID: <20260617031122.2086827-2-david@gibson.dropbear.id.au> X-Mailer: git-send-email 2.54.0 In-Reply-To: <20260617031122.2086827-1-david@gibson.dropbear.id.au> References: <20260617031122.2086827-1-david@gibson.dropbear.id.au> MIME-Version: 1.0 Content-Transfer-Encoding: 8bit Message-ID-Hash: YZL354LMESBGIZ632PC4Z4Z2BD5CWCRG X-Message-ID-Hash: YZL354LMESBGIZ632PC4Z4Z2BD5CWCRG 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 7a5c81c2..e71f3de7 100644 --- a/flow.c +++ b/flow.c @@ -269,17 +269,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; @@ -293,45 +296,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); + } + } } /** @@ -347,10 +346,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)); } /** @@ -551,8 +549,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 2623b3db..cfa22783 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 097ab72e..3538eec2 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 375befa7..c95bb200 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