Multiple Issues with ZHA and Aqara Devices after update to 2024.8.x

tbrausch commented 2 months ago

The problem

After uprading to any version of 2024.8.x I have the following 4 issues:

1) All zigbee devices are offline after the update. Slowly the Philips lights and SONOFF switches will come back online but even with a reset I cannot get the Aqara devices to work (door, temperature, button and motion sensors). If I revert back to 2024.7.x, then all sensors are back online. The following is the ZHA debug info from the update and subsequent restart: home-assistant_zha_2024-08-25T18-43-57.936Z.log The following is the diagnostic data file: config_entry-zha-7eb3d3902e082d5ae18fe04b1f890571.json

2) After the HA upgrade, I tried to load a ZHA backup that was done previously to see if this corrected the offline issues and it reported an error. On further testing the backup file was successfully loaded, but the devices were still not available and the groups were still deleted.

3) All groups defined in ZHA were deleted after the HA update. Note that they only referenced Aqara devices.

4) I have multiple automations that use Aqara buttons as the trigger. After the HA update I could not restart HA due to config errors reported in all of these automations. Commmenting them out allowed the system to restart. Each automation had a trigger similar to this:

- id: button_lr_single
  alias: '[Light] Control Living Room Light'
  initial_state: true
  mode: single
  trigger:
  - device_id: dc08ad3eab5e9e12cdee7c5b0204799f
    domain: zha
    platform: device
    type: remote_button_short_press
    subtype: remote_button_short_press

Afterr reverting back to HA 2024.7.4 everything was restored to working order.

The following is a log of the errors reported when trying to load these automations: Cannot Restart.log

I am using a Conbee ii coordinator:

Device info
Conbee II
by dresden elektronik
Connected via dresden elektronik Conbee II
Firmware: 0x26720700
Zigbee info
IEEE: e0:79:8d:ff:fe:1d:15:b5
Nwk: 0x0000
Device Type: Coordinator
LQI: 221
RSSI: 30
Last seen: 2024-08-25T14:43:07
Power source: Mains

What version of Home Assistant Core has the issue?

core-2024.8.0

What was the last working version of Home Assistant Core?

core-2024.7.4

What type of installation are you running?

Home Assistant OS

Integration causing the issue

ZHA with Aqara devices

Link to integration documentation on our website

No response

Diagnostics information

No response

Example YAML snippet

No response

Anything in the logs that might be useful for us?

No response

Additional information

No response

cossiboon commented 2 months ago

EDIT: Full quotes are uncool 😉

I didn't perform an in depth analysis but I can confirm all my aqara button triggers are missing after installing 2024.8.3.

Restoring 2024.8.2 brought them back.

home-assistant[bot] commented 2 months ago

Hey there @dmulcahey, @adminiuga, @puddly, @thejulianjes, mind taking a look at this issue as it has been labeled with an integration (zha) you are listed as a code owner for? Thanks!

Code owner commands

