Freeze in nrf_bootloader_app_start on NRF_LOG_FLUSH

[Dmitry Polshaklov]

Hello. I have the same problem with https://devzone.nordicsemi.com/f/nordic-q-a/54373/uart-logging-backend-hangs-in-nrf_bootloader_app_start/220132

But this thread was stuck so we still have no answer.

With gdb, I checked the code flow and found that freeze happens in `NRF_LOG_FLUSH`

#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

Removing line contains NRF_LOG_FLUSH (nrf_bootloader_app_start.c:75) fixes freezing

[Vidar Berg]

Hello,

All interrupts are disabled before calling NRF_LOG_FLUSH in this case, which is going to prevent the asynchronous UART backend from receiving the interrupts that are supposed to be triggered when the transfer of a log message is complete. Thus, the logger won't be able to flush the log buffer. Did you try to disable the NRF_LOG_DEFERRED config option as suggested in the other thread? It should make the backend synchronous (not interrupt driven).

[Dmitry Polshaklov]

Yes, it works too. But why not place 'NRF_LOG_FLUSH' before interrupts disable? Does this limitation (prohibition of use UART backend + deferred logging in the bootloader) is documented?

[Vidar Berg]

Probably because we would risk losing the last log message if nrf_dfu_mbr_irq_forward_address_set() failed. We are only using RTT logging in our bootloader examples, so we have not tested the implementation with UART.

[Dmitry Polshaklov]

Just IMO. Interrupts can be enabled and disabled back for the last log message. But thank you, now it's quite clear for me