Skip to content
New issue

Have a question about this project? Sign up for a free GitHub account to open an issue and contact its maintainers and the community.

By clicking “Sign up for GitHub”, you agree to our terms of service and privacy statement. We’ll occasionally send you account related emails.

Already on GitHub? Sign in to your account

Crash immediately after State Preservation/Restoration - "Connected peripheral is assigned a nil value despite Bluejay has successfully finished a connection." #206

Open
SaintNicholas opened this issue May 28, 2019 · 7 comments · May be fixed by #235

Comments

@SaintNicholas
Copy link

SaintNicholas commented May 28, 2019

Summary:

I stumbled upon a crash in my app that happens immediately on app startup, after state preservation/restoration has completed.

Steps to Reproduce:

  1. Be running my app, connected to a BLE peripheral, using it regularly.
  2. In Xcode, hit Run to re-build the project and run it. This kills the currently running app and starts it again.
  3. After the app has been killed, and before the app starts up again, power cycle the BLE peripheral.

Actual Result:

I get a crash in

public func centralManager(_ central: CBCentralManager, didConnect peripheral: CBPeripheral) {

at line

precondition(connectedPeripheral != nil, "Connected peripheral is assigned a nil value despite Bluejay has successfully finished a connection.")

The log contains:

2019-05-27 21:18:01.502 [Bluejay] [main] > Bluejay initialized with UUID: 2E3BF94F-3C77-4D18-B134-23A1CDA31369.
2019-05-27 21:18:01.502 [Bluejay] [main] > Queue initialized with UUID: 02C5BE07-0319-42B2-B189-9A1912276AFB.
2019-05-27 21:18:01.502 [Bluejay] [main] > Background restoration enabled with restore identifier: test.bluejay
2019-05-27 21:18:01.503 [Bluejay] [main] > CBCentralManager initialized.
2019-05-27 21:18:01.503 [Bluejay] [main] > Bluejay with UUID: 2E3BF94F-3C77-4D18-B134-23A1CDA31369 started.
2019-05-27 21:18:01.592 [Bluejay] [main] > Central manager will restore state.
2019-05-27 21:18:01.592 [Bluejay] [main] > Init Peripheral: <Bluejay.Peripheral: 0x282f14b70>, Optional(<CBPeripheral: 0x281099ea0, identifier = DC02558C-CF8E-EC0A-A177-D3F819407226, name = Test, state = connected>)
2019-05-27 21:18:01.592 [Bluejay] [main] > Peripheral state to restore: Connected
2019-05-27 21:18:01.592 [Bluejay] [main] > Central manager state updated: Powered On
2019-05-27 21:18:01.592 [Bluejay] [main] > Cancel everything called with error: Background restoration is in progress, shouldDisconnect: false
2019-05-27 21:18:01.592 [Bluejay] [main] > Queue is empty, nothing to cancel.
2019-05-27 21:18:01.592 [Bluejay] [main] > Starting queue with UUID: 02C5BE07-0319-42B2-B189-9A1912276AFB.
2019-05-27 21:18:01.592 [Bluejay] [main] > Queue is empty, nothing to update.
2019-05-27 21:18:01.593 [Bluejay] [main] > Did restore connection to peripheral: Peripheral: Test, UUID: DC02558C-CF8E-EC0A-A177-D3F819407226
2019-05-27 21:18:01.593 [Bluejay] [main] > Requesting read on Characteristic: D1E6D07D-6C31-40D1-850A-03FCFE75B84B, Service: 9D8E58B2-1D2D-4DC4-B324-EDDF69746AD4...
2019-05-27 21:18:01.593 [Bluejay] [main] > Queue will start Bluejay.DiscoverService...
2019-05-27 21:18:01.593 [Bluejay] [main] > Queue has removed Bluejay.DiscoverService because it has finished.
2019-05-27 21:18:01.593 [Bluejay] [main] > Queue is empty, nothing to update.
2019-05-27 21:18:01.593 [Bluejay] [main] > Queue will start Bluejay.DiscoverCharacteristic...
2019-05-27 21:18:01.593 [Bluejay] [main] > Bluejay.ReadCharacteristic<Test> added to queue with UUID: 02C5BE07-0319-42B2-B189-9A1912276AFB.
2019-05-27 21:18:01.593 [Bluejay] [main] > Queue has removed Bluejay.DiscoverCharacteristic because it has finished.
2019-05-27 21:18:01.593 [Bluejay] [main] > Queue will start Bluejay.ReadCharacteristic<Test>...
2019-05-27 21:18:01.593 [Bluejay] [main] > Started read for Characteristic: D1E6D07D-6C31-40D1-850A-03FCFE75B84B, Service: 9D8E58B2-1D2D-4DC4-B324-EDDF69746AD4 on DC02558C-CF8E-EC0A-A177-D3F819407226.
2019-05-27 21:18:01.593 [Bluejay] [main] > Cleared all restoration peripheral references.
2019-05-27 21:18:01.593 [Bluejay] [main] > CoreBluetooth restoration completed.
2019-05-27 21:18:01.593 [Bluejay] [main] > Central manager did connect to: Test
2019-05-27 21:18:01.593 [Bluejay] [main] > Deinit Peripheral: <Bluejay.Peripheral: 0x282f14b70>, Optional(<CBPeripheral: 0x281099ea0, identifier = DC02558C-CF8E-EC0A-A177-D3F819407226, name = Test, state = connected>))
Bluejay was compiled with optimization - stepping may behave oddly; variables may not be available.

