Ceph

thank you sage for review it. yes it can reproducible in our envirment. and it is vesy stange it

only happen in the second mon. I have three mon, when i use watch ceph osd perf, it will core dump

it the second mon. But if i remove the second mon and use watch ceph osd perf it will normal. I

will do it as you said later to see what is wrong with it.

Hi sage the below is the gdb trace.

(gdb) where
#0 0x00007fdc75ea6269 in raise (sig=6) at ../sysdeps/unix/sysv/linux/pt-raise.c:35
#1 0x0000559c16766e4e in ?? ()
#2 <signal handler called>
#3 0x00007fdc745f4428 in _GI_raise (sig=sig@entry=6) at ../sysdeps/unix/sysv/linux/raise.c:54
#4 0x00007fdc745f602a in __GI_abort () at abort.c:89
#5 0x0000559c16255489 in PGStatService::process_pg_command(std::_cxx11::basic_string<char, std::char_traits<char>, std::allocator<char> > const&, std::map<std::__cxx11::basic_string<char, std::char_traits<char>, std::allocator<char> >, boost::variant<std::__cxx11::basic_string<char, std::char_traits<char>, std::allocator<char> >, bool, long, double, std::vector<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> > > >, std::vector<long, std::allocator<long> >, std::vector<double, std::allocator<double> > >, std::less<std::__cxx11::basic_string<char, std::char_traits<char>, std::allocator<char> > >, std::allocator<std::pair<std::__cxx11::basic_string<char, std::char_traits<char>, std::allocator<char> > const, boost::variant<std::__cxx11::basic_string<char, std::char_traits<char>, std::allocator<char> >, bool, long, double, std::vector<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> > > >, std::vector<long, std::allocator<long> >, std::vector<double, std::allocator<double> > > > > > const&, OSDMap const&, ceph::Formatter*, std::__cxx11::basic_stringstream<char, std::char_traits<char>, std::allocator<char> >, ceph::buffer::list) const ()
#6 0x0000559c1633ca99 in OSDMonitor::preprocess_command(boost::intrusive_ptr<MonOpRequest>) ()
#7 0x0000559c163465b0 in OSDMonitor::preprocess_query(boost::intrusive_ptr<MonOpRequest>) ()
#8 0x0000559c162f0970 in PaxosService::dispatch(boost::intrusive_ptr<MonOpRequest>) ()
#9 0x0000559c161b618a in Monitor::handle_command(boost::intrusive_ptr<MonOpRequest>) ()
#10 0x0000559c161bd1ce in Monitor::dispatch_op(boost::intrusive_ptr<MonOpRequest>) ()
#11 0x0000559c161be21b in Monitor::_ms_dispatch(Message*) ()
#12 0x0000559c161ed9e3 in Monitor::ms_dispatch(Message*) ()
#13 0x0000559c1670f3da in DispatchQueue::entry() ()
#14 0x0000559c164c0e3d in DispatchQueue::DispatchThread::entry() ()
#15 0x00007fdc75e9c6ba in start_thread (arg=0x7fdc6e153700) at pthread_create.c:333
#16 0x00007fdc746c63dd in clone () at ../sysdeps/unix/sysv/linux/x86_64/clone.S:109

Hi sage i want to debug it myself. why i use gdb can not enter the funtion like below. I have install the mon-dbg. do i need to rebuild the ceph code and enable the -g option in makefile? thank you !

Thread 15 "ms_dispatch" hit Breakpoint 1, 0x0000559b25a9fe34 in Monitor::handle_command(boost::intrusive_ptr<MonOpRequest>) ()
(gdb) n
Single stepping until exit from function _ZN7Monitor14handle_commandEN5boost13intrusive_ptrI12MonOpRequestEE,
which has no line number information.
0x0000559b25aa91ce in Monitor::dispatch_op(boost::intrusive_ptr<MonOpRequest>) ()
(gdb) n
Single stepping until exit from function _ZN7Monitor11dispatch_opEN5boost13intrusive_ptrI12MonOpRequestEE,
which has no line number information.
0x0000559b25aaa21b in Monitor::_ms_dispatch(Message*) ()
(gdb) n
Single stepping until exit from function _ZN7Monitor12_ms_dispatchEP7Message,
which has no line number information.
0x0000559b25ad99e3 in Monitor::ms_dispatch(Message*) ()
(gdb) n
Single stepping until exit from function _ZN7Monitor11ms_dispatchEP7Message,
which has no line number information.
0x0000559b25ffb3da in DispatchQueue::entry() ()
(gdb) n

It mush be a bug. for the same command ceph pg dump. sometimes it will success.sometimes it will have the below error.it is very amazing.

root@node-1151:~# ceph -s
cluster:
id: 3edc30f3-2157-4251-b94c-2a81db839bc8
health: HEALTH_WARN
too many PGs per OSD (320 > max 300)

