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=YavKF6st; dkim-atps=neutral Received: from mail.ozlabs.org (mail.ozlabs.org [IPv6:2404:9400:2221:ea00::3]) by passt.top (Postfix) with ESMTPS id BC8385A0269 for ; Wed, 17 Jun 2026 05:08:56 +0200 (CEST) DKIM-Signature: v=1; a=rsa-sha256; c=relaxed/relaxed; d=gibson.dropbear.id.au; s=202606; t=1781665732; bh=G7J8Ra/cgdCa1y5ZZPqYW7be73eMlrCIb7qdJ5W0NJI=; h=Date:From:To:Cc:Subject:References:In-Reply-To:From; b=YavKF6staOKIe/WFQS4v4ThZMpoNCGhuX5RDvjVMH6jDLLFD/yDjOrvjYiexerM2H yuig+4P5zO4EpvjD3tve+MXf+Iep5gAl4pNiLyrp1rzHuu3AvGfHMq1Vf6T+5Typw9 JY9ebc7Fxjh1zQNCjqeB2UhQ7Qd5F6gGmt6uZDuN7g5xCscooRG4/nxbxl5nJx4gfY zY0w+A/F6QNhfFuaPhwonWp740IAkaHWnTpvN5s8ylyr/1VncWis7xExsZWrdEmV07 3CLakvyH+tNUEMI8f68SKstduqUUHNQLzmWAqlBGWTFpJ+p1XUsjgcsGatXx0HyICC xInUw5lyECcPA== Received: by gandalf.ozlabs.org (Postfix, from userid 1007) id 4gg82X6K8tz58nv; Wed, 17 Jun 2026 13:08:52 +1000 (AEST) Date: Wed, 17 Jun 2026 12:03:50 +1000 From: David Gibson To: Stefano Brivio Subject: Re: [PATCH 1/4] flow: Regularise flow specific logging helpers Message-ID: References: <20260609023226.86058-1-david@gibson.dropbear.id.au> <20260609023226.86058-2-david@gibson.dropbear.id.au> <20260617010903.6502100e@elisabeth> MIME-Version: 1.0 Content-Type: multipart/signed; micalg=pgp-sha512; protocol="application/pgp-signature"; boundary="lZrF57ZZLRwQl600" Content-Disposition: inline In-Reply-To: <20260617010903.6502100e@elisabeth> Message-ID-Hash: 4EZ67L6D65GCZP4U2CT27CQTGROHLMGG X-Message-ID-Hash: 4EZ67L6D65GCZP4U2CT27CQTGROHLMGG 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: passt-dev@passt.top 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: --lZrF57ZZLRwQl600 Content-Type: text/plain; charset=us-ascii Content-Disposition: inline Content-Transfer-Encoding: quoted-printable On Wed, Jun 17, 2026 at 01:09:04AM +0200, Stefano Brivio wrote: > On Tue, 9 Jun 2026 12:32:23 +1000 > David Gibson wrote: >=20 > > 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 addition= al > > log messages with more details of the flow (basically its addresses). > > It's particularly awkward to try to combine that with ratelimiting. > >=20 > > Re-organise this to be based around a flow_log__() internal helper, whi= ch > > 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. > >=20 > > Be a little more consistent about parameter order between the various > > functions / macros / wrappers while we're at it. > >=20 > > Signed-off-by: David Gibson > > --- > > flow.c | 89 ++++++++++++++++++++++++++++------------------------------ > > flow.h | 70 +++++++++++++++++++++++---------------------- > > tcp.c | 4 +-- > > udp.c | 6 ++-- > > 4 files changed, 85 insertions(+), 84 deletions(-) > >=20 > > 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)); > > } > > =20 > > -/** 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, boo= l details, > > + enum flow_state state, const char *fmt, ...) > > { > > const char *type_or_state; > > + int errno_ =3D errno; > > char msg[BUFSIZ]; > > va_list args; > > =20 > > @@ -294,45 +297,41 @@ void flow_log_(const struct flow_common *f, bool = newline, int pri, > > else > > type_or_state =3D FLOW_TYPE(f); > > =20 > > - logmsg(newline, false, pri, > > + logmsg(!perror, false, pri, >=20 > Shouldn't we pass a false 'newline' also if 'details' is set, or did > you intend to print details on a separate line anyway? The details are quite long - a decent length line on their own. So, they're intentionally printed on a separate line. That's already true, and I'm not changing it here. > If you did, > shouldn't you prefix the second line with a couple of spaces? That's a nice idea. I'll implement it as an extra patch. >=20 > It's probably going to get messy with multithreading though. A little, but not too bad I think. The messages could be interleaved, but both the primary message and the details are still prefixed with the flow number, so it shouldn't be too hard to correlated them. > > "Flow %u (%s): %s", flow_idx(f), type_or_state, msg); > > -} > > =20 > > -/** 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 =3D &f->side[INISIDE]; > > - const struct flowside *tgt =3D &f->side[TGTSIDE]; > > - > > - if (state >=3D FLOW_STATE_TGT) > > - flow_log_(f, true, pri, > > - "%s [%s]:%hu -> [%s]:%hu =3D> %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 >=3D FLOW_STATE_INI) > > - flow_log_(f, true, pri, "%s [%s]:%hu -> [%s]:%hu =3D> ?", > > - 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 =3D &f->side[INISIDE]; > > + const struct flowside *tgt =3D &f->side[TGTSIDE]; > > + > > + if (state >=3D FLOW_STATE_TGT) { > > + flow_log__(f, pri, false, false, state, > > +"%s [%s]:%hu -> [%s]:%hu =3D> %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 >=3D FLOW_STATE_INI) { > > + flow_log__(f, pri, false, false, state, > > + "%s [%s]:%hu -> [%s]:%hu =3D> ?", > > + pif_name(f->pif[INISIDE]), > > + inany_ntop(&ini->eaddr, estr0, sizeof(estr0)), > > + ini->eport, > > + inany_ntop(&ini->oaddr, fstr0, sizeof(fstr0)), > > + ini->oport); > > + } > > + } > > } > > =20 > > /** > > @@ -348,10 +347,9 @@ static void flow_set_state(struct flow_common *f, = enum flow_state state) > > assert(oldstate < FLOW_NUM_STATES); > > =20 > > f->state =3D 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)); >=20 > Looking at the new interface, here, and... >=20 > > } > > =20 > > /** > > @@ -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"); >=20 > ...here, but... >=20 > > =20 > > 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 stru= ct migrate_stage *stage, > > int flow_migrate_target(struct ctx *c, const struct migrate_stage *sta= ge, > > int fd); > > =20 > > -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_A= RGS__) > > -#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, boo= l 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_ =3D errno; \ > > - flow_log_((f), false, (pri), __VA_ARGS__); \ > > - logmsg(true, true, (pri), ": %s", strerror_(errno_)); \ > > + flow_dbg((flow_), __VA_ARGS__); \ > > } while (0) > > =20 > > -#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__) > > =20 > > #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, in= t 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"); >=20 > ...especially here, I think this actually decreases readability because > one needs to remember what those boolean parameters are, instead of a > clear _perror_() indication in the function name. For these cases, yes it's less readable, but these are fairly rare cases. The majority of cases don't show up in the patch because we didn't change the interface for them. > I wonder if we shouldn't rather reimplement _perror_() and _details_() > as simple wrappers around flow_log_() with the appropriate arguments. > Does that get in the way of rate limiting? We already do, but those macros take an arbitrary whole-flow pointer instead of a flow_common *. I judged that making the handful of cases which need to pass a flow_common * more awkward was preferable to doubling the number of macros by having variants that take a flow_common *. >=20 > > } > > } > > =20 > > 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 ep= oll_ref ref, > > =20 > > 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 ep= oll_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 ep= oll_ref ref, > > return; > > =20 > > fail: > > - flow_err_details(uflow); > > udp_flow_close(c, uflow); > > } > > =20 >=20 > --=20 > Stefano >=20 --=20 David Gibson (he or they) | I'll have my music baroque, and my code david AT gibson.dropbear.id.au | minimalist, thank you, not the other way | around. http://www.ozlabs.org/~dgibson --lZrF57ZZLRwQl600 Content-Type: application/pgp-signature; name=signature.asc -----BEGIN PGP SIGNATURE----- iQIzBAEBCgAdFiEEO+dNsU4E3yXUXRK2zQJF27ox2GcFAmoyAHcACgkQzQJF27ox 2Gd26RAAnSaGzS4bTtyonkRBWw3DYoWtGp6y0fP8FvYMqOI/mohqH1bTb10sKTnm XZRj6IDW0MdYnGygv2HbUmibp4vMSiiVTOqvvfj88D7uZH3KtbHmCmarboT8RWbX QoDV4uGUTHtc1VZv+qOHSu+yXcSzTov9qhcJ5EqITdn8XSTgj8fkZ54k3xweH3l2 zTieGc1buz7Qh9PPRNwroxwkALvOBtHvgaDr6Xo6gyScUHEPDpOMDsqLSIz0fost YgU0ngk/ScysI07rP6CfdAhye5WuRimEcDAJ1yuYw2SEZly6NUH1RzGr6CKiPG/N ZCMurEONT85k+iIdBjRicdvJqI3QOSyFvl2myzQNn6l5EuL6LJwfMg+VTA6tSavT M1iX9ffKiEXrigxgUE5oXUeMCjszEI+eX7uwvUpbPtzaEDBI+ZEBwqDh2YZilcKK 3t58JyjicBY7iZjuFx93liHbSoer7lHvGwG857VUgJQ16yANjgm4oN8iyu2GNRwQ 9QNnI6AHFPnfH4G43MJ5VJK6bjVdD/c87hFIDB2/CjSSPoGJ07srJbO/0YbtP7cn /8aPf916oV6KttpxopZDzYEhQf+qSDrIrAc0PUJH0ixHXi6Me6pOImdA7/GMLYkg cOAXR+Ad4AcNs/x90X8oYsZtxnYDllsy0ofFJI+kntFUe4Mwxl8= =2ssU -----END PGP SIGNATURE----- --lZrF57ZZLRwQl600--