Ceph » RADOS

Neha Ojha wrote:

Is it possible for you to capture osd logs with debug_osd=30? We'll also try to reproduce this at our end.

Unfortunately we already reset the OSD, as we've been suffering from a number of problems with our cluster and didn't have a chance to keep this in a broken state for investigation. We expect that we may run into further issues like this though, and if permits we'll happily provide more output.

Neha, can you draw any conclusions from the above debug_osd=30 log with this issue?

Just got this again during a recovery after doing maintenance on another node this OSD crashed.

1> 2022-03-06T21:08:01.635+0100 7fc59a875700 -1 /home/jenkins-build/build/workspace/ceph-build/ARCH/x86_64/AVAILABLE_ARCH/x86_64/AVAILABLE_DIST/centos7/DIST/centos7/MACHINE_SIZE/gigantic/release/15.2.15/rpm/el7/BUILD/ceph-15.2.15/src/osd/osd_types.h: In function 'void pg_missing_set<TrackChanges>::got(const hobject_t&, eversion_t) [with bool TrackChanges = false]' thread 7fc59a875700 time 2022-03-06T21:08:01.523875+0100
/home/jenkins-build/build/workspace/ceph-build/ARCH/x86_64/AVAILABLE_ARCH/x86_64/AVAILABLE_DIST/centos7/DIST/centos7/MACHINE_SIZE/gigantic/release/15.2.15/rpm/el7/BUILD/ceph-15.2.15/src/osd/osd_types.h: 4774: FAILED ceph_assert(p>second.need <= v || p->second.is_delete())

ceph version 15.2.15 (2dfb18841cfecc2f7eb7eb2afd65986ca4d95985) octopus (stable)
 1: (ceph::__ceph_assert_fail(char const*, char const*, int, char const*)+0x14c) [0x558cce356419]
 2: (()+0x4df5e1) [0x558cce3565e1]
 3: (PeeringState::on_peer_recover(pg_shard_t, hobject_t const&, eversion_t const&)+0x1a1) [0x558cce68a261]
 4: (ReplicatedBackend::handle_push_reply(pg_shard_t, PushReplyOp const&, PushOp*)+0x56d) [0x558cce754acd]
 5: (ReplicatedBackend::do_push_reply(boost::intrusive_ptr<OpRequest>)+0xf2) [0x558cce759142]
 6: (ReplicatedBackend::_handle_message(boost::intrusive_ptr<OpRequest>)+0x227) [0x558cce7594d7]
 7: (PGBackend::handle_message(boost::intrusive_ptr<OpRequest>)+0x4a) [0x558cce5f532a]
 8: (PrimaryLogPG::do_request(boost::intrusive_ptr<OpRequest>&, ThreadPool::TPHandle&)+0x5cb) [0x558cce59b47b]
 9: (OSD::dequeue_op(boost::intrusive_ptr<PG>, boost::intrusive_ptr<OpRequest>, ThreadPool::TPHandle&)+0x2f9) [0x558cce43ab69]
 10: (ceph::osd::scheduler::PGOpItem::run(OSD*, OSDShard*, boost::intrusive_ptr<PG>&, ThreadPool::TPHandle&)+0x69) [0x558cce676609]
 11: (OSD::ShardedOpWQ::_process(unsigned int, ceph::heartbeat_handle_d*)+0x143a) [0x558cce45644a]
 12: (ShardedThreadPool::shardedthreadpool_worker(unsigned int)+0x5b6) [0x558ccea42206]
 13: (ShardedThreadPool::WorkThreadSharded::entry()+0x10) [0x558ccea44d50]
 14: (()+0x7ea5) [0x7fc5bda74ea5]
 15: (clone()+0x6d) [0x7fc5bc9379fd]

0> 2022-03-06T21:08:01.673+0100 7fc59a875700 -1 ** Caught signal (Aborted) *
 in thread 7fc59a875700 thread_name:tp_osd_tp

