"[PATCH] nfsd: rework refcounting in filecache" caused nfstest/test/nfstest_delegation stuck

From: Jie Zhou (Fujitsu)
Date: Wed Apr 26 2023 - 23:51:47 EST

Next message: Bjorn Helgaas: "Re: [GIT PULL] PCI changes for v6.4"
Previous message: Takashi Sakamoto: "[GIT PULL] firewire updates for 6.4-rc1"
Next in thread: dai . ngo: "Re: "[PATCH] nfsd: rework refcounting in filecache" caused nfstest/test/nfstest_delegation stuck"
Messages sorted by: [ date ] [ thread ] [ subject ] [ author ]

hi,

Download nfstest program from
"http://git.linux-nfs.org/?p=mora/nfstest.git;a=summary";.
And run following test command and stuck at recall12 recall14
recall20 recall22 recall40 recall42 recall48 recall50.
./nfstest_delegation --nfsversion=4.0 -e /nfsroot --server <server
ip> --client <client2 ip> --trcdelay 10
test OS: RHEL9.2 Nightly Build

After I bisect linux kerenl, found that following patch caused above
bug.
From ac3a2585f018f10039b4a856dcb122da88c1c1c9 Mon Sep 17 00:00:00 2001
From: Jeff Layton <jlayton@xxxxxxxxxx>
Date: Sun, 11 Dec 2022 06:19:33 -0500
Subject: [PATCH] nfsd: rework refcounting in filecache

Run following command at different kernel version.
./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
>nfstest-delegationv4-log_recall22 2>&1

The following test result are attached.
kernel:
commit 0cfd8703e7da687924371e9bc77a025bdeba9637
Merge: 793582ff47f8 d3f2c402e448
Author: Linus Torvalds <torvalds@xxxxxxxxxxxxxxxxxxxx>
Date: Tue Apr 25 18:44:10 2023 -0700
Merge tag 'pm-6.4-rc1' of
git://git.kernel.org/pub/scm/linux/kernel/git/rafael/linux-pm
result:
test program stuck
log:
nfstest-delegationv4-log_recall22_6.3.0

kernel:
commit ac3a2585f018f10039b4a856dcb122da88c1c1c9
Author: Jeff Layton <jlayton@xxxxxxxxxx>
Date: Sun Dec 11 06:19:33 2022 -0500
nfsd: rework refcounting in filecache
result:
test program stuck
log:
nfstest-delegationv4-log_recall22_ac3a2585f018

kernel:
commit e78e274eb22d966258a3845acc71d3c5b8ee2ea8
Author: Kees Cook <keescook@xxxxxxxxxxxx>
Date: Fri Dec 2 12:48:59 2022 -0800
NFSD: Avoid clashing function prototypes
result:
test program stop normally
log:
nfstest-delegationv4-log_recall22_e78e274eb22d

