Closed 3wnbr1 closed 4 months ago
rs_matter::data_model::objects::encoder: Error invoking command: CmdStatus { path: CmdPath { path: GenericPath { endpoint: Some(0), cluster: Some(49), leaf: Some(2) } }, status: Status { status: UnsupportedCommand, cluster_status: 0 } }`
I am a beginner with Matter but the way I understand the error message is that it points towards the (Root Node 0) Network Commissioning endpoint (49) Thread (2) is not implemented. Looking at the code I can't figure out with my HomePod tried to commission it as a Thread Device
It actually always points to Node 0 (which is not logged, as rs-matter
currently supports only one node)
... then endpoint 0 (the root endpoint)
... then cluster 49 (dec) = 0x0031 (hex) = network commissioning
... then command = 2 (dec) = 0x02 (hec) = "AddOrUpdateWifiNetwork"
... so it calls what it should (which is very good news), but the fact that it fails means I probably regressed the code, because there were upstream merges in rs-matter
, so a had to refactor a bit the code in esp-idf-matter
(blush).
OK - let me try to first reproduce it locally, and then fix it tomorrow. I'll let you know my progress.
@3wnbr1 - I've found the issue and opened a PR against rs-matter
.
However, you don't have to wait until it is merged as esp-idf-matter
uses my own rs-matter
fork for now (where the BLE PR is enabled so that we can pre-test it), where I've applied this fix as well.
Just do cargo update
in your esp-idf-matter
clone. Then re-build and re-flash. That should be good enough.
Please report if you hit further issues. You might have a problem with mDNS further down the line, but I'm not sure. I have such a problem, but it is very intermittent, hence not addressed yet.
Awesome, this specific error is fixed and from the logs it seems that the example running on the ESP32C3 managed to pair to the network 🎉
However I am still unable to get it to pair with HomeKit. I pulled logs my iPhone and found a suspicious error message (after which it aborts the pairing process): Received failure response src/controller/TypedCommandCallback.h:127: CHIP Error 0x0000008E: Schema mismatch
homed
logsdefault 09:36:17.623737+0200 homed Performing next commissioning step 'WiFiNetworkEnable'
default 09:36:17.623864+0200 homed SendCommand kWiFiNetworkEnable, supportsConcurrentConnection=false
default 09:36:17.623220+0200 homed Commissioning stage next step: 'FailsafeBeforeWiFiEnable' -> 'WiFiNetworkEnable'
default 09:36:17.624711+0200 homed <<< [E:38380i S:29140 M:73333980] (S) Msg TX to 0:FFFFFFFB00000000 [0000] [BLE] --- Type 0001:08 (IM:InvokeCommandRequest)
default 09:36:17.623704+0200 homed Setting wifi connection time min = 60
error 09:36:17.625549+0200 homed SendMessage() to BLE failed: src/transport/raw/BLE.cpp:114: Success
default 09:36:17.623831+0200 homed Performing next commissioning step 'WiFiNetworkEnable'
default 09:36:17.623893+0200 homed SendCommand kWiFiNetworkEnable, supportsConcurrentConnection=false
default 09:36:17.625082+0200 homed <<< [E:38380i S:29140 M:73333980] (S) Msg TX to 0:FFFFFFFB00000000 [0000] [BLE] --- Type 0001:08 (IM:InvokeCommandRequest)
error 09:36:17.625576+0200 homed SendMessage() to BLE failed: src/transport/raw/BLE.cpp:114: Success
default 09:36:17.773758+0200 homed >>> [E:38380i S:29140 M:232400453] (S) Msg RX from 0:FFFFFFFB00000000 [0000] --- Type 0001:09 (IM:InvokeCommandResponse)
default 09:36:17.773794+0200 homed >>> [E:38380i S:29140 M:232400453] (S) Msg RX from 0:FFFFFFFB00000000 [0000] --- Type 0001:09 (IM:InvokeCommandResponse)
default 09:36:17.774096+0200 homed Received Command Response Data, Endpoint=0 Cluster=0x0000_0031 Command=0x0000_0005
default 09:36:17.774204+0200 homed Received failure response src/controller/TypedCommandCallback.h:127: CHIP Error 0x0000008E: Schema mismatch
default 09:36:17.774123+0200 homed Received Command Response Data, Endpoint=0 Cluster=0x0000_0031 Command=0x0000_0005
default 09:36:17.774305+0200 homed Received failure response src/controller/TypedCommandCallback.h:127: CHIP Error 0x0000008E: Schema mismatch
error 09:36:17.775094+0200 homed Error on commissioning step 'WiFiNetworkEnable': 'src/controller/TypedCommandCallback.h:127: CHIP Error 0x0000008E: Schema mismatch'
default 09:36:17.775182+0200 homed Going from commissioning step 'WiFiNetworkEnable' with lastErr = 'src/controller/TypedCommandCallback.h:127: CHIP Error 0x0000008E: Schema mismatch' -> 'Cleanup'
error 09:36:17.775060+0200 homed Error on commissioning step 'WiFiNetworkEnable': 'src/controller/TypedCommandCallback.h:127: CHIP Error 0x0000008E: Schema mismatch'
default 09:36:17.775124+0200 homed Going from commissioning step 'WiFiNetworkEnable' with lastErr = 'src/controller/TypedCommandCallback.h:127: CHIP Error 0x0000008E: Schema mismatch' -> 'Cleanup'
default 09:36:17.775249+0200 homed Performing next commissioning step 'Cleanup' with completion status = 'src/controller/TypedCommandCallback.h:127: CHIP Error 0x0000008E: Schema mismatch'
default 09:36:17.775480+0200 homed Successfully finished commissioning step 'Cleanup'
Can you also paste the logs from the esp32 device? Sorry, I don't have a home kit device (yet), so we need to do some remote debugging.
Sure, no worries
ESP-ROM:esp32c3-api1-20210207
Build:Feb 7 2021
rst:0x15 (USB_UART_CHIP_RESET),boot:0xd (SPI_FAST_FLASH_BOOT)
Saved PC:0x40380630
0x40380630 - spiflash_start_default
at /Users/ewen/Downloads/esp-idf-matter/.embuild/espressif/esp-idf/v5.1.2/components/spi_flash/esp_flash_api.c:194
SPIWP:0xee
mode:DIO, clock div:2
load:0x3fcd5820,len:0x1714
load:0x403cc710,len:0x968
load:0x403ce710,len:0x2f9c
entry 0x403cc710
I (24) boot: ESP-IDF v5.1.2-342-gbcf1645e44 2nd stage bootloader
I (24) boot: compile time Dec 12 2023 10:50:58
I (25) boot: chip revision: v0.4
I (29) boot.esp32c3: SPI Speed : 40MHz
I (34) boot.esp32c3: SPI Mode : DIO
I (38) boot.esp32c3: SPI Flash Size : 4MB
I (43) boot: Enabling RNG early entropy source...
I (48) boot: Partition Table:
I (52) boot: ## Label Usage Type ST Offset Length
I (59) boot: 0 nvs WiFi data 01 02 00009000 00006000
I (67) boot: 1 phy_init RF data 01 01 0000f000 00001000
I (74) boot: 2 factory factory app 00 00 00010000 00300000
I (82) boot: End of partition table
I (86) esp_image: segment 0: paddr=00010020 vaddr=3c1c0020 size=7df28h (515880) map
I (209) esp_image: segment 1: paddr=0008df50 vaddr=3fc92e00 size=020c8h ( 8392) load
I (211) esp_image: segment 2: paddr=00090020 vaddr=42000020 size=1b6444h (1795140) map
I (612) esp_image: segment 3: paddr=0024646c vaddr=3fc94ec8 size=0de7ch ( 56956) load
I (627) esp_image: segment 4: paddr=002542f0 vaddr=40380000 size=12c0ch ( 76812) load
I (655) boot: Loaded app from partition at offset 0x10000
I (656) boot: Disabling RNG early entropy source...
I (667) cpu_start: Unicore app
I (667) cpu_start: Pro cpu up.
I (676) cpu_start: Pro cpu start user code
I (676) cpu_start: cpu freq: 160000000 Hz
I (676) cpu_start: Application information:
I (679) cpu_start: Project name: libespidf
I (684) cpu_start: App version: 347b5a5-dirty
I (690) cpu_start: Compile time: May 27 2024 12:15:09
I (696) cpu_start: ELF file SHA256: 0000000000000000...
I (702) cpu_start: ESP-IDF: v5.1.2
I (707) cpu_start: Min chip rev: v0.3
I (711) cpu_start: Max chip rev: v0.99
I (716) cpu_start: Chip rev: v0.4
I (721) heap_init: Initializing. RAM available for dynamic allocation:
I (728) heap_init: At 3FCA7A10 len 000185F0 (97 KiB): DRAM
I (734) heap_init: At 3FCC0000 len 0001C710 (113 KiB): DRAM/RETENTION
I (741) heap_init: At 3FCDC710 len 00002950 (10 KiB): DRAM/RETENTION/STACK
I (749) heap_init: At 50000010 len 00001FD8 (7 KiB): RTCRAM
I (756) spi_flash: detected chip: generic
I (760) spi_flash: flash io: dio
W (764) timer_group: legacy driver is deprecated, please migrate to `driver/gptimer.h`
I (772) sleep: Configure to isolate all GPIO pins in sleep state
I (779) sleep: Enable automatic switching of GPIO sleep configuration
I (786) coexist: coex firmware version: b6d5e8c
I (792) coexist: coexist rom version 9387209
I (797) app_start: Starting scheduler on CPU0
I (801) main_task: Started on CPU0
I (801) main_task: Calling app_main()
I (811) light: Starting...
I (811) esp_idf_matter::stack: Async IO initialized; using `async-io-mini`
I (821) rs_matter_stack::wifible: Matter Stack memory: 52440B
I (831) esp_idf_svc::bt: Init bluetooth controller
I (831) BLE_INIT: BT controller compile version [59725b5]
I (831) BLE_INIT: Bluetooth MAC: dc:da:0c:88:be:92
I (841) esp_idf_svc::bt: Enable bluetooth controller
I (841) phy_init: phy_version 1130,b4e4b80,Sep 5 2023,11:09:30
I (881) esp_idf_svc::bt: Init bluedroid
I (891) esp_idf_svc::bt: Enable bluedroid
I (911) rs_matter_stack::wifible: BLE driver initialized
I (911) rs_matter_stack::wifible: Running Matter in commissioning mode (BLE)
I (911) esp_idf_matter::ble: BLE Gap and Gatts initialized
I (921) esp_idf_matter::ble: BLE Gap and Gatts subscriptions initialized
I (941) esp_idf_matter::ble: Gatts BTP app registered
I (941) rs_matter_stack: Responder memory: Responder=160B, Runner=10496B
I (941) rs_matter::respond: Responder: Creating 4 handlers
I (941) rs_matter::respond: Responder: Handlers size: 7976B
I (951) rs_matter::respond: Busy Responder: Creating 2 handlers
I (961) rs_matter::respond: Busy Responder: Handlers size: 648B
I (971) rs_matter::pairing::code: Pairing Code: 0087-6800-071
I (971) rs_matter::pairing::qr: QR Code Text: MT:Y.K90KQS02Z6Q66D33P084L90Z.I332SQ43I15T0
I (1031) rs_matter::pairing::qr: █████████████████████████████████████
I (1031) rs_matter::pairing::qr: █████████████████████████████████████
I (1051) rs_matter::pairing::qr: ████ ▄▄▄▄▄ █ ▄▄▄ ██▄ █ ▄ █ ▄▄▄▄▄ ████
I (1061) rs_matter::pairing::qr: ████ █ █ █▄▄▀▀▀██▄ ▄ █▄█ █ █ ████
I (1071) rs_matter::pairing::qr: ████ █▄▄▄█ █▄▀▀▀▄█▄ █▀▀ █ █▄▄▄█ ████
I (1081) rs_matter::pairing::qr: ████▄▄▄▄▄▄▄█▄█ █ ▀▄▀ █ ▀▄█▄▄▄▄▄▄▄████
I (1101) rs_matter::pairing::qr: ████ ██ ▄ ▄▄ ▀██▄ ██▀▀ ▄█▄▀▀ ▀▄ ████
I (1111) rs_matter::pairing::qr: ████▀ ▀ █▄▄█▄▀▄▄ █▄ ▀███▀▀ ▄ ▀ ████
I (1121) rs_matter::pairing::qr: ████ ▀▀▀▄▄▄█▀▀ ▄ ▀▄ ▀ █▀ ██ ▄▄▀▀████
I (1131) rs_matter::pairing::qr: ████ ▀█ ▄▄ ▀ ██▀▄█▀▄▀█▀▀▄▀▀ ▄█ █████
I (1151) rs_matter::pairing::qr: ████ ▀█▄▀▄▀▀▀▀█▄▀ █ ▄█▀█▄█▀▄█▀▀▄████
I (1161) rs_matter::pairing::qr: ████ █▀ ▄ ▀▀ █▄█▀▄█▄▄ ▀▄█ ▀█ ▀████
I (1171) rs_matter::pairing::qr: ████▄▄▄███▄█▀▀▀ █▄ ▄▄▀██ ▄▄▄ ▀█▀█████
I (1181) rs_matter::pairing::qr: ████ ▄▄▄▄▄ █ ▄ ▄ █ ▀█▄ ▀ █▄█ █▀ ████
I (1201) rs_matter::pairing::qr: ████ █ █ █ █ █▄▄▄█▄▀█▀ ▄▄ ▄█▄▀▄████
I (1211) rs_matter::pairing::qr: ████ █▄▄▄█ ██▀▀▄▀▄█▄ ▄▀▄▀▄ ▀██▄▄████
I (1221) rs_matter::pairing::qr: ████▄▄▄▄▄▄▄█▄██▄█▄█▄█▄▄▄▄▄█▄▄█▄▄█████
I (1241) rs_matter::pairing::qr: █████████████████████████████████████
I (1251) rs_matter::pairing::qr: █████████████████████████████████████
I (1271) rs_matter::transport::core: Running Matter transport
I (1271) rs_matter::transport::core: Waiting for orphaned RX packets
I (6281) light: Light toggled
I (11281) light: Light toggled
I (14781) rs_matter::transport::network::btp::session:
>>>>> (BTP IO) 7C:95:4D:2F:0E:E8 [H|M|B|E,OP:6c]
HANDSHAKE REQ HandshakeReq { versions: 4, mtu: 517, window_size: 6 }
Selected version: 4, MTU: 244, window size: 6
I (14961) rs_matter::transport::network::btp::context: Subscribe request from 7C:95:4D:2F:0E:E8
I (14971) rs_matter::transport::network::btp::session:
<<<<< (BTP IO) 7C:95:4D:2F:0E:E8 [H|M|B|E,OP:6c]
HANDSHAKE RESP HandshakeResp { version: 4, mtu: 244, window_size: 6 }
I (15021) rs_matter::transport::network::btp::session:
>>>>> (BTP IO) 7C:95:4D:2F:0E:E8 [A|B|E,ACTR:0,CTR:0,LEN:62]
READ 98B
I (15031) rs_matter::transport::session: Creating a new exchange: 95c7/Responder(AcceptPending)
I (15031) rs_matter::transport::core:
>>>>> BTP 7C:95:4D:2F:0E:E8 [S,SID:0,CTR:dff6917,SRC:55c0857e346feccc][I,EID:95c7,PROTO:0,OP:20]
SC::PBKDFParamRequest
=> Processing (new exchange)
I (15051) rs_matter::transport::core: Exchange 0::0: Accepted
I (15061) rs_matter::respond: Responder: Handler 0 / exchange 0::0: Starting
I (15071) rs_matter::transport::exchange:
<<<<< BTP 7C:95:4D:2F:0E:E8 [U,SID:0,CTR:c22091f,DST:55c0857e346feccc][EID:95c7,PROTO:0,OP:21]
SC::PBKDFParamResponse
=> Sending
I (15081) rs_matter::transport::network::btp::session:
<<<<< (BTP IO) 7C:95:4D:2F:0E:E8 [A|B|E,ACTR:0,CTR:1,LEN:8b]
WRITE 139B
I (15141) rs_matter::transport::network::btp::session:
>>>>> (BTP IO) 7C:95:4D:2F:0E:E8 [A|B|E,ACTR:1,CTR:1,LEN:5c]
READ 92B
I (15151) rs_matter::transport::core:
>>>>> BTP 7C:95:4D:2F:0E:E8 [S,SID:0,CTR:dff6918,SRC:55c0857e346feccc][I,EID:95c7,PROTO:0,OP:22]
SC::PASEPake1
=> Processing
I (17391) rs_matter::transport::exchange:
<<<<< BTP 7C:95:4D:2F:0E:E8 [U,SID:0,CTR:c220920,DST:55c0857e346feccc][EID:95c7,PROTO:0,OP:23]
SC::PASEPake2
=> Sending
I (17401) rs_matter::transport::network::btp::session:
<<<<< (BTP IO) 7C:95:4D:2F:0E:E8 [A|B|E,ACTR:1,CTR:2,LEN:7f]
WRITE 127B
I (17411) light: Light toggled
I (17451) rs_matter::transport::network::btp::session:
>>>>> (BTP IO) 7C:95:4D:2F:0E:E8 [A|B|E,ACTR:2,CTR:2,LEN:3b]
READ 59B
I (17461) rs_matter::transport::core:
>>>>> BTP 7C:95:4D:2F:0E:E8 [S,SID:0,CTR:dff6919,SRC:55c0857e346feccc][I,EID:95c7,PROTO:0,OP:24]
SC::PASEPake3
=> Processing
I (17481) rs_matter::transport::exchange:
<<<<< BTP 7C:95:4D:2F:0E:E8 [U,SID:0,CTR:c220921,DST:55c0857e346feccc][EID:95c7,PROTO:0,OP:40]
SC::StatusReport
=> Sending
I (17491) rs_matter::respond: Responder: Handler 0 / exchange 0::0: Completed
I (17491) rs_matter::transport::network::btp::session:
<<<<< (BTP IO) 7C:95:4D:2F:0E:E8 [A|B|E,ACTR:2,CTR:3,LEN:1e]
WRITE 30B
I (17571) rs_matter::transport::network::btp::session:
>>>>> (BTP IO) 7C:95:4D:2F:0E:E8 [A|B|E,ACTR:3,CTR:3,LEN:33]
READ 51B
I (17581) rs_matter::transport::session: Creating a new exchange: 95c8/Responder(AcceptPending)
I (17581) rs_matter::transport::core:
>>>>> BTP 7C:95:4D:2F:0E:E8 [SID:1,CTR:8dc488e][I,EID:95c8,PROTO:1,OP:2]
IM::ReadRequest
=> Processing (new exchange)
I (17601) rs_matter::transport::core: Exchange 1::0: Accepted
I (17601) rs_matter::respond: Responder: Handler 0 / exchange 1::0: Starting
I (17621) rs_matter::transport::exchange:
<<<<< BTP 7C:95:4D:2F:0E:E8 [SID:71d3,CTR:7433736][EID:95c8,PROTO:1,OP:5]
IM::ReportData
=> Sending
I (17631) rs_matter::respond: Responder: Handler 0 / exchange 1::0: Completed
I (17641) rs_matter::transport::network::btp::session:
<<<<< (BTP IO) 7C:95:4D:2F:0E:E8 [A|B|E,ACTR:3,CTR:4,LEN:41]
WRITE 65B
I (17691) rs_matter::transport::network::btp::session:
>>>>> (BTP IO) 7C:95:4D:2F:0E:E8 [A|B|E,ACTR:4,CTR:4,LEN:33]
READ 51B
I (17701) rs_matter::transport::session: Creating a new exchange: 95c9/Responder(AcceptPending)
I (17701) rs_matter::transport::core:
>>>>> BTP 7C:95:4D:2F:0E:E8 [SID:1,CTR:8dc488f][I,EID:95c9,PROTO:1,OP:2]
IM::ReadRequest
=> Processing (new exchange)
I (17721) rs_matter::transport::core: Exchange 1::1: Accepted
I (17721) rs_matter::respond: Responder: Handler 0 / exchange 1::1: Starting
I (17741) rs_matter::transport::exchange:
<<<<< BTP 7C:95:4D:2F:0E:E8 [SID:71d3,CTR:7433737][EID:95c9,PROTO:1,OP:5]
IM::ReportData
=> Sending
I (17751) rs_matter::respond: Responder: Handler 0 / exchange 1::1: Completed
I (17761) rs_matter::transport::network::btp::session:
<<<<< (BTP IO) 7C:95:4D:2F:0E:E8 [A|B|E,ACTR:4,CTR:5,LEN:53]
WRITE 83B
I (17811) rs_matter::transport::network::btp::session:
>>>>> (BTP IO) 7C:95:4D:2F:0E:E8 [A|B|E,ACTR:5,CTR:5,LEN:34]
READ 52B
I (17821) rs_matter::transport::session: Creating a new exchange: 95ca/Responder(AcceptPending)
I (17821) rs_matter::transport::core:
>>>>> BTP 7C:95:4D:2F:0E:E8 [SID:1,CTR:8dc4890][I,EID:95ca,PROTO:1,OP:2]
IM::ReadRequest
=> Processing (new exchange)
I (17841) rs_matter::transport::core: Exchange 1::2: Accepted
I (17841) rs_matter::respond: Responder: Handler 0 / exchange 1::2: Starting
I (17861) rs_matter::transport::exchange:
<<<<< BTP 7C:95:4D:2F:0E:E8 [SID:71d3,CTR:7433738][EID:95ca,PROTO:1,OP:5]
IM::ReportData
=> Sending
I (17871) rs_matter::respond: Responder: Handler 0 / exchange 1::2: Completed
I (17881) rs_matter::transport::network::btp::session:
<<<<< (BTP IO) 7C:95:4D:2F:0E:E8 [A|B|E,ACTR:5,CTR:6,LEN:40]
WRITE 64B
I (17961) rs_matter::transport::network::btp::session:
>>>>> (BTP IO) 7C:95:4D:2F:0E:E8 [A|B|E,ACTR:6,CTR:6,LEN:33]
READ 51B
I (17971) rs_matter::transport::session: Creating a new exchange: 95cb/Responder(AcceptPending)
I (17981) rs_matter::transport::core:
>>>>> BTP 7C:95:4D:2F:0E:E8 [SID:1,CTR:8dc4891][I,EID:95cb,PROTO:1,OP:2]
IM::ReadRequest
=> Processing (new exchange)
I (17991) rs_matter::transport::core: Exchange 1::3: Accepted
I (17991) rs_matter::respond: Responder: Handler 0 / exchange 1::3: Starting
I (18011) rs_matter::transport::exchange:
<<<<< BTP 7C:95:4D:2F:0E:E8 [SID:71d3,CTR:7433739][EID:95cb,PROTO:1,OP:5]
IM::ReportData
=> Sending
I (18021) rs_matter::respond: Responder: Handler 0 / exchange 1::3: Completed
I (18031) rs_matter::transport::network::btp::session:
<<<<< (BTP IO) 7C:95:4D:2F:0E:E8 [A|B|E,ACTR:6,CTR:7,LEN:3f]
WRITE 63B
I (18081) rs_matter::transport::network::btp::session:
>>>>> (BTP IO) 7C:95:4D:2F:0E:E8 [A|B|E,ACTR:7,CTR:7,LEN:34]
READ 52B
I (18091) rs_matter::transport::session: Creating a new exchange: 95cc/Responder(AcceptPending)
I (18091) rs_matter::transport::core:
>>>>> BTP 7C:95:4D:2F:0E:E8 [SID:1,CTR:8dc4892][I,EID:95cc,PROTO:1,OP:2]
IM::ReadRequest
=> Processing (new exchange)
I (18111) rs_matter::transport::core: Exchange 1::4: Accepted
I (18111) rs_matter::respond: Responder: Handler 0 / exchange 1::4: Starting
I (18131) rs_matter::transport::exchange:
<<<<< BTP 7C:95:4D:2F:0E:E8 [SID:71d3,CTR:743373a][EID:95cc,PROTO:1,OP:5]
IM::ReportData
=> Sending
I (18141) rs_matter::respond: Responder: Handler 0 / exchange 1::4: Completed
I (18151) rs_matter::transport::network::btp::session:
<<<<< (BTP IO) 7C:95:4D:2F:0E:E8 [A|B|E,ACTR:7,CTR:8,LEN:40]
WRITE 64B
I (18201) rs_matter::transport::network::btp::session:
>>>>> (BTP IO) 7C:95:4D:2F:0E:E8 [A|B|E,ACTR:8,CTR:8,LEN:83]
READ 131B
I (18221) rs_matter::transport::session: Creating a new exchange: 95cd/Responder(AcceptPending)
I (18221) rs_matter::transport::core:
>>>>> BTP 7C:95:4D:2F:0E:E8 [SID:1,CTR:8dc4893][I,EID:95cd,PROTO:1,OP:2]
IM::ReadRequest
=> Processing (new exchange)
I (18231) rs_matter::transport::core: Exchange 1::0: Accepted
I (18241) rs_matter::respond: Responder: Handler 0 / exchange 1::0: Starting
I (18251) rs_matter::transport::exchange:
<<<<< BTP 7C:95:4D:2F:0E:E8 [SID:71d3,CTR:743373b][EID:95cd,PROTO:1,OP:5]
IM::ReportData
=> Sending
I (18271) rs_matter::respond: Responder: Handler 0 / exchange 1::0: Completed
I (18271) rs_matter::transport::network::btp::session:
<<<<< (BTP IO) 7C:95:4D:2F:0E:E8 [A|B,ACTR:8,CTR:9,LEN:fe]
WRITE 239B
I (18281) rs_matter::transport::network::btp::session:
<<<<< (BTP IO) 7C:95:4D:2F:0E:E8 [C|E,CTR:a]
WRITE 15B
I (18411) rs_matter::transport::network::btp::session:
>>>>> (BTP IO) 7C:95:4D:2F:0E:E8 [A|B|E,ACTR:a,CTR:9,LEN:6a]
READ 106B
I (18431) rs_matter::transport::session: Creating a new exchange: 95ce/Responder(AcceptPending)
I (18431) rs_matter::transport::core:
>>>>> BTP 7C:95:4D:2F:0E:E8 [SID:1,CTR:8dc4894][I,EID:95ce,PROTO:1,OP:2]
IM::ReadRequest
=> Processing (new exchange)
I (18441) rs_matter::transport::core: Exchange 1::0: Accepted
I (18451) rs_matter::respond: Responder: Handler 0 / exchange 1::0: Starting
I (18461) rs_matter::transport::exchange:
<<<<< BTP 7C:95:4D:2F:0E:E8 [SID:71d3,CTR:743373c][EID:95ce,PROTO:1,OP:5]
IM::ReportData
=> Sending
I (18481) rs_matter::respond: Responder: Handler 0 / exchange 1::0: Completed
I (18481) rs_matter::transport::network::btp::session:
<<<<< (BTP IO) 7C:95:4D:2F:0E:E8 [A|B|E,ACTR:9,CTR:b,LEN:c0]
WRITE 192B
I (18531) rs_matter::transport::network::btp::session:
>>>>> (BTP IO) 7C:95:4D:2F:0E:E8 [A|B|E,ACTR:b,CTR:a,LEN:41]
READ 65B
I (18541) rs_matter::transport::session: Creating a new exchange: 95cf/Responder(AcceptPending)
I (18541) rs_matter::transport::core:
>>>>> BTP 7C:95:4D:2F:0E:E8 [SID:1,CTR:8dc4895][I,EID:95cf,PROTO:1,OP:8]
IM::InvokeRequest
=> Processing (new exchange)
I (18561) rs_matter::transport::core: Exchange 1::0: Accepted
I (18561) rs_matter::respond: Responder: Handler 0 / exchange 1::0: Starting
I (18581) rs_matter::data_model::sdm::general_commissioning: Handling command ARM Fail Safe
I (18591) rs_matter::transport::exchange:
<<<<< BTP 7C:95:4D:2F:0E:E8 [SID:71d3,CTR:743373d][EID:95cf,PROTO:1,OP:9]
IM::InvokeResponse
=> Sending
I (18601) rs_matter::respond: Responder: Handler 0 / exchange 1::0: Completed
I (18611) rs_matter::transport::network::btp::session:
<<<<< (BTP IO) 7C:95:4D:2F:0E:E8 [A|B|E,ACTR:a,CTR:c,LEN:3f]
WRITE 63B
I (18681) rs_matter::transport::network::btp::session:
>>>>> (BTP IO) 7C:95:4D:2F:0E:E8 [A|B|E,ACTR:c,CTR:b,LEN:46]
READ 70B
I (18691) rs_matter::transport::session: Creating a new exchange: 95d0/Responder(AcceptPending)
I (18701) rs_matter::transport::core:
>>>>> BTP 7C:95:4D:2F:0E:E8 [SID:1,CTR:8dc4896][I,EID:95d0,PROTO:1,OP:8]
IM::InvokeRequest
=> Processing (new exchange)
I (18711) rs_matter::transport::core: Exchange 1::0: Accepted
I (18711) rs_matter::respond: Responder: Handler 0 / exchange 1::0: Starting
I (18731) rs_matter::data_model::sdm::general_commissioning: Handling command Set Regulatory Config
I (18731) rs_matter::data_model::sdm::general_commissioning: Received country code: [78, 76]
I (18751) rs_matter::transport::exchange:
<<<<< BTP 7C:95:4D:2F:0E:E8 [SID:71d3,CTR:743373e][EID:95d0,PROTO:1,OP:9]
IM::InvokeResponse
=> Sending
I (18761) rs_matter::respond: Responder: Handler 0 / exchange 1::0: Completed
I (18771) rs_matter::transport::network::btp::session:
<<<<< (BTP IO) 7C:95:4D:2F:0E:E8 [A|B|E,ACTR:b,CTR:d,LEN:3f]
WRITE 63B
I (18831) rs_matter::transport::network::btp::session:
>>>>> (BTP IO) 7C:95:4D:2F:0E:E8 [A|B|E,ACTR:d,CTR:c,LEN:3e]
READ 62B
I (18841) rs_matter::transport::session: Creating a new exchange: 95d1/Responder(AcceptPending)
I (18841) rs_matter::transport::core:
>>>>> BTP 7C:95:4D:2F:0E:E8 [SID:1,CTR:8dc4897][I,EID:95d1,PROTO:1,OP:8]
IM::InvokeRequest
=> Processing (new exchange)
I (18861) rs_matter::transport::core: Exchange 1::0: Accepted
I (18861) rs_matter::respond: Responder: Handler 0 / exchange 1::0: Starting
I (18881) rs_matter::data_model::sdm::noc: Handling command CertChainRequest
I (18881) rs_matter::data_model::sdm::noc: Received data: 1: {
I (18891) rs_matter::data_model::sdm::noc: Received Cert Type:2
I (18901) rs_matter::transport::exchange:
<<<<< BTP 7C:95:4D:2F:0E:E8 [SID:71d3,CTR:743373f][EID:95d1,PROTO:1,OP:9]
IM::InvokeResponse
=> Sending
I (18921) rs_matter::respond: Responder: Handler 0 / exchange 1::0: Completed
I (18931) rs_matter::transport::network::btp::session:
<<<<< (BTP IO) 7C:95:4D:2F:0E:E8 [A|B,ACTR:c,CTR:e,LEN:20c]
WRITE 239B
I (18931) rs_matter::transport::network::btp::session:
<<<<< (BTP IO) 7C:95:4D:2F:0E:E8 [C,CTR:f]
WRITE 242B
I (18951) rs_matter::transport::network::btp::session:
<<<<< (BTP IO) 7C:95:4D:2F:0E:E8 [C|E,CTR:10]
WRITE 43B
I (19131) rs_matter::transport::network::btp::session:
>>>>> (BTP IO) 7C:95:4D:2F:0E:E8 [A|B|E,ACTR:10,CTR:d,LEN:3e]
READ 62B
I (19141) rs_matter::transport::session: Creating a new exchange: 95d2/Responder(AcceptPending)
I (19151) rs_matter::transport::core:
>>>>> BTP 7C:95:4D:2F:0E:E8 [SID:1,CTR:8dc4898][I,EID:95d2,PROTO:1,OP:8]
IM::InvokeRequest
=> Processing (new exchange)
I (19161) rs_matter::transport::core: Exchange 1::0: Accepted
I (19161) rs_matter::respond: Responder: Handler 0 / exchange 1::0: Starting
I (19181) rs_matter::data_model::sdm::noc: Handling command CertChainRequest
I (19181) rs_matter::data_model::sdm::noc: Received data: 1: {
I (19191) rs_matter::data_model::sdm::noc: Received Cert Type:1
I (19201) rs_matter::transport::exchange:
<<<<< BTP 7C:95:4D:2F:0E:E8 [SID:71d3,CTR:7433740][EID:95d2,PROTO:1,OP:9]
IM::InvokeResponse
=> Sending
I (19221) rs_matter::respond: Responder: Handler 0 / exchange 1::0: Completed
I (19231) rs_matter::transport::network::btp::session:
<<<<< (BTP IO) 7C:95:4D:2F:0E:E8 [A|B,ACTR:d,CTR:11,LEN:229]
WRITE 239B
I (19241) rs_matter::transport::network::btp::session:
<<<<< (BTP IO) 7C:95:4D:2F:0E:E8 [C,CTR:12]
WRITE 242B
I (19251) rs_matter::transport::network::btp::session:
<<<<< (BTP IO) 7C:95:4D:2F:0E:E8 [C|E,CTR:13]
WRITE 72B
I (19431) rs_matter::transport::network::btp::session:
>>>>> (BTP IO) 7C:95:4D:2F:0E:E8 [A|B|E,ACTR:13,CTR:e,LEN:5e]
READ 94B
I (19441) rs_matter::transport::session: Creating a new exchange: 95d3/Responder(AcceptPending)
I (19451) rs_matter::transport::core:
>>>>> BTP 7C:95:4D:2F:0E:E8 [SID:1,CTR:8dc4899][I,EID:95d3,PROTO:1,OP:8]
IM::InvokeRequest
=> Processing (new exchange)
I (19461) rs_matter::transport::core: Exchange 1::0: Accepted
I (19471) rs_matter::respond: Responder: Handler 0 / exchange 1::0: Starting
I (19481) rs_matter::data_model::sdm::noc: Handling command AttestationRequest
I (19481) rs_matter::data_model::sdm::noc: Received Attestation Nonce:OctetStr([247, 136, 106, 243, 39, 28, 99, 175, 29, 232, 125, 241, 201, 32, 188, 81, 250, 227, 166, 134, 0, 23, 225, 26, 85, 15, 211, 230, 17, 32, 64, 104])
I (19871) rs_matter::transport::exchange:
<<<<< BTP 7C:95:4D:2F:0E:E8 [SID:71d3,CTR:7433741][EID:95d3,PROTO:1,OP:9]
IM::InvokeResponse
=> Sending
I (19901) rs_matter::respond: Responder: Handler 0 / exchange 1::0: Completed
I (19901) rs_matter::transport::network::btp::session:
<<<<< (BTP IO) 7C:95:4D:2F:0E:E8 [A|B,ACTR:e,CTR:14,LEN:2c9]
WRITE 239B
I (19911) rs_matter::transport::network::btp::session:
<<<<< (BTP IO) 7C:95:4D:2F:0E:E8 [C,CTR:15]
WRITE 242B
I (19921) rs_matter::transport::network::btp::session:
<<<<< (BTP IO) 7C:95:4D:2F:0E:E8 [C|E,CTR:16]
WRITE 232B
I (21831) rs_matter::transport::network::btp::session:
>>>>> (BTP IO) 7C:95:4D:2F:0E:E8 [A|B|E,ACTR:16,CTR:f,LEN:5e]
READ 94B
I (21851) rs_matter::transport::session: Creating a new exchange: 95d4/Responder(AcceptPending)
I (21851) rs_matter::transport::core:
>>>>> BTP 7C:95:4D:2F:0E:E8 [SID:1,CTR:8dc489a][I,EID:95d4,PROTO:1,OP:8]
IM::InvokeRequest
=> Processing (new exchange)
I (21861) rs_matter::transport::core: Exchange 1::0: Accepted
I (21871) rs_matter::respond: Responder: Handler 0 / exchange 1::0: Starting
I (21881) rs_matter::data_model::sdm::noc: Handling command CSRRequest
I (21881) rs_matter::data_model::sdm::noc: Received CSR Nonce:OctetStr([51, 37, 234, 50, 197, 160, 130, 10, 129, 48, 71, 31, 180, 10, 218, 37, 87, 106, 108, 230, 107, 254, 3, 5, 37, 135, 94, 149, 167, 123, 249, 252])
I (22641) rs_matter::transport::exchange:
<<<<< BTP 7C:95:4D:2F:0E:E8 [SID:71d3,CTR:7433742][EID:95d4,PROTO:1,OP:9]
IM::InvokeResponse
=> Sending
I (22661) rs_matter::respond: Responder: Handler 0 / exchange 1::0: Completed
I (22661) rs_matter::transport::network::btp::session:
<<<<< (BTP IO) 7C:95:4D:2F:0E:E8 [A|B,ACTR:f,CTR:17,LEN:172]
WRITE 239B
I (22671) rs_matter::transport::network::btp::session:
<<<<< (BTP IO) 7C:95:4D:2F:0E:E8 [C|E,CTR:18]
WRITE 131B
I (22681) light: Light toggled
I (22791) rs_matter::transport::network::btp::session:
>>>>> (BTP IO) 7C:95:4D:2F:0E:E8 [A|B,ACTR:18,CTR:10,LEN:134]
READ 239B
I (22851) rs_matter::transport::network::btp::session:
>>>>> (BTP IO) 7C:95:4D:2F:0E:E8 [C|E,CTR:11]
READ 69B
I (22871) rs_matter::transport::session: Creating a new exchange: 95d5/Responder(AcceptPending)
I (22871) rs_matter::transport::core:
>>>>> BTP 7C:95:4D:2F:0E:E8 [SID:1,CTR:8dc489b][I,EID:95d5,PROTO:1,OP:8]
IM::InvokeRequest
=> Processing (new exchange)
I (22891) rs_matter::transport::core: Exchange 1::0: Accepted
I (22891) rs_matter::respond: Responder: Handler 0 / exchange 1::0: Starting
I (22901) rs_matter::data_model::sdm::noc: Handling command AddTrustedRootCert
I (22911) rs_matter::data_model::sdm::noc: Received Trusted Cert:OctetStr([15, 30, 1, 1, 0, 24, 2, 1, 37, 3, 26, 14, 34, 4, f8, 4, 26, 15, f7, c0, a6, be, 18, 26, 4, 83, 1f, 53, 2c, 24, 5, 0, 37, 6, 26, 14, 34, 4, f8, 4, 26, 15, f7, c0, a6, be, 18, 24, 7, 1, 24, 8, 1, 30, 9, 41, 4, 59, 1b, 81, 31, 2, 6f, ef, c5, 71, 1a, f, a5, 94, b8, f1, b, 64, 15, d2, 5e, 22, 24, 4, 94, b8, 86, 5a, 8e, db, e8, 2b, 25, e0, 7d, 2c, a1, f6, 6b, 7d, bb, e8, 7, ca, dc, e0, d0, bb, 14, 10, 3d, 6c, c0, d9, 4a, 71, 77, da, 1e, 95, 97, c0, 94, 2d, 64, 37, a, 35, 1, 29, 1, 18, 24, 2, 60, 30, 4, 14, 65, 75, 90, c7, 9b, 47, f5, 43, 80, c9, d3, 14, 4f, 1, 9, be, 80, cf, e9, 41, 30, 5, 14, 65, 75, 90, c7, 9b, 47, f5, 43, 80, c9, d3, 14, 4f, 1, 9, be, 80, cf, e9, 41, 18, 30, b, 40, d8, e7, 2d, ff, 72, 36, aa, 6b, 86, 2c, 8a, b0, c6, 40, 57, f3, 97, f5, 64, f0, 5b, 12, bc, 42, 4b, 75, fe, 17, a5, 3, 5, 24, 9c, a1, 73, 84, 65, 9f, b6, 5c, db, e, 18, d4, 71, fa, 9a, f8, c6, 9b, 3f, f, 2f, ef, 5, d8, bd, 24, ad, c8, 5d, ac, 3f, b9, 18])
I (23001) rs_matter::transport::exchange:
<<<<< BTP 7C:95:4D:2F:0E:E8 [SID:71d3,CTR:7433743][EID:95d5,PROTO:1,OP:9]
IM::InvokeResponse
=> Sending
I (23021) rs_matter::respond: Responder: Handler 0 / exchange 1::0: Completed
I (23021) rs_matter::transport::network::btp::session:
<<<<< (BTP IO) 7C:95:4D:2F:0E:E8 [A|B|E,ACTR:11,CTR:19,LEN:3f]
WRITE 63B
I (23091) rs_matter::transport::network::btp::session:
>>>>> (BTP IO) 7C:95:4D:2F:0E:E8 [A|B,ACTR:19,CTR:12,LEN:15b]
READ 239B
I (23151) rs_matter::transport::network::btp::session:
>>>>> (BTP IO) 7C:95:4D:2F:0E:E8 [C|E,CTR:13]
READ 108B
I (23171) rs_matter::transport::session: Creating a new exchange: 95d6/Responder(AcceptPending)
I (23171) rs_matter::transport::core:
>>>>> BTP 7C:95:4D:2F:0E:E8 [SID:1,CTR:8dc489c][I,EID:95d6,PROTO:1,OP:8]
IM::InvokeRequest
=> Processing (new exchange)
I (23191) rs_matter::transport::core: Exchange 1::0: Accepted
I (23191) rs_matter::respond: Responder: Handler 0 / exchange 1::0: Starting
I (23201) rs_matter::data_model::sdm::noc: Handling command AddNOC
I (23211) rs_matter::data_model::sdm::noc: Received NOC as: Version: [0]
[2]
Serial Num: [1]
Signature Algorithm:
ECDSA with SHA256
Issuer:
Chip Root CA Id:
"0000000004F80434"
Chip Fabric Id:
"00000000BEA6C0F7"
Validity:
Not Before: 2024-06-01 7:33:31.0 +00:00:00
Not After: 9999-12-31 23:59:59.0 +00:00:00
Subject:
Chip Fabric Id:
"00000000BEA6C0F7"
Chip Node Id:
"00000000536611E0"
Public Key Algorithm
ECPubKey
Prime256v1
Public-Key: [4, 49, 15, 3, 8b, 42, 8f, c, 85, b1, 29, 56, e6, e0, 74, fa, b7, 5f, 78, ed, 42, f6, db, 68, a2, f8, ac, 0, be, 8b, 80, d1, e1, 44, f5, 2b, 80, f, 65, 1d, c7, 6a, 38, 9e, 21, 79, e3, 18, 6f, a5, 81, 58, 76, 46, 4f, f2, b5, 0, 25, 8e, 8b, df, 37, 3, 2c]
X509v3 extensions: [3]
X509v3 Basic Constraints
critical: true
value:
X509v3 Key Usage
critical: true
value:
digitalSignature [80, 0]
X509v3 Extended Key Usage
critical: true
value:
ClientAuth
ServerAuth
Subject Key ID
value:
[8b, 52, 22, cf, c0, cf, 23, c2, b0, 80, fe, d4, 4c, dc, 9a, 9c, e4, ab, d3, 49]
Auth Key ID
value:
[0][65, 75, 90, c7, 9b, 47, f5, 43, 80, c9, d3, 14, 4f, 1, 9, be, 80, cf, e9, 41]
Signature: [e9, 1a, 1d, c1, 91, f8, aa, 97, c0, ad, e2, 8f, da, 1f, 24, e7, 62, dd, 1e, 3b, 27, cd, a3, 74, bb, 85, ed, fb, 36, ed, d8, 35, 94, 45, 2, de, b4, c7, 69, f, 79, 2b, 31, 32, 78, 94, 6, fc, 7f, bc, 8, 84, 20, 73, 42, c0, 26, c5, c1, a8, fa, 2c, 5e, af]
I (23371) rs_matter::fabric: MDNS Service Name: 1BB7D1A63D26A524-00000000536611E0
I (23381) rs_matter::transport::exchange:
<<<<< BTP 7C:95:4D:2F:0E:E8 [SID:71d3,CTR:7433744][EID:95d6,PROTO:1,OP:9]
IM::InvokeResponse
=> Sending
I (23391) rs_matter::respond: Responder: Handler 0 / exchange 1::0: Completed
I (23401) rs_matter::transport::network::btp::session:
<<<<< (BTP IO) 7C:95:4D:2F:0E:E8 [A|B|E,ACTR:13,CTR:1a,LEN:42]
WRITE 66B
I (23451) rs_matter::transport::network::btp::session:
>>>>> (BTP IO) 7C:95:4D:2F:0E:E8 [A|B|E,ACTR:1a,CTR:14,LEN:5b]
READ 91B
I (23461) rs_matter::transport::session: Creating a new exchange: 95d7/Responder(AcceptPending)
I (23471) rs_matter::transport::core:
>>>>> BTP 7C:95:4D:2F:0E:E8 [SID:1,CTR:8dc489d][I,EID:95d7,PROTO:1,OP:8]
IM::InvokeRequest
=> Processing (new exchange)
I (23481) rs_matter::transport::core: Exchange 1::0: Accepted
I (23491) rs_matter::respond: Responder: Handler 0 / exchange 1::0: Starting
I (23501) rs_matter_stack::wifi::comm: AddOrUpdateWifiNetwork
I (23501) rs_matter_stack::wifi::comm: Added network with SSID Home-3wnB
I (23511) rs_matter::transport::exchange:
<<<<< BTP 7C:95:4D:2F:0E:E8 [SID:71d3,CTR:7433745][EID:95d7,PROTO:1,OP:9]
IM::InvokeResponse
=> Sending
I (23531) rs_matter::respond: Responder: Handler 0 / exchange 1::0: Completed
I (23531) rs_matter::transport::network::btp::session:
<<<<< (BTP IO) 7C:95:4D:2F:0E:E8 [A|B|E,ACTR:14,CTR:1b,LEN:3f]
WRITE 63B
I (23601) rs_matter::transport::network::btp::session:
>>>>> (BTP IO) 7C:95:4D:2F:0E:E8 [A|B|E,ACTR:1b,CTR:15,LEN:41]
READ 65B
I (23611) rs_matter::transport::session: Creating a new exchange: 95d8/Responder(AcceptPending)
I (23621) rs_matter::transport::core:
>>>>> BTP 7C:95:4D:2F:0E:E8 [SID:1,CTR:8dc489e][I,EID:95d8,PROTO:1,OP:8]
IM::InvokeRequest
=> Processing (new exchange)
I (23631) rs_matter::transport::core: Exchange 1::0: Accepted
I (23631) rs_matter::respond: Responder: Handler 0 / exchange 1::0: Starting
I (23651) rs_matter::data_model::sdm::general_commissioning: Handling command ARM Fail Safe
I (23661) rs_matter::transport::exchange:
<<<<< BTP 7C:95:4D:2F:0E:E8 [SID:71d3,CTR:7433746][EID:95d8,PROTO:1,OP:9]
IM::InvokeResponse
=> Sending
I (23671) rs_matter::respond: Responder: Handler 0 / exchange 1::0: Completed
I (23681) rs_matter::transport::network::btp::session:
<<<<< (BTP IO) 7C:95:4D:2F:0E:E8 [A|B|E,ACTR:15,CTR:1c,LEN:3f]
WRITE 63B
I (23751) rs_matter::transport::network::btp::session:
>>>>> (BTP IO) 7C:95:4D:2F:0E:E8 [A|B|E,ACTR:1c,CTR:16,LEN:4a]
READ 74B
I (23761) rs_matter::transport::session: Creating a new exchange: 95d9/Responder(AcceptPending)
I (23771) rs_matter::transport::core:
>>>>> BTP 7C:95:4D:2F:0E:E8 [SID:1,CTR:8dc489f][I,EID:95d9,PROTO:1,OP:8]
IM::InvokeRequest
=> Processing (new exchange)
I (23781) rs_matter::transport::core: Exchange 1::0: Accepted
I (23791) rs_matter::respond: Responder: Handler 0 / exchange 1::0: Starting
I (23801) rs_matter_stack::wifi::comm: ConnectNetwork
I (23801) rs_matter_stack::wifi::comm: Request to connect to network with SSID Home-3wnB received
I (23811) rs_matter::transport::exchange:
<<<<< BTP 7C:95:4D:2F:0E:E8 [SID:71d3,CTR:7433747][EID:95d9,PROTO:1,OP:9]
IM::InvokeResponse
=> Sending
I (23831) rs_matter::respond: Responder: Handler 0 / exchange 1::0: Completed
I (23831) rs_matter::transport::network::btp::session:
<<<<< (BTP IO) 7C:95:4D:2F:0E:E8 [A|B|E,ACTR:16,CTR:1d,LEN:3f]
WRITE 63B
W (23851) rs_matter_stack::wifi: Giving BLE/BTP extra 4 seconds for any outstanding messages before switching to Wifi
I (26391) rs_matter::transport::network::btp::session:
>>>>> (BTP IO) 7C:95:4D:2F:0E:E8 [A,ACTR:1d,CTR:17]
READ 0B
I (27691) light: Light toggled
W (27861) BT_HCI: hci cmd send: disconnect: hdl 0x1, rsn:0x13
W (27891) BT_HCI: hcif disc complete: hdl 0x1, rsn 0x16
I (28901) pp: pp rom version: 9387209
I (28901) net80211: net80211 rom version: 9387209
I (28911) wifi:wifi driver task: 3fcbf748, prio:23, stack:6656, core=0
I (28911) wifi:wifi firmware version: 91b9630
I (28911) wifi:wifi certification version: v7.0
I (28911) wifi:config NVS flash: enabled
I (28911) wifi:config nano formating: disabled
I (28921) wifi:Init data frame dynamic rx buffer num: 32
I (28921) wifi:Init static rx mgmt buffer num: 10
I (28931) wifi:Init management short buffer num: 32
I (28931) wifi:Init dynamic tx buffer num: 32
I (28941) wifi:Init static tx FG buffer num: 2
I (28941) wifi:Init static rx buffer size: 1600
I (28941) wifi:Init static rx buffer num: 10
I (28951) wifi:Init dynamic rx buffer num: 32
I (28951) wifi_init: rx ba win: 6
I (28961) wifi_init: tcpip mbox: 32
I (28961) wifi_init: udp mbox: 6
I (28961) wifi_init: tcp mbox: 6
I (28971) wifi_init: tcp tx win: 5744
I (28971) wifi_init: tcp rx win: 5744
I (28981) wifi_init: tcp mss: 1440
I (28981) wifi_init: WiFi IRAM OP enabled
I (28991) wifi_init: WiFi RX IRAM OP enabled
I (29001) rs_matter_stack::wifible: Wifi driver initialized
I (29001) rs_matter_stack::wifible: Running Matter in operating mode (Wifi)
I (29011) rs_matter_stack::wifi: Trying with requested network first - SSID: Home-3wnB
I (29011) rs_matter_stack::wifi::mgmt: Connecting to SSID Home-3wnB
I (29021) rs_matter_stack::wifi::mgmt: Connecting with Client(ClientConfiguration { ssid: "Home-3wnB", bssid: None, auth_method: WPAWPA2Personal, channel: None, scan_method: CompleteScan(Signal), pmf_cfg: NotCapable })
I (29061) wifi:mode : sta (dc:da:0c:88:be:90)
I (29061) wifi:enable tsf
I (29061) rs_matter_stack: Waiting for the network to come up...
I (31471) wifi:new:<9,0>, old:<1,0>, ap:<255,255>, sta:<9,0>, prof:1
I (31751) wifi:state: init -> auth (b0)
I (31751) wifi:state: auth -> assoc (0)
I (31751) wifi:state: assoc -> run (10)
I (31761) wifi:connected with Home-3wnB, aid = 2, channel 9, BW20, bssid = 00:5f:67:9a:30:bf
I (31771) wifi:security: WPA2-PSK, phy: bg, rssi: -61
I (31781) wifi:pm start, type: 1
I (31781) wifi:set rx beacon pti, rx_bcn_pti: 14, bcn_timeout: 25000, mt_pti: 14, mt_time: 10000
I (31781) rs_matter_stack::wifi::mgmt: Successfully connected with Client(ClientConfiguration { ssid: "Home-3wnB", bssid: None, auth_method: WPAWPA2Personal, channel: None, scan_method: CompleteScan(Signal), pmf_cfg: NotCapable })
I (31801) rs_matter_stack::wifi::mgmt: Connected to SSID Home-3wnB
I (31841) wifi:AP's beacon interval = 102400 us, DTIM period = 2
I (32691) light: Light toggled
I (33281) esp_netif_handlers: sta ip: 192.168.1.110, mask: 255.255.255.0, gw: 192.168.1.1
I (37691) light: Light toggled
I (42691) light: Light toggled
I (47701) light: Light toggled
I (52701) light: Light toggled
Is that all? I don't see in the esp logs the mdns broadcast messages at all...
Also, does it fail immediately, or is the provisioning on the iPhone somehow "stuck" for a while?
Trying to understand if you are experiencing the mDNS error, or something else...
Yes, that's all I have. Unless you know of a more verbose logging mode
No it failed immediately right after the Wi-Fi credentials were sent to the device but before it reported as connected to the network
OK, so it seems homed does not like something in our ConnectNetwork
response (the error message for command ID 0x05). Let me look unto the exact reason for the "schema mismatch" error report in the C++ Matter SDK homed uses.
Ha. Actually 0x05 is a response to ConfigNetwork
, not to ConnectNetwork
...
Ok I'm relatively sure this is the bug, or at least "a" bug. Should be len() - 1
. Will fix in a couple of hours.
Weird that Google Home did not yell at me about that...
OK the index error should be fixed now if you do cargo update
.
Whether this is the root cause for the provisioning failure - I don't know, because your provisioning still continues after this error, or else we would've not received the ConnectNetwork
command which triggers the switch-over to Wifi.
But I guess it does not hurt if you give it a try again?
No, unfortunately still no success.
homed
logsdefault 12:50:29.694996+0200 homed Discovered device to be commissioned over BLE
default 12:50:29.695023+0200 homed Attempting PASE connection to BLE
error 12:50:29.695070+0200 homed Found unconnected device, removing
default 12:50:29.695097+0200 homed Closing all BLE connections
default 12:50:29.695285+0200 homed SecureSession[0xb98837340, LSID:29143]: State change 'kActive' --> 'kPendingEviction'
default 12:50:29.695785+0200 homed ATT MTU = 517
default 12:50:29.697067+0200 homed <<< [E:38431i S:0 M:234842409] (U) Msg TX to 0:0000000000000000 [0000] [BLE] --- Type 0000:20 (SecureChannel:PBKDFParamRequest)
error 12:50:29.697238+0200 homed SendMessage() to BLE failed: src/transport/raw/BLE.cpp:114: Success
default 12:50:29.939918+0200 homed subscribe complete, ep = 0x2501ebca8
default 12:50:29.939973+0200 homed peripheral chose BTP version 4; central expected between 4 and 4
default 12:50:29.940028+0200 homed using BTP fragment sizes rx 244 / tx 244.
default 12:50:29.940248+0200 homed local and remote recv window size = 6
default 12:50:30.060183+0200 homed >>> [E:38431i S:0 M:93740153] (U) Msg RX from 0:0000000000000000 [0000] --- Type 0000:21 (SecureChannel:PBKDFParamResponse)
default 12:50:30.069133+0200 homed <<< [E:38431i S:0 M:234842410] (U) Msg TX to 0:0000000000000000 [0000] [BLE] --- Type 0000:22 (SecureChannel:PASE_Pake1)
error 12:50:30.069555+0200 homed SendMessage() to BLE failed: src/transport/raw/BLE.cpp:114: Success
default 12:50:32.231687+0200 homed SendResponseID 'com.apple.home.hh2.messaging.rid', 0 keys
default 12:50:32.232362+0200 homed Received message over Rapport: <HMDRemoteMessage, Identifier = 3921869D-5FA6-47D0-A312-F20061C61AB7, Name = kCharacterisiticsChangedInternalNotificationKey, QoS = Utility, Type = oneway, TransactionIdentifier = (null), Destination = <HMDRemoteDeviceMessageDestination, Target = 04FDA73C-1019-4FBF-B828-2363E42223C7, Device <HMDDevice, Id: DC507C34-F96A-5141-9ABE-E134F9F5C5A7, Nm: <redacted>, Ver: 11.4, Cap: (null), Shid: (null), Ids: 5C43B857-C38E-405D-A7EE-0E070EE8C99A, Hndl: (
"<HMDDeviceHandle, Identifier: DC507C34-F96A-5141-9ABE-E134F9F5C5A7, Type: Global, Value: <redacted>, Account Handle: <HMDAccountHandle, Id: B6ECB088-41C7-51CB-91CA-473FAF1FB333, Tp: Email, Lc: NO, Va: e***@i***.c***>>",
"<HMDDeviceHandle, Identifier: 88E93EE7-5007-5C6E-9DA8-C218A50330A8, Type: Local, Value: <redacted>, Account Handle: (null)>"
)>>,
User Info = ...,
Headers = {
"hmd_mrmrst" = "1717239032.198155";
"hmd_mrmttl" = 60;
}>
default 12:50:32.651870+0200 homed HAPWACBrowser: Suspend
default 12:50:32.652000+0200 homed HAPWACBrowser: Resume
default 12:50:32.652041+0200 homed HAPWACBrowser: WiFi scan start
error 12:50:32.654217+0200 homed __WiFiManagerClientAddDevice: for device [<private>] using server port [81491]
error 12:50:32.654412+0200 homed __WiFiManagerClientAddDevice: for device [<private>] using server port [81491]
error 12:50:32.655890+0200 homed __WiFiManagerClientAddDevice: for device [<private>] using server port [81491]
default 12:50:32.656084+0200 homed WiFi scan starting
default 12:50:33.649594+0200 homed >>> [E:38431i S:0 M:93740154] (U) Msg RX from 0:0000000000000000 [0000] --- Type 0000:23 (SecureChannel:PASE_Pake2)
default 12:50:33.649940+0200 homed <<< [E:38431i S:0 M:234842411] (U) Msg TX to 0:0000000000000000 [0000] [BLE] --- Type 0000:24 (SecureChannel:PASE_Pake3)
error 12:50:33.650491+0200 homed SendMessage() to BLE failed: src/transport/raw/BLE.cpp:114: Success
default 12:50:33.750392+0200 homed >>> [E:38431i S:0 M:93740155] (U) Msg RX from 0:0000000000000000 [0000] --- Type 0000:40 (SecureChannel:StatusReport)
default 12:50:33.750718+0200 homed SecureSession[0xb983fc000, LSID:29145]: State change 'kEstablishing' --> 'kActive'
default 12:50:33.751584+0200 homed Pairing with commissionee successful, stopping discovery
error 12:50:33.751708+0200 homed Mdns: Browse failure (src/platform/Darwin/DnssdImpl.cpp:412: CHIP Error 0x00000074: The operation has been cancelled)
default 12:50:33.751758+0200 homed DeviceControllerDelegate Pairing complete. Status src/controller/CHIPDeviceController.cpp:1088: Success
error 12:50:33.753204+0200 homed Attempting to update an uninitialized progress state map for <private>
default 12:50:33.753705+0200 homed <<< [E:38432i S:29145 M:254168911] (S) Msg TX to 0:FFFFFFFB00000000 [0000] [BLE] --- Type 0001:02 (IM:ReadRequest)
error 12:50:33.754004+0200 homed SendMessage() to BLE failed: src/transport/raw/BLE.cpp:114: Success
default 12:50:33.869501+0200 homed >>> [E:38432i S:29145 M:232787666] (S) Msg RX from 0:FFFFFFFB00000000 [0000] --- Type 0001:05 (IM:ReportData)
default 12:50:33.870250+0200 homed <<< [E:38433i S:29145 M:254168912] (S) Msg TX to 0:FFFFFFFB00000000 [0000] [BLE] --- Type 0001:02 (IM:ReadRequest)
error 12:50:33.870610+0200 homed SendMessage() to BLE failed: src/transport/raw/BLE.cpp:114: Success
default 12:50:33.989835+0200 homed >>> [E:38433i S:29145 M:232787667] (S) Msg RX from 0:FFFFFFFB00000000 [0000] --- Type 0001:05 (IM:ReportData)
default 12:50:33.990755+0200 homed <<< [E:38434i S:29145 M:254168913] (S) Msg TX to 0:FFFFFFFB00000000 [0000] [BLE] --- Type 0001:02 (IM:ReadRequest)
error 12:50:33.990994+0200 homed SendMessage() to BLE failed: src/transport/raw/BLE.cpp:114: Success
default 12:50:34.109802+0200 homed >>> [E:38434i S:29145 M:232787668] (S) Msg RX from 0:FFFFFFFB00000000 [0000] --- Type 0001:05 (IM:ReportData)
error 12:50:34.115302+0200 homed __WiFiManagerClientAddDevice: for device [<private>] using server port [155587]
error 12:50:34.115343+0200 homed __WiFiManagerClientAddDevice: for device [<private>] using server port [155587]
error 12:50:34.115382+0200 homed __WiFiManagerClientAddDevice: for device [<private>] using server port [155587]
default 12:50:34.117535+0200 homed WiFiNetworkCopyPassword: Copy password for Network <private>
error 12:50:34.146253+0200 homed Attempting to update an uninitialized progress state map for <private>
default 12:50:34.149667+0200 homed {"msg":"RegulatoryDomain current estimates", "estimates":"(\n \"NL, priority = 4 (LatLonLocation), timestamp = 2024-06-01 12:48:54+0200\"\n)"}
default 12:50:34.152327+0200 homed <<< [E:38435i S:29145 M:254168914] (S) Msg TX to 0:FFFFFFFB00000000 [0000] [BLE] --- Type 0001:02 (IM:ReadRequest)
error 12:50:34.152403+0200 homed SendMessage() to BLE failed: src/transport/raw/BLE.cpp:114: Success
default 12:50:34.259860+0200 homed >>> [E:38435i S:29145 M:232787669] (S) Msg RX from 0:FFFFFFFB00000000 [0000] --- Type 0001:05 (IM:ReportData)
default 12:50:34.260548+0200 homed <<< [E:38436i S:29145 M:254168915] (S) Msg TX to 0:FFFFFFFB00000000 [0000] [BLE] --- Type 0001:02 (IM:ReadRequest)
error 12:50:34.260855+0200 homed SendMessage() to BLE failed: src/transport/raw/BLE.cpp:114: Success
default 12:50:34.389256+0200 homed >>> [E:38436i S:29145 M:232787670] (S) Msg RX from 0:FFFFFFFB00000000 [0000] --- Type 0001:05 (IM:ReportData)
error 12:50:34.391562+0200 homed __WiFiManagerClientAddDevice: for device [<private>] using server port [161367]
error 12:50:34.391618+0200 homed __WiFiManagerClientAddDevice: for device [<private>] using server port [161367]
error 12:50:34.391673+0200 homed __WiFiManagerClientAddDevice: for device [<private>] using server port [161367]
default 12:50:34.391891+0200 homed WiFiNetworkCopyPassword: Copy password for Network <private>
error 12:50:34.392347+0200 homed Attempting to update an uninitialized progress state map for <private>
default 12:50:34.393302+0200 homed Setting wifi credentials from parameters
error 12:50:34.393330+0200 homed Attempting to update an uninitialized progress state map for <private>
default 12:50:34.393393+0200 homed Setting attestation nonce to random value
default 12:50:34.393466+0200 homed Setting CSR nonce to random value
default 12:50:34.393495+0200 homed Setting DST offsets from parameters
default 12:50:34.393522+0200 homed Setting Time Zone from parameters
default 12:50:34.393675+0200 homed Commission called for node ID 0x00000000DAA90CDA
default 12:50:34.393728+0200 homed Commissioning stage next step: 'SecurePairing' -> 'ReadCommissioningInfo'
default 12:50:34.393802+0200 homed Performing next commissioning step 'ReadCommissioningInfo'
default 12:50:34.393860+0200 homed Sending read request for commissioning information
error 12:50:34.393995+0200 homed Attempting to update an uninitialized progress state map for <private>
default 12:50:34.394076+0200 homed <<< [E:38437i S:29145 M:254168916] (S) Msg TX to 0:FFFFFFFB00000000 [0000] [BLE] --- Type 0001:02 (IM:ReadRequest)
error 12:50:34.394207+0200 homed SendMessage() to BLE failed: src/transport/raw/BLE.cpp:114: Success
default 12:50:34.589025+0200 homed >>> [E:38437i S:29145 M:232787671] (S) Msg RX from 0:FFFFFFFB00000000 [0000] --- Type 0001:05 (IM:ReportData)
default 12:50:34.589397+0200 homed Successfully finished commissioning step 'ReadCommissioningInfo'
default 12:50:34.589428+0200 homed Commissioning stage next step: 'ReadCommissioningInfo' -> 'ReadCommissioningInfo2'
default 12:50:34.589457+0200 homed Performing next commissioning step 'ReadCommissioningInfo2'
default 12:50:34.589596+0200 homed <<< [E:38438i S:29145 M:254168917] (S) Msg TX to 0:FFFFFFFB00000000 [0000] [BLE] --- Type 0001:02 (IM:ReadRequest)
error 12:50:34.589931+0200 homed SendMessage() to BLE failed: src/transport/raw/BLE.cpp:114: Success
default 12:50:34.709706+0200 homed >>> [E:38438i S:29145 M:232787672] (S) Msg RX from 0:FFFFFFFB00000000 [0000] --- Type 0001:05 (IM:ReportData)
default 12:50:34.709853+0200 homed ----- NetworkCommissioning Features: has WiFi. endpointid = 0
default 12:50:34.709913+0200 homed DeviceControllerDelegate Read Commissioning Info. VendorId 65521 ProductId 32768
default 12:50:34.710006+0200 homed Successfully finished commissioning step 'ReadCommissioningInfo2'
default 12:50:34.710074+0200 homed Commissioning stage next step: 'ReadCommissioningInfo2' -> 'ArmFailSafe'
default 12:50:34.710104+0200 homed Performing next commissioning step 'ArmFailSafe'
default 12:50:34.710167+0200 homed Arming failsafe (120 seconds)
default 12:50:34.710356+0200 homed <<< [E:38439i S:29145 M:254168918] (S) Msg TX to 0:FFFFFFFB00000000 [0000] [BLE] --- Type 0001:08 (IM:InvokeCommandRequest)
error 12:50:34.710825+0200 homed SendMessage() to BLE failed: src/transport/raw/BLE.cpp:114: Success
default 12:50:34.859998+0200 homed >>> [E:38439i S:29145 M:232787673] (S) Msg RX from 0:FFFFFFFB00000000 [0000] --- Type 0001:09 (IM:InvokeCommandResponse)
default 12:50:34.860178+0200 homed Received Command Response Data, Endpoint=0 Cluster=0x0000_0030 Command=0x0000_0001
default 12:50:34.860208+0200 homed Received ArmFailSafe response errorCode=0
default 12:50:34.860301+0200 homed Successfully finished commissioning step 'ArmFailSafe'
default 12:50:34.860330+0200 homed Commissioning stage next step: 'ArmFailSafe' -> 'ConfigRegulatory'
default 12:50:34.860357+0200 homed Performing next commissioning step 'ConfigRegulatory'
default 12:50:34.860383+0200 homed Setting Regulatory Config
default 12:50:34.860455+0200 homed No regulatory config supplied by controller, leaving as device default (2)
default 12:50:34.860647+0200 homed <<< [E:38440i S:29145 M:254168919] (S) Msg TX to 0:FFFFFFFB00000000 [0000] [BLE] --- Type 0001:08 (IM:InvokeCommandRequest)
error 12:50:34.861025+0200 homed SendMessage() to BLE failed: src/transport/raw/BLE.cpp:114: Success
default 12:50:35.015681+0200 homed >>> [E:38440i S:29145 M:232787674] (S) Msg RX from 0:FFFFFFFB00000000 [0000] --- Type 0001:09 (IM:InvokeCommandResponse)
default 12:50:35.015784+0200 homed Received Command Response Data, Endpoint=0 Cluster=0x0000_0030 Command=0x0000_0003
default 12:50:35.015856+0200 homed Received SetRegulatoryConfig response errorCode=0
default 12:50:35.015909+0200 homed Successfully finished commissioning step 'ConfigRegulatory'
default 12:50:35.015938+0200 homed Commissioning stage next step: 'ConfigRegulatory' -> 'SendPAICertificateRequest'
default 12:50:35.015965+0200 homed Performing next commissioning step 'SendPAICertificateRequest'
default 12:50:35.015994+0200 homed Sending request for PAI certificate
default 12:50:35.018840+0200 homed <<< [E:38441i S:29145 M:254168920] (S) Msg TX to 0:FFFFFFFB00000000 [0000] [BLE] --- Type 0001:08 (IM:InvokeCommandRequest)
error 12:50:35.018981+0200 homed SendMessage() to BLE failed: src/transport/raw/BLE.cpp:114: Success
default 12:50:35.285845+0200 homed >>> [E:38441i S:29145 M:232787675] (S) Msg RX from 0:FFFFFFFB00000000 [0000] --- Type 0001:09 (IM:InvokeCommandResponse)
default 12:50:35.286192+0200 homed Received Command Response Data, Endpoint=0 Cluster=0x0000_003E Command=0x0000_0003
default 12:50:35.286349+0200 homed Received certificate chain from the device
default 12:50:35.286585+0200 homed Successfully finished commissioning step 'SendPAICertificateRequest'
default 12:50:35.286669+0200 homed Commissioning stage next step: 'SendPAICertificateRequest' -> 'SendDACCertificateRequest'
default 12:50:35.286751+0200 homed Performing next commissioning step 'SendDACCertificateRequest'
default 12:50:35.286822+0200 homed Sending request for DAC certificate
default 12:50:35.287220+0200 homed <<< [E:38442i S:29145 M:254168921] (S) Msg TX to 0:FFFFFFFB00000000 [0000] [BLE] --- Type 0001:08 (IM:InvokeCommandRequest)
error 12:50:35.287380+0200 homed SendMessage() to BLE failed: src/transport/raw/BLE.cpp:114: Success
default 12:50:35.551409+0200 homed >>> [E:38442i S:29145 M:232787676] (S) Msg RX from 0:FFFFFFFB00000000 [0000] --- Type 0001:09 (IM:InvokeCommandResponse)
default 12:50:35.551493+0200 homed Received Command Response Data, Endpoint=0 Cluster=0x0000_003E Command=0x0000_0003
default 12:50:35.551542+0200 homed Received certificate chain from the device
default 12:50:35.551703+0200 homed Successfully finished commissioning step 'SendDACCertificateRequest'
default 12:50:35.551736+0200 homed Commissioning stage next step: 'SendDACCertificateRequest' -> 'SendAttestationRequest'
default 12:50:35.551763+0200 homed Performing next commissioning step 'SendAttestationRequest'
default 12:50:35.551789+0200 homed Sending Attestation Request to the device.
default 12:50:35.551976+0200 homed <<< [E:38443i S:29145 M:254168922] (S) Msg TX to 0:FFFFFFFB00000000 [0000] [BLE] --- Type 0001:08 (IM:InvokeCommandRequest)
error 12:50:35.552087+0200 homed SendMessage() to BLE failed: src/transport/raw/BLE.cpp:114: Success
default 12:50:35.709311+0200 homed WiFi scan completed: 3 results, 3.053 seconds, 0/0x0 noErr
default 12:50:35.709512+0200 homed HAPWACBrowser: WiFi scan finish: 3 results, status 0/0x0 noErr
default 12:50:35.709551+0200 homed HAPWACBrowser: WiFi scan found: CUWiFiDevice 0x3331, BSSID 18:7C:0B:12:FD:58, SSID '*** private ***', IE 105 bytes, RSSI -72, 0x0 < >
default 12:50:35.709578+0200 homed HAPWACBrowser: WiFi scan found: CUWiFiDevice 0x2C99, BSSID 00:5F:67:9A:30:BE, SSID 'Home-3wnB', IE 112 bytes, RSSI -38, 0x0 < >
default 12:50:36.215287+0200 homed >>> [E:38443i S:29145 M:232787677] (S) Msg RX from 0:FFFFFFFB00000000 [0000] --- Type 0001:09 (IM:InvokeCommandResponse)
default 12:50:36.215523+0200 homed Received Command Response Data, Endpoint=0 Cluster=0x0000_003E Command=0x0000_0001
default 12:50:36.215604+0200 homed Received Attestation Information from the device
default 12:50:36.216011+0200 homed Successfully finished commissioning step 'SendAttestationRequest'
default 12:50:36.216207+0200 homed Commissioning stage next step: 'SendAttestationRequest' -> 'AttestationVerification'
default 12:50:36.216238+0200 homed Performing next commissioning step 'AttestationVerification'
default 12:50:36.216268+0200 homed Verifying attestation
error 12:50:36.217619+0200 homed Failed in verifying 'Attestation Information' command received from the device: err 101. Look at AttestationVerificationResult enum to understand the errors
default 12:50:36.217649+0200 homed Changing fail-safe timer to 60 seconds to handle DA failure
default 12:50:36.217679+0200 homed Skipping arming failsafe: new time (60 seconds from now) before old time (118 seconds from now)
default 12:50:36.217749+0200 homed Device attestation completed, delegating continuation to client
default 12:50:36.217987+0200 homed MTRDeviceAttestationDelegateBridge::OnDeviceAttestationFailed completed with result: 101
error 12:50:36.218091+0200 homed Creating NSError from /Library/Caches/com.apple.xbs/Sources/CHIPFramework/connectedhomeip/src/darwin/Framework/CHIP/MTRDeviceAttestationDelegateBridge.mm:52: CHIP Error 0x00000013: Integrity check failed (context: (null))
default 12:50:37.207046+0200 homed Continuing commissioning after attestation failure for device ID 0x00000000DAA90CDA
default 12:50:37.207132+0200 homed Overriding attestation failure per client and continuing commissioning
default 12:50:37.207638+0200 homed Successfully finished commissioning step 'AttestationVerification'
default 12:50:37.207685+0200 homed Commissioning stage next step: 'AttestationVerification' -> 'SendOpCertSigningRequest'
default 12:50:37.208292+0200 homed Performing next commissioning step 'SendOpCertSigningRequest'
default 12:50:37.208806+0200 homed <<< [E:38444i S:29145 M:254168923] (S) Msg TX to 0:FFFFFFFB00000000 [0000] [BLE] --- Type 0001:08 (IM:InvokeCommandRequest)
error 12:50:37.208946+0200 homed SendMessage() to BLE failed: src/transport/raw/BLE.cpp:114: Success
default 12:50:38.163028+0200 homed >>> [E:38444i S:29145 M:232787678] (S) Msg RX from 0:FFFFFFFB00000000 [0000] --- Type 0001:09 (IM:InvokeCommandResponse)
default 12:50:38.163192+0200 homed Received Command Response Data, Endpoint=0 Cluster=0x0000_003E Command=0x0000_0005
default 12:50:38.163290+0200 homed Received certificate signing request from the device
default 12:50:38.163367+0200 homed Successfully finished commissioning step 'SendOpCertSigningRequest'
default 12:50:38.163428+0200 homed Commissioning stage next step: 'SendOpCertSigningRequest' -> 'ValidateCSR'
default 12:50:38.163531+0200 homed Performing next commissioning step 'ValidateCSR'
default 12:50:38.163748+0200 homed Successfully finished commissioning step 'ValidateCSR'
default 12:50:38.163821+0200 homed Commissioning stage next step: 'ValidateCSR' -> 'GenerateNOCChain'
default 12:50:38.163881+0200 homed Performing next commissioning step 'GenerateNOCChain'
default 12:50:38.163970+0200 homed Getting certificate chain for the device from the issuer
default 12:50:38.171606+0200 homed Generating operational certificate
default 12:50:38.172754+0200 homed Received callback from the CA for NOC Chain generation. Status /Library/Caches/com.apple.xbs/Sources/CHIPFramework/connectedhomeip/src/darwin/Framework/CHIP/MTROperationalCredentialsDelegate.mm:245: Success
default 12:50:38.173369+0200 homed Successfully finished commissioning step 'GenerateNOCChain'
default 12:50:38.173669+0200 homed Performing next commissioning step 'SendTrustedRootCert'
default 12:50:38.174127+0200 homed Sending root certificate to the device
default 12:50:38.174241+0200 homed <<< [E:38445i S:29145 M:254168924] (S) Msg TX to 0:FFFFFFFB00000000 [0000] [BLE] --- Type 0001:08 (IM:InvokeCommandRequest)
error 12:50:38.174323+0200 homed SendMessage() to BLE failed: src/transport/raw/BLE.cpp:114: Success
default 12:50:38.175514+0200 homed Sent root certificate to the device
default 12:50:38.459511+0200 homed >>> [E:38445i S:29145 M:232787679] (S) Msg RX from 0:FFFFFFFB00000000 [0000] --- Type 0001:09 (IM:InvokeCommandResponse)
default 12:50:38.459703+0200 homed Received Command Response Status for Endpoint=0 Cluster=0x0000_003E Command=0x0000_000B Status=0x0
default 12:50:38.459964+0200 homed Device confirmed that it has received the root certificate
default 12:50:38.460084+0200 homed Successfully finished commissioning step 'SendTrustedRootCert'
default 12:50:38.460133+0200 homed Commissioning stage next step: 'SendTrustedRootCert' -> 'SendNOC'
default 12:50:38.460205+0200 homed Performing next commissioning step 'SendNOC'
default 12:50:38.460364+0200 homed <<< [E:38446i S:29145 M:254168925] (S) Msg TX to 0:FFFFFFFB00000000 [0000] [BLE] --- Type 0001:08 (IM:InvokeCommandRequest)
error 12:50:38.460499+0200 homed SendMessage() to BLE failed: src/transport/raw/BLE.cpp:114: Success
default 12:50:38.460736+0200 homed Sent operational certificate to the device
default 12:50:38.830157+0200 homed >>> [E:38446i S:29145 M:232787680] (S) Msg RX from 0:FFFFFFFB00000000 [0000] --- Type 0001:09 (IM:InvokeCommandResponse)
default 12:50:38.830513+0200 homed Received Command Response Data, Endpoint=0 Cluster=0x0000_003E Command=0x0000_0008
default 12:50:38.830570+0200 homed Device returned status 0 on receiving the NOC
default 12:50:38.830620+0200 homed Operational credentials provisioned on device 0xb991f0000
default 12:50:38.830647+0200 homed DeviceControllerDelegate status updated: 0
default 12:50:38.831032+0200 homed Successfully finished commissioning step 'SendNOC'
default 12:50:38.831090+0200 homed No NetworkScan enabled or WiFi/Thread endpoint not specified, skipping ScanNetworks
default 12:50:38.831119+0200 homed Commissioning stage next step: 'SendNOC' -> 'WiFiNetworkSetup'
default 12:50:38.831145+0200 homed Performing next commissioning step 'WiFiNetworkSetup'
default 12:50:38.831857+0200 homed <<< [E:38447i S:29145 M:254168926] (S) Msg TX to 0:FFFFFFFB00000000 [0000] [BLE] --- Type 0001:08 (IM:InvokeCommandRequest)
error 12:50:38.831937+0200 homed SendMessage() to BLE failed: src/transport/raw/BLE.cpp:114: Success
default 12:50:38.969846+0200 homed >>> [E:38447i S:29145 M:232787681] (S) Msg RX from 0:FFFFFFFB00000000 [0000] --- Type 0001:09 (IM:InvokeCommandResponse)
default 12:50:38.969990+0200 homed Received Command Response Data, Endpoint=0 Cluster=0x0000_0031 Command=0x0000_0005
default 12:50:38.970024+0200 homed Received NetworkConfig response, networkingStatus=0
default 12:50:38.970114+0200 homed Successfully finished commissioning step 'WiFiNetworkSetup'
default 12:50:38.970153+0200 homed Commissioning stage next step: 'WiFiNetworkSetup' -> 'FailsafeBeforeWiFiEnable'
default 12:50:38.970187+0200 homed Performing next commissioning step 'FailsafeBeforeWiFiEnable'
default 12:50:38.970328+0200 homed Arming failsafe (129 seconds)
default 12:50:38.970623+0200 homed <<< [E:38448i S:29145 M:254168927] (S) Msg TX to 0:FFFFFFFB00000000 [0000] [BLE] --- Type 0001:08 (IM:InvokeCommandRequest)
error 12:50:38.970932+0200 homed SendMessage() to BLE failed: src/transport/raw/BLE.cpp:114: Success
default 12:50:39.120455+0200 homed >>> [E:38448i S:29145 M:232787682] (S) Msg RX from 0:FFFFFFFB00000000 [0000] --- Type 0001:09 (IM:InvokeCommandResponse)
default 12:50:39.121462+0200 homed Received Command Response Data, Endpoint=0 Cluster=0x0000_0030 Command=0x0000_0001
default 12:50:39.121630+0200 homed Received ArmFailSafe response errorCode=0
default 12:50:39.121870+0200 homed Successfully finished commissioning step 'FailsafeBeforeWiFiEnable'
default 12:50:39.121959+0200 homed Commissioning stage next step: 'FailsafeBeforeWiFiEnable' -> 'WiFiNetworkEnable'
default 12:50:39.122044+0200 homed Setting wifi connection time min = 60
default 12:50:39.122123+0200 homed Performing next commissioning step 'WiFiNetworkEnable'
default 12:50:39.122208+0200 homed SendCommand kWiFiNetworkEnable, supportsConcurrentConnection=false
default 12:50:39.122632+0200 homed <<< [E:38449i S:29145 M:254168928] (S) Msg TX to 0:FFFFFFFB00000000 [0000] [BLE] --- Type 0001:08 (IM:InvokeCommandRequest)
error 12:50:39.122869+0200 homed SendMessage() to BLE failed: src/transport/raw/BLE.cpp:114: Success
default 12:50:39.269973+0200 homed >>> [E:38449i S:29145 M:232787683] (S) Msg RX from 0:FFFFFFFB00000000 [0000] --- Type 0001:09 (IM:InvokeCommandResponse)
default 12:50:39.270109+0200 homed Received Command Response Data, Endpoint=0 Cluster=0x0000_0031 Command=0x0000_0005
default 12:50:39.270143+0200 homed Received failure response src/controller/TypedCommandCallback.h:127: CHIP Error 0x0000008E: Schema mismatch
error 12:50:39.270204+0200 homed Error on commissioning step 'WiFiNetworkEnable': 'src/controller/TypedCommandCallback.h:127: CHIP Error 0x0000008E: Schema mismatch'
default 12:50:39.270240+0200 homed Going from commissioning step 'WiFiNetworkEnable' with lastErr = 'src/controller/TypedCommandCallback.h:127: CHIP Error 0x0000008E: Schema mismatch' -> 'Cleanup'
default 12:50:39.270272+0200 homed Performing next commissioning step 'Cleanup' with completion status = 'src/controller/TypedCommandCallback.h:127: CHIP Error 0x0000008E: Schema mismatch'
default 12:50:39.270378+0200 homed Successfully finished commissioning step 'Cleanup'
default 12:50:39.270441+0200 homed Commissioning complete for node ID 0x00000000DAA90CDA: src/controller/TypedCommandCallback.h:127: CHIP Error 0x0000008E: Schema mismatch
default 12:50:39.270473+0200 homed DeviceControllerDelegate Commissioning complete. NodeId 3668511962 Status src/controller/TypedCommandCallback.h:127: CHIP Error 0x0000008E: Schema mismatch
error 12:50:39.271553+0200 homed Creating NSError from src/controller/TypedCommandCallback.h:127: CHIP Error 0x0000008E: Schema mismatch (context: (null))
error 12:50:39.271800+0200 homed [3668511962/3198599415(3918029532)] tag="hmmtrAccessoryServerStateChange" desc="Error in progress state" errorDomain="MTRErrorDomain" errorCode="1" state="29"
error 12:50:39.273642+0200 homed Attempting to update an uninitialized progress state map for <private>
error 12:50:39.273679+0200 homed [3668511962/3198599415(3918029532)] CHIP Accessory pairing failed: Error Domain=MTRErrorDomain Code=1 UserInfo={NSLocalizedDescription=<private>, errorCode=142}, <HMMTRAccessoryPairingEndContext, Step: HMMTRAccessoryPairingStep_Commissioning, Error: Error Domain=MTRErrorDomain Code=1 "General error: 142", Sourceerrordomain: MTRErrorDomain>
error 12:50:39.273943+0200 homed [3668511962/3198599415(3918029532)] Cleaning up state due to pairing failure <HMMTRAccessoryPairingEndContext, Step: HMMTRAccessoryPairingStep_Commissioning, Error: Error Domain=MTRErrorDomain Code=1 "General error: 142", Sourceerrordomain: MTRErrorDomain>
ESP-ROM:esp32c3-api1-20210207
Build:Feb 7 2021
rst:0x15 (USB_UART_CHIP_RESET),boot:0xd (SPI_FAST_FLASH_BOOT)
Saved PC:0x420371d4
0x420371d4 - async_io_mini::reactor::Registrations<_>::set_fds
at /Users/ewen/.cargo/git/checkouts/async-io-mini-e233321a2e3791f3/a070ca7/src/reactor.rs:184
SPIWP:0xee
mode:DIO, clock div:2
load:0x3fcd5820,len:0x1714
load:0x403cc710,len:0x968
load:0x403ce710,len:0x2f9c
entry 0x403cc710
I (24) boot: ESP-IDF v5.1.2-342-gbcf1645e44 2nd stage bootloader
I (24) boot: compile time Dec 12 2023 10:50:58
I (25) boot: chip revision: v0.4
I (29) boot.esp32c3: SPI Speed : 40MHz
I (34) boot.esp32c3: SPI Mode : DIO
I (38) boot.esp32c3: SPI Flash Size : 4MB
I (43) boot: Enabling RNG early entropy source...
I (48) boot: Partition Table:
I (52) boot: ## Label Usage Type ST Offset Length
I (59) boot: 0 nvs WiFi data 01 02 00009000 00006000
I (67) boot: 1 phy_init RF data 01 01 0000f000 00001000
I (74) boot: 2 factory factory app 00 00 00010000 00300000
I (82) boot: End of partition table
I (86) esp_image: segment 0: paddr=00010020 vaddr=3c1b0020 size=74150h (475472) map
I (200) esp_image: segment 1: paddr=00084178 vaddr=3fc92c00 size=0bea0h ( 48800) load
I (212) esp_image: segment 2: paddr=00090020 vaddr=42000020 size=1a5714h (1726228) map
I (595) esp_image: segment 3: paddr=0023573c vaddr=3fc9eaa0 size=04174h ( 16756) load
I (600) esp_image: segment 4: paddr=002398b8 vaddr=40380000 size=12bc8h ( 76744) load
I (629) boot: Loaded app from partition at offset 0x10000
I (629) boot: Disabling RNG early entropy source...
I (641) cpu_start: Unicore app
I (641) cpu_start: Pro cpu up.
I (650) cpu_start: Pro cpu start user code
I (650) cpu_start: cpu freq: 160000000 Hz
I (650) cpu_start: Application information:
I (653) cpu_start: Project name: libespidf
I (658) cpu_start: App version: eb6ec2b-dirty
I (663) cpu_start: Compile time: Jun 1 2024 12:47:06
I (669) cpu_start: ELF file SHA256: 0000000000000000...
I (675) cpu_start: ESP-IDF: v5.1.2
I (680) cpu_start: Min chip rev: v0.3
I (685) cpu_start: Max chip rev: v0.99
I (690) cpu_start: Chip rev: v0.4
I (695) heap_init: Initializing. RAM available for dynamic allocation:
I (702) heap_init: At 3FCA7690 len 00018970 (98 KiB): DRAM
I (708) heap_init: At 3FCC0000 len 0001C710 (113 KiB): DRAM/RETENTION
I (715) heap_init: At 3FCDC710 len 00002950 (10 KiB): DRAM/RETENTION/STACK
I (723) heap_init: At 50000010 len 00001FD8 (7 KiB): RTCRAM
I (730) spi_flash: detected chip: generic
I (733) spi_flash: flash io: dio
W (738) timer_group: legacy driver is deprecated, please migrate to `driver/gptimer.h`
I (746) sleep: Configure to isolate all GPIO pins in sleep state
I (753) sleep: Enable automatic switching of GPIO sleep configuration
I (760) coexist: coex firmware version: b6d5e8c
I (765) coexist: coexist rom version 9387209
I (770) app_start: Starting scheduler on CPU0
I (775) main_task: Started on CPU0
I (775) main_task: Calling app_main()
I (785) light: Starting...
I (785) esp_idf_matter::stack: Async IO initialized; using `async-io-mini`
I (805) esp_idf_matter::stack::wifible: Matter Stack memory: 52400B
I (805) esp_idf_svc::bt: Init bluetooth controller
I (805) BLE_INIT: BT controller compile version [59725b5]
I (805) BLE_INIT: Bluetooth MAC: dc:da:0c:88:be:92
I (815) esp_idf_svc::bt: Enable bluetooth controller
I (825) phy_init: phy_version 1130,b4e4b80,Sep 5 2023,11:09:30
I (855) esp_idf_svc::bt: Init bluedroid
I (875) esp_idf_svc::bt: Enable bluedroid
I (885) esp_idf_matter::stack::wifible: BLE driver initialized
I (885) esp_idf_matter::stack::wifible: Running Matter in commissioning mode (BLE)
I (885) esp_idf_matter::ble: BLE Gap and Gatts initialized
I (895) esp_idf_matter::ble: BLE Gap and Gatts subscriptions initialized
I (915) esp_idf_matter::ble: Gatts BTP app registered
I (915) esp_idf_matter::stack: Responder memory: Responder=160B, Runner=10496B
I (915) rs_matter::respond: Responder: Creating 4 handlers
I (925) rs_matter::respond: Responder: Handlers size: 7976B
I (925) rs_matter::respond: Busy Responder: Creating 2 handlers
I (935) rs_matter::respond: Busy Responder: Handlers size: 648B
I (945) rs_matter::pairing::code: Pairing Code: 0087-6800-071
I (945) rs_matter::pairing::qr: QR Code Text: MT:Y.K90KQS02Z6Q66D33P084L90Z.I332SQ43I15T0
I (1005) rs_matter::pairing::qr: █████████████████████████████████████
I (1005) rs_matter::pairing::qr: █████████████████████████████████████
I (1025) rs_matter::pairing::qr: ████ ▄▄▄▄▄ █ ▄▄▄ ██▄ █ ▄ █ ▄▄▄▄▄ ████
I (1035) rs_matter::pairing::qr: ████ █ █ █▄▄▀▀▀██▄ ▄ █▄█ █ █ ████
I (1045) rs_matter::pairing::qr: ████ █▄▄▄█ █▄▀▀▀▄█▄ █▀▀ █ █▄▄▄█ ████
I (1055) rs_matter::pairing::qr: ████▄▄▄▄▄▄▄█▄█ █ ▀▄▀ █ ▀▄█▄▄▄▄▄▄▄████
I (1075) rs_matter::pairing::qr: ████ ██ ▄ ▄▄ ▀██▄ ██▀▀ ▄█▄▀▀ ▀▄ ████
I (1085) rs_matter::pairing::qr: ████▀ ▀ █▄▄█▄▀▄▄ █▄ ▀███▀▀ ▄ ▀ ████
I (1095) rs_matter::pairing::qr: ████ ▀▀▀▄▄▄█▀▀ ▄ ▀▄ ▀ █▀ ██ ▄▄▀▀████
I (1105) rs_matter::pairing::qr: ████ ▀█ ▄▄ ▀ ██▀▄█▀▄▀█▀▀▄▀▀ ▄█ █████
I (1125) rs_matter::pairing::qr: ████ ▀█▄▀▄▀▀▀▀█▄▀ █ ▄█▀█▄█▀▄█▀▀▄████
I (1135) rs_matter::pairing::qr: ████ █▀ ▄ ▀▀ █▄█▀▄█▄▄ ▀▄█ ▀█ ▀████
I (1145) rs_matter::pairing::qr: ████▄▄▄███▄█▀▀▀ █▄ ▄▄▀██ ▄▄▄ ▀█▀█████
I (1165) rs_matter::pairing::qr: ████ ▄▄▄▄▄ █ ▄ ▄ █ ▀█▄ ▀ █▄█ █▀ ████
I (1175) rs_matter::pairing::qr: ████ █ █ █ █ █▄▄▄█▄▀█▀ ▄▄ ▄█▄▀▄████
I (1185) rs_matter::pairing::qr: ████ █▄▄▄█ ██▀▀▄▀▄█▄ ▄▀▄▀▄ ▀██▄▄████
I (1195) rs_matter::pairing::qr: ████▄▄▄▄▄▄▄█▄██▄█▄█▄█▄▄▄▄▄█▄▄█▄▄█████
I (1215) rs_matter::pairing::qr: █████████████████████████████████████
I (1225) rs_matter::pairing::qr: █████████████████████████████████████
I (1245) rs_matter::transport::core: Running Matter transport
I (1245) rs_matter::transport::core: Waiting for orphaned RX packets
I (6255) light: Light toggled
I (11265) light: Light toggled
I (16265) light: Light toggled
I (21265) light: Light toggled
I (26275) light: Light toggled
I (31275) light: Light toggled
I (34735) rs_matter::transport::network::btp::session:
>>>>> (BTP IO) 67:59:B3:F7:F0:D3 [H|M|B|E,OP:6c]
HANDSHAKE REQ HandshakeReq { versions: 4, mtu: 517, window_size: 6 }
Selected version: 4, MTU: 244, window size: 6
I (34925) rs_matter::transport::network::btp::context: Subscribe request from 67:59:B3:F7:F0:D3
I (34925) rs_matter::transport::network::btp::session:
<<<<< (BTP IO) 67:59:B3:F7:F0:D3 [H|M|B|E,OP:6c]
HANDSHAKE RESP HandshakeResp { version: 4, mtu: 244, window_size: 6 }
I (34985) rs_matter::transport::network::btp::session:
>>>>> (BTP IO) 67:59:B3:F7:F0:D3 [A|B|E,ACTR:0,CTR:0,LEN:62]
READ 98B
I (34995) rs_matter::transport::session: Creating a new exchange: 961f/Responder(AcceptPending)
I (34995) rs_matter::transport::core:
>>>>> BTP 67:59:B3:F7:F0:D3 [S,SID:0,CTR:dff6929,SRC:991295173648cbc][I,EID:961f,PROTO:0,OP:20]
SC::PBKDFParamRequest
=> Processing (new exchange)
I (35015) rs_matter::transport::core: Exchange 0::0: Accepted
I (35015) rs_matter::respond: Responder: Handler 0 / exchange 0::0: Starting
I (35035) rs_matter::transport::exchange:
<<<<< BTP 67:59:B3:F7:F0:D3 [U,SID:0,CTR:5965c79,DST:991295173648cbc][EID:961f,PROTO:0,OP:21]
SC::PBKDFParamResponse
=> Sending
I (35045) rs_matter::transport::network::btp::session:
<<<<< (BTP IO) 67:59:B3:F7:F0:D3 [A|B|E,ACTR:0,CTR:1,LEN:8b]
WRITE 139B
I (35105) rs_matter::transport::network::btp::session:
>>>>> (BTP IO) 67:59:B3:F7:F0:D3 [A|B|E,ACTR:1,CTR:1,LEN:5c]
READ 92B
I (35115) rs_matter::transport::core:
>>>>> BTP 67:59:B3:F7:F0:D3 [S,SID:0,CTR:dff692a,SRC:991295173648cbc][I,EID:961f,PROTO:0,OP:22]
SC::PASEPake1
=> Processing
I (38595) rs_matter::transport::exchange:
<<<<< BTP 67:59:B3:F7:F0:D3 [U,SID:0,CTR:5965c7a,DST:991295173648cbc][EID:961f,PROTO:0,OP:23]
SC::PASEPake2
=> Sending
I (38605) rs_matter::transport::network::btp::session:
<<<<< (BTP IO) 67:59:B3:F7:F0:D3 [A|B|E,ACTR:1,CTR:2,LEN:7f]
WRITE 127B
I (38615) light: Light toggled
I (38675) rs_matter::transport::network::btp::session:
>>>>> (BTP IO) 67:59:B3:F7:F0:D3 [A|B|E,ACTR:2,CTR:2,LEN:3b]
READ 59B
I (38685) rs_matter::transport::core:
>>>>> BTP 67:59:B3:F7:F0:D3 [S,SID:0,CTR:dff692b,SRC:991295173648cbc][I,EID:961f,PROTO:0,OP:24]
SC::PASEPake3
=> Processing
I (38695) rs_matter::transport::exchange:
<<<<< BTP 67:59:B3:F7:F0:D3 [U,SID:0,CTR:5965c7b,DST:991295173648cbc][EID:961f,PROTO:0,OP:40]
SC::StatusReport
=> Sending
I (38705) rs_matter::respond: Responder: Handler 0 / exchange 0::0: Completed
I (38715) rs_matter::transport::network::btp::session:
<<<<< (BTP IO) 67:59:B3:F7:F0:D3 [A|B|E,ACTR:2,CTR:3,LEN:1e]
WRITE 30B
I (38795) rs_matter::transport::network::btp::session:
>>>>> (BTP IO) 67:59:B3:F7:F0:D3 [A|B|E,ACTR:3,CTR:3,LEN:33]
READ 51B
I (38805) rs_matter::transport::session: Creating a new exchange: 9620/Responder(AcceptPending)
I (38805) rs_matter::transport::core:
>>>>> BTP 67:59:B3:F7:F0:D3 [SID:1,CTR:f264f4f][I,EID:9620,PROTO:1,OP:2]
IM::ReadRequest
=> Processing (new exchange)
I (38825) rs_matter::transport::core: Exchange 1::0: Accepted
I (38825) rs_matter::respond: Responder: Handler 0 / exchange 1::0: Starting
I (38835) rs_matter::transport::exchange:
<<<<< BTP 67:59:B3:F7:F0:D3 [SID:71d9,CTR:de00ed2][EID:9620,PROTO:1,OP:5]
IM::ReportData
=> Sending
I (38855) rs_matter::respond: Responder: Handler 0 / exchange 1::0: Completed
I (38855) rs_matter::transport::network::btp::session:
<<<<< (BTP IO) 67:59:B3:F7:F0:D3 [A|B|E,ACTR:3,CTR:4,LEN:41]
WRITE 65B
I (38915) rs_matter::transport::network::btp::session:
>>>>> (BTP IO) 67:59:B3:F7:F0:D3 [A|B|E,ACTR:4,CTR:4,LEN:33]
READ 51B
I (38925) rs_matter::transport::session: Creating a new exchange: 9621/Responder(AcceptPending)
I (38925) rs_matter::transport::core:
>>>>> BTP 67:59:B3:F7:F0:D3 [SID:1,CTR:f264f50][I,EID:9621,PROTO:1,OP:2]
IM::ReadRequest
=> Processing (new exchange)
I (38945) rs_matter::transport::core: Exchange 1::1: Accepted
I (38945) rs_matter::respond: Responder: Handler 0 / exchange 1::1: Starting
I (38955) rs_matter::transport::exchange:
<<<<< BTP 67:59:B3:F7:F0:D3 [SID:71d9,CTR:de00ed3][EID:9621,PROTO:1,OP:5]
IM::ReportData
=> Sending
I (38975) rs_matter::respond: Responder: Handler 0 / exchange 1::1: Completed
I (38975) rs_matter::transport::network::btp::session:
<<<<< (BTP IO) 67:59:B3:F7:F0:D3 [A|B|E,ACTR:4,CTR:5,LEN:53]
WRITE 83B
I (39035) rs_matter::transport::network::btp::session:
>>>>> (BTP IO) 67:59:B3:F7:F0:D3 [A|B|E,ACTR:5,CTR:5,LEN:34]
READ 52B
I (39045) rs_matter::transport::session: Creating a new exchange: 9622/Responder(AcceptPending)
I (39045) rs_matter::transport::core:
>>>>> BTP 67:59:B3:F7:F0:D3 [SID:1,CTR:f264f51][I,EID:9622,PROTO:1,OP:2]
IM::ReadRequest
=> Processing (new exchange)
I (39065) rs_matter::transport::core: Exchange 1::2: Accepted
I (39065) rs_matter::respond: Responder: Handler 0 / exchange 1::2: Starting
I (39075) rs_matter::transport::exchange:
<<<<< BTP 67:59:B3:F7:F0:D3 [SID:71d9,CTR:de00ed4][EID:9622,PROTO:1,OP:5]
IM::ReportData
=> Sending
I (39095) rs_matter::respond: Responder: Handler 0 / exchange 1::2: Completed
I (39095) rs_matter::transport::network::btp::session:
<<<<< (BTP IO) 67:59:B3:F7:F0:D3 [A|B|E,ACTR:5,CTR:6,LEN:40]
WRITE 64B
I (39185) rs_matter::transport::network::btp::session:
>>>>> (BTP IO) 67:59:B3:F7:F0:D3 [A|B|E,ACTR:6,CTR:6,LEN:33]
READ 51B
I (39195) rs_matter::transport::session: Creating a new exchange: 9623/Responder(AcceptPending)
I (39195) rs_matter::transport::core:
>>>>> BTP 67:59:B3:F7:F0:D3 [SID:1,CTR:f264f52][I,EID:9623,PROTO:1,OP:2]
IM::ReadRequest
=> Processing (new exchange)
I (39215) rs_matter::transport::core: Exchange 1::3: Accepted
I (39215) rs_matter::respond: Responder: Handler 0 / exchange 1::3: Starting
I (39225) rs_matter::transport::exchange:
<<<<< BTP 67:59:B3:F7:F0:D3 [SID:71d9,CTR:de00ed5][EID:9623,PROTO:1,OP:5]
IM::ReportData
=> Sending
I (39245) rs_matter::respond: Responder: Handler 0 / exchange 1::3: Completed
I (39245) rs_matter::transport::network::btp::session:
<<<<< (BTP IO) 67:59:B3:F7:F0:D3 [A|B|E,ACTR:6,CTR:7,LEN:3f]
WRITE 63B
I (39305) rs_matter::transport::network::btp::session:
>>>>> (BTP IO) 67:59:B3:F7:F0:D3 [A|B|E,ACTR:7,CTR:7,LEN:34]
READ 52B
I (39315) rs_matter::transport::session: Creating a new exchange: 9624/Responder(AcceptPending)
I (39315) rs_matter::transport::core:
>>>>> BTP 67:59:B3:F7:F0:D3 [SID:1,CTR:f264f53][I,EID:9624,PROTO:1,OP:2]
IM::ReadRequest
=> Processing (new exchange)
I (39335) rs_matter::transport::core: Exchange 1::4: Accepted
I (39335) rs_matter::respond: Responder: Handler 0 / exchange 1::4: Starting
I (39355) rs_matter::transport::exchange:
<<<<< BTP 67:59:B3:F7:F0:D3 [SID:71d9,CTR:de00ed6][EID:9624,PROTO:1,OP:5]
IM::ReportData
=> Sending
I (39365) rs_matter::respond: Responder: Handler 0 / exchange 1::4: Completed
I (39365) rs_matter::transport::network::btp::session:
<<<<< (BTP IO) 67:59:B3:F7:F0:D3 [A|B|E,ACTR:7,CTR:8,LEN:40]
WRITE 64B
I (39425) rs_matter::transport::network::btp::session:
>>>>> (BTP IO) 67:59:B3:F7:F0:D3 [A|B|E,ACTR:8,CTR:8,LEN:83]
READ 131B
I (39435) rs_matter::transport::session: Creating a new exchange: 9625/Responder(AcceptPending)
I (39435) rs_matter::transport::core:
>>>>> BTP 67:59:B3:F7:F0:D3 [SID:1,CTR:f264f54][I,EID:9625,PROTO:1,OP:2]
IM::ReadRequest
=> Processing (new exchange)
I (39455) rs_matter::transport::core: Exchange 1::0: Accepted
I (39455) rs_matter::respond: Responder: Handler 0 / exchange 1::0: Starting
I (39475) rs_matter::transport::exchange:
<<<<< BTP 67:59:B3:F7:F0:D3 [SID:71d9,CTR:de00ed7][EID:9625,PROTO:1,OP:5]
IM::ReportData
=> Sending
I (39485) rs_matter::respond: Responder: Handler 0 / exchange 1::0: Completed
I (39495) rs_matter::transport::network::btp::session:
<<<<< (BTP IO) 67:59:B3:F7:F0:D3 [A|B,ACTR:8,CTR:9,LEN:fe]
WRITE 239B
I (39505) rs_matter::transport::network::btp::session:
<<<<< (BTP IO) 67:59:B3:F7:F0:D3 [C|E,CTR:a]
WRITE 15B
I (39635) rs_matter::transport::network::btp::session:
>>>>> (BTP IO) 67:59:B3:F7:F0:D3 [A|B|E,ACTR:a,CTR:9,LEN:6a]
READ 106B
I (39645) rs_matter::transport::session: Creating a new exchange: 9626/Responder(AcceptPending)
I (39645) rs_matter::transport::core:
>>>>> BTP 67:59:B3:F7:F0:D3 [SID:1,CTR:f264f55][I,EID:9626,PROTO:1,OP:2]
IM::ReadRequest
=> Processing (new exchange)
I (39665) rs_matter::transport::core: Exchange 1::0: Accepted
I (39665) rs_matter::respond: Responder: Handler 0 / exchange 1::0: Starting
I (39685) rs_matter::transport::exchange:
<<<<< BTP 67:59:B3:F7:F0:D3 [SID:71d9,CTR:de00ed8][EID:9626,PROTO:1,OP:5]
IM::ReportData
=> Sending
I (39695) rs_matter::respond: Responder: Handler 0 / exchange 1::0: Completed
I (39695) rs_matter::transport::network::btp::session:
<<<<< (BTP IO) 67:59:B3:F7:F0:D3 [A|B|E,ACTR:9,CTR:b,LEN:c0]
WRITE 192B
I (39755) rs_matter::transport::network::btp::session:
>>>>> (BTP IO) 67:59:B3:F7:F0:D3 [A|B|E,ACTR:b,CTR:a,LEN:41]
READ 65B
I (39765) rs_matter::transport::session: Creating a new exchange: 9627/Responder(AcceptPending)
I (39765) rs_matter::transport::core:
>>>>> BTP 67:59:B3:F7:F0:D3 [SID:1,CTR:f264f56][I,EID:9627,PROTO:1,OP:8]
IM::InvokeRequest
=> Processing (new exchange)
I (39785) rs_matter::transport::core: Exchange 1::0: Accepted
I (39785) rs_matter::respond: Responder: Handler 0 / exchange 1::0: Starting
I (39795) rs_matter::data_model::sdm::general_commissioning: Handling command ARM Fail Safe
I (39805) rs_matter::transport::exchange:
<<<<< BTP 67:59:B3:F7:F0:D3 [SID:71d9,CTR:de00ed9][EID:9627,PROTO:1,OP:9]
IM::InvokeResponse
=> Sending
I (39825) rs_matter::respond: Responder: Handler 0 / exchange 1::0: Completed
I (39825) rs_matter::transport::network::btp::session:
<<<<< (BTP IO) 67:59:B3:F7:F0:D3 [A|B|E,ACTR:a,CTR:c,LEN:3f]
WRITE 63B
I (39905) rs_matter::transport::network::btp::session:
>>>>> (BTP IO) 67:59:B3:F7:F0:D3 [A|B|E,ACTR:c,CTR:b,LEN:46]
READ 70B
I (39915) rs_matter::transport::session: Creating a new exchange: 9628/Responder(AcceptPending)
I (39915) rs_matter::transport::core:
>>>>> BTP 67:59:B3:F7:F0:D3 [SID:1,CTR:f264f57][I,EID:9628,PROTO:1,OP:8]
IM::InvokeRequest
=> Processing (new exchange)
I (39935) rs_matter::transport::core: Exchange 1::0: Accepted
I (39935) rs_matter::respond: Responder: Handler 0 / exchange 1::0: Starting
I (39945) rs_matter::data_model::sdm::general_commissioning: Handling command Set Regulatory Config
I (39955) rs_matter::data_model::sdm::general_commissioning: Received country code: [78, 76]
I (39965) rs_matter::transport::exchange:
<<<<< BTP 67:59:B3:F7:F0:D3 [SID:71d9,CTR:de00eda][EID:9628,PROTO:1,OP:9]
IM::InvokeResponse
=> Sending
I (39985) rs_matter::respond: Responder: Handler 0 / exchange 1::0: Completed
I (39985) rs_matter::transport::network::btp::session:
<<<<< (BTP IO) 67:59:B3:F7:F0:D3 [A|B|E,ACTR:b,CTR:d,LEN:3f]
WRITE 63B
I (40055) rs_matter::transport::network::btp::session:
>>>>> (BTP IO) 67:59:B3:F7:F0:D3 [A|B|E,ACTR:d,CTR:c,LEN:3e]
READ 62B
I (40065) rs_matter::transport::session: Creating a new exchange: 9629/Responder(AcceptPending)
I (40065) rs_matter::transport::core:
>>>>> BTP 67:59:B3:F7:F0:D3 [SID:1,CTR:f264f58][I,EID:9629,PROTO:1,OP:8]
IM::InvokeRequest
=> Processing (new exchange)
I (40085) rs_matter::transport::core: Exchange 1::0: Accepted
I (40085) rs_matter::respond: Responder: Handler 0 / exchange 1::0: Starting
I (40095) rs_matter::data_model::sdm::noc: Handling command CertChainRequest
I (40105) rs_matter::data_model::sdm::noc: Received data: 1: {
I (40115) rs_matter::data_model::sdm::noc: Received Cert Type:2
I (40115) rs_matter::transport::exchange:
<<<<< BTP 67:59:B3:F7:F0:D3 [SID:71d9,CTR:de00edb][EID:9629,PROTO:1,OP:9]
IM::InvokeResponse
=> Sending
I (40145) rs_matter::respond: Responder: Handler 0 / exchange 1::0: Completed
I (40145) rs_matter::transport::network::btp::session:
<<<<< (BTP IO) 67:59:B3:F7:F0:D3 [A|B,ACTR:c,CTR:e,LEN:20c]
WRITE 239B
I (40155) rs_matter::transport::network::btp::session:
<<<<< (BTP IO) 67:59:B3:F7:F0:D3 [C,CTR:f]
WRITE 242B
I (40165) rs_matter::transport::network::btp::session:
<<<<< (BTP IO) 67:59:B3:F7:F0:D3 [C|E,CTR:10]
WRITE 43B
I (40325) rs_matter::transport::network::btp::session:
>>>>> (BTP IO) 67:59:B3:F7:F0:D3 [A|B|E,ACTR:10,CTR:d,LEN:3e]
READ 62B
I (40335) rs_matter::transport::session: Creating a new exchange: 962a/Responder(AcceptPending)
I (40335) rs_matter::transport::core:
>>>>> BTP 67:59:B3:F7:F0:D3 [SID:1,CTR:f264f59][I,EID:962a,PROTO:1,OP:8]
IM::InvokeRequest
=> Processing (new exchange)
I (40355) rs_matter::transport::core: Exchange 1::0: Accepted
I (40355) rs_matter::respond: Responder: Handler 0 / exchange 1::0: Starting
I (40365) rs_matter::data_model::sdm::noc: Handling command CertChainRequest
I (40375) rs_matter::data_model::sdm::noc: Received data: 1: {
I (40385) rs_matter::data_model::sdm::noc: Received Cert Type:1
I (40385) rs_matter::transport::exchange:
<<<<< BTP 67:59:B3:F7:F0:D3 [SID:71d9,CTR:de00edc][EID:962a,PROTO:1,OP:9]
IM::InvokeResponse
=> Sending
I (40415) rs_matter::respond: Responder: Handler 0 / exchange 1::0: Completed
I (40415) rs_matter::transport::network::btp::session:
<<<<< (BTP IO) 67:59:B3:F7:F0:D3 [A|B,ACTR:d,CTR:11,LEN:229]
WRITE 239B
I (40425) rs_matter::transport::network::btp::session:
<<<<< (BTP IO) 67:59:B3:F7:F0:D3 [C,CTR:12]
WRITE 242B
I (40435) rs_matter::transport::network::btp::session:
<<<<< (BTP IO) 67:59:B3:F7:F0:D3 [C|E,CTR:13]
WRITE 72B
I (40595) rs_matter::transport::network::btp::session:
>>>>> (BTP IO) 67:59:B3:F7:F0:D3 [A|B|E,ACTR:13,CTR:e,LEN:5e]
READ 94B
I (40605) rs_matter::transport::session: Creating a new exchange: 962b/Responder(AcceptPending)
I (40605) rs_matter::transport::core:
>>>>> BTP 67:59:B3:F7:F0:D3 [SID:1,CTR:f264f5a][I,EID:962b,PROTO:1,OP:8]
IM::InvokeRequest
=> Processing (new exchange)
I (40625) rs_matter::transport::core: Exchange 1::0: Accepted
I (40625) rs_matter::respond: Responder: Handler 0 / exchange 1::0: Starting
I (40635) rs_matter::data_model::sdm::noc: Handling command AttestationRequest
I (40645) rs_matter::data_model::sdm::noc: Received Attestation Nonce:OctetStr([96, 202, 133, 236, 115, 86, 37, 111, 44, 34, 53, 220, 35, 86, 168, 125, 204, 171, 249, 13, 39, 28, 10, 46, 158, 168, 95, 238, 213, 59, 245, 175])
I (41035) rs_matter::transport::exchange:
<<<<< BTP 67:59:B3:F7:F0:D3 [SID:71d9,CTR:de00edd][EID:962b,PROTO:1,OP:9]
IM::InvokeResponse
=> Sending
I (41055) rs_matter::respond: Responder: Handler 0 / exchange 1::0: Completed
I (41055) rs_matter::transport::network::btp::session:
<<<<< (BTP IO) 67:59:B3:F7:F0:D3 [A|B,ACTR:e,CTR:14,LEN:2ca]
WRITE 239B
I (41065) rs_matter::transport::network::btp::session:
<<<<< (BTP IO) 67:59:B3:F7:F0:D3 [C,CTR:15]
WRITE 242B
I (41075) rs_matter::transport::network::btp::session:
<<<<< (BTP IO) 67:59:B3:F7:F0:D3 [C|E,CTR:16]
WRITE 233B
I (42245) rs_matter::transport::network::btp::session:
>>>>> (BTP IO) 67:59:B3:F7:F0:D3 [A|B|E,ACTR:16,CTR:f,LEN:5e]
READ 94B
I (42255) rs_matter::transport::session: Creating a new exchange: 962c/Responder(AcceptPending)
I (42255) rs_matter::transport::core:
>>>>> BTP 67:59:B3:F7:F0:D3 [SID:1,CTR:f264f5b][I,EID:962c,PROTO:1,OP:8]
IM::InvokeRequest
=> Processing (new exchange)
I (42275) rs_matter::transport::core: Exchange 1::0: Accepted
I (42275) rs_matter::respond: Responder: Handler 0 / exchange 1::0: Starting
I (42285) rs_matter::data_model::sdm::noc: Handling command CSRRequest
I (42295) rs_matter::data_model::sdm::noc: Received CSR Nonce:OctetStr([121, 33, 130, 201, 219, 174, 197, 4, 170, 255, 244, 186, 96, 143, 246, 15, 175, 115, 123, 149, 199, 197, 157, 48, 127, 144, 234, 184, 110, 111, 171, 184])
I (43055) rs_matter::transport::exchange:
<<<<< BTP 67:59:B3:F7:F0:D3 [SID:71d9,CTR:de00ede][EID:962c,PROTO:1,OP:9]
IM::InvokeResponse
=> Sending
I (43065) rs_matter::respond: Responder: Handler 0 / exchange 1::0: Completed
I (43075) rs_matter::transport::network::btp::session:
<<<<< (BTP IO) 67:59:B3:F7:F0:D3 [A|B,ACTR:f,CTR:17,LEN:172]
WRITE 239B
I (43085) rs_matter::transport::network::btp::session:
<<<<< (BTP IO) 67:59:B3:F7:F0:D3 [C|E,CTR:18]
WRITE 131B
I (43205) rs_matter::transport::network::btp::session:
>>>>> (BTP IO) 67:59:B3:F7:F0:D3 [A|B,ACTR:18,CTR:10,LEN:134]
READ 239B
I (43265) rs_matter::transport::network::btp::session:
>>>>> (BTP IO) 67:59:B3:F7:F0:D3 [C|E,CTR:11]
READ 69B
I (43275) rs_matter::transport::session: Creating a new exchange: 962d/Responder(AcceptPending)
I (43275) rs_matter::transport::core:
>>>>> BTP 67:59:B3:F7:F0:D3 [SID:1,CTR:f264f5c][I,EID:962d,PROTO:1,OP:8]
IM::InvokeRequest
=> Processing (new exchange)
I (43295) rs_matter::transport::core: Exchange 1::0: Accepted
I (43305) rs_matter::respond: Responder: Handler 0 / exchange 1::0: Starting
I (43315) rs_matter::data_model::sdm::noc: Handling command AddTrustedRootCert
I (43315) rs_matter::data_model::sdm::noc: Received Trusted Cert:OctetStr([15, 30, 1, 1, 0, 24, 2, 1, 37, 3, 26, 14, 34, 4, f8, 4, 26, 15, f7, c0, a6, be, 18, 26, 4, 83, 1f, 53, 2c, 24, 5, 0, 37, 6, 26, 14, 34, 4, f8, 4, 26, 15, f7, c0, a6, be, 18, 24, 7, 1, 24, 8, 1, 30, 9, 41, 4, 59, 1b, 81, 31, 2, 6f, ef, c5, 71, 1a, f, a5, 94, b8, f1, b, 64, 15, d2, 5e, 22, 24, 4, 94, b8, 86, 5a, 8e, db, e8, 2b, 25, e0, 7d, 2c, a1, f6, 6b, 7d, bb, e8, 7, ca, dc, e0, d0, bb, 14, 10, 3d, 6c, c0, d9, 4a, 71, 77, da, 1e, 95, 97, c0, 94, 2d, 64, 37, a, 35, 1, 29, 1, 18, 24, 2, 60, 30, 4, 14, 65, 75, 90, c7, 9b, 47, f5, 43, 80, c9, d3, 14, 4f, 1, 9, be, 80, cf, e9, 41, 30, 5, 14, 65, 75, 90, c7, 9b, 47, f5, 43, 80, c9, d3, 14, 4f, 1, 9, be, 80, cf, e9, 41, 18, 30, b, 40, d8, e7, 2d, ff, 72, 36, aa, 6b, 86, 2c, 8a, b0, c6, 40, 57, f3, 97, f5, 64, f0, 5b, 12, bc, 42, 4b, 75, fe, 17, a5, 3, 5, 24, 9c, a1, 73, 84, 65, 9f, b6, 5c, db, e, 18, d4, 71, fa, 9a, f8, c6, 9b, 3f, f, 2f, ef, 5, d8, bd, 24, ad, c8, 5d, ac, 3f, b9, 18])
I (43405) rs_matter::transport::exchange:
<<<<< BTP 67:59:B3:F7:F0:D3 [SID:71d9,CTR:de00edf][EID:962d,PROTO:1,OP:9]
IM::InvokeResponse
=> Sending
I (43425) rs_matter::respond: Responder: Handler 0 / exchange 1::0: Completed
I (43435) rs_matter::transport::network::btp::session:
<<<<< (BTP IO) 67:59:B3:F7:F0:D3 [A|B|E,ACTR:11,CTR:19,LEN:3f]
WRITE 63B
I (43505) rs_matter::transport::network::btp::session:
>>>>> (BTP IO) 67:59:B3:F7:F0:D3 [A|B,ACTR:19,CTR:12,LEN:15b]
READ 239B
I (43565) rs_matter::transport::network::btp::session:
>>>>> (BTP IO) 67:59:B3:F7:F0:D3 [C|E,CTR:13]
READ 108B
I (43575) rs_matter::transport::session: Creating a new exchange: 962e/Responder(AcceptPending)
I (43585) rs_matter::transport::core:
>>>>> BTP 67:59:B3:F7:F0:D3 [SID:1,CTR:f264f5d][I,EID:962e,PROTO:1,OP:8]
IM::InvokeRequest
=> Processing (new exchange)
I (43595) rs_matter::transport::core: Exchange 1::0: Accepted
I (43605) rs_matter::respond: Responder: Handler 0 / exchange 1::0: Starting
I (43615) rs_matter::data_model::sdm::noc: Handling command AddNOC
I (43615) rs_matter::data_model::sdm::noc: Received NOC as: Version: [0]
[2]
Serial Num: [1]
Signature Algorithm:
ECDSA with SHA256
Issuer:
Chip Root CA Id:
"0000000004F80434"
Chip Fabric Id:
"00000000BEA6C0F7"
Validity:
Not Before: 2024-06-01 10:50:38.0 +00:00:00
Not After: 9999-12-31 23:59:59.0 +00:00:00
Subject:
Chip Fabric Id:
"00000000BEA6C0F7"
Chip Node Id:
"00000000DAA90CDA"
Public Key Algorithm
ECPubKey
Prime256v1
Public-Key: [4, b6, e7, 6b, fc, 67, 79, d, 1c, 33, 78, 63, ec, 4f, e2, a9, 6, ff, 36, ad, 9e, d6, d8, 24, d7, 1c, 3c, 3a, 58, d5, 5d, b, e9, 9f, d5, a4, 92, cb, 79, cc, 2d, c3, 2a, f4, d1, a3, c5, ae, 7d, d0, e1, 30, a8, 1e, 7c, ce, f6, 3e, 91, aa, d, 59, 84, 5f, 5f]
X509v3 extensions: [3]
X509v3 Basic Constraints
critical: true
value:
X509v3 Key Usage
critical: true
value:
digitalSignature [80, 0]
X509v3 Extended Key Usage
critical: true
value:
ClientAuth
ServerAuth
Subject Key ID
value:
[a1, ae, 68, 2b, 14, 53, 8e, 9c, 1b, ae, b6, 77, b5, 53, e1, fb, 7a, a8, cc, 50]
Auth Key ID
value:
[0][65, 75, 90, c7, 9b, 47, f5, 43, 80, c9, d3, 14, 4f, 1, 9, be, 80, cf, e9, 41]
Signature: [a3, e0, d2, 8f, b8, fe, e6, 5e, 72, ff, 9b, 73, 10, 3, 8b, e, 7f, 4c, 6e, 90, d8, 9c, 8c, 91, f3, 2f, 50, 71, 4c, 16, 10, 43, a4, d2, cb, e7, 28, 4a, f5, 45, 17, b0, 8c, 81, c3, d6, 99, 94, d4, 98, ce, 64, 2c, 2, 68, b, 8f, 9f, 40, 7d, 16, 5d, 8b, 7b]
I (43785) rs_matter::fabric: MDNS Service Name: 1BB7D1A63D26A524-00000000DAA90CDA
I (43785) rs_matter::transport::exchange:
<<<<< BTP 67:59:B3:F7:F0:D3 [SID:71d9,CTR:de00ee0][EID:962e,PROTO:1,OP:9]
IM::InvokeResponse
=> Sending
I (43805) rs_matter::respond: Responder: Handler 0 / exchange 1::0: Completed
I (43805) rs_matter::transport::network::btp::session:
<<<<< (BTP IO) 67:59:B3:F7:F0:D3 [A|B|E,ACTR:13,CTR:1a,LEN:42]
WRITE 66B
I (43825) light: Light toggled
I (43865) rs_matter::transport::network::btp::session:
>>>>> (BTP IO) 67:59:B3:F7:F0:D3 [A|B|E,ACTR:1a,CTR:14,LEN:5b]
READ 91B
I (43875) rs_matter::transport::session: Creating a new exchange: 962f/Responder(AcceptPending)
I (43875) rs_matter::transport::core:
>>>>> BTP 67:59:B3:F7:F0:D3 [SID:1,CTR:f264f5e][I,EID:962f,PROTO:1,OP:8]
IM::InvokeRequest
=> Processing (new exchange)
I (43895) rs_matter::transport::core: Exchange 1::0: Accepted
I (43895) rs_matter::respond: Responder: Handler 0 / exchange 1::0: Starting
I (43915) esp_idf_matter::wifi::comm: AddOrUpdateWifiNetwork
I (43915) esp_idf_matter::wifi::comm: Added network with SSID Home-3wnB
I (43925) rs_matter::transport::exchange:
<<<<< BTP 67:59:B3:F7:F0:D3 [SID:71d9,CTR:de00ee1][EID:962f,PROTO:1,OP:9]
IM::InvokeResponse
=> Sending
I (43935) rs_matter::respond: Responder: Handler 0 / exchange 1::0: Completed
I (43945) rs_matter::transport::network::btp::session:
<<<<< (BTP IO) 67:59:B3:F7:F0:D3 [A|B|E,ACTR:14,CTR:1b,LEN:3f]
WRITE 63B
I (44015) rs_matter::transport::network::btp::session:
>>>>> (BTP IO) 67:59:B3:F7:F0:D3 [A|B|E,ACTR:1b,CTR:15,LEN:41]
READ 65B
I (44025) rs_matter::transport::session: Creating a new exchange: 9630/Responder(AcceptPending)
I (44025) rs_matter::transport::core:
>>>>> BTP 67:59:B3:F7:F0:D3 [SID:1,CTR:f264f5f][I,EID:9630,PROTO:1,OP:8]
IM::InvokeRequest
=> Processing (new exchange)
I (44045) rs_matter::transport::core: Exchange 1::0: Accepted
I (44045) rs_matter::respond: Responder: Handler 0 / exchange 1::0: Starting
I (44055) rs_matter::data_model::sdm::general_commissioning: Handling command ARM Fail Safe
I (44065) rs_matter::transport::exchange:
<<<<< BTP 67:59:B3:F7:F0:D3 [SID:71d9,CTR:de00ee2][EID:9630,PROTO:1,OP:9]
IM::InvokeResponse
=> Sending
I (44085) rs_matter::respond: Responder: Handler 0 / exchange 1::0: Completed
I (44095) rs_matter::transport::network::btp::session:
<<<<< (BTP IO) 67:59:B3:F7:F0:D3 [A|B|E,ACTR:15,CTR:1c,LEN:3f]
WRITE 63B
I (44165) rs_matter::transport::network::btp::session:
>>>>> (BTP IO) 67:59:B3:F7:F0:D3 [A|B|E,ACTR:1c,CTR:16,LEN:4a]
READ 74B
I (44175) rs_matter::transport::session: Creating a new exchange: 9631/Responder(AcceptPending)
I (44175) rs_matter::transport::core:
>>>>> BTP 67:59:B3:F7:F0:D3 [SID:1,CTR:f264f60][I,EID:9631,PROTO:1,OP:8]
IM::InvokeRequest
=> Processing (new exchange)
I (44195) rs_matter::transport::core: Exchange 1::0: Accepted
I (44195) rs_matter::respond: Responder: Handler 0 / exchange 1::0: Starting
I (44205) esp_idf_matter::wifi::comm: ConnectNetwork
I (44215) esp_idf_matter::wifi::comm: Request to connect to network with SSID Home-3wnB received
I (44225) rs_matter::transport::exchange:
<<<<< BTP 67:59:B3:F7:F0:D3 [SID:71d9,CTR:de00ee3][EID:9631,PROTO:1,OP:9]
IM::InvokeResponse
=> Sending
I (44235) rs_matter::respond: Responder: Handler 0 / exchange 1::0: Completed
I (44245) rs_matter::transport::network::btp::session:
<<<<< (BTP IO) 67:59:B3:F7:F0:D3 [A|B|E,ACTR:16,CTR:1d,LEN:3f]
WRITE 63B
W (44255) esp_idf_matter::wifi: Giving BLE/BTP extra 4 seconds for any outstanding messages before switching to Wifi
I (46805) rs_matter::transport::network::btp::session:
>>>>> (BTP IO) 67:59:B3:F7:F0:D3 [A,ACTR:1d,CTR:17]
READ 0B
W (48275) BT_HCI: hci cmd send: disconnect: hdl 0x1, rsn:0x13
W (48305) BT_HCI: hcif disc complete: hdl 0x1, rsn 0x16
I (49305) pp: pp rom version: 9387209
I (49305) net80211: net80211 rom version: 9387209
I (49325) wifi:wifi driver task: 3fcbf55c, prio:23, stack:6656, core=0
I (49325) wifi:wifi firmware version: 91b9630
I (49325) wifi:wifi certification version: v7.0
I (49325) wifi:config NVS flash: enabled
I (49325) wifi:config nano formating: disabled
I (49335) wifi:Init data frame dynamic rx buffer num: 32
I (49335) wifi:Init static rx mgmt buffer num: 10
I (49345) wifi:Init management short buffer num: 32
I (49345) wifi:Init dynamic tx buffer num: 32
I (49355) wifi:Init static tx FG buffer num: 2
I (49355) wifi:Init static rx buffer size: 1600
I (49355) wifi:Init static rx buffer num: 10
I (49365) wifi:Init dynamic rx buffer num: 32
I (49365) wifi_init: rx ba win: 6
I (49375) wifi_init: tcpip mbox: 32
I (49375) wifi_init: udp mbox: 6
I (49375) wifi_init: tcp mbox: 6
I (49385) wifi_init: tcp tx win: 5744
I (49385) wifi_init: tcp rx win: 5744
I (49395) wifi_init: tcp mss: 1440
I (49395) wifi_init: WiFi IRAM OP enabled
I (49405) wifi_init: WiFi RX IRAM OP enabled
I (49405) esp_idf_matter::stack::wifible: Wifi driver initialized
I (49415) esp_idf_matter::stack::wifible: Running Matter in operating mode (Wifi)
I (49425) esp_idf_matter::wifi: Trying with requested network first - SSID: Home-3wnB
I (49435) esp_idf_matter::wifi::mgmt: Connecting to SSID Home-3wnB
I (49435) esp_idf_matter::wifi::mgmt: Connecting with Client(ClientConfiguration { ssid: "Home-3wnB", bssid: None, auth_method: WPAWPA2Personal, channel: None, scan_method: CompleteScan(Signal), pmf_cfg: NotCapable })
I (49465) wifi:mode : sta (dc:da:0c:88:be:90)
I (49465) wifi:enable tsf
I (49475) esp_idf_matter::stack: Waiting for the network to come up...
I (49475) light: Light toggled
I (51885) wifi:new:<9,0>, old:<1,0>, ap:<255,255>, sta:<9,0>, prof:1
I (51885) wifi:state: init -> auth (b0)
I (51985) wifi:state: auth -> assoc (0)
I (51985) wifi:state: assoc -> run (10)
I (51995) wifi:connected with Home-3wnB, aid = 2, channel 9, BW20, bssid = 00:5f:67:9a:30:bf
I (51995) wifi:security: WPA2-PSK, phy: bg, rssi: -63
I (51995) wifi:pm start, type: 1
I (52005) wifi:set rx beacon pti, rx_bcn_pti: 14, bcn_timeout: 25000, mt_pti: 14, mt_time: 10000
I (52015) esp_idf_matter::wifi::mgmt: Successfully connected with Client(ClientConfiguration { ssid: "Home-3wnB", bssid: None, auth_method: WPAWPA2Personal, channel: None, scan_method: CompleteScan(Signal), pmf_cfg: NotCapable })
I (52035) esp_idf_matter::wifi::mgmt: Connected to SSID Home-3wnB
I (52035) wifi:AP's beacon interval = 102400 us, DTIM period = 2
I (53515) esp_netif_handlers: sta ip: 192.168.1.110, mask: 255.255.255.0, gw: 192.168.1.1
I (53515) esp_idf_matter::stack: Got IP network: IPv4: 192.168.1.110, IPv6: fe80::deda:cff:fe88:be90, Interface: 2, MAC: DC:DA:0C:88:BE:90
I (53525) esp_idf_matter::stack: Responder memory: Responder=160B, Runner=10496B
I (53535) rs_matter::respond: Responder: Creating 4 handlers
I (53535) rs_matter::respond: Responder: Handlers size: 7976B
I (53545) rs_matter::respond: Busy Responder: Creating 2 handlers
I (53555) rs_matter::respond: Busy Responder: Handlers size: 648B
I (53555) rs_matter::transport::core: Running Matter transport
I (53565) rs_matter::transport::core: Waiting for orphaned RX packets
I (53575) esp_idf_matter::multicast: Joined IP multicast 224.0.0.251/192.168.1.110
I (53585) esp_idf_matter::multicast: Joined IPV6 multicast ff02::fb/2
I (53585) rs_matter::transport::core: Running Matter built-in mDNS service
I (53595) rs_matter::mdns::builtin: Broadcasting mDNS entry to 224.0.0.251:5353
I (53605) rs_matter::mdns::builtin: Broadcasting mDNS entry to [ff02::fb%2]:5353
I (54485) light: Light toggled
I (57675) rs_matter::mdns::builtin: Replying to mDNS query from UDP [::ffff:192.168.1.114]:5353
I (57695) rs_matter::mdns::builtin: Replying to mDNS query from UDP [fe80::35:fa83:74e1:ef6d%2]:5353
I (59485) light: Light toggled
I (64485) light: Light toggled
I (67515) rs_matter::mdns::builtin: Replying to mDNS query from UDP [::ffff:192.168.1.114]:5353
I (67545) rs_matter::mdns::builtin: Replying to mDNS query from UDP [fe80::35:fa83:74e1:ef6d%2]:5353
I (67555) rs_matter::transport::session: Creating a new exchange: 9632/Responder(AcceptPending)
I (67555) rs_matter::transport::core:
>>>>> UDP [fe80::35:fa83:74e1:ef6d%2]:64698 [S,SID:0,CTR:dff692c,SRC:2b6ea949f012ec1a][I|R,EID:9632,PROTO:0,OP:30]
SC::CASESigma1
=> Processing (new exchange)
I (67575) rs_matter::transport::core: Exchange 2::0: Accepted
I (67585) rs_matter::respond: Responder: Handler 0 / exchange 2::0: Starting
I (68095) rs_matter::transport::exchange:
<<<<< UDP [fe80::35:fa83:74e1:ef6d%2]:64698 [U,SID:0,CTR:207d040,DST:2b6ea949f012ec1a][A|R,EID:9632,PROTO:0,OP:31,ACTR:dff692c]
SC::CASESigma2
=> Sending
I (68125) rs_matter::transport::core:
>>>>> UDP [fe80::35:fa83:74e1:ef6d%2]:64698 [S,SID:0,CTR:dff692d,SRC:2b6ea949f012ec1a][I|A|R,EID:9632,PROTO:0,OP:32,ACTR:207d040]
SC::CASESigma3
=> Processing
I (68915) rs_matter::transport::exchange:
<<<<< UDP [fe80::35:fa83:74e1:ef6d%2]:64698 [U,SID:0,CTR:207d041,DST:2b6ea949f012ec1a][A|R,EID:9632,PROTO:0,OP:40,ACTR:dff692d]
SC::StatusReport
=> Sending
I (68925) rs_matter::transport::core:
>>>>> UDP [fe80::35:fa83:74e1:ef6d%2]:64698 [S,SID:0,CTR:dff692d,SRC:2b6ea949f012ec1a][I|A|R,EID:9632,PROTO:0,OP:32,ACTR:207d040]
SC::CASESigma3
=> Duplicate, sending ACK
I (68945) rs_matter::transport::core:
<<<<< UDP [fe80::35:fa83:74e1:ef6d%2]:64698 [U,SID:0,CTR:207d042,DST:2b6ea949f012ec1a][A,EID:9632,PROTO:0,OP:10,ACTR:dff692d]
SC::MRPStandAloneAck
=> Sending (system)
I (68985) rs_matter::transport::core:
>>>>> UDP [fe80::35:fa83:74e1:ef6d%2]:64698 [S,SID:0,CTR:dff692d,SRC:2b6ea949f012ec1a][I|A|R,EID:9632,PROTO:0,OP:32,ACTR:207d040]
SC::CASESigma3
=> Duplicate, sending ACK
I (68995) rs_matter::transport::core:
<<<<< UDP [fe80::35:fa83:74e1:ef6d%2]:64698 [U,SID:0,CTR:207d043,DST:2b6ea949f012ec1a][A,EID:9632,PROTO:0,OP:10,ACTR:dff692d]
SC::MRPStandAloneAck
=> Sending (system)
I (69065) rs_matter::transport::core:
>>>>> UDP [fe80::35:fa83:74e1:ef6d%2]:64698 [S,SID:0,CTR:dff692e,SRC:2b6ea949f012ec1a][I|A,EID:9632,PROTO:0,OP:10,ACTR:207d041]
SC::MRPStandAloneAck
=> Standalone Ack, dropping
I (69085) rs_matter::respond: Responder: Handler 0 / exchange 2::0: Completed
I (69095) rs_matter::transport::session: Creating a new exchange: 9633/Responder(AcceptPending)
I (69105) rs_matter::transport::core:
>>>>> UDP [fe80::35:fa83:74e1:ef6d%2]:64698 [SID:1,CTR:97186cf][I|R,EID:9633,PROTO:1,OP:2]
IM::ReadRequest
=> Processing (new exchange)
I (69115) rs_matter::transport::core: Exchange 3::0: Accepted
I (69125) rs_matter::respond: Responder: Handler 0 / exchange 3::0: Starting
I (69135) rs_matter::transport::exchange:
<<<<< UDP [fe80::35:fa83:74e1:ef6d%2]:64698 [SID:71da,CTR:b9009c][A|R,EID:9633,PROTO:1,OP:5,ACTR:97186cf]
IM::ReportData
=> Sending
I (69175) rs_matter::transport::core:
>>>>> UDP [fe80::35:fa83:74e1:ef6d%2]:64698 [SID:1,CTR:97186d0][I|A,EID:9633,PROTO:0,OP:10,ACTR:b9009c]
SC::MRPStandAloneAck
=> Standalone Ack, dropping
I (69185) rs_matter::respond: Responder: Handler 0 / exchange 3::0: Completed
I (69205) rs_matter::transport::session: Creating a new exchange: 9634/Responder(AcceptPending)
I (69205) rs_matter::transport::core:
>>>>> UDP [fe80::35:fa83:74e1:ef6d%2]:64698 [SID:1,CTR:97186d1][I|R,EID:9634,PROTO:1,OP:2]
IM::ReadRequest
=> Processing (new exchange)
I (69225) rs_matter::transport::core: Exchange 3::1: Accepted
I (69225) rs_matter::respond: Responder: Handler 0 / exchange 3::1: Starting
I (69235) rs_matter::transport::exchange:
<<<<< UDP [fe80::35:fa83:74e1:ef6d%2]:64698 [SID:71da,CTR:b9009d][A|R,EID:9634,PROTO:1,OP:5,ACTR:97186d1]
IM::ReportData
=> Sending
I (69265) rs_matter::transport::session: Creating a new exchange: 9635/Responder(AcceptPending)
I (69265) rs_matter::transport::core:
>>>>> UDP [fe80::35:fa83:74e1:ef6d%2]:64698 [SID:1,CTR:97186d2][I|R,EID:9635,PROTO:1,OP:2]
IM::ReadRequest
=> Processing (new exchange)
I (69285) rs_matter::transport::core: Exchange 3::2: Accepted
I (69285) rs_matter::respond: Responder: Handler 1 / exchange 3::2: Starting
I (69295) rs_matter::transport::exchange:
<<<<< UDP [fe80::35:fa83:74e1:ef6d%2]:64698 [SID:71da,CTR:b9009e][A|R,EID:9635,PROTO:1,OP:5,ACTR:97186d2]
IM::ReportData
=> Sending
I (69325) rs_matter::transport::core:
>>>>> UDP [fe80::35:fa83:74e1:ef6d%2]:64698 [SID:1,CTR:97186d3][I|A,EID:9634,PROTO:0,OP:10,ACTR:b9009d]
SC::MRPStandAloneAck
=> Standalone Ack, dropping
I (69345) rs_matter::respond: Responder: Handler 0 / exchange 3::1: Completed
I (69345) rs_matter::transport::core:
>>>>> UDP [fe80::35:fa83:74e1:ef6d%2]:64698 [SID:1,CTR:97186d4][I|A,EID:9635,PROTO:0,OP:10,ACTR:b9009e]
SC::MRPStandAloneAck
=> Standalone Ack, dropping
I (69365) rs_matter::respond: Responder: Handler 1 / exchange 3::2: Completed
I (69375) rs_matter::transport::session: Creating a new exchange: 9636/Responder(AcceptPending)
I (69375) rs_matter::transport::core:
>>>>> UDP [fe80::35:fa83:74e1:ef6d%2]:64698 [SID:1,CTR:97186d5][I|R,EID:9636,PROTO:1,OP:2]
IM::ReadRequest
=> Processing (new exchange)
I (69395) rs_matter::transport::core: Exchange 3::3: Accepted
I (69395) rs_matter::respond: Responder: Handler 0 / exchange 3::3: Starting
I (69415) rs_matter::transport::exchange:
<<<<< UDP [fe80::35:fa83:74e1:ef6d%2]:64698 [SID:71da,CTR:b9009f][A|R,EID:9636,PROTO:1,OP:5,ACTR:97186d5]
IM::ReportData
=> Sending
I (69455) rs_matter::transport::core:
>>>>> UDP [fe80::35:fa83:74e1:ef6d%2]:64698 [SID:1,CTR:97186d6][I|A,EID:9636,PROTO:0,OP:10,ACTR:b9009f]
SC::MRPStandAloneAck
=> Standalone Ack, dropping
I (69465) rs_matter::respond: Responder: Handler 0 / exchange 3::3: Completed
I (69475) rs_matter::transport::session: Creating a new exchange: 9637/Responder(AcceptPending)
I (69485) rs_matter::transport::core:
>>>>> UDP [fe80::35:fa83:74e1:ef6d%2]:64698 [SID:1,CTR:97186d7][I|R,EID:9637,PROTO:1,OP:8]
IM::InvokeRequest
=> Processing (new exchange)
I (69495) light: Light toggled
I (69505) rs_matter::transport::core: Exchange 3::4: Accepted
I (69505) rs_matter::respond: Responder: Handler 0 / exchange 3::4: Starting
I (69515) rs_matter::data_model::sdm::noc: Handling command Remove Fabric
I (69525) rs_matter::transport::exchange:
<<<<< UDP [fe80::35:fa83:74e1:ef6d%2]:64698 [SID:71da,CTR:b900a0][A|R,EID:9637,PROTO:1,OP:9,ACTR:97186d7]
IM::InvokeResponse
=> Sending
I (69555) rs_matter::mdns::builtin: Broadcasting mDNS entry to 224.0.0.251:5353
I (69565) rs_matter::mdns::builtin: Broadcasting mDNS entry to [ff02::fb%2]:5353
I (69575) rs_matter::transport::core:
>>>>> UDP [fe80::35:fa83:74e1:ef6d%2]:64698 [SID:1,CTR:97186d8][I|A,EID:9637,PROTO:0,OP:10,ACTR:b900a0]
SC::MRPStandAloneAck
=> Standalone Ack, dropping
I (69595) rs_matter::respond: Responder: Handler 0 / exchange 3::4: Completed
I (74505) light: Light toggled
I (79515) light: Light toggled
I (84525) light: Light toggled
I (89535) light: Light toggled
I (94535) light: Light toggled
I (99545) light: Light toggled
I (99575) rs_matter::mdns::builtin: Broadcasting mDNS entry to 224.0.0.251:5353
I (99585) rs_matter::mdns::builtin: Broadcasting mDNS entry to [ff02::fb%2]:5353
I (104545) light: Light toggled
I (109555) light: Light toggled
I (114555) light: Light toggled
I (119565) light: Light toggled
I (124565) light: Light toggled
I (129575) light: Light toggled
I (129585) rs_matter::mdns::builtin: Broadcasting mDNS entry to 224.0.0.251:5353
I (129595) rs_matter::mdns::builtin: Broadcasting mDNS entry to [ff02::fb%2]:5353
I (134575) light: Light toggled
I (139585) light: Light toggled
I (144595) light: Light toggled
I (149595) light: Light toggled
I (154605) light: Light toggled
I (159605) rs_matter::mdns::builtin: Broadcasting mDNS entry to 224.0.0.251:5353
I (159615) rs_matter::mdns::builtin: Broadcasting mDNS entry to [ff02::fb%2]:5353
I (159625) light: Light toggled
I (164625) light: Light toggled
I (169635) light: Light toggled
I (174635) light: Light toggled
I (179645) light: Light toggled
I (184645) light: Light toggled
I (189625) rs_matter::mdns::builtin: Broadcasting mDNS entry to 224.0.0.251:5353
I (189635) rs_matter::mdns::builtin: Broadcasting mDNS entry to [ff02::fb%2]:5353
I (189655) light: Light toggled
I (194655) light: Light toggled
I (199665) light: Light toggled
I (204665) light: Light toggled
I (209675) light: Light toggled
I (214675) light: Light toggled
I (219635) rs_matter::mdns::builtin: Broadcasting mDNS entry to 224.0.0.251:5353
I (219645) rs_matter::mdns::builtin: Broadcasting mDNS entry to [ff02::fb%2]:5353
I (219685) light: Light toggled
I (224685) light: Light toggled
I (229695) light: Light toggled
I (234695) light: Light toggled
I (239705) light: Light toggled
I (244715) light: Light toggled
I (249655) rs_matter::mdns::builtin: Broadcasting mDNS entry to 224.0.0.251:5353
I (249665) rs_matter::mdns::builtin: Broadcasting mDNS entry to [ff02::fb%2]:5353
I (249715) light: Light toggled
I (254725) light: Light toggled
I (259725) light: Light toggled
I (264735) light: Light toggled
I (269735) light: Light toggled
I (274745) light: Light toggled
I (279675) rs_matter::mdns::builtin: Broadcasting mDNS entry to 224.0.0.251:5353
I (279685) rs_matter::mdns::builtin: Broadcasting mDNS entry to [ff02::fb%2]:5353
I (279755) light: Light toggled
I (284755) light: Light toggled
I (289765) light: Light toggled
I (294765) light: Light toggled
I (299775) light: Light toggled
I (304775) light: Light toggled
I (309695) rs_matter::mdns::builtin: Broadcasting mDNS entry to 224.0.0.251:5353
I (309695) rs_matter::mdns::builtin: Broadcasting mDNS entry to [ff02::fb%2]:5353
I (309795) light: Light toggled
I (314795) light: Light toggled
I (319805) light: Light toggled
I (324805) light: Light toggled
I (329815) light: Light toggled
I (334825) light: Light toggled
I (339705) rs_matter::mdns::builtin: Broadcasting mDNS entry to 224.0.0.251:5353
I (339715) rs_matter::mdns::builtin: Broadcasting mDNS entry to [ff02::fb%2]:5353
I (339825) light: Light toggled
I (344835) light: Light toggled
I (349835) light: Light toggled
@3wnbr1 OK, just found the real root cause.
Would you do the cargo update
+ rebuild + flash + run dance again? Sorry and thanks for supporting this debugging excercise!
Awesome, thank you so much @ivmarkov it worked 🎉
Pasting the log from the ESP32 for posterity (I saw a few error messages but pairing when through just fine)
ESP-ROM:esp32c3-api1-20210207
Build:Feb 7 2021
rst:0x15 (USB_UART_CHIP_RESET),boot:0xd (SPI_FAST_FLASH_BOOT)
Saved PC:0x420162ca
0x420162ca - core::ops::function::impls::<impl core::ops::function::FnOnce<A> for &mut F>::call_once
at /Users/ewen/.rustup/toolchains/nightly-aarch64-apple-darwin/lib/rustlib/src/rust/library/core/src/ops/function.rs:304
SPIWP:0xee
mode:DIO, clock div:2
load:0x3fcd5820,len:0x1714
load:0x403cc710,len:0x968
load:0x403ce710,len:0x2f9c
entry 0x403cc710
I (24) boot: ESP-IDF v5.1.2-342-gbcf1645e44 2nd stage bootloader
I (24) boot: compile time Dec 12 2023 10:50:58
I (25) boot: chip revision: v0.4
I (29) boot.esp32c3: SPI Speed : 40MHz
I (34) boot.esp32c3: SPI Mode : DIO
I (38) boot.esp32c3: SPI Flash Size : 4MB
I (43) boot: Enabling RNG early entropy source...
I (48) boot: Partition Table:
I (52) boot: ## Label Usage Type ST Offset Length
I (59) boot: 0 nvs WiFi data 01 02 00009000 00006000
I (67) boot: 1 phy_init RF data 01 01 0000f000 00001000
I (74) boot: 2 factory factory app 00 00 00010000 00300000
I (82) boot: End of partition table
I (86) esp_image: segment 0: paddr=00010020 vaddr=3c1b0020 size=74150h (475472) map
I (200) esp_image: segment 1: paddr=00084178 vaddr=3fc92c00 size=0bea0h ( 48800) load
I (212) esp_image: segment 2: paddr=00090020 vaddr=42000020 size=1a5714h (1726228) map
I (595) esp_image: segment 3: paddr=0023573c vaddr=3fc9eaa0 size=04174h ( 16756) load
I (600) esp_image: segment 4: paddr=002398b8 vaddr=40380000 size=12bc8h ( 76744) load
I (629) boot: Loaded app from partition at offset 0x10000
I (629) boot: Disabling RNG early entropy source...
I (641) cpu_start: Unicore app
I (641) cpu_start: Pro cpu up.
I (650) cpu_start: Pro cpu start user code
I (650) cpu_start: cpu freq: 160000000 Hz
I (650) cpu_start: Application information:
I (653) cpu_start: Project name: libespidf
I (658) cpu_start: App version: eb6ec2b-dirty
I (663) cpu_start: Compile time: Jun 1 2024 12:47:06
I (669) cpu_start: ELF file SHA256: 0000000000000000...
I (675) cpu_start: ESP-IDF: v5.1.2
I (680) cpu_start: Min chip rev: v0.3
I (685) cpu_start: Max chip rev: v0.99
I (690) cpu_start: Chip rev: v0.4
I (695) heap_init: Initializing. RAM available for dynamic allocation:
I (702) heap_init: At 3FCA7690 len 00018970 (98 KiB): DRAM
I (708) heap_init: At 3FCC0000 len 0001C710 (113 KiB): DRAM/RETENTION
I (715) heap_init: At 3FCDC710 len 00002950 (10 KiB): DRAM/RETENTION/STACK
I (723) heap_init: At 50000010 len 00001FD8 (7 KiB): RTCRAM
I (730) spi_flash: detected chip: generic
I (733) spi_flash: flash io: dio
W (738) timer_group: legacy driver is deprecated, please migrate to `driver/gptimer.h`
I (746) sleep: Configure to isolate all GPIO pins in sleep state
I (753) sleep: Enable automatic switching of GPIO sleep configuration
I (760) coexist: coex firmware version: b6d5e8c
I (765) coexist: coexist rom version 9387209
I (770) app_start: Starting scheduler on CPU0
I (775) main_task: Started on CPU0
I (775) main_task: Calling app_main()
I (785) light: Starting...
I (785) esp_idf_matter::stack: Async IO initialized; using `async-io-mini`
I (805) esp_idf_matter::stack::wifible: Matter Stack memory: 52400B
I (805) esp_idf_svc::bt: Init bluetooth controller
I (805) BLE_INIT: BT controller compile version [59725b5]
I (805) BLE_INIT: Bluetooth MAC: dc:da:0c:88:be:92
I (815) esp_idf_svc::bt: Enable bluetooth controller
I (825) phy_init: phy_version 1130,b4e4b80,Sep 5 2023,11:09:30
I (855) esp_idf_svc::bt: Init bluedroid
I (875) esp_idf_svc::bt: Enable bluedroid
I (885) esp_idf_matter::stack::wifible: BLE driver initialized
I (885) esp_idf_matter::stack::wifible: Running Matter in commissioning mode (BLE)
I (885) esp_idf_matter::ble: BLE Gap and Gatts initialized
I (895) esp_idf_matter::ble: BLE Gap and Gatts subscriptions initialized
I (915) esp_idf_matter::ble: Gatts BTP app registered
I (915) esp_idf_matter::stack: Responder memory: Responder=160B, Runner=10496B
I (915) rs_matter::respond: Responder: Creating 4 handlers
I (925) rs_matter::respond: Responder: Handlers size: 7976B
I (925) rs_matter::respond: Busy Responder: Creating 2 handlers
I (935) rs_matter::respond: Busy Responder: Handlers size: 648B
I (945) rs_matter::pairing::code: Pairing Code: 0087-6800-071
I (945) rs_matter::pairing::qr: QR Code Text: MT:Y.K90KQS02Z6Q66D33P084L90Z.I332SQ43I15T0
I (1005) rs_matter::pairing::qr: █████████████████████████████████████
I (1005) rs_matter::pairing::qr: █████████████████████████████████████
I (1025) rs_matter::pairing::qr: ████ ▄▄▄▄▄ █ ▄▄▄ ██▄ █ ▄ █ ▄▄▄▄▄ ████
I (1035) rs_matter::pairing::qr: ████ █ █ █▄▄▀▀▀██▄ ▄ █▄█ █ █ ████
I (1045) rs_matter::pairing::qr: ████ █▄▄▄█ █▄▀▀▀▄█▄ █▀▀ █ █▄▄▄█ ████
I (1055) rs_matter::pairing::qr: ████▄▄▄▄▄▄▄█▄█ █ ▀▄▀ █ ▀▄█▄▄▄▄▄▄▄████
I (1075) rs_matter::pairing::qr: ████ ██ ▄ ▄▄ ▀██▄ ██▀▀ ▄█▄▀▀ ▀▄ ████
I (1085) rs_matter::pairing::qr: ████▀ ▀ █▄▄█▄▀▄▄ █▄ ▀███▀▀ ▄ ▀ ████
I (1095) rs_matter::pairing::qr: ████ ▀▀▀▄▄▄█▀▀ ▄ ▀▄ ▀ █▀ ██ ▄▄▀▀████
I (1105) rs_matter::pairing::qr: ████ ▀█ ▄▄ ▀ ██▀▄█▀▄▀█▀▀▄▀▀ ▄█ █████
I (1125) rs_matter::pairing::qr: ████ ▀█▄▀▄▀▀▀▀█▄▀ █ ▄█▀█▄█▀▄█▀▀▄████
I (1135) rs_matter::pairing::qr: ████ █▀ ▄ ▀▀ █▄█▀▄█▄▄ ▀▄█ ▀█ ▀████
I (1145) rs_matter::pairing::qr: ████▄▄▄███▄█▀▀▀ █▄ ▄▄▀██ ▄▄▄ ▀█▀█████
I (1165) rs_matter::pairing::qr: ████ ▄▄▄▄▄ █ ▄ ▄ █ ▀█▄ ▀ █▄█ █▀ ████
I (1175) rs_matter::pairing::qr: ████ █ █ █ █ █▄▄▄█▄▀█▀ ▄▄ ▄█▄▀▄████
I (1185) rs_matter::pairing::qr: ████ █▄▄▄█ ██▀▀▄▀▄█▄ ▄▀▄▀▄ ▀██▄▄████
I (1195) rs_matter::pairing::qr: ████▄▄▄▄▄▄▄█▄██▄█▄█▄█▄▄▄▄▄█▄▄█▄▄█████
I (1215) rs_matter::pairing::qr: █████████████████████████████████████
I (1225) rs_matter::pairing::qr: █████████████████████████████████████
I (1245) rs_matter::transport::core: Running Matter transport
I (1245) rs_matter::transport::core: Waiting for orphaned RX packets
I (4775) rs_matter::transport::network::btp::session:
>>>>> (BTP IO) 52:DA:FB:79:82:B3 [H|M|B|E,OP:6c]
HANDSHAKE REQ HandshakeReq { versions: 4, mtu: 517, window_size: 6 }
Selected version: 4, MTU: 244, window size: 6
I (4955) rs_matter::transport::network::btp::context: Subscribe request from 52:DA:FB:79:82:B3
I (4955) rs_matter::transport::network::btp::session:
<<<<< (BTP IO) 52:DA:FB:79:82:B3 [H|M|B|E,OP:6c]
HANDSHAKE RESP HandshakeResp { version: 4, mtu: 244, window_size: 6 }
I (5015) rs_matter::transport::network::btp::session:
>>>>> (BTP IO) 52:DA:FB:79:82:B3 [A|B|E,ACTR:0,CTR:0,LEN:62]
READ 98B
I (5025) rs_matter::transport::session: Creating a new exchange: 963e/Responder(AcceptPending)
I (5025) rs_matter::transport::core:
>>>>> BTP 52:DA:FB:79:82:B3 [S,SID:0,CTR:dff6932,SRC:ffd7e44631ebf4aa][I,EID:963e,PROTO:0,OP:20]
SC::PBKDFParamRequest
=> Processing (new exchange)
I (5045) rs_matter::transport::core: Exchange 0::0: Accepted
I (5045) rs_matter::respond: Responder: Handler 0 / exchange 0::0: Starting
I (5055) rs_matter::transport::exchange:
<<<<< BTP 52:DA:FB:79:82:B3 [U,SID:0,CTR:8918d7e,DST:ffd7e44631ebf4aa][EID:963e,PROTO:0,OP:21]
SC::PBKDFParamResponse
=> Sending
I (5075) rs_matter::transport::network::btp::session:
<<<<< (BTP IO) 52:DA:FB:79:82:B3 [A|B|E,ACTR:0,CTR:1,LEN:8b]
WRITE 139B
I (5135) rs_matter::transport::network::btp::session:
>>>>> (BTP IO) 52:DA:FB:79:82:B3 [A|B|E,ACTR:1,CTR:1,LEN:5c]
READ 92B
I (5135) rs_matter::transport::core:
>>>>> BTP 52:DA:FB:79:82:B3 [S,SID:0,CTR:dff6933,SRC:ffd7e44631ebf4aa][I,EID:963e,PROTO:0,OP:22]
SC::PASEPake1
=> Processing
I (8745) rs_matter::transport::exchange:
<<<<< BTP 52:DA:FB:79:82:B3 [U,SID:0,CTR:8918d7f,DST:ffd7e44631ebf4aa][EID:963e,PROTO:0,OP:23]
SC::PASEPake2
=> Sending
I (8755) rs_matter::transport::network::btp::session:
<<<<< (BTP IO) 52:DA:FB:79:82:B3 [A|B|E,ACTR:1,CTR:2,LEN:7f]
WRITE 127B
I (8765) light: Light toggled
I (8855) rs_matter::transport::network::btp::session:
>>>>> (BTP IO) 52:DA:FB:79:82:B3 [A|B|E,ACTR:2,CTR:2,LEN:3b]
READ 59B
I (8855) rs_matter::transport::core:
>>>>> BTP 52:DA:FB:79:82:B3 [S,SID:0,CTR:dff6934,SRC:ffd7e44631ebf4aa][I,EID:963e,PROTO:0,OP:24]
SC::PASEPake3
=> Processing
I (8875) rs_matter::transport::exchange:
<<<<< BTP 52:DA:FB:79:82:B3 [U,SID:0,CTR:8918d80,DST:ffd7e44631ebf4aa][EID:963e,PROTO:0,OP:40]
SC::StatusReport
=> Sending
I (8885) rs_matter::respond: Responder: Handler 0 / exchange 0::0: Completed
I (8895) rs_matter::transport::network::btp::session:
<<<<< (BTP IO) 52:DA:FB:79:82:B3 [A|B|E,ACTR:2,CTR:3,LEN:1e]
WRITE 30B
I (8975) rs_matter::transport::network::btp::session:
>>>>> (BTP IO) 52:DA:FB:79:82:B3 [A|B|E,ACTR:3,CTR:3,LEN:33]
READ 51B
I (8985) rs_matter::transport::session: Creating a new exchange: 963f/Responder(AcceptPending)
I (8985) rs_matter::transport::core:
>>>>> BTP 52:DA:FB:79:82:B3 [SID:1,CTR:591de80][I,EID:963f,PROTO:1,OP:2]
IM::ReadRequest
=> Processing (new exchange)
I (9005) rs_matter::transport::core: Exchange 1::0: Accepted
I (9005) rs_matter::respond: Responder: Handler 0 / exchange 1::0: Starting
I (9015) rs_matter::transport::exchange:
<<<<< BTP 52:DA:FB:79:82:B3 [SID:71dc,CTR:3fe436][EID:963f,PROTO:1,OP:5]
IM::ReportData
=> Sending
I (9025) rs_matter::respond: Responder: Handler 0 / exchange 1::0: Completed
I (9035) rs_matter::transport::network::btp::session:
<<<<< (BTP IO) 52:DA:FB:79:82:B3 [A|B|E,ACTR:3,CTR:4,LEN:41]
WRITE 65B
I (9095) rs_matter::transport::network::btp::session:
>>>>> (BTP IO) 52:DA:FB:79:82:B3 [A|B|E,ACTR:4,CTR:4,LEN:33]
READ 51B
I (9105) rs_matter::transport::session: Creating a new exchange: 9640/Responder(AcceptPending)
I (9105) rs_matter::transport::core:
>>>>> BTP 52:DA:FB:79:82:B3 [SID:1,CTR:591de81][I,EID:9640,PROTO:1,OP:2]
IM::ReadRequest
=> Processing (new exchange)
I (9125) rs_matter::transport::core: Exchange 1::1: Accepted
I (9125) rs_matter::respond: Responder: Handler 0 / exchange 1::1: Starting
I (9135) rs_matter::transport::exchange:
<<<<< BTP 52:DA:FB:79:82:B3 [SID:71dc,CTR:3fe437][EID:9640,PROTO:1,OP:5]
IM::ReportData
=> Sending
I (9155) rs_matter::respond: Responder: Handler 0 / exchange 1::1: Completed
I (9155) rs_matter::transport::network::btp::session:
<<<<< (BTP IO) 52:DA:FB:79:82:B3 [A|B|E,ACTR:4,CTR:5,LEN:53]
WRITE 83B
I (9215) rs_matter::transport::network::btp::session:
>>>>> (BTP IO) 52:DA:FB:79:82:B3 [A|B|E,ACTR:5,CTR:5,LEN:34]
READ 52B
I (9225) rs_matter::transport::session: Creating a new exchange: 9641/Responder(AcceptPending)
I (9225) rs_matter::transport::core:
>>>>> BTP 52:DA:FB:79:82:B3 [SID:1,CTR:591de82][I,EID:9641,PROTO:1,OP:2]
IM::ReadRequest
=> Processing (new exchange)
I (9245) rs_matter::transport::core: Exchange 1::2: Accepted
I (9245) rs_matter::respond: Responder: Handler 0 / exchange 1::2: Starting
I (9255) rs_matter::transport::exchange:
<<<<< BTP 52:DA:FB:79:82:B3 [SID:71dc,CTR:3fe438][EID:9641,PROTO:1,OP:5]
IM::ReportData
=> Sending
I (9265) rs_matter::respond: Responder: Handler 0 / exchange 1::2: Completed
I (9275) rs_matter::transport::network::btp::session:
<<<<< (BTP IO) 52:DA:FB:79:82:B3 [A|B|E,ACTR:5,CTR:6,LEN:40]
WRITE 64B
I (9485) rs_matter::transport::network::btp::session:
>>>>> (BTP IO) 52:DA:FB:79:82:B3 [A|B|E,ACTR:6,CTR:6,LEN:33]
READ 51B
I (9495) rs_matter::transport::session: Creating a new exchange: 9642/Responder(AcceptPending)
I (9495) rs_matter::transport::core:
>>>>> BTP 52:DA:FB:79:82:B3 [SID:1,CTR:591de83][I,EID:9642,PROTO:1,OP:2]
IM::ReadRequest
=> Processing (new exchange)
I (9515) rs_matter::transport::core: Exchange 1::3: Accepted
I (9515) rs_matter::respond: Responder: Handler 0 / exchange 1::3: Starting
I (9525) rs_matter::transport::exchange:
<<<<< BTP 52:DA:FB:79:82:B3 [SID:71dc,CTR:3fe439][EID:9642,PROTO:1,OP:5]
IM::ReportData
=> Sending
I (9535) rs_matter::respond: Responder: Handler 0 / exchange 1::3: Completed
I (9545) rs_matter::transport::network::btp::session:
<<<<< (BTP IO) 52:DA:FB:79:82:B3 [A|B|E,ACTR:6,CTR:7,LEN:3f]
WRITE 63B
I (9605) rs_matter::transport::network::btp::session:
>>>>> (BTP IO) 52:DA:FB:79:82:B3 [A|B|E,ACTR:7,CTR:7,LEN:34]
READ 52B
I (9615) rs_matter::transport::session: Creating a new exchange: 9643/Responder(AcceptPending)
I (9615) rs_matter::transport::core:
>>>>> BTP 52:DA:FB:79:82:B3 [SID:1,CTR:591de84][I,EID:9643,PROTO:1,OP:2]
IM::ReadRequest
=> Processing (new exchange)
I (9635) rs_matter::transport::core: Exchange 1::4: Accepted
I (9635) rs_matter::respond: Responder: Handler 0 / exchange 1::4: Starting
I (9645) rs_matter::transport::exchange:
<<<<< BTP 52:DA:FB:79:82:B3 [SID:71dc,CTR:3fe43a][EID:9643,PROTO:1,OP:5]
IM::ReportData
=> Sending
I (9665) rs_matter::respond: Responder: Handler 0 / exchange 1::4: Completed
I (9665) rs_matter::transport::network::btp::session:
<<<<< (BTP IO) 52:DA:FB:79:82:B3 [A|B|E,ACTR:7,CTR:8,LEN:40]
WRITE 64B
I (9785) rs_matter::transport::network::btp::session:
>>>>> (BTP IO) 52:DA:FB:79:82:B3 [A|B|E,ACTR:8,CTR:8,LEN:83]
READ 131B
I (9795) rs_matter::transport::session: Creating a new exchange: 9644/Responder(AcceptPending)
I (9795) rs_matter::transport::core:
>>>>> BTP 52:DA:FB:79:82:B3 [SID:1,CTR:591de85][I,EID:9644,PROTO:1,OP:2]
IM::ReadRequest
=> Processing (new exchange)
I (9815) rs_matter::transport::core: Exchange 1::0: Accepted
I (9815) rs_matter::respond: Responder: Handler 0 / exchange 1::0: Starting
I (9835) rs_matter::transport::exchange:
<<<<< BTP 52:DA:FB:79:82:B3 [SID:71dc,CTR:3fe43b][EID:9644,PROTO:1,OP:5]
IM::ReportData
=> Sending
I (9845) rs_matter::respond: Responder: Handler 0 / exchange 1::0: Completed
I (9845) rs_matter::transport::network::btp::session:
<<<<< (BTP IO) 52:DA:FB:79:82:B3 [A|B,ACTR:8,CTR:9,LEN:fe]
WRITE 239B
I (9855) rs_matter::transport::network::btp::session:
<<<<< (BTP IO) 52:DA:FB:79:82:B3 [C|E,CTR:a]
WRITE 15B
I (9995) rs_matter::transport::network::btp::session:
>>>>> (BTP IO) 52:DA:FB:79:82:B3 [A|B|E,ACTR:a,CTR:9,LEN:6a]
READ 106B
I (10005) rs_matter::transport::session: Creating a new exchange: 9645/Responder(AcceptPending)
I (10005) rs_matter::transport::core:
>>>>> BTP 52:DA:FB:79:82:B3 [SID:1,CTR:591de86][I,EID:9645,PROTO:1,OP:2]
IM::ReadRequest
=> Processing (new exchange)
I (10025) rs_matter::transport::core: Exchange 1::0: Accepted
I (10025) rs_matter::respond: Responder: Handler 0 / exchange 1::0: Starting
I (10035) rs_matter::transport::exchange:
<<<<< BTP 52:DA:FB:79:82:B3 [SID:71dc,CTR:3fe43c][EID:9645,PROTO:1,OP:5]
IM::ReportData
=> Sending
I (10055) rs_matter::respond: Responder: Handler 0 / exchange 1::0: Completed
I (10055) rs_matter::transport::network::btp::session:
<<<<< (BTP IO) 52:DA:FB:79:82:B3 [A|B|E,ACTR:9,CTR:b,LEN:c0]
WRITE 192B
I (10115) rs_matter::transport::network::btp::session:
>>>>> (BTP IO) 52:DA:FB:79:82:B3 [A|B|E,ACTR:b,CTR:a,LEN:41]
READ 65B
I (10125) rs_matter::transport::session: Creating a new exchange: 9646/Responder(AcceptPending)
I (10125) rs_matter::transport::core:
>>>>> BTP 52:DA:FB:79:82:B3 [SID:1,CTR:591de87][I,EID:9646,PROTO:1,OP:8]
IM::InvokeRequest
=> Processing (new exchange)
I (10145) rs_matter::transport::core: Exchange 1::0: Accepted
I (10145) rs_matter::respond: Responder: Handler 0 / exchange 1::0: Starting
I (10155) rs_matter::data_model::sdm::general_commissioning: Handling command ARM Fail Safe
I (10165) rs_matter::transport::exchange:
<<<<< BTP 52:DA:FB:79:82:B3 [SID:71dc,CTR:3fe43d][EID:9646,PROTO:1,OP:9]
IM::InvokeResponse
=> Sending
I (10185) rs_matter::respond: Responder: Handler 0 / exchange 1::0: Completed
I (10185) rs_matter::transport::network::btp::session:
<<<<< (BTP IO) 52:DA:FB:79:82:B3 [A|B|E,ACTR:a,CTR:c,LEN:3f]
WRITE 63B
I (10265) rs_matter::transport::network::btp::session:
>>>>> (BTP IO) 52:DA:FB:79:82:B3 [A|B|E,ACTR:c,CTR:b,LEN:46]
READ 70B
I (10275) rs_matter::transport::session: Creating a new exchange: 9647/Responder(AcceptPending)
I (10275) rs_matter::transport::core:
>>>>> BTP 52:DA:FB:79:82:B3 [SID:1,CTR:591de88][I,EID:9647,PROTO:1,OP:8]
IM::InvokeRequest
=> Processing (new exchange)
I (10295) rs_matter::transport::core: Exchange 1::0: Accepted
I (10295) rs_matter::respond: Responder: Handler 0 / exchange 1::0: Starting
I (10305) rs_matter::data_model::sdm::general_commissioning: Handling command Set Regulatory Config
I (10315) rs_matter::data_model::sdm::general_commissioning: Received country code: [78, 76]
I (10325) rs_matter::transport::exchange:
<<<<< BTP 52:DA:FB:79:82:B3 [SID:71dc,CTR:3fe43e][EID:9647,PROTO:1,OP:9]
IM::InvokeResponse
=> Sending
I (10345) rs_matter::respond: Responder: Handler 0 / exchange 1::0: Completed
I (10345) rs_matter::transport::network::btp::session:
<<<<< (BTP IO) 52:DA:FB:79:82:B3 [A|B|E,ACTR:b,CTR:d,LEN:3f]
WRITE 63B
I (10415) rs_matter::transport::network::btp::session:
>>>>> (BTP IO) 52:DA:FB:79:82:B3 [A|B|E,ACTR:d,CTR:c,LEN:3e]
READ 62B
I (10425) rs_matter::transport::session: Creating a new exchange: 9648/Responder(AcceptPending)
I (10425) rs_matter::transport::core:
>>>>> BTP 52:DA:FB:79:82:B3 [SID:1,CTR:591de89][I,EID:9648,PROTO:1,OP:8]
IM::InvokeRequest
=> Processing (new exchange)
I (10445) rs_matter::transport::core: Exchange 1::0: Accepted
I (10445) rs_matter::respond: Responder: Handler 0 / exchange 1::0: Starting
I (10455) rs_matter::data_model::sdm::noc: Handling command CertChainRequest
I (10465) rs_matter::data_model::sdm::noc: Received data: 1: {
I (10465) rs_matter::data_model::sdm::noc: Received Cert Type:2
I (10475) rs_matter::transport::exchange:
<<<<< BTP 52:DA:FB:79:82:B3 [SID:71dc,CTR:3fe43f][EID:9648,PROTO:1,OP:9]
IM::InvokeResponse
=> Sending
I (10495) rs_matter::respond: Responder: Handler 0 / exchange 1::0: Completed
I (10505) rs_matter::transport::network::btp::session:
<<<<< (BTP IO) 52:DA:FB:79:82:B3 [A|B,ACTR:c,CTR:e,LEN:20c]
WRITE 239B
I (10505) rs_matter::transport::network::btp::session:
<<<<< (BTP IO) 52:DA:FB:79:82:B3 [C,CTR:f]
WRITE 242B
I (10525) rs_matter::transport::network::btp::session:
<<<<< (BTP IO) 52:DA:FB:79:82:B3 [C|E,CTR:10]
WRITE 43B
I (10715) rs_matter::transport::network::btp::session:
>>>>> (BTP IO) 52:DA:FB:79:82:B3 [A|B|E,ACTR:10,CTR:d,LEN:3e]
READ 62B
I (10725) rs_matter::transport::session: Creating a new exchange: 9649/Responder(AcceptPending)
I (10725) rs_matter::transport::core:
>>>>> BTP 52:DA:FB:79:82:B3 [SID:1,CTR:591de8a][I,EID:9649,PROTO:1,OP:8]
IM::InvokeRequest
=> Processing (new exchange)
I (10745) rs_matter::transport::core: Exchange 1::0: Accepted
I (10745) rs_matter::respond: Responder: Handler 0 / exchange 1::0: Starting
I (10755) rs_matter::data_model::sdm::noc: Handling command CertChainRequest
I (10765) rs_matter::data_model::sdm::noc: Received data: 1: {
I (10765) rs_matter::data_model::sdm::noc: Received Cert Type:1
I (10775) rs_matter::transport::exchange:
<<<<< BTP 52:DA:FB:79:82:B3 [SID:71dc,CTR:3fe440][EID:9649,PROTO:1,OP:9]
IM::InvokeResponse
=> Sending
I (10795) rs_matter::respond: Responder: Handler 0 / exchange 1::0: Completed
I (10805) rs_matter::transport::network::btp::session:
<<<<< (BTP IO) 52:DA:FB:79:82:B3 [A|B,ACTR:d,CTR:11,LEN:229]
WRITE 239B
I (10815) rs_matter::transport::network::btp::session:
<<<<< (BTP IO) 52:DA:FB:79:82:B3 [C,CTR:12]
WRITE 242B
I (10825) rs_matter::transport::network::btp::session:
<<<<< (BTP IO) 52:DA:FB:79:82:B3 [C|E,CTR:13]
WRITE 72B
I (10985) rs_matter::transport::network::btp::session:
>>>>> (BTP IO) 52:DA:FB:79:82:B3 [A|B|E,ACTR:13,CTR:e,LEN:5e]
READ 94B
I (10995) rs_matter::transport::session: Creating a new exchange: 964a/Responder(AcceptPending)
I (10995) rs_matter::transport::core:
>>>>> BTP 52:DA:FB:79:82:B3 [SID:1,CTR:591de8b][I,EID:964a,PROTO:1,OP:8]
IM::InvokeRequest
=> Processing (new exchange)
I (11015) rs_matter::transport::core: Exchange 1::0: Accepted
I (11015) rs_matter::respond: Responder: Handler 0 / exchange 1::0: Starting
I (11025) rs_matter::data_model::sdm::noc: Handling command AttestationRequest
I (11035) rs_matter::data_model::sdm::noc: Received Attestation Nonce:OctetStr([16, 129, 147, 176, 81, 24, 168, 211, 200, 153, 8, 208, 232, 246, 94, 246, 133, 81, 250, 138, 175, 72, 3, 152, 39, 18, 137, 185, 25, 87, 140, 229])
I (11425) rs_matter::transport::exchange:
<<<<< BTP 52:DA:FB:79:82:B3 [SID:71dc,CTR:3fe441][EID:964a,PROTO:1,OP:9]
IM::InvokeResponse
=> Sending
I (11435) rs_matter::respond: Responder: Handler 0 / exchange 1::0: Completed
I (11445) rs_matter::transport::network::btp::session:
<<<<< (BTP IO) 52:DA:FB:79:82:B3 [A|B,ACTR:e,CTR:14,LEN:2c9]
WRITE 239B
I (11445) rs_matter::transport::network::btp::session:
<<<<< (BTP IO) 52:DA:FB:79:82:B3 [C,CTR:15]
WRITE 242B
I (11465) rs_matter::transport::network::btp::session:
<<<<< (BTP IO) 52:DA:FB:79:82:B3 [C|E,CTR:16]
WRITE 232B
I (13145) rs_matter::transport::network::btp::session:
>>>>> (BTP IO) 52:DA:FB:79:82:B3 [A|B|E,ACTR:16,CTR:f,LEN:5e]
READ 94B
I (13155) rs_matter::transport::session: Creating a new exchange: 964b/Responder(AcceptPending)
I (13155) rs_matter::transport::core:
>>>>> BTP 52:DA:FB:79:82:B3 [SID:1,CTR:591de8c][I,EID:964b,PROTO:1,OP:8]
IM::InvokeRequest
=> Processing (new exchange)
I (13175) rs_matter::transport::core: Exchange 1::0: Accepted
I (13175) rs_matter::respond: Responder: Handler 0 / exchange 1::0: Starting
I (13185) rs_matter::data_model::sdm::noc: Handling command CSRRequest
I (13195) rs_matter::data_model::sdm::noc: Received CSR Nonce:OctetStr([119, 208, 46, 153, 159, 99, 183, 245, 31, 65, 90, 151, 5, 58, 234, 164, 78, 239, 177, 48, 30, 1, 113, 152, 20, 104, 198, 224, 53, 73, 12, 176])
I (13955) rs_matter::transport::exchange:
<<<<< BTP 52:DA:FB:79:82:B3 [SID:71dc,CTR:3fe442][EID:964b,PROTO:1,OP:9]
IM::InvokeResponse
=> Sending
I (13965) rs_matter::respond: Responder: Handler 0 / exchange 1::0: Completed
I (13965) rs_matter::transport::network::btp::session:
<<<<< (BTP IO) 52:DA:FB:79:82:B3 [A|B,ACTR:f,CTR:17,LEN:172]
WRITE 239B
I (13975) rs_matter::transport::network::btp::session:
<<<<< (BTP IO) 52:DA:FB:79:82:B3 [C|E,CTR:18]
WRITE 131B
I (13985) light: Light toggled
I (14105) rs_matter::transport::network::btp::session:
>>>>> (BTP IO) 52:DA:FB:79:82:B3 [A|B,ACTR:18,CTR:10,LEN:134]
READ 239B
I (14165) rs_matter::transport::network::btp::session:
>>>>> (BTP IO) 52:DA:FB:79:82:B3 [C|E,CTR:11]
READ 69B
I (14175) rs_matter::transport::session: Creating a new exchange: 964c/Responder(AcceptPending)
I (14175) rs_matter::transport::core:
>>>>> BTP 52:DA:FB:79:82:B3 [SID:1,CTR:591de8d][I,EID:964c,PROTO:1,OP:8]
IM::InvokeRequest
=> Processing (new exchange)
I (14195) rs_matter::transport::core: Exchange 1::0: Accepted
I (14195) rs_matter::respond: Responder: Handler 0 / exchange 1::0: Starting
I (14205) rs_matter::data_model::sdm::noc: Handling command AddTrustedRootCert
I (14215) rs_matter::data_model::sdm::noc: Received Trusted Cert:OctetStr([15, 30, 1, 1, 0, 24, 2, 1, 37, 3, 26, 14, 34, 4, f8, 4, 26, 15, f7, c0, a6, be, 18, 26, 4, 83, 1f, 53, 2c, 24, 5, 0, 37, 6, 26, 14, 34, 4, f8, 4, 26, 15, f7, c0, a6, be, 18, 24, 7, 1, 24, 8, 1, 30, 9, 41, 4, 59, 1b, 81, 31, 2, 6f, ef, c5, 71, 1a, f, a5, 94, b8, f1, b, 64, 15, d2, 5e, 22, 24, 4, 94, b8, 86, 5a, 8e, db, e8, 2b, 25, e0, 7d, 2c, a1, f6, 6b, 7d, bb, e8, 7, ca, dc, e0, d0, bb, 14, 10, 3d, 6c, c0, d9, 4a, 71, 77, da, 1e, 95, 97, c0, 94, 2d, 64, 37, a, 35, 1, 29, 1, 18, 24, 2, 60, 30, 4, 14, 65, 75, 90, c7, 9b, 47, f5, 43, 80, c9, d3, 14, 4f, 1, 9, be, 80, cf, e9, 41, 30, 5, 14, 65, 75, 90, c7, 9b, 47, f5, 43, 80, c9, d3, 14, 4f, 1, 9, be, 80, cf, e9, 41, 18, 30, b, 40, d8, e7, 2d, ff, 72, 36, aa, 6b, 86, 2c, 8a, b0, c6, 40, 57, f3, 97, f5, 64, f0, 5b, 12, bc, 42, 4b, 75, fe, 17, a5, 3, 5, 24, 9c, a1, 73, 84, 65, 9f, b6, 5c, db, e, 18, d4, 71, fa, 9a, f8, c6, 9b, 3f, f, 2f, ef, 5, d8, bd, 24, ad, c8, 5d, ac, 3f, b9, 18])
I (14305) rs_matter::transport::exchange:
<<<<< BTP 52:DA:FB:79:82:B3 [SID:71dc,CTR:3fe443][EID:964c,PROTO:1,OP:9]
IM::InvokeResponse
=> Sending
I (14325) rs_matter::respond: Responder: Handler 0 / exchange 1::0: Completed
I (14325) rs_matter::transport::network::btp::session:
<<<<< (BTP IO) 52:DA:FB:79:82:B3 [A|B|E,ACTR:11,CTR:19,LEN:3f]
WRITE 63B
I (14405) rs_matter::transport::network::btp::session:
>>>>> (BTP IO) 52:DA:FB:79:82:B3 [A|B,ACTR:19,CTR:12,LEN:15b]
READ 239B
I (14465) rs_matter::transport::network::btp::session:
>>>>> (BTP IO) 52:DA:FB:79:82:B3 [C|E,CTR:13]
READ 108B
I (14475) rs_matter::transport::session: Creating a new exchange: 964d/Responder(AcceptPending)
I (14475) rs_matter::transport::core:
>>>>> BTP 52:DA:FB:79:82:B3 [SID:1,CTR:591de8e][I,EID:964d,PROTO:1,OP:8]
IM::InvokeRequest
=> Processing (new exchange)
I (14495) rs_matter::transport::core: Exchange 1::0: Accepted
I (14495) rs_matter::respond: Responder: Handler 0 / exchange 1::0: Starting
I (14505) rs_matter::data_model::sdm::noc: Handling command AddNOC
I (14515) rs_matter::data_model::sdm::noc: Received NOC as: Version: [0]
[2]
Serial Num: [1]
Signature Algorithm:
ECDSA with SHA256
Issuer:
Chip Root CA Id:
"0000000004F80434"
Chip Fabric Id:
"00000000BEA6C0F7"
Validity:
Not Before: 2024-06-01 12:24:17.0 +00:00:00
Not After: 9999-12-31 23:59:59.0 +00:00:00
Subject:
Chip Fabric Id:
"00000000BEA6C0F7"
Chip Node Id:
"00000000515DF31F"
Public Key Algorithm
ECPubKey
Prime256v1
Public-Key: [4, 95, e0, 24, 5c, e1, c2, 30, fa, 35, 6d, 55, d8, f0, 92, 66, 1f, 9c, 34, 90, 79, 48, 8, cc, f0, 15, cc, 79, 22, cd, 2, af, 58, 35, 70, a6, f3, 4f, 88, ac, 38, 1, 9b, ff, ac, 26, 87, a4, f4, 6f, d4, 65, 4c, 2e, 46, 4c, 65, dd, ae, ca, 46, 9e, 4a, 4c, 43]
X509v3 extensions: [3]
X509v3 Basic Constraints
critical: true
value:
X509v3 Key Usage
critical: true
value:
digitalSignature [80, 0]
X509v3 Extended Key Usage
critical: true
value:
ClientAuth
ServerAuth
Subject Key ID
value:
[2c, 14, 4d, 5e, f3, 44, 9e, b0, c, 84, 14, 7, e3, 8c, 7c, 42, b6, 6e, f4, a6]
Auth Key ID
value:
[0][65, 75, 90, c7, 9b, 47, f5, 43, 80, c9, d3, 14, 4f, 1, 9, be, 80, cf, e9, 41]
Signature: [8c, bf, 14, 3, ac, 7e, f9, df, 87, 1e, 61, 62, 66, fc, e6, 2b, dd, c9, 74, 6e, d6, 49, 6f, 0, 4a, d3, 9, a0, d9, a5, 25, 3, c7, da, 2, b4, 25, 7b, f4, ef, cb, e9, 4c, 4, cb, 87, 7f, cf, 93, 30, f, 71, 52, e, e7, ee, 6d, ea, d9, 7f, 88, e1, 1b, 3d]
I (14675) rs_matter::fabric: MDNS Service Name: 1BB7D1A63D26A524-00000000515DF31F
I (14685) rs_matter::transport::exchange:
<<<<< BTP 52:DA:FB:79:82:B3 [SID:71dc,CTR:3fe444][EID:964d,PROTO:1,OP:9]
IM::InvokeResponse
=> Sending
I (14695) rs_matter::respond: Responder: Handler 0 / exchange 1::0: Completed
I (14705) rs_matter::transport::network::btp::session:
<<<<< (BTP IO) 52:DA:FB:79:82:B3 [A|B|E,ACTR:13,CTR:1a,LEN:42]
WRITE 66B
I (14765) rs_matter::transport::network::btp::session:
>>>>> (BTP IO) 52:DA:FB:79:82:B3 [A|B|E,ACTR:1a,CTR:14,LEN:5b]
READ 91B
I (14775) rs_matter::transport::session: Creating a new exchange: 964e/Responder(AcceptPending)
I (14775) rs_matter::transport::core:
>>>>> BTP 52:DA:FB:79:82:B3 [SID:1,CTR:591de8f][I,EID:964e,PROTO:1,OP:8]
IM::InvokeRequest
=> Processing (new exchange)
I (14795) rs_matter::transport::core: Exchange 1::0: Accepted
I (14795) rs_matter::respond: Responder: Handler 0 / exchange 1::0: Starting
I (14805) esp_idf_matter::wifi::comm: AddOrUpdateWifiNetwork
I (14815) esp_idf_matter::wifi::comm: Added network with SSID Home-3wnB
I (14815) rs_matter::transport::exchange:
<<<<< BTP 52:DA:FB:79:82:B3 [SID:71dc,CTR:3fe445][EID:964e,PROTO:1,OP:9]
IM::InvokeResponse
=> Sending
I (14835) rs_matter::respond: Responder: Handler 0 / exchange 1::0: Completed
I (14845) rs_matter::transport::network::btp::session:
<<<<< (BTP IO) 52:DA:FB:79:82:B3 [A|B|E,ACTR:14,CTR:1b,LEN:3f]
WRITE 63B
I (14915) rs_matter::transport::network::btp::session:
>>>>> (BTP IO) 52:DA:FB:79:82:B3 [A|B|E,ACTR:1b,CTR:15,LEN:41]
READ 65B
I (14925) rs_matter::transport::session: Creating a new exchange: 964f/Responder(AcceptPending)
I (14925) rs_matter::transport::core:
>>>>> BTP 52:DA:FB:79:82:B3 [SID:1,CTR:591de90][I,EID:964f,PROTO:1,OP:8]
IM::InvokeRequest
=> Processing (new exchange)
I (14945) rs_matter::transport::core: Exchange 1::0: Accepted
I (14945) rs_matter::respond: Responder: Handler 0 / exchange 1::0: Starting
I (14955) rs_matter::data_model::sdm::general_commissioning: Handling command ARM Fail Safe
I (14965) rs_matter::transport::exchange:
<<<<< BTP 52:DA:FB:79:82:B3 [SID:71dc,CTR:3fe446][EID:964f,PROTO:1,OP:9]
IM::InvokeResponse
=> Sending
I (14985) rs_matter::respond: Responder: Handler 0 / exchange 1::0: Completed
I (14985) rs_matter::transport::network::btp::session:
<<<<< (BTP IO) 52:DA:FB:79:82:B3 [A|B|E,ACTR:15,CTR:1c,LEN:3f]
WRITE 63B
I (15065) rs_matter::transport::network::btp::session:
>>>>> (BTP IO) 52:DA:FB:79:82:B3 [A|B|E,ACTR:1c,CTR:16,LEN:4a]
READ 74B
I (15075) rs_matter::transport::session: Creating a new exchange: 9650/Responder(AcceptPending)
I (15075) rs_matter::transport::core:
>>>>> BTP 52:DA:FB:79:82:B3 [SID:1,CTR:591de91][I,EID:9650,PROTO:1,OP:8]
IM::InvokeRequest
=> Processing (new exchange)
I (15095) rs_matter::transport::core: Exchange 1::0: Accepted
I (15095) rs_matter::respond: Responder: Handler 0 / exchange 1::0: Starting
I (15105) esp_idf_matter::wifi::comm: ConnectNetwork
I (15105) esp_idf_matter::wifi::comm: Request to connect to network with SSID Home-3wnB received
I (15115) rs_matter::transport::exchange:
<<<<< BTP 52:DA:FB:79:82:B3 [SID:71dc,CTR:3fe447][EID:9650,PROTO:1,OP:9]
IM::InvokeResponse
=> Sending
I (15135) rs_matter::respond: Responder: Handler 0 / exchange 1::0: Completed
I (15145) rs_matter::transport::network::btp::session:
<<<<< (BTP IO) 52:DA:FB:79:82:B3 [A|B|E,ACTR:16,CTR:1d,LEN:3f]
WRITE 63B
W (15155) esp_idf_matter::wifi: Giving BLE/BTP extra 4 seconds for any outstanding messages before switching to Wifi
I (17695) rs_matter::transport::network::btp::session:
>>>>> (BTP IO) 52:DA:FB:79:82:B3 [A,ACTR:1d,CTR:17]
READ 0B
I (18995) light: Light toggled
W (19165) BT_HCI: hci cmd send: disconnect: hdl 0x1, rsn:0x13
W (19195) BT_HCI: hcif disc complete: hdl 0x1, rsn 0x16
I (20205) pp: pp rom version: 9387209
I (20205) net80211: net80211 rom version: 9387209
I (20215) wifi:wifi driver task: 3fcbf55c, prio:23, stack:6656, core=0
I (20215) wifi:wifi firmware version: 91b9630
I (20215) wifi:wifi certification version: v7.0
I (20215) wifi:config NVS flash: enabled
I (20225) wifi:config nano formating: disabled
I (20225) wifi:Init data frame dynamic rx buffer num: 32
I (20235) wifi:Init static rx mgmt buffer num: 10
I (20235) wifi:Init management short buffer num: 32
I (20245) wifi:Init dynamic tx buffer num: 32
I (20245) wifi:Init static tx FG buffer num: 2
I (20245) wifi:Init static rx buffer size: 1600
I (20255) wifi:Init static rx buffer num: 10
I (20255) wifi:Init dynamic rx buffer num: 32
I (20265) wifi_init: rx ba win: 6
I (20265) wifi_init: tcpip mbox: 32
I (20275) wifi_init: udp mbox: 6
I (20275) wifi_init: tcp mbox: 6
I (20275) wifi_init: tcp tx win: 5744
I (20285) wifi_init: tcp rx win: 5744
I (20285) wifi_init: tcp mss: 1440
I (20295) wifi_init: WiFi IRAM OP enabled
I (20295) wifi_init: WiFi RX IRAM OP enabled
I (20305) esp_idf_matter::stack::wifible: Wifi driver initialized
I (20305) esp_idf_matter::stack::wifible: Running Matter in operating mode (Wifi)
I (20315) esp_idf_matter::wifi: Trying with requested network first - SSID: Home-3wnB
I (20325) esp_idf_matter::wifi::mgmt: Connecting to SSID Home-3wnB
I (20335) esp_idf_matter::wifi::mgmt: Connecting with Client(ClientConfiguration { ssid: "Home-3wnB", bssid: None, auth_method: WPAWPA2Personal, channel: None, scan_method: CompleteScan(Signal), pmf_cfg: NotCapable })
I (20355) wifi:mode : sta (dc:da:0c:88:be:90)
I (20355) wifi:enable tsf
I (20365) esp_idf_matter::stack: Waiting for the network to come up...
I (22775) wifi:new:<9,0>, old:<1,0>, ap:<255,255>, sta:<9,0>, prof:1
I (22775) wifi:state: init -> auth (b0)
I (22785) wifi:state: auth -> assoc (0)
I (22785) wifi:state: assoc -> run (10)
I (22795) wifi:connected with Home-3wnB, aid = 2, channel 9, BW20, bssid = 00:5f:67:9a:30:bf
I (22795) wifi:security: WPA2-PSK, phy: bg, rssi: -85
I (22805) wifi:pm start, type: 1
I (22805) wifi:set rx beacon pti, rx_bcn_pti: 14, bcn_timeout: 25000, mt_pti: 14, mt_time: 10000
I (22815) wifi:AP's beacon interval = 102400 us, DTIM period = 2
I (22825) esp_idf_matter::wifi::mgmt: Successfully connected with Client(ClientConfiguration { ssid: "Home-3wnB", bssid: None, auth_method: WPAWPA2Personal, channel: None, scan_method: CompleteScan(Signal), pmf_cfg: NotCapable })
I (22835) esp_idf_matter::wifi::mgmt: Connected to SSID Home-3wnB
I (23995) light: Light toggled
I (24315) esp_netif_handlers: sta ip: 192.168.1.110, mask: 255.255.255.0, gw: 192.168.1.1
I (24315) esp_idf_matter::stack: Got IP network: IPv4: 192.168.1.110, IPv6: fe80::deda:cff:fe88:be90, Interface: 2, MAC: DC:DA:0C:88:BE:90
I (24325) esp_idf_matter::stack: Responder memory: Responder=160B, Runner=10496B
I (24335) rs_matter::respond: Responder: Creating 4 handlers
I (24335) rs_matter::respond: Responder: Handlers size: 7976B
I (24345) rs_matter::respond: Busy Responder: Creating 2 handlers
I (24355) rs_matter::respond: Busy Responder: Handlers size: 648B
I (24355) rs_matter::transport::core: Running Matter transport
I (24365) rs_matter::transport::core: Waiting for orphaned RX packets
I (24375) esp_idf_matter::multicast: Joined IP multicast 224.0.0.251/192.168.1.110
I (24385) esp_idf_matter::multicast: Joined IPV6 multicast ff02::fb/2
I (24385) rs_matter::transport::core: Running Matter built-in mDNS service
I (24395) rs_matter::mdns::builtin: Broadcasting mDNS entry to 224.0.0.251:5353
I (24405) rs_matter::mdns::builtin: Broadcasting mDNS entry to [ff02::fb%2]:5353
I (26305) rs_matter::transport::session: Creating a new exchange: 9651/Responder(AcceptPending)
I (26305) rs_matter::transport::core:
>>>>> UDP [fe80::35:fa83:74e1:ef6d%2]:64698 [S,SID:0,CTR:dff6935,SRC:9134b75cc28b30c9][I|R,EID:9651,PROTO:0,OP:30]
SC::CASESigma1
=> Processing (new exchange)
I (26325) rs_matter::transport::core: Exchange 2::0: Accepted
I (26325) rs_matter::respond: Responder: Handler 0 / exchange 2::0: Starting
I (26835) rs_matter::transport::exchange:
<<<<< UDP [fe80::35:fa83:74e1:ef6d%2]:64698 [U,SID:0,CTR:14f750f,DST:9134b75cc28b30c9][A|R,EID:9651,PROTO:0,OP:31,ACTR:dff6935]
SC::CASESigma2
=> Sending
I (26855) rs_matter::transport::core:
>>>>> UDP [fe80::35:fa83:74e1:ef6d%2]:64698 [S,SID:0,CTR:dff6935,SRC:9134b75cc28b30c9][I|R,EID:9651,PROTO:0,OP:30]
SC::CASESigma1
=> Duplicate, sending ACK
I (26865) rs_matter::transport::core:
<<<<< UDP [fe80::35:fa83:74e1:ef6d%2]:64698 [U,SID:0,CTR:14f7510,DST:9134b75cc28b30c9][A,EID:9651,PROTO:0,OP:10,ACTR:dff6935]
SC::MRPStandAloneAck
=> Sending (system)
I (27045) rs_matter::transport::exchange:
<<<<< UDP [fe80::35:fa83:74e1:ef6d%2]:64698 [U,SID:0,CTR:14f750f,DST:9134b75cc28b30c9][A|R,EID:9651,PROTO:0,OP:31,ACTR:dff6935]
SC::CASESigma2
=> Re-sending
I (27075) rs_matter::transport::core:
>>>>> UDP [fe80::35:fa83:74e1:ef6d%2]:64698 [S,SID:0,CTR:dff6935,SRC:9134b75cc28b30c9][I|R,EID:9651,PROTO:0,OP:30]
SC::CASESigma1
=> Duplicate, sending ACK
I (27085) rs_matter::transport::core:
<<<<< UDP [fe80::35:fa83:74e1:ef6d%2]:64698 [U,SID:0,CTR:14f7511,DST:9134b75cc28b30c9][A,EID:9651,PROTO:0,OP:10,ACTR:dff6935]
SC::MRPStandAloneAck
=> Sending (system)
I (27125) rs_matter::transport::core:
>>>>> UDP [fe80::35:fa83:74e1:ef6d%2]:64698 [S,SID:0,CTR:dff6936,SRC:9134b75cc28b30c9][I|A|R,EID:9651,PROTO:0,OP:32,ACTR:14f750f]
SC::CASESigma3
=> Processing
I (27905) rs_matter::transport::exchange:
<<<<< UDP [fe80::35:fa83:74e1:ef6d%2]:64698 [U,SID:0,CTR:14f7512,DST:9134b75cc28b30c9][A|R,EID:9651,PROTO:0,OP:40,ACTR:dff6936]
SC::StatusReport
=> Sending
E (27915) rs_matter::transport::mrp: Mismatch in retrans-table's msg counter and received msg counter: received 14f750f, expected 14f7512.
I (27925) rs_matter::transport::core:
>>>>> UDP [fe80::35:fa83:74e1:ef6d%2]:64698 [S,SID:0,CTR:dff6937,SRC:9134b75cc28b30c9][I|A,EID:9651,PROTO:0,OP:10,ACTR:14f750f]
SC::MRPStandAloneAck
=> Standalone Ack, dropping
I (27955) rs_matter::respond: Responder: Handler 0 / exchange 2::0: Completed
I (27965) rs_matter::transport::core:
>>>>> UDP [fe80::35:fa83:74e1:ef6d%2]:64698 [S,SID:0,CTR:dff6936,SRC:9134b75cc28b30c9][I|A|R,EID:9651,PROTO:0,OP:32,ACTR:14f750f]
SC::CASESigma3
=> Duplicate, sending ACK
I (27975) rs_matter::transport::core:
<<<<< UDP [fe80::35:fa83:74e1:ef6d%2]:64698 [U,SID:0,CTR:14f7513,DST:9134b75cc28b30c9][A,EID:9651,PROTO:0,OP:10,ACTR:dff6936]
SC::MRPStandAloneAck
=> Sending (system)
I (28005) rs_matter::transport::core:
>>>>> UDP [fe80::35:fa83:74e1:ef6d%2]:64698 [S,SID:0,CTR:dff6936,SRC:9134b75cc28b30c9][I|A|R,EID:9651,PROTO:0,OP:32,ACTR:14f750f]
SC::CASESigma3
=> Duplicate, sending ACK
I (28015) rs_matter::transport::core:
<<<<< UDP [fe80::35:fa83:74e1:ef6d%2]:64698 [U,SID:0,CTR:14f7514,DST:9134b75cc28b30c9][A,EID:9651,PROTO:0,OP:10,ACTR:dff6936]
SC::MRPStandAloneAck
=> Sending (system)
I (28055) rs_matter::transport::session: Creating a new exchange: 9652/Responder(AcceptPending)
I (28055) rs_matter::transport::core:
>>>>> UDP [fe80::35:fa83:74e1:ef6d%2]:64698 [SID:1,CTR:2fcafe2][I|R,EID:9652,PROTO:1,OP:8]
IM::InvokeRequest
=> Processing (new exchange)
I (28075) rs_matter::transport::core: Exchange 3::0: Accepted
I (28075) rs_matter::respond: Responder: Handler 0 / exchange 3::0: Starting
I (28095) rs_matter::data_model::sdm::general_commissioning: Handling command Commissioning Complete
I (28095) rs_matter::transport::exchange:
<<<<< UDP [fe80::35:fa83:74e1:ef6d%2]:64698 [SID:71dd,CTR:c5f46b3][A|R,EID:9652,PROTO:1,OP:9,ACTR:2fcafe2]
IM::InvokeResponse
=> Sending
I (28125) rs_matter::transport::session: Creating a new exchange: 9651/Responder(AcceptPending)
I (28125) rs_matter::transport::core:
>>>>> UDP [fe80::35:fa83:74e1:ef6d%2]:64698 [S,SID:0,CTR:dff6938,SRC:9134b75cc28b30c9][I|A,EID:9651,PROTO:0,OP:10,ACTR:14f7512]
SC::MRPStandAloneAck
=> Standalone Ack, dropping
I (28155) rs_matter::transport::core: Exchange 2::1: Accepted
I (28155) rs_matter::respond: Responder: Handler 1 / exchange 2::1: Starting
I (28165) rs_matter::transport::core:
>>>>> UDP [fe80::35:fa83:74e1:ef6d%2]:64698 [SID:1,CTR:2fcafe3][I|A,EID:9652,PROTO:0,OP:10,ACTR:c5f46b3]
SC::MRPStandAloneAck
=> Standalone Ack, dropping
I (28175) rs_matter::respond: Responder: Handler 0 / exchange 3::0: Completed
I (28355) rs_matter::transport::session: Creating a new exchange: 9653/Responder(AcceptPending)
I (28355) rs_matter::transport::core:
>>>>> UDP [fe80::35:fa83:74e1:ef6d%2]:64698 [SID:1,CTR:2fcafe4][I|R,EID:9653,PROTO:1,OP:2]
IM::ReadRequest
=> Processing (new exchange)
I (28375) rs_matter::transport::core: Exchange 3::1: Accepted
I (28375) rs_matter::respond: Responder: Handler 0 / exchange 3::1: Starting
I (28395) rs_matter::transport::exchange:
<<<<< UDP [fe80::35:fa83:74e1:ef6d%2]:64698 [SID:71dd,CTR:c5f46b4][A|R,EID:9653,PROTO:1,OP:5,ACTR:2fcafe4]
IM::ReportData
=> Sending
I (28555) rs_matter::transport::core:
>>>>> UDP [fe80::35:fa83:74e1:ef6d%2]:64698 [SID:1,CTR:2fcafe5][I|A,EID:9653,PROTO:0,OP:10,ACTR:c5f46b4]
SC::MRPStandAloneAck
=> Standalone Ack, dropping
I (28575) rs_matter::respond: Responder: Handler 0 / exchange 3::1: Completed
I (28585) rs_matter::transport::session: Creating a new exchange: 9654/Responder(AcceptPending)
I (28585) rs_matter::transport::core:
>>>>> UDP [fe80::35:fa83:74e1:ef6d%2]:64698 [SID:1,CTR:2fcafe6][I|R,EID:9654,PROTO:1,OP:2]
IM::ReadRequest
=> Processing (new exchange)
I (28605) rs_matter::transport::core: Exchange 3::2: Accepted
I (28605) rs_matter::respond: Responder: Handler 0 / exchange 3::2: Starting
I (28625) rs_matter::transport::exchange:
<<<<< UDP [fe80::35:fa83:74e1:ef6d%2]:64698 [SID:71dd,CTR:c5f46b5][A|R,EID:9654,PROTO:1,OP:5,ACTR:2fcafe6]
IM::ReportData
=> Sending
I (28655) rs_matter::transport::core:
>>>>> UDP [fe80::35:fa83:74e1:ef6d%2]:64698 [SID:1,CTR:2fcafe7][I|A,EID:9654,PROTO:0,OP:10,ACTR:c5f46b5]
SC::MRPStandAloneAck
=> Standalone Ack, dropping
I (28665) rs_matter::respond: Responder: Handler 0 / exchange 3::2: Completed
I (28685) rs_matter::transport::session: Creating a new exchange: 9655/Responder(AcceptPending)
I (28685) rs_matter::transport::core:
>>>>> UDP [fe80::35:fa83:74e1:ef6d%2]:64698 [SID:1,CTR:2fcafe8][I|R,EID:9655,PROTO:1,OP:2]
IM::ReadRequest
=> Processing (new exchange)
I (28705) rs_matter::transport::core: Exchange 3::3: Accepted
I (28705) rs_matter::respond: Responder: Handler 0 / exchange 3::3: Starting
I (28715) rs_matter::transport::exchange:
<<<<< UDP [fe80::35:fa83:74e1:ef6d%2]:64698 [SID:71dd,CTR:c5f46b6][A|R,EID:9655,PROTO:1,OP:5,ACTR:2fcafe8]
IM::ReportData
=> Sending
I (28765) rs_matter::transport::core:
>>>>> UDP [fe80::35:fa83:74e1:ef6d%2]:64698 [SID:1,CTR:2fcafe9][I|A,EID:9655,PROTO:0,OP:10,ACTR:c5f46b6]
SC::MRPStandAloneAck
=> Standalone Ack, dropping
I (28775) rs_matter::respond: Responder: Handler 0 / exchange 3::3: Completed
I (28795) rs_matter::transport::session: Creating a new exchange: 9656/Responder(AcceptPending)
I (28795) rs_matter::transport::core:
>>>>> UDP [fe80::35:fa83:74e1:ef6d%2]:64698 [SID:1,CTR:2fcafea][I|R,EID:9656,PROTO:1,OP:2]
IM::ReadRequest
=> Processing (new exchange)
I (28815) rs_matter::transport::core: Exchange 3::4: Accepted
I (28815) rs_matter::respond: Responder: Handler 0 / exchange 3::4: Starting
I (28835) rs_matter::transport::exchange:
<<<<< UDP [fe80::35:fa83:74e1:ef6d%2]:64698 [SID:71dd,CTR:c5f46b7][A|R,EID:9656,PROTO:1,OP:5,ACTR:2fcafea]
IM::ReportData
=> Sending
I (28875) rs_matter::transport::core:
>>>>> UDP [fe80::35:fa83:74e1:ef6d%2]:64698 [SID:1,CTR:2fcafeb][I|A,EID:9656,PROTO:0,OP:10,ACTR:c5f46b7]
SC::MRPStandAloneAck
=> Standalone Ack, dropping
I (28885) rs_matter::respond: Responder: Handler 0 / exchange 3::4: Completed
I (28895) rs_matter::transport::session: Creating a new exchange: 9657/Responder(AcceptPending)
I (28895) rs_matter::transport::core:
>>>>> UDP [fe80::35:fa83:74e1:ef6d%2]:64698 [SID:1,CTR:2fcafec][I|R,EID:9657,PROTO:1,OP:2]
IM::ReadRequest
=> Processing (new exchange)
I (28915) rs_matter::transport::core: Exchange 3::0: Accepted
I (28925) rs_matter::respond: Responder: Handler 0 / exchange 3::0: Starting
I (28935) rs_matter::transport::exchange:
<<<<< UDP [fe80::35:fa83:74e1:ef6d%2]:64698 [SID:71dd,CTR:c5f46b8][A|R,EID:9657,PROTO:1,OP:5,ACTR:2fcafec]
IM::ReportData
=> Sending
I (28975) rs_matter::transport::core:
>>>>> UDP [fe80::35:fa83:74e1:ef6d%2]:64698 [SID:1,CTR:2fcafed][I|A,EID:9657,PROTO:0,OP:10,ACTR:c5f46b8]
SC::MRPStandAloneAck
=> Standalone Ack, dropping
I (28985) rs_matter::respond: Responder: Handler 0 / exchange 3::0: Completed
I (29005) rs_matter::transport::session: Creating a new exchange: 9658/Responder(AcceptPending)
I (29005) rs_matter::transport::core:
>>>>> UDP [fe80::35:fa83:74e1:ef6d%2]:64698 [SID:1,CTR:2fcafee][I|R,EID:9658,PROTO:1,OP:2]
IM::ReadRequest
=> Processing (new exchange)
I (29025) light: Light toggled
I (29025) rs_matter::transport::core: Exchange 3::0: Accepted
I (29025) rs_matter::respond: Responder: Handler 0 / exchange 3::0: Starting
I (29045) rs_matter::transport::exchange:
<<<<< UDP [fe80::35:fa83:74e1:ef6d%2]:64698 [SID:71dd,CTR:c5f46b9][A|R,EID:9658,PROTO:1,OP:5,ACTR:2fcafee]
IM::ReportData
=> Sending
I (29085) rs_matter::transport::core:
>>>>> UDP [fe80::35:fa83:74e1:ef6d%2]:64698 [SID:1,CTR:2fcafef][I|A,EID:9658,PROTO:0,OP:10,ACTR:c5f46b9]
SC::MRPStandAloneAck
=> Standalone Ack, dropping
I (29095) rs_matter::respond: Responder: Handler 0 / exchange 3::0: Completed
I (29115) rs_matter::transport::session: Creating a new exchange: 9659/Responder(AcceptPending)
I (29115) rs_matter::transport::core:
>>>>> UDP [fe80::35:fa83:74e1:ef6d%2]:64698 [SID:1,CTR:2fcaff0][I|R,EID:9659,PROTO:1,OP:2]
IM::ReadRequest
=> Processing (new exchange)
I (29135) rs_matter::transport::core: Exchange 3::0: Accepted
I (29135) rs_matter::respond: Responder: Handler 0 / exchange 3::0: Starting
I (29155) rs_matter::transport::exchange:
<<<<< UDP [fe80::35:fa83:74e1:ef6d%2]:64698 [SID:71dd,CTR:c5f46ba][A|R,EID:9659,PROTO:1,OP:5,ACTR:2fcaff0]
IM::ReportData
=> Sending
I (29195) rs_matter::transport::core:
>>>>> UDP [fe80::35:fa83:74e1:ef6d%2]:64698 [SID:1,CTR:2fcaff1][I|A,EID:9659,PROTO:0,OP:10,ACTR:c5f46ba]
SC::MRPStandAloneAck
=> Standalone Ack, dropping
I (29215) rs_matter::respond: Responder: Handler 0 / exchange 3::0: Completed
I (29225) rs_matter::transport::session: Creating a new exchange: 965a/Responder(AcceptPending)
I (29225) rs_matter::transport::core:
>>>>> UDP [fe80::35:fa83:74e1:ef6d%2]:64698 [SID:1,CTR:2fcaff2][I|R,EID:965a,PROTO:1,OP:2]
IM::ReadRequest
=> Processing (new exchange)
I (29245) rs_matter::transport::core: Exchange 3::0: Accepted
I (29245) rs_matter::respond: Responder: Handler 0 / exchange 3::0: Starting
I (29265) rs_matter::transport::exchange:
<<<<< UDP [fe80::35:fa83:74e1:ef6d%2]:64698 [SID:71dd,CTR:c5f46bb][A|R,EID:965a,PROTO:1,OP:5,ACTR:2fcaff2]
IM::ReportData
=> Sending
I (29305) rs_matter::transport::core:
>>>>> UDP [fe80::35:fa83:74e1:ef6d%2]:64698 [SID:1,CTR:2fcaff3][I|A,EID:965a,PROTO:0,OP:10,ACTR:c5f46bb]
SC::MRPStandAloneAck
=> Standalone Ack, dropping
I (29315) rs_matter::respond: Responder: Handler 0 / exchange 3::0: Completed
I (29335) rs_matter::transport::session: Creating a new exchange: 965b/Responder(AcceptPending)
I (29335) rs_matter::transport::core:
>>>>> UDP [fe80::35:fa83:74e1:ef6d%2]:64698 [SID:1,CTR:2fcaff4][I|R,EID:965b,PROTO:1,OP:2]
IM::ReadRequest
=> Processing (new exchange)
I (29355) rs_matter::transport::core: Exchange 3::0: Accepted
I (29355) rs_matter::respond: Responder: Handler 0 / exchange 3::0: Starting
I (29375) rs_matter::transport::exchange:
<<<<< UDP [fe80::35:fa83:74e1:ef6d%2]:64698 [SID:71dd,CTR:c5f46bc][A|R,EID:965b,PROTO:1,OP:5,ACTR:2fcaff4]
IM::ReportData
=> Sending
I (29415) rs_matter::transport::core:
>>>>> UDP [fe80::35:fa83:74e1:ef6d%2]:64698 [SID:1,CTR:2fcaff5][I|A,EID:965b,PROTO:0,OP:10,ACTR:c5f46bc]
SC::MRPStandAloneAck
=> Standalone Ack, dropping
I (29425) rs_matter::respond: Responder: Handler 0 / exchange 3::0: Completed
I (29435) rs_matter::transport::session: Creating a new exchange: 965c/Responder(AcceptPending)
I (29435) rs_matter::transport::core:
>>>>> UDP [fe80::35:fa83:74e1:ef6d%2]:64698 [SID:1,CTR:2fcaff6][I|R,EID:965c,PROTO:1,OP:2]
IM::ReadRequest
=> Processing (new exchange)
I (29455) rs_matter::transport::core: Exchange 3::0: Accepted
I (29465) rs_matter::respond: Responder: Handler 0 / exchange 3::0: Starting
I (29475) rs_matter::transport::exchange:
<<<<< UDP [fe80::35:fa83:74e1:ef6d%2]:64698 [SID:71dd,CTR:c5f46bd][A|R,EID:965c,PROTO:1,OP:5,ACTR:2fcaff6]
IM::ReportData
=> Sending
I (29495) rs_matter::transport::session: Creating a new exchange: 965d/Responder(AcceptPending)
I (29505) rs_matter::transport::core:
>>>>> UDP [fe80::35:fa83:74e1:ef6d%2]:64698 [SID:1,CTR:2fcaff7][I|R,EID:965d,PROTO:1,OP:2]
IM::ReadRequest
=> Processing (new exchange)
I (29525) rs_matter::transport::core: Exchange 3::1: Accepted
I (29525) rs_matter::respond: Responder: Handler 2 / exchange 3::1: Starting
I (29535) rs_matter::transport::exchange:
<<<<< UDP [fe80::35:fa83:74e1:ef6d%2]:64698 [SID:71dd,CTR:c5f46be][A|R,EID:965d,PROTO:1,OP:5,ACTR:2fcaff7]
IM::ReportData
=> Sending
I (29555) rs_matter::transport::core:
>>>>> UDP [fe80::35:fa83:74e1:ef6d%2]:64698 [SID:1,CTR:2fcaff8][I|A,EID:965c,PROTO:0,OP:10,ACTR:c5f46bd]
SC::MRPStandAloneAck
=> Standalone Ack, dropping
I (29575) rs_matter::respond: Responder: Handler 0 / exchange 3::0: Completed
I (29585) rs_matter::transport::core:
>>>>> UDP [fe80::35:fa83:74e1:ef6d%2]:64698 [SID:1,CTR:2fcaff9][I|A,EID:965d,PROTO:0,OP:10,ACTR:c5f46be]
SC::MRPStandAloneAck
=> Standalone Ack, dropping
I (29595) rs_matter::respond: Responder: Handler 2 / exchange 3::1: Completed
I (29615) rs_matter::transport::session: Creating a new exchange: 965e/Responder(AcceptPending)
I (29615) rs_matter::transport::core:
>>>>> UDP [fe80::35:fa83:74e1:ef6d%2]:64698 [SID:1,CTR:2fcaffa][I|R,EID:965e,PROTO:1,OP:2]
IM::ReadRequest
=> Processing (new exchange)
I (29635) rs_matter::transport::core: Exchange 3::0: Accepted
I (29635) rs_matter::respond: Responder: Handler 0 / exchange 3::0: Starting
I (29655) rs_matter::transport::exchange:
<<<<< UDP [fe80::35:fa83:74e1:ef6d%2]:64698 [SID:71dd,CTR:c5f46bf][A|R,EID:965e,PROTO:1,OP:5,ACTR:2fcaffa]
IM::ReportData
=> Sending
I (29685) rs_matter::transport::core:
>>>>> UDP [fe80::35:fa83:74e1:ef6d%2]:64698 [SID:1,CTR:2fcaffb][I|A,EID:965e,PROTO:0,OP:10,ACTR:c5f46bf]
SC::MRPStandAloneAck
=> Standalone Ack, dropping
I (29695) rs_matter::respond: Responder: Handler 0 / exchange 3::0: Completed
I (29725) rs_matter::transport::session: Creating a new exchange: 965f/Responder(AcceptPending)
I (29735) rs_matter::transport::core:
>>>>> UDP [fe80::35:fa83:74e1:ef6d%2]:64698 [SID:1,CTR:2fcaffc][I|R,EID:965f,PROTO:1,OP:8]
IM::InvokeRequest
=> Processing (new exchange)
I (29745) rs_matter::transport::core: Exchange 3::0: Accepted
I (29755) rs_matter::respond: Responder: Handler 0 / exchange 3::0: Starting
I (29765) rs_matter::data_model::sdm::general_commissioning: Handling command ARM Fail Safe
I (29775) rs_matter::transport::exchange:
<<<<< UDP [fe80::35:fa83:74e1:ef6d%2]:64698 [SID:71dd,CTR:c5f46c0][A|R,EID:965f,PROTO:1,OP:9,ACTR:2fcaffc]
IM::InvokeResponse
=> Sending
I (29815) rs_matter::transport::core:
>>>>> UDP [fe80::35:fa83:74e1:ef6d%2]:64698 [SID:1,CTR:2fcaffd][I|A,EID:965f,PROTO:0,OP:10,ACTR:c5f46c0]
SC::MRPStandAloneAck
=> Standalone Ack, dropping
I (29825) rs_matter::respond: Responder: Handler 0 / exchange 3::0: Completed
I (29845) rs_matter::transport::session: Creating a new exchange: 9660/Responder(AcceptPending)
I (29845) rs_matter::transport::core:
>>>>> UDP [fe80::35:fa83:74e1:ef6d%2]:64698 [SID:1,CTR:2fcaffe][I|R,EID:9660,PROTO:1,OP:8]
IM::InvokeRequest
=> Processing (new exchange)
I (29865) rs_matter::transport::core: Exchange 3::0: Accepted
I (29865) rs_matter::respond: Responder: Handler 0 / exchange 3::0: Starting
I (29875) rs_matter::data_model::sdm::noc: Handling command CSRRequest
I (29885) rs_matter::data_model::sdm::noc: Received CSR Nonce:OctetStr([50, 79, 131, 147, 10, 45, 233, 114, 100, 133, 72, 51, 102, 5, 139, 116, 45, 12, 48, 228, 204, 26, 133, 236, 68, 225, 109, 15, 60, 71, 104, 230])
I (30665) rs_matter::transport::exchange:
<<<<< UDP [fe80::35:fa83:74e1:ef6d%2]:64698 [SID:71dd,CTR:c5f46c1][A|R,EID:9660,PROTO:1,OP:9,ACTR:2fcaffe]
IM::InvokeResponse
=> Sending
I (30695) rs_matter::transport::core:
>>>>> UDP [fe80::35:fa83:74e1:ef6d%2]:64698 [SID:1,CTR:2fcaffe][I|R,EID:9660,PROTO:1,OP:8]
IM::InvokeRequest
=> Duplicate, sending ACK
I (30695) rs_matter::transport::core:
<<<<< UDP [fe80::35:fa83:74e1:ef6d%2]:64698 [SID:71dd,CTR:c5f46c2][A,EID:9660,PROTO:0,OP:10,ACTR:2fcaffe]
SC::MRPStandAloneAck
=> Sending (system)
I (30745) rs_matter::transport::core:
>>>>> UDP [fe80::35:fa83:74e1:ef6d%2]:64698 [SID:1,CTR:2fcaffe][I|R,EID:9660,PROTO:1,OP:8]
IM::InvokeRequest
=> Duplicate, sending ACK
I (30755) rs_matter::transport::core:
<<<<< UDP [fe80::35:fa83:74e1:ef6d%2]:64698 [SID:71dd,CTR:c5f46c3][A,EID:9660,PROTO:0,OP:10,ACTR:2fcaffe]
SC::MRPStandAloneAck
=> Sending (system)
I (30785) rs_matter::transport::core:
>>>>> UDP [fe80::35:fa83:74e1:ef6d%2]:64698 [SID:1,CTR:2fcafff][I|A,EID:9660,PROTO:0,OP:10,ACTR:c5f46c1]
SC::MRPStandAloneAck
=> Standalone Ack, dropping
I (30805) rs_matter::respond: Responder: Handler 0 / exchange 3::0: Completed
I (30815) rs_matter::transport::session: Creating a new exchange: 9661/Responder(AcceptPending)
I (30815) rs_matter::transport::core:
>>>>> UDP [fe80::35:fa83:74e1:ef6d%2]:64698 [SID:1,CTR:2fcb000][I|R,EID:9661,PROTO:1,OP:8]
IM::InvokeRequest
=> Processing (new exchange)
I (30835) rs_matter::transport::core: Exchange 3::0: Accepted
I (30845) rs_matter::respond: Responder: Handler 0 / exchange 3::0: Starting
I (30855) rs_matter::data_model::sdm::noc: Handling command AddTrustedRootCert
I (30855) rs_matter::data_model::sdm::noc: Received Trusted Cert:OctetStr([15, 30, 1, 1, 0, 24, 2, 1, 37, 3, 27, 14, 91, 25, b9, a0, b4, 72, 6, 8b, 26, 15, b2, 91, 88, b5, 18, 26, 4, 15, 19, dd, 2d, 24, 5, 0, 37, 6, 27, 14, 91, 25, b9, a0, b4, 72, 6, 8b, 26, 15, b2, 91, 88, b5, 18, 24, 7, 1, 24, 8, 1, 30, 9, 41, 4, f0, 85, a5, 2, 16, 92, 89, fb, 61, ff, 18, 4e, c6, ff, 8b, 5a, a, 4c, 28, 19, 8e, 2f, 57, 61, 6f, 81, f6, 76, ff, 25, f3, 89, 31, 66, 3b, 8e, 81, 3e, 28, 77, 76, 9c, 7c, eb, 61, a1, d0, fb, 85, 8e, 58, 3a, c8, 35, 62, 9f, 15, 33, 3a, d7, cf, 5b, 2, c5, 37, a, 35, 1, 29, 1, 18, 24, 2, 60, 30, 4, 14, 15, 1f, 95, 70, 90, e4, 8d, 92, 8b, f9, 7f, 4e, 65, 27, 5, ab, d4, 62, af, a6, 30, 5, 14, 15, 1f, 95, 70, 90, e4, 8d, 92, 8b, f9, 7f, 4e, 65, 27, 5, ab, d4, 62, af, a6, 18, 30, b, 40, 5d, 4, a8, 26, 6e, 9a, 17, 49, 71, f8, 76, 58, ac, ab, 42, 1d, 76, 41, 7a, 76, a6, ea, 7, be, a5, 7c, 6f, 47, 7c, c1, 9f, 3, 63, 8b, 1, cc, 8e, 44, d, f3, fd, 3a, b5, a3, 15, 4c, fa, 8d, 67, aa, 68, cf, 5e, 70, cc, 8f, cc, ae, 61, e2, 20, 85, 27, 1c, 18])
I (30955) rs_matter::transport::exchange:
<<<<< UDP [fe80::35:fa83:74e1:ef6d%2]:64698 [SID:71dd,CTR:c5f46c4][A|R,EID:9661,PROTO:1,OP:9,ACTR:2fcb000]
IM::InvokeResponse
=> Sending
I (30995) rs_matter::transport::core:
>>>>> UDP [fe80::35:fa83:74e1:ef6d%2]:64698 [SID:1,CTR:2fcb001][I|A,EID:9661,PROTO:0,OP:10,ACTR:c5f46c4]
SC::MRPStandAloneAck
=> Standalone Ack, dropping
I (31005) rs_matter::respond: Responder: Handler 0 / exchange 3::0: Completed
I (31025) rs_matter::transport::session: Creating a new exchange: 9662/Responder(AcceptPending)
I (31025) rs_matter::transport::core:
>>>>> UDP [fe80::35:fa83:74e1:ef6d%2]:64698 [SID:1,CTR:2fcb002][I|R,EID:9662,PROTO:1,OP:8]
IM::InvokeRequest
=> Processing (new exchange)
I (31045) rs_matter::transport::core: Exchange 3::0: Accepted
I (31045) rs_matter::respond: Responder: Handler 0 / exchange 3::0: Starting
I (31055) rs_matter::data_model::sdm::noc: Handling command AddNOC
I (31065) rs_matter::data_model::sdm::noc: Received NOC as: Version: [0]
[2]
Serial Num: [1]
Signature Algorithm:
ECDSA with SHA256
Issuer:
Chip Root CA Id:
"8B0672B4A0B92591"
Chip Fabric Id:
"00000000B58891B2"
Validity:
Not Before: 2024-06-01 12:24:34.0 +00:00:00
Not After: 9999-12-31 23:59:59.0 +00:00:00
Subject:
Chip Fabric Id:
"00000000B58891B2"
Chip Node Id:
"00000000B9F58F01"
Public Key Algorithm
ECPubKey
Prime256v1
Public-Key: [4, 96, ee, 15, e9, 24, ee, fd, a6, b3, 53, 8e, 18, 60, 4c, dc, aa, 3b, 94, 3f, 67, 53, 2a, b8, 82, e6, 8f, 76, db, 63, 37, 7b, c, 48, c5, ef, be, b1, 5d, 9f, 12, 8b, af, e2, 55, 13, 9c, 5f, 89, f2, ac, b1, 1d, 6e, 2b, 6c, d6, 13, 4c, c6, bb, 4b, 76, 8a, da]
X509v3 extensions: [3]
X509v3 Basic Constraints
critical: true
value:
X509v3 Key Usage
critical: true
value:
digitalSignature [80, 0]
X509v3 Extended Key Usage
critical: true
value:
ClientAuth
ServerAuth
Subject Key ID
value:
[7a, e2, bf, dc, 4, 92, c, d3, 4d, e0, e9, 83, d3, eb, 1b, 85, c, e0, a3, e]
Auth Key ID
value:
[0][15, 1f, 95, 70, 90, e4, 8d, 92, 8b, f9, 7f, 4e, 65, 27, 5, ab, d4, 62, af, a6]
Signature: [aa, 7a, a6, 45, 27, 46, 49, ad, b7, 7c, cb, d, c0, ef, eb, 65, b7, 3c, f9, 6c, 49, b2, ef, 90, 38, fc, c, 61, 7e, 80, 66, 3a, 49, 36, 48, 4, 2e, 6c, 75, be, c5, 56, d4, a9, be, 80, dd, 1f, 17, f6, 63, 7, 9e, 4e, 6a, 8b, f6, 39, a4, 4d, ae, a, d7, db]
I (31225) rs_matter::fabric: MDNS Service Name: 90A53EAD94034E37-00000000B9F58F01
I (31235) rs_matter::transport::exchange:
<<<<< UDP [fe80::35:fa83:74e1:ef6d%2]:64698 [SID:71dd,CTR:c5f46c5][A|R,EID:9662,PROTO:1,OP:9,ACTR:2fcb002]
IM::InvokeResponse
=> Sending
I (31265) rs_matter::mdns::builtin: Broadcasting mDNS entry to 224.0.0.251:5353
I (31275) rs_matter::mdns::builtin: Broadcasting mDNS entry to [ff02::fb%2]:5353
I (31295) rs_matter::transport::core:
>>>>> UDP [fe80::35:fa83:74e1:ef6d%2]:64698 [SID:1,CTR:2fcb003][I|A,EID:9662,PROTO:0,OP:10,ACTR:c5f46c5]
SC::MRPStandAloneAck
=> Standalone Ack, dropping
I (31305) rs_matter::respond: Responder: Handler 0 / exchange 3::0: Completed
I (31335) rs_matter::mdns::builtin: Replying to mDNS query from UDP [::ffff:192.168.1.114]:5353
I (31345) rs_matter::mdns::builtin: Replying to mDNS query from UDP [fe80::35:fa83:74e1:ef6d%2]:5353
I (31525) rs_matter::transport::session: Creating a new exchange: 9663/Responder(AcceptPending)
I (31525) rs_matter::transport::core:
>>>>> UDP [fe80::35:fa83:74e1:ef6d%2]:64698 [S,SID:0,CTR:dff6939,SRC:6fe121941da228d9][I|R,EID:9663,PROTO:0,OP:30]
SC::CASESigma1
=> Processing (new exchange)
I (31545) rs_matter::transport::core: Exchange 4::0: Accepted
I (31555) rs_matter::respond: Responder: Handler 0 / exchange 4::0: Starting
I (32065) rs_matter::transport::exchange:
<<<<< UDP [fe80::35:fa83:74e1:ef6d%2]:64698 [U,SID:0,CTR:eeb5215,DST:6fe121941da228d9][A|R,EID:9663,PROTO:0,OP:31,ACTR:dff6939]
SC::CASESigma2
=> Sending
I (32105) rs_matter::transport::core:
>>>>> UDP [fe80::35:fa83:74e1:ef6d%2]:64698 [S,SID:0,CTR:dff693a,SRC:6fe121941da228d9][I|A|R,EID:9663,PROTO:0,OP:32,ACTR:eeb5215]
SC::CASESigma3
=> Processing
I (32895) rs_matter::transport::exchange:
<<<<< UDP [fe80::35:fa83:74e1:ef6d%2]:64698 [U,SID:0,CTR:eeb5216,DST:6fe121941da228d9][A|R,EID:9663,PROTO:0,OP:40,ACTR:dff693a]
SC::StatusReport
=> Sending
I (32905) rs_matter::transport::core:
>>>>> UDP [fe80::35:fa83:74e1:ef6d%2]:64698 [S,SID:0,CTR:dff693a,SRC:6fe121941da228d9][I|A|R,EID:9663,PROTO:0,OP:32,ACTR:eeb5215]
SC::CASESigma3
=> Duplicate, sending ACK
I (32915) rs_matter::transport::core:
<<<<< UDP [fe80::35:fa83:74e1:ef6d%2]:64698 [U,SID:0,CTR:eeb5217,DST:6fe121941da228d9][A,EID:9663,PROTO:0,OP:10,ACTR:dff693a]
SC::MRPStandAloneAck
=> Sending (system)
I (32955) rs_matter::transport::core:
>>>>> UDP [fe80::35:fa83:74e1:ef6d%2]:64698 [S,SID:0,CTR:dff693a,SRC:6fe121941da228d9][I|A|R,EID:9663,PROTO:0,OP:32,ACTR:eeb5215]
SC::CASESigma3
=> Duplicate, sending ACK
I (32965) rs_matter::transport::core:
<<<<< UDP [fe80::35:fa83:74e1:ef6d%2]:64698 [U,SID:0,CTR:eeb5218,DST:6fe121941da228d9][A,EID:9663,PROTO:0,OP:10,ACTR:dff693a]
SC::MRPStandAloneAck
=> Sending (system)
E (33005) rs_matter::transport::core:
>>>>> UDP [fe80::35:fa83:74e1:ef6d%2]:64698 [SID:2,CTR:cb1b0e5][R,EID:0,PROTO:0,OP:0]
SC::MsgCounterSyncReq
=> Error (Error::NoSession), dropping
I (33015) rs_matter::transport::core:
>>>>> UDP [fe80::35:fa83:74e1:ef6d%2]:64698 [S,SID:0,CTR:dff693b,SRC:6fe121941da228d9][I|A,EID:9663,PROTO:0,OP:10,ACTR:eeb5216]
SC::MRPStandAloneAck
=> Standalone Ack, dropping
I (33035) rs_matter::respond: Responder: Handler 0 / exchange 4::0: Completed
I (33325) rs_matter::transport::session: Creating a new exchange: 9664/Responder(AcceptPending)
I (33325) rs_matter::transport::core:
>>>>> UDP [fe80::35:fa83:74e1:ef6d%2]:64698 [SID:2,CTR:cb1b0e5][I|R,EID:9664,PROTO:1,OP:8]
IM::InvokeRequest
=> Processing (new exchange)
I (33345) rs_matter::transport::core: Exchange 5::0: Accepted
I (33345) rs_matter::respond: Responder: Handler 0 / exchange 5::0: Starting
I (33365) rs_matter::data_model::sdm::general_commissioning: Handling command Commissioning Complete
I (33375) rs_matter::transport::exchange:
<<<<< UDP [fe80::35:fa83:74e1:ef6d%2]:64698 [SID:71de,CTR:729e4dd][A|R,EID:9664,PROTO:1,OP:9,ACTR:cb1b0e5]
IM::InvokeResponse
=> Sending
I (33415) rs_matter::transport::core:
>>>>> UDP [fe80::35:fa83:74e1:ef6d%2]:64698 [SID:2,CTR:cb1b0e6][I|A,EID:9664,PROTO:0,OP:10,ACTR:729e4dd]
SC::MRPStandAloneAck
=> Standalone Ack, dropping
I (33425) rs_matter::respond: Responder: Handler 0 / exchange 5::0: Completed
I (33435) rs_matter::transport::session: Creating a new exchange: 9665/Responder(AcceptPending)
I (33445) rs_matter::transport::core:
>>>>> UDP [fe80::35:fa83:74e1:ef6d%2]:64698 [SID:2,CTR:cb1b0e7][I|R,EID:9665,PROTO:1,OP:2]
IM::ReadRequest
=> Processing (new exchange)
I (33465) rs_matter::transport::core: Exchange 5::1: Accepted
I (33465) rs_matter::respond: Responder: Handler 0 / exchange 5::1: Starting
I (33475) rs_matter::transport::exchange:
<<<<< UDP [fe80::35:fa83:74e1:ef6d%2]:64698 [SID:71de,CTR:729e4de][A|R,EID:9665,PROTO:1,OP:5,ACTR:cb1b0e7]
IM::ReportData
=> Sending
I (33515) rs_matter::transport::core:
>>>>> UDP [fe80::35:fa83:74e1:ef6d%2]:64698 [SID:2,CTR:cb1b0e8][I|A,EID:9665,PROTO:0,OP:10,ACTR:729e4de]
SC::MRPStandAloneAck
=> Standalone Ack, dropping
I (33525) rs_matter::respond: Responder: Handler 0 / exchange 5::1: Completed
I (34035) light: Light toggled
I (35315) rs_matter::transport::session: Creating a new exchange: 9666/Responder(AcceptPending)
I (35315) rs_matter::transport::core:
>>>>> UDP [fe80::35:fa83:74e1:ef6d%2]:64698 [SID:1,CTR:2fcb004][I|R,EID:9666,PROTO:1,OP:2]
IM::ReadRequest
=> Processing (new exchange)
I (35335) rs_matter::transport::core: Exchange 3::0: Accepted
I (35335) rs_matter::respond: Responder: Handler 0 / exchange 3::0: Starting
I (35355) rs_matter::transport::exchange:
<<<<< UDP [fe80::35:fa83:74e1:ef6d%2]:64698 [SID:71dd,CTR:c5f46c6][A|R,EID:9666,PROTO:1,OP:5,ACTR:2fcb004]
IM::ReportData
=> Sending
I (35525) rs_matter::transport::core:
>>>>> UDP [fe80::35:fa83:74e1:ef6d%2]:64698 [SID:1,CTR:2fcb005][I|A,EID:9666,PROTO:0,OP:10,ACTR:c5f46c6]
SC::MRPStandAloneAck
=> Standalone Ack, dropping
I (35535) rs_matter::respond: Responder: Handler 0 / exchange 3::0: Completed
I (35545) rs_matter::transport::session: Creating a new exchange: 9667/Responder(AcceptPending)
I (35545) rs_matter::transport::core:
>>>>> UDP [fe80::35:fa83:74e1:ef6d%2]:64698 [SID:1,CTR:2fcb006][I|R,EID:9667,PROTO:1,OP:2]
IM::ReadRequest
=> Processing (new exchange)
I (35565) rs_matter::transport::core: Exchange 3::0: Accepted
I (35575) rs_matter::respond: Responder: Handler 0 / exchange 3::0: Starting
I (35585) rs_matter::transport::exchange:
<<<<< UDP [fe80::35:fa83:74e1:ef6d%2]:64698 [SID:71dd,CTR:c5f46c7][A|R,EID:9667,PROTO:1,OP:5,ACTR:2fcb006]
IM::ReportData
=> Sending
I (35735) rs_matter::transport::core:
>>>>> UDP [fe80::35:fa83:74e1:ef6d%2]:64698 [SID:1,CTR:2fcb007][I|A,EID:9667,PROTO:0,OP:10,ACTR:c5f46c7]
SC::MRPStandAloneAck
=> Standalone Ack, dropping
I (35745) rs_matter::respond: Responder: Handler 0 / exchange 3::0: Completed
I (35765) rs_matter::transport::session: Creating a new exchange: 9668/Responder(AcceptPending)
I (35765) rs_matter::transport::core:
>>>>> UDP [fe80::35:fa83:74e1:ef6d%2]:64698 [SID:1,CTR:2fcb008][I|R,EID:9668,PROTO:1,OP:2]
IM::ReadRequest
=> Processing (new exchange)
I (35785) rs_matter::transport::core: Exchange 3::0: Accepted
I (35785) rs_matter::respond: Responder: Handler 0 / exchange 3::0: Starting
I (35795) rs_matter::transport::exchange:
<<<<< UDP [fe80::35:fa83:74e1:ef6d%2]:64698 [SID:71dd,CTR:c5f46c8][A|R,EID:9668,PROTO:1,OP:5,ACTR:2fcb008]
IM::ReportData
=> Sending
I (35835) rs_matter::transport::core:
>>>>> UDP [fe80::35:fa83:74e1:ef6d%2]:64698 [SID:1,CTR:2fcb009][I|A,EID:9668,PROTO:0,OP:10,ACTR:c5f46c8]
SC::MRPStandAloneAck
=> Standalone Ack, dropping
I (35845) rs_matter::respond: Responder: Handler 0 / exchange 3::0: Completed
I (36345) rs_matter::mdns::builtin: Replying to mDNS query from UDP [::ffff:192.168.1.114]:5353
I (36375) rs_matter::mdns::builtin: Replying to mDNS query from UDP [fe80::35:fa83:74e1:ef6d%2]:5353
I (37775) rs_matter::transport::session: Creating a new exchange: 8241/Responder(AcceptPending)
I (37775) rs_matter::transport::core:
>>>>> UDP [fe80::10c7:e96a:b4fd:87e9%2]:62537 [S,SID:0,CTR:985027c,SRC:fa0470768dfe4348][I|R,EID:8241,PROTO:0,OP:30]
SC::CASESigma1
=> Processing (new exchange)
I (37795) rs_matter::transport::core: Exchange 6::0: Accepted
I (37805) rs_matter::respond: Responder: Handler 0 / exchange 6::0: Starting
I (38315) rs_matter::transport::exchange:
<<<<< UDP [fe80::10c7:e96a:b4fd:87e9%2]:62537 [U,SID:0,CTR:992c8c5,DST:fa0470768dfe4348][A|R,EID:8241,PROTO:0,OP:31,ACTR:985027c]
SC::CASESigma2
=> Sending
I (38345) rs_matter::transport::core:
>>>>> UDP [fe80::10c7:e96a:b4fd:87e9%2]:62537 [S,SID:0,CTR:985027d,SRC:fa0470768dfe4348][I|A|R,EID:8241,PROTO:0,OP:32,ACTR:992c8c5]
SC::CASESigma3
=> Processing
I (39125) rs_matter::transport::exchange:
<<<<< UDP [fe80::10c7:e96a:b4fd:87e9%2]:62537 [U,SID:0,CTR:992c8c6,DST:fa0470768dfe4348][A|R,EID:8241,PROTO:0,OP:40,ACTR:985027d]
SC::StatusReport
=> Sending
I (39145) rs_matter::transport::core:
>>>>> UDP [fe80::10c7:e96a:b4fd:87e9%2]:62537 [S,SID:0,CTR:985027d,SRC:fa0470768dfe4348][I|A|R,EID:8241,PROTO:0,OP:32,ACTR:992c8c5]
SC::CASESigma3
=> Duplicate, sending ACK
I (39155) rs_matter::transport::core:
<<<<< UDP [fe80::10c7:e96a:b4fd:87e9%2]:62537 [U,SID:0,CTR:992c8c7,DST:fa0470768dfe4348][A,EID:8241,PROTO:0,OP:10,ACTR:985027d]
SC::MRPStandAloneAck
=> Sending (system)
I (39185) light: Light toggled
I (39205) rs_matter::transport::core:
>>>>> UDP [fe80::10c7:e96a:b4fd:87e9%2]:62537 [S,SID:0,CTR:985027d,SRC:fa0470768dfe4348][I|A|R,EID:8241,PROTO:0,OP:32,ACTR:992c8c5]
SC::CASESigma3
=> Duplicate, sending ACK
I (39215) rs_matter::transport::core:
<<<<< UDP [fe80::10c7:e96a:b4fd:87e9%2]:62537 [U,SID:0,CTR:992c8c8,DST:fa0470768dfe4348][A,EID:8241,PROTO:0,OP:10,ACTR:985027d]
SC::MRPStandAloneAck
=> Sending (system)
E (39245) rs_matter::transport::core:
>>>>> UDP [fe80::10c7:e96a:b4fd:87e9%2]:62537 [SID:3,CTR:417fa72][R,EID:0,PROTO:0,OP:0]
SC::MsgCounterSyncReq
=> Error (Error::NoSession), dropping
E (39265) rs_matter::transport::core:
>>>>> UDP [fe80::10c7:e96a:b4fd:87e9%2]:62537 [SID:3,CTR:417fa73][R,EID:0,PROTO:0,OP:0]
SC::MsgCounterSyncReq
=> Error (Error::NoSession), dropping
E (39285) rs_matter::transport::core:
>>>>> UDP [fe80::10c7:e96a:b4fd:87e9%2]:62537 [SID:3,CTR:417fa74][R,EID:0,PROTO:0,OP:0]
SC::MsgCounterSyncReq
=> Error (Error::NoSession), dropping
I (39305) rs_matter::transport::core:
>>>>> UDP [fe80::10c7:e96a:b4fd:87e9%2]:62537 [S,SID:0,CTR:985027e,SRC:fa0470768dfe4348][I|A,EID:8241,PROTO:0,OP:10,ACTR:992c8c6]
SC::MRPStandAloneAck
=> Standalone Ack, dropping
I (39315) rs_matter::respond: Responder: Handler 0 / exchange 6::0: Completed
I (39335) rs_matter::transport::session: Creating a new exchange: 8245/Responder(AcceptPending)
I (39335) rs_matter::transport::core:
>>>>> UDP [fe80::10c7:e96a:b4fd:87e9%2]:62537 [SID:3,CTR:417fa75][I|R,EID:8245,PROTO:1,OP:8]
IM::InvokeRequest
=> Processing (new exchange)
I (39355) rs_matter::transport::core: Exchange 7::0: Accepted
I (39355) rs_matter::respond: Responder: Handler 0 / exchange 7::0: Starting
I (39365) rs_matter::data_model::sdm::noc: Handling command Update Fabric Label
I (39375) rs_matter::transport::exchange:
<<<<< UDP [fe80::10c7:e96a:b4fd:87e9%2]:62537 [SID:b1f3,CTR:94a3fa7][A|R,EID:8245,PROTO:1,OP:9,ACTR:417fa75]
IM::InvokeResponse
=> Sending
I (39415) rs_matter::transport::core:
>>>>> UDP [fe80::10c7:e96a:b4fd:87e9%2]:62537 [SID:3,CTR:417fa76][I|A,EID:8245,PROTO:0,OP:10,ACTR:94a3fa7]
SC::MRPStandAloneAck
=> Standalone Ack, dropping
I (39435) rs_matter::respond: Responder: Handler 0 / exchange 7::0: Completed
I (39625) rs_matter::transport::core:
>>>>> UDP [fe80::10c7:e96a:b4fd:87e9%2]:62537 [SID:3,CTR:417fa73][I|R,EID:8243,PROTO:1,OP:3]
IM::SubscribeRequest
=> Duplicate, sending ACK
I (39635) rs_matter::transport::core:
<<<<< UDP [fe80::10c7:e96a:b4fd:87e9%2]:62537 [SID:b1f3,CTR:94a3fa8][A,EID:8243,PROTO:0,OP:10,ACTR:417fa73]
SC::MRPStandAloneAck
=> Sending (system)
I (39675) rs_matter::transport::core:
>>>>> UDP [fe80::10c7:e96a:b4fd:87e9%2]:62537 [SID:3,CTR:417fa72][I|R,EID:8242,PROTO:1,OP:2]
IM::ReadRequest
=> Duplicate, sending ACK
I (39675) rs_matter::transport::core:
<<<<< UDP [fe80::10c7:e96a:b4fd:87e9%2]:62537 [SID:b1f3,CTR:94a3fa9][A,EID:8242,PROTO:0,OP:10,ACTR:417fa72]
SC::MRPStandAloneAck
=> Sending (system)
I (39715) rs_matter::transport::core:
>>>>> UDP [fe80::10c7:e96a:b4fd:87e9%2]:62537 [SID:3,CTR:417fa74][I|R,EID:8244,PROTO:1,OP:2]
IM::ReadRequest
=> Duplicate, sending ACK
I (39725) rs_matter::transport::core:
<<<<< UDP [fe80::10c7:e96a:b4fd:87e9%2]:62537 [SID:b1f3,CTR:94a3faa][A,EID:8244,PROTO:0,OP:10,ACTR:417fa74]
SC::MRPStandAloneAck
=> Sending (system)
I (44195) light: Light toggled
I (45755) rs_matter::transport::session: Creating a new exchange: 8246/Responder(AcceptPending)
I (45755) rs_matter::transport::core:
>>>>> UDP [fe80::10c7:e96a:b4fd:87e9%2]:62537 [S,SID:0,CTR:985027f,SRC:768a8546f0c7a918][I|R,EID:8246,PROTO:0,OP:30]
SC::CASESigma1
=> Processing (new exchange)
I (45785) rs_matter::transport::core: Exchange 8::0: Accepted
I (45785) rs_matter::respond: Responder: Handler 0 / exchange 8::0: Starting
I (46295) rs_matter::transport::exchange:
<<<<< UDP [fe80::10c7:e96a:b4fd:87e9%2]:62537 [U,SID:0,CTR:4290fa7,DST:768a8546f0c7a918][A|R,EID:8246,PROTO:0,OP:31,ACTR:985027f]
SC::CASESigma2
=> Sending
I (46325) rs_matter::transport::core:
>>>>> UDP [fe80::10c7:e96a:b4fd:87e9%2]:62537 [S,SID:0,CTR:985027f,SRC:768a8546f0c7a918][I|R,EID:8246,PROTO:0,OP:30]
SC::CASESigma1
=> Duplicate, sending ACK
I (46335) rs_matter::transport::core:
<<<<< UDP [fe80::10c7:e96a:b4fd:87e9%2]:62537 [U,SID:0,CTR:4290fa8,DST:768a8546f0c7a918][A,EID:8246,PROTO:0,OP:10,ACTR:985027f]
SC::MRPStandAloneAck
=> Sending (system)
I (46365) rs_matter::transport::core:
>>>>> UDP [fe80::10c7:e96a:b4fd:87e9%2]:62537 [S,SID:0,CTR:9850280,SRC:768a8546f0c7a918][I|A|R,EID:8246,PROTO:0,OP:32,ACTR:4290fa7]
SC::CASESigma3
=> Processing
I (47145) rs_matter::transport::exchange:
<<<<< UDP [fe80::10c7:e96a:b4fd:87e9%2]:62537 [U,SID:0,CTR:4290fa9,DST:768a8546f0c7a918][A|R,EID:8246,PROTO:0,OP:40,ACTR:9850280]
SC::StatusReport
=> Sending
I (47155) rs_matter::transport::core:
>>>>> UDP [fe80::10c7:e96a:b4fd:87e9%2]:62537 [S,SID:0,CTR:9850280,SRC:768a8546f0c7a918][I|A|R,EID:8246,PROTO:0,OP:32,ACTR:4290fa7]
SC::CASESigma3
=> Duplicate, sending ACK
I (47175) rs_matter::transport::core:
<<<<< UDP [fe80::10c7:e96a:b4fd:87e9%2]:62537 [U,SID:0,CTR:4290faa,DST:768a8546f0c7a918][A,EID:8246,PROTO:0,OP:10,ACTR:9850280]
SC::MRPStandAloneAck
=> Sending (system)
I (47215) rs_matter::transport::core:
>>>>> UDP [fe80::10c7:e96a:b4fd:87e9%2]:62537 [S,SID:0,CTR:9850280,SRC:768a8546f0c7a918][I|A|R,EID:8246,PROTO:0,OP:32,ACTR:4290fa7]
SC::CASESigma3
=> Duplicate, sending ACK
I (47225) rs_matter::transport::core:
<<<<< UDP [fe80::10c7:e96a:b4fd:87e9%2]:62537 [U,SID:0,CTR:4290fab,DST:768a8546f0c7a918][A,EID:8246,PROTO:0,OP:10,ACTR:9850280]
SC::MRPStandAloneAck
=> Sending (system)
E (47255) rs_matter::transport::core:
>>>>> UDP [fe80::10c7:e96a:b4fd:87e9%2]:62537 [SID:4,CTR:d43c89][R,EID:0,PROTO:0,OP:0]
SC::MsgCounterSyncReq
=> Error (Error::NoSession), dropping
E (47275) rs_matter::transport::core:
>>>>> UDP [fe80::10c7:e96a:b4fd:87e9%2]:62537 [SID:4,CTR:d43c8a][R,EID:0,PROTO:0,OP:0]
SC::MsgCounterSyncReq
=> Error (Error::NoSession), dropping
I (47295) rs_matter::transport::core:
>>>>> UDP [fe80::10c7:e96a:b4fd:87e9%2]:62537 [S,SID:0,CTR:9850281,SRC:768a8546f0c7a918][I|A,EID:8246,PROTO:0,OP:10,ACTR:4290fa9]
SC::MRPStandAloneAck
=> Standalone Ack, dropping
I (47305) rs_matter::respond: Responder: Handler 0 / exchange 8::0: Completed
I (47605) rs_matter::transport::session: Creating a new exchange: 8247/Responder(AcceptPending)
I (47605) rs_matter::transport::core:
>>>>> UDP [fe80::10c7:e96a:b4fd:87e9%2]:62537 [SID:4,CTR:d43c89][I|R,EID:8247,PROTO:1,OP:3]
IM::SubscribeRequest
=> Processing (new exchange)
I (47625) rs_matter::transport::core: Exchange 9::0: Accepted
I (47625) rs_matter::respond: Responder: Handler 0 / exchange 9::0: Starting
I (47655) rs_matter::transport::exchange:
<<<<< UDP [fe80::10c7:e96a:b4fd:87e9%2]:62537 [SID:b1f4,CTR:9cb96e6][A|R,EID:8247,PROTO:1,OP:5,ACTR:d43c89]
IM::ReportData
=> Sending
I (47685) rs_matter::transport::session: Creating a new exchange: 8248/Responder(AcceptPending)
I (47685) rs_matter::transport::core:
>>>>> UDP [fe80::10c7:e96a:b4fd:87e9%2]:62537 [SID:4,CTR:d43c8a][I|R,EID:8248,PROTO:1,OP:2]
IM::ReadRequest
=> Processing (new exchange)
I (47705) rs_matter::transport::core: Exchange 9::1: Accepted
I (47715) rs_matter::respond: Responder: Handler 2 / exchange 9::1: Starting
I (47725) rs_matter::transport::exchange:
<<<<< UDP [fe80::10c7:e96a:b4fd:87e9%2]:62537 [SID:b1f4,CTR:9cb96e7][A|R,EID:8248,PROTO:1,OP:5,ACTR:d43c8a]
IM::ReportData
=> Sending
I (47745) rs_matter::transport::core:
>>>>> UDP [fe80::10c7:e96a:b4fd:87e9%2]:62537 [SID:4,CTR:d43c8b][I|A|R,EID:8247,PROTO:1,OP:1,ACTR:9cb96e6]
IM::StatusResponse
=> Processing
E (47775) rs_matter::acl: ACL Disallow for subjects [1374029535, ] fab idx 1
E (47785) rs_matter::acl: ACLS: [ { AclEntry { privilege: Privilege(V | O | M | A), auth_mode: Case, subjects: [Some(1374029535), None, None, None], targets: NotNull([None, None, None]), fab_idx: Some(1) } }, { AclEntry { privilege: Privilege(V | O | M | A), auth_mode: Case, subjects: [Some(1392877287), None, None, None], targets: NotNull([None, None, None]), fab_idx: Some(2) } }, ]
E (47815) rs_matter::acl: ACL Disallow for subjects [1374029535, ] fab idx 1
E (47815) rs_matter::acl: ACLS: [ { AclEntry { privilege: Privilege(V | O | M | A), auth_mode: Case, subjects: [Some(1374029535), None, None, None], targets: NotNull([None, None, None]), fab_idx: Some(1) } }, { AclEntry { privilege: Privilege(V | O | M | A), auth_mode: Case, subjects: [Some(1392877287), None, None, None], targets: NotNull([None, None, None]), fab_idx: Some(2) } }, ]
E (47855) rs_matter::acl: ACL Disallow for subjects [1374029535, ] fab idx 1
E (47865) rs_matter::acl: ACLS: [ { AclEntry { privilege: Privilege(V | O | M | A), auth_mode: Case, subjects: [Some(1374029535), None, None, None], targets: NotNull([None, None, None]), fab_idx: Some(1) } }, { AclEntry { privilege: Privilege(V | O | M | A), auth_mode: Case, subjects: [Some(1392877287), None, None, None], targets: NotNull([None, None, None]), fab_idx: Some(2) } }, ]
I (47895) rs_matter::transport::exchange:
<<<<< UDP [fe80::10c7:e96a:b4fd:87e9%2]:62537 [SID:b1f4,CTR:9cb96e8][A|R,EID:8247,PROTO:1,OP:5,ACTR:d43c8b]
IM::ReportData
=> Sending
I (47945) rs_matter::transport::core:
>>>>> UDP [fe80::10c7:e96a:b4fd:87e9%2]:62537 [SID:4,CTR:d43c8c][I|A,EID:8248,PROTO:0,OP:10,ACTR:9cb96e7]
SC::MRPStandAloneAck
=> Standalone Ack, dropping
I (47955) rs_matter::respond: Responder: Handler 2 / exchange 9::1: Completed
I (47975) rs_matter::transport::session: Creating a new exchange: 8249/Responder(AcceptPending)
I (47975) rs_matter::transport::core:
>>>>> UDP [fe80::10c7:e96a:b4fd:87e9%2]:62537 [SID:4,CTR:d43c8d][I|R,EID:8249,PROTO:1,OP:2]
IM::ReadRequest
=> Processing (new exchange)
I (48005) rs_matter::transport::core: Exchange 9::2: Accepted
I (48005) rs_matter::respond: Responder: Handler 2 / exchange 9::2: Starting
I (48015) rs_matter::transport::exchange:
<<<<< UDP [fe80::10c7:e96a:b4fd:87e9%2]:62537 [SID:b1f4,CTR:9cb96e9][A|R,EID:8249,PROTO:1,OP:5,ACTR:d43c8d]
IM::ReportData
=> Sending
I (48035) rs_matter::transport::core:
>>>>> UDP [fe80::10c7:e96a:b4fd:87e9%2]:62537 [SID:4,CTR:d43c8e][I|A|R,EID:8247,PROTO:1,OP:1,ACTR:9cb96e8]
IM::StatusResponse
=> Processing
I (48065) rs_matter::transport::exchange:
<<<<< UDP [fe80::10c7:e96a:b4fd:87e9%2]:62537 [SID:b1f4,CTR:9cb96ea][A|R,EID:8247,PROTO:1,OP:5,ACTR:d43c8e]
IM::ReportData
=> Sending
I (48085) rs_matter::transport::core:
>>>>> UDP [fe80::10c7:e96a:b4fd:87e9%2]:62537 [SID:4,CTR:d43c8f][I|A,EID:8249,PROTO:0,OP:10,ACTR:9cb96e9]
SC::MRPStandAloneAck
=> Standalone Ack, dropping
I (48105) rs_matter::respond: Responder: Handler 2 / exchange 9::2: Completed
I (48115) rs_matter::transport::session: Creating a new exchange: 824a/Responder(AcceptPending)
I (48115) rs_matter::transport::core:
>>>>> UDP [fe80::10c7:e96a:b4fd:87e9%2]:62537 [SID:4,CTR:d43c90][I|R,EID:824a,PROTO:1,OP:2]
IM::ReadRequest
=> Processing (new exchange)
I (48135) rs_matter::transport::core: Exchange 9::3: Accepted
I (48135) rs_matter::respond: Responder: Handler 2 / exchange 9::3: Starting
I (48145) rs_matter::transport::exchange:
<<<<< UDP [fe80::10c7:e96a:b4fd:87e9%2]:62537 [SID:b1f4,CTR:9cb96eb][A|R,EID:824a,PROTO:1,OP:5,ACTR:d43c90]
IM::ReportData
=> Sending
I (48175) rs_matter::transport::core:
>>>>> UDP [fe80::10c7:e96a:b4fd:87e9%2]:62537 [SID:4,CTR:d43c91][I|A|R,EID:8247,PROTO:1,OP:1,ACTR:9cb96ea]
IM::StatusResponse
=> Processing
I (48195) rs_matter::transport::exchange:
<<<<< UDP [fe80::10c7:e96a:b4fd:87e9%2]:62537 [SID:b1f4,CTR:9cb96ec][A|R,EID:8247,PROTO:1,OP:4,ACTR:d43c91]
IM::SubscribeResponse
=> Sending
I (48215) rs_matter::transport::session: Creating a new exchange: 824b/Responder(AcceptPending)
I (48215) rs_matter::transport::core:
>>>>> UDP [fe80::10c7:e96a:b4fd:87e9%2]:62537 [SID:4,CTR:d43c92][I|R,EID:824b,PROTO:1,OP:2]
IM::ReadRequest
=> Processing (new exchange)
I (48235) rs_matter::transport::core: Exchange 9::4: Accepted
I (48245) rs_matter::respond: Responder: Handler 3 / exchange 9::4: Starting
I (48255) rs_matter::transport::exchange:
<<<<< UDP [fe80::10c7:e96a:b4fd:87e9%2]:62537 [SID:b1f4,CTR:9cb96ed][A|R,EID:824b,PROTO:1,OP:5,ACTR:d43c92]
IM::ReportData
=> Sending
I (48275) rs_matter::transport::core:
>>>>> UDP [fe80::10c7:e96a:b4fd:87e9%2]:62537 [SID:4,CTR:d43c93][I|A,EID:824a,PROTO:0,OP:10,ACTR:9cb96eb]
SC::MRPStandAloneAck
=> Standalone Ack, dropping
I (48295) rs_matter::respond: Responder: Handler 2 / exchange 9::3: Completed
I (48305) rs_matter::transport::session: Creating a new exchange: 824c/Responder(AcceptPending)
I (48305) rs_matter::transport::core:
>>>>> UDP [fe80::10c7:e96a:b4fd:87e9%2]:62537 [SID:4,CTR:d43c94][I|R,EID:824c,PROTO:1,OP:2]
IM::ReadRequest
=> Processing (new exchange)
I (48325) rs_matter::transport::core: Exchange 9::1: Accepted
I (48325) rs_matter::respond: Responder: Handler 2 / exchange 9::1: Starting
I (48345) rs_matter::transport::exchange:
<<<<< UDP [fe80::10c7:e96a:b4fd:87e9%2]:62537 [SID:b1f4,CTR:9cb96ee][A|R,EID:824c,PROTO:1,OP:5,ACTR:d43c94]
IM::ReportData
=> Sending
I (48365) rs_matter::transport::core:
>>>>> UDP [fe80::10c7:e96a:b4fd:87e9%2]:62537 [SID:4,CTR:d43c95][I|A,EID:8247,PROTO:0,OP:10,ACTR:9cb96ec]
SC::MRPStandAloneAck
=> Standalone Ack, dropping
I (48385) rs_matter::data_model::core: Subscription 51e606df::1 created
I (48385) rs_matter::respond: Responder: Handler 0 / exchange 9::0: Completed
I (48395) rs_matter::transport::core:
>>>>> UDP [fe80::10c7:e96a:b4fd:87e9%2]:62537 [SID:4,CTR:d43c96][I|A,EID:824b,PROTO:0,OP:10,ACTR:9cb96ed]
SC::MRPStandAloneAck
=> Standalone Ack, dropping
I (48415) rs_matter::respond: Responder: Handler 3 / exchange 9::4: Completed
I (48435) rs_matter::transport::core:
>>>>> UDP [fe80::10c7:e96a:b4fd:87e9%2]:62537 [SID:4,CTR:d43c97][I|A,EID:824c,PROTO:0,OP:10,ACTR:9cb96ee]
SC::MRPStandAloneAck
=> Standalone Ack, dropping
I (48445) rs_matter::respond: Responder: Handler 2 / exchange 9::1: Completed
I (48455) rs_matter::transport::session: Creating a new exchange: 824d/Responder(AcceptPending)
I (48455) rs_matter::transport::core:
>>>>> UDP [fe80::10c7:e96a:b4fd:87e9%2]:62537 [SID:4,CTR:d43c98][I|R,EID:824d,PROTO:1,OP:2]
IM::ReadRequest
=> Processing (new exchange)
I (48475) rs_matter::transport::core: Exchange 9::0: Accepted
I (48485) rs_matter::respond: Responder: Handler 0 / exchange 9::0: Starting
I (48495) rs_matter::transport::exchange:
<<<<< UDP [fe80::10c7:e96a:b4fd:87e9%2]:62537 [SID:b1f4,CTR:9cb96ef][A|R,EID:824d,PROTO:1,OP:5,ACTR:d43c98]
IM::ReportData
=> Sending
I (48515) rs_matter::transport::session: Creating a new exchange: 824e/Responder(AcceptPending)
I (48515) rs_matter::transport::core:
>>>>> UDP [fe80::10c7:e96a:b4fd:87e9%2]:62537 [SID:4,CTR:d43c99][I|R,EID:824e,PROTO:1,OP:2]
IM::ReadRequest
=> Processing (new exchange)
I (48545) rs_matter::transport::core: Exchange 9::1: Accepted
I (48545) rs_matter::respond: Responder: Handler 2 / exchange 9::1: Starting
I (48555) rs_matter::transport::exchange:
<<<<< UDP [fe80::10c7:e96a:b4fd:87e9%2]:62537 [SID:b1f4,CTR:9cb96f0][A|R,EID:824e,PROTO:1,OP:5,ACTR:d43c99]
IM::ReportData
=> Sending
I (48585) rs_matter::transport::core:
>>>>> UDP [fe80::10c7:e96a:b4fd:87e9%2]:62537 [SID:4,CTR:d43c9a][I|A,EID:824d,PROTO:0,OP:10,ACTR:9cb96ef]
SC::MRPStandAloneAck
=> Standalone Ack, dropping
I (48595) rs_matter::respond: Responder: Handler 0 / exchange 9::0: Completed
I (48615) rs_matter::transport::session: Creating a new exchange: 824f/Responder(AcceptPending)
I (48615) rs_matter::transport::core:
>>>>> UDP [fe80::10c7:e96a:b4fd:87e9%2]:62537 [SID:4,CTR:d43c9b][I|R,EID:824f,PROTO:1,OP:2]
IM::ReadRequest
=> Processing (new exchange)
I (48635) rs_matter::transport::core: Exchange 9::0: Accepted
I (48635) rs_matter::respond: Responder: Handler 0 / exchange 9::0: Starting
I (48645) rs_matter::transport::exchange:
<<<<< UDP [fe80::10c7:e96a:b4fd:87e9%2]:62537 [SID:b1f4,CTR:9cb96f1][A|R,EID:824f,PROTO:1,OP:5,ACTR:d43c9b]
IM::ReportData
=> Sending
I (48675) rs_matter::transport::core:
>>>>> UDP [fe80::10c7:e96a:b4fd:87e9%2]:62537 [SID:4,CTR:d43c9c][I|A,EID:824e,PROTO:0,OP:10,ACTR:9cb96f0]
SC::MRPStandAloneAck
=> Standalone Ack, dropping
I (48695) rs_matter::respond: Responder: Handler 2 / exchange 9::1: Completed
I (48705) rs_matter::transport::core:
>>>>> UDP [fe80::10c7:e96a:b4fd:87e9%2]:62537 [SID:4,CTR:d43c9d][I|A,EID:824f,PROTO:0,OP:10,ACTR:9cb96f1]
SC::MRPStandAloneAck
=> Standalone Ack, dropping
I (48715) rs_matter::respond: Responder: Handler 0 / exchange 9::0: Completed
I (48725) rs_matter::transport::session: Creating a new exchange: 8250/Responder(AcceptPending)
I (48735) rs_matter::transport::core:
>>>>> UDP [fe80::10c7:e96a:b4fd:87e9%2]:62537 [SID:4,CTR:d43c9e][I|R,EID:8250,PROTO:1,OP:2]
IM::ReadRequest
=> Processing (new exchange)
I (48745) rs_matter::transport::core: Exchange 9::0: Accepted
I (48755) rs_matter::respond: Responder: Handler 0 / exchange 9::0: Starting
I (48765) rs_matter::transport::exchange:
<<<<< UDP [fe80::10c7:e96a:b4fd:87e9%2]:62537 [SID:b1f4,CTR:9cb96f2][A|R,EID:8250,PROTO:1,OP:5,ACTR:d43c9e]
IM::ReportData
=> Sending
I (48785) rs_matter::transport::session: Creating a new exchange: 8251/Responder(AcceptPending)
I (48795) rs_matter::transport::core:
>>>>> UDP [fe80::10c7:e96a:b4fd:87e9%2]:62537 [SID:4,CTR:d43c9f][I|R,EID:8251,PROTO:1,OP:2]
IM::ReadRequest
=> Processing (new exchange)
I (48815) rs_matter::transport::core: Exchange 9::1: Accepted
I (48825) rs_matter::respond: Responder: Handler 2 / exchange 9::1: Starting
I (48835) rs_matter::transport::exchange:
<<<<< UDP [fe80::10c7:e96a:b4fd:87e9%2]:62537 [SID:b1f4,CTR:9cb96f3][A|R,EID:8251,PROTO:1,OP:5,ACTR:d43c9f]
IM::ReportData
=> Sending
I (48855) rs_matter::transport::core:
>>>>> UDP [fe80::10c7:e96a:b4fd:87e9%2]:62537 [SID:4,CTR:d43ca0][I|A,EID:8250,PROTO:0,OP:10,ACTR:9cb96f2]
SC::MRPStandAloneAck
=> Standalone Ack, dropping
I (48875) rs_matter::respond: Responder: Handler 0 / exchange 9::0: Completed
I (48885) rs_matter::transport::core:
>>>>> UDP [fe80::10c7:e96a:b4fd:87e9%2]:62537 [SID:4,CTR:d43ca1][I|A,EID:8251,PROTO:0,OP:10,ACTR:9cb96f3]
SC::MRPStandAloneAck
=> Standalone Ack, dropping
I (48895) rs_matter::respond: Responder: Handler 2 / exchange 9::1: Completed
I (49205) light: Light toggled
I (49205) rs_matter::data_model::core: About to report data for subscription 51e606df::1
I (49215) rs_matter::transport::session: Creating a new exchange: 1/Initiator(Owned)
I (49215) rs_matter::transport::core: Exchange 3::0: Initiated
I (49245) rs_matter::transport::exchange:
<<<<< UDP [fe80::35:fa83:74e1:ef6d%2]:64698 [SID:71dd,CTR:c5f46c9][I|R,EID:1,PROTO:1,OP:5]
IM::ReportData
=> Sending
I (49275) rs_matter::transport::session: Creating a new exchange: 8252/Responder(AcceptPending)
I (49275) rs_matter::transport::core:
>>>>> UDP [fe80::10c7:e96a:b4fd:87e9%2]:62537 [SID:4,CTR:d43ca2][I|R,EID:8252,PROTO:1,OP:2]
IM::ReadRequest
=> Processing (new exchange)
I (49295) rs_matter::transport::core: Exchange 9::0: Accepted
I (49295) rs_matter::respond: Responder: Handler 0 / exchange 9::0: Starting
I (49315) rs_matter::transport::exchange:
<<<<< UDP [fe80::10c7:e96a:b4fd:87e9%2]:62537 [SID:b1f4,CTR:9cb96f4][A|R,EID:8252,PROTO:1,OP:5,ACTR:d43ca2]
IM::ReportData
=> Sending
I (49335) rs_matter::transport::core:
>>>>> UDP [fe80::35:fa83:74e1:ef6d%2]:64698 [SID:1,CTR:2fcb00a][A|R,EID:1,PROTO:1,OP:1,ACTR:c5f46c9]
IM::StatusResponse
=> Processing
W (49355) rs_matter::data_model::core: Got status response InvalidSubscription, aborting interaction
I (49355) rs_matter::transport::exchange:
<<<<< UDP [fe80::35:fa83:74e1:ef6d%2]:64698 [SID:71dd,CTR:c5f46ca][I|A,EID:1,PROTO:0,OP:10,ACTR:2fcb00a]
SC::MRPStandAloneAck
=> Sending
I (49375) rs_matter::data_model::core: Subscription 51e606df::1 removed during reporting
I (49385) rs_matter::transport::core:
>>>>> UDP [fe80::10c7:e96a:b4fd:87e9%2]:62537 [SID:4,CTR:d43ca3][I|A,EID:8252,PROTO:0,OP:10,ACTR:9cb96f4]
SC::MRPStandAloneAck
=> Standalone Ack, dropping
I (49415) rs_matter::respond: Responder: Handler 0 / exchange 9::0: Completed
By the way, something must've changed since already the previous bugfix, because if you look at the esp32 logs, it is switching to Wifi and, then actual controller (not your phone) is talking to it over UDP,.
The conversation ends up approximately here:
>>>>> UDP [fe80::35:fa83:74e1:ef6d%2]:64698 [SID:1,CTR:97186d7][I|R,EID:9637,PROTO:1,OP:8]
IM::InvokeRequest
=> Processing (new exchange)
I (69495) light: Light toggled
I (69505) rs_matter::transport::core: Exchange 3::4: Accepted
I (69505) rs_matter::respond: Responder: Handler 0 / exchange 3::4: Starting
I (69515) rs_matter::data_model::sdm::noc: Handling command Remove Fabric
I (69525) rs_matter::transport::exchange:
<<<<< UDP [fe80::35:fa83:74e1:ef6d%2]:64698 [SID:71da,CTR:b900a0][A|R,EID:9637,PROTO:1,OP:9,ACTR:97186d7]
IM::InvokeResponse
=> Sending
... and I don't think it is successful, because I don't see anywhere a SubscribeRequest
, so there must still be something not quite right going on. If you still have issues after the last fix, I'll enable more detailed logging.
Hmm, weird that Homekit does not even subscribe to us for notifications. AWS Alexa does not do it either, but Google Home does.
A couple of questions:
BTW If by error message you mean this in the esp32 log:
E (47775) rs_matter::acl: ACL Disallow for subjects [1374029535, ] fab idx 1
... this is not really an error and we have to lower it to "info". I'll open an issue for that. If you saw error message on the phone/Homekit controller itself, would you share those? You should not see any, or else something is still not quite right...
Hmm, weird that Homekit does not even subscribe to us for notifications. AWS Alexa does not do it either, but Google Home does.
A couple of questions:
- Can you turn on/off the light from within the UI of Homekit (whatever it is)?
- Do you see - in the UI of HomeKit - the light turning off and on approx. every 5 seconds?
I can turn it OFF / ON but it doesn't toggle state every 5s (it kinda does it after a while ~30s) but looks like something is not quite right there
Finding a few warnings in logs (maybe related ?)
W (506595) rs_matter::data_model::core: Got status response InvalidSubscription, aborting interaction
For the error messages, I meant things like
E (366585) rs_matter::transport::mrp: Mismatch in retrans-table's msg counter and received msg counter: received 7b63f59, expected 7b63f5b.
E (47775) rs_matter::acl: ACL Disallow for subjects [1374029535, ] fab idx 1
E (47785) rs_matter::acl: ACLS: [ { AclEntry { privilege: Privilege(V | O | M | A), auth_mode: Case, subjects: [Some(1374029535), None, None, None], targets: NotNull([None, None, None]), fab_idx: Some(1) } }, { AclEntry { privilege: Privilege(V | O | M | A), auth_mode: Case, subjects: [Some(1392877287), None, None, None], targets: NotNull([None, None, None]), fab_idx: Some(2) } }, ]
E (47815) rs_matter::acl: ACL Disallow for subjects [1374029535, ] fab idx 1
E (47815) rs_matter::acl: ACLS: [ { AclEntry { privilege: Privilege(V | O | M | A), auth_mode: Case, subjects: [Some(1374029535), None, None, None], targets: NotNull([None, None, None]), fab_idx: Some(1) } }, { AclEntry { privilege: Privilege(V | O | M | A), auth_mode: Case, subjects: [Some(1392877287), None, None, None], targets: NotNull([None, None, None]), fab_idx: Some(2) } }, ]
E (47855) rs_matter::acl: ACL Disallow for subjects [1374029535, ] fab idx 1
E (47865) rs_matter::acl: ACLS: [ { AclEntry { privilege: Privilege(V | O | M | A), auth_mode: Case, subjects: [Some(1374029535), None, None, None], targets: NotNull([None, None, None]), fab_idx: Some(1) } }, { AclEntry { privilege: Privilege(V | O | M | A), auth_mode: Case, subjects: [Some(1392877287), None, None, None], targets: NotNull([None, None, None]), fab_idx: Some(2) } }, ]
I can turn it OFF / ON but it doesn't toggle state every 5s (it kinda does it after a while ~30s) but looks like something is not quite right there
Finding a few warnings in logs (maybe related ?)
W (506595) rs_matter::data_model::core: Got status response InvalidSubscription, aborting interaction
Ahhh, yes, that's a problem! Let me dig into it myself.
For the error messages, I meant things like
E (366585) rs_matter::transport::mrp: Mismatch in retrans-table's msg counter and received msg counter: received 7b63f59,
This needs fixing, but is not the end of the world.
E (47775) rs_matter::acl: ACL Disallow for subjects [1374029535, ] fab idx 1
All ACL "errors" are not real errors, so they need to be suppressed as per my previous message.
Rather than torturing you with remote debugging, I just got myself an Apple TV device and an old iPhone. So let me see what is going on with the subscriptions in HomeKit...
No worries, was really happy to do the testing but yeah, wise decision I think. Seems like Apple Home is more intricate that some other vendor's solutions 😄
@3wnbr1 How did you get access to the Home app logs on the iPhone? (Sorry, Android user here.)
BTW, are you running iOS 16.x or 17.x? With latest iOS 17.x I see one extra problem...
I used the builtin macOS Console
app, you can stream logs when tethered with a cable to the iPhone
As of iOS, I am running latest 17.5.1
Ah, also idevicesyslog | grep "homed(Matter)"
when connected to Linux over USB... (not owning a Mac myself anymore...)
@3wnbr1 Sorry for the delay, I have not forgotten the "invalid subscription" issue - it is just that I had to fix a few more urgent issues first.
BTW: I can reproduce it every time, BUT: after a while (say - 2/3 minutes) it auto-recovers, and I get reliable subscription reports every 5 seconds. As in, the light is switching on and off in Home. Don't you?
No worries
I never had it recovering in the sense that it would display toggling. Seems like at a certain point it pools again the status and display either on or off but nothing more
But as the original pairing issue is now resolved, would you prefer if we were to close this one and follow up on a new issue ?
Up to you if you feel like opening a new issue - do it and I'll close this one.
BTW: Can you help me with some remote debugging again? I don't think I can pair to my Apple TV from my Linux machines yet. If you can just do it from your Mac, and then send me the Matter logs on your controller. I'm basically trying to understand what is the error seen on the controller when I see at the other side "invalid subscription"...
Sure, let's do that.
Yeah, sure. Happy to help. Btw if you want a more direct communication, you can DM me through X / Twitter and I can share my Signal / WhatsApp
Closing as this was fixed by commits https://github.com/ivmarkov/esp-idf-matter/commit/2450644775a5b11cba5cadc1a0f61c8e25054e46, https://github.com/ivmarkov/esp-idf-matter/commit/eb6ec2b4a2c7faeac42e4e961fbeec84b982aa55 and https://github.com/project-chip/rs-matter/pull/175
Subscription issue tracked in #3
Sure, let's do that.
Yeah, sure. Happy to help. Btw if you want a more direct communication, you can DM me through X / Twitter and I can share my Signal / WhatsApp
No no - all I need is an excerpt of the logs from your controller (not from your phone as it is only commissioning, but from the homepod) which are from around the same time when you get the invalid subscription message on the esp32. Not a "real" remote debugging in the strict sense. :)
Description
First of all, that's really awesome work, thank you so much for all your efforts to bring Rust and Matter to embedded devices. This is really exiting for hobby / smart home devices
I got really excited when I was able to "pair" the https://github.com/project-chip/rs-matter
onoff_light
example with my HomePod / HomeKit.However I was not able to reproduce that success with the
esp-idf-matter
light
example. It fails about midway during the setup process and reports in the console the following errorI am a beginner with Matter but the way I understand the error message is that it points towards the (Root Node 0) Network Commissioning endpoint (49) Thread (2) is not implemented. Looking at the code I can't figure out with my HomePod tried to commission it as a Thread Device
I would be glad to help if you have some indications of where to start
Full log