[Gluster-users] Fwd: bug in 3.4.1 when creating symlinks

Wed Nov 13 19:34:49 UTC 2013

On Wed, Nov 13, 2013 at 9:01 AM, Peter Drake <peter.drake at acquia.com> wrote:

> I have a replicated Gluster setup, 2 servers (fs-1 and fs-2) x 1 brick.  I
> have two clients (web-1 and web-2) which are connected and simultaneously
> execute tasks.  These clients mount the Gluster volume at /mnt/gfs.  One
> task they execute looks like this (note this is pseudocode, the actual task
> is PHP):
>
> 1. @symlink(/mnt/gfs/slow265, /mnt/gfs/slow265.prod);
> 2. if (!is_link(/mnt/gfs/slow265.prod)) {
> 3.   throw Exception;
> 4. }
> 5. symlink(/mnt/gfs/slow265.prod, /home/user/slow265.prod)
>
> Note that line 1 may fail on either client because the link may have been
> created by the other client, but this is suppressed, the link is checked
> and an exception is thrown if the link does not exist.  These two tasks,
> when executed at the same time, usually succeed.  However, in a recent run,
> we saw an error on web-1 in line 5 because the local filesystem symlink
> creation failed, despite line 2 confirming that the target Gluster symlink
> existed.
>

This is strange. The creation of a symlink is completely independent of
whether the destination exists, readable, or whatever. If creation of a
symlink failed, it cannot be because of anything to do with the
destination. Unless symlink() of PHP does something "intelligent" and makes
it behave differently than symlink(2) syscall.

> I've created a PHP script which can be run simultaneously on two clients
> to recreate the error: https://gist.github.com/pdrakeweb/7347198
>
> Running the same test script on a Gluster 3.0.8 setup does not cause the
> error to occur.  Running the same test on a local-only filesystem also does
> not cause the error to occur.  I'd appreciate any insight people might have
> into what is going on here and whether this is a bug in 3.4.1.  Below are
> the related log entries from my Gluster servers and clients.
>
> Entries from web-1's mnt-gfs.log file:
>
> [2013-11-05 05:25:24.686506] W [client-rpc-fops.c:259:client3_3_mknod_cbk] 0-test-fs-cluster-1-client-1: remote operation failed: File exists. Path: /slow265.prod (00000000-0000-0000-0000-000000000000)
> [2013-11-05 05:25:24.686584] W [client-rpc-fops.c:259:client3_3_mknod_cbk] 0-test-fs-cluster-1-client-0: remote operation failed: File exists. Path: /slow265.prod (00000000-0000-0000-0000-000000000000)
>
>
So, slow265.prod is supposed to be a symlink? I really wonder why mknod()
is in the picture.

> [2013-11-05 05:25:24.686649] E [dht-helper.c:1052:dht_inode_ctx_get] (-->/usr/lib/x86_64-linux-gnu/glusterfs/3.4git/xlator/cluster/distribute.so(dht_lookup_linkfile_create_cbk+0x75) [0x7f5e03dd4ff5] (-->/usr/lib/x86_64-linux-gnu/glusterfs/3.4git/xlator/cluster/distribute.so(dht_layout_preset+0x59) [0x7f5e03dc1c89] (-->/usr/lib/x86_64-linux-gnu/glusterfs/3.4git/xlator/cluster/distribute.so(dht_inode_ctx_layout_set+0x34) [0x7f5e03dc3b34]))) 0-test-fs-cluster-1-dht: invalid argument: inode
> [2013-11-05 05:25:24.686687] E [dht-helper.c:1071:dht_inode_ctx_set] (-->/usr/lib/x86_64-linux-gnu/glusterfs/3.4git/xlator/cluster/distribute.so(dht_lookup_linkfile_create_cbk+0x75) [0x7f5e03dd4ff5] (-->/usr/lib/x86_64-linux-gnu/glusterfs/3.4git/xlator/cluster/distribute.so(dht_layout_preset+0x59) [0x7f5e03dc1c89] (-->/usr/lib/x86_64-linux-gnu/glusterfs/3.4git/xlator/cluster/distribute.so(dht_inode_ctx_layout_set+0x52) [0x7f5e03dc3b52]))) 0-test-fs-cluster-1-dht: invalid argument: inode
> [2013-11-05 05:25:24.689670] W [fuse-bridge.c:1311:fuse_readlink_cbk] 0-glusterfs-fuse: 1736: /slow265.prod => -1 (Invalid argument)
>
>
> Entries from web-2's mnt-gfs.log file:
>
> [2013-11-05 05:25:26.164593] W [client-rpc-fops.c:2469:client3_3_link_cbk] 0-test-fs-cluster-1-client-1: remote operation failed: File exists (00000000-0000-0000-0000-000000000000 -> /slow265.prod)
>
>
client3_3_link_cbk is the callback for the link() hardlink system call.
Wonder why that is coming in the picture! Neither should mknod(). Going by
your script, the only calls should be SYMLINK, LOOKUP and READLINK.

> [2013-11-05 05:25:26.210652] W [client-rpc-fops.c:2469:client3_3_link_cbk] 0-test-fs-cluster-1-client-0: remote operation failed: File exists (00000000-0000-0000-0000-000000000000 -> /slow265.prod)
>
>
> Entries from fs-1's brick.log:
>
> [2013-11-05 05:25:24.832262] I [server-rpc-fops.c:575:server_mknod_cbk] 0-test-fs-cluster-1-server: 3337: MKNOD (null) (00000000-0000-0000-0000-000000000001/slow265.prod) ==> (File exists)
>
> [2013-11-05 05:25:26.391611] I [server-rpc-fops.c:1211:server_link_cbk] 0-test-fs-cluster-1-server: 3301: LINK /slow265.prod (3658314e-7730-4771-8ac3-2d6fb20b1b13) -> 00000000-0000-0000-0000-000000000001/slow265.prod ==> (File exists)
>
>
>
>
> Entries from fs-2's brick.log:
>
> [2013-11-05 05:25:24.554824] I [server-rpc-fops.c:575:server_mknod_cbk] 0-test-fs-cluster-1-server: 3290: MKNOD (null) (00000000-0000-0000-0000-000000000001/slow265.prod) ==> (File exists)
>
> [2013-11-05 05:25:26.160204] I [server-rpc-fops.c:1211:server_link_cbk] 0-test-fs-cluster-1-server: 3341: LINK /slow265.prod (3658314e-7730-4771-8ac3-2d6fb20b1b13) -> 00000000-0000-0000-0000-000000000001/slow265.prod ==> (File exists)
>
>
Again, LINK is a hardlink call. Not sure why that is coming into the
picture. Is slow265 supposed to be a symlink or a hardlink?

Is rename() somehow involved? I don't see any rename() calls in your script.

With the info you have given above, all I can say is: either the script in
gist did not create the above logs, or PHP does something really really
weird under the hoods. Is it possible to give the strace logs on the script
while it executed? That should clarify a lot of things..

Avati
-------------- next part --------------
An HTML attachment was scrubbed...
URL: <http://supercolony.gluster.org/pipermail/gluster-users/attachments/20131113/a0714858/attachment.html>