Re: [PATCH 2/4] flow: Include flow details with higher priority log messages

[Stefano Brivio <sbrivio@redhat.com>]

On Tue,  9 Jun 2026 12:32:24 +1000
David Gibson <david@gibson.dropbear.id.au> wrote:

> Currently flow_log() and related functions / macros have a 'details'
> parameter which indicates whether to add extra messages with details of the
> flow's addresses.  This is still a bit awkward to invoke, and only used in
> a few places.  Change the logic, to automatically include the details if
> and only if the log priority is greater than LOG_DEBUG.
> 
> Rationale:
> 
> If at debug log level, there are already a bunch of debug messages tracking
> the flow life cycle, which include those details (we make sure to retain
> those).  It's usually pretty easy to cross reference a specific flow debug
> message with the flow's history including the details.
> 
> If at higher log level, and we generate a flow-connected error or warning
> we don't have those life cycle messages.  So, just giving the flow index
> doesn't really tell you anything about which flow tripped the error.
> Adding the address details make the error message significantly more
> useful.
> 
> Signed-off-by: David Gibson <david@gibson.dropbear.id.au>
> ---
>  flow.c |  2 +-
>  flow.h | 22 +++++++++++-----------
>  udp.c  |  5 ++---
>  3 files changed, 14 insertions(+), 15 deletions(-)
> 
> diff --git a/flow.c b/flow.c
> index 6cf3905a..dd92bad7 100644
> --- a/flow.c
> +++ b/flow.c
> @@ -550,7 +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_log(flow, LOG_DEBUG, false, true, "Missing forward rule");
> +	flow_dbg(flow, "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 d168a35a..e055defb 100644
> --- a/flow.h
> +++ b/flow.h
> @@ -283,19 +283,19 @@ int flow_migrate_target(struct ctx *c, const struct migrate_stage *stage,
>  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_(f_, pri_, perror_, ...)				\
> +	flow_log__((f_), (pri_), (perror_), (pri_) > LOG_DEBUG,		\

On one hand, this looks quite practical, and we need the effects of
this change anyway. On the other hand, it's a bit sneaky to do this
implicitly. I wonder:

> +		   (f_)->state, __VA_ARGS__)
>  
> -#define flow_log(flow_, pri_, perror_, details_, ...)			\
> -	flow_log_(&(flow_)->f, (pri_), (perror_), (details_), __VA_ARGS__)
> +#define flow_log(flow_, pri_, perror_, ...)				\
> +	flow_log_(&(flow_)->f, (pri_), (perror_), __VA_ARGS__)
>  
>  #define flow_dbg(flow_, ...)						\
> -	flow_log((flow_), LOG_DEBUG, false, false, __VA_ARGS__)
> +	flow_log((flow_), LOG_DEBUG, false, __VA_ARGS__)
>  #define flow_warn(flow_, ...)						\
> -	flow_log((flow_), LOG_WARNING, false, false, __VA_ARGS__)
> +	flow_log((flow_), LOG_WARNING, false, __VA_ARGS__)
>  #define flow_err(flow_, ...)						\
> -	flow_log((flow_), LOG_ERR, false, false, __VA_ARGS__)
> +	flow_log((flow_), LOG_ERR, false, __VA_ARGS__)
>  #define flow_trace(flow_, ...)						\
>  	do {								\
>  		if (log_trace)						\
> @@ -303,11 +303,11 @@ void flow_log__(const struct flow_common *f, int pri, bool perror, bool details,
>  	} while (0)
>  
>  #define flow_dbg_perror(flow_, ...) \
> -	flow_log((flow_), LOG_DEBUG, true, false, __VA_ARGS__)
> +	flow_log((flow_), LOG_DEBUG, true, __VA_ARGS__)
>  #define flow_warn_perror(flow_, ...) \
> -	flow_log((flow_), LOG_WARNING, true, false, __VA_ARGS__)
> +	flow_log((flow_), LOG_WARNING, true, __VA_ARGS__)
>  #define flow_perror(flow_, ...) \
> -	flow_log((flow_), LOG_ERR, true, false, __VA_ARGS__)
> +	flow_log((flow_), LOG_ERR, true, __VA_ARGS__)
>  
>  #define flow_dbg_ratelimit(flow_, now_, ...)				\
>  	logmsg_ratelimit(flow_dbg, debug, (now_), (flow_), __VA_ARGS__)
> diff --git a/udp.c b/udp.c
> index f29ca3da..caeedf8f 100644
> --- a/udp.c
> +++ b/udp.c
> @@ -943,8 +943,7 @@ 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_log(uflow, LOG_ERR, false, true,
> -				 "Unrecoverable error on flow socket");
> +			flow_err(uflow, "Unrecoverable error on flow socket");

...what if this, and...

>  			goto fail;
>  		}
>  	}
> @@ -975,7 +974,7 @@ void udp_sock_handler(const struct ctx *c, union epoll_ref ref,
>  				udp_buf_sock_to_tap(c, s, n, tosidx);
>  			}
>  		} else {
> -			flow_log(uflow, LOG_ERR, false, true,
> +			flow_err(uflow,

...this would both become flow_err_details()? There might be future
cases where we already print flow details separately, even above
LOG_DEBUG, and in those cases we could keep calling flow_err() without
the details.

Not a strong preference from my side, I also see the value of keeping
this terse like the current patch does.

>  				 "No support for forwarding UDP from %s to %s",
>  				 pif_name(pif_at_sidx(ref.flowside)),
>  				 pif_name(topif));

-- 
Stefano