Unable to Perform a DFU over USB CDC ACM (the Bootloader never boots the new app)

[abdelali]

Hi,

For my all DFU i follow the steps on the Getting started guide , just in the Performing DFU step i use the nrfutil tool for the over USB.

First i tried with the DFU examples provided, i started with the open_bootloader , uploaded that to the nrf52840 dk after a full erase. and then use nrfutil to upload the blinky_mbr.zip package located in the secure_dfu_test_images folder. the package gets loaded to the board, i can see the uploading process over the Command line.but, after that the blinky_mbr app never gets started. the board just turns off all the LEDs , and when i Reset it starts in the Bootloader mode, it never jumps to the app. i still can see the the bootloader /app files in nrf connect.

I used the debug version of the bootloader, And here is the logging i get:

Starting from the upload of the bootloader till the end of the DFU.

<info> app: Open USB bootloader started
<debug> app: In nrf_bootloader_init
<debug> nrf_dfu_settings: Calling nrf_dfu_settings_init()...
<debug> nrf_dfu_flash: Initializing nrf_fstorage_nvmc backend.
<warning> nrf_dfu_settings: Resetting bootloader settings since neither the settings page nor the backup are valid (CRC error).
<debug> nrf_dfu_settings: Writing settings...
<debug> nrf_dfu_settings: Erasing old settings at: 0x000FF000
<debug> nrf_dfu_flash: nrf_fstorage_erase(addr=0x0x000FF000, len=1 pages), queue usage: 0
<debug> nrf_dfu_flash: Flash erase success: addr=0x000FF000, pending 0
<debug> nrf_dfu_flash: nrf_fstorage_write(addr=0x000FF000, src=0x20008640, len=896 bytes), queue usage: 1
<debug> nrf_dfu_flash: Flash write success: addr=0x000FF000, pending 0
<info> nrf_dfu_settings: Backing up settings page to address 0xFE000.
<debug> nrf_dfu_settings: Writing settings...
<debug> nrf_dfu_settings: Erasing old settings at: 0x000FE000
<debug> nrf_dfu_flash: nrf_fstorage_erase(addr=0x0x000FE000, len=1 pages), queue usage: 1
<debug> nrf_dfu_flash: Flash erase success: addr=0x000FE000, pending 0
<debug> nrf_dfu_flash: nrf_fstorage_write(addr=0x000FE000, src=0x200089C0, len=896 bytes), queue usage: 1
<debug> nrf_dfu_flash: Flash write success: addr=0x000FE000, pending 0
<debug> app: Enter nrf_bootloader_fw_activate
<info> app: No firmware to activate.
<info> app: Boot validation failed. No valid app to boot.
<debug> app: DFU mode because app is not valid.
<info> nrf_bootloader_wdt: WDT is not enabled
<debug> app: in weak nrf_dfu_init_user
<debug> app: timer_stop (0x20000054)
<info> app: Entering DFU mode.
<info> app_timer: RTC: initialized.
<debug> app: Initializing transports (found: 1)
<debug> nrf_dfu_serial_usb: Initializing drivers.
<debug> nrf_dfu_serial_usb: Starting USB
<debug> nrf_dfu_serial_usb: USB Transport initialized
<debug> nrf_dfu_flash: Initializing nrf_fstorage_nvmc backend.
<debug> app: Enter main loop
<info> nrf_dfu_serial_usb: USB power detected
<info> nrf_dfu_serial_usb: USB ready
<warning> nrf_dfu_serial_usb: Could not read from CDC. Error: 0x92.
<debug> nrf_dfu_serial: Set receipt notif target: 0
<debug> nrf_dfu_serial_usb: Allocated buffer 20000130
<debug> nrf_dfu_req_handler: Handle NRF_DFU_OP_RECEIPT_NOTIF_SET
<debug> nrf_dfu_req_handler: Request handling complete. Result: 0x1
<debug> nrf_dfu_serial: Sending Response: [0x2, 0x1]
<debug> nrf_dfu_serial: Received serial mtu
<debug> nrf_dfu_serial_usb: Allocated buffer 20000130
<debug> nrf_dfu_req_handler: Handle NRF_DFU_OP_MTU_GET
<debug> nrf_dfu_req_handler: Request handling complete. Result: 0x1
<debug> nrf_dfu_serial: Sending Response: [0x7, 0x1]
<debug> nrf_dfu_serial_usb: Allocated buffer 20000130
<debug> nrf_dfu_req_handler: Handle NRF_DFU_OP_OBJECT_SELECT (command)
<debug> nrf_dfu_req_handler: Request handling complete. Result: 0x1
<debug> nrf_dfu_serial: Sending Response: [0x6, 0x1]
<debug> app: Shutting down transports (found: 1)
<debug> nrf_dfu_serial_usb: Allocated buffer 20000130
<debug> nrf_dfu_req_handler: Handle NRF_DFU_OP_OBJECT_CREATE (command)
<debug> app: timer_stop (0x20000054)
<debug> nrf_dfu_req_handler: Request handling complete. Result: 0x1
<debug> nrf_dfu_serial: Sending Response: [0x1, 0x1]
<debug> nrf_dfu_serial_usb: Allocated buffer 20000934
<debug> nrf_dfu_req_handler: Handle NRF_DFU_OP_OBJECT_WRITE (command)
<debug> nrf_dfu_req_handler: Request handling complete. Result: 0x1
<debug> nrf_dfu_serial_usb: Allocated buffer 20000934
<debug> nrf_dfu_req_handler: Handle NRF_DFU_OP_CRC_GET (command)
<debug> nrf_dfu_req_handler: Request handling complete. Result: 0x1
<debug> nrf_dfu_serial: Sending Response: [0x3, 0x1]
<debug> nrf_dfu_serial_usb: Allocated buffer 20000934
<debug> nrf_dfu_req_handler: Handle NRF_DFU_OP_OBJECT_EXECUTE (command)
<debug> nrf_dfu_validation: PB: Init packet data len: 62
<debug> app: Enter nrf_dfu_cache_prepare()
<debug> app: required_size: 0x5E4.
<debug> app: single_bank: true.
<debug> app: keep_app: false.
<debug> app: keep_softdevice: false.
<debug> app: SD_PRESENT: false.
<debug> app: Bank contents:
<debug> app: Bank 0 code: 0x00: Size: 0x0
<debug> app: Bank 1 code: 0x00: Size: 0x0
<debug> app: pass: 0.
<debug> app: cache_address: 0x1000.
<debug> app: cache_too_small: false.
<debug> app: keep_firmware: false.
<debug> app: delete_more: true.
<debug> app: pass: 1.
<debug> app: cache_address: 0x1000.
<debug> app: cache_too_small: false.
<debug> app: keep_firmware: true.
<debug> app: delete_more: true.
<debug> app: Invalidating app.
<debug> nrf_dfu_validation: Write address set to 0x00001000
<debug> nrf_dfu_settings: Writing settings...
<debug> nrf_dfu_settings: Erasing old settings at: 0x000FF000
<debug> nrf_dfu_flash: nrf_fstorage_erase(addr=0x0x000FF000, len=1 pages), queue usage: 1
<debug> nrf_dfu_flash: Flash erase success: addr=0x000FF000, pending 0
<debug> nrf_dfu_flash: nrf_fstorage_write(addr=0x000FF000, src=0x20008640, len=896 bytes), queue usage: 1
<debug> nrf_dfu_flash: Flash write success: addr=0x000FF000, pending 0
<info> nrf_dfu_settings: Backing up settings page to address 0xFE000.
<debug> nrf_dfu_settings: Writing settings...
<debug> nrf_dfu_settings: Erasing old settings at: 0x000FE000
<debug> nrf_dfu_flash: nrf_fstorage_erase(addr=0x0x000FE000, len=1 pages), queue usage: 1
<debug> nrf_dfu_flash: Flash erase success: addr=0x000FE000, pending 0
<debug> nrf_dfu_flash: nrf_fstorage_write(addr=0x000FE000, src=0x200089C0, len=896 bytes), queue usage: 1
<debug> nrf_dfu_flash: Flash write success: addr=0x000FE000, pending 0
<debug> nrf_dfu_req_handler: Writing valid init command to flash.
<debug> nrf_dfu_req_handler: Request handling complete. Result: 0x1
<debug> nrf_dfu_serial: Sending Response: [0x4, 0x1]
<debug> nrf_dfu_serial_usb: Allocated buffer 20000934
<debug> nrf_dfu_req_handler: Handle NRF_DFU_OP_OBJECT_SELECT (data)
<debug> nrf_dfu_req_handler: crc = 0x0, offset = 0x0, max_size = 0x1000
<debug> nrf_dfu_req_handler: Request handling complete. Result: 0x1
<debug> nrf_dfu_serial: Sending Response: [0x6, 0x1]
<debug> nrf_dfu_serial_usb: Allocated buffer 20000934
<debug> nrf_dfu_req_handler: Handle NRF_DFU_OP_OBJECT_CREATE (data)
<debug> nrf_dfu_flash: nrf_fstorage_erase(addr=0x0x00001000, len=1 pages), queue usage: 1
<debug> nrf_dfu_flash: Flash erase success: addr=0x00001000, pending 0
<debug> nrf_dfu_req_handler: Creating object with size: 1508. Offset: 0x00000000, CRC: 0x00000000
<debug> nrf_dfu_req_handler: Request handling complete. Result: 0x1
<debug> nrf_dfu_serial: Sending Response: [0x1, 0x1]
<debug> nrf_dfu_serial_usb: Allocated buffer 20000130
<debug> nrf_dfu_req_handler: Handle NRF_DFU_OP_OBJECT_WRITE (data)
<debug> nrf_dfu_flash: nrf_fstorage_write(addr=0x00001000, src=0x20000938, len=1024 bytes), queue usage: 1
<debug> nrf_dfu_flash: Flash write success: addr=0x00001000, pending 0
<debug> nrf_dfu_req_handler: Request handling complete. Result: 0x1
<debug> nrf_dfu_serial_usb: Allocated buffer 20000934
<debug> nrf_dfu_req_handler: Handle NRF_DFU_OP_OBJECT_WRITE (data)
<debug> nrf_dfu_flash: nrf_fstorage_write(addr=0x00001400, src=0x20000134, len=484 bytes), queue usage: 1
<debug> nrf_dfu_flash: Flash write success: addr=0x00001400, pending 0
<debug> nrf_dfu_req_handler: Request handling complete. Result: 0x1
<debug> nrf_dfu_serial_usb: Allocated buffer 20000934
<debug> nrf_dfu_req_handler: Handle NRF_DFU_OP_CRC_GET (data)
<debug> nrf_dfu_req_handler: Offset:1508, CRC:0x3477E14C
<debug> nrf_dfu_req_handler: Request handling complete. Result: 0x1
<debug> nrf_dfu_serial: Sending Response: [0x3, 0x1]
<debug> nrf_dfu_serial_usb: Allocated buffer 20000934
<debug> nrf_dfu_req_handler: Handle NRF_DFU_OP_OBJECT_EXECUTE (data)
<debug> nrf_dfu_req_handler: Whole firmware image received. Postvalidating.
<debug> nrf_dfu_validation: Hash verification. start address: 0x1000, size: 0x5E4
<debug> nrf_dfu_validation: Invalidating old application in bank 0.
<debug> nrf_dfu_serial: Sending Response: [0x4, 0x1]
<debug> nrf_dfu_settings: Writing settings...
<debug> nrf_dfu_settings: Erasing old settings at: 0x000FF000
<debug> nrf_dfu_flash: nrf_fstorage_erase(addr=0x0x000FF000, len=1 pages), queue usage: 1
<debug> nrf_dfu_flash: Flash erase success: addr=0x000FF000, pending 0
<debug> nrf_dfu_flash: nrf_fstorage_write(addr=0x000FF000, src=0x20008640, len=896 bytes), queue usage: 1
<debug> nrf_dfu_flash: Flash write success: addr=0x000FF000, pending 0
<info> nrf_dfu_settings: Backing up settings page to address 0xFE000.
<debug> nrf_dfu_settings: Writing settings...
<debug> nrf_dfu_settings: Erasing old settings at: 0x000FE000
<debug> nrf_dfu_flash: nrf_fstorage_erase(addr=0x0x000FE000, len=1 pages), queue usage: 1
<debug> nrf_dfu_flash: Flash erase success: addr=0x000FE000, pending 0
<debug> nrf_dfu_flash: nrf_fstorage_write(addr=0x000FE000, src=0x200089C0, len=896 bytes), queue usage: 1
<debug> nrf_dfu_flash: Flash write success: addr=0x000FE000, pending 0
<debug> nrf_dfu_req_handler: All flash operations have completed. DFU completed.
<debug> app: Shutting down transports (found: 1)
<debug> app: Resetting bootloader.
<info> nrf_dfu_settings: Backing up settings page to address 0xFE000.
<debug> nrf_dfu_settings: Destination settings are identical to source, write not needed. Skipping.
<info> app: Open USB bootloader started
<debug> app: In nrf_bootloader_init
<debug> nrf_dfu_settings: Calling nrf_dfu_settings_init()...
<debug> nrf_dfu_flash: Initializing nrf_fstorage_nvmc backend.
<debug> nrf_dfu_settings: Using settings page.
<debug> nrf_dfu_settings: Copying forbidden parts from backup page.
<debug> nrf_dfu_settings: Destination settings are identical to source, write not needed. Skipping.
<info> nrf_dfu_settings: Backing up settings page to address 0xFE000.
<debug> nrf_dfu_settings: Destination settings are identical to source, write not needed. Skipping.
<debug> app: Enter nrf_bootloader_fw_activate
<debug> app: Valid App
<debug> app: Enter nrf_dfu_app_continue
<debug> app: No copy needed
<debug> app: Setting app as valid
<debug> nrf_dfu_settings: Writing settings...
<debug> nrf_dfu_settings: Erasing old settings at: 0x000FF000
<debug> nrf_dfu_flash: nrf_fstorage_erase(addr=0x0x000FF000, len=1 pages), queue usage: 0
<debug> nrf_dfu_flash: Flash erase success: addr=0x000FF000, pending 0
<debug> nrf_dfu_flash: nrf_fstorage_write(addr=0x000FF000, src=0x20008640, len=896 bytes), queue usage: 1
<debug> nrf_dfu_flash: Flash write success: addr=0x000FF000, pending 0
<info> nrf_dfu_settings: Backing up settings page to address 0xFE000.
<debug> nrf_dfu_settings: Writing settings...
<debug> nrf_dfu_settings: Erasing old settings at: 0x000FE000
<debug> nrf_dfu_flash: nrf_fstorage_erase(addr=0x0x000FE000, len=1 pages), queue usage: 1
<debug> nrf_dfu_flash: Flash erase success: addr=0x000FE000, pending 0
<debug> nrf_dfu_flash: nrf_fstorage_write(addr=0x000FE000, src=0x200089C0, len=896 bytes), queue usage: 1
<debug> nrf_dfu_flash: Flash write success: addr=0x000FE000, pending 0
<debug> app: Resetting bootloader.
<info> nrf_dfu_settings: Backing up settings page to address 0xFE000.
<debug> nrf_dfu_settings: Destination settings are identical to source, write not needed. Skipping.
<info> app: Open USB bootloader started
<debug> app: In nrf_bootloader_init

