Actions
Bug #8894
closedosd/ReplicatedPG.cc: 9281: FAILED assert(object_contexts.empty())
% Done:
0%
Source:
Q/A
Tags:
Backport:
Regression:
Severity:
3 - minor
Reviewed:
Affected Versions:
ceph-qa-suite:
Pull request ID:
Crash signature (v1):
Crash signature (v2):
Description
ubuntu@teuthology:/var/lib/teuthworker/archive/teuthology-2014-07-20_02:30:01-rados-next-testing-basic-plana/371110
-325> 2014-07-20 10:44:14.304770 7f33bbd8a700 -1 osd/ReplicatedPG.cc: In function 'virtual void ReplicatedPG::on_flushed()' thread 7f33bbd8a700 time 2014-07-20 10:44:14.300516 osd/ReplicatedPG.cc: 9281: FAILED assert(object_contexts.empty()) ceph version 0.82-391-g4a63396 (4a63396ba1611ed36cccc8c6d0f5e6e3e13d83ee) 1: (ReplicatedPG::on_flushed()+0x24e) [0x7cbd4e] 2: (PG::RecoveryState::Started::react(PG::FlushedEvt const&)+0x22) [0x74da12] 3: (boost::statechart::detail::reaction_result boost::statechart::simple_state<PG::RecoveryState::Started, PG::RecoveryState::RecoveryMachine, PG::RecoveryState::Start, (boost::statechart::history_mode)0>::local_react_impl_non_empty::local_react_impl<boost::mpl::list2<boost::statechart::custom_reaction<PG::Flushed Evt>, boost::statechart::transition<boost::statechart::event_base, PG::RecoveryState::Crashed, boost::statechart::detail::no_context<boost::statechart::event_base>, &(boost::statechart::detail::no_context<boost::statechart::event_base>::no_function(boost::statechart::event_base const&))> >, boost::statechart::simpl e_state<PG::RecoveryState::Started, PG::RecoveryState::RecoveryMachine, PG::RecoveryState::Start, (boost::statechart::history_mode)0> >(boost::statechart::simple_state<PG::RecoveryState::Started, PG::RecoveryState::RecoveryMachine, PG::RecoveryState::Start, (boost::statechart::history_mode)0>&, boost::statechart::e vent_base const&, void const*)+0x110) [0x7b03c0] 4: (boost::statechart::simple_state<PG::RecoveryState::Started, PG::RecoveryState::RecoveryMachine, PG::RecoveryState::Start, (boost::statechart::history_mode)0>::react_impl(boost::statechart::event_base const&, void const*)+0xc0) [0x7b04d0] 5: (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*)+0xf9) [0x7b0149] 6: (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) [0x7959eb] 7: (boost::statechart::state_machine<PG::RecoveryState::RecoveryMachine, PG::RecoveryState::Initial, std::allocator<void>, boost::statechart::null_exception_translator>::process_event(boost::statechart::event_base const&)+0x11) [0x795d41] 8: (PG::handle_peering_event(std::tr1::shared_ptr<PG::CephPeeringEvt>, PG::RecoveryCtx*)+0x303) [0x74dfb3] 9: (OSD::process_peering_events(std::list<PG*, std::allocator<PG*> > const&, ThreadPool::TPHandle&)+0x2ce) [0x66077e] 10: (OSD::PeeringWQ::_process(std::list<PG*, std::allocator<PG*> > const&, ThreadPool::TPHandle&)+0x12) [0x6b3332] 11: (ThreadPool::worker(ThreadPool::WorkThread*)+0x4e6) [0xa731d6] 12: (ThreadPool::WorkThread::entry()+0x10) [0xa76280] 13: (()+0x7e9a) [0x7f33d3636e9a] 14: (clone()+0x6d) [0x7f33d1bf73fd] NOTE: a copy of the executable, or `objdump -rdS <executable>` is needed to interpret this.
Updated by Sage Weil over 9 years ago
- Status changed from New to In Progress
- Assignee set to Sage Weil
Updated by Sage Weil over 9 years ago
- Status changed from In Progress to 12
- Assignee deleted (
Sage Weil)
2014-07-20 10:44:13.430353 7f33bad88700 10 osd.4 pg_epoch: 105 pg[4.0( v 105'6302 (35'2152,105'6302] local-les=103 n=1258 ec=8 les/c 103/103 102/102/102) [4] r=0 lpr=102 luod=93'6301 crt=88'6179 lcod 93'6300 mlcod 0'0 active+degraded] do_op osd_op(client.4141.0:22089 plana3530287-5257 [write 778766~535437] 4.54573e 8c RETRY=1 ack+ondisk+retry+write+known_if_redirected e104) v4 may_write -> write-ordered flags ack+ondisk+retry+write+known_if_redirected 2014-07-20 10:44:13.430602 7f33bad88700 10 osd.4 pg_epoch: 105 pg[4.0( v 105'6302 (35'2152,105'6302] local-les=103 n=1258 ec=8 les/c 103/103 102/102/102) [4] r=0 lpr=102 luod=93'6301 crt=88'6179 lcod 93'6300 mlcod 0'0 active+degraded] get_object_context: no obc for soid 54573e8c/plana3530287-5257/head//4 but can_cr eate 2014-07-20 10:44:13.430894 7f33bad88700 10 osd.4 pg_epoch: 105 pg[4.0( v 105'6302 (35'2152,105'6302] local-les=103 n=1258 ec=8 les/c 103/103 102/102/102) [4] r=0 lpr=102 luod=93'6301 crt=88'6179 lcod 93'6300 mlcod 0'0 active+degraded] create_object_context 0x414d340 54573e8c/plana3530287-5257/head//4 2014-07-20 10:44:13.430918 7f33bad88700 10 osd.4 pg_epoch: 105 pg[4.0( v 105'6302 (35'2152,105'6302] local-les=103 n=1258 ec=8 les/c 103/103 102/102/102) [4] r=0 lpr=102 luod=93'6301 crt=88'6179 lcod 93'6300 mlcod 0'0 active+degraded] populate_obc_watchers 54573e8c/plana3530287-5257/head//4 2014-07-20 10:44:13.430938 7f33bad88700 20 osd.4 pg_epoch: 105 pg[4.0( v 105'6302 (35'2152,105'6302] local-les=103 n=1258 ec=8 les/c 103/103 102/102/102) [4] r=0 lpr=102 luod=93'6301 crt=88'6179 lcod 93'6300 mlcod 0'0 active+degraded] ReplicatedPG::check_blacklisted_obc_watchers for obc 54573e8c/plana3530287-5257/h ead//4 2014-07-20 10:44:13.430958 7f33bad88700 10 osd.4 pg_epoch: 105 pg[4.0( v 105'6302 (35'2152,105'6302] local-les=103 n=1258 ec=8 les/c 103/103 102/102/102) [4] r=0 lpr=102 luod=93'6301 crt=88'6179 lcod 93'6300 mlcod 0'0 active+degraded] get_object_context: 0x414d340 54573e8c/plana3530287-5257/head//4 rwstate(none n=0 w=0) oi: 54573e8c/plana3530287-5257/head//4(0'0 unknown.0.0:0 wrlock_by=unknown.0.0:0 s 0 uv0) ssc: 0x1df79a0 snapset: 0=[]:[] 2014-07-20 10:44:13.430987 7f33bad88700 10 osd.4 pg_epoch: 105 pg[4.0( v 105'6302 (35'2152,105'6302] local-les=103 n=1258 ec=8 les/c 103/103 102/102/102) [4] r=0 lpr=102 luod=93'6301 crt=88'6179 lcod 93'6300 mlcod 0'0 active+degraded] find_object_context 54573e8c/plana3530287-5257/head//4 @head oi=54573e8c/plana353 0287-5257/head//4(0'0 unknown.0.0:0 wrlock_by=unknown.0.0:0 s 0 uv0) 2014-07-20 10:44:13.431014 7f33bad88700 10 osd.4 pg_epoch: 105 pg[4.0( v 105'6302 (35'2152,105'6302] local-les=103 n=1258 ec=8 les/c 103/103 102/102/102) [4] r=0 lpr=102 luod=93'6301 crt=88'6179 lcod 93'6300 mlcod 0'0 active+degraded] agent_choose_mode: num_objects: 1258 num_bytes: 2522129843 num_objects_dirty: 81 8 num_objects_omap: 0 num_dirty: 818 num_user_objects: 1250 pool.info.target_max_bytes: 0 pool.info.target_max_objects: 5000 2014-07-20 10:44:13.431036 7f33bad88700 20 osd.4 pg_epoch: 105 pg[4.0( v 105'6302 (35'2152,105'6302] local-les=103 n=1258 ec=8 les/c 103/103 102/102/102) [4] r=0 lpr=102 luod=93'6301 crt=88'6179 lcod 93'6300 mlcod 0'0 active+degraded] agent_choose_mode dirty 0.6544 full 1 2014-07-20 10:44:13.431064 7f33bad88700 10 osd.4 pg_epoch: 105 pg[4.0( v 105'6302 (35'2152,105'6302] local-les=103 n=1258 ec=8 les/c 103/103 102/102/102) [4] r=0 lpr=102 luod=93'6301 crt=88'6179 lcod 93'6300 mlcod 0'0 active+degraded] promote_object 54573e8c/plana3530287-5257/head//4 2014-07-20 10:44:13.431087 7f33bad88700 10 osd.4 pg_epoch: 105 pg[4.0( v 105'6302 (35'2152,105'6302] local-les=103 n=1258 ec=8 les/c 103/103 102/102/102) [4] r=0 lpr=102 luod=93'6301 crt=88'6179 lcod 93'6300 mlcod 0'0 active+degraded] start_copy 54573e8c/plana3530287-5257/head//4 from 54573e8c/plana3530287-5257/hea d//4 @3 v0 flags 14 mirror_snapset 2014-07-20 10:44:13.431117 7f33bad88700 10 osd.4 pg_epoch: 105 pg[4.0( v 105'6302 (35'2152,105'6302] local-les=103 n=1258 ec=8 les/c 103/103 102/102/102) [4] r=0 lpr=102 luod=93'6301 crt=88'6179 lcod 93'6300 mlcod 0'0 active+degraded] _copy_some 0x414d340 0x3a808c0 2014-07-20 10:44:13.431290 7f33bad88700 10 osd.4 pg_epoch: 105 pg[4.0( v 105'6302 (35'2152,105'6302] local-les=103 n=1258 ec=8 les/c 103/103 102/102/102) [4] r=0 lpr=102 luod=93'6301 crt=88'6179 lcod 93'6300 mlcod 0'0 active+degraded] wait_for_blocked_object 54573e8c/plana3530287-5257/head//4 0x2615300 2014-07-20 10:44:13.431361 7f33bad88700 10 osd.4 105 dequeue_op 0x2615600 prio 63 cost 543266 latency 1.304039 osd_op(client.4141.0:22090 plana3530287-5257 [write 1872378~543266] 4.54573e8c RETRY=1 ack+ondisk+retry+write+known_if_redirected e104) v4 pg pg[4.0( v 105'6302 (35'2152,105'6302] local-les=103 n=1258 ec=8 les/c 103/103 102/102/102) [4] r=0 lpr=102 luod=93'6301 crt=88'6179 lcod 93'6300 mlcod 0'0 active+degraded] 2014-07-20 10:44:13.431407 7f33bad88700 20 osd.4 pg_epoch: 105 pg[4.0( v 105'6302 (35'2152,105'6302] local-les=103 n=1258 ec=8 les/c 103/103 102/102/102) [4] r=0 lpr=102 luod=93'6301 crt=88'6179 lcod 93'6300 mlcod 0'0 active+degraded] op_has_sufficient_caps pool=4 (cache ) owner=0 need_read_cap=0 need_write_cap=1 n eed_class_read_cap=0 need_class_write_cap=0 -> yes 2014-07-20 10:44:13.431431 7f33bad88700 10 osd.4 pg_epoch: 105 pg[4.0( v 105'6302 (35'2152,105'6302] local-les=103 n=1258 ec=8 les/c 103/103 102/102/102) [4] r=0 lpr=102 luod=93'6301 crt=88'6179 lcod 93'6300 mlcod 0'0 active+degraded] handle_message: 0x2615600 2014-07-20 10:44:13.431452 7f33bad88700 10 osd.4 pg_epoch: 105 pg[4.0( v 105'6302 (35'2152,105'6302] local-les=103 n=1258 ec=8 les/c 103/103 102/102/102) [4] r=0 lpr=102 luod=93'6301 crt=88'6179 lcod 93'6300 mlcod 0'0 active+degraded] do_op osd_op(client.4141.0:22090 plana3530287-5257 [write 1872378~543266] 4.54573 e8c RETRY=1 ack+ondisk+retry+write+known_if_redirected e104) v4 may_write -> write-ordered flags ack+ondisk+retry+write+known_if_redirected 2014-07-20 10:44:13.431486 7f33bad88700 10 osd.4 pg_epoch: 105 pg[4.0( v 105'6302 (35'2152,105'6302] local-les=103 n=1258 ec=8 les/c 103/103 102/102/102) [4] r=0 lpr=102 luod=93'6301 crt=88'6179 lcod 93'6300 mlcod 0'0 active+degraded] wait_for_blocked_object 54573e8c/plana3530287-5257/head//4 0x2615600 2014-07-20 10:44:13.431544 7f33bad88700 10 osd.4 105 dequeue_op 0x2f77900 prio 63 cost 410741 latency 1.302237 osd_op(client.4141.0:22091 plana3530287-5257 [write 3154871~410741] 4.54573e8c RETRY=1 ack+ondisk+retry+write+known_if_redirected e104) v4 pg pg[4.0( v 105'6302 (35'2152,105'6302] local-les=103 n=1258 ec=8 les/c 103/103 102/102/102) [4] r=0 lpr=102 luod=93'6301 crt=88'6179 lcod 93'6300 mlcod 0'0 active+degraded] 2014-07-20 10:44:13.431589 7f33bad88700 20 osd.4 pg_epoch: 105 pg[4.0( v 105'6302 (35'2152,105'6302] local-les=103 n=1258 ec=8 les/c 103/103 102/102/102) [4] r=0 lpr=102 luod=93'6301 crt=88'6179 lcod 93'6300 mlcod 0'0 active+degraded] op_has_sufficient_caps pool=4 (cache ) owner=0 need_read_cap=0 need_write_cap=1 n eed_class_read_cap=0 need_class_write_cap=0 -> yes 2014-07-20 10:44:13.431613 7f33bad88700 10 osd.4 pg_epoch: 105 pg[4.0( v 105'6302 (35'2152,105'6302] local-les=103 n=1258 ec=8 les/c 103/103 102/102/102) [4] r=0 lpr=102 luod=93'6301 crt=88'6179 lcod 93'6300 mlcod 0'0 active+degraded] handle_message: 0x2f77900 2014-07-20 10:44:13.431633 7f33bad88700 10 osd.4 pg_epoch: 105 pg[4.0( v 105'6302 (35'2152,105'6302] local-les=103 n=1258 ec=8 les/c 103/103 102/102/102) [4] r=0 lpr=102 luod=93'6301 crt=88'6179 lcod 93'6300 mlcod 0'0 active+degraded] do_op osd_op(client.4141.0:22091 plana3530287-5257 [write 3154871~410741] 4.54573 e8c RETRY=1 ack+ondisk+retry+write+known_if_redirected e104) v4 may_write -> write-ordered flags ack+ondisk+retry+write+known_if_redirected 2014-07-20 10:44:13.431665 7f33bad88700 10 osd.4 pg_epoch: 105 pg[4.0( v 105'6302 (35'2152,105'6302] local-les=103 n=1258 ec=8 les/c 103/103 102/102/102) [4] r=0 lpr=102 luod=93'6301 crt=88'6179 lcod 93'6300 mlcod 0'0 active+degraded] wait_for_blocked_object 54573e8c/plana3530287-5257/head//4 0x2f77900 2014-07-20 10:44:13.431723 7f33bad88700 10 osd.4 105 dequeue_op 0x2f77f00 prio 63 cost 1 latency 1.301559 osd_op(client.4141.0:22092 plana3530287-5257 [write 3578765~1] 4.54573e8c RETRY=1 ack+ondisk+retry+write+known_if_redirected e104) v4 pg pg[4.0( v 105'6302 (35'2152,105'6302] local-les=103 n=1258 ec=8 les/c 103 /103 102/102/102) [4] r=0 lpr=102 luod=93'6301 crt=88'6179 lcod 93'6300 mlcod 0'0 active+degraded] 2014-07-20 10:44:13.431767 7f33bad88700 20 osd.4 pg_epoch: 105 pg[4.0( v 105'6302 (35'2152,105'6302] local-les=103 n=1258 ec=8 les/c 103/103 102/102/102) [4] r=0 lpr=102 luod=93'6301 crt=88'6179 lcod 93'6300 mlcod 0'0 active+degraded] op_has_sufficient_caps pool=4 (cache ) owner=0 need_read_cap=0 need_write_cap=1 n eed_class_read_cap=0 need_class_write_cap=0 -> yes 2014-07-20 10:44:13.431791 7f33bad88700 10 osd.4 pg_epoch: 105 pg[4.0( v 105'6302 (35'2152,105'6302] local-les=103 n=1258 ec=8 les/c 103/103 102/102/102) [4] r=0 lpr=102 luod=93'6301 crt=88'6179 lcod 93'6300 mlcod 0'0 active+degraded] handle_message: 0x2f77f00 2014-07-20 10:44:13.431811 7f33bad88700 10 osd.4 pg_epoch: 105 pg[4.0( v 105'6302 (35'2152,105'6302] local-les=103 n=1258 ec=8 les/c 103/103 102/102/102) [4] r=0 lpr=102 luod=93'6301 crt=88'6179 lcod 93'6300 mlcod 0'0 active+degraded] do_op osd_op(client.4141.0:22092 plana3530287-5257 [write 3578765~1] 4.54573e8c R ETRY=1 ack+ondisk+retry+write+known_if_redirected e104) v4 may_write -> write-ordered flags ack+ondisk+retry+write+known_if_redirected 2014-07-20 10:44:13.431843 7f33bad88700 10 osd.4 pg_epoch: 105 pg[4.0( v 105'6302 (35'2152,105'6302] local-les=103 n=1258 ec=8 les/c 103/103 102/102/102) [4] r=0 lpr=102 luod=93'6301 crt=88'6179 lcod 93'6300 mlcod 0'0 active+degraded] wait_for_blocked_object 54573e8c/plana3530287-5257/head//4 0x2f77f00 2014-07-20 10:44:13.431902 7f33bad88700 10 osd.4 105 dequeue_op 0x2f77000 prio 63 cost 63 latency 1.301557 osd_op(client.4141.0:22093 plana3530287-5257 [setxattr _header (56),truncate 3578766] 4.54573e8c RETRY=1 ack+ondisk+retry+write+known_if_redirected e104) v4 pg pg[4.0( v 105'6302 (35'2152,105'6302] local-les=1 03 n=1258 ec=8 les/c 103/103 102/102/102) [4] r=0 lpr=102 luod=93'6301 crt=88'6179 lcod 93'6300 mlcod 0'0 active+degraded] 2014-07-20 10:44:13.431952 7f33bad88700 20 osd.4 pg_epoch: 105 pg[4.0( v 105'6302 (35'2152,105'6302] local-les=103 n=1258 ec=8 les/c 103/103 102/102/102) [4] r=0 lpr=102 luod=93'6301 crt=88'6179 lcod 93'6300 mlcod 0'0 active+degraded] op_has_sufficient_caps pool=4 (cache ) owner=0 need_read_cap=0 need_write_cap=1 n eed_class_read_cap=0 need_class_write_cap=0 -> yes 2014-07-20 10:44:13.431975 7f33bad88700 10 osd.4 pg_epoch: 105 pg[4.0( v 105'6302 (35'2152,105'6302] local-les=103 n=1258 ec=8 les/c 103/103 102/102/102) [4] r=0 lpr=102 luod=93'6301 crt=88'6179 lcod 93'6300 mlcod 0'0 active+degraded] handle_message: 0x2f77000 2014-07-20 10:44:13.431995 7f33bad88700 10 osd.4 pg_epoch: 105 pg[4.0( v 105'6302 (35'2152,105'6302] local-les=103 n=1258 ec=8 les/c 103/103 102/102/102) [4] r=0 lpr=102 luod=93'6301 crt=88'6179 lcod 93'6300 mlcod 0'0 active+degraded] do_op osd_op(client.4141.0:22093 plana3530287-5257 [setxattr _header (56),truncat e 3578766] 4.54573e8c RETRY=1 ack+ondisk+retry+write+known_if_redirected e104) v4 may_write -> write-ordered flags ack+ondisk+retry+write+known_if_redirected 2014-07-20 10:44:13.432031 7f33bad88700 10 osd.4 pg_epoch: 105 pg[4.0( v 105'6302 (35'2152,105'6302] local-les=103 n=1258 ec=8 les/c 103/103 102/102/102) [4] r=0 lpr=102 luod=93'6301 crt=88'6179 lcod 93'6300 mlcod 0'0 active+degraded] wait_for_blocked_object 54573e8c/plana3530287-5257/head//4 0x2f77000 2014-07-20 10:44:13.432160 7f33bad88700 10 osd.4 105 dequeue_op 0x2f77800 prio 63 cost 0 latency 1.301628 osd_op(client.4141.0:22094 plana3530287-5257 [read 0~1] 4.54573e8c RETRY=1 ack+retry+read+rwordered+known_if_redirected e104) v4 pg pg[4.0( v 105'6302 (35'2152,105'6302] local-les=103 n=1258 ec=8 les/c 103/103 102/102/102) [4] r=0 lpr=102 luod=93'6301 crt=88'6179 lcod 93'6300 mlcod 0'0 active+degraded] 2014-07-20 10:44:13.432208 7f33bad88700 20 osd.4 pg_epoch: 105 pg[4.0( v 105'6302 (35'2152,105'6302] local-les=103 n=1258 ec=8 les/c 103/103 102/102/102) [4] r=0 lpr=102 luod=93'6301 crt=88'6179 lcod 93'6300 mlcod 0'0 active+degraded] op_has_sufficient_caps pool=4 (cache ) owner=0 need_read_cap=1 need_write_cap=0 n eed_class_read_cap=0 need_class_write_cap=0 -> yes 2014-07-20 10:44:13.432232 7f33bad88700 10 osd.4 pg_epoch: 105 pg[4.0( v 105'6302 (35'2152,105'6302] local-les=103 n=1258 ec=8 les/c 103/103 102/102/102) [4] r=0 lpr=102 luod=93'6301 crt=88'6179 lcod 93'6300 mlcod 0'0 active+degraded] handle_message: 0x2f77800 2014-07-20 10:44:13.432252 7f33bad88700 10 osd.4 pg_epoch: 105 pg[4.0( v 105'6302 (35'2152,105'6302] local-les=103 n=1258 ec=8 les/c 103/103 102/102/102) [4] r=0 lpr=102 luod=93'6301 crt=88'6179 lcod 93'6300 mlcod 0'0 active+degraded] do_op osd_op(client.4141.0:22094 plana3530287-5257 [read 0~1] 4.54573e8c RETRY=1 ack+retry+read+rwordered+known_if_redirected e104) v4 may_read -> write-ordered flags ack+retry+read+rwordered+known_if_redirected 2014-07-20 10:44:13.432285 7f33bad88700 10 osd.4 pg_epoch: 105 pg[4.0( v 105'6302 (35'2152,105'6302] local-les=103 n=1258 ec=8 les/c 103/103 102/102/102) [4] r=0 lpr=102 luod=93'6301 crt=88'6179 lcod 93'6300 mlcod 0'0 active+degraded] wait_for_blocked_object 54573e8c/plana3530287-5257/head//4 0x2f77800 2014-07-20 10:44:13.432341 7f33bad88700 10 osd.4 105 dequeue_op 0x2f77200 prio 63 cost 1 latency 0.085707 osd_op(client.4141.0:22101 plana3530287-5259 [write 535177~1] 4.b0dbd8ec ack+ondisk+write+known_if_redirected e105) v4 pg pg[4.0( v 105'6302 (35'2152,105'6302] local-les=103 n=1258 ec=8 les/c 103/103 102/102/10 2) [4] r=0 lpr=102 luod=93'6301 crt=88'6179 lcod 93'6300 mlcod 0'0 active+degraded] 2014-07-20 10:44:13.432388 7f33bad88700 20 osd.4 pg_epoch: 105 pg[4.0( v 105'6302 (35'2152,105'6302] local-les=103 n=1258 ec=8 les/c 103/103 102/102/102) [4] r=0 lpr=102 luod=93'6301 crt=88'6179 lcod 93'6300 mlcod 0'0 active+degraded] op_has_sufficient_caps pool=4 (cache ) owner=0 need_read_cap=0 need_write_cap=1 n eed_class_read_cap=0 need_class_write_cap=0 -> yes ... 2014-07-20 10:44:14.212623 7f33bb589700 10 osd.4 pg_epoch: 106 pg[4.0( v 105'6354 (35'2152,105'6354] local-les=103 n=1265 ec=8 les/c 103/103 102/102/102) [4,0]/[0,4] r=1 lpr=106 pi=102-105/1 luod=105'6309 crt=88'6179 lcod 105'6308 active+remapped] start_peering_interval: check_new_interval output: generate_past_int ervals interval(102-105 up [4](4) acting [4](4)): not rw, up_thru 104 up_from 3 last_epoch_clean 103 2014-07-20 10:44:14.212637 7f33bb589700 10 osd.4 pg_epoch: 106 pg[4.0( v 105'6354 (35'2152,105'6354] local-les=103 n=1265 ec=8 les/c 103/103 102/102/102) [4,0]/[0,4] r=1 lpr=106 pi=102-105/1 luod=105'6309 crt=88'6179 lcod 105'6308 active+remapped] noting past interval(102-105 up [4](4) acting [4](4) maybe_went_rw) 2014-07-20 10:44:14.212651 7f33bb589700 10 osd.4 pg_epoch: 106 pg[4.0( v 105'6354 (35'2152,105'6354] local-les=103 n=1265 ec=8 les/c 103/103 106/106/106) [4,0]/[0,4] r=1 lpr=106 pi=102-105/1 luod=105'6309 crt=88'6179 lcod 105'6308 active+remapped] up [4] -> [4,0], acting [4] -> [0,4], acting_primary 4 -> 0, up_pri mary 4 -> 4, role 0 -> 1 2014-07-20 10:44:14.212666 7f33bb589700 10 osd.4 pg_epoch: 106 pg[4.0( v 105'6354 (35'2152,105'6354] local-les=103 n=1265 ec=8 les/c 103/103 106/106/106) [4,0]/[0,4] r=1 lpr=106 pi=102-105/1 crt=88'6179 lcod 105'6308 remapped] clear_primary_state 2014-07-20 10:44:14.212681 7f33bb589700 20 osd.4 pg_epoch: 106 pg[4.0( v 105'6354 (35'2152,105'6354] local-les=103 n=1265 ec=8 les/c 103/103 106/106/106) [4,0]/[0,4] r=1 lpr=106 pi=102-105/1 crt=88'6179 lcod 105'6308 remapped] agent_stop 2014-07-20 10:44:14.212704 7f33bb589700 10 osd.4 pg_epoch: 106 pg[4.0( v 105'6354 (35'2152,105'6354] local-les=103 n=1265 ec=8 les/c 103/103 106/106/106) [4,0]/[0,4] r=1 lpr=106 pi=102-105/1 crt=88'6179 lcod 105'6308 remapped] on_change 2014-07-20 10:44:14.212718 7f33bb589700 15 osd.4 pg_epoch: 106 pg[4.0( v 105'6354 (35'2152,105'6354] local-les=103 n=1265 ec=8 les/c 103/103 106/106/106) [4,0]/[0,4] r=1 lpr=106 pi=102-105/1 crt=88'6179 lcod 105'6308 remapped] publish_stats_to_osd -- not primary 2014-07-20 10:44:14.212730 7f33bb589700 15 osd.4 pg_epoch: 106 pg[4.0( v 105'6354 (35'2152,105'6354] local-les=103 n=1265 ec=8 les/c 103/103 106/106/106) [4,0]/[0,4] r=1 lpr=106 pi=102-105/1 crt=88'6179 lcod 105'6308 remapped] requeue_ops 2014-07-20 10:44:14.212763 7f33bb589700 10 osd.4 pg_epoch: 106 pg[4.0( v 105'6354 (35'2152,105'6354] local-les=103 n=1265 ec=8 les/c 103/103 106/106/106) [4,0]/[0,4] r=1 lpr=106 pi=102-105/1 crt=88'6179 lcod 105'6308 remapped] cancel_copy_ops 2014-07-20 10:44:14.212780 7f33bb589700 10 osd.4 pg_epoch: 106 pg[4.0( v 105'6354 (35'2152,105'6354] local-les=103 n=1265 ec=8 les/c 103/103 106/106/106) [4,0]/[0,4] r=1 lpr=106 pi=102-105/1 crt=88'6179 lcod 105'6308 remapped] cancel_copy 54573e8c/plana3530287-5257/head//4 from 54573e8c/plana3530287-5257/head//4 @3 v0 2014-07-20 10:44:14.212808 7f33bb589700 10 osd.4 pg_epoch: 106 pg[4.0( v 105'6354 (35'2152,105'6354] local-les=103 n=1265 ec=8 les/c 103/103 106/106/106) [4,0]/[0,4] r=1 lpr=106 pi=102-105/1 crt=88'6179 lcod 105'6308 remapped] kick_object_context_blocked 54573e8c/plana3530287-5257/head//4 requeuing 6 requests 2014-07-20 10:44:14.212833 7f33bb589700 15 osd.4 pg_epoch: 106 pg[4.0( v 105'6354 (35'2152,105'6354] local-les=103 n=1265 ec=8 les/c 103/103 106/106/106) [4,0]/[0,4] r=1 lpr=106 pi=102-105/1 crt=88'6179 lcod 105'6308 remapped] requeue_ops 0x2615300,0x2615600,0x2f77900,0x2f77f00,0x2f77000,0x2f77800 2014-07-20 10:44:14.212905 7f33bb589700 10 osd.4 pg_epoch: 106 pg[4.0( v 105'6354 (35'2152,105'6354] local-les=103 n=1265 ec=8 les/c 103/103 106/106/106) [4,0]/[0,4] r=1 lpr=106 pi=102-105/1 crt=88'6179 lcod 105'6308 remapped] finish_promote 54573e8c/plana3530287-5257/head//4 r=-125 uv0 2014-07-20 10:44:14.212926 7f33bb589700 10 osd.4 pg_epoch: 106 pg[4.0( v 105'6354 (35'2152,105'6354] local-les=103 n=1265 ec=8 les/c 103/103 106/106/106) [4,0]/[0,4] r=1 lpr=106 pi=102-105/1 crt=88'6179 lcod 105'6308 remapped] cancel_copy b0dbd8ec/plana3530287-5259/head//4 from b0dbd8ec/plana3530287-5259/head//4 @3 v0 2014-07-20 10:44:14.212942 7f33bb589700 10 osd.4 pg_epoch: 106 pg[4.0( v 105'6354 (35'2152,105'6354] local-les=103 n=1265 ec=8 les/c 103/103 106/106/106) [4,0]/[0,4] r=1 lpr=106 pi=102-105/1 crt=88'6179 lcod 105'6308 remapped] kick_object_context_blocked b0dbd8ec/plana3530287-5259/head//4 requeuing 3 requests 2014-07-20 10:44:14.212956 7f33bb589700 15 osd.4 pg_epoch: 106 pg[4.0( v 105'6354 (35'2152,105'6354] local-les=103 n=1265 ec=8 les/c 103/103 106/106/106) [4,0]/[0,4] r=1 lpr=106 pi=102-105/1 crt=88'6179 lcod 105'6308 remapped] requeue_ops 0x2f77200,0x2f77a00,0x2f77b00 2014-07-20 10:44:14.212976 7f33bb589700 10 osd.4 pg_epoch: 106 pg[4.0( v 105'6354 (35'2152,105'6354] local-les=103 n=1265 ec=8 les/c 103/103 106/106/106) [4,0]/[0,4] r=1 lpr=106 pi=102-105/1 crt=88'6179 lcod 105'6308 remapped] finish_promote b0dbd8ec/plana3530287-5259/head//4 r=-125 uv0 2014-07-20 10:44:14.212989 7f33bb589700 10 osd.4 pg_epoch: 106 pg[4.0( v 105'6354 (35'2152,105'6354] local-les=103 n=1265 ec=8 les/c 103/103 106/106/106) [4,0]/[0,4] r=1 lpr=106 pi=102-105/1 crt=88'6179 lcod 105'6308 remapped] cancel_flush_ops ... 2014-07-20 10:44:14.300376 7f33c9ed4700 10 osd.4 pg_epoch: 106 pg[4.0( v 105'6354 (35'2152,105'6354] local-les=103 n=1265 ec=8 les/c 103/103 106/106/106) [4,0]/[0,4] r=1 lpr=106 pi=102-105/1 crt=88'6179 lcod 105'6308 remapped NOTIFY] flushed 2014-07-20 10:44:14.300437 7f33bbd8a700 10 osd.4 pg_epoch: 106 pg[4.0( v 105'6354 (35'2152,105'6354] local-les=103 n=1265 ec=8 les/c 103/103 106/106/106) [4,0]/[0,4] r=1 lpr=106 pi=102-105/1 crt=88'6179 lcod 105'6308 remapped NOTIFY] handle_peering_event: epoch_sent: 106 epoch_requested: 106 FlushedEvt 2014-07-20 10:44:14.300469 7f33bbd8a700 15 osd.4 pg_epoch: 106 pg[4.0( v 105'6354 (35'2152,105'6354] local-les=103 n=1265 ec=8 les/c 103/103 106/106/106) [4,0]/[0,4] r=1 lpr=106 pi=102-105/1 crt=88'6179 lcod 105'6308 remapped NOTIFY] requeue_ops 2014-07-20 10:44:14.300486 7f33bbd8a700 -1 osd.4 pg_epoch: 106 pg[4.0( v 105'6354 (35'2152,105'6354] local-les=103 n=1265 ec=8 les/c 103/103 106/106/106) [4,0]/[0,4] r=1 lpr=106 pi=102-105/1 crt=88'6179 lcod 105'6308 remapped NOTIFY] on_flushed: object 54573e8c/plana3530287-5257/head//4 obc still alive 2014-07-20 10:44:14.300501 7f33bbd8a700 -1 osd.4 pg_epoch: 106 pg[4.0( v 105'6354 (35'2152,105'6354] local-les=103 n=1265 ec=8 les/c 103/103 106/106/106) [4,0]/[0,4] r=1 lpr=106 pi=102-105/1 crt=88'6179 lcod 105'6308 remapped NOTIFY] on_flushed: object b0dbd8ec/plana3530287-5259/head//4 obc still alive
for comparison, here is a normal sequence on another osd. different role, but otherwise very similar:
2014-07-20 10:41:07.916805 7f1628dfd700 10 osd.5 pg_epoch: 55 pg[4.2( v 55'4726 (31'1344,55'4726] local-les=53 n=1008 ec=8 les/c 53/19 51/52/51) [5,4]/[5,1] r=0 lpr=52 pi=8-51/4 luod=55'4714 rops=1 bft=4 crt=0'0 lcod 55'4713 mlcod 55'4713 active+remapped+backfilling] do_op osd_op(client.4141.0:16696 plana3530287-39 72 [write 752618~730375] 4.7e211f32 ack+ondisk+write+known_if_redirected e55) v4 may_write -> write-ordered flags ack+ondisk+write+known_if_redirected 2014-07-20 10:41:07.916995 7f1628dfd700 10 osd.5 pg_epoch: 55 pg[4.2( v 55'4726 (31'1344,55'4726] local-les=53 n=1008 ec=8 les/c 53/19 51/52/51) [5,4]/[5,1] r=0 lpr=52 pi=8-51/4 luod=55'4714 rops=1 bft=4 crt=0'0 lcod 55'4713 mlcod 55'4713 active+remapped+backfilling] get_object_context: no obc for soid 7e211f32/pla na3530287-3972/head//4 but can_create 2014-07-20 10:41:07.917284 7f1628dfd700 10 osd.5 pg_epoch: 55 pg[4.2( v 55'4726 (31'1344,55'4726] local-les=53 n=1008 ec=8 les/c 53/19 51/52/51) [5,4]/[5,1] r=0 lpr=52 pi=8-51/4 luod=55'4714 rops=1 bft=4 crt=0'0 lcod 55'4713 mlcod 55'4713 active+remapped+backfilling] create_object_context 0x423c340 7e211f32/plana35 30287-3972/head//4 2014-07-20 10:41:07.917303 7f1628dfd700 10 osd.5 pg_epoch: 55 pg[4.2( v 55'4726 (31'1344,55'4726] local-les=53 n=1008 ec=8 les/c 53/19 51/52/51) [5,4]/[5,1] r=0 lpr=52 pi=8-51/4 luod=55'4714 rops=1 bft=4 crt=0'0 lcod 55'4713 mlcod 55'4713 active+remapped+backfilling] populate_obc_watchers 7e211f32/plana3530287-3972 /head//4 2014-07-20 10:41:07.917317 7f1628dfd700 20 osd.5 pg_epoch: 55 pg[4.2( v 55'4726 (31'1344,55'4726] local-les=53 n=1008 ec=8 les/c 53/19 51/52/51) [5,4]/[5,1] r=0 lpr=52 pi=8-51/4 luod=55'4714 rops=1 bft=4 crt=0'0 lcod 55'4713 mlcod 55'4713 active+remapped+backfilling] ReplicatedPG::check_blacklisted_obc_watchers for obc 7e211f32/plana3530287-3972/head//4 2014-07-20 10:41:07.917331 7f1628dfd700 10 osd.5 pg_epoch: 55 pg[4.2( v 55'4726 (31'1344,55'4726] local-les=53 n=1008 ec=8 les/c 53/19 51/52/51) [5,4]/[5,1] r=0 lpr=52 pi=8-51/4 luod=55'4714 rops=1 bft=4 crt=0'0 lcod 55'4713 mlcod 55'4713 active+remapped+backfilling] get_object_context: 0x423c340 7e211f32/plana3530 287-3972/head//4 rwstate(none n=0 w=0) oi: 7e211f32/plana3530287-3972/head//4(0'0 unknown.0.0:0 wrlock_by=unknown.0.0:0 s 0 uv0) ssc: 0x39d5380 snapset: 0=[]:[] 2014-07-20 10:41:07.917421 7f1628dfd700 10 osd.5 pg_epoch: 55 pg[4.2( v 55'4726 (31'1344,55'4726] local-les=53 n=1008 ec=8 les/c 53/19 51/52/51) [5,4]/[5,1] r=0 lpr=52 pi=8-51/4 luod=55'4714 rops=1 bft=4 crt=0'0 lcod 55'4713 mlcod 55'4713 active+remapped+backfilling] find_object_context 7e211f32/plana3530287-3972/h ead//4 @head oi=7e211f32/plana3530287-3972/head//4(0'0 unknown.0.0:0 wrlock_by=unknown.0.0:0 s 0 uv0) 2014-07-20 10:41:07.917457 7f1628dfd700 10 osd.5 pg_epoch: 55 pg[4.2( v 55'4726 (31'1344,55'4726] local-les=53 n=1008 ec=8 les/c 53/19 51/52/51) [5,4]/[5,1] r=0 lpr=52 pi=8-51/4 luod=55'4714 rops=1 bft=4 crt=0'0 lcod 55'4713 mlcod 55'4713 active+remapped+backfilling] agent_choose_mode: num_objects: 1008 num_bytes: 2026876972 num_objects_dirty: 519 num_objects_omap: 0 num_dirty: 519 num_user_objects: 1002 pool.info.target_max_bytes: 0 pool.info.target_max_objects: 5000 2014-07-20 10:41:07.917554 7f1628dfd700 20 osd.5 pg_epoch: 55 pg[4.2( v 55'4726 (31'1344,55'4726] local-les=53 n=1008 ec=8 les/c 53/19 51/52/51) [5,4]/[5,1] r=0 lpr=52 pi=8-51/4 luod=55'4714 rops=1 bft=4 crt=0'0 lcod 55'4713 mlcod 55'4713 active+remapped+backfilling] agent_choose_mode dirty 0.4152 full 0.8016 2014-07-20 10:41:07.917592 7f1628dfd700 10 osd.5 pg_epoch: 55 pg[4.2( v 55'4726 (31'1344,55'4726] local-les=53 n=1008 ec=8 les/c 53/19 51/52/51) [5,4]/[5,1] r=0 lpr=52 pi=8-51/4 luod=55'4714 rops=1 bft=4 crt=0'0 lcod 55'4713 mlcod 55'4713 active+remapped+backfilling] promote_object 7e211f32/plana3530287-3972/head// 4 2014-07-20 10:41:07.917622 7f1628dfd700 10 osd.5 pg_epoch: 55 pg[4.2( v 55'4726 (31'1344,55'4726] local-les=53 n=1008 ec=8 les/c 53/19 51/52/51) [5,4]/[5,1] r=0 lpr=52 pi=8-51/4 luod=55'4714 rops=1 bft=4 crt=0'0 lcod 55'4713 mlcod 55'4713 active+remapped+backfilling] start_copy 7e211f32/plana3530287-3972/head//4 fr om 7e211f32/plana3530287-3972/head//4 @3 v0 flags 14 mirror_snapset 2014-07-20 10:41:07.917641 7f1628dfd700 10 osd.5 pg_epoch: 55 pg[4.2( v 55'4726 (31'1344,55'4726] local-les=53 n=1008 ec=8 les/c 53/19 51/52/51) [5,4]/[5,1] r=0 lpr=52 pi=8-51/4 luod=55'4714 rops=1 bft=4 crt=0'0 lcod 55'4713 mlcod 55'4713 active+remapped+backfilling] _copy_some 0x423c340 0x423b580 2014-07-20 10:41:07.917776 7f1628dfd700 10 osd.5 pg_epoch: 55 pg[4.2( v 55'4726 (31'1344,55'4726] local-les=53 n=1008 ec=8 les/c 53/19 51/52/51) [5,4]/[5,1] r=0 lpr=52 pi=8-51/4 luod=55'4714 rops=1 bft=4 crt=0'0 lcod 55'4713 mlcod 55'4713 active+remapped+backfilling] wait_for_blocked_object 7e211f32/plana3530287-39 72/head//4 0x4203800 2014-07-20 10:41:07.917973 7f162b602700 10 osd.5 55 dequeue_op 0x4203e00 prio 63 cost 1 latency 0.001314 osd_op(client.4141.0:16697 plana3530287-3972 [write 1952617~1] 4.7e211f32 ack+ondisk+write+known_if_redirected e55) v4 pg pg[4.2( v 55'4726 (31'1344,55'4726] local-les=53 n=1008 ec=8 les/c 53/19 51/52/51) [5,4]/ [5,1] r=0 lpr=52 pi=8-51/4 luod=55'4714 rops=1 bft=4 crt=0'0 lcod 55'4713 mlcod 55'4713 active+remapped+backfilling] 2014-07-20 10:41:07.918031 7f162b602700 20 osd.5 pg_epoch: 55 pg[4.2( v 55'4726 (31'1344,55'4726] local-les=53 n=1008 ec=8 les/c 53/19 51/52/51) [5,4]/[5,1] r=0 lpr=52 pi=8-51/4 luod=55'4714 rops=1 bft=4 crt=0'0 lcod 55'4713 mlcod 55'4713 active+remapped+backfilling] op_has_sufficient_caps pool=4 (cache ) owner=0 n eed_read_cap=0 need_write_cap=1 need_class_read_cap=0 need_class_write_cap=0 -> yes 2014-07-20 10:41:07.918050 7f162b602700 10 osd.5 pg_epoch: 55 pg[4.2( v 55'4726 (31'1344,55'4726] local-les=53 n=1008 ec=8 les/c 53/19 51/52/51) [5,4]/[5,1] r=0 lpr=52 pi=8-51/4 luod=55'4714 rops=1 bft=4 crt=0'0 lcod 55'4713 mlcod 55'4713 active+remapped+backfilling] handle_message: 0x4203e00 2014-07-20 10:41:07.918064 7f162b602700 10 osd.5 pg_epoch: 55 pg[4.2( v 55'4726 (31'1344,55'4726] local-les=53 n=1008 ec=8 les/c 53/19 51/52/51) [5,4]/[5,1] r=0 lpr=52 pi=8-51/4 luod=55'4714 rops=1 bft=4 crt=0'0 lcod 55'4713 mlcod 55'4713 active+remapped+backfilling] do_op osd_op(client.4141.0:16697 plana3530287-39 72 [write 1952617~1] 4.7e211f32 ack+ondisk+write+known_if_redirected e55) v4 may_write -> write-ordered flags ack+ondisk+write+known_if_redirected 2014-07-20 10:41:07.918091 7f162b602700 10 osd.5 pg_epoch: 55 pg[4.2( v 55'4726 (31'1344,55'4726] local-les=53 n=1008 ec=8 les/c 53/19 51/52/51) [5,4]/[5,1] r=0 lpr=52 pi=8-51/4 luod=55'4714 rops=1 bft=4 crt=0'0 lcod 55'4713 mlcod 55'4713 active+remapped+backfilling] wait_for_blocked_object 7e211f32/plana3530287-39 72/head//4 0x4203e00 2014-07-20 10:41:07.918137 7f162b602700 10 osd.5 55 dequeue_op 0x4203a00 prio 63 cost 63 latency 0.001303 osd_op(client.4141.0:16698 plana3530287-3972 [setxattr _header (56),truncate 1952618] 4.7e211f32 ack+ondisk+write+known_if_redirected e55) v4 pg pg[4.2( v 55'4726 (31'1344,55'4726] local-les=53 n=1008 ec=8 les/ c 53/19 51/52/51) [5,4]/[5,1] r=0 lpr=52 pi=8-51/4 luod=55'4714 rops=1 bft=4 crt=0'0 lcod 55'4713 mlcod 55'4713 active+remapped+backfilling] 2014-07-20 10:41:07.918184 7f162b602700 20 osd.5 pg_epoch: 55 pg[4.2( v 55'4726 (31'1344,55'4726] local-les=53 n=1008 ec=8 les/c 53/19 51/52/51) [5,4]/[5,1] r=0 lpr=52 pi=8-51/4 luod=55'4714 rops=1 bft=4 crt=0'0 lcod 55'4713 mlcod 55'4713 active+remapped+backfilling] op_has_sufficient_caps pool=4 (cache ) owner=0 n eed_read_cap=0 need_write_cap=1 need_class_read_cap=0 need_class_write_cap=0 -> yes 2014-07-20 10:41:07.918201 7f162b602700 10 osd.5 pg_epoch: 55 pg[4.2( v 55'4726 (31'1344,55'4726] local-les=53 n=1008 ec=8 les/c 53/19 51/52/51) [5,4]/[5,1] r=0 lpr=52 pi=8-51/4 luod=55'4714 rops=1 bft=4 crt=0'0 lcod 55'4713 mlcod 55'4713 active+remapped+backfilling] handle_message: 0x4203a00 2014-07-20 10:41:07.918214 7f162b602700 10 osd.5 pg_epoch: 55 pg[4.2( v 55'4726 (31'1344,55'4726] local-les=53 n=1008 ec=8 les/c 53/19 51/52/51) [5,4]/[5,1] r=0 lpr=52 pi=8-51/4 luod=55'4714 rops=1 bft=4 crt=0'0 lcod 55'4713 mlcod 55'4713 active+remapped+backfilling] do_op osd_op(client.4141.0:16698 plana3530287-39 72 [setxattr _header (56),truncate 1952618] 4.7e211f32 ack+ondisk+write+known_if_redirected e55) v4 may_write -> write-ordered flags ack+ondisk+write+known_if_redirected 2014-07-20 10:41:07.918240 7f162b602700 10 osd.5 pg_epoch: 55 pg[4.2( v 55'4726 (31'1344,55'4726] local-les=53 n=1008 ec=8 les/c 53/19 51/52/51) [5,4]/[5,1] r=0 lpr=52 pi=8-51/4 luod=55'4714 rops=1 bft=4 crt=0'0 lcod 55'4713 mlcod 55'4713 active+remapped+backfilling] wait_for_blocked_object 7e211f32/plana3530287-39 72/head//4 0x4203a00 2014-07-20 10:41:07.918295 7f1628dfd700 10 osd.5 55 dequeue_op 0x4203000 prio 63 cost 0 latency 0.001246 osd_op(client.4141.0:16699 plana3530287-3972 [read 0~1] 4.7e211f32 ack+read+rwordered+known_if_redirected e55) v4 pg pg[4.2( v 55'4726 (31'1344,55'4726] local-les=53 n=1008 ec=8 les/c 53/19 51/52/51) [5,4]/[5,1] r=0 lpr=52 pi=8-51/4 luod=55'4714 rops=1 bft=4 crt=0'0 lcod 55'4713 mlcod 55'4713 active+remapped+backfilling] 2014-07-20 10:41:07.918384 7f1628dfd700 20 osd.5 pg_epoch: 55 pg[4.2( v 55'4726 (31'1344,55'4726] local-les=53 n=1008 ec=8 les/c 53/19 51/52/51) [5,4]/[5,1] r=0 lpr=52 pi=8-51/4 luod=55'4714 rops=1 bft=4 crt=0'0 lcod 55'4713 mlcod 55'4713 active+remapped+backfilling] op_has_sufficient_caps pool=4 (cache ) owner=0 n eed_read_cap=1 need_write_cap=0 need_class_read_cap=0 need_class_write_cap=0 -> yes 2014-07-20 10:41:07.918402 7f1628dfd700 10 osd.5 pg_epoch: 55 pg[4.2( v 55'4726 (31'1344,55'4726] local-les=53 n=1008 ec=8 les/c 53/19 51/52/51) [5,4]/[5,1] r=0 lpr=52 pi=8-51/4 luod=55'4714 rops=1 bft=4 crt=0'0 lcod 55'4713 mlcod 55'4713 active+remapped+backfilling] handle_message: 0x4203000 2014-07-20 10:41:07.918416 7f1628dfd700 10 osd.5 pg_epoch: 55 pg[4.2( v 55'4726 (31'1344,55'4726] local-les=53 n=1008 ec=8 les/c 53/19 51/52/51) [5,4]/[5,1] r=0 lpr=52 pi=8-51/4 luod=55'4714 rops=1 bft=4 crt=0'0 lcod 55'4713 mlcod 55'4713 active+remapped+backfilling] do_op osd_op(client.4141.0:16699 plana3530287-39 72 [read 0~1] 4.7e211f32 ack+read+rwordered+known_if_redirected e55) v4 may_read -> write-ordered flags ack+read+rwordered+known_if_redirected 2014-07-20 10:41:07.918459 7f1628dfd700 10 osd.5 pg_epoch: 55 pg[4.2( v 55'4726 (31'1344,55'4726] local-les=53 n=1008 ec=8 les/c 53/19 51/52/51) [5,4]/[5,1] r=0 lpr=52 pi=8-51/4 luod=55'4714 rops=1 bft=4 crt=0'0 lcod 55'4713 mlcod 55'4713 active+remapped+backfilling] wait_for_blocked_object 7e211f32/plana3530287-39 72/head//4 0x4203000 2014-07-20 10:41:07.918543 7f1624df5700 10 osd.5 pg_epoch: 55 pg[4.2( v 55'4726 (31'1344,55'4726] local-les=53 n=1008 ec=8 les/c 53/19 51/52/51) [5,4]/[5,1] r=0 lpr=52 pi=8-51/4 luod=55'4714 rops=1 bft=4 crt=0'0 lcod 55'4713 mlcod 55'4713 active+remapped+backfilling] process_copy_chunk eb134bf2/plana3530287-3966/he ad//4 tid 212 (2) No such file or directory 2014-07-20 10:41:07.918588 7f1624df5700 20 osd.5 pg_epoch: 55 pg[4.2( v 55'4726 (31'1344,55'4726] local-les=53 n=1008 ec=8 les/c 53/19 51/52/51) [5,4]/[5,1] r=0 lpr=52 pi=8-51/4 luod=55'4714 rops=1 bft=4 crt=0'0 lcod 55'4713 mlcod 55'4713 active+remapped+backfilling] process_copy_chunk complete r = (2) No such file or directory ... 2014-07-20 10:41:08.030130 7f162d606700 10 osd.5 pg_epoch: 56 pg[4.2( v 55'4734 (31'1344,55'4734] local-les=53 n=1010 ec=8 les/c 53/19 56/56/51) [4,0]/[5,1] r=0 lpr=56 pi=8-55/5 rops=1 bft=4 crt=0'0 lcod 55'4713 mlcod 55'4713 remapped] clear_primary_state 2014-07-20 10:41:08.030147 7f162d606700 20 osd.5 pg_epoch: 56 pg[4.2( v 55'4734 (31'1344,55'4734] local-les=53 n=1010 ec=8 les/c 53/19 56/56/51) [4,0]/[5,1] r=0 lpr=56 pi=8-55/5 rops=1 bft=4 crt=0'0 lcod 55'4713 mlcod 0'0 remapped] agent_stop 2014-07-20 10:41:08.030161 7f162d606700 10 osd.5 pg_epoch: 56 pg[4.2( v 55'4734 (31'1344,55'4734] local-les=53 n=1010 ec=8 les/c 53/19 56/56/51) [4,0]/[5,1] r=0 lpr=56 pi=8-55/5 rops=1 bft=4 crt=0'0 lcod 55'4713 mlcod 0'0 remapped] on_change 2014-07-20 10:41:08.030176 7f162d606700 15 osd.5 pg_epoch: 56 pg[4.2( v 55'4734 (31'1344,55'4734] local-les=53 n=1010 ec=8 les/c 53/19 56/56/51) [4,0]/[5,1] r=0 lpr=56 pi=8-55/5 rops=1 bft=4 crt=0'0 lcod 55'4713 mlcod 0'0 remapped] publish_stats_to_osd 56:4963 2014-07-20 10:41:08.030190 7f162d606700 15 osd.5 pg_epoch: 56 pg[4.2( v 55'4734 (31'1344,55'4734] local-les=53 n=1010 ec=8 les/c 53/19 56/56/51) [4,0]/[5,1] r=0 lpr=56 pi=8-55/5 rops=1 bft=4 crt=0'0 lcod 55'4713 mlcod 0'0 remapped] requeue_ops 2014-07-20 10:41:08.030217 7f162d606700 10 osd.5 pg_epoch: 56 pg[4.2( v 55'4734 (31'1344,55'4734] local-les=53 n=1010 ec=8 les/c 53/19 56/56/51) [4,0]/[5,1] r=0 lpr=56 pi=8-55/5 rops=1 bft=4 crt=0'0 lcod 55'4713 mlcod 0'0 remapped] cancel_copy_ops 2014-07-20 10:41:08.030230 7f162d606700 10 osd.5 pg_epoch: 56 pg[4.2( v 55'4734 (31'1344,55'4734] local-les=53 n=1010 ec=8 les/c 53/19 56/56/51) [4,0]/[5,1] r=0 lpr=56 pi=8-55/5 rops=1 bft=4 crt=0'0 lcod 55'4713 mlcod 0'0 remapped] cancel_copy 7e211f32/plana3530287-3972/head//4 from 7e211f32/plana3530287-3972/head//4 @3 v0 2014-07-20 10:41:08.030272 7f162d606700 10 osd.5 pg_epoch: 56 pg[4.2( v 55'4734 (31'1344,55'4734] local-les=53 n=1010 ec=8 les/c 53/19 56/56/51) [4,0]/[5,1] r=0 lpr=56 pi=8-55/5 rops=1 bft=4 crt=0'0 lcod 55'4713 mlcod 0'0 remapped] kick_object_context_blocked 7e211f32/plana3530287-3972/head//4 requeuing 4 requests 2014-07-20 10:41:08.030299 7f162d606700 15 osd.5 pg_epoch: 56 pg[4.2( v 55'4734 (31'1344,55'4734] local-les=53 n=1010 ec=8 les/c 53/19 56/56/51) [4,0]/[5,1] r=0 lpr=56 pi=8-55/5 rops=1 bft=4 crt=0'0 lcod 55'4713 mlcod 0'0 remapped] requeue_ops 0x4203800,0x4203e00,0x4203a00,0x4203000 2014-07-20 10:41:08.030389 7f162d606700 10 osd.5 pg_epoch: 56 pg[4.2( v 55'4734 (31'1344,55'4734] local-les=53 n=1010 ec=8 les/c 53/19 56/56/51) [4,0]/[5,1] r=0 lpr=56 pi=8-55/5 rops=1 bft=4 crt=0'0 lcod 55'4713 mlcod 0'0 remapped] finish_promote 7e211f32/plana3530287-3972/head//4 r=-125 uv0 2014-07-20 10:41:08.030432 7f162d606700 10 osd.5 pg_epoch: 56 pg[4.2( v 55'4734 (31'1344,55'4734] local-les=53 n=1010 ec=8 les/c 53/19 56/56/51) [4,0]/[5,1] r=0 lpr=56 pi=8-55/5 rops=1 bft=4 crt=0'0 lcod 55'4713 mlcod 0'0 remapped] cancel_copy 3c2fd6/plana3530287-3968/head//4 from 3c2fd6/plana3530287-3968/head//4 @3 v0 2014-07-20 10:41:08.030484 7f162d606700 10 osd.5 pg_epoch: 56 pg[4.2( v 55'4734 (31'1344,55'4734] local-les=53 n=1010 ec=8 les/c 53/19 56/56/51) [4,0]/[5,1] r=0 lpr=56 pi=8-55/5 rops=1 bft=4 crt=0'0 lcod 55'4713 mlcod 0'0 remapped] kick_object_context_blocked 3c2fd6/plana3530287-3968/head//4 requeuing 3 requests 2014-07-20 10:41:08.030515 7f162d606700 15 osd.5 pg_epoch: 56 pg[4.2( v 55'4734 (31'1344,55'4734] local-les=53 n=1010 ec=8 les/c 53/19 56/56/51) [4,0]/[5,1] r=0 lpr=56 pi=8-55/5 rops=1 bft=4 crt=0'0 lcod 55'4713 mlcod 0'0 remapped] requeue_ops 0x755ca00,0x755c800,0x755c500 2014-07-20 10:41:08.030554 7f162d606700 10 osd.5 pg_epoch: 56 pg[4.2( v 55'4734 (31'1344,55'4734] local-les=53 n=1010 ec=8 les/c 53/19 56/56/51) [4,0]/[5,1] r=0 lpr=56 pi=8-55/5 rops=1 bft=4 crt=0'0 lcod 55'4713 mlcod 0'0 remapped] finish_promote 3c2fd6/plana3530287-3968/head//4 r=-125 uv0 2014-07-20 10:41:08.030584 7f162d606700 10 osd.5 pg_epoch: 56 pg[4.2( v 55'4734 (31'1344,55'4734] local-les=53 n=1010 ec=8 les/c 53/19 56/56/51) [4,0]/[5,1] r=0 lpr=56 pi=8-55/5 rops=1 bft=4 crt=0'0 lcod 55'4713 mlcod 0'0 remapped] cancel_copy ffd4c6e6/plana3530287-3969/head//4 from ffd4c6e6/plana3530287-3969/head//4 @3 v0 2014-07-20 10:41:08.030631 7f162d606700 10 osd.5 pg_epoch: 56 pg[4.2( v 55'4734 (31'1344,55'4734] local-les=53 n=1010 ec=8 les/c 53/19 56/56/51) [4,0]/[5,1] r=0 lpr=56 pi=8-55/5 rops=1 bft=4 crt=0'0 lcod 55'4713 mlcod 0'0 remapped] kick_object_context_blocked ffd4c6e6/plana3530287-3969/head//4 requeuing 3 requests 2014-07-20 10:41:08.030662 7f162d606700 15 osd.5 pg_epoch: 56 pg[4.2( v 55'4734 (31'1344,55'4734] local-les=53 n=1010 ec=8 les/c 53/19 56/56/51) [4,0]/[5,1] r=0 lpr=56 pi=8-55/5 rops=1 bft=4 crt=0'0 lcod 55'4713 mlcod 0'0 remapped] requeue_ops 0x755cb00,0x4203500,0x4203900 2014-07-20 10:41:08.030701 7f162d606700 10 osd.5 pg_epoch: 56 pg[4.2( v 55'4734 (31'1344,55'4734] local-les=53 n=1010 ec=8 les/c 53/19 56/56/51) [4,0]/[5,1] r=0 lpr=56 pi=8-55/5 rops=1 bft=4 crt=0'0 lcod 55'4713 mlcod 0'0 remapped] finish_promote ffd4c6e6/plana3530287-3969/head//4 r=-125 uv0 2014-07-20 10:41:08.030729 7f162d606700 10 osd.5 pg_epoch: 56 pg[4.2( v 55'4734 (31'1344,55'4734] local-les=53 n=1010 ec=8 les/c 53/19 56/56/51) [4,0]/[5,1] r=0 lpr=56 pi=8-55/5 rops=1 bft=4 crt=0'0 lcod 55'4713 mlcod 0'0 remapped] cancel_flush_ops
Updated by Sage Weil over 9 years ago
ubuntu@teuthology:/var/lib/teuthworker/archive/sage-2014-08-08_22:30:19-rados-wip-sage-testing-testing-basic-burnupi/408063
Updated by Sage Weil over 9 years ago
ubuntu@teuthology:/var/lib/teuthworker/archive/sage-2014-08-09_14:13:44-rados-next-testing-basic-multi/410806
always seems to follow a cancel_copy ..
-971> 2014-08-10 06:17:59.800874 7ffa0ddfa700 10 osd.2 pg_epoch: 832 pg[2.1( v 831'5629 (306'2625,831'5629] local-les=796 n=54 ec=10 les/c 796/796 832/832/795) [2] r=0 lpr=832 pi=795-831/1 crt=830'5619 lcod 830'5619 mlcod 0'0 inactive] cancel_copy_ops -969> 2014-08-10 06:17:59.800882 7ffa0ddfa700 10 osd.2 pg_epoch: 832 pg[2.1( v 831'5629 (306'2625,831'5629] local-les=796 n=54 ec=10 les/c 796/796 832/832/795) [2] r=0 lpr=832 pi=795-831/1 crt=830'5619 lcod 830'5619 mlcod 0'0 inactive] cancel_copy 4b0b87d9/burnupi157049-47/head//2 from 19214a2a/burnupi157049-74/head//1 @1 v4566
Updated by Samuel Just over 9 years ago
I think it's the C_Copyfrom which we gave the objecter in _copy_some. It's got a CopyOpRef.
Updated by Samuel Just over 9 years ago
- Status changed from 7 to Pending Backport
Updated by Sage Weil over 9 years ago
- Status changed from Pending Backport to Resolved
Updated by Loïc Dachary over 9 years ago
- Status changed from Resolved to 12
- Backport set to giant
The fix was reverted by ea90d9f46b2716df6e10dccaed908fd235f2000c which is probably why it showed up again at http://pulpito.ceph.com/loic-2015-01-10_11:54:25-rados-giant-backports-testing-basic-vps/694155/ in remote/vpm095/log/ceph-osd.5.log.gz
-7> 2015-01-11 05:58:12.799993 7fe4f87b2700 20 osd.5 577 send_pg_stats
-6> 2015-01-11 05:58:12.799998 7fe4f87b2700 10 osd.5 577 send_pg_stats - 0 pgs updated
-5> 2015-01-11 05:58:12.800003 7fe4f87b2700 10 monclient: _send_mon_message to mon.a at 10.214.139.181:6789/0
-4> 2015-01-11 05:58:12.800017 7fe4f87b2700 1 -- 10.214.138.150:6810/5635 --> 10.214.139.181:6789/0 -- pg_stats(0 pgs tid 314 v 0) v1 -- ?+0 0x48e6dc0 con 0x81996e0
-3> 2015-01-11 05:58:12.800039 7fe4f87b2700 20 osd.5 577 scrub_random_backoff lost coin flip, randomly backing off
-2> 2015-01-11 05:58:12.800042 7fe4f87b2700 10 osd.5 577 do_waiters -- start
-1> 2015-01-11 05:58:12.800044 7fe4f87b2700 10 osd.5 577 do_waiters -- finish
0> 2015-01-11 05:58:12.817699 7fe4e7bcd700 -1 osd/ReplicatedPG.cc: In function 'virtual void ReplicatedPG::on_flushed()' thread 7fe4e7bcd700 time 2015-01-11 05:58:11.441341
osd/ReplicatedPG.cc: 9548: FAILED assert(object_contexts.empty())
ceph version 0.87-87-g0ea20e6 (0ea20e6c51208d6710f469454ab3f964bfa7c9d2)
1: (ceph::__ceph_assert_fail(char const*, char const*, int, char const*)+0x7f) [0xaa04bf]
2: (ReplicatedPG::on_flushed()+0x24e) [0x7cf03e]
3: (PG::RecoveryState::Started::react(PG::FlushedEvt const&)+0x22) [0x75d342]
4: (boost::statechart::detail::reaction_result boost::statechart::simple_state<PG::RecoveryState::Started, PG::RecoveryState::RecoveryMachine, PG::RecoveryState::Start, (boost::statechart::history_mode)0>::local_react_impl_non_empty::local_react_impl<boost::mpl::list5<boost::statechart::custom_reaction<PG::AdvMap>, boost::statechart::custom_reaction<PG::NullEvt>, boost::statechart::custom_reaction<PG::FlushedEvt>, boost::statechart::custom_reaction<PG::IntervalFlush>, boost::statechart::transition<boost::statechart::event_base, PG::RecoveryState::Crashed, boost::statechart::detail::no_context<boost::statechart::event_base>, &(boost::statechart::detail::no_context<boost::statechart::event_base>::no_function(boost::statechart::event_base const&))> >, boost::statechart::simple_state<PG::RecoveryState::Started, PG::RecoveryState::RecoveryMachine, PG::RecoveryState::Start, (boost::statechart::history_mode)0> >(boost::statechart::simple_state<PG::RecoveryState::Started, PG::RecoveryState::RecoveryMachine, PG::RecoveryState::Start, (boost::statechart::history_mode)0>&, boost::statechart::event_base const&, void const*)+0x147) [0x7c4217]
5: (boost::statechart::simple_state<PG::RecoveryState::Started, PG::RecoveryState::RecoveryMachine, PG::RecoveryState::Start, (boost::statechart::history_mode)0>::react_impl(boost::statechart::event_base const&, void const*)+0x52) [0x7c4292]
6: (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*)+0xf9
Actions