Adding a thread device

Configuration Matter/Thread
21

I found various IP addresses for the Apple TV and pinged them all.

IPv4 192.168.50.40 ping successfully
IPv6 has 5 IP addresses according to Ubiquiti - the first pings successfully the other 4 time out.
Finally ping livingroom.local responds - reporting the IPv4 address.

22

Today I tried temporarily moving the HomeAssistant Yellow over to the main VLAN so that Apple TV and HA are on the same network.

The pairing process changed in that Apple Home reported the pairing

IMG_3970
IMG_39701125×923 101 KB

But on the HA side the results were not better, though the logs are slightly differerent:

Please, share the above information when looking for help
 or support in, e.g., GitHub, forums or the Discord chat.
-----------------------------------------------------------
s6-rc: info: service banner successfully started
s6-rc: info: service matter-server: starting
s6-rc: info: service matter-server successfully started
s6-rc: info: service legacy-services: starting
[08:34:26] INFO: Starting Matter Server...
s6-rc: info: service legacy-services successfully started
[08:34:28] INFO: Using 'end0' as primary network interface.
[08:34:28] INFO: Successfully send discovery information to Home Assistant.
2024-05-27 08:34:35.230 (MainThread) INFO [matter_server.server.stack] Initializing CHIP/Matter Logging...
2024-05-27 08:34:35.231 (MainThread) INFO [matter_server.server.stack] Initializing CHIP/Matter Controller Stack...
[1716795275.424814][126:126] CHIP:CTL: Setting attestation nonce to random value
[1716795275.430899][126:126] CHIP:CTL: Setting CSR nonce to random value
[1716795275.449510][126:126] CHIP:DL: ChipLinuxStorage::Init: Using KVS config file: /tmp/chip_kvs
[1716795275.450137][126:126] CHIP:DL: writing settings to file (/tmp/chip_kvs-5xxFXH)
[1716795275.450674][126:126] CHIP:DL: renamed tmp file to file (/tmp/chip_kvs)
[1716795275.451837][126:126] CHIP:DL: ChipLinuxStorage::Init: Using KVS config file: /data/chip_factory.ini
[1716795275.456256][126:126] CHIP:DL: ChipLinuxStorage::Init: Using KVS config file: /data/chip_config.ini
[1716795275.456925][126:126] CHIP:DL: ChipLinuxStorage::Init: Using KVS config file: /data/chip_counters.ini
[1716795275.459012][126:126] CHIP:DL: writing settings to file (/data/chip_counters.ini-46tAWG)
[1716795275.459963][126:126] CHIP:DL: renamed tmp file to file (/data/chip_counters.ini)
[1716795275.460031][126:126] CHIP:DL: NVS set: chip-counters/reboot-count = 50 (0x32)
[1716795275.461209][126:126] CHIP:DL: Got Ethernet interface: end0
[1716795275.462013][126:126] CHIP:DL: Found the primary Ethernet interface:end0
[1716795275.462581][126:126] CHIP:DL: Got WiFi interface: wlan0
[1716795275.462651][126:126] CHIP:DL: Failed to reset WiFi statistic counts
2024-05-27 08:34:35.464 (MainThread) WARNING [PersistentStorage] Initializing persistent storage from file: /data/chip.json
2024-05-27 08:34:35.465 (MainThread) WARNING [PersistentStorage] Loading configuration from /data/chip.json...
2024-05-27 08:34:35.749 (MainThread) WARNING [CertificateAuthorityManager] Loading certificate authorities from storage...
2024-05-27 08:34:35.750 (MainThread) WARNING [CertificateAuthority] New CertificateAuthority at index 1
2024-05-27 08:34:35.753 (MainThread) WARNING [CertificateAuthority] Loading fabric admins from storage...
2024-05-27 08:34:35.754 (MainThread) WARNING [FabricAdmin] New FabricAdmin: FabricId: 0x0000000000000002, VendorId = 0x134B
2024-05-27 08:34:35.755 (MainThread) INFO [matter_server.server.stack] CHIP Controller Stack initialized.
2024-05-27 08:34:35.766 (MainThread) INFO [matter_server.server.server] Starting the Matter Server...
2024-05-27 08:34:35.778 (MainThread) INFO [matter_server.server.helpers.paa_certificates] Skip fetching certificates (already fetched within the last 24h).
2024-05-27 08:34:35.778 (MainThread) WARNING [FabricAdmin] Allocating new controller with CaIndex: 1, FabricId: 0x0000000000000002, NodeId: 0x000000000001B669, CatTags: []
2024-05-27 08:34:36.246 (Dummy-2) CHIP_ERROR [chip.native.DL] Long dispatch time: 464 ms, for event type 2
2024-05-27 08:34:36.260 (MainThread) INFO [matter_server.server.device_controller] Loaded 1 nodes from stored configuration
2024-05-27 08:34:36.277 (MainThread) INFO [matter_server.server.vendor_info] Loading vendor info from storage.
2024-05-27 08:34:36.290 (MainThread) INFO [matter_server.server.vendor_info] Loaded 196 vendors from storage.
2024-05-27 08:34:36.290 (MainThread) INFO [matter_server.server.vendor_info] Fetching the latest vendor info from DCL.
2024-05-27 08:34:36.734 (MainThread) INFO [matter_server.server.vendor_info] Fetched 194 vendors from DCL.
2024-05-27 08:34:36.734 (MainThread) INFO [matter_server.server.vendor_info] Saving vendor info to storage.
2024-05-27 08:34:36.931 (MainThread) INFO [matter_server.server.device_controller.mdns] Node 4 discovered on MDNS
2024-05-27 08:34:36.932 (MainThread) INFO [matter_server.server.device_controller.node_4] Setting-up node...
2024-05-27 08:34:43.296 (Dummy-2) CHIP_ERROR [chip.native.EM] Failed to Send CHIP MessageCounter:88635637 on exchange 60652i with Node: <0000000000000000, 0> sendCount: 4 max retries: 4
2024-05-27 08:34:46.182 (Dummy-2) CHIP_ERROR [chip.native.SC] CASESession timed out while waiting for a response from the peer. Current state was 1
2024-05-27 08:34:52.718 (Dummy-2) CHIP_ERROR [chip.native.EM] Failed to Send CHIP MessageCounter:88635638 on exchange 60653i with Node: <0000000000000000, 0> sendCount: 4 max retries: 4
2024-05-27 08:34:55.231 (Dummy-2) CHIP_ERROR [chip.native.SC] CASESession timed out while waiting for a response from the peer. Current state was 1
2024-05-27 08:34:58.692 (MainThread) INFO [matter_server.server.device_controller.node_4] Setting up attributes and events subscription.
2024-05-27 08:35:01.257 (MainThread) INFO [matter_server.server.device_controller.node_4] Subscription succeeded with report interval [0, 60]
2024-05-27 08:35:38.482 (MainThread) INFO [matter_server.server.device_controller] Starting Matter commissioning with code using Node ID 40 (attempt 1/3).
2024-05-27 08:35:40.960 (Dummy-2) INFO [root] Established secure session with Device
2024-05-27 08:35:50.269 (Dummy-2) CHIP_ERROR [chip.native.SC] Received error (protocol code 2) during pairing process: src/protocols/secure_channel/CASESession.cpp:1980: CHIP Error 0x00000054: Invalid CASE parameter
2024-05-27 08:35:50.270 (Dummy-2) CHIP_ERROR [chip.native.CTL] Error on commissioning step 'kFindOperationalForStayActive': 'src/protocols/secure_channel/CASESession.cpp:1980: CHIP Error 0x00000054: Invalid CASE parameter'
2024-05-27 08:35:50.271 (Dummy-2) WARNING [root] Failed to commission: src/protocols/secure_channel/CASESession.cpp:1980: CHIP Error 0x00000054: Invalid CASE parameter
2024-05-27 08:35:55.275 (MainThread) INFO [matter_server.server.device_controller] Starting Matter commissioning with code using Node ID 40 (attempt 2/3).
2024-05-27 08:36:25.279 (Dummy-2) CHIP_ERROR [chip.native.CTL] Discovery timed out
2024-05-27 08:36:25.280 (Dummy-2) CHIP_ERROR [chip.native.ZCL] Secure Pairing Failed
2024-05-27 08:36:25.280 (Dummy-2) WARNING [root] Failed to establish secure session to device: src/controller/python/ChipDeviceController-ScriptDevicePairingDelegate.cpp:89: CHIP Error 0x00000003: Incorrect state
2024-05-27 08:36:25.281 (Dummy-2) WARNING [root] Failed to commission: src/controller/python/ChipDeviceController-ScriptDevicePairingDelegate.cpp:89: CHIP Error 0x00000003: Incorrect state
2024-05-27 08:36:30.287 (MainThread) INFO [matter_server.server.device_controller] Starting Matter commissioning with code using Node ID 40 (attempt 3/3).
2024-05-27 08:36:43.837 (Dummy-2) INFO [root] Established secure session with Device
2024-05-27 08:37:26.033 (Dummy-2) CHIP_ERROR [chip.native.EM] Failed to Send CHIP MessageCounter:165370396 on exchange 60668i with Node: <FFFFFFFB00000000, 0> sendCount: 4 max retries: 4
2024-05-27 08:37:32.348 (Dummy-2) CHIP_ERROR [chip.native.DMG] Time out! failed to receive report data from Exchange: 60668i with Node: <FFFFFFFB00000000, 0>
2024-05-27 08:38:13.292 (Dummy-2) CHIP_ERROR [chip.native.EM] Failed to Send CHIP MessageCounter:165370397 on exchange 60669i with Node: <FFFFFFFB00000000, 0> sendCount: 4 max retries: 4
2024-05-27 08:38:20.861 (Dummy-2) CHIP_ERROR [chip.native.DMG] Time out! failed to receive report data from Exchange: 60669i with Node: <FFFFFFFB00000000, 0>
2024-05-27 08:38:20.861 (Dummy-2) CHIP_ERROR [chip.native.CTL] Failed to read BasicCommissioningInfo: src/app/ClusterStateCache.cpp:303: CHIP Error 0x00000010: Key not found
2024-05-27 08:38:20.862 (Dummy-2) CHIP_ERROR [chip.native.CTL] Failed to read RegulatoryConfig: src/app/ClusterStateCache.cpp:303: CHIP Error 0x00000010: Key not found
2024-05-27 08:38:20.863 (Dummy-2) CHIP_ERROR [chip.native.CTL] Failed to read LocationCapability: src/app/ClusterStateCache.cpp:303: CHIP Error 0x00000010: Key not found
2024-05-27 08:38:20.863 (Dummy-2) CHIP_ERROR [chip.native.CTL] Failed to read Breadcrumb: src/app/ClusterStateCache.cpp:303: CHIP Error 0x00000010: Key not found
2024-05-27 08:38:20.864 (Dummy-2) CHIP_ERROR [chip.native.CTL] Error parsing commissioning information
2024-05-27 08:38:20.865 (Dummy-2) CHIP_ERROR [chip.native.CTL] Error on commissioning step 'ReadCommissioningInfo2': 'src/app/ClusterStateCache.cpp:303: CHIP Error 0x00000010: Key not found'
2024-05-27 08:39:04.155 (Dummy-2) CHIP_ERROR [chip.native.EM] Failed to Send CHIP MessageCounter:165370398 on exchange 60670i with Node: <FFFFFFFB00000000, 0> sendCount: 4 max retries: 4
2024-05-27 08:39:09.376 (Dummy-2) WARNING [root] Failed to commission: src/app/ClusterStateCache.cpp:303: CHIP Error 0x00000010: Key not found
2024-05-27 08:39:09.377 (MainThread) ERROR [matter_server.server.client_handler] [548104738320] Error while handling: commission_with_code: Commission with code failed for node 40.
23

