Bug 1299724

Summary:	Excessive logging in mount when bricks of the replica are down
Product:	[Red Hat Storage] Red Hat Gluster Storage	Reporter:	spandura
Component:	replicate	Assignee:	Ravishankar N <ravishankar>
Status:	CLOSED ERRATA	QA Contact:	spandura
Severity:	high	Docs Contact:
Priority:	unspecified
Version:	rhgs-3.1	CC:	bugs, byarlaga, pkarampu, ravishankar, rcyriac, rhinduja, rhs-bugs, sankarshan, sbhaloth, storage-qa-internal
Target Milestone:	---	Keywords:	Triaged, ZStream
Target Release:	RHGS 3.1.2
Hardware:	Unspecified
OS:	Unspecified
Whiteboard:
Fixed In Version:	glusterfs-3.7.5-18	Doc Type:	Bug Fix
Doc Text:		Story Points:	---
Clone Of:	1294053	Environment:
Last Closed:	2016-03-01 06:07:15 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:	1294053
Bug Blocks:

Description spandura 2016-01-19 06:38:43 UTC

+++ This bug was initially created as a clone of Bug #1294053 +++

Description of problem:

Commit 2b7226f9d3470d8fe4c98c1fddb06e7f641e364d did not check for the
validity of a dict before doing a dict_get. This floods the mount log with lot of spurios messages when one of the bricks is down in a replica subovolume:

[2015-12-24 09:31:48.793530] I [dict.c:462:dict_get] (-->/usr/local/lib/glusterfs/3.8dev/xlator/cluster/replicate.so(+0x4de19) [0x7fabffdd6e19] -->/usr/local/lib/glusterfs/3.8dev/xlator/cluster/replicate.so(+0x4d946) [0x7fabffdd6946] -->/usr/local/lib/libglusterfs.so.0(dict_get+0x72) [0x7fac11800302] ) 0-dict: !this || key=glusterfs.bad-inode [Invalid argument]
[2015-12-24 09:31:48.794164] I [dict.c:462:dict_get] (-->/usr/local/lib/glusterfs/3.8dev/xlator/cluster/replicate.so(+0x4de19) [0x7fabffdd6e19] -->/usr/local/lib/glusterfs/3.8dev/xlator/cluster/replicate.so(+0x4d946) [0x7fabffdd6946] -->/usr/local/lib/libglusterfs.so.0(dict_get+0x72) [0x7fac11800302] ) 0-dict: !this || key=glusterfs.bad-inode [Invalid argument]
[2015-12-24 09:31:48.794692] I [dict.c:462:dict_get] (-->/usr/local/lib/glusterfs/3.8dev/xlator/cluster/replicate.so(+0x4de19) [0x7fabffdd6e19]

--- Additional comment from Vijay Bellur on 2015-12-24 05:12:23 EST ---

REVIEW: http://review.gluster.org/13077 (afr: Fix excessive logging in afr_accuse_smallfiles()) posted (#1) for review on master by Ravishankar N (ravishankar)

--- Additional comment from Vijay Bellur on 2015-12-28 06:55:47 EST ---

REVIEW: http://review.gluster.org/13077 (afr: Fix excessive logging in afr_accuse_smallfiles()) posted (#2) for review on master by Ravishankar N (ravishankar)

--- Additional comment from Vijay Bellur on 2015-12-29 02:26:33 EST ---

COMMIT: http://review.gluster.org/13077 committed in master by Pranith Kumar Karampuri (pkarampu) 
------
commit 4c1b66720121ca97ccfac3e09f93519f2f07ddfd
Author: Ravishankar N <ravishankar>
Date:   Thu Dec 24 15:22:05 2015 +0530

    afr: Fix excessive logging in afr_accuse_smallfiles()
    
    Commit 2b7226f9d3470d8fe4c98c1fddb06e7f641e364d did not check for the
    validity of a dict before doing a dict_get. Fix that.
    
    Change-Id: Ie21f4da19256b17196f242cd8fd5bb76b0a69c1e
    BUG: 1294053
    Signed-off-by: Ravishankar N <ravishankar>
    Reviewed-on: http://review.gluster.org/13077
    Tested-by: NetBSD Build System <jenkins.org>
    Tested-by: Gluster Build System <jenkins.com>
    Reviewed-by: Pranith Kumar Karampuri <pkarampu>

--- Additional comment from Ravishankar N on 2016-01-06 08:32:31 EST ---

Found one more code path where the message gets logged, hence moving the bug back to post and using the same bug ID for the next patch.

--- Additional comment from Vijay Bellur on 2016-01-06 08:37:05 EST ---

REVIEW: http://review.gluster.org/13185 (afr : Check if dict is valid in afr_replies_interpret()) posted (#1) for review on master by Ravishankar N (ravishankar)

--- Additional comment from Vijay Bellur on 2016-01-10 23:32:27 EST ---

REVIEW: http://review.gluster.org/13185 (afr : Check if dict is valid in afr_replies_interpret()) posted (#2) for review on master by Ravishankar N (ravishankar)

--- Additional comment from Vijay Bellur on 2016-01-12 05:42:54 EST ---

REVIEW: http://review.gluster.org/13185 (afr : Check if dict is valid in afr_replies_interpret()) posted (#3) for review on master by Ravishankar N (ravishankar)

--- Additional comment from Vijay Bellur on 2016-01-18 02:12:01 EST ---

REVIEW: http://review.gluster.org/13185 (afr : Check if dict is valid in afr_replies_interpret()) posted (#4) for review on master by Ravishankar N (ravishankar)

Comment 2 surabhi 2016-01-19 08:32:19 UTC

Samba-client logs getting filled heavily with following log messages :

***********************************************************************

[2016-01-18 10:17:35.821196] I [dict.c:473:dict_get] (-->/usr/lib64/glusterfs/3.7.5/xlator/cluster/replicate.so(afr_replies_interpret+0x1ad) [0x7fd8bda90edd] -->/usr/li
b64/glusterfs/3.7.5/xlator/cluster/replicate.so(afr_accuse_smallfiles+0x66) [0x7fd8bda90ca6] -->/lib64/libglusterfs.so.0(dict_get+0xac) [0x7fd8c22160cc] ) 0-dict: !this
 || key=glusterfs.bad-inode [Invalid argument]
[2016-01-18 10:17:35.821247] I [dict.c:473:dict_get] (-->/usr/lib64/glusterfs/3.7.5/xlator/cluster/replicate.so(afr_replies_interpret+0x1ad) [0x7fd8bda90edd] -->/usr/li
b64/glusterfs/3.7.5/xlator/cluster/replicate.so(afr_accuse_smallfiles+0x66) [0x7fd8bda90ca6] -->/lib64/libglusterfs.so.0(dict_get+0xac) [0x7fd8c22160cc] ) 0-dict: !this
 || key=glusterfs.bad-inode [Invalid argument]
[2016-01-18 10:17:35.823257] I [MSGID: 109036] [dht-common.c:7957:dht_log_new_layout_for_dir_selfheal] 0-testvol-dht: Setting layout of /d2 with [Subvol_name: testvol-r
eplicate-0, Err: -1 , Start: 2147483647 , Stop: 4294967295 , Hash: 1 ], [Subvol_name: testvol-replicate-1, Err: -1 , Start: 0 , Stop: 2147483646 , Hash: 1 ], 
[2016-01-18 10:17:35.848572] I [dict.c:473:dict_get] (-->/usr/lib64/glusterfs/3.7.5/xlator/cluster/replicate.so(+0x11c41) [0x7fd8bda62c41] -->/usr/lib64/glusterfs/3.7.5
/xlator/cluster/replicate.so(afr_replies_interpret+0x15e) [0x7fd8bda90e8e] -->/lib64/libglusterfs.so.0(dict_get+0xac) [0x7fd8c22160cc] ) 0-dict: !this || key=glusterfs.
bad-inode [Invalid argument]
[2016-01-18 10:17:35.848669] I [dict.c:473:dict_get] (-->/usr/lib64/glusterfs/3.7.5/xlator/cluster/replicate.so(+0x11c41) [0x7fd8bda62c41] -->/usr/lib64/glusterfs/3.7.5/xlator/cluster/replicate.so(afr_replies_interpret+0x15e) [0x7fd8bda90e8e] -->/lib64/libglusterfs.so.0(dict_get+0xac) [0x7fd8c22160cc] ) 0-dict: !this || key=glusterfs.bad-inode [Invalid argument]
[2016-01-18 10:17:35.848755] I [dict.c:473:dict_get] (-->/usr/lib64/glusterfs/3.7.5/xlator/cluster/replicate.so(afr_replies_interpret+0x1ad) [0x7fd8bda90edd] -->/usr/lib64/glusterfs/3.7.5/xlator/cluster/replicate.so(afr_accuse_smallfiles+0x66) [0x7fd8bda90ca6] -->/lib64/libglusterfs.so.0(dict_get+0xac) [0x7fd8c22160cc] ) 0-dict: !this || key=glusterfs.bad-inode [Invalid argument]
[2016-01-18 10:17:35.848816] I [dict.c:473:dict_get] (-->/usr/lib64/glusterfs/3.7.5/xlator/cluster/replicate.so(afr_replies_interpret+0x1ad) [0x7fd8bda90edd] -->/usr/lib64/glusterfs/3.7.5/xlator/cluster/replicate.so(afr_accuse_smallfiles+0x66) [0x7fd8bda90ca6] -->/lib64/libglusterfs.so.0(dict_get+0xac) [0x7fd8c22160cc] ) 0-dict: !this || key=glusterfs.bad-inode [Invalid argument]
[2016-01-18 10:17:35.850492] I [dict.c:473:dict_get] (-->/usr/lib64/glusterfs/3.7.5/xlator/cluster/replicate.so(+0x11c41) [0x7fd8bda62c41] -->/usr/lib64/glusterfs/3.7.5/xlator/cluster/replicate.so(afr_replies_interpret+0x15e) [0x7fd8bda90e8e] -->/lib64/libglusterfs.so.0(dict_get+0xac) [0x7fd8c22160cc] ) 0-dict: !this || key=glusterfs.bad-inode [Invalid argument]
[2016-01-18 10:17:35.850568] I [dict.c:473:dict_get] (-->/usr/lib64/glusterfs/3.7.5/xlator/cluster/replicate.so(+0x11c41) [0x7fd8bda62c41] -->/usr/lib64/glusterfs/3.7.5/xlator/cluster/replicate.so(afr_replies_interpret+0x15e) [0x7fd8bda90e8e] -->/lib64/libglusterfs.so.0(dict_get+0xac) [0x7fd8c22160cc] ) 0-dict: !this || key=glusterfs.bad-inode [Invalid argument]
[2016-01-18 10:17:35.850627] I [dict.c:473:dict_get] (-->/usr/lib64/glusterfs/3.7.5/xlator/cluster/replicate.so(afr_replies_interpret+0x1ad) [0x7fd8bda90edd] -->/usr/lib64/glusterfs/3.7.5/xlator/cluster/replicate.so(afr_accuse_smallfiles+0x66) [0x7fd8bda90ca6] -->/lib64/libglusterfs.so.0(dict_get+0xac) [0x7fd8c22160cc] ) 0-dict: !this || key=glusterfs.bad-inode [Invalid argument]
[2016-01-18 10:17:35.850679] I [dict.c:473:dict_get] (-->/usr/lib64/glusterfs/3.7.5/xlator/cluster/replicate.so(afr_replies_interpret+0x1ad) [0x7fd8bda90edd] -->/usr/lib64/glusterfs/3.7.5/xlator/cluster/replicate.so(afr_accuse_smallfiles+0x66) [0x7fd8bda90ca6] -->/lib64/libglusterfs.so.0(dict_get+0xac) [0x7fd8c22160cc] ) 0-dict: !this || key=glusterfs.bad-inode [Invalid argument]
[2016-01-18 10:17:35.856216] I [MSGID: 109036] [dht-common.c:7957:dht_log_new_layout_for_dir_selfheal] 0-testvol-dht: Setting layout of /d3 with [Subvol_name: testvol-replicate-0, Err: -1 , Start: 2147483647 , Stop: 4294967295 , Hash: 1 ], [Subvol_name: testvol-replicate-1, Err: -1 , Start: 0 , Stop: 2147483646 , Hash: 1 ], 
[2016-01-18 10:17:35.889379] I [dict.c:473:dict_get] (-->/usr/lib64/glusterfs/3.7.5/xlator/cluster/replicate.so(+0x11c41) [0x7fd8bda62c41] -->/usr/lib64/glusterfs/3.7.5:

Comment 3 Rahul Hinduja 2016-01-20 10:41:09 UTC

Geo-Replication client logs too field with the same logs:

Note: None of the bricks were brought offline


[2016-01-20 10:38:50.838346] I [dict.c:473:dict_get] (-->/usr/lib64/glusterfs/3.7.5/xlator/cluster/replicate.so(afr_replies_interpret+0x1ad) [0x7f8fbccb5edd] -->/usr/lib64/glusterfs/3.7.5/xlator/cluster/replicate.so(afr_accuse_smallfiles+0x66) [0x7f8fbccb5ca6] -->/lib64/libglusterfs.so.0(dict_get+0xac) [0x7f8fcae600cc] ) 0-dict: !this || key=glusterfs.bad-inode [Invalid argument]
[2016-01-20 10:38:50.844804] I [dict.c:473:dict_get] (-->/usr/lib64/glusterfs/3.7.5/xlator/cluster/replicate.so(afr_replies_interpret+0x1ad) [0x7f8fbccb5edd] -->/usr/lib64/glusterfs/3.7.5/xlator/cluster/replicate.so(afr_accuse_smallfiles+0x66) [0x7f8fbccb5ca6] -->/lib64/libglusterfs.so.0(dict_get+0xac) [0x7f8fcae600cc] ) 0-dict: !this || key=glusterfs.bad-inode [Invalid argument]
[2016-01-20 10:38:50.844945] I [dict.c:473:dict_get] (-->/usr/lib64/glusterfs/3.7.5/xlator/cluster/replicate.so(afr_replies_interpret+0x1ad) [0x7f8fbccb5edd] -->/usr/lib64/glusterfs/3.7.5/xlator/cluster/replicate.so(afr_accuse_smallfiles+0x66) [0x7f8fbccb5ca6] -->/lib64/libglusterfs.so.0(dict_get+0xac) [0x7f8fcae600cc] ) 0-dict: !this || key=glusterfs.bad-inode [Invalid argument]
[2016-01-20 10:38:50.851509] I [dict.c:473:dict_get] (-->/usr/lib64/glusterfs/3.7.5/xlator/cluster/replicate.so(afr_replies_interpret+0x1ad) [0x7f8fbccb5edd] -->/usr/lib64/glusterfs/3.7.5/xlator/cluster/replicate.so(afr_accuse_smallfiles+0x66) [0x7f8fbccb5ca6] -->/lib64/libglusterfs.so.0(dict_get+0xac) [0x7f8fcae600cc] ) 0-dict: !this || key=glusterfs.bad-inode [Invalid argument]
[2016-01-20 10:38:50.851623] I [dict.c:473:dict_get] (-->/usr/lib64/glusterfs/3.7.5/xlator/cluster/replicate.so(afr_replies_interpret+0x1ad) [0x7f8fbccb5edd] -->/usr/lib64/glusterfs/3.7.5/xlator/cluster/replicate.so(afr_accuse_smallfiles+0x66) [0x7f8fbccb5ca6] -->/lib64/libglusterfs.so.0(dict_get+0xac) [0x7f8fcae600cc] ) 0-dict: !this || key=glusterfs.bad-inode [Invalid argument]

Comment 4 Ravishankar N 2016-01-20 11:45:27 UTC

The logs can appear when we do an mkdir/rmdir, even with all bricks are up. I have sent a downstream patch https://code.engineering.redhat.com/gerrit/66001 which contains http://review.gluster.org/#/c/13077/ and http://review.gluster.org/#/c/13185/

Comment 9 spandura 2016-02-01 13:06:15 UTC

Verified the fix on the build "glusterfs-3.7.5-18.el7rhgs.x86_64". Bug is fixed. Moving the bug to verified state.

Comment 11 errata-xmlrpc 2016-03-01 06:07:15 UTC

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.

https://rhn.redhat.com/errata/RHBA-2016-0193.html