home-assistant / core

:house_with_garden: Open source home automation that puts local control and privacy first.
https://www.home-assistant.io
Apache License 2.0
73.68k stars 30.81k forks source link

SRV record already actively processed #104497

Closed jvmahon closed 10 months ago

jvmahon commented 11 months ago

The problem

I've noticed that in the Matter server logs, I get long repeats of a "DEBUG SRV record already actively processed" - is this a normal thing, or signs of an issue? If it isn't normal, are there any logs I can provide to help resolve this.

What version of Home Assistant Core has the issue?

2023.11.3

What was the last working version of Home Assistant Core?

No response

What type of installation are you running?

Home Assistant OS

Integration causing the issue

Matter

Link to integration documentation on our website

Matter

Diagnostics information

No response

Example YAML snippet

No response

Anything in the logs that might be useful for us?

2023-11-25 06:34:40 core-matter-server chip.EM[126] INFO <<< [E:48048r S:63462 M:10814931 (Ack:238548329)] (S) Msg TX to 1:000000000000002E [B2EC] [UDP:[fe80::3e52:a1ff:fefe:f18f%end0]:5540] --- Type 0001:01 (IM:StatusResponse)
2023-11-25 06:34:40 core-matter-server chip.EM[126] INFO >>> [E:48048r S:63462 M:238548330 (Ack:10814931)] (S) Msg RX from 1:000000000000002E [B2EC] --- Type 0000:10 (SecureChannel:StandaloneAck)
2023-11-25 06:34:40 core-matter-server chip.EM[126] DEBUG Found matching exchange: 48048r, Delegate: (nil)
2023-11-25 06:34:40 core-matter-server chip.EM[126] DEBUG Rxd Ack; Removing MessageCounter:10814931 from Retrans Table on exchange 48048r
2023-11-25 06:34:40 core-matter-server chip.DIS[126] DEBUG SRV record already actively processed.
2023-11-25 06:34:40 core-matter-server chip.DIS[126] DEBUG SRV record already actively processed.
2023-11-25 06:34:40 core-matter-server chip.DIS[126] DEBUG SRV record already actively processed.
2023-11-25 06:34:40 core-matter-server chip.DIS[126] DEBUG SRV record already actively processed.
2023-11-25 06:34:40 core-matter-server chip.DIS[126] DEBUG SRV record already actively processed.
2023-11-25 06:34:40 core-matter-server chip.DIS[126] DEBUG SRV record already actively processed.
2023-11-25 06:34:40 core-matter-server chip.DIS[126] DEBUG SRV record already actively processed.
2023-11-25 06:34:40 core-matter-server chip.DIS[126] DEBUG SRV record already actively processed.
2023-11-25 06:34:40 core-matter-server chip.DIS[126] DEBUG SRV record already actively processed.
2023-11-25 06:34:40 core-matter-server chip.DIS[126] DEBUG SRV record already actively processed.
2023-11-25 06:34:40 core-matter-server chip.DIS[126] DEBUG SRV record already actively processed.
2023-11-25 06:34:40 core-matter-server chip.DIS[126] DEBUG SRV record already actively processed.
2023-11-25 06:34:40 core-matter-server chip.DIS[126] DEBUG SRV record already actively processed.
2023-11-25 06:34:40 core-matter-server chip.DIS[126] DEBUG SRV record already actively processed.
2023-11-25 06:34:40 core-matter-server chip.DIS[126] DEBUG SRV record already actively processed.
2023-11-25 06:34:40 core-matter-server chip.DIS[126] DEBUG SRV record already actively processed.
2023-11-25 06:34:40 core-matter-server chip.DIS[126] DEBUG SRV record already actively processed.
2023-11-25 06:34:40 core-matter-server chip.DIS[126] DEBUG SRV record already actively processed.
2023-11-25 06:34:40 core-matter-server chip.DIS[126] DEBUG SRV record already actively processed.
2023-11-25 06:34:40 core-matter-server chip.DIS[126] DEBUG SRV record already actively processed.
2023-11-25 06:34:40 core-matter-server chip.DIS[126] DEBUG SRV record already actively processed.
2023-11-25 06:34:40 core-matter-server chip.DIS[126] DEBUG SRV record already actively processed.
2023-11-25 06:34:40 core-matter-server chip.DIS[126] DEBUG SRV record already actively processed.
2023-11-25 06:34:40 core-matter-server chip.DIS[126] DEBUG SRV record already actively processed.
2023-11-25 06:34:40 core-matter-server chip.DIS[126] DEBUG SRV record already actively processed.
2023-11-25 06:34:40 core-matter-server chip.DIS[126] DEBUG SRV record already actively processed.
2023-11-25 06:34:40 core-matter-server chip.DIS[126] DEBUG SRV record already actively processed.
2023-11-25 06:34:40 core-matter-server chip.DIS[126] DEBUG SRV record already actively processed.
2023-11-25 06:34:40 core-matter-server chip.DIS[126] DEBUG SRV record already actively processed.
2023-11-25 06:34:40 core-matter-server chip.DIS[126] DEBUG SRV record already actively processed.
2023-11-25 06:34:40 core-matter-server chip.DIS[126] DEBUG SRV record already actively processed.
2023-11-25 06:34:40 core-matter-server chip.DIS[126] DEBUG SRV record already actively processed.
2023-11-25 06:34:40 core-matter-server chip.DIS[126] DEBUG SRV record already actively processed.
2023-11-25 06:34:40 core-matter-server chip.DIS[126] DEBUG SRV record already actively processed.
2023-11-25 06:34:40 core-matter-server chip.DIS[126] DEBUG SRV record already actively processed.
2023-11-25 06:34:40 core-matter-server chip.DIS[126] DEBUG SRV record already actively processed.
2023-11-25 06:34:41 core-matter-server chip.DIS[126] DEBUG SRV record already actively processed.
2023-11-25 06:34:41 core-matter-server chip.DIS[126] DEBUG SRV record already actively processed.
2023-11-25 06:34:41 core-matter-server chip.DIS[126] DEBUG SRV record already actively processed.
2023-11-25 06:34:41 core-matter-server chip.DIS[126] DEBUG SRV record already actively processed.
2023-11-25 06:34:41 core-matter-server chip.DIS[126] DEBUG SRV record already actively processed.
2023-11-25 06:34:41 core-matter-server chip.DIS[126] DEBUG SRV record already actively processed.
2023-11-25 06:34:41 core-matter-server chip.DIS[126] DEBUG SRV record already actively processed.
2023-11-25 06:34:41 core-matter-server chip.DIS[126] DEBUG SRV record already actively processed.
2023-11-25 06:34:41 core-matter-server chip.DIS[126] DEBUG SRV record already actively processed.
2023-11-25 06:34:41 core-matter-server chip.DIS[126] DEBUG SRV record already actively processed.
2023-11-25 06:34:41 core-matter-server chip.DIS[126] DEBUG SRV record already actively processed.
2023-11-25 06:34:41 core-matter-server chip.DIS[126] DEBUG SRV record already actively processed.
2023-11-25 06:34:41 core-matter-server chip.DIS[126] DEBUG SRV record already actively processed.
2023-11-25 06:34:41 core-matter-server chip.DIS[126] DEBUG SRV record already actively processed.
2023-11-25 06:34:41 core-matter-server chip.DIS[126] DEBUG SRV record already actively processed.
2023-11-25 06:34:41 core-matter-server chip.DIS[126] DEBUG SRV record already actively processed.
2023-11-25 06:34:41 core-matter-server chip.DIS[126] DEBUG SRV record already actively processed.
2023-11-25 06:34:41 core-matter-server chip.DIS[126] DEBUG SRV record already actively processed.
2023-11-25 06:34:41 core-matter-server chip.DIS[126] DEBUG SRV record already actively processed.
2023-11-25 06:34:41 core-matter-server chip.DIS[126] DEBUG SRV record already actively processed.
2023-11-25 06:34:41 core-matter-server chip.DIS[126] DEBUG SRV record already actively processed.
2023-11-25 06:34:41 core-matter-server chip.DIS[126] DEBUG SRV record already actively processed.
2023-11-25 06:34:41 core-matter-server chip.DIS[126] DEBUG SRV record already actively processed.
2023-11-25 06:34:41 core-matter-server chip.DIS[126] DEBUG SRV record already actively processed.
2023-11-25 06:34:41 core-matter-server chip.DIS[126] DEBUG SRV record already actively processed.
2023-11-25 06:34:41 core-matter-server chip.DIS[126] DEBUG SRV record already actively processed.
2023-11-25 06:34:41 core-matter-server chip.DIS[126] DEBUG SRV record already actively processed.
2023-11-25 06:34:41 core-matter-server chip.DIS[126] DEBUG SRV record already actively processed.
2023-11-25 06:34:41 core-matter-server chip.DIS[126] DEBUG SRV record already actively processed.
2023-11-25 06:34:41 core-matter-server chip.DIS[126] DEBUG SRV record already actively processed.
2023-11-25 06:34:41 core-matter-server chip.DIS[126] DEBUG SRV record already actively processed.
2023-11-25 06:34:41 core-matter-server chip.DIS[126] DEBUG SRV record already actively processed.
2023-11-25 06:34:41 core-matter-server chip.DIS[126] DEBUG SRV record already actively processed.
2023-11-25 06:34:41 core-matter-server chip.DIS[126] DEBUG SRV record already actively processed.

