espressif / esp-matter

Espressif's SDK for Matter
Apache License 2.0
694 stars 157 forks source link

switch binding with light, but switch can't control light (CON-543) #440

Closed Wvirgil123 closed 1 year ago

Wvirgil123 commented 1 year ago

switch device : runing light_switch demo light device: runing light demo

  1. commission switch device , node id 0x0123 ( 291 in decimal )
  2. commission light device , node id 0x0124 ( 292 in decimal )
  3. Update the light's acl attribute: accesscontrol write acl '[{"privilege": 5, "authMode": 2, "subjects": [ 112233, 291 ], "targets": null}]' 0x0124 0x0
  4. binding: binding write binding '[{"node":292, "endpoint":1, "cluster":6}]' 0x0123 0x1

switch log: FSend command failure

> I (2492453) app_driver: Toggle button pressed
I (2492453) chip[DIS]: Found an existing secure session to [1:0000000000000124]!
I (2492453) chip[EM]: <<< [E:54804i S:43767 M:52359527] (S) Msg TX to 1:0000000000000124 [A192] --- Type 0001:08 (IM:InvokeCommandRequest)
I (2492473) chip[IN]: (S) Sending msg 52359527 on secure session with LSID: 43767
I (2492673) chip[EM]: >>> [E:54804i S:43767 M:52329957 (Ack:52359527)] (S) Msg RX from 1:0000000000000124 [A192] --- Type 0001:09 (IM:InvokeCommandResponse)
I (2492683) chip[DMG]: Received Command Response Status for Endpoint=1 Cluster=0x0000_0006 Command=0x0000_0002 Status=0xc3
I (2492683) esp_matter_client: FSend command failure
I (2492703) chip[EM]: <<< [E:54804i S:43767 M:52359528 (Ack:52329957)] (S) Msg TX to 1:0000000000000124 [A192] --- Type 0000:10 (SecureChannel:StandaloneAck)
I (2492713) chip[IN]: (S) Sending msg 52359528 on secure session with LSID: 43767

light log:

> I (1226559) chip[EM]: >>> [E:54804r S:60336 M:52359527] (S) Msg RX from 1:0000000000000123 [A192] --- Type 0001:08 (IM:InvokeCommandRequest)
I (1226569) chip[EM]: <<< [E:54804r S:60336 M:52329957 (Ack:52359527)] (S) Msg TX to 1:0000000000000123 [A192] --- Type 0001:09 (IM:InvokeCommandResponse)
I (1226579) chip[IN]: (S) Sending msg 52329957 on secure session with LSID: 60336
I (1226769) chip[EM]: >>> [E:54804r S:60336 M:52359528 (Ack:52329957)] (S) Msg RX from 1:0000000000000123 [A192] --- Type 0000:10 (SecureChannel:StandaloneAck)
shubhamdp commented 1 year ago

@Wvirgil123 Can you please attach the complete logs from light and switch. Also, please share more detail like esp-matter and esp-idf commit's used.

Wvirgil123 commented 1 year ago

esp-idf: v5.0 esp-matter: 2f0929e5f8fd58b1a4cbaa2bd8b171ce50ad2a75 device: esp32s3

I'll try again later, and I'll be able to toggle the light via switch. and I have to restart the lights before they can establish a connection.

switch logs

