Help with serial DFU; "Failed to send data over serial interface!"

[nkrinsky]

I'm attempting to use the serial DFU bootloader to update my nRF52832 firmware but am unable to. I started by following this guide though I changed some things so that the uart and not the ble bootloader was loaded. My setup consists of a nRF52832 on a custom board connected via a serial port to a linux computer. I'm using the most recent SDK (15.3) My process so far has been:

1. Generate public and private keys with nrfutil
2. Compiling uECC in external/micro-ecc/nRF52hf_gcc/armgcc
3. Building the bootloader in examples/dfu/secure_bootloader/pca10040_uart_debug/armgcc
4. Flash the nRF with the commands
    

   nrfjprog -f nrf52 --program softdevice.hex --chiperase
   nrfjprog -f nrf52 --program bootloader.hex -r

   
   Thanks to a comment on this post.
   
   I should note that when I flash with the version of the bootloader in pca10040_ble_debug, the nRF now begins advertising with the name DFUTarg, indicating to me that the DFU bootloader has been loaded successfully.
5. In my Linux computer, which is separate from the computer I flashed the Bluetooth module with, I generate a DFU packet with the ble_app_blinky example and my private key with the command
    

   nrfutil pkg generate --debug-mode --application ble_blinky_example.hex --key-file private.key app_dfu_package.zip

6. Try to perform a DFU with the command 
   

   nrfutil dfu serial -pkg app_dfu_package.zip -p /dev/ttymxc3 -b 115200

At this point after a while the terminal where I run nrfutil prints "pc_ble_driver_py.exceptions.NordicSemiException: No ping response after opening COM port".

To try to figure out what was going wrong, I added a bunch of debug statements in the files for the DFU bootloader and in dfu_transport_serial.py, which is called by nrfutil. On the terminal where I run nrfutil, I see that it continuously sends pings to the nRF but never receives a response. I also confirmed that the serial connection made with pyserial has identical parameters to serial connections I have made between my Linux computer and the nRF in the past, where each device was able to send and receive properly. Using the JLinkRTTViewer, I see the following from the nRF when I try to perform the DFU (please excuse the inconsistent debug format): 

in nrfx_uarte_0_irq_handler
in nrfx_uarte uarte_irq_handler
Receive buffer is filled up
secondary buffer == 0
in nrfx_uarte rx_done_event
in nrf_drv_uart uarte_evt_handler
in nrfx_uarte_rx
Function: nrfx_uarte_rx, error code: NRF_SUCCESS.
reached end of uarte_irq_handler
in nrfx_uarte_0_irq_handler
in nrfx_uarte uarte_irq_handler
Receive buffer is filled up
secondary buffer == 0
in nrfx_uarte rx_done_event
in nrf_drv_uart uarte_evt_handler
in nrfx_uarte_rx
Function: nrfx_uarte_rx, error code: NRF_SUCCESS.
reached end of uarte_irq_handler
in nrfx_uarte_0_irq_handler
in nrfx_uarte uarte_irq_handler
Receive buffer is filled up
secondary buffer == 0
in nrfx_uarte rx_done_event
in nrf_drv_uart uarte_evt_handler
in nrfx_uarte_rx
Function: nrfx_uarte_rx, error code: NRF_SUCCESS.
reached end of uarte_irq_handler
in nrf_drv_uart_tx
NRF_DRV_UART_USE_UARTE==true
in nrfx_uarte_tx
in nrf_uarte_tx_buffer_set
<debug> nrf_dfu_serial: Received ping 1
<info> nrf_dfu_serial_uart: Allocated buffer 20001764
<debug> nrf_dfu_req_handler: Handle NRF_DFU_OP_PING
<debug> nrf_dfu_req_handler: Request handling complete. Result: 0x1
<debug> nrf_dfu_serial: Sending Response: [0x9, 0x1]
in nrfx_uarte_0_irq_handler
in nrfx_uarte uarte_irq_handler
Receive buffer is filled up
secondary buffer == 0
in nrfx_uarte rx_done_event
in nrf_drv_uart uarte_evt_handler
in nrfx_uarte_rx
Function: nrfx_uarte_rx, error code: NRF_SUCCESS.
reached end of uarte_irq_handler
in nrfx_uarte_0_irq_handler
in nrfx_uarte uarte_irq_handler
Receive buffer is filled up
secondary buffer == 0
in nrfx_uarte rx_done_event
in nrf_drv_uart uarte_evt_handler
in nrfx_uarte_rx
Function: nrfx_uarte_rx, error code: NRF_SUCCESS.
reached end of uarte_irq_handler
in nrfx_uarte_0_irq_handler
in nrfx_uarte uarte_irq_handler
Receive buffer is filled up
secondary buffer == 0
in nrfx_uarte rx_done_event
in nrf_drv_uart uarte_evt_handler
in nrfx_uarte_rx
Function: nrfx_uarte_rx, error code: NRF_SUCCESS.
reached end of uarte_irq_handler
in nrf_drv_uart_tx
NRF_DRV_UART_USE_UARTE==true
in nrfx_uarte_tx
uarte tx in progress
<debug> nrf_dfu_serial: Received ping 2
<info> nrf_dfu_serial_uart: Allocated buffer 20001764
<debug> nrf_dfu_req_handler: Handle NRF_DFU_OP_PING
<debug> nrf_dfu_req_handler: Request handling complete. Result: 0x1
<debug> nrf_dfu_serial: Sending Response: [0x9, 0x1]
<error> nrf_dfu_serial: Failed to send data over serial interface!

