Matter: mDNS error when pairing immediately after unpair

[mlampacher]

I'm using

• the nRF52840 DK and the Matter light_bulb example, SDK v2.7.0.
• a raspberry pi with the nRF dongle as a thread border router
• the chip-tool running and compiled for macos (but with the repository version from the SDK)

When trying to pair directly after the device has been unpaired, meaning

• chip-tool pairing ble-thread <node-id> hex:<dataset active -x> 20202021 3840
• chip-tool pairing unpair <node-id>

then the pairing process takes significantly longer due to some reported mDNS error and a lookup for some address that doesn't seem to belong to my device (there are no other nodes on the fabric). The "offending" log in the chip-tool is the following (comparing compared to an OK pairing sequence):

[1731047068526] [4486:2075296] [DIS] Checking node lookup status after 202 ms
[1731047071245] [4486:2075296] [DIS] Mdns: OnResolve flags: 0, interface: 11, fullname: BC457DD5B6258255-0000000000000045._matter._tcp.local., hostname: 1E6BC32C13681711.local., port: 5540
[1731047071245] [4486:2075296] [DIS] Mdns : OnNewInterface hostname:1E6BC32C13681711.local. fullname:BC457DD5B6258255-0000000000000045._matter._tcp.local. interface: 11 port: 5540 TXT:"SII=2000,SAI=2000,SAT=4000"
[1731047073328] [4486:2075295] [DIS] Mdns: OnGetAddrInfo flags: 3, interface: 0, hostname: 0E38BB10063D903E.local.
[1731047073328] [4486:2075295] [DIS] OnGetAddrInfo (kDNSServiceErr_Timeout)
[1731047073328] [4486:2075295] [DIS] Mdns: OnGetAddrInfo flags: 2, interface: 0, hostname: 0E38BB10063D903E.local.
[1731047073328] [4486:2075295] [DIS] OnGetAddrInfo (kDNSServiceErr_Timeout)
[1731047073328] [4486:2075295] [DIS] Mdns: Resolve failure (kDNSServiceErr_BadState)
[1731047113327] [4486:2075296] [DIS] Checking node lookup status after 45002 ms
[1731047113327] [4486:2075296] [DIS] No longer need resolve for BC457DD5B6258255-0000000000000045
[1731047113327] [4486:2075296] [DIS] OperationalSessionSetup[1:0000000000000045]: operational discovery failed: src/lib/address_resolve/AddressResolve_DefaultImpl.cpp:119: CHIP Error 0x00000032: Timeout
[1731047113327] [4486:2075296] [DIS] Retrying operational DNS-SD discovery. Attempts remaining: 2
[1731047113327] [4486:2075296] [DIS] Resolving BC457DD5B6258255:0000000000000045 ...
[1731047113327] [4486:2075296] [DIS] Resolve type=_matter._tcp name=BC457DD5B6258255-0000000000000045 interface=0
[1731047113328] [4486:2075296] [CTL] Session establishment failed for <0000000000000045, 1>, error: src/lib/address_resolve/AddressResolve_DefaultImpl.cpp:119: CHIP Error 0x00000032: Timeout.  Next retry expected to get a response to Sigma1 or fail within 60 seconds
[1731047113328] [4486:2075296] [CTL] Arming failsafe (120 seconds)
[1731047113328] [4486:2075296] [DMG] ICR moving to [AddingComm]
[1731047113328] [4486:2075296] [DMG] ICR moving to [AddedComma]
[1731047113329] [4486:2075296] [EM] <<< [E:10437i S:63980 M:221767263] (S) Msg TX to 0:FFFFFFFB00000000 [0000] [BLE] --- Type 0001:08 (IM:InvokeCommandRequest)
[1731047113329] [4486:2075296] [DMG] ICR moving to [AwaitingRe]
[1731047113329] [4486:2075296] [DIS] Mdns: OnResolve flags: 0, interface: 11, fullname: BC457DD5B6258255-0000000000000045._matter._tcp.local., hostname: 1E6BC32C13681711.local., port: 5540
[1731047113329] [4486:2075296] [DIS] Mdns : OnNewInterface hostname:1E6BC32C13681711.local. fullname:BC457DD5B6258255-0000000000000045._matter._tcp.local. interface: 11 port: 5540 TXT:"SII=2000,SAI=2000,SAT=4000"
[1731047113331] [4486:2075296] [DIS] Mdns: OnGetAddrInfo flags: 1073741826, interface: 11, hostname: 1E6BC32C13681711.local.
[1731047113331] [4486:2075296] [DIS] Mdns: OnNewAddress interface: 11 ip:fd21:ad93:14a0:1:d117:fae1:8f33:f012
[1731047113331] [4486:2075296] [DIS] Mdns: Resolve success on interface 11
[1731047113331] [4486:2075296] [DIS] Node ID resolved for BC457DD5B6258255:0000000000000045
[1731047113331] [4486:2075296] [DIS] 	Hostname: 1E6BC32C13681711
[1731047113331] [4486:2075296] [DIS] 	IP Address #1: fd21:ad93:14a0:1:d117:fae1:8f33:f012
[1731047113331] [4486:2075296] [DIS] 	Port: 5540
[1731047113331] [4486:2075296] [DIS] 	Mrp Interval idle: 2000 ms
[1731047113332] [4486:2075296] [DIS] 	Mrp Interval active: 2000 ms
[1731047113332] [4486:2075296] [DIS] 	Mrp Active Threshold: 4000 ms
[1731047113332] [4486:2075296] [DIS] 	TCP Supported: 0
[1731047113332] [4486:2075296] [DIS] 	ICD: not present
[1731047113332] [4486:2075296] [DIS] Lookup clearing interface for non LL address
[1731047113332] [4486:2075296] [DIS] UDP:[fd21:ad93:14a0:1:d117:fae1:8f33:f012%en0]:5540: new best score: 3
[1731047113332] [4486:2075296] [DIS] Checking node lookup status after 5 ms
[1731047113332] [4486:2075296] [DIS] Keeping DNSSD lookup active
[1731047113503] [4486:2075295] [EM] >>> [E:10437i S:63980 M:22159] (S) Msg RX from 0:FFFFFFFB00000000 [0000] --- Type 0001:09 (IM:InvokeCommandResponse)
[1731047113503] [4486:2075295] [EM] Found matching exchange: 10437i, Delegate: 0x14b504258
[1731047113503] [4486:2075295] [DMG] ICR moving to [ResponseRe]
[1731047113503] [4486:2075295] [DMG] InvokeResponseMessage =
[1731047113503] [4486:2075295] [DMG] {
[1731047113503] [4486:2075295] [DMG] 	suppressResponse = false,
[1731047113503] [4486:2075295] [DMG] 	InvokeResponseIBs =
[1731047113503] [4486:2075295] [DMG] 	[
[1731047113503] [4486:2075295] [DMG] 		InvokeResponseIB =
[1731047113503] [4486:2075295] [DMG] 		{
[1731047113503] [4486:2075295] [DMG] 			CommandDataIB =
[1731047113503] [4486:2075295] [DMG] 			{
[1731047113503] [4486:2075295] [DMG] 				CommandPathIB =
[1731047113503] [4486:2075295] [DMG] 				{
[1731047113503] [4486:2075295] [DMG] 					EndpointId = 0x0,
[1731047113503] [4486:2075295] [DMG] 					ClusterId = 0x30,
[1731047113503] [4486:2075295] [DMG] 					CommandId = 0x1,
[1731047113503] [4486:2075295] [DMG] 				},
[1731047113503] [4486:2075295] [DMG]
[1731047113503] [4486:2075295] [DMG] 				CommandFields =
[1731047113503] [4486:2075295] [DMG] 				{
[1731047113504] [4486:2075295] [DMG] 					0x0 = 0 (unsigned),
[1731047113504] [4486:2075295] [DMG] 					0x1 = "" (0 chars),
[1731047113504] [4486:2075295] [DMG] 				},
[1731047113504] [4486:2075295] [DMG] 			},
[1731047113504] [4486:2075295] [DMG]
[1731047113504] [4486:2075295] [DMG] 		},
[1731047113504] [4486:2075295] [DMG]
[1731047113504] [4486:2075295] [DMG] 	],
[1731047113504] [4486:2075295] [DMG]
[1731047113504] [4486:2075295] [DMG] 	InteractionModelRevision = 11
[1731047113504] [4486:2075295] [DMG] },
[1731047113504] [4486:2075295] [DMG] Received Command Response Data, Endpoint=0 Cluster=0x0000_0030 Command=0x0000_0001
[1731047113504] [4486:2075295] [CTL] Status of extending fail-safe for CASE retry: 0

