From: DENIEL Philippe <philippe.deniel@cea.fr>
To: Ganesha NFS List <nfs-ganesha-devel@lists.sourceforge.net>,
NFS list <linux-nfs@vger.kernel.org>
Subject: Help wanted: ENOCLK returned during lock test#2 in connectathon's test
Date: Mon, 05 Dec 2011 14:52:09 +0100 [thread overview]
Message-ID: <4EDCCC89.6080205@cea.fr> (raw)
[-- Attachment #1: Type: text/plain, Size: 3295 bytes --]
Hi,
as you may know (we may have met at Bake-A-Thon), I am working on
NFS-Ganesha, a NFS server running in userspace. I currently face an
issue when running cthon04 test suite, during the "lock step".
Client is linux 3.1.0-rc4, server is nfs-ganesha compiled with FSAL_VFS
support. Server is mounted via command "mount
-overs=4.minorversion=1,lock <server>:<path> /mnt"
During the test#2 in "lock" tests, I got the following error:
Creating parent/child synchronization pipes.
Test #2 - Try to lock the whole file.
Parent: 2.0 - F_TLOCK [ 0, ENDING]
FAILED!
Parent: **** Expected success, returned errno=37...
Parent: **** Probably implementation error.
** PARENT pass 1 results: 0/0 pass, 0/0 warn, 1/1 fail (pass/total).
** CHILD pass 1 results: 0/0 pass, 0/0 warn, 0/0 fail (pass/total).
I made a wireshark capture of the packet (see attachement). Apparently,
the client does 2 compounds, one for OP4_OPEN and a second to call
OP4_OPEN_CONFIRM.
On the client side, the "locl/locklfs" binary fails when calling lockf()
(this is not the first time it calls it, it has been done in test#1
which passed successfully). Error return is ENOLCK (posix error #37).
I enabled the kernel's debug message by using the command 'echo 32767 >
/proc/sys/sunrpc/nfs_debug' (complete log in attachement, reduced to
what is related to lock#2). Grepping 'NFS' in this shows this:
Dec 5 13:31:08 aury63 kernel: NFS: nfs_update_inode(0:16/523265
ct=2 info=0x27e7f)
Dec 5 13:31:08 aury63 kernel: NFS: permission(0:16/523265),
mask=0x1, res=0
Dec 5 13:31:08 aury63 kernel: NFS: nfs_lookup_revalidate(/rep) is valid
Dec 5 13:31:08 aury63 kernel: NFS: nfs_update_inode(0:16/544895
ct=1 info=0x27e7f)
Dec 5 13:31:08 aury63 kernel: NFS: permission(0:16/544895),
mask=0x1, res=0
Dec 5 13:31:08 aury63 kernel: NFS: permission(0:16/544895),
mask=0x1, res=0
Dec 5 13:31:08 aury63 kernel: NFS: atomic_lookup(0:16/544895),
lockfile2908
Dec 5 13:31:08 aury63 kernel: decode_attr_pnfstype: bitmap is 0
Dec 5 13:31:08 aury63 kernel: nfs4_schedule_state_renewal:
requeueing work. Lease period = 80
Dec 5 13:31:08 aury63 kernel: --> nfs_put_client({2})
Dec 5 13:31:08 aury63 kernel: <-- nfs4_setup_sequence status=0
Dec 5 13:31:08 aury63 kernel: NFS: nfs_update_inode(0:16/544895
ct=1 info=0x27e67)
Dec 5 13:31:08 aury63 kernel: NFS: change_attr change on server for
file 0:16/544895
Dec 5 13:31:08 aury63 kernel: NFS: mtime change on server for file
0:16/544895
Dec 5 13:31:08 aury63 kernel: NFS: nfs_fhget(0:16/544930 ct=1)
Dec 5 13:31:08 aury63 kernel: NFS: open file(rep/lockfile2908)
Dec 5 13:31:08 aury63 kernel: NFS: permission(0:16/544930),
mask=0x26, res=0
Dec 5 13:31:08 aury63 kernel: NFS: lock(rep/lockfile2908, t=1,
fl=1, r=0:9223372036854775807)
I can see no reason why ENOLCK is returned. This is clearly a bug on the
server handside (within nfs-ganesha) but I have to know what the client
is doing here to have a clearer idea.
I ran the same test using NFSv4.1 and NFSv3+NLMv4, things go perfectly
OK with no failure.
Can someone help me ?
Regards
Philippe
[-- Attachment #2: bug_lock_2.pcap --]
[-- Type: application/octet-stream, Size: 1548 bytes --]
[-- Attachment #3: log_kernel_bug_lock2.txt --]
[-- Type: text/plain, Size: 6686 bytes --]
Dec 5 13:31:08 aury63 kernel: encode_compound: tag=
Dec 5 13:31:08 aury63 kernel: decode_attr_type: type=040000
Dec 5 13:31:08 aury63 kernel: decode_attr_change: change attribute=1323082676
Dec 5 13:31:08 aury63 kernel: decode_attr_size: file size=856064
Dec 5 13:31:08 aury63 kernel: decode_attr_fsid: fsid=(0xc0/0xa8)
Dec 5 13:31:08 aury63 kernel: decode_attr_fileid: fileid=523265
Dec 5 13:31:08 aury63 kernel: decode_attr_fs_locations: fs_locations done, error = 0
Dec 5 13:31:08 aury63 kernel: decode_attr_mode: file mode=01777
Dec 5 13:31:08 aury63 kernel: decode_attr_nlink: nlink=14
Dec 5 13:31:08 aury63 kernel: decode_attr_owner: uid=0
Dec 5 13:31:08 aury63 kernel: decode_attr_group: gid=0
Dec 5 13:31:08 aury63 kernel: decode_attr_rdev: rdev=(0x0:0x0)
Dec 5 13:31:08 aury63 kernel: decode_attr_space_used: space used=860160
Dec 5 13:31:08 aury63 kernel: decode_attr_time_access: atime=1323081627
Dec 5 13:31:08 aury63 kernel: decode_attr_time_metadata: ctime=1323082676
Dec 5 13:31:08 aury63 kernel: decode_attr_time_modify: mtime=1323082676
Dec 5 13:31:08 aury63 kernel: decode_attr_mounted_on_fileid: fileid=0
Dec 5 13:31:08 aury63 kernel: decode_getfattr: xdr returned 0
Dec 5 13:31:08 aury63 kernel: NFS: nfs_update_inode(0:16/523265 ct=2 info=0x27e7f)
Dec 5 13:31:08 aury63 kernel: NFS: permission(0:16/523265), mask=0x1, res=0
Dec 5 13:31:08 aury63 kernel: NFS: nfs_lookup_revalidate(/rep) is valid
Dec 5 13:31:08 aury63 kernel: encode_compound: tag=
Dec 5 13:31:08 aury63 kernel: decode_attr_type: type=040000
Dec 5 13:31:08 aury63 kernel: decode_attr_change: change attribute=1323088137
Dec 5 13:31:08 aury63 kernel: decode_attr_size: file size=4096
Dec 5 13:31:08 aury63 kernel: decode_attr_fsid: fsid=(0xc0/0xa8)
Dec 5 13:31:08 aury63 kernel: decode_attr_fileid: fileid=544895
Dec 5 13:31:08 aury63 kernel: decode_attr_fs_locations: fs_locations done, error = 0
Dec 5 13:31:08 aury63 kernel: decode_attr_mode: file mode=0755
Dec 5 13:31:08 aury63 kernel: decode_attr_nlink: nlink=2
Dec 5 13:31:08 aury63 kernel: decode_attr_owner: uid=0
Dec 5 13:31:08 aury63 kernel: decode_attr_group: gid=0
Dec 5 13:31:08 aury63 kernel: decode_attr_rdev: rdev=(0x0:0x0)
Dec 5 13:31:08 aury63 kernel: decode_attr_space_used: space used=4096
Dec 5 13:31:08 aury63 kernel: decode_attr_time_access: atime=1323071853
Dec 5 13:31:08 aury63 kernel: decode_attr_time_metadata: ctime=1323088137
Dec 5 13:31:08 aury63 kernel: decode_attr_time_modify: mtime=1323088137
Dec 5 13:31:08 aury63 kernel: decode_attr_mounted_on_fileid: fileid=0
Dec 5 13:31:08 aury63 kernel: decode_getfattr: xdr returned 0
Dec 5 13:31:08 aury63 kernel: NFS: nfs_update_inode(0:16/544895 ct=1 info=0x27e7f)
Dec 5 13:31:08 aury63 kernel: NFS: permission(0:16/544895), mask=0x1, res=0
Dec 5 13:31:08 aury63 kernel: NFS: permission(0:16/544895), mask=0x1, res=0
Dec 5 13:31:08 aury63 kernel: NFS: atomic_lookup(0:16/544895), lockfile2908
Dec 5 13:31:08 aury63 kernel: encode_compound: tag=
Dec 5 13:31:08 aury63 kernel: encode_compound: tag=
Dec 5 13:31:08 aury63 kernel: decode_attr_lease_time: file size=120
Dec 5 13:31:08 aury63 kernel: decode_attr_maxfilesize: maxfilesize=0
Dec 5 13:31:08 aury63 kernel: decode_attr_maxread: maxread=1024
Dec 5 13:31:08 aury63 kernel: decode_attr_maxwrite: maxwrite=1024
Dec 5 13:31:08 aury63 kernel: decode_attr_pnfstype: bitmap is 0
Dec 5 13:31:08 aury63 kernel: decode_attr_layout_blksize: bitmap is 0
Dec 5 13:31:08 aury63 kernel: decode_fsinfo: xdr returned 0!
Dec 5 13:31:08 aury63 kernel: nfs4_schedule_state_renewal: requeueing work. Lease period = 80
Dec 5 13:31:08 aury63 kernel: --> nfs_put_client({2})
Dec 5 13:31:08 aury63 kernel: <-- nfs4_setup_sequence status=0
Dec 5 13:31:08 aury63 kernel: encode_compound: tag=
Dec 5 13:31:08 aury63 kernel: decode_attr_type: type=0100000
Dec 5 13:31:08 aury63 kernel: decode_attr_change: change attribute=1323088268
Dec 5 13:31:08 aury63 kernel: decode_attr_size: file size=0
Dec 5 13:31:08 aury63 kernel: decode_attr_fsid: fsid=(0xc0/0xa8)
Dec 5 13:31:08 aury63 kernel: decode_attr_fileid: fileid=544930
Dec 5 13:31:08 aury63 kernel: decode_attr_fs_locations: fs_locations done, error = 0
Dec 5 13:31:08 aury63 kernel: decode_attr_mode: file mode=0644
Dec 5 13:31:08 aury63 kernel: decode_attr_nlink: nlink=1
Dec 5 13:31:08 aury63 kernel: decode_attr_owner: uid=-2
Dec 5 13:31:08 aury63 kernel: decode_attr_group: gid=-2
Dec 5 13:31:08 aury63 kernel: decode_attr_rdev: rdev=(0x0:0x0)
Dec 5 13:31:08 aury63 kernel: decode_attr_space_used: space used=0
Dec 5 13:31:08 aury63 kernel: decode_attr_time_access: atime=1323088268
Dec 5 13:31:08 aury63 kernel: decode_attr_time_metadata: ctime=1323088268
Dec 5 13:31:08 aury63 kernel: decode_attr_time_modify: mtime=1323088268
Dec 5 13:31:08 aury63 kernel: decode_attr_mounted_on_fileid: fileid=0
Dec 5 13:31:08 aury63 kernel: decode_getfattr: xdr returned 0
Dec 5 13:31:08 aury63 kernel: decode_attr_type: type=040000
Dec 5 13:31:08 aury63 kernel: decode_attr_change: change attribute=1323088137
Dec 5 13:31:08 aury63 kernel: decode_attr_size: file size=4096
Dec 5 13:31:08 aury63 kernel: decode_attr_fsid: fsid=(0xc0/0xa8)
Dec 5 13:31:08 aury63 kernel: decode_attr_fileid: fileid=544895
Dec 5 13:31:08 aury63 kernel: decode_attr_fs_locations: fs_locations done, error = 0
Dec 5 13:31:08 aury63 kernel: decode_attr_mode: file mode=0755
Dec 5 13:31:08 aury63 kernel: decode_attr_nlink: nlink=2
Dec 5 13:31:08 aury63 kernel: decode_attr_owner: uid=-2
Dec 5 13:31:08 aury63 kernel: decode_attr_group: gid=-2
Dec 5 13:31:08 aury63 kernel: decode_attr_rdev: rdev=(0x0:0x0)
Dec 5 13:31:08 aury63 kernel: decode_attr_space_used: space used=4096
Dec 5 13:31:08 aury63 kernel: decode_attr_time_access: atime=1323071853
Dec 5 13:31:08 aury63 kernel: decode_attr_time_metadata: ctime=1323088268
Dec 5 13:31:08 aury63 kernel: decode_attr_time_modify: mtime=1323088268
Dec 5 13:31:08 aury63 kernel: decode_attr_mounted_on_fileid: fileid=0
Dec 5 13:31:08 aury63 kernel: decode_getfattr: xdr returned 0
Dec 5 13:31:08 aury63 kernel: NFS: nfs_update_inode(0:16/544895 ct=1 info=0x27e67)
Dec 5 13:31:08 aury63 kernel: NFS: change_attr change on server for file 0:16/544895
Dec 5 13:31:08 aury63 kernel: NFS: mtime change on server for file 0:16/544895
Dec 5 13:31:08 aury63 kernel: encode_compound: tag=
Dec 5 13:31:08 aury63 kernel: NFS: nfs_fhget(0:16/544930 ct=1)
Dec 5 13:31:08 aury63 kernel: NFS: open file(rep/lockfile2908)
Dec 5 13:31:08 aury63 kernel: NFS: permission(0:16/544930), mask=0x26, res=0
Dec 5 13:31:08 aury63 kernel: NFS: lock(rep/lockfile2908, t=1, fl=1, r=0:9223372036854775807)
next reply other threads:[~2011-12-05 14:02 UTC|newest]
Thread overview: 6+ messages / expand[flat|nested] mbox.gz Atom feed top
2011-12-05 13:52 DENIEL Philippe [this message]
2011-12-05 23:33 ` Help wanted: ENOCLK returned during lock test#2 in connectathon's test Trond Myklebust
2011-12-06 12:11 ` DENIEL Philippe
2011-12-06 19:37 ` J. Bruce Fields
2011-12-07 13:29 ` DENIEL Philippe
2011-12-07 15:12 ` [Nfs-ganesha-devel] " Frank S Filz
Reply instructions:
You may reply publicly to this message via plain-text email
using any one of the following methods:
* Save the following mbox file, import it into your mail client,
and reply-to-all from there: mbox
Avoid top-posting and favor interleaved quoting:
https://en.wikipedia.org/wiki/Posting_style#Interleaved_style
* Reply using the --to, --cc, and --in-reply-to
switches of git-send-email(1):
git send-email \
--in-reply-to=4EDCCC89.6080205@cea.fr \
--to=philippe.deniel@cea.fr \
--cc=linux-nfs@vger.kernel.org \
--cc=nfs-ganesha-devel@lists.sourceforge.net \
/path/to/YOUR_REPLY
https://kernel.org/pub/software/scm/git/docs/git-send-email.html
* If your mail client supports setting the In-Reply-To header
via mailto: links, try the mailto: link
Be sure your reply has a Subject: header at the top and a blank line
before the message body.
This is an external index of several public inboxes,
see mirroring instructions on how to clone and mirror
all data and code used by this external index.