SPI Master causing Hardfault

[abarnas-airly]

Hello, community,
I am writing a multi-board system that will communicate using SPI. To simplify the problem let's assume I have two boards (master and slave) running Zephyr.
I am facing a significant problem of hard fault on the master's side (during the debugging the slave is disconnected to separate the master).
The communication scheme looks like that:

(Cmd from master [write/read/...]) -> (1ms for the slave to prepare/execute) -> (Actual transaction )

Hard faults are happening on the actual transaction and stop happening if between Command and Transfer is at least 4ms.

I need to understand what is causing the fault and why changing timeout prevents hard faults (my code does not do anything in the meantime)

Sometimes logs show hard fault messages but not always and different values and types of hard faults are mentioned depending on nothing.

Could anyone find any potential flaws in my code or point me a way to debug those faults I will be thankful.

examples:

[00:00:01.001,000] <wrn> main: CMD: 0 Sent!

[00:00:01.002,000] <err> os: ***** USAGE FAULT *****
[00:00:01.002,000] <err> os:   Attempt to execute undefined instruction
[00:00:01.002,000] <err> os: r0/a1:  0x00000000  r1/a2:  0x00000001  r2/a3:  0x0000037d
[00:00:01.002,000] <err> os: r3/a4:  0x40013000 r12/ip:  0x00000000 r14/lr:  0x080117cd
[00:00:01.002,000] <err> os:  xpsr:  0x01000000
[00:00:01.002,000] <err> os: r4/v1:  0x0801183f  r5/v2:  0x00000000  r6/v3:  0xffffffb5
[00:00:01.003,000] <err> os: r7/v4:  0x20002b18  r8/v5:  0x00000000  r9/v6:  0x00000000
[00:00:01.003,000] <err> os: r10/v7: 0x00000000  r11/v8: 0x00000000    psp:  0x20002af0
[00:00:01.003,000] <err> os: EXC_RETURN: 0xfffffffd
[00:00:01.003,000] <err> os: Faulting instruction address (r15/pc): 0x080117dc
[00:00:01.003,000] <err> os: >>> ZEPHYR FATAL ERROR 36: Unknown error on CPU 0
[00:00:01.003,000] <err> os: Current thread: 0x200006f8 (main)
[00:00:01.097,000] <err> os: Halting system

[00:00:01.508,000] <err> os: ***** BUS FAULT *****
[00:00:01.508,000] <err> os:   Instruction bus error
[00:00:01.508,000] <err> os: r0/a1:  0x20000074  r1/a2:  0x00000001  r2/a3:  0x0000037d
[00:00:01.508,000] <err> os: r3/a4:  0x20000074 r12/ip:  0x00000000 r14/lr:  0x08000017
[00:00:01.508,000] <err> os:  xpsr:  0x01000000
[00:00:01.508,000] <err> os: r4/v1:  0x0801183f  r5/v2:  0x00000000  r6/v3:  0x00000000
[00:00:01.509,000] <err> os: r7/v4:  0x20002b10  r8/v5:  0x00000000  r9/v6:  0x00000000
[00:00:01.509,000] <err> os: r10/v7: 0x00000000  r11/v8: 0x00000000    psp:  0x20002ae8
[00:00:01.509,000] <err> os: EXC_RETURN: 0xfffffffd
[00:00:01.509,000] <err> os: Faulting instruction address (r15/pc): 0x07fffc36
[00:00:01.509,000] <err> os: >>> ZEPHYR FATAL ERROR 27: Unknown error on CPU 0
[00:00:01.509,000] <err> os: Current thread: 0x200006f8 (main)
[00:00:01.616,000] <err> os: Halting system

Board is Nucleo STM32L412RB

Here is my code (simplified as much as I could):

#include <zephyr/kernel.h>
#include <zephyr/device.h>
#include <zephyr/devicetree.h>
#include <zephyr/drivers/gpio.h>
#include <zephyr/drivers/spi.h>

#include <zephyr/logging/log.h>

LOG_MODULE_REGISTER(main, LOG_LEVEL_WRN);

#define MY_SPI_MASTER DT_ALIAS(spi_master)
#define SLAVE_BOARD DT_NODELABEL(slave_board)

// SPI master functionality
const struct spi_dt_spec spi_master = SPI_DT_SPEC_GET(SLAVE_BOARD,
                                                      (SPI_WORD_SET(8) | SPI_TRANSFER_MSB | SPI_MODE_CPHA), 0);

