Matter Integration: cannot add bridge device

[derabbink]

The problem

I installed the Matter Service Addon (v5.0.4) onto my HA Raspberry Pi 4b. On my iPhone 15 I try to add a matter device.
When I try to add a Matter Device, I observe 3 things.

1. I can only add a matter device on my phone, because apparently scanning a QR code is essential to the process. However, once the "Add Matter device" dialog loads the camera overlay, there is also an option to add the device manually by entering a code, which my Matter device provides, so why can't I use this approach in a browser?
2. Usually, the "Add Matter device" dialog is a mostly blank screen with a spinner, that takes many minutes (sometimes hours) to load the QR code scanner camera overlay. And even if I cancel it, sometimes later on, while I'm in the middle of something completely different again, the camera overlay suddenly pops up over the top of another app.
   The wait time for the camera overlay to appear is rather strange, and the fact that the dialog eventually appears asynchronously out of nowhere is even stranger. This delay subsides after the 4th or 5th try of opening the dialog.
3. Once I scanned a QR code, the setup takes some minutes, and eventually always fails. My Matter Device reports that 2 Matter integrations have been registered (they all have a mac-address like structure), and it immediately closes its "ready for pairing" status, once those two integrations have been created. After that, the HA dialog for setting up a new Matter Bridge device will keep on spinning for a while.
   PS: I just noticed that with debug level logging enabled, only one matter integration is registered with the bridge, and the whole thing fails very quickly

Home assistant version data:

• Core: 2024.1.6
• Supervisor: 2024.01.1
• Operating System: 11.5
• Frontend: 20240104.0

HA iOS App:

• version: 2024.1

My Matter Device:

• Make: Ubisys
• Model: G1
• Function: This is a bridge. It should hopefully allow HA access to a whole range of zigbee devices, for which the G1 is the coordinator.
• Matter certification: fully certified (Ubisys is part of CSA and co-wrote the matter spec)

What version of Home Assistant Core has the issue?

core-2024.1.6

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 Server

Link to integration documentation on our website

https://www.home-assistant.io/integrations/matter/

Diagnostics information

debug log (the other log further down is just an info level log)

2024-02-05 19:19:41 core-matter-server chip.CTL[126] DEBUG StorageAdapter::GetKeyValue: Key = f/1/r, Value = 0x7f7401fb00 (400)
2024-02-05 19:19:41 core-matter-server chip.CTL[126] DEBUG Key Found 231

2024-02-05 19:19:41 core-matter-server chip.FP[126] INFO Validating NOC chain
2024-02-05 19:19:41 core-matter-server chip.FP[126] INFO NOC chain validation successful
2024-02-05 19:19:41 core-matter-server chip.FP[126] INFO Updated fabric at index: 0x1, Node ID: 0x000000000001B669
2024-02-05 19:19:41 core-matter-server chip.TS[126] INFO Last Known Good Time: 2023-10-14T01:16:48
2024-02-05 19:19:41 core-matter-server chip.TS[126] INFO New proposed Last Known Good Time: 2021-01-01T00:00:00
2024-02-05 19:19:41 core-matter-server chip.TS[126] INFO Retaining current Last Known Good Time
2024-02-05 19:19:41 core-matter-server chip.CTL[126] DEBUG StorageAdapter::GetKeyValue: Key = g/sri, Value = 0x7f82202890 (966)
2024-02-05 19:19:41 core-matter-server chip.CTL[126] DEBUG Key Found 18

2024-02-05 19:19:41 core-matter-server chip.CTL[126] DEBUG StorageAdapter::GetKeyValue: Key = f/1/s/0000000000000005, Value = 0x7f82202bf8 (74)
2024-02-05 19:19:41 core-matter-server chip.CTL[126] DEBUG Key Found 71

2024-02-05 19:19:41 core-matter-server chip.CTL[126] DEBUG StorageAdapter::GetKeyValue: Key = g/s/2CXhKPZAdSL4MHzhz803BQ==, Value = 0x7f82202ba0 (0)
2024-02-05 19:19:41 core-matter-server chip.CTL[126] DEBUG Buf not big enough

2024-02-05 19:19:41 core-matter-server chip.CTL[126] DEBUG StorageAdapter::DeleteKeyValue: Key = g/s/2CXhKPZAdSL4MHzhz803BQ==
2024-02-05 19:19:41 core-matter-server PersistentStorage[126] INFO DeleteSdkKey: g/s/2CXhKPZAdSL4MHzhz803BQ==
2024-02-05 19:19:41 core-matter-server PersistentStorage[126] INFO Committing...
2024-02-05 19:19:41 core-matter-server chip.CTL[126] DEBUG StorageAdapter::GetKeyValue: Key = f/1/s/0000000000000005, Value = 0x7f82202ba0 (0)
2024-02-05 19:19:41 core-matter-server chip.CTL[126] DEBUG Buf not big enough

