[Bugs] [Bug 1394225] New: "nfs-grace-monitor" timed out messages observed

bugzilla at redhat.com bugzilla at redhat.com
Fri Nov 11 12:46:31 UTC 2016 

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

            Bug ID: 1394225
           Summary: "nfs-grace-monitor" timed out messages observed
           Product: GlusterFS
           Version: 3.9
         Component: common-ha
          Keywords: Triaged
          Severity: high
          Assignee: bugs at gluster.org
          Reporter: kkeithle at redhat.com
                CC: asoman at redhat.com, bugs at gluster.org,
                    jthottan at redhat.com, kkeithle at redhat.com,
                    ndevos at redhat.com, sashinde at redhat.com,
                    skoduri at redhat.com, sraj at redhat.com,
                    storage-qa-internal at redhat.com
        Depends On: 1337565, 1394224



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

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

Description of problem:

"nfs-grace-monitor" timed out messages observed in pcs status.

Version-Release number of selected component (if applicable):

glusterfs-3.7.9-5.el7rhgs.x86_64
nfs-ganesha-2.3.1-7.el7rhgs.x86_64

How reproducible:
2/2

Steps to Reproduce:
1.Create a 4 node ganesha cluster.
2.Create a volume, enable ganesha and mount the volume with vers=4.
3.Start executing iozone test suite on the mount point.
4.During the test, stop nfs-ganesha service on the mounted node and once the IO
resumes from other node, after sometime start the ganesha service on that node.
5.Check the pcs status and observe that there are timed out messages for
nfs-grace-monitor and nfs-mon-monitor as below:

Failed Actions:
* nfs-mon_monitor_10000 on dhcp46-26.lab.eng.blr.redhat.com 'unknown error'
(1): call=21, status=Timed Out, exitreason='none',
    last-rc-change='Thu May 19 18:35:08 2016', queued=0ms, exec=0ms
* nfs-grace_monitor_5000 on dhcp46-202.lab.eng.blr.redhat.com 'unknown error'
(1): call=22, status=Timed Out, exitreason='none',
    last-rc-change='Thu May 19 00:53:52 2016', queued=0ms, exec=0ms
* nfs-mon_monitor_10000 on dhcp46-202.lab.eng.blr.redhat.com 'unknown error'
(1): call=21, status=Timed Out, exitreason='none',
    last-rc-change='Thu May 19 00:53:56 2016', queued=0ms, exec=0ms
* nfs-grace_monitor_5000 on dhcp46-247.lab.eng.blr.redhat.com 'unknown error'
(1): call=46, status=Timed Out, exitreason='none',
    last-rc-change='Wed May 18 23:54:22 2016', queued=0ms, exec=0ms
* nfs-mon_monitor_10000 on dhcp46-247.lab.eng.blr.redhat.com 'unknown error'
(1): call=21, status=Timed Out, exitreason='none',
    last-rc-change='Wed May 18 23:54:27 2016', queued=0ms, exec=0ms
* nfs-mon_monitor_10000 on dhcp47-139.lab.eng.blr.redhat.com 'unknown error'
(1): call=21, status=Timed Out, exitreason='none',
    last-rc-change='Thu May 19 00:53:57 2016', queued=0ms, exec=0ms


6. Below messages are observed in ganesha.log

8/05/2016 23:49:15 : epoch 4cd30000 : dhcp46-247.lab.eng.blr.redhat.com :
ganesha.nfsd-31387[work-6] nfs4_add_clid :CLIENT ID :EVENT :Failed to create
client in recovery dir
(/var/lib/nfs/ganesha/v4recov/::ffff:10.70.37.206-(86:0x4c696e7578204e465376342e302031302e37302e33372e3230362f31302e37302e34342e393220746370)),
errno=107
18/05/2016 23:49:35 : epoch 4cd30000 : dhcp46-247.lab.eng.blr.redhat.com :
ganesha.nfsd-31387[work-1] nfs4_add_clid :CLIENT ID :EVENT :Failed to create
client in recovery dir
(/var/lib/nfs/ganesha/v4recov/::ffff:10.70.37.136-(86:0x4c696e7578204e465376342e302031302e37302e33372e3133362f31302e37302e34342e393220746370)),
errno=107
18/05/2016 23:50:43 : epoch 4cd30000 : dhcp46-247.lab.eng.blr.redhat.com :
ganesha.nfsd-31387[reaper] nfs_in_grace :STATE :EVENT :NFS Server Now NOT IN
GRACE
18/05/2016 23:50:43 : epoch 4cd30000 : dhcp46-247.lab.eng.blr.redhat.com :
ganesha.nfsd-31387[reaper] nfs4_clean_old_recov_dir :CLIENT ID :EVENT :Failed
to open old v4 recovery dir (/var/lib/nfs/ganesha/v4old), errno=107


