apple / swift-matter-examples

An Embedded Swift Matter application running on ESP32-C6
https://apple.github.io/swift-matter-examples/tutorials/tutorial-table-of-contents/
Apache License 2.0
279 stars 22 forks source link

Cannot commission smart light example #10

Open TimmyRB opened 5 months ago

TimmyRB commented 5 months ago

ESP-IDF: v5.2.1 ESP-Matter: v1.2 Swift Toolchain: org.swift.59202406131a Swift Version: 6.0-dev (LLVM 57177aa1b91540b, Swift 8be62863326595c) Target: arm64-apple-macosx15.0

I setup my environment following the steps here

I then cloned the examples and followed the steps for the smart light example here

My ESP32C6 gets flashed and runs the example fine until I enter the setup code in the Home app then it encounters a Load Access Fault and restarts itself, the Home app then displays "Unable to Connect to Network" "Make sure the network can reach your accessory, reset the accessory and try adding to your home again"

Here is the output logs

🏎️   Hello, Embedded Swift! (Smart Light)
I (676) led_driver_ws2812: Initializing light driver
I (676) led_driver_ws2812: led set r:0, g:0, b:0
I (706) pp: pp rom version: 5b8dcfa
I (706) net80211: net80211 rom version: 5b8dcfa
I (716) wifi:wifi driver task: 4083dac0, prio:23, stack:6656, core=0
I (716) wifi:wifi firmware version: a9f5b59
I (716) wifi:wifi certification version: v7.0
I (716) wifi:config NVS flash: enabled
I (726) wifi:config nano formating: disabled
I (726) wifi:mac_version:HAL_MAC_ESP32AX_761,ut_version:N
I (736) wifi:Init data frame dynamic rx buffer num: 32
I (736) wifi:Init static rx mgmt buffer num: 5
I (746) wifi:Init management short buffer num: 32
I (746) wifi:Init dynamic tx buffer num: 32
I (746) wifi:Init static tx FG buffer num: 2
I (756) wifi:Init static rx buffer size: 1700
I (756) wifi:Init static rx buffer num: 10
I (766) wifi:Init dynamic rx buffer num: 32
I (766) wifi_init: rx ba win: 6
I (766) wifi_init: tcpip mbox: 32
I (776) wifi_init: udp mbox: 6
I (776) wifi_init: tcp mbox: 6
I (786) wifi_init: tcp tx win: 5760
I (786) wifi_init: tcp rx win: 5760
I (786) wifi_init: tcp mss: 1440
I (796) wifi_init: WiFi IRAM OP enabled
I (796) wifi_init: WiFi RX IRAM OP enabled
I (826) chip[DL]: NVS set: chip-counters/reboot-count = 4 (0x4)
I (826) chip[DL]: Real time clock set to 946684800 (0100/00/01 00:00:00 UTC)
I (826) BLE_INIT: Using main XTAL as clock source
I (836) BLE_INIT: ble controller commit:[217f1bf]
I (836) phy_init: phy_version 250,e14681b,Jan 24 2024,17:43:11
I (896) phy: libbtbb version: 939f79c, Jan 24 2024, 17:43:26
I (896) NimBLE: GAP procedure initiated: stop advertising.

I (896) NimBLE: Failed to restore IRKs from store; status=8

I (906) CHIP[DL]: BLE host-controller synced
I (1406) chip[DL]: Configuring CHIPoBLE advertising (interval 25 ms, connectable)
I (1406) NimBLE: GAP procedure initiated: advertise;
I (1406) NimBLE: disc_mode=2
I (1406) NimBLE:  adv_channel_map=0 own_addr_type=1 adv_filter_policy=0 adv_itvl_min=40 adv_itvl_max=40
I (1416) NimBLE:

I (1426) chip[DL]: CHIPoBLE advertising started
I (1426) chip[DL]: Starting ESP WiFi layer
W (1436) wifi:(bf)761:0x600a7cac:0x01b4b4b0
W (1436) wifi:(agc)0x600a7128:0xd203b800, min.avgNF:0xce->0xd2(dB), RCalCount:0x3b, min.RRssi:0x800(-128.00)
W (1446) wifi:(TB)WDEV_PWR_TB_MCS0:19
W (1446) wifi:(TB)WDEV_PWR_TB_MCS1:19
W (1456) wifi:(TB)WDEV_PWR_TB_MCS2:19
W (1456) wifi:(TB)WDEV_PWR_TB_MCS3:19
W (1456) wifi:(TB)WDEV_PWR_TB_MCS4:19
W (1466) wifi:(TB)WDEV_PWR_TB_MCS5:19
W (1466) wifi:(TB)WDEV_PWR_TB_MCS6:18
W (1466) wifi:(TB)WDEV_PWR_TB_MCS7:18
W (1476) wifi:(TB)WDEV_PWR_TB_MCS8:17
W (1476) wifi:(TB)WDEV_PWR_TB_MCS9:15
W (1476) wifi:(TB)WDEV_PWR_TB_MCS10:15
W (1486) wifi:(TB)WDEV_PWR_TB_MCS11:15
I (1486) wifi:11ax coex: WDEVAX_PTI0(0x55777555), WDEVAX_PTI1(0x00003377).