ceph version 15.2.15 (2dfb18841cfecc2f7eb7eb2afd65986ca4d95985) octopus (stable)
 1: (()+0xf630) [0x7fc5bda7c630]
 2: (gsignal()+0x37) [0x7fc5bc86f3d7]
 3: (abort()+0x148) [0x7fc5bc870ac8]
 4: (ceph::__ceph_assert_fail(char const*, char const*, int, char const*)+0x19b) [0x558cce356468]
 5: (()+0x4df5e1) [0x558cce3565e1]
 6: (PeeringState::on_peer_recover(pg_shard_t, hobject_t const&, eversion_t const&)+0x1a1) [0x558cce68a261]
 7: (ReplicatedBackend::handle_push_reply(pg_shard_t, PushReplyOp const&, PushOp*)+0x56d) [0x558cce754acd]
 8: (ReplicatedBackend::do_push_reply(boost::intrusive_ptr<OpRequest>)+0xf2) [0x558cce759142]
 9: (ReplicatedBackend::_handle_message(boost::intrusive_ptr<OpRequest>)+0x227) [0x558cce7594d7]
 10: (PGBackend::handle_message(boost::intrusive_ptr<OpRequest>)+0x4a) [0x558cce5f532a]
 11: (PrimaryLogPG::do_request(boost::intrusive_ptr<OpRequest>&, ThreadPool::TPHandle&)+0x5cb) [0x558cce59b47b]
 12: (OSD::dequeue_op(boost::intrusive_ptr<PG>, boost::intrusive_ptr<OpRequest>, ThreadPool::TPHandle&)+0x2f9) [0x558cce43ab69]
 13: (ceph::osd::scheduler::PGOpItem::run(OSD*, OSDShard*, boost::intrusive_ptr<PG>&, ThreadPool::TPHandle&)+0x69) [0x558cce676609]
 14: (OSD::ShardedOpWQ::_process(unsigned int, ceph::heartbeat_handle_d*)+0x143a) [0x558cce45644a]
 15: (ShardedThreadPool::shardedthreadpool_worker(unsigned int)+0x5b6) [0x558ccea42206]
 16: (ShardedThreadPool::WorkThreadSharded::entry()+0x10) [0x558ccea44d50]
 17: (()+0x7ea5) [0x7fc5bda74ea5]
 18: (clone()+0x6d) [0x7fc5bc9379fd]
 NOTE: a copy of the executable, or `objdump -rdS <executable>` is needed to interpret this.

--- logging levels ---
0/ 0 none
0/ 0 lockdep
0/ 0 context
0/ 0 crush
0/ 0 mds
1/ 5 mds_balancer
1/ 5 mds_locker
1/ 5 mds_log
1/ 5 mds_log_expire
1/ 5 mds_migrator
0/ 0 buffer
0/ 0 timer
0/ 0 filer
0/ 0 striper
0/ 0 objecter
0/ 0 rados
0/ 0 rbd
0/ 5 rbd_mirror
0/ 5 rbd_replay
0/ 5 rbd_rwl
0/ 0 journaler
0/ 0 objectcacher
0/ 5 immutable_obj_cache
0/ 0 client
0/ 0 osd
0/ 0 optracker
0/ 0 objclass
0/ 0 filestore
0/ 0 journal
0/ 0 ms
0/ 0 mon
0/ 0 monc
0/ 0 paxos
0/ 0 tp
0/ 0 auth
0/ 0 crypto
0/ 0 finisher
0/ 0 reserver
0/ 0 heartbeatmap
0/ 0 perfcounter
0/ 0 rgw
1/ 5 rgw_sync
0/ 0 civetweb
0/ 0 javaclient
0/ 0 asok
0/ 0 throttle
0/ 0 refs
0/ 0 compressor
0/ 0 bluestore
0/ 0 bluefs
0/ 0 bdev
0/ 0 kstore
0/ 0 rocksdb
0/ 0 leveldb
0/ 0 memdb
0/ 0 fuse
0/ 0 mgr
0/ 0 mgrc
0/ 0 dpdk
0/ 0 eventtrace
1/ 5 prioritycache
0/ 5 test
2/-2 (syslog threshold)
-1/-1 (stderr threshold)
-- pthread ID / name mapping for recent threads ---
7fc59a875700 / tp_osd_tp
7fc5ad09a700 / bstore_mempool
max_recent 10000
max_new 1000
log_file /var/log/ceph/ceph-osd.67.log
--- end dump of recent events ---

