Filtering Logs at Run Time

[jm_solar]

We have a system with multiple log backends enabled. The goal is to ultimately keep one of the backends to globally only see errors/warnings while the other gets all the a module sends.

Currently, I cannot get log filtering to work at all. I am using nrf Connect SDK 2.7. The hardware is an nrf52840 module.

prj.conf includes:

CONFIG_LOG_RUNTIME_FILTERING=y

In my code I have just tried to do some basic filtering of logs with:

Fullscreen

1

2

3

4

5

6

7

8

9

10

11

const struct log_backend *uart_backend = log_backend_get_by_name("log_backend_uart");

if (uart_backend != NULL) {

LOG_INF("Setting Logs to WRN");

uint32_t filret = log_filter_set(uart_backend, 0, LOG_CURRENT_MODULE_ID(), LOG_LEVEL_WRN);

LOG_INF("Filter Set Result: %d", filret);

} else {

LOG_WRN("Backend NULL");

}

uint32_t runtime_filter = log_filter_get(uart_backend, 0, LOG_CURRENT_MODULE_ID(), true);

uint32_t static_filter = log_filter_get(uart_backend, 0, LOG_CURRENT_MODULE_ID(), false);

LOG_WRN("Runtime: %d, Static: %d", runtime_filter, static_filter);

XXXXXXXXXXXXXXXXXXXXXXXXXXXXXXXXXXXXXXXXXXXXXXXXXX

const struct log_backend *uart_backend = log_backend_get_by_name("log_backend_uart");
if (uart_backend != NULL) {
    LOG_INF("Setting Logs to WRN");
    uint32_t filret = log_filter_set(uart_backend, 0, LOG_CURRENT_MODULE_ID(), LOG_LEVEL_WRN);
    LOG_INF("Filter Set Result: %d", filret);
} else {
    LOG_WRN("Backend NULL");
}
uint32_t runtime_filter = log_filter_get(uart_backend, 0, LOG_CURRENT_MODULE_ID(), true);
uint32_t static_filter = log_filter_get(uart_backend, 0, LOG_CURRENT_MODULE_ID(), false);
LOG_WRN("Runtime: %d, Static: %d", runtime_filter, static_filter);

The logs from this look like:

Fullscreen

1

2

3

<inf> main : Setting Logs to WRN

<inf> main : Filter Set Result: 2

<wrn> main : Runtime: 4, Static: 4

XXXXXXXXXXXXXXXXXXXXXXXXXXXXXXXXXXXXXXXXXXXXXXXXXX

<inf> main : Setting Logs to WRN 
<inf> main : Filter Set Result: 2 
<wrn> main : Runtime: 4, Static: 4

                                                               

This is very confusing to me because "log_filter_set" is supposed to return the log level that is being set, but then I immediately do a "log_level_get" and the value is not the same as what was just set a few lines earlier. My INF level logs are still coming through as well.

I have tried a bunch of different types of filter and cannot get the logging level to change at all. I am at the point where I am out of ideas, I cannot get log_filter_set to do anything but it always returns the value I expect it to as if it has worked correctly. 

Are there other project configurations or settings that could be overriding this runtime setting?

[jm_solar]

I seem to have got something to work - just adding a delay at the beginning based on some discord thread I just came across. Now my basic filter is doing something.

Is there a good way to check that the logging susbsystem is up and running rather than just adding a wait?

[Kenneth]

Hi,

Not entirely sure what is the problem, but there should be various logger test examples that show usage of CONFIG_LOG_RUNTIME_FILTERING=y I suggest to take a look at them for guidance also.

It could be that any existing log in the que will not be filtered, and the log que will only be executed when in idle. To change this behavior you can use CONFIG_LOG_MODE_IMMEDIATE=y, but that will affect timing overall, since the logging will add delays on each log message (instead of waiting for idle to print logs).

Kenneth

[jm_solar]

So it turns out my issue was that the logging system wasn't fully initialized. It seems that there is no way to apply a filter before any logs get printed which is my ultimate goal. Some discussion in the zephyr discord about this functionality, but it seems to be a limitation of zephyr that the compiled log level is the same as the initial log level and it is near impossible to apply a filter before any logs get put in the queue by various threads.