gluster / glusterfs

Gluster Filesystem : Build your distributed storage in minutes
https://www.gluster.org
GNU General Public License v2.0
4.7k stars 1.08k forks source link

9.0/9.2: qemu-img always reports: "All subvolumes are down. Going offline until at least one of them comes back up." #2583

Closed wxiaoguang closed 3 years ago

wxiaoguang commented 3 years ago

Description of problem:

qemu-img always reports: "All subvolumes are down. Going offline until at least one of them comes back up."

I have tried glusterfs 9.0 cluster and 9.2 cluster in debian 10 with fresh installation.

I have tried to turn on/off server.allow-inseucre, it doesn't have affect.

The exact command to reproduce the issue:

qemu-img qcow2 format:

~# qemu-img create -f qcow2 gluster://test-host-alpha/gv-zfs-common/test.img 1G
Formatting 'gluster://test-host-alpha/gv-zfs-common/test.img', fmt=qcow2 size=1073741824 cluster_size=65536 lazy_refcounts=off refcount_bits=16
[2021-06-28 15:57:16.804080 +0000] I [io-stats.c:3708:ios_sample_buf_size_configure] 0-gv-zfs-common: Configure ios_sample_buf  size is 1024 because ios_sample_interval is 0
[2021-06-28 15:57:16.913917 +0000] E [MSGID: 108006] [afr-common.c:6146:__afr_handle_child_down_event] 0-gv-zfs-common-replicate-0: All subvolumes are down. Going offline until at least one of them comes back up.

### ---- (hangs up for 10 seconds) ----

[2021-06-28 15:57:26.807258 +0000] I [io-stats.c:4038:fini] 0-gv-zfs-common: io-stats translator unloaded
[2021-06-28 15:57:27.815345 +0000] I [io-stats.c:3708:ios_sample_buf_size_configure] 0-gv-zfs-common: Configure ios_sample_buf  size is 1024 because ios_sample_interval is 0
[2021-06-28 15:57:27.940674 +0000] E [MSGID: 108006] [afr-common.c:6146:__afr_handle_child_down_event] 0-gv-zfs-common-replicate-0: All subvolumes are down. Going offline until at least one of them comes back up.

### ---- (hangs up for 10 seconds) ----

[2021-06-28 15:57:37.817966 +0000] I [io-stats.c:4038:fini] 0-gv-zfs-common: io-stats translator unloaded

qemu-img raw format:

~# qemu-img create -f raw gluster://test-host-alpha/gv-zfs-common/test.img 100M
Formatting 'gluster://test-host-alpha/gv-zfs-common/test.img', fmt=raw size=104857600
[2021-06-29 04:18:07.502391 +0000] I [io-stats.c:3708:ios_sample_buf_size_configure] 0-gv-zfs-common: Configure ios_sample_buf  size is 1024 because ios_sample_interval is 0
[2021-06-29 04:18:07.612651 +0000] E [MSGID: 108006] [afr-common.c:6146:__afr_handle_child_down_event] 0-gv-zfs-common-replicate-0: All subvolumes are down. Going offline until at least one of them comes back up.

### ---- (hangs up for 10 seconds) ----

[2021-06-29 04:18:17.505541 +0000] I [io-stats.c:4038:fini] 0-gv-zfs-common: io-stats translator unloaded

then if we look into the gluster data directory, we can find the file is there,

~# ls -l /data1/glusterfs-storage/common/
total 1
-rw------- 2 root root 104857600 Jun 29 12:18 test.img

The full output of the command that failed:

* brick debug logs ``` [2021-06-29 07:22:47.481912 +0000] D [logging.c:1735:gf_log_flush_timeout_cbk] 0-logging-infra: Log timer timed out. About to flush outstanding messages if present [2021-06-29 07:22:39.158797 +0000] D [MSGID: 0] [posix-metadata.c:135:posix_fetch_mdata_xattr] 0-gv-zfs-common-posix: No such attribute:trusted.glusterfs.mdata for file /data1/glusterfs-storage/common/.glusterfs/landfill gfid: null [2021-06-29 07:22:47.482015 +0000] D [logging.c:1697:__gf_log_inject_timer_event] 0-logging-infra: Starting timer now. Timeout = 120, current buf size = 5 [2021-06-29 07:22:47.774790 +0000] D [socket.c:4555:socket_init] 0-tcp.gv-zfs-common-server: Configured transport.tcp-user-timeout=42 [2021-06-29 07:22:47.774823 +0000] D [socket.c:4575:socket_init] 0-tcp.gv-zfs-common-server: Reconfigured transport.keepalivecnt=9 [2021-06-29 07:22:47.775163 +0000] D [client_t.c:235:gf_client_get] (-->/lib/x86_64-linux-gnu/libgfrpc.so.0(+0x9a9d) [0x7f4422206a9d] -->/usr/lib/x86_64-linux-gnu/glusterfs/9.0/xlator/protocol/server.so(+0x2c2d4) [0x7f441c4492d4] -->/lib/x86_64-linux-gnu/libglusterfs.so.0(gf_client_get+0x2c4) [0x7f44222c17b4] ) 0-client_t: CTX_ID:9dc5dbb0-f400-467b-9904-4c072ad121ab-GRAPH_ID:0-PID:57263-HOST:test-host-beta-PC_NAME:gv-zfs-common-client-0-RECON_NO:-0: bind_ref: 1, ref: 1 [2021-06-29 07:22:47.775208 +0000] D [MSGID: 0] [server-handshake.c:432:server_setvolume] 0-gv-zfs-common-server: Connected to CTX_ID:9dc5dbb0-f400-467b-9904-4c072ad121ab-GRAPH_ID:0-PID:57263-HOST:test-host-beta-PC_NAME:gv-zfs-common-client-0-RECON_NO:-0 [2021-06-29 07:22:47.775236 +0000] D [MSGID: 0] [server-helpers.c:1351:auth_set_username_passwd] 0-auth/login: username not found, returning DONT-CARE [2021-06-29 07:22:47.775272 +0000] I [addr.c:54:compare_addr_and_update] 0-/data1/glusterfs-storage/common: allowed = "*", received addr = "10.0.0.75" [2021-06-29 07:22:47.775294 +0000] D [login.c:66:gf_auth] 0-auth/login: username not found, returning DONT-CARE [2021-06-29 07:22:47.775326 +0000] I [MSGID: 115029] [server-handshake.c:561:server_setvolume] 0-gv-zfs-common-server: accepted client from CTX_ID:9dc5dbb0-f400-467b-9904-4c072ad121ab-GRAPH_ID:0-PID:57263-HOST:test-host-beta-PC_NAME:gv-zfs-common-client-0-RECON_NO:-0 (version: 9.0) with subvol /data1/glusterfs-storage/common [2021-06-29 07:22:47.775530 +0000] D [MSGID: 0] [io-threads.c:376:iot_schedule] 0-gv-zfs-common-io-threads: LOOKUP scheduled as fast priority fop [2021-06-29 07:22:47.776572 +0000] D [client_t.c:285:gf_client_ref] (-->/usr/lib/x86_64-linux-gnu/glusterfs/9.0/xlator/protocol/server.so(+0x22ef5) [0x7f441c43fef5] -->/usr/lib/x86_64-linux-gnu/glusterfs/9.0/xlator/protocol/server.so(+0xfa8d) [0x7f441c42ca8d] -->/lib/x86_64-linux-gnu/libglusterfs.so.0(gf_client_ref+0x57) [0x7f44222c1987] ) 0-client_t: CTX_ID:9dc5dbb0-f400-467b-9904-4c072ad121ab-GRAPH_ID:0-PID:57263-HOST:test-host-beta-PC_NAME:gv-zfs-common-client-0-RECON_NO:-0: ref-count 2 [2021-06-29 07:22:47.776611 +0000] D [MSGID: 0] [io-threads.c:376:iot_schedule] 0-gv-zfs-common-io-threads: STATFS scheduled as fast priority fop [2021-06-29 07:22:47.776700 +0000] D [client_t.c:394:gf_client_unref] (-->/usr/lib/x86_64-linux-gnu/glusterfs/9.0/xlator/protocol/server.so(+0x49f35) [0x7f441c466f35] -->/usr/lib/x86_64-linux-gnu/glusterfs/9.0/xlator/protocol/server.so(+0xa0d8) [0x7f441c4270d8] -->/lib/x86_64-linux-gnu/libglusterfs.so.0(gf_client_unref+0x68) [0x7f44222c1ab8] ) 0-client_t: CTX_ID:9dc5dbb0-f400-467b-9904-4c072ad121ab-GRAPH_ID:0-PID:57263-HOST:test-host-beta-PC_NAME:gv-zfs-common-client-0-RECON_NO:-0: ref-count 1 [2021-06-29 07:22:47.777364 +0000] D [client_t.c:285:gf_client_ref] (-->/usr/lib/x86_64-linux-gnu/glusterfs/9.0/xlator/protocol/server.so(+0x22ef5) [0x7f441c43fef5] -->/usr/lib/x86_64-linux-gnu/glusterfs/9.0/xlator/protocol/server.so(+0xfa8d) [0x7f441c42ca8d] -->/lib/x86_64-linux-gnu/libglusterfs.so.0(gf_client_ref+0x57) [0x7f44222c1987] ) 0-client_t: CTX_ID:9dc5dbb0-f400-467b-9904-4c072ad121ab-GRAPH_ID:0-PID:57263-HOST:test-host-beta-PC_NAME:gv-zfs-common-client-0-RECON_NO:-0: ref-count 2 [2021-06-29 07:22:47.777513 +0000] D [logging.c:1862:_gf_msg_internal] 0-logging-infra: Buffer overflow of a buffer whose size limit is 5. About to flush least recently used log message to disk [2021-06-29 07:22:47.777401 +0000] D [MSGID: 0] [io-threads.c:376:iot_schedule] 0-gv-zfs-common-io-threads: LOOKUP scheduled as fast priority fop [2021-06-29 07:22:47.777512 +0000] D [MSGID: 101016] [glusterfs3.h:781:dict_to_xdr] 0-dict: key 'trusted.glusterfs.mdata' would not be sent on wire in the future [Invalid argument] [2021-06-29 07:22:47.777589 +0000] D [client_t.c:394:gf_client_unref] (-->/usr/lib/x86_64-linux-gnu/glusterfs/9.0/xlator/protocol/server.so(+0x3c7bb) [0x7f441c4597bb] -->/usr/lib/x86_64-linux-gnu/glusterfs/9.0/xlator/protocol/server.so(+0xa0d8) [0x7f441c4270d8] -->/lib/x86_64-linux-gnu/libglusterfs.so.0(gf_client_unref+0x68) [0x7f44222c1ab8] ) 0-client_t: CTX_ID:9dc5dbb0-f400-467b-9904-4c072ad121ab-GRAPH_ID:0-PID:57263-HOST:test-host-beta-PC_NAME:gv-zfs-common-client-0-RECON_NO:-0: ref-count 1 [2021-06-29 07:22:47.777670 +0000] D [client_t.c:285:gf_client_ref] (-->/usr/lib/x86_64-linux-gnu/glusterfs/9.0/xlator/protocol/server.so(+0x22ef5) [0x7f441c43fef5] -->/usr/lib/x86_64-linux-gnu/glusterfs/9.0/xlator/protocol/server.so(+0xfa8d) [0x7f441c42ca8d] -->/lib/x86_64-linux-gnu/libglusterfs.so.0(gf_client_ref+0x57) [0x7f44222c1987] ) 0-client_t: CTX_ID:9dc5dbb0-f400-467b-9904-4c072ad121ab-GRAPH_ID:0-PID:57263-HOST:test-host-beta-PC_NAME:gv-zfs-common-client-0-RECON_NO:-0: ref-count 2 [2021-06-29 07:22:47.777689 +0000] D [marker.c:519:marker_getxattr] 0-gv-zfs-common-marker: USER:PID = 0 [2021-06-29 07:22:47.777699 +0000] D [MSGID: 0] [io-threads.c:376:iot_schedule] 0-gv-zfs-common-io-threads: GETXATTR scheduled as normal priority fop [2021-06-29 07:22:47.777775 +0000] D [client_t.c:394:gf_client_unref] (-->/usr/lib/x86_64-linux-gnu/glusterfs/9.0/xlator/protocol/server.so(+0x3da8b) [0x7f441c45aa8b] -->/usr/lib/x86_64-linux-gnu/glusterfs/9.0/xlator/protocol/server.so(+0xa0d8) [0x7f441c4270d8] -->/lib/x86_64-linux-gnu/libglusterfs.so.0(gf_client_unref+0x68) [0x7f44222c1ab8] ) 0-client_t: CTX_ID:9dc5dbb0-f400-467b-9904-4c072ad121ab-GRAPH_ID:0-PID:57263-HOST:test-host-beta-PC_NAME:gv-zfs-common-client-0-RECON_NO:-0: ref-count 1 [2021-06-29 07:22:47.778210 +0000] D [client_t.c:285:gf_client_ref] (-->/usr/lib/x86_64-linux-gnu/glusterfs/9.0/xlator/protocol/server.so(+0x22ef5) [0x7f441c43fef5] -->/usr/lib/x86_64-linux-gnu/glusterfs/9.0/xlator/protocol/server.so(+0xfa8d) [0x7f441c42ca8d] -->/lib/x86_64-linux-gnu/libglusterfs.so.0(gf_client_ref+0x57) [0x7f44222c1987] ) 0-client_t: CTX_ID:9dc5dbb0-f400-467b-9904-4c072ad121ab-GRAPH_ID:0-PID:57263-HOST:test-host-beta-PC_NAME:gv-zfs-common-client-0-RECON_NO:-0: ref-count 2 [2021-06-29 07:22:47.778244 +0000] D [MSGID: 0] [io-threads.c:376:iot_schedule] 0-gv-zfs-common-io-threads: LOOKUP scheduled as fast priority fop [2021-06-29 07:22:47.778393 +0000] D [MSGID: 101016] [glusterfs3.h:781:dict_to_xdr] 0-dict: key 'trusted.afr.dirty' would not be sent on wire in the future [Invalid argument] [2021-06-29 07:22:47.778407 +0000] D [MSGID: 101016] [glusterfs3.h:781:dict_to_xdr] 0-dict: key 'trusted.afr.gv-zfs-common-client-1' would not be sent on wire in the future [Invalid argument] [2021-06-29 07:22:47.778415 +0000] D [MSGID: 101016] [glusterfs3.h:781:dict_to_xdr] 0-dict: key 'trusted.glusterfs.mdata' would not be sent on wire in the future [Invalid argument] [2021-06-29 07:22:47.778459 +0000] D [client_t.c:394:gf_client_unref] (-->/usr/lib/x86_64-linux-gnu/glusterfs/9.0/xlator/protocol/server.so(+0x3c7bb) [0x7f441c4597bb] -->/usr/lib/x86_64-linux-gnu/glusterfs/9.0/xlator/protocol/server.so(+0xa0d8) [0x7f441c4270d8] -->/lib/x86_64-linux-gnu/libglusterfs.so.0(gf_client_unref+0x68) [0x7f44222c1ab8] ) 0-client_t: CTX_ID:9dc5dbb0-f400-467b-9904-4c072ad121ab-GRAPH_ID:0-PID:57263-HOST:test-host-beta-PC_NAME:gv-zfs-common-client-0-RECON_NO:-0: ref-count 1 [2021-06-29 07:22:47.778985 +0000] D [client_t.c:285:gf_client_ref] (-->/usr/lib/x86_64-linux-gnu/glusterfs/9.0/xlator/protocol/server.so(+0x22ef5) [0x7f441c43fef5] -->/usr/lib/x86_64-linux-gnu/glusterfs/9.0/xlator/protocol/server.so(+0xfa8d) [0x7f441c42ca8d] -->/lib/x86_64-linux-gnu/libglusterfs.so.0(gf_client_ref+0x57) [0x7f44222c1987] ) 0-client_t: CTX_ID:9dc5dbb0-f400-467b-9904-4c072ad121ab-GRAPH_ID:0-PID:57263-HOST:test-host-beta-PC_NAME:gv-zfs-common-client-0-RECON_NO:-0: ref-count 2 [2021-06-29 07:22:47.779005 +0000] D [MSGID: 0] [io-threads.c:376:iot_schedule] 0-gv-zfs-common-io-threads: OPEN scheduled as fast priority fop [2021-06-29 07:22:47.779105 +0000] D [client_t.c:394:gf_client_unref] (-->/usr/lib/x86_64-linux-gnu/glusterfs/9.0/xlator/protocol/server.so(+0x41da9) [0x7f441c45eda9] -->/usr/lib/x86_64-linux-gnu/glusterfs/9.0/xlator/protocol/server.so(+0xa0d8) [0x7f441c4270d8] -->/lib/x86_64-linux-gnu/libglusterfs.so.0(gf_client_unref+0x68) [0x7f44222c1ab8] ) 0-client_t: CTX_ID:9dc5dbb0-f400-467b-9904-4c072ad121ab-GRAPH_ID:0-PID:57263-HOST:test-host-beta-PC_NAME:gv-zfs-common-client-0-RECON_NO:-0: ref-count 1 [2021-06-29 07:22:47.779389 +0000] D [client_t.c:285:gf_client_ref] (-->/usr/lib/x86_64-linux-gnu/glusterfs/9.0/xlator/protocol/server.so(+0x22ef5) [0x7f441c43fef5] -->/usr/lib/x86_64-linux-gnu/glusterfs/9.0/xlator/protocol/server.so(+0xfa8d) [0x7f441c42ca8d] -->/lib/x86_64-linux-gnu/libglusterfs.so.0(gf_client_ref+0x57) [0x7f44222c1987] ) 0-client_t: CTX_ID:9dc5dbb0-f400-467b-9904-4c072ad121ab-GRAPH_ID:0-PID:57263-HOST:test-host-beta-PC_NAME:gv-zfs-common-client-0-RECON_NO:-0: ref-count 2 [2021-06-29 07:22:47.779400 +0000] D [MSGID: 0] [server-rpc-fops_v2.c:2505:server4_finodelk_resume] 0-/data1/glusterfs-storage/common: frame 0x7f440800c9c8, xlator 0x7f441802b5b0 [2021-06-29 07:22:47.779412 +0000] D [MSGID: 0] [io-threads.c:376:iot_schedule] 0-gv-zfs-common-io-threads: FINODELK scheduled as normal priority fop [2021-06-29 07:22:47.779461 +0000] D [client_t.c:394:gf_client_unref] (-->/usr/lib/x86_64-linux-gnu/glusterfs/9.0/xlator/protocol/server.so(+0x4db77) [0x7f441c46ab77] -->/usr/lib/x86_64-linux-gnu/glusterfs/9.0/xlator/protocol/server.so(+0xa0d8) [0x7f441c4270d8] -->/lib/x86_64-linux-gnu/libglusterfs.so.0(gf_client_unref+0x68) [0x7f44222c1ab8] ) 0-client_t: CTX_ID:9dc5dbb0-f400-467b-9904-4c072ad121ab-GRAPH_ID:0-PID:57263-HOST:test-host-beta-PC_NAME:gv-zfs-common-client-0-RECON_NO:-0: ref-count 1 [2021-06-29 07:22:47.779755 +0000] D [client_t.c:285:gf_client_ref] (-->/usr/lib/x86_64-linux-gnu/glusterfs/9.0/xlator/protocol/server.so(+0x22ef5) [0x7f441c43fef5] -->/usr/lib/x86_64-linux-gnu/glusterfs/9.0/xlator/protocol/server.so(+0xfa8d) [0x7f441c42ca8d] -->/lib/x86_64-linux-gnu/libglusterfs.so.0(gf_client_ref+0x57) [0x7f44222c1987] ) 0-client_t: CTX_ID:9dc5dbb0-f400-467b-9904-4c072ad121ab-GRAPH_ID:0-PID:57263-HOST:test-host-beta-PC_NAME:gv-zfs-common-client-0-RECON_NO:-0: ref-count 2 [2021-06-29 07:22:47.779859 +0000] D [MSGID: 0] [io-threads.c:376:iot_schedule] 0-gv-zfs-common-io-threads: FXATTROP scheduled as slow priority fop [2021-06-29 07:22:47.779979 +0000] D [MSGID: 101016] [glusterfs3.h:781:dict_to_xdr] 0-dict: key 'trusted.afr.dirty' would not be sent on wire in the future [Invalid argument] [2021-06-29 07:22:47.779992 +0000] D [MSGID: 101016] [glusterfs3.h:781:dict_to_xdr] 0-dict: key 'trusted.afr.gv-zfs-common-client-2' would not be sent on wire in the future [Invalid argument] [2021-06-29 07:22:47.779998 +0000] D [MSGID: 101016] [glusterfs3.h:781:dict_to_xdr] 0-dict: key 'trusted.afr.gv-zfs-common-client-1' would not be sent on wire in the future [Invalid argument] [2021-06-29 07:22:47.780004 +0000] D [MSGID: 101016] [glusterfs3.h:781:dict_to_xdr] 0-dict: key 'trusted.afr.gv-zfs-common-client-0' would not be sent on wire in the future [Invalid argument] [2021-06-29 07:22:47.780041 +0000] D [client_t.c:394:gf_client_unref] (-->/usr/lib/x86_64-linux-gnu/glusterfs/9.0/xlator/protocol/server.so(+0x3e83a) [0x7f441c45b83a] -->/usr/lib/x86_64-linux-gnu/glusterfs/9.0/xlator/protocol/server.so(+0xa0d8) [0x7f441c4270d8] -->/lib/x86_64-linux-gnu/libglusterfs.so.0(gf_client_unref+0x68) [0x7f44222c1ab8] ) 0-client_t: CTX_ID:9dc5dbb0-f400-467b-9904-4c072ad121ab-GRAPH_ID:0-PID:57263-HOST:test-host-beta-PC_NAME:gv-zfs-common-client-0-RECON_NO:-0: ref-count 1 [2021-06-29 07:22:47.780517 +0000] D [client_t.c:285:gf_client_ref] (-->/usr/lib/x86_64-linux-gnu/glusterfs/9.0/xlator/protocol/server.so(+0x22ef5) [0x7f441c43fef5] -->/usr/lib/x86_64-linux-gnu/glusterfs/9.0/xlator/protocol/server.so(+0xfa8d) [0x7f441c42ca8d] -->/lib/x86_64-linux-gnu/libglusterfs.so.0(gf_client_ref+0x57) [0x7f44222c1987] ) 0-client_t: CTX_ID:9dc5dbb0-f400-467b-9904-4c072ad121ab-GRAPH_ID:0-PID:57263-HOST:test-host-beta-PC_NAME:gv-zfs-common-client-0-RECON_NO:-0: ref-count 2 [2021-06-29 07:22:47.780533 +0000] D [MSGID: 0] [io-threads.c:376:iot_schedule] 0-gv-zfs-common-io-threads: FTRUNCATE scheduled as slow priority fop [2021-06-29 07:22:47.780706 +0000] D [client_t.c:394:gf_client_unref] (-->/usr/lib/x86_64-linux-gnu/glusterfs/9.0/xlator/protocol/server.so(+0x43695) [0x7f441c460695] -->/usr/lib/x86_64-linux-gnu/glusterfs/9.0/xlator/protocol/server.so(+0xa0d8) [0x7f441c4270d8] -->/lib/x86_64-linux-gnu/libglusterfs.so.0(gf_client_unref+0x68) [0x7f44222c1ab8] ) 0-client_t: CTX_ID:9dc5dbb0-f400-467b-9904-4c072ad121ab-GRAPH_ID:0-PID:57263-HOST:test-host-beta-PC_NAME:gv-zfs-common-client-0-RECON_NO:-0: ref-count 1 [2021-06-29 07:22:47.781064 +0000] D [client_t.c:285:gf_client_ref] (-->/usr/lib/x86_64-linux-gnu/glusterfs/9.0/xlator/protocol/server.so(+0x22ef5) [0x7f441c43fef5] -->/usr/lib/x86_64-linux-gnu/glusterfs/9.0/xlator/protocol/server.so(+0xfa8d) [0x7f441c42ca8d] -->/lib/x86_64-linux-gnu/libglusterfs.so.0(gf_client_ref+0x57) [0x7f44222c1987] ) 0-client_t: CTX_ID:9dc5dbb0-f400-467b-9904-4c072ad121ab-GRAPH_ID:0-PID:57263-HOST:test-host-beta-PC_NAME:gv-zfs-common-client-0-RECON_NO:-0: ref-count 2 [2021-06-29 07:22:47.781083 +0000] D [MSGID: 0] [io-threads.c:376:iot_schedule] 0-gv-zfs-common-io-threads: FSTAT scheduled as fast priority fop [2021-06-29 07:22:47.781146 +0000] D [client_t.c:285:gf_client_ref] (-->/usr/lib/x86_64-linux-gnu/glusterfs/9.0/xlator/protocol/server.so(+0x22ef5) [0x7f441c43fef5] -->/usr/lib/x86_64-linux-gnu/glusterfs/9.0/xlator/protocol/server.so(+0xfa8d) [0x7f441c42ca8d] -->/lib/x86_64-linux-gnu/libglusterfs.so.0(gf_client_ref+0x57) [0x7f44222c1987] ) 0-client_t: CTX_ID:9dc5dbb0-f400-467b-9904-4c072ad121ab-GRAPH_ID:0-PID:57263-HOST:test-host-beta-PC_NAME:gv-zfs-common-client-0-RECON_NO:-0: ref-count 3 [2021-06-29 07:22:47.781188 +0000] D [MSGID: 101016] [glusterfs3.h:781:dict_to_xdr] 0-dict: key 'trusted.glusterfs.mdata' would not be sent on wire in the future [Invalid argument] [2021-06-29 07:22:47.781202 +0000] D [MSGID: 101016] [glusterfs3.h:781:dict_to_xdr] 0-dict: key 'trusted.afr.dirty' would not be sent on wire in the future [Invalid argument] [2021-06-29 07:22:47.781209 +0000] D [MSGID: 101016] [glusterfs3.h:781:dict_to_xdr] 0-dict: key 'trusted.afr.gv-zfs-common-client-1' would not be sent on wire in the future [Invalid argument] [2021-06-29 07:22:47.781205 +0000] D [MSGID: 0] [io-threads.c:376:iot_schedule] 0-gv-zfs-common-io-threads: FXATTROP scheduled as slow priority fop [2021-06-29 07:22:47.781248 +0000] D [client_t.c:394:gf_client_unref] (-->/usr/lib/x86_64-linux-gnu/glusterfs/9.0/xlator/protocol/server.so(+0x45b0f) [0x7f441c462b0f] -->/usr/lib/x86_64-linux-gnu/glusterfs/9.0/xlator/protocol/server.so(+0xa0d8) [0x7f441c4270d8] -->/lib/x86_64-linux-gnu/libglusterfs.so.0(gf_client_unref+0x68) [0x7f44222c1ab8] ) 0-client_t: CTX_ID:9dc5dbb0-f400-467b-9904-4c072ad121ab-GRAPH_ID:0-PID:57263-HOST:test-host-beta-PC_NAME:gv-zfs-common-client-0-RECON_NO:-0: ref-count 2 [2021-06-29 07:22:47.781422 +0000] D [MSGID: 101016] [glusterfs3.h:781:dict_to_xdr] 0-dict: key 'trusted.afr.dirty' would not be sent on wire in the future [Invalid argument] [2021-06-29 07:22:47.781434 +0000] D [MSGID: 101016] [glusterfs3.h:781:dict_to_xdr] 0-dict: key 'trusted.afr.gv-zfs-common-client-2' would not be sent on wire in the future [Invalid argument] [2021-06-29 07:22:47.781440 +0000] D [MSGID: 101016] [glusterfs3.h:781:dict_to_xdr] 0-dict: key 'trusted.afr.gv-zfs-common-client-1' would not be sent on wire in the future [Invalid argument] [2021-06-29 07:22:47.781445 +0000] D [MSGID: 101016] [glusterfs3.h:781:dict_to_xdr] 0-dict: key 'trusted.afr.gv-zfs-common-client-0' would not be sent on wire in the future [Invalid argument] [2021-06-29 07:22:47.781483 +0000] D [client_t.c:394:gf_client_unref] (-->/usr/lib/x86_64-linux-gnu/glusterfs/9.0/xlator/protocol/server.so(+0x3e83a) [0x7f441c45b83a] -->/usr/lib/x86_64-linux-gnu/glusterfs/9.0/xlator/protocol/server.so(+0xa0d8) [0x7f441c4270d8] -->/lib/x86_64-linux-gnu/libglusterfs.so.0(gf_client_unref+0x68) [0x7f44222c1ab8] ) 0-client_t: CTX_ID:9dc5dbb0-f400-467b-9904-4c072ad121ab-GRAPH_ID:0-PID:57263-HOST:test-host-beta-PC_NAME:gv-zfs-common-client-0-RECON_NO:-0: ref-count 1 [2021-06-29 07:22:47.781664 +0000] D [client_t.c:285:gf_client_ref] (-->/usr/lib/x86_64-linux-gnu/glusterfs/9.0/xlator/protocol/server.so(+0x22ef5) [0x7f441c43fef5] -->/usr/lib/x86_64-linux-gnu/glusterfs/9.0/xlator/protocol/server.so(+0xfa8d) [0x7f441c42ca8d] -->/lib/x86_64-linux-gnu/libglusterfs.so.0(gf_client_ref+0x57) [0x7f44222c1987] ) 0-client_t: CTX_ID:9dc5dbb0-f400-467b-9904-4c072ad121ab-GRAPH_ID:0-PID:57263-HOST:test-host-beta-PC_NAME:gv-zfs-common-client-0-RECON_NO:-0: ref-count 2 [2021-06-29 07:22:47.781695 +0000] D [MSGID: 0] [io-threads.c:376:iot_schedule] 0-gv-zfs-common-io-threads: FSTAT scheduled as fast priority fop [2021-06-29 07:22:47.781788 +0000] D [client_t.c:394:gf_client_unref] (-->/usr/lib/x86_64-linux-gnu/glusterfs/9.0/xlator/protocol/server.so(+0x45b0f) [0x7f441c462b0f] -->/usr/lib/x86_64-linux-gnu/glusterfs/9.0/xlator/protocol/server.so(+0xa0d8) [0x7f441c4270d8] -->/lib/x86_64-linux-gnu/libglusterfs.so.0(gf_client_unref+0x68) [0x7f44222c1ab8] ) 0-client_t: CTX_ID:9dc5dbb0-f400-467b-9904-4c072ad121ab-GRAPH_ID:0-PID:57263-HOST:test-host-beta-PC_NAME:gv-zfs-common-client-0-RECON_NO:-0: ref-count 1 [2021-06-29 07:22:47.782004 +0000] D [client_t.c:285:gf_client_ref] (-->/usr/lib/x86_64-linux-gnu/glusterfs/9.0/xlator/protocol/server.so(+0x22ef5) [0x7f441c43fef5] -->/usr/lib/x86_64-linux-gnu/glusterfs/9.0/xlator/protocol/server.so(+0xfa8d) [0x7f441c42ca8d] -->/lib/x86_64-linux-gnu/libglusterfs.so.0(gf_client_ref+0x57) [0x7f44222c1987] ) 0-client_t: CTX_ID:9dc5dbb0-f400-467b-9904-4c072ad121ab-GRAPH_ID:0-PID:57263-HOST:test-host-beta-PC_NAME:gv-zfs-common-client-0-RECON_NO:-0: ref-count 2 [2021-06-29 07:22:47.782025 +0000] D [MSGID: 0] [server-rpc-fops_v2.c:2505:server4_finodelk_resume] 0-/data1/glusterfs-storage/common: frame 0x7f4404005bc8, xlator 0x7f441802b5b0 [2021-06-29 07:22:47.782048 +0000] D [MSGID: 0] [io-threads.c:376:iot_schedule] 0-gv-zfs-common-io-threads: FINODELK scheduled as normal priority fop [2021-06-29 07:22:47.782078 +0000] D [inodelk.c:517:__inode_unlock_lock] 0-gv-zfs-common-locks: Matching lock found for unlock 0-9223372036854775807, by 480358b39f550000 on 0x7f441001a9d0 for gfid:a95f57c6-5e98-4667-a725-a427e163ac60 [2021-06-29 07:22:47.782114 +0000] D [client_t.c:394:gf_client_unref] (-->/usr/lib/x86_64-linux-gnu/glusterfs/9.0/xlator/protocol/server.so(+0x4db77) [0x7f441c46ab77] -->/usr/lib/x86_64-linux-gnu/glusterfs/9.0/xlator/protocol/server.so(+0xa0d8) [0x7f441c4270d8] -->/lib/x86_64-linux-gnu/libglusterfs.so.0(gf_client_unref+0x68) [0x7f44222c1ab8] ) 0-client_t: CTX_ID:9dc5dbb0-f400-467b-9904-4c072ad121ab-GRAPH_ID:0-PID:57263-HOST:test-host-beta-PC_NAME:gv-zfs-common-client-0-RECON_NO:-0: ref-count 1 [2021-06-29 07:22:47.782502 +0000] D [client_t.c:285:gf_client_ref] (-->/usr/lib/x86_64-linux-gnu/glusterfs/9.0/xlator/protocol/server.so(+0x22ef5) [0x7f441c43fef5] -->/usr/lib/x86_64-linux-gnu/glusterfs/9.0/xlator/protocol/server.so(+0xfa8d) [0x7f441c42ca8d] -->/lib/x86_64-linux-gnu/libglusterfs.so.0(gf_client_ref+0x57) [0x7f44222c1987] ) 0-client_t: CTX_ID:9dc5dbb0-f400-467b-9904-4c072ad121ab-GRAPH_ID:0-PID:57263-HOST:test-host-beta-PC_NAME:gv-zfs-common-client-0-RECON_NO:-0: ref-count 2 [2021-06-29 07:22:47.782522 +0000] D [MSGID: 0] [server-rpc-fops_v2.c:2505:server4_finodelk_resume] 0-/data1/glusterfs-storage/common: frame 0x7f4404003c58, xlator 0x7f441802b5b0 [2021-06-29 07:22:47.782541 +0000] D [MSGID: 0] [io-threads.c:376:iot_schedule] 0-gv-zfs-common-io-threads: FINODELK scheduled as normal priority fop [2021-06-29 07:22:47.782588 +0000] D [client_t.c:394:gf_client_unref] (-->/usr/lib/x86_64-linux-gnu/glusterfs/9.0/xlator/protocol/server.so(+0x4db77) [0x7f441c46ab77] -->/usr/lib/x86_64-linux-gnu/glusterfs/9.0/xlator/protocol/server.so(+0xa0d8) [0x7f441c4270d8] -->/lib/x86_64-linux-gnu/libglusterfs.so.0(gf_client_unref+0x68) [0x7f44222c1ab8] ) 0-client_t: CTX_ID:9dc5dbb0-f400-467b-9904-4c072ad121ab-GRAPH_ID:0-PID:57263-HOST:test-host-beta-PC_NAME:gv-zfs-common-client-0-RECON_NO:-0: ref-count 1 [2021-06-29 07:22:47.783012 +0000] D [client_t.c:285:gf_client_ref] (-->/usr/lib/x86_64-linux-gnu/glusterfs/9.0/xlator/protocol/server.so(+0x22ef5) [0x7f441c43fef5] -->/usr/lib/x86_64-linux-gnu/glusterfs/9.0/xlator/protocol/server.so(+0xfa8d) [0x7f441c42ca8d] -->/lib/x86_64-linux-gnu/libglusterfs.so.0(gf_client_ref+0x57) [0x7f44222c1987] ) 0-client_t: CTX_ID:9dc5dbb0-f400-467b-9904-4c072ad121ab-GRAPH_ID:0-PID:57263-HOST:test-host-beta-PC_NAME:gv-zfs-common-client-0-RECON_NO:-0: ref-count 2 [2021-06-29 07:22:47.783101 +0000] D [MSGID: 0] [io-threads.c:376:iot_schedule] 0-gv-zfs-common-io-threads: FXATTROP scheduled as slow priority fop [2021-06-29 07:22:47.783209 +0000] D [MSGID: 101016] [glusterfs3.h:781:dict_to_xdr] 0-dict: key 'trusted.afr.dirty' would not be sent on wire in the future [Invalid argument] [2021-06-29 07:22:47.783222 +0000] D [MSGID: 101016] [glusterfs3.h:781:dict_to_xdr] 0-dict: key 'trusted.afr.gv-zfs-common-client-2' would not be sent on wire in the future [Invalid argument] [2021-06-29 07:22:47.783229 +0000] D [MSGID: 101016] [glusterfs3.h:781:dict_to_xdr] 0-dict: key 'trusted.afr.gv-zfs-common-client-1' would not be sent on wire in the future [Invalid argument] [2021-06-29 07:22:47.783242 +0000] D [MSGID: 101016] [glusterfs3.h:781:dict_to_xdr] 0-dict: key 'trusted.afr.gv-zfs-common-client-0' would not be sent on wire in the future [Invalid argument] [2021-06-29 07:22:47.783276 +0000] D [client_t.c:394:gf_client_unref] (-->/usr/lib/x86_64-linux-gnu/glusterfs/9.0/xlator/protocol/server.so(+0x3e83a) [0x7f441c45b83a] -->/usr/lib/x86_64-linux-gnu/glusterfs/9.0/xlator/protocol/server.so(+0xa0d8) [0x7f441c4270d8] -->/lib/x86_64-linux-gnu/libglusterfs.so.0(gf_client_unref+0x68) [0x7f44222c1ab8] ) 0-client_t: CTX_ID:9dc5dbb0-f400-467b-9904-4c072ad121ab-GRAPH_ID:0-PID:57263-HOST:test-host-beta-PC_NAME:gv-zfs-common-client-0-RECON_NO:-0: ref-count 1 [2021-06-29 07:22:47.783714 +0000] D [client_t.c:285:gf_client_ref] (-->/usr/lib/x86_64-linux-gnu/glusterfs/9.0/xlator/protocol/server.so(+0x22ef5) [0x7f441c43fef5] -->/usr/lib/x86_64-linux-gnu/glusterfs/9.0/xlator/protocol/server.so(+0xfa8d) [0x7f441c42ca8d] -->/lib/x86_64-linux-gnu/libglusterfs.so.0(gf_client_ref+0x57) [0x7f44222c1987] ) 0-client_t: CTX_ID:9dc5dbb0-f400-467b-9904-4c072ad121ab-GRAPH_ID:0-PID:57263-HOST:test-host-beta-PC_NAME:gv-zfs-common-client-0-RECON_NO:-0: ref-count 2 [2021-06-29 07:22:47.783741 +0000] D [MSGID: 0] [io-threads.c:376:iot_schedule] 0-gv-zfs-common-io-threads: FTRUNCATE scheduled as slow priority fop [2021-06-29 07:22:47.783890 +0000] D [client_t.c:394:gf_client_unref] (-->/usr/lib/x86_64-linux-gnu/glusterfs/9.0/xlator/protocol/server.so(+0x43695) [0x7f441c460695] -->/usr/lib/x86_64-linux-gnu/glusterfs/9.0/xlator/protocol/server.so(+0xa0d8) [0x7f441c4270d8] -->/lib/x86_64-linux-gnu/libglusterfs.so.0(gf_client_unref+0x68) [0x7f44222c1ab8] ) 0-client_t: CTX_ID:9dc5dbb0-f400-467b-9904-4c072ad121ab-GRAPH_ID:0-PID:57263-HOST:test-host-beta-PC_NAME:gv-zfs-common-client-0-RECON_NO:-0: ref-count 1 [2021-06-29 07:22:47.784275 +0000] D [client_t.c:285:gf_client_ref] (-->/usr/lib/x86_64-linux-gnu/glusterfs/9.0/xlator/protocol/server.so(+0x22ef5) [0x7f441c43fef5] -->/usr/lib/x86_64-linux-gnu/glusterfs/9.0/xlator/protocol/server.so(+0xfa8d) [0x7f441c42ca8d] -->/lib/x86_64-linux-gnu/libglusterfs.so.0(gf_client_ref+0x57) [0x7f44222c1987] ) 0-client_t: CTX_ID:9dc5dbb0-f400-467b-9904-4c072ad121ab-GRAPH_ID:0-PID:57263-HOST:test-host-beta-PC_NAME:gv-zfs-common-client-0-RECON_NO:-0: ref-count 2 [2021-06-29 07:22:47.784304 +0000] D [MSGID: 0] [io-threads.c:376:iot_schedule] 0-gv-zfs-common-io-threads: FXATTROP scheduled as slow priority fop [2021-06-29 07:22:47.784357 +0000] D [client_t.c:285:gf_client_ref] (-->/usr/lib/x86_64-linux-gnu/glusterfs/9.0/xlator/protocol/server.so(+0x22ef5) [0x7f441c43fef5] -->/usr/lib/x86_64-linux-gnu/glusterfs/9.0/xlator/protocol/server.so(+0xfa8d) [0x7f441c42ca8d] -->/lib/x86_64-linux-gnu/libglusterfs.so.0(gf_client_ref+0x57) [0x7f44222c1987] ) 0-client_t: CTX_ID:9dc5dbb0-f400-467b-9904-4c072ad121ab-GRAPH_ID:0-PID:57263-HOST:test-host-beta-PC_NAME:gv-zfs-common-client-0-RECON_NO:-0: ref-count 3 [2021-06-29 07:22:47.784378 +0000] D [MSGID: 0] [io-threads.c:376:iot_schedule] 0-gv-zfs-common-io-threads: FLUSH scheduled as normal priority fop [2021-06-29 07:22:47.784459 +0000] D [MSGID: 101016] [glusterfs3.h:781:dict_to_xdr] 0-dict: key 'trusted.afr.dirty' would not be sent on wire in the future [Invalid argument] [2021-06-29 07:22:47.784472 +0000] D [MSGID: 101016] [glusterfs3.h:781:dict_to_xdr] 0-dict: key 'trusted.afr.gv-zfs-common-client-2' would not be sent on wire in the future [Invalid argument] [2021-06-29 07:22:47.784479 +0000] D [MSGID: 101016] [glusterfs3.h:781:dict_to_xdr] 0-dict: key 'trusted.afr.gv-zfs-common-client-1' would not be sent on wire in the future [Invalid argument] [2021-06-29 07:22:47.784484 +0000] D [MSGID: 101016] [glusterfs3.h:781:dict_to_xdr] 0-dict: key 'trusted.afr.gv-zfs-common-client-0' would not be sent on wire in the future [Invalid argument] [2021-06-29 07:22:47.784519 +0000] D [client_t.c:394:gf_client_unref] (-->/usr/lib/x86_64-linux-gnu/glusterfs/9.0/xlator/protocol/server.so(+0x3e83a) [0x7f441c45b83a] -->/usr/lib/x86_64-linux-gnu/glusterfs/9.0/xlator/protocol/server.so(+0xa0d8) [0x7f441c4270d8] -->/lib/x86_64-linux-gnu/libglusterfs.so.0(gf_client_unref+0x68) [0x7f44222c1ab8] ) 0-client_t: CTX_ID:9dc5dbb0-f400-467b-9904-4c072ad121ab-GRAPH_ID:0-PID:57263-HOST:test-host-beta-PC_NAME:gv-zfs-common-client-0-RECON_NO:-0: ref-count 2 [2021-06-29 07:22:47.784571 +0000] D [client_t.c:394:gf_client_unref] (-->/usr/lib/x86_64-linux-gnu/glusterfs/9.0/xlator/protocol/server.so(+0x4e517) [0x7f441c46b517] -->/usr/lib/x86_64-linux-gnu/glusterfs/9.0/xlator/protocol/server.so(+0xa0d8) [0x7f441c4270d8] -->/lib/x86_64-linux-gnu/libglusterfs.so.0(gf_client_unref+0x68) [0x7f44222c1ab8] ) 0-client_t: CTX_ID:9dc5dbb0-f400-467b-9904-4c072ad121ab-GRAPH_ID:0-PID:57263-HOST:test-host-beta-PC_NAME:gv-zfs-common-client-0-RECON_NO:-0: ref-count 1 [2021-06-29 07:22:47.784938 +0000] D [client_t.c:285:gf_client_ref] (-->/usr/lib/x86_64-linux-gnu/glusterfs/9.0/xlator/protocol/server.so(+0x22ef5) [0x7f441c43fef5] -->/usr/lib/x86_64-linux-gnu/glusterfs/9.0/xlator/protocol/server.so(+0xfa8d) [0x7f441c42ca8d] -->/lib/x86_64-linux-gnu/libglusterfs.so.0(gf_client_ref+0x57) [0x7f44222c1987] ) 0-client_t: CTX_ID:9dc5dbb0-f400-467b-9904-4c072ad121ab-GRAPH_ID:0-PID:57263-HOST:test-host-beta-PC_NAME:gv-zfs-common-client-0-RECON_NO:-0: ref-count 2 [2021-06-29 07:22:47.784957 +0000] D [MSGID: 0] [server-rpc-fops_v2.c:2505:server4_finodelk_resume] 0-/data1/glusterfs-storage/common: frame 0x7f4404001038, xlator 0x7f441802b5b0 [2021-06-29 07:22:47.784977 +0000] D [MSGID: 0] [io-threads.c:376:iot_schedule] 0-gv-zfs-common-io-threads: FINODELK scheduled as normal priority fop [2021-06-29 07:22:47.785004 +0000] D [inodelk.c:517:__inode_unlock_lock] 0-gv-zfs-common-locks: Matching lock found for unlock 0-9223372036854775807, by 480358b39f550000 on 0x7f441001a9d0 for gfid:a95f57c6-5e98-4667-a725-a427e163ac60 [2021-06-29 07:22:47.785036 +0000] D [client_t.c:394:gf_client_unref] (-->/usr/lib/x86_64-linux-gnu/glusterfs/9.0/xlator/protocol/server.so(+0x4db77) [0x7f441c46ab77] -->/usr/lib/x86_64-linux-gnu/glusterfs/9.0/xlator/protocol/server.so(+0xa0d8) [0x7f441c4270d8] -->/lib/x86_64-linux-gnu/libglusterfs.so.0(gf_client_unref+0x68) [0x7f44222c1ab8] ) 0-client_t: CTX_ID:9dc5dbb0-f400-467b-9904-4c072ad121ab-GRAPH_ID:0-PID:57263-HOST:test-host-beta-PC_NAME:gv-zfs-common-client-0-RECON_NO:-0: ref-count 1 [2021-06-29 07:22:47.884847 +0000] D [socket.c:738:__socket_rwv] 0-tcp.gv-zfs-common-server: EOF on socket 270 (errno:0:Success); returning ENODATA [2021-06-29 07:22:47.884886 +0000] W [socket.c:767:__socket_rwv] 0-tcp.gv-zfs-common-server: readv on 10.0.0.75:49144 failed (No data available) [2021-06-29 07:22:47.884907 +0000] D [socket.c:2963:socket_event_handler] 0-transport: EPOLLERR - disconnecting (sock:270) (non-SSL) [2021-06-29 07:22:47.884939 +0000] I [MSGID: 115036] [server.c:500:server_rpc_notify] 0-gv-zfs-common-server: disconnecting connection [{client-uid=CTX_ID:9dc5dbb0-f400-467b-9904-4c072ad121ab-GRAPH_ID:0-PID:57263-HOST:test-host-beta-PC_NAME:gv-zfs-common-client-0-RECON_NO:-0}] [2021-06-29 07:22:47.885060 +0000] D [client_t.c:285:gf_client_ref] (-->/lib/x86_64-linux-gnu/libgfrpc.so.0(+0x74de) [0x7f44222044de] -->/usr/lib/x86_64-linux-gnu/glusterfs/9.0/xlator/protocol/server.so(+0xa972) [0x7f441c427972] -->/lib/x86_64-linux-gnu/libglusterfs.so.0(gf_client_ref+0x57) [0x7f44222c1987] ) 0-client_t: CTX_ID:9dc5dbb0-f400-467b-9904-4c072ad121ab-GRAPH_ID:0-PID:57263-HOST:test-host-beta-PC_NAME:gv-zfs-common-client-0-RECON_NO:-0: ref-count 2 [2021-06-29 07:22:47.885146 +0000] D [client_t.c:261:gf_client_put] (-->/lib/x86_64-linux-gnu/libgfrpc.so.0(+0x74de) [0x7f44222044de] -->/usr/lib/x86_64-linux-gnu/glusterfs/9.0/xlator/protocol/server.so(+0xa97f) [0x7f441c42797f] -->/lib/x86_64-linux-gnu/libglusterfs.so.0(gf_client_put+0x7e) [0x7f44222c1d4e] ) 0-client_t: CTX_ID:9dc5dbb0-f400-467b-9904-4c072ad121ab-GRAPH_ID:0-PID:57263-HOST:test-host-beta-PC_NAME:gv-zfs-common-client-0-RECON_NO:-0: bind_ref: 0, ref: 2, unref: 1 [2021-06-29 07:22:47.885236 +0000] D [client_t.c:394:gf_client_unref] (-->/lib/x86_64-linux-gnu/libgfrpc.so.0(+0x74de) [0x7f44222044de] -->/usr/lib/x86_64-linux-gnu/glusterfs/9.0/xlator/protocol/server.so(+0xa97f) [0x7f441c42797f] -->/lib/x86_64-linux-gnu/libglusterfs.so.0(gf_client_unref+0x68) [0x7f44222c1ab8] ) 0-client_t: CTX_ID:9dc5dbb0-f400-467b-9904-4c072ad121ab-GRAPH_ID:0-PID:57263-HOST:test-host-beta-PC_NAME:gv-zfs-common-client-0-RECON_NO:-0: ref-count 1 [2021-06-29 07:22:47.885305 +0000] D [MSGID: 0] [server-helpers.c:410:server_connection_cleanup] 0-gv-zfs-common-server: Performing cleanup on 128 fdentries [2021-06-29 07:22:47.885436 +0000] D [client_t.c:394:gf_client_unref] (-->/lib/x86_64-linux-gnu/libgfrpc.so.0(+0x5c75) [0x7f4422202c75] -->/usr/lib/x86_64-linux-gnu/glusterfs/9.0/xlator/protocol/server.so(+0xa856) [0x7f441c427856] -->/lib/x86_64-linux-gnu/libglusterfs.so.0(gf_client_unref+0x68) [0x7f44222c1ab8] ) 0-client_t: CTX_ID:9dc5dbb0-f400-467b-9904-4c072ad121ab-GRAPH_ID:0-PID:57263-HOST:test-host-beta-PC_NAME:gv-zfs-common-client-0-RECON_NO:-0: ref-count 0 [2021-06-29 07:22:47.885447 +0000] I [MSGID: 101055] [client_t.c:397:gf_client_unref] 0-gv-zfs-common-server: Shutting down connection CTX_ID:9dc5dbb0-f400-467b-9904-4c072ad121ab-GRAPH_ID:0-PID:57263-HOST:test-host-beta-PC_NAME:gv-zfs-common-client-0-RECON_NO:-0 [2021-06-29 07:22:50.170218 +0000] D [MSGID: 0] [posix-metadata.c:135:posix_fetch_mdata_xattr] 0-gv-zfs-common-posix: No such attribute:trusted.glusterfs.mdata for file /data1/glusterfs-storage/common/.glusterfs/landfill gfid: null ``` * client debug logs ``` ~# qemu-img create -f raw gluster://test-host-alpha/gv-zfs-common/test.img 1M Formatting 'gluster://test-host-alpha/gv-zfs-common/test.img', fmt=raw size=1048576 [2021-06-29 07:22:47.737135 +0000] D [MSGID: 0] [options.c:1230:xlator_option_init_bool] 0-gv-zfs-common: option count-fop-hits using set value off [2021-06-29 07:22:47.737157 +0000] D [MSGID: 0] [options.c:1230:xlator_option_init_bool] 0-gv-zfs-common: option latency-measurement using set value off [2021-06-29 07:22:47.737171 +0000] I [io-stats.c:3708:ios_sample_buf_size_configure] 0-gv-zfs-common: Configure ios_sample_buf size is 1024 because ios_sample_interval is 0 [2021-06-29 07:22:47.737190 +0000] D [MSGID: 0] [options.c:1221:xlator_option_init_str] 0-gv-zfs-common: option log-level using set value DEBUG [2021-06-29 07:22:47.737216 +0000] D [MSGID: 0] [options.c:1225:xlator_option_init_int32] 0-gv-zfs-common: option threads using set value 16 [2021-06-29 07:22:47.737284 +0000] D [MSGID: 0] [quick-read.c:1170:check_cache_size_ok] 0-gv-zfs-common-quick-read: Max cache size is 540648435712 [2021-06-29 07:22:47.737338 +0000] D [MSGID: 0] [options.c:1230:xlator_option_init_bool] 0-gv-zfs-common-utime: option noatime using set value on [2021-06-29 07:22:47.737377 +0000] D [MSGID: 0] [options.c:1230:xlator_option_init_bool] 0-gv-zfs-common-dht: option lock-migration using set value off [2021-06-29 07:22:47.737389 +0000] D [MSGID: 0] [options.c:1230:xlator_option_init_bool] 0-gv-zfs-common-dht: option force-migration using set value off [2021-06-29 07:22:47.737417 +0000] D [MSGID: 0] [dht-shared.c:329:dht_init_regex] 0-gv-zfs-common-dht: using regex rsync-hash-regex = ^\.(.+)\.[^.]+$ [2021-06-29 07:22:47.737468 +0000] D [MSGID: 0] [options.c:1224:xlator_option_init_uint32] 0-gv-zfs-common-replicate-0: option arbiter-count using set value 1 [2021-06-29 07:22:47.737593 +0000] D [MSGID: 0] [options.c:1230:xlator_option_init_bool] 0-gv-zfs-common-replicate-0: option granular-entry-heal using set value on [2021-06-29 07:22:47.737676 +0000] D [MSGID: 0] [options.c:1230:xlator_option_init_bool] 0-gv-zfs-common-replicate-0: option use-anonymous-inode using set value yes [2021-06-29 07:22:47.737690 +0000] D [MSGID: 0] [options.c:1221:xlator_option_init_str] 0-gv-zfs-common-replicate-0: option afr-pending-xattr using set value gv-zfs-common-client-0,gv-zfs-common-client-1,gv-zfs-common-client-2 [2021-06-29 07:22:47.738343 +0000] D [MSGID: 0] [options.c:1225:xlator_option_init_int32] 0-gv-zfs-common-client-2: option ping-timeout using set value 42 [2021-06-29 07:22:47.738352 +0000] D [MSGID: 0] [options.c:1232:xlator_option_init_path] 0-gv-zfs-common-client-2: option remote-subvolume using set value /data/glusterfs-storage-arbiter/common [2021-06-29 07:22:47.738365 +0000] D [MSGID: 0] [options.c:1230:xlator_option_init_bool] 0-gv-zfs-common-client-2: option send-gids using set value true [2021-06-29 07:22:47.738378 +0000] D [MSGID: 0] [options.c:1230:xlator_option_init_bool] 0-gv-zfs-common-client-2: option strict-locks using set value off [2021-06-29 07:22:47.738387 +0000] D [rpc-clnt.c:1012:rpc_clnt_connection_init] 0-gv-zfs-common-client-2: defaulting frame-timeout to 30mins [2021-06-29 07:22:47.738394 +0000] D [rpc-clnt.c:1020:rpc_clnt_connection_init] 0-gv-zfs-common-client-2: setting ping-timeout to 42 [2021-06-29 07:22:47.738406 +0000] D [rpc-transport.c:278:rpc_transport_load] 0-rpc-transport: attempt to load file /usr/lib/x86_64-linux-gnu/glusterfs/9.0/rpc-transport/socket.so [2021-06-29 07:22:47.738495 +0000] D [socket.c:4555:socket_init] 0-gv-zfs-common-client-2: Configured transport.tcp-user-timeout=0 [2021-06-29 07:22:47.738501 +0000] D [socket.c:4575:socket_init] 0-gv-zfs-common-client-2: Reconfigured transport.keepalivecnt=9 [2021-06-29 07:22:47.738508 +0000] D [rpc-clnt.c:1587:rpcclnt_cbk_program_register] 0-gv-zfs-common-client-2: New program registered: GlusterFS Callback, Num: 52743234, Ver: 1 [2021-06-29 07:22:47.738513 +0000] D [MSGID: 0] [client.c:2507:client_init_rpc] 0-gv-zfs-common-client-2: client init successful [2021-06-29 07:22:47.738536 +0000] D [MSGID: 0] [options.c:1225:xlator_option_init_int32] 0-gv-zfs-common-client-1: option ping-timeout using set value 42 [2021-06-29 07:22:47.738544 +0000] D [MSGID: 0] [options.c:1232:xlator_option_init_path] 0-gv-zfs-common-client-1: option remote-subvolume using set value /data1/glusterfs-storage/common [2021-06-29 07:22:47.738556 +0000] D [MSGID: 0] [options.c:1230:xlator_option_init_bool] 0-gv-zfs-common-client-1: option send-gids using set value true [2021-06-29 07:22:47.738568 +0000] D [MSGID: 0] [options.c:1230:xlator_option_init_bool] 0-gv-zfs-common-client-1: option strict-locks using set value off [2021-06-29 07:22:47.738575 +0000] D [rpc-clnt.c:1012:rpc_clnt_connection_init] 0-gv-zfs-common-client-1: defaulting frame-timeout to 30mins [2021-06-29 07:22:47.738581 +0000] D [rpc-clnt.c:1020:rpc_clnt_connection_init] 0-gv-zfs-common-client-1: setting ping-timeout to 42 [2021-06-29 07:22:47.738588 +0000] D [rpc-transport.c:278:rpc_transport_load] 0-rpc-transport: attempt to load file /usr/lib/x86_64-linux-gnu/glusterfs/9.0/rpc-transport/socket.so [2021-06-29 07:22:47.738675 +0000] D [socket.c:4555:socket_init] 0-gv-zfs-common-client-1: Configured transport.tcp-user-timeout=0 [2021-06-29 07:22:47.738680 +0000] D [socket.c:4575:socket_init] 0-gv-zfs-common-client-1: Reconfigured transport.keepalivecnt=9 [2021-06-29 07:22:47.738686 +0000] D [rpc-clnt.c:1587:rpcclnt_cbk_program_register] 0-gv-zfs-common-client-1: New program registered: GlusterFS Callback, Num: 52743234, Ver: 1 [2021-06-29 07:22:47.738691 +0000] D [MSGID: 0] [client.c:2507:client_init_rpc] 0-gv-zfs-common-client-1: client init successful [2021-06-29 07:22:47.738711 +0000] D [MSGID: 0] [options.c:1225:xlator_option_init_int32] 0-gv-zfs-common-client-0: option ping-timeout using set value 42 [2021-06-29 07:22:47.738719 +0000] D [MSGID: 0] [options.c:1232:xlator_option_init_path] 0-gv-zfs-common-client-0: option remote-subvolume using set value /data1/glusterfs-storage/common [2021-06-29 07:22:47.738731 +0000] D [MSGID: 0] [options.c:1230:xlator_option_init_bool] 0-gv-zfs-common-client-0: option send-gids using set value true [2021-06-29 07:22:47.738743 +0000] D [MSGID: 0] [options.c:1230:xlator_option_init_bool] 0-gv-zfs-common-client-0: option strict-locks using set value off [2021-06-29 07:22:47.738753 +0000] D [rpc-clnt.c:1012:rpc_clnt_connection_init] 0-gv-zfs-common-client-0: defaulting frame-timeout to 30mins [2021-06-29 07:22:47.738758 +0000] D [rpc-clnt.c:1020:rpc_clnt_connection_init] 0-gv-zfs-common-client-0: setting ping-timeout to 42 [2021-06-29 07:22:47.738764 +0000] D [rpc-transport.c:278:rpc_transport_load] 0-rpc-transport: attempt to load file /usr/lib/x86_64-linux-gnu/glusterfs/9.0/rpc-transport/socket.so [2021-06-29 07:22:47.738845 +0000] D [socket.c:4555:socket_init] 0-gv-zfs-common-client-0: Configured transport.tcp-user-timeout=0 [2021-06-29 07:22:47.738850 +0000] D [socket.c:4575:socket_init] 0-gv-zfs-common-client-0: Reconfigured transport.keepalivecnt=9 [2021-06-29 07:22:47.738856 +0000] D [rpc-clnt.c:1587:rpcclnt_cbk_program_register] 0-gv-zfs-common-client-0: New program registered: GlusterFS Callback, Num: 52743234, Ver: 1 [2021-06-29 07:22:47.738861 +0000] D [MSGID: 0] [client.c:2507:client_init_rpc] 0-gv-zfs-common-client-0: client init successful [2021-06-29 07:22:47.738903 +0000] D [MSGID: 101174] [graph.c:460:_log_if_unknown_option] 0-gv-zfs-common-replicate-0: option 'volume-id' is not recognized [2021-06-29 07:22:47.738948 +0000] D [MSGID: 101174] [graph.c:460:_log_if_unknown_option] 0-gv-zfs-common-client-2: option 'transport.address-family' is not recognized [2021-06-29 07:22:47.738958 +0000] D [MSGID: 101174] [graph.c:460:_log_if_unknown_option] 0-gv-zfs-common-client-2: option 'transport.socket.ssl-enabled' is not recognized [2021-06-29 07:22:47.738968 +0000] D [MSGID: 101174] [graph.c:460:_log_if_unknown_option] 0-gv-zfs-common-client-2: option 'transport.tcp-user-timeout' is not recognized [2021-06-29 07:22:47.738977 +0000] D [MSGID: 101174] [graph.c:460:_log_if_unknown_option] 0-gv-zfs-common-client-2: option 'transport.socket.keepalive-time' is not recognized [2021-06-29 07:22:47.738987 +0000] D [MSGID: 101174] [graph.c:460:_log_if_unknown_option] 0-gv-zfs-common-client-2: option 'transport.socket.keepalive-interval' is not recognized [2021-06-29 07:22:47.738997 +0000] D [MSGID: 101174] [graph.c:460:_log_if_unknown_option] 0-gv-zfs-common-client-2: option 'transport.socket.keepalive-count' is not recognized [2021-06-29 07:22:47.739016 +0000] D [MSGID: 101174] [graph.c:460:_log_if_unknown_option] 0-gv-zfs-common-client-1: option 'transport.address-family' is not recognized [2021-06-29 07:22:47.739025 +0000] D [MSGID: 101174] [graph.c:460:_log_if_unknown_option] 0-gv-zfs-common-client-1: option 'transport.socket.ssl-enabled' is not recognized [2021-06-29 07:22:47.739035 +0000] D [MSGID: 101174] [graph.c:460:_log_if_unknown_option] 0-gv-zfs-common-client-1: option 'transport.tcp-user-timeout' is not recognized [2021-06-29 07:22:47.739047 +0000] D [MSGID: 101174] [graph.c:460:_log_if_unknown_option] 0-gv-zfs-common-client-1: option 'transport.socket.keepalive-time' is not recognized [2021-06-29 07:22:47.739056 +0000] D [MSGID: 101174] [graph.c:460:_log_if_unknown_option] 0-gv-zfs-common-client-1: option 'transport.socket.keepalive-interval' is not recognized [2021-06-29 07:22:47.739066 +0000] D [MSGID: 101174] [graph.c:460:_log_if_unknown_option] 0-gv-zfs-common-client-1: option 'transport.socket.keepalive-count' is not recognized [2021-06-29 07:22:47.739084 +0000] D [MSGID: 101174] [graph.c:460:_log_if_unknown_option] 0-gv-zfs-common-client-0: option 'transport.address-family' is not recognized [2021-06-29 07:22:47.739093 +0000] D [MSGID: 101174] [graph.c:460:_log_if_unknown_option] 0-gv-zfs-common-client-0: option 'transport.socket.ssl-enabled' is not recognized [2021-06-29 07:22:47.739102 +0000] D [MSGID: 101174] [graph.c:460:_log_if_unknown_option] 0-gv-zfs-common-client-0: option 'transport.tcp-user-timeout' is not recognized [2021-06-29 07:22:47.739112 +0000] D [MSGID: 101174] [graph.c:460:_log_if_unknown_option] 0-gv-zfs-common-client-0: option 'transport.socket.keepalive-time' is not recognized [2021-06-29 07:22:47.739121 +0000] D [MSGID: 101174] [graph.c:460:_log_if_unknown_option] 0-gv-zfs-common-client-0: option 'transport.socket.keepalive-interval' is not recognized [2021-06-29 07:22:47.739131 +0000] D [MSGID: 101174] [graph.c:460:_log_if_unknown_option] 0-gv-zfs-common-client-0: option 'transport.socket.keepalive-count' is not recognized [2021-06-29 07:22:47.739150 +0000] I [MSGID: 104045] [glfs-primary.c:81:notify] 0-gfapi: New graph coming up [{graph-uuid=66767473-2d68-6f73-742d-636e2d626574}, {id=0}] [2021-06-29 07:22:47.739170 +0000] D [MSGID: 0] [afr-common.c:5846:__afr_launch_notify_timer] 0-gv-zfs-common-replicate-0: Initiating child-down timer [2021-06-29 07:22:47.739179 +0000] I [MSGID: 114020] [client.c:2319:notify] 0-gv-zfs-common-client-0: parent translators are ready, attempting connect on transport [] [2021-06-29 07:22:47.739291 +0000] D [MSGID: 0] [common-utils.c:545:gf_resolve_ip6] 0-resolver: returning ip-10.0.0.74 (port-24007) for hostname: test-host-alpha and port: 24007 [2021-06-29 07:22:47.739300 +0000] D [socket.c:3291:socket_fix_ssl_opts] 0-gv-zfs-common-client-0: disabling SSL for portmapper connection [2021-06-29 07:22:47.739359 +0000] I [MSGID: 114020] [client.c:2319:notify] 0-gv-zfs-common-client-1: parent translators are ready, attempting connect on transport [] [2021-06-29 07:22:47.739416 +0000] D [MSGID: 0] [client.c:2211:client_rpc_notify] 0-gv-zfs-common-client-0: got RPC_CLNT_CONNECT [2021-06-29 07:22:47.739453 +0000] D [MSGID: 0] [common-utils.c:545:gf_resolve_ip6] 0-resolver: returning ip-10.0.0.75 (port-24007) for hostname: test-host-beta and port: 24007 [2021-06-29 07:22:47.739462 +0000] D [socket.c:3291:socket_fix_ssl_opts] 0-gv-zfs-common-client-1: disabling SSL for portmapper connection [2021-06-29 07:22:47.739510 +0000] I [MSGID: 114020] [client.c:2319:notify] 0-gv-zfs-common-client-2: parent translators are ready, attempting connect on transport [] [2021-06-29 07:22:47.739610 +0000] D [MSGID: 0] [common-utils.c:545:gf_resolve_ip6] 0-resolver: returning ip-10.0.0.71 (port-24007) for hostname: test-db-beta and port: 24007 [2021-06-29 07:22:47.739618 +0000] D [socket.c:3291:socket_fix_ssl_opts] 0-gv-zfs-common-client-2: disabling SSL for portmapper connection [2021-06-29 07:22:47.739629 +0000] D [rpc-clnt-ping.c:96:rpc_clnt_remove_ping_timer_locked] (--> /lib/x86_64-linux-gnu/libglusterfs.so.0(_gf_log_callingfn+0x131)[0x7f774b3dcca1] (--> /lib/x86_64-linux-gnu/libgfrpc.so.0(+0x130e7)[0x7f774b3850e7] (--> /lib/x86_64-linux-gnu/libgfrpc.so.0(+0x138cd)[0x7f774b3858cd] (--> /lib/x86_64-linux-gnu/libgfrpc.so.0(rpc_clnt_submit+0x323)[0x7f774b381b43] (--> /usr/lib/x86_64-linux-gnu/glusterfs/9.0/xlator/protocol/client.so(+0x1598d)[0x7f774089e98d] ))))) 0-: 10.0.0.74:24007: ping timer event already removed Final graph: +------------------------------------------------------------------------------+ 1: volume gv-zfs-common-client-0 2: type protocol/client 3: option ping-timeout 42 4: option remote-host test-host-alpha [2021-06-29 07:22:47.739667 +0000] D [socket.c:2963:socket_event_handler] 0-transport: EPOLLERR - disconnecting (sock:16) (non-SSL) 5: option remote-subvolume /data1/glusterfs-storage/common 6: option transport-type socket 7: option transport.address-family inet 8: option transport.socket.ssl-enabled off 9: option transport.tcp-user-timeout 0 10: option transport.socket.keepalive-time 20 11: option transport.socket.keepalive-interval 2 12: option transport.socket.keepalive-count 9 13: option strict-locks off 14: option send-gids true 15: end-volume 16: 17: volume gv-zfs-common-client-1 18: type protocol/client 19: option ping-timeout 42 20: option remote-host test-host-beta 21: option remote-subvolume /data1/glusterfs-storage/common 22: option transport-type socket 23: option transport.address-family inet 24: option transport.socket.ssl-enabled off 25: option transport.tcp-user-timeout 0 26: option transport.socket.keepalive-time 20 27: option transport.socket.keepalive-interval 2 28: option transport.socket.keepalive-count 9 29: option strict-locks off 30: option send-gids true 31: end-volume 32: 33: volume gv-zfs-common-client-2 34: type protocol/client 35: option ping-timeout 42 36: option remote-host test-db-beta 37: option remote-subvolume /data/glusterfs-storage-arbiter/common 38: option transport-type socket 39: option transport.address-family inet 40: option transport.socket.ssl-enabled off 41: option transport.tcp-user-timeout 0 42: option transport.socket.keepalive-time 20 43: option transport.socket.keepalive-interval 2 44: option transport.socket.keepalive-count 9 45: option strict-locks off 46: option send-gids true 47: end-volume 48: 49: volume gv-zfs-common-replicate-0 50: type cluster/replicate 51: option afr-pending-xattr gv-zfs-common-client-0,gv-zfs-common-client-1,gv-zfs-common-client-2 52: option volume-id d7f664e3-d59f-4187-be90-f31da7732493 53: option arbiter-count 1 54: option granular-entry-heal on 55: option use-compound-fops off 56: option use-anonymous-inode yes [2021-06-29 07:22:47.739839 +0000] D [MSGID: 0] [client.c:2220:client_rpc_notify] 0-gv-zfs-common-client-1: got RPC_CLNT_DISCONNECT 57: subvolumes gv-zfs-common-client-0 gv-zfs-common-client-1 gv-zfs-common-client-2 58: end-volume 59: 60: volume gv-zfs-common-dht 61: type cluster/distribute 62: option lock-migration off 63: option force-migration off 64: subvolumes gv-zfs-common-replicate-0 65: end-volume 66: 67: volume gv-zfs-common-utime 68: type features/utime 69: option noatime on 70: subvolumes gv-zfs-common-dht 71: end-volume 72: 73: volume gv-zfs-common-write-behind 74: type performance/write-behind 75: subvolumes gv-zfs-common-utime 76: end-volume 77: 78: volume gv-zfs-common-open-behind 79: type performance/open-behind 80: subvolumes gv-zfs-common-write-behind 81: end-volume 82: 83: volume gv-zfs-common-quick-read 84: type performance/quick-read 85: subvolumes gv-zfs-common-open-behind 86: end-volume 87: 88: volume gv-zfs-common-md-cache 89: type performance/md-cache 90: subvolumes gv-zfs-common-quick-read 91: end-volume 92: 93: volume gv-zfs-common 94: type debug/io-stats 95: option log-level DEBUG 96: option threads 16 97: option latency-measurement off 98: option count-fop-hits off 99: option global-threading off 100: subvolumes gv-zfs-common-md-cache 101: end-volume 102: 103: volume meta-autoload 104: type meta 105: subvolumes gv-zfs-common 106: end-volume 107: +------------------------------------------------------------------------------+ [2021-06-29 07:22:47.740181 +0000] E [MSGID: 108006] [afr-common.c:6146:__afr_handle_child_down_event] 0-gv-zfs-common-replicate-0: All subvolumes are down. Going offline until at least one of them comes back up. [2021-06-29 07:22:47.740222 +0000] D [MSGID: 0] [client-handshake.c:1150:server_has_portmap] 0-gv-zfs-common-client-0: detected portmapper on server [2021-06-29 07:22:47.740254 +0000] D [MSGID: 0] [client.c:2211:client_rpc_notify] 0-gv-zfs-common-client-2: got RPC_CLNT_CONNECT [2021-06-29 07:22:47.740388 +0000] D [rpc-clnt-ping.c:96:rpc_clnt_remove_ping_timer_locked] (--> /lib/x86_64-linux-gnu/libglusterfs.so.0(_gf_log_callingfn+0x131)[0x7f774b3dcca1] (--> /lib/x86_64-linux-gnu/libgfrpc.so.0(+0x130e7)[0x7f774b3850e7] (--> /lib/x86_64-linux-gnu/libgfrpc.so.0(+0x138cd)[0x7f774b3858cd] (--> /lib/x86_64-linux-gnu/libgfrpc.so.0(rpc_clnt_submit+0x323)[0x7f774b381b43] (--> /usr/lib/x86_64-linux-gnu/glusterfs/9.0/xlator/protocol/client.so(+0x1598d)[0x7f774089e98d] ))))) 0-: : ping timer event already removed [2021-06-29 07:22:47.740400 +0000] D [rpc-clnt-ping.c:96:rpc_clnt_remove_ping_timer_locked] (--> /lib/x86_64-linux-gnu/libglusterfs.so.0(_gf_log_callingfn+0x131)[0x7f774b3dcca1] (--> /lib/x86_64-linux-gnu/libgfrpc.so.0(+0x130e7)[0x7f774b3850e7] (--> /lib/x86_64-linux-gnu/libgfrpc.so.0(+0x138cd)[0x7f774b3858cd] (--> /lib/x86_64-linux-gnu/libgfrpc.so.0(rpc_clnt_submit+0x323)[0x7f774b381b43] (--> /usr/lib/x86_64-linux-gnu/glusterfs/9.0/xlator/protocol/client.so(+0x1598d)[0x7f774089e98d] ))))) 0-: 10.0.0.71:24007: ping timer event already removed [2021-06-29 07:22:47.740419 +0000] D [rpc-clnt-ping.c:195:rpc_clnt_ping_cbk] 0-gv-zfs-common-client-0: Ping latency is 0ms [2021-06-29 07:22:47.740439 +0000] I [rpc-clnt.c:1968:rpc_clnt_reconfig] 0-gv-zfs-common-client-0: changing port to 49152 (from 0) [2021-06-29 07:22:47.740453 +0000] I [socket.c:849:__socket_shutdown] 0-gv-zfs-common-client-0: intentional socket shutdown(15) [2021-06-29 07:22:47.740465 +0000] D [socket.c:2963:socket_event_handler] 0-transport: EPOLLERR - disconnecting (sock:15) (non-SSL) [2021-06-29 07:22:47.740474 +0000] D [MSGID: 0] [client.c:2220:client_rpc_notify] 0-gv-zfs-common-client-0: got RPC_CLNT_DISCONNECT [2021-06-29 07:22:47.740482 +0000] D [MSGID: 0] [client.c:2275:client_rpc_notify] 0-gv-zfs-common-client-0: disconnected (skipped notify) [2021-06-29 07:22:47.740498 +0000] D [MSGID: 0] [client-handshake.c:1150:server_has_portmap] 0-gv-zfs-common-client-2: detected portmapper on server [2021-06-29 07:22:47.740544 +0000] D [rpc-clnt-ping.c:195:rpc_clnt_ping_cbk] 0-gv-zfs-common-client-2: Ping latency is 0ms [2021-06-29 07:22:47.740587 +0000] D [MSGID: 0] [common-utils.c:545:gf_resolve_ip6] 0-resolver: returning ip-10.0.0.74 (port-24007) for hostname: test-host-alpha and port: 24007 [2021-06-29 07:22:47.740613 +0000] I [rpc-clnt.c:1968:rpc_clnt_reconfig] 0-gv-zfs-common-client-2: changing port to 49152 (from 0) [2021-06-29 07:22:47.740623 +0000] I [socket.c:849:__socket_shutdown] 0-gv-zfs-common-client-2: intentional socket shutdown(17) [2021-06-29 07:22:47.740633 +0000] D [socket.c:2963:socket_event_handler] 0-transport: EPOLLERR - disconnecting (sock:17) (non-SSL) [2021-06-29 07:22:47.740640 +0000] D [MSGID: 0] [client.c:2220:client_rpc_notify] 0-gv-zfs-common-client-2: got RPC_CLNT_DISCONNECT [2021-06-29 07:22:47.740648 +0000] D [MSGID: 0] [client.c:2275:client_rpc_notify] 0-gv-zfs-common-client-2: disconnected (skipped notify) [2021-06-29 07:22:47.740704 +0000] D [MSGID: 0] [client.c:2211:client_rpc_notify] 0-gv-zfs-common-client-0: got RPC_CLNT_CONNECT [2021-06-29 07:22:47.740758 +0000] D [MSGID: 0] [common-utils.c:545:gf_resolve_ip6] 0-resolver: returning ip-10.0.0.71 (port-24007) for hostname: test-db-beta and port: 24007 [2021-06-29 07:22:47.740802 +0000] D [rpc-clnt-ping.c:96:rpc_clnt_remove_ping_timer_locked] (--> /lib/x86_64-linux-gnu/libglusterfs.so.0(_gf_log_callingfn+0x131)[0x7f774b3dcca1] (--> /lib/x86_64-linux-gnu/libgfrpc.so.0(+0x130e7)[0x7f774b3850e7] (--> /lib/x86_64-linux-gnu/libgfrpc.so.0(+0x138cd)[0x7f774b3858cd] (--> /lib/x86_64-linux-gnu/libgfrpc.so.0(rpc_clnt_submit+0x323)[0x7f774b381b43] (--> /usr/lib/x86_64-linux-gnu/glusterfs/9.0/xlator/protocol/client.so(+0x1598d)[0x7f774089e98d] ))))) 0-: 10.0.0.74:49152: ping timer event already removed [2021-06-29 07:22:47.740912 +0000] I [MSGID: 114057] [client-handshake.c:1128:select_server_supported_programs] 0-gv-zfs-common-client-0: Using Program [{Program-name=GlusterFS 4.x v1}, {Num=1298437}, {Version=400}] [2021-06-29 07:22:47.740940 +0000] D [rpc-clnt-ping.c:195:rpc_clnt_ping_cbk] 0-gv-zfs-common-client-0: Ping latency is 0ms [2021-06-29 07:22:47.740962 +0000] D [MSGID: 0] [client.c:2211:client_rpc_notify] 0-gv-zfs-common-client-2: got RPC_CLNT_CONNECT [2021-06-29 07:22:47.741052 +0000] D [rpc-clnt-ping.c:96:rpc_clnt_remove_ping_timer_locked] (--> /lib/x86_64-linux-gnu/libglusterfs.so.0(_gf_log_callingfn+0x131)[0x7f774b3dcca1] (--> /lib/x86_64-linux-gnu/libgfrpc.so.0(+0x130e7)[0x7f774b3850e7] (--> /lib/x86_64-linux-gnu/libgfrpc.so.0(+0x138cd)[0x7f774b3858cd] (--> /lib/x86_64-linux-gnu/libgfrpc.so.0(rpc_clnt_submit+0x323)[0x7f774b381b43] (--> /usr/lib/x86_64-linux-gnu/glusterfs/9.0/xlator/protocol/client.so(+0x1598d)[0x7f774089e98d] ))))) 0-: 10.0.0.71:49152: ping timer event already removed [2021-06-29 07:22:47.741294 +0000] I [MSGID: 114057] [client-handshake.c:1128:select_server_supported_programs] 0-gv-zfs-common-client-2: Using Program [{Program-name=GlusterFS 4.x v1}, {Num=1298437}, {Version=400}] [2021-06-29 07:22:47.741358 +0000] D [rpc-clnt-ping.c:195:rpc_clnt_ping_cbk] 0-gv-zfs-common-client-2: Ping latency is 0ms [2021-06-29 07:22:47.741742 +0000] I [MSGID: 114046] [client-handshake.c:857:client_setvolume_cbk] 0-gv-zfs-common-client-0: Connected, attached to remote volume [{conn-name=gv-zfs-common-client-0}, {remote_subvol=/data1/glusterfs-storage/common}] [2021-06-29 07:22:47.741752 +0000] D [MSGID: 0] [client-handshake.c:677:client_post_handshake] 0-gv-zfs-common-client-0: No fds to open - notifying all parents child up [2021-06-29 07:22:47.741761 +0000] D [MSGID: 0] [afr-common.c:5981:afr_get_halo_latency] 0-gv-zfs-common-replicate-0: Using halo latency 5 [2021-06-29 07:22:47.741769 +0000] I [MSGID: 108005] [afr-common.c:6068:__afr_handle_child_up_event] 0-gv-zfs-common-replicate-0: Subvolume 'gv-zfs-common-client-0' came back up; going online. [2021-06-29 07:22:47.741872 +0000] D [MSGID: 0] [stack.h:510:copy_frame] 0-stack: groups is null (ngrps: 0) [Invalid argument] [2021-06-29 07:22:47.742300 +0000] I [MSGID: 114046] [client-handshake.c:857:client_setvolume_cbk] 0-gv-zfs-common-client-2: Connected, attached to remote volume [{conn-name=gv-zfs-common-client-2}, {remote_subvol=/data/glusterfs-storage-arbiter/common}] [2021-06-29 07:22:47.742311 +0000] D [MSGID: 0] [client-handshake.c:677:client_post_handshake] 0-gv-zfs-common-client-2: No fds to open - notifying all parents child up [2021-06-29 07:22:47.742319 +0000] D [MSGID: 0] [afr-common.c:5981:afr_get_halo_latency] 0-gv-zfs-common-replicate-0: Using halo latency 5 [2021-06-29 07:22:47.742381 +0000] I [MSGID: 108002] [afr-common.c:6438:afr_notify] 0-gv-zfs-common-replicate-0: Client-quorum is met [2021-06-29 07:22:47.742404 +0000] D [MSGID: 0] [stack.h:510:copy_frame] 0-stack: groups is null (ngrps: 0) [Invalid argument] [2021-06-29 07:22:47.742691 +0000] D [MSGID: 0] [dht-diskusage.c:90:dht_du_info_cbk] 0-gv-zfs-common-dht: subvolume 'gv-zfs-common-replicate-0': avail_percent is: 98.00 and avail_space is: 9700331356160 and avail_inodes is: 99.00 [2021-06-29 07:22:47.743769 +0000] D [MSGID: 0] [client-rpc-fops_v2.c:917:client4_0_getxattr_cbk] 0-gv-zfs-common-client-0: resetting op_ret to 0 from 92 [2021-06-29 07:22:47.744037 +0000] D [MSGID: 0] [glfs-resolve.c:49:glfs_first_lookup_safe] 0-meta-autoload: first lookup complete 0 [2021-06-29 07:22:47.744063 +0000] I [MSGID: 104041] [glfs-resolve.c:974:__glfs_active_subvol] 0-gv-zfs-common: switched to graph [{subvol=66767473-2d68-6f73-742d-636e2d626574}, {id=0}] [2021-06-29 07:22:47.744412 +0000] D [MSGID: 0] [client-rpc-fops_v2.c:917:client4_0_getxattr_cbk] 0-gv-zfs-common-client-2: resetting op_ret to 0 from 103 [2021-06-29 07:22:47.745630 +0000] D [MSGID: 0] [afr-transaction.c:2035:afr_post_nonblocking_lock_cbk] 0-gv-zfs-common-replicate-0: Non blocking locks done. Proceeding to FOP [2021-06-29 07:22:47.745647 +0000] D [MSGID: 101016] [glusterfs3.h:781:dict_to_xdr] 0-dict: key 'trusted.afr.dirty' would not be sent on wire in the future [Invalid argument] [2021-06-29 07:22:47.745657 +0000] D [MSGID: 101016] [glusterfs3.h:781:dict_to_xdr] 0-dict: key 'trusted.afr.gv-zfs-common-client-2' would not be sent on wire in the future [Invalid argument] [2021-06-29 07:22:47.745665 +0000] D [MSGID: 101016] [glusterfs3.h:781:dict_to_xdr] 0-dict: key 'trusted.afr.gv-zfs-common-client-1' would not be sent on wire in the future [Invalid argument] [2021-06-29 07:22:47.745672 +0000] D [MSGID: 101016] [glusterfs3.h:781:dict_to_xdr] 0-dict: key 'trusted.afr.gv-zfs-common-client-0' would not be sent on wire in the future [Invalid argument] [2021-06-29 07:22:47.745689 +0000] D [MSGID: 101016] [glusterfs3.h:781:dict_to_xdr] 0-dict: key 'trusted.afr.dirty' would not be sent on wire in the future [Invalid argument] [2021-06-29 07:22:47.745699 +0000] D [MSGID: 101016] [glusterfs3.h:781:dict_to_xdr] 0-dict: key 'trusted.afr.gv-zfs-common-client-2' would not be sent on wire in the future [Invalid argument] [2021-06-29 07:22:47.745706 +0000] D [MSGID: 101016] [glusterfs3.h:781:dict_to_xdr] 0-dict: key 'trusted.afr.gv-zfs-common-client-1' would not be sent on wire in the future [Invalid argument] [2021-06-29 07:22:47.745712 +0000] D [MSGID: 101016] [glusterfs3.h:781:dict_to_xdr] 0-dict: key 'trusted.afr.gv-zfs-common-client-0' would not be sent on wire in the future [Invalid argument] [2021-06-29 07:22:47.746041 +0000] D [MSGID: 0] [client-rpc-fops_v2.c:1603:client4_0_fxattrop_cbk] 0-gv-zfs-common-client-0: resetting op_ret to 0 from 0 [2021-06-29 07:22:47.746430 +0000] D [MSGID: 0] [client-rpc-fops_v2.c:1603:client4_0_fxattrop_cbk] 0-gv-zfs-common-client-2: resetting op_ret to 0 from 0 [2021-06-29 07:22:47.746957 +0000] D [MSGID: 101016] [glusterfs3.h:781:dict_to_xdr] 0-dict: key 'trusted.afr.dirty' would not be sent on wire in the future [Invalid argument] [2021-06-29 07:22:47.746966 +0000] D [MSGID: 101016] [glusterfs3.h:781:dict_to_xdr] 0-dict: key 'trusted.afr.gv-zfs-common-client-2' would not be sent on wire in the future [Invalid argument] [2021-06-29 07:22:47.746970 +0000] D [MSGID: 0] [afr-read-txn.c:455:afr_read_txn] 0-gv-zfs-common-replicate-0: a95f57c6-5e98-4667-a725-a427e163ac60: generation now vs cached: 2, 2 [2021-06-29 07:22:47.746974 +0000] D [MSGID: 101016] [glusterfs3.h:781:dict_to_xdr] 0-dict: key 'trusted.afr.gv-zfs-common-client-1' would not be sent on wire in the future [Invalid argument] [2021-06-29 07:22:47.746988 +0000] D [MSGID: 101016] [glusterfs3.h:781:dict_to_xdr] 0-dict: key 'trusted.afr.gv-zfs-common-client-0' would not be sent on wire in the future [Invalid argument] [2021-06-29 07:22:47.747010 +0000] D [MSGID: 101016] [glusterfs3.h:781:dict_to_xdr] 0-dict: key 'trusted.afr.dirty' would not be sent on wire in the future [Invalid argument] [2021-06-29 07:22:47.747020 +0000] D [MSGID: 101016] [glusterfs3.h:781:dict_to_xdr] 0-dict: key 'trusted.afr.gv-zfs-common-client-2' would not be sent on wire in the future [Invalid argument] [2021-06-29 07:22:47.747027 +0000] D [MSGID: 101016] [glusterfs3.h:781:dict_to_xdr] 0-dict: key 'trusted.afr.gv-zfs-common-client-1' would not be sent on wire in the future [Invalid argument] [2021-06-29 07:22:47.747034 +0000] D [MSGID: 101016] [glusterfs3.h:781:dict_to_xdr] 0-dict: key 'trusted.afr.gv-zfs-common-client-0' would not be sent on wire in the future [Invalid argument] [2021-06-29 07:22:47.747481 +0000] D [MSGID: 0] [client-rpc-fops_v2.c:1603:client4_0_fxattrop_cbk] 0-gv-zfs-common-client-0: resetting op_ret to 0 from 0 [2021-06-29 07:22:47.747898 +0000] D [MSGID: 0] [client-rpc-fops_v2.c:1603:client4_0_fxattrop_cbk] 0-gv-zfs-common-client-2: resetting op_ret to 0 from 0 [2021-06-29 07:22:47.747925 +0000] D [write-behind.c:1765:wb_process_queue] (--> /lib/x86_64-linux-gnu/libglusterfs.so.0(_gf_log_callingfn+0x131)[0x7f774b3dcca1] (--> /usr/lib/x86_64-linux-gnu/glusterfs/9.0/xlator/performance/write-behind.so(+0xaabc)[0x7f7740708abc] (--> /usr/lib/x86_64-linux-gnu/glusterfs/9.0/xlator/performance/write-behind.so(+0xd293)[0x7f774070b293] (--> /lib/x86_64-linux-gnu/libglusterfs.so.0(default_ftruncate+0xc6)[0x7f774b466416] (--> /usr/lib/x86_64-linux-gnu/glusterfs/9.0/xlator/performance/open-behind.so(+0x6074)[0x7f77406f4074] ))))) 0-gv-zfs-common-write-behind: processing queues [2021-06-29 07:22:47.747941 +0000] D [MSGID: 0] [write-behind.c:1717:__wb_pick_winds] 0-gv-zfs-common-write-behind: (unique=23, fop=FTRUNCATE, gfid=a95f57c6-5e98-4667-a725-a427e163ac60, gen=0): picking the request for winding [2021-06-29 07:22:47.748018 +0000] D [write-behind.c:419:__wb_request_unref] (--> /lib/x86_64-linux-gnu/libglusterfs.so.0(_gf_log_callingfn+0x131)[0x7f774b3dcca1] (--> /usr/lib/x86_64-linux-gnu/glusterfs/9.0/xlator/performance/write-behind.so(+0x368a)[0x7f774070168a] (--> /usr/lib/x86_64-linux-gnu/glusterfs/9.0/xlator/performance/write-behind.so(+0x62a9)[0x7f77407042a9] (--> /usr/lib/x86_64-linux-gnu/glusterfs/9.0/xlator/performance/write-behind.so(+0xa940)[0x7f7740708940] (--> /usr/lib/x86_64-linux-gnu/glusterfs/9.0/xlator/performance/write-behind.so(+0xaa6d)[0x7f7740708a6d] ))))) 0-gv-zfs-common-write-behind: (unique = 23, fop=FTRUNCATE, gfid=a95f57c6-5e98-4667-a725-a427e163ac60, gen=0): destroying request, removing from all queues [2021-06-29 07:22:47.748880 +0000] D [MSGID: 0] [afr-transaction.c:2035:afr_post_nonblocking_lock_cbk] 0-gv-zfs-common-replicate-0: Non blocking locks done. Proceeding to FOP [2021-06-29 07:22:47.748893 +0000] D [MSGID: 101016] [glusterfs3.h:781:dict_to_xdr] 0-dict: key 'trusted.afr.dirty' would not be sent on wire in the future [Invalid argument] [2021-06-29 07:22:47.748901 +0000] D [MSGID: 101016] [glusterfs3.h:781:dict_to_xdr] 0-dict: key 'trusted.afr.gv-zfs-common-client-2' would not be sent on wire in the future [Invalid argument] [2021-06-29 07:22:47.748909 +0000] D [MSGID: 101016] [glusterfs3.h:781:dict_to_xdr] 0-dict: key 'trusted.afr.gv-zfs-common-client-1' would not be sent on wire in the future [Invalid argument] [2021-06-29 07:22:47.748915 +0000] D [MSGID: 101016] [glusterfs3.h:781:dict_to_xdr] 0-dict: key 'trusted.afr.gv-zfs-common-client-0' would not be sent on wire in the future [Invalid argument] [2021-06-29 07:22:47.748931 +0000] D [MSGID: 101016] [glusterfs3.h:781:dict_to_xdr] 0-dict: key 'trusted.afr.dirty' would not be sent on wire in the future [Invalid argument] [2021-06-29 07:22:47.748939 +0000] D [MSGID: 101016] [glusterfs3.h:781:dict_to_xdr] 0-dict: key 'trusted.afr.gv-zfs-common-client-2' would not be sent on wire in the future [Invalid argument] [2021-06-29 07:22:47.748946 +0000] D [MSGID: 101016] [glusterfs3.h:781:dict_to_xdr] 0-dict: key 'trusted.afr.gv-zfs-common-client-1' would not be sent on wire in the future [Invalid argument] [2021-06-29 07:22:47.748952 +0000] D [MSGID: 101016] [glusterfs3.h:781:dict_to_xdr] 0-dict: key 'trusted.afr.gv-zfs-common-client-0' would not be sent on wire in the future [Invalid argument] [2021-06-29 07:22:47.749276 +0000] D [MSGID: 0] [client-rpc-fops_v2.c:1603:client4_0_fxattrop_cbk] 0-gv-zfs-common-client-0: resetting op_ret to 0 from 0 [2021-06-29 07:22:47.749617 +0000] D [MSGID: 0] [client-rpc-fops_v2.c:1603:client4_0_fxattrop_cbk] 0-gv-zfs-common-client-2: resetting op_ret to 0 from 0 [2021-06-29 07:22:47.750158 +0000] D [MSGID: 101016] [glusterfs3.h:781:dict_to_xdr] 0-dict: key 'trusted.afr.dirty' would not be sent on wire in the future [Invalid argument] [2021-06-29 07:22:47.750168 +0000] D [MSGID: 101016] [glusterfs3.h:781:dict_to_xdr] 0-dict: key 'trusted.afr.gv-zfs-common-client-2' would not be sent on wire in the future [Invalid argument] [2021-06-29 07:22:47.750176 +0000] D [MSGID: 101016] [glusterfs3.h:781:dict_to_xdr] 0-dict: key 'trusted.afr.gv-zfs-common-client-1' would not be sent on wire in the future [Invalid argument] [2021-06-29 07:22:47.750183 +0000] D [MSGID: 101016] [glusterfs3.h:781:dict_to_xdr] 0-dict: key 'trusted.afr.gv-zfs-common-client-0' would not be sent on wire in the future [Invalid argument] [2021-06-29 07:22:47.750200 +0000] D [MSGID: 101016] [glusterfs3.h:781:dict_to_xdr] 0-dict: key 'trusted.afr.dirty' would not be sent on wire in the future [Invalid argument] [2021-06-29 07:22:47.750207 +0000] D [MSGID: 101016] [glusterfs3.h:781:dict_to_xdr] 0-dict: key 'trusted.afr.gv-zfs-common-client-2' would not be sent on wire in the future [Invalid argument] [2021-06-29 07:22:47.750214 +0000] D [MSGID: 101016] [glusterfs3.h:781:dict_to_xdr] 0-dict: key 'trusted.afr.gv-zfs-common-client-1' would not be sent on wire in the future [Invalid argument] [2021-06-29 07:22:47.750221 +0000] D [MSGID: 101016] [glusterfs3.h:781:dict_to_xdr] 0-dict: key 'trusted.afr.gv-zfs-common-client-0' would not be sent on wire in the future [Invalid argument] [2021-06-29 07:22:47.750232 +0000] D [write-behind.c:1765:wb_process_queue] (--> /lib/x86_64-linux-gnu/libglusterfs.so.0(_gf_log_callingfn+0x131)[0x7f774b3dcca1] (--> /usr/lib/x86_64-linux-gnu/glusterfs/9.0/xlator/performance/write-behind.so(+0xaabc)[0x7f7740708abc] (--> /usr/lib/x86_64-linux-gnu/glusterfs/9.0/xlator/performance/write-behind.so(+0xbc38)[0x7f7740709c38] (--> /lib/x86_64-linux-gnu/libglusterfs.so.0(default_flush+0xb6)[0x7f774b4653e6] (--> /usr/lib/x86_64-linux-gnu/glusterfs/9.0/xlator/performance/open-behind.so(+0x6551)[0x7f77406f4551] ))))) 0-gv-zfs-common-write-behind: processing queues [2021-06-29 07:22:47.750245 +0000] D [MSGID: 0] [write-behind.c:1717:__wb_pick_winds] 0-gv-zfs-common-write-behind: (unique=24, fop=FLUSH, gfid=a95f57c6-5e98-4667-a725-a427e163ac60, gen=0): picking the request for winding [2021-06-29 07:22:47.750355 +0000] D [write-behind.c:419:__wb_request_unref] (--> /lib/x86_64-linux-gnu/libglusterfs.so.0(_gf_log_callingfn+0x131)[0x7f774b3dcca1] (--> /usr/lib/x86_64-linux-gnu/glusterfs/9.0/xlator/performance/write-behind.so(+0x368a)[0x7f774070168a] (--> /usr/lib/x86_64-linux-gnu/glusterfs/9.0/xlator/performance/write-behind.so(+0x62a9)[0x7f77407042a9] (--> /usr/lib/x86_64-linux-gnu/glusterfs/9.0/xlator/performance/write-behind.so(+0xa940)[0x7f7740708940] (--> /usr/lib/x86_64-linux-gnu/glusterfs/9.0/xlator/performance/write-behind.so(+0xaa6d)[0x7f7740708a6d] ))))) 0-gv-zfs-common-write-behind: (unique = 24, fop=FLUSH, gfid=a95f57c6-5e98-4667-a725-a427e163ac60, gen=0): destroying request, removing from all queues [2021-06-29 07:22:47.750425 +0000] D [rpc-clnt-ping.c:96:rpc_clnt_remove_ping_timer_locked] (--> /lib/x86_64-linux-gnu/libglusterfs.so.0(_gf_log_callingfn+0x131)[0x7f774b3dcca1] (--> /lib/x86_64-linux-gnu/libgfrpc.so.0(+0x130e7)[0x7f774b3850e7] (--> /lib/x86_64-linux-gnu/libgfrpc.so.0(rpc_clnt_disable+0x96)[0x7f774b3807d6] (--> /lib/x86_64-linux-gnu/libgfapi.so.0(glfs_fini+0x54)[0x7f774b512454] (--> /usr/lib/x86_64-linux-gnu/qemu/block-gluster.so(+0x38b9)[0x7f774cc318b9] ))))) 0-: 10.0.0.74:24007: ping timer event already removed [2021-06-29 07:22:47.750443 +0000] I [socket.c:849:__socket_shutdown] 0-gfapi: intentional socket shutdown(13) [2021-06-29 07:22:47.750456 +0000] D [socket.c:2963:socket_event_handler] 0-transport: EPOLLERR - disconnecting (sock:13) (non-SSL) [2021-06-29 07:22:47.750538 +0000] D [MSGID: 0] [client-rpc-fops_v2.c:1603:client4_0_fxattrop_cbk] 0-gv-zfs-common-client-0: resetting op_ret to 0 from 0 [2021-06-29 07:22:47.750557 +0000] D [rpc-clnt-ping.c:96:rpc_clnt_remove_ping_timer_locked] (--> /lib/x86_64-linux-gnu/libglusterfs.so.0(_gf_log_callingfn+0x131)[0x7f774b3dcca1] (--> /lib/x86_64-linux-gnu/libgfrpc.so.0(+0x130e7)[0x7f774b3850e7] (--> /lib/x86_64-linux-gnu/libgfrpc.so.0(rpc_clnt_connection_cleanup+0x9f)[0x7f774b380bbf] (--> /lib/x86_64-linux-gnu/libgfrpc.so.0(+0xf7d8)[0x7f774b3817d8] (--> /lib/x86_64-linux-gnu/libgfrpc.so.0(rpc_transport_notify+0x23)[0x7f774b37e193] ))))) 0-: 10.0.0.74:24007: ping timer event already removed [2021-06-29 07:22:47.750843 +0000] D [MSGID: 0] [client-rpc-fops_v2.c:1603:client4_0_fxattrop_cbk] 0-gv-zfs-common-client-2: resetting op_ret to 0 from 0 [2021-06-29 07:22:47.850480 +0000] I [MSGID: 114021] [client.c:2326:notify] 0-gv-zfs-common-client-0: current graph is no longer active, destroying rpc_client [] [2021-06-29 07:22:47.850603 +0000] I [timer.c:86:gf_timer_call_cancel] (-->/usr/lib/x86_64-linux-gnu/glusterfs/9.0/xlator/protocol/client.so(+0x12436) [0x7f774089b436] -->/lib/x86_64-linux-gnu/libgfrpc.so.0(rpc_clnt_disable+0x4a) [0x7f774b38078a] -->/lib/x86_64-linux-gnu/libglusterfs.so.0(gf_timer_call_cancel+0x12f) [0x7f774b3e926f] ) 0-timer: ctx cleanup started [2021-06-29 07:22:47.850681 +0000] I [timer.c:86:gf_timer_call_cancel] (-->/usr/lib/x86_64-linux-gnu/glusterfs/9.0/xlator/protocol/client.so(+0x12436) [0x7f774089b436] -->/lib/x86_64-linux-gnu/libgfrpc.so.0(rpc_clnt_disable+0x76) [0x7f774b3807b6] -->/lib/x86_64-linux-gnu/libglusterfs.so.0(gf_timer_call_cancel+0x12f) [0x7f774b3e926f] ) 0-timer: ctx cleanup started [2021-06-29 07:22:47.850749 +0000] I [timer.c:86:gf_timer_call_cancel] (-->/lib/x86_64-linux-gnu/libgfrpc.so.0(rpc_clnt_disable+0x96) [0x7f774b3807d6] -->/lib/x86_64-linux-gnu/libgfrpc.so.0(+0x13107) [0x7f774b385107] -->/lib/x86_64-linux-gnu/libglusterfs.so.0(gf_timer_call_cancel+0x12f) [0x7f774b3e926f] ) 0-timer: ctx cleanup started [2021-06-29 07:22:47.850796 +0000] I [MSGID: 114021] [client.c:2326:notify] 0-gv-zfs-common-client-1: current graph is no longer active, destroying rpc_client [] [2021-06-29 07:22:47.850819 +0000] D [socket.c:2963:socket_event_handler] 0-transport: EPOLLERR - disconnecting (sock:14) (non-SSL) [2021-06-29 07:22:47.850857 +0000] I [timer.c:86:gf_timer_call_cancel] (-->/usr/lib/x86_64-linux-gnu/glusterfs/9.0/xlator/protocol/client.so(+0x12436) [0x7f774089b436] -->/lib/x86_64-linux-gnu/libgfrpc.so.0(rpc_clnt_disable+0x76) [0x7f774b3807b6] -->/lib/x86_64-linux-gnu/libglusterfs.so.0(gf_timer_call_cancel+0x12f) [0x7f774b3e926f] ) 0-timer: ctx cleanup started [2021-06-29 07:22:47.850854 +0000] D [MSGID: 0] [client.c:2220:client_rpc_notify] 0-gv-zfs-common-client-0: got RPC_CLNT_DISCONNECT [2021-06-29 07:22:47.850911 +0000] I [MSGID: 114018] [client.c:2229:client_rpc_notify] 0-gv-zfs-common-client-0: disconnected from client, process will keep trying to connect glusterd until brick's port is available [{conn-name=gv-zfs-common-client-0}] [2021-06-29 07:22:47.850922 +0000] W [MSGID: 108001] [afr-common.c:6444:afr_notify] 0-gv-zfs-common-replicate-0: Client-quorum is not met [2021-06-29 07:22:47.850991 +0000] D [rpc-clnt-ping.c:96:rpc_clnt_remove_ping_timer_locked] (--> /lib/x86_64-linux-gnu/libglusterfs.so.0(_gf_log_callingfn+0x131)[0x7f774b3dcca1] (--> /lib/x86_64-linux-gnu/libgfrpc.so.0(+0x130e7)[0x7f774b3850e7] (--> /lib/x86_64-linux-gnu/libgfrpc.so.0(rpc_clnt_disable+0x96)[0x7f774b3807d6] (--> /usr/lib/x86_64-linux-gnu/glusterfs/9.0/xlator/protocol/client.so(+0x12436)[0x7f774089b436] (--> /lib/x86_64-linux-gnu/libglusterfs.so.0(xlator_notify+0x34)[0x7f774b3d6d04] ))))) 0-: : ping timer event already removed [2021-06-29 07:22:47.851005 +0000] I [MSGID: 114021] [client.c:2326:notify] 0-gv-zfs-common-client-2: current graph is no longer active, destroying rpc_client [] [2021-06-29 07:22:47.851031 +0000] I [timer.c:86:gf_timer_call_cancel] (-->/usr/lib/x86_64-linux-gnu/glusterfs/9.0/xlator/protocol/client.so(+0x12436) [0x7f774089b436] -->/lib/x86_64-linux-gnu/libgfrpc.so.0(rpc_clnt_disable+0x4a) [0x7f774b38078a] -->/lib/x86_64-linux-gnu/libglusterfs.so.0(gf_timer_call_cancel+0x12f) [0x7f774b3e926f] ) 0-timer: ctx cleanup started [2021-06-29 07:22:47.851061 +0000] I [timer.c:86:gf_timer_call_cancel] (-->/usr/lib/x86_64-linux-gnu/glusterfs/9.0/xlator/protocol/client.so(+0x12436) [0x7f774089b436] -->/lib/x86_64-linux-gnu/libgfrpc.so.0(rpc_clnt_disable+0x76) [0x7f774b3807b6] -->/lib/x86_64-linux-gnu/libglusterfs.so.0(gf_timer_call_cancel+0x12f) [0x7f774b3e926f] ) 0-timer: ctx cleanup started [2021-06-29 07:22:47.851080 +0000] I [timer.c:86:gf_timer_call_cancel] (-->/lib/x86_64-linux-gnu/libgfrpc.so.0(rpc_clnt_disable+0x96) [0x7f774b3807d6] -->/lib/x86_64-linux-gnu/libgfrpc.so.0(+0x13107) [0x7f774b385107] -->/lib/x86_64-linux-gnu/libglusterfs.so.0(gf_timer_call_cancel+0x12f) [0x7f774b3e926f] ) 0-timer: ctx cleanup started [2021-06-29 07:22:47.851087 +0000] D [rpc-clnt-ping.c:96:rpc_clnt_remove_ping_timer_locked] (--> /lib/x86_64-linux-gnu/libglusterfs.so.0(_gf_log_callingfn+0x131)[0x7f774b3dcca1] (--> /lib/x86_64-linux-gnu/libgfrpc.so.0(+0x130e7)[0x7f774b3850e7] (--> /lib/x86_64-linux-gnu/libgfrpc.so.0(rpc_clnt_connection_cleanup+0x9f)[0x7f774b380bbf] (--> /lib/x86_64-linux-gnu/libgfrpc.so.0(+0xf7d8)[0x7f774b3817d8] (--> /lib/x86_64-linux-gnu/libgfrpc.so.0(rpc_transport_notify+0x23)[0x7f774b37e193] ))))) 0-: 10.0.0.74:49152: ping timer event already removed [2021-06-29 07:22:47.851104 +0000] D [socket.c:2963:socket_event_handler] 0-transport: EPOLLERR - disconnecting (sock:15) (non-SSL) [2021-06-29 07:22:47.851117 +0000] D [MSGID: 0] [client.c:2220:client_rpc_notify] 0-gv-zfs-common-client-2: got RPC_CLNT_DISCONNECT [2021-06-29 07:22:47.851131 +0000] I [MSGID: 114018] [client.c:2229:client_rpc_notify] 0-gv-zfs-common-client-2: disconnected from client, process will keep trying to connect glusterd until brick's port is available [{conn-name=gv-zfs-common-client-2}] [2021-06-29 07:22:47.851142 +0000] E [MSGID: 108006] [afr-common.c:6146:__afr_handle_child_down_event] 0-gv-zfs-common-replicate-0: All subvolumes are down. Going offline until at least one of them comes back up. [2021-06-29 07:22:47.851329 +0000] D [rpc-clnt-ping.c:96:rpc_clnt_remove_ping_timer_locked] (--> /lib/x86_64-linux-gnu/libglusterfs.so.0(_gf_log_callingfn+0x131)[0x7f774b3dcca1] (--> /lib/x86_64-linux-gnu/libgfrpc.so.0(+0x130e7)[0x7f774b3850e7] (--> /lib/x86_64-linux-gnu/libgfrpc.so.0(rpc_clnt_connection_cleanup+0x9f)[0x7f774b380bbf] (--> /usr/lib/x86_64-linux-gnu/glusterfs/9.0/xlator/protocol/client.so(+0x125a3)[0x7f774089b5a3] (--> /lib/x86_64-linux-gnu/libglusterfs.so.0(+0x24bf6)[0x7f774b3d5bf6] ))))) 0-: 10.0.0.71:49152: ping timer event already removed [2021-06-29 07:22:47.851337 +0000] D [rpc-clnt-ping.c:96:rpc_clnt_remove_ping_timer_locked] (--> /lib/x86_64-linux-gnu/libglusterfs.so.0(_gf_log_callingfn+0x131)[0x7f774b3dcca1] (--> /lib/x86_64-linux-gnu/libgfrpc.so.0(+0x130e7)[0x7f774b3850e7] (--> /lib/x86_64-linux-gnu/libgfrpc.so.0(rpc_clnt_connection_cleanup+0x9f)[0x7f774b380bbf] (--> /usr/lib/x86_64-linux-gnu/glusterfs/9.0/xlator/protocol/client.so(+0x125a3)[0x7f774089b5a3] (--> /lib/x86_64-linux-gnu/libglusterfs.so.0(+0x24bf6)[0x7f774b3d5bf6] ))))) 0-: 10.0.0.74:49152: ping timer event already removed [2021-06-29 07:22:57.741129 +0000] D [rpc-clnt-ping.c:96:rpc_clnt_remove_ping_timer_locked] (--> /lib/x86_64-linux-gnu/libglusterfs.so.0(_gf_log_callingfn+0x131)[0x7f774b3dcca1] (--> /lib/x86_64-linux-gnu/libgfrpc.so.0(+0x130e7)[0x7f774b3850e7] (--> /lib/x86_64-linux-gnu/libgfrpc.so.0(rpc_clnt_disable+0x96)[0x7f774b3807d6] (--> /lib/x86_64-linux-gnu/libgfrpc.so.0(rpc_clnt_unref+0x3c)[0x7f774b38089c] (--> /lib/x86_64-linux-gnu/libgfrpc.so.0(+0x10408)[0x7f774b382408] ))))) 0-: 10.0.0.74:49152: ping timer event already removed [2021-06-29 07:22:57.741190 +0000] D [MSGID: 0] [xlator.c:672:xlator_fini_rec] 0-gv-zfs-common-client-0: fini done [2021-06-29 07:22:57.741515 +0000] D [rpc-clnt-ping.c:96:rpc_clnt_remove_ping_timer_locked] (--> /lib/x86_64-linux-gnu/libglusterfs.so.0(_gf_log_callingfn+0x131)[0x7f774b3dcca1] (--> /lib/x86_64-linux-gnu/libgfrpc.so.0(+0x130e7)[0x7f774b3850e7] (--> /lib/x86_64-linux-gnu/libgfrpc.so.0(rpc_clnt_connection_cleanup+0x9f)[0x7f774b380bbf] (--> /usr/lib/x86_64-linux-gnu/glusterfs/9.0/xlator/protocol/client.so(+0x125a3)[0x7f774089b5a3] (--> /lib/x86_64-linux-gnu/libglusterfs.so.0(+0x24bf6)[0x7f774b3d5bf6] ))))) 0-: : ping timer event already removed [2021-06-29 07:22:57.741697 +0000] D [rpc-clnt-ping.c:96:rpc_clnt_remove_ping_timer_locked] (--> /lib/x86_64-linux-gnu/libglusterfs.so.0(_gf_log_callingfn+0x131)[0x7f774b3dcca1] (--> /lib/x86_64-linux-gnu/libgfrpc.so.0(+0x130e7)[0x7f774b3850e7] (--> /lib/x86_64-linux-gnu/libgfrpc.so.0(rpc_clnt_disable+0x96)[0x7f774b3807d6] (--> /lib/x86_64-linux-gnu/libgfrpc.so.0(rpc_clnt_unref+0x3c)[0x7f774b38089c] (--> /usr/lib/x86_64-linux-gnu/glusterfs/9.0/xlator/protocol/client.so(+0x125ab)[0x7f774089b5ab] ))))) 0-: : ping timer event already removed [2021-06-29 07:22:57.741740 +0000] D [MSGID: 0] [xlator.c:672:xlator_fini_rec] 0-gv-zfs-common-client-1: fini done [2021-06-29 07:22:57.741921 +0000] D [rpc-clnt-ping.c:96:rpc_clnt_remove_ping_timer_locked] (--> /lib/x86_64-linux-gnu/libglusterfs.so.0(_gf_log_callingfn+0x131)[0x7f774b3dcca1] (--> /lib/x86_64-linux-gnu/libgfrpc.so.0(+0x130e7)[0x7f774b3850e7] (--> /lib/x86_64-linux-gnu/libgfrpc.so.0(rpc_clnt_connection_cleanup+0x9f)[0x7f774b380bbf] (--> /usr/lib/x86_64-linux-gnu/glusterfs/9.0/xlator/protocol/client.so(+0x125a3)[0x7f774089b5a3] (--> /lib/x86_64-linux-gnu/libglusterfs.so.0(+0x24bf6)[0x7f774b3d5bf6] ))))) 0-: 10.0.0.71:49152: ping timer event already removed [2021-06-29 07:22:57.742074 +0000] D [rpc-clnt-ping.c:96:rpc_clnt_remove_ping_timer_locked] (--> /lib/x86_64-linux-gnu/libglusterfs.so.0(_gf_log_callingfn+0x131)[0x7f774b3dcca1] (--> /lib/x86_64-linux-gnu/libgfrpc.so.0(+0x130e7)[0x7f774b3850e7] (--> /lib/x86_64-linux-gnu/libgfrpc.so.0(rpc_clnt_disable+0x96)[0x7f774b3807d6] (--> /lib/x86_64-linux-gnu/libgfrpc.so.0(rpc_clnt_unref+0x3c)[0x7f774b38089c] (--> /usr/lib/x86_64-linux-gnu/glusterfs/9.0/xlator/protocol/client.so(+0x125ab)[0x7f774089b5ab] ))))) 0-: 10.0.0.71:49152: ping timer event already removed [2021-06-29 07:22:57.742108 +0000] D [MSGID: 0] [xlator.c:672:xlator_fini_rec] 0-gv-zfs-common-client-2: fini done [2021-06-29 07:22:57.742295 +0000] D [MSGID: 0] [xlator.c:672:xlator_fini_rec] 0-gv-zfs-common-replicate-0: fini done [2021-06-29 07:22:57.742328 +0000] D [MSGID: 0] [xlator.c:672:xlator_fini_rec] 0-gv-zfs-common-dht: fini done [2021-06-29 07:22:57.742344 +0000] D [MSGID: 0] [xlator.c:672:xlator_fini_rec] 0-gv-zfs-common-utime: fini done [2021-06-29 07:22:57.742358 +0000] D [MSGID: 0] [xlator.c:672:xlator_fini_rec] 0-gv-zfs-common-write-behind: fini done [2021-06-29 07:22:57.742374 +0000] D [MSGID: 0] [xlator.c:672:xlator_fini_rec] 0-gv-zfs-common-open-behind: fini done [2021-06-29 07:22:57.742389 +0000] D [MSGID: 0] [xlator.c:672:xlator_fini_rec] 0-gv-zfs-common-quick-read: fini done [2021-06-29 07:22:57.742404 +0000] D [MSGID: 0] [xlator.c:672:xlator_fini_rec] 0-gv-zfs-common-md-cache: fini done [2021-06-29 07:22:57.742433 +0000] I [io-stats.c:4038:fini] 0-gv-zfs-common: io-stats translator unloaded [2021-06-29 07:22:57.742449 +0000] D [MSGID: 0] [xlator.c:672:xlator_fini_rec] 0-gv-zfs-common: fini done [2021-06-29 07:22:57.742562 +0000] I [MSGID: 101191] [event-epoll.c:735:event_dispatch_epoll_worker] 0-epoll: Exited thread [{index=2}] [2021-06-29 07:22:57.742574 +0000] I [MSGID: 101191] [event-epoll.c:735:event_dispatch_epoll_worker] 0-epoll: Exited thread [{index=1}] [2021-06-29 07:22:58.742587 +0000] D [MSGID: 0] [event.c:279:gf_event_dispatch_destroy] 0-event: thread cond-timedwait failed active-thread-count: 0, retry: 3 [2021-06-29 07:22:58.742828 +0000] D [rpc-clnt-ping.c:96:rpc_clnt_remove_ping_timer_locked] (--> /lib/x86_64-linux-gnu/libglusterfs.so.0(_gf_log_callingfn+0x131)[0x7f774b3dcca1] (--> /lib/x86_64-linux-gnu/libgfrpc.so.0(+0x130e7)[0x7f774b3850e7] (--> /lib/x86_64-linux-gnu/libgfrpc.so.0(rpc_clnt_disable+0x96)[0x7f774b3807d6] (--> /lib/x86_64-linux-gnu/libgfrpc.so.0(rpc_clnt_unref+0x3c)[0x7f774b38089c] (--> /lib/x86_64-linux-gnu/libgfapi.so.0(glfs_fini+0x18a)[0x7f774b51258a] ))))) 0-: 10.0.0.74:24007: ping timer event already removed [2021-06-29 07:22:58.742959 +0000] D [logging.c:1669:gf_log_flush_extra_msgs] 0-logging-infra: Log buffer size reduced. About to flush 5 extra log messages [2021-06-29 07:22:58.742981 +0000] D [logging.c:1672:gf_log_flush_extra_msgs] 0-logging-infra: Just flushed 5 extra log messages [2021-06-29 07:22:58.743124 +0000] I [timer.c:86:gf_timer_call_cancel] (-->/lib/x86_64-linux-gnu/libglusterfs.so.0(gf_log_fini+0x15) [0x7f774b3dd975] -->/lib/x86_64-linux-gnu/libglusterfs.so.0(gf_log_disable_suppression_before_exit+0x33) [0x7f774b3dd943] -->/lib/x86_64-linux-gnu/libglusterfs.so.0(gf_timer_call_cancel+0x12f) [0x7f774b3e926f] ) 0-timer: ctx cleanup started ``` **Mandatory info:** **- The output of the `gluster volume info` command**: ``` ~# gluster volume info Volume Name: gv-zfs-common Type: Replicate Volume ID: d7f664e3-d59f-4187-be90-f31da7732493 Status: Started Snapshot Count: 0 Number of Bricks: 1 x (2 + 1) = 3 Transport-type: tcp Bricks: Brick1: test-host-alpha:/data1/glusterfs-storage/common Brick2: test-host-beta:/data1/glusterfs-storage/common Brick3: test-other-beta:/data/glusterfs-storage-arbiter/common (arbiter) Options Reconfigured: diagnostics.client-log-level: DEBUG cluster.granular-entry-heal: on storage.fips-mode-rchecksum: on transport.address-family: inet nfs.disable: on performance.client-io-threads: off ``` **- The output of the `gluster volume status` command**: ``` ~# gluster volume status Status of volume: gv-zfs-common Gluster process TCP Port RDMA Port Online Pid ------------------------------------------------------------------------------ Brick test-host-alpha:/d ata1/glusterfs-storage/common 49152 0 Y 37747 Brick test-host-beta:/da ta1/glusterfs-storage/common 49152 0 Y 45174 Brick test-other-beta:/data /glusterfs-storage-arbiter/common 49152 0 Y 11144 Self-heal Daemon on localhost N/A N/A Y 37764 Self-heal Daemon on test-host-beta N/A N/A Y 45191 Self-heal Daemon on test-other-beta N/A N/A Y 11161 Task Status of Volume gv-zfs-common ------------------------------------------------------------------------------ There are no active volume tasks ``` **Additional info:**

