Cannot add a device to Matter Python (Docker Container) Failed interview

Tomatenplukker · August 7, 2024, 6:58pm

I have a Meros Smart plug and 2 Nous GU10 LED spots.
When trying to add them to Home Assistant it seems like they are added (both on the app as well as in the logs) but at the last moment when connecting to Home Assistant Netork, it fails.

In the logs it seems like the interview with the device never works after adding.

2024-08-07 18:42:41.281 (MainThread) INFO [chip.storage] Initializing persistent storage from file: /data/chip.json
2024-08-07 18:42:41.281 (MainThread) INFO [chip.storage] Loading configuration from /data/chip.json...
2024-08-07 18:42:41.349 (MainThread) INFO [chip.CertificateAuthority] Loading certificate authorities from storage...
2024-08-07 18:42:41.349 (MainThread) INFO [chip.CertificateAuthority] New CertificateAuthority at index 1
2024-08-07 18:42:41.349 (MainThread) INFO [chip.CertificateAuthority] Loading fabric admins from storage...
2024-08-07 18:42:41.350 (MainThread) INFO [chip.FabricAdmin] New FabricAdmin: FabricId: 0x0000000000000001, VendorId = 0xFFF1
2024-08-07 18:42:41.350 (MainThread) INFO [matter_server.server.stack] CHIP Controller Stack initialized.
2024-08-07 18:42:41.350 (MainThread) INFO [matter_server.server.server] Starting the Matter Server...
2024-08-07 18:42:41.352 (MainThread) INFO [matter_server.server.helpers.paa_certificates] Skip fetching certificates (already fetched within the last 24h).
2024-08-07 18:42:41.352 (MainThread) INFO [chip.FabricAdmin] Allocating new controller with CaIndex: 1, FabricId: 0x0000000000000001, NodeId: 0x000000000001B669, CatTags: []
2024-08-07 18:42:41.474 (Dummy-2) CHIP_ERROR [chip.native.DIS] Failed to advertise records: src/inet/UDPEndPointImplSockets.cpp:416: OS Error 0x02000065: Network is unreachable
2024-08-07 18:42:41.477 (Dummy-2) CHIP_ERROR [chip.native.DL] Long dispatch time: 124 ms, for event type 2
2024-08-07 18:42:41.481 (MainThread) INFO [matter_server.server.vendor_info] Loading vendor info from storage.
2024-08-07 18:42:41.485 (MainThread) INFO [matter_server.server.vendor_info] Loaded 231 vendors from storage.
2024-08-07 18:42:41.486 (MainThread) INFO [matter_server.server.vendor_info] Fetching the latest vendor info from DCL.
2024-08-07 18:42:41.739 (MainThread) INFO [matter_server.server.vendor_info] Fetched 229 vendors from DCL.
2024-08-07 18:42:41.740 (MainThread) INFO [matter_server.server.vendor_info] Saving vendor info to storage.
2024-08-07 18:42:41.757 (MainThread) INFO [matter_server.server.device_controller] Loaded 0 nodes from stored configuration
2024-08-07 18:42:41.790 (MainThread) INFO [matter_server.server.server] Matter Server successfully initialized.
2024-08-07 18:50:17.386 (MainThread) INFO [matter_server.server.device_controller] Starting Matter commissioning using Node ID 18 and IP fe80::dad6:68ff:fe4e:a463.
2024-08-07 18:50:19.109 (Dummy-2) INFO [chip.ChipDeviceCtrl] Established secure session with Device
2024-08-07 18:50:30.439 (Dummy-2) INFO [chip.ChipDeviceCtrl] Commissioning complete
2024-08-07 18:50:30.440 (MainThread) INFO [matter_server.server.device_controller] Matter commissioning of Node ID 18 successful.
2024-08-07 18:50:30.440 (MainThread) INFO [matter_server.server.device_controller] Interviewing node: 18
2024-08-07 18:51:04.275 (Dummy-2) CHIP_ERROR [chip.native.DMG] Time out! failed to receive report data from Exchange: 7045i with Node: <0000000000000012, 1>
2024-08-07 18:51:04.276 (MainThread) WARNING [matter_server.server.device_controller] Unable to interview Node 18: Failed to interview node 18
2024-08-07 18:51:09.281 (MainThread) INFO [matter_server.server.device_controller] Interviewing node: 18
2024-08-07 18:51:19.570 (Dummy-2) CHIP_ERROR [chip.native.DMG] Time out! failed to receive report data from Exchange: 7046i with Node: <0000000000000012, 1>
2024-08-07 18:51:19.571 (MainThread) WARNING [matter_server.server.device_controller] Unable to interview Node 18: Failed to interview node 18
2024-08-07 18:51:24.573 (MainThread) INFO [matter_server.server.device_controller] Interviewing node: 18
2024-08-07 18:51:27.106 (Dummy-2) CHIP_ERROR [chip.native.EM] Failed to Send CHIP MessageCounter:90830142 on exchange 7047i with Node: <0000000000000012, 1> sendCount: 4 max retries: 4
2024-08-07 18:51:29.393 (Dummy-2) CHIP_ERROR [chip.native.DMG] Time out! failed to receive report data from Exchange: 7047i with Node: <0000000000000012, 1>
2024-08-07 18:51:29.394 (MainThread) WARNING [matter_server.server.device_controller] Unable to interview Node 18: Failed to interview node 18
2024-08-07 18:51:34.397 (MainThread) ERROR [matter_server.server.client_handler] [139962082215760] Error while handling: commission_on_network: Node 18 does not exist.

