search

home-assistant / core

:house_with_garden: Open source home automation that puts local control and privacy first.
https://www.home-assistant.io
Apache License 2.0
72.03k stars 30.17k forks source link

Inconsistent success adopting Nanoleaf downlights into HA from HomeKit #114465

Closed zmumbauer closed 5 months ago

zmumbauer commented 6 months ago

The problem

I've been able to successfully adopt several lights (after many retries) with seemingly no common pattern to copy.

Below is a log of a recent attempt to adopt one single downlight (multiple different node numbers are in the logs). In the end I was able to adopt it after:

  1. Trying once (fail)
  2. Killing power to the light and trying on power back on (fail)
  3. Trying again (fail)
  4. Killing power again (fail)
  5. Trying again (fail)
  6. Trying again (success)

This light was previously paired after a similar situation but my SD card recently went bust so I upgraded to a RP5 with ssd and have to readopt all my lights (except for one that still worked).

I've never worked with embedded devices so I'm not sure what to look for. Even if you could point me to a good resource to try and understand whats happening here better, it would be much appreciated.

Previously this same struggle was on a RP4 (2024.3.1); before that update (and an update to the Nanoleaf firmware) it didn't work at all.

What version of Home Assistant Core has the issue?

core-2024.3.3

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

Link to integration documentation on our website

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

Diagnostics information

home-assistant_matter_2024-03-30T02-25-12.659Z.log

Example YAML snippet

No response

Anything in the logs that might be useful for us?

