Bug 1397386

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

... snip'd some comments

--- Additional comment from Soumya Koduri on 2016-11-09 13:33:18 EST ---

Ambarish,
If you happen to reproduce the issue, please take the core (using gdb) before running service stop/restart so as to compare the threads before and after the crash. Thanks!

--- Additional comment from Ambarish on 2016-11-10 06:34:54 EST ---

I tried it twice,but I could not reproduce the issue post setting client-io-threads to "off".

The issue is a bit intermittent,so it's hard to say that with certainty ,though. (if that is or is not the culprit).

--- Additional comment from Soumya Koduri on 2016-11-10 06:47:36 EST ---

From the cores and logs provided here, 

gqas006 :
No symbol table info available.
#1  0x00007fb6f120180c in iot_worker (data=0x7fb6d4022be0) at io-threads.c:180
        conf = 0x7fb6d4022be0
        this = <optimized out>
        stub = 0x0
        sleep_till = {tv_sec = 1478711539, tv_nsec = 0}
        ret = <optimized out>
        pri = -1
        sleep = {tv_sec = 0, tv_nsec = 0}
        bye = _gf_false
        __FUNCTION__ = "iot_worker"

gqas005 :
Thread 10 (Thread 0x7f5c45e03700 (LWP 722)):
#0  0x00007f5cdb628a82 in pthread_cond_timedwait@@GLIBC_2.3.2 () from /lib64/libpthread.so.0
No symbol table info available.
#1  0x00007f5c2e5ae80c in iot_worker (data=0x7f5c10022be0) at io-threads.c:180
        conf = 0x7f5c10022be0
        this = <optimized out>
        stub = 0x0
        sleep_till = {tv_sec = 1478711539, tv_nsec = 0}
        ret = <optimized out>
        pri = -1
        sleep = {tv_sec = 0, tv_nsec = 0}
        bye = _gf_false
        __FUNCTION__ = "iot_worker"


There was iot_worker thread still active in both the cores provided.

In the logs,

gqas006:
Nov  9 12:10:23 gqas006 systemd: Stopping GlusterFS, a clustered file-system server...
Nov  9 12:10:23 gqas006 systemd: glusterd.service: main process exited, code=exited, status=15/n/a
Nov  9 12:10:23 gqas006 systemd: Unit glusterd.service entered failed state.
Nov  9 12:10:23 gqas006 systemd: glusterd.service failed.
Nov  9 12:10:23 gqas006 systemd: Starting GlusterFS, a clustered file-system server...
Nov  9 12:10:27 gqas006 kernel: ganesha.nfsd[18212]: segfault at 7fb6f39e780c ip 00007fb6f39e780c sp 00007fb7001e9500 error 15
Nov  9 12:10:27 gqas006 systemd: Started GlusterFS, a clustered file-system server.
Nov  9 12:10:29 gqas006 systemd: Stopping GlusterFS, a clustered file-system server...
Nov  9 12:10:29 gqas006 systemd: glusterd.service: main process exited, code=exited, status=15/n/a
Nov  9 12:10:29 gqas006 systemd: Unit glusterd.service entered failed state.
Nov  9 12:10:29 gqas006 systemd: glusterd.service failed.
Nov  9 12:10:29 gqas006 systemd: Stopping RPC bind service...


gqas005:
Nov  9 12:10:23 gqas005 systemd: Stopping GlusterFS, a clustered file-system server...
Nov  9 12:10:23 gqas005 systemd: glusterd.service: main process exited, code=exited, status=15/n/a
Nov  9 12:10:23 gqas005 systemd: Unit glusterd.service entered failed state.
Nov  9 12:10:23 gqas005 systemd: glusterd.service failed.
Nov  9 12:10:23 gqas005 systemd: Starting GlusterFS, a clustered file-system server...
Nov  9 12:10:27 gqas005 kernel: ganesha.nfsd[32318]: segfault at 7f5c3c34880c ip 00007f5c3c34880c sp 00007f5c3c11d500 error 14 in write-behind.so[7f5c3c1ee000+200000]
Nov  9 12:10:27 gqas005 systemd: Started GlusterFS, a clustered file-system server.
Nov  9 12:10:29 gqas005 systemd: nfs-ganesha.service: main process exited, code=killed, status=11/SEGV
Nov  9 12:10:29 gqas005 systemd: Unit nfs-ganesha.service entered failed state.
Nov  9 12:10:29 gqas005 systemd: nfs-ganesha.service failed.


