Bug 1608305 - [glusterfs-3.6.9] Fuse-mount has been forced off
Summary: [glusterfs-3.6.9] Fuse-mount has been forced off
Keywords:
Status: CLOSED EOL
Alias: None
Product: GlusterFS
Classification: Community
Component: fuse
Version: mainline
Hardware: x86_64
OS: Linux
high
high
Target Milestone: ---
Assignee: bugs@gluster.org
QA Contact:
URL:
Whiteboard:
Depends On:
Blocks:
TreeView+ depends on / blocked
 
Reported: 2018-07-25 09:37 UTC by JeongKinam
Modified: 2020-05-14 07:40 UTC (History)
6 users (show)

Fixed In Version:
Doc Type: If docs needed, set a value
Doc Text:
Clone Of:
Environment:
Last Closed: 2019-07-27 08:35:24 UTC
Regression: ---
Mount Type: fuse
Documentation: ---
CRM:
Verified Versions:
Embargoed:
knjeong: needinfo-

Attachments (Terms of Use)

Description JeongKinam 2018-07-25 09:37:42 UTC 
Description of problem:


I was using glusterfs-3.6.9(community version) and suddenly fuse-mount was disabled on the client with the error below. 
I have seen all of the gluster-logs and os-logs(/var/log/messages) on the unmounted client and on the glusterfs server, and I'm guessing it is related to memory, but I do not know the exact cause of the error.

What is the best way to determine the cause of the error in this situation?
Can you determine the exact cause with this information?
Help!



- /var/log/messages (unmounted client)

