Ceph » RADOS

Hi, we got the crash because of the same reason in Ceph 0.94.5

I think it is possible that objiter->second->version == last_divergent_update?

Yao Ning wrote:

Hi, we got the crash because of the same reason in Ceph 0.94.5

I think it is possible that objiter->second->version == last_divergent_update?

Is there a way to stably reproduce this problem?

Detailed osd log about this pg and crash stack info can help us to find the reason.

hi, we got this error again,
we plug out the power cable when doing heavy writes,
after machine boot, one osd crashed.

here is the log filtered by thread address:

-785> 2016-12-21 22:16:14.382242 7fad437e8700 10 osd.11 pg_epoch: 255 pg[1.83( v 234'1033 (0'0,234'1033] local-les=226 n=822 ec=50 les/c/f 252/252/0 255/255/255) [11,6] r=0 lpr=255 pi=225-2
54/5 crt=234'1023 lcod 0'0 mlcod 0'0 peering] state<Started/Primary/Peering/GetLog>: GetLog: received master log from osd3
  -781> 2016-12-21 22:16:14.382261 7fad437e8700 10 osd.11 pg_epoch: 255 pg[1.83( v 234'1033 (0'0,234'1033] local-les=226 n=822 ec=50 les/c/f 252/252/0 255/255/255) [11,6] r=0 lpr=255 pi=225-2
54/5 crt=234'1023 lcod 0'0 mlcod 0'0 peering] state<Started/Primary/Peering/GetLog>: leaving GetLog
  -775> 2016-12-21 22:16:14.382275 7fad437e8700 10 osd.11 pg_epoch: 255 pg[1.83( v 234'1033 (0'0,234'1033] local-les=226 n=822 ec=50 les/c/f 252/252/0 255/255/255) [11,6] r=0 lpr=255 pi=225-2
54/5 crt=234'1023 lcod 0'0 mlcod 0'0 peering] state<Started/Primary/Peering/GetLog>: processing master log
  -771> 2016-12-21 22:16:14.382295 7fad437e8700 10 osd.11 pg_epoch: 255 pg[1.83( v 234'1033 (0'0,234'1033] local-les=226 n=822 ec=50 les/c/f 252/252/0 255/255/255) [11,6] r=0 lpr=255 pi=225-2
54/5 crt=234'1023 lcod 0'0 mlcod 0'0 peering] proc_master_log for osd.3: log((0'0,234'1034], crt=234'1034) missing(0)
  -768> 2016-12-21 22:16:14.382310 7fad437e8700 10 merge_log log((0'0,234'1034], crt=234'1034) from osd.3 into log((0'0,234'1033], crt=234'1023)
  -766> 2016-12-21 22:16:14.382317 7fad437e8700 10 merge_log extending head to 234'1034
  -758> 2016-12-21 22:16:14.382324 7fad437e8700 10 merge_log divergent 234'1034 (0'0) modify   7e99ba83/10000000c01.00000f67/head//1 by client.114220.1:12420 2016-12-21 18:54:28.173860
  -492> 2016-12-21 22:16:14.383148 7fad437e8700 10 _merge_object_divergent_entries: merging hoid 7e99ba83/10000000c01.00000f67/head//1 entries: 234'1034 (0'0) modify   7e99ba83/10000000c01.00
000f67/head//1 by client.114220.1:12420 2016-12-21 18:54:28.173860
  -488> 2016-12-21 22:16:14.383173 7fad437e8700 10 _merge_object_divergent_entries: hoid 7e99ba83/10000000c01.00000f67/head//1 prior_version: 0'0 first_divergent_update: 234'1034 last_diverge
nt_update: 234'1034
  -168> 2016-12-21 22:16:14.386491 7fad437e8700 -1 osd/PGLog.cc: In function 'static void PGLog::_merge_object_divergent_entries(const PGLog::IndexedLog&, const hobject_t&, const std::list<pg
_log_entry_t, std::allocator<pg_log_entry_t> >&, const pg_info_t&, eversion_t, pg_missing_t&, boost::optional<std::pair<eversion_t, hobject_t> >, PGLog::LogEntryHandler)' thread 7fad437e870
0 time 2016-12-21 22:16:14.383189

what i thought:
olog is (0'0,234'1034]
log is (0'0,234'1033]
divergent entry is 234'1034
so the lower_bound is 234'1033

In function _merge_object_divergent_entries()
there is only 1 entry to merge,
so the first_divergent_update equals to last_divergent_update,
in this case, entry "234'1034 (0'0) modify 7e99ba83/10000000c01.00000f67/head//1 by client.114220.1:12420 2016-12-21 18:54:28.173860"
has already merged, it Meet case 1) of "5 distinct cases".

so i think we can let is through by
/// Case 1)
- assert(objiter->second->version > last_divergent_update);
+ assert(objiter->second->version >= last_divergent_update);

it is a bit weird that the divergent entry is 234'1034
olog is (0'0,234'1034]
log is (0'0,234'1033]

so the lower_bound <= 234'1033

the divergent entry came from log, it should also <= 234'1033,
should never be 234'1034

am i right?

1. We got the same problem when the power of data center is shutdown(the electricity was cut off). There are two osds's log:

Apr 9 15:01:43 node10 ceph-osd: osd/PGLog.cc: In function 'static void PGLog::_merge_object_divergent_entries(const PGLog::IndexedLog&, const hobject_t&, const std::list<pg_log_entry_t>&,
const pg_info_t&, eversion_t, pg_missing_t&, boost::optional<std::pair<eversion_t, hobject_t> >, PGLog::LogEntryHandler, const DoutPrefixProvider*)' thread 7fdeb91bf700 time 2017-04-09 15
:01:43.360441
Apr 9 15:01:43 node10 ceph-osd: osd/PGLog.cc: 391: FAILED assert(objiter->second->version > last_divergent_update)
Apr 9 15:01:43 node10 ceph-osd: ceph version 10.2.2 (45107e21c568dd033c2f0a3107dec8f0b0e58374)
Apr 9 15:01:43 node10 ceph-osd: 1: (ceph::__ceph_assert_fail(char const*, char const*, int, char const*)+0x85) [0x7fded958fb95]
Apr 9 15:01:43 node10 ceph-osd: 2: (PGLog::_merge_object_divergent_entries(PGLog::IndexedLog const&, hobject_t const&, std::list<pg_log_entry_t, std::allocator<pg_log_entry_t> > const&, pg
info_t const&, eversion_t, pg_missing_t&, boost::optional<std::pair<eversion_t, hobject_t> >, PGLog::LogEntryHandler, DoutPrefixProvider const*)+0x20d4) [0x7fded9186ea4]
Apr 9 15:01:43 node10 ceph-osd: 3: (PGLog::_merge_divergent_entries(PGLog::IndexedLog const&, std::list<pg_log_entry_t, std::allocator<pg_log_entry_t> >&, pg_info_t const&, eversion_t, pg
missing_t&, std::map<eversion_t, hobject_t, std::less<eversion_t>, std::allocator<std::pair<eversion_t const, hobject_t> > >, PGLog::LogEntryHandler, DoutPrefixProvider const*)+0x20b) [0x
7fded918da6b]
Apr 9 15:01:43 node10 ceph-osd: 4: (PGLog::merge_log(ObjectStore::Transaction&, pg_info_t&, pg_log_t&, pg_shard_t, pg_info_t&, PGLog::LogEntryHandler*, bool&, bool&)+0xd8c) [0x7fded918b14c
]
Apr 9 15:01:43 node10 ceph-osd: 5: (PG::merge_log(ObjectStore::Transaction&, pg_info_t&, pg_log_t&, pg_shard_t)+0xbf) [0x7fded8fbd99f]
Apr 9 15:01:43 node10 ceph-osd: 6: (PG::RecoveryState::Stray::react(PG::MLogRec const&)+0x3d1) [0x7fded8fe87a1]
Apr 9 15:01:43 node10 ceph-osd: 7: (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*)+0x214) [0x7fded9025204]
Apr 9 15:01:43 node10 ceph-osd: 8: (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&)+0x6b) [0x7fded900e61b]
Apr 9 15:01:43 node10 ceph-osd: 9: (PG::handle_peering_event(std::shared_ptr<PG::CephPeeringEvt>, PG::RecoveryCtx*)+0x1f4) [0x7fded8fd58c4]
Apr 9 15:01:43 node10 ceph-osd: 10: (OSD::process_peering_events(std::list<PG*, std::allocator<PG*> > const&, ThreadPool::TPHandle&)+0x259) [0x7fded8f2ec19]
Apr 9 15:01:43 node10 ceph-osd: 11: (OSD::PeeringWQ::_process(std::list<PG*, std::allocator<PG*> > const&, ThreadPool::TPHandle&)+0x12) [0x7fded8f79372]
Apr 9 15:01:43 node10 ceph-osd: 12: (ThreadPool::worker(ThreadPool::WorkThread*)+0xa7e) [0x7fded9580a4e]
Apr 9 15:01:43 node10 ceph-osd: 13: (ThreadPool::WorkThread::entry()+0x10) [0x7fded9581930]
Apr 9 15:01:43 node10 ceph-osd: 14: (()+0x7df3) [0x7fded74a0df3]
Apr 9 15:01:43 node10 ceph-osd: 15: (clone()+0x6d) [0x7fded5b2d3dd]

2. And we also got a problem of XFS file system corruption,the log is:

Apr 10 10:05:17 node1 ceph-osd-prestart.sh: create-or-move updated item name 'osd.19' weight 0.0187 at location {host=node1,root=default} to crush map
Apr 10 10:05:17 node1 kernel: XFS (sdc1): xfs_log_force: error 5 returned.
Apr 10 10:05:17 node1 systemd: Started Ceph object storage daemon.
Apr 10 10:05:17 node1 ceph-osd: 2017-04-10 10:05:17.784412 7fc519049800 -1 ^{[[0;31m ** ERROR: unable to open OSD superblock on /var/lib/ceph/osd/ceph-19: (2) No such file or directory}[[0m
Apr 10 10:05:17 node1 systemd: ceph-osd@19.service: main process exited, code=exited, status=1/FAILURE
Apr 10 10:05:17 node1 systemd: Unit ceph-osd@19.service entered failed state.
Apr 10 10:05:17 node1 systemd: ceph-osd@19.service failed.
Apr 10 10:05:17 node1 kernel: XFS (sdc1): xfs_log_force: error 5 returned.
Apr 10 10:05:17 node1 kernel: XFS (sdc1): xfs_log_force: error 5 returned.

Is there someone can interpret this, or privide us some idea to resolve this problem ?

i have also met this problem when testing pull out disk and insert; ceph version 0.94.5,according @huang jun's osd log,I think the divergent log must not be 234'1034;

local log is (0'0, 234'1033], auth log is (0'0, 234'1034);
if the divergent is 234'1034,it means that log.log.rbegin and log.head are not pointing to the same address;

another doubt is that if divergent only has one node(first_divergent_update == last_divergent_update),and (objiter->second->version > last_divergent_update >= first_divergent_update), whether it means that objiter->second->version must not be equal to first_divergent_update or not?

same problem: http://tracker.ceph.com/issues/21174