services:
    mon: 3 daemons, quorum node-1150,node-1151,node-1152
    mgr: node-1150(active), standbys: node-1152, node-1151
    osd: 3 osds: 3 up, 3 in

data:
    pools:   5 pools, 320 pgs
    objects: 16605 objects, 95870 MB
    usage:   287 GB used, 2509 GB / 2797 GB avail
    pgs:     320 active+clean

root@node-1151:~# ceph pg dump
Error ENOTSUP: this command is obsolete

(gdb) bt
#0 0x00007ff1b4d35269 in raise (sig=6) at ../sysdeps/unix/sysv/linux/pt-raise.c:35
#1 0x000055e6ef92c62c in reraise_fatal (signum=6) at /home/ceph/ceph/src/global/signal_handler.cc:74
#2 0x000055e6ef92c9a4 in handle_fatal_signal (signum=6) at /home/ceph/ceph/src/global/signal_handler.cc:138
#3 <signal handler called>
#4 0x00007ff1b3483428 in __GI_raise (sig=sig@entry=6) at ../sysdeps/unix/sysv/linux/raise.c:54
#5 0x00007ff1b348502a in __GI_abort () at abort.c:89
#6 0x000055e6ef1ae053 in PGStatService::process_pg_command (this=0x55e6fa112470, prefix="osd perf", cmdmap=std::map with 1 elements = {...}, osdmap=..., f=0x0,
ss=0x7ff1acfdd9c0, odata=0x7ff1acfdcb80) at /home/ceph/ceph/src/mon/PGStatService.h:90
#7 0x000055e6ef2eceb1 in OSDMonitor::preprocess_command (this=0x55e6fa64a000, op=...) at /home/ceph/ceph/src/mon/OSDMonitor.cc:3933
#8 0x000055e6ef2cee12 in OSDMonitor::preprocess_query (this=0x55e6fa64a000, op=...) at /home/ceph/ceph/src/mon/OSDMonitor.cc:1450
#9 0x000055e6ef2b92e8 in PaxosService::dispatch (this=0x55e6fa64a000, op=...) at /home/ceph/ceph/src/mon/PaxosService.cc:74
#10 0x000055e6ef07ed99 in Monitor::handle_command (this=0x55e6fa172800, op=...) at /home/ceph/ceph/src/mon/Monitor.cc:3179
#11 0x000055e6ef08b40d in Monitor::dispatch_op (this=0x55e6fa172800, op=...) at /home/ceph/ceph/src/mon/Monitor.cc:4276
#12 0x000055e6ef08abad in Monitor::_ms_dispatch (this=0x55e6fa172800, m=0x55e6fa19af40) at /home/ceph/ceph/src/mon/Monitor.cc:4171
#13 0x000055e6ef0c7004 in Monitor::ms_dispatch (this=0x55e6fa172800, m=0x55e6fa19af40) at /home/ceph/ceph/src/mon/Monitor.h:899
#14 0x000055e6ef8c6a17 in Messenger::ms_deliver_dispatch (this=0x55e6fa554800, m=0x55e6fa19af40) at /home/ceph/ceph/src/msg/Messenger.h:625
#15 0x000055e6ef8c59ee in DispatchQueue::entry (this=0x55e6fa554980) at /home/ceph/ceph/src/msg/DispatchQueue.cc:197
#16 0x000055e6ef5c5f70 in DispatchQueue::DispatchThread::entry (this=0x55e6fa554b28) at /home/ceph/ceph/src/msg/DispatchQueue.h:101
#17 0x000055e6ef6fc58f in Thread::entry_wrapper (this=0x55e6fa554b28) at /home/ceph/ceph/src/common/Thread.cc:79
#18 0x000055e6ef6fc4c4 in Thread::_entry_func (arg=0x55e6fa554b28) at /home/ceph/ceph/src/common/Thread.cc:59
#19 0x00007ff1b4d2b6ba in start_thread (arg=0x7ff1acfe2700) at pthread_create.c:333
#20 0x00007ff1b35553dd in clone () at ../sysdeps/unix/sysv/linux/x86_64/clone.S:109

virtual int process_pg_command(const string& prefix, | |85 const map<string,cmd_vartype>& cmdmap, | |86 const OSDMap& osdmap, | |87 Formatter *f, | |88 stringstream *ss, | |89 bufferlist *odata) const { |
B+>|90 ceph_abort(); | |91 }

linghucong linghucong wrote:

virtual int process_pg_command(const string& prefix, | |85 const map<string,cmd_vartype>& cmdmap, | |86 const OSDMap& osdmap, | |87 Formatter *f, | |88 stringstream *ss, | |89 bufferlist *odata) const { |
B+>|90 ceph_abort(); | |91 }

why the code come here? it is amazing!

it look like the pgservice shoule be the sub class but it is the base class. haha!

linghucong linghucong wrote:

it look like the pgservice shoule be the sub class but it is the base class. haha!

