1. Please describe the problem: NFS mount of an AWS EFS volume consistently takes 3 minutes on a 6.12.x kernel versus immediately mounting on a 6.11.x kernel. 2. What is the Version-Release number of the kernel: 6.12.6-200.fc41.x86_6 3. Did it work previously in Fedora? If so, what kernel version did the issue *first* appear? Old kernels are available for download at https://koji.fedoraproject.org/koji/packageinfo?packageID=8 : It was working fine in the 6.11.x kernels. The problem first appears in 6.12.0-65.fc42.x86_64. 4. Can you reproduce this issue? If so, please provide the steps to reproduce the issue below: [fedora@ip-10-75-180-241 ~]$ uname -a Linux ip-10-75-180-241 6.11.11-300.fc41.x86_64 #1 SMP PREEMPT_DYNAMIC Thu Dec 5 18:38:25 UTC 2024 x86_64 GNU/Linux [root@ip-10-75-180-241 fedora]# time mount -t nfs -o nfsvers=4.1,rsize=1048576,wsize=1048576,hard,timeo=600,retrans=2,noresvport fs-XXXX.efs.us-east-1.amazonaws.com:/ /var/www/html/ real 0m0.311s user 0m0.003s sys 0m0.005s ** REBOOT ** [fedora@ip-10-75-180-241 ~]$ uname -a Linux ip-10-75-180-241 6.12.0-65.fc42.x86_64 #1 SMP PREEMPT_DYNAMIC Mon Nov 18 13:39:20 UTC 2024 x86_64 GNU/Linux [root@ip-10-75-180-241 fedora]# time mount -t nfs -o nfsvers=4.1,rsize=1048576,wsize=1048576,hard,timeo=600,retrans=2,noresvport fs-XXXX.efs.us-east-1.amazonaws.com:/ /var/www/html/ real 3m0.333s user 0m0.004s sys 0m0.483s ** REBOOT ** [root@ip-10-75-180-241 fedora]# uname -a Linux ip-10-75-180-241 6.12.6-200.fc41.x86_64 #1 SMP PREEMPT_DYNAMIC Thu Dec 19 21:06:34 UTC 2024 x86_64 GNU/Linux [root@ip-10-75-180-241 fedora]# time mount -t nfs -o nfsvers=4.1,rsize=1048576,wsize=1048576,hard,timeo=600,retrans=2,noresvport fs-XXXX.efs.us-east-1.amazonaws.com:/ /var/www/html/ real 3m0.308s user 0m0.002s sys 0m0.523s 5. Does this problem occur with the latest Rawhide kernel? To install the Rawhide kernel, run ``sudo dnf install fedora-repos-rawhide`` followed by ``sudo dnf update --enablerepo=rawhide kernel``: Yes. 6. Are you running any modules that not shipped with directly Fedora's kernel?: No. 7. Please attach the kernel logs. You can get the complete kernel log for a boot with ``journalctl --no-hostname -k > dmesg.txt``. If the issue occurred on a previous boot, use the journalctl ``-b`` flag. Reproducible: Always
Created attachment 2064407 [details] dmesg.txt
Adjusting the "timeo" and "retrans" values yield different, but reproducible, results. timeo=600 (60 seconds, the default),retrans=2 results in a 3-minute mount. timeo=600 (60 seconds, the default),retrans=0 results in a 60-second mount. timeo=150 (15 seconds),retrans=2 results in a 45-second mount. timeo=150 (15 seconds),retrans=0 results in a 15-second mount. timeo=900 (90 seconds),retrans=2 results in a 4.5-minute mount. timeo=900 (90 seconds),retrans=0 results in a 90-second mount. timeo=10 (1 second),retrans=2 results in a 3-second mount. timeo=1 (0.1 second),retrans=2 results in a 0.3-second mount. It seems like the the mount is taking timeo*(retrans+1) seconds to succeed. [root@ip-10-75-180-241 fedora]# time mount -v -t nfs -o nfsvers=4.1,rsize=1048576,wsize=1048576,hard,timeo=600,retrans=2,noresvport fs-XXXX.efs.us-east-1.amazonaws.com:/ /var/www/html/ mount.nfs: timeout set for Wed Jan 1 16:11:33 2025 mount.nfs: trying text-based options 'nfsvers=4.1,rsize=1048576,wsize=1048576,hard,timeo=600,retrans=2,noresvport,addr=10.75.180.183,clientaddr=10.75.180.241' real 3m0.323s user 0m0.003s sys 0m0.520s [root@ip-10-75-180-241 fedora]# umount /var/www/html [root@ip-10-75-180-241 fedora]# time mount -v -t nfs -o nfsvers=4.1,rsize=1048576,wsize=1048576,hard,timeo=600,retrans=2,noresvport fs-XXXX.efs.us-east-1.amazonaws.com:/ /var/www/html/ mount.nfs: timeout set for Wed Jan 1 16:14:46 2025 mount.nfs: trying text-based options 'nfsvers=4.1,rsize=1048576,wsize=1048576,hard,timeo=600,retrans=2,noresvport,addr=10.75.180.183,clientaddr=10.75.180.241' real 3m0.043s user 0m0.004s sys 0m0.810s [root@ip-10-75-180-241 fedora]# umount /var/www/html [root@ip-10-75-180-241 fedora]# date ; time mount -v -t nfs -o nfsvers=4.1,rsize=1048576,wsize=1048576,hard,timeo=150,retrans=2,noresvport fs-XXXX.efs.us-east-1.amazonaws.com:/ /var/www/html/ Wed Jan 1 04:20:02 PM UTC 2025 mount.nfs: timeout set for Wed Jan 1 16:22:02 2025 mount.nfs: trying text-based options 'nfsvers=4.1,rsize=1048576,wsize=1048576,hard,timeo=150,retrans=2,noresvport,addr=10.75.180.183,clientaddr=10.75.180.241' real 0m45.041s user 0m0.002s sys 0m0.127s [root@ip-10-75-180-241 fedora]# umount /var/www/html [root@ip-10-75-180-241 fedora]# date ; time mount -v -t nfs -o nfsvers=4.1,rsize=1048576,wsize=1048576,hard,timeo=150,retrans=2,noresvport fs-XXXX.efs.us-east-1.amazonaws.com:/ /var/www/html/ Wed Jan 1 04:22:12 PM UTC 2025 mount.nfs: timeout set for Wed Jan 1 16:24:12 2025 mount.nfs: trying text-based options 'nfsvers=4.1,rsize=1048576,wsize=1048576,hard,timeo=150,retrans=2,noresvport,addr=10.75.180.183,clientaddr=10.75.180.241' real 0m45.038s user 0m0.000s sys 0m0.137s [root@ip-10-75-180-241 fedora]# umount /var/www/html [root@ip-10-75-180-241 fedora]# date ; time mount -v -t nfs -o nfsvers=4.1,rsize=1048576,wsize=1048576,hard,retrans=2,noresvport fs-XXXX.efs.us-east-1.amazonaws.com:/ /var/www/html/ Wed Jan 1 04:23:07 PM UTC 2025 mount.nfs: timeout set for Wed Jan 1 16:25:07 2025 mount.nfs: trying text-based options 'nfsvers=4.1,rsize=1048576,wsize=1048576,hard,retrans=2,noresvport,addr=10.75.180.183,clientaddr=10.75.180.241' real 3m0.039s user 0m0.003s sys 0m0.503s [root@ip-10-75-180-241 fedora]# umount /var/www/html [root@ip-10-75-180-241 fedora]# date ; time mount -v -t nfs -o nfsvers=4.1,rsize=1048576,wsize=1048576,hard,timeo=150,retrans=2,noresvport fs-XXXX.efs.us-east-1.amazonaws.com:/ /var/www/html/ Wed Jan 1 04:26:40 PM UTC 2025 mount.nfs: timeout set for Wed Jan 1 16:28:40 2025 mount.nfs: trying text-based options 'nfsvers=4.1,rsize=1048576,wsize=1048576,hard,timeo=150,retrans=2,noresvport,addr=10.75.180.183,clientaddr=10.75.180.241' real 0m45.037s user 0m0.001s sys 0m0.235s [root@ip-10-75-180-241 fedora]# umount /var/www/html [root@ip-10-75-180-241 fedora]# date ; time mount -v -t nfs -o nfsvers=4.1,rsize=1048576,wsize=1048576,hard,timeo=900,retrans=2,noresvport fs-XXXX.efs.us-east-1.amazonaws.com:/ /var/www/html/ Wed Jan 1 04:28:02 PM UTC 2025 mount.nfs: timeout set for Wed Jan 1 16:30:02 2025 mount.nfs: trying text-based options 'nfsvers=4.1,rsize=1048576,wsize=1048576,hard,timeo=900,retrans=2,noresvport,addr=10.75.180.183,clientaddr=10.75.180.241' real 4m30.042s user 0m0.002s sys 0m0.751s [root@ip-10-75-180-241 fedora]# date ; time mount -v -t nfs -o nfsvers=4.1,rsize=1048576,wsize=1048576,hard,timeo=1,retrans=2,noresvport fs-XXXX.efs.us-east-1.amazonaws.com:/ /var/www/html/ Wed Jan 1 04:42:50 PM UTC 2025 mount.nfs: timeout set for Wed Jan 1 16:44:50 2025 mount.nfs: trying text-based options 'nfsvers=4.1,rsize=1048576,wsize=1048576,hard,timeo=1,retrans=2,noresvport,addr=10.75.180.183,clientaddr=10.75.180.241' real 0m0.339s user 0m0.002s sys 0m0.010s [root@ip-10-75-180-241 fedora]# date ; time mount -v -t nfs -o nfsvers=4.1,rsize=1048576,wsize=1048576,hard,timeo=10,retrans=2,noresvport fs-XXXX.efs.us-east-1.amazonaws.com:/ /var/www/html/ Wed Jan 1 04:43:17 PM UTC 2025 mount.nfs: timeout set for Wed Jan 1 16:45:17 2025 mount.nfs: trying text-based options 'nfsvers=4.1,rsize=1048576,wsize=1048576,hard,timeo=10,retrans=2,noresvport,addr=10.75.180.183,clientaddr=10.75.180.241' real 0m3.033s user 0m0.001s sys 0m0.041s [root@ip-10-75-180-241 fedora]# date ; time mount -v -t nfs -o nfsvers=4.1,rsize=1048576,wsize=1048576,hard,timeo=600,retrans=0,noresvport fs-XXXX.efs.us-east-1.amazonaws.com:/ /var/www/html/ Wed Jan 1 04:49:58 PM UTC 2025 mount.nfs: timeout set for Wed Jan 1 16:51:58 2025 mount.nfs: trying text-based options 'nfsvers=4.1,rsize=1048576,wsize=1048576,hard,timeo=600,retrans=0,noresvport,addr=10.75.180.183,clientaddr=10.75.180.241' real 1m0.039s user 0m0.002s sys 0m0.171s [root@ip-10-75-180-241 fedora]# date ; time mount -v -t nfs -o nfsvers=4.1,rsize=1048576,wsize=1048576,hard,timeo=900,retrans=0,noresvport fs-XXXX.efs.us-east-1.amazonaws.com:/ /var/www/html/ Wed Jan 1 04:51:53 PM UTC 2025 mount.nfs: timeout set for Wed Jan 1 16:53:53 2025 mount.nfs: trying text-based options 'nfsvers=4.1,rsize=1048576,wsize=1048576,hard,timeo=900,retrans=0,noresvport,addr=10.75.180.183,clientaddr=10.75.180.241' real 1m30.042s user 0m0.004s sys 0m0.420s
Would it be possible to get a network trace via 'sudo tshark -o /tmp/trace.pcap host <hostname>'
Created attachment 2064569 [details] network trace [root@ip-10-75-180-241 fedora]# date ; time mount -v -t nfs -o nfsvers=4.1,rsize=1048576,wsize=1048576,soft,timeo=150,retrans=2,noresvport fs-XXXX.efs.us-east-1.amazonaws.com:/ /var/www/html/ Fri Jan 3 03:59:39 AM UTC 2025 mount.nfs: timeout set for Fri Jan 3 04:01:39 2025 mount.nfs: trying text-based options 'nfsvers=4.1,rsize=1048576,wsize=1048576,soft,timeo=150,retrans=2,noresvport,addr=10.75.180.183,clientaddr=10.75.180.241' real 0m45.038s user 0m0.003s sys 0m0.127s
(In reply to Ryan from comment #4) > Created attachment 2064569 [details] > network trace > > [root@ip-10-75-180-241 fedora]# date ; time mount -v -t nfs -o > nfsvers=4.1,rsize=1048576,wsize=1048576,soft,timeo=150,retrans=2,noresvport > fs-XXXX.efs.us-east-1.amazonaws.com:/ /var/www/html/ > Fri Jan 3 03:59:39 AM UTC 2025 > mount.nfs: timeout set for Fri Jan 3 04:01:39 2025 > mount.nfs: trying text-based options > 'nfsvers=4.1,rsize=1048576,wsize=1048576,soft,timeo=150,retrans=2,noresvport, > addr=10.75.180.183,clientaddr=10.75.180.241' > > real 0m45.038s > user 0m0.003s > sys 0m0.127s The server (10.75.180.183) is rejecting the TCP connection due to a RECLAIM_COMPLETE loop... Then the session times out (NFS4ERR_BADSESSION) and the mount continues... Hmm... this only started to happen on a 6.12 kernel.
I don't see a RECLAIM_COMPLETE loop, rather the server seems triggered by something the client sends and just starts resetting any TCP connection attempts. The last thing the client sent was a RECLAIM_COMPLETE. I think you'll need to bisect the client to find whats upsetting the server, but more likely it seems theres some very sensitive IPS-like behavior on the server side. It would be much easier to check out the server logs to find why the server never responds to RECLAIM_COMPLETE and instead starts resetting all connection attempts.
Looks like a broken client. It starts off by sending exchange_id, create_session (all great), then it skips sending putrootfh compound (?). Then sends a reclaim_complete followed by some garbage rpc bytes which I think makes the server to reset the connection. After TCP handshake is done (and on each of the connection attempts) the client resends reclaim_complete compound with some garbage at the end which wireshark doesn't event parse as an NFS operation (but frame 417 is a good one to see wireshark parsing but you still see garbage bytes in the end). I dont know why this keeps happening and then suddenly in frame 53921 client sends a properly formatted reclaim_complete which gets badsession and etc since (from server's point of view lease hasn't been renewed).
Just an observation but the last RPC operation before things go off the rails isn't the RECLAIM_COMPLETE in frame 14, but a LOCALIOPROC_NULL in frame 15. It seems wireshark isn't able to decode those packets yet (they show up as continuation packets on my system): 0000 80 00 00 28 70 9e 22 ef 00 00 00 00 00 00 00 02 fraghdr xid msgtyp rpcver 0010 00 06 1a fa 00 00 00 01 00 00 00 00 00 00 00 00 rpcprog rpcprogver flavor len 0020 00 00 00 00 00 00 00 00 00 00 00 00 flavor len localioproc_null The xid (0x709e22ef) is the 1 after the xid in the RECLAIM_COMPLETE (0x6f9e22ef) and the program number is 0x61afa (400122) which is NFS_LOCALIO_PROGRAM, so maybe the NFS server doesn't like the LOCALIO probe?
Piggybacking on what Ben said, maybe there's some sort of IPS feature on the NFS server that's looking at packets being sent to port 2049 and resetting the connection because it's seeing something other than 0x186a3 (100003) in the RPC program number field. It might be worthwhile disabling the NFS LOCALIO feature and see if that makes the mounts happen faster. # echo "options nfs localio_enabled=0" > /etc/modprobe.d/disable-nfs-localio.conf # reboot # cat /sys/module/nfs/parameters/localio_enabled Make sure it says 'N' and then try mounting again.
> It might be worthwhile disabling the NFS LOCALIO feature and see if that > makes the mounts happen faster. > Thanks, Scott. That does appear to fix the problem! [root@ip-10-75-180-241 fedora]# uname -a Linux ip-10-75-180-241 6.12.6-200.fc41.x86_64 #1 SMP PREEMPT_DYNAMIC Thu Dec 19 21:06:34 UTC 2024 x86_64 GNU/Linux [root@ip-10-75-180-241 fedora]# cat /sys/module/nfs/parameters/localio_enabled N [root@ip-10-75-180-241 fedora]# date ; time mount -v -t nfs -o nfsvers=4.1,rsize=1048576,wsize=1048576,soft,timeo=150,retrans=2,noresvport fs-XXXX.efs.us-east-1.amazonaws.com:/ /var/www/html/ Fri Jan 3 09:52:30 PM UTC 2025 mount.nfs: timeout set for Fri Jan 3 21:54:30 2025 mount.nfs: trying text-based options 'nfsvers=4.1,rsize=1048576,wsize=1048576,soft,timeo=150,retrans=2,noresvport,addr=10.75.180.183,clientaddr=10.75.180.241' real 0m0.037s user 0m0.001s sys 0m0.005s
Can you give more details the server? If it is a Linux server what distro is the server and the version (NVR) is the server. Again, if it is a Linux server, has the server been modified
(In reply to Steve Dickson from comment #11) > Can you give more details the server? > > If it is a Linux server what distro is the > server and the version (NVR) is the server. > > Again, if it is a Linux server, has the server > been modified > The server is an Amazon (AWS) Elastic File System (EFS) (https://en.wikipedia.org/wiki/Amazon_Elastic_File_System) volume. I don't have access to the server, but I suspect it's highly modified :). I opened a support case on their end after we discovered this is related to LOCALIO.
(In reply to Ryan from comment #12) > (In reply to Steve Dickson from comment #11) > > Can you give more details the server? > > > > If it is a Linux server what distro is the > > server and the version (NVR) is the server. > > > > Again, if it is a Linux server, has the server > > been modified > > > > The server is an Amazon (AWS) Elastic File System (EFS) > (https://en.wikipedia.org/wiki/Amazon_Elastic_File_System) volume. I don't > have access to the server, but I suspect it's highly modified :). Me Too! ;-) > > I opened a support case on their end after we discovered this is related to > LOCALIO. Do we (the NFS team) have access to that support case?
(In reply to Ryan from comment #12) > (In reply to Steve Dickson from comment #11) > > Can you give more details the server? > > > > If it is a Linux server what distro is the > > server and the version (NVR) is the server. > > > > Again, if it is a Linux server, has the server > > been modified > > > > The server is an Amazon (AWS) Elastic File System (EFS) > (https://en.wikipedia.org/wiki/Amazon_Elastic_File_System) volume. I don't > have access to the server, but I suspect it's highly modified :). > > I opened a support case on their end after we discovered this is related to > LOCALIO. I'm happy to work with the team at AWS to support LOCALIO (and explain/justify it if need be).
(In reply to Mike Snitzer from comment #14) > I'm happy to work with the team at AWS to support LOCALIO (and > explain/justify it if need be). Thank you, Mike. I'm not sure how to facilitate this. Do you want me to pass along your contact info in the AWS ticket?
I received an update to my AWS ticket: I would like to inform you that I've received the following update from Amazon EFS internal team. "We are able to reproduce the issue and we are working on the solution. In order to getting the customer out of pain, they can temporarily disable LOCALIO on the client instance editing /sys/module/nfs/parameters/localio_enabled with N."
(In reply to Ryan from comment #15) > (In reply to Mike Snitzer from comment #14) > > > I'm happy to work with the team at AWS to support LOCALIO (and > > explain/justify it if need be). > > Thank you, Mike. I'm not sure how to facilitate this. Do you want me to > pass along your contact info in the AWS ticket? Yes, that would be perfect. Please share all 3 of my emails: snitzer snitzer snitzer Apologies for not responding until now.
This issue should be resolved now with the latest upstream kernel via commit 1ff4716f420b ("NFS: always probe for LOCALIO support asynchronously"). See: https://git.kernel.org/linus/1ff4716f420b