MIME-Version: 1.0
References: <20211202181308.279592-1-plambri@redhat.com>
In-Reply-To: <20211202181308.279592-1-plambri@redhat.com>
From:   David Wysochanski <dwysocha@redhat.com>
Date:   Mon, 6 Dec 2021 09:54:30 -0500
Message-ID: <CALF+zOm32pbbnAVrVdWte1=MC_COEfUqjyDf++OqrcS0gc4dHA@mail.gmail.com>
Subject: Re: [PATCH] SUNRPC: Add source address/port to rpc_socket* traces
To:     Pierguido Lambri <plambri@redhat.com>
Cc:     linux-nfs <linux-nfs@vger.kernel.org>,
        Anna Schumaker <anna.schumaker@netapp.com>,
        Trond Myklebust <trond.myklebust@hammerspace.com>
Content-Type: text/plain; charset="UTF-8"
Precedence: bulk

On Thu, Dec 2, 2021 at 1:13 PM Pierguido Lambri <plambri@redhat.com> wrote:
>
> The rpc_socket* traces now show also the source address
> and port. An example is:
>
> kworker/u17:1-951   [005] 134218.925343: rpc_socket_close:
>    socket:[46913] srcaddr=192.168.100.187:793 dstaddr=192.168.100.129:2049
>    state=4 (DISCONNECTING) sk_state=7 (CLOSE)
> kworker/u17:0-242   [006] 134360.841370: rpc_socket_connect:
>    error=-115 socket:[56322] srcaddr=192.168.100.187:769
>    dstaddr=192.168.100.129:2049 state=2 (CONNECTING) sk_state=2 (SYN_SENT)
>        <idle>-0     [006] 134360.841859: rpc_socket_state_change: socket:[56322]
>    srcaddr=192.168.100.187:769 dstaddr=192.168.100.129:2049 state=2 (CONNECTING)
>    sk_state=1 (ESTABLISHED)
>
> Signed-off-by: Pierguido Lambri <plambri@redhat.com>
> ---
>  include/trace/events/sunrpc.h | 52 +++++++++++++++++++++--------------
>  1 file changed, 32 insertions(+), 20 deletions(-)
>
> diff --git a/include/trace/events/sunrpc.h b/include/trace/events/sunrpc.h
> index 3a99358c262b..c9a5babf3be8 100644
> --- a/include/trace/events/sunrpc.h
> +++ b/include/trace/events/sunrpc.h
> @@ -794,6 +794,9 @@ RPC_SHOW_SOCKET
>
>  RPC_SHOW_SOCK
>
> +
> +#include <trace/events/net_probe_common.h>
> +
>  /*
>   * Now redefine the EM() and EMe() macros to map the enums to the strings
>   * that will be printed in the output.
> @@ -816,27 +819,32 @@ DECLARE_EVENT_CLASS(xs_socket_event,
>                         __field(unsigned int, socket_state)
>                         __field(unsigned int, sock_state)
>                         __field(unsigned long long, ino)
> -                       __string(dstaddr,
> -                               xprt->address_strings[RPC_DISPLAY_ADDR])
> -                       __string(dstport,
> -                               xprt->address_strings[RPC_DISPLAY_PORT])
> +                       __array(__u8, saddr, sizeof(struct sockaddr_in6))
> +                       __array(__u8, daddr, sizeof(struct sockaddr_in6))
>                 ),
>
>                 TP_fast_assign(
>                         struct inode *inode = SOCK_INODE(socket);
> +                       const struct sock *sk = socket->sk;
> +                       const struct inet_sock *inet = inet_sk(sk);
> +
> +                       memset(__entry->saddr, 0, sizeof(struct sockaddr_in6));
> +                       memset(__entry->daddr, 0, sizeof(struct sockaddr_in6));
> +
> +                       TP_STORE_ADDR_PORTS(__entry, inet, sk);
> +
>                         __entry->socket_state = socket->state;
>                         __entry->sock_state = socket->sk->sk_state;
>                         __entry->ino = (unsigned long long)inode->i_ino;
> -                       __assign_str(dstaddr,
> -                               xprt->address_strings[RPC_DISPLAY_ADDR]);
> -                       __assign_str(dstport,
> -                               xprt->address_strings[RPC_DISPLAY_PORT]);
> +
>                 ),
>
>                 TP_printk(
> -                       "socket:[%llu] dstaddr=%s/%s "
> +                       "socket:[%llu] srcaddr=%pISpc dstaddr=%pISpcst "

Shouldn't the above scan code be the same as dstaddr below: "dstaddr=%pISpc "

>                         "state=%u (%s) sk_state=%u (%s)",
> -                       __entry->ino, __get_str(dstaddr), __get_str(dstport),
> +                       __entry->ino,
> +                       __entry->saddr,
> +                       __entry->daddr,
>                         __entry->socket_state,
>                         rpc_show_socket_state(__entry->socket_state),
>                         __entry->sock_state,
> @@ -866,29 +874,33 @@ DECLARE_EVENT_CLASS(xs_socket_event_done,
>                         __field(unsigned int, socket_state)
>                         __field(unsigned int, sock_state)
>                         __field(unsigned long long, ino)
> -                       __string(dstaddr,
> -                               xprt->address_strings[RPC_DISPLAY_ADDR])
> -                       __string(dstport,
> -                               xprt->address_strings[RPC_DISPLAY_PORT])
> +                       __array(__u8, saddr, sizeof(struct sockaddr_in6))
> +                       __array(__u8, daddr, sizeof(struct sockaddr_in6))
>                 ),
>
>                 TP_fast_assign(
>                         struct inode *inode = SOCK_INODE(socket);
> +                       const struct sock *sk = socket->sk;
> +                       const struct inet_sock *inet = inet_sk(sk);
> +
> +                       memset(__entry->saddr, 0, sizeof(struct sockaddr_in6));
> +                       memset(__entry->daddr, 0, sizeof(struct sockaddr_in6));
> +
> +                       TP_STORE_ADDR_PORTS(__entry, inet, sk);
> +
>                         __entry->socket_state = socket->state;
>                         __entry->sock_state = socket->sk->sk_state;
>                         __entry->ino = (unsigned long long)inode->i_ino;
>                         __entry->error = error;
> -                       __assign_str(dstaddr,
> -                               xprt->address_strings[RPC_DISPLAY_ADDR]);
> -                       __assign_str(dstport,
> -                               xprt->address_strings[RPC_DISPLAY_PORT]);
>                 ),
>
>                 TP_printk(
> -                       "error=%d socket:[%llu] dstaddr=%s/%s "
> +                       "error=%d socket:[%llu] srcaddr=%pISpc dstaddr=%pISpc "
>                         "state=%u (%s) sk_state=%u (%s)",
>                         __entry->error,
> -                       __entry->ino, __get_str(dstaddr), __get_str(dstport),
> +                       __entry->ino,
> +                       __entry->saddr,
> +                       __entry->daddr,
>                         __entry->socket_state,
>                         rpc_show_socket_state(__entry->socket_state),
>                         __entry->sock_state,
> --
> 2.33.1
>

This patch is useful for troubleshooting reconnect issues, making it
easier to match up tcpdumps with kernel traces.

Acked-and-tested-by: Dave Wysochanski <dwysocha@redhat.com>