Jul 25 08:11:00 CLIENT gluster[5966]: pending frames:
Jul 25 08:11:00 CLIENT gluster[5966]: pending frames:
Jul 25 08:11:00 CLIENT gluster[5966]: frame : type(1) op(WRITE)
Jul 25 08:11:00 CLIENT gluster[5966]: frame : type(1) op(WRITE)
Jul 25 08:11:00 CLIENT gluster[5966]: frame : type(1) op(WRITE)
Jul 25 08:11:00 CLIENT gluster[5966]: frame : type(1) op(WRITE)
Jul 25 08:11:00 CLIENT gluster[5966]: frame : type(1) op(WRITE)
Jul 25 08:11:00 CLIENT gluster[5966]: frame : type(0) op(0)
Jul 25 08:11:00 CLIENT gluster[5966]: frame : type(0) op(0)
Jul 25 08:11:00 CLIENT gluster[5966]: frame : type(0) op(0)
Jul 25 08:11:00 CLIENT gluster[5966]: frame : type(0) op(0)
Jul 25 08:11:00 CLIENT gluster[5966]: frame : type(0) op(0)
Jul 25 08:11:00 CLIENT gluster[5966]: frame : type(0) op(0)
Jul 25 08:11:00 CLIENT gluster[5966]: frame : type(0) op(0)
Jul 25 08:11:00 CLIENT gluster[5966]: frame : type(0) op(0)
Jul 25 08:11:00 CLIENT gluster[5966]: frame : type(0) op(0)
Jul 25 08:11:00 CLIENT gluster[5966]: frame : type(0) op(0)
Jul 25 08:11:00 CLIENT gluster[5966]: frame : type(0) op(0)
Jul 25 08:11:00 CLIENT gluster[5966]: frame : type(0) op(0)
Jul 25 08:11:00 CLIENT gluster[5966]: frame : type(1) op(WRITE)
Jul 25 08:11:00 CLIENT gluster[5966]: frame : type(1) op(WRITE)
Jul 25 08:11:00 CLIENT gluster[5966]: frame : type(1) op(WRITE)
Jul 25 08:11:00 CLIENT gluster[5966]: frame : type(1) op(WRITE)
Jul 25 08:11:00 CLIENT gluster[5966]: frame : type(1) op(WRITE)
Jul 25 08:11:00 CLIENT gluster[5966]: frame : type(0) op(0)
Jul 25 08:11:00 CLIENT gluster[5966]: frame : type(0) op(0)
Jul 25 08:11:00 CLIENT gluster[5966]: frame : type(0) op(0)
Jul 25 08:11:00 CLIENT gluster[5966]: frame : type(0) op(0)
Jul 25 08:11:00 CLIENT gluster[5966]: frame : type(0) op(0)
Jul 25 08:11:00 CLIENT gluster[5966]: frame : type(0) op(0)
Jul 25 08:11:00 CLIENT gluster[5966]: frame : type(0) op(0)
Jul 25 08:11:00 CLIENT gluster[5966]: frame : type(0) op(0)
Jul 25 08:11:00 CLIENT gluster[5966]: frame : type(0) op(0)
Jul 25 08:11:00 CLIENT gluster[5966]: frame : type(0) op(0)
Jul 25 08:11:00 CLIENT gluster[5966]: frame : type(0) op(0)
Jul 25 08:11:00 CLIENT gluster[5966]: frame : type(0) op(0)
Jul 25 08:11:00 CLIENT gluster[5966]: frame : type(0) op(0)
Jul 25 08:11:00 CLIENT gluster[5966]: frame : type(0) op(0)
Jul 25 08:11:00 CLIENT gluster[5966]: frame : type(0) op(0)
Jul 25 08:11:00 CLIENT gluster[5966]: frame : type(0) op(0)
Jul 25 08:11:00 CLIENT gluster[5966]: frame : type(0) op(0)
Jul 25 08:11:00 CLIENT gluster[5966]: frame : type(0) op(0)
Jul 25 08:11:00 CLIENT gluster[5966]: frame : type(0) op(0)
Jul 25 08:11:00 CLIENT gluster[5966]: frame : type(0) op(0)
Jul 25 08:11:00 CLIENT gluster[5966]: frame : type(0) op(0)
Jul 25 08:11:00 CLIENT gluster[5966]: frame : type(0) op(0)
Jul 25 08:11:00 CLIENT gluster[5966]: frame : type(0) op(0)
Jul 25 08:11:00 CLIENT gluster[5966]: frame : type(0) op(0)
Jul 25 08:11:00 CLIENT gluster[5966]: frame : type(0) op(0)
Jul 25 08:11:00 CLIENT gluster[5966]: frame : type(0) op(0)
Jul 25 08:11:00 CLIENT gluster[5966]: frame : type(1) op(LOOKUP)
Jul 25 08:11:00 CLIENT gluster[5966]: frame : type(0) op(0)
Jul 25 08:11:00 CLIENT gluster[5966]: frame : type(0) op(0)
Jul 25 08:11:00 CLIENT gluster[5966]: frame : type(0) op(0)
Jul 25 08:11:00 CLIENT gluster[5966]: frame : type(0) op(0)
Jul 25 08:11:00 CLIENT gluster[5966]: patchset: git://git.gluster.com/glusterfs.git
Jul 25 08:11:00 CLIENT gluster[5966]: signal received: 6
Jul 25 08:11:00 CLIENT gluster[5966]: time of crash:
Jul 25 08:11:00 CLIENT gluster[5966]: 2018-07-24 23:11:00
Jul 25 08:11:00 CLIENT gluster[5966]: configuration details:
Jul 25 08:11:00 CLIENT gluster[5966]: argp 1
Jul 25 08:11:00 CLIENT gluster[5966]: backtrace 1
Jul 25 08:11:00 CLIENT gluster[5966]: dlfcn 1
Jul 25 08:11:00 CLIENT gluster[5966]: libpthread 1
Jul 25 08:11:00 CLIENT gluster[5966]: llistxattr 1
Jul 25 08:11:00 CLIENT gluster[5966]: setfsid 1
Jul 25 08:11:00 CLIENT gluster[5966]: spinlock 1
Jul 25 08:11:00 CLIENT gluster[5966]: epoll.h 1
Jul 25 08:11:00 CLIENT gluster[5966]: frame : type(0) op(0)
Jul 25 08:11:00 CLIENT gluster[5966]: frame : type(0) op(0)
Jul 25 08:11:00 CLIENT gluster[5966]: frame : type(0) op(0)
Jul 25 08:11:00 CLIENT gluster[5966]: frame : type(0) op(0)
Jul 25 08:11:00 CLIENT gluster[5966]: frame : type(0) op(0)
Jul 25 08:11:00 CLIENT gluster[5966]: frame : type(0) op(0)
Jul 25 08:11:00 CLIENT gluster[5966]: frame : type(0) op(0)
Jul 25 08:11:00 CLIENT gluster[5966]: frame : type(0) op(0)
Jul 25 08:11:00 CLIENT gluster[5966]: frame : type(0) op(0)
Jul 25 08:11:00 CLIENT gluster[5966]: frame : type(0) op(0)
Jul 25 08:11:00 CLIENT gluster[5966]: frame : type(0) op(0)
Jul 25 08:11:00 CLIENT gluster[5966]: frame : type(0) op(0)
Jul 25 08:11:00 CLIENT gluster[5966]: frame : type(0) op(0)
Jul 25 08:11:00 CLIENT gluster[5966]: frame : type(0) op(0)
Jul 25 08:11:00 CLIENT gluster[5966]: frame : type(1) op(LOOKUP)
Jul 25 08:11:00 CLIENT gluster[5966]: frame : type(0) op(0)
Jul 25 08:11:00 CLIENT gluster[5966]: frame : type(0) op(0)
Jul 25 08:11:00 CLIENT gluster[5966]: frame : type(0) op(0)
Jul 25 08:11:00 CLIENT gluster[5966]: frame : type(0) op(0)
Jul 25 08:11:00 CLIENT gluster[5966]: patchset: git://git.gluster.com/glusterfs.git
Jul 25 08:11:00 CLIENT gluster[5966]: signal received: 6
Jul 25 08:11:00 CLIENT gluster[5966]: time of crash:
Jul 25 08:11:00 CLIENT gluster[5966]: 2018-07-24 23:11:00
Jul 25 08:11:00 CLIENT gluster[5966]: configuration details:
Jul 25 08:11:00 CLIENT gluster[5966]: argp 1
Jul 25 08:11:00 CLIENT gluster[5966]: backtrace 1
Jul 25 08:11:00 CLIENT gluster[5966]: dlfcn 1
Jul 25 08:11:00 CLIENT gluster[5966]: libpthread 1
Jul 25 08:11:00 CLIENT gluster[5966]: llistxattr 1
Jul 25 08:11:00 CLIENT gluster[5966]: setfsid 1
Jul 25 08:11:00 CLIENT gluster[5966]: spinlock 1
Jul 25 08:11:00 CLIENT gluster[5966]: epoll.h 1
Jul 25 08:11:00 CLIENT gluster[5966]: xattr.h 1
Jul 25 08:11:00 CLIENT gluster[5966]: st_atim.tv_nsec 1
Jul 25 08:11:00 CLIENT gluster[5966]: package-string: glusterfs 3.7.1
Jul 25 08:11:00 CLIENT gluster[5966]: ---------
Jul 25 08:11:00 CLIENT kernel: audit_printk_skb: 75 callbacks suppressed
Jul 25 08:11:00 CLIENT kernel: type=1701 audit(1532473860.042:2595231): auid=0 uid=0 gid=0 ses=2 pid=5971 comm="glusterfs" reason="memory violation" sig=6
Jul 25 08:11:00 CLIENT gluster[5966]: xattr.h 1
Jul 25 08:11:00 CLIENT gluster[5966]: st_atim.tv_nsec 1
Jul 25 08:11:00 CLIENT gluster[5966]: package-string: glusterfs 3.7.1
Jul 25 08:11:00 CLIENT gluster[5966]: ---------
Jul 25 08:11:00 CLIENT kernel: audit_printk_skb: 75 callbacks suppressed
Jul 25 08:11:00 CLIENT kernel: type=1701 audit(1532473860.042:2595231): auid=0 uid=0 gid=0 ses=2 pid=5971 comm="glusterfs" reason="memory violation" sig=6



