Bug 1196057

Summary: NFS logs are filled with system.posix_acl_access messages
Product: [Red Hat Storage] Red Hat Gluster Storage Reporter: Bhaskarakiran <byarlaga>
Component: gluster-nfsAssignee: Ben Turner <bturner>
Status: CLOSED CURRENTRELEASE QA Contact: Saurabh <saujain>
Severity: unspecified Docs Contact:
Priority: unspecified    
Version: rhgs-3.0CC: akhakhar, annair, asrivast, byarlaga, mzywusko, ndevos, nsathyan, rcyriac, vagarwal
Target Milestone: ---Keywords: EasyFix, Patch, ZStream
Target Release: ---   
Hardware: Unspecified   
OS: Unspecified   
Whiteboard:
Fixed In Version: Doc Type: Bug Fix
Doc Text:
Story Points: ---
Clone Of:
: 1197253 1214211 1224126 (view as bug list) Environment:
Last Closed: 2015-08-10 07:45:02 UTC Type: Bug
Regression: --- Mount Type: ---
Documentation: --- CRM:
Verified Versions: Category: ---
oVirt Team: --- RHEL 7.3 requirements from Atomic Host:
Cloudforms Team: --- Target Upstream Version:
Embargoed:
Bug Depends On: 1197253    
Bug Blocks: 1186580, 1214211, 1224126    
Attachments:
Description Flags
sosreport of Node1
none
sosreport of Node2
none
SOS from node with NFS process at 100% CPU none

Description Bhaskarakiran 2015-02-25 08:41:58 UTC 
Description of problem:
======================

NFS logs are getting filled with below messages :

[2015-02-25 06:21:12.993029] I [dict.c:371:dict_get] (-->/usr/lib64/glusterfs/3.6.0.46/xlator/debug/io-stats.so(io_stats_getxattr_cbk+0xf6) [0x7ff08c07ea86] (-->/usr/lib64/glusterfs/3.6.0.46/xlator/nfs/server.so(nfs_fop_getxattr_cbk+0x2f) [0x7ff087dba91f] (-->/usr/lib64/glusterfs/3.6.0.46/xlator/nfs/server.so(acl3_getacl_cbk+0x8d) [0x7ff087de4e5d]))) 0-dict: !this || key=system.posix_acl_access
[2015-02-25 06:21:12.995279] I [dict.c:371:dict_get] (-->/usr/lib64/glusterfs/3.6.0.46/xlator/debug/io-stats.so(io_stats_getxattr_cbk+0xf6) [0x7ff08c07ea86] (-->/usr/lib64/glusterfs/3.6.0.46/xlator/nfs/server.so(nfs_fop_getxattr_cbk+0x2f) [0x7ff087dba91f] (-->/usr/lib64/glusterfs/3.6.0.46/xlator/nfs/server.so(acl3_getacl_cbk+0x8d) [0x7ff087de4e5d]))) 0-dict: !this || key=system.posix_acl_access
[2015-02-25 06:21:12.997439] I [dict.c:371:dict_get] (-->/usr/lib64/glusterfs/3.6.0.46/xlator/debug/io-stats.so(io_stats_getxattr_cbk+0xf6) [0x7ff08c07ea86] (-->/usr/lib64/glusterfs/3.6.0.46/xlator/nfs/server.so(nfs_fop_getxattr_cbk+0x2f) [0x7ff087dba91f] (-->/usr/lib64/glusterfs/3.6.0.46/xlator/nfs/server.so(acl3_getacl_cbk+0x8d) [0x7ff087de4e5d]))) 0-dict: !this || key=system.posix_acl_access
[2015-02-25 06:22:30.395445] I [dict.c:371:dict_get] (-->/usr/lib64/glusterfs/3.6.0.46/xlator/debug/io-stats.so(io_stats_getxattr_cbk+0xf6) [0x7ff08c07ea86] (-->/usr/lib64/glusterfs/3.6.0.46/xlator/nfs/server.so(nfs_fop_getxattr_cbk+0x2f) [0x7ff087dba91f] (-->/usr/lib64/glusterfs/3.6.0.46/xlator/nfs/server.so(acl3_getacl_cbk+0x8d) [0x7ff087de4e5d]))) 0-dict: !this || key=system.posix_acl_access
[2015-02-25 06:22:30.405158] I [dict.c:371:dict_get] (-->/usr/lib64/glusterfs/3.6.0.46/xlator/debug/io-stats.so(io_stats_getxattr_cbk+0xf6) [0x7ff08c07ea86] (-->/usr/lib64/glusterfs/3.6.0.46/xlator/nfs/server.so(nfs_fop_getxattr_cbk+0x2f) [0x7ff087dba91f] (-->/usr/lib64/glusterfs/3.6.0.46/xlator/nfs/server.so(acl3_getacl_cbk+0x8d) [0x7ff087de4e5d]))) 0-dict: !this || key=system.posix_acl_access


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