So it seems that the Bluetooth module is receiving the ping and attempting to send a response but the python script called by nrfutil never receives it. Thinking that nrfutil may simply be pinging too frequently and too quickly, I tried adding a delay but that didn't help. I have written other programs on this same set up where the nRF device was able to send serial messages that were received by the Linux computer, so I'm not sure what could be the issue now. Does anybody have any suggestions?

[nkrinsky]

UPDATE: In addition to the nRF52832 on the custom board, I also have a BMD-301 evaluation kit which I have flashed with the same bootloader and SoftDevice with a Mac. I noticed that nrfutil starts with an initial ping that contains the hex values 9 1 and 192 so I've been manually sending those bytes to both nRF devices to see how they respond. After cleaning up my debugging statements this is what I get on the custom board: 

Enter main loop
in nrfx_uarte_0_irq_handler
in nrfx_uarte uarte_irq_handler
in function nrf_uarte_event_check
in function nrf_uarte_event_check
Receive buffer is filled up
in function nrf_uarte_rx_amount_get
secondary buffer == 0
in nrfx_uarte rx_done_event
in nrf_drv_uart uarte_evt_handler
in function uart_event_handler
event type = NRF_DRV_UART_EVT_RX_DONE
in functino on_rx_complete
in nrfx_uarte_rx
in function nrf_uarte_int_disable
Transfer rx_len: 1.
in function nrf_uarte_rx_buffer_set
in nrf_uarte_task_trigger
in function nrf_uarte_int_enable
Function: nrfx_uarte_rx, error code: NRF_SUCCESS.
in function nrf_uarte_event_check
in function nrf_uarte_event_check
reached end of uarte_irq_handler
in nrfx_uarte_0_irq_handler
in nrfx_uarte uarte_irq_handler
in function nrf_uarte_event_check
in function nrf_uarte_event_check
Receive buffer is filled up
in function nrf_uarte_rx_amount_get
secondary buffer == 0
in nrfx_uarte rx_done_event
in nrf_drv_uart uarte_evt_handler
in function uart_event_handler
event type = NRF_DRV_UART_EVT_RX_DONE
in functino on_rx_complete
in nrfx_uarte_rx
in function nrf_uarte_int_disable
Transfer rx_len: 1.
in function nrf_uarte_rx_buffer_set
in nrf_uarte_task_trigger
in function nrf_uarte_int_enable
Function: nrfx_uarte_rx, error code: NRF_SUCCESS.
in function nrf_uarte_event_check
in function nrf_uarte_event_check
reached end of uarte_irq_handler
in nrfx_uarte_0_irq_handler
in nrfx_uarte uarte_irq_handler
in function nrf_uarte_event_check
in function nrf_uarte_event_check
Receive buffer is filled up
in function nrf_uarte_rx_amount_get
secondary buffer == 0
in nrfx_uarte rx_done_event
in nrf_drv_uart uarte_evt_handler
in function uart_event_handler
event type = NRF_DRV_UART_EVT_RX_DONE
in functino on_rx_complete
in nrfx_uarte_rx
in function nrf_uarte_int_disable
Transfer rx_len: 1.
in function nrf_uarte_rx_buffer_set
in nrf_uarte_task_trigger
in function nrf_uarte_int_enable
Function: nrfx_uarte_rx, error code: NRF_SUCCESS.
in function nrf_dfu_serial_on_packet_received
Received ping 1
in function payload_free
in function nrf_dfu_req_handler_on_req
end of nrf_dfu_req_handler_on_req
Allocated buffer 20001764
in function nrf_uarte_event_check
in function nrf_uarte_event_check
reached end of uarte_irq_handler
in function nrf_dfu_req_handler_req
in function nrf_dfu_req_handler_req_process
Handle NRF_DFU_OP_PING
Request handling complete. Result: 0x1.
in function dfu_req_handler_rsp_clbk
p_res->requestion != NRF_DFU_OP_OBJECT_WRITE
in function response send
Sending Response: [0x9, 0x1]
p_response->result == NRF_DFU_RES_CODE_SUCCESS
in function rsp_send
in nrf_drv_uart_tx
NRF_DRV_UART_USE_UARTE==true
in nrfx_uarte_tx
Transfer tx_len: 5.
Tx data:
60 9 1 1 C0 
in nrf_uarte_tx_buffer_set
in nrf_uarte_task_trigger
Function: nrfx_uarte_tx, error code: NRF_SUCCESS.

