Crash on 'Observable.notifyObservers' #28

JMCPH · 2020-10-19T07:30:29Z

I'm are experiencing new crashes on the Observable.notifyObservers function.

I have investigated, but I haven't been able to reproduce it. Have you experienced the same thing, or have an idea of where to look, in order to fix this?

Stacktrace

Crashed: NSOperationQueue 0x11dfada10 (QOS: UTILITY)
0  Communicator                   0x103979658 specialized static Observable.notifyObservers(_:) + 4346893912 (<compiler-generated>:4346893912)
1  Communicator                   0x103974ea4 specialized SessionDelegate.session(_:activationDidCompleteWith:error:) + 52 (CommunicatorSessionDelegate.swift:52)
2  Communicator                   0x103974594 @objc SessionDelegate.session(_:activationDidCompleteWith:error:) + 4346873236 (<compiler-generated>:4346873236)
3  WatchConnectivity              0x1b10f72c0 __57-[WCSession onqueue_completeSwitchTask:withSessionState:]_block_invoke_2 + 388
4  Foundation                     0x190392004 __NSBLOCKOPERATION_IS_CALLING_OUT_TO_A_BLOCK__ + 24
5  Foundation                     0x1902945a4 -[NSBlockOperation main] + 104
6  Foundation                     0x190394344 __NSOPERATION_IS_INVOKING_MAIN__ + 24
7  Foundation                     0x19029427c -[NSOperation start] + 752
8  Foundation                     0x190394d70 __NSOPERATIONQUEUE_IS_STARTING_AN_OPERATION__ + 24
9  Foundation                     0x190394830 __NSOQSchedule_f + 184
10 libdispatch.dylib              0x18fc52134 _dispatch_call_block_and_release + 32
11 libdispatch.dylib              0x18fc535ac _dispatch_client_callout + 20
12 libdispatch.dylib              0x18fc55d60 _dispatch_continuation_pop + 408
13 libdispatch.dylib              0x18fc554c0 _dispatch_async_redirect_invoke + 588
14 libdispatch.dylib              0x18fc62724 _dispatch_root_queue_drain + 348
15 libdispatch.dylib              0x18fc62ed0 _dispatch_worker_thread2 + 116
16 libsystem_pthread.dylib        0x18fcb96dc _pthread_wqthread + 216
17 libsystem_pthread.dylib        0x18fcbf9c8 start_wqthread + 8

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

KaneCheshire · 2020-10-19T07:33:11Z

Hey!

I haven't seen this before no. It looks like it's saying the crash is in NSOperationQueue which is suspicious, because Communicator doesn't use NSOperationQueue (but I imagine WatchConnectivity does under the hood). Communicator just uses closures

KaneCheshire · 2020-10-19T07:38:52Z

It looks like the crash is related to switching watches, which might help us narrow down the issue. Do you know if this is just happening on iOS 14 with watchOS 7?

JMCPH · 2020-10-19T07:57:40Z

Thanks for your quick reply 🙂

It have actually only happened on iOS version 13.7.0 and 13.5.1.

Thanks for helping me get to the bottom of this 👍

KaneCheshire · 2020-10-19T10:34:04Z

Is this the only stack trace or are there others? Just trying to understand if it's always after onqueue_completeSwitchTask gets called in WatchConnectivity

KaneCheshire · 2020-10-19T11:41:01Z

Oh also and do you have any observers attached for Communicator.State or Reachability? It's not clear from the stack trace which of those two observables are having notifyObservers when it crashes

JMCPH · 2020-10-19T12:27:44Z

Yes the stack traces looks all the same.

I have the following observers:

iOSSessionHandler.swift


        // Observe for a message from the WatchOS
        GuaranteedMessage.observe { [weak self] (message) in
            guard message.identifier == "user_information" else { return }
            self?.updateContext(withUser: user, profile: profile)
        }
        
        // Observe for data sent from the watch.
        Blob.observe { blob in
           debugPrint(blob.content.toString())
        }
        
        // Observe on the reachability of the WatchOS
        Reachability.observe { [weak self] reachability in
            guard reachability == .immediatelyReachable else { return }
            self?.updateContext(withUser: user, profile: profile)
        }

WatchOSSessionHandler.swift


        Communicator.State.observe { state in
            debugPrint("[WatchOS] - Activation state changed: ", state)
        }
        
        ComplicationInfo.observe { [weak self] complicationInfo in
            debugPrint("[WatchOS] - Received complication info: ", complicationInfo)
            self?.reloadAllComplications()
        }
        
        Context.observe { context in
            debugPrint("[WatchOS] - Received context")
        }

        Blob.observe { blob in
            
            do {
                let decodedActivities = try JSONDecoder().decode([String : [String]].self, from: blob.content)
            } catch (let error) {
                debugPrint(error)
            }
            
        }