I (25) boot: ESP-IDF v5.0-322-g6181cc6868 2nd stage bootloader
I (25) boot: compile time 16:26:04
I (25) boot: chip revision: v0.1
I (28) boot_comm: chip revision: 1, min. bootloader chip revision: 0
I (35) boot.esp32s3: Boot SPI Speed : 80MHz
I (40) boot.esp32s3: SPI Mode       : DIO
I (44) boot.esp32s3: SPI Flash Size : 4MB
I (49) boot: Enabling RNG early entropy source...
I (55) boot: Partition Table:
I (58) boot: ## Label            Usage          Type ST Offset   Length
I (65) boot:  0 esp_secure_cert  unknown          3f 06 0000d000 00002000
I (73) boot:  1 nvs              WiFi data        01 02 00010000 00006000
I (80) boot:  2 nvs_keys         NVS keys         01 04 00016000 00001000
I (88) boot:  3 otadata          OTA data         01 00 00017000 00002000
I (95) boot:  4 phy_init         RF data          01 01 00019000 00001000
I (103) boot:  5 ota_0            OTA app          00 10 00020000 001e0000
I (110) boot:  6 ota_1            OTA app          00 11 00200000 001e0000
I (118) boot:  7 fctry            WiFi data        01 02 003e0000 00006000
I (125) boot: End of partition table
I (130) boot_comm: chip revision: 1, min. application chip revision: 0
I (137) esp_image: segment 0: paddr=00020020 vaddr=3c0f0020 size=37068h (225384) map
I (186) esp_image: segment 1: paddr=00057090 vaddr=3fc98f00 size=050b0h ( 20656) load
I (195) esp_image: segment 2: paddr=0005c148 vaddr=40374000 size=03ed0h ( 16080) load
I (199) esp_image: segment 3: paddr=00060020 vaddr=42000020 size=e2eb4h (929460) map
I (368) esp_image: segment 4: paddr=00142edc vaddr=40377ed0 size=10f74h ( 69492) load
I (392) boot: Loaded app from partition at offset 0x20000
I (392) boot: Disabling RNG early entropy source...
I (404) cpu_start: Pro cpu up.
I (404) cpu_start: Starting app cpu, entry point is 0x40375504
0x40375504: call_start_cpu1 at /Users/virgil/seeed/SenseCAP_Terminal_ESP32/code/esp-idf/components/esp_system/port/cpu_start.c:142

