Beware that this post is related to an SDK in maintenance mode
More Info: Consider nRF Connect SDK for new designs
This post is older than 2 years and might not be relevant anymore
More Info: Consider searching for newer posts

Bootloader fails to allocate a memory buffer and DFU hangs - Bug in DFU process

Hi,

I'm working with a modified version of the secure bootloader included in the nRF5 SDK 17.0.0. I'm using an nRF52832 to update an STM32 over the air.

I have two update modes:
- A safe update process which saves the STM firmware on bank 1 and then flashes the firmware using the STM32's I2C bootloader.
- An "on-the-fly" update process which writes data to the STM as it is being received over BLE. This is used when the STM's firmware is too big and does not fit in bank 1.

The issue I have is that in the "on-the-fly" process, the memory buffer is not emptied fast enough, so we fail to allocate further memory blocks. At this point the DFU process hangs. This seems to be a bug in the original bootloader.

The problem as far as I can tell is that the bootloader stops responding to the app. The bug in particular seems to be in `nrf_dfu_ble` lines 590-596. When the bootloader gets to the point where `nrf_balloc_alloc()` returns NULL, the bootloader does nothing. There is a comment in the code that says that operations are retried by the host, but that does not seem to be the case. The nRF Connect app for iOS does not retry anything.

This is the log of the nRF Connect app when it hangs:

File Name: unleashed_stm_Release_2_0_0_1218_beta_20210804_1655.zip
Parts: 1
Size: 202 KB
Soft Device Size: Zero KB
Bootloader Size: Zero KB
[Callback] Central Manager did update state to: Powered ON
Connecting to Unleashed Boot...
centralManager.connect(peripheral, options: nil)
[Callback] Central Manager did connect peripheral
Connected to Unleashed Boot
Discovering services...
peripheral.discoverServices(nil)
Services discovered
Starting Secure DFU...
Connected to Unleashed Boot
Services discovered
Secure DFU Service found
Discovering characteristics in DFU Service...
peripheral.discoverCharacteristics(nil, for: FE59)
DFU characteristics discovered
MTU set to 247
Enabling notifications for 8EC90001-F315-4F60-9FB8-838830DAEA50...
peripheral.setNotifyValue(true, for: 8EC90001-F315-4F60-9FB8-838830DAEA50)
Notifications enabled for 8EC90001-F315-4F60-9FB8-838830DAEA50
Secure DFU Control Point notifications enabled
Writing to characteristic 8EC90001-F315-4F60-9FB8-838830DAEA50...
peripheral.writeValue(0x0601, for: 8EC90001-F315-4F60-9FB8-838830DAEA50, type: .withResponse)
Data written to 8EC90001-F315-4F60-9FB8-838830DAEA50
Notification received from 8EC90001-F315-4F60-9FB8-838830DAEA50, value (0x): 60060100020000d200000000000000
Command object info (Max size = 512, Offset = 210, CRC = 00000000) received
Writing to characteristic 8EC90001-F315-4F60-9FB8-838830DAEA50...
peripheral.writeValue(0x0101d2000000, for: 8EC90001-F315-4F60-9FB8-838830DAEA50, type: .withResponse)
Data written to 8EC90001-F315-4F60-9FB8-838830DAEA50
Notification received from 8EC90001-F315-4F60-9FB8-838830DAEA50, value (0x): 600101
Writing to characteristic 8EC90001-F315-4F60-9FB8-838830DAEA50...
peripheral.writeValue(0x020000, for: 8EC90001-F315-4F60-9FB8-838830DAEA50, type: .withResponse)
Data written to 8EC90001-F315-4F60-9FB8-838830DAEA50
Notification received from 8EC90001-F315-4F60-9FB8-838830DAEA50, value (0x): 600201
Packet Receipt Notif disabled (Op Code = 2, Value = 0)
Writing to characteristic 8EC90002-F315-4F60-9FB8-838830DAEA50...
peripheral.writeValue(0x12cf010a8801080112830108c281801010341a02cb012000280030003898a70c4224080312209068264cad5daac2175e46f366d2eaef955cd9660a33a64faebced854b6cd6ac48005244080312408c4c8869526a007a854a4c0cf8dd662dea794ed1df4e922dbb211872e11c2f115a7dad0ccba90a01839653f3bee043414e08d2c3820722276ae6eeae0dadf0d110001a4026f8ae16faa9d500dfec3c469b669b643eb8c29c1e5cf80e50887a2fb78124f1106ed1da2a5bcb66ce813dcaf7dacd9d42ea6b9c129740e6e97441722ba69674, for: 8EC90002-F315-4F60-9FB8-838830DAEA50, type: .withoutResponse)
Command object sent (CRC = D90B2275)
Writing to characteristic 8EC90001-F315-4F60-9FB8-838830DAEA50...
peripheral.writeValue(0x03, for: 8EC90001-F315-4F60-9FB8-838830DAEA50, type: .withResponse)
Data written to 8EC90001-F315-4F60-9FB8-838830DAEA50
Notification received from 8EC90001-F315-4F60-9FB8-838830DAEA50, value (0x): 600301d200000075220bd9
Checksum (Offset = 210, CRC = D90B2275) received
Writing to characteristic 8EC90001-F315-4F60-9FB8-838830DAEA50...
peripheral.writeValue(0x04, for: 8EC90001-F315-4F60-9FB8-838830DAEA50, type: .withResponse)
Data written to 8EC90001-F315-4F60-9FB8-838830DAEA50
Notification received from 8EC90001-F315-4F60-9FB8-838830DAEA50, value (0x): 600401
Command object executed
Writing to characteristic 8EC90001-F315-4F60-9FB8-838830DAEA50...
peripheral.writeValue(0x020c00, for: 8EC90001-F315-4F60-9FB8-838830DAEA50, type: .withResponse)
Data written to 8EC90001-F315-4F60-9FB8-838830DAEA50
Notification received from 8EC90001-F315-4F60-9FB8-838830DAEA50, value (0x): 600201
Packet Receipt Notif enabled (Op Code = 2, Value = 12)
Writing to characteristic 8EC90001-F315-4F60-9FB8-838830DAEA50...
peripheral.writeValue(0x0602, for: 8EC90001-F315-4F60-9FB8-838830DAEA50, type: .withResponse)
Data written to 8EC90001-F315-4F60-9FB8-838830DAEA50
Notification received from 8EC90001-F315-4F60-9FB8-838830DAEA50, value (0x): 600601001000000000000000000000
Data object info (Max size = 4096, Offset = 0, CRC = 00000000) received
Writing to characteristic 8EC90001-F315-4F60-9FB8-838830DAEA50...
peripheral.writeValue(0x010200100000, for: 8EC90001-F315-4F60-9FB8-838830DAEA50, type: .withResponse)
Data written to 8EC90001-F315-4F60-9FB8-838830DAEA50
Notification received from 8EC90001-F315-4F60-9FB8-838830DAEA50, value (0x): 600101
Data object 1/50 created
wait(400)
Uploading firmware...
Sending firmware to DFU Packet characteristic...
Writing to characteristic 8EC90001-F315-4F60-9FB8-838830DAEA50...
peripheral.writeValue(0x03, for: 8EC90001-F315-4F60-9FB8-838830DAEA50, type: .withResponse)
Data written to 8EC90001-F315-4F60-9FB8-838830DAEA50
Notification received from 8EC90001-F315-4F60-9FB8-838830DAEA50, value (0x): 600301001000009f82036a
Checksum (Offset = 4096, CRC = 6A03829F) received
Writing to characteristic 8EC90001-F315-4F60-9FB8-838830DAEA50...
peripheral.writeValue(0x04, for: 8EC90001-F315-4F60-9FB8-838830DAEA50, type: .withResponse)
Data written to 8EC90001-F315-4F60-9FB8-838830DAEA50
Notification received from 8EC90001-F315-4F60-9FB8-838830DAEA50, value (0x): 600401
Data object executed
Writing to characteristic 8EC90001-F315-4F60-9FB8-838830DAEA50...
peripheral.writeValue(0x010200100000, for: 8EC90001-F315-4F60-9FB8-838830DAEA50, type: .withResponse)
Data written to 8EC90001-F315-4F60-9FB8-838830DAEA50
Notification received from 8EC90001-F315-4F60-9FB8-838830DAEA50, value (0x): 600101
Data object 2/50 created
Uploading firmware...
Sending firmware to DFU Packet characteristic...
Writing to characteristic 8EC90001-F315-4F60-9FB8-838830DAEA50...
peripheral.writeValue(0x03, for: 8EC90001-F315-4F60-9FB8-838830DAEA50, type: .withResponse)
Data written to 8EC90001-F315-4F60-9FB8-838830DAEA50
Notification received from 8EC90001-F315-4F60-9FB8-838830DAEA50, value (0x): 60030100200000d2ac8edf
Checksum (Offset = 8192, CRC = DF8EACD2) received
Writing to characteristic 8EC90001-F315-4F60-9FB8-838830DAEA50...
peripheral.writeValue(0x04, for: 8EC90001-F315-4F60-9FB8-838830DAEA50, type: .withResponse)
Data written to 8EC90001-F315-4F60-9FB8-838830DAEA50
Notification received from 8EC90001-F315-4F60-9FB8-838830DAEA50, value (0x): 600401
Data object executed
Writing to characteristic 8EC90001-F315-4F60-9FB8-838830DAEA50...
peripheral.writeValue(0x010200100000, for: 8EC90001-F315-4F60-9FB8-838830DAEA50, type: .withResponse)
Data written to 8EC90001-F315-4F60-9FB8-838830DAEA50
Notification received from 8EC90001-F315-4F60-9FB8-838830DAEA50, value (0x): 600101
Data object 3/50 created
Uploading firmware...
Sending firmware to DFU Packet characteristic...
Writing to characteristic 8EC90001-F315-4F60-9FB8-838830DAEA50...
peripheral.writeValue(0x03, for: 8EC90001-F315-4F60-9FB8-838830DAEA50, type: .withResponse)
Data written to 8EC90001-F315-4F60-9FB8-838830DAEA50
Notification received from 8EC90001-F315-4F60-9FB8-838830DAEA50, value (0x): 6003010030000090d9c155
Checksum (Offset = 12288, CRC = 55C1D990) received
Writing to characteristic 8EC90001-F315-4F60-9FB8-838830DAEA50...
peripheral.writeValue(0x04, for: 8EC90001-F315-4F60-9FB8-838830DAEA50, type: .withResponse)
Data written to 8EC90001-F315-4F60-9FB8-838830DAEA50
Notification received from 8EC90001-F315-4F60-9FB8-838830DAEA50, value (0x): 600401
Data object executed
Writing to characteristic 8EC90001-F315-4F60-9FB8-838830DAEA50...
peripheral.writeValue(0x010200100000, for: 8EC90001-F315-4F60-9FB8-838830DAEA50, type: .withResponse)
Data written to 8EC90001-F315-4F60-9FB8-838830DAEA50
Notification received from 8EC90001-F315-4F60-9FB8-838830DAEA50, value (0x): 600101
Data object 4/50 created
Uploading firmware...
Sending firmware to DFU Packet characteristic...

