Bug 1324338 - Too many log messages showing inode ctx is NULL for 00000000-0000-0000-0000-000000000000
Summary: Too many log messages showing inode ctx is NULL for 00000000-0000-0000-0000-0...
Keywords:
Status: CLOSED ERRATA
Alias: None
Product: Red Hat Gluster Storage
Classification: Red Hat Storage
Component: core
Version: rhgs-3.1
Hardware: Unspecified
OS: Unspecified
unspecified
unspecified
Target Milestone: ---
: RHGS 3.1.3
Assignee: Manikandan
QA Contact: krishnaram Karthick
URL:
Whiteboard:
Depends On:
Blocks: 1311817 1325822 1325826
TreeView+ depends on / blocked
 
Reported: 2016-04-06 06:32 UTC by Bhaskarakiran
Modified: 2016-11-23 23:12 UTC (History)
10 users (show)

Fixed In Version: glusterfs-3.7.9-3
Doc Type: Bug Fix
Doc Text:
Clone Of:
: 1325822 (view as bug list)
Environment:
Last Closed: 2016-06-23 05:15:43 UTC
Embargoed:


Attachments (Terms of Use)


Links
System ID Private Priority Status Summary Last Updated
Red Hat Product Errata RHBA-2016:1240 0 normal SHIPPED_LIVE Red Hat Gluster Storage 3.1 Update 3 2016-06-23 08:51:28 UTC

Description Bhaskarakiran 2016-04-06 06:32:15 UTC
Description of problem:
=======================

While trying to reproduce one of the goldman issue, hit this and the brick logs are getting filled up pretty fast and inturn /.

[2016-04-06 01:28:19.152827] E [posix-acl.c:359:posix_acl_ctx_get] (--> /usr/lib64/libglusterfs.so.0(_gf_log_callingfn+0x1e0)[0x7f352984a620] (--> /usr/lib64/glusterfs/3.7.1/xlator/features/access-control.so(posix_acl_ctx_get+0xa1)[0x7f35166a22f1] (--> /usr/lib64/glusterfs/3.7.1/xlator/features/access-control.so(__posix_acl_get+0x19)[0x7f35166a2489] (--> /usr/lib64/glusterfs/3.7.1/xlator/features/access-control.so(posix_acl_get+0x5c)[0x7f35166a251c] (--> /usr/lib64/glusterfs/3.7.1/xlator/features/access-control.so(posix_acl_lookup_cbk+0x1cd)[0x7f35166a637d] ))))) 0-vol1-access-control: inode ctx is NULL for 00000000-0000-0000-0000-000000000000
[2016-04-06 01:28:20.535181] E [posix-acl.c:359:posix_acl_ctx_get] (--> /usr/lib64/libglusterfs.so.0(_gf_log_callingfn+0x1e0)[0x7f352984a620] (--> /usr/lib64/glusterfs/3.7.1/xlator/features/access-control.so(posix_acl_ctx_get+0xa1)[0x7f35166a22f1] (--> /usr/lib64/glusterfs/3.7.1/xlator/features/access-control.so(__posix_acl_get+0x19)[0x7f35166a2489] (--> /usr/lib64/glusterfs/3.7.1/xlator/features/access-control.so(posix_acl_get+0x5c)[0x7f35166a251c] (--> /usr/lib64/glusterfs/3.7.1/xlator/features/access-control.so(posix_acl_lookup_cbk+0x1cd)[0x7f35166a637d] ))))) 0-vol1-access-control: inode ctx is NULL for 00000000-0000-0000-0000-000000000000
[2016-04-06 01:28:21.489531] E [posix-acl.c:359:posix_acl_ctx_get] (--> /usr/lib64/libglusterfs.so.0(_gf_log_callingfn+0x1e0)[0x7f352984a620] (--> /usr/lib64/glusterfs/3.7.1/xlator/features/access-control.so(posix_acl_ctx_get+0xa1)[0x7f35166a22f1] (--> /usr/lib64/glusterfs/3.7.1/xlator/features/access-control.so(__posix_acl_get+0x19)[0x7f35166a2489] (--> /usr/lib64/glusterfs/3.7.1/xlator/features/access-control.so(posix_acl_get+0x5c)[0x7f35166a251c] (--> /usr/lib64/glusterfs/3.7.1/xlator/features/access-control.so(posix_acl_lookup_cbk+0x1cd)[0x7f35166a637d] ))))) 0-vol1-access-control: inode ctx is NULL for 00000000-0000-0000-0000-000000000000

[root@dhcp42-134 bricks]# grep "posix-acl.c:359:posix_acl_ctx_get" rhs-brick* | wc -l
11776152

