Received-SPF: pass (google.com: domain of linux-nfs-owner@vger.kernel.org designates 23.128.96.18 as permitted sender) client-ip=23.128.96.18;
Date:   Fri, 19 Mar 2021 18:08:05 -0400
From:   "J. Bruce Fields" <bfields@redhat.com>
To:     Chuck Lever III <chuck.lever@oracle.com>
Cc:     Chris Down <chris@chrisdown.name>,
        Linux NFS Mailing List <linux-nfs@vger.kernel.org>,
        Linux-Net <netdev@vger.kernel.org>,
        LKML <linux-kernel@vger.kernel.org>,
        Trond Myklebust <trond.myklebust@hammerspace.com>,
        "David S. Miller" <davem@davemloft.net>
Subject: Re: [PATCH] SUNRPC: Output oversized frag reclen as ASCII if
 printable
Message-ID: <YFUgxdSXu34SvFsd@pick.fieldses.org>
References: <YFS7L4FIQBDtIY9d@chrisdown.name>
 <3844BF67-8820-4D6C-95BA-8BA0B0956BD0@oracle.com>
MIME-Version: 1.0
Content-Type: text/plain; charset=us-ascii
Content-Disposition: inline
In-Reply-To: <3844BF67-8820-4D6C-95BA-8BA0B0956BD0@oracle.com>
Precedence: bulk

On Fri, Mar 19, 2021 at 02:58:14PM +0000, Chuck Lever III wrote:
> Hi Chris-
> 
> > On Mar 19, 2021, at 10:54 AM, Chris Down <chris@chrisdown.name> wrote:
> > 
> > The reclen is taken directly from the first four bytes of the message
> > with the highest bit stripped, which makes it ripe for protocol mixups.
> > For example, if someone tries to send a HTTP GET request to us, we'll
> > interpret it as a 1195725856-sized fragment (ie. (u32)'GET '), and print
> > a ratelimited KERN_NOTICE with that number verbatim.
> > 
> > This can be confusing for downstream users, who don't know what messages
> > like "fragment too large: 1195725856" actually mean, or that they
> > indicate some misconfigured infrastructure elsewhere.
> 
> One wonders whether that error message is actually useful at all.
> We could, for example, turn this into a tracepoint, or just get
> rid of it.

Just going on vague memories here, but: I think we've seen both spurious
and real bugs reported based on this.

I'm inclined to go with a dprintk or tracepoint but not removing it
entirely.

--b.

> 
> 
> > To allow users to more easily understand and debug these cases, add the
> > number interpreted as ASCII if all characters are printable:
> > 
> >    RPC: fragment too large: 1195725856 (ASCII "GET ")
> > 
> > If demand grows elsewhere, a new printk format that takes a number and
> > outputs it in various formats is also a possible solution. For now, it
> > seems reasonable to put this here since this particular code path is the
> > one that has repeatedly come up in production.
> > 
> > Signed-off-by: Chris Down <chris@chrisdown.name>
> > Cc: Chuck Lever <chuck.lever@oracle.com>
> > Cc: J. Bruce Fields <bfields@redhat.com>
> > Cc: Trond Myklebust <trond.myklebust@hammerspace.com>
> > Cc: David S. Miller <davem@davemloft.net>
> > ---
> > net/sunrpc/svcsock.c | 39 +++++++++++++++++++++++++++++++++++++--
> > 1 file changed, 37 insertions(+), 2 deletions(-)
> > 
> > diff --git a/net/sunrpc/svcsock.c b/net/sunrpc/svcsock.c
> > index 2e2f007dfc9f..046b1d104340 100644
> > --- a/net/sunrpc/svcsock.c
> > +++ b/net/sunrpc/svcsock.c
> > @@ -46,6 +46,7 @@
> > #include <linux/uaccess.h>
> > #include <linux/highmem.h>
> > #include <asm/ioctls.h>
> > +#include <linux/ctype.h>
> > 
> > #include <linux/sunrpc/types.h>
> > #include <linux/sunrpc/clnt.h>
> > @@ -863,6 +864,34 @@ static void svc_tcp_clear_pages(struct svc_sock *svsk)
> > 	svsk->sk_datalen = 0;
> > }
> > 
> > +/* The reclen is taken directly from the first four bytes of the message with
> > + * the highest bit stripped, which makes it ripe for protocol mixups. For
> > + * example, if someone tries to send a HTTP GET request to us, we'll interpret
> > + * it as a 1195725856-sized fragment (ie. (u32)'GET '), and print a ratelimited
> > + * KERN_NOTICE with that number verbatim.
> > + *
> > + * To allow users to more easily understand and debug these cases, this
> > + * function decodes the purported length as ASCII, and returns it if all
> > + * characters were printable. Otherwise, we return NULL.
> > + *
> > + * WARNING: Since we reuse the u32 directly, the return value is not null
> > + * terminated, and must be printed using %.*s with
> > + * sizeof(svc_sock_reclen(svsk)).
> > + */
> > +static char *svc_sock_reclen_ascii(struct svc_sock *svsk)
> > +{
> > +	u32 len_be = cpu_to_be32(svc_sock_reclen(svsk));
> > +	char *len_be_ascii = (char *)&len_be;
> > +	size_t i;
> > +
> > +	for (i = 0; i < sizeof(len_be); i++) {
> > +		if (!isprint(len_be_ascii[i]))
> > +			return NULL;
> > +	}
> > +
> > +	return len_be_ascii;
> > +}
> > +
> > /*
> >  * Receive fragment record header into sk_marker.
> >  */
> > @@ -870,6 +899,7 @@ static ssize_t svc_tcp_read_marker(struct svc_sock *svsk,
> > 				   struct svc_rqst *rqstp)
> > {
> > 	ssize_t want, len;
> > +	char *reclen_ascii;
> > 
> > 	/* If we haven't gotten the record length yet,
> > 	 * get the next four bytes.
> > @@ -898,9 +928,14 @@ static ssize_t svc_tcp_read_marker(struct svc_sock *svsk,
> > 	return svc_sock_reclen(svsk);
> > 
> > err_too_large:
> > -	net_notice_ratelimited("svc: %s %s RPC fragment too large: %d\n",
> > +	reclen_ascii = svc_sock_reclen_ascii(svsk);
> > +	net_notice_ratelimited("svc: %s %s RPC fragment too large: %d%s%.*s%s\n",
> > 			       __func__, svsk->sk_xprt.xpt_server->sv_name,
> > -			       svc_sock_reclen(svsk));
> > +			       svc_sock_reclen(svsk),
> > +			       reclen_ascii ? " (ASCII \"" : "",
> > +			       (int)sizeof(u32),
> > +			       reclen_ascii ?: "",
> > +			       reclen_ascii ? "\")" : "");
> > 	set_bit(XPT_CLOSE, &svsk->sk_xprt.xpt_flags);
> > err_short:
> > 	return -EAGAIN;
> > -- 
> > 2.30.2
> > 
> 
> --
> Chuck Lever
> 
> 
>