2024-03-29 21:32:08 (Dummy-2) CHIP_ERROR [chip.native.SC] CASESession timed out while waiting for a response from the peer. Current state was 1
2024-03-29 21:32:11 (MainThread) INFO [matter_server.server.device_controller] Attempting to resolve node 17... (attempt 2 of 2)
2024-03-29 21:32:19 (Dummy-2) CHIP_ERROR [chip.native.EM] Failed to Send CHIP MessageCounter:163137978 on exchange 51998i sendCount: 4 max retries: 4
2024-03-29 21:32:21 (Dummy-2) CHIP_ERROR [chip.native.SC] CASESession timed out while waiting for a response from the peer. Current state was 1
2024-03-29 21:32:24 (MainThread) INFO [matter_server.server.device_controller] Attempting to resolve node 19... (attempt 2 of 2)
2024-03-29 21:32:32 (Dummy-2) CHIP_ERROR [chip.native.EM] Failed to Send CHIP MessageCounter:163137979 on exchange 51999i sendCount: 4 max retries: 4
2024-03-29 21:32:35 (Dummy-2) CHIP_ERROR [chip.native.SC] CASESession timed out while waiting for a response from the peer. Current state was 1
2024-03-29 21:32:35 (MainThread) WARNING [matter_server.server.device_controller.node_10] Setup for node failed: Unable to resolve Node 10
2024-03-29 21:32:45 (Dummy-2) CHIP_ERROR [chip.native.EM] Failed to Send CHIP MessageCounter:163137980 on exchange 52000i sendCount: 4 max retries: 4
2024-03-29 21:32:48 (Dummy-2) CHIP_ERROR [chip.native.SC] CASESession timed out while waiting for a response from the peer. Current state was 1
2024-03-29 21:32:48 (MainThread) WARNING [matter_server.server.device_controller.node_18] Setup for node failed: Unable to resolve Node 18
2024-03-29 21:32:59 (Dummy-2) CHIP_ERROR [chip.native.EM] Failed to Send CHIP MessageCounter:163137981 on exchange 52001i sendCount: 4 max retries: 4
2024-03-29 21:33:02 (Dummy-2) CHIP_ERROR [chip.native.SC] CASESession timed out while waiting for a response from the peer. Current state was 1
2024-03-29 21:33:02 (MainThread) WARNING [matter_server.server.device_controller.node_14] Setup for node failed: Unable to resolve Node 14
2024-03-29 21:33:12 (Dummy-2) CHIP_ERROR [chip.native.EM] Failed to Send CHIP MessageCounter:163137982 on exchange 52002i sendCount: 4 max retries: 4
2024-03-29 21:33:15 (Dummy-2) CHIP_ERROR [chip.native.SC] CASESession timed out while waiting for a response from the peer. Current state was 1
2024-03-29 21:33:15 (MainThread) WARNING [matter_server.server.device_controller.node_17] Setup for node failed: Unable to resolve Node 17
2024-03-29 21:33:26 (Dummy-2) CHIP_ERROR [chip.native.EM] Failed to Send CHIP MessageCounter:163137983 on exchange 52003i sendCount: 4 max retries: 4
2024-03-29 21:33:29 (Dummy-2) CHIP_ERROR [chip.native.SC] CASESession timed out while waiting for a response from the peer. Current state was 1
2024-03-29 21:33:29 (MainThread) WARNING [matter_server.server.device_controller.node_19] Setup for node failed: Unable to resolve Node 19
2024-03-29 21:34:27 (MainThread) INFO [matter_server.server.device_controller.mdns] Node 10 discovered on MDNS
2024-03-29 21:34:27 (MainThread) INFO [matter_server.server.device_controller.node_10] Setting-up node...
2024-03-29 21:34:27 (MainThread) INFO [matter_server.server.device_controller.node_10] Setting up attributes and events subscription.
2024-03-29 21:34:29 (MainThread) INFO [matter_server.server.device_controller.node_10] Subscription succeeded
2024-03-29 21:34:31 (MainThread) INFO [matter_server.server.device_controller.mdns] Node 17 discovered on MDNS
2024-03-29 21:34:31 (MainThread) INFO [matter_server.server.device_controller.node_17] Setting-up node...
2024-03-29 21:34:35 (MainThread) INFO [matter_server.server.device_controller.mdns] Node 19 discovered on MDNS
2024-03-29 21:34:35 (MainThread) INFO [matter_server.server.device_controller.node_19] Setting-up node...
2024-03-29 21:34:41 (Dummy-2) CHIP_ERROR [chip.native.EM] Failed to Send CHIP MessageCounter:163137987 on exchange 52006i sendCount: 4 max retries: 4
2024-03-29 21:34:44 (Dummy-2) CHIP_ERROR [chip.native.SC] CASESession timed out while waiting for a response from the peer. Current state was 1
2024-03-29 21:34:47 (MainThread) INFO [matter_server.server.device_controller.mdns] Node 18 discovered on MDNS
2024-03-29 21:34:47 (MainThread) INFO [matter_server.server.device_controller.node_18] Setting-up node...
2024-03-29 21:34:47 (MainThread) INFO [matter_server.server.device_controller] Attempting to resolve node 17... (attempt 2 of 2)
2024-03-29 21:34:52 (MainThread) INFO [matter_server.server.device_controller.mdns] Node 14 discovered on MDNS
2024-03-29 21:34:52 (MainThread) INFO [matter_server.server.device_controller.node_14] Setting-up node...
2024-03-29 21:34:54 (Dummy-2) CHIP_ERROR [chip.native.EM] Failed to Send CHIP MessageCounter:163137988 on exchange 52007i sendCount: 4 max retries: 4
2024-03-29 21:34:58 (Dummy-2) CHIP_ERROR [chip.native.SC] CASESession timed out while waiting for a response from the peer. Current state was 1
2024-03-29 21:35:01 (MainThread) INFO [matter_server.server.device_controller] Attempting to resolve node 19... (attempt 2 of 2)
2024-03-29 21:35:08 (Dummy-2) CHIP_ERROR [chip.native.EM] Failed to Send CHIP MessageCounter:163137989 on exchange 52008i sendCount: 4 max retries: 4
2024-03-29 21:35:11 (Dummy-2) CHIP_ERROR [chip.native.SC] CASESession timed out while waiting for a response from the peer. Current state was 1
2024-03-29 21:35:14 (MainThread) INFO [matter_server.server.device_controller] Attempting to resolve node 18... (attempt 2 of 2)
2024-03-29 21:35:22 (Dummy-2) CHIP_ERROR [chip.native.EM] Failed to Send CHIP MessageCounter:163137990 on exchange 52009i sendCount: 4 max retries: 4
2024-03-29 21:35:25 (Dummy-2) CHIP_ERROR [chip.native.SC] CASESession timed out while waiting for a response from the peer. Current state was 1
2024-03-29 21:35:25 (MainThread) WARNING [matter_server.server.device_controller.node_17] Setup for node failed: Unable to resolve Node 17
2024-03-29 21:35:35 (Dummy-2) CHIP_ERROR [chip.native.EM] Failed to Send CHIP MessageCounter:163137991 on exchange 52010i sendCount: 4 max retries: 4
2024-03-29 21:35:38 (Dummy-2) CHIP_ERROR [chip.native.SC] CASESession timed out while waiting for a response from the peer. Current state was 1
2024-03-29 21:35:41 (MainThread) INFO [matter_server.server.device_controller] Attempting to resolve node 14... (attempt 2 of 2)
2024-03-29 21:35:49 (Dummy-2) CHIP_ERROR [chip.native.EM] Failed to Send CHIP MessageCounter:163137992 on exchange 52011i sendCount: 4 max retries: 4
2024-03-29 21:35:52 (Dummy-2) CHIP_ERROR [chip.native.SC] CASESession timed out while waiting for a response from the peer. Current state was 1
2024-03-29 21:35:52 (MainThread) WARNING [matter_server.server.device_controller.node_19] Setup for node failed: Unable to resolve Node 19
2024-03-29 21:36:02 (Dummy-2) CHIP_ERROR [chip.native.EM] Failed to Send CHIP MessageCounter:163137993 on exchange 52012i sendCount: 4 max retries: 4
2024-03-29 21:36:05 (Dummy-2) CHIP_ERROR [chip.native.SC] CASESession timed out while waiting for a response from the peer. Current state was 1
2024-03-29 21:36:05 (MainThread) WARNING [matter_server.server.device_controller.node_18] Setup for node failed: Unable to resolve Node 18
2024-03-29 21:36:15 (Dummy-2) CHIP_ERROR [chip.native.EM] Failed to Send CHIP MessageCounter:163137994 on exchange 52013i sendCount: 4 max retries: 4
2024-03-29 21:36:19 (Dummy-2) CHIP_ERROR [chip.native.SC] CASESession timed out while waiting for a response from the peer. Current state was 1
2024-03-29 21:36:19 (MainThread) WARNING [matter_server.server.device_controller.node_14] Setup for node failed: Unable to resolve Node 14
2024-03-29 21:36:28 (Dummy-2) CHIP_ERROR [chip.native.DMG] Subscription Liveness timeout with SubscriptionID = 0x0b724945, Peer = 01:000000000000000A
2024-03-29 21:36:28 (MainThread) INFO [matter_server.server.device_controller.node_10] Previous subscription failed with Error: 50, re-subscribing in 0 ms...
2024-03-29 21:36:37 (Dummy-2) CHIP_ERROR [chip.native.EM] Failed to Send CHIP MessageCounter:163137995 on exchange 52014i sendCount: 4 max retries: 4
2024-03-29 21:36:41 (Dummy-2) CHIP_ERROR [chip.native.SC] CASESession timed out while waiting for a response from the peer. Current state was 4
2024-03-29 21:36:41 (Dummy-2) CHIP_ERROR [chip.native.DMG] Failed to establish CASE for re-subscription with error 'src/protocols/secure_channel/CASESession.cpp:553: CHIP Error 0x00000032: Timeout'
2024-03-29 21:36:41 (MainThread) INFO [matter_server.server.device_controller.node_10] Previous subscription failed with Error: 50, re-subscribing in 8630 ms...
2024-03-29 21:37:00 (Dummy-2) CHIP_ERROR [chip.native.EM] Failed to Send CHIP MessageCounter:163137996 on exchange 52015i sendCount: 4 max retries: 4
2024-03-29 21:37:03 (Dummy-2) CHIP_ERROR [chip.native.SC] CASESession timed out while waiting for a response from the peer. Current state was 4
2024-03-29 21:37:03 (Dummy-2) CHIP_ERROR [chip.native.DMG] Failed to establish CASE for re-subscription with error 'src/protocols/secure_channel/CASESession.cpp:553: CHIP Error 0x00000032: Timeout'
2024-03-29 21:37:03 (MainThread) INFO [matter_server.server.device_controller.node_10] Previous subscription failed with Error: 50, re-subscribing in 5259 ms...
2024-03-29 21:37:03 (MainThread) INFO [matter_server.server.device_controller] Marked node 10 as unavailable
2024-03-29 21:37:15 (MainThread) INFO [root] Re-subscription succeeded!
2024-03-29 21:37:15 (MainThread) INFO [matter_server.server.device_controller.node_10] Re-Subscription succeeded
2024-03-29 21:51:44 (Dummy-2) CHIP_ERROR [chip.native.DMG] Subscription Liveness timeout with SubscriptionID = 0x4d6fb947, Peer = 01:000000000000000A
2024-03-29 21:51:44 (MainThread) INFO [matter_server.server.device_controller.node_10] Previous subscription failed with Error: 50, re-subscribing in 0 ms...
2024-03-29 21:51:49 (MainThread) INFO [root] Re-subscription succeeded!
2024-03-29 21:51:49 (MainThread) INFO [matter_server.server.device_controller.node_10] Re-Subscription succeeded
2024-03-29 21:52:05 (MainThread) INFO [matter_server.server.device_controller] Starting Matter commissioning with code using Node ID 20 (attempt 1/3).
2024-03-29 21:52:35 (Dummy-2) CHIP_ERROR [chip.native.CTL] Discovery timed out
2024-03-29 21:52:35 (Dummy-2) CHIP_ERROR [chip.native.ZCL] Secure Pairing Failed
2024-03-29 21:52:40 (MainThread) INFO [matter_server.server.device_controller] Starting Matter commissioning with code using Node ID 20 (attempt 2/3).
2024-03-29 21:53:10 (Dummy-2) CHIP_ERROR [chip.native.CTL] Discovery timed out
2024-03-29 21:53:10 (Dummy-2) CHIP_ERROR [chip.native.ZCL] Secure Pairing Failed
2024-03-29 21:53:15 (MainThread) INFO [matter_server.server.device_controller] Starting Matter commissioning with code using Node ID 20 (attempt 3/3).
2024-03-29 21:53:45 (Dummy-2) CHIP_ERROR [chip.native.CTL] Discovery timed out
2024-03-29 21:53:45 (Dummy-2) CHIP_ERROR [chip.native.ZCL] Secure Pairing Failed
2024-03-29 21:53:45 (MainThread) ERROR [matter_server.server.client_handler] [547878340880] Error while handling: commission_with_code: Commission with code failed for node 20.
2024-03-29 21:53:58 (MainThread) INFO [matter_server.server.device_controller] Starting Matter commissioning with code using Node ID 21 (attempt 1/3).
2024-03-29 21:54:28 (Dummy-2) CHIP_ERROR [chip.native.CTL] Discovery timed out
2024-03-29 21:54:28 (Dummy-2) CHIP_ERROR [chip.native.ZCL] Secure Pairing Failed
2024-03-29 21:54:33 (MainThread) INFO [matter_server.server.device_controller] Starting Matter commissioning with code using Node ID 21 (attempt 2/3).
2024-03-29 21:55:03 (Dummy-2) CHIP_ERROR [chip.native.CTL] Discovery timed out
2024-03-29 21:55:03 (Dummy-2) CHIP_ERROR [chip.native.ZCL] Secure Pairing Failed
2024-03-29 21:55:08 (MainThread) INFO [matter_server.server.device_controller] Starting Matter commissioning with code using Node ID 21 (attempt 3/3).
2024-03-29 21:55:38 (Dummy-2) CHIP_ERROR [chip.native.CTL] Discovery timed out
2024-03-29 21:55:38 (Dummy-2) CHIP_ERROR [chip.native.ZCL] Secure Pairing Failed
2024-03-29 21:55:38 (MainThread) ERROR [matter_server.server.client_handler] [547878340880] Error while handling: commission_with_code: Commission with code failed for node 21.
2024-03-29 21:56:14 (MainThread) INFO [matter_server.server.device_controller] Starting Matter commissioning with code using Node ID 22 (attempt 1/3).
2024-03-29 21:56:19 (MainThread) INFO [matter_server.server.device_controller] Matter commissioning of Node ID 22 successful.
2024-03-29 21:56:19 (MainThread) INFO [matter_server.server.device_controller] Interviewing node: 22
2024-03-29 21:56:21 (MainThread) INFO [matter_server.server.device_controller.node_22] Setting-up node...
2024-03-29 21:56:21 (MainThread) INFO [matter_server.server.device_controller.node_22] Setting up attributes and events subscription.
2024-03-29 21:56:23 (MainThread) INFO [matter_server.server.device_controller.node_22] Subscription succeeded
2024-03-29 21:56:23 (MainThread) INFO [matter_server.server.device_controller] Commissioning of Node ID 22 completed.

