Bug 1430042

+++ This bug was initially created as a clone of Bug #1422781 +++
(Welcome to the most unnecessarily cumbersome bug-tracking process ever)

Description of problem:
when glusterd is restarted on the node from which volume is mounted on the client, IO fails on the mountpoint. 'Transport endpoint is not connected' error is seen.

Version-Release number of selected component (if applicable):
rpm -qa | grep 'gluster'
glusterfs-resource-agents-3.10.0rc-0.0.el7.centos.noarch
glusterfs-events-3.10.0rc-0.0.el7.centos.x86_64
glusterfs-debuginfo-3.10.0rc-0.0.el7.centos.x86_64
glusterfs-3.10.0rc-0.0.el7.centos.x86_64
glusterfs-api-3.10.0rc-0.0.el7.centos.x86_64
python2-gluster-3.10.0rc-0.0.el7.centos.x86_64
glusterfs-fuse-3.10.0rc-0.0.el7.centos.x86_64
glusterfs-server-3.10.0rc-0.0.el7.centos.x86_64
glusterfs-devel-3.10.0rc-0.0.el7.centos.x86_64
glusterfs-api-devel-3.10.0rc-0.0.el7.centos.x86_64
glusterfs-geo-replication-3.10.0rc-0.0.el7.centos.x86_64
glusterfs-libs-3.10.0rc-0.0.el7.centos.x86_64
glusterfs-client-xlators-3.10.0rc-0.0.el7.centos.x86_64
glusterfs-extra-xlators-3.10.0rc-0.0.el7.centos.x86_64
glusterfs-cli-3.10.0rc-0.0.el7.centos.x86_64

How reproducible:
always

Steps to Reproduce:
1. on a 3 node gluster cluster, set cluster.brick-multiplex on
2. create a 2x3 volume
3. mount the volume and run IO
4. restart glusterd on the node from which volume is mounted
5. check if IO continues from the client

Actual results:
Transport endpoint not connected error is seen and IO halts

Expected results:
IO should continue and glusterd restart should not affect client IOs

Additional info:
No logs shall be attached as this is easily reproducible, let me know if sosreports are needed

--- Additional comment from Atin Mukherjee on 2017-02-16 05:25:03 EST ---

This is reproducible locally as well. client log indicates that client process is shutdown. Something is wrong in the reconnect logic.

[2017-02-16 10:21:29.026311] E [timer.c:44:gf_timer_call_after] (-->/usr/local/lib/libgfrpc.so.0(rpc_transport_notify+0x23) [0x7fe5ffce4223] -->/usr/local/lib/libgfrpc.so.0(rpc_clnt_notify+0x2b0) [0x7fe5ffce7ca0] -->/usr/local/lib/     libglusterfs.so.0(gf_timer_call_after+0x2a9) [0x7fe5fff293c9] ) 0-timer: !reg
[2017-02-16 10:21:29.026317] W [rpc-clnt.c:893:rpc_clnt_handle_disconnect] 0-test-vol-client-0: Cannot create         rpc_clnt_reconnect timer
[2017-02-16 10:21:29.026322] I [MSGID: 114018] [client.c:2276:client_rpc_notify] 0-test-vol-client-0: disconnected    from test-vol-client-0. Client process will keep trying to connect to glusterd until brick's port is available        [2017-02-16 10:21:29.030938] W [glusterfsd.c:1329:cleanup_and_exit] (-->/lib64/libpthread.so.0(+0x75ba)               [0x7fe5fed775ba] -->/usr/local/sbin/glusterfs(glusterfs_sigwaiter+0xc5) [0x408615] -->/usr/local/sbin/                glusterfs(cleanup_and_exit+0x4b) [0x4084ab] ) 0-: received signum (15), shutting down

--- Additional comment from Jeff Darcy on 2017-02-16 15:35:28 EST ---

Setting priority as medium because GlusterD restarting while bricks continue to run is not a common case either as an administrative action or as a failure event.

--- Additional comment from Worker Ant on 2017-02-17 11:44:07 EST ---

REVIEW: https://review.gluster.org/16665 (tests: add test for restarting glusterd with I/O ongoing) posted (#1) for review on master by Jeff Darcy (jdarcy)

--- Additional comment from Jeff Darcy on 2017-02-17 11:45:21 EST ---

Test is here:

https://review.gluster.org/#/c/16665/

Still no errors.  What's missing?

--- Additional comment from Atin Mukherjee on 2017-02-17 12:00:57 EST ---

Jeff,

I was able to reproduce it with a 2x3 volume on a 3 node cluster.

--- Additional comment from Jeff Darcy on 2017-02-17 12:46:48 EST ---