I (1496) wifi:mode : sta (60:55:f9:f7:29:34)
I (1496) wifi:enable tsf
W (1496) wifi:Haven't to connect to a suitable AP now!
I (1506) chip[DL]: Done driving station state, nothing else to do...
W (1506) wifi:Haven't to connect to a suitable AP now!
I (1516) chip[DL]: Done driving station state, nothing else to do...
I (1526) chip[SVR]: Initializing subscription resumption storage...
I (1526) chip[SVR]: Server initializing...
I (1536) chip[TS]: Last Known Good Time: 2023-10-14T01:16:48
I (1536) chip[DMG]: AccessControl: initializing
I (1546) chip[DMG]: Examples::AccessControlDelegate::Init
I (1556) chip[DMG]: AccessControl: setting
I (1556) chip[DMG]: DefaultAclStorage: initializing
I (1566) chip[DMG]: DefaultAclStorage: 0 entries loaded
I (1576) chip[ZCL]: Using ZAP configuration...
I (1576) esp_matter_cluster: Cluster plugin init common callback
I (1576) chip[DMG]: AccessControlCluster: initializing
I (1586) chip[ZCL]: 0x421357a8ep 0 clus 0x0000_0030 attr 0x0000_0000 not supported
I (1596) chip[ZCL]: Initiating Admin Commissioning cluster.
I (1606) chip[DIS]: Updating services using commissioning mode 1
I (1606) chip[DIS]: CHIP minimal mDNS started advertising.
I (1616) chip[DIS]: Advertise commission parameter vendorID=65521 productID=32768 discriminator=3840/15 cm=1
I (1626) chip[DIS]: CHIP minimal mDNS configured as 'Commissionable node device'; instance name: 093C757B250575F9.
I (1636) chip[DIS]: mDNS service published: _matterc._udp
I (1636) chip[IN]: CASE Server enabling CASE session setups
I (1646) chip[SVR]: Joining Multicast groups
I (1656) chip[SVR]: Server Listening...
I (1656) esp_matter_core: Dynamic endpoint 0 added
I (1666) esp_matter_attribute: ********** W : Endpoint 0x0001's Cluster 0x00000003's Attribute 0x00000001 is 0 **********
lightEndpoint.eventHandler:
unknown
0
I (1676) esp_matter_attribute: ********** W : Endpoint 0x0001's Cluster 0x00000004's Attribute 0x00000000 is 128 **********
lightEndpoint.eventHandler:
unknown
128
I (1696) esp_matter_attribute: ********** W : Endpoint 0x0001's Cluster 0x00000004's Attribute 0x0000FFFC is <invalid type: 0> **********
I (1706) esp_matter_attribute: ********** R : Endpoint 0x0001's Cluster 0x00000006's Attribute 0x0000FFFC is 1 **********
I (1716) esp_matter_attribute: ********** R : Endpoint 0x0001's Cluster 0x00000006's Attribute 0x00004003 is 0 **********
I (1726) esp_matter_attribute: ********** R : Endpoint 0x0001's Cluster 0x00000006's Attribute 0x00000000 is 0 **********
I (1736) esp_matter_attribute: ********** R : Endpoint 0x0001's Cluster 0x00000006's Attribute 0x00000000 is 0 **********
I (1756) chip[ZCL]: Endpoint 1 On/off already set to new value
I (1756) esp_matter_attribute: ********** R : Endpoint 0x0001's Cluster 0x00000008's Attribute 0x00000002 is 1 **********
I (1766) esp_matter_attribute: ********** R : Endpoint 0x0001's Cluster 0x00000008's Attribute 0x00000003 is 254 **********
I (1786) esp_matter_attribute: ********** R : Endpoint 0x0001's Cluster 0x00000008's Attribute 0x0000FFFC is 3 **********
I (1796) esp_matter_attribute: ********** R : Endpoint 0x0001's Cluster 0x00000008's Attribute 0x00000000 is 64 **********
I (1806) esp_matter_attribute: ********** R : Endpoint 0x0001's Cluster 0x00000008's Attribute 0x00004000 is 64 **********
I (1816) esp_matter_attribute: ********** W : Endpoint 0x0001's Cluster 0x00000008's Attribute 0x00000000 is 64 **********
lightEndpoint.eventHandler:
levelControl
64
I (1836) led_driver_ws2812: led set r:63, g:63, b:63
I (1836) esp_matter_attribute: ********** R : Endpoint 0x0001's Cluster 0x00000300's Attribute 0x00004010 is 250 **********
I (1846) esp_matter_attribute: ********** R : Endpoint 0x0001's Cluster 0x00000300's Attribute 0x00000007 is 250 **********
I (1866) esp_matter_attribute: ********** R : Endpoint 0x0001's Cluster 0x00000300's Attribute 0x0000400B is 0 **********
I (1876) esp_matter_attribute: ********** R : Endpoint 0x0001's Cluster 0x00000300's Attribute 0x0000400C is 65279 **********
I (1886) esp_matter_attribute: ********** W : Endpoint 0x0001's Cluster 0x00000300's Attribute 0x00000007 is 250 **********
lightEndpoint.eventHandler:
colorControl(colorTemperatureMireds)
250
I (1906) led_driver_ws2812: led set r:63, g:51, b:40
I (1906) esp_matter_attribute: ********** W : Endpoint 0x0001's Cluster 0x00000300's Attribute 0x00000008 is 2 **********
lightEndpoint.eventHandler:
colorControl(colorMode)
2
I (1926) esp_matter_attribute: ********** W : Endpoint 0x0001's Cluster 0x00000300's Attribute 0x00004001 is 2 **********
I (1936) esp_matter_core: Dynamic endpoint 1 added
I (1946) chip[DL]: WIFI_EVENT_STA_START
W (1946) wifi:Haven't to connect to a suitable AP now!
I (1956) chip[DL]: Done driving station state, nothing else to do...
I (1956) chip[DL]: Configuring CHIPoBLE advertising (interval 25 ms, connectable)
I (1966) chip[DL]: Device already advertising, stop active advertisement and restart
I (1976) NimBLE: GAP procedure initiated: stop advertising.

I (1986) NimBLE: GAP procedure initiated: advertise;
I (1986) NimBLE: disc_mode=2
I (1996) NimBLE:  adv_channel_map=0 own_addr_type=1 adv_filter_policy=0 adv_itvl_min=40 adv_itvl_max=40
I (2006) NimBLE:

I (2006) main_task: Returned from app_main()
I (7086) chip[DL]: BLE GAP connection established (con 1)
I (7096) chip[DL]: CHIPoBLE advertising stopped
I (7796) CHIP[DL]: Write request received for CHIPoBLE RX characteristic con 1 16
I (7796) chip[BLE]: local and remote recv window sizes = 5
I (7796) chip[BLE]: selected BTP version 4
I (7806) chip[BLE]: using BTP fragment sizes rx 244 / tx 244.
I (7976) chip[DL]: Write request/command received for CHIPoBLE TX CCCD characteristic (con 1 ) indicate = 1
I (7976) chip[DL]: CHIPoBLE subscribe received
I (7976) NimBLE: GATT procedure initiated: indicate;
I (7986) NimBLE: att_handle=18

I (8016) chip[DL]: Confirm received for CHIPoBLE TX characteristic indication (con 1) status= 14
I (8016) CHIP[DL]: Write request received for CHIPoBLE RX characteristic con 1 16
I (8026) chip[EM]: >>> [E:58064r S:0 M:97973608] (U) Msg RX from 0:E718CD1E08D6E3CA [0000] --- Type 0000:20 (SecureChannel:PBKDFParamRequest)
I (8046) chip[EM]: <<< [E:58064r S:0 M:227999118] (U) Msg TX to 0:0000000000000000 [0000] [BLE] --- Type 0000:21 (SecureChannel:PBKDFParamResponse)
I (8056) NimBLE: GATT procedure initiated: indicate;
I (8056) NimBLE: att_handle=18

I (8066) chip[SVR]: Commissioning session establishment step started
I (8106) chip[DL]: Confirm received for CHIPoBLE TX characteristic indication (con 1) status= 14
I (8106) CHIP[DL]: Write request received for CHIPoBLE RX characteristic con 1 16
I (8116) chip[EM]: >>> [E:58064r S:0 M:97973609] (U) Msg RX from 0:E718CD1E08D6E3CA [0000] --- Type 0000:22 (SecureChannel:PASE_Pake1)
I (8186) chip[EM]: <<< [E:58064r S:0 M:227999119] (U) Msg TX to 0:0000000000000000 [0000] [BLE] --- Type 0000:23 (SecureChannel:PASE_Pake2)
I (8186) NimBLE: GATT procedure initiated: indicate;
I (8196) NimBLE: att_handle=18

I (8246) chip[DL]: Confirm received for CHIPoBLE TX characteristic indication (con 1) status= 14
I (8246) CHIP[DL]: Write request received for CHIPoBLE RX characteristic con 1 16
I (8256) chip[EM]: >>> [E:58064r S:0 M:97973610] (U) Msg RX from 0:E718CD1E08D6E3CA [0000] --- Type 0000:24 (SecureChannel:PASE_Pake3)
I (8266) chip[EM]: <<< [E:58064r S:0 M:227999120] (U) Msg TX to 0:0000000000000000 [0000] [BLE] --- Type 0000:40 (SecureChannel:StatusReport)
I (8276) NimBLE: GATT procedure initiated: indicate;
I (8286) NimBLE: att_handle=18

I (8286) chip[SC]: SecureSession[0x40822b00, LSID:40926]: State change 'kEstablishing' --> 'kActive'
I (8296) chip[SVR]: Commissioning completed session establishment step
I (8306) chip[DIS]: Updating services using commissioning mode 0
I (8306) chip[DIS]: CHIP minimal mDNS started advertising.
I (8316) chip[DIS]: Advertise commission parameter vendorID=65521 productID=32768 discriminator=3840/15 cm=0
I (8326) chip[DIS]: CHIP minimal mDNS configured as 'Commissionable node device'; instance name: 093C757B250575F9.
I (8336) chip[DIS]: mDNS service published: _matterc._udp
I (8346) chip[SVR]: Device completed Rendezvous process
I (8316) chip[DL]: Confirm received for CHIPoBLE TX characteristic indication (con 1) status= 14
I (8356) CHIP[DL]: Write request received for CHIPoBLE RX characteristic con 1 16
I (8366) chip[EM]: >>> [E:58065r S:40926 M:200157078] (S) Msg RX from 0:FFFFFFFB00000000 [0000] --- Type 0001:02 (IM:ReadRequest)
I (8386) chip[EM]: <<< [E:58065r S:40926 M:202262816] (S) Msg TX to 0:FFFFFFFB00000000 [0000] [BLE] --- Type 0001:05 (IM:ReportData)
I (8396) NimBLE: GATT procedure initiated: indicate;
I (8396) NimBLE: att_handle=18

I (8446) chip[DL]: Confirm received for CHIPoBLE TX characteristic indication (con 1) status= 14
I (8446) CHIP[DL]: Write request received for CHIPoBLE RX characteristic con 1 16
I (8456) chip[EM]: >>> [E:58066r S:40926 M:200157079] (S) Msg RX from 0:FFFFFFFB00000000 [0000] --- Type 0001:02 (IM:ReadRequest)
I (8466) chip[EM]: <<< [E:58066r S:40926 M:202262817] (S) Msg TX to 0:FFFFFFFB00000000 [0000] [BLE] --- Type 0001:05 (IM:ReportData)
I (8476) NimBLE: GATT procedure initiated: indicate;
I (8486) NimBLE: att_handle=18

