Init packet not sent on iOS
QuentinFarizon opened this issue · 22 comments
I created this issue on november but the initial fix proposed was wrong and it derailed.
DFU Bootloader version (please complete the following information):
- SDK version: SDK 16
- Bonding used: no
- Library version: 4.11.1
Device information (please complete the following information):
- Device: all iPhone/iPad
- OS: all iOS versions
Describe the bug
On iOS, some customers can't perform a DFU.
This issue increased in proportion with newer versions of iOS, increasing in proportion from a few percent errors at summer 2022 to almost all iOS phones at end of 2022.
As we did not reproduce on nRF connect, and observed that on new iOS there was a ATT MTU exchange prior to sending the init packet, we added a delay of 3 seconds between connection successful and starting DFU.
(on nRF connect, there is a natural delay because you need to connect, then manually use the file picker for zip selection)
Adding the 3 seconds delay reduced the percentage of customers with error from almost ~100% to 30%. We plan to increase the delay further but this is definitely not the best solution.
I feel that the library should await that all exchanges are done before sending the init packet. Somehow it is just not sent.
Logs
You can see my implementation here : https://github.com/QuentinFarizon/cordova-plugin-ble-central/blob/no_background_permissions_dfu/src/ios/BLECentralPlugin.m#L488
This is integrated in my Ionic/Cordova application.
Logs from device when connecting+DFU from iOS :
00> <info> app: Phone connected
00> <debug> app: PHY update request.
00> <debug> app: Unkwown on_ble_peripheral_evt : 34
00> <debug> nrf_ble_gatt: Peer on connection 0x1 requested a data length of 251 bytes.
00> <debug> nrf_ble_gatt: Updating data length to 27 on connection 0x1.
00> <debug> app: Unkwown on_ble_peripheral_evt : 35
00> <debug> nrf_ble_gatt: Data length updated to 27 on connection 0x1.
00> <debug> nrf_ble_gatt: max_rx_octets: 27
00> <debug> nrf_ble_gatt: max_tx_octets: 27
00> <debug> nrf_ble_gatt: max_rx_time: 2120
00> <debug> nrf_ble_gatt: max_tx_time: 2120
00> <debug> app: ATT MTU exchange completed. central 0x17 peripheral 0x17
00> <debug> app: Unkwown on_ble_peripheral_evt : 36
00> <debug> nrf_ble_gatt: Peer on connection 0x1 requested an ATT MTU of 293 bytes.
00> <debug> nrf_ble_gatt: Updating ATT MTU to 23 bytes (desired: 23) on connection 0x1.
00> <info> app: Data len is set to 0x14(20)
00> <debug> app: ATT MTU exchange completed. central 0x17 peripheral 0x17
00> <debug> app: Unkwown on_ble_peripheral_evt : 85
00> <debug> app: Unkwown on_ble_peripheral_evt : 80
<from there, nothing, we are connected, but we do not receive the DFU command>
Logs from device when connecting+DFU from Android :
00> <info> app: Phone connected
00> <debug> app: Unkwown on_ble_peripheral_evt : 18
00> <debug> app: Unkwown on_ble_peripheral_evt : 18
00> <debug> app: Unkwown on_ble_peripheral_evt : 80
00> <debug> app: Unkwown on_ble_peripheral_evt : 81
00> <info> app: Device is preparing to enter bootloader mode.
00> <debug> app: Disconnected connection handle 1
00> <info> app: Disconnected 1 links.
00> <debug> app: In ble_dfu_buttonless_bootloader_start_finalize
00>
00> <info> app: Device will enter bootloader mode.
00> <info> app: Power management wants to reset to DFU mode.
00> <info> app: Power management allowed to reset to DFU mode.
@philips77 I am reading #473 (comment)
Am I supposed to set PRNs to 0 ? Should I manage myself peripheralIsReady(toSendWriteWithoutResponse)? I'd expect the library to wait for peripheral ready before writing data
Hello,
Could you paste here logs from the log delegate from dfu library? That would tell us a lot.
I have never seen a need for an initial delay. Our test app was performing series of dfu operations one after another just after connection and had 100% success rate.
The library is managing the outgoing buffer on its own. Setting prn to 0 makes upload faster, but fails for some devices with slower flash memory.
@philips77 Maybe your test scénario uses a board with a MTU already at 40, so there is no need for a MTU update exchange ?
Our board has a initial MTU of 23
Also you said your test "had/was", but the issue is only with recent iOS versions. It had been working for us without a delay for years, until now
We reproduced on an iPhone. For this one, increasing the delay to 3sec or even 8sec doesn't fix the issue.
It's connecting but never starts the DFU.
For the same board, same code, it's not working for this iPhone but working for another.
For the non-working iphone 13 max iOS 16.0.2 :
00> <info> app: Phone connected
00> <debug> app: PHY update request.
00> <debug> app: Unkwown on_ble_peripheral_evt : 34
00> <debug> nrf_ble_gatt: Peer on connection 0x1 requested a data length of 251 bytes.
00> <debug> nrf_ble_gatt: Updating data length to 27 on connection 0x1.
00> <debug> app: Unkwown on_ble_peripheral_evt : 35
00> <debug> nrf_ble_gatt: Data length updated to 27 on connection 0x1.
00> <debug> nrf_ble_gatt: max_rx_octets: 27
00> <debug> nrf_ble_gatt: max_tx_octets: 27
00> <debug> nrf_ble_gatt: max_rx_time: 2120
00> <debug> nrf_ble_gatt: max_tx_time: 2120
00> <debug> app: ATT MTU exchange completed. central 0x17 peripheral 0x17
00> <debug> app: Unkwown on_ble_peripheral_evt : 36
00> <debug> nrf_ble_gatt: Peer on connection 0x1 requested an ATT MTU of 293 bytes.
00> <debug> nrf_ble_gatt: Updating ATT MTU to 23 bytes (desired: 23) on connection 0x1.
00> <info> app: Data len is set to 0x14(20)
00> <debug> app: ATT MTU exchange completed. central 0x17 peripheral 0x17
00> <debug> app: Unkwown on_ble_peripheral_evt : 85 // BLE_GATTS_EVT_EXCHANGE_MTU_REQUEST
00> <debug> app: Unkwown on_ble_peripheral_evt : 80 // BLE_GATTS_EVT_WRITE
<nothing sent anymore>
For the working iphone 12 mini iOS 16.3.1 :
00> <info> app: Phone connected
00> <debug> app: PHY update request.
00> <debug> app: Unkwown on_ble_peripheral_evt : 34
00> <debug> nrf_ble_gatt: Peer on connection 0x1 requested a data length of 251 bytes.
00> <debug> nrf_ble_gatt: Updating data length to 27 on connection 0x1.
00> <debug> app: Unkwown on_ble_peripheral_evt : 35
00> <debug> nrf_ble_gatt: Data length updated to 27 on connection 0x1.
00> <debug> nrf_ble_gatt: max_rx_octets: 27
00> <debug> nrf_ble_gatt: max_tx_octets: 27
00> <debug> nrf_ble_gatt: max_rx_time: 2120
00> <debug> nrf_ble_gatt: max_tx_time: 2120
00> <debug> app: ATT MTU exchange completed. central 0x17 peripheral 0x17
00> <debug> app: Unkwown on_ble_peripheral_evt : 36
00> <debug> nrf_ble_gatt: Peer on connection 0x1 requested an ATT MTU of 293 bytes.
00> <debug> nrf_ble_gatt: Updating ATT MTU to 23 bytes (desired: 23) on connection 0x1.
00> <info> app: Data len is set to 0x14(20)
00> <debug> app: ATT MTU exchange completed. central 0x17 peripheral 0x17
00> <debug> app: Unkwown on_ble_peripheral_evt : 85 // BLE_GATTS_EVT_EXCHANGE_MTU_REQUEST
00> <debug> app: Unkwown on_ble_peripheral_evt : 80 // BLE_GATTS_EVT_WRITE
00> <debug> app: Unkwown on_ble_peripheral_evt : 80 // BLE_GATTS_EVT_WRITE
00> <debug> app: Unkwown on_ble_peripheral_evt : 81 // BLE_GATTS_EVT_RW_AUTHORIZE_REQUEST
00> <debug> app: Unkwown on_ble_peripheral_evt : 83 // BLE_GATTS_EVT_HVC
00> <debug> app: Unkwown on_ble_peripheral_evt : 81 // BLE_GATTS_EVT_RW_AUTHORIZE_REQUEST
00> <info> app: Device is preparing to enter bootloader mode.
00> <debugby the > app: Disconnected connection handle 1
00> <info> app: Disconnected 1 links.
00> <debug> app: In ble_dfu_buttonless_bootloader_start_finalize
00>
00> <info> app: Device will enter bootloader mode.
00> <info> app: Power management wants to reset to DFU mode.
00> <info> app: Power management allowed to reset to DFU mode.
I'm completely lost as to why the DFU is never started by the library and what's seemingly blocking the process
I have tried : connecting -> waiting 3s -> requesting MTU of 293 -> waiting 3s -> starting DFU
Same issue, no luck
Hi,
I have an idea. Did you try with iOS 16.2+ or before iOS 16?
On iOS 16 and 16.1 Apple decided to be very strict in the connection intervals. Their []guidelines](https://developer.apple.com/accessories/Accessory-Design-Guidelines.pdf) in chapter 41.6 say:
The connection parameter request may be rejected if it does not meet the following guidelines:
● Peripheral Latency of up to 30 connection intervals.
● Supervision Timeout from 2 seconds to 6 seconds.
● Interval Min of at least 15 ms.
● Interval Min is a multiple of 15 ms.
● One of the following:
● Interval Max at least 15 ms greater than Interval Min.
● Interval Max and Interval Min both set to 15 ms.
● Interval Max * (Peripheral Latency + 1) of 2 seconds or less.
● Supervision Timeout greater than Interval Max * (Peripheral Latency + 1) * 3.Note:
If an accessory requests both an Interval Min and Interval Max of 15 ms, some devices will
scale the interval to 30 ms to balance power and performance constraints.
In out testing, in iOS 16 and 16.1 when min and max connection interval was too low (e.g. 15ms), the iPhone was dropping connection.
Perhaps your device is switching to longer connection interval after some time, and with the longer interval it works?
Did you try on iOS 16.2+?
Unfortunately, if that's the root cause, there's nothing we can do in the library. Remember, that it is the iOS that initiates MTU request just after connection, not the library.
@philips77 We have changed recently from "min 7.5ms / max 150 ms" to "min 15ms / max 150 ms" to match Apple recommendations, but I doubt that is the cause since our max connection interval was correct.
Moreover, our issue occurs with all recent iOS versions, before 16, between 16.0 and 16.2, and after
version | nb errors
------------+-------
iOS 14.4 | 1
iOS 14.7.1 | 1
iOS 15.5 | 5
iOS 15.6 | 3
iOS 15.6.1 | 70
iOS 15.7 | 17
iOS 15.7.1 | 6
iOS 16.0 | 62
iOS 16.0.1 | 4
iOS 16.0.2 | 59
iOS 16.0.3 | 11
iOS 16.1 | 40
iOS 16.1.1 | 135
iOS 16.1.2 | 81
iOS 16.2 | 282
iOS 16.3 | 86
iOS 16.3.1 | 63
iOS 16.4 | 2
Are you sure the library waits for the MTU request ?
I guess using https://developer.apple.com/documentation/corebluetooth/cbperipheraldelegate/2874034-peripheralisready
That method is for handling outgoing buffer when multiple write requests are made. As the connection can send data slower than they are added to the queue, at some point writeValue(_:for:type:) will fail (buffer full) and sender needs to wait for the peripheral to be ready again. It has nothing to do with MTU, which on iOS is handled internally by the system together with connection. The library / app just received connection state change event meaning it can start discovering services. MTU should already be negotiated at that moment.
Again, could you post there logs from the logDelegate from the iOS DFU library? Are you able to reproduce the issue on your side?
We reproduce randomly on one phone, we are trying to setup the environment to get the logs
@philips77 Setting PRNs to 0 fixed the issue on the phone at work where we reproduced.
Looking at this code comment, it kind of makes sense : "If PRNs are enabled we ignore this second case as the PRNs are responsible for synchronization."
// This callback is called from SecureDFUControlPoint in 2 cases: when a PRN
// is received (`bytesReceived` contains number of bytes reported), or when the
// iOS reports the `peripheralIsReady(toSendWriteWithoutResponse:)` callback
// (`bytesReceived` is `nil`). If PRNs are enabled we ignore this second case as
// the PRNs are responsible for synchronization.
Try PRN = 12. That should also work, but should be faster.
I was at 10 before, I don't really understand what that means, but don't you think PRNs are the cause of the issue if you disable waiting for ready to write, and then failing to write the init packet ?
So I have no idea why disabling PRNs (setting it to 0) fixed your issue. This setting is only used when the fw is actually sent. Before that the library is dosing service discovery, reads Command Object (Init packet) data, creates one, sends Init Packet (with no PRNs), creates a Data Object and only then starts sending firmware (with or without PRNs).
From what you wrote I understood that the lib doesn't even have a chance to do the initialization, that's why I asked for the logs from the library. To see where it actually stops.
PRNs are not be needed on iOS 11+, btw. They were introduced before, as then iOS didn't have any method preventing butter overflow other than just manually limiting upload speed.
@philips77 I printed the logs from delegate (initiator.logger), there is no logs on any level when there is the error.
When everything is OK, I get logs correctly.
We never enter the first state changed (deviceConnecting)
Hi, i don't think it's possible to not get any logs of the dfu if started. In any path at least the central manager state is logged. Did you try debugging it?
Do you get and error in error(_:didOccurWithMessage:)?
Ok, the issue was that I was passing an incorrect file name to the library. It was difficult to debug as I was not retrieving the error message correctly (furthermore, the error message was unclear : "Invalid firmware")
Which lib version are you using? The latest one should throw when you create a DFUFirmware object, I suppose...