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

[Stefano Brivio <sbrivio@redhat.com>]

On Wed, 17 Jun 2026 12:15:54 +1000
David Gibson <david@gibson.dropbear.id.au> wrote:

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

Right, yes, see my comment to 1/4 for why I was suggesting that an
explicit flow_err_details() looked like a better interface to me.

But if it's just a few corner cases I don't really have a preference.

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

Yes, that's the case I was describing. I was thinking of a function
failing to do something with a flow, and then reporting further
details. But I guess it's not very likely to happen anyway.

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

Ah, sure, fair point.

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

Right, I see now.

-- 
Stefano