[Gluster-users] remote operation failed [Permission denied] every 10 minutes after upgrading from 5.10 to 7.0

Tue Jan 14 20:57:36 UTC 2020

Hi,

Any updates here please?

Sincerely,
Artem

--
Founder, Android Police <http://www.androidpolice.com>, APK Mirror
<http://www.apkmirror.com/>, Illogical Robot LLC
beerpla.net | @ArtemR <http://twitter.com/ArtemR>

On Mon, Jan 6, 2020 at 4:18 PM Artem Russakovskii <archon810 at gmail.com>
wrote:

> Thanks Amar,
>
> Checking the brick logs, I'm seeing these and numerous other files with
> Permission denied. The question is why is the permission being denied?
> Gluster runs as root and the files are owned by wwwrun:www, which it should
> have full access to.
>
> Is there any more documentation on what enabling or disabling this feature
> accomplishes, why it was added to 7.1 by default (and 7.0 as far as I can
> tell), and what side effects it may have? Basically, I'd like to understand
> the problem better instead of simply turning the flag off and fix the
> underlying issue (or help fix a bug if it's a bug in gluster).
>
> ==> bricks/mnt-pylon_block6-dev_SNIP_data.log <==
>> [2020-01-06 21:39:00.176476] I [MSGID: 115060]
>> [server-rpc-fops_v2.c:897:server4_setxattr_cbk] 0-dev_SNIP_data-server:
>> client:
>> CTX_ID:3e0436a5-cdf8-4d3f-a4e9-fc681fe902d3-GRAPH_ID:2-PID:32069-HOST:pylon-PC_NAME:dev_SNIP_data-client-2-RECON_NO:-0,
>> error-xlator: dev_SNIP_data-access-control [Permission denied]
>> [2020-01-06 21:39:00.325329] I [MSGID: 139001]
>> [posix-acl.c:262:posix_acl_log_permit_denied]
>> 0-dev_SNIP_data-access-control: client:
>> CTX_ID:3e0436a5-cdf8-4d3f-a4e9-fc681fe902d3-GRAPH_ID:2-PID:32069-HOST:pylon-PC_NAME:dev_SNIP_data-client-2-RECON_NO:-0,
>> gfid: e9bd83fd-b16e-44ef-8fde-2ae320ee54d0,
>> req(uid:491,gid:488,perm:2,ngrps:1),
>> ctx(uid:30,gid:8,in-groups:0,perm:664,updated-fop:LOOKUP, acl:-)
>> [Permission denied]
>> [2020-01-06 21:39:00.325435] I [MSGID: 115060]
>> [server-rpc-fops.c:937:_gf_server_log_setxattr_failure]
>> 0-dev_SNIP_data-server: 709342: SETXATTR
>> /uploads/2019/06/Anker-PowerPort-Atom-10-768x512.jpg
>> (e9bd83fd-b16e-44ef-8fde-2ae320ee54d0) ==> set-ctime-mdata, client:
>> CTX_ID:3e0436a5-cdf8-4d3f-a4e9-fc681fe902d3-GRAPH_ID:2-PID:32069-HOST:pylon-PC_NAME:dev_SNIP_data-client-2-RECON_NO:-0,
>> error-xlator: dev_SNIP_data-access-control
>> [2020-01-06 21:39:00.325460] I [MSGID: 115060]
>> [server-rpc-fops_v2.c:897:server4_setxattr_cbk] 0-dev_SNIP_data-server:
>> client:
>> CTX_ID:3e0436a5-cdf8-4d3f-a4e9-fc681fe902d3-GRAPH_ID:2-PID:32069-HOST:pylon-PC_NAME:dev_SNIP_data-client-2-RECON_NO:-0,
>> error-xlator: dev_SNIP_data-access-control [Permission denied]
>> [2020-01-06 21:39:01.195012] I [MSGID: 139001]
>> [posix-acl.c:262:posix_acl_log_permit_denied]
>> 0-dev_SNIP_data-access-control: client:
>> CTX_ID:3e0436a5-cdf8-4d3f-a4e9-fc681fe902d3-GRAPH_ID:2-PID:32069-HOST:pylon-PC_NAME:dev_SNIP_data-client-2-RECON_NO:-0,
>> gfid: ff96827e-777b-45fb-a40d-e5089cd024fe,
>> req(uid:491,gid:488,perm:2,ngrps:1),
>> ctx(uid:30,gid:8,in-groups:0,perm:664,updated-fop:LOOKUP, acl:-)
>> [Permission denied]
>> [2020-01-06 21:39:01.195091] I [MSGID: 115060]
>> [server-rpc-fops.c:937:_gf_server_log_setxattr_failure]
>> 0-dev_SNIP_data-server: 709349: SETXATTR
>> /uploads/2019/06/Anker-PowerPort-Atom-768x512.jpg
>> (ff96827e-777b-45fb-a40d-e5089cd024fe) ==> set-ctime-mdata, client:
>> CTX_ID:3e0436a5-cdf8-4d3f-a4e9-fc681fe902d3-GRAPH_ID:2-PID:32069-HOST:pylon-PC_NAME:dev_SNIP_data-client-2-RECON_NO:-0,
>> error-xlator: dev_SNIP_data-access-control
>> [2020-01-06 21:39:01.195291] I [MSGID: 115060]
>> [server-rpc-fops_v2.c:897:server4_setxattr_cbk] 0-dev_SNIP_data-server:
>> client:
>> CTX_ID:3e0436a5-cdf8-4d3f-a4e9-fc681fe902d3-GRAPH_ID:2-PID:32069-HOST:pylon-PC_NAME:dev_SNIP_data-client-2-RECON_NO:-0,
>> error-xlator: dev_SNIP_data-access-control [Permission denied]
>> [2020-01-06 21:39:04.184502] I [MSGID: 139001]
>> [posix-acl.c:262:posix_acl_log_permit_denied]
>> 0-dev_SNIP_data-access-control: client:
>> CTX_ID:3e0436a5-cdf8-4d3f-a4e9-fc681fe902d3-GRAPH_ID:2-PID:32069-HOST:pylon-PC_NAME:dev_SNIP_data-client-2-RECON_NO:-0,
>> gfid: 546305c8-7611-4752-9168-215e9eb03938,
>> req(uid:491,gid:488,perm:2,ngrps:1),
>> ctx(uid:30,gid:8,in-groups:0,perm:664,updated-fop:LOOKUP, acl:-)
>> [Permission denied]
>> [2020-01-06 21:39:04.184554] I [MSGID: 115060]
>> [server-rpc-fops.c:937:_gf_server_log_setxattr_failure]
>> 0-dev_SNIP_data-server: 709360: SETXATTR
>> /uploads/2019/06/Anker-PowerPort-Atom-10-1-768x512.jpg
>> (546305c8-7611-4752-9168-215e9eb03938) ==> set-ctime-mdata, client:
>> CTX_ID:3e0436a5-cdf8-4d3f-a4e9-fc681fe902d3-GRAPH_ID:2-PID:32069-HOST:pylon-PC_NAME:dev_SNIP_data-client-2-RECON_NO:-0,
>> error-xlator: dev_SNIP_data-access-control
>> [2020-01-06 21:39:04.184576] I [MSGID: 115060]
>> [server-rpc-fops_v2.c:897:server4_setxattr_cbk] 0-dev_SNIP_data-server:
>> client:
>> CTX_ID:3e0436a5-cdf8-4d3f-a4e9-fc681fe902d3-GRAPH_ID:2-PID:32069-HOST:pylon-PC_NAME:dev_SNIP_data-client-2-RECON_NO:-0,
>> error-xlator: dev_SNIP_data-access-control [Permission denied]
>>
>
> Btw, cluster.op-version is 70000, which is the latest. I always rev it up
> after upgrading the cluster.
>
> Sincerely,
> Artem
>
> --
> Founder, Android Police <http://www.androidpolice.com>, APK Mirror
> <http://www.apkmirror.com/>, Illogical Robot LLC
> beerpla.net | @ArtemR <http://twitter.com/ArtemR>
>
>
> On Sat, Dec 28, 2019 at 1:19 AM Amar Tumballi <amarts at gmail.com> wrote:
>
>> Answers inline.
>>
>> On Wed, Dec 25, 2019 at 2:06 AM Artem Russakovskii <archon810 at gmail.com>
>> wrote:
>>
>>> Hi everyone,
>>>
>>> I'm preparing the upgrade for our 5.10 gluster cluster running 1x4
>>> replicate volumes to 7.X and decided to upgrade our test cluster first.
>>>
>>> As soon as I upgraded to 7.0 (and now 7.1), I started seeing the
>>> following messages every 10 minutes in the log for one of the volumes:
>>>
>>> [2019-12-19 21:27:55.041949] W [MSGID: 114031]
>>>> [client-rpc-fops_v2.c:850:client4_0_setxattr_cbk] 0-dev_SNIP_data-client-0:
>>>> remote operation failed [Permission denied]
>>>> [2019-12-19 21:27:55.042002] W [MSGID: 114031]
>>>> [client-rpc-fops_v2.c:850:client4_0_setxattr_cbk] 0-dev_SNIP_data-client-2:
>>>> remote operation failed [Permission denied]
>>>> [2019-12-19 21:27:55.042013] W [MSGID: 114031]
>>>> [client-rpc-fops_v2.c:850:client4_0_setxattr_cbk] 0-dev_SNIP_data-client-1:
>>>> remote operation failed [Permission denied]
>>>> [2019-12-19 21:27:55.042634] E [MSGID: 148002]
>>>> [utime.c:146:gf_utime_set_mdata_setxattr_cbk] 0-dev_SNIP_data-utime: dict
>>>> set of key for set-ctime-mdata failed [Permission denied]
>>>> The message "W [MSGID: 114031]
>>>> [client-rpc-fops_v2.c:850:client4_0_setxattr_cbk] 0-dev_SNIP_data-client-0:
>>>> remote operation failed [Permission denied]" repeated 2 times between
>>>> [2019-12-19 21:27:55.041949] and [2019-12-19 21:27:55.047300]
>>>> The message "W [MSGID: 114031]
>>>> [client-rpc-fops_v2.c:850:client4_0_setxattr_cbk] 0-dev_SNIP_data-client-2:
>>>> remote operation failed [Permission denied]" repeated 2 times between
>>>> [2019-12-19 21:27:55.042002] and [2019-12-19 21:27:55.047312]
>>>> The message "W [MSGID: 114031]
>>>> [client-rpc-fops_v2.c:850:client4_0_setxattr_cbk] 0-dev_SNIP_data-client-1:
>>>> remote operation failed [Permission denied]" repeated 2 times between
>>>> [2019-12-19 21:27:55.042013] and [2019-12-19 21:27:55.047524]
>>>> The message "E [MSGID: 148002]
>>>> [utime.c:146:gf_utime_set_mdata_setxattr_cbk] 0-dev_SNIP_data-utime: dict
>>>> set of key for set-ctime-mdata failed [Permission denied]" repeated 2 times
>>>> between [2019-12-19 21:27:55.042634] and [2019-12-19 21:27:55.047887]
>>>>
>>>
>>>
>>>> [2019-12-19 21:37:55.541329] W [MSGID: 114031]
>>>> [client-rpc-fops_v2.c:850:client4_0_setxattr_cbk] 0-dev_SNIP_data-client-2:
>>>> remote operation failed [Permission denied]
>>>> [2019-12-19 21:37:55.541644] W [MSGID: 114031]
>>>> [client-rpc-fops_v2.c:850:client4_0_setxattr_cbk] 0-dev_SNIP_data-client-1:
>>>> remote operation failed [Permission denied]
>>>> [2019-12-19 21:37:55.541681] W [MSGID: 114031]
>>>> [client-rpc-fops_v2.c:850:client4_0_setxattr_cbk] 0-dev_SNIP_data-client-0:
>>>> remote operation failed [Permission denied]
>>>> [2019-12-19 21:37:55.542067] E [MSGID: 148002]
>>>> [utime.c:146:gf_utime_set_mdata_setxattr_cbk] 0-dev_SNIP_data-utime: dict
>>>> set of key for set-ctime-mdata failed [Permission denied]
>>>> The message "W [MSGID: 114031]
>>>> [client-rpc-fops_v2.c:850:client4_0_setxattr_cbk] 0-dev_SNIP_data-client-2:
>>>> remote operation failed [Permission denied]" repeated 3 times between
>>>> [2019-12-19 21:37:55.541329] and [2019-12-19 21:37:55.546695]
>>>> The message "W [MSGID: 114031]
>>>> [client-rpc-fops_v2.c:850:client4_0_setxattr_cbk] 0-dev_SNIP_data-client-1:
>>>> remote operation failed [Permission denied]" repeated 3 times between
>>>> [2019-12-19 21:37:55.541644] and [2019-12-19 21:37:55.546711]
>>>> The message "W [MSGID: 114031]
>>>> [client-rpc-fops_v2.c:850:client4_0_setxattr_cbk] 0-dev_SNIP_data-client-0:
>>>> remote operation failed [Permission denied]" repeated 3 times between
>>>> [2019-12-19 21:37:55.541681] and [2019-12-19 21:37:55.546761]
>>>> The message "E [MSGID: 148002]
>>>> [utime.c:146:gf_utime_set_mdata_setxattr_cbk] 0-dev_SNIP_data-utime: dict
>>>> set of key for set-ctime-mdata failed [Permission denied]" repeated 3 times
>>>> between [2019-12-19 21:37:55.542067] and [2019-12-19 21:37:55.547042]
>>>>
>>>
>>> etc.
>>>
>>> The questions are:
>>>
>>>    1. Is it a cause for concern? They weren't there before the upgrade.
>>>
>>> Looks like all these logs are related to ctime feature which is by
>> default enabled in 7.1 (and not in 5.x series)
>>
>>
>>>
>>>    1. How can I determine what's causing the errors?
>>>
>>>
>> Also check the server logs.
>>
>>
>>>
>>>    1. How can I fix them and prevent them from spamming the logs?
>>>
>>>
>> Check op-version of the cluster after upgrade. Disable 'ctime' option
>> (volume set <vol> ctime off).
>>
>>
>>
>>> Thank you and happy holidays!
>>>
>>
>> +1
>>
>> Regards,
>> Amar
>> https://kadalu.io
>>
>>
>>
>>>
>>> Sincerely,
>>> Artem
>>>
>>> --
>>> Founder, Android Police <http://www.androidpolice.com>, APK Mirror
>>> <http://www.apkmirror.com/>, Illogical Robot LLC
>>> beerpla.net | @ArtemR <http://twitter.com/ArtemR>
>>> ________
>>>
>>> Community Meeting Calendar:
>>>
>>> APAC Schedule -
>>> Every 2nd and 4th Tuesday at 11:30 AM IST
>>> Bridge: https://bluejeans.com/441850968
>>>
>>> NA/EMEA Schedule -
>>> Every 1st and 3rd Tuesday at 01:00 PM EDT
>>> Bridge: https://bluejeans.com/441850968
>>>
>>> Gluster-users mailing list
>>> Gluster-users at gluster.org
>>> https://lists.gluster.org/mailman/listinfo/gluster-users
>>>
>>
-------------- next part --------------
An HTML attachment was scrubbed...
URL: <http://lists.gluster.org/pipermail/gluster-users/attachments/20200114/cc451d6b/attachment.html>