I attempted to fix this issue by sending an error response to the app. The app does not seem to recognize the response and it disconnects from my device. This are the logs for that case:

File Name: unleashed_stm_Release_2_0_0_1218_beta_20210804_1655.zip
Parts: 1
Size: 202 KB
Soft Device Size: Zero KB
Bootloader Size: Zero KB
[Callback] Central Manager did update state to: Powered ON
Connecting to Unleashed Boot...
centralManager.connect(peripheral, options: nil)
[Callback] Central Manager did connect peripheral
Connected to Unleashed Boot
Discovering services...
peripheral.discoverServices(nil)
Services discovered
Starting Secure DFU...
Connected to Unleashed Boot
Services discovered
Secure DFU Service found
Discovering characteristics in DFU Service...
peripheral.discoverCharacteristics(nil, for: FE59)
DFU characteristics discovered
MTU set to 247
Enabling notifications for 8EC90001-F315-4F60-9FB8-838830DAEA50...
peripheral.setNotifyValue(true, for: 8EC90001-F315-4F60-9FB8-838830DAEA50)
Notifications enabled for 8EC90001-F315-4F60-9FB8-838830DAEA50
Secure DFU Control Point notifications enabled
Writing to characteristic 8EC90001-F315-4F60-9FB8-838830DAEA50...
peripheral.writeValue(0x0601, for: 8EC90001-F315-4F60-9FB8-838830DAEA50, type: .withResponse)
Data written to 8EC90001-F315-4F60-9FB8-838830DAEA50
Notification received from 8EC90001-F315-4F60-9FB8-838830DAEA50, value (0x): 60060100020000d200000000000000
Command object info (Max size = 512, Offset = 210, CRC = 00000000) received
Writing to characteristic 8EC90001-F315-4F60-9FB8-838830DAEA50...
peripheral.writeValue(0x0101d2000000, for: 8EC90001-F315-4F60-9FB8-838830DAEA50, type: .withResponse)
Data written to 8EC90001-F315-4F60-9FB8-838830DAEA50
Notification received from 8EC90001-F315-4F60-9FB8-838830DAEA50, value (0x): 600101
Writing to characteristic 8EC90001-F315-4F60-9FB8-838830DAEA50...
peripheral.writeValue(0x020000, for: 8EC90001-F315-4F60-9FB8-838830DAEA50, type: .withResponse)
Data written to 8EC90001-F315-4F60-9FB8-838830DAEA50
Notification received from 8EC90001-F315-4F60-9FB8-838830DAEA50, value (0x): 600201
Packet Receipt Notif disabled (Op Code = 2, Value = 0)
Writing to characteristic 8EC90002-F315-4F60-9FB8-838830DAEA50...
peripheral.writeValue(0x12cf010a8801080112830108c281801010341a02cb012000280030003898a70c4224080312209068264cad5daac2175e46f366d2eaef955cd9660a33a64faebced854b6cd6ac48005244080312408c4c8869526a007a854a4c0cf8dd662dea794ed1df4e922dbb211872e11c2f115a7dad0ccba90a01839653f3bee043414e08d2c3820722276ae6eeae0dadf0d110001a4026f8ae16faa9d500dfec3c469b669b643eb8c29c1e5cf80e50887a2fb78124f1106ed1da2a5bcb66ce813dcaf7dacd9d42ea6b9c129740e6e97441722ba69674, for: 8EC90002-F315-4F60-9FB8-838830DAEA50, type: .withoutResponse)
Command object sent (CRC = D90B2275)
Writing to characteristic 8EC90001-F315-4F60-9FB8-838830DAEA50...
peripheral.writeValue(0x03, for: 8EC90001-F315-4F60-9FB8-838830DAEA50, type: .withResponse)
Data written to 8EC90001-F315-4F60-9FB8-838830DAEA50
Notification received from 8EC90001-F315-4F60-9FB8-838830DAEA50, value (0x): 600301d200000075220bd9
Checksum (Offset = 210, CRC = D90B2275) received
Writing to characteristic 8EC90001-F315-4F60-9FB8-838830DAEA50...
peripheral.writeValue(0x04, for: 8EC90001-F315-4F60-9FB8-838830DAEA50, type: .withResponse)
Data written to 8EC90001-F315-4F60-9FB8-838830DAEA50
Notification received from 8EC90001-F315-4F60-9FB8-838830DAEA50, value (0x): 600401
Command object executed
Writing to characteristic 8EC90001-F315-4F60-9FB8-838830DAEA50...
peripheral.writeValue(0x020c00, for: 8EC90001-F315-4F60-9FB8-838830DAEA50, type: .withResponse)
Data written to 8EC90001-F315-4F60-9FB8-838830DAEA50
Notification received from 8EC90001-F315-4F60-9FB8-838830DAEA50, value (0x): 600201
Packet Receipt Notif enabled (Op Code = 2, Value = 12)
Writing to characteristic 8EC90001-F315-4F60-9FB8-838830DAEA50...
peripheral.writeValue(0x0602, for: 8EC90001-F315-4F60-9FB8-838830DAEA50, type: .withResponse)
Data written to 8EC90001-F315-4F60-9FB8-838830DAEA50
Notification received from 8EC90001-F315-4F60-9FB8-838830DAEA50, value (0x): 600601001000000000000000000000
Data object info (Max size = 4096, Offset = 0, CRC = 00000000) received
Writing to characteristic 8EC90001-F315-4F60-9FB8-838830DAEA50...
peripheral.writeValue(0x010200100000, for: 8EC90001-F315-4F60-9FB8-838830DAEA50, type: .withResponse)
Data written to 8EC90001-F315-4F60-9FB8-838830DAEA50
Notification received from 8EC90001-F315-4F60-9FB8-838830DAEA50, value (0x): 600101
Data object 1/50 created
wait(400)
Uploading firmware...
Sending firmware to DFU Packet characteristic...
Writing to characteristic 8EC90001-F315-4F60-9FB8-838830DAEA50...
peripheral.writeValue(0x03, for: 8EC90001-F315-4F60-9FB8-838830DAEA50, type: .withResponse)
Data written to 8EC90001-F315-4F60-9FB8-838830DAEA50
Notification received from 8EC90001-F315-4F60-9FB8-838830DAEA50, value (0x): 600301001000009f82036a
Checksum (Offset = 4096, CRC = 6A03829F) received
Writing to characteristic 8EC90001-F315-4F60-9FB8-838830DAEA50...
peripheral.writeValue(0x04, for: 8EC90001-F315-4F60-9FB8-838830DAEA50, type: .withResponse)
Data written to 8EC90001-F315-4F60-9FB8-838830DAEA50
Notification received from 8EC90001-F315-4F60-9FB8-838830DAEA50, value (0x): 600401
Data object executed
Writing to characteristic 8EC90001-F315-4F60-9FB8-838830DAEA50...
peripheral.writeValue(0x010200100000, for: 8EC90001-F315-4F60-9FB8-838830DAEA50, type: .withResponse)
Data written to 8EC90001-F315-4F60-9FB8-838830DAEA50
Notification received from 8EC90001-F315-4F60-9FB8-838830DAEA50, value (0x): 600101
Data object 2/50 created
Uploading firmware...
Sending firmware to DFU Packet characteristic...
Writing to characteristic 8EC90001-F315-4F60-9FB8-838830DAEA50...
peripheral.writeValue(0x03, for: 8EC90001-F315-4F60-9FB8-838830DAEA50, type: .withResponse)
Data written to 8EC90001-F315-4F60-9FB8-838830DAEA50
Notification received from 8EC90001-F315-4F60-9FB8-838830DAEA50, value (0x): 60030100200000d2ac8edf
Checksum (Offset = 8192, CRC = DF8EACD2) received
Writing to characteristic 8EC90001-F315-4F60-9FB8-838830DAEA50...
peripheral.writeValue(0x04, for: 8EC90001-F315-4F60-9FB8-838830DAEA50, type: .withResponse)
Data written to 8EC90001-F315-4F60-9FB8-838830DAEA50
Notification received from 8EC90001-F315-4F60-9FB8-838830DAEA50, value (0x): 600401
Data object executed
Writing to characteristic 8EC90001-F315-4F60-9FB8-838830DAEA50...
peripheral.writeValue(0x010200100000, for: 8EC90001-F315-4F60-9FB8-838830DAEA50, type: .withResponse)
Data written to 8EC90001-F315-4F60-9FB8-838830DAEA50
Notification received from 8EC90001-F315-4F60-9FB8-838830DAEA50, value (0x): 600101
Data object 3/50 created
Uploading firmware...
Sending firmware to DFU Packet characteristic...
Writing to characteristic 8EC90001-F315-4F60-9FB8-838830DAEA50...
peripheral.writeValue(0x03, for: 8EC90001-F315-4F60-9FB8-838830DAEA50, type: .withResponse)
Notification received from 8EC90001-F315-4F60-9FB8-838830DAEA50, value (0x): 600804
Unknown response received: 0x600804
Disconnecting...
centralManager.cancelPeripheralConnection(peripheral)
[Callback] Central Manager did disconnect peripheral
Disconnected

The nRF Connect version is 2.4.12.

What can I do in this case? Thanks in advance for your support.

  • FYI, I have temporarily fixed this by limiting the BLE throughput and forcing the PHY to stay on 1Mbps, but this isn't a proper fix. We would like to have our firmware updates happen as fast as possible.

  • An "on-the-fly" update process which writes data to the STM as it is being received over BLE

     Typically writing to flash can be a bottleneck, and the speed of the BLE throughput with 2M-PHY, long MTU, DLE enabled, is higher than the flash writing/erasing speed.

    The problem as far as I can tell is that the bootloader stops responding to the app. The bug in particular seems to be in `nrf_dfu_ble` lines 590-596. When the bootloader gets to the point where `nrf_balloc_alloc()` returns NULL, the bootloader does nothing. There is a comment in the code that says that operations are retried by the host, but that does not seem to be the case.

     I have not seen this issue before. Do you have logs from the bootloader as well? The _debug variant of the bootloader project have logging enabled.

Related