So the ganesha server has crashed during glusterd service start.

--- Additional comment from Soumya Koduri on 2016-11-10 07:08:34 EST ---

Ambarish could reproduce the issue. And this time the crash happened before the restart of the services.

Nov 10 05:28:39 gqas014 kernel: ganesha.nfsd[31902]: segfault at 7f4e6817e80c ip 00007f4e6817e80c sp 00007f4e68178500 error 14 in libssl.so.1.0.1e[7f4e69726000+64000]
Nov 10 05:28:42 gqas014 systemd: nfs-ganesha.service: main process exited, code=killed, status=11/SEGV
Nov 10 05:28:42 gqas014 systemd: Unit nfs-ganesha.service entered failed state.
Nov 10 05:28:42 gqas014 systemd: nfs-ganesha.service failed.


Nov 10 05:31:15 gqas014 systemd: Stopping GlusterFS, a clustered file-system server...
Nov 10 05:31:15 gqas014 systemd: glusterd.service: main process exited, code=exited, status=15/n/a
Nov 10 05:31:15 gqas014 systemd: Unit glusterd.service entered failed state.
Nov 10 05:31:15 gqas014 systemd: glusterd.service failed.
Nov 10 05:31:15 gqas014 systemd: Starting GlusterFS, a clustered file-system server...
Nov 10 05:31:19 gqas014 systemd: Started GlusterFS, a clustered file-system server.
Nov 10 05:31:22 gqas014 systemd: Stopping GlusterFS, a clustered file-system server...
Nov 10 05:31:22 gqas014 systemd: glusterd.service: main process exited, code=exited, status=15/n/a
Nov 10 05:31:22 gqas014 systemd: Unit glusterd.service entered failed state.
Nov 10 05:31:22 gqas014 systemd: glusterd.service failed.
Nov 10 05:31:22 gqas014 systemd: Stopping RPC bind service...
Nov 10 05:31:22 gqas014 systemd: Starting RPC bind service...

So maybe the crash is not related to any service restart but just happened to be at the same time by coincidence.

And this time he could collect the information requested in comment#5,

>> before crash
(gdb) thread 272
[Switching to thread 272 (Thread 0x7f4e68179700 (LWP 31902))]
#0  pthread_cond_timedwait@@GLIBC_2.3.2 () at ../nptl/sysdeps/unix/sysv/linux/x86_64/pthread_cond_timedwait.S:238
238	62:	movq	%rax, %r14
(gdb) bt
#0  pthread_cond_timedwait@@GLIBC_2.3.2 () at ../nptl/sysdeps/unix/sysv/linux/x86_64/pthread_cond_timedwait.S:238
#1  0x00007f4e6817e80c in ?? ()
#2  0x0000000000000000 in ?? ()
(gdb) 

>> the core generated with segfault -

Thread 1 (Thread 0x7f4e68179700 (LWP 31902)):
#0  0x00007f4e6817e80c in ?? ()
No symbol table info available.

Looks like a stack corruption.

From ganesha.log,