Have also tried to use the secure_bootloader, and trying to upload my DFU package, but same issue .and here is the logging i get:

Logs dropped (1)
<info> cdc_acm: EPOUT_DATA: 01 done
Logs dropped (1)
<info> cdc_acm: EPOUT_DATA: 01 done
Logs dropped (1)
<info> cdc_acm: EPOUT_DATA: 01 done
Logs dropped (1)
<info> cdc_acm: EPOUT_DATA: 01 done
Logs dropped (1)
<info> cdc_acm: EPOUT_DATA: 01 done
Logs dropped (1)
<info> cdc_acm: EPOUT_DATA: 01 done
Logs dropped (1)
<info> cdc_acm: EPOUT_DATA: 01 done
Logs dropped (1)
<info> cdc_acm: EPOUT_DATA: 01 done
Logs dropped (1)
<info> cdc_acm: EPOUT_DATA: 01 done
Logs dropped (1)
<info> cdc_acm: EPOUT_DATA: 01 done
Logs dropped (1)
<debug> nrf_dfu_serial_usb: Allocated buffer 20000924
<debug> nrf_dfu_req_handler: Handle NRF_DFU_OP_OBJECT_WRITE (data)
Logs dropped (1)
<debug> nrf_dfu_flash: nrf_fstorage_write(addr=0x00017400, src=0x20000124, len=1024 bytes), queue usage: 1
Logs dropped (1)
<debug> nrf_dfu_flash: Flash write success: addr=0x00017400, pending 0
Logs dropped (1)
<debug> nrf_dfu_req_handler: Request handling complete. Result: 0x1
Logs dropped (2)
<info> cdc_acm: EPOUT_DATA: 01 done
Logs dropped (2)
<info> cdc_acm: EPOUT_DATA: 01 done
Logs dropped (1)
<info> cdc_acm: EPOUT_DATA: 01 done
Logs dropped (1)
<info> cdc_acm: EPOUT_DATA: 01 done
Logs dropped (2)
<info> cdc_acm: EPOUT_DATA: 01 done
Logs dropped (2)
<info> cdc_acm: EPOUT_DATA: 01 done
Logs dropped (2)
<info> cdc_acm: EPOUT_DATA: 01 done
Logs dropped (2)
<info> cdc_acm: EPOUT_DATA: 01 done
Logs dropped (2)
<info> cdc_acm: EPOUT_DATA: 01 done
Logs dropped (2)
<info> cdc_acm: EPOUT_DATA: 01 done
Logs dropped (3)
<info> cdc_acm: EPOUT_DATA: 01 done
Logs dropped (2)
<info> cdc_acm: EPOUT_DATA: 01 done
Logs dropped (1)
<info> cdc_acm: EPOUT_DATA: 01 done
Logs dropped (2)
<info> cdc_acm: EPOUT_DATA: 01 done
Logs dropped (1)
<info> cdc_acm: EPOUT_DATA: 01 done
Logs dropped (2)
<info> cdc_acm: EPOUT_DATA: 01 done
Logs dropped (1)
<info> cdc_acm: EPOUT_DATA: 01 done
Logs dropped (2)
<debug> nrf_dfu_serial_usb: Allocated buffer 20000120
Logs dropped (2)
<debug> nrf_dfu_req_handler: Handle NRF_DFU_OP_OBJECT_WRITE (data)
Logs dropped (4)
<debug> nrf_dfu_flash: nrf_fstorage_write(addr=0x00017800, src=0x20000928, len=1024 bytes), queue usage: 1
Logs dropped (2)
<debug> nrf_dfu_flash: Flash write success: addr=0x00017800, pending 0
Logs dropped (2)
<debug> nrf_dfu_req_handler: Request handling complete. Result: 0x1
<info> cdc_acm: EPOUT_DATA: 01 done
Logs dropped (2)
<info> cdc_acm: EPOUT_DATA: 01 done
Logs dropped (1)
<info> cdc_acm: EPOUT_DATA: 01 done
Logs dropped (2)
<info> cdc_acm: EPOUT_DATA: 01 done
Logs dropped (1)
<info> cdc_acm: EPOUT_DATA: 01 done
Logs dropped (3)
<info> cdc_acm: EPOUT_DATA: 01 done
Logs dropped (2)
<info> cdc_acm: EPOUT_DATA: 01 done
Logs dropped (1)
<info> cdc_acm: EPOUT_DATA: 01 done
Logs dropped (2)
<info> cdc_acm: EPOUT_DATA: 01 done
Logs dropped (2)
<info> cdc_acm: EPOUT_DATA: 01 done
Logs dropped (2)
<info> cdc_acm: EPOUT_DATA: 01 done
Logs dropped (3)
<info> cdc_acm: EPOUT_DATA: 01 done
Logs dropped (1)
<info> cdc_acm: EPOUT_DATA: 01 done
Logs dropped (2)
<info> cdc_acm: EPOUT_DATA: 01 done
Logs dropped (2)
<info> cdc_acm: EPOUT_DATA: 01 done
Logs dropped (2)
<info> cdc_acm: EPOUT_DATA: 01 done
Logs dropped (2)
<info> cdc_acm: EPOUT_DATA: 01 done
Logs dropped (2)
<debug> nrf_dfu_serial_usb: Allocated buffer 20000924
Logs dropped (2)
<debug> nrf_dfu_req_handler: Handle NRF_DFU_OP_OBJECT_WRITE (data)
Logs dropped (3)
<debug> nrf_dfu_flash: nrf_fstorage_write(addr=0x00017C00, src=0x20000124, len=1024 bytes), queue usage: 1
Logs dropped (2)
<debug> nrf_dfu_flash: Flash write success: addr=0x00017C00, pending 0
Logs dropped (2)
<debug> nrf_dfu_req_handler: Request handling complete. Result: 0x1
<info> cdc_acm: EPOUT_DATA: 01 done
Logs dropped (2)
<debug> nrf_dfu_serial_usb: Allocated buffer 20000924
Logs dropped (2)
<debug> nrf_dfu_req_handler: Handle NRF_DFU_OP_CRC_GET (data)
Logs dropped (2)
<debug> nrf_dfu_req_handler: Offset:94208, CRC:0xA6AE13B9
Logs dropped (2)
<debug> nrf_dfu_req_handler: Request handling complete. Result: 0x1
Logs dropped (2)
<debug> nrf_dfu_serial: Sending Response: [0x3, 0x1]
<info> cdc_acm: EPIN_DATA: 81 done
Logs dropped (2)
<info> cdc_acm: EPOUT_DATA: 01 done
Logs dropped (2)
<debug> nrf_dfu_serial_usb: Allocated buffer 20000924
Logs dropped (2)
<debug> nrf_dfu_req_handler: Handle NRF_DFU_OP_OBJECT_EXECUTE (data)
Logs dropped (2)
<debug> nrf_dfu_serial: Sending Response: [0x4, 0x1]
Logs dropped (2)
<debug> nrf_dfu_req_handler: Request handling complete. Result: 0x1
Logs dropped (2)
<debug> app: timer_stop (0x20000044)
Logs dropped (2)
<debug> app: timer_activate (0x20000044)
Logs dropped (2)
<info> cdc_acm: EPIN_DATA: 81 done
<info> cdc_acm: EPOUT_DATA: 01 done
Logs dropped (2)
<debug> nrf_dfu_serial_usb: Allocated buffer 20000924
Logs dropped (2)
<debug> nrf_dfu_req_handler: Handle NRF_DFU_OP_OBJECT_CREATE (data)
Logs dropped (4)
<debug> nrf_dfu_flash: nrf_fstorage_erase(addr=0x0x00018000, len=1 pages), queue usage: 1
Logs dropped (5)
<debug> nrf_dfu_flash: Flash erase success: addr=0x00018000, pending 0
<debug> nrf_dfu_req_handler: Creating object with size: 4096. Offset: 0x00017000, CRC: 0xA6AE13B9
Logs dropped (2)
<debug> nrf_dfu_req_handler: Request handling complete. Result: 0x1
Logs dropped (2)
<debug> nrf_dfu_serial: Sending Response: [0x1, 0x1]
Logs dropped (1)
<info> cdc_acm: EPIN_DATA: 81 done
<info> cdc_acm: EPOUT_DATA: 01 done
Logs dropped (2)
<info> cdc_acm: EPOUT_DATA: 01 done
Logs dropped (2)
<info> cdc_acm: EPOUT_DATA: 01 done
Logs dropped (2)
<info> cdc_acm: EPOUT_DATA: 01 done
Logs dropped (2)
<info> cdc_acm: EPOUT_DATA: 01 done
Logs dropped (2)
<info> cdc_acm: EPOUT_DATA: 01 done
Logs dropped (2)
<info> cdc_acm: EPOUT_DATA: 01 done
Logs dropped (2)
<info> cdc_acm: EPOUT_DATA: 01 done
Logs dropped (2)
<info> cdc_acm: EPOUT_DATA: 01 done
Logs dropped (2)
<info> cdc_acm: EPOUT_DATA: 01 done
Logs dropped (2)
<info> cdc_acm: EPOUT_DATA: 01 done
Logs dropped (2)
<info> cdc_acm: EPOUT_DATA: 01 done
Logs dropped (2)
<info> cdc_acm: EPOUT_DATA: 01 done
Logs dropped (2)
<info> cdc_acm: EPOUT_DATA: 01 done
Logs dropped (2)
<info> cdc_acm: EPOUT_DATA: 01 done
Logs dropped (2)
<info> cdc_acm: EPOUT_DATA: 01 done
Logs dropped (2)
<info> cdc_acm: EPOUT_DATA: 01 done
Logs dropped (2)
<debug> nrf_dfu_serial_usb: Allocated buffer 20000120
Logs dropped (3)
<debug> nrf_dfu_req_handler: Handle NRF_DFU_OP_OBJECT_WRITE (data)
Logs dropped (2)
<debug> nrf_dfu_flash: nrf_fstorage_write(addr=0x00018000, src=0x20000928, len=1024 bytes), queue usage: 1
Logs dropped (2)
<debug> nrf_dfu_flash: Flash write success: addr=0x00018000, pending 0
Logs dropped (1)
<debug> nrf_dfu_req_handler: Request handling complete. Result: 0x1
Logs dropped (2)
<info> cdc_acm: EPOUT_DATA: 01 done
Logs dropped (2)
<info> cdc_acm: EPOUT_DATA: 01 done
Logs dropped (2)
<info> cdc_acm: EPOUT_DATA: 01 done
Logs dropped (2)
<info> cdc_acm: EPOUT_DATA: 01 done
Logs dropped (2)
<info> cdc_acm: EPOUT_DATA: 01 done
Logs dropped (1)
<info> cdc_acm: EPOUT_DATA: 01 done
Logs dropped (2)
<info> cdc_acm: EPOUT_DATA: 01 done
Logs dropped (2)
<info> cdc_acm: EPOUT_DATA: 01 done
Logs dropped (2)
<info> cdc_acm: EPOUT_DATA: 01 done
Logs dropped (2)
<info> cdc_acm: EPOUT_DATA: 01 done
Logs dropped (2)
<info> cdc_acm: EPOUT_DATA: 01 done
Logs dropped (2)
<info> cdc_acm: EPOUT_DATA: 01 done
Logs dropped (2)
<info> cdc_acm: EPOUT_DATA: 01 done
Logs dropped (2)
<info> cdc_acm: EPOUT_DATA: 01 done
Logs dropped (1)
<info> cdc_acm: EPOUT_DATA: 01 done
Logs dropped (2)
<info> cdc_acm: EPOUT_DATA: 01 done
Logs dropped (2)
<info> cdc_acm: EPOUT_DATA: 01 done
Logs dropped (3)
<debug> nrf_dfu_serial_usb: Allocated buffer 20000924
<debug> nrf_dfu_req_handler: Handle NRF_DFU_OP_OBJECT_WRITE (data)
Logs dropped (3)
<debug> nrf_dfu_flash: nrf_fstorage_write(addr=0x00018400, src=0x20000124, len=1024 bytes), queue usage: 1
Logs dropped (1)
<debug> nrf_dfu_flash: Flash write success: addr=0x00018400, pending 0
Logs dropped (2)
<debug> nrf_dfu_req_handler: Request handling complete. Result: 0x1
Logs dropped (2)
<info> cdc_acm: EPOUT_DATA: 01 done
Logs dropped (1)
<info> cdc_acm: EPOUT_DATA: 01 done
Logs dropped (2)
<info> cdc_acm: EPOUT_DATA: 01 done
Logs dropped (2)
<info> cdc_acm: EPOUT_DATA: 01 done
Logs dropped (2)
<info> cdc_acm: EPOUT_DATA: 01 done
Logs dropped (2)
<info> cdc_acm: EPOUT_DATA: 01 done
Logs dropped (2)
<info> cdc_acm: EPOUT_DATA: 01 done
Logs dropped (2)
<info> cdc_acm: EPOUT_DATA: 01 done
Logs dropped (2)
<info> cdc_acm: EPOUT_DATA: 01 done
Logs dropped (2)
<info> cdc_acm: EPOUT_DATA: 01 done
Logs dropped (2)
<info> cdc_acm: EPOUT_DATA: 01 done
Logs dropped (2)
<info> cdc_acm: EPOUT_DATA: 01 done
Logs dropped (2)
<info> cdc_acm: EPOUT_DATA: 01 done
Logs dropped (2)
<info> cdc_acm: EPOUT_DATA: 01 done
Logs dropped (2)
<info> cdc_acm: EPOUT_DATA: 01 done
Logs dropped (2)
<info> cdc_acm: EPOUT_DATA: 01 done
Logs dropped (2)
<info> cdc_acm: EPOUT_DATA: 01 done
Logs dropped (2)
<debug> nrf_dfu_serial_usb: Allocated buffer 20000120
Logs dropped (2)
<debug> nrf_dfu_req_handler: Handle NRF_DFU_OP_OBJECT_WRITE (data)
Logs dropped (4)
<debug> nrf_dfu_flash: nrf_fstorage_write(addr=0x00018800, src=0x20000928, len=1024 bytes), queue usage: 1
Logs dropped (2)
<debug> nrf_dfu_flash: Flash write success: addr=0x00018800, pending 0
Logs dropped (2)
<debug> nrf_dfu_req_handler: Request handling complete. Result: 0x1
<info> cdc_acm: EPOUT_DATA: 01 done
Logs dropped (2)
<info> cdc_acm: EPOUT_DATA: 01 done
Logs dropped (2)
<info> cdc_acm: EPOUT_DATA: 01 done
Logs dropped (2)
<info> cdc_acm: EPOUT_DATA: 01 done
Logs dropped (2)
<info> cdc_acm: EPOUT_DATA: 01 done
Logs dropped (2)
<info> cdc_acm: EPOUT_DATA: 01 done
Logs dropped (2)
<info> cdc_acm: EPOUT_DATA: 01 done
Logs dropped (2)
<info> cdc_acm: EPOUT_DATA: 01 done
Logs dropped (2)
<info> cdc_acm: EPOUT_DATA: 01 done
Logs dropped (2)
<info> cdc_acm: EPOUT_DATA: 01 done
Logs dropped (2)
<info> cdc_acm: EPOUT_DATA: 01 done
Logs dropped (2)
<info> cdc_acm: EPOUT_DATA: 01 done
Logs dropped (2)
<info> cdc_acm: EPOUT_DATA: 01 done
Logs dropped (2)
<info> cdc_acm: EPOUT_DATA: 01 done
Logs dropped (2)
<info> cdc_acm: EPOUT_DATA: 01 done
Logs dropped (2)
<info> cdc_acm: EPOUT_DATA: 01 done
Logs dropped (2)
<info> cdc_acm: EPOUT_DATA: 01 done
Logs dropped (2)
<debug> nrf_dfu_serial_usb: Allocated buffer 20000924
Logs dropped (2)
<debug> nrf_dfu_req_handler: Handle NRF_DFU_OP_OBJECT_WRITE (data)
Logs dropped (3)
<debug> nrf_dfu_flash: nrf_fstorage_write(addr=0x00018C00, src=0x20000124, len=1024 bytes), queue usage: 1
Logs dropped (2)
<debug> nrf_dfu_flash: Flash write success: addr=0x00018C00, pending 0
Logs dropped (2)
<debug> nrf_dfu_req_handler: Request handling complete. Result: 0x1
<info> cdc_acm: EPOUT_DATA: 01 done
Logs dropped (2)
<debug> nrf_dfu_serial_usb: Allocated buffer 20000924
Logs dropped (2)
<debug> nrf_dfu_req_handler: Handle NRF_DFU_OP_CRC_GET (data)
Logs dropped (2)
<debug> nrf_dfu_req_handler: Offset:98304, CRC:0xD86AAEC2
Logs dropped (2)
<debug> nrf_dfu_req_handler: Request handling complete. Result: 0x1
Logs dropped (2)
<debug> nrf_dfu_serial: Sending Response: [0x3, 0x1]
<info> cdc_acm: EPIN_DATA: 81 done
Logs dropped (2)
<info> cdc_acm: EPOUT_DATA: 01 done
Logs dropped (2)
<debug> nrf_dfu_serial_usb: Allocated buffer 20000924
Logs dropped (2)
<debug> nrf_dfu_req_handler: Handle NRF_DFU_OP_OBJECT_EXECUTE (data)
Logs dropped (2)
<debug> nrf_dfu_serial: Sending Response: [0x4, 0x1]
Logs dropped (2)
<debug> nrf_dfu_req_handler: Request handling complete. Result: 0x1
Logs dropped (2)
<debug> app: timer_stop (0x20000044)
Logs dropped (2)
<debug> app: timer_activate (0x20000044)
Logs dropped (2)
<info> cdc_acm: EPIN_DATA: 81 done
<info> cdc_acm: EPOUT_DATA: 01 done
Logs dropped (2)
<debug> nrf_dfu_serial_usb: Allocated buffer 20000924
Logs dropped (2)
<debug> nrf_dfu_req_handler: Handle NRF_DFU_OP_OBJECT_CREATE (data)
Logs dropped (4)
<debug> nrf_dfu_flash: nrf_fstorage_erase(addr=0x0x00019000, len=1 pages), queue usage: 1
Logs dropped (5)
<debug> nrf_dfu_flash: Flash erase success: addr=0x00019000, pending 0
<debug> nrf_dfu_req_handler: Creating object with size: 784. Offset: 0x00018000, CRC: 0xD86AAEC2
Logs dropped (2)
<debug> nrf_dfu_req_handler: Request handling complete. Result: 0x1
Logs dropped (2)
<debug> nrf_dfu_serial: Sending Response: [0x1, 0x1]
Logs dropped (1)
<info> cdc_acm: EPIN_DATA: 81 done
<info> cdc_acm: EPOUT_DATA: 01 done
Logs dropped (2)
<info> cdc_acm: EPOUT_DATA: 01 done
Logs dropped (2)
<info> cdc_acm: EPOUT_DATA: 01 done
Logs dropped (2)
<info> cdc_acm: EPOUT_DATA: 01 done
Logs dropped (2)
<info> cdc_acm: EPOUT_DATA: 01 done
Logs dropped (2)
<info> cdc_acm: EPOUT_DATA: 01 done
Logs dropped (2)
<info> cdc_acm: EPOUT_DATA: 01 done
Logs dropped (2)
<info> cdc_acm: EPOUT_DATA: 01 done
Logs dropped (2)
<info> cdc_acm: EPOUT_DATA: 01 done
Logs dropped (2)
<info> cdc_acm: EPOUT_DATA: 01 done
Logs dropped (2)
<info> cdc_acm: EPOUT_DATA: 01 done
Logs dropped (2)
<info> cdc_acm: EPOUT_DATA: 01 done
Logs dropped (2)
<info> cdc_acm: EPOUT_DATA: 01 done
Logs dropped (2)
<debug> nrf_dfu_serial_usb: Allocated buffer 20000120
Logs dropped (2)
<debug> nrf_dfu_req_handler: Handle NRF_DFU_OP_OBJECT_WRITE (data)
Logs dropped (4)
<debug> nrf_dfu_flash: nrf_fstorage_write(addr=0x00019000, src=0x20000928, len=784 bytes), queue usage: 1
Logs dropped (5)
<debug> nrf_dfu_flash: Flash write success: addr=0x00019000, pending 0
<debug> nrf_dfu_req_handler: Request handling complete. Result: 0x1
Logs dropped (2)
<info> cdc_acm: EPOUT_DATA: 01 done
<debug> nrf_dfu_serial_usb: Allocated buffer 20000120
Logs dropped (2)
<debug> nrf_dfu_req_handler: Handle NRF_DFU_OP_CRC_GET (data)
Logs dropped (1)
<debug> nrf_dfu_req_handler: Offset:99088, CRC:0x3C49E020
Logs dropped (2)
<debug> nrf_dfu_req_handler: Request handling complete. Result: 0x1
Logs dropped (4)
<debug> nrf_dfu_serial: Sending Response: [0x3, 0x1]
<info> cdc_acm: EPIN_DATA: 81 done
<info> cdc_acm: EPOUT_DATA: 01 done
Logs dropped (2)
<debug> nrf_dfu_serial_usb: Allocated buffer 20000120
Logs dropped (1)
<debug> nrf_dfu_req_handler: Handle NRF_DFU_OP_OBJECT_EXECUTE (data)
<debug> nrf_dfu_req_handler: Whole firmware image received. Postvalidating.
Logs dropped (4)
<debug> nrf_dfu_validation: Hash verification. start address: 0x1000, size: 0x18310
<debug> nrf_dfu_validation: Invalidating old application in bank 0.
Logs dropped (4)
<debug> nrf_dfu_serial: Sending Response: [0x4, 0x1]
<debug> nrf_dfu_settings: Writing settings...
Logs dropped (2)
<debug> nrf_dfu_settings: Erasing old settings at: 0x000FF000
Logs dropped (4)
<debug> nrf_dfu_flash: nrf_fstorage_erase(addr=0x0x000FF000, len=1 pages), queue usage: 1
Logs dropped (3)
<debug> nrf_dfu_flash: Flash erase success: addr=0x000FF000, pending 0
Logs dropped (4)
<debug> nrf_dfu_flash: nrf_fstorage_write(addr=0x000FF000, src=0x200084C8, len=896 bytes), queue usage: 1
Logs dropped (3)
<debug> nrf_dfu_flash: Flash write success: addr=0x000FF000, pending 0
Logs dropped (3)
<info> nrf_dfu_settings: Backing up settings page to address 0xFE000.
<debug> nrf_dfu_settings: Writing settings...
Logs dropped (1)
<debug> nrf_dfu_settings: Erasing old settings at: 0x000FE000
Logs dropped (2)
<debug> nrf_dfu_flash: nrf_fstorage_erase(addr=0x0x000FE000, len=1 pages), queue usage: 1
Logs dropped (2)
<debug> nrf_dfu_flash: Flash erase success: addr=0x000FE000, pending 0
Logs dropped (3)
<debug> nrf_dfu_flash: nrf_fstorage_write(addr=0x000FE000, src=0x20008848, len=896 bytes), queue usage: 1
Logs dropped (4)
<debug> nrf_dfu_flash: Flash write success: addr=0x000FE000, pending 0
Logs dropped (2)
<debug> nrf_dfu_req_handler: All flash operations have completed. DFU completed.
Logs dropped (2)
<debug> app: Shutting down transports (found: 1)
<debug> app: Resetting bootloader.
Logs dropped (2)
<info> nrf_dfu_settings: Backing up settings page to address 0xFE000.
Logs dropped (2)
<debug> nrf_dfu_settings: Destination settings are identical to source, write not needed. Skipping.
<info> app: Inside main
<debug> app: In nrf_bootloader_init
<debug> nrf_dfu_settings: Calling nrf_dfu_settings_init()...
<debug> nrf_dfu_flash: Initializing nrf_fstorage_nvmc backend.
<debug> nrf_dfu_settings: Using settings page.
<debug> nrf_dfu_settings: Copying forbidden parts from backup page.
<debug> nrf_dfu_settings: Destination settings are identical to source, write not needed. Skipping.
<info> nrf_dfu_settings: Backing up settings page to address 0xFE000.
<debug> nrf_dfu_settings: Destination settings are identical to source, write not needed. Skipping.
<debug> app: Enter nrf_bootloader_fw_activate
<debug> app: Valid App
<debug> app: Enter nrf_dfu_app_continue
<debug> app: No copy needed
<debug> app: Setting app as valid
<debug> nrf_dfu_settings: Writing settings...
<debug> nrf_dfu_settings: Erasing old settings at: 0x000FF000
<debug> nrf_dfu_flash: nrf_fstorage_erase(addr=0x0x000FF000, len=1 pages), queue usage: 0
<debug> nrf_dfu_flash: Flash erase success: addr=0x000FF000, pending 0
<debug> nrf_dfu_flash: nrf_fstorage_write(addr=0x000FF000, src=0x200084C8, len=896 bytes), queue usage: 1
<debug> nrf_dfu_flash: Flash write success: addr=0x000FF000, pending 0
<info> nrf_dfu_settings: Backing up settings page to address 0xFE000.
<debug> nrf_dfu_settings: Writing settings...
<debug> nrf_dfu_settings: Erasing old settings at: 0x000FE000
<debug> nrf_dfu_flash: nrf_fstorage_erase(addr=0x0x000FE000, len=1 pages), queue usage: 1
<debug> nrf_dfu_flash: Flash erase success: addr=0x000FE000, pending 0
<debug> nrf_dfu_flash: nrf_fstorage_write(addr=0x000FE000, src=0x20008848, len=896 bytes), queue usage: 1
<debug> nrf_dfu_flash: Flash write success: addr=0x000FE000, pending 0
<debug> app: Resetting bootloader.
<info> nrf_dfu_settings: Backing up settings page to address 0xFE000.
<debug> nrf_dfu_settings: Destination settings are identical to source, write not needed. Skipping.
<info> app: Inside main
<info> app: Inside main

