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

Wed Mar 4 04:25:30 UTC 2020

On Sat, Feb 15, 2020 at 7:27 AM Amar Tumballi <amar at kadalu.io> wrote:

>
>
> On Sat, Feb 15, 2020 at 3:02 AM Artem Russakovskii <archon810 at gmail.com>
> wrote:
>
>> Amar,
>>
>> From what I can tell, there's no error actually using the referenced
>> files, but the log messages all constantly pop up in the log when accessed
>> through the web server. The files display OK in the browser.
>>
>> I also tried renaming/touching them via shell as the user that owns them,
>> and that worked fine (with no notices generated).
>>
>
> Thanks for this update.
>
>
>>
>> I hope you guys figure it out because I really don't feel comfortable
>> upgrading to 6 or 7 from 5 which has been stable.
>>
>>
> Ack! Makes sense, upgrading to a version when you know there is a
> regression is not a good thing. We will check this out.
>
>

https://review.gluster.org/#/c/glusterfs/+/24200/ would hopefully fix the
issue.

> -Amar
>
>
>> 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 Wed, Feb 12, 2020 at 11:02 PM Amar Tumballi <amarts at gmail.com> wrote:
>>
>>>
>>>
>>>
>>> On Fri, Feb 7, 2020 at 1:56 PM Artem Russakovskii <archon810 at gmail.com>
>>> wrote:
>>>
>>>> Still no response? Amar?
>>>>
>>>>
>>> Sorry, this got down in my Inbox, and missed responding, and also I got
>>> busy with few other engagements. Reply inline.
>>>
>>> Sincerely,
>>>> Artem
>>>>
>>>> On Tue, Jan 14, 2020 at 12:57 PM Artem Russakovskii <
>>>> archon810 at gmail.com> wrote:
>>>>
>>>>> 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.
>>>>>>
>>>>>>
>>> I don't have any reports of this error coming for other users, and not
>>> able to reproduce locally too.  I am starting to think that this error and
>>> the issue Strahil faced after upgrading (saying there was an ACL issue) may
>>> be related. Will check and update. Meantime, is there any application error
>>> you are seeing? That would also give us some hints to reproduce the issue.
>>>
>>> -Amar
>>>
>>>
>>>> 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
>>>>>>>>
>>>>>>> ________
>>
>> 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
>>
>
>
> --
> --
> https://kadalu.io
> Container Storage made easy!
>
>

-- 
--
https://kadalu.io
Container Storage made easy!
-------------- next part --------------
An HTML attachment was scrubbed...
URL: <http://lists.gluster.org/pipermail/gluster-users/attachments/20200304/350f0e1e/attachment.html>