Realm-cocoa: Dead lock while beginWiteTransaction() starting

[tbaranes]

Goals

What do you want to achieve?

Just using Realm as usual 😬

Expected Results

No dead lock

Actual Results

While using the app, it will freeze randomly. When I pause the app in Xcode, I have the following stack which seems to be a dead lock:

The writeTransaction will never end, so we have to restart the app to unlock it. we never get that bug using Realm 2.1.0.

Steps to Reproduce

I have no idea... we get it randomly while using it. The stack is always the same even if the transaction is started elsewhere.

Code Sample

:(

Version of Realm and Tooling

In the CONTRIBUTING guidelines, you will find a script,
which will help determining these versions.

Realm version: ? 2.1.1

Xcode version: ? 8.1

iOS/OSX version: ? iOS 10.1.1 (tested only on iPad Pro)

Dependency manager + version: ? Carthage 0.18.1

I will try to get more information next week.

[jpsim]

Thanks for reporting this! I have a small favor to ask for future bug reports: could you please include the backtrace for unexpected exceptions or crashes in textual format? That will make it easier for other users and the Realm team to search for related issues.

In this case, I don't think we're aware of a deadlock regression as you describe, so hopefully you can provide more information this week as you've stated, and then we can take a closer look at this.

[tbaranes]

I have a small favor to ask for future bug reports: could you please include the backtrace for unexpected exceptions or crashes in textual format?

Sure. Here it is (should I edit my first post?):

* thread #1: tid = 0x1730ec, 0x0000000187675e1c libsystem_kernel.dylib`__psynch_cvwait + 8, queue = 'com.apple.main-thread', stop reason = signal SIGSTOP
    frame #0: 0x0000000187675e1c libsystem_kernel.dylib`__psynch_cvwait + 8
    frame #1: 0x000000018773b9c0 libsystem_pthread.dylib`_pthread_cond_wait + 640
    frame #2: 0x00000001870653ec libc++.1.dylib`std::__1::condition_variable::wait(std::__1::unique_lock<std::__1::mutex>&) + 56
    frame #3: 0x0000000101b04af8 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>)::$_11>(realm::_impl::NotifierPackage::package_and_wait(realm::util::Optional<unsigned long long>)::$_11&&)::'lambda'()>(this=<unavailable>, __pred=<unavailable>)::$_11) + 204 at __mutex_base:345 [opt]
    frame #4: 0x0000000101b04a8c 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>)::$_11>(realm::_impl::NotifierPackage::package_and_wait(realm::util::Optional<unsigned long long>)::$_11&&) + 32 at realm_coordinator.hpp:170 [opt]
    frame #5: 0x0000000101b04a6c Realm`realm::_impl::NotifierPackage::package_and_wait(this=<unavailable>, target_version=<unavailable>) + 64 at collection_notifier.cpp:415 [opt]
    frame #6: 0x0000000101bd7958 Realm`realm::_impl::transaction::begin(realm::SharedGroup&, realm::BindingContext*, realm::SchemaMode, realm::_impl::NotifierPackage&) [inlined] (anonymous namespace)::TransactLogObserver::TransactLogObserver<realm::_impl::transaction::begin(this=0x000000016fda9438, context=<unavailable>, sg=0x00000001260c2000, notifiers=<unavailable>)::$_2>(realm::BindingContext*, realm::SharedGroup&, realm::_impl::transaction::begin(realm::SharedGroup&, realm::BindingContext*, realm::SchemaMode, realm::_impl::NotifierPackage&)::$_2&&, realm::util::Optional<realm::SchemaMode>, realm::_impl::NotifierPackage&) + 608 at transact_log_handler.cpp:291 [opt]
    frame #7: 0x0000000101bd76f8 Realm`realm::_impl::transaction::begin(realm::SharedGroup&, realm::BindingContext*, realm::SchemaMode, realm::_impl::NotifierPackage&) [inlined] (anonymous namespace)::TransactLogObserver::TransactLogObserver<realm::_impl::transaction::begin(context=<unavailable>, sg=0x00000001260c2000, notifiers=<unavailable>)::$_2>(realm::BindingContext*, realm::SharedGroup&, realm::_impl::transaction::begin(realm::SharedGroup&, realm::BindingContext*, realm::SchemaMode, realm::_impl::NotifierPackage&)::$_2&&, realm::util::Optional<realm::SchemaMode>, realm::_impl::NotifierPackage&) at transact_log_handler.cpp:262 [opt]
    frame #8: 0x0000000101bd76f8 Realm`realm::_impl::transaction::begin(sg=0x00000001260c2000, context=<unavailable>, schema_mode=<unavailable>, notifiers=<unavailable>) + 52 at transact_log_handler.cpp:842 [opt]
    frame #9: 0x0000000101b1ff88 Realm`realm::_impl::RealmCoordinator::promote_to_write(this=<unavailable>, realm=0x0000000125d38f68) + 152 at realm_coordinator.cpp:710 [opt]
    frame #10: 0x0000000101bd2ee8 Realm`realm::Realm::begin_transaction(this=0x0000000125d38f68) + 152 at shared_realm.cpp:467 [opt]
    frame #11: 0x0000000101bb1e2c Realm`::-[RLMRealm beginWriteTransaction](self=<unavailable>, _cmd=<unavailable>) + 28 at RLMRealm.mm:435 [opt]
    frame #12: 0x0000000101bb2124 Realm`::-[RLMRealm transactionWithBlock:error:](self=0x00000001700bd760, _cmd=<unavailable>, block=<unavailable>, outError=0x0000000000000000)(), NSError **) + 52 at RLMRealm.mm:480 [opt]
  * frame #13: 0x0000000101bb20e8 Realm`::-[RLMRealm transactionWithBlock:](self=<unavailable>, _cmd=<unavailable>, block=<unavailable>)()) + 24 at RLMRealm.mm:476 [opt]

As said in my first comment, I got that stack by pausing Xcode (then using bt in the console).

Also, I discover that we have the same warning as #4422 just before freezing (systematically):

uncaught exception in notifier thread: N5realm10LogicErrorE: Bad version number
2016-12-14 10:55:02.500177 Project[2943:1521182] uncaught exception in notifier thread: N5realm10LogicErrorE: Bad version number

Also, we don't reproduce it on simulator, and in the mac app. Only on real iOS device.

EDIT: Just reproduce it using 2.1.0, but it seems harder to trigger.

[kishikawakatsumi]

We'd love to address this, but to make progress we'll likely need a sample project that reproduces this issue. Can anyone who's experienced this provide us with steps to trigger?

[TimOliver]

@tbaranes Can you please try updating to Realm 2.1.1 and trying there? Additionally, if we can get a reproducible code sample, that would be really helpful for us. Thanks!

[kirtiparghi]

I am also facing that below uncaught exception,

uncaught exception in notifier thread: N5realm10LogicErrorE: Bad version number

Realm version: ? 2.1.2

Xcode version: ? 8.2.1

[tbaranes]

@TimOliver Sorry, I missed your answer. We are already using 2.1.1, nothing changed. Sadly, we still have no tips how to reproduce it... for now, we rollback to 2.0.4 which didn't have that issue. I will try to get more information next week, but it seems to be a mysterious bug.

[tbaranes]

I still have no information to add (completely random...), but just tried realm 2.2.0, the issue is still here.

[tbaranes]

2.4.0 seems to fix that issue, still not sure what happened, thanks anyway!
Closing this now, I will let you know if I get it back.

[tbaranes]

Reopening this, it's not completely fix. It's definitely better than the previous version, harder to reproduce, but we still got a few freeze randomly after ~10min usage. Sadly, we still have no information to share in order to reproduce it, it's completely random...

For now, we rollback to 2.0.4 😢

[semireg]

We are affected by this deadlock.

[semireg]

We can reproduce this in a single VC of our app. It seems realm needs to be under some load. The offender seems to be RLMNotificationToken's stop(). I can trigger it because we start/stop notifications based on viewWillAppear/viewWillDisappear. If I remove the call to stop() it doesn't crash ... yet.

[tgoyne]

Any chance you'd be able to extract the relevant parts of that VC into a standalone repro case?

If you're okay with privately sharing the full project with us you could also send it to [email protected] along with whatever information we need to hit the problem.

[semireg]

TLDR: Make sure that the object (collection) that generates a RLMNotificationToken via addNotificationBlock are not deallocated before stop is called on the token.

We think we might have a cause/solution for our crash. I don't know if this will be a fix for the other cases - but it might point you in the right direction.

Our code was being lazy about the creation of a collection.

override func liveRealmObjects() -> RLMResults<RLMObject>? {
        guard let realm = SemiSensorManager.sharedSSKRealm(), let reading = reading else { return nil }
        return reading.realmReading(in: realm)?.recordings.sortedResults(usingKeyPath: "timestamp", ascending: false)
    }

Then we'd have this Obj-C superclass setting up the notifications on a collection object that has no strong reference. At the end of this method the collection is deallocated:

-(void)startRealmNotifications
{
    id<RLMCollection> collection = [self notificationCollection]; // Just returned liveRealmObjects() by default
    if(_realmToken == nil && (collection != nil))
    {
        __weak RealmTableViewController *weakSelf = self;

        _realmToken = [collection addNotificationBlock:^(RLMResults *results, RLMCollectionChange *change, NSError *error) {
            if (error) {
                NSLog(@"Failed to open Realm on background worker: %@", error);
                return;
            }

            [weakSelf collectionChangedWithResults:results change:change];
        }];
    }
}

To "fix" this we made sure the collection was being cached in the subclass, but this could move to the superclass as well. Just offering this bit of code because we're hastily working on a workaround:

    override func notificationCollection() -> RLMCollection? {
        if(cachedCollection == nil) {
            cachedCollection = liveRealmObjects()
        }
        return cachedCollection
    }

And then something small, too:

    override func notificationsEnabled(_ enabled: Bool) {
        super.notificationsEnabled(enabled)
        if(!enabled) {
            cachedCollection = nil
        }
    }

Let us know if this helps! It seems to be holding water for us.

[jpsim]

Thanks for sharing that info @semireg! Although I still don't think that's enough for us to reproduce this, so I'll mark this as "waiting for user" again. Please do try to send us a more complete repro case if you can.

[luna-kx]

Hi @semireg. Just echoing @jpsim's request. Would you be able to provide more information?

[semireg]

Due to time constraints and the app being a client project I will not be able to send a complete repro case.

If I needed to reproduce on a fresh project I would create a simple database schema with basic relationships and have a queue that constantly created, updated and deleted objects and updated relationships on background threads. This would put some stress on the database.

Then, I would have a VC that creates a realm notification via RLMNotificationToken in viewWillAppear/viewWillDisappear. Try to set up the notification using a collection generated using sortedResults(usingKeyPath: "timestamp", ascending: false), or similar, and DO NOT hold a reference to this collection. These results should come from a relationship on an object. Let the collection be temporary and get deallocated. Then, put this VC in a tab bar with another tab so you can quickly switch between the tabs using your thumbs. This will quickly trigger the VC appearance methods.

Good luck!

[tbaranes]

Just tried the fix of @semireg, but that doesn't change anything in our case, but I'm joining him to say that the issue is around from the RLMRealmNotification. I can't go in details since I'm not able to reproduce it (still random), but I'm almost sure that if I remove the notification, it should work (the action done before the deadlock are triggering the notification).

I'm gonna try to remove the notification subscription to check if that change anything, I will let you know if I have new information.

[luna-kx]

Okay @semireg - thanks for the summary.

[luna-kx]

And awesome, @tbaranes. I'll add the waiting for user tag and please share anything you find when you get a chance. :)

[tbaranes]

After one week of internal testing, we don't reproduce that deadlock anymore. So, in conclusion:

• The issue is definitely from the realm notification even if I have no way to reproduce it, neither any explanation. It's probably a rare case with a special context
• I will stick with that new flow instead of notifications since it has fixed the issue for me

Anyway, closing that issue is up to you, but I'm finally able to update Realm 🎉

[austinzheng]

Thank you for the follow-up! We'll close this ticket, but if you run into issues in the future feel free to open a new one.

[semireg]

I noticed the release notes for 2.4.4 at https://github.com/realm/realm-cocoa/releases/tag/v2.4.4 contain this text:

Fix a bug that could lead to bad version number errors when delivering change notifications.

Seems related...

[iOkay]

I think the deadlock is going on.
This is the stack info printed by bt on console.

* thread #1, queue = 'com.apple.main-thread', stop reason = signal SIGSTOP
  * frame #0: 0x00000001844a4e64 libsystem_kernel.dylib`__psynch_mutexwait + 8
    frame #1: 0x0000000184570b8c libsystem_pthread.dylib`_pthread_mutex_lock_wait + 96
    frame #2: 0x0000000101281700 xxx`realm::SharedGroup::do_begin_write() + 72
    frame #3: 0x0000000101162944 xxx`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::SharedGroup::promote_to_write<(anonymous namespace)::TransactLogValidator>(this=0x0000000110034600)::TransactLogValidator*) at group_shared.hpp:977 [opt]
    frame #4: 0x0000000101162914 xxx`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)::TransactLogValidator>(sg=0x0000000110034600)::TransactLogValidator*) at group_shared.hpp:1140 [opt]
    frame #5: 0x0000000101162914 xxx`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)::TransactLogValidator>(sg=0x0000000110034600)::TransactLogValidator&&) at lang_bind_helper.hpp:347 [opt]
    frame #6: 0x0000000101162914 xxx`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&)::$_2::operator()<(anonymous namespace)::TransactLogValidator>((anonymous namespace)::TransactLogValidator&&) const at transact_log_handler.cpp:825 [opt]
    frame #7: 0x0000000101162910 xxx`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=0x000000017402dcc0, sg=0x000000010fd151d8)::$_2>(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&)::$_2&&, realm::_impl::NotifierPackage&) at transact_log_handler.cpp:778 [opt]
    frame #8: 0x0000000101162888 xxx`realm::_impl::transaction::begin(sg=0x000000010fd151d8, context=0x000000017402dcc0, notifiers=0x000000016fd34030) at transact_log_handler.cpp:824 [opt]
    frame #9: 0x0000000101079fa8 xxx`realm::_impl::RealmCoordinator::promote_to_write(this=0x000000010fd152f8, realm=<unavailable>) at realm_coordinator.cpp:845 [opt]
    frame #10: 0x000000010113f0d4 xxx`realm::Realm::begin_transaction(this=0x000000010fd150a8) at shared_realm.cpp:622 [opt]
    frame #11: 0x0000000101116bb8 xxx`::-[RLMRealm beginWriteTransaction](self=<unavailable>, _cmd=<unavailable>) at RLMRealm.mm:572 [opt]
    frame #12: 0x00000001002b976c xxx`-[AccountManager setLastMatchGender:](self=0x0000000174117a00, _cmd="setLastMatchGender:", lastMatchGender=GenderAny) at AccountManager.m:325
    frame #13: 0x000000010013b8b0 xxx`-[RootViewController matchWithTopic:customTopic:gender:](self=0x0000000110074c00, _cmd="matchWithTopic:customTopic:gender:", topicId=0, custom=0x0000000000000000, gender=GenderAny) at RootViewController.m:790
    frame #14: 0x00000001001bc0e0 xxx`-[MatchNode genderDidChanged:](self=0x000000010fe70540, _cmd="genderDidChanged:", gender=GenderAny) at MatchNode.m:383
    frame #15: 0x0000000100395f00 xxx`-[GenderSwitchNode setGender:](self=0x0000000110a11800, _cmd="setGender:", gender=GenderAny) at GenderSwitchNode.m:53
    frame #16: 0x0000000100396020 xxx`-[GenderSwitchNode tapped:](self=0x0000000110a11800, _cmd="tapped:", sender=0x0000000110a11800) at GenderSwitchNode.m:64
    frame #17: 0x0000000100727dc4 xxx`::-[ASControlNode sendActionsForControlEvents:withEvent:](self=0x0000000110a11800, _cmd="sendActionsForControlEvents:withEvent:", controlEvents=16, event=0x00000001740f4200) at ASControlNode.mm:465
    frame #18: 0x0000000100724ebc xxx`::-[ASControlNode touchesEnded:withEvent:](self=0x0000000110a11800, _cmd="touchesEnded:withEvent:", touches=1 element, event=0x00000001740f4200) at ASControlNode.mm:241
    frame #19: 0x00000001006afc54 xxx`::-[_ASDisplayView touchesEnded:withEvent:](self=0x000000010fe859c0, _cmd="touchesEnded:withEvent:", touches=1 element, event=0x00000001740f4200) at _ASDisplayView.mm:278
    frame #20: 0x000000018b610390 UIKit`-[UIWindow _sendTouchesForEvent:] + 2480
    frame #21: 0x000000018b60b728 UIKit`-[UIWindow sendEvent:] + 3192
    frame #22: 0x000000018b5dc33c UIKit`-[UIApplication sendEvent:] + 340
    frame #23: 0x000000018bdd6014 UIKit`__dispatchPreprocessedEventFromEventQueue + 2400
    frame #24: 0x000000018bdd0770 UIKit`__handleEventQueue + 4268
    frame #25: 0x000000018bdd0b9c UIKit`__handleHIDEventFetcherDrain + 148
    frame #26: 0x000000018545942c CoreFoundation`__CFRUNLOOP_IS_CALLING_OUT_TO_A_SOURCE0_PERFORM_FUNCTION__ + 24
    frame #27: 0x0000000185458d9c CoreFoundation`__CFRunLoopDoSources0 + 540
    frame #28: 0x00000001854569a8 CoreFoundation`__CFRunLoopRun + 744
    frame #29: 0x0000000185386da4 CoreFoundation`CFRunLoopRunSpecific + 424
    frame #30: 0x000000018b584134 UIFoundation`-[NSHTMLReader _loadUsingWebKit] + 1764
    frame #31: 0x0000000185f9e4cc Foundation`__NSThreadPerformPerform + 340
    frame #32: 0x000000018545942c CoreFoundation`__CFRUNLOOP_IS_CALLING_OUT_TO_A_SOURCE0_PERFORM_FUNCTION__ + 24
    frame #33: 0x0000000185458d9c CoreFoundation`__CFRunLoopDoSources0 + 540
    frame #34: 0x00000001854569a8 CoreFoundation`__CFRunLoopRun + 744
    frame #35: 0x0000000185386da4 CoreFoundation`CFRunLoopRunSpecific + 424
    frame #36: 0x0000000186df0074 GraphicsServices`GSEventRunModal + 100
    frame #37: 0x000000018b641058 UIKit`UIApplicationMain + 208
    frame #38: 0x000000010022bf58 xxx`main(argc=1, argv=0x000000016fd37970) at main.m:15
    frame #39: 0x000000018439559c libdyld.dylib`start + 4

And the screenshot is

[bdash]

This issue has been closed for almost a year. If you're experiencing a problem, please _file a new issue_.