best regards,
--
------------------------------------------------
zhoujie
Dept 1
No. 6 Wenzhu Road,
Nanjing, 210012, China
TEL：+86+25-86630566-8508
FUJITSU INTERNAL：7998-8508
E-Mail：zhoujie2011@xxxxxxxxxxx
------------------------------------------------ OPTS: 11:11:23.797348 - ./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: 11:11:23.797388 - basename =
OPTS: 11:11:23.797406 - bugmsgs = None
OPTS: 11:11:23.797419 - client = 192.168.122.152
OPTS: 11:11:23.797431 - client-ipaddr = None
OPTS: 11:11:23.797444 - client-nfsvers = 4.0,4.1
OPTS: 11:11:23.797457 - createlog = True
OPTS: 11:11:23.797469 - createtraces = False
OPTS: 11:11:23.797481 - datadir =
OPTS: 11:11:23.797492 - export = /nfsroot
OPTS: 11:11:23.797503 - file =
OPTS: 11:11:23.797514 - filesize = 64k
OPTS: 11:11:23.797527 - interface = None
OPTS: 11:11:23.797542 - iodelay = 0.1
OPTS: 11:11:23.797553 - iptables = /usr/sbin/iptables
OPTS: 11:11:23.797564 - isatty = False
OPTS: 11:11:23.797575 - keeptraces = True
OPTS: 11:11:23.797586 - kill = /usr/bin/kill
OPTS: 11:11:23.797597 - lock-len = 4096
OPTS: 11:11:23.797608 - lock-offset = 0
OPTS: 11:11:23.797620 - lock-poffset = 8192
OPTS: 11:11:23.797630 - messages = /var/log/messages
OPTS: 11:11:23.797641 - mtopts = hard,rsize=4096,wsize=4096
OPTS: 11:11:23.797652 - mtpoint = /mnt/t
OPTS: 11:11:23.797663 - nconnect = 1
OPTS: 11:11:23.797673 - nfiles = 2
OPTS: 11:11:23.797684 - nfsdebug =
OPTS: 11:11:23.797695 - nfserrors = False
OPTS: 11:11:23.797705 - nfsstat = /usr/sbin/nfsstat
OPTS: 11:11:23.797726 - nfsstats = False
OPTS: 11:11:23.797738 - nfsversion = 4.0
OPTS: 11:11:23.797748 - nocleanup = False
OPTS: 11:11:23.797759 - nomount = False
OPTS: 11:11:23.797770 - notimestamps = False
OPTS: 11:11:23.797781 - notty = False
OPTS: 11:11:23.797791 - offset-delta = 4k
OPTS: 11:11:23.797802 - pktdisp = False
OPTS: 11:11:23.797812 - port = 2049
OPTS: 11:11:23.797824 - proto = tcp
OPTS: 11:11:23.797837 - rexeclog = True
OPTS: 11:11:23.797847 - rmtraces = False
OPTS: 11:11:23.797858 - rpcdebug =
OPTS: 11:11:23.797868 - rsize = 4k
OPTS: 11:11:23.797879 - runtest = recall22
OPTS: 11:11:23.797890 - sec = sys
OPTS: 11:11:23.797901 - server = 192.168.122.153
OPTS: 11:11:23.797912 - setup-delay = 4.0
OPTS: 11:11:23.797923 - sudo = /usr/bin/sudo
OPTS: 11:11:23.797934 - tag =
OPTS: 11:11:23.797945 - tbsize = 192k
OPTS: 11:11:23.797955 - tcpdump = /usr/sbin/tcpdump
OPTS: 11:11:23.797966 - tmpdir = /tmp
OPTS: 11:11:23.797976 - tracepoints =
OPTS: 11:11:23.797988 - trcdelay = 10.0
OPTS: 11:11:23.797998 - trcevents = /sys/kernel/debug/tracing/events
OPTS: 11:11:23.798009 - trcpipe = /sys/kernel/debug/tracing/trace_pipe
OPTS: 11:11:23.798020 - truncate = False
OPTS: 11:11:23.798030 - tverbose = 1
OPTS: 11:11:23.798041 - verbose = all
OPTS: 11:11:23.798051 - warnings = False
OPTS: 11:11:23.798062 - wsize = 4k
OPTS: 11:11:23.798073 - xunit-report = False
OPTS: 11:11:23.798085 - xunit-report-file = None

