Project

General

Profile

Bug #24037

osd: Assertion `!node_algorithms::inited(this->priv_value_traits().to_node_ptr(value))' failed.

Added by Patrick Donnelly about 1 year ago. Updated about 1 year ago.

Status:
Resolved
Priority:
Urgent
Category:
Correctness/Safety
Target version:
Start date:
05/07/2018
Due date:
% Done:

0%

Source:
Q/A
Tags:
Backport:
mimic
Regression:
No
Severity:
2 - major
Reviewed:
Affected Versions:
ceph-qa-suite:
Component(RADOS):
OSD
Pull request ID:

Description

2018-05-07T19:02:30.902 INFO:tasks.ceph.osd.0.smithi110.stderr:ceph-osd: /build/ceph-13.0.2-2151-g180ce3f/obj-x86_64-linux-gnu/boost/include/boost/intrusive/list.hpp:1307: boost::intrusive::list_impl<ValueTraits, SizeType, ConstantTimeSize, HeaderHolder>::iterator boost::intrusive::list_impl<ValueTraits, SizeType, ConstantTimeSize, HeaderHolder>::iterator_to(boost::intrusive::list_impl<ValueTraits, SizeType, ConstantTimeSize, HeaderHolder>::reference) [with ValueTraits = boost::intrusive::mhtraits<TrackedOp, boost::intrusive::list_member_hook<>, &TrackedOp::tracker_item>; SizeType = long unsigned int; bool ConstantTimeSize = true; HeaderHolder = void; boost::intrusive::list_impl<ValueTraits, SizeType, ConstantTimeSize, HeaderHolder>::iterator = boost::intrusive::list_iterator<boost::intrusive::mhtraits<TrackedOp, boost::intrusive::list_member_hook<>, &TrackedOp::tracker_item>, false>; boost::intrusive::list_impl<ValueTraits, SizeType, ConstantTimeSize, HeaderHolder>::reference = TrackedOp&]: Assertion `!node_algorithms::inited(this->priv_value_traits().to_node_ptr(value))' failed.
2018-05-07T19:02:30.902 INFO:tasks.ceph.osd.0.smithi110.stderr:*** Caught signal (Aborted) **
2018-05-07T19:02:30.903 INFO:tasks.ceph.osd.0.smithi110.stderr: in thread 7fc216b11700 thread_name:safe_timer
2018-05-07T19:02:30.903 INFO:tasks.ceph.osd.0.smithi110.stderr: ceph version 13.0.2-2151-g180ce3f (180ce3fb9ca95b195a595828062c76237435e6de) mimic (dev)
2018-05-07T19:02:30.903 INFO:tasks.ceph.osd.0.smithi110.stderr: 1: (()+0x9159d0) [0x55dbfe4839d0]
2018-05-07T19:02:30.904 INFO:tasks.ceph.osd.0.smithi110.stderr: 2: (()+0x11390) [0x7fc21f71f390]
2018-05-07T19:02:30.904 INFO:tasks.ceph.osd.0.smithi110.stderr: 3: (gsignal()+0x38) [0x7fc21ee6c428]
2018-05-07T19:02:30.904 INFO:tasks.ceph.osd.0.smithi110.stderr: 4: (abort()+0x16a) [0x7fc21ee6e02a]
2018-05-07T19:02:30.904 INFO:tasks.ceph.osd.0.smithi110.stderr: 5: (()+0x2dbd7) [0x7fc21ee64bd7]
2018-05-07T19:02:30.904 INFO:tasks.ceph.osd.0.smithi110.stderr: 6: (()+0x2dc82) [0x7fc21ee64c82]
2018-05-07T19:02:30.904 INFO:tasks.ceph.osd.0.smithi110.stderr: 7: (OpTracker::unregister_inflight_op(TrackedOp*)+0x42d) [0x55dbfe1ab71d]
2018-05-07T19:02:30.904 INFO:tasks.ceph.osd.0.smithi110.stderr: 8: (TrackedOp::put()+0x33e) [0x55dbfdf6eb9e]
2018-05-07T19:02:30.904 INFO:tasks.ceph.osd.0.smithi110.stderr: 9: (OSD::get_health_metrics()+0x34b) [0x55dbfdf51fdb]
2018-05-07T19:02:30.905 INFO:tasks.ceph.osd.0.smithi110.stderr: 10: (OSD::tick_without_osd_lock()+0x131) [0x55dbfdf52681]
2018-05-07T19:02:30.905 INFO:tasks.ceph.osd.0.smithi110.stderr: 11: (Context::complete(int)+0x9) [0x55dbfdf63e89]
2018-05-07T19:02:30.905 INFO:tasks.ceph.osd.0.smithi110.stderr: 12: (SafeTimer::timer_thread()+0x18b) [0x7fc220c68aeb]
2018-05-07T19:02:30.905 INFO:tasks.ceph.osd.0.smithi110.stderr: 13: (SafeTimerThread::entry()+0xd) [0x7fc220c6a0ad]
2018-05-07T19:02:30.905 INFO:tasks.ceph.osd.0.smithi110.stderr: 14: (()+0x76ba) [0x7fc21f7156ba]
2018-05-07T19:02:30.905 INFO:tasks.ceph.osd.0.smithi110.stderr: 15: (clone()+0x6d) [0x7fc21ef3e41d]

