Data Access Violation when LOG_* is called on ISR context

[sdalu]

Data Access Violation when LOG_* is called on ISR context

To Reproduce
On Zephyr 2.4, using the samples/basic/button example.

Add to prj.conf (I didn't manage to get it shorter):

CONFIG_LOG=y
CONFIG_CONSOLE=y
CONFIG_UART_CONSOLE=y
CONFIG_USE_SEGGER_RTT=y
CONFIG_RTT_CONSOLE=n
CONFIG_DEBUG=y
CONFIG_DEBUG_INFO=y
CONFIG_ASSERT=y
CONFIG_ASSERT_VERBOSE=y
CONFIG_NO_OPTIMIZATIONS=y
CONFIG_MPU_STACK_GUARD=y
CONFIG_HW_STACK_PROTECTION=y
CONFIG_STACK_CANARIES=y
CONFIG_ENTROPY_GENERATOR=y

In main.c add:

#define LOG_LEVEL LOG_LEVEL_DBG
#include <logging/log.h>
LOG_MODULE_REGISTER(main);

and for button_pressed

    LOG_WRN("aaaaaaaaaa");

I'm using the decawave board (nrf52 based).

Logs and console output

*** Booting Zephyr OS build zephyr-v2.4.0  ***
Set up button at GPIO_0 pin 2
Set up LED at GPIO_0 pin 14
Press the button
Button pressed at 254950
[[[00:00:08.780,944] <err> os: ***** MPU FAULT *****
[00:00:08.781,005] <err> os:   Stacking error (context area might be not valid)
[00:00:08.781,036] <err> os:   Data Access Violation
[00:00:08.781,066] <err> os:   MMFAR Address: 0x2000097c
[00:00:08.781,127] <err> os: r0/a1:  0x01020101  r1/a2:  0x00000001  r2/a3:  0x6870657a
[00:00:08.781,127] <err> os: r3/a4:  0x692f7279 r12/ip:  0x756c636e r14/lr:  0x732f6564
[00:00:08.781,158] <err> os:  xpsr:  0x2e6b6200
[00:00:08.781,188] <err> os: Faulting instruction address (r15/pc): 0x6c6e6970
[00:00:08.781,219] <err> os: >>> ZEPHYR FATAL ERROR 2: Stack overflow on CPU 0
[00:00:08.781,280] <err> os: Current thread: 0x20000110 (unknown)
[00:00:09.969,635] <err> os: Halting system

If I'm removing stack canaries, I got instead:

*** Booting Zephyr OS build zephyr-v2.4.0  ***
Set up button at GPIO_0 pin 2
Set up LED at GPIO_0 pin 14
Press the button
Button pressed at 42454
[00:00:01.295,562] <wrn> main: aaaaaaaaaa
ASSERTION FAIL [z_spin_lock_valid(l)] @ WEST_TOPDIR/zephyr/include/spinlock.h:92
	Recursive spinlock 0x200008e0
[00:00:02.301,910] <err> os: ***** MPU FAULT *****
ASSERTION FAIL [z_spin_lock_valid(l)] @ WEST_TOPDIR/zephyr/include/spinlock.h:92
	Recursive spinlock 0x200008e0

[nashif]

should consider increasing the interrupt handler stack maybe?

CONFIG_ISR_STACK_SIZE

[sdalu]

Nope, same with CONFIG_ISR_STACK_SIZE=4096 (default was arround 2k)
Application is "just": a button generating a log, it shouldn't have a huge impact on the stack.

[remy-luisant]

I might be having the same issue on a custom board, but I'm blocked from investigating by issue #30074, since the noise from spurious spinlock validation errors is deafening. In my case, I get undefined instruction errors when execution is taken out of the RAM and into MMIO areas.

I have OpenOCD running and the issue, if indeed this is the same one, reliably reproducible. While this is a port to ARMv7-A with NEON, things are very stable and I will be glad to take a look once spinlock validation stops failing.

[remy-luisant]

@sdalu I'm trying to narrow this down now that the spinlock issue is resolved for me. This is a pretty slippery one, however. I am trying to look for common things while I ponder a more useful approach. I have a suspicion about the uart_poll functions. What is your UART driver? Can you tell me what code does the LR register point to when you have a backtrace? (You can use addr2line, the list file or the list commmand in a debugger, if you have one.)

[remy-luisant]

I have my problem fixed and it turns out it was unrelated.

[nordic-krch]

Can you try to increase LOG_PROCESS_THREAD_STACK_SIZE?

[carlescufi]

@sdalu closing this for now, since this has seen no feedback from you for a while. If this is still an issue on the latest Zephyr master, please reopen it.