Here, we enable mds debug logging into stdout
ceph tell mds.gml-okd-cephfs-a config set debug_mds 20/0
...
debug 2023-02-16T09:49:56.265+0000 7f0462329700 10 mds.0.server reply to stat
on client_request(client.66426408:170 lookup
#0x10000000001/csi-vol-91510028-3e45-11ec-9461-0a580a82014a
2023-02-16T09:49:56.266338+0000 caller_uid=0, caller_gid=0{}) v5
debug 2023-02-16T09:49:56.265+0000 7f0462329700 20 mds.0.server
respond_to_request batch head request(client.66426408:170 nref=3
cr=0x558f9a150580)
debug 2023-02-16T09:49:56.265+0000 7f0462329700 20 respond: responding to batch
ops with result=0: [batch front=request(client.66426408:170 nref=3
cr=0x558f9a150580)]
debug 2023-02-16T09:49:56.265+0000 7f0462329700 7 mds.0.server
reply_client_request 0 ((0) Success) client_request(client.66426408:170 lookup
#0x10000000001/csi-vol-91510028-3e45-11ec-9461-0a580a82014a
2023-02-16T09:49:56.266338+0000 caller_uid=0, caller_gid=0{}) v5
debug 2023-02-16T09:49:56.265+0000 7f0462329700 10 mds.0.server
apply_allocated_inos 0x0 / [] / 0x0
debug 2023-02-16T09:49:56.265+0000 7f0462329700 20 mds.0.server lat 0.000551
debug 2023-02-16T09:49:56.265+0000 7f0462329700 20 mds.0.server set_trace_dist
snapid head
debug 2023-02-16T09:49:56.265+0000 7f0462329700 10 mds.0.server set_trace_dist
snaprealm snaprealm(0x10001be180e seq 1 lc 0 cr 1 cps 2 snaps={}
past_parent_snaps= 0x558f9982a200) len=96
debug 2023-02-16T09:49:56.265+0000 7f0462329700 20
mds.0.cache.ino(0x10000000001) pfile 0 pauth 0 plink 0 pxattr 0 plocal 0 ctime
2022-12-26T14:29:05.859667+0000 valid=1
debug 2023-02-16T09:49:56.265+0000 7f0462329700 10
mds.0.cache.ino(0x10000000001) encode_inodestat issuing pAsLsXsFs seq 56
debug 2023-02-16T09:49:56.265+0000 7f0462329700 10
mds.0.cache.ino(0x10000000001) encode_inodestat caps pAsLsXsFs seq 56 mseq 0
xattrv 0
debug 2023-02-16T09:49:56.265+0000 7f0462329700 20 mds.0.server set_trace_dist
added diri [inode 0x10000000001 [...c,head] /volumes/csi/ auth v119902405 f(v0
m2022-12-26T14:29:05.859667+0000 125=3+122) n(v9165118
rc2023-01-03T22:32:29.158670+0000 b264347773624 1549126=1354219+194907)
old_inodes=1 (isnap sync r=1) (iversion lock) caps={66426408=pAsLsXsFs/-@56} |
request=0 lock=1 dirfrag=1 caps=1 dirty=1 authpin=0 0x558f99801600]
debug 2023-02-16T09:49:56.265+0000 7f0462329700 20 mds.0.server set_trace_dist
added dir [dir 0x10000000001 /volumes/csi/ [2,head] auth v=400540078
cv=400540078/400540078 ap=0+2 state=1074003969|complete f(v0
m2022-12-26T14:29:05.859667+0000 125=3+122) n(v9165118
rc2023-01-03T22:32:29.158670+0000 b264347773624 1549125=1354219+194906)
hs=125+0,ss=0+0 | child=1 waiter=0 authpin=0 0x558f9aa22d80]
debug 2023-02-16T09:49:56.265+0000 7f0462329700 20 mds.0.locker
issue_client_lease no/null lease on [dentry
#0x1/volumes/csi/csi-vol-91510028-3e45-11ec-9461-0a580a82014a [2,head] auth (dn
sync r=1) (dversion lock) pv=0 v=400540078 ap=1 ino=0x10001be180e
state=1073741824 | request=1 lock=1 inodepin=1 authpin=1 0x558f99828780]
debug 2023-02-16T09:49:56.265+0000 7f0462329700 20 mds.0.server set_trace_dist
added dn head [dentry
#0x1/volumes/csi/csi-vol-91510028-3e45-11ec-9461-0a580a82014a [2,head] auth (dn
sync r=1) (dversion lock) pv=0 v=400540078 ap=1 ino=0x10001be180e
state=1073741824 | request=1 lock=1 inodepin=1 authpin=1 0x558f99828780]
debug 2023-02-16T09:49:56.265+0000 7f0462329700 20
mds.0.cache.ino(0x10001be180e) pfile 0 pauth 0 plink 0 pxattr 0 plocal 0 ctime
2021-11-05T14:35:05.441183+0000 valid=1
debug 2023-02-16T09:49:56.265+0000 7f0462329700 10
mds.0.cache.ino(0x10001be180e) add_client_cap first cap, joining realm
snaprealm(0x10001be180e seq 1 lc 0 cr 1 cps 2 snaps={} past_parent_snaps=
0x558f9982a200)
debug 2023-02-16T09:49:56.265+0000 7f0462329700 10
mds.0.cache.ino(0x10001be180e) encode_inodestat issuing pAsLsXsFs seq 1
debug 2023-02-16T09:49:56.265+0000 7f0462329700 10
mds.0.cache.ino(0x10001be180e) encode_inodestat caps pAsLsXsFs seq 1 mseq 0
xattrv 1
debug 2023-02-16T09:49:56.265+0000 7f0462329700 10
mds.0.cache.ino(0x10001be180e) including xattrs version 1
debug 2023-02-16T09:49:56.265+0000 7f0462329700 20 mds.0.server set_trace_dist
added in [inode 0x10001be180e [...2,head]
/volumes/csi/csi-vol-91510028-3e45-11ec-9461-0a580a82014a/ auth v388627147 ap=1
snaprealm=0x558f9982a200 f(v0 m2021-11-05T14:35:05.441183+0000 2=1+1) n(v29796
rc2022-12-21T19:28:27.124662+0000 b57179 36=24+12) (iauth sync r=1) (ilink sync
r=1) (isnap sync r=1) (ifile sync r=1) (ixattr sync r=1) (iversion lock)
caps={66426408=pAsLsXsFs/-@1} | request=1 lock=5 dirfrag=1 caps=1
openingsnapparents=0 authpin=1 0x558f99825b80]
debug 2023-02-16T09:49:56.265+0000 7f0462329700 10 mds.0.350627
send_message_client client.66426408 10.25.1.17:0/1669277120
client_reply(???:170 = 0 (0) Success) v1
debug 2023-02-16T09:49:56.265+0000 7f0462329700 7 mds.0.cache request_finish
request(client.66426408:170 nref=3 cr=0x558f9a150580)
debug 2023-02-16T09:49:56.265+0000 7f0462329700 15 mds.0.cache request_cleanup
request(client.66426408:170 nref=3 cr=0x558f9a150580)
debug 2023-02-16T09:49:56.265+0000 7f0462329700 7 mds.0.locker rdlock_finish
on (isnap sync) on [inode 0x1 [...2,head] / auth v5 snaprealm=0x558f9859d800
f(v1 m2021-07-31T21:13:24.403917+0000 3=0+3) n(v3
rc2023-01-03T22:32:29.158670+0000 b264347801454 1549251=1354337+194914)/n()
(iversion lock) caps={66426408=pAsLsXsFs/-@2} | request=0 lock=0 dirfrag=1
caps=1 openingsnapparents=0 dirty=1 authpin=0 0x558f99800b00]
debug 2023-02-16T09:49:56.265+0000 7f0462329700 10 mds.0.locker simple_eval
(isnap sync) on [inode 0x1 [...2,head] / auth v5 snaprealm=0x558f9859d800 f(v1
m2021-07-31T21:13:24.403917+0000 3=0+3) n(v3 rc2023-01-03T22:32:29.158670+0000
b264347801454 1549251=1354337+194914)/n() (iversion lock)
caps={66426408=pAsLsXsFs/-@2} | request=0 lock=0 dirfrag=1 caps=1
openingsnapparents=0 dirty=1 authpin=0 0x558f99800b00]
debug 2023-02-16T09:49:56.265+0000 7f0462329700 7 mds.0.locker rdlock_finish
on (isnap sync) on [inode 0x10000000000 [...c,head] /volumes/ auth v94872546
f(v0 m2022-12-26T14:29:06.030099+0000 119=116+3) n(v8702956
rc2023-01-03T22:32:29.158670+0000 b264347773624 1549246=1354335+194911)
old_inodes=1 (iversion lock) caps={66426408=pAsLsXsFs/-@2} | request=0 lock=0
dirfrag=1 caps=1 dirty=1 authpin=0 0x558f99801080]
debug 2023-02-16T09:49:56.265+0000 7f0462329700 10 mds.0.locker simple_eval
(isnap sync) on [inode 0x10000000000 [...c,head] /volumes/ auth v94872546 f(v0
m2022-12-26T14:29:06.030099+0000 119=116+3) n(v8702956
rc2023-01-03T22:32:29.158670+0000 b264347773624 1549246=1354335+194911)
old_inodes=1 (iversion lock) caps={66426408=pAsLsXsFs/-@2} | request=0 lock=0
dirfrag=1 caps=1 dirty=1 authpin=0 0x558f99801080]
debug 2023-02-16T09:49:56.265+0000 7f0462329700 7 mds.0.locker rdlock_finish
on (isnap sync) on [inode 0x10000000001 [...c,head] /volumes/csi/ auth
v119902405 f(v0 m2022-12-26T14:29:05.859667+0000 125=3+122) n(v9165118
rc2023-01-03T22:32:29.158670+0000 b264347773624 1549126=1354219+194907)
old_inodes=1 (iversion lock) caps={66426408=pAsLsXsFs/-@56} | request=0 lock=0
dirfrag=1 caps=1 dirty=1 authpin=0 0x558f99801600]
debug 2023-02-16T09:49:56.265+0000 7f0462329700 10 mds.0.locker simple_eval
(isnap sync) on [inode 0x10000000001 [...c,head] /volumes/csi/ auth v119902405
f(v0 m2022-12-26T14:29:05.859667+0000 125=3+122) n(v9165118
rc2023-01-03T22:32:29.158670+0000 b264347773624 1549126=1354219+194907)
old_inodes=1 (iversion lock) caps={66426408=pAsLsXsFs/-@56} | request=0 lock=0
dirfrag=1 caps=1 dirty=1 authpin=0 0x558f99801600]
debug 2023-02-16T09:49:56.265+0000 7f0462329700 7 mds.0.locker rdlock_finish
on (iauth sync) on [inode 0x10001be180e [...2,head]
/volumes/csi/csi-vol-91510028-3e45-11ec-9461-0a580a82014a/ auth v388627147 ap=1
snaprealm=0x558f9982a200 f(v0 m2021-11-05T14:35:05.441183+0000 2=1+1) n(v29796
rc2022-12-21T19:28:27.124662+0000 b57179 36=24+12) (ilink sync r=1) (isnap sync
r=1) (ifile sync r=1) (ixattr sync r=1) (iversion lock)
caps={66426408=pAsLsXsFs/-@1} | request=1 lock=4 dirfrag=1 caps=1
openingsnapparents=0 authpin=1 0x558f99825b80]
debug 2023-02-16T09:49:56.265+0000 7f0462329700 10 mds.0.locker simple_eval
(iauth sync) on [inode 0x10001be180e [...2,head]
/volumes/csi/csi-vol-91510028-3e45-11ec-9461-0a580a82014a/ auth v388627147 ap=1
snaprealm=0x558f9982a200 f(v0 m2021-11-05T14:35:05.441183+0000 2=1+1) n(v29796
rc2022-12-21T19:28:27.124662+0000 b57179 36=24+12) (ilink sync r=1) (isnap sync
r=1) (ifile sync r=1) (ixattr sync r=1) (iversion lock)
caps={66426408=pAsLsXsFs/-@1} | request=1 lock=4 dirfrag=1 caps=1
openingsnapparents=0 authpin=1 0x558f99825b80]
debug 2023-02-16T09:49:56.265+0000 7f0462329700 7 mds.0.locker rdlock_finish
on (ilink sync) on [inode 0x10001be180e [...2,head]
/volumes/csi/csi-vol-91510028-3e45-11ec-9461-0a580a82014a/ auth v388627147 ap=1
snaprealm=0x558f9982a200 f(v0 m2021-11-05T14:35:05.441183+0000 2=1+1) n(v29796
rc2022-12-21T19:28:27.124662+0000 b57179 36=24+12) (isnap sync r=1) (ifile sync
r=1) (ixattr sync r=1) (iversion lock) caps={66426408=pAsLsXsFs/-@1} |
request=1 lock=3 dirfrag=1 caps=1 openingsnapparents=0 authpin=1 0x558f99825b80]
debug 2023-02-16T09:49:56.265+0000 7f0462329700 10 mds.0.locker simple_eval
(ilink sync) on [inode 0x10001be180e [...2,head]
/volumes/csi/csi-vol-91510028-3e45-11ec-9461-0a580a82014a/ auth v388627147 ap=1
snaprealm=0x558f9982a200 f(v0 m2021-11-05T14:35:05.441183+0000 2=1+1) n(v29796
rc2022-12-21T19:28:27.124662+0000 b57179 36=24+12) (isnap sync r=1) (ifile sync
r=1) (ixattr sync r=1) (iversion lock) caps={66426408=pAsLsXsFs/-@1} |
request=1 lock=3 dirfrag=1 caps=1 openingsnapparents=0 authpin=1 0x558f99825b80]
debug 2023-02-16T09:49:56.265+0000 7f0462329700 7 mds.0.locker rdlock_finish
on (ifile sync) on [inode 0x10001be180e [...2,head]
/volumes/csi/csi-vol-91510028-3e45-11ec-9461-0a580a82014a/ auth v388627147 ap=1
snaprealm=0x558f9982a200 f(v0 m2021-11-05T14:35:05.441183+0000 2=1+1) n(v29796
rc2022-12-21T19:28:27.124662+0000 b57179 36=24+12) (isnap sync r=1) (ixattr
sync r=1) (iversion lock) caps={66426408=pAsLsXsFs/-@1} | request=1 lock=2
dirfrag=1 caps=1 openingsnapparents=0 authpin=1 0x558f99825b80]
debug 2023-02-16T09:49:56.265+0000 7f0462329700 7 mds.0.locker file_eval
wanted= loner_wanted= other_wanted= filelock=(ifile sync) on [inode
0x10001be180e [...2,head]
/volumes/csi/csi-vol-91510028-3e45-11ec-9461-0a580a82014a/ auth v388627147 ap=1
snaprealm=0x558f9982a200 f(v0 m2021-11-05T14:35:05.441183+0000 2=1+1) n(v29796
rc2022-12-21T19:28:27.124662+0000 b57179 36=24+12) (isnap sync r=1) (ixattr
sync r=1) (iversion lock) caps={66426408=pAsLsXsFs/-@1} | request=1 lock=2
dirfrag=1 caps=1 openingsnapparents=0 authpin=1 0x558f99825b80]
debug 2023-02-16T09:49:56.265+0000 7f0462329700 7 mds.0.locker rdlock_finish
on (ixattr sync) on [inode 0x10001be180e [...2,head]
/volumes/csi/csi-vol-91510028-3e45-11ec-9461-0a580a82014a/ auth v388627147 ap=1
snaprealm=0x558f9982a200 f(v0 m2021-11-05T14:35:05.441183+0000 2=1+1) n(v29796
rc2022-12-21T19:28:27.124662+0000 b57179 36=24+12) (isnap sync r=1) (iversion
lock) caps={66426408=pAsLsXsFs/-@1} | request=1 lock=1 dirfrag=1 caps=1
openingsnapparents=0 authpin=1 0x558f99825b80]
debug 2023-02-16T09:49:56.265+0000 7f0462329700 10 mds.0.locker simple_eval
(ixattr sync) on [inode 0x10001be180e [...2,head]
/volumes/csi/csi-vol-91510028-3e45-11ec-9461-0a580a82014a/ auth v388627147 ap=1
snaprealm=0x558f9982a200 f(v0 m2021-11-05T14:35:05.441183+0000 2=1+1) n(v29796
rc2022-12-21T19:28:27.124662+0000 b57179 36=24+12) (isnap sync r=1) (iversion
lock) caps={66426408=pAsLsXsFs/-@1} | request=1 lock=1 dirfrag=1 caps=1
openingsnapparents=0 authpin=1 0x558f99825b80]
debug 2023-02-16T09:49:56.265+0000 7f0462329700 7 mds.0.locker rdlock_finish
on (isnap sync) on [inode 0x10001be180e [...2,head]
/volumes/csi/csi-vol-91510028-3e45-11ec-9461-0a580a82014a/ auth v388627147 ap=1
snaprealm=0x558f9982a200 f(v0 m2021-11-05T14:35:05.441183+0000 2=1+1) n(v29796
rc2022-12-21T19:28:27.124662+0000 b57179 36=24+12) (iversion lock)
caps={66426408=pAsLsXsFs/-@1} | request=1 lock=0 dirfrag=1 caps=1
openingsnapparents=0 authpin=1 0x558f99825b80]
debug 2023-02-16T09:49:56.265+0000 7f0462329700 10 mds.0.locker simple_eval
(isnap sync) on [inode 0x10001be180e [...2,head]
/volumes/csi/csi-vol-91510028-3e45-11ec-9461-0a580a82014a/ auth v388627147 ap=1
snaprealm=0x558f9982a200 f(v0 m2021-11-05T14:35:05.441183+0000 2=1+1) n(v29796
rc2022-12-21T19:28:27.124662+0000 b57179 36=24+12) (iversion lock)
caps={66426408=pAsLsXsFs/-@1} | request=1 lock=0 dirfrag=1 caps=1
openingsnapparents=0 authpin=1 0x558f99825b80]
debug 2023-02-16T09:49:56.265+0000 7f0462329700 7 mds.0.locker rdlock_finish
on (dn sync) on [dentry
#0x1/volumes/csi/csi-vol-91510028-3e45-11ec-9461-0a580a82014a [2,head] auth
(dversion lock) pv=0 v=400540078 ap=1 ino=0x10001be180e state=1073741824 |
request=1 lock=0 inodepin=1 authpin=1 0x558f99828780]
debug 2023-02-16T09:49:56.265+0000 7f0462329700 10 mds.0.locker simple_eval (dn
sync) on [dentry #0x1/volumes/csi/csi-vol-91510028-3e45-11ec-9461-0a580a82014a
[2,head] auth (dversion lock) pv=0 v=400540078 ap=1 ino=0x10001be180e
state=1073741824 | request=1 lock=0 inodepin=1 authpin=1 0x558f99828780]
debug 2023-02-16T09:49:56.265+0000 7f0462329700 10
mds.0.cache.ino(0x10001be180e) auth_unpin by 0x558f9aa3fc00 on [inode
0x10001be180e [...2,head]
/volumes/csi/csi-vol-91510028-3e45-11ec-9461-0a580a82014a/ auth v388627147
snaprealm=0x558f9982a200 f(v0 m2021-11-05T14:35:05.441183+0000 2=1+1) n(v29796
rc2022-12-21T19:28:27.124662+0000 b57179 36=24+12) (iversion lock)
caps={66426408=pAsLsXsFs/-@1} | request=1 lock=0 dirfrag=1 caps=1
openingsnapparents=0 authpin=0 0x558f99825b80] now 0
debug 2023-02-16T09:49:56.265+0000 7f0462329700 15
mds.0.cache.dir(0x10000000001) adjust_nested_auth_pins -1 on [dir 0x10000000001
/volumes/csi/ [2,head] auth v=400540078 cv=400540078/400540078 ap=0+1
state=1074003969|complete f(v0 m2022-12-26T14:29:05.859667+0000 125=3+122)
n(v9165118 rc2023-01-03T22:32:29.158670+0000 b264347773624
1549125=1354219+194906) hs=125+0,ss=0+0 | child=1 waiter=0 authpin=0
0x558f9aa22d80] by 0x558f9aa3fc00 count now 0/1
debug 2023-02-16T09:49:56.265+0000 7f0462329700 10
mds.0.cache.den(0x10000000001 csi-vol-91510028-3e45-11ec-9461-0a580a82014a)
auth_unpin by 0x558f9aa3fc00 on [dentry
#0x1/volumes/csi/csi-vol-91510028-3e45-11ec-9461-0a580a82014a [2,head] auth
(dversion lock) pv=0 v=400540078 ino=0x10001be180e state=1073741824 | request=1
lock=0 inodepin=1 authpin=0 0x558f99828780] now 0
debug 2023-02-16T09:49:56.265+0000 7f0462329700 15
mds.0.cache.dir(0x10000000001) adjust_nested_auth_pins -1 on [dir 0x10000000001
/volumes/csi/ [2,head] auth v=400540078 cv=400540078/400540078
state=1074003969|complete f(v0 m2022-12-26T14:29:05.859667+0000 125=3+122)
n(v9165118 rc2023-01-03T22:32:29.158670+0000 b264347773624
1549125=1354219+194906) hs=125+0,ss=0+0 | child=1 waiter=0 authpin=0
0x558f9aa22d80] by 0x558f9aa3fc00 count now 0/0
debug 2023-02-16T09:49:56.266+0000 7f0462329700 4 mds.0.server
handle_client_request client_request(client.66426408:171 lookup
#0x10001be180e/.meta 2023-02-16T09:49:56.268272+0000 caller_uid=0,
caller_gid=0{}) v5
debug 2023-02-16T09:49:56.266+0000 7f0462329700 20 mds.0.350627 get_session
have 0x558f98893900 client.66426408 10.25.1.17:0/1669277120 state open
debug 2023-02-16T09:49:56.266+0000 7f0462329700 15 mds.0.server
oldest_client_tid=170
debug 2023-02-16T09:49:56.266+0000 7f0462329700 7 mds.0.cache request_start
request(client.66426408:171 nref=2 cr=0x558f9a150840)
debug 2023-02-16T09:49:56.266+0000 7f0462329700 7 mds.0.server
dispatch_client_request client_request(client.66426408:171 lookup
#0x10001be180e/.meta 2023-02-16T09:49:56.268272+0000 caller_uid=0,
caller_gid=0{}) v5
debug 2023-02-16T09:49:56.266+0000 7f0462329700 7 mds.0.cache traverse:
opening base ino 0x10001be180e snap head
debug 2023-02-16T09:49:56.266+0000 7f0462329700 12 mds.0.cache traverse: path
seg depth 0 '.meta' snapid head
debug 2023-02-16T09:49:56.266+0000 7f0462329700 20
mds.0.cache.dir(0x10001be180e) lookup (head, '.meta')
debug 2023-02-16T09:49:56.266+0000 7f0462329700 20
mds.0.cache.dir(0x10001be180e) hit -> (.meta,head)
debug 2023-02-16T09:49:56.266+0000 7f0462329700 10 mds.0.cache path_traverse
finish on snapid head
debug 2023-02-16T09:49:56.266+0000 7f0462329700 10 mds.0.server
rdlock_path_pin_ref request(client.66426408:171 nref=3 cr=0x558f9a150840)
#0x10001be180e/.meta
debug 2023-02-16T09:49:56.266+0000 7f0462329700 7 mds.0.cache traverse:
opening base ino 0x10001be180e snap head
debug 2023-02-16T09:49:56.266+0000 7f0462329700 10 mds.0.locker
try_rdlock_snap_layout request(client.66426408:171 nref=4 cr=0x558f9a150840)
[inode 0x10001be180e [...2,head]
/volumes/csi/csi-vol-91510028-3e45-11ec-9461-0a580a82014a/ auth v388627147
snaprealm=0x558f9982a200 f(v0 m2021-11-05T14:35:05.441183+0000 2=1+1) n(v29796
rc2022-12-21T19:28:27.124662+0000 b57179 36=24+12) (iversion lock)
caps={66426408=pAsLsXsFs/-@1} | request=0 lock=0 dirfrag=1 caps=1
openingsnapparents=0 authpin=0 0x558f99825b80]
debug 2023-02-16T09:49:56.266+0000 7f0462329700 20 mds.0.locker got rdlock on
(isnap sync r=1) [inode 0x10001be180e [...2,head]
/volumes/csi/csi-vol-91510028-3e45-11ec-9461-0a580a82014a/ auth v388627147
snaprealm=0x558f9982a200 f(v0 m2021-11-05T14:35:05.441183+0000 2=1+1) n(v29796
rc2022-12-21T19:28:27.124662+0000 b57179 36=24+12) (isnap sync r=1) (iversion
lock) caps={66426408=pAsLsXsFs/-@1} | request=0 lock=1 dirfrag=1 caps=1
openingsnapparents=0 authpin=0 0x558f99825b80]
debug 2023-02-16T09:49:56.266+0000 7f0462329700 20 mds.0.locker got rdlock on
(isnap sync r=1) [inode 0x10000000001 [...c,head] /volumes/csi/ auth v119902405
f(v0 m2022-12-26T14:29:05.859667+0000 125=3+122) n(v9165118
rc2023-01-03T22:32:29.158670+0000 b264347773624 1549126=1354219+194907)
old_inodes=1 (isnap sync r=1) (iversion lock) caps={66426408=pAsLsXsFs/-@56} |
request=0 lock=1 dirfrag=1 caps=1 dirty=1 authpin=0 0x558f99801600]
debug 2023-02-16T09:49:56.266+0000 7f0462329700 20 mds.0.locker got rdlock on
(isnap sync r=1) [inode 0x10000000000 [...c,head] /volumes/ auth v94872546 f(v0
m2022-12-26T14:29:06.030099+0000 119=116+3) n(v8702956
rc2023-01-03T22:32:29.158670+0000 b264347773624 1549246=1354335+194911)
old_inodes=1 (isnap sync r=1) (iversion lock) caps={66426408=pAsLsXsFs/-@2} |
request=0 lock=1 dirfrag=1 caps=1 dirty=1 authpin=0 0x558f99801080]
debug 2023-02-16T09:49:56.266+0000 7f0462329700 20 mds.0.locker got rdlock on
(isnap sync r=1) [inode 0x1 [...2,head] / auth v5 snaprealm=0x558f9859d800 f(v1
m2021-07-31T21:13:24.403917+0000 3=0+3) n(v3 rc2023-01-03T22:32:29.158670+0000
b264347801454 1549251=1354337+194914)/n() (isnap sync r=1) (iversion lock)
caps={66426408=pAsLsXsFs/-@2} | request=0 lock=1 dirfrag=1 caps=1
openingsnapparents=0 dirty=1 authpin=0 0x558f99800b00]
debug 2023-02-16T09:49:56.266+0000 7f0462329700 12 mds.0.cache traverse: path
seg depth 0 '.meta' snapid head
debug 2023-02-16T09:49:56.266+0000 7f0462329700 20
mds.0.cache.dir(0x10001be180e) lookup (head, '.meta')
debug 2023-02-16T09:49:56.266+0000 7f0462329700 20
mds.0.cache.dir(0x10001be180e) hit -> (.meta,head)
debug 2023-02-16T09:49:56.266+0000 7f0462329700 10 mds.0.locker acquire_locks
request(client.66426408:171 nref=4 cr=0x558f9a150840)
debug 2023-02-16T09:49:56.266+0000 7f0462329700 20 mds.0.locker must rdlock
(dn sync) [dentry
#0x1/volumes/csi/csi-vol-91510028-3e45-11ec-9461-0a580a82014a/.meta [2,head]
auth (dversion lock) pv=0 v=192774 ino=0x10001be1810 state=1073741824 |
request=1 lock=0 inodepin=0 authpin=0 0x558f988d2a00]
debug 2023-02-16T09:49:56.266+0000 7f0462329700 10 mds.0.locker must authpin
[dentry #0x1/volumes/csi/csi-vol-91510028-3e45-11ec-9461-0a580a82014a/.meta
[2,head] auth (dversion lock) pv=0 v=192774 ino=0x10001be1810 state=1073741824
| request=1 lock=0 inodepin=0 authpin=0 0x558f988d2a00]
debug 2023-02-16T09:49:56.266+0000 7f0462329700 10 mds.0.locker auth_pinning
[dentry #0x1/volumes/csi/csi-vol-91510028-3e45-11ec-9461-0a580a82014a/.meta
[2,head] auth (dversion lock) pv=0 v=192774 ino=0x10001be1810 state=1073741824
| request=1 lock=0 inodepin=0 authpin=0 0x558f988d2a00]
debug 2023-02-16T09:49:56.266+0000 7f0462329700 10
mds.0.cache.den(0x10001be180e .meta) auth_pin by 0x558f9aa38000 on [dentry
#0x1/volumes/csi/csi-vol-91510028-3e45-11ec-9461-0a580a82014a/.meta [2,head]
auth (dversion lock) pv=0 v=192774 ap=1 ino=0x10001be1810 state=1073741824 |
request=1 lock=0 inodepin=0 authpin=1 0x558f988d2a00] now 1
debug 2023-02-16T09:49:56.266+0000 7f0462329700 15
mds.0.cache.dir(0x10001be180e) adjust_nested_auth_pins 1 on [dir 0x10001be180e
/volumes/csi/csi-vol-91510028-3e45-11ec-9461-0a580a82014a/ [2,head] auth
v=192774 cv=192774/192774 ap=0+1 state=1073741825|complete f(v0
m2021-11-05T14:35:05.441183+0000 2=1+1) n(v29796
rc2022-12-21T19:28:27.124662+0000 b57179 35=24+11) hs=2+0,ss=0+0 | child=1
waiter=0 authpin=0 0x558f98722480] by 0x558f9aa38000 count now 0/1
debug 2023-02-16T09:49:56.266+0000 7f0462329700 7 mds.0.locker rdlock_start
on (dn sync) on [dentry
#0x1/volumes/csi/csi-vol-91510028-3e45-11ec-9461-0a580a82014a/.meta [2,head]
auth (dversion lock) pv=0 v=192774 ap=1 ino=0x10001be1810 state=1073741824 |
request=1 lock=0 inodepin=0 authpin=1 0x558f988d2a00]
debug 2023-02-16T09:49:56.266+0000 7f0462329700 10 mds.0.locker got rdlock on
(dn sync r=1) [dentry
#0x1/volumes/csi/csi-vol-91510028-3e45-11ec-9461-0a580a82014a/.meta [2,head]
auth (dn sync r=1) (dversion lock) pv=0 v=192774 ap=1 ino=0x10001be1810
state=1073741824 | request=1 lock=1 inodepin=0 authpin=1 0x558f988d2a00]
debug 2023-02-16T09:49:56.266+0000 7f0462329700 10 mds.0.locker acquire_locks
request(client.66426408:171 nref=4 cr=0x558f9a150840)
debug 2023-02-16T09:49:56.266+0000 7f0462329700 20 mds.0.locker must rdlock
(isnap sync) [inode 0x10001be1810 [2,head]
/volumes/csi/csi-vol-91510028-3e45-11ec-9461-0a580a82014a/.meta auth v12 s=158
n(v0 rc2021-11-05T14:35:05.443099+0000 b158 1=1+0) (iversion lock)
0x558f988cf600]
debug 2023-02-16T09:49:56.266+0000 7f0462329700 10 mds.0.locker must authpin
[inode 0x10001be1810 [2,head]
/volumes/csi/csi-vol-91510028-3e45-11ec-9461-0a580a82014a/.meta auth v12 s=158
n(v0 rc2021-11-05T14:35:05.443099+0000 b158 1=1+0) (iversion lock)
0x558f988cf600]
debug 2023-02-16T09:49:56.266+0000 7f0462329700 10 mds.0.locker auth_pinning
[inode 0x10001be1810 [2,head]
/volumes/csi/csi-vol-91510028-3e45-11ec-9461-0a580a82014a/.meta auth v12 s=158
n(v0 rc2021-11-05T14:35:05.443099+0000 b158 1=1+0) (iversion lock)
0x558f988cf600]
debug 2023-02-16T09:49:56.266+0000 7f0462329700 10
mds.0.cache.ino(0x10001be1810) auth_pin by 0x558f9aa38000 on [inode
0x10001be1810 [2,head]
/volumes/csi/csi-vol-91510028-3e45-11ec-9461-0a580a82014a/.meta auth v12 ap=1
s=158 n(v0 rc2021-11-05T14:35:05.443099+0000 b158 1=1+0) (iversion lock) |
request=0 lock=0 caps=0 authpin=1 0x558f988cf600] now 1
debug 2023-02-16T09:49:56.266+0000 7f0462329700 15
mds.0.cache.dir(0x10001be180e) adjust_nested_auth_pins 1 on [dir 0x10001be180e
/volumes/csi/csi-vol-91510028-3e45-11ec-9461-0a580a82014a/ [2,head] auth
v=192774 cv=192774/192774 ap=0+2 state=1073741825|complete f(v0
m2021-11-05T14:35:05.441183+0000 2=1+1) n(v29796
rc2022-12-21T19:28:27.124662+0000 b57179 35=24+11) hs=2+0,ss=0+0 | child=1
waiter=0 authpin=0 0x558f98722480] by 0x558f988cf600 count now 0/2
debug 2023-02-16T09:49:56.266+0000 7f0462329700 7 mds.0.locker rdlock_start
on (isnap sync) on [inode 0x10001be1810 [2,head]
/volumes/csi/csi-vol-91510028-3e45-11ec-9461-0a580a82014a/.meta auth v12 ap=1
s=158 n(v0 rc2021-11-05T14:35:05.443099+0000 b158 1=1+0) (iversion lock) |
request=0 lock=0 caps=0 authpin=1 0x558f988cf600]
debug 2023-02-16T09:49:56.266+0000 7f0462329700 10 mds.0.locker got rdlock on
(isnap sync r=1) [inode 0x10001be1810 [2,head]
/volumes/csi/csi-vol-91510028-3e45-11ec-9461-0a580a82014a/.meta auth v12 ap=1
s=158 n(v0 rc2021-11-05T14:35:05.443099+0000 b158 1=1+0) (iversion lock) |
request=0 lock=1 caps=0 authpin=1 0x558f988cf600]
debug 2023-02-16T09:49:56.266+0000 7f0462329700 10 mds.0.cache path_traverse
finish on snapid head
debug 2023-02-16T09:49:56.266+0000 7f0462329700 10 mds.0.server ref is [inode
0x10001be1810 [2,head]
/volumes/csi/csi-vol-91510028-3e45-11ec-9461-0a580a82014a/.meta auth v12 ap=1
s=158 n(v0 rc2021-11-05T14:35:05.443099+0000 b158 1=1+0) (iversion lock) |
request=0 lock=1 caps=0 authpin=1 0x558f988cf600]
debug 2023-02-16T09:49:56.266+0000 7f0462329700 10 mds.0.locker acquire_locks
request(client.66426408:171 nref=3 cr=0x558f9a150840)
debug 2023-02-16T09:49:56.266+0000 7f0462329700 20 mds.0.locker must rdlock
(iauth sync) [inode 0x10001be1810 [2,head]
/volumes/csi/csi-vol-91510028-3e45-11ec-9461-0a580a82014a/.meta auth v12 ap=1
s=158 n(v0 rc2021-11-05T14:35:05.443099+0000 b158 1=1+0) (iversion lock) |
request=1 lock=1 caps=0 authpin=1 0x558f988cf600]
debug 2023-02-16T09:49:56.266+0000 7f0462329700 20 mds.0.locker must rdlock
(ifile sync) [inode 0x10001be1810 [2,head]
/volumes/csi/csi-vol-91510028-3e45-11ec-9461-0a580a82014a/.meta auth v12 ap=1
s=158 n(v0 rc2021-11-05T14:35:05.443099+0000 b158 1=1+0) (iversion lock) |
request=1 lock=1 caps=0 authpin=1 0x558f988cf600]
debug 2023-02-16T09:49:56.266+0000 7f0462329700 10 mds.0.locker must authpin
[inode 0x10001be1810 [2,head]
/volumes/csi/csi-vol-91510028-3e45-11ec-9461-0a580a82014a/.meta auth v12 ap=1
s=158 n(v0 rc2021-11-05T14:35:05.443099+0000 b158 1=1+0) (iversion lock) |
request=1 lock=1 caps=0 authpin=1 0x558f988cf600]
debug 2023-02-16T09:49:56.267+0000 7f0462329700 10 mds.0.locker already
auth_pinned [inode 0x10001be1810 [2,head]
/volumes/csi/csi-vol-91510028-3e45-11ec-9461-0a580a82014a/.meta auth v12 ap=1
s=158 n(v0 rc2021-11-05T14:35:05.443099+0000 b158 1=1+0) (iversion lock) |
request=1 lock=1 caps=0 authpin=1 0x558f988cf600]
debug 2023-02-16T09:49:56.267+0000 7f0462329700 7 mds.0.locker rdlock_start
on (ifile sync) on [inode 0x10001be1810 [2,head]
/volumes/csi/csi-vol-91510028-3e45-11ec-9461-0a580a82014a/.meta auth v12 ap=1
s=158 n(v0 rc2021-11-05T14:35:05.443099+0000 b158 1=1+0) (iversion lock) |
request=1 lock=1 caps=0 authpin=1 0x558f988cf600]
debug 2023-02-16T09:49:56.267+0000 7f0462329700 10 mds.0.locker got rdlock on
(ifile sync r=1) [inode 0x10001be1810 [2,head]
/volumes/csi/csi-vol-91510028-3e45-11ec-9461-0a580a82014a/.meta auth v12 ap=1
s=158 n(v0 rc2021-11-05T14:35:05.443099+0000 b158 1=1+0) (ifile sync r=1)
(iversion lock) | request=1 lock=2 caps=0 authpin=1 0x558f988cf600]
debug 2023-02-16T09:49:56.267+0000 7f0462329700 7 mds.0.locker rdlock_start
on (iauth sync) on [inode 0x10001be1810 [2,head]
/volumes/csi/csi-vol-91510028-3e45-11ec-9461-0a580a82014a/.meta auth v12 ap=1
s=158 n(v0 rc2021-11-05T14:35:05.443099+0000 b158 1=1+0) (ifile sync r=1)
(iversion lock) | request=1 lock=2 caps=0 authpin=1 0x558f988cf600]
debug 2023-02-16T09:49:56.267+0000 7f0462329700 10 mds.0.locker got rdlock on
(iauth sync r=1) [inode 0x10001be1810 [2,head]
/volumes/csi/csi-vol-91510028-3e45-11ec-9461-0a580a82014a/.meta auth v12 ap=1
s=158 n(v0 rc2021-11-05T14:35:05.443099+0000 b158 1=1+0) (iauth sync r=1)
(ifile sync r=1) (iversion lock) | request=1 lock=3 caps=0 authpin=1
0x558f988cf600]
debug 2023-02-16T09:49:56.267+0000 7f0462329700 20 Session check_access path
/volumes/csi/csi-vol-91510028-3e45-11ec-9461-0a580a82014a/.meta
debug 2023-02-16T09:49:56.267+0000 7f0462329700 10 MDSAuthCap is_capable
inode(path /volumes/csi/csi-vol-91510028-3e45-11ec-9461-0a580a82014a/.meta
owner 0:0 mode 0100640) by caller 0:0 mask 1 new 0:0 cap: MDSAuthCaps[allow *]
debug 2023-02-16T09:49:56.267+0000 7f0462329700 20 mds.0.bal hit_dir 0 pop is
1, frag * size 2 [pop IRD:[C 1.00e+00] IWR:[C 0.00e+00] RDR:[C 0.00e+00] FET:[C
0.00e+00] STR:[C 0.00e+00] *LOAD:1.0]
_______________________________________________
ceph-users mailing list -- ceph-users@ceph.io
To unsubscribe send an email to ceph-users-le...@ceph.io
