From mboxrd@z Thu Jan 1 00:00:00 1970 Authentication-Results: passt.top; dmarc=pass (p=quarantine dis=none) header.from=redhat.com Authentication-Results: passt.top; dkim=pass (1024-bit key; unprotected) header.d=redhat.com header.i=@redhat.com header.a=rsa-sha256 header.s=mimecast20190719 header.b=XyH9l3H5; dkim-atps=neutral Received: from us-smtp-delivery-124.mimecast.com (us-smtp-delivery-124.mimecast.com [170.10.129.124]) by passt.top (Postfix) with ESMTPS id DF1145A0262 for ; Wed, 17 Jun 2026 01:09:08 +0200 (CEST) DKIM-Signature: v=1; a=rsa-sha256; c=relaxed/relaxed; d=redhat.com; s=mimecast20190719; t=1781651347; h=from:from:reply-to:subject:subject:date:date:message-id:message-id: to:to:cc:cc:mime-version:mime-version:content-type:content-type: content-transfer-encoding:content-transfer-encoding: in-reply-to:in-reply-to:references:references; bh=1gKwKaDSL4VkOeyPFrebXDykQHl7T+X0kn8puFnQuAA=; b=XyH9l3H5QdOVnXT1O75bzBVdHZW4OrCyWHPBTBfwcYqDgUVX7X/UI49vExyP1UBIhDJIxC WtSLCr9EyFsPJPRg2qfGftQx+NkOPvmWAUTZV69wjn08uAQUOt+7ikcxAJGKEFezc8rnVn RdGsWT33JESMg/6IgAhNyTbBPaOdt5k= Received: from mail-wm1-f69.google.com (mail-wm1-f69.google.com [209.85.128.69]) by relay.mimecast.com with ESMTP with STARTTLS (version=TLSv1.3, cipher=TLS_AES_256_GCM_SHA384) id us-mta-617-DD0r4uUeMHuQj3LQOcOlXw-1; Tue, 16 Jun 2026 19:09:06 -0400 X-MC-Unique: DD0r4uUeMHuQj3LQOcOlXw-1 X-Mimecast-MFC-AGG-ID: DD0r4uUeMHuQj3LQOcOlXw_1781651345 Received: by mail-wm1-f69.google.com with SMTP id 5b1f17b1804b1-490b9cd54f3so30062235e9.2 for ; Tue, 16 Jun 2026 16:09:06 -0700 (PDT) X-Google-DKIM-Signature: v=1; a=rsa-sha256; c=relaxed/relaxed; d=1e100.net; s=20251104; t=1781651345; x=1782256145; h=date:content-transfer-encoding:mime-version:organization:references :in-reply-to:message-id:subject:cc:to:from:x-gm-gg :x-gm-message-state:from:to:cc:subject:date:message-id:reply-to; bh=1gKwKaDSL4VkOeyPFrebXDykQHl7T+X0kn8puFnQuAA=; b=ApQ9zFfrZ/SfsIU4rsmX225zzgTCJfg6m5h/LsUnzID0cnRuPySFzhmmvGkzlK+AFX io8ubVGIjHItd2lB07mQRnpG12XOAzZxsdZtXvZDxhkQ6Whb0v1miN0F49ffyJOcIgS+ guItLD3VN6JWngNZIYaQXYc4Q4/RPdqb4vjmx25pjGrdFSi2m2rRdQVvzC8A0niia4Cx TGsjiCzZj5HQuHWmmva5zGeuBsa0OiQa6as9DxwycDvakTlhKQtP8ldn4XsVfp7GZhUK gqPdgiQn5OSDN1x9uEbo2G/PbDeDkTLOu18xfa9QIXfP3iBsumMX9tQr4iMTxiLKsEGz unsQ== X-Gm-Message-State: AOJu0YxdNnQJxYOmrttrp0sY1X9ZOvEhLmqz0CacVf/Z6Lig2yAyUsWr fI+ldZS3/C5/PqFt+FN1TwE4a7ZO6oOGXFu+1ybQoGqbm73JRJPDgA1zPOqYIiLyE/1yyJi0Ig5 Z34C1p/FNYL6DnfXMTC4H2HmEYchM0Md9H4mkx7O/ZslJsCj+B1g9XurjCxDcHg== X-Gm-Gg: Acq92OHFUrnawLXpVnC3939UAWKfaCoamBqKZg3v+y45lTK8gZnujcOEvWfuX4s//tv TLA9Mx89I2vLwyKB8NXLnkL66CPamjXnBX687Xxz6bO8f2KFN0D+nOaZRnUPsinqi/aLtjQJPku 5mplKpGSD+Hjb2PbJXmMpi1TgwHyixQtqIstPYPA8ZVu3Jiexdz3h35w8C4Zpd87eZsoXCPlY4r /1jHsFwoFfCseBZZZDRpjlQETZj9+aDOwEZWVRa1hUeN6f9sBZRh3ziE4M/J+hzlbSVLJg0jlMQ cnLA5OfQYH94PwM7mxG7erMj4H5YX810RmZr90gNNkAXpquz74bRsjpR7slfEbxVGiw1sl5Rr9g rF4ZUCpq/UW6MdOomfI79MW2yvyiGdTCE X-Received: by 2002:a05:600d:84ca:20b0:490:c2a2:b1d4 with SMTP id 5b1f17b1804b1-492333f7f68mr17208015e9.35.1781651345268; Tue, 16 Jun 2026 16:09:05 -0700 (PDT) X-Received: by 2002:a05:600d:84ca:20b0:490:c2a2:b1d4 with SMTP id 5b1f17b1804b1-492333f7f68mr17207825e9.35.1781651344797; Tue, 16 Jun 2026 16:09:04 -0700 (PDT) Received: from maya.myfinge.rs (ifcgrfdd.trafficplex.cloud. [2a10:fc81:a806:d6a9::1]) by smtp.gmail.com with ESMTPSA id 5b1f17b1804b1-49230a4601esm112493365e9.1.2026.06.16.16.09.04 (version=TLS1_3 cipher=TLS_AES_256_GCM_SHA384 bits=256/256); Tue, 16 Jun 2026 16:09:04 -0700 (PDT) From: Stefano Brivio To: David Gibson Subject: Re: [PATCH 1/4] flow: Regularise flow specific logging helpers Message-ID: <20260617010903.6502100e@elisabeth> In-Reply-To: <20260609023226.86058-2-david@gibson.dropbear.id.au> References: <20260609023226.86058-1-david@gibson.dropbear.id.au> <20260609023226.86058-2-david@gibson.dropbear.id.au> Organization: Red Hat X-Mailer: Claws Mail 4.2.0 (GTK 3.24.49; x86_64-pc-linux-gnu) MIME-Version: 1.0 Date: Wed, 17 Jun 2026 01:09:04 +0200 (CEST) X-Mimecast-Spam-Score: 0 X-Mimecast-MFC-PROC-ID: 6nMOxyyQaS-7_oClQXVhp2LmtJxdtqqQ70rvRzLotGI_1781651345 X-Mimecast-Originator: redhat.com Content-Type: text/plain; charset=US-ASCII Content-Transfer-Encoding: 7bit Message-ID-Hash: QRZS2CGMY56EDR3QLWKM7BOZULTWZ4AU X-Message-ID-Hash: QRZS2CGMY56EDR3QLWKM7BOZULTWZ4AU X-MailFrom: sbrivio@redhat.com X-Mailman-Rule-Misses: dmarc-mitigation; no-senders; approved; emergency; loop; banned-address; member-moderation; nonmember-moderation; administrivia; implicit-dest; max-recipients; max-size; news-moderation; no-subject; digests; suspicious-header CC: passt-dev@passt.top X-Mailman-Version: 3.3.8 Precedence: list List-Id: Development discussion and patches for passt Archived-At: Archived-At: List-Archive: List-Archive: List-Help: List-Owner: List-Post: List-Subscribe: List-Unsubscribe: On Tue, 9 Jun 2026 12:32:23 +1000 David Gibson 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 > --- > 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