I (0) cpu_start: App cpu up.
I (418) cpu_start: Pro cpu start user code
I (418) cpu_start: cpu freq: 160000000 Hz
I (419) cpu_start: Application information:
I (421) cpu_start: Project name:     light_switch
I (427) cpu_start: App version:      v1.0
I (432) cpu_start: Compile time:     Jun  5 2023 16:39:24
I (438) cpu_start: ELF file SHA256:  badfeb69e3fba67f...
I (444) cpu_start: ESP-IDF:          v5.0-322-g6181cc6868
I (450) heap_init: Initializing. RAM available for dynamic allocation:
I (457) heap_init: At 3FCAE428 len 0003B2E8 (236 KiB): D/IRAM
I (463) heap_init: At 3FCE9710 len 00005724 (21 KiB): STACK/DRAM
I (470) heap_init: At 3FCF0000 len 00008000 (32 KiB): DRAM
I (476) heap_init: At 600FE010 len 00001FF0 (7 KiB): RTCRAM
I (483) spi_flash: detected chip: winbond
I (487) spi_flash: flash io: dio
W (491) spi_flash: Detected size(8192k) larger than the size in the binary image header(4096k). Using the size in the binary image header.
I (506) coexist: coexist rom version e7ae62f
I (510) cpu_start: Starting scheduler on PRO CPU.
I (0) cpu_start: Starting scheduler on APP CPU.
I (630) gpio: GPIO[38]| InputEn: 1| OutputEn: 0| OpenDrain: 0| Pullup: 1| Pulldown: 0| Intr:0 
I (630) app_main: Switch created with endpoint_id 1
I (640) pp: pp rom version: e7ae62f
I (640) net80211: net80211 rom version: e7ae62f
I (650) wifi:wifi driver task: 3fcf7630, prio:23, stack:6656, core=0
I (650) system_api: Base MAC address is not set
I (650) system_api: read default base MAC address from EFUSE
I (670) wifi:wifi firmware version: aa12444
I (670) wifi:wifi certification version: v7.0
I (670) wifi:config NVS flash: enabled
I (670) wifi:config nano formating: disabled
I (670) wifi:Init data frame dynamic rx buffer num: 32
I (680) wifi:Init management frame dynamic rx buffer num: 32
I (680) wifi:Init management short buffer num: 32
I (690) wifi:Init dynamic tx buffer num: 32
I (690) wifi:Init static tx FG buffer num: 2
I (690) wifi:Init static rx buffer size: 1600
I (700) wifi:Init static rx buffer num: 10
I (700) wifi:Init dynamic rx buffer num: 32
I (710) wifi_init: rx ba win: 6
I (710) wifi_init: tcpip mbox: 32
I (710) wifi_init: udp mbox: 6
I (720) wifi_init: tcp mbox: 6
I (720) wifi_init: tcp tx win: 5744
I (730) wifi_init: tcp rx win: 5744
I (730) wifi_init: tcp mss: 1440
I (730) wifi_init: WiFi IRAM OP enabled
I (740) wifi_init: WiFi RX IRAM OP enabled
I (770) chip[DL]: NVS set: chip-counters/reboot-count = 21 (0x15)
I (770) CHIP[DL]: WiFi station already provisioned, not initializing BLE
I (770) chip[DL]: Real time clock set to 946684800 (0100/00/01 00:00:00 UTC)
I (780) chip[DL]: Starting ESP WiFi layer
I (780) phy_init: phy_version 540,a5d905b,Oct 20 2022,19:36:11
I (830) wifi:mode : sta (f4:12:fa:cf:34:ec)
I (830) wifi:enable tsf
W (830) wifi:Haven't to connect to a suitable AP now!
I (830) chip[DL]: Attempting to connect WiFi station interface
I (830) chip[DL]: WiFi station state change: NotConnected -> Connecting
I (840) chip[DL]: Done driving station state, nothing else to do...
I (850) chip[SVR]: Initializing subscription resumption storage...
I (860) chip[SVR]: Server initializing...
I (860) chip[TS]: Last Known Good Time: 2023-06-05T16:40:38
I (890) chip[FP]: Fabric index 0x2 was retrieved from storage. Compressed FabricId 0xB45E93CB15D4A192, FabricId 0x0000000000000001, NodeId 0x0000000000000123, VendorId 0xFFF1
I (890) chip[DMG]: AccessControl: initializing
I (900) chip[DMG]: Examples::AccessControlDelegate::Init
I (900) chip[DMG]: AccessControl: setting
I (910) chip[DMG]: DefaultAclStorage: initializing
I (910) chip[DMG]: DefaultAclStorage: 1 entries loaded
I (950) chip[ZCL]: Using ZAP configuration...
I (950) esp_matter_cluster: Cluster plugin init common callback
I (950) chip[DMG]: AccessControlCluster: initializing
I (950) chip[ZCL]: 0x3c0fcdc8ep 0 clus 0x0000_0030 attr 0x0000_0000 not supported
I (960) chip[ZCL]: Initiating Admin Commissioning cluster.
E (970) chip[ZCL]: Duplicate attribute override registration failed
I (970) chip[SVR]: Fabric already commissioned. Disabling BLE advertisement
I (980) chip[IN]: CASE Server enabling CASE session setups
I (990) chip[SVR]: Joining Multicast groups
I (990) chip[SVR]: Server Listening...
I (1000) esp_matter_core: Dynamic endpoint 0 added
I (1000) esp_matter_attribute: ********** W : Endpoint 0x0001's Cluster 0x00000003's Attribute 0x00000001 is 0 **********
I (1010) esp_matter_attribute: ********** W : Endpoint 0x0001's Cluster 0x00000004's Attribute 0x00000000 is 128 **********
I (1030) esp_matter_attribute: ********** W : Endpoint 0x0001's Cluster 0x00000004's Attribute 0x0000FFFC is <invalid type: 0> **********
I (1040) esp_matter_core: Dynamic endpoint 1 added
I (1050) chip[DL]: WIFI_EVENT_STA_START
W (1050) wifi:Haven't to connect to a suitable AP now!
I (1050) chip[DL]: Attempting to connect WiFi station interface
E (1070) wifJ��W (1070) wifi:Haven't to connect to a suitable AP now!
E (1070) chip[DL]: Failed to get configured network when updating network status: Error ESP32:0x0500300F
> I (3240) wifi:new:<6,2>, old:<1,0>, ap:<255,255>, sta:<6,2>, prof:1
I (3250) wifi:state: init -> auth (b0)
I (3250) wifi:state: auth -> assoc (0)
I (3290) wifi:state: assoc -> run (10)
I (3580) wifi:<ba-add>idx:0 (ifx:0, 34:f7:16:dd:aa:77), tid:0, ssn:1318, winSize:64
I (3590) wifi:connected with M2-TEST, aid = 4, channel 6, 40D, bssid = 34:f7:16:dd:aa:77
I (3600) wifi:security: WPA2-PSK, phy: bgn, rssi: -82
I (3600) wifi:pm start, type: 1