From: /ceph/teuthology-archive/pdonnell-2018-05-07_17:31:28-multimds-wip-pdonnell-testing-20180504.211521-testing-basic-smithi/2490951/teuthology.log


Related issues

Related to RADOS - Bug #23892: luminous->mimic: mon segv in ~MonOpRequest from OpHistoryServiceThread Verified 04/26/2018
Related to RADOS - Bug #23352: osd: segfaults under normal operation Resolved 03/14/2018
Related to RADOS - Bug #24664: osd: crash in OpTracker::unregister_inflight_op via OSD::get_health_metrics Pending Backport 06/26/2018
Copied to RADOS - Backport #24256: mimic: osd: Assertion `!node_algorithms::inited(this->priv_value_traits().to_node_ptr(value))' failed. Resolved

History

#1 Updated by Josh Durgin about 1 year ago

Sounds like a use-after-free of some sort, unrelated to other crashes we've seen.

#2 Updated by Patrick Donnelly about 1 year ago

  • Severity changed from 3 - minor to 2 - major

Here's another that looks related:

Crash: "2018-05-08 18:53:24.101339 mon.a mon.0 172.21.15.17:6789/0 334 : cluster [WRN] MDS health message (mds.0): 1 slow requests are blocked > 30 sec" in cluster log
ceph version 13.1.0-37-g5e16dd6 (5e16dd6cf52c7659501738658195ccd76e4d2cad) mimic (dev)
 1: (()+0x9159e0) [0x55d4533b59e0]
 2: (()+0x11390) [0x7fdf68475390]
 3: (gsignal()+0x38) [0x7fdf67bc2428]
 4: (abort()+0x16a) [0x7fdf67bc402a]
 5: (()+0x2dbd7) [0x7fdf67bbabd7]
 6: (()+0x2dc82) [0x7fdf67bbac82]
 7: (OpTracker::unregister_inflight_op(TrackedOp*)+0x42d) [0x55d4530dd6ed]
 8: (TrackedOp::put()+0x33e) [0x55d452ea0b6e]
 9: (ECBackend::Op::~Op()+0x8b) [0x55d45317de3b]
 10: (std::_Rb_tree<unsigned long, std::pair<unsigned long const, ECBackend::Op>, std::_Select1st<std::pair<unsigned long const, ECBackend::Op> >, std::less<unsigned long>, std::allocator<std::pair<unsigned long const, ECBackend::Op> > >::erase(unsigned long const&)+0x122) [0x55d45317e642]
 11: (ECBackend::try_finish_rmw()+0x182) [0x55d45315ff02]
 12: (ECBackend::check_ops()+0x28) [0x55d453166038]
 13: (ECBackend::handle_sub_write_reply(pg_shard_t, ECSubWriteReply const&, ZTracer::Trace const&)+0xd2) [0x55d453166112]
 14: (ECBackend::_handle_message(boost::intrusive_ptr<OpRequest>)+0x1cd) [0x55d45316be3d]
 15: (PGBackend::handle_message(boost::intrusive_ptr<OpRequest>)+0x97) [0x55d4530578b7]
 16: (PrimaryLogPG::do_request(boost::intrusive_ptr<OpRequest>&, ThreadPool::TPHandle&)+0x6ed) [0x55d4530062dd]
 17: (OSD::dequeue_op(boost::intrusive_ptr<PG>, boost::intrusive_ptr<OpRequest>, ThreadPool::TPHandle&)+0x1b8) [0x55d452e61058]
 18: (PGOpItem::run(OSD*, OSDShard*, boost::intrusive_ptr<PG>&, ThreadPool::TPHandle&)+0x62) [0x55d4530d9bb2]
 19: (OSD::ShardedOpWQ::_process(unsigned int, ceph::heartbeat_handle_d*)+0x590) [0x55d452e807b0]
 20: (ShardedThreadPool::shardedthreadpool_worker(unsigned int)+0x46e) [0x7fdf699c70ae]
 21: (ShardedThreadPool::WorkThreadSharded::entry()+0x10) [0x7fdf699c9130]
 22: (()+0x76ba) [0x7fdf6846b6ba]
 23: (clone()+0x6d) [0x7fdf67c9441d]
