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 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 NNTP newsgroup(s).