From mboxrd@z Thu Jan 1 00:00:00 1970 Authentication-Results: passt.top; dmarc=none (p=none dis=none) header.from=gibson.dropbear.id.au Authentication-Results: passt.top; dkim=pass (2048-bit key; secure) header.d=gibson.dropbear.id.au header.i=@gibson.dropbear.id.au header.a=rsa-sha256 header.s=202602 header.b=exd+MuFw; dkim-atps=neutral Received: from mail.ozlabs.org (mail.ozlabs.org [IPv6:2404:9400:2221:ea00::3]) by passt.top (Postfix) with ESMTPS id 06E185A026D for ; Thu, 21 May 2026 08:37:52 +0200 (CEST) DKIM-Signature: v=1; a=rsa-sha256; c=relaxed/relaxed; d=gibson.dropbear.id.au; s=202602; t=1779345468; bh=3u0qLUfyzDe4kLYnkUh8DFIw0xjIhoc/VAb6HXOEBro=; h=From:To:Cc:Subject:Date:In-Reply-To:References:From; b=exd+MuFwok4hR0z+tJNBIPog04NQWO5SeGbEROkjUC6Pow40O8jt2tzO7vPqO685A /vFa9ItocQKfOAJDpvEMTKikn0TdcKGZtH5rzhrItyIN/2nsDBVUOPdjcAtcG8Y5tl 1fcQPmWMH5Z6GnKWs0chpic7CVBtwPuRW981ZzoxEcBhQx2EhEUJwGHWsjq/BM/ORM pkgzTDpoPzo5jRlNfUgznoLtBzQnK1sTe/lXVZG3GmffkTO9m+InOzksaPN4WiGvIm F8ipgCIs3ozzuxjb6QNzhXoi76381daH+D5VFCC1NQc7FNUXXbGEIa/R06LPtv2p43 0uOLSeGY5Lzjw== Received: by gandalf.ozlabs.org (Postfix, from userid 1007) id 4gLdy44FD0z4wHj; Thu, 21 May 2026 16:37:48 +1000 (AEST) From: David Gibson To: passt-dev@passt.top, Stefano Brivio Subject: [PATCH v2 1/4] tcp_splice: Improve error reporting Date: Thu, 21 May 2026 16:37:42 +1000 Message-ID: <20260521063745.1211215-2-david@gibson.dropbear.id.au> X-Mailer: git-send-email 2.54.0 In-Reply-To: <20260521063745.1211215-1-david@gibson.dropbear.id.au> References: <20260521063745.1211215-1-david@gibson.dropbear.id.au> MIME-Version: 1.0 Content-Transfer-Encoding: 8bit Message-ID-Hash: EMJEQGUSCG2D4OWCOVUIZR5TTXCK5PTR X-Message-ID-Hash: EMJEQGUSCG2D4OWCOVUIZR5TTXCK5PTR X-MailFrom: dgibson@gandalf.ozlabs.org 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: Paul Holzinger , David Gibson 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: A number of things can, at least theoretically, go wrong when forwarding data across a spliced connection. We generally handle this by resetting the connection on both sides. However, in many cases we don't log any message about why the connection was reset, which can make it hard to debug why this is happening. Add a bunch of debug and error logging to make this easier to figure out. We ratelimit for safety, which requires some tweaks to make the ratelimit logic work with the flow specific log functions. Signed-off-by: David Gibson --- flow.h | 7 +++++++ log.h | 19 ++++++++++--------- passt.c | 2 +- tcp_splice.c | 45 ++++++++++++++++++++++++++++++++++----------- tcp_splice.h | 2 +- 5 files changed, 53 insertions(+), 22 deletions(-) diff --git a/flow.h b/flow.h index 897c9ea8..6c6a9260 100644 --- a/flow.h +++ b/flow.h @@ -311,4 +311,11 @@ void flow_log_details_(const struct flow_common *f, int pri, #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__) + #endif /* FLOW_H */ diff --git a/log.h b/log.h index c6befe3a..69cfb507 100644 --- a/log.h +++ b/log.h @@ -103,9 +103,10 @@ void logmsg_perror(int pri, const char *format, ...) /** * logmsg_ratelimit() - Log a message with rate limiting * @fn: Logging function name (e.g. warn, info, debug) + * @fn_s: Logging function name for suppression messages * @now: Current timestamp */ -#define logmsg_ratelimit(fn, now, ...) \ +#define logmsg_ratelimit(fn, fn_s, now, ...) \ do { \ static unsigned int rl_suppressed_; \ static unsigned int rl_printed_; \ @@ -119,27 +120,27 @@ void logmsg_perror(int pri, const char *format, ...) if (rl_printed_ < LOG_RATELIMIT_BURST) { \ fn(__VA_ARGS__); \ if (rl_suppressed_) { \ - fn("(suppressed %u similar messages)", \ - rl_suppressed_); \ + fn_s("(suppressed %u similar messages)", \ + rl_suppressed_); \ rl_suppressed_ = 0; \ } \ rl_printed_++; \ if (rl_printed_ == LOG_RATELIMIT_BURST) \ - fn("(suppressing further similar" \ - " messages)"); \ + fn_s("(suppressing further similar" \ + " messages)"); \ } else { \ rl_suppressed_++; \ } \ } while (0) #define err_ratelimit(now, ...) \ - logmsg_ratelimit(err, now, __VA_ARGS__) + logmsg_ratelimit(err, err, now, __VA_ARGS__) #define warn_ratelimit(now, ...) \ - logmsg_ratelimit(warn, now, __VA_ARGS__) + logmsg_ratelimit(warn, warn, now, __VA_ARGS__) #define info_ratelimit(now, ...) \ - logmsg_ratelimit(info, now, __VA_ARGS__) + logmsg_ratelimit(info, info, now, __VA_ARGS__) #define debug_ratelimit(now, ...) \ - logmsg_ratelimit(debug, now, __VA_ARGS__) + logmsg_ratelimit(debug, debug, now, __VA_ARGS__) extern int log_file; extern int log_trace; diff --git a/passt.c b/passt.c index bc42ea33..b6fc12d4 100644 --- a/passt.c +++ b/passt.c @@ -273,7 +273,7 @@ static void passt_worker(void *opaque, int nfds, struct epoll_event *events) tcp_sock_handler(c, ref, eventmask); break; case EPOLL_TYPE_TCP_SPLICE: - tcp_splice_sock_handler(c, ref, eventmask); + tcp_splice_sock_handler(c, ref, eventmask, &now); break; case EPOLL_TYPE_TCP_LISTEN: tcp_listen_handler(c, ref, &now); diff --git a/tcp_splice.c b/tcp_splice.c index 42ee8abc..915ac114 100644 --- a/tcp_splice.c +++ b/tcp_splice.c @@ -478,11 +478,12 @@ void tcp_splice_conn_from_sock(const struct ctx *c, union flow *flow, int s0) * @c: Execution context * @ref: epoll reference * @events: epoll events bitmap + * @now: Current timestamp * * #syscalls:pasta splice */ void tcp_splice_sock_handler(struct ctx *c, union epoll_ref ref, - uint32_t events) + uint32_t events, const struct timespec *now) { struct tcp_splice_conn *conn = conn_at_sidx(ref.flowside); unsigned evsidei = ref.flowside.sidei, fromsidei; @@ -499,18 +500,25 @@ void tcp_splice_sock_handler(struct ctx *c, union epoll_ref ref, socklen_t sl = sizeof(err); rc = getsockopt(ref.fd, SOL_SOCKET, SO_ERROR, &err, &sl); - if (rc) + if (rc) { flow_perror(conn, "Error retrieving SO_ERROR"); - else - flow_trace(conn, "Error event on socket: %s", - strerror_(err)); - + } else { + flow_dbg_ratelimit(conn, now, + "Error event on %s socket: %s", + pif_name(conn->f.pif[evsidei]), + strerror_(err)); + } goto reset; } if (conn->events == SPLICE_CONNECT) { - if (!(events & EPOLLOUT)) + if (!(events & EPOLLOUT)) { + flow_err_ratelimit( + conn, now, + "Unexpected events 0x%x during connect", + events); goto reset; + } if (tcp_splice_connect_finish(c, conn)) goto reset; } @@ -545,8 +553,12 @@ retry: SPLICE_F_MOVE | SPLICE_F_NONBLOCK); while (readlen < 0 && errno == EINTR); - if (readlen < 0 && errno != EAGAIN) + if (readlen < 0 && errno != EAGAIN) { + flow_perror_ratelimit( + conn, now, "Splicing from %s socket", + pif_name(conn->f.pif[fromsidei])); goto reset; + } flow_trace(conn, "%zi from read-side call", readlen); @@ -569,8 +581,12 @@ retry: SPLICE_F_MOVE | more | SPLICE_F_NONBLOCK); while (written < 0 && errno == EINTR); - if (written < 0 && errno != EAGAIN) + if (written < 0 && errno != EAGAIN) { + flow_perror_ratelimit( + conn, now, "Splicing to %s socket", + pif_name(conn->f.pif[!fromsidei])); goto reset; + } flow_trace(conn, "%zi from write-side call (passed %zi)", written, c->tcp.pipe_size); @@ -627,8 +643,12 @@ retry: flow_foreach_sidei(sidei) { if ((conn->events & FIN_RCVD(sidei)) && !(conn->events & FIN_SENT(!sidei))) { - if (shutdown(conn->s[!sidei], SHUT_WR) < 0) + if (shutdown(conn->s[!sidei], SHUT_WR) < 0) { + flow_perror_ratelimit( + conn, now, "shutdown() on %s", + pif_name(conn->f.pif[!sidei])); goto reset; + } conn_event(conn, FIN_SENT(!sidei)); } } @@ -647,8 +667,11 @@ retry: goto swap; } - if (events & EPOLLHUP) + if (events & EPOLLHUP) { + flow_dbg_ratelimit(conn, now, "Hangup from %s socket", + pif_name(conn->f.pif[evsidei])); goto reset; + } return; diff --git a/tcp_splice.h b/tcp_splice.h index dbfd55db..8a1a1f67 100644 --- a/tcp_splice.h +++ b/tcp_splice.h @@ -12,7 +12,7 @@ struct tcp_splice_conn; union sockaddr_inany; void tcp_splice_sock_handler(struct ctx *c, union epoll_ref ref, - uint32_t events); + uint32_t events, const struct timespec *now); void tcp_splice_conn_from_sock(const struct ctx *c, union flow *flow, int s0); void tcp_splice_init(struct ctx *c); -- 2.54.0