18/05/2016 23:57:00 : epoch 00670000 : dhcp46-202.lab.eng.blr.redhat.com :
ganesha.nfsd-25624[reaper] nfs4_rm_revoked_handles :CLIENT ID :EVENT :opendir
/var/lib/nfs/ganesha/v4recov/::ffff:10.70.37.136-(86:0x4c696e7578204e465376342e302031302e37302e33372e3133362f31302e37302e34342e393220746370)
failed errno=107
18/05/2016 23:57:00 : epoch 00670000 : dhcp46-202.lab.eng.blr.redhat.com :
ganesha.nfsd-25624[reaper] nfs4_rm_clid :CLIENT ID :EVENT :Failed to remove
client recovery dir
(/var/lib/nfs/ganesha/v4recov/::ffff:10.70.37.136-(86:0x4c696e7578204e465376342e302031302e37302e33372e3133362f31302e37302e34342e393220746370)),
errno=107
18/05/2016 23:57:10 : epoch 00670000 : dhcp46-202.lab.eng.blr.redhat.com :
ganesha.nfsd-25624[reaper] nfs4_rm_revoked_handles :CLIENT ID :EVENT :opendir
/var/lib/nfs/ganesha/v4recov/::ffff:10.70.37.206-(86:0x4c696e7578204e465376342e302031302e37302e33372e3230362f31302e37302e34342e393220746370)
failed errno=107
18/05/2016 23:57:10 : epoch 00670000 : dhcp46-202.lab.eng.blr.redhat.com :
ganesha.nfsd-25624[reaper] nfs4_rm_clid :CLIENT ID :EVENT :Failed to remove
client recovery dir
(/var/lib/nfs/ganesha/v4recov/::ffff:10.70.37.206-(86:0x4c696e7578204e465376342e302031302e37302e33372e3230362f31302e37302e34342e393220746370)),
errno=107


18/05/2016 23:46:58 : epoch 00670000 : dhcp46-202.lab.eng.blr.redhat.com :
ganesha.nfsd-25624[dbus_heartbeat] nfs4_load_recov_clids_nolock :CLIENT ID
:EVENT :Recovery for nodeid -1 dir
(/var/lib/nfs/ganesha/dhcp46-247.lab.eng.blr.redhat.com/v4recov)
18/05/2016 23:46:58 : epoch 00670000 : dhcp46-202.lab.eng.blr.redhat.com :
ganesha.nfsd-25624[dbus_heartbeat] nfs4_load_recov_clids_nolock :CLIENT ID
:EVENT :Failed to open v4 recovery dir
(/var/lib/nfs/ganesha/dhcp46-247.lab.eng.blr.redhat.com/v4recov), errno=107
18/05/2016 23:47:00 : epoch 00670000 : dhcp46-202.lab.eng.blr.redhat.com :
ganesha.nfsd-25624[reaper] nfs_in_grace :STATE :EVENT :NFS Server Now IN GRACE
18/05/2016 23:47:06 : epoch 00670000 : dhcp46-202.lab.eng.blr.redhat.com :
ganesha.nfsd-25624[work-5] nfs4_add_clid :CLIENT ID :EVENT :Failed to create
client in recovery dir
(/var/lib/nfs/ganesha/v4recov/::ffff:10.70.37.136-(86:0x4c696e7578204e465376342e302031302e37302e33372e3133362f31302e37302e34342e393220746370)),
errno=107
18/05/2016 23:47:08 : epoch 00670000 : dhcp46-202.lab.eng.blr.redhat.com :
ganesha.nfsd-25624[work-9] nfs4_add_clid :CLIENT ID :EVENT :Failed to create
client in recovery dir
(/var/lib/nfs/ganesha/v4recov/::ffff:10.70.37.206-(86:0x4c696e7578204e465376342e302031302e37302e33372e3230362f31302e37302e34342e393220746370)),
errno=107