10/11/2016 05:26:35 : epoch 14570000 : gqas014.sbu.lab.eng.bos.redhat.com : ganesha.nfsd-30752[dbus_heartbeat] glusterfs_create_export :FSAL :EVENT :Volume testvol exported at : '/'
10/11/2016 05:26:39 : epoch 14570000 : gqas014.sbu.lab.eng.bos.redhat.com : ganesha.nfsd-30752[dbus_heartbeat] glusterfs_create_export :FSAL :CRIT :Unable to initialize volume. Export: /testvol
10/11/2016 05:26:40 : epoch 14570000 : gqas014.sbu.lab.eng.bos.redhat.com : ganesha.nfsd-30752[dbus_heartbeat] fsal_cfg_commit :CONFIG :CRIT :Could not create export for (/testvol) to (/testvol)
10/11/2016 05:26:40 : epoch 14570000 : gqas014.sbu.lab.eng.bos.redhat.com : ganesha.nfsd-30752[dbus_heartbeat] gsh_export_addexport :EXPORT :CRIT :0 export entries in /var/run/gluster/shared_storage/nfs-ganesha/exports/export.testvol.conf added because (export create, block validation) errors
10/11/2016 05:26:40 : epoch 14570000 : gqas014.sbu.lab.eng.bos.redhat.com : ganesha.nfsd-30752[dbus_heartbeat] dbus_message_entrypoint :DBUS :MAJ :Method (AddExport) on (org.ganesha.nfsd.exportmgr) failed: name = (org.freedesktop.DBus.Error.InvalidFileContent), message = (0 export entries in /var/run/gluster/shared_storage/nfs-ganesha/exports/export.testvol.conf added because (export create, block validation) errors. Details:
Config File (/var/run/gluster/shared_storage/nfs-ganesha/exports/export.testvol.conf:7): 1 validation errors in block FSAL
Config File (/var/run/gluster/shared_storage/nfs-ganesha/exports/export.testvol.conf:7): Errors processing block (FSAL)
Config File (/var/run/gluster/shared_storage/nfs-ganesha/exports/export.testvol.conf:4): 1 validation errors in block EXPORT
Config File (/var/run/gluster/shared_storage/nfs-ganesha/exports/export.testvol.conf:4): Errors found in configuration block EXPORT
)

Volume is not exported. The reason being volume was not started by then. Maybe there is some issue with exporting a volume via nfs-ganesha (doing glfs_init) before it is even started.

--- Additional comment from Ambarish on 2016-11-11 00:05:50 EST ---

Soumya,

I tried the steps after keeping my volume in "Started" state,before setting up the Ganesha cluster and exporting the volume,twice on fresh setups,and I could not reproduce the crash on multiple tries of system service restarts.

--- Additional comment from Soumya Koduri on 2016-11-11 01:03:25 EST ---

Thanks Amabrish. That almost confirms the theory that this crash is hit only if a volume is being exported via nfs-ganesha before it is even started. 

Since this is not a recommended configuration, lowering the priority of the bug for now.

I suspect that probably when the volume is not started, the flow shall be 

glfs_init() -> xlator_init() of all the child subvols -> and then rpc_connection to brick which shall fail.

Post which "glfs_fini" shall be called. May be since glfs_init() itself failed, graph would have not been setup and PARENT_DOWN may not have been sent to io-threads xlator, resulting in the dangling thread.

This is just the theory I have on top of my mind. Will look through the code a bit. CCin Pranith too.

--- Additional comment from Soumya Koduri on 2016-11-14 04:38:09 EST ---

I could reproduce the issue even with single-node nfs-ganesha server. When the volume is not started and is being exported , there will be client-io-thread spawned which doesn't get cleaned up properly leading to crashes at later point. Assigning it to Pranith as per discussions with him,

--- Additional comment from Pranith Kumar K on 2016-11-20 04:10:46 EST ---

