Ceph

An update:

We were able to finish the rebalancing by setting:
osd pg max concurrent snap trims = 0

We also need noscrub and nodeeb-scrub flags to be set to avoid osd's to crash.

Really like some feedback or suggestions

So far the problem keeps persisting, so here is a small part of the log from an crashing osd...

2015-08-08 23:31:17.446134 7f4599edb780 0 filestore(/ceph/osd294) backend xfs (magic 0x58465342)
2015-08-08 23:31:17.449008 7f4599edb780 0 genericfilestorebackend(/ceph/osd294) detect_features: FIEMAP ioctl is supported and appears to work
2015-08-08 23:31:17.449017 7f4599edb780 0 genericfilestorebackend(/ceph/osd294) detect_features: FIEMAP ioctl is disabled via 'filestore fiemap' config option
2015-08-08 23:31:17.449162 7f4599edb780 0 genericfilestorebackend(/ceph/osd294) detect_features: syncfs(2) syscall not supported
2015-08-08 23:31:17.449169 7f4599edb780 0 genericfilestorebackend(/ceph/osd294) detect_features: no syncfs(2), must use sync(2).
2015-08-08 23:31:17.449172 7f4599edb780 0 genericfilestorebackend(/ceph/osd294) detect_features: WARNING: multiple ceph-osd daemons on the same host will be slow
2015-08-08 23:31:17.449238 7f4599edb780 0 xfsfilestorebackend(/ceph/osd294) detect_feature: extsize is supported and kernel 3.18.14 >= 3.5
2015-08-08 23:31:17.597437 7f4599edb780 0 filestore(/ceph/osd294) mount: enabling WRITEAHEAD journal mode: checkpoint is not enabled
2015-08-08 23:31:17.599591 7f4599edb780 1 journal FileJournal::_open: disabling aio for non-block journal. Use journal_force_aio to force use of aio anyway
2015-08-08 23:31:17.599593 7f4599edb780 1 journal _open /ceph/journals/osd294.journal fd 20: 10737418240 bytes, block size 4096 bytes, directio = 1, aio = 0
2015-08-08 23:31:18.966346 7f4599edb780 1 journal _open /ceph/journals/osd294.journal fd 19: 10737418240 bytes, block size 4096 bytes, directio = 1, aio = 0
2015-08-08 23:31:18.969114 7f4599edb780 0 <cls> cls/hello/cls_hello.cc:271: loading cls_hello
2015-08-08 23:31:18.971901 7f4599edb780 0 osd.294 131995 load_pgs
2015-08-08 23:31:23.370619 7f4599edb780 0 osd.294 131995 load_pgs opened 236 pgs
2015-08-08 23:31:23.371524 7f4599edb780 -1 osd.294 131995 log_to_monitors {default=true}
2015-08-08 23:31:23.385258 7f457fc2f700 0 osd.294 131995 ignoring osdmap until we have initialized
2015-08-08 23:31:23.388683 7f457fc2f700 0 osd.294 131995 ignoring osdmap until we have initialized
2015-08-08 23:31:23.430444 7f4599edb780 0 osd.294 131995 done with init, starting boot process
2015-08-08 23:31:23.628194 7f457741e700 -1 osd.294 131995 lsb_release_parse - pclose failed: (0) Success
2015-08-08 23:31:26.538498 7f458e06b700 0 - 192.168.252.126:6907/549 >> 192.168.252.175:0/4144533872 pipe(0x2843a000 sd=33 :6907 s=0 pgs=0 cs=0 l=0 c=0x289fe000).accept peer addr is really 192.168.252.175:0/4144533872 (socket is 192.168.252.175:40657/0)
2015-08-08 23:31:36.539982 7f454bf06700 0 -- 192.168.252.126:6907/549 >> 192.168.252.20:0/2174871064 pipe(0x1bb93500 sd=420 :6907 s=0 pgs=0 cs=0 l=0 c=0x281ab9a0).accept peer addr is really 192.168.252.20:0/2174871064 (socket is 192.168.252.20:58718/0)
2015-08-08 23:32:08.345959 7f4570410700 -1 osd/ReplicatedPG.cc: In function 'ReplicatedPG::RepGather* ReplicatedPG::trim_object(const hobject_t&)' thread 7f4570410700 time 2015-08-08 23:32:08.344485
osd/ReplicatedPG.cc: 2706: FAILED assert(p != snapset.clones.end())

