tcp_splice: Improve error reporting

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>
Signed-off-by: Stefano Brivio <sbrivio@redhat.com>

5 files changed, 53 insertions, 22 deletions

diff --git a/flow.h b/flow.h
index 897c9ea..6c6a926 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 c6befe3..69cfb50 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 bc42ea3..b6fc12d 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 42ee8ab..915ac11 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 dbfd55d..8a1a1f6 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);