I do see that I am doing a characteristic read in the middle of this process, but it's not a critical read, and I had thought that it would be ok if that just failed (assuming bluejay handled it ok).

Expected Result:

It doesn't crash I guess?

Device, Build, OS:

iPhone Xs, iOS 12.3, bluejay v0.8.5

@SaintNicholas
Copy link
Author

SaintNicholas commented Jul 9, 2019

I'm seeing a lot of this crash with my users, and so I tried to gather some more information.

I was able to reproduce this crash several times at my desk. The process was:

  1. Get into a connected state with the peripheral.
  2. In Xcode, hit 'Stop'.
  3. Power cycle the peripheral, leaving it in an off state.
  4. In Xcode, hit 'Start', which causes the app to reload, and state preservation/restoration to occur.

Sometimes (not always), when the state preservation/restoration occurred, I would get the following sequence of events. It seems like it's restoring the system back to a state where it's trying to connect to the peripheral, but then it gets a disconnect. Getting the disconnect is weird because the peripheral was powered off when I started the app. Perhaps the disconnect is queued within iOS, and is then handled by the app once it starts up again?

Based on the Bluejay logs, I would have expected that when I powered the peripheral on, iOS would not automatically reconnect, since the logs indicated auto-reconnect was false. However, when I power the peripheral on, iOS automatically reconnects to it, and Bluejay crashes.

I think Bluejay is crashing because as part of the disconnect sequence, clearAllNonRestorationPeripherals is called, which clears connectingPeripheral. Then, when iOS establishes the connection, line 1311 is hit, connectingPeripheral was nil, and Bluejay crashes.

