Ceph » CephFS

We had a successful quiesce on the mds.0 followed by the said export dir request. The export dir request has failed to acquire the quiesce lock, expectedly, but it somehow got stuck

2024-04-21T12:14:58.973+0000 7fa9ec953700 20 mds.0.cache dispatch_quiesce_inode request(mds.0:1992 nref=3) quiescing [inode 0x10000000007 [...12,head] /volumes/qa/sv_1/567795c4-3420-4752-a6f2-111d0eb520d0/postgres/data/pg_wal/ rep@1.1 fragt
ree_t(*^3) v4180 f(v21 m2024-04-21T12:13:33.779632+0000 65=64+1) n(v31 rc2024-04-21T12:14:06.122296+0000 b1073741824 66=64+2)/n(v25 rc2024-04-21T12:13:33.779632+0000 b1073741824 66=64+2) old_inodes=11 (inest mix dirty) (ifile mix) (iquiesce
 lock x=1 by request(mds.0:1992 nref=4)) caps={24989=pAsLsXs/-@1} | dirtyscattered=1 request=1 lock=1 importing=0 dirfrag=1 caps=1 waiter=0 0x55cadcdecc00]
2024-04-21T12:14:58.973+0000 7fa9ec953700 10 mds.0.cache dispatch_quiesce_inode request(mds.0:1992 nref=3) non-auth quiesce complete of [inode 0x10000000007 [...12,head] /volumes/qa/sv_1/567795c4-3420-4752-a6f2-111d0eb520d0/postgres/data/pg
_wal/ rep@1.1 fragtree_t(*^3) v4180 f(v21 m2024-04-21T12:13:33.779632+0000 65=64+1) n(v31 rc2024-04-21T12:14:06.122296+0000 b1073741824 66=64+2)/n(v25 rc2024-04-21T12:13:33.779632+0000 b1073741824 66=64+2) old_inodes=11 (inest mix dirty) (i
file mix) (iquiesce lock x=1 by request(mds.0:1992 nref=4)) caps={24989=pAsLsXs/-@1} | dirtyscattered=1 request=1 lock=1 importing=0 dirfrag=1 caps=1 waiter=0 0x55cadcdecc00]
...
2024-04-21T12:15:00.097+0000 7fa9ee156700  7 mds.0.mig dispatch_export_dir request(mds.0:1981 nref=3) [dir 0x10000000007.110* /volumes/qa/sv_1/567795c4-3420-4752-a6f2-111d0eb520d0/postgres/data/pg_wal/ [2,head] auth{1=1} v=3089 cv=3083/3083 dir_auth=0 ap=1+13 state=1610875905|complete|exporting f(v21 m2024-04-21T12:13:33.672633+0000 8=7+1) n(v31 rc2024-04-21T12:14:45.426888+0000 b117440512 8=7+1)/n(v31 rc2024-04-21T12:13:57.056390+0000 b117440512 8=7+1) hs=8+8,ss=16+0 dirty=3 | ptrwaiter=0 request=1 child=1 frozen=0 subtree=1 importing=0 replicated=1 dirty=1 authpin=1 0x55cadd716000]
...
2024-04-21T12:15:00.097+0000 7fa9f3160700  7 mds.0.locker local_wrlock_start  on (iquiesce lock x=1 by request(mds.0:1992 nref=3)) on [inode 0x10000000007 [...12,head] /volumes/qa/sv_1/567795c4-3420-4752-a6f2-111d0eb520d0/postgres/data/pg_w
al/ rep@1.1 fragtree_t(*^3) v4198 f(v21 m2024-04-21T12:13:33.779632+0000 65=64+1) n(v31 rc2024-04-21T12:14:06.122296+0000 b1073741824 66=64+2)/n(v25 rc2024-04-21T12:13:33.779632+0000 b1073741824 66=64+2) old_inodes=11 (inest mix dirty) (ifi
le mix) (iquiesce lock x=1 by request(mds.0:1992 nref=3)) caps={24989=pAsLsXs/-@1} | dirtyscattered=1 request=2 lock=1 importing=0 dirfrag=1 caps=1 waiter=0 0x55cadcdecc00]

The said quiesce has finished after 15 seconds