Actual results:

"nfs-grace-monitor" timed out messages observed in pcs status.

Expected results:

there should not be any failures in pcs status.

Additional info:

sosreports are attached for the reference.

--- Additional comment from Red Hat Bugzilla Rules Engine on 2016-05-19
09:24:57 EDT ---

This bug is automatically being proposed for the current z-stream release of
Red Hat Gluster Storage 3 by setting the release flag 'rhgs‑3.1.z' to '?'. 

If this bug should be proposed for a different release, please manually change
the proposed release flag.

--- Additional comment from Shashank Raj on 2016-05-19 09:28:44 EDT ---

sosreports are placed at
http://rhsqe-repo.lab.eng.blr.redhat.com/sosreports/1337565

--- Additional comment from Kaleb KEITHLEY on 2016-05-19 09:48:53 EDT ---

something is timing out, but it's not `pcs status`.

None of the /usr/lib/ocfs/resource.d/heartbeat/ganesha_* resource agents run a
`pcs status`

--- Additional comment from Kaleb KEITHLEY on 2016-05-19 10:16:47 EDT ---

sorry, I misread the original. 

Now I see that a `pcs status` run by admin is showing Failed Actions for
nfs-mon_monitor and nfs-grace_monitor with status=Timed Out.

The last ones occurred at May 19 00:53:57 (UTC?)  It is now 14:00:00 UTC
(19:30:00 IST), so they are not happening continuously.

It would certainly be better if these did not happen, but I think they're
mainly benign and can be reasonably safely ignored.

--- Additional comment from Shashank Raj on 2016-06-01 05:41:33 EDT ---

With the latest glusterfs-3.7.9-7 and nfs-ganesha-2.3.1-7 build, observed that
after setting up ganesha on a RHEL 7 platform, below messages are observed in
pcs status:

Failed Actions:
* nfs-grace_monitor_0 on dhcp46-26.lab.eng.blr.redhat.com 'unknown error' (1):
call=16, status=complete, exitreason='none',
    last-rc-change='Wed Jun  1 12:01:00 2016', queued=0ms, exec=86ms
* nfs-grace_monitor_0 on dhcp47-139.lab.eng.blr.redhat.com 'unknown error' (1):
call=16, status=complete, exitreason='none',
    last-rc-change='Wed Jun  1 12:00:59 2016', queued=0ms, exec=102ms
* nfs-grace_monitor_0 on dhcp46-202.lab.eng.blr.redhat.com 'unknown error' (1):
call=16, status=complete, exitreason='none',
    last-rc-change='Wed Jun  1 12:00:59 2016', queued=0ms, exec=84ms
* nfs-grace_monitor_0 on dhcp46-247.lab.eng.blr.redhat.com 'unknown error' (1):
call=16, status=complete, exitreason='none',
    last-rc-change='Wed Jun  1 11:53:59 2016', queued=0ms, exec=92ms

This doesn't effect any functionality, initial tests for failover and failback
works fine.

Reporting this because these messages were not seen after ganesha setup with
earlier glusterfs/ganesha builds.

--- Additional comment from Shashank Raj on 2016-09-29 09:33:52 EDT ---

Kaleb,

Can we confirm this behavior?

--- Additional comment from Niels de Vos on 2016-10-14 06:21:17 EDT ---

The error messages in comment #0 mention "errno=107". This is:

    ENOTCONN: Transport endpoint is not connected

We need to understand what side-effects this problem can have.

--- Additional comment from John Skeoch on 2016-11-07 22:54:01 EST ---

User sraj at redhat.com's account has been closed

--- Additional comment from Kaleb KEITHLEY on 2016-11-08 12:00:29 EST ---

I'm not sure what I was being asked to confirm. That these warnings were
benign?

I installed the latest downstream: glusterfs*-3.8.4-3.rhgs and
nfs-ganesha-2.4.1-1.rhgs on RHEL7.3.  Did not observe any nfs-grace-monitor
timed out messages. From this I conclude that the fix provided in rhgs-3.1.3
has in fact resolved the issue.  If this is seen again in testing please open a
new BZ.

