OPTS: 13:58:46.521389 - ./nfstest_delegation --nfsversion=4.0 -e /nfsroot --server 192.168.122.153 --client 192.168.122.152 --trcdelay 10 -v all --createlog --keeptraces --rexeclog recall22 OPTS: 13:58:46.521429 - basename = OPTS: 13:58:46.521448 - bugmsgs = None OPTS: 13:58:46.521462 - client = 192.168.122.152 OPTS: 13:58:46.521477 - client-ipaddr = None OPTS: 13:58:46.521490 - client-nfsvers = 4.0,4.1 OPTS: 13:58:46.521503 - createlog = True OPTS: 13:58:46.521514 - createtraces = False OPTS: 13:58:46.521526 - datadir = OPTS: 13:58:46.521537 - export = /nfsroot OPTS: 13:58:46.521548 - file = OPTS: 13:58:46.521562 - filesize = 64k OPTS: 13:58:46.521573 - interface = None OPTS: 13:58:46.521587 - iodelay = 0.1 OPTS: 13:58:46.521599 - iptables = /usr/sbin/iptables OPTS: 13:58:46.521610 - isatty = False OPTS: 13:58:46.521621 - keeptraces = True OPTS: 13:58:46.521632 - kill = /usr/bin/kill OPTS: 13:58:46.521643 - lock-len = 4096 OPTS: 13:58:46.521655 - lock-offset = 0 OPTS: 13:58:46.521666 - lock-poffset = 8192 OPTS: 13:58:46.521677 - messages = /var/log/messages OPTS: 13:58:46.521687 - mtopts = hard,rsize=4096,wsize=4096 OPTS: 13:58:46.521699 - mtpoint = /mnt/t OPTS: 13:58:46.521710 - nconnect = 1 OPTS: 13:58:46.521720 - nfiles = 2 OPTS: 13:58:46.521731 - nfsdebug = OPTS: 13:58:46.521742 - nfserrors = False OPTS: 13:58:46.521753 - nfsstat = /usr/sbin/nfsstat OPTS: 13:58:46.521764 - nfsstats = False OPTS: 13:58:46.521775 - nfsversion = 4.0 OPTS: 13:58:46.521785 - nocleanup = False OPTS: 13:58:46.521796 - nomount = False OPTS: 13:58:46.521807 - notimestamps = False OPTS: 13:58:46.521817 - notty = False OPTS: 13:58:46.521828 - offset-delta = 4k OPTS: 13:58:46.521839 - pktdisp = False OPTS: 13:58:46.521860 - port = 2049 OPTS: 13:58:46.521873 - proto = tcp OPTS: 13:58:46.521884 - rexeclog = True OPTS: 13:58:46.521895 - rmtraces = False OPTS: 13:58:46.521906 - rpcdebug = OPTS: 13:58:46.521917 - rsize = 4k OPTS: 13:58:46.521927 - runtest = recall22 OPTS: 13:58:46.521938 - sec = sys OPTS: 13:58:46.521948 - server = 192.168.122.153 OPTS: 13:58:46.521960 - setup-delay = 4.0 OPTS: 13:58:46.521971 - sudo = /usr/bin/sudo OPTS: 13:58:46.521982 - tag = OPTS: 13:58:46.521993 - tbsize = 192k OPTS: 13:58:46.522004 - tcpdump = /usr/sbin/tcpdump OPTS: 13:58:46.522015 - tmpdir = /tmp OPTS: 13:58:46.522026 - tracepoints = OPTS: 13:58:46.522037 - trcdelay = 10.0 OPTS: 13:58:46.522047 - trcevents = /sys/kernel/debug/tracing/events OPTS: 13:58:46.522058 - trcpipe = /sys/kernel/debug/tracing/trace_pipe OPTS: 13:58:46.522069 - truncate = False OPTS: 13:58:46.522080 - tverbose = 1 OPTS: 13:58:46.522090 - verbose = all OPTS: 13:58:46.522101 - warnings = False OPTS: 13:58:46.522112 - wsize = 4k OPTS: 13:58:46.522123 - xunit-report = False OPTS: 13:58:46.522134 - xunit-report-file = None INFO: 13:58:46.522151 - SYSTEM: Linux zj-rhel92-client1 5.14.0-244.el9.x86_64 #1 SMP PREEMPT_DYNAMIC Wed Jan 25 15:35:31 EST 2023 x86_64 DBG5: 13:58:46.522530 - Get routing info: /usr/sbin/ip route get 192.168.122.153 DBG2: 13:58:46.528470 - Start remote procedure server at 192.168.122.152 DBG7: 13:58:47.042864 - SETUP starts DBG5: 13:58:47.043023 - Sync all buffers to disk DBG2: 13:58:47.118630 - Unmount volume: /usr/bin/sudo umount -f /mnt/t DBG2: 13:58:47.140014 - Mount volume: /usr/bin/sudo mount -o vers=4.0,proto=tcp,sec=sys,hard,rsize=4096,wsize=4096 192.168.122.153:/nfsroot /mnt/t DBG5: 13:58:47.452390 - Get the actual NFS version of mount point: findmnt /mnt/t DBG6: 13:58:47.455952 - NFS version of mount point: 4.0 DBG2: 13:58:47.456067 - Creating file [/mnt/t/nfstest_delegation_20230426_135846_f_001] 65536@0 DBG2: 13:58:47.662452 - Creating file [/mnt/t/nfstest_delegation_20230426_135846_f_002] 65536@0 DBG2: 13:58:47.696017 - Creating file [/mnt/t/nfstest_delegation_20230426_135846_f_003] 65536@0 DBG5: 13:58:47.720817 - Sync all buffers to disk DBG2: 13:58:47.758162 - Unmount volume: /usr/bin/sudo umount -f /mnt/t DBG7: 13:58:47.782349 - SETUP done TIME: 5.270680s *** Recall WRITE delegation with RENAME (DST) with file lock TEST: Running test 'recall22' DBG5: 13:58:51.787163 - Sync all buffers to disk DBG2: 13:58:51.907246 - Unmount volume: /usr/bin/sudo umount -f /mnt/t DBG4: 13:58:51.916964 - Check if mount point directory exists: ssh -t -t 192.168.122.152 "test -e '/mnt/t'" DBG4: 13:58:52.098696 - Check if mount point is a directory: ssh -t -t 192.168.122.152 "test -d '/mnt/t'" DBG5: 13:58:52.275360 - Sync all buffers to disk DBG2: 13:58:52.355149 - Unmount volume: ssh -t -t 192.168.122.152 "/usr/bin/sudo umount -f /mnt/t" DBG2: 13:58:52.552613 - Trace start: /usr/bin/sudo /usr/sbin/tcpdump -i ens3 -n -B 196608 -s 0 -w /tmp/nfstest_delegation_20230426_135846_001.cap host 192.168.122.152 or 192.168.122.151 DBG2: 13:58:53.637829 - Mount volume: /usr/bin/sudo mount -o vers=4.0,proto=tcp,sec=sys,hard,rsize=4096,wsize=4096 192.168.122.153:/nfsroot /mnt/t DBG5: 13:58:53.661597 - Get the actual NFS version of mount point: findmnt /mnt/t DBG6: 13:58:53.664503 - NFS version of mount point: 4.0 DBG2: 13:58:53.664626 - Mount volume: ssh -t -t 192.168.122.152 "/usr/bin/sudo mount -o vers=4.1,proto=tcp,sec=sys,hard,rsize=4096,wsize=4096 192.168.122.153:/nfsroot /mnt/t" DBG5: 13:58:54.262063 - Get the actual NFS version of mount point: ssh -t -t 192.168.122.152 "findmnt /mnt/t" DBG6: 13:58:54.441579 - NFS version of mount point: 4.1 DBG4: 13:58:54.441684 - Open /mnt/t/nfstest_delegation_20230426_135846_f_001 so open owner sticks around DBG2: 13:58:54.442611 - Open file for WRITE [/mnt/t/nfstest_delegation_20230426_135846_f_002] PASS: Open file for WRITE should succeed DBG3: 13:58:54.442839 - Lock /mnt/t/nfstest_delegation_20230426_135846_f_002 (F_SETLK, F_WRLCK) start=0 len=4096 PASS: Lock file with F_WRLCK should succeed DBG3: 13:58:54.443029 - Write file on client holding delegation [/mnt/t/nfstest_delegation_20230426_135846_f_002] PASS: Write file on client holding delegation should succeed DBG2: 13:58:54.543377 - Rename into the file (DST) from another client to recall delegation [nfstest_delegation_20230426_135846_f_003 -> nfstest_delegation_20230426_135846_f_002] PASS: Rename into the file (DST) from another client should succeed DBG3: 13:58:54.558718 - Write file after conflicting operation [/mnt/t/nfstest_delegation_20230426_135846_f_002] PASS: Write file after conflicting operation may succeed DBG4: 13:58:54.707755 - Close /mnt/t/nfstest_delegation_20230426_135846_f_002 DBG5: 13:58:54.709818 - Sync all buffers to disk DBG2: 13:58:54.805635 - Unmount volume: /usr/bin/sudo umount -f /mnt/t DBG5: 13:58:54.831311 - Sync all buffers to disk DBG2: 13:58:54.870586 - Unmount volume: ssh -t -t 192.168.122.152 "/usr/bin/sudo umount -f /mnt/t" DBG5: 13:59:05.135158 - Get all processes: ps -ef DBG5: 13:59:05.156147 - Stopping packet trace capture: /usr/bin/sudo /usr/bin/kill -SIGINT 3267 DBG5: 13:59:05.166850 - Stopping packet trace capture: /usr/bin/sudo /usr/bin/kill -SIGINT 3266 DBG1: 13:59:05.276494 - trace_open [/tmp/nfstest_delegation_20230426_135846_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: 13.527226s DBG7: 13:59:05.313885 - CLEANUP starts DBG3: 13:59:05.313921 - Stop remote procedure server at 192.168.122.152 DBG4: 13:59:05.321722 - Copy remote file: scp 192.168.122.152:/tmp/nfstest_delegation_20230426_135846_01.log /tmp DBG4: 13:59:05.536957 - Removing remote file: ssh -t 192.168.122.152 sudo rm -f /tmp/nfstest_delegation_20230426_135846_01.log DBG2: 13:59:05.718077 - Mount volume: /usr/bin/sudo mount -o vers=4.0,proto=tcp,sec=sys,hard,rsize=4096,wsize=4096 192.168.122.153:/nfsroot /mnt/t DBG5: 13:59:05.742620 - Get the actual NFS version of mount point: findmnt /mnt/t DBG6: 13:59:05.745719 - NFS version of mount point: 4.0 DBG4: 13:59:05.746482 - Removing file [/mnt/t/nfstest_delegation_20230426_135846_f_002] DBG4: 13:59:05.784384 - Removing file [/mnt/t/nfstest_delegation_20230426_135846_f_001] DBG5: 13:59:05.792128 - Sync all buffers to disk DBG2: 13:59:05.857090 - Unmount volume: /usr/bin/sudo umount -f /mnt/t DBG7: 13:59:05.882206 - CLEANUP done Logfile: /tmp/nfstest_delegation_20230426_135846.log 10 tests (9 passed, 1 failed) Total time: 19.366397s