Bug 1476871 - [NFS] nfs process crashed in "nfs3_getattr"
[NFS] nfs process crashed in "nfs3_getattr"
Status: CLOSED ERRATA
Product: Red Hat Gluster Storage
Classification: Red Hat
Component: gluster-nfs (Show other bugs)
3.3
Unspecified Unspecified
unspecified Severity medium
: ---
: RHGS 3.3.0
Assigned To: Jiffin
Rochelle
: Regression
Depends On: 1479030
Blocks: 1417151
  Show dependency treegraph
 
Reported: 2017-07-31 12:40 EDT by Rochelle
Modified: 2017-09-21 01:04 EDT (History)
10 users (show)

See Also:
Fixed In Version: glusterfs-3.8.4-39
Doc Type: If docs needed, set a value
Doc Text:
Story Points: ---
Clone Of:
: 1479030 (view as bug list)
Environment:
Last Closed: 2017-09-21 01:04:21 EDT
Type: Bug
Regression: ---
Mount Type: ---
Documentation: ---
CRM:
Verified Versions:
Category: ---
oVirt Team: ---
RHEL 7.3 requirements from Atomic Host:
Cloudforms Team: ---


Attachments (Terms of Use)

  None (edit)
Description Rochelle 2017-07-31 12:40:12 EDT
Description:
============

While running geo-replication automation cases on nfs master mount which performs different fops like (chmod,chown,choown,chgrp,hardlink,symlink,truncate,rename and remove) found a crash with the following bt:

(gdb) bt
#0  0x00007ff1cfea9205 in _gf_ref_put (ref=ref@entry=0x0) at refcount.c:36
#1  0x00007ff1c1997455 in nfs3_call_state_wipe (cs=cs@entry=0x0) at nfs3.c:559
#2  0x00007ff1c1998931 in nfs3_getattr (req=req@entry=0x7ff1bc0b26d0, fh=fh@entry=0x7ff1c2f76ae0) at nfs3.c:962
#3  0x00007ff1c1998c8a in nfs3svc_getattr (req=0x7ff1bc0b26d0) at nfs3.c:987
#4  0x00007ff1cfbfd8c5 in rpcsvc_handle_rpc_call (svc=0x7ff1bc03e500, trans=trans@entry=0x7ff1bc0c8020, msg=<optimized out>) at rpcsvc.c:695
#5  0x00007ff1cfbfdaab in rpcsvc_notify (trans=0x7ff1bc0c8020, mydata=<optimized out>, event=<optimized out>, data=<optimized out>) at rpcsvc.c:789
#6  0x00007ff1cfbff9e3 in rpc_transport_notify (this=this@entry=0x7ff1bc0c8020, event=event@entry=RPC_TRANSPORT_MSG_RECEIVED, data=data@entry=0x7ff1bc0038d0)
    at rpc-transport.c:538
#7  0x00007ff1c4a2e3d6 in socket_event_poll_in (this=this@entry=0x7ff1bc0c8020, notify_handled=<optimized out>) at socket.c:2306
#8  0x00007ff1c4a3097c in socket_event_handler (fd=21, idx=9, gen=19, data=0x7ff1bc0c8020, poll_in=1, poll_out=0, poll_err=0) at socket.c:2458
#9  0x00007ff1cfe950f6 in event_dispatch_epoll_handler (event=0x7ff1c2f76e80, event_pool=0x5618154d5ee0) at event-epoll.c:572
#10 event_dispatch_epoll_worker (data=0x56181551cbd0) at event-epoll.c:648
#11 0x00007ff1cec99e25 in start_thread () from /lib64/libpthread.so.0
#12 0x00007ff1ce56634d in clone () from /lib64/libc.so.6
(gdb) 


[root@dhcp37-181 ~]# file /core*
/core.14053: ELF 64-bit LSB core file x86-64, version 1 (SYSV), SVR4-style, from '/usr/sbin/glusterfs -s localhost --volfile-id gluster/nfs -p /var/lib/glusterd/', real uid: 0, effective uid: 0, real gid: 0, effective gid: 0, execfn: '/usr/sbin/glusterfs', platform: 'x86_64'
[root@dhcp37-181 ~]# 


Version:
========

glusterfs-server-3.8.4-36.el7rhgs.x86_64

How to reproduce:
=================

