Buttonless DFU not working with my App, but with DFU example OK

[alphapapa]

Hi Nordic team,

I have a 52832_xxaa processor with SDK 14.2 and Softdevice 5.1.0. My App run without problems if I only add SD. No problems as well if I add my bootloader (incl. App Settings).
A DFU from my mobile (Sony with andriod, last version) doesn't work.

To prove my bootloader is ok, I tried the buttonless example from the SDK first. Setup was: SD + my bootloader + settings flashed via nRFConnect J-Link Programmer.
With this setup, I can see DFUTarg on my mobile, start DFU, transfer the example and successfully start the example app after reset.

If I do the same with my app, the DFU transfer works well and also after reset I can see my app runing correctly. If I try to DFU my app again know using my app as buttonless DFU service, the DFUTarg (bootloader) is starting, but no transfer of data happens.

Here is my log file, I hope you can help my finding the source of the problem.

Fullscreen Log 2023-10-16 21_32_29 My App trying to DFU the buttonless DFU example.txt Download

nRF Connect, 2023-10-16
DRACER000003 (F0:CF:C4:F3:10:D0)
V	21:30:37.034	Connecting to F0:CF:C4:F3:10:D0...
D	21:30:37.034	gatt = device.connectGatt(autoConnect = false, TRANSPORT_LE, preferred PHY = LE 1M)
D	21:30:37.393	[Callback] Connection state changed with status: 0 and new state: CONNECTED (2)
I	21:30:37.393	Connected to F0:CF:C4:F3:10:D0
V	21:30:37.421	Discovering services...
D	21:30:37.421	gatt.discoverServices()
D	21:30:37.433	[Broadcast] Action received: android.bluetooth.device.action.ACL_CONNECTED
I	21:30:37.830	Connection parameters updated (interval: 7.5ms, latency: 0, timeout: 5000ms)
D	21:30:38.037	[Callback] Services discovered with status: 0
I	21:30:38.037	Services discovered
V	21:30:38.041	Generic Access (0x1800)
- Device Name [R W] (0x2A00)
- Appearance [R] (0x2A01)
- Peripheral Preferred Connection Parameters [R] (0x2A04)
- Central Address Resolution [R] (0x2AA6)
Generic Attribute (0x1801)
Secure DFU Service (0xFE59)
- Buttonless DFU [I W] (8ec90003-f315-4f60-9fb8-838830daea50)
   Client Characteristic Configuration (0x2902)
Nordic UART Service (6e400001-b5a3-f393-e0a9-e50e24dcca9e)
- RX Characteristic [W WNR] (6e400002-b5a3-f393-e0a9-e50e24dcca9e)
- TX Characteristic [N] (6e400003-b5a3-f393-e0a9-e50e24dcca9e)
   Client Characteristic Configuration (0x2902)
