Backend Logging in SD Card and LoRa incompatibility

Hi, I have been having some trouble lately using an SD card together with a LoRa radio in Zephyr in a custom board based on the RAK4630, toolchain v3.2.0 from Nordic and SDK also v3.2.0 (Zephyr 4.2.99). I am using separate SPI instances for LoRa and the SD card (SPI1 and SPI2). However, when I initialize the SD card and enable backend logging to it, neither LoRa works properly nor are the logs correctly stored on the SD card (I also tried a few methods to prevent this such as disabling momentarely the backend, log flush and so one).

I have tried multiple approaches to make it work, but my main question is whether there is any incompatibility between them or if this is simply a firmware issue.

Here is my code:

main.c:

#include <zephyr/device.h>
#include <zephyr/kernel.h>
#include <zephyr/lorawan/lorawan.h>
#include <zephyr/logging/log.h>
#include <zephyr/sys/reboot.h>
#include <string.h>
#include "settings.h"
#include <zephyr/storage/disk_access.h>
#include <zephyr/fs/fs.h>
#include <ff.h>

LOG_MODULE_REGISTER(MAIN_, CONFIG_LOG_DEFAULT_LEVEL);

#define LORA_MSG_MAX_SIZE   32
#define LORA_MSG_QUEUE_LEN  5

K_MSGQ_DEFINE(lora_msgq, LORA_MSG_MAX_SIZE, LORA_MSG_QUEUE_LEN, 4);
K_SEM_DEFINE(lora_start_sem, 0, 1);

static void dl_callback(uint8_t port, uint8_t flags, int16_t rssi, int8_t snr, uint8_t len, const uint8_t *hex_data) {
    LOG_INF("Port %d, Pending %d, RSSI %ddB, SNR %ddBm, Time %d", port, flags & LORAWAN_DATA_PENDING, rssi, snr, !!(flags & LORAWAN_TIME_UPDATED));

    if (hex_data && len > 0) {
        LOG_HEXDUMP_INF(hex_data, len, "Payload:");
    }
}

static void lorawan_datarate_changed(enum lorawan_datarate dr) {
    uint8_t unused, max_size;

    lorawan_get_payload_sizes(&unused, &max_size);
    LOG_INF("New Datarate: DR_%d | Max Payload: %d", dr, max_size);
}

void lora_thread(void) {
    const struct device *lora_dev;
    struct lorawan_join_config join_cfg;
    struct lorawan_downlink_cb downlink_cb;

    uint8_t dev_eui[]  = LORAWAN_DEV_EUI;
    uint8_t join_eui[] = LORAWAN_JOIN_EUI;
    uint8_t app_key[]  = LORAWAN_APP_KEY;

    uint8_t tx_buf[LORA_MSG_MAX_SIZE];
    int ret;

    k_sem_take(&lora_start_sem, K_FOREVER);

    LOG_INF("LoRaWAN thread starting");

    lora_dev = DEVICE_DT_GET(DT_ALIAS(lora0));
    if (!device_is_ready(lora_dev)) {
        LOG_ERR("LoRa device not ready");
        return;
    }

    ret = lorawan_start();
    if (ret < 0) {
        LOG_ERR("lorawan_start failed: %d", ret);
        return;
    }

    downlink_cb.port = LW_RECV_PORT_ANY;
    downlink_cb.cb   = dl_callback;

    lorawan_register_downlink_callback(&downlink_cb);
    lorawan_register_dr_changed_callback(lorawan_datarate_changed);

    join_cfg.mode = LORAWAN_ACT_OTAA;
    join_cfg.dev_eui = dev_eui;
    join_cfg.otaa.join_eui = join_eui;
    join_cfg.otaa.app_key  = app_key;
    join_cfg.otaa.nwk_key  = app_key;

    uint8_t tries = 0;
    while (tries++ < 5) {
        LOG_INF("Joining network via OTAA");

        if (!lorawan_join(&join_cfg)) {
            LOG_INF("Successfully joined network");
            goto JOINED;
        }

        LOG_ERR("Failed to join. Retrying in 10 seconds...");
        k_sleep(K_SECONDS(10));
    }
    LOG_ERR("Failed to join network after %d attempts. Reseting board...", 5);
    k_sleep(K_SECONDS(2));
    sys_reboot(SYS_REBOOT_COLD);
    return;

JOINED:

    while (true) {
        k_msgq_get(&lora_msgq, tx_buf, K_FOREVER);

        ret = lorawan_send(2, tx_buf, strlen((char *)tx_buf), LORAWAN_MSG_CONFIRMED);

        if (ret < 0) {
            LOG_ERR("lorawan_send failed: %d", ret);
        }
        else {
            LOG_INF("Data sent");
        }
    }
}

