[Bugs] [Bug 1767305] New: READDIRP incorrectly updates posix-acl inode ctx
bugzilla at redhat.com
bugzilla at redhat.com
Thu Oct 31 06:28:40 UTC 2019
https://bugzilla.redhat.com/show_bug.cgi?id=1767305
Bug ID: 1767305
Summary: READDIRP incorrectly updates posix-acl inode ctx
Product: GlusterFS
Version: 5
OS: Linux
Status: NEW
Component: posix-acl
Severity: urgent
Priority: medium
Assignee: bugs at gluster.org
Reporter: hgowtham at redhat.com
CC: asender at testlabs.com.au, atumball at redhat.com,
bugs at gluster.org, homma at allworks.co.jp,
jthottan at redhat.com, nbalacha at redhat.com,
pgurusid at redhat.com, rgowdapp at redhat.com,
spalai at redhat.com
Depends On: 1668286
Blocks: 1741402
Target Milestone: ---
Classification: Community
+++ 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 at testlabs.com.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 at testlabs.com.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 at testlabs.com.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 at testlabs.com.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 at entry=0x7fbdac01e8b8,
this=this at entry=0x7fbdbc01dc00, loc=loc at entry=0x7fbdac000f30,
flags=flags at entry=32769, fd=fd at entry=0x7fbdac009d88, xdata=xdata at 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 at entry=0x7fbdac014fe8,
this=this at entry=0x7fbdbc01dc00, loc=loc at entry=0x7fbdac000f30,
flags=flags at entry=32768, fd=fd at entry=0x7fbdac00ab28, xdata=xdata at 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 at entry=0x7fbdac013978,
this=this at entry=0x7fbdbc01dc00, loc=loc at entry=0x7fbdac000f30,
flags=flags at entry=32768, fd=fd at entry=0x7fbdac014638, xdata=xdata at 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 at entry=0x7fbdac0126a8,
this=this at entry=0x7fbdbc01dc00, loc=loc at entry=0x7fbdac000f30,
flags=flags at entry=32768, fd=fd at entry=0x7fbdac017b48, xdata=xdata at 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 at entry=0x7fbdac017b48,
this=this at entry=0x7fbdbc01dc00, loc=loc at entry=0x7fbdac000f30,
flags=flags at entry=32768, fd=fd at entry=0x7fbdac014fe8, xdata=xdata at 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 at entry=0x7fbdac014fe8,
this=this at entry=0x7fbdbc01dc00, loc=loc at entry=0x7fbdac000f30,
flags=flags at entry=32768, fd=fd at entry=0x7fbdac0126a8, xdata=xdata at 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 at entry=0x7fbdac0126a8,
this=this at entry=0x7fbdbc01dc00, loc=loc at entry=0x7fbdac000f30,
flags=flags at entry=32768, fd=fd at entry=0x7fbdac017b48, xdata=xdata at 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 at entry=0x7fbdac018b38,
this=this at entry=0x7fbdbc01dc00, loc=loc at entry=0x7fbdac000f30,
flags=flags at entry=32768, fd=fd at entry=0x7fbdac0179d8, xdata=xdata at 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 at testlabs.com.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 at testlabs.com.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 at entry=0x7fef2005c628,
cookie=0x7fef2006a4d8, this=0x7fef200132e0,
op_ret=op_ret at entry=4, op_errno=op_errno at entry=2,
entries=entries at entry=0x7fef25b36710, xdata=xdata at 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 at entry=0x7fef2005c628,
cookie=<optimized out>, this=0x7fef200132e0,
op_ret=op_ret at entry=4, op_errno=op_errno at entry=2,
entries=entries at entry=0x7fef25b36710, xdata=xdata at 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
Referenced Bugs:
https://bugzilla.redhat.com/show_bug.cgi?id=1668286
[Bug 1668286] READDIRP incorrectly updates posix-acl inode ctx
https://bugzilla.redhat.com/show_bug.cgi?id=1741402
[Bug 1741402] READDIRP incorrectly updates posix-acl inode ctx
--
You are receiving this mail because:
You are on the CC list for the bug.
You are the assignee for the bug.
More information about the Bugs
mailing list