D	21:30:38.043	gatt.setCharacteristicNotification(6e400003-b5a3-f393-e0a9-e50e24dcca9e, true)
I	21:30:38.144	Connection parameters updated (interval: 45.0ms, latency: 0, timeout: 5000ms)
I	21:30:40.709	PHY updated (TX: LE 2M, RX: LE 2M)
I	21:30:43.365	Connection parameters updated (interval: 75.0ms, latency: 0, timeout: 4000ms)
V	21:31:02.751	[DFU] DFU service started
V	21:31:02.751	[DFU] Opening file...
I	21:31:02.766	[DFU] Firmware file opened successfully
V	21:31:02.768	[DFU] Connecting to DFU target...
D	21:31:02.783	[DFU] gatt = device.connectGatt(autoConnect = false, TRANSPORT_LE, preferredPhy = LE_1M | LE_2M)
I	21:31:02.783	[DFU] Connected to F0:CF:C4:F3:10:D0
V	21:31:02.783	[DFU] Discovering services...
D	21:31:02.783	[DFU] gatt.discoverServices()
I	21:31:02.804	[DFU] Services discovered
D	21:31:02.804	[DFU] wait(1000)
W	21:31:03.815	[DFU] Application with buttonless update found
V	21:31:03.815	[DFU] Jumping to the DFU Bootloader...
V	21:31:03.815	[DFU] Enabling indications for 8ec90003-f315-4f60-9fb8-838830daea50
D	21:31:03.816	[DFU] gatt.setCharacteristicNotification(8ec90003-f315-4f60-9fb8-838830daea50, true)
D	21:31:03.816	[DFU] gatt.writeDescriptor(00002902-0000-1000-8000-00805f9b34fb, value=0x02-00)
I	21:31:03.916	[DFU] Data written to descr.8ec90003-f315-4f60-9fb8-838830daea50, value (0x): 02-00
V	21:31:03.916	[DFU] Notifications enabled for 8ec90003-f315-4f60-9fb8-838830daea50
A	21:31:03.918	[DFU] Indications enabled
D	21:31:03.918	[DFU] wait(1000)
V	21:31:04.940	[DFU] Writing to characteristic 8ec90003-f315-4f60-9fb8-838830daea50
D	21:31:04.940	[DFU] gatt.writeCharacteristic(8ec90003-f315-4f60-9fb8-838830daea50)
A	21:31:05.040	[DFU] Enter bootloader sent (Op Code = 1)
I	21:31:05.041	[DFU] Notification received from 8ec90003-f315-4f60-9fb8-838830daea50, value (0x): 20-01-01
A	21:31:05.041	[DFU] Response received (Op Code = 1, Status = 1)
D	21:31:05.041	[DFU] gatt.refresh() (hidden)
D	21:31:05.045	[DFU] gatt.disconnect()
D	21:31:05.047	[DFU] gatt.close()
V	21:31:05.051	[DFU] Scanning for the DFU Bootloader... (timeout 5000 ms)
I	21:31:05.211	[DFU] DFU Bootloader found with address F0:CF:C4:F3:10:D1
V	21:31:05.227	[DFU] DFU service started
I	21:31:05.227	[DFU] Firmware file opened successfully
D	21:31:05.227	[DFU] wait(1000)
I	21:31:05.792	Connection parameters updated (interval: 7.5ms, latency: 0, timeout: 5000ms)
D	21:31:06.227	[DFU] wait(1000)
V	21:31:07.248	[DFU] Connecting to DFU target...
D	21:31:07.250	[DFU] gatt = device.connectGatt(autoConnect = false, TRANSPORT_LE, preferredPhy = LE_1M | LE_2M)
I	21:31:07.694	[DFU] Connected to F0:CF:C4:F3:10:D1
V	21:31:07.702	[DFU] Discovering services...
D	21:31:07.702	[DFU] gatt.discoverServices()
D	21:31:07.835	[DFU] [Broadcast] Action received: android.bluetooth.device.action.ACL_CONNECTED
I	21:31:08.321	[DFU] Services discovered
D	21:31:08.321	[DFU] wait(1000)
V	21:31:09.321	[DFU] Requesting new MTU...
D	21:31:09.322	[DFU] gatt.requestMtu(517)
D	21:31:10.820	[Callback] Connection state changed with status: 8 and new state: DISCONNECTED (0)
E	21:31:10.821	Error 8 (0x8): GATT CONN TIMEOUT
I	21:31:10.822	Disconnected
D	21:31:10.855	[Broadcast] Action received: android.bluetooth.device.action.ACL_DISCONNECTED
V	21:31:14.206	[DFU] Enabling notifications for 8ec90001-f315-4f60-9fb8-838830daea50
D	21:31:14.206	[DFU] gatt.setCharacteristicNotification(8ec90001-f315-4f60-9fb8-838830daea50, true)
D	21:31:14.251	[DFU] gatt.writeDescriptor(00002902-0000-1000-8000-00805f9b34fb, value=0x01-00)
E	21:31:14.251	[DFU] Device has disconnected
D	21:31:14.251	[DFU] gatt.disconnect()
D	21:31:14.251	[DFU] gatt.close()
D	21:31:14.255	[DFU] [Broadcast] Action received: android.bluetooth.device.action.ACL_DISCONNECTED
V	21:31:14.260	[DFU] DFU service started
I	21:31:14.260	[DFU] Firmware file opened successfully
D	21:31:14.260	[DFU] wait(1000)
D	21:31:15.282	[DFU] wait(1000)
V	21:31:16.260	[DFU] Connecting to DFU target...
D	21:31:16.294	[DFU] gatt = device.connectGatt(autoConnect = false, TRANSPORT_LE, preferredPhy = LE_1M | LE_2M)
E	21:31:46.294	[DFU] Connection failed (0xFF): UNKNOWN (255)
W	21:31:46.295	[DFU] Retrying...
D	21:31:46.295	[DFU] gatt.refresh() (hidden)
D	21:31:46.301	[DFU] gatt.disconnect()
D	21:31:46.303	[DFU] gatt.close()
V	21:31:46.322	[DFU] DFU service started
I	21:31:46.322	[DFU] Firmware file opened successfully
D	21:31:46.322	[DFU] wait(1000)
D	21:31:47.338	[DFU] wait(1000)
V	21:31:48.323	[DFU] Connecting to DFU target...
D	21:31:48.324	[DFU] gatt = device.connectGatt(autoConnect = false, TRANSPORT_LE, preferredPhy = LE_1M | LE_2M)
E	21:32:18.337	[DFU] Connection failed (0xFF): UNKNOWN (255)
W	21:32:18.337	[DFU] Retrying...
D	21:32:18.337	[DFU] gatt.refresh() (hidden)
D	21:32:18.341	[DFU] gatt.disconnect()
D	21:32:18.343	[DFU] gatt.close()
V	21:32:18.358	[DFU] DFU service started
I	21:32:18.358	[DFU] Firmware file opened successfully
D	21:32:18.358	[DFU] wait(1000)
D	21:32:19.358	[DFU] wait(1000)
V	21:32:20.376	[DFU] Connecting to DFU target...
D	21:32:20.376	[DFU] gatt = device.connectGatt(autoConnect = false, TRANSPORT_LE, preferredPhy = LE_1M | LE_2M)

