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

On Wed, Jun 17, 2026 at 01:09:11AM +0200, Stefano Brivio wrote:

On Tue, 9 Jun 2026 12:32:24 +1000 David Gibson 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 --- 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