K_THREAD_DEFINE(lora_tid, 8192, lora_thread, NULL, NULL, NULL, 1, 0, 0);
FATFS fatfs;
#define MOUNT_POINT "/SD:"

static struct fs_mount_t fatfs_mnt = {
    .type = FS_FATFS,
    .mnt_point = MOUNT_POINT,
    .fs_data = &fatfs,
};

int main(void) {
    static const char *disk_pdrv = "SD";
    uint64_t memory_size_mb;
    uint32_t block_count;
    uint32_t block_size;
    char msg[] = "helloworld";

    k_sleep(K_SECONDS(5));
    LOG_INF("Main started");
   
    if (disk_access_init(disk_pdrv) != 0) {
        LOG_ERR("Storage init Error!");
        return -1;
    }

    if (disk_access_ioctl(disk_pdrv, DISK_IOCTL_GET_SECTOR_COUNT, &block_count)) {
        LOG_ERR("Unable to get sector count");
        return -1;
    }

    if (disk_access_ioctl(disk_pdrv, DISK_IOCTL_GET_SECTOR_SIZE, &block_size)) {
        LOG_ERR("Unable to get sector size");
        return -1;
    }
    memory_size_mb = (uint64_t)block_count * block_size;
    LOG_INF("Memory Size %uMB", (uint32_t)(memory_size_mb >> 20));

    if (fs_mount(&fatfs_mnt) == FR_OK) {
        LOG_INF("SD Card mounted");
    } else {
        LOG_ERR("Error mounting SD Card");
    }

    k_sem_give(&lora_start_sem);

    while (true) {
        if (k_msgq_put(&lora_msgq, msg, K_NO_WAIT) != 0) {
            LOG_WRN("MSGQ full, dropping message");
        }
        else {
            LOG_INF("Message queued");
        }

        k_sleep(K_SECONDS(20));
    }
}

proj.conf

CONFIG_LOG=y
CONFIG_LORA=y
CONFIG_LORAWAN=y
CONFIG_LORAMAC_REGION_EU868=y
CONFIG_MAIN_STACK_SIZE=4096
CONFIG_SYSTEM_WORKQUEUE_STACK_SIZE=4096
CONFIG_REBOOT=y

# NVS
CONFIG_NVS=y
CONFIG_FLASH=y
CONFIG_FLASH_MAP=y
CONFIG_FLASH_PAGE_LAYOUT=y

# SD Card

CONFIG_DISK_ACCESS=y                        
CONFIG_FILE_SYSTEM=y                        
CONFIG_FAT_FILESYSTEM_ELM=y                
CONFIG_LOG_BACKEND_FS=y                    
CONFIG_LOG_BACKEND_FS_OUTPUT_TEXT=y        
CONFIG_LOG_BACKEND_FS_DIR="/SD:"            
CONFIG_LOG_BACKEND_FS_FILE_PREFIX="log"    
CONFIG_LOG_BACKEND_FS_FILES_LIMIT=100
CONFIG_LOG_BACKEND_FS_FILE_SIZE=131072    
CONFIG_LOG_BACKEND_FS_OVERWRITE=y

dts for custom board:

/dts-v1/;
#include <nordic/nrf52840_qiaa.dtsi>
#include <nordic/nrf52840_partition.dtsi>
#include "esav01_nrf52840-pinctrl.dtsi"
#include <zephyr/dt-bindings/lora/sx126x.h>

/ {
    model = "Board 1";
    compatible = "nordic,esav01_nrf52840";

    chosen {
        zephyr,console = &uart1;
        zephyr,shell-uart = &uart1;
        zephyr,uart-mcumgr = &uart1;
        zephyr,bt-mon-uart = &uart1;
        zephyr,bt-c2h-uart = &uart1;
    };

    aliases {
        lora0 = &lora;
    };
};

&reg0 {
    status = "okay";
};

&reg1 {
    regulator-initial-mode = <NRF5X_REG_MODE_DCDC>;
};

