DFU update failed (TIMEOUT occured)

[amineKhik]

Where do you suspect the issue?

Issue related to Android version or specific device

Version

2.4.0

Describe the issue

I am using DFU Bootloader v8.1.0 for my application and trying to perform a DFU using the DFU app version 2.4.0. I am using a Redmi 9C running Android 10 for the process.
The issue is that whenever I start the DFU, it always returns an error during the initialization. The logs can be found below.
I tried debugging the bootloader during the process and discovered that the issue stems from the pstorage_callback_handler function, specifically in the case where the callback code is PSTORAGE_CLEAR_OP_CODE. In this case, m_data_pkt_cb returns the error code NRF_ERROR_TIMEOUT.
However, when I tried with another phone, a Pixel 5, the process worked without any issues. This suggests that the issue may be reproducible on specific phones.
Can anyone help me solve this issue?
Note: I tried increasing the BLE connection parameters, but this did not resolve the problem.

Relevant log output

V 16:36:28.450 [DFU] DFU service started
V 16:36:28.459 [DFU] Opening file...
I 16:36:28.480 [DFU] Firmware file opened successfully
V 16:36:28.488 [DFU] Connecting to DFU target...
D 16:36:28.494 [DFU] gatt = device.connectGatt(autoConnect = false, TRANSPORT_LE, preferredPhy = LE_1M | LE_2M)
D 16:36:29.962 [DFU] [Broadcast] Action received: android.bluetooth.device.action.ACL_CONNECTED
I 16:36:30.004 [DFU] Connected to F0:AA:0E:80:2E:B4
V 16:36:30.022 [DFU] Discovering services...
D 16:36:30.045 [DFU] gatt.discoverServices()
I 16:36:30.971 [DFU] Services discovered
V 16:36:30.988 [DFU] Reading DFU version number...
D 16:36:31.002 [DFU] gatt.readCharacteristic(00001534-1212-efde-1523-785feabcd123)
I 16:36:31.072 [DFU] Read Response received from 00001534-1212-efde-1523-785feabcd123, value (0x): 01-00
A 16:36:31.090 [DFU] Version number read: 0.1
W 16:36:31.106 [DFU] Application with buttonless update found
V 16:36:31.118 [DFU] Jumping to the DFU Bootloader...
V 16:36:31.129 [DFU] Enabling notifications for 00001531-1212-efde-1523-785feabcd123
D 16:36:31.141 [DFU] gatt.setCharacteristicNotification(00001531-1212-efde-1523-785feabcd123, true)
D 16:36:31.151 [DFU] gatt.writeDescriptor(00002902-0000-1000-8000-00805f9b34fb, value=0x01-00)
I 16:36:31.165 [DFU] Data written to descr.00001531-1212-efde-1523-785feabcd123
V 16:36:31.174 [DFU] Notifications enabled for 00001531-1212-efde-1523-785feabcd123
A 16:36:31.184 [DFU] Notifications enabled
V 16:36:31.194 [DFU] Writing to characteristic 00001531-1212-efde-1523-785feabcd123, value (0x): 01-04
D 16:36:31.203 [DFU] gatt.writeCharacteristic(00001531-1212-efde-1523-785feabcd123)
A 16:36:31.263 [DFU] Jump to bootloader sent (Op Code = 1, Upload Mode = 4)
I 16:36:31.365 [DFU] Disconnected by the remote device
D 16:36:31.382 [DFU] gatt.refresh() (hidden)
D 16:36:31.398 [DFU] gatt.disconnect()
D 16:36:31.415 [DFU] gatt.close()
D 16:36:31.426 [DFU] [Broadcast] Action received: android.bluetooth.device.action.ACL_DISCONNECTED
V 16:36:31.435 [DFU] DFU service started
I 16:36:31.441 [DFU] Firmware file opened successfully
V 16:36:31.446 [DFU] Connecting to DFU target...
D 16:36:31.451 [DFU] gatt = device.connectGatt(autoConnect = false, TRANSPORT_LE, preferredPhy = LE_1M | LE_2M)
D 16:36:31.857 [DFU] [Broadcast] Action received: android.bluetooth.device.action.ACL_CONNECTED
I 16:36:31.884 [DFU] Connected to F0:AA:0E:80:2E:B4
V 16:36:31.902 [DFU] Discovering services...
D 16:36:31.915 [DFU] gatt.discoverServices()
I 16:36:33.051 [DFU] Services discovered
V 16:36:33.058 [DFU] Reading DFU version number...
D 16:36:33.066 [DFU] gatt.readCharacteristic(00001534-1212-efde-1523-785feabcd123)
I 16:36:33.085 [DFU] Read Response received from 00001534-1212-efde-1523-785feabcd123, value (0x): 06-00
A 16:36:33.098 [DFU] Version number read: 0.6
V 16:36:33.105 [DFU] Enabling notifications for 00001531-1212-efde-1523-785feabcd123
D 16:36:33.112 [DFU] gatt.setCharacteristicNotification(00001531-1212-efde-1523-785feabcd123, true)
D 16:36:33.121 [DFU] gatt.writeDescriptor(00002902-0000-1000-8000-00805f9b34fb, value=0x01-00)
I 16:36:33.129 [DFU] Data written to descr.00001531-1212-efde-1523-785feabcd123
V 16:36:33.207 [DFU] Notifications enabled for 00001531-1212-efde-1523-785feabcd123
A 16:36:33.218 [DFU] Notifications enabled
V 16:36:33.228 [DFU] Writing to characteristic 00001531-1212-efde-1523-785feabcd123, value (0x): 01-04
D 16:36:33.238 [DFU] gatt.writeCharacteristic(00001531-1212-efde-1523-785feabcd123)
I 16:36:33.246 [DFU] Data written to 00001531-1212-efde-1523-785feabcd123
A 16:36:33.257 [DFU] DFU Start sent (Op Code = 1, Upload Mode = 4)
V 16:36:33.263 [DFU] Writing to characteristic 00001532-1212-efde-1523-785feabcd123, value (0x): 00-00-00-00-00-00-00-00-04-E5-00-00
D 16:36:33.270 [DFU] gatt.writeCharacteristic(00001532-1212-efde-1523-785feabcd123)
I 16:36:33.276 [DFU] Data written to 00001532-1212-efde-1523-785feabcd123
A 16:36:33.281 [DFU] Firmware image size sent (0b, 0b, 58628b)
E 16:36:38.142 [DFU] Device has disconnected
D 16:36:38.178 [DFU] gatt.disconnect()
D 16:36:38.196 [DFU] gatt.close()
D 16:36:38.224 [DFU] [Broadcast] Action received: android.bluetooth.device.action.ACL_DISCONNECTED