[root@ninja glusterfs]# gluster --version
glusterfs 3.6.0.46 built on Feb 20 2015 12:32:40
Repository revision: git://git.gluster.com/glusterfs.git
Copyright (c) 2006-2011 Gluster Inc. <http://www.gluster.com>
GlusterFS comes with ABSOLUTELY NO WARRANTY.
You may redistribute copies of GlusterFS under the terms of the GNU General Public License.
[root@ninja glusterfs]# 

How reproducible:
=================
100%


Steps to Reproduce:
1. Mount NFS volume and run IO.
2.
3.

Actual results:


Expected results:


Additional info:
================
Attaching the sosreports.
Comment 1 Bhaskarakiran 2015-02-25 09:06:31 UTC 
Created attachment 995033 [details]
sosreport of Node1
Comment 2 Bhaskarakiran 2015-02-25 09:07:50 UTC 
Created attachment 995034 [details]
sosreport of Node2
Comment 4 Niels de Vos 2015-02-27 23:02:45 UTC 
This should get fixed by backporting http://review.gluster.org/9773
Comment 5 Niels de Vos 2015-03-02 08:58:34 UTC 
And http://review.gluster.org/9781 would be needed for that too.
Comment 10 Ben Turner 2015-04-08 18:06:43 UTC 
Created attachment 1012349 [details]
SOS from node with NFS process at 100% CPU
Comment 11 Ben Turner 2015-04-08 18:08:25 UTC 
Snip from NFS.log:

[2015-04-07 05:51:39.407690] I [dht-layout.c:684:dht_layout_normalize] 0-testvol-dht: Found anomalies in / (gfid = 00000000-0000-0000-0000-000000000001). Holes=1 overlaps=0
[2015-04-07 05:51:43.267282] I [rpc-clnt.c:1759:rpc_clnt_reconfig] 0-testvol-client-1: changing port to 49152 (from 0)
[2015-04-07 05:51:43.271365] I [rpc-clnt.c:1759:rpc_clnt_reconfig] 0-testvol-client-2: changing port to 49152 (from 0)
[2015-04-07 05:51:43.275668] I [client-handshake.c:1412:select_server_supported_programs] 0-testvol-client-1: Using Program GlusterFS 3.3, Num (1298437), Version (330)
[2015-04-07 05:51:43.276132] I [client-handshake.c:1200:client_setvolume_cbk] 0-testvol-client-1: Connected to testvol-client-1, attached to remote volume '/bricks/testvol_brick1'.
[2015-04-07 05:51:43.276160] I [client-handshake.c:1210:client_setvolume_cbk] 0-testvol-client-1: Server and Client lk-version numbers are not same, reopening the fds
[2015-04-07 05:51:43.276393] I [client-handshake.c:187:client_set_lk_version_cbk] 0-testvol-client-1: Server lk version = 1
[2015-04-07 05:51:43.280068] I [client-handshake.c:1412:select_server_supported_programs] 0-testvol-client-2: Using Program GlusterFS 3.3, Num (1298437), Version (330)
[2015-04-07 05:51:43.280434] I [client-handshake.c:1200:client_setvolume_cbk] 0-testvol-client-2: Connected to testvol-client-2, attached to remote volume '/bricks/testvol_brick2'.
[2015-04-07 05:51:43.280456] I [client-handshake.c:1210:client_setvolume_cbk] 0-testvol-client-2: Server and Client lk-version numbers are not same, reopening the fds
[2015-04-07 05:51:43.280718] I [client-handshake.c:187:client_set_lk_version_cbk] 0-testvol-client-2: Server lk version = 1
[2015-04-07 05:51:44.804876] W [socket.c:546:__socket_rwv] 0-testvol-client-0: readv on 192.168.79.100:49152 failed (No data available)
[2015-04-07 05:51:44.804936] I [client.c:2282:client_rpc_notify] 0-testvol-client-0: disconnected from testvol-client-0. Client process will keep trying to connect to glusterd until brick's port is available
[2015-04-07 05:51:46.930456] W [socket.c:546:__socket_rwv] 0-testvol-client-3: readv on 192.168.79.103:49152 failed (No data available)
[2015-04-07 05:51:46.930506] I [client.c:2282:client_rpc_notify] 0-testvol-client-3: disconnected from testvol-client-3. Client process will keep trying to connect to glusterd until brick's port is available
[2015-04-07 05:51:46.930608] W [socket.c:546:__socket_rwv] 0-testvol-client-2: readv on 192.168.79.102:49152 failed (No data available)
[2015-04-07 05:51:46.930641] I [client.c:2282:client_rpc_notify] 0-testvol-client-2: disconnected from testvol-client-2. Client process will keep trying to connect to glusterd until brick's port is available
[2015-04-07 05:51:46.930664] E [MSGID: 108006] [afr-common.c:4527:afr_notify] 0-testvol-replicate-1: All subvolumes are down. Going offline until atleast one of them comes back up.
[2015-04-07 05:51:46.930709] W [socket.c:546:__socket_rwv] 0-testvol-client-1: readv on 192.168.79.101:49152 failed (No data available)
[2015-04-07 05:51:46.930792] I [client.c:2282:client_rpc_notify] 0-testvol-client-1: disconnected from testvol-client-1. Client process will keep trying to connect to glusterd until brick's port is available
[2015-04-07 05:51:46.930819] E [MSGID: 108006] [afr-common.c:4527:afr_notify] 0-testvol-replicate-0: All subvolumes are down. Going offline until atleast one of them comes back up.
[2015-04-07 05:51:58.235793] I [MSGID: 100030] [glusterfsd.c:2019:main] 0-/usr/sbin/glusterfs: Started running /usr/sbin/glusterfs version 3.6.0.53 (args: /usr/sbin/glusterfs -s localhost --volfile-id gluster/nf
s -p /var/lib/glusterd/nfs/run/nfs.pid -l /var/log/glusterfs/nfs.log -S /var/run/9ab9f5d0fa80dbb72e3d178d2fbef502.socket)
[2015-04-07 05:51:58.248977] I [event-epoll.c:629:event_dispatch_epoll_worker] 0-epoll: Started thread with index 1
[2015-04-07 05:51:58.253742] I [rpcsvc.c:2142:rpcsvc_set_outstanding_rpc_limit] 0-rpc-service: Configured rpc.outstanding-rpc-limit with value 16
[2015-04-07 05:51:58.280618] I [rpc-drc.c:731:rpcsvc_drc_init] 0-rpc-service: DRC is turned OFF
[2015-04-07 05:51:58.280664] I [nfs.c:1354:init] 0-nfs: NFS service started
[2015-04-07 05:51:58.280931] I [dht-shared.c:337:dht_init_regex] 0-testvol-dht: using regex rsync-hash-regex = ^\.(.+)\.[^.]+$
[2015-04-07 05:51:58.284498] I [event-epoll.c:629:event_dispatch_epoll_worker] 0-epoll: Started thread with index 2
Comment 12 Ben Turner 2015-04-08 18:09:05 UTC 
Oops, I updated the wrong BZ, ignore these.
Comment 14 Apeksha 2015-07-02 08:45:08 UTC 
Verified on glusterfs-3.7.1-6.el6rhs.x86_64
No posix_acl messages found in nfs.log file while running IO on nfs volume