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

Description of problem:

On FUSE client with mount option use-readdirp=on (default) and acl, access to a file is denied for about a second after listing the directory in which the file resides.


Version-Release number of selected component (if applicable):

glusterfs-fuse.x86_64 5.2-1.el7 from centos-gluster5 repository


How reproducible:

Always, with mount option use-readdirp=on and acl


Steps to Reproduce:

1. Mount GlusterFS volume with acl and use-readdirp=on

2. Chdir to the mounted directory

3. Execute the following commands:
echo TEST > foo; echo -n "[`date -u --rfc-3339=ns`] "; cat foo; ls -l; while :; do echo -n "[`date -u --rfc-3339=ns`] "; cat foo && break; usleep 200000; done


Actual results:

Access is denied for about a second after executing ls:

[2019-01-22 10:24:18.802855191+00:00] TEST
total 1
-rw-rw-r-- 1 centos centos 5 Jan 22 16:30 bar
-rw-rw-r-- 1 centos centos 5 Jan 22 19:24 foo
[2019-01-22 10:24:18.825725474+00:00] cat: foo: Permission denied
[2019-01-22 10:24:19.029015958+00:00] cat: foo: Permission denied
[2019-01-22 10:24:19.232249483+00:00] cat: foo: Permission denied
[2019-01-22 10:24:19.435580108+00:00] cat: foo: Permission denied
[2019-01-22 10:24:19.638781941+00:00] cat: foo: Permission denied
[2019-01-22 10:24:19.843016193+00:00] TEST

Gluster log on the client:

[2019-01-22 10:24:18.826671] I [MSGID: 139001] [posix-acl.c:263:posix_acl_log_permit_denied] 0-posix-acl-autoload: client: -, gfid: e16e1d3e-7518-4323-982f-1ad348f9608f, req(uid:1000,gid:1000,perm:4,ngrps:4), ctx(uid:0,gid:0,in-groups:0,perm:000,updated-fop:READDIRP, acl:-) [Permission denied]
[2019-01-22 10:24:18.826711] W [fuse-bridge.c:1124:fuse_fd_cbk] 0-glusterfs-fuse: 930: OPEN() /centos/test/foo => -1 (Permission denied)
[2019-01-22 10:24:19.030036] W [fuse-bridge.c:1124:fuse_fd_cbk] 0-glusterfs-fuse: 931: OPEN() /centos/test/foo => -1 (Permission denied)
[2019-01-22 10:24:19.233301] W [fuse-bridge.c:1124:fuse_fd_cbk] 0-glusterfs-fuse: 932: OPEN() /centos/test/foo => -1 (Permission denied)
[2019-01-22 10:24:19.436612] W [fuse-bridge.c:1124:fuse_fd_cbk] 0-glusterfs-fuse: 933: OPEN() /centos/test/foo => -1 (Permission denied)
[2019-01-22 10:24:19.639804] W [fuse-bridge.c:1124:fuse_fd_cbk] 0-glusterfs-fuse: 934: OPEN() /centos/test/foo => -1 (Permission denied)
The message "I [MSGID: 139001] [posix-acl.c:263:posix_acl_log_permit_denied] 0-posix-acl-autoload: client: -, gfid: e16e1d3e-7518-4323-982f-1ad348f9608f, req(uid:1000,gid:1000,perm:4,ngrps:4), ctx(uid:0,gid:0,in-groups:0,perm:000,updated-fop:READDIRP, acl:-) [Permission denied]" repeated 4 times between [2019-01-22 10:24:18.826671] and [2019-01-22 10:24:19.639797]


Expected results:

Access to the file is always granted.


Additional info:

In readdir-ahead.c, rda_fill_fd_cbk() replaces dentries and zeroes out iatts exept for ia_gfid and ia_type.
Then in posix-acl.c, posix_acl_readdirp_cbk() updates its inode ctx by that zeroed permission, and permission is denied.

--- Additional comment from asender.au on 2019-02-13 04:43:45 UTC ---

We need a procedure to downgrade from 5 to 4 without causing any further disruptions. 

I think this bug report should be a blocker.

--- Additional comment from Raghavendra G on 2019-02-13 05:09:10 UTC ---

