Ceph » CephFS

BTW, this crash is seen in the standby-replay MDS daemon.

Venky Shankar wrote:

BTW, this crash is seen in the standby-replay MDS daemon.

Sure Venky, not getting a chance to check it yet.

... and we have a core to inspect. Hopefully things go well.

Venky Shankar wrote:

... and we have a core to inspect. Hopefully things go well.

Sounds good.

The LogSegment has an empty `pending_commit_tids` map

(gdb) p pending_commit
$9 = std::map with 1 element = {[174037] = 0x55919f128300}
(gdb) p (LogSegment *)0x55919f128300
$10 = (LogSegment *) 0x55919f128300
(gdb) p *(LogSegment *)0x55919f128300
$11 = {seq = 94081258618881, offset = 94083927409456, end = 0, num_events = 0, dirty_dirfrags = {_head = {_prev = 0x2a0b, _next = 0x0}, item_offset = 94081258618881}, new_dirfrags = {_head = {_prev = 0x55919f1282d0, _next = 0x55919f128300},
    item_offset = 94083927409504}, dirty_inodes = {_head = {_prev = 0x2a0c, _next = 0x0}, item_offset = 94081258618881}, dirty_dentries = {_head = {_prev = 0x55919f128330, _next = 0x0}, item_offset = 0}, open_files = {_head = {_prev = 0x2a0d, _next = 0x0},
    item_offset = 94081258618881}, dirty_parent_inodes = {_head = {_prev = 0x55919f128690, _next = 0x55919f128210}, item_offset = 94083927409936}, dirty_dirfrag_dir = {_head = {_prev = 0x2a0e, _next = 0x0}, item_offset = 94081258618881}, dirty_dirfrag_nest = {_head = {
      _prev = 0x55919f1283f0, _next = 0x0}, item_offset = 0}, dirty_dirfrag_dirfragtree = {_head = {_prev = 0x2a0f, _next = 0x0}, item_offset = 94081258618881},
  truncating_inodes = std::set with 94081258618881 elements<error reading variable: Cannot access memory at address 0x2a28>, purging_inodes = {_size = 94083927409648,
    m = std::map with 94083927409936 elements<error reading variable: Cannot access memory at address 0x18>}, purged_cb = 0x55919f1283f0, pending_commit_tids = std::map with 0 elements,
  uncommitted_leaders = std::set with 94083927409792 elements<error reading variable: Cannot access memory at address 0x400010>, uncommitted_peers = std::set with 0 elements,
  uncommitted_fragments = std::set with 94083927409744 elements<error reading variable: Cannot access memory at address 0x400010>, last_client_tids = std::map with 0 elements,
  touched_sessions = std::set with 94083927409984 elements<error reading variable: Cannot access memory at address 0x400010>, inotablev = 94083927410080, sessionmapv = 10776,
  tablev = std::map with 10777 elements<error reading variable: Cannot access memory at address 0x18>, expiry_waiters = std::vector of length 0, capacity 11760490926242 = {<error reading variable>
(gdb) p ((LogSegment *)0x55919f128300)->pending_commit_tids
$12 = std::map with 0 elements

but `MDSTableClient::got_journaled_ack` tries to remove an element from the map value.

void MDSTableClient::got_journaled_ack(version_t tid)
{
  dout(10) << "got_journaled_ack " << tid << dendl;
  if (pending_commit.count(tid)) {
    pending_commit[tid]->pending_commit_tids[table].erase(tid);  <-- here
    pending_commit.erase(tid);
  }
}

So, this happens in a standby-replay daemon

(gdb) bt
#0  0x00007f6a667c854c in __pthread_kill_implementation () from /lib64/libc.so.6
#1  0x00007f6a6677bd46 in raise () from /lib64/libc.so.6
#2  0x0000558ffa73187a in reraise_fatal (signum=11) at /usr/src/debug/ceph-17.2.6-148.el9cp.x86_64/src/global/signal_handler.cc:88
#3  handle_oneshot_fatal_signal (signum=11) at /usr/src/debug/ceph-17.2.6-148.el9cp.x86_64/src/global/signal_handler.cc:363
#4  <signal handler called>
#5  0x00007f6a66aee0d3 in std::_Rb_tree_decrement(std::_Rb_tree_node_base*) () from /lib64/libstdc++.so.6
#6  0x0000558ffa4078e5 in std::_Rb_tree_iterator<std::pair<int const, std::__cxx11::basic_string<char, std::char_traits<char>, std::allocator<char> > > >::operator-- (this=<synthetic pointer>) at /usr/include/c++/11/bits/stl_tree.h:302
#7  std::_Rb_tree<int, std::pair<int const, std::__cxx11::basic_string<char, std::char_traits<char>, std::allocator<char> > >, std::_Select1st<std::pair<int const, std::__cxx11::basic_string<char, std::char_traits<char>, std::allocator<char> > > >, std::less<int>, std::allocator<std::pair<int const, std::__cxx11::basic_string<char, std::char_traits<char>, std::allocator<char> > > > >::_M_get_insert_unique_pos (this=<optimized out>, __k=@0x559077906bc0: 1) at /usr/include/c++/11/bits/stl_tree.h:2080
#8  0x0000558ffa7ccea2 in std::_Rb_tree<int, std::pair<int const, std::unordered_set<unsigned long, std::hash<unsigned long>, std::equal_to<unsigned long>, std::allocator<unsigned long> > >, std::_Select1st<std::pair<int const, std::unordered_set<unsigned long, std::hash<unsigned long>, std::equal_to<unsigned long>, std::allocator<unsigned long> > > >, std::less<int>, std::allocator<std::pair<int const, std::unordered_set<unsigned long, std::hash<unsigned long>, std::equal_to<unsigned long>, std::allocator<unsigned long> > > > >::_M_get_insert_hint_unique_pos (__k=@0x559077906bc0: 1, __position={first = 0, second = std::unordered_set with 94081258618881 elements}, this=0x55919f128468) at /usr/include/c++/11/bits/stl_tree.h:2209
#9  std::_Rb_tree<int, std::pair<int const, std::unordered_set<unsigned long, std::hash<unsigned long>, std::equal_to<unsigned long>, std::allocator<unsigned long> > >, std::_Select1st<std::pair<int const, std::unordered_set<unsigned long, std::hash<unsigned long>, std::equal_to<unsigned long>, std::allocator<unsigned long> > > >, std::less<int>, std::allocator<std::pair<int const, std::unordered_set<unsigned long, std::hash<unsigned long>, std::equal_to<unsigned long>, std::allocator<unsigned long> > > > >::_M_emplace_hint_unique<std::piecewise_construct_t const&, std::tuple<int const&>, std::tuple<> >(std::_Rb_tree_const_iterator<std::pair<int const, std::unordered_set<unsigned long, std::hash<unsigned long>, std::equal_to<unsigned long>, std::allocator<unsigned long> > > >, std::piecewise_construct_t const&, std::tuple<int const&>&&, std::tuple<>&&) [clone .constprop.0] [clone .isra.0] (this=0x55919f128468, __pos={first = 0, second = std::unordered_set with 94081258618881 elements}) at /usr/include/c++/11/bits/stl_tree.h:2435
#10 0x0000558ffa67d9fc in std::map<int, std::unordered_set<unsigned long, std::hash<unsigned long>, std::equal_to<unsigned long>, std::allocator<unsigned long> >, std::less<int>, std::allocator<std::pair<int const, std::unordered_set<unsigned long, std::hash<unsigned long>, std::equal_to<unsigned long>, std::allocator<unsigned long> > > > >::operator[] (__k=@0x558ffb691450: 1, this=<optimized out>) at /usr/include/c++/11/bits/stl_tree.h:350
#11 MDSTableClient::got_journaled_ack (this=0x558ffb691440, tid=<optimized out>) at /usr/src/debug/ceph-17.2.6-148.el9cp.x86_64/src/mds/MDSTableClient.cc:222
#12 0x0000558ffa6c8923 in MDLog::_replay_thread (this=0x558ffc40c300) at /usr/src/debug/ceph-17.2.6-148.el9cp.x86_64/src/mds/MDLog.cc:1436
#13 0x0000558ffa43ff41 in MDLog::ReplayThread::entry (this=<optimized out>) at /usr/src/debug/ceph-17.2.6-148.el9cp.x86_64/src/mds/MDLog.h:192
#14 0x00007f6a667c6802 in start_thread () from /lib64/libc.so.6
#15 0x00007f6a66766450 in clone3 () from /lib64/libc.so.6
(gdb) f 12
#12 0x0000558ffa6c8923 in MDLog::_replay_thread (this=0x558ffc40c300) at /usr/src/debug/ceph-17.2.6-148.el9cp.x86_64/src/mds/MDLog.cc:1436
1436            le->replay(mds);
(gdb) p mds->state
$36 = MDSMap::STATE_STANDBY_REPLAY

EMetaBlob::table_tids is persisted in mdlog which holds the commits tids, however, the standby-replay daemon didn't seem to replay that log segment (perhaps that log segment was trimmed by the active MDS?). If the next log segment has the `TABLESERVER_OP_ACK` log event, this crash will happen.

/a/vshankar-2024-05-10_15:47:15-fs-wip-vshankar-testing-20240509.114851-debug-testing-default-smithi/7701383

The underlying cause is describe in https://tracker.ceph.com/issues/59119 - the active MDS trims a log segment from the journal but the s-r daemon still think it can still continue replaying the log segments which is incorrect and leads to this crash.