Kind regards, Andreas

[Einar Thorsrud]

Hi,

Based on the log it seems that there is a problem connecting to the device after it entered bootloader mode. First there is a supervsion timeout, and then there is a connection failed for some reason. Do you have another phone to test with? Do you see the same in that case? If not, can you let me know which exact phone model you are using and which Android version it is using?

Also, are you able to make a sniffer trace and also get a log from the bootloader? For the latter you will need to use the debug bootloader (example project suffixed with _debug), which has RTT logging enabled.

Lastly,  if this an old/existing product or a new product? If it is a new product I would recommend that you use a newer SDK. Preferably the nRF Connect SDK which is under active development, but at least the latest nRF5 SDK (17.1.0), which is the last nRF5 SDK version.

[alphapapa]

Hi Einar,

thanks for the quick reply. The phone is a Sony XQ-CC54 with current Android. The problem is the same also with an old Samsung A5 phone.

I can't create a sniffer log, I don't have a DK, only my customer board.

The project is based on an older project, which even still used SD 3.0. I transferred it - to be able to use at least the buttonless bootloder - to SDK 14.2 and SD 5.1. This was necessary because at first only the xxab type should be used and the newer SDs need much more space. In the meantime the xxaa is used, therefore an update would be possible. If it is not absolutely necessary, I would like to postpone this to a later time and concentrate more on the actual development at the moment.

What I can add as information is, that my app uses the NUS service in addition to the DFU. Do I need to stop the NUS service before I dop into DFU process?

As all is running perfect with my phone, the examle buttonless DFU combined with my bootloader and the SD, I guess it has to do with my app. The only difference I can see between the example and my app is, that I use

    init.srdata.uuids_complete.uuid_cnt = sizeof(m_adv_uuids) / sizeof(m_adv_uuids[0]);
    init.srdata.uuids_complete.p_uuids  = m_adv_uuids;

instead of

    init.advdata.uuids_complete.uuid_cnt = sizeof(m_adv_uuids) / sizeof(m_adv_uuids[0]);
    init.advdata.uuids_complete.p_uuids  = m_adv_uuids;

If I use advdata I get only 4 characters as device name.

I could install the debug version of the bootloader and log the following sequences:
First the log when the buttonless example was running, OTA DFU my app successfull:

Fullscreen log_DFU_my_app_while_buttoness_example_is_running.log Download

