case about CONFIG_LOG_DEFAULT_LEVEL=4 case nRF52840 error

[peter.min]

Hi,

1. Please help me resolve the log error that occurs with CONFIG_LOG_DEFAULT_LEVEL=4

2. I created a very simple example of log printing and it worked fine when I set CONFIG_LOG_DEFAULT_LEVEL=3.

3. When I set CONFIG_LOG_DEFAULT_LEVEL=4, the printed log shows the error message as follows:

4. The code is as follows:

[17:18:27.649]收←◆[00:00:1[00:00:00.306,945] <dbg> os: setup_thread_stack: stack 0x20002340 for thread 0x20000828: obj_size=4160 buf_start=0x20002380  buf_size 4096 stack_ptr=0x20003380
[00:00:00.306,976] <dbg> os: setup_thread_stack: stack 0x200021c0 for thread 0x20000788: obj_size=384 buf_start=0x20002200  buf_size 320 stack_ptr=0x20002340
--- 24 messages dropped ---
[00:00:00.306,976] <dbg> mpu: mpu_configure_region: Configure MPU region at index 0x2
[00:00:00.307,006] <dbg> mpu: region_allocate_and_init: Program MPU region at index 0x2
[00:00:00.307,006] <dbg> mpu: region_init: [2] 0x20002340 0x150b000a
[00:00:00.307,037] <dbg> clock_control: clkstarted_handle: lfclk: Clock started
[00:00:00.307,067] <dbg> os: setup_thread_stack: stack 0x20001640 for thread 0x20000288: obj_size=832 buf_start=0x20001680  buf_size 768 stack_ptr=0x20001980
[00:00:00.307,128] <dbg> os: setup_thread_stack: stack 0x20003380 for thread 0x200008e8: obj_size=2112 buf_start=0x200033c0  buf_size 2048 stack_ptr=0x20003bc0
[00:00:00.307,159] <dbg> mpu: mpu_configure_region: Configure MPU region at index 0x2
[00:00:00.307,159] <dbg> mpu: region_allocate_and_init: Program MPU region at index 0x2
[00:00:00.307,189] <dbg> mpu: region_init: [2] 0x20003380 0x150b000a
[00:00:00.307,189] <dbg> mpu: mpu_configure_region: Configure MPU region at index 0x2
[00:00:00.307,220] <dbg> mpu: region_allocate_and_init: Program MPU region at index 0x2
[00:00:00.307,220] <dbg> mpu: region_init: [2] 0x20002340 0x150b000a
[00:00:00.307,250] <dbg> os: setup_thread_stack: stack 0x20001200 for thread 0x200001e8: obj_size=1088 buf_start=0x20001240  buf_size 1024 stack_ptr=0x20001640
[00:00:00.307,281] <dbg> os: k_sched_unlock: scheduler unlocked (0x20000828:0)
[00:00:00.307,281] <dbg> mpu: mpu_configure_region: Configure MPU region at index 0x2
[00:00:00.307,312] <dbg> mpu: region_allocate_and_init: Program MPU region at index 0x2
[00:00:00.307,312] <dbg> mpu: region_init: [2] 0x20002340 0x150b000a
LOG_PRINTK Hello World! nrf52840dk_nrf52840
LOG_RAW Hello World! nrf52840dk_nrf52840
[00:00:00.307,434] <err> hello_world: LOG_ERR Hello World! nrf52840dk_nrf52840

[00:00:00.307,464] <wrn> hello_world: LOG_WRN Hello World! nrf52840dk_nrf52840

[00:00:00.307,495] <inf> hello_world: LOG_INF Hello World! nrf52840dk_nrf52840

[00:00:00.307,525] <dbg> hello_world: log_test: LOG_DBG Hello World! nrf52840dk_nrf52840

[00:00:00.307,556] <err> hello_world: LOG_HEXDUMP_ERR Hello World!

                                      6e 72 66 39 31 36 30 64  6b 5f 6e 72 66 39 31 36 |nrf9160d k_nrf916
                                      30                                               |0                

[17:18:28.897]收←◆[00:00:00.555,725] <dbg> mpu: mpu_configure_region: Configure MPU region at index 0x2
[00:00:00.555,755] <dbg> mpu: region_allocate_and_init: Program MPU region at index 0x2
[00:00:00.555,755] <dbg> mpu: region_init: [2] 0x200021c0 0x150b000a
[00:00:00.555,786] <dbg> pm: pm_system_suspend: No PM operations done.
[00:00:01.555,755] <dbg> mpu: mpu_configure_region: Configure MPU region at index 0x2
[00:00:01.555,786] <dbg> mpu: region_allocate_and_init: Program MPU region at index 0x2
[00:00:01.555,786] <dbg> mpu: region_init: [2] 0x20001640 0x150b000a

[17:18:29.951]收←◆[00:00:01.608,734] <dbg> mpu: mpu_configure_region: Configure MPU region at index 0x2
[00:00:01.608,764] <dbg> mpu: region_allocate_and_init: Program MPU region at index 0x2
[00:00:01.608,795] <dbg> mpu: region_init: [2] 0x200021c0 0x150b000a
[00:00:01.608,795] <dbg> pm: pm_system_suspend: No PM operations done.
[00:00:02.608,795] <dbg> mpu: mpu_configure_region: Configure MPU region at index 0x2
[00:00:02.608,825] <dbg> mpu: region_allocate_and_init: Program MPU region at index 0x2
[00:00:02.608,825] <dbg> mpu: region_init: [2] 0x20001640 0x150b000a

[17:18:30.650]收←◆[00:00:02.661,804] <dbg> mpu: mpu_configure_region: Configure MPU region at index 0x2
[00:00:02.661,804] <dbg> mpu: region_allocate_and_init: Program MPU region at index 0x2
[00:00:02.661,834] <dbg> mpu: region_init: [2] 0x200021c0 0x150b000a
[00:00:02.661,865] <dbg> pm: pm_system_suspend: No PM operations done.
[00:00:03.307,800] <dbg> mpu: mpu_configure_region: Configure MPU region at index 0x2
[00:00:03.307,830] <dbg> mpu: region_allocate_and_init: Program MPU region at index 0x2
[00:00:03.307,830] <dbg> mpu: region_init: [2] 0x20002340 0x150b000a
LOG_PRINTK Hello World! nrf52840dk_nrf52840
LOG_RAW Hello World! nrf52840dk_nrf52840
[00:00:03.307,922] <err> hello_world: LOG_ERR Hello World! nrf52840dk_nrf52840

[00:00:03.307,983] <wrn> hello_world: LOG_WRN Hello World! nrf52840dk_nrf52840

[00:00:03.308,013] <inf> hello_world: LOG_INF Hello World! nrf52840dk_nrf52840

[00:00:03.308,044] <dbg> hello_world: log_test: LOG_DBG Hello World! nrf52840dk_nrf52840

[00:00:03.308,074] <err> hello_world: LOG_HEXDUMP_ERR Hello World!

                                      6e 72 66 39 31 36 30 64  6b 5f 6e 72 66 39 31 36 |nrf9160d k_nrf916
                                      30                                               |0                
[00:00:03.308,105] <wrn> hello_world: LOG_HEXDUMP_WRN Hello World!

                                      6e 72 66 39 31 36 30 64  6b 5f 6e 72 66 39 31 36 |nrf9160d k_nrf916
                                      30                                               |0                
[00:00:03.308,105] <inf> hello_world: LOG_HEXDUMP_INF Hello World!

                                      6e 72 66 39 31 36 30 64  6b 5f 6e 72 66 39 31 36 |nrf9160d k_nrf916
                                      30                                               |0                
[00:00:03.308,135] <dbg> hello_world: log_test: LOG_HEXDUMP_DBG Hello World!

                                      6e 72 66 39 31 36 30 64  6b 5f 6e 72 66 39 31 36 |nrf9160d k_nrf916
                                      30                                               |0                
[00:00:03.308,166] <dbg> os: z_tick_sleep: thread 0x20000828 for 98304 ticks
[00:00:03.308,197] <dbg> mpu: mpu_configure_region: Configure MPU region at index 0x2
[00:00:03.308,197] <dbg> mpu: region_allocate_and_init: Program MPU region at index 0x2
[00:00:03.308,227] <dbg> mpu: region_init: [2] 0x20001640 0x150b000a

[17:18:31.874]收←◆[00:00:03.533,081] <dbg> mpu: mpu_configure_region: Configure MPU region at index 0x2
[00:00:03.533,111] <dbg> mpu: region_allocate_and_init: Program MPU region at index 0x2
[00:00:03.533,111] <dbg> mpu: region_init: [2] 0x200021c0 0x150b000a
[00:00:03.533,142] <dbg> pm: pm_system_suspend: No PM operations done.
[00:00:04.533,111] <dbg> mpu: mpu_configure_region: Configure MPU region at index 0x2
[00:00:04.533,142] <dbg> mpu: region_allocate_and_init: Program MPU region at index 0x2
[00:00:04.533,142] <dbg> mpu: region_init: [2] 0x20001640 0x150b000a

[17:18:32.928]收←◆[00:00:04.586,151] <dbg> mpu: mpu_configure_region: Configure MPU region at index 0x2
[00:00:04.586,181] <dbg> mpu: region_allocate_and_init: Program MPU region at index 0x2
[00:00:04.586,181] <dbg> mpu: region_init: [2] 0x200021c0 0x150b000a
[00:00:04.586,212] <dbg> pm: pm_system_suspend: No PM operations done.
[00:00:05.586,181] <dbg> mpu: mpu_configure_region: Configure MPU region at index 0x2
[00:00:05.586,212] <dbg> mpu: region_allocate_and_init: Program MPU region at index 0x2
[00:00:05.586,212] <dbg> mpu: region_init: [2] 0x20001640 0x150b000a

[17:18:33.651]收←◆[00:00:05.639,190] <dbg> mpu: mpu_configure_region: Configure MPU region at index 0x2
[00:00:05.639,190] <dbg> mpu: region_allocate_and_init: Program MPU region at index 0x2
[00:00:05.639,221] <dbg> mpu: region_init: [2] 0x200021c0 0x150b000a
[00:00:05.639,251] <dbg> pm: pm_system_suspend: No PM operations done.
[00:00:06.308,258] <dbg> mpu: mpu_configure_region: Configure MPU region at index 0x2
[00:00:06.308,288] <dbg> mpu: region_allocate_and_init: Program MPU region at index 0x2
[00:00:06.308,288] <dbg> mpu: region_init: [2] 0x20002340 0x150b000a
LOG_PRINTK Hello World! nrf52840dk_nrf52840
LOG_RAW Hello World! nrf52840dk_nrf52840
[00:00:06.308,410] <err> hello_world: LOG_ERR Hello World! nrf52840dk_nrf52840

[00:00:06.308,441] <wrn> hello_world: LOG_WRN Hello World! nrf52840dk_nrf52840

[00:00:06.308,471] <inf> hello_world: LOG_INF Hello World! nrf52840dk_nrf52840

[00:00:06.308,502] <dbg> hello_world: log_test: LOG_DBG Hello World! nrf52840dk_nrf52840

[00:00:06.308,532] <err> hello_world: LOG_HEXDUMP_ERR Hello World!

                                      6e 72 66 39 31 36 30 64  6b 5f 6e 72 66 39 31 36 |nrf9160d k_nrf916
                                      30                                               |0                
[00:00:06.308,563] <wrn> hello_world: LOG_HEXDUMP_WRN Hello World!

                                      6e 72 66 39 31 36 30 64  6b 5f 6e 72 66 39 31 36 |nrf9160d k_nrf916
                                      30                                               |0                
[00:00:06.308,563] <inf> hello_world: LOG_HEXDUMP_INF Hello World!

                                      6e 72 66 39 31 36 30 64  6b 5f 6e 72 66 39 31 36 |nrf9160d k_nrf916
                                      30                                               |0                
[00:00:06.308,593] <dbg> hello_world: log_test: LOG_HEXDUMP_DBG Hello World!

                                      6e 72 66 39 31 36 30 64  6b 5f 6e 72 66 39 31 36 |nrf9160d k_nrf916
                                      30                                               |0                
[00:00:06.308,624] <dbg> os: z_tick_sleep: thread 0x20000828 for 98304 ticks
[00:00:06.308,654] <dbg> mpu: mpu_configure_region: Configure MPU region at index 0x2
[00:00:06.308,654] <dbg> mpu: region_allocate_and_init: Program MPU region at index 0x2
[00:00:06.308,685] <dbg> mpu: region_init: [2] 0x20001640 0x150b000a

5. Test environment:

ncs v2.4.0

DK:PCA10056 3.0.0

Thank you for all your assistance.
Kind regards,
Peter.Min

[wisph]

Hi,

To get the default log level to work at debug, you realy need to be mindful about the logging system itself, it uses alot of memory, and since ALL parts of zephyr will start logging like crazy, this can turn into a problem fast enough.

Check stack/heap sizes, consider using more targeted log_level settings, and play around with the LOG config, direct/indirect mode can make a big difference.

Hope it helps

Grts,

[peter.min]

Hi wisph,

1. Is the test code, you can test this problem.

2. This problem is easy to recur, but difficult to solve.

1_hello_world.zip

Thank you for all your assistance.
Kind regards,
Peter.Min