2024-02-05 19:19:41 core-matter-server chip.CTL[126] DEBUG StorageAdapter::DeleteKeyValue: Key = f/1/s/0000000000000005
2024-02-05 19:19:41 core-matter-server PersistentStorage[126] INFO DeleteSdkKey: f/1/s/0000000000000005
2024-02-05 19:19:41 core-matter-server PersistentStorage[126] INFO Committing...
2024-02-05 19:19:41 core-matter-server chip.CTL[126] DEBUG StorageAdapter::GetKeyValue: Key = f/1/s/0000000000000006, Value = 0x7f82202bf8 (74)
2024-02-05 19:19:41 core-matter-server chip.CTL[126] DEBUG Key Found 71

2024-02-05 19:19:41 core-matter-server chip.CTL[126] DEBUG StorageAdapter::GetKeyValue: Key = g/s/wsdRpL5VY+kEy0C1Lr9HQw==, Value = 0x7f82202ba0 (0)
2024-02-05 19:19:41 core-matter-server chip.CTL[126] DEBUG Buf not big enough

2024-02-05 19:19:41 core-matter-server chip.CTL[126] DEBUG StorageAdapter::DeleteKeyValue: Key = g/s/wsdRpL5VY+kEy0C1Lr9HQw==
2024-02-05 19:19:41 core-matter-server PersistentStorage[126] INFO DeleteSdkKey: g/s/wsdRpL5VY+kEy0C1Lr9HQw==
2024-02-05 19:19:41 core-matter-server PersistentStorage[126] INFO Committing...
2024-02-05 19:19:41 core-matter-server chip.CTL[126] DEBUG StorageAdapter::GetKeyValue: Key = f/1/s/0000000000000006, Value = 0x7f82202ba0 (0)
2024-02-05 19:19:41 core-matter-server chip.CTL[126] DEBUG Buf not big enough

