From mboxrd@z Thu Jan 1 00:00:00 1970 Authentication-Results: passt.top; dmarc=pass (p=none dis=none) header.from=redhat.com Authentication-Results: passt.top; dkim=pass (1024-bit key; unprotected) header.d=redhat.com header.i=@redhat.com header.a=rsa-sha256 header.s=mimecast20190719 header.b=WNy3WH0p; dkim-atps=neutral Received: from us-smtp-delivery-124.mimecast.com (us-smtp-delivery-124.mimecast.com [170.10.133.124]) by passt.top (Postfix) with ESMTPS id 9EC055A0271 for ; Wed, 12 Mar 2025 21:39:22 +0100 (CET) DKIM-Signature: v=1; a=rsa-sha256; c=relaxed/relaxed; d=redhat.com; s=mimecast20190719; t=1741811961; h=from:from:reply-to:subject:subject:date:date:message-id:message-id: to:to:cc:cc:mime-version:mime-version:content-type:content-type: content-transfer-encoding:content-transfer-encoding: in-reply-to:in-reply-to:references:references; bh=ilZhmgN5bF1QqW+6Sgx6k6J+Kc/rmXdiFoT7auTjyD4=; b=WNy3WH0pXmUP935Li4/IgwZKhWB6HjpRoUXDFWnrS9Y4TAGOMAt0SlRAW/fBiM6MtarE9x P6nqDsMQSP+azaBlLKNuGq4nRlrQ4X3sohCIbebZ6Vi9Zz+LtM0oW8MBmIYkcDpnpQ/j6p xkYyZTvUtQ3CfY+tyrMOubHQxS4eCEA= Received: from mail-wm1-f70.google.com (mail-wm1-f70.google.com [209.85.128.70]) by relay.mimecast.com with ESMTP with STARTTLS (version=TLSv1.3, cipher=TLS_AES_256_GCM_SHA384) id us-mta-350-h9D3T7USMtSX3H7NENftww-1; Wed, 12 Mar 2025 16:39:20 -0400 X-MC-Unique: h9D3T7USMtSX3H7NENftww-1 X-Mimecast-MFC-AGG-ID: h9D3T7USMtSX3H7NENftww_1741811959 Received: by mail-wm1-f70.google.com with SMTP id 5b1f17b1804b1-4388eee7073so6263535e9.0 for ; Wed, 12 Mar 2025 13:39:19 -0700 (PDT) X-Google-DKIM-Signature: v=1; a=rsa-sha256; c=relaxed/relaxed; d=1e100.net; s=20230601; t=1741811958; x=1742416758; h=content-transfer-encoding:mime-version:organization:references :in-reply-to:message-id:subject:cc:to:from:date:x-gm-message-state :from:to:cc:subject:date:message-id:reply-to; bh=ilZhmgN5bF1QqW+6Sgx6k6J+Kc/rmXdiFoT7auTjyD4=; b=gWY13OuNnQNsO/Xztv37/OLbEGvUcKfwYBSDCDZwC1erRd2jAfAfTkkHSQiZjiUAVJ R4igOH686MVb4sX+FdFmjhGSImwtSHsuox71tuWvdqtA5bpKBD3Z+uOzYvtWrZH0pt6B t93R1EZmVBUXD3NPF8Sk6TWJighV/TU7E1GjbKhO3iOI11q8xQEGj8ZU3eut4FFWVrAF C6ZHl1J37W2ADW5eHJEeF5QPmYtX8SV/rWu5Lu/0j76hwz8BbPJyEs8IAGKI2oyR4na/ QM694FnNmYmPBvdDgEGczCcsAoXlh2LNvHnkw/3vviu2izQREu9eVHR/Xrt+crDP7TlP 3N8g== X-Gm-Message-State: AOJu0YxDxAnlDWn4sRfD3LtPceU0d1erLDI/aGGNM/PBO/sMwB8aDgJV veLGge5IksoZi9ahMNfyWMHbCR3GnrGAWHxFm1bSnViveBNaIZBuWcBmrCXZwAKDr+l6UluQkxx qBoGLpWHcEoGM64/mAA0i0HyyrMQedkDcY1djheKhtayFF1+oIaLWZfyJcw== X-Gm-Gg: ASbGnctgmiwNXHyDR/GQ56l0XAH4p8z2ei3vpt/DXaRdOVFsQwGEquiZLY2RB/7TB39 4/flRqtTj/LtULQIDw2SoVX/5go9afoQ/9PkhZjKETio5mde8TsNyuhHTE+xLKZ3xmmw0rwI7za eVScC6aJo8q2sH4ZKrOS0nchceUEThdr8axzFHSSLJ1dyCRRTaU4R7xwfI+53QISTi4cBd8FsNF lUe/Q3fQQ9wRBN5XwMx0c4+Hgkf78cLv3I7Cf/6iZlhIdEbc2CAEVliIFXJg2dOwACgJlZtuX0A pnmgfZLd7zIJCuPt7AHvFBSkaxQ= X-Received: by 2002:a05:600c:1986:b0:43c:f3e1:a729 with SMTP id 5b1f17b1804b1-43d17dbfb07mr350845e9.12.1741811958433; Wed, 12 Mar 2025 13:39:18 -0700 (PDT) X-Google-Smtp-Source: AGHT+IHQAz7wRsQCNV++XSA5QAxVRyazGmg0JbYL+J0mtn3yProJW3oFUNei10GiQMYuEcwneaI6ig== X-Received: by 2002:a05:600c:1986:b0:43c:f3e1:a729 with SMTP id 5b1f17b1804b1-43d17dbfb07mr350735e9.12.1741811957927; Wed, 12 Mar 2025 13:39:17 -0700 (PDT) Received: from maya.myfinge.rs (ifcgrfdd.trafficplex.cloud. [2a10:fc81:a806:d6a9::1]) by smtp.gmail.com with ESMTPSA id 5b1f17b1804b1-43d0a75829fsm31201085e9.21.2025.03.12.13.39.17 (version=TLS1_3 cipher=TLS_AES_256_GCM_SHA384 bits=256/256); Wed, 12 Mar 2025 13:39:17 -0700 (PDT) Date: Wed, 12 Mar 2025 21:39:16 +0100 From: Stefano Brivio To: David Gibson Subject: Re: [PATCH] tcp, flow: Better use flow specific logging heleprs Message-ID: <20250312213916.141a905a@elisabeth> In-Reply-To: <20250312070004.4137684-1-david@gibson.dropbear.id.au> References: <20250312070004.4137684-1-david@gibson.dropbear.id.au> Organization: Red Hat X-Mailer: Claws Mail 4.2.0 (GTK 3.24.41; x86_64-pc-linux-gnu) MIME-Version: 1.0 X-Mimecast-Spam-Score: 0 X-Mimecast-MFC-PROC-ID: 7mPtj20ZOYIBa866OLDRIIsRzlBgCjmnf_RaQ8FEVz4_1741811959 X-Mimecast-Originator: redhat.com Content-Type: text/plain; charset=US-ASCII Content-Transfer-Encoding: 7bit Message-ID-Hash: FTAMNDVMEKQIVTEVAHZLOJG5HX5SF7AS X-Message-ID-Hash: FTAMNDVMEKQIVTEVAHZLOJG5HX5SF7AS X-MailFrom: sbrivio@redhat.com 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: On Wed, 12 Mar 2025 18:00:04 +1100 David Gibson 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 > --- > 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