I (3600) wifi:set rx beacon pti, rx_bcn_pti: 14, bcn_timeout: 14, mt_pti: 25000, mt_time: 10000
I (3610) chip[DL]: WIFI_EVENT_STA_CONNECTED
I (3620) chip[DL]: WiFi station state change: Connecting -> Connecting_Succeeded
I (3620) chip[DL]: WiFi station state change: Connecting_Succeeded -> Connected
I (3630) chip[DL]: WiFi station interface connected
I (3630) chip[ZCL]: WiFiDiagnosticsDelegate: OnConnectionStatusChanged
I (3650) chip[DL]: Done driving station state, nothing else to do...
I (3640) wifi:BcnInt:102400, DTIM:1
I (3650) chip[DL]: Updating advertising data
I (3740) wifi:<ba-del>idx
I (4610) esp_netif_handlers: sta ip: 192.168.8.103, mask: 255.255.255.0, gw: 192.168.8.1
I (4610) chip[DL]: IP_EVENT_STA_GOT_IP
I (4610) chip[DL]: IPv4 address changed on WiFi station interface: 192.168.8.103/255.255.255.0 gateway 192.168.8.1
I (4620) chip[DL]: IPv4 Internet connectivity ESTABLISHED
I (4630) app_main: Interface IP Address Changed
I (4630) chip[DIS]: Updating services using commissioning mode 0
I (4650) chip[DIS]: CHIP minimal mDNS started advertising.
I (4650) chip[DIS]: Advertise operational node B45E93CB15D4A192-0000000000000123
I (4650) chip[DIS]: CHIP minimal mDNS configured as 'Operational device'; instance name: B45E93CB15D4A192-0000000000000123.
I (4670) chip[DIS]: mDNS service published: _matter._tcp
I (4670) chip[DL]: IP_EVENT_GOT_IP6
I (4680) chip[DL]: IPv6 addr available. Ready on WIFI_STA_DEF interface: fe80:0000:0000:0000:f612:faff:fecf:34ec
I (4700) chip[DIS]: Updating services using commissioning mode 0
I (4700) chip[DIS]: CHIP minimal mDNS started advertising.
I (4710) chip[DIS]: Advertise operational node B45E93CB15D4A192-0000000000000123
I (4710) chip[DIS]: CHIP minimal mDNS configured as 'Operational device'; instance name: B45E93CB15D4A192-0000000000000123.
I (4730) chip[DIS]: mDNS service published: _matter._tcp
E (4730) chip[SVR]: Server initialization complete
I (4730) app_main: Interface IP Address Changed
I (4740) chip[DIS]: Updating services using commissioning mode 0
I (4740) chip[DIS]: CHIP minimal mDNS started advertising.
I (4770) chip[DIS]: Advertise operational node B45E93CB15D4A192-0000000000000123
I (4770) chip[DIS]: CHIP minimal mDNS configured as 'Operational device'; instance name: B45E93CB15D4A192-0000000000000123.
I (4790) chip[DIS]: mDNS service published: _matter._tcp
I (4790) chip[IM]: No subscriptions to resume
I (5650) ROUTE_HOOK: Received RIO
I (5650) ROUTE_HOOK: prefix FDA8:7D64:A257:: lifetime 1800
I (6930) chip[DIS]: Checking node lookup status after 200 ms
I (7640) chip[DL]: IP_EVENT_GOT_IP6
I (7640) chip[DL]: IPv6 addr available. Ready on WIFI_STA_DEF interface: fd14:5b11:c7f3:42ec:f612:faff:fecf:34ec
I (7650) ROUTE_HOOK: Hook already installed on netif, skip...
I (7650) app_main: Interface IP Address Changed
I (7660) chip[DIS]: Updating services using commissioning mode 0
I (7670) chip[DIS]: CHIP minimal mDNS started advertising.
I (7680) chip[DIS]: Advertise operational node B45E93CB15D4A192-0000000000000123
I (7680) chip[DIS]: CHIP minimal mDNS configured as 'Operational device'; instance name: B45E93CB15D4A192-0000000000000123.
I (7700) chip[DIS]: mDNS service published: _matter._tcp
I (10000) ROUTE_HOOK: Received RIO
I (10000) ROUTE_HOOK: prefix FDA8:7D64:A257:: lifetime 1800
I (14400) ROUTE_HOOK: Received RIO
I (14400) ROUTE_HOOK: prefix FDA8:7D64:A257:: lifetime 1800
I (19110) ROUTE_HOOK: Received RIO
I (19110) ROUTE_HOOK: prefix FDA8:7D64:A257:: lifetime 1800