Additional information

No response

home-assistant[bot] commented 11 months ago

Hey there @home-assistant/matter, mind taking a look at this issue as it has been labeled with an integration (matter) you are listed as a code owner for? Thanks!

Code owner commands Code owners of `matter` can trigger bot actions by commenting: - `@home-assistant close` Closes the issue. - `@home-assistant rename Awesome new title` Renames the issue. - `@home-assistant reopen` Reopen the issue. - `@home-assistant unassign matter` Removes the current integration label and assignees on the issue, add the integration domain after the command. - `@home-assistant add-label needs-more-information` Add a label (needs-more-information, problem in dependency, problem in custom component) to the issue. - `@home-assistant remove-label needs-more-information` Remove a label (needs-more-information, problem in dependency, problem in custom component) on the issue.

(message by CodeOwnersMention)


matter documentation matter source (message by IssueLinks)

marcelveldt commented 11 months ago

Do you run an mDNS responder in your network perhaps ? Especially the Unifi mdns implementation is known of over duplicating the broadcasts.

jvmahon commented 11 months ago

No, just "off the shelf" Google Nest Wifi Pro 6e. See: https://store.google.com/product/nest_wifi_pro?hl=en-US

I have a mesh of 6 of these, each with Ethernet for the backhaul connection between the WiFi points. I have both IPV4 and IPV6 enabled, but UPNP disabled.