1 jobs: ['2501825']
suites: ['clusters/9-mds.yaml', 'frag_enable.yaml', 'fuse-default-perm-no.yaml}', 'inline/yes.yaml', 'mount/kclient.yaml', 'multimds/basic/{begin.yaml', 'objectstore-ec/bluestore-ec-root.yaml', 'overrides/{basic/{debug.yaml', 'q_check_counter/check_counter.yaml', 'tasks/cfuse_workunit_suites_ffsb.yaml}', 'whitelist_health.yaml', 'whitelist_wrongly_marked_down.yaml}']

From: http://pulpito.ceph.com/pdonnell-2018-05-08_18:15:43-multimds-mimic-testing-basic-smithi/2501825

#3 Updated by Radoslaw Zarzynski about 1 year ago

  • Assignee set to Radoslaw Zarzynski

#4 Updated by Radoslaw Zarzynski about 1 year ago

  • Related to Bug #23892: luminous->mimic: mon segv in ~MonOpRequest from OpHistoryServiceThread added

#5 Updated by Radoslaw Zarzynski about 1 year ago

Scenario I can see after static analysis:

1. An instance of `TrackedOp` in `STATE_LIVE` is being dereferenced - the control flows to `TrackedOp::put`.
2. Reference counter hits `0` and `OpTracker::unregister_inflight_op(TrackedOp *i)` is being called.
3. There is a time window between zeroing the ref-counter and locking the shard.

class TrackedOp {
  // ...
  void put() {
    if (--nref == 0) {
      switch (state.load()) {
      // ...
      case STATE_LIVE:
        mark_event("done");
        tracker->unregister_inflight_op(this);
        break;
      // ...
      }
    }
  }
}