else if (prefix "osd perf" ||
prefix "osd blocked-by") {
r = mon->pgservice->process_pg_command(prefix, cmdmap,
osdmap, f.get(), &ss, &rdata);

the ceph osd perf cmd should handle the by the mgr not the mon. so the core dump here is why this cmd is handled by the mon.in my other two mon there are not this problem. it is really make me some amazing and confused.

this bug look like relate to the mgr. after I reboot all the three mgr. this bug can not happen again! but it can be sure it is bug for mgr. it is no doubt.

Looks like an iteration of http://tracker.ceph.com/issues/21300

Please try the luminous branch, which will eventually become v12.2.2; the fix for #21300 is not included in v12.2.1.

oh thank you for reply. I will try to merge that change code and rebuild it. I will try to verification it.

look like the code have change a lot. i will wait the v12.2.2 release to verification it.

look like that 21300 pr can not fix this just from the code. because i have see the log in mon.

look like it is a diffrent problem. I also found a bug accidental when i repeat reboot the mgr in ceph cluster.

some of the pg become unknown with ceph -s. But i do not catch it.

2017-10-26 20:36:08.781453 7f8e4a2fef00 15 mon.node-1151@-1(probing).log v43405 update_from_paxos logging for 0 channels
2017-10-26 20:36:08.781465 7f8e4a2fef00 10 mon.node-1151@-1(probing).log v43405 check_subs
2017-10-26 20:36:08.781616 7f8e4a2fef00 1 mon.node-1151@-1(probing).paxosservice(auth 501..545) refresh upgraded, format 0 -> 2
2017-10-26 20:36:08.781628 7f8e4a2fef00 10 mon.node-1151@-1(probing).auth v545 update_from_paxos
2017-10-26 20:36:08.781668 7f8e4a2fef00 10 mon.node-1151@-1(probing).auth v545 update_from_paxos version 545 keys ver 0 latest 541
2017-10-26 20:36:08.781729 7f8e4a2fef00 7 mon.node-1151@-1(probing).auth v545 update_from_paxos loading summary e 541
2017-10-26 20:36:08.781739 7f8e4a2fef00 7 mon.node-1151@-1(probing).auth v545 update_from_paxos latest length 2636
2017-10-26 20:36:08.782706 7f8e4a2fef00 10 mon.node-1151@-1(probing).auth v545 update_from_paxos key server version 541
2017-10-26 20:36:08.783420 7f8e4a2fef00 10 mon.node-1151@-1(probing).auth v545 update_from_paxos() last_allocated_id=1374096 max_global_id=1374096 format_version 2
2017-10-26 20:36:08.783518 7f8e4a2fef00 4 mon.node-1151@-1(probing).mgr e0 loading version 10803
2017-10-26 20:36:08.783626 7f8e4a2fef00 4 mon.node-1151@-1(probing).mgr e10803 active server: 10.11.1.150:6802/114872(394134)
2017-10-26 20:36:08.783727 7f8e4a2fef00 4 mon.node-1151@-1(probing).mgr e10803 mkfs or daemon transitioned to available, loading commands
2017-10-26 20:36:08.783760 7f8e4a2fef00 -1 mon.node-1151@-1(probing).mgr e10803 Failed to load mgr commands: (2) No such file or directory

Hi Joao I have merge your change code pr. but it also core dump. The error msg as below maybe help to you.

this only happen in the second mon.like below node-1151. the node-1150 and node-1152 are all ok.

root@node-1151:/usr/bin# ceph -s
cluster:
id: 3edc30f3-2157-4251-b94c-2a81db839bc8
health: HEALTH_WARN
too many PGs per OSD (320 > max 300)

services:
    mon: 3 daemons, quorum node-1150,node-1151,node-1152
    mgr: node-1150(active), standbys: node-1151, node-1152
    osd: 3 osds: 3 up, 3 in

data:
    pools:   5 pools, 320 pgs
    objects: 16605 objects, 95875 MB
    usage:   287 GB used, 2509 GB / 2797 GB avail
    pgs:     320 active+clean

root@node-1151:/usr/bin# ceph-mon -i node-1151
2017-10-27 10:22:41.806705 7f7d2d7d7f00 -1 mon.node-1151@-1(probing).mgr e10827 Failed to load mgr commands: (2) No such file or directory

I have fix it!HA HA!

https://github.com/ceph/ceph/pull/18580

Noted. I will need to go through the code and attempt to reproduce this over the weekend or first thing on monday.

Thanks Paul. Looking into it this afternoon.

Paul, I was able to reliably reproduce this in v12.2.1, but completely unable to do so when running a version with the monitor patches that have been mentioned in this ticket.

Could you please try it on your side with the patches available from the following branch?

https://github.com/jecluis/ceph/tree/wip-mon-fixes-for-v12.2.1

(All these patches are available on the luminous branch, and will be part of v12.2.2)

Thanks!

can confirm, 12.2.2 fixes this, thanks :)