From: David Gibson <david@gibson.dropbear.id.au>
To: passt-dev@passt.top, Stefano Brivio <sbrivio@redhat.com>
Cc: David Gibson <david@gibson.dropbear.id.au>
Subject: [PATCH v3 07/16] flow, tcp: Add logging helpers for connection related messages
Date: Thu, 30 Nov 2023 13:02:13 +1100 [thread overview]
Message-ID: <20231130020222.4056647-8-david@gibson.dropbear.id.au> (raw)
In-Reply-To: <20231130020222.4056647-1-david@gibson.dropbear.id.au>
Most of the messages logged by the TCP code (be they errors, debug or
trace messages) are related to a specific connection / flow. We're fairly
consistent about prefixing these with the type of connection and the
connection / flow index. However there are a few places where we put the
index later in the message or omit it entirely. The template with the
prefix is also a little bulky to carry around for every message,
particularly for spliced connections.
To help keep this consistent, introduce some helpers to log messages
linked to a specific flow. It takes the flow as a parameter and adds a
uniform prefix to each message. This makes things slightly neater now, but
more importantly will help keep formatting consistent as we add more things
to the flow table.
Signed-off-by: David Gibson <david@gibson.dropbear.id.au>
---
flow.c | 18 ++++++++++++
flow.h | 14 +++++++++
tcp.c | 81 ++++++++++++++++++++++++----------------------------
tcp_splice.c | 61 +++++++++++++++++----------------------
4 files changed, 96 insertions(+), 78 deletions(-)
diff --git a/flow.c b/flow.c
index 534638b..d24726d 100644
--- a/flow.c
+++ b/flow.c
@@ -66,3 +66,21 @@ void flow_table_compact(struct ctx *c, union flow *hole)
memset(from, 0, sizeof(*from));
}
+
+/** flow_log_ - Log flow-related message
+ * @f: flow the message is related to
+ * @pri: Log priority
+ * @fmt: Format string
+ * @...: printf-arguments
+ */
+void flow_log_(const struct flow_common *f, int pri, const char *fmt, ...)
+{
+ char msg[BUFSIZ];
+ va_list args;
+
+ va_start(args, fmt);
+ (void)vsnprintf(msg, sizeof(msg), fmt, args);
+ va_end(args);
+
+ logmsg(pri, "Flow %u (%s): %s", flow_idx(f), FLOW_TYPE(f), msg);
+}
diff --git a/flow.h b/flow.h
index f3dad53..c820a15 100644
--- a/flow.h
+++ b/flow.h
@@ -43,4 +43,18 @@ union flow;
void flow_table_compact(struct ctx *c, union flow *hole);
+void flow_log_(const struct flow_common *f, int pri, const char *fmt, ...)
+ __attribute__((format(printf, 3, 4)));
+
+#define flow_log(f_, pri, ...) flow_log_(&(f_)->f, (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, ...) \
+ do { \
+ if (log_trace) \
+ flow_dbg((f), __VA_ARGS__); \
+ } while (0)
+
#endif /* FLOW_H */
diff --git a/tcp.c b/tcp.c
index 6924dd2..f427047 100644
--- a/tcp.c
+++ b/tcp.c
@@ -624,7 +624,7 @@ static void conn_flag_do(const struct ctx *c, struct tcp_tap_conn *conn,
unsigned long flag);
#define conn_flag(c, conn, flag) \
do { \
- trace("TCP: flag at %s:%i", __func__, __LINE__); \
+ flow_trace(conn, "flag at %s:%i", __func__, __LINE__); \
conn_flag_do(c, conn, flag); \
} while (0)
@@ -695,7 +695,8 @@ static void tcp_timer_ctl(const struct ctx *c, struct tcp_tap_conn *conn)
fd = timerfd_create(CLOCK_MONOTONIC, 0);
if (fd == -1 || fd > FD_REF_MAX) {
- debug("TCP: failed to get timer: %s", strerror(errno));
+ flow_dbg(conn, "failed to get timer: %s",
+ strerror(errno));
if (fd > -1)
close(fd);
conn->timer = -1;
@@ -704,7 +705,8 @@ static void tcp_timer_ctl(const struct ctx *c, struct tcp_tap_conn *conn)
conn->timer = fd;
if (epoll_ctl(c->epollfd, EPOLL_CTL_ADD, conn->timer, &ev)) {
- debug("TCP: failed to add timer: %s", strerror(errno));
+ flow_dbg(conn, "failed to add timer: %s",
+ strerror(errno));
close(conn->timer);
conn->timer = -1;
return;
@@ -724,8 +726,8 @@ static void tcp_timer_ctl(const struct ctx *c, struct tcp_tap_conn *conn)
it.it_value.tv_sec = ACT_TIMEOUT;
}
- debug("TCP: index %u, timer expires in %lu.%03lus", FLOW_IDX(conn),
- it.it_value.tv_sec, it.it_value.tv_nsec / 1000 / 1000);
+ flow_dbg(conn, "timer expires in %lu.%03lus", it.it_value.tv_sec,
+ it.it_value.tv_nsec / 1000 / 1000);
timerfd_settime(conn->timer, 0, &it, NULL);
}
@@ -746,10 +748,8 @@ static void conn_flag_do(const struct ctx *c, struct tcp_tap_conn *conn,
return;
conn->flags &= flag;
- if (flag_index >= 0) {
- debug("TCP: index %u: %s dropped", FLOW_IDX(conn),
- tcp_flag_str[flag_index]);
- }
+ if (flag_index >= 0)
+ flow_dbg(conn, "%s dropped", tcp_flag_str[flag_index]);
} else {
int flag_index = fls(flag);
@@ -767,10 +767,8 @@ static void conn_flag_do(const struct ctx *c, struct tcp_tap_conn *conn,
}
conn->flags |= flag;
- if (flag_index >= 0) {
- debug("TCP: index %u: %s", FLOW_IDX(conn),
- tcp_flag_str[flag_index]);
- }
+ if (flag_index >= 0)
+ flow_dbg(conn, "%s", tcp_flag_str[flag_index]);
}
if (flag == STALLED || flag == ~STALLED)
@@ -817,15 +815,14 @@ static void conn_event_do(const struct ctx *c, struct tcp_tap_conn *conn,
if (conn->flags & ACTIVE_CLOSE)
new += 5;
- if (prev != new) {
- debug("TCP: index %u, %s: %s -> %s", FLOW_IDX(conn),
- num == -1 ? "CLOSED" : tcp_event_str[num],
- prev == -1 ? "CLOSED" : tcp_state_str[prev],
- (new == -1 || num == -1) ? "CLOSED" : tcp_state_str[new]);
- } else {
- debug("TCP: index %u, %s", FLOW_IDX(conn),
- num == -1 ? "CLOSED" : tcp_event_str[num]);
- }
+ if (prev != new)
+ flow_dbg(conn, "%s: %s -> %s",
+ num == -1 ? "CLOSED" : tcp_event_str[num],
+ prev == -1 ? "CLOSED" : tcp_state_str[prev],
+ (new == -1 || num == -1) ? "CLOSED" : tcp_state_str[new]);
+ else
+ flow_dbg(conn, "%s",
+ num == -1 ? "CLOSED" : tcp_event_str[num]);
if ((event == TAP_FIN_RCVD) && !(conn->events & SOCK_FIN_RCVD))
conn_flag(c, conn, ACTIVE_CLOSE);
@@ -838,7 +835,7 @@ static void conn_event_do(const struct ctx *c, struct tcp_tap_conn *conn,
#define conn_event(c, conn, event) \
do { \
- trace("TCP: event at %s:%i", __func__, __LINE__); \
+ flow_trace(conn, "event at %s:%i", __func__, __LINE__); \
conn_event_do(c, conn, event); \
} while (0)
@@ -1206,9 +1203,8 @@ static void tcp_hash_insert(const struct ctx *c, struct tcp_tap_conn *conn)
conn->next_index = tc_hash[b] ? FLOW_IDX(tc_hash[b]) : -1U;
tc_hash[b] = conn;
- debug("TCP: hash table insert: index %u, sock %i, bucket: %i, next: "
- "%p", FLOW_IDX(conn), conn->sock, b,
- (void *)conn_at_idx(conn->next_index));
+ flow_dbg(conn, "hash table insert: sock %i, bucket: %i, next: %p",
+ conn->sock, b, (void *)conn_at_idx(conn->next_index));
}
/**
@@ -1233,9 +1229,9 @@ static void tcp_hash_remove(const struct ctx *c,
}
}
- debug("TCP: hash table remove: index %u, sock %i, bucket: %i, new: %p",
- FLOW_IDX(conn), conn->sock, b,
- (void *)(prev ? conn_at_idx(prev->next_index) : tc_hash[b]));
+ flow_dbg(conn, "hash table remove: sock %i, bucket: %i, new: %p",
+ conn->sock, b,
+ (void *)(prev ? conn_at_idx(prev->next_index) : tc_hash[b]));
}
/**
@@ -1318,8 +1314,7 @@ static void tcp_conn_destroy(struct ctx *c, union flow *flow)
static void tcp_rst_do(struct ctx *c, struct tcp_tap_conn *conn);
#define tcp_rst(c, conn) \
do { \
- debug("TCP: index %u, reset at %s:%i", FLOW_IDX(conn), \
- __func__, __LINE__); \
+ flow_dbg((conn), "TCP reset at %s:%i", __func__, __LINE__); \
tcp_rst_do(c, conn); \
} while (0)
@@ -1998,7 +1993,7 @@ static void tcp_conn_from_tap(struct ctx *c,
mss = tcp_conn_tap_mss(conn, opts, optlen);
if (setsockopt(s, SOL_TCP, TCP_MAXSEG, &mss, sizeof(mss)))
- trace("TCP: failed to set TCP_MAXSEG on socket %i", s);
+ flow_trace(conn, "failed to set TCP_MAXSEG on socket %i", s);
MSS_SET(conn, mss);
tcp_get_tap_ws(conn, opts, optlen);
@@ -2159,8 +2154,8 @@ static int tcp_data_from_sock(struct ctx *c, struct tcp_tap_conn *conn)
if (SEQ_LT(already_sent, 0)) {
/* RFC 761, section 2.1. */
- trace("TCP: ACK sequence gap: ACK for %u, sent: %u",
- conn->seq_ack_from_tap, conn->seq_to_tap);
+ flow_trace(conn, "ACK sequence gap: ACK for %u, sent: %u",
+ conn->seq_ack_from_tap, conn->seq_to_tap);
conn->seq_to_tap = conn->seq_ack_from_tap;
already_sent = 0;
}
@@ -2392,8 +2387,9 @@ static int tcp_data_from_tap(struct ctx *c, struct tcp_tap_conn *conn,
tcp_tap_window_update(conn, max_ack_seq_wnd);
if (retr) {
- trace("TCP: fast re-transmit, ACK: %u, previous sequence: %u",
- max_ack_seq, conn->seq_to_tap);
+ flow_trace(conn,
+ "fast re-transmit, ACK: %u, previous sequence: %u",
+ max_ack_seq, conn->seq_to_tap);
conn->seq_ack_from_tap = max_ack_seq;
conn->seq_to_tap = max_ack_seq;
tcp_data_from_sock(c, conn);
@@ -2542,7 +2538,7 @@ int tcp_tap_handler(struct ctx *c, uint8_t pif, int af,
return 1;
}
- trace("TCP: packet length %lu from tap for index %u", len, FLOW_IDX(conn));
+ flow_trace(conn, "packet length %lu from tap", len);
if (th->rst) {
conn_event(c, conn, CLOSED);
@@ -2782,17 +2778,16 @@ void tcp_timer_handler(struct ctx *c, union epoll_ref ref)
tcp_timer_ctl(c, conn);
} else if (conn->flags & ACK_FROM_TAP_DUE) {
if (!(conn->events & ESTABLISHED)) {
- debug("TCP: index %u, handshake timeout", FLOW_IDX(conn));
+ flow_dbg(conn, "handshake timeout");
tcp_rst(c, conn);
} else if (CONN_HAS(conn, SOCK_FIN_SENT | TAP_FIN_ACKED)) {
- debug("TCP: index %u, FIN timeout", FLOW_IDX(conn));
+ flow_dbg(conn, "FIN timeout");
tcp_rst(c, conn);
} else if (conn->retrans == TCP_MAX_RETRANS) {
- debug("TCP: index %u, retransmissions count exceeded",
- FLOW_IDX(conn));
+ flow_dbg(conn, "retransmissions count exceeded");
tcp_rst(c, conn);
} else {
- debug("TCP: index %u, ACK timeout, retry", FLOW_IDX(conn));
+ flow_dbg(conn, "ACK timeout, retry");
conn->retrans++;
conn->seq_to_tap = conn->seq_ack_from_tap;
tcp_data_from_sock(c, conn);
@@ -2810,7 +2805,7 @@ void tcp_timer_handler(struct ctx *c, union epoll_ref ref)
*/
timerfd_settime(conn->timer, 0, &new, &old);
if (old.it_value.tv_sec == ACT_TIMEOUT) {
- debug("TCP: index %u, activity timeout", FLOW_IDX(conn));
+ flow_dbg(conn, "activity timeout");
tcp_rst(c, conn);
}
}
diff --git a/tcp_splice.c b/tcp_splice.c
index 212fe16..28b91e1 100644
--- a/tcp_splice.c
+++ b/tcp_splice.c
@@ -139,8 +139,7 @@ static int tcp_splice_epoll_ctl(const struct ctx *c,
if (epoll_ctl(c->epollfd, m, conn->s[0], &ev[0]) ||
epoll_ctl(c->epollfd, m, conn->s[1], &ev[1])) {
int ret = -errno;
- err("TCP (spliced): index %u, ERROR on epoll_ctl(): %s",
- FLOW_IDX(conn), strerror(errno));
+ flow_err(conn, "ERROR on epoll_ctl(): %s", strerror(errno));
return ret;
}
@@ -165,10 +164,9 @@ static void conn_flag_do(const struct ctx *c, struct tcp_splice_conn *conn,
return;
conn->flags &= flag;
- if (flag_index >= 0) {
- debug("TCP (spliced): index %u: %s dropped", FLOW_IDX(conn),
- tcp_splice_flag_str[flag_index]);
- }
+ if (flag_index >= 0)
+ flow_dbg(conn, "%s dropped",
+ tcp_splice_flag_str[flag_index]);
} else {
int flag_index = fls(flag);
@@ -176,10 +174,8 @@ static void conn_flag_do(const struct ctx *c, struct tcp_splice_conn *conn,
return;
conn->flags |= flag;
- if (flag_index >= 0) {
- debug("TCP (spliced): index %u: %s", FLOW_IDX(conn),
- tcp_splice_flag_str[flag_index]);
- }
+ if (flag_index >= 0)
+ flow_dbg(conn, "%s", tcp_splice_flag_str[flag_index]);
}
if (flag == CLOSING) {
@@ -190,8 +186,7 @@ static void conn_flag_do(const struct ctx *c, struct tcp_splice_conn *conn,
#define conn_flag(c, conn, flag) \
do { \
- trace("TCP (spliced): flag at %s:%i", \
- __func__, __LINE__); \
+ flow_trace(conn, "flag at %s:%i", __func__, __LINE__); \
conn_flag_do(c, conn, flag); \
} while (0)
@@ -211,10 +206,8 @@ static void conn_event_do(const struct ctx *c, struct tcp_splice_conn *conn,
return;
conn->events &= event;
- if (flag_index >= 0) {
- debug("TCP (spliced): index %u, ~%s", FLOW_IDX(conn),
- tcp_splice_event_str[flag_index]);
- }
+ if (flag_index >= 0)
+ flow_dbg(conn, "~%s", tcp_splice_event_str[flag_index]);
} else {
int flag_index = fls(event);
@@ -222,10 +215,8 @@ static void conn_event_do(const struct ctx *c, struct tcp_splice_conn *conn,
return;
conn->events |= event;
- if (flag_index >= 0) {
- debug("TCP (spliced): index %u, %s", FLOW_IDX(conn),
- tcp_splice_event_str[flag_index]);
- }
+ if (flag_index >= 0)
+ flow_dbg(conn, "%s", tcp_splice_event_str[flag_index]);
}
if (tcp_splice_epoll_ctl(c, conn))
@@ -234,8 +225,7 @@ static void conn_event_do(const struct ctx *c, struct tcp_splice_conn *conn,
#define conn_event(c, conn, event) \
do { \
- trace("TCP (spliced): event at %s:%i", \
- __func__, __LINE__); \
+ flow_trace(conn, "event at %s:%i",__func__, __LINE__); \
conn_event_do(c, conn, event); \
} while (0)
@@ -281,7 +271,7 @@ void tcp_splice_destroy(struct ctx *c, union flow *flow)
conn->events = SPLICE_CLOSED;
conn->flags = 0;
- debug("TCP (spliced): index %u, CLOSED", FLOW_IDX(conn));
+ flow_dbg(conn, "CLOSED");
flow_table_compact(c, flow);
}
@@ -314,16 +304,17 @@ static int tcp_splice_connect_finish(const struct ctx *c,
if (conn->pipe[side][0] < 0) {
if (pipe2(conn->pipe[side], O_NONBLOCK | O_CLOEXEC)) {
- err("TCP (spliced): cannot create %d->%d pipe: %s",
- side, !side, strerror(errno));
+ flow_err(conn, "cannot create %d->%d pipe: %s",
+ side, !side, strerror(errno));
conn_flag(c, conn, CLOSING);
return -EIO;
}
if (fcntl(conn->pipe[side][0], F_SETPIPE_SZ,
c->tcp.pipe_size)) {
- trace("TCP (spliced): cannot set %d->%d pipe size to %lu",
- side, !side, c->tcp.pipe_size);
+ flow_trace(conn,
+ "cannot set %d->%d pipe size to %lu",
+ side, !side, c->tcp.pipe_size);
}
}
}
@@ -363,8 +354,8 @@ static int tcp_splice_connect(const struct ctx *c, struct tcp_splice_conn *conn,
if (setsockopt(conn->s[1], SOL_TCP, TCP_QUICKACK,
&((int){ 1 }), sizeof(int))) {
- trace("TCP (spliced): failed to set TCP_QUICKACK on socket %i",
- conn->s[1]);
+ flow_trace(conn, "failed to set TCP_QUICKACK on socket %i",
+ conn->s[1]);
}
if (CONN_V6(conn)) {
@@ -475,7 +466,7 @@ bool tcp_splice_conn_from_sock(const struct ctx *c,
}
if (setsockopt(s, SOL_TCP, TCP_QUICKACK, &((int){ 1 }), sizeof(int)))
- trace("TCP (spliced): failed to set TCP_QUICKACK on %i", s);
+ flow_trace(conn, "failed to set TCP_QUICKACK on %i", s);
conn->f.type = FLOW_TCP_SPLICE;
conn->s[0] = s;
@@ -555,7 +546,7 @@ retry:
readlen = splice(conn->s[fromside], NULL,
conn->pipe[fromside][1], NULL, c->tcp.pipe_size,
SPLICE_F_MOVE | SPLICE_F_NONBLOCK);
- trace("TCP (spliced): %li from read-side call", readlen);
+ flow_trace(conn, "%li from read-side call", readlen);
if (readlen < 0) {
if (errno == EINTR)
goto retry;
@@ -581,8 +572,8 @@ eintr:
written = splice(conn->pipe[fromside][0], NULL,
conn->s[!fromside], NULL, to_write,
SPLICE_F_MOVE | more | SPLICE_F_NONBLOCK);
- trace("TCP (spliced): %li from write-side call (passed %lu)",
- written, to_write);
+ flow_trace(conn, "%li from write-side call (passed %lu)",
+ written, to_write);
/* Most common case: skip updating counters. */
if (readlen > 0 && readlen == written) {
@@ -794,8 +785,8 @@ void tcp_splice_timer(struct ctx *c, union flow *flow)
if ((conn->flags & set) && !(conn->flags & act)) {
if (setsockopt(conn->s[side], SOL_SOCKET, SO_RCVLOWAT,
&((int){ 1 }), sizeof(int))) {
- trace("TCP (spliced): can't set SO_RCVLOWAT on "
- "%i", conn->s[side]);
+ flow_trace(conn, "can't set SO_RCVLOWAT on %d",
+ conn->s[side]);
}
conn_flag(c, conn, ~set);
}
--
@@ -139,8 +139,7 @@ static int tcp_splice_epoll_ctl(const struct ctx *c,
if (epoll_ctl(c->epollfd, m, conn->s[0], &ev[0]) ||
epoll_ctl(c->epollfd, m, conn->s[1], &ev[1])) {
int ret = -errno;
- err("TCP (spliced): index %u, ERROR on epoll_ctl(): %s",
- FLOW_IDX(conn), strerror(errno));
+ flow_err(conn, "ERROR on epoll_ctl(): %s", strerror(errno));
return ret;
}
@@ -165,10 +164,9 @@ static void conn_flag_do(const struct ctx *c, struct tcp_splice_conn *conn,
return;
conn->flags &= flag;
- if (flag_index >= 0) {
- debug("TCP (spliced): index %u: %s dropped", FLOW_IDX(conn),
- tcp_splice_flag_str[flag_index]);
- }
+ if (flag_index >= 0)
+ flow_dbg(conn, "%s dropped",
+ tcp_splice_flag_str[flag_index]);
} else {
int flag_index = fls(flag);
@@ -176,10 +174,8 @@ static void conn_flag_do(const struct ctx *c, struct tcp_splice_conn *conn,
return;
conn->flags |= flag;
- if (flag_index >= 0) {
- debug("TCP (spliced): index %u: %s", FLOW_IDX(conn),
- tcp_splice_flag_str[flag_index]);
- }
+ if (flag_index >= 0)
+ flow_dbg(conn, "%s", tcp_splice_flag_str[flag_index]);
}
if (flag == CLOSING) {
@@ -190,8 +186,7 @@ static void conn_flag_do(const struct ctx *c, struct tcp_splice_conn *conn,
#define conn_flag(c, conn, flag) \
do { \
- trace("TCP (spliced): flag at %s:%i", \
- __func__, __LINE__); \
+ flow_trace(conn, "flag at %s:%i", __func__, __LINE__); \
conn_flag_do(c, conn, flag); \
} while (0)
@@ -211,10 +206,8 @@ static void conn_event_do(const struct ctx *c, struct tcp_splice_conn *conn,
return;
conn->events &= event;
- if (flag_index >= 0) {
- debug("TCP (spliced): index %u, ~%s", FLOW_IDX(conn),
- tcp_splice_event_str[flag_index]);
- }
+ if (flag_index >= 0)
+ flow_dbg(conn, "~%s", tcp_splice_event_str[flag_index]);
} else {
int flag_index = fls(event);
@@ -222,10 +215,8 @@ static void conn_event_do(const struct ctx *c, struct tcp_splice_conn *conn,
return;
conn->events |= event;
- if (flag_index >= 0) {
- debug("TCP (spliced): index %u, %s", FLOW_IDX(conn),
- tcp_splice_event_str[flag_index]);
- }
+ if (flag_index >= 0)
+ flow_dbg(conn, "%s", tcp_splice_event_str[flag_index]);
}
if (tcp_splice_epoll_ctl(c, conn))
@@ -234,8 +225,7 @@ static void conn_event_do(const struct ctx *c, struct tcp_splice_conn *conn,
#define conn_event(c, conn, event) \
do { \
- trace("TCP (spliced): event at %s:%i", \
- __func__, __LINE__); \
+ flow_trace(conn, "event at %s:%i",__func__, __LINE__); \
conn_event_do(c, conn, event); \
} while (0)
@@ -281,7 +271,7 @@ void tcp_splice_destroy(struct ctx *c, union flow *flow)
conn->events = SPLICE_CLOSED;
conn->flags = 0;
- debug("TCP (spliced): index %u, CLOSED", FLOW_IDX(conn));
+ flow_dbg(conn, "CLOSED");
flow_table_compact(c, flow);
}
@@ -314,16 +304,17 @@ static int tcp_splice_connect_finish(const struct ctx *c,
if (conn->pipe[side][0] < 0) {
if (pipe2(conn->pipe[side], O_NONBLOCK | O_CLOEXEC)) {
- err("TCP (spliced): cannot create %d->%d pipe: %s",
- side, !side, strerror(errno));
+ flow_err(conn, "cannot create %d->%d pipe: %s",
+ side, !side, strerror(errno));
conn_flag(c, conn, CLOSING);
return -EIO;
}
if (fcntl(conn->pipe[side][0], F_SETPIPE_SZ,
c->tcp.pipe_size)) {
- trace("TCP (spliced): cannot set %d->%d pipe size to %lu",
- side, !side, c->tcp.pipe_size);
+ flow_trace(conn,
+ "cannot set %d->%d pipe size to %lu",
+ side, !side, c->tcp.pipe_size);
}
}
}
@@ -363,8 +354,8 @@ static int tcp_splice_connect(const struct ctx *c, struct tcp_splice_conn *conn,
if (setsockopt(conn->s[1], SOL_TCP, TCP_QUICKACK,
&((int){ 1 }), sizeof(int))) {
- trace("TCP (spliced): failed to set TCP_QUICKACK on socket %i",
- conn->s[1]);
+ flow_trace(conn, "failed to set TCP_QUICKACK on socket %i",
+ conn->s[1]);
}
if (CONN_V6(conn)) {
@@ -475,7 +466,7 @@ bool tcp_splice_conn_from_sock(const struct ctx *c,
}
if (setsockopt(s, SOL_TCP, TCP_QUICKACK, &((int){ 1 }), sizeof(int)))
- trace("TCP (spliced): failed to set TCP_QUICKACK on %i", s);
+ flow_trace(conn, "failed to set TCP_QUICKACK on %i", s);
conn->f.type = FLOW_TCP_SPLICE;
conn->s[0] = s;
@@ -555,7 +546,7 @@ retry:
readlen = splice(conn->s[fromside], NULL,
conn->pipe[fromside][1], NULL, c->tcp.pipe_size,
SPLICE_F_MOVE | SPLICE_F_NONBLOCK);
- trace("TCP (spliced): %li from read-side call", readlen);
+ flow_trace(conn, "%li from read-side call", readlen);
if (readlen < 0) {
if (errno == EINTR)
goto retry;
@@ -581,8 +572,8 @@ eintr:
written = splice(conn->pipe[fromside][0], NULL,
conn->s[!fromside], NULL, to_write,
SPLICE_F_MOVE | more | SPLICE_F_NONBLOCK);
- trace("TCP (spliced): %li from write-side call (passed %lu)",
- written, to_write);
+ flow_trace(conn, "%li from write-side call (passed %lu)",
+ written, to_write);
/* Most common case: skip updating counters. */
if (readlen > 0 && readlen == written) {
@@ -794,8 +785,8 @@ void tcp_splice_timer(struct ctx *c, union flow *flow)
if ((conn->flags & set) && !(conn->flags & act)) {
if (setsockopt(conn->s[side], SOL_SOCKET, SO_RCVLOWAT,
&((int){ 1 }), sizeof(int))) {
- trace("TCP (spliced): can't set SO_RCVLOWAT on "
- "%i", conn->s[side]);
+ flow_trace(conn, "can't set SO_RCVLOWAT on %d",
+ conn->s[side]);
}
conn_flag(c, conn, ~set);
}
--
2.43.0
next prev parent reply other threads:[~2023-11-30 2:02 UTC|newest]
Thread overview: 25+ messages / expand[flat|nested] mbox.gz Atom feed top
2023-11-30 2:02 [PATCH v3 00/16] Introduce unified flow table, first steps David Gibson
2023-11-30 2:02 ` [PATCH v3 01/16] treewide: Add messages to static_assert() calls David Gibson
2023-11-30 2:02 ` [PATCH v3 02/16] flow, tcp: Generalise connection types David Gibson
2023-11-30 2:02 ` [PATCH v3 03/16] flow, tcp: Move TCP connection table to unified flow table David Gibson
2023-11-30 2:02 ` [PATCH v3 04/16] flow, tcp: Consolidate flow pointer<->index helpers David Gibson
2023-11-30 2:02 ` [PATCH v3 05/16] util: MAX_FROM_BITS() should be unsigned David Gibson
2023-11-30 2:02 ` [PATCH v3 06/16] flow: Make unified version of flow table compaction David Gibson
2023-11-30 2:02 ` David Gibson [this message]
2023-11-30 2:02 ` [PATCH v3 08/16] flow: Introduce 'sidx' type to represent one side of one flow David Gibson
2023-12-02 4:35 ` Stefano Brivio
2023-11-30 2:02 ` [PATCH v3 09/16] tcp: Remove unneccessary bounds check in tcp_timer_handler() David Gibson
2023-11-30 2:02 ` [PATCH v3 10/16] flow,tcp: Generalise TCP epoll_ref to generic flows David Gibson
2023-11-30 2:02 ` [PATCH v3 11/16] tcp_splice: Use unsigned to represent side David Gibson
2023-11-30 2:02 ` [PATCH v3 12/16] flow,tcp: Use epoll_ref type including flow and side David Gibson
2023-11-30 2:02 ` [PATCH v3 13/16] test: Avoid hitting guestfish command length limits David Gibson
2023-11-30 2:02 ` [PATCH v3 14/16] pif: Add helpers to get the name of a pif David Gibson
2023-11-30 12:45 ` Stefano Brivio
2023-12-01 0:08 ` David Gibson
2023-11-30 2:02 ` [PATCH v3 15/16] tcp: "TCP" hash secret doesn't need to be TCP specific David Gibson
2023-11-30 2:02 ` [PATCH v3 16/16] tcp: Don't defer hash table removal David Gibson
2023-11-30 12:45 ` Stefano Brivio
2023-12-01 0:07 ` David Gibson
2023-12-02 4:34 ` Stefano Brivio
2023-12-04 0:43 ` David Gibson
2023-12-04 9:54 ` [PATCH v3 00/16] Introduce unified flow table, first steps Stefano Brivio
Reply instructions:
You may reply publicly to this message via plain-text email
using any one of the following methods:
* Save the following mbox file, import it into your mail client,
and reply-to-all from there: mbox
Avoid top-posting and favor interleaved quoting:
https://en.wikipedia.org/wiki/Posting_style#Interleaved_style
* Reply using the --to, --cc, and --in-reply-to
switches of git-send-email(1):
git send-email \
--in-reply-to=20231130020222.4056647-8-david@gibson.dropbear.id.au \
--to=david@gibson.dropbear.id.au \
--cc=passt-dev@passt.top \
--cc=sbrivio@redhat.com \
/path/to/YOUR_REPLY
https://kernel.org/pub/software/scm/git/docs/git-send-email.html
* If your mail client supports setting the In-Reply-To header
via mailto: links, try the mailto: link
Be sure your reply has a Subject: header at the top and a blank line
before the message body.
Code repositories for project(s) associated with this public inbox
https://passt.top/passt
This is a public inbox, see mirroring instructions
for how to clone and mirror all data and code used for this inbox;
as well as URLs for IMAP folder(s).