&uicr {
    gpio-as-nreset;
    nfct-pins-as-gpios;
};

&gpiote {
    status = "okay";
};

&gpio0 {
    status = "okay";
};

&gpio1 {
    status = "okay";
};

&uart1 {
    compatible = "nordic,nrf-uarte";
    status = "okay";
    current-speed = <115200>;
    pinctrl-0 = <&uart1_default>;
    pinctrl-1 = <&uart1_sleep>;
    pinctrl-names = "default", "sleep";
};

&i2c1 {
    status = "disabled";
};

&spi0 {
    status = "disabled";
};

&spi1 {
    compatible = "nordic,nrf-spim";
    status = "okay";
    cs-gpios = <&gpio1 10 GPIO_ACTIVE_LOW>;

    pinctrl-0 = <&spi1_default>;
    pinctrl-1 = <&spi1_sleep>;
    pinctrl-names = "default", "sleep";

    lora: lora@0 {
        compatible = "semtech,sx1262";
        reg = <0>;
        reset-gpios = <&gpio1 6 GPIO_ACTIVE_LOW>;
        busy-gpios = <&gpio1 14 GPIO_ACTIVE_HIGH>;
        dio1-gpios = <&gpio1 15 GPIO_ACTIVE_HIGH>;
        dio2-tx-enable;
        dio3-tcxo-voltage = <SX126X_DIO3_TCXO_3V3>;
        tcxo-power-startup-delay-ms = <5>;
        spi-max-frequency = <1000000>;
    };
};

&spi2 {
    compatible = "nordic,nrf-spim";
    status = "okay";
    cs-gpios = <&gpio0 26 GPIO_ACTIVE_LOW>;
   
    pinctrl-0 = <&spi2_default>;
    pinctrl-1 = <&spi2_sleep>;
    pinctrl-names = "default", "sleep";

    sdhc0: sdhc@0 {
        compatible = "zephyr,sdhc-spi-slot";
        reg = <0>;
        status = "okay";
        mmc {
            compatible = "zephyr,sdmmc-disk";
            disk-name = "SD";
            status = "okay";
        };
        spi-max-frequency = <25000000>;
    };
};

&qspi {
    status = "disabled";
}

Thank you for your help.

@sercan
Can you have a look?

Hello @Yopoitio

Welcome to forum. Can you please try to add this to your code? Let’s see how it will behave.

static int sd_card_early_init(void)
{
    static const char *disk_pdrv = "SD";
    int ret;

    ret = disk_access_init(disk_pdrv);
    if (ret != 0) {
        return ret;
    }

    ret = fs_mount(&fatfs_mnt);
    if (ret != 0) {
        return ret;
    }

    return 0;
}

SYS_INIT(sd_card_early_init, APPLICATION, 0);

Hi,

Thank you for your response, I think you meant something like this right?

main.c

#include <zephyr/device.h>
#include <zephyr/kernel.h>
#include <zephyr/lorawan/lorawan.h>
#include <zephyr/logging/log.h>
#include <zephyr/sys/reboot.h>
#include <string.h>
#include "settings.h"
#include <zephyr/storage/disk_access.h>
#include <zephyr/fs/fs.h>
#include <ff.h>

LOG_MODULE_REGISTER(MAIN_, CONFIG_LOG_DEFAULT_LEVEL);

#define LORA_MSG_MAX_SIZE   32
#define LORA_MSG_QUEUE_LEN  5

K_MSGQ_DEFINE(lora_msgq, LORA_MSG_MAX_SIZE, LORA_MSG_QUEUE_LEN, 4);
K_SEM_DEFINE(lora_start_sem, 0, 1);

static void dl_callback(uint8_t port, uint8_t flags, int16_t rssi, int8_t snr, uint8_t len, const uint8_t *hex_data) {
    LOG_INF("Port %d, Pending %d, RSSI %ddB, SNR %ddBm, Time %d", port, flags & LORAWAN_DATA_PENDING, rssi, snr, !!(flags & LORAWAN_TIME_UPDATED));

    if (hex_data && len > 0) {
        LOG_HEXDUMP_INF(hex_data, len, "Payload:");
    }
}

static void lorawan_datarate_changed(enum lorawan_datarate dr) {
    uint8_t unused, max_size;

    lorawan_get_payload_sizes(&unused, &max_size);
    LOG_INF("New Datarate: DR_%d | Max Payload: %d", dr, max_size);
}