I have setup several observers for the Context, but that shouldn't be the issue right? It should be okay to have several Context.Observe { } in different controllers right?

KaneCheshire · 2020-10-19T15:06:05Z

Yep should be totally fine! I'm wondering whether I've implemented watch switching support incorrectly, the docs do say the app will terminate if certain methods aren't implemented when the user switches watches, but could also just be a bug in WatchConnectivity

JMCPH · 2020-10-21T12:08:25Z

Hmm yes that could be a possibility. The weird part is that I don't think it was triggered by a watch switching.

I just stumbled upon two new crashes with the following stack trace. It seems like there is an issue with the blobTransferCompletionHandlers[fileTransfer] look up..

    func session(_ session: WCSession, didFinish fileTransfer: WCSessionFileTransfer, error: Error?) {
        guard let handler = blobTransferCompletionHandlers[fileTransfer] else { return }
        if let error = error {
            handler(.failure(error))
        } else {
            handler(.success(()))
        }
    }

Thread 8 name:
Thread 8 Crashed:
0   Communicator                  	0x0000000104e409b0 specialized Dictionary.subscript.getter + 24
1   Communicator                  	0x0000000104e41448 specialized SessionDelegate.session(_:didFinish:error:) + 100 (CommunicatorSessionDelegate.swift:124)
2   Communicator                  	0x0000000104e41448 specialized SessionDelegate.session(_:didFinish:error:) + 100 (CommunicatorSessionDelegate.swift:124)
3   Communicator                  	0x0000000104e40c4c @objc SessionDelegate.session(_:didFinish:error:) + 108
4   WatchConnectivity             	0x00000001beebd770 __56-[WCSession onqueue_notifyOfFileError:withFileTransfer:]_block_invoke + 308 (WCSession.m:1756)
5   Foundation                    	0x000000018d0da7f4 __NSBLOCKOPERATION_IS_CALLING_OUT_TO_A_BLOCK__ + 24 (NSOperation.m:1544)
6   Foundation                    	0x000000018cfcd120 -[NSBlockOperation main] + 104 (NSOperation.m:1563)
7   Foundation                    	0x000000018d0dcbb8 __NSOPERATION_IS_INVOKING_MAIN__ + 24 (NSOperation.m:2188)
8   Foundation                    	0x000000018cfccda8 -[NSOperation start] + 808 (NSOperation.m:2205)
9   Foundation                    	0x000000018d0dd624 __NSOPERATIONQUEUE_IS_STARTING_AN_OPERATION__ + 24 (NSOperation.m:2219)
10  Foundation                    	0x000000018d0dd0d0 __NSOQSchedule_f + 184 (NSOperation.m:2230)
11  libdispatch.dylib             	0x000000018b9befd0 _dispatch_call_block_and_release + 32 (init.c:1454)
12  libdispatch.dylib             	0x000000018b9c0ac8 _dispatch_client_callout + 20 (object.m:559)
13  libdispatch.dylib             	0x000000018b9c3d60 _dispatch_continuation_pop + 416 (inline_internal.h:2548)
14  libdispatch.dylib             	0x000000018b9c3494 _dispatch_async_redirect_invoke + 592 (queue.c:805)
15  libdispatch.dylib             	0x000000018b9d1104 _dispatch_root_queue_drain + 356 (inline_internal.h:2589)
16  libdispatch.dylib             	0x000000018b9d18e8 _dispatch_worker_thread2 + 116 (queue.c:6766)
17  libsystem_pthread.dylib       	0x00000001d331c8cc _pthread_wqthread + 216 (pthread.c:2206)
18  libsystem_pthread.dylib       	0x00000001d332377c start_wqthread + 8``

zacwest · 2021-03-05T04:38:10Z

I've been able to reproduce this; this is a race condition where configuring the callbacks can occur at the same time as one notifying.

For example, on thread #0:

Thread 0
0   libswiftCore.dylib              0x326464c44         _NativeDictionary._copyOrMoveAndResize
1   libswiftCore.dylib              0x326394634         Dictionary._Variant.setValue
2   Communicator                    0x1026b5244         Dictionary.subscript.setter
3   Communicator                    0x1026b4040         [inlined] subscript.set
4   Communicator                    0x1026b4040         Observable.observe (Observations.swift:35)
5   Home Assistant                  0x202285404         AppDelegate.setupWatchCommunicator (AppDelegate.swift:425)
…

