Bug 1506438

Summary:	[RHCeph 3.0 / 12.2.1-26.el7cp] rbd/fsx on bluestore: FAILED assert(p != extents.end())
Product:	[Red Hat Storage] Red Hat Ceph Storage	Reporter:	Vasu Kulkarni <vakulkar>
Component:	RADOS	Assignee:	Josh Durgin <jdurgin>
Status:	CLOSED ERRATA	QA Contact:	Vasu Kulkarni <vakulkar>
Severity:	medium	Docs Contact:
Priority:	unspecified
Version:	3.0	CC:	ceph-eng-bugs, dzafman, hnallurv, jdillama, jdurgin, kchai, kdreyer
Target Milestone:	z2
Target Release:	3.0
Hardware:	Unspecified
OS:	Unspecified
Whiteboard:
Fixed In Version:	RHEL: ceph-12.2.4-1.el7cp Ubuntu: ceph_12.2.4-2redhat1	Doc Type:	If docs needed, set a value
Doc Text:		Story Points:	---
Clone Of:		Environment:
Last Closed:	2018-04-26 17:38:39 UTC	Type:	Bug
Regression:	---	Mount Type:	---
Documentation:	---	CRM:
Verified Versions:		Category:	---
oVirt Team:	---	RHEL 7.3 requirements from Atomic Host:
Cloudforms Team:	---	Target Upstream Version:
Embargoed:
Bug Depends On:	1548067
Bug Blocks:

Description Vasu Kulkarni 2017-10-26 04:21:57 UTC

Description of problem:

I am seeing some following assert during rbd fsx workload test, the job has been runnng for sometime so i guess the logs would not be there, I will kill it and see if it collect logs.