# SEGGER J-Link RTT Viewer V7.80c Terminal Log File
# Compiled: 16:09:36 on Sep 27 2022
# Logging started @ 17 Oct 2023 20:33:15
00> <info> app: Received indication state 1
00> <info> app: Device is preparing to enter bootloader mode.
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.
00> <info> app: Inside main
00> <debug> app: In nrf_bootloader_init
00> <debug> app: in weak nrf_dfu_init_user
00> <debug> app: In real nrf_dfu_init
00> <debug> nrf_dfu_settings: Running nrf_dfu_settings_init(sd_irq_initialized=false).
00> <debug> nrf_dfu_flash: Calling nrf_dfu_flash_init(sd_irq_initialized=false)...
00> <debug> nrf_dfu_flash: Initializing nrf_fstorage_nvmc backend.
00> <debug> app: Initializing the clock.
00> <debug> app: Enter nrf_dfu_continue
00> <debug> app: Valid App
00> <debug> app: Application sent bootloader request
00> <debug> app: In nrf_dfu_transports_init
00> <debug> app: num transports: 1
00> <debug> app: Initializing BLE DFU transport
00> <debug> app: vector table: 0x00073000
00> <debug> app: vector table: 0x00073000
00> <debug> app: Error code - sd_softdevice_vector_table_base_set: 0x00000000
00> <debug> app: Enabling SoftDevice.
00> <warning> nrf_sdh_ble: RAM starts at 0x200025E0, can be adjusted to 0x20001FF0.
00> <warning> nrf_sdh_ble: RAM size can be adjusted to 0xE010.
00> <debug> app: SoftDevice enabled.
00> <debug> app: nrf_dfu_settings_adv_name_is_valid FALSE
00> <debug> app: Regular adv name
00> <debug> app: #### Advertising NO BONDING ####
00> <debug> app: Finished initializing BLE DFU transport
00> <debug> app: After nrf_dfu_transports_init
00> <debug> nrf_dfu_flash: Calling nrf_dfu_flash_init(sd_irq_initialized=true)...
00> <debug> nrf_dfu_flash: Initializing nrf_fstorage_sd backend.
00> <debug> app: Waiting for events
00> <debug> app: Received: BLE_GAP_EVT_CONN_PARAM_UPDATE
00> <debug> app: conn_sup_timeout: 500
00> max_conn_interval: 6
00> min_conn_interval: 6
00> slave_latency 0
00> <debug> app: Received: BLE_GAP_EVT_CONN_PARAM_UPDATE
00> <debug> app: conn_sup_timeout: 500
00> max_conn_interval: 36
00> min_conn_interval: 36
00> slave_latency 0
00> <debug> app: Received select object
00> <info> dfu_req_handling: Valid Command: NRF_DFU_OBJECT_OP_SELECT
00> <debug> app: Sending Object Info: [0x60, 0x06, 0x01 max: 0:x00000100 0:x00000000, CRC:0x00000000]
00> <debug> app: Set receipt notif
00> <debug> app: Sending Response: [0x2, 0x1]
00> <debug> app: Received create object
00> <info> dfu_req_handling: Before OP create command
00> <info> dfu_req_handling: Valid Command Create
00> <debug> app: Sending Response: [0x1, 0x1]
00> <info> dfu_req_handling: Before OP write command
00> <info> dfu_req_handling: Before OP write command
00> <info> dfu_req_handling: Before OP write command
00> <info> dfu_req_handling: Before OP write command
00> <info> dfu_req_handling: Before OP write command
00> <info> dfu_req_handling: Before OP write command
00> <info> dfu_req_handling: Before OP write command
00> <info> dfu_req_handling: Before OP write command
00> <debug> app: Received calculate CRC
00> <info> dfu_req_handling: Valid Command CRC
00> <debug> app: Sending CRC: [0x60, 0x03, 0x01, 0:x0000008D, CRC:0x95F75FE0]
00> <debug> app: Received execute object
00> <info> dfu_req_handling: Before OP execute command
00> <info> dfu_req_handling: Valid command execute
00> <info> dfu_req_handling: PB: Init packet data len: 64
00> <info> dfu_req_handling: Handling signed command
00> <info> dfu_req_handling: Req version: 1, Expected: 1
00> <info> dfu_req_handling: Calculating init packet hash
00> <info> dfu_req_handling: Verify signature
00> <info> dfu_req_handling: Image verified
00> <info> dfu_req_handling: Running hash check
00> <debug> app: Enter nrf_dfu_find_cache
00> <debug> app: Bank content
00> <debug> app: Bank type: 0
00> <debug> app: Bank 0 code: 0x01: Size: 54148
00> <debug> app: Bank 1 code: 0x00: Size: 0
00> <debug> app: free_size before bank select: 315392
00> <debug> app: free_size: 258048, size_req: 76588
00> <debug> app: Using second bank
00> <info> dfu_req_handling: Write address set to 0x00031000
00> <info> dfu_req_handling: DFU prevalidate SUCCESSFUL!
00> <info> dfu_req_handling: Prevalidate OK.
00> <info> dfu_req_handling: Saving init command...
00> <debug> nrf_dfu_settings: Writing settings...
00> <debug> nrf_dfu_settings: Erasing old settings at: 0x0007F000
00> <debug> nrf_dfu_flash: nrf_fstorage_erase(addr=0x0x0007F000, len=1 pages), queue usage: 1
00> <debug> nrf_dfu_flash: nrf_fstorage_write(addr=0x0007F000, len=0x1B8 bytes), queue usage: 2
00> <info> dfu_req_handling: Setting DFU flag to initialized
00> ding 1
00> ding 0
00> ding 0
00> ding 0
00> <debug> nrf_dfu_flash: nrf_fstorage_write(addr=0x00032300, len=0x80 bytes), queue usage: 1
00> <info> dfu_req_handling: Storing 128 bytes at: 0x00032300
00> <debug> nrf_dfu_flash: Flash write success: addr=0x00032300, pending 0
00> <debug> nrf_dfu_flash: nrf_fstorage_write(addr=0x00032380, len=0x80 bytes), queue usage: 1
00> <info> dfu_req_handling: Storing 128 bytes at: 0x00032380
00> <debug> nrf_dfu_flash: Flash write success: addr=0x00032380, pending 0
00> <debug> nrf_dfu_flash: nrf_fstorage_write(addr=0x00032400, len=0x80 bytes), queue usage: 1
00> <info> dfu_req_handling: Storing 128 bytes at: 0x00032400
00> <debug> nrf_dfu_flash: Flash write success: addr=0x00032400, pending 0
00> <debug> nrf_dfu_flash: nrf_fstorage_write(addr=0x00032480, len=0x80 bytes), queue usage: 1
00> <info> dfu_req_handling: Storing 128 bytes at: 0x00032480

...

