+++ 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)
REVIEW: https://review.gluster.org/16866 (glusterfsd: don't quit (in client) on connection failure) posted (#2) for review on master by Jeff Darcy (jdarcy)
COMMIT: https://review.gluster.org/16866 committed in master by Jeff Darcy (jdarcy) ------ commit eb038c19e2c799e35e72eeb500dfb81efc5567e2 Author: Jeff Darcy <jdarcy> Date: Tue Mar 7 11:53:04 2017 -0500 glusterfsd: don't quit (in client) on connection failure Change-Id: I32be91e9db361a45454d6340a4c4ac2d0d7efffc BUG: 1430042 Signed-off-by: Jeff Darcy <jdarcy> Reviewed-on: https://review.gluster.org/16866 Smoke: Gluster Build System <jenkins.org> NetBSD-regression: NetBSD Build System <jenkins.org> CentOS-regression: Gluster Build System <jenkins.org> Reviewed-by: Prashanth Pai <ppai>
REVIEW: https://review.gluster.org/16665 (tests: add test for restarting glusterd with I/O ongoing) posted (#2) for review on master by Jeff Darcy (jdarcy)
This bug is getting closed because a release has been made available that should address the reported issue. In case the problem is still not fixed with glusterfs-3.11.0, please open a new bug report. glusterfs-3.11.0 has been announced on the Gluster mailinglists [1], packages for several distributions should become available in the near future. Keep an eye on the Gluster Users mailinglist [2] and the update infrastructure for your distribution. [1] http://lists.gluster.org/pipermail/announce/2017-May/000073.html [2] https://www.gluster.org/pipermail/gluster-users/