On the evaluation board it is exactly the same except these additional statements are printed at the end:

in nrfx_uarte_0_irq_handler
in nrfx_uarte uarte_irq_handler
in function nrf_uarte_event_check
in function nrf_uarte_event_check
in function nrf_uarte_event_check
in function nrf_uarte_event_check
Last TX byte transmitted.
in function nrf_uarte_tx_amount_get
in nrfx_uarte tx_done_event
in nrf_drv_uart uarte_evt_handler
in function uart_event_handler
event type = NRF_DRV_UART_EVT_TX_DONE
reached end of uarte_irq_handler

For whatever reason my custom board isn't triggering nrfx_uarte_0_irq_handler that final time when the Last TX byte transmitted event occurs. What exactly triggers nrfx_uarte_0_irq_handler? Why would the same exact code result in this difference?

[bjorn-spockeli]

Hi nkrinsky, 

I apologize for not replying sooner. 

The nrfx_uarte_0_irq_handler() will be invoked by any of the following events

EVENTS_CTS	0x100	CTS is activated (set low). Clear To Send.
EVENTS_NCTS	0x104	CTS is deactivated (set high). Not Clear To Send.
EVENTS_RXDRDY	0x108	Data received in RXD (but potentially not yet transferred to Data RAM)
EVENTS_ENDRX	0x110	Receive buffer is filled up
EVENTS_TXDRDY	0x11C	Data sent from TXD
EVENTS_ENDTX	0x120	Last TX byte transmitted
EVENTS_ERROR	0x124	Error detected
EVENTS_RXTO	0x144	Receiver timeout
EVENTS_RXSTARTED	0x14C	UART receiver has started
EVENTS_TXSTARTED	0x150	UART transmitter has started
EVENTS_TXSTOPPED	0x158	Transmitter stopped

Its hard to say whats going on without knowing which events that are triggering the nrfx_uarte_0_irq_handler on the DK, but not the custom board. Do you think you could print the type of event in addition to "in function nrf_uarte_event_check" - It would also be useful if you could do a logic trace of the UART pins,just to verify that there nothing going on HW wise. 

Best regards

Bjørn

[nkrinsky]

Here's what's going on on the custom board:

Enter main loop
in nrfx_uarte_0_irq_handler
in nrfx_uarte uarte_irq_handler
in function nrf_uarte_event_check
NRF_UARTE_EVENT_ERROR, Error detected.
in function nrf_uarte_event_check
NRF_UARTE_EVENT_ENDRX, Receive buffer is filled up.
Receive buffer is filled up
in function nrf_uarte_event_clear
in function nrf_uarte_rx_amount_get
secondary buffer == 0
in nrfx_uarte rx_done_event
in nrf_drv_uart uarte_evt_handler
in function uart_event_handler
event type = NRF_DRV_UART_EVT_RX_DONE
in functino on_rx_complete
in nrfx_uarte_rx
in function nrf_uarte_int_disable
Transfer rx_len: 1.
in function nrf_uarte_event_clear
in function nrf_uarte_event_clear
in function nrf_uarte_rx_buffer_set
in nrf_uarte_task_trigger
task = NRF_UARTE_TASK_STARTRX
in function nrf_uarte_int_enable
Function: nrfx_uarte_rx, error code: NRF_SUCCESS.
in function nrf_uarte_event_check
NRF_UARTE_EVENT_RXTO, Receiver timeout.
in function nrf_uarte_event_check
NRF_UARTE_EVENT_ENDTX, Last TX byte transmitted.
reached end of uarte_irq_handler
in nrfx_uarte_0_irq_handler
in nrfx_uarte uarte_irq_handler
in function nrf_uarte_event_check
NRF_UARTE_EVENT_ERROR, Error detected.
in function nrf_uarte_event_check
NRF_UARTE_EVENT_ENDRX, Receive buffer is filled up.
Receive buffer is filled up
in function nrf_uarte_event_clear
in function nrf_uarte_rx_amount_get
secondary buffer == 0
in nrfx_uarte rx_done_event
in nrf_drv_uart uarte_evt_handler
in function uart_event_handler
event type = NRF_DRV_UART_EVT_RX_DONE
in functino on_rx_complete
in nrfx_uarte_rx
in function nrf_uarte_int_disable
Transfer rx_len: 1.
in function nrf_uarte_event_clear
in function nrf_uarte_event_clear
in function nrf_uarte_rx_buffer_set
in nrf_uarte_task_trigger
task = NRF_UARTE_TASK_STARTRX
in function nrf_uarte_int_enable
Function: nrfx_uarte_rx, error code: NRF_SUCCESS.
in function nrf_uarte_event_check
NRF_UARTE_EVENT_RXTO, Receiver timeout.
in function nrf_uarte_event_check
NRF_UARTE_EVENT_ENDTX, Last TX byte transmitted.
reached end of uarte_irq_handler
in nrfx_uarte_0_irq_handler
in nrfx_uarte uarte_irq_handler
in function nrf_uarte_event_check
NRF_UARTE_EVENT_ERROR, Error detected.
in function nrf_uarte_event_check
NRF_UARTE_EVENT_ENDRX, Receive buffer is filled up.
Receive buffer is filled up
in function nrf_uarte_event_clear
in function nrf_uarte_rx_amount_get
secondary buffer == 0
in nrfx_uarte rx_done_event
in nrf_drv_uart uarte_evt_handler
in function uart_event_handler
event type = NRF_DRV_UART_EVT_RX_DONE
in functino on_rx_complete
in nrfx_uarte_rx
in function nrf_uarte_int_disable
Transfer rx_len: 1.
in function nrf_uarte_event_clear
in function nrf_uarte_event_clear
in function nrf_uarte_rx_buffer_set
in nrf_uarte_task_trigger
task = NRF_UARTE_TASK_STARTRX
in function nrf_uarte_int_enable
Function: nrfx_uarte_rx, error code: NRF_SUCCESS.
in function nrf_dfu_serial_on_packet_received
Received ping 1
in function payload_free
in function nrf_dfu_req_handler_on_req
end of nrf_dfu_req_handler_on_req
Allocated buffer 20001764
in function nrf_uarte_event_check
NRF_UARTE_EVENT_RXTO, Receiver timeout.
in function nrf_uarte_event_check
NRF_UARTE_EVENT_ENDTX, Last TX byte transmitted.
reached end of uarte_irq_handler
in function nrf_dfu_req_handler_req
in function nrf_dfu_req_handler_req_process
Handle NRF_DFU_OP_PING
Request handling complete. Result: 0x1.
in function dfu_req_handler_rsp_clbk
p_res->requestion != NRF_DFU_OP_OBJECT_WRITE
in function response send
Sending Response: [0x9, 0x1]
p_response->result == NRF_DFU_RES_CODE_SUCCESS
p_response->request = NRF_DFU_OP_PING
in function rsp_send
in nrf_drv_uart_tx
NRF_DRV_UART_USE_UARTE==true
in nrfx_uarte_tx
Transfer tx_len: 5.
Tx data:
60 9 1 1 C0 
in function nrf_uarte_event_clear
in function nrf_uarte_event_clear
in nrf_uarte_tx_buffer_set
in nrf_uarte_task_trigger
task = NRF_UARTE_TASK_STARTTX
Function: nrfx_uarte_tx, error code: NRF_SUCCESS.