I (8516) chip[DL]: Confirm received for CHIPoBLE TX characteristic indication (con 1) status= 14
I (8516) CHIP[DL]: Write request received for CHIPoBLE RX characteristic con 1 16
I (8526) chip[EM]: >>> [E:58067r S:40926 M:200157080] (S) Msg RX from 0:FFFFFFFB00000000 [0000] --- Type 0001:02 (IM:ReadRequest)
I (8536) chip[EM]: <<< [E:58067r S:40926 M:202262818] (S) Msg TX to 0:FFFFFFFB00000000 [0000] [BLE] --- Type 0001:05 (IM:ReportData)
I (8546) NimBLE: GATT procedure initiated: indicate;
I (8556) NimBLE: att_handle=18

I (8586) chip[DL]: Confirm received for CHIPoBLE TX characteristic indication (con 1) status= 14
I (8586) CHIP[DL]: Write request received for CHIPoBLE RX characteristic con 1 16
I (8586) chip[EM]: >>> [E:58068r S:40926 M:200157081] (S) Msg RX from 0:FFFFFFFB00000000 [0000] --- Type 0001:02 (IM:ReadRequest)
I (8606) chip[EM]: <<< [E:58068r S:40926 M:202262819] (S) Msg TX to 0:FFFFFFFB00000000 [0000] [BLE] --- Type 0001:05 (IM:ReportData)
I (8616) NimBLE: GATT procedure initiated: indicate;
I (8616) NimBLE: att_handle=18

I (8646) chip[DL]: Confirm received for CHIPoBLE TX characteristic indication (con 1) status= 14
I (8646) CHIP[DL]: Write request received for CHIPoBLE RX characteristic con 1 16
I (8656) chip[EM]: >>> [E:58069r S:40926 M:200157082] (S) Msg RX from 0:FFFFFFFB00000000 [0000] --- Type 0001:02 (IM:ReadRequest)
I (8666) chip[EM]: <<< [E:58069r S:40926 M:202262820] (S) Msg TX to 0:FFFFFFFB00000000 [0000] [BLE] --- Type 0001:05 (IM:ReportData)
I (8676) NimBLE: GATT procedure initiated: indicate;
I (8686) NimBLE: att_handle=18

I (8766) chip[DL]: Confirm received for CHIPoBLE TX characteristic indication (con 1) status= 14
I (8766) CHIP[DL]: Write request received for CHIPoBLE RX characteristic con 1 16
I (8766) chip[EM]: >>> [E:58070r S:40926 M:200157083] (S) Msg RX from 0:FFFFFFFB00000000 [0000] --- Type 0001:02 (IM:ReadRequest)
I (8786) esp_matter_attribute: ********** R : Endpoint 0x0000's Cluster 0x00000030's Attribute 0x00000000 is 0 **********
I (8796) chip[EM]: <<< [E:58070r S:40926 M:202262821] (S) Msg TX to 0:FFFFFFFB00000000 [0000] [BLE] --- Type 0001:05 (IM:ReportData)
I (8806) NimBLE: GATT procedure initiated: indicate;
I (8806) NimBLE: att_handle=18

I (8846) chip[DL]: Confirm received for CHIPoBLE TX characteristic indication (con 1) status= 14
I (8856) NimBLE: GATT procedure initiated: indicate;
I (8856) NimBLE: att_handle=18

I (8896) chip[DL]: Confirm received for CHIPoBLE TX characteristic indication (con 1) status= 14
I (8896) CHIP[DL]: Write request received for CHIPoBLE RX characteristic con 1 16
I (8906) chip[EM]: >>> [E:58071r S:40926 M:200157084] (S) Msg RX from 0:FFFFFFFB00000000 [0000] --- Type 0001:02 (IM:ReadRequest)
I (8916) chip[EM]: <<< [E:58071r S:40926 M:202262822] (S) Msg TX to 0:FFFFFFFB00000000 [0000] [BLE] --- Type 0001:05 (IM:ReportData)
I (8926) NimBLE: GATT procedure initiated: indicate;
I (8936) NimBLE: att_handle=18

I (8966) chip[DL]: Confirm received for CHIPoBLE TX characteristic indication (con 1) status= 14
I (8966) CHIP[DL]: Write request received for CHIPoBLE RX characteristic con 1 16
I (8976) chip[EM]: >>> [E:58072r S:40926 M:200157085] (S) Msg RX from 0:FFFFFFFB00000000 [0000] --- Type 0001:08 (IM:InvokeCommandRequest)
I (8986) esp_matter_command: Received command 0x00000000 for endpoint 0x0000's cluster 0x00000030
I (8996) chip[FS]: GeneralCommissioning: Received ArmFailSafe (60s)
I (8996) esp_matter_attribute: ********** W : Endpoint 0x0000's Cluster 0x00000030's Attribute 0x00000000 is 4 **********
Guru Meditation Error: Core  0 panic'ed (Load access fault). Exception was unhandled.

Stack dump detected
Core  0 register dump:
MEPC    : 0x4200af3a  RA      : 0x4200b3be  SP      : 0x408468c0  GP      : 0x4081ae30
0x4200af3a: $s10__idf_main6MatterO4NodeC12eventHandler4type8endpoint7cluster9attribute5valueyAA0C14AttributeEventO_AA8EndpointVAA7ClusterVs6UInt32VSpySo21esp_matter_attr_val_taGSgtF at ??:?
0x4200b3be: $s10__idf_main8RootNodeV9attribute8identifyACSgyAA20MatterAttributeEventO_AA8EndpointVAA7ClusterVs6UInt32VSpySo21esp_matter_attr_val_taGSgtc_ySo0m1_N0O14identificationO13callback_typeV_s6UInt16Vs5UInt8VA0_tctcfcs5Int32VAtDOAWV_Az2nRSvSgtcfU_ at ??:?

TP      : 0x4080cb4c  T0      : 0x4200fcc4  T1      : 0x0000000f  T2      : 0xffffffff
0x4080cb4c: xQueueGiveFromISR at /Users/jnbra/esp/esp-idf/components/freertos/FreeRTOS-Kernel/queue.c:1347
0x4200fcc4: MatterPostAttributeChangeCallback(chip::app::ConcreteAttributePath const&, unsigned char, unsigned short, unsigned char*) at /Users/jnbra/esp/esp-matter/components/esp_matter/esp_matter_attribute_utils.cpp:2044