[philips77]

Hello,
I can see that the disconnection happens after sending the image size:

A 16:36:33.281 [DFU] Firmware image size sent (0b, 0b, 58628b)
E 16:36:38.142 [DFU] Device has disconnected

There's a 5 second delay between these two messages, suggesting that the device started erasing memory and does not reply when doing so. The connection parameters may have a Supervision Timeout set to 5 seconds, so after that time the phone disconnects. I suggest requesting a different supervision timeout from the device side before DFU or checking why the device does not reply. Some phones request 20 second timeout instead of 5, perhaps that's why it works on other phones. Check the time that it takes for the device to reply to firmware image size sent command on phones that are working.

[amineKhik]

Hello,
Thank you for your prompt reply.
I believe the issue is caused by the library starting from version 2.2.0. I conducted the same tests with older versions, specifically those between 2.0.0 and 2.1.0. With these versions, the DFU works correctly with no issues. However, when updating the application starting from version 2.2.0, the issue occurs consistently on the Redmi 9C.
Additionally, below you will find the logs from another phone, the Pixel 5, running the latest version of the application, which is working fine:

V 09:54:26.607 [DFU] DFU service started
V 09:54:26.610 [DFU] Opening file...
I 09:54:26.620 [DFU] Firmware file opened successfully
V 09:54:26.622 [DFU] Connecting to DFU target...
D 09:54:26.624 [DFU] gatt = device.connectGatt(autoConnect = false, TRANSPORT_LE, preferredPhy = LE_1M | LE_2M)
I 09:54:26.994 [DFU] Connected to F0:AA:0E:80:2E:B4
V 09:54:27.001 [DFU] Discovering services...
D 09:54:27.005 [DFU] gatt.discoverServices()
D 09:54:27.050 [DFU] [Broadcast] Action received: android.bluetooth.device.action.ACL_CONNECTED
I 09:54:27.984 [DFU] Services discovered
V 09:54:27.995 [DFU] Reading DFU version number...
D 09:54:28.002 [DFU] gatt.readCharacteristic(00001534-1212-efde-1523-785feabcd123)
I 09:54:28.009 [DFU] Read Response received from 00001534-1212-efde-1523-785feabcd123, value (0x): 01-00
A 09:54:28.016 [DFU] Version number read: 0.1
W 09:54:28.022 [DFU] Application with buttonless update found
V 09:54:28.030 [DFU] Jumping to the DFU Bootloader...
V 09:54:28.039 [DFU] Requesting new MTU...
D 09:54:28.044 [DFU] gatt.requestMtu(517)
I 09:54:28.051 [DFU] MTU changed to: 23
V 09:54:28.058 [DFU] Enabling notifications for 00001531-1212-efde-1523-785feabcd123
D 09:54:28.066 [DFU] gatt.setCharacteristicNotification(00001531-1212-efde-1523-785feabcd123, true)
D 09:54:28.073 [DFU] gatt.writeDescriptor(00002902-0000-1000-8000-00805f9b34fb, value=0x01-00)
I 09:54:28.123 [DFU] Data written to descr.00001531-1212-efde-1523-785feabcd123
V 09:54:28.129 [DFU] Notifications enabled for 00001531-1212-efde-1523-785feabcd123
A 09:54:28.135 [DFU] Notifications enabled
V 09:54:28.141 [DFU] Writing to characteristic 00001531-1212-efde-1523-785feabcd123, value (0x): 01-04
D 09:54:28.148 [DFU] gatt.writeCharacteristic(00001531-1212-efde-1523-785feabcd123, value=0x01-04, WRITE_TYPE_DEFAULT)
A 09:54:28.211 [DFU] Jump to bootloader sent (Op Code = 1, Upload Mode = 4)
I 09:54:28.308 [DFU] Disconnected by the remote device
D 09:54:28.312 [DFU] gatt.refresh() (hidden)
D 09:54:28.315 [DFU] gatt.disconnect()
D 09:54:28.317 [DFU] gatt.close()
V 09:54:28.336 [DFU] DFU service started
I 09:54:28.339 [DFU] Firmware file opened successfully
V 09:54:28.341 [DFU] Connecting to DFU target...
D 09:54:28.343 [DFU] [Broadcast] Action received: android.bluetooth.device.action.ACL_DISCONNECTED
D 09:54:28.347 [DFU] gatt = device.connectGatt(autoConnect = false, TRANSPORT_LE, preferredPhy = LE_1M | LE_2M)
I 09:54:28.842 [DFU] Connected to F0:AA:0E:80:2E:B4
V 09:54:28.849 [DFU] Discovering services...
D 09:54:28.854 [DFU] gatt.discoverServices()
D 09:54:28.861 [DFU] [Broadcast] Action received: android.bluetooth.device.action.ACL_CONNECTED
I 09:54:29.693 [DFU] Services discovered
V 09:54:29.707 [DFU] Reading DFU version number...
D 09:54:29.716 [DFU] gatt.readCharacteristic(00001534-1212-efde-1523-785feabcd123)
I 09:54:29.728 [DFU] Read Response received from 00001534-1212-efde-1523-785feabcd123, value (0x): 06-00
A 09:54:29.737 [DFU] Version number read: 0.6
V 09:54:29.743 [DFU] Requesting new MTU...
D 09:54:29.751 [DFU] gatt.requestMtu(517)
I 09:54:29.759 [DFU] MTU changed to: 23
V 09:54:29.770 [DFU] Enabling notifications for 00001531-1212-efde-1523-785feabcd123
D 09:54:29.777 [DFU] gatt.setCharacteristicNotification(00001531-1212-efde-1523-785feabcd123, true)
D 09:54:29.783 [DFU] gatt.writeDescriptor(00002902-0000-1000-8000-00805f9b34fb, value=0x01-00)
I 09:54:29.819 [DFU] Data written to descr.00001531-1212-efde-1523-785feabcd123
V 09:54:29.829 [DFU] Notifications enabled for 00001531-1212-efde-1523-785feabcd123
A 09:54:29.836 [DFU] Notifications enabled
V 09:54:29.844 [DFU] Writing to characteristic 00001531-1212-efde-1523-785feabcd123, value (0x): 01-04
D 09:54:29.852 [DFU] gatt.writeCharacteristic(00001531-1212-efde-1523-785feabcd123, value=0x01-04, WRITE_TYPE_DEFAULT)
I 09:54:29.877 [DFU] Data written to 00001531-1212-efde-1523-785feabcd123
A 09:54:29.886 [DFU] DFU Start sent (Op Code = 1, Upload Mode = 4)
V 09:54:29.894 [DFU] Writing to characteristic 00001532-1212-efde-1523-785feabcd123, value (0x): 00-00-00-00-00-00-00-00-04-E5-00-00
D 09:54:29.903 [DFU] gatt.writeCharacteristic(00001532-1212-efde-1523-785feabcd123, value=00-00-00-00-00-00-00-00-04-E5-00-00, WRITE_TYPE_NO_RESPONSE)
I 09:54:29.911 [DFU] Data written to 00001532-1212-efde-1523-785feabcd123
A 09:54:29.919 [DFU] Firmware image size sent (0b, 0b, 58628b)
I 09:54:32.079 [DFU] Notification received from 00001531-1212-efde-1523-785feabcd123, value (0x): 10-01-01
A 09:54:32.098 [DFU] Response received (Op Code = 1 Status = 1)
A 09:54:32.110 [DFU] Writing Initialize DFU Parameters...
V 09:54:32.118 [DFU] Writing to characteristic 00001531-1212-efde-1523-785feabcd123, value (0x): 02-00
D 09:54:32.124 [DFU] gatt.writeCharacteristic(00001531-1212-efde-1523-785feabcd123, value=0x02-00, WRITE_TYPE_DEFAULT)
I 09:54:32.159 [DFU] Data written to 00001531-1212-efde-1523-785feabcd123
V 09:54:32.170 [DFU] Writing to characteristic 00001532-1212-efde-1523-785feabcd123 value (0x): FF-FF-DD-DD-FF-FF-FF-FF-01-00-64-00-8F-27
D 09:54:32.177 [DFU] gatt.writeCharacteristic(00001532-1212-efde-1523-785feabcd123, value=0xFF-FF-DD-DD-FF-FF-FF-FF-01-00-64-00-8F-27, WRITE_TYPE_NO_RESPONSE)
I 09:54:32.183 [DFU] Data written to 00001532-1212-efde-1523-785feabcd123
V 09:54:32.190 [DFU] Writing to characteristic 00001531-1212-efde-1523-785feabcd123, value (0x): 02-01
D 09:54:32.196 [DFU] gatt.writeCharacteristic(00001531-1212-efde-1523-785feabcd123, value=0x02-01, WRITE_TYPE_DEFAULT)
I 09:54:32.217 [DFU] Notification received from 00001531-1212-efde-1523-785feabcd123, value (0x): 10-02-01
I 09:54:32.225 [DFU] Data written to 00001531-1212-efde-1523-785feabcd123
A 09:54:32.231 [DFU] Initialize DFU Parameters completed
A 09:54:32.236 [DFU] Response received (Op Code = 2, Status = 1)
V 09:54:32.243 [DFU] Writing to characteristic 00001531-1212-efde-1523-785feabcd123, value (0x): 03
D 09:54:32.250 [DFU] gatt.writeCharacteristic(00001531-1212-efde-1523-785feabcd123, value=0x03, WRITE_TYPE_DEFAULT)
I 09:54:32.278 [DFU] Data written to 00001531-1212-efde-1523-785feabcd123
A 09:54:32.285 [DFU] Receive Firmware Image request sent
A 09:54:32.296 [DFU] Uploading firmware...
V 09:54:32.304 [DFU] Sending firmware to characteristic 00001532-1212-efde-1523-785feabcd123...
I 09:54:47.048 [DFU] Notification received from 00001531-1212-efde-1523-785feabcd123, value (0x): 10-03-01
A 09:54:47.060 [DFU] Response received (Op Code = 3, Status = 1)
A 09:54:47.066 [DFU] Upload completed in 14006 ms
V 09:54:47.070 [DFU] Writing to characteristic 00001531-1212-efde-1523-785feabcd123, value (0x): 04
D 09:54:47.075 [DFU] gatt.writeCharacteristic(00001531-1212-efde-1523-785feabcd123, value=0x04, WRITE_TYPE_DEFAULT)
I 09:54:47.097 [DFU] Data written to 00001531-1212-efde-1523-785feabcd123
A 09:54:47.104 [DFU] Validate request sent
I 09:54:47.160 [DFU] Notification received from 00001531-1212-efde-1523-785feabcd123, value (0x): 10-04-01
A 09:54:47.168 [DFU] Response received (Op Code = 4, Status = 1)
V 09:54:47.177 [DFU] Writing to characteristic 00001531-1212-efde-1523-785feabcd123, value (0x): 05
D 09:54:47.184 [DFU] gatt.writeCharacteristic(00001531-1212-efde-1523-785feabcd123, value=0x05, WRITE_TYPE_DEFAULT)
I 09:54:47.249 [DFU] Data written to 00001531-1212-efde-1523-785feabcd123
A 09:54:47.256 [DFU] Activate and Reset request sent
I 09:54:47.344 [DFU] Disconnected by the remote device
D 09:54:47.353 [DFU] gatt.refresh() (hidden)
D 09:54:47.361 [DFU] gatt.disconnect()
D 09:54:47.368 [DFU] gatt.close()
D 09:54:47.384 [DFU] [Broadcast] Action received: android.bluetooth.device.action.ACL_DISCONNECTED

