Paul Allen
2018-May-23 06:32 UTC
[Gluster-users] cluster brick logs filling after upgrade from 3.6 to 3.12
Recently we updated a Gluster replicated setup from 3.6 to 3.12 (stepping through 3.8 first before going to 3.12). Afterwards I noticed the brick logs were filling at an alarming rate on the server we have the NFS service running from: $ sudo tail -20 /var/log/glusterfs/bricks/export-gluster-shared.log [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] [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] [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] [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] [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] [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] [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] [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] [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] [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] [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] [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] [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] [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] [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] [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] 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] [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] [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] [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] 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. Here are the NFS settings for the volume in Gluster: $ sudo gluster volume get sharedvol all | grep nfs performance.nfs.flush-behind on performance.nfs.write-behind-window-size1MB performance.nfs.strict-o-direct off performance.nfs.strict-write-ordering off performance.nfs.write-behind on performance.nfs.read-ahead off performance.nfs.io-cache off performance.nfs.quick-read off performance.nfs.stat-prefetch off performance.nfs.io-threads off nfs.enable-ino32 no nfs.mem-factor 15 nfs.export-dirs on nfs.export-volumes on nfs.addr-namelookup off nfs.dynamic-volumes off nfs.register-with-portmap on nfs.outstanding-rpc-limit 16 nfs.port 2049 nfs.rpc-auth-unix on nfs.rpc-auth-null on nfs.rpc-auth-allow all nfs.rpc-auth-reject none nfs.ports-insecure off nfs.trusted-sync off nfs.trusted-write off nfs.volume-access read-write nfs.export-dir nfs.disable off nfs.nlm on nfs.acl on nfs.mount-udp off nfs.mount-rmtab /var/lib/glusterd/nfs/rmtab nfs.rpc-statd /sbin/rpc.statd nfs.server-aux-gids off nfs.drc off nfs.drc-size 0x20000 nfs.read-size (1 * 1048576ULL) nfs.write-size (1 * 1048576ULL) nfs.readdir-size (1 * 1048576ULL) nfs.rdirplus on nfs.exports-auth-enable (null) nfs.auth-refresh-interval-sec (null) nfs.auth-cache-ttl-sec (null) cluster.halo-nfsd-max-latency 5 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: https://bugzilla.redhat.com/show_bug.cgi?id=862908 <https://bugzilla.redhat.com/show_bug.cgi?id=862908> Any help would be greatly appreciated. Paul -------------- next part -------------- An HTML attachment was scrubbed... URL: <http://lists.gluster.org/pipermail/gluster-users/attachments/20180523/5077f532/attachment.html>
Possibly Parallel Threads
Wisdom of the Ancients
