Thanks! I did that and my system does not have Bluetooth. I will get a BT dongle and try again.
I too am struggling with the “Thread Border Router Required” message. I’m running Home Assistant OS on a RPi 4 with the SkyConnect dongle. Home Assistant seems to be working fine, except I can’t get any Thread devices to connect.
First of all, can someone confirm I’ve set this up properly?
-I’m currently running Silicon Labs Multiprotocol Add-on, not OpenThread Border Router (I shouldn’t be running both simultaneously, right?). Though I have tested OpenThread Border Router as well. (I don’t need Zigbee, so either would be fine for me)
-I have configured the “Device” to the SkyConnect device, and left all other options as their default. I should NOT configure the network ports (e.g. 8080 and 8081), correct?
-Open Thread Border Router shows up under integrations, and shows “Home Assistant SkyConnect (Silicon Labs Multiprotocol)” when clicked.
-When I configure the Thread integration, it shows Preferred network “home-assistant”, 1 border router, and “Silicon Labs Multiprotocol”.
-Under the Preferred network, I have clicked “Used for Android + iOS credentials”
My Home Assistant is connected to my network over WiFi, though I’ve also attempted to plug in using Ethernet with the same results. I’ve also confirmed my interfaces have IPv6 (under IP Information in Network settings). I’ve also tested that Matter over WiFi devices work, so the Matter Server seems OK. I don’t have any other Thread Border Routers (or devices) on my network.
I’ve attempted to add the devices using the Home Assistant app on both an iPhone X and iPhone 8, which typically give the “Thread Border Router Required” error, but occasionally I get an “Unable To Pair”, “Pairing Failed” error. I’ve also tried the WebSocket as described above using the Firefox console. Unfortunately, I always get the “Commission with code failed” error. All devices are physically within a couple feet of each other.
Some other things I tried:
I have an nRF52840 dongle, so I flashed that with the OpenThread RCP, and attempted to use it with the OpenThread Border Router Add-on, with the same results. As mentioned above, I’ve also tried that Add-on with the SkyConnect dongle.
I enabled the networking ports (8080 and 8081) and attempted to form a new thread network, etc. but again, made no difference.
I’ve tried a few different Thread devices to make sure I didn’t simply have a defective device, but all of them do the same thing.
I feel like I’m just banging my head on a wall at this point - does anyone see anything wrong in my current setup, or have ideas/thoughts on troubleshooting? Thanks!
1 Like
Maybe you get the “Commission with code failed” error because you dont have bluetooth on your raspi or the distance between your eve device and the raspi is too large.
Edit: Can you post your matter and/or thread log?
Thanks for the reply… I’m running a standard Raspberry Pi 4 4GB, which should have Bluetooth (it shows up under devices). I’ve also tried deleting the Bluetooth integration as was mentioned above, in case it somehow blocked access (which made no difference). It came back when I rebooted, so this most recent test had it enabled. All devices are all sitting next to each other on my desk (<1 ft. from each other), so nothing should be out of range.
Below are the logs following my attempt to manually add through the console. The common theme in these logs seems to be mDNS. Do you think that’s related, and any ideas on troubleshooting? Thanks!
Matter:
[1695918587.400953][125:125] CHIP:DL: ChipLinuxStorage::Init: Using KVS config file: /data/chip_config.ini
[1695918587.405835][125:125] CHIP:DL: ChipLinuxStorage::Init: Using KVS config file: /data/chip_counters.ini
[1695918587.408530][125:125] CHIP:DL: writing settings to file (/data/chip_counters.ini-pRvtkC)
[1695918587.414860][125:125] CHIP:DL: renamed tmp file to file (/data/chip_counters.ini)
[1695918587.414946][125:125] CHIP:DL: NVS set: chip-counters/reboot-count = 4 (0x4)
[1695918587.416358][125:125] CHIP:DL: Got Ethernet interface: eth0
[1695918587.416960][125:125] CHIP:DL: Found the primary Ethernet interface:eth0
[1695918587.417724][125:125] CHIP:DL: Got WiFi interface: wlan0
[1695918587.424020][125:125] CHIP:DL: Found the primary WiFi interface:wlan0
2023-09-28 12:29:47 core-matter-server PersistentStorage[125] WARNING Initializing persistent storage from file: /data/chip.json
2023-09-28 12:29:47 core-matter-server PersistentStorage[125] WARNING Loading configuration from /data/chip.json...
2023-09-28 12:29:47 core-matter-server PersistentStorage[125] INFO SetSdkKey: g/gcc = b'\xa0\x0f\x00\x00'
2023-09-28 12:29:47 core-matter-server PersistentStorage[125] INFO Committing...
2023-09-28 12:29:47 core-matter-server PersistentStorage[125] INFO SetSdkKey: g/gdc = b'\xa0\x0f\x00\x00'
2023-09-28 12:29:47 core-matter-server PersistentStorage[125] INFO Committing...
2023-09-28 12:29:47 core-matter-server chip.DL[125] ERROR MDNS failed to join multicast group on eth0 for address type IPv4: src/inet/UDPEndPointImplSockets.cpp:764: Inet Error 0x00000110: Address not found
2023-09-28 12:29:47 core-matter-server chip.DL[125] ERROR MDNS failed to join multicast group on vethdeec44d for address type IPv4: src/inet/UDPEndPointImplSockets.cpp:764: Inet Error 0x00000110: Address not found
2023-09-28 12:29:47 core-matter-server chip.DL[125] ERROR MDNS failed to join multicast group on veth2099766 for address type IPv4: src/inet/UDPEndPointImplSockets.cpp:764: Inet Error 0x00000110: Address not found
2023-09-28 12:29:47 core-matter-server chip.DL[125] ERROR MDNS failed to join multicast group on veth57c873e for address type IPv4: src/inet/UDPEndPointImplSockets.cpp:764: Inet Error 0x00000110: Address not found
2023-09-28 12:29:47 core-matter-server chip.DL[125] ERROR MDNS failed to join multicast group on vethf74de18 for address type IPv4: src/inet/UDPEndPointImplSockets.cpp:764: Inet Error 0x00000110: Address not found
2023-09-28 12:29:47 core-matter-server chip.DL[125] ERROR MDNS failed to join multicast group on veth2b3a0f8 for address type IPv4: src/inet/UDPEndPointImplSockets.cpp:764: Inet Error 0x00000110: Address not found
2023-09-28 12:29:47 core-matter-server chip.DL[125] ERROR MDNS failed to join multicast group on veth639bfcb for address type IPv4: src/inet/UDPEndPointImplSockets.cpp:764: Inet Error 0x00000110: Address not found
2023-09-28 12:29:47 core-matter-server CertificateAuthorityManager[125] WARNING Loading certificate authorities from storage...
2023-09-28 12:29:47 core-matter-server CertificateAuthority[125] WARNING New CertificateAuthority at index 1
2023-09-28 12:29:47 core-matter-server CertificateAuthority[125] WARNING Loading fabric admins from storage...
2023-09-28 12:29:47 core-matter-server FabricAdmin[125] WARNING New FabricAdmin: FabricId: 0x0000000000000002, VendorId = 0x134B
2023-09-28 12:29:47 core-matter-server PersistentStorage[125] INFO SetReplKey: caList = {'1': [{'fabricId': 2, 'vendorId': 4939}]}
2023-09-28 12:29:47 core-matter-server PersistentStorage[125] INFO Committing...
2023-09-28 12:29:47 core-matter-server matter_server.server.stack[125] INFO CHIP Controller Stack initialized.
2023-09-28 12:29:48 core-matter-server matter_server.server.server[125] INFO Starting the Matter Server...
2023-09-28 12:29:48 core-matter-server matter_server.server.helpers.paa_certificates[125] 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())
2023-09-28 12:29:57 core-matter-server matter_server.server.helpers.paa_certificates[125] INFO Fetched 108 PAA root certificates from DCL.
2023-09-28 12:29:57 core-matter-server matter_server.server.helpers.paa_certificates[125] INFO Fetching the latest PAA root certificates from Git.
2023-09-28 12:29:58 core-matter-server matter_server.server.helpers.paa_certificates[125] INFO Fetched 2 PAA root certificates from Git.
2023-09-28 12:29:58 core-matter-server FabricAdmin[125] WARNING Allocating new controller with CaIndex: 1, FabricId: 0x0000000000000002, NodeId: 0x000000000001B669, CatTags: []
2023-09-28 12:29:59 core-matter-server PersistentStorage[125] INFO SetSdkKey: g/fs/c = b'\x15$\x00\x01(\x01\x18'
2023-09-28 12:29:59 core-matter-server PersistentStorage[125] INFO Committing...
2023-09-28 12:29:59 core-matter-server PersistentStorage[125] INFO SetSdkKey: f/1/m = b'\x15%\x00K\x13,\x01\x00\x18'
2023-09-28 12:29:59 core-matter-server PersistentStorage[125] INFO Committing...
2023-09-28 12:29:59 core-matter-server PersistentStorage[125] 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\x042\xfeF\xe2\xb8\x17\xa6xL\x9c\x0e;\xa7\x9c\xb1H*\xd3\n\nM\x03\xbeD\xd7\xb1G/W\x07K[\x0b\x106\x0cA\xa3\xdbs\xea$\x1c\xc6Sd\x1a9\x9c\xc3\xd2\x9f\xd7\x0ba\x14\x1c\x13\xbaHT,m\xd07\n5\x01(\x01\x18$\x02\x016\x03\x04\x02\x04\x01\x180\x04\x14\xf2\x06\xa8\x859\x15\xfc*\xbaF\xcd\x8f\xa5\xed\xe6R\x11u\xad\xf50\x05\x14\xb2\r\x12[y+\x16$7\xac\x1e\xdf\t\x9f\xdb\x88\x13x9l\x180\x0b@f\xf1\x83g\xbf{\'\xb6\xa7\xf1\x1d\x8fF\x9a\xb1\x13\xfd\xa1\xbck\r?Q\xa94d\x9f\xba\xf5\x91\xcb:\xe0j\xb3\xf7\x1f\xd8\xe3-\xc9k\x9fA\x0e\x9f\xd2\xaf\x02\x975\x00\x85\x83\xe2\xd7dw\xe7\x8d*\xd9S\xae\x18'
2023-09-28 12:29:59 core-matter-server PersistentStorage[125] INFO Committing...
2023-09-28 12:29:59 core-matter-server PersistentStorage[125] 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\xf3\xf2\xef\x8c\x81_\xc3\xfb! l\xc6U\x11\x8c\x98%\xba\xe3M\x11\x99\xd0\x1d\xab\xe6\xb2%0#\xd6F\xd6\x92\xd1U\xad\t\x80\x94]\xcegpw~|\x16l2\x1d\xf9\x0f|F\xa6\x91\x1f\xf9\x0f\x1c\xda\xbf,7\n5\x01)\x01\x18$\x02`0\x04\x14\xb2\r\x12[y+\x16$7\xac\x1e\xdf\t\x9f\xdb\x88\x13x9l0\x05\x14\xf2\xf2\xe8\xbcrC\x9a\xb1\x88\t\x03u:\xf0AA\x90sl<\x180\x0b@y\xd8u\x9d\xb8\xd1\xef}\tp?\xc2\xb3\x15\x89\x84\xea#\x1a\x9e^\xf5\xe1^(\xce|\xf5^\xe2\x01\xda\xf1\xb4\xa5\x96\x8f\xcdVE\xb1\x97u\x0b\xd5B\xcc(\x8a\n\x1fy\x8b\x1fR\xb3\xbf\x16\xebp:\xbee\xa0\x18'
2023-09-28 12:29:59 core-matter-server PersistentStorage[125] INFO Committing...
2023-09-28 12:29:59 core-matter-server PersistentStorage[125] INFO SetSdkKey: g/lkgt = b'\x15&\x00\r\x80\x0c,\x18'
2023-09-28 12:29:59 core-matter-server PersistentStorage[125] INFO Committing...
2023-09-28 12:29:59 core-matter-server PersistentStorage[125] INFO DeleteSdkKey: g/fs/c
2023-09-28 12:29:59 core-matter-server PersistentStorage[125] INFO Committing...
2023-09-28 12:29:59 core-matter-server PersistentStorage[125] INFO SetSdkKey: f/1/k/0 = b'\x15$\x01\x00$\x02\x016\x03\x15$\x04\x00%\x05\x12\x8d0\x06\x10\xb1&\xe1\xe8\x1f3m\x86\x88\xb2\x88\xee\xf0\xdeD\x1d\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'
2023-09-28 12:29:59 core-matter-server PersistentStorage[125] INFO Committing...
2023-09-28 12:29:59 core-matter-server chip.DL[125] ERROR Long dispatch time: 144 ms, for event type 2
2023-09-28 12:29:59 core-matter-server matter_server.server.vendor_info[125] INFO Loading vendor info from storage.
2023-09-28 12:29:59 core-matter-server matter_server.server.vendor_info[125] INFO Loaded 100 vendors from storage.
2023-09-28 12:29:59 core-matter-server matter_server.server.vendor_info[125] INFO Fetching the latest vendor info from DCL.
2023-09-28 12:29:59 core-matter-server matter_server.server.vendor_info[125] INFO Fetched 100 vendors from DCL.
2023-09-28 12:29:59 core-matter-server matter_server.server.vendor_info[125] INFO Saving vendor info to storage.
2023-09-28 12:30:30 core-matter-server chip.DIS[125] ERROR Timeout waiting for mDNS resolution.
2023-09-28 12:30:44 core-matter-server chip.DIS[125] ERROR OperationalSessionSetup[1:0000000000000001]: operational discovery failed: src/lib/address_resolve/AddressResolve_DefaultImpl.cpp:114: CHIP Error 0x00000032: Timeout
2023-09-28 12:31:15 core-matter-server chip.DIS[125] ERROR Timeout waiting for mDNS resolution.
2023-09-28 12:31:29 core-matter-server chip.DIS[125] ERROR OperationalSessionSetup[1:0000000000000001]: operational discovery failed: src/lib/address_resolve/AddressResolve_DefaultImpl.cpp:114: CHIP Error 0x00000032: Timeout
2023-09-28 12:32:00 core-matter-server chip.DIS[125] ERROR Timeout waiting for mDNS resolution.
2023-09-28 12:32:14 core-matter-server chip.DIS[125] ERROR OperationalSessionSetup[1:0000000000000001]: operational discovery failed: src/lib/address_resolve/AddressResolve_DefaultImpl.cpp:114: CHIP Error 0x00000032: Timeout
2023-09-28 12:32:14 core-matter-server matter_server.server.device_controller[125] WARNING Unable to subscribe to Node 1 as it is unavailable, will retry later in the background.
2023-09-28 12:33:15 core-matter-server chip.DIS[125] ERROR Timeout waiting for mDNS resolution.
2023-09-28 12:33:29 core-matter-server chip.DIS[125] ERROR OperationalSessionSetup[1:0000000000000001]: operational discovery failed: src/lib/address_resolve/AddressResolve_DefaultImpl.cpp:114: CHIP Error 0x00000032: Timeout
2023-09-28 12:34:00 core-matter-server chip.DIS[125] ERROR Timeout waiting for mDNS resolution.
2023-09-28 12:34:14 core-matter-server chip.DIS[125] ERROR OperationalSessionSetup[1:0000000000000001]: operational discovery failed: src/lib/address_resolve/AddressResolve_DefaultImpl.cpp:114: CHIP Error 0x00000032: Timeout
2023-09-28 12:34:45 core-matter-server chip.DIS[125] ERROR Timeout waiting for mDNS resolution.
2023-09-28 12:34:59 core-matter-server chip.DIS[125] ERROR OperationalSessionSetup[1:0000000000000001]: operational discovery failed: src/lib/address_resolve/AddressResolve_DefaultImpl.cpp:114: CHIP Error 0x00000032: Timeout
2023-09-28 12:34:59 core-matter-server matter_server.server.device_controller[125] WARNING Unable to subscribe to Node 1 as it is unavailable, will retry later in the background.
2023-09-28 12:35:51 core-matter-server matter_server.server.helpers.paa_certificates[125] INFO Fetching the latest PAA root certificates from DCL.
2023-09-28 12:35:52 core-matter-server matter_server.server.helpers.paa_certificates[125] INFO Fetched 0 PAA root certificates from DCL.
2023-09-28 12:35:52 core-matter-server matter_server.server.helpers.paa_certificates[125] INFO Fetching the latest PAA root certificates from Git.
2023-09-28 12:35:52 core-matter-server matter_server.server.helpers.paa_certificates[125] INFO Fetched 0 PAA root certificates from Git.
2023-09-28 12:35:52 core-matter-server chip.DL[125] ERROR Long dispatch time: 102 ms, for event type 2
2023-09-28 12:36:02 core-matter-server chip.BLE[125] ERROR BLE scan error: src/platform/Linux/bluez/ChipDeviceScanner.cpp:154: CHIP Error 0x00000032: Timeout
2023-09-28 12:36:05 core-matter-server chip.DL[125] ERROR FAIL: ConnectDevice : Operation was cancelled (19)
2023-09-28 12:36:05 core-matter-server chip.CTL[125] ERROR Commissioning discovery over BLE failed: src/platform/Linux/bluez/Helper.cpp:1761: CHIP Error 0x000000AC: Internal error
2023-09-28 12:36:05 core-matter-server chip.-[125] ERROR src/platform/Linux/bluez/Helper.cpp:1761: CHIP Error 0x000000AC: Internal error at src/controller/SetUpCodePairer.cpp:299
2023-09-28 12:36:10 core-matter-server chip.DIS[125] ERROR Timeout waiting for mDNS resolution.
2023-09-28 12:36:22 core-matter-server chip.CTL[125] ERROR Discovery timed out
2023-09-28 12:36:22 core-matter-server chip.ZCL[125] ERROR Secure Pairing Failed
2023-09-28 12:36:22 core-matter-server matter_server.server.client_handler[125] ERROR [548147418192] Error handling message: CommandMessage(message_id='2', command='commission_with_code', args={'code': '24503012203'})
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 171, in commission_with_code
raise NodeCommissionFailed(
matter_server.common.errors.NodeCommissionFailed: Commission with code failed for node 33
2023-09-28 12:36:23 core-matter-server chip.DIS[125] ERROR Timeout waiting for mDNS resolution.
2023-09-28 12:36:24 core-matter-server chip.DIS[125] ERROR OperationalSessionSetup[1:0000000000000001]: operational discovery failed: src/lib/address_resolve/AddressResolve_DefaultImpl.cpp:114: CHIP Error 0x00000032: Timeout
2023-09-28 12:36:55 core-matter-server chip.DIS[125] ERROR Timeout waiting for mDNS resolution.
2023-09-28 12:37:09 core-matter-server chip.DIS[125] ERROR OperationalSessionSetup[1:0000000000000001]: operational discovery failed: src/lib/address_resolve/AddressResolve_DefaultImpl.cpp:114: CHIP Error 0x00000032: Timeout
2023-09-28 12:37:40 core-matter-server chip.DIS[125] ERROR Timeout waiting for mDNS resolution.
2023-09-28 12:37:54 core-matter-server chip.DIS[125] ERROR OperationalSessionSetup[1:0000000000000001]: operational discovery failed: src/lib/address_resolve/AddressResolve_DefaultImpl.cpp:114: CHIP Error 0x00000032: Timeout
2023-09-28 12:37:54 core-matter-server matter_server.server.device_controller[125] WARNING Unable to subscribe to Node 1 as it is unavailable, will retry later in the background.
2023-09-28 12:39:15 core-matter-server chip.DIS[125] ERROR Timeout waiting for mDNS resolution.
2023-09-28 12:39:29 core-matter-server chip.DIS[125] ERROR OperationalSessionSetup[1:0000000000000001]: operational discovery failed: src/lib/address_resolve/AddressResolve_DefaultImpl.cpp:114: CHIP Error 0x00000032: Timeout
OpenThread Border Router (Silicon Labs Multiprotocol):
2023-09-28 12:29:40 homeassistant universal_silabs_flasher.flash[187] INFO Extracted GBL metadata: NabuCasaMetadata(metadata_version=1, sdk_version='4.3.1', ezsp_version=None, ot_rcp_version=None, fw_type=<FirmwareImageType.RCP_UART_802154: 'rcp-uart-802154'>, baudrate=460800)
2023-09-28 12:29:40 homeassistant universal_silabs_flasher.flasher[187] INFO Probing ApplicationType.GECKO_BOOTLOADER at 115200 baud
2023-09-28 12:29:43 homeassistant universal_silabs_flasher.flasher[187] INFO Probing ApplicationType.CPC at 460800 baud
2023-09-28 12:29:43 homeassistant universal_silabs_flasher.flasher[187] INFO Detected ApplicationType.CPC, version '4.3.1' at 460800 baudrate (bootloader baudrate None)
2023-09-28 12:29:43 homeassistant universal_silabs_flasher.flash[187] INFO Firmware version '4.3.1' is flashed, not re-installing
s6-rc: info: service universal-silabs-flasher successfully started
s6-rc: info: service cpcd-config: starting
[12:29:46] INFO: Using known baudrate of 460800 for cpcd!
[12:29:47] INFO: Generating cpcd configuration.
s6-rc: info: service cpcd-config successfully started
s6-rc: info: service cpcd: starting
[12:29:49] INFO: Starting cpcd...
WARNING in function 'main' in file /usr/src/cpc-daemon/main.c at line #186 : Running CPCd as 'root' is not recommended. Proceed at your own risk.
s6-rc: info: service cpcd successfully started
s6-rc: info: service zigbeed: starting
s6-rc: info: service otbr-agent: starting
s6-rc: info: service zigbeed successfully started
[12:29:49:096408] Info : [CPCd v4.3.1.0] [Library API v3] [RCP Protocol v4]
[12:29:49:096589] Info : Git commit: 133b29678b3d0bc7578e098d2f46b4d5bcd2ebb4 / branch:
[12:29:49:096593] Info : Sources hash: ff8300587e7e4ab1def7a89a272c0baef32f9eb3bff9b0ba06b94e655d652367
[12:29:49:096601] WARNING : In function 'main' in file /usr/src/cpc-daemon/main.c at line #186 : Running CPCd as 'root' is not recommended. Proceed at your own risk.
[12:29:49:096635] Info : Reading cli arguments
[12:29:49:096644] Info : /usr/local/bin/cpcd
[12:29:49:101916] Info : Reading configuration
[12:29:49:101936] Info : file_path = /usr/local/etc/cpcd.conf
[12:29:49:101939] Info : instance_name = cpcd_0
[12:29:49:101941] Info : socket_folder = /dev/shm
[12:29:49:101943] Info : operation_mode = MODE_NORMAL
[12:29:49:101945] Info : use_encryption = false
[12:29:49:101947] Info : binding_key_file = /etc/binding-key.key
[12:29:49:101949] Info : stdout_tracing = false
[12:29:49:101951] Info : file_tracing = false
[12:29:49:101953] Info : lttng_tracing = false
[12:29:49:101955] Info : enable_frame_trace = false
[12:29:49:101957] Info : traces_folder = /dev/shm/cpcd-traces
[12:29:49:101959] Info : bus = UART
[12:29:49:101960] Info : uart_baudrate = 460800
[12:29:49:101963] Info : uart_hardflow = true
[12:29:49:101965] Info : uart_file = /dev/ttyUSB0
[12:29:49:101967] Info : fu_recovery_pins_enabled = false
[12:29:49:101971] Info : fu_connect_to_bootloader = false
[12:29:49:101973] Info : fu_enter_bootloader = false
[12:29:49:101975] Info : restart_cpcd = false
[12:29:49:101976] Info : application_version_validation = false
[12:29:49:101978] Info : print_secondary_versions_and_exit = false
[12:29:49:101980] Info : use_noop_keep_alive = false
[12:29:49:101982] Info : reset_sequence = true
[12:29:49:101983] Info : stats_interval = 0
[12:29:49:101985] Info : rlimit_nofile = 2000
[12:29:49:101987] Info : ENCRYPTION IS DISABLED
[12:29:49:101989] Info : Starting daemon in normal mode
[12:29:49:119761] Info : Connecting to Secondary...
[12:29:49:201056] Info : RX capability is 256 bytes
[12:29:49:201089] Info : Connected to Secondary
[12:29:49:204521] Info : Secondary Protocol v4
[12:29:49:211818] Info : Secondary CPC v4.3.1
[12:29:49:215781] Info : Secondary bus bitrate is 460800
[12:29:49:222933] Info : Secondary APP vUNDEFINED
[12:29:49:223217] Info : Daemon startup was successful. Waiting for client connections
[12:29:50] INFO: Starting zigbeed...
[12:29:51] INFO: Setup OTBR firewall...
[12:29:52] INFO: Starting otbr-agent...
[12:29:51:503277] Info : New client connection using library v4.3.1.0
[12:29:51:507751] Info : Opened connection socket for ep#12
[12:29:51:508449] Info : Endpoint socket #12: Client connected. 1 connections
otbr-agent[314]: [NOTE]-AGENT---: Running 0.3.0
otbr-agent[314]: [NOTE]-AGENT---: Thread version: 1.3.0
otbr-agent[314]: [NOTE]-AGENT---: Thread interface: wpan0
otbr-agent[314]: [NOTE]-AGENT---: Radio URL: spinel+cpc://cpcd_0?iid=2&iid-list=0
otbr-agent[314]: [NOTE]-ILS-----: Infra link selected: wlan0
otbr-agent[314]: 49d.17:06:53.421 [C] Platform------: mCpcBusSpeed = 115200
[12:29:52:205322] Info : New client connection using library v4.3.1.0
[12:29:52:209813] Info : Endpoint socket #12: Client connected. 2 connections
otbr-agent[314]: 00:00:00.172 [N] RoutingManager: BR ULA prefix: fd78:dd61:dfa4::/48 (loaded)
otbr-agent[314]: 00:00:00.172 [N] RoutingManager: Local on-link prefix: fd52:b8bb:c917:92a9::/64
otbr-agent[314]: 00:00:00.345 [N] Mle-----------: Role disabled -> detached
otbr-agent[314]: 00:00:00.450 [N] Platform------: [netif] Changing interface state to up.
s6-rc: info: service otbr-agent successfully started
s6-rc: info: service otbr-agent-rest-discovery: starting
Listening on port 9999 for connection...
Accepting connection.
[12:29:55] INFO: Successfully sent discovery information to Home Assistant.
s6-rc: info: service otbr-agent-rest-discovery successfully started
s6-rc: info: service legacy-services: starting
s6-rc: info: service legacy-services successfully started
otbr-agent[314]: 00:00:26.021 [N] Mle-----------: RLOC16 5800 -> fffe
otbr-agent[314]: 00:00:26.025 [W] Platform------: [netif] Failed to process request#5: Unknown error -95
otbr-agent[314]: 00:00:26.365 [N] Mle-----------: Attach attempt 1, AnyPartition reattaching with Active Dataset
otbr-agent[314]: 00:00:32.867 [N] RouterTable---: Allocate router id 22
otbr-agent[314]: 00:00:32.868 [N] Mle-----------: RLOC16 fffe -> 5800
otbr-agent[314]: 00:00:32.872 [N] Mle-----------: Role detached -> leader
otbr-agent[314]: 00:00:32.873 [N] Mle-----------: Partition ID 0x678ac244
otbr-agent[314]: 00:00:39.924 [W] Platform------: [netif] Failed to process request#6: Unknown error -17
otbr-agent[314]: [NOTE]-BBA-----: BackboneAgent: Backbone Router becomes Primary!
Default: mDNSPlatformSendUDP got error 99 (Cannot assign requested address) sending packet to ff02::fb on interface fe80::702f:3fff:fed5:deb4/veth7b6fec1/20
Default: mDNSPlatformSendUDP got error 99 (Cannot assign requested address) sending packet to ff02::fb on interface fe80::702f:3fff:fed5:deb4/veth7b6fec1/20
Default: mDNSPlatformSendUDP got error 99 (Cannot assign requested address) sending packet to ff02::fb on interface fe80::702f:3fff:fed5:deb4/veth7b6fec1/20
Default: mDNSPlatformSendUDP got error 99 (Cannot assign requested address) sending packet to ff02::fb on interface fe80::702f:3fff:fed5:deb4/veth7b6fec1/20
Default: mDNSPlatformSendUDP got error 99 (Cannot assign requested address) sending packet to ff02::fb on interface fe80::702f:3fff:fed5:deb4/veth7b6fec1/20
Default: mDNSPlatformSendUDP got error 99 (Cannot assign requested address) sending packet to ff02::fb on interface fe80::702f:3fff:fed5:deb4/veth7b6fec1/20
1 Like
I will now post both my matter and seliconlab multiprotocol logs after a fresh restart.
Matter Server Log:
- “ERROR MDNS failed to join multicast group on …” error is not a problem, it is normal
- “core-matter-server PersistentStorage[125] INFO Committing…” everything until this line is normal, except that i have a 125 and you a 126.
- I dont have the “2023-09-28 12:29:59 core-matter-server chip.DL[125] ERROR Long dispatch time: 144 ms, for event type 2” error
- “2023-09-28 20:19:02 core-matter-server chip.DIS[126] ERROR Timeout waiting for mDNS resolution.” is also ok, it should be no problem
- “2023-09-28 20:19:16 core-matter-server chip.DIS[126] ERROR OperationalSessionSetup[1:0000000000000009]: operational discovery failed: src/lib/address_resolve/AddressResolve_DefaultImpl.cpp:114: CHIP Error 0x00000032: Timeout” another error, but no problem
- side note: “2023-09-28 20:19:55 core-matter-server matter_server.server.device_controller.[node 9][126] INFO Subscription succeeded” Now my eve device is available. After restarting homeassistant i have to wait 5 minutes to use my eve device.
From your matter log i can only gues two problems:
“2023-09-28 12:35:52 core-matter-server chip.DL[125] ERROR Long dispatch time: 102 ms, for event type 2” I dont know what this means. Question: Did this error appear before or after starting the commission?
“2023-09-28 12:36:02 core-matter-server chip.BLE[125] ERROR BLE scan error: src/platform/Linux/bluez/ChipDeviceScanner.cpp:154: CHIP Error 0x00000032: Timeout” BLE stands for bluetooth low energy. Maybe your bluetooth is really not working. Or the bluetooth of your eve device is not answering. Maybe reset the eve device. I tried to reproduce this error by commising an eve device which is out of the bluetooth range of my homeassistant. I think, i can reproduce this error.
[1695924935.767662][126:126] CHIP:CTL: Setting CSR nonce to random value
[1695924935.781874][126:126] CHIP:DL: ChipLinuxStorage::Init: Using KVS config file: /tmp/chip_kvs
[1695924935.782170][126:126] CHIP:DL: writing settings to file (/tmp/chip_kvs-sOxDHH)
[1695924935.782257][126:126] CHIP:DL: renamed tmp file to file (/tmp/chip_kvs)
[1695924935.782504][126:126] CHIP:DL: ChipLinuxStorage::Init: Using KVS config file: /data/chip_factory.ini
[1695924935.784161][126:126] CHIP:DL: ChipLinuxStorage::Init: Using KVS config file: /data/chip_config.ini
[1695924935.784659][126:126] CHIP:DL: ChipLinuxStorage::Init: Using KVS config file: /data/chip_counters.ini
[1695924935.785710][126:126] CHIP:DL: writing settings to file (/data/chip_counters.ini-QHXnTK)
[1695924935.786033][126:126] CHIP:DL: renamed tmp file to file (/data/chip_counters.ini)
[1695924935.786061][126:126] CHIP:DL: NVS set: chip-counters/reboot-count = 74 (0x4A)
[1695924935.786580][126:126] CHIP:DL: Got Ethernet interface: enp0s18
[1695924935.786846][126:126] CHIP:DL: Found the primary Ethernet interface:enp0s18
[1695924935.787355][126:126] CHIP:DL: Failed to get WiFi interface
[1695924935.787369][126:126] CHIP:DL: Failed to reset WiFi statistic counts
2023-09-28 20:15:35 core-matter-server PersistentStorage[126] WARNING Initializing persistent storage from file: /data/chip.json
2023-09-28 20:15:35 core-matter-server PersistentStorage[126] WARNING Loading configuration from /data/chip.json...
2023-09-28 20:15:35 core-matter-server PersistentStorage[126] INFO SetSdkKey: g/gcc = b'\x10!\x01\x00'
2023-09-28 20:15:35 core-matter-server PersistentStorage[126] INFO Committing...
2023-09-28 20:15:35 core-matter-server PersistentStorage[126] INFO SetSdkKey: g/gdc = b'\x10!\x01\x00'
2023-09-28 20:15:35 core-matter-server PersistentStorage[126] INFO Committing...
2023-09-28 20:15:35 core-matter-server chip.DL[126] ERROR MDNS failed to join multicast group on veth5774fb1 for address type IPv4: src/inet/UDPEndPointImplSockets.cpp:764: Inet Error 0x00000110: Address not found
2023-09-28 20:15:35 core-matter-server chip.DL[126] ERROR MDNS failed to join multicast group on veth3b5ffce for address type IPv4: src/inet/UDPEndPointImplSockets.cpp:764: Inet Error 0x00000110: Address not found
2023-09-28 20:15:35 core-matter-server chip.DL[126] ERROR MDNS failed to join multicast group on veth56df2fa for address type IPv4: src/inet/UDPEndPointImplSockets.cpp:764: Inet Error 0x00000110: Address not found
2023-09-28 20:15:35 core-matter-server chip.DL[126] ERROR MDNS failed to join multicast group on veth1c7458d for address type IPv4: src/inet/UDPEndPointImplSockets.cpp:764: Inet Error 0x00000110: Address not found
2023-09-28 20:15:35 core-matter-server chip.DL[126] ERROR MDNS failed to join multicast group on veth222a52a for address type IPv4: src/inet/UDPEndPointImplSockets.cpp:764: Inet Error 0x00000110: Address not found
2023-09-28 20:15:35 core-matter-server chip.DL[126] ERROR MDNS failed to join multicast group on veth19867e5 for address type IPv4: src/inet/UDPEndPointImplSockets.cpp:764: Inet Error 0x00000110: Address not found
2023-09-28 20:15:35 core-matter-server CertificateAuthorityManager[126] WARNING Loading certificate authorities from storage...
2023-09-28 20:15:35 core-matter-server CertificateAuthority[126] WARNING New CertificateAuthority at index 1
2023-09-28 20:15:35 core-matter-server CertificateAuthority[126] WARNING Loading fabric admins from storage...
2023-09-28 20:15:35 core-matter-server FabricAdmin[126] WARNING New FabricAdmin: FabricId: 0x0000000000000002, VendorId = 0x134B
2023-09-28 20:15:35 core-matter-server PersistentStorage[126] INFO SetReplKey: caList = {'1': [{'fabricId': 2, 'vendorId': 4939}]}
2023-09-28 20:15:35 core-matter-server PersistentStorage[126] INFO Committing...
2023-09-28 20:15:35 core-matter-server matter_server.server.stack[126] INFO CHIP Controller Stack initialized.
2023-09-28 20:15:35 core-matter-server matter_server.server.server[126] INFO Starting the Matter Server...
2023-09-28 20:15:35 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())
2023-09-28 20:15:45 core-matter-server matter_server.server.helpers.paa_certificates[126] INFO Fetched 108 PAA root certificates from DCL.
2023-09-28 20:15:45 core-matter-server matter_server.server.helpers.paa_certificates[126] INFO Fetching the latest PAA root certificates from Git.
2023-09-28 20:15:45 core-matter-server matter_server.server.helpers.paa_certificates[126] INFO Fetched 2 PAA root certificates from Git.
2023-09-28 20:15:45 core-matter-server FabricAdmin[126] WARNING Allocating new controller with CaIndex: 1, FabricId: 0x0000000000000002, NodeId: 0x000000000001B669, CatTags: []
2023-09-28 20:15:45 core-matter-server PersistentStorage[126] INFO DeleteSdkKey: g/s/gt+LrNz9jw7LBBPTsc4sIg==
2023-09-28 20:15:45 core-matter-server PersistentStorage[126] INFO Committing...
2023-09-28 20:15:45 core-matter-server PersistentStorage[126] INFO DeleteSdkKey: f/1/s/0000000000000009
2023-09-28 20:15:45 core-matter-server PersistentStorage[126] INFO Committing...
2023-09-28 20:15:45 core-matter-server PersistentStorage[126] INFO SetSdkKey: g/sri = b'\x16\x18'
2023-09-28 20:15:45 core-matter-server PersistentStorage[126] INFO Committing...
2023-09-28 20:15:45 core-matter-server PersistentStorage[126] INFO SetSdkKey: g/fs/c = b'\x15$\x00\x01(\x01\x18'
2023-09-28 20:15:45 core-matter-server PersistentStorage[126] INFO Committing...
2023-09-28 20:15:45 core-matter-server PersistentStorage[126] INFO SetSdkKey: f/1/m = b'\x15%\x00K\x13,\x01\x00\x18'
2023-09-28 20:15:45 core-matter-server PersistentStorage[126] INFO Committing...
2023-09-28 20:15:45 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`\x08#w/\x82\xafL\xe2\xc0sJ\x9a\xbe~\xec\xf9\x8db\xd6\xc7\xc64\xcayv\xca\x00+M\x17\x07\xbcM\x8eWJ\xffo=d\xd3\xe7\x10\'\t:\xb2s\xd8\xa3\x0e<|\x9f\xb2\xbd\x8e\x8f\x05z\x8fh\x9b7\n5\x01(\x01\x18$\x02\x016\x03\x04\x02\x04\x01\x180\x04\x14%#\x1d\x06y\xa6\xb9\x98+2\xb0gJ\x83"|\xb0y`\xed0\x05\x14\xf4\xa9%\x940d\x1b\xeeN%\x07\xa3\x1cZ\x88,\xe8~\x1e"\x180\x0b@\x1d\xb3\xa0$\x9d62^\x13\xc4\x19\xe1\x89\x1f\x9d\xb5(@j\xda\xd1<R\xba\x9d\x7f\x8a\x98\xda\x87\xa5.\x11\xf4\xe5\xd5\x82\xbaG\xb4\xc8B@\xacB^\nv\xb1\xe2\xcd,\x0e\xfa\xd4\x84\xb0\x87\x92\xf3Bo\x1a\x1f\x18'
2023-09-28 20:15:45 core-matter-server PersistentStorage[126] INFO Committing...
2023-09-28 20:15:45 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\x9c\xfd\xe9\x83O\xb3YWmB\xb98E\x88\xbe\xc4p\x00\xa6\xaa\xaft\x08^\x8ah\xe8\xf4\x16\x05\x8f^u\xe6\xc8\x94\xa3\xaa\xf3Y\xb3=\x8a\xb2\x86B\xe0\xb3R\xd0X\xed\xfc7\xa7M\\\x0c\xc9\x84Q\t\x1aM7\n5\x01)\x01\x18$\x02`0\x04\x14\xf4\xa9%\x940d\x1b\xeeN%\x07\xa3\x1cZ\x88,\xe8~\x1e"0\x05\x14\x84\x15\x0b\xd7Hw\xaf\x9db$6^\x04\x91\x0fe/\xde6\xe3\x180\x0b@\x0f\xa8\x14!\x18\xa8a\xe4\xdd\xf9%\x17 d\xce\xe8\xf2D\x9b+\xe4\xfe\xa4\x89\x9ca1Xc\xa2\xf5O\xd98F\xa4\xda\x9fS\xa9@\xa6P-\xc8\xbdA\xef\xa7p\xea`c_\x866R\x7fl\x12\xb6C\xdb%\x18'
2023-09-28 20:15:45 core-matter-server PersistentStorage[126] INFO Committing...
2023-09-28 20:15:45 core-matter-server PersistentStorage[126] INFO SetSdkKey: g/lkgt = b'\x15&\x00\xd8\x7f\x0c,\x18'
2023-09-28 20:15:45 core-matter-server PersistentStorage[126] INFO Committing...
2023-09-28 20:15:45 core-matter-server PersistentStorage[126] INFO DeleteSdkKey: g/fs/c
2023-09-28 20:15:45 core-matter-server PersistentStorage[126] INFO Committing...
2023-09-28 20:15:45 core-matter-server PersistentStorage[126] INFO SetSdkKey: f/1/k/0 = b'\x15$\x01\x00$\x02\x016\x03\x15$\x04\x00%\x05\xfen0\x06\x10\n\xd4\x1cQ\xf3\xa1`\x91\x9c!\xad\x86\xac;\xf0\xd8\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'
2023-09-28 20:15:45 core-matter-server PersistentStorage[126] INFO Committing...
2023-09-28 20:15:45 core-matter-server matter_server.server.vendor_info[126] INFO Loading vendor info from storage.
2023-09-28 20:15:45 core-matter-server matter_server.server.vendor_info[126] INFO Loaded 102 vendors from storage.
2023-09-28 20:15:45 core-matter-server matter_server.server.vendor_info[126] INFO Fetching the latest vendor info from DCL.
2023-09-28 20:15:46 core-matter-server matter_server.server.vendor_info[126] INFO Fetched 100 vendors from DCL.
2023-09-28 20:15:46 core-matter-server matter_server.server.vendor_info[126] INFO Saving vendor info to storage.
2023-09-28 20:16:16 core-matter-server chip.DIS[126] ERROR Timeout waiting for mDNS resolution.
2023-09-28 20:16:30 core-matter-server chip.DIS[126] ERROR OperationalSessionSetup[1:0000000000000009]: operational discovery failed: src/lib/address_resolve/AddressResolve_DefaultImpl.cpp:114: CHIP Error 0x00000032: Timeout
2023-09-28 20:17:01 core-matter-server chip.DIS[126] ERROR Timeout waiting for mDNS resolution.
2023-09-28 20:17:15 core-matter-server chip.DIS[126] ERROR OperationalSessionSetup[1:0000000000000009]: operational discovery failed: src/lib/address_resolve/AddressResolve_DefaultImpl.cpp:114: CHIP Error 0x00000032: Timeout
2023-09-28 20:17:47 core-matter-server chip.DIS[126] ERROR Timeout waiting for mDNS resolution.
2023-09-28 20:18:00 core-matter-server chip.DIS[126] ERROR OperationalSessionSetup[1:0000000000000009]: operational discovery failed: src/lib/address_resolve/AddressResolve_DefaultImpl.cpp:114: CHIP Error 0x00000032: Timeout
2023-09-28 20:18:00 core-matter-server matter_server.server.device_controller[126] WARNING Unable to interview Node 9, will retry later in the background.
2023-09-28 20:19:02 core-matter-server chip.DIS[126] ERROR Timeout waiting for mDNS resolution.
2023-09-28 20:19:16 core-matter-server chip.DIS[126] ERROR OperationalSessionSetup[1:0000000000000009]: operational discovery failed: src/lib/address_resolve/AddressResolve_DefaultImpl.cpp:114: CHIP Error 0x00000032: Timeout
2023-09-28 20:19:38 core-matter-server PersistentStorage[126] INFO SetSdkKey: f/1/s/0000000000000009 = b'\x150\x03\x10\x94DV@\x84-\x87u\xe8\xe8#\x1b\x1bdA\xf80\x04 \xc2#\x12?@"\x01\x87\xf1\xe2X\xaf>+\xff\x19\xa9\x86\x1e\r\xa5\xa2\x9d[\xa3,\xed>\x87\xfb\xf5v0\x05\x0c\x00\x00\x00\x00\x00\x00\x00\x00\x00\x00\x00\x00\x18'
2023-09-28 20:19:38 core-matter-server PersistentStorage[126] INFO Committing...
2023-09-28 20:19:38 core-matter-server PersistentStorage[126] INFO SetSdkKey: g/s/lERWQIQth3Xo6CMbG2RB+A== = b'\x15$\x01\x01$\x02\t\x18'
2023-09-28 20:19:38 core-matter-server PersistentStorage[126] INFO Committing...
2023-09-28 20:19:38 core-matter-server PersistentStorage[126] INFO SetSdkKey: g/sri = b'\x16\x15$\x01\x01$\x02\t\x18\x18'
2023-09-28 20:19:38 core-matter-server PersistentStorage[126] INFO Committing...
2023-09-28 20:19:55 core-matter-server matter_server.server.device_controller.[node 9][126] INFO Subscription succeeded
Waiting some minutes. And starting commision with device out of range.
2023-09-28 20:36:30 core-matter-server matter_server.server.helpers.paa_certificates[126] INFO Fetching the latest PAA root certificates from DCL.
2023-09-28 20:36:30 core-matter-server matter_server.server.helpers.paa_certificates[126] INFO Fetched 0 PAA root certificates from DCL.
2023-09-28 20:36:30 core-matter-server matter_server.server.helpers.paa_certificates[126] INFO Fetching the latest PAA root certificates from Git.
2023-09-28 20:36:30 core-matter-server matter_server.server.helpers.paa_certificates[126] INFO Fetched 0 PAA root certificates from Git.
2023-09-28 20:36:40 core-matter-server chip.BLE[126] ERROR BLE scan error: src/platform/Linux/bluez/ChipDeviceScanner.cpp:154: CHIP Error 0x00000032: Timeout
2023-09-28 20:37:00 core-matter-server chip.CTL[126] ERROR Discovery timed out
2023-09-28 20:37:00 core-matter-server chip.BLE[126] ERROR BleConnectionDelegate::CancelConnection is not implemented.
2023-09-28 20:37:00 core-matter-server chip.-[126] ERROR src/platform/Linux/BLEManagerImpl.cpp:732: CHIP Error 0x0000002D: Not Implemented at src/controller/SetUpCodePairer.cpp:551
2023-09-28 20:37:00 core-matter-server chip.ZCL[126] ERROR Secure Pairing Failed
2023-09-28 20:37:00 core-matter-server matter_server.server.client_handler[126] ERROR [140545453361360] Error handling message: CommandMessage(message_id='2', command='commission_with_code', args={'code': '33976113343'})
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 171, in commission_with_code
raise NodeCommissionFailed(
matter_server.common.errors.NodeCommissionFailed: Commission with code failed for node 19
2023-09-28 20:37:01 core-matter-server chip.DIS[126] ERROR Timeout waiting for mDNS resolution.
O
O
My Silicon Labs Multiprotocol Log.
2023-09-28 20:15:36 homeassistant universal_silabs_flasher.flasher[186] INFO Probing ApplicationType.CPC at 460800 baud
2023-09-28 20:15:36 homeassistant universal_silabs_flasher.flasher[186] INFO Detected ApplicationType.CPC, version '4.3.1' at 460800 baudrate (bootloader baudrate None)
2023-09-28 20:15:36 homeassistant universal_silabs_flasher.flash[186] INFO Firmware version '4.3.1' is flashed, not re-installing
s6-rc: info: service universal-silabs-flasher successfully started
s6-rc: info: service cpcd-config: starting
[20:15:37] INFO: Using known baudrate of 460800 for cpcd!
[20:15:37] INFO: Generating cpcd configuration.
s6-rc: info: service cpcd-config successfully started
s6-rc: info: service cpcd: starting
[20:15:37] INFO: Starting cpcd...
WARNING in function 'main' in file /usr/src/cpc-daemon/main.c at line #186 : Running CPCd as 'root' is not recommended. Proceed at your own risk.
s6-rc: info: service cpcd successfully started
s6-rc: info: service zigbeed: starting
s6-rc: info: service otbr-agent: starting
s6-rc: info: service zigbeed successfully started
[20:15:37] INFO: Starting zigbeed...
[20:15:37] INFO: Setup OTBR firewall...
[20:15:37] INFO: Starting otbr-agent...
otbr-agent[305]: [NOTE]-AGENT---: Running 0.3.0
otbr-agent[305]: [NOTE]-AGENT---: Thread version: 1.3.0
otbr-agent[305]: [NOTE]-AGENT---: Thread interface: wpan0
otbr-agent[305]: [NOTE]-AGENT---: Radio URL: spinel+cpc://cpcd_0?iid=2&iid-list=0
otbr-agent[305]: [NOTE]-ILS-----: Infra link selected: enp0s18
otbr-agent[305]: 49d.17:03:11.069 [C] Platform------: mCpcBusSpeed = 115200
[20:15:37:368086] Info : [CPCd v4.3.1.0] [Library API v3] [RCP Protocol v4]
[20:15:37:368142] Info : Git commit: 133b29678b3d0bc7578e098d2f46b4d5bcd2ebb4 / branch:
[20:15:37:368143] Info : Sources hash: ff8300587e7e4ab1def7a89a272c0baef32f9eb3bff9b0ba06b94e655d652367
[20:15:37:368146] WARNING : In function 'main' in file /usr/src/cpc-daemon/main.c at line #186 : Running CPCd as 'root' is not recommended. Proceed at your own risk.
[20:15:37:368166] Info : Reading cli arguments
[20:15:37:368170] Info : /usr/local/bin/cpcd
[20:15:37:369926] Info : Reading configuration
[20:15:37:369932] Info : file_path = /usr/local/etc/cpcd.conf
[20:15:37:369933] Info : instance_name = cpcd_0
[20:15:37:369934] Info : socket_folder = /dev/shm
[20:15:37:369935] Info : operation_mode = MODE_NORMAL
[20:15:37:369935] Info : use_encryption = false
[20:15:37:369936] Info : binding_key_file = /etc/binding-key.key
[20:15:37:369936] Info : stdout_tracing = false
[20:15:37:369937] Info : file_tracing = false
[20:15:37:369938] Info : lttng_tracing = false
[20:15:37:369938] Info : enable_frame_trace = false
[20:15:37:369939] Info : traces_folder = /dev/shm/cpcd-traces
[20:15:37:369939] Info : bus = UART
[20:15:37:369940] Info : uart_baudrate = 460800
[20:15:37:369940] Info : uart_hardflow = true
[20:15:37:369941] Info : uart_file = /dev/ttyUSB0
[20:15:37:369942] Info : fu_recovery_pins_enabled = false
[20:15:37:369942] Info : fu_connect_to_bootloader = false
[20:15:37:369943] Info : fu_enter_bootloader = false
[20:15:37:369943] Info : restart_cpcd = false
[20:15:37:369944] Info : application_version_validation = false
[20:15:37:369944] Info : print_secondary_versions_and_exit = false
[20:15:37:369945] Info : use_noop_keep_alive = false
[20:15:37:369946] Info : reset_sequence = true
[20:15:37:369946] Info : stats_interval = 0
[20:15:37:369947] Info : rlimit_nofile = 2000
[20:15:37:369947] Info : ENCRYPTION IS DISABLED
[20:15:37:369960] Info : Starting daemon in normal mode
[20:15:37:382128] Info : Connecting to Secondary...
[20:15:37:463572] Info : RX capability is 256 bytes
[20:15:37:463587] Info : Connected to Secondary
[20:15:37:467030] Info : Secondary Protocol v4
[20:15:37:474024] Info : Secondary CPC v4.3.1
[20:15:37:477461] Info : Secondary bus bitrate is 460800
[20:15:37:484596] Info : Secondary APP vUNDEFINED
[20:15:37:484667] Info : Daemon startup was successful. Waiting for client connections
[20:15:38:010191] Info : New client connection using library v4.3.1.0
[20:15:38:013937] Info : Opened connection socket for ep#12
[20:15:38:014003] Info : Endpoint socket #12: Client connected. 1 connections
[20:15:38:795737] Info : New client connection using library v4.3.1.0
[20:15:38:799852] Info : Endpoint socket #12: Client connected. 2 connections
otbr-agent[305]: 00:00:00.118 [N] RoutingManager: BR ULA prefix: fde7:c1df:f22e::/48 (loaded)
otbr-agent[305]: 00:00:00.119 [N] RoutingManager: Local on-link prefix: fd23:890f:d24a:fb3d::/64
otbr-agent[305]: 00:00:00.145 [N] Mle-----------: Role disabled -> detached
otbr-agent[305]: 00:00:00.152 [N] Platform------: [netif] Changing interface state to up.
s6-rc: info: service otbr-agent successfully started
s6-rc: info: service otbr-agent-rest-discovery: starting
[20:15:40] INFO: Successfully sent discovery information to Home Assistant.
s6-rc: info: service otbr-agent-rest-discovery successfully started
s6-rc: info: service legacy-services: starting
s6-rc: info: service legacy-services successfully started
Listening on port 9999 for connection...
Accepting connection.
Accepted connection 7.
Default: mDNSPlatformSendUDP got error 99 (Cannot assign requested address) sending packet to ff02::fb on interface fe80::7044:2eff:fe9c:56dc/veth083da0c/19
otbr-agent[305]: 00:00:25.813 [N] Mle-----------: RLOC16 3400 -> fffe
otbr-agent[305]: 00:00:25.817 [W] Platform------: [netif] Failed to process request#5: Unknown error -95
Default: mDNSPlatformSendUDP got error 99 (Cannot assign requested address) sending packet to ff02::fb on interface fe80::7044:2eff:fe9c:56dc/veth083da0c/19
Default: mDNSPlatformSendUDP got error 99 (Cannot assign requested address) sending packet to ff02::fb on interface fe80::7044:2eff:fe9c:56dc/veth083da0c/19
Default: mDNSPlatformSendUDP got error 99 (Cannot assign requested address) sending packet to ff02::fb on interface fe80::7044:2eff:fe9c:56dc/veth083da0c/19
Default: mDNSPlatformSendUDP got error 99 (Cannot assign requested address) sending packet to ff02::fb on interface fe80::7044:2eff:fe9c:56dc/veth083da0c/19
otbr-agent[305]: 00:00:26.565 [N] Mle-----------: Attach attempt 1, AnyPartition reattaching with Active Dataset
Default: mDNSPlatformSendUDP got error 99 (Cannot assign requested address) sending packet to ff02::fb on interface fe80::7044:2eff:fe9c:56dc/veth083da0c/19
otbr-agent[305]: 00:00:33.065 [N] RouterTable---: Allocate router id 13
otbr-agent[305]: 00:00:33.065 [N] Mle-----------: RLOC16 fffe -> 3400
otbr-agent[305]: 00:00:33.069 [N] Mle-----------: Role detached -> leader
otbr-agent[305]: 00:00:33.070 [N] Mle-----------: Partition ID 0x1b14bf9
otbr-agent[305]: 00:00:33.084 [W] Platform------: [netif] Failed to process request#6: Unknown error -17
otbr-agent[305]: [NOTE]-BBA-----: BackboneAgent: Backbone Router becomes Primary!
otbr-agent[305]: 00:00:34.754 [W] Mle-----------: Failed to process Child ID Request: Security
Thanks for looking at this, and comparing logs. I figured maybe I broke something in all the changes I made, so I decided to start from scratch, only setting up the multiprotocol add-on and Matter… but ended up with the exact same results.
I then tried the generic x86-64 image on an older laptop I had laying around, and it worked on the first try (using the WebSocket… iPhone app QR code scanning still didn’t work - maybe someone could make a MatterAdder Add-on to make the WebSocket process more convenient? 
). So, it seems my Thread device and SkyConnect dongle work fine. That helped regain some sanity.
After that, I decided to quickly revisit the RPi… I plugged a USB Bluetooth dongle in and disabled the onboard Bluetooth device in HA, but that didn’t seem to make any difference. Though I’m not sure if the Matter add-on would know to switch to the other. FWIW, it seems like both Bluetooth devices were working, based on the device list returned when I ran “bluetoothctl devices” at the terminal.
BTW, I saw this issue on Github: Onboard Bluetooth not working in HA 2023.8 · Issue #98461 · home-assistant/core · GitHub , not sure if it’s at all related.
Anyway, I think I’m giving up on using the RPi for now, and will just move forward with the Intel version. Thanks for the help, and good luck to anyone else running into this issue.
Hello!
So, it worked! I bought a 8 EUR BT dongle and connected it to my Home Assistant Yellow. Then went through the steps you described using the websocket, dataset, and pairing code. And after a few seconds the Eve Motion popped up in the Matter integration in HA.
This is unrelated, but the integrated luminosity sensor doesn’t seem to be reporting correct values. it’s daylight and toggling between 1.0 and 1.2 or 1.4 lux… any ideas?
Thanks again for your help and patience!
Best regards,
Andrew
My Illuminance value is also weird. Always 1 or none. Dont know why. Battery and occupancy are working.
huh. that’s too bad - I was primarily interested in measuring luminance outdoors… ah well.
Oh thank you so much for the exact code to add a matter device, I’ve just successfully paired a Nanoleaf Essentials A19 Matter bulb to the thread network provided by HA Open Thread Border Router (via SkyConnect).
Interestingly I was able to pair it close to the HA running on a raspi with deactivated wifi on the raspi, after moving it to it’s final destination (far away from the HA but near a thread router) HA didn’t find it, the matter server log mentioned it’s failing to broadcast mDNS on wlan0, so I reenabled wifi on the raspi (I prefer to have it turned off, as the raspi gives preference to wifi over ethernet and I’d want it to use the ethernet connection).
I have tried ALL of the steps you did and got the same result, I can’t add my Nanoleaf essential matter smart bulb in any way
Hi,
I’m tring to send the websocket message but server response 405 Method not Allowed
I send the request as POST, I have tried also PUT
Do I miss something ?
Thanks
Could you please attach two screenshots, one with the request and one with the error?
I have tried in any way possibile, with external bluetooth, internal one, with added and not added to HA (I’m using a pi4) and also with my iPhone. I can’t make it work 
2023-10-25 22:52:37 core-matter-server chip.DL[126] ERROR Long dispatch time: 129 ms, for event type 2
2023-10-25 22:52:37 core-matter-server matter_server.server.vendor_info[126] INFO Loading vendor info from storage.
2023-10-25 22:52:37 core-matter-server matter_server.server.vendor_info[126] INFO Loaded 100 vendors from storage.
2023-10-25 22:52:37 core-matter-server matter_server.server.vendor_info[126] INFO Fetching the latest vendor info from DCL.
2023-10-25 22:52:37 core-matter-server matter_server.server.vendor_info[126] INFO Fetched 100 vendors from DCL.
2023-10-25 22:52:37 core-matter-server matter_server.server.vendor_info[126] INFO Saving vendor info to storage.
2023-10-25 23:23:30 core-matter-server matter_server.server.helpers.paa_certificates[126] INFO Fetching the latest PAA root certificates from DCL.
2023-10-25 23:23:31 core-matter-server matter_server.server.helpers.paa_certificates[126] INFO Fetched 0 PAA root certificates from DCL.
2023-10-25 23:23:31 core-matter-server matter_server.server.helpers.paa_certificates[126] INFO Fetching the latest PAA root certificates from Git.
2023-10-25 23:23:31 core-matter-server matter_server.server.helpers.paa_certificates[126] INFO Fetched 0 PAA root certificates from Git.
2023-10-25 23:23:31 core-matter-server chip.DL[126] ERROR Long dispatch time: 108 ms, for event type 2
2023-10-25 23:23:41 core-matter-server chip.BLE[126] ERROR BLE scan error: src/platform/Linux/bluez/ChipDeviceScanner.cpp:154: CHIP Error 0x00000032: Timeout
2023-10-25 23:24:01 core-matter-server chip.CTL[126] ERROR Discovery timed out
2023-10-25 23:24:01 core-matter-server chip.BLE[126] ERROR BleConnectionDelegate::CancelConnection is not implemented.
2023-10-25 23:24:01 core-matter-server chip.-[126] ERROR src/platform/Linux/BLEManagerImpl.cpp:732: CHIP Error 0x0000002D: Not Implemented at src/controller/SetUpCodePairer.cpp:551
2023-10-25 23:24:01 core-matter-server chip.ZCL[126] ERROR Secure Pairing Failed
2023-10-25 23:24:01 core-matter-server matter_server.server.client_handler[126] ERROR [548384221968] Error handling message: CommandMessage(message_id='1', command='commission_with_code', args={'code': 'CENSOR'})
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 171, in commission_with_code
raise NodeCommissionFailed(
matter_server.common.errors.NodeCommissionFailed: Commission with code failed for node 13
2023-10-25 23:24:02 core-matter-server chip.DIS[126] ERROR Timeout waiting for mDNS resolution.
2023-10-25 23:23:31 core-matter-server chip.DL[126] ERROR Long dispatch time: 108 ms, for event type 2
We have a bluetooth problem (BLE = Bluetooth Low Energy). Do you have a raspi with bluetooth?
Yes, I have a raspberry pi4 with bluetooth (it also works since I can see my bluetooth toothbrush)
I also tried with a bluetooth usb stick
Some other ideas:
- Install fresh homeassistant on another device (e.g. old laptop) and try it there
- The error could als mean, that the commission code is wrong or the thread device is out of range
- Did you got the “Message from server” reply from the websocket connection?
- Which value is stored in “thread_credentials_set”?
The commission code is right, and the device should not be out of range (it’s in the same room as my phone) and when using bluetoothctl on the pi4 with an external adapter, it can see it when doing a scan. bluetoothctl list doesn’t find anything with the internal one?)
The message from the server I got is the following one
"{
\"message_id\": \"1\",
\"error_code\": 1,
\"details\": \"Commission with code failed for node 18\"
}"
thread_credentials_set is false (did not work even when it was true via the set_thread_dataset and it resets after the server is restarted)
I’ll try on my second pi4 on a fresh install
It doesn’t work even on a FRESH install of home assistant on DIFFERENT hardware (another pi4)
2023-10-27 23:13:06 core-matter-server chip.BLE[126] ERROR BLE scan error: src/platform/Linux/bluez/ChipDeviceScanner.cpp:154: CHIP Error 0x00000032: Timeout
2023-10-27 23:13:14 core-matter-server chip.DL[126] ERROR FAIL: ConnectDevice : GDBus.Error:org.bluez.Error.Failed: le-connection-abort-by-local (36)
2023-10-27 23:13:14 core-matter-server chip.DL[126] ERROR FAIL: ConnectDevice : Operation was cancelled (19)
2023-10-27 23:13:14 core-matter-server chip.CTL[126] ERROR Commissioning discovery over BLE failed: src/platform/Linux/BLEManagerImpl.cpp:63: CHIP Error 0x00000032: Timeout
2023-10-27 23:13:14 core-matter-server chip.-[126] ERROR src/platform/Linux/BLEManagerImpl.cpp:63: CHIP Error 0x00000032: Timeout at src/controller/SetUpCodePairer.cpp:299
2023-10-27 23:13:26 core-matter-server chip.CTL[126] ERROR Discovery timed out
2023-10-27 23:13:26 core-matter-server chip.ZCL[126] ERROR Secure Pairing Failed
2023-10-27 23:13:26 core-matter-server matter_server.server.client_handler[126] ERROR [548288964752] Error handling message: CommandMessage(message_id='1', command='commission_with_code', args={'code': 'CENSORED'})
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 171, in commission_with_code
raise NodeCommissionFailed(
matter_server.common.errors.NodeCommissionFailed: Commission with code failed for node 1
2023-10-27 23:13:27 core-matter-server chip.DIS[126] ERROR Timeout waiting for mDNS resolution.
even with an usb bluetooth plug
2023-10-27 23:19:59 core-matter-server chip.BLE[126] ERROR BLE scan error: src/platform/Linux/bluez/ChipDeviceScanner.cpp:154: CHIP Error 0x00000032: Timeout
2023-10-27 23:19:59 core-matter-server chip.DL[126] ERROR FAIL: ConnectDevice : Operation was cancelled (19)
2023-10-27 23:19:59 core-matter-server chip.CTL[126] ERROR Commissioning discovery over BLE failed: src/platform/Linux/BLEManagerImpl.cpp:63: CHIP Error 0x00000032: Timeout
2023-10-27 23:19:59 core-matter-server chip.-[126] ERROR src/platform/Linux/BLEManagerImpl.cpp:63: CHIP Error 0x00000032: Timeout at src/controller/SetUpCodePairer.cpp:299
2023-10-27 23:20:19 core-matter-server chip.CTL[126] ERROR Discovery timed out
2023-10-27 23:20:19 core-matter-server chip.ZCL[126] ERROR Secure Pairing Failed
2023-10-27 23:20:19 core-matter-server matter_server.server.client_handler[126] ERROR [547880592912] Error handling message: CommandMessage(message_id='1', command='commission_with_code', args={'code': 'CENSOR'})
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 171, in commission_with_code
raise NodeCommissionFailed(
matter_server.common.errors.NodeCommissionFailed: Commission with code failed for node 3
2023-10-27 23:20:20 core-matter-server chip.DIS[126] ERROR Timeout waiting for mDNS resolution.
You are the first on trying the Nanoleaf essential matter smart bulb in this thread. I and the others are using eve motion or eve smart plugs. This could be the problem, but I do not think so.
We could repeat step by step how I did it with Andrew.
Andrew fixed his issue by switching from a raspi4 to an x86-64 laptop ( "Thread border router required" with Eve and Matter - #66 by calwip ).