On Wed, Mar 12, 2025 at 09:39:16PM +0100, Stefano Brivio wrote:On Wed, 12 Mar 2025 18:00:04 +1100 David Gibson <david(a)gibson.dropbear.id.au> wrote:I suppose that's true...A number of places in the TCP code use general logging functions, instead of the flow specific ones. That includes a few older ones as well as many places in the new migration code. Thus they either don't identify which flow the problem happened on, or identify it in a non-standard way. Convert many of these to use the existing flow specific helpers. Signed-off-by: David Gibson <david(a)gibson.dropbear.id.au> --- flow.c | 16 ++-- tcp.c | 254 +++++++++++++++++++++++++++---------------------- tcp.h | 1 - tcp_buf.c | 4 +- tcp_internal.h | 1 + tcp_vu.c | 2 +- 6 files changed, 150 insertions(+), 128 deletions(-) diff --git a/flow.c b/flow.c index 749c4984..99b1a1df 100644 --- a/flow.c +++ b/flow.c @@ -1019,8 +1019,8 @@ int flow_migrate_source(struct ctx *c, const struct migrate_stage *stage, foreach_established_tcp_flow(flow) { rc = tcp_flow_migrate_source(fd, &flow->tcp); if (rc) { - err("Can't send data, flow %u: %s", FLOW_IDX(flow), - strerror_(-rc)); + flow_err(flow, "Can't send data: %s", + strerror_(-rc)); if (!first) die("Inconsistent migration state, exiting"); @@ -1046,8 +1046,8 @@ int flow_migrate_source(struct ctx *c, const struct migrate_stage *stage, foreach_established_tcp_flow(flow) { rc = tcp_flow_migrate_source_ext(fd, &flow->tcp); if (rc) { - err("Extended data for flow %u: %s", FLOW_IDX(flow), - strerror_(-rc)); + flow_err(flow, "Can't send extended data: %s", + strerror_(-rc)); if (rc == -EIO) die("Inconsistent migration state, exiting"); @@ -1092,8 +1092,8 @@ int flow_migrate_target(struct ctx *c, const struct migrate_stage *stage, for (i = 0; i < count; i++) { rc = tcp_flow_migrate_target(c, fd); if (rc) { - debug("Migration data failure at flow %u: %s, abort", - i, strerror_(-rc)); + flow_dbg(FLOW(i), "Migration data failure, abort: %s", + strerror_(-rc));For these, I actually used a generic print on purpose, because in some sense they're not really "flows" yet.It doesn't make sense to extend the same reasoning to the prints in flow_migrate_source() as I did, though, and regardless of my reasoning, I guess it's anyway more reasonable/consistent to use flow_dbg()....but that's also my position.Fixedreturn -rc; } } @@ -1103,8 +1103,8 @@ int flow_migrate_target(struct ctx *c, const struct migrate_stage *stage, for (i = 0; i < count; i++) { rc = tcp_flow_migrate_target_ext(c, &flowtab[i].tcp, fd); if (rc) { - debug("Migration data failure at flow %u: %s, abort", - i, strerror_(-rc)); + flow_dbg(FLOW(i),"Migration data failure, abort: %s",Missing whitespace.Oops.+ strerror_(-rc)); return -rc; } } diff --git a/tcp.c b/tcp.c index 32a08bd1..6acaf4c3 100644 --- a/tcp.c +++ b/tcp.c @@ -434,19 +434,20 @@ static struct tcp_tap_conn *conn_at_sidx(flow_sidx_t sidx) } /** - * tcp_set_peek_offset() - Set SO_PEEK_OFF offset on a socket if supported - * @s: Socket to update + * tcp_set_peek_offset() - Set SO_PEEK_OFF offset on connection if supported + * @conn: Pointer to the TCP connection structure * @offset: Offset in bytes * * Return: -1 when it fails, 0 otherwise. */ -int tcp_set_peek_offset(int s, int offset) +int tcp_set_peek_offset(const struct tcp_tap_conn *conn, int offset) { if (!peek_offset_cap) return 0; - if (setsockopt(s, SOL_SOCKET, SO_PEEK_OFF, &offset, sizeof(offset))) { - err("Failed to set SO_PEEK_OFF to %i in socket %i", offset, s); + if (setsockopt(conn->sock, SOL_SOCKET, SO_PEEK_OFF, + &offset, sizeof(offset))) { + flow_perror(conn, "Failed to set SO_PEEK_OFF to %i", offset); return -1; } return 0; @@ -1757,7 +1758,7 @@ static int tcp_data_from_tap(const struct ctx *c, struct tcp_tap_conn *conn, "fast re-transmit, ACK: %u, previous sequence: %u", max_ack_seq, conn->seq_to_tap); conn->seq_to_tap = max_ack_seq; - if (tcp_set_peek_offset(conn->sock, 0)) { + if (tcp_set_peek_offset(conn, 0)) { tcp_rst(c, conn); return -1; } @@ -1854,7 +1855,7 @@ static void tcp_conn_from_sock_finish(const struct ctx *c, conn->seq_ack_to_tap = conn->seq_from_tap; conn_event(c, conn, ESTABLISHED); - if (tcp_set_peek_offset(conn->sock, 0)) { + if (tcp_set_peek_offset(conn, 0)) { tcp_rst(c, conn); return; } @@ -2022,7 +2023,7 @@ int tcp_tap_handler(const struct ctx *c, uint8_t pif, sa_family_t af, goto reset; conn_event(c, conn, ESTABLISHED); - if (tcp_set_peek_offset(conn->sock, 0)) + if (tcp_set_peek_offset(conn, 0)) goto reset; if (th->fin) { @@ -2286,7 +2287,7 @@ void tcp_timer_handler(const struct ctx *c, union epoll_ref ref) conn->seq_to_tap = conn->seq_ack_from_tap; if (!conn->wnd_from_tap) conn->wnd_from_tap = 1; /* Zero-window probe */ - if (tcp_set_peek_offset(conn->sock, 0)) { + if (tcp_set_peek_offset(conn, 0)) { tcp_rst(c, conn); } else { tcp_data_from_sock(c, conn); @@ -2810,20 +2811,21 @@ int tcp_flow_repair_off(struct ctx *c, const struct tcp_tap_conn *conn) /** * tcp_flow_dump_tinfo() - Dump window scale, tcpi_state, tcpi_options - * @c: Execution context - * @t: Extended migration data + * @conn: Pointer to the TCP connection structure +q * @t: Extended migration dataStray 'q' (I thought you used Emacs :D).I think so, yes. This is an err() level, not a dbg() level message, so its primary audience is a general end user, not someone specifically debugging. For that purpose the flow number (which links it to details of the flow elsewhere in the log) is more useful that the socket fd which is essentially invisible. In this case the fd is also not particularly necessary even if you are correlating with an strace, since the getsockopt() failure will be right there in the trace with the error and the fd.* * Return: 0 on success, negative error code on failure */ -static int tcp_flow_dump_tinfo(int s, struct tcp_tap_transfer_ext *t) +static int tcp_flow_dump_tinfo(const struct tcp_tap_conn *conn, + struct tcp_tap_transfer_ext *t) { struct tcp_info tinfo; socklen_t sl; sl = sizeof(tinfo); - if (getsockopt(s, SOL_TCP, TCP_INFO, &tinfo, &sl)) { + if (getsockopt(conn->sock, SOL_TCP, TCP_INFO, &tinfo, &sl)) { int rc = -errno; - err_perror("Querying TCP_INFO, socket %i", s); + flow_perror(conn, "Querying TCP_INFO");Hmm... do we really want the flow in these cases, or does the socket number make more sense? If you're stracing in parallel the socket number is more convenient.Ditto.return rc; } @@ -2837,18 +2839,19 @@ static int tcp_flow_dump_tinfo(int s, struct tcp_tap_transfer_ext *t) /** * tcp_flow_dump_mss() - Dump MSS clamp (not current MSS) via TCP_MAXSEG - * @c: Execution context + * @conn: Pointer to the TCP connection structure * @t: Extended migration data * * Return: 0 on success, negative error code on failure */ -static int tcp_flow_dump_mss(int s, struct tcp_tap_transfer_ext *t) +static int tcp_flow_dump_mss(const struct tcp_tap_conn *conn, + struct tcp_tap_transfer_ext *t) { socklen_t sl = sizeof(t->mss); - if (getsockopt(s, SOL_TCP, TCP_MAXSEG, &t->mss, &sl)) { + if (getsockopt(conn->sock, SOL_TCP, TCP_MAXSEG, &t->mss, &sl)) { int rc = -errno; - err_perror("Getting MSS, socket %i", s); + flow_perror(conn, "Getting MSS");Same here.Ditto.return rc; } @@ -2857,19 +2860,20 @@ static int tcp_flow_dump_mss(int s, struct tcp_tap_transfer_ext *t) /** * tcp_flow_dump_wnd() - Dump current tcp_repair_window parameters - * @c: Execution context + * @conn: Pointer to the TCP connection structure * @t: Extended migration data * * Return: 0 on success, negative error code on failure */ -static int tcp_flow_dump_wnd(int s, struct tcp_tap_transfer_ext *t) +static int tcp_flow_dump_wnd(const struct tcp_tap_conn *conn, + struct tcp_tap_transfer_ext *t) { struct tcp_repair_window wnd; socklen_t sl = sizeof(wnd); - if (getsockopt(s, IPPROTO_TCP, TCP_REPAIR_WINDOW, &wnd, &sl)) { + if (getsockopt(conn->sock, IPPROTO_TCP, TCP_REPAIR_WINDOW, &wnd, &sl)) { int rc = -errno; - err_perror("Getting window repair data, socket %i", s); + flow_perror(conn, "Getting window repair data");And here.Dittoreturn rc; } @@ -2893,12 +2897,13 @@ static int tcp_flow_dump_wnd(int s, struct tcp_tap_transfer_ext *t) /** * tcp_flow_repair_wnd() - Restore window parameters from extended data - * @c: Execution context + * @conn: Pointer to the TCP connection structure * @t: Extended migration data * * Return: 0 on success, negative error code on failure */ -static int tcp_flow_repair_wnd(int s, const struct tcp_tap_transfer_ext *t) +static int tcp_flow_repair_wnd(const struct tcp_tap_conn *conn, + const struct tcp_tap_transfer_ext *t) { struct tcp_repair_window wnd; @@ -2908,9 +2913,10 @@ static int tcp_flow_repair_wnd(int s, const struct tcp_tap_transfer_ext *t) wnd.rcv_wnd = t->rcv_wnd; wnd.rcv_wup = t->rcv_wup; - if (setsockopt(s, IPPROTO_TCP, TCP_REPAIR_WINDOW, &wnd, sizeof(wnd))) { + if (setsockopt(conn->sock, IPPROTO_TCP, TCP_REPAIR_WINDOW, + &wnd, sizeof(wnd))) { int rc = -errno; - err_perror("Setting window data, socket %i", s); + flow_perror(conn, "Setting window data");And here, and in most places below.Well, if we have the flow number, we can rebuild the socket number, but... does it make sense?For error messages, I think so. The case is muddier for debug or trace messages.Or should we rather have the socket number printed by flow_*() helpers? It might get annoyingly verbose, though.It might, plus the socket is specific to the TCP structure, whereas the flow logging helpers are not.No further comments, other than a concern about the general validity of this type of change.-- David Gibson (he or they) | I'll have my music baroque, and my code david AT gibson.dropbear.id.au | minimalist, thank you, not the other way | around. http://www.ozlabs.org/~dgibson