Bug #49427
Updated by Brad Hubbard about 3 years ago
/a/bhubbard-2021-02-22_23:51:15-rados-master-distro-basic-smithi/5904732
rados/verify/{centos_latest ceph clusters/{fixed-2 openstack} d-thrash/default/{default
thrashosds-health} mon_election/connectivity msgr/async-v2only objectstore/bluestore-bitmap
rados tasks/rados_api_tests validater/lockdep}
<pre>
2021-02-23T00:40:55.023+0000 7f653a802700 20 osd.0 pg_epoch: 416 pg[60.0( v 407'66 lc 81'27 (0'0,407'66] local-lis/les=414/415 n=7 ec=48/48 lis/c=414/409 les/c/f=415/411/0 sis=414) [0,6] r=0 lpr=414 pi=[409,414)/1 crt=407'66 mlcod 0'0 active+recovery_wait+degraded m=18 mbc={255={(1+1)=6}}] finish_ctx 60:005cdd9b:test-rados-api-smithi003-44693-70::foo:head 0x5610a457b600 op modify
2021-02-23T00:40:55.025+0000 7f653e009700 20 osd.0 op_wq(1) _process 60.9 to_process <> waiting <> waiting_peering {}
2021-02-23T00:40:55.025+0000 7f653e009700 20 osd.0 op_wq(1) _process OpSchedulerItem(60.9 PGRecovery(pgid=60.9 epoch_queued=416 reserved_pushes=1) prio 5 cost 20971520 e416 reserved_pushes 1) queued
2021-02-23T00:40:55.025+0000 7f653e009700 20 osd.0 op_wq(1) _process 60.9 to_process <OpSchedulerItem(60.9 PGRecovery(pgid=60.9 epoch_queued=416 reserved_pushes=1) prio 5 cost 20971520 e416 reserved_pushes 1)> waiting <> waiting_peering {}
2021-02-23T00:40:55.025+0000 7f653e009700 20 osd.0 op_wq(1) _process OpSchedulerItem(60.9 PGRecovery(pgid=60.9 epoch_queued=416 reserved_pushes=1) prio 5 cost 20971520 e416 reserved_pushes 1) pg 0x5610a307c000
2021-02-23T00:40:55.025+0000 7f653e009700 10 osd.0 416 do_recovery starting 1 pg[60.9( v 284'52 lc 81'27 (0'0,284'52] local-lis/les=414/415 n=4 ec=48/48 lis/c=414/409 les/c/f=415/412/0 sis=414) [0,7] r=0 lpr=414 pi=[409,414)/1 crt=284'52 lcod 0'0 mlcod 0'0 active+recovery_wait+degraded m=16 mbc={255={(1+1)=4}}]
2021-02-23T00:40:55.025+0000 7f653e009700 10 osd.0 pg_epoch: 416 pg[60.9( v 284'52 lc 81'27 (0'0,284'52] local-lis/les=414/415 n=4 ec=48/48 lis/c=414/409 les/c/f=415/412/0 sis=414) [0,7] r=0 lpr=414 pi=[409,414)/1 crt=284'52 lcod 0'0 mlcod 0'0 active+recovery_wait+degraded m=16 mbc={255={(1+1)=4}}] recovery raced and were queued twice, ignoring!
2021-02-23T00:40:55.025+0000 7f653e009700 10 osd.0 416 do_recovery started 0/1 on pg[60.9( v 284'52 lc 81'27 (0'0,284'52] local-lis/les=414/415 n=4 ec=48/48 lis/c=414/409 les/c/f=415/412/0 sis=414) [0,7] r=0 lpr=414 pi=[409,414)/1 crt=284'52 lcod 0'0 mlcod 0'0 active+recovery_wait+degraded m=16 mbc={255={(1+1)=4}}]
2021-02-23T00:40:55.025+0000 7f653e009700 10 osd.0 416 release_reserved_pushes(1), recovery_ops_reserved 3 -> 2
2021-02-23T00:40:55.025+0000 7f653a001700 10 osd.0 op_wq(1) _process dequeue future request at 2021-02-23T00:40:55.074352+0000
2021-02-23T00:40:55.027+0000 7f653a802700 -1 /home/jenkins-build/build/workspace/ceph-dev-build/ARCH/x86_64/AVAILABLE_ARCH/x86_64/AVAILABLE_DIST/centos8/DIST/centos8/MACHINE_SIZE/gigantic/release/17.0.0-1024-ga3591378/rpm/el8/BUILD/ceph-17.0.0-1024-ga3591378/src/osd/PrimaryLogPG.cc: In function 'ObjectContextRef PrimaryLogPG::get_object_context(const hobject_t&, bool, const std::map<std::__cxx11::basic_string<char>, ceph::buffer::v15_2_0::list>*)' thread 7f653a802700 time 2021-02-23T00:40:55.024443+0000
/home/jenkins-build/build/workspace/ceph-dev-build/ARCH/x86_64/AVAILABLE_ARCH/x86_64/AVAILABLE_DIST/centos8/DIST/centos8/MACHINE_SIZE/gigantic/release/17.0.0-1024-ga3591378/rpm/el8/BUILD/ceph-17.0.0-1024-ga3591378/src/osd/PrimaryLogPG.cc: 11423: FAILED ceph_assert(attrs || !recovery_state.get_pg_log().get_missing().is_missing(soid) || (it_objects != recovery_state.get_pg_log().get_log().objects.end() && it_objects->second->op == pg_log_entry_t::LOST_REVERT))
ceph version 17.0.0-1024-ga3591378 (a3591378a59c621ac597987facb3fb30707c218f) quincy (dev)
1: (ceph::__ceph_assert_fail(char const*, char const*, int, char const*)+0x158) [0x56108a9df99e]
2: ceph-osd(+0x568bb8) [0x56108a9dfbb8]
3: (PrimaryLogPG::get_object_context(hobject_t const&, bool, std::map<std::__cxx11::basic_string<char, std::char_traits<char>, std::allocator<char> >, ceph::buffer::v15_2_0::list, std::less<std::__cxx11::basic_string<char, std::char_traits<char>, std::allocator<char> > >, std::allocator<std::pair<std::__cxx11::basic_string<char, std::char_traits<char>, std::allocator<char> > const, ceph::buffer::v15_2_0::list> > > const*)+0x6ff) [0x56108abf6b5f]
4: (PrimaryLogPG::get_prev_clone_obc(std::shared_ptr<ObjectContext>)+0xc1) [0x56108abf76c1]
5: (PrimaryLogPG::dec_refcount_by_dirty(PrimaryLogPG::OpContext*)+0x12b) [0x56108abf788b]
6: (PrimaryLogPG::finish_ctx(PrimaryLogPG::OpContext*, int, int)+0x1327) [0x56108abf9ff7]
7: (PrimaryLogPG::prepare_transaction(PrimaryLogPG::OpContext*)+0x25c) [0x56108ac4805c]
8: (PrimaryLogPG::execute_ctx(PrimaryLogPG::OpContext*)+0x326) [0x56108ac4a066]
9: (PrimaryLogPG::do_op(boost::intrusive_ptr<OpRequest>&)+0x2d50) [0x56108ac53980]
10: (PrimaryLogPG::do_request(boost::intrusive_ptr<OpRequest>&, ThreadPool::TPHandle&)+0xd1c) [0x56108ac5acdc]
11: (OSD::dequeue_op(boost::intrusive_ptr<PG>, boost::intrusive_ptr<OpRequest>, ThreadPool::TPHandle&)+0x309) [0x56108aae4ac9]
12: (ceph::osd::scheduler::PGOpItem::run(OSD*, OSDShard*, boost::intrusive_ptr<PG>&, ThreadPool::TPHandle&)+0x68) [0x56108ad40f38]
13: (OSD::ShardedOpWQ::_process(unsigned int, ceph::heartbeat_handle_d*)+0xa58) [0x56108ab04038]
14: (ShardedThreadPool::shardedthreadpool_worker(unsigned int)+0x5c4) [0x56108b168d64]
15: (ShardedThreadPool::WorkThreadSharded::entry()+0x14) [0x56108b16ba04]
16: (Thread::_entry_func(void*)+0xd) [0x56108b15a86d]
17: /lib64/libpthread.so.0(+0x82de) [0x7f6561e4a2de]
18: clone()
</pre>