Re: [PATCH] tcp, flow: Better use flow specific logging heleprs

[Stefano Brivio <sbrivio@redhat.com>]

On Wed, 12 Mar 2025 18:00:04 +1100
David Gibson <david@gibson.dropbear.id.au> wrote:

> 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@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().

>  			return -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.

> +				 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 data

Stray 'q' (I thought you used Emacs :D).

>   *
>   * 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.

>  		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.

>  		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.

>  		return 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?

Or should we rather have the socket number printed by flow_*() helpers?
It might get annoyingly verbose, though.

No further comments, other than a concern about the general validity of
this type of change.

-- 
Stefano