Description of problem: The below log message filled 99% of the /var/log/samba/glusterfs-dis-rep3.log file for a particular fops i.e. remove file and recreate the same file. [2013-09-11 18:19:07.521255] W [client-rpc-fops.c:1170:client3_3_fgetxattr_cbk] 9-dis-rep3-client-5: remote operation failed: No data available [2013-09-11 18:19:07.521724] W [client-rpc-fops.c:1170:client3_3_fgetxattr_cbk] 9-dis-rep3-client-4: remote operation failed: No data available [2013-09-11 18:19:07.636170] W [client-rpc-fops.c:1170:client3_3_fgetxattr_cbk] 0-dis-rep3-client-11: remote operation failed: No data available [2013-09-11 18:19:07.636739] W [client-rpc-fops.c:1170:client3_3_fgetxattr_cbk] 0-dis-rep3-client-10: remote operation failed: No data available [2013-09-11 18:19:08.059362] W [client-rpc-fops.c:1170:client3_3_fgetxattr_cbk] 0-dis-rep3-client-7: remote operation failed: No data available [2013-09-11 18:19:08.059707] W [client-rpc-fops.c:1170:client3_3_fgetxattr_cbk] 0-dis-rep3-client-6: remote operation failed: No data available [2013-09-11 18:19:08.286463] W [client-rpc-fops.c:1170:client3_3_fgetxattr_cbk] 9-dis-rep3-client-5: remote operation failed: No data available [2013-09-11 18:19:08.286937] W [client-rpc-fops.c:1170:client3_3_fgetxattr_cbk] 9-dis-rep3-client-4: remote operation failed: No data available [2013-09-11 18:19:08.334356] W [client-rpc-fops.c:1170:client3_3_fgetxattr_cbk] 9-dis-rep3-client-5: remote operation failed: No data available [2013-09-11 18:19:08.334903] W [client-rpc-fops.c:1170:client3_3_fgetxattr_cbk] 9-dis-rep3-client-4: remote operation failed: No data available [root@dhcp159-136 samba]# cat glusterfs-dis-rep3.log | wc -l 314820 [root@dhcp159-136 samba]# cat glusterfs-dis-rep3.log | grep 'remote operation failed' | wc -l 308636 Version-Release number of selected component (if applicable): Samba version: 3.6.9-160.3 Gluster version: 3.4.0.33rhs-1 How reproducible: Always Steps to Reproduce: 1. Mount a gluster samba share on Windows client 2. Run a script to do below steps, in an infinite loop a. create a file b. write in to the file c. delete the file d. go to step a 3. Check the /var/log/samba/gluster-<volume name>.log in the samba server Actual results: The log file is continuously filled with the mentioned log message. Expected results: We should not log same messages so much , else it will fill up the /var/log/samba directory Additional info: We can see from the log message the message is coming from client3_3_fgetxattr_cbk function present in xlators/protocol/client/src/client-rpc-fops.c Though this means it is not a bug from gluster-smb. But it seems only samba users are getting effected by this as the log file in /var/log/samba is getting filled by it. So kept the component as gluster-smb
I am only seeing this issue while doing fops or I/O from Cygwin installed on a Windows client. Hence lowering the severity.
I am seeing the same issue when running a Perl script too. Hence removed the Cygwin from the description.
We have almost enough information to do a proper analysis on this. We need a network capture (Wireshark-compatible) of the traffic that is associated with this error.
Posting my observations on this issue: 1. These log messages are seen when stat-prefetch on the volume is turned off. 2. The log messages mentioned in comment #1 are due to getxattr failures on 'system.posix_acl_access' on the filename after it is created. 3. Also, one must note that there are 4 (innocuous) warning messages in the brick logfiles for every file that is created. This happens because of the get_real_filename requests sent by samba BEFORE creating the file, leading to a getxattr failure with ENOENT on the bricks in posix xlator.
Removed the need info as Krutika figured out the root cause and found a fix for it
Seen the following errors in brick logs in gluster version: glusterfs-3.4.0.47.1u2rhs-1.el6rhs.x86_64 [2013-12-09 12:19:02.053160] E [posix.c:3539:posix_fgetxattr] 0-dis-rep-posix: fgetxattr failed on key system.posix_acl_access (No data available) [2013-12-09 12:19:02.053211] I [server-rpc-fops.c:863:server_fgetxattr_cbk] 0-dis-rep-server: 11757: FGETXATTR 1 (a525071b-01c8-4228-b4e9-5402cb908549) (system.posix_acl_access) ==> (No data available) [2013-12-09 12:19:05.924497] E [posix.c:3539:posix_fgetxattr] 0-dis-rep-posix: fgetxattr failed on key system.posix_acl_access (No data available) [2013-12-09 12:19:05.924545] I [server-rpc-fops.c:863:server_fgetxattr_cbk] 0-dis-rep-server: 13074: FGETXATTR 1 (b8381953-ffa5-40fa-90dd-ae122335cc4b) (system.posix_acl_access) ==> (No data available) [2013-12-09 12:19:09.126985] E [posix.c:3539:posix_fgetxattr] 0-dis-rep-posix: fgetxattr failed on key system.posix_acl_access (No data available) [2013-12-09 12:19:09.127049] I [server-rpc-fops.c:863:server_fgetxattr_cbk] 0-dis-rep-server: 13967: FGETXATTR 1 (cc7e4d5d-7ab7-41ac-a34d-d0ebbccc213b) (system.posix_acl_access) ==> (No data available) [2013-12-09 12:19:12.861238] E [posix.c:3539:posix_fgetxattr] 0-dis-rep-posix: fgetxattr failed on key system.posix_acl_access (No data available) [2013-12-09 12:19:12.861326] I [server-rpc-fops.c:863:server_fgetxattr_cbk] 0-dis-rep-server: 15280: FGETXATTR 1 (ebb7eec3-897f-4601-a773-57b5ba6a6e9b) (system.posix_acl_access) ==> (No data available) [2013-12-09 12:19:42.200533] E [posix.c:3539:posix_fgetxattr] 0-dis-rep-posix: fgetxattr failed on key system.posix_acl_access (No data available) [2013-12-09 12:19:42.200584] I [server-rpc-fops.c:863:server_fgetxattr_cbk] 0-dis-rep-server: 16784: FGETXATTR 1 (bff61862-5c21-4e67-a810-031caacd4d5a) (system.posix_acl_access) ==> (No data available) [2013-12-09 12:19:51.766865] E [posix.c:3539:posix_fgetxattr] 0-dis-rep-posix: fgetxattr failed on key system.posix_acl_access (No data available) [2013-12-09 12:19:51.766914] I [server-rpc-fops.c:863:server_fgetxattr_cbk] 0-dis-rep-server: 17546: FGETXATTR 1 (914da2c8-6a08-49ce-97aa-b6e78fba40b1) (system.posix_acl_access) ==> (No data available) [2013-12-09 12:19:55.492649] E [posix.c:3539:posix_fgetxattr] 0-dis-rep-posix: fgetxattr failed on key system.posix_acl_access (No data available) [2013-12-09 12:19:55.492749] I [server-rpc-fops.c:863:server_fgetxattr_cbk] 0-dis-rep-server: 18863: FGETXATTR 1 (db584f43-dd70-40ba-a573-7b4d97ab5387) (system.posix_acl_access) ==> (No data available) [2013-12-09 12:37:10.165411] I [server-handshake.c:569:server_setvolume] 0-dis-rep-server: accepted client from dhcp159-237.sbu.lab.eng.bos.redhat.com-28971-2013/12/09-12:37:09:947586-dis-rep-client-4-0 (version: 3.4.0.47.1u2rhs) [2013-12-10 06:29:14.288816] I [server-handshake.c:569:server_setvolume] 0-dis-rep-server: accepted client from dhcp159-237.sbu.lab.eng.bos.redhat.com-9434-20
Posted http://review.gluster.org/7171 for upstream. When that gets accepted, we can pull that in to resolve comment #9.
(In reply to Niels de Vos from comment #10) > Posted http://review.gluster.org/7171 for upstream. When that gets accepted, > we can pull that in to resolve comment #9. Now we can backport upstream commit 7b3399cd462d0fca6509168f13a67f43e8b2c7d2.
Merged as a part of rebase
With the latest glusterfs build : rpm -qa | grep glusterfs [root@dhcp159-197 samba]# rpm -qa | grep glusterfs glusterfs-cli-3.6.0.24-1.el6rhs.x86_64 glusterfs-3.6.0.24-1.el6rhs.x86_64 glusterfs-server-3.6.0.24-1.el6rhs.x86_64 glusterfs-libs-3.6.0.24-1.el6rhs.x86_64 glusterfs-api-3.6.0.24-1.el6rhs.x86_64 glusterfs-fuse-3.6.0.24-1.el6rhs.x86_64 glusterfs-api-devel-3.6.0.24-1.el6rhs.x86_64 glusterfs-geo-replication-3.6.0.24-1.el6rhs.x86_64 glusterfs-debuginfo-3.6.0.24-1.el6rhs.x86_64 samba-glusterfs-3.6.9-168.4.el6rhs.x86_64 glusterfs-devel-3.6.0.24-1.el6rhs.x86_64 glusterfs-rdma-3.6.0.24-1.el6rhs.x86_64 Seeing the following errors in client logs: [2014-07-16 09:56:53.615618] W [client-rpc-fops.c:1155:client3_3_fgetxattr_cbk] 0-dis-rep-client-10: remote operation failed: No data available [2014-07-16 09:56:55.537775] W [client-rpc-fops.c:1155:client3_3_fgetxattr_cbk] 0-dis-rep-client-4: remote operation failed: No data available [2014-07-16 09:56:55.538067] W [client-rpc-fops.c:1155:client3_3_fgetxattr_cbk] 0-dis-rep-client-5: remote operation failed: No data available [2014-07-16 09:57:23.159832] W [client-rpc-fops.c:1155:client3_3_fgetxattr_cbk] 0-dis-rep-client-10: remote operation failed: No data available [2014-07-16 09:57:23.160215] W [client-rpc-fops.c:1155:client3_3_fgetxattr_cbk] 0-dis-rep-client-11: remote operation failed: No data available [2014-07-16 09:57:25.120439] W [client-rpc-fops.c:1155:client3_3_fgetxattr_cbk] 0-dis-rep-client-11: remote operation failed: No data available [2014-07-16 09:57:25.120920] W [client-rpc-fops.c:1155:client3_3_fgetxattr_cbk] 0-dis-rep-client-10: remote operation failed: No data available [2014-07-16 09:57:27.296431] W [client-rpc-fops.c:1155:client3_3_fgetxattr_cbk] However, Not seeing the errors in brick logs as was seen earlier.had discussion with Talur and it seems the fix has gone in for brick logs and client logs fix is pending.Moving the bug to Assigned state.
Upstream patch: http://review.gluster.org/8315
Patch merged downstream https://code.engineering.redhat.com/gerrit/#/c/29374/
With the build glusterfs-3.6.0.25-1.el6rhs.x86_64 .tried the same test and not seeing excessive errors in client/server logs.marking the bz to verified.
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. http://rhn.redhat.com/errata/RHEA-2014-1278.html