Anirban Ghoshal
2014-Feb-06 15:24 UTC
[Gluster-users] : On breaking the connection between replicated volumes certain files return -ENOTCONN
We migrated to stable version 3.4.2 and confirmed that the error occurs with that as well. I reported this over bug 1062287. Thanks again, Anirban ------------------------------ On Tue 4 Feb, 2014 2:27 PM MST Anirban Ghoshal wrote:>Hi everyone, > >Here's a strange issue. I am using glusterfs 3.4.0 alpha. We need to move to a stable version ASAP, but I am telling you this just off chance that it might be interesting for somebody from the glusterfs development team. Please excuse the sheer length of this mail, but I am new to browsing such massive code, and not good at presenting my ideas very clearly. > > >Here's a set of observations: > >1. You have a replica 2 volume (testvol) on server1 and server2. You assume that on either server, it is also locally mounted via mount.glusterfs at /testvol. >2. You have a large number of soft-linked files within the volume. >3. You check heal info (all its facets) to ensure not a single file is out of sync (also, verify md5sum or such, if possible). >4. You abrupty take down the ethernet device over which the servers are conencted (ip link set <eth-dev> down). >5. On one of the servers (say, server1 for definiteness), if you do an 'ls -l' readlink returns 'Transport endpoint is not connected'. >6. The error resolves all by itself if you get the eth-link up. > >Here's some additional detail: >7. The error is intermittent, and not all soft-linked files have the issue. >8. If you take a directory containing soft-linked files, and if you do a ls -l _on_the_directory, like so, > >server1$ ls -l /testvol/somedir/bin/ > >ls: cannot read symbolic link /testvol/somedir/bin/reset: Transport endpoint is not connected >ls: cannot read symbolic link /testvol/somedir/bin/bzless: Transport endpoint is not connected >ls: cannot read symbolic link /testvol/somedir/bin/i386: Transport endpoint is not connected >ls: cannot read symbolic link /testvol/somedir/bin/kill: Transport endpoint is not connected >ls: cannot read symbolic link /testvol/somedir/bin/linux32: Transport endpoint is not connected >ls: cannot read symbolic link /testvol/somedir/bin/linux64: Transport endpoint is not connected >ls: cannot read symbolic link /testvol/somedir/bin/logger: Transport endpoint is not connected >ls: cannot read symbolic link /testvol/somedir/bin/x86_64: Transport endpoint is not connected >ls: cannot read symbolic link /testvol/somedir/bin/python2: Transport endpoint is not connected >connected > > >9. If, however, you take a faulty soft-link and do an ls -l on it directly, then it rights itself immediately. > >server1$ ls -l /testvol/somedir/bin/x86_64 >lrwxrwxrwx 1 root root 7 May? 7 23:11 /testvol/somedir/bin/x86_64 -> setarch > > >I tried raising the client log level to 'trace'. Here's what I saw: > >Upon READLINK failures, (ls -l /testvol/somedir/bin/): > >[2010-05-09 01:13:28.140265] T [fuse-bridge.c:2453:fuse_readdir_cbk] 0-glusterfs-fuse: 2783484: READDIR => 23/4096,1380 >[2010-05-09 01:13:28.140444] T [fuse-resolve.c:51:fuse_resolve_loc_touchup] 0-fuse: return value inode_path 45 >[2010-05-09 01:13:28.140477] T [fuse-bridge.c:708:fuse_getattr_resume] 0-glusterfs-fuse: 2783485: GETATTR 140299577689176 (/testvol/somedir/bin) >[2010-05-09 01:13:28.140618] T [fuse-bridge.c:641:fuse_attr_cbk] 0-glusterfs-fuse: 2783485: STAT() /testvol/somedir/bin => -5626802993936595428 >[2010-05-09 01:13:28.140722] T [fuse-resolve.c:51:fuse_resolve_loc_touchup] 0-fuse: return value inode_path 52 >[2010-05-09 01:13:28.140737] T [fuse-bridge.c:506:fuse_lookup_resume] 0-glusterfs-fuse: 2783486: LOOKUP /testvol/somedir/bin/x86_64(025d1c57-865f-4f1f-bc95-96ddcef3dc03) >[2010-05-09 01:13:28.140851] T [fuse-bridge.c:376:fuse_entry_cbk] 0-glusterfs-fuse: 2783486: LOOKUP() /testvol/somedir/bin/x86_64 => -4857810743645185021 >[2010-05-09 01:13:28.140954] T [fuse-resolve.c:51:fuse_resolve_loc_touchup] 0-fuse: return value inode_path 52 >[2010-05-09 01:13:28.140975] T [fuse-bridge.c:1296:fuse_readlink_resume] 0-glusterfs-fuse: 2783487 READLINK /testvol/somedir/bin/x86_64/025d1c57-865f-4f1f-bc95-96ddcef3dc03 >[2010-05-09 01:13:28.141090] D [afr-common.c:760:afr_get_call_child] 0-_testvol-replicate-0: Returning -107, call_child: -1, last_index: -1 >[2010-05-09 01:13:28.141120] W [fuse-bridge.c:1271:fuse_readlink_cbk] 0-glusterfs-fuse: 2783487: /testvol/somedir/bin/x86_64 => -1 (Transport endpoint is not connected) > >Upon successful readlink (ls -l /testvol/somedir/bin/x86_64): > >[2010-05-09 01:13:37.717904] T [fuse-bridge.c:376:fuse_entry_cbk] 0-glusterfs-fuse: 2790073: LOOKUP() /testvol/somedir/bin => -5626802993936595428 >[2010-05-09 01:13:37.718070] T [fuse-resolve.c:51:fuse_resolve_loc_touchup] 0-fuse: return value inode_path 52 >[2010-05-09 01:13:37.718127] T [fuse-bridge.c:506:fuse_lookup_resume] 0-glusterfs-fuse: 2790074: LOOKUP /testvol/somedir/bin/x86_64(025d1c57-865f-4f1f-bc95-96ddcef3dc03) >[2010-05-09 01:13:37.718306] D [afr-common.c:131:afr_lookup_xattr_req_prepare] 0-_testvol-replicate-0: /testvol/somedir/bin/x86_64: failed to get the gfid from dict >[2010-05-09 01:13:37.718355] T [rpc-clnt.c:1301:rpc_clnt_record] 0-_testvol-client-1: Auth Info: pid: 3343, uid: 0, gid: 0, owner: 0000000000000000 >[2010-05-09 01:13:37.718383] T [rpc-clnt.c:1181:rpc_clnt_record_build_header] 0-rpc-clnt: Request fraglen 464, payload: 368, rpc hdr: 96 >[2010-05-09 01:13:37.718459] T [rpc-clnt.c:1498:rpc_clnt_submit] 0-rpc-clnt: submitted request (XID: 0x1527955x Program: GlusterFS 3.3, ProgVers: 330, Proc: 27) to rpc-transport (_testvol-client-1) >[2010-05-09 01:13:37.718775] T [rpc-clnt.c:669:rpc_clnt_reply_init] 0-_testvol-client-1: received rpc message (RPC XID: 0x1527955x Program: GlusterFS 3.3, ProgVers: 330, Proc: 27) from rpc-transport (_testvol-client-1) >[2010-05-09 01:13:37.718848] D [afr-self-heal-common.c:138:afr_sh_print_pending_matrix] 0-_testvol-replicate-0: pending_matrix: [ 0 0 ] >[2010-05-09 01:13:37.718884] D [afr-self-heal-common.c:138:afr_sh_print_pending_matrix] 0-_testvol-replicate-0: pending_matrix: [ 1 0 ] >[2010-05-09 01:13:37.718893] D [afr-self-heal-common.c:887:afr_mark_sources] 0-_testvol-replicate-0: Number of sources: 1 >[2010-05-09 01:13:37.718903] D [afr-self-heal-data.c:814:afr_lookup_select_read_child_by_txn_type] 0-_testvol-replicate-0: returning read_child: 1 >[2010-05-09 01:13:37.718916] D [afr-common.c:1397:afr_lookup_select_read_child] 0-_testvol-replicate-0: Source selected as 1 for /testvol/somedir/bin/x86_64 >[2010-05-09 01:13:37.718927] D [afr-common.c:1134:afr_lookup_build_response_params] 0-_testvol-replicate-0: Building lookup response from 1 >[2010-05-09 01:13:37.718954] D [afr-common.c:1749:afr_lookup_perform_self_heal] 0-_testvol-replicate-0: Only 1 child up - do not attempt to detect self heal >[2010-05-09 01:13:37.718970] T [io-cache.c:224:ioc_lookup_cbk] 0-_testvol-io-cache: locked inode(0x7f9a057d3fe0) >[2010-05-09 01:13:37.718981] T [io-cache.c:233:ioc_lookup_cbk] 0-_testvol-io-cache: unlocked inode(0x7f9a057d3fe0) >[2010-05-09 01:13:37.718991] T [io-cache.c:128:ioc_inode_flush] 0-_testvol-io-cache: locked inode(0x7f9a057d3fe0) >[2010-05-09 01:13:37.719001] T [io-cache.c:132:ioc_inode_flush] 0-_testvol-io-cache: unlocked inode(0x7f9a057d3fe0) >[2010-05-09 01:13:37.719010] T [io-cache.c:242:ioc_lookup_cbk] 0-_testvol-io-cache: locked table(0x668ec0) >[2010-05-09 01:13:37.719020] T [io-cache.c:247:ioc_lookup_cbk] 0-_testvol-io-cache: unlocked table(0x668ec0) >[2010-05-09 01:13:37.719050] T [fuse-bridge.c:376:fuse_entry_cbk] 0-glusterfs-fuse: 2790074: LOOKUP() /testvol/somedir/bin/x86_64 => -4857810743645185021 >[2010-05-09 01:13:37.719239] T [fuse-resolve.c:51:fuse_resolve_loc_touchup] 0-fuse: return value inode_path 52 >[2010-05-09 01:13:37.719291] T [fuse-bridge.c:1296:fuse_readlink_resume] 0-glusterfs-fuse: 2790075 READLINK /testvol/somedir/bin/x86_64/025d1c57-865f-4f1f-bc95-96ddcef3dc03 >[2010-05-09 01:13:37.719426] D [afr-common.c:760:afr_get_call_child] 0-_testvol-replicate-0: Returning 0, call_child: 1, last_index: -1 >[2010-05-09 01:13:37.719468] T [rpc-clnt.c:1301:rpc_clnt_record] 0-_testvol-client-1: Auth Info: pid: 3343, uid: 0, gid: 0, owner: 0000000000000000 >[2010-05-09 01:13:37.719485] T [rpc-clnt.c:1181:rpc_clnt_record_build_header] 0-rpc-clnt: Request fraglen 120, payload: 24, rpc hdr: 96 >[2010-05-09 01:13:37.719561] T [rpc-clnt.c:1498:rpc_clnt_submit] 0-rpc-clnt: submitted request (XID: 0x1527956x Program: GlusterFS 3.3, ProgVers: 330, Proc: 2) to rpc-transport (_testvol-client-1) >[2010-05-09 01:13:37.719728] T [rpc-clnt.c:669:rpc_clnt_reply_init] 0-_testvol-client-1: received rpc message (RPC XID: 0x1527956x Program: GlusterFS 3.3, ProgVers: 330, Proc: 2) from rpc-transport (_testvol-client-1) >[2010-05-09 01:13:37.719780] T [fuse-bridge.c:1265:fuse_readlink_cbk] 0-glusterfs-fuse: 2790075: /testvol/somedir/bin/x86_64 => setarch > > > >I cannot quite figure out how the whole thing works, but looks like in the failure case we end up with the wrong set of read_child(ren). If we first take a look at the fuse_lookup_cbk, which I reproduce here, > > >static int >fuse_lookup_cbk (call_frame_t *frame, void *cookie, xlator_t *this, >???????????????? int32_t op_ret, int32_t op_errno, >???????????????? inode_t *inode, struct iatt *stat, dict_t *dict, >???????????????? struct iatt *postparent) >{ >??????? fuse_state_t??????????? *state = NULL; >??????? call_frame_t??????????? *prev = NULL; >??????? inode_table_t?????????? *itable = NULL; > >??????? state = frame->root->state; >??????? prev? = cookie; > >??????? if (op_ret == -1 && state->is_revalidate == 1) { >??????????????? itable = state->itable; >??????????????? inode_unref (state->loc.inode); >??????????????? state->loc.inode = inode_new (itable); >??????????????? state->is_revalidate = 2; >??????????????? if (uuid_is_null (state->gfid)) >??????????????????????? uuid_generate (state->gfid); >??????????????? fuse_gfid_set (state); > >??????????????? STACK_WIND (frame, fuse_lookup_cbk, >??????????????????????????? prev->this, prev->this->fops->lookup, >??????????????????????????? &state->loc, state->xdata); >??????????????? return 0; >??????? } > >??????? fuse_entry_cbk (frame, cookie, this, op_ret, op_errno, inode, stat, >??????????????????????? dict); >??????? return 0; >} > > >then one can see that a resolve failure causing op_ret to be -1 (note, from logs its is_revalidate == 1 for both cases) would cause the mount program to refresh the inode context. In fact, this is where the flow diverges between the success and the failure scenarios. I am inclined to think that at this point a soft-link on which readlink fails (on the mount on server1) has its read-child set as the afr-client on server2. Thus, in theory, a refresh of context would be necessary. > >Now, if we take a look at the actual failure log: > >[2010-05-09 01:13:28.141090] D [afr-common.c:760:afr_get_call_child] >0-_testvol-replicate-0: Returning -107, call_child: -1, last_index: -1 >[2010-05-09 > 01:13:28.141120] W [fuse-bridge.c:1271:fuse_readlink_cbk] >0-glusterfs-fuse: 2783487: /testvol/somedir/bin/x86_64 => -1 >(Transport endpoint is not connected) > >Here, if we see the below code snippet from afr_get_call_child(), then looks like there might be a problem (or maybe, I am just not reading it right)? > >??????? if (child_up[read_child]) { >??????????????? *call_child = read_child; >??????? } else { >??????????????? for (i = 0; i < priv->child_count; i++) { >??????????????????????? if (fresh_children[i] == -1) >??????????????????????????????? break; >??????????????????????? if (child_up[fresh_children[i]]) { >??????????????????????????????? *call_child = fresh_children[i]; >??????????????????????????????? ret = 0; >??????????????????????????????? break; >??????????????????????? } >??????????????? } > >??????????????? if (*call_child == -1) { >??????????????????????? ret = -ENOTCONN; >??????????????????????? goto out; >??????????????? } > >??????????????? *last_index = i; >??????? } >out: >??????? gf_log (this->name, GF_LOG_DEBUG, "Returning %d, call_child: %d, " >??????????????? "last_index: %d", ret, *call_child, *last_index); >??????? return ret; > > >I would suppose 'child_up [read_child]' should equal 0, in which case we would loop over all children. This is where I am confused. If we read a link on server1, and server1 allows me to read so manyother files correctly, then surely all subvolumes on server1 MUST be active? But then, we return -ENOTCONN only when it is discovered that not one of the subvolumes is active! > > >It would be great if somebody could confirm my ideas for me. Also, should I need to open a bug for this? > > >Thanks a lot for your answers! >Anirban > >P.s. And yes, umount/mount does resolve the problem as well.