[Gluster-devel] Losing connection to bricks, Gluster processes restarting
Logan Barfield
lbarfield at tqhosting.com
Fri Jan 29 18:25:46 UTC 2016
We're running a fairly large 2-replica volume across two servers. The
volume is approximately 20TB of small 1K-4MB files. The volume is exported
via NFS, and mounted remotely by two clients.
For the past few weeks the Gluster brick processes have been randomly
restarting. Luckily they've been doing so at non-peak times, so we didn't
notice until our monitoring checks happened to pick up on zombied
'glusterfs' process.
>From the logs it looks like something is blocking communication to the
brick processes, and Gluster automatically restarts everything to
compensate. I've so far not been able to figure out the underlying cause.
I've included log snippets from 'glustershd.log' and
'etc-glusterfs-glusterd.vol.log' here. If anyone can provide some insight
into the issue it would be greatly appreciated. I'll also be happy to
provide any further details as needed.
[2016-01-29 05:03:47.039886] I [MSGID: 106144]
[glusterd-pmap.c:274:pmap_registry_remove] 0-pmap: removing brick
/export/data/brick02 on port 49155
[2016-01-29 05:03:47.075521] W [socket.c:588:__socket_rwv] 0-management:
readv on /var/run/gluster/53a233b05f5d4be45dc94391bc3ebfe5.socket failed
(No data available)
[2016-01-29 05:03:47.078282] I [MSGID: 106005]
[glusterd-handler.c:4908:__glusterd_brick_rpc_notify] 0-management: Brick
gluster-stor02:/export/data/brick02 has disconnected from glusterd.
[2016-01-29 05:03:47.149161] W [glusterfsd.c:1236:cleanup_and_exit]
(-->/lib64/libpthread.so.0() [0x3e47a079d1]
-->/usr/sbin/glusterd(glusterfs_sigwaiter+0xcd) [0x405e6d]
-->/usr/sbin/glusterd(cleanup_and_exit+0x65) [0x4059d5] ) 0-: recei
ved signum (15), shutting down
[2016-01-29 05:03:54.067012] I [MSGID: 100030] [glusterfsd.c:2318:main]
0-/usr/sbin/glusterd: Started running /usr/sbin/glusterd version 3.7.6
(args: /usr/sbin/glusterd --pid-file=/var/run/glusterd.pid)
[2016-01-29 05:03:54.071901] I [MSGID: 106478] [glusterd.c:1350:init]
0-management: Maximum allowed open file descriptors set to 65536
[2016-01-29 05:03:54.071935] I [MSGID: 106479] [glusterd.c:1399:init]
0-management: Using /var/lib/glusterd as working directory
[2016-01-29 05:03:54.075655] E [rpc-transport.c:292:rpc_transport_load]
0-rpc-transport: /usr/lib64/glusterfs/3.7.6/rpc-transport/rdma.so: cannot
open shared object file: No such file or directory
[2016-01-29 05:03:54.075672] W [rpc-transport.c:296:rpc_transport_load]
0-rpc-transport: volume 'rdma.management': transport-type 'rdma' is not
valid or not found on this machine
[2016-01-29 05:03:54.075680] W [rpcsvc.c:1597:rpcsvc_transport_create]
0-rpc-service: cannot create listener, initing the transport failed
[2016-01-29 05:03:54.075687] E [MSGID: 106243] [glusterd.c:1623:init]
0-management: creation of 1 listeners failed, continuing with succeeded
transport
[2016-01-29 05:03:55.869717] I [MSGID: 106513]
[glusterd-store.c:2047:glusterd_restore_op_version] 0-glusterd: retrieved
op-version: 30702
[2016-01-29 05:03:55.995747] I [MSGID: 106498]
[glusterd-handler.c:3579:glusterd_friend_add_from_peerinfo] 0-management:
connect returned 0
[2016-01-29 05:03:55.995866] I [rpc-clnt.c:984:rpc_clnt_connection_init]
0-management: setting frame-timeout to 600
[2016-01-29 05:03:56.000937] I [MSGID: 106544]
[glusterd.c:159:glusterd_uuid_init] 0-management: retrieved UUID:
9b103ea8-d248-44fc-8f80-3e87f7c4971c
Final graph:
+------------------------------------------------------------------------------+
1: volume management
2: type mgmt/glusterd
3: option rpc-auth.auth-glusterfs on
4: option rpc-auth.auth-unix on
5: option rpc-auth.auth-null on
6: option rpc-auth-allow-insecure on
7: option transport.socket.listen-backlog 128
8: option ping-timeout 30
9: option transport.socket.read-fail-log off
10: option transport.socket.keepalive-interval 2
11: option transport.socket.keepalive-time 10
12: option transport-type rdma
13: option working-directory /var/lib/glusterd
14: end-volume
15:
+------------------------------------------------------------------------------+
[2016-01-29 05:03:56.002570] I [MSGID: 101190]
[event-epoll.c:632:event_dispatch_epoll_worker] 0-epoll: Started thread
with index 2
[2016-01-29 05:03:56.003098] I [MSGID: 101190]
[event-epoll.c:632:event_dispatch_epoll_worker] 0-epoll: Started thread
with index 1
[2016-01-29 05:03:56.003158] I [MSGID: 101190]
[event-epoll.c:632:event_dispatch_epoll_worker] 0-epoll: Started thread
with index 2
[2016-01-29 05:03:56.855628] I [MSGID: 106493]
[glusterd-rpc-ops.c:480:__glusterd_friend_add_cbk] 0-glusterd: Received ACC
from uuid: 388a8bb4-c530-44ff-838b-8f7b9e4c95db, host: 10.1.1.10, port: 0
[2016-01-29 05:03:56.856787] I [rpc-clnt.c:984:rpc_clnt_connection_init]
0-nfs: setting frame-timeout to 600
[2016-01-29 05:03:57.859093] I [MSGID: 106540]
[glusterd-utils.c:4191:glusterd_nfs_pmap_deregister] 0-glusterd:
De-registered MOUNTV3 successfully
[2016-01-29 05:03:57.860228] I [MSGID: 106540]
[glusterd-utils.c:4200:glusterd_nfs_pmap_deregister] 0-glusterd:
De-registered MOUNTV1 successfully
[2016-01-29 05:03:57.861329] I [MSGID: 106540]
[glusterd-utils.c:4209:glusterd_nfs_pmap_deregister] 0-glusterd:
De-registered NFSV3 successfully
[2016-01-29 05:03:57.862421] I [MSGID: 106540]
[glusterd-utils.c:4218:glusterd_nfs_pmap_deregister] 0-glusterd:
De-registered NLM v4 successfully
[2016-01-29 05:03:57.863510] I [MSGID: 106540]
[glusterd-utils.c:4227:glusterd_nfs_pmap_deregister] 0-glusterd:
De-registered NLM v1 successfully
[2016-01-29 05:03:57.864600] I [MSGID: 106540]
[glusterd-utils.c:4236:glusterd_nfs_pmap_deregister] 0-glusterd:
De-registered ACL v3 successfully
[2016-01-29 05:03:57.870948] W [socket.c:3009:socket_connect] 0-nfs: Ignore
failed connection attempt on , (No such file or directory)
[2016-01-29 05:03:47.075614] W [socket.c:588:__socket_rwv]
0-data02-client-1: readv on 10.1.1.10:49155 failed (No data available)
[2016-01-29 05:03:47.076871] I [MSGID: 114018]
[client.c:2042:client_rpc_notify] 0-data02-client-1: disconnected from
data02-client-1. Client process will keep trying to connect to glusterd
until brick's port is available
[2016-01-29 05:03:47.170284] W [socket.c:588:__socket_rwv] 0-glusterfs:
readv on 127.0.0.1:24007 failed (No data available)
[2016-01-29 05:03:47.639163] W [socket.c:588:__socket_rwv]
0-data02-client-0: readv on 10.1.1.11:49153 failed (No data available)
[2016-01-29 05:03:47.639206] I [MSGID: 114018]
[client.c:2042:client_rpc_notify] 0-data02-client-0: disconnected from
data02-client-0. Client process will keep trying to connect to glusterd
until brick's port is available
[2016-01-29 05:03:47.640222] E [MSGID: 108006]
[afr-common.c:3880:afr_notify] 0-data02-replicate-0: All subvolumes are
down. Going offline until atleast one of them comes back up.
[2016-01-29 05:03:57.872983] W [glusterfsd.c:1236:cleanup_and_exit]
(-->/lib64/libpthread.so.0() [0x3e47a079d1]
-->/usr/sbin/glusterfs(glusterfs_sigwaiter+0xcd) [0x405e6d]
-->/usr/sbin/glusterfs(cleanup_and_exit+0x65) [0x4059d5] ) 0-: rec
eived signum (15), shutting down
[2016-01-29 05:03:58.881541] I [MSGID: 100030] [glusterfsd.c:2318:main]
0-/usr/sbin/glusterfs: Started running /usr/sbin/glusterfs version 3.7.6
(args: /usr/sbin/glusterfs -s localhost --volfile-id gluster/glustershd -p
/var/lib/glusterd/
glustershd/run/glustershd.pid -l /var/log/glusterfs/glustershd.log -S
/var/run/gluster/8d72de580ccac07d2ecfc2491a9b1648.socket --xlator-option
*replicate*.node-uuid=9b103ea8-d248-44fc-8f80-3e87f7c4971c)
[2016-01-29 05:03:58.890833] I [MSGID: 101190]
[event-epoll.c:632:event_dispatch_epoll_worker] 0-epoll: Started thread
with index 1
[2016-01-29 05:03:59.340030] I [graph.c:269:gf_add_cmdline_options]
0-data02-replicate-0: adding option 'node-uuid' for volume
'data02-replicate-0' with value '9b103ea8-d248-44fc-8f80-3e87f7c4971c'
[2016-01-29 05:03:59.342682] I [MSGID: 101190]
[event-epoll.c:632:event_dispatch_epoll_worker] 0-epoll: Started thread
with index 2
[2016-01-29 05:03:59.342742] I [MSGID: 101190]
[event-epoll.c:632:event_dispatch_epoll_worker] 0-epoll: Started thread
with index 3
[2016-01-29 05:03:59.342827] I [MSGID: 101190]
[event-epoll.c:632:event_dispatch_epoll_worker] 0-epoll: Started thread
with index 4
[2016-01-29 05:03:59.342892] I [MSGID: 101190]
[event-epoll.c:632:event_dispatch_epoll_worker] 0-epoll: Started thread
with index 5
[2016-01-29 05:03:59.342917] I [MSGID: 101190]
[event-epoll.c:632:event_dispatch_epoll_worker] 0-epoll: Started thread
with index 6
[2016-01-29 05:03:59.343563] I [MSGID: 101190]
[event-epoll.c:632:event_dispatch_epoll_worker] 0-epoll: Started thread
with index 8
[2016-01-29 05:03:59.343569] I [MSGID: 101190]
[event-epoll.c:632:event_dispatch_epoll_worker] 0-epoll: Started thread
with index 7
[2016-01-29 05:03:59.343657] I [MSGID: 101190]
[event-epoll.c:632:event_dispatch_epoll_worker] 0-epoll: Started thread
with index 9
[2016-01-29 05:03:59.343705] I [MSGID: 101190]
[event-epoll.c:632:event_dispatch_epoll_worker] 0-epoll: Started thread
with index 11
[2016-01-29 05:03:59.343710] I [MSGID: 101190]
[event-epoll.c:632:event_dispatch_epoll_worker] 0-epoll: Started thread
with index 10
[2016-01-29 05:03:59.344278] I [MSGID: 114020] [client.c:2118:notify]
0-data02-client-0: parent translators are ready, attempting connect on
transport
[2016-01-29 05:03:59.346553] I [MSGID: 114020] [client.c:2118:notify]
0-data02-client-1: parent translators are ready, attempting connect on
transport
Final graph:
+------------------------------------------------------------------------------+
1: volume data02-client-0
2: type protocol/client
3: option ping-timeout 42
4: option remote-host gluster-stor01
5: option remote-subvolume /export/data/brick02
6: option transport-type socket
7: option username 5cc4f5d1-bcc8-4e06-ac74-520b20e2b452
8: option password 66b85782-5833-4f2d-ad0e-8de75247b094F
9: option event-threads 11
10: end-volume
11:
12: volume data02-client-1
13: type protocol/client
14: option ping-timeout 42
15: option remote-host gluster-stor02
16: option remote-subvolume /export/data/brick02
17: option transport-type socket
18: option username 5cc4f5d1-bcc8-4e06-ac74-520b20e2b452
19: option password 66b85782-5833-4f2d-ad0e-8de75247b094
20: option event-threads 11
21: end-volume
22:
23: volume data02-replicate-0
24: type cluster/replicate
25: option node-uuid 9b103ea8-d248-44fc-8f80-3e87f7c4971c
26: option background-self-heal-count 0
27: option metadata-self-heal on
28: option data-self-heal on
29: option entry-self-heal on
30: option self-heal-daemon enable
31: option iam-self-heal-daemon yes
32: subvolumes data02-client-0 data02-client-1
33: end-volume
34:
35: volume glustershd
36: type debug/io-stats
37: subvolumes data02-replicate-0
38: end-volume
39:
+------------------------------------------------------------------------------+
[2016-01-29 05:03:59.348913] E [MSGID: 114058]
[client-handshake.c:1524:client_query_portmap_cbk] 0-data02-client-1:
failed to get the port number for remote subvolume. Please run 'gluster
volume status' on server to see if brick process
is running.
[2016-01-29 05:03:59.348960] I [MSGID: 114018]
[client.c:2042:client_rpc_notify] 0-data02-client-1: disconnected from
data02-client-1. Client process will keep trying to connect to glusterd
until brick's port is available
[2016-01-29 05:03:59.436909] E [MSGID: 114058]
[client-handshake.c:1524:client_query_portmap_cbk] 0-data02-client-0:
failed to get the port number for remote subvolume. Please run 'gluster
volume status' on server to see if brick process
is running.
[2016-01-29 05:03:59.436974] I [MSGID: 114018]
[client.c:2042:client_rpc_notify] 0-data02-client-0: disconnected from
data02-client-0. Client process will keep trying to connect to glusterd
until brick's port is available
[2016-01-29 05:03:59.436991] E [MSGID: 108006]
[afr-common.c:3880:afr_notify] 0-data02-replicate-0: All subvolumes are
down. Going offline until atleast one of them comes back up.
[2016-01-29 05:04:02.886317] I [rpc-clnt.c:1847:rpc_clnt_reconfig]
0-data02-client-0: changing port to 49153 (from 0)
[2016-01-29 05:04:02.888761] I [rpc-clnt.c:1847:rpc_clnt_reconfig]
0-data02-client-1: changing port to 49155 (from 0)
[2016-01-29 05:04:02.891105] I [MSGID: 114057]
[client-handshake.c:1437:select_server_supported_programs]
0-data02-client-0: Using Program GlusterFS 3.3, Num (1298437), Version (330)
[2016-01-29 05:04:02.891360] I [MSGID: 114046]
[client-handshake.c:1213:client_setvolume_cbk] 0-data02-client-0: Connected
to data02-client-0, attached to remote volume '/export/data/brick02'.
[2016-01-29 05:04:02.891373] I [MSGID: 114047]
[client-handshake.c:1224:client_setvolume_cbk] 0-data02-client-0: Server
and Client lk-version numbers are not same, reopening the fds
[2016-01-29 05:04:02.891403] I [MSGID: 108005]
[afr-common.c:3841:afr_notify] 0-data02-replicate-0: Subvolume
'data02-client-0' came back up; going online.
[2016-01-29 05:04:02.891518] I [MSGID: 114035]
[client-handshake.c:193:client_set_lk_version_cbk] 0-data02-client-0:
Server lk version = 1
[2016-01-29 05:04:02.893074] I [MSGID: 114057]
[client-handshake.c:1437:select_server_supported_programs]
0-data02-client-1: Using Program GlusterFS 3.3, Num (1298437), Version (330)
[2016-01-29 05:04:02.893251] I [MSGID: 114046]
[client-handshake.c:1213:client_setvolume_cbk] 0-data02-client-1: Connected
to data02-client-1, attached to remote volume '/export/data/brick02'.
[2016-01-29 05:04:02.893276] I [MSGID: 114047]
[client-handshake.c:1224:client_setvolume_cbk] 0-data02-client-1: Server
and Client lk-version numbers are not same, reopening the fds
[2016-01-29 05:04:02.893401] I [MSGID: 114035]
[client-handshake.c:193:client_set_lk_version_cbk] 0-data02-client-1:
Server lk version = 1
-------------- next part --------------
An HTML attachment was scrubbed...
URL: <http://www.gluster.org/pipermail/gluster-devel/attachments/20160129/e9548c26/attachment-0001.html>
More information about the Gluster-devel
mailing list