GlusterFS stuck on mount, times out after 1 minute

Description of problem: Mount gets stuck for 1 minute, then times out. Normally it works fine, but now it doesn't work anymore on my device. I am connected through a different access point now, but IPv4 and IPv6 just work fine, and I have no reason to believe this should be an issue. I can still successfully mount the volume on the server itself, so that still works fine.

The exact command to reproduce the issue:

mount -o log-level=TRACE -t glusterfs 10.1.2.1:myvolume /mnt/test

The full output of the command that failed: After one minute:

Mounting glusterfs on /mnt/test failed.

And in the log-file:

[2023-06-25 12:49:52.190985 +0000] I [MSGID: 100030] [glusterfsd.c:2767:main] 0-/usr/sbin/glusterfs: Started running version [{arg=/usr/sbin/glusterfs}, {version=10.3}, {cmdlinestr=/usr/sbin/glusterfs --log-level=TRACE --process-name fuse --volfile-server=10.1.2.1 --volfile-id=myvolume /mnt/test}] 
[2023-06-25 12:49:52.191063 +0000] T [MSGID: 0] [xlator.c:388:xlator_dynload] 0-xlator: attempt to load file /usr/lib/x86_64-linux-gnu/glusterfs/10.3/xlator/mount/fuse.so 
[2023-06-25 12:49:52.191317 +0000] T [MSGID: 0] [xlator.c:301:xlator_dynload_apis] 0-xlator: fuse: method missing (reconfigure) 
[2023-06-25 12:49:52.191335 +0000] T [MSGID: 0] [xlator.c:319:xlator_dynload_apis] 0-xlator: fuse: method missing (dump_metrics) 
[2023-06-25 12:49:52.191342 +0000] T [MSGID: 0] [xlator.c:325:xlator_dynload_apis] 0-xlator: fuse: method missing (pass_through_fops), falling back to default 
[2023-06-25 12:49:52.191360 +0000] D [MSGID: 0] [glusterfsd.c:421:set_fuse_mount_options] 0-glusterfsd: fopen-keep-cache mode 2 
[2023-06-25 12:49:52.191369 +0000] D [MSGID: 0] [glusterfsd.c:465:set_fuse_mount_options] 0-glusterfsd: fuse direct io type 2 
[2023-06-25 12:49:52.191378 +0000] D [MSGID: 0] [glusterfsd.c:478:set_fuse_mount_options] 0-glusterfsd: fuse no-root-squash mode 0 
[2023-06-25 12:49:52.191387 +0000] D [MSGID: 0] [glusterfsd.c:519:set_fuse_mount_options] 0-glusterfsd: kernel-writeback-cache mode 2 
[2023-06-25 12:49:52.191393 +0000] D [MSGID: 0] [glusterfsd.c:537:set_fuse_mount_options] 0-glusterfsd: fuse-flush-handle-interrupt mode 2 
[2023-06-25 12:49:52.191477 +0000] T [MSGID: 0] [options.c:1239:xlator_option_init_double] 0-fuse: option attribute-timeout using default value 1.0 
[2023-06-25 12:49:52.191490 +0000] T [MSGID: 0] [options.c:513:xlator_option_validate_double] 0-fuse: no range check required for 'option attribute-timeout 1.0' 
[2023-06-25 12:49:52.191505 +0000] T [MSGID: 0] [options.c:1230:xlator_option_init_uint32] 0-fuse: option reader-thread-count using default value 1 
[2023-06-25 12:49:52.191855 +0000] D [dict.c:2503:dict_get_str] (-->/usr/lib/x86_64-linux-gnu/glusterfs/10.3/xlator/mount/fuse.so(+0x1eb50) [0x7f88fd708b50] -->/lib/x86_64-linux-gnu/libglusterfs.so.0(xlator_option_init_bool+0x60) [0x7f88fec6a430] -->/lib/x86_64-linux-gnu/libglusterfs.so.0(dict_get_str+0xdf) [0x7f88fec1682f] ) 0-dict: key auto-invalidation, string type asked, has unsigned integer type [Invalid argument]
[2023-06-25 12:49:52.191929 +0000] D [MSGID: 0] [options.c:1236:xlator_option_init_bool] 0-fuse: option auto-invalidation using set value 0 
[2023-06-25 12:49:52.191944 +0000] T [MSGID: 0] [options.c:1239:xlator_option_init_double] 0-fuse: option entry-timeout using default value 1.0 
[2023-06-25 12:49:52.191952 +0000] T [MSGID: 0] [options.c:513:xlator_option_validate_double] 0-fuse: no range check required for 'option entry-timeout 1.0' 
[2023-06-25 12:49:52.192011 +0000] D [dict.c:2503:dict_get_str] (-->/usr/lib/x86_64-linux-gnu/glusterfs/10.3/xlator/mount/fuse.so(+0x1ebae) [0x7f88fd708bae] -->/lib/x86_64-linux-gnu/libglusterfs.so.0(xlator_option_init_double+0x60) [0x7f88fec6a8c0] -->/lib/x86_64-linux-gnu/libglusterfs.so.0(dict_get_str+0xdf) [0x7f88fec1682f] ) 0-dict: key negative-timeout, string type asked, has float type [Invalid argument]
[2023-06-25 12:49:52.192022 +0000] D [MSGID: 0] [options.c:1239:xlator_option_init_double] 0-fuse: option negative-timeout using set value 0.000000 
[2023-06-25 12:49:52.192030 +0000] T [MSGID: 0] [options.c:513:xlator_option_validate_double] 0-fuse: no range check required for 'option negative-timeout 0.000000' 
[2023-06-25 12:49:52.192040 +0000] T [MSGID: 0] [options.c:1231:xlator_option_init_int32] 0-fuse: option client-pid not set 
[2023-06-25 12:49:52.192049 +0000] T [MSGID: 0] [options.c:1230:xlator_option_init_uint32] 0-fuse: option uid-map-root not set 
[2023-06-25 12:49:52.192058 +0000] T [MSGID: 0] [options.c:1236:xlator_option_init_bool] 0-fuse: option strict-volfile-check using default value false 
[2023-06-25 12:49:52.192067 +0000] T [MSGID: 0] [options.c:1236:xlator_option_init_bool] 0-fuse: option acl using default value false 
[2023-06-25 12:49:52.192089 +0000] T [MSGID: 0] [options.c:1236:xlator_option_init_bool] 0-fuse: option selinux using default value false 
[2023-06-25 12:49:52.192101 +0000] T [MSGID: 0] [options.c:1236:xlator_option_init_bool] 0-fuse: option capability using default value false 
[2023-06-25 12:49:52.192111 +0000] T [MSGID: 0] [options.c:1236:xlator_option_init_bool] 0-fuse: option read-only not set 
[2023-06-25 12:49:52.192121 +0000] T [MSGID: 0] [options.c:1236:xlator_option_init_bool] 0-fuse: option enable-ino32 using default value false 
[2023-06-25 12:49:52.192131 +0000] T [MSGID: 0] [options.c:1236:xlator_option_init_bool] 0-fuse: option use-readdirp using default value yes 
[2023-06-25 12:49:52.192184 +0000] D [dict.c:2503:dict_get_str] (-->/lib/x86_64-linux-gnu/libglusterfs.so.0(xlator_init+0xc5) [0x7f88fec19c85] -->/usr/lib/x86_64-linux-gnu/glusterfs/10.3/xlator/mount/fuse.so(+0x1ee3d) [0x7f88fd708e3d] -->/lib/x86_64-linux-gnu/libglusterfs.so.0(dict_get_str+0xdf) [0x7f88fec1682f] ) 0-dict: key sync-to-mount, string type asked, has pointer type [Invalid argument]
[2023-06-25 12:49:52.192200 +0000] T [MSGID: 0] [options.c:1240:xlator_option_init_time] 0-fuse: option gid-timeout using default value 300 
[2023-06-25 12:49:52.192208 +0000] T [MSGID: 0] [options.c:80:xlator_option_validate_int] 0-fuse: no range check required for 'option gid-timeout 300' 
[2023-06-25 12:49:52.192220 +0000] T [MSGID: 0] [options.c:1227:xlator_option_init_str] 0-fuse: option fuse-mountopts not set 
[2023-06-25 12:49:52.192253 +0000] T [MSGID: 0] [options.c:1236:xlator_option_init_bool] 0-fuse: option resolve-gids using default value false 
[2023-06-25 12:49:52.192265 +0000] T [MSGID: 0] [options.c:1231:xlator_option_init_int32] 0-fuse: option background-qlen using default value 64 
[2023-06-25 12:49:52.192277 +0000] T [MSGID: 0] [options.c:1231:xlator_option_init_int32] 0-fuse: option congestion-threshold using default value 48 
[2023-06-25 12:49:52.192450 +0000] D [dict.c:2503:dict_get_str] (-->/usr/lib/x86_64-linux-gnu/glusterfs/10.3/xlator/mount/fuse.so(+0x1efe1) [0x7f88fd708fe1] -->/lib/x86_64-linux-gnu/libglusterfs.so.0(xlator_option_init_bool+0x60) [0x7f88fec6a430] -->/lib/x86_64-linux-gnu/libglusterfs.so.0(dict_get_str+0xdf) [0x7f88fec1682f] ) 0-dict: key no-root-squash, string type asked, has pointer type [Invalid argument]
[2023-06-25 12:49:52.192473 +0000] D [MSGID: 0] [options.c:1236:xlator_option_init_bool] 0-fuse: option no-root-squash using set value disable 
[2023-06-25 12:49:52.192499 +0000] T [MSGID: 0] [options.c:1230:xlator_option_init_uint32] 0-fuse: option lru-limit using default value 65536 
[2023-06-25 12:49:52.192509 +0000] T [MSGID: 0] [options.c:80:xlator_option_validate_int] 0-fuse: no range check required for 'option lru-limit 65536' 
[2023-06-25 12:49:52.192571 +0000] D [dict.c:2503:dict_get_str] (-->/usr/lib/x86_64-linux-gnu/glusterfs/10.3/xlator/mount/fuse.so(+0x1f052) [0x7f88fd709052] -->/lib/x86_64-linux-gnu/libglusterfs.so.0(xlator_option_init_uint32+0x60) [0x7f88fec6b140] -->/lib/x86_64-linux-gnu/libglusterfs.so.0(dict_get_str+0xdf) [0x7f88fec1682f] ) 0-dict: key invalidate-limit, string type asked, has integer type [Invalid argument]
[2023-06-25 12:49:52.192581 +0000] D [MSGID: 0] [options.c:1230:xlator_option_init_uint32] 0-fuse: option invalidate-limit using set value 0 
[2023-06-25 12:49:52.192588 +0000] T [MSGID: 0] [options.c:80:xlator_option_validate_int] 0-fuse: no range check required for 'option invalidate-limit 0' 
[2023-06-25 12:49:52.192600 +0000] T [MSGID: 0] [options.c:1236:xlator_option_init_bool] 0-fuse: option event-history using default value false 
[2023-06-25 12:49:52.192614 +0000] T [MSGID: 0] [options.c:1236:xlator_option_init_bool] 0-fuse: option thin-client using default value false 
[2023-06-25 12:49:52.192637 +0000] T [MSGID: 0] [options.c:1236:xlator_option_init_bool] 0-fuse: option kernel-writeback-cache using default value false 
[2023-06-25 12:49:52.192660 +0000] T [MSGID: 0] [options.c:1231:xlator_option_init_int32] 0-fuse: option attr-times-granularity using default value 0 
[2023-06-25 12:49:52.192698 +0000] T [MSGID: 0] [options.c:1236:xlator_option_init_bool] 0-fuse: option flush-handle-interrupt using default value false 
[2023-06-25 12:49:52.192716 +0000] T [MSGID: 0] [options.c:1230:xlator_option_init_uint32] 0-fuse: option fuse-dev-eperm-ratelimit-ns using default value 10000000 
[2023-06-25 12:49:52.193612 +0000] I [glusterfsd.c:2447:daemonize] 0-glusterfs: Pid of current running process is 51439
[2023-06-25 12:49:52.193670 +0000] D [logging.c:1705:__gf_log_inject_timer_event] 0-logging-infra: Starting timer now. Timeout = 120, current buf size = 5
[2023-06-25 12:49:52.195882 +0000] D [MSGID: 0] [gf-io.c:513:gf_io_run] 0-io: Trying I/O engine 'legacy' 
[2023-06-25 12:49:52.195957 +0000] D [MSGID: 0] [gf-io.c:517:gf_io_run] 0-io: I/O engine 'legacy' is ready 
[2023-06-25 12:49:52.196581 +0000] D [rpc-clnt.c:1018:rpc_clnt_connection_init] 0-glusterfs: defaulting frame-timeout to 30mins
[2023-06-25 12:49:52.196602 +0000] D [rpc-clnt.c:1030:rpc_clnt_connection_init] 0-glusterfs: disable ping-timeout
[2023-06-25 12:49:52.196622 +0000] D [rpc-transport.c:278:rpc_transport_load] 0-rpc-transport: attempt to load file /usr/lib/x86_64-linux-gnu/glusterfs/10.3/rpc-transport/socket.so
[2023-06-25 12:49:52.197709 +0000] D [MSGID: 101233] [options.c:973:xl_opt_validate] 0-glusterfs: option is deprecated, continuing with correction [{key=address-family}, {preferred=transport.address-family}] 
[2023-06-25 12:49:52.197742 +0000] T [MSGID: 0] [options.c:80:xlator_option_validate_int] 0-glusterfs: no range check required for 'option remote-port 24007' 
[2023-06-25 12:49:52.198977 +0000] D [socket.c:4560:socket_init] 0-glusterfs: Configured transport.tcp-user-timeout=42
[2023-06-25 12:49:52.198994 +0000] D [socket.c:4580:socket_init] 0-glusterfs: Reconfigured transport.keepalivecnt=9
[2023-06-25 12:49:52.199005 +0000] D [rpc-clnt.c:1591:rpcclnt_cbk_program_register] 0-glusterfs: New program registered: GlusterFS Callback, Num: 52743234, Ver: 1
[2023-06-25 12:49:52.199011 +0000] T [rpc-clnt.c:396:rpc_clnt_reconnect] 0-glusterfs: attempting reconnect
[2023-06-25 12:49:52.199017 +0000] T [socket.c:3377:socket_connect] 0-glusterfs: connecting 0x5632bb0a1588, sock=-1
[2023-06-25 12:49:52.199084 +0000] D [dict.c:1290:data_to_uint16] (-->/usr/lib/x86_64-linux-gnu/glusterfs/10.3/rpc-transport/socket.so(+0x988d) [0x7f88fa0ad88d] -->/usr/lib/x86_64-linux-gnu/glusterfs/10.3/rpc-transport/socket.so(socket_client_get_remote_sockaddr+0x29b) [0x7f88fa0ad3bb] -->/lib/x86_64-linux-gnu/libglusterfs.so.0(data_to_uint16+0x146) [0x7f88fec13696] ) 0-dict: key null, unsigned integer type asked, has integer type [Invalid argument]
[2023-06-25 12:49:52.199109 +0000] T [MSGID: 0] [common-utils.c:504:gf_resolve_ip6] 0-resolver: DNS cache not present, freshly probing hostname: 10.1.2.1 
[2023-06-25 12:49:52.199480 +0000] D [MSGID: 0] [common-utils.c:542:gf_resolve_ip6] 0-resolver: returning ip-10.1.2.1 (port-24007) for hostname: 10.1.2.1 and port: 24007 
[2023-06-25 12:49:52.199497 +0000] D [socket.c:3294:socket_fix_ssl_opts] 0-glusterfs: disabling SSL for portmapper connection
[2023-06-25 12:49:52.199515 +0000] T [socket.c:1021:__socket_nodelay] 0-glusterfs: NODELAY enabled for socket 9
[2023-06-25 12:49:52.199525 +0000] T [socket.c:1107:__socket_keepalive] 0-glusterfs: Keep-alive enabled for socket: 9, (idle: 20, interval: 2, max-probes: 9, timeout: 42)
[2023-06-25 12:49:52.199555 +0000] T [socket.c:3494:socket_connect] 0-glusterfs: >>> connect() with non-blocking IO for ALL
[2023-06-25 12:49:52.199568 +0000] T [socket.c:206:socket_dump_info] 0-glusterfs: $$$ client: connecting to (af:2,sock:9) 10.1.2.1 non-SSL (errno:0:Success)
[2023-06-25 12:49:52.199976 +0000] I [MSGID: 101190] [event-epoll.c:667:event_dispatch_epoll_worker] 0-epoll: Started thread with index [{index=0}] 
[2023-06-25 12:49:52.200065 +0000] I [MSGID: 101190] [event-epoll.c:667:event_dispatch_epoll_worker] 0-epoll: Started thread with index [{index=1}] 
[2023-06-25 12:49:52.222993 +0000] T [socket.c:2897:socket_event_handler] 0-glusterfs: client (sock:9) in:0, out:4, err:0
[2023-06-25 12:49:52.223035 +0000] T [socket.c:2903:socket_event_handler] 0-glusterfs: client (sock:9) socket is not connected, completing connection
[2023-06-25 12:49:52.223105 +0000] T [rpc-clnt.c:1443:rpc_clnt_record_build_header] 0-rpc-clnt: Request fraglen 144, payload: 80, rpc hdr: 64
[2023-06-25 12:49:52.223154 +0000] T [rpc-clnt.c:1729:rpc_clnt_submit] 0-rpc-clnt: submitted request (unique: 0, XID: 0x2, Program: GlusterFS Handshake, ProgVers: 2, Proc: 2) to rpc-transport (glusterfs)
[2023-06-25 12:49:52.223165 +0000] D [rpc-clnt-ping.c:296:rpc_clnt_start_ping] 0-glusterfs: ping timeout is 0, returning
[2023-06-25 12:49:52.223175 +0000] T [socket.c:2803:socket_handle_client_connection_attempt] 0-glusterfs: socket_connect_finish() returned 0
[2023-06-25 12:49:52.223190 +0000] T [socket.c:2910:socket_event_handler] 0-glusterfs: (sock:9) socket_complete_connection() returned 1
[2023-06-25 12:49:52.223197 +0000] T [socket.c:2916:socket_event_handler] 0-glusterfs: (sock:9) returning to wait on socket
[2023-06-25 12:49:52.223205 +0000] T [socket.c:2897:socket_event_handler] 0-glusterfs: client (sock:9) in:0, out:4, err:0
[2023-06-25 12:49:52.223211 +0000] T [socket.c:2923:socket_event_handler] 0-glusterfs: Client socket (9) is already connected
[2023-06-25 12:49:52.223218 +0000] T [socket.c:2932:socket_event_handler] 0-glusterfs: (sock:9) socket_event_poll_out returned 0
[2023-06-25 12:49:55.200047 +0000] T [rpc-clnt.c:407:rpc_clnt_reconnect] 0-glusterfs: breaking reconnect chain
[2023-06-25 12:50:53.865573 +0000] T [socket.c:2897:socket_event_handler] 0-glusterfs: client (sock:9) in:1, out:0, err:24
[2023-06-25 12:50:53.865718 +0000] T [socket.c:206:socket_dump_info] 0-glusterfs: $$$ client: disconnecting from (af:2,sock:9) 10.1.2.1 non-SSL (errno:104:Connection reset by peer)
[2023-06-25 12:50:53.865746 +0000] D [socket.c:2966:socket_event_handler] 0-transport: EPOLLERR - disconnecting (sock:9) (non-SSL)
[2023-06-25 12:50:53.865821 +0000] I [glusterfsd-mgmt.c:2673:mgmt_rpc_notify] 0-glusterfsd-mgmt: disconnected from remote-host: 10.1.2.1
[2023-06-25 12:50:53.865855 +0000] I [glusterfsd-mgmt.c:2712:mgmt_rpc_notify] 0-glusterfsd-mgmt: Exhausted all volfile servers
[2023-06-25 12:50:53.865962 +0000] D [logging.c:1675:gf_log_flush_extra_msgs] 0-logging-infra: Log buffer size reduced. About to flush 5 extra log messages
[2023-06-25 12:50:53.866014 +0000] D [logging.c:1681:gf_log_flush_extra_msgs] 0-logging-infra: Just flushed 5 extra log messages
[2023-06-25 12:50:53.866166 +0000] W [glusterfsd.c:1458:cleanup_and_exit] (-->/lib/x86_64-linux-gnu/libgfrpc.so.0(+0xf965) [0x7f88febca965] -->/usr/sbin/glusterfs(+0x14639) [0x5632ba379639] -->/usr/sbin/glusterfs(cleanup_and_exit+0x57) [0x5632ba370467] ) 0-: received signum (1), shutting down 
[2023-06-25 12:50:53.866238 +0000] D [mgmt-pmap.c:90:rpc_clnt_mgmt_pmap_signout] 0-fsd-mgmt: portmapper signout arguments not given
[2023-06-25 12:50:53.866328 +0000] I [fuse-bridge.c:7065:fini] 0-fuse: Unmounting '/mnt/test'.
[2023-06-25 12:50:53.867295 +0000] I [fuse-bridge.c:7069:fini] 0-fuse: Closing fuse connection to '/mnt/test'.
[2023-06-25 12:50:53.867930 +0000] W [glusterfsd.c:1458:cleanup_and_exit] (-->/lib/x86_64-linux-gnu/libc.so.6(+0x88fd4) [0x7f88fea4efd4] -->/usr/sbin/glusterfs(glusterfs_sigwaiter+0xc5) [0x5632ba377cd5] -->/usr/sbin/glusterfs(cleanup_and_exit+0x57) [0x5632ba370467] ) 0-: received signum (15), shutting down

