Ceph » RADOS

Hi Greg,

Thank you for taking the time to look into this.

Following the incident of the present ticket the cluster was upgraded to Kraken. We then had a further issue (http://tracker.ceph.com/issues/19824).

I believe my colleague Ross was given a hint in IRC the the problem could be stale/inconsistent metadata in a pool. We then recreated the pools and all has been good since. Hope this makes sense.

So, as far as our cluster is concerned all is good now. However, with the pointer that some bad pool metadata may have triggered this it may be good idea to come get to the bottom of this in the interest of ceph stability.

The fact that the error stopped when cinder was stopped makes me thing this was related to in-flight requests from those services. Maybe two racing pool snap updates were interfering?

I've got a cluster here where this issue is 100% reproducible when trying to delete snapshots. Let me know if we can do/test anything to help debug this.

Still happening on 12.2.4

    -9> 2018-02-27 09:44:28.558861 7f721f786700  1 -- 10.255.0.30:6789/0 <== client.3417026 10.255.0.52:0/2767607806 5 ==== pool_op(delete unmanaged snap pool 6 auid 0 tid 17 name  v0) v4 ==== 65+0+0 (3863449434 0 0) 0x55b72b5bb680 con 0x55b72b586000
    -8> 2018-02-27 09:44:28.558868 7f721f786700 20 mon.ceph-dal-mon-a1@0(leader) e1 _ms_dispatch existing session 0x55b72bcf5d80 for client.3417026 10.255.0.52:0/2767607806
    -7> 2018-02-27 09:44:28.558884 7f721f786700 20 mon.ceph-dal-mon-a1@0(leader) e1  caps profile rbd
    -6> 2018-02-27 09:44:28.558887 7f721f786700  5 mon.ceph-dal-mon-a1@0(leader).paxos(paxos writing c 6153015..6153739) is_readable = 1 - now=2018-02-27 09:44:28.558887 lease_expire=2018-02-27 09:44:32.953713 has v0 lc 6153739
    -5> 2018-02-27 09:44:28.558894 7f721f786700 10 mon.ceph-dal-mon-a1@0(leader).osd e24190 preprocess_query pool_op(delete unmanaged snap pool 6 auid 0 tid 17 name  v0) v4 from client.3417026 10.255.0.52:0/2767607806
    -4> 2018-02-27 09:44:28.558908 7f721f786700  7 mon.ceph-dal-mon-a1@0(leader).osd e24190 prepare_update pool_op(delete unmanaged snap pool 6 auid 0 tid 17 name  v0) v4 from client.3417026 10.255.0.52:0/2767607806
    -3> 2018-02-27 09:44:28.558915 7f721f786700 10 mon.ceph-dal-mon-a1@0(leader).osd e24190 prepare_pool_op pool_op(delete unmanaged snap pool 6 auid 0 tid 17 name  v0) v4
    -2> 2018-02-27 09:44:28.562240 7f721f786700 -1 /home/jenkins-build/build/workspace/ceph-build/ARCH/x86_64/AVAILABLE_ARCH/x86_64/AVAILABLE_DIST/centos7/DIST/centos7/MACHINE_SIZE/huge/release/12.2.4/rpm/el7/BUILD/ceph-12.2.4/src/include/interval_set.h: In function 'void interval_set<T>::insert(T, T, T*, T*) [with T = snapid_t]' thread 7f721f786700 time 2018-02-27 09:44:28.558926
/home/jenkins-build/build/workspace/ceph-build/ARCH/x86_64/AVAILABLE_ARCH/x86_64/AVAILABLE_DIST/centos7/DIST/centos7/MACHINE_SIZE/huge/release/12.2.4/rpm/el7/BUILD/ceph-12.2.4/src/include/interval_set.h: 396: FAILED assert(p->first > start+len)

 ceph version 12.2.4 (52085d5249a80c5f5121a76d6288429f35e4e77b) luminous (stable)
 1: (ceph::__ceph_assert_fail(char const*, char const*, int, char const*)+0x110) [0x55b7209a0470]
 2: (interval_set<snapid_t>::insert(snapid_t, snapid_t, snapid_t*, snapid_t*)+0x32b) [0x55b720ae91ab]
 3: (pg_pool_t::remove_unmanaged_snap(snapid_t)+0x4d) [0x55b720ad65ed]
 4: (OSDMonitor::prepare_pool_op(boost::intrusive_ptr<MonOpRequest>)+0xe40) [0x55b7208cb4a0]
 5: (OSDMonitor::prepare_update(boost::intrusive_ptr<MonOpRequest>)+0x33e) [0x55b720902f0e]
 6: (PaxosService::dispatch(boost::intrusive_ptr<MonOpRequest>)+0xaf8) [0x55b72088f6a8]
 7: (Monitor::dispatch_op(boost::intrusive_ptr<MonOpRequest>)+0x5af) [0x55b72076fc9f]
 8: (Monitor::_ms_dispatch(Message*)+0x7eb) [0x55b72077128b]
 9: (Monitor::ms_dispatch(Message*)+0x23) [0x55b72079d3f3]
 10: (DispatchQueue::entry()+0x792) [0x55b720c4fd92]
 11: (DispatchQueue::DispatchThread::entry()+0xd) [0x55b720a477fd]
 12: (()+0x7e25) [0x7f722898fe25]
 13: (clone()+0x6d) [0x7f7225b0734d]
 NOTE: a copy of the executable, or `objdump -rdS <executable>` is needed to interpret this.

To summarize what I've figured out to reproduce this:

• both rbd client and mon are running 12.2.4, happened with 12.2.2 as well
• crashes when running "rbd snap rm" on some snapshots
• seen it happen on two different clusters, multiple different snapshots trigger this
• things that the clusters and snapshots have in common: the crashing images are based on a non-flattened clone in an erasure-coded pool

The OpenStack test referenced in the original description also seems to be using an image with a parent.

Well, turns out there were both 12.2.1 and 12.2.4 clients doing snapshot operations. This messed up removed_snaps due to issue #21567 with data_pool handling in the librbd snapshot functionality.

So my bug is different from this issue originally described here since it predates data_pool.

Anyways, the only place where this can happen is if snap_seq < max(removed_snaps) because the deletion request inserts two elements into removed_snaps but only checks the precondition for one insert. The precondition for the second one will be violated if anyone ever sent a snap delete request for a snap id larger than snap_seq (which shouldn't be allowed).

I've fixed both of this in https://github.com/ceph/ceph/pull/20835