Runtime Errors over Compile Time Errors

[TorstenRobitzki]

Currently, I'm investigating, why I'm unable to log messages to the RTT backend, with having CONFIG_LOG_MODE_DEFERRED=y to not slow down the program flow, when no RTT console is attached. In the middle, I ended up with this call stack:

Program received signal SIGTRAP, Trace/breakpoint trap.
arch_system_halt (reason=reason@entry=4) at /Users/todi/bloomlife/zephyr-workspace/zephyr/kernel/fatal.c:32
32      }
(gdb) bt
#0  arch_system_halt (reason=reason@entry=4) at /Users/todi/bloomlife/zephyr-workspace/zephyr/kernel/fatal.c:32
#1  0x0000547c in k_sys_fatal_error_handler (reason=reason@entry=4, esf=esf@entry=0x20002610 <z_main_stack+952>)
    at /Users/todi/bloomlife/zephyr-workspace/zephyr/kernel/fatal.c:44
#2  0x00005532 in z_fatal_error (reason=reason@entry=4, esf=esf@entry=0x20002610 <z_main_stack+952>)
    at /Users/todi/bloomlife/zephyr-workspace/zephyr/kernel/fatal.c:118
#3  0x00002140 in z_arm_fatal_error (reason=4, esf=0x20002610 <z_main_stack+952>) at /Users/todi/bloomlife/zephyr-workspace/zephyr/arch/arm/core/fatal.c:76
#4  0x0000281a in _oops () at /Users/todi/bloomlife/zephyr-workspace/zephyr/arch/arm/core/cortex_m/swap_helper.S:448
#5  <signal handler called>
#6  0xee0da104 in ?? ()
#7  0xdfdaffa6 in ?? ()

And found myself trying to understand the assembler code in swap_helper.S until I understood, that the code just forwarded a problem that was reported somewhere else. Inspecting the arguments passed to k_sys_fatal_error_handler and looking up the address on the other side of the signal handler called, led me to the conclusion, that this was "simply" an assert.

This was the failing function:

void log_thread_set(k_tid_t process_tid)
{
	if (IS_ENABLED(CONFIG_LOG_PROCESS_THREAD)) {
		__ASSERT_NO_MSG(0);
	} else {
		thread_set(process_tid);
	}
}

And here, I would like to hear your opinions. If I understand the function correctly, it will always fail given a certain compile time configuration (CONFIG_LOG_PROCESS_THREAD and asserts enabled). So, as soon as the function is linked into the binary, the linker proofed, that there is a mistake.

Wouldn't it be more helpful, to not have the function at all, if the configuration is set? This would result in compile and / or linker error and probably would save a lot of time for those, who think, they might try to call that function to get the logging working.

[koffes]

As a general note, when using RTT as logging backend, the logs are written into a memory area. This is commonly much faster than UART, so So, having CONFIG_LOG_MODE_IMMEDIATE=y should not impact timings much.

[TorstenRobitzki]

Same is usually true, if you use an UART in combination with a ring buffer. My point was: Why let the compiler generate code, that will fail 100% of the time at runtime instead of simply generating a compile time error in case, that the system can not satisfy the requested configuration.

[yashi]

@TorstenRobitzki Sure, but how?

[yashi]

It's just that we can't call we can call log_thread_set() but has no effect when IS_ENABLED(CONFIG_LOG_PROCESS_THREAD)). All other functions are allowed to be call with it enabled.

Your fix prevents it.

[TorstenRobitzki]

An easy alternative would be:

#if !IS_ENABLED(CONFIG_LOG_PROCESS_THREAD)
void log_thread_set(k_tid_t process_tid)
{
    thread_set(process_tid);
}
#endif

This way, the call to log_thread_set would have triggered a linker error during build time.

[yashi]

Yeah, I thought that as well, but I believe we have a policy to keep all symbols regardless of the configuration.

I think the best approach is to print an error message at runtime. I mean, the assertion doesn't have any message, does it?

[TorstenRobitzki]

Well, a comment next to the assert would probably do the job. But does that mean, I have to run the software at least once with asserts enabled to find all configuration errors? ;-)

[yashi]

Or add -DCONFIG_ASSERT=y to see what it says:

ASSERTION FAIL [0] @ WEST_TOPDIR/zephyr/subsys/logging/log_core.c:397
[00:00:00.000,000] <err> os: r0/a1:  0x00000004  r1/a2:  0x0000018d  r2/a3:  0x00000002
[00:00:00.000,000] <err> os: r3/a4:  0x00000004 r12/ip:  0x00000014 r14/lr:  0x00001219
[00:00:00.000,000] <err> os:  xpsr:  0x21000000
[00:00:00.000,000] <err> os: Faulting instruction address (r15/pc): 0x000050e8
[00:00:00.000,000] <err> os: >>> ZEPHYR FATAL ERROR 4: Kernel panic on CPU 0
[00:00:00.000,000] <err> os: Current thread: 0x200005b8 (unknown)
[00:00:00.000,000] <err> os: Halting system
qemu-system-arm: terminating on signal 2

The doc says it has assertion and it's a no op (unless you enable assertion like above)

Function has asserts and has no effect when CONFIG_LOG_PROCESS_THREAD is set.

https://docs.zephyrproject.org/apidoc/latest/group__log__ctrl.html#ga5f58516c3c155dde0f44ea9cc7cd8b37