Ceph » RADOS

Neha Ojha wrote:

Do you happen to have a coredump for this or can you provide a copy of the mon store db?

Unfortunately there is no coredump (unless Ceph has stored that somewhere I did not look).
I gladly provide a copy of the mon store db - just let me know how to create / dump what you need.

Hi Christian,

From the log this was a segfault in MonitorDBStore::get_synchronizer.

2021-03-14 18:00:28.679 7f1c0236f700 -1 ** Caught signal (Segmentation fault) *

If you could archive the store.db directory of the mon and upload that with
ceph-post-file that might be helpful. Please also include the dmesg and syslog
files from the time the crash occurred. Let us know the id returned by
ceph-post-file in a comment so we can find it on our side.

Meantime, I'm working on trying to narrow down the exact line where the segfault
took place which will give us a better idea of what specific data caused the
issue.

So the offset into MonitorDBStore::get_synchronizer where we segfaulted was
0x3f.

If we set up a binary compatible environment we can work out what line and
instruction that was in gdb.

(gdb) p/d 0x3f
$2 = 63
(gdb) disass /m MonitorDBStore::get_synchronizer
...
520 if (!key.first.empty() && !key.second.empty())
0x000055555566a56f <+63>: cmpq $0x0,0x8(%rbx)

So that is line 520 in src/mon/MonitorDBStore.h