INFO: 11:11:23.798101 - 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: 11:11:23.798497 - Get routing info: /usr/sbin/ip route get 192.168.122.153
DBG2: 11:11:23.802100 - Start remote procedure server at 192.168.122.152
DBG7: 11:11:24.216221 - SETUP starts
DBG5: 11:11:24.216353 - Sync all buffers to disk
DBG2: 11:11:24.252951 - Unmount volume: /usr/bin/sudo umount -f /mnt/t
DBG2: 11:11:24.264966 - 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: 11:11:24.303836 - Get the actual NFS version of mount point: findmnt /mnt/t
DBG6: 11:11:24.307553 - NFS version of mount point: 4.0
DBG2: 11:11:24.307638 - Creating file [/mnt/t/nfstest_delegation_20230426_111123_f_001] 65536@0
DBG2: 11:11:24.375956 - Creating file [/mnt/t/nfstest_delegation_20230426_111123_f_002] 65536@0
DBG2: 11:11:24.401048 - Creating file [/mnt/t/nfstest_delegation_20230426_111123_f_003] 65536@0
DBG5: 11:11:24.426116 - Sync all buffers to disk
DBG2: 11:11:24.443417 - Unmount volume: /usr/bin/sudo umount -f /mnt/t
DBG7: 11:11:24.473468 - SETUP done
TIME: 4.684914s

