NRF_LOG_INFO lost lines

[_Dejan_]

Hi,

After long time(around 5 years) Im try developing ble things on my nrf52840 DK Preview board and found some issues with NRF_LOG functions...

I use latest SEGGER Studio(5.42a) and latest fw(Feb  2 2021 16:47:20) on JLINK. Im try update dll in SEGGER Studio from 6.98e to 7.00 but doesnt help. Im using latest nrf5 SDK  17.0.2

What is problem? For example if there is a lot of lines of log they are lost. For example it print 9 lines and all next lines are lost.

I call logging like this(no variable only fixed string):

NRF_LOG_INFO("App Control started.");

NRF_LOG_FLUSH();

Same happen also with one demo which print around 100 lines and if remember right it print only around 60 lines...

Im try call NRF_LOG_FLUSH after every NRF_LOG_INFO call but do not help...

Im try change different settings for buffer, rtt buffers, to block rtt if fifo is full but log data are still lost...

Im increase SEGGER_RTT_CONFIG_BUFFER_SIZE_UP, SEGGER_RTT_CONFIG_MAX_NUM_UP_BUFFERS, SEGGER_RTT_CONFIG_BUFFER_SIZE_DOWN, SEGGER_RTT_CONFIG_MAX_NUM_DOWN_BUFFERS.

Im set SEGGER_RTT_CONFIG_DEFAULT_MODE to 2(BLOCK_IF_FIFO_FULL).

I have enabled(1) NRF_LOG_BACKEND_RTT_ENABLED

Im increase NRF_LOG_BACKEND_RTT_TEMP_BUFFER_SIZE

I have disabled(0) NRF_LOG_BACKEND_UART_ENABLED.

I have enabled(1) NRF_LOG_ENABLED

Im increase NRF_LOG_BUFSIZE

Im try NRF_LOG_DEFERRED set to 0 and 1.

Im try increase NRF_LOG_STR_PUSH_BUFFER_SIZE

Any idea what I can try or how to log data without lost lines of log? Currently I don't care if logging slow down application, and it need more time/power to do work...

Thanks for any help.

[_Dejan_]

Hi,

Im copy your project into \examples\ble_peripheral directory and erase all from board(nrfjprog --eraseall) then build and Debug it

After Build Im press "continue execution" and app is started and debugger inside SEGGER Studio start writing lines. Then after few seconds Im press break and check lines inside log. They are normaly inserted but I think a lot of slower that in my example. Im check and you use SEGGER_RTT_CONFIG_DEFAULT_MODE 2 which block logging if buffer is full and also app stop responding if RTT is not connected because LOG function when buffer is full block executing code...

This is your example:

If I only change in your example SEGGER_RTT_CONFIG_DEFAULT_MODE back to 0 I can reproduce my problem:

I think that here is problem with NRF_LOG_FLUSH() function which do not block and flush logs from buffer when you call it and probably do this asynchronous ...

[Edvin]

I think you may expect a bit too much from the logging module.

I just took your project and changed deferred to 0. 

As you see from the description of SEGGER_RTT_CONFIG_DEFAULT_MODE in sdk_config.h when set to 2 all NRF_LOG_INFO/DEBUG/... calls are blocking, meaning they will be blocked until the log buffer has room for that log message. When it is set to 0, it will skip all messages that doesn't fit. This is why you see the gaps. 

Another note:

You can use NRF_LOG_FLUSH() in your main loop, but you can't use this wherever you want. Basically, if a call to NRF_LOG_FLUSH() is interrupted by another call to NRF_LOG_FLUSH(), then the device will crash, so keep this in your main function (and you can use it in error handlers that will reset after calling this, like it is done in the error handler).

Best regards,

Edvin

[_Dejan_]

Hi Edvin,

Thanks for that informations and all  your help. Im still learning C/C++ and microcontroller app developing and I came from computer application developing(Delphi, C#, Java) where I have around 15 years of expirience so maybe realy expect to much from this small devices... Before NRF Im only develop on  .NET Micro Framework(C#) and using "GHI Electronics" devices...

Im find this issue when Im try debug initialization functions in my application so when Im in main function call:

I have on start and end of each init function debug log which in the end produce log like:

<debug> app: Logging Initialization COMPLETED.
<debug> app: Device Initialization...
<debug> app: Device ID: SERIAL_NR
<debug> app: Device Initialization COMPLETED.
<debug> app: Clock Initialization...
<debug> app: Clock Initialization COMPLETED.
<debug> app: Timer Initialization...
<info> app_timer: RTC: initialized.
<debug> app: Timer Initialization COMPLETED.
<debug> app: LED & Buttons Initialization...
<debug> app: LED & Buttons Initialization COMPLETED.
<debug> app: Power Management Initialization...
<info> pwr_mgmt: Init
<debug> app: Power Management Initialization COMPLETED.
<debug> app: BLE Stack Initialization...
<debug> app: BLE Stack Initialization COMPLETED.
<debug> app: BLE GAP Initialization...
<debug> app: BLE GAP Initialization COMPLETED.
<debug> app: BLE GATT Initialization...
<debug> app: BLE GATT Initialization COMPLETED.
<debug> app: BLE Services Initialization...
<debug> app: BLE Services Initialization COMPLETED.
<debug> app: BLE Advertising Initialization...
<debug> app: BLE Advertising Initialization COMPLETED.
<debug> app: BLE Connection params Initialization...
<debug> app: BLE Connection params Initialization COMPLETED.
<debug> app: Peer Manager Initialization...
<debug> nrf_ble_lesc: Initialized nrf_crypto.
<debug> nrf_ble_lesc: Initialized nrf_ble_lesc.
<debug> nrf_ble_lesc: Generating ECC key pair
<debug> app: Peer Manager Initialization COMPLETED.
<debug> app: Custom app started.
<debug> app: BLE Advertising starting...
<info> pwr_mgmt: CPU Usage: 55%
<info> pwr_mgmt: CPU Usage: 0%
<info> pwr_mgmt: CPU Usage: 0%

And usualy logging module has skip line:

<debug> app: Power Management Initialization COMPLETED.

or some very close to it...

Right now I use SEGGER_RTT_CONFIG_DEFAULT_MODE set to 0 to allow app normaly run also without RTT connected. Im increase SEGGER RTT buffers to avoid skipping log lines and with that settings it work normaly:

SEGGER_RTT_CONFIG_BUFFER_SIZE_UP 4096

SEGGER_RTT_CONFIG_MAX_NUM_UP_BUFFERS 8

SEGGER_RTT_CONFIG_BUFFER_SIZE_DOWN 128

SEGGER_RTT_CONFIG_MAX_NUM_DOWN_BUFFERS 8

SEGGER_RTT_CONFIG_DEFAULT_MODE 0

Im not sure what exactly I will do with this logs but maybe later I will push them to mobile(Android) app if user will request debug logging(I need to check if that is possible)...

I think that case can be closed

[Edvin]

_Dejan_ said:

Im not sure what exactly I will do with this logs but maybe later I will push them to mobile(Android) app if user will request debug logging(I need to check if that is possible)...

 Please note that the APP_ERROR_CHECK(err_code) will print errors in the log if you define DEBUG in your preprocessor definitions (let me know if you don't know how to add preprocessor definitions). 

That is probably easier to use than a lot of custom logging like this. The log module requires a lot of memory if you log this much before reaching NRF_LOG_PROCESS() (called from idle_state_handle()).