If this is easily reproducible could you please provide us with logs of replicas for the failing PG? It can be figured out ceph osd pg dump.
Alternatively, a log from primary but with increased debugs (debug_ms = 1, debug_osd = 30) would be also helpful.

    "assert_condition": "p->second.need <= v || p->second.is_delete()",
    "assert_file": "/home/jenkins-build/build/workspace/ceph-build/ARCH/x86_64/AVAILABLE_ARCH/x86_64/AVAILABLE_DIST/centos8/DIST/centos8/MACHINE_SIZE/gigantic/release/16.2.7/rpm/el8/BUILD/ceph-16.2.7/src/osd/osd_types.h",
    "assert_func": "void pg_missing_set<TrackChanges>::got(const hobject_t&, eversion_t) [with bool TrackChanges = false]",
    "assert_line": 4910,
    "assert_msg": "/home/jenkins-build/build/workspace/ceph-build/ARCH/x86_64/AVAILABLE_ARCH/x86_64/AVAILABLE_DIST/centos8/DIST/centos8/MACHINE_SIZE/gigantic/release/16.2.7/rpm/el8/BUILD/ceph-16.2.7/src/osd/osd_types.h: In function 'void pg_missing_set<TrackChanges>::got(const hobject_t&, eversion_t) [with bool TrackChanges = false]' thread 7f41e33ba700 time 2022-05-12T11:21:23.175952+0200\n/home/jenkins-build/build/workspace/ceph-build/ARCH/x86_64/AVAILABLE_ARCH/x86_64/AVAILABLE_DIST/centos8/DIST/centos8/MACHINE_SIZE/gigantic/release/16.2.7/rpm/el8/BUILD/ceph-16.2.7/src/osd/osd_types.h: 4910: FAILED ceph_assert(p->second.need <= v || p->second.is_delete())\n",
    "assert_thread_name": "tp_osd_tp",
    "backtrace": [
        "/lib64/libpthread.so.0(+0x12ce0) [0x7f4207b5dce0]",
        "gsignal()",
        "abort()",
        "(ceph::__ceph_assert_fail(char const*, char const*, int, char const*)+0x1a9) [0x5637d1a4dbcf]",
        "/usr/bin/ceph-osd(+0x56ad98) [0x5637d1a4dd98]",
        "(PeeringState::on_peer_recover(pg_shard_t, hobject_t const&, eversion_t const&)+0x1b4) [0x5637d1dcc164]",
        "(ReplicatedBackend::handle_push_reply(pg_shard_t, PushReplyOp const&, PushOp*)+0x585) [0x5637d1eef615]",
        "(ReplicatedBackend::do_push_reply(boost::intrusive_ptr<OpRequest>)+0x101) [0x5637d1ef22a1]",
        "(ReplicatedBackend::_handle_message(boost::intrusive_ptr<OpRequest>)+0x237) [0x5637d1ef6e17]",
        "(PGBackend::handle_message(boost::intrusive_ptr<OpRequest>)+0x52) [0x5637d1d297d2]",
        "(PrimaryLogPG::do_request(boost::intrusive_ptr<OpRequest>&, ThreadPool::TPHandle&)+0x5de) [0x5637d1ccc95e]",
        "(OSD::dequeue_op(boost::intrusive_ptr<PG>, boost::intrusive_ptr<OpRequest>, ThreadPool::TPHandle&)+0x309) [0x5637d1b558e9]",
        "(ceph::osd::scheduler::PGRecoveryMsg::run(OSD*, OSDShard*, boost::intrusive_ptr<PG>&, ThreadPool::TPHandle&)+0x68) [0x5637d1db3248]",
        "(OSD::ShardedOpWQ::_process(unsigned int, ceph::heartbeat_handle_d*)+0xc28) [0x5637d1b75d48]",
        "(ShardedThreadPool::shardedthreadpool_worker(unsigned int)+0x5c4) [0x5637d21e75b4]",
        "(ShardedThreadPool::WorkThreadSharded::entry()+0x14) [0x5637d21ea254]",
        "/lib64/libpthread.so.0(+0x81cf) [0x7f4207b531cf]",
        "clone()" 
    ],

One OSD crashed with this when upgrading from Octopus to Pacific

Hello! A note from a bug scrub:

1. This issue looks like being caused by a particular data stored in OSD which
2. makes it very hard to replicate locally so
3. logs (or a coredump) would be really helpful.

For improving the debugging in the future we can also to split the assert's conditions into dedicated assert. However, this won't help with this particular case.