*** Recall WRITE delegation with RENAME (DST) with file lock
TEST: Running test 'recall22'
DBG5: 11:11:28.478358 - Sync all buffers to disk
DBG2: 11:11:28.533355 - Unmount volume: /usr/bin/sudo umount -f /mnt/t
DBG4: 11:11:28.546005 - Check if mount point directory exists: ssh -t -t 192.168.122.152 "test -e '/mnt/t'"
DBG4: 11:11:28.727029 - Check if mount point is a directory: ssh -t -t 192.168.122.152 "test -d '/mnt/t'"
DBG5: 11:11:28.907466 - Sync all buffers to disk
DBG2: 11:11:28.932577 - Unmount volume: ssh -t -t 192.168.122.152 "/usr/bin/sudo umount -f /mnt/t"
DBG2: 11:11:29.123644 - Trace start: /usr/bin/sudo /usr/sbin/tcpdump -i ens3 -n -B 196608 -s 0 -w /tmp/nfstest_delegation_20230426_111123_001.cap host 192.168.122.151 or 192.168.122.152
DBG2: 11:11:30.172102 - 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: 11:11:30.202242 - Get the actual NFS version of mount point: findmnt /mnt/t
DBG6: 11:11:30.205016 - NFS version of mount point: 4.0
DBG2: 11:11:30.205132 - 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: 11:11:30.503255 - Get the actual NFS version of mount point: ssh -t -t 192.168.122.152 "findmnt /mnt/t"
DBG6: 11:11:30.682155 - NFS version of mount point: 4.1
DBG4: 11:11:30.682246 - Open /mnt/t/nfstest_delegation_20230426_111123_f_001 so open owner sticks around
DBG2: 11:11:30.682968 - Open file for WRITE [/mnt/t/nfstest_delegation_20230426_111123_f_002]
PASS: Open file for WRITE should succeed
DBG3: 11:11:30.683219 - Lock /mnt/t/nfstest_delegation_20230426_111123_f_002 (F_SETLK, F_WRLCK) start=0 len=4096
PASS: Lock file with F_WRLCK should succeed
DBG3: 11:11:30.683424 - Write file on client holding delegation [/mnt/t/nfstest_delegation_20230426_111123_f_002]
PASS: Write file on client holding delegation should succeed
DBG2: 11:11:30.783744 - Rename into the file (DST) from another client to recall delegation [nfstest_delegation_20230426_111123_f_003 -> nfstest_delegation_20230426_111123_f_002]
PASS: Rename into the file (DST) from another client should succeed
OPTS: 13:39:41.968621 - ./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:39:41.968663 - basename =
OPTS: 13:39:41.968681 - bugmsgs = None
OPTS: 13:39:41.968695 - client = 192.168.122.152
OPTS: 13:39:41.968709 - client-ipaddr = None
OPTS: 13:39:41.968721 - client-nfsvers = 4.0,4.1
OPTS: 13:39:41.968733 - createlog = True
OPTS: 13:39:41.968745 - createtraces = False
OPTS: 13:39:41.968755 - datadir =
OPTS: 13:39:41.968766 - export = /nfsroot
OPTS: 13:39:41.968778 - file =
OPTS: 13:39:41.968791 - filesize = 64k
OPTS: 13:39:41.968803 - interface = None
OPTS: 13:39:41.968818 - iodelay = 0.1
OPTS: 13:39:41.968829 - iptables = /usr/sbin/iptables
OPTS: 13:39:41.968840 - isatty = False
OPTS: 13:39:41.968851 - keeptraces = True
OPTS: 13:39:41.968862 - kill = /usr/bin/kill
OPTS: 13:39:41.968873 - lock-len = 4096
OPTS: 13:39:41.968884 - lock-offset = 0
OPTS: 13:39:41.968896 - lock-poffset = 8192
OPTS: 13:39:41.968906 - messages = /var/log/messages
OPTS: 13:39:41.968917 - mtopts = hard,rsize=4096,wsize=4096
OPTS: 13:39:41.968928 - mtpoint = /mnt/t
OPTS: 13:39:41.968939 - nconnect = 1
OPTS: 13:39:41.968957 - nfiles = 2
OPTS: 13:39:41.968969 - nfsdebug =
OPTS: 13:39:41.968980 - nfserrors = False
OPTS: 13:39:41.968990 - nfsstat = /usr/sbin/nfsstat
OPTS: 13:39:41.969001 - nfsstats = False
OPTS: 13:39:41.969012 - nfsversion = 4.0
OPTS: 13:39:41.969022 - nocleanup = False
OPTS: 13:39:41.969033 - nomount = False
OPTS: 13:39:41.969043 - notimestamps = False
OPTS: 13:39:41.969054 - notty = False
OPTS: 13:39:41.969065 - offset-delta = 4k
OPTS: 13:39:41.969076 - pktdisp = False
OPTS: 13:39:41.969087 - port = 2049
OPTS: 13:39:41.969098 - proto = tcp
OPTS: 13:39:41.969110 - rexeclog = True
OPTS: 13:39:41.969121 - rmtraces = False
OPTS: 13:39:41.969131 - rpcdebug =
OPTS: 13:39:41.969142 - rsize = 4k
OPTS: 13:39:41.969152 - runtest = recall22
OPTS: 13:39:41.969163 - sec = sys
OPTS: 13:39:41.969173 - server = 192.168.122.153
OPTS: 13:39:41.969186 - setup-delay = 4.0
OPTS: 13:39:41.969197 - sudo = /usr/bin/sudo
OPTS: 13:39:41.969207 - tag =
OPTS: 13:39:41.969218 - tbsize = 192k
OPTS: 13:39:41.969228 - tcpdump = /usr/sbin/tcpdump
OPTS: 13:39:41.969239 - tmpdir = /tmp
OPTS: 13:39:41.969250 - tracepoints =
OPTS: 13:39:41.969261 - trcdelay = 10.0
OPTS: 13:39:41.969272 - trcevents = /sys/kernel/debug/tracing/events
OPTS: 13:39:41.969283 - trcpipe = /sys/kernel/debug/tracing/trace_pipe
OPTS: 13:39:41.969294 - truncate = False
OPTS: 13:39:41.969304 - tverbose = 1
OPTS: 13:39:41.969315 - verbose = all
OPTS: 13:39:41.969325 - warnings = False
OPTS: 13:39:41.969336 - wsize = 4k
OPTS: 13:39:41.969347 - xunit-report = False
OPTS: 13:39:41.969359 - xunit-report-file = None

