* help interpreting nfstest_lock output
@ 2023-03-14 10:30 Jeff Layton
2023-03-17 19:29 ` Mora, Jorge
0 siblings, 1 reply; 2+ messages in thread
From: Jeff Layton @ 2023-03-14 10:30 UTC (permalink / raw
To: mora; +Cc: linux-nfs, Amir Goldstein
[-- Attachment #1: Type: text/plain, Size: 614 bytes --]
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@kernel.org>
[-- Attachment #2: optest01.out --]
[-- Type: text/plain, Size: 48531 bytes --]
OPTS: 06:22:55.276029 - ./test/nfstest_lock -s knfsd -e /export --nfsopts nfsversion=3 --runtest=optest01
OPTS: 06:22:55.276360 - basename =
OPTS: 06:22:55.276395 - bugmsgs = None
OPTS: 06:22:55.276420 - client = None
OPTS: 06:22:55.276445 - client-ipaddr = None
OPTS: 06:22:55.276479 - createlog = False
OPTS: 06:22:55.276503 - createtraces = False
OPTS: 06:22:55.276525 - datadir =
OPTS: 06:22:55.276546 - export = /export
OPTS: 06:22:55.276567 - file =
OPTS: 06:22:55.276588 - filesize = 64k
OPTS: 06:22:55.276608 - interface = None
OPTS: 06:22:55.276636 - iodelay = 0.1
OPTS: 06:22:55.276658 - iptables = /usr/sbin/iptables
OPTS: 06:22:55.276679 - isatty = False
OPTS: 06:22:55.276700 - keeptraces = False
OPTS: 06:22:55.276720 - kill = /usr/bin/kill
OPTS: 06:22:55.276740 - length = 4k
OPTS: 06:22:55.276760 - locktype = read,write
OPTS: 06:22:55.276781 - locktype2 = read,write
OPTS: 06:22:55.276802 - lockw-timeout = 30
OPTS: 06:22:55.276822 - messages = /var/log/messages
OPTS: 06:22:55.276843 - mtopts = hard,rsize=4096,wsize=4096
OPTS: 06:22:55.276863 - mtpoint = /mnt/t
OPTS: 06:22:55.276883 - nconnect = 1
OPTS: 06:22:55.276903 - nfiles = 2
OPTS: 06:22:55.276932 - nfsdebug =
OPTS: 06:22:55.276952 - nfserrors = False
OPTS: 06:22:55.276973 - nfsopts = nfsversion=3
OPTS: 06:22:55.276993 - nfsstat = /usr/sbin/nfsstat
OPTS: 06:22:55.277013 - nfsstats = False
OPTS: 06:22:55.277033 - nfsversion = 4.1
OPTS: 06:22:55.277053 - nocleanup = False
OPTS: 06:22:55.277074 - nomount = False
OPTS: 06:22:55.277094 - notimestamps = False
OPTS: 06:22:55.277114 - notty = False
OPTS: 06:22:55.277134 - offset = 4k
OPTS: 06:22:55.277155 - offset-delta = 4k
OPTS: 06:22:55.277186 - opentype = read,write,rdwr
OPTS: 06:22:55.277207 - opentype2 = read,write,rdwr
OPTS: 06:22:55.277228 - pktdisp = False
OPTS: 06:22:55.277248 - port = 2049
OPTS: 06:22:55.277268 - proto = tcp
OPTS: 06:22:55.277289 - rexeclog = False
OPTS: 06:22:55.277309 - rmtraces = False
OPTS: 06:22:55.277330 - rpcdebug =
OPTS: 06:22:55.277350 - rsize = 4k
OPTS: 06:22:55.277370 - runtest = optest01
OPTS: 06:22:55.277390 - sec = sys
OPTS: 06:22:55.277410 - server = knfsd
OPTS: 06:22:55.277431 - setlock = immediate,block
OPTS: 06:22:55.277451 - subtraces = False
OPTS: 06:22:55.277483 - sudo = /usr/bin/sudo
OPTS: 06:22:55.277505 - tag =
OPTS: 06:22:55.277526 - tbsize = 192k
OPTS: 06:22:55.277547 - tcpdump = /usr/sbin/tcpdump
OPTS: 06:22:55.277567 - tmpdir = /tmp
OPTS: 06:22:55.277587 - tracepoints =
OPTS: 06:22:55.277608 - trcdelay = 2.0
OPTS: 06:22:55.277629 - trcevents = /sys/kernel/debug/tracing/events
OPTS: 06:22:55.277649 - trcpipe = /sys/kernel/debug/tracing/trace_pipe
OPTS: 06:22:55.277670 - tverbose = 1
OPTS: 06:22:55.277691 - unlock-delay = 2.0
OPTS: 06:22:55.277712 - verbose = opts|info|dbg1|dbg2|dbg3
OPTS: 06:22:55.277733 - warnings = False
OPTS: 06:22:55.277753 - wsize = 4k
OPTS: 06:22:55.277774 - xunit-report = False
OPTS: 06:22:55.277796 - xunit-report-file = None
INFO: 06:22:55.277822 - SYSTEM: Linux nfsclnt 6.3.0-rc2+ #119 SMP PREEMPT_DYNAMIC Mon Mar 13 14:44:03 EDT 2023 x86_64
DBG2: 06:22:55.334593 - Unmount volume: /usr/bin/sudo umount -f /mnt/t_01
DBG2: 06:22:55.401345 - Mount volume: /usr/bin/sudo mount -o vers=3,proto=tcp,sec=sys,hard,rsize=4096,wsize=4096 knfsd:/export /mnt/t_01
DBG2: 06:22:55.536997 - Start remote procedure server locally
DBG2: 06:22:55.685705 - Unmount volume: /usr/bin/sudo umount -f /mnt/t
DBG2: 06:22:55.755413 - Mount volume: /usr/bin/sudo mount -o vers=4.1,proto=tcp,sec=sys,hard,rsize=4096,wsize=4096 knfsd:/export /mnt/t
DBG2: 06:22:55.928547 - Creating file [/mnt/t/nfstest_lock_20230314_062255_f_001] 65536@0
TIME: 0.698925s
*** Locking same range from a second process
TEST: Running test 'optest01'
DBG2: 06:22:55.970190 - Open file for reading [nfstest_lock_20230314_062255_f_001]
DBG1: 06:22:55.971608 - Lock file (F_RDLCK, F_SETLK) off=4096 len=4096 range(4096, 8191)
DBG2: 06:22:55.972551 - Open file for reading [nfstest_lock_20230314_062255_f_001] on second process
DBG1: 06:22:55.975258 - Lock file (F_RDLCK, F_SETLK) off=4096 len=4096 range(4096, 8191) on second process @0.69
DBG1: 06:22:56.010226 - Unlock file (F_UNLCK, F_SETLK) off=0 len=0 range(0, 18446744073709551615)
DBG1: 06:22:56.011443 - Lock file (F_RDLCK, F_SETLK) off=4096 len=4096 range(4096, 8191) on second process @0.72
DBG1: 06:22:56.012904 - Unlock file (F_UNLCK, F_SETLK) off=0 len=0 range(0, 18446744073709551615) on second process @0.72
DBG2: 06:22:56.015385 - Open file for reading [nfstest_lock_20230314_062255_f_001]
DBG1: 06:22:56.016539 - Lock file (F_RDLCK, F_SETLK) off=4096 len=4096 range(4096, 8191)
DBG2: 06:22:56.016724 - Open file for reading [nfstest_lock_20230314_062255_f_001] on second process
DBG1: 06:22:56.018919 - Lock file (F_WRLCK, F_SETLK) off=4096 len=4096 range(4096, 8191) on second process @0.73
DBG1: 06:22:56.019580 - Unlock file (F_UNLCK, F_SETLK) off=0 len=0 range(0, 18446744073709551615)
DBG2: 06:22:56.020957 - Open file for reading [nfstest_lock_20230314_062255_f_001]
DBG1: 06:22:56.021882 - Lock file (F_RDLCK, F_SETLK) off=4096 len=4096 range(4096, 8191)
DBG2: 06:22:56.022036 - Open file for writing [nfstest_lock_20230314_062255_f_001] on second process
DBG1: 06:22:56.023145 - Lock file (F_RDLCK, F_SETLK) off=4096 len=4096 range(4096, 8191) on second process @0.74
DBG1: 06:22:56.023634 - Unlock file (F_UNLCK, F_SETLK) off=0 len=0 range(0, 18446744073709551615)
DBG2: 06:22:56.024146 - Open file for reading [nfstest_lock_20230314_062255_f_001]
DBG1: 06:22:56.024414 - Lock file (F_RDLCK, F_SETLK) off=4096 len=4096 range(4096, 8191)
DBG2: 06:22:56.024579 - Open file for writing [nfstest_lock_20230314_062255_f_001] on second process
DBG1: 06:22:56.025736 - Lock file (F_WRLCK, F_SETLK) off=4096 len=4096 range(4096, 8191) on second process @0.74
DBG1: 06:22:56.027014 - Unlock file (F_UNLCK, F_SETLK) off=0 len=0 range(0, 18446744073709551615)
DBG1: 06:22:56.027183 - Lock file (F_WRLCK, F_SETLK) off=4096 len=4096 range(4096, 8191) on second process @0.74
DBG1: 06:22:56.028308 - Unlock file (F_UNLCK, F_SETLK) off=0 len=0 range(0, 18446744073709551615) on second process @0.74
DBG2: 06:22:56.029865 - Open file for reading [nfstest_lock_20230314_062255_f_001]
DBG1: 06:22:56.030894 - Lock file (F_RDLCK, F_SETLK) off=4096 len=4096 range(4096, 8191)
DBG2: 06:22:56.031656 - Open file for reading and writing [nfstest_lock_20230314_062255_f_001] on second process
DBG1: 06:22:56.032713 - Lock file (F_RDLCK, F_SETLK) off=4096 len=4096 range(4096, 8191) on second process @0.74
DBG1: 06:22:56.033953 - Unlock file (F_UNLCK, F_SETLK) off=0 len=0 range(0, 18446744073709551615)
DBG1: 06:22:56.034853 - Lock file (F_RDLCK, F_SETLK) off=4096 len=4096 range(4096, 8191) on second process @0.75
DBG1: 06:22:56.035875 - Unlock file (F_UNLCK, F_SETLK) off=0 len=0 range(0, 18446744073709551615) on second process @0.75
DBG2: 06:22:56.038154 - Open file for reading [nfstest_lock_20230314_062255_f_001]
DBG1: 06:22:56.039218 - Lock file (F_RDLCK, F_SETLK) off=4096 len=4096 range(4096, 8191)
DBG2: 06:22:56.039976 - Open file for reading and writing [nfstest_lock_20230314_062255_f_001] on second process
DBG1: 06:22:56.041617 - Lock file (F_WRLCK, F_SETLK) off=4096 len=4096 range(4096, 8191) on second process @0.75
DBG1: 06:22:56.042935 - Unlock file (F_UNLCK, F_SETLK) off=0 len=0 range(0, 18446744073709551615)
DBG1: 06:22:56.043862 - Lock file (F_WRLCK, F_SETLK) off=4096 len=4096 range(4096, 8191) on second process @0.76
DBG1: 06:22:56.045049 - Unlock file (F_UNLCK, F_SETLK) off=0 len=0 range(0, 18446744073709551615) on second process @0.76
DBG2: 06:22:56.047222 - Open file for reading [nfstest_lock_20230314_062255_f_001]
DBG1: 06:22:56.048232 - Lock file (F_WRLCK, F_SETLK) off=4096 len=4096 range(4096, 8191)
DBG2: 06:22:56.049116 - Open file for reading [nfstest_lock_20230314_062255_f_001]
DBG1: 06:22:56.049998 - Lock file (F_WRLCK, F_SETLK) off=4096 len=4096 range(4096, 8191)
DBG2: 06:22:56.050728 - Open file for reading [nfstest_lock_20230314_062255_f_001]
DBG1: 06:22:56.051582 - Lock file (F_WRLCK, F_SETLK) off=4096 len=4096 range(4096, 8191)
DBG2: 06:22:56.052348 - Open file for reading [nfstest_lock_20230314_062255_f_001]
DBG1: 06:22:56.053566 - Lock file (F_WRLCK, F_SETLK) off=4096 len=4096 range(4096, 8191)
DBG2: 06:22:56.054379 - Open file for reading [nfstest_lock_20230314_062255_f_001]
DBG1: 06:22:56.055410 - Lock file (F_WRLCK, F_SETLK) off=4096 len=4096 range(4096, 8191)
DBG2: 06:22:56.056223 - Open file for reading [nfstest_lock_20230314_062255_f_001]
DBG1: 06:22:56.057300 - Lock file (F_WRLCK, F_SETLK) off=4096 len=4096 range(4096, 8191)
DBG2: 06:22:56.058107 - Open file for writing [nfstest_lock_20230314_062255_f_001]
DBG1: 06:22:56.059006 - Lock file (F_RDLCK, F_SETLK) off=4096 len=4096 range(4096, 8191)
DBG2: 06:22:56.059801 - Open file for writing [nfstest_lock_20230314_062255_f_001]
DBG1: 06:22:56.060742 - Lock file (F_RDLCK, F_SETLK) off=4096 len=4096 range(4096, 8191)
DBG2: 06:22:56.061506 - Open file for writing [nfstest_lock_20230314_062255_f_001]
DBG1: 06:22:56.062344 - Lock file (F_RDLCK, F_SETLK) off=4096 len=4096 range(4096, 8191)
DBG2: 06:22:56.063095 - Open file for writing [nfstest_lock_20230314_062255_f_001]
DBG1: 06:22:56.063905 - Lock file (F_RDLCK, F_SETLK) off=4096 len=4096 range(4096, 8191)
DBG2: 06:22:56.064641 - Open file for writing [nfstest_lock_20230314_062255_f_001]
DBG1: 06:22:56.065517 - Lock file (F_RDLCK, F_SETLK) off=4096 len=4096 range(4096, 8191)
DBG2: 06:22:56.066215 - Open file for writing [nfstest_lock_20230314_062255_f_001]
DBG1: 06:22:56.067052 - Lock file (F_RDLCK, F_SETLK) off=4096 len=4096 range(4096, 8191)
DBG2: 06:22:56.067770 - Open file for writing [nfstest_lock_20230314_062255_f_001]
DBG1: 06:22:56.068613 - Lock file (F_WRLCK, F_SETLK) off=4096 len=4096 range(4096, 8191)
DBG2: 06:22:56.069390 - Open file for reading [nfstest_lock_20230314_062255_f_001] on second process
DBG1: 06:22:56.071037 - Lock file (F_RDLCK, F_SETLK) off=4096 len=4096 range(4096, 8191) on second process @0.78
DBG1: 06:22:56.072311 - Unlock file (F_UNLCK, F_SETLK) off=0 len=0 range(0, 18446744073709551615)
DBG1: 06:22:56.073169 - Lock file (F_RDLCK, F_SETLK) off=4096 len=4096 range(4096, 8191) on second process @0.79
DBG1: 06:22:56.074316 - Unlock file (F_UNLCK, F_SETLK) off=0 len=0 range(0, 18446744073709551615) on second process @0.79
DBG2: 06:22:56.076491 - Open file for writing [nfstest_lock_20230314_062255_f_001]
DBG1: 06:22:56.077414 - Lock file (F_WRLCK, F_SETLK) off=4096 len=4096 range(4096, 8191)
DBG2: 06:22:56.078160 - Open file for reading [nfstest_lock_20230314_062255_f_001] on second process
DBG1: 06:22:56.079581 - Lock file (F_WRLCK, F_SETLK) off=4096 len=4096 range(4096, 8191) on second process @0.79
DBG1: 06:22:56.080084 - Unlock file (F_UNLCK, F_SETLK) off=0 len=0 range(0, 18446744073709551615)
DBG2: 06:22:56.082161 - Open file for writing [nfstest_lock_20230314_062255_f_001]
DBG1: 06:22:56.083195 - Lock file (F_WRLCK, F_SETLK) off=4096 len=4096 range(4096, 8191)
DBG2: 06:22:56.083959 - Open file for writing [nfstest_lock_20230314_062255_f_001] on second process
DBG1: 06:22:56.085148 - Lock file (F_RDLCK, F_SETLK) off=4096 len=4096 range(4096, 8191) on second process @0.80
DBG1: 06:22:56.085653 - Unlock file (F_UNLCK, F_SETLK) off=0 len=0 range(0, 18446744073709551615)
DBG2: 06:22:56.087582 - Open file for writing [nfstest_lock_20230314_062255_f_001]
DBG1: 06:22:56.088488 - Lock file (F_WRLCK, F_SETLK) off=4096 len=4096 range(4096, 8191)
DBG2: 06:22:56.089272 - Open file for writing [nfstest_lock_20230314_062255_f_001] on second process
DBG1: 06:22:56.090499 - Lock file (F_WRLCK, F_SETLK) off=4096 len=4096 range(4096, 8191) on second process @0.80
DBG1: 06:22:56.091647 - Unlock file (F_UNLCK, F_SETLK) off=0 len=0 range(0, 18446744073709551615)
DBG1: 06:22:56.092496 - Lock file (F_WRLCK, F_SETLK) off=4096 len=4096 range(4096, 8191) on second process @0.80
DBG1: 06:22:56.093630 - Unlock file (F_UNLCK, F_SETLK) off=0 len=0 range(0, 18446744073709551615) on second process @0.81
DBG2: 06:22:56.095795 - Open file for writing [nfstest_lock_20230314_062255_f_001]
DBG1: 06:22:56.096852 - Lock file (F_WRLCK, F_SETLK) off=4096 len=4096 range(4096, 8191)
DBG2: 06:22:56.097661 - Open file for reading and writing [nfstest_lock_20230314_062255_f_001] on second process
DBG1: 06:22:56.099216 - Lock file (F_RDLCK, F_SETLK) off=4096 len=4096 range(4096, 8191) on second process @0.81
DBG1: 06:22:56.100341 - Unlock file (F_UNLCK, F_SETLK) off=0 len=0 range(0, 18446744073709551615)
DBG1: 06:22:56.101181 - Lock file (F_RDLCK, F_SETLK) off=4096 len=4096 range(4096, 8191) on second process @0.81
DBG1: 06:22:56.102335 - Unlock file (F_UNLCK, F_SETLK) off=0 len=0 range(0, 18446744073709551615) on second process @0.81
DBG2: 06:22:56.104444 - Open file for writing [nfstest_lock_20230314_062255_f_001]
DBG1: 06:22:56.105388 - Lock file (F_WRLCK, F_SETLK) off=4096 len=4096 range(4096, 8191)
DBG2: 06:22:56.106131 - Open file for reading and writing [nfstest_lock_20230314_062255_f_001] on second process
DBG1: 06:22:56.107550 - Lock file (F_WRLCK, F_SETLK) off=4096 len=4096 range(4096, 8191) on second process @0.82
DBG1: 06:22:56.108636 - Unlock file (F_UNLCK, F_SETLK) off=0 len=0 range(0, 18446744073709551615)
DBG1: 06:22:56.109457 - Lock file (F_WRLCK, F_SETLK) off=4096 len=4096 range(4096, 8191) on second process @0.82
DBG1: 06:22:56.110607 - Unlock file (F_UNLCK, F_SETLK) off=0 len=0 range(0, 18446744073709551615) on second process @0.82
DBG2: 06:22:56.112759 - Open file for reading and writing [nfstest_lock_20230314_062255_f_001]
DBG1: 06:22:56.113782 - Lock file (F_RDLCK, F_SETLK) off=4096 len=4096 range(4096, 8191)
DBG2: 06:22:56.114542 - Open file for reading [nfstest_lock_20230314_062255_f_001] on second process
DBG1: 06:22:56.115889 - Lock file (F_RDLCK, F_SETLK) off=4096 len=4096 range(4096, 8191) on second process @0.83
DBG1: 06:22:56.116957 - Unlock file (F_UNLCK, F_SETLK) off=0 len=0 range(0, 18446744073709551615)
DBG1: 06:22:56.117744 - Lock file (F_RDLCK, F_SETLK) off=4096 len=4096 range(4096, 8191) on second process @0.83
DBG1: 06:22:56.118803 - Unlock file (F_UNLCK, F_SETLK) off=0 len=0 range(0, 18446744073709551615) on second process @0.83
DBG2: 06:22:56.120906 - Open file for reading and writing [nfstest_lock_20230314_062255_f_001]
DBG1: 06:22:56.121920 - Lock file (F_RDLCK, F_SETLK) off=4096 len=4096 range(4096, 8191)
DBG2: 06:22:56.122665 - Open file for reading [nfstest_lock_20230314_062255_f_001] on second process
DBG1: 06:22:56.124189 - Lock file (F_WRLCK, F_SETLK) off=4096 len=4096 range(4096, 8191) on second process @0.84
DBG1: 06:22:56.124789 - Unlock file (F_UNLCK, F_SETLK) off=0 len=0 range(0, 18446744073709551615)
DBG2: 06:22:56.126710 - Open file for reading and writing [nfstest_lock_20230314_062255_f_001]
DBG1: 06:22:56.127683 - Lock file (F_RDLCK, F_SETLK) off=4096 len=4096 range(4096, 8191)
DBG2: 06:22:56.128483 - Open file for writing [nfstest_lock_20230314_062255_f_001] on second process
DBG1: 06:22:56.129514 - Lock file (F_RDLCK, F_SETLK) off=4096 len=4096 range(4096, 8191) on second process @0.84
DBG1: 06:22:56.130011 - Unlock file (F_UNLCK, F_SETLK) off=0 len=0 range(0, 18446744073709551615)
DBG2: 06:22:56.131938 - Open file for reading and writing [nfstest_lock_20230314_062255_f_001]
DBG1: 06:22:56.133008 - Lock file (F_RDLCK, F_SETLK) off=4096 len=4096 range(4096, 8191)
DBG2: 06:22:56.133822 - Open file for writing [nfstest_lock_20230314_062255_f_001] on second process
DBG1: 06:22:56.134815 - Lock file (F_WRLCK, F_SETLK) off=4096 len=4096 range(4096, 8191) on second process @0.85
DBG1: 06:22:56.136060 - Unlock file (F_UNLCK, F_SETLK) off=0 len=0 range(0, 18446744073709551615)
DBG1: 06:22:56.136921 - Lock file (F_WRLCK, F_SETLK) off=4096 len=4096 range(4096, 8191) on second process @0.85
DBG1: 06:22:56.138158 - Unlock file (F_UNLCK, F_SETLK) off=0 len=0 range(0, 18446744073709551615) on second process @0.85
DBG2: 06:22:56.140416 - Open file for reading and writing [nfstest_lock_20230314_062255_f_001]
DBG1: 06:22:56.141562 - Lock file (F_RDLCK, F_SETLK) off=4096 len=4096 range(4096, 8191)
DBG2: 06:22:56.142320 - Open file for reading and writing [nfstest_lock_20230314_062255_f_001] on second process
DBG1: 06:22:56.143746 - Lock file (F_RDLCK, F_SETLK) off=4096 len=4096 range(4096, 8191) on second process @0.86
DBG1: 06:22:56.144935 - Unlock file (F_UNLCK, F_SETLK) off=0 len=0 range(0, 18446744073709551615)
DBG1: 06:22:56.145683 - Lock file (F_RDLCK, F_SETLK) off=4096 len=4096 range(4096, 8191) on second process @0.86
DBG1: 06:22:56.146794 - Unlock file (F_UNLCK, F_SETLK) off=0 len=0 range(0, 18446744073709551615) on second process @0.86
DBG2: 06:22:56.148919 - Open file for reading and writing [nfstest_lock_20230314_062255_f_001]
DBG1: 06:22:56.149959 - Lock file (F_RDLCK, F_SETLK) off=4096 len=4096 range(4096, 8191)
DBG2: 06:22:56.150728 - Open file for reading and writing [nfstest_lock_20230314_062255_f_001] on second process
DBG1: 06:22:56.152091 - Lock file (F_WRLCK, F_SETLK) off=4096 len=4096 range(4096, 8191) on second process @0.86
DBG1: 06:22:56.153357 - Unlock file (F_UNLCK, F_SETLK) off=0 len=0 range(0, 18446744073709551615)
DBG1: 06:22:56.154102 - Lock file (F_WRLCK, F_SETLK) off=4096 len=4096 range(4096, 8191) on second process @0.87
DBG1: 06:22:56.155274 - Unlock file (F_UNLCK, F_SETLK) off=0 len=0 range(0, 18446744073709551615) on second process @0.87
DBG2: 06:22:56.157485 - Open file for reading and writing [nfstest_lock_20230314_062255_f_001]
DBG1: 06:22:56.158507 - Lock file (F_WRLCK, F_SETLK) off=4096 len=4096 range(4096, 8191)
DBG2: 06:22:56.159290 - Open file for reading [nfstest_lock_20230314_062255_f_001] on second process
DBG1: 06:22:56.160774 - Lock file (F_RDLCK, F_SETLK) off=4096 len=4096 range(4096, 8191) on second process @0.87
DBG1: 06:22:56.162050 - Unlock file (F_UNLCK, F_SETLK) off=0 len=0 range(0, 18446744073709551615)
DBG1: 06:22:56.162860 - Lock file (F_RDLCK, F_SETLK) off=4096 len=4096 range(4096, 8191) on second process @0.87
DBG1: 06:22:56.164034 - Unlock file (F_UNLCK, F_SETLK) off=0 len=0 range(0, 18446744073709551615) on second process @0.88
DBG2: 06:22:56.166062 - Open file for reading and writing [nfstest_lock_20230314_062255_f_001]
DBG1: 06:22:56.167013 - Lock file (F_WRLCK, F_SETLK) off=4096 len=4096 range(4096, 8191)
DBG2: 06:22:56.167735 - Open file for reading [nfstest_lock_20230314_062255_f_001] on second process
DBG1: 06:22:56.169309 - Lock file (F_WRLCK, F_SETLK) off=4096 len=4096 range(4096, 8191) on second process @0.88
DBG1: 06:22:56.169806 - Unlock file (F_UNLCK, F_SETLK) off=0 len=0 range(0, 18446744073709551615)
DBG2: 06:22:56.171651 - Open file for reading and writing [nfstest_lock_20230314_062255_f_001]
DBG1: 06:22:56.172547 - Lock file (F_WRLCK, F_SETLK) off=4096 len=4096 range(4096, 8191)
DBG2: 06:22:56.173299 - Open file for writing [nfstest_lock_20230314_062255_f_001] on second process
DBG1: 06:22:56.174253 - Lock file (F_RDLCK, F_SETLK) off=4096 len=4096 range(4096, 8191) on second process @0.89
DBG1: 06:22:56.174735 - Unlock file (F_UNLCK, F_SETLK) off=0 len=0 range(0, 18446744073709551615)
DBG2: 06:22:56.176598 - Open file for reading and writing [nfstest_lock_20230314_062255_f_001]
DBG1: 06:22:56.177534 - Lock file (F_WRLCK, F_SETLK) off=4096 len=4096 range(4096, 8191)
DBG2: 06:22:56.178252 - Open file for writing [nfstest_lock_20230314_062255_f_001] on second process
DBG1: 06:22:56.179270 - Lock file (F_WRLCK, F_SETLK) off=4096 len=4096 range(4096, 8191) on second process @0.89
DBG1: 06:22:56.180485 - Unlock file (F_UNLCK, F_SETLK) off=0 len=0 range(0, 18446744073709551615)
DBG1: 06:22:56.181309 - Lock file (F_WRLCK, F_SETLK) off=4096 len=4096 range(4096, 8191) on second process @0.89
DBG1: 06:22:56.182554 - Unlock file (F_UNLCK, F_SETLK) off=0 len=0 range(0, 18446744073709551615) on second process @0.89
DBG2: 06:22:56.184734 - Open file for reading and writing [nfstest_lock_20230314_062255_f_001]
DBG1: 06:22:56.185731 - Lock file (F_WRLCK, F_SETLK) off=4096 len=4096 range(4096, 8191)
DBG2: 06:22:56.186454 - Open file for reading and writing [nfstest_lock_20230314_062255_f_001] on second process
DBG1: 06:22:56.187929 - Lock file (F_RDLCK, F_SETLK) off=4096 len=4096 range(4096, 8191) on second process @0.90
DBG1: 06:22:56.189256 - Unlock file (F_UNLCK, F_SETLK) off=0 len=0 range(0, 18446744073709551615)
DBG1: 06:22:56.190024 - Lock file (F_RDLCK, F_SETLK) off=4096 len=4096 range(4096, 8191) on second process @0.90
DBG1: 06:22:56.191246 - Unlock file (F_UNLCK, F_SETLK) off=0 len=0 range(0, 18446744073709551615) on second process @0.90
DBG2: 06:22:56.193275 - Open file for reading and writing [nfstest_lock_20230314_062255_f_001]
DBG1: 06:22:56.194223 - Lock file (F_WRLCK, F_SETLK) off=4096 len=4096 range(4096, 8191)
DBG2: 06:22:56.194962 - Open file for reading and writing [nfstest_lock_20230314_062255_f_001] on second process
DBG1: 06:22:56.196339 - Lock file (F_WRLCK, F_SETLK) off=4096 len=4096 range(4096, 8191) on second process @0.91
DBG1: 06:22:56.197500 - Unlock file (F_UNLCK, F_SETLK) off=0 len=0 range(0, 18446744073709551615)
DBG1: 06:22:56.198223 - Lock file (F_WRLCK, F_SETLK) off=4096 len=4096 range(4096, 8191) on second process @0.91
DBG1: 06:22:56.199457 - Unlock file (F_UNLCK, F_SETLK) off=0 len=0 range(0, 18446744073709551615) on second process @0.91
DBG2: 06:22:56.201567 - Open file for reading [nfstest_lock_20230314_062255_f_001]
DBG1: 06:22:56.202491 - Lock file (F_RDLCK, F_SETLKW) off=4096 len=4096 range(4096, 8191)
DBG2: 06:22:56.203326 - Open file for reading [nfstest_lock_20230314_062255_f_001] on second process
DBG1: 06:22:56.204795 - Lock file (F_RDLCK, F_SETLKW) off=4096 len=4096 range(4096, 8191) on second process @0.92
DBG1: 06:22:56.206008 - Unlock file (F_UNLCK, F_SETLK) off=0 len=0 range(0, 18446744073709551615)
DBG1: 06:22:56.206787 - Lock file (F_RDLCK, F_SETLKW) off=4096 len=4096 range(4096, 8191) on second process @0.92
DBG1: 06:22:56.208029 - Unlock file (F_UNLCK, F_SETLK) off=0 len=0 range(0, 18446744073709551615) on second process @0.92
DBG2: 06:22:56.210220 - Open file for reading [nfstest_lock_20230314_062255_f_001]
DBG1: 06:22:56.211124 - Lock file (F_RDLCK, F_SETLKW) off=4096 len=4096 range(4096, 8191)
DBG2: 06:22:56.211877 - Open file for reading [nfstest_lock_20230314_062255_f_001] on second process
DBG1: 06:22:56.213275 - Lock file (F_WRLCK, F_SETLKW) off=4096 len=4096 range(4096, 8191) on second process @0.93
DBG1: 06:22:56.213822 - Unlock file (F_UNLCK, F_SETLK) off=0 len=0 range(0, 18446744073709551615)
DBG2: 06:22:56.215584 - Open file for reading [nfstest_lock_20230314_062255_f_001]
DBG1: 06:22:56.216506 - Lock file (F_RDLCK, F_SETLKW) off=4096 len=4096 range(4096, 8191)
DBG2: 06:22:56.217259 - Open file for writing [nfstest_lock_20230314_062255_f_001] on second process
DBG1: 06:22:56.218250 - Lock file (F_RDLCK, F_SETLKW) off=4096 len=4096 range(4096, 8191) on second process @0.93
DBG1: 06:22:56.218783 - Unlock file (F_UNLCK, F_SETLK) off=0 len=0 range(0, 18446744073709551615)
DBG2: 06:22:56.220629 - Open file for reading [nfstest_lock_20230314_062255_f_001]
DBG1: 06:22:56.221648 - Lock file (F_RDLCK, F_SETLKW) off=4096 len=4096 range(4096, 8191)
DBG2: 06:22:56.222413 - Open file for writing [nfstest_lock_20230314_062255_f_001] on second process
DBG1: 06:22:56.223413 - Lock file (F_WRLCK, F_SETLKW) off=4096 len=4096 range(4096, 8191) on second process @0.94
DBG3: 06:22:56.323926 - Wait 2.00 secs to unlock conflicting lock @1.04
DBG3: 06:22:56.324034 - Check if blocked lock is still waiting @1.04
DBG3: 06:22:56.724704 - Check if blocked lock is still waiting @1.44
DBG3: 06:22:57.125451 - Check if blocked lock is still waiting @1.84
DBG3: 06:22:57.526195 - Check if blocked lock is still waiting @2.24
DBG3: 06:22:57.926988 - Check if blocked lock is still waiting @2.64
DBG3: 06:22:58.327696 - Check if blocked lock is still waiting @3.04
DBG1: 06:22:58.327796 - Unlock file (F_UNLCK, F_SETLK) off=0 len=0 range(0, 18446744073709551615)
DBG3: 06:22:58.329017 - Wait up to 30 secs to check if blocked lock has been granted @3.04
DBG3: 06:22:58.332899 - Getting results from blocked lock @3.04
DBG1: 06:22:58.333084 - Unlock file (F_UNLCK, F_SETLK) off=0 len=0 range(0, 18446744073709551615) on second process @3.05
DBG2: 06:22:58.336114 - Open file for reading [nfstest_lock_20230314_062255_f_001]
DBG1: 06:22:58.337906 - Lock file (F_RDLCK, F_SETLKW) off=4096 len=4096 range(4096, 8191)
DBG2: 06:22:58.339010 - Open file for reading and writing [nfstest_lock_20230314_062255_f_001] on second process
DBG1: 06:22:58.340741 - Lock file (F_RDLCK, F_SETLKW) off=4096 len=4096 range(4096, 8191) on second process @3.05
DBG1: 06:22:58.341983 - Unlock file (F_UNLCK, F_SETLK) off=0 len=0 range(0, 18446744073709551615)
DBG1: 06:22:58.342799 - Lock file (F_RDLCK, F_SETLKW) off=4096 len=4096 range(4096, 8191) on second process @3.05
DBG1: 06:22:58.343809 - Unlock file (F_UNLCK, F_SETLK) off=0 len=0 range(0, 18446744073709551615) on second process @3.06
DBG2: 06:22:58.346065 - Open file for reading [nfstest_lock_20230314_062255_f_001]
DBG1: 06:22:58.347191 - Lock file (F_RDLCK, F_SETLKW) off=4096 len=4096 range(4096, 8191)
DBG2: 06:22:58.348068 - Open file for reading and writing [nfstest_lock_20230314_062255_f_001] on second process
DBG1: 06:22:58.349749 - Lock file (F_WRLCK, F_SETLKW) off=4096 len=4096 range(4096, 8191) on second process @3.06
DBG3: 06:22:58.450241 - Wait 2.00 secs to unlock conflicting lock @3.16
DBG3: 06:22:58.450343 - Check if blocked lock is still waiting @3.16
DBG3: 06:22:58.851014 - Check if blocked lock is still waiting @3.56
DBG3: 06:22:59.251761 - Check if blocked lock is still waiting @3.96
DBG3: 06:22:59.652554 - Check if blocked lock is still waiting @4.36
DBG3: 06:23:00.053394 - Check if blocked lock is still waiting @4.77
DBG3: 06:23:00.454178 - Check if blocked lock is still waiting @5.17
DBG1: 06:23:00.454313 - Unlock file (F_UNLCK, F_SETLK) off=0 len=0 range(0, 18446744073709551615)
DBG3: 06:23:00.455585 - Wait up to 30 secs to check if blocked lock has been granted @5.17
DBG3: 06:23:00.455916 - Getting results from blocked lock @5.17
DBG1: 06:23:00.456178 - Unlock file (F_UNLCK, F_SETLK) off=0 len=0 range(0, 18446744073709551615) on second process @5.17
DBG2: 06:23:00.458307 - Open file for reading [nfstest_lock_20230314_062255_f_001]
DBG1: 06:23:00.459242 - Lock file (F_WRLCK, F_SETLKW) off=4096 len=4096 range(4096, 8191)
DBG2: 06:23:00.460119 - Open file for reading [nfstest_lock_20230314_062255_f_001]
DBG1: 06:23:00.460943 - Lock file (F_WRLCK, F_SETLKW) off=4096 len=4096 range(4096, 8191)
DBG2: 06:23:00.461641 - Open file for reading [nfstest_lock_20230314_062255_f_001]
DBG1: 06:23:00.462373 - Lock file (F_WRLCK, F_SETLKW) off=4096 len=4096 range(4096, 8191)
DBG2: 06:23:00.463161 - Open file for reading [nfstest_lock_20230314_062255_f_001]
DBG1: 06:23:00.463935 - Lock file (F_WRLCK, F_SETLKW) off=4096 len=4096 range(4096, 8191)
DBG2: 06:23:00.464642 - Open file for reading [nfstest_lock_20230314_062255_f_001]
DBG1: 06:23:00.465530 - Lock file (F_WRLCK, F_SETLKW) off=4096 len=4096 range(4096, 8191)
DBG2: 06:23:00.466248 - Open file for reading [nfstest_lock_20230314_062255_f_001]
DBG1: 06:23:00.467033 - Lock file (F_WRLCK, F_SETLKW) off=4096 len=4096 range(4096, 8191)
DBG2: 06:23:00.467792 - Open file for writing [nfstest_lock_20230314_062255_f_001]
DBG1: 06:23:00.468638 - Lock file (F_RDLCK, F_SETLKW) off=4096 len=4096 range(4096, 8191)
DBG2: 06:23:00.469408 - Open file for writing [nfstest_lock_20230314_062255_f_001]
DBG1: 06:23:00.470229 - Lock file (F_RDLCK, F_SETLKW) off=4096 len=4096 range(4096, 8191)
DBG2: 06:23:00.470944 - Open file for writing [nfstest_lock_20230314_062255_f_001]
DBG1: 06:23:00.471715 - Lock file (F_RDLCK, F_SETLKW) off=4096 len=4096 range(4096, 8191)
DBG2: 06:23:00.472404 - Open file for writing [nfstest_lock_20230314_062255_f_001]
DBG1: 06:23:00.473231 - Lock file (F_RDLCK, F_SETLKW) off=4096 len=4096 range(4096, 8191)
DBG2: 06:23:00.473928 - Open file for writing [nfstest_lock_20230314_062255_f_001]
DBG1: 06:23:00.474663 - Lock file (F_RDLCK, F_SETLKW) off=4096 len=4096 range(4096, 8191)
DBG2: 06:23:00.475351 - Open file for writing [nfstest_lock_20230314_062255_f_001]
DBG1: 06:23:00.476104 - Lock file (F_RDLCK, F_SETLKW) off=4096 len=4096 range(4096, 8191)
DBG2: 06:23:00.476825 - Open file for writing [nfstest_lock_20230314_062255_f_001]
DBG1: 06:23:00.477621 - Lock file (F_WRLCK, F_SETLKW) off=4096 len=4096 range(4096, 8191)
DBG2: 06:23:00.478305 - Open file for reading [nfstest_lock_20230314_062255_f_001] on second process
DBG1: 06:23:00.479824 - Lock file (F_RDLCK, F_SETLKW) off=4096 len=4096 range(4096, 8191) on second process @5.19
DBG3: 06:23:00.580316 - Wait 2.00 secs to unlock conflicting lock @5.29
DBG3: 06:23:00.580411 - Check if blocked lock is still waiting @5.29
DBG3: 06:23:00.981095 - Check if blocked lock is still waiting @5.69
DBG3: 06:23:01.381848 - Check if blocked lock is still waiting @6.09
DBG3: 06:23:01.782624 - Check if blocked lock is still waiting @6.49
DBG3: 06:23:02.183389 - Check if blocked lock is still waiting @6.90
DBG3: 06:23:02.584173 - Check if blocked lock is still waiting @7.30
DBG1: 06:23:02.584404 - Unlock file (F_UNLCK, F_SETLK) off=0 len=0 range(0, 18446744073709551615)
DBG3: 06:23:02.585823 - Wait up to 30 secs to check if blocked lock has been granted @7.30
DBG3: 06:23:02.586066 - Getting results from blocked lock @7.30
DBG1: 06:23:02.586346 - Unlock file (F_UNLCK, F_SETLK) off=0 len=0 range(0, 18446744073709551615) on second process @7.30
DBG2: 06:23:02.588420 - Open file for writing [nfstest_lock_20230314_062255_f_001]
DBG1: 06:23:02.589429 - Lock file (F_WRLCK, F_SETLKW) off=4096 len=4096 range(4096, 8191)
DBG2: 06:23:02.590209 - Open file for reading [nfstest_lock_20230314_062255_f_001] on second process
DBG1: 06:23:02.591829 - Lock file (F_WRLCK, F_SETLKW) off=4096 len=4096 range(4096, 8191) on second process @7.30
DBG1: 06:23:02.592414 - Unlock file (F_UNLCK, F_SETLK) off=0 len=0 range(0, 18446744073709551615)
DBG2: 06:23:02.594425 - Open file for writing [nfstest_lock_20230314_062255_f_001]
DBG1: 06:23:02.595427 - Lock file (F_WRLCK, F_SETLKW) off=4096 len=4096 range(4096, 8191)
DBG2: 06:23:02.596225 - Open file for writing [nfstest_lock_20230314_062255_f_001] on second process
DBG1: 06:23:02.597332 - Lock file (F_RDLCK, F_SETLKW) off=4096 len=4096 range(4096, 8191) on second process @7.31
DBG1: 06:23:02.597867 - Unlock file (F_UNLCK, F_SETLK) off=0 len=0 range(0, 18446744073709551615)
DBG2: 06:23:02.599683 - Open file for writing [nfstest_lock_20230314_062255_f_001]
DBG1: 06:23:02.601477 - Lock file (F_WRLCK, F_SETLKW) off=4096 len=4096 range(4096, 8191)
DBG2: 06:23:02.602230 - Open file for writing [nfstest_lock_20230314_062255_f_001] on second process
DBG1: 06:23:02.603230 - Lock file (F_WRLCK, F_SETLKW) off=4096 len=4096 range(4096, 8191) on second process @7.32
DBG3: 06:23:02.703717 - Wait 2.00 secs to unlock conflicting lock @7.42
DBG3: 06:23:02.703842 - Check if blocked lock is still waiting @7.42
DBG3: 06:23:03.104521 - Check if blocked lock is still waiting @7.82
DBG3: 06:23:03.505257 - Check if blocked lock is still waiting @8.22
DBG3: 06:23:03.906005 - Check if blocked lock is still waiting @8.62
DBG3: 06:23:04.306756 - Check if blocked lock is still waiting @9.02
DBG3: 06:23:04.707517 - Check if blocked lock is still waiting @9.42
DBG1: 06:23:04.707655 - Unlock file (F_UNLCK, F_SETLK) off=0 len=0 range(0, 18446744073709551615)
DBG3: 06:23:04.708852 - Wait up to 30 secs to check if blocked lock has been granted @9.42
DBG3: 06:23:04.709374 - Getting results from blocked lock @9.42
DBG1: 06:23:04.709643 - Unlock file (F_UNLCK, F_SETLK) off=0 len=0 range(0, 18446744073709551615) on second process @9.42
DBG2: 06:23:04.711734 - Open file for writing [nfstest_lock_20230314_062255_f_001]
DBG1: 06:23:04.712755 - Lock file (F_WRLCK, F_SETLKW) off=4096 len=4096 range(4096, 8191)
DBG2: 06:23:04.713506 - Open file for reading and writing [nfstest_lock_20230314_062255_f_001] on second process
DBG1: 06:23:04.715201 - Lock file (F_RDLCK, F_SETLKW) off=4096 len=4096 range(4096, 8191) on second process @9.43
DBG3: 06:23:04.815680 - Wait 2.00 secs to unlock conflicting lock @9.53
DBG3: 06:23:04.815751 - Check if blocked lock is still waiting @9.53
DBG3: 06:23:05.216420 - Check if blocked lock is still waiting @9.93
DBG3: 06:23:05.617248 - Check if blocked lock is still waiting @10.33
DBG3: 06:23:06.017992 - Check if blocked lock is still waiting @10.73
DBG3: 06:23:06.418758 - Check if blocked lock is still waiting @11.13
DBG3: 06:23:06.819551 - Check if blocked lock is still waiting @11.53
DBG1: 06:23:06.819690 - Unlock file (F_UNLCK, F_SETLK) off=0 len=0 range(0, 18446744073709551615)
DBG3: 06:23:06.821052 - Wait up to 30 secs to check if blocked lock has been granted @11.53
DBG3: 06:23:06.821324 - Getting results from blocked lock @11.53
DBG1: 06:23:06.821500 - Unlock file (F_UNLCK, F_SETLK) off=0 len=0 range(0, 18446744073709551615) on second process @11.53
DBG2: 06:23:06.823196 - Open file for writing [nfstest_lock_20230314_062255_f_001]
DBG1: 06:23:06.824148 - Lock file (F_WRLCK, F_SETLKW) off=4096 len=4096 range(4096, 8191)
DBG2: 06:23:06.825012 - Open file for reading and writing [nfstest_lock_20230314_062255_f_001] on second process
DBG1: 06:23:06.826537 - Lock file (F_WRLCK, F_SETLKW) off=4096 len=4096 range(4096, 8191) on second process @11.54
DBG3: 06:23:06.926952 - Wait 2.00 secs to unlock conflicting lock @11.64
DBG3: 06:23:06.927017 - Check if blocked lock is still waiting @11.64
DBG3: 06:23:07.327640 - Check if blocked lock is still waiting @12.04
DBG3: 06:23:07.728351 - Check if blocked lock is still waiting @12.44
DBG3: 06:23:08.129052 - Check if blocked lock is still waiting @12.84
DBG3: 06:23:08.529797 - Check if blocked lock is still waiting @13.24
DBG3: 06:23:08.930560 - Check if blocked lock is still waiting @13.64
DBG1: 06:23:08.930686 - Unlock file (F_UNLCK, F_SETLK) off=0 len=0 range(0, 18446744073709551615)
DBG3: 06:23:08.932085 - Wait up to 30 secs to check if blocked lock has been granted @13.64
DBG3: 06:23:08.932587 - Getting results from blocked lock @13.64
DBG1: 06:23:08.932845 - Unlock file (F_UNLCK, F_SETLK) off=0 len=0 range(0, 18446744073709551615) on second process @13.64
DBG2: 06:23:08.934929 - Open file for reading and writing [nfstest_lock_20230314_062255_f_001]
DBG1: 06:23:08.935954 - Lock file (F_RDLCK, F_SETLKW) off=4096 len=4096 range(4096, 8191)
DBG2: 06:23:08.936922 - Open file for reading [nfstest_lock_20230314_062255_f_001] on second process
DBG1: 06:23:08.938598 - Lock file (F_RDLCK, F_SETLKW) off=4096 len=4096 range(4096, 8191) on second process @13.65
DBG1: 06:23:08.939725 - Unlock file (F_UNLCK, F_SETLK) off=0 len=0 range(0, 18446744073709551615)
DBG1: 06:23:08.940587 - Lock file (F_RDLCK, F_SETLKW) off=4096 len=4096 range(4096, 8191) on second process @13.65
DBG1: 06:23:08.941665 - Unlock file (F_UNLCK, F_SETLK) off=0 len=0 range(0, 18446744073709551615) on second process @13.65
DBG2: 06:23:08.943781 - Open file for reading and writing [nfstest_lock_20230314_062255_f_001]
DBG1: 06:23:08.944787 - Lock file (F_RDLCK, F_SETLKW) off=4096 len=4096 range(4096, 8191)
DBG2: 06:23:08.945596 - Open file for reading [nfstest_lock_20230314_062255_f_001] on second process
DBG1: 06:23:08.947130 - Lock file (F_WRLCK, F_SETLKW) off=4096 len=4096 range(4096, 8191) on second process @13.66
DBG1: 06:23:08.947671 - Unlock file (F_UNLCK, F_SETLK) off=0 len=0 range(0, 18446744073709551615)
DBG2: 06:23:08.949500 - Open file for reading and writing [nfstest_lock_20230314_062255_f_001]
DBG1: 06:23:08.950393 - Lock file (F_RDLCK, F_SETLKW) off=4096 len=4096 range(4096, 8191)
DBG2: 06:23:08.951112 - Open file for writing [nfstest_lock_20230314_062255_f_001] on second process
DBG1: 06:23:08.952117 - Lock file (F_RDLCK, F_SETLKW) off=4096 len=4096 range(4096, 8191) on second process @13.66
DBG1: 06:23:08.952682 - Unlock file (F_UNLCK, F_SETLK) off=0 len=0 range(0, 18446744073709551615)
DBG2: 06:23:08.954569 - Open file for reading and writing [nfstest_lock_20230314_062255_f_001]
DBG1: 06:23:08.955422 - Lock file (F_RDLCK, F_SETLKW) off=4096 len=4096 range(4096, 8191)
DBG2: 06:23:08.956170 - Open file for writing [nfstest_lock_20230314_062255_f_001] on second process
DBG1: 06:23:08.957164 - Lock file (F_WRLCK, F_SETLKW) off=4096 len=4096 range(4096, 8191) on second process @13.67
DBG3: 06:23:09.057678 - Wait 2.00 secs to unlock conflicting lock @13.77
DBG3: 06:23:09.057827 - Check if blocked lock is still waiting @13.77
DBG3: 06:23:09.458543 - Check if blocked lock is still waiting @14.17
DBG3: 06:23:09.859373 - Check if blocked lock is still waiting @14.57
DBG3: 06:23:10.260159 - Check if blocked lock is still waiting @14.97
DBG3: 06:23:10.660940 - Check if blocked lock is still waiting @15.37
DBG3: 06:23:11.061652 - Check if blocked lock is still waiting @15.77
DBG1: 06:23:11.061790 - Unlock file (F_UNLCK, F_SETLK) off=0 len=0 range(0, 18446744073709551615)
DBG3: 06:23:11.063264 - Wait up to 30 secs to check if blocked lock has been granted @15.78
DBG3: 06:23:11.063573 - Getting results from blocked lock @15.78
DBG1: 06:23:11.063810 - Unlock file (F_UNLCK, F_SETLK) off=0 len=0 range(0, 18446744073709551615) on second process @15.78
DBG2: 06:23:11.066051 - Open file for reading and writing [nfstest_lock_20230314_062255_f_001]
DBG1: 06:23:11.067110 - Lock file (F_RDLCK, F_SETLKW) off=4096 len=4096 range(4096, 8191)
DBG2: 06:23:11.067910 - Open file for reading and writing [nfstest_lock_20230314_062255_f_001] on second process
DBG1: 06:23:11.069455 - Lock file (F_RDLCK, F_SETLKW) off=4096 len=4096 range(4096, 8191) on second process @15.78
DBG1: 06:23:11.070678 - Unlock file (F_UNLCK, F_SETLK) off=0 len=0 range(0, 18446744073709551615)
DBG1: 06:23:11.071530 - Lock file (F_RDLCK, F_SETLKW) off=4096 len=4096 range(4096, 8191) on second process @15.78
DBG1: 06:23:11.072589 - Unlock file (F_UNLCK, F_SETLK) off=0 len=0 range(0, 18446744073709551615) on second process @15.78
DBG2: 06:23:11.074517 - Open file for reading and writing [nfstest_lock_20230314_062255_f_001]
DBG1: 06:23:11.075427 - Lock file (F_RDLCK, F_SETLKW) off=4096 len=4096 range(4096, 8191)
DBG2: 06:23:11.076208 - Open file for reading and writing [nfstest_lock_20230314_062255_f_001] on second process
DBG1: 06:23:11.077861 - Lock file (F_WRLCK, F_SETLKW) off=4096 len=4096 range(4096, 8191) on second process @15.79
DBG3: 06:23:11.178350 - Wait 2.00 secs to unlock conflicting lock @15.89
DBG3: 06:23:11.178495 - Check if blocked lock is still waiting @15.89
DBG3: 06:23:11.579193 - Check if blocked lock is still waiting @16.29
DBG3: 06:23:11.979953 - Check if blocked lock is still waiting @16.69
DBG3: 06:23:12.380701 - Check if blocked lock is still waiting @17.09
DBG3: 06:23:12.781403 - Check if blocked lock is still waiting @17.49
DBG3: 06:23:13.182140 - Check if blocked lock is still waiting @17.89
DBG1: 06:23:13.182277 - Unlock file (F_UNLCK, F_SETLK) off=0 len=0 range(0, 18446744073709551615)
DBG3: 06:23:13.183493 - Wait up to 30 secs to check if blocked lock has been granted @17.90
DBG3: 06:23:13.183848 - Getting results from blocked lock @17.90
DBG1: 06:23:13.184082 - Unlock file (F_UNLCK, F_SETLK) off=0 len=0 range(0, 18446744073709551615) on second process @17.90
DBG2: 06:23:13.186297 - Open file for reading and writing [nfstest_lock_20230314_062255_f_001]
DBG1: 06:23:13.187353 - Lock file (F_WRLCK, F_SETLKW) off=4096 len=4096 range(4096, 8191)
DBG2: 06:23:13.188158 - Open file for reading [nfstest_lock_20230314_062255_f_001] on second process
DBG1: 06:23:13.189912 - Lock file (F_RDLCK, F_SETLKW) off=4096 len=4096 range(4096, 8191) on second process @17.90
DBG3: 06:23:13.290408 - Wait 2.00 secs to unlock conflicting lock @18.00
DBG3: 06:23:13.290554 - Check if blocked lock is still waiting @18.00
DBG3: 06:23:13.691249 - Check if blocked lock is still waiting @18.40
DBG3: 06:23:14.092001 - Check if blocked lock is still waiting @18.80
DBG3: 06:23:14.492850 - Check if blocked lock is still waiting @19.20
DBG3: 06:23:14.893615 - Check if blocked lock is still waiting @19.61
DBG3: 06:23:15.294385 - Check if blocked lock is still waiting @20.01
DBG1: 06:23:15.294546 - Unlock file (F_UNLCK, F_SETLK) off=0 len=0 range(0, 18446744073709551615)
DBG3: 06:23:15.295931 - Wait up to 30 secs to check if blocked lock has been granted @20.01
DBG3: 06:23:15.296454 - Getting results from blocked lock @20.01
DBG1: 06:23:15.296707 - Unlock file (F_UNLCK, F_SETLK) off=0 len=0 range(0, 18446744073709551615) on second process @20.01
DBG2: 06:23:15.298805 - Open file for reading and writing [nfstest_lock_20230314_062255_f_001]
DBG1: 06:23:15.299886 - Lock file (F_WRLCK, F_SETLKW) off=4096 len=4096 range(4096, 8191)
DBG2: 06:23:15.300656 - Open file for reading [nfstest_lock_20230314_062255_f_001] on second process
DBG1: 06:23:15.302197 - Lock file (F_WRLCK, F_SETLKW) off=4096 len=4096 range(4096, 8191) on second process @20.01
DBG1: 06:23:15.302737 - Unlock file (F_UNLCK, F_SETLK) off=0 len=0 range(0, 18446744073709551615)
DBG2: 06:23:15.304708 - Open file for reading and writing [nfstest_lock_20230314_062255_f_001]
DBG1: 06:23:15.305634 - Lock file (F_WRLCK, F_SETLKW) off=4096 len=4096 range(4096, 8191)
DBG2: 06:23:15.306358 - Open file for writing [nfstest_lock_20230314_062255_f_001] on second process
DBG1: 06:23:15.307455 - Lock file (F_RDLCK, F_SETLKW) off=4096 len=4096 range(4096, 8191) on second process @20.02
DBG1: 06:23:15.307976 - Unlock file (F_UNLCK, F_SETLK) off=0 len=0 range(0, 18446744073709551615)
DBG2: 06:23:15.309862 - Open file for reading and writing [nfstest_lock_20230314_062255_f_001]
DBG1: 06:23:15.310781 - Lock file (F_WRLCK, F_SETLKW) off=4096 len=4096 range(4096, 8191)
DBG2: 06:23:15.311511 - Open file for writing [nfstest_lock_20230314_062255_f_001] on second process
DBG1: 06:23:15.312685 - Lock file (F_WRLCK, F_SETLKW) off=4096 len=4096 range(4096, 8191) on second process @20.02
DBG3: 06:23:15.413205 - Wait 2.00 secs to unlock conflicting lock @20.13
DBG3: 06:23:15.413326 - Check if blocked lock is still waiting @20.13
DBG3: 06:23:15.814032 - Check if blocked lock is still waiting @20.53
DBG3: 06:23:16.214765 - Check if blocked lock is still waiting @20.93
DBG3: 06:23:16.615532 - Check if blocked lock is still waiting @21.33
DBG3: 06:23:17.016244 - Check if blocked lock is still waiting @21.73
DBG3: 06:23:17.417073 - Check if blocked lock is still waiting @22.13
DBG1: 06:23:17.417205 - Unlock file (F_UNLCK, F_SETLK) off=0 len=0 range(0, 18446744073709551615)
DBG3: 06:23:17.418637 - Wait up to 30 secs to check if blocked lock has been granted @22.13
DBG3: 06:23:17.419060 - Getting results from blocked lock @22.13
DBG1: 06:23:17.419277 - Unlock file (F_UNLCK, F_SETLK) off=0 len=0 range(0, 18446744073709551615) on second process @22.13
DBG2: 06:23:17.421602 - Open file for reading and writing [nfstest_lock_20230314_062255_f_001]
DBG1: 06:23:17.422734 - Lock file (F_WRLCK, F_SETLKW) off=4096 len=4096 range(4096, 8191)
DBG2: 06:23:17.423519 - Open file for reading and writing [nfstest_lock_20230314_062255_f_001] on second process
DBG1: 06:23:17.425107 - Lock file (F_RDLCK, F_SETLKW) off=4096 len=4096 range(4096, 8191) on second process @22.14
DBG3: 06:23:17.525565 - Wait 2.00 secs to unlock conflicting lock @22.24
DBG3: 06:23:17.525664 - Check if blocked lock is still waiting @22.24
DBG3: 06:23:17.926317 - Check if blocked lock is still waiting @22.64
DBG3: 06:23:18.327034 - Check if blocked lock is still waiting @23.04
DBG3: 06:23:18.727747 - Check if blocked lock is still waiting @23.44
DBG3: 06:23:19.128483 - Check if blocked lock is still waiting @23.84
DBG3: 06:23:19.529251 - Check if blocked lock is still waiting @24.24
DBG1: 06:23:19.529363 - Unlock file (F_UNLCK, F_SETLK) off=0 len=0 range(0, 18446744073709551615)
DBG3: 06:23:19.530746 - Wait up to 30 secs to check if blocked lock has been granted @24.24
DBG3: 06:23:19.531207 - Getting results from blocked lock @24.24
DBG1: 06:23:19.531480 - Unlock file (F_UNLCK, F_SETLK) off=0 len=0 range(0, 18446744073709551615) on second process @24.24
DBG2: 06:23:19.533654 - Open file for reading and writing [nfstest_lock_20230314_062255_f_001]
DBG1: 06:23:19.534652 - Lock file (F_WRLCK, F_SETLKW) off=4096 len=4096 range(4096, 8191)
DBG2: 06:23:19.535368 - Open file for reading and writing [nfstest_lock_20230314_062255_f_001] on second process
DBG1: 06:23:19.536879 - Lock file (F_WRLCK, F_SETLKW) off=4096 len=4096 range(4096, 8191) on second process @24.25
DBG3: 06:23:19.637347 - Wait 2.00 secs to unlock conflicting lock @24.35
DBG3: 06:23:19.637475 - Check if blocked lock is still waiting @24.35
DBG3: 06:23:20.038165 - Check if blocked lock is still waiting @24.75
DBG3: 06:23:20.438926 - Check if blocked lock is still waiting @25.15
DBG3: 06:23:20.839666 - Check if blocked lock is still waiting @25.55
DBG3: 06:23:21.240411 - Check if blocked lock is still waiting @25.95
DBG3: 06:23:21.641165 - Check if blocked lock is still waiting @26.35
DBG1: 06:23:21.641288 - Unlock file (F_UNLCK, F_SETLK) off=0 len=0 range(0, 18446744073709551615)
DBG3: 06:23:21.642541 - Wait up to 30 secs to check if blocked lock has been granted @26.35
DBG3: 06:23:21.643050 - Getting results from blocked lock @26.36
DBG1: 06:23:21.643321 - Unlock file (F_UNLCK, F_SETLK) off=0 len=0 range(0, 18446744073709551615) on second process @26.36
PASS: Locking byte range (72 passed, 0 failed)
FAIL: Locking with overlapping range on second process (47 passed, 1 failed)
PASS: Unlocking full file should be granted (36 passed, 0 failed)
FAIL: Locking byte range on second process (19 passed, 1 failed)
PASS: Unlocking full file on second process should be granted (32 passed, 0 failed)
PASS: Unlocking full file after delay should be granted (12 passed, 0 failed)
PASS: Blocked lock is granted after conflicting lock is released (12 passed, 0 failed)
TIME: 25.676022s
DBG3: 06:23:21.645848 - Stop remote procedure server locally
DBG2: 06:23:21.660399 - Unmount volume: /usr/bin/sudo umount -f /mnt/t_01
DBG2: 06:23:21.845561 - Unmount volume: /usr/bin/sudo umount -f /mnt/t
7 tests (5 passed, 2 failed)
Total time: 26.671202s
^ permalink raw reply [flat|nested] 2+ messages in thread
* Re: help interpreting nfstest_lock output
2023-03-14 10:30 help interpreting nfstest_lock output Jeff Layton
@ 2023-03-17 19:29 ` Mora, Jorge
0 siblings, 0 replies; 2+ messages in thread
From: Mora, Jorge @ 2023-03-17 19:29 UTC (permalink / raw
To: Jeff Layton; +Cc: linux-nfs@vger.kernel.org, Amir Goldstein
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@kernel.org>
Sent: Tuesday, March 14, 2023 4:30 AM
To: Mora, Jorge
Cc: linux-nfs@vger.kernel.org; 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@kernel.org>
^ permalink raw reply [flat|nested] 2+ messages in thread
end of thread, other threads:[~2023-03-17 19:29 UTC | newest]
Thread overview: 2+ messages (download: mbox.gz follow: Atom feed
-- links below jump to the message on this page --
2023-03-14 10:30 help interpreting nfstest_lock output Jeff Layton
2023-03-17 19:29 ` Mora, Jorge
This is a public inbox, see mirroring instructions
for how to clone and mirror all data and code used for this inbox;
as well as URLs for read-only IMAP folder(s) and NNTP newsgroup(s).