Skip to content

logging: Incorrect init sequence when log thread has lower priority #87276

Open
@lromeraj

Description

@lromeraj

Describe the bug

Logging does not work when the shell is used as the logging backend and the shell thread priority is higher than the log thread.

To Reproduce

Build an application enabling the shell and logging while setting a lower priority for the log thread. The following configuration should be enough:

CONFIG_SHELL=y
CONFIG_SHELL_THREAD_PRIORITY=5
CONFIG_SHELL_THREAD_PRIORITY_OVERRIDE=y

CONFIG_LOG=y
CONFIG_LOG_PROCESS_THREAD_CUSTOM_PRIORITY=y
CONFIG_LOG_PROCESS_THREAD_PRIORITY=10

No log messages appear in the output.

Expected behavior

The shell should print log messages since this is a valid configuration.

Impact

This issue has always existed but became symptomatic after PR #84955. It prevents log output when the shell thread priority is higher than the logging thread priority.

Environment:

Additional context

This issue is caused by an initialization priority problem. The function enable_logger() executes the following:

static int enable_logger(void)
{
	if (IS_ENABLED(CONFIG_LOG_PROCESS_THREAD)) {
		k_timer_init(&log_process_thread_timer,
			     log_process_thread_timer_expiry_fn, NULL);
		/* Start logging thread */
		k_thread_create(&logging_thread, logging_stack,
				K_KERNEL_STACK_SIZEOF(logging_stack),
				log_process_thread_func, NULL, NULL, NULL,
				LOG_PROCESS_THREAD_PRIORITY, 0,
				COND_CODE_1(CONFIG_LOG_PROCESS_THREAD,
					    K_MSEC(CONFIG_LOG_PROCESS_THREAD_STARTUP_DELAY_MS),
					    K_NO_WAIT));
		k_thread_name_set(&logging_thread, "logging");
	} else {
		(void)z_log_init(false, false);
	}

	return 0;
}

When the log thread is enabled, z_log_init() is called inside the logging thread, causing an improper initialization order when the log thread priority is lower than the shell thread priority. As a result, when the shell thread starts, it runs log_backend_enable() before z_log_init(), which is responsible for setting the actual backend ID.

This explains why the logging backend stopped working with the above configuration after the modifications in PR #84955, which changed log_backend_enable() and z_log_init().

Additionally, if CONFIG_LOG_PROCESS_THREAD_STARTUP_DELAY_MS is set to a significantly high value, the same problem is likely to occur.

I believe that z_log_init() should also be called inside enable_logger() when the log thread is enabled, since enable_logger() is executed during the POST_KERNEL stage:

SYS_INIT(enable_logger, POST_KERNEL, CONFIG_LOG_CORE_INIT_PRIORITY);

This issue could be resolved by:

  1. Passing an argument to the main thread function with the activate_mask.
  2. Declaring a static variable to store the activate_mask and using it only during initialization.

Additionally, renaming the static function enable_logger() to init_logger() might make its purpose clearer.

I can create a PR with the proposed changes to fix this issue.

Metadata

Metadata

Assignees

Labels

area: LoggingbugThe issue is a bug, or the PR is fixing a bugpriority: mediumMedium impact/importance bug

Type

No type

Projects

No projects

Milestone

No milestone

Relationships

None yet

Development

No branches or pull requests

Issue actions