(gdb) l src/mon/MonitorDBStore.h:520
515 Synchronizer get_synchronizer(pair<string,string> &key,
516 set<string> &prefixes) {
517 KeyValueDB::WholeSpaceIterator iter;
518 iter = db->get_wholespace_iterator();
519
520 if (!key.first.empty() && !key.second.empty())
521 iter->upper_bound(key.first, key.second);
522 else
523 iter->seek_to_first();
524

So this looks like there is something wrong with the 'key' pair passed in to
this function from Monitor::_scrub. An analysis of the database might tell us
which key/value pair that was and how it is corrupt.

I'd expect to see this every day on this mon since mon_scrub_interval is by
default one day but perhaps the offending kv pair was successfully
overwritten or deleted, or perhaps this was a memory glitch on the machine
itself? If that's the case, in the absence of a core dump, we are unlikely to be
able to determine what the issue was.

Brad Hubbard wrote:

Hi Christian,

From the log this was a segfault in MonitorDBStore::get_synchronizer.

2021-03-14 18:00:28.679 7f1c0236f700 -1 ** Caught signal (Segmentation fault) *

If you could archive the store.db directory of the mon and upload that with
ceph-post-file that might be helpful. Please also include the dmesg and syslog
files from the time the crash occurred. Let us know the id returned by
ceph-post-file in a comment so we can find it on our side.

Meantime, I'm working on trying to narrow down the exact line where the segfault
took place which will give us a better idea of what specific data caused the
issue.

Thank Brad for looking into this issue! I tared the store.db and also added the ceph-mon log output.
But there is no more info than I shared in the initial post. Nothing in dmesg or else.

Here you go with the ID:

ceph-post-file: 7a666273-a0c5-43b4-8764-e023a50edead

Hi Christian,

Is there no message in syslog or dmesg about the segfault at all? That seems odd. Maybe you should check why your system is not creating coredumps and not even logging about application segfaults?

I'm beginning to think the previous line makes more sense in the context of what we are seeing and threfore I'm leaning away from database corruption.

I'll explain.

./src/mon/MonitorDBStore.h:
518         iter = db->get_wholespace_iterator();
   0x000000000026a55b <+43>:    mov    (%rsi),%rax
   0x000000000026a55e <+46>:    mov    %rdi,%r12
   0x000000000026a561 <+49>:    mov    %rdx,%rbx
   0x000000000026a564 <+52>:    mov    %rcx,%r15
   0x000000000026a567 <+55>:    lea    0x20(%rsp),%rdi
   0x000000000026a56c <+60>:    callq  *0x60(%rax) <<--------------- HERE

519
520         if (!key.first.empty() && !key.second.empty())
   0x000000000026a56f <+63>:    cmpq   $0x0,0x8(%rbx)

The position counter (instruction pointer if you like) is pointing to +63 but it will move there as we execute +60 and that appears to be the call to db->get_wholespace_iterator().

If I run the binary under gdb and set a breakpoint on get_wholespace_iterator() I see the following.

(gdb) bt 3
#0  RocksDBStore::get_wholespace_iterator (this=0x555556754300) at ./src/kv/RocksDBStore.cc:1525
#1  0x000055555566a56f in MonitorDBStore::get_synchronizer (this=<optimized out>, key={...}, prefixes=std::set with 17 elements = {...}) at ./src/mon/MonitorDBStore.h:518
#2  0x000055555562c379 in Monitor::_scrub (this=0x55555677a800, r=0x5555576d0028, start=0x5555573facd8, num_keys=0x7fffe1423c8c) at ./src/mon/Monitor.cc:5539
(gdb) f 1
#1  0x000055555566a56f in MonitorDBStore::get_synchronizer (this=<optimized out>, key={...}, prefixes=std::set with 17 elements = {...}) at ./src/mon/MonitorDBStore.h:518
518         iter = db->get_wholespace_iterator();
(gdb) x/i $pc
=> 0x55555566a56f <MonitorDBStore::get_synchronizer(std::pair<std::__cxx11::basic_string<char, std::char_traits<char>, std::allocator<char> >, std::__cxx11::basic_string<char, std::char_traits<char>, std::allocator<char> > >&, std::set<std::__cxx11::basic_string<char, std::char_traits<char>, std::allocator<char> >, std::less<std::__cxx11::basic_string<char, std::char_traits<char>, std::allocator<char> > >, std::allocator<std::__cxx11::basic_string<char, std::char_traits<char>, std::allocator<char> > > >&)+63>:     cmpq   $0x0,0x8(%rbx)
(gdb) x/a 0x000055555566a56f
0x55555566a56f <MonitorDBStore::get_synchronizer(std::pair<std::__cxx11::basic_string<char, std::char_traits<char>, std::allocator<char> >, std::__cxx11::basic_string<char, std::char_traits<char>, std::allocator<char> > >&, std::set<std::__cxx11::basic_string<char, std::char_traits<char>, std::allocator<char> >, std::less<std::__cxx11::basic_string<char, std::char_traits<char>, std::allocator<char> > >, std::allocator<std::__cxx11::basic_string<char, std::char_traits<char>, std::allocator<char> > > >&)+63>:        0x748b4c00087b8348
(gdb) info reg rax
rax            0x555555eacdc8   93825002032584
(gdb) p/x 0x555555eacdc8+0x60
$10 = 0x555555eace28                            
(gdb) x/a 0x555555eace28
0x555555eace28 <_ZTV12RocksDBStore+112>:        0x55555585c820 <RocksDBStore::get_wholespace_iterator()>

Without going into ridiculous detail this is enough to convince me that the pointer to the RocksDBStore instance (db) in MonitorDBStore::get_synchronizer was invalid and that's why we end up with the weird frame 0 on the stack.

"(()+0x12980) [0x7f1c0cfbe980]",

It looks to me like we are actually trying to call a function at 0x12980 indicating that 'db' is uninitialised or has been, or is in the process of being, deleted. This is a better explanation of why you have only seen this once than that the database corruption was deleted/changed/fixed itself. I think there wasn't any corruption and what we are seeing here is a rare race condition which leads to the db structure being invalid at that point in the code under exactly the right circumstances. That also explains why I can find no corruption in the database you uploaded and can list/dump all keys and values without issue.

I need to look further into how this might come about.

I think I've found an issue related to this message in the logs but I'll need to test that theory.

2021-03-14 18:00:28.399 7f1bffb6a700  1 mon.ctrl-01@0(electing) e6 collect_metadata :  no unique device id for : fallback method has no model nor serial'

Will update in the next couple of days.

Brad Hubbard wrote:

I think I've found an issue related to this message in the logs but I'll need to test that theory.

[...]

Will update in the next couple of days.

Thank you very much Brad for really digging into this!
I really appreciate that such a report of a "single" and apparently "random" crash is taken this seriously!

Brad were you able to find out more about the root cause of this crash?

Hi Christian,

No, unfortunately I hit a dead end on this as the log message issue was a red herring.

I'm afraid all we know is that the db pointer somehow ended up corrupted but we would need more information to work out why.