+++ This bug was initially created as a clone of Bug #1418629 +++ +++ This bug was initially created as a clone of Bug #1415101 +++ Description of problem: ======================= On my systemic setup , glustershd crashed for the exact testing information kindly refer to <hidden> root@dhcp37-154 ~]# file /core.3893 /core.3893: ELF 64-bit LSB core file x86-64, version 1 (SYSV), SVR4-style, from '/usr/sbin/glusterfs -s localhost --volfile-id gluster/glustershd -p /var/lib/gl', real uid: 0, effective uid: 0, real gid: 0, effective gid: 0, execfn: '/usr/sbin/glusterfs', platform: 'x86_64' [root@dhcp37-154 ~]# [root@dhcp37-154 ~]# [root@dhcp37-154 ~]# [root@dhcp37-154 ~]# [root@dhcp37-154 ~]# [root@dhcp37-154 ~]# gdb /usr/sbin/glusterfs /core.3893 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 3914] [New LWP 13648] [New LWP 3894] [New LWP 3895] [New LWP 13826] [New LWP 3898] [New LWP 3897] [New LWP 3896] [New LWP 3893] [Thread debugging using libthread_db enabled] Using host libthread_db library "/lib64/libthread_db.so.1". Core was generated by `/usr/sbin/glusterfs -s localhost --volfile-id gluster/glustershd -p /var/lib/gl'. Program terminated with signal 11, Segmentation fault. #0 0x00007fd8bda87ce5 in __gf_free (free_ptr=0x7fd8ac21f630) at mem-pool.c:314 314 GF_ASSERT (GF_MEM_TRAILER_MAGIC == Missing separate debuginfos, use: debuginfo-install glibc-2.17-157.el7_3.1.x86_64 keyutils-libs-1.5.8-3.el7.x86_64 krb5-libs-1.14.1-27.el7_3.x86_64 libcom_err-1.42.9-9.el7.x86_64 libgcc-4.8.5-11.el7.x86_64 libselinux-2.5-6.el7.x86_64 libuuid-2.23.2-33.el7.x86_64 openssl-libs-1.0.1e-60.el7.x86_64 pcre-8.32-15.el7_2.1.x86_64 zlib-1.2.7-17.el7.x86_64 (gdb) bt #0 0x00007fd8bda87ce5 in __gf_free (free_ptr=0x7fd8ac21f630) at mem-pool.c:314 #1 0x00007fd8b004746b in client_fdctx_destroy (this=<optimized out>, fdctx=0x7fd8ac21f630) at client-rpc-fops.c:3304 #2 0x00007fd8b0049946 in client_child_up_reopen_done (fdctx=0x7fd8ac21f630, this=0x7fd8ac00f7a0) at client-handshake.c:672 #3 0x00007fd8b0048811 in client3_3_reopendir_cbk (req=<optimized out>, iov=<optimized out>, count=<optimized out>, myframe=0x7fd8bb53bb30) at client-handshake.c:832 #4 0x00007fd8bd82b6e0 in rpc_clnt_handle_reply (clnt=clnt@entry=0x7fd8ac07b8f0, pollin=pollin@entry=0x7fd8a0002750) at rpc-clnt.c:791 #5 0x00007fd8bd82b9cf in rpc_clnt_notify (trans=<optimized out>, mydata=0x7fd8ac07b948, event=<optimized out>, data=0x7fd8a0002750) at rpc-clnt.c:971 #6 0x00007fd8bd827893 in rpc_transport_notify (this=this@entry=0x7fd8ac08b5d0, event=event@entry=RPC_TRANSPORT_MSG_RECEIVED, data=data@entry=0x7fd8a0002750) at rpc-transport.c:538 #7 0x00007fd8b23192d4 in socket_event_poll_in (this=this@entry=0x7fd8ac08b5d0) at socket.c:2267 #8 0x00007fd8b231b785 in socket_event_handler (fd=<optimized out>, idx=8, data=0x7fd8ac08b5d0, poll_in=1, poll_out=0, poll_err=0) at socket.c:2397 #9 0x00007fd8bdabb5b0 in event_dispatch_epoll_handler (event=0x7fd8a946de80, event_pool=0x7fd8be59df00) at event-epoll.c:571 #10 event_dispatch_epoll_worker (data=0x7fd8ac03dfc0) at event-epoll.c:674 #11 0x00007fd8bc8c2dc5 in start_thread () from /lib64/libpthread.so.0 #12 0x00007fd8bc20773d in clone () from /lib64/libc.so.6 (gdb) #0 0x00007fd8bda87ce5 in __gf_free (free_ptr=0x7fd8ac21f630) at mem-pool.c:314 #1 0x00007fd8b004746b in client_fdctx_destroy (this=<optimized out>, fdctx=0x7fd8ac21f630) at client-rpc-fops.c:3304 #2 0x00007fd8b0049946 in client_child_up_reopen_done (fdctx=0x7fd8ac21f630, this=0x7fd8ac00f7a0) at client-handshake.c:672 #3 0x00007fd8b0048811 in client3_3_reopendir_cbk (req=<optimized out>, iov=<optimized out>, count=<optimized out>, myframe=0x7fd8bb53bb30) at client-handshake.c:832 #4 0x00007fd8bd82b6e0 in rpc_clnt_handle_reply (clnt=clnt@entry=0x7fd8ac07b8f0, pollin=pollin@entry=0x7fd8a0002750) at rpc-clnt.c:791 #5 0x00007fd8bd82b9cf in rpc_clnt_notify (trans=<optimized out>, mydata=0x7fd8ac07b948, event=<optimized out>, data=0x7fd8a0002750) at rpc-clnt.c:971 #6 0x00007fd8bd827893 in rpc_transport_notify (this=this@entry=0x7fd8ac08b5d0, event=event@entry=RPC_TRANSPORT_MSG_RECEIVED, data=data@entry=0x7fd8a0002750) at rpc-transport.c:538 #7 0x00007fd8b23192d4 in socket_event_poll_in (this=this@entry=0x7fd8ac08b5d0) at socket.c:2267 #8 0x00007fd8b231b785 in socket_event_handler (fd=<optimized out>, idx=8, data=0x7fd8ac08b5d0, poll_in=1, poll_out=0, poll_err=0) at socket.c:2397 #9 0x00007fd8bdabb5b0 in event_dispatch_epoll_handler (event=0x7fd8a946de80, event_pool=0x7fd8be59df00) at event-epoll.c:571 #10 event_dispatch_epoll_worker (data=0x7fd8ac03dfc0) at event-epoll.c:674 #11 0x00007fd8bc8c2dc5 in start_thread () from /lib64/libpthread.so.0 #12 0x00007fd8bc20773d in clone () from /lib64/libc.so.6 (gdb) #0 0x00007fd8bda87ce5 in __gf_free (free_ptr=0x7fd8ac21f630) at mem-pool.c:314 #1 0x00007fd8b004746b in client_fdctx_destroy (this=<optimized out>, fdctx=0x7fd8ac21f630) at client-rpc-fops.c:3304 #2 0x00007fd8b0049946 in client_child_up_reopen_done (fdctx=0x7fd8ac21f630, this=0x7fd8ac00f7a0) at client-handshake.c:672 #3 0x00007fd8b0048811 in client3_3_reopendir_cbk (req=<optimized out>, iov=<optimized out>, count=<optimized out>, myframe=0x7fd8bb53bb30) at client-handshake.c:832 #4 0x00007fd8bd82b6e0 in rpc_clnt_handle_reply (clnt=clnt@entry=0x7fd8ac07b8f0, pollin=pollin@entry=0x7fd8a0002750) at rpc-clnt.c:791 #5 0x00007fd8bd82b9cf in rpc_clnt_notify (trans=<optimized out>, mydata=0x7fd8ac07b948, event=<optimized out>, data=0x7fd8a0002750) at rpc-clnt.c:971 #6 0x00007fd8bd827893 in rpc_transport_notify (this=this@entry=0x7fd8ac08b5d0, event=event@entry=RPC_TRANSPORT_MSG_RECEIVED, data=data@entry=0x7fd8a0002750) at rpc-transport.c:538 #7 0x00007fd8b23192d4 in socket_event_poll_in (this=this@entry=0x7fd8ac08b5d0) at socket.c:2267 #8 0x00007fd8b231b785 in socket_event_handler (fd=<optimized out>, idx=8, data=0x7fd8ac08b5d0, poll_in=1, poll_out=0, poll_err=0) at socket.c:2397 #9 0x00007fd8bdabb5b0 in event_dispatch_epoll_handler (event=0x7fd8a946de80, event_pool=0x7fd8be59df00) at event-epoll.c:571 #10 event_dispatch_epoll_worker (data=0x7fd8ac03dfc0) at event-epoll.c:674 #11 0x00007fd8bc8c2dc5 in start_thread () from /lib64/libpthread.so.0 #12 0x00007fd8bc20773d in clone () from /lib64/libc.so.6 (gdb) #0 0x00007fd8bda87ce5 in __gf_free (free_ptr=0x7fd8ac21f630) at mem-pool.c:314 #1 0x00007fd8b004746b in client_fdctx_destroy (this=<optimized out>, fdctx=0x7fd8ac21f630) at client-rpc-fops.c:3304 #2 0x00007fd8b0049946 in client_child_up_reopen_done (fdctx=0x7fd8ac21f630, this=0x7fd8ac00f7a0) at client-handshake.c:672 #3 0x00007fd8b0048811 in client3_3_reopendir_cbk (req=<optimized out>, iov=<optimized out>, count=<optimized out>, myframe=0x7fd8bb53bb30) at client-handshake.c:832 #4 0x00007fd8bd82b6e0 in rpc_clnt_handle_reply (clnt=clnt@entry=0x7fd8ac07b8f0, pollin=pollin@entry=0x7fd8a0002750) at rpc-clnt.c:791 #5 0x00007fd8bd82b9cf in rpc_clnt_notify (trans=<optimized out>, mydata=0x7fd8ac07b948, event=<optimized out>, data=0x7fd8a0002750) at rpc-clnt.c:971 #6 0x00007fd8bd827893 in rpc_transport_notify (this=this@entry=0x7fd8ac08b5d0, event=event@entry=RPC_TRANSPORT_MSG_RECEIVED, data=data@entry=0x7fd8a0002750) at rpc-transport.c:538 #7 0x00007fd8b23192d4 in socket_event_poll_in (this=this@entry=0x7fd8ac08b5d0) at socket.c:2267 #8 0x00007fd8b231b785 in socket_event_handler (fd=<optimized out>, idx=8, data=0x7fd8ac08b5d0, poll_in=1, poll_out=0, poll_err=0) at socket.c:2397 #9 0x00007fd8bdabb5b0 in event_dispatch_epoll_handler (event=0x7fd8a946de80, event_pool=0x7fd8be59df00) at event-epoll.c:571 #10 event_dispatch_epoll_worker (data=0x7fd8ac03dfc0) at event-epoll.c:674 #11 0x00007fd8bc8c2dc5 in start_thread () from /lib64/libpthread.so.0 #12 0x00007fd8bc20773d in clone () from /lib64/libc.so.6 (gdb) #0 0x00007fd8bda87ce5 in __gf_free (free_ptr=0x7fd8ac21f630) at mem-pool.c:314 #1 0x00007fd8b004746b in client_fdctx_destroy (this=<optimized out>, fdctx=0x7fd8ac21f630) at client-rpc-fops.c:3304 #2 0x00007fd8b0049946 in client_child_up_reopen_done (fdctx=0x7fd8ac21f630, this=0x7fd8ac00f7a0) at client-handshake.c:672 #3 0x00007fd8b0048811 in client3_3_reopendir_cbk (req=<optimized out>, iov=<optimized out>, count=<optimized out>, myframe=0x7fd8bb53bb30) at client-handshake.c:832 #4 0x00007fd8bd82b6e0 in rpc_clnt_handle_reply (clnt=clnt@entry=0x7fd8ac07b8f0, pollin=pollin@entry=0x7fd8a0002750) at rpc-clnt.c:791 #5 0x00007fd8bd82b9cf in rpc_clnt_notify (trans=<optimized out>, mydata=0x7fd8ac07b948, event=<optimized out>, data=0x7fd8a0002750) at rpc-clnt.c:971 #6 0x00007fd8bd827893 in rpc_transport_notify (this=this@entry=0x7fd8ac08b5d0, event=event@entry=RPC_TRANSPORT_MSG_RECEIVED, data=data@entry=0x7fd8a0002750) at rpc-transport.c:538 #7 0x00007fd8b23192d4 in socket_event_poll_in (this=this@entry=0x7fd8ac08b5d0) at socket.c:2267 #8 0x00007fd8b231b785 in socket_event_handler (fd=<optimized out>, idx=8, data=0x7fd8ac08b5d0, poll_in=1, poll_out=0, poll_err=0) at socket.c:2397 #9 0x00007fd8bdabb5b0 in event_dispatch_epoll_handler (event=0x7fd8a946de80, event_pool=0x7fd8be59df00) at event-epoll.c:571 #10 event_dispatch_epoll_worker (data=0x7fd8ac03dfc0) at event-epoll.c:674 #11 0x00007fd8bc8c2dc5 in start_thread () from /lib64/libpthread.so.0 #12 0x00007fd8bc20773d in clone () from /lib64/libc.so.6 (gdb) Version-Release number of selected component (if applicable): ===================================== 3.8.4-12 --- Additional comment from nchilaka on 2017-01-20 04:30:28 EST --- Volume Name: systemic Type: Distributed-Replicate Volume ID: 8c0f9f83-65a0-49df-a8e8-d3f8ca08bd9a Status: Started Snapshot Count: 0 Number of Bricks: 4 x 2 = 8 Transport-type: tcp Bricks: Brick1: 10.70.35.20:/rhs/brick1/systemic Brick2: 10.70.37.86:/rhs/brick1/systemic Brick3: 10.70.35.156:/rhs/brick1/systemic Brick4: 10.70.37.154:/rhs/brick1/systemic Brick5: 10.70.35.20:/rhs/brick2/systemic Brick6: 10.70.37.86:/rhs/brick2/systemic Brick7: 10.70.35.156:/rhs/brick2/systemic Brick8: 10.70.37.154:/rhs/brick2/systemic Options Reconfigured: diagnostics.count-fop-hits: on diagnostics.latency-measurement: on performance.md-cache-timeout: 600 performance.cache-invalidation: on performance.stat-prefetch: on features.cache-invalidation-timeout: 600 features.cache-invalidation: on features.quota-deem-statfs: on features.inode-quota: on features.quota: on transport.address-family: inet performance.readdir-ahead: on nfs.disable: on More information: It is a 4x2 volume spanning across 4 nodes, each hosting 2 bricks node 1 and 2 which host b1,b2,b5,b6 have no heal pendings or files in splitbrains node 3 and 4 which host b3,b4,b7,b8 have lot of files in pending heals and lot of directories in split-brains Note: n4 is the node where shd crashed following is heal info pending information: [root@dhcp35-20 glusterfs]# gluster v heal systemic info|grep ntries Number of entries: 0 Number of entries: 0 Number of entries: 6753 Number of entries: 15934 Number of entries: 0 Number of entries: 0 Number of entries: 1084 Number of entries: 8011 split brain details are attached --- Additional comment from nchilaka on 2017-01-20 07:01:38 EST --- almost all (except 3 files which were logging directory creations) split=brain entries are directories, which were being created from 3 different clients in parallel node 3 has seen a few kernel hang information in dmesg, this could be that one of the client creating directory couldn't successfully create over here due to that momentary hang, while the other client successfully wrote to this node first and hence may be this caused the splitbrain However, I did validate a couple of directories in the xattrs to see if they were due to gfid mismatch, but rather found them blaming each other in entries bits --- Additional comment from nchilaka on 2017-01-20 07:28:04 EST --- kernel hangs in dmesg of node3 ....other nodes have none [root@dhcp35-156 ~]# dmesg -T [Thu Jan 19 22:18:13 2017] INFO: task xfsaild/dm-0:487 blocked for more than 120 seconds. [Thu Jan 19 22:18:13 2017] "echo 0 > /proc/sys/kernel/hung_task_timeout_secs" disables this message. [Thu Jan 19 22:18:13 2017] xfsaild/dm-0 D ffff88044fb87000 0 487 2 0x00000000 [Thu Jan 19 22:18:13 2017] ffff880450293d58 0000000000000046 ffff88044fe31f60 ffff880450293fd8 [Thu Jan 19 22:18:13 2017] ffff880450293fd8 ffff880450293fd8 ffff88044fe31f60 ffff88045022ac00 [Thu Jan 19 22:18:13 2017] 0000000000000000 ffff88044fe31f60 ffff880466014128 ffff88044fb87000 [Thu Jan 19 22:18:13 2017] Call Trace: [Thu Jan 19 22:18:13 2017] [<ffffffff8168b799>] schedule+0x29/0x70 [Thu Jan 19 22:18:13 2017] [<ffffffffa029497d>] _xfs_log_force+0x1bd/0x2b0 [xfs] [Thu Jan 19 22:18:13 2017] [<ffffffff810c4fe0>] ? wake_up_state+0x20/0x20 [Thu Jan 19 22:18:13 2017] [<ffffffffa0294a96>] xfs_log_force+0x26/0x80 [xfs] [Thu Jan 19 22:18:13 2017] [<ffffffffa02a0360>] ? xfs_trans_ail_cursor_first+0x90/0x90 [xfs] [Thu Jan 19 22:18:13 2017] [<ffffffffa02a04ba>] xfsaild+0x15a/0x660 [xfs] [Thu Jan 19 22:18:13 2017] [<ffffffffa02a0360>] ? xfs_trans_ail_cursor_first+0x90/0x90 [xfs] [Thu Jan 19 22:18:13 2017] [<ffffffff810b064f>] kthread+0xcf/0xe0 [Thu Jan 19 22:18:13 2017] [<ffffffff810b0580>] ? kthread_create_on_node+0x140/0x140 [Thu Jan 19 22:18:13 2017] [<ffffffff81696618>] ret_from_fork+0x58/0x90 [Thu Jan 19 22:18:13 2017] [<ffffffff810b0580>] ? kthread_create_on_node+0x140/0x140 [Thu Jan 19 22:24:13 2017] INFO: task glusterd:1323 blocked for more than 120 seconds. [Thu Jan 19 22:24:13 2017] "echo 0 > /proc/sys/kernel/hung_task_timeout_secs" disables this message. [Thu Jan 19 22:24:13 2017] glusterd D ffff8804505f7968 0 1323 1 0x00000080 [Thu Jan 19 22:24:13 2017] ffff8800bb843c70 0000000000000082 ffff88044bb23ec0 ffff8800bb843fd8 [Thu Jan 19 22:24:13 2017] ffff8800bb843fd8 ffff8800bb843fd8 ffff88044bb23ec0 ffff8804505f7960 [Thu Jan 19 22:24:13 2017] ffff8804505f7964 ffff88044bb23ec0 00000000ffffffff ffff8804505f7968 [Thu Jan 19 22:24:13 2017] Call Trace: [Thu Jan 19 22:24:13 2017] [<ffffffff8168c889>] schedule_preempt_disabled+0x29/0x70 [Thu Jan 19 22:24:13 2017] [<ffffffff8168a4e5>] __mutex_lock_slowpath+0xc5/0x1c0 [Thu Jan 19 22:24:13 2017] [<ffffffff8168994f>] mutex_lock+0x1f/0x2f [Thu Jan 19 22:24:13 2017] [<ffffffff8120ccff>] do_last+0x28f/0x12a0 [Thu Jan 19 22:24:13 2017] [<ffffffff811de456>] ? kmem_cache_alloc_trace+0x1d6/0x200 [Thu Jan 19 22:24:13 2017] [<ffffffff8120ddd2>] path_openat+0xc2/0x490 [Thu Jan 19 22:24:13 2017] [<ffffffff811b0f21>] ? handle_mm_fault+0x6b1/0xfe0 [Thu Jan 19 22:24:13 2017] [<ffffffff810f5090>] ? futex_wake+0x80/0x160 [Thu Jan 19 22:24:13 2017] [<ffffffff8120ff4b>] do_filp_open+0x4b/0xb0 [Thu Jan 19 22:24:13 2017] [<ffffffff8121cbc7>] ? __alloc_fd+0xa7/0x130 [Thu Jan 19 22:24:13 2017] [<ffffffff811fd453>] do_sys_open+0xf3/0x1f0 [Thu Jan 19 22:24:13 2017] [<ffffffff811fd56e>] SyS_open+0x1e/0x20 [Thu Jan 19 22:24:13 2017] [<ffffffff816966c9>] system_call_fastpath+0x16/0x1b [Thu Jan 19 22:24:13 2017] INFO: task glusterfsd:4048 blocked for more than 120 seconds. [Thu Jan 19 22:24:13 2017] "echo 0 > /proc/sys/kernel/hung_task_timeout_secs" disables this message. [Thu Jan 19 22:24:13 2017] glusterfsd D ffff8804505f7968 0 4048 1 0x00000080 [Thu Jan 19 22:24:13 2017] ffff8804522cfdf0 0000000000000086 ffff88043a3c1f60 ffff8804522cffd8 [Thu Jan 19 22:24:13 2017] ffff8804522cffd8 ffff8804522cffd8 ffff88043a3c1f60 ffff8804505f7960 [Thu Jan 19 22:24:13 2017] ffff8804505f7964 ffff88043a3c1f60 00000000ffffffff ffff8804505f7968 [Thu Jan 19 22:24:13 2017] Call Trace: [Thu Jan 19 22:24:13 2017] [<ffffffff8168c889>] schedule_preempt_disabled+0x29/0x70 [Thu Jan 19 22:24:13 2017] [<ffffffff8168a4e5>] __mutex_lock_slowpath+0xc5/0x1c0 [Thu Jan 19 22:24:13 2017] [<ffffffff8168994f>] mutex_lock+0x1f/0x2f [Thu Jan 19 22:24:13 2017] [<ffffffff8120f40b>] do_unlinkat+0x13b/0x2b0 [Thu Jan 19 22:24:13 2017] [<ffffffff81210486>] SyS_unlink+0x16/0x20 [Thu Jan 19 22:24:13 2017] [<ffffffff816966c9>] system_call_fastpath+0x16/0x1b [Thu Jan 19 22:24:13 2017] INFO: task glusterfsd:4049 blocked for more than 120 seconds. [Thu Jan 19 22:24:13 2017] "echo 0 > /proc/sys/kernel/hung_task_timeout_secs" disables this message. [Thu Jan 19 22:24:13 2017] glusterfsd D ffff8804505f7968 0 4049 1 0x00000080 [Thu Jan 19 22:24:13 2017] ffff880451b4bc70 0000000000000086 ffff88043a3c4e70 ffff880451b4bfd8 [Thu Jan 19 22:24:13 2017] ffff880451b4bfd8 ffff880451b4bfd8 ffff88043a3c4e70 ffff8804505f7960 [Thu Jan 19 22:24:13 2017] ffff8804505f7964 ffff88043a3c4e70 00000000ffffffff ffff8804505f7968 [Thu Jan 19 22:24:13 2017] Call Trace: [Thu Jan 19 22:24:13 2017] [<ffffffff8168c889>] schedule_preempt_disabled+0x29/0x70 [Thu Jan 19 22:24:13 2017] [<ffffffff8168a4e5>] __mutex_lock_slowpath+0xc5/0x1c0 [Thu Jan 19 22:24:13 2017] [<ffffffff8168994f>] mutex_lock+0x1f/0x2f [Thu Jan 19 22:24:13 2017] [<ffffffff8120ccff>] do_last+0x28f/0x12a0 [Thu Jan 19 22:24:13 2017] [<ffffffff811de456>] ? kmem_cache_alloc_trace+0x1d6/0x200 [Thu Jan 19 22:24:13 2017] [<ffffffff8120ddd2>] path_openat+0xc2/0x490 [Thu Jan 19 22:24:13 2017] [<ffffffff810f5090>] ? futex_wake+0x80/0x160 [Thu Jan 19 22:24:13 2017] [<ffffffff8120ff4b>] do_filp_open+0x4b/0xb0 [Thu Jan 19 22:24:13 2017] [<ffffffff8121cbc7>] ? __alloc_fd+0xa7/0x130 [Thu Jan 19 22:24:13 2017] [<ffffffff811fd453>] do_sys_open+0xf3/0x1f0 [Thu Jan 19 22:24:13 2017] [<ffffffff811fd56e>] SyS_open+0x1e/0x20 [Thu Jan 19 22:24:13 2017] [<ffffffff816966c9>] system_call_fastpath+0x16/0x1b [Thu Jan 19 22:24:13 2017] INFO: task glusterfsd:4380 blocked for more than 120 seconds. [Thu Jan 19 22:24:13 2017] "echo 0 > /proc/sys/kernel/hung_task_timeout_secs" disables this message. [Thu Jan 19 22:24:13 2017] glusterfsd D ffff8804505f7968 0 4380 1 0x00000080 [Thu Jan 19 22:24:13 2017] ffff880417a3bdf0 0000000000000086 ffff88043eefaf10 ffff880417a3bfd8 [Thu Jan 19 22:24:13 2017] ffff880417a3bfd8 ffff880417a3bfd8 ffff88043eefaf10 ffff8804505f7960 [Thu Jan 19 22:24:13 2017] ffff8804505f7964 ffff88043eefaf10 00000000ffffffff ffff8804505f7968 [Thu Jan 19 22:24:13 2017] Call Trace: [Thu Jan 19 22:24:13 2017] [<ffffffff8168c889>] schedule_preempt_disabled+0x29/0x70 [Thu Jan 19 22:24:13 2017] [<ffffffff8168a4e5>] __mutex_lock_slowpath+0xc5/0x1c0 [Thu Jan 19 22:24:13 2017] [<ffffffff8168994f>] mutex_lock+0x1f/0x2f [Thu Jan 19 22:24:13 2017] [<ffffffff8120f40b>] do_unlinkat+0x13b/0x2b0 [Thu Jan 19 22:24:13 2017] [<ffffffff81210486>] SyS_unlink+0x16/0x20 [Thu Jan 19 22:24:13 2017] [<ffffffff816966c9>] system_call_fastpath+0x16/0x1b [Thu Jan 19 22:24:13 2017] INFO: task glusterfsd:4442 blocked for more than 120 seconds. [Thu Jan 19 22:24:13 2017] "echo 0 > /proc/sys/kernel/hung_task_timeout_secs" disables this message. [Thu Jan 19 22:24:13 2017] glusterfsd D ffff8804505f7968 0 4442 1 0x00000080 [Thu Jan 19 22:24:13 2017] ffff8803c960bdf0 0000000000000086 ffff88043c225e20 ffff8803c960bfd8 [Thu Jan 19 22:24:13 2017] ffff8803c960bfd8 ffff8803c960bfd8 ffff88043c225e20 ffff8804505f7960 [Thu Jan 19 22:24:13 2017] ffff8804505f7964 ffff88043c225e20 00000000ffffffff ffff8804505f7968 [Thu Jan 19 22:24:13 2017] Call Trace: [Thu Jan 19 22:24:13 2017] [<ffffffff8168c889>] schedule_preempt_disabled+0x29/0x70 [Thu Jan 19 22:24:13 2017] [<ffffffff8168a4e5>] __mutex_lock_slowpath+0xc5/0x1c0 [Thu Jan 19 22:24:13 2017] [<ffffffff8168994f>] mutex_lock+0x1f/0x2f [Thu Jan 19 22:24:13 2017] [<ffffffff8120f40b>] do_unlinkat+0x13b/0x2b0 [Thu Jan 19 22:24:13 2017] [<ffffffff81210486>] SyS_unlink+0x16/0x20 [Thu Jan 19 22:24:13 2017] [<ffffffff816966c9>] system_call_fastpath+0x16/0x1b [Thu Jan 19 22:24:13 2017] INFO: task glusterfsd:4994 blocked for more than 120 seconds. [Thu Jan 19 22:24:13 2017] "echo 0 > /proc/sys/kernel/hung_task_timeout_secs" disables this message. [Thu Jan 19 22:24:13 2017] glusterfsd D ffff8804505f7968 0 4994 1 0x00000080 [Thu Jan 19 22:24:13 2017] ffff88000b1c7df0 0000000000000086 ffff88043c220fb0 ffff88000b1c7fd8 [Thu Jan 19 22:24:13 2017] ffff88000b1c7fd8 ffff88000b1c7fd8 ffff88043c220fb0 ffff8804505f7960 [Thu Jan 19 22:24:13 2017] ffff8804505f7964 ffff88043c220fb0 00000000ffffffff ffff8804505f7968 [Thu Jan 19 22:24:13 2017] Call Trace: [Thu Jan 19 22:24:13 2017] [<ffffffff8168c889>] schedule_preempt_disabled+0x29/0x70 [Thu Jan 19 22:24:13 2017] [<ffffffff8168a4e5>] __mutex_lock_slowpath+0xc5/0x1c0 [Thu Jan 19 22:24:13 2017] [<ffffffff8168994f>] mutex_lock+0x1f/0x2f [Thu Jan 19 22:24:13 2017] [<ffffffff8120f40b>] do_unlinkat+0x13b/0x2b0 [Thu Jan 19 22:24:13 2017] [<ffffffff811b4463>] ? remove_vma+0x63/0x70 [Thu Jan 19 22:24:13 2017] [<ffffffff81210486>] SyS_unlink+0x16/0x20 [Thu Jan 19 22:24:13 2017] [<ffffffff816966c9>] system_call_fastpath+0x16/0x1b [Thu Jan 19 22:24:13 2017] INFO: task glusterfsd:4996 blocked for more than 120 seconds. [Thu Jan 19 22:24:13 2017] "echo 0 > /proc/sys/kernel/hung_task_timeout_secs" disables this message. [Thu Jan 19 22:24:13 2017] glusterfsd D ffff8804505f7968 0 4996 1 0x00000080 [Thu Jan 19 22:24:13 2017] ffff88000b1afc70 0000000000000086 ffff88044037ce70 ffff88000b1affd8 [Thu Jan 19 22:24:13 2017] ffff88000b1affd8 ffff88000b1affd8 ffff88044037ce70 ffff8804505f7960 [Thu Jan 19 22:24:13 2017] ffff8804505f7964 ffff88044037ce70 00000000ffffffff ffff8804505f7968 [Thu Jan 19 22:24:13 2017] Call Trace: [Thu Jan 19 22:24:13 2017] [<ffffffff8168c889>] schedule_preempt_disabled+0x29/0x70 [Thu Jan 19 22:24:13 2017] [<ffffffff8168a4e5>] __mutex_lock_slowpath+0xc5/0x1c0 [Thu Jan 19 22:24:13 2017] [<ffffffff8168994f>] mutex_lock+0x1f/0x2f [Thu Jan 19 22:24:13 2017] [<ffffffff8120ccff>] do_last+0x28f/0x12a0 [Thu Jan 19 22:24:13 2017] [<ffffffff811de456>] ? kmem_cache_alloc_trace+0x1d6/0x200 [Thu Jan 19 22:24:13 2017] [<ffffffff8120ddd2>] path_openat+0xc2/0x490 [Thu Jan 19 22:24:13 2017] [<ffffffff8120ff4b>] do_filp_open+0x4b/0xb0 [Thu Jan 19 22:24:13 2017] [<ffffffff8121cbc7>] ? __alloc_fd+0xa7/0x130 [Thu Jan 19 22:24:13 2017] [<ffffffff811fd453>] do_sys_open+0xf3/0x1f0 [Thu Jan 19 22:24:13 2017] [<ffffffff811fd56e>] SyS_open+0x1e/0x20 [Thu Jan 19 22:24:13 2017] [<ffffffff816966c9>] system_call_fastpath+0x16/0x1b [Thu Jan 19 22:24:13 2017] INFO: task glusterfsd:6159 blocked for more than 120 seconds. [Thu Jan 19 22:24:13 2017] "echo 0 > /proc/sys/kernel/hung_task_timeout_secs" disables this message. [Thu Jan 19 22:24:13 2017] glusterfsd D ffff8804505f7968 0 6159 1 0x00000080 [Thu Jan 19 22:24:13 2017] ffff88009db83df0 0000000000000086 ffff880452214e70 ffff88009db83fd8 [Thu Jan 19 22:24:13 2017] ffff88009db83fd8 ffff88009db83fd8 ffff880452214e70 ffff8804505f7960 [Thu Jan 19 22:24:13 2017] ffff8804505f7964 ffff880452214e70 00000000ffffffff ffff8804505f7968 [Thu Jan 19 22:24:13 2017] Call Trace: [Thu Jan 19 22:24:13 2017] [<ffffffff8168c889>] schedule_preempt_disabled+0x29/0x70 [Thu Jan 19 22:24:13 2017] [<ffffffff8168a4e5>] __mutex_lock_slowpath+0xc5/0x1c0 [Thu Jan 19 22:24:13 2017] [<ffffffff8168994f>] mutex_lock+0x1f/0x2f [Thu Jan 19 22:24:13 2017] [<ffffffff8120f40b>] do_unlinkat+0x13b/0x2b0 [Thu Jan 19 22:24:13 2017] [<ffffffff811b4463>] ? remove_vma+0x63/0x70 [Thu Jan 19 22:24:13 2017] [<ffffffff81210486>] SyS_unlink+0x16/0x20 [Thu Jan 19 22:24:13 2017] [<ffffffff816966c9>] system_call_fastpath+0x16/0x1b [Thu Jan 19 22:24:13 2017] INFO: task glusterfsd:6276 blocked for more than 120 seconds. [Thu Jan 19 22:24:13 2017] "echo 0 > /proc/sys/kernel/hung_task_timeout_secs" disables this message. [Thu Jan 19 22:24:13 2017] glusterfsd D ffff8804505f7968 0 6276 1 0x00000080 [Thu Jan 19 22:24:13 2017] ffff88000618fdf0 0000000000000086 ffff88044debce70 ffff88000618ffd8 [Thu Jan 19 22:24:13 2017] ffff88000618ffd8 ffff88000618ffd8 ffff88044debce70 ffff8804505f7960 [Thu Jan 19 22:24:13 2017] ffff8804505f7964 ffff88044debce70 00000000ffffffff ffff8804505f7968 [Thu Jan 19 22:24:13 2017] Call Trace: [Thu Jan 19 22:24:13 2017] [<ffffffff8168c889>] schedule_preempt_disabled+0x29/0x70 [Thu Jan 19 22:24:13 2017] [<ffffffff8168a4e5>] __mutex_lock_slowpath+0xc5/0x1c0 [Thu Jan 19 22:24:13 2017] [<ffffffff8168994f>] mutex_lock+0x1f/0x2f [Thu Jan 19 22:24:13 2017] [<ffffffff8120f40b>] do_unlinkat+0x13b/0x2b0 [Thu Jan 19 22:24:13 2017] [<ffffffff81210486>] SyS_unlink+0x16/0x20 [Thu Jan 19 22:24:13 2017] [<ffffffff816966c9>] system_call_fastpath+0x16/0x1b [Fri Jan 20 15:22:26 2017] nr_pdflush_threads exported in /proc is scheduled for removal [Fri Jan 20 15:27:08 2017] warning: `turbostat' uses 32-bit capabilities (legacy support in use) [root@dhcp35-156 ~]# --- Additional comment from nchilaka on 2017-01-20 07:38:26 EST --- client logs which were creating parallely directories /var/www/html/sosreports/nchilaka/bug.1415101/clients/same-dir-create-clients --- Additional comment from nchilaka on 2017-01-20 07:39:09 EST --- web link http://rhsqe-repo.lab.eng.blr.redhat.com/sosreports/nchilaka/bug.1415101/clients/same-dir-create-clients/ --- Additional comment from nchilaka on 2017-01-20 07:41:20 EST --- one kernel hang on 2nd client of the same-dir-create set ie rhs-client23 [root@rhs-client23 tmp]# dmesg [990206.629702] INFO: task mkdir:16145 blocked for more than 120 seconds. [990206.629742] "echo 0 > /proc/sys/kernel/hung_task_timeout_secs" disables this message. [990206.629775] mkdir D ffff8804719280b0 0 16145 10981 0x00000080 [990206.629780] ffff88043b523d90 0000000000000086 ffff88043b495c00 ffff88043b523fd8 [990206.629785] ffff88043b523fd8 ffff88043b523fd8 ffff88043b495c00 ffff8804719280a8 [990206.629788] ffff8804719280ac ffff88043b495c00 00000000ffffffff ffff8804719280b0 [990206.629791] Call Trace: [990206.629802] [<ffffffff8163b9e9>] schedule_preempt_disabled+0x29/0x70 [990206.629806] [<ffffffff816396e5>] __mutex_lock_slowpath+0xc5/0x1c0 [990206.629809] [<ffffffff81638b4f>] mutex_lock+0x1f/0x2f [990206.629814] [<ffffffff811ee085>] filename_create+0x85/0x180 [990206.629819] [<ffffffff811c0e65>] ? kmem_cache_alloc+0x35/0x1d0 [990206.629821] [<ffffffff811eec0f>] ? getname_flags+0x4f/0x1a0 [990206.629823] [<ffffffff811eec84>] ? getname_flags+0xc4/0x1a0 [990206.629825] [<ffffffff811eef31>] user_path_create+0x41/0x60 [990206.629829] [<ffffffff811f0246>] SyS_mkdirat+0x46/0xe0 [990206.629833] [<ffffffff81641113>] ? do_page_fault+0x23/0x80 [990206.629835] [<ffffffff811f02f9>] SyS_mkdir+0x19/0x20 [990206.629838] [<ffffffff81645909>] system_call_fastpath+0x16/0x1b [1003985.918712] SELinux: initialized (dev binfmt_misc, type binfmt_misc), uses genfs_contexts [1003990.523134] nr_pdflush_threads exported in /proc is scheduled for removal [1003994.086202] warning: `turbostat' uses 32-bit capabilities (legacy support in use) --- Additional comment from nchilaka on 2017-01-20 08:32:37 EST --- raised a seperate bug for rpc ping time out issue https://bugzilla.redhat.com/show_bug.cgi?id=1415178 - systemic testing: seeing lot of ping time outs which would lead to splitbrains --- Additional comment from Ravishankar N on 2017-01-24 07:54:27 EST --- RCA: This is due to client_fdctx_destroy() being called twice due to a race between client3_3_releasedir() and client_reopen_done(). The following are the steps to hit it. 1. shd sends an opendir to its children (client xlators) which send the fop to the bricks to get a valid fd. 2. Client xlator loses connection to the brick. fdctx->remotefd is -1 3. Client re-establishes connection. After handshake, it reopens the dir and sets fdctx->remotefd to a valid fd in client3_3_reopendir_cbk(). 4. Meanwhile, shd sends a fd unref after it is done with the opendir. This triggers a releasedir (since fd->refcount becomes 0). 5. client3_3_releasedir() sees that fdctx-->remotefd is a valid number (i.e not -1), sets fdctx->released=1 and calls client_fdctx_destroy() 6. As a continuation of step3, client_reopen_done() is called, which sees that fdctx->released==1 and again calls client_fdctx_destroy(). --- Additional comment from Worker Ant on 2017-02-02 06:39:13 EST --- REVIEW: https://review.gluster.org/16521 (protocol/client: Fix double free of client fdctx destroy) posted (#1) for review on master by Ravishankar N (ravishankar) --- Additional comment from Worker Ant on 2017-02-02 07:41:00 EST --- REVIEW: https://review.gluster.org/16521 (protocol/client: Fix double free of client fdctx destroy) posted (#2) for review on master by Ravishankar N (ravishankar) --- Additional comment from Worker Ant on 2017-02-08 06:18:57 EST --- REVIEW: https://review.gluster.org/16521 (protocol/client: Fix double free of client fdctx destroy) posted (#3) for review on master by Ravishankar N (ravishankar) --- Additional comment from Worker Ant on 2017-02-08 06:27:10 EST --- REVIEW: https://review.gluster.org/16521 (protocol/client: Fix double free of client fdctx destroy) posted (#4) for review on master by Ravishankar N (ravishankar) --- Additional comment from Worker Ant on 2017-02-09 01:04:19 EST --- REVIEW: https://review.gluster.org/16521 (protocol/client: Fix double free of client fdctx destroy) posted (#5) for review on master by Ravishankar N (ravishankar) --- Additional comment from Worker Ant on 2017-02-09 22:44:48 EST --- REVIEW: https://review.gluster.org/16521 (protocol/client: Fix double free of client fdctx destroy) posted (#6) for review on master by Ravishankar N (ravishankar) --- Additional comment from Worker Ant on 2017-02-09 22:52:24 EST --- REVIEW: https://review.gluster.org/16521 (protocol/client: Fix double free of client fdctx destroy) posted (#7) for review on master by Ravishankar N (ravishankar) --- Additional comment from Worker Ant on 2017-02-09 22:54:13 EST --- REVIEW: https://review.gluster.org/16521 (protocol/client: Fix double free of client fdctx destroy) posted (#8) for review on master by Ravishankar N (ravishankar) --- Additional comment from Worker Ant on 2017-02-13 06:29:27 EST --- COMMIT: https://review.gluster.org/16521 committed in master by Pranith Kumar Karampuri (pkarampu) ------ commit 25fc74f9d1f2b1e7bab76485a99f27abadd10b7b Author: Ravishankar N <ravishankar> Date: Thu Feb 2 16:41:45 2017 +0530 protocol/client: Fix double free of client fdctx destroy This patch fixes the race between fd re-open code and fd release code, both of which free the fd context due to a race in certain variable checks as explained below: 1. client process (shd in the case of this BZ) sends an opendir to its children (client xlators) which send the fop to the bricks to get a valid fd. 2. Client xlator loses connection to the brick. fdctx->remotefd is -1 3. Client re-establishes connection. After handshake, it reopens the dir and sets fdctx->remotefd to a valid fd in client3_3_reopendir_cbk(). 4. Meanwhile, shd sends a fd unref after it is done with the opendir. This triggers a releasedir (since fd->refcount becomes 0). 5. client3_3_releasedir() sees that fdctx-->remotefd is a valid number (i.e not -1), sets fdctx->released=1 and calls client_fdctx_destroy() 6. As a continuation of step3, client_reopen_done() is called by client3_3_reopendir_cbk(), which sees that fdctx->released==1 and again calls client_fdctx_destroy(). Depending on when step-5 does GF_FREE(fdctx), we may crash at any place in step-6 in client3_3_reopendir_cbk() when it tries to access fdctx->{whatever}. Change-Id: Ia50873d11763e084e41d2a1f4d53715438e5e947 BUG: 1418629 Signed-off-by: Ravishankar N <ravishankar> Reviewed-on: https://review.gluster.org/16521 CentOS-regression: Gluster Build System <jenkins.org> NetBSD-regression: NetBSD Build System <jenkins.org> Smoke: Gluster Build System <jenkins.org> Reviewed-by: Pranith Kumar Karampuri <pkarampu>
REVIEW: https://review.gluster.org/16619 (protocol/client: Fix double free of client fdctx destroy) posted (#1) for review on release-3.10 by Ravishankar N (ravishankar)
COMMIT: https://review.gluster.org/16619 committed in release-3.10 by Shyamsundar Ranganathan (srangana) ------ commit 5d8951afdc083008ad1d6f930291b36dca86c94f Author: Ravishankar N <ravishankar> Date: Thu Feb 2 16:41:45 2017 +0530 protocol/client: Fix double free of client fdctx destroy This patch fixes the race between fd re-open code and fd release code, both of which free the fd context due to a race in certain variable checks as explained below: 1. client process (shd in the case of this BZ) sends an opendir to its children (client xlators) which send the fop to the bricks to get a valid fd. 2. Client xlator loses connection to the brick. fdctx->remotefd is -1 3. Client re-establishes connection. After handshake, it reopens the dir and sets fdctx->remotefd to a valid fd in client3_3_reopendir_cbk(). 4. Meanwhile, shd sends a fd unref after it is done with the opendir. This triggers a releasedir (since fd->refcount becomes 0). 5. client3_3_releasedir() sees that fdctx-->remotefd is a valid number (i.e not -1), sets fdctx->released=1 and calls client_fdctx_destroy() 6. As a continuation of step3, client_reopen_done() is called by client3_3_reopendir_cbk(), which sees that fdctx->released==1 and again calls client_fdctx_destroy(). Depending on when step-5 does GF_FREE(fdctx), we may crash at any place in step-6 in client3_3_reopendir_cbk() when it tries to access fdctx->{whatever}. > Reviewed-on: https://review.gluster.org/16521 > CentOS-regression: Gluster Build System <jenkins.org> > NetBSD-regression: NetBSD Build System <jenkins.org> > Smoke: Gluster Build System <jenkins.org> > Reviewed-by: Pranith Kumar Karampuri <pkarampu> (cherry picked from commit 25fc74f9d1f2b1e7bab76485a99f27abadd10b7b) Change-Id: Ia50873d11763e084e41d2a1f4d53715438e5e947 BUG: 1422350 Signed-off-by: Ravishankar N <ravishankar> Reviewed-on: https://review.gluster.org/16619 Smoke: Gluster Build System <jenkins.org> NetBSD-regression: NetBSD Build System <jenkins.org> CentOS-regression: Gluster Build System <jenkins.org> Reviewed-by: Shyamsundar Ranganathan <srangana>
This bug is getting closed because a release has been made available that should address the reported issue. In case the problem is still not fixed with glusterfs-3.10.0, please open a new bug report. glusterfs-3.10.0 has been announced on the Gluster mailinglists [1], packages for several distributions should become available in the near future. Keep an eye on the Gluster Users mailinglist [2] and the update infrastructure for your distribution. [1] http://lists.gluster.org/pipermail/gluster-users/2017-February/030119.html [2] https://www.gluster.org/pipermail/gluster-users/