The important parts seem to be

• OnGetAddrInfo (kDNSServiceErr_Timeout)
• Mdns: Resolve failure (kDNSServiceErr_BadState)
• OperationalSessionSetup[1:0000000000000045]: operational discovery failed: src/lib/address_resolve/AddressResolve_DefaultImpl.cpp:119: CHIP Error 0x00000032: Timeout
• Session establishment failed for <0000000000000045, 1>, error: src/lib/address_resolve/AddressResolve_DefaultImpl.cpp:119: CHIP Error 0x00000032: Timeout.  Next retry expected to get a response to Sigma1 or fail within 60 seconds

I'm not an expert on how mDNS and the translation to DNS-SD works, so I'm really struggling to understand what goes wrong here. My best guess is that maybe a "goodbye" message went missing and therefore the mDNS cache at the border router keeps a now invalid entry. This would explain why the pairing works without problems if you wait for ~2 minutes after unpairing.

Even with the above error, the pairing itself is successful 90% of the time - it just takes significantly longer. Arbitrarily I observed that the sequence failed but (after a reboot of the nRF52840 DK) I could pair successfully.

Is there anything I'm missing? I only found the following tickets on the connectedhomeip project, but they didn't really seem to match my problem

• https://github.com/project-chip/connectedhomeip/issues/31582
• https://github.com/project-chip/connectedhomeip/issues/28568