S0/FP   : 0x40835394  S1      : 0x00000001  A0      : 0x00000001  A1      : 0x408353b0
A2      : 0x40835bec  A3      : 0x00000000  A4      : 0x40846958  A5      : 0x40834b80
A6      : 0x4200b3e4  A7      : 0x4084f570  S2      : 0x00000000  S3      : 0x40835bec
0x4200b3e4: $s10__idf_main8RootNodeV9attribute8identifyACSgyAA20MatterAttributeEventO_AA8EndpointVAA7ClusterVs6UInt32VSpySo21esp_matter_attr_val_taGSgtc_ySo0m1_N0O14identificationO13callback_typeV_s6UInt16Vs5UInt8VA0_tctcfcs5Int32VAtDOAWV_Az2nRSvSgtcfU_To at ??:?

S4      : 0x40846958  S5      : 0x408353b0  S6      : 0x00000001  S7      : 0x00000000
S8      : 0x00000000  S9      : 0x4213c144  S10     : 0x40846e40  S11     : 0x00000000
T3      : 0x00000024  T4      : 0x00000080  T5      : 0x00000040  T6      : 0xdfffffff
MSTATUS : 0x00001881  MTVEC   : 0x40800001  MCAUSE  : 0x00000005  MTVAL   : 0x00000008
0x40800001: _vector_table at ??:?

MHARTID : 0x00000000

Backtrace:

0x4200af3a in $s10__idf_main6MatterO4NodeC12eventHandler4type8endpoint7cluster9attribute5valueyAA0C14AttributeEventO_AA8EndpointVAA7ClusterVs6UInt32VSpySo21esp_matter_attr_val_taGSgtF ()
#0  0x4200af3a in $s10__idf_main6MatterO4NodeC12eventHandler4type8endpoint7cluster9attribute5valueyAA0C14AttributeEventO_AA8EndpointVAA7ClusterVs6UInt32VSpySo21esp_matter_attr_val_taGSgtF ()
#1  0x4200b3be in $s10__idf_main8RootNodeV9attribute8identifyACSgyAA20MatterAttributeEventO_AA8EndpointVAA7ClusterVs6UInt32VSpySo21esp_matter_attr_val_taGSgtc_ySo0m1_N0O14identificationO13callback_typeV_s6UInt16Vs5UInt8VA0_tctcfcs5Int32VAtDOAWV_Az2nRSvSgtcfU_ ()
Backtrace stopped: frame did not save the PC
ELF file SHA256: 4bb77fb8b

I (2656) esp_core_dump_flash: Save core dump to flash...
I (2662) esp_core_dump_flash: Erase flash 12288 bytes @ 0x3e6000
I (2766) esp_core_dump_flash: Write end offset 0x2684, check sum length 4
I (2766) esp_core_dump_flash: Core dump has been saved to flash.
Rebooting...
ESP-ROM:esp32c6-20220919
Build:Sep 19 2022
rst:0xc (SW_CPU),boot:0xc (SPI_FAST_FLASH_BOOT)
Saved PC:0x4001975a
0x4001975a: software_reset_cpu in ROM

