Getting more information on FATAL ERROR: SecureFault on nRF9151

[Fridtjof]

Hello,

I'm working with the nRF9151, and I want to get useful information when a NULL pointer dereference happens, as I am used to on other devices. However, when a NULL pointer dereference happens, all I get in my log is

FATAL ERROR: SecureFault
Assert:stdio_init,0x00000060

I read on devacademy that because of TrustZone, I cannot get more info when a NULL pointer dereferences happens. But I cannot choose what errors I encounter, and NULL pointer dereferences are a common bug! Is there really nothing I can do to get e.g. the program counter or something? When I cause a crash in other ways (e.g. __asm__("udf #0");) I get a list of all the registers in the CPU including the PC printed in my terminal.

Any help is appreciated,
-Fridtjof

[Fridtjof]

Here is a log showing two power cycles. One where it crashes due to an undefined instruction, giving a nice debug dump, and one where it crashes due to null ptr deref, and doesn't give a nice dump.

All pins have been configured as non-secure
Booting TF-M v2.1.1-ncs4-2
[Sec Thread] Secure image initializing!
*** Booting nRF Connect SDK v3.0.1-9eb5615da66b ***
*** Using Zephyr OS v4.0.99-77f865b8f8d0 ***
[00:00:00.250,671] <inf> main: #########
[00:00:00.250,671] <inf> main: # Start #
[00:00:00.250,671] <inf> main: #########
[00:00:00.250,701] <inf> main: Initialization complete!
[00:00:01.250,885] <err> os: ***** USAGE FAULT *****
[00:00:01.250,915] <err> os:   Attempt to execute undefined instruction
[00:00:01.250,915] <err> os: r0/a1:  0x00000000  r1/a2:  0x00007fff  r2/a3:  0x00000000
[00:00:01.250,946] <err> os: r3/a4:  0x0002a093 r12/ip:  0x00000001 r14/lr:  0x00023b9f
[00:00:01.250,946] <err> os:  xpsr:  0x61000000
[00:00:01.250,976] <err> os: Faulting instruction address (r15/pc): 0x0002045c
[00:00:01.251,007] <err> os: >>> ZEPHYR FATAL ERROR 36: Unknown error on CPU 0
[00:00:01.251,037] <err> os: Current thread: 0x2000ce60 (main)
[00:00:01.308,197] <err> os: Halting system
All pins have been configured as non-secure
Booting TF-M v2.1.1-ncs4-2
[Sec Thread] Secure image initializing!
*** Booting nRF Connect SDK v3.0.1-9eb5615da66b ***
*** Using Zephyr OS v4.0.99-77f865b8f8d0 ***
[00:00:00.250,732] <inf> main: #########
[00:00:00.250,762] <inf> main: # Start #
[00:00:00.250,762] <inf> main: #########
[00:00:00.250,762] <inf> main: Initialization complete!
FATAL ERROR: SecureFault
Assert:stdio_init,0x00000060

Here is code to reproduce the issue. Line 6 of main.c can be commented in and out to change whether the program crashes with an undefined instruction or a NULL ptr deref.

0363.sample.zip

[Simon D-M]

Hi,

I just tried your sample and I can't reproduce your output. I always get the full crash dump... I tried with NCS 3.0.2 and 3.2.4, and I got the same result in both.

I just did the following modification to see in which configuration I am.

main.c : LOG_WRN(...):

#include <zephyr/kernel.h>

#include <zephyr/logging/log.h>
LOG_MODULE_REGISTER(main);

#define NULLPTR_CRASH

int main(void) {
    LOG_INF("#########");
    LOG_INF("# Start #");
    LOG_INF("#########");

    LOG_INF("Initialization complete!");
    k_sleep(K_MSEC(1000));

    #ifdef NULLPTR_CRASH
    LOG_WRN("Crashing by dereferencing NULL pointer...");
    volatile int *a = NULL;
    *a = 0;
    #else
    LOG_WRN("Crashing by executing undefined instruction...");
    __asm__("udf #0");
    #endif

    /* Main-loop */
    while (true) {
        LOG_INF("Looping...\n");
        k_sleep(K_MSEC(5000));
    }
}

prj.conf: CONFIG_LOG_MODE_IMMEDIATE=y

# UART
CONFIG_SERIAL=y
CONFIG_UART_ASYNC_API=y

# Debug
CONFIG_DEBUG=y
CONFIG_THREAD_NAME=y
CONFIG_STACK_USAGE=y
CONFIG_THREAD_ANALYZER=y
CONFIG_THREAD_ANALYZER_USE_PRINTK=y

# Logging / Printing
CONFIG_LOG=y
CONFIG_LOG_MODE_IMMEDIATE=y
CONFIG_CONSOLE=y
CONFIG_UART_CONSOLE=y
CONFIG_CBPRINTF_FP_SUPPORT=y

