Re: nfstest_delegation test can not stop

["Mora, Jorge" <Jorge.Mora@netapp.com>]

Hello,

First of all, the --client option can be used successfully when the system in which you are running the test is able to capture the traffic for both clients, e.g., when you are running VMware and both clients are VMs. If you are using real clients, tcpdump will only capture traffic for the local system.

./nfstest_delegation -h
  Test options:
    --runtest=RUNTEST
          Comma separated list of tests to run, if list starts with a '^' then
          all tests are run except the ones listed [default: 'all']
    --client=CLIENT
          Remote NFS client and options used for recall delegation tests.
          Clients are separated by a ',' and each client definition is a list
          of arguments separated by a ':' given in the following order if
          positional arguments is used (see examples):
          clientname:server:export:nfsversion:port:proto:sec:mtpoint [default:
          'nfsversion=3:proto=tcp:port=2049']
    --client-nfsvers=CLIENT_NFSVERS
          Comma separated list of valid NFS versions to use in the --client
          option. An NFS version from this list, which is different than that
          given by --nfsversion, is selected and included in the --client
          option [default: 4.0,4.1]

The second client is a combination of --client and --client-nfsvers and the default for --client is 'nfsversion=3:proto=tcp:port=2049'. This means that the mount for the second 'client' is on the main client with the following nfs mount options: 'nfsversion=4.0:proto=tcp:port=2049' or 'nfsversion=4.1:proto=tcp:port=2049' depending on the value for option --nfsversion. In you case, --nfsversion=4 (if you mean 4.0) the mount options for the second client should be 'nfsversion=4.1...'. This way main mount is 4.0 (holding delegation) and the second mount is 4.1 (recall delegation) on the same system so the network traffic could be fully captured.

Of course, if you specify --nfsversion=4, the client will mount either 4.2, 4.1 or 4.0 (in your logs: NFS version of mount point: 4.2). You need to explicitly specify the NFS version as 4.0, 4.1 or 4.2.

The reason why the test is hanging is because the server is sending NFS4ERR_DELAY to COMMIT:
133 2023-03-30 07:46:22.533580 192.168.122.110 -> 192.168.122.108 NFS   v4.2 reply xid:0xfd10f3db SEQUENCE;PUTFH;OPEN;GETFH;ACCESS;GETATTR stid:1,0xe37587e3 rd_deleg_stid:1,0xf1c0280d FH:0x634cb2d9
135 2023-03-30 07:46:22.533973 192.168.122.110 -> 192.168.122.108 NFS   v4.2 reply xid:0xfe10f3db SEQUENCE;PUTFH;OPEN;GETFH;ACCESS;GETATTR stid:1,0x497c4f68  FH:0x62ab8136
136 2023-03-30 07:46:22.534191 192.168.122.108 -> 192.168.122.110 NFS   v4.2 call  xid:0xff10f3db SEQUENCE;PUTFH;LOCK       FH:0x62ab8136 WRITE_LT off:0 len:4096 open(stid:1,0x497c4f68, seqid:0) seqid:0
137 2023-03-30 07:46:22.534304 192.168.122.110 -> 192.168.122.108 NFS   v4.2 reply xid:0xff10f3db SEQUENCE;PUTFH;LOCK       stid:1,0xd4ab77d1
146 2023-03-30 07:46:22.659988 192.168.122.108 -> 192.168.122.110 NFS   v4.2 call  xid:0x0011f3db SEQUENCE;PUTFH;WRITE;GETATTR FH:0x62ab8136 stid:0,0xd4ab77d1 off:0 len:4096 UNSTABLE4
147 2023-03-30 07:46:22.660009 192.168.122.108 -> 192.168.122.110 NFS   v4.2 call  xid:0x0111f3db SEQUENCE;PUTFH;WRITE;GETATTR FH:0x62ab8136 stid:0,0xd4ab77d1 off:4096 len:4096 UNSTABLE4
...
191 2023-03-30 07:46:22.660695 192.168.122.108 -> 192.168.122.110 NFS   v4.2 call  xid:0x1011f3db SEQUENCE;PUTFH;COMMIT     FH:0x62ab8136 off:0 len:0
192 2023-03-30 07:46:22.672090 192.168.122.110 -> 192.168.122.108 NFS   v4.2 reply xid:0x1011f3db SEQUENCE;PUTFH;COMMIT     NFS4ERR_DELAY
194 2023-03-30 07:46:22.778177 192.168.122.108 -> 192.168.122.110 NFS   v4.2 call  xid:0x1111f3db SEQUENCE;PUTFH;COMMIT     FH:0x62ab8136 off:0 len:0
195 2023-03-30 07:46:22.779064 192.168.122.110 -> 192.168.122.108 NFS   v4.2 reply xid:0x1111f3db SEQUENCE;PUTFH;COMMIT     NFS4ERR_DELAY
197 2023-03-30 07:46:22.882100 192.168.122.108 -> 192.168.122.110 NFS   v4.2 call  xid:0x1211f3db SEQUENCE;PUTFH;COMMIT     FH:0x62ab8136 off:0 len:0
198 2023-03-30 07:46:22.882566 192.168.122.110 -> 192.168.122.108 NFS   v4.2 reply xid:0x1211f3db SEQUENCE;PUTFH;COMMIT     NFS4ERR_DELAY
200 2023-03-30 07:46:22.986157 192.168.122.108 -> 192.168.122.110 NFS   v4.2 call  xid:0x1311f3db SEQUENCE;PUTFH;COMMIT     FH:0x62ab8136 off:0 len:0
201 2023-03-30 07:46:22.986931 192.168.122.110 -> 192.168.122.108 NFS   v4.2 reply xid:0x1311f3db SEQUENCE;PUTFH;COMMIT     NFS4ERR_DELAY