2019-07-09 13:11:57.428 [Bluejay] [main] > Bluejay initialized with UUID: 4DEB7431-41E9-4C4C-90C8-009310C9A3F3.
2019-07-09 13:11:57.429 [Bluejay] [main] > Queue initialized with UUID: 3EE4D781-D35F-4BA5-8F15-43F2FF84C68C.
2019-07-09 13:11:57.429 [Bluejay] [main] > Background restoration enabled with restore identifier: peripheral.bluejay
2019-07-09 13:11:57.430 [Bluejay] [main] > CBCentralManager initialized.
2019-07-09 13:11:57.430 [Bluejay] [main] > Bluejay with UUID: 4DEB7431-41E9-4C4C-90C8-009310C9A3F3 started.
2019-07-09 13:11:57.527 [Bluejay] [main] > Central manager will restore state.
2019-07-09 13:11:57.527 [Bluejay] [main] > Init Peripheral: <Bluejay.Peripheral: 0x114421ad0>, Optional(<CBPeripheral: 0x10a9065c0, identifier = DC02558C-CF8E-EC0A-A177-D3F819407226, name = Peripheral, state = connecting>)
2019-07-09 13:11:57.527 [Bluejay] [main] > Peripheral state to restore: Connecting
2019-07-09 13:11:57.528 [Bluejay] [main] > Central manager state updated: Powered On
2019-07-09 13:11:57.528 [Bluejay] [main] > Cancel everything called with error: Background restoration is in progress, shouldDisconnect: false
2019-07-09 13:11:57.528 [Bluejay] [main] > Queue is empty, nothing to cancel.
2019-07-09 13:11:57.528 [Bluejay] [main] > Starting queue with UUID: 3EE4D781-D35F-4BA5-8F15-43F2FF84C68C.
2019-07-09 13:11:57.528 [Bluejay] [main] > Queue is empty, nothing to update.
2019-07-09 13:11:57.528 [Bluejay] [main] > Bluejay.Connection added to queue with UUID: 3EE4D781-D35F-4BA5-8F15-43F2FF84C68C.
2019-07-09 13:11:57.528 [Bluejay] [main] > Init Peripheral: <Bluejay.Peripheral: 0x11441e850>, Optional(<CBPeripheral: 0x10a9065c0, identifier = DC02558C-CF8E-EC0A-A177-D3F819407226, name = Peripheral, state = connecting>)
2019-07-09 13:11:57.528 [Bluejay] [main] > Queue will start Bluejay.Connection...
2019-07-09 13:11:57.529 [Bluejay] [main] > Started connecting to Peripheral.
2019-07-09 13:11:57.529 [Bluejay] [main] > Central manager did disconnect from Peripheral with error: The connection has timed out unexpectedly.
2019-07-09 13:11:57.529 [Bluejay] [main] > Peripheral state was connecting during background restoration before centralManager(_:didDisconnectPeripheral:error:).
2019-07-09 13:11:57.529 [Bluejay] [main] > Cleared all restoration peripheral references.
2019-07-09 13:11:57.529 [Bluejay] [main] > Cleared all non restoration peripheral references.
2019-07-09 13:11:57.529 [Bluejay] [main] > The disconnect is unexpected.
2019-07-09 13:11:57.529 [Bluejay] [main] > Should auto-reconnect: false
2019-07-09 13:11:57.529 [Bluejay] [main] > Starting disconnect clean up...
2019-07-09 13:11:57.529 [Bluejay] [main] > Disconnect clean up: delivering expected disconnected event back to the pending connection in the queue...
2019-07-09 13:11:57.529 [Bluejay] [main] > Failed connecting to: Peripheral with error: Unexpected disconnect
2019-07-09 13:11:57.529 [Bluejay] [main] > Did fail to to restore connection with error: Unexpected disconnect
2019-07-09 13:11:57.530 [Bluejay] [main] > Cleared all restoration peripheral references.
2019-07-09 13:11:57.530 [Bluejay] [main] > CoreBluetooth restoration completed.
2019-07-09 13:11:57.530 [Bluejay] [main] > Queue has removed Bluejay.Connection because it has finished.
2019-07-09 13:11:57.530 [Bluejay] [main] > Queue is empty, nothing to update.
2019-07-09 13:11:57.530 [Bluejay] [main] > Connection deinitialized.
2019-07-09 13:11:57.530 [Bluejay] [main] > Disconnect clean up: disconnected while restoring a connecting peripheral, will not auto-reconnect.
2019-07-09 13:11:57.530 [Bluejay] [main] > Did fail to to restore connection with error: Unexpected disconnect
2019-07-09 13:11:57.530 [Bluejay] [main] > Cleared all restoration peripheral references.
2019-07-09 13:11:57.530 [Bluejay] [main] > CoreBluetooth restoration completed.
2019-07-09 13:11:57.530 [Bluejay] [main] > Deinit Peripheral: <Bluejay.Peripheral: 0x114421ad0>, Optional(<CBPeripheral: 0x10a9065c0, identifier = DC02558C-CF8E-EC0A-A177-D3F819407226, name = Peripheral, state = disconnected>))
2019-07-09 13:11:57.530 [Bluejay] [main] > End of disconnect clean up.

< Some time passed here. When I powered on the peripheral, iOS automatically reconnected, causing the following logs to occur, and Bluejay to crash. >

Bluejay was compiled with optimization - stepping may behave oddly; variables may not be available.
2019-07-09 13:12:08.839 [Bluejay] [main] > Central manager did connect to: Peripheral
(lldb)