INFO: 13:39:41.969376 - 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:39:41.969769 - Get routing info: /usr/sbin/ip route get 192.168.122.153
DBG2: 13:39:41.975744 - Start remote procedure server at 192.168.122.152
DBG7: 13:39:42.390831 - SETUP starts
DBG5: 13:39:42.391003 - Sync all buffers to disk
DBG2: 13:39:42.435502 - Unmount volume: /usr/bin/sudo umount -f /mnt/t
DBG2: 13:39:42.456351 - 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:39:42.762404 - Get the actual NFS version of mount point: findmnt /mnt/t
DBG6: 13:39:42.766005 - NFS version of mount point: 4.0
DBG2: 13:39:42.766116 - Creating file [/mnt/t/nfstest_delegation_20230426_133941_f_001] 65536@0
DBG2: 13:39:42.843108 - Creating file [/mnt/t/nfstest_delegation_20230426_133941_f_002] 65536@0
DBG2: 13:39:42.869074 - Creating file [/mnt/t/nfstest_delegation_20230426_133941_f_003] 65536@0
DBG5: 13:39:42.901989 - Sync all buffers to disk
DBG2: 13:39:42.920251 - Unmount volume: /usr/bin/sudo umount -f /mnt/t
DBG7: 13:39:42.943900 - SETUP done
TIME: 4.985141s

*** Recall WRITE delegation with RENAME (DST) with file lock
TEST: Running test 'recall22'
DBG5: 13:39:46.948755 - Sync all buffers to disk
DBG2: 13:39:46.999247 - Unmount volume: /usr/bin/sudo umount -f /mnt/t
DBG4: 13:39:47.009069 - Check if mount point directory exists: ssh -t -t 192.168.122.152 "test -e '/mnt/t'"
DBG4: 13:39:47.187663 - Check if mount point is a directory: ssh -t -t 192.168.122.152 "test -d '/mnt/t'"
DBG5: 13:39:47.365745 - Sync all buffers to disk
DBG2: 13:39:47.384329 - Unmount volume: ssh -t -t 192.168.122.152 "/usr/bin/sudo umount -f /mnt/t"
DBG2: 13:39:47.580512 - Trace start: /usr/bin/sudo /usr/sbin/tcpdump -i ens3 -n -B 196608 -s 0 -w /tmp/nfstest_delegation_20230426_133941_001.cap host 192.168.122.151 or 192.168.122.152
DBG2: 13:39:48.669627 - 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:39:48.703165 - Get the actual NFS version of mount point: findmnt /mnt/t
DBG6: 13:39:48.705938 - NFS version of mount point: 4.0
DBG2: 13:39:48.706064 - 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:39:49.244565 - Get the actual NFS version of mount point: ssh -t -t 192.168.122.152 "findmnt /mnt/t"
DBG6: 13:39:49.423739 - NFS version of mount point: 4.1
DBG4: 13:39:49.423846 - Open /mnt/t/nfstest_delegation_20230426_133941_f_001 so open owner sticks around
DBG2: 13:39:49.424788 - Open file for WRITE [/mnt/t/nfstest_delegation_20230426_133941_f_002]
PASS: Open file for WRITE should succeed
DBG3: 13:39:49.425050 - Lock /mnt/t/nfstest_delegation_20230426_133941_f_002 (F_SETLK, F_WRLCK) start=0 len=4096
PASS: Lock file with F_WRLCK should succeed
DBG3: 13:39:49.425266 - Write file on client holding delegation [/mnt/t/nfstest_delegation_20230426_133941_f_002]
PASS: Write file on client holding delegation should succeed
DBG2: 13:39:49.525732 - Rename into the file (DST) from another client to recall delegation [nfstest_delegation_20230426_133941_f_003 -> nfstest_delegation_20230426_133941_f_002]
PASS: Rename into the file (DST) from another client should succeed
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

Next message: Bjorn Helgaas: "Re: [GIT PULL] PCI changes for v6.4"
Previous message: Takashi Sakamoto: "[GIT PULL] firewire updates for 6.4-rc1"
Next in thread: dai . ngo: "Re: "[PATCH] nfsd: rework refcounting in filecache" caused nfstest/test/nfstest_delegation stuck"
Messages sorted by: [ date ] [ thread ] [ subject ] [ author ]