Patrick,
Thank you for reaching out.
> Have you tried remounting? Updating auth credentials usually requires remount.
Yes, we have tried both changing caps on our original user as well as
using the client.admin user with remounts between each change.
> Next thing to do is collect mds logs:
>
> ceph config set mds debug_mds 20
> ceph config set mds debug_ms 1
>
> And share a snippet during the failure.
I attempted to create another snapshot in a subdirectory as follows:
root@ceph-01:/mnt/dncephfs/testfolder/.snap# mkdir
testsnapshotincreasedlogging
mkdir: cannot create directory ‘testsnapshotincreasedlogging’:
Operation not permitted
Here is what I see in the mds logs (NOTE: I have since my initial
writing enabled scheduled snapshots on / which seem to have created
"_scheduled-$DATETIME" snapshots recursively on all subdirs. This was
not enabled when I initially reported this):
-----SNIP-----
debug 2021-08-21T04:23:01.118+0000 7f2f47eb9700 1 --
[v2:10.30.0.146:6800/2592330660,v1:10.30.0.146:6801/2592330660] <==
client.974668 v1:10.30.0.145:0/2049851970 105 ====
client_request(client.974668:49 lookupsnap #0x100001be68f//testsna
pshotincreasedlogging 2021-08-21T04:23:01.124841+0000 caller_uid=0,
caller_gid=0{}) v2 ==== 151+0+0 (unknown 3477258848 0 0) 0x5587517e5080
con 0x55876c48b400
debug 2021-08-21T04:23:01.118+0000 7f2f47eb9700 4 mds.0.server
handle_client_request client_request(client.974668:49 lookupsnap
#0x100001be68f//testsnapshotincreasedlogging
2021-08-21T04:23:01.124841+0000 caller_uid=0, caller_gid=0{}) v2
debug 2021-08-21T04:23:01.118+0000 7f2f47eb9700 20 mds.0.4397
get_session have 0x55876f6fc800 client.974668
v1:10.30.0.145:0/2049851970 state open
debug 2021-08-21T04:23:01.118+0000 7f2f47eb9700 15 mds.0.server
oldest_client_tid=49
debug 2021-08-21T04:23:01.118+0000 7f2f47eb9700 7 mds.0.cache
request_start request(client.974668:49 nref=2 cr=0x5587517e5080)
debug 2021-08-21T04:23:01.118+0000 7f2f47eb9700 7 mds.0.server
dispatch_client_request client_request(client.974668:49 lookupsnap
#0x100001be68f//testsnapshotincreasedlogging
2021-08-21T04:23:01.124841+0000 caller_uid=0, caller_gid=0{}) v
2
debug 2021-08-21T04:23:01.118+0000 7f2f47eb9700 10 mds.0.server
rdlock_path_pin_ref request(client.974668:49 nref=2 cr=0x5587517e5080)
#0x100001be68f//testsnapshotincreasedlogging
debug 2021-08-21T04:23:01.118+0000 7f2f47eb9700 7 mds.0.cache traverse:
opening base ino 0x100001be68f snap head
debug 2021-08-21T04:23:01.118+0000 7f2f47eb9700 12 mds.0.cache traverse:
path seg depth 0 '' snapid head
debug 2021-08-21T04:23:01.118+0000 7f2f47eb9700 10 mds.0.cache traverse:
snapdir
debug 2021-08-21T04:23:01.118+0000 7f2f47eb9700 12 mds.0.cache traverse:
path seg depth 1 'testsnapshotincreasedlogging' snapid snapdir
debug 2021-08-21T04:23:01.118+0000 7f2f47eb9700 10
mds.0.cache.snaprealm(0x1 seq 32 0x55874abc0600) resolve_snapname
'testsnapshotincreasedlogging' in [0,head]
debug 2021-08-21T04:23:01.118+0000 7f2f47eb9700 15
mds.0.cache.snaprealm(0x1 seq 32 0x55874abc0600) ? snap(10 0x1
'scheduled-2021-08-20-12_00_00' 2021-08-20T12:00:00.886935+0000)
debug 2021-08-21T04:23:01.118+0000 7f2f47eb9700 15
mds.0.cache.snaprealm(0x1 seq 32 0x55874abc0600) ? snap(11 0x1
'scheduled-2021-08-20-13_00_00' 2021-08-20T13:00:00.049476+0000)
debug 2021-08-21T04:23:01.118+0000 7f2f47eb9700 15
mds.0.cache.snaprealm(0x1 seq 32 0x55874abc0600) ? snap(12 0x1
'scheduled-2021-08-20-14_00_00' 2021-08-20T14:00:00.136498+0000)
debug 2021-08-21T04:23:01.118+0000 7f2f47eb9700 15
mds.0.cache.snaprealm(0x1 seq 32 0x55874abc0600) ? snap(13 0x1
'scheduled-2021-08-20-15_00_00' 2021-08-20T15:00:00.220621+0000)
debug 2021-08-21T04:23:01.118+0000 7f2f47eb9700 15
mds.0.cache.snaprealm(0x1 seq 32 0x55874abc0600) ? snap(14 0x1
'scheduled-2021-08-20-16_00_00' 2021-08-20T16:00:00.343340+0000)
debug 2021-08-21T04:23:01.118+0000 7f2f47eb9700 15
mds.0.cache.snaprealm(0x1 seq 32 0x55874abc0600) ? snap(15 0x1
'scheduled-2021-08-20-17_00_00' 2021-08-20T17:00:00.628487+0000)
debug 2021-08-21T04:23:01.118+0000 7f2f47eb9700 15
mds.0.cache.snaprealm(0x1 seq 32 0x55874abc0600) ? snap(16 0x1
'scheduled-2021-08-20-18_00_00' 2021-08-20T18:00:00.755029+0000)
debug 2021-08-21T04:23:01.118+0000 7f2f47eb9700 15
mds.0.cache.snaprealm(0x1 seq 32 0x55874abc0600) ? snap(17 0x1
'scheduled-2021-08-20-19_00_00' 2021-08-20T19:00:00.935843+0000)
debug 2021-08-21T04:23:01.118+0000 7f2f47eb9700 15
mds.0.cache.snaprealm(0x1 seq 32 0x55874abc0600) ? snap(18 0x1
'scheduled-2021-08-20-20_00_00' 2021-08-20T20:00:00.106956+0000)
debug 2021-08-21T04:23:01.118+0000 7f2f47eb9700 15
mds.0.cache.snaprealm(0x1 seq 32 0x55874abc0600) ? snap(19 0x1
'scheduled-2021-08-20-21_00_00' 2021-08-20T21:00:00.228902+0000)
debug 2021-08-21T04:23:01.118+0000 7f2f47eb9700 15
mds.0.cache.snaprealm(0x1 seq 32 0x55874abc0600) ? snap(1a 0x1
'scheduled-2021-08-20-22_00_00' 2021-08-20T22:00:00.380137+0000)
debug 2021-08-21T04:23:01.118+0000 7f2f47eb9700 15
mds.0.cache.snaprealm(0x1 seq 32 0x55874abc0600) ? snap(1b 0x1
'scheduled-2021-08-20-23_00_00' 2021-08-20T23:00:00.567952+0000)
debug 2021-08-21T04:23:01.118+0000 7f2f47eb9700 15
mds.0.cache.snaprealm(0x1 seq 32 0x55874abc0600) ? snap(1c 0x1
'scheduled-2021-08-21-00_00_00' 2021-08-21T00:00:00.760474+0000)
debug 2021-08-21T04:23:01.118+0000 7f2f47eb9700 15
mds.0.cache.snaprealm(0x1 seq 32 0x55874abc0600) ? snap(1d 0x1
'scheduled-2021-08-21-01_00_00' 2021-08-21T01:00:00.891052+0000)
debug 2021-08-21T04:23:01.118+0000 7f2f47eb9700 15
mds.0.cache.snaprealm(0x1 seq 32 0x55874abc0600) ? snap(1e 0x1
'scheduled-2021-08-21-02_00_00' 2021-08-21T02:00:01.019409+0000)
debug 2021-08-21T04:23:01.118+0000 7f2f47eb9700 15
mds.0.cache.snaprealm(0x1 seq 32 0x55874abc0600) ? snap(1f 0x1
'scheduled-2021-08-21-03_00_00' 2021-08-21T03:00:00.154135+0000)
debug 2021-08-21T04:23:01.118+0000 7f2f47eb9700 15
mds.0.cache.snaprealm(0x1 seq 32 0x55874abc0600) ? snap(20 0x1
'scheduled-2021-08-21-04_00_00' 2021-08-21T04:00:00.323577+0000)
debug 2021-08-21T04:23:01.118+0000 7f2f47eb9700 10 mds.0.cache traverse:
snap testsnapshotincreasedlogging -> 0
debug 2021-08-21T04:23:01.118+0000 7f2f47eb9700 10 mds.0.server FAIL on
error -2
debug 2021-08-21T04:23:01.118+0000 7f2f47eb9700 7 mds.0.server
reply_client_request -2 ((2) No such file or directory)
client_request(client.974668:49 lookupsnap
#0x100001be68f//testsnapshotincreasedlogging 2021-08-21T04:23:01.124841+0000
caller_uid=0, caller_gid=0{}) v2
debug 2021-08-21T04:23:01.118+0000 7f2f47eb9700 10 mds.0.server
apply_allocated_inos 0x0 / [] / 0x0
debug 2021-08-21T04:23:01.118+0000 7f2f47eb9700 20 mds.0.server lat 0.000139
debug 2021-08-21T04:23:01.118+0000 7f2f47eb9700 10 mds.0.4397
send_message_client client.974668 v1:10.30.0.145:0/2049851970
client_reply(???:49 = -2 (2) No such file or directory) v1
debug 2021-08-21T04:23:01.118+0000 7f2f47eb9700 1 --
[v2:10.30.0.146:6800/2592330660,v1:10.30.0.146:6801/2592330660] -->
v1:10.30.0.145:0/2049851970 -- client_reply(???:49 = -2 (2) No such file
or directory) v1 -- 0x558760f94a80 con 0x558
76c48b400
debug 2021-08-21T04:23:01.118+0000 7f2f47eb9700 7 mds.0.cache
request_finish request(client.974668:49 nref=3 cr=0x5587517e5080)
debug 2021-08-21T04:23:01.118+0000 7f2f47eb9700 15 mds.0.cache
request_cleanup request(client.974668:49 nref=3 cr=0x5587517e5080)
debug 2021-08-21T04:23:01.118+0000 7f2f47eb9700 1 --
[v2:10.30.0.146:6800/2592330660,v1:10.30.0.146:6801/2592330660] <==
client.974668 v1:10.30.0.145:0/2049851970 106 ====
client_request(client.974668:50 mksnap #0x100001be68f//testsnapsho
tincreasedlogging 2021-08-21T04:23:01.124841+0000 caller_uid=0,
caller_gid=0{}) v2 ==== 151+0+0 (unknown 2625648301 0 0) 0x55875013fb80
con 0x55876c48b400
debug 2021-08-21T04:23:01.118+0000 7f2f47eb9700 4 mds.0.server
handle_client_request client_request(client.974668:50 mksnap
#0x100001be68f//testsnapshotincreasedlogging
2021-08-21T04:23:01.124841+0000 caller_uid=0, caller_gid=0{}) v2
debug 2021-08-21T04:23:01.118+0000 7f2f47eb9700 20 mds.0.4397
get_session have 0x55876f6fc800 client.974668
v1:10.30.0.145:0/2049851970 state open
debug 2021-08-21T04:23:01.118+0000 7f2f47eb9700 15 mds.0.server
oldest_client_tid=50
debug 2021-08-21T04:23:01.118+0000 7f2f47eb9700 7 mds.0.cache
request_start request(client.974668:50 nref=2 cr=0x55875013fb80)
debug 2021-08-21T04:23:01.118+0000 7f2f47eb9700 7 mds.0.server
dispatch_client_request client_request(client.974668:50 mksnap
#0x100001be68f//testsnapshotincreasedlogging
2021-08-21T04:23:01.124841+0000 caller_uid=0, caller_gid=0{}) v2
debug 2021-08-21T04:23:01.118+0000 7f2f47eb9700 10 mds.0.server mksnap
testsnapshotincreasedlogging on [inode 0x100001be68f [...c,head]
/testfolder/ auth v1035687 f() n(v0 1=0+1) (ifile excl) (iversion lock)
caps={974668=pAsLsXsFsx/AsLsXsF
sx@38},l=974668 | request=0 lock=0 dirfrag=1 caps=1 waiter=0 authpin=0
0x558757ecc580]
debug 2021-08-21T04:23:01.118+0000 7f2f47eb9700 10 mds.0.locker
acquire_locks request(client.974668:50 nref=2 cr=0x55875013fb80)
debug 2021-08-21T04:23:01.118+0000 7f2f47eb9700 20 mds.0.locker must
xlock (isnap sync) [inode 0x100001be68f [...c,head] /testfolder/ auth
v1035687 f() n(v0 1=0+1) (ifile excl) (iversion lock)
caps={974668=pAsLsXsFsx/AsLsXsFsx@38},l=97466
8 | request=0 lock=0 dirfrag=1 caps=1 waiter=0 authpin=0 0x558757ecc580]
debug 2021-08-21T04:23:01.118+0000 7f2f47eb9700 20 mds.0.locker must
wrlock (iversion lock) [inode 0x100001be68f [...c,head] /testfolder/
auth v1035687 f() n(v0 1=0+1) (ifile excl) (iversion lock)
caps={974668=pAsLsXsFsx/AsLsXsFsx@38},l=9
74668 | request=0 lock=0 dirfrag=1 caps=1 waiter=0 authpin=0 0x558757ecc580]
debug 2021-08-21T04:23:01.118+0000 7f2f47eb9700 10 mds.0.locker must
authpin [inode 0x100001be68f [...c,head] /testfolder/ auth v1035687 f()
n(v0 1=0+1) (ifile excl) (iversion lock)
caps={974668=pAsLsXsFsx/AsLsXsFsx@38},l=974668 | request
=0 lock=0 dirfrag=1 caps=1 waiter=0 authpin=0 0x558757ecc580]
debug 2021-08-21T04:23:01.118+0000 7f2f47eb9700 10 mds.0.locker
auth_pinning [inode 0x100001be68f [...c,head] /testfolder/ auth v1035687
f() n(v0 1=0+1) (ifile excl) (iversion lock)
caps={974668=pAsLsXsFsx/AsLsXsFsx@38},l=974668 | request
=0 lock=0 dirfrag=1 caps=1 waiter=0 authpin=0 0x558757ecc580]
debug 2021-08-21T04:23:01.118+0000 7f2f47eb9700 10
mds.0.cache.ino(0x100001be68f) auth_pin by 0x55876b680800 on [inode
0x100001be68f [...c,head] /testfolder/ auth v1035687 ap=1 f() n(v0
1=0+1) (ifile excl) (iversion lock) caps={974668=pAsL
sXsFsx/AsLsXsFsx@38},l=974668 | request=0 lock=0 dirfrag=1 caps=1
waiter=0 authpin=1 0x558757ecc580] now 1
debug 2021-08-21T04:23:01.118+0000 7f2f47eb9700 15 mds.0.cache.dir(0x1)
adjust_nested_auth_pins 1 on [dir 0x1 / [2,head] auth v=1048982
cv=1048871/1048871 dir_auth=0 ap=0+1 state=1610874881|complete f(v0
m2021-08-20T11:10:36.706227+0000 7=
0+7) n(v60138 rc2106-02-06T09:40:08.000000+0000 b89832201935102
1775959=1579958+196001) hs=7+0,ss=0+0 dirty=2 | child=1 subtree=1
subtreetemp=0 dirty=1 waiter=0 authpin=0 0x558749665600] by
0x558757ecc580 count now 0/1
debug 2021-08-21T04:23:01.118+0000 7f2f47eb9700 7 mds.0.locker
xlock_start on (isnap sync) on [inode 0x100001be68f [...c,head]
/testfolder/ auth v1035687 ap=1 f() n(v0 1=0+1) (ifile excl) (iversion
lock) caps={974668=pAsLsXsFsx/AsLsXsFsx@
38},l=974668 | request=0 lock=0 dirfrag=1 caps=1 waiter=0 authpin=1
0x558757ecc580]
debug 2021-08-21T04:23:01.118+0000 7f2f47eb9700 7 mds.0.locker
simple_lock on (isnap sync) on [inode 0x100001be68f [...c,head]
/testfolder/ auth v1035687 ap=1 f() n(v0 1=0+1) (ifile excl) (iversion
lock) caps={974668=pAsLsXsFsx/AsLsXsFsx@
38},l=974668 | request=0 lock=0 dirfrag=1 caps=1 waiter=0 authpin=1
0x558757ecc580]
debug 2021-08-21T04:23:01.118+0000 7f2f47eb9700 7 mds.0.locker
simple_xlock on (isnap lock) on [inode 0x100001be68f [...c,head]
/testfolder/ auth v1035687 ap=1 f() n(v0 1=0+1) (isnap lock) (ifile
excl) (iversion lock) caps={974668=pAsLsXs
Fsx/AsLsXsFsx@38},l=974668 | request=1 lock=0 dirfrag=1 caps=1 waiter=0
authpin=1 0x558757ecc580]
debug 2021-08-21T04:23:01.118+0000 7f2f47eb9700 10
mds.0.cache.ino(0x100001be68f) auth_pin by 0x558757ecc8e8 on [inode
0x100001be68f [...c,head] /testfolder/ auth v1035687 ap=2 f() n(v0
1=0+1) (isnap lock) (ifile excl) (iversion lock)
caps={974668=pAsLsXsFsx/AsLsXsFsx@38},l=974668 | request=1 lock=0
dirfrag=1 caps=1 waiter=0 authpin=1 0x558757ecc580] now 2
debug 2021-08-21T04:23:01.118+0000 7f2f47eb9700 15 mds.0.cache.dir(0x1)
adjust_nested_auth_pins 1 on [dir 0x1 / [2,head] auth v=1048982
cv=1048871/1048871 dir_auth=0 ap=0+2 state=1610874881|complete f(v0
m2021-08-20T11:10:36.706227+0000 7=0+7) n(v60138
rc2106-02-06T09:40:08.000000+0000 b89832201935102
1775959=1579958+196001) hs=7+0,ss=0+0 dirty=2 | child=1 subtree=1
subtreetemp=0 dirty=1 waiter=0 authpin=0 0x558749665600] by
0x558757ecc580 count now 0/2
debug 2021-08-21T04:23:01.118+0000 7f2f47eb9700 10 mds.0.locker got
xlock on (isnap xlock x=1 by 0x55876b680800) [inode 0x100001be68f
[...c,head] /testfolder/ auth v1035687 ap=2 f() n(v0 1=0+1) (isnap xlock
x=1 by 0x55876b680800) (ifile excl) (iversion lock)
caps={974668=pAsLsXsFsx/AsLsXsFsx@38},l=974668 | request=1 lock=1
dirfrag=1 caps=1 waiter=0 authpin=1 0x558757ecc580]
debug 2021-08-21T04:23:01.118+0000 7f2f47eb9700 7 mds.0.locker
local_wrlock_start on (iversion lock) on [inode 0x100001be68f
[...c,head] /testfolder/ auth v1035687 ap=2 f() n(v0 1=0+1) (isnap xlock
x=1 by 0x55876b680800) (ifile excl) (iversion lock)
caps={974668=pAsLsXsFsx/AsLsXsFsx@38},l=974668 | request=1 lock=1
dirfrag=1 caps=1 waiter=0 authpin=1 0x558757ecc580]
debug 2021-08-21T04:23:01.118+0000 7f2f47eb9700 10 mds.0.locker got
wrlock on (iversion lock w=1 last_client=974668) [inode 0x100001be68f
[...c,head] /testfolder/ auth v1035687 ap=2 f() n(v0 1=0+1) (isnap xlock
x=1 by 0x55876b680800) (ifile excl) (iversion lock w=1
last_client=974668) caps={974668=pAsLsXsFsx/AsLsXsFsx@38},l=974668 |
request=1 lock=2 dirfrag=1 caps=1 waiter=0 authpin=1 0x558757ecc580]
debug 2021-08-21T04:23:01.118+0000 7f2f47eb9700 10 mds.0.locker
try_rdlock_snap_layout request(client.974668:50 nref=3
cr=0x55875013fb80) [inode 0x1 [...21,head] / auth v474681
snaprealm=0x55874abc0600 f(v0 m2021-08-20T11:10:36.706227+0000 7=0+7)
n(v60138 rc2106-02-06T09:40:08.000000+0000 b89832201935102 rs17
1775960=1579958+196002)/n(v0 rc2021-07-14T17:15:30.300918+0000 1=0+1)
old_inodes=18 (isnap sync r=5) (inest lock dirty) (ipolicy sync r=2)
(iversion lock) caps={974668=pAsLsXsFs/AsLsXsFsx@6} | dirtyscattered=1
request=0 lock=2 dirfrag=1 caps=1 openingsnapparents=0 dirty=1 authpin=0
0x55874abc4b00]
debug 2021-08-21T04:23:01.118+0000 7f2f47eb9700 20 mds.0.locker got
rdlock on (isnap sync r=6) [inode 0x1 [...21,head] / auth v474681
snaprealm=0x55874abc0600 f(v0 m2021-08-20T11:10:36.706227+0000 7=0+7)
n(v60138 rc2106-02-06T09:40:08.000000+0000 b89832201935102 rs17
1775960=1579958+196002)/n(v0 rc2021-07-14T17:15:30.300918+0000 1=0+1)
old_inodes=18 (isnap sync r=6) (inest lock dirty) (ipolicy sync r=2)
(iversion lock) caps={974668=pAsLsXsFs/AsLsXsFsx@6} | dirtyscattered=1
request=0 lock=2 dirfrag=1 caps=1 openingsnapparents=0 dirty=1 authpin=0
0x55874abc4b00]
debug 2021-08-21T04:23:01.118+0000 7f2f47eb9700 20 Session check_access
path /testfolder
debug 2021-08-21T04:23:01.118+0000 7f2f47eb9700 10 MDSAuthCap is_capable
inode(path /testfolder owner 0:0 mode 040755) by caller 0:0 mask 130 new
0:0 cap: MDSAuthCaps[allow *]
debug 2021-08-21T04:23:01.118+0000 7f2f47eb9700 7 mds.0.server
reply_client_request -1 ((1) Operation not permitted)
client_request(client.974668:50 mksnap
#0x100001be68f//testsnapshotincreasedlogging
2021-08-21T04:23:01.124841+0000 caller_uid=0, caller_gid=0{}) v2
----SNIP----
Please let me know if any additional information would be helpful.
Thank you,
-David
--
David Prude
Systems Administrator
PGP Fingerprint: 1DAA 4418 7F7F B8AA F50C 6FDF C294 B58F A286 F847
Democracy Now!
www.democracynow.org
_______________________________________________
ceph-users mailing list -- ceph-users@xxxxxxx
To unsubscribe send an email to ceph-users-leave@xxxxxxx
