Bug #62052
Updated by Patrick Donnelly 10 months ago
During a lot of request contention for locks, it's possible for getattr to change the requested locks for the target inode if the filelock changes state. This optimization:
https://github.com/ceph/ceph/pull/20386/commits/c822b3e2573578c288d170d1031672b74e02dced#diff-277dc6e796ccecb6aa14c9357f7a86898d6ddcf4113c110a4e00e0a10f6fefa7R3048-R3055
If the filelock becomes unstable or the condition otherwise changes, the a read lock on the filelock will be added. The problem with doing this is that this can alter the inode lock order if the operation has acquired locks that normally follow the filelock acquisition. This can result in deadlock looking like:
<pre>
{
"description": "client_request(client.160517946:52928 getattr AsLsXsFs #0x1000033752e 2023-07-13T09:56:49.594318+0000 caller_uid=0, caller_gid=0{0,1,2,3,4,6,10,11,20,26,27,})",
"initiated_at": "2023-07-13T09:56:49.595649+0000",
"age": 23854.850265265,
"duration": 23854.947446915,
"type_data": {
"flag_point": "failed to rdlock, waiting",
"reqid": "client.160517946:52928",
"op_type": "client_request",
"client_info": {
"client": "client.160517946",
"tid": 52928
},
"events": [
{
"time": "2023-07-13T09:56:49.595649+0000",
"event": "initiated"
},
{
"time": "2023-07-13T09:56:49.595649+0000",
"event": "throttled"
},
{
"time": "2023-07-13T09:56:49.595649+0000",
"event": "header_read"
},
{
"time": "2023-07-13T09:56:49.595653+0000",
"event": "all_read"
},
{
"time": "2023-07-13T09:56:49.595671+0000",
"event": "dispatched"
},
{
"time": "2023-07-13T09:56:49.595685+0000",
"event": "failed to rdlock, waiting"
},
{
"time": "2023-07-13T09:56:49.834238+0000",
"event": "failed to rdlock, waiting"
},
{
"time": "2023-07-13T09:56:49.834669+0000",
"event": "failed to rdlock, waiting"
},
{
"time": "2023-07-13T09:56:49.835164+0000",
"event": "failed to rdlock, waiting"
},
{
"time": "2023-07-13T09:56:49.835380+0000",
"event": "failed to rdlock, waiting"
},
{
"time": "2023-07-13T09:56:50.150443+0000",
"event": "failed to rdlock, waiting"
}
]
}
},
{
"description": "client_request(client.161452256:598076 create #0x1000006fb46/file 2023-07-13T09:56:49.740019+0000 caller_uid=0, caller_gid=0{})",
"initiated_at": "2023-07-13T09:56:49.740519+0000",
"age": 23854.705395434,
"duration": 23854.736352394,
"type_data": {
"flag_point": "failed to rdlock, waiting",
"reqid": "client.161452256:598076",
"op_type": "client_request",
"client_info": {
"client": "client.161452256",
"tid": 598076
},
"events": [
{
"time": "2023-07-13T09:56:49.740519+0000",
"event": "initiated"
},
{
"time": "2023-07-13T09:56:49.740520+0000",
"event": "throttled"
},
{
"time": "2023-07-13T09:56:49.740519+0000",
"event": "header_read"
},
{
"time": "2023-07-13T09:56:49.740526+0000",
"event": "all_read"
},
{
"time": "2023-07-13T09:56:49.740563+0000",
"event": "dispatched"
},
{
"time": "2023-07-13T09:56:49.740707+0000",
"event": "failed to wrlock, waiting"
},
{
"time": "2023-07-13T09:56:49.744927+0000",
"event": "acquired locks"
},
{
"time": "2023-07-13T09:56:49.744932+0000",
"event": "acquired locks"
},
{
"time": "2023-07-13T09:56:49.745023+0000",
"event": "failed to xlock, waiting"
},
{
"time": "2023-07-13T09:56:49.834242+0000",
"event": "acquired locks"
},
{
"time": "2023-07-13T09:56:49.834245+0000",
"event": "failed to xlock, waiting"
},
{
"time": "2023-07-13T09:56:49.834742+0000",
"event": "acquired locks"
},
{
"time": "2023-07-13T09:56:49.834753+0000",
"event": "failed to xlock, waiting"
},
{
"time": "2023-07-13T09:56:49.835360+0000",
"event": "acquired locks"
},
{
"time": "2023-07-13T09:56:49.835378+0000",
"event": "failed to xlock, waiting"
},
{
"time": "2023-07-13T09:56:50.150399+0000",
"event": "acquired locks"
},
{
"time": "2023-07-13T09:56:50.150438+0000",
"event": "failed to rdlock, waiting"
}
]
}
},
</pre>
Here, the "create" RPC has acquired the filelock and is trying to obtain the authlock (not visible in the above debug output). MDS debug output that can correspond to this situation:
getattr step #1:
<pre>
2023-07-15T13:33:01.346-0400 7f2d8788f700 7 mds.0.server dispatch_client_request client_request(client.7205:24769 getattr AsLsXsFs #0x10000000001 2023-07-15T13:33:01.286827-0400 caller_uid=10000, caller_gid=100{10,100,}) v4
2023-07-15T13:33:01.346-0400 7f2d8788f700 10 mds.0.server rdlock_path_pin_ref request(client.7205:24769 nref=3 cr=0x56001bc23200) #0x10000000001
2023-07-15T13:33:01.346-0400 7f2d8788f700 10 mds.0.locker acquire_locks request(client.7205:24769 nref=3 cr=0x56001bc23200)
2023-07-15T13:33:01.346-0400 7f2d8788f700 20 mds.0.locker must rdlock (ilink sync) [inode 0x10000000001 [2,head] /bar/test auth v132334 ap=3 s=0 n(v0 rc2023-07-15T13:33:00.982044-0400 1=1+0) (iauth excl) (ifile lock->excl) (ixattr excl) (iversion lock) cr={13924=0-4194304@1} caps={7205=pLs/pLsFc/-@3,13924=pAsLsXsxFcb/pAsxXsxFxwb@12},l=13924 | ptrwaiter=0 request=1 lock=1 caps=1 truncating=0 dirtyparent=0 dirty=1 waiter=1 authpin=1 0x56001aeb1700]
2023-07-15T13:33:01.346-0400 7f2d8788f700 20 mds.0.locker must rdlock (iauth excl) [inode 0x10000000001 [2,head] /bar/test auth v132334 ap=3 s=0 n(v0 rc2023-07-15T13:33:00.982044-0400 1=1+0) (iauth excl) (ifile lock->excl) (ixattr excl) (iversion lock) cr={13924=0-4194304@1} caps={7205=pLs/pLsFc/-@3,13924=pAsLsXsxFcb/pAsxXsxFxwb@12},l=13924 | ptrwaiter=0 request=1 lock=1 caps=1 truncating=0 dirtyparent=0 dirty=1 waiter=1 authpin=1 0x56001aeb1700]
2023-07-15T13:33:01.346-0400 7f2d8788f700 20 mds.0.locker must rdlock (ixattr excl) [inode 0x10000000001 [2,head] /bar/test auth v132334 ap=3 s=0 n(v0 rc2023-07-15T13:33:00.982044-0400 1=1+0) (iauth excl) (ifile lock->excl) (ixattr excl) (iversion lock) cr={13924=0-4194304@1} caps={7205=pLs/pLsFc/-@3,13924=pAsLsXsxFcb/pAsxXsxFxwb@12},l=13924 | ptrwaiter=0 request=1 lock=1 caps=1 truncating=0 dirtyparent=0 dirty=1 waiter=1 authpin=1 0x56001aeb1700]
2023-07-15T13:33:01.346-0400 7f2d8788f700 10 mds.0.locker must authpin [inode 0x10000000001 [2,head] /bar/test auth v132334 ap=3 s=0 n(v0 rc2023-07-15T13:33:00.982044-0400 1=1+0) (iauth excl) (ifile lock->excl) (ixattr excl) (iversion lock) cr={13924=0-4194304@1} caps={7205=pLs/pLsFc/-@3,13924=pAsLsXsxFcb/pAsxXsxFxwb@12},l=13924 | ptrwaiter=0 request=1 lock=1 caps=1 truncating=0 dirtyparent=0 dirty=1 waiter=1 authpin=1 0x56001aeb1700]
2023-07-15T13:33:01.346-0400 7f2d8788f700 10 mds.0.locker already auth_pinned [inode 0x10000000001 [2,head] /bar/test auth v132334 ap=3 s=0 n(v0 rc2023-07-15T13:33:00.982044-0400 1=1+0) (iauth excl) (ifile lock->excl) (ixattr excl) (iversion lock) cr={13924=0-4194304@1} caps={7205=pLs/pLsFc/-@3,13924=pAsLsXsxFcb/pAsxXsxFxwb@12},l=13924 | ptrwaiter=0 request=1 lock=1 caps=1 truncating=0 dirtyparent=0 dirty=1 waiter=1 authpin=1 0x56001aeb1700]
2023-07-15T13:33:01.346-0400 7f2d8788f700 7 mds.0.locker rdlock_start on (iauth excl) on [inode 0x10000000001 [2,head] /bar/test auth v132334 ap=3 s=0 n(v0 rc2023-07-15T13:33:00.982044-0400 1=1+0) (iauth excl) (ifile lock->excl) (ixattr excl) (iversion lock) cr={13924=0-4194304@1} caps={7205=pLs/pLsFc/-@3,13924=pAsLsXsxFcb/pAsxXsxFxwb@12},l=13924 | ptrwaiter=0 request=1 lock=1 caps=1 truncating=0 dirtyparent=0 dirty=1 waiter=1 authpin=1 0x56001aeb1700]
2023-07-15T13:33:01.346-0400 7f2d8788f700 7 mds.0.locker simple_sync on (iauth excl) on [inode 0x10000000001 [2,head] /bar/test auth v132334 ap=3 s=0 n(v0 rc2023-07-15T13:33:00.982044-0400 1=1+0) (iauth excl) (ifile lock->excl) (ixattr excl) (iversion lock) cr={13924=0-4194304@1} caps={7205=pLs/pLsFc/-@3,13924=pAsLsXsxFcb/pAsxXsxFxwb@12},l=13924 | ptrwaiter=0 request=1 lock=1 caps=1 truncating=0 dirtyparent=0 dirty=1 waiter=1 authpin=1 0x56001aeb1700]
2023-07-15T13:33:01.346-0400 7f2d8788f700 7 mds.0.locker get_allowed_caps loner client.13924 allowed=pAsLsXsxFcb, xlocker allowed=pAsLsXsxFcb, others allowed=pAsLs on [inode 0x10000000001 [2,head] /bar/test auth v132334 ap=3 s=0 n(v0 rc2023-07-15T13:33:00.982044-0400 1=1+0) (ifile lock->excl) (ixattr excl) (iversion lock) cr={13924=0-4194304@1} caps={7205=pLs/pLsFc/-@3,13924=pAsLsXsxFcb/pAsxXsxFxwb@12},l=13924 | ptrwaiter=0 request=1 lock=1 caps=1 truncating=0 dirtyparent=0 dirty=1 waiter=1 authpin=1 0x56001aeb1700]
2023-07-15T13:33:01.346-0400 7f2d8788f700 20 mds.0.locker client.7205 pending pLs allowed pAsLs wanted -
2023-07-15T13:33:01.346-0400 7f2d8788f700 7 mds.0.locker get_allowed_caps loner client.13924 allowed=pAsLsXsxFcb, xlocker allowed=pAsLsXsxFcb, others allowed=pAsLs on [inode 0x10000000001 [2,head] /bar/test auth v132334 ap=3 s=0 n(v0 rc2023-07-15T13:33:00.982044-0400 1=1+0) (ifile lock->excl) (ixattr excl) (iversion lock) cr={13924=0-4194304@1} caps={7205=pLs/pLsFc/-@3,13924=pAsLsXsxFcb/pAsxXsxFxwb@12},l=13924 | ptrwaiter=0 request=1 lock=1 caps=1 truncating=0 dirtyparent=0 dirty=1 waiter=1 authpin=1 0x56001aeb1700]
2023-07-15T13:33:01.346-0400 7f2d8788f700 20 mds.0.locker client.13924 pending pAsLsXsxFcb allowed pAsLsXsxFcb wanted pAsxXsxFxwb
2023-07-15T13:33:01.346-0400 7f2d8788f700 10 mds.0.locker got rdlock on (iauth sync r=1) [inode 0x10000000001 [2,head] /bar/test auth v132334 ap=3 s=0 n(v0 rc2023-07-15T13:33:00.982044-0400 1=1+0) (iauth sync r=1) (ifile lock->excl) (ixattr excl) (iversion lock) cr={13924=0-4194304@1} caps={7205=pLs/pLsFc/-@3,13924=pAsLsXsxFcb/pAsxXsxFxwb@12},l=13924 | ptrwaiter=0 request=1 lock=2 caps=1 truncating=0 dirtyparent=0 dirty=1 waiter=1 authpin=1 0x56001aeb1700]
2023-07-15T13:33:01.346-0400 7f2d8788f700 7 mds.0.locker rdlock_start on (ilink sync) on [inode 0x10000000001 [2,head] /bar/test auth v132334 ap=3 s=0 n(v0 rc2023-07-15T13:33:00.982044-0400 1=1+0) (iauth sync r=1) (ifile lock->excl) (ixattr excl) (iversion lock) cr={13924=0-4194304@1} caps={7205=pLs/pLsFc/-@3,13924=pAsLsXsxFcb/pAsxXsxFxwb@12},l=13924 | ptrwaiter=0 request=1 lock=2 caps=1 truncating=0 dirtyparent=0 dirty=1 waiter=1 authpin=1 0x56001aeb1700]
2023-07-15T13:33:01.346-0400 7f2d8788f700 10 mds.0.locker got rdlock on (ilink sync r=1) [inode 0x10000000001 [2,head] /bar/test auth v132334 ap=3 s=0 n(v0 rc2023-07-15T13:33:00.982044-0400 1=1+0) (iauth sync r=1) (ilink sync r=1) (ifile lock->excl) (ixattr excl) (iversion lock) cr={13924=0-4194304@1} caps={7205=pLs/pLsFc/-@3,13924=pAsLsXsxFcb/pAsxXsxFxwb@12},l=13924 | ptrwaiter=0 request=1 lock=3 caps=1 truncating=0 dirtyparent=0 dirty=1 waiter=1 authpin=1 0x56001aeb1700]
2023-07-15T13:33:01.346-0400 7f2d8788f700 7 mds.0.locker rdlock_start on (ixattr excl) on [inode 0x10000000001 [2,head] /bar/test auth v132334 ap=3 s=0 n(v0 rc2023-07-15T13:33:00.982044-0400 1=1+0) (iauth sync r=1) (ilink sync r=1) (ifile lock->excl) (ixattr excl) (iversion lock) cr={13924=0-4194304@1} caps={7205=pLs/pLsFc/-@3,13924=pAsLsXsxFcb/pAsxXsxFxwb@12},l=13924 | ptrwaiter=0 request=1 lock=3 caps=1 truncating=0 dirtyparent=0 dirty=1 waiter=1 authpin=1 0x56001aeb1700]
2023-07-15T13:33:01.346-0400 7f2d8788f700 7 mds.0.locker simple_sync on (ixattr excl) on [inode 0x10000000001 [2,head] /bar/test auth v132334 ap=3 s=0 n(v0 rc2023-07-15T13:33:00.982044-0400 1=1+0) (iauth sync r=1) (ilink sync r=1) (ifile lock->excl) (ixattr excl) (iversion lock) cr={13924=0-4194304@1} caps={7205=pLs/pLsFc/-@3,13924=pAsLsXsxFcb/pAsxXsxFxwb@12},l=13924 | ptrwaiter=0 request=1 lock=3 caps=1 truncating=0 dirtyparent=0 dirty=1 waiter=1 authpin=1 0x56001aeb1700]
2023-07-15T13:33:01.346-0400 7f2d8788f700 7 mds.0.locker get_allowed_caps loner client.13924 allowed=pAsLsXsFcb, xlocker allowed=pAsLsXsFcb, others allowed=pAsLs on [inode 0x10000000001 [2,head] /bar/test auth v132334 ap=3 s=0 n(v0 rc2023-07-15T13:33:00.982044-0400 1=1+0) (iauth sync r=1) (ilink sync r=1) (ifile lock->excl) (ixattr excl->sync) (iversion lock) cr={13924=0-4194304@1} caps={7205=pLs/pLsFc/-@3,13924=pAsLsXsxFcb/pAsxXsxFxwb@12},l=13924 | ptrwaiter=0 request=1 lock=3 caps=1 truncating=0 dirtyparent=0 dirty=1 waiter=1 authpin=1 0x56001aeb1700]
2023-07-15T13:33:01.346-0400 7f2d8788f700 20 mds.0.locker client.7205 pending pLs allowed pAsLs wanted -
2023-07-15T13:33:01.346-0400 7f2d8788f700 7 mds.0.locker get_allowed_caps loner client.13924 allowed=pAsLsXsFcb, xlocker allowed=pAsLsXsFcb, others allowed=pAsLs on [inode 0x10000000001 [2,head] /bar/test auth v132334 ap=3 s=0 n(v0 rc2023-07-15T13:33:00.982044-0400 1=1+0) (iauth sync r=1) (ilink sync r=1) (ifile lock->excl) (ixattr excl->sync) (iversion lock) cr={13924=0-4194304@1} caps={7205=pLs/pLsFc/-@3,13924=pAsLsXsxFcb/pAsxXsxFxwb@12},l=13924 | ptrwaiter=0 request=1 lock=3 caps=1 truncating=0 dirtyparent=0 dirty=1 waiter=1 authpin=1 0x56001aeb1700]
2023-07-15T13:33:01.346-0400 7f2d8788f700 20 mds.0.locker client.13924 pending pAsLsXsxFcb allowed pAsLsXsFcb wanted pAsxXsxFxwb
2023-07-15T13:33:01.346-0400 7f2d8788f700 7 mds.0.locker sending MClientCaps to client.13924 seq 13 new pending pAsLsXsFcb was pAsLsXsxFcb
2023-07-15T13:33:01.346-0400 7f2d8788f700 20 mds.0.cache.ino(0x10000000001) encode_cap_message pfile 0 pauth 0 plink 0 pxattr 0 mtime 2023-07-15T13:33:00.982044-0400 ctime 2023-07-15T13:33:00.982044-0400 change_attr 31374
2023-07-15T13:33:01.346-0400 7f2d8788f700 10 mds.0.10 send_message_client_counted client.13924 seq 15 client_caps(revoke ino 0x10000000001 30880 seq 13 caps=pAsLsXsFcb dirty=- wanted=pAsxXsxFxwb follows 0 size 0/4194304 ts 9110/0 mtime 2023-07-15T13:33:00.982044-0400 ctime 2023-07-15T13:33:00.982044-0400 change_attr 31374 tws 15414) v12
2023-07-15T13:33:01.346-0400 7f2d8788f700 1 -- [v2:192.168.230.102:6872/3649207549,v1:192.168.230.102:6873/3649207549] --> v1:192.168.230.102:0/3806998182 -- client_caps(revoke ino 0x10000000001 30880 seq 13 caps=pAsLsXsFcb dirty=- wanted=pAsxXsxFxwb follows 0 size 0/4194304 ts 9110/0 mtime 2023-07-15T13:33:00.982044-0400 ctime 2023-07-15T13:33:00.982044-0400 change_attr 31374 tws 15414) v12 -- 0x56001b171180 con 0x56001aef5c00
DONE?
2023-07-15T13:33:01.346-0400 7f2d8788f700 10 mds.0.cache.ino(0x10000000001) auth_pin by 0x56001aeb1a40 on [inode 0x10000000001 [2,head] /bar/test auth v132334 ap=4 s=0 n(v0 rc2023-07-15T13:33:00.982044-0400 1=1+0) (iauth sync r=1) (ilink sync r=1) (ifile lock->excl) (ixattr excl->sync) (iversion lock) cr={13924=0-4194304@1} caps={7205=pLs/pLsFc/-@3,13924=pAsLsXsFcb/pAsLsXsxFcb/pAsxXsxFxwb@13},l=13924 | ptrwaiter=0 request=1 lock=3 caps=1 truncating=0 dirtyparent=0 dirty=1 waiter=1 authpin=1 0x56001aeb1700] now 4
2023-07-15T13:33:01.346-0400 7f2d8788f700 15 mds.0.cache.dir(0x10000000000) adjust_nested_auth_pins 1 on [dir 0x10000000000 /bar/ [2,head] auth v=132335 cv=76971/76971 ap=0+5 state=1610874881|complete f(v0 m2023-07-14T22:49:04.657776-0400 1=1+0) n(v0 rc2023-07-15T13:33:00.982044-0400 1=1+0) hs=1+0,ss=0+0 dirty=1 | child=1 dirty=1 authpin=0 0x560015fbd600] by 0x56001aeb1700 count now 0/5
2023-07-15T13:33:01.346-0400 7f2d8788f700 7 mds.0.locker rdlock_start waiting on (ixattr excl->sync) on [inode 0x10000000001 [2,head] /bar/test auth v132334 ap=4 s=0 n(v0 rc2023-07-15T13:33:00.982044-0400 1=1+0) (iauth sync r=1) (ilink sync r=1) (ifile lock->excl) (ixattr excl->sync) (iversion lock) cr={13924=0-4194304@1} caps={7205=pLs/pLsFc/-@3,13924=pAsLsXsFcb/pAsLsXsxFcb/pAsxXsxFxwb@13},l=13924 | ptrwaiter=0 request=1 lock=3 caps=1 truncating=0 dirtyparent=0 dirty=1 waiter=1 authpin=1 0x56001aeb1700]
2023-07-15T13:33:01.346-0400 7f2d8788f700 10 mds.0.cache.ino(0x10000000001) add_waiter tag 2000004000000000 0x56001b2b17e0 !ambig 1 !frozen 1 !freezing 1
2023-07-15T13:33:01.346-0400 7f2d8788f700 15 mds.0.cache.ino(0x10000000001) taking waiter here
2023-07-15T13:33:01.346-0400 7f2d8788f700 10 mds.0.locker nudge_log (ixattr excl->sync) on [inode 0x10000000001 [2,head] /bar/test auth v132334 ap=4 s=0 n(v0 rc2023-07-15T13:33:00.982044-0400 1=1+0) (iauth sync r=1) (ilink sync r=1) (ifile lock->excl) (ixattr excl->sync) (iversion lock) cr={13924=0-4194304@1} caps={7205=pLs/pLsFc/-@3,13924=pAsLsXsFcb/pAsLsXsxFcb/pAsxXsxFxwb@13},l=13924 | ptrwaiter=0 request=1 lock=3 caps=1 truncating=0 dirtyparent=0 dirty=1 waiter=1 authpin=1 0x56001aeb1700]
2023-07-15T13:33:01.346-0400 7f2d8788f700 7 mds.0.locker get_allowed_caps loner client.13924 allowed=pAsLsXsFcb, xlocker allowed=pAsLsXsFcb, others allowed=pAsLs on [inode 0x10000000001 [2,head] /bar/test auth v132334 ap=4 s=0 n(v0 rc2023-07-15T13:33:00.982044-0400 1=1+0) (iauth sync r=1) (ilink sync r=1) (ifile lock->excl) (ixattr excl->sync) (iversion lock) cr={13924=0-4194304@1} caps={7205=pLs/pLsFc/-@3,13924=pAsLsXsFcb/pAsLsXsxFcb/pAsxXsxFxwb@13},l=13924 | ptrwaiter=0 request=1 lock=3 caps=1 truncating=0 dirtyparent=0 dirty=1 waiter=1 authpin=1 0x56001aeb1700]
2023-07-15T13:33:01.346-0400 7f2d8788f700 20 mds.0.locker client.7205 pending pLs allowed pAsLs wanted -
2023-07-15T13:33:01.346-0400 7f2d8788f700 7 mds.0.locker get_allowed_caps loner client.13924 allowed=pAsLsXsFcb, xlocker allowed=pAsLsXsFcb, others allowed=pAsLs on [inode 0x10000000001 [2,head] /bar/test auth v132334 ap=4 s=0 n(v0 rc2023-07-15T13:33:00.982044-0400 1=1+0) (iauth sync r=1) (ilink sync r=1) (ifile lock->excl) (ixattr excl->sync) (iversion lock) cr={13924=0-4194304@1} caps={7205=pLs/pLsFc/-@3,13924=pAsLsXsFcb/pAsLsXsxFcb/pAsxXsxFxwb@13},l=13924 | ptrwaiter=0 request=1 lock=3 caps=1 truncating=0 dirtyparent=0 dirty=1 waiter=1 authpin=1 0x56001aeb1700]
2023-07-15T13:33:01.346-0400 7f2d8788f700 20 mds.0.locker client.13924 pending pAsLsXsFcb allowed pAsLsXsFcb wanted pAsxXsxFxwb
2023-07-15T13:33:01.346-0400 7f2d8788f700 10 mds.0.locker eval done
</pre>
then:
<pre>
2023-07-15T13:33:01.346-0400 7f2d8788f700 1 -- [v2:192.168.230.102:6872/3649207549,v1:192.168.230.102:6873/3649207549] <== client.7205 v1:192.168.230.102:0/3507006748 96753 ==== client_caps(update ino 0x10000000001 30883 seq 3 caps=pLs dirty=- wanted=- follows 0 size 0/0 mtime 2023-07-15T13:33:00.982044-0400 ctime 2023-07-15T13:33:00.982044-0400 change_attr 31374 tws 15414 xattrs(v=7414799382010986976 l=0)) v10 ==== 236+0+0 (unknown 2808319627 0 0) 0x56001b3b6380 con 0x56001aef4000
2023-07-15T13:33:01.346-0400 7f2d8788f700 7 mds.0.locker handle_client_caps on 0x10000000001 tid 0 follows 0 op update flags 0x0
2023-07-15T13:33:01.346-0400 7f2d8788f700 20 mds.0.10 get_session have 0x56001c350300 client.7205 v1:192.168.230.102:0/3507006748 state open
2023-07-15T13:33:01.346-0400 7f2d8788f700 10 mds.0.locker head inode [inode 0x10000000001 [2,head] /bar/test auth v132334 ap=4 s=0 n(v0 rc2023-07-15T13:33:00.982044-0400 1=1+0) (iauth sync r=1) (ilink sync r=1) (ifile lock->excl) (ixattr excl->sync) (iversion lock) cr={13924=0-4194304@1} caps={7205=pLs/pLsFc/-@3,13924=pAsLsXsFcb/pAsLsXsxFcb/pAsxXsxFxwb@13},l=13924 | ptrwaiter=0 request=1 lock=3 caps=1 truncating=0 dirtyparent=0 dirty=1 waiter=1 authpin=1 0x56001aeb1700]
2023-07-15T13:33:01.346-0400 7f2d8788f700 10 mds.0.locker follows 0 retains pLs dirty - on [inode 0x10000000001 [2,head] /bar/test auth v132334 ap=4 s=0 n(v0 rc2023-07-15T13:33:00.982044-0400 1=1+0) (iauth sync r=1) (ilink sync r=1) (ifile lock->excl) (ixattr excl->sync) (iversion lock) cr={13924=0-4194304@1} caps={7205=pLs/-@3,13924=pAsLsXsFcb/pAsLsXsxFcb/pAsxXsxFxwb@13},l=13924 | ptrwaiter=0 request=1 lock=3 caps=1 truncating=0 dirtyparent=0 dirty=1 waiter=1 authpin=1 0x56001aeb1700]
2023-07-15T13:33:01.346-0400 7f2d8788f700 10 mds.0.locker _do_cap_update dirty - issued pLs wanted - on [inode 0x10000000001 [2,head] /bar/test auth v132334 ap=4 s=0 n(v0 rc2023-07-15T13:33:00.982044-0400 1=1+0) (iauth sync r=1) (ilink sync r=1) (ifile lock->excl) (ixattr excl->sync) (iversion lock) cr={13924=0-4194304@1} caps={7205=pLs/-@3,13924=pAsLsXsFcb/pAsLsXsxFcb/pAsxXsxFxwb@13},l=13924 | ptrwaiter=0 request=1 lock=3 caps=1 truncating=0 dirtyparent=0 dirty=1 waiter=1 authpin=1 0x56001aeb1700]
2023-07-15T13:33:01.346-0400 7f2d8788f700 20 mds.0.locker inode is file
2023-07-15T13:33:01.346-0400 7f2d8788f700 10 mds.0.locker eval 3648 [inode 0x10000000001 [2,head] /bar/test auth v132334 ap=4 s=0 n(v0 rc2023-07-15T13:33:00.982044-0400 1=1+0) (iauth sync r=1) (ilink sync r=1) (ifile lock->excl) (ixattr excl->sync) (iversion lock) cr={13924=0-4194304@1} caps={7205=pLs/-@3,13924=pAsLsXsFcb/pAsLsXsxFcb/pAsxXsxFxwb@13},l=13924 | ptrwaiter=0 request=1 lock=3 caps=1 truncating=0 dirtyparent=0 dirty=1 waiter=1 authpin=1 0x56001aeb1700]
2023-07-15T13:33:01.346-0400 7f2d8788f700 10 mds.0.locker eval_gather (ifile lock->excl) on [inode 0x10000000001 [2,head] /bar/test auth v132334 ap=4 s=0 n(v0 rc2023-07-15T13:33:00.982044-0400 1=1+0) (iauth sync r=1) (ilink sync r=1) (ifile lock->excl) (ixattr excl->sync) (iversion lock) cr={13924=0-4194304@1} caps={7205=pLs/-@3,13924=pAsLsXsFcb/pAsLsXsxFcb/pAsxXsxFxwb@13},l=13924 | ptrwaiter=0 request=1 lock=3 caps=1 truncating=0 dirtyparent=0 dirty=1 waiter=1 authpin=1 0x56001aeb1700]
2023-07-15T13:33:01.346-0400 7f2d8788f700 10 mds.0.locker next state is excl issued/allows loner cb/sxcrwb xlocker /sxcrwb other /
2023-07-15T13:33:01.346-0400 7f2d8788f700 7 mds.0.locker eval_gather finished gather on (ifile lock->excl) on [inode 0x10000000001 [2,head] /bar/test auth v132334 ap=4 s=0 n(v0 rc2023-07-15T13:33:00.982044-0400 1=1+0) (iauth sync r=1) (ilink sync r=1) (ifile lock->excl) (ixattr excl->sync) (iversion lock) cr={13924=0-4194304@1} caps={7205=pLs/-@3,13924=pAsLsXsFcb/pAsLsXsxFcb/pAsxXsxFxwb@13},l=13924 | ptrwaiter=0 request=1 lock=3 caps=1 truncating=0 dirtyparent=0 dirty=1 waiter=1 authpin=1 0x56001aeb1700]
2023-07-15T13:33:01.346-0400 7f2d8788f700 10 mds.0.cache.ino(0x10000000001) auth_unpin by 0x56001aeb1a10 on [inode 0x10000000001 [2,head] /bar/test auth v132334 ap=3 s=0 n(v0 rc2023-07-15T13:33:00.982044-0400 1=1+0) (iauth sync r=1) (ilink sync r=1) (ifile excl) (ixattr excl->sync) (iversion lock) cr={13924=0-4194304@1} caps={7205=pLs/-@3,13924=pAsLsXsFcb/pAsLsXsxFcb/pAsxXsxFxwb@13},l=13924 | ptrwaiter=0 request=1 lock=3 caps=1 truncating=0 dirtyparent=0 dirty=1 waiter=1 authpin=1 0x56001aeb1700] now 3
2023-07-15T13:33:01.346-0400 7f2d8788f700 15 mds.0.cache.dir(0x10000000000) adjust_nested_auth_pins -1 on [dir 0x10000000000 /bar/ [2,head] auth v=132335 cv=76971/76971 ap=0+4 state=1610874881|complete f(v0 m2023-07-14T22:49:04.657776-0400 1=1+0) n(v0 rc2023-07-15T13:33:00.982044-0400 1=1+0) hs=1+0,ss=0+0 dirty=1 | child=1 dirty=1 authpin=0 0x560015fbd600] by 0x56001aeb1a10 count now 0/4
2023-07-15T13:33:01.346-0400 7f2d8788f700 7 mds.0.locker file_eval wanted=xwb loner_wanted=xwb other_wanted= filelock=(ifile excl) on [inode 0x10000000001 [2,head] /bar/test auth v132334 ap=3 s=0 n(v0 rc2023-07-15T13:33:00.982044-0400 1=1+0) (iauth sync r=1) (ilink sync r=1) (ifile excl) (ixattr excl->sync) (iversion lock) cr={13924=0-4194304@1} caps={7205=pLs/-@3,13924=pAsLsXsFcb/pAsLsXsxFcb/pAsxXsxFxwb@13},l=13924 | ptrwaiter=0 request=1 lock=3 caps=1 truncating=0 dirtyparent=0 dirty=1 waiter=1 authpin=1 0x56001aeb1700]
2023-07-15T13:33:01.346-0400 7f2d8788f700 20 mds.0.locker is excl
2023-07-15T13:33:01.346-0400 7f2d8788f700 7 mds.0.locker file_eval loner_issued=cb other_issued= xlocker_issued=
2023-07-15T13:33:01.346-0400 7f2d8788f700 10 mds.0.locker simple_eval (iauth sync r=1) on [inode 0x10000000001 [2,head] /bar/test auth v132334 ap=3 s=0 n(v0 rc2023-07-15T13:33:00.982044-0400 1=1+0) (iauth sync r=1) (ilink sync r=1) (ifile excl) (ixattr excl->sync) (iversion lock) cr={13924=0-4194304@1} caps={7205=pLs/-@3,13924=pAsLsXsFcb/pAsLsXsxFcb/pAsxXsxFxwb@13},l=13924 | ptrwaiter=0 request=1 lock=3 caps=1 truncating=0 dirtyparent=0 dirty=1 waiter=1 authpin=1 0x56001aeb1700]
2023-07-15T13:33:01.346-0400 7f2d8788f700 7 mds.0.locker simple_eval stable, going to excl (iauth sync r=1) on [inode 0x10000000001 [2,head] /bar/test auth v132334 ap=3 s=0 n(v0 rc2023-07-15T13:33:00.982044-0400 1=1+0) (iauth sync r=1) (ilink sync r=1) (ifile excl) (ixattr excl->sync) (iversion lock) cr={13924=0-4194304@1} caps={7205=pLs/-@3,13924=pAsLsXsFcb/pAsLsXsxFcb/pAsxXsxFxwb@13},l=13924 | ptrwaiter=0 request=1 lock=3 caps=1 truncating=0 dirtyparent=0 dirty=1 waiter=1 authpin=1 0x56001aeb1700]
2023-07-15T13:33:01.346-0400 7f2d8788f700 7 mds.0.locker simple_excl on (iauth sync r=1) on [inode 0x10000000001 [2,head] /bar/test auth v132334 ap=3 s=0 n(v0 rc2023-07-15T13:33:00.982044-0400 1=1+0) (iauth sync r=1) (ilink sync r=1) (ifile excl) (ixattr excl->sync) (iversion lock) cr={13924=0-4194304@1} caps={7205=pLs/-@3,13924=pAsLsXsFcb/pAsLsXsxFcb/pAsxXsxFxwb@13},l=13924 | ptrwaiter=0 request=1 lock=3 caps=1 truncating=0 dirtyparent=0 dirty=1 waiter=1 authpin=1 0x56001aeb1700]
2023-07-15T13:33:01.346-0400 7f2d8788f700 10 mds.0.cache.ino(0x10000000001) auth_pin by 0x56001aeb1990 on [inode 0x10000000001 [2,head] /bar/test auth v132334 ap=4 s=0 n(v0 rc2023-07-15T13:33:00.982044-0400 1=1+0) (iauth sync->excl r=1) (ilink sync r=1) (ifile excl) (ixattr excl->sync) (iversion lock) cr={13924=0-4194304@1} caps={7205=pLs/-@3,13924=pAsLsXsFcb/pAsLsXsxFcb/pAsxXsxFxwb@13},l=13924 | ptrwaiter=0 request=1 lock=3 caps=1 truncating=0 dirtyparent=0 dirty=1 waiter=1 authpin=1 0x56001aeb1700] now 4
2023-07-15T13:33:01.346-0400 7f2d8788f700 15 mds.0.cache.dir(0x10000000000) adjust_nested_auth_pins 1 on [dir 0x10000000000 /bar/ [2,head] auth v=132335 cv=76971/76971 ap=0+5 state=1610874881|complete f(v0 m2023-07-14T22:49:04.657776-0400 1=1+0) n(v0 rc2023-07-15T13:33:00.982044-0400 1=1+0) hs=1+0,ss=0+0 dirty=1 | child=1 dirty=1 authpin=0 0x560015fbd600] by 0x56001aeb1700 count now 0/5
2023-07-15T13:33:01.346-0400 7f2d8788f700 10 mds.0.locker simple_eval (ilink sync r=1) on [inode 0x10000000001 [2,head] /bar/test auth v132334 ap=4 s=0 n(v0 rc2023-07-15T13:33:00.982044-0400 1=1+0) (iauth sync->excl r=1) (ilink sync r=1) (ifile excl) (ixattr excl->sync) (iversion lock) cr={13924=0-4194304@1} caps={7205=pLs/-@3,13924=pAsLsXsFcb/pAsLsXsxFcb/pAsxXsxFxwb@13},l=13924 | ptrwaiter=0 request=1 lock=3 caps=1 truncating=0 dirtyparent=0 dirty=1 waiter=1 authpin=1 0x56001aeb1700]
2023-07-15T13:33:01.346-0400 7f2d8788f700 10 mds.0.locker eval_gather (ixattr excl->sync) on [inode 0x10000000001 [2,head] /bar/test auth v132334 ap=4 s=0 n(v0 rc2023-07-15T13:33:00.982044-0400 1=1+0) (iauth sync->excl r=1) (ilink sync r=1) (ifile excl) (ixattr excl->sync) (iversion lock) cr={13924=0-4194304@1} caps={7205=pLs/-@3,13924=pAsLsXsFcb/pAsLsXsxFcb/pAsxXsxFxwb@13},l=13924 | ptrwaiter=0 request=1 lock=3 caps=1 truncating=0 dirtyparent=0 dirty=1 waiter=1 authpin=1 0x56001aeb1700]
2023-07-15T13:33:01.346-0400 7f2d8788f700 10 mds.0.locker next state is sync issued/allows loner sx/s xlocker /s other /s
2023-07-15T13:33:01.346-0400 7f2d8788f700 10 MDSContext::complete: 18C_MDS_RetryRequest
2023-07-15T13:33:01.346-0400 7f2d8788f700 7 mds.0.server dispatch_client_request client_request(client.13927:3 create #0x10000000000/test 2023-07-15T13:33:01.188897-0400 caller_uid=10000, caller_gid=100{10,100,}) v4
2023-07-15T13:33:01.346-0400 7f2d8788f700 7 mds.0.server open w/ O_CREAT on #0x10000000000/test
2023-07-15T13:33:01.346-0400 7f2d8788f700 10 mds.0.server rdlock_path_xlock_dentry request(client.13927:3 nref=2 cr=0x56001bc19b00) #0x10000000000/test
2023-07-15T13:33:01.346-0400 7f2d8788f700 10 mds.0.locker xlock_downgrade on (dn sync l r=1) [dentry #0x1/bar/test [2,head] auth (dn sync l r=1) (dversion lock w=1 last_client=13927) v=132334 ap=1 ino=0x10000000001 state=1610612736 | request=1 lock=2 inodepin=1 dirty=1 waiter=0 authpin=1 clientlease=1 0x56001ae84500]
2023-07-15T13:33:01.346-0400 7f2d8788f700 10 mds.0.locker acquire_locks request(client.13927:3 nref=2 cr=0x56001bc19b00)
2023-07-15T13:33:01.346-0400 7f2d8788f700 20 mds.0.locker must rdlock (isnap sync r=2) [inode 0x10000000001 [2,head] /bar/test auth v132334 ap=4 s=0 n(v0 rc2023-07-15T13:33:00.982044-0400 1=1+0) (iauth sync->excl r=1) (ilink sync r=1) (ifile excl) (ixattr excl->sync) (iversion lock) cr={13924=0-4194304@1} caps={7205=pLs/-@3,13924=pAsLsXsFcb/pAsLsXsxFcb/pAsxXsxFxwb@13},l=13924 | ptrwaiter=0 request=1 lock=3 caps=1 truncating=0 dirtyparent=0 dirty=1 waiter=1 authpin=1 0x56001aeb1700]
2023-07-15T13:33:01.346-0400 7f2d8788f700 10 mds.0.locker must authpin [inode 0x10000000001 [2,head] /bar/test auth v132334 ap=4 s=0 n(v0 rc2023-07-15T13:33:00.982044-0400 1=1+0) (iauth sync->excl r=1) (ilink sync r=1) (ifile excl) (ixattr excl->sync) (iversion lock) cr={13924=0-4194304@1} caps={7205=pLs/-@3,13924=pAsLsXsFcb/pAsLsXsxFcb/pAsxXsxFxwb@13},l=13924 | ptrwaiter=0 request=1 lock=3 caps=1 truncating=0 dirtyparent=0 dirty=1 waiter=1 authpin=1 0x56001aeb1700]
2023-07-15T13:33:01.346-0400 7f2d8788f700 10 mds.0.locker already auth_pinned [inode 0x10000000001 [2,head] /bar/test auth v132334 ap=4 s=0 n(v0 rc2023-07-15T13:33:00.982044-0400 1=1+0) (iauth sync->excl r=1) (ilink sync r=1) (ifile excl) (ixattr excl->sync) (iversion lock) cr={13924=0-4194304@1} caps={7205=pLs/-@3,13924=pAsLsXsFcb/pAsLsXsxFcb/pAsxXsxFxwb@13},l=13924 | ptrwaiter=0 request=1 lock=3 caps=1 truncating=0 dirtyparent=0 dirty=1 waiter=1 authpin=1 0x56001aeb1700]
2023-07-15T13:33:01.347-0400 7f2d8788f700 10 mds.0.locker already rdlocked (isnap sync r=2) [inode 0x10000000001 [2,head] /bar/test auth v132334 ap=4 s=0 n(v0 rc2023-07-15T13:33:00.982044-0400 1=1+0) (iauth sync->excl r=1) (ilink sync r=1) (ifile excl) (ixattr excl->sync) (iversion lock) cr={13924=0-4194304@1} caps={7205=pLs/-@3,13924=pAsLsXsFcb/pAsLsXsxFcb/pAsxXsxFxwb@13},l=13924 | ptrwaiter=0 request=1 lock=3 caps=1 truncating=0 dirtyparent=0 dirty=1 waiter=1 authpin=1 0x56001aeb1700]
2023-07-15T13:33:01.347-0400 7f2d8788f700 7 mds.0.server open on #0x10000000000/test
2023-07-15T13:33:01.347-0400 7f2d8788f700 10 mds.0.server rdlock_path_pin_ref request(client.13927:3 nref=2 cr=0x56001bc19b00) #0x10000000000/test
2023-07-15T13:33:01.347-0400 7f2d8788f700 10 mds.0.server open flags = 577, filemode = 2, need_auth = 1
2023-07-15T13:33:01.347-0400 7f2d8788f700 1 mds.0.server getting filelock
2023-07-15T13:33:01.347-0400 7f2d8788f700 10 mds.0.locker acquire_locks request(client.13927:3 nref=2 cr=0x56001bc19b00)
2023-07-15T13:33:01.347-0400 7f2d8788f700 20 mds.0.locker must rdlock (iauth sync->excl r=1) [inode 0x10000000001 [2,head] /bar/test auth v132334 ap=4 s=0 n(v0 rc2023-07-15T13:33:00.982044-0400 1=1+0) (iauth sync->excl r=1) (ilink sync r=1) (ifile excl) (ixattr excl->sync) (iversion lock) cr={13924=0-4194304@1} caps={7205=pLs/-@3,13924=pAsLsXsFcb/pAsLsXsxFcb/pAsxXsxFxwb@13},l=13924 | ptrwaiter=0 request=1 lock=3 caps=1 truncating=0 dirtyparent=0 dirty=1 waiter=1 authpin=1 0x56001aeb1700]
2023-07-15T13:33:01.347-0400 7f2d8788f700 20 mds.0.locker must rdlock (ixattr excl->sync) [inode 0x10000000001 [2,head] /bar/test auth v132334 ap=4 s=0 n(v0 rc2023-07-15T13:33:00.982044-0400 1=1+0) (iauth sync->excl r=1) (ilink sync r=1) (ifile excl) (ixattr excl->sync) (iversion lock) cr={13924=0-4194304@1} caps={7205=pLs/-@3,13924=pAsLsXsFcb/pAsLsXsxFcb/pAsxXsxFxwb@13},l=13924 | ptrwaiter=0 request=1 lock=3 caps=1 truncating=0 dirtyparent=0 dirty=1 waiter=1 authpin=1 0x56001aeb1700]
2023-07-15T13:33:01.347-0400 7f2d8788f700 20 mds.0.locker must xlock (ifile excl) [inode 0x10000000001 [2,head] /bar/test auth v132334 ap=4 s=0 n(v0 rc2023-07-15T13:33:00.982044-0400 1=1+0) (iauth sync->excl r=1) (ilink sync r=1) (ifile excl) (ixattr excl->sync) (iversion lock) cr={13924=0-4194304@1} caps={7205=pLs/-@3,13924=pAsLsXsFcb/pAsLsXsxFcb/pAsxXsxFxwb@13},l=13924 | ptrwaiter=0 request=1 lock=3 caps=1 truncating=0 dirtyparent=0 dirty=1 waiter=1 authpin=1 0x56001aeb1700]
2023-07-15T13:33:01.347-0400 7f2d8788f700 20 mds.0.locker must wrlock (iversion lock) [inode 0x10000000001 [2,head] /bar/test auth v132334 ap=4 s=0 n(v0 rc2023-07-15T13:33:00.982044-0400 1=1+0) (iauth sync->excl r=1) (ilink sync r=1) (ifile excl) (ixattr excl->sync) (iversion lock) cr={13924=0-4194304@1} caps={7205=pLs/-@3,13924=pAsLsXsFcb/pAsLsXsxFcb/pAsxXsxFxwb@13},l=13924 | ptrwaiter=0 request=1 lock=3 caps=1 truncating=0 dirtyparent=0 dirty=1 waiter=1 authpin=1 0x56001aeb1700]
2023-07-15T13:33:01.347-0400 7f2d8788f700 10 mds.0.locker must authpin [inode 0x10000000001 [2,head] /bar/test auth v132334 ap=4 s=0 n(v0 rc2023-07-15T13:33:00.982044-0400 1=1+0) (iauth sync->excl r=1) (ilink sync r=1) (ifile excl) (ixattr excl->sync) (iversion lock) cr={13924=0-4194304@1} caps={7205=pLs/-@3,13924=pAsLsXsFcb/pAsLsXsxFcb/pAsxXsxFxwb@13},l=13924 | ptrwaiter=0 request=1 lock=3 caps=1 truncating=0 dirtyparent=0 dirty=1 waiter=1 authpin=1 0x56001aeb1700]
2023-07-15T13:33:01.347-0400 7f2d8788f700 10 mds.0.locker already auth_pinned [inode 0x10000000001 [2,head] /bar/test auth v132334 ap=4 s=0 n(v0 rc2023-07-15T13:33:00.982044-0400 1=1+0) (iauth sync->excl r=1) (ilink sync r=1) (ifile excl) (ixattr excl->sync) (iversion lock) cr={13924=0-4194304@1} caps={7205=pLs/-@3,13924=pAsLsXsFcb/pAsLsXsxFcb/pAsxXsxFxwb@13},l=13924 | ptrwaiter=0 request=1 lock=3 caps=1 truncating=0 dirtyparent=0 dirty=1 waiter=1 authpin=1 0x56001aeb1700]
2023-07-15T13:33:01.347-0400 7f2d8788f700 7 mds.0.locker xlock_start on (ifile excl) on [inode 0x10000000001 [2,head] /bar/test auth v132334 ap=4 s=0 n(v0 rc2023-07-15T13:33:00.982044-0400 1=1+0) (iauth sync->excl r=1) (ilink sync r=1) (ifile excl) (ixattr excl->sync) (iversion lock) cr={13924=0-4194304@1} caps={7205=pLs/-@3,13924=pAsLsXsFcb/pAsLsXsxFcb/pAsxXsxFxwb@13},l=13924 | ptrwaiter=0 request=1 lock=3 caps=1 truncating=0 dirtyparent=0 dirty=1 waiter=1 authpin=1 0x56001aeb1700]
2023-07-15T13:33:01.347-0400 7f2d8788f700 7 mds.0.locker simple_lock on (ifile excl) on [inode 0x10000000001 [2,head] /bar/test auth v132334 ap=4 s=0 n(v0 rc2023-07-15T13:33:00.982044-0400 1=1+0) (iauth sync->excl r=1) (ilink sync r=1) (ifile excl) (ixattr excl->sync) (iversion lock) cr={13924=0-4194304@1} caps={7205=pLs/-@3,13924=pAsLsXsFcb/pAsLsXsxFcb/pAsxXsxFxwb@13},l=13924 | ptrwaiter=0 request=1 lock=3 caps=1 truncating=0 dirtyparent=0 dirty=1 waiter=1 authpin=1 0x56001aeb1700]
2023-07-15T13:33:01.347-0400 7f2d8788f700 7 mds.0.locker simple_xlock on (ifile lock) on [inode 0x10000000001 [2,head] /bar/test auth v132334 ap=4 s=0 n(v0 rc2023-07-15T13:33:00.982044-0400 1=1+0) (iauth sync->excl r=1) (ilink sync r=1) (ifile lock) (ixattr excl->sync) (iversion lock) cr={13924=0-4194304@1} caps={7205=pLs/-@3,13924=pAsLsXsFcb/pAsLsXsxFcb/pAsxXsxFxwb@13},l=13924 | ptrwaiter=0 request=2 lock=3 caps=1 truncating=0 dirtyparent=0 dirty=1 waiter=1 authpin=1 0x56001aeb1700]
2023-07-15T13:33:01.347-0400 7f2d8788f700 10 mds.0.cache.ino(0x10000000001) auth_pin by 0x56001aeb1a10 on [inode 0x10000000001 [2,head] /bar/test auth v132334 ap=5 s=0 n(v0 rc2023-07-15T13:33:00.982044-0400 1=1+0) (iauth sync->excl r=1) (ilink sync r=1) (ifile lock) (ixattr excl->sync) (iversion lock) cr={13924=0-4194304@1} caps={7205=pLs/-@3,13924=pAsLsXsFcb/pAsLsXsxFcb/pAsxXsxFxwb@13},l=13924 | ptrwaiter=0 request=2 lock=3 caps=1 truncating=0 dirtyparent=0 dirty=1 waiter=1 authpin=1 0x56001aeb1700] now 5
2023-07-15T13:33:01.347-0400 7f2d8788f700 15 mds.0.cache.dir(0x10000000000) adjust_nested_auth_pins 1 on [dir 0x10000000000 /bar/ [2,head] auth v=132335 cv=76971/76971 ap=0+6 state=1610874881|complete f(v0 m2023-07-14T22:49:04.657776-0400 1=1+0) n(v0 rc2023-07-15T13:33:00.982044-0400 1=1+0) hs=1+0,ss=0+0 dirty=1 | child=1 dirty=1 authpin=0 0x560015fbd600] by 0x56001aeb1700 count now 0/6
2023-07-15T13:33:01.347-0400 7f2d8788f700 10 mds.0.locker got xlock on (ifile xlock x=1 by 0x56001b11df80) [inode 0x10000000001 [2,head] /bar/test auth v132334 ap=5 s=0 n(v0 rc2023-07-15T13:33:00.982044-0400 1=1+0) (iauth sync->excl r=1) (ilink sync r=1) (ifile xlock x=1 by 0x56001b11df80) (ixattr excl->sync) (iversion lock) cr={13924=0-4194304@1} caps={7205=pLs/-@3,13924=pAsLsXsFcb/pAsLsXsxFcb/pAsxXsxFxwb@13},l=13924 | ptrwaiter=0 request=2 lock=4 caps=1 truncating=0 dirtyparent=0 dirty=1 waiter=1 authpin=1 0x56001aeb1700]
2023-07-15T13:33:01.347-0400 7f2d8788f700 7 mds.0.locker rdlock_start on (iauth sync->excl r=1) on [inode 0x10000000001 [2,head] /bar/test auth v132334 ap=5 s=0 n(v0 rc2023-07-15T13:33:00.982044-0400 1=1+0) (iauth sync->excl r=1) (ilink sync r=1) (ifile xlock x=1 by 0x56001b11df80) (ixattr excl->sync) (iversion lock) cr={13924=0-4194304@1} caps={7205=pLs/-@3,13924=pAsLsXsFcb/pAsLsXsxFcb/pAsxXsxFxwb@13},l=13924 | ptrwaiter=0 request=2 lock=4 caps=1 truncating=0 dirtyparent=0 dirty=1 waiter=1 authpin=1 0x56001aeb1700]
2023-07-15T13:33:01.347-0400 7f2d8788f700 7 mds.0.locker rdlock_start waiting on (iauth sync->excl r=1) on [inode 0x10000000001 [2,head] /bar/test auth v132334 ap=5 s=0 n(v0 rc2023-07-15T13:33:00.982044-0400 1=1+0) (iauth sync->excl r=1) (ilink sync r=1) (ifile xlock x=1 by 0x56001b11df80) (ixattr excl->sync) (iversion lock) cr={13924=0-4194304@1} caps={7205=pLs/-@3,13924=pAsLsXsFcb/pAsLsXsxFcb/pAsxXsxFxwb@13},l=13924 | ptrwaiter=0 request=2 lock=4 caps=1 truncating=0 dirtyparent=0 dirty=1 waiter=1 authpin=1 0x56001aeb1700]
2023-07-15T13:33:01.347-0400 7f2d8788f700 10 mds.0.cache.ino(0x10000000001) add_waiter tag 2000000000040000 0x56001ae8bc40 !ambig 1 !frozen 1 !freezing 1
2023-07-15T13:33:01.347-0400 7f2d8788f700 15 mds.0.cache.ino(0x10000000001) taking waiter here
2023-07-15T13:33:01.347-0400 7f2d8788f700 10 mds.0.locker nudge_log (iauth sync->excl r=1) on [inode 0x10000000001 [2,head] /bar/test auth v132334 ap=5 s=0 n(v0 rc2023-07-15T13:33:00.982044-0400 1=1+0) (iauth sync->excl r=1) (ilink sync r=1) (ifile xlock x=1 by 0x56001b11df80) (ixattr excl->sync) (iversion lock) cr={13924=0-4194304@1} caps={7205=pLs/-@3,13924=pAsLsXsFcb/pAsLsXsxFcb/pAsxXsxFxwb@13},l=13924 | ptrwaiter=0 request=2 lock=4 caps=1 truncating=0 dirtyparent=0 dirty=1 waiter=1 authpin=1 0x56001aeb1700]
2023-07-15T13:33:01.347-0400 7f2d8788f700 7 mds.0.locker get_allowed_caps loner client.13924 allowed=pAsLsXsFcb, xlocker allowed=pAsLsXsFcb, others allowed=pLsFcb on [inode 0x10000000001 [2,head] /bar/test auth v132334 ap=5 s=0 n(v0 rc2023-07-15T13:33:00.982044-0400 1=1+0) (iauth sync->excl r=1) (ilink sync r=1) (ifile xlock x=1 by 0x56001b11df80) (ixattr excl->sync) (iversion lock) cr={13924=0-4194304@1} caps={7205=pLs/-@3,13924=pAsLsXsFcb/pAsLsXsxFcb/pAsxXsxFxwb@13},l=13924 | ptrwaiter=0 request=2 lock=4 caps=1 truncating=0 dirtyparent=0 dirty=1 waiter=1 authpin=1 0x56001aeb1700]
2023-07-15T13:33:01.347-0400 7f2d8788f700 20 mds.0.locker client.7205 pending pLs allowed pLsFcb wanted -
2023-07-15T13:33:01.347-0400 7f2d8788f700 7 mds.0.locker get_allowed_caps loner client.13924 allowed=pAsLsXsFcb, xlocker allowed=pAsLsXsFcb, others allowed=pLsFcb on [inode 0x10000000001 [2,head] /bar/test auth v132334 ap=5 s=0 n(v0 rc2023-07-15T13:33:00.982044-0400 1=1+0) (iauth sync->excl r=1) (ilink sync r=1) (ifile xlock x=1 by 0x56001b11df80) (ixattr excl->sync) (iversion lock) cr={13924=0-4194304@1} caps={7205=pLs/-@3,13924=pAsLsXsFcb/pAsLsXsxFcb/pAsxXsxFxwb@13},l=13924 | ptrwaiter=0 request=2 lock=4 caps=1 truncating=0 dirtyparent=0 dirty=1 waiter=1 authpin=1 0x56001aeb1700]
2023-07-15T13:33:01.347-0400 7f2d8788f700 20 mds.0.locker client.13924 pending pAsLsXsFcb allowed pAsLsXsFcb wanted pAsxXsxFxwb
2023-07-15T13:33:01.347-0400 7f2d8788f700 10 mds.0.locker eval done
</pre>
Finally getattr woken again:
<pre>
2023-07-15T13:33:01.347-0400 7f2d8788f700 1 -- [v2:192.168.230.102:6872/3649207549,v1:192.168.230.102:6873/3649207549] <== client.13924 v1:192.168.230.102:0/3806998182 13 ==== client_caps(update ino 0x10000000001 30880 seq 13 caps=pAsLsXsFcb dirty=- wanted=pAsxXsxFxwb follows 0 size 0/0 mtime 2023-07-15T13:33:00.982044-0400 ctime 2023-07-15T13:33:00.982044-0400 change_attr 31374 tws 15414 xattrs(v=7414799382010986976 l=0)) v10 ==== 236+0+0 (unknown 2751808202 0 0) 0x56001b171180 con 0x56001aef5c00
2023-07-15T13:33:01.347-0400 7f2d8788f700 7 mds.0.locker handle_client_caps on 0x10000000001 tid 0 follows 0 op update flags 0x0
2023-07-15T13:33:01.347-0400 7f2d8788f700 20 mds.0.10 get_session have 0x56001b406300 client.13924 v1:192.168.230.102:0/3806998182 state open
2023-07-15T13:33:01.347-0400 7f2d8788f700 10 mds.0.locker head inode [inode 0x10000000001 [2,head] /bar/test auth v132334 ap=5 s=0 n(v0 rc2023-07-15T13:33:00.982044-0400 1=1+0) (iauth sync->excl r=1) (ilink sync r=1) (ifile xlock x=1 by 0x56001b11df80) (ixattr excl->sync) (iversion lock) cr={13924=0-4194304@1} caps={7205=pLs/-@3,13924=pAsLsXsFcb/pAsLsXsxFcb/pAsxXsxFxwb@13},l=13924 | ptrwaiter=0 request=2 lock=4 caps=1 truncating=0 dirtyparent=0 dirty=1 waiter=1 authpin=1 0x56001aeb1700]
2023-07-15T13:33:01.347-0400 7f2d8788f700 10 mds.0.locker follows 0 retains pAsLsXsFcb dirty - on [inode 0x10000000001 [2,head] /bar/test auth v132334 ap=5 s=0 n(v0 rc2023-07-15T13:33:00.982044-0400 1=1+0) (iauth sync->excl r=1) (ilink sync r=1) (ifile xlock x=1 by 0x56001b11df80) (ixattr excl->sync) (iversion lock) cr={13924=0-4194304@1} caps={7205=pLs/-@3,13924=pAsLsXsFcb/pAsxXsxFxwb@13},l=13924 | ptrwaiter=0 request=2 lock=4 caps=1 truncating=0 dirtyparent=0 dirty=1 waiter=1 authpin=1 0x56001aeb1700]
2023-07-15T13:33:01.347-0400 7f2d8788f700 10 mds.0.locker _do_cap_update dirty - issued pAsLsXsFcb wanted pAsxXsxFxwb on [inode 0x10000000001 [2,head] /bar/test auth v132334 ap=5 s=0 n(v0 rc2023-07-15T13:33:00.982044-0400 1=1+0) (iauth sync->excl r=1) (ilink sync r=1) (ifile xlock x=1 by 0x56001b11df80) (ixattr excl->sync) (iversion lock) cr={13924=0-4194304@1} caps={7205=pLs/-@3,13924=pAsLsXsFcb/pAsxXsxFxwb@13},l=13924 | ptrwaiter=0 request=2 lock=4 caps=1 truncating=0 dirtyparent=0 dirty=1 waiter=1 authpin=1 0x56001aeb1700]
2023-07-15T13:33:01.347-0400 7f2d8788f700 20 mds.0.locker inode is file
2023-07-15T13:33:01.347-0400 7f2d8788f700 20 mds.0.locker client has write caps; m->get_max_size=0; old_max=4194304
2023-07-15T13:33:01.347-0400 7f2d8788f700 10 mds.0.locker eval 3648 [inode 0x10000000001 [2,head] /bar/test auth v132334 ap=5 s=0 n(v0 rc2023-07-15T13:33:00.982044-0400 1=1+0) (iauth sync->excl r=1) (ilink sync r=1) (ifile xlock x=1 by 0x56001b11df80) (ixattr excl->sync) (iversion lock) cr={13924=0-4194304@1} caps={7205=pLs/-@3,13924=pAsLsXsFcb/pAsxXsxFxwb@13},l=13924 | ptrwaiter=0 request=2 lock=4 caps=1 truncating=0 dirtyparent=0 dirty=1 waiter=1 authpin=1 0x56001aeb1700]
2023-07-15T13:33:01.347-0400 7f2d8788f700 10 mds.0.locker eval_gather (ifile xlock x=1 by 0x56001b11df80) on [inode 0x10000000001 [2,head] /bar/test auth v132334 ap=5 s=0 n(v0 rc2023-07-15T13:33:00.982044-0400 1=1+0) (iauth sync->excl r=1) (ilink sync r=1) (ifile xlock x=1 by 0x56001b11df80) (ixattr excl->sync) (iversion lock) cr={13924=0-4194304@1} caps={7205=pLs/-@3,13924=pAsLsXsFcb/pAsxXsxFxwb@13},l=13924 | ptrwaiter=0 request=2 lock=4 caps=1 truncating=0 dirtyparent=0 dirty=1 waiter=1 authpin=1 0x56001aeb1700]
2023-07-15T13:33:01.347-0400 7f2d8788f700 10 mds.0.locker next state is lock issued/allows loner cb/cb xlocker /cb other /cb
2023-07-15T13:33:01.347-0400 7f2d8788f700 10 mds.0.locker eval_gather (iauth sync->excl r=1) on [inode 0x10000000001 [2,head] /bar/test auth v132334 ap=5 s=0 n(v0 rc2023-07-15T13:33:00.982044-0400 1=1+0) (iauth sync->excl r=1) (ilink sync r=1) (ifile xlock x=1 by 0x56001b11df80) (ixattr excl->sync) (iversion lock) cr={13924=0-4194304@1} caps={7205=pLs/-@3,13924=pAsLsXsFcb/pAsxXsxFxwb@13},l=13924 | ptrwaiter=0 request=2 lock=4 caps=1 truncating=0 dirtyparent=0 dirty=1 waiter=1 authpin=1 0x56001aeb1700]
2023-07-15T13:33:01.347-0400 7f2d8788f700 10 mds.0.locker next state is excl issued/allows loner s/sx xlocker /sx other /
2023-07-15T13:33:01.347-0400 7f2d8788f700 10 mds.0.locker simple_eval (ilink sync r=1) on [inode 0x10000000001 [2,head] /bar/test auth v132334 ap=5 s=0 n(v0 rc2023-07-15T13:33:00.982044-0400 1=1+0) (iauth sync->excl r=1) (ilink sync r=1) (ifile xlock x=1 by 0x56001b11df80) (ixattr excl->sync) (iversion lock) cr={13924=0-4194304@1} caps={7205=pLs/-@3,13924=pAsLsXsFcb/pAsxXsxFxwb@13},l=13924 | ptrwaiter=0 request=2 lock=4 caps=1 truncating=0 dirtyparent=0 dirty=1 waiter=1 authpin=1 0x56001aeb1700]
2023-07-15T13:33:01.347-0400 7f2d8788f700 10 mds.0.locker eval_gather (ixattr excl->sync) on [inode 0x10000000001 [2,head] /bar/test auth v132334 ap=5 s=0 n(v0 rc2023-07-15T13:33:00.982044-0400 1=1+0) (iauth sync->excl r=1) (ilink sync r=1) (ifile xlock x=1 by 0x56001b11df80) (ixattr excl->sync) (iversion lock) cr={13924=0-4194304@1} caps={7205=pLs/-@3,13924=pAsLsXsFcb/pAsxXsxFxwb@13},l=13924 | ptrwaiter=0 request=2 lock=4 caps=1 truncating=0 dirtyparent=0 dirty=1 waiter=1 authpin=1 0x56001aeb1700]
2023-07-15T13:33:01.347-0400 7f2d8788f700 10 mds.0.locker next state is sync issued/allows loner s/s xlocker /s other /s
2023-07-15T13:33:01.347-0400 7f2d8788f700 7 mds.0.locker eval_gather finished gather on (ixattr excl->sync) on [inode 0x10000000001 [2,head] /bar/test auth v132334 ap=5 s=0 n(v0 rc2023-07-15T13:33:00.982044-0400 1=1+0) (iauth sync->excl r=1) (ilink sync r=1) (ifile xlock x=1 by 0x56001b11df80) (ixattr excl->sync) (iversion lock) cr={13924=0-4194304@1} caps={7205=pLs/-@3,13924=pAsLsXsFcb/pAsxXsxFxwb@13},l=13924 | ptrwaiter=0 request=2 lock=4 caps=1 truncating=0 dirtyparent=0 dirty=1 waiter=1 authpin=1 0x56001aeb1700]
2023-07-15T13:33:01.347-0400 7f2d8788f700 10 mds.0.cache.ino(0x10000000001) auth_unpin by 0x56001aeb1a40 on [inode 0x10000000001 [2,head] /bar/test auth v132334 ap=4 s=0 n(v0 rc2023-07-15T13:33:00.982044-0400 1=1+0) (iauth sync->excl r=1) (ilink sync r=1) (ifile xlock x=1 by 0x56001b11df80) (iversion lock) cr={13924=0-4194304@1} caps={7205=pLs/-@3,13924=pAsLsXsFcb/pAsxXsxFxwb@13},l=13924 | ptrwaiter=0 request=2 lock=4 caps=1 truncating=0 dirtyparent=0 dirty=1 waiter=1 authpin=1 0x56001aeb1700] now 4
2023-07-15T13:33:01.347-0400 7f2d8788f700 15 mds.0.cache.dir(0x10000000000) adjust_nested_auth_pins -1 on [dir 0x10000000000 /bar/ [2,head] auth v=132335 cv=76971/76971 ap=0+5 state=1610874881|complete f(v0 m2023-07-14T22:49:04.657776-0400 1=1+0) n(v0 rc2023-07-15T13:33:00.982044-0400 1=1+0) hs=1+0,ss=0+0 dirty=1 | child=1 dirty=1 authpin=0 0x560015fbd600] by 0x56001aeb1a40 count now 0/5
2023-07-15T13:33:01.347-0400 7f2d8788f700 10 mds.0.locker simple_eval (ixattr sync) on [inode 0x10000000001 [2,head] /bar/test auth v132334 ap=4 s=0 n(v0 rc2023-07-15T13:33:00.982044-0400 1=1+0) (iauth sync->excl r=1) (ilink sync r=1) (ifile xlock x=1 by 0x56001b11df80) (iversion lock) cr={13924=0-4194304@1} caps={7205=pLs/-@3,13924=pAsLsXsFcb/pAsxXsxFxwb@13},l=13924 | ptrwaiter=0 request=2 lock=4 caps=1 truncating=0 dirtyparent=0 dirty=1 waiter=1 authpin=1 0x56001aeb1700]
2023-07-15T13:33:01.347-0400 7f2d8788f700 7 mds.0.locker simple_eval stable, going to excl (ixattr sync) on [inode 0x10000000001 [2,head] /bar/test auth v132334 ap=4 s=0 n(v0 rc2023-07-15T13:33:00.982044-0400 1=1+0) (iauth sync->excl r=1) (ilink sync r=1) (ifile xlock x=1 by 0x56001b11df80) (iversion lock) cr={13924=0-4194304@1} caps={7205=pLs/-@3,13924=pAsLsXsFcb/pAsxXsxFxwb@13},l=13924 | ptrwaiter=0 request=2 lock=4 caps=1 truncating=0 dirtyparent=0 dirty=1 waiter=1 authpin=1 0x56001aeb1700]
2023-07-15T13:33:01.347-0400 7f2d8788f700 7 mds.0.locker simple_excl on (ixattr sync) on [inode 0x10000000001 [2,head] /bar/test auth v132334 ap=4 s=0 n(v0 rc2023-07-15T13:33:00.982044-0400 1=1+0) (iauth sync->excl r=1) (ilink sync r=1) (ifile xlock x=1 by 0x56001b11df80) (iversion lock) cr={13924=0-4194304@1} caps={7205=pLs/-@3,13924=pAsLsXsFcb/pAsxXsxFxwb@13},l=13924 | ptrwaiter=0 request=2 lock=4 caps=1 truncating=0 dirtyparent=0 dirty=1 waiter=1 authpin=1 0x56001aeb1700]
2023-07-15T13:33:01.347-0400 7f2d8788f700 10 MDSContext::complete: 18C_MDS_RetryRequest
2023-07-15T13:33:01.347-0400 7f2d8788f700 7 mds.0.server dispatch_client_request client_request(client.7205:24769 getattr AsLsXsFs #0x10000000001 2023-07-15T13:33:01.286827-0400 caller_uid=10000, caller_gid=100{10,100,}) v4
2023-07-15T13:33:01.347-0400 7f2d8788f700 10 mds.0.server rdlock_path_pin_ref request(client.7205:24769 nref=3 cr=0x56001bc23200) #0x10000000001
2023-07-15T13:33:01.347-0400 7f2d8788f700 10 mds.0.locker acquire_locks request(client.7205:24769 nref=3 cr=0x56001bc23200)
2023-07-15T13:33:01.347-0400 7f2d8788f700 20 mds.0.locker must rdlock (ilink sync r=1) [inode 0x10000000001 [2,head] /bar/test auth v132334 ap=4 s=0 n(v0 rc2023-07-15T13:33:00.982044-0400 1=1+0) (iauth sync->excl r=1) (ilink sync r=1) (ifile xlock x=1 by 0x56001b11df80) (ixattr excl) (iversion lock) cr={13924=0-4194304@1} caps={7205=pLs/-@3,13924=pAsLsXsFcb/pAsxXsxFxwb@13},l=13924 | ptrwaiter=0 request=2 lock=4 caps=1 truncating=0 dirtyparent=0 dirty=1 waiter=1 authpin=1 0x56001aeb1700]
2023-07-15T13:33:01.347-0400 7f2d8788f700 20 mds.0.locker must rdlock (iauth sync->excl r=1) [inode 0x10000000001 [2,head] /bar/test auth v132334 ap=4 s=0 n(v0 rc2023-07-15T13:33:00.982044-0400 1=1+0) (iauth sync->excl r=1) (ilink sync r=1) (ifile xlock x=1 by 0x56001b11df80) (ixattr excl) (iversion lock) cr={13924=0-4194304@1} caps={7205=pLs/-@3,13924=pAsLsXsFcb/pAsxXsxFxwb@13},l=13924 | ptrwaiter=0 request=2 lock=4 caps=1 truncating=0 dirtyparent=0 dirty=1 waiter=1 authpin=1 0x56001aeb1700]
2023-07-15T13:33:01.347-0400 7f2d8788f700 20 mds.0.locker must rdlock (ixattr excl) [inode 0x10000000001 [2,head] /bar/test auth v132334 ap=4 s=0 n(v0 rc2023-07-15T13:33:00.982044-0400 1=1+0) (iauth sync->excl r=1) (ilink sync r=1) (ifile xlock x=1 by 0x56001b11df80) (ixattr excl) (iversion lock) cr={13924=0-4194304@1} caps={7205=pLs/-@3,13924=pAsLsXsFcb/pAsxXsxFxwb@13},l=13924 | ptrwaiter=0 request=2 lock=4 caps=1 truncating=0 dirtyparent=0 dirty=1 waiter=1 authpin=1 0x56001aeb1700]
BUG NOW ASKING FOR ifile
2023-07-15T13:33:01.347-0400 7f2d8788f700 20 mds.0.locker must rdlock (ifile xlock x=1 by 0x56001b11df80) [inode 0x10000000001 [2,head] /bar/test auth v132334 ap=4 s=0 n(v0 rc2023-07-15T13:33:00.982044-0400 1=1+0) (iauth sync->excl r=1) (ilink sync r=1) (ifile xlock x=1 by 0x56001b11df80) (ixattr excl) (iversion lock) cr={13924=0-4194304@1} caps={7205=pLs/-@3,13924=pAsLsXsFcb/pAsxXsxFxwb@13},l=13924 | ptrwaiter=0 request=2 lock=4 caps=1 truncating=0 dirtyparent=0 dirty=1 waiter=1 authpin=1 0x56001aeb1700]
2023-07-15T13:33:01.347-0400 7f2d8788f700 10 mds.0.locker must authpin [inode 0x10000000001 [2,head] /bar/test auth v132334 ap=4 s=0 n(v0 rc2023-07-15T13:33:00.982044-0400 1=1+0) (iauth sync->excl r=1) (ilink sync r=1) (ifile xlock x=1 by 0x56001b11df80) (ixattr excl) (iversion lock) cr={13924=0-4194304@1} caps={7205=pLs/-@3,13924=pAsLsXsFcb/pAsxXsxFxwb@13},l=13924 | ptrwaiter=0 request=2 lock=4 caps=1 truncating=0 dirtyparent=0 dirty=1 waiter=1 authpin=1 0x56001aeb1700]
2023-07-15T13:33:01.347-0400 7f2d8788f700 10 mds.0.locker already auth_pinned [inode 0x10000000001 [2,head] /bar/test auth v132334 ap=4 s=0 n(v0 rc2023-07-15T13:33:00.982044-0400 1=1+0) (iauth sync->excl r=1) (ilink sync r=1) (ifile xlock x=1 by 0x56001b11df80) (ixattr excl) (iversion lock) cr={13924=0-4194304@1} caps={7205=pLs/-@3,13924=pAsLsXsFcb/pAsxXsxFxwb@13},l=13924 | ptrwaiter=0 request=2 lock=4 caps=1 truncating=0 dirtyparent=0 dirty=1 waiter=1 authpin=1 0x56001aeb1700]
2023-07-15T13:33:01.347-0400 7f2d8788f700 7 mds.0.locker rdlock_start on (ifile xlock x=1 by 0x56001b11df80) on [inode 0x10000000001 [2,head] /bar/test auth v132334 ap=4 s=0 n(v0 rc2023-07-15T13:33:00.982044-0400 1=1+0) (iauth sync->excl r=1) (ilink sync r=1) (ifile xlock x=1 by 0x56001b11df80) (ixattr excl) (iversion lock) cr={13924=0-4194304@1} caps={7205=pLs/-@3,13924=pAsLsXsFcb/pAsxXsxFxwb@13},l=13924 | ptrwaiter=0 request=2 lock=4 caps=1 truncating=0 dirtyparent=0 dirty=1 waiter=1 authpin=1 0x56001aeb1700]
2023-07-15T13:33:01.347-0400 7f2d8788f700 7 mds.0.locker rdlock_start waiting on (ifile xlock x=1 by 0x56001b11df80) on [inode 0x10000000001 [2,head] /bar/test auth v132334 ap=4 s=0 n(v0 rc2023-07-15T13:33:00.982044-0400 1=1+0) (iauth sync->excl r=1) (ilink sync r=1) (ifile xlock x=1 by 0x56001b11df80) (ixattr excl) (iversion lock) cr={13924=0-4194304@1} caps={7205=pLs/-@3,13924=pAsLsXsFcb/pAsxXsxFxwb@13},l=13924 | ptrwaiter=0 request=2 lock=4 caps=1 truncating=0 dirtyparent=0 dirty=1 waiter=1 authpin=1 0x56001aeb1700]
2023-07-15T13:33:01.347-0400 7f2d8788f700 10 mds.0.cache.ino(0x10000000001) add_waiter tag 2000000040000000 0x56001b2b5ec0 !ambig 1 !frozen 1 !freezing 1
2023-07-15T13:33:01.347-0400 7f2d8788f700 15 mds.0.cache.ino(0x10000000001) taking waiter here
2023-07-15T13:33:01.347-0400 7f2d8788f700 10 mds.0.locker nudge_log (ifile xlock x=1 by 0x56001b11df80) on [inode 0x10000000001 [2,head] /bar/test auth v132334 ap=4 s=0 n(v0 rc2023-07-15T13:33:00.982044-0400 1=1+0) (iauth sync->excl r=1) (ilink sync r=1) (ifile xlock x=1 by 0x56001b11df80) (ixattr excl) (iversion lock) cr={13924=0-4194304@1} caps={7205=pLs/-@3,13924=pAsLsXsFcb/pAsxXsxFxwb@13},l=13924 | ptrwaiter=0 request=2 lock=4 caps=1 truncating=0 dirtyparent=0 dirty=1 waiter=1 authpin=1 0x56001aeb1700]
2023-07-15T13:33:01.347-0400 7f2d8788f700 7 mds.0.locker get_allowed_caps loner client.13924 allowed=pAsLsXsxFcb, xlocker allowed=pAsLsXsxFcb, others allowed=pLsFcb on [inode 0x10000000001 [2,head] /bar/test auth v132334 ap=4 s=0 n(v0 rc2023-07-15T13:33:00.982044-0400 1=1+0) (iauth sync->excl r=1) (ilink sync r=1) (ifile xlock x=1 by 0x56001b11df80) (ixattr excl) (iversion lock) cr={13924=0-4194304@1} caps={7205=pLs/-@3,13924=pAsLsXsFcb/pAsxXsxFxwb@13},l=13924 | ptrwaiter=0 request=2 lock=4 caps=1 truncating=0 dirtyparent=0 dirty=1 waiter=1 authpin=1 0x56001aeb1700]
2023-07-15T13:33:01.347-0400 7f2d8788f700 20 mds.0.locker client.7205 pending pLs allowed pLsFcb wanted -
2023-07-15T13:33:01.347-0400 7f2d8788f700 7 mds.0.locker get_allowed_caps loner client.13924 allowed=pAsLsXsxFcb, xlocker allowed=pAsLsXsxFcb, others allowed=pLsFcb on [inode 0x10000000001 [2,head] /bar/test auth v132334 ap=4 s=0 n(v0 rc2023-07-15T13:33:00.982044-0400 1=1+0) (iauth sync->excl r=1) (ilink sync r=1) (ifile xlock x=1 by 0x56001b11df80) (ixattr excl) (iversion lock) cr={13924=0-4194304@1} caps={7205=pLs/-@3,13924=pAsLsXsFcb/pAsxXsxFxwb@13},l=13924 | ptrwaiter=0 request=2 lock=4 caps=1 truncating=0 dirtyparent=0 dirty=1 waiter=1 authpin=1 0x56001aeb1700]
2023-07-15T13:33:01.347-0400 7f2d8788f700 20 mds.0.locker client.13924 pending pAsLsXsFcb allowed pAsLsXsxFcb wanted pAsxXsxFxwb
2023-07-15T13:33:01.347-0400 7f2d8788f700 7 mds.0.locker sending MClientCaps to client.13924 seq 14 new pending pAsLsXsxFcb was pAsLsXsFcb
2023-07-15T13:33:01.347-0400 7f2d8788f700 20 mds.0.cache.ino(0x10000000001) encode_cap_message pfile 0 pauth 0 plink 0 pxattr 0 mtime 2023-07-15T13:33:00.982044-0400 ctime 2023-07-15T13:33:00.982044-0400 change_attr 31374
2023-07-15T13:33:01.347-0400 7f2d8788f700 10 mds.0.10 send_message_client_counted client.13924 seq 16 client_caps(grant ino 0x10000000001 30880 seq 14 caps=pAsLsXsxFcb dirty=- wanted=pAsxXsxFxwb follows 0 size 0/4194304 ts 9110/0 mtime 2023-07-15T13:33:00.982044-0400 ctime 2023-07-15T13:33:00.982044-0400 change_attr 31374 tws 15414) v12
2023-07-15T13:33:01.347-0400 7f2d8788f700 1 -- [v2:192.168.230.102:6872/3649207549,v1:192.168.230.102:6873/3649207549] --> v1:192.168.230.102:0/3806998182 -- client_caps(grant ino 0x10000000001 30880 seq 14 caps=pAsLsXsxFcb dirty=- wanted=pAsxXsxFxwb follows 0 size 0/4194304 ts 9110/0 mtime 2023-07-15T13:33:00.982044-0400 ctime 2023-07-15T13:33:00.982044-0400 change_attr 31374 tws 15414) v12 -- 0x56001b3b6380 con 0x56001aef5c00
2023-07-15T13:33:01.347-0400 7f2d8788f700 10 mds.0.locker eval done
</pre>
Note the second getattr adds the rdlock on the filelock:
<pre>
2023-07-15T13:33:01.345-0400 7f2d81883700 20 mds.0.locker must rdlock (ifile excl->lock) [inode 0x10000000001 [2,head] /bar/test auth v132334 ap=4 s=0 n(v0 rc2023-07-15T13:33:00.982044-0400 1=1+0) (iauth excl) (ifile excl->lock) (ixattr excl) (iversion lock) cr={13924=0-4194304@1} caps={7205=pLsFc/-@2,13924=pAsxLsXsxFcb/pAsxLsXsxFscb/pAsxXsxFxwb@11},l=13924 | ptrwaiter=0 request=2 lock=1 caps=1 truncating=0 dirtyparent=0 dirty=1 waiter=1 authpin=1 0x56001aeb1700]
</pre>
This causes the lock order change resulting in the deadlock.
Reproducing this is tricky as it requires the right order of lock state changes to reproduce. Broadly:
- Do open("...", O_CREAT|O_TRUNC|...) on a number of kernel clients and write a variable amount of data. The kernel client should remount each time to its caches. This will result in a create + setattr + getattr from the kclient.
- Have a number of clients stating the file to produce a constant stream of getattrs.
Finally, because of a recent change in the kernel [1], the MDS must be patched to add O_TRUNC manually to the create request (hack!). I'm not certain this can be reproduced easily without doing this. I have not tried with ceph-fuse to do this differently.
[1] https://github.com/ceph/ceph-client/commit/7cb9994754f8a36ae9e5ec4597c5c4c2d6c03832