2024-02-05 19:19:41 core-matter-server chip.CTL[126] DEBUG StorageAdapter::DeleteKeyValue: Key = f/1/s/0000000000000006
2024-02-05 19:19:41 core-matter-server PersistentStorage[126] INFO DeleteSdkKey: f/1/s/0000000000000006
2024-02-05 19:19:41 core-matter-server PersistentStorage[126] INFO Committing...
2024-02-05 19:19:41 core-matter-server chip.CTL[126] DEBUG StorageAdapter::SetKeyValue: Key = g/sri, Value = 0x7f82202890 (2)
2024-02-05 19:19:41 core-matter-server PersistentStorage[126] INFO SetSdkKey: g/sri = b'\x16\x18'
2024-02-05 19:19:41 core-matter-server PersistentStorage[126] INFO Committing...
2024-02-05 19:19:41 core-matter-server chip.CTL[126] DEBUG StorageAdapter::SetKeyValue: Key = g/fs/c, Value = 0x7f82203120 (7)
2024-02-05 19:19:41 core-matter-server PersistentStorage[126] INFO SetSdkKey: g/fs/c = b'\x15$\x00\x01(\x01\x18'
2024-02-05 19:19:41 core-matter-server PersistentStorage[126] INFO Committing...
2024-02-05 19:19:41 core-matter-server chip.CTL[126] DEBUG StorageAdapter::SetKeyValue: Key = f/1/m, Value = 0x7f82203098 (9)
2024-02-05 19:19:41 core-matter-server PersistentStorage[126] INFO SetSdkKey: f/1/m = b'\x15%\x00K\x13,\x01\x00\x18'
2024-02-05 19:19:41 core-matter-server PersistentStorage[126] INFO Committing...
2024-02-05 19:19:41 core-matter-server chip.FP[126] INFO Metadata for Fabric 0x1 persisted to storage.
2024-02-05 19:19:41 core-matter-server chip.CTL[126] DEBUG StorageAdapter::SetKeyValue: Key = f/1/n, Value = 0x7f7401b8c0 (244)
2024-02-05 19:19:41 core-matter-server PersistentStorage[126] INFO SetSdkKey: f/1/n = b'\x150\x01\x01\x01$\x02\x017\x03$\x13\x02\x18&\x04\x80"\x81\'&\x05\x80%M:7\x06$\x15\x02&\x11i\xb6\x01\x00\x18$\x07\x01$\x08\x010\tA\x04\x96m>$\xb1`\xb3\x7f\xba\x8e\x8c\xacx\x91\x9a\x12\r\\\xa3N\x8a\xd1W$\xeeZj\xd6\xe6\x11\x98W\xb0\xffQ9\xd7\x83\t\x13\x1e\x17\xeap\x10\xad\xbe.\xd8vL\x80\xb1}#\xba\xe0\x1b\x17\x1b\xa0Tj\xd67\n5\x01(\x01\x18$\x02\x016\x03\x04\x02\x04\x01\x180\x04\x14)\xf6\xdds\x01\xda\x85\x98Z/F\x17\x1f\xce\xf6\x94\x12\x95\x9c\x850\x05\x14n\x99v\xeb\xb3\x0c\xa0\xc4\x94\xf2\xc0\xab_\x9dF\x1a\x13\xd2\x16[\x180\x0b@\xf4\x12}#"G\x1a\xda\xe1/\xfe\xd1\xe6\xe7\x11\x15\n\x9a\xbfP5\x88\xf1I\xccRF\x95\xa6\x9a\xb6F\xa5\x90\x00\x13\x94b\x199\xd1E;\x0c\xcc\xeb~q\xa5\xdc/\xbd\xdc\xfb\xbc\x93\xc1<\xe8p\x88_\x8f\xaa\x18'
2024-02-05 19:19:41 core-matter-server PersistentStorage[126] INFO Committing...
2024-02-05 19:19:41 core-matter-server chip.CTL[126] DEBUG StorageAdapter::SetKeyValue: Key = f/1/i, Value = 0x7f74002290 (231)
2024-02-05 19:19:41 core-matter-server PersistentStorage[126] INFO SetSdkKey: f/1/i = b'\x150\x01\x01\x01$\x02\x017\x03$\x14\x01\x18&\x04\x80"\x81\'&\x05\x80%M:7\x06$\x13\x02\x18$\x07\x01$\x08\x010\tA\x04\xf7\xe6y\xad\xba\x84k\xdd-\xb2De_7O\x0c\x80bi\x0c\xf0\xe0\x0bv\xf7E\xdea\xb8\xda\xaa{\xd9\x03"\xba\xc8\x1d\xd6P\x05c\xcf\x95\x91\xb9#\xb8F\xc1w\xa0ve\x89\xfc\x98\xceFZ\x828\xda37\n5\x01)\x01\x18$\x02`0\x04\x14n\x99v\xeb\xb3\x0c\xa0\xc4\x94\xf2\xc0\xab_\x9dF\x1a\x13\xd2\x16[0\x05\x14\x0b\x17g\x95u\xd7I\xcb\xaf\xb7sTB\xc8\x8f\xf2\'\xdb\x916\x180\x0b@\x16V\x12ujT\xccFvs\xb9v\xe3+\x18\x16H54\xdeS\x9eSg\x9c\xdc\x1ev\xb6\tl\\/\xaf\xbb\xc7\x06\xb5+\xd1\xc5\xe4\xa9\x05s\xe7\x86SD\xe8\x8f\xe59\xf3\x7f\xd8\xf7\x944\x88\xf7\x99F\xfd\x18'
2024-02-05 19:19:41 core-matter-server PersistentStorage[126] INFO Committing...
2024-02-05 19:19:41 core-matter-server chip.TS[126] INFO Committing Last Known Good Time to storage: 2023-10-14T01:16:48
2024-02-05 19:19:41 core-matter-server chip.CTL[126] DEBUG StorageAdapter::SetKeyValue: Key = g/lkgt, Value = 0x7f822030c0 (8)
2024-02-05 19:19:41 core-matter-server PersistentStorage[126] INFO SetSdkKey: g/lkgt = b'\x15&\x00\x80\xa8\xbc,\x18'
2024-02-05 19:19:41 core-matter-server PersistentStorage[126] INFO Committing...
2024-02-05 19:19:41 core-matter-server chip.CTL[126] DEBUG StorageAdapter::GetKeyValue: Key = g/fs/c, Value = 0x7f822030c0 (0)
2024-02-05 19:19:41 core-matter-server chip.CTL[126] DEBUG Buf not big enough

2024-02-05 19:19:41 core-matter-server chip.CTL[126] DEBUG StorageAdapter::DeleteKeyValue: Key = g/fs/c
2024-02-05 19:19:41 core-matter-server PersistentStorage[126] INFO DeleteSdkKey: g/fs/c
2024-02-05 19:19:41 core-matter-server PersistentStorage[126] INFO Committing...
2024-02-05 19:19:41 core-matter-server chip.CTL[126] INFO Joined the fabric at index 1. Fabric ID is 0x0000000000000002 (Compressed Fabric ID: A3717998F9F4B3E8)
2024-02-05 19:19:41 core-matter-server chip.CTL[126] INFO *** Missing DeviceAttestationVerifier configuration at DeviceCommissioner init: using global default, consider passing one in CommissionerInitParams.
2024-02-05 19:19:41 core-matter-server chip.SPT[126] INFO Setting up group data for Fabric Index 1 with Compressed Fabric ID:
2024-02-05 19:19:41 core-matter-server chip.SPT[126] DEBUG 0xa3, 0x71, 0x79, 0x98, 0xf9, 0xf4, 0xb3, 0xe8, 
2024-02-05 19:19:41 core-matter-server chip.CTL[126] DEBUG StorageAdapter::GetKeyValue: Key = f/1/g, Value = 0x7f822034d8 (128)
2024-02-05 19:19:41 core-matter-server chip.CTL[126] DEBUG Key Found 23

