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.

[Edvin]

Hello,

What are you using to monitor your logs? If you are using a debug session in Segger Embedded Studio, try to set the NRF_FPRINTF_FLAG_AUTOMATIC_CR_ON_LF_ENABLED to 0 in sdk_config.h.

 

For example it print 9 lines and all next lines are lost.

 So you do see some lines? After this, do you see anything like "Fatal error." in the log? Or does it just stop?

What project are you running? A completely custom project? Have you tried debugging to check that the app is still running, and that it didn't stop by some error handler or hardfault handler? Are you using the softdevice?

Have you tried one of the examples from the SDK, such as the ble_app_uart example? Does the logging work if you don't modify it too much? Try this sample, and set NRF_FPRINTF_FLAG_AUTOMATIC_CR_ON_LF_ENABLED to 0 if you are monitoring the log through a debug session:

If that doesn't work, I see you are using a PDK? What version is that? Do you have a regular DK, and if so, can you please test that one?

Best regards,

Edvin

[_Dejan_]

Hi Edvin,

Thanks for reply and help. I use nRF52840 Preview DK board version 0.9.0 which Im buy around 5 years ago when Im start learning developing on microcontrollers and then I didn't need it and put it on box for all that time... This is my only Nordic device so I don't have normal DK... I know that 5 years ago I had similar problem with KEIL but don't remember how Im fix it. I have same problem with Segger Debug window and with J-Link RTT Viewer.

Im try set NRF_FPRINTF_FLAG_AUTOMATIC_CR_ON_LF_ENABLED to 0 but didn't help. Im found that on one post somewhere here...

I see some log lines I see for example first 9 lines then some lines are missing and then I see again some lines ... This happen only if lines are written very fast for example when I init "modules"... For example if I enable power management logging for CPU usage it normaly print line every second. I call NRF_LOG_FLUSH after every NRF_LOG_INFO/NRF_LOG_DEBUG call but log messages are still lost. There is no errors also debugging do not break, just debug viewer or RTT viewer do not get log data... I run custom project with softdevice S140 7.2.0 and app normaly work when lines are lost. Also code after log line which missing is executed.

If I use simple example "examples\ble_peripheral\ble_app_blinky\pca10056\s140\ses"

And set

NRF_LOG_BACKEND_RTT_ENABLED 1

NRF_LOG_BACKEND_UART_ENABLED 0

And modify main to:

int main(void)
{
    // Initialize.
    log_init();
  /*  leds_init();
    timers_init();
    buttons_init();
    power_management_init();
    ble_stack_init();
    gap_params_init();
    gatt_init();
    services_init();
    advertising_init();
    conn_params_init();

    // Start execution.
    NRF_LOG_INFO("Blinky example started.");
    advertising_start();*/

    int i=0;
    // Enter main loop.
    while(true)
    {
      NRF_LOG_INFO("Blinky example i=%d", i);
      NRF_LOG_FLUSH();
      i++;
     
        //idle_state_handle();
    }
}

Then I get in log:

<info> app: Blinky example i=22790
<info> app: Blinky example i=22791
<info> app: Blinky example i=22854
<info> app: Blinky example i=22855
<info> app: Blinky example i=22856
<info> app: Blinky example i=22857
<info> app: Blinky example i=22858
<info> app: Blinky example i=22859
<info> app: Blinky example i=22860
<info> app: Blinky example i=22861
<info> app: Blinky example i=22862
<info> app: Blinky example i=22863
<info> app: Blinky example i=22864
<info> app: Blinky example i=22865
<info> app: Blinky example i=22866
<info> app: Blinky example i=22925
<info> app: Blinky example i=22926
<info> app: Blinky example i=22927

Im found that right now it work normaly if I have set SEGGER_RTT_CONFIG_DEFAULT_MODE 2. Now with BLOCK_IF_FIFO_FULL mode I must have connected RTT Viewer otherwise application on board stop working but I get all log lines...

Right now I use this settings:

SEGGER_RTT_CONFIG_BUFFER_SIZE_UP 512
SEGGER_RTT_CONFIG_MAX_NUM_UP_BUFFERS 2
SEGGER_RTT_CONFIG_BUFFER_SIZE_DOWN 16
SEGGER_RTT_CONFIG_MAX_NUM_DOWN_BUFFERS 2
SEGGER_RTT_CONFIG_DEFAULT_MODE 2

NRF_FPRINTF_ENABLED 1
NRF_FPRINTF_FLAG_AUTOMATIC_CR_ON_LF_ENABLED 1
NRF_FPRINTF_DOUBLE_ENABLED 0

NRF_LOG_BACKEND_RTT_ENABLED 1
NRF_LOG_BACKEND_RTT_TEMP_BUFFER_SIZE 64
NRF_LOG_BACKEND_RTT_TX_RETRY_DELAY_MS 1
NRF_LOG_BACKEND_RTT_TX_RETRY_CNT 3
NRF_LOG_BACKEND_UART_ENABLED 0
NRF_LOG_BACKEND_UART_TX_PIN 6
NRF_LOG_BACKEND_UART_BAUDRATE 30801920
NRF_LOG_BACKEND_UART_TEMP_BUFFER_SIZE 64
NRF_LOG_ENABLED 1
NRF_LOG_MSGPOOL_ELEMENT_SIZE 20
NRF_LOG_MSGPOOL_ELEMENT_COUNT 16
NRF_LOG_ALLOW_OVERFLOW 1
NRF_LOG_BUFSIZE 1024
NRF_LOG_CLI_CMDS 0
NRF_LOG_DEFAULT_LEVEL 4
NRF_LOG_DEFERRED 1
NRF_LOG_FILTERS_ENABLED 0
NRF_LOG_NON_DEFFERED_CRITICAL_REGION_ENABLED 0
NRF_LOG_STR_PUSH_BUFFER_SIZE 128

Probably when Im test first time with SEGGER_RTT_CONFIG_DEFAULT_MODE 2 Im made something else wrong that logging didn't work...

I have only one question: Is there settings that when I use BLOCK_IF_FIFO_FULL mode to skip RTT logging if RTT debugger is not connected?

Thanks for your time and help.

[Edvin]

You are using SDK17.0.2, right? I can't find BLOCK_IF_FIFO_FULL in SDK17.0.2, but perhaps it is used in some examples. Did you try to set it to 0?

If you set NRF_LOG_DEFERRED to 0, then you shouldn't need the NRF_LOG_FLUSH().

I have seen something like "LOGS SKIPPED" before in the log, which I believe is printed if log is deferred, but printed too fast.

Is there some way for me to reproduce what you are seeing? Can you please zip the project folder, and I can check whether it reproduces on a non-preview DK.

Best regards,

Edvin

[_Dejan_]

Yes Im using SDK17.0.2. There is no BLOCK_IF_FIFO_FULL "definition" but BLOCK_IF_FIFO_FULL you get when you set SEGGER_RTT_CONFIG_DEFAULT_MODE 2 by default is 0(SKIP mode). I understand that in mode SKIP I will lose log lines if I will not flush logs. If I understand documentation NRF_LOG_FLUSH() must block untill all is processed from buffer...

Documentation:

Macro for processing all log entries from the buffer. It blocks until all buffered entries are processed by the backend.

But because I call NRF_LOG_FLUSH()after every NRF_LOG_INFO/NRF_LOG_DEBUG call there can't happen that log lines can be skipped from buffer if I use skip mode...

If I set NRF_LOG_DEFERRED to 0 and SEGGER_RTT_CONFIG_DEFAULT_MODE is 0 it also SKIP log lines. By quick test there is no difference if I call NRF_LOG_FLUSH() or not.

Here is simple example(modified ble_app_blinky). After run press pause and check i numbers in log and you will see something like that(missing lines):

<info> app: Blinky example i=12423
<info> app: Blinky example i=12424
<info> app: Blinky example i=12425
<info> app: Blinky example i=12486
<info> app: Blinky example i=12487
<info> app: Blinky example i=12488

ble_app_blinky.rar

[Edvin]

Try the attached project:

ble_app_blinky_cust.zip

How do you monitor your log? Can you plaese share a screenshot?

Do you see more than 9 lines in the attached project?

BR,

Edvin

[_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()).