Bug #38724: _txc_add_transaction error (39) Directory not empty not handled on operation 21 (op 1, counting from 0) - RADOS - Ceph

Copied to Backport #39693: nautilus: _txc_add_transaction error (39) Directory not empty not handled on operation 21 (op 1, counting from 0) added

Actions

Copy link

#10

Updated by Nathan Cutler almost 5 years ago

Copied to Backport #39694: luminous: _txc_add_transaction error (39) Directory not empty not handled on operation 21 (op 1, counting from 0) added

Actions

Copy link

#11

Updated by Igor Fedotov almost 5 years ago

Has duplicate Bug #40642: Bluestore crash due to mass activation on another pool added

Actions

Copy link

#12

Updated by Edward Kalk almost 5 years ago

We have hit this as well, it was triggered when I rebooted a node. A few OSD on other hosts crashed. Here's some log:
Jul 08 16:00:54 synergy0 ceph-osd⁴⁴⁶⁸²: 2019-07-08 16:00:54.962 7fe236221700 -1 bluestore(/var/lib/ceph/osd/ceph-12) txc_add_transaction error (39) Directory not empty not handled on operation 21 (op 1, counting from 0)
Jul 08 16:00:54 synergy0 ceph-osd⁴⁴⁶⁸²: /build/ceph-14.2.1/src/os/bluestore/BlueStore.cc: In function 'void BlueStore::_txc_add_transaction(BlueStore::TransContext*, ObjectStore::Transaction*)' thread 7fe236221700 time 2019-07-08 16:00:54.965119
Jul 08 16:00:54 synergy0 ceph-osd⁴⁴⁶⁸²: /build/ceph-14.2.1/src/os/bluestore/BlueStore.cc: 11089: abort()
Jul 08 16:00:54 synergy0 ceph-osd⁴⁴⁶⁸²: ceph version 14.2.1 (d555a9489eb35f84f2e1ef49b77e19da9d113972) nautilus (stable)
Jul 08 16:00:54 synergy0 ceph-osd⁴⁴⁶⁸²: 1: (ceph::_ceph_abort(char const*, int, char const*, std::__cxx11::basic_string<char, std::char_traits<char>, std::allocator<char> > const&)+0xda) [0x850a01]
Jul 08 16:00:54 synergy0 ceph-osd⁴⁴⁶⁸²: 2: (BlueStore::_txc_add_transaction(BlueStore::TransContext*, ObjectStore::Transaction*)+0x296a) [0xe44a2a]
Jul 08 16:00:54 synergy0 ceph-osd⁴⁴⁶⁸²: 3: (BlueStore::queue_transactions(boost::intrusive_ptr<ObjectStore::CollectionImpl>&, std::vector<ObjectStore::Transaction, std::allocator<ObjectStore::Transaction> >&, boost::intrusive_ptr<TrackedOp>, ThreadPool::TPHandle*)+0x5e6) [0xe48f96]
Jul 08 16:00:54 synergy0 ceph-osd⁴⁴⁶⁸²: 4: (ObjectStore::queue_transaction(boost::intrusive_ptr<ObjectStore::CollectionImpl>&, ObjectStore::Transaction&&, boost::intrusive_ptr<TrackedOp>, ThreadPool::TPHandle*)+0x7f) [0xa0099f]
Jul 08 16:00:54 synergy0 ceph-osd⁴⁴⁶⁸²: 5: (PG::_delete_some(ObjectStore::Transaction*)+0x710) [0xa64b30]
Jul 08 16:00:54 synergy0 ceph-osd⁴⁴⁶⁸²: 6: (PG::RecoveryState::Deleting::react(PG::DeleteSome const&)+0x71) [0xa658f1]
Jul 08 16:00:54 synergy0 ceph-osd⁴⁴⁶⁸²: 7: (boost::statechart::simple_state<PG::RecoveryState::Deleting, PG::RecoveryState::ToDelete, boost::mpl::list<mpl_::na, mpl_::na, mpl_::na, mpl_::na, mpl_::na, mpl_::na, mpl_::na, mpl_::na, mpl_::na, mpl_::na, mpl_::na, mpl_::na, mpl_::na, mpl_::na, mpl_::na, mpl_::na, mpl_::na, mpl_::na, mpl_::na, mpl_::na>, (boost::statechart::history_mode)0>::react_impl(boost::statechart::event_base const&, void const*)+0x131) [0xaaf151]
Jul 08 16:00:54 synergy0 ceph-osd⁴⁴⁶⁸²: 8: (boost::statechart::state_machine<PG::RecoveryState::RecoveryMachine, PG::RecoveryState::Initial, std::allocator<void>, boost::statechart::null_exception_translator>::process_event(boost::statechart::event_base const&)+0x6b) [0xa82b0b]
Jul 08 16:00:54 synergy0 ceph-osd⁴⁴⁶⁸²: 9: (PG::do_peering_event(std::shared_ptr<PGPeeringEvent>, PG::RecoveryCtx*)+0x122) [0xa72052]
Jul 08 16:00:54 synergy0 ceph-osd⁴⁴⁶⁸²: 10: (OSD::dequeue_peering_evt(OSDShard*, PG*, std::shared_ptr<PGPeeringEvent>, ThreadPool::TPHandle&)+0x1b4) [0x9ac6a4]
Jul 08 16:00:54 synergy0 ceph-osd⁴⁴⁶⁸²: 11: (OSD::dequeue_delete(OSDShard*, PG*, unsigned int, ThreadPool::TPHandle&)+0xd2) [0x9ac982]
Jul 08 16:00:54 synergy0 ceph-osd⁴⁴⁶⁸²: 12: (OSD::ShardedOpWQ::_process(unsigned int, ceph::heartbeat_handle_d*)+0xbed) [0x9a07dd]
Jul 08 16:00:54 synergy0 ceph-osd⁴⁴⁶⁸²: 13: (ShardedThreadPool::shardedthreadpool_worker(unsigned int)+0x4ac) [0xfc37bc]
Jul 08 16:00:54 synergy0 ceph-osd⁴⁴⁶⁸²: 14: (ShardedThreadPool::WorkThreadSharded::entry()+0x10) [0xfc6970]
Jul 08 16:00:54 synergy0 ceph-osd⁴⁴⁶⁸²: 15: (()+0x76ba) [0x7fe2557446ba]
Jul 08 16:00:54 synergy0 ceph-osd⁴⁴⁶⁸²: 16: (clone()+0x6d) [0x7fe254d4b41d]
Jul 08 16:00:54 synergy0 ceph-osd⁴⁴⁶⁸²: 2019-07-08 16:00:54.974 7fe236221700 -1 /build/ceph-14.2.1/src/os/bluestore/BlueStore.cc: In function 'void BlueStore::_txc_add_transaction(BlueStore::TransContext*, ObjectStore::Transaction*)' thread 7fe236221700 time 2019-07-08 16:00:54.965119
Jul 08 16:00:54 synergy0 ceph-osd⁴⁴⁶⁸²: /build/ceph-14.2.1/src/os/bluestore/BlueStore.cc: 11089: abort()
Jul 08 16:00:54 synergy0 ceph-osd⁴⁴⁶⁸²: ceph version 14.2.1 (d555a9489eb35f84f2e1ef49b77e19da9d113972) nautilus (stable)
Jul 08 16:00:54 synergy0 ceph-osd⁴⁴⁶⁸²: 1: (ceph::__ceph_abort(char const*, int, char const*, std::__cxx11::basic_string<char, std::char_traits<char>, std::allocator<char> > const&)+0xda) [0x850a01]
Jul 08 16:00:54 synergy0 ceph-osd⁴⁴⁶⁸²: 2: (BlueStore::_txc_add_transaction(BlueStore::TransContext*, ObjectStore::Transaction*)+0x296a) [0xe44a2a]
Jul 08 16:00:54 synergy0 ceph-osd⁴⁴⁶⁸²: 3: (BlueStore::queue_transactions(boost::intrusive_ptr<ObjectStore::CollectionImpl>&, std::vector<ObjectStore::Transaction, std::allocator<ObjectStore::Transaction> >&, boost::intrusive_ptr<TrackedOp>, ThreadPool::TPHandle*)+0x5e6) [0xe48f96]
Jul 08 16:00:54 synergy0 ceph-osd⁴⁴⁶⁸²: 4: (ObjectStore::queue_transaction(boost::intrusive_ptr<ObjectStore::CollectionImpl>&, ObjectStore::Transaction&&, boost::intrusive_ptr<TrackedOp>, ThreadPool::TPHandle*)+0x7f) [0xa0099f]
Jul 08 16:00:54 synergy0 ceph-osd⁴⁴⁶⁸²: 5: (PG::_delete_some(ObjectStore::Transaction*)+0x710) [0xa64b30]
Jul 08 16:00:54 synergy0 ceph-osd⁴⁴⁶⁸²: 6: (PG::RecoveryState::Deleting::react(PG::DeleteSome const&)+0x71) [0xa658f1]
Jul 08 16:00:54 synergy0 ceph-osd⁴⁴⁶⁸²: 7: (boost::statechart::simple_state<PG::RecoveryState::Deleting, PG::RecoveryState::ToDelete, boost::mpl::list<mpl_::na, mpl_::na, mpl_::na, mpl_::na, mpl_::na, mpl_::na, mpl_::na, mpl_::na, mpl_::na, mpl_::na, mpl_::na, mpl_::na, mpl_::na, mpl_::na, mpl_::na, mpl_::na, mpl_::na, mpl_::na, mpl_::na, mpl_::na>, (boost::statechart::history_mode)0>::react_impl(boost::statechart::event_base const&, void const*)+0x131) [0xaaf151]
Jul 08 16:00:54 synergy0 ceph-osd⁴⁴⁶⁸²: 8: (boost::statechart::state_machine<PG::RecoveryState::RecoveryMachine, PG::RecoveryState::Initial, std::allocator<void>, boost::statechart::null_exception_translator>::process_event(boost::statechart::event_base const&)+0x6b) [0xa82b0b]
Jul 08 16:00:54 synergy0 ceph-osd⁴⁴⁶⁸²: 9: (PG::do_peering_event(std::shared_ptr<PGPeeringEvent>, PG::RecoveryCtx*)+0x122) [0xa72052]
Jul 08 16:00:54 synergy0 ceph-osd⁴⁴⁶⁸²: 10: (OSD::dequeue_peering_evt(OSDShard*, PG*, std::shared_ptr<PGPeeringEvent>, ThreadPool::TPHandle&)+0x1b4) [0x9ac6a4]
Jul 08 16:00:54 synergy0 ceph-osd⁴⁴⁶⁸²: 11: (OSD::dequeue_delete(OSDShard*, PG*, unsigned int, ThreadPool::TPHandle&)+0xd2) [0x9ac982]
Jul 08 16:00:54 synergy0 ceph-osd⁴⁴⁶⁸²: 12: (OSD::ShardedOpWQ::_process(unsigned int, ceph::heartbeat_handle_d*)+0xbed) [0x9a07dd]
Jul 08 16:00:54 synergy0 ceph-osd⁴⁴⁶⁸²: 13: (ShardedThreadPool::shardedthreadpool_worker(unsigned int)+0x4ac) [0xfc37bc]
Jul 08 16:00:54 synergy0 ceph-osd⁴⁴⁶⁸²: 14: (ShardedThreadPool::WorkThreadSharded::entry()+0x10) [0xfc6970]
Jul 08 16:00:54 synergy0 ceph-osd⁴⁴⁶⁸²: 15: (()+0x76ba) [0x7fe2557446ba]
Jul 08 16:00:54 synergy0 ceph-osd⁴⁴⁶⁸²: 16: (clone()+0x6d) [0x7fe254d4b41d]
Jul 08 16:00:54 synergy0 ceph-osd⁴⁴⁶⁸²: * Caught signal (Aborted) *
Jul 08 16:00:54 synergy0 ceph-osd⁴⁴⁶⁸²: in thread 7fe236221700 thread_name:tp_osd_tp
Jul 08 16:00:54 synergy0 ceph-osd⁴⁴⁶⁸²: ceph version 14.2.1 (d555a9489eb35f84f2e1ef49b77e19da9d113972) nautilus (stable)
Jul 08 16:00:54 synergy0 ceph-osd⁴⁴⁶⁸²: 1: (()+0x11390) [0x7fe25574e390]
Jul 08 16:00:54 synergy0 ceph-osd⁴⁴⁶⁸²: 2: (gsignal()+0x38) [0x7fe254c79428]
Jul 08 16:00:54 synergy0 ceph-osd⁴⁴⁶⁸²: 3: (abort()+0x16a) [0x7fe254c7b02a]
Jul 08 16:00:54 synergy0 ceph-osd⁴⁴⁶⁸²: 4: (ceph::__ceph_abort(char const, int, char const*, std::__cxx11::basic_string<char, std::char_traits<char>, std::allocator<char> > const&)+0x1a0) [0x850ac7]
Jul 08 16:00:54 synergy0 ceph-osd⁴⁴⁶⁸²: 5: (BlueStore::_txc_add_transaction(BlueStore::TransContext*, ObjectStore::Transaction*)+0x296a) [0xe44a2a]
Jul 08 16:00:54 synergy0 ceph-osd⁴⁴⁶⁸²: 6: (BlueStore::queue_transactions(boost::intrusive_ptr<ObjectStore::CollectionImpl>&, std::vector<ObjectStore::Transaction, std::allocator<ObjectStore::Transaction> >&, boost::intrusive_ptr<TrackedOp>, ThreadPool::TPHandle*)+0x5e6) [0xe48f96]
Jul 08 16:00:54 synergy0 ceph-osd⁴⁴⁶⁸²: 7: (ObjectStore::queue_transaction(boost::intrusive_ptr<ObjectStore::CollectionImpl>&, ObjectStore::Transaction&&, boost::intrusive_ptr<TrackedOp>, ThreadPool::TPHandle*)+0x7f) [0xa0099f]
Jul 08 16:00:54 synergy0 ceph-osd⁴⁴⁶⁸²: 8: (PG::_delete_some(ObjectStore::Transaction*)+0x710) [0xa64b30]
Jul 08 16:00:54 synergy0 ceph-osd⁴⁴⁶⁸²: 9: (PG::RecoveryState::Deleting::react(PG::DeleteSome const&)+0x71) [0xa658f1]
Jul 08 16:00:54 synergy0 ceph-osd⁴⁴⁶⁸²: 10: (boost::statechart::simple_state<PG::RecoveryState::Deleting, PG::RecoveryState::ToDelete, boost::mpl::list<mpl_::na, mpl_::na, mpl_::na, mpl_::na, mpl_::na, mpl_::na, mpl_::na, mpl_::na, mpl_::na, mpl_::na, mpl_::na, mpl_::na, mpl_::na, mpl_::na, mpl_::na, mpl_::na, mpl_::na, mpl_::na, mpl_::na, mpl_::na>, (boost::statechart::history_mode)0>::react_impl(boost::statechart::event_base const&, void const*)+0x131) [0xaaf151]
Jul 08 16:00:54 synergy0 ceph-osd⁴⁴⁶⁸²: 11: (boost::statechart::state_machine<PG::RecoveryState::RecoveryMachine, PG::RecoveryState::Initial, std::allocator<void>, boost::statechart::null_exception_translator>::process_event(boost::statechart::event_base const&)+0x6b) [0xa82b0b]
Jul 08 16:00:54 synergy0 ceph-osd⁴⁴⁶⁸²: 12: (PG::do_peering_event(std::shared_ptr<PGPeeringEvent>, PG::RecoveryCtx*)+0x122) [0xa72052]
Jul 08 16:00:54 synergy0 ceph-osd⁴⁴⁶⁸²: 13: (OSD::dequeue_peering_evt(OSDShard*, PG*, std::shared_ptr<PGPeeringEvent>, ThreadPool::TPHandle&)+0x1b4) [0x9ac6a4]
Jul 08 16:00:54 synergy0 ceph-osd⁴⁴⁶⁸²: 14: (OSD::dequeue_delete(OSDShard*, PG*, unsigned int, ThreadPool::TPHandle&)+0xd2) [0x9ac982]
Jul 08 16:00:54 synergy0 ceph-osd⁴⁴⁶⁸²: 15: (OSD::ShardedOpWQ::_process(unsigned int, ceph::heartbeat_handle_d*)+0xbed) [0x9a07dd]
Jul 08 16:00:54 synergy0 ceph-osd⁴⁴⁶⁸²: 16: (ShardedThreadPool::shardedthreadpool_worker(unsigned int)+0x4ac) [0xfc37bc]
Jul 08 16:00:54 synergy0 ceph-osd⁴⁴⁶⁸²: 17: (ShardedThreadPool::WorkThreadSharded::entry()+0x10) [0xfc6970]
Jul 08 16:00:54 synergy0 ceph-osd⁴⁴⁶⁸²: 18: (()+0x76ba) [0x7fe2557446ba]
Jul 08 16:00:54 synergy0 ceph-osd⁴⁴⁶⁸²: 19: (clone()+0x6d) [0x7fe254d4b41d]
Jul 08 16:00:54 synergy0 ceph-osd⁴⁴⁶⁸²: 2019-07-08 16:00:54.986 7fe236221700 -1 Caught signal (Aborted) *
Jul 08 16:00:54 synergy0 ceph-osd⁴⁴⁶⁸²: in thread 7fe236221700 thread_name:tp_osd_tp
Jul 08 16:00:54 synergy0 ceph-osd⁴⁴⁶⁸²: ceph version 14.2.1 (d555a9489eb35f84f2e1ef49b77e19da9d113972) nautilus (stable)
Jul 08 16:00:54 synergy0 ceph-osd⁴⁴⁶⁸²: 1: (()+0x11390) [0x7fe25574e390]
Jul 08 16:00:54 synergy0 ceph-osd⁴⁴⁶⁸²: 2: (gsignal()+0x38) [0x7fe254c79428]
Jul 08 16:00:54 synergy0 ceph-osd⁴⁴⁶⁸²: 3: (abort()+0x16a) [0x7fe254c7b02a]
Jul 08 16:00:54 synergy0 ceph-osd⁴⁴⁶⁸²: 4: (ceph::__ceph_abort(char const*, int, char const*, std::__cxx11::basic_string<char, std::char_traits<char>, std::allocator<char> > const&)+0x1a0) [0x850ac7]
Jul 08 16:00:54 synergy0 ceph-osd⁴⁴⁶⁸²: 5: (BlueStore::_txc_add_transaction(BlueStore::TransContext*, ObjectStore::Transaction*)+0x296a) [0xe44a2a]
Jul 08 16:00:54 synergy0 ceph-osd⁴⁴⁶⁸²: 6: (BlueStore::queue_transactions(boost::intrusive_ptr<ObjectStore::CollectionImpl>&, std::vector<ObjectStore::Transaction, std::allocator<ObjectStore::Transaction> >&, boost::intrusive_ptr<TrackedOp>, ThreadPool::TPHandle*)+0x5e6) [0xe48f96]
Jul 08 16:00:54 synergy0 ceph-osd⁴⁴⁶⁸²: 7: (ObjectStore::queue_transaction(boost::intrusive_ptr<ObjectStore::CollectionImpl>&, ObjectStore::Transaction&&, boost::intrusive_ptr<TrackedOp>, ThreadPool::TPHandle*)+0x7f) [0xa0099f]
Jul 08 16:00:54 synergy0 ceph-osd⁴⁴⁶⁸²: 8: (PG::_delete_some(ObjectStore::Transaction*)+0x710) [0xa64b30]
Jul 08 16:00:54 synergy0 ceph-osd⁴⁴⁶⁸²: 9: (PG::RecoveryState::Deleting::react(PG::DeleteSome const&)+0x71) [0xa658f1]
Jul 08 16:00:54 synergy0 ceph-osd⁴⁴⁶⁸²: 10: (boost::statechart::simple_state<PG::RecoveryState::Deleting, PG::RecoveryState::ToDelete, boost::mpl::list<mpl_::na, mpl_::na, mpl_::na, mpl_::na, mpl_::na, mpl_::na, mpl_::na, mpl_::na, mpl_::na, mpl_::na, mpl_::na, mpl_::na, mpl_::na, mpl_::na, mpl_::na, mpl_::na, mpl_::na, mpl_::na, mpl_::na, mpl_::na>, (boost::statechart::history_mode)0>::react_impl(boost::statechart::event_base const&...

Actions

Copy link

#13

Updated by Edward Kalk almost 5 years ago

I am confused by the "Copied to RADOS - Backport #39693: nautilus" status. "Pending Backport 07/03/2019"
Does this mean it has been fixed and there is a patch or? Is there a workaround or code change I can insert?

Actions

Copy link

#14

Updated by Edward Kalk almost 5 years ago

will this be included in : https://tracker.ceph.com/projects/ceph/roadmap#v14.2.2 . ?

Actions

Copy link Download all files

#15

Updated by Edward Kalk almost 5 years ago

File ceph-osd.5.clippedtoupload.log ceph-osd.5.clippedtoupload.log added
File ceph-osd.21.clippedtoupload.log ceph-osd.21.clippedtoupload.log added

We hit this bug again : "2019-07-10 09:16:27.728 7f73b844c700 -1 bluestore(/var/lib/ceph/osd/ceph-5) _txc_add_transaction error (39) Directory not empty not handled on operation 21"
This time it triggered when I added a OSD to a node.
Logs attached.

Actions

Copy link

#16

Updated by Edward Kalk almost 5 years ago

found a few things that seem like fixes for this on github... : https://github.com/ceph/ceph/pull/27929/commits

Actions

Copy link

#17

Updated by Edward Kalk almost 5 years ago

OSD 9, 15, 10, 13 crashed this AM.
```ceph.log:2019-07-11 09:15:15.501601 mon.synergy0 (mon.0) 4248 : cluster [INF] osd.10 [v2:216.106.44.201:6802/25418,v1:216.106.44.201:6803/25418] boot
ceph.log:2019-07-11 09:15:20.561861 mon.synergy0 (mon.0) 4257 : cluster [INF] osd.13 [v2:216.106.44.201:6818/25427,v1:216.106.44.201:6820/25427] boot
ceph.log:2019-07-11 09:15:23.620936 mon.synergy0 (mon.0) 4263 : cluster [INF] osd.15 [v2:216.106.44.200:6802/17179,v1:216.106.44.200:6803/17179] boot
ceph.log:2019-07-11 09:15:39.440562 mon.synergy0 (mon.0) 4277 : cluster [INF] osd.9 [v2:216.106.44.200:6814/17315,v1:216.106.44.200:6815/17315] boot```

Actions

Copy link

#18

Updated by Edward Kalk almost 5 years ago

Was Bug 38724:
```ceph-osd.9.log: -3> 2019-07-11 09:15:13.569 7fc7b8243700 -1 bluestore(/var/lib/ceph/osd/ceph-9) _txc_add_transaction error (39) Directory not empty not handled on operation 21 (op 1, counting from 0)
ceph-osd.15.log:2019-07-11 09:15:08.593 7fbe46b8b700 -1 bluestore(/var/lib/ceph/osd/ceph-15) _txc_add_transaction error (39) Directory not empty not handled on operation 21 (op 1, counting from 0)
ceph-osd.13.log:2019-07-11 09:15:08.627 7fc575850700 -1 bluestore(/var/lib/ceph/osd/ceph-13) _txc_add_transaction error (39) Directory not empty not handled on operation 21 (op 1, counting from 0)
ceph-osd.10.log:2019-07-11 09:15:08.543 7f0ef2a03700 -1 bluestore(/var/lib/ceph/osd/ceph-10) _txc_add_transaction error (39) Directory not empty not handled on operation 21 (op 1, counting from 0)```

We are 14.2.1 on Ubuntu 16.04

Actions

Copy link

#19

Updated by Edward Kalk almost 5 years ago

Sometimes when this happens, the OSDs repeatedly crash and Linux system prevents them from being started. it takes 10 minuets for linux to allow them to start again. (too many start attempts)
15:24:13 synergy0 systemd¹: ceph-osd@12.service: Start request repeated too quickly.
Jul 08 15:24:13 synergy0 systemd¹: Failed to start Ceph object storage daemon osd.12.

Actions

Copy link

#20

Updated by Edward Kalk almost 5 years ago

^^this results in the Production VMs becoming unresponsive as their disks are unavailable when we have multiple OSDs down on multiple hosts. (we are doing 2 copy) I've seen it where 3 OSDs are down at the same time on different hosts due to this bug. That's when we are seemingly really un lucky with the BUG. (3 copy would not have saved us from that)

Actions

Copy link

#21

Updated by Edward Kalk almost 5 years ago

File osd 10 will not start 07112019.txt osd 10 will not start 07112019.txt added

Rebooted node 4, on node 1 and 2, 2 OSDs each crashed and will not start.
The logs are similar, seems to be the BUG related to 38724
Tried to manually start the OSDs, failed. It’s been about 20 minuets with prod down.

Actions

Copy link

#22

Updated by Nathan Fish almost 5 years ago

Edward Kalk wrote:

Sometimes when this happens, the OSDs repeatedly crash and Linux system prevents them from being started. it takes 10 minuets for linux to allow them to start again. (too many start attempts)
15:24:13 synergy0 systemd¹: ceph-osd@12.service: Start request repeated too quickly.
Jul 08 15:24:13 synergy0 systemd¹: Failed to start Ceph object storage daemon osd.12.

General systemd tip: you can reset the failure limit with 'systemctl reset-failed'. Then you can 'systemctl restart ceph-osd@12'.

Actions

Copy link

#23

Updated by Nathan Fish almost 5 years ago

It seems this will be in 14.2.3. When the fix comes out, will my crashed OSDs work again, or should I just purge and recreate them now?

Actions

Copy link

#24

Updated by Nathan Fish almost 5 years ago

Just lost another OSD on 14.2.2. The cluster is still mostly empty, but a large parallel cp is going on, so rebuild will take a while. This is somewhat worrying. Any update on this?

Actions

Copy link

#25

Updated by Nathan Fish almost 5 years ago

That OSD failure seems to have caused a cascade. Several more OSDs have crashed. 12% of objects were degraded, and I had to create new 'ssd' class OSDs to get enough failure domains. I cancelled the cp to prioritize recovery. Is there any workaround to repair the OSDs and get them to restart properly? They just crash again every time I restart them.

Can this bug please be set to a higher priority? This has caused an outage for myself and Edward above, and threatens data loss. That warrants at least Major.

Actions

Copy link

#26

Updated by Florian Haas over 4 years ago

Affected Versions v12.2.12 added

So we're seeing a similar error after upgrading a Jewel cluster to Luminous (12.2.12), and then adding BlueStore OSDs to it:

    -3> 2019-08-09 11:17:04.772976 7fb41585d700 -1 bluestore(/var/lib/ceph/osd/ceph-78) _txc_add_transaction error (7) Argument list too long not handled on operation 12 (op 2, counting from 0)
    -2> 2019-08-09 11:17:04.772993 7fb41585d700 -1 bluestore(/var/lib/ceph/osd/ceph-78) unexpected error code
    -1> 2019-08-09 11:17:04.773013 7fb41585d700  0 bluestore(/var/lib/ceph/osd/ceph-78)  transaction dump:
{
    "ops": [
        {
            "op_num": 0,
            "op_name": "remove",
            "collection": "2.293_head",
            "oid": "#-4:c96337db:::temp_recovering_2.293_11123'6472830_288833_head:head#" 
        },
        {
            "op_num": 1,
            "op_name": "touch",
            "collection": "2.293_head",
            "oid": "#-4:c96337db:::temp_recovering_2.293_11123'6472830_288833_head:head#" 
        },
        {
            "op_num": 2,
            "op_name": "truncate",
            "collection": "2.293_head",
            "oid": "#-4:c96337db:::temp_recovering_2.293_11123'6472830_288833_head:head#",
            "offset": 4457615932
        },
        {
            "op_num": 3,
            "op_name": "op_setallochint",
            "collection": "2.293_head",
            "oid": "#-4:c96337db:::temp_recovering_2.293_11123'6472830_288833_head:head#",
            "expected_object_size": "0",
            "expected_write_size": "0" 
        },
        {
            "op_num": 4,
            "op_name": "write",
            "collection": "2.293_head",
            "oid": "#-4:c96337db:::temp_recovering_2.293_11123'6472830_288833_head:head#",
            "length": 8388608,
            "offset": 0,
            "bufferlist length": 8388608
        },
        {
            "op_num": 5,
            "op_name": "setattrs",
            "collection": "2.293_head",
            "oid": "#-4:c96337db:::temp_recovering_2.293_11123'6472830_288833_head:head#",
            "attr_lens": {
                "_": 254,
                "snapset": 31
            }
        }
    ]
}

In our case, that's an E2BIG as opposed to ENOTEMPTY, but it does look awfully similar, at least superficially.

Actions

Copy link

#27

Updated by Sage Weil over 4 years ago

Florian Haas wrote:

So we're seeing a similar error after upgrading a Jewel cluster to Luminous (12.2.12), and then adding BlueStore OSDs to it:

[...]

In our case, that's an E2BIG as opposed to ENOTEMPTY, but it does look awfully similar, at least superficially.

BlueStore returns E2BIG because the object is > 4GB, which is not supported (size is stored in an u32). This cluster has some big rados objects.

Actions

Copy link

#28

Updated by Brad Hubbard over 4 years ago

Priority changed from Normal to High

Bumping priority based on community feedback.

Actions

Copy link

#29

Updated by Nathan Cutler over 3 years ago

Status changed from Pending Backport to Resolved

While running with --resolve-parent, the script "backport-create-issue" noticed that all backports of this issue are in status "Resolved" or "Rejected".

ceph-osd.5.clippedtoupload.log (77.4 KB) ceph-osd.5.clippedtoupload.log	OSD 5 crashed	Edward Kalk, 07/10/2019 02:46 PM
ceph-osd.21.clippedtoupload.log (17.7 KB) ceph-osd.21.clippedtoupload.log	OSD 21 crashed	Edward Kalk, 07/10/2019 02:49 PM
osd 10 will not start 07112019.txt (222 KB) osd 10 will not start 07112019.txt		Edward Kalk, 07/11/2019 04:39 PM

Project

General

Profile

Ceph » RADOS

Custom queries

Bug #38724

_txc_add_transaction error (39) Directory not empty not handled on operation 21 (op 1, counting from 0)

Updated by Sage Weil about 5 years ago

Updated by Sage Weil about 5 years ago

Updated by Greg Farnum about 5 years ago

Updated by Sage Weil about 5 years ago

Updated by Sage Weil about 5 years ago

Updated by Lenz Grimmer almost 5 years ago

Updated by Sage Weil almost 5 years ago

Updated by Nathan Cutler almost 5 years ago

Updated by Nathan Cutler almost 5 years ago

Updated by Nathan Cutler almost 5 years ago

Updated by Igor Fedotov almost 5 years ago

Updated by Edward Kalk almost 5 years ago

Updated by Edward Kalk almost 5 years ago

Updated by Edward Kalk almost 5 years ago

Updated by Edward Kalk almost 5 years ago

Updated by Edward Kalk almost 5 years ago

Updated by Edward Kalk almost 5 years ago

Updated by Edward Kalk almost 5 years ago

Updated by Edward Kalk almost 5 years ago

Updated by Edward Kalk almost 5 years ago

Updated by Edward Kalk almost 5 years ago

Updated by Nathan Fish almost 5 years ago

Updated by Nathan Fish almost 5 years ago

Updated by Nathan Fish almost 5 years ago

Updated by Nathan Fish almost 5 years ago

Updated by Florian Haas over 4 years ago

Updated by Sage Weil over 4 years ago

Updated by Brad Hubbard over 4 years ago

Updated by Nathan Cutler over 3 years ago