search

zigpy / zha-device-handlers

ZHA device handlers bridge the functionality gap created when manufacturers deviate from the ZCL specification, handling deviations and exceptions by parsing custom messages to and from Zigbee devices.
Apache License 2.0
720 stars 669 forks source link

[BUG] Issue pairing and subsequent updating of Aqara FP1 (zhaquirks.xiaomi.aqara.motion_ac01.AqaraLumiMotionAc01) #2276

Closed cvocvo closed 1 year ago

cvocvo commented 1 year ago

Describe the bug I am trying to deploy an Aqara FP1 via ZHA on Home Assistant (latest version). I'm able to detect and add the Aqara FP1, however, it fails to add other sensors and it fails to load device information such as Device Temperature. Last Seen timestamp also fails to update. I've tried resetting the device and repairing ~10 times and have power cycled the device and also restarted Home Assistant several times.

To Reproduce What I'm doing is:

Expected behavior Other users with ZHA such as this person have a setup that includes more data and also seems to work. screenshot via: http://www.youtube.com/watch?v=8Ri2LCvH3-g&t=14m43s image

Screenshots image

image

Device Reconfiguration also fails: image

Device signature ```yaml { "node_descriptor": "NodeDescriptor(logical_type=, complex_descriptor_available=0, user_descriptor_available=0, reserved=0, aps_flags=0, frequency_band=, mac_capability_flags=, manufacturer_code=4660, maximum_buffer_size=108, maximum_incoming_transfer_size=127, server_mask=11264, maximum_outgoing_transfer_size=127, descriptor_capability_field=, *allocate_address=True, *is_alternate_pan_coordinator=False, *is_coordinator=False, *is_end_device=True, *is_full_function_device=False, *is_mains_powered=True, *is_receiver_on_when_idle=True, *is_router=False, *is_security_capable=False)", "endpoints": { "1": { "profile_id": 260, "device_type": "0xfff0", "in_clusters": [ "0x0000", "0x0002", "0x0003", "0x0406", "0xfcc0" ], "out_clusters": [ "0x0003", "0x0019" ] } }, "manufacturer": "aqara", "model": "lumi.motion.ac01", "class": "zhaquirks.xiaomi.aqara.motion_ac01.AqaraLumiMotionAc01" } ```
Diagnostic information ```yaml { "home_assistant": { "installation_type": "Home Assistant OS", "version": "2023.3.4", "dev": false, "hassio": true, "virtualenv": false, "python_version": "3.10.10", "docker": true, "arch": "x86_64", "timezone": "America/Chicago", "os_name": "Linux", "os_version": "5.15.90", "supervisor": "2023.03.1", "host_os": "Home Assistant OS 9.5", "docker_version": "20.10.22", "chassis": "vm", "run_as_root": true }, "custom_components": { "dyson_cloud": { "version": "0.15.0", "requirements": [ "libdyson==0.8.7" ] }, "weatheralerts": { "version": "0.1.5", "requirements": [] }, "dlink_hnap": { "version": "1.0.0", "requirements": [] }, "hacs": { "version": "1.31.0", "requirements": [ "aiogithubapi>=22.10.1" ] }, "dyson_local": { "version": "0.16.4-4", "requirements": [ "libdyson==0.8.11" ] }, "simple_wyze_vac": { "version": "1.7.3", "requirements": [ "https://github.com/romedtino/wyze-sdk/archive/refs/tags/10.2.7.zip#wyze-sdk==10.2.7" ] }, "icloud3": { "version": "2.4.6", "requirements": [] }, "frigate": { "version": "4.0.0-beta4", "requirements": [ "pytz==2022.7" ] } }, "integration_manifest": { "domain": "zha", "name": "Zigbee Home Automation", "after_dependencies": [ "onboarding", "usb" ], "codeowners": [ "@dmulcahey", "@adminiuga", "@puddly" ], "config_flow": true, "dependencies": [ "file_upload" ], "documentation": "https://www.home-assistant.io/integrations/zha", "iot_class": "local_polling", "loggers": [ "aiosqlite", "bellows", "crccheck", "pure_pcapy3", "zhaquirks", "zigpy", "zigpy_deconz", "zigpy_xbee", "zigpy_zigate", "zigpy_znp" ], "requirements": [ "bellows==0.34.10", "pyserial==3.5", "pyserial-asyncio==0.6", "zha-quirks==0.0.94", "zigpy-deconz==0.19.2", "zigpy==0.53.2", "zigpy-xbee==0.16.2", "zigpy-zigate==0.10.3", "zigpy-znp==0.9.3" ], "usb": [ { "vid": "10C4", "pid": "EA60", "description": "*2652*", "known_devices": [ "slae.sh cc2652rb stick" ] }, { "vid": "1A86", "pid": "55D4", "description": "*sonoff*plus*", "known_devices": [ "sonoff zigbee dongle plus v2" ] }, { "vid": "10C4", "pid": "EA60", "description": "*sonoff*plus*", "known_devices": [ "sonoff zigbee dongle plus" ] }, { "vid": "10C4", "pid": "EA60", "description": "*tubeszb*", "known_devices": [ "TubesZB Coordinator" ] }, { "vid": "1A86", "pid": "7523", "description": "*tubeszb*", "known_devices": [ "TubesZB Coordinator" ] }, { "vid": "1A86", "pid": "7523", "description": "*zigstar*", "known_devices": [ "ZigStar Coordinators" ] }, { "vid": "1CF1", "pid": "0030", "description": "*conbee*", "known_devices": [ "Conbee II" ] }, { "vid": "10C4", "pid": "8A2A", "description": "*zigbee*", "known_devices": [ "Nortek HUSBZB-1" ] }, { "vid": "0403", "pid": "6015", "description": "*zigate*", "known_devices": [ "ZiGate+" ] }, { "vid": "10C4", "pid": "EA60", "description": "*zigate*", "known_devices": [ "ZiGate" ] }, { "vid": "10C4", "pid": "8B34", "description": "*bv 2010/10*", "known_devices": [ "Bitron Video AV2010/10" ] } ], "zeroconf": [ { "type": "_esphomelib._tcp.local.", "name": "tube*" }, { "type": "_zigate-zigbee-gateway._tcp.local.", "name": "*zigate*" }, { "type": "_zigstar_gw._tcp.local.", "name": "*zigstar*" }, { "type": "_slzb-06._tcp.local.", "name": "slzb-06*" } ], "is_built_in": true }, "data": { "ieee": "**REDACTED**", "nwk": 12126, "manufacturer": "aqara", "model": "lumi.motion.ac01", "name": "aqara lumi.motion.ac01", "quirk_applied": true, "quirk_class": "zhaquirks.xiaomi.aqara.motion_ac01.AqaraLumiMotionAc01", "manufacturer_code": 4660, "power_source": "Mains", "lqi": null, "rssi": null, "last_seen": "2023-03-15T19:52:50", "available": true, "device_type": "EndDevice", "signature": { "node_descriptor": "NodeDescriptor(logical_type=, complex_descriptor_available=0, user_descriptor_available=0, reserved=0, aps_flags=0, frequency_band=, mac_capability_flags=, manufacturer_code=4660, maximum_buffer_size=108, maximum_incoming_transfer_size=127, server_mask=11264, maximum_outgoing_transfer_size=127, descriptor_capability_field=, *allocate_address=True, *is_alternate_pan_coordinator=False, *is_coordinator=False, *is_end_device=True, *is_full_function_device=False, *is_mains_powered=True, *is_receiver_on_when_idle=True, *is_router=False, *is_security_capable=False)", "endpoints": { "1": { "profile_id": 260, "device_type": "0xfff0", "in_clusters": [ "0x0000", "0x0002", "0x0003", "0x0406", "0xfcc0" ], "out_clusters": [ "0x0003", "0x0019" ] } } }, "active_coordinator": false, "entities": [ { "entity_id": "binary_sensor.aqara_lumi_motion_ac01_occupancy", "name": "aqara lumi.motion.ac01" }, { "entity_id": "button.aqara_lumi_motion_ac01_identify", "name": "aqara lumi.motion.ac01" }, { "entity_id": "button.aqara_lumi_motion_ac01_presence_status_reset", "name": "aqara lumi.motion.ac01" }, { "entity_id": "sensor.aqara_lumi_motion_ac01_device_temperature", "name": "aqara lumi.motion.ac01" } ], "neighbors": [], "routes": [], "endpoint_names": [ { "name": "undefined_0xfff0" } ], "user_given_name": null, "device_reg_id": "5f514ac7f5fecb5af5eee625a4f41251", "area_id": null, "cluster_details": { "1": { "device_type": { "name": "undefined_0xfff0", "id": 65520 }, "profile_id": 260, "in_clusters": { "0x0000": { "endpoint_attribute": "basic", "attributes": { "0x0004": { "attribute_name": "manufacturer", "value": "aqara" }, "0x0005": { "attribute_name": "model", "value": "lumi.motion.ac01" } }, "unsupported_attributes": {} }, "0x0003": { "endpoint_attribute": "identify", "attributes": {}, "unsupported_attributes": {} }, "0x0002": { "endpoint_attribute": "device_temperature", "attributes": {}, "unsupported_attributes": {} }, "0x0406": { "endpoint_attribute": "occupancy", "attributes": {}, "unsupported_attributes": {} }, "0xfcc0": { "endpoint_attribute": "opple_cluster", "attributes": {}, "unsupported_attributes": {} } }, "out_clusters": { "0x0003": { "endpoint_attribute": "identify", "attributes": {}, "unsupported_attributes": {} }, "0x0019": { "endpoint_attribute": "ota", "attributes": {}, "unsupported_attributes": {} } } } } } } ```
Additional logs ``` During setup, I'm seeing this popup in the logs: [0x35DB](lumi.motion.ac01): power source: Mains [0x35DB](lumi.motion.ac01): completed initialization monitoring_mode is not supported - skipping AqaraMonitoringMode entity creation approach_distance is not supported - skipping AqaraApproachDistance entity creation motion_sensitivity is not supported - skipping AqaraMotionSensitivity entity creation Here's the log output when I try to add it: [0xC315](DS01): Device seen - marking the device available and resetting counter [0xC315](DS01): Update device availability - device available: True - new availability: True - changed: False [0x72F8](S31 Lite zb): Device seen - marking the device available and resetting counter [0x72F8](S31 Lite zb): Update device availability - device available: True - new availability: True - changed: False [0x9F5A](TH01): Device seen - marking the device available and resetting counter [0x9F5A](TH01): Update device availability - device available: True - new availability: True - changed: False [0x9602](unk_model): last_seen is None, marking the device unavailable [0x9602](unk_model): Update device availability - device available: False - new availability: False - changed: False New device 0x095b (54:ef:44:10:00:6d:ac:e3) joined the network [0x095b] Scheduling initialization Tries remaining: 3 [0x095b] Requesting 'Node Descriptor' Tries remaining: 2 [0x095b] Extending timeout for 0x28 request Received a packet: ZigbeePacket(src=AddrModeAddress(addr_mode=, address=0x095B), src_ep=0, dst=AddrModeAddress(addr_mode=, address=), dst_ep=0, source_route=None, extended_timeout=False, tsn=108, profile_id=0, cluster_id=19, data=Serialized[b'\x01[\t\xe3\xacm\x00\x10D\xefT\x8c'], tx_options=, radius=0, non_member_radius=0, lqi=255, rssi=-53) Device 0x095b (54:ef:44:10:00:6d:ac:e3) joined the network [0x095b] Scheduling initialization [0x095b] Canceling old initialize call Received frame on uninitialized device from ep 0 to ep 0, cluster 19: b'\x01[\t\xe3\xacm\x00\x10D\xefT\x8c' [0x095b:zdo] ZDO request ZDOCmd.Device_annce: [0x095B, 54:ef:44:10:00:6d:ac:e3, 140] Received a packet: ZigbeePacket(src=AddrModeAddress(addr_mode=, address=0x095B), src_ep=0, dst=AddrModeAddress(addr_mode=, address=0x0000), dst_ep=0, source_route=None, extended_timeout=False, tsn=109, profile_id=0, cluster_id=32770, data=Serialized[b'(\x00[\t\x02@\x8c4\x12l\x7f\x00\x00,\x7f\x00\x00'], tx_options=, radius=0, non_member_radius=0, lqi=255, rssi=-53) Received frame on uninitialized device from ep 0 to ep 0, cluster 32770: b'(\x00[\t\x02@\x8c4\x12l\x7f\x00\x00,\x7f\x00\x00' [0x095b] Got Node Descriptor: NodeDescriptor(logical_type=, complex_descriptor_available=0, user_descriptor_available=0, reserved=0, aps_flags=0, frequency_band=, mac_capability_flags=, manufacturer_code=4660, maximum_buffer_size=108, maximum_incoming_transfer_size=127, server_mask=11264, maximum_outgoing_transfer_size=127, descriptor_capability_field=, *allocate_address=True, *is_alternate_pan_coordinator=False, *is_coordinator=False, *is_end_device=True, *is_full_function_device=False, *is_mains_powered=True, *is_receiver_on_when_idle=True, *is_router=False, *is_security_capable=False) [0x095b] Discovering endpoints Tries remaining: 3 [0x095b] Extending timeout for 0x2a request Tries remaining: 3 [0x095b] Discovering endpoints Tries remaining: 3 [0x095b] Extending timeout for 0x2c request Received a packet: ZigbeePacket(src=AddrModeAddress(addr_mode=, address=0x095B), src_ep=0, dst=AddrModeAddress(addr_mode=, address=0x0000), dst_ep=0, source_route=None, extended_timeout=False, tsn=110, profile_id=0, cluster_id=32773, data=Serialized[b'*\x00[\t\x01\x01'], tx_options=, radius=0, non_member_radius=0, lqi=255, rssi=-52) Received frame on uninitialized device from ep 0 to ep 0, cluster 32773: b'*\x00[\t\x01\x01' [0x095b] Discovered endpoints: [1] [0x095b] Initializing endpoints [>] [0x095b:1] Discovering endpoint information Tries remaining: 3 [0x095b] Extending timeout for 0x2e request Received a packet: ZigbeePacket(src=AddrModeAddress(addr_mode=, address=0x095B), src_ep=0, dst=AddrModeAddress(addr_mode=, address=0x0000), dst_ep=0, source_route=None, extended_timeout=False, tsn=111, profile_id=0, cluster_id=32773, data=Serialized[b',\x00[\t\x01\x01'], tx_options=, radius=0, non_member_radius=0, lqi=255, rssi=-52) Received frame on uninitialized device from ep 0 to ep 0, cluster 32773: b',\x00[\t\x01\x01' [0x095b] Discovered endpoints: [1] [0x095b] Initializing endpoints [>] [0x095b:1] Discovering endpoint information Tries remaining: 3 [0x095b] Extending timeout for 0x30 request Received a packet: ZigbeePacket(src=AddrModeAddress(addr_mode=, address=0x095B), src_ep=0, dst=AddrModeAddress(addr_mode=, address=0x0000), dst_ep=0, source_route=None, extended_timeout=False, tsn=112, profile_id=0, cluster_id=32772, data=Serialized[b'.\x00[\t\x12\x01\x04\x01\xf0\xff\x00\x03\x00\x00\x03\x00\xc0\xfc\x02\x03\x00\x19\x00'], tx_options=, radius=0, non_member_radius=0, lqi=255, rssi=-52) Received frame on uninitialized device from ep 0 to ep 0, cluster 32772: b'.\x00[\t\x12\x01\x04\x01\xf0\xff\x00\x03\x00\x00\x03\x00\xc0\xfc\x02\x03\x00\x19\x00' [0x095b:1] Discovered endpoint information: SizePrefixedSimpleDescriptor(endpoint=1, profile=260, device_type=65520, device_version=0, input_clusters=[0, 3, 64704], output_clusters=[3, 25]) [0x095b] Read model None and manufacturer None from > [0x095b] Discovered basic device information for Device is initialized Checking quirks for None None (54:ef:44:10:00:6d:ac:e3) Considering Fail because endpoint list mismatch: {1, 2, 242} {1} Considering Fail because endpoint list mismatch: {1, 2, 41, 42, 242, 51, 21, 31} {1} Considering Fail because endpoint list mismatch: {232, 230} {1} Considering Fail because endpoint list mismatch: {232, 230} {1} Considering Fail because profile_id mismatch on at least one endpoint Considering Fail because profile_id mismatch on at least one endpoint Considering Fail because profile_id mismatch on at least one endpoint Considering Fail because profile_id mismatch on at least one endpoint Considering Fail because endpoint list mismatch: {11, 13} {1} Considering Fail because endpoint list mismatch: {1, 2, 242} {1} Considering Fail because endpoint list mismatch: {1, 2, 41, 42, 242, 51, 21, 31} {1} Considering Fail because endpoint list mismatch: {232, 230} {1} Considering Fail because endpoint list mismatch: {232, 230} {1} Considering Fail because profile_id mismatch on at least one endpoint Considering Fail because profile_id mismatch on at least one endpoint Considering Fail because profile_id mismatch on at least one endpoint Considering Fail because profile_id mismatch on at least one endpoint Considering Fail because endpoint list mismatch: {11, 13} {1} Considering Fail because endpoint list mismatch: {1, 2, 242} {1} Considering Fail because endpoint list mismatch: {1, 2, 41, 42, 242, 51, 21, 31} {1} Considering Fail because endpoint list mismatch: {232, 230} {1} Considering Fail because endpoint list mismatch: {232, 230} {1} Considering Fail because profile_id mismatch on at least one endpoint Considering Fail because profile_id mismatch on at least one endpoint Considering Fail because profile_id mismatch on at least one endpoint Considering Fail because profile_id mismatch on at least one endpoint Considering Fail because endpoint list mismatch: {11, 13} {1} Considering Fail because endpoint list mismatch: {1, 2, 242} {1} Considering Fail because endpoint list mismatch: {1, 2, 41, 42, 242, 51, 21, 31} {1} Considering Fail because endpoint list mismatch: {232, 230} {1} Considering Fail because endpoint list mismatch: {232, 230} {1} Considering Fail because profile_id mismatch on at least one endpoint Considering Fail because profile_id mismatch on at least one endpoint Considering Fail because profile_id mismatch on at least one endpoint Considering Fail because profile_id mismatch on at least one endpoint Considering Fail because endpoint list mismatch: {11, 13} {1} device - 0x095B:54:ef:44:10:00:6d:ac:e3 entering async_device_initialized - is_new_join: True device - 0x095B:54:ef:44:10:00:6d:ac:e3 has joined the ZHA zigbee network [0x095B](unk_model): started configuration [0x095B:ZDO](unk_model): 'async_configure' stage succeeded [0x095B](unk_model): completed configuration [0x095B](unk_model): started initialization [0x095B:ZDO](unk_model): 'async_initialize' stage succeeded [0x095B](unk_model): power source: Mains [0x095B](unk_model): completed initialization Error handling '_save_device' event with (,) params: NOT NULL constraint failed: endpoints_v11.profile_id Received a packet: ZigbeePacket(src=AddrModeAddress(addr_mode=, address=0x095B), src_ep=0, dst=AddrModeAddress(addr_mode=, address=0x0000), dst_ep=0, source_route=None, extended_timeout=False, tsn=113, profile_id=0, cluster_id=32772, data=Serialized[b'0\x00[\t\x12\x01\x04\x01\xf0\xff\x00\x03\x00\x00\x03\x00\xc0\xfc\x02\x03\x00\x19\x00'], tx_options=, radius=0, non_member_radius=0, lqi=255, rssi=-51) Received frame on uninitialized device from ep 0 to ep 0, cluster 32772: b'0\x00[\t\x12\x01\x04\x01\xf0\xff\x00\x03\x00\x00\x03\x00\xc0\xfc\x02\x03\x00\x19\x00' [0x095b:1] Discovered endpoint information: SizePrefixedSimpleDescriptor(endpoint=1, profile=260, device_type=65520, device_version=0, input_clusters=[0, 3, 64704], output_clusters=[3, 25]) [0x095B:1:0x0000] Sending request header: ZCLHeader(frame_control=FrameControl(frame_type=, is_manufacturer_specific=False, direction=, disable_default_response=0, reserved=0, *is_cluster=False, *is_general=True, *is_reply=False), tsn=50, command_id=, *direction=, *is_reply=False) [0x095B:1:0x0000] Sending request: Read_Attributes(attribute_ids=[4, 5]) [0x095b] Extending timeout for 0x32 request Received a packet: ZigbeePacket(src=AddrModeAddress(addr_mode=, address=0x095B), src_ep=1, dst=AddrModeAddress(addr_mode=, address=0x0000), dst_ep=1, source_route=None, extended_timeout=False, tsn=114, profile_id=260, cluster_id=0, data=Serialized[b'\x182\x01\x04\x00\x00B\x05aqara\x05\x00\x00B\x10lumi.motion.ac01'], tx_options=, radius=0, non_member_radius=0, lqi=255, rssi=-51) [0x095B:1:0x0000] Received ZCL frame: b'\x182\x01\x04\x00\x00B\x05aqara\x05\x00\x00B\x10lumi.motion.ac01' [0x095B:1:0x0000] Decoded ZCL frame header: ZCLHeader(frame_control=FrameControl(frame_type=, is_manufacturer_specific=0, direction=, disable_default_response=1, reserved=0, *is_cluster=False, *is_general=True, *is_reply=True), tsn=50, command_id=1, *direction=, *is_reply=True) [0x095B:1:0x0000] Decoded ZCL frame: Basic:Read_Attributes_rsp(status_records=[ReadAttributeRecord(attrid=0x0004, status=, value=TypeValue(type=CharacterString, value='aqara')), ReadAttributeRecord(attrid=0x0005, status=, value=TypeValue(type=CharacterString, value='lumi.motion.ac01'))]) [0x095b] Read model 'lumi.motion.ac01' and manufacturer 'aqara' from > [0x095b] Discovered basic device information for Device is initialized Checking quirks for aqara lumi.motion.ac01 (54:ef:44:10:00:6d:ac:e3) Considering Found custom device replacement for 54:ef:44:10:00:6d:ac:e3: device - 0x095B:54:ef:44:10:00:6d:ac:e3 entering async_device_initialized - is_new_join: False device - 0x095B:54:ef:44:10:00:6d:ac:e3 has been reset and re-added or its nwk address changed skipping discovery for previously discovered device - 0x095B:54:ef:44:10:00:6d:ac:e3 [0x095B](lumi.motion.ac01): started configuration [0x095B:ZDO](lumi.motion.ac01): 'async_configure' stage succeeded [0x095B](lumi.motion.ac01): completed configuration [0x095B](lumi.motion.ac01): Update device availability - device available: False - new availability: True - changed: True [0x095B](lumi.motion.ac01): Device availability changed and device became available, reinitializing channels [0x095B](lumi.motion.ac01): started initialization [0x095B:ZDO](lumi.motion.ac01): 'async_initialize' stage succeeded [0x095B](lumi.motion.ac01): power source: Mains [0x095B](lumi.motion.ac01): completed initialization [0x72F8](S31 Lite zb): Device seen - marking the device available and resetting counter [0x72F8](S31 Lite zb): Update device availability - device available: True - new availability: True - changed: False Received a packet: ZigbeePacket(src=AddrModeAddress(addr_mode=, address=0x095B), src_ep=0, dst=AddrModeAddress(addr_mode=, address=0x0000), dst_ep=0, source_route=None, extended_timeout=False, tsn=115, profile_id=0, cluster_id=2, data=Serialized[b'\x02\x00\x00'], tx_options=, radius=0, non_member_radius=0, lqi=255, rssi=-52) [0x095b:zdo] ZDO request ZDOCmd.Node_Desc_req: [0x0000] [0x095b:zdo] No handler for ZDO request:ZDOCmd.Node_Desc_req([0x0000]) Device 0x095b (54:ef:44:10:00:6d:ac:e3) left the network [0x095B](lumi.motion.ac01): Update device availability - device available: True - new availability: False - changed: True [0x095B](lumi.motion.ac01): Device availability changed and device became unavailable [0x66E6](S31 Lite zb): Device seen - marking the device available and resetting counter [0x66E6](S31 Lite zb): Update device availability - device available: True - new availability: True - changed: False [0x66E6](S31 Lite zb): Device seen - marking the device available and resetting counter [0x66E6](S31 Lite zb): Update device availability - device available: True - new availability: True - changed: False [0x9602](unk_model): last_seen is None, marking the device unavailable [0x9602](unk_model): Update device availability - device available: False - new availability: False - changed: False [0x5C07](WB01): Device seen - marking the device available and resetting counter [0x5C07](WB01): Update device availability - device available: True - new availability: True - changed: False [0xF3B8](TH01): Device seen - marking the device available and resetting counter [0xF3B8](TH01): Update device availability - device available: True - new availability: True - changed: False ```

