[PATCH v2 1/4] tcp_splice: Improve error reporting

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

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 <david@gibson.dropbear.id.au>
---
 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