[amineKhik]

Hello,
I have discovered a way to make it work by bonding the device and the peripheral before starting a DFU, and it's working fine. If the peripheral is not bonded, the DFU always fails.
Could you please explain why the DFU fails when bonding is not established? From my understanding, bonding is not mandatory for performing a DFU.

[philips77]

Hello,

On your last logs you can find these:

A 09:54:29.919 [DFU] Firmware image size sent (0b, 0b, 58628b)
// erasing slot for new image, takes 2 seconds
I 09:54:32.079 [DFU] Notification received from 00001531-1212-efde-1523-785feabcd123, value (0x): 10-01-01
A 09:54:32.098 [DFU] Response received (Op Code = 1 Status = 1)

However, on the non-working log there's this:

A 16:36:33.281 [DFU] Firmware image size sent (0b, 0b, 58628b)
// after 5 seconds the phone disconnects, I think due to supervision timeout
E 16:36:38.142 [DFU] Device has disconnected

Perhaps the device isn't sending any packets when it's erasing the slot? The phone can think that the connected device has been reset / died and reports disconnection.

Did you do the tests on the same device and in the same state? In example, was the slot empty already in both cases, or is it that the 1st dfu worked, but following didn't?

[philips77]

Could you please explain why the DFU fails when bonding is not established? From my understanding, bonding is not mandatory for performing a DFU.