SPIWP:0xee
mode:DIO, clock div:2
load:0x40875720,len:0x1804
load:0x4086c410,len:0xe58
load:0x4086e610,len:0x2e20
entry 0x4086c41a
I (26) boot: ESP-IDF v5.2.1 2nd stage bootloader
I (27) boot: compile time Jun 24 2024 16:08:15
I (28) boot: chip revision: v0.0
I (30) boot.esp32c6: SPI Speed      : 80MHz
I (34) boot.esp32c6: SPI Mode       : DIO
I (39) boot.esp32c6: SPI Flash Size : 4MB
I (44) boot: Enabling RNG early entropy source...
I (50) boot: Partition Table:
I (53) boot: ## Label            Usage          Type ST Offset   Length
I (60) boot:  0 esp_secure_cert  unknown          3f 06 0000d000 00002000
I (68) boot:  1 nvs              WiFi data        01 02 00010000 0000c000
I (75) boot:  2 nvs_keys         NVS keys         01 04 0001c000 00001000
I (83) boot:  3 otadata          OTA data         01 00 0001d000 00002000
I (90) boot:  4 phy_init         RF data          01 01 0001f000 00001000
I (97) boot:  5 ota_0            OTA app          00 10 00020000 001e0000
I (105) boot:  6 ota_1            OTA app          00 11 00200000 001e0000
I (112) boot:  7 fctry            WiFi data        01 02 003e0000 00006000
I (120) boot:  8 coredump         Unknown data     01 03 003e6000 00010000
I (128) boot: End of partition table
I (132) esp_image: segment 0: paddr=00020020 vaddr=42130020 size=3cb28h (248616) map
I (242) esp_image: segment 1: paddr=0005cb50 vaddr=40800000 size=034c8h ( 13512) load
I (250) esp_image: segment 2: paddr=00060020 vaddr=42000020 size=12d4bch (1234108) map
I (753) esp_image: segment 3: paddr=0018d4e4 vaddr=408034c8 size=17164h ( 94564) load
I (798) esp_image: segment 4: paddr=001a4650 vaddr=4081a630 size=04f58h ( 20312) load
I (822) boot: Loaded app from partition at offset 0x20000
I (823) boot: Disabling RNG early entropy source...
I (834) cpu_start: Unicore app
W (844) clk: esp_perip_clk_init() has not been implemented yet
I (850) cpu_start: Pro cpu start user code
I (850) cpu_start: cpu freq: 160000000 Hz
I (850) cpu_start: Application information:
I (853) cpu_start: Project name:     light
I (858) cpu_start: App version:      1.0
I (863) cpu_start: Compile time:     Jun 24 2024 16:07:54
I (869) cpu_start: ELF file SHA256:  4bb77fb8b...
I (874) cpu_start: ESP-IDF:          v5.2.1
I (879) cpu_start: Min chip rev:     v0.0
I (884) cpu_start: Max chip rev:     v0.99
I (888) cpu_start: Chip rev:         v0.0
I (893) heap_init: Initializing. RAM available for dynamic allocation:
I (900) heap_init: At 40830B30 len 0004BAE0 (302 KiB): RAM
I (906) heap_init: At 4087C610 len 00002F54 (11 KiB): RAM
I (913) heap_init: At 50000000 len 00003FE8 (15 KiB): RTCRAM
I (920) spi_flash: detected chip: generic
I (924) spi_flash: flash io: dio
W (927) spi_flash: Detected size(8192k) larger than the size in the binary image header(4096k). Using the size in the binary image header.
W (941) rmt(legacy): legacy driver is deprecated, please migrate to `driver/rmt_tx.h` and/or `driver/rmt_rx.h`
I (952) sleep: Configure to isolate all GPIO pins in sleep state
I (958) sleep: Enable automatic switching of GPIO sleep configuration
I (965) esp_core_dump_flash: Init core dump to flash
I (971) esp_core_dump_flash: Found partition 'coredump' @ 3e6000 65536 bytes
I (988) esp_core_dump_flash: Core dump data checksum is correct
I (988) esp_core_dump_flash: Found core dump 9860 bytes in flash @ 0x3e6000
I (993) coexist: coex firmware version: 77cd7f8
I (998) coexist: coexist rom version 5b8dcfa
I (1003) main_task: Started on CPU0
I (1003) main_task: Calling app_main()
🏎️   Hello, Embedded Swift! (Smart Light)
I (1013) led_driver_ws2812: Initializing light driver
I (1013) led_driver_ws2812: led set r:0, g:0, b:0
I (1043) pp: pp rom version: 5b8dcfa
I (1043) net80211: net80211 rom version: 5b8dcfa
I (1053) wifi:wifi driver task: 4083dac0, prio:23, stack:6656, core=0
I (1053) wifi:wifi firmware version: a9f5b59
I (1053) wifi:wifi certification version: v7.0
I (1063) wifi:config NVS flash: enabled
I (1063) wifi:config nano formating: disabled
I (1063) wifi:mac_version:HAL_MAC_ESP32AX_761,ut_version:N
I (1073) wifi:Init data frame dynamic rx buffer num: 32
I (1073) wifi:Init static rx mgmt buffer num: 5
I (1083) wifi:Init management short buffer num: 32
I (1083) wifi:Init dynamic tx buffer num: 32
I (1093) wifi:Init static tx FG buffer num: 2
I (1093) wifi:Init static rx buffer size: 1700
I (1093) wifi:Init static rx buffer num: 10
I (1103) wifi:Init dynamic rx buffer num: 32
I (1103) wifi_init: rx ba win: 6
I (1113) wifi_init: tcpip mbox: 32
I (1113) wifi_init: udp mbox: 6
I (1113) wifi_init: tcp mbox: 6
I (1123) wifi_init: tcp tx win: 5760
I (1123) wifi_init: tcp rx win: 5760
I (1133) wifi_init: tcp mss: 1440
I (1133) wifi_init: WiFi IRAM OP enabled
I (1133) wifi_init: WiFi RX IRAM OP enabled
I (1163) chip[DL]: NVS set: chip-counters/reboot-count = 5 (0x5)
I (1163) chip[DL]: Real time clock set to 946684800 (0100/00/01 00:00:00 UTC)
I (1163) BLE_INIT: Using main XTAL as clock source
I (1173) BLE_INIT: ble controller commit:[217f1bf]
I (1173) phy_init: phy_version 250,e14681b,Jan 24 2024,17:43:11
I (1233) phy: libbtbb version: 939f79c, Jan 24 2024, 17:43:26
I (1233) NimBLE: GAP procedure initiated: stop advertising.

I (1233) NimBLE: Failed to restore IRKs from store; status=8

I (1243) CHIP[DL]: BLE host-controller synced
I (1743) chip[DL]: Configuring CHIPoBLE advertising (interval 25 ms, connectable)
I (1743) NimBLE: GAP procedure initiated: advertise;
I (1743) NimBLE: disc_mode=2
I (1743) NimBLE:  adv_channel_map=0 own_addr_type=1 adv_filter_policy=0 adv_itvl_min=40 adv_itvl_max=40
I (1753) NimBLE:

I (1763) chip[DL]: CHIPoBLE advertising started
I (1763) chip[DL]: Starting ESP WiFi layer
W (1773) wifi:(bf)761:0x600a7cac:0x01b4b4b0
W (1773) wifi:(agc)0x600a7128:0xd21c9b8a, min.avgNF:0xce->0xd2(dB), RCalCount:0x1c9, min.RRssi:0xb8a(-71.38)
W (1783) wifi:(TB)WDEV_PWR_TB_MCS0:19
W (1783) wifi:(TB)WDEV_PWR_TB_MCS1:19
W (1793) wifi:(TB)WDEV_PWR_TB_MCS2:19
W (1793) wifi:(TB)WDEV_PWR_TB_MCS3:19
W (1793) wifi:(TB)WDEV_PWR_TB_MCS4:19
W (1803) wifi:(TB)WDEV_PWR_TB_MCS5:19
W (1803) wifi:(TB)WDEV_PWR_TB_MCS6:18
W (1803) wifi:(TB)WDEV_PWR_TB_MCS7:18
W (1813) wifi:(TB)WDEV_PWR_TB_MCS8:17
W (1813) wifi:(TB)WDEV_PWR_TB_MCS9:15
W (1813) wifi:(TB)WDEV_PWR_TB_MCS10:15
W (1823) wifi:(TB)WDEV_PWR_TB_MCS11:15
I (1823) wifi:11ax coex: WDEVAX_PTI0(0x55777555), WDEVAX_PTI1(0x00003377).