00> <debug> nrf_dfu_settings: Writing settings...
00> <debug> nrf_dfu_settings: Erasing old settings at: 0x0007F000
00> <debug> nrf_dfu_flash: nrf_fstorage_erase(addr=0x0x0007F000, len=1 pages), queue usage: 1
00> <debug> nrf_dfu_flash: Flash erase success: addr=0x0007F000, pending 0
00> <debug> nrf_dfu_flash: nrf_fstorage_write(addr=0x0007F000, len=0x1B8 bytes), queue usage: 1
00> <debug> nrf_dfu_flash: Flash write success: addr=0x0007F000, pending 0
00> <debug> app: Enter nrf_dfu_app_is_valid
00> <debug> app: Return true. App was valid
00> <debug> app: Enter nrf_dfu_app_is_valid
00> <debug> app: Return true. App was valid
00> <debug> app: Jumping to: 0x00023000
00> <debug> app: Running nrf_<debug> app: Return true. App was valid
00> <debug> app: Enter nrf_dfu_app_is_valid
00> <debug> app: Return true. App was valid
00> <debug> app: Jumping to: 0x00023000
00> [00000000] <info> app: after Reset 0
00> [00000000] <info> app: State 0
00> [00000000] <info> app: State 1
00> [00000000] <info> app: State 2
00> [00000037] <info> app: Setting vector table to bootloader: 0x00073000
00> [00000037] <info> app: Setting vector table to main app: 0x00023000
00> [00000268] <info> app: State 5

# Logging stopped @ 17 Oct 2023 20:35:26

Second log file was taken when my app was running, trying to OTA DFU ma app again. Not succcessful:

Fullscreen log_DFU_my_app_while_my_app_is_running.log Download

00> <info> app: Inside main
00> <debug> app: In nrf_bootloader_init
00> <debug> app: in weak nrf_dfu_init_user
00> <debug> app: In real nrf_dfu_init
00> <debug> nrf_dfu_settings: Running nrf_dfu_settings_init(sd_irq_initialized=false).
00> <debug> nrf_dfu_flash: Calling nrf_dfu_flash_init(sd_irq_initialized=false)...
00> <debug> nrf_dfu_flash: Initializing nrf_fstorage_nvmc backend.
00> <debug> app: Initializing the clock.
00> <debug> app: Enter nrf_dfu_continue
00> <debug> app: Valid App
00> <debug> app: Enter nrf_dfu_app_is_valid
00> <debug> app: Return true. App was valid
00> <debug> app: Enter nrf_dfu_app_is_valid
00> <debug> app: Return true. App was valid
00> [00000000] <info> app: after Reset 0
00> [00000000] <info> app: State 0
00> [00000000] <info> app: State 1
00> [00000000] <info> app: State 2
00> [00000037] <info> app: Setting vector table to bootloader: 0x00073000
00> [00000037] <info> app: Setting vector table to main app: 0x00023000
00> [00000276] <info> app: State 5

[Einar Thorsrud]

Hi,

In the second log it seems that the bootloader starts the app directly, as buttonless DFU has not been requested (if it was, you should see "Application sent bootloader request" in the log). In practice, that means that the magic word that should be set in GPREGRET and which is checked by nrf_dfu_enter_check() in nrf_dfu.c is not set for some reason. So I would start by debugging your application to verify that it actually writes the correct word to GPREGRET before resetting when initiating DFU mode.

[alphapapa]

Hi Einar,

thanks again. I repeated the logging again and this time I only captured the bootloader output. (yesterday I switched between bootloader and my app and maybe corrupted the output) See result below. The magic value B1 is written to the GPREGRET correctly and I can see via debugging, that in the bootloader it is read and later set back to 0.

In the following log file, I added some comments with my ideas on what I would expect at that place, or how I interpret the logging. Hope that helps to finally find the source of the problem.

Fullscreen log_DFU_my_app_while_my_app_is_running_2.log Download

