esp-matter
esp-matter copied to clipboard
espressif
Matter controller fails to start on esp32-s3 & esp32-h2 (CON-1604)
Describe the bug I'm trying to run the esp-matter-controller example on two seperate boards. I've connected them using the table here I've used pin 4/5 as tx/rx on both the RCP and the controller side.
however, openthread fails to start, due to an error:
E (5940) OPENTHREAD: esp_openthread_lock_acquire(21): Failed to acquire the lock because the mutex is not ready
E (5940) OPENTHREAD: otPlatSettingsGet(151): OT NVS handle is invalid.
E (5940) OPENTHREAD: esp_openthread_discovery_delegate_init(505): Failed to create discovery delegate eventfd
E (5940) OPENTHREAD: esp_openthread_border_router_init(143): Failed to initialize discovery delegate
E (5940) OPENTHREAD: esp_openthread_lock_release(30): Failed to release the lock because the mutex is not ready
I'm not sure if this is supposed to go here, or in the esp-idf repo, or maybe in the esp-thread-lib repo because the issue seems to originate there.
The ESP32-S3 is the 8MB PSRAM version.
I've tested with the esp-thread-br recommended version of ESP-IDF, v5.2.4. But I've also tried v5.4 and v5.2.3, but the issue persists
please see the full logs attached below.
Environment
- ESP-Matter Commit Id: c39d4aecbab71f90523d3739b6a56374a31ec099
- ESP-IDF Commit Id: af4a98ba99dd5cdc5b0be532230fe9fd7f6d4084
- SoC (eg: ESP32 or ESP32-C3): ESP32-S3 & ESP32-H2
- Device Logs (Please attach the log file):
I (26) boot: ESP-IDF v5.2.4-dirty 2nd stage bootloader
I (27) boot: compile time Mar 17 2025 23:30:20
I (27) boot: Multicore bootloader
I (30) boot: chip revision: v0.2
I (34) boot: efuse block revision: v1.3
I (39) boot.esp32s3: Boot SPI Speed : 80MHz
I (43) boot.esp32s3: SPI Mode : DIO
I (48) boot.esp32s3: SPI Flash Size : 4MB
I (53) boot: Enabling RNG early entropy source...
I (58) boot: Partition Table:
I (62) boot: ## Label Usage Type ST Offset Length
I (69) boot: 0 nvs WiFi data 01 02 00009000 0000c000
I (77) boot: 1 phy_init RF data 01 01 00015000 00001000
I (84) boot: 2 factory factory app 00 00 00020000 002ee000
I (92) boot: 3 rcp_fw Unknown data 01 82 0030e000 00096000
I (99) boot: End of partition table
I (103) esp_image: segment 0: paddr=00020020 vaddr=3c190020 size=55758h (350040) map
I (173) esp_image: segment 1: paddr=00075780 vaddr=3fc9ed00 size=057f4h ( 22516) load
I (178) esp_image: segment 2: paddr=0007af7c vaddr=40374000 size=0509ch ( 20636) load
I (184) esp_image: segment 3: paddr=00080020 vaddr=42000020 size=182e68h (1584744) map
I (467) esp_image: segment 4: paddr=00202e90 vaddr=4037909c size=15bach ( 89004) load
I (498) boot: Loaded app from partition at offset 0x20000
I (498) boot: Disabling RNG early entropy source...
I (499) cpu_start: Multicore app
I (503) octal_psram: vendor id : 0x0d (AP)
I (507) octal_psram: dev id : 0x02 (generation 3)
I (513) octal_psram: density : 0x03 (64 Mbit)
I (518) octal_psram: good-die : 0x01 (Pass)
I (524) octal_psram: Latency : 0x01 (Fixed)
I (529) octal_psram: VCC : 0x01 (3V)
I (534) octal_psram: SRF : 0x01 (Fast Refresh)
I (540) octal_psram: BurstType : 0x01 (Hybrid Wrap)
I (546) octal_psram: BurstLen : 0x01 (32 Byte)
I (551) octal_psram: Readlatency : 0x02 (10 cycles@Fixed)
I (557) octal_psram: DriveStrength: 0x00 (1/1)
I (563) MSPI Timing: PSRAM timing tuning index: 4
I (568) esp_psram: Found 8MB PSRAM device
I (572) esp_psram: Speed: 80MHz
I (983) esp_psram: SPI SRAM memory test OK
I (992) cpu_start: Pro cpu start user code
I (992) cpu_start: cpu freq: 160000000 Hz
I (992) cpu_start: Application information:
I (992) cpu_start: Project name: controller
I (992) cpu_start: App version: c39d4ae-dirty
I (993) cpu_start: Compile time: Mar 17 2025 23:30:06
I (993) cpu_start: ELF file SHA256: d91296e86...
I (993) cpu_start: ESP-IDF: v5.2.4-dirty
I (993) cpu_start: Min chip rev: v0.0
I (993) cpu_start: Max chip rev: v0.99
I (994) cpu_start: Chip rev: v0.2
I (994) heap_init: Initializing. RAM available for dynamic allocation:
I (994) heap_init: At 3FCBDA38 len 0002BCD8 (175 KiB): RAM
I (994) heap_init: At 3FCE9710 len 00005724 (21 KiB): RAM
I (995) heap_init: At 3FCF0000 len 00008000 (32 KiB): DRAM
I (995) heap_init: At 600FE010 len 00001FD8 (7 KiB): RTCRAM
I (995) esp_psram: Adding pool of 8174K of PSRAM memory to heap allocator
I (996) spi_flash: detected chip: generic
I (997) spi_flash: flash io: dio
W (997) spi_flash: Detected size(16384k) larger than the size in the binary image header(4096k). Using the size in the binary image header.
I (998) sleep: Configure to isolate all GPIO pins in sleep state
I (999) sleep: Enable automatic switching of GPIO sleep configuration
I (999) coexist: coex firmware version: 994b23e
I (1000) coexist: coexist rom version e7ae62f
I (1000) main_task: Started on CPU0
I (1010) esp_psram: Reserving pool of 8K of internal memory for DMA/internal allocations
I (1010) main_task: Calling app_main()
I (1260) pp: pp rom version: e7ae62f
I (1260) net80211: net80211 rom version: e7ae62f
I (1270) wifi:wifi driver task: 3fccd440, prio:23, stack:6656, core=0
I (1280) wifi:wifi firmware version: 01d22db
I (1280) wifi:wifi certification version: v7.0
I (1280) wifi:config NVS flash: enabled
I (1280) wifi:config nano formating: disabled
I (1280) wifi:Init data frame dynamic rx buffer num: 32
I (1280) wifi:Init static rx mgmt buffer num: 5
I (1280) wifi:Init management short buffer num: 32
I (1280) wifi:Init static tx buffer num: 16
I (1280) wifi:Init tx cache buffer num: 32
I (1280) wifi:Init static tx FG buffer num: 2
I (1280) wifi:Init static rx buffer size: 1600
I (1280) wifi:Init static rx buffer num: 16
I (1280) wifi:Init dynamic rx buffer num: 32
I (1280) wifi_init: rx ba win: 16
I (1280) wifi_init: tcpip mbox: 32
I (1280) wifi_init: udp mbox: 6
I (1280) wifi_init: tcp mbox: 6
I (1280) wifi_init: tcp tx win: 5760
I (1280) wifi_init: tcp rx win: 5760
I (1280) wifi_init: tcp mss: 1440
I (1280) wifi_init: WiFi/LWIP prefer SPIRAM
I (1290) wifi_init: WiFi IRAM OP enabled
I (1290) wifi_init: WiFi RX IRAM OP enabled
> I (1310) chip[DL]: NVS set: chip-counters/reboot-count = 83 (0x53)
I (1310) chip[DL]: Real time clock set to 946684800 (0100/00/01 00:00:00 UTC)
I (1310) BLE_INIT: BT controller compile version [fd62b31]
I (1310) BLE_INIT: Bluetooth MAC: 94:a9:90:30:27:26
I (1310) phy_init: phy_version 680,a6008b2,Jun 4 2024,16:41:10
I (1350) phy_init: Saving new calibration data due to checksum failure or outdated calibration data, mode(0)
I (1380) NimBLE: GAP procedure initiated: stop advertising.
I (1380) NimBLE: Failed to restore IRKs from store; status=8
I (1380) CHIP[DL]: BLE host-controller synced
I (1880) chip[DL]: Starting ESP WiFi layer
I (1880) wifi:mode : sta (94:a9:90:30:27:24)
I (1880) wifi:enable tsf
W (1880) wifi:Haven't to connect to a suitable AP now!
I (1880) chip[DL]: Attempting to connect WiFi station interface
I (1880) chip[DL]: WiFi station state change: NotConnected -> Connecting
I (1880) chip[DL]: Done driving station state, nothing else to do...
I (1880) chip[DL]: Posting ESPSystemEvent: Wifi Event with eventId : 43
I (1880) chip[DL]: HandlePlatformSpecificBLEEvent 49152
I (1890) chip[DL]: Posting ESPSystemEvent: Wifi Event with eventId : 2
I (1890) chip[DL]: HandlePlatformSpecificBLEEvent 49152
I (1890) chip[DL]: WIFI_EVENT_STA_START
W (1890) wifi:Haven't to connect to a suitable AP now!
I (1890) chip[DL]: Attempting to connect WiFi station interface
E (1890) wifi:sta is connecting, return error
E (1890) chip[DL]: esp_wifi_connect() failed: ESP_ERR_WIFI_CONN
I (1890) chip[CTL]: Setting attestation nonce to random value
I (1890) chip[CTL]: Setting CSR nonce to random value
I (1890) chip[CTL]: Setting attestation nonce to random value
I (1890) chip[CTL]: Setting CSR nonce to random value
I (1900) chip[TS]: Last Known Good Time: 2023-10-14T01:16:48
I (1900) chip[FP]: Fabric index 0x1 was retrieved from storage. Compressed FabricId 0x671131127CDE81E2, FabricId 0x0000000000000001, NodeId 0x000000000001B669, VendorId 0x131B
I (1930) mdns_mem: mDNS task will be created from internal RAM
I (1940) chip[IN]: CASE Server enabling CASE session setups
I (2110) chip[CTL]: Generating NOC
I (2290) chip[FP]: Validating NOC chain
I (2960) chip[FP]: NOC chain validation successful
I (2960) chip[FP]: Updated fabric at index: 0x1, Node ID: 0x000000000001B669
I (2970) chip[TS]: Last Known Good Time: 2023-10-14T01:16:48
I (2970) chip[TS]: New proposed Last Known Good Time: 2021-01-01T00:00:00
I (2970) chip[TS]: Retaining current Last Known Good Time
I (2970) chip[FP]: Metadata for Fabric 0x1 persisted to storage.
I (2980) chip[TS]: Committing Last Known Good Time to storage: 2023-10-14T01:16:48
I (3000) chip[CTL]: Joined the fabric at index 1. Fabric ID is 0x0000000000000001 (Compressed Fabric ID: 671131127CDE81E2)
I (3000) chip[DIS]: Updating services using commissioning mode 0
I (3000) chip[DIS]: Advertise operational node 671131127CDE81E2-000000000001B669
I (3000) chip[DIS]: Advertise commission parameter vendorID=65521 productID=32768 discriminator=3840/15 cm=0 cp=0
I (3000) chip[DIS]: Advertise commission parameter vendorID=65521 productID=32768 discriminator=0000/00 cm=0 cp=0
I (3080) main_task: Returned from app_main()
I (3080) chip[DL]: HandlePlatformSpecificBLEEvent 32786
I (3080) chip[DIS]: Updating services using commissioning mode 0
I (3080) chip[DIS]: Advertise operational node 671131127CDE81E2-000000000001B669
I (3080) chip[DIS]: Advertise commission parameter vendorID=65521 productID=32768 discriminator=3840/15 cm=0 cp=0
I (3080) chip[DIS]: Advertise commission parameter vendorID=65521 productID=32768 discriminator=0000/00 cm=0 cp=0
I (4290) wifi:new:<11,2>, old:<1,0>, ap:<255,255>, sta:<11,2>, prof:1
I (4300) wifi:state: init -> auth (b0)
I (4300) chip[DL]: Posting ESPSystemEvent: Wifi Event with eventId : 43
I (4300) chip[DL]: HandlePlatformSpecificBLEEvent 49152
I (4300) wifi:state: auth -> assoc (0)
I (4310) wifi:state: assoc -> run (10)
I (4320) wifi:<ba-add>idx:0 (ifx:0, b8:d5:26:de:78:d1), tid:5, ssn:0, winSize:64
I (4430) wifi:<ba-add>idx:1 (ifx:0, b8:d5:26:de:78:d1), tid:0, ssn:1, winSize:64
I (4430) wifi:connected with Huize viking 2, aid = 3, channel 11, 40D, bssid = b8:d5:26:de:78:d1
I (4430) wifi:security: WPA2-PSK, phy: bgn, rssi: -79
I (4430) wifi:pm start, type: 1
I (4430) wifi:dp: 1, bi: 102400, li: 3, scale listen interval from 307200 us to 307200 us
I (4430) wifi:set rx beacon pti, rx_bcn_pti: 14, bcn_timeout: 25000, mt_pti: 14, mt_time: 10000
I (4440) chip[DL]: Posting ESPSystemEvent: Wifi Event with eventId : 4
I (4440) chip[DL]: HandlePlatformSpecificBLEEvent 49152
I (4440) chip[DL]: WIFI_EVENT_STA_CONNECTED
I (4440) chip[DL]: WiFi station state change: Connecting -> Connecting_Succeeded
I (4440) chip[DL]: WiFi station state change: Connecting_Succeeded -> Connected
I (4440) chip[DL]: WiFi station interface connected
I (4440) chip[DL]: Done driving station state, nothing else to do...
I (4440) chip[DL]: Updating advertising data
I (4470) wifi:AP's beacon interval = 102400 us, DTIM period = 1
I (5940) esp_netif_handlers: sta ip: 192.168.1.76, mask: 255.255.255.0, gw: 192.168.1.1
I (5940) chip[DL]: Posting ESPSystemEvent: IP Event with eventId : 0
I (5940) chip[DL]: HandlePlatformSpecificBLEEvent 49152
I (5940) chip[DL]: IP_EVENT_STA_GOT_IP
I (5940) chip[DL]: IPv4 address changed on WiFi station interface: 192.168.1.76/255.255.255.0 gateway 192.168.1.1
I (5940) chip[DL]: IPv4 Internet connectivity ESTABLISHED
E (5940) OPENTHREAD: esp_openthread_lock_acquire(21): Failed to acquire the lock because the mutex is not ready
E (5940) OPENTHREAD: otPlatSettingsGet(151): OT NVS handle is invalid.
I(5940) OPENTHREAD:[I] SrpServer-----: Selected port 53536
I(5940) OPENTHREAD:[I] NetDataPublshr: Publishing DNS/SRP service unicast (ml-eid, port:53536)
I(5940) OPENTHREAD:[I] NetDataPublshr: DNS/SRP service - State: NoEntry -> ToAdd
E (5940) OPENTHREAD: esp_openthread_discovery_delegate_init(505): Failed to create discovery delegate eventfd
E (5940) OPENTHREAD: esp_openthread_border_router_init(143): Failed to initialize discovery delegate
E (5940) OPENTHREAD: esp_openthread_lock_release(30): Failed to release the lock because the mutex is not ready
I (5940) chip[DL]: HandlePlatformSpecificBLEEvent 32770
I (5950) chip[DL]: HandlePlatformSpecificBLEEvent 32782
I (5950) app_main: Interface IP Address changed
I (5950) chip[DIS]: Updating services using commissioning mode 0
I (5950) chip[DIS]: Advertise operational node 671131127CDE81E2-000000000001B669
I (5950) chip[DIS]: Advertise commission parameter vendorID=65521 productID=32768 discriminator=3840/15 cm=0 cp=0
I (5950) chip[DIS]: Advertise commission parameter vendorID=65521 productID=32768 discriminator=0000/00 cm=0 cp=0
I (6260) chip[DL]: Posting ESPSystemEvent: IP Event with eventId : 3
I (6260) chip[DL]: HandlePlatformSpecificBLEEvent 49152
I (6260) chip[DL]: IP_EVENT_GOT_IP6
I (6260) chip[DL]: IPv6 addr available. Ready on WIFI_STA_DEF interface: fe80:0000:0000:0000:96a9:90ff:fe30:2724
I (6260) chip[DL]: HandlePlatformSpecificBLEEvent 32782
I (6260) app_main: Interface IP Address changed
I (6260) chip[DIS]: Updating services using commissioning mode 0
I (6260) chip[DIS]: Advertise operational node 671131127CDE81E2-000000000001B669
I (6270) chip[DIS]: Advertise commission parameter vendorID=65521 productID=32768 discriminator=3840/15 cm=0 cp=0
I (6270) chip[DIS]: Advertise commission parameter vendorID=65521 productID=32768 discriminator=0000/00 cm=0 cp=0
I (8260) chip[DL]: Posting ESPSystemEvent: IP Event with eventId : 3
I (8260) chip[DL]: HandlePlatformSpecificBLEEvent 49152
I (8260) chip[DL]: IP_EVENT_GOT_IP6
I (8260) chip[DL]: IPv6 addr available. Ready on WIFI_STA_DEF interface: fda1:1c14:16ac:0001:96a9:90ff:fe30:2724
I (8260) chip[DL]: HandlePlatformSpecificBLEEvent 32782
I (8260) app_main: Interface IP Address changed
I (8260) chip[DIS]: Updating services using commissioning mode 0
I (8260) chip[DIS]: Advertise operational node 671131127CDE81E2-000000000001B669
I (8260) chip[DIS]: Advertise commission parameter vendorID=65521 productID=32768 discriminator=3840/15 cm=0 cp=0
I (8270) chip[DIS]: Advertise commission parameter vendorID=65521 productID=32768 discriminator=0000/00 cm=0 cp=0
- Host Machine OS: Fedora
- Host Machine Python version: 3.12.8
Any additional details ...
Could you update your esp-matter to the latest main branch and try again? there is an issue that the Thread stack is not initialized when initializing Border Router feature.
@sjoerd0301 @dhrishi @wqx6 Which commits fix this problem? I still have it even using the main branch. Even though the main branch does not compile.