And on the DK:

Enter main loop
in nrfx_uarte_0_irq_handler
in nrfx_uarte uarte_irq_handler
in function nrf_uarte_event_check
NRF_UARTE_EVENT_ERROR, Error detected.
in function nrf_uarte_event_check
NRF_UARTE_EVENT_ENDRX, Receive buffer is filled up.
Receive buffer is filled up
in function nrf_uarte_event_clear
in function nrf_uarte_rx_amount_get
secondary buffer == 0
in nrfx_uarte rx_done_event
in nrf_drv_uart uarte_evt_handler
in function uart_event_handler
event type = NRF_DRV_UART_EVT_RX_DONE
in functino on_rx_complete
in nrfx_uarte_rx
in function nrf_uarte_int_disable
Transfer rx_len: 1.
in function nrf_uarte_event_clear
in function nrf_uarte_event_clear
in function nrf_uarte_rx_buffer_set
in nrf_uarte_task_trigger
task = NRF_UARTE_TASK_STARTRX
in function nrf_uarte_int_enable
Function: nrfx_uarte_rx, error code: NRF_SUCCESS.
in function nrf_uarte_event_check
NRF_UARTE_EVENT_RXTO, Receiver timeout.
in function nrf_uarte_event_check
NRF_UARTE_EVENT_ENDTX, Last TX byte transmitted.
reached end of uarte_irq_handler
in nrfx_uarte_0_irq_handler
in nrfx_uarte uarte_irq_handler
in function nrf_uarte_event_check
NRF_UARTE_EVENT_ERROR, Error detected.
in function nrf_uarte_event_check
NRF_UARTE_EVENT_ENDRX, Receive buffer is filled up.
Receive buffer is filled up
in function nrf_uarte_event_clear
in function nrf_uarte_rx_amount_get
secondary buffer == 0
in nrfx_uarte rx_done_event
in nrf_drv_uart uarte_evt_handler
in function uart_event_handler
event type = NRF_DRV_UART_EVT_RX_DONE
in functino on_rx_complete
in nrfx_uarte_rx
in function nrf_uarte_int_disable
Transfer rx_len: 1.
in function nrf_uarte_event_clear
in function nrf_uarte_event_clear
in function nrf_uarte_rx_buffer_set
in nrf_uarte_task_trigger
task = NRF_UARTE_TASK_STARTRX
in function nrf_uarte_int_enable
Function: nrfx_uarte_rx, error code: NRF_SUCCESS.
in function nrf_uarte_event_check
NRF_UARTE_EVENT_RXTO, Receiver timeout.
in function nrf_uarte_event_check
NRF_UARTE_EVENT_ENDTX, Last TX byte transmitted.
reached end of uarte_irq_handler
in nrfx_uarte_0_irq_handler
in nrfx_uarte uarte_irq_handler
in function nrf_uarte_event_check
NRF_UARTE_EVENT_ERROR, Error detected.
in function nrf_uarte_event_check
NRF_UARTE_EVENT_ENDRX, Receive buffer is filled up.
Receive buffer is filled up
in function nrf_uarte_event_clear
in function nrf_uarte_rx_amount_get
secondary buffer == 0
in nrfx_uarte rx_done_event
in nrf_drv_uart uarte_evt_handler
in function uart_event_handler
event type = NRF_DRV_UART_EVT_RX_DONE
in functino on_rx_complete
in nrfx_uarte_rx
in function nrf_uarte_int_disable
Transfer rx_len: 1.
in function nrf_uarte_event_clear
in function nrf_uarte_event_clear
in function nrf_uarte_rx_buffer_set
in nrf_uarte_task_trigger
task = NRF_UARTE_TASK_STARTRX
in function nrf_uarte_int_enable
Function: nrfx_uarte_rx, error code: NRF_SUCCESS.
in function nrf_dfu_serial_on_packet_received
Received ping 1
in function payload_free
in function nrf_dfu_req_handler_on_req
end of nrf_dfu_req_handler_on_req
Allocated buffer 20001764
in function nrf_uarte_event_check
NRF_UARTE_EVENT_RXTO, Receiver timeout.
in function nrf_uarte_event_check
NRF_UARTE_EVENT_ENDTX, Last TX byte transmitted.
reached end of uarte_irq_handler
in function nrf_dfu_req_handler_req
in function nrf_dfu_req_handler_req_process
Handle NRF_DFU_OP_PING
Request handling complete. Result: 0x1.
in function dfu_req_handler_rsp_clbk
p_res->requestion != NRF_DFU_OP_OBJECT_WRITE
in function response send
Sending Response: [0x9, 0x1]
p_response->result == NRF_DFU_RES_CODE_SUCCESS
p_response->request = NRF_DFU_OP_PING
in function rsp_send
in nrf_drv_uart_tx
NRF_DRV_UART_USE_UARTE==true
in nrfx_uarte_tx
Transfer tx_len: 5.
Tx data:
60 9 1 1 C0 
in function nrf_uarte_event_clear
in function nrf_uarte_event_clear
in nrf_uarte_tx_buffer_set
in nrf_uarte_task_trigger
task = NRF_UARTE_TASK_STARTTX
Function: nrfx_uarte_tx, error code: NRF_SUCCESS.
in nrfx_uarte_0_irq_handler
in nrfx_uarte uarte_irq_handler
in function nrf_uarte_event_check
NRF_UARTE_EVENT_ERROR, Error detected.
in function nrf_uarte_event_check
NRF_UARTE_EVENT_ENDRX, Receive buffer is filled up.
in function nrf_uarte_event_check
NRF_UARTE_EVENT_RXTO, Receiver timeout.
in function nrf_uarte_event_check
NRF_UARTE_EVENT_ENDTX, Last TX byte transmitted.
Last TX byte transmitted.
in function nrf_uarte_event_clear
in function nrf_uarte_tx_amount_get
in nrfx_uarte tx_done_event