void lora_thread(void) {
    const struct device *lora_dev;
    struct lorawan_join_config join_cfg;
    struct lorawan_downlink_cb downlink_cb;

    uint8_t dev_eui[]  = LORAWAN_DEV_EUI;
    uint8_t join_eui[] = LORAWAN_JOIN_EUI;
    uint8_t app_key[]  = LORAWAN_APP_KEY;

    uint8_t tx_buf[LORA_MSG_MAX_SIZE];
    int ret;

    k_sem_take(&lora_start_sem, K_FOREVER);

    LOG_INF("LoRaWAN thread starting");

    lora_dev = DEVICE_DT_GET(DT_ALIAS(lora0));
    if (!device_is_ready(lora_dev)) {
        LOG_ERR("LoRa device not ready");
        return;
    }

    ret = lorawan_start();
    if (ret < 0) {
        LOG_ERR("lorawan_start failed: %d", ret);
        return;
    }

    downlink_cb.port = LW_RECV_PORT_ANY;
    downlink_cb.cb   = dl_callback;

    lorawan_register_downlink_callback(&downlink_cb);
    lorawan_register_dr_changed_callback(lorawan_datarate_changed);

    join_cfg.mode = LORAWAN_ACT_OTAA;
    join_cfg.dev_eui = dev_eui;
    join_cfg.otaa.join_eui = join_eui;
    join_cfg.otaa.app_key  = app_key;
    join_cfg.otaa.nwk_key  = app_key;

    uint8_t tries = 0;
    while (tries++ < 5) {
        LOG_INF("Joining network via OTAA");

        if (!lorawan_join(&join_cfg)) {
            LOG_INF("Successfully joined network");
            goto JOINED;
        }

        LOG_ERR("Failed to join. Retrying in 10 seconds...");
        k_sleep(K_SECONDS(10));
    }
    LOG_ERR("Failed to join network after %d attempts. Reseting board...", 5);
    k_sleep(K_SECONDS(2));
    sys_reboot(SYS_REBOOT_COLD);
    return;

JOINED:

    while (true) {
        k_msgq_get(&lora_msgq, tx_buf, K_FOREVER);

        ret = lorawan_send(2, tx_buf, strlen((char *)tx_buf), LORAWAN_MSG_CONFIRMED);

        if (ret < 0) {
            LOG_ERR("lorawan_send failed: %d", ret);
        }
        else {
            LOG_INF("Data sent");
        }
    }
}

K_THREAD_DEFINE(lora_tid, 8192, lora_thread, NULL, NULL, NULL, 1, 0, 0);
FATFS fatfs;
#define MOUNT_POINT "/SD:"

static struct fs_mount_t fatfs_mnt = {
    .type = FS_FATFS,
    .mnt_point = MOUNT_POINT,
    .fs_data = &fatfs,
};

static int sd_card_early_init(void)
{
    static const char *disk_pdrv = "SD";
    int ret;

    ret = disk_access_init(disk_pdrv);
    if (ret != 0) {
        return ret;
    }

    ret = fs_mount(&fatfs_mnt);
    if (ret != 0) {
        return ret;
    }

    return 0;
}

SYS_INIT(sd_card_early_init, APPLICATION, 0);

int main(void) {
    char msg[] = "helloworld";
    static const char *disk_pdrv = "SD";
    uint64_t memory_size_mb;
    uint32_t block_count;
    uint32_t block_size;
    

    k_sleep(K_SECONDS(5));
    LOG_INF("Main started");
   
    /*if (disk_access_init(disk_pdrv) != 0) {
        LOG_ERR("Storage init Error!");
        return -1;
    }

    if (disk_access_ioctl(disk_pdrv, DISK_IOCTL_GET_SECTOR_COUNT, &block_count)) {
        LOG_ERR("Unable to get sector count");
        return -1;
    }

    if (disk_access_ioctl(disk_pdrv, DISK_IOCTL_GET_SECTOR_SIZE, &block_size)) {
        LOG_ERR("Unable to get sector size");
        return -1;
    }
    memory_size_mb = (uint64_t)block_count * block_size;
    LOG_INF("Memory Size %uMB", (uint32_t)(memory_size_mb >> 20));

    if (fs_mount(&fatfs_mnt) == FR_OK) {
        LOG_INF("SD Card mounted");
    } else {
        LOG_ERR("Error mounting SD Card");
    }*/

    k_sem_give(&lora_start_sem);

    while (true) {
        if (k_msgq_put(&lora_msgq, msg, K_NO_WAIT) != 0) {
            LOG_WRN("MSGQ full, dropping message");
        }
        else {
            LOG_INF("Message queued");
        }

        k_sleep(K_SECONDS(20));
    }
}