Additional context Add any other context about the problem here.

cvocvo commented 1 year ago

I did a device removal, reboot of HASS OS, and reset of the Aqara FP1; I got the logs during pairing that show more of the errors I think:

Logs during pairing ``` [0xF3B8](TH01): Device seen - marking the device available and resetting counter [0xF3B8](TH01): Update device availability - device available: True - new availability: True - changed: False [0x72F8](S31 Lite zb): Device seen - marking the device available and resetting counter [0x72F8](S31 Lite zb): Update device availability - device available: True - new availability: True - changed: False [0x8C12](WB01): Device seen - marking the device available and resetting counter [0x8C12](WB01): Update device availability - device available: True - new availability: True - changed: False [0x916B](S31 Lite zb): Device seen - marking the device available and resetting counter [0x916B](S31 Lite zb): Update device availability - device available: True - new availability: True - changed: False [0x5C07](WB01): Device seen - marking the device available and resetting counter [0x5C07](WB01): Update device availability - device available: True - new availability: True - changed: False [0x9F5A](TH01): Device seen - marking the device available and resetting counter [0x9F5A](TH01): Update device availability - device available: True - new availability: True - changed: False New device 0x782c (54:ef:44:10:00:6d:ac:e3) joined the network [0x782c] Scheduling initialization Tries remaining: 3 [0x782c] Requesting 'Node Descriptor' Tries remaining: 2 [0x782c] Extending timeout for 0x21 request Received a packet: ZigbeePacket(src=AddrModeAddress(addr_mode=, address=0x782C), src_ep=0, dst=AddrModeAddress(addr_mode=, address=), dst_ep=0, source_route=None, extended_timeout=False, tsn=132, profile_id=0, cluster_id=19, data=Serialized[b'\x01,x\xe3\xacm\x00\x10D\xefT\x8c'], tx_options=, radius=0, non_member_radius=0, lqi=255, rssi=-50) Device 0x782c (54:ef:44:10:00:6d:ac:e3) joined the network [0x782c] Scheduling initialization [0x782c] Canceling old initialize call Received frame on uninitialized device from ep 0 to ep 0, cluster 19: b'\x01,x\xe3\xacm\x00\x10D\xefT\x8c' [0x782c:zdo] ZDO request ZDOCmd.Device_annce: [0x782C, 54:ef:44:10:00:6d:ac:e3, 140] Tries remaining: 3 [0x782c] Requesting 'Node Descriptor' Tries remaining: 2 [0x782c] Extending timeout for 0x23 request Received a packet: ZigbeePacket(src=AddrModeAddress(addr_mode=, address=0x782C), src_ep=0, dst=AddrModeAddress(addr_mode=, address=0x0000), dst_ep=0, source_route=None, extended_timeout=False, tsn=133, profile_id=0, cluster_id=32770, data=Serialized[b'!\x00,x\x02@\x8c4\x12l\x7f\x00\x00,\x7f\x00\x00'], tx_options=, radius=0, non_member_radius=0, lqi=255, rssi=-50) Received frame on uninitialized device from ep 0 to ep 0, cluster 32770: b'!\x00,x\x02@\x8c4\x12l\x7f\x00\x00,\x7f\x00\x00' [0x782c:zdo] ZDO request ZDOCmd.Node_Desc_rsp: [, 0x782C, NodeDescriptor(logical_type=, complex_descriptor_available=0, user_descriptor_available=0, reserved=0, aps_flags=0, frequency_band=, mac_capability_flags=, manufacturer_code=4660, maximum_buffer_size=108, maximum_incoming_transfer_size=127, server_mask=11264, maximum_outgoing_transfer_size=127, descriptor_capability_field=, *allocate_address=True, *is_alternate_pan_coordinator=False, *is_coordinator=False, *is_end_device=True, *is_full_function_device=False, *is_mains_powered=True, *is_receiver_on_when_idle=True, *is_router=False, *is_security_capable=False)] [0x782c:zdo] No handler for ZDO request:ZDOCmd.Node_Desc_rsp([, 0x782C, NodeDescriptor(logical_type=, complex_descriptor_available=0, user_descriptor_available=0, reserved=0, aps_flags=0, frequency_band=, mac_capability_flags=, manufacturer_code=4660, maximum_buffer_size=108, maximum_incoming_transfer_size=127, server_mask=11264, maximum_outgoing_transfer_size=127, descriptor_capability_field=, *allocate_address=True, *is_alternate_pan_coordinator=False, *is_coordinator=False, *is_end_device=True, *is_full_function_device=False, *is_mains_powered=True, *is_receiver_on_when_idle=True, *is_router=False, *is_security_capable=False)]) Received a packet: ZigbeePacket(src=AddrModeAddress(addr_mode=, address=0x782C), src_ep=0, dst=AddrModeAddress(addr_mode=, address=0x0000), dst_ep=0, source_route=None, extended_timeout=False, tsn=134, profile_id=0, cluster_id=32770, data=Serialized[b'#\x00,x\x02@\x8c4\x12l\x7f\x00\x00,\x7f\x00\x00'], tx_options=, radius=0, non_member_radius=0, lqi=255, rssi=-50) Received frame on uninitialized device from ep 0 to ep 0, cluster 32770: b'#\x00,x\x02@\x8c4\x12l\x7f\x00\x00,\x7f\x00\x00' [0x782c] Got Node Descriptor: NodeDescriptor(logical_type=, complex_descriptor_available=0, user_descriptor_available=0, reserved=0, aps_flags=0, frequency_band=, mac_capability_flags=, manufacturer_code=4660, maximum_buffer_size=108, maximum_incoming_transfer_size=127, server_mask=11264, maximum_outgoing_transfer_size=127, descriptor_capability_field=, *allocate_address=True, *is_alternate_pan_coordinator=False, *is_coordinator=False, *is_end_device=True, *is_full_function_device=False, *is_mains_powered=True, *is_receiver_on_when_idle=True, *is_router=False, *is_security_capable=False) [0x782c] Discovering endpoints Tries remaining: 3 [0x782c] Extending timeout for 0x25 request Received a packet: ZigbeePacket(src=AddrModeAddress(addr_mode=, address=0x782C), src_ep=0, dst=AddrModeAddress(addr_mode=, address=0x0000), dst_ep=0, source_route=None, extended_timeout=False, tsn=135, profile_id=0, cluster_id=32773, data=Serialized[b'%\x00,x\x01\x01'], tx_options=, radius=0, non_member_radius=0, lqi=255, rssi=-50) Received frame on uninitialized device from ep 0 to ep 0, cluster 32773: b'%\x00,x\x01\x01' [0x782c] Discovered endpoints: [1] [0x782c] Initializing endpoints [>] [0x782c:1] Discovering endpoint information Tries remaining: 3 [0x782c] Extending timeout for 0x27 request Received a packet: ZigbeePacket(src=AddrModeAddress(addr_mode=, address=0x782C), src_ep=0, dst=AddrModeAddress(addr_mode=, address=0x0000), dst_ep=0, source_route=None, extended_timeout=False, tsn=136, profile_id=0, cluster_id=32772, data=Serialized[b"'\x00,x\x12\x01\x04\x01\xf0\xff\x00\x03\x00\x00\x03\x00\xc0\xfc\x02\x03\x00\x19\x00"], tx_options=, radius=0, non_member_radius=0, lqi=255, rssi=-49) Received frame on uninitialized device from ep 0 to ep 0, cluster 32772: b"'\x00,x\x12\x01\x04\x01\xf0\xff\x00\x03\x00\x00\x03\x00\xc0\xfc\x02\x03\x00\x19\x00" [0x782c:1] Discovered endpoint information: SizePrefixedSimpleDescriptor(endpoint=1, profile=260, device_type=65520, device_version=0, input_clusters=[0, 3, 64704], output_clusters=[3, 25]) [0x782C:1:0x0000] Sending request header: ZCLHeader(frame_control=FrameControl(frame_type=, is_manufacturer_specific=False, direction=, disable_default_response=0, reserved=0, *is_cluster=False, *is_general=True, *is_reply=False), tsn=41, command_id=, *direction=, *is_reply=False) [0x782C:1:0x0000] Sending request: Read_Attributes(attribute_ids=[4, 5]) [0x782c] Extending timeout for 0x29 request Received a packet: ZigbeePacket(src=AddrModeAddress(addr_mode=, address=0x782C), src_ep=1, dst=AddrModeAddress(addr_mode=, address=0x0000), dst_ep=1, source_route=None, extended_timeout=False, tsn=137, profile_id=260, cluster_id=0, data=Serialized[b'\x18)\x01\x04\x00\x00B\x05aqara\x05\x00\x00B\x10lumi.motion.ac01'], tx_options=, radius=0, non_member_radius=0, lqi=255, rssi=-49) [0x782C:1:0x0000] Received ZCL frame: b'\x18)\x01\x04\x00\x00B\x05aqara\x05\x00\x00B\x10lumi.motion.ac01' [0x782C:1:0x0000] Decoded ZCL frame header: ZCLHeader(frame_control=FrameControl(frame_type=, is_manufacturer_specific=0, direction=, disable_default_response=1, reserved=0, *is_cluster=False, *is_general=True, *is_reply=True), tsn=41, command_id=1, *direction=, *is_reply=True) [0x782C:1:0x0000] Decoded ZCL frame: Basic:Read_Attributes_rsp(status_records=[ReadAttributeRecord(attrid=0x0004, status=, value=TypeValue(type=CharacterString, value='aqara')), ReadAttributeRecord(attrid=0x0005, status=, value=TypeValue(type=CharacterString, value='lumi.motion.ac01'))]) [0x782c] Read model 'lumi.motion.ac01' and manufacturer 'aqara' from > [0x782c] Discovered basic device information for Device is initialized Checking quirks for aqara lumi.motion.ac01 (54:ef:44:10:00:6d:ac:e3) Considering Found custom device replacement for 54:ef:44:10:00:6d:ac:e3: 'binary_sensor' component -> 'Occupancy' using ['occupancy'] 'button' component -> 'ZHAIdentifyButton' using ['identify'] 'sensor' component -> 'DeviceTemperature' using ['device_temperature'] 'sensor' component -> 'RSSISensor' using ['basic'] 'sensor' component -> 'LQISensor' using ['basic'] 'button' component -> 'NoPresenceStatusResetButton' using ['opple_cluster'] 'select' component -> 'AqaraMonitoringMode' using ['opple_cluster'] 'select' component -> 'AqaraApproachDistance' using ['opple_cluster'] 'select' component -> 'AqaraMotionSensitivity' using ['opple_cluster'] device - 0x782C:54:ef:44:10:00:6d:ac:e3 entering async_device_initialized - is_new_join: True device - 0x782C:54:ef:44:10:00:6d:ac:e3 has joined the ZHA zigbee network [0x782C](lumi.motion.ac01): started configuration [0x782C:ZDO](lumi.motion.ac01): 'async_configure' stage succeeded [0x782C:1:0x0003]: Configuring cluster attribute reporting [0x782C:1:0x0003]: finished channel configuration [0x782C:1:0x0406]: Performing cluster binding [0x782c] Extending timeout for 0x2b request [0x782C:1:0x0002]: Performing cluster binding [0x782c] Extending timeout for 0x2d request [0x782C:1:0x0000]: Configuring cluster attribute reporting [0x782C:1:0x0000]: finished channel configuration [0x782C:1:0xfcc0]: Performing cluster binding [0x782c] Extending timeout for 0x2f request [0x782C:1:0x0019]: finished channel configuration Error handling '_save_attribute' event with (54:ef:44:10:00:6d:ac:e3, 1, 0, 4, 'aqara') params: FOREIGN KEY constraint failed Error handling '_save_attribute' event with (54:ef:44:10:00:6d:ac:e3, 1, 0, 5, 'lumi.motion.ac01') params: FOREIGN KEY constraint failed Received a packet: ZigbeePacket(src=AddrModeAddress(addr_mode=, address=0x782C), src_ep=0, dst=AddrModeAddress(addr_mode=, address=0x0000), dst_ep=0, source_route=None, extended_timeout=False, tsn=138, profile_id=0, cluster_id=32801, data=Serialized[b'+\x00'], tx_options=, radius=0, non_member_radius=0, lqi=255, rssi=-49) [0x782C:1:0x0406]: bound 'occupancy' cluster: Status.SUCCESS [0x782C:1:0x0406]: Configuring cluster attribute reporting [0x782C:1:0x0406] Sending request header: ZCLHeader(frame_control=FrameControl(frame_type=, is_manufacturer_specific=False, direction=, disable_default_response=0, reserved=0, *is_cluster=False, *is_general=True, *is_reply=False), tsn=49, command_id=, *direction=, *is_reply=False) [0x782C:1:0x0406] Sending request: Configure_Reporting(config_records=[AttributeReportingConfig(direction=0, attrid=0x0000, datatype=24, min_interval=0, max_interval=900, reportable_change=1)]) [0x782c] Extending timeout for 0x31 request Received a packet: ZigbeePacket(src=AddrModeAddress(addr_mode=, address=0x782C), src_ep=0, dst=AddrModeAddress(addr_mode=, address=0x0000), dst_ep=0, source_route=None, extended_timeout=False, tsn=139, profile_id=0, cluster_id=32801, data=Serialized[b'-\x00'], tx_options=, radius=0, non_member_radius=0, lqi=255, rssi=-49) [0x782C:1:0x0002]: bound 'device_temperature' cluster: Status.SUCCESS [0x782C:1:0x0002]: Configuring cluster attribute reporting [0x782C:1:0x0002] Sending request header: ZCLHeader(frame_control=FrameControl(frame_type=, is_manufacturer_specific=False, direction=, disable_default_response=0, reserved=0, *is_cluster=False, *is_general=True, *is_reply=False), tsn=51, command_id=, *direction=, *is_reply=False) [0x782C:1:0x0002] Sending request: Configure_Reporting(config_records=[AttributeReportingConfig(direction=0, attrid=0x0000, datatype=41, min_interval=30, max_interval=900, reportable_change=50)]) [0x782c] Extending timeout for 0x33 request Received a packet: ZigbeePacket(src=AddrModeAddress(addr_mode=, address=0x782C), src_ep=0, dst=AddrModeAddress(addr_mode=, address=0x0000), dst_ep=0, source_route=None, extended_timeout=False, tsn=140, profile_id=0, cluster_id=32801, data=Serialized[b'/\x00'], tx_options=, radius=0, non_member_radius=0, lqi=255, rssi=-49) [0x782C:1:0xfcc0]: bound 'opple_cluster' cluster: Status.SUCCESS [0x782C:1:0xfcc0]: Configuring cluster attribute reporting [0x782C:1:0xfcc0]: finished channel configuration Received a packet: ZigbeePacket(src=AddrModeAddress(addr_mode=, address=0x782C), src_ep=1, dst=AddrModeAddress(addr_mode=, address=0x0000), dst_ep=1, source_route=None, extended_timeout=False, tsn=141, profile_id=260, cluster_id=1030, data=Serialized[b'\x181\x0b\x06\xc3'], tx_options=, radius=0, non_member_radius=0, lqi=255, rssi=-49) [0x782C:1:0x0406] Received ZCL frame: b'\x181\x0b\x06\xc3' [0x782C:1:0x0406] Decoded ZCL frame header: ZCLHeader(frame_control=FrameControl(frame_type=, is_manufacturer_specific=0, direction=, disable_default_response=1, reserved=0, *is_cluster=False, *is_general=True, *is_reply=True), tsn=49, command_id=11, *direction=, *is_reply=True) [0x782C:1:0x0406] Decoded ZCL frame: OccupancySensing:Default_Response(command_id=6, status=) Received a packet: ZigbeePacket(src=AddrModeAddress(addr_mode=, address=0x782C), src_ep=1, dst=AddrModeAddress(addr_mode=, address=0x0000), dst_ep=1, source_route=None, extended_timeout=False, tsn=142, profile_id=260, cluster_id=2, data=Serialized[b'\x183\x0b\x06\xc3'], tx_options=, radius=0, non_member_radius=0, lqi=255, rssi=-49) [0x782C:1:0x0002] Received ZCL frame: b'\x183\x0b\x06\xc3' [0x782C:1:0x0002] Decoded ZCL frame header: ZCLHeader(frame_control=FrameControl(frame_type=, is_manufacturer_specific=0, direction=, disable_default_response=1, reserved=0, *is_cluster=False, *is_general=True, *is_reply=True), tsn=51, command_id=11, *direction=, *is_reply=True) [0x782C:1:0x0002] Decoded ZCL frame: DeviceTemperature:Default_Response(command_id=6, status=) [0x782C:1:0x0003]: 'async_configure' stage succeeded [0x782C:1:0x0406]: 'async_configure' stage failed: 'uint8_t' object is not subscriptable [0x782C:1:0x0002]: 'async_configure' stage failed: 'uint8_t' object is not subscriptable [0x782C:1:0x0000]: 'async_configure' stage succeeded [0x782C:1:0xfcc0]: 'async_configure' stage succeeded [0x782C:1:0x0019]: 'async_configure' stage succeeded [0x782C](lumi.motion.ac01): completed configuration [0x782C:1:0x0003] Sending request header: ZCLHeader(frame_control=FrameControl(frame_type=, is_manufacturer_specific=False, direction=, disable_default_response=0, reserved=0, *is_cluster=True, *is_general=False, *is_reply=False), tsn=53, command_id=64, *direction=, *is_reply=False) [0x782C:1:0x0003] Sending request: trigger_effect(effect_id=, effect_variant=) [0x782c] Extending timeout for 0x35 request Received a packet: ZigbeePacket(src=AddrModeAddress(addr_mode=, address=0x782C), src_ep=0, dst=AddrModeAddress(addr_mode=, address=0x0000), dst_ep=0, source_route=None, extended_timeout=False, tsn=143, profile_id=0, cluster_id=2, data=Serialized[b'\x02\x00\x00'], tx_options=, radius=0, non_member_radius=0, lqi=255, rssi=-49) [0x782c:zdo] ZDO request ZDOCmd.Node_Desc_req: [0x0000] [0x782c:zdo] No handler for ZDO request:ZDOCmd.Node_Desc_req([0x0000]) Received a packet: ZigbeePacket(src=AddrModeAddress(addr_mode=, address=0x782C), src_ep=1, dst=AddrModeAddress(addr_mode=, address=0x0000), dst_ep=1, source_route=None, extended_timeout=False, tsn=145, profile_id=260, cluster_id=3, data=Serialized[b'\x185\x0b@\x00'], tx_options=, radius=0, non_member_radius=0, lqi=255, rssi=-49) [0x782C:1:0x0003] Received ZCL frame: b'\x185\x0b@\x00' [0x782C:1:0x0003] Decoded ZCL frame header: ZCLHeader(frame_control=FrameControl(frame_type=, is_manufacturer_specific=0, direction=, disable_default_response=1, reserved=0, *is_cluster=False, *is_general=True, *is_reply=True), tsn=53, command_id=11, *direction=, *is_reply=True) [0x782C:1:0x0003] Decoded ZCL frame: Identify:Default_Response(command_id=64, status=) [0x782C:1:0x0003]: executed 'trigger_effect' command with args: '()' kwargs: '{'effect_id': , 'effect_variant': }' result: Default_Response(command_id=64, status=) [0x782C](lumi.motion.ac01): started initialization [0x782C:ZDO](lumi.motion.ac01): 'async_initialize' stage succeeded [0x782C:1:0x0003]: initializing channel: from_cache: False [0x782C:1:0x0003]: finished channel initialization [0x782C:1:0x0406]: initializing channel: from_cache: False [0x782C:1:0x0406]: initializing uncached channel attributes: ['occupancy'] - from cache[False] [0x782C:1:0x0406]: Reading attributes in chunks: ['occupancy'] [0x782C:1:0x0406] Sending request header: ZCLHeader(frame_control=FrameControl(frame_type=, is_manufacturer_specific=False, direction=, disable_default_response=0, reserved=0, *is_cluster=False, *is_general=True, *is_reply=False), tsn=55, command_id=, *direction=, *is_reply=False) [0x782C:1:0x0406] Sending request: Read_Attributes(attribute_ids=[0]) [0x782c] Extending timeout for 0x37 request [0x782C:1:0x0002]: initializing channel: from_cache: False [0x782C:1:0x0002]: initializing uncached channel attributes: ['current_temperature'] - from cache[False] [0x782C:1:0x0002]: Reading attributes in chunks: ['current_temperature'] [0x782C:1:0x0002] Sending request header: ZCLHeader(frame_control=FrameControl(frame_type=, is_manufacturer_specific=False, direction=, disable_default_response=0, reserved=0, *is_cluster=False, *is_general=True, *is_reply=False), tsn=57, command_id=, *direction=, *is_reply=False) [0x782C:1:0x0002] Sending request: Read_Attributes(attribute_ids=[0]) [0x782c] Extending timeout for 0x39 request [0x782C:1:0x0000]: initializing channel: from_cache: False [0x782C:1:0x0000]: finished channel initialization [0x782C:1:0xfcc0]: initializing channel: from_cache: False [0x782C:1:0xfcc0]: initializing cached channel attributes: ['presence', 'monitoring_mode', 'motion_sensitivity', 'approach_distance'] [0x782C:1:0xfcc0]: Reading attributes in chunks: ['presence', 'monitoring_mode', 'motion_sensitivity', 'approach_distance'] [0x782C:1:0xfcc0] Sending request header: ZCLHeader(frame_control=FrameControl(frame_type=, is_manufacturer_specific=True, direction=, disable_default_response=0, reserved=0, *is_cluster=False, *is_general=True, *is_reply=False), manufacturer=4660, tsn=59, command_id=, *direction=, *is_reply=False) [0x782C:1:0xfcc0] Sending request: Read_Attributes(attribute_ids=[322, 324, 268, 326]) [0x782c] Extending timeout for 0x3b request [0x782C:1:0x0019]: initializing channel: from_cache: False [0x782C:1:0x0019]: finished channel initialization Device 0x782c (54:ef:44:10:00:6d:ac:e3) left the network [0x66E6](S31 Lite zb): Device seen - marking the device available and resetting counter [0x66E6](S31 Lite zb): Update device availability - device available: True - new availability: True - changed: False [0x782C:1:0x0406]: failed to get attributes '['occupancy']' on 'occupancy' cluster: Failed to deliver message: [0x782C:1:0x0406]: async_initialize: retryable request #1 failed: Failed to deliver message: . Retrying in 1.2s [0x782C:1:0x0002]: failed to get attributes '['current_temperature']' on 'device_temperature' cluster: Failed to deliver message: [0x782C:1:0x0002]: async_initialize: retryable request #1 failed: Failed to deliver message: . Retrying in 0.8s [0x782C:1:0xfcc0]: failed to get attributes '['presence', 'monitoring_mode', 'motion_sensitivity', 'approach_distance']' on 'opple_cluster' cluster: Failed to deliver message: [0x782C:1:0xfcc0]: async_initialize: retryable request #1 failed: Failed to deliver message: . Retrying in 1.0s [0xC102](TH01): Device seen - marking the device available and resetting counter [0xC102](TH01): Update device availability - device available: True - new availability: True - changed: False [0x782C:1:0x0002]: initializing channel: from_cache: False [0x782C:1:0x0002]: initializing uncached channel attributes: ['current_temperature'] - from cache[False] [0x782C:1:0x0002]: Reading attributes in chunks: ['current_temperature'] [0x782C:1:0x0002] Sending request header: ZCLHeader(frame_control=FrameControl(frame_type=, is_manufacturer_specific=False, direction=, disable_default_response=0, reserved=0, *is_cluster=False, *is_general=True, *is_reply=False), tsn=61, command_id=, *direction=, *is_reply=False) [0x782C:1:0x0002] Sending request: Read_Attributes(attribute_ids=[0]) [0x782c] Extending timeout for 0x3d request [0x782C:1:0xfcc0]: initializing channel: from_cache: False [0x782C:1:0xfcc0]: initializing cached channel attributes: ['presence', 'monitoring_mode', 'motion_sensitivity', 'approach_distance'] [0x782C:1:0xfcc0]: Reading attributes in chunks: ['presence', 'monitoring_mode', 'motion_sensitivity', 'approach_distance'] [0x782C:1:0xfcc0] Sending request header: ZCLHeader(frame_control=FrameControl(frame_type=, is_manufacturer_specific=True, direction=, disable_default_response=0, reserved=0, *is_cluster=False, *is_general=True, *is_reply=False), manufacturer=4660, tsn=63, command_id=, *direction=, *is_reply=False) [0x782C:1:0xfcc0] Sending request: Read_Attributes(attribute_ids=[322, 324, 268, 326]) [0x782c] Extending timeout for 0x3f request [0x782C:1:0x0406]: initializing channel: from_cache: False [0x782C:1:0x0406]: initializing uncached channel attributes: ['occupancy'] - from cache[False] [0x782C:1:0x0406]: Reading attributes in chunks: ['occupancy'] [0x782C:1:0x0406] Sending request header: ZCLHeader(frame_control=FrameControl(frame_type=, is_manufacturer_specific=False, direction=, disable_default_response=0, reserved=0, *is_cluster=False, *is_general=True, *is_reply=False), tsn=65, command_id=, *direction=, *is_reply=False) [0x782C:1:0x0406] Sending request: Read_Attributes(attribute_ids=[0]) [0x782c] Extending timeout for 0x41 request [0x782C:1:0x0002]: failed to get attributes '['current_temperature']' on 'device_temperature' cluster: Failed to deliver message: [0x782C:1:0x0002]: async_initialize: retryable request #2 failed: Failed to deliver message: . Retrying in 0.9s [0x782C:1:0xfcc0]: failed to get attributes '['presence', 'monitoring_mode', 'motion_sensitivity', 'approach_distance']' on 'opple_cluster' cluster: Failed to deliver message: [0x782C:1:0xfcc0]: async_initialize: retryable request #2 failed: Failed to deliver message: . Retrying in 0.8s [0x782C:1:0x0406]: failed to get attributes '['occupancy']' on 'occupancy' cluster: Failed to deliver message: [0x782C:1:0x0406]: async_initialize: retryable request #2 failed: Failed to deliver message: . Retrying in 1.0s [0x782C:1:0x0002]: initializing channel: from_cache: False [0x782C:1:0x0002]: initializing uncached channel attributes: ['current_temperature'] - from cache[False] [0x782C:1:0x0002]: Reading attributes in chunks: ['current_temperature'] [0x782C:1:0x0002] Sending request header: ZCLHeader(frame_control=FrameControl(frame_type=, is_manufacturer_specific=False, direction=, disable_default_response=0, reserved=0, *is_cluster=False, *is_general=True, *is_reply=False), tsn=67, command_id=, *direction=, *is_reply=False) [0x782C:1:0x0002] Sending request: Read_Attributes(attribute_ids=[0]) [0x782c] Extending timeout for 0x43 request [0x782C:1:0xfcc0]: initializing channel: from_cache: False [0x782C:1:0xfcc0]: initializing cached channel attributes: ['presence', 'monitoring_mode', 'motion_sensitivity', 'approach_distance'] [0x782C:1:0xfcc0]: Reading attributes in chunks: ['presence', 'monitoring_mode', 'motion_sensitivity', 'approach_distance'] [0x782C:1:0xfcc0] Sending request header: ZCLHeader(frame_control=FrameControl(frame_type=, is_manufacturer_specific=True, direction=, disable_default_response=0, reserved=0, *is_cluster=False, *is_general=True, *is_reply=False), manufacturer=4660, tsn=69, command_id=, *direction=, *is_reply=False) [0x782C:1:0xfcc0] Sending request: Read_Attributes(attribute_ids=[322, 324, 268, 326]) [0x782c] Extending timeout for 0x45 request [0x782C:1:0x0406]: initializing channel: from_cache: False [0x782C:1:0x0406]: initializing uncached channel attributes: ['occupancy'] - from cache[False] [0x782C:1:0x0406]: Reading attributes in chunks: ['occupancy'] [0x782C:1:0x0406] Sending request header: ZCLHeader(frame_control=FrameControl(frame_type=, is_manufacturer_specific=False, direction=, disable_default_response=0, reserved=0, *is_cluster=False, *is_general=True, *is_reply=False), tsn=71, command_id=, *direction=, *is_reply=False) [0x782C:1:0x0406] Sending request: Read_Attributes(attribute_ids=[0]) [0x782c] Extending timeout for 0x47 request [0x782C:1:0x0002]: failed to get attributes '['current_temperature']' on 'device_temperature' cluster: Failed to deliver message: [0x782C:1:0x0002]: async_initialize: retryable request #3 failed: Failed to deliver message: . Retrying in 2.8s [0x782C:1:0xfcc0]: failed to get attributes '['presence', 'monitoring_mode', 'motion_sensitivity', 'approach_distance']' on 'opple_cluster' cluster: Failed to deliver message: [0x782C:1:0xfcc0]: async_initialize: retryable request #3 failed: Failed to deliver message: . Retrying in 3.3s [0x782C:1:0x0406]: failed to get attributes '['occupancy']' on 'occupancy' cluster: Failed to deliver message: [0x782C:1:0x0406]: async_initialize: retryable request #3 failed: Failed to deliver message: . Retrying in 3.3s [0x312D](MCT-350 SMA): Device seen - marking the device available and resetting counter [0x312D](MCT-350 SMA): Update device availability - device available: True - new availability: True - changed: False [0x782C:1:0x0002]: initializing channel: from_cache: False [0x782C:1:0x0002]: initializing uncached channel attributes: ['current_temperature'] - from cache[False] [0x782C:1:0x0002]: Reading attributes in chunks: ['current_temperature'] [0x782C:1:0x0002] Sending request header: ZCLHeader(frame_control=FrameControl(frame_type=, is_manufacturer_specific=False, direction=, disable_default_response=0, reserved=0, *is_cluster=False, *is_general=True, *is_reply=False), tsn=73, command_id=, *direction=, *is_reply=False) [0x782C:1:0x0002] Sending request: Read_Attributes(attribute_ids=[0]) [0x782c] Extending timeout for 0x49 request [0x782C:1:0xfcc0]: initializing channel: from_cache: False [0x782C:1:0xfcc0]: initializing cached channel attributes: ['presence', 'monitoring_mode', 'motion_sensitivity', 'approach_distance'] [0x782C:1:0xfcc0]: Reading attributes in chunks: ['presence', 'monitoring_mode', 'motion_sensitivity', 'approach_distance'] [0x782C:1:0xfcc0] Sending request header: ZCLHeader(frame_control=FrameControl(frame_type=, is_manufacturer_specific=True, direction=, disable_default_response=0, reserved=0, *is_cluster=False, *is_general=True, *is_reply=False), manufacturer=4660, tsn=75, command_id=, *direction=, *is_reply=False) [0x782C:1:0xfcc0] Sending request: Read_Attributes(attribute_ids=[322, 324, 268, 326]) [0x782c] Extending timeout for 0x4b request [0x782C:1:0x0406]: initializing channel: from_cache: False [0x782C:1:0x0406]: initializing uncached channel attributes: ['occupancy'] - from cache[False] [0x782C:1:0x0406]: Reading attributes in chunks: ['occupancy'] [0x782C:1:0x0406] Sending request header: ZCLHeader(frame_control=FrameControl(frame_type=, is_manufacturer_specific=False, direction=, disable_default_response=0, reserved=0, *is_cluster=False, *is_general=True, *is_reply=False), tsn=77, command_id=, *direction=, *is_reply=False) [0x782C:1:0x0406] Sending request: Read_Attributes(attribute_ids=[0]) [0x782c] Extending timeout for 0x4d request [0x782C:1:0x0002]: failed to get attributes '['current_temperature']' on 'device_temperature' cluster: Failed to deliver message: [0x782C:1:0x0002]: async_initialize: all attempts have failed: [DeliveryError('Failed to deliver message: '), DeliveryError('Failed to deliver message: '), DeliveryError('Failed to deliver message: '), DeliveryError('Failed to deliver message: ')] [0x782C:1:0xfcc0]: failed to get attributes '['presence', 'monitoring_mode', 'motion_sensitivity', 'approach_distance']' on 'opple_cluster' cluster: Failed to deliver message: [0x782C:1:0xfcc0]: async_initialize: all attempts have failed: [DeliveryError('Failed to deliver message: '), DeliveryError('Failed to deliver message: '), DeliveryError('Failed to deliver message: '), DeliveryError('Failed to deliver message: ')] [0x782C:1:0x0406]: failed to get attributes '['occupancy']' on 'occupancy' cluster: Failed to deliver message: [0x782C:1:0x0406]: async_initialize: all attempts have failed: [DeliveryError('Failed to deliver message: '), DeliveryError('Failed to deliver message: '), DeliveryError('Failed to deliver message: '), DeliveryError('Failed to deliver message: ')] [0x782C:1:0x0003]: 'async_initialize' stage succeeded [0x782C:1:0x0406]: 'async_initialize' stage succeeded [0x782C:1:0x0002]: 'async_initialize' stage succeeded [0x782C:1:0x0000]: 'async_initialize' stage succeeded [0x782C:1:0xfcc0]: 'async_initialize' stage succeeded [0x782C:1:0x0019]: 'async_initialize' stage succeeded [0x782C](lumi.motion.ac01): power source: Mains [0x782C](lumi.motion.ac01): completed initialization monitoring_mode is not supported - skipping AqaraMonitoringMode entity creation approach_distance is not supported - skipping AqaraApproachDistance entity creation motion_sensitivity is not supported - skipping AqaraMotionSensitivity entity creation Received a packet: ZigbeePacket(src=AddrModeAddress(addr_mode=, address=0xCADA), src_ep=1, dst=AddrModeAddress(addr_mode=, address=0x0000), dst_ep=255, source_route=None, extended_timeout=False, tsn=250, profile_id=260, cluster_id=6, data=Serialized[b'\x08\xac\n\x00\x00\x10\x01'], tx_options=, radius=0, non_member_radius=0, lqi=255, rssi=-59) [0xCADA:1:0x0006] Received ZCL frame: b'\x08\xac\n\x00\x00\x10\x01' [0xCADA:1:0x0006] Decoded ZCL frame header: ZCLHeader(frame_control=FrameControl(frame_type=, is_manufacturer_specific=0, direction=, disable_default_response=0, reserved=0, *is_cluster=False, *is_general=True, *is_reply=True), tsn=172, command_id=10, *direction=, *is_reply=True) [0xCADA:1:0x0006] Decoded ZCL frame: OnOff:Report_Attributes(attribute_reports=[Attribute(attrid=0x0000, value=TypeValue(type=Bool, value=))]) [0xCADA:1:0x0006] Received command 0x0A (TSN 172): Report_Attributes(attribute_reports=[Attribute(attrid=0x0000, value=TypeValue(type=Bool, value=))]) [0xCADA:1:0x0006] Attribute report received: on_off= [0xCADA:1:0x0006] Sending reply header: ZCLHeader(frame_control=FrameControl(frame_type=, is_manufacturer_specific=False, direction=, disable_default_response=1, reserved=0, *is_cluster=False, *is_general=True, *is_reply=True), tsn=172, command_id=, *direction=, *is_reply=True) [0xCADA:1:0x0006] Sending reply: Default_Response(command_id=10, status=) [0xCADA](S31 Lite zb): Device seen - marking the device available and resetting counter [0xCADA](S31 Lite zb): Update device availability - device available: True - new availability: True - changed: False [0xC315](DS01): Device seen - marking the device available and resetting counter [0xC315](DS01): Update device availability - device available: True - new availability: True - changed: False [0x9602](unk_model): last_seen is None, marking the device unavailable [0x9602](unk_model): Update device availability - device available: False - new availability: False - changed: False ```
TheJulianJES commented 1 year ago