> 
> E (36310) chip[IN]: Data received on an unknown session (LSID=62377). Dropping it!
E (36630) chip[IN]: Data received on an unknown session (LSID=62377). Dropping it!
E (37030) chip[IN]: Data received on an unknown session (LSID=62377). Dropping it!
E (37540) chip[IN]: Data received on an unknown session (LSID=62377). Dropping it!
E (37730) chip[DIS]: Timeout waiting for mDNS resolution.
E (38460) chip[IN]: Data received on an unknown session (LSID=62377). Dropping it!
I (46960) chip[EM]: >>> [E:25539r S:0 M:46321653] (U) Msg RX from 0:8F656CE23D7D03CC [0000] --- Type 0000:30 (SecureChannel:CASE_Sigma1)
I (46970) chip[IN]: CASE Server received Sigma1 message . Starting handshake. EC 0x3fca4fa8
I (46980) chip[IN]: CASE Server disabling CASE session setups
I (46990) chip[EM]: <<< [E:25539r S:0 M:159393701 (Ack:46321653)] (U) Msg TX to 0:0000000000000000 [0000] --- Type 0000:10 (SecureChannel:StandaloneAck)
I (47000) chip[IN]: (U) Sending msg 159393701 to IP address 'UDP:[FE80::17:2EDB:8BDF:3BF6%st1]:49218'
I (47010) chip[SC]: Received Sigma1 msg
I (47020) chip[EM]: <<< [E:25539r S:0 M:159393702 (Ack:46321653)] (U) Msg TX to 0:0000000000000000 [0000] --- Type 0000:33 (SecureChannel:CASE_Sigma2Resume)
I (47040) chip[IN]: (U) Sending msg 159393702 to IP address 'UDP:[FE80::17:2EDB:8BDF:3BF6%st1]:49218'
E (47050) chip[IN]: Secure transport received message on a session in an invalid state (state = 'kEstablishing')
I (47370) chip[IN]: (U) Sending msg 159393702 to IP address 'UDP:[FE80::17:2EDB:8BDF:3BF6%st1]:49218'
I (47390) chip[EM]: >>> [E:25539r S:0 M:46321655 (Ack:159393702)] (U) Msg RX from 0:8F656CE23D7D03CC [0000] --- Type 0000:10 (SecureChannel:StandaloneAck)
I (47410) chip[EM]: >>> [E:25539r S:0 M:46321654 (Ack:159393702)] (U) Msg RX from 0:8F656CE23D7D03CC [0000] --- Type 0000:40 (SecureChannel:StatusReport)
I (47420) chip[SC]: Success status report received. Session was established
I (47470) chip[SC]: SecureSession[0x3fca36f0]: Moving from state 'kEstablishing' --> 'kActive'
I (47480) chip[IN]: CASE Session established to peer: <000000000001B669, 2>
I (47490) chip[IN]: CASE Server enabling CASE session setups
I (47490) chip[EM]: <<< [E:25539r S:0 M:159393703 (Ack:46321654)] (U) Msg TX to 0:0000000000000000 [0000] --- Type 0000:10 (SecureChannel:StandaloneAck)
I (47500) chip[IN]: (U) Sending msg 159393703 to IP address 'UDP:[FE80::17:2EDB:8BDF:3BF6%st1]:49218'
I (47520) chip[EM]: >>> [E:25540r S:10175 M:214037480] (S) Msg RX from 2:000000000001B669 [A192] --- Type 0001:02 (IM:ReadRequest)
I (47530) chip[EM]: <<< [E:25540r S:10175 M:107114666 (Ack:214037480)] (S) Msg TX to 2:000000000001B669 [A192] --- Type 0001:05 (IM:ReportData)
I (47550) chip[IN]: (S) Sending msg 107114666 on secure session with LSID: 10175
I (47560) chip[EM]: >>> [E:25540r S:10175 M:214037481 (Ack:107114666)] (S) Msg RX from 2:000000000001B669 [A192] --- Type 0000:10 (SecureChannel:StandaloneAck)
I (51730) chip[DIS]: Checking node lookup status after 45000 ms
E (51730) chip[DIS]: OperationalSessionSetup[2:0000000000000124]: operational discovery failed: 32
E (51750) chip[SVR]: Failed to establish connection to node 0x0000000000000124
I (60170) chip[EM]: >>> [E:25541r S:10175 M:214037482] (S) Msg RX from 2:000000000001B669 [A192] --- Type 0001:06 (IM:WriteRequest)
I (60220) chip[EM]: <<< [E:25541r S:10175 M:107114667 (Ack:214037482)] (S) Msg TX to 2:000000000001B669 [A192] --- Type 0001:07 (IM:WriteResponse)
I (60240) chip[IN]: (S) Sending msg 107114667 on secure session with LSID: 10175
I (60250) chip[EM]: >>> [E:25541r S:10175 M:214037483 (Ack:107114667)] (S) Msg RX from 2:000000000001B669 [A192] --- Type 0000:10 (SecureChannel:StandaloneAck)
I (60420) chip[DIS]: Checking node lookup status after 200 ms
I (68310) app_driver: Toggle button pressed
I (78160) chip[DIS]: UDP:[FE80::F612:FAFF:FECF:34F8%st1]:5540: new best score: 3
I (78160) chip[DIS]: UDP:192.168.8.106%st1:5540: score has not improved: 2
I (78170) chip[DIS]: Checking node lookup status after 17953 ms
I (78180) chip[SC]: Initiating session on local FabricIndex 2 from 0x0000000000000123 -> 0x0000000000000124
I (78260) chip[EM]: <<< [E:54278i S:0 M:159393704] (U) Msg TX to 0:0000000000000000 [0000] --- Type 0000:30 (SecureChannel:CASE_Sigma1)
I (78260) chip[IN]: (U) Sending msg 159393704 to IP address 'UDP:[FE80::F612:FAFF:FECF:34F8%st1]:5540'
I (78270) chip[SC]: Sent Sigma1 msg
I (78400) chip[EM]: >>> [E:54278i S:0 M:247772399 (Ack:159393704)] (U) Msg RX from 0:0000000000000000 [0000] --- Type 0000:10 (SecureChannel:StandaloneAck)
I (78420) chip[EM]: >>> [E:54278i S:0 M:247772400 (Ack:159393704)] (U) Msg RX from 0:0000000000000000 [0000] --- Type 0000:33 (SecureChannel:CASE_Sigma2Resume)
I (78430) chip[EM]: <<< [E:54278i S:0 M:159393705 (Ack:247772400)] (U) Msg TX to 0:0000000000000000 [0000] --- Type 0000:10 (SecureChannel:StandaloneAck)
I (78450) chip[IN]: (U) Sending msg 159393705 to IP address 'UDP:[FE80::F612:FAFF:FECF:34F8%st1]:5540'
I (78500) chip[EM]: <<< [E:54278i S:0 M:159393706 (Ack:247772400)] (U) Msg TX to 0:0000000000000000 [0000] --- Type 0000:40 (SecureChannel:StatusReport)
I (78520) chip[IN]: (U) Sending msg 159393706 to IP address 'UDP:[FE80::F612:FAFF:FECF:34F8%st1]:5540'
I (78520) chip[SC]: SecureSession[0x3fca3860]: Moving from state 'kEstablishing' --> 'kActive'
I (78540) chip[EM]: <<< [E:54279i S:10177 M:45334608] (S) Msg TX to 2:0000000000000124 [A192] --- Type 0001:08 (IM:InvokeCommandRequest)
I (78550) chip[IN]: (S) Sending msg 45334608 on secure session with LSID: 10177
I (78920) chip[IN]: (U) Sending msg 159393706 to IP address 'UDP:[FE80::F612:FAFF:FECF:34F8%st1]:5540'
I (78930) chip[IN]: (S) Sending msg 45334608 on secure session with LSID: 10177
I (79110) chip[EM]: >>> [E:54278i S:0 M:247772401 (Ack:159393706)] (U) Msg RX from 0:0000
> 
> 
> 
> 
> I (106530) app_driver: Toggle button pressed
I (106530) chip[DIS]: Found an existing secure session to [2:0000000000000124]!
I (106530) chip[EM]: <<< [E:54280i S:10177 M:45334610] (S) Msg TX to 2:0000000000000124 [A192] --- Type 0001:08 (IM:InvokeCommandRequest)
I (106540) chip[IN]: (S) Sending msg 45334610 on secure session with LSID: 10177
I (106870) chip[EM]: >>> [E:54280i S:10177 M:166260950 (Ack:45334610)] (S) Msg RX from 2:0000000000000124 [A192] --- Type 0001:09 (IM:InvokeCommandResponse)
I (106880) chip[DMG]: Received Command Response Status for Endpoint=1 Cluster=0x0000_0006 Command=0x0000_0002 Status=0x0
I (106880) esp_matter_client: Send command success
I (106890) chip[EM]: <<< [E:54280i S:10177 M:45334611 (Ack:166260950)] (S) Msg TX to 2:0000000000000124 [A192] --- Type 0000:10 (SecureChannel:StandaloneAck)
I (106910) chip[IN]: (S) Sending msg 45334611 on secure session with LSID: 10177

