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.
Created attachment 995033 [details] sosreport of Node1
Created attachment 995034 [details] sosreport of Node2
This should get fixed by backporting http://review.gluster.org/9773
And http://review.gluster.org/9781 would be needed for that too.
Created attachment 1012349 [details] SOS from node with NFS process at 100% CPU
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
Oops, I updated the wrong BZ, ignore these.
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