Ceph » RADOS

In the context of the newly created PGs:

pg[10.5a5s3( DNE empty local-lis/les=0/0 n=0 ec=0/0 lis/c 0/0 les/c/f 0/0/0 0/0/0)
pg[10.5d3s1( DNE empty local-lis/les=0/0 n=0 ec=0/0 lis/c 0/0 les/c/f 0/0/0 0/0/0)
pg[10.522s2( DNE empty local-lis/les=0/0 n=0 ec=0/0 lis/c 0/0 les/c/f 0/0/0 0/0/0)

Building interval 439159-439159 is probably wrong.
-7> 2017-10-17 00:33:47.358730 7fde3f784e80 10 osd.137 440635 10.522s2 needs 439159-0
-6> 2017-10-17 00:33:47.358912 7fde3f784e80 10 osd.137 440635 10.5d3s1 needs 439159-0
-5> 2017-10-17 00:33:47.359763 7fde3f784e80 10 osd.137 440635 10.5a5s3 needs 439159-0
-4> 2017-10-17 00:33:47.360321 7fde3f784e80 1 osd.137 440635 build_past_intervals_parallel over 439159-439159
-3> 2017-10-17 00:33:47.360329 7fde3f784e80 10 osd.137 440635 build_past_intervals_parallel epoch 439159
-2> 2017-10-17 00:33:47.360343 7fde3f784e80 20 osd.137 0 get_map 439159 - loading and decoding 0x561954274700
-1> 2017-10-17 00:33:47.392569 7fde3f784e80 10 osd.137 0 add_map_bl 439159 81522 bytes

I just wanted to report that I managed to produce what certainly seems to be the same error on Ubuntu's 12.2.0 release. Happened without using ceph-objectstore-tool to import PG or such. It was a result of running crash tests (such as just forcibly shutting down, unplugging drives during operation, restarting ceph components in random order... ~two cycles and I had this and another OSD with a rockdb that can't be recovered with ceph fsck).

/usr/bin/ceph-osd -f --cluster ceph --id 3 --setuser ceph --setgroup ceph
starting osd.3 at - osd_data /var/lib/ceph/osd/ceph-3 /var/lib/ceph/osd/ceph-3/journal
/build/ceph-pKGC1D/ceph-12.2.0/src/osd/OSD.cc: In function 'void OSD::build_past_intervals_parallel()' thread 7f49e66fce40 time 2017-10-29 17:21:49.634188
/build/ceph-pKGC1D/ceph-12.2.0/src/osd/OSD.cc: 4171: FAILED assert(p.same_interval_since)
ceph version 12.2.0 (32ce2a3ae5239ee33d6150705cdb24d43bab910c) luminous (rc)
1: (ceph::__ceph_assert_fail(char const*, char const*, int, char const*)+0xf5) [0x563180071b55]
2: (OSD::build_past_intervals_parallel()+0x1a26) [0x56317fab5156]
3: (OSD::load_pgs()+0x53e) [0x56317fab569e]
4: (OSD::init()+0x2029) [0x56317facd3a9]
5: (main()+0x38a4) [0x56317f9e7514]
6: (__libc_start_main()+0xf1) [0x7f49e31c21c1]
7: (_start()+0x2a) [0x56317fa6f27a]

ceph-bluestore-tool fsck --path /var/lib/ceph/osd/ceph-3 is coming up clean (it's not the one with the broken rockdb), in case that matters.

Hello,

I wanted to report that I seem to be running into this bug as well.
I had a very overloaded node that OOM'd many times and upon adding memory and rebooting the node, three OSDs crash with the same assert error.
This is happening in a cluster created with Luminous 12.2.0 on Ubuntu 16.04.

I am more than happy to provide debug logs or troubleshooting if needed.

David Zafman wrote:

Tentative fix which still needs testing. Anyone seeing this can try applying this to their OSDs and report back.

I believe I managed to apply the patch to ubuntu's 12.2.1 bionic configuration & presumably because of this the error changed to "FAILED assert(info.history.same_interval_since != 0)":

starting osd.3 at - osd_data /var/lib/ceph/osd/ceph-3 /var/lib/ceph/osd/ceph-3/journal
2017-11-04 11:09:31.828016 7fdb030a3e40 -1 osd.3 952 log_to_monitors {default=true}
2017-11-04 11:09:31.843163 7fdae6978700 -1 log_channel(cluster) log [ERR] : 3.25 required past_interval bounds are empty [253,0) but past_intervals is not: ([843,942] intervals=([843,855] acting 1,2),([929,936] acting 1,5))
2017-11-04 11:09:31.843175 7fdae6978700 -1 osd.3 pg_epoch: 949 pg[3.25( DNE empty local-lis/les=0/0 n=0 ec=0/0 lis/c 0/0 les/c/f 0/0/0 0/0/0) [5] r=-1 lpr=948 pi=[843,943)/2 crt=0'0 unknown NOTIFY] 3.25 required past_interval bounds are empty [253,0) but past_intervals is
not: ([843,942] intervals=([843,855] acting 1,2),([929,936] acting 1,5))
2017-11-04 11:09:31.843227 7fdae6978700 -1 log_channel(cluster) log [ERR] : 3.25 required past_interval bounds are empty [253,0) but past_intervals is not: ([843,942] intervals=([843,855] acting 1,2),([929,936] acting 1,5))
2017-11-04 11:09:31.843242 7fdae6978700 -1 osd.3 pg_epoch: 950 pg[3.25( DNE empty local-lis/les=0/0 n=0 ec=0/0 lis/c 0/0 les/c/f 0/0/0 0/0/0) [5] r=-1 lpr=948 pi=[843,943)/2 crt=0'0 unknown NOTIFY] 3.25 required past_interval bounds are empty [253,0) but past_intervals is
not: ([843,942] intervals=([843,855] acting 1,2),([929,936] acting 1,5))
2017-11-04 11:09:31.843310 7fdae6978700 -1 log_channel(cluster) log [ERR] : 3.25 required past_interval bounds are empty [253,0) but past_intervals is not: ([843,942] intervals=([843,855] acting 1,2),([929,936] acting 1,5))
2017-11-04 11:09:31.843316 7fdae6978700 -1 osd.3 pg_epoch: 951 pg[3.25( DNE empty local-lis/les=0/0 n=0 ec=0/0 lis/c 0/0 les/c/f 0/0/0 0/0/0) [5] r=-1 lpr=948 pi=[843,943)/2 crt=0'0 unknown NOTIFY] 3.25 required past_interval bounds are empty [253,0) but past_intervals is
not: ([843,942] intervals=([843,855] acting 1,2),([929,936] acting 1,5))
/build/ceph-12.2.1/src/osd/PG.cc: In function 'void PG::start_peering_interval(OSDMapRef, const std::vector<int>&, int, const std::vector<int>&, int, ObjectStore::Transaction*)' thread 7fdae6978700 time 2017-11-04 11:09:31.843351
/build/ceph-12.2.1/src/osd/PG.cc: 5381: FAILED assert(info.history.same_interval_since != 0)

I got the patch applied to my OSDs and I see the same thing that Michael Schmid reported. The original p.same_interval_since assert has been taken care of, but I'm now seeing info.history.same_interval_since != 0.

@David I can only guess that this is not reproducible in master and that's why it requires a luminous-only fix. Could you explain that in your commit messages?

I can confirm this on 12.2.2. It makes data unavailable.

My output:

1: (ceph::__ceph_assert_fail(char const*, char const*, int, char const*)+0x102) [0x5606007838e2]
 2: (PG::start_peering_interval(std::shared_ptr<OSDMap const>, std::vector<int, std::allocator<int> > const&, int, std::vector<int, std::allocator<int> > const&, int, ObjectStore::Transaction*)+0x151e) [0x560600
266d0e]
 3: (PG::RecoveryState::Reset::react(PG::AdvMap const&)+0x479) [0x5606002672d9]
 4: (boost::statechart::simple_state<PG::RecoveryState::Reset, PG::RecoveryState::RecoveryMachine, 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*)+0x166)
 [0x5606002b1296]
 5: (boost::statechart::state_machine<PG::RecoveryState::RecoveryMachine, PG::RecoveryState::Initial, std::allocator<void>, boost::statechart::null_exception_translator>::process_event(boost::statechart::event_b
ase const&)+0x69) [0x560600286ed9]
 6: (PG::handle_advance_map(std::shared_ptr<OSDMap const>, std::shared_ptr<OSDMap const>, std::vector<int, std::allocator<int> >&, int, std::vector<int, std::allocator<int> >&, int, PG::RecoveryCtx*)+0x496) [0x5
6060024cb26]
 7: (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> > >*)+0x2e4) [0x5
60600192144]
 8: (OSD::process_peering_events(std::__cxx11::list<PG*, std::allocator<PG*> > const&, ThreadPool::TPHandle&)+0x1e4) [0x560600193074]
 9: (ThreadPool::BatchWorkQueue<PG>::_void_process(void*, ThreadPool::TPHandle&)+0x27) [0x560600205a17]
 10: (ThreadPool::worker(ThreadPool::WorkThread*)+0xdb9) [0x56060078a7e9]
 11: (ThreadPool::WorkThread::entry()+0x10) [0x56060078b8f0]
 12: (()+0x76ba) [0x7f0ea78346ba]
 13: (clone()+0x6d) [0x7f0ea68ab41d]
 NOTE: a copy of the executable, or `objdump -rdS <executable>` is needed to interpret this.

I was working on this last week, but got distracted by other issues. I'm going to force this scenario and see about fixing this possibly by deleting the bad pg on osd start-up.

https://github.com/ceph/ceph/pull/20571