[root@dhcp42-134 bricks]# gluster v info vol1
 
Volume Name: vol1
Type: Distributed-Replicate
Volume ID: d98c7790-e80f-4479-b79d-d20c430381f3
Status: Started
Number of Bricks: 18 x 2 = 36
Transport-type: tcp
Bricks:
Brick1: dhcp42-134:/rhs/brick1/b1
Brick2: dhcp42-124:/rhs/brick1/b2
Brick3: dhcp42-131:/rhs/brick1/b3
Brick4: dhcp42-141:/rhs/brick1/b4
Brick5: dhcp42-134:/rhs/brick2/b5
Brick6: dhcp42-124:/rhs/brick2/b6
Brick7: dhcp42-131:/rhs/brick2/b7
Brick8: dhcp42-141:/rhs/brick2/b8
Brick9: dhcp42-134:/rhs/brick3/b9
Brick10: dhcp42-124:/rhs/brick3/b10
Brick11: dhcp42-131:/rhs/brick3/b11
Brick12: dhcp42-141:/rhs/brick3/b12
Brick13: dhcp42-134:/rhs/brick1/b13
Brick14: dhcp42-124:/rhs/brick1/b14
Brick15: dhcp42-131:/rhs/brick1/b15
Brick16: dhcp42-141:/rhs/brick1/b16
Brick17: dhcp42-134:/rhs/brick2/b17
Brick18: dhcp42-124:/rhs/brick2/b18
Brick19: dhcp42-131:/rhs/brick2/b19
Brick20: dhcp42-141:/rhs/brick2/b20
Brick21: dhcp42-134:/rhs/brick3/b21
Brick22: dhcp42-124:/rhs/brick3/b22
Brick23: dhcp42-131:/rhs/brick3/b23
Brick24: dhcp42-141:/rhs/brick3/b24
Brick25: dhcp42-134:/rhs/brick1/b25
Brick26: dhcp42-124:/rhs/brick1/b26
Brick27: dhcp42-131:/rhs/brick1/b27
Brick28: dhcp42-141:/rhs/brick1/b28
Brick29: dhcp42-134:/rhs/brick2/b29
Brick30: dhcp42-124:/rhs/brick2/b30
Brick31: dhcp42-131:/rhs/brick2/b31
Brick32: dhcp42-141:/rhs/brick2/b32
Brick33: dhcp42-134:/rhs/brick3/b33
Brick34: dhcp42-124:/rhs/brick3/b34
Brick35: dhcp42-131:/rhs/brick3/b35
Brick36: dhcp42-141:/rhs/brick3/b36
Options Reconfigured:
features.quota-deem-statfs: on
performance.stat-prefetch: off
features.inode-quota: on
features.quota: on
performance.readdir-ahead: on
[root@dhcp42-134 bricks]# 

Steps that are done:
====================

1. created 6x2 volume  and nfs mount on the clients. quota is enabled.
2. Created directories multiple level deep and width
3. Added bricks (18x2) 
4. Created same set of directories under the parent directory from multiple clients
5. started rebalance and lookups from 2 of the clients.


Version-Release number of selected component (if applicable):
=============================================================
[root@dhcp42-134 bricks]# gluster --version
glusterfs 3.7.1 built on Apr  2 2016 11:55:18
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@dhcp42-134 bricks]# 

[root@dhcp42-134 bricks]# rpm -qa |grep gluster
glusterfs-3.7.1-17.el6rhs.11.hotfix.sfdc01581565.x86_64
glusterfs-debuginfo-3.7.1-17.el6rhs.11.hotfix.sfdc01581565.x86_64
glusterfs-server-3.7.1-17.el6rhs.11.hotfix.sfdc01581565.x86_64
glusterfs-geo-replication-3.7.1-17.el6rhs.11.hotfix.sfdc01581565.x86_64
glusterfs-api-devel-3.7.1-17.el6rhs.11.hotfix.sfdc01581565.x86_64
glusterfs-libs-3.7.1-17.el6rhs.11.hotfix.sfdc01581565.x86_64
glusterfs-rdma-3.7.1-17.el6rhs.11.hotfix.sfdc01581565.x86_64
glusterfs-resource-agents-3.7.1-17.el6rhs.11.hotfix.sfdc01581565.noarch
glusterfs-client-xlators-3.7.1-17.el6rhs.11.hotfix.sfdc01581565.x86_64
glusterfs-cli-3.7.1-17.el6rhs.11.hotfix.sfdc01581565.x86_64
glusterfs-fuse-3.7.1-17.el6rhs.11.hotfix.sfdc01581565.x86_64
glusterfs-devel-3.7.1-17.el6rhs.11.hotfix.sfdc01581565.x86_64
glusterfs-api-3.7.1-17.el6rhs.11.hotfix.sfdc01581565.x86_64
[root@dhcp42-134 bricks]# 




