ivmarkov / esp-idf-matter

Run rs-matter on Espressif chips with ESP IDF
https://github.com/ivmarkov/esp-idf-matter
Apache License 2.0
19 stars 1 forks source link

Homekit controller denies subscription reports with an "Invalid Subscription" error #3

Closed 3wnbr1 closed 1 month ago

3wnbr1 commented 1 month ago

Noticed with @ivmarkov during the investigation of #2 that the Apple Home app was not reporting the toggling of the lightbulb state from the example

A sample of the log lines around the warning Got status response InvalidSubscription, aborting interaction

>>>>> UDP [fe80::10c7:e96a:b4fd:87e9%2]:62537 [SID:7,CTR:11e8e25][I|A,EID:8384,PROTO:0,OP:10,ACTR:ec857f5]
SC::MRPStandAloneAck
 => Standalone Ack, dropping
I (213625) rs_matter::data_model::core: Subscription 51e606df::3 created
I (213635) rs_matter::respond: Responder: Handler 0 / exchange 15::0: Completed
I (217775) light: Light toggled
I (217775) rs_matter::data_model::core: About to report data for subscription 51e606df::3
I (217775) rs_matter::transport::session: New exchange: 3::0 [SID:1,RSID:8dad,EID:3] :: Initiator(Owned)
I (217785) rs_matter::transport::core: Exchange 3::0 [SID:1,RSID:8dad,EID:3]: Initiated
I (217815) rs_matter::transport::exchange:
<<<<< UDP [fe80::c28:c959:bc1c:ecbe%2]:60672 [SID:8dad,CTR:b53a79][I|R,EID:3,PROTO:1,OP:5]
IM::ReportData
 => Sending
I (217875) rs_matter::transport::core:
>>>>> UDP [fe80::c28:c959:bc1c:ecbe%2]:60672 [SID:1,CTR:523100][A|R,EID:3,PROTO:1,OP:1,ACTR:b53a79]
IM::StatusResponse
 => Processing
W (217885) rs_matter::data_model::core: Got status response InvalidSubscription, aborting interaction
I (217895) rs_matter::transport::exchange:
<<<<< UDP [fe80::c28:c959:bc1c:ecbe%2]:60672 [SID:8dad,CTR:b53a7a][I|A,EID:3,PROTO:0,OP:10,ACTR:523100]
SC::MRPStandAloneAck
 => Sending
I (217915) rs_matter::data_model::core: Subscription 51e606df::3 removed during reporting
I (222775) light: Light toggled
I (227785) light: Light toggled
ivmarkov commented 1 month ago

As per this I only need an excerpt of your homepod logs which is around the same time as the esp32 logs from above ^^^.

3wnbr1 commented 1 month ago

I managed to capture the logs from a full paring + usage on my HomePod. As it turns out, you can plug the USB-C connector and plug it into a laptop. It will blink orange due to power limitations but you can stream the logs similarly to the iPhone as soon as it is done booting up which took ~30s - 60s

Pairing + Subscription homepod.log esp32.log

ivmarkov commented 1 month ago

@3wnbr1 I think I found the problem. The PR linked to this issue will address part of the problem, but not all of it. We need to understand also why Homekit is so picky w.r.t. what Ipv6 address from the several it has we are contacting.

3wnbr1 commented 1 month ago

Yay, I tested your last commit and the issue seems to be resolved 👍

Thanks

ivmarkov commented 1 month ago

Yes - the last fix is still not in upstream rs-matter - only in my fork, but hopefully it will be merged upstream soon as well.