Actions
Bug #63685
closedmds: FAILED ceph_assert(_head.empty())
% Done:
0%
Source:
Tags:
Backport:
quincy,reef,pacific
Regression:
No
Severity:
3 - minor
Reviewed:
Affected Versions:
ceph-qa-suite:
Component(FS):
Labels (FS):
Pull request ID:
Crash signature (v1):
Crash signature (v2):
Description
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.
Actions