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