[Bugs] [Bug 1422351] New: glustershd process crashed on systemic setup

bugzilla at redhat.com bugzilla at redhat.com
Wed Feb 15 05:09:38 UTC 2017


https://bugzilla.redhat.com/show_bug.cgi?id=1422351

            Bug ID: 1422351
           Summary: glustershd process crashed on systemic setup
           Product: GlusterFS
           Version: 3.9
         Component: replicate
          Keywords: Triaged
          Severity: urgent
          Assignee: bugs at gluster.org
          Reporter: ravishankar at redhat.com
                CC: amukherj at redhat.com, bugs at gluster.org
        Depends On: 1422350



+++ This bug was initially created as a clone of Bug #1422350 +++

+++ 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 at 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 at dhcp37-154 ~]# 



[root at dhcp37-154 ~]# 
[root at dhcp37-154 ~]# 
[root at dhcp37-154 ~]# 
[root at dhcp37-154 ~]# 
[root at 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 at entry=0x7fd8ac07b8f0, pollin=pollin at 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 at entry=0x7fd8ac08b5d0, 
    event=event at entry=RPC_TRANSPORT_MSG_RECEIVED,
data=data at entry=0x7fd8a0002750) at rpc-transport.c:538
#7  0x00007fd8b23192d4 in socket_event_poll_in (this=this at 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 at entry=0x7fd8ac07b8f0, pollin=pollin at 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 at entry=0x7fd8ac08b5d0, 
    event=event at entry=RPC_TRANSPORT_MSG_RECEIVED,
data=data at entry=0x7fd8a0002750) at rpc-transport.c:538
#7  0x00007fd8b23192d4 in socket_event_poll_in (this=this at 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 at entry=0x7fd8ac07b8f0, pollin=pollin at 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 at entry=0x7fd8ac08b5d0, 
    event=event at entry=RPC_TRANSPORT_MSG_RECEIVED,
data=data at entry=0x7fd8a0002750) at rpc-transport.c:538
#7  0x00007fd8b23192d4 in socket_event_poll_in (this=this at 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 at entry=0x7fd8ac07b8f0, pollin=pollin at 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 at entry=0x7fd8ac08b5d0, 
    event=event at entry=RPC_TRANSPORT_MSG_RECEIVED,
data=data at entry=0x7fd8a0002750) at rpc-transport.c:538
#7  0x00007fd8b23192d4 in socket_event_poll_in (this=this at 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 at entry=0x7fd8ac07b8f0, pollin=pollin at 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 at entry=0x7fd8ac08b5d0, 
    event=event at entry=RPC_TRANSPORT_MSG_RECEIVED,
data=data at entry=0x7fd8a0002750) at rpc-transport.c:538
#7  0x00007fd8b23192d4 in socket_event_poll_in (this=this at 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 at 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 at 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 at 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 at 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 at redhat.com)

--- 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 at redhat.com)

--- 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 at redhat.com)

--- 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 at redhat.com)

--- 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 at redhat.com)

--- 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 at redhat.com)

--- 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 at redhat.com)

--- 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 at redhat.com)

--- 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 at redhat.com) 
------
commit 25fc74f9d1f2b1e7bab76485a99f27abadd10b7b
Author: Ravishankar N <ravishankar at redhat.com>
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 at redhat.com>
    Reviewed-on: https://review.gluster.org/16521
    CentOS-regression: Gluster Build System <jenkins at build.gluster.org>
    NetBSD-regression: NetBSD Build System <jenkins at build.gluster.org>
    Smoke: Gluster Build System <jenkins at build.gluster.org>
    Reviewed-by: Pranith Kumar Karampuri <pkarampu at redhat.com>

--- Additional comment from Worker Ant on 2017-02-15 00:07:34 EST ---

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 at redhat.com)


Referenced Bugs:

https://bugzilla.redhat.com/show_bug.cgi?id=1422350
[Bug 1422350] glustershd process crashed on systemic setup
-- 
You are receiving this mail because:
You are on the CC list for the bug.
You are the assignee for the bug.


More information about the Bugs mailing list