NordicSemiconductor / Android-DFU-Library

Device Firmware Update library and Android app
http://www.nordicsemi.com/dfu
BSD 3-Clause "New" or "Revised" License
760 stars 269 forks source link

DFU update failed (TIMEOUT occured) #452

Open amineKhik opened 1 month ago

amineKhik commented 1 month ago

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 commented 1 month ago

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 commented 3 weeks ago

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 commented 2 weeks ago

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 commented 1 week ago

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?