What coordinator are you using and which firmware version is running on it?

cvocvo commented 1 year ago

I'm using a Nortek HUSBZB-1 with the v6.7.8 firmware from here: https://github.com/walthowd/husbzb-firmware

dmulcahey commented 1 year ago

You need to have hashed link keys enabled. How old is your Zigbee network? if it’s a couple years old there is a chance you need to tweak a setting.

cvocvo commented 1 year ago

Huh yea it’s a year or two old. How do I turn that on or check if it’s configured? Thank you!

edit: If I download a backup of my configuration I do have a section that may be that?

},
        "tc_link_key": {
            "key": "REDACTED",
            "tx_counter": 135168,
            "rx_counter": 0,
            "seq": 0,
            "partner_ieee": "REDACTED"
        },

Notably the key doesn’t look hashed so maybe it needs migrated or updated somehow?

dmulcahey commented 1 year ago

You need to take a bellows backup of the coordinator and then use bellows restore with the -U option to upgrade it to hashed link keys: https://github.com/zigpy/bellows/blob/e700caf2a50454d0060c3fcd5f67f4b49ebfce46/bellows/cli/backup.py#L156

Procedures for backup and restore: https://github.com/zigpy/zigpy/wiki/Coordinator-Backup-and-Migration#instructions-for-ezsp-radios