2024-02-05 19:19:41 core-matter-server chip.CTL[126] DEBUG StorageAdapter::GetKeyValue: Key = f/1/k/0, Value = 0x7f82203578 (128)
2024-02-05 19:19:41 core-matter-server chip.CTL[126] DEBUG Key Found 97

2024-02-05 19:19:41 core-matter-server chip.CTL[126] DEBUG StorageAdapter::SetKeyValue: Key = f/1/k/0, Value = 0x7f82203578 (97)
2024-02-05 19:19:41 core-matter-server PersistentStorage[126] INFO SetSdkKey: f/1/k/0 = b'\x15$\x01\x00$\x02\x016\x03\x15$\x04\x00%\x05\xa7\xc50\x06\x10\xcef\xf2RjwK\x17\xb7\xb7d<s\x03-^\x18\x15$\x04\x00$\x05\x000\x06\x10\x00\x00\x00\x00\x00\x00\x00\x00\x00\x00\x00\x00\x00\x00\x00\x00\x18\x15$\x04\x00$\x05\x000\x06\x10\x00\x00\x00\x00\x00\x00\x00\x00\x00\x00\x00\x00\x00\x00\x00\x00\x18\x18%\x07\xff\xff\x18'
2024-02-05 19:19:41 core-matter-server PersistentStorage[126] INFO Committing...
2024-02-05 19:19:41 core-matter-server chip.DL[126] ERROR Long dispatch time: 111 ms, for event type 2
2024-02-05 19:19:41 core-matter-server matter_server.server.device_controller[126] DEBUG CHIP Device Controller Initialized
2024-02-05 19:19:41 core-matter-server matter_server.server.storage[126] DEBUG Loading persistent settings from /data/11777328198486111208.json
2024-02-05 19:19:41 core-matter-server matter_server.server.storage[126] DEBUG Started.
2024-02-05 19:19:41 core-matter-server matter_server.server.device_controller[126] INFO Loaded 0 nodes from stored configuration
2024-02-05 19:19:41 core-matter-server matter_server.server.vendor_info[126] INFO Loading vendor info from storage.
2024-02-05 19:19:41 core-matter-server matter_server.server.vendor_info[126] INFO Loaded 155 vendors from storage.
2024-02-05 19:19:41 core-matter-server matter_server.server.vendor_info[126] INFO Fetching the latest vendor info from DCL.
2024-02-05 19:19:41 core-matter-server matter_server.server.vendor_info[126] INFO Fetched 155 vendors from DCL.
2024-02-05 19:19:41 core-matter-server matter_server.server.vendor_info[126] INFO Saving vendor info to storage.
2024-02-05 19:19:41 core-matter-server matter_server.server.server[126] DEBUG Webserver initialized.
2024-02-05 19:19:52 core-matter-server matter_server.server.client_handler[126] DEBUG [547748657104] Connected from 10.0.3.19
2024-02-05 19:19:52 core-matter-server matter_server.server.client_handler[126] DEBUG [547748657104] Received: {
  "message_id": "46d8e6356e424010aba39d8a894f05ee",
  "command": "start_listening",
  "args": null
}
2024-02-05 19:19:52 core-matter-server matter_server.server.client_handler[126] DEBUG [547748657104] Received CommandMessage(message_id='46d8e6356e424010aba39d8a894f05ee', command='start_listening', args=None)
2024-02-05 19:19:52 core-matter-server matter_server.server.client_handler[126] DEBUG [547748657104] Handling command start_listening

Example YAML snippet

No response

Anything in the logs that might be useful for us?

Home Assistant Supervisor: 2024.01.1
-----------------------------------------------------------
 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