ceph version 0.94.1 (e4bfad3a3c51054df7e537a724c8d0bf9be972ff)
 1: (ReplicatedPG::trim_object(hobject_t const&)+0x19aa) [0x86f42a]
 2: (ReplicatedPG::TrimmingObjects::react(ReplicatedPG::SnapTrim const&)+0x972) [0x876c92]
 3: (boost::statechart::simple_state<ReplicatedPG::TrimmingObjects, ReplicatedPG::SnapTrimmer, 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*)+0xa8) [0x8cd2d8]
 4: (boost::statechart::state_machine<ReplicatedPG::SnapTrimmer, ReplicatedPG::NotTrimming, std::allocator<void>, boost::statechart::null_exception_translator>::process_event(boost::statechart::event_base const&)+0x16b) [0x8bd02b]
 5: (ReplicatedPG::snap_trimmer()+0x4f0) [0x8348a0]
 6: (OSD::SnapTrimWQ::_process(PG*)+0x1d) [0x68330d]
 7: (ThreadPool::worker(ThreadPool::WorkThread*)+0x4fa) [0xb0acca]
 8: (ThreadPool::WorkThread::entry()+0x10) [0xb0c720]
 9: (()+0x68ca) [0x7f45994098ca]
 10: (clone()+0x6d) [0x7f4597adfb6d]
 NOTE: a copy of the executable, or `objdump -rdS <executable>` is needed to interpret this.

