Ceph » CephFS

When I was running some xfstests locally I hit the mds crash:

  -129> 2023-11-30T10:21:45.810+0800 7fe51f97b640 10 mds.0.cache.strays  inode is [inode 0x10000009d3b [...2,head] ~mds0/stray5/10000009d3b/ auth v79513 DIRTYPARENT f() n(v0 rc2023-11-30T10:21:39.674268+0800 1=0+1) (inest lock) (iversion lock) | request=0 lock=0 dirfrag=0 caps=0 dirtyparent=1 dirty=1 authpin=0 0x56285f7dac00]
  -128> 2023-11-30T10:21:45.810+0800 7fe51f97b640 10 mds.0.cache clear_dirty_bits_for_stray [inode 0x10000009d3b [...2,head] ~mds0/stray5/10000009d3b/ auth v79513 DIRTYPARENT f() n(v0 rc2023-11-30T10:21:39.674268+0800 1=0+1) (inest lock) (iversion lock) | request=0 lock=0 dirfrag=0 caps=0 dirtyparent=1 dirty=1 authpin=0 0x56285f7dac00]
  -127> 2023-11-30T10:21:45.810+0800 7fe51f97b640 10 mds.0.cache.dir(0x10000009d3b) try_remove_dentries_for_stray
  -126> 2023-11-30T10:21:45.810+0800 7fe51f97b640 14 mds.0.cache.ino(0x10000009d3b) close_dirfrag *
  -125> 2023-11-30T10:21:45.810+0800 7fe51f97b640 12 mds.0.cache.dir(0x10000009d3b) remove_null_dentries [dir 0x10000009d3b ~mds0/stray5/10000009d3b/ [2,head] auth v=1 cv=0/0 state=1073741825|complete f() n() hs=0+0,ss=0+0 0x562859e6b600]
  -124> 2023-11-30T10:21:45.810+0800 7fe51f97b640 10 mds.0.cache.ino(0x10000009d3b) clear_dirty_parent
  -123> 2023-11-30T10:21:45.810+0800 7fe51f97b640 20 mds.0.cache.strays enqueue: purging dn: [dentry #0x100/stray5/10000009d3b [2,head] auth (dversion lock) v=79513 ino=0x10000009d3b state=1879048213|new | request=0 lock=0 inodepin=1 dirty=1 authpin=0 0x56285e73d400]
  -122> 2023-11-30T10:21:45.810+0800 7fe51f97b640 10 mds.0.cache.dir(0x605) auth_pin by 0x562858d735b8 on [dir 0x605 ~mds0/stray5/ [2,head] auth v=79536 cv=79482/79482 ap=3+0 state=1610620929|complete|sticky f(v0 m2023-11-30T10:21:44.439498+0800 11=8+3) n(v0 rc2023-11-30T10:21:44.439498+0800 b2138112 11=8+3) hs=11+7,ss=0+0 dirty=11 | child=1 sticky=1 dirty=1 authpin=1 0x562858dda880] count now 3
  -121> 2023-11-30T10:21:45.810+0800 7fe51f97b640 10 mds.0.cache.strays purge [dentry #0x100/stray5/10000009d3b [2,head] auth (dversion lock) v=79513 ino=0x10000009d3b state=1879048245|new | request=0 lock=0 inodepin=1 purging=1 dirty=1 authpin=0 0x56285e73d400] [inode 0x10000009d3b [...2,head] ~mds0/stray5/10000009d3b/ auth v79513 f() n(v0 rc2023-11-30T10:21:39.674268+0800 1=0+1) (inest lock) (iversion lock) | request=0 lock=0 dirfrag=0 caps=0 dirtyparent=0 dirty=1 authpin=0 0x56285f7dac00]
  -120> 2023-11-30T10:21:45.810+0800 7fe51f97b640  4 mds.0.purge_queue push: pushing inode 0x10000009d3b
  -119> 2023-11-30T10:21:45.810+0800 7fe51f97b640 20 mds.0.purge_queue _can_consume: 0/64 ops, 0/64 files
  -118> 2023-11-30T10:21:45.810+0800 7fe51f97b640 10 mds.0.purge_queue _consume:  not readable right now
  -117> 2023-11-30T10:21:45.810+0800 7fe51f97b640 10 mds.0.cache.strays enqueue: purging this dentry immediately: [dentry #0x100/stray5/10000009d3b [2,head] auth (dversion lock) v=79513 ino=0x10000009d3b state=1879048245|new | request=0 lock=0 inodepin=1 purging=1 dirty=1 authpin=0 0x56285e73d400]
  -116> 2023-11-30T10:21:45.810+0800 7fe51f97b640 10 mds.0.cache.strays eval_stray [dentry #0x100/stray6/100000092b8 [2,head] auth (dversion lock) v=78342 ino=0x100000092b8 state=1879048209|new | request=0 lock=0 inodepin=1 dirty=1 authpin=0 0x56285f101680]
  -115> 2023-11-30T10:21:45.810+0800 7fe51f97b640 10 mds.0.cache.strays  inode is [inode 0x100000092b8 [2,head] ~mds0/stray6/100000092b8 auth v78342 DIRTYPARENT s=413696 nl=0 n(v0 rc2023-11-30T10:21:39.678247+0800 b413696 1=1+0) (iversion lock) cr={4254=0-4194304@1} | ptrwaiter=0 request=0 lock=0 caps=0 dirtyparent=1 dirty=1 authpin=0 0x56285b2ab700]
  -114> 2023-11-30T10:21:45.810+0800 7fe51f97b640 10 mds.0.cache.ino(0x100000092b8) clear_dirty_parent
  -113> 2023-11-30T10:21:45.810+0800 7fe51f97b640 20 mds.0.cache.strays enqueue: purging dn: [dentry #0x100/stray6/100000092b8 [2,head] auth (dversion lock) v=78342 ino=0x100000092b8 state=1879048213|new | request=0 lock=0 inodepin=1 dirty=1 authpin=0 0x56285f101680]
  -112> 2023-11-30T10:21:45.810+0800 7fe51f97b640 10 mds.0.cache.dir(0x606) auth_pin by 0x562858d735b8 on [dir 0x606 ~mds0/stray6/ [2,head] auth v=78353 cv=78329/78329 ap=1+0 state=1610620929|complete|sticky f(v0 m2023-11-30T10:21:43.247942+0800 3=3+0) n(v1 rc2023-11-30T10:21:43.247942+0800 b1286144 3=3+0) hs=3+9,ss=0+0 dirty=3 | child=1 sticky=1 dirty=1 authpin=1 0x562858ddad00] count now 1
  -111> 2023-11-30T10:21:45.810+0800 7fe51f97b640 10 mds.0.cache.strays purge [dentry #0x100/stray6/100000092b8 [2,head] auth (dversion lock) v=78342 ino=0x100000092b8 state=1879048245|new | request=0 lock=0 inodepin=1 purging=1 dirty=1 authpin=0 0x56285f101680] [inode 0x100000092b8 [2,head] ~mds0/stray6/100000092b8 auth v78342 s=413696 nl=0 n(v0 rc2023-11-30T10:21:39.678247+0800 b413696 1=1+0) (iversion lock) cr={4254=0-4194304@1} | ptrwaiter=0 request=0 lock=0 caps=0 dirtyparent=0 dirty=1 authpin=0 0x56285b2ab700]
  -110> 2023-11-30T10:21:45.810+0800 7fe51f97b640 10 mds.0.cache.strays  realm snaprealm(0x100 seq 1 lc 0 cr 0 cps 1 snaps={} last_modified 0.000000 change_attr 0 0x562858d65200)
  -109> 2023-11-30T10:21:45.810+0800 7fe51f97b640  4 mds.0.purge_queue push: pushing inode 0x100000092b8
  -108> 2023-11-30T10:21:45.810+0800 7fe51f97b640 20 mds.0.purge_queue _can_consume: 0/64 ops, 0/64 files
  -107> 2023-11-30T10:21:45.810+0800 7fe51f97b640 10 mds.0.purge_queue _consume:  not readable right now
  -106> 2023-11-30T10:21:45.810+0800 7fe51f97b640 10 mds.0.cache.strays enqueue: purging this dentry immediately: [dentry #0x100/stray6/100000092b8 [2,head] auth (dversion lock) v=78342 ino=0x100000092b8 state=1879048245|new | request=0 lock=0 inodepin=1 purging=1 dirty=1 authpin=0 0x56285f101680]
  -105> 2023-11-30T10:21:45.810+0800 7fe51f97b640 10 mds.0.cache.strays eval_stray [dentry #0x100/stray4/10000009d40 [2,head] auth (dversion lock) v=79472 ino=0x10000009d40 state=1879048209|new | request=0 lock=0 inodepin=1 dirty=1 authpin=0 0x56285baaa780]
  -104> 2023-11-30T10:21:45.810+0800 7fe51f97b640 10 mds.0.cache.strays  inode is [inode 0x10000009d40 [2,head] ~mds0/stray4/10000009d40 auth v79472 DIRTYPARENT s=0 nl=0 n(v0 rc2023-11-30T10:21:39.697145+0800 1=1+0) (iversion lock) cr={4254=0-4194304@1} | request=0 lock=0 caps=0 dirtyparent=1 dirty=1 authpin=0 0x56285b64db80]
  -103> 2023-11-30T10:21:45.810+0800 7fe51f97b640 10 mds.0.cache.ino(0x10000009d40) clear_dirty_parent
  -102> 2023-11-30T10:21:45.810+0800 7fe51f97b640 20 mds.0.cache.strays enqueue: purging dn: [dentry #0x100/stray4/10000009d40 [2,head] auth (dversion lock) v=79472 ino=0x10000009d40 state=1879048213|new | request=0 lock=0 inodepin=1 dirty=1 authpin=0 0x56285baaa780]
  -101> 2023-11-30T10:21:45.810+0800 7fe51f97b640 10 mds.0.cache.dir(0x604) auth_pin by 0x562858d735b8 on [dir 0x604 ~mds0/stray4/ [2,head] auth pv=79763 v=79483 cv=79445/79445 ap=3+2 state=1610620929|complete|sticky f(v0 m2023-11-30T10:21:43.337458+0800 5=4+1) n(v0 rc2023-11-30T10:21:43.337458+0800 5=4+1) hs=5+11,ss=0+0 dirty=5 | child=1 sticky=1 dirty=1 authpin=1 0x562858dda400] count now 3
  -100> 2023-11-30T10:21:45.810+0800 7fe51f97b640 10 mds.0.cache.strays purge [dentry #0x100/stray4/10000009d40 [2,head] auth (dversion lock) v=79472 ino=0x10000009d40 state=1879048245|new | request=0 lock=0 inodepin=1 purging=1 dirty=1 authpin=0 0x56285baaa780] [inode 0x10000009d40 [2,head] ~mds0/stray4/10000009d40 auth v79472 s=0 nl=0 n(v0 rc2023-11-30T10:21:39.697145+0800 1=1+0) (iversion lock) cr={4254=0-4194304@1} | request=0 lock=0 caps=0 dirtyparent=0 dirty=1 authpin=0 0x56285b64db80]
   -99> 2023-11-30T10:21:45.810+0800 7fe51f97b640 10 mds.0.cache.strays  realm snaprealm(0x100 seq 1 lc 0 cr 0 cps 1 snaps={} last_modified 0.000000 change_attr 0 0x562858d65200)
   -98> 2023-11-30T10:21:45.810+0800 7fe51f97b640  4 mds.0.purge_queue push: pushing inode 0x10000009d40
   -97> 2023-11-30T10:21:45.810+0800 7fe51f97b640 20 mds.0.purge_queue _can_consume: 0/64 ops, 0/64 files
   -96> 2023-11-30T10:21:45.810+0800 7fe51f97b640 10 mds.0.purge_queue _consume:  not readable right now
   -95> 2023-11-30T10:21:45.810+0800 7fe51f97b640 10 mds.0.cache.strays enqueue: purging this dentry immediately: [dentry #0x100/stray4/10000009d40 [2,head] auth (dversion lock) v=79472 ino=0x10000009d40 state=1879048245|new | request=0 lock=0 inodepin=1 purging=1 dirty=1 authpin=0 0x56285baaa780]
   -94> 2023-11-30T10:21:45.810+0800 7fe51f97b640 10 mds.0.cache.strays eval_stray [dentry #0x100/stray9/10000009d3f [2,head] auth (dversion lock) v=78344 ino=0x10000009d3f state=1879048209|new | request=0 lock=0 inodepin=1 dirty=1 authpin=0 0x56285ff74f00]
   -93> 2023-11-30T10:21:45.810+0800 7fe51f97b640 10 mds.0.cache.strays  inode is [inode 0x10000009d3f [2,head] ~mds0/stray9/10000009d3f auth v78344 DIRTYPARENT s=0 nl=0 n(v0 rc2023-11-30T10:21:39.703112+0800 1=1+0) (iversion lock) cr={4254=0-4194304@1} | request=0 lock=0 caps=0 dirtyparent=1 dirty=1 authpin=0 0x56285b64e100]
   -92> 2023-11-30T10:21:45.810+0800 7fe51f97b640 10 mds.0.cache.ino(0x10000009d3f) clear_dirty_parent
   -91> 2023-11-30T10:21:45.810+0800 7fe51f97b640 20 mds.0.cache.strays enqueue: purging dn: [dentry #0x100/stray9/10000009d3f [2,head] auth (dversion lock) v=78344 ino=0x10000009d3f state=1879048213|new | request=0 lock=0 inodepin=1 dirty=1 authpin=0 0x56285ff74f00]
   -90> 2023-11-30T10:21:45.810+0800 7fe51f97b640 10 mds.0.cache.dir(0x609) auth_pin by 0x562858d735b8 on [dir 0x609 ~mds0/stray9/ [2,head] auth pv=79578 v=79574 cv=78337/78337 ap=3+2 state=1610883073|complete|sticky f(v0 m2023-11-30T10:21:44.108289+0800 10=7+3) n(v1 rc2023-11-30T10:21:44.108289+0800 b4669440 10=7+3) hs=10+13,ss=0+0 dirty=11 | child=1 sticky=1 dirty=1 authpin=1 0x562858ddba80] count now 3
   -89> 2023-11-30T10:21:45.810+0800 7fe51f97b640 10 mds.0.cache.strays purge [dentry #0x100/stray9/10000009d3f [2,head] auth (dversion lock) v=78344 ino=0x10000009d3f state=1879048245|new | request=0 lock=0 inodepin=1 purging=1 dirty=1 authpin=0 0x56285ff74f00] [inode 0x10000009d3f [2,head] ~mds0/stray9/10000009d3f auth v78344 s=0 nl=0 n(v0 rc2023-11-30T10:21:39.703112+0800 1=1+0) (iversion lock) cr={4254=0-4194304@1} | request=0 lock=0 caps=0 dirtyparent=0 dirty=1 authpin=0 0x56285b64e100]
   -88> 2023-11-30T10:21:45.811+0800 7fe51f97b640 10 mds.0.cache.strays  realm snaprealm(0x100 seq 1 lc 0 cr 0 cps 1 snaps={} last_modified 0.000000 change_attr 0 0x562858d65200)
   -87> 2023-11-30T10:21:45.811+0800 7fe51f97b640  4 mds.0.purge_queue push: pushing inode 0x10000009d3f
   -86> 2023-11-30T10:21:45.811+0800 7fe51f97b640 20 mds.0.purge_queue _can_consume: 0/64 ops, 0/64 files
   -85> 2023-11-30T10:21:45.811+0800 7fe51f97b640 10 mds.0.purge_queue _consume:  not readable right now
   -84> 2023-11-30T10:21:45.811+0800 7fe51f97b640 10 mds.0.cache.strays enqueue: purging this dentry immediately: [dentry #0x100/stray9/10000009d3f [2,head] auth (dversion lock) v=78344 ino=0x10000009d3f state=1879048245|new | request=0 lock=0 inodepin=1 purging=1 dirty=1 authpin=0 0x56285ff74f00]
   -83> 2023-11-30T10:21:45.811+0800 7fe51f97b640 10 mds.0.cache.strays eval_stray [dentry #0x100/stray2/100000092bb [2,head] auth (dversion lock) v=79715 ino=0x100000092bb state=1879048209|new | request=0 lock=0 inodepin=1 dirty=1 authpin=0 0x5628594ee000]
   -82> 2023-11-30T10:21:45.811+0800 7fe51f97b640 10 mds.0.cache.strays  inode is [inode 0x100000092bb [2,head] ~mds0/stray2/100000092bb auth v79715 DIRTYPARENT s=0 nl=0 n(v0 rc2023-11-30T10:21:39.709080+0800 1=1+0) (iversion lock) cr={4254=0-4194304@1} | request=0 lock=0 caps=0 dirtyparent=1 dirty=1 authpin=0 0x56285b64c000]
   -81> 2023-11-30T10:21:45.811+0800 7fe51f97b640 10 mds.0.cache.ino(0x100000092bb) clear_dirty_parent
   -80> 2023-11-30T10:21:45.811+0800 7fe51f97b640 20 mds.0.cache.strays enqueue: purging dn: [dentry #0x100/stray2/100000092bb [2,head] auth (dversion lock) v=79715 ino=0x100000092bb state=1879048213|new | request=0 lock=0 inodepin=1 dirty=1 authpin=0 0x5628594ee000]
   -79> 2023-11-30T10:21:45.811+0800 7fe51f97b640 10 mds.0.cache.dir(0x602) auth_pin by 0x562858d735b8 on [dir 0x602 ~mds0/stray2/ [2,head] auth v=79789 cv=79712/79712 ap=1+0 state=1610620929|complete|sticky f(v0 m2023-11-30T10:21:44.404686+0800 7=7+0) n(v0 rc2023-11-30T10:21:44.404686+0800 b1183744 7=7+0) hs=7+11,ss=0+0 dirty=8 | child=1 sticky=1 dirty=1 authpin=1 0x562858dd9b00] count now 1
   -78> 2023-11-30T10:21:45.811+0800 7fe51f97b640 10 mds.0.cache.strays purge [dentry #0x100/stray2/100000092bb [2,head] auth (dversion lock) v=79715 ino=0x100000092bb state=1879048245|new | request=0 lock=0 inodepin=1 purging=1 dirty=1 authpin=0 0x5628594ee000] [inode 0x100000092bb [2,head] ~mds0/stray2/100000092bb auth v79715 s=0 nl=0 n(v0 rc2023-11-30T10:21:39.709080+0800 1=1+0) (iversion lock) cr={4254=0-4194304@1} | request=0 lock=0 caps=0 dirtyparent=0 dirty=1 authpin=0 0x56285b64c000]
   -77> 2023-11-30T10:21:45.811+0800 7fe51f97b640 10 mds.0.cache.strays  realm snaprealm(0x100 seq 1 lc 0 cr 0 cps 1 snaps={} last_modified 0.000000 change_attr 0 0x562858d65200)
   -76> 2023-11-30T10:21:45.811+0800 7fe51f97b640  4 mds.0.purge_queue push: pushing inode 0x100000092bb
   -75> 2023-11-30T10:21:45.811+0800 7fe51f97b640 20 mds.0.purge_queue _can_consume: 0/64 ops, 0/64 files
   -74> 2023-11-30T10:21:45.811+0800 7fe51f97b640 10 mds.0.purge_queue _consume:  not readable right now
   -73> 2023-11-30T10:21:45.811+0800 7fe51f97b640 10 mds.0.cache.strays enqueue: purging this dentry immediately: [dentry #0x100/stray2/100000092bb [2,head] auth (dversion lock) v=79715 ino=0x100000092bb state=1879048245|new | request=0 lock=0 inodepin=1 purging=1 dirty=1 authpin=0 0x5628594ee000]
   -72> 2023-11-30T10:21:45.811+0800 7fe51f97b640 10 mds.0.cache.strays eval_stray [dentry #0x100/stray8/10000009d36 [2,head] auth (dversion lock) v=78425 ino=0x10000009d36 state=1879048209|new | request=0 lock=0 inodepin=1 dirty=1 authpin=0 0x56285f420f00]
   -71> 2023-11-30T10:21:45.811+0800 7fe51f97b640 10 mds.0.cache.strays  inode is [inode 0x10000009d36 [...2,head] ~mds0/stray8/10000009d36/ auth v78425 DIRTYPARENT f(v0 m2023-11-30T10:21:39.423624+0800) n(v0 rc2023-11-30T10:21:39.653381+0800 1=0+1) (inest lock) (iversion lock) | request=0 lock=0 dirfrag=0 caps=0 dirtyparent=1 dirty=1 waiter=0 authpin=0 0x5628593d8580]
   -70> 2023-11-30T10:21:45.811+0800 7fe51f97b640 10 mds.0.cache clear_dirty_bits_for_stray [inode 0x10000009d36 [...2,head] ~mds0/stray8/10000009d36/ auth v78425 DIRTYPARENT f(v0 m2023-11-30T10:21:39.423624+0800) n(v0 rc2023-11-30T10:21:39.653381+0800 1=0+1) (inest lock) (iversion lock) | request=0 lock=0 dirfrag=0 caps=0 dirtyparent=1 dirty=1 waiter=0 authpin=0 0x5628593d8580]
   -69> 2023-11-30T10:21:45.811+0800 7fe51f97b640 10 mds.0.cache.dir(0x10000009d36) try_remove_dentries_for_stray
   -68> 2023-11-30T10:21:45.811+0800 7fe51f97b640 14 mds.0.cache.ino(0x10000009d36) close_dirfrag *
   -67> 2023-11-30T10:21:45.811+0800 7fe51f97b640 12 mds.0.cache.dir(0x10000009d36) remove_null_dentries [dir 0x10000009d36 ~mds0/stray8/10000009d36/ [2,head] auth v=28 cv=0/0 state=1073741825|complete f(v0 m2023-11-30T10:21:39.423624+0800) n(v0 rc2023-11-30T10:21:39.423624+0800) hs=0+0,ss=0+0 0x56285db55680]
   -66> 2023-11-30T10:21:45.811+0800 7fe51f97b640 10 mds.0.cache.ino(0x10000009d36) clear_dirty_parent
   -65> 2023-11-30T10:21:45.811+0800 7fe51f97b640 20 mds.0.cache.strays enqueue: purging dn: [dentry #0x100/stray8/10000009d36 [2,head] auth (dversion lock) v=78425 ino=0x10000009d36 state=1879048213|new | request=0 lock=0 inodepin=1 dirty=1 authpin=0 0x56285f420f00]
   -64> 2023-11-30T10:21:45.811+0800 7fe51f97b640 10 mds.0.cache.dir(0x608) auth_pin by 0x562858d735b8 on [dir 0x608 ~mds0/stray8/ [2,head] auth pv=79801 v=79797 cv=78414/78414 ap=4+2 state=1610620929|complete|sticky f(v0 m2023-11-30T10:21:44.421594+0800 10=6+4) n(v0 rc2023-11-30T10:21:44.457401+0800 b2011136 10=6+4) hs=10+12,ss=0+0 dirty=12 | child=1 sticky=1 dirty=1 authpin=1 0x562858ddb600] count now 4
   -63> 2023-11-30T10:21:45.811+0800 7fe51f97b640 10 mds.0.cache.strays purge [dentry #0x100/stray8/10000009d36 [2,head] auth (dversion lock) v=78425 ino=0x10000009d36 state=1879048245|new | request=0 lock=0 inodepin=1 purging=1 dirty=1 authpin=0 0x56285f420f00] [inode 0x10000009d36 [...2,head] ~mds0/stray8/10000009d36/ auth v78425 f(v0 m2023-11-30T10:21:39.423624+0800) n(v0 rc2023-11-30T10:21:39.653381+0800 1=0+1) (inest lock) (iversion lock) | request=0 lock=0 dirfrag=0 caps=0 dirtyparent=0 dirty=1 waiter=0 authpin=0 0x5628593d8580]
   -62> 2023-11-30T10:21:45.811+0800 7fe51f97b640  4 mds.0.purge_queue push: pushing inode 0x10000009d36
   -61> 2023-11-30T10:21:45.811+0800 7fe51f97b640 20 mds.0.purge_queue _can_consume: 0/64 ops, 0/64 files
   -60> 2023-11-30T10:21:45.811+0800 7fe51f97b640 10 mds.0.purge_queue _consume:  not readable right now
   -59> 2023-11-30T10:21:45.811+0800 7fe51f97b640 10 mds.0.cache.strays enqueue: purging this dentry immediately: [dentry #0x100/stray8/10000009d36 [2,head] auth (dversion lock) v=78425 ino=0x10000009d36 state=1879048245|new | request=0 lock=0 inodepin=1 purging=1 dirty=1 authpin=0 0x56285f420f00]
   -58> 2023-11-30T10:21:45.811+0800 7fe51f97b640 10 mds.0.cache.strays eval_stray [dentry #0x100/stray8/100000092b6 [2,head] auth (dversion lock) v=78429 ino=0x100000092b6 state=1879048209|new | request=0 lock=0 inodepin=1 dirty=1 authpin=0 0x562859640500]
   -57> 2023-11-30T10:21:45.811+0800 7fe51f97b640 10 mds.0.cache.strays  inode is [inode 0x100000092b6 [2,head] ~mds0/stray8/100000092b6 auth v78429 DIRTYPARENT s=0 nl=0 n(v0 rc2023-11-30T10:21:39.979617+0800 1=1+0) (iversion lock) cr={4254=0-4194304@1} | request=0 lock=0 caps=0 dirtyparent=1 dirty=1 authpin=0 0x5628593db180]
   -56> 2023-11-30T10:21:45.811+0800 7fe51f97b640 10 mds.0.cache.ino(0x100000092b6) clear_dirty_parent
   -55> 2023-11-30T10:21:45.811+0800 7fe51f97b640 20 mds.0.cache.strays enqueue: purging dn: [dentry #0x100/stray8/100000092b6 [2,head] auth (dversion lock) v=78429 ino=0x100000092b6 state=1879048213|new | request=0 lock=0 inodepin=1 dirty=1 authpin=0 0x562859640500]
   -54> 2023-11-30T10:21:45.811+0800 7fe51f97b640 10 mds.0.cache.dir(0x608) auth_pin by 0x562858d735b8 on [dir 0x608 ~mds0/stray8/ [2,head] auth pv=79801 v=79797 cv=78414/78414 ap=5+2 state=1610620929|complete|sticky f(v0 m2023-11-30T10:21:44.421594+0800 10=6+4) n(v0 rc2023-11-30T10:21:44.457401+0800 b2011136 10=6+4) hs=10+12,ss=0+0 dirty=12 | child=1 sticky=1 dirty=1 authpin=1 0x562858ddb600] count now 5
   -53> 2023-11-30T10:21:45.811+0800 7fe51f97b640 10 mds.0.cache.strays purge [dentry #0x100/stray8/100000092b6 [2,head] auth (dversion lock) v=78429 ino=0x100000092b6 state=1879048245|new | request=0 lock=0 inodepin=1 purging=1 dirty=1 authpin=0 0x562859640500] [inode 0x100000092b6 [2,head] ~mds0/stray8/100000092b6 auth v78429 s=0 nl=0 n(v0 rc2023-11-30T10:21:39.979617+0800 1=1+0) (iversion lock) cr={4254=0-4194304@1} | request=0 lock=0 caps=0 dirtyparent=0 dirty=1 authpin=0 0x5628593db180]
   -52> 2023-11-30T10:21:45.811+0800 7fe51f97b640 10 mds.0.cache.strays  realm snaprealm(0x100 seq 1 lc 0 cr 0 cps 1 snaps={} last_modified 0.000000 change_attr 0 0x562858d65200)
   -51> 2023-11-30T10:21:45.811+0800 7fe51f97b640  4 mds.0.purge_queue push: pushing inode 0x100000092b6
   -50> 2023-11-30T10:21:45.811+0800 7fe51f97b640 20 mds.0.purge_queue _can_consume: 0/64 ops, 0/64 files
   -49> 2023-11-30T10:21:45.811+0800 7fe51f97b640 10 mds.0.purge_queue _consume:  not readable right now
   -48> 2023-11-30T10:21:45.811+0800 7fe51f97b640 10 mds.0.cache.strays enqueue: purging this dentry immediately: [dentry #0x100/stray8/100000092b6 [2,head] auth (dversion lock) v=78429 ino=0x100000092b6 state=1879048245|new | request=0 lock=0 inodepin=1 purging=1 dirty=1 authpin=0 0x562859640500]
   -47> 2023-11-30T10:21:45.811+0800 7fe51f97b640 10 mds.0.cache.strays eval_stray [dentry #0x100/stray9/10000009d3c [2,head] auth (dversion lock) v=78346 ino=0x10000009d3c state=1879048209|new | request=0 lock=0 inodepin=1 dirty=1 authpin=0 0x56285e978500]
   -46> 2023-11-30T10:21:45.811+0800 7fe51f97b640 10 mds.0.cache.strays  inode is [inode 0x10000009d3c [...2,head] ~mds0/stray9/10000009d3c/ auth v78346 DIRTYPARENT f() n(v0 rc2023-11-30T10:21:39.707091+0800 1=0+1) (inest lock) (iversion lock) | request=0 lock=0 dirfrag=0 caps=0 dirtyparent=1 dirty=1 authpin=0 0x56285f7d9080]
   -45> 2023-11-30T10:21:45.811+0800 7fe51f97b640 10 mds.0.cache clear_dirty_bits_for_stray [inode 0x10000009d3c [...2,head] ~mds0/stray9/10000009d3c/ auth v78346 DIRTYPARENT f() n(v0 rc2023-11-30T10:21:39.707091+0800 1=0+1) (inest lock) (iversion lock) | request=0 lock=0 dirfrag=0 caps=0 dirtyparent=1 dirty=1 authpin=0 0x56285f7d9080]
   -44> 2023-11-30T10:21:45.811+0800 7fe51f97b640 10 mds.0.cache.dir(0x10000009d3c) try_remove_dentries_for_stray
   -43> 2023-11-30T10:21:45.811+0800 7fe51f97b640 14 mds.0.cache.ino(0x10000009d3c) close_dirfrag *
   -42> 2023-11-30T10:21:45.811+0800 7fe51f97b640 12 mds.0.cache.dir(0x10000009d3c) remove_null_dentries [dir 0x10000009d3c ~mds0/stray9/10000009d3c/ [2,head] auth v=1 cv=0/0 state=1073741825|complete f() n() hs=0+0,ss=0+0 0x56286505f180]
   -41> 2023-11-30T10:21:45.811+0800 7fe51f97b640 10 mds.0.cache.ino(0x10000009d3c) clear_dirty_parent
   -40> 2023-11-30T10:21:45.811+0800 7fe51f97b640 20 mds.0.cache.strays enqueue: purging dn: [dentry #0x100/stray9/10000009d3c [2,head] auth (dversion lock) v=78346 ino=0x10000009d3c state=1879048213|new | request=0 lock=0 inodepin=1 dirty=1 authpin=0 0x56285e978500]
   -39> 2023-11-30T10:21:45.811+0800 7fe51f97b640 10 mds.0.cache.dir(0x609) auth_pin by 0x562858d735b8 on [dir 0x609 ~mds0/stray9/ [2,head] auth pv=79578 v=79574 cv=78337/78337 ap=4+2 state=1610883073|complete|sticky f(v0 m2023-11-30T10:21:44.108289+0800 10=7+3) n(v1 rc2023-11-30T10:21:44.108289+0800 b4669440 10=7+3) hs=10+13,ss=0+0 dirty=11 | child=1 sticky=1 dirty=1 authpin=1 0x562858ddba80] count now 4
   -38> 2023-11-30T10:21:45.811+0800 7fe51f97b640 10 mds.0.cache.strays purge [dentry #0x100/stray9/10000009d3c [2,head] auth (dversion lock) v=78346 ino=0x10000009d3c state=1879048245|new | request=0 lock=0 inodepin=1 purging=1 dirty=1 authpin=0 0x56285e978500] [inode 0x10000009d3c [...2,head] ~mds0/stray9/10000009d3c/ auth v78346 f() n(v0 rc2023-11-30T10:21:39.707091+0800 1=0+1) (inest lock) (iversion lock) | request=0 lock=0 dirfrag=0 caps=0 dirtyparent=0 dirty=1 authpin=0 0x56285f7d9080]
   -37> 2023-11-30T10:21:45.811+0800 7fe51f97b640  4 mds.0.purge_queue push: pushing inode 0x10000009d3c
   -36> 2023-11-30T10:21:45.811+0800 7fe51f97b640 20 mds.0.purge_queue _can_consume: 0/64 ops, 0/64 files
   -35> 2023-11-30T10:21:45.811+0800 7fe51f97b640 10 mds.0.purge_queue _consume:  not readable right now
   -34> 2023-11-30T10:21:45.811+0800 7fe51f97b640 10 mds.0.cache.strays enqueue: purging this dentry immediately: [dentry #0x100/stray9/10000009d3c [2,head] auth (dversion lock) v=78346 ino=0x10000009d3c state=1879048245|new | request=0 lock=0 inodepin=1 purging=1 dirty=1 authpin=0 0x56285e978500]
   -33> 2023-11-30T10:21:45.811+0800 7fe51f97b640 10 mds.0.cache.strays eval_stray [dentry #0x100/stray0/10000009d3e [2,head] auth (dversion lock) v=78279 ino=0x10000009d3e state=1879048209|new | request=0 lock=0 inodepin=1 dirty=1 authpin=0 0x56285ff74000]
   -32> 2023-11-30T10:21:45.811+0800 7fe51f97b640 10 mds.0.cache.strays  inode is [inode 0x10000009d3e [2,head] ~mds0/stray0/10000009d3e auth v78279 DIRTYPARENT s=729088 nl=0 n(v0 rc2023-11-30T10:21:39.715048+0800 b729088 1=1+0) (iversion lock) cr={4254=0-4194304@1} | ptrwaiter=0 request=0 lock=0 caps=0 dirtyparent=1 dirty=1 authpin=0 0x56285f7d9b80]
   -31> 2023-11-30T10:21:45.811+0800 7fe51f97b640 10 mds.0.cache.ino(0x10000009d3e) clear_dirty_parent
   -30> 2023-11-30T10:21:45.811+0800 7fe51f97b640 20 mds.0.cache.strays enqueue: purging dn: [dentry #0x100/stray0/10000009d3e [2,head] auth (dversion lock) v=78279 ino=0x10000009d3e state=1879048213|new | request=0 lock=0 inodepin=1 dirty=1 authpin=0 0x56285ff74000]
   -29> 2023-11-30T10:21:45.811+0800 7fe51f97b640 10 mds.0.cache.dir(0x600) auth_pin by 0x562858d735b8 on [dir 0x600 ~mds0/stray0/ [2,head] auth pv=79554 v=79552 cv=78272/78272 ap=2+1 state=1610883073|complete|sticky f(v0 m2023-11-30T10:21:43.351382+0800 7=6+1) n(v0 rc2023-11-30T10:21:43.351382+0800 b3432448 7=6+1) hs=7+7,ss=0+0 dirty=8 | child=1 sticky=1 dirty=1 authpin=1 0x562858dd9200] count now 2
   -28> 2023-11-30T10:21:45.811+0800 7fe51f97b640 10 mds.0.cache.strays purge [dentry #0x100/stray0/10000009d3e [2,head] auth (dversion lock) v=78279 ino=0x10000009d3e state=1879048245|new | request=0 lock=0 inodepin=1 purging=1 dirty=1 authpin=0 0x56285ff74000] [inode 0x10000009d3e [2,head] ~mds0/stray0/10000009d3e auth v78279 s=729088 nl=0 n(v0 rc2023-11-30T10:21:39.715048+0800 b729088 1=1+0) (iversion lock) cr={4254=0-4194304@1} | ptrwaiter=0 request=0 lock=0 caps=0 dirtyparent=0 dirty=1 authpin=0 0x56285f7d9b80]
   -27> 2023-11-30T10:21:45.811+0800 7fe51f97b640 10 mds.0.cache.strays  realm snaprealm(0x100 seq 1 lc 0 cr 0 cps 1 snaps={} last_modified 0.000000 change_attr 0 0x562858d65200)
   -26> 2023-11-30T10:21:45.811+0800 7fe51f97b640  4 mds.0.purge_queue push: pushing inode 0x10000009d3e
   -25> 2023-11-30T10:21:45.811+0800 7fe51f97b640 20 mds.0.purge_queue _can_consume: 0/64 ops, 0/64 files
   -24> 2023-11-30T10:21:45.811+0800 7fe51f97b640 10 mds.0.purge_queue _consume:  not readable right now
   -23> 2023-11-30T10:21:45.811+0800 7fe51f97b640 10 mds.0.cache.strays enqueue: purging this dentry immediately: [dentry #0x100/stray0/10000009d3e [2,head] auth (dversion lock) v=78279 ino=0x10000009d3e state=1879048245|new | request=0 lock=0 inodepin=1 purging=1 dirty=1 authpin=0 0x56285ff74000]
   -22> 2023-11-30T10:21:45.811+0800 7fe51f97b640 10 mds.0.cache.strays eval_stray [dentry #0x100/stray4/100000092be [2,head] auth (dversion lock) v=79474 ino=0x100000092be state=1879048209|new | request=0 lock=0 inodepin=1 dirty=1 authpin=0 0x56285ee76f00]
   -21> 2023-11-30T10:21:45.811+0800 7fe51f97b640 10 mds.0.cache.strays  inode is [inode 0x100000092be [2,head] ~mds0/stray4/100000092be auth v79474 DIRTYPARENT s=0 nl=0 n(v0 rc2023-11-30T10:21:40.002493+0800 1=1+0) (iversion lock) cr={4254=0-4194304@1} | request=0 lock=0 caps=0 dirtyparent=1 dirty=1 waiter=0 authpin=0 0x56285bad4100]
   -20> 2023-11-30T10:21:45.811+0800 7fe51f97b640 10 mds.0.cache.ino(0x100000092be) clear_dirty_parent
   -19> 2023-11-30T10:21:45.811+0800 7fe51f97b640 20 mds.0.cache.strays enqueue: purging dn: [dentry #0x100/stray4/100000092be [2,head] auth (dversion lock) v=79474 ino=0x100000092be state=1879048213|new | request=0 lock=0 inodepin=1 dirty=1 authpin=0 0x56285ee76f00]
   -18> 2023-11-30T10:21:45.811+0800 7fe51f97b640 10 mds.0.cache.dir(0x604) auth_pin by 0x562858d735b8 on [dir 0x604 ~mds0/stray4/ [2,head] auth pv=79763 v=79483 cv=79445/79445 ap=4+2 state=1610620929|complete|sticky f(v0 m2023-11-30T10:21:43.337458+0800 5=4+1) n(v0 rc2023-11-30T10:21:43.337458+0800 5=4+1) hs=5+11,ss=0+0 dirty=5 | child=1 sticky=1 dirty=1 authpin=1 0x562858dda400] count now 4
   -17> 2023-11-30T10:21:45.811+0800 7fe51f97b640 10 mds.0.cache.strays purge [dentry #0x100/stray4/100000092be [2,head] auth (dversion lock) v=79474 ino=0x100000092be state=1879048245|new | request=0 lock=0 inodepin=1 purging=1 dirty=1 authpin=0 0x56285ee76f00] [inode 0x100000092be [2,head] ~mds0/stray4/100000092be auth v79474 s=0 nl=0 n(v0 rc2023-11-30T10:21:40.002493+0800 1=1+0) (iversion lock) cr={4254=0-4194304@1} | request=0 lock=0 caps=0 dirtyparent=0 dirty=1 waiter=0 authpin=0 0x56285bad4100]
   -16> 2023-11-30T10:21:45.811+0800 7fe51f97b640 10 mds.0.cache.strays  realm snaprealm(0x100 seq 1 lc 0 cr 0 cps 1 snaps={} last_modified 0.000000 change_attr 0 0x562858d65200)
   -15> 2023-11-30T10:21:45.811+0800 7fe51f97b640  4 mds.0.purge_queue push: pushing inode 0x100000092be
   -14> 2023-11-30T10:21:45.811+0800 7fe51f97b640 20 mds.0.purge_queue _can_consume: 0/64 ops, 0/64 files
   -13> 2023-11-30T10:21:45.811+0800 7fe51f97b640 10 mds.0.purge_queue _consume:  not readable right now
   -12> 2023-11-30T10:21:45.811+0800 7fe51f97b640 10 mds.0.cache.strays enqueue: purging this dentry immediately: [dentry #0x100/stray4/100000092be [2,head] auth (dversion lock) v=79474 ino=0x100000092be state=1879048245|new | request=0 lock=0 inodepin=1 purging=1 dirty=1 authpin=0 0x56285ee76f00]
   -11> 2023-11-30T10:21:45.811+0800 7fe51f97b640 10 mds.0.cache.strays eval_stray [dentry #0x100/stray7/10000009d25 [2,head] auth (dversion lock) v=78672 ino=0x10000009d25 state=1879048209|new | request=0 lock=0 inodepin=1 dirty=1 authpin=0 0x56285f870780]
   -10> 2023-11-30T10:21:45.811+0800 7fe51f97b640 10 mds.0.cache.strays  inode is [inode 0x10000009d25 [...2,head] ~mds0/stray7/10000009d25/ auth v78672 DIRTYPARENT f(v0 m2023-11-30T10:21:38.672685+0800) n(v0 rc2023-11-30T10:21:40.008461+0800 1=0+1) (inest lock) (iversion lock) | dirtyscattered=0 request=0 lock=0 dirfrag=0 caps=0 dirtyparent=1 dirty=1 waiter=0 authpin=0 0x56285b2e6b00]
    -9> 2023-11-30T10:21:45.811+0800 7fe51f97b640 10 mds.0.cache clear_dirty_bits_for_stray [inode 0x10000009d25 [...2,head] ~mds0/stray7/10000009d25/ auth v78672 DIRTYPARENT f(v0 m2023-11-30T10:21:38.672685+0800) n(v0 rc2023-11-30T10:21:40.008461+0800 1=0+1) (inest lock) (iversion lock) | dirtyscattered=0 request=0 lock=0 dirfrag=0 caps=0 dirtyparent=1 dirty=1 waiter=0 authpin=0 0x56285b2e6b00]
    -8> 2023-11-30T10:21:45.811+0800 7fe51f97b640 10 mds.0.cache.dir(0x10000009d25) try_remove_dentries_for_stray
    -7> 2023-11-30T10:21:45.811+0800 7fe51f97b640 14 mds.0.cache.ino(0x10000009d25) close_dirfrag *
    -6> 2023-11-30T10:21:45.811+0800 7fe51f97b640 12 mds.0.cache.dir(0x10000009d25) remove_null_dentries [dir 0x10000009d25 ~mds0/stray7/10000009d25/ [2,head] auth v=30 cv=0/0 state=1073741825|complete f(v0 m2023-11-30T10:21:38.672685+0800) n(v0 rc2023-11-30T10:21:38.672685+0800) hs=0+0,ss=0+0 0x562859576400]
    -5> 2023-11-30T10:21:45.860+0800 7fe522981640 10 monclient: tick
    -4> 2023-11-30T10:21:45.860+0800 7fe522981640 10 monclient: _check_auth_tickets
    -3> 2023-11-30T10:21:45.860+0800 7fe522981640 10 monclient: _check_auth_rotating renewing rotating keys (they expired before 2023-11-30T10:21:15.860971+0800)
    -2> 2023-11-30T10:21:45.913+0800 7fe523983640  1 -- v1:192.168.0.103:6813/3126691049 <== client.4254 v1:192.168.0.103:0/3585876660 99518 ==== client_caps(update ino 0x10000009a3c 1 seq 5 caps=pAsLsXsFsc dirty=- wanted=- follows 0 size 2105344/0 mtime 2023-11-30T10:21:35.767397+0800 ctime 2023-11-30T10:21:35.767397+0800 change_attr 22 tws 1 xattrs(v=18446744071793450223 l=0)) v12 ==== 316+0+0 (unknown 1434914571 0 0) 0x56285c24a000 con 0x562858f82400
    -1> 2023-11-30T10:21:46.015+0800 7fe51f97b640 -1 /home/xiubli/cephdev/ceph/src/include/elist.h: In function 'elist<T>::~elist() [with T = MDLockCache::DirItem*]' thread 7fe51f97b640 time 2023-11-30T10:21:45.812068+0800
/home/xiubli/cephdev/ceph/src/include/elist.h: 91: FAILED ceph_assert(_head.empty())

 ceph version 18.0.0-6843-g092ae0c319c (092ae0c319ca3f6846be394747507421c8f9c257) reef (dev)
 1: (ceph::__ceph_assert_fail(char const*, char const*, int, char const*)+0x11c) [0x7fe529898769]
 2: (ceph::register_assert_context(ceph::common::CephContext*)+0) [0x7fe529898970]
 3: (CDir::~CDir()+0x3c5) [0x562852d48345]
 4: (CDir::~CDir()+0x9) [0x562852d483df]
 5: (CInode::close_dirfrag(frag_t)+0x6de) [0x562852d83086]
 6: (CInode::close_dirfrags()+0x44) [0x562852d8314e]
 7: (StrayManager::_eval_stray(CDentry*)+0x1233) [0x562852c60509]
 8: (StrayManager::eval_stray(CDentry*)+0x1c) [0x562852c6062e]
 9: (StrayManager::advance_delayed()+0x69) [0x562852c6069d]
 10: (MDCache::trim(unsigned long)+0x8e) [0x562852bac908]
 11: (MDCache::upkeep_main()+0x67f) [0x562852bc2d3b]
 12: (std::thread::_State_impl<std::thread::_Invoker<std::tuple<void (MDCache::*)(), MDCache*> > >::_M_run()+0x2a) [0x562852c0bfc0]
 13: /lib64/libstdc++.so.6(+0xdb9d4) [0x7fe528adb9d4]
 14: /lib64/libc.so.6(+0x9f832) [0x7fe52869f832]
 15: /lib64/libc.so.6(+0x3f450) [0x7fe52863f450]

     0> 2023-11-30T10:21:46.065+0800 7fe51f97b640 -1 *** Caught signal (Aborted) **
 in thread 7fe51f97b640 thread_name:ms_dispatch

 ceph version 18.0.0-6843-g092ae0c319c (092ae0c319ca3f6846be394747507421c8f9c257) reef (dev)
 1: /lib64/libc.so.6(+0x54df0) [0x7fe528654df0]
 2: /lib64/libc.so.6(+0xa157c) [0x7fe5286a157c]
 3: raise()
 4: abort()
 5: (ceph::__ceph_assert_fail(char const*, char const*, int, char const*)+0x263) [0x7fe5298988b0]
 6: (ceph::register_assert_context(ceph::common::CephContext*)+0) [0x7fe529898970]
 7: (CDir::~CDir()+0x3c5) [0x562852d48345]
 8: (CDir::~CDir()+0x9) [0x562852d483df]
 9: (CInode::close_dirfrag(frag_t)+0x6de) [0x562852d83086]
 10: (CInode::close_dirfrags()+0x44) [0x562852d8314e]
 11: (StrayManager::_eval_stray(CDentry*)+0x1233) [0x562852c60509]
 12: (StrayManager::eval_stray(CDentry*)+0x1c) [0x562852c6062e]
 13: (StrayManager::advance_delayed()+0x69) [0x562852c6069d]
 14: (MDCache::trim(unsigned long)+0x8e) [0x562852bac908]
 15: (MDCache::upkeep_main()+0x67f) [0x562852bc2d3b]
 16: (std::thread::_State_impl<std::thread::_Invoker<std::tuple<void (MDCache::*)(), MDCache*> > >::_M_run()+0x2a) [0x562852c0bfc0]
 17: /lib64/libstdc++.so.6(+0xdb9d4) [0x7fe528adb9d4]
 18: /lib64/libc.so.6(+0x9f832) [0x7fe52869f832]
 19: /lib64/libc.so.6(+0x3f450) [0x7fe52863f450]
 NOTE: a copy of the executable, or `objdump -rdS <executable>` is needed to interpret this.