Strahil Nikolov
2020-Apr-11 11:25 UTC
[Gluster-users] gluster 6.8: brick logs flooded by Information messages
On April 11, 2020 2:06:22 PM GMT+03:00, Hu Bert <revirii at googlemail.com> wrote:>Hi Strahil, > >looking into the mount logs i think i see the same (or at least very >similar) log messages: > >[2020-04-11 11:01:21.676613] I [MSGID: 108031] >[afr-common.c:2548:afr_local_discovery_cbk] 0-workdata-replicate-0: >selecting local read_child workdata-client-0 >[2020-04-11 11:01:21.791039] W [MSGID: 114031] >[client-rpc-fops_v2.c:851:client4_0_setxattr_cbk] 0-workdata-client-0: >remote operation failed [Permission denied] >[2020-04-11 11:01:21.791099] W [MSGID: 114031] >[client-rpc-fops_v2.c:851:client4_0_setxattr_cbk] 0-workdata-client-1: >remote operation failed [Permission denied] >[2020-04-11 11:01:21.791172] W [MSGID: 114031] >[client-rpc-fops_v2.c:851:client4_0_setxattr_cbk] 0-workdata-client-2: >remote operation failed [Permission denied] >[2020-04-11 11:01:21.791598] E [MSGID: 148002] >[utime.c:146:gf_utime_set_mdata_setxattr_cbk] 0-workdata-utime: dict >set of key for set-ctime-mdata failed [Permission denied] >The message "I [MSGID: 108031] >[afr-common.c:2548:afr_local_discovery_cbk] 0-workdata-replicate-0: >selecting local read_child workdata-client-0" repeated 947 times >between [2020-04-11 11:01:21.676613] and [2020-04-11 11:03:21.405740] >The message "W [MSGID: 114031] >[client-rpc-fops_v2.c:851:client4_0_setxattr_cbk] 0-workdata-client-0: >remote operation failed [Permission denied]" repeated 3947 times >between [2020-04-11 11:01:21.791039] and [2020-04-11 11:03:21.443929] >The message "W [MSGID: 114031] >[client-rpc-fops_v2.c:851:client4_0_setxattr_cbk] 0-workdata-client-2: >remote operation failed [Permission denied]" repeated 3947 times >between [2020-04-11 11:01:21.791172] and [2020-04-11 11:03:21.443958] >The message "W [MSGID: 114031] >[client-rpc-fops_v2.c:851:client4_0_setxattr_cbk] 0-workdata-client-1: >remote operation failed [Permission denied]" repeated 3947 times >between [2020-04-11 11:01:21.791099] and [2020-04-11 11:03:21.444008] >The message "E [MSGID: 148002] >[utime.c:146:gf_utime_set_mdata_setxattr_cbk] 0-workdata-utime: dict >set of key for set-ctime-mdata failed [Permission denied]" repeated >3947 times between [2020-04-11 11:01:21.791598] and [2020-04-11 >11:03:21.444357] > >Best regards, >Hubert > >Am Sa., 11. Apr. 2020 um 11:11 Uhr schrieb Strahil Nikolov ><hunter86_bg at yahoo.com>: >> >> On April 11, 2020 8:35:41 AM GMT+03:00, Hu Bert ><revirii at googlemail.com> wrote: >> >Hi, >> > >> >this week i upgraded from 5.11 to 6.8. Since that the brick logs get >> >flooded by such messages: >> > >> >[2020-04-11 05:22:48.774688] I [MSGID: 139001] >> >[posix-acl.c:263:posix_acl_log_permit_denied] >> >0-workdata-access-control: client: >> >>CTX_ID:a1b55e2b-af03-484a-9be0-9314fec4bb61-GRAPH_ID:0-PID:8204-HOST:gluster1-PC_NAME:workdata-client-0-RECON_NO:-0, >> >gfid: 25f487a5-2973-407c-87d2-74979c16c5ab, >> >req(uid:33,gid:33,perm:2,ngrps:1), >> >ctx(uid:109,gid:114,in-groups:0,perm:644,updated-fop:LOOKUP, acl:-) >> >[Permission denied] >> >[2020-04-11 05:22:48.774768] I [MSGID: 115060] >> >[server-rpc-fops.c:938:_gf_server_log_setxattr_failure] >> >0-workdata-server: 60517534: SETXATTR >> >/images/383/200/38320023/800x800f.jpg >> >(25f487a5-2973-407c-87d2-74979c16c5ab) ==> set-ctime-mdata, client: >> >>CTX_ID:a1b55e2b-af03-484a-9be0-9314fec4bb61-GRAPH_ID:0-PID:8204-HOST:gluster1-PC_NAME:workdata-client-0-RECON_NO:-0, >> >error-xlator: workdata-access-control >> > >> >The file in the filesystem: >> > >> >-rw-r--r-- 1 tomcat8 tomcat8 283K Jun 13 2019 800x800f.jpg >> > >> >So this file exists for 9 months now. The log messages appear for >> >files and directories. And there are over 9.5 million log entries in >> >the last 10 hours. >> > >> >Is this behaviour normal for 6.8? Will it disappear? Anyone an idea >> >what is happening here? >> > >> > >> >Regards, >> >Hubert >> >________ >> > >> > >> > >> >Community Meeting Calendar: >> > >> >Schedule - >> >Every 2nd and 4th Tuesday at 14:30 IST / 09:00 UTC >> >Bridge: https://bluejeans.com/441850968 >> > >> >Gluster-users mailing list >> >Gluster-users at gluster.org >> >https://lists.gluster.org/mailman/listinfo/gluster-users >> >> Hi Hubert, >> Not normal at all. >> It looks like my ACL problem. >> The workaround for me is to copy the file/dir and replace it: >> cp -a orig new >> mv orig old && mv new orig >> >> @Amar, is the 'https://review.gluster.org/#/c/glusterfs/+/24264/' >in 6.8 ? >> The output seems just like mine. >> >> Best Regards, >> Strahil NikolovFor me the ACL issue hit me when I migrated from 6.5 to 6.6 . For me 6.5 & 7.0 were OK, while anything above was a problem. What was your version prior the upgrade ? Best Regards, Strahil Nikolov
Hu Bert
2020-Apr-11 13:38 UTC
[Gluster-users] gluster 6.8: brick logs flooded by Information messages
as i wrote in the opening post: the previous version was 5.11. Best regards, Hubert Am Sa., 11. Apr. 2020 um 13:25 Uhr schrieb Strahil Nikolov <hunter86_bg at yahoo.com>:> > On April 11, 2020 2:06:22 PM GMT+03:00, Hu Bert <revirii at googlemail.com> wrote: > >Hi Strahil, > > > >looking into the mount logs i think i see the same (or at least very > >similar) log messages: > > > >[2020-04-11 11:01:21.676613] I [MSGID: 108031] > >[afr-common.c:2548:afr_local_discovery_cbk] 0-workdata-replicate-0: > >selecting local read_child workdata-client-0 > >[2020-04-11 11:01:21.791039] W [MSGID: 114031] > >[client-rpc-fops_v2.c:851:client4_0_setxattr_cbk] 0-workdata-client-0: > >remote operation failed [Permission denied] > >[2020-04-11 11:01:21.791099] W [MSGID: 114031] > >[client-rpc-fops_v2.c:851:client4_0_setxattr_cbk] 0-workdata-client-1: > >remote operation failed [Permission denied] > >[2020-04-11 11:01:21.791172] W [MSGID: 114031] > >[client-rpc-fops_v2.c:851:client4_0_setxattr_cbk] 0-workdata-client-2: > >remote operation failed [Permission denied] > >[2020-04-11 11:01:21.791598] E [MSGID: 148002] > >[utime.c:146:gf_utime_set_mdata_setxattr_cbk] 0-workdata-utime: dict > >set of key for set-ctime-mdata failed [Permission denied] > >The message "I [MSGID: 108031] > >[afr-common.c:2548:afr_local_discovery_cbk] 0-workdata-replicate-0: > >selecting local read_child workdata-client-0" repeated 947 times > >between [2020-04-11 11:01:21.676613] and [2020-04-11 11:03:21.405740] > >The message "W [MSGID: 114031] > >[client-rpc-fops_v2.c:851:client4_0_setxattr_cbk] 0-workdata-client-0: > >remote operation failed [Permission denied]" repeated 3947 times > >between [2020-04-11 11:01:21.791039] and [2020-04-11 11:03:21.443929] > >The message "W [MSGID: 114031] > >[client-rpc-fops_v2.c:851:client4_0_setxattr_cbk] 0-workdata-client-2: > >remote operation failed [Permission denied]" repeated 3947 times > >between [2020-04-11 11:01:21.791172] and [2020-04-11 11:03:21.443958] > >The message "W [MSGID: 114031] > >[client-rpc-fops_v2.c:851:client4_0_setxattr_cbk] 0-workdata-client-1: > >remote operation failed [Permission denied]" repeated 3947 times > >between [2020-04-11 11:01:21.791099] and [2020-04-11 11:03:21.444008] > >The message "E [MSGID: 148002] > >[utime.c:146:gf_utime_set_mdata_setxattr_cbk] 0-workdata-utime: dict > >set of key for set-ctime-mdata failed [Permission denied]" repeated > >3947 times between [2020-04-11 11:01:21.791598] and [2020-04-11 > >11:03:21.444357] > > > >Best regards, > >Hubert > > > >Am Sa., 11. Apr. 2020 um 11:11 Uhr schrieb Strahil Nikolov > ><hunter86_bg at yahoo.com>: > >> > >> On April 11, 2020 8:35:41 AM GMT+03:00, Hu Bert > ><revirii at googlemail.com> wrote: > >> >Hi, > >> > > >> >this week i upgraded from 5.11 to 6.8. Since that the brick logs get > >> >flooded by such messages: > >> > > >> >[2020-04-11 05:22:48.774688] I [MSGID: 139001] > >> >[posix-acl.c:263:posix_acl_log_permit_denied] > >> >0-workdata-access-control: client: > >> > >>CTX_ID:a1b55e2b-af03-484a-9be0-9314fec4bb61-GRAPH_ID:0-PID:8204-HOST:gluster1-PC_NAME:workdata-client-0-RECON_NO:-0, > >> >gfid: 25f487a5-2973-407c-87d2-74979c16c5ab, > >> >req(uid:33,gid:33,perm:2,ngrps:1), > >> >ctx(uid:109,gid:114,in-groups:0,perm:644,updated-fop:LOOKUP, acl:-) > >> >[Permission denied] > >> >[2020-04-11 05:22:48.774768] I [MSGID: 115060] > >> >[server-rpc-fops.c:938:_gf_server_log_setxattr_failure] > >> >0-workdata-server: 60517534: SETXATTR > >> >/images/383/200/38320023/800x800f.jpg > >> >(25f487a5-2973-407c-87d2-74979c16c5ab) ==> set-ctime-mdata, client: > >> > >>CTX_ID:a1b55e2b-af03-484a-9be0-9314fec4bb61-GRAPH_ID:0-PID:8204-HOST:gluster1-PC_NAME:workdata-client-0-RECON_NO:-0, > >> >error-xlator: workdata-access-control > >> > > >> >The file in the filesystem: > >> > > >> >-rw-r--r-- 1 tomcat8 tomcat8 283K Jun 13 2019 800x800f.jpg > >> > > >> >So this file exists for 9 months now. The log messages appear for > >> >files and directories. And there are over 9.5 million log entries in > >> >the last 10 hours. > >> > > >> >Is this behaviour normal for 6.8? Will it disappear? Anyone an idea > >> >what is happening here? > >> > > >> > > >> >Regards, > >> >Hubert > >> >________ > >> > > >> > > >> > > >> >Community Meeting Calendar: > >> > > >> >Schedule - > >> >Every 2nd and 4th Tuesday at 14:30 IST / 09:00 UTC > >> >Bridge: https://bluejeans.com/441850968 > >> > > >> >Gluster-users mailing list > >> >Gluster-users at gluster.org > >> >https://lists.gluster.org/mailman/listinfo/gluster-users > >> > >> Hi Hubert, > >> Not normal at all. > >> It looks like my ACL problem. > >> The workaround for me is to copy the file/dir and replace it: > >> cp -a orig new > >> mv orig old && mv new orig > >> > >> @Amar, is the 'https://review.gluster.org/#/c/glusterfs/+/24264/' > >in 6.8 ? > >> The output seems just like mine. > >> > >> Best Regards, > >> Strahil Nikolov > > For me the ACL issue hit me when I migrated from 6.5 to 6.6 . > For me 6.5 & 7.0 were OK, while anything above was a problem. > > What was your version prior the upgrade ? > > Best Regards, > Strahil Nikolov