2024-04-21T12:15:32.654+0000 7fa9ea14e700 20 quiesce.mgr.24545 <leader_upkeep_db> updating peer 24460 with 1 sets modified in db version range ((56:42)..43]
2024-04-21T12:15:32.654+0000 7fa9ea14e700 10 quiesce.mds.0 <operator()> sending listing q-db[v:(56:43) sets:1/0] to the peer 24460
2024-04-21T12:15:32.654+0000 7fa9ea14e700  1 -- [v2:172.21.15.73:6838/2448738084,v1:172.21.15.73:6839/2448738084] send_to--> mds [v2:172.21.15.129:6836/3029675336,v1:172.21.15.129:6837/3029675336] --  -- ?+0 0x55cadd5aea80
2024-04-21T12:15:32.654+0000 7fa9ea94f700 20 quiesce.agt <agent_thread_main> old = (56:42), current = (56:43)
2024-04-21T12:15:32.654+0000 7fa9ea14e700  1 -- [v2:172.21.15.73:6838/2448738084,v1:172.21.15.73:6839/2448738084] --> [v2:172.21.15.129:6836/3029675336,v1:172.21.15.129:6837/3029675336] --  -- 0x55cadd5aea80 con 0x55cadc8bbc00
2024-04-21T12:15:32.654+0000 7fa9ea94f700 10 quiesce.agt <agent_thread_main> Calling `cancel` on `file:/` with handle <mds.0:1982>

2024-04-21T12:15:32.655+0000 7fa9ea94f700 20 mds.0.cache killing quiesce op request(mds.0:1992 nref=3)
2024-04-21T12:15:32.655+0000 7fa9ea94f700 10 mds.0.cache request_kill request(mds.0:1992 nref=3)
2024-04-21T12:15:32.655+0000 7fa9ea94f700 15 mds.0.cache request_cleanup request(mds.0:1992 nref=3)
2024-04-21T12:15:32.655+0000 7fa9ea94f700  1 -- [v2:172.21.15.73:6838/2448738084,v1:172.21.15.73:6839/2448738084] send_to--> mds [v2:172.21.15.129:6836/3029675336,v1:172.21.15.129:6837/3029675336] -- peer_request(mds.0:1992.0 finish) -- ?+0 0x55cadd1b1180
2024-04-21T12:15:32.655+0000 7fa9ea94f700  1 -- [v2:172.21.15.73:6838/2448738084,v1:172.21.15.73:6839/2448738084] --> [v2:172.21.15.129:6836/3029675336,v1:172.21.15.129:6837/3029675336] -- peer_request(mds.0:1992.0 finish) -- 0x55cadd1b1180 con 0x55cadc8bbc00
2024-04-21T12:15:32.655+0000 7fa9ea94f700 10 mds.0.cache request_drop_foreign_locks forgetting lock (iquiesce lock x=1 by request(mds.0:1992 nref=4)) on 0x55cadcdecc00

this is suspicious.. iquiesce is a local lock, should it be even considered in request_drop_foreign_locks? If this code erroneously excludes this lock from the list, we may be never dropping it properly via Locker::local_xlock_finish(). This would explain why the internal op waiting for that lock never resumed.

The incorrect behavior of the method that stripped the local quiesce lock from the request resulted in the crash when the client happened to release the wrlock on the quiesce lock on the same inode:

2024-04-21T12:18:40.863+0000 7fa9ec953700  7 mds.0.locker local_wrlock_finish  on (iquiesce lock w=1 last_client=24989) on [inode 0x10000000007 [...1a,head] /volumes/qa/sv_1/567795c4-3420-4752-a6f2-111d0eb520d0/postgres/data/pg_wal/ rep@1.1
 fragtree_t(*^3) v4824 f(v21 m2024-04-21T12:13:33.779632+0000 65=64+1) n(v40 rc2024-04-21T12:17:53.624957+0000 b1073741824 66=64+2)/n(v25 rc2024-04-21T12:13:33.779632+0000 b1073741824 66=64+2) old_inodes=11 (isnap sync r=1) (inest mix w=1 d
irty) (ifile mix w=1 dirty) (iquiesce lock w=1 last_client=24989) caps={24989=pAsLsXs/pAsLsXsFsxcral@26} | dirtyscattered=2 request=2 lock=4 importing=0 dirfrag=7 caps=1 dirwaiter=0 waiter=1 discoverbase=0 0x55cadcdecc00]
2024-04-21T12:18:40.864+0000 7fa9f3160700  1 -- [v2:172.21.15.73:6838/2448738084,v1:172.21.15.73:6839/2448738084] <== mds.2 v2:172.21.15.129:6838/2581261009 3851 ==== peer_request(client.24989:4542.0 committed) ==== 139+0+0 (crc 0 0 0) 0x55
cadd255180 con 0x55cadc7ea800
2024-04-21T12:18:40.865+0000 7fa9ec953700 -1 /home/jenkins-build/build/workspace/ceph-dev-new-build/ARCH/x86_64/AVAILABLE_ARCH/x86_64/AVAILABLE_DIST/centos8/DIST/centos8/MACHINE_SIZE/gigantic/release/19.0.0-3154-ga630765c/rpm/el8/BUILD/ceph
-19.0.0-3154-ga630765c/src/mds/Locker.cc: In function 'void Locker::local_wrlock_finish(const lock_iterator&, MutationImpl*)' thread 7fa9ec953700 time 2024-04-21T12:18:40.864289+0000
/home/jenkins-build/build/workspace/ceph-dev-new-build/ARCH/x86_64/AVAILABLE_ARCH/x86_64/AVAILABLE_DIST/centos8/DIST/centos8/MACHINE_SIZE/gigantic/release/19.0.0-3154-ga630765c/rpm/el8/BUILD/ceph-19.0.0-3154-ga630765c/src/mds/Locker.cc: 5513: FAILED ceph_assert(!lock->is_waiter_for(SimpleLock::WAIT_WR) || lock->is_waiter_for(SimpleLock::WAIT_XLOCK))