- glusterfs server log (brick-log / time -9h = same time)

[2018-07-24 23:11:00.580994] I [server.c:518:server_rpc_notify] 0-repl_dist_vol-server: disconnecting connection from CLIENT-5964-2018/03/27-14:05:04:231328-VOL-client-6-0-1
[2018-07-24 23:11:00.581059] W [inodelk.c:404:pl_inodelk_log_cleanup] 0-VOL-server: releasing lock on 3614fad5-8de0-42f1-bd35-c13d9e451ca6 held by {client=0x7eff9498d950, pid=0 lk-owner=9862425c0a7f0000}
[2018-07-24 23:11:00.581080] I [server-helpers.c:290:do_fd_cleanup] 0-VOL-server: fd cleanup on /SdBackup/101970/20180725T072155.avi
[2018-07-24 23:11:00.581111] I [client_t.c:417:gf_client_unref] 0-VOL-server: Shutting down connection CLIENT-5964-2018/03/27-14:05:04:231328-VOL-client-6-0-1
[2018-07-24 23:11:00.581045] I [server.c:518:server_rpc_notify] 0-VOL-server: disconnecting connection from CLIENT-5964-2018/03/27-14:05:04:231328-VOL-client-8-0-1
[2018-07-24 23:11:00.581121] I [client_t.c:417:gf_client_unref] 0-tidc_media_repl_dist_vol-server: Shutting down connection CLIENT-5964-2018/03/27-14:05:04:231328-VOL-client-8-0-1