As Jeff mentioned earlier, Linux server does not grant write delegations. I don't know what server are you using but the OPEN clearly shows it did not grant a write delegation so this test should fail.

Here is a sample run against a RHEL 8.6 server:
./nfstest_delegation -s 192.168.68.86 -e /export --nfsversion 4.0 -v all --createlog --keeptraces --rexeclog --tracepoints nfs,nfs4 recall22

*** Recall WRITE delegation with RENAME (DST) with file lock
    TEST: Running test 'recall22'
    DBG5: 10:48:51.644258 - Sync all buffers to disk
    DBG2: 10:48:51.651724 - Unmount volume: /usr/bin/sudo umount -f /mnt/t
    DBG5: 10:48:51.684054 - Sync all buffers to disk
    DBG2: 10:48:51.685482 - Unmount volume: /usr/bin/sudo umount -f /mnt/t_01
    DBG2: 10:48:51.719133 - Enable trace points: /usr/bin/sudo sh -c "echo 1 > /sys/kernel/debug/tracing/events/nfs/enable"
    DBG2: 10:48:51.761795 - Enable trace points: /usr/bin/sudo sh -c "echo 1 > /sys/kernel/debug/tracing/events/nfs4/enable"
    DBG2: 10:48:51.805703 - Capturing trace points: /usr/bin/sudo sh -c "cat /sys/kernel/debug/tracing/trace_pipe > /tmp/nfstest_delegation_20230330_104846_001.out"
    DBG2: 10:48:51.808284 - Trace start: /usr/bin/sudo /usr/sbin/tcpdump -i ens160 -n -B 196608 -s 0 -w /tmp/nfstest_delegation_20230330_104846_001.cap host 192.168.68.87
    DBG2: 10:48:52.904843 - Mount volume: /usr/bin/sudo mount -o vers=4.0,proto=tcp,sec=sys,hard,rsize=4096,wsize=4096 192.168.68.86:/export /mnt/t
    DBG5: 10:48:53.045345 - Get the actual NFS version of mount point: findmnt /mnt/t
    DBG6: 10:48:53.053811 -     NFS version of mount point: 4.0
    DBG2: 10:48:53.054069 - Mount volume: /usr/bin/sudo mount -o vers=4.1,proto=tcp,sec=sys,hard,rsize=4096,wsize=4096 192.168.68.86:/export /mnt/t_01
    DBG5: 10:48:53.194449 - Get the actual NFS version of mount point: findmnt /mnt/t_01
    DBG6: 10:48:53.202076 -     NFS version of mount point: 4.1
    DBG4: 10:48:53.202297 - Open /mnt/t/nfstest_delegation_20230330_104846_f_001 so open owner sticks around
    DBG2: 10:48:53.207257 - Open file for WRITE [/mnt/t/nfstest_delegation_20230330_104846_f_002]
    PASS: Open file for WRITE should succeed
    DBG3: 10:48:53.208168 - Lock /mnt/t/nfstest_delegation_20230330_104846_f_002 (F_SETLK, F_WRLCK) start=0 len=4096
    PASS: Lock file with F_WRLCK should succeed
    DBG3: 10:48:53.209489 - Write file on client holding delegation [/mnt/t/nfstest_delegation_20230330_104846_f_002]
    PASS: Write file on client holding delegation should succeed
    DBG2: 10:48:53.310548 - Rename into the file (DST) from another client to recall delegation [nfstest_delegation_20230330_104846_f_003 -> nfstest_delegation_20230330_104846_f_002]
    PASS: Rename into the file (DST) from another client should succeed
    DBG3: 10:48:53.320851 - Write file after conflicting operation [/mnt/t/nfstest_delegation_20230330_104846_f_002]
    PASS: Write file after conflicting operation may succeed
    DBG4: 10:48:53.447733 - Close /mnt/t/nfstest_delegation_20230330_104846_f_002
    DBG5: 10:48:53.450185 - Sync all buffers to disk
    DBG2: 10:48:53.457125 - Unmount volume: /usr/bin/sudo umount -f /mnt/t
    DBG5: 10:48:53.515896 - Sync all buffers to disk
    DBG2: 10:48:53.520120 - Unmount volume: /usr/bin/sudo umount -f /mnt/t_01
    DBG5: 10:48:55.580838 - Get all processes: ps -ef
    DBG5: 10:48:55.621321 - Stopping packet trace capture: /usr/bin/sudo /usr/bin/kill -SIGINT 348494
    DBG5: 10:48:55.656126 - Stopping packet trace capture: /usr/bin/sudo /usr/bin/kill -SIGINT 348489
    DBG2: 10:48:55.788319 - Disable trace points: /usr/bin/sudo sh -c "echo 0 > /sys/kernel/debug/tracing/events/nfs/enable"
    DBG2: 10:48:55.829243 - Disable trace points: /usr/bin/sudo sh -c "echo 0 > /sys/kernel/debug/tracing/events/nfs4/enable"
    DBG5: 10:48:55.875925 - Get all processes: ps -ef
    DBG2: 10:48:55.908161 - Stopping trace points capture: /usr/bin/sudo /usr/bin/kill -SIGINT 348493
    DBG2: 10:48:55.939992 - Stopping trace points capture: /usr/bin/sudo /usr/bin/kill -SIGINT 348492
    DBG2: 10:48:55.972241 - Stopping trace points capture: /usr/bin/sudo /usr/bin/kill -SIGINT 348488
    DBG1: 10:48:56.104525 - trace_open [/tmp/nfstest_delegation_20230330_104846_001.cap]
    PASS: 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: WRITE delegation should be granted
    TIME: 4.570563s