2017-10-25T02:03:52.520 INFO:tasks.ceph.osd.1.pluto010.stderr:/builddir/build/BUILD/ceph-12.2.1/src/os/bluestore/bluestore_types.h: 740: FAILED assert(p != extents.end())
2017-10-25T02:03:52.520 INFO:tasks.ceph.osd.1.pluto010.stderr: ceph version 12.2.1-26.el7cp (0e61383ab27c879d3fbe8230e082e7a63be36dcd) luminous (stable)
2017-10-25T02:03:52.521 INFO:tasks.ceph.osd.1.pluto010.stderr: 1: (ceph::__ceph_assert_fail(char const*, char const*, int, char const*)+0x110) [0x561092c1c6c0]
2017-10-25T02:03:52.521 INFO:tasks.ceph.osd.1.pluto010.stderr: 2: (bluestore_blob_t::map(unsigned long, unsigned long, std::function<int (unsigned long, unsigned long)>) const+0xfe) [0x561092aff91e]
2017-10-25T02:03:52.521 INFO:tasks.ceph.osd.1.pluto010.stderr: 3: (BlueStore::_do_remove(BlueStore::TransContext*, boost::intrusive_ptr<BlueStore::Collection>&, boost::intrusive_ptr<BlueStore::Onode>)+0x1161) [0x561092ade461]
2017-10-25T02:03:52.521 INFO:tasks.ceph.osd.1.pluto010.stderr: 4: (BlueStore::_remove(BlueStore::TransContext*, boost::intrusive_ptr<BlueStore::Collection>&, boost::intrusive_ptr<BlueStore::Onode>&)+0x94) [0x561092aded34]
2017-10-25T02:03:52.522 INFO:tasks.ceph.osd.1.pluto010.stderr: 5: (BlueStore::_txc_add_transaction(BlueStore::TransContext*, ObjectStore::Transaction*)+0x15af) [0x561092af176f]
2017-10-25T02:03:52.522 INFO:tasks.ceph.osd.1.pluto010.stderr: 6: (BlueStore::queue_transactions(ObjectStore::Sequencer*, std::vector<ObjectStore::Transaction, std::allocator<ObjectStore::Transaction> >&, boost::intrusive_ptr<TrackedOp>, ThreadPool::TPHandle*)+0x3a0) [0x561092af2690]
2017-10-25T02:03:52.522 INFO:tasks.ceph.osd.1.pluto010.stderr: 7: (PrimaryLogPG::queue_transactions(std::vector<ObjectStore::Transaction, std::allocator<ObjectStore::Transaction> >&, boost::intrusive_ptr<OpRequest>)+0x65) [0x561092862785]
2017-10-25T02:03:52.523 INFO:tasks.ceph.osd.1.pluto010.stderr: 8: (ECBackend::handle_sub_write(pg_shard_t, boost::intrusive_ptr<OpRequest>, ECSubWrite&, ZTracer::Trace const&, Context*)+0x631) [0x561092982a81]
2017-10-25T02:03:52.523 INFO:tasks.ceph.osd.1.pluto010.stderr: 9: (ECBackend::try_reads_to_commit()+0x1ad3) [0x561092990cd3]
2017-10-25T02:03:52.523 INFO:tasks.ceph.osd.1.pluto010.stderr: 10: (ECBackend::check_ops()+0x1c) [0x56109299120c]
2017-10-25T02:03:52.523 INFO:tasks.ceph.osd.1.pluto010.stderr: 11: (ECBackend::handle_sub_write_reply(pg_shard_t, ECSubWriteReply const&, ZTracer::Trace const&)+0x2ae) [0x5610929914ce]
2017-10-25T02:03:52.524 INFO:tasks.ceph.osd.1.pluto010.stderr: 12: (ECBackend::_handle_message(boost::intrusive_ptr<OpRequest>)+0x2df) [0x56109299358f]
2017-10-25T02:03:52.524 INFO:tasks.ceph.osd.1.pluto010.stderr: 13: (PGBackend::handle_message(boost::intrusive_ptr<OpRequest>)+0x50) [0x561092897f10]
2017-10-25T02:03:52.524 INFO:tasks.ceph.osd.1.pluto010.stderr: 14: (PrimaryLogPG::do_request(boost::intrusive_ptr<OpRequest>&, ThreadPool::TPHandle&)+0x5ae) [0x5610928037be]
2017-10-25T02:03:52.525 INFO:tasks.ceph.osd.1.pluto010.stderr: 15: (OSD::dequeue_op(boost::intrusive_ptr<PG>, boost::intrusive_ptr<OpRequest>, ThreadPool::TPHandle&)+0x3f9) [0x561092693a49]
2017-10-25T02:03:52.525 INFO:tasks.ceph.osd.1.pluto010.stderr: 16: (PGQueueable::RunVis::operator()(boost::intrusive_ptr<OpRequest> const&)+0x57) [0x561092905ef7]
2017-10-25T02:03:52.525 INFO:tasks.ceph.osd.1.pluto010.stderr: 17: (OSD::ShardedOpWQ::_process(unsigned int, ceph::heartbeat_handle_d*)+0xfce) [0x5610926bf18e]
2017-10-25T02:03:52.525 INFO:tasks.ceph.osd.1.pluto010.stderr: 18: (ShardedThreadPool::shardedthreadpool_worker(unsigned int)+0x839) [0x561092c221d9]
2017-10-25T02:03:52.525 INFO:tasks.ceph.osd.1.pluto010.stderr: 19: (ShardedThreadPool::WorkThreadSharded::entry()+0x10) [0x561092c24170]
2017-10-25T02:03:52.526 INFO:tasks.ceph.osd.1.pluto010.stderr: 20: (()+0x7e25) [0x7f71f8dbee25]
2017-10-25T02:03:52.526 INFO:tasks.ceph.osd.1.pluto010.stderr: 21: (clone()+0x6d) [0x7f71f7eb234d]
2017-10-25T02:03:52.526 INFO:tasks.ceph.osd.1.pluto010.stderr: NOTE: a copy of the executable, or `objdump -rdS <executable>` is needed to interpret this.
2017-10-25T02:03:52.526 INFO:tasks.ceph.osd.2.pluto010.stderr: ceph version 12.2.1-26.el7cp (0e61383ab27c879d3fbe8230e082e7a63be36dcd) luminous (stable)
2017-10-25T02:03:52.527 INFO:tasks.ceph.osd.2.pluto010.stderr: 1: (ceph::__ceph_assert_fail(char const*, char const*, int, char const*)+0x110) [0x55627a6ff6c0]
2017-10-25T02:03:52.527 INFO:tasks.ceph.osd.2.pluto010.stderr: 2: (bluestore_blob_t::map(unsigned long, unsigned long, std::function<int (unsigned long, unsigned long)>) const+0xfe) [0x55627a5e291e]
2017-10-25T02:03:52.527 INFO:tasks.ceph.osd.2.pluto010.stderr: 3: (BlueStore::_do_remove(BlueStore::TransContext*, boost::intrusive_ptr<BlueStore::Collection>&, boost::intrusive_ptr<BlueStore::Onode>)+0x1161) [0x55627a5c1461]
2017-10-25T02:03:52.527 INFO:tasks.ceph.osd.2.pluto010.stderr: 4: (BlueStore::_remove(BlueStore::TransContext*, boost::intrusive_ptr<BlueStore::Collection>&, boost::intrusive_ptr<BlueStore::Onode>&)+0x94) [0x55627a5c1d34]
2017-10-25T02:03:52.528 INFO:tasks.ceph.osd.2.pluto010.stderr: 5: (BlueStore::_txc_add_transaction(BlueStore::TransContext*, ObjectStore::Transaction*)+0x15af) [0x55627a5d476f]
2017-10-25T02:03:52.528 INFO:tasks.ceph.osd.2.pluto010.stderr: 6: (BlueStore::queue_transactions(ObjectStore::Sequencer*, std::vector<ObjectStore::Transaction, std::allocator<ObjectStore::Transaction> >&, boost::intrusive_ptr<TrackedOp>, ThreadPool::TPHandle*)+0x3a0) [0x55627a5d5690]
2017-10-25T02:03:52.528 INFO:tasks.ceph.osd.2.pluto010.stderr: 7: (PrimaryLogPG::queue_transactions(std::vector<ObjectStore::Transaction, std::allocator<ObjectStore::Transaction> >&, boost::intrusive_ptr<OpRequest>)+0x65) [0x55627a345785]
2017-10-25T02:03:52.528 INFO:tasks.ceph.osd.2.pluto010.stderr: 8: (ECBackend::handle_sub_write(pg_shard_t, boost::intrusive_ptr<OpRequest>, ECSubWrite&, ZTracer::Trace const&, Context*)+0x631) [0x55627a465a81]
2017-10-25T02:03:52.529 INFO:tasks.ceph.osd.2.pluto010.stderr: 9: (ECBackend::_handle_message(boost::intrusive_ptr<OpRequest>)+0x327) [0x55627a4765d7]
2017-10-25T02:03:52.529 INFO:tasks.ceph.osd.2.pluto010.stderr: 10: (PGBackend::handle_message(boost::intrusive_ptr<OpRequest>)+0x50) [0x55627a37af10]
2017-10-25T02:03:52.529 INFO:tasks.ceph.osd.2.pluto010.stderr: 11: (PrimaryLogPG::do_request(boost::intrusive_ptr<OpRequest>&, ThreadPool::TPHandle&)+0x5ae) [0x55627a2e67be]
2017-10-25T02:03:52.529 INFO:tasks.ceph.osd.2.pluto010.stderr: 12: (OSD::dequeue_op(boost::intrusive_ptr<PG>, boost::intrusive_ptr<OpRequest>, ThreadPool::TPHandle&)+0x3f9) [0x55627a176a49]
2017-10-25T02:03:52.530 INFO:tasks.ceph.osd.2.pluto010.stderr: 13: (PGQueueable::RunVis::operator()(boost::intrusive_ptr<OpRequest> const&)+0x57) [0x55627a3e8ef7]
2017-10-25T02:03:52.530 INFO:tasks.ceph.osd.2.pluto010.stderr: 14: (OSD::ShardedOpWQ::_process(unsigned int, ceph::heartbeat_handle_d*)+0xfce) [0x55627a1a218e]
2017-10-25T02:03:52.530 INFO:tasks.ceph.osd.2.pluto010.stderr: 15: (ShardedThreadPool::shardedthreadpool_worker(unsigned int)+0x839) [0x55627a7051d9]
2017-10-25T02:03:52.530 INFO:tasks.ceph.osd.2.pluto010.stderr: 16: (ShardedThreadPool::WorkThreadSharded::entry()+0x10) [0x55627a707170]
2017-10-25T02:03:52.531 INFO:tasks.ceph.osd.2.pluto010.stderr: 17: (()+0x7e25) [0x7effe4f15e25]
2017-10-25T02:03:52.531 INFO:tasks.ceph.osd.2.pluto010.stderr: 18: (clone()+0x6d) [0x7effe400934d]
2017-10-25T02:03:52.531 INFO:tasks.ceph.osd.2.pluto010.stderr: NOTE: a copy of the executable, or `objdump -rdS <executable>` is needed to interpret this.
2017-10-25T02:03:52.531 INFO:tasks.ceph.osd.2.pluto010.stderr:2017-10-25 06:06:02.875165 7effc9e48700 -1 /builddir/build/BUILD/ceph-12.2.1/src/os/bluestore/bluestore_types.h: In function 'int bluestore_blob_t::map(uint64_t, uint64_t, std::function<int(long unsigned int, long unsigned int)>) const' thread 7effc9e48700 time 2017-10-25 06:06:02.868718
2017-10-25T02:03:52.531 INFO:tasks.ceph.osd.2.pluto010.stderr:/builddir/build/BUILD/ceph-12.2.1/src/os/bluestore/bluestore_types.h: 740: FAILED assert(p != extents.end())
2017-10-25T02:03:52.532 INFO:tasks.ceph.osd.2.pluto010.stderr:
2017-10-25T02:03:52.532 INFO:tasks.ceph.osd.2.pluto010.stderr: ceph version 12.2.1-26.el7cp (0e61383ab27c879d3fbe8230e082e7a63be36dcd) luminous (stable)
2017-10-25T02:03:52.532 INFO:tasks.ceph.osd.2.pluto010.stderr: 1: (ceph::__ceph_assert_fail(char const*, char const*, int, char const*)+0x110) [0x55627a6ff6c0]
2017-10-25T02:03:52.532 INFO:tasks.ceph.osd.2.pluto010.stderr: 2: (bluestore_blob_t::map(unsigned long, unsigned long, std::function<int (unsigned long, unsigned long)>) const+0xfe) [0x55627a5e291e]
2017-10-25T02:03:52.533 INFO:tasks.ceph.osd.2.pluto010.stderr: 3: (BlueStore::_do_remove(BlueStore::TransContext*, boost::intrusive_ptr<BlueStore::Collection>&, boost::intrusive_ptr<BlueStore::Onode>)+0x1161) [0x55627a5c1461]
2017-10-25T02:03:52.533 INFO:tasks.ceph.osd.2.pluto010.stderr: 4: (BlueStore::_remove(BlueStore::TransContext*, boost::intrusive_ptr<BlueStore::Collection>&, boost::intrusive_ptr<BlueStore::Onode>&)+0x94) [0x55627a5c1d34]
2017-10-25T02:03:52.533 INFO:tasks.ceph.osd.2.pluto010.stderr: 5: (BlueStore::_txc_add_transaction(BlueStore::TransContext*, ObjectStore::Transaction*)+0x15af) [0x55627a5d476f]
2017-10-25T02:03:52.534 INFO:tasks.ceph.osd.2.pluto010.stderr: 6: (BlueStore::queue_transactions(ObjectStore::Sequencer*, std::vector<ObjectStore::Transaction, std::allocator<ObjectStore::Transaction> >&, boost::intrusive_ptr<TrackedOp>, ThreadPool::TPHandle*)+0x3a0) [0x55627a5d5690]
2017-10-25T02:03:52.534 INFO:tasks.ceph.osd.2.pluto010.stderr: 7: (PrimaryLogPG::queue_transactions(std::vector<ObjectStore::Transaction, std::allocator<ObjectStore::Transaction> >&, boost::intrusive_ptr<OpRequest>)+0x65) [0x55627a345785]
2017-10-25T02:03:52.534 INFO:tasks.ceph.osd.2.pluto010.stderr: 8: (ECBackend::handle_sub_write(pg_shard_t, boost::intrusive_ptr<OpRequest>, ECSubWrite&, ZTracer::Trace const&, Context*)+0x631) [0x55627a465a81]
2017-10-25T02:03:52.534 INFO:tasks.ceph.osd.2.pluto010.stderr: 9: (ECBackend::_handle_message(boost::intrusive_ptr<OpRequest>)+0x327) [0x55627a4765d7]
2017-10-25T02:03:52.534 INFO:tasks.ceph.osd.2.pluto010.stderr: 10: (PGBackend::handle_message(boost::intrusive_ptr<OpRequest>)+0x50) [0x55627a37af10]
2017-10-25T02:03:52.535 INFO:tasks.ceph.osd.2.pluto010.stderr: 11: (PrimaryLogPG::do_request(boost::intrusive_ptr<OpRequest>&, ThreadPool::TPHandle&)+0x5ae) [0x55627a2e67be]
2017-10-25T02:03:52.535 INFO:tasks.ceph.osd.2.pluto010.stderr: 12: (OSD::dequeue_op(boost::intrusive_ptr<PG>, boost::intrusive_ptr<OpRequest>, ThreadPool::TPHandle&)+0x3f9) [0x55627a176a49]
2017-10-25T02:03:52.535 INFO:tasks.ceph.osd.2.pluto010.stderr: 13: (PGQueueable::RunVis::operator()(boost::intrusive_ptr<OpRequest> const&)+0x57) [0x55627a3e8ef7]
2017-10-25T02:03:52.535 INFO:tasks.ceph.osd.2.pluto010.stderr: 14: (OSD::ShardedOpWQ::_process(unsigned int, ceph::heartbeat_handle_d*)+0xfce) [0x55627a1a218e]
2017-10-25T02:03:52.536 INFO:tasks.ceph.osd.2.pluto010.stderr: 15: (ShardedThreadPool::shardedthreadpool_worker(unsigned int)+0x839) [0x55627a7051d9]
2017-10-25T02:03:52.536 INFO:tasks.ceph.osd.2.pluto010.stderr: 16: (ShardedThreadPool::WorkThreadSharded::entry()+0x10) [0x55627a707170]
2017-10-25T02:03:52.536 INFO:tasks.ceph.osd.2.pluto010.stderr: 17: (()+0x7e25) [0x7effe4f15e25]
2017-10-25T02:03:52.536 INFO:tasks.ceph.osd.2.pluto010.stderr: 18: (clone()+0x6d) [0x7effe400934d]
2017-10-25T02:03:52.537 INFO:tasks.ceph.osd.2.pluto010.stderr: NOTE: a copy of the executable, or `objdump -rdS <executable>` is needed to interpret this.
2017-10-25T02:03:52.537 INFO:tasks.ceph.osd.2.pluto010.stderr:


Full logs:
http://magna002.ceph.redhat.com/vasu-2017-10-23_18:41:49-rbd-luminous---basic-multi/279165/teuthology.log

Comment 7 Vasu Kulkarni 2018-02-19 20:38:12 UTC

Josh,

Can we get this for z2, which is 6 weeks away, I can run good subsets of RADOS and RBD to be sure we dont have other regressions.

Comment 10 Harish NV Rao 2018-02-20 07:04:04 UTC

It looks the bot reset this back to z1 rc after Vasu tried to target it to z2. I am trying that again.....

Comment 14 Vasu Kulkarni 2018-04-11 03:09:03 UTC

Tests are running, Looks like some of the facets have run, but I will be able to close this tomorrow after complete runs. http://pulpito.ceph.redhat.com/vasu-2018-04-09_21:22:21-rbd-luminous-distro-basic-multi/

Comment 15 Vasu Kulkarni 2018-04-11 23:01:06 UTC

Multiple tests with Bluestore passed

Comment 19 errata-xmlrpc 2018-04-26 17:38:39 UTC

Since the problem described in this bug report should be
resolved in a recent advisory, it has been closed with a
resolution of ERRATA.

For information on the advisory, and where to find the updated
files, follow the link below.

If the solution does not work for you, open a new bug report.

https://access.redhat.com/errata/RHBA-2018:1259