Have seen this only once

Steps:
======

No straight forward steps available yet, however nfs+geo-rep testing is in progress. Will update the bug in case seen with any manual steps.
Comment 3 Soumya Koduri 2017-08-02 05:27:19 EDT
This bug looks like DUP of bug1472773 - https://review.gluster.org/17822 fixes this issue. Niels shall be able to confirm.
Comment 4 Niels de Vos 2017-08-02 10:01:20 EDT
(In reply to Soumya Koduri from comment #3)
> This bug looks like DUP of bug1472773 - https://review.gluster.org/17822
> fixes this issue. Niels shall be able to confirm.

I do not think that is the same problem, as that fix was added to nfs3_lookup() while this crashes in nfs3_getattr().

Maybe the nfs.log contains some details on how this happened.
Comment 5 Manisha Saini 2017-08-05 13:39:33 EDT
Hit the same crash while verifying bZ-https://bugzilla.redhat.com/show_bug.cgi?id=1451224

#glusterfs-api-3.8.4-38.el7rhgs.x86_64

Missing separate debuginfos, use: debuginfo-install glibc-2.17-196.el7.x86_64 keyutils-libs-1.5.8-3.el7.x86_64 krb5-libs-1.15.1-8.el7.x86_64 libacl-2.2.51-12.el7.x86_64 libattr-2.4.46-12.el7.x86_64 libcom_err-1.42.9-10.el7.x86_64 libgcc-4.8.5-16.el7.x86_64 libselinux-2.5-11.el7.x86_64 libuuid-2.23.2-43.el7.x86_64 openssl-libs-1.0.2k-8.el7.x86_64 pcre-8.32-17.el7.x86_64 zlib-1.2.7-17.el7.x86_64
(gdb) bt
#0  0x00007fcb4d4ef2c5 in _gf_ref_put (ref=ref@entry=0x0) at refcount.c:36
#1  0x00007fcb3f1f1465 in nfs3_call_state_wipe (cs=cs@entry=0x0) at nfs3.c:559
#2  0x00007fcb3f1f2941 in nfs3_getattr (req=req@entry=0x7fcb380a6330, fh=fh@entry=0x7fcb407c5ae0) at nfs3.c:962
#3  0x00007fcb3f1f2c9a in nfs3svc_getattr (req=0x7fcb380a6330) at nfs3.c:987
#4  0x00007fcb4d2438c5 in rpcsvc_handle_rpc_call (svc=0x7fcb3803a530, trans=trans@entry=0x7fcb380a29f0, msg=<optimized out>)
    at rpcsvc.c:695
#5  0x00007fcb4d243aab in rpcsvc_notify (trans=0x7fcb380a29f0, mydata=<optimized out>, event=<optimized out>, data=<optimized out>)
    at rpcsvc.c:789
#6  0x00007fcb4d2459e3 in rpc_transport_notify (this=this@entry=0x7fcb380a29f0, event=event@entry=RPC_TRANSPORT_MSG_RECEIVED, 
    data=data@entry=0x7fcb380a2760) at rpc-transport.c:538
#7  0x00007fcb420743d6 in socket_event_poll_in (this=this@entry=0x7fcb380a29f0, notify_handled=<optimized out>) at socket.c:2306
#8  0x00007fcb4207697c in socket_event_handler (fd=21, idx=21, gen=34, data=0x7fcb380a29f0, poll_in=1, poll_out=0, poll_err=0)
    at socket.c:2458