I also added option --tracepoints to collect all nfs and nfs4 tracepoints. These are the files that are created:
ll /tmp/nfstest_delegation_20230330_104846*
-rw-r--r--. 1 tcpdump tcpdump 106776 Mar 30 10:48 /tmp/nfstest_delegation_20230330_104846_001.cap (packet trace)
-rw-r--r--. 1 root    root     64218 Mar 30 10:48 /tmp/nfstest_delegation_20230330_104846_001.out (tracepoints)
-rw-rw-r--. 1 mora    mora       317 Mar 30 10:48 /tmp/nfstest_delegation_20230330_104846_01.log  (second 'client' process log file)
-rw-rw-r--. 1 mora    mora      9779 Mar 30 10:48 /tmp/nfstest_delegation_20230330_104846.log     (main logfile)


--Jorge

________________________________________
From: zhoujie2011@fujitsu.com <zhoujie2011@fujitsu.com>
Sent: Wednesday, March 29, 2023 7:42 PM
To: Mora, Jorge; Jeff Layton
Cc: linux-nfs
Subject: Re: nfstest_delegation test can not stop

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,

> I am still waiting for all the files created for the run, not just the output to the screen:
>
> /tmp/nfstest_delegation_20230317_170647*
The log file is attached.

best regards,

>
> ping
>
> On 3/17/23 16:58, zhoujie2011 wrote:
>> hi,
>>
>>   > Can you provide a log file for the run?
>> run following command and test result is attached.
>> ./nfstest_delegation --nfsversion=4 -e /nfsroot --server 192.168.122.110
>> --client 192.168.122.109 --trcdelay 10 -v all --createlog --keeptraces
>> --rexeclog recall22 >nfstest-delegationv4-log_recall22 2>&1
>>
>> In server run "cat /etc/exports" output is following.
>> /nfsroot      *(rw,insecure,no_subtree_check,no_root_squash,fsid=1)
>>
>> best regards,
>>
>> On 3/15/23 22:28, Mora, Jorge wrote:
>>> Hello,
>>>
>>> Can you provide a log file for the run?
>>>
>>> ./nfstest_delegation -s 192.168.68.86 -e /export -v all --createlog
>>> --keeptraces --rexeclog recall22
>>>
>>> --Jorge
>>>
>>> *From: *Jeff Layton <jlayton@kernel.org>
>>> *Date: *Wednesday, March 15, 2023 at 5:40 AM
>>> *To: *zhoujie2011@fujitsu.com <zhoujie2011@fujitsu.com>, Mora, Jorge
>>> <Jorge.Mora@netapp.com>
>>> *Cc: *linux-nfs <linux-nfs@vger.kernel.org>
>>> *Subject: *Re: nfstest_delegation test can not stop
>>>
>>> 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.
>>>
>>>
>>>
>>>
>>> On Tue, 2023-03-14 at 02:28 +0000, zhoujie2011@fujitsu.com wrote:
>>>   > hi,
>>>   >
>>>   > I run following test command and stuck at recall12 recall14 recall20
>>>   > recall22 recall40 recall42 recall48 recall50.
>>>   >
>>>   > ./nfstest_delegation --nfsversion=4 -e /nfsroot --server <server ip>
>>>   > --client <client2 ip> --trcdelay 10
>>>   > ./nfstest_delegation --nfsversion=4.1 -e /nfsroot --server  <server
>>> ip>
>>>   > --client <client2 ip> --trcdelay 10
>>>   > ./nfstest_delegation --nfsversion=4.2 -e /nfsroot --server  <server
>>> ip>
>>>   > --client <client2 ip> --trcdelay 10
>>>   >
>>>   > recall12 recall14 recall20 recall22 recall40 recall42 recall48
>>> recall50
>>>   > tests write files after remove.
>>>   > After comment out above testcases result is:
>>>   > 646 tests (588 passed, 58 failed)
>>>   > FAIL: WRITE delegation should be granted
>>>   >
>>>   > run ./nfstest_dio have following messages.
>>>   > INFO: 16:19:51.455222 - WRITE delegations are not available --
>>> skipping
>>>   > tests expecting write delegations
>>>   >
>>>   > test OS: RHEL9.2 Nightly Build
>>>   > Why do these testcases can not stop?
>>>
>>> Are you asking why these testcases don't pass? If you're testing against
>>> the kernel's NFS server then it's because it does not (yet) support
>>> write delegations.
>>> --
>>> Jeff Layton <jlayton@kernel.org>
>>>
>>
>
> --
> ------------------------------------------------
> zhoujie
> Dept 1
> No. 6 Wenzhu Road,
> Nanjing, 210012, China
> TEL：+86+25-86630566-8508
> FUJITSU INTERNAL：7998-8508
> E-Mail：zhoujie2011@fujitsu.com
> ------------------------------------------------

--
------------------------------------------------
zhoujie
Dept 1
No. 6 Wenzhu Road,
Nanjing, 210012, China
TEL：+86+25-86630566-8508
FUJITSU INTERNAL：7998-8508
E-Mail：zhoujie2011@fujitsu.com
------------------------------------------------