Mpsl init hard fault

[thiago_hd]

Hello guys,

I am having problems on addressing an issue with my firmware. Maybe someone can assist me to find out the root cause for this, because I don't understand too much of the error log.

The firmware runs smooth for some time (it varies from time to time, but in most cases it runs for several hours before crash).

See below that the firmware stopped logging to RTT (and it stopped working too) at `[15:12:44.837,554]`. It just freezed.

The output from RTT log is only printed out in the serial monitor if I open GDB Server and close it (I don't understand why this happens too).

I am testing the application by simulating beacons in the NRF Connect app in android, simulating several advertising beacons so that this device can keep scanning.

I am using Bluetooth with whitelisting for scanning devices around.

See the log output below:

[15:12:44.837,554] <inf> lora_receive_task: lora tx config
[16:25:42.304,595] <err> mpsl_init: MPSL ASSERT: 108, 530
[16:25:42.304,626] <err> os: ***** HARD FAULT *****
[16:25:42.304,626] <err> os: Fault escalation (see below)
[16:25:42.304,626] <err> os: ARCH_EXCEPT with reason 3

[16:25:42.304,626] <err> os: r0/a1: 0x00000003 r1/a2: 0x00000010 r2/a3: 0x0000000f
[16:25:42.304,656] <err> os: r3/a4: 0x20002760 r12/ip: 0x2000001f r14/lr: 0x00022e3f
[16:25:42.304,656] <err> os: xpsr: 0x6101001b
[16:25:42.304,656] <err> os: Faulting instruction address (r15/pc): 0x00036f52
[16:25:42.304,656] <err> os: >>> ZEPHYR FATAL ERROR 3: Kernel oops on CPU 0
[16:25:42.304,687] <err> os: Fault during interrupt handling

[16:25:42.304,779] <err> os: Current thread: 0x200024d0 (ble_task_id)
[16:25:43.033,081] <err> os: Halting system

See below projconf:

# choose RTT console
CONFIG_UART_CONSOLE=n
CONFIG_USE_SEGGER_RTT=y
CONFIG_RTT_CONSOLE=y

CONFIG_LOG=y
CONFIG_PRINTK=n
CONFIG_LOG_PRINTK=n
CONFIG_LOG_DETECT_MISSED_STRDUP=y
CONFIG_LOG_PRINTK_MAX_STRING_LENGTH=1024
CONFIG_LOG_STRDUP_BUF_COUNT=20
CONFIG_LOG_STRDUP_MAX_STRING=1024
CONFIG_NEWLIB_LIBC=y
CONFIG_CBPRINTF_FULL_INTEGRAL=y
CONFIG_CBPRINTF_FP_SUPPORT=y
CONFIG_NEWLIB_LIBC_FLOAT_SCANF=y
CONFIG_NEWLIB_LIBC_FLOAT_PRINTF=y
CONFIG_NEWLIB_LIBC_NANO=n

CONFIG_DEBUG=y
CONFIG_DEBUG_OPTIMIZATIONS=y
CONFIG_DEBUG_THREAD_INFO=y

# -- Bluetooth LE
CONFIG_BT=y
CONFIG_BT_BROADCASTER=y
CONFIG_BT_DEBUG_LOG=n
CONFIG_BT_CENTRAL=y

# para usar um (1) filtro de nome
CONFIG_BT_SCAN=y
CONFIG_BT_SCAN_FILTER_ENABLE=y
CONFIG_BT_SCAN_NAME_CNT=1

# para usar Le Coded Phy (longa distancia)
CONFIG_BT_CTLR_PHY_CODED=y
CONFIG_BT_EXT_ADV=y
CONFIG_BT_USER_PHY_UPDATE=y

# para poder utilizar endereço estatico
CONFIG_BT_SMP=y
CONFIG_BT_PRIVACY=n

# para usar advertising estendido
CONFIG_BT_EXT_ADV=y
CONFIG_BT_GATT_CLIENT=y
CONFIG_BT_LL_SW_SPLIT=n

# -- Lora
CONFIG_SPI=y
CONFIG_GPIO=y
CONFIG_LORA=y
CONFIG_LORA_SX12XX=y

# -- Blinky
CONFIG_HEAP_MEM_POOL_SIZE=10240
CONFIG_ASSERT=y

# -- UART
CONFIG_UART_INTERRUPT_DRIVEN=y

Support Information:

{
  "platform": {
    "os": "darwin",
    "osVersion": "Darwin Kernel Version 19.6.0: Thu Jan 13 01:26:33 PST 2022; root:xnu-6153.141.51~3/RELEASE_X86_64",
    "osKernel": "19.6.0",
    "vscode": "1.66.1",
    "electron": "17.2.0",
    "node": "v16.13.0"
  },
  "system": {
    "date": "2022-04-09T19:16:53.373Z",
    "vscodeRoot": "/Applications/Visual Studio Code.app/Contents/Resources/app",
    "nrfConnectForDesktopInstalled": true,
    "vscodeUptime": "21:12:36",
    "osUptime": "21:14:20",
    "cpu": {
      "model": "Intel(R) Core(TM) i5-3210M CPU @ 2.50GHz",
      "speed": "2500 MHz",
      "count": 2
    },
    "memory": {
      "total": "6.00 GB",
      "free": "0.06 GB"
    }
  },
  "workspace": {
    "name": "cracha",
    "workspaceFile": null,
    "folders": [
      "/Users/thiago/nRF52_apps/cracha"
    ]
  },
  "extensions": {
    "internal": {
      "nordic-semiconductor.nrf-connect": {
        "version": "2022.3.104",
        "path": "/Users/thiago/.vscode/extensions/nordic-semiconductor.nrf-connect-2022.3.104",
        "isActive": true
      },
      "nordic-semiconductor.nrf-terminal": {
        "version": "2022.3.31",
        "path": "/Users/thiago/.vscode/extensions/nordic-semiconductor.nrf-terminal-2022.3.31",
        "isActive": true
      },
      "nordic-semiconductor.devicetree": null,
      "nordic-semiconductor.kconfig": null
    },
    "external": {
      "marus25.cortex-debug": "1.4.4",
      "ms-vscode.cpptools": "1.9.7",
      "ms-vscode.js-debug": "1.66.1",
      "ms-vscode.js-debug-companion": "1.0.17",
      "ms-vscode.references-view": "0.0.89",
      "ms-vscode.vscode-js-profile-table": "1.0.0",
      "2gua.rainbow-brackets": "0.0.6",
      "bbenoist.Doxygen": "1.0.0",
      "betwo.vscode-doxygen-runner": "1.7.3",
      "cameronbieganek.julia-color-themes": "0.1.1",
      "ceciljacob.code-plus-theme": "1.0.0",
      "cl.stm8-debug": "1.4.1",
      "cschlosser.doxdocgen": "1.4.0",
      "cweijan.vscode-mysql-client2": "5.0.9",
      "dan-c-underwood.arm": "1.7.4",
      "david-j-lee.github-dark-color-theme": "0.3.2",
      "DotJoshJohnson.xml": "2.5.1",
      "eamodio.gitlens": "12.0.5",
      "espressif.esp-idf-extension": "1.4.0",
      "formulahendry.vscode-mysql": "0.4.1",
      "ghgofort.neon-vommit": "1.2.2",
      "go2sh.cmake-integration-vscode": "0.7.1",
      "guobing.material-color": "1.3.2",
      "hancel.serialport-helper": "0.0.15",
      "httpsterio.henna": "0.11.0",
      "IBM.output-colorizer": "0.1.2",
      "jeff-hykin.better-cpp-syntax": "1.15.13",
      "johnpapa.winteriscoming": "1.4.4",
      "KevinRose.vsc-python-indent": "1.15.0",
      "kosz78.nim": "0.6.6",
      "kuscamara.electron": "0.2.6",
      "lucabockmann.midnight-color": "1.4.0",
      "magson.material-dark-color-theme": "0.0.3",
      "Marcelino-Jorge-Romero.matrix-theme": "0.0.1",
      "MaxfieldWalker.vscode-color-theme-spirited-away": "1.3.2",
      "mechatroner.rainbow-csv": "2.2.0",
      "ms-azuretools.vscode-docker": "1.21.0",
      "ms-python.python": "2022.4.1",
      "ms-python.vscode-pylance": "2022.4.0",
      "ms-toolsai.jupyter": "2022.3.1000901801",
      "ms-toolsai.jupyter-keymap": "1.0.0",
      "ms-toolsai.jupyter-renderers": "1.0.6",
      "ms-vscode-remote.remote-containers": "0.231.5",
      "ms-vscode-remote.remote-ssh": "0.78.0",
      "ms-vscode-remote.remote-ssh-edit": "0.80.0",
      "ms-vscode-remote.remote-wsl": "0.66.0",
      "ms-vscode.cpptools-extension-pack": "1.1.0",
      "ms-vscode.cpptools-themes": "1.0.0",
      "mtxr.sqltools": "0.23.0",
      "mtxr.sqltools-driver-mysql": "0.2.0",
      "octref.vetur": "0.35.0",
      "oguhpereira.spotify-color-theme": "1.3.0",
      "PauloSouza.matrix-revolution-color-theme": "0.0.1",
      "PKief.material-icon-theme": "4.15.0",
      "redhat.vscode-yaml": "1.6.0",
      "Roghib.nani": "1.1.2",
      "tal7aouy.theme": "2.2.0",
      "trond-snekvik.gnu-mapfiles": "1.1.0",
      "twxs.cmake": "0.0.17",
      "UstymUkhman.matrix-theme": "0.1.2",
      "yile-ou.paddy-color-theme": "1.9.3",
      "Youssef.viow": "0.3.3",
      "zary-dev.Zary": "1.3.0"
    }
  },
  "tools": {
    "/Applications/SEGGER/JLink/JLinkExe": "7.60c",
    "/usr/local/bin/nrfjprog": "10.15.4",
    "nrfutil": "Not found",
    "/opt/nordic/ncs/v1.9.1/toolchain/bin/cmake": "3.21.1",
    "/opt/nordic/ncs/v1.9.1/toolchain/bin/west": "0.12.0",
    "/opt/nordic/ncs/v1.9.1/toolchain/bin/python3": "3.9.6",
    "/opt/nordic/ncs/v1.9.1/toolchain/bin/ninja": "1.10.2",
    "/opt/nordic/ncs/v1.9.1/toolchain/bin/gperf": "3.1",
    "/opt/nordic/ncs/v1.9.1/toolchain/bin/dtc": "1.6.1",
    "/opt/nordic/ncs/v1.9.1/toolchain/bin/arm-none-eabi-gcc": "9-2019-q4-major",
    "/opt/nordic/ncs/v1.9.1/toolchain/bin/gn": "1977",
    "/opt/nordic/ncs/v1.9.1/toolchain/bin/git": "2.32.0"
  },
  "sdks": [
    {
      "version": "1.9.1",
      "path": "/opt/nordic/ncs/v1.9.1"
    }
  ],
  "toolchains": [
    {
      "version": "1.9.1",
      "path": "/opt/nordic/ncs/v1.9.1/toolchain"
    }
  ],
  "connectedDevices": [
    {
      "serialNumber": "683771177"
    }
  ],
  "deviceProviders": [
    "nrfjprog"
  ],
  "config": {
    "nordic-semiconductor.nrf-connect": {
      "topdir": "${nrf-connect.sdk:1.9.1}",
      "toolchain": {
        "path": "${nrf-connect.toolchain:1.9.1}"
      },
      "ozonePath": "",
      "applications": [
        "${workspaceFolder}"
      ],
      "kconfig": {
        "interface": "menuconfig"
      },
      "welcome": {
        "showOnStartup": true
      },
      "west": {
        "env": {
          "$base": "terminal"
        }
      },
      "boardRoots": [],
      "enableTelemetry": true
    },
    "nordic-semiconductor.nrf-terminal": {
      "terminalMode": "character"
    },
    "nordic-semiconductor.devicetree": {
      "modules": [
        "${zephyrBase}",
        "${zephyrBase}/../nrf",
        "."
      ],
      "zephyr": "",
      "ctxFile": "",
      "defaultBoard": ""
    },
    "nordic-semiconductor.kconfig": {
      "root": "",
      "env": {},
      "cfiles": true,
      "disable": false,
      "zephyr": {
        "base": ""
      },
      "python": "",
      "liveValue": true
    },
    "marus25.cortex-debug": {
      "armToolchainPath": null,
      "armToolchainPrefix": "arm-none-eabi",
      "gdbPath": null,
      "objdumpPath": null,
      "JLinkGDBServerPath": null,
      "openocdPath": null,
      "pyocdPath": null,
      "PEGDBServerPath": null,
      "stutilPath": null,
      "stlinkPath": null,
      "stm32cubeprogrammer": null,
      "enableTelemetry": true,
      "flattenAnonymous": false,
      "registerUseNaturalFormat": true,
      "variableUseNaturalFormat": true,
      "dbgServerLogfile": null,
      "showRTOS": false,
      "showDevDebugOutput": "none"
    }
  },
  "environment": {
    "westExe": "/opt/nordic/ncs/v1.9.1/toolchain/bin/west",
    "westEnv": {
      "ELECTRON_RUN_AS_NODE": "1",
      "GIT_EXEC_PATH": "/opt/nordic/ncs/v1.9.1/toolchain/Cellar/git/2.32.0_1/libexec/git-core",
      "HOME": "/Users/thiago",
      "PATH": "/opt/nordic/ncs/v1.9.1/toolchain/bin:/usr/bin:/bin:/usr/sbin:/sbin:/usr/local/bin",
      "ZEPHYR_BASE": "/opt/nordic/ncs/v1.9.1/zephyr",
      "GNUARMEMB_TOOLCHAIN_PATH": "/opt/nordic/ncs/v1.9.1/toolchain",
      "ZEPHYR_TOOLCHAIN_VARIANT": "gnuarmemb",
      "USER": "thiago"
    },
    "toolchainPath": "/opt/nordic/ncs/v1.9.1/toolchain",
    "toolchainBinPath": "/opt/nordic/ncs/v1.9.1/toolchain/bin",
    "toolchainVersion": "1.9.1"
  },
  "terminal": {
    "shell": null,
    "defaultProfile": null
  }
}

[thiago_hd]

I see that the task which was running was the ble task I have created. So describing a little bit of this task:

In the bluetooth task, I am capturing the BLE advertisers' information inside the scanning handler, when the filter matches the device's name, and adding the captured data  to a FIFO using k_fifo_put.

Inside the bluetooth task loop I get the data added to the FIFO by calling k_fifo_get.

[dejans]

Hi,

Could you try closing gdb server and gdb before starting logging via RTT?

How do you print the output of RTT log?

What happens if you use UART instead of RTT for logging? Do you experience similar problem?

Best regards,
Dejan

[thiago_hd]

Hello dejans,

I am using RTT through VSCode by clicking the button "Connect to RTT in nRF Terminal" in the nRF Connect SDK extension. I was using JLinkRTTViewer as well, the problem happened similarly. The problem happens even if I don't have the logger on, and no monitor hardware connected to the board.

I don't use directly GDB server for anything. After some time struggling with the freezed board I just noted that, after the firmware freezed, if I opened GDB Server and then closed it, the log with the hard fault appeared... After the firmware freezes, the RTT logs stopped showing, the only way the hard fault log appears is if I do that trick using GDB Server. Everything was freezed, the board didn't even rebooted through watchdog. I believe maybe the board didn't rebooted because I don't have edited anything in the HardFault handler.

Resuming, the log was freezed, the firmware wasn't running anymore, and then the hard fault log appeared after opening and closing the gdb server.

The log stopped at approximately 15 hours of timestamp. One hour later I went to see how it was going and there were no more logs. Then, doing the GDB Server trick, the hard fault log showed up.

I am only using VSCode for flashing and monitoring the RTT log.

I cannot use UART log right now because I don't have such serial connections in my custom board, do you think the problem is related to using RTT logs?

The problem also didn't seem to happen in versions below 1.9.1 of the SDK.

Maybe it has something to do with the scanning handler and other interrupts in the firmware (such as LoRa interrupts from Zephyr's driver, or UART interrupts)?

The firmware implements 2 other tasks other than the ble task I described before:

LoRa task and GPS task.

The LoRa task uses Zephyr's driver to receive and send data around.

And the GPS task uses UART interrupts to put chars from the GPS module inside a buffer, then the buffer is processed in the main loop of the task.

Edit: for RTT logging I use LOG_INF, LOG_ERR... there are some logs from Zephyr OS which are using printk. I have some printf statements too in the code but they are disabled through pre-processor.

[dejans]

Hi,

Thank you for providing additional information.
Stop of the logging might be related to the logging buffer size.

thiago_hd said:

The problem also didn't seem to happen in versions below 1.9.1 of the SDK.

Could you please test how your firmware behaves with NCS versions 1.7.0 and 1.8.0 and 1.9.0?

Best regards,
Dejan

[thiago_hd]

Hi again dejans,

I will do that.

In the meanwhile, could you provide some insight on the log output, and how can I interpret it?

Thanks once more.

[dejans]

Hi,

Log suggests an error with interrupt handling. You might have a problem with stack overflow or zero latency. You can read more about zero latency IRQ from the Zephyr documentation. There was an issue reported with zero latency interrupt conflicts.

Best regards,
Dejan

[dejans]

Hi,

In general, it is hard to say what is wrong just by looking at the assert. 
If you would need more assistance, you should provide the steps to reproduce the issue that you reported.

Best regards,
Dejan