- The operating system / glusterfs version:

Debian 10 GlusterFS 9.0 cluster (all packages are 9.0) GlusterFS 9.2 cluster (all packages are 9.2)

Note: Please hide any confidential data which you don't want to share in public like IP address, file name, hostname or any other configuration

wxiaoguang commented 3 years ago

More information is discussed in https://github.com/gluster/glusterfs/issues/2606, I think these issues are highly related.

(And other issues: https://github.com/gluster/glusterfs/issues/1962)

Shahrokh-Af commented 3 years ago

Hello Mr @wxiaoguang

in the current state, we tested this problem with these environments and we have the same issue :

Distributor ID: Ubuntu Description: Ubuntu 20.04.2 LTS Release: 20.04 Codename: focal glusterfs version : 9.0 9.02 9.03 qemu-img version 5.2.0

ubuntu@Node-4:~$ sudo qemu-img create  gluster://storage-master-3/gv0/testimage.img 1G
Formatting 'gluster://storage-master-3/gv0/testimage.img', fmt=raw size=1073741824
[2021-07-11 15:50:55.887803 +0000] I [io-stats.c:3706:ios_sample_buf_size_configure] 0-gv0: Configure ios_sample_buf  size is 1024 because ios_sample_interval is 0
[2021-07-11 15:50:56.009168 +0000] E [MSGID: 108006] [afr-common.c:6140:__afr_handle_child_down_event] 0-gv0-replicate-0: All subvolumes are down. Going offline until at least one of them comes back up.
[2021-07-11 15:51:05.896412 +0000] I [io-stats.c:4038:fini] 0-gv0: io-stats translator unloaded

Distributor ID: Debian Description: Debian GNU/Linux 10 (buster) Release: 10 Codename: buster glusterfs version :5.5.3 qemu-img version 5.2.0

debian@Node-5:~$ sudo qemu-img create  gluster://storage-node-5/gv0/testimage.img 1G
Formatting 'gluster://storage-node-5/gv0/testimage.img', fmt=raw size=1073741824
[2021-07-11 15:49:50.227484] E [MSGID: 108006] [afr-common.c:5314:__afr_handle_child_down_event] 0-gv0-replicate-0: All subvolumes are down. Going offline until at least one of them comes back up.
Details gluster volume info : ``` Volume Name: gv0 Type: Replicate Volume ID: f6f9b9da-30d1-42de-8d51-7c69f8096c2f Status: Started Snapshot Count: 0 Number of Bricks: 1 x (2 + 1) = 3 Transport-type: tcp Bricks: Brick1: storage-node-4:/data/brick/gv0 Brick2: storage-master-3:/data/brick/gv0 Brick3: storage-node-7:/data/brick/gv0 (arbiter) Options Reconfigured: server.allow-insecure: On diagnostics.count-fop-hits: on diagnostics.latency-measurement: on cluster.lookup-optimize: off server.keepalive-count: 5 server.keepalive-interval: 2 server.keepalive-time: 10 server.tcp-user-timeout: 20 network.ping-timeout: 20 server.event-threads: 4 client.event-threads: 4 cluster.choose-local: off user.cifs: off features.shard: on cluster.shd-wait-qlength: 10000 cluster.shd-max-threads: 8 cluster.locking-scheme: granular cluster.data-self-heal-algorithm: full cluster.server-quorum-type: server cluster.quorum-type: auto cluster.eager-lock: enable performance.strict-o-direct: on network.remote-dio: disable performance.low-prio-threads: 32 performance.io-cache: off performance.read-ahead: off performance.quick-read: off cluster.granular-entry-heal: on storage.fips-mode-rchecksum: on transport.address-family: inet nfs.disable: on performance.client-io-threads: on ``` gluster volume status : ``` Status of volume: gv0 Gluster process TCP Port RDMA Port Online Pid ------------------------------------------------------------------------------ Brick storage-node-4:/data/brick/gv0 49152 0 Y 570442 Brick storage-master-3:/data/brick/gv0 49152 0 Y 317343 Brick storage-node-7:/data/brick/gv0 49152 0 Y 2635158 Self-heal Daemon on localhost N/A N/A Y 570459 Self-heal Daemon on storage-node-7 N/A N/A Y 2635175 Self-heal Daemon on storage-master-3 N/A N/A Y 317360 Task Status of Volume gv0 ------------------------------------------------------------------------------ There are no active volume tasks ```
itisravi commented 3 years ago

@wxiaoguang I don't think this is a bug. When fini is executed, replicate xlator (AFR) will receive child down for each of its children. When connection to all its children are lost, you will see this message. You can observe it in any gfapi program that calls glfs_fini() and can be ignored.

pranithk commented 3 years ago

@wxiaoguang I don't think this is a bug. When fini is executed, replicate xlator (AFR) will receive child down for each of its children. When connection to all its children are lost, you will see this message. You can observe it in any gfapi program that calls glfs_fini() and can be ignored.

@itisravi I think the user's question is why are they coming on the terminal and not in logs.

itisravi commented 3 years ago

@itisravi I think the user's question is why are they coming on the terminal and not in logs.

I think this could be due to the logfile location configured in qemu. In the source code (qemu/block/gluster.c), I do see #define GLUSTER_LOGFILE_DEFAULT "-" /* handled in libgfapi as /dev/stderr */

wxiaoguang commented 3 years ago

@itisravi @pranithk it is a bug, it takes too much time in glfs_fini, please see details in:

https://github.com/gluster/glusterfs/issues/2606 glfs_fini takes too much time and slows down qemu-img and other clients

https://github.com/gluster/glusterfs/issues/1962 gfapi: glfs_fini fucntion consume more time reusult in qemu create image or start vm slow

and the bug doesn't exist in glusterfs-5.5 (or 4.1), I can not say which version introduced this bug.

pranithk commented 3 years ago

@itisravi @pranithk it is a bug, it takes too much time in glfs_fini, please see details in:

2606 glfs_fini takes too much time and slows down qemu-img and other clients

1962 gfapi: glfs_fini fucntion consume more time reusult in qemu create image or start vm slow

and the bug doesn't exist in glusterfs-5.5 (or 4.1), I can not say which version introduced this bug.

@wxiaoguang They are separate issues. I believe Mohit is working on the delay issue. @soumyakoduri @thotz Is it okay if we make the default /dev/null instead?

wxiaoguang commented 3 years ago

Although I agree that the log is a little misleading .... however, without this terminal log, I won't look into the delay problem, I may accept the wrong situation that qemu-img is slow with glusterfs ....

I think showing serious errors to end users is a good choice, and if the delay issue is resolved, there will be no error outputs anymore.

itisravi commented 3 years ago

Closing the issue since

wxiaoguang commented 2 years ago