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

[Stefano Brivio <sbrivio@redhat.com>]

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? If you did,
shouldn't you prefix the second line with a couple of spaces?

It's probably going to get messy with multithreading though.

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

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?

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