Hello Jeff,
Sorry, I missed you e-mail.
On nfstest_lock I always use the --tverbose 2 option to display each and every test it is running (I should make this option the default for this test script):
./test/nfstest_lock -s knfsd -e /export --nfsopts nfsversion=3 -v all --tverbose 2 --createlog --rexeclog --createtraces --keeptraces --tracepoints nfs optest01
I got some failures as well (RHEL 8.7 client using a RHEL 8.6 server):
Logfile: /tmp/nfstest_lock_20230317_124056.log
232 tests (226 passed, 6 failed)
The --createlog option creates the main logfile.
The --rexeclog creates the logfile (*_01.log) of commands sent to the second process.
The --tracepoints nfs enables and collects the tracepoints for nfs (*_001.out) I don't know if there are any trace points for NLM.
And finally --createtraces create a packet trace for each main test for test scripts which does not inspect the packet trace like nfstest_lock.
ll /tmp/nfstest_lock_20230317_124056*
-rw-r--r--. 1 tcpdump tcpdump 243420 Mar 17 12:41 /tmp/nfstest_lock_20230317_124056_001.cap
-rw-r--r--. 1 root root 398590 Mar 17 12:41 /tmp/nfstest_lock_20230317_124056_001.out
-rw-rw-r--. 1 mora mora 33618 Mar 17 12:41 /tmp/nfstest_lock_20230317_124056_01.log
-rw-rw-r--. 1 mora mora 77438 Mar 17 12:41 /tmp/nfstest_lock_20230317_124056.log
In the first few tests, the main process opens the file for reading and it is granted a delegation, thus no read locks are sent to the server for the main process:
3 2023-03-17 12:40:58.775615 192.168.68.87 -> 192.168.68.86 NFS v4.1 call xid:0xacbfb9d7 SEQUENCE;PUTFH;OPEN;ACCESS;GETATTR CLAIM_FH:0x1bccf28d acc:0x01 deny:0x00
4 2023-03-17 12:40:58.776120 192.168.68.86 -> 192.168.68.87 NFS v4.1 reply xid:0xacbfb9d7 SEQUENCE;PUTFH;OPEN;ACCESS;GETATTR stid:1,0xcfd443db rd_deleg_stid:1,0x776824be
This is the first failure I got on my run for test optest01_004:
INFO: 12:40:58.853433 - Running optest01_004
DBG2: 12:40:58.854301 - Open file for reading [nfstest_lock_20230317_124056_f_001]
DBG1: 12:40:58.854544 - Lock file (F_RDLCK, F_SETLK) off=4096 len=4096 range(4096, 8191)
PASS: Locking byte range should be granted, lock1(O_RDONLY, F_RDLCK, F_SETLK)
DBG2: 12:40:58.854643 - Open file for writing [nfstest_lock_20230317_124056_f_001] on second process
DBG1: 12:40:58.856974 - Lock file (F_WRLCK, F_SETLK) off=4096 len=4096 range(4096, 8191) on second process @2.01
FAIL: Locking with overlapping range on second process should return EAGAIN, lock2(O_WRONLY, F_WRLCK, F_SETLK): no error was returned
In the packet trace, I added markers (a LOOKUP for a file with name as the test) to know which packets belong to which test. There are no locks for the main process because of the delegation but it is clear that the lock on the second process succeeded and it should have failed:
55 2023-03-17 12:40:58.853572 192.168.68.87 -> 192.168.68.86 NFS v4.1 call xid:0xb1bfb9d7 SEQUENCE;PUTFH;LOOKUP;GETFH;GETATTR DH:0xc2e69d7e/optest01_004
56 2023-03-17 12:40:58.854073 192.168.68.86 -> 192.168.68.87 NFS v4.1 reply xid:0xb1bfb9d7 SEQUENCE;PUTFH;LOOKUP NFS4ERR_NOENT
57 2023-03-17 12:40:58.855007 192.168.68.87 -> 192.168.68.86 NFS v3 call xid:0xec26b3a1 GETATTR FH:0x1bccf28d
58 2023-03-17 12:40:58.855577 192.168.68.86 -> 192.168.68.87 NFS v3 reply xid:0xec26b3a1 GETATTR NF3REG mode:0775 nlink:1 uid:1000 gid:1000 size:65536 fileid:154
59 2023-03-17 12:40:58.857401 192.168.68.87 -> 192.168.68.86 NLM v4 call xid:0x26b0a492 LOCK FH:0x1bccf28d off:4096 len:4096 excl:TRUE block:FALSE
60 2023-03-17 12:40:58.857831 192.168.68.86 -> 192.168.68.87 NLM v4 reply xid:0x26b0a492 LOCK NLM4_GRANTED
61 2023-03-17 12:40:58.858600 192.168.68.87 -> 192.168.68.86 NLM v4 call xid:0x27b0a492 LOCK FH:0x1bccf28d off:4096 len:4096 excl:TRUE block:FALSE
62 2023-03-17 12:40:58.859009 192.168.68.86 -> 192.168.68.87 NLM v4 reply xid:0x27b0a492 LOCK NLM4_GRANTED
63 2023-03-17 12:40:58.859698 192.168.68.87 -> 192.168.68.86 NLM v4 call xid:0x28b0a492 UNLOCK FH:0x1bccf28d off:0 len:0
64 2023-03-17 12:40:58.860244 192.168.68.86 -> 192.168.68.87 NLM v4 reply xid:0x28b0a492 UNLOCK NLM4_GRANTED
65 2023-03-17 12:40:58.861183 192.168.68.87 -> 192.168.68.86 NFS v4.1 call xid:0xb2bfb9d7 SEQUENCE;PUTFH;LOOKUP;GETFH;GETATTR DH:0xc2e69d7e/optest01_005
I don't know why the client sends the same lock twice.
--Jorge
________________________________________
From: Jeff Layton <jlayton@xxxxxxxxxx>
Sent: Tuesday, March 14, 2023 4:30 AM
To: Mora, Jorge
Cc: linux-nfs@xxxxxxxxxxxxxxx; Amir Goldstein
Subject: help interpreting nfstest_lock output
NetApp Security WARNING: This is an external email. Do not click links or open attachments unless you recognize the sender and know the content is safe.
Hi Jorge!
I recently fixed a client-side NLM bug that was causing some stalls in
testing. With that, things are running much better but I still see some
failures when running nfstest_lock over NFSv3:
FAIL: Locking with overlapping range on second process (47 passed, 1 failed)
FAIL: Locking byte range on second process (19 passed, 1 failed)
I don't see any indication in the test output of what's actually failing
though. Can you help interpret what's still going wrong with these
tests?
Thanks,
--
Jeff Layton <jlayton@xxxxxxxxxx>