- memory (usual)

# free -h
              total        used        free      shared  buff/cache   available
Mem:            31G        2.6G        1.6G        203M         26G         27G
Swap:           15G        8.1G        7.6G



Version-Release number of selected component (if applicable): glusterfs-3.6.9 (community version)
Comment 1 JeongKinam 2018-07-25 09:48:28 UTC 
* version
- server : 3.6.9
- client : 3.7.1
Comment 2 JeongKinam 2018-07-27 09:21:54 UTC 
* gdb-core

GNU gdb (GDB) Red Hat Enterprise Linux 7.6.1-94.el7
Copyright (C) 2013 Free Software Foundation, Inc.
License GPLv3+: GNU GPL version 3 or later <http://gnu.org/licenses/gpl.html>
This is free software: you are free to change and redistribute it.
There is NO WARRANTY, to the extent permitted by law.  Type "show copying"
and "show warranty" for details.
This GDB was configured as "x86_64-redhat-linux-gnu".
For bug reporting instructions, please see:
<http://www.gnu.org/software/gdb/bugs/>...
Reading symbols from /usr/sbin/glusterfsd...Reading symbols from /usr/lib/debug/usr/sbin/glusterfsd.debug...done.
done.

warning: core file may not match specified executable file.
[New LWP 5971]
[New LWP 11970]
[New LWP 5983]
[New LWP 46774]
[New LWP 5982]
[New LWP 6329]
[New LWP 46775]
[New LWP 5972]
[New LWP 13475]
[New LWP 111260]
[New LWP 111261]
[New LWP 45769]
[New LWP 5969]
[New LWP 5970]
[New LWP 5967]
[New LWP 5968]
[New LWP 111259]
[New LWP 5966]
[Thread debugging using libthread_db enabled]
Using host libthread_db library "/lib64/libthread_db.so.1".
Core was generated by `/usr/sbin/glusterfs --log-level=WARNING --log-file=/var/log/glusterfs/gluster.l'.
Program terminated with signal 6, Aborted.
#0  0x00007f0a6eba15f7 in __GI_raise (sig=sig@entry=6) at ../nptl/sysdeps/unix/sysv/linux/raise.c:56
56	  return INLINE_SYSCALL (tgkill, 3, pid, selftid, sig);
(gdb)
(gdb)
(gdb) bt
#0  0x00007f0a6eba15f7 in __GI_raise (sig=sig@entry=6) at ../nptl/sysdeps/unix/sysv/linux/raise.c:56
#1  0x00007f0a6eba2ce8 in __GI_abort () at abort.c:90
#2  0x00007f0a6ebe1317 in __libc_message (do_abort=do_abort@entry=2,
    fmt=fmt@entry=0x7f0a6eceaa28 "*** Error in `%s': %s: 0x%s ***\n") at ../sysdeps/unix/sysv/linux/libc_fatal.c:196
