Hi,
While running our recent nfs related tests, we found a delegation regression by nfstests[1]:
======================================================================
/root 10:49# ./test.sh
nfsd sock fh export svc proc fileop auth repcache xdr lockd
INFO: 10:49:21.015795 - SYSTEM: Linux btrfs 5.16.0-rc5-custom #41 SMP PREEMPT Mon Dec 13 10:47:00 CST 2021 x86_64
DBG1: 10:49:21.016102 - Get routing info: /usr/bin/ip route get 192.168.122.77
DBG7: 10:49:21.029015 - SETUP starts
DBG3: 10:49:21.029135 - Sync all buffers to disk
DBG2: 10:49:21.912538 - Unmount volume: umount -f /mnt/t
DBG2: 10:49:21.918442 - Mount volume: mount -o vers=4.2,proto=tcp,sec=sys,hard,rsize=4096,wsize=4096 192.168.122.77:/nfstest /mnt/t
DBG5: 10:49:22.227222 - Get the actual NFS version of mount point: findmnt /mnt/t
DBG6: 10:49:22.235422 - NFS version of mount point: 4.2
DBG3: 10:49:22.235579 - Creating file [/mnt/t/nfstest_delegation_20211213_104921_f_001] 65536@0
DBG3: 10:49:22.305370 - Creating file [/mnt/t/nfstest_delegation_20211213_104921_f_002] 65536@0
DBG3: 10:49:22.367123 - Sync all buffers to disk
DBG2: 10:49:22.382804 - Unmount volume: umount -f /mnt/t
DBG7: 10:49:22.427507 - SETUP done
TIME: 1.416896s
*** Basic READ delegation test
TEST: Running test 'basic01'
DBG3: 10:49:22.430398 - Sync all buffers to disk
DBG2: 10:49:22.439226 - Unmount volume: umount -f /mnt/t
DBG2: 10:49:22.444660 - Start remote procedure server locally
DBG2: 10:49:22.552758 - Trace start: /usr/bin/tcpdump -i lo -n -B 196608 -s 0 -w /tmp/nfstest_delegation_20211213_104921_001.cap host 192.168.122.77
DBG2: 10:49:22.629611 - Mount volume: mount -o vers=4.2,proto=tcp,sec=sys,hard,rsize=4096,wsize=4096 192.168.122.77:/nfstest /mnt/t
DBG5: 10:49:22.758927 - Get the actual NFS version of mount point: findmnt /mnt/t
DBG6: 10:49:22.766713 - NFS version of mount point: 4.2
DBG4: 10:49:22.766848 - Open /mnt/t/nfstest_delegation_20211213_104921_f_001 so open owner sticks around
DBG2: 10:49:22.779669 - Open file for READ [/mnt/t/nfstest_delegation_20211213_104921_f_002]
PASS: Open file for READ should succeed
DBG3: 10:49:22.788609 - Read file [/mnt/t/nfstest_delegation_20211213_104921_f_002]
PASS: Read file should succeed
DBG2: 10:49:22.911668 - Open file for READ on same process [/mnt/t/nfstest_delegation_20211213_104921_f_002]
PASS: Open file for READ on same process should succeed
DBG3: 10:49:22.918108 - Read file on same process [/mnt/t/nfstest_delegation_20211213_104921_f_002]
PASS: Read file on same process should succeed
DBG2: 10:49:23.028735 - Open file for READ from a different process [/mnt/t/nfstest_delegation_20211213_104921_f_002]
PASS: Open file for READ from a different process should succeed
DBG3: 10:49:23.035165 - Read file from a different process [/mnt/t/nfstest_delegation_20211213_104921_f_002]
PASS: Read file from a different process should succeed
DBG3: 10:49:23.144099 - Sync all buffers to disk
DBG2: 10:49:23.161263 - Unmount volume: umount -f /mnt/t
DBG2: 10:49:23.224145 - Trace stop
DBG2: 10:49:33.231485 - Stopping packet trace capture: stopping process 1550
DBG1: 10:49:33.311940 - trace_open [/tmp/nfstest_delegation_20211213_104921_001.cap]
FAIL: OPEN should be sent
PASS: OPEN should be sent with CLAIM_NULL
PASS: OPEN should be sent with the name of the file to be opened
PASS: OPEN should be sent with the filehandle of the directory
FAIL: READ delegation should be granted
TIME: 10.946048s
=============================================================
/root 10:51# cat test.sh
dmesg -C
rpcdebug -m nfsd -s all
export PYTHONPATH=/root/nfstest/
cd /root/nfstest/test
./nfstest_delegation --nfsversion=4.2 -e /nfstest --server 192.168.122.77 --trcdelay 10 --runtest basic01 -v debug
rpcdebug -m nfsd -c all
=============================================================
The output of dmesg is on link[2].
The test first opens and creates file1 and file2. Does umount and mount again,
opens the files with O_RDONLY, and tries to get a READ delegation from the server.
However, the reply sever sent did not contain a delegation so it failed.
The test fails with kernel version v5.14..v5.16-rc5.
Please correct me if something below is wrong :)
After some investigations, I realized there is nfsd file cache mechanism since
the commit 65294c1f2c5e ("nfsd: add a new struct file caching facility to nfsd").
The last refcount of one dentry and the inode is always held by the nfs file lru list.
The refcount will be freed when nfsd_file_gc() is called. And the times to call it
are 1) NFSD_LAUNDRETTE_DELAY elapsed. 2) nfsd is shutting down.
In the above scenario, the client closed the file just created which triggered
nfsd_file_put() to queue nfsd_filecache_laundrette and umountd.
However, before the cleanup start (in NFSD_LAUNDRETTE_DELAY), the client
mounted and opened the file again. nfsd found the dentry because nfsd lru list entry
is still holding it. And nfsd4_check_conflicting_opens() refused to give a delegation
(-EAGAIN) because inode->i_writecount is 1 even @fp->fi_fds[O_RDONLY] is not NULL.
And the server won't give any READ delegation until the second umount (nfsd_file_free()
called by the nfsd_file_gc_worker()).
So I wonder if it's a real regression/bug or an expected "cost" of speedup on
nfsd file caches?
[1]: http://git.linux-nfs.org/?p=mora/nfstest.git;a=summary
[2]: https://pastebin.com/w8eBF5Qi
Thanks
--
Su