They're the same until the end, where the DK has a NRF_UARTE_EVENT_ENDRX and then a NRF_UARTE_EVENT_ENDTX event, and the custom board does not. Where in the code do serial messages actually get sent? It seems the custom board is not entering that part.

[bjorn-spockeli]

HI nkrinsky, 

I apologize for the late reply, I was on vacation the past week. 

Ok, so it the following part that's not happening on the custom board.

in nrfx_uarte_0_irq_handler
in nrfx_uarte uarte_irq_handler
in function nrf_uarte_event_check
NRF_UARTE_EVENT_ERROR, Error detected.
in function nrf_uarte_event_check
NRF_UARTE_EVENT_ENDRX, Receive buffer is filled up.
in function nrf_uarte_event_check
NRF_UARTE_EVENT_RXTO, Receiver timeout.
in function nrf_uarte_event_check
NRF_UARTE_EVENT_ENDTX, Last TX byte transmitted.
Last TX byte transmitted.
in function nrf_uarte_event_clear
in function nrf_uarte_tx_amount_get
in nrfx_uarte tx_done_event

nkrinsky said:

They're the same until the end, where the DK has a NRF_UARTE_EVENT_ENDRX and then a NRF_UARTE_EVENT_ENDTX event, and the custom board does not. Where in the code do serial messages actually get sent? It seems the custom board is not entering that part.

It should be nrfx_uarte_tx() in nrfx_uarte.c, which set the tx buffer using nrf_uarte_tx_buffer_set() and then triggers the NRF_UARTE_TASK_STARTTX task using nrf_uarte_task_trigger().

 Do you have a way of checking that there is data on the UART lines of the custom board after the last nrfx_uarte_tx call that returns NRF_SUCCESS? i.e. a logic analyzer or an oscilloscope?

Best regards

Bjørn