Additionally, during the mount, even if I interrupt the mount-process using CTRL+C, the glusterfs daemon is still waiting on the timeout.

Expected results: The mount succeeds.

Mandatory info: - The output of the gluster volume info command:

Volume Name: myvolume
Type: Replicate
Volume ID: 26d***d08
Status: Started
Snapshot Count: 0
Number of Bricks: 1 x 3 = 3
Transport-type: tcp
Bricks:
Brick1: virtual.s1.mydomain:/srv/myvolume/s1
Brick2: virtual.s2.mydomain:/srv/myvolume/s2
Brick3: virtual.s3.mydomain:/srv/myvolume/s3
Options Reconfigured:
cluster.server-quorum-type: server
performance.client-io-threads: off
nfs.disable: on
transport.address-family: inet
storage.fips-mode-rchecksum: on
cluster.granular-entry-heal: on
cluster.self-heal-daemon: on
features.bitrot: on
features.scrub: Active

- The output of the gluster volume status command:

Status of volume: myvolume
Gluster process                             TCP Port  RDMA Port  Online  Pid
------------------------------------------------------------------------------
Brick virtual.s1.mydomain:/srv/myvolume/s1   49152     0          Y       624386
Brick virtual.s2.mydomain:/srv/myvolume/s2   49152     0          Y       78025
Brick virtual.s3.mydomain:/srv/myvolume/s3   49152     0          Y       3089 
Self-heal Daemon on localhost               N/A       N/A        Y       1440 
Bitrot Daemon on localhost                  N/A       N/A        Y       2325579
Scrubber Daemon on localhost                N/A       N/A        Y       2325598
Self-heal Daemon on virtual.s3.mydomain     N/A       N/A        Y       844  
Bitrot Daemon on virtual.s3.mydomain        N/A       N/A        Y       61053
Scrubber Daemon on virtual.s3.mydomain      N/A       N/A        Y       61072
Self-heal Daemon on virtual.s2.mydomain     N/A       N/A        Y       1357 
Bitrot Daemon on virtual.s2.mydomain        N/A       N/A        Y       78090
Scrubber Daemon on virtual.s2.mydomain      N/A       N/A        Y       78109

Task Status of Volume myvolume
------------------------------------------------------------------------------
There are no active volume tasks

- The output of the gluster volume heal command:

Launching heal operation to perform index self heal on volume myvolume has been successful 
Use heal info commands to check status.

**- Provide logs present on following locations of client and server nodes - /var/log/glusterfs/

[2023-06-25 12:49:52.236716 +0000] I [MSGID: 106496] [glusterd-handshake.c:968:__server_getspec] 0-management: Received mount request for volume myvolume

**- Is there any crash ? Provide the backtrace and coredump No crashes.

Additional info: I run a local VPN, but there doesn't seem to be any issues with regard to connectivity. I can't think of anything that changed since yesterday, when this still worked. I made sure no processes containing gluster are lingering in the process list.

- The operating system / glusterfs version: uname -a:

Linux myhostname 6.1.0-9-amd64 #1 SMP PREEMPT_DYNAMIC Debian 6.1.27-1 (2023-05-08) x86_64 GNU/Linux

glusterfs --version:

glusterfs 10.3
(...)

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 I renamed hostnames and volume names to 'my(...)'.

gluster / glusterfs

GlusterFS stuck on mount, times out after 1 minute #4183