@SaintNicholas SaintNicholas changed the title Crash immediately after State Preservation/Restoration Crash immediately after State Preservation/Restoration - "Connected peripheral is assigned a nil value despite Bluejay has successfully finished a connection." Jul 9, 2019
@SaintNicholas
Copy link
Author

SaintNicholas commented Jul 11, 2019

Another thing I noticed is that I see the following log entries repeated, which is surprising.

[Bluejay] [main] > Did fail to to restore connection with error: Unexpected disconnect
[Bluejay] [main] > Cleared all restoration peripheral references.
[Bluejay] [main] > CoreBluetooth restoration completed.

I also get 2 calls to: didFailToRestoreConnection, which is surprising.

In looking at code, maybe this is happening because the initial connect request fails, which causes restoration to "complete", and then there's also a disconnect happening, which also causes the restoration to "complete"?

@sakuraehikaru
Copy link

Hi @SaintNicholas state restoration is one of the hardest things to get right, and obviously Bluejay is not quite there yet. I remember reviewing another similar bug report internally here at Steamclock, but can't remember what became of it - maybe because I do remember something along the lines of iOS 12 may have different state restoration behaviours, or possibly only different in some unknown cases, or in some iOS devices, or on certain iOS versions, or perhaps even dependent on the Bluetooth LE peripheral itself!

We are very busy right now, so I don't have the bandwidth to provide an official fix to you in a timely manner, but I do have some ideas for a solution that you could try in your fork.

If you look at line 1308 in Bluejay.swift, you'll see that we try to update the states via:

connectedPeripheral = connectingPeripheral

Based on your specific report and logs, there may be multiple issues, but one of the most alarming one is: we're getting a rogue "did connect" callback from CB that doesn't seem to come from any Bluejay connection, nor a CB state restoration? Does this conclusion sound right to you as well?

To me, state restoration actually seems to be working fine based on your logs, regardless of whether the restoration reconnected or disconnected, it still completed all the way. But we just need to zero in on what is triggering that final extra and rogue "did connect" event after everything seems to be finished already.

If you can repro this, try breakpointing on line 1308 and examine all the peripheral references:

  • connectingPeripheral
  • connectedPeripheral
  • connectingPeripheralAtRestoration
  • disconnectingPeripheralAtRestoration
  • disconnectedPeripheralAtRestoration

And also see if you can inspect the state of the Bluejay queue and other related states. They may tell us more about where this "did connect" is coming from. If we can figure that out, then we may be able to handle it.

@SaintNicholas
Copy link
Author

Hi @jeremychiang I was able to reproduce it again, and collect some more information. It's at the bottom of the response.

I agree that the rogue 'did connect' callback is unexpected. I think the information I collected shows that Bluejay isn't expecting the connection, as all the variables you asked me to look at are nil, and the queue is empty. Is it possible that when bluejay says 'Should auto-reconnect: false' that it's wrong, iOS is going to be auto-reconnecting? In my experience with other disconnects, when Bluejay says 'The disconnect is unexpected.', it usually does auto-reconnect, and I'm not sure why this case is different.

Also, do you have any idea why I'm seeing multiple calls to didFailToRestoreConnection? I was hoping to manually call bluejay.connect in that function, so that even if the restoration fails, my app will try to connect to the peripheral. However, with 2 calls to didFailToRestoreConnection, I'm not sure if I'll run into problems.

