bluejay
bluejay copied to clipboard
steamclock
Handle explicit disconnect vs pending connection race condition
Summary:
I found this doing the same testing that I mention in https://github.com/steamclock/bluejay/issues/213.
Steps to Reproduce:
- Press the connect/disconnect button very quickly, causing fast sequences of connecting and disconnecting.
Actual Result:
Crashes on:
2019-06-24 13:36:00.309 [Bluejay] [main] > Bluejay.Connection added to queue with UUID: 71FD0814-5022-4F54-893F-73D18B5099D1. 2019-06-24 13:36:00.310 [Bluejay] [main] > Init Peripheral: <Bluejay.Peripheral: 0x1187ad410>, Optional(<CBPeripheral: 0x10e317dc0, identifier = BC21C4F8-8545-A51A-873F-25A51D8EB13D, name = Peripheral, state = disconnected>) 2019-06-24 13:36:00.311 [Bluejay] [main] > Queue will start Bluejay.Connection... 2019-06-24 13:36:00.312 [Bluejay] [main] > Started connecting to Peripheral. 2019-06-24 13:36:00.825 [Bluejay] [main] > Explicit disconnect called. 2019-06-24 13:36:00.830 [Bluejay] [main] > Cancel everything called with error: Explicit disconnect, shouldDisconnect: true 2019-06-24 13:36:00.830 [Bluejay] [main] > Cancel everything called while still connecting... 2019-06-24 13:36:00.831 [Bluejay] [main] > Should auto-reconnect: false 2019-06-24 13:36:00.831 [Bluejay] [main] > Queue will now cancel all operations with error: Explicit disconnect 2019-06-24 13:36:00.831 [Bluejay] [main] > Cancelling a pending connection to Peripheral 2019-06-24 13:36:00.832 [Bluejay] [main] > Interrupting cancel all to terminate a pending connection... 2019-06-24 13:36:00.836 [Bluejay] [main] > Central manager did connect to: Peripheral 2019-06-24 13:36:00.836 [Bluejay] [main] > Should auto-reconnect: true 2019-06-24 13:36:00.837 [Bluejay] [main] > Connected to: Peripheral 2019-06-24 13:36:00.837 [Bluejay] [main] > Queue has removed Bluejay.Connection because it has finished. 2019-06-24 13:36:00.837 [Bluejay] [main] > Queue is empty, nothing to update. 2019-06-24 13:36:00.837 [Bluejay] [main] > Connection deinitialized. 2019-06-24 13:36:00.838 [Bluejay] [main] > Requesting read on Characteristic: D1E6D07D-6C31-40D1-850A-03FCFE75B84B, Service: 9D8E58B2-1D2D-4DC4-B324-EDDF69746AD4... 2019-06-24 13:36:00.839 [Bluejay] [main] > Queue will start Bluejay.DiscoverService... 2019-06-24 13:36:00.840 [Bluejay] [main] > Central manager did disconnect from Peripheral without errors. 2019-06-24 13:36:00.840 [Bluejay] [main] > Peripheral was connected before centralManager(_:didDisconnectPeripheral:error:). 2019-06-24 13:36:00.840 [Bluejay] [main] > Cleared all restoration peripheral references. 2019-06-24 13:36:00.840 [Bluejay] [main] > Cleared all non restoration peripheral references. 2019-06-24 13:36:00.841 [Bluejay] [main] > The disconnect is expected. 2019-06-24 13:36:00.841 [Bluejay] [main] > Should auto-reconnect: false 2019-06-24 13:36:00.841 [Bluejay] [main] > Deinit Peripheral: <Bluejay.Peripheral: 0x118759c90>, Optional(<CBPeripheral: 0x10e317dc0, identifier = BC21C4F8-8545-A51A-873F-25A51D8EB13D, name = Peripheral, state = disconnected>)) 2019-06-24 13:36:00.841 [Bluejay] [main] > Starting disconnect clean up... < Crash occurs here >
Expected Result:
The connects/disconnects happen as expected.
Device, Build, OS:
iPhone Xs, Bluejay 0.8.5, iOS 12.3.1
Similar to my comment for #213, I am wondering whether your app makes other Bluejay calls in any of Bluejay's delegations. Also see the discussion in #210, these crashes may be related in that you might have extra logic in some callbacks or delegation method that may conflict with each other, therefore causing the precondition in the queue.
Also from your log, there is a read request being issued right after you call disconnect.
2019-06-24 13:36:00.838 [Bluejay] [main] > Requesting read on Characteristic: D1E6D07D-6C31-40D1-850A-03FCFE75B84B, Service: 9D8E58B2-1D2D-4DC4-B324-EDDF69746AD4....
If you can figure out where and why and how your app is issuing that read to Bluejay after you start a disconnect, then I think you can fix this crash and potentially #213 as well.
Finally, it looks like things are happening so quickly that when you start a disconnect, Bluejay is unable to cancel the pending connection in time, and CBCentralManager still manages to connect to the peripheral. This is not something we can always prevent, but it is something Bluejay can handle better. For now, you can deal with this bug without needing to wait for a Bluejay update:
Your read might be a result of your connection callback, so you could read Bluejay's isDisconnecting variable inside your connection callback, and don't try to perform any connection completion logic if Bluejay gives you a connection success while isDisconnecting is true.
Regarding the above. Is there any reason that actually can't be handled in Bluejay? It seems if we can do it on our end to check for isDisconnecting, so could Bluejay?
Hi @kylebrowning, yes Bluejay can handle it (in a future but coming soon update)
This is not something we can always prevent, but it is something Bluejay can handle better.
The thing we can't prevent is the edge case when you sometimes cancel a connection, CB will still connect anyway (because of timing). This is not because Bluejay is too slow to cancel, because in most cases of immediate cancels, Bluejay is able to issue cancelPeripheralConnection to CB (almost) immediately, but that call is non-blocking.
https://developer.apple.com/documentation/corebluetooth/cbcentralmanager/1518952-cancelperipheralconnection