Bug 1027174 - Excessive logging of warning message "remote operation failed: No data available" in samba-vfs logfile
Summary: Excessive logging of warning message "remote operation failed: No data availa...
Keywords:
Status: CLOSED CURRENTRELEASE
Alias: None
Product: GlusterFS
Classification: Community
Component: logging
Version: mainline
Hardware: Unspecified
OS: Unspecified
unspecified
medium
Target Milestone: ---
Assignee: Raghavendra Talur
QA Contact:
URL:
Whiteboard:
Depends On:
Blocks: 1007033 1120136
TreeView+ depends on / blocked
 
Reported: 2013-11-06 10:24 UTC by Krutika Dhananjay
Modified: 2014-07-16 10:23 UTC (History)
8 users (show)

Fixed In Version: glusterfs-3.5.0
Doc Type: Bug Fix
Doc Text:
Clone Of: 1007033
Environment:
Last Closed: 2014-04-17 11:50:14 UTC
Regression: ---
Mount Type: ---
Documentation: ---
CRM:
Verified Versions:
Embargoed:


Attachments (Terms of Use)

Description Krutika Dhananjay 2013-11-06 10:24:06 UTC
+++ This bug was initially created as a clone of Bug #1007033 +++

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

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

--- Additional comment from Jose A. Rivera on 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.

--- Additional comment from Krutika Dhananjay on 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.

4. Also present in the client logs are messages of the kind '[2013-11-05 15:18:23.847545] E [afr-common.c:2109:afr_lookup_done] 1-dis-rep-replicate-1: /..: No gfid present' for every file that is created.

Comment 1 Anand Avati 2013-11-07 06:14:02 UTC
REVIEW: http://review.gluster.org/6237 (posix: Fix excessive logging resulting from get_real_filename failure from samba) posted (#1) for review on master by Krutika Dhananjay (kdhananj)

Comment 2 Anand Avati 2013-11-08 07:53:18 UTC
COMMIT: http://review.gluster.org/6237 committed in master by Vijay Bellur (vbellur) 
------
commit 9ebe1ede1f7bcf9a7cbc42314053ddf28c45b864
Author: Krutika Dhananjay <kdhananj>
Date:   Wed Nov 6 17:25:22 2013 +0530

    posix: Fix excessive logging resulting from get_real_filename failure from samba
    
    Change-Id: I641d028165da7b8501bd372c62d2df89a9d4db1f
    BUG: 1027174
    Signed-off-by: Krutika Dhananjay <kdhananj>
    Reviewed-on: http://review.gluster.org/6237
    Reviewed-by: poornima g <pgurusid>
    Tested-by: Gluster Build System <jenkins.com>
    Reviewed-by: Vijay Bellur <vbellur>

Comment 3 Anand Avati 2014-02-28 17:28:22 UTC
REVIEW: http://review.gluster.org/7171 (Reduce logging caused by non-existing extended attributes) posted (#1) for review on master by Niels de Vos (ndevos)

Comment 4 Anand Avati 2014-03-02 03:03:36 UTC
COMMIT: http://review.gluster.org/7171 committed in master by Anand Avati (avati) 
------
commit 7b3399cd462d0fca6509168f13a67f43e8b2c7d2
Author: Niels de Vos <ndevos>
Date:   Fri Feb 28 17:34:03 2014 +0100

    Reduce logging caused by non-existing extended attributes
    
    This changes the following log messages from INFO (default value) to
    DEBUG. We do not really care if someone tries to read extended
    attributes that do not exist.
    
        [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)
    
    Change-Id: Idbbeb026f81e67025a2b36d7bfeb125ad2a1f61b
    BUG: 1027174
    Signed-off-by: Niels de Vos <ndevos>
    Reviewed-on: http://review.gluster.org/7171
    Tested-by: Gluster Build System <jenkins.com>
    Reviewed-by: Harshavardhana <harsha>
    Reviewed-by: Anand Avati <avati>

Comment 5 Niels de Vos 2014-04-17 11:50:14 UTC
This bug is getting closed because a release has been made available that should address the reported issue. In case the problem is still not fixed with glusterfs-3.5.0, please reopen this bug report.

glusterfs-3.5.0 has been announced on the Gluster Developers mailinglist [1], packages for several distributions should become available in the near future. Keep an eye on the Gluster Users mailinglist [2] and the update infrastructure for your distribution.

[1] http://thread.gmane.org/gmane.comp.file-systems.gluster.devel/6137
[2] http://thread.gmane.org/gmane.comp.file-systems.gluster.user


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