At least some progress… HA Matter Server is now talking to the device and has accepted the passcode; That is what “Established a secure session” means. The last part of commissioning is setting up a CASE session with the device which means you got this far, but I really have no idea at this point what the “Invalid CASE parameter” means. Are you using the iOS HA Companion App when adding the device to HA?

24

Yes, used all the permutations available to me - ios Home to ios HomeAssistant app, iPad OS versions, and Macos too, but with the same results.

I have two matter / thread devices on the Apple Home - a smart plug and the blinds. The blinds are quite distant from the Apple TV but they are working well enough in the Home app.

Is there any way in the Apple Home ecosystem to tell if a Matter device has a good signal or is using another device as a repeater?

Steve.

25

Since HA and Apple are on the same VLAN, and what Matter calls the “Device Discovery” phase works (which means the communication with the device is working), I really don’t know why the “Operational Discovery” (CASE) phase is failing. I would recommend writing up an issue here and provide the logs above and see what they say.

26

In general, Thread and Matter are quite orthogonal technologies. If a device is on a Thread network the Matter can control, pretty much all things Thread are not relevant anymore: As long as the device is on the Thread network and HA gets routes to that Thread network (via a existing Thread BR), you’re good. The fact that you see the Apple BR in the Thread panel tells you that the BR and HA is in the same network indeed :+1:

This is because the Matter Server is stateful: It stores all the devices it is connected to. If you want to really start clean slate all things Matter, you have to remove the Matter Server add-on as well.

Hm, sounds the Matter Server is able to find the device, but the device doesn’t like to setup a password authenticated session (PASE) with the Matter server. From what I understand, this is typically for two reasons: The IP address which got resolved is not reachable/stale (restarting HAOS/Thread border router and wait for a bit might help to get a clean slate). The setup code is wrong (the fact that we see this quite often I wonder sometimes if some of the devices are buggy and report a setup code but have a commissioning phase open with an older code maybe? :thinking: ).

Uh that is weird. Can you try to remove the existing fabric entry on the device? E.g. from Apple Home in the device settings under “Connected Services”. Remove any entry with number 4939 (the vendor ID of Nabu Casa, used by the Python Matter Server).

27

Ah - missed that - I removed the integrations, and forgot there was an add on.

Could not find that path - found the following
Apple Home > … > Home Settings > Connected Services (1) > Manage in IOS settings > I can see the Blind and MSS315 > Connected services 4939

I’m going to be busy for the next week, so will have to pick this up later.

Thanks to all for your expert assistance.

1 Like
28

Some progress.

  • Removed the blinds and the Wemo smart plug from Apple Home
  • Then uninstalled Matter server and the two integrations from HA.
  • Reset the Wemo plug and tried to add it to Apple Home - it said device already exists, but I could not find it ( I wonder if I originally installed this on HA with multi-protocol).
  • However the Wemo plug showed up in HA as a new device. I simply clicked on matter config and then added the web plug.
  • Checking the HA thread integration, I can see Apple Home is added back in automatically
    image
    image1238×1374 54.3 KB