#3  0x00007f0a6ebe9023 in malloc_printerr (ar_ptr=0x7f0a4c000020, ptr=<optimized out>,
    str=0x7f0a6ece8141 "invalid fastbin entry (free)", action=3) at malloc.c:5018
#4  _int_free (av=0x7f0a4c000020, p=<optimized out>, have_lock=0) at malloc.c:3842
#5  0x00007f0a704b0c67 in loc_wipe (loc=loc@entry=0x7f0a5c323424) at xlator.c:694
#6  0x00007f0a629756ee in client_local_wipe (local=local@entry=0x7f0a5c323424) at client-helpers.c:129
#7  0x00007f0a6299248b in client3_3_lookup_cbk (req=<optimized out>, iov=<optimized out>, count=<optimized out>,
    myframe=0x7f0a6dfd39a4) at client-rpc-fops.c:2978
#8  0x00007f0a70281a80 in rpc_clnt_handle_reply (clnt=clnt@entry=0x7f0a5c32a410, pollin=pollin@entry=0x7f0a5c5b1df0)
    at rpc-clnt.c:766
#9  0x00007f0a70281d3f in rpc_clnt_notify (trans=<optimized out>, mydata=0x7f0a5c32a440, event=<optimized out>, data=0x7f0a5c5b1df0)
    at rpc-clnt.c:907
#10 0x00007f0a7027d873 in rpc_transport_notify (this=this@entry=0x7f0a5c33a140, event=event@entry=RPC_TRANSPORT_MSG_RECEIVED,
    data=data@entry=0x7f0a5c5b1df0) at rpc-transport.c:543
#11 0x00007f0a64e72ba6 in socket_event_poll_in (this=this@entry=0x7f0a5c33a140) at socket.c:2290
#12 0x00007f0a64e75a94 in socket_event_handler (fd=fd@entry=17, idx=idx@entry=11, data=0x7f0a5c33a140, poll_in=1, poll_out=0,
    poll_err=0) at socket.c:2403
#13 0x00007f0a705146da in event_dispatch_epoll_handler (event=0x7f0a633a9e80, event_pool=0x7f0a7130cdb0) at event-epoll.c:575
#14 event_dispatch_epoll_worker (data=0x7f0a71362ba0) at event-epoll.c:678
#15 0x00007f0a6f31bdc5 in start_thread (arg=0x7f0a633aa700) at pthread_create.c:308
#16 0x00007f0a6ec6228d in clone () at ../sysdeps/unix/sysv/linux/x86_64/clone.S:113
Comment 3 Amar Tumballi 2019-06-14 10:20:18 UTC 
Looks like this got introduced in that specific version where in-place migration was not supported. Would have caused because of upgrading the clients before, when the servers were of older version.

Would like to mention that we have not seen any such issues in a long time. Please upgrade to higher glusterfs version.

If you have not seen this issue with higher versions, would like to close the issue as EOL (as 3.6.7 is EOL'd).
Comment 4 Amar Tumballi 2019-07-15 18:23:57 UTC 
Please answer comment#3.
Comment 5 Amar Tumballi 2019-07-27 08:35:24 UTC 
3.6.9 is no more supported. Please upgrade and let us know.
Comment 6 JeongKinam 2019-11-18 03:08:01 UTC 
(In reply to Amar Tumballi from comment #5)
> 3.6.9 is no more supported. Please upgrade and let us know.


Thank you so much, but a version upgrade is not something to consider. 

The latest version of glusterfs(another service) has not encountered the same issue yet, so it will not happen through a version upgrade.

But I wanted to find a solution in the current version.

Thank you for the reply!
Note You need to log in before you can comment on or make changes to this bug.