Best Regards,

Abdelali

[bjorn-spockeli]

Hi Abdelali, 
which SDK version are you using?

Can you place a breakpoint at nrf_bootloader_app_start() in nrf_bootloader_init()? IF you reach the nrf_bootloader_app_start() call, then its the application that is not functioning properly. 

Best regards

Bjørn

[abdelali]

Hi Bjørn,

I'm using nRF5_SDK V16.0.0.

Yes i can reach the nrf_bootloader_app_start() call. and here's the log i get after that : 

<debug> app: Running nrf_bootloader_app_start with address: 0x00001000
<debug> app: Disabling interrupts. NVIC->ICER[0]: 0x4

// i think a reset was done here

<info> app: Inside main
<info> app: In nrf_bootloader_init
<debug> nrf_dfu_settings: Calling nrf_dfu_settings_init()...
<debug> nrf_dfu_flash: Initializing nrf_fstorage_nvmc backend.
<debug> nrf_dfu_settings: Using settings page.
<debug> nrf_dfu_settings: Copying forbidden parts from backup page.
<debug> nrf_dfu_settings: Destination settings are identical to source, write not needed. Skipping.
<info> nrf_dfu_settings: Backing up settings page to address 0xFE000.
<debug> nrf_dfu_settings: Destination settings are identical to source, write not needed. Skipping.
<debug> app: Enter nrf_bootloader_fw_activate