Code owners of `zha` 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 zha` 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)}}

zha documentation zha source _{^{(message by IssueLinks)}}

tbrausch commented 1 month ago

All probems (except restoring ZHA backup) still exist in 2024.9.0. Reverting back to 2024.7.4 still fixes everything. Let me know if you want new logs or any other information that may help.

netsloh commented 1 month ago

Same problem here...

edgarveersel commented 1 month ago

I never had a problem with ZHA, but today i upgraded HA core from 2.8.3 to 2.9.1 and encountered this issue. So, other than the reporter of this issue @tbrausch, I only encountered it after upgrading beyond 2.8.3.

I have a rather serious problem in my house now, with none of my wall light switches are working...

Here's what I've tried

Removed a light switch, and then rejoined it.
Restore version 2.8.3 (last night)
Restart ZHA
Restart HA
Power cycle my HA RasPI + Sonoff ZigBee USB Dongle+ E

No luck thus far...

edgarveersel commented 1 month ago

Also for me: restoring 2024.7.4 brought them all back.

For those devices that did remained connected via ZHA with 2024.9.1, many were corrupted somehow. eg.some door/window sensors had a switch, besides the open/close sensor. Makes no sense.

puddly commented 1 month ago

@edgarveersel Can you upload diagnostics information for the affected sensors?

edgarveersel commented 1 month ago

Hi @puddly, unfortunately i didn't download any when I was on 2024.9.1. But this is important, so i will restore the 2024.9.1 backup with the ZHA issue and then download the diagnostics. Might take a couple of days, though.

waltailji commented 1 month ago

I'm having the same issues with my aqara buttons, temperature sensors, and leak detectors. I tried 2024.8.x and 2004.9.x (including the current 2024.9.2) and have to downgrade back to 2024.7.3 to get them working again.

My Zigbee diagnostics from 2024.7.3: config_entry-zha-301682d2256f4c6a84c71a334ddb5319 (1).json My Zigbee diagnostics from 2024.9.2: config_entry-zha-301682d2256f4c6a84c71a334ddb5319 (2).json My HA Core log with Zigbee debug logging enabled in 2024.9.2: home-assistant_2024-09-17T04-21-19.883Z.log

edgarveersel commented 1 month ago

I intended to recreate the issue. As stated above, I was using 2024.7.4 again. Today, the latest version is 2024.9.2, so updated to that. 'Unfortunately' the problems did not reappear...

waltailji commented 3 weeks ago

I'm having the same issues with my aqara buttons, temperature sensors, and leak detectors. I tried 2024.8.x and 2004.9.x (including the current 2024.9.2) and have to downgrade back to 2024.7.3 to get them working again.

My Zigbee diagnostics from 2024.7.3: config_entry-zha-301682d2256f4c6a84c71a334ddb5319 (1).json My Zigbee diagnostics from 2024.9.2: config_entry-zha-301682d2256f4c6a84c71a334ddb5319 (2).json My HA Core log with Zigbee debug logging enabled in 2024.9.2: home-assistant_2024-09-17T04-21-19.883Z.log

any updates on this issue @puddly ? I tried 2024.10 and still no dice on my battery powered aqara buttons and temperature sensors (oddly, i have one aqara motion sensor that worked though).

dmulcahey commented 3 weeks ago

I'm having the same issues with my aqara buttons, temperature sensors, and leak detectors. I tried 2024.8.x and 2004.9.x (including the current 2024.9.2) and have to downgrade back to 2024.7.3 to get them working again. My Zigbee diagnostics from 2024.7.3: config_entry-zha-301682d2256f4c6a84c71a334ddb5319 (1).json My Zigbee diagnostics from 2024.9.2: config_entry-zha-301682d2256f4c6a84c71a334ddb5319 (2).json My HA Core log with Zigbee debug logging enabled in 2024.9.2: home-assistant_2024-09-17T04-21-19.883Z.log

any updates on this issue @puddly ? I tried 2024.10 and still no dice on my battery powered aqara buttons and temperature sensors (oddly, i have one aqara motion sensor that worked though).

Out of curiosity how are you upgrading and how do you run HA? Look at the devices sections at the bottom of both config entry json files. Something is preventing all of your devices from loading on the newer version. I need to look closer at the log file. I peeked from mobile and I don’t see anything that should cause this.

waltailji commented 3 weeks ago

Out of curiosity how are you upgrading and how do you run HA? Look at the devices sections at the bottom of both config entry json files. Something is preventing all of your devices from loading on the newer version. I need to look closer at the log file. I peeked from mobile and I don’t see anything that should cause this.

I use the update dialog on the Settings screen, and running as HA OS on a Home Assistant Blue ODROID-N2+.

I noticed while running the newer versions that my automations break because the hardware addresses of the battery-operated devices no longer exist, causing my configs to no pass validation. I'll have to look closer in the logs too. When I try to re-pair any of these devices it gets stuck in "Starting Interview".

dmulcahey commented 3 weeks ago

can you upgrade again please and attach the zigbee.db here. Give us the db before and after the upgrade please.

andyb2000 commented 3 weeks ago

Hi, I think I'm also seeing the same issue as commented on another open issue, however I've now upgraded to 2024.10.1 and having the same problem, unfortunately I didn't see this post so couldn't grab my zigbee.db before the upgrade.

I've attached mine as of now (2024.10.1) zigbee.db.gz

I have also noticed that trying to add aquara devices now are also exhibiting similar issues and I wonder if this is the problem. (I'm aware you often have to try adding multiple times) When I'm trying to add Aquara (And actually Sonoff so not sure if this is similar) they get stuck on "Interview complete. Configuring" and never end. I enabled ZHA debug logging and then went to add the device (In this case Sonoff SNZB-01) which did as you can see:

So that is also the debug log attached: home-assistant_zha_2024-10-10T12-13-57.816Z.log.gz

andyb2000 commented 3 weeks ago

I have also just done the same process for the Aqara motion sensor, again debug logs from ZHA for the pairing process. This time it did pair correctly and appear. I'll post back when it fails to continue communicating.

lumi.sensor_motion.aq2 by LUMI Zigbee info IEEE: 00:15:8d:00:07:be:f4:3b Nwk: 0xa26c Device Type: EndDevice LQI: Unknown RSSI: Unknown Last Seen: 2024-10-10T13:20:04 Power Source: Battery or Unknown Quirk: zhaquirks.xiaomi.aqara.motion_aq2.MotionAQ2

home-assistant_zha_2024-10-10T12-20-15.088Z-aqara.log.gz

andyb2000 commented 3 weeks ago

The Aqara has gone unknown almost straight away. Last Seen: 2024-10-10T13:20:04 Is still the same, it went to clear (motion detection) and even though it senses movement (flashes blue led) the state doesn't change in ZHA.

LUMI lumi.sensor_motion.aq2 Firmware became unknown
13:20:04 - 13 minutes ago
LUMI lumi.sensor_motion.aq2 Identify became unknown
13:20:04 - 13 minutes ago
LUMI lumi.sensor_motion.aq2 Motion cleared (no motion detected)
13:20:04 - 13 minutes ago
LUMI lumi.sensor_motion.aq2 Occupancy cleared (no occupancy detected)
13:20:04 - 13 minutes ago

dmulcahey commented 3 weeks ago

The Aqara has gone unknown almost straight away. Last Seen: 2024-10-10T13:20:04 Is still the same, it went to clear (motion detection) and even though it senses movement (flashes blue led) the state doesn't change in ZHA.
LUMI lumi.sensor_motion.aq2 Firmware became unknown
13:20:04 - 13 minutes ago
LUMI lumi.sensor_motion.aq2 Identify became unknown
13:20:04 - 13 minutes ago
LUMI lumi.sensor_motion.aq2 Motion cleared (no motion detected)
13:20:04 - 13 minutes ago
LUMI lumi.sensor_motion.aq2 Occupancy cleared (no occupancy detected)
13:20:04 - 13 minutes ago

Did you override the consider unavailable time settings in the ZHA config panel???

andyb2000 commented 3 weeks ago

@dmulcahey Yes but not down to that low number:

Mine is set to 28800 which is 8 hours.

Just to add, I checked to see if there was any further reference of that sensor in my home-assistant.log and there wasn't after that time (but ZHA isn't in debug, would that help if I left it in debug, paired it up again and watched for any logs containing the id?):

homeassistant:/config# grep "00:15:8d:00:07:be:f4:3b" home-assistant.log | tail -2
2024-10-10 13:20:06.135 DEBUG (MainThread) [zha.application.platforms] 00:15:8d:00:07:be:f4:3b-1-0-rssi: polling for updated state
2024-10-10 13:20:06.136 DEBUG (MainThread) [zha.application.platforms] 00:15:8d:00:07:be:f4:3b-1-0-lqi: polling for updated state
homeassistant:/config#

dmulcahey commented 3 weeks ago

What is [homeassistant.components.automation.zha_autoretrieve] While executing automation automation.zha_autoretrieve Doing? (This is more just for my own knowledge)

dmulcahey commented 3 weeks ago

@dmulcahey Yes but not down to that low number:

Mine is set to 28800 which is 8 hours.

Just to add, I checked to see if there was any further reference of that sensor in my home-assistant.log and there wasn't after that time (but ZHA isn't in debug, would that help if I left it in debug, paired it up again and watched for any logs containing the id?):
homeassistant:/config# grep "00:15:8d:00:07:be:f4:3b" home-assistant.log | tail -2
2024-10-10 13:20:06.135 DEBUG (MainThread) [zha.application.platforms] 00:15:8d:00:07:be:f4:3b-1-0-rssi: polling for updated state
2024-10-10 13:20:06.136 DEBUG (MainThread) [zha.application.platforms] 00:15:8d:00:07:be:f4:3b-1-0-lqi: polling for updated state
homeassistant:/config# 

Get it connected again and leave debug on. Attach the full log when it is unavailable again please.

andyb2000 commented 3 weeks ago

What is [homeassistant.components.automation.zha_autoretrieve] While executing automation automation.zha_autoretrieve Doing? (This is more just for my own knowledge)

It's polling a zigbee rain sensor to retrieve some stats that aren't exposed under the current quirks using zha toolkit. The automation code:

alias: ZHA-autoretrieve
description: ""
triggers:
  - hours: /1
    trigger: time_pattern
conditions: []
actions:
  - data:
      ieee: a4:c1:38:ec:5d:1d:0e:f0
      cluster: 61184
      attribute: 61285
      use_cache: true
      state_id: sensor.outdoor_rain_light_intensity
      allow_create: true
    action: zha_toolkit.attr_read
  - data:
      ieee: a4:c1:38:ec:5d:1d:0e:f0
      cluster: 61184
      attribute: 61289
      use_cache: true
      state_id: sensor.outdoor_rain_rain_intensity
      allow_create: true
    action: zha_toolkit.attr_read
  - action: zha_toolkit.attr_read
    metadata: {}
    data:
      ieee: 00:15:8d:00:07:be:f4:3b
      attribute: 500

I'll do the debug in a moment. Thank you!

andyb2000 commented 3 weeks ago

Typically, after enabling debugging and re-adding this device (Aqara motion) it's working fine for motion detection for the past hour. I'll update after a few hours. However, no battery state:

2024-10-10 14:50:52.812 DEBUG (MainThread) [zha.application.platforms] 00:15:8d:00:07:be:f4:3b-1-0-lqi: polling for updated state
2024-10-10 14:51:25.835 DEBUG (MainThread) [zha.application.platforms] 00:15:8d:00:07:be:f4:3b-1-0-rssi: polling for updated state
2024-10-10 14:51:25.835 DEBUG (MainThread) [zha.application.platforms] 00:15:8d:00:07:be:f4:3b-1-0-lqi: polling for updated state
2024-10-10 14:51:58.853 DEBUG (MainThread) [zha.application.platforms] 00:15:8d:00:07:be:f4:3b-1-0-rssi: polling for updated state
2024-10-10 14:51:58.853 DEBUG (MainThread) [zha.application.platforms] 00:15:8d:00:07:be:f4:3b-1-0-lqi: polling for updated state
2024-10-10 14:52:31.869 DEBUG (MainThread) [zha.application.platforms] 00:15:8d:00:07:be:f4:3b-1-0-rssi: polling for updated state
2024-10-10 14:52:31.869 DEBUG (MainThread) [zha.application.platforms] 00:15:8d:00:07:be:f4:3b-1-0-lqi: polling for updated state
2024-10-10 14:53:04.887 DEBUG (MainThread) [zha.application.platforms] 00:15:8d:00:07:be:f4:3b-1-0-rssi: polling for updated state
2024-10-10 14:53:04.887 DEBUG (MainThread) [zha.application.platforms] 00:15:8d:00:07:be:f4:3b-1-0-lqi: polling for updated state
2024-10-10 14:53:37.903 DEBUG (MainThread) [zha.application.platforms] 00:15:8d:00:07:be:f4:3b-1-0-rssi: polling for updated state
2024-10-10 14:53:37.903 DEBUG (MainThread) [zha.application.platforms] 00:15:8d:00:07:be:f4:3b-1-0-lqi: polling for updated state
2024-10-10 14:54:05.588 DEBUG (MainThread) [zha] Emitting event cluster_handler_attribute_updated with data ClusterAttributeUpdatedEvent(attribute_id=0, attribute_name='measured_value', attribute_value=20254.058652647705, cluster_handler_unique_id='00:15:8d:00:07:be:f4:3b:1:0x0400', cluster_id=1024, event_type='cluster_handler_event', event='cluster_handler_attribute_updated') (1 listeners)
2024-10-10 14:54:05.589 DEBUG (MainThread) [zha] Emitting event state_changed with data EntityStateChangedEvent(event_type='entity', event='state_changed', platform=<Platform.SENSOR: 'sensor'>, unique_id='00:15:8d:00:07:be:f4:3b-1-1024', device_ieee=00:15:8d:00:07:be:f4:3b, endpoint_id=1, group_id=None) (1 listeners)
2024-10-10 14:54:05.589 DEBUG (MainThread) [homeassistant.components.zha.entity] sensor.lumi_lumi_sensor_motion_aq2_illuminance: Handling event from entity: EntityStateChangedEvent(event_type='entity', event='state_changed', platform=<Platform.SENSOR: 'sensor'>, unique_id='00:15:8d:00:07:be:f4:3b-1-1024', device_ieee=00:15:8d:00:07:be:f4:3b, endpoint_id=1, group_id=None)
2024-10-10 14:54:05.593 DEBUG (Thread-4) [aiosqlite] executing functools.partial(<built-in method execute of sqlite3.Connection object at 0x7f182c732890>, 'UPDATE devices_v13\n                    SET last_seen=:ts\n                    WHERE ieee=:ieee AND :ts - last_seen > :min_update_delta', {'ts': 1728568445.584051, 'ieee': 00:15:8d:00:07:be:f4:3b, 'min_update_delta': 30.0})
2024-10-10 14:54:05.593 DEBUG (Thread-4) [aiosqlite] operation functools.partial(<built-in method execute of sqlite3.Connection object at 0x7f182c732890>, 'UPDATE devices_v13\n                    SET last_seen=:ts\n                    WHERE ieee=:ieee AND :ts - last_seen > :min_update_delta', {'ts': 1728568445.584051, 'ieee': 00:15:8d:00:07:be:f4:3b, 'min_update_delta': 30.0}) completed
2024-10-10 14:54:05.601 DEBUG (Thread-4) [aiosqlite] executing functools.partial(<built-in method execute of sqlite3.Connection object at 0x7f182c732890>, 'UPDATE devices_v13\n                    SET last_seen=:ts\n                    WHERE ieee=:ieee AND :ts - last_seen > :min_update_delta', {'ts': 1728568445.584051, 'ieee': 00:15:8d:00:07:be:f4:3b, 'min_update_delta': 30.0})
2024-10-10 14:54:05.606 DEBUG (Thread-4) [aiosqlite] operation functools.partial(<built-in method execute of sqlite3.Connection object at 0x7f182c732890>, 'UPDATE devices_v13\n                    SET last_seen=:ts\n                    WHERE ieee=:ieee AND :ts - last_seen > :min_update_delta', {'ts': 1728568445.584051, 'ieee': 00:15:8d:00:07:be:f4:3b, 'min_update_delta': 30.0}) completed
2024-10-10 14:54:05.608 DEBUG (MainThread) [zha] Emitting event cluster_handler_attribute_updated with data ClusterAttributeUpdatedEvent(attribute_id=0, attribute_name='occupancy', attribute_value=<Occupancy.Occupied: 1>, cluster_handler_unique_id='00:15:8d:00:07:be:f4:3b:1:0x0406', cluster_id=1030, event_type='cluster_handler_event', event='cluster_handler_attribute_updated') (1 listeners)
2024-10-10 14:54:05.608 DEBUG (MainThread) [zha] Emitting event state_changed with data EntityStateChangedEvent(event_type='entity', event='state_changed', platform=<Platform.BINARY_SENSOR: 'binary_sensor'>, unique_id='00:15:8d:00:07:be:f4:3b-1-1030', device_ieee=00:15:8d:00:07:be:f4:3b, endpoint_id=1, group_id=None) (1 listeners)
2024-10-10 14:54:05.608 DEBUG (MainThread) [homeassistant.components.zha.entity] binary_sensor.lumi_lumi_sensor_motion_aq2_occupancy: Handling event from entity: EntityStateChangedEvent(event_type='entity', event='state_changed', platform=<Platform.BINARY_SENSOR: 'binary_sensor'>, unique_id='00:15:8d:00:07:be:f4:3b-1-1030', device_ieee=00:15:8d:00:07:be:f4:3b, endpoint_id=1, group_id=None)
2024-10-10 14:54:05.609 DEBUG (MainThread) [zha] Emitting event cluster_handler_attribute_updated with data ClusterAttributeUpdatedEvent(attribute_id=2, attribute_name='zone_status', attribute_value=1, cluster_handler_unique_id='00:15:8d:00:07:be:f4:3b:1:0x0500', cluster_id=1280, event_type='cluster_handler_event', event='cluster_handler_attribute_updated') (1 listeners)
2024-10-10 14:54:05.609 DEBUG (MainThread) [zha] Emitting event state_changed with data EntityStateChangedEvent(event_type='entity', event='state_changed', platform=<Platform.BINARY_SENSOR: 'binary_sensor'>, unique_id='00:15:8d:00:07:be:f4:3b-1-1280', device_ieee=00:15:8d:00:07:be:f4:3b, endpoint_id=1, group_id=None) (1 listeners)
2024-10-10 14:54:05.609 DEBUG (MainThread) [homeassistant.components.zha.entity] binary_sensor.lumi_lumi_sensor_motion_aq2_motion: Handling event from entity: EntityStateChangedEvent(event_type='entity', event='state_changed', platform=<Platform.BINARY_SENSOR: 'binary_sensor'>, unique_id='00:15:8d:00:07:be:f4:3b-1-1280', device_ieee=00:15:8d:00:07:be:f4:3b, endpoint_id=1, group_id=None)
2024-10-10 14:54:05.610 DEBUG (MainThread) [zigpy.zcl] [0x8413:1:0x0500] 00:15:8d:00:07:be:f4:3b - Received motion event message
2024-10-10 14:54:05.618 DEBUG (Thread-4) [aiosqlite] executing functools.partial(<built-in method execute of sqlite3.Connection object at 0x7f182c732890>, 'UPDATE devices_v13\n                    SET last_seen=:ts\n                    WHERE ieee=:ieee AND :ts - last_seen > :min_update_delta', {'ts': 1728568445.584051, 'ieee': 00:15:8d:00:07:be:f4:3b, 'min_update_delta': 30.0})
2024-10-10 14:54:05.619 DEBUG (Thread-4) [aiosqlite] operation functools.partial(<built-in method execute of sqlite3.Connection object at 0x7f182c732890>, 'UPDATE devices_v13\n                    SET last_seen=:ts\n                    WHERE ieee=:ieee AND :ts - last_seen > :min_update_delta', {'ts': 1728568445.584051, 'ieee': 00:15:8d:00:07:be:f4:3b, 'min_update_delta': 30.0}) completed
2024-10-10 14:54:05.621 DEBUG (Thread-4) [aiosqlite] executing functools.partial(<built-in method execute of sqlite3.Connection object at 0x7f182c732890>, '\n            INSERT INTO attributes_cache_v13\n            VALUES (:ieee, :endpoint_id, :cluster_type, :cluster_id, :attr_id, :value, :timestamp)\n                ON CONFLICT (ieee, endpoint_id, cluster_type, cluster_id, attr_id) DO UPDATE\n                SET value=excluded.value, last_updated=excluded.last_updated\n                WHERE\n                    value != excluded.value\n                    OR :timestamp - last_updated > :min_update_delta\n            ', {'ieee': 00:15:8d:00:07:be:f4:3b, 'endpoint_id': 1, 'cluster_type': <ClusterType.Server: 0>, 'cluster_id': 1024, 'attr_id': 0, 'value': 20254.058652647705, 'timestamp': 1728568445.588629, 'min_update_delta': 30.0})
2024-10-10 14:54:05.622 DEBUG (Thread-4) [aiosqlite] operation functools.partial(<built-in method execute of sqlite3.Connection object at 0x7f182c732890>, '\n            INSERT INTO attributes_cache_v13\n            VALUES (:ieee, :endpoint_id, :cluster_type, :cluster_id, :attr_id, :value, :timestamp)\n                ON CONFLICT (ieee, endpoint_id, cluster_type, cluster_id, attr_id) DO UPDATE\n                SET value=excluded.value, last_updated=excluded.last_updated\n                WHERE\n                    value != excluded.value\n                    OR :timestamp - last_updated > :min_update_delta\n            ', {'ieee': 00:15:8d:00:07:be:f4:3b, 'endpoint_id': 1, 'cluster_type': <ClusterType.Server: 0>, 'cluster_id': 1024, 'attr_id': 0, 'value': 20254.058652647705, 'timestamp': 1728568445.588629, 'min_update_delta': 30.0}) completed
2024-10-10 14:54:05.625 DEBUG (Thread-4) [aiosqlite] executing functools.partial(<built-in method execute of sqlite3.Connection object at 0x7f182c732890>, 'UPDATE devices_v13\n                    SET last_seen=:ts\n                    WHERE ieee=:ieee AND :ts - last_seen > :min_update_delta', {'ts': 1728568445.602912, 'ieee': 00:15:8d:00:07:be:f4:3b, 'min_update_delta': 30.0})
2024-10-10 14:54:05.626 DEBUG (Thread-4) [aiosqlite] operation functools.partial(<built-in method execute of sqlite3.Connection object at 0x7f182c732890>, 'UPDATE devices_v13\n                    SET last_seen=:ts\n                    WHERE ieee=:ieee AND :ts - last_seen > :min_update_delta', {'ts': 1728568445.602912, 'ieee': 00:15:8d:00:07:be:f4:3b, 'min_update_delta': 30.0}) completed
2024-10-10 14:54:05.629 DEBUG (Thread-4) [aiosqlite] executing functools.partial(<built-in method execute of sqlite3.Connection object at 0x7f182c732890>, 'UPDATE devices_v13\n                    SET last_seen=:ts\n                    WHERE ieee=:ieee AND :ts - last_seen > :min_update_delta', {'ts': 1728568445.602912, 'ieee': 00:15:8d:00:07:be:f4:3b, 'min_update_delta': 30.0})
2024-10-10 14:54:05.630 DEBUG (Thread-4) [aiosqlite] operation functools.partial(<built-in method execute of sqlite3.Connection object at 0x7f182c732890>, 'UPDATE devices_v13\n                    SET last_seen=:ts\n                    WHERE ieee=:ieee AND :ts - last_seen > :min_update_delta', {'ts': 1728568445.602912, 'ieee': 00:15:8d:00:07:be:f4:3b, 'min_update_delta': 30.0}) completed
2024-10-10 14:54:05.631 DEBUG (Thread-4) [aiosqlite] executing functools.partial(<built-in method execute of sqlite3.Connection object at 0x7f182c732890>, 'UPDATE devices_v13\n                    SET last_seen=:ts\n                    WHERE ieee=:ieee AND :ts - last_seen > :min_update_delta', {'ts': 1728568445.602912, 'ieee': 00:15:8d:00:07:be:f4:3b, 'min_update_delta': 30.0})
2024-10-10 14:54:05.632 DEBUG (Thread-4) [aiosqlite] operation functools.partial(<built-in method execute of sqlite3.Connection object at 0x7f182c732890>, 'UPDATE devices_v13\n                    SET last_seen=:ts\n                    WHERE ieee=:ieee AND :ts - last_seen > :min_update_delta', {'ts': 1728568445.602912, 'ieee': 00:15:8d:00:07:be:f4:3b, 'min_update_delta': 30.0}) completed
2024-10-10 14:54:05.635 DEBUG (Thread-4) [aiosqlite] executing functools.partial(<built-in method execute of sqlite3.Connection object at 0x7f182c732890>, '\n            INSERT INTO attributes_cache_v13\n            VALUES (:ieee, :endpoint_id, :cluster_type, :cluster_id, :attr_id, :value, :timestamp)\n                ON CONFLICT (ieee, endpoint_id, cluster_type, cluster_id, attr_id) DO UPDATE\n                SET value=excluded.value, last_updated=excluded.last_updated\n                WHERE\n                    value != excluded.value\n                    OR :timestamp - last_updated > :min_update_delta\n            ', {'ieee': 00:15:8d:00:07:be:f4:3b, 'endpoint_id': 1, 'cluster_type': <ClusterType.Server: 0>, 'cluster_id': 1030, 'attr_id': 0, 'value': <Occupancy.Occupied: 1>, 'timestamp': 1728568445.60778, 'min_update_delta': 30.0})
2024-10-10 14:54:05.636 DEBUG (Thread-4) [aiosqlite] operation functools.partial(<built-in method execute of sqlite3.Connection object at 0x7f182c732890>, '\n            INSERT INTO attributes_cache_v13\n            VALUES (:ieee, :endpoint_id, :cluster_type, :cluster_id, :attr_id, :value, :timestamp)\n                ON CONFLICT (ieee, endpoint_id, cluster_type, cluster_id, attr_id) DO UPDATE\n                SET value=excluded.value, last_updated=excluded.last_updated\n                WHERE\n                    value != excluded.value\n                    OR :timestamp - last_updated > :min_update_delta\n            ', {'ieee': 00:15:8d:00:07:be:f4:3b, 'endpoint_id': 1, 'cluster_type': <ClusterType.Server: 0>, 'cluster_id': 1030, 'attr_id': 0, 'value': <Occupancy.Occupied: 1>, 'timestamp': 1728568445.60778, 'min_update_delta': 30.0}) completed
2024-10-10 14:54:05.638 DEBUG (Thread-4) [aiosqlite] executing functools.partial(<built-in method execute of sqlite3.Connection object at 0x7f182c732890>, '\n            INSERT INTO attributes_cache_v13\n            VALUES (:ieee, :endpoint_id, :cluster_type, :cluster_id, :attr_id, :value, :timestamp)\n                ON CONFLICT (ieee, endpoint_id, cluster_type, cluster_id, attr_id) DO UPDATE\n                SET value=excluded.value, last_updated=excluded.last_updated\n                WHERE\n                    value != excluded.value\n                    OR :timestamp - last_updated > :min_update_delta\n            ', {'ieee': 00:15:8d:00:07:be:f4:3b, 'endpoint_id': 1, 'cluster_type': <ClusterType.Server: 0>, 'cluster_id': 1280, 'attr_id': 2, 'value': 1, 'timestamp': 1728568445.60918, 'min_update_delta': 30.0})
2024-10-10 14:54:05.638 DEBUG (Thread-4) [aiosqlite] operation functools.partial(<built-in method execute of sqlite3.Connection object at 0x7f182c732890>, '\n            INSERT INTO attributes_cache_v13\n            VALUES (:ieee, :endpoint_id, :cluster_type, :cluster_id, :attr_id, :value, :timestamp)\n                ON CONFLICT (ieee, endpoint_id, cluster_type, cluster_id, attr_id) DO UPDATE\n                SET value=excluded.value, last_updated=excluded.last_updated\n                WHERE\n                    value != excluded.value\n                    OR :timestamp - last_updated > :min_update_delta\n            ', {'ieee': 00:15:8d:00:07:be:f4:3b, 'endpoint_id': 1, 'cluster_type': <ClusterType.Server: 0>, 'cluster_id': 1280, 'attr_id': 2, 'value': 1, 'timestamp': 1728568445.60918, 'min_update_delta': 30.0}) completed
2024-10-10 14:54:10.919 DEBUG (MainThread) [zha.application.platforms] 00:15:8d:00:07:be:f4:3b-1-0-rssi: polling for updated state
2024-10-10 14:54:10.919 DEBUG (MainThread) [zha.application.platforms] 00:15:8d:00:07:be:f4:3b-1-0-lqi: polling for updated state

andyb2000 commented 3 weeks ago

Meanwhile since that one kept working, I thought I'd try the same for the Sonoff SNZB-01 (Please tell me if I should send this elsewhere though if it's not helping this issue, it does appear to have happened at the same time so suspecting the ZHA updates)

Debug on, went to add device, put device into pairing. It finds it but gets stuck on "Configuring":

DEBUG output (filtered for the IEEE):

2024-10-10 15:32:08.084 DEBUG (MainThread) [zha.application.platforms] 00:12:4b:00:24:ce:3b:02-1-0-rssi: polling for updated state
2024-10-10 15:32:08.085 DEBUG (MainThread) [zha.application.platforms] 00:12:4b:00:24:ce:3b:02-1-0-lqi: polling for updated state
2024-10-10 15:32:19.785 DEBUG (MainThread) [zigpy_znp.api] Received command: ZDO.TCDevInd.Callback(SrcNwk=0x856C, SrcIEEE=00:12:4b:00:24:ce:3b:02, ParentNwk=0x342F)
2024-10-10 15:32:19.786 INFO (MainThread) [zigpy_znp.zigbee.application] TC device join: ZDO.TCDevInd.Callback(SrcNwk=0x856C, SrcIEEE=00:12:4b:00:24:ce:3b:02, ParentNwk=0x342F)
2024-10-10 15:32:19.786 INFO (MainThread) [zigpy.application] Device 0x856c (00:12:4b:00:24:ce:3b:02) joined the network
2024-10-10 15:32:19.786 DEBUG (MainThread) [zigpy.application] Device 00:12:4b:00:24:ce:3b:02 changed id (0xcc55 => 0x856c)
2024-10-10 15:32:19.787 DEBUG (MainThread) [zha] Emitting event device_joined with data DeviceJoinedEvent(device_info=DeviceJoinedDeviceInfo(ieee=00:12:4b:00:24:ce:3b:02, nwk=0x856C, pairing_status=<DevicePairingStatus.PAIRED: 1>), event_type='zha_gateway_message', event='device_joined') (1 listeners)
2024-10-10 15:32:19.787 DEBUG (MainThread) [zha] (ZHAGatewayProxy) handling event protocol for event: DeviceJoinedEvent(device_info=DeviceJoinedDeviceInfo(ieee=00:12:4b:00:24:ce:3b:02, nwk=0x856C, pairing_status=<DevicePairingStatus.PAIRED: 1>), event_type='zha_gateway_message', event='device_joined')
2024-10-10 15:32:19.788 DEBUG (MainThread) [zigpy.application] Device is initialized <CustomDeviceV2 model='WB01' manuf='eWeLink' nwk=0x856C ieee=00:12:4b:00:24:ce:3b:02 is_initialized=True>
2024-10-10 15:32:19.788 DEBUG (MainThread) [zha] Emitting event raw_device_initialized with data RawDeviceInitializedEvent(device_info=RawDeviceInitializedDeviceInfo(ieee=00:12:4b:00:24:ce:3b:02, nwk=0x856C, pairing_status=<DevicePairingStatus.INTERVIEW_COMPLETE: 2>, model='WB01', manufacturer='eWeLink', signature={'manufacturer': 'eWeLink', 'model': 'WB01', 'node_desc': {'logical_type': <LogicalType.EndDevice: 2>, 'complex_descriptor_available': 0, 'user_descriptor_available': 0, 'reserved': 0, 'aps_flags': 0, 'frequency_band': <FrequencyBand.Freq2400MHz: 8>, 'mac_capability_flags': <MACCapabilityFlags.AllocateAddress: 128>, 'manufacturer_code': 0, 'maximum_buffer_size': 80, 'maximum_incoming_transfer_size': 160, 'server_mask': 0, 'maximum_outgoing_transfer_size': 160, 'descriptor_capability_field': <DescriptorCapability.NONE: 0>}, 'endpoints': {1: {'profile_id': 260, 'device_type': <DeviceType.ON_OFF_SWITCH: 0>, 'input_clusters': [0, 3, 1], 'output_clusters': [6, 3]}}}), event_type='zha_gateway_message', event='raw_device_initialized') (1 listeners)
2024-10-10 15:32:19.789 DEBUG (MainThread) [zha] (ZHAGatewayProxy) handling event protocol for event: RawDeviceInitializedEvent(device_info=RawDeviceInitializedDeviceInfo(ieee=00:12:4b:00:24:ce:3b:02, nwk=0x856C, pairing_status=<DevicePairingStatus.INTERVIEW_COMPLETE: 2>, model='WB01', manufacturer='eWeLink', signature={'manufacturer': 'eWeLink', 'model': 'WB01', 'node_desc': {'logical_type': <LogicalType.EndDevice: 2>, 'complex_descriptor_available': 0, 'user_descriptor_available': 0, 'reserved': 0, 'aps_flags': 0, 'frequency_band': <FrequencyBand.Freq2400MHz: 8>, 'mac_capability_flags': <MACCapabilityFlags.AllocateAddress: 128>, 'manufacturer_code': 0, 'maximum_buffer_size': 80, 'maximum_incoming_transfer_size': 160, 'server_mask': 0, 'maximum_outgoing_transfer_size': 160, 'descriptor_capability_field': <DescriptorCapability.NONE: 0>}, 'endpoints': {1: {'profile_id': 260, 'device_type': <DeviceType.ON_OFF_SWITCH: 0>, 'input_clusters': [0, 3, 1], 'output_clusters': [6, 3]}}}), event_type='zha_gateway_message', event='raw_device_initialized')
2024-10-10 15:32:19.791 DEBUG (MainThread) [zha.application.gateway] device - 0x856C:00:12:4b:00:24:ce:3b:02 entering async_device_initialized - is_new_join: False
2024-10-10 15:32:19.792 DEBUG (MainThread) [zha.application.gateway] device - 0x856C:00:12:4b:00:24:ce:3b:02 has been reset and re-added or its nwk address changed
2024-10-10 15:32:19.792 DEBUG (MainThread) [zha.application.gateway] skipping discovery for previously discovered device - 0x7762:00:12:4b:00:24:ce:3b:02
2024-10-10 15:32:19.797 DEBUG (MainThread) [zha] Emitting event zha_channel_configure_reporting with data ClusterConfigureReportingEvent(cluster_name='Basic', cluster_id=0, attributes={}, cluster_handler_unique_id='00:12:4b:00:24:ce:3b:02:1:0x0000', event_type='zha_channel_message', event='zha_channel_configure_reporting') (1 listeners)
2024-10-10 15:32:19.798 DEBUG (MainThread) [zha] (ZHADeviceProxy) handling event protocol for event: ClusterConfigureReportingEvent(cluster_name='Basic', cluster_id=0, attributes={}, cluster_handler_unique_id='00:12:4b:00:24:ce:3b:02:1:0x0000', event_type='zha_channel_message', event='zha_channel_configure_reporting')
2024-10-10 15:32:19.799 DEBUG (MainThread) [zha] Emitting event zha_channel_configure_reporting with data ClusterConfigureReportingEvent(cluster_name='Identify', cluster_id=3, attributes={}, cluster_handler_unique_id='00:12:4b:00:24:ce:3b:02:1:0x0003', event_type='zha_channel_message', event='zha_channel_configure_reporting') (1 listeners)
2024-10-10 15:32:19.799 DEBUG (Thread-4) [aiosqlite] executing functools.partial(<built-in method execute of sqlite3.Connection object at 0x7f182c732890>, 'UPDATE devices_v13\n                    SET last_seen=:ts\n                    WHERE ieee=:ieee AND :ts - last_seen > :min_update_delta', {'ts': 1728570739.787022, 'ieee': 00:12:4b:00:24:ce:3b:02, 'min_update_delta': 30.0})
2024-10-10 15:32:19.800 DEBUG (Thread-4) [aiosqlite] operation functools.partial(<built-in method execute of sqlite3.Connection object at 0x7f182c732890>, 'UPDATE devices_v13\n                    SET last_seen=:ts\n                    WHERE ieee=:ieee AND :ts - last_seen > :min_update_delta', {'ts': 1728570739.787022, 'ieee': 00:12:4b:00:24:ce:3b:02, 'min_update_delta': 30.0}) completed
2024-10-10 15:32:19.799 DEBUG (MainThread) [zha] (ZHADeviceProxy) handling event protocol for event: ClusterConfigureReportingEvent(cluster_name='Identify', cluster_id=3, attributes={}, cluster_handler_unique_id='00:12:4b:00:24:ce:3b:02:1:0x0003', event_type='zha_channel_message', event='zha_channel_configure_reporting')
2024-10-10 15:32:19.807 DEBUG (Thread-4) [aiosqlite] executing functools.partial(<built-in method execute of sqlite3.Connection object at 0x7f182c732890>, 'UPDATE devices_v13 SET nwk=? WHERE ieee=?', (0x856C, 00:12:4b:00:24:ce:3b:02))
2024-10-10 15:32:19.807 DEBUG (Thread-4) [aiosqlite] operation functools.partial(<built-in method execute of sqlite3.Connection object at 0x7f182c732890>, 'UPDATE devices_v13 SET nwk=? WHERE ieee=?', (0x856C, 00:12:4b:00:24:ce:3b:02)) completed
2024-10-10 15:32:19.814 DEBUG (Thread-4) [aiosqlite] executing functools.partial(<built-in method execute of sqlite3.Connection object at 0x7f182c732890>, 'INSERT INTO devices_v13 (ieee, nwk, status, last_seen)\n                    VALUES (?, ?, ?, ?)\n                    ON CONFLICT (ieee)\n                    DO UPDATE SET\n                        nwk=excluded.nwk,\n                        status=excluded.status,\n                        last_seen=excluded.last_seen', (00:12:4b:00:24:ce:3b:02, 0x856C, <Status.ENDPOINTS_INIT: 2>, 1728570739.787022))
2024-10-10 15:32:19.815 DEBUG (Thread-4) [aiosqlite] operation functools.partial(<built-in method execute of sqlite3.Connection object at 0x7f182c732890>, 'INSERT INTO devices_v13 (ieee, nwk, status, last_seen)\n                    VALUES (?, ?, ?, ?)\n                    ON CONFLICT (ieee)\n                    DO UPDATE SET\n                        nwk=excluded.nwk,\n                        status=excluded.status,\n                        last_seen=excluded.last_seen', (00:12:4b:00:24:ce:3b:02, 0x856C, <Status.ENDPOINTS_INIT: 2>, 1728570739.787022)) completed
2024-10-10 15:32:19.817 DEBUG (Thread-4) [aiosqlite] executing functools.partial(<built-in method execute of sqlite3.Connection object at 0x7f182c732890>, 'INSERT INTO node_descriptors_v13\n                VALUES (?, ?, ?, ?, ?, ?, ?, ?, ?, ?, ?, ?, ?, ?)\n                    ON CONFLICT (ieee)\n                    DO UPDATE SET\n                logical_type=excluded.logical_type,\n                complex_descriptor_available=excluded.complex_descriptor_available,\n                user_descriptor_available=excluded.user_descriptor_available,\n                reserved=excluded.reserved,\n                aps_flags=excluded.aps_flags,\n                frequency_band=excluded.frequency_band,\n                mac_capability_flags=excluded.mac_capability_flags,\n                manufacturer_code=excluded.manufacturer_code,\n                maximum_buffer_size=excluded.maximum_buffer_size,\n                maximum_incoming_transfer_size=excluded.maximum_incoming_transfer_size,\n                server_mask=excluded.server_mask,\n                maximum_outgoing_transfer_size=excluded.maximum_outgoing_transfer_size,\n                descriptor_capability_field=excluded.descriptor_capability_field', (00:12:4b:00:24:ce:3b:02, <LogicalType.EndDevice: 2>, 0, 0, 0, 0, <FrequencyBand.Freq2400MHz: 8>, <MACCapabilityFlags.AllocateAddress: 128>, 0, 80, 160, 0, 160, <DescriptorCapability.NONE: 0>))
2024-10-10 15:32:19.818 DEBUG (Thread-4) [aiosqlite] operation functools.partial(<built-in method execute of sqlite3.Connection object at 0x7f182c732890>, 'INSERT INTO node_descriptors_v13\n                VALUES (?, ?, ?, ?, ?, ?, ?, ?, ?, ?, ?, ?, ?, ?)\n                    ON CONFLICT (ieee)\n                    DO UPDATE SET\n                logical_type=excluded.logical_type,\n                complex_descriptor_available=excluded.complex_descriptor_available,\n                user_descriptor_available=excluded.user_descriptor_available,\n                reserved=excluded.reserved,\n                aps_flags=excluded.aps_flags,\n                frequency_band=excluded.frequency_band,\n                mac_capability_flags=excluded.mac_capability_flags,\n                manufacturer_code=excluded.manufacturer_code,\n                maximum_buffer_size=excluded.maximum_buffer_size,\n                maximum_incoming_transfer_size=excluded.maximum_incoming_transfer_size,\n                server_mask=excluded.server_mask,\n                maximum_outgoing_transfer_size=excluded.maximum_outgoing_transfer_size,\n                descriptor_capability_field=excluded.descriptor_capability_field', (00:12:4b:00:24:ce:3b:02, <LogicalType.EndDevice: 2>, 0, 0, 0, 0, <FrequencyBand.Freq2400MHz: 8>, <MACCapabilityFlags.AllocateAddress: 128>, 0, 80, 160, 0, 160, <DescriptorCapability.NONE: 0>)) completed
2024-10-10 15:32:19.822 DEBUG (Thread-4) [aiosqlite] executing functools.partial(<built-in method executemany of sqlite3.Connection object at 0x7f182c732890>, 'INSERT INTO endpoints_v13 VALUES (?, ?, ?, ?, ?)\n                    ON CONFLICT (ieee, endpoint_id)\n                    DO UPDATE SET\n                        profile_id=excluded.profile_id,\n                        device_type=excluded.device_type,\n                        status=excluded.status', [(00:12:4b:00:24:ce:3b:02, 1, 260, <DeviceType.ON_OFF_SWITCH: 0>, <Status.ZDO_INIT: 1>)])
2024-10-10 15:32:19.824 DEBUG (Thread-4) [aiosqlite] operation functools.partial(<built-in method executemany of sqlite3.Connection object at 0x7f182c732890>, 'INSERT INTO endpoints_v13 VALUES (?, ?, ?, ?, ?)\n                    ON CONFLICT (ieee, endpoint_id)\n                    DO UPDATE SET\n                        profile_id=excluded.profile_id,\n                        device_type=excluded.device_type,\n                        status=excluded.status', [(00:12:4b:00:24:ce:3b:02, 1, 260, <DeviceType.ON_OFF_SWITCH: 0>, <Status.ZDO_INIT: 1>)]) completed
2024-10-10 15:32:19.826 DEBUG (Thread-4) [aiosqlite] executing functools.partial(<built-in method executemany of sqlite3.Connection object at 0x7f182c732890>, 'INSERT INTO clusters_v13 VALUES (?, ?, ?, ?)\n                    ON CONFLICT (ieee, endpoint_id, cluster_type, cluster_id)\n                    DO NOTHING', [(00:12:4b:00:24:ce:3b:02, 1, <ClusterType.Server: 0>, 0), (00:12:4b:00:24:ce:3b:02, 1, <ClusterType.Server: 0>, 3), (00:12:4b:00:24:ce:3b:02, 1, <ClusterType.Server: 0>, 1), (00:12:4b:00:24:ce:3b:02, 1, <ClusterType.Client: 1>, 6), (00:12:4b:00:24:ce:3b:02, 1, <ClusterType.Client: 1>, 3)])
2024-10-10 15:32:19.831 DEBUG (Thread-4) [aiosqlite] operation functools.partial(<built-in method executemany of sqlite3.Connection object at 0x7f182c732890>, 'INSERT INTO clusters_v13 VALUES (?, ?, ?, ?)\n                    ON CONFLICT (ieee, endpoint_id, cluster_type, cluster_id)\n                    DO NOTHING', [(00:12:4b:00:24:ce:3b:02, 1, <ClusterType.Server: 0>, 0), (00:12:4b:00:24:ce:3b:02, 1, <ClusterType.Server: 0>, 3), (00:12:4b:00:24:ce:3b:02, 1, <ClusterType.Server: 0>, 1), (00:12:4b:00:24:ce:3b:02, 1, <ClusterType.Client: 1>, 6), (00:12:4b:00:24:ce:3b:02, 1, <ClusterType.Client: 1>, 3)]) completed
2024-10-10 15:32:19.832 DEBUG (Thread-4) [aiosqlite] executing functools.partial(<built-in method executemany of sqlite3.Connection object at 0x7f182c732890>, 'INSERT INTO attributes_cache_v13 VALUES (?, ?, ?, ?, ?, ?, ?)\n                    ON CONFLICT (ieee, endpoint_id, cluster_type, cluster_id, attr_id)\n                    DO UPDATE SET value=excluded.value, last_updated=excluded.last_updated', [(00:12:4b:00:24:ce:3b:02, 1, <ClusterType.Server: 0>, 0, 4, 'eWeLink', 0.0), (00:12:4b:00:24:ce:3b:02, 1, <ClusterType.Server: 0>, 0, 5, 'WB01', 0.0), (00:12:4b:00:24:ce:3b:02, 1, <ClusterType.Server: 0>, 1, 32, 40, 0.0), (00:12:4b:00:24:ce:3b:02, 1, <ClusterType.Server: 0>, 1, 33, 200, 0.0)])
2024-10-10 15:32:19.834 DEBUG (Thread-4) [aiosqlite] operation functools.partial(<built-in method executemany of sqlite3.Connection object at 0x7f182c732890>, 'INSERT INTO attributes_cache_v13 VALUES (?, ?, ?, ?, ?, ?, ?)\n                    ON CONFLICT (ieee, endpoint_id, cluster_type, cluster_id, attr_id)\n                    DO UPDATE SET value=excluded.value, last_updated=excluded.last_updated', [(00:12:4b:00:24:ce:3b:02, 1, <ClusterType.Server: 0>, 0, 4, 'eWeLink', 0.0), (00:12:4b:00:24:ce:3b:02, 1, <ClusterType.Server: 0>, 0, 5, 'WB01', 0.0), (00:12:4b:00:24:ce:3b:02, 1, <ClusterType.Server: 0>, 1, 32, 40, 0.0), (00:12:4b:00:24:ce:3b:02, 1, <ClusterType.Server: 0>, 1, 33, 200, 0.0)]) completed
2024-10-10 15:32:20.343 DEBUG (MainThread) [zigpy_znp.api] Received command: ZDO.EndDeviceAnnceInd.Callback(Src=0x856C, NWK=0x856C, IEEE=00:12:4b:00:24:ce:3b:02, Capabilities=<MACCapabilities.AllocateShortAddrDuringAssocNeeded: 128>)
2024-10-10 15:32:20.345 INFO (MainThread) [zigpy.application] Device 0x856c (00:12:4b:00:24:ce:3b:02) joined the network
2024-10-10 15:32:20.346 DEBUG (MainThread) [zigpy.zdo] [0x856c:zdo] ZDO request ZDOCmd.Device_annce: [0x856C, 00:12:4b:00:24:ce:3b:02, 128]
2024-10-10 15:32:20.347 DEBUG (Thread-4) [aiosqlite] executing functools.partial(<built-in method execute of sqlite3.Connection object at 0x7f182c732890>, 'UPDATE devices_v13\n                    SET last_seen=:ts\n                    WHERE ieee=:ieee AND :ts - last_seen > :min_update_delta', {'ts': 1728570740.345895, 'ieee': 00:12:4b:00:24:ce:3b:02, 'min_update_delta': 30.0})
2024-10-10 15:32:20.351 DEBUG (Thread-4) [aiosqlite] operation functools.partial(<built-in method execute of sqlite3.Connection object at 0x7f182c732890>, 'UPDATE devices_v13\n                    SET last_seen=:ts\n                    WHERE ieee=:ieee AND :ts - last_seen > :min_update_delta', {'ts': 1728570740.345895, 'ieee': 00:12:4b:00:24:ce:3b:02, 'min_update_delta': 30.0}) completed
2024-10-10 15:32:20.355 DEBUG (Thread-4) [aiosqlite] executing functools.partial(<built-in method execute of sqlite3.Connection object at 0x7f182c732890>, 'UPDATE devices_v13\n                    SET last_seen=:ts\n                    WHERE ieee=:ieee AND :ts - last_seen > :min_update_delta', {'ts': 1728570740.344644, 'ieee': 00:12:4b:00:24:ce:3b:02, 'min_update_delta': 30.0})
2024-10-10 15:32:20.356 DEBUG (Thread-4) [aiosqlite] operation functools.partial(<built-in method execute of sqlite3.Connection object at 0x7f182c732890>, 'UPDATE devices_v13\n                    SET last_seen=:ts\n                    WHERE ieee=:ieee AND :ts - last_seen > :min_update_delta', {'ts': 1728570740.344644, 'ieee': 00:12:4b:00:24:ce:3b:02, 'min_update_delta': 30.0}) completed
2024-10-10 15:32:41.118 DEBUG (MainThread) [zha.application.platforms] 00:12:4b:00:24:ce:3b:02-1-0-rssi: polling for updated state
2024-10-10 15:32:41.119 DEBUG (MainThread) [zha.application.platforms] 00:12:4b:00:24:ce:3b:02-1-0-lqi: polling for updated state
2024-10-10 15:32:49.288 DEBUG (MainThread) [zha] Emitting event zha_channel_bind with data ClusterBindEvent(cluster_name='Power Configuration', cluster_id=1, success=False, cluster_handler_unique_id='00:12:4b:00:24:ce:3b:02:1:0x0001', event_type='zha_channel_message', event='zha_channel_bind') (1 listeners)
2024-10-10 15:32:49.289 DEBUG (MainThread) [zha] (ZHADeviceProxy) handling event protocol for event: ClusterBindEvent(cluster_name='Power Configuration', cluster_id=1, success=False, cluster_handler_unique_id='00:12:4b:00:24:ce:3b:02:1:0x0001', event_type='zha_channel_message', event='zha_channel_bind')
2024-10-10 15:32:49.375 DEBUG (MainThread) [zha] Emitting event zha_channel_bind with data ClusterBindEvent(cluster_name='On/Off', cluster_id=6, success=False, cluster_handler_unique_id='00:12:4b:00:24:ce:3b:02:1:0x0006', event_type='zha_channel_message', event='zha_channel_bind') (1 listeners)
2024-10-10 15:32:49.376 DEBUG (MainThread) [zha] (ZHADeviceProxy) handling event protocol for event: ClusterBindEvent(cluster_name='On/Off', cluster_id=6, success=False, cluster_handler_unique_id='00:12:4b:00:24:ce:3b:02:1:0x0006', event_type='zha_channel_message', event='zha_channel_bind')
2024-10-10 15:33:14.152 DEBUG (MainThread) [zha.application.platforms] 00:12:4b:00:24:ce:3b:02-1-0-rssi: polling for updated state
2024-10-10 15:33:14.152 DEBUG (MainThread) [zha.application.platforms] 00:12:4b:00:24:ce:3b:02-1-0-lqi: polling for updated state
2024-10-10 15:33:17.327 DEBUG (MainThread) [zha] Emitting event zha_channel_configure_reporting with data ClusterConfigureReportingEvent(cluster_name='Power Configuration', cluster_id=1, attributes={'battery_voltage': {'min': 3600, 'max': 10800, 'id': 'battery_voltage', 'name': 'battery_voltage', 'change': 1, 'status': None}, 'battery_percentage_remaining': {'min': 3600, 'max': 10800, 'id': 'battery_percentage_remaining', 'name': 'battery_percentage_remaining', 'change': 1, 'status': None}}, cluster_handler_unique_id='00:12:4b:00:24:ce:3b:02:1:0x0001', event_type='zha_channel_message', event='zha_channel_configure_reporting') (1 listeners)
2024-10-10 15:33:17.328 DEBUG (MainThread) [zha] (ZHADeviceProxy) handling event protocol for event: ClusterConfigureReportingEvent(cluster_name='Power Configuration', cluster_id=1, attributes={'battery_voltage': {'min': 3600, 'max': 10800, 'id': 'battery_voltage', 'name': 'battery_voltage', 'change': 1, 'status': None}, 'battery_percentage_remaining': {'min': 3600, 'max': 10800, 'id': 'battery_percentage_remaining', 'name': 'battery_percentage_remaining', 'change': 1, 'status': None}}, cluster_handler_unique_id='00:12:4b:00:24:ce:3b:02:1:0x0001', event_type='zha_channel_message', event='zha_channel_configure_reporting')
2024-10-10 15:33:17.333 DEBUG (MainThread) [zha] Emitting event zha_channel_cfg_done with data ClusterHandlerConfigurationComplete(device_ieee=00:12:4b:00:24:ce:3b:02, unique_id=00:12:4b:00:24:ce:3b:02, event_type='zha_channel_message', event='zha_channel_cfg_done') (1 listeners)
2024-10-10 15:33:17.333 DEBUG (MainThread) [zha] (ZHADeviceProxy) handling event protocol for event: ClusterHandlerConfigurationComplete(device_ieee=00:12:4b:00:24:ce:3b:02, unique_id=00:12:4b:00:24:ce:3b:02, event_type='zha_channel_message', event='zha_channel_cfg_done')
2024-10-10 15:33:47.184 DEBUG (MainThread) [zha.application.platforms] 00:12:4b:00:24:ce:3b:02-1-0-rssi: polling for updated state
2024-10-10 15:33:47.184 DEBUG (MainThread) [zha.application.platforms] 00:12:4b:00:24:ce:3b:02-1-0-lqi: polling for updated state
2024-10-10 15:34:20.219 DEBUG (MainThread) [zha.application.platforms] 00:12:4b:00:24:ce:3b:02-1-0-rssi: polling for updated state
2024-10-10 15:34:20.220 DEBUG (MainThread) [zha.application.platforms] 00:12:4b:00:24:ce:3b:02-1-0-lqi: polling for updated state
2024-10-10 15:34:53.256 DEBUG (MainThread) [zha.application.platforms] 00:12:4b:00:24:ce:3b:02-1-0-rssi: polling for updated state
2024-10-10 15:34:53.256 DEBUG (MainThread) [zha.application.platforms] 00:12:4b:00:24:ce:3b:02-1-0-lqi: polling for updated state

It seems to state it completes/configurationdone but it doesn't report in the gui and it doesn't then start reporting values.

waltailji commented 3 weeks ago

can you upgrade again please and attach the zigbee.db here. Give us the db before and after the upgrade please.

@dmulcahey here are the db files before and after the upgrade (just performed a few moments ago). It doesn't look like the zigbee.db actually changed so I'm also attaching zigbee.db-shm and zigbee.db-wal that showed up on the 2024.10.1:

zigbee db files.zip

puddly commented 3 weeks ago

@waltailji In your config entry, I see you've changed the ZHA database path to /share/zigbee.db. Do you also have a /config/zigbee.db file? If so, can you upload that one too?

puddly commented 3 weeks ago

Also, just so that we understand how people are using this, could you explain why you changed the database path from the default of /config/zigbee.db?

waltailji commented 3 weeks ago

@waltailji In your config entry, I see you've changed the ZHA database path to /share/zigbee.db. Do you also have a /config/zigbee.db file? If so, can you upload that one too?

@puddly I'm not sure where I got this setting from but I've been running with it for a few years now... at least back to version 0.118.2, which is the oldest backup I have. Should I change it to /config/zigbee.db?

waltailji commented 3 weeks ago

Here are the two zigbee.db files from my config and share folders: zigbee_share_config.zip

puddly commented 3 weeks ago

Should I change it to /config/zigbee.db?

I would delete any references to a database path from your YAML config and make sure /config/zigbee.db is your up-to-date database. ZHA doesn't require any YAML config to function.

waltailji commented 3 weeks ago

I would delete any references to a database path from your YAML config and make sure /config/zigbee.db is your up-to-date database. ZHA doesn't require any YAML config to function.

That did the trick. Tested it out on 2024.7.3 to make sure everything still showed up okay, then upgraded to 2024.10.1. Everything is there. Thanks @puddly.

dmulcahey commented 3 weeks ago

Sorry about that. We'll get it cleaned up.

tbrausch commented 3 weeks ago

@dmulcahey - I had also moved my ZHA database to a sub-directory. After moving it back to /config everything now works after the update. Thanks for your persistence on this,

home-assistant / core