From mboxrd@z Thu Jan 1 00:00:00 1970 Authentication-Results: passt.top; dmarc=none (p=none dis=none) header.from=gibson.dropbear.id.au Authentication-Results: passt.top; dkim=pass (2048-bit key; secure) header.d=gibson.dropbear.id.au header.i=@gibson.dropbear.id.au header.a=rsa-sha256 header.s=202502 header.b=U9yz3l4w; dkim-atps=neutral Received: from mail.ozlabs.org (gandalf.ozlabs.org [150.107.74.76]) by passt.top (Postfix) with ESMTPS id 410865A026F for ; Thu, 13 Mar 2025 03:56:41 +0100 (CET) DKIM-Signature: v=1; a=rsa-sha256; c=relaxed/relaxed; d=gibson.dropbear.id.au; s=202502; t=1741834579; bh=E0T6fGe7Z1lAsLNvc3VO5+R18CcpWpNOIOF17pwzZi8=; h=Date:From:To:Cc:Subject:References:In-Reply-To:From; b=U9yz3l4wjAPWK26Sf/6dH+F41RlmO2mM4znEwi6UPGObwxqEEKHNJ7Jcve8o+A33M J5upyPlTJwMMAN1N1CMtQ78YDaN4tqw8vsKYiiPIUFgmN3dYiVdaZH+7Vvt6oj27+w iRvUmpwtPcInHZ8ejqS9SYDpCltLWFD6FzT3n/xVCynOJWwH5jlgtxjSi5OxczfC1y 814L+QnTOjiJu65qxlur24IbiREFP8FgI8OUdfEM/7h6NSPXs+zGtuDGTF34ti8DYk v2pM4pFkulVp2tk3hMvVWfl7Xqy4KybjJDd95/8hyjZTFUYZudcqmLzihuMBcAftEF LyRQFihqgCtYg== Received: by gandalf.ozlabs.org (Postfix, from userid 1007) id 4ZCsZq2r95z4x04; Thu, 13 Mar 2025 13:56:19 +1100 (AEDT) Date: Thu, 13 Mar 2025 13:55:07 +1100 From: David Gibson To: Stefano Brivio Subject: Re: [PATCH] tcp, flow: Better use flow specific logging heleprs Message-ID: References: <20250312070004.4137684-1-david@gibson.dropbear.id.au> <20250312213916.141a905a@elisabeth> MIME-Version: 1.0 Content-Type: multipart/signed; micalg=pgp-sha256; protocol="application/pgp-signature"; boundary="6KbI5jWjofA6ues7" Content-Disposition: inline In-Reply-To: <20250312213916.141a905a@elisabeth> Message-ID-Hash: CTOIDJ32VXNSQK4XQKYWPMATOGXMNQB4 X-Message-ID-Hash: CTOIDJ32VXNSQK4XQKYWPMATOGXMNQB4 X-MailFrom: dgibson@gandalf.ozlabs.org X-Mailman-Rule-Misses: dmarc-mitigation; no-senders; approved; emergency; loop; banned-address; member-moderation; nonmember-moderation; administrivia; implicit-dest; max-recipients; max-size; news-moderation; no-subject; digests; suspicious-header CC: passt-dev@passt.top X-Mailman-Version: 3.3.8 Precedence: list List-Id: Development discussion and patches for passt Archived-At: Archived-At: List-Archive: List-Archive: List-Help: List-Owner: List-Post: List-Subscribe: List-Unsubscribe: --6KbI5jWjofA6ues7 Content-Type: text/plain; charset=us-ascii Content-Disposition: inline Content-Transfer-Encoding: quoted-printable On Wed, Mar 12, 2025 at 09:39:16PM +0100, Stefano Brivio wrote: > On Wed, 12 Mar 2025 18:00:04 +1100 > David Gibson wrote: >=20 > > A number of places in the TCP code use general logging functions, inste= ad > > of the flow specific ones. That includes a few older ones as well as m= any > > 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. > >=20 > > Convert many of these to use the existing flow specific helpers. > >=20 > > Signed-off-by: David Gibson > > --- > > 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(-) > >=20 > > 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 stru= ct migrate_stage *stage, > > foreach_established_tcp_flow(flow) { > > rc =3D 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"); > > =20 > > @@ -1046,8 +1046,8 @@ int flow_migrate_source(struct ctx *c, const stru= ct migrate_stage *stage, > > foreach_established_tcp_flow(flow) { > > rc =3D 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)); > > =20 > > if (rc =3D=3D -EIO) > > die("Inconsistent migration state, exiting"); > > @@ -1092,8 +1092,8 @@ int flow_migrate_target(struct ctx *c, const stru= ct migrate_stage *stage, > > for (i =3D 0; i < count; i++) { > > rc =3D 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)); >=20 > For these, I actually used a generic print on purpose, because in some > sense they're not really "flows" yet. I suppose that's true... > 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(). =2E..but that's also my position. >=20 > > return -rc; > > } > > } > > @@ -1103,8 +1103,8 @@ int flow_migrate_target(struct ctx *c, const stru= ct migrate_stage *stage, > > for (i =3D 0; i < count; i++) { > > rc =3D 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", >=20 > Missing whitespace. Fixed > > + 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_sid= x_t sidx) > > } > > =20 > > /** > > - * tcp_set_peek_offset() - Set SO_PEEK_OFF offset on a socket if suppo= rted > > - * @s: Socket to update > > + * tcp_set_peek_offset() - Set SO_PEEK_OFF offset on connection if sup= ported > > + * @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; > > =20 > > - 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 =3D 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 struc= t ctx *c, > > conn->seq_ack_to_tap =3D conn->seq_from_tap; > > =20 > > 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; > > =20 > > conn_event(c, conn, ESTABLISHED); > > - if (tcp_set_peek_offset(conn->sock, 0)) > > + if (tcp_set_peek_offset(conn, 0)) > > goto reset; > > =20 > > if (th->fin) { > > @@ -2286,7 +2287,7 @@ void tcp_timer_handler(const struct ctx *c, union= epoll_ref ref) > > conn->seq_to_tap =3D conn->seq_ack_from_tap; > > if (!conn->wnd_from_tap) > > conn->wnd_from_tap =3D 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 st= ruct tcp_tap_conn *conn) > > =20 > > /** > > * 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 >=20 > Stray 'q' (I thought you used Emacs :D). Oops. > > * > > * 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; > > =20 > > sl =3D sizeof(tinfo); > > - if (getsockopt(s, SOL_TCP, TCP_INFO, &tinfo, &sl)) { > > + if (getsockopt(conn->sock, SOL_TCP, TCP_INFO, &tinfo, &sl)) { > > int rc =3D -errno; > > - err_perror("Querying TCP_INFO, socket %i", s); > > + flow_perror(conn, "Querying TCP_INFO"); >=20 > 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. 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. >=20 > > return rc; > > } > > =20 > > @@ -2837,18 +2839,19 @@ static int tcp_flow_dump_tinfo(int s, struct tc= p_tap_transfer_ext *t) > > =20 > > /** > > * tcp_flow_dump_mss() - Dump MSS clamp (not current MSS) via TCP_MAXS= EG > > - * @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 =3D sizeof(t->mss); > > =20 > > - if (getsockopt(s, SOL_TCP, TCP_MAXSEG, &t->mss, &sl)) { > > + if (getsockopt(conn->sock, SOL_TCP, TCP_MAXSEG, &t->mss, &sl)) { > > int rc =3D -errno; > > - err_perror("Getting MSS, socket %i", s); > > + flow_perror(conn, "Getting MSS"); >=20 > Same here. Ditto. > > return rc; > > } > > =20 > > @@ -2857,19 +2860,20 @@ static int tcp_flow_dump_mss(int s, struct tcp_= tap_transfer_ext *t) > > =20 > > /** > > * 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 =3D sizeof(wnd); > > =20 > > - if (getsockopt(s, IPPROTO_TCP, TCP_REPAIR_WINDOW, &wnd, &sl)) { > > + if (getsockopt(conn->sock, IPPROTO_TCP, TCP_REPAIR_WINDOW, &wnd, &sl)= ) { > > int rc =3D -errno; > > - err_perror("Getting window repair data, socket %i", s); > > + flow_perror(conn, "Getting window repair data"); >=20 > And here. Ditto. > > return rc; > > } > > =20 > > @@ -2893,12 +2897,13 @@ static int tcp_flow_dump_wnd(int s, struct tcp_= tap_transfer_ext *t) > > =20 > > /** > > * 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_ex= t *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; > > =20 > > @@ -2908,9 +2913,10 @@ static int tcp_flow_repair_wnd(int s, const stru= ct tcp_tap_transfer_ext *t) > > wnd.rcv_wnd =3D t->rcv_wnd; > > wnd.rcv_wup =3D t->rcv_wup; > > =20 > > - 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 =3D -errno; > > - err_perror("Setting window data, socket %i", s); > > + flow_perror(conn, "Setting window data"); >=20 > And here, and in most places below. Ditto > 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. >=20 > No further comments, other than a concern about the general validity of > this type of change. >=20 --=20 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 --6KbI5jWjofA6ues7 Content-Type: application/pgp-signature; name=signature.asc -----BEGIN PGP SIGNATURE----- iQIzBAEBCAAdFiEEO+dNsU4E3yXUXRK2zQJF27ox2GcFAmfSSP0ACgkQzQJF27ox 2Gc5bRAAl6zjr09te0uWGS25KqQBoVIup1lo+U7BO4mkKQzkhjZof7DHfrV9n9MY SLbXgXijv9ZHIh5Uyy1x48YCV/alitZg0/e58ZiVEqEQbI4685aw7Wk6wpbEXQ0D mDCkYiOTHpttlqq2kEi5UoOQ5ZvF9yEbpDi+FEN09wGs2rd75VnrLEWu+USHIQFw ay42MLgk3yx7zVvn7b1mFTLQ2Thj6aFYds0OFuSBo8oVCc3wIrEPqFErVaRo4K6j d53dCt3EaBoS4U9xRYSDut5znaVr3PkMKJiJUoXQHFk89sdaaytZ32m/KwauWhxl ggkGU/5lCNiO6LCHo6Z0B6DPNp2bh98BUoGVJ8TqaLDXRuwY0B6LW1e21ZMLJoRk jRplo7if+phmTBF5UNxe/Y4Yp+qdONLGoL9BzChaO/ATgJyXpQY4T577une/wRr3 2kgtpMXEJffrmFb0x6+Imd9Dw+PCodtoEePFu5FG23hfa2EwpislvsjU2mUAaua7 GuUtvrpy40e4YVBwUcoqajqWpbVVO4Eqr6dRWWTiJfCYPLH2awm6QQLy5PP2lkWI cGahJMl7YsF+YS1OwG2gcLuhD2eTtPI3khiql4EGtcIIsJduJP3DMr1DvuIbc84J H0rDkGAPzn3A+xRccTfbBwbeyHUeTCNqLjjUGLdBkJNCkcf91h8= =77RZ -----END PGP SIGNATURE----- --6KbI5jWjofA6ues7--