Great.  I'll try to rearrange the test script to use the cluster.rc stuff, and see if that's sufficient.

--- Additional comment from Jeff Darcy on 2017-02-17 13:56:17 EST ---

Still no luck.  How much I/O are you doing?  If it's some sort of a race that has to be hit in the middle of a fop, maybe the script just isn't doing enough.  If that's not it, we might need to start looking at differences in how things are being built, because we're running out of other possibilities.  Having to test on a physical three-node cluster is going to slow things down a lot, especially if it has to be manual, and it doesn't allow for verification through our regression-test infrastructure.

--- Additional comment from Jeff Darcy on 2017-02-17 14:02:15 EST ---

Also, when you talk about three nodes are you talking physical machines, virtual machines, or containers?  Could there be an environment-specific aspect to this?

--- Additional comment from krishnaram Karthick on 2017-03-01 10:42:03 EST ---

(In reply to Jeff Darcy from comment #8)
> Also, when you talk about three nodes are you talking physical machines,
> virtual machines, or containers?  Could there be an environment-specific
> aspect to this?

Sorry, I wanted to try this out with the latest build before replying to the questions. I'm still seeing this issue quite consistently with the latest build too. I'm using gluster containers for my testing. I'll attach the logs shortly.

--- Additional comment from krishnaram Karthick on 2017-03-01 23:03:17 EST ---

snippet of client log:

2017-03-02 04:00:17.481864] D [write-behind.c:380:__wb_request_unref] (--> /lib64/libglusterfs.so.0(_gf_log_callingfn+0x13b)[0x7fac5d51fddb] (--> /usr/lib64/glusterfs/3.10.0rc0/xlator/performance/write-behind.s
o(+0x2582)[0x7fac55a6d582] (--> /usr/lib64/glusterfs/3.10.0rc0/xlator/performance/write-behind.so(+0x6857)[0x7fac55a71857] (--> /usr/lib64/glusterfs/3.10.0rc0/xlator/performance/write-behind.so(+0x6b88)[0x7fac55
a71b88] (--> /usr/lib64/glusterfs/3.10.0rc0/xlator/performance/write-behind.so(+0x8b5f)[0x7fac55a73b5f] ))))) 0-vol1-write-behind: (unique = 681, fop=WRITE, gfid=d0eb059e-f1e9-497f-b325-08e21de9ceb7, gen=7): des
troying request, removing from all queues
[2017-03-02 04:00:17.482039] D [write-behind.c:1695:wb_process_queue] (--> /lib64/libglusterfs.so.0(_gf_log_callingfn+0x13b)[0x7fac5d51fddb] (--> /usr/lib64/glusterfs/3.10.0rc0/xlator/performance/write-behind.so
(+0x8acb)[0x7fac55a73acb] (--> /usr/lib64/glusterfs/3.10.0rc0/xlator/performance/write-behind.so(+0x8b67)[0x7fac55a73b67] (--> /usr/lib64/glusterfs/3.10.0rc0/xlator/cluster/distribute.so(+0x5b32a)[0x7fac55cda32a
] (--> /usr/lib64/glusterfs/3.10.0rc0/xlator/cluster/replicate.so(+0x220e2)[0x7fac55f2b0e2] ))))) 0-vol1-write-behind: processing queues
[2017-03-02 04:00:17.488751] D [socket.c:562:__socket_rwv] 0-glusterfs: EOF on socket
[2017-03-02 04:00:17.488771] W [socket.c:593:__socket_rwv] 0-glusterfs: readv on 10.70.46.80:24007 failed (No data available)
[2017-03-02 04:00:17.488782] D [socket.c:2404:socket_event_handler] 0-transport: disconnecting now
[2017-03-02 04:00:17.488920] D [rpc-clnt-ping.c:93:rpc_clnt_remove_ping_timer_locked] (--> /lib64/libglusterfs.so.0(_gf_log_callingfn+0x13b)[0x7fac5d51fddb] (--> /lib64/libgfrpc.so.0(rpc_clnt_remove_ping_timer_l
ocked+0x8e)[0x7fac5d2ebcce] (--> /lib64/libgfrpc.so.0(rpc_clnt_connection_cleanup+0x5b)[0x7fac5d2e80fb] (--> /lib64/libgfrpc.so.0(rpc_clnt_notify+0x8c)[0x7fac5d2e89ac] (--> /lib64/libgfrpc.so.0(rpc_transport_not
ify+0x23)[0x7fac5d2e49e3] ))))) 0-: 10.70.46.80:24007: ping timer event already removed
[2017-03-02 04:00:17.488943] E [glusterfsd-mgmt.c:2102:mgmt_rpc_notify] 0-glusterfsd-mgmt: failed to connect with remote-host: 10.70.46.80 (No data available)
[2017-03-02 04:00:17.488950] I [glusterfsd-mgmt.c:2120:mgmt_rpc_notify] 0-glusterfsd-mgmt: Exhausted all volfile servers
[2017-03-02 04:00:17.488955] D [logging.c:1764:gf_log_flush_extra_msgs] 0-logging-infra: Log buffer size reduced. About to flush 5 extra log messages
[2017-03-02 04:00:17.488964] D [logging.c:1767:gf_log_flush_extra_msgs] 0-logging-infra: Just flushed 5 extra log messages
[2017-03-02 04:00:17.488993] W [glusterfsd.c:1329:cleanup_and_exit] (-->/lib64/libgfrpc.so.0(rpc_clnt_notify+0xd3) [0x7fac5d2e89f3] -->/usr/sbin/glusterfs(+0x10a9f) [0x7fac5da1ea9f] -->/usr/sbin/glusterfs(cleanu
p_and_exit+0x6b) [0x7fac5da17dfb] ) 0-: received signum (1), shutting down
[2017-03-02 04:00:17.489002] D [glusterfsd-mgmt.c:2577:glusterfs_mgmt_pmap_signout] 0-fsd-mgmt: portmapper signout arguments not given
[2017-03-02 04:00:17.489009] I [fuse-bridge.c:5802:fini] 0-fuse: Unmounting '/mnt/krk1'.