/// --- Buffers for SPI

static uint8_t tx_buffer[128];
static uint8_t rx_buffer[128];

static struct spi_buf tx_buf = {
    .buf = tx_buffer,
    .len = sizeof(tx_buffer)};
const struct spi_buf_set tx = {
    .buffers = &tx_buf,
    .count = 1};

static struct spi_buf rx_buf = {
    .buf = rx_buffer,
    .len = sizeof(rx_buffer),
};
const struct spi_buf_set rx = {
    .buffers = &rx_buf,
    .count = 1};

// --- Async operation is based on the semaphore
K_SEM_DEFINE(semphr_master_operation_done, 0, 1);

static void master_callback(const struct device *dev, int result, void *data)
{
    k_sem_give(&semphr_master_operation_done);
}

/**
 * @brief Function checks if SPI peripheral is configured ok in dts
 *
 * @return int
 */
int spi_master_check()
{
    return spi_is_ready_dt(&spi_master);
}

/**
 * @brief Function write command to the slave
 *
 * @param cmd   Command to the slave (0: Read value <pointed by data>) (1: Write value <pointed by data>)
 * @param data  Data for command
 * @return int
 */
int spi_master_write_cmd(uint8_t cmd, uint16_t data)
{
    // Set buffer to point to proper values
    tx_buf.buf = tx_buffer;
    rx_buf.buf = rx_buffer;
    // Set command in TX buffer
    tx_buffer[0] = cmd;
    // Copy data to TX buffer
    memcpy(&tx_buffer[1], &data, sizeof(data));

    // Set length of both transfer
    tx_buf.len = 3;
    rx_buf.len = 3;

    // Start transaction
    int error = spi_transceive_cb(spi_master.bus, &spi_master.config, &tx, &rx, master_callback, NULL);
    if (error != 0)
    {
        LOG_WRN("SPI transceive error: %i\n", error);
        return error;
    }
    if (k_sem_take(&semphr_master_operation_done, K_MSEC(1)) != 0)
    {
        LOG_WRN("Timeout!\n");
    }
    else
    {
        LOG_WRN("CMD: %d Sent!\n", (int)cmd);
    }

    return 0;
}

typedef struct
{
    uint16_t value1;
    uint16_t value2;
    uint16_t value3;
} slave_values_t;

int spi_master_read_values(slave_values_t *readings)
{
    // Send read command (read value enumerated as 0x0102)
    spi_master_write_cmd(0, 0x0102);
    // Sleep to give slave time to prepare data
    k_sleep(K_MSEC(1U));    /// <--- Here we can change timeout value to 5ms and then system stops faulting

    // Set read length
    rx_buf.len = sizeof(slave_values_t);

    // No TX
    tx_buf.buf = NULL;
    tx_buf.len = sizeof(slave_values_t);

    // Start transaction
    int error = spi_transceive_cb(spi_master.bus, &spi_master.config, &tx, &rx, master_callback, NULL);
    if (error != 0)
    {
        LOG_WRN("SPI transceive error: %i\n", error);
        return error;
    }
    if (k_sem_take(&semphr_master_operation_done, K_MSEC(50)) != 0)
    {
        LOG_WRN("Timeout!\n");
    }
    else
    {
        memcpy(readings, rx_buffer, sizeof(slave_values_t));
        LOG_WRN("PM read cmplt\n");
    }

    return 0;
}

int spi_master_write_setting(uint16_t value)
{
    // Send write command (write value to slave register enumerated as 0x0304)
    spi_master_write_cmd(1, 0x0304);
    // Give time to slave to prepare transfer of selected data
    k_sleep(K_MSEC(1U)); /// <--- Here we can change timeout value to 5ms and then system stops faulting

    // Copy value to tx buffer
    memcpy(tx_buffer, &value, sizeof(value));

    // Set tx buffer
    tx_buf.len = sizeof(value);
    tx_buf.buf = tx_buffer;

    // No RX
    rx_buf.len = sizeof(uint16_t);
    rx_buf.buf = NULL;

    // Start transaction
    int error = spi_transceive_cb(spi_master.bus, &spi_master.config, &tx, &rx, master_callback, NULL);
    if (error != 0)
    {
        LOG_DBG("SPI transceive error: %i\n", error);
        return error;
    }
    if (k_sem_take(&semphr_master_operation_done, K_MSEC(50)) != 0)
    {
        LOG_DBG("Timeout!\n");
    }
    else
    {
        // Check return code

        LOG_WRN("Master done!\n");
    }

    return 0;
}

