On Thu, Apr 17, 2008 at 07:44:08PM +0200, Miklos Szeredi wrote:
> 1) on server lock file X
> 2) on client lock file X
> blocks
> 3) on client send interrupt to process doing locking
> locking syscall restarted, continues blocking
> 4) on server release lock on file X
> on client lock is acquired
> 5) on client release lock on file X
> 6) on client lock file X
> blocks
>
> Everything up to the last step is fine, but something goes wrong
> during the final unlock. Stopping the nfs-server removes the stray
> lock.
>
> Here's a trace on the server:
>
> lockd: request from 192.168.1.1, port=862
> lockd: LOCK called
> lockd: nlm_lookup_host(192.168.1.2->192.168.1.1, p=6, v=4, my role=server, name=tucsk)
> lockd: get host tucsk
> lockd: nsm_monitor(tucsk)
> lockd: nlm_lookup_file (02000001 00006200 00000002 0001783d 7f54ef79 00017801 d06c5915 00000000)
> lockd: creating file for (02000001 00006200 00000002 0001783d 7f54ef79 00017801 d06c5915 00000000)
> lockd: found file 0ad074c0 (count 0)
> lockd: nlmsvc_lock(ubda/96317, ty=1, pi=1, 0-99, bl=1)
> lockd: nlm_lookup_host(192.168.1.2->192.168.1.1, p=6, v=4, my role=server, name=tucsk)
> lockd: get host tucsk
> lockd: nlmsvc_lookup_block f=0ad074c0 pd=1 0-99 ty=1
> lockd: get host tucsk
> lockd: created block 0aeabf80...
> lockd: vfs_lock_file returned 1
Why is vfs_lock_file returning 1? It should be 0 or -ERRNO.
--b.
> lockd: nlmsvc_insert_block(0aeabf80, -1)
> lockd: release host tucsk
> lockd: nlmsvc_lock returned 50331648
> lockd: LOCK status 3
> lockd: release host tucsk
> lockd: nlm_release_file(0ad074c0, ct = 2)
> lockd: request from 192.168.1.1, port=862
> lockd: CANCEL called
> lockd: nlm_lookup_host(192.168.1.2->192.168.1.1, p=6, v=4, my role=server, name=tucsk)
> lockd: get host tucsk
> lockd: nlm_lookup_file (02000001 00006200 00000002 0001783d 7f54ef79 00017801 d06c5915 00000000)
> lockd: found file 0ad074c0 (count 1)
> lockd: nlmsvc_cancel(ubda/96317, pi=1, 0-99)
> lockd: nlmsvc_lookup_block f=0ad074c0 pd=1 0-99 ty=1
> lockd: check f=0ad074c0 pd=1 0-99 ty=1 cookie=36120000
> lockd: unlinking block 0aeabf80...
> lockd: freeing block 0aeabf80...
> lockd: release host tucsk
> lockd: nlm_release_file(0ad074c0, ct = 2)
> lockd: CANCEL status 0
> lockd: release host tucsk
> lockd: nlm_release_file(0ad074c0, ct = 1)
> lockd: closing file ubda/96317
> lockd: request from 192.168.1.1, port=862
> lockd: LOCK called
> lockd: nlm_lookup_host(192.168.1.2->192.168.1.1, p=6, v=4, my role=server, name=tucsk)
> lockd: get host tucsk
> lockd: nsm_monitor(tucsk)
> lockd: nlm_lookup_file (02000001 00006200 00000002 0001783d 7f54ef79 00017801 d06c5915 00000000)
> lockd: creating file for (02000001 00006200 00000002 0001783d 7f54ef79 00017801 d06c5915 00000000)
> lockd: found file 0ad074c0 (count 0)
> lockd: nlmsvc_lock(ubda/96317, ty=1, pi=2, 0-99, bl=1)
> lockd: nlm_lookup_host(192.168.1.2->192.168.1.1, p=6, v=4, my role=server, name=tucsk)
> lockd: get host tucsk
> lockd: nlmsvc_lookup_block f=0ad074c0 pd=2 0-99 ty=1
> lockd: get host tucsk
> lockd: created block 0aeab240...
> lockd: vfs_lock_file returned 0
> lockd: freeing block 0aeab240...
> lockd: release host tucsk
> lockd: nlm_release_file(0ad074c0, ct = 2)
> lockd: release host tucsk
> lockd: nlmsvc_lock returned 0
> lockd: LOCK status 0
> lockd: release host tucsk
> lockd: nlm_release_file(0ad074c0, ct = 1)
> lockd: request from 192.168.1.1, port=862
> lockd: UNLOCK called
> lockd: nlm_lookup_host(192.168.1.2->192.168.1.1, p=6, v=4, my role=server, name=tucsk)
> lockd: get host tucsk
> lockd: nlm_lookup_file (02000001 00006200 00000002 0001783d 7f54ef79 00017801 d06c5915 00000000)
> lockd: found file 0ad074c0 (count 0)
> lockd: nlmsvc_unlock(ubda/96317, pi=3, 0-9223372036854775807)
> lockd: nlmsvc_cancel(ubda/96317, pi=3, 0-9223372036854775807)
> lockd: nlmsvc_lookup_block f=0ad074c0 pd=3 0-9223372036854775807 ty=2
> lockd: UNLOCK status 0
> lockd: release host tucsk
> lockd: nlm_release_file(0ad074c0, ct = 1)
>
>
> Everything looks normal, yet...
>
> This is 100% reproducable for me (ext3 exported over nfs, server and
> client: 2.6-git).
>
> Miklos
> > lockd: vfs_lock_file returned 1
>
> Why is vfs_lock_file returning 1? It should be 0 or -ERRNO.
Er sorry, that was the "return special value for async lock requests"
patch, which I was testing at the time.
It doesn't make a difference, but here's the log for nfs-2.6.git. It
also contains a '/etc/init.d/nfs-kernel-server stop' at the end, which
eventually removes the stuck lock.
Miklos
[ 180.770000] lockd: request from 192.168.1.3, port=928
[ 180.770000] lockd: LOCK called
[ 180.770000] lockd: nlm_lookup_host(192.168.1.2->192.168.1.3, p=6, v=4, my role=server, name=uml2)
[ 180.770000] lockd: get host uml2
[ 180.770000] lockd: nsm_monitor(uml2)
[ 180.770000] lockd: nlm_lookup_file (02000001 00006200 00000002 0001783d 93dc4121 00017801 d06c5915 00000000)
[ 180.770000] lockd: creating file for (02000001 00006200 00000002 0001783d 93dc4121 00017801 d06c5915 00000000)
[ 180.770000] lockd: found file 0ad722c0 (count 0)
[ 180.770000] lockd: nlmsvc_lock(ubda/96317, ty=1, pi=1, 0-99, bl=1)
[ 180.770000] lockd: nlm_lookup_host(192.168.1.2->192.168.1.3, p=6, v=4, my role=server, name=uml2)
[ 180.770000] lockd: get host uml2
[ 180.770000] lockd: nlmsvc_lookup_block f=0ad722c0 pd=1 0-99 ty=1
[ 180.770000] lockd: get host uml2
[ 180.770000] lockd: created block 0ae26200...
[ 180.770000] lockd: vfs_lock_file returned -11
[ 180.770000] lockd: nlmsvc_insert_block(0ae26200, -1)
[ 180.770000] lockd: release host uml2
[ 180.770000] lockd: nlmsvc_lock returned 50331648
[ 180.770000] lockd: LOCK status 3
[ 180.770000] lockd: release host uml2
[ 180.770000] lockd: nlm_release_file(0ad722c0, ct = 2)
[ 181.490000] lockd: request from 192.168.1.3, port=928
[ 181.490000] lockd: CANCEL called
[ 181.490000] lockd: nlm_lookup_host(192.168.1.2->192.168.1.3, p=6, v=4, my role=server, name=uml2)
[ 181.490000] lockd: get host uml2
[ 181.490000] lockd: nlm_lookup_file (02000001 00006200 00000002 0001783d 93dc4121 00017801 d06c5915 00000000)
[ 181.490000] lockd: found file 0ad722c0 (count 1)
[ 181.490000] lockd: nlmsvc_cancel(ubda/96317, pi=1, 0-99)
[ 181.490000] lockd: nlmsvc_lookup_block f=0ad722c0 pd=1 0-99 ty=1
[ 181.490000] lockd: check f=0ad722c0 pd=1 0-99 ty=1 cookie=36120000
[ 181.490000] lockd: unlinking block 0ae26200...
[ 181.490000] lockd: freeing block 0ae26200...
[ 181.490000] lockd: release host uml2
[ 181.490000] lockd: nlm_release_file(0ad722c0, ct = 2)
[ 181.490000] lockd: CANCEL status 0
[ 181.490000] lockd: release host uml2
[ 181.490000] lockd: nlm_release_file(0ad722c0, ct = 1)
[ 181.490000] lockd: closing file ubda/96317
[ 181.490000] lockd: request from 192.168.1.3, port=928
[ 181.490000] lockd: LOCK called
[ 181.490000] lockd: nlm_lookup_host(192.168.1.2->192.168.1.3, p=6, v=4, my role=server, name=uml2)
[ 181.490000] lockd: get host uml2
[ 181.490000] lockd: nsm_monitor(uml2)
[ 181.490000] lockd: nlm_lookup_file (02000001 00006200 00000002 0001783d 93dc4121 00017801 d06c5915 00000000)
[ 181.490000] lockd: creating file for (02000001 00006200 00000002 0001783d 93dc4121 00017801 d06c5915 00000000)
[ 181.490000] lockd: found file 0ad722c0 (count 0)
[ 181.490000] lockd: nlmsvc_lock(ubda/96317, ty=1, pi=2, 0-99, bl=1)
[ 181.490000] lockd: nlm_lookup_host(192.168.1.2->192.168.1.3, p=6, v=4, my role=server, name=uml2)
[ 181.490000] lockd: get host uml2
[ 181.490000] lockd: nlmsvc_lookup_block f=0ad722c0 pd=2 0-99 ty=1
[ 181.490000] lockd: get host uml2
[ 181.490000] lockd: created block 0ae26200...
[ 181.490000] lockd: vfs_lock_file returned -11
[ 181.490000] lockd: nlmsvc_insert_block(0ae26200, -1)
[ 181.490000] lockd: release host uml2
[ 181.490000] lockd: nlmsvc_lock returned 50331648
[ 181.490000] lockd: LOCK status 3
[ 181.490000] lockd: release host uml2
[ 181.490000] lockd: nlm_release_file(0ad722c0, ct = 2)
[ 183.390000] lockd: VFS unblock notification for block 0ad6c0c4
[ 183.390000] lockd: nlmsvc_insert_block(0ae26200, 0)
[ 183.390000] nlmsvc_retry_blocked(0ae26200, when=-11661)
[ 183.390000] lockd: grant blocked lock 0ae26200
[ 183.390000] lockd: unlinking block 0ae26200...
[ 183.390000] lockd: GRANTing blocked lock.
[ 183.390000] lockd: nlmsvc_insert_block(0ae26200, -1)
[ 183.390000] lockd: call procedure 10 on uml2 (async)
[ 183.390000] lockd: nlm_bind_host(192.168.1.2->192.168.1.3)
[ 183.390000] lockd: GRANT_MSG RPC callback
[ 183.390000] lockd: nlmsvc_insert_block(0ae26200, 6000)
[ 183.390000] lockd: request from 192.168.1.3, port=758
[ 183.390000] lockd: GRANTED_RES called
[ 183.390000] grant_reply: looking for cookie 1237, s=0
[ 183.390000] nlmsvc_find_block(37120000): block=0ae26200
[ 183.390000] lockd: unlinking block 0ae26200...
[ 183.390000] lockd: freeing block 0ae26200...
[ 183.390000] lockd: release host uml2
[ 183.390000] lockd: nlm_release_file(0ad722c0, ct = 1)
[ 185.100000] lockd: request from 192.168.1.3, port=928
[ 185.100000] lockd: UNLOCK called
[ 185.100000] lockd: nlm_lookup_host(192.168.1.2->192.168.1.3, p=6, v=4, my role=server, name=uml2)
[ 185.100000] lockd: get host uml2
[ 185.100000] lockd: nlm_lookup_file (02000001 00006200 00000002 0001783d 93dc4121 00017801 d06c5915 00000000)
[ 185.100000] lockd: found file 0ad722c0 (count 0)
[ 185.100000] lockd: nlmsvc_unlock(ubda/96317, pi=3, 0-9223372036854775807)
[ 185.100000] lockd: nlmsvc_cancel(ubda/96317, pi=3, 0-9223372036854775807)
[ 185.100000] lockd: nlmsvc_lookup_block f=0ad722c0 pd=3 0-9223372036854775807 ty=2
[ 185.100000] lockd: UNLOCK status 0
[ 185.100000] lockd: release host uml2
[ 185.100000] lockd: nlm_release_file(0ad722c0, ct = 1)
[ 192.280000] lockd: shutting down host module
[ 192.280000] lockd: nuking all hosts...
[ 192.280000] lockd: host garbage collection
[ 192.280000] lockd: nlmsvc_mark_resources
[ 192.280000] lockd: delete host uml2
[ 192.280000] nfsd: last server has exited
[ 192.280000] nfsd: unexporting all filesystems