I flashed this code and had the following result:

*** Booting nRF Connect SDK v3.2.0-5dcc6bd39b0f ***
*** Using Zephyr OS v4.2.99-a57ad913cf4e ***
[00:00:00.494,323] sd: Maximum SD clock is under 25MHz, using clock of 24000000Hz
[00:00:05.498,626] MAIN_: Main started
[00:00:05.498,657] MAIN_: Message queued
[00:00:05.498,687] MAIN_: LoRaWAN thread starting
[00:00:05.558,776] MAIN_: Joining network via OTAA
[00:00:13.325,195] lorawan: MlmeConfirm failed : Rx 2 timeout
[00:00:13.326,477] MAIN_: Failed to join. Retrying in 10 seconds…
[00:00:23.326,568] MAIN_: Joining network via OTAA
[00:00:25.498,748] MAIN_: Message queued
[00:00:31.085,327] lorawan: MlmeConfirm failed : Rx 2 timeout
[00:00:31.086,608] MAIN_: Failed to join. Retrying in 10 seconds…
[00:00:41.086,730] MAIN_: Joining network via OTAA
[00:00:45.498,840] MAIN_: Message queued
[00:00:48.845,367] lorawan: MlmeConfirm failed : Rx 2 timeout
[00:00:48.846,649] MAIN_: Failed to join. Retrying in 10 seconds…
[00:00:58.846,771] MAIN_: Joining network via OTAA
[00:01:05.498,931] MAIN_: Message queued
[00:01:06.604,095] lorawan: MlmeConfirm failed : Rx 2 timeout
[00:01:06.605,377] MAIN_: Failed to join. Retrying in 10 seconds…
[00:01:16.605,468] MAIN_: Joining network via OTAA
[00:01:24.364,074] lorawan: MlmeConfirm failed : Rx 2 timeout
[00:01:24.365,356] MAIN_: Failed to join. Retrying in 10 seconds…

Exactly, this version is what I wanna try. Are you able to save logs to sd card now? RX 2 timeouts are related to LoRaWAN gateway. Your gateway is not returning a response to join requests.

Thanks,
Sercan.

Hi, unfortunately it is not as it seems. If I remove the SD card (or in this case comment out the SD card initialization), it connects to the gateway without any problem. However, if I initialize the SD card, the join request does not reach the gateway. If it does, I assume it does not leave the radio, since the conditions are the same (and the DR when transmitting normally is 5) and nothing appears on Chirpstack. It seems that the SPI interfaces are interfering with each other.
Also, this was the only thing the SD Card saved:

*** Booting nRF Connect SDK v3.2.0-5dcc6bd39b0f ***
*** Using Zephyr OS v4.2.99-a57ad913cf4e ***
[00:00:00.353,790] <inf> sd: Maximum SD clock is under 25MHz, using clock of 24000000Hz

Thanks

Got it. Can you please try to add these flags to prj.conf file?

CONFIG_LOG_PROCESS_THREAD=y
CONFIG_LOG_BACKEND_UART=n
CONFIG_LOG_MODE_DEFERRED=y
CONFIG_LOG_BUFFER_SIZE=20000
CONFIG_LOG_PROCESS_THREAD_SLEEP_MS=100

With these flags, we will process logs inside a thread and I also closed uart logging which consumes CPU time. Thread sleep time is used to slow down logging process. Let’s see how it will behave.

Sorry for the late response, but I had some problems with my LoRa network and couldn’t test it until today. I tested several times and the issue persists. Only these logs were saved on the SD card:

*** Booting nRF Connect SDK v3.2.0-5dcc6bd39b0f ***
*** Using Zephyr OS v4.2.99-a57ad913cf4e ***
[00:00:00.350,860] <inf> sd: Maximum SD clock is under 25MHz, using clock of 8000000Hz

@Yopoitio Please take a look hello_world project on this repo: GitHub - srcnert/rak-zephyr-app at case-sd-card · GitHub