Docker Compose file:

  matter-server:
    image: ghcr.io/home-assistant-libs/python-matter-server:stable
    container_name: matter-server
    # Required for mDNS to work correctly
    # network_mode: host
    security_opt:
      # needed for bluetooth via dbus
      - apparmor=unconfined
    command: "--log-level debug"
    ports:
      - "5580:5580"
    volumes:
      - /opt/matter/data:/data/
      - /opt/matter/run/dbus:/run/dbus:ro
      # If you adjust command line, make sure to pass the default CMD arguments too:
      #command: --storage-path /data --paa-root-cert-dir /data/credentials --bluetooth-adapter 0
      - /etc/timezone:/etc/timezone:ro

    restart: unless-stopped

peterxian · August 8, 2024, 7:27pm

The instructions on the python-matter-server GitHub suggest the container should be run with host networking, rather than just port 5580. Frankly I’m curious how you got as far as you did, since mDNS is normally used for commissioning, but your logs show the IP address was already known (how?). Also your dbus mapping looks unusual, but maybe you’re using symlinks to /run/dbus? I would suggest review the example compose file or provide some additional details on your setup and what commissioning method you’re using.

WallyR · August 8, 2024, 7:38pm

You need to have

IPv6 enabled
only one NIC in HA, Matter server and OTBR
HA, Matter, OTBR and phone on the same Network/VLAN

agners · August 9, 2024, 8:54am

When using the Android commissioning flow (through the Home Assistant Android App), we get an IP and the pin code directly. We pass that off to the Matter Server, so this could be the reason. @Tomatenplukker can you confirm that is the flow you were using?

But yeah, in general to make discovery work from that point onwards, mDNS is required. So use host network, and then things should run smoother.

From the logs it seems that initial commissioning worked, but the interviewing not. I would expect that the same CASE session is reused for interviewing, so this is somewhat surprising. It is probably not mDNS related. What we have seen in early Matter implementation some bulbs just randomly crash. Then the CASE session needs to be recreated, which needs mDNS. I’d recommend check if you have the latest firmware update from the Meross app. Unfortunately Meross does not support Matter updates

tl;dr: Use host network. Make sure to update the bulb to the lastest firmware using Meross App.

Tomatenplukker · August 9, 2024, 2:29pm

That should all be the case.
Expect OTBR, I do not have that. Is that a problem? I do not think the devices use Thread.

Tomatenplukker · August 9, 2024, 2:34pm