00> <info> app: Inside main
00> <debug> app: In nrf_bootloader_init
00> <debug> app: in weak nrf_dfu_init_user
00> <debug> app: In real nrf_dfu_init
00> <debug> nrf_dfu_settings: Running nrf_dfu_settings_init(sd_irq_initialized=false).
00> <debug> nrf_dfu_flash: Calling nrf_dfu_flash_init(sd_irq_initialized=false)...
00> <debug> nrf_dfu_flash: Initializing nrf_fstorage_nvmc backend.
00> <debug> app: Initializing the clock.
00> <debug> app: Enter nrf_dfu_continue
00> <debug> app: Valid App
00> <debug> app: Application sent bootloader request
00> <debug> app: In nrf_dfu_transports_init
00> <debug> app: num transports: 1
00> <debug> app: Initializing BLE DFU transport
00> <debug> app: vector table: 0x00073000
00> <debug> app: vector table: 0x00073000
00> <debug> app: Error code - sd_softdevice_vector_table_base_set: 0x00000000
00> <debug> app: Enabling SoftDevice.
00> <warning> nrf_sdh_ble: RAM starts at 0x200025E0, can be adjusted to 0x20001FF0.
00> <warning> nrf_sdh_ble: RAM size can be adjusted to 0xE010.
00> <debug> app: SoftDevice enabled.
00> <debug> app: nrf_dfu_settings_adv_name_is_valid FALSE
00> <debug> app: Regular adv name
00> <debug> app: #### Advertising NO BONDING ####
00> <debug> app: Finished initializing BLE DFU transport
00> <debug> app: After nrf_dfu_transports_init
00> <debug> nrf_dfu_flash: Calling nrf_dfu_flash_init(sd_irq_initialized=true)...
00> <debug> nrf_dfu_flash: Initializing nrf_fstorage_sd backend.
00> <debug> app: Waiting for events
00> <debug> app: Received: BLE_GAP_EVT_CONN_PARAM_UPDATE
00> <debug> app: conn_sup_timeout: 500
00> max_conn_interval: 6
00> min_conn_interval: 6
00> slave_latency 0
00> <debug> app: Received: BLE_GAP_EVT_CONN_PARAM_UPDATE
00> <debug> app: conn_sup_timeout: 500
00> max_conn_interval: 36
00> min_conn_interval: 36
00> slave_latency 0
00> <debug> app: Received select object
00> <info> dfu_req_handling: Valid Command: NRF_DFU_OBJECT_OP_SELECT
00> <debug> app: Sending Object Info: [0x60, 0x06, 0x01 max: 0:x00000100 0:x00000000, CRC:0x00000000]
00> <debug> app: Set receipt notif
00> <debug> app: Sending Response: [0x2, 0x1]
00> <debug> app: Received create object
00> <info> dfu_req_handling: Before OP create command
00> <info> dfu_req_handling: Valid Command Create
00> <debug> app: Sending Response: [0x1, 0x1]
00> <info> dfu_req_handling: Before OP write command
00> <info> dfu_req_handling: Before OP write command
00> <info> dfu_req_handling: Before OP write command
00> <info> dfu_req_handling: Before OP write command
00> <info> dfu_req_handling: Before OP write command
00> <info> dfu_req_handling: Before OP write command
00> <info> dfu_req_handling: Before OP write command
00> <info> dfu_req_handling: Before OP write command
00> <debug> app: Received calculate CRC
00> <info> dfu_req_handling: Valid Command CRC
00> <debug> app: Sending CRC: [0x60, 0x03, 0x01, 0:x0000008D, CRC:0x95F75FE0]
00> <debug> app: Received execute object
00> <info> dfu_req_handling: Before OP execute command
00> <info> dfu_req_handling: Valid command execute
00> <info> dfu_req_handling: PB: Init packet data len: 64
00> <info> dfu_req_handling: Handling signed command
00> <info> dfu_req_handling: Req version: 1, Expected: 1
00> <info> dfu_req_handling: Calculating init packet hash
00> <info> dfu_req_handling: Verify signature
00> <info> dfu_req_handling: Image verified
00> <info> dfu_req_handling: Running hash check
00> <debug> app: Enter nrf_dfu_find_cache
00> <debug> app: Bank content
00> <debug> app: Bank type: 0
00> <debug> app: Bank 0 code: 0x01: Size: 76588
00> <debug> app: Bank 1 code: 0x00: Size: 0
00> <debug> app: free_size before bank select: 315392
00> <debug> app: free_size: 237568, size_req: 76588
00> <debug> app: Using second bank
00> <info> dfu_req_handling: Write address set to 0x00036000
00> <info> dfu_req_handling: DFU prevalidate SUCCESSFUL!
00> <info> dfu_req_handling: Prevalidate OK.
00> <info> dfu_req_handling: Saving init command...
00> <debug> nrf_dfu_settings: Writing settings...
00> <debug> nrf_dfu_settings: Erasing old settings at: 0x0007F000
00> <debug> nrf_dfu_flash: nrf_fstorage_erase(addr=0x0x0007F000, len=1 pages), queue usage: 1
00> <debug> nrf_dfu_flash: nrf_fstorage_write(addr=0x0007F000, len=0x1B8 bytes), queue usage: 2
00> <info> dfu_req_handling: Setting DFU flag to initialized

################   Here it should start with "ding 1" and data transfer

00> <debug> app: Sending Response: [0x4, 0x1]
00> <debug> app: Received select object
00> <info> dfu_req_handling: Valid Data Read info
00> <debug> app: Sending Object Info: [0x60, 0x06, 0x01 max: 0:x00001000 0:x00000000, CRC:0x00000000]
00> <debug> nrf_dfu_flash: Flash erase success: addr=0x0007F000, pending 1
00> <debug> nrf_dfu_flash: Flash write success: addr=0x0007F000, pending 0

###############    Looks like a reset was performed

