Received-SPF: pass (google.com: domain of linux-nfs+bounces-3795-linux.lists.archive=gmail.com@vger.kernel.org designates 2604:1380:45e3:2400::1 as permitted sender) client-ip=2604:1380:45e3:2400::1;
Message-ID: <8ac2bb6f-63da-412f-8469-2a5be823fa40@usask.ca>
Date: Thu, 13 Jun 2024 16:44:24 -0600
User-Agent: Mozilla Thunderbird
Content-Language: en-US
To: linux-nfs@vger.kernel.org
From: Chris Friesen <cbf123@usask.ca>
Subject: Seeing strange behaviour from RPC/NFSD on 6.6.7 kernel, looking for
 debug advice
Content-Type: text/plain; charset=UTF-8; format=flowed
Content-Transfer-Encoding: 7bit
Precedence: bulk
MIME-Version: 1.0
X-MS-Exchange-AntiSpam-MessageData-ChunkCount: 1
X-MS-Exchange-AntiSpam-MessageData-0:
	=?utf-8?B?ZE9Ccld0Tlg4Q04vRkVKT1U5MFRITEZEWExPNjZIT2gxOGNGWVN5UmNaMEhZ?=
 =?utf-8?B?QncwLzJBRU03MlNmT1pnc0F6aExhM3RlUHBnR2JoYzN3cWxpaWx0SzFOdHJz?=
 =?utf-8?B?TDFNdDFsdVV4RDBLelIwY2tvYWxWeStFQmFTcTdDSHRmamhGaEJzTWtrQ0Rz?=
 =?utf-8?B?NE1yZU5qc2lieTUwbGEwZVB6NnpTcEJGT2dkajF3cUpRRzZYRkVBRVpXVTdH?=
 =?utf-8?B?YW1nTDlpU3VUVm5uUGl2Q1BKb2NNUTJ0L3NTZm05T3NPV0YrWXhmdlFvZTdQ?=
 =?utf-8?B?SEluN2JXeTZOTnJKcnY3TnlSZExob2hNVlRwdjE2ZVBxSzUvWTYwR3d6VXg2?=
 =?utf-8?B?K25PZUNEVHVQM0pmQjFhNDd1UTN1ZUN1UEUvTFVEWHhZblFSRHhSYjBIV21j?=
 =?utf-8?B?Z0JDRWZOdzNILzBQZ0JKMWlKRkxlbGdxWElBaDRET1BiNERseVZwOE5mZ2ph?=
 =?utf-8?B?ZVBYYkdQTDVhRGh1WUF1T3pDSGt3OTNRZURHUmJGYVRTMnk4R0JNM0xnejdn?=
 =?utf-8?B?WEEyR01YeVYrVTEySXRiWi83Y2hFaDFpKzcvZXQvR1ZIbFluWFlMU1c0Tmdi?=
 =?utf-8?B?NVZYc1NwQmdzbDIyVEZEWWduM0pwa0hWYU8wR3JvOVhxT3BGM3BXNmxwRW1a?=
 =?utf-8?B?VTJNOEJ5SGw0SkVkVXoyQTdhTzJlcXZ5aWllUUd0NDllVVZVRlJLV0x3RHVD?=
 =?utf-8?B?SnQ2ZDJzV2I5TXJTV3JEM0k2ekhRZzlpK3YzMGo5eUlzbnc5ZHZRRU80ek9B?=
 =?utf-8?B?TjlRSkNwVjZHajF0NkdqYy9xWmt4dGFMQ0dTRVVsRGIvL3ZBN0ZVYjhrMmZQ?=
 =?utf-8?B?UFpkcFoyMEMvK2Q0VUhST2JuSm5aQ1Zlczh3dUR5SEtrYkxiYnJOaVZmbnBC?=
 =?utf-8?B?R3JJaVVVU1lsdURWV043OVlMMVFsMkJ5dzhtZWw2OTdMZVkvTXZFaS9GNkNp?=
 =?utf-8?B?czB4R0U5VCtNS25ldW1WalUzRDM0a0hkUjE5R3lWbDdVVnlncE9hZE9yalZM?=
 =?utf-8?B?MnU0MUIxeFVDRDR5MGZUSkFZSFNKV0t0cFRLWTdBMkt1b1R2bHBQM1RxQWVi?=
 =?utf-8?B?TWRzK1FNWHB3MHNKTGkwVTJyaW0ralRkWWFxU3dIQ2hLZVZ0RE9rWkt5NXN2?=
 =?utf-8?B?YU10MFVVSW9LcUhDRDJ0V3BDWEZsN2NnTlBmaGRtd1pQbUxCa0tjY0RUdWx1?=
 =?utf-8?B?Y2JMRXVCWTB2RHFlejRjVk83WXpOL29rRWZ1UXFjRStmODJTSFU5ZlBCSHds?=
 =?utf-8?B?ZlZ6MEdOZ25pcDlIdDBHb3kwZ1dyYjFjS0xLT2NKODhta1F1MmpPNm9BMnla?=
 =?utf-8?B?UHhTVEFwWmZHYVJSaENjYU5FV0dLUzlTL1NFWkU5U0pLajBBMlBaR2NIQ2VU?=
 =?utf-8?B?REV6L2tOaHZCaDRMb3FwcGx5Y1pNcGhEUFBHaWh1VWdsZEs0V2E4VWlTNng1?=
 =?utf-8?B?WXd5T2dEUi9Obyt3OWxENmJOT1lGWDJlai9ZbGNkODlwR0FyamlhRnRtM05D?=
 =?utf-8?B?TFYvR0Mvb1FIeGJHUUJldzZOY0JrSFlMcG16YXc2ODVDRjM1UzRkQlNBSzdj?=
 =?utf-8?B?ellSK2FlYTNBbm5wRysxUEgraCtCaFpIZ3lJR0JOY2xncWZac3g1emYzSm94?=
 =?utf-8?B?S2E2WHpKc1B4NnY4RnFLYlkvOEIwSzdGazZTUGJvQUpuL2g0QTg3d3JXbzR3?=
 =?utf-8?B?ZHdWVlRpd3ZnQ0hjdG1UTmwrN1hVMzlWRFB6TWxRZTRwWndNdEJEakZjQXdn?=
 =?utf-8?B?bXhydzVHazJJMUFreHhodThxWk82a3U1S2dRQ0o3YW9zeU4wNlFJaHFjSi9U?=
 =?utf-8?B?RWZEZFhoR1VxdXpHNGdQaEhuaTg1ei9zUTRLazFtWlJodWZvdzRIQlMxMDdE?=
 =?utf-8?B?cDR6VTg5QnR2VlVBVVl0OG9YREJHeXRZQ2pQNXFucG9odEpCOVIwYVJiZzZG?=
 =?utf-8?B?cktCcWFoM2pPck5PR1IzUDc1WHBNbzQyd0JCejZMQnIvZFlvT0ZEOVpVWmox?=
 =?utf-8?B?ZWEra253TndyOGRvejg3YTZldW84R0xINEJYY3RWMG1QTklhRmdUdUk0WnVo?=
 =?utf-8?B?dGt2anRHRDJaUmVTeTdtR0NMZWZnM2lwZjdNYmdRZzNEZ3lMRTdUdG83MFJo?=
 =?utf-8?Q?eBqw6Hn0CAoiCBGNbGsp/AVRj?=