--- begin dump of recent events ---
10000> 2015-08-08 23:31:59.192474 7f4575c1b700 5 - op tracker -- seq: 4641, time: 2015-08-08 23:31:59.192474, event: done, op: pg_backfill(progress 9.82 e 132009/132009 lb cdc9ac82/default.1812767.6_ebab74e952455e327d9a45574339efbd.jpg/head//9)
9999> 2015-08-08 23:31:59.193402 7f45852ff700 1 - 172.31.0.126:6906/549 --> 172.31.0.37:6902/12529 -- pg_trim(9.82 to 130716'91608 e132009) v1 -- ?+0 0x28663c00 con 0x274e1dc0
9998> 2015-08-08 23:31:59.195139 7f4585b00700 1 - 172.31.0.126:6906/549 --> 172.31.0.37:6902/12529 -- MOSDPGPushReply(9.82 132009 [PushReplyOp(eb6aac82/default.2431383.1_f16b-1e97b6f11ffb117fdc2ef7081566d4cce2a4/head//9)]) v2 -- ?+0 0x2c8d6c00 con 0x274e1dc0
9997> 2015-08-08 23:31:59.198878 7f456569b700 1 - 172.31.0.126:6906/549 <== osd.224 172.31.0.171:6906/7829 639 ==== MOSDPGPush(9.1bb 132009 [PushOp(8d841dbb/default.1812767.3_sys-master/root/h1f/h15/8806611615774/bodyMedia-8799173253184/head//9, version: 90902'92220, data_included: [0~14252], data_size: 14252, omap_header_size: 0, omap_entries_size: 0, attrset_size: 9, recovery_info: ObjectRecoveryInfo(8d841dbb/default.1812767.3_sys-master/root/h1f/h15/8806611615774/bodyMedia-8799173253184/head//9@90902'92220, copy_subset: [0~14252], clone_subset: {}), after_progress: ObjectRecoveryProgress(!first, data_recovered_to:14252, data_complete:true, omap_recovered_to:, omap_complete:true), before_progress: ObjectRecoveryProgress(first, data_recovered_to:0, data_complete:false, omap_recovered_to:, omap_complete:false))]) v2 ==== 16171+0+0 (1445467986 0 0) 0x2c8cbe00 con 0x274b7580
9996> 2015-08-08 23:31:59.198905 7f456569b700 5 - op tracker -- seq: 4642, time: 2015-08-08 23:31:59.198793, event: header_read, op: MOSDPGPush(9.1bb 132009 [PushOp(8d841dbb/default.1812767.3_sys-master/root/h1f/h15/8806611615774/bodyMedia-8799173253184/head//9, version: 90902'92220, data_included: [0~14252], data_size: 14252, omap_header_size: 0, omap_entries_size: 0, attrset_size: 9, recovery_info: ObjectRecoveryInfo(8d841dbb/default.1812767.3_sys-master/root/h1f/h15/8806611615774/bodyMedia-8799173253184/head//9@90902'92220, copy_subset: [0~14252], clone_subset: {}), after_progress: ObjectRecoveryProgress(!first, data_recovered_to:14252, data_complete:true, omap_recovered_to:, omap_complete:true), before_progress: ObjectRecoveryProgress(first, data_recovered_to:0, data_complete:false, omap_recovered_to:, omap_complete:false))])
9995> 2015-08-08 23:31:59.198927 7f456569b700 5 - op tracker -- seq: 4642, time: 2015-08-08 23:31:59.198795, event: throttled, op: MOSDPGPush(9.1bb 132009 [PushOp(8d841dbb/default.1812767.3_sys-master/root/h1f/h15/8806611615774/bodyMedia-8799173253184/head//9, version: 90902'92220, data_included: [0~14252], data_size: 14252, omap_header_size: 0, omap_entries_size: 0, attrset_size: 9, recovery_info: ObjectRecoveryInfo(8d841dbb/default.1812767.3_sys-master/root/h1f/h15/8806611615774/bodyMedia-8799173253184/head//9@90902'92220, copy_subset: [0~14252], clone_subset: {}), after_progress: ObjectRecoveryProgress(!first, data_recovered_to:14252, data_complete:true, omap_recovered_to:, omap_complete:true), before_progress: ObjectRecoveryProgress(first, data_recovered_to:0, data_complete:false, omap_recovered_to:, omap_complete:false))])
9994> 2015-08-08 23:31:59.198938 7f456569b700 5 - op tracker -- seq: 4642, time: 2015-08-08 23:31:59.198872, event: all_read, op: MOSDPGPush(9.1bb 132009 [PushOp(8d841dbb/default.1812767.3_sys-master/root/h1f/h15/8806611615774/bodyMedia-8799173253184/head//9, version: 90902'92220, data_included: [0~14252], data_size: 14252, omap_header_size: 0, omap_entries_size: 0, attrset_size: 9, recovery_info: ObjectRecoveryInfo(8d841dbb/default.1812767.3_sys-master/root/h1f/h15/8806611615774/bodyMedia-8799173253184/head//9@90902'92220, copy_subset: [0~14252], clone_subset: {}), after_progress: ObjectRecoveryProgress(!first, data_recovered_to:14252, data_complete:true, omap_recovered_to:, omap_complete:true), before_progress: ObjectRecoveryProgress(first, data_recovered_to:0, data_complete:false, omap_recovered_to:, omap_complete:false))])
9993> 2015-08-08 23:31:59.198947 7f456569b700 5 - op tracker -- seq: 4642, time: 0.000000, event: dispatched, op: MOSDPGPush(9.1bb 132009 [PushOp(8d841dbb/default.1812767.3_sys-master/root/h1f/h15/8806611615774/bodyMedia-8799173253184/head//9, version: 90902'92220, data_included: [0~14252], data_size: 14252, omap_header_size: 0, omap_entries_size: 0, attrset_size: 9, recovery_info: ObjectRecoveryInfo(8d841dbb/default.1812767.3_sys-master/root/h1f/h15/8806611615774/bodyMedia-8799173253184/head//9@90902'92220, copy_subset: [0~14252], clone_subset: {}), after_progress: ObjectRecoveryProgress(!first, data_recovered_to:14252, data_complete:true, omap_recovered_to:, omap_complete:true), before_progress: ObjectRecoveryProgress(first, data_recovered_to:0, data_complete:false, omap_recovered_to:, omap_complete:false))])
9992> 2015-08-08 23:31:59.199015 7f456569b700 1 - 172.31.0.126:6906/549 <== osd.224 172.31.0.171:6906/7829 640 ==== pg_backfill(progress 9.1bb e 132009/132009 lb 22a31dbb/default.2431891.2_312d-6f41d4c71246385099d7e0fba31898ec22d5/head//9) v3 ==== 812+0+0 (2046507159 0 0) 0x4171680 con 0x274b7580
9991> 2015-08-08 23:31:59.199026 7f456569b700 5 - op tracker -- seq: 4643, time: 2015-08-08 23:31:59.198980, event: header_read, op: pg_backfill(progress 9.1bb e 132009/132009 lb 22a31dbb/default.2431891.2_312d-6f41d4c71246385099d7e0fba31898ec22d5/head//9)

Hi Sage,

No, untill now we've never used cache tiering.
This cluster is pretty "old" and went thru upgrades since v0.56

Only since 2 weeks osd's are starting to crash when we were running v0.80.4.
We were able stop the crashing by setting noscrub and nodeep-scrub.

We hoped to fix this by upgrading to v0.94.1. This was not the case so we started to remove all snaps from all rbd's.
This triggered numerous extra crashes by different OSD's (not all of them) and we had alot of trouble to get to a stable situation as you can see from the ceph osd tree.

By setting
osd pg max concurrent snap trims = 0
and noscrub and nodeep-scrub, the cluster was able to finish replicating and we have then re-added all down osd's again.

But these 3 parameters/flags need to remain set to prevent "random" OSD's to go down.

We think it's an issue which has been solved in the 0.8x series in a version we've never ran, based on other issue's we've seen in the bug tracker.
And this "fix" does not exist anymore in 0.94.1.
So this would then be a potential upgrade issue from v0.80.4 directly to 0.94.1.

We have 3 other clusters which all ran and run the same versions. We've tested the upgrade on all those clusters first before upgrading this cluster without issues.
The difference is that the other clusters never have had snapshots on rbd's.

Kr,
Bram

PS: Brad should be Bram ;)

Hi Sage,

Any ideas on this problem ?
Can we provide more logs or should we run some extra tests ?
The problem is very easy to trigger so generating additional debugs is no problem.

Kr,
Bram

We are encountering the same issue after trying to delete a snapshot.
Here is a log file with debug osd = 20/20 (set with inject_args right after starting it up, hopefully early enough): https://dl.dropboxusercontent.com/u/24773939/ceph-crash.log.gz (1.7mb)

A work-around is setting osd disk threads = 0 to get IO back up running, then export/backup and delete the broken objects/image.

P.S.: uploading files here is broken, I get a "request entity too large error" when trying to upload 1.7mb

Here is a complete log with debug osd = 20 from startup to crash.

https://www.dropbox.com/s/62v6rprsfo2ghdh/crash.109.log.gz?dl=1 (10.2 MiB, ~100 MB uncompressed)