[logging] Initialization order error with multidomain immediate mode logging using IPC on nRF5340

[bogdanm]

Configuration options:

CONFIG_LOG_MULTIDOMAIN=y
CONFIG_LOG_LINK_IPC_SERVICE=y
CONFIG_LOG_IMMEDIATE=y
CONFIG_LOG_PROCESS_THREAD=n

With the configuration above, link_ipc_service_init (in log_link_ipc_service.c) is called by enable_logger (log_core.c) as follows (note the assert at the top):

#0  assert_print (fmt=0x20004788 <backend_data_0+704> "HH") at ....
#1  0x0003c9de in nrfx_ipc_receive_event_enable (event_index=event_index@entry=1 '\001') at modules/hal/nordic/nrfx/drivers/src/nrfx_ipc.c:108
#2  0x0003aa7a in mbox_nrf_set_enabled (dev=<optimized out>, channel=1, enable=<optimized out>) at zephyr/drivers/mbox/mbox_nrfx_ipc.c:134
#3  0x00029258 in z_impl_mbox_set_enabled (enable=true, channel=0x20002940 <backend_config_0+20>) at zephyr/include/zephyr/drivers/mbox.h:375
#4  mbox_set_enabled (enable=true, channel=0x20002940 <backend_config_0+20>) at build/zephyr/include/generated/syscalls/mbox.h:83
#5  mbox_init (instance=<optimized out>) at zephyr/subsys/ipc/ipc_service/backends/ipc_rpmsg_static_vrings.c:337
#6  open (instance=<optimized out>) at zephyr/subsys/ipc/ipc_service/backends/ipc_rpmsg_static_vrings.c:564
#7  0x0002a622 in link_ipc_service_init (link_remote=0x20002994 <link_ipc_service_data+8>) at zephyr/subsys/logging/log_link_ipc_service.c:68
#8  0x00029f3c in log_link_initiate (config=0x0, link=0x6ceec <link_ipc_service>) at zephyr/include/zephyr/logging/log_link.h:128
#9  z_log_links_initiate () at zephyr/subsys/logging/log_mgmt.c:571
#10 0x00029696 in z_log_init (blocking=blocking@entry=false, can_sleep=can_sleep@entry=false) at zephyr/subsys/logging/log_core.c:289
#11 0x0005ff7c in enable_logger () at zephyr/subsys/logging/log_core.c:923
#12 0x000433b6 in z_sys_init_run_level (level=level@entry=INIT_LEVEL_POST_KERNEL) at zephyr/kernel/init.c:288
#13 0x000433ca in bg_thread_main (unused1=<optimized out>, unused2=<optimized out>, unused3=<optimized out>) at zephyr/kernel/init.c:318
#14 0x00027ee2 in z_thread_entry (entry=0x433bd <bg_thread_main>, p1=0x0, p2=0x0, p3=0x0) at zephyr/lib/os/thread_entry.c:48
#15 0x0002ca56 in arch_switch_to_main_thread (main_thread=0x20053de8 <z_main_stack+8232>, stack_ptr=0x0, _main=0x433bd <bg_thread_main>) at zephyr/arch/arm/core/aarch32/thread.c:577
#16 0xaaaaaaaa in ?? ()

This happens because the initialization priority of the logger is 0 (log_core.c):

SYS_INIT(enable_logger, POST_KERNEL, CONFIG_LOG_CORE_INIT_PRIORITY);

But the initialization priority of the nRF5340 IPC mailbox driver is 40 (mbox_nrfx_ipc.c):

DEVICE_DT_INST_DEFINE(0, mbox_nrf_init, NULL, &nrfx_mbox_data, &nrfx_mbox_conf,
            POST_KERNEL, CONFIG_MBOX_INIT_PRIORITY,
            &mbox_nrf_driver_api);

So the hardware mailbox driver is not initialized when link_ipc_service_init is called.

My Zephyr version: https://github.com/nrfconnect/sdk-zephyr/tree/v3.4.99-ncs1-1 (I'm using Nordic Connect SDK, but this appears to be a mainline Zephyr issue).

[bogdanm]

Forgot to add: the priority of this is very low as far as I'm concerned. I had immediate logging enabled in my project and this is why I noticed this issue, because otherwise the utility of immediate mode multidomain logging is very questionable. I just thought that I should mention this issue since I stumbled upon it.

[github-actions[bot]]

This issue has been marked as stale because it has been open (more than) 60 days with no activity. Remove the stale label or add a comment saying that you would like to have the label removed otherwise this issue will automatically be closed in 14 days. Note, that you can always re-open a closed issue at any time.

[github-actions[bot]]

This issue has been marked as stale because it has been open (more than) 60 days with no activity. Remove the stale label or add a comment saying that you would like to have the label removed otherwise this issue will automatically be closed in 14 days. Note, that you can always re-open a closed issue at any time.

[nordic-krch]

This issue is seen only because you are using log immediate. When deferred mode is used (the one intended to be used with multidomain configuration) then z_log_init is used by the logging thread and not by enable_logger which just creates the thread. I will some configuration check to prevent that.

@bogdanm Are you trying to use multidomain logging in immediate mode?

[bogdanm]

This issue is seen only because you are using log immediate. When deferred mode is used (the one intended to be used with multidomain configuration) then z_log_init is used by the logging thread and not by enable_logger which just creates the thread. I will some configuration check to prevent that.

@bogdanm Are you trying to use multidomain logging in immediate mode?

That is indeed what I was trying to do, yes. I was not aware that multidomain logging was supposed to work only in deferred mode. In this case, maybe the real fix is a depends on LOG_MODE_DEFERRED in Kconfig.