How reproducible:
================
100%

Steps to Reproduce:
===================
As in description

Actual results:


Expected results:


Additional info:

Comment 2 Bhaskarakiran 2016-04-06 06:33:08 UTC
Bug that was tried to reproduce : https://bugzilla.redhat.com/show_bug.cgi?id=1323042

Comment 3 Vijaikumar Mallikarjuna 2016-04-11 10:21:37 UTC
Patch submitted upstream:
mainline: http://review.gluster.org/#/c/13961/
release-3.7: http://review.gluster.org/#/c/13962/

Comment 5 Vijaikumar Mallikarjuna 2016-04-11 16:31:15 UTC
Patch submitted: https://code.engineering.redhat.com/gerrit/71896

Comment 9 Rahul Hinduja 2016-04-25 12:28:35 UTC
I could hit this issue on glusterfs-3.7.9-2 on geo-replication brick logs. Patch mentioned at comment 5 is cherry picked 

"Change has been successfully cherry-picked as 14abb0c32e9ab9bd43c1476dcc3e2125f80ad08d by Raghavendra Gowdappa
Apr 20 9:49 AM"

Whereas the gluster version mentions:

[root@dhcp47-24 master]# gluster --version
glusterfs 3.7.9 built on Apr 19 2016 07:02:38
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@dhcp47-24 master]# 

Moving this bug back to MODIFIED

Log Snippet:
============

sh%3A%2F%2Froot%4010.70.47.5%3Agluster%3A%2F%2F127.0.0.1%3Aslave.%2Fbricks%2Fbrick1%2Fmaster_brick2.gluster.log-20160424:[2016-04-22 10:34:50.660524] E [posix-acl.c:357:posix_acl_ctx_get] (--> /usr/lib64/libglusterfs.so.0(_gf_log_callingfn+0x1f2)[0x7f55e0f07902] (--> /usr/lib64/glusterfs/3.7.9/xlator/system/posix-acl.so(posix_acl_ctx_get+0xa9)[0x7f55d1e632f9] (--> /usr/lib64/glusterfs/3.7.9/xlator/system/posix-acl.so(__posix_acl_get+0x19)[0x7f55d1e63459] (--> /usr/lib64/glusterfs/3.7.9/xlator/system/posix-acl.so(posix_acl_get+0x5c)[0x7f55d1e634ec] (--> /usr/lib64/glusterfs/3.7.9/xlator/system/posix-acl.so(posix_acl_lookup_cbk+0x1cd)[0x7f55d1e672dd] ))))) 0-posix-acl-autoload: inode ctx is NULL for 00000000-0000-0000-0000-000000000000
ssh%3A%2F%2Froot%4010.70.47.5%3Agluster%3A%2F%2F127.0.0.1%3Aslave.%2Fbricks%2Fbrick1%2Fmaster_brick2.gluster.log-20160424:[2016-04-22 10:34:50.663416] E [posix-acl.c:357:posix_acl_ctx_get] (--> /usr/lib64/libglusterfs.so.0(_gf_log_callingfn+0x1f2)[0x7f55e0f07902] (--> /usr/lib64/glusterfs/3.7.9/xlator/system/posix-acl.so(posix_acl_ctx_get+0xa9)[0x7f55d1e632f9] (--> /usr/lib64/glusterfs/3.7.9/xlator/system/posix-acl.so(__posix_acl_get+0x19)[0x7f55d1e63459] (--> /usr/lib64/glusterfs/3.7.9/xlator/system/posix-acl.so(posix_acl_get+0x5c)[0x7f55d1e634ec] (--> /usr/lib64/glusterfs/3.7.9/xlator/system/posix-acl.so(posix_acl_lookup_cbk+0x1cd)[0x7f55d1e672dd] ))))) 0-posix-acl-autoload: inode ctx is NULL for 00000000-0000-0000-0000-000000000000
ssh%3A%2F%2Froot%4010.70.47.5%3Agluster%3A%2F%2F127.0.0.1%3Aslave.%2Fbricks%2Fbrick1%2Fmaster_brick2.gluster.log-20160424:[2016-04-22 10:34:50.667093] E [posix-acl.c:357:posix_acl_ctx_get] (--> /usr/lib64/libglusterfs.so.0(_gf_log_callingfn+0x1f2)[0x7f55e0f07902] (--> /usr/lib64/glusterfs/3.7.9/xlator/system/posix-acl.so(posix_acl_ctx_get+0xa9)[0x7f55d1e632f9] (--> /usr/lib64/glusterfs/3.7.9/xlator/system/posix-acl.so(__posix_acl_get+0x19)[0x7f55d1e63459] (--> /usr/lib64/glusterfs/3.7.9/xlator/system/posix-acl.so(posix_acl_get+0x5c)[0x7f55d1e634ec] (--> /usr/lib64/glusterfs/3.7.9/xlator/system/posix-acl.so(posix_acl_lookup_cbk+0x1cd)[0x7f55d1e672dd] ))))) 0-posix-acl-autoload: inode ctx is NULL for 00000000-0000-0000-0000-000000000000
ssh%3A%2F%2Froot%4010.70.47.5%3Agluster%3A%2F%2F127.0.0.1%3Aslave.%2Fbricks%2Fbrick1%2Fmaster_brick2.gluster.log-20160424:[2016-04-22 10:34:50.672591] E [posix-acl.c:357:posix_acl_ctx_get] (--> /usr/lib64/libglusterfs.so.0(_gf_log_callingfn+0x1f2)[0x7f55e0f07902] (--> /usr/lib64/glusterfs/3.7.9/xlator/system/posix-acl.so(posix_acl_ctx_get+0xa9)[0x7f55d1e632f9] (--> /usr/lib64/glusterfs/3.7.9/xlator/system/posix-acl.so(__posix_acl_get+0x19)[0x7f55d1e63459] (--> /usr/lib64/glusterfs/3.7.9/xlator/system/posix-acl.so(posix_acl_get+0x5c)[0x7f55d1e634ec] (--> /usr/lib64/glusterfs/3.7.9/xlator/system/posix-acl.so(posix_acl_lookup_cbk+0x1cd)[0x7f55d1e672dd] ))))) 0-posix-acl-autoload: inode ctx is NULL for 00000000-0000-0000-0000-000000000000