--- Additional comment from Atin Mukherjee on 2017-03-06 08:55:59 EST ---

Jeff,

I was able to hit this issue again. Here is how the volume status looks like:

root@15e82395bcbc:/home/glusterfs# gluster v status
Status of volume: test-vol
Gluster process                             TCP Port  RDMA Port  Online  Pid
------------------------------------------------------------------------------
Brick 172.17.0.2:/tmp/b1                    49152     0          Y       25014
Brick 172.17.0.3:/tmp/b1                    49154     0          Y       1727 
Brick 172.17.0.4:/tmp/b1                    49154     0          Y       20966
Brick 172.17.0.2:/tmp/b2                    49152     0          Y       25014
Brick 172.17.0.3:/tmp/b2                    49154     0          Y       1727 
Brick 172.17.0.4:/tmp/b2                    49154     0          Y       20966
Self-heal Daemon on localhost               N/A       N/A        N       N/A  
Self-heal Daemon on 172.17.0.3              N/A       N/A        Y       1759 
Self-heal Daemon on 172.17.0.4              N/A       N/A        Y       20998
 
Task Status of Volume test-vol
------------------------------------------------------------------------------
There are no active volume tasks


When I mount the client in 172.17.0.2 and ran touch f{1..100000} and kill glusterd on the same node mount started throwing "Transport endpoint is not connected" errors for all the files.

Mount log shows the following:

[2017-03-06 13:49:36.437709] I [fuse-bridge.c:5802:fini] 0-fuse: Unmounting '/mnt/test-vol-mnt'.
[2017-03-06 13:49:36.442986] W [socket.c:593:__socket_rwv] 0-test-vol-client-3: readv on 172.17.0.2:49154 failed     (Connection reset by peer)
[2017-03-06 13:49:36.443247] E [rpc-clnt.c:365:saved_frames_unwind] (--> /usr/local/lib/libglusterfs.so.             0(_gf_log_callingfn+0x12a)[0x7faa629c4a0a] (--> /usr/local/lib/libgfrpc.so.0(saved_frames_unwind+                    0x1b5)[0x7faa6278bd05] (--> /usr/local/lib/libgfrpc.so.0(saved_frames_destroy+0xe)[0x7faa6278bdfe] (--> /usr/local/  lib/libgfrpc.so.0(rpc_clnt_connection_cleanup+0x89)[0x7faa6278d379] (--> /usr/local/lib/libgfrpc.so.                 0(rpc_clnt_notify+0x84)[0x7faa6278dc04] ))))) 0-test-vol-client-3: forced unwinding frame type(GlusterFS 3.3)        op(CREATE(23)) called at 2017-03-06 13:49:36.440699 (xid=0x268a)
[2017-03-06 13:49:36.443264] W [MSGID: 114031] [client-rpc-fops.c:2332:client3_3_create_cbk] 0-test-vol-client-3:    remote operation failed. Path: /f1244 [Transport endpoint is not connected]
[2017-03-06 13:49:36.446152] I [socket.c:3476:socket_submit_request] 0-test-vol-client-3: not connected (priv-       >connected = 0)
[2017-03-06 13:49:36.446170] W [rpc-clnt.c:1656:rpc_clnt_submit] 0-test-vol-client-3: failed to submit rpc-request   (XID: 0x268b Program: GlusterFS 3.3, ProgVers: 330, Proc: 33) to rpc-transport (test-vol-client-3)
[2017-03-06 13:49:36.446183] E [MSGID: 114031] [client-rpc-fops.c:1758:client3_3_xattrop_cbk] 0-test-vol-client-3:   remote operation failed. Path: / (00000000-0000-0000-0000-000000000001)
[2017-03-06 13:49:36.446249] I [timer.c:198:gf_timer_registry_init] (-->/usr/local/lib/libgfrpc.so.                  0(rpc_transport_notify+0x23) [0x7faa6278a3b3] -->/usr/local/lib/libgfrpc.so.0(rpc_clnt_notify+0x2b0)                 [0x7faa6278de30] -->/usr/local/lib/libglusterfs.so.0(gf_timer_call_after+0x265) [0x7faa629cf3b5] ) 0-timer: ctx      cleanup started
[2017-03-06 13:49:36.446283] E [timer.c:44:gf_timer_call_after] (-->/usr/local/lib/libgfrpc.so.                      0(rpc_transport_notify+0x23) [0x7faa6278a3b3] -->/usr/local/lib/libgfrpc.so.0(rpc_clnt_notify+0x2b0)                 [0x7faa6278de30] -->/usr/local/lib/libglusterfs.so.0(gf_timer_call_after+0x2a9) [0x7faa629cf3f9] ) 0-timer: !reg
[2017-03-06 13:49:36.446289] W [rpc-clnt.c:893:rpc_clnt_handle_disconnect] 0-test-vol-client-3: Cannot create        rpc_clnt_reconnect timer
[2017-03-06 13:49:36.446296] I [MSGID: 114018] [client.c:2276:client_rpc_notify] 0-test-vol-client-3: disconnected   from test-vol-client-3. Client process will keep trying to connect to glusterd until brick's port is available
[2017-03-06 13:49:36.446575] E [MSGID: 114031] [client-rpc-fops.c:1646:client3_3_entrylk_cbk] 0-test-vol-client-3:   remote operation failed [Transport endpoint is not connected]
[2017-03-06 13:49:36.446593] E [MSGID: 108007] [afr-lk-common.c:825:afr_unlock_entrylk_cbk] 0-test-vol-replicate-1: /f1244: unlock failed on test-vol-client-3 [Transport endpoint is not connected]
[2017-03-06 13:49:36.457023] W [glusterfsd.c:1329:cleanup_and_exit] (-->/lib64/libpthread.so.0(+0x75ba)              [0x7faa6181d5ba] -->/usr/local/sbin/glusterfs(glusterfs_sigwaiter+0xc5) [0x408615] -->/usr/local/sbin/               glusterfs(cleanup_and_exit+0x4b) [0x4084ab] ) 0-: received signum (15), shutting down
[2017-03-06 13:49:36.457023] W [glusterfsd.c:1329:cleanup_and_exit] (-->/lib64/libpthread.so.0(+0x75ba)              [0x7faa6181d5ba] -->/usr/local/sbin/glusterfs(glusterfs_sigwaiter+0xc5) [0x408615] -->/usr/local/sbin/               glusterfs(cleanup_and_exit+0x4b) [0x4084ab] ) 0-: received signum (15), shutting down

--- Additional comment from Jeff Darcy on 2017-03-07 12:36:07 EST ---

The key is probably "Exhausted all volfile servers" from comment 10.  This code is reused on clients, bricks, and (I think) auxiliary daemons - i.e. everywhere but glusterd and pure gfapi clients.  Perhaps that's a bad idea, because those things do have different needs.  In this case, while it's semi-appropriate to have a brick daemon give up at this point, it's just as clearly the wrong thing to do for clients.  I've reverted the change to this behavior, which was made as part of the multiplexing patch.  This should fix the immediate problem, though it's hard to verify whether there might still be others because I still haven't been able to reproduce the problem on a normal configuration.  Also, there's a pretty high chance that the revert will re-introduce whatever problem the change was originally made to fix.  I doubt that it was changed for no reason, but I don't recall which specific test was failing before.  I guess we'll find out.  ;)

--- Additional comment from Worker Ant on 2017-03-07 12:37:09 EST ---

REVIEW: https://review.gluster.org/16866 (glusterfsd: don't quit (in client) on connection failure) posted (#1) for review on master by Jeff Darcy (jdarcy)