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@xxxxxxxxxx>
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