No idea what MyHome92391987 is and if it can be deleted.

  • Reset the blind and put it in pairing mode. Opened Apple Home and add device. Device is discovered (nothing new with this).
  • Go to the device in Apple Home, turn on pairing mode, go to HA, and add device > matter > existing HomeKit device and enter the pairing code. This fails as before.
  • Shut down HA, change the vlan, cycle PoE power and HA starts up on the default vlan. i.e. the same subnet as two Apple TVs.
  • Turn off the HomeKit Apple TV as it was the older one without Thread.
  • Go to the blinds in Apple Home and turn on pairing mode again.
  • Go to HA devices > add > matter > existing HomeKit device and SUCCESS!

This was probably due to resetting HA Matter server and starting over.

Blinds added to dashboard and being controlled correctly.

HOWEVER - HA is not on the IOT VLAN.

The Matter log has various messages:

2024-06-08 11:20:38.482 (Dummy-2) CHIP_ERROR [chip.native.SC] CASESession timed out while waiting for a response from the peer. Current state was 1
2024-06-08 11:20:38.484 (MainThread) WARNING [matter_server.server.device_controller.node_3] Setup for node failed: Unable to establish CASE session with Node 3
2024-06-08 11:58:23.314 (MainThread) INFO [matter_server.server.device_controller.mdns] Node 3 discovered on MDNS
2024-06-08 11:58:23.315 (MainThread) INFO [matter_server.server.device_controller.node_3] Setting-up node...
2024-06-08 11:58:23.528 (Dummy-2) CHIP_ERROR [chip.native.-] src/inet/UDPEndPointImplSockets.cpp:416: OS Error 0x02000065: Network is unreachable at src/app/OperationalSessionSetup.cpp:246
  • At some point the wemo plug turned up in Apple Home in the default room that Homeassistant uses.

In summary.
A clean install of Matter server really helped, but I suspect that Apple Home still has some old configuration that comes back (causing the Wemo plug issues). The successful connection of the HomeKit blinds to HomeAssistant on the same vlan but not on separate vlans shows that the current problem is with the inter vlan routing of the Ubiquiti router.