[Bugs] [Bug 1793376] 2 VOlume is UP out of 3 . But still we could not mount the volume
bugzilla at redhat.com
bugzilla at redhat.com
Tue Jan 21 11:56:26 UTC 2020
https://bugzilla.redhat.com/show_bug.cgi?id=1793376
--- Comment #3 from Kannan <kannanv06 at gmail.com> ---
(In reply to Mohit Agrawal from comment #1)
> Please share mount logs also to debug it more.
Hi,
Following is the mount log with DEBUG mode
```
[2020-01-21 11:39:09.220147] I [MSGID: 100030] [glusterfsd.c:2836:main]
0-/usr/sbin/glusterfs: Started running /usr/sbin/glusterfs version 6.0 (args:
/usr/sbin/glusterfs --log-level=DEBUG --log-file=/var/log/glusterfs/mount.log
--fuse-mountopts=auto_unmount --process-name fuse --volfile-server=10.8.30.246
--volfile-server=10.8.30.244 --volfile-server=10.8.30.245
--volfile-server=10.8.30.246 --volfile-id=vol_845cf26d86cc37b9c1d492c762a9a02b
--fuse-mountopts=auto_unmount /mnt/)
[2020-01-21 11:39:09.222062] D [MSGID: 0]
[glusterfsd.c:484:set_fuse_mount_options] 0-glusterfsd: fopen-keep-cache mode 2
[2020-01-21 11:39:09.222079] D [MSGID: 0]
[glusterfsd.c:557:set_fuse_mount_options] 0-glusterfsd: fuse direct io type 2
[2020-01-21 11:39:09.222087] D [MSGID: 0]
[glusterfsd.c:581:set_fuse_mount_options] 0-glusterfsd: fuse no-root-squash
mode 0
[2020-01-21 11:39:09.222099] D [MSGID: 0]
[glusterfsd.c:662:set_fuse_mount_options] 0-glusterfsd: kernel-writeback-cache
mode 2
[2020-01-21 11:39:09.222105] D [MSGID: 0]
[glusterfsd.c:697:set_fuse_mount_options] 0-glusterfsd:
fuse-flush-handle-interrupt mode 2
[2020-01-21 11:39:09.222427] D [dict.c:2380:dict_get_str]
(-->/usr/lib64/glusterfs/6.0/xlator/mount/fuse.so(+0xa62e) [0x7f4ef02c562e]
-->/lib64/libglusterfs.so.0(xlator_option_init_bool+0x60) [0x7f4ef8f71500]
-->/lib64/libglusterfs.so.0(dict_get_str+0x11a) [0x7f4ef8f0db1a] ) 0-dict: key
auto-invalidation, string type asked, has unsigned integer type [Invalid
argument]
[2020-01-21 11:39:09.222856] D [MSGID: 0]
[options.c:1228:xlator_option_init_bool] 0-fuse: option auto-invalidation using
set value 0
[2020-01-21 11:39:09.222928] D [dict.c:2380:dict_get_str]
(-->/usr/lib64/glusterfs/6.0/xlator/mount/fuse.so(+0xa68c) [0x7f4ef02c568c]
-->/lib64/libglusterfs.so.0(xlator_option_init_double+0x60) [0x7f4ef8f71c70]
-->/lib64/libglusterfs.so.0(dict_get_str+0x11a) [0x7f4ef8f0db1a] ) 0-dict: key
negative-timeout, string type asked, has float type [Invalid argument]
[2020-01-21 11:39:09.222940] D [MSGID: 0]
[options.c:1231:xlator_option_init_double] 0-fuse: option negative-timeout
using set value 0.000000
[2020-01-21 11:39:09.223005] D [dict.c:2380:dict_get_str]
(-->/lib64/libglusterfs.so.0(xlator_init+0xc1) [0x7f4ef8f133e1]
-->/usr/lib64/glusterfs/6.0/xlator/mount/fuse.so(+0xa958) [0x7f4ef02c5958]
-->/lib64/libglusterfs.so.0(dict_get_str+0x11a) [0x7f4ef8f0db1a] ) 0-dict: key
sync-to-mount, string type asked, has pointer type [Invalid argument]
[2020-01-21 11:39:09.223058] D [dict.c:2380:dict_get_str]
(-->/usr/lib64/glusterfs/6.0/xlator/mount/fuse.so(+0xab62) [0x7f4ef02c5b62]
-->/lib64/libglusterfs.so.0(xlator_option_init_str+0x5e) [0x7f4ef8f6fdce]
-->/lib64/libglusterfs.so.0(dict_get_str+0x11a) [0x7f4ef8f0db1a] ) 0-dict: key
fuse-mountopts, string type asked, has pointer type [Invalid argument]
[2020-01-21 11:39:09.223068] D [MSGID: 0]
[options.c:1219:xlator_option_init_str] 0-fuse: option fuse-mountopts using set
value auto_unmount
[2020-01-21 11:39:09.223149] D [dict.c:2380:dict_get_str]
(-->/usr/lib64/glusterfs/6.0/xlator/mount/fuse.so(+0xac44) [0x7f4ef02c5c44]
-->/lib64/libglusterfs.so.0(xlator_option_init_bool+0x60) [0x7f4ef8f71500]
-->/lib64/libglusterfs.so.0(dict_get_str+0x11a) [0x7f4ef8f0db1a] ) 0-dict: key
no-root-squash, string type asked, has pointer type [Invalid argument]
[2020-01-21 11:39:09.223160] D [MSGID: 0]
[options.c:1228:xlator_option_init_bool] 0-fuse: option no-root-squash using
set value disable
[2020-01-21 11:39:09.224282] D [logging.c:1841:__gf_log_inject_timer_event]
0-logging-infra: Starting timer now. Timeout = 120, current buf size = 5
[2020-01-21 11:39:09.225080] D [rpc-clnt.c:1007:rpc_clnt_connection_init]
0-glusterfs: defaulting frame-timeout to 30mins
[2020-01-21 11:39:09.225098] D [rpc-clnt.c:1019:rpc_clnt_connection_init]
0-glusterfs: disable ping-timeout
[2020-01-21 11:39:09.225119] D [rpc-transport.c:293:rpc_transport_load]
0-rpc-transport: attempt to load file
/usr/lib64/glusterfs/6.0/rpc-transport/socket.so
[2020-01-21 11:39:09.236514] D [MSGID: 101002] [options.c:972:xl_opt_validate]
0-glusterfs: option 'address-family' is deprecated, preferred is
'transport.address-family', continuing with correction
[2020-01-21 11:39:09.238081] D [socket.c:4505:socket_init] 0-glusterfs:
Configued transport.tcp-user-timeout=42
[2020-01-21 11:39:09.238100] D [socket.c:4523:socket_init] 0-glusterfs:
Reconfigued transport.keepalivecnt=9
[2020-01-21 11:39:09.238112] D [socket.c:4209:ssl_setup_connection_params]
0-glusterfs: SSL support on the I/O path is NOT enabled
[2020-01-21 11:39:09.238119] D [socket.c:4212:ssl_setup_connection_params]
0-glusterfs: SSL support for glusterd is NOT enabled
[2020-01-21 11:39:09.238142] D [rpc-clnt.c:1584:rpcclnt_cbk_program_register]
0-glusterfs: New program registered: GlusterFS Callback, Num: 52743234, Ver: 1
[2020-01-21 11:39:09.238248] D [dict.c:1162:data_to_uint16]
(-->/usr/lib64/glusterfs/6.0/rpc-transport/socket.so(+0x6f72) [0x7f4eece86f72]
-->/usr/lib64/glusterfs/6.0/rpc-transport/socket.so(socket_client_get_remote_sockaddr+0xe1)
[0x7f4eece8e611] -->/lib64/libglusterfs.so.0(data_to_uint16+0x111)
[0x7f4ef8f0b371] ) 0-dict: key null, unsigned integer type asked, has integer
type [Invalid argument]
[2020-01-21 11:39:09.242485] D [MSGID: 0] [common-utils.c:535:gf_resolve_ip6]
0-resolver: returning ip-10.8.30.246 (port-24007) for hostname: 10.8.30.246 and
port: 24007
[2020-01-21 11:39:09.242515] D [socket.c:3254:socket_fix_ssl_opts] 0-glusterfs:
disabling SSL for portmapper connection
[2020-01-21 11:39:09.244149] I [MSGID: 101190]
[event-epoll.c:680:event_dispatch_epoll_worker] 0-epoll: Started thread with
index 0
[2020-01-21 11:39:09.245209] I [MSGID: 101190]
[event-epoll.c:680:event_dispatch_epoll_worker] 0-epoll: Started thread with
index 1
[2020-01-21 11:39:09.245435] D [rpc-clnt-ping.c:298:rpc_clnt_start_ping]
0-glusterfs: ping timeout is 0, returning
[2020-01-21 11:39:09.268699] D [MSGID: 0]
[quick-read.c:1187:check_cache_size_ok]
0-vol_845cf26d86cc37b9c1d492c762a9a02b-quick-read: Max cache size is
33548136448
[2020-01-21 11:39:09.269238] D [MSGID: 0] [io-cache.c:1687:check_cache_size_ok]
0-vol_845cf26d86cc37b9c1d492c762a9a02b-io-cache: Max cache size is 33548136448
[2020-01-21 11:39:09.269286] D [MSGID: 0]
[options.c:1225:xlator_option_init_size_uint64]
0-vol_845cf26d86cc37b9c1d492c762a9a02b-readdir-ahead: option rda-request-size
using set value 131072
[2020-01-21 11:39:09.269303] D [MSGID: 0]
[options.c:1225:xlator_option_init_size_uint64]
0-vol_845cf26d86cc37b9c1d492c762a9a02b-readdir-ahead: option rda-cache-limit
using set value 10MB
[2020-01-21 11:39:09.269313] D [MSGID: 0]
[options.c:1228:xlator_option_init_bool]
0-vol_845cf26d86cc37b9c1d492c762a9a02b-readdir-ahead: option parallel-readdir
using set value off
[2020-01-21 11:39:09.269412] D [MSGID: 0]
[options.c:1228:xlator_option_init_bool]
0-vol_845cf26d86cc37b9c1d492c762a9a02b-utime: option noatime using set value on
[2020-01-21 11:39:09.269481] D [MSGID: 0]
[options.c:1228:xlator_option_init_bool]
0-vol_845cf26d86cc37b9c1d492c762a9a02b-dht: option lock-migration using set
value off
[2020-01-21 11:39:09.269496] D [MSGID: 0]
[options.c:1228:xlator_option_init_bool]
0-vol_845cf26d86cc37b9c1d492c762a9a02b-dht: option force-migration using set
value off
[2020-01-21 11:39:09.269567] D [MSGID: 0] [dht-shared.c:355:dht_init_regex]
0-vol_845cf26d86cc37b9c1d492c762a9a02b-dht: using regex rsync-hash-regex =
^\.(.+)\.[^.]+$
[2020-01-21 11:39:09.269852] D [MSGID: 0]
[options.c:1219:xlator_option_init_str]
0-vol_845cf26d86cc37b9c1d492c762a9a02b-replicate-0: option afr-pending-xattr
using set value
vol_845cf26d86cc37b9c1d492c762a9a02b-client-0,vol_845cf26d86cc37b9c1d492c762a9a02b-client-1,vol_845cf26d86cc37b9c1d492c762a9a02b-client-2
[2020-01-21 11:39:09.270823] D [MSGID: 0]
[options.c:1223:xlator_option_init_int32]
0-vol_845cf26d86cc37b9c1d492c762a9a02b-client-2: option ping-timeout using set
value 42
[2020-01-21 11:39:09.270842] D [MSGID: 0]
[options.c:1230:xlator_option_init_path]
0-vol_845cf26d86cc37b9c1d492c762a9a02b-client-2: option remote-subvolume using
set value
/var/lib/heketi/mounts/vg_1b7440bad4ce40de70d16b8e3f141772/brick_a30c14b4c53ccd2ace7aeb88d9d7389c/brick
[2020-01-21 11:39:09.270868] D [MSGID: 0]
[options.c:1228:xlator_option_init_bool]
0-vol_845cf26d86cc37b9c1d492c762a9a02b-client-2: option send-gids using set
value true
[2020-01-21 11:39:09.270883] D [rpc-clnt.c:1007:rpc_clnt_connection_init]
0-vol_845cf26d86cc37b9c1d492c762a9a02b-client-2: defaulting frame-timeout to
30mins
[2020-01-21 11:39:09.270890] D [rpc-clnt.c:1015:rpc_clnt_connection_init]
0-vol_845cf26d86cc37b9c1d492c762a9a02b-client-2: setting ping-timeout to 42
[2020-01-21 11:39:09.270924] D [rpc-transport.c:293:rpc_transport_load]
0-rpc-transport: attempt to load file
/usr/lib64/glusterfs/6.0/rpc-transport/socket.so
[2020-01-21 11:39:09.271019] D [socket.c:4505:socket_init]
0-vol_845cf26d86cc37b9c1d492c762a9a02b-client-2: Configued
transport.tcp-user-timeout=0
[2020-01-21 11:39:09.271027] D [socket.c:4523:socket_init]
0-vol_845cf26d86cc37b9c1d492c762a9a02b-client-2: Reconfigued
transport.keepalivecnt=9
[2020-01-21 11:39:09.271035] D [socket.c:4209:ssl_setup_connection_params]
0-vol_845cf26d86cc37b9c1d492c762a9a02b-client-2: SSL support on the I/O path is
NOT enabled
[2020-01-21 11:39:09.271041] D [socket.c:4212:ssl_setup_connection_params]
0-vol_845cf26d86cc37b9c1d492c762a9a02b-client-2: SSL support for glusterd is
NOT enabled
[2020-01-21 11:39:09.271051] D [rpc-clnt.c:1584:rpcclnt_cbk_program_register]
0-vol_845cf26d86cc37b9c1d492c762a9a02b-client-2: New program registered:
GlusterFS Callback, Num: 52743234, Ver: 1
[2020-01-21 11:39:09.271058] D [MSGID: 0] [client.c:2578:client_init_rpc]
0-vol_845cf26d86cc37b9c1d492c762a9a02b-client-2: client init successful
[2020-01-21 11:39:09.271088] D [MSGID: 0]
[options.c:1223:xlator_option_init_int32]
0-vol_845cf26d86cc37b9c1d492c762a9a02b-client-1: option ping-timeout using set
value 42
[2020-01-21 11:39:09.271097] D [MSGID: 0]
[options.c:1230:xlator_option_init_path]
0-vol_845cf26d86cc37b9c1d492c762a9a02b-client-1: option remote-subvolume using
set value
/var/lib/heketi/mounts/vg_7b477fb6bfdc692bf3e7b05e93e4d5f4/brick_411aab06bdd9ee9c555f395a124f1456/brick
[2020-01-21 11:39:09.271110] D [MSGID: 0]
[options.c:1228:xlator_option_init_bool]
0-vol_845cf26d86cc37b9c1d492c762a9a02b-client-1: option send-gids using set
value true
[2020-01-21 11:39:09.271118] D [rpc-clnt.c:1007:rpc_clnt_connection_init]
0-vol_845cf26d86cc37b9c1d492c762a9a02b-client-1: defaulting frame-timeout to
30mins
[2020-01-21 11:39:09.271125] D [rpc-clnt.c:1015:rpc_clnt_connection_init]
0-vol_845cf26d86cc37b9c1d492c762a9a02b-client-1: setting ping-timeout to 42
[2020-01-21 11:39:09.271137] D [rpc-transport.c:293:rpc_transport_load]
0-rpc-transport: attempt to load file
/usr/lib64/glusterfs/6.0/rpc-transport/socket.so
[2020-01-21 11:39:09.271216] D [socket.c:4505:socket_init]
0-vol_845cf26d86cc37b9c1d492c762a9a02b-client-1: Configued
transport.tcp-user-timeout=0
[2020-01-21 11:39:09.271223] D [socket.c:4523:socket_init]
0-vol_845cf26d86cc37b9c1d492c762a9a02b-client-1: Reconfigued
transport.keepalivecnt=9
[2020-01-21 11:39:09.271230] D [socket.c:4209:ssl_setup_connection_params]
0-vol_845cf26d86cc37b9c1d492c762a9a02b-client-1: SSL support on the I/O path is
NOT enabled
[2020-01-21 11:39:09.271236] D [socket.c:4212:ssl_setup_connection_params]
0-vol_845cf26d86cc37b9c1d492c762a9a02b-client-1: SSL support for glusterd is
NOT enabled
[2020-01-21 11:39:09.271244] D [rpc-clnt.c:1584:rpcclnt_cbk_program_register]
0-vol_845cf26d86cc37b9c1d492c762a9a02b-client-1: New program registered:
GlusterFS Callback, Num: 52743234, Ver: 1
[2020-01-21 11:39:09.271250] D [MSGID: 0] [client.c:2578:client_init_rpc]
0-vol_845cf26d86cc37b9c1d492c762a9a02b-client-1: client init successful
[2020-01-21 11:39:09.271278] D [MSGID: 0]
[options.c:1223:xlator_option_init_int32]
0-vol_845cf26d86cc37b9c1d492c762a9a02b-client-0: option ping-timeout using set
value 42
[2020-01-21 11:39:09.271288] D [MSGID: 0]
[options.c:1230:xlator_option_init_path]
0-vol_845cf26d86cc37b9c1d492c762a9a02b-client-0: option remote-subvolume using
set value
/var/lib/heketi/mounts/vg_c7173f0e66d49934e004b58f9951903f/brick_6ad49978cf26127ec835d7a5a3085fe4/brick
[2020-01-21 11:39:09.271304] D [MSGID: 0]
[options.c:1228:xlator_option_init_bool]
0-vol_845cf26d86cc37b9c1d492c762a9a02b-client-0: option send-gids using set
value true
[2020-01-21 11:39:09.271312] D [rpc-clnt.c:1007:rpc_clnt_connection_init]
0-vol_845cf26d86cc37b9c1d492c762a9a02b-client-0: defaulting frame-timeout to
30mins
[2020-01-21 11:39:09.271319] D [rpc-clnt.c:1015:rpc_clnt_connection_init]
0-vol_845cf26d86cc37b9c1d492c762a9a02b-client-0: setting ping-timeout to 42
[2020-01-21 11:39:09.271327] D [rpc-transport.c:293:rpc_transport_load]
0-rpc-transport: attempt to load file
/usr/lib64/glusterfs/6.0/rpc-transport/socket.so
[2020-01-21 11:39:09.271405] D [socket.c:4505:socket_init]
0-vol_845cf26d86cc37b9c1d492c762a9a02b-client-0: Configued
transport.tcp-user-timeout=0
[2020-01-21 11:39:09.271411] D [socket.c:4523:socket_init]
0-vol_845cf26d86cc37b9c1d492c762a9a02b-client-0: Reconfigued
transport.keepalivecnt=9
[2020-01-21 11:39:09.271418] D [socket.c:4209:ssl_setup_connection_params]
0-vol_845cf26d86cc37b9c1d492c762a9a02b-client-0: SSL support on the I/O path is
NOT enabled
[2020-01-21 11:39:09.271425] D [socket.c:4212:ssl_setup_connection_params]
0-vol_845cf26d86cc37b9c1d492c762a9a02b-client-0: SSL support for glusterd is
NOT enabled
[2020-01-21 11:39:09.271432] D [rpc-clnt.c:1584:rpcclnt_cbk_program_register]
0-vol_845cf26d86cc37b9c1d492c762a9a02b-client-0: New program registered:
GlusterFS Callback, Num: 52743234, Ver: 1
[2020-01-21 11:39:09.271443] D [MSGID: 0] [client.c:2578:client_init_rpc]
0-vol_845cf26d86cc37b9c1d492c762a9a02b-client-0: client init successful
[2020-01-21 11:39:09.271496] D [MSGID: 101174]
[graph.c:397:_log_if_unknown_option]
0-vol_845cf26d86cc37b9c1d492c762a9a02b-client-2: option
'transport.address-family' is not recognized
[2020-01-21 11:39:09.271507] D [MSGID: 101174]
[graph.c:397:_log_if_unknown_option]
0-vol_845cf26d86cc37b9c1d492c762a9a02b-client-2: option
'transport.socket.ssl-enabled' is not recognized
[2020-01-21 11:39:09.271516] D [MSGID: 101174]
[graph.c:397:_log_if_unknown_option]
0-vol_845cf26d86cc37b9c1d492c762a9a02b-client-2: option
'transport.tcp-user-timeout' is not recognized
[2020-01-21 11:39:09.271526] D [MSGID: 101174]
[graph.c:397:_log_if_unknown_option]
0-vol_845cf26d86cc37b9c1d492c762a9a02b-client-2: option
'transport.socket.keepalive-time' is not recognized
[2020-01-21 11:39:09.271535] D [MSGID: 101174]
[graph.c:397:_log_if_unknown_option]
0-vol_845cf26d86cc37b9c1d492c762a9a02b-client-2: option
'transport.socket.keepalive-interval' is not recognized
[2020-01-21 11:39:09.271545] D [MSGID: 101174]
[graph.c:397:_log_if_unknown_option]
0-vol_845cf26d86cc37b9c1d492c762a9a02b-client-2: option
'transport.socket.keepalive-count' is not recognized
[2020-01-21 11:39:09.271559] D [MSGID: 101174]
[graph.c:397:_log_if_unknown_option]
0-vol_845cf26d86cc37b9c1d492c762a9a02b-client-1: option
'transport.address-family' is not recognized
[2020-01-21 11:39:09.271569] D [MSGID: 101174]
[graph.c:397:_log_if_unknown_option]
0-vol_845cf26d86cc37b9c1d492c762a9a02b-client-1: option
'transport.socket.ssl-enabled' is not recognized
[2020-01-21 11:39:09.271578] D [MSGID: 101174]
[graph.c:397:_log_if_unknown_option]
0-vol_845cf26d86cc37b9c1d492c762a9a02b-client-1: option
'transport.tcp-user-timeout' is not recognized
[2020-01-21 11:39:09.271587] D [MSGID: 101174]
[graph.c:397:_log_if_unknown_option]
0-vol_845cf26d86cc37b9c1d492c762a9a02b-client-1: option
'transport.socket.keepalive-time' is not recognized
[2020-01-21 11:39:09.271597] D [MSGID: 101174]
[graph.c:397:_log_if_unknown_option]
0-vol_845cf26d86cc37b9c1d492c762a9a02b-client-1: option
'transport.socket.keepalive-interval' is not recognized
[2020-01-21 11:39:09.271606] D [MSGID: 101174]
[graph.c:397:_log_if_unknown_option]
0-vol_845cf26d86cc37b9c1d492c762a9a02b-client-1: option
'transport.socket.keepalive-count' is not recognized
[2020-01-21 11:39:09.271620] D [MSGID: 101174]
[graph.c:397:_log_if_unknown_option]
0-vol_845cf26d86cc37b9c1d492c762a9a02b-client-0: option
'transport.address-family' is not recognized
[2020-01-21 11:39:09.271630] D [MSGID: 101174]
[graph.c:397:_log_if_unknown_option]
0-vol_845cf26d86cc37b9c1d492c762a9a02b-client-0: option
'transport.socket.ssl-enabled' is not recognized
[2020-01-21 11:39:09.271642] D [MSGID: 101174]
[graph.c:397:_log_if_unknown_option]
0-vol_845cf26d86cc37b9c1d492c762a9a02b-client-0: option
'transport.tcp-user-timeout' is not recognized
[2020-01-21 11:39:09.271651] D [MSGID: 101174]
[graph.c:397:_log_if_unknown_option]
0-vol_845cf26d86cc37b9c1d492c762a9a02b-client-0: option
'transport.socket.keepalive-time' is not recognized
[2020-01-21 11:39:09.271660] D [MSGID: 101174]
[graph.c:397:_log_if_unknown_option]
0-vol_845cf26d86cc37b9c1d492c762a9a02b-client-0: option
'transport.socket.keepalive-interval' is not recognized
[2020-01-21 11:39:09.271670] D [MSGID: 101174]
[graph.c:397:_log_if_unknown_option]
0-vol_845cf26d86cc37b9c1d492c762a9a02b-client-0: option
'transport.socket.keepalive-count' is not recognized
[2020-01-21 11:39:09.271689] D [fuse-bridge.c:6209:notify] 0-fuse: got event 12
on graph 0
[2020-01-21 11:39:09.271715] D [MSGID: 0]
[afr-common.c:5007:__afr_launch_notify_timer]
0-vol_845cf26d86cc37b9c1d492c762a9a02b-replicate-0: Initiating child-down timer
[2020-01-21 11:39:09.271726] I [MSGID: 114020] [client.c:2389:notify]
0-vol_845cf26d86cc37b9c1d492c762a9a02b-client-0: parent translators are ready,
attempting connect on transport
[2020-01-21 11:39:09.274264] D [MSGID: 0] [common-utils.c:535:gf_resolve_ip6]
0-resolver: returning ip-10.8.30.244 (port-24007) for hostname: 10.8.30.244 and
port: 24007
[2020-01-21 11:39:09.274284] D [socket.c:3254:socket_fix_ssl_opts]
0-vol_845cf26d86cc37b9c1d492c762a9a02b-client-0: disabling SSL for portmapper
connection
[2020-01-21 11:39:09.274649] I [MSGID: 114020] [client.c:2389:notify]
0-vol_845cf26d86cc37b9c1d492c762a9a02b-client-1: parent translators are ready,
attempting connect on transport
[2020-01-21 11:39:09.274925] D [MSGID: 0] [client.c:2295:client_rpc_notify]
0-vol_845cf26d86cc37b9c1d492c762a9a02b-client-0: got RPC_CLNT_CONNECT
[2020-01-21 11:39:09.275341] D
[rpc-clnt-ping.c:96:rpc_clnt_remove_ping_timer_locked] (-->
/lib64/libglusterfs.so.0(_gf_log_callingfn+0x13b)[0x7f4ef8f166bb] (-->
/lib64/libgfrpc.so.0(+0x130ab)[0x7f4ef8cc30ab] (-->
/lib64/libgfrpc.so.0(+0x13851)[0x7f4ef8cc3851] (-->
/lib64/libgfrpc.so.0(rpc_clnt_submit+0x3b4)[0x7f4ef8cbf934] (-->
/usr/lib64/glusterfs/6.0/xlator/protocol/client.so(+0x14569)[0x7f4eea350569]
))))) 0-: 10.8.30.244:24007: ping timer event already removed
[2020-01-21 11:39:09.275428] D [MSGID: 0]
[client-handshake.c:1394:server_has_portmap]
0-vol_845cf26d86cc37b9c1d492c762a9a02b-client-0: detected portmapper on server
[2020-01-21 11:39:09.275483] D [rpc-clnt-ping.c:195:rpc_clnt_ping_cbk]
0-vol_845cf26d86cc37b9c1d492c762a9a02b-client-0: Ping latency is 0ms
[2020-01-21 11:39:09.275635] I [rpc-clnt.c:2028:rpc_clnt_reconfig]
0-vol_845cf26d86cc37b9c1d492c762a9a02b-client-0: changing port to 49171 (from
0)
[2020-01-21 11:39:09.275657] I [socket.c:811:__socket_shutdown]
0-vol_845cf26d86cc37b9c1d492c762a9a02b-client-0: intentional socket
shutdown(14)
[2020-01-21 11:39:09.275676] D [socket.c:2946:socket_event_handler]
0-transport: EPOLLERR - disconnecting (sock:14) (non-SSL)
[2020-01-21 11:39:09.275686] D [MSGID: 0] [client.c:2306:client_rpc_notify]
0-vol_845cf26d86cc37b9c1d492c762a9a02b-client-0: got RPC_CLNT_DISCONNECT
[2020-01-21 11:39:09.275694] D [MSGID: 0] [client.c:2347:client_rpc_notify]
0-vol_845cf26d86cc37b9c1d492c762a9a02b-client-0: disconnected (skipped notify)
[2020-01-21 11:39:09.276953] D [MSGID: 0] [common-utils.c:535:gf_resolve_ip6]
0-resolver: returning ip-10.8.30.245 (port-24007) for hostname: 10.8.30.245 and
port: 24007
[2020-01-21 11:39:09.276976] D [socket.c:3254:socket_fix_ssl_opts]
0-vol_845cf26d86cc37b9c1d492c762a9a02b-client-1: disabling SSL for portmapper
connection
[2020-01-21 11:39:09.277175] I [MSGID: 114020] [client.c:2389:notify]
0-vol_845cf26d86cc37b9c1d492c762a9a02b-client-2: parent translators are ready,
attempting connect on transport
[2020-01-21 11:39:09.279616] D [MSGID: 0] [common-utils.c:535:gf_resolve_ip6]
0-resolver: returning ip-10.8.30.244 (port-24007) for hostname: 10.8.30.244 and
port: 24007
[2020-01-21 11:39:09.280211] D [MSGID: 0] [client.c:2295:client_rpc_notify]
0-vol_845cf26d86cc37b9c1d492c762a9a02b-client-1: got RPC_CLNT_CONNECT
[2020-01-21 11:39:09.280438] D
[rpc-clnt-ping.c:96:rpc_clnt_remove_ping_timer_locked] (-->
/lib64/libglusterfs.so.0(_gf_log_callingfn+0x13b)[0x7f4ef8f166bb] (-->
/lib64/libgfrpc.so.0(+0x130ab)[0x7f4ef8cc30ab] (-->
/lib64/libgfrpc.so.0(+0x13851)[0x7f4ef8cc3851] (-->
/lib64/libgfrpc.so.0(rpc_clnt_submit+0x3b4)[0x7f4ef8cbf934] (-->
/usr/lib64/glusterfs/6.0/xlator/protocol/client.so(+0x14569)[0x7f4eea350569]
))))) 0-: 10.8.30.245:24007: ping timer event already removed
[2020-01-21 11:39:09.280642] D [MSGID: 0] [client.c:2295:client_rpc_notify]
0-vol_845cf26d86cc37b9c1d492c762a9a02b-client-0: got RPC_CLNT_CONNECT
[2020-01-21 11:39:09.280833] D
[rpc-clnt-ping.c:96:rpc_clnt_remove_ping_timer_locked] (-->
/lib64/libglusterfs.so.0(_gf_log_callingfn+0x13b)[0x7f4ef8f166bb] (-->
/lib64/libgfrpc.so.0(+0x130ab)[0x7f4ef8cc30ab] (-->
/lib64/libgfrpc.so.0(+0x13851)[0x7f4ef8cc3851] (-->
/lib64/libgfrpc.so.0(rpc_clnt_submit+0x3b4)[0x7f4ef8cbf934] (-->
/usr/lib64/glusterfs/6.0/xlator/protocol/client.so(+0x14569)[0x7f4eea350569]
))))) 0-: 10.8.30.244:49171: ping timer event already removed
[2020-01-21 11:39:09.280891] D [MSGID: 0]
[client-handshake.c:1394:server_has_portmap]
0-vol_845cf26d86cc37b9c1d492c762a9a02b-client-1: detected portmapper on server
[2020-01-21 11:39:09.280952] D [rpc-clnt-ping.c:195:rpc_clnt_ping_cbk]
0-vol_845cf26d86cc37b9c1d492c762a9a02b-client-1: Ping latency is 0ms
[2020-01-21 11:39:09.281291] D [rpc-clnt-ping.c:195:rpc_clnt_ping_cbk]
0-vol_845cf26d86cc37b9c1d492c762a9a02b-client-0: Ping latency is 0ms
[2020-01-21 11:39:09.281308] I [rpc-clnt.c:2028:rpc_clnt_reconfig]
0-vol_845cf26d86cc37b9c1d492c762a9a02b-client-1: changing port to 49172 (from
0)
[2020-01-21 11:39:09.281329] I [socket.c:811:__socket_shutdown]
0-vol_845cf26d86cc37b9c1d492c762a9a02b-client-1: intentional socket
shutdown(16)
[2020-01-21 11:39:09.281342] D [socket.c:2946:socket_event_handler]
0-transport: EPOLLERR - disconnecting (sock:16) (non-SSL)
[2020-01-21 11:39:09.281351] D [MSGID: 0] [client.c:2306:client_rpc_notify]
0-vol_845cf26d86cc37b9c1d492c762a9a02b-client-1: got RPC_CLNT_DISCONNECT
[2020-01-21 11:39:09.281360] D [MSGID: 0] [client.c:2347:client_rpc_notify]
0-vol_845cf26d86cc37b9c1d492c762a9a02b-client-1: disconnected (skipped notify)
[2020-01-21 11:39:09.281956] D [MSGID: 0] [common-utils.c:535:gf_resolve_ip6]
0-resolver: returning ip-10.8.30.246 (port-24007) for hostname: 10.8.30.246 and
port: 24007
[2020-01-21 11:39:09.281980] D [socket.c:3254:socket_fix_ssl_opts]
0-vol_845cf26d86cc37b9c1d492c762a9a02b-client-2: disabling SSL for portmapper
connection
Final graph:
+------------------------------------------------------------------------------+
1: volume vol_845cf26d86cc37b9c1d492c762a9a02b-client-0
2: type protocol/client
3: option opversion 60000
4: option clnt-lk-version 1
5: option volfile-checksum 0
6: option volfile-key vol_845cf26d86cc37b9c1d492c762a9a02b
7: option client-version 6.0
8: option process-name fuse
9: option process-uuid
CTX_ID:ebb9c633-91c9-48ae-832b-f66fb3101436-GRAPH_ID:0-PID:49369-HOST:chnipc3stg06-PC_NAME:vol_845cf26d86cc37b9c1d492c762a9a02b-client-0-RECON_NO:-0
10: option fops-version 1298437
11: option ping-timeout 42
12: option remote-host 10.8.30.244
13: option remote-subvolume
/var/lib/heketi/mounts/vg_c7173f0e66d49934e004b58f9951903f/brick_6ad49978cf26127ec835d7a5a3085fe4/brick
14: option transport-type socket
15: option transport.address-family inet
16: option username 9f16dcf8-0254-466a-9268-d70e87b0a57e
17: option password a75f0d6c-004f-4695-b6f9-2b49cbde9521
18: option transport.socket.ssl-enabled off
19: option transport.tcp-user-timeout 0
20: option transport.socket.keepalive-time 20
21: option transport.socket.keepalive-interval 2
22: option transport.socket.keepalive-count 9
23: option send-gids true
24: end-volume
25:
26: volume vol_845cf26d86cc37b9c1d492c762a9a02b-client-1
27: type protocol/client
28: option ping-timeout 42
29: option remote-host 10.8.30.245
30: option remote-subvolume
/var/lib/heketi/mounts/vg_7b477fb6bfdc692bf3e7b05e93e4d5f4/brick_411aab06bdd9ee9c555f395a124f1456/brick
31: option transport-type socket
32: option transport.address-family inet
33: option username 9f16dcf8-0254-466a-9268-d70e87b0a57e
34: option password a75f0d6c-004f-4695-b6f9-2b49cbde9521
35: option transport.socket.ssl-enabled off
36: option transport.tcp-user-timeout 0
37: option transport.socket.keepalive-time 20
38: option transport.socket.keepalive-interval 2
39: option transport.socket.keepalive-count 9
40: option send-gids true
41: end-volume
42:
43: volume vol_845cf26d86cc37b9c1d492c762a9a02b-client-2
44: type protocol/client
45: option ping-timeout 42
46: option remote-host 10.8.30.246
47: option remote-subvolume
/var/lib/heketi/mounts/vg_1b7440bad4ce40de70d16b8e3f141772/brick_a30c14b4c53ccd2ace7aeb88d9d7389c/brick
48: option transport-type socket
49: option transport.address-family inet
50: option username 9f16dcf8-0254-466a-9268-d70e87b0a57e
51: option password a75f0d6c-004f-4695-b6f9-2b49cbde9521
52: option transport.socket.ssl-enabled off
53: option transport.tcp-user-timeout 0
54: option transport.socket.keepalive-time 20
55: option transport.socket.keepalive-interval 2
56: option transport.socket.keepalive-count 9
57: option send-gids true
58: end-volume
59:
60: volume vol_845cf26d86cc37b9c1d492c762a9a02b-replicate-0
61: type cluster/replicate
62: option afr-pending-xattr
vol_845cf26d86cc37b9c1d492c762a9a02b-client-0,vol_845cf26d86cc37b9c1d492c762a9a02b-client-1,vol_845cf26d86cc37b9c1d492c762a9a02b-client-2
63: option use-compound-fops off
64: subvolumes vol_845cf26d86cc37b9c1d492c762a9a02b-client-0
vol_845cf26d86cc37b9c1d492c762a9a02b-client-1
vol_845cf26d86cc37b9c1d492c762a9a02b-client-2
65: end-volume
66:
67: volume vol_845cf26d86cc37b9c1d492c762a9a02b-dht
68: type cluster/distribute
69: option lock-migration off
70: option force-migration off
71: subvolumes vol_845cf26d86cc37b9c1d492c762a9a02b-replicate-0
72: end-volume
73:
74: volume vol_845cf26d86cc37b9c1d492c762a9a02b-utime
75: type features/utime
76: option noatime on
77: subvolumes vol_845cf26d86cc37b9c1d492c762a9a02b-dht
78: end-volume
79:
80: volume vol_845cf26d86cc37b9c1d492c762a9a02b-write-behind
81: type performance/write-behind
82: subvolumes vol_845cf26d86cc37b9c1d492c762a9a02b-utime
83: end-volume
84:
85: volume vol_845cf26d86cc37b9c1d492c762a9a02b-read-ahead
86: type performance/read-ahead
87: subvolumes vol_845cf26d86cc37b9c1d492c762a9a02b-write-behind
88: end-volume
89:
90: volume vol_845cf26d86cc37b9c1d492c762a9a02b-readdir-ahead
91: type performance/readdir-ahead
92: option parallel-readdir off
93: option rda-request-size 131072
94: option rda-cache-limit 10MB
95: subvolumes vol_845cf26d86cc37b9c1d492c762a9a02b-read-ahead
96: end-volume
97:
98: volume vol_845cf26d86cc37b9c1d492c762a9a02b-io-cache
99: type performance/io-cache
100: subvolumes vol_845cf26d86cc37b9c1d492c762a9a02b-readdir-ahead
101: end-volume
102:
103: volume vol_845cf26d86cc37b9c1d492c762a9a02b-open-behind
104: type performance/open-behind
105: subvolumes vol_845cf26d86cc37b9c1d492c762a9a02b-io-cache
106: end-volume
107:
108: volume vol_845cf26d86cc37b9c1d492c762a9a02b-quick-read
109: type performance/quick-read
110: subvolumes vol_845cf26d86cc37b9c1d492c762a9a02b-open-behind
111: end-volume
112:
113: volume vol_845cf26d86cc37b9c1d492c762a9a02b-md-cache
114: type performance/md-cache
115: subvolumes vol_845cf26d86cc37b9c1d492c762a9a02b-quick-read
116: end-volume
117:
118: volume vol_845cf26d86cc37b9c1d492c762a9a02b
119: type debug/io-stats
120: option log-level INFO
121: option latency-measurement off
122: option count-fop-hits off
123: subvolumes vol_845cf26d86cc37b9c1d492c762a9a02b-md-cache
124: end-volume
125:
126: volume meta-autoload
127: type meta
128: subvolumes vol_845cf26d86cc37b9c1d492c762a9a02b
129: end-volume
130:
+------------------------------------------------------------------------------+
[2020-01-21 11:39:09.282813] D
[glusterfsd-mgmt.c:2862:glusterfs_mgmt_pmap_signin] 0-fsd-mgmt: portmapper
signin arguments not given
[2020-01-21 11:39:09.282863] D [MSGID: 0] [client.c:2295:client_rpc_notify]
0-vol_845cf26d86cc37b9c1d492c762a9a02b-client-2: got RPC_CLNT_CONNECT
[2020-01-21 11:39:09.283156] D
[rpc-clnt-ping.c:96:rpc_clnt_remove_ping_timer_locked] (-->
/lib64/libglusterfs.so.0(_gf_log_callingfn+0x13b)[0x7f4ef8f166bb] (-->
/lib64/libgfrpc.so.0(+0x130ab)[0x7f4ef8cc30ab] (-->
/lib64/libgfrpc.so.0(+0x13851)[0x7f4ef8cc3851] (-->
/lib64/libgfrpc.so.0(rpc_clnt_submit+0x3b4)[0x7f4ef8cbf934] (-->
/usr/lib64/glusterfs/6.0/xlator/protocol/client.so(+0x14569)[0x7f4eea350569]
))))) 0-: 10.8.30.246:24007: ping timer event already removed
[2020-01-21 11:39:09.283253] I [MSGID: 114046]
[client-handshake.c:1107:client_setvolume_cbk]
0-vol_845cf26d86cc37b9c1d492c762a9a02b-client-0: Connected to
vol_845cf26d86cc37b9c1d492c762a9a02b-client-0, attached to remote volume
'/var/lib/heketi/mounts/vg_c7173f0e66d49934e004b58f9951903f/brick_6ad49978cf26127ec835d7a5a3085fe4/brick'.
[2020-01-21 11:39:09.283267] D [MSGID: 0]
[client-handshake.c:946:client_post_handshake]
0-vol_845cf26d86cc37b9c1d492c762a9a02b-client-0: No fds to open - notifying all
parents child up
[2020-01-21 11:39:09.283281] D [MSGID: 0]
[afr-common.c:5154:afr_get_halo_latency]
0-vol_845cf26d86cc37b9c1d492c762a9a02b-replicate-0: Using halo latency 5
[2020-01-21 11:39:09.283290] I [MSGID: 108005]
[afr-common.c:5235:__afr_handle_child_up_event]
0-vol_845cf26d86cc37b9c1d492c762a9a02b-replicate-0: Subvolume
'vol_845cf26d86cc37b9c1d492c762a9a02b-client-0' came back up; going online.
[2020-01-21 11:39:09.284110] D [MSGID: 0]
[client-handshake.c:1394:server_has_portmap]
0-vol_845cf26d86cc37b9c1d492c762a9a02b-client-2: detected portmapper on server
[2020-01-21 11:39:09.284189] D [rpc-clnt-ping.c:195:rpc_clnt_ping_cbk]
0-vol_845cf26d86cc37b9c1d492c762a9a02b-client-2: Ping latency is 1ms
[2020-01-21 11:39:09.284246] I [rpc-clnt.c:2028:rpc_clnt_reconfig]
0-vol_845cf26d86cc37b9c1d492c762a9a02b-client-2: changing port to 49173 (from
0)
[2020-01-21 11:39:09.284240] D [MSGID: 0] [common-utils.c:535:gf_resolve_ip6]
0-resolver: returning ip-10.8.30.245 (port-24007) for hostname: 10.8.30.245 and
port: 24007
[2020-01-21 11:39:09.284294] I [socket.c:811:__socket_shutdown]
0-vol_845cf26d86cc37b9c1d492c762a9a02b-client-2: intentional socket
shutdown(15)
[2020-01-21 11:39:09.284318] D [socket.c:2946:socket_event_handler]
0-transport: EPOLLERR - disconnecting (sock:15) (non-SSL)
[2020-01-21 11:39:09.284328] D [MSGID: 0] [client.c:2306:client_rpc_notify]
0-vol_845cf26d86cc37b9c1d492c762a9a02b-client-2: got RPC_CLNT_DISCONNECT
[2020-01-21 11:39:09.284340] D [MSGID: 0] [client.c:2347:client_rpc_notify]
0-vol_845cf26d86cc37b9c1d492c762a9a02b-client-2: disconnected (skipped notify)
[2020-01-21 11:39:09.284694] D [MSGID: 0] [client.c:2295:client_rpc_notify]
0-vol_845cf26d86cc37b9c1d492c762a9a02b-client-1: got RPC_CLNT_CONNECT
[2020-01-21 11:39:09.284946] D
[rpc-clnt-ping.c:96:rpc_clnt_remove_ping_timer_locked] (-->
/lib64/libglusterfs.so.0(_gf_log_callingfn+0x13b)[0x7f4ef8f166bb] (-->
/lib64/libgfrpc.so.0(+0x130ab)[0x7f4ef8cc30ab] (-->
/lib64/libgfrpc.so.0(+0x13851)[0x7f4ef8cc3851] (-->
/lib64/libgfrpc.so.0(rpc_clnt_submit+0x3b4)[0x7f4ef8cbf934] (-->
/usr/lib64/glusterfs/6.0/xlator/protocol/client.so(+0x14569)[0x7f4eea350569]
))))) 0-: 10.8.30.245:49172: ping timer event already removed
[2020-01-21 11:39:09.285261] D [rpc-clnt-ping.c:195:rpc_clnt_ping_cbk]
0-vol_845cf26d86cc37b9c1d492c762a9a02b-client-1: Ping latency is 0ms
[2020-01-21 11:39:09.286420] W [MSGID: 114043]
[client-handshake.c:998:client_setvolume_cbk]
0-vol_845cf26d86cc37b9c1d492c762a9a02b-client-1: failed to set the volume
[Permission denied]
[2020-01-21 11:39:09.286446] W [MSGID: 114007]
[client-handshake.c:1027:client_setvolume_cbk]
0-vol_845cf26d86cc37b9c1d492c762a9a02b-client-1: failed to get 'process-uuid'
from reply dict [Invalid argument]
[2020-01-21 11:39:09.286456] E [MSGID: 114044]
[client-handshake.c:1032:client_setvolume_cbk]
0-vol_845cf26d86cc37b9c1d492c762a9a02b-client-1: SETVOLUME on remote-host
failed: Authentication failed [Permission denied]
[2020-01-21 11:39:09.286465] I [MSGID: 114049]
[client-handshake.c:1116:client_setvolume_cbk]
0-vol_845cf26d86cc37b9c1d492c762a9a02b-client-1: sending AUTH_FAILED event
[2020-01-21 11:39:09.286494] D [fuse-bridge.c:6209:notify] 0-fuse: got event 15
on graph 0
[2020-01-21 11:39:09.286502] E [fuse-bridge.c:6268:notify] 0-fuse: Server
authenication failed. Shutting down.
[2020-01-21 11:39:09.286520] I [fuse-bridge.c:6812:fini] 0-fuse: Closing fuse
connection to '/mnt/'.
[2020-01-21 11:39:09.286579] D [logging.c:1813:gf_log_flush_extra_msgs]
0-logging-infra: Log buffer size reduced. About to flush 5 extra log messages
[2020-01-21 11:39:09.286605] D [logging.c:1816:gf_log_flush_extra_msgs]
0-logging-infra: Just flushed 5 extra log messages
[2020-01-21 11:39:09.286635] D [MSGID: 0] [common-utils.c:535:gf_resolve_ip6]
0-resolver: returning ip-10.8.30.246 (port-24007) for hostname: 10.8.30.246 and
port: 24007
[2020-01-21 11:39:09.286686] W [glusterfsd.c:1567:cleanup_and_exit]
(-->/lib64/libpthread.so.0(+0x7dd5) [0x7f4ef7d54dd5]
-->/usr/sbin/glusterfs(glusterfs_sigwaiter+0xe5) [0x55e413e05155]
-->/usr/sbin/glusterfs(cleanup_and_exit+0x6b) [0x55e413e04fbb] ) 0-: received
signum (15), shutting down
[2020-01-21 11:39:09.286708] D [mgmt-pmap.c:92:rpc_clnt_mgmt_pmap_signout]
0-fsd-mgmt: portmapper signout arguments not given
[2020-01-21 11:39:09.286964] E [timer.c:34:gf_timer_call_after]
(-->/lib64/libgfrpc.so.0(rpc_clnt_cleanup_and_start+0x41) [0x7f4ef8cbee51]
-->/lib64/libgfrpc.so.0(rpc_clnt_reconnect+0xee) [0x7f4ef8cbe7ae]
-->/lib64/libglusterfs.so.0(gf_timer_call_after+0x229) [0x7f4ef8f242f9] )
0-timer: Either ctx is NULL or ctx cleanup started [Invalid argument]
[2020-01-21 11:39:09.286992] E [rpc-clnt.c:406:rpc_clnt_reconnect]
0-vol_845cf26d86cc37b9c1d492c762a9a02b-client-2: Error adding to timer event
queue
```
--
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