[PATCH v3 05/15] flow, tcp, tcp_splice: Uniform debug helpers for new flows

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

When debugging passt/pasta, and the flow table in particular, one of the
most obvious things to know is when a new flow is initiated, along with the
details of its interface, addresses and ports.  Once we've determined to
what interface the flow should be forwarded, it's useful to know the
details of how it will appear on that other interface.

To help present that information uniformly, introduce FLOW_NEW_DBG() and
FLOW_FWD_DBG() helpers and use them for TCP connections, both "tap" and
spliced.

Signed-off-by: David Gibson <david@gibson.dropbear.id.au>
---
 flow.c       | 40 ++++++++++++++++++++++++++++++++++++++++
 flow.h       | 16 ++++++++++++++++
 tcp.c        | 11 +++++++++--
 tcp_splice.c |  3 ++-
 4 files changed, 67 insertions(+), 3 deletions(-)

diff --git a/flow.c b/flow.c
index b9c4a18..bc8cfc6 100644
--- a/flow.c
+++ b/flow.c
@@ -9,6 +9,7 @@
 #include <unistd.h>
 #include <string.h>
 #include <errno.h>
+#include <arpa/inet.h>
 
 #include "util.h"
 #include "passt.h"
@@ -50,6 +51,45 @@ void flow_log_(const struct flow_common *f, int pri, const char *fmt, ...)
 	logmsg(pri, "Flow %u (%s): %s", flow_idx(f), FLOW_TYPE(f), msg);
 }
 
+/**
+ * flow_new_dbg() - Print debug message for new flow
+ * @f:		Common flow structure
+ * @side:	Which side initiated the new flow
+ */
+void flow_new_dbg(const struct flow_common *f, unsigned side)
+{
+	char ebuf[INET6_ADDRSTRLEN], fbuf[INET6_ADDRSTRLEN];
+	const struct flowside *fside = &f->side[side];
+
+	flow_log_(f, LOG_DEBUG, "New %s from %s/%u: [%s]:%hu <-> [%s]:%hu",
+		  flow_type_str[f->type], pif_name(fside->pif), side,
+		  inet_ntop(AF_INET6, &fside->faddr, fbuf, sizeof(fbuf)),
+		  fside->fport,
+		  inet_ntop(AF_INET6, &fside->eaddr, ebuf, sizeof(ebuf)),
+		  fside->eport);
+}
+
+/**
+ * flow_fwd_dbg() - Print debug message for newly forwarded flow
+ * @f:		Common flow structure
+ * @side:	Which side was the flow forwarded to
+ */
+void flow_fwd_dbg(const struct flow_common *f, unsigned side)
+{
+	char ebuf[INET6_ADDRSTRLEN], fbuf[INET6_ADDRSTRLEN];
+	const struct flowside *fside = &f->side[side];
+
+	inet_ntop(AF_INET6, &fside->eaddr, ebuf, sizeof(ebuf));
+	inet_ntop(AF_INET6, &fside->faddr, fbuf, sizeof(fbuf));
+
+	flow_log_(f, LOG_DEBUG, "Forwarded to %s/%u: [%s]:%hu <-> [%s]:%hu",
+		  pif_name(fside->pif), side,
+		  inet_ntop(AF_INET6, &fside->faddr, fbuf, sizeof(fbuf)),
+		  fside->fport,
+		  inet_ntop(AF_INET6, &fside->eaddr, ebuf, sizeof(ebuf)),
+		  fside->eport);
+}
+
 /** flowside_from_sock - Initialize flowside to match an existing socket
  * @fside:	flowside to initialize
  * @pif:	pif id of this flowside
diff --git a/flow.h b/flow.h
index 37885b2..e7c4484 100644
--- a/flow.h
+++ b/flow.h
@@ -97,6 +97,22 @@ struct flow_common {
 #define FLOW_TABLE_PRESSURE		30	/* % of FLOW_MAX */
 #define FLOW_FILE_PRESSURE		30	/* % of c->nofile */
 