Soumya while testing my change, I encountered the following assert in nfs-ganesha:
Thread 271 "ganesha.nfsd" received signal SIGABRT, Aborted.
[Switching to Thread 0x7f6dfb4cf700 (LWP 7303)]
0x00007f6eb2892e55 in raise () from /lib64/libc.so.6
(gdb) bt
#0  0x00007f6eb2892e55 in raise () from /lib64/libc.so.6
#1  0x00007f6eb2894a5a in abort () from /lib64/libc.so.6
#2  0x00007f6eb288b6f7 in __assert_fail_base () from /lib64/libc.so.6
#3  0x00007f6eb288b7a2 in __assert_fail () from /lib64/libc.so.6
#4  0x00005560c8d508f3 in export_init ()
#5  0x00005560c8d88699 in proc_block ()
#6  0x00005560c8d88fb9 in load_config_from_node ()
#7  0x00005560c8d6053a in gsh_export_addexport ()
#8  0x00005560c8d83eef in dbus_message_entrypoint ()
#9  0x00007f6eb4463713 in _dbus_object_tree_dispatch_and_unlock () from /lib64/libdbus-1.so.3
#10 0x00007f6eb4454d94 in dbus_connection_dispatch () from /lib64/libdbus-1.so.3
#11 0x00007f6eb44550ad in _dbus_connection_read_write_dispatch () from /lib64/libdbus-1.so.3
#12 0x00005560c8d84eef in gsh_dbus_thread ()
#13 0x00007f6eb30715ba in start_thread () from /lib64/libpthread.so.0
#14 0x00007f6eb29617cd in clone () from /lib64/libc.so.6
(gdb) fr 4

Here are the steps which exposed this issue:
In terminal 1:
while true; do gluster --mode=script volume stop r2 ; sleep 30 ; gluster --mode=script volume start r2; sleep 30; done

In terminal 2:
while true; do /usr/libexec/ganesha/dbus-send.sh /etc/ganesha on r2; sleep 10 && showmount -e localhost; /usr/libexec/ganesha/dbus-send.sh /etc/ganesha off r2; showmount -e localhost; done

In termina 3:
watch systemctl status nfs-ganesha


Since this is not related to the bug we are discussing in this bz, I changed the script so that we do "while true; do /usr/libexec/ganesha/dbus-send.sh /etc/ganesha on r2; sleep 10 && showmount -e localhost; /usr/libexec/ganesha/dbus-send.sh /etc/ganesha off r2; showmount -e localhost; done" in a loop when the brick is online and offline. That didn't crash. So sending the fix from gluster side. Soumya, feel free to raise a separate bug for the "assert failure".

--- Additional comment from Worker Ant on 2016-11-20 10:36:45 CET ---

REVIEW: http://review.gluster.org/15888 (performance/io-threads: Exit threads in fini() as well) posted (#1) for review on master by Pranith Kumar Karampuri (pkarampu)

--- Additional comment from Worker Ant on 2016-11-22 08:01:21 CET ---

COMMIT: http://review.gluster.org/15888 committed in master by Raghavendra G (rgowdapp) 
------
commit 25817a8c868b6c1b8149117f13e4216a99e453aa
Author: Pranith Kumar K <pkarampu>
Date:   Fri Nov 18 13:30:08 2016 +0530

    performance/io-threads: Exit threads in fini() as well
    
    Problem:
    io-threads starts the thread in 'init()' but doesn't clean them up
    on 'fini()'. It relies on PARENT_DOWN to exit threads but there can
    be cases where event before PARENT_UP the graph init code can think
    of issuing fini(). This code path is hit when glfs_init() is called
    on a volume that is in 'stopped' state. It leads to a crash in ganesha
    process, because the io-thread tries to access freed memory.
    
    Fix:
    Ideal fix would be to wait for all fops in io-thread list to be completed on
    PARENT_DOWN, and have fini() do cleanup of threads. Because there is no proper
    documentation about how PARENT_DOWN/fini are supposed to be used,
    we are getting different kinds of sequences in different higher level protocols.
    So for now cleaning up in both PARENT_DOWN and fini(). Fuse doesn't call fini()
    gfapi is not calling PARENT_DOWN in some cases, so for now I don't see
    another way out.
    
    BUG: 1396793
    Change-Id: I9c9154e7d57198dbaff0f30d3ffc25f6d8088aec
    Signed-off-by: Pranith Kumar K <pkarampu>
    Reviewed-on: http://review.gluster.org/15888
    Smoke: Gluster Build System <jenkins.org>
    CentOS-regression: Gluster Build System <jenkins.org>
    NetBSD-regression: NetBSD Build System <jenkins.org>
    Reviewed-by: Raghavendra G <rgowdapp>