fixing the request_drop_foreign_locks method uncovered another crash due to the same reason, this time when dropping the locks:

2024-04-22T06:57:07.321+0000 7f1b41447700 20 mds.0.cache killing quiesce op request(mds.0:2027 nref=3)
2024-04-22T06:57:07.321+0000 7f1b41447700 10 mds.0.cache request_kill request(mds.0:2027 nref=3)
2024-04-22T06:57:07.321+0000 7f1b41447700 15 mds.0.cache request_cleanup request(mds.0:2027 nref=3)
2024-04-22T06:57:07.323+0000 7f1b41447700 -1 /home/jenkins-build/build/workspace/ceph-dev-new-build/ARCH/x86_64/AVAILABLE_ARCH/x86_64/AVAILABLE_DIST/centos8/DIST/centos8/MACHINE_SIZE/gigantic/release/19.0.0-3156-g86f7587a/rpm/el8/BUILD/ceph
-19.0.0-3156-g86f7587a/src/mds/Locker.cc: In function 'void Locker::_drop_locks(MutationImpl*, std::set<CInode*>*, bool)' thread 7f1b41447700 time 2024-04-22T06:57:07.322796+0000
/home/jenkins-build/build/workspace/ceph-dev-new-build/ARCH/x86_64/AVAILABLE_ARCH/x86_64/AVAILABLE_DIST/centos8/DIST/centos8/MACHINE_SIZE/gigantic/release/19.0.0-3156-g86f7587a/rpm/el8/BUILD/ceph-19.0.0-3156-g86f7587a/src/mds/Locker.cc: 720
: FAILED ceph_assert(lock->get_sm()->can_remote_xlock)

 ceph version 19.0.0-3156-g86f7587a (86f7587a5a09af35f0895e1a2d08527638fae697) squid (dev)
 1: (ceph::__ceph_assert_fail(char const*, char const*, int, char const*)+0x135) [0x7f1b542813dd]
 2: /usr/lib64/ceph/libceph-common.so.2(+0x2d15a3) [0x7f1b542815a3]
 3: (Locker::_drop_locks(MutationImpl*, std::set<CInode*, std::less<CInode*>, std::allocator<CInode*> >*, bool)+0xa2c) [0x55624223ae9c]
 4: (Locker::drop_locks(MutationImpl*, std::set<CInode*, std::less<CInode*>, std::allocator<CInode*> >*)+0x7f) [0x55624223af9f]
 5: (MDCache::request_cleanup(boost::intrusive_ptr<MDRequestImpl> const&)+0x243) [0x5562421690d3]
 6: (MDCache::request_cleanup(boost::intrusive_ptr<MDRequestImpl> const&)+0x1ac) [0x55624216903c]
 7: /usr/bin/ceph-mds(+0x60dd3f) [0x5562423e8d3f]
 8: (QuiesceAgent::agent_thread_main()+0x1680) [0x556242451560]
 9: /lib64/libpthread.so.0(+0x81ca) [0x7f1b52fff1ca]
 10: clone()

The assumption wasn't correct that any xlock that's not an auth must be a remote xlock:

  if (it->is_xlock()) {
    if (obj->is_auth()) {
      ...
    } else {
      ceph_assert(lock->get_sm()->can_remote_xlock); // <<

Another instance of this issue: https://pulpito.ceph.com/leonidus-2024-04-21_11:37:13-fs-wip-lusov-quiescer-distro-default-smithi/7666596/

2024-04-21T12:09:29.474 INFO:journalctl@ceph.mon.c.smithi188.stdout:Apr 21 12:09:29 smithi188 ceph-mon[31370]: 1 slow requests, 1 included below; oldest blocked for > 184.805394 secs
2024-04-21T12:09:29.474 INFO:journalctl@ceph.mon.c.smithi188.stdout:Apr 21 12:09:29 smithi188 ceph-mon[31370]: slow request 184.805394 seconds old, received at 2024-04-21T12:06:22.675885+0000: client_request(client.24946:39803 create owner_uid=1000, owner_gid=1316 #0x10000000273/file7017 2024-04-21T12:06:17.693293+0000 FWD=1 caller_uid=1000, caller_gid=1316{6,36,1000,1316,}) currently failed to acquire quiesce lock