00> <info> app: Inside main
00> <debug> app: In nrf_bootloader_init
00> <debug> app: in weak nrf_dfu_init_user
00> <debug> app: In real nrf_dfu_init
00> <debug> nrf_dfu_settings: Running nrf_dfu_settings_init(sd_irq_initialized=false).
00> <debug> nrf_dfu_flash: Calling nrf_dfu_flash_init(sd_irq_initialized=false)...
00> <debug> nrf_dfu_flash: Initializing nrf_fstorage_nvmc backend.
00> <debug> app: Initializing the clock.
00> <debug> app: Enter nrf_dfu_continue
00> <error> app: Single: Invalid bank
00> <debug> app: Enter nrf_dfu_app_is_valid
00> <debug> app: Return true. App was valid
00> <debug> app: Enter nrf_dfu_app_is_valid
00> <debug> app: Return true. App was valid
00> <debug> app: Jump<info>

###############    Looks like a reset was performed

00> <info> app: Inside main
00> <debug> app: In nrf_bootloader_init
00> <debug> app: in weak nrf_dfu_init_user
00> <debug> app: In real nrf_dfu_init
00> <debug> nrf_dfu_settings: Running nrf_dfu_settings_init(sd_irq_initialized=false).
00> <debug> nrf_dfu_flash: Calling nrf_dfu_flash_init(sd_irq_initialized=false)...
00> <debug> nrf_dfu_flash: Initializing nrf_fstorage_nvmc backend.
00> <debug> app: Initializing the clock.
00> <debug> app: Enter nrf_dfu_continue
00> <error> app: Single: Invalid bank
00> <debug> app: Application sent bootloader request
00> <debug> app: In nrf_dfu_transports_init
00> <debug> app: num transports: 1
00> <debug> app: Initializing BLE DFU transport
00> <debug> app: vector table: 0x00073000
00> <debug> app: vector table: 0x00073000
00> <debug> app: Error code - sd_softdevice_vector_table_base_set: 0x00000000
00> <debug> app: Enabling SoftDevice.
00> <warning> nrf_sdh_ble: RAM starts at 0x200025E0, can be adjusted to 0x20001FF0.
00> <warning> nrf_sdh_ble: RAM size can be adjusted to 0xE010.
00> <debug> app: SoftDevice enabled.
00> <debug> app: nrf_dfu_settings_adv_name_is_valid FALSE
00> <debug> app: Regular adv name
00> <debug> app: #### Advertising NO BONDING ####
00> <debug> app: Finished initializing BLE DFU transport
00> <debug> app: After nrf_dfu_transports_init
00> <debug> nrf_dfu_flash: Calling nrf_dfu_flash_init(sd_irq_initialized=true)...
00> <debug> nrf_dfu_flash: Initializing nrf_fstorage_sd backend.
00> <info> dfu_req_handling: PB: Init packet data len: 64
00> <debug> app: Enter nrf_dfu_find_cache
00> <debug> app: Bank content
00> <debug> app: Bank type: 0
00> <debug> app: Bank 0 code: 0x01: Size: 76588
00> <debug> app: Bank 1 code: 0x00: Size: 76588
00> <debug> app: free_size before bank select: 315392
00> <debug> app: free_size: 237568, size_req: 76588
00> <debug> app: Using second bank
00> <debug> app: Waiting for events

######## "Waiting for events" sounds like bootloader is in standby for data transfer
######## instead there is a next reset

00> <info> app: Inside main
00> <debug> app: In nrf_bootloader_init
00> <debug> app: in weak nrf_dfu_init_user
00> <debug> app: In real nrf_dfu_init
00> <debug> nrf_dfu_settings: Running nrf_dfu_settings_init(sd_irq_initialized=false).
00> <debug> nrf_dfu_flash: Calling nrf_dfu_flash_init(sd_irq_initialized=false)...
00> <debug> nrf_dfu_flash: Initializing nrf_fstorage_nvmc backend.
00> <debug> app: Initializing the clock.
00> <debug> app: Enter nrf_dfu_continue
00> <error> app: Single: Invalid bank
00> <debug> app: Enter nrf_dfu_app_is_valid
00> <debug> app: Return true. App was valid
00> <debug> app: Enter nrf_dfu_app_is_valid
00> <debug> app: Return true. App was valid
00> <debu

I repeated the logging, expecting the same result, but no, it is again different:

Fullscreen log_DFU_my_app_while_my_app_is_running_3.log Download

