Deadlock after receiving a "N5realm10LogicErrorE: Bad version number " #4768

tbaranes · 2017-03-24T09:50:16Z

May be a duplicate / follow up of #4428 and #4649

Goals

Just using Realm.

Expected Results

No bugs, no freeze, no warnings.

Actual Results

I'm getting this using Realm v2.4.4, but I got a customer getting that same freeze using v2.0.4, so I was wrong when I was saying that issue was introduced after 2.0.4 (cf the previous issue).

The app is freezing after logging "N5realm10LogicErrorE: Bad version number".
Looks like a deadlock (since the audio is still playing, just the interface won't respond anymore)

Here the full stack trace from Xcode when the app has entered in the deadlock:

* thread #1: tid = 0x14ac3, 0x000000018f6cae1c libsystem_kernel.dylib`__psynch_cvwait + 8, queue = 'com.apple.main-thread', stop reason = signal SIGSTOP
  * frame #0: 0x000000018f6cae1c libsystem_kernel.dylib`__psynch_cvwait + 8
    frame #1: 0x000000018f7909c0 libsystem_pthread.dylib`_pthread_cond_wait + 640
    frame #2: 0x000000018f0b93ec libc++.1.dylib`std::__1::condition_variable::wait(std::__1::unique_lock<std::__1::mutex>&) + 56
    frame #3: 0x0000000101e629f4 Realm`realm::_impl::NotifierPackage::package_and_wait(realm::util::Optional<unsigned long long>) [inlined] void std::__1::condition_variable::wait<std::__1::unique_lock<std::__1::mutex> realm::_impl::RealmCoordinator::wait_for_notifiers<realm::_impl::NotifierPackage::package_and_wait(realm::util::Optional<unsigned long long>)::$_12>(realm::_impl::NotifierPackage::package_and_wait(realm::util::Optional<unsigned long long>)::$_12&&)::'lambda'()>(this=<unavailable>, __pred=<unavailable>)::$_12) + 204 at __mutex_base:345 [opt]
    frame #4: 0x0000000101e62988 Realm`realm::_impl::NotifierPackage::package_and_wait(realm::util::Optional<unsigned long long>) [inlined] std::__1::unique_lock<std::__1::mutex> realm::_impl::RealmCoordinator::wait_for_notifiers<realm::_impl::NotifierPackage::package_and_wait(this=<unavailable>)::$_12>(realm::_impl::NotifierPackage::package_and_wait(realm::util::Optional<unsigned long long>)::$_12&&) + 32 at realm_coordinator.hpp:175 [opt]
    frame #5: 0x0000000101e62968 Realm`realm::_impl::NotifierPackage::package_and_wait(this=<unavailable>, target_version=<unavailable>) + 64 at collection_notifier.cpp:422 [opt]
    frame #6: 0x0000000101f4c124 Realm`(anonymous namespace)::KVOTransactLogObserver::parse_complete(this=<unavailable>) + 1208 at transact_log_handler.cpp:639 [opt]
    frame #7: 0x0000000101f4b024 Realm`bool realm::SharedGroup::do_advance_read<(anonymous namespace)::KVOTransactLogObserver>(this=<unavailable>, observer=<unavailable>, version_id=<unavailable>, hist=<unavailable>)::KVOTransactLogObserver*, realm::VersionID, realm::_impl::History&) + 300 at group_shared.hpp:1058 [opt]
    frame #8: 0x0000000101f4214c Realm`realm::_impl::transaction::begin(std::__1::unique_ptr<realm::SharedGroup, std::__1::default_delete<realm::SharedGroup> > const&, realm::BindingContext*, realm::_impl::NotifierPackage&) + 72 at group_shared.hpp:960 [opt]
    frame #9: 0x0000000101f42104 Realm`realm::_impl::transaction::begin(std::__1::unique_ptr<realm::SharedGroup, std::__1::default_delete<realm::SharedGroup> > const&, realm::BindingContext*, realm::_impl::NotifierPackage&) [inlined] void realm::_impl::SharedGroupFriend::promote_to_write<(anonymous namespace)::KVOTransactLogObserver>(sg=0x00000001058a3600)::KVOTransactLogObserver*) at group_shared.hpp:1120 [opt]
    frame #10: 0x0000000101f42104 Realm`realm::_impl::transaction::begin(std::__1::unique_ptr<realm::SharedGroup, std::__1::default_delete<realm::SharedGroup> > const&, realm::BindingContext*, realm::_impl::NotifierPackage&) [inlined] void realm::LangBindHelper::promote_to_write<(anonymous namespace)::KVOTransactLogObserver>(sg=0x00000001058a3600)::KVOTransactLogObserver&&) at lang_bind_helper.hpp:349 [opt]
    frame #11: 0x0000000101f42104 Realm`realm::_impl::transaction::begin(std::__1::unique_ptr<realm::SharedGroup, std::__1::default_delete<realm::SharedGroup> > const&, realm::BindingContext*, realm::_impl::NotifierPackage&) [inlined] auto realm::_impl::transaction::begin(std::__1::unique_ptr<realm::SharedGroup, std::__1::default_delete<realm::SharedGroup> > const&, realm::BindingContext*, realm::_impl::NotifierPackage&)::$_1::operator()<(anonymous namespace)::KVOTransactLogObserver>((anonymous namespace)::KVOTransactLogObserver&&) const + 4 at transact_log_handler.cpp:706 [opt]
    frame #12: 0x0000000101f42100 Realm`realm::_impl::transaction::begin(std::__1::unique_ptr<realm::SharedGroup, std::__1::default_delete<realm::SharedGroup> > const&, realm::BindingContext*, realm::_impl::NotifierPackage&) [inlined] void (anonymous namespace)::advance_with_notifications<realm::_impl::transaction::begin(context=<unavailable>, sg=0x0000000104c52298)::$_1>(realm::BindingContext*, std::__1::unique_ptr<realm::SharedGroup, std::__1::default_delete<realm::SharedGroup> > const&, realm::_impl::transaction::begin(std::__1::unique_ptr<realm::SharedGroup, std::__1::default_delete<realm::SharedGroup> > const&, realm::BindingContext*, realm::_impl::NotifierPackage&)::$_1&&, realm::_impl::NotifierPackage&) + 476 at transact_log_handler.cpp:674 [opt]
    frame #13: 0x0000000101f41f24 Realm`realm::_impl::transaction::begin(sg=0x0000000104c52298, context=<unavailable>, notifiers=0x000000016fd294f0) + 40 at transact_log_handler.cpp:705 [opt]
    frame #14: 0x0000000101e7f7ac Realm`realm::_impl::RealmCoordinator::promote_to_write(this=0x0000000104c1a6b8, realm=<unavailable>) + 148 at realm_coordinator.cpp:777 [opt]
    frame #15: 0x0000000101f2db44 Realm`realm::Realm::begin_transaction(this=0x0000000104c521a8) + 168 at shared_realm.cpp:458 [opt]
    frame #16: 0x0000000101f111e0 Realm`::-[RLMRealm beginWriteTransaction](self=<unavailable>, _cmd=<unavailable>) + 28 at RLMRealm.mm:443 [opt]
    frame #17: 0x0000000101f114d8 Realm`::-[RLMRealm transactionWithBlock:error:](self=0x00000001740bf380, _cmd=<unavailable>, block=<unavailable>, outError=0x0000000000000000)(), NSError **) + 52 at RLMRealm.mm:488 [opt]
    frame #18: 0x0000000101f1149c Realm`::-[RLMRealm transactionWithBlock:](self=<unavailable>, _cmd=<unavailable>, block=<unavailable>)()) + 24 at RLMRealm.mm:484 [opt]
    frame #19: 0x0000000101b96624 ****`-[**** ****:](self=0x00000001702267e0, _cmd="****:", idx=0) + 268 at ****.m:291
    frame #20: 0x0000000101b97140 ****`-[**** ****](self=0x00000001702267e0, _cmd="****") + 76 at ****.m:332
    frame #21: 0x0000000101b927a4 ****`-[**** ****](self=0x00000001702267e0, _cmd="****") + 40 at ****.m:62
    frame #22: 0x00000001001000a4 ****`-[**** ****:](self=0x00000001058ade00, _cmd="****:", sender=0x00000001058e3000) + 112 at ****:284
    frame #23: 0x00000001965e7d30 UIKit`-[UIApplication sendAction:to:from:forEvent:] + 96
    frame #24: 0x00000001965e7cb0 UIKit`-[UIControl sendAction:to:forEvent:] + 80
    frame #25: 0x00000001965d2128 UIKit`-[UIControl _sendActionsForEvents:withEvent:] + 452
    frame #26: 0x00000001965e759c UIKit`-[UIControl touchesEnded:withEvent:] + 584
    frame #27: 0x00000001965e70c4 UIKit`-[UIWindow _sendTouchesForEvent:] + 2484
    frame #28: 0x00000001965e2328 UIKit`-[UIWindow sendEvent:] + 2988
    frame #29: 0x00000001965b2da0 UIKit`-[UIApplication sendEvent:] + 340
    frame #30: 0x0000000196d9c75c UIKit`__dispatchPreprocessedEventFromEventQueue + 2736
    frame #31: 0x0000000196d96130 UIKit`__handleEventQueue + 784
    frame #32: 0x00000001906aab5c CoreFoundation`__CFRUNLOOP_IS_CALLING_OUT_TO_A_SOURCE0_PERFORM_FUNCTION__ + 24
    frame #33: 0x00000001906aa4a4 CoreFoundation`__CFRunLoopDoSources0 + 524
    frame #34: 0x00000001906a80a4 CoreFoundation`__CFRunLoopRun + 804
    frame #35: 0x00000001905d62b8 CoreFoundation`CFRunLoopRunSpecific + 444
    frame #36: 0x000000019208a198 GraphicsServices`GSEventRunModal + 180
    frame #37: 0x000000019661d7fc UIKit`-[UIApplication _run] + 684
    frame #38: 0x0000000196618534 UIKit`UIApplicationMain + 208
    frame #39: 0x00000001002050b4 ****`main + 140 at AppDelegate.swift:21
    frame #40: 0x000000018f5b95b8 libdyld.dylib`start + 4

I replaced the app symbols by **** because I can't post it in public. However, I can share the full stack by email if that help.

Steps to Reproduce

Once again, I don't have an easy way to reproduce it. It's a global environment issue: having a few realm transactions running at the same time, after a few more, it will freeze.
In this context, my realm is storing around 50k objects, not sure if that can change something.

Code Sample

Sadly, don't have one... but I will try right now to make a sample project reproducing that issue since I have a better idea of the context.

Version of Realm and Tooling

Realm version: 2.4.4

Xcode version: 8.2.1

iOS/OSX version: iOS 10.2.1

Dependency manager + version: Carthage 0.20.1

The text was updated successfully, but these errors were encountered:

tbaranes · 2017-03-24T10:26:31Z

More input: it seems that I'm able to reproduce it only when I have a few dozens of objects in Realm, and only if I'm doing live updates on realm objects (meaning for example synchronising a full catalog of song, so the object state will changed every few seconds).

If don't have a large database, and doing these real time changes, I can't reproduce it. So, it's probably a different case than #4428 since it was reproductible without these both conditions.

tbaranes · 2017-03-24T10:50:49Z

More input: I can also reproduce it by firing manual realm transaction (by clicking on buttons in the app), it seems to freeze when two transactions are starting / ending at the same time, race condition?

I started a sample app beside, but no luck for now. So, I'm able to tell you how to reproduce it, but I can tell you if a fix is working or no 😬

TimOliver · 2017-03-24T20:03:43Z

Hi @tbaranes! Thanks for the info! Sorry to hear you're having some trouble here.

There's probably not a lot we can do without a sample app to let us properly examine what's going on here. Would you even be able to post some sample code of the actual write transaction that's causing this failure? You can email it to help@realm.io if you need to keep it private.

Thanks!

tbaranes · 2017-03-29T09:47:29Z

Sorry for the delay @TimOliver, I just sent an email with more information and a few lines of code, hope that helps.

Also, I tried v4.5.0, but the bug is still here (no miracle here 😬 )

tgoyne · 2017-03-30T01:01:12Z

Hanging forever in beginWriteTransaction or refresh after an error occurs on the notification worker thread is expected, as it's waiting for the notification worker to finish its current set of work and that'll never happen. As a result, the state of things when the actual freeze happens isn't very interesting; it's what leads to the LogicError(bad_version) being thrown that matters.

The stack trace when the exception is thrown might be somewhat informative, if you can enable exception breakpoints in Xcode and then trigger the problem.

tbaranes · 2017-03-30T07:56:07Z

@tgoyne Here the stack trace when he exception is thrown (and caught by exception breakpoints):

Realm was compiled with optimization - stepping may behave oddly; variables may not be available.
* thread #21, name = 'RLMRealm notification listener', stop reason = breakpoint 1.1
    frame #0: 0x000000018f122efc libc++abi.dylib`__cxa_throw
  * frame #1: 0x0000000101ebda7c Realm`void realm::LangBindHelper::advance_read<(anonymous namespace)::TransactLogValidator>(realm::SharedGroup&, (anonymous namespace)::TransactLogValidator&&, realm::VersionID) [inlined] void realm::SharedGroup::advance_read<(anonymous namespace)::TransactLogValidator>(this=<unavailable>)::TransactLogValidator*, realm::VersionID) at group_shared.hpp:934 [opt]
    frame #2: 0x0000000101ebd9b0 Realm`void realm::LangBindHelper::advance_read<(anonymous namespace)::TransactLogValidator>(realm::SharedGroup&, (anonymous namespace)::TransactLogValidator&&, realm::VersionID) [inlined] void realm::_impl::SharedGroupFriend::advance_read<(anonymous namespace)::TransactLogValidator>(sg=<unavailable>)::TransactLogValidator*, realm::VersionID) at group_shared.hpp:1114 [opt]
    frame #3: 0x0000000101ebd9b0 Realm`void realm::LangBindHelper::advance_read<(anonymous namespace)::TransactLogValidator>(sg=<unavailable>, observer=<unavailable>, version=<unavailable>)::TransactLogValidator&&, realm::VersionID) at lang_bind_helper.hpp:335 [opt]
    frame #4: 0x0000000101ebd984 Realm`realm::_impl::transaction::advance(sg=<unavailable>, (null)=<unavailable>, version=<unavailable>) at transact_log_handler.cpp:688 [opt]
    frame #5: 0x0000000101dfbc90 Realm`realm::_impl::RealmCoordinator::run_async_notifiers(this=0x000000011de55a48) at realm_coordinator.cpp:652 [opt]
    frame #6: 0x0000000101dfb764 Realm`realm::_impl::RealmCoordinator::on_change(this=0x000000011de55a48) at realm_coordinator.cpp:463 [opt]
    frame #7: 0x0000000101de2d80 Realm`realm::_impl::ExternalCommitHelper::listen(this=0x0000000170241e90) at external_commit_helper.cpp:217 [opt]
    frame #8: 0x0000000101de3e4c Realm`std::__1::__async_func<realm::_impl::ExternalCommitHelper::ExternalCommitHelper(realm::_impl::RealmCoordinator&)::$_0>::operator()() [inlined] realm::_impl::ExternalCommitHelper::ExternalCommitHelper(realm::_impl::RealmCoordinator&)::$_0::operator()() const at external_commit_helper.cpp:159 [opt]
    frame #9: 0x0000000101de3e48 Realm`std::__1::__async_func<realm::_impl::ExternalCommitHelper::ExternalCommitHelper(realm::_impl::RealmCoordinator&)::$_0>::operator()() [inlined] std::__1::__invoke<realm::_impl::ExternalCommitHelper::ExternalCommitHelper(realm::_impl::RealmCoordinator&)::$_0>(decltype(std::__1::forward<realm::_impl::ExternalCommitHelper::ExternalCommitHelper(realm::_impl::RealmCoordinator&)::$_0>(fp)(std::__1::forward<>(fp0))), realm::_impl::ExternalCommitHelper::ExternalCommitHelper(realm::_impl::RealmCoordinator&)::$_0&&) at __functional_base:416 [opt]
    frame #10: 0x0000000101de3e44 Realm`std::__1::__async_func<realm::_impl::ExternalCommitHelper::ExternalCommitHelper(realm::_impl::RealmCoordinator&)::$_0>::operator()() [inlined] _ZNSt3__112__async_funcIZN5realm5_impl20ExternalCommitHelperC1ERNS2_16RealmCoordinatorEE3$_0JEE9__executeIJEEEvNS_15__tuple_indicesIJXspT_EEEE(this=<unavailable>) at future:2348 [opt]
    frame #11: 0x0000000101de3e44 Realm`std::__1::__async_func<realm::_impl::ExternalCommitHelper::ExternalCommitHelper(realm::_impl::RealmCoordinator&)::$_0>::operator(this=<unavailable>)() at future:2341 [opt]
    frame #12: 0x0000000101de3dd4 Realm`std::__1::__async_assoc_state<void, std::__1::__async_func<realm::_impl::ExternalCommitHelper::ExternalCommitHelper(realm::_impl::RealmCoordinator&)::$_0> >::__execute(this=0x000000017012e6a0) at future:1031 [opt]
    frame #13: 0x0000000101de3f98 Realm`std::__1::__thread_proxy<std::__1::tuple<void (std::__1::__async_assoc_state<void, std::__1::__async_func<realm::_impl::ExternalCommitHelper::ExternalCommitHelper(realm::_impl::RealmCoordinator&)::$_0> >::*)(), std::__1::__async_assoc_state<void, std::__1::__async_func<realm::_impl::ExternalCommitHelper::ExternalCommitHelper(realm::_impl::RealmCoordinator&)::$_0> >*> >(void*, void*) [inlined] std::__1::__invoke<void (std::__1::__async_assoc_state<void, std::__1::__async_func<realm::_impl::ExternalCommitHelper::ExternalCommitHelper(realm::_impl::RealmCoordinator&)::$_0> >::*)(), std::__1::__async_assoc_state<void, std::__1::__async_func<realm::_impl::ExternalCommitHelper::ExternalCommitHelper(realm::_impl::RealmCoordinator&)::$_0> >*, void>(decltype(*(std::__1::forward<std::__1::__async_assoc_state<void, std::__1::__async_func<realm::_impl::ExternalCommitHelper::ExternalCommitHelper(realm::_impl::RealmCoordinator&)::$_0> >*>(fp0)).*fp(std::__1::forward<>(fp1))), void (std::__1::__async_assoc_state<void, std::__1::__async_func<realm::_impl::ExternalCommitHelper::ExternalCommitHelper(realm::_impl::RealmCoordinator&)::$_0> >::*&&)(), std::__1::__async_assoc_state<void, std::__1::__async_func<realm::_impl::ExternalCommitHelper::ExternalCommitHelper(realm::_impl::RealmCoordinator&)::$_0> >*&&) at __functional_base:383 [opt]
    frame #14: 0x0000000101de3f7c Realm`std::__1::__thread_proxy<std::__1::tuple<void (std::__1::__async_assoc_state<void, std::__1::__async_func<realm::_impl::ExternalCommitHelper::ExternalCommitHelper(realm::_impl::RealmCoordinator&)::$_0> >::*)(), std::__1::__async_assoc_state<void, std::__1::__async_func<realm::_impl::ExternalCommitHelper::ExternalCommitHelper(realm::_impl::RealmCoordinator&)::$_0> >*> >(void*, void*) [inlined] _ZNSt3__116__thread_executeIMNS_19__async_assoc_stateIvNS_12__async_funcIZN5realm5_impl20ExternalCommitHelperC1ERNS4_16RealmCoordinatorEE3$_0JEEEEEFvvEJPSA_EJLm1EEEEvRNS_5tupleIJT_DpT0_EEENS_15__tuple_indicesIJXspT1_EEEE at thread:347 [opt]
    frame #15: 0x0000000101de3f7c Realm`std::__1::__thread_proxy<std::__1::tuple<void (std::__1::__async_assoc_state<void, std::__1::__async_func<realm::_impl::ExternalCommitHelper::ExternalCommitHelper(realm::_impl::RealmCoordinator&)::$_0> >::*)(), std::__1::__async_assoc_state<void, std::__1::__async_func<realm::_impl::ExternalCommitHelper::ExternalCommitHelper(realm::_impl::RealmCoordinator&)::$_0> >*> >(__vp=0x0000000170220480) at thread:357 [opt]
    frame #16: 0x000000018f791850 libsystem_pthread.dylib`_pthread_body + 240
    frame #17: 0x000000018f791760 libsystem_pthread.dylib`_pthread_start + 284
    frame #18: 0x000000018f78ed94 libsystem_pthread.dylib`thread_start + 4

realm/realm-swift#4768 realm/realm-java#4369 When m_notifiers is empty, m_notifier_sg will be advanced to the latest. But the skip_version might be behind. In this case, bad_version will be throw when calling advance_to_final().

* Fix bad_version when m_notifiers is empty realm/realm-swift#4768 realm/realm-java#4369 When m_notifiers is empty, m_notifier_sg will be advanced to the latest. But the skip_version might be behind. In this case, bad_version will be throw when calling advance_to_final(). * Add a test which reproduces the problem

tgoyne · 2017-03-31T17:52:14Z

This should be fixed by realm/realm-object-store#424.

tbaranes · 2017-03-31T20:46:27Z

Good to know! Let me know when it will be available in realm-cocoa, I will test it again. Also, is realm-object-store embed in realm-cocoa even if we are not using it?

tbaranes · 2017-04-04T08:09:57Z

Since #4813 has been merged, I tested the master version, seems to be fixed! Thanks 🤘

jpsim · 2017-04-04T15:49:28Z

Glad to hear it!

austinzheng added the T-Help label Mar 24, 2017

TimOliver added the S:Waiting For User label Mar 24, 2017

realm-ci removed the S:Waiting For User label Mar 29, 2017

kishikawakatsumi assigned tgoyne Mar 29, 2017

kishikawakatsumi added the S:Waiting For User label Mar 30, 2017

realm-ci removed the S:Waiting For User label Mar 30, 2017

beeender mentioned this issue Mar 31, 2017

Fix bad_version when m_notifiers is empty realm/realm-object-store#424

Merged

jpsim added S:In Progress T-Bug and removed T-Help labels Mar 31, 2017

jpsim mentioned this issue Apr 3, 2017

update Object Store #4813

Merged

jpsim added S:Review and removed S:In Progress labels Apr 3, 2017

jpsim mentioned this issue Apr 3, 2017

Bad version number in Realm 2.5.0 (Swift) #4802

Closed

tbaranes closed this as completed Apr 4, 2017

alazier removed the S:Review label Apr 4, 2017

weibel mentioned this issue Jun 2, 2017

Deadlock on beginWriteTransaction #4896

Closed

github-actions bot locked as resolved and limited conversation to collaborators Mar 16, 2024

Provide feedback

Saved searches

Use saved searches to filter your results more quickly

Deadlock after receiving a "N5realm10LogicErrorE: Bad version number " #4768

Deadlock after receiving a "N5realm10LogicErrorE: Bad version number " #4768

tbaranes commented Mar 24, 2017 •

edited by kishikawakatsumi

Loading

tbaranes commented Mar 24, 2017

tbaranes commented Mar 24, 2017 •

edited

Loading

TimOliver commented Mar 24, 2017

tbaranes commented Mar 29, 2017 •

edited

Loading

tgoyne commented Mar 30, 2017

tbaranes commented Mar 30, 2017 •

edited

Loading

tgoyne commented Mar 31, 2017

tbaranes commented Mar 31, 2017

tbaranes commented Apr 4, 2017

jpsim commented Apr 4, 2017

Deadlock after receiving a "N5realm10LogicErrorE: Bad version number " #4768

Deadlock after receiving a "N5realm10LogicErrorE: Bad version number " #4768

Comments

tbaranes commented Mar 24, 2017 • edited by kishikawakatsumi Loading

Goals

Expected Results

Actual Results

Steps to Reproduce

Code Sample

Version of Realm and Tooling

tbaranes commented Mar 24, 2017

tbaranes commented Mar 24, 2017 • edited Loading

TimOliver commented Mar 24, 2017

tbaranes commented Mar 29, 2017 • edited Loading

tgoyne commented Mar 30, 2017

tbaranes commented Mar 30, 2017 • edited Loading

tgoyne commented Mar 31, 2017

tbaranes commented Mar 31, 2017

tbaranes commented Apr 4, 2017

jpsim commented Apr 4, 2017

tbaranes commented Mar 24, 2017 •

edited by kishikawakatsumi

Loading

tbaranes commented Mar 24, 2017 •

edited

Loading

tbaranes commented Mar 29, 2017 •

edited

Loading

tbaranes commented Mar 30, 2017 •

edited

Loading