Actions
Bug #69844
closedmds: assert crash at FAILED ceph_assert(o->get_num_ref() == 0)
Status:
Resolved
Priority:
Urgent
Assignee:
Category:
Correctness/Safety
Target version:
% Done:
0%
Source:
Q/A
Backport:
squid,reef
Regression:
No
Severity:
2 - major
Reviewed:
Affected Versions:
ceph-qa-suite:
ceph-deploy
Component(FS):
MDS, quiesce
Labels (FS):
crash
Pull request ID:
Tags (freeform):
backport_processed
Merge Commit:
Fixed In:
v19.3.0-7581-ge80e73c6c3
Released In:
v20.2.0~1123
Upkeep Timestamp:
2025-11-01T01:32:13+00:00
Description
2025-02-06T07:25:39.912+0000 7f3832dd7640 20 mds.2.purge_queue _consume: decoding entry 2025-02-06T07:25:39.912+0000 7f3832dd7640 20 mds.2.purge_queue _consume: executing item (0x30000001680) 2025-02-06T07:25:39.912+0000 7f3832dd7640 10 mds.2.purge_queue _execute_item: remove backtrace object 30000001680.00000000 pool 4 snapc 6=[6,5] 2025-02-06T07:25:39.912+0000 7f3832dd7640 10 mds.2.purge_queue _execute_item: remove backtrace object 30000001680.00000000 old pool 3 snapc 6=[6,5] 2025-02-06T07:25:39.912+0000 7f3832dd7640 20 mds.2.purge_queue _can_consume: 16/16 ops, 8/64 files 2025-02-06T07:25:39.912+0000 7f3832dd7640 20 mds.2.purge_queue _can_consume: Throttling on op limit 16/16 2025-02-06T07:25:39.912+0000 7f3832dd7640 10 mds.2.purge_queue _consume: cannot consume right now 2025-02-06T07:25:39.912+0000 7f3832dd7640 10 mds.2.purge_queue _commit_ops: PURGE_FILE 2025-02-06T07:25:39.912+0000 7f3832dd7640 1 -- [v2:172.21.15.192:6836/128425721,v1:172.21.15.192:6837/128425721] --> [v2:172.21.15.196:6824/911994908,v1:172.21.15.196:6825/911994908] -- osd_op(unknown.0.21:27234 4.1fs0 4:fe9c624a:::30000001624.00000000:head [delete] snapc 6=[6,5] ondisk+write+known_if_redirected+full_force+supports_pool_eio e87) -- 0x55b54ae84400 con 0x55b546fdc000 2025-02-06T07:25:39.912+0000 7f3832dd7640 10 mds.2.purge_queue _commit_ops: PURGE_FILE 2025-02-06T07:25:39.912+0000 7f3832dd7640 1 -- [v2:172.21.15.192:6836/128425721,v1:172.21.15.192:6837/128425721] --> [v2:172.21.15.196:6824/911994908,v1:172.21.15.196:6825/911994908] -- osd_op(unknown.0.21:27235 3.3f 3:fe9c624a:::30000001624.00000000:head [delete] snapc 6=[6,5] ondisk+write+known_if_redirected+full_force+supports_pool_eio e87) -- 0x55b5472ba800 con 0x55b546fdc000 2025-02-06T07:25:39.912+0000 7f3832dd7640 10 mds.2.purge_queue _commit_ops: PURGE_FILE 2025-02-06T07:25:39.912+0000 7f3832dd7640 1 -- [v2:172.21.15.192:6836/128425721,v1:172.21.15.192:6837/128425721] --> [v2:172.21.15.177:6826/1885875871,v1:172.21.15.177:6827/1885875871] -- osd_op(unknown.0.21:27236 4.17s0 4:ef016ba0:::30000001636.00000000:head [delete] snapc 6=[6,5] ondisk+write+known_if_redirected+full_force+supports_pool_eio e87) -- 0x55b54beb8400 con 0x55b546fd6400 2025-02-06T07:25:39.912+0000 7f3832dd7640 10 mds.2.purge_queue _commit_ops: PURGE_FILE 2025-02-06T07:25:39.912+0000 7f3832dd7640 1 -- [v2:172.21.15.192:6836/128425721,v1:172.21.15.192:6837/128425721] --> [v2:172.21.15.192:6800/2150231619,v1:172.21.15.192:6801/2150231619] -- osd_op(unknown.0.21:27237 3.37 3:ef016ba0:::30000001636.00000000:head [delete] snapc 6=[6,5] ondisk+write+known_if_redirected+full_force+supports_pool_eio e87) -- 0x55b546d49400 con 0x55b54936b800 2025-02-06T07:25:39.912+0000 7f3832dd7640 10 mds.2.purge_queue _commit_ops: PURGE_FILE 2025-02-06T07:25:39.912+0000 7f3832dd7640 1 -- [v2:172.21.15.192:6836/128425721,v1:172.21.15.192:6837/128425721] --> [v2:172.21.15.196:6816/630658411,v1:172.21.15.196:6817/630658411] -- osd_op(unknown.0.21:27238 4.fs0 4:f2ffe141:::30000001680.00000000:head [delete] snapc 6=[6,5] ondisk+write+known_if_redirected+full_force+supports_pool_eio e87) -- 0x55b54dce1c00 con 0x55b546d49000 2025-02-06T07:25:39.912+0000 7f3832dd7640 10 mds.2.purge_queue _commit_ops: PURGE_FILE 2025-02-06T07:25:39.912+0000 7f3832dd7640 1 -- [v2:172.21.15.192:6836/128425721,v1:172.21.15.192:6837/128425721] --> [v2:172.21.15.192:6816/3467572071,v1:172.21.15.192:6817/3467572071] -- osd_op(unknown.0.21:27239 3.f 3:f2ffe141:::30000001680.00000000:head [delete] snapc 6=[6,5] ondisk+write+known_if_redirected+full_force+supports_pool_eio e87) -- 0x55b54eeefc00 con 0x55b546d49800 2025-02-06T07:25:39.912+0000 7f383bde9640 2 --2- [v2:172.21.15.192:6836/128425721,v1:172.21.15.192:6837/128425721] >> [v2:172.21.15.177:6826/1885875871,v1:172.21.15.177:6827/1885875871] conn(0x55b546fd6400 0x55b546f76c00 crc :-1 s=READY pgs=8 cs=0 l=1 rev1=1 crypto rx=0 tx=0 comp rx=0 tx=0).write_message sending message m=0x55b54beb8400 seq=2097 osd_op(mds.2.21:27236 4.17s0 4:ef016ba0:::30000001636.00000000:head [delete] snapc 6=[6,5] ondisk+write+known_if_redirected+full_force+supports_pool_eio e87) 2025-02-06T07:25:39.912+0000 7f383b5e8640 2 --2- [v2:172.21.15.192:6836/128425721,v1:172.21.15.192:6837/128425721] >> [v2:172.21.15.192:6800/2150231619,v1:172.21.15.192:6801/2150231619] conn(0x55b54936b800 0x55b549490000 crc :-1 s=READY pgs=14 cs=0 l=1 rev1=1 crypto rx=0 tx=0 comp rx=0 tx=0).write_message sending message m=0x55b546d49400 seq=1642 osd_op(mds.2.21:27237 3.37 3:ef016ba0:::30000001636.00000000:head [delete] snapc 6=[6,5] ondisk+write+known_if_redirected+full_force+supports_pool_eio e87) 2025-02-06T07:25:39.912+0000 7f383b5e8640 2 --2- [v2:172.21.15.192:6836/128425721,v1:172.21.15.192:6837/128425721] >> [v2:172.21.15.196:6816/630658411,v1:172.21.15.196:6817/630658411] conn(0x55b546d49000 0x55b546f76100 crc :-1 s=READY pgs=8 cs=0 l=1 rev1=1 crypto rx=0 tx=0 comp rx=0 tx=0).write_message sending message m=0x55b54dce1c00 seq=1990 osd_op(mds.2.21:27238 4.fs0 4:f2ffe141:::30000001680.00000000:head [delete] snapc 6=[6,5] ondisk+write+known_if_redirected+full_force+supports_pool_eio e87) 2025-02-06T07:25:39.913+0000 7f3831dd5640 -1 /home/jenkins-build/build/workspace/ceph-dev-new-build/ARCH/x86_64/AVAILABLE_ARCH/x86_64/AVAILABLE_DIST/centos9/DIST/centos9/MACHINE_SIZE/gigantic/release/19.3.0-7359-gbda3f257/rpm/el9/BUILD/ceph-19.3.0-7359-gbda3f257/src/mds/MDCache.cc: In function 'void MDCache::remove_inode(CInode*)' thread 7f3831dd5640 time 2025-02-06T07:25:39.913191+0000 /home/jenkins-build/build/workspace/ceph-dev-new-build/ARCH/x86_64/AVAILABLE_ARCH/x86_64/AVAILABLE_DIST/centos9/DIST/centos9/MACHINE_SIZE/gigantic/release/19.3.0-7359-gbda3f257/rpm/el9/BUILD/ceph-19.3.0-7359-gbda3f257/src/mds/MDCache.cc: 365: FAILED ceph_assert(o->get_num_ref() == 0) ceph version 19.3.0-7359-gbda3f257 (bda3f2572bc7c9ac5349d0d89e2c5682371b1581) squid (dev) 1: (ceph::__ceph_assert_fail(char const*, char const*, int, char const*)+0x121) [0x7f383e141bdf] 2: /usr/lib64/ceph/libceph-common.so.2(+0x256dec) [0x7f383e141dec] 3: (MDCache::remove_inode(CInode*)+0x502) [0x55b5401fc1a6] 4: (StrayManager::_purge_stray_logged(CDentry*, unsigned long, boost::intrusive_ptr<MutationImpl>&)+0x26c) [0x55b5402de788] 5: /usr/bin/ceph-mds(+0x34b96e) [0x55b5402de96e] 6: (MDSContext::complete(int)+0x7c) [0x55b540451226] 7: (MDSIOContextBase::complete(int)+0x5a6) [0x55b54045196c] 8: (MDSLogContextBase::complete(int)+0x46) [0x55b5404519e8] 9: (Finisher::finisher_thread_entry()+0x4e0) [0x7f383e0c81a6] 10: /usr/lib64/ceph/libceph-common.so.2(+0x1dda97) [0x7f383e0c8a97] 11: (Thread::entry_wrapper()+0x33) [0x7f383e11ddab] 12: (Thread::_entry_func(void*)+0xd) [0x7f383e11ddc1] 13: /lib64/libc.so.6(+0x8a3b2) [0x7f383da073b2] 14: /lib64/libc.so.6(+0x10f430) [0x7f383da8c430]
From: /teuthology/pdonnell-2025-02-06_01:25:33-fs-wip-pdonnell-testing-20250205.192508-debug-distro-default-smithi/8118088
Also happened in earlier runs, unrecorded:
pdonnell@vossi04 /a$ grep 'StrayManager::_purge_stray_logged' *2025-01*-fs-*/*/teu* khiremat-2025-01-15_06:54:14-fs-wip-khiremat-49945-referent-inode-multimds-Jan102025-0-testing-default-smithi/8078064/teuthology.log:2025-01-15T21:01:33.129 INFO:journalctl@ceph.mds.f.smithi176.stdout:Jan 15 21:01:32 smithi176 ceph-8ab276c0-d380-11ef-9d63-a94da4efb481-mds-f[67174]: 4: (StrayManager::_purge_stray_logged(CDentry*, unsigned long, boost::intrusive_ptr<MutationImpl>&)+0x18d) [0x55dc81d3356d] khiremat-2025-01-15_06:54:14-fs-wip-khiremat-49945-referent-inode-multimds-Jan102025-0-testing-default-smithi/8078064/teuthology.log:2025-01-15T21:01:33.131 INFO:journalctl@ceph.mds.f.smithi176.stdout:Jan 15 21:01:32 smithi176 ceph-8ab276c0-d380-11ef-9d63-a94da4efb481-mds-f[67174]: 4: (StrayManager::_purge_stray_logged(CDentry*, unsigned long, boost::intrusive_ptr<MutationImpl>&)+0x18d) [0x55dc81d3356d] khiremat-2025-01-15_06:54:14-fs-wip-khiremat-49945-referent-inode-multimds-Jan102025-0-testing-default-smithi/8078064/teuthology.log:2025-01-15T21:01:33.132 INFO:journalctl@ceph.mds.f.smithi176.stdout:Jan 15 21:01:32 smithi176 ceph-8ab276c0-d380-11ef-9d63-a94da4efb481-mds-f[67174]: 8: (StrayManager::_purge_stray_logged(CDentry*, unsigned long, boost::intrusive_ptr<MutationImpl>&)+0x18d) [0x55dc81d3356d] khiremat-2025-01-15_06:54:14-fs-wip-khiremat-49945-referent-inode-multimds-Jan102025-0-testing-default-smithi/8078064/teuthology.log:2025-01-15T21:01:33.134 INFO:journalctl@ceph.mds.f.smithi176.stdout:Jan 15 21:01:32 smithi176 ceph-8ab276c0-d380-11ef-9d63-a94da4efb481-mds-f[67174]: 8: (StrayManager::_purge_stray_logged(CDentry*, unsigned long, boost::intrusive_ptr<MutationImpl>&)+0x18d) [0x55dc81d3356d] khiremat-2025-01-15_06:54:14-fs-wip-khiremat-49945-referent-inode-multimds-Jan102025-0-testing-default-smithi/8078064/teuthology.log:2025-01-15T21:01:33.135 INFO:journalctl@ceph.mds.f.smithi176.stdout:Jan 15 21:01:32 smithi176 ceph-8ab276c0-d380-11ef-9d63-a94da4efb481-mds-f[67174]: 4: (StrayManager::_purge_stray_logged(CDentry*, unsigned long, boost::intrusive_ptr<MutationImpl>&)+0x18d) [0x55dc81d3356d] khiremat-2025-01-15_06:54:14-fs-wip-khiremat-49945-referent-inode-multimds-Jan102025-0-testing-default-smithi/8078064/teuthology.log:2025-01-15T21:01:33.136 INFO:journalctl@ceph.mds.f.smithi176.stdout:Jan 15 21:01:32 smithi176 ceph-8ab276c0-d380-11ef-9d63-a94da4efb481-mds-f[67174]: 8: (StrayManager::_purge_stray_logged(CDentry*, unsigned long, boost::intrusive_ptr<MutationImpl>&)+0x18d) [0x55dc81d3356d] khiremat-2025-01-15_06:54:14-fs-wip-khiremat-49945-referent-inode-multimds-Jan102025-0-testing-default-smithi/8078064/teuthology.log:2025-01-15T21:01:33.138 INFO:journalctl@ceph.mds.f.smithi176.stdout:Jan 15 21:01:32 smithi176 ceph-8ab276c0-d380-11ef-9d63-a94da4efb481-mds-f[67174]: 4: (StrayManager::_purge_stray_logged(CDentry*, unsigned long, boost::intrusive_ptr<MutationImpl>&)+0x18d) [0x55dc81d3356d] khiremat-2025-01-15_06:54:14-fs-wip-khiremat-49945-referent-inode-multimds-Jan102025-0-testing-default-smithi/8078064/teuthology.log:2025-01-15T21:01:33.139 INFO:journalctl@ceph.mds.f.smithi176.stdout:Jan 15 21:01:32 smithi176 ceph-8ab276c0-d380-11ef-9d63-a94da4efb481-mds-f[67174]: 8: (StrayManager::_purge_stray_logged(CDentry*, unsigned long, boost::intrusive_ptr<MutationImpl>&)+0x18d) [0x55dc81d3356d] khiremat-2025-01-28_12:06:07-fs-wip-khiremat-49945-referent-inode-multimds-Jan272025-1-testing-default-smithi/8098842/teuthology.log:2025-01-28T15:05:18.925 INFO:journalctl@ceph.mds.h.smithi112.stdout:Jan 28 15:05:18 smithi112 ceph-273a1e5c-dd87-11ef-bb7f-bd4984dce30f-mds-h[50964]: 4: (StrayManager::_purge_stray_logged(CDentry*, unsigned long, boost::intrusive_ptr<MutationImpl>&)+0xfa) [0x55831ddd721a] khiremat-2025-01-28_12:06:07-fs-wip-khiremat-49945-referent-inode-multimds-Jan272025-1-testing-default-smithi/8098842/teuthology.log:2025-01-28T15:05:18.927 INFO:journalctl@ceph.mds.h.smithi112.stdout:Jan 28 15:05:18 smithi112 ceph-273a1e5c-dd87-11ef-bb7f-bd4984dce30f-mds-h[50964]: 4: (StrayManager::_purge_stray_logged(CDentry*, unsigned long, boost::intrusive_ptr<MutationImpl>&)+0xfa) [0x55831ddd721a] khiremat-2025-01-28_12:06:07-fs-wip-khiremat-49945-referent-inode-multimds-Jan272025-1-testing-default-smithi/8098842/teuthology.log:2025-01-28T15:05:18.929 INFO:journalctl@ceph.mds.h.smithi112.stdout:Jan 28 15:05:18 smithi112 ceph-273a1e5c-dd87-11ef-bb7f-bd4984dce30f-mds-h[50964]: 8: (StrayManager::_purge_stray_logged(CDentry*, unsigned long, boost::intrusive_ptr<MutationImpl>&)+0xfa) [0x55831ddd721a] khiremat-2025-01-28_12:06:07-fs-wip-khiremat-49945-referent-inode-multimds-Jan272025-1-testing-default-smithi/8098842/teuthology.log:2025-01-28T15:05:18.930 INFO:journalctl@ceph.mds.h.smithi112.stdout:Jan 28 15:05:18 smithi112 ceph-273a1e5c-dd87-11ef-bb7f-bd4984dce30f-mds-h[50964]: 8: (StrayManager::_purge_stray_logged(CDentry*, unsigned long, boost::intrusive_ptr<MutationImpl>&)+0xfa) [0x55831ddd721a] khiremat-2025-01-28_12:06:07-fs-wip-khiremat-49945-referent-inode-multimds-Jan272025-1-testing-default-smithi/8098842/teuthology.log:2025-01-28T15:05:18.931 INFO:journalctl@ceph.mds.h.smithi112.stdout:Jan 28 15:05:18 smithi112 ceph-273a1e5c-dd87-11ef-bb7f-bd4984dce30f-mds-h[50964]: 4: (StrayManager::_purge_stray_logged(CDentry*, unsigned long, boost::intrusive_ptr<MutationImpl>&)+0xfa) [0x55831ddd721a] khiremat-2025-01-28_12:06:07-fs-wip-khiremat-49945-referent-inode-multimds-Jan272025-1-testing-default-smithi/8098842/teuthology.log:2025-01-28T15:05:18.933 INFO:journalctl@ceph.mds.h.smithi112.stdout:Jan 28 15:05:18 smithi112 ceph-273a1e5c-dd87-11ef-bb7f-bd4984dce30f-mds-h[50964]: 8: (StrayManager::_purge_stray_logged(CDentry*, unsigned long, boost::intrusive_ptr<MutationImpl>&)+0xfa) [0x55831ddd721a] khiremat-2025-01-28_12:06:07-fs-wip-khiremat-49945-referent-inode-multimds-Jan272025-1-testing-default-smithi/8098842/teuthology.log:2025-01-28T15:05:18.934 INFO:journalctl@ceph.mds.h.smithi112.stdout:Jan 28 15:05:18 smithi112 ceph-273a1e5c-dd87-11ef-bb7f-bd4984dce30f-mds-h[50964]: 4: (StrayManager::_purge_stray_logged(CDentry*, unsigned long, boost::intrusive_ptr<MutationImpl>&)+0xfa) [0x55831ddd721a] khiremat-2025-01-28_12:06:07-fs-wip-khiremat-49945-referent-inode-multimds-Jan272025-1-testing-default-smithi/8098842/teuthology.log:2025-01-28T15:05:18.935 INFO:journalctl@ceph.mds.h.smithi112.stdout:Jan 28 15:05:18 smithi112 ceph-273a1e5c-dd87-11ef-bb7f-bd4984dce30f-mds-h[50964]: 8: (StrayManager::_purge_stray_logged(CDentry*, unsigned long, boost::intrusive_ptr<MutationImpl>&)+0xfa) [0x55831ddd721a]
Genesis of problem:
2025-02-06T07:25:37.783+0000 7f3831dd5640 10 MDSIOContextBase::complete: 25C_MDS_unlink_local_finish
2025-02-06T07:25:37.783+0000 7f3831dd5640 10 MDSContext::complete: 25C_MDS_unlink_local_finish
2025-02-06T07:25:37.783+0000 7f3831dd5640 10 mds.2.server _unlink_local_finish [dentry #0x1/volumes/qa/sv_0/b002ea56-5500-453d-82b0-68d7a670bba4/client.0/tmp/testdir/dir1/dir2/file9365 [7,head] auth (dn xlockdone l x=1) (dversion lock w=1 last_client=15480) pv=2148 v=2080 ap=2 ino=0x300000026a0 state=1610612736 | request=1 lock=2 inodepin=1 dirty=1 authpin=1 clientlease=1 0x55b54f2f8c80]
2025-02-06T07:25:37.783+0000 7f3831dd5640 10 mds.2.cache.ino(0x300000026a0) pop_projected_snaprealm (early) 0x55b54efd68f0 seq 6
2025-02-06T07:25:37.783+0000 7f3831dd5640 10 mds.2.cache.ino(0x300000026a0) open_snaprealm snaprealm(0x300000026a0 seq 0 lc 0 cr 0 cps 1 snaps={} last_modified 0.000000 change_attr 0 0x55b54eaa7200) parent is snaprealm(0x10000000002 seq 1 lc 0 cr 1 cps 2 snaps={} last_modified 0.000000 change_attr 0 0x55b546f266c0)
2025-02-06T07:25:37.783+0000 7f3831dd5640 10 mds.2.cache.snaprealm(0x10000000002 seq 1 0x55b546f266c0) split_at: snaprealm(0x300000026a0 seq 0 lc 0 cr 0 cps 1 snaps={} last_modified 0.000000 change_attr 0 0x55b54eaa7200) on [inode 0x300000026a0 [...7,head] ~mds2/stray0/300000026a0 auth v2080 pv7553 ap=3 snaprealm=0x55b54eaa7200 DIRTYPARENT s=0 n(v0 rc2025-02-06T07:23:46.897211+0000 1=1+0)->n(v0 rc2025-02-06T07:25:36.295597+0000 1=1+0) (ilink xlockdone x=1) (iversion lock w=1 last_client=15480) (iquiesce lock w=1 last_client=15480) caps={15480=pAsXsFscr/-@5} | ptrwaiter=0 request=1 lock=4 caps=1 dirtyparent=1 dirty=1 waiter=0 authpin=1 0x55b54f3cb180]
2025-02-06T07:25:37.783+0000 7f3831dd5640 20 mds.2.cache.ino(0x300000026a0) move_to_realm joining realm snaprealm(0x300000026a0 seq 0 lc 0 cr 0 cps 1 snaps={} last_modified 0.000000 change_attr 0 0x55b54eaa7200), leaving realm snaprealm(0x10000000002 seq 1 lc 0 cr 1 cps 2 snaps={} last_modified 0.000000 change_attr 0 0x55b546f266c0)
2025-02-06T07:25:37.783+0000 7f3831dd5640 10 mds.2.cache.ino(0x300000026a0) realm snaprealm(0x300000026a0 seq 6 lc 0 cr 6 cps 7 snaps={} past_parent_snaps=5,6 last_modified 0.000000 change_attr 0 0x55b54eaa7200) parent snaprealm(0x10000000002 seq 1 lc 0 cr 1 cps 2 snaps={} last_modified 0.000000 change_attr 0 0x55b546f266c0)
2025-02-06T07:25:37.783+0000 7f3831dd5640 12 mds.2.cache.dir(0x1000000020c.101100110*) unlink_inode [dentry #0x1/volumes/qa/sv_0/b002ea56-5500-453d-82b0-68d7a670bba4/client.0/tmp/testdir/dir1/dir2/file9365 [7,head] auth (dn xlockdone l x=1) (dversion lock w=1 last_client=15480) pv=2148 v=2080 ap=2 ino=0x300000026a0 state=1610612736 | request=1 lock=2 inodepin=1 dirty=1 authpin=1 clientlease=1 0x55b54f2f8c80] [inode 0x300000026a0 [...7,head] ~mds2/stray0/300000026a0 auth v2080 pv7553 ap=3 snaprealm=0x55b54eaa7200 DIRTYPARENT s=0 n(v0 rc2025-02-06T07:23:46.897211+0000 1=1+0)->n(v0 rc2025-02-06T07:25:36.295597+0000 1=1+0) (ilink xlockdone x=1) (iversion lock w=1 last_client=15480) (iquiesce lock w=1 last_client=15480) caps={15480=pAsXsFscr/-@5} | ptrwaiter=0 request=1 lock=4 caps=1 dirtyparent=1 dirty=1 waiter=0 authpin=1 0x55b54f3cb180]
...
2025-02-06T07:25:38.425+0000 7f3831dd5640 7 mds.2.mig encode_export_dir exporting [dentry #0x1/volumes/qa/sv_0/b002ea56-5500-453d-82b0-68d7a670bba4/client.0/tmp/testdir/dir1/dir2/file9365 [5,6] auth (dversion lock) v=2149 ino=0x300000026a0 state=1610612736 | request=0 inodepin=1 dirty=1 0x55b5480eb680]
2025-02-06T07:25:38.425+0000 7f3831dd5640 7 mds.2.mig encode_export_inode [inode 0x300000026a0 [5,6] /volumes/qa/sv_0/b002ea56-5500-453d-82b0-68d7a670bba4/client.0/tmp/testdir/dir1/dir2/file9365 auth v2080 s=0 n(v0 rc2025-02-06T07:23:46.897211+0000 1=1+0) | request=0 dirty=1 0x55b548f02000]
2025-02-06T07:25:38.425+0000 7f3831dd5640 20 mds.2.mig encode_export_inode_caps [inode 0x300000026a0 [5,6] /volumes/qa/sv_0/b002ea56-5500-453d-82b0-68d7a670bba4/client.0/tmp/testdir/dir1/dir2/file9365 auth v2080 s=0 n(v0 rc2025-02-06T07:23:46.897211+0000 1=1+0) | request=0 dirty=1 tempexporting=1 0x55b548f02000]
...
2025-02-06T07:25:39.206+0000 7f38385e2640 7 mds.2.locker _do_cap_release for client.15480 on [inode 0x300000026a0 [...7,head] ~mds2/stray0/300000026a0 auth v7553 snaprealm=0x55b54eaa7200 DIRTYPARENT s=0 nl=0 n(v0 rc2025-02-06T07:25:36.295597+0000 1=1+0) caps={15480=pAsLsXsFscr/-@6} | ptrwaiter=0 request=0 lock=0 caps=1 dirtyparent=1 dirty=1 waiter=0 authpin=0 0x55b54f3cb180]
2025-02-06T07:25:39.206+0000 7f38385e2640 10 mds.2.cache.ino(0x300000026a0) remove_client_cap last cap, leaving realm snaprealm(0x300000026a0 seq 6 lc 0 cr 6 cps 7 snaps={} past_parent_snaps=5,6 last_modified 0.000000 change_attr 0 0x55b54eaa7200)
...
2025-02-06T07:25:39.221+0000 7f3831dd5640 10 mds.2.cache.den(0x1000000020c.101100110* file9365) mark_clean [dentry #0x1/volumes/qa/sv_0/b002ea56-5500-453d-82b0-68d7a670bba4/client.0/tmp/testdir/dir1/dir2/file9365 [5,6] rep@0,2.1 (dversion lock) v=2149 ino=0x300000026a0 state=536870912 | request=0 inodepin=1 dirty=1 tempexporting=1 0x55b5480eb680]
2025-02-06T07:25:39.221+0000 7f3831dd5640 12 mds.2.mig finish_export_inode [inode 0x300000026a0 [5,6] /volumes/qa/sv_0/b002ea56-5500-453d-82b0-68d7a670bba4/client.0/tmp/testdir/dir1/dir2/file9365 auth v2080 s=0 n(v0 rc2025-02-06T07:23:46.897211+0000 1=1+0) | request=0 exportingcaps=1 dirty=1 tempexporting=1 0x55b548f02000]
2025-02-06T07:25:39.221+0000 7f3831dd5640 10 mds.2.cache.ino(0x300000026a0) mark_clean [inode 0x300000026a0 [5,6] /volumes/qa/sv_0/b002ea56-5500-453d-82b0-68d7a670bba4/client.0/tmp/testdir/dir1/dir2/file9365 auth v2080 s=0 n(v0 rc2025-02-06T07:23:46.897211+0000 1=1+0) | request=0 exportingcaps=1 dirty=1 tempexporting=1 0x55b548f02000]
2025-02-06T07:25:39.221+0000 7f3831dd5640 20 mds.2.mig finish_export_inode_caps [inode 0x300000026a0 [5,6] /volumes/qa/sv_0/b002ea56-5500-453d-82b0-68d7a670bba4/client.0/tmp/testdir/dir1/dir2/file9365 rep@0,2.1 v2080 s=0 n(v0 rc2025-02-06T07:23:46.897211+0000 1=1+0) | request=0 exportingcaps=1 dirty=0 tempexporting=0 0x55b548f02000]
2025-02-06T07:25:39.221+0000 7f3831dd5640 10 mds.2.locker eval 7296 [inode 0x300000026a0 [5,6] /volumes/qa/sv_0/b002ea56-5500-453d-82b0-68d7a670bba4/client.0/tmp/testdir/dir1/dir2/file9365 rep@0,2.1 v2080 s=0 n(v0 rc2025-02-06T07:23:46.897211+0000 1=1+0) 0x55b548f02000]
...
2025-02-06T07:25:39.222+0000 7f3831dd5640 10 mds.2.cache.strays eval_stray [dentry #0x102/stray0/300000026a0 [7,head] auth (dversion lock) v=7553 ino=0x300000026a0 state=1879048209|new | request=0 lock=0 inodepin=1 dirty=1 authpin=0 0x55b5496de780]
2025-02-06T07:25:39.222+0000 7f3831dd5640 10 mds.2.cache.strays inode is [inode 0x300000026a0 [...7,head] ~mds2/stray0/300000026a0 auth v7553 snaprealm=0x55b54eaa7200 DIRTYPARENT s=0 nl=0 n(v0 rc2025-02-06T07:25:36.295597+0000 1=1+0) | ptrwaiter=0 request=0 lock=0 caps=0 dirtyparent=1 dirty=1 waiter=0 authpin=0 0x55b54f3cb180]
2025-02-06T07:25:39.222+0000 7f3831dd5640 10 mds.2.cache.snaprealm(0x300000026a0 seq 6 0x55b54eaa7200) prune_past_parent_snaps
2025-02-06T07:25:39.222+0000 7f3831dd5640 10 mds.2.cache.snaprealm(0x300000026a0 seq 6 0x55b54eaa7200) prune_past_parent_snaps keeping 5
2025-02-06T07:25:39.222+0000 7f3831dd5640 10 mds.2.cache.snaprealm(0x300000026a0 seq 6 0x55b54eaa7200) prune_past_parent_snaps keeping 6
2025-02-06T07:25:39.222+0000 7f3831dd5640 10 mds.2.cache.snaprealm(0x300000026a0 seq 6 0x55b54eaa7200) get_snaps 5,6 (seq 6 cached_seq 6)
2025-02-06T07:25:39.222+0000 7f3831dd5640 10 mds.2.cache.ino(0x300000026a0) purge_stale_snap_data 5,6
2025-02-06T07:25:39.222+0000 7f3831dd5640 10 mds.2.cache.ino(0x300000026a0) clear_dirty_parent
2025-02-06T07:25:39.222+0000 7f3831dd5640 20 mds.2.cache.strays enqueue: purging dn: [dentry #0x102/stray0/300000026a0 [7,head] auth (dversion lock) v=7553 ino=0x300000026a0 state=1879048213|new | request=0 lock=0 inodepin=1 dirty=1 authpin=0 0x55b5496de780]
2025-02-06T07:25:39.222+0000 7f3831dd5640 20 mds.2.cache.dir(0x614) can_auth_pin: auth!
2025-02-06T07:25:39.222+0000 7f3831dd5640 10 mds.2.cache.dir(0x614) auth_pin by 0x55b546f14de8 on [dir 0x614 ~mds2/stray0/ [2,head] auth{0=16,1=14} v=8600 cv=1/1 ap=23+0 state=1610883073|complete|sticky f(v0 m2025-02-06T07:25:37.314166+0000 238=238+0)/f(v0 m2025-02-06T07:25:37.314166+0000 525=525+0) n(v0 rc2025-02-06T07:25:37.314166+0000 238=238+0)/n(v0 rc2025-02-06T07:25:37.314166+0000 525=525+0) hs=238+0,ss=0+0 dirty=238 | child=1 sticky=1 replicated=1 dirty=1 authpin=1 0x55b546f1e900] count now 23
2025-02-06T07:25:39.222+0000 7f3831dd5640 10 mds.2.cache.strays purge [dentry #0x102/stray0/300000026a0 [7,head] auth (dversion lock) v=7553 ino=0x300000026a0 state=1879048245|new | request=0 lock=0 inodepin=1 purging=1 dirty=1 authpin=0 0x55b5496de780] [inode 0x300000026a0 [...7,head] ~mds2/stray0/300000026a0 auth v7553 snaprealm=0x55b54eaa7200 s=0 nl=0 n(v0 rc2025-02-06T07:25:36.295597+0000 1=1+0) | ptrwaiter=0 request=0 lock=0 caps=0 dirtyparent=0 dirty=1 waiter=0 authpin=0 0x55b54f3cb180]
2025-02-06T07:25:39.222+0000 7f3831dd5640 10 mds.2.cache.strays realm snaprealm(0x300000026a0 seq 6 lc 0 cr 6 cps 7 snaps={} past_parent_snaps=5,6 last_modified 0.000000 change_attr 0 0x55b54eaa7200)
2025-02-06T07:25:39.222+0000 7f3831dd5640 4 mds.2.purge_queue push: pushing inode 0x300000026a0
...
2025-02-06T07:25:39.228+0000 7f3831dd5640 12 mds.2.cache trim_dentry [dentry #0x1/volumes/qa/sv_0/b002ea56-5500-453d-82b0-68d7a670bba4/client.0/tmp/testdir/dir1/dir2/file9365 [5,6] rep@0.1 (dversion lock) v=2149 ino=0x300000026a0 state=0 0x55b5480eb680]
2025-02-06T07:25:39.228+0000 7f3831dd5640 12 mds.2.cache in container [dir 0x1 / [2,head] rep@0.1 REP dir_auth=0 state=0 f(v0 m2025-02-06T07:19:17.004075+0000 1=0+1) n(v2 rc2025-02-06T07:22:47.734827+0000 b234 7199=7185+14) hs=1+0,ss=0+0 | child=1 subtree=1 0x55b547164000]
2025-02-06T07:25:39.228+0000 7f3831dd5640 15 mds.2.cache trim_inode [inode 0x300000026a0 [5,6] /volumes/qa/sv_0/b002ea56-5500-453d-82b0-68d7a670bba4/client.0/tmp/testdir/dir1/dir2/file9365 rep@0.1 v2080 s=0 n(v0 rc2025-02-06T07:23:46.897211+0000 1=1+0) 0x55b548f02000]
2025-02-06T07:25:39.228+0000 7f3831dd5640 12 mds.2.cache sending expire to mds.0 on [inode 0x300000026a0 [5,6] /volumes/qa/sv_0/b002ea56-5500-453d-82b0-68d7a670bba4/client.0/tmp/testdir/dir1/dir2/file9365 rep@0.1 v2080 s=0 n(v0 rc2025-02-06T07:23:46.897211+0000 1=1+0) 0x55b548f02000]
2025-02-06T07:25:39.228+0000 7f3831dd5640 12 mds.2.cache.dir(0x1000000020c.101100110*) unlink_inode [dentry #0x1/volumes/qa/sv_0/b002ea56-5500-453d-82b0-68d7a670bba4/client.0/tmp/testdir/dir1/dir2/file9365 [5,6] rep@0.1 (dversion lock) v=2149 ino=0x300000026a0 state=0 0x55b5480eb680] [inode 0x300000026a0 [5,6] /volumes/qa/sv_0/b002ea56-5500-453d-82b0-68d7a670bba4/client.0/tmp/testdir/dir1/dir2/file9365 rep@0.1 v2080 s=0 n(v0 rc2025-02-06T07:23:46.897211+0000 1=1+0) 0x55b548f02000]
2025-02-06T07:25:39.228+0000 7f3831dd5640 14 mds.2.cache remove_inode [inode 0x300000026a0 [5,6] #300000026a0 rep@-2.1 v2080 s=0 n(v0 rc2025-02-06T07:23:46.897211+0000 1=1+0) 0x55b548f02000]
,,,
2025-02-06T07:25:39.733+0000 7f3832dd7640 10 MDSIOContextBase::complete: 21C_IO_PurgeStrayPurged
2025-02-06T07:25:39.733+0000 7f3832dd7640 10 MDSContext::complete: 21C_IO_PurgeStrayPurged
2025-02-06T07:25:39.733+0000 7f3832dd7640 10 mds.2.cache.strays _purge_stray_purged [dentry #0x102/stray0/300000026a0 [7,head] auth (dversion lock) v=7553 ino=0x300000026a0 state=1879048229|new | request=0 lock=0 inodepin=1 purging=1 dirty=1 authpin=0 0x55b5496de780] [inode 0x300000026a0 [...7,head] ~mds2/stray0/300000026a0 auth v7553 snaprealm=0x55b54eaa7200 s=0 nl=0 n(v0 rc2025-02-06T07:25:36.295597+0000 1=1+0) | ptrwaiter=0 request=0 lock=0 caps=0 dirtyparent=0 dirty=1 waiter=0 authpin=0 0x55b54f3cb180]
2025-02-06T07:25:39.733+0000 7f3832dd7640 10 mds.2.cache.dir(0x614) pre_dirty 8645
2025-02-06T07:25:39.733+0000 7f3832dd7640 10 mds.2.cache.den(0x614 300000026a0) pre_dirty [dentry #0x102/stray0/300000026a0 [7,head] auth (dversion lock) pv=8645 v=7553 ino=0x300000026a0 state=1879048229|new | request=0 lock=0 inodepin=1 purging=1 dirty=1 authpin=0 0x55b5496de780]
...
2025-02-06T07:25:39.884+0000 7f38385e2640 15 mds.2.mig decode_import_dir got [dentry #0x1/volumes/qa/sv_0/b002ea56-5500-453d-82b0-68d7a670bba4/client.0/tmp/testdir/dir1/dir2/file9365 [5,6] auth{0=1} NULL (dversion lock) v=2149 ino=(nil) state=1610612736 | replicated=1 dirty=1 0x55b547a31400]
2025-02-06T07:25:39.884+0000 7f38385e2640 15 mds.2.mig decode_import_inode on [dentry #0x1/volumes/qa/sv_0/b002ea56-5500-453d-82b0-68d7a670bba4/client.0/tmp/testdir/dir1/dir2/file9365 [5,6] auth{0=1} NULL (dversion lock) v=2149 ino=(nil) state=1610612736 | replicated=1 dirty=1 0x55b547a31400]
2025-02-06T07:25:39.884+0000 7f38385e2640 10 mds.2.mig decode_import_inode added [inode 0x300000026a0 [5,6] #300000026a0 auth v2080 s=0 n(v0 rc2025-02-06T07:23:46.897211+0000 1=1+0) | dirty=1 0x55b54aa8fb80]
2025-02-06T07:25:39.884+0000 7f38385e2640 12 mds.2.cache.dir(0x1000000020c.101100110*) link_primary_inode [dentry #0x1/volumes/qa/sv_0/b002ea56-5500-453d-82b0-68d7a670bba4/client.0/tmp/testdir/dir1/dir2/file9365 [5,6] auth{0=1} NULL (dversion lock) v=2149 ino=(nil) state=1610612736 | replicated=1 dirty=1 0x55b547a31400] [inode 0x300000026a0 [5,6] #300000026a0 auth v2080 s=0 n(v0 rc2025-02-06T07:23:46.897211+0000 1=1+0) | dirty=1 0x55b54aa8fb80]
2025-02-06T07:25:39.884+0000 7f38385e2640 10 mds.2.cache add_quiesce: scheduling op to quiesce [inode 0x300000026a0 [5,6] /volumes/qa/sv_0/b002ea56-5500-453d-82b0-68d7a670bba4/client.0/tmp/testdir/dir1/dir2/file9365 auth v2080 s=0 n(v0 rc2025-02-06T07:23:46.897211+0000 1=1+0) | dirty=1 0x55b54aa8fb80]
...
2025-02-06T07:25:39.911+0000 7f3831dd5640 10 MDSIOContextBase::complete: 18C_PurgeStrayLogged
2025-02-06T07:25:39.911+0000 7f3831dd5640 10 MDSContext::complete: 18C_PurgeStrayLogged
2025-02-06T07:25:39.911+0000 7f3831dd5640 10 mds.2.cache.strays _purge_stray_logged [dentry #0x102/stray0/300000026a0 [7,head] auth (dversion lock) pv=8645 v=7553 ino=0x300000026a0 state=1879048229|new | request=0 lock=0 inodepin=1 purging=1 dirty=1 authpin=0 0x55b5496de780] [inode 0x300000026a0 [...7,head] ~mds2/stray0/300000026a0 auth v7553 ap=1 snaprealm=0x55b54eaa7200 s=0 nl=0 n(v0 rc2025-02-06T07:25:36.295597+0000 1=1+0) (iquiesce lock x=1 by request(mds.2:18651 nref=3)) | ptrwaiter=0 request=1 lock=2 caps=0 dirtyparent=0 dirty=1 waiter=0 authpin=1 0x55b54f3cb180]
2025-02-06T07:25:39.911+0000 7f3831dd5640 12 mds.2.cache.dir(0x614) unlink_inode [dentry #0x102/stray0/300000026a0 [7,head] auth (dversion lock) pv=8645 v=7553 ino=0x300000026a0 state=1879048229|new | request=0 lock=0 inodepin=1 purging=1 dirty=1 authpin=0 0x55b5496de780] [inode 0x300000026a0 [...7,head] ~mds2/stray0/300000026a0 auth v7553 ap=1 snaprealm=0x55b54eaa7200 s=0 nl=0 n(v0 rc2025-02-06T07:25:36.295597+0000 1=1+0) (iquiesce lock x=1 by request(mds.2:18651 nref=3)) | ptrwaiter=0 request=1 lock=2 caps=0 dirtyparent=0 dirty=1 waiter=0 authpin=1 0x55b54f3cb180]
2025-02-06T07:25:39.911+0000 7f3831dd5640 15 mds.2.cache.dir(0x614) adjust_nested_auth_pins -1 on [dir 0x614 ~mds2/stray0/ [2,head] auth{0=16,1=14} pv=8870 v=8644 cv=1/1 ap=113+6 state=1610883073|complete|sticky f(v0 m2025-02-06T07:25:37.314166+0000 216=216+0)/f(v0 m2025-02-06T07:25:37.314166+0000 525=525+0)->f(v0 m2025-02-06T07:25:37.314166+0000 103=103+0)/f(v0 m2025-02-06T07:25:37.314166+0000 525=525+0) n(v0 rc2025-02-06T07:25:37.314166+0000 216=216+0)/n(v0 rc2025-02-06T07:25:37.314166+0000 525=525+0)->n(v0 rc2025-02-06T07:25:37.314166+0000 103=103+0)/n(v0 rc2025-02-06T07:25:37.314166+0000 525=525+0) hs=216+0,ss=0+0 dirty=216 | child=1 sticky=1 replicated=1 dirty=1 authpin=1 0x55b546f1e900] by 0 count now 113/6
2025-02-06T07:25:39.911+0000 7f3831dd5640 10 mds.2.cache.den(0x614 300000026a0) mark_dirty [dentry #0x102/stray0/300000026a0 [7,head] auth NULL (dversion lock) pv=8645 v=7553 ino=(nil) state=1879048229|new | request=0 lock=0 inodepin=0 purging=1 dirty=1 authpin=0 0x55b5496de780]
2025-02-06T07:25:39.911+0000 7f383b5e8640 2 --2- [v2:172.21.15.192:6836/128425721,v1:172.21.15.192:6837/128425721] >> [v2:172.21.15.196:6816/630658411,v1:172.21.15.196:6817/630658411] conn(0x55b546d49000 0x55b546f76100 crc :-1 s=READY pgs=8 cs=0 l=1 rev1=1 crypto rx=0 tx=0 comp rx=0 tx=0).write_message sending message m=0x55b5497b1c00 seq=1989 osd_op(mds.2.21:27233 2.b 2:d586b5a8:::202.00000020:head [write 351566~23350 in=23350b] snapc 0=[] ondisk+write+known_if_redirected+full_force+supports_pool_eio e87)
2025-02-06T07:25:39.911+0000 7f3831dd5640 10 mds.2.cache.dir(0x614) _mark_dirty (already dirty) [dir 0x614 ~mds2/stray0/ [2,head] auth{0=16,1=14} pv=8870 v=8644 cv=1/1 ap=113+6 state=1610883073|complete|sticky f(v0 m2025-02-06T07:25:37.314166+0000 216=216+0)/f(v0 m2025-02-06T07:25:37.314166+0000 525=525+0)->f(v0 m2025-02-06T07:25:37.314166+0000 103=103+0)/f(v0 m2025-02-06T07:25:37.314166+0000 525=525+0) n(v0 rc2025-02-06T07:25:37.314166+0000 216=216+0)/n(v0 rc2025-02-06T07:25:37.314166+0000 525=525+0)->n(v0 rc2025-02-06T07:25:37.314166+0000 103=103+0)/n(v0 rc2025-02-06T07:25:37.314166+0000 525=525+0) hs=215+1,ss=0+0 dirty=216 | child=1 sticky=1 replicated=1 dirty=1 authpin=1 0x55b546f1e900] version 8644
2025-02-06T07:25:39.911+0000 7f3831dd5640 15 mds.2.cache.dir(0x614) pop_and_dirty_projected_fnode 0x55b54d366fe0 v8646
2025-02-06T07:25:39.911+0000 7f3831dd5640 10 mds.2.cache.dir(0x614) _mark_dirty (already dirty) [dir 0x614 ~mds2/stray0/ [2,head] auth{0=16,1=14} pv=8870 v=8646 cv=1/1 ap=113+6 state=1610883073|complete|sticky f(v0 m2025-02-06T07:25:37.314166+0000 215=215+0)/f(v0 m2025-02-06T07:25:37.314166+0000 525=525+0)->f(v0 m2025-02-06T07:25:37.314166+0000 103=103+0)/f(v0 m2025-02-06T07:25:37.314166+0000 525=525+0) n(v0 rc2025-02-06T07:25:37.314166+0000 215=215+0)/n(v0 rc2025-02-06T07:25:37.314166+0000 525=525+0)->n(v0 rc2025-02-06T07:25:37.314166+0000 103=103+0)/n(v0 rc2025-02-06T07:25:37.314166+0000 525=525+0) hs=215+1,ss=0+0 dirty=216 | child=1 sticky=1 replicated=1 dirty=1 authpin=1 0x55b546f1e900] version 8646
2025-02-06T07:25:39.911+0000 7f3831dd5640 20 mds.2.cache.strays dn is new, removing
2025-02-06T07:25:39.911+0000 7f3831dd5640 10 mds.2.cache.den(0x614 300000026a0) mark_clean [dentry #0x102/stray0/300000026a0 [7,head] auth NULL (dversion lock) v=8645 ino=(nil) state=1879048193|new | request=0 lock=0 inodepin=0 purging=0 dirty=1 authpin=0 0x55b5496de780]
2025-02-06T07:25:39.911+0000 7f3831dd5640 12 mds.2.cache.dir(0x614) remove_dentry [dentry #0x102/stray0/300000026a0 [7,head] auth NULL (dversion lock) v=8645 ino=(nil) state=1342177280 0x55b5496de780]
2025-02-06T07:25:39.911+0000 7f3831dd5640 10 mds.2.cache.ino(0x300000026a0) mark_clean [inode 0x300000026a0 [...7,head] #300000026a0 auth v7553 ap=1 snaprealm=0x55b54eaa7200 s=0 nl=0 n(v0 rc2025-02-06T07:25:36.295597+0000 1=1+0) (iquiesce lock x=1 by request(mds.2:18651 nref=3)) | ptrwaiter=0 request=1 lock=2 caps=0 dirtyparent=0 dirty=1 waiter=0 authpin=1 0x55b54f3cb180]
2025-02-06T07:25:39.911+0000 7f3831dd5640 14 mds.2.cache remove_inode [inode 0x300000026a0 [...7,head] #300000026a0 auth v7553 ap=1 snaprealm=0x55b54eaa7200 s=0 nl=0 n(v0 rc2025-02-06T07:25:36.295597+0000 1=1+0) (iquiesce lock x=1 by request(mds.2:18651 nref=3)) | ptrwaiter=0 request=1 lock=2 caps=0 dirtyparent=0 dirty=0 waiter=0 authpin=1 0x55b54f3cb180]
2025-02-06T07:25:39.911+0000 7f383bde9640 1 -- [v2:172.21.15.192:6836/128425721,v1:172.21.15.192:6837/128425721] <== osd.5 v2:172.21.15.196:6808/1461308415 2687 ==== osd_op_reply(27217 30000001468.00000000 [delete] v87'1314 uv0 ondisk = -2 ((2) No such file or directory)) ==== 164+0+0 (crc 0 0 0) 0x55b548623b80 con 0x55b546fd6c00
2025-02-06T07:25:39.911+0000 7f383bde9640 1 -- [v2:172.21.15.192:6836/128425721,v1:172.21.15.192:6837/128425721] <== osd.9 v2:172.21.15.177:6826/1885875871 2096 ==== osd_op_reply(27220 30000001584.00000000 [delete] v87'593 uv0 ondisk = -2 ((2) No such file or directory)) ==== 164+0+0 (crc 0 0 0) 0x55b548623b80 con 0x55b546fd6400
2025-02-06T07:25:39.911+0000 7f383bde9640 1 -- [v2:172.21.15.192:6836/128425721,v1:172.21.15.192:6837/128425721] <== osd.4 v2:172.21.15.192:6808/2976217905 3012 ==== osd_op_reply(27212 300000012f5.00000000 [delete] v87'1234 uv0 ondisk = -2 ((2) No such file or directory)) ==== 164+0+0 (crc 0 0 0) 0x55b548623b80 con 0x55b546fe3c00
2025-02-06T07:25:39.911+0000 7f383bde9640 1 -- [v2:172.21.15.192:6836/128425721,v1:172.21.15.192:6837/128425721] <== osd.4 v2:172.21.15.192:6808/2976217905 3013 ==== osd_op_reply(27214 30000001397.00000000 [delete] v87'1287 uv0 ondisk = -2 ((2) No such file or directory)) ==== 164+0+0 (crc 0 0 0) 0x55b548623b80 con 0x55b546fe3c00
2025-02-06T07:25:39.911+0000 7f383bde9640 2 --2- [v2:172.21.15.192:6836/128425721,v1:172.21.15.192:6837/128425721] >> [v2:172.21.15.192:6808/2976217905,v1:172.21.15.192:6809/2976217905] conn(0x55b546fe3c00 0x55b546fe8000 crc :-1 s=READY pgs=9 cs=0 l=1 rev1=1 crypto rx=0 tx=0 comp rx=0 tx=0).write_message sending message m=0x55b5477ec800 seq=3014 osd_op(mds.2.21:27231 4.ds0 4:b68132aa:::3000000161e.00000000:head [delete] snapc 6=[6,5] ondisk+write+known_if_redirected+full_force+supports_pool_eio e87)
2025-02-06T07:25:39.911+0000 7f3832dd7640 10 mds.2.purge_queue _execute_item_complete: complete at 0x575daf
2025-02-06T07:25:39.911+0000 7f3832dd7640 10 mds.2.purge_queue _execute_item_complete: non-sequential completion, not expiring anything
2025-02-06T07:25:39.911+0000 7f3832dd7640 10 mds.2.purge_queue _execute_item_complete: completed item for ino 0x30000001468
2025-02-06T07:25:39.911+0000 7f3832dd7640 10 mds.2.purge_queue _execute_item_complete: in_flight.size() now 7
2025-02-06T07:25:39.911+0000 7f3832dd7640 10 mds.2.purge_queue _execute_item_complete: left purge items in journal: 27 (purge_item_journal_size/write_pos/read_pos/expire_pos) now at (101/5727990/5726365/5725240)
2025-02-06T07:25:39.911+0000 7f3832dd7640 20 mds.2.purge_queue _can_consume: 14/16 ops, 7/64 files
2025-02-06T07:25:39.911+0000 7f3832dd7640 20 mds.2.purge_queue _consume: decoding entry
2025-02-06T07:25:39.911+0000 7f3832dd7640 20 mds.2.purge_queue _consume: executing item (0x30000001624)
2025-02-06T07:25:39.911+0000 7f3832dd7640 10 mds.2.purge_queue _execute_item: remove backtrace object 30000001624.00000000 pool 4 snapc 6=[6,5]
2025-02-06T07:25:39.912+0000 7f3832dd7640 10 mds.2.purge_queue _execute_item: remove backtrace object 30000001624.00000000 old pool 3 snapc 6=[6,5]
2025-02-06T07:25:39.912+0000 7f3832dd7640 20 mds.2.purge_queue _can_consume: 16/16 ops, 8/64 files
2025-02-06T07:25:39.912+0000 7f3832dd7640 20 mds.2.purge_queue _can_consume: Throttling on op limit 16/16
2025-02-06T07:25:39.912+0000 7f3832dd7640 10 mds.2.purge_queue _consume: cannot consume right now
2025-02-06T07:25:39.912+0000 7f3832dd7640 10 mds.2.purge_queue _execute_item_complete: complete at 0x575e2c
2025-02-06T07:25:39.912+0000 7f3832dd7640 10 mds.2.purge_queue _execute_item_complete: non-sequential completion, not expiring anything
2025-02-06T07:25:39.912+0000 7f3832dd7640 10 mds.2.purge_queue _execute_item_complete: completed item for ino 0x30000001584
2025-02-06T07:25:39.912+0000 7f3832dd7640 10 mds.2.purge_queue _execute_item_complete: in_flight.size() now 7
2025-02-06T07:25:39.912+0000 7f3832dd7640 10 mds.2.purge_queue _execute_item_complete: left purge items in journal: 27 (purge_item_journal_size/write_pos/read_pos/expire_pos) now at (101/5727990/5726490/5725240)
2025-02-06T07:25:39.912+0000 7f3832dd7640 20 mds.2.purge_queue _can_consume: 14/16 ops, 7/64 files
2025-02-06T07:25:39.912+0000 7f3832dd7640 20 mds.2.purge_queue _consume: decoding entry
2025-02-06T07:25:39.912+0000 7f3832dd7640 20 mds.2.purge_queue _consume: executing item (0x30000001636)
2025-02-06T07:25:39.912+0000 7f3832dd7640 10 mds.2.purge_queue _execute_item: remove backtrace object 30000001636.00000000 pool 4 snapc 6=[6,5]
2025-02-06T07:25:39.912+0000 7f3832dd7640 10 mds.2.purge_queue _execute_item: remove backtrace object 30000001636.00000000 old pool 3 snapc 6=[6,5]
2025-02-06T07:25:39.912+0000 7f3832dd7640 20 mds.2.purge_queue _can_consume: 16/16 ops, 8/64 files
2025-02-06T07:25:39.912+0000 7f3832dd7640 20 mds.2.purge_queue _can_consume: Throttling on op limit 16/16
2025-02-06T07:25:39.912+0000 7f3832dd7640 10 mds.2.purge_queue _consume: cannot consume right now
2025-02-06T07:25:39.912+0000 7f3832dd7640 10 mds.2.purge_queue _execute_item_complete: complete at 0x575cb5
2025-02-06T07:25:39.912+0000 7f3832dd7640 10 mds.2.purge_queue _execute_item_complete: expiring to 0x575cb5
2025-02-06T07:25:39.912+0000 7f3832dd7640 10 mds.2.purge_queue _execute_item_complete: completed item for ino 0x300000012f5
2025-02-06T07:25:39.912+0000 7f3832dd7640 10 mds.2.purge_queue _execute_item_complete: in_flight.size() now 7
2025-02-06T07:25:39.912+0000 7f3832dd7640 10 mds.2.purge_queue _execute_item_complete: left purge items in journal: 25 (purge_item_journal_size/write_pos/read_pos/expire_pos) now at (101/5727990/5726615/5725365)
2025-02-06T07:25:39.912+0000 7f3832dd7640 20 mds.2.purge_queue _can_consume: 14/16 ops, 7/64 files
2025-02-06T07:25:39.912+0000 7f3832dd7640 20 mds.2.purge_queue _consume: decoding entry
2025-02-06T07:25:39.912+0000 7f3832dd7640 20 mds.2.purge_queue _consume: executing item (0x30000001680)
2025-02-06T07:25:39.912+0000 7f3832dd7640 10 mds.2.purge_queue _execute_item: remove backtrace object 30000001680.00000000 pool 4 snapc 6=[6,5]
2025-02-06T07:25:39.912+0000 7f3832dd7640 10 mds.2.purge_queue _execute_item: remove backtrace object 30000001680.00000000 old pool 3 snapc 6=[6,5]
2025-02-06T07:25:39.912+0000 7f3832dd7640 20 mds.2.purge_queue _can_consume: 16/16 ops, 8/64 files
2025-02-06T07:25:39.912+0000 7f3832dd7640 20 mds.2.purge_queue _can_consume: Throttling on op limit 16/16
2025-02-06T07:25:39.912+0000 7f3832dd7640 10 mds.2.purge_queue _consume: cannot consume right now
2025-02-06T07:25:39.912+0000 7f3832dd7640 10 mds.2.purge_queue _commit_ops: PURGE_FILE
2025-02-06T07:25:39.912+0000 7f3832dd7640 1 -- [v2:172.21.15.192:6836/128425721,v1:172.21.15.192:6837/128425721] --> [v2:172.21.15.196:6824/911994908,v1:172.21.15.196:6825/911994908] -- osd_op(unknown.0.21:27234 4.1fs0 4:fe9c624a:::30000001624.00000000:head [delete] snapc 6=[6,5] ondisk+write+known_if_redirected+full_force+supports_pool_eio e87) -- 0x55b54ae84400 con 0x55b546fdc000
2025-02-06T07:25:39.912+0000 7f3832dd7640 10 mds.2.purge_queue _commit_ops: PURGE_FILE
2025-02-06T07:25:39.912+0000 7f3832dd7640 1 -- [v2:172.21.15.192:6836/128425721,v1:172.21.15.192:6837/128425721] --> [v2:172.21.15.196:6824/911994908,v1:172.21.15.196:6825/911994908] -- osd_op(unknown.0.21:27235 3.3f 3:fe9c624a:::30000001624.00000000:head [delete] snapc 6=[6,5] ondisk+write+known_if_redirected+full_force+supports_pool_eio e87) -- 0x55b5472ba800 con 0x55b546fdc000
2025-02-06T07:25:39.912+0000 7f3832dd7640 10 mds.2.purge_queue _commit_ops: PURGE_FILE
2025-02-06T07:25:39.912+0000 7f3832dd7640 1 -- [v2:172.21.15.192:6836/128425721,v1:172.21.15.192:6837/128425721] --> [v2:172.21.15.177:6826/1885875871,v1:172.21.15.177:6827/1885875871] -- osd_op(unknown.0.21:27236 4.17s0 4:ef016ba0:::30000001636.00000000:head [delete] snapc 6=[6,5] ondisk+write+known_if_redirected+full_force+supports_pool_eio e87) -- 0x55b54beb8400 con 0x55b546fd6400
2025-02-06T07:25:39.912+0000 7f3832dd7640 10 mds.2.purge_queue _commit_ops: PURGE_FILE
2025-02-06T07:25:39.912+0000 7f3832dd7640 1 -- [v2:172.21.15.192:6836/128425721,v1:172.21.15.192:6837/128425721] --> [v2:172.21.15.192:6800/2150231619,v1:172.21.15.192:6801/2150231619] -- osd_op(unknown.0.21:27237 3.37 3:ef016ba0:::30000001636.00000000:head [delete] snapc 6=[6,5] ondisk+write+known_if_redirected+full_force+supports_pool_eio e87) -- 0x55b546d49400 con 0x55b54936b800
2025-02-06T07:25:39.912+0000 7f3832dd7640 10 mds.2.purge_queue _commit_ops: PURGE_FILE
2025-02-06T07:25:39.912+0000 7f3832dd7640 1 -- [v2:172.21.15.192:6836/128425721,v1:172.21.15.192:6837/128425721] --> [v2:172.21.15.196:6816/630658411,v1:172.21.15.196:6817/630658411] -- osd_op(unknown.0.21:27238 4.fs0 4:f2ffe141:::30000001680.00000000:head [delete] snapc 6=[6,5] ondisk+write+known_if_redirected+full_force+supports_pool_eio e87) -- 0x55b54dce1c00 con 0x55b546d49000
2025-02-06T07:25:39.912+0000 7f3832dd7640 10 mds.2.purge_queue _commit_ops: PURGE_FILE
2025-02-06T07:25:39.912+0000 7f3832dd7640 1 -- [v2:172.21.15.192:6836/128425721,v1:172.21.15.192:6837/128425721] --> [v2:172.21.15.192:6816/3467572071,v1:172.21.15.192:6817/3467572071] -- osd_op(unknown.0.21:27239 3.f 3:f2ffe141:::30000001680.00000000:head [delete] snapc 6=[6,5] ondisk+write+known_if_redirected+full_force+supports_pool_eio e87) -- 0x55b54eeefc00 con 0x55b546d49800
2025-02-06T07:25:39.912+0000 7f383bde9640 2 --2- [v2:172.21.15.192:6836/128425721,v1:172.21.15.192:6837/128425721] >> [v2:172.21.15.177:6826/1885875871,v1:172.21.15.177:6827/1885875871] conn(0x55b546fd6400 0x55b546f76c00 crc :-1 s=READY pgs=8 cs=0 l=1 rev1=1 crypto rx=0 tx=0 comp rx=0 tx=0).write_message sending message m=0x55b54beb8400 seq=2097 osd_op(mds.2.21:27236 4.17s0 4:ef016ba0:::30000001636.00000000:head [delete] snapc 6=[6,5] ondisk+write+known_if_redirected+full_force+supports_pool_eio e87)
2025-02-06T07:25:39.912+0000 7f383b5e8640 2 --2- [v2:172.21.15.192:6836/128425721,v1:172.21.15.192:6837/128425721] >> [v2:172.21.15.192:6800/2150231619,v1:172.21.15.192:6801/2150231619] conn(0x55b54936b800 0x55b549490000 crc :-1 s=READY pgs=14 cs=0 l=1 rev1=1 crypto rx=0 tx=0 comp rx=0 tx=0).write_message sending message m=0x55b546d49400 seq=1642 osd_op(mds.2.21:27237 3.37 3:ef016ba0:::30000001636.00000000:head [delete] snapc 6=[6,5] ondisk+write+known_if_redirected+full_force+supports_pool_eio e87)
2025-02-06T07:25:39.912+0000 7f383b5e8640 2 --2- [v2:172.21.15.192:6836/128425721,v1:172.21.15.192:6837/128425721] >> [v2:172.21.15.196:6816/630658411,v1:172.21.15.196:6817/630658411] conn(0x55b546d49000 0x55b546f76100 crc :-1 s=READY pgs=8 cs=0 l=1 rev1=1 crypto rx=0 tx=0 comp rx=0 tx=0).write_message sending message m=0x55b54dce1c00 seq=1990 osd_op(mds.2.21:27238 4.fs0 4:f2ffe141:::30000001680.00000000:head [delete] snapc 6=[6,5] ondisk+write+known_if_redirected+full_force+supports_pool_eio e87)
2025-02-06T07:25:39.913+0000 7f3831dd5640 -1 /home/jenkins-build/build/workspace/ceph-dev-new-build/ARCH/x86_64/AVAILABLE_ARCH/x86_64/AVAILABLE_DIST/centos9/DIST/centos9/MACHINE_SIZE/gigantic/release/19.3.0-7359-gbda3f257/rpm/el9/BUILD/ceph-19.3.0-7359-gbda3f257/src/mds/MDCache.cc: In function 'void MDCache::remove_inode(CInode*)' thread 7f3831dd5640 time 2025-02-06T07:25:39.913191+0000
/home/jenkins-build/build/workspace/ceph-dev-new-build/ARCH/x86_64/AVAILABLE_ARCH/x86_64/AVAILABLE_DIST/centos9/DIST/centos9/MACHINE_SIZE/gigantic/release/19.3.0-7359-gbda3f257/rpm/el9/BUILD/ceph-19.3.0-7359-gbda3f257/src/mds/MDCache.cc: 365: FAILED ceph_assert(o->get_num_ref() == 0)
ceph version 19.3.0-7359-gbda3f257 (bda3f2572bc7c9ac5349d0d89e2c5682371b1581) squid (dev)
1: (ceph::__ceph_assert_fail(char const*, char const*, int, char const*)+0x121) [0x7f383e141bdf]
2: /usr/lib64/ceph/libceph-common.so.2(+0x256dec) [0x7f383e141dec]
3: (MDCache::remove_inode(CInode*)+0x502) [0x55b5401fc1a6]
4: (StrayManager::_purge_stray_logged(CDentry*, unsigned long, boost::intrusive_ptr<MutationImpl>&)+0x26c) [0x55b5402de788]
5: /usr/bin/ceph-mds(+0x34b96e) [0x55b5402de96e]
6: (MDSContext::complete(int)+0x7c) [0x55b540451226]
7: (MDSIOContextBase::complete(int)+0x5a6) [0x55b54045196c]
8: (MDSLogContextBase::complete(int)+0x46) [0x55b5404519e8]
9: (Finisher::finisher_thread_entry()+0x4e0) [0x7f383e0c81a6]
10: /usr/lib64/ceph/libceph-common.so.2(+0x1dda97) [0x7f383e0c8a97]
11: (Thread::entry_wrapper()+0x33) [0x7f383e11ddab]
12: (Thread::_entry_func(void*)+0xd) [0x7f383e11ddc1]
13: /lib64/libc.so.6(+0x8a3b2) [0x7f383da073b2]
14: /lib64/libc.so.6(+0x10f430) [0x7f383da8c430]
Quiesce is scheduling an op to quiesce "inode 0x300000026a0 [5,6]" and then resolving it to "inode 0x300000026a0 [...7,head] ~mds2/stray0/300000026a0". That bumps the reference count on the inode to-be-purged triggering the assertion.
Updated by Patrick Donnelly about 1 year ago
- Status changed from New to Fix Under Review
- Pull request ID set to 61680
Updated by Patrick Donnelly about 1 year ago
- Status changed from Fix Under Review to Pending Backport
Updated by Upkeep Bot about 1 year ago
- Copied to Backport #69955: reef: mds: assert crash at FAILED ceph_assert(o->get_num_ref() == 0) added
Updated by Upkeep Bot about 1 year ago
- Copied to Backport #69956: squid: mds: assert crash at FAILED ceph_assert(o->get_num_ref() == 0) added
Updated by Upkeep Bot about 1 year ago
- Tags (freeform) set to backport_processed
Updated by Upkeep Bot 9 months ago
- Merge Commit set to e80e73c6c3b028b528e043a9ea693675d1f78173
- Fixed In set to v19.3.0-7581-ge80e73c6c3b
- Upkeep Timestamp set to 2025-07-08T18:07:38+00:00
Updated by Upkeep Bot 8 months ago
- Fixed In changed from v19.3.0-7581-ge80e73c6c3b to v19.3.0-7581-ge80e73c6c3b0
- Upkeep Timestamp changed from 2025-07-08T18:07:38+00:00 to 2025-07-14T15:22:07+00:00
Updated by Upkeep Bot 8 months ago
- Fixed In changed from v19.3.0-7581-ge80e73c6c3b0 to v19.3.0-7581-ge80e73c6c3
- Upkeep Timestamp changed from 2025-07-14T15:22:07+00:00 to 2025-07-14T20:46:36+00:00
Updated by Jos Collin 6 months ago
- Status changed from Pending Backport to Resolved
Updated by Upkeep Bot 5 months ago
- Released In set to v20.2.0~1123
- Upkeep Timestamp changed from 2025-07-14T20:46:36+00:00 to 2025-11-01T01:32:13+00:00
Actions