00> <info> app: Inside main
00> <debug> app: In nrf_bootloader_init
00> <debug> app: in weak nrf_dfu_init_user
00> <debug> app: In real nrf_dfu_init
00> <debug> nrf_dfu_settings: Running nrf_dfu_settings_init(sd_irq_initialized=false).
00> <debug> nrf_dfu_flash: Calling nrf_dfu_flash_init(sd_irq_initialized=false)...
00> <debug> nrf_dfu_flash: Initializing nrf_fstorage_nvmc backend.
00> <debug> app: Initializing the clock.
00> <debug> app: Enter nrf_dfu_continue
00> <error> app: Single: Invalid bank
00> <debug> app: Application sent bootloader request
00> <debug> app: In nrf_dfu_transports_init
00> <debug> app: num transports: 1
00> <debug> app: Initializing BLE DFU transport
00> <debug> app: vector table: 0x00073000
00> <debug> app: vector table: 0x00073000
00> <debug> app: Error code - sd_softdevice_vector_table_base_set: 0x00000000
00> <debug> app: Enabling SoftDevice.
00> <warning> nrf_sdh_ble: RAM starts at 0x200025E0, can be adjusted to 0x20001FF0.
00> <warning> nrf_sdh_ble: RAM size can be adjusted to 0xE010.
00> <debug> app: SoftDevice enabled.
00> <debug> app: nrf_dfu_settings_adv_name_is_valid FALSE
00> <debug> app: Regular adv name
00> <debug> app: #### Advertising NO BONDING ####
00> <debug> app: Finished initializing BLE DFU transport
00> <debug> app: After nrf_dfu_transports_init
00> <debug> nrf_dfu_flash: Calling nrf_dfu_flash_init(sd_irq_initialized=true)...
00> <debug> nrf_dfu_flash: Initializing nrf_fstorage_sd backend.
00> <info> dfu_req_handling: PB: Init packet data len: 64
00> <debug> app: Enter nrf_dfu_find_cache
00> <debug> app: Bank content
00> <debug> app: Bank type: 0
00> <debug> app: Bank 0 code: 0x01: Size: 76588
00> <debug> app: Bank 1 code: 0x00: Size: 76588
00> <debug> app: free_size before bank select: 315392
00> <debug> app: free_size: 237568, size_req: 76588
00> <debug> app: Using second bank
00> <debug> app: Waiting for events
00> <debug> app: Received: BLE_GAP_EVT_CONN_PARAM_UPDATE
00> <debug> app: conn_sup_timeout: 500
00> max_conn_interval: 6
00> min_conn_interval: 6
00> slave_latency 0
00> <debug> app: Received: BLE_GAP_EVT_CONN_PARAM_UPDATE
00> <debug> app: conn_sup_timeout: 500
00> max_conn_interval: 36
00> min_conn_interval: 36
00> slave_latency 0
00> <info> app: Inside main
00> <debug> app: In nrf_bootloader_init
00> <debug> app: in weak nrf_dfu_init_user
00> <debug> app: In real nrf_dfu_init
00> <debug> nrf_dfu_settings: Running nrf_dfu_settings_init(sd_irq_initialized=false).
00> <debug> nrf_dfu_flash: Calling nrf_dfu_flash_init(sd_irq_initialized=false)...
00> <debug> nrf_dfu_flash: Initializing nrf_fstorage_nvmc backend.
00> <debug> app: Initializing the clock.
00> <debug> app: Enter nrf_dfu_continue
00> <error> app: Single: Invalid bank
00> <debug> app: Enter nrf_dfu_app_is_valid
00> <debug> app: Return true. App was valid
00> <debug> app: Enter nrf_dfu_app_is_valid
00> <debug> app: Return true. App was valid

[Einar Thorsrud]

It seems like you get unexpected resets from the bootloader? That also match that there was a supervision timeout in the log from the phone side in your first post. 

Most errors that will trigger a reset would also cause a log to be written. However, in 14.2 this is not properly handles in main.c of the bootloader, as NVIC_SystemReset() is called immediately after NRF_LOG_ERROR. Can you t improve app_error_fault_handler() and app_error_handler_bare() so that they you have a NRF_LOG_FINAL_FLUSH() and a delay between the log statement and the reset, similarly to how it is done in the latest SDK? That would be something similar to this:

#include "nrf_delay.h"

void app_error_fault_handler(uint32_t id, uint32_t pc, uint32_t info)
{
    NRF_LOG_ERROR("Received a fault! id: 0x%08x, pc: 0x%08x, info: 0x%08x", id, pc, info);
    NRF_LOG_FINAL_FLUSH();
    nrf_delay_ms(100);
    NVIC_SystemReset();
}


void app_error_handler_bare(uint32_t error_code)
{
    (void)error_code;
    NRF_LOG_ERROR("Received an error: 0x%08x!", error_code);
    NRF_LOG_FINAL_FLUSH();
    nrf_delay_ms(100);
    NVIC_SystemReset();
}

Other than that, a potential problem could be if the reset pin is asserted for some reason (or is floating), or if VDD drops too low for some reason, or similar. I have no indication that is the problem, but if you are not able to find another reason for the reset, it is worth investigating. In that case you could start with logging the RESETREAS (remember to clear it as it is cumulative).

[alphapapa]

Hi Einar,

I owe you more than a beer! It was the watchdog's fault! I was not aware that it continues to run after a soft reset. As soon as I disable the watchdog in my app everything is OK.

Thanks a lot for your support, the case can be closed.

Andreas