cvocvo commented 1 year ago

Ahh perfect that did the trick -- THANK YOU!!!

I upgraded, removed and readded the FP1 and everything is working as expected.

By the way if anyone stumbles across this, you can check via bellows if you have hashed link keys enabled on your coordinator / network.

Running this: sudo bellows -d /dev/ttyUSB1 info

Yielded a bunch of output but, BEFORE: [<EmberStatus.SUCCESS: 0>, EmberCurrentSecurityState(bitmask=<EmberCurrentSecurityBitmask.64|32|HAVE_TRUST_CENTER_LINK_KEY|GLOBAL_LINK_KEY: And AFTER doing the backup and restore upgrade -- you'll see the HASHED_LINK_KEY part noted in the output: [<EmberStatus.SUCCESS: 0>, EmberCurrentSecurityState(bitmask=<EmberCurrentSecurityBitmask.TRUST_CENTER_USES_HASHED_LINK_KEY|64|32|HAVE_TRUST_CENTER_LINK_KEY|GLOBAL_LINK_KEY:

Backup command: sudo bellows -d /dev/ttyUSB1 backup > husbzb1-backup-03162023.txt

Also, this is the upgrade command I used that didn't work:

sudo bellows -d /dev/ttyUSB1 restore -U -B husbzb1-backup-03162023.txt
Restoring NCP
Network is up, not forcing restore

But forcing it did work:

sudo bellows -d /dev/ttyUSB1 restore -U -B husbzb1-backup-03162023.txt --force
Restoring NCP