Matter Light Bulb sample will crash on connection when CONFIG_SERIAL is enabled

[Ignacio]

Hi there,

Please check logs and below data on ZEPHYR FATAL ERROR. Please let me know if you need any other info. 

* Sample: Matter Light Bulb

* nRF Connect SDK version: 2.6.0

* HW: nRF21540-DK

* Behaviour: Device will crash on establishing a connection when CONFIG_SERIAL=y flag is enabled.

* Logs: Attached

Fullscreen err_logs.txt Download

[00:00:00.001,831] <err> qspi_nor: JEDEC id [00 00 00] expect [c2 28 17]
*** Booting nRF Connect SDK v3.5.99-ncs1 ***
[00:00:00.022,338] <inf> chip: [DL]BLE address: F8:AC:68:19:31:DB
[00:00:00.035,827] <inf> chip: [DL]CHIP task running
[00:00:00.042,358] <inf> app: Init CHIP stack
[00:00:00.049,530] <inf> chip: [DL]OpenThread started: OK
[00:00:00.056,396] <inf> chip: [DL]Setting OpenThread device type to ROUTER
[00:00:00.064,910] <inf> chip: [SVR]Subscription persistence not supported
[00:00:00.073,303] <inf> chip: [SVR]Server initializing...
[00:[00:00:00.001,831] <err> qspi_nor: JEDEC id [00 00 00] expect [c2 28 17]
*** Booting nRF Connect SDK v3.5.99-ncs1 ***
[00:00:00.022,308] <inf> chip: [DL]BLE address: E8:5C:DE:B3:4E:91
[00:00:00.035,797] <inf> chip: [DL]CHIP task running
[00:00:00.042,327] <inf> app: Init CHIP stack
[00:00:00.049,499] <inf> chip: [DL]OpenThread started: OK
[00:00:00.056,365] <inf> chip: [DL]Setting OpenThread device type to ROUTER
[00:00:00.064,880] <inf> chip: [SVR]Subscription persistence not supported
[00:00:00.073,272] <inf> chip: [SVR]Server initializing...
[00:00:00.080,596] <inf> chip: [TS]Last Known Good Time: 2023-10-14T01:16:48
[00:00:00.089,752] <inf> chip: [DMG]AccessControl: initializing
[00:00:00.097,167] <inf> chip: [DMG]Examples::AccessControlDelegate::Init
[00:00:00.105,560] <inf> chip: [DMG]AccessControl: setting
[00:00:00.112,518] <inf> chip: [DMG]DefaultAclStorage: initializing
[00:00:00.120,300] <inf> chip: [DMG]DefaultAclStorage: 0 entries loaded
[00:00:00.128,479] <dbg> chip: LogV: [IN]UDP::Init bind&listen port=5540
[00:00:00.136,901] <dbg> chip: LogV: [IN]UDP::Init bound to port=5540
[00:00:00.144,866] <dbg> chip: LogV: [IN]BLEBase::Init - setting/overriding transport
[00:00:00.154,266] <dbg> chip: LogV: [IN]TransportMgr initialized
[00:00:00.165,069] <dbg> chip: LogV: [DL]Using Thread extended MAC for hostname.
[00:00:00.175,659] <inf> chip: [ZCL]Using ZAP configuration...
[00:00:00.185,333] <inf> chip: [DMG]AccessControlCluster: initializing
[00:00:00.193,450] <dbg> chip: LogV: [DL]Boot reason: 1
[00:00:00.200,347] <inf> chip: [ZCL]Initiating Admin Commissioning cluster.
[00:00:00.209,106] <inf> chip: [ZCL]Endpoint 1 On/off already set to new value
[00:00:00.218,170] <inf> chip: [ZCL]Cluster LevelControl: attribute CurrentLevel set to 254
[00:00:00.229,858] <dbg> chip: LogV: [IN]SecureSession[0x20002fe8]: Allocated Type:1 LSID:49973
[00:00:00.240,203] <dbg> chip: LogV: [DL]CHIPoBLE advertising set to on
[00:00:00.248,413] <inf> chip: [DIS]Updating services using commissioning mode 1
[00:00:00.257,415] <err> chip: [DIS]Failed to remove advertised services: 3
[00:00:00.265,960] <dbg> chip: LogV: [DL]Using Thread extended MAC for hostname.
[00:00:00.275,360] <inf> chip: [DIS]Advertise commission parameter vendorID=65521 productID=32773 discriminator=3840/15 cm=1
[00:00:00.288,299] <err> chip: [DIS]Failed to advertise commissionable node: 3
[00:00:00.297,058] <err> chip: [DIS]Failed to finalize service update: 3
[00:00:00.305,328] <inf> chip: [DIS]Updating services using commissioning mode 1
[00:00:00.314,270] <err> chip: [DIS]Failed to remove advertised services: 3
[00:00:00.322,845] <dbg> chip: LogV: [DL]Using Thread extended MAC for hostname.
[00:00:00.332,214] <inf> chip: [DIS]Advertise commission parameter vendorID=65521 productID=32773 discriminator=3840/15 cm=1
[00:00:00.345,153] <err> chip: [DIS]Failed to advertise commissionable node: 3
[00:00:00.353,942] <err> chip: [DIS]Failed to finalize service update: 3
[00:00:00.362,182] <inf> chip: [IN]CASE Server enabling CASE session setups
[00:00:00.371,063] <dbg> chip: LogV: [IN]SecureSession[0x200030a8]: Allocated Type:2 LSID:49974
[00:00:00.381,378] <inf> chip: [SVR]Joining Multicast groups
[00:00:00.388,671] <inf> chip: [SVR]Server Listening...
[00:00:00.395,355] <inf> chip: [DL]Device Configuration:
[00:00:00.402,404] <inf> chip: [DL]  Serial Number: 11223344556677889900
[00:00:00.410,644] <inf> chip: [DL]  Vendor Id: 65521 (0xFFF1)
[00:00:00.417,999] <inf> chip: [DL]  Product Id: 32773 (0x8005)
[00:00:00.425,415] <inf> chip: [DL]  Product Name: not-specified
[00:00:00.433,166] <inf> chip: [DL]  Hardware Version: 0
[00:00:00.440,246] <inf> chip: [DL]  Setup Pin Code (0 for UNKNOWN/ERROR): 20202021
[00:00:00.449,798] <inf> chip: [DL]  Setup Discriminator (0xFFFF for UNKNOWN/ERROR): 3840 (0xF00)
[00:00:00.460,540] <inf> chip: [DL]  Manufacturing Date: (not set)
[00:00:00.468,231] <inf> chip: [DL]  Device Type: 65535 (0xFFFF)
[00:00:00.476,348] <inf> chip: [SVR]SetupQRCode: [MT:6FCJ142C00KA0648G00]
[00:00:00.484,741] <inf> chip: [SVR]Copy/paste the below URL in a browser to see the QR Code:
[00:00:00.494,873] <inf> chip: [SVR]https://project-chip.github.io/connectedhomeip/qrcode.html?data=MT%3A6FCJ142C00KA0648G00
[00:00:00.507,904] <inf> chip: [SVR]Manual pairing code: [34970112332]
[00:00:00.516,113] <err> chip: [DL]Long dispatch time: 474 ms, for event type 2
[00:00:00.525,146] <inf> chip: [ZCL]Cluster OnOff: attribute OnOff set to 0
[00:00:00.533,782] <inf> chip: [ZCL]Cluster LevelControl: attribute CurrentLevel set to 254
[00:00:00.545,532] <inf> chip: [DL]CHIPoBLE advertising started
[00:00:00.553,619] <inf> chip: [DL]NFC Tag emulation started
[00:00:26.787,414] <err> os: ***** MPU FAULT *****
[00:00:26.793,579] <err> os:   Stacking error (context area might be not valid)
[00:00:26.802,307] <err> os:   Data Access Violation
[00:00:26.808,624] <err> os:   MMFAR Address: 0x200231b8
[00:00:26.815,368] <err> os: r0/a1:  0x865cee3c  r1/a2:  0x5a65e243  r2/a3:  0x23f7755f
[00:00:26.824,920] <err> os: r3/a4:  0x21200ac1 r12/ip:  0xaaaaaaaa r14/lr:  0xaaaaaaaa
[00:00:26.834,472] <err> os:  xpsr:  0x21000000
[00:00:26.840,423] <err> os: s[ 0]:  0x0000005b  s[ 1]:  0x5b0ab320  s[ 2]:  0x000b0f55  s[ 3]:  0x00011187
[00:00:26.851,867] <err> os: s[ 4]:  0xaaaaaaaa  s[ 5]:  0xaaaaaaaa  s[ 6]:  0xaaaaaaaa  s[ 7]:  0x000ab320
[00:00:26.863,311] <err> os: s[ 8]:  0xaaaaaaaa  s[ 9]:  0xaaaaaaaa  s[10]:  0x000b0f56  s[11]:  0xaaaaaaaa
[00:00:26.874,786] <err> os: s[12]:  0xaaaaaaaa  s[13]:  0xaaaaaaaa  s[14]:  0xaaaaaaaa  s[15]:  0xaaaaaaaa
[00:00:26.886,230] <err> os: fpscr:  0xaaaaaaaa
[00:00:26.892,150] <err> os: Faulting instruction address (r15/pc): 0x00021740
[00:00:26.900,848] <err> os: >>> ZEPHYR FATAL ERROR 2: Stack overflow on CPU 0
[00:00:26.909,545] <err> os: Current thread: 0x20006178 (BT RX)
[00:00:26.916,870] [1;31m<err> os: Halting system[0m

* Changes:

- Added below lines to prj_no_dfu.con

# Reduce application size

#CONFIG_USE_SEGGER_RTT=n

# Config logger

CONFIG_LOG=y

CONFIG_MATTER_LOG_LEVEL_DBG=y

CONFIG_LOG_MODE_IMMEDIATE=y

# Config UART

CONFIG_SERIAL=y

 

[Ignacio]

Follow up:

If only adding and no more changes than the line below, the device will not crash.

# Config UART

CONFIG_SERIAL=y

I wonder. Is there a conflict between activating matter logs and a serial port?

 

[Amanda Hsieh]

Hi, 

The log indicated that the BT RX thread caused the fault.

Could you check the value of CONFIG_BT_RX_STACK_SIZE in the.config file under build/zephyr and try to increase the value?

Regards,
Amanda H.

[Ignacio]

I change the logging to use below config parameters:

# Config logger

CONFIG_LOG=y

CONFIG_MATTER_LOG_LEVEL_DBG=y

CONFIG_USE_SEGGER_RTT=y

CONFIG_RTT_CONSOLE=y

CONFIG_UART_CONSOLE=n

That makes both the RTT logging and serial comms to work.

I also increase the CONFIG_BT_RX_STACK_SIZE  from 1200 to 2400 just in case