search

t0bst4r / home-assistant-matter-hub

Publish your Home-Assistant Instance using Matter.
Apache License 2.0
157 stars 10 forks source link

Devices not reacting in Alexa #175

Closed schdief06 closed 2 days ago

schdief06 commented 5 days ago

Pairing the hub to alexa works just fine and all devices are working after pairing. But aprox. 24h later all the devices stop working and are showing "not reacting".

If I remove the hub from alexa, do a facotry reset on the hub and reconnect everything, I get another 24h followed by the same problem.

I can't find any errors in the logs. But ,when restarting the addon in Home Assistant, I find some of those:

[ 2024-11-20T07:22:31.209Z ] [ DEBUG ] [ matter.js / ExchangeManager                        ]: Cannot find a session for ID 16127
  at ExchangeManager.onMessage (file:///usr/local/lib/node_modules/home-assistant-matter-hub/node_modules/@matter/protocol/dist/esm/protocol/ExchangeManager.js:165:13)
  at file:///usr/local/lib/node_modules/home-assistant-matter-hub/node_modules/@matter/protocol/dist/esm/protocol/ExchangeManager.js:334:16
  at file:///usr/local/lib/node_modules/home-assistant-matter-hub/node_modules/@matter/general/dist/esm/net/UdpInterface.js:29:52
  at Socket.messageListener (file:///usr/local/lib/node_modules/home-assistant-matter-hub/node_modules/@matter/nodejs/dist/esm/net/NodeJsUdpChannel.js:111:7)
  at Socket.emit (node:events:517:28)
  at UDP.onMessage [as onmessage] (node:dgram:942:8)

Maybe the session is expired?

t0bst4r commented 5 days ago

After restarting the addon, the session needs to be re-established. E.g. Alexa needs 5-10 minutes to get that done. Or you can decrease the time by controlling an entity several times until it gets "available" again.

Anyway they should not get "not reachable" automatically after 24h.

Do you have any special network setup? Do you have IPv6 enabled in your network?

Is the disconnect reproducable? Can you find the logs of the exact time it stops working? Or at least, can you share the debug log when Alexa tries to control a device which is unavailable? It probably won’t print an error, but maybe some useful debug logs.

What happens if you tell Alexa to search for new devices? Do the "not reachable" ones come up as "available“ again?

schdief06 commented 5 days ago

Thanks for your answer. I will try to answer all your questions.

Do you have any special network setup? Do you have IPv6 enabled in your network?

Nothing special in my opinion. FritzBox router, Unifi access points, a dumb TP-Link switch and PiHole as dns server. Maybe I try disable blocking on PiHole and try again... But I hope you will find something with the logs below. :) IPv6 is disabeld.

Is the disconnect reproducable?

I had it happen twice. So I guess, yes.

Can you find the logs of the exact time it stops working?

I think I found the moment, when it stopped working. I didn't have debug logs enabled back then, but there is an error:

[ 2024-11-19T19:36:17.884Z ] [ ERROR ] [ matter.js / ServerSubscription                     ]: Error sending subscription update message (error count=1): RetransmissionLimitReachedError
  at #retransmitMessage (file:///usr/local/lib/node_modules/home-assistant-matter-hub/node_modules/@matter/protocol/dist/esm/protocol/MessageExchange.js:382:37)
  at StandardTimer.callback (file:///usr/local/lib/node_modules/home-assistant-matter-hub/node_modules/@matter/protocol/dist/esm/protocol/MessageExchange.js:375:42)
  at Timeout._onTimeout (file:///usr/local/lib/node_modules/home-assistant-matter-hub/node_modules/@matter/general/dist/esm/time/Time.js:110:12)
  at listOnTimeout (node:internal/timers:569:17)
  at process.processTimers (node:internal/timers:512:7)
[ 2024-11-19T19:36:18.136Z ] [ INFO  ] [ matter.js / CaseServer                             ]: Received pairing request from udp://10.0.12.157:5541
[ 2024-11-19T19:36:18.153Z ] [ INFO  ] [ matter.js / CaseServer                             ]: session 16087 resumed with udp://10.0.12.157:5541 for Fabric 0412725686FE1520(index 1) and PeerNode 0410FCCB4E3CE901 with CATs 1114154
[ 2024-11-19T19:36:18.164Z ] [ INFO  ] [ matter.js / InsecureSession                        ]: End insecure session insecure/4606607159700784098
[ 2024-11-19T19:36:19.741Z ] [ INFO  ] [ matter.js / CaseServer                             ]: Received pairing request from udp://10.0.12.23:5541
[ 2024-11-19T19:36:19.758Z ] [ INFO  ] [ matter.js / CaseServer                             ]: session 16088 resumed with udp://10.0.12.23:5541 for Fabric 0412725686FE1520(index 1) and PeerNode 04054D49BE4C8EE1 with CATs 1114154
[ 2024-11-19T19:36:19.808Z ] [ INFO  ] [ matter.js / InsecureSession                        ]: End insecure session insecure/16432174918559891896
[ 2024-11-19T19:36:19.809Z ] [ INFO  ] [ matter.js / SecureSession                          ]: End CASE session secure/16079
[ 2024-11-19T19:36:19.809Z ] [ INFO  ] [ matter.js / ChannelManager                         ]: Close oldest channel for fabric peer@1:0x4054d49be4c8ee1 (from session 16079)
[ 2024-11-19T19:36:21.560Z ] [ INFO  ] [ matter.js / CaseServer                             ]: Received pairing request from udp://10.0.12.247:5541
[ 2024-11-19T19:36:21.565Z ] [ INFO  ] [ matter.js / CaseServer                             ]: session 16089 resumed with udp://10.0.12.247:5541 for Fabric 0412725686FE1520(index 1) and PeerNode 04054D4B63AD7321 with CATs 1114154
[ 2024-11-19T19:36:21.677Z ] [ INFO  ] [ matter.js / InsecureSession                        ]: End insecure session insecure/5102614778733346838
[ 2024-11-19T19:37:52.306Z ] [ ERROR ] [ matter.js / ServerSubscription                     ]: Error sending subscription update message (error count=2): RetransmissionLimitReachedError
  at #retransmitMessage (file:///usr/local/lib/node_modules/home-assistant-matter-hub/node_modules/@matter/protocol/dist/esm/protocol/MessageExchange.js:382:37)
  at StandardTimer.callback (file:///usr/local/lib/node_modules/home-assistant-matter-hub/node_modules/@matter/protocol/dist/esm/protocol/MessageExchange.js:375:42)
  at Timeout._onTimeout (file:///usr/local/lib/node_modules/home-assistant-matter-hub/node_modules/@matter/general/dist/esm/time/Time.js:110:12)
  at listOnTimeout (node:internal/timers:569:17)
  at process.processTimers (node:internal/timers:512:7)
[ 2024-11-19T19:39:26.937Z ] [ ERROR ] [ matter.js / ServerSubscription                     ]: Error sending subscription update message (error count=3): RetransmissionLimitReachedError
  at #retransmitMessage (file:///usr/local/lib/node_modules/home-assistant-matter-hub/node_modules/@matter/protocol/dist/esm/protocol/MessageExchange.js:382:37)
  at StandardTimer.callback (file:///usr/local/lib/node_modules/home-assistant-matter-hub/node_modules/@matter/protocol/dist/esm/protocol/MessageExchange.js:375:42)
  at Timeout._onTimeout (file:///usr/local/lib/node_modules/home-assistant-matter-hub/node_modules/@matter/general/dist/esm/time/Time.js:110:12)
  at listOnTimeout (node:internal/timers:569:17)
  at process.processTimers (node:internal/timers:512:7)
[ 2024-11-19T19:39:26.937Z ] [ ERROR ] [ matter.js / ServerSubscription                     ]: Sending update failed 3 times in a row, canceling subscription 2539789168 and let controller subscribe again.
[ 2024-11-19T19:39:26.941Z ] [ INFO  ] [ matter.js / SecureSession                          ]: Register Session secure/16086 to close when exchange is ended.
[ 2024-11-19T19:39:30.649Z ] [ INFO  ] [ matter.js / SecureSession                          ]: End CASE session secure/16086
[ 2024-11-19T19:51:48.884Z ] [ INFO  ] [ matter.js / CaseServer                             ]: Received pairing request from udp://10.0.12.247:5541
[ 2024-11-19T19:51:48.891Z ] [ INFO  ] [ matter.js / CaseServer                             ]: session 16090 resumed with udp://10.0.12.247:5541 for Fabric 0412725686FE1520(index 1) and PeerNode 04054D4B63AD7321 with CATs 1114154
[ 2024-11-19T19:51:48.973Z ] [ INFO  ] [ matter.js / InsecureSession                        ]: End insecure session insecure/2716267180421967303
[ 2024-11-19T19:51:48.973Z ] [ INFO  ] [ matter.js / SecureSession                          ]: End CASE session secure/16078
[ 2024-11-19T19:51:48.973Z ] [ INFO  ] [ matter.js / ChannelManager                         ]: Close oldest channel for fabric peer@1:0x4054d4b63ad7321 (from session 16078)

After this, the paring request repeats in varying time intervals until I restarted the addon this morning. Interestingly, I don't see any pairing requests now (after restarting).

Or at least, can you share the debug log when Alexa tries to control a device which is unavailable? It probably won’t print an error, but maybe some useful debug logs.

I don't get any log entries at all, when trying to control a device. I only get some read requests from time to time. The ip addresses match my echo devices:

[ 2024-11-20T08:13:01.327Z ] [ DEBUG ] [ matter.js / MessageExchange                        ]: New exchange channel: udp://10.0.12.23:5541 on session secure/49147 protocol: 1 id: 7002 session: secure/49147 peerSessionId: 49147 active threshold ms: 4000 active interval ms: 300 idle interval ms: 500 maxTransmissions: 5 useMrp: true
[ 2024-11-20T08:13:01.327Z ] [ DEBUG ] [ matter.js / MessageExchange                        ]: Message « id: 49147/7002/131521078 type: 1/2 acked: undefined reqAck: true duplicate: false payload: 1536001724020024031d2404031818280324ff0b18
[ 2024-11-20T08:13:01.327Z ] [ DEBUG ] [ matter.js / InteractionServer                      ]: Received read request from udp://10.0.12.23:5541 on session secure/49147: attributes:RootNode(0x0)/Descriptor(0x1d)/partsList(0x3), events:none isFabricFiltered=false
[ 2024-11-20T08:13:01.327Z ] [ DEBUG ] [ matter.js / Behavior                               ]: Read 0d821f6dc187419c85ba5177843170fb.descriptor.state.partsList via online#7d6da36@4054d49be4c8ee1
[ 2024-11-20T08:13:01.328Z ] [ DEBUG ] [ matter.js / InteractionServer                      ]: Read attribute from udp://10.0.12.23:5541 on session secure/49147: RootNode(0x0)/Descriptor(0x1d)/partsList(0x3)=[1,10,11,12,13,14,15,16,17,18,19,2,20,21,22,23,24,25,26,27,28,29,3,30,31,32,33,34,35,36,37,38,39,4,40,41,42,43,44,45,46,47,48,49,5,50,51,52,53,54,55,56,57,58,6,7,8,9] (version=3376484151)
[ 2024-11-20T08:13:01.328Z ] [ DEBUG ] [ matter.js / InteractionMessenger                   ]: Sending DataReport chunk with 1 attributes and 0 events: 152 bytes (moreChunkedMessages: false, suppressResponse: true)
[ 2024-11-20T08:13:01.328Z ] [ DEBUG ] [ matter.js / ExchangeManager                        ]: Message » id: 49147/7002/265441208 type: 1/5 acked: 131521078 reqAck: true duplicate: false payload: 1536011535012600370f41c9370124020024031d2404031836020401040a040b040c040d040e040f04100411041204130402041404150416041704180419041a041b041c041d0403041e041f04200421042204230424042504260427040404280429042a042b042c042d042e042f04300431040504320433043404350436043704380439043a040604070408040918181818290424ff0c18
[ 2024-11-20T08:13:01.354Z ] [ DEBUG ] [ matter.js / MessageExchange                        ]: Message « id: 49147/7002/131521079 type: 0/16 acked: 265441208 reqAck: false duplicate: false payload:

What happens if you tell Alexa to search for new devices? Do the "not reachable" ones come up as "available“ again?

The devices stay unreachable.

Apollon77 commented 4 days ago

Would be great to see that matter.js side Debug logs

schdief06 commented 4 days ago

Would be great to see that matter.js side Debug logs

No problem. How can I provide those? Or do you mean the debug logs, when the error occured?

t0bst4r commented 4 days ago

Yes, matter.js logs are part of the normal log. tbh. since you added some debug logs above, i don't know what else @Apollon77 is expecting 😄

Would it be a problem to factory reset it and pair it again? Just make sure, to delete the bridge within the Alexa App first, because Alexa seems to have problems managing a device which isnt paired anymore. At least for me the Alexa app is very buggy.

IPv6 is disabeld.

We currently have a discussion in #171 . Can you try turning IPv6 on, or do you have any concerns?

Apollon77 commented 4 days ago

The first shows logs was just info logs :-))ut yes ipv6 should be enabled !!

schdief06 commented 4 days ago

The first shows logs was just info logs :-))ut yes ipv6 should be enabled !!

Yeah the first logs are from before I enabled debug log level.

IPv6 is disabeld.

We currently have a discussion in #171 . Can you try turning IPv6 on, or do you have any concerns?

Ok, I should have been more specific about IPv6. I don't have any DHCPv6-server in my network, but routing is still enabled by default. I just read #171 and the troubleshooting readme of matter.js. As far as I understand, this should be fine like this?

Would it be a problem to factory reset it and pair it again? Just make sure, to delete the bridge within the Alexa App first, because Alexa seems to have problems managing a device which isnt paired anymore. At least for me the Alexa app is very buggy.

The Alexa app is just the worst app in the universe.... I will now

  1. delete the bridge from Alexa app
  2. factory reset the bridge
  3. pair it again
  4. see you again in 24h ;)
schdief06 commented 4 days ago

Alexa app stated that "something went wrong while pairing". But it just worked. At least I see all devices and can control them. Maybe you are interested in the logs:

491eb00d_hamh_2024-11-21T15-10-52.851Z.log

t0bst4r commented 4 days ago

Thank you for the log. But is everything operational now? As you described initially it will randomly stop working after 24 hrs right?

t0bst4r commented 4 days ago

Just had a look at the log. How many devices do you have exposed through matter? Alexa cannot handle too many devices (in the past some users reported about 80-100). Especially when they are paired all at once.

This is definetly missing in the docs. I'll add it.

myevit commented 3 days ago

Just will leave my experience. Alexa works snappy with matter hub. This is exact reason I use it. I have Unifi ad block enabled, as well, IPV6. Got 58 devices.

schdief06 commented 3 days ago

Thank you for the log. But is everything operational now? As you described initially it will randomly stop working after 24 hrs right?

Yes everything is operational right now. And yes, the last 2 times it stopped working after 24h. We will see at about 4 pm today.

How many devices do you have exposed through matter?

57 devices.

schdief06 commented 2 days ago

So, now it's more than 40h later and it is still working. No idea what happend the last 2 times, but it seems to be fine now. I will keep the debug logs on for now, in case it happens again later. But I will close this ticket.

Thanks for your help anyway! It's highly apreciated!