Additional information

No response

home-assistant[bot] commented 6 months ago

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 commented 6 months ago

Nanoleaf devices are known to be very unstable on early firmware versions. Make sure you have the latest firmware version. You can update the firmware in the Nanoleaf app.

zmumbauer commented 6 months ago

hey @marcelveldt, thanks for the response. All of my lights are on the latest firmware 3.6.173. I updated HA and the matter integration and was able to get one working on the first try; however, subsequent tries failed due to CHIP Error 0x00000003: Incorrect state. Based on https://github.com/home-assistant/core/issues/114604#issuecomment-2032418628, I'm going to try uninstalling the matter integration.

zmumbauer commented 6 months ago

Does the node id refer to the device? I tried adding the same light 3 times in a row and the logs show 3 different node ids:

2024-04-04 23:08:23.899 (MainThread) INFO [matter_server.server.vendor_info] Fetched 182 vendors from DCL.
2024-04-04 23:08:23.899 (MainThread) INFO [matter_server.server.vendor_info] Saving vendor info to storage.
2024-04-04 23:09:22.777 (MainThread) INFO [matter_server.server.device_controller] Starting Matter commissioning with code using Node ID 1 (attempt 1/3).
2024-04-04 23:09:52.779 (Dummy-2) CHIP_ERROR [chip.native.CTL] Discovery timed out
2024-04-04 23:09:52.779 (Dummy-2) CHIP_ERROR [chip.native.ZCL] Secure Pairing Failed
2024-04-04 23:09:52.780 (Dummy-2) WARNING [root] Failed to establish secure session to device: src/controller/python/ChipDeviceController-ScriptDevicePairingDelegate.cpp:89: CHIP Error 0x00000003: Incorrect state
2024-04-04 23:09:52.780 (Dummy-2) WARNING [root] Failed to commission: src/controller/python/ChipDeviceController-ScriptDevicePairingDelegate.cpp:89: CHIP Error 0x00000003: Incorrect state
2024-04-04 23:09:53.782 (Dummy-2) CHIP_ERROR [chip.native.DIS] Timeout waiting for mDNS resolution.
2024-04-04 23:09:57.782 (MainThread) INFO [matter_server.server.device_controller] Starting Matter commissioning with code using Node ID 1 (attempt 2/3).
2024-04-04 23:10:27.784 (Dummy-2) CHIP_ERROR [chip.native.CTL] Discovery timed out
2024-04-04 23:10:27.785 (Dummy-2) CHIP_ERROR [chip.native.ZCL] Secure Pairing Failed
2024-04-04 23:10:27.785 (Dummy-2) WARNING [root] Failed to establish secure session to device: src/controller/python/ChipDeviceController-ScriptDevicePairingDelegate.cpp:89: CHIP Error 0x00000003: Incorrect state
2024-04-04 23:10:27.785 (Dummy-2) WARNING [root] Failed to commission: src/controller/python/ChipDeviceController-ScriptDevicePairingDelegate.cpp:89: CHIP Error 0x00000003: Incorrect state
2024-04-04 23:10:28.785 (Dummy-2) CHIP_ERROR [chip.native.DIS] Timeout waiting for mDNS resolution.
2024-04-04 23:10:32.786 (MainThread) INFO [matter_server.server.device_controller] Starting Matter commissioning with code using Node ID 1 (attempt 3/3).
2024-04-04 23:10:36.704 (MainThread) INFO [matter_server.server.device_controller] Starting Matter commissioning with code using Node ID 2 (attempt 1/3).
2024-04-04 23:11:06.707 (Dummy-2) CHIP_ERROR [chip.native.CTL] Discovery timed out
2024-04-04 23:11:06.708 (Dummy-2) CHIP_ERROR [chip.native.ZCL] Secure Pairing Failed
2024-04-04 23:11:06.708 (Dummy-2) WARNING [root] Failed to establish secure session to device: src/controller/python/ChipDeviceController-ScriptDevicePairingDelegate.cpp:89: CHIP Error 0x00000003: Incorrect state
2024-04-04 23:11:06.708 (Dummy-2) WARNING [root] Failed to commission: src/controller/python/ChipDeviceController-ScriptDevicePairingDelegate.cpp:89: CHIP Error 0x00000003: Incorrect state
2024-04-04 23:11:06.709 (MainThread) ERROR [matter_server.server.client_handler] [547810446928] Error while handling: commission_with_code: Commission with code failed for node 1.
2024-04-04 23:11:07.709 (Dummy-2) CHIP_ERROR [chip.native.DIS] Timeout waiting for mDNS resolution.
2024-04-04 23:11:11.711 (MainThread) INFO [matter_server.server.device_controller] Starting Matter commissioning with code using Node ID 2 (attempt 2/3).
2024-04-04 23:11:41.714 (Dummy-2) CHIP_ERROR [chip.native.CTL] Discovery timed out
2024-04-04 23:11:41.714 (Dummy-2) CHIP_ERROR [chip.native.ZCL] Secure Pairing Failed
2024-04-04 23:11:41.714 (Dummy-2) WARNING [root] Failed to establish secure session to device: src/controller/python/ChipDeviceController-ScriptDevicePairingDelegate.cpp:89: CHIP Error 0x00000003: Incorrect state
2024-04-04 23:11:41.714 (Dummy-2) WARNING [root] Failed to commission: src/controller/python/ChipDeviceController-ScriptDevicePairingDelegate.cpp:89: CHIP Error 0x00000003: Incorrect state
2024-04-04 23:11:42.714 (Dummy-2) CHIP_ERROR [chip.native.DIS] Timeout waiting for mDNS resolution.
2024-04-04 23:11:45.749 (MainThread) INFO [matter_server.server.device_controller] Starting Matter commissioning with code using Node ID 3 (attempt 1/3).
2024-04-04 23:11:46.715 (MainThread) INFO [matter_server.server.device_controller] Starting Matter commissioning with code using Node ID 2 (attempt 3/3).
marcelveldt commented 5 months ago

With each commission attempt the node id will increment. Looking at this log the device is not ready to be commissioned at all or connectivity is failing.

I'd restore the device to factory settings and try again.

MR-Apple-uk commented 5 months ago

I am having the same error with three brand new devices all GU10's running 3.6.173 and HA and matter upto date also

marcelveldt commented 5 months ago

Did you all read our documentation for Matter ? Especially the tips about networking:

No vLANS (or have your IoT devices and HA on the same IoT vlan) no mDNS repeaters ! If you have (semi)professional network gear such as Unifi, Omada etc. be very careful with enabling multicast filtering options. Although not strictly required by the spec (it should work fully with link local IPV6 neighbour discovery) - it might be needed to setup IPv6 in your network, either by having a native IPv6 setup from your ISP or have an DHPv6 server active Make sure that IPv6 is enabled is your HA server network config. When commissioning a device, make sure your phone is not connected to a 5ghz only WiFi SSID. Read all recommendations about Thread and Thread border routers if you're commissioning Matter-over-thread devices. This issue tracker is for reporting bugs. For user support refer to the forums or better yet, the Matter channel on our discord server. There we can help you out with set-up related questions.