I was indeed using an android phone the add the devices.
Later I tried an Ipad and I was able to add the Merros plug! All be it without power monitoring. I looked that up and apparently thats normal, cause Merros does not support that data in the payload over Matter.

I also tried to add the GU10 LEDs with the Ipad, and only half succeeded with 1 of the 2.

Here I got 2 entities in HA that do not work, 1 to switch the light and 1 “On Level” entity?

I tried again today with the network switched to host.
I could add the second bulb with Android. But the result is the same as with the Ipad.

Tomatenplukker · August 9, 2024, 2:41pm

New logs after switching to host.

2024-08-09 14:35:05.361 (MainThread) INFO [chip.FabricAdmin] New FabricAdmin: FabricId: 0x0000000000000001, VendorId = 0xFFF1
2024-08-09 14:35:05.361 (MainThread) INFO [matter_server.server.stack] CHIP Controller Stack initialized.
2024-08-09 14:35:05.362 (MainThread) INFO [matter_server.server.server] Starting the Matter Server...
2024-08-09 14:35:05.364 (MainThread) INFO [matter_server.server.helpers.paa_certificates] Skip fetching certificates (already fetched within the last 24h).
2024-08-09 14:35:05.364 (MainThread) INFO [chip.FabricAdmin] Allocating new controller with CaIndex: 1, FabricId: 0x0000000000000001, NodeId: 0x000000000001B669, CatTags: []
2024-08-09 14:35:05.486 (Dummy-2) CHIP_ERROR [chip.native.DIS] Failed to advertise records: src/inet/UDPEndPointImplSockets.cpp:416: OS Error 0x02000065: Network is unreachable
2024-08-09 14:35:05.488 (Dummy-2) CHIP_ERROR [chip.native.DL] Long dispatch time: 124 ms, for event type 2
2024-08-09 14:35:05.493 (MainThread) INFO [matter_server.server.vendor_info] Loading vendor info from storage.
2024-08-09 14:35:05.497 (MainThread) INFO [matter_server.server.vendor_info] Loaded 233 vendors from storage.
2024-08-09 14:35:05.497 (MainThread) INFO [matter_server.server.vendor_info] Fetching the latest vendor info from DCL.
2024-08-09 14:35:05.891 (MainThread) INFO [matter_server.server.vendor_info] Fetched 231 vendors from DCL.
2024-08-09 14:35:05.891 (MainThread) INFO [matter_server.server.vendor_info] Saving vendor info to storage.
2024-08-09 14:35:05.917 (MainThread) INFO [matter_server.server.device_controller] Loaded 3 nodes from stored configuration
2024-08-09 14:35:05.930 (MainThread) INFO [matter_server.server.server] Matter Server successfully initialized.
2024-08-09 14:35:07.589 (MainThread) INFO [matter_server.server.device_controller.mdns] <Node:22> Discovered on mDNS
2024-08-09 14:35:07.590 (MainThread) INFO [matter_server.server.device_controller] <Node:22> Setting-up node...
2024-08-09 14:35:12.614 (Dummy-2) CHIP_ERROR [chip.native.SC] CASESession timed out while waiting for a response from the peer. Current state was 1
2024-08-09 14:35:15.284 (Dummy-2) CHIP_ERROR [chip.native.EM] Failed to Send CHIP MessageCounter:94664974 on exchange 10119i with Node: <0000000000000000, 0> sendCount: 4 max retries: 4
2024-08-09 14:35:17.438 (Dummy-2) CHIP_ERROR [chip.native.SC] CASESession timed out while waiting for a response from the peer. Current state was 1
2024-08-09 14:35:22.262 (Dummy-2) CHIP_ERROR [chip.native.SC] CASESession timed out while waiting for a response from the peer. Current state was 1
2024-08-09 14:35:24.822 (Dummy-2) CHIP_ERROR [chip.native.EM] Failed to Send CHIP MessageCounter:94664976 on exchange 10121i with Node: <0000000000000000, 0> sendCount: 4 max retries: 4
2024-08-09 14:35:27.085 (Dummy-2) CHIP_ERROR [chip.native.SC] CASESession timed out while waiting for a response from the peer. Current state was 1
2024-08-09 14:35:30.087 (MainThread) INFO [matter_server.server.sdk] <Node:22> Attempting to establish CASE session... (attempt 2 of 2)
2024-08-09 14:35:30.618 (MainThread) INFO [matter_server.server.device_controller] <Node:19> Node could not be discovered on the network, returning cached IP's
2024-08-09 14:35:30.637 (MainThread) INFO [matter_server.server.device_controller] <Node:19> Node could not be discovered on the network, returning cached IP's
2024-08-09 14:35:32.952 (Dummy-2) CHIP_ERROR [chip.native.EM] Failed to Send CHIP MessageCounter:94664977 on exchange 10122i with Node: <0000000000000000, 0> sendCount: 4 max retries: 4
2024-08-09 14:35:35.110 (Dummy-2) CHIP_ERROR [chip.native.SC] CASESession timed out while waiting for a response from the peer. Current state was 1
2024-08-09 14:35:39.933 (Dummy-2) CHIP_ERROR [chip.native.SC] CASESession timed out while waiting for a response from the peer. Current state was 1
2024-08-09 14:35:42.379 (Dummy-2) CHIP_ERROR [chip.native.EM] Failed to Send CHIP MessageCounter:94664979 on exchange 10124i with Node: <0000000000000000, 0> sendCount: 4 max retries: 4
2024-08-09 14:35:44.752 (Dummy-2) CHIP_ERROR [chip.native.SC] CASESession timed out while waiting for a response from the peer. Current state was 1
2024-08-09 14:35:46.447 (MainThread) INFO [matter_server.server.device_controller] <Node:19> Node could not be discovered on the network, returning cached IP's
2024-08-09 14:35:46.453 (MainThread) INFO [matter_server.server.device_controller] <Node:19> Node could not be discovered on the network, returning cached IP's
2024-08-09 14:35:49.576 (Dummy-2) CHIP_ERROR [chip.native.SC] CASESession timed out while waiting for a response from the peer. Current state was 1
2024-08-09 14:35:49.577 (MainThread) WARNING [matter_server.server.device_controller] <Node:22> Setup for node failed: Unable to establish CASE session with Node 22
2024-08-09 14:37:42.730 (MainThread) INFO [matter_server.server.device_controller.mdns] <Node:22> Discovered on mDNS
2024-08-09 14:37:42.730 (MainThread) INFO [matter_server.server.device_controller] <Node:22> Setting-up node...
2024-08-09 14:38:13.747 (Dummy-2) CHIP_ERROR [chip.native.DIS] Timeout waiting for mDNS resolution.
2024-08-09 14:38:27.731 (Dummy-2) CHIP_ERROR [chip.native.DIS] OperationalSessionSetup[1:0000000000000016]: operational discovery failed: src/lib/address_resolve/AddressResolve_DefaultImpl.cpp:119: CHIP Error 0x00000032: Timeout
2024-08-09 14:38:30.736 (MainThread) INFO [matter_server.server.sdk] <Node:22> Attempting to establish CASE session... (attempt 2 of 2)
2024-08-09 14:39:01.742 (Dummy-2) CHIP_ERROR [chip.native.DIS] Timeout waiting for mDNS resolution.
2024-08-09 14:39:15.738 (Dummy-2) CHIP_ERROR [chip.native.DIS] OperationalSessionSetup[1:0000000000000016]: operational discovery failed: src/lib/address_resolve/AddressResolve_DefaultImpl.cpp:119: CHIP Error 0x00000032: Timeout
2024-08-09 14:39:15.739 (MainThread) WARNING [matter_server.server.device_controller] <Node:22> Setup for node failed: Unable to establish CASE session with Node 22

WallyR · August 9, 2024, 4:20pm

Just looked up your brand of smart plugs and there seems to be only wifi ones, so no need for OTBR.