Re: [PATCH 1/4] flow: Regularise flow specific logging helpers

[David Gibson <david@gibson.dropbear.id.au>]

[-- Attachment #1: Type: text/plain, Size: 14036 bytes --]

On Wed, Jun 17, 2026 at 01:09:04AM +0200, Stefano Brivio wrote:
> On Tue,  9 Jun 2026 12:32:23 +1000
> David Gibson <david@gibson.dropbear.id.au> wrote:
> 
> > 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 <david@gibson.dropbear.id.au>
> > ---
> >  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,
> 
> 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.

> 
> 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);
> > -}
> >  
> > -/** 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));
> 
> Looking at the new interface, here, and...
> 
> >  }
> >  
> >  /**
> > @@ -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");
> 
> ...here, but...
> 
> >  
> >  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");
> 
> ...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 *.

> 
> >  	}
> >  }
> >  
> > 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);
> >  }
> >  
> 
> -- 
> Stefano
> 

-- 
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

[-- Attachment #2: signature.asc --]
[-- Type: application/pgp-signature, Size: 833 bytes --]