+/** flow_complete - Check if common parts of flow are fully initialized
+ * @flow:	flow to check
+ */
+static inline bool flow_complete(const struct flow_common *f)
+{
+	return f->type != FLOW_TYPE_NONE && f->type < FLOW_NUM_TYPES &&
+		flowside_complete(&f->side[0]) &&
+		flowside_complete(&f->side[1]);
+}
+
+void flow_new_dbg(const struct flow_common *f, unsigned side);
+#define FLOW_NEW_DBG(flow, side)	(flow_new_dbg(&(flow)->f, (side)))
+
+void flow_fwd_dbg(const struct flow_common *f, unsigned side);
+#define FLOW_FWD_DBG(flow, side)	(flow_fwd_dbg(&(flow)->f, (side)))
+
 /**
  * struct flow_sidx - ID for one side of a specific flow
  * @side:	Side referenced (0 or 1)
diff --git a/tcp.c b/tcp.c
index 6d77cf6..954c24f 100644
--- a/tcp.c
+++ b/tcp.c
@@ -1949,6 +1949,8 @@ static void tcp_conn_from_tap(struct ctx *c,
 	conn->f.type = FLOW_TCP;
 	flowside_from_af(TAPFSIDE(conn), PIF_TAP, af,
 			 daddr, ntohs(th->dest), saddr, ntohs(th->source));
+
+	FLOW_NEW_DBG(conn, TAPSIDE);
 	ASSERT(flowside_complete(TAPFSIDE(conn)));
 
 	conn->sock = s;
@@ -2021,7 +2023,8 @@ static void tcp_conn_from_tap(struct ctx *c,
 		return;
 	}
 
-	ASSERT(flowside_complete(SOCKFSIDE(conn)));
+	FLOW_FWD_DBG(conn, SOCKSIDE);
+	ASSERT(flow_complete(&conn->f));
 
 	tcp_epoll_ctl(c, conn);
 	return;
@@ -2690,7 +2693,8 @@ static void tcp_tap_conn_from_sock(struct ctx *c,
 	}
 	TAPFSIDE(conn)->eport = ref.port;
 
-	ASSERT(flowside_complete(TAPFSIDE(conn)));
+	FLOW_FWD_DBG(conn, TAPSIDE);
+	ASSERT(flow_complete(&conn->f));
 
 	tcp_seq_init(c, conn, now);
 	tcp_hash_insert(c, conn);
@@ -2734,6 +2738,9 @@ void tcp_listen_handler(struct ctx *c, union epoll_ref ref,
 		return;
 	}
 
+	FLOW_NEW_DBG(flow, 0);
+	ASSERT(flowside_complete(&flow->f.side[0]));
+
 	if (c->mode == MODE_PASTA &&
 	    tcp_splice_conn_from_sock(c, ref.tcp_listen, &flow->tcp_splice, s))
 		return;
diff --git a/tcp_splice.c b/tcp_splice.c
index 0faeb1b..b59ac90 100644
--- a/tcp_splice.c
+++ b/tcp_splice.c
@@ -296,7 +296,8 @@ static int tcp_splice_connect_finish(const struct ctx *c,
 	inany_from_sockaddr(&FSIDE1(conn)->faddr, &FSIDE1(conn)->fport,
 			    (struct sockaddr *)&sa);
 
-	ASSERT(flowside_complete(FSIDE1(conn)));
+	FLOW_FWD_DBG(conn, 1);
+	ASSERT(flow_complete(&conn->f));
 
 	for (side = 0; side < SIDES; side++) {
 		conn->pipe[side][0] = conn->pipe[side][1] = -1;
-- 
@@ -296,7 +296,8 @@ static int tcp_splice_connect_finish(const struct ctx *c,
 	inany_from_sockaddr(&FSIDE1(conn)->faddr, &FSIDE1(conn)->fport,
 			    (struct sockaddr *)&sa);
 
-	ASSERT(flowside_complete(FSIDE1(conn)));
+	FLOW_FWD_DBG(conn, 1);
+	ASSERT(flow_complete(&conn->f));
 
 	for (side = 0; side < SIDES; side++) {
 		conn->pipe[side][0] = conn->pipe[side][1] = -1;
-- 
2.43.0