--- Additional comment from Ambarish on 2016-11-09 13:33:52 EST ---

Hitting this issue on 3.8.4-3 gluster bits and 2.4.1-1 Ganesha.


I had restarted Ganesha,glusterd and rpcbind services post setting up the
cluster.


[root at gqas013 tmp]# pcs status
Cluster name: G1474623742.03
Stack: corosync
Current DC: gqas013.sbu.lab.eng.bos.redhat.com (version 1.1.15-11.el7-e174ec8)
- partition with quorum
Last updated: Wed Nov  9 13:28:59 2016        Last change: Wed Nov  9 12:12:41
2016 by root via crm_attribute on gqas011.sbu.lab.eng.bos.redhat.com

4 nodes and 16 resources configured

Online: [ gqas005.sbu.lab.eng.bos.redhat.com gqas006.sbu.lab.eng.bos.redhat.com
gqas011.sbu.lab.eng.bos.redhat.com gqas013.sbu.lab.eng.bos.redhat.com ]

Full list of resources:

 Clone Set: nfs_setup-clone [nfs_setup]
     Started: [ gqas005.sbu.lab.eng.bos.redhat.com
gqas006.sbu.lab.eng.bos.redhat.com gqas011.sbu.lab.eng.bos.redhat.com
gqas013.sbu.lab.eng.bos.redhat.com ]
 Clone Set: nfs-mon-clone [nfs-mon]
     Started: [ gqas005.sbu.lab.eng.bos.redhat.com
gqas006.sbu.lab.eng.bos.redhat.com gqas011.sbu.lab.eng.bos.redhat.com
gqas013.sbu.lab.eng.bos.redhat.com ]
 Clone Set: nfs-grace-clone [nfs-grace]
     Started: [ gqas005.sbu.lab.eng.bos.redhat.com
gqas006.sbu.lab.eng.bos.redhat.com gqas011.sbu.lab.eng.bos.redhat.com
gqas013.sbu.lab.eng.bos.redhat.com ]
 gqas013.sbu.lab.eng.bos.redhat.com-cluster_ip-1    (ocf::heartbeat:IPaddr):   
Started gqas013.sbu.lab.eng.bos.redhat.com
 gqas005.sbu.lab.eng.bos.redhat.com-cluster_ip-1    (ocf::heartbeat:IPaddr):   
Started gqas005.sbu.lab.eng.bos.redhat.com
 gqas006.sbu.lab.eng.bos.redhat.com-cluster_ip-1    (ocf::heartbeat:IPaddr):   
Started gqas006.sbu.lab.eng.bos.redhat.com
 gqas011.sbu.lab.eng.bos.redhat.com-cluster_ip-1    (ocf::heartbeat:IPaddr):   
Started gqas011.sbu.lab.eng.bos.redhat.com

Failed Actions:
* nfs-grace_monitor_0 on gqas013.sbu.lab.eng.bos.redhat.com 'unknown error'
(1): call=18, status=complete, exitreason='none',
    last-rc-change='Wed Nov  9 12:08:14 2016', queued=0ms, exec=65ms
* nfs-grace_monitor_0 on gqas011.sbu.lab.eng.bos.redhat.com 'unknown error'
(1): call=18, status=complete, exitreason='none',
    last-rc-change='Wed Nov  9 12:08:14 2016', queued=0ms, exec=64ms


Daemon Status:
  corosync: active/disabled
  pacemaker: active/disabled
  pcsd: active/disabled
[root at gqas013 tmp]# 



Logs,core dump copied here :

http://rhsqe-repo.lab.eng.blr.redhat.com/sosreports/1393526

--- Additional comment from Ambarish on 2016-11-10 06:46:41 EST ---

One thing I'd like to add to my previous comment is that it is fairly
reproducible this time,with the latest builds.
I hit this four times,out of the 5 times I tried.


Referenced Bugs:

https://bugzilla.redhat.com/show_bug.cgi?id=1337565
[Bug 1337565] "nfs-grace-monitor" timed out messages observed
https://bugzilla.redhat.com/show_bug.cgi?id=1394224
[Bug 1394224] "nfs-grace-monitor" timed out messages observed
-- 
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