X-OriginatorOrg: usask.ca
X-MS-Exchange-CrossTenant-Network-Message-Id: ec6df7bf-8fb7-44ba-0720-08dc8bfa612e
X-MS-Exchange-CrossTenant-AuthSource: YQBPR0101MB6200.CANPRD01.PROD.OUTLOOK.COM
X-MS-Exchange-CrossTenant-AuthAs: Internal
X-MS-Exchange-CrossTenant-OriginalArrivalTime: 13 Jun 2024 22:44:26.9360
 (UTC)
X-MS-Exchange-CrossTenant-FromEntityHeader: Hosted
X-MS-Exchange-CrossTenant-Id: 24ab6cd0-487e-4722-9bc3-da9c4232776c
X-MS-Exchange-CrossTenant-MailboxType: HOSTED
X-MS-Exchange-CrossTenant-UserPrincipalName: fpgwcA2RHBSkfYgnhXAyOfTQ20v+8VNGKmXNoFtt81THB3Hm7wi9padNGLuJkmA0
X-MS-Exchange-Transport-CrossTenantHeadersStamped: YQBPR0101MB6633

Hi all,

I'm not subscribed to the list so please CC me on replies.  I'm seeing 
some odd behaviour and I'm not sure what's going on.

The short version is that I can mount NFS exports from this server 
(including mounting on the server itself) via TCP but not via UDP.

rpcinfo on the server gives the following:

root@controller-0:/var/home/sysadmin# rpcinfo -s
    program version(s) netid(s)                     service     owner
     100000  2,3,4     local,udp,tcp,udp6,tcp6      portmapper  superuser
     100024  1         tcp6,udp6,tcp,udp            status      116
     100003  4,3       udp6,tcp6,udp,tcp            nfs         superuser
     100227  3         udp6,tcp6,udp,tcp            -           superuser
     100021  4,3,1     tcp6,udp6,tcp,udp            nlockmgr    superuser
     100005  3,2,1     tcp6,udp6,tcp,udp            mountd      superuser

root@controller-0:/var/home/sysadmin# rpcinfo -p
    program vers proto   port  service
     100000    4   tcp    111  portmapper
     100000    3   tcp    111  portmapper
     100000    2   tcp    111  portmapper
     100000    4   udp    111  portmapper
     100000    3   udp    111  portmapper
     100000    2   udp    111  portmapper
     100024    1   udp  44993  status
     100024    1   tcp  60561  status
     100003    3   tcp   2049  nfs
     100003    4   tcp   2049  nfs
     100227    3   tcp   2049
     100003    3   udp   2049  nfs
     100227    3   udp   2049
     100021    1   udp  36993  nlockmgr
     100021    3   udp  36993  nlockmgr
     100021    4   udp  36993  nlockmgr
     100021    1   tcp  33239  nlockmgr
     100021    3   tcp  33239  nlockmgr
     100021    4   tcp  33239  nlockmgr
     100005    1   udp  43636  mountd
     100005    1   tcp  49357  mountd
     100005    2   udp  39783  mountd
     100005    2   tcp  54527  mountd
     100005    3   udp  40970  mountd
     100005    3   tcp  41761  mountd


So it *looks* okay to me, but if I probe it I get the expected response 
for TCP but not for UDP:

root@controller-0:/var/home/sysadmin# rpcinfo -T tcp localhost 100003 4
program 100003 version 4 ready and waiting
root@controller-0:/var/home/sysadmin# rpcinfo -T tcp localhost 100003 3
program 100003 version 3 ready and waiting
root@controller-0:/var/home/sysadmin# rpcinfo -T udp localhost 100003 3
rpcinfo: RPC: Timed out
program 100003 version 3 is not available


Oddly the last command returns immediately so it's not actually timing 
out, the error message is a bit misleading.   If I sniff the network 
traffic while running that last command, I see this:

root@controller-0:/var/home/sysadmin# tcpdump -vvv -i lo port 2049
tcpdump: listening on lo, link-type EN10MB (Ethernet), snapshot length 
262144 bytes
20:20:53.159743 IP (tos 0x0, ttl 64, id 58251, offset 0, flags [DF], 
proto UDP (17), length 68)
     localhost.887 > localhost.nfs: NFS request xid 1717614110 40 null
20:20:53.160016 IP (tos 0x0, ttl 64, id 58252, offset 0, flags [DF], 
proto UDP (17), length 28)
     localhost.nfs > localhost.887: [bad udp cksum 0xfe1b -> 0xf663!] 
UDP, length 0


Ignoring the checksums, I get this:

root@controller-0:/var/home/sysadmin# tcpdump -vvv -K -i lo port 2049
tcpdump: listening on lo, link-type EN10MB (Ethernet), snapshot length 
262144 bytes
20:21:49.642588 IP (tos 0x0, ttl 64, id 22026, offset 0, flags [DF], 
proto UDP (17), length 68)
     localhost.934 > localhost.nfs: NFS request xid 1718297876 40 null
20:21:49.642697 IP (tos 0x0, ttl 64, id 22027, offset 0, flags [DF], 
proto UDP (17), length 28)
     localhost.nfs > localhost.934: UDP, length 0


On a separate system with a 5.10 kernel I get a successful response that 
is longer and is properly decoded:

root@controller-0:/var/home/sysadmin#  tcpdump -vvv -K -i lo port 2049
tcpdump: listening on lo, link-type EN10MB (Ethernet), snapshot length 
262144 bytes
22:22:00.388497 IP (tos 0x0, ttl 64, id 806, offset 0, flags [DF], proto 
UDP (17), length 68)
     localhost.808 > localhost.nfs: NFS request xid 1718037578 40 null
22:22:00.388525 IP (tos 0x0, ttl 64, id 807, offset 0, flags [DF], proto 
UDP (17), length 52)
     localhost.nfs > localhost.808: NFS reply xid 1718037578 reply ok 24 
null


Anyone have any ideas what might be going on or how to debug?  I'm 
building a kernel with CONFIG_SUNRPC_DEBUG enabled to see if that gives 
anything useful.

Thanks,
Chris