I'm also attaching a screenshot where the left side is the log of an OK pairing sequence and the right side is a failed sequence.

[AHaug]

Hi,

Thank you for supplying all this information. I will look closer into this and discuss it with the developers early in the coming week and get back to you then with more follow ups.

Kind regards,
Andreas

[mlampacher]

Of course, thank you very much!

[AHaug]

Just a status update from me. Apologies for the long response time. I'm waiting for some input from the relevant teams. I've reached out to them again to get an ETA for a reply.

For now, what I understand is that you're onto the reason for why it is as you see, i.e there are some artifacts that needs to be removed before the re-pairing process does not use too much time. A disclaimer, I'm not 100% sure, so I'll update this reply when I hear back from the team.

Kind regards,
Andreas

[mlampacher]

Thanks for letting me know! I'm not in a rush but I'm always glad to be kept in the loop!

[AHaug]

Hi again,

There seems to be no other input than what I previously stated, i.e that there are some artifacts that needs to be removed from the network/fabric before the device can be re-paired in the events that it has been purposefully removed.

Let me know if you have any additional questions/follow ups to this topic and I'll look into it

Kind regards,
Andreas

[AHaug]

And Hi again,

I had another update with some more information. 

In general device should remove its SRP services on last fabric removal: https://github.com/nrfconnect/sdk-nrf/blob/c4d21873602f35d4ccddccf1fcc665b9263c060e/samples/matter/common/src/app/fabric_table_delegate.h#L58, which is also executed on factory reset ThreadStackMgr().ClearAllSrpHostAndServices(); and the Goodbye message to clear caches on the DNS clients should be sent by the OTBR .

One thought it that it might be an issue with the client side i.e Avahi cache for CHIP Tool using avahi - where cached records is used instead of performing full mDNS discovery. Could you verify if you're using Avahi or Bonjour? The latter seems to have issues with Goodbye messages: https://github.com/openthread/ot-br-posix/blob/17c2b1a1f4fe5ef410a53ff9676fa6a9ef1714be/src/mdns/mdns_mdnssd.cpp#L601-L606 

Kind regards,
Andreas 

 

[mlampacher]

Hi,

I'm running the `chip-tool` on macos so I'm pretty sure it's using Bonjour (e.g., I couldn't run the `chip-ota-provider-app` within Docker on macos host since I'd have to pass avahi into the container, which I didn't manage).

Yeah so it's not too far off, might simply be a client-side issue. I'm using `ClearAllSrpHostAndServices` in my fabric removal - and it's also part of the default fabric delegate used by the light bulb example. Since both applications fail I was quite confident I'm not doing anything wrong.

Maybe I'll try to run the `chip-tool` on the OTBR and see if it behaves differently, but currently I'm in the middle of testing so I'd like to keep the setup as it is for now.

Thank you very much for the feedback!

Cheers.M