I (1833) wifi:mode : sta (60:55:f9:f7:29:34)
I (1833) wifi:enable tsf
W (1833) wifi:Haven't to connect to a suitable AP now!
I (1843) chip[DL]: Done driving station state, nothing else to do...
W (1843) wifi:Haven't to connect to a suitable AP now!
I (1853) chip[DL]: Done driving station state, nothing else to do...
I (1863) chip[SVR]: Initializing subscription resumption storage...
I (1863) chip[SVR]: Server initializing...
I (1873) chip[TS]: Last Known Good Time: 2023-10-14T01:16:48
I (1873) chip[DMG]: AccessControl: initializing
I (1883) chip[DMG]: Examples::AccessControlDelegate::Init
I (1893) chip[DMG]: AccessControl: setting
I (1893) chip[DMG]: DefaultAclStorage: initializing
I (1903) chip[DMG]: DefaultAclStorage: 0 entries loaded
I (1913) chip[ZCL]: Using ZAP configuration...
I (1913) esp_matter_cluster: Cluster plugin init common callback
I (1913) chip[DMG]: AccessControlCluster: initializing
I (1923) chip[ZCL]: 0x421357a8ep 0 clus 0x0000_0030 attr 0x0000_0000 not supported
I (1933) chip[ZCL]: Initiating Admin Commissioning cluster.
I (1943) chip[DIS]: Updating services using commissioning mode 1
I (1943) chip[DIS]: CHIP minimal mDNS started advertising.
I (1953) chip[DIS]: Advertise commission parameter vendorID=65521 productID=32768 discriminator=3840/15 cm=1
I (1963) chip[DIS]: CHIP minimal mDNS configured as 'Commissionable node device'; instance name: 8E237CF666682BC5.
I (1973) chip[DIS]: mDNS service published: _matterc._udp
I (1973) chip[IN]: CASE Server enabling CASE session setups
I (1983) chip[SVR]: Joining Multicast groups
I (1993) chip[SVR]: Server Listening...
I (1993) esp_matter_core: Dynamic endpoint 0 added
I (2003) esp_matter_attribute: ********** W : Endpoint 0x0001's Cluster 0x00000003's Attribute 0x00000001 is 0 **********
lightEndpoint.eventHandler:
unknown
0
I (2013) esp_matter_attribute: ********** W : Endpoint 0x0001's Cluster 0x00000004's Attribute 0x00000000 is 128 **********
lightEndpoint.eventHandler:
unknown
128
I (2033) esp_matter_attribute: ********** W : Endpoint 0x0001's Cluster 0x00000004's Attribute 0x0000FFFC is <invalid type: 0> **********
I (2043) esp_matter_attribute: ********** R : Endpoint 0x0001's Cluster 0x00000006's Attribute 0x0000FFFC is 1 **********
I (2053) esp_matter_attribute: ********** R : Endpoint 0x0001's Cluster 0x00000006's Attribute 0x00004003 is 0 **********
I (2063) esp_matter_attribute: ********** R : Endpoint 0x0001's Cluster 0x00000006's Attribute 0x00000000 is 0 **********
I (2073) esp_matter_attribute: ********** R : Endpoint 0x0001's Cluster 0x00000006's Attribute 0x00000000 is 0 **********
I (2093) chip[ZCL]: Endpoint 1 On/off already set to new value
I (2093) esp_matter_attribute: ********** R : Endpoint 0x0001's Cluster 0x00000008's Attribute 0x00000002 is 1 **********
I (2103) esp_matter_attribute: ********** R : Endpoint 0x0001's Cluster 0x00000008's Attribute 0x00000003 is 254 **********
I (2123) esp_matter_attribute: ********** R : Endpoint 0x0001's Cluster 0x00000008's Attribute 0x0000FFFC is 3 **********
I (2133) esp_matter_attribute: ********** R : Endpoint 0x0001's Cluster 0x00000008's Attribute 0x00000000 is 64 **********
I (2143) esp_matter_attribute: ********** R : Endpoint 0x0001's Cluster 0x00000008's Attribute 0x00004000 is 64 **********
I (2153) esp_matter_attribute: ********** W : Endpoint 0x0001's Cluster 0x00000008's Attribute 0x00000000 is 64 **********
lightEndpoint.eventHandler:
levelControl
64
I (2173) led_driver_ws2812: led set r:63, g:63, b:63
I (2173) esp_matter_attribute: ********** R : Endpoint 0x0001's Cluster 0x00000300's Attribute 0x00004010 is 250 **********
I (2183) esp_matter_attribute: ********** R : Endpoint 0x0001's Cluster 0x00000300's Attribute 0x00000007 is 250 **********
I (2203) esp_matter_attribute: ********** R : Endpoint 0x0001's Cluster 0x00000300's Attribute 0x0000400B is 0 **********
I (2213) esp_matter_attribute: ********** R : Endpoint 0x0001's Cluster 0x00000300's Attribute 0x0000400C is 65279 **********
I (2223) esp_matter_attribute: ********** W : Endpoint 0x0001's Cluster 0x00000300's Attribute 0x00000007 is 250 **********
lightEndpoint.eventHandler:
colorControl(colorTemperatureMireds)
250
I (2243) led_driver_ws2812: led set r:63, g:51, b:40
I (2243) esp_matter_attribute: ********** W : Endpoint 0x0001's Cluster 0x00000300's Attribute 0x00000008 is 2 **********
lightEndpoint.eventHandler:
colorControl(colorMode)
2
I (2263) esp_matter_attribute: ********** W : Endpoint 0x0001's Cluster 0x00000300's Attribute 0x00004001 is 2 **********
I (2273) esp_matter_core: Dynamic endpoint 1 added
I (2283) chip[DL]: WIFI_EVENT_STA_START
W (2283) wifi:Haven't to connect to a suitable AP now!
I (2293) chip[DL]: Done driving station state, nothing else to do...
I (2293) chip[DL]: Configuring CHIPoBLE advertising (interval 25 ms, connectable)
I (2303) chip[DL]: Device already advertising, stop active advertisement and restart
I (2313) NimBLE: GAP procedure initiated: stop advertising.