and a  NRF_LOG_INFO("p_bank->bank_code = 0x%x.", p_bank->bank_code); at this point returns
<info> app: p_bank->bank_code = 0x0.

i think the issue here is the p_bank->bank_code  value is 0x0 means  NRF_DFU_BANK_INVALID is returned.

and so the bootloader won't ever start the actual application, it will just keep checking for dfu_enter_check() and timeouts.

the bootloader keeps logging  the same logs as above .

Not sure why the p_bank->bank_code = 0 , i'm using the  secure_bootloader\pca10056_usb_debug, tested with the blinky_mbr package provided in secure_dfu_test_images\uart\nrf52840. also with my own generated Zip package, and got the same issue/log.

Best regards,

Abdelali

[abdelali]

Hi Bjørn,

Thanks for the instructions.

Well, I'm able to flash this package blinky_mbr.zip and produce my own, after playing with the blinky main file, to test the firmware update.but, still have the same issue with my application firmware. beside that, i noticed that the blinky example has two versions blank and mbr, i can update the mbr version main file and build the package and successfully flash it .but, this doesn't work for the blank version! even generating the settings file, fail.

Comparing between the two projects, i noticed that the FLASH/RAM START parameters values are different. for the mbr version the FLASH starts at 0x1000, and the RAM at 0x20000008. i think this is what makes it compatible with the bootloader. can you please elaborate a little bit on this ?

