Using CONFIG_LOG_THREAD_ID_PREFIX logging with already terminated thread leads to reading invalid memory

[mkaranki]

Describe the bug

There is a possibility that log processing, when deferred logging is enabled, and when printing thread name by CONFIG_LOG_THREAD_ID_PREFIX option, accesses memory that does not anymore contain thread information.

I think this happens because logging task gets just the tid of the logging thread, and resolves that to the name string very late. Happens here:

zephyr/subsys/logging/log_output.c

Lines 314 to 315 in b8541c5

	total += print_formatted(output, "[%s] ",
	tid == NULL ? "irq" : k_thread_name_get(tid));

At that point, the thread might have already be destroyed and the memory used for struct k_thread might be used already for something else.

Regression

• This is a regression.

Steps to reproduce

1. Have deferred logging and CONFIG_LOG_THREAD_ID_PREFIX set on so that log messages should contain the thread name from where the log output was originated.
2. Create a new thread on run-time, so that struct k_thread is storage is not persistent. For example, locate it to the stack or to the heap.
3. Log something in the new thread and terminate and join it.
4. Run the program e.g. with ASAN, and see it raising an error about use-after-free or otherwise invalid memory access on the logging backend.

Relevant log output

READ of size 11 at 0xefc03780 thread T4
    #0 0xf79cd1ed in strlen ../../../../../src/libsanitizer/sanitizer_common/sanitizer_common_interceptors.inc:391
    #1 0x80dd470 in z_cbvprintf_impl zephyr/lib/os/cbprintf_complete.c:1629
    #2 0x80d10e3 in cbvprintf zephyr/include/zephyr/sys/cbprintf.h:752
    #3 0x810e160 in print_formatted zephyr/subsys/logging/log_output.c:144
    #4 0x810eeb5 in ids_print zephyr/subsys/logging/log_output.c:342
    #5 0x810f681 in prefix_print /home/mikar/vdl200-zephyr/zephyr/subsys/logging/log_output.c:654
    #6 0x810f77a in log_output_process zephyr/subsys/logging/log_output.c:684
    #7 0x810fa40 in log_output_msg_process zephyr/subsys/logging/log_output.c:727
    #8 0x8115772 in process zephyr/subsys/logging/backends/log_backend_fs.c:649

Impact

Intermittent – Occurs occasionally; hard to reproduce.

Environment

No response

Additional Context

No response

[ljd42]

Hello @mkaranki

Many thanks for your report. This issue has been already reported in issue #95077. Possible technical resolution is being discussed, and a proper documentation of this limitation is on the way (PR #96640).

[ljd42]

@cfriedt , @jhedberg: suggest to close as duplicate (can be discussed in release meeting, if needed).