Thread 2 Crashed:
0   Communicator                    0x1026aec40         [inlined] <redacted>
1   Communicator                    0x1026aec40         [inlined] <redacted>
2   Communicator                    0x1026aec40         [inlined] <redacted>
3   Communicator                    0x1026aec40         [inlined] forEach
4   Communicator                    0x1026aec40         Observable.notifyObservers (Observations.swift:48)
5   Communicator                    0x1026aec34         [inlined] <redacted> (Observations.swift:95)
6   Communicator                    0x1026aec34         [inlined] observations.get
7   Communicator                    0x1026aec34         [inlined] observations.get (<compiler-generated>:95)
8   Communicator                    0x1026aec34         Observable.notifyObservers (Observations.swift:48)
9   Communicator                    0x1026b17d8         [inlined] notifyObservers
10  Communicator                    0x1026b17d8         SessionDelegate.session (CommunicatorSessionDelegate.swift:50)
11  Communicator                    0x1026acb7c         [inlined] session
12  Communicator                    0x1026acb7c         SessionDelegate.session (<compiler-generated>:48)
13  WatchConnectivity               0x389680cb8         __57-[WCSession onqueue_completeSwitchTask:withSessionState:]_block_invoke_2

So thread #2 and #0 are trying to access and use the observer list at the same time.

Ideally observers would be able to be set up before the delegate is set up, so no messages are lost in-between those two points in time. However, adding an observer also explicitly creates the singleton.

KaneCheshire · 2021-03-05T09:17:16Z

Omg nice find! I think that can be solved by creating the shared instance asynchronously. Good ol' DispatchQueue.main.async to the rescue!

KaneCheshire · 2021-03-05T09:18:35Z

Possibly also WatchConnectivity might expect us to only access the WCSession on the main thread too but I'll have to check that

KaneCheshire · 2021-03-26T23:42:09Z

I've been trying to reproduce this race condition in a test case (without using Communicator) so that I can see if there's a nicer way than just using DispatchQueue.main.async but I'm struggling to get a test case to crash. Difficult to get two threads to access the same dictionary at the same time in a test

KaneCheshire · 2021-03-27T00:06:25Z

Okay using this code I can make some crash although not exactly the same as the ones above, but it is still related to the setter of the dictionary, so that's something. Would be nice to make that work nicely so that we know the crash is fixed. I think it's also right to delay the creation of the shared Communicator instance until the next run of the main queue because it gives you a chance to set up all the observers. Alternatively, I could make it so there's an extra step and you have to initialise the communicator object which is a bit ugly but at least gives more stability

func test_raceCondition() {
        let group = DispatchGroup()
        for _ in 0 ..< 1000 {
            group.enter()
            DispatchQueue.global().async {
                MyThing.observe { thing in }
                MyThing.notifyObservers(MyThing())
                group.leave()
            }
        }
        group.wait()
    }

KaneCheshire linked a pull request Mar 19, 2021 that will close this issue

Attempt to fix crash by performing communicator implicit construction… #35

Open

Provide feedback

Saved searches

Use saved searches to filter your results more quickly

Crash on 'Observable.notifyObservers' #28

Crash on 'Observable.notifyObservers' #28

JMCPH commented Oct 19, 2020

KaneCheshire commented Oct 19, 2020

KaneCheshire commented Oct 19, 2020

JMCPH commented Oct 19, 2020

KaneCheshire commented Oct 19, 2020

KaneCheshire commented Oct 19, 2020

JMCPH commented Oct 19, 2020 •

edited

Loading

KaneCheshire commented Oct 19, 2020

JMCPH commented Oct 21, 2020 •

edited

Loading

zacwest commented Mar 5, 2021 •

edited

Loading

KaneCheshire commented Mar 5, 2021

KaneCheshire commented Mar 5, 2021

KaneCheshire commented Mar 26, 2021

KaneCheshire commented Mar 27, 2021

Crash on 'Observable.notifyObservers' #28

Crash on 'Observable.notifyObservers' #28

Comments

JMCPH commented Oct 19, 2020

KaneCheshire commented Oct 19, 2020

KaneCheshire commented Oct 19, 2020

JMCPH commented Oct 19, 2020

KaneCheshire commented Oct 19, 2020

KaneCheshire commented Oct 19, 2020

JMCPH commented Oct 19, 2020 • edited Loading

KaneCheshire commented Oct 19, 2020

JMCPH commented Oct 21, 2020 • edited Loading

zacwest commented Mar 5, 2021 • edited Loading

KaneCheshire commented Mar 5, 2021

KaneCheshire commented Mar 5, 2021

KaneCheshire commented Mar 26, 2021

KaneCheshire commented Mar 27, 2021

JMCPH commented Oct 19, 2020 •

edited

Loading

JMCPH commented Oct 21, 2020 •

edited

Loading

zacwest commented Mar 5, 2021 •

edited

Loading