// ...
void OpTracker::unregister_inflight_op(TrackedOp *i)
{
  // caller checks;
  assert(i->state);

  uint32_t shard_index = i->seq % num_optracker_shards;
  ShardedTrackingData* sdata = sharded_in_flight_list[shard_index];
  assert(NULL != sdata);
  {
    Mutex::Locker locker(sdata->ops_in_flight_lock_sharded);
    `
    auto p = sdata->ops_in_flight_sharded.iterator_to(*i);
    sdata->ops_in_flight_sharded.erase(p);
  }

4. `OSD::get_health_metrics` jumps in between the update and the locking.

vector<DaemonHealthMetric> OSD::get_health_metrics()
{
  vector<DaemonHealthMetric> metrics;
  {
    // ...
    TrackedOpRef oldest_op;
    auto count_slow_ops = [&](TrackedOp& op) {
      // ...
      oldest_op = &op;
      // ...
    };
    if (op_tracker.visit_ops_in_flight(&oldest_secs, count_slow_ops)) {
      // ...
    }
  }

5. Assigning to `oldest_op` triggers the `TrackedOp::get()`/`TrackedOp::put()` pair, and thus `OpTracker::unregister_inflight_op` can be executed second time for same op while another call is in progress. This is dangerous as `boost::intrusive::list::iterator_to` must not be called on an object that doesn't belong to a given list instance (because e.g. it was erased earlier):

Requires: value must be a reference to a value inserted in a list.

#6 Updated by Radoslaw Zarzynski about 1 year ago

  • Status changed from New to In Progress

#7 Updated by Sage Weil about 1 year ago

related?

2018-05-18T03:29:21.427 INFO:tasks.ceph.mon.a.ovh098.stderr:*** Caught signal (Bus error) **
2018-05-18T03:29:21.427 INFO:tasks.ceph.mon.a.ovh098.stderr: in thread 7f60d12de700 thread_name:OpHistorySvc
2018-05-18T03:29:21.427 INFO:tasks.ceph.mon.a.ovh098.stderr: ceph version 13.1.0-129-gd3a3371 (d3a3371798df3316c173c967bc5300119f20cd22) mimic (rc)
2018-05-18T03:29:21.427 INFO:tasks.ceph.mon.a.ovh098.stderr: 1: (()+0x4b4120) [0x5619e499a120]
2018-05-18T03:29:21.427 INFO:tasks.ceph.mon.a.ovh098.stderr: 2: (()+0x11390) [0x7f60d8900390]
2018-05-18T03:29:21.428 INFO:tasks.ceph.mon.a.ovh098.stderr: 3: (RefCountedObject::put() const+0xb8) [0x5619e4791828]
2018-05-18T03:29:21.428 INFO:tasks.ceph.mon.a.ovh098.stderr: 4: (MonOpRequest::~MonOpRequest()+0x32) [0x5619e4791b22]
2018-05-18T03:29:21.428 INFO:tasks.ceph.mon.a.ovh098.stderr: 5: (std::_Rb_tree<std::pair<double, boost::intrusive_ptr<TrackedOp> >, std::pair<double, boost::intrusive_ptr<TrackedOp> >, std::_Identity<std::pair<double, boost::intrusive_ptr<TrackedOp> > >, std::less<std::pair<double, boost::intrusive_ptr<TrackedOp> > >, std::allocator<std::pair<double, boost::intrusive_ptr<TrackedOp> > > >::_M_erase_aux(std::_Rb_tree_const_iterator<std::pair<double, boost::intrusive_ptr<TrackedOp> > >)+0x83) [0x7f60d9014f83]
2018-05-18T03:29:21.428 INFO:tasks.ceph.mon.a.ovh098.stderr: 6: (OpHistory::cleanup(utime_t)+0x2b4) [0x7f60d9011c04]
2018-05-18T03:29:21.428 INFO:tasks.ceph.mon.a.ovh098.stderr: 7: (OpHistory::_insert_delayed(utime_t const&, boost::intrusive_ptr<TrackedOp>)+0x20c) [0x7f60d901258c]
2018-05-18T03:29:21.428 INFO:tasks.ceph.mon.a.ovh098.stderr: 8: (OpHistoryServiceThread::entry()+0xe9) [0x7f60d9012969]
2018-05-18T03:29:21.428 INFO:tasks.ceph.mon.a.ovh098.stderr: 9: (()+0x76ba) [0x7f60d88f66ba]
2018-05-18T03:29:21.428 INFO:tasks.ceph.mon.a.ovh098.stderr: 10: (clone()+0x6d) [0x7f60d7c5441d]
2018-05-18T03:29:21.428 INFO:tasks.ceph.mon.a.ovh098.stderr:2018-05-18 03:29:21.404 7f60d12de700 -1 *** Caught signal (Bus error) **
2018-05-18T03:29:21.428 INFO:tasks.ceph.mon.a.ovh098.stderr: in thread 7f60d12de700 thread_name:OpHistorySvc

/a/teuthology-2018-05-18_02:25:02-upgrade:luminous-x-mimic-distro-basic-ovh/2545544

#8 Updated by Radoslaw Zarzynski about 1 year ago

  • Status changed from In Progress to Need Review

#9 Updated by Sage Weil about 1 year ago

  • Backport set to mimic

#10 Updated by Sage Weil about 1 year ago

  • Status changed from Need Review to Pending Backport

#11 Updated by Nathan Cutler about 1 year ago

  • Copied to Backport #24256: mimic: osd: Assertion `!node_algorithms::inited(this->priv_value_traits().to_node_ptr(value))' failed. added

#12 Updated by Sage Weil about 1 year ago

  • Status changed from Pending Backport to Resolved

#13 Updated by Brad Hubbard about 1 year ago

  • Related to Bug #23352: osd: segfaults under normal operation added

#14 Updated by Brad Hubbard about 1 year ago

  • Related to Bug #24664: osd: crash in OpTracker::unregister_inflight_op via OSD::get_health_metrics added

Also available in: Atom PDF