void main(void)
{
    if (!spi_master_check())
    {
        LOG_ERR("SPI master device not ready!\n");
    }

    printk("SPI master/slave test started\n");

    k_sleep(K_SECONDS(1U));

    slave_values_t readings;

    spi_master_read_values(&readings);

    printk("Received:\n\rvalue1 = %d\n\rvalue2 = %d,\n\rvalue3 = %d\n\r",
           readings.value1, readings.value2, readings.value3);
    k_sleep(K_MSEC(500U));

    spi_master_write_setting(0x1234);

    while (1)
    {
        k_sleep(K_SECONDS(2));
    }
}

[erwango]

@FRASTM, @gautierg-st Does this ring any bell ?

[abarnas-airly]

As additional information, I have checked the same code on Nucleo WB55RB. I just run it with no additional testing but it seems to work fine.

[gautierg-st]

Seeing that it seems to work fine on another board, have you checked the errata sheet for STM32L412?
There is notably the following issue "SPI master communication failure at high SYSCLK frequency within the specified voltage range". Maybe that's what you're experiencing?

[abarnas-airly]

Sorry for my misunderstanding. Indeed SYSCLK is set higher than the limits mentioned by errata but as far as the BR field in the SPI1_CR1 register is set to 0b111 it does not meet the second condition.
"the BR[2:0] bitfield of the SPIx_CR1 register is at 001 (fPCLK divided by four)"
Also, I think that such communication corruption shouldn't lead to a hard fault.

Appreciate your help :)

[erwango]

@abarnas-airly Are you able to provide the callstack of the bus fault ?

[abarnas-airly]

arch_system_halt@0x08011a04 (./zephyr/kernel/fatal.c:32)
k_sys_fatal_error_handler@0x08008ce8 (./zephyr/kernel/fatal.c:46)
z_fatal_error@0x08008ea0 (./zephyr/kernel/fatal.c:131)
z_arm_fatal_error@0x0800e40c (./zephyr/arch/arm/core/aarch32/fatal.c:63)
z_arm_fault@0x0800509a (./zephyr/arch/arm/core/aarch32/cortex_m/fault.c:1132)
z_arm_usage_fault@0x080050dc (./zephyr/arch/arm/core/aarch32/cortex_m/fault_s.S:102)
<signal handler called>@0xfffffffd (Unknown Source:0)
transceive@0x080117da (./zephyr/drivers/spi/spi_ll_stm32.c:662)
spi_stm32_transceive_async@0x08011864 (./zephyr/drivers/spi/spi_ll_stm32.c:866)
spi_transceive_cb@0x0800c03c (./zephyr/include/zephyr/drivers/spi.h:892)
spi_master_read_values@0x08000af4 (./application/spi-master-slave-tryout/src/main.c:118)
main@0x08000dd6 (./application/spi-master-slave-tryout/src/main.c:189)

Copied from vs code call stack tab (edited paths from absolute to relative to workspace for better readability)

[erwango]

Great, can you provide the SHA1 you're using ? This would help identifying the suspect lines

[abarnas-airly]

Output from west update:

=== updating zephyr (zephyr):
--- zephyr: fetching, need revision main
From https://github.com/zephyrproject-rtos/zephyr
 * branch                  main       -> FETCH_HEAD
HEAD is now at 0773cc88c8 release: document major changes
=== updating cmsis (modules/hal/cmsis):
HEAD is now at 74981bf Update DSP library for additional platforms
=== updating hal_stm32 (modules/hal/stm32):
HEAD is now at c865374f dts: pinctrl: add autogenerated BKIN entries

[tbursztyka]

Just a tiny comment, you shouldn't have to give any tx buffers in spi_master_read_values() and any rx buffers in spi_master_write_values(). Just pass NULL in spi_transceive_cb relevantly.

[abarnas-airly]

Any new thoughts? Maybe it should be transformed into an issue? I could not find the reason for the fault. I suspect that stack was somehow corrupted (that would explain why errors differ depending on what data corrupted the stack), but I cannot find the source of the corruption.
@erwango @gautierg-st

[erwango]

Yes, please open an issue.