Comment 10 krishnaram Karthick 2016-04-29 04:40:32 UTC
These logs are flooded with tiered volume as well (build - glusterfs-server-3.7.9-2.el7rhgs.x86_64)

[2016-04-29 09:55:12.856299] E [posix-acl.c:357:posix_acl_ctx_get] (--> /lib64/libglusterfs.so.0(_gf_log_callingfn+0x192)[0x7f7b13df3b42] (--> /usr/lib64/glusterfs/3.7.9/xlator/features/access-control.so(posix_acl_ctx_get+0x88)[0x7f7b04c143c8] (--> /usr/lib64/glusterfs/3.7.9/xlator/features/access-control.so(__posix_acl_get+0x11)[0x7f7b04c14541] (--> /usr/lib64/glusterfs/3.7.9/xlator/features/access-control.so(posix_acl_get+0x5e)[0x7f7b04c1490e] (--> /usr/lib64/glusterfs/3.7.9/xlator/features/access-control.so(posix_acl_lookup_cbk+0x1e5)[0x7f7b04c18515] ))))) 0-ganesha-tier-access-control: inode ctx is NULL for 00000000-0000-0000-0000-000000000000
[2016-04-29 09:55:13.013036] E [posix-acl.c:357:posix_acl_ctx_get] (--> /lib64/libglusterfs.so.0(_gf_log_callingfn+0x192)[0x7f7b13df3b42] (--> /usr/lib64/glusterfs/3.7.9/xlator/features/access-control.so(posix_acl_ctx_get+0x88)[0x7f7b04c143c8] (--> /usr/lib64/glusterfs/3.7.9/xlator/features/access-control.so(__posix_acl_get+0x11)[0x7f7b04c14541] (--> /usr/lib64/glusterfs/3.7.9/xlator/features/access-control.so(posix_acl_get+0x5e)[0x7f7b04c1490e] (--> /usr/lib64/glusterfs/3.7.9/xlator/features/access-control.so(posix_acl_lookup_cbk+0x1e5)[0x7f7b04c18515] ))))) 0-ganesha-tier-access-control: inode ctx is NULL for 00000000-0000-0000-0000-000000000000

Comment 12 krishnaram Karthick 2016-05-17 07:36:25 UTC
The log messages reported in the bug are no more seen in build - glusterfs-3.7.9-4.el7rhgs.x86_64. The logs were consistently seen in previous builds.

Marking the bug as verified.

Comment 14 errata-xmlrpc 2016-06-23 05:15:43 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://access.redhat.com/errata/RHBA-2016:1240


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