I (2323) NimBLE: GAP procedure initiated: advertise;
I (2323) NimBLE: disc_mode=2
I (2333) NimBLE:  adv_channel_map=0 own_addr_type=1 adv_filter_policy=0 adv_itvl_min=40 adv_itvl_max=40
I (2343) NimBLE:

I (2343) main_task: Returned from app_main()
I (31943) chip[DL]: Configuring CHIPoBLE advertising (interval 500 ms, connectable)
I (31943) chip[DL]: Device already advertising, stop active advertisement and restart
I (31943) NimBLE: GAP procedure initiated: stop advertising.

I (31953) NimBLE: GAP procedure initiated: advertise;
I (31953) NimBLE: disc_mode=2
I (31963) NimBLE:  adv_channel_map=0 own_addr_type=1 adv_filter_policy=0 adv_itvl_min=800 adv_itvl_max=800
I (31973) NimBLE:

Since the ESP32C6 only supports 2.4Ghz I have tried disabling both the 5Ghz and 6Ghz networks on my router but to no avail, I was however able to get it commissioned with Espressif's own matter light example even when the 5Ghz & 6Ghz networks were enabled.

Any help would be greatly appreciated!

farhan-syed commented 5 months ago

I also have this issue. Followed the guide to the dot and unable to connect but ESP Launch Pad works flawlessly.

RaemondBW commented 5 months ago

I got stuck at this point as well. I noticed in the WWDC video that they had pre-connected to Matter. This makes me wonder if this is a known issue.

johankool commented 5 months ago

I was wondering if this perhaps could be due to there not being a Threads Border router in the network?

RaemondBW commented 5 months ago

I have a thread border router on my network and I still have this issue.

rauhul commented 5 months ago

I got stuck at this point as well. I noticed in the WWDC video that they had pre-connected to Matter. This makes me wonder if this is a known issue.

I put together the tutorial while following the exact steps listed in it. The setup I used was an Airport Express (2012), a HomePod (2018) both updated to the latest firmware and an iPhone running the latest version of iOS 17 at the time. All devices were setup from scratch.

Note: I did end up using idf.py erase-flash at least once to restart the paring process from scratch.

The original post in this thread does include a crash in the log which is definitely interesting and not something I encountered.

0x4200af3a: $s10__idf_main6MatterO4NodeC12eventHandler4type8endpoint7cluster9attribute5valueyAA0C14AttributeEventO_AA8EndpointVAA7ClusterVs6UInt32VSpySo21esp_matter_attr_val_taGSgtF at ??:?
0x4200b3be: $s10__idf_main8RootNodeV9attribute8identifyACSgyAA20MatterAttributeEventO_AA8EndpointVAA7ClusterVs6UInt32VSpySo21esp_matter_attr_val_taGSgtc_ySo0m1_N0O14identificationO13callback_typeV_s6UInt16Vs5UInt8VA0_tctcfcs5Int32VAtDOAWV_Az2nRSvSgtcfU_ at ??:?

Hopefully I or someone else can try to find time next week to reproduce this crash and see if it the root issue.

lorenzofiamingo commented 5 months ago

Same problem with same logs here...

anders0nmat commented 4 months ago

I have got the same problem but it seems that the issue is with Swifts automatic resource management.

When running the example, I noticed the message app_main() finished. From the Backtrace i suspect the error to be in this code snippet

struct RootNode {
  init?(attribute: @escaping AttributeCallback, identify: @escaping identifyCallback) {
    [...]

    let context = Context(attribute: attribute, identify: identify)
    withUnsafeMutablePointer(to: &nodeConfig.root_node)
      // Transfer ownership to the node. This is a leak for now, but we don't expect nodes to be created and destroyed repeatedly.
      _ = esp_matter.endpoint.root_node.create(node, $0, 0x00, Unmanaged.passRetained(context).toOpaque())
    }

    [...]
  }
}

(Disclaimer: I don't know anything about this kind of debugging, this is just an uneducated guess based on the readable words in the trace) Because the example finished app_main() without errors, this code is not outright flawed but probably more subtile.

If app_main() finishes, all local variables declared would get wiped, including the app and led-objects. Passing references to these objects (or parts of it) back to the idf-matter library would result in chaos. And indeed, in the Matter-wrapper-code the cleanup is prevented by throwing Unmanaged.passRetained() at everything and a healthy memory leak but it'll be fine-comment.

To get around Swifts Resource Management I just appended a while true { sleep(1) } to the app_main(). After that, i was able to see the glory that is Matter Accessory Connection in HomeKit and finally a working Matter Device from Embedded Swift 😱.

Hope that helps someone.

lorenzofiamingo commented 4 months ago

@anders0nmat makeshift solution is working for me

gracien-app commented 4 months ago

I can also confirm that @anders0nmat's infinite loop solution works on my end.

rauhul commented 4 months ago

@anders0nmat great digging, are you interested in putting a pr for this workaround while we find a better solution?

Note: I think we should keep these crash-related issues open until a real solution is found.