Actions
Bug #8229
closed0.80~rc1: OSD crash (domino effect)
% Done:
0%
Source:
Community (user)
Tags:
Backport:
Regression:
Severity:
2 - major
Reviewed:
Affected Versions:
ceph-qa-suite:
Pull request ID:
Crash signature (v1):
Crash signature (v2):
Description
Situation: degraded cluster recovering/remapping ~20% after replacing some OSDs.
During recovery I reboot two servers with MONs/OSDs so cluster temporary didn't have copies of some (unfound) objects during restart of those servers.
Remaining machines had 6 OSDs up in total.
Some time later I've noticed that all OSDs are down (crashed) due to some sort of domino effect.
Here are log and backtrace from OSD that was up during restart of other machines.
This OSD was expected to stay operational but it crashed during restart of other servers/OSDs.
-7> 2014-04-27 15:14:33.155598 7fd1503e2700 10 monclient: tick
-6> 2014-04-27 15:14:33.155616 7fd1503e2700 10 monclient: _check_auth_rotating have uptodate secrets (they expire after 2014-04-27 15:14:03.155615)
-5> 2014-04-27 15:14:33.155628 7fd1503e2700 10 monclient: renew subs? (now: 2014-04-27 15:14:33.155627; renew after: 2014-04-27 15:14:53.153509) -- no
-4> 2014-04-27 15:14:33.164726 7fd1523e6700 1 -- 192.168.0.7:6802/4596 <== osd.0 192.168.0.250:0/5715 1009 ==== osd_ping(ping e22127 stamp 2014-04-27 15:14:33.166041) v2 ==== 47+0+0 (295349861 0 0) 0x7fd18f1d1500 con 0x7fd182c566e0
-3> 2014-04-27 15:14:33.164751 7fd1523e6700 1 -- 192.168.0.7:6802/4596 --> 192.168.0.250:0/5715 -- osd_ping(ping_reply e22127 stamp 2014-04-27 15:14:33.166041) v2 -- ?+0 0x7fd18f44a000 con 0x7fd182c566e0
-2> 2014-04-27 15:14:33.164825 7fd1533e8700 1 -- 192.168.0.7:6803/4596 <== osd.0 192.168.0.250:0/5715 1009 ==== osd_ping(ping e22127 stamp 2014-04-27 15:14:33.166041) v2 ==== 47+0+0 (295349861 0 0) 0x7fd1950e6bc0 con 0x7fd193891080
-1> 2014-04-27 15:14:33.164843 7fd1533e8700 1 -- 192.168.0.7:6803/4596 --> 192.168.0.250:0/5715 -- osd_ping(ping_reply e22127 stamp 2014-04-27 15:14:33.166041) v2 -- ?+0 0x7fd1947cd340 con 0x7fd193891080
0> 2014-04-27 15:14:33.188354 7fd14f3e0700 -1 osd/PGLog.cc: In function 'void PGLog::merge_log(ObjectStore::Transaction&, pg_info_t&, pg_log_t&, pg_shard_t, pg_info_t&, PGLog::LogEntryHandler*, bool&, bool&)' thread 7fd14f3e0700 time 2014-04-27 15:14:33.113457
osd/PGLog.cc: 512: FAILED assert(log.head >= olog.tail && olog.head >= log.tail)
ceph version 0.80-rc1 (6769f4dc88425396921f94e1a37a1c90758aa3ea)
1: (PGLog::merge_log(ObjectStore::Transaction&, pg_info_t&, pg_log_t&, pg_shard_t, pg_info_t&, PGLog::LogEntryHandler*, bool&, bool&)+0x1c50) [0x7fd16a4dad30]
2: (PG::merge_log(ObjectStore::Transaction&, pg_info_t&, pg_log_t&, pg_shard_t)+0x9c) [0x7fd16a46035c]
3: (PG::RecoveryState::Stray::react(PG::MLogRec const&)+0x482) [0x7fd16a49a352]
4: (boost::statechart::simple_state<PG::RecoveryState::Stray, PG::RecoveryState::Started, boost::mpl::list<mpl_::na, mpl_::na, mpl_::na, mpl_::na, mpl_::na, mpl_::na, mpl_::na, mpl_::na, mpl_::na, mpl_::na, mpl_::na, mpl_::na, mpl_::na, mpl_::na, mpl_::na, mpl_::na, mpl_::na, mpl_::na, mpl_::na, mpl_::na>, (boost::statechart::history_mode)0>::react_impl(boost::statechart::event_base const&, void const*)+0x1f4) [0x7fd16a4ce594]
5: (boost::statechart::state_machine<PG::RecoveryState::RecoveryMachine, PG::RecoveryState::Initial, std::allocator<void>, boost::statechart::null_exception_translator>::send_event(boost::statechart::event_base const&)+0x5b) [0x7fd16a4bb87b]
6: (PG::handle_peering_event(std::tr1::shared_ptr<PG::CephPeeringEvt>, PG::RecoveryCtx*)+0x1c0) [0x7fd16a46cbc0]
7: (OSD::process_peering_events(std::list<PG*, std::allocator<PG*> > const&, ThreadPool::TPHandle&)+0x28c) [0x7fd16a38d7dc]
8: (OSD::PeeringWQ::_process(std::list<PG*, std::allocator<PG*> > const&, ThreadPool::TPHandle&)+0x18) [0x7fd16a3d4a78]
9: (ThreadPool::worker(ThreadPool::WorkThread*)+0xaf1) [0x7fd16a78abb1]
10: (ThreadPool::WorkThread::entry()+0x10) [0x7fd16a78baa0]
11: (()+0x8062) [0x7fd16986a062]
12: (clone()+0x6d) [0x7fd167d92a3d]
NOTE: a copy of the executable, or `objdump -rdS <executable>` is needed to interpret this.
--- logging levels ---
0/ 5 none
0/ 1 lockdep
0/ 1 context
1/ 1 crush
1/ 5 mds
1/ 5 mds_balancer
1/ 5 mds_locker
1/ 5 mds_log
1/ 5 mds_log_expire
1/ 5 mds_migrator
0/ 1 buffer
0/ 1 timer
0/ 1 filer
0/ 1 striper
0/ 1 objecter
0/ 5 rados
0/ 5 rbd
0/ 5 journaler
0/ 5 objectcacher
0/ 5 client
0/ 5 osd
0/ 5 optracker
0/ 5 objclass
1/ 3 filestore
1/ 3 keyvaluestore
1/ 3 journal
0/ 5 ms
1/ 5 mon
0/10 monc
1/ 5 paxos
0/ 5 tp
1/ 5 auth
1/ 5 crypto
1/ 1 finisher
1/ 5 heartbeatmap
1/ 5 perfcounter
1/ 5 rgw
1/ 5 javaclient
1/ 5 asok
1/ 1 throttle
-2/-2 (syslog threshold)
-1/-1 (stderr threshold)
max_recent 10000
max_new 1000
log_file /var/log/ceph/ceph-osd.9.log
--- end dump of recent events ---
2014-04-27 15:14:33.188381 7fd14ebdf700 -1 osd/PGLog.cc: In function 'void PGLog::merge_log(ObjectStore::Transaction&, pg_info_t&, pg_log_t&, pg_shard_t, pg_info_t&, PGLog::LogEntryHandler*, bool&, bool&)' thread 7fd14ebdf700 time 2014-04-27 15:14:33.107709
osd/PGLog.cc: 512: FAILED assert(log.head >= olog.tail && olog.head >= log.tail)
ceph version 0.80-rc1 (6769f4dc88425396921f94e1a37a1c90758aa3ea)
1: (PGLog::merge_log(ObjectStore::Transaction&, pg_info_t&, pg_log_t&, pg_shard_t, pg_info_t&, PGLog::LogEntryHandler*, bool&, bool&)+0x1c50) [0x7fd16a4dad30]
2: (PG::merge_log(ObjectStore::Transaction&, pg_info_t&, pg_log_t&, pg_shard_t)+0x9c) [0x7fd16a46035c]
3: (PG::RecoveryState::Stray::react(PG::MLogRec const&)+0x482) [0x7fd16a49a352]
4: (boost::statechart::simple_state<PG::RecoveryState::Stray, PG::RecoveryState::Started, boost::mpl::list<mpl_::na, mpl_::na, mpl_::na, mpl_::na, mpl_::na, mpl_::na, mpl_::na, mpl_::na, mpl_::na, mpl_::na, mpl_::na, mpl_::na, mpl_::na, mpl_::na, mpl_::na, mpl_::na, mpl_::na, mpl_::na, mpl_::na, mpl_::na>, (boost::statechart::history_mode)0>::react_impl(boost::statechart::event_base const&, void const*)+0x1f4) [0x7fd16a4ce594]
5: (boost::statechart::state_machine<PG::RecoveryState::RecoveryMachine, PG::RecoveryState::Initial, std::allocator<void>, boost::statechart::null_exception_translator>::send_event(boost::statechart::event_base const&)+0x5b) [0x7fd16a4bb87b]
6: (PG::handle_peering_event(std::tr1::shared_ptr<PG::CephPeeringEvt>, PG::RecoveryCtx*)+0x1c0) [0x7fd16a46cbc0]
7: (OSD::process_peering_events(std::list<PG*, std::allocator<PG*> > const&, ThreadPool::TPHandle&)+0x28c) [0x7fd16a38d7dc]
8: (OSD::PeeringWQ::_process(std::list<PG*, std::allocator<PG*> > const&, ThreadPool::TPHandle&)+0x18) [0x7fd16a3d4a78]
9: (ThreadPool::worker(ThreadPool::WorkThread*)+0xaf1) [0x7fd16a78abb1]
10: (ThreadPool::WorkThread::entry()+0x10) [0x7fd16a78baa0]
11: (()+0x8062) [0x7fd16986a062]
12: (clone()+0x6d) [0x7fd167d92a3d]
NOTE: a copy of the executable, or `objdump -rdS <executable>` is needed to interpret this.
--- begin dump of recent events ---
-4> 2014-04-27 15:14:33.188381 7fd14ebdf700 -1 osd/PGLog.cc: In function 'void PGLog::merge_log(ObjectStore::Transaction&, pg_info_t&, pg_log_t&, pg_shard_t, pg_info_t&, PGLog::LogEntryHandler*, bool&, bool&)' thread 7fd14ebdf700 time 2014-04-27 15:14:33.107709
osd/PGLog.cc: 512: FAILED assert(log.head >= olog.tail && olog.head >= log.tail)
ceph version 0.80-rc1 (6769f4dc88425396921f94e1a37a1c90758aa3ea)
1: (PGLog::merge_log(ObjectStore::Transaction&, pg_info_t&, pg_log_t&, pg_shard_t, pg_info_t&, PGLog::LogEntryHandler*, bool&, bool&)+0x1c50) [0x7fd16a4dad30]
2: (PG::merge_log(ObjectStore::Transaction&, pg_info_t&, pg_log_t&, pg_shard_t)+0x9c) [0x7fd16a46035c]
3: (PG::RecoveryState::Stray::react(PG::MLogRec const&)+0x482) [0x7fd16a49a352]
4: (boost::statechart::simple_state<PG::RecoveryState::Stray, PG::RecoveryState::Started, boost::mpl::list<mpl_::na, mpl_::na, mpl_::na, mpl_::na, mpl_::na, mpl_::na, mpl_::na, mpl_::na, mpl_::na, mpl_::na, mpl_::na, mpl_::na, mpl_::na, mpl_::na, mpl_::na, mpl_::na, mpl_::na, mpl_::na, mpl_::na, mpl_::na>, (boost::statechart::history_mode)0>::react_impl(boost::statechart::event_base const&, void const*)+0x1f4) [0x7fd16a4ce594]
5: (boost::statechart::state_machine<PG::RecoveryState::RecoveryMachine, PG::RecoveryState::Initial, std::allocator<void>, boost::statechart::null_exception_translator>::send_event(boost::statechart::event_base const&)+0x5b) [0x7fd16a4bb87b]
6: (PG::handle_peering_event(std::tr1::shared_ptr<PG::CephPeeringEvt>, PG::RecoveryCtx*)+0x1c0) [0x7fd16a46cbc0]
7: (OSD::process_peering_events(std::list<PG*, std::allocator<PG*> > const&, ThreadPool::TPHandle&)+0x28c) [0x7fd16a38d7dc]
8: (OSD::PeeringWQ::_process(std::list<PG*, std::allocator<PG*> > const&, ThreadPool::TPHandle&)+0x18) [0x7fd16a3d4a78]
9: (ThreadPool::worker(ThreadPool::WorkThread*)+0xaf1) [0x7fd16a78abb1]
10: (ThreadPool::WorkThread::entry()+0x10) [0x7fd16a78baa0]
11: (()+0x8062) [0x7fd16986a062]
12: (clone()+0x6d) [0x7fd167d92a3d]
NOTE: a copy of the executable, or `objdump -rdS <executable>` is needed to interpret this.
-3> 2014-04-27 15:14:33.188407 7fd1523e6700 1 -- 192.168.0.7:6802/4596 <== osd.6 192.168.0.204:0/14861 3676 ==== osd_ping(ping e22127 stamp 2014-04-27 15:14:33.190958) v2 ==== 47+0+0 (1266741472 0 0) 0x7fd190931500 con 0x7fd18e9d3440
-2> 2014-04-27 15:14:33.188407 7fd1533e8700 1 -- 192.168.0.7:6803/4596 <== osd.6 192.168.0.204:0/14861 3676 ==== osd_ping(ping e22127 stamp 2014-04-27 15:14:33.190958) v2 ==== 47+0+0 (1266741472 0 0) 0x7fd1738e1340 con 0x7fd18e9d3b20
-1> 2014-04-27 15:14:33.188447 7fd1533e8700 1 -- 192.168.0.7:6803/4596 --> 192.168.0.204:0/14861 -- osd_ping(ping_reply e22127 stamp 2014-04-27 15:14:33.190958) v2 -- ?+0 0x7fd1950e6bc0 con 0x7fd18e9d3b20
0> 2014-04-27 15:14:33.188518 7fd1523e6700 1 -- 192.168.0.7:6802/4596 --> 192.168.0.204:0/14861 -- osd_ping(ping_reply e22127 stamp 2014-04-27 15:14:33.190958) v2 -- ?+0 0x7fd18f1d1500 con 0x7fd18e9d3440
--- logging levels ---
0/ 5 none
0/ 1 lockdep
0/ 1 context
1/ 1 crush
1/ 5 mds
1/ 5 mds_balancer
1/ 5 mds_locker
1/ 5 mds_log
1/ 5 mds_log_expire
1/ 5 mds_migrator
0/ 1 buffer
0/ 1 timer
0/ 1 filer
0/ 1 striper
0/ 1 objecter
0/ 5 rados
0/ 5 rbd
0/ 5 journaler
0/ 5 objectcacher
0/ 5 client
0/ 5 osd
0/ 5 optracker
0/ 5 objclass
1/ 3 filestore
1/ 3 keyvaluestore
1/ 3 journal
0/ 5 ms
1/ 5 mon
0/10 monc
1/ 5 paxos
0/ 5 tp
1/ 5 auth
1/ 5 crypto
1/ 1 finisher
1/ 5 heartbeatmap
1/ 5 perfcounter
1/ 5 rgw
1/ 5 javaclient
1/ 5 asok
1/ 1 throttle
-2/-2 (syslog threshold)
-1/-1 (stderr threshold)
max_recent 10000
max_new 1000
log_file /var/log/ceph/ceph-osd.9.log
--- end dump of recent events ---
From crash dump:
Core was generated by `/usr/bin/ceph-osd -i 9 --pid-file /var/run/ceph/osd.9.pid -c /etc/ceph/ceph.con'.
Program terminated with signal 6, Aborted.
#0 0x00007fd167ce23a9 in __GI_raise (sig=sig@entry=6) at ../nptl/sysdeps/unix/sysv/linux/raise.c:56
56 ../nptl/sysdeps/unix/sysv/linux/raise.c: No such file or directory.
(gdb) where
#0 0x00007fd167ce23a9 in __GI_raise (sig=sig@entry=6) at ../nptl/sysdeps/unix/sysv/linux/raise.c:56
#1 0x00007fd167ce54c8 in __GI_abort () at abort.c:89
#2 0x00007fd1685cf5e5 in __gnu_cxx::__verbose_terminate_handler() () from /usr/lib/x86_64-linux-gnu/libstdc++.so.6
#3 0x00007fd1685cd746 in ?? () from /usr/lib/x86_64-linux-gnu/libstdc++.so.6
#4 0x00007fd1685cd773 in std::terminate() () from /usr/lib/x86_64-linux-gnu/libstdc++.so.6
#5 0x00007fd1685cd9b2 in __cxa_throw () from /usr/lib/x86_64-linux-gnu/libstdc++.so.6
#6 0x00007fd16a799cf2 in ceph::__ceph_assert_fail (assertion=assertion@entry=0x7fd16a8aed68 "log.head >= olog.tail && olog.head >= log.tail",
file=file@entry=0x7fd16a8ae56a "osd/PGLog.cc", line=line@entry=512,
func=func@entry=0x7fd16a8af140 <PGLog::merge_log(ObjectStore::Transaction&, pg_info_t&, pg_log_t&, pg_shard_t, pg_info_t&, PGLog::LogEntryHandler*, bool&, bool&)::__PRETTY_FUNCTION__> "void PGLog::merge_log(ObjectStore::Transaction&, pg_info_t&, pg_log_t&, pg_shard_t, pg_info_t&, PGLog::LogEntryHandler*, bool&, bool&)") at common/assert.cc:77
#7 0x00007fd16a4dad30 in PGLog::merge_log (this=this@entry=0x7fd18868c818, t=..., oinfo=..., olog=..., fromosd=..., info=..., rollbacker=rollbacker@entry=0x7fd14ebde540,
dirty_info=@0x7fd18868c4a9: false, dirty_big_info=@0x7fd18868c4aa: false) at osd/PGLog.cc:512
#8 0x00007fd16a46035c in PG::merge_log (this=this@entry=0x7fd18868c000, t=..., oinfo=..., olog=..., from=...) at osd/PG.cc:370
#9 0x00007fd16a49a352 in PG::RecoveryState::Stray::react (this=this@entry=0x7fd16eb6c480, logevt=...) at osd/PG.cc:6584
#10 0x00007fd16a4ce594 in react<PG::RecoveryState::Stray, boost::statechart::event_base, void const*> (eventType=<synthetic pointer>, evt=..., stt=...)
at /usr/include/boost/statechart/custom_reaction.hpp:42
#11 local_react_impl<boost::mpl::list4<boost::statechart::custom_reaction<PG::MLogRec>, boost::statechart::custom_reaction<PG::MInfoRec>, boost::statechart::custom_reaction<PG::ActMap>, boost::statechart::custom_reaction<PG::RecoveryDone> >, boost::statechart::simple_state<PG::RecoveryState::Stray, PG::RecoveryState::Started, boost::mpl::list<mpl_::na, mpl_::na, mpl_::na, mpl_::na, mpl_::na, mpl_::na, mpl_::na, mpl_::na, mpl_::na, mpl_::na, mpl_::na, mpl_::na, mpl_::na, mpl_::na, mpl_::na, mpl_::na, mpl_::na, mpl_::na, mpl_::na, mpl_::na>, (boost::statechart::history_mode)0> > (eventType=0x7fd16ac3a790 <boost::statechart::detail::id_holder<PG::MLogRec>::idProvider_>, evt=..., stt=...)
at /usr/include/boost/statechart/simple_state.hpp:816
#12 local_react<boost::mpl::list4<boost::statechart::custom_reaction<PG::MLogRec>, boost::statechart::custom_reaction<PG::MInfoRec>, boost::statechart::custom_reaction<PG::ActMap>, boost::statechart::custom_reaction<PG::RecoveryDone> > > (eventType=0x7fd16ac3a790 <boost::statechart::detail::id_holder<PG::MLogRec>::idProvider_>, evt=..., this=0x7fd16eb6c480)
at /usr/include/boost/statechart/simple_state.hpp:851
#13 local_react_impl<boost::mpl::list<boost::statechart::custom_reaction<PG::MQuery>, boost::statechart::custom_reaction<PG::MLogRec>, boost::statechart::custom_reaction<PG::MInfoRec>, boost::statechart::custom_reaction<PG::ActMap>, boost::statechart::custom_reaction<PG::RecoveryDone> >, boost::statechart::simple_state<PG::RecoveryState::Stray, PG::RecoveryState::Started, boost::mpl::list<mpl_::na, mpl_::na, mpl_::na, mpl_::na, mpl_::na, mpl_::na, mpl_::na, mpl_::na, mpl_::na, mpl_::na, mpl_::na, mpl_::na, mpl_::na, mpl_::na, mpl_::na, mpl_::na, mpl_::na, mpl_::na, mpl_::na, mpl_::na>, (boost::statechart::history_mode)0> > (eventType=0x7fd16ac3a790 <boost::statechart::detail::id_holder<PG::MLogRec>::idProvider_>, evt=...,
stt=...) at /usr/include/boost/statechart/simple_state.hpp:820
#14 local_react<boost::mpl::list<boost::statechart::custom_reaction<PG::MQuery>, boost::statechart::custom_reaction<PG::MLogRec>, boost::statechart::custom_reaction<PG::MInfoRec>, boost::statechart::custom_reaction<PG::ActMap>, boost::statechart::custom_reaction<PG::RecoveryDone> > > (
eventType=0x7fd16ac3a790 <boost::statechart::detail::id_holder<PG::MLogRec>::idProvider_>, evt=..., this=0x7fd16eb6c480) at /usr/include/boost/statechart/simple_state.hpp:851
#15 boost::statechart::simple_state<PG::RecoveryState::Stray, PG::RecoveryState::Started, boost::mpl::list<mpl_::na, mpl_::na, mpl_::na, mpl_::na, mpl_::na, mpl_::na, mpl_::na, mpl_::na, mpl_::na, mpl_::na, mpl_::na, mpl_::na, mpl_::na, mpl_::na, mpl_::na, mpl_::na, mpl_::na, mpl_::na, mpl_::na, mpl_::na>, (boost::statechart::history_mode)0>::react_impl (
this=0x7fd16eb6c480, evt=..., eventType=0x7fd16ac3a790 <boost::statechart::detail::id_holder<PG::MLogRec>::idProvider_>) at /usr/include/boost/statechart/simple_state.hpp:489
#16 0x00007fd16a4bb87b in operator() (this=<synthetic pointer>) at /usr/include/boost/statechart/state_machine.hpp:87
#17 operator()<boost::statechart::detail::send_function<boost::statechart::detail::state_base<std::allocator<void>, boost::statechart::detail::rtti_policy>, boost::statechart::event_base, void const*>, boost::statechart::state_machine<PG::RecoveryState::RecoveryMachine, PG::RecoveryState::Initial>::exception_event_handler> (this=0x7fd18868d988, action=...)
at /usr/include/boost/statechart/null_exception_translator.hpp:33
#18 boost::statechart::state_machine<PG::RecoveryState::RecoveryMachine, PG::RecoveryState::Initial, std::allocator<void>, boost::statechart::null_exception_translator>::send_event (
this=0x7fd18868d930, evt=...) at /usr/include/boost/statechart/state_machine.hpp:889
#19 0x00007fd16a46cbc0 in process_event (evt=..., this=0x7fd18868d930) at /usr/include/boost/statechart/state_machine.hpp:275
#20 handle_event (rctx=0x7fd14ebdea60, evt=..., this=0x7fd18868d930) at osd/PG.h:1864
#21 PG::handle_peering_event (this=this@entry=0x7fd18868c000, evt=..., rctx=rctx@entry=0x7fd14ebdea60) at osd/PG.cc:5152
#22 0x00007fd16a38d7dc in OSD::process_peering_events (this=0x7fd16d599000, pgs=..., handle=...) at osd/OSD.cc:7722
#23 0x00007fd16a3d4a78 in OSD::PeeringWQ::_process (this=<optimized out>, pgs=..., handle=...) at osd/OSD.h:1199
#24 0x00007fd16a78abb1 in ThreadPool::worker (this=0x7fd16d599470, wt=0x7fd175ddf620) at common/WorkQueue.cc:125
#25 0x00007fd16a78baa0 in ThreadPool::WorkThread::entry (this=<optimized out>) at common/WorkQueue.h:317
#26 0x00007fd16986a062 in start_thread (arg=0x7fd14ebdf700) at pthread_create.c:312
#27 0x00007fd167d92a3d in clone () at ../sysdeps/unix/sysv/linux/x86_64/clone.S:111
Files
Actions