<html><body style="word-wrap: break-word; -webkit-nbsp-mode: space; -webkit-line-break: after-white-space;" class="">Recently we updated a Gluster replicated setup from 3.6 to 3.12 (stepping through 3.8 first before going to 3.12).<br class=""><br class="">Afterwards I noticed the brick logs were filling at an alarming rate on the server we have the NFS service running from:<br class=""><br class="">$ sudo tail -20 /var/log/glusterfs/bricks/export-gluster-shared.log <br class="">[2018-05-23 06:22:12.405240] I [MSGID: 139001] [posix-acl.c:269:posix_acl_log_permit_denied] 0-sharedvol-access-control: client: mfc-nas1-14785-2018/05/23-06:10:20:243359-sharedvol-client-0-0-0, gfid: 59d4c3da-9943-469e-9694-b14ca348007b, req(uid:33,gid:33,perm:2,ngrps:1), ctx(uid:1002,gid:100,in-groups:0,perm:664,updated-fop:LOOKUP, acl:-) [Permission denied]<br class="">[2018-05-23 06:22:12.405284] I [MSGID: 139001] [posix-acl.c:269:posix_acl_log_permit_denied] 0-sharedvol-access-control: client: mfc-nas1-14785-2018/05/23-06:10:20:243359-sharedvol-client-0-0-0, gfid: 59d4c3da-9943-469e-9694-b14ca348007b, req(uid:33,gid:33,perm:1,ngrps:1), ctx(uid:1002,gid:100,in-groups:0,perm:664,updated-fop:LOOKUP, acl:-) [Permission denied]<br class="">[2018-05-23 06:22:12.410581] I [MSGID: 139001] [posix-acl.c:269:posix_acl_log_permit_denied] 0-sharedvol-access-control: client: mfc-nas1-14785-2018/05/23-06:10:20:243359-sharedvol-client-0-0-0, gfid: d978d132-0c95-4a67-9bf4-21cfc87746ba, req(uid:33,gid:33,perm:2,ngrps:1), ctx(uid:1002,gid:100,in-groups:0,perm:664,updated-fop:LOOKUP, acl:-) [Permission denied]<br class="">[2018-05-23 06:22:12.410624] I [MSGID: 139001] [posix-acl.c:269:posix_acl_log_permit_denied] 0-sharedvol-access-control: client: mfc-nas1-14785-2018/05/23-06:10:20:243359-sharedvol-client-0-0-0, gfid: d978d132-0c95-4a67-9bf4-21cfc87746ba, req(uid:33,gid:33,perm:1,ngrps:1), ctx(uid:1002,gid:100,in-groups:0,perm:664,updated-fop:LOOKUP, acl:-) [Permission denied]<br class="">[2018-05-23 06:22:12.411382] I [MSGID: 139001] [posix-acl.c:269:posix_acl_log_permit_denied] 0-sharedvol-access-control: client: mfc-nas1-14785-2018/05/23-06:10:20:243359-sharedvol-client-0-0-0, gfid: b75fcfce-b0ed-48f7-b927-6d0c805b8c49, req(uid:33,gid:33,perm:2,ngrps:1), ctx(uid:1002,gid:100,in-groups:0,perm:775,updated-fop:LOOKUP, acl:-) [Permission denied]<br class="">[2018-05-23 06:22:12.412903] I [MSGID: 139001] [posix-acl.c:269:posix_acl_log_permit_denied] 0-sharedvol-access-control: client: mfc-nas1-14785-2018/05/23-06:10:20:243359-sharedvol-client-0-0-0, gfid: f5a73dcd-6ad2-4952-a98e-86c76fc30847, req(uid:33,gid:33,perm:2,ngrps:1), ctx(uid:1002,gid:100,in-groups:0,perm:775,updated-fop:LOOKUP, acl:-) [Permission denied]<br class="">[2018-05-23 06:22:12.413941] I [MSGID: 139001] [posix-acl.c:269:posix_acl_log_permit_denied] 0-sharedvol-access-control: client: mfc-nas1-14785-2018/05/23-06:10:20:243359-sharedvol-client-0-0-0, gfid: 4c7f51fc-fd92-44fc-95a1-b49e177a3545, req(uid:33,gid:33,perm:2,ngrps:1), ctx(uid:1002,gid:100,in-groups:0,perm:775,updated-fop:LOOKUP, acl:-) [Permission denied]<br class="">[2018-05-23 06:22:12.415360] I [MSGID: 139001] [posix-acl.c:269:posix_acl_log_permit_denied] 0-sharedvol-access-control: client: mfc-nas1-14785-2018/05/23-06:10:20:243359-sharedvol-client-0-0-0, gfid: a0da63c1-a7e6-412a-b6cb-732b8e74a85d, req(uid:33,gid:33,perm:2,ngrps:1), ctx(uid:1002,gid:100,in-groups:0,perm:664,updated-fop:LOOKUP, acl:-) [Permission denied]<br class="">[2018-05-23 06:22:12.415405] I [MSGID: 139001] [posix-acl.c:269:posix_acl_log_permit_denied] 0-sharedvol-access-control: client: mfc-nas1-14785-2018/05/23-06:10:20:243359-sharedvol-client-0-0-0, gfid: a0da63c1-a7e6-412a-b6cb-732b8e74a85d, req(uid:33,gid:33,perm:1,ngrps:1), ctx(uid:1002,gid:100,in-groups:0,perm:664,updated-fop:LOOKUP, acl:-) [Permission denied]<br class="">[2018-05-23 06:22:12.418244] I [MSGID: 139001] [posix-acl.c:269:posix_acl_log_permit_denied] 0-sharedvol-access-control: client: mfc-nas1-14785-2018/05/23-06:10:20:243359-sharedvol-client-0-0-0, gfid: dff386f8-d59b-4b94-ad5d-be9a54c65342, req(uid:33,gid:33,perm:2,ngrps:1), ctx(uid:1002,gid:100,in-groups:0,perm:775,updated-fop:LOOKUP, acl:-) [Permission denied]<br class="">[2018-05-23 06:22:12.419225] I [MSGID: 139001] [posix-acl.c:269:posix_acl_log_permit_denied] 0-sharedvol-access-control: client: mfc-nas1-14785-2018/05/23-06:10:20:243359-sharedvol-client-0-0-0, gfid: c8f8fe1f-42b7-4e3b-a9b2-f9b8917e4d57, req(uid:33,gid:33,perm:2,ngrps:1), ctx(uid:1002,gid:100,in-groups:0,perm:775,updated-fop:LOOKUP, acl:-) [Permission denied]<br class="">[2018-05-23 06:22:12.420422] I [MSGID: 139001] [posix-acl.c:269:posix_acl_log_permit_denied] 0-sharedvol-access-control: client: mfc-nas1-14785-2018/05/23-06:10:20:243359-sharedvol-client-0-0-0, gfid: a5a913d5-f6de-4437-aa23-6bf430159533, req(uid:33,gid:33,perm:2,ngrps:1), ctx(uid:1002,gid:100,in-groups:0,perm:775,updated-fop:LOOKUP, acl:-) [Permission denied]<br class="">[2018-05-23 06:22:12.421641] I [MSGID: 139001] [posix-acl.c:269:posix_acl_log_permit_denied] 0-sharedvol-access-control: client: mfc-nas1-14785-2018/05/23-06:10:20:243359-sharedvol-client-0-0-0, gfid: ce203850-6d98-46d8-8789-d5796f09da57, req(uid:33,gid:33,perm:2,ngrps:1), ctx(uid:1002,gid:100,in-groups:0,perm:775,updated-fop:LOOKUP, acl:-) [Permission denied]<br class="">[2018-05-23 06:22:12.422428] I [MSGID: 139001] [posix-acl.c:269:posix_acl_log_permit_denied] 0-sharedvol-access-control: client: mfc-nas1-14785-2018/05/23-06:10:20:243359-sharedvol-client-0-0-0, gfid: 38ed6fb4-fc75-4c7c-bf88-db8db03665b2, req(uid:33,gid:33,perm:2,ngrps:1), ctx(uid:1002,gid:100,in-groups:0,perm:775,updated-fop:LOOKUP, acl:-) [Permission denied]<br class="">[2018-05-23 06:22:12.539753] I [MSGID: 139001] [posix-acl.c:269:posix_acl_log_permit_denied] 0-sharedvol-access-control: client: mfc-nas1-14785-2018/05/23-06:10:20:243359-sharedvol-client-0-0-0, gfid: ab44763e-3739-4370-aaf7-d0d390e70c5d, req(uid:20000,gid:20000,perm:1,ngrps:1), ctx(uid:20000,gid:20000,in-groups:1,perm:674,updated-fop:LOOKUP, acl:(tag:1,perm:6,id:4294967295)(tag:2,perm:7,id:10437)(tag:4,perm:7,id:4294967295)(tag:16,perm:7,id:4294967295)(tag:32,perm:4,id:4294967295) [Permission denied]<br class="">[2018-05-23 06:22:12.947762] I [MSGID: 139001] [posix-acl.c:269:posix_acl_log_permit_denied] 0-sharedvol-access-control: client: mfc-nas1-14785-2018/05/23-06:10:20:243359-sharedvol-client-0-0-0, gfid: 839a087e-4997-4140-ac4f-aafbf1bb9e3b, req(uid:33,gid:33,perm:1,ngrps:1), ctx(uid:33,gid:0,in-groups:0,perm:644,updated-fop:SETATTR, acl:-) [Permission denied]<br class="">The message "I [MSGID: 139001] [posix-acl.c:269:posix_acl_log_permit_denied] 0-sharedvol-access-control: client: mfc-nas1-14785-2018/05/23-06:10:20:243359-sharedvol-client-0-0-0, gfid: 839a087e-4997-4140-ac4f-aafbf1bb9e3b, req(uid:33,gid:33,perm:1,ngrps:1), ctx(uid:33,gid:0,in-groups:0,perm:644,updated-fop:SETATTR, acl:-) [Permission denied]" repeated 2 times between [2018-05-23 06:22:12.947762] and [2018-05-23 06:22:13.145374]<br class="">[2018-05-23 06:22:13.200285] I [MSGID: 139001] [posix-acl.c:269:posix_acl_log_permit_denied] 0-sharedvol-access-control: client: mfc-nas1-14785-2018/05/23-06:10:20:243359-sharedvol-client-0-0-0, gfid: bf1b4131-ce67-4ae8-8c54-fab53aed117f, req(uid:33,gid:33,perm:2,ngrps:1), ctx(uid:0,gid:0,in-groups:0,perm:755,updated-fop:READDIRP, acl:-) [Permission denied]<br class="">[2018-05-23 06:22:13.200342] I [MSGID: 139001] [posix-acl.c:269:posix_acl_log_permit_denied] 0-sharedvol-access-control: client: mfc-nas1-14785-2018/05/23-06:10:20:243359-sharedvol-client-0-0-0, gfid: bf1b4131-ce67-4ae8-8c54-fab53aed117f, req(uid:33,gid:33,perm:2,ngrps:1), ctx(uid:0,gid:0,in-groups:0,perm:755,updated-fop:READDIRP, acl:-) [Permission denied]<br class="">[2018-05-23 06:22:13.201385] I [MSGID: 139001] [posix-acl.c:269:posix_acl_log_permit_denied] 0-sharedvol-access-control: client: mfc-nas1-14785-2018/05/23-06:10:20:243359-sharedvol-client-0-0-0, gfid: 839a087e-4997-4140-ac4f-aafbf1bb9e3b, req(uid:33,gid:33,perm:1,ngrps:1), ctx(uid:33,gid:0,in-groups:0,perm:644,updated-fop:SETATTR, acl:-) [Permission denied]<br class=""><br class="">There are not any issues with the actual file access, everything is working as it should be from the clients which are all mounting to the Gluster NFS process on the main server. So far I have tried lowering the log level for both the bricks and the clients to CRITICAL but the messages were still pouring in, checked to make sure there aren’t any ACL’s set on the files in the first place (the vast majority of them have no ACL set on them), and even tried restarting the servers as a desperate attempt to get them working right. We did not have this problem on 3.6, and we have other 3.12 Gluster setups that are similarly configured that are not having this issue either. The only difference with those is we did not go from 3.6 to 3.12, at most we went from 3.8 to 3.10 then to 3.12. I have another setup running 3.6 still that I need to do an update on pretty soon here and really don’t want to have this happening on that one as well.<br class=""><br class="">Here are the NFS settings for the volume in Gluster:<br class=""><br class="">$ sudo gluster volume get sharedvol all | grep nfs<br class="">performance.nfs.flush-behind on <br class="">performance.nfs.write-behind-window-size1MB <br class="">performance.nfs.strict-o-direct off <br class="">performance.nfs.strict-write-ordering off <br class="">performance.nfs.write-behind on <br class="">performance.nfs.read-ahead off <br class="">performance.nfs.io-cache off <br class="">performance.nfs.quick-read off <br class="">performance.nfs.stat-prefetch off <br class="">performance.nfs.io-threads off <br class="">nfs.enable-ino32 no <br class="">nfs.mem-factor 15 <br class="">nfs.export-dirs on <br class="">nfs.export-volumes on <br class="">nfs.addr-namelookup off <br class="">nfs.dynamic-volumes off <br class="">nfs.register-with-portmap on <br class="">nfs.outstanding-rpc-limit 16 <br class="">nfs.port 2049 <br class="">nfs.rpc-auth-unix on <br class="">nfs.rpc-auth-null on <br class="">nfs.rpc-auth-allow all <br class="">nfs.rpc-auth-reject none <br class="">nfs.ports-insecure off <br class="">nfs.trusted-sync off <br class="">nfs.trusted-write off <br class="">nfs.volume-access read-write <br class="">nfs.export-dir <br class="">nfs.disable off <br class="">nfs.nlm on <br class="">nfs.acl on <br class="">nfs.mount-udp off <br class="">nfs.mount-rmtab /var/lib/glusterd/nfs/rmtab <br class="">nfs.rpc-statd /sbin/rpc.statd <br class="">nfs.server-aux-gids off <br class="">nfs.drc off <br class="">nfs.drc-size 0x20000 <br class="">nfs.read-size (1 * 1048576ULL) <br class="">nfs.write-size (1 * 1048576ULL) <br class="">nfs.readdir-size (1 * 1048576ULL) <br class="">nfs.rdirplus on <br class="">nfs.exports-auth-enable (null) <br class="">nfs.auth-refresh-interval-sec (null) <br class="">nfs.auth-cache-ttl-sec (null) <br class="">cluster.halo-nfsd-max-latency 5<div class=""><br class=""></div><div class="">I’ve tried searching on this but have found virtually no information that comes even close to this issue aside from this very old bug report for 3.4: <a href="https://bugzilla.redhat.com/show_bug.cgi?id=862908" class="">https://bugzilla.redhat.com/show_bug.cgi?id=862908</a></div><div class=""><br class=""></div><div class="">Any help would be greatly appreciated.</div><div class=""><br class=""></div><div class="">Paul</div></body></html>