I purchased these Nest WiFi points before starting my migration to Matter for two main reasons: 1. They each act as Openthread 1.3.0 Border Router which means my thread devices are always fairly close (30-40 feet) from one of these, so they each have a direct router connection, and 2. Given they are one of the newest Google Nest WiFi products, I assumed Google would have tested these thoroughly for use with Matter / Thread.

I also have 2 Apple TV 4Ks, each of which is also an 1.3.0 OTBR. I note that, at one point, in an attempt to see if the situation could be improved, I updated the Apple TVs and my iPhone to the iOS 17.2 beta. No difference.

I also tried where I basically shut down everything in my network except the WiFi points, the Apple TVs, HomeAssistant, and a number of TP-Link TAPO WiFi Matter devices. Still no luck.

I've now ordered a few Eve Energy plugs. I should have them by Saturday and I plan to then test with those in the mix. My planned testing will be pretty simple - un plug every network device except 1 of the WiFi points, 1 Apple TV, and the Matter devices, then try again. If there are any logs I should try to gather to help diagnose, please let me know what to do and how.

Thanks.

PS - Current Matter devices include ...

15 Aqara P2 contact sensors 3 Eve Motion sensors 17 Tapo WiFi Matter enabled products (Switches, Dimmers, outlets) 5 OREiN RGB bulbs (Matter over WiFi)