[18:57:23] INFO: Starting Matter Server...
s6-rc: info: service legacy-services successfully started
[18:57:24] INFO: Using 'end0' as primary network interface.
[18:57:24] INFO: Successfully send discovery information to Home Assistant.
2024-02-05 18:57:30 core-matter-server matter_server.server.stack[126] INFO Initializing CHIP/Matter Controller Stack...
[1707155850.954227][126:126] CHIP:CTL: Setting attestation nonce to random value
[1707155850.957866][126:126] CHIP:CTL: Setting CSR nonce to random value
[1707155851.045286][126:126] CHIP:DL: ChipLinuxStorage::Init: Using KVS config file: /tmp/chip_kvs
[1707155851.045769][126:126] CHIP:DL: writing settings to file (/tmp/chip_kvs-C4BiHH)
[1707155851.046846][126:126] CHIP:DL: renamed tmp file to file (/tmp/chip_kvs)
[1707155851.048818][126:126] CHIP:DL: ChipLinuxStorage::Init: Using KVS config file: /data/chip_factory.ini
[1707155851.067090][126:126] CHIP:DL: ChipLinuxStorage::Init: Using KVS config file: /data/chip_config.ini
[1707155851.068663][126:126] CHIP:DL: ChipLinuxStorage::Init: Using KVS config file: /data/chip_counters.ini
[1707155851.074238][126:126] CHIP:DL: writing settings to file (/data/chip_counters.ini-pY2fvJ)
[1707155851.076149][126:126] CHIP:DL: renamed tmp file to file (/data/chip_counters.ini)
[1707155851.076222][126:126] CHIP:DL: NVS set: chip-counters/reboot-count = 2 (0x2)
[1707155851.077228][126:126] CHIP:DL: Got Ethernet interface: end0
[1707155851.077825][126:126] CHIP:DL: Found the primary Ethernet interface:end0
[1707155851.078378][126:126] CHIP:DL: Got WiFi interface: wlan0
[1707155851.078459][126:126] CHIP:DL: Failed to reset WiFi statistic counts
2024-02-05 18:57:31 core-matter-server PersistentStorage[126] WARNING Initializing persistent storage from file: /data/chip.json
2024-02-05 18:57:31 core-matter-server PersistentStorage[126] WARNING Loading configuration from /data/chip.json...
2024-02-05 18:57:31 core-matter-server chip.DL[126] ERROR MDNS failed to join multicast group on wlan0 for address type IPv4: src/inet/UDPEndPointImplSockets.cpp:777: Inet Error 0x00000110: Address not found
2024-02-05 18:57:31 core-matter-server chip.DL[126] ERROR MDNS failed to join multicast group on vethe05bd8c for address type IPv4: src/inet/UDPEndPointImplSockets.cpp:777: Inet Error 0x00000110: Address not found
2024-02-05 18:57:31 core-matter-server chip.DL[126] ERROR MDNS failed to join multicast group on vethf658cd4 for address type IPv4: src/inet/UDPEndPointImplSockets.cpp:777: Inet Error 0x00000110: Address not found
2024-02-05 18:57:31 core-matter-server chip.DL[126] ERROR MDNS failed to join multicast group on vetha8084b2 for address type IPv4: src/inet/UDPEndPointImplSockets.cpp:777: Inet Error 0x00000110: Address not found
2024-02-05 18:57:31 core-matter-server chip.DL[126] ERROR MDNS failed to join multicast group on vethadf9164 for address type IPv4: src/inet/UDPEndPointImplSockets.cpp:777: Inet Error 0x00000110: Address not found
2024-02-05 18:57:31 core-matter-server chip.DL[126] ERROR MDNS failed to join multicast group on veth24973ca for address type IPv4: src/inet/UDPEndPointImplSockets.cpp:777: Inet Error 0x00000110: Address not found
2024-02-05 18:57:31 core-matter-server chip.DL[126] ERROR MDNS failed to join multicast group on veth8535fbe for address type IPv4: src/inet/UDPEndPointImplSockets.cpp:777: Inet Error 0x00000110: Address not found
2024-02-05 18:57:31 core-matter-server CertificateAuthorityManager[126] WARNING Loading certificate authorities from storage...
2024-02-05 18:57:31 core-matter-server CertificateAuthority[126] WARNING New CertificateAuthority at index 1
2024-02-05 18:57:31 core-matter-server CertificateAuthority[126] WARNING Loading fabric admins from storage...
2024-02-05 18:57:31 core-matter-server FabricAdmin[126] WARNING New FabricAdmin: FabricId: 0x0000000000000002, VendorId = 0x134B
2024-02-05 18:57:31 core-matter-server matter_server.server.stack[126] INFO CHIP Controller Stack initialized.
2024-02-05 18:57:31 core-matter-server matter_server.server.server[126] INFO Starting the Matter Server...
2024-02-05 18:57:31 core-matter-server matter_server.server.helpers.paa_certificates[126] INFO Fetching the latest PAA root certificates from DCL.
/usr/local/lib/python3.11/site-packages/matter_server/server/helpers/paa_certificates.py:46: CryptographyDeprecationWarning: The parsed certificate contains a NULL parameter value in its signature algorithm parameters. This is invalid and will be rejected in a future version of cryptography. If this certificate was created via Java, please upgrade to JDK16+ or the latest JDK11 once a fix is issued. If this certificate was created in some other fashion please report the issue to the cryptography issue tracker. See https://github.com/pyca/cryptography/issues/8996 for more details.
  pem_certificate = x509.load_pem_x509_certificate(certificate.encode())