I did some (a lot) testing. I believe I know what's going on. On one of my devices (Samsung Tab A8) I am not able to reconnect to the device in bootloader mode after using Buttonless service. This was found on DFU from nRF5 SDK 8 and 11 (and i believe all in between). The reason is that the bootloader is using Direct advertising with very short advertising interval (3 ms). Samsung Tab A8 cannot reconnect to it, while other phones (Pixel 5 and Pixel 7 can without any problems).
This seems to work when the tablet is bonded, which would match your description.

I added a hint to the logs with possible workaround:

1. bond (as you said)
2. trigger DFU bootloader mode using a button (without buttonless service it's broadcasting)
3. modify the bootloader firmware not to use Direct advertising (may not be possible when the devices are already in the field)

[philips77]

A way to test it:

1. Check if your device is from nRF5 SDK version 8-11? I don't know how 7 or 7.1 behaves.
2. On affected phone / tablet open nRF Connect for Mobile app scan and connect to the device in normal mode.
3. Enable notifications in DFU Control Point characteristic.
4. Tap Write icon in DFU Control Point and send "Start DFU" with "Application" selected (0x01-04).
5. The device should restart (observe possible LED indication).
6. Got o Scanner tab and start scanning. The device should not change the MAC address, so observe how the advertising data changes. The packet may be empty - no name, no Service UUID. Check if advertising interval is very short.
7. Try scanning for this device on another device - it should not be shown there - only the device which triggered jump to bootloader mode should be able to scan it.
8. Affected devices won't be able to connect to it. Every time you should get 133 error.
9. Non-affected devices should connect without problems.

[philips77]

Hmm... in your case you are able to connect to the device in bootloader mode... so it must be a different issue.
The one I'm describing wouldn't go that far.

But I also managed to get your case, i believe. Let me try something.

[philips77]

This may be the same as #376.

[gte1]

We are also having to support an old product with nRF51822 and SDK8.1, and we see similar behaviour, particularly when the firmware image gets larger. But if I increase the supervision timeout in the SDK8 bootloader from 4 to 8 seconds, then dfu works fine. Tried this out with nRFConnect for Android 4.28.1 (but I guess this does not have the latest Android DFU library?)

Update: worked yesterday, but today it only intermittently works (random), so something else is going on....

[tudang88]

Hello, I have discovered a way to make it work by bonding the device and the peripheral before starting a DFU, and it's working fine. If the peripheral is not bonded, the DFU always fails. Could you please explain why the DFU fails when bonding is not established? From my understanding, bonding is not mandatory for performing a DFU.

Hi @amineKhik

I'm facing the same issue and trying to find a way to workaround because the device already in the field.
Can you share how to bond before starting a DFU?
Thank you in advance.
Best Regards,