jvmahon commented 11 months ago

Is there any way to include in the logs an identifier of the device creating the SRV records? Even if just an IP address or something as that would make diagnostics much easier.

marcelveldt commented 11 months ago

Is there any way to include in the logs an identifier of the device creating the SRV records? Even if just an IP address or something as that would make diagnostics much easier.

No, this is coming from the lowlevel matter sdk doing the network discovery. https://github.com/project-chip/connectedhomeip/blob/ba504e34396545b506cb69adf8aa062cb94815c7/src/lib/dnssd/Resolver_ImplMinimalMdns.cpp#L206

From what I can tell, either some device(s) is sending duplicated packets or something in your network is forwarding the discovery packets. In any case it can't harm but is just a bit strange.

Maybe power off a few devices to discover which one is causing it.

jvmahon commented 11 months ago

Thanks. Is it possible to add details to that diagnostic message on the SDK level so as to identify the problem device?

I will try as you suggest - i.e., powering off devices - but I have about 75 devices on WiFi and many on Thread. It seems this would likely be at the device level, rather than network level.

marcelveldt commented 11 months ago

Nope, I don't have any influence over that message and this is actually the very first time I have seen it and I do A LOT of testing with all kind of Matter devices.

Sure you do not have an mDNS repeater running somewhere in your network without you knowing ? Shutdown any services/add-ons you may have running on your NAS/server/HA to see if one of those is doing fancy stuff

jvmahon commented 11 months ago

Nope, I don't have any influence over that message and this is actually the very first time I have seen it and I do A LOT of testing with all kind of Matter devices.

Sure you do not have an mDNS repeater running somewhere in your network without you knowing ? Shutdown any services/add-ons you may have running on your NAS/server/HA to see if one of those is doing fancy stuff

For the mDNS issue, I was wondering if it could be setting on my AT&T / Arris fiber modem - though that sits behind the Google Nest setup, so it should not be the source. Even HA is just the basic HA that one flashes to a RPI using the standard RPi imager copy - nothing custom. I'll check this weekend to see if there are any configuration settings on the modem that I can try.

I haven't tried WireShark, but would it be able to tell which device all those SRV Records are coming from?

I've seen other mentions of this problem (for example: https://community.home-assistant.io/t/trouble-commissioning-matter-device-w-skyconnect/548186) but nobody seems to have a good idea as to specific cause.

marcelveldt commented 10 months ago

Do we need to keep this report open as its not really an issue with HA core ?

jvmahon commented 10 months ago

I am closing this issue.

I concluded that the problem likely relates to TP-Link Tapo Matter devices.

**There was a solution that you may want to know about in case you get similar inquiries.**

A bit more detail ...

I have a number of TP-Link Tapo Matter devices (dimmers, switches, outdoor plugs). About 15 in total. These devices were constantly disappearing for iOS Home (even though they worked in the Tapo app), which indicated a problem with the Matter implementation. Looking at the CSA certification web site and the date of certification, it was clear that they must have been developed with a relatively early Matter SDK

I wrote to the TP-Link support group about the issue, explaining the problem and that there was a new Matter SDK release with many error fixes (1.2.0.1). They prepared a beta firmware with an updated SDK and provided that to me via a Beta release push to my devices.

Immediately after the beta update, my devices started working perfectly and many of the errors disappeared from the Matter Server log.

So, for TP-Link Tapo users, the solution is to wait for the beta update to be released to everyone. But not all errors are gone, so this may be a case where other vendors (Eve, Aqara) also need to do firmware updates with updated SDK code. In any case, everything is much more responsive now.

jvmahon commented 10 months ago

And thank you!