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]