Bug 1007033 - Excessive logging of warning message "remote operation failed: No data available" in samba-vfs logfile
Excessive logging of warning message "remote operation failed: No data availa...
Status: CLOSED ERRATA
Product: Red Hat Gluster Storage
Classification: Red Hat
Component: samba (Show other bugs)
2.1
Unspecified Unspecified
medium Severity medium
: ---
: RHGS 3.0.0
Assigned To: Raghavendra Talur
surabhi
: Patch, ZStream
Depends On: 1027174
Blocks: 1036465 1120136
  Show dependency treegraph
 
Reported: 2013-09-11 14:56 EDT by Lalatendu Mohanty
Modified: 2015-05-13 12:54 EDT (History)
10 users (show)

See Also:
Fixed In Version: glusterfs-3.6.0.25-1.el6rhs
Doc Type: Bug Fix
Doc Text:
Story Points: ---
Clone Of:
: 1027174 1120136 (view as bug list)
Environment:
Last Closed: 2014-09-22 15:29:00 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 Lalatendu Mohanty 2013-09-11 14:56:39 EDT
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
Comment 2 Lalatendu Mohanty 2013-09-16 22:54:35 EDT
I am only seeing this issue while doing fops or I/O from Cygwin installed on a Windows client. Hence lowering the severity.
Comment 3 Lalatendu Mohanty 2013-09-18 22:08:59 EDT
I am seeing the same issue when running a Perl script too. Hence removed the Cygwin from the description.
Comment 5 Jose A. Rivera 2013-10-18 15:13:23 EDT
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.
Comment 6 Krutika Dhananjay 2013-10-31 04:48:20 EDT
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.
Comment 8 Lalatendu Mohanty 2013-11-21 07:37:46 EST
Removed the need info as Krutika figured out the root cause and found a fix for it
Comment 9 surabhi 2013-12-10 02:15:15 EST
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
Comment 10 Niels de Vos 2014-02-28 12:30:48 EST
Posted http://review.gluster.org/7171 for upstream. When that gets accepted, we can pull that in to resolve comment #9.
Comment 11 Niels de Vos 2014-03-03 03:32:00 EST
(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.
Comment 13 Vivek Agarwal 2014-05-22 07:57:29 EDT
Merged as a part of rebase
Comment 14 surabhi 2014-07-16 06:16:23 EDT
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.
Comment 15 Vivek Agarwal 2014-07-18 02:06:48 EDT
Upstream patch: http://review.gluster.org/8315
Comment 16 Raghavendra Talur 2014-07-21 02:20:06 EDT
Patch merged downstream https://code.engineering.redhat.com/gerrit/#/c/29374/
Comment 17 surabhi 2014-07-24 03:20:29 EDT
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.
Comment 19 errata-xmlrpc 2014-09-22 15:29:00 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.

http://rhn.redhat.com/errata/RHEA-2014-1278.html

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