(In reply to homma from comment #0)
> Additional info:
> 
> In readdir-ahead.c, rda_fill_fd_cbk() replaces dentries and zeroes out iatts
> exept for ia_gfid and ia_type.
> Then in posix-acl.c, posix_acl_readdirp_cbk() updates its inode ctx by that
> zeroed permission, and permission is denied.

The expectation is kernel would do a fresh lookup for getting other attributes like permissions and that's what Glusterfs indicates kernel too - that only entry information (mapping of path to inode/gfid)  is valid and the attributes are not valid. How did you conclude zeroed out permissions are set on posix-acl? Did you see a call like setattr or any setxattr updating posix acls? If yes, whether these zeroed out attributes were sent from kernel?

--- Additional comment from asender.au on 2019-02-13 05:20:50 UTC ---

gluster volume info
 
Volume Name: common
Type: Replicate
Volume ID: 359a079c-0c67-4a07-aa92-65d746ae6440
Status: Started
Snapshot Count: 0
Number of Bricks: 1 x 2 = 2
Transport-type: tcp
Bricks:
Brick1: hplintnfs30063:/export/common/common
Brick2: hplintnfs30065:/export/common/common
Options Reconfigured:
transport.address-family: inet
performance.readdir-ahead: on
nfs.disable: on
 
Volume Name: external
Type: Replicate
Volume ID: b76d3a71-6c0c-4df3-9411-baa30a586489
Status: Started
Snapshot Count: 0
Number of Bricks: 1 x 2 = 2
Transport-type: tcp
Bricks:
Brick1: hplintnfs30065:/export/external/external
Brick2: hplintnfs30064:/export/external/external
Options Reconfigured:
transport.address-family: inet
performance.readdir-ahead: on
nfs.disable: on
nfs.log-level: debug
 
Volume Name: input
Type: Replicate
Volume ID: 399caee1-4acc-48bc-9416-5510dc056280
Status: Started
Snapshot Count: 0
Number of Bricks: 1 x 2 = 2
Transport-type: tcp
Bricks:
Brick1: hplintnfs30063:/export/input/input
Brick2: hplintnfs30065:/export/input/input
Options Reconfigured:
transport.address-family: inet
performance.readdir-ahead: enable
nfs.disable: on
performance.cache-size: 1GB
performance.client-io-threads: on
performance.io-cache: on
performance.io-thread-count: 16
performance.read-ahead: disable
server.allow-insecure: on
cluster.lookup-optimize: on
client.event-threads: 4
server.event-threads: 4
cluster.readdir-optimize: on
performance.write-behind-window-size: 1MB
 
Volume Name: logs
Type: Replicate
Volume ID: a5afa578-441b-4392-887a-2e3d71a27408
Status: Started
Snapshot Count: 0
Number of Bricks: 1 x 2 = 2
Transport-type: tcp
Bricks:
Brick1: hplintnfs30063:/export/logs/logs
Brick2: hplintnfs30065:/export/logs/logs
Options Reconfigured:
transport.address-family: inet
performance.readdir-ahead: on
nfs.disable: on
 
Volume Name: output
Type: Replicate
Volume ID: bf333aa2-7260-4a8c-aa8b-cb9aeac16d36
Status: Started
Snapshot Count: 0
Number of Bricks: 1 x 2 = 2
Transport-type: tcp
Bricks:
Brick1: hplintnfs30063:/export/output/output
Brick2: hplintnfs30065:/export/output/output
Options Reconfigured:
transport.address-family: inet
performance.readdir-ahead: on
nfs.disable: on
 
Volume Name: report
Type: Replicate
Volume ID: caf38a37-9228-4d2a-b636-6a168ce89183
Status: Started
Snapshot Count: 0
Number of Bricks: 1 x 2 = 2
Transport-type: tcp
Bricks:
Brick1: hplintnfs30065:/export/report/report
Brick2: hplintnfs30064:/export/report/report
Options Reconfigured:
transport.address-family: inet
performance.readdir-ahead: on
nfs.disable: on
 
Volume Name: statement
Type: Replicate
Volume ID: 238e520d-d493-4b0e-89e2-15707847e1e7
Status: Started
Snapshot Count: 0
Number of Bricks: 1 x 2 = 2
Transport-type: tcp
Bricks:
Brick1: hplintnfs30065:/export/statement/statement
Brick2: hplintnfs30063:/export/statement/statement
Options Reconfigured:
transport.address-family: inet
performance.readdir-ahead: on
nfs.disable: on

--- Additional comment from asender.au on 2019-02-13 05:33:15 UTC ---

Applications returning permission denied.

2019-02-07 15:00:35 DEBUG - stderr: gpg: can't open `/data/common/direct-entry-files/first-data-returns/sftp/512733_ADEF020701.gpg': Permission denied

--- Additional comment from asender.au on 2019-02-13 05:38:26 UTC ---

Could someone kindly provide a "rollback" procedure with minimal impact. Can we set Gluster back to version 4 compatibility mode and downgrade.? Prefer non-impacting, but whatever is the safest. 

We need to go back to version 4.

--- Additional comment from  on 2019-02-13 08:25:41 UTC ---

(In reply to Raghavendra G from comment #2)
> (In reply to homma from comment #0)
> > Additional info:
> > 
> > In readdir-ahead.c, rda_fill_fd_cbk() replaces dentries and zeroes out iatts
> > exept for ia_gfid and ia_type.
> > Then in posix-acl.c, posix_acl_readdirp_cbk() updates its inode ctx by that
> > zeroed permission, and permission is denied.
> 
> The expectation is kernel would do a fresh lookup for getting other
> attributes like permissions and that's what Glusterfs indicates kernel too -
> that only entry information (mapping of path to inode/gfid)  is valid and
> the attributes are not valid. How did you conclude zeroed out permissions
> are set on posix-acl? Did you see a call like setattr or any setxattr
> updating posix acls? If yes, whether these zeroed out attributes were sent
> from kernel?

In the client log, 'ctx(uid:0,gid:0,in-groups:0,perm:000,updated-fop:READDIRP, acl:-)' indicates that owner, group, and permissions are all zero in posix-acl ctx.

With gdb, the following output is obtained when executing the above commands (see 'Steps to Reproduce').
The ctx is zeroed out (uid = 0, gid = 0, perm = 32768) when updated by READDIRP, while it has correct values (uid = 1000, gid = 1000, perm = 33204) when updated by LOOKUP.


(gdb) break posix-acl.c:1196
Breakpoint 1 at 0x7fbdc0fecb28: file posix-acl.c, line 1196.
(gdb) commands
Type commands for breakpoint(s) 1, one per line.
End with a line saying just "end".
>print *loc
>print *(struct posix_acl_ctx *)loc.inode._ctx[13].ptr1
>continue
>end
(gdb) break posix-acl.c:1200
Breakpoint 2 at 0x7fbdc0fec953: file posix-acl.c, line 1200.
(gdb) commands
Type commands for breakpoint(s) 2, one per line.
End with a line saying just "end".
>print *loc
>print *(struct posix_acl_ctx *)loc.inode._ctx[13].ptr1
>continue
>end
(gdb) set pagination off
(gdb) continue
Continuing.
[Switching to Thread 0x7fbdbb7fe700 (LWP 7156)]

Breakpoint 1, posix_acl_open (frame=frame@entry=0x7fbdac01e8b8, this=this@entry=0x7fbdbc01dc00, loc=loc@entry=0x7fbdac000f30, flags=flags@entry=32769, fd=fd@entry=0x7fbdac009d88, xdata=xdata@entry=0x0) at posix-acl.c:1196
1196        STACK_WIND(frame, posix_acl_open_cbk, FIRST_CHILD(this),
$1 = {path = 0x7fbdac007f20 "/centos/test/foo", name = 0x0, inode = 0x7fbdac001e98, parent = 0x0, gfid = "\341n\035>u\030C#\230/\032\323H\371`\217", pargfid = '\000' <repeats 15 times>}
$2 = {uid = 1000, gid = 1000, perm = 33204, fop = GF_FOP_LOOKUP, acl_access = 0x0, acl_default = 0x0}

Breakpoint 1, posix_acl_open (frame=frame@entry=0x7fbdac014fe8, this=this@entry=0x7fbdbc01dc00, loc=loc@entry=0x7fbdac000f30, flags=flags@entry=32768, fd=fd@entry=0x7fbdac00ab28, xdata=xdata@entry=0x0) at posix-acl.c:1196
1196        STACK_WIND(frame, posix_acl_open_cbk, FIRST_CHILD(this),
$3 = {path = 0x7fbdac009090 "/centos/test/foo", name = 0x0, inode = 0x7fbdac001e98, parent = 0x0, gfid = "\341n\035>u\030C#\230/\032\323H\371`\217", pargfid = '\000' <repeats 15 times>}
$4 = {uid = 1000, gid = 1000, perm = 33204, fop = GF_FOP_LOOKUP, acl_access = 0x0, acl_default = 0x0}

Breakpoint 2, posix_acl_open (frame=frame@entry=0x7fbdac013978, this=this@entry=0x7fbdbc01dc00, loc=loc@entry=0x7fbdac000f30, flags=flags@entry=32768, fd=fd@entry=0x7fbdac014638, xdata=xdata@entry=0x0) at posix-acl.c:1200
1200        STACK_UNWIND_STRICT(open, frame, -1, EACCES, NULL, NULL);
$5 = {path = 0x7fbdac009090 "/centos/test/foo", name = 0x0, inode = 0x7fbdac001e98, parent = 0x0, gfid = "\341n\035>u\030C#\230/\032\323H\371`\217", pargfid = '\000' <repeats 15 times>}
$6 = {uid = 0, gid = 0, perm = 32768, fop = GF_FOP_READDIRP, acl_access = 0x0, acl_default = 0x0}

Breakpoint 2, posix_acl_open (frame=frame@entry=0x7fbdac0126a8, this=this@entry=0x7fbdbc01dc00, loc=loc@entry=0x7fbdac000f30, flags=flags@entry=32768, fd=fd@entry=0x7fbdac017b48, xdata=xdata@entry=0x0) at posix-acl.c:1200
1200        STACK_UNWIND_STRICT(open, frame, -1, EACCES, NULL, NULL);
$7 = {path = 0x7fbdac007f20 "/centos/test/foo", name = 0x0, inode = 0x7fbdac001e98, parent = 0x0, gfid = "\341n\035>u\030C#\230/\032\323H\371`\217", pargfid = '\000' <repeats 15 times>}
$8 = {uid = 0, gid = 0, perm = 32768, fop = GF_FOP_READDIRP, acl_access = 0x0, acl_default = 0x0}

Breakpoint 2, posix_acl_open (frame=frame@entry=0x7fbdac017b48, this=this@entry=0x7fbdbc01dc00, loc=loc@entry=0x7fbdac000f30, flags=flags@entry=32768, fd=fd@entry=0x7fbdac014fe8, xdata=xdata@entry=0x0) at posix-acl.c:1200
1200        STACK_UNWIND_STRICT(open, frame, -1, EACCES, NULL, NULL);
$9 = {path = 0x7fbdac009090 "/centos/test/foo", name = 0x0, inode = 0x7fbdac001e98, parent = 0x0, gfid = "\341n\035>u\030C#\230/\032\323H\371`\217", pargfid = '\000' <repeats 15 times>}
$10 = {uid = 0, gid = 0, perm = 32768, fop = GF_FOP_READDIRP, acl_access = 0x0, acl_default = 0x0}

Breakpoint 2, posix_acl_open (frame=frame@entry=0x7fbdac014fe8, this=this@entry=0x7fbdbc01dc00, loc=loc@entry=0x7fbdac000f30, flags=flags@entry=32768, fd=fd@entry=0x7fbdac0126a8, xdata=xdata@entry=0x0) at posix-acl.c:1200
1200        STACK_UNWIND_STRICT(open, frame, -1, EACCES, NULL, NULL);
$11 = {path = 0x7fbdac007f20 "/centos/test/foo", name = 0x0, inode = 0x7fbdac001e98, parent = 0x0, gfid = "\341n\035>u\030C#\230/\032\323H\371`\217", pargfid = '\000' <repeats 15 times>}
$12 = {uid = 0, gid = 0, perm = 32768, fop = GF_FOP_READDIRP, acl_access = 0x0, acl_default = 0x0}

Breakpoint 2, posix_acl_open (frame=frame@entry=0x7fbdac0126a8, this=this@entry=0x7fbdbc01dc00, loc=loc@entry=0x7fbdac000f30, flags=flags@entry=32768, fd=fd@entry=0x7fbdac017b48, xdata=xdata@entry=0x0) at posix-acl.c:1200
1200        STACK_UNWIND_STRICT(open, frame, -1, EACCES, NULL, NULL);
$13 = {path = 0x7fbdac009090 "/centos/test/foo", name = 0x0, inode = 0x7fbdac001e98, parent = 0x0, gfid = "\341n\035>u\030C#\230/\032\323H\371`\217", pargfid = '\000' <repeats 15 times>}
$14 = {uid = 0, gid = 0, perm = 32768, fop = GF_FOP_READDIRP, acl_access = 0x0, acl_default = 0x0}

Breakpoint 1, posix_acl_open (frame=frame@entry=0x7fbdac018b38, this=this@entry=0x7fbdbc01dc00, loc=loc@entry=0x7fbdac000f30, flags=flags@entry=32768, fd=fd@entry=0x7fbdac0179d8, xdata=xdata@entry=0x0) at posix-acl.c:1196
1196        STACK_WIND(frame, posix_acl_open_cbk, FIRST_CHILD(this),
$15 = {path = 0x7fbdac007f20 "/centos/test/foo", name = 0x0, inode = 0x7fbdac001e98, parent = 0x0, gfid = "\341n\035>u\030C#\230/\032\323H\371`\217", pargfid = '\000' <repeats 15 times>}
$16 = {uid = 1000, gid = 1000, perm = 33204, fop = GF_FOP_LOOKUP, acl_access = 0x0, acl_default = 0x0}

--- Additional comment from asender.au on 2019-02-13 22:23:50 UTC ---

I also have the errors from client:


data-common.log-20190210:[2019-02-07 04:00:34.845536] I [MSGID: 139001] [posix-acl.c:263:posix_acl_log_permit_denied] 0-posix-acl-autoload: client: -, gfid: 9cdaca25-8b70-4d5c-ab7c-23711af54f29, req(uid:582601439,gid:582600513,perm:4,ngrps:1), ctx(uid:0,gid:0,in-groups:0,perm:000,updated-fop:READDIRP, acl:(tag:1,perm:0,id:4294967295)(tag:2,perm:7,id:582601439)(tag:4,perm:5,id:4294967295)(tag:16,perm:0,id:4294967295)(tag:32,perm:0,id:4294967295) [Permission denied]
data-common.log-20190210:[2019-02-07 04:00:34.903357] I [MSGID: 139001] [posix-acl.c:263:posix_acl_log_permit_denied] 0-posix-acl-autoload: client: -, gfid: 3ddd4e64-38a2-456d-82c7-8361fd2f12a0, req(uid:582601439,gid:582600513,perm:4,ngrps:1), ctx(uid:0,gid:0,in-groups:0,perm:000,updated-fop:READDIRP, acl:(tag:1,perm:0,id:4294967295)(tag:2,perm:7,id:582601439)(tag:4,perm:5,id:4294967295)(tag:16,perm:0,id:4294967295)(tag:32,perm:0,id:4294967295) [Permission denied]
data-common.log-20190210:[2019-02-07 04:00:34.933803] I [MSGID: 139001] [posix-acl.c:263:posix_acl_log_permit_denied] 0-posix-acl-autoload: client: -, gfid: ce5220ed-2ac0-436d-9c3b-6978fba22409, req(uid:582601439,gid:582600513,perm:4,ngrps:1), ctx(uid:0,gid:0,in-groups:0,perm:000,updated-fop:READDIRP, acl:(tag:1,perm:0,id:4294967295)(tag:2,perm:7,id:582601439)(tag:4,perm:5,id:4294967295)(tag:16,perm:0,id:4294967295)(tag:32,perm:0,id:4294967295) [Permission denied]
data-common.log-20190210:[2019-02-07 04:00:34.968269] I [MSGID: 139001] [posix-acl.c:263:posix_acl_log_permit_denied] 0-posix-acl-autoload: client: -, gfid: 01f64a01-6657-408e-80bc-2daa2fa4c3d6, req(uid:582601439,gid:582600513,perm:4,ngrps:1), ctx(uid:0,gid:0,in-groups:0,perm:000,updated-fop:READDIRP, acl:(tag:1,perm:0,id:4294967295)(tag:2,perm:7,id:582601439)(tag:4,perm:5,id:4294967295)(tag:16,perm:0,id:4294967295)(tag:32,perm:0,id:4294967295) [Permission denied]
data-common.log-20190210:[2019-02-07 04:00:35.001639] I [MSGID: 139001] [posix-acl.c:263:posix_acl_log_permit_denied] 0-posix-acl-autoload: client: -, gfid: dd58bcb9-123c-4149-a101-87c145c8d75e, req(uid:582601439,gid:582600513,perm:4,ngrps:1), ctx(uid:0,gid:0,in-groups:0,perm:000,updated-fop:READDIRP, acl:(tag:1,perm:0,id:4294967295)(tag:2,perm:7,id:582601439)(tag:4,perm:5,id:4294967295)(tag:16,perm:0,id:4294967295)(tag:32,perm:0,id:4294967295) [Permission denied]
data-common.log-20190210:[2019-02-07 04:00:35.029941] I [MSGID: 139001] [posix-acl.c:263:posix_acl_log_permit_denied] 0-posix-acl-autoload: client: -, gfid: afba3b44-82a4-4cc8-8412-2e6640b3ee41, req(uid:582601439,gid:582600513,perm:4,ngrps:1), ctx(uid:0,gid:0,in-groups:0,perm:000,updated-fop:READDIRP, acl:(tag:1,perm:0,id:4294967295)(tag:2,perm:7,id:582601439)(tag:4,perm:5,id:4294967295)(tag:16,perm:0,id:4294967295)(tag:32,perm:0,id:4294967295) [Permission denied]
data-common.log-20190210:[2019-02-07 04:00:35.062942] I [MSGID: 139001] [posix-acl.c:263:posix_acl_log_permit_denied] 0-posix-acl-autoload: client: -, gfid: 6e2761ce-4ae6-4a57-b77a-aca9d675d4a7, req(uid:582601439,gid:582600513,perm:4,ngrps:1), ctx(uid:0,gid:0,in-groups:0,perm:000,updated-fop:READDIRP, acl:(tag:1,perm:0,id:4294967295)(tag:2,perm:7,id:582601439)(tag:4,perm:5,id:4294967295)(tag:16,perm:0,id:4294967295)(tag:32,perm:0,id:4294967295) [Permission denied]
data-common.log-20190210:[2019-02-07 04:00:35.088658] I [MSGID: 139001] [posix-acl.c:263:posix_acl_log_permit_denied] 0-posix-acl-autoload: client: -, gfid: 95150a45-e2af-43be-97c5-3d6c68f2cc45, req(uid:582601439,gid:582600513,perm:4,ngrps:1), ctx(uid:0,gid:0,in-groups:0,perm:000,updated-fop:READDIRP, acl:(tag:1,perm:0,id:4294967295)(tag:2,perm:7,id:582601439)(tag:4,perm:5,id:4294967295)(tag:16,perm:0,id:4294967295)(tag:32,perm:0,id:4294967295) [Permission denied]
data-common.log-20190210:[2019-02-07 04:00:35.115121] I [MSGID: 139001] [posix-acl.c:263:posix_acl_log_permit_denied] 0-posix-acl-autoload: client: -, gfid: beba071f-3107-4955-b132-6871c5a4b4a7, req(uid:582601439,gid:582600513,perm:4,ngrps:1), ctx(uid:0,gid:0,in-groups:0,perm:000,updated-fop:READDIRP, acl:(tag:1,perm:0,id:4294967295)(tag:2,perm:7,id:582601439)(tag:4,perm:5,id:4294967295)(tag:16,perm:0,id:4294967295)(tag:32,perm:0,id:4294967295) [Permission denied]
data-common.log-20190210:[2019-02-07 04:00:35.142953] I [MSGID: 139001] [posix-acl.c:263:posix_acl_log_permit_denied] 0-posix-acl-autoload: client: -, gfid: 08ce9205-f7c9-40da-bae7-0a6f313a2a4b, req(uid:582601439,gid:582600513,perm:4,ngrps:1), ctx(uid:0,gid:0,in-groups:0,perm:000,updated-fop:READDIRP, acl:(tag:1,perm:0,id:4294967295)(tag:2,perm:7,id:582601439)(tag:4,perm:5,id:4294967295)(tag:16,perm:0,id:4294967295)(tag:32,perm:0,id:4294967295) [Permission denied]
data-common.log-20190210:[2019-02-07 04:00:35.169342] I [MSGID: 139001] [posix-acl.c:263:posix_acl_log_permit_denied] 0-posix-acl-autoload: client: -, gfid: 219ae3ee-6783-4194-9952-32b859b6e9e6, req(uid:582601439,gid:582600513,perm:4,ngrps:1), ctx(uid:0,gid:0,in-groups:0,perm:000,updated-fop:READDIRP, acl:(tag:1,perm:0,id:4294967295)(tag:2,perm:7,id:582601439)(tag:4,perm:5,id:4294967295)(tag:16,perm:0,id:4294967295)(tag:32,perm:0,id:4294967295) [Permission denied]
data-common.log-20190210:[2019-02-07 04:00:35.195090] I [MSGID: 139001] [posix-acl.c:263:posix_acl_log_permit_denied] 0-posix-acl-autoload: client: -, gfid: eec300d6-5e58-4dc4-9779-cb5872bcfde3, req(uid:582601439,gid:582600513,perm:4,ngrps:1), ctx(uid:0,gid:0,in-groups:0,perm:000,updated-fop:READDIRP, acl:(tag:1,perm:0,id:4294967295)(tag:2,perm:7,id:582601439)(tag:4,perm:5,id:4294967295)(tag:16,perm:0,id:4294967295)(tag:32,perm:0,id:4294967295) [Permission denied]
data-common.log-20190210:[2019-02-07 04:00:35.222026] I [MSGID: 139001] [posix-acl.c:263:posix_acl_log_permit_denied] 0-posix-acl-autoload: client: -, gfid: e7ebe43c-611b-48c0-91da-bc8cff0e257d, req(uid:582601439,gid:582600513,perm:4,ngrps:1), ctx(uid:0,gid:0,in-groups:0,perm:000,updated-fop:READDIRP, acl:(tag:1,perm:0,id:4294967295)(tag:2,perm:7,id:582601439)(tag:4,perm:5,id:4294967295)(tag:16,perm:0,id:4294967295)(tag:32,perm:0,id:4294967295) [Permission denied]
data-common.log-20190210:[2019-02-07 04:00:35.248727] I [MSGID: 139001] [posix-acl.c:263:posix_acl_log_permit_denied] 0-posix-acl-autoload: client: -, gfid: 75e84ea7-ee13-499e-a9ed-9924ca795220, req(uid:582601439,gid:582600513,perm:4,ngrps:1), ctx(uid:0,gid:0,in-groups:0,perm:000,updated-fop:READDIRP, acl:(tag:1,perm:0,id:4294967295)(tag:2,perm:7,id:582601439)(tag:4,perm:5,id:4294967295)(tag:16,perm:0,id:4294967295)(tag:32,perm:0,id:4294967295) [Permission denied]
data-common.log-20190210:[2019-02-07 04:00:35.273546] I [MSGID: 139001] [posix-acl.c:263:posix_acl_log_permit_denied] 0-posix-acl-autoload: client: -, gfid: bfb17595-25fd-48b1-b63c-5de711575e77, req(uid:582601439,gid:582600513,perm:4,ngrps:1), ctx(uid:0,gid:0,in-groups:0,perm:000,updated-fop:READDIRP, acl:(tag:1,perm:0,id:4294967295)(tag:2,perm:7,id:582601439)(tag:4,perm:5,id:4294967295)(tag:16,perm:0,id:4294967295)(tag:32,perm:0,id:4294967295) [Permission denied]
data-common.log-20190210:[2019-02-07 04:00:35.298552] I [MSGID: 139001] [posix-acl.c:263:posix_acl_log_permit_denied] 0-posix-acl-autoload: client: -, gfid: 41133cbc-0287-41e2-b38b-18e73d986b86, req(uid:582601439,gid:582600513,perm:4,ngrps:1), ctx(uid:0,gid:0,in-groups:0,perm:000,updated-fop:READDIRP, acl:(tag:1,perm:0,id:4294967295)(tag:2,perm:7,id:582601439)(tag:4,perm:5,id:4294967295)(tag:16,perm:0,id:4294967295)(tag:32,perm:0,id:4294967295) [Permission denied]
data-common.log-20190210:[2019-02-07 04:00:35.325860] I [MSGID: 139001] [posix-acl.c:263:posix_acl_log_permit_denied] 0-posix-acl-autoload: client: -, gfid: c926e9f8-ec94-47de-a669-7f0b1623297e, req(uid:582601439,gid:582600513,perm:4,ngrps:1), ctx(uid:0,gid:0,in-groups:0,perm:000,updated-fop:READDIRP, acl:(tag:1,perm:0,id:4294967295)(tag:2,perm:7,id:582601439)(tag:4,perm:5,id:4294967295)(tag:16,perm:0,id:4294967295)(tag:32,perm:0,id:4294967295) [Permission denied]
data-common.log-20190210:[2019-02-07 22:42:43.312845] I [MSGID: 139001] [posix-acl.c:263:posix_acl_log_permit_denied] 0-posix-acl-autoload: client: -, gfid: 7f53991d-0db7-4f1c-8deb-35cd5bcda822, req(uid:582601182,gid:582600513,perm:1,ngrps:7), ctx(uid:0,gid:0,in-groups:0,perm:770,updated-fop:LOOKUP, acl:(tag:1,perm:7,id:4294967295)(tag:2,perm:7,id:1000)(tag:2,perm:7,id:582601439)(tag:2,perm:7,id:582601746)(tag:4,perm:0,id:4294967295)(tag:16,perm:7,id:4294967295)(tag:32,perm:0,id:4294967295) [Permission denied]
data-common.log-20190210:The message "I [MSGID: 139001] [posix-acl.c:263:posix_acl_log_permit_denied] 0-posix-acl-autoload: client: -, gfid: 7f53991d-0db7-4f1c-8deb-35cd5bcda822, req(uid:582601182,gid:582600513,perm:1,ngrps:7), ctx(uid:0,gid:0,in-groups:0,perm:770,updated-fop:LOOKUP, acl:(tag:1,perm:7,id:4294967295)(tag:2,perm:7,id:1000)(tag:2,perm:7,id:582601439)(tag:2,perm:7,id:582601746)(tag:4,perm:0,id:4294967295)(tag:16,perm:7,id:4294967295)(tag:32,perm:0,id:4294967295) [Permission denied]" repeated 3 times between [2019-02-07 22:42:43.312845] and [2019-02-07 22:42:43.314192]

--- Additional comment from Nithya Balachandran on 2019-02-15 13:32:27 UTC ---

(In reply to asender.au from comment #5)
> Could someone kindly provide a "rollback" procedure with minimal impact. Can
> we set Gluster back to version 4 compatibility mode and downgrade.? Prefer
> non-impacting, but whatever is the safest. 
> 
> We need to go back to version 4.

From Kaushal on IRC:

<kshlm> sendro, To rollback do the following.
<kshlm> 1. Kill glusterds on all the nodes.
<kshlm> 2. Edit /var/lib/gluster/glusterd.info and manually change opversion to what you want. Do this on all the nodes.
<kshlm> 3. Downgrade glusterfs-server to the version you want.
<kshlm> 4. Restart glusterd.

--- Additional comment from Jiffin on 2019-02-19 04:35:16 UTC ---

As far as I understand, rda_fill_fd_cbk() sets iatt to zero and that info is stored in its context not passed to the other layers.
I tried to reproduce, but was not able to hit till now.(turned on performance.readdir-ahead).
Prior to this bug myself have seen similar issue when, the permission of acl ctx gets zeroed after readdir operations. The issue was
very much spurious and there was no specific steps to hit that issue

--- Additional comment from  on 2019-02-26 13:31:31 UTC ---

(In reply to Jiffin from comment #9)
> As far as I understand, rda_fill_fd_cbk() sets iatt to zero and that info is
> stored in its context not passed to the other layers.
> I tried to reproduce, but was not able to hit till now.(turned on
> performance.readdir-ahead).
> Prior to this bug myself have seen similar issue when, the permission of acl
> ctx gets zeroed after readdir operations. The issue was
> very much spurious and there was no specific steps to hit that issue

I think rda_fill_fd_cbk() passes entries with zeroed iatts to other xlators.

On entry of rda_fill_fd_cbk(), 'entries' holds dentries obtained by READDIRP operation.
After setting iatt to zero, it calls STACK_UNWIND_STRICT with modified 'serve_entries', not the original 'entries'.
Then posix_acl_readdirp_cbk() receives that modified entries information.

(gdb) b rda_fill_fd_cbk
Breakpoint 1 at 0x7fef2451f9d0: file readdir-ahead.c, line 424.
(gdb) b readdir-ahead.c:537
b posix_acl_readdirp_cbk
Breakpoint 2 at 0x7fef2451fcd9: file readdir-ahead.c, line 537.
(gdb) b posix_acl_readdirp_cbk
Breakpoint 3 at 0x7fef1f7990b0: file posix-acl.c, line 1654.
(gdb) c
Continuing.
[Switching to Thread 0x7fef25b37700 (LWP 12060)]

Breakpoint 1, rda_fill_fd_cbk (frame=frame@entry=0x7fef2005c628, cookie=0x7fef2006a4d8, this=0x7fef200132e0,
    op_ret=op_ret@entry=4, op_errno=op_errno@entry=2, entries=entries@entry=0x7fef25b36710, xdata=xdata@entry=0x0)
    at readdir-ahead.c:424
424     {
(gdb) p *entries.next.next.next
$1 = {{list = {next = 0x7fef200011a0, prev = 0x7fef20000f40}, {next = 0x7fef200011a0, prev = 0x7fef20000f40}},
  d_ino = 10966013112435171471, d_off = 28, d_len = 3, d_type = 8, d_stat = {ia_flags = 6143, ia_ino = 10966013112435171471,
    ia_dev = 51792, ia_rdev = 0, ia_size = 5, ia_nlink = 1, ia_uid = 1000, ia_gid = 1000, ia_blksize = 4096, ia_blocks = 1,
    ia_atime = 1551186297, ia_mtime = 1551186488, ia_ctime = 1551186488, ia_btime = 0, ia_atime_nsec = 517274116,
    ia_mtime_nsec = 150035482, ia_ctime_nsec = 153035462, ia_btime_nsec = 0, ia_attributes = 0, ia_attributes_mask = 0,
    ia_gfid = "\341n\035>u\030C#\230/\032\323H\371`\217", ia_type = IA_IFREG, ia_prot = {suid = 0 '\000', sgid = 0 '\000',
      sticky = 0 '\000', owner = {read = 1 '\001', write = 1 '\001', exec = 0 '\000'}, group = {read = 1 '\001', write = 1 '\001',
        exec = 0 '\000'}, other = {read = 1 '\001', write = 0 '\000', exec = 0 '\000'}}}, dict = 0x7fef200658f8,
  inode = 0x7fef100032c8, d_name = 0x7fef20001140 "foo"}
(gdb) c
Continuing.

Breakpoint 2, rda_fill_fd_cbk (frame=frame@entry=0x7fef2005c628, cookie=<optimized out>, this=0x7fef200132e0,
    op_ret=op_ret@entry=4, op_errno=op_errno@entry=2, entries=entries@entry=0x7fef25b36710, xdata=xdata@entry=0x0)
    at readdir-ahead.c:537
537             STACK_UNWIND_STRICT(readdirp, stub->frame, ret, op_errno,
(gdb) l
532             op_errno = 0;
533
534         UNLOCK(&ctx->lock);
535
536         if (serve) {
537             STACK_UNWIND_STRICT(readdirp, stub->frame, ret, op_errno,
538                                 &serve_entries, xdata);
539             gf_dirent_free(&serve_entries);
540             call_stub_destroy(stub);
541         }
(gdb) p &serve_entries
$2 = (gf_dirent_t *) 0x7fef25b364c0
(gdb) p *serve_entries.next.next.next
$3 = {{list = {next = 0x7fef200011a0, prev = 0x7fef20000f40}, {next = 0x7fef200011a0, prev = 0x7fef20000f40}},
  d_ino = 10966013112435171471, d_off = 28, d_len = 3, d_type = 8, d_stat = {ia_flags = 0, ia_ino = 0, ia_dev = 0, ia_rdev = 0,
    ia_size = 0, ia_nlink = 0, ia_uid = 0, ia_gid = 0, ia_blksize = 0, ia_blocks = 0, ia_atime = 0, ia_mtime = 0, ia_ctime = 0,
    ia_btime = 0, ia_atime_nsec = 0, ia_mtime_nsec = 0, ia_ctime_nsec = 0, ia_btime_nsec = 0, ia_attributes = 0,
    ia_attributes_mask = 0, ia_gfid = "\341n\035>u\030C#\230/\032\323H\371`\217", ia_type = IA_IFREG, ia_prot = {suid = 0 '\000',
      sgid = 0 '\000', sticky = 0 '\000', owner = {read = 0 '\000', write = 0 '\000', exec = 0 '\000'}, group = {read = 0 '\000',
        write = 0 '\000', exec = 0 '\000'}, other = {read = 0 '\000', write = 0 '\000', exec = 0 '\000'}}}, dict = 0x7fef200658f8,
  inode = 0x7fef100032c8, d_name = 0x7fef20001140 "foo"}
(gdb) c
Continuing.

Breakpoint 3, posix_acl_readdirp_cbk (frame=0x7fef1000b8c8, cookie=0x7fef1000c9e8, this=0x7fef2001dc00, op_ret=4, op_errno=2,
    entries=0x7fef25b364c0, xdata=0x0) at posix-acl.c:1654
1654    {
(gdb) p entries
$4 = (gf_dirent_t *) 0x7fef25b364c0
(gdb) p *entries.next.next.next
$5 = {{list = {next = 0x7fef200011a0, prev = 0x7fef20000f40}, {next = 0x7fef200011a0, prev = 0x7fef20000f40}},
  d_ino = 10966013112435171471, d_off = 28, d_len = 3, d_type = 8, d_stat = {ia_flags = 0, ia_ino = 0, ia_dev = 0, ia_rdev = 0,
    ia_size = 0, ia_nlink = 0, ia_uid = 0, ia_gid = 0, ia_blksize = 0, ia_blocks = 0, ia_atime = 0, ia_mtime = 0, ia_ctime = 0,
    ia_btime = 0, ia_atime_nsec = 0, ia_mtime_nsec = 0, ia_ctime_nsec = 0, ia_btime_nsec = 0, ia_attributes = 0,
    ia_attributes_mask = 0, ia_gfid = "\341n\035>u\030C#\230/\032\323H\371`\217", ia_type = IA_IFREG, ia_prot = {suid = 0 '\000',
      sgid = 0 '\000', sticky = 0 '\000', owner = {read = 0 '\000', write = 0 '\000', exec = 0 '\000'}, group = {read = 0 '\000',
        write = 0 '\000', exec = 0 '\000'}, other = {read = 0 '\000', write = 0 '\000', exec = 0 '\000'}}}, dict = 0x7fef200658f8,
  inode = 0x7fef100032c8, d_name = 0x7fef20001140 "foo"}

--- Additional comment from  on 2019-03-29 11:16:37 UTC ---

The problem still exists on release 5.5.

THe cause of the problem may be that posix_acl_readdirp_cbk() updates its ctx without checking that dentries contain valid iatts.
If so, please change the component to posix-acl.

--- Additional comment from  on 2019-07-01 12:05:16 UTC ---

The problem persists on release 5.6.
We cannot update fuse client to release 5 (or even 6) on our production environment because of this problem.

I have examined the source code in more detail.
rda_fill_fd_cbk() passes entries with zeroed iatts to other xlators, but for example, md-cache invalidates its cache entry when iatt with ia_ctime=0 is passed.
In md-cache.c, function mdc_inode_iatt_set_validate():

        if (!iatt || !iatt->ia_ctime) {
            gf_msg_callingfn("md-cache", GF_LOG_TRACE, 0, 0,
                             "invalidating iatt(NULL)"
                             "(%s)",
                             uuid_utoa(inode->gfid));
            mdc->ia_time = 0;
            mdc->valid = 0;

            gen = __mdc_get_generation(this, mdc);
            mdc->invalidation_time = (gen & 0xffffffff);
            goto unlock;
        }

On the other hand, posix-acl updates its ctx without checking the content of the passed iatts.
In posix-acl.c, function posix_acl_ctx_update():

        ctx = __posix_acl_ctx_get(inode, this, _gf_true);
        if (!ctx) {
            ret = -1;
            goto unlock;
        }

        ctx->uid = buf->ia_uid;
        ctx->gid = buf->ia_gid;
        ctx->perm = st_mode_from_ia(buf->ia_prot, buf->ia_type);
        ctx->fop = fop;

I think posix-acl.c should be modified not to update its ctx, when iatt with ia_ctime=0 is passed.

--- Additional comment from Amar Tumballi on 2019-07-01 12:10:31 UTC ---

Homma,

Thanks for the detailed check on this. Your analysis seems right. Does the patch fix the issues for you? Will be sending a patch for the issue soon.

--- Additional comment from  on 2019-07-05 10:31:19 UTC ---

Amar,

Thank you for your prompt reply. I will try to see if the patch solves the problem when it has been sent.

--- Additional comment from Worker Ant on 2019-07-05 10:44:31 UTC ---

REVIEW: https://review.gluster.org/23003 (system/posix-acl: update ctx only if iatt is non-NULL) posted (#1) for review on master by Amar Tumballi

--- Additional comment from  on 2019-07-08 08:23:27 UTC ---

Amar,

I have built posix-acl.so applying your modification to release 5.6 source code, and confirmed that the problem is solved.
Waiting for this fix to be officially released.

--- Additional comment from Amar Tumballi on 2019-07-08 08:28:42 UTC ---

Just note that it is 'your' fix. Ie, you identified it, I just sent it to repo. Once it gets merged, you can see yourself as contributor to glusterfs.

--- Additional comment from Worker Ant on 2019-07-16 04:44:46 UTC ---

REVIEW: https://review.gluster.org/23003 (system/posix-acl: update ctx only if iatt is non-NULL) merged (#4) on master by jiffin tony Thottan