(lldb) p bluejay.queue
(Test_Program.Queue?) $R10 = 0x0000000160a81e60 {
  bluejay = 0x000000015f53bd40 {
    ObjectiveC.NSObject = {}
    cbCentralManager = 0x0000000160a85e80 {
      CoreBluetooth.CBManager = {
        ObjectiveC.NSObject = {}
      }
    }
    queue = 0x0000000160a81e60 {...}
    connectionObservers = 2 values {
      [0] = {
        weakReference = (instance = 0x000000015e19b831, witness_table_ConnectionObserver = 0x0000000101cde000 Test Program`protocol witness table for Test_Program.Queue : Test_Program.ConnectionObserver in Test_Program) {
          instance = 0x000000015e19b831
          witness_table_ConnectionObserver = 0x0000000101cde000 Test Program`protocol witness table for Test_Program.Queue : Test_Program.ConnectionObserver in Test_Program
        }
      }
      [1] = {
        weakReference = (instance = 0x000000015e19ded1, witness_table_ConnectionObserver = 0x0000000101cc2ca0 Test Program`protocol witness table for Test_Program.AvailabilityAndConnectionObserver : Test_Program.ConnectionObserver in Test_Program) {
          instance = 0x000000015e19ded1
          witness_table_ConnectionObserver = 0x0000000101cc2ca0 Test Program`protocol witness table for Test_Program.AvailabilityAndConnectionObserver : Test_Program.ConnectionObserver in Test_Program
        }
      }
    }
    rssiObservers = 0 values {}
    serviceObservers = 0 values {}
    logObservers = 0 values {}
    connectingPeripheral = nil
    connectedPeripheral = nil
    previousConnectionTimeout = (seconds = 15)
    connectingCallback = nil
    disconnectCallback = nil
    disconnectHandler = (instance = 0x000000015e19ded1, witness_table_DisconnectHandler = 0x0000000101cc2ce0 Test Program`protocol witness table for Test_Program.AvailabilityAndConnectionObserver : Test_Program.DisconnectHandler in Test_Program) {
      instance = 0x000000015e19ded1
      witness_table_DisconnectHandler = 0x0000000101cc2ce0 Test Program`protocol witness table for Test_Program.AvailabilityAndConnectionObserver : Test_Program.DisconnectHandler in Test_Program
    }
    disconnectCleanUp = 0x00000001014c9c50 Test Program`partial apply forwarder for function signature specialization <Arg[6] = Value Promoted from Box> of  at <compiler-generated>
    restoreIdentifier = "testprogram.bluejay"
    backgroundRestorer = (instance = 0x000000015e13bce0, witness_table_BackgroundRestorer = 0x0000000101cdc9e0 Test Program`protocol witness table for Test_Program.AppDelegate : Test_Program.BackgroundRestorer in Test_Program) {
      instance = 0x000000015e13bce0
      witness_table_BackgroundRestorer = 0x0000000101cdc9e0 Test Program`protocol witness table for Test_Program.AppDelegate : Test_Program.BackgroundRestorer in Test_Program
    }
    listenRestorer = (instance = 0x000000015e13bce0, witness_table_ListenRestorer = 0x0000000101cdca20 Test Program`protocol witness table for Test_Program.AppDelegate : Test_Program.ListenRestorer in Test_Program) {
      instance = 0x000000015e13bce0
      witness_table_ListenRestorer = 0x0000000101cdca20 Test Program`protocol witness table for Test_Program.AppDelegate : Test_Program.ListenRestorer in Test_Program
    }
    isRestoring = false
    startupBackgroundTask = {
      rawValue = 0
    }
    isRunningBackgroundTask = false
    connectingPeripheralAtRestoration = nil
    disconnectingPeripheralAtRestoration = nil
    disconnectedPeripheralAtRestoration = nil
    logFileName = "bluejay_debug.txt"
    logFileMonitorSource = nil
    logFileDescriptor = 0
    uuid = 6CC5974A-9A31-45B8-A84F-AD45BD8112F7
    isDisconnecting = false
    shouldAutoReconnect = false
    defaultWarningOptions = {
      notifyOnConnection = false
      notifyOnDisconnection = false
      notifyOnNotification = false
    }
  }
  scan = nil
  queue = 0 values {}
  uuid = 6EADA633-7C34-4AA2-A835-B84A65285323
  isCBCentralManagerReady = true
}

@SaintNicholas
Copy link
Author

Hey @jeremychiang, I'm seeing another crash that's very similar to what I discussed above, but different. This crash is from restoring a 'connected' peripheral, where the discussion above is describing a crash from restoring a 'connecting' peripheral.

debugLog(_:) > Bluejay initialized with UUID: 1A029AFF-35B8-4684-802D-E1BC95028BD6.
debugLog(_:) > Queue initialized with UUID: 412EE06E-07CD-4BC0-8642-5F60D48B58B8.
debugLog(_:) > Background restoration enabled with restore identifier: com.test.bluejay
debugLog(_:) > Begin startup background task for restoring CoreBluetooth.
debugLog(_:) > CBCentralManager initialized.
debugLog(_:) > Bluejay with UUID: 1A029AFF-35B8-4684-802D-E1BC95028BD6 started.
debugLog(_:) > Central manager will restore state.
debugLog(_:) > Init Peripheral: <Test.Peripheral: 0x2805eaeb0>, Optional(<CBPeripheral: 0x283af4320, identifier = 08C5ABD0-8F3B-F65A-EAA6-559CE4237B76, name = Peripheral, state = connected>)
debugLog(_:) > Peripheral state to restore: Connected
debugLog(_:) > Central manager state updated: Powered On
debugLog(_:) > Cancel everything called with error: Background restoration is in progress, shouldDisconnect: false
debugLog(_:) > Queue is empty, nothing to cancel.
debugLog(_:) > Starting queue with UUID: 412EE06E-07CD-4BC0-8642-5F60D48B58B8.
debugLog(_:) > Queue is empty, nothing to update.

< At this point, the `func connected(to peripheral: PeripheralIdentifier)` function is called by Bluejay.swift line 1147. This is what
  kicks off the reads that you will see coming next. I tried removing the reads, and it didn't make a difference. >

debugLog(_:) > Did restore connection to peripheral: Peripheral: Peripheral, UUID: 08C5ABD0-8F3B-F65A-EAA6-559CE4237B76
debugLog(_:) > Requesting read on Characteristic: D1E6D07D-6C31-40D1-850A-03FCFE75B84B, Service: 9D8E58B2-1D2D-4DC4-B324-EDDF69746AD4...
debugLog(_:) > Queue will start Test.DiscoverService...
debugLog(_:) > Queue has removed Test.DiscoverService because it has finished.
debugLog(_:) > Queue is empty, nothing to update.
debugLog(_:) > Queue will start Test.DiscoverCharacteristic...
debugLog(_:) > Test.ReadCharacteristic<Test.BondedStatusCharacteristicReadResult> added to queue with UUID: 412EE06E-07CD-4BC0-8642-5F60D48B58B8.
debugLog(_:) > Queue has removed Test.DiscoverCharacteristic because it has finished.
debugLog(_:) > Queue will start Test.ReadCharacteristic<Test.BondedStatusCharacteristicReadResult>...
debugLog(_:) > Started read for Characteristic: D1E6D07D-6C31-40D1-850A-03FCFE75B84B, Service: 9D8E58B2-1D2D-4DC4-B324-EDDF69746AD4 on 08C5ABD0-8F3B-F65A-EAA6-559CE4237B76.
debugLog(_:) > Ending startup background task.

< At this point, restoration information like connectedPeripheral and connectingPeripheral are removed (by clearAllRestorationPeripherals and
  clearAllNonRestorationPeripherals), because Bluejay believes that the connection is established, and iOS won't be calling the
  `public func centralManager(_ central: CBCentralManager, didConnect peripheral: CBPeripheral)` function. >

debugLog(_:) > Cleared all restoration peripheral references.
debugLog(_:) > CoreBluetooth restoration completed.

< Here, iOS calls `public func centralManager(_ central: CBCentralManager, didConnect peripheral: CBPeripheral)`. Because connectedPeripheral and connectingPeripheral
  were cleared earlier, this is where the crash occurs. I think, like I said earlier, that Bluejay doesn't expect this to be called?

debugLog(_:) > Central manager did connect to: Peripheral
debugLog(_:) > Deinit Peripheral: <Test.Peripheral: 0x2805eaeb0>, Optional(<CBPeripheral: 0x283af4320, identifier = 08C5ABD0-8F3B-F65A-EAA6-559CE4237B76, name = Peripheral, state = connected>))
Precondition failed: Connected peripheral is assigned a nil value despite Bluejay has successfully finished a connection.: file Bluejay.swift, line 1315

@sakuraehikaru
Copy link

Thank you for your report. This is on my radar, but we do have a few other features and fixes planned. We'll circle back to this as soon as we can.

@gKamelo gKamelo linked a pull request Apr 26, 2020 that will close this issue
@solita-jtn
Copy link

Any change this could be revisited? We are seeing this a lot with our users. We can at least help to test the possible fix.

@brendanlensink brendanlensink removed their assignment Jan 28, 2022
Sign up for free to join this conversation on GitHub. Already have an account? Sign in to comment
Labels
None yet
Projects
None yet
Development

Successfully merging a pull request may close this issue.

4 participants