SUNRPC: Replace dprintk call sites in TCP state change callouts

Report TCP socket state changes and accept failures via
tracepoints, replacing dprintk() call sites.

No tracepoint is added in svc_tcp_listen_data_ready. There's
no information available there that isn't also reported by the
svcsock_new_socket and the accept failure tracepoints.

Signed-off-by: Chuck Lever <chuck.lever@oracle.com>

diff --git a/include/trace/events/sunrpc.h b/include/trace/events/sunrpc.h
index bf08664..ed8c991 100644 (file)
--- a/include/trace/events/sunrpc.h
+++ b/include/trace/events/sunrpc.h
@@ -1481,6 +1481,73 @@ DEFINE_SVCSOCK_EVENT(tcp_send);
 DEFINE_SVCSOCK_EVENT(data_ready);
 DEFINE_SVCSOCK_EVENT(write_space);
 
+TRACE_EVENT(svcsock_tcp_state,
+       TP_PROTO(
+               const struct svc_xprt *xprt,
+               const struct socket *socket
+       ),
+
+       TP_ARGS(xprt, socket),
+
+       TP_STRUCT__entry(
+               __field(unsigned long, socket_state)
+               __field(unsigned long, sock_state)
+               __field(unsigned long, flags)
+               __string(addr, xprt->xpt_remotebuf)
+       ),
+
+       TP_fast_assign(
+               __entry->socket_state = socket->state;
+               __entry->sock_state = socket->sk->sk_state;
+               __entry->flags = xprt->xpt_flags;
+               __assign_str(addr, xprt->xpt_remotebuf);
+       ),
+
+       TP_printk("addr=%s state=%s sk_state=%s flags=%s", __get_str(addr),
+               rpc_show_socket_state(__entry->socket_state),
+               rpc_show_sock_state(__entry->sock_state),
+               show_svc_xprt_flags(__entry->flags)
+       )
+);
+
+DECLARE_EVENT_CLASS(svcsock_accept_class,
+       TP_PROTO(
+               const struct svc_xprt *xprt,
+               const char *service,
+               long status
+       ),
+
+       TP_ARGS(xprt, service, status),
+
+       TP_STRUCT__entry(
+               __field(long, status)
+               __string(service, service)
+               __array(unsigned char, addr, sizeof(struct sockaddr_in6))
+       ),
+
+       TP_fast_assign(
+               __entry->status = status;
+               __assign_str(service, service);
+               memcpy(__entry->addr, &xprt->xpt_local, sizeof(__entry->addr));
+       ),
+
+       TP_printk("listener=%pISpc service=%s status=%ld",
+               __entry->addr, __get_str(service), __entry->status
+       )
+);
+
+#define DEFINE_ACCEPT_EVENT(name) \
+       DEFINE_EVENT(svcsock_accept_class, svcsock_##name##_err, \
+                       TP_PROTO( \
+                               const struct svc_xprt *xprt, \
+                               const char *service, \
+                               long status \
+                       ), \
+                       TP_ARGS(xprt, service, status))
+
+DEFINE_ACCEPT_EVENT(accept);
+DEFINE_ACCEPT_EVENT(getpeername);
+
 DECLARE_EVENT_CLASS(cache_event,
        TP_PROTO(
                const struct cache_detail *cd,

diff --git a/net/sunrpc/svcsock.c b/net/sunrpc/svcsock.c
index 758b835..4ac1180 100644 (file)
--- a/net/sunrpc/svcsock.c
+++ b/net/sunrpc/svcsock.c
@@ -657,9 +657,6 @@ static void svc_tcp_listen_data_ready(struct sock *sk)
 {
        struct svc_sock *svsk = (struct svc_sock *)sk->sk_user_data;
 
-       dprintk("svc: socket %p TCP (listen) state change %d\n",
-               sk, sk->sk_state);
-
        if (svsk) {
                /* Refer to svc_setup_socket() for details. */
                rmb();
@@ -680,8 +677,7 @@ static void svc_tcp_listen_data_ready(struct sock *sk)
                if (svsk) {
                        set_bit(XPT_CONN, &svsk->sk_xprt.xpt_flags);
                        svc_xprt_enqueue(&svsk->sk_xprt);
-               } else
-                       printk("svc: socket %p: no user data\n", sk);
+               }
        }
 }
 
@@ -692,15 +688,11 @@ static void svc_tcp_state_change(struct sock *sk)
 {
        struct svc_sock *svsk = (struct svc_sock *)sk->sk_user_data;
 
-       dprintk("svc: socket %p TCP (connected) state change %d (svsk %p)\n",
-               sk, sk->sk_state, sk->sk_user_data);
-
-       if (!svsk)
-               printk("svc: socket %p: no user data\n", sk);
-       else {
+       if (svsk) {
                /* Refer to svc_setup_socket() for details. */
                rmb();
                svsk->sk_ostate(sk);
+               trace_svcsock_tcp_state(&svsk->sk_xprt, svsk->sk_sock);
                if (sk->sk_state != TCP_ESTABLISHED) {
                        set_bit(XPT_CLOSE, &svsk->sk_xprt.xpt_flags);
                        svc_xprt_enqueue(&svsk->sk_xprt);
@@ -721,7 +713,6 @@ static struct svc_xprt *svc_tcp_accept(struct svc_xprt *xprt)
        struct socket   *newsock;
        struct svc_sock *newsvsk;
        int             err, slen;
-       RPC_IFDEBUG(char buf[RPC_MAX_ADDRBUFLEN]);
 
        if (!sock)
                return NULL;
@@ -735,30 +726,18 @@ static struct svc_xprt *svc_tcp_accept(struct svc_xprt *xprt)
                else if (err != -EAGAIN)
                        net_warn_ratelimited("%s: accept failed (err %d)!\n",
                                             serv->sv_name, -err);
+               trace_svcsock_accept_err(xprt, serv->sv_name, err);
                return NULL;
        }
        set_bit(XPT_CONN, &svsk->sk_xprt.xpt_flags);
 
        err = kernel_getpeername(newsock, sin);
        if (err < 0) {
-               net_warn_ratelimited("%s: peername failed (err %d)!\n",
-                                    serv->sv_name, -err);
+               trace_svcsock_getpeername_err(xprt, serv->sv_name, err);
                goto failed;            /* aborted connection or whatever */
        }
        slen = err;
 
-       /* Ideally, we would want to reject connections from unauthorized
-        * hosts here, but when we get encryption, the IP of the host won't
-        * tell us anything.  For now just warn about unpriv connections.
-        */
-       if (!svc_port_is_privileged(sin)) {
-               dprintk("%s: connect from unprivileged port: %s\n",
-                       serv->sv_name,
-                       __svc_print_addr(sin, buf, sizeof(buf)));
-       }
-       dprintk("%s: connect from %s\n", serv->sv_name,
-               __svc_print_addr(sin, buf, sizeof(buf)));
-
        /* Reset the inherited callbacks before calling svc_setup_socket */
        newsock->sk->sk_state_change = svsk->sk_ostate;
        newsock->sk->sk_data_ready = svsk->sk_odata;
@@ -776,10 +755,8 @@ static struct svc_xprt *svc_tcp_accept(struct svc_xprt *xprt)
        svc_xprt_set_remote(&newsvsk->sk_xprt, sin, slen);
        err = kernel_getsockname(newsock, sin);
        slen = err;
-       if (unlikely(err < 0)) {
-               dprintk("svc_tcp_accept: kernel_getsockname error %d\n", -err);
+       if (unlikely(err < 0))
                slen = offsetof(struct sockaddr, sa_data);
-       }
        svc_xprt_set_local(&newsvsk->sk_xprt, sin, slen);
 
        if (sock_is_loopback(newsock->sk))