UART Logging Backend hangs in nrf_bootloader_app_start

[niecore]

Hi Community,

I want to use the UART Logging backend in my bootloader. Whenever I want to start the actual application via nrf_bootloader_app_start(), the bootloader hangs in nrf_fprintf_buffer_flush in a while loop.

    while (m_async_mode && (m_xfer_done == false))

    {

    }

Can someone help solving this issue?

Best regards,

Nico

[bjorn-spockeli]

Hi Niecore, 

NRF_LOG_FLUSH should return when the queued log data has been emptied. THis is not an issue in our DFU debug examples that uses the UART backend for logging. Are you calling NRF_LOG_FLUSH or  NRF_LOG_PROCESS from any other places in your code except main()?  Does commenting out the NRF_LOG_FLUSH call in nrf_bootloader_app_start allow you to jump to the application? 

void nrf_bootloader_app_start(void)
{
    uint32_t start_addr = MBR_SIZE; // Always boot from end of MBR. If a SoftDevice is present, it will boot the app.
    NRF_LOG_DEBUG("Running nrf_bootloader_app_start with address: 0x%08x", start_addr);
    uint32_t err_code;

    // Disable and clear interrupts
    // Notice that this disables only 'external' interrupts (positive IRQn).
    NRF_LOG_DEBUG("Disabling interrupts. NVIC->ICER[0]: 0x%x", NVIC->ICER[0]);

    NVIC->ICER[0]=0xFFFFFFFF;
    NVIC->ICPR[0]=0xFFFFFFFF;
#if defined(__NRF_NVIC_ISER_COUNT) && __NRF_NVIC_ISER_COUNT == 2
    NVIC->ICER[1]=0xFFFFFFFF;
    NVIC->ICPR[1]=0xFFFFFFFF;
#endif

    err_code = nrf_dfu_mbr_irq_forward_address_set();
    if (err_code != NRF_SUCCESS)
    {
        NRF_LOG_ERROR("Failed running nrf_dfu_mbr_irq_forward_address_set()");
    }

    NRF_LOG_FLUSH();
    nrf_bootloader_app_start_final(start_addr);
}

Best regards

Bjørn

[schef]

I have something similar:

<debug> nrf_dfu_req_handler: Whole firmware image received. Postvalidating.
<debug> nrf_dfu_validation: Hash verification. Firmware start address: 0x73000, size: 0x4B888
<debug> nrf_dfu_validation: Invalidating old application in bank 0.
<debug> nrf_dfu_serial: Sending Response: [0x4, 0x1]
<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=0x20000B64, len=348 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=0x20000CC0, len=348 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.
<error> app: Received a fault! id: 0x00004002, pc: 0x00000000, info: 0x2003FD18
<error> app: ASSERTION FAILED at ../../../../firmware_nrf52_sdk_15_2/src/nRF5_SDK_15.2.0_9412b96/modules/nrfx/drivers/src/nrfx_uarte.c:269

I use nrf52840 with sdk15.2 and pca10056_uart_debug.

[bjorn-spockeli]

schef: Please post the code where the assert originated from, i.e. nRF5_SDK_15.2.0_9412b96/modules/nrfx/drivers/src/nrfx_uarte.c: line 269

[niecore]

I quick fixed my problem by setting NRF_LOG_DEFERRED to "0"

[Dmitry Polshaklov]

Hello. I have the same issue with nRF5_SDK_for_Thread_and_Zigbee_v4.0.0_dc7186b and nRF52840-DK.

> Are you calling NRF_LOG_FLUSH or  NRF_LOG_PROCESS from any other places in your code except main()? 

Yes. But with gdb I checked, that freeze happens in nrf_bootloader_app_start.

