Unable to connect Matter Light Switch to Home Assistant

[Vincent124]

Hello,

I'm trying to set up a Home Assistant with different Matter devices. For this I am using the nRF Connect Matter Samples "light_switch" and "light_bulb". 

For commissioning I'm using the Home Assistant Mobile App while following this Documentation: https://developer.nordicsemi.com/nRF_Connect_SDK/doc/2.5.0/nrf/samples/matter/light_switch/README.html#matter-light-switch-sample-remote-control-commissioning. 

Sadly I am unable to connect my light switch. With the bulb I didn't have any problems. I just scanned the Code via the App and got it to connect. But when I do the same with the light switch then after trying to connect the device with the Home Assistant for a while, the App says "An Error has occured".

I did enable the advertising mode manually as it is said in the documentation. My Border Router also works fine. After scanning the Code and starting the commissioning, the Matter device is trying to connect but after working a while the Error occurs. 

For some reason after this, the device is somehow connected to the Border Router. I can see that in the Web-GUI. But in my Home Assistant device/entity list there is no Matter light switch.

The Home Assistant Matter Server Log prints this:

2024-01-04 08:54:52 core-matter-server chip.DIS[65] ERROR Timeout waiting for mDNS resolution.
2024-01-04 08:55:06 core-matter-server chip.DIS[65] ERROR OperationalSessionSetup[1:000000000000000A]: operational discovery failed: src/lib/address_resolve/AddressResolve_DefaultImpl.cpp:119: CHIP Error 0x00000032: Timeout
2024-01-04 08:55:37 core-matter-server chip.DIS[65] ERROR Timeout waiting for mDNS resolution.
2024-01-04 08:55:51 core-matter-server chip.DIS[65] ERROR OperationalSessionSetup[1:0000000000000009]: operational discovery failed: src/lib/address_resolve/AddressResolve_DefaultImpl.cpp:119: CHIP Error 0x00000032: Timeout
2024-01-04 08:55:51 core-matter-server matter_server.server.device_controller[65] WARNING Unable to subscribe to Node 9 as it is unavailable, will retry later in the background.
2024-01-04 08:56:22 core-matter-server chip.DIS[65] ERROR Timeout waiting for mDNS resolution.
2024-01-04 08:56:36 core-matter-server chip.DIS[65] ERROR OperationalSessionSetup[1:000000000000000A]: operational discovery failed: src/lib/address_resolve/AddressResolve_DefaultImpl.cpp:119: CHIP Error 0x00000032: Timeout
2024-01-04 08:57:07 core-matter-server chip.DIS[65] ERROR Timeout waiting for mDNS resolution.
2024-01-04 08:57:21 core-matter-server chip.DIS[65] ERROR OperationalSessionSetup[1:000000000000000A]: operational discovery failed: src/lib/address_resolve/AddressResolve_DefaultImpl.cpp:119: CHIP Error 0x00000032: Timeout
2024-01-04 08:57:21 core-matter-server matter_server.server.device_controller[65] WARNING Unable to subscribe to Node 10 as it is unavailable, will retry later in the background.
2024-01-04 08:57:39 core-matter-server matter_server.server.helpers.paa_certificates[65] INFO Fetching the latest PAA root certificates from DCL.
2024-01-04 08:57:40 core-matter-server matter_server.server.helpers.paa_certificates[65] INFO Fetched 0 PAA root certificates from DCL.
2024-01-04 08:57:40 core-matter-server matter_server.server.helpers.paa_certificates[65] INFO Fetching the latest PAA root certificates from Git.
2024-01-04 08:57:40 core-matter-server matter_server.server.helpers.paa_certificates[65] INFO Fetched 0 PAA root certificates from Git.
2024-01-04 08:57:52 core-matter-server chip.DIS[65] ERROR Timeout waiting for mDNS resolution.
2024-01-04 08:58:06 core-matter-server chip.DIS[65] ERROR OperationalSessionSetup[1:0000000000000009]: operational discovery failed: src/lib/address_resolve/AddressResolve_DefaultImpl.cpp:119: CHIP Error 0x00000032: Timeout
2024-01-04 08:58:06 core-matter-server matter_server.server.client_handler[65] ERROR [547813051728] Error handling message: CommandMessage(message_id='7ba6d27ef0f54654ade14e1bbc6d1278', command='commission_on_network', args={'setup_pin_code': 61719140, 'ip_addr': None})
Traceback (most recent call last):
  File "/usr/local/lib/python3.11/site-packages/matter_server/server/client_handler.py", line 188, in _run_handler
    result = await result
             ^^^^^^^^^^^^
  File "/usr/local/lib/python3.11/site-packages/matter_server/server/device_controller.py", line 230, in commission_on_network
    raise NodeCommissionFailed(
matter_server.common.errors.NodeCommissionFailed: Commission on network failed for node 23

In the log of my Matter device I can't find any Errors.

Is this a problem with the light switch or the Home Assistant? 

[Charlie]

Hi Vincent,

I doubt it is related to the sample itself since we normally test the samples on Apple and Google smart home ecosystems.

 (+) Matter: Testing the nRF Connect platform with Apple, Google and Samsung ecosystems - Blogs - Nordic Blog - Nordic DevZone (nordicsemi.com)

The Home Assistant log shows some errors are related to mDNS resolution timeout. Do you test in an office network environment? you need to pay attention to the router's mDNS setting.

Can you share the nRF Connect SDK version you are testing? Maybe you can enable more log information from the device and share it here. It would be helpful to understand the device's behaviour even if an error does not happen.

Best regards,

Charlie

[Vincent124]

Hi Charlie,

The mDNS Error was also there for the time the commissioning worked. I wasn't able to resolve this yet but it also wasn't a problem till now. I'll look into this too.

I'm using SDK verion 2.4.2.

For some reason I'm now getting the same Error for the light bulb too even though it worked just fine before. Here are some of the last few lines of the light bulb device log before the error occurs:

I: 90714 [ZCL]Commissioning window is now open
I: 90719 [EM]<<< [E:10474r S:23150 M:251748559 (Ack:124261149)] (S) Msg TX to 1:D07881E73455012C [23E9] --- Type 0001:09 (IM:InvokeCommandResponse)
I: 90732 [IN](S) Sending msg 251748559 on secure session with LSID: 23150
I: 90765 [EM]>>> [E:10474r S:23150 M:124261150 (Ack:251748559)] (S) Msg RX from 1:D07881E73455012C [23E9] --- Type 0000:10 (SecureChannel:StandaloneAck)
I: 90832 [EM]>>> [E:10475r S:23150 M:124261151] (S) Msg RX from 1:D07881E73455012C [23E9] --- Type 0001:02 (IM:ReadRequest)
D: 90843 [IM]Received Read request
I: 90848 [EM]<<< [E:10475r S:23150 M:251748560 (Ack:124261151)] (S) Msg TX to 1:D07881E73455012C [23E9] --- Type 0001:05 (IM:ReportData)
I: 90860 [IN](S) Sending msg 251748560 on secure session with LSID: 23150
I: 90897 [EM]>>> [E:10475r S:23150 M:124261152 (Ack:251748560)] (S) Msg RX from 1:D07881E73455012C [23E9] --- Type 0000:10 (SecureChannel:StandaloneAck)
I: 90914 [EM]>>> [E:10476r S:23150 M:124261153] (S) Msg RX from 1:D07881E73455012C [23E9] --- Type 0001:0a (IM:TimedRequest)
I: 90926 [EM]<<< [E:10476r S:23150 M:251748561 (Ack:124261153)] (S) Msg TX to 1:D07881E73455012C [23E9] --- Type 0001:01 (IM:StatusResponse)
I: 90938 [IN](S) Sending msg 251748561 on secure session with LSID: 23150
I: 90968 [EM]>>> [E:10476r S:23150 M:124261154 (Ack:251748561)] (S) Msg RX from 1:D07881E73455012C [23E9] --- Type 0001:08 (IM:InvokeCommandRequest)
I: 90981 [ZCL]Received command to close commissioning window
I: 90987 [SVR]Closing pairing window
D: 90990 [IN]SecureSession[0x20003320]: Released - Type:1 LSID:23152
I: 90996 [DIS]Updating services using commissioning mode 0
D: 91001 [DL]Using Thread extended MAC for hostname.
I: 91006 [DIS]Advertise operational node 310A9064FE4923E9-FCAA50B3BD23B59E
D: 91013 [DL]Using Thread extended MAC for hostname.
I: 91019 [DIS]Advertise commission parameter vendorID=65521 productID=32773 discriminator=3840/15 cm=0
I: 91029 [DL]advertising srp service: 592473A0AEB11410._matterc._udp
D: 91035 [DIS]Scheduling extended discovery timeout in 900s
I: 91040 [DL]removing srp service: FC0492C5D7C89E9C._matterc._udp
I: 91046 [ZCL]Commissioning window is now closed
I: 91051 [EM]<<< [E:10476r S:23150 M:251748562 (Ack:124261154)] (S) Msg TX to 1:D07881E73455012C [23E9] --- Type 0001:09 (IM:InvokeCommandResponse)
I: 91064 [IN](S) Sending msg 251748562 on secure session with LSID: 23150
I: 91412 [EM]>>> [E:10476r S:23150 M:124261155 (Ack:251748562)] (S) Msg RX from 1:D07881E73455012C [23E9] --- Type 0000:10 (SecureChannel:StandaloneAck)
I: 91429 [EM]>>> [E:10477r S:23150 M:124261156] (S) Msg RX from 1:D07881E73455012C [23E9] --- Type 0001:02 (IM:ReadRequest)
D: 91440 [IM]Received Read request
I: 91445 [EM]<<< [E:10477r S:23150 M:251748563 (Ack:124261156)] (S) Msg TX to 1:D07881E73455012C [23E9] --- Type 0001:05 (IM:ReportData)
I: 91457 [IN](S) Sending msg 251748563 on secure session with LSID: 23150
I: 91497 [EM]>>> [E:10477r S:23150 M:124261157 (Ack:251748563)] (S) Msg RX from 1:D07881E73455012C [23E9] --- Type 0000:10 (SecureChannel:StandaloneAck)
I: 91513 [EM]>>> [E:10478r S:23150 M:124261158] (S) Msg RX from 1:D07881E73455012C [23E9] --- Type 0001:02 (IM:ReadRequest)
D: 91524 [IM]Received Read request
I: 91529 [EM]<<< [E:10478r S:23150 M:251748564 (Ack:124261158)] (S) Msg TX to 1:D07881E73455012C [23E9] --- Type 0001:05 (IM:ReportData)
I: 91541 [IN](S) Sending msg 251748564 on secure session with LSID: 23150
I: 91582 [EM]>>> [E:10478r S:23150 M:124261159 (Ack:251748564)] (S) Msg RX from 1:D07881E73455012C [23E9] --- Type 0000:10 (SecureChannel:StandaloneAck)
I: 91598 [EM]>>> [E:10479r S:23150 M:124261160] (S) Msg RX from 1:D07881E73455012C [23E9] --- Type 0001:0a (IM:TimedRequest)
I: 91610 [EM]<<< [E:10479r S:23150 M:251748565 (Ack:124261160)] (S) Msg TX to 1:D07881E73455012C [23E9] --- Type 0001:01 (IM:StatusResponse)
I: 91622 [IN](S) Sending msg 251748565 on secure session with LSID: 23150
I: 91680 [EM]>>> [E:10479r S:23150 M:124261161 (Ack:251748565)] (S) Msg RX from 1:D07881E73455012C [23E9] --- Type 0001:08 (IM:InvokeCommandRequest)
I: 91694 [ZCL]Received command to open commissioning window
D: 91700 [IN]SecureSession[0x20003320]: Allocated Type:1 LSID:23153
I: 91706 [DIS]Updating services using commissioning mode 2
D: 91711 [DL]Using Thread extended MAC for hostname.
I: 91716 [DIS]Advertise operational node 310A9064FE4923E9-FCAA50B3BD23B59E
D: 91723 [DL]Using Thread extended MAC for hostname.
I: 91728 [DIS]Advertise commission parameter vendorID=65521 productID=32773 discriminator=3106/12 cm=2
I: 91738 [DL]advertising srp service: 77AD62A682F4EF64._matterc._udp
I: 91744 [DL]removing srp service: FC0492C5D7C89E9C._matterc._udp
I: 91750 [DL]removing srp service: 592473A0AEB11410._matterc._udp
I: 91756 [ZCL]Commissioning window is now open
I: 91761 [EM]<<< [E:10479r S:23150 M:251748566 (Ack:124261161)] (S) Msg TX to 1:D07881E73455012C [23E9] --- Type 0001:09 (IM:InvokeCommandResponse)
I: 91774 [IN](S) Sending msg 251748566 on secure session with LSID: 23150
I: 91849 [EM]>>> [E:10479r S:23150 M:124261162 (Ack:251748566)] (S) Msg RX from 1:D07881E73455012C [23E9] --- Type 0000:10 (SecureChannel:StandaloneAck)
D: 92618 [DL]SRP update succeeded
E: 120209 [SWU]No suitable OTA Provider candidate found
I: 120214 [SWU]No provider available

I hope this is enough of the log, I'm not sure how much of it is important sorry!

Thanks in advance!

[Charlie]

Hi Vincent,

mDNS is used for bidirectional service discovery. Matter device commission would not work if the mDNS feature is disabled by your network.

I used to test in the office environment which blocks mDNS discovery, and the commission did not work. Switching to a home network or mobile phone WiFi host will solve the issue. Could you have a try?

Best regards,

Charlie

[Vincent124]

Hi Charlie,

I'm not working in a office environment and as I understand it, mDNS should be enabled in my network configuration, since I don't receive these many "ERROR Timeout waiting for mDNS resolution." Errors anymore. 

So the important logs form Matter Server Log state this:

2024-01-08 08:34:09 core-matter-server matter_server.server.device_controller[126] INFO Starting Matter commissioning on network using Node ID 5.
2024-01-08 08:34:39 core-matter-server chip.CTL[126] ERROR Mdns discovery timed out
2024-01-08 08:34:39 core-matter-server matter_server.server.client_handler[126] ERROR [548351953232] Error handling message: CommandMessage(message_id='afe520bcea0e4fdc8fcc09c8a1dd984d', command='commission_on_network', args={'setup_pin_code': 6859429, 'ip_addr': None})
Traceback (most recent call last):
  File "/usr/local/lib/python3.11/site-packages/matter_server/server/client_handler.py", line 188, in _run_handler
    result = await result
             ^^^^^^^^^^^^
  File "/usr/local/lib/python3.11/site-packages/matter_server/server/device_controller.py", line 261, in commission_on_network
    raise NodeCommissionFailed(
matter_server.common.errors.NodeCommissionFailed: Commission on network failed for node 5

What I don't understand is why this only occurs when I use the light_switch. Adding another light_bulb is no problem

[Charlie]

so the current state is light_bulb is ok but light_swith has commissioning issue?

If yes, could you also share the log from the light_switch device?