> 
> I (111110) app_driver: Toggle button pressed
I (111110) chip[DIS]: Found an existing secure session to [2:0000000000000124]!
I (111110) chip[EM]: <<< [E:54281i S:10177 M:45334612] (S) Msg TX to 2:0000000000000124 [A192] --- Type 0001:08 (IM:InvokeCommandRequest)
I (111120) chip[IN]: (S) Sending msg 45334612 on secure session with LSID: 10177
I (111370) chip[EM]: >>> [E:54281i S:10177 M:166260951 (Ack:45334612)] (S) Msg RX from 2:0000000000000124 [A192] --- Type 0001:09 (IM:InvokeCommandResponse)
I (111380) chip[DMG]: Received Command Response Status for Endpoint=1 Cluster=0x0000_0006 Command=0x0000_0002 Status=0x0
I (111390) esp_matter_client: Send command success
I (111400) chip[EM]: <<< [E:54281i S:10177 M:45334613 (Ack:166260951)] (S) Msg TX to 2:0000000000000124 [A192] --- Type 0000:10 (SecureChannel:StandaloneAck)
I (111410) chip[IN]: (S) Sending msg 45334613 on secure session with LSID: 10177
dhairyashah1 commented 1 year ago

@Wvirgil123 I was able to run the light and light_switch examples successfully with toggling the light's onoff state using the BOOT button on the light_switch on both esp32c3 and esp32s3 with the latest mentioned versions of esp-idf and esp-matter in the docs. Could you please update to the following versions, the submodules as well and retry?

dhrishi commented 1 year ago

@Wvirgil123 Closing as it is working fine as mentioned above. Please check your setup and commands, if you are still seeing an issue

goloveychuk commented 1 year ago

I had same error

E (51730) chip[DIS]: OperationalSessionSetup[2:0000000000000124]: operational discovery failed: 32
E (51750) chip[SVR]: Failed to establish connection to node 0x0000000000000124

My flow is: 1) build and flash light and switch 2) commission to apple home via Apple tv (thread) 3) enable pairing mode and commission via chip tool (pairing code ID CODE) 4) set ACL and binding 5) get error.

I've fixed it by restarting Apple TV. (after both devices are paired)

It seems like it has bug and server which should resolve node to ip (SRP server) does not work correctly.