Kconfig CONFIG_LOG_OVERRIDE_LEVEL=4 breaks logging system

[wkpolara]

Using the Zephyr logging system, setting Kconfig option in prj.conf to override logging to level 4 (output LOG_DBG messages) breaks the console and no output is sent at all.

CONFIG_LOG_OVERRIDE_LEVEL=4

Setting the override level to 1-3 works as expected.

We are using nRF SDK v2.0.2.  This can be reproduced using the "Blinky" sample in the SDK and enabling logging.  The blinky sample is in:

C:\ncs\v2.0.0\zephyr\samples\basic\blinky

I'm attaching the modified prj.conf and main.c files that show the issue.

The following is added to the blinky sample prj.conf file:

CONFIG_GPIO=y

CONFIG_LOG=y
CONFIG_LOG_PRINTK=y
CONFIG_LOG_MODE_DEFERRED=y
CONFIG_LOG_BUFFER_SIZE=2048
CONFIG_LOG_PROCESS_TRIGGER_THRESHOLD=0
CONFIG_LOG_DEFAULT_LEVEL=2

CONFIG_LOG_OVERRIDE_LEVEL=3

The following lines are added to the blinky sample main.c

...
#include <zephyr/logging/log.h>
...
LOG_MODULE_REGISTER(Blinky, CONFIG_LOG_DEFAULT_LEVEL);

...

void main(void)
{

    ...

	while (1) {
		ret = gpio_pin_toggle_dt(&led);
		if (ret < 0) {
			return;
		}

        ret = gpio_pin_get_dt(&led);
        if (ret) {
            LOG_INF("LED is on"); // shows up with override level 3 & 4
        } else {
            LOG_DBG("LED is off"); // shows up with override level 4
        }

		k_msleep(SLEEP_TIME_MS);
	}
}

We ran this on a BDM-340 evaluation board, which uses the nRF52840.  The project board configuration is set to 

ubx-bmd340eval-nrf52840

To reproduce:

1) Connect a serial terminal (e.g. PuTTY) to the demo board debug COM port at 115200.

2) Build the project with the attached, modified files.

3) Flash the image on the demo board.

4) In the serial Terminal, the following output appears:

*** Booting Zephyr OS build v3.0.99-ncs1 ***
[00:00:00.340,484] <inf> Blinky: LED is on
[00:00:01.340,606] <inf> Blinky: LED is on

NOTE that "LED is off" does not show up because it is LOG_DBG and will not be shown with CONFIG_LOG_OVERRIDE_LEVEL=3

 

5) Edit prj.conf to set CONFIG_LOG_OVERRIDE_LEVEL=4  

6) Do a pristine Build, and flash to the demo board.

7) Note that after flash completes, NO OUTPUT appears, not even "*** Booting Zephyr OS build v3.0.99-ncs1 ***"

The override level can be set back to 3 and it will work again, just not show the LOG_DBG() "off" message again.  Setting it to 2 shows only the boot message, as expected, since LOG_INF() and LOG_DBG() are both above level 2.

Why does override of level 4 not work?

[Håkon Alseth]

Hi,

 

Edit prj.conf to set CONFIG_LOG_OVERRIDE_LEVEL=4  

This will set all registered log modules to debug mode, which will use alot of stack memory.

 

To enable a given level on your specified logging module, you do this in the definition itself.

In your case, it is this:

LOG_MODULE_REGISTER(Blinky, CONFIG_LOG_DEFAULT_LEVEL);

 

So f you set CONFIG_LOG_DEFAULT_LEVEL=4 in prj.conf, you should get both info and debug prints.

This function:

ret = gpio_pin_get_dt(&led);

Is for a GPIO configured as input (ie. reads NRF_P0->IN register), and will not return the state of a output. The problem is that the zephyr gpio driver does not have a API for reading the state of a output device, it just sets it directly.

I would recommend that you instead just print directly:

LOG_INF("Info");
LOG_DBG("Debug");

 

Kind regards,

Håkon

[wkpolara]

Hi Håkon,

Thank  you for the reply.  I see your point about the gpio_pin_get_dt(), and your suggestion to just print directly the Info and Debug messages is good.

I understand that where the default log level is used, that can alternatively be used to change the log level in those modules.

However, I would still expect CONFIG_LOG_OVERRIDE_LEVEL=4 to work.  Why does it break it instead?

Regards,

Walt

[Håkon Alseth]

Hi Walt,

 

I can confirm that there's an issue with this configuration and the deferred logging option:

wkpolara said:

CONFIG_LOG_OVERRIDE_LEVEL=4

The problem seems to be specific to the logging in the MPU initialization, more specifically these two LOG_DBG calls:

https://github.com/nrfconnect/sdk-zephyr/blob/v3.1.99-ncs1/arch/arm/core/aarch32/mpu/arm_mpu_v8_internal.h#L174

https://github.com/nrfconnect/sdk-zephyr/blob/v3.1.99-ncs1/arch/arm/core/aarch32/mpu/arm_mpu.c#L341

 

Disabling the MPU is not recommended. 

One way to work around this is to change the logging method to for instance minimal footprint (CONFIG_LOG_MODE_MINIMAL).

 

I'll report this issue back to the team that works with the logger.

 

Kind regards,

Håkon

[wkpolara]

Alright, thanks Håkon