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;
From:   Chuck Lever III <chuck.lever@oracle.com>
To:     Bruce Fields <bfields@redhat.com>,
        Chris Down <chris@chrisdown.name>
CC:     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
Thread-Topic: [PATCH] SUNRPC: Output oversized frag reclen as ASCII if
 printable
Thread-Index: AQHXHM/NVCtugqioaUyypXdJqaYWcqqLZvMAgAB4GYCABDaVgA==
Date:   Mon, 22 Mar 2021 14:28:29 +0000
Message-ID: <117735A5-0545-451E-AFD8-28440F7E2DBE@oracle.com>
References: <YFS7L4FIQBDtIY9d@chrisdown.name>
 <3844BF67-8820-4D6C-95BA-8BA0B0956BD0@oracle.com>
 <YFUgxdSXu34SvFsd@pick.fieldses.org>
In-Reply-To: <YFUgxdSXu34SvFsd@pick.fieldses.org>
Accept-Language: en-US
Content-Language: en-US
Content-Type: text/plain; charset="us-ascii"
Content-ID: <E06A01D4EFA94F4EA36AD7EA52B6F73D@namprd10.prod.outlook.com>
Content-Transfer-Encoding: quoted-printable
MIME-Version: 1.0
X-MS-Exchange-CrossTenant-Network-Message-Id: 62578d2a-a1ef-410a-7405-08d8ed3ec35c
X-MS-Exchange-CrossTenant-originalarrivaltime: 22 Mar 2021 14:28:29.3619
 (UTC)
X-MS-Exchange-CrossTenant-fromentityheader: Hosted
X-MS-Exchange-CrossTenant-id: 4e2c6054-71cb-48f1-bd6c-3a9705aca71b
X-MS-Exchange-CrossTenant-mailboxtype: HOSTED
X-MS-Exchange-CrossTenant-userprincipalname: kY2btQ7TmU62+iP+SSafJBD0dcb2Rl10E12qfLixMlWW+fPE1TyHgI3dSgUHYJm0ZOiL2chK4XFNKzPRgIj2Yg==
X-MS-Exchange-Transport-CrossTenantHeadersStamped: BY5PR10MB3857
X-Proofpoint-Virus-Version: vendor=nai engine=6200 definitions=9931 signatures=668683
X-Proofpoint-Spam-Details: rule=notspam policy=default score=0 adultscore=0 mlxscore=0 phishscore=0
 bulkscore=0 suspectscore=0 malwarescore=0 mlxlogscore=999 spamscore=0
 classifier=spam adjust=0 reason=mlx scancount=1 engine=8.12.0-2009150000
 definitions=main-2103220106
X-Proofpoint-Virus-Version: vendor=nai engine=6200 definitions=9931 signatures=668683
X-Proofpoint-Spam-Details: rule=notspam policy=default score=0 lowpriorityscore=0 phishscore=0
 mlxlogscore=999 priorityscore=1501 impostorscore=0 bulkscore=0 spamscore=0
 adultscore=0 clxscore=1015 malwarescore=0 mlxscore=0 suspectscore=0
 classifier=spam adjust=0 reason=mlx scancount=1 engine=8.12.0-2009150000
 definitions=main-2103220106
Precedence: bulk
List-ID: <linux-nfs.vger.kernel.org>
X-Mailing-List: linux-nfs@vger.kernel.org


> On Mar 19, 2021, at 6:08 PM, J. Bruce Fields <bfields@redhat.com> wrote:
>=20
> On Fri, Mar 19, 2021 at 02:58:14PM +0000, Chuck Lever III wrote:
>> Hi Chris-
>>=20
>>> On Mar 19, 2021, at 10:54 AM, Chris Down <chris@chrisdown.name> wrote:
>>>=20
>>> 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 prin=
t
>>> a ratelimited KERN_NOTICE with that number verbatim.
>>>=20
>>> This can be confusing for downstream users, who don't know what message=
s
>>> like "fragment too large: 1195725856" actually mean, or that they
>>> indicate some misconfigured infrastructure elsewhere.
>>=20
>> 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.
>=20
> Just going on vague memories here, but: I think we've seen both spurious
> and real bugs reported based on this.
>=20
> I'm inclined to go with a dprintk or tracepoint but not removing it
> entirely.

Because this event can be chatty in some cases, I would prefer making
it a tracepoint rather than directing it to the log. Note also it would
be helpful if the server's net namespace and the client's IP address
and port were recorded.

Chris, there exists some boilerplate in fs/nfsd/trace.h to help with
the latter (just so you can see how to build the trace event definition;
you don't have to copy the macros to include/trace/events/sunrpc.h).


> --b.
>=20
>>=20
>>=20
>>> To allow users to more easily understand and debug these cases, add the
>>> number interpreted as ASCII if all characters are printable:
>>>=20
>>>   RPC: fragment too large: 1195725856 (ASCII "GET ")
>>>=20
>>> 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 th=
e
>>> one that has repeatedly come up in production.
>>>=20
>>> 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(-)
>>>=20
>>> 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>
>>>=20
>>> #include <linux/sunrpc/types.h>
>>> #include <linux/sunrpc/clnt.h>
>>> @@ -863,6 +864,34 @@ static void svc_tcp_clear_pages(struct svc_sock *s=
vsk)
>>> 	svsk->sk_datalen =3D 0;
>>> }
>>>=20
>>> +/* The reclen is taken directly from the first four bytes of the messa=
ge 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 i=
nterpret
>>> + * it as a 1195725856-sized fragment (ie. (u32)'GET '), and print a ra=
telimited
>>> + * KERN_NOTICE with that number verbatim.
>>> + *
>>> + * To allow users to more easily understand and debug these cases, thi=
s
>>> + * function decodes the purported length as ASCII, and returns it if a=
ll
>>> + * characters were printable. Otherwise, we return NULL.
>>> + *
>>> + * WARNING: Since we reuse the u32 directly, the return value is not n=
ull
>>> + * 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 =3D cpu_to_be32(svc_sock_reclen(svsk));
>>> +	char *len_be_ascii =3D (char *)&len_be;
>>> +	size_t i;
>>> +
>>> +	for (i =3D 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;
>>>=20
>>> 	/* 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);
>>>=20
>>> err_too_large:
>>> -	net_notice_ratelimited("svc: %s %s RPC fragment too large: %d\n",
>>> +	reclen_ascii =3D 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;
>>> --=20
>>> 2.30.2
>>>=20
>>=20
>> --
>> Chuck Lever

--
Chuck Lever