2024-02-05 18:57:41 core-matter-server matter_server.server.helpers.paa_certificates[126] INFO Fetched 124 PAA root certificates from DCL.
2024-02-05 18:57:41 core-matter-server matter_server.server.helpers.paa_certificates[126] INFO Fetching the latest PAA root certificates from Git.
2024-02-05 18:57:41 core-matter-server matter_server.server.helpers.paa_certificates[126] INFO Fetched 2 PAA root certificates from Git.
2024-02-05 18:57:41 core-matter-server FabricAdmin[126] WARNING Allocating new controller with CaIndex: 1, FabricId: 0x0000000000000002, NodeId: 0x000000000001B669, CatTags: []
2024-02-05 18:57:41 core-matter-server chip.DL[126] ERROR Long dispatch time: 116 ms, for event type 2
2024-02-05 18:57:41 core-matter-server matter_server.server.device_controller[126] INFO Loaded 0 nodes from stored configuration
2024-02-05 18:57:41 core-matter-server matter_server.server.vendor_info[126] INFO Loading vendor info from storage.
2024-02-05 18:57:41 core-matter-server matter_server.server.vendor_info[126] INFO Loaded 155 vendors from storage.
2024-02-05 18:57:41 core-matter-server matter_server.server.vendor_info[126] INFO Fetching the latest vendor info from DCL.
2024-02-05 18:57:42 core-matter-server matter_server.server.vendor_info[126] INFO Fetched 155 vendors from DCL.
2024-02-05 18:57:42 core-matter-server matter_server.server.vendor_info[126] INFO Saving vendor info to storage.
2024-02-05 19:08:13 core-matter-server matter_server.server.device_controller[126] INFO Starting Matter commissioning with code using Node ID 5 (attempt 0/3).
2024-02-05 19:08:16 core-matter-server matter_server.server.device_controller[126] INFO Matter commissioning of Node ID 5 successful.
2024-02-05 19:08:16 core-matter-server matter_server.server.device_controller[126] INFO Interviewing node: 5
2024-02-05 19:09:05 core-matter-server chip.DMG[126] ERROR Time out! failed to receive report data from Exchange: 41675i
2024-02-05 19:09:05 core-matter-server matter_server.server.device_controller[126] WARNING Unable to interview Node 5: Failed to interview node 5
2024-02-05 19:09:10 core-matter-server matter_server.server.device_controller[126] INFO Interviewing node: 5
2024-02-05 19:09:24 core-matter-server chip.DMG[126] ERROR Time out! failed to receive report data from Exchange: 41676i
2024-02-05 19:09:24 core-matter-server matter_server.server.device_controller[126] WARNING Unable to interview Node 5: Failed to interview node 5
2024-02-05 19:09:29 core-matter-server matter_server.server.device_controller[126] INFO Interviewing node: 5
2024-02-05 19:10:15 core-matter-server chip.DMG[126] ERROR Time out! failed to receive report data from Exchange: 41677i
2024-02-05 19:10:15 core-matter-server matter_server.server.device_controller[126] WARNING Unable to interview Node 5: Failed to interview node 5
2024-02-05 19:10:20 core-matter-server matter_server.server.client_handler[126] ERROR [548014109264] Error handling message: CommandMessage(message_id='225f8b86a80d4af196ce14c4af8b6aab', command='commission_with_code', args={'code': 'MT:A1O00UVQ15-JF346N10', 'network_only': True})
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 234, in commission_with_code
    await self._subscribe_node(node_id)
  File "/usr/local/lib/python3.11/site-packages/matter_server/server/device_controller.py", line 677, in _subscribe_node
    raise NodeNotExists(
matter_server.common.errors.NodeNotExists: Node 5 does not exist or has not been interviewed.
2024-02-05 19:13:27 core-matter-server matter_server.server.device_controller[126] INFO Starting Matter commissioning with code using Node ID 6 (attempt 0/3).
2024-02-05 19:13:29 core-matter-server matter_server.server.device_controller[126] INFO Matter commissioning of Node ID 6 successful.
2024-02-05 19:13:29 core-matter-server matter_server.server.device_controller[126] INFO Interviewing node: 6
2024-02-05 19:14:16 core-matter-server chip.DMG[126] ERROR Time out! failed to receive report data from Exchange: 41690i
2024-02-05 19:14:16 core-matter-server matter_server.server.device_controller[126] WARNING Unable to interview Node 6: Failed to interview node 6
2024-02-05 19:14:21 core-matter-server matter_server.server.device_controller[126] INFO Interviewing node: 6
2024-02-05 19:14:44 core-matter-server chip.DMG[126] ERROR Time out! failed to receive report data from Exchange: 41691i
2024-02-05 19:14:44 core-matter-server matter_server.server.device_controller[126] WARNING Unable to interview Node 6: Failed to interview node 6
2024-02-05 19:14:49 core-matter-server matter_server.server.device_controller[126] INFO Interviewing node: 6
2024-02-05 19:15:37 core-matter-server chip.DMG[126] ERROR Time out! failed to receive report data from Exchange: 41692i
2024-02-05 19:15:37 core-matter-server matter_server.server.device_controller[126] WARNING Unable to interview Node 6: Failed to interview node 6
2024-02-05 19:15:42 core-matter-server matter_server.server.client_handler[126] ERROR [548014109264] Error handling message: CommandMessage(message_id='6d67c4fd118848fba858f81b8f7f48a9', command='commission_with_code', args={'code': 'MT:A1O0006Z169JQD3HO00', 'network_only': True})
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 234, in commission_with_code
    await self._subscribe_node(node_id)
  File "/usr/local/lib/python3.11/site-packages/matter_server/server/device_controller.py", line 677, in _subscribe_node
    raise NodeNotExists(
matter_server.common.errors.NodeNotExists: Node 6 does not exist or has not been interviewed.

Additional information

No response

[home-assistant[bot]]

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]

1. Because we did not yet implement that functionality. It is on the roadmap for later, didn't you see our blog post and live stream recently about the current state ? For now focus is on the scenario that is most common: adding a new matter device using the QR code for which we utilize the SDK framework on the phone to do the first bluetooth commissioning.

2. Strange that sounds like a bug in our iOS companion app. Note that our Matter support is still in beta so it may contain bugs. I'll report your observation to our iOS developer.

3. Do you have a flat network ? No vLANS ? Is IPv6 enabled on your local network router and the Home Assistant server ? Looking at your log, the HA Matter controller has trouble reaching your bridge device over the network.

TIP: unless specifically asked there is no need to turn on debug logging. It makes the logs VERY verbose as you may have seen.

[derabbink]

1. I did look for resources on the state of implementation, but I was not able to get a definitive answer to my (then yet unarticulated) question "is a matter bridge supported by HA yet?"
   Thanks for providing that answer here. Is there a ticket I can subscribe to, to track progress made on that?
2. thanks
3. The HA Raspberry Pi, the Ubisys G1, and the iPhone were in the same network during all tests. This network does have IPv6 enabled and I know for sure that all of this works well. There are no other tagged VLANs in this network either. I'll see if I can troubleshoot the G1's IPv6 connectivity in parallel, and if I observe any issues there, I'll report them to the vendor.
4. The "report issue" form prompted me for debug logs, so I thought to myself "sure why not"

[marcelveldt]

1. Don't get me wrong. Matter bridges should work totally fine with our implementation of Matter. The only thing "missing" is the ability to add a Matter bridge device to HA without a phone which is a (very) low priority addition as it works completely fine with the phone app. You can keep an eye on the release notes and blog posts to track progress.

2. Strange, like I said, it should work completely fine. I have tested many matter bridge devices and they all work perfect. Were you able to add this bridge device to any other Matter controlleron the exact same network setup by any chance ?

[derabbink]

Coming back to the connectivity issue: I don't see this reflected in the logs as you mentioned. I do see Time out a couple of times, but in principle some form of connectivity must actually exist, since the G1 reports that two matter integrations have been set up, when I try to link it to my HA installation. I'm also not sure that it all must work over IPv6, as I also don't see the raspberry Pi's IPv6 address in the logs, but rather its IPv4 address (10.0.3.19) from when HA connects to the matter server.

I have not used any other matter controller to link the G1 to, as I currently do not have access to one.

[marcelveldt]

Matter commissioning is a 2 step process. It first gets commissioned to a temporary fabric on the phone and then from there shared to the HA fabric. That is how Google and Apple implemented this part in their OS-level SDK for Matter that we consume in the Companion app. So if the first step succeeds, the second step fails. The timeout means that the HA controller isn't able to communicate with the device. The fact that the HA Mater server is trying this at all, already means that the first step went fine (the temp fabric) so the issue lies in the second step where the device is handed over from the temp fabric to the HA matter controller.

We have added a bunch of updates in the last weeks so one thing you may want to try is either wait for the release of HA 2024.2 tomorrow or switch to the beta version. In case you want to try the beta, make sure that you also enable the beta version on the add-on settings of the matter server.

[brunosabot]

Hello!

I have the same issue when I want to pair my Aqara E1 Hub to Home Assistant. I'm using a Pixel Phone, on Android, and it ends up with an error message. I waited until today to report to check with the 2024.2 release, but it's still failing.

I have this in the logs:

2024-02-07 21:31:18 core-matter-server chip.EM[126] ERROR Failed to Send CHIP MessageCounter:168973653 on exchange 11878i sendCount: 4 max retries: 4
2024-02-07 21:31:21 core-matter-server chip.SC[126] ERROR PASESession timed out while waiting for a response from the peer. Expected message type was 33
2024-02-07 21:31:21 core-matter-server chip.ZCL[126] ERROR Secure Pairing Failed
2024-02-07 21:31:30 core-matter-server chip.EM[126] ERROR Failed to Send CHIP MessageCounter:168973654 on exchange 11879i sendCount: 4 max retries: 4
2024-02-07 21:31:32 core-matter-server chip.SC[126] ERROR PASESession timed out while waiting for a response from the peer. Expected message type was 33
2024-02-07 21:31:32 core-matter-server chip.ZCL[126] ERROR Secure Pairing Failed
2024-02-07 21:31:41 core-matter-server chip.EM[126] ERROR Failed to Send CHIP MessageCounter:168973655 on exchange 11880i sendCount: 4 max retries: 4
2024-02-07 21:31:43 core-matter-server chip.SC[126] ERROR PASESession timed out while waiting for a response from the peer. Expected message type was 33
2024-02-07 21:31:43 core-matter-server chip.ZCL[126] ERROR Secure Pairing Failed
2024-02-07 21:31:52 core-matter-server chip.EM[126] ERROR Failed to Send CHIP MessageCounter:168973656 on exchange 11881i sendCount: 4 max retries: 4
2024-02-07 21:31:54 core-matter-server chip.SC[126] ERROR PASESession timed out while waiting for a response from the peer. Expected message type was 33
2024-02-07 21:31:54 core-matter-server chip.ZCL[126] ERROR Secure Pairing Failed
2024-02-07 21:31:54 core-matter-server matter_server.server.client_handler[126] ERROR [547633806096] Error handling message: CommandMessage(message_id='a48e79fc7a434dd881e00c0ae3ef0607', command='commission_on_network', args={'setup_pin_code': 3761270, 'ip_addr': 'fe80::56ef:44ff:fe37:c75d%48'})
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 302, in commission_on_network
    raise NodeCommissionFailed(f"Commissioning failed for node {node_id}.")
matter_server.common.errors.NodeCommissionFailed: Commissioning failed for node 12.

I'm not expert enough to understand if it's related, but I just wanted to let you know just in case :)