#0  0x000e0b1a in serial_tx (p_context=<optimized out>, p_buffer=<optimized out>, len=<optimized out>) at ../../../../../components/libraries/log/src/nrf_log_backend_uart.c:88
#1  0x000e614e in nrf_fprintf_buffer_flush (p_ctx=p_ctx@entry=0x2003ff58) at ../../../../../external/fprintf/nrf_fprintf.c:56
#2  0x000e19b0 in postfix_process (p_params=p_params@entry=0x2003ff4c, p_ctx=p_ctx@entry=0x2003ff58, newline=newline@entry=false) at ../../../../../components/libraries/log/src/nrf_log_str_formatter.c:150
#3  0x000e1a1a in nrf_log_std_entry_process (p_str=p_str@entry=0xf2b44 "In nrf_bootloader_init", p_args=p_args@entry=0x2003ff28, nargs=nargs@entry=0, p_params=p_params@entry=0x2003ff4c, p_ctx=p_ctx@entry=0x2003ff58) at ../../../../../components/libraries/log/src/nrf_log_str_formatter.c:192
#4  0x000e0a0c in nrf_log_backend_serial_put (p_backend=<optimized out>, p_msg=0x20001a9c <log_mempool_nrf_balloc_pool_mem>, p_buffer=p_buffer@entry=0x20001a50 <m_string_buff> "<debug> app: In nrf_bootloader_init\r\r\ner]==========\r\r\n", length=length@entry=64, tx_func=tx_func@entry=0xe0afd <serial_tx>) at ../../../../../components/libraries/log/src/nrf_log_backend_serial.c:87
#5  0x000e0aec in nrf_log_backend_uart_put (p_backend=<optimized out>, p_msg=<optimized out>) at ../../../../../components/libraries/log/src/nrf_log_backend_uart.c:95
#6  0x000e0fc6 in nrf_log_backend_put (p_msg=0x20001a9c <log_mempool_nrf_balloc_pool_mem>, p_backend=0xf4b4c <uart_log_backend>) at ../../../../../components/libraries/log/nrf_log_backend_interface.h:225
#7  nrf_log_frontend_dequeue () at ../../../../../components/libraries/log/src/nrf_log_frontend.c:862
#8  0x000eb708 in nrf_bootloader_app_start () at ../../../../../../../bootloader/nrf_bootloader_app_start.c:75
#9  0x000eb62a in nrf_bootloader_init_ext (observer=observer@entry=0xeb07d <dfu_observer>, image_copy=image_copy@entry=0x0, copy_bl=copy_bl@entry=0x0) at ../../../../../../../bootloader/nrf_bootloader.c:528
#10 0x000eb6c6 in nrf_bootloader_init (observer=observer@entry=0xeb07d <dfu_observer>) at ../../../../../../../bootloader/nrf_bootloader.c:425
#11 0x000eb1fe in main () at ../../main.c:226

> Does commenting out the NRF_LOG_FLUSH call in nrf_bootloader_app_start allow you to jump to the application? 

Yes.

What can I do to avoid SDK code change? Or should I create a new topic?

[pineapple pizza]

Hi, I found the same issue here. If NRF_LOG_DEFERRED is set to 1 the backend in `nrf_log_backend_uart.c` uses interrupts to set `m_xfer_done` to true once the UART transfer is done, this is done via the even handler `uart_evt_handler` in that file.

However, in `nrf_bootloader_app_start` the code is disabling the interrupts and calling NRF_LOG_FLUSH which then hangs because the `uart_evt_handler` is never called (the interrupt is probably pending).

This is a bug in the SDK code.

One option is to set NRF_LOG_DEFERRED to 0 as mentioned here, this will not use the event handler/interrupts. This doesn't require any code changes.

The other option would be for nordic to fix the SDK code. I think that one way to fix this in this case would be to call the log messages and flush before we disable the interrupts. Another option is to fix the flush logic to not rely on the interrupt being attended since it is doing a busy loop anyway. In `nrf_log_backend_uart.c`, function serial_tx there's this while() loop waiting for the event handler to be done. I think that if your message is too long you need several interrupts to trigger before you get a call to the event handler, so maybe forcing an interrupt call (just calling directly the equivalent function from the loop body) would work, but this is not exposed at all in the driver.

Should we create a support case for this?