My application is a HID device, with the cdc acm class added for serial communication. do i need to update any project settings, or configs in order to build the DFU package ?

Thanks again

Best regards,

Abdelali

[bjorn-spockeli]

abdelali said:

Comparing between the two projects, i noticed that the FLASH/RAM START parameters values are different. for the mbr version the FLASH starts at 0x1000, and the RAM at 0x20000008. i think this is what makes it compatible with the bootloader. can you please elaborate a little bit on this ?

 Yes, if you have an application that does not use the SoftDevice, then the flash start address should be 0x1000 and the RAM start address should be 0x20000008. The SDK examples are not compiled to be position independent so since the MBR occupies the first flash page, i.e. 0x0000 to 0x1000, then the application should be compiled with flash start address set to 0x1000. 

The MBR uses the RAM from 0x20000000 to 0x20000008, so the application RAM start address should be set to 0x20000008.

[abdelali]

Hi Bjorn,

Thanks for that.

Well, i just tested it without using the DFU. the application doesn't start, unless i use the default configuration : 

FLASH_PH_START=0x0
FLASH_PH_SIZE=0x100000
RAM_PH_START=0x20000000
RAM_PH_SIZE=0x40000
FLASH_START=0x000
FLASH_SIZE=0x200000
RAM_START=0x20000000
RAM_SIZE=0x40000

The project does not use the Softdevice, and built on top of the usbd_hid_composite_pca10056 SDK example.

[bjorn-spockeli]

Ok, but did you flash the MBR to the nRF52840 before flashing the application with the updated flash settings?

[abdelali]

Just tested that, works well! didn't know about that before.and this might be the issue for the DFU.

So, for the DFU process and for building the package. i should maybe merge the application (with the updated Flash settings) and the mbr hex files, and use that as it is the hex file of the application. 

Can you please elaborate a little bit on the MBR 'job' compared to the bootloader ?

Thanks again for your assistance, very appreciated!

[bjorn-spockeli]

No, the MBR should be flashed to your NRF52840 together with the bootloader. The MBR will not be modified in any DFU update after it is flashed to the SoC.  The MBR should not be merger with the application. 

The MRB is necessary for the bootloader to perform SoftDevice and Bootloader updates, see Master boot record and bootloader for more information

[abdelali]

Hi Bjorn,

Alright, thanks for the instructions and the link. wasn't aware of that. the DFU process in the docs didn't mention that.

And Thanks again for your assistance.

Best regards,

Abdelali

[bjorn-spockeli]

Happy to help!

Best regards

Bjørn