Assert and printk not printed on RTT

[Qbicz]

Describe the bug
Log messages are printed, but assert message is not printed out. As a result, it gives impression that device hanged, but does not give any clue why. You can see that it was an assertion, by opening debugger and stopping after the device hanged:

>> ninja debug
gdb> c
gdb> (CTRL + C)

To Reproduce
Happens for any assert in Zephyr subsystems.
Can be reproduced on hello_world with small modification:

#include <zephyr.h>
#include <misc/printk.h>
#include <assert.h>

#define HELLO_LOG_LEVEL 4
#include <logging/log.h>
LOG_MODULE_REGISTER(hello, HELLO_LOG_LEVEL);

void main(void)
{
	for (int i=0; i<5; i++) {
		LOG_WRN("test %d", i);
	}

	k_sleep(100);

	__ASSERT(false, "Asserted!");

	printk("Hello World! %s\n", CONFIG_BOARD);
}

Output:

[00000000] <wrn> hello: test 0
[00000000] <wrn> hello: test 1
[00000000] <wrn> hello: test 2
[00000000] <wrn> hello: test 3
[00000000] <wrn> hello: test 4

Assert message ASSERTION FAIL ... is not printed. Is is the same with __ASSERT_NO_MSG or if instead of assert there is just a call to printk();

Environment:
In configuration, printk is processed by logger: CONFIG_LOG_PRINTK=y

Full config:

CONFIG_ASSERT=y
CONFIG_ASSERT_LEVEL=2

CONFIG_LOG=y
CONFIG_LOG_DEFAULT_LEVEL=2
CONFIG_LOG_BACKEND_RTT=y
CONFIG_LOG_BACKEND_RTT_MODE_DROP=y
CONFIG_LOG_MODE_NO_OVERFLOW=y
CONFIG_LOG_PRINTK=y
CONFIG_LOG_PRINTK_MAX_STRING_LENGTH=256
CONFIG_LOG_BUFFER_SIZE=4096
CONFIG_LOG_BACKEND_RTT_MESSAGE_SIZE=256
CONFIG_LOG_STRDUP_BUF_COUNT=64
CONFIG_LOG_STRDUP_MAX_STRING=64
CONFIG_LOG_BACKEND_SHOW_COLOR=n
CONFIG_LOG_BACKEND_FORMAT_TIMESTAMP=n
CONFIG_LOG_PROCESS_THREAD_STACK_SIZE=1024

CONFIG_CONSOLE=y
CONFIG_USE_SEGGER_RTT=y
CONFIG_SEGGER_RTT_BUFFER_SIZE_UP=4096
CONFIG_RTT_CONSOLE=y
CONFIG_UART_CONSOLE=n

[Qbicz]

FYI @nordic-krch @pdunaj @wiminordic

[nordic-krch]

@Qbicz i've reproduced the issue.

[Qbicz]

Thank you @nordic-krch. Let me know if you need any further info.

[nordic-krch]

So the problem is that assert ends up in forever loop in current context so logger thread cannot process logs:

zephyr/include/misc/__assert.h

Line 90 in c716f9c

for (;;) { \

I'm not sure what is the intention there because depending on the context it will block the system (high priority task or interrupt) or system will continue if it happens in low priority task.

@nashif I see that it's been like that from the beginning of github history. Do we consider assert as unrecoverable? If yes then we need to do something with it because current local loop is not good.

[Qbicz]

I think the goal of assert is to print the message and hang/exit.
Probably the logger should flush the messages when the assert happens?

[nordic-krch]

@nashif @galak so what should we do there? current infinite loop is definitely not a good solution. What about calling k_oops() there?

[Qbicz]

IMHO assert should be considered a fatal, unrecoverable condition. This is used in development only and its goal is to early reveal bugs in the code and show it to a developer. If the program is buggy, it does not matter if the program can continue or not (in development) - because the bug should be fixed.

In production, the program is released without assertions. Because of that, it makes no difference if assert trigger fatal termination of thread or entire system. So I believe there should be LOG_PANIC when assert happens.

[carlescufi]

Calling k_oops might make it harder to debug ASSERT conditions. Maybe @andrewboie has a suggestion here on how to deal with this particular issue.

[Qbicz]

@nordic-krch can we first fix the problem I mentioned? The visible problem is that on any assert, nothing is printed out and user has to guess that it was an assertion and use debugger to get to know where it happened.

And the printk has to be handled by logger CONFIG_LOG_PRINTK=y, because otherwise it locks RTT which is dangerous when anything is printed from interrupts.

Let's handle this problem first, maybe by using logger panic?