# Watchdog:
CONFIG_WATCHDOG=y
CONFIG_WDT_DISABLE_AT_BOOT=n

My output :

I: Secondary image: magic=unset, swap_type=0x1, copy_done=0x3, image_ok=0x3
I: Boot source: none
I: Image index: 0, Swap type: none
I: Bootloader chainload address offset: 0x10000
I: Image version: v0.0.0
*** Booting nRF Connect SDK v3.2.4-4c3fc0d44534 ***
*** Using Zephyr OS v4.2.99-9673eec75908 ***
[00:00:00.264,831] <inf> main: #########
[00:00:00.270,812] <inf> main: # Start #
[00:00:00.276,824] <inf> main: #########
[00:00:00.282,806] <inf> main: Initialization complete!
[00:00:01.290,802] <wrn> main: Crashing by dereferencing NULL pointer...
[00:00:01.304,138] <err> os: ***** SECURE FAULT *****
[00:00:01.309,936] <err> os:   Address: 0x0
[00:00:01.314,880] <err> os:   Attribution unit violation
[00:00:01.321,075] <err> os: r0/a1:  0x0002c7e0  r1/a2:  0x00000000  r2/a3:  0x00000000
[00:00:01.329,925] <err> os: r3/a4:  0x000289e7 r12/ip:  0x0000000f r14/lr:  0x00021173
[00:00:01.338,745] <err> os:  xpsr:  0x01000000
[00:00:01.344,055] <err> os: Faulting instruction address (r15/pc): 0x00020498
[00:00:01.352,081] <err> os: >>> ZEPHYR FATAL ERROR 41: Unknown error on CPU 0
[00:00:01.360,137] <err> os: Current thread: 0x2000c8c0 (main)
[00:00:01.366,729] <err> os: Halting system
*** Booting MCUboot v2.3.0-dev-d537e5b5d244 ***
*** Using nRF Connect SDK v3.2.4-4c3fc0d44534 ***
*** Using Zephyr OS v4.2.99-9673eec75908 ***
I: Starting bootloader
I: Primary image: magic=unset, swap_type=0x1, copy_done=0x3, image_ok=0x3
I: Secondary image: magic=unset, swap_type=0x1, copy_done=0x3, image_ok=0x3
I: Boot source: none
I: Image index: 0, Swap type: none
I: Bootloader chainload address offset: 0x10000
I: Image version: v0.0.0
*** Booting nRF Connect SDK v3.2.4-4c3fc0d44534 ***
*** Using Zephyr OS v4.2.99-9673eec75908 ***
[00:00:00.264,678] <inf> main: #########
[00:00:00.270,629] <inf> main: # Start #
[00:00:00.276,580] <inf> main: #########
[00:00:00.282,531] <inf> main: Initialization complete!
[00:00:01.290,435] <wrn> main: Crashing by executing undefined instruction...
[00:00:01.301,055] <err> os: ***** USAGE FAULT *****
[00:00:01.306,793] <err> os:   Attempt to execute undefined instruction
[00:00:01.314,239] <err> os: r0/a1:  0x0002c7e4  r1/a2:  0x00000000  r2/a3:  0x00000000
[00:00:01.323,059] <err> os: r3/a4:  0x000289e7 r12/ip:  0x0000000f r14/lr:  0x00021173
[00:00:01.331,878] <err> os:  xpsr:  0x01000000
[00:00:01.337,188] <err> os: Faulting instruction address (r15/pc): 0x00020498
[00:00:01.345,245] <err> os: >>> ZEPHYR FATAL ERROR 36: Unknown error on CPU 0
[00:00:01.353,271] <err> os: Current thread: 0x2000c8c0 (main)
[00:00:01.359,893] <err> os: Halting system

I believe there must be a difference in how we build the project. Can you try using nRF Connect for VS Code extension ?

Best regards,

Simon D-M

[Fridtjof]

I installed Code and the nRF extension, and have managed to build and flash an image with NCS v3.0.2. I still get the different outputs. I modified my code so that it is random whether it crashes due to udf or null ptr to make testing faster.

I notice that your output also has a bootloader info log which I don't have.

Something else: When it crashes, the device locks up and needs to be recovered.

Here is the build command that the VS Code extension uses on a pristine build. Maybe we can compare?

west build --build-dir <project path>/app/build <project path>/app --pristine --board nrf9151dk/nrf9151/ns -- -DCONF_FILE="prj.conf" -DDTC_OVERLAY_FILE="boards/myboard.overlay" -DDEBUG_THREAD_INFO=On -DCONFIG_DEBUG_THREAD_INFO=y -Dapp_DEBUG_THREAD_INFO=On -Dmcuboot_DEBUG_THREAD_INFO=Off

Output:

Booting TF-M v2.1.1-ncs4-2
[Sec Thread] Secure image initializing!
*** Booting nRF Connect SDK v3.0.2-89ba1294ac9b ***
*** Using Zephyr OS v4.0.99-f791c49f492c ***
[00:00:00.259,674] <inf> main: #########
[00:00:00.264,434] <inf> main: # Start #
[00:00:00.269,195] <inf> main: #########
[00:00:00.273,956] <inf> main: Initialization complete!
[00:00:00.280,731] <wrn> main: Crashing due to Undefined Instruction...
[00:00:01.288,787] <err> os: ***** USAGE FAULT *****
[00:00:01.294,342] <err> os:   Attempt to execute undefined instruction
[00:00:01.301,574] <err> os: r0/a1:  0x00000000  r1/a2:  0x00007fff  r2/a3:  0x00000000
[00:00:01.310,180] <err> os: r3/a4:  0x00027fb5 r12/ip:  0x00000001 r14/lr:  0x000232cb
[00:00:01.318,756] <err> os:  xpsr:  0x61000000
[00:00:01.323,944] <err> os: Faulting instruction address (r15/pc): 0x000204e8
[00:00:01.331,756] <err> os: >>> ZEPHYR FATAL ERROR 36: Unknown error on CPU 0
[00:00:01.339,599] <err> os: Current thread: 0x2000c938 (main)
[00:00:01.346,038] <err> os: Halting system
All pins have been configured as non-secure
Booting TF-M v2.1.1-ncs4-2
[Sec Thread] Secure image initializing!
*** Booting nRF Connect SDK v3.0.2-89ba1294ac9b ***
*** Using Zephyr OS v4.0.99-f791c49f492c ***
[00:00:00.259,674] <inf> main: #########
[00:00:00.264,434] <inf> main: # Start #
[00:00:00.269,195] <inf> main: #########
[00:00:00.273,956] <inf> main: Initialization complete!
[00:00:00.280,731] <wrn> main: Crashing due to NULL PTR...
FATAL ERROR: SecureFault
Assert:stdio_init,0x00000060

Code:

#include <zephyr/kernel.h>
#include <zephyr/random/random.h>

#include <zephyr/logging/log.h>
LOG_MODULE_REGISTER(main);

int main(void) {
    LOG_INF("#########");
    LOG_INF("# Start #");
    LOG_INF("#########");

    LOG_INF("Initialization complete!");

    int rand = sys_rand32_get();
    if (rand % 2 == 0) {
        LOG_WRN("Crashing due to NULL PTR...");
        k_sleep(K_MSEC(1000));
        volatile int *a = NULL;
        *a = 0;
    } else {
        LOG_WRN("Crashing due to Undefined Instruction...");
        k_sleep(K_MSEC(1000));
        __asm__("udf #0");
    }

    /* Main-loop */
    while (true) {
        LOG_INF("Looping...\n");
        k_sleep(K_MSEC(5000));
    }
}

prj.conf:

# Random
CONFIG_ENTROPY_GENERATOR=y

# UART
CONFIG_SERIAL=y
CONFIG_UART_ASYNC_API=y

# Debug
CONFIG_DEBUG=y

# Logging / Printing
CONFIG_LOG=y
CONFIG_LOG_MODE_IMMEDIATE=y
CONFIG_CONSOLE=y
CONFIG_UART_CONSOLE=y

[Simon D-M]

Hi,

Ok, I was able to reproduce your issue if I use your overlay. I think I found what is happening...

I wasn't using your overlay file before as I was testing on an nRF9151 DK, but then the difference between the two configuration was that I was using UART0 and you were using UART1. (This is also why I had some more MCUboot logs)

By default, the UART1 is used as the "secure" UART and to get the error logs of a Usage fault, you need a non-secure UART.

To make the UART1 non-secure, you can add the config CONFIG_TFM_SECURE_UART0=y so that the UART0 will become the secure one, thus releasing the UART1.

prj.conf:

# Random
CONFIG_ENTROPY_GENERATOR=y

# UART
CONFIG_SERIAL=y
CONFIG_UART_ASYNC_API=y

CONFIG_TFM_SECURE_UART0=y

# Debug
CONFIG_DEBUG=y

# Logging / Printing
CONFIG_LOG=y
CONFIG_LOG_MODE_IMMEDIATE=y
CONFIG_CONSOLE=y
CONFIG_UART_CONSOLE=y

Please, tell me if this worked for you too!

Best regards,

Simon D-M

[Fridtjof]

I can successfully get the full crash dump in the NULL PTR case if I either implement your change, setting the secure uart to uart0; or setting the log uart to 0.

Is there any other differences between the UARTs on nrf9151 that I should keep in mind when choosing which one to use for what? In the PS it seems like they are pretty much interchangable.

[Simon D-M]

Hi,

I don't think there is any major difference between the UARTs in the nRF9151. They are just configured a bit differently by default in NCS/Zephyr. But I think it should be possible to use them indifferently (if configured correctly).

Best regards,

Simon D-M