[Bugs] [Bug 1430042] New: Transport endpoint not connected error seen on client when glusterd is restarted
bugzilla at redhat.com
bugzilla at redhat.com
Tue Mar 7 18:01:02 UTC 2017
https://bugzilla.redhat.com/show_bug.cgi?id=1430042
Bug ID: 1430042
Summary: Transport endpoint not connected error seen on client
when glusterd is restarted
Product: GlusterFS
Version: mainline
Component: rpc
Severity: high
Priority: medium
Assignee: bugs at gluster.org
Reporter: jdarcy at redhat.com
CC: amukherj at redhat.com, bugs at gluster.org,
jdarcy at redhat.com, kramdoss at redhat.com
Depends On: 1422781
+++ 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 at redhat.com)
--- 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 at 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 at redhat.com)
Referenced Bugs:
https://bugzilla.redhat.com/show_bug.cgi?id=1422781
[Bug 1422781] Transport endpoint not connected error seen on client when
glusterd is restarted
--
You are receiving this mail because:
You are on the CC list for the bug.
You are the assignee for the bug.
More information about the Bugs
mailing list