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

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

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

On Wed, Jun 17, 2026 at 01:09:11AM +0200, Stefano Brivio wrote:
> 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()?

That's roughly what we used to have.

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

.. or we could remove the separate print of the details, knowing it
was included in flow_err()?  Or maybe I don't quite grasp the case
you're describing.

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

Terse is nice, but for me the bigger advantage is it's much harder to
forget to include relevant details in an error/warning message.  Part
of the context of this is debugging
https://github.com/podman-container-tools/podman/issues/23739 where we
were seeing an error message that was somewhat useful, but would have
been much more useful if we knew the details of the flow it applied
to.




> 
> >  				 "No support for forwarding UDP from %s to %s",
> >  				 pif_name(pif_at_sidx(ref.flowside)),
> >  				 pif_name(topif));
> 
> -- 
> 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 --]