[marcelveldt]

@brunosabot please join our discord server for support on this. 10001 reasons why it could be failing, most importantly network setup. Do you have a flat network (no vlans, no mdns forwarders) ? IPv6 set-up on your router as well as the HA host ?

[marcelveldt]

@derabbink do you still need assistance on this or can we close this ?

[derabbink]

I just tried this a few more times last night with the latest updates installed. The experience is still exactly the same as before. Closing this would seem inappropriate.

PS: I could not determine any reasons as to why the supposed connectivity between devices on my network might not be working. and I am still unsure how much of this is the root cause of the issue, since I am in fact seeing matter devices registered on the Ubisys G1 bridge.

[marcelveldt]

Sorry, but I have no more tricks in my sleeve to help you. I am not familiar with this Ubisys device at all, you are the first mentioning it. Your logs are polluted with failed attempts and from what I make up from it, communication is disturbed.

You mention seeing matter devices registered on the Ubisys G1, now I'm really confused. That Ubisys is not a matter controller but a bridge right ? So there can not be matter devices on that bridge.

Perhaps you mean that the bridge is displaying Matter fabrics that are connected to the bridge. Well, that can also be explained because the whole commissioning (the term for onboarding devices in the matter world) consists of 2 stages where in the first stage the credentials are exchanged and the trust set-up between device and controller, while the second stage is actual device communication. In your case stage 2 is clearly failing, hence me saying that you should check if IPv6 based communication is working in your network. Check your router is its handing out IPv6 addresses (DHCPv6 server enabled). A IPv6 based ISP setup should not be needed but we have seen manby cases (especially with bridges) that a working IPv6 dhcp server needs to be present in the local network.

Also check if the network setup of your HA server is setup with IPv6 enabled.

Did you ever try adding it to Apple Home as a test ?

One thing you may want to try as well is re-install matter completely in HA. Uninstall it from HA settings --> Matter and then check if the add-on is uninstalled.

[issue-triage-workflows[bot]]

There hasn't been any activity on this issue recently. Due to the high number of incoming GitHub notifications, we have to clean some of the old issues, as many of them have already been resolved with the latest updates. Please make sure to update to the latest Home Assistant version and check if that solves the issue. Let us know if that works for you by adding a comment 👍 This issue has now been marked as stale and will be closed if no further activity occurs. Thank you for your contributions.