#9  0x00007fcb4d4db1b6 in event_dispatch_epoll_handler (event=0x7fcb407c5e80, event_pool=0x564421f6ffd0) at event-epoll.c:572
#10 event_dispatch_epoll_worker (data=0x564421fb65f0) at event-epoll.c:648
#11 0x00007fcb4c2dfe25 in start_thread () from /lib64/libpthread.so.0
#12 0x00007fcb4bbac34d in clone () from /lib64/libc.so.6
Comment 9 Jiffin 2017-08-07 15:06:37 EDT
RCA : In old code there was NULL check in nfs3_call_state_wipe(), as part of  refcounting for nfs call state(https://review.gluster.org/#/c/17696/), the check moved to __nfs3_call_state_wipe(release function in refcounting). But there are cases in which nfs call state(cs value itself can be NULL). So we need to add previous NULL check

Patch posted upstream : https://review.gluster.org/#/c/17989
Comment 13 Atin Mukherjee 2017-08-09 00:54:02 EDT
release-3.12 patch : https://review.gluster.org/17994
downstream patch : https://code.engineering.redhat.com/gerrit/#/c/114663/
Comment 15 Manisha Saini 2017-08-10 07:39:53 EDT
Verified this bug on glusterfs-fuse-3.8.4-39.el7rhgs.x86_64

Hit this crash while verifying bug-https://bugzilla.redhat.com/show_bug.cgi?id=1451224

Validated the steps mentioned in this bug.
With 39 gluster build,I am unable to hit this crash.


As mentioned by Jiffin in comment#10, observed few "nfs calling state NULL" messages in /var/log/glusterfs/nfs.log .But the frequency of these messages is not high.


# cat /var/log/glusterfs/nfs.log | grep "nfs calling state NULL"
[2017-08-09 14:18:44.559277] W [nfs3.c:557:nfs3_call_state_wipe] (--> /lib64/libglusterfs.so.0(_gf_log_callingfn+0x192)[0x7efca1a81222] (--> /usr/lib64/glusterfs/3.8.4/xlator/nfs/server.so(+0x269b1)[0x7efc8f6ef9b1] (--> /usr/lib64/glusterfs/3.8.4/xlator/nfs/server.so(+0x26d0a)[0x7efc8f6efd0a] (--> /lib64/libgfrpc.so.0(rpcsvc_handle_rpc_call+0x325)[0x7efca18428c5] (--> /lib64/libgfrpc.so.0(rpcsvc_notify+0x10b)[0x7efca1842aab] ))))) 0-nfs: nfs calling state NULL
[2017-08-09 14:18:44.559879] W [nfs3.c:557:nfs3_call_state_wipe] (--> /lib64/libglusterfs.so.0(_gf_log_callingfn+0x192)[0x7efca1a81222] (--> /usr/lib64/glusterfs/3.8.4/xlator/nfs/server.so(+0x269b1)[0x7efc8f6ef9b1] (--> /usr/lib64/glusterfs/3.8.4/xlator/nfs/server.so(+0x26d0a)[0x7efc8f6efd0a] (--> /lib64/libgfrpc.so.0(rpcsvc_handle_rpc_call+0x325)[0x7efca18428c5] (--> /lib64/libgfrpc.so.0(rpcsvc_notify+0x10b)[0x7efca1842aab] ))))) 0-nfs: nfs calling state NULL
[2017-08-09 14:18:44.565719] W [nfs3.c:557:nfs3_call_state_wipe] (--> /lib64/libglusterfs.so.0(_gf_log_callingfn+0x192)[0x7efca1a81222] (--> /usr/lib64/glusterfs/3.8.4/xlator/nfs/server.so(+0x269b1)[0x7efc8f6ef9b1] (--> /usr/lib64/glusterfs/3.8.4/xlator/nfs/server.so(+0x26d0a)[0x7efc8f6efd0a] (--> /lib64/libgfrpc.so.0(rpcsvc_handle_rpc_call+0x325)[0x7efca18428c5] (--> /lib64/libgfrpc.so.0(rpcsvc_notify+0x10b)[0x7efca1842aab] ))))) 0-nfs: nfs calling state NULL
[2017-08-09 14:18:44.566210] W [nfs3.c:557:nfs3_call_state_wipe] (--> /lib64/libglusterfs.so.0(_gf_log_callingfn+0x192)[0x7efca1a81222] (--> /usr/lib64/glusterfs/3.8.4/xlator/nfs/server.so(+0x269b1)[0x7efc8f6ef9b1] (--> /usr/lib64/glusterfs/3.8.4/xlator/nfs/server.so(+0x26d0a)[0x7efc8f6efd0a] (--> /lib64/libgfrpc.so.0(rpcsvc_handle_rpc_call+0x325)[0x7efca18428c5] (--> /lib64/libgfrpc.so.0(rpcsvc_notify+0x10b)[0x7efca1842aab] ))))) 0-nfs: nfs calling state NULL
[2017-08-09 14:18:49.534665] W [nfs3.c:557:nfs3_call_state_wipe] (--> /lib64/libglusterfs.so.0(_gf_log_callingfn+0x192)[0x7efca1a81222] (--> /usr/lib64/glusterfs/3.8.4/xlator/nfs/server.so(+0x269b1)[0x7efc8f6ef9b1] (--> /usr/lib64/glusterfs/3.8.4/xlator/nfs/server.so(+0x26d0a)[0x7efc8f6efd0a] (--> /lib64/libgfrpc.so.0(rpcsvc_handle_rpc_call+0x325)[0x7efca18428c5] (--> /lib64/libgfrpc.so.0(rpcsvc_notify+0x10b)[0x7efca1842aab] ))))) 0-nfs: nfs calling state NULL
[2017-08-09 14:18:49.535150] W [nfs3.c:557:nfs3_call_state_wipe] (--> /lib64/libglusterfs.so.0(_gf_log_callingfn+0x192)[0x7efca1a81222] (--> /usr/lib64/glusterfs/3.8.4/xlator/nfs/server.so(+0x269b1)[0x7efc8f6ef9b1] (--> /usr/lib64/glusterfs/3.8.4/xlator/nfs/server.so(+0x26d0a)[0x7efc8f6efd0a] (--> /lib64/libgfrpc.so.0(rpcsvc_handle_rpc_call+0x325)[0x7efca18428c5] (--> /lib64/libgfrpc.so.0(rpcsvc_notify+0x10b)[0x7efca1842aab] ))))) 0-nfs: nfs calling state NULL
[2017-08-09 14:18:49.541257] W [nfs3.c:557:nfs3_call_state_wipe] (--> /lib64/libglusterfs.so.0(_gf_log_callingfn+0x192)[0x7efca1a81222] (--> /usr/lib64/glusterfs/3.8.4/xlator/nfs/server.so(+0x269b1)[0x7efc8f6ef9b1] (--> /usr/lib64/glusterfs/3.8.4/xlator/nfs/server.so(+0x26d0a)[0x7efc8f6efd0a] (--> /lib64/libgfrpc.so.0(rpcsvc_handle_rpc_call+0x325)[0x7efca18428c5] (--> /lib64/libgfrpc.so.0(rpcsvc_notify+0x10b)[0x7efca1842aab] ))))) 0-nfs: nfs calling state NULL
[2017-08-09 14:18:49.541893] W [nfs3.c:557:nfs3_call_state_wipe] (--> /lib64/libglusterfs.so.0(_gf_log_callingfn+0x192)[0x7efca1a81222] (--> /usr/lib64/glusterfs/3.8.4/xlator/nfs/server.so(+0x269b1)[0x7efc8f6ef9b1] (--> /usr/lib64/glusterfs/3.8.4/xlator/nfs/server.so(+0x26d0a)[0x7efc8f6efd0a] (--> /lib64/libgfrpc.so.0(rpcsvc_handle_rpc_call+0x325)[0x7efca18428c5] (--> /lib64/libgfrpc.so.0(rpcsvc_notify+0x10b)[0x7efca1842aab] ))))) 0-nfs: nfs calling state NULL
[2017-08-09 14:20:47.649784] W [nfs3.c:557:nfs3_call_state_wipe] (--> /lib64/libglusterfs.so.0(_gf_log_callingfn+0x192)[0x7efca1a81222] (--> /usr/lib64/glusterfs/3.8.4/xlator/nfs/server.so(+0x269b1)[0x7efc8f6ef9b1] (--> /usr/lib64/glusterfs/3.8.4/xlator/nfs/server.so(+0x26d0a)[0x7efc8f6efd0a] (--> /lib64/libgfrpc.so.0(rpcsvc_handle_rpc_call+0x325)[0x7efca18428c5] (--> /lib64/libgfrpc.so.0(rpcsvc_notify+0x10b)[0x7efca1842aab] ))))) 0-nfs: nfs calling state NULL
Comment 16 Manisha Saini 2017-08-10 07:43:10 EDT
rochelle will validate the geo-rep scenario on which this bug was initially raised before moving this bug to verified state.
Comment 17 Jiffin 2017-08-11 01:25:34 EDT
(In reply to Manisha Saini from comment #15)
> Verified this bug on glusterfs-fuse-3.8.4-39.el7rhgs.x86_64
> 
> Hit this crash while verifying
> bug-https://bugzilla.redhat.com/show_bug.cgi?id=1451224
> 
> Validated the steps mentioned in this bug.
> With 39 gluster build,I am unable to hit this crash.
> 
> 
> As mentioned by Jiffin in comment#10, observed few "nfs calling state NULL"
> messages in /var/log/glusterfs/nfs.log .But the frequency of these messages
> is not high.

Thanks Manisha.

> 
> 
> # cat /var/log/glusterfs/nfs.log | grep "nfs calling state NULL"
> [2017-08-09 14:18:44.559277] W [nfs3.c:557:nfs3_call_state_wipe] (-->
> /lib64/libglusterfs.so.0(_gf_log_callingfn+0x192)[0x7efca1a81222] (-->
> /usr/lib64/glusterfs/3.8.4/xlator/nfs/server.so(+0x269b1)[0x7efc8f6ef9b1]
> (-->
> /usr/lib64/glusterfs/3.8.4/xlator/nfs/server.so(+0x26d0a)[0x7efc8f6efd0a]
> (--> /lib64/libgfrpc.so.0(rpcsvc_handle_rpc_call+0x325)[0x7efca18428c5] (-->
> /lib64/libgfrpc.so.0(rpcsvc_notify+0x10b)[0x7efca1842aab] ))))) 0-nfs: nfs
> calling state NULL
> [2017-08-09 14:18:44.559879] W [nfs3.c:557:nfs3_call_state_wipe] (-->
> /lib64/libglusterfs.so.0(_gf_log_callingfn+0x192)[0x7efca1a81222] (-->
> /usr/lib64/glusterfs/3.8.4/xlator/nfs/server.so(+0x269b1)[0x7efc8f6ef9b1]
> (-->
> /usr/lib64/glusterfs/3.8.4/xlator/nfs/server.so(+0x26d0a)[0x7efc8f6efd0a]
> (--> /lib64/libgfrpc.so.0(rpcsvc_handle_rpc_call+0x325)[0x7efca18428c5] (-->
> /lib64/libgfrpc.so.0(rpcsvc_notify+0x10b)[0x7efca1842aab] ))))) 0-nfs: nfs
> calling state NULL
> [2017-08-09 14:18:44.565719] W [nfs3.c:557:nfs3_call_state_wipe] (-->
> /lib64/libglusterfs.so.0(_gf_log_callingfn+0x192)[0x7efca1a81222] (-->
> /usr/lib64/glusterfs/3.8.4/xlator/nfs/server.so(+0x269b1)[0x7efc8f6ef9b1]
> (-->
> /usr/lib64/glusterfs/3.8.4/xlator/nfs/server.so(+0x26d0a)[0x7efc8f6efd0a]
> (--> /lib64/libgfrpc.so.0(rpcsvc_handle_rpc_call+0x325)[0x7efca18428c5] (-->
> /lib64/libgfrpc.so.0(rpcsvc_notify+0x10b)[0x7efca1842aab] ))))) 0-nfs: nfs
> calling state NULL
> [2017-08-09 14:18:44.566210] W [nfs3.c:557:nfs3_call_state_wipe] (-->
> /lib64/libglusterfs.so.0(_gf_log_callingfn+0x192)[0x7efca1a81222] (-->
> /usr/lib64/glusterfs/3.8.4/xlator/nfs/server.so(+0x269b1)[0x7efc8f6ef9b1]
> (-->
> /usr/lib64/glusterfs/3.8.4/xlator/nfs/server.so(+0x26d0a)[0x7efc8f6efd0a]
> (--> /lib64/libgfrpc.so.0(rpcsvc_handle_rpc_call+0x325)[0x7efca18428c5] (-->
> /lib64/libgfrpc.so.0(rpcsvc_notify+0x10b)[0x7efca1842aab] ))))) 0-nfs: nfs
> calling state NULL
> [2017-08-09 14:18:49.534665] W [nfs3.c:557:nfs3_call_state_wipe] (-->
> /lib64/libglusterfs.so.0(_gf_log_callingfn+0x192)[0x7efca1a81222] (-->
> /usr/lib64/glusterfs/3.8.4/xlator/nfs/server.so(+0x269b1)[0x7efc8f6ef9b1]
> (-->
> /usr/lib64/glusterfs/3.8.4/xlator/nfs/server.so(+0x26d0a)[0x7efc8f6efd0a]
> (--> /lib64/libgfrpc.so.0(rpcsvc_handle_rpc_call+0x325)[0x7efca18428c5] (-->
> /lib64/libgfrpc.so.0(rpcsvc_notify+0x10b)[0x7efca1842aab] ))))) 0-nfs: nfs
> calling state NULL
> [2017-08-09 14:18:49.535150] W [nfs3.c:557:nfs3_call_state_wipe] (-->
> /lib64/libglusterfs.so.0(_gf_log_callingfn+0x192)[0x7efca1a81222] (-->
> /usr/lib64/glusterfs/3.8.4/xlator/nfs/server.so(+0x269b1)[0x7efc8f6ef9b1]
> (-->
> /usr/lib64/glusterfs/3.8.4/xlator/nfs/server.so(+0x26d0a)[0x7efc8f6efd0a]
> (--> /lib64/libgfrpc.so.0(rpcsvc_handle_rpc_call+0x325)[0x7efca18428c5] (-->
> /lib64/libgfrpc.so.0(rpcsvc_notify+0x10b)[0x7efca1842aab] ))))) 0-nfs: nfs
> calling state NULL
> [2017-08-09 14:18:49.541257] W [nfs3.c:557:nfs3_call_state_wipe] (-->
> /lib64/libglusterfs.so.0(_gf_log_callingfn+0x192)[0x7efca1a81222] (-->
> /usr/lib64/glusterfs/3.8.4/xlator/nfs/server.so(+0x269b1)[0x7efc8f6ef9b1]
> (-->
> /usr/lib64/glusterfs/3.8.4/xlator/nfs/server.so(+0x26d0a)[0x7efc8f6efd0a]
> (--> /lib64/libgfrpc.so.0(rpcsvc_handle_rpc_call+0x325)[0x7efca18428c5] (-->
> /lib64/libgfrpc.so.0(rpcsvc_notify+0x10b)[0x7efca1842aab] ))))) 0-nfs: nfs
> calling state NULL
> [2017-08-09 14:18:49.541893] W [nfs3.c:557:nfs3_call_state_wipe] (-->
> /lib64/libglusterfs.so.0(_gf_log_callingfn+0x192)[0x7efca1a81222] (-->
> /usr/lib64/glusterfs/3.8.4/xlator/nfs/server.so(+0x269b1)[0x7efc8f6ef9b1]
> (-->
> /usr/lib64/glusterfs/3.8.4/xlator/nfs/server.so(+0x26d0a)[0x7efc8f6efd0a]
> (--> /lib64/libgfrpc.so.0(rpcsvc_handle_rpc_call+0x325)[0x7efca18428c5] (-->
> /lib64/libgfrpc.so.0(rpcsvc_notify+0x10b)[0x7efca1842aab] ))))) 0-nfs: nfs
> calling state NULL
> [2017-08-09 14:20:47.649784] W [nfs3.c:557:nfs3_call_state_wipe] (-->
> /lib64/libglusterfs.so.0(_gf_log_callingfn+0x192)[0x7efca1a81222] (-->
> /usr/lib64/glusterfs/3.8.4/xlator/nfs/server.so(+0x269b1)[0x7efc8f6ef9b1]
> (-->
> /usr/lib64/glusterfs/3.8.4/xlator/nfs/server.so(+0x26d0a)[0x7efc8f6efd0a]
> (--> /lib64/libgfrpc.so.0(rpcsvc_handle_rpc_call+0x325)[0x7efca18428c5] (-->
> /lib64/libgfrpc.so.0(rpcsvc_notify+0x10b)[0x7efca1842aab] ))))) 0-nfs: nfs
> calling state NULL
Comment 18 Rochelle 2017-08-16 00:21:43 EDT
Verified with build : glusterfs-geo-replication-3.8.4-39.el7rhgs.x86_64

Ran the Geo-rep automation cases with nfs master mount and was not able to hit this.

Moving this bug to verified.
Comment 20 errata-xmlrpc 2017-09-21 01:04:21 EDT
Since the problem described in this bug report should be
resolved in a recent advisory, it has been closed with a
resolution of ERRATA.

For information on the advisory, and where to find the updated
files, follow the link below.

If the solution does not work for you, open a new bug report.

https://access.redhat.com/errata/RHBA-2017:2774

Note You need to log in before you can comment on or make changes to this bug.