Bug #6685
closedosd/ReplicatedPG.cc: 8345: FAILED assert(0 == "erroneously present object")
0%
Description
0> 2013-10-30 01:25:16.471146 7eff572f7700 -1 osd/ReplicatedPG.cc: In function 'virtual void ReplicatedPG::check_local()' thread 7eff572f7700 time 2013-10-30 01:25:16.465970
osd/ReplicatedPG.cc: 8345: FAILED assert(0 == "erroneously present object")
ceph version 0.71-328-g1e2e429 (1e2e4297f8ed56ad83fb2083ae7e0ff4b86bdee1)
1: (ReplicatedPG::check_local()+0x4c6) [0x7eb3a6]
2: (PG::activate(ObjectStore::Transaction&, unsigned int, std::list<Context*, std::allocator<Context*> >&, std::map<int, std::map<pg_t, pg_query_t, std::less<pg_t>, std::allocator<std::pair<pg_t const, pg_query_t> > >, std::less<int>, std::allocator<std::pair<int const, std:
:map<pg_t, pg_query_t, std::less<pg_t>, std::allocator<std::pair<pg_t const, pg_query_t> > > > > >&, std::map<int, std::vector<std::pair<pg_notify_t, std::map<unsigned int, pg_interval_t, std::less<unsigned int>, std::allocator<std::pair<unsigned int const, pg_interval_t> > >
>, std::allocator<std::pair<pg_notify_t, std::map<unsigned int, pg_interval_t, std::less<unsigned int>, std::allocator<std::pair<unsigned int const, pg_interval_t> > > > > >, std::less<int>, std::allocator<std::pair<int const, std::vector<std::pair<pg_notify_t, std::map<unsi
gned int, pg_interval_t, std::less<unsigned int>, std::allocator<std::pair<unsigned int const, pg_interval_t> > > >, std::allocator<std::pair<pg_notify_t, std::map<unsigned int, pg_interval_t, std::less<unsigned int>, std::allocator<std::pair<unsigned int const, pg_interval_t
> > > > > > > > >*)+0x157) [0x796a87]
3: (PG::RecoveryState::Active::Active(boost::statechart::state<PG::RecoveryState::Active, PG::RecoveryState::Primary, PG::RecoveryState::Activating, (boost::statechart::history_mode)0>::my_context)+0x34f) [0x799fff]
4: (boost::statechart::state<PG::RecoveryState::Active, PG::RecoveryState::Primary, PG::RecoveryState::Activating, (boost::statechart::history_mode)0>::shallow_construct(boost::intrusive_ptr<PG::RecoveryState::Primary> const&, boost::statechart::state_machine<PG::RecoverySta
te::RecoveryMachine, PG::RecoveryState::Initial, std::allocator<void>, boost::statechart::null_exception_translator>&)+0x5c) [0x7ce64c]
5: (boost::statechart::detail::safe_reaction_result boost::statechart::simple_state<PG::RecoveryState::Peering, PG::RecoveryState::Primary, PG::RecoveryState::GetInfo, (boost::statechart::history_mode)0>::transit_impl<PG::RecoveryState::Active, PG::RecoveryState::RecoveryMac
hine, boost::statechart::detail::no_transition_function>(boost::statechart::detail::no_transition_function const&)+0x94) [0x7cf104]
6: (boost::statechart::simple_state<PG::RecoveryState::Peering, PG::RecoveryState::Primary, PG::RecoveryState::GetInfo, (boost::statechart::history_mode)0>::react_impl(boost::statechart::event_base const&, void const*)+0x192) [0x7cf3a2]
7: (boost::statechart::simple_state<PG::RecoveryState::WaitFlushedPeering, PG::RecoveryState::Peering, 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*)+0x90) [0x7c96f0]
8: (boost::statechart::state_machine<PG::RecoveryState::RecoveryMachine, PG::RecoveryState::Initial, std::allocator<void>, boost::statechart::null_exception_translator>::process_queued_events()+0xfb) [0x7af58b]
9: (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&)+0x1e) [0x7af70e]
10: (PG::handle_activate_map(PG::RecoveryCtx*)+0x103) [0x76b293]
11: (OSD::advance_pg(unsigned int, PG*, ThreadPool::TPHandle&, PG::RecoveryCtx*, std::set<boost::intrusive_ptr<PG>, std::less<boost::intrusive_ptr<PG> >, std::allocator<boost::intrusive_ptr<PG> > >*)+0x420) [0x621bd0]
12: (OSD::process_peering_events(std::list<PG*, std::allocator<PG*> > const&, ThreadPool::TPHandle&)+0x1d3) [0x621ef3]
13: (OSD::PeeringWQ::_process(std::list<PG*, std::allocator<PG*> > const&, ThreadPool::TPHandle&)+0x12) [0x669bb2]
14: (ThreadPool::worker(ThreadPool::WorkThread*)+0x4e6) [0x943796]
15: (ThreadPool::WorkThread::entry()+0x10) [0x9455a0]
16: (()+0x7e9a) [0x7eff6bb96e9a]
17: (clone()+0x6d) [0x7eff69f4fccd]
NOTE: a copy of the executable, or `objdump -rdS <executable>` is needed to interpret this.
ubuntu@teuthology:/var/lib/teuthworker/archive/teuthology-2013-10-29_23:00:22-rados-next-testing-basic-plana/75536
Files
Updated by Samuel Just over 10 years ago
Urgh, this is because we can advance last_backfill past uncompleted removal ops during backfill. Working on it.
Updated by Samuel Just over 10 years ago
- Status changed from New to In Progress
- Assignee set to Samuel Just
Updated by Samuel Just over 10 years ago
Or not, we process the OP_BACKFILL_PROGRESS ordered vs the removal ops.
Updated by Samuel Just over 10 years ago
It did happen immediately after transitioning from being the backfill target
Updated by Samuel Just over 10 years ago
ubuntu@teuthology:/a/teuthology-2013-11-01_23:00:05-rados-next-testing-basic-plana/80229/remote
Updated by Samuel Just over 10 years ago
Got it with logging, working on branch.
Updated by Greg Farnum over 10 years ago
commit:72e2874f402575846d1bd84f2af865d28947bc67 ("ReplicatedPG::recover_backfill: adjust last_backfill to HEAD if snapdir") looks good to me.
Updated by Tamilarasi muthamizhan over 10 years ago
- Status changed from Resolved to In Progress
- Assignee changed from Samuel Just to Sage Weil
log: ubuntu@teuthology:/a/teuthology-2013-12-04_23:00:01-rados-master-testing-basic-plana/130920
this seems to be happening in the nightlies on master branch
0> 2013-12-05 00:20:01.433548 7fc6c4eea700 -1 osd/ReplicatedPG.cc: In function 'virtual void ReplicatedPG::check_local()' thread 7fc6c4eea700 time 2013-12-05 00:20:01.428199
osd/ReplicatedPG.cc: 8409: FAILED assert(0 == "erroneously present object")
ceph version 0.72-390-g0dd7d29 (0dd7d2985af95716423ebebb417866f83c76b508)
1: (ReplicatedPG::check_local()+0x4c6) [0x7780f6]
2: (PG::activate(ObjectStore::Transaction&, unsigned int, std::list<Context*, std::allocator<Context*> >&, std::map<int, std::map<pg_t, pg_query_t, std::less<pg_t>, std::allocator<std::pair<pg_t const, pg
_query_t> > >, std::less<int>, std::allocator<std::pair<int const, std::map<pg_t, pg_query_t, std::less<pg_t>, std::allocator<std::pair<pg_t const, pg_query_t> > > > > >&, std::map<int, std::vector<std::pa
ir<pg_notify_t, std::map<unsigned int, pg_interval_t, std::less<unsigned int>, std::allocator<std::pair<unsigned int const, pg_interval_t> > > >, std::allocator<std::pair<pg_notify_t, std::map<unsigned int
, pg_interval_t, std::less<unsigned int>, std::allocator<std::pair<unsigned int const, pg_interval_t> > > > > >, std::less<int>, std::allocator<std::pair<int const, std::vector<std::pair<pg_notify_t, std::
map<unsigned int, pg_interval_t, std::less<unsigned int>, std::allocator<std::pair<unsigned int const, pg_interval_t> > > >, std::allocator<std::pair<pg_notify_t, std::map<unsigned int, pg_interval_t, std:
:less<unsigned int>, std::allocator<std::pair<unsigned int const, pg_interval_t> > > > > > > > >*)+0x157) [0x7233c7]
3: (PG::RecoveryState::Active::Active(boost::statechart::state<PG::RecoveryState::Active, PG::RecoveryState::Primary, PG::RecoveryState::Activating, (boost::statechart::history_mode)0>::my_context)+0x399)
[0x726849]
4: (boost::statechart::state<PG::RecoveryState::Active, PG::RecoveryState::Primary, PG::RecoveryState::Activating, (boost::statechart::history_mode)0>::shallow_construct(boost::intrusive_ptr<PG::RecoveryS
tate::Primary> const&, boost::statechart::state_machine<PG::RecoveryState::RecoveryMachine, PG::RecoveryState::Initial, std::allocator<void>, boost::statechart::null_exception_translator>&)+0x5c) [0x75b5ec
]
5: (boost::statechart::detail::safe_reaction_result boost::statechart::simple_state<PG::RecoveryState::Peering, PG::RecoveryState::Primary, PG::RecoveryState::GetInfo, (boost::statechart::history_mode)0>:
:transit_impl<PG::RecoveryState::Active, PG::RecoveryState::RecoveryMachine, boost::statechart::detail::no_transition_function>(boost::statechart::detail::no_transition_function const&)+0x94) [0x75c0a4]
6: (boost::statechart::simple_state<PG::RecoveryState::Peering, PG::RecoveryState::Primary, PG::RecoveryState::GetInfo, (boost::statechart::history_mode)0>::react_impl(boost::statechart::event_base const&
, void const*)+0x192) [0x75c342]
7: (boost::statechart::simple_state<PG::RecoveryState::WaitFlushedPeering, PG::RecoveryState::Peering, 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&, vo
id const*)+0x90) [0x756860]
8: (boost::statechart::state_machine<PG::RecoveryState::RecoveryMachine, PG::RecoveryState::Initial, std::allocator<void>, boost::statechart::null_exception_translator>::process_queued_events()+0xfb) [0x7
3c23b]
9: (boost::statechart::state_machine<PG::RecoveryState::RecoveryMachine, PG::RecoveryState::Initial, std::allocator<void>, boost::statechart::null_exception_translator>::process_event(boost::statechart::e
vent_base const&)+0x1e) [0x73c3be]
10: (PG::handle_activate_map(PG::RecoveryCtx*)+0x103) [0x6f7b03]
11: (OSD::advance_pg(unsigned int, PG*, ThreadPool::TPHandle&, PG::RecoveryCtx*, std::set<boost::intrusive_ptr<PG>, std::less<boost::intrusive_ptr<PG> >, std::allocator<boost::intrusive_ptr<PG> > >*)+0x42
0) [0x622c30]
12: (OSD::process_peering_events(std::list<PG*, std::allocator<PG*> > const&, ThreadPool::TPHandle&)+0x1d3) [0x622f53]
13: (OSD::PeeringWQ::_process(std::list<PG*, std::allocator<PG*> > const&, ThreadPool::TPHandle&)+0x12) [0x66a4b2]
14: (ThreadPool::worker(ThreadPool::WorkThread*)+0x4e6) [0x945906]
15: (ThreadPool::WorkThread::entry()+0x10) [0x947710]
16: (()+0x7e9a) [0x7fc6d9582e9a]
17: (clone()+0x6d) [0x7fc6d7b433fd]
NOTE: a copy of the executable, or `objdump -rdS <executable>` is needed to interpret this.
Updated by Sage Weil over 10 years ago
/a/teuthology-2013-12-07_23:00:19-rados-next-testing-basic-plana/135872
also possibly
ubuntu@teuthology:/a/teuthology-2013-12-07_23:00:19-rados-next-testing-basic-plana/135917
which got an ENOTEMPTY from the FileStore.. probably the same bug
Updated by Sage Weil over 10 years ago
- Assignee changed from Sage Weil to Samuel Just
Updated by Sage Weil over 10 years ago
ubuntu@teuthology:/a/teuthology-2013-12-19_23:00:07-rados-next-distro-basic-plana/9508
Updated by Sage Weil about 10 years ago
- File ceph-osd.1.log.gz ceph-osd.1.log.gz added
i got a complete log with osd=20 and filestore=20
Updated by Samuel Just about 10 years ago
- Assignee changed from Samuel Just to David Zafman
Updated by David Zafman about 10 years ago
- Status changed from In Progress to Fix Under Review
Updated by David Zafman about 10 years ago
- Status changed from Fix Under Review to In Progress
Updated by David Zafman about 10 years ago
As unsigned values CEPH_SNAPDIR (snapdir) > CEPH_NOSNAP (head). The code wants to collapse both into a single last_backfill_started value because there can never be a snapdir and a head at the same time. Since we are currently mapping snapdir to head, the test in is_degraded_object() for last_backfill_started is broken when the object being compared is snapdir.
So if there is a snapdir in flight and we are checking soid = CEPH_NOSNAP, but last_backfill_started == head, then last_backfill_started < slid so we don't even check backfills_in_flight() and return false when it should have returned true.
if (is_backfill_targets(peer) &&
peer_info[peer].last_backfill <= soid &&
last_backfill_started >= soid &&
backfills_in_flight.count(soid))
return true;The fix is to reverse the mapping and map head to snapdir.
Updated by David Zafman about 10 years ago
- Status changed from In Progress to 7
Updated by David Zafman about 10 years ago
- Status changed from 7 to In Progress
Updated by David Zafman about 10 years ago
The fix 545135f3e1c75318940caa2c82ac32a53fc4f957 went in because it was thought that a race was occurring between backfill and a snapdir/head change. A head change while last_backfill_started == head affects snapdir which violates the constraint of not sending operations to peers for objects past last_backfill_started (see should_send_op()).
The fix was itself causing problems because it was backing up last_back_started by setting to head for a snapdir object but head < snapdir. The in-flight snapdir push wasn't considered by a client op because of the is_degraded_object() check. It is supposed to be that any object past last_backfill_started can't be in the backfills_in_flight set.
It is assuming that the original crash seen Oct 29 has been fix because we have not been able to come up with a scenario that would cause it based on the current code. We will revert the previous fix because recover_backfill() can return with last_backfill_started == head for the following reasons. First, because update_range() will detect in the pg_log any client operation which might have affected snapdir. The snapdir is still part of the BackfillInterval remaining work because begin is set to the value of last_backfill_started. Second, a redundant snapdir removal or snapdir creation will silently succeed. A crash like that on snapdir has not been seen as far as I know. Finally, it is assumed that enough locking between client ops being sent to peers and recover_backfill() processing is present to prevent the previous 2 requirements from failing.
Updated by David Zafman about 10 years ago
- Status changed from In Progress to Resolved
a9677e136ee4753b86ed1151ca6ff08e4b63473d