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
685 stars 638 forks source link

[BUG] IKEA Vallhorn Update failed #3018

Open theincogtion opened 4 months ago

theincogtion commented 4 months ago

Bug description

Firmware update is displayed in Home Assistant. Trying to install it fails with this error Message: Screenshot 2024-03-02 173418

Steps to reproduce

Go to settings and try to update vallhorn firmware image

Expected behavior

Update works

Screenshots/Video

Screenshots/Video [Paste/upload your media here]

Device signature

Device signature ```json [Paste the device signature here] ```

Diagnostic information

Diagnostic information ```json [Paste the diagnostic information here] ```

Logs

Logs ```python 2024-03-02 17:34:04.577 DEBUG (MainThread) [zigpy_deconz.uart] Frame received: 0x0e87000700aa00 2024-03-02 17:34:04.579 DEBUG (MainThread) [zigpy_deconz.api] Received command CommandId.device_state_changed{'status': , 'frame_length': 7, 'device_state': DeviceState(network_state=, device_state=), 'reserved': 0} (seq 135) 2024-03-02 17:34:04.583 DEBUG (MainThread) [zigpy_deconz.api] Sending CommandId.aps_data_indication{'flags': } (seq=135) 2024-03-02 17:34:04.584 DEBUG (MainThread) [zigpy_deconz.uart] Send: 1787000800010001 2024-03-02 17:34:04.587 DEBUG (MainThread) [zigpy_deconz.uart] Frame received: 0x17870026001f002202000001020e4003040100040800184b0a0000214d1b00afffbd7bbd00b0 2024-03-02 17:34:04.590 DEBUG (MainThread) [zigpy_deconz.api] Received command CommandId.aps_data_indication{'status': , 'frame_length': 38, 'payload_length': 31, 'device_state': DeviceState(network_state=, device_state=), 'dst_addr': DeconzAddress(address_mode=, address=0x0000), 'dst_ep': 1, 'src_addr': DeconzAddress(address_mode=, address=0x400E), 'src_ep': 3, 'profile_id': 260, 'cluster_id': 1024, 'asdu': b'\x18K\n\x00\x00!M\x1b', 'reserved1': 0, 'reserved2': 175, 'lqi': 255, 'reserved3': 189, 'reserved4': 123, 'reserved5': 189, 'reserved6': 0, 'rssi': -80} (seq 135) 2024-03-02 17:34:04.591 DEBUG (MainThread) [zigpy.application] Received a packet: ZigbeePacket(timestamp=datetime.datetime(2024, 3, 2, 16, 34, 4, 591288, tzinfo=datetime.timezone.utc), src=AddrModeAddress(addr_mode=, address=0x400E), src_ep=3, dst=AddrModeAddress(addr_mode=, address=0x0000), dst_ep=1, source_route=None, extended_timeout=False, tsn=None, profile_id=260, cluster_id=1024, data=Serialized[b'\x18K\n\x00\x00!M\x1b'], tx_options=, radius=0, non_member_radius=0, lqi=255, rssi=-80) 2024-03-02 17:34:04.592 DEBUG (MainThread) [zigpy.zcl] [0x400E:3:0x0400] Received ZCL frame: b'\x18K\n\x00\x00!M\x1b' 2024-03-02 17:34:04.593 DEBUG (MainThread) [zigpy.zcl] [0x400E:3:0x0400] Decoded ZCL frame header: ZCLHeader(frame_control=FrameControl<0x18>(frame_type=, is_manufacturer_specific=0, direction=, disable_default_response=1, reserved=0, *is_cluster=False, *is_general=True), tsn=75, command_id=10, *direction=) 2024-03-02 17:34:04.594 DEBUG (MainThread) [zigpy.zcl] [0x400E:3:0x0400] Decoded ZCL frame: IlluminanceMeasurement:Report_Attributes(attribute_reports=[Attribute(attrid=0x0000, value=TypeValue(type=uint16_t, value=6989))]) 2024-03-02 17:34:04.594 DEBUG (MainThread) [zigpy.zcl] [0x400E:3:0x0400] Received command 0x0A (TSN 75): Report_Attributes(attribute_reports=[Attribute(attrid=0x0000, value=TypeValue(type=uint16_t, value=6989))]) 2024-03-02 17:34:04.595 DEBUG (MainThread) [zigpy.zcl] [0x400E:3:0x0400] Attribute report received: measured_value=6989 2024-03-02 17:34:04.595 DEBUG (MainThread) [homeassistant.components.zha.core.cluster_handlers] [0x400E:3:0x0400]: cluster_handler[illuminance] attribute_updated - cluster[Illuminance Measurement] attr[measured_value] value[6989] 2024-03-02 17:34:04.597 DEBUG (Thread-5) [aiosqlite] executing functools.partial(, 'UPDATE devices_v12\n SET last_seen=:ts\n WHERE ieee=:ieee AND :ts - last_seen > :min_update_delta', {'ts': 1709397244.591288, 'ieee': 8c:6f:b9:ff:fe:1c:0c:51, 'min_update_delta': 30.0}) 2024-03-02 17:34:04.598 DEBUG (Thread-5) [aiosqlite] operation functools.partial(, 'UPDATE devices_v12\n SET last_seen=:ts\n WHERE ieee=:ieee AND :ts - last_seen > :min_update_delta', {'ts': 1709397244.591288, 'ieee': 8c:6f:b9:ff:fe:1c:0c:51, 'min_update_delta': 30.0}) completed 2024-03-02 17:34:04.600 DEBUG (Thread-5) [aiosqlite] executing functools.partial() 2024-03-02 17:34:04.600 DEBUG (Thread-5) [aiosqlite] operation functools.partial() completed 2024-03-02 17:34:04.601 DEBUG (Thread-5) [aiosqlite] executing functools.partial(, '\n INSERT INTO attributes_cache_v12\n VALUES (:ieee, :endpoint_id, :cluster_id, :attrid, :value, :timestamp)\n ON CONFLICT (ieee, endpoint_id, cluster, attrid) 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': 8c:6f:b9:ff:fe:1c:0c:51, 'endpoint_id': 3, 'cluster_id': 1024, 'attrid': 0, 'value': 6989, 'timestamp': 1709397244.595276, 'min_update_delta': 30.0}) 2024-03-02 17:34:04.602 DEBUG (Thread-5) [aiosqlite] operation functools.partial(, '\n INSERT INTO attributes_cache_v12\n VALUES (:ieee, :endpoint_id, :cluster_id, :attrid, :value, :timestamp)\n ON CONFLICT (ieee, endpoint_id, cluster, attrid) 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': 8c:6f:b9:ff:fe:1c:0c:51, 'endpoint_id': 3, 'cluster_id': 1024, 'attrid': 0, 'value': 6989, 'timestamp': 1709397244.595276, 'min_update_delta': 30.0}) completed 2024-03-02 17:34:04.603 DEBUG (Thread-5) [aiosqlite] executing functools.partial() 2024-03-02 17:34:04.603 DEBUG (Thread-5) [aiosqlite] operation functools.partial() completed 2024-03-02 17:34:07.610 DEBUG (MainThread) [zigpy_deconz.uart] Frame received: 0x0e88000700aa00 2024-03-02 17:34:07.611 DEBUG (MainThread) [zigpy_deconz.api] Received command CommandId.device_state_changed{'status': , 'frame_length': 7, 'device_state': DeviceState(network_state=, device_state=), 'reserved': 0} (seq 136) 2024-03-02 17:34:07.613 DEBUG (MainThread) [zigpy_deconz.api] Sending CommandId.aps_data_indication{'flags': } (seq=136) 2024-03-02 17:34:07.614 DEBUG (MainThread) [zigpy_deconz.uart] Send: 1788000800010001 2024-03-02 17:34:07.622 DEBUG (MainThread) [zigpy_deconz.uart] Frame received: 0x17880026001f0022020000010220a30104010003080008920a070021720100afffbd7bbd00b1 2024-03-02 17:34:07.623 DEBUG (MainThread) [zigpy_deconz.api] Received command CommandId.aps_data_indication{'status': , 'frame_length': 38, 'payload_length': 31, 'device_state': DeviceState(network_state=, device_state=), 'dst_addr': DeconzAddress(address_mode=, address=0x0000), 'dst_ep': 1, 'src_addr': DeconzAddress(address_mode=, address=0xA320), 'src_ep': 1, 'profile_id': 260, 'cluster_id': 768, 'asdu': b'\x08\x92\n\x07\x00!r\x01', 'reserved1': 0, 'reserved2': 175, 'lqi': 255, 'reserved3': 189, 'reserved4': 123, 'reserved5': 189, 'reserved6': 0, 'rssi': -79} (seq 136) 2024-03-02 17:34:07.625 DEBUG (MainThread) [zigpy.application] Received a packet: ZigbeePacket(timestamp=datetime.datetime(2024, 3, 2, 16, 34, 7, 625024, tzinfo=datetime.timezone.utc), src=AddrModeAddress(addr_mode=, address=0xA320), src_ep=1, dst=AddrModeAddress(addr_mode=, address=0x0000), dst_ep=1, source_route=None, extended_timeout=False, tsn=None, profile_id=260, cluster_id=768, data=Serialized[b'\x08\x92\n\x07\x00!r\x01'], tx_options=, radius=0, non_member_radius=0, lqi=255, rssi=-79) 2024-03-02 17:34:07.626 DEBUG (MainThread) [zigpy.zcl] [0xA320:1:0x0300] Received ZCL frame: b'\x08\x92\n\x07\x00!r\x01' 2024-03-02 17:34:07.627 DEBUG (MainThread) [zigpy.zcl] [0xA320:1:0x0300] Decoded ZCL frame header: ZCLHeader(frame_control=FrameControl<0x08>(frame_type=, is_manufacturer_specific=0, direction=, disable_default_response=0, reserved=0, *is_cluster=False, *is_general=True), tsn=146, command_id=10, *direction=) 2024-03-02 17:34:07.628 DEBUG (MainThread) [zigpy.zcl] [0xA320:1:0x0300] Decoded ZCL frame: Color:Report_Attributes(attribute_reports=[Attribute(attrid=0x0007, value=TypeValue(type=uint16_t, value=370))]) 2024-03-02 17:34:07.629 DEBUG (MainThread) [zigpy.zcl] [0xA320:1:0x0300] Received command 0x0A (TSN 146): Report_Attributes(attribute_reports=[Attribute(attrid=0x0007, value=TypeValue(type=uint16_t, value=370))]) 2024-03-02 17:34:07.630 DEBUG (MainThread) [zigpy.zcl] [0xA320:1:0x0300] Attribute report received: color_temperature=370 2024-03-02 17:34:07.630 DEBUG (MainThread) [homeassistant.components.zha.core.cluster_handlers] [0xA320:1:0x0300]: cluster_handler[light_color] attribute_updated - cluster[Color Control] attr[color_temperature] value[370] 2024-03-02 17:34:07.631 DEBUG (MainThread) [zigpy.zcl] [0xA320:1:0x0300] Sending reply header: ZCLHeader(frame_control=FrameControl<0x10>(frame_type=, is_manufacturer_specific=False, direction=, disable_default_response=1, reserved=0, *is_cluster=False, *is_general=True), tsn=146, command_id=, *direction=) 2024-03-02 17:34:07.632 DEBUG (MainThread) [zigpy.zcl] [0xA320:1:0x0300] Sending reply: Default_Response(command_id=10, status=) 2024-03-02 17:34:07.633 DEBUG (MainThread) [zigpy_deconz.zigbee.application] Sending packet: ZigbeePacket(timestamp=datetime.datetime(2024, 3, 2, 16, 34, 7, 633158, tzinfo=datetime.timezone.utc), src=AddrModeAddress(addr_mode=, address=0x0000), src_ep=1, dst=AddrModeAddress(addr_mode=, address=0xA320), dst_ep=1, source_route=None, extended_timeout=False, tsn=146, profile_id=260, cluster_id=768, data=Serialized[b'\x10\x92\x0b\n\x00'], tx_options=, radius=0, non_member_radius=0, lqi=None, rssi=None) 2024-03-02 17:34:07.634 DEBUG (MainThread) [zigpy_deconz.api] Sending CommandId.aps_data_request{'request_id': 200, 'flags': , 'dst': DeconzAddressEndpoint(address_mode=, address=0xA320, endpoint=1), 'profile_id': 260, 'cluster_id': 768, 'src_ep': 1, 'asdu': b'\x10\x92\x0b\n\x00', 'tx_options': , 'radius': 0, 'relays': None} (seq=137) 2024-03-02 17:34:07.635 DEBUG (MainThread) [zigpy_deconz.uart] Send: 1289001b001400c8000220a3010401000301050010920b0a000600 2024-03-02 17:34:07.635 DEBUG (Thread-5) [aiosqlite] executing functools.partial(, 'UPDATE devices_v12\n SET last_seen=:ts\n WHERE ieee=:ieee AND :ts - last_seen > :min_update_delta', {'ts': 1709397247.625024, 'ieee': 00:15:8d:00:06:c6:81:a3, 'min_update_delta': 30.0}) 2024-03-02 17:34:07.636 DEBUG (Thread-5) [aiosqlite] operation functools.partial(, 'UPDATE devices_v12\n SET last_seen=:ts\n WHERE ieee=:ieee AND :ts - last_seen > :min_update_delta', {'ts': 1709397247.625024, 'ieee': 00:15:8d:00:06:c6:81:a3, 'min_update_delta': 30.0}) completed 2024-03-02 17:34:07.637 DEBUG (MainThread) [zigpy_deconz.uart] Frame received: 0x1289000900020026c8 2024-03-02 17:34:07.638 DEBUG (MainThread) [zigpy_deconz.api] Received command CommandId.aps_data_request{'status': , 'frame_length': 9, 'payload_length': 2, 'device_state': DeviceState(network_state=, device_state=), 'request_id': 200} (seq 137) 2024-03-02 17:34:07.639 DEBUG (MainThread) [zigpy_deconz.uart] Frame received: 0x0e8a000700a600 2024-03-02 17:34:07.640 DEBUG (MainThread) [zigpy_deconz.api] Received command CommandId.device_state_changed{'status': , 'frame_length': 7, 'device_state': DeviceState(network_state=, device_state=), 'reserved': 0} (seq 138) 2024-03-02 17:34:07.640 DEBUG (Thread-5) [aiosqlite] executing functools.partial() 2024-03-02 17:34:07.641 DEBUG (Thread-5) [aiosqlite] operation functools.partial() completed 2024-03-02 17:34:07.643 DEBUG (MainThread) [zigpy_deconz.api] Sending CommandId.aps_data_confirm{} (seq=138) 2024-03-02 17:34:07.643 DEBUG (MainThread) [zigpy_deconz.uart] Send: 048a0007000000 2024-03-02 17:34:07.646 DEBUG (Thread-5) [aiosqlite] executing functools.partial(, '\n INSERT INTO attributes_cache_v12\n VALUES (:ieee, :endpoint_id, :cluster_id, :attrid, :value, :timestamp)\n ON CONFLICT (ieee, endpoint_id, cluster, attrid) 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:06:c6:81:a3, 'endpoint_id': 1, 'cluster_id': 768, 'attrid': 7, 'value': 370, 'timestamp': 1709397247.630301, 'min_update_delta': 30.0}) 2024-03-02 17:34:07.647 DEBUG (Thread-5) [aiosqlite] operation functools.partial(, '\n INSERT INTO attributes_cache_v12\n VALUES (:ieee, :endpoint_id, :cluster_id, :attrid, :value, :timestamp)\n ON CONFLICT (ieee, endpoint_id, cluster, attrid) 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:06:c6:81:a3, 'endpoint_id': 1, 'cluster_id': 768, 'attrid': 7, 'value': 370, 'timestamp': 1709397247.630301, 'min_update_delta': 30.0}) completed 2024-03-02 17:34:07.648 DEBUG (MainThread) [zigpy_deconz.uart] Frame received: 0x048a0013000c0022c80220a301010000000000 2024-03-02 17:34:07.650 DEBUG (MainThread) [zigpy_deconz.api] Received command CommandId.aps_data_confirm{'status': , 'frame_length': 19, 'payload_length': 12, 'device_state': DeviceState(network_state=, device_state=), 'request_id': 200, 'dst_addr': DeconzAddressEndpoint(address_mode=, address=0xA320, endpoint=1), 'src_ep': 1, 'confirm_status': , 'reserved1': 0, 'reserved2': 0, 'reserved3': 0, 'reserved4': 0} (seq 138) 2024-03-02 17:34:07.653 DEBUG (MainThread) [zigpy.zcl] [0xCAE6:1:0x0019] Sending reply header: ZCLHeader(frame_control=FrameControl<0x19>(frame_type=, is_manufacturer_specific=False, direction=, disable_default_response=1, reserved=0, *is_cluster=True, *is_general=False), tsn=59, command_id=0, *direction=) 2024-03-02 17:34:07.654 DEBUG (MainThread) [zigpy.zcl] [0xCAE6:1:0x0019] Sending reply: ImageNotifyCommand(payload_type=, query_jitter=100) 2024-03-02 17:34:07.654 DEBUG (MainThread) [zigpy_deconz.zigbee.application] Sending packet: ZigbeePacket(timestamp=datetime.datetime(2024, 3, 2, 16, 34, 7, 654946, tzinfo=datetime.timezone.utc), src=AddrModeAddress(addr_mode=, address=0x0000), src_ep=1, dst=AddrModeAddress(addr_mode=, address=0xCAE6), dst_ep=1, source_route=None, extended_timeout=False, tsn=59, profile_id=260, cluster_id=25, data=Serialized[b'\x19;\x00\x00d'], tx_options=, radius=0, non_member_radius=0, lqi=None, rssi=None) 2024-03-02 17:34:07.659 DEBUG (MainThread) [zigpy_deconz.api] Sending CommandId.aps_data_request{'request_id': 201, 'flags': , 'dst': DeconzAddressEndpoint(address_mode=, address=0xCAE6, endpoint=1), 'profile_id': 260, 'cluster_id': 25, 'src_ep': 1, 'asdu': b'\x19;\x00\x00d', 'tx_options': , 'radius': 0, 'relays': None} (seq=139) 2024-03-02 17:34:07.659 DEBUG (MainThread) [zigpy_deconz.uart] Send: 128b001b001400c90002e6ca0104011900010500193b0000640600 2024-03-02 17:34:07.660 DEBUG (Thread-5) [aiosqlite] executing functools.partial() 2024-03-02 17:34:07.661 DEBUG (Thread-5) [aiosqlite] operation functools.partial() completed 2024-03-02 17:34:07.669 DEBUG (MainThread) [zigpy_deconz.uart] Frame received: 0x128b000900020022c9 2024-03-02 17:34:07.670 DEBUG (MainThread) [zigpy_deconz.api] Received command CommandId.aps_data_request{'status': , 'frame_length': 9, 'payload_length': 2, 'device_state': DeviceState(network_state=, device_state=), 'request_id': 201} (seq 139) 2024-03-02 17:34:09.424 DEBUG (MainThread) [zigpy_deconz.uart] Frame received: 0x0e8c000700aa00 2024-03-02 17:34:09.426 DEBUG (MainThread) [zigpy_deconz.api] Received command CommandId.device_state_changed{'status': , 'frame_length': 7, 'device_state': DeviceState(network_state=, device_state=), 'reserved': 0} (seq 140) 2024-03-02 17:34:09.427 DEBUG (MainThread) [zigpy_deconz.api] Sending CommandId.aps_data_indication{'flags': } (seq=140) 2024-03-02 17:34:09.428 DEBUG (MainThread) [zigpy_deconz.uart] Send: 178c000800010001 2024-03-02 17:34:09.430 DEBUG (MainThread) [zigpy_deconz.uart] Frame received: 0x178c002a00230022020000010220a301040119000c000103010010120c110100000000afffbd7bbd00b0 2024-03-02 17:34:09.433 DEBUG (MainThread) [zigpy_deconz.api] Received command CommandId.aps_data_indication{'status': , 'frame_length': 42, 'payload_length': 35, 'device_state': DeviceState(network_state=, device_state=), 'dst_addr': DeconzAddress(address_mode=, address=0x0000), 'dst_ep': 1, 'src_addr': DeconzAddress(address_mode=, address=0xA320), 'src_ep': 1, 'profile_id': 260, 'cluster_id': 25, 'asdu': b'\x01\x03\x01\x00\x10\x12\x0c\x11\x01\x00\x00\x00', 'reserved1': 0, 'reserved2': 175, 'lqi': 255, 'reserved3': 189, 'reserved4': 123, 'reserved5': 189, 'reserved6': 0, 'rssi': -80} (seq 140) 2024-03-02 17:34:09.435 DEBUG (MainThread) [zigpy.application] Received a packet: ZigbeePacket(timestamp=datetime.datetime(2024, 3, 2, 16, 34, 9, 435162, tzinfo=datetime.timezone.utc), src=AddrModeAddress(addr_mode=, address=0xA320), src_ep=1, dst=AddrModeAddress(addr_mode=, address=0x0000), dst_ep=1, source_route=None, extended_timeout=False, tsn=None, profile_id=260, cluster_id=25, data=Serialized[b'\x01\x03\x01\x00\x10\x12\x0c\x11\x01\x00\x00\x00'], tx_options=, radius=0, non_member_radius=0, lqi=255, rssi=-80) 2024-03-02 17:34:09.437 DEBUG (MainThread) [zigpy.zcl] [0xA320:1:0x0019] Received ZCL frame: b'\x01\x03\x01\x00\x10\x12\x0c\x11\x01\x00\x00\x00' 2024-03-02 17:34:09.438 DEBUG (MainThread) [zigpy.zcl] [0xA320:1:0x0019] Decoded ZCL frame header: ZCLHeader(frame_control=FrameControl<0x01>(frame_type=, is_manufacturer_specific=0, direction=, disable_default_response=0, reserved=0, *is_cluster=True, *is_general=False), tsn=3, command_id=1, *direction=) 2024-03-02 17:34:09.439 DEBUG (MainThread) [zigpy.zcl] [0xA320:1:0x0019] Decoded ZCL frame: Ota:QueryNextImageCommand(field_control=, manufacturer_code=4624, image_type=4364, current_file_version=1) 2024-03-02 17:34:09.440 DEBUG (MainThread) [zigpy.zcl] [0xA320:1:0x0019] Received command 0x01 (TSN 3): QueryNextImageCommand(field_control=, manufacturer_code=4624, image_type=4364, current_file_version=1) 2024-03-02 17:34:09.441 DEBUG (MainThread) [zigpy.zcl] [0xA320:1:0x0019] OTA query_next_image handler for 'Paulmann Licht 371000001': field_control=0, manufacturer_id=4624, image_type=4364, current_file_version=1, hardware_version=None, model='371000001' 2024-03-02 17:34:09.442 DEBUG (MainThread) [zigpy.zcl] [0xA320:1:0x0019] No OTA image is available 2024-03-02 17:34:09.443 DEBUG (MainThread) [zigpy.zcl] [0xA320:1:0x0019] Sending reply header: ZCLHeader(frame_control=FrameControl<0x19>(frame_type=, is_manufacturer_specific=False, direction=, disable_default_response=1, reserved=0, *is_cluster=True, *is_general=False), tsn=3, command_id=2, *direction=) 2024-03-02 17:34:09.443 DEBUG (MainThread) [zigpy.zcl] [0xA320:1:0x0019] Sending reply: query_next_image_response(status=, manufacturer_code=None, image_type=None, file_version=None, image_size=None) 2024-03-02 17:34:09.444 DEBUG (MainThread) [zigpy_deconz.zigbee.application] Sending packet: ZigbeePacket(timestamp=datetime.datetime(2024, 3, 2, 16, 34, 9, 444316, tzinfo=datetime.timezone.utc), src=AddrModeAddress(addr_mode=, address=0x0000), src_ep=1, dst=AddrModeAddress(addr_mode=, address=0xA320), dst_ep=1, source_route=None, extended_timeout=False, tsn=3, profile_id=260, cluster_id=25, data=Serialized[b'\x19\x03\x02\x98'], tx_options=, radius=0, non_member_radius=0, lqi=None, rssi=None) 2024-03-02 17:34:09.445 DEBUG (MainThread) [zigpy_deconz.api] Sending CommandId.aps_data_request{'request_id': 202, 'flags': , 'dst': DeconzAddressEndpoint(address_mode=, address=0xA320, endpoint=1), 'profile_id': 260, 'cluster_id': 25, 'src_ep': 1, 'asdu': b'\x19\x03\x02\x98', 'tx_options': , 'radius': 0, 'relays': None} (seq=141) 2024-03-02 17:34:09.446 DEBUG (MainThread) [zigpy_deconz.uart] Send: 128d001a001300ca000220a30104011900010400190302980600 2024-03-02 17:34:09.446 DEBUG (Thread-5) [aiosqlite] executing functools.partial(, 'UPDATE devices_v12\n SET last_seen=:ts\n WHERE ieee=:ieee AND :ts - last_seen > :min_update_delta', {'ts': 1709397249.435162, 'ieee': 00:15:8d:00:06:c6:81:a3, 'min_update_delta': 30.0}) 2024-03-02 17:34:09.447 DEBUG (Thread-5) [aiosqlite] operation functools.partial(, 'UPDATE devices_v12\n SET last_seen=:ts\n WHERE ieee=:ieee AND :ts - last_seen > :min_update_delta', {'ts': 1709397249.435162, 'ieee': 00:15:8d:00:06:c6:81:a3, 'min_update_delta': 30.0}) completed 2024-03-02 17:34:09.448 DEBUG (Thread-5) [aiosqlite] executing functools.partial() 2024-03-02 17:34:09.449 DEBUG (Thread-5) [aiosqlite] operation functools.partial() completed 2024-03-02 17:34:09.456 DEBUG (MainThread) [zigpy_deconz.uart] Frame received: 0x128d000900020022ca 2024-03-02 17:34:09.457 DEBUG (MainThread) [zigpy_deconz.api] Received command CommandId.aps_data_request{'status': , 'frame_length': 9, 'payload_length': 2, 'device_state': DeviceState(network_state=, device_state=), 'request_id': 202} (seq 141) 2024-03-02 17:34:09.475 DEBUG (MainThread) [zigpy_deconz.uart] Frame received: 0x0e8e000700a600 2024-03-02 17:34:09.476 DEBUG (MainThread) [zigpy_deconz.api] Received command CommandId.device_state_changed{'status': , 'frame_length': 7, 'device_state': DeviceState(network_state=, device_state=), 'reserved': 0} (seq 142) 2024-03-02 17:34:09.477 DEBUG (MainThread) [zigpy_deconz.api] Sending CommandId.aps_data_confirm{} (seq=142) 2024-03-02 17:34:09.478 DEBUG (MainThread) [zigpy_deconz.uart] Send: 048e0007000000 2024-03-02 17:34:09.479 DEBUG (MainThread) [zigpy_deconz.uart] Frame received: 0x048e0013000c0022ca0220a301010000000000 2024-03-02 17:34:09.480 DEBUG (MainThread) [zigpy_deconz.api] Received command CommandId.aps_data_confirm{'status': , 'frame_length': 19, 'payload_length': 12, 'device_state': DeviceState(network_state=, device_state=), 'request_id': 202, 'dst_addr': DeconzAddressEndpoint(address_mode=, address=0xA320, endpoint=1), 'src_ep': 1, 'confirm_status': , 'reserved1': 0, 'reserved2': 0, 'reserved3': 0, 'reserved4': 0} (seq 142) 2024-03-02 17:34:10.375 DEBUG (MainThread) [zigpy.application] Feeding watchdog 2024-03-02 17:34:10.376 DEBUG (MainThread) [zigpy_deconz.api] Sending CommandId.write_parameter{'parameter_id': , 'parameter': b'<\x00\x00\x00'} (seq=143) 2024-03-02 17:34:10.377 DEBUG (MainThread) [zigpy_deconz.uart] Send: 0b8f000c000500263c000000 2024-03-02 17:34:10.379 DEBUG (MainThread) [zigpy_deconz.uart] Frame received: 0x0b8f000800010026 2024-03-02 17:34:10.380 DEBUG (MainThread) [zigpy_deconz.api] Received command CommandId.write_parameter{'status': , 'frame_length': 8, 'payload_length': 1, 'parameter_id': } (seq 143) 2024-03-02 17:34:12.206 DEBUG (MainThread) [homeassistant.components.zha.core.device] [0x329B](TRADFRI control outlet): Device seen - marking the device available and resetting counter 2024-03-02 17:34:12.207 DEBUG (MainThread) [homeassistant.components.zha.core.device] [0x329B](TRADFRI control outlet): Update device availability - device available: True - new availability: True - changed: False 2024-03-02 17:34:12.208 DEBUG (MainThread) [homeassistant.components.zha.core.device] [0xD207](TS011F): last_seen is 599950.165397644 seconds ago and ping attempts have been exhausted, marking the device unavailable 2024-03-02 17:34:12.208 DEBUG (MainThread) [homeassistant.components.zha.core.device] [0xD207](TS011F): Update device availability - device available: False - new availability: False - changed: False 2024-03-02 17:34:12.257 DEBUG (MainThread) [homeassistant.components.zha.core.device] [0x029D](TS0601): last_seen is 9959909.167658329 seconds ago and ping attempts have been exhausted, marking the device unavailable 2024-03-02 17:34:12.258 DEBUG (MainThread) [homeassistant.components.zha.core.device] [0x029D](TS0601): Update device availability - device available: False - new availability: False - changed: False 2024-03-02 17:34:12.262 DEBUG (MainThread) [homeassistant.components.zha.core.device] [0x400E](VALLHORN Wireless Motion Sensor): Device seen - marking the device available and resetting counter 2024-03-02 17:34:12.262 DEBUG (MainThread) [homeassistant.components.zha.core.device] [0x400E](VALLHORN Wireless Motion Sensor): Update device availability - device available: True - new availability: True - changed: False 2024-03-02 17:34:16.180 DEBUG (MainThread) [homeassistant.components.zha.core.device] [0xA320](371000001): Device seen - marking the device available and resetting counter 2024-03-02 17:34:16.181 DEBUG (MainThread) [homeassistant.components.zha.core.device] [0xA320](371000001): Update device availability - device available: True - new availability: True - changed: False 2024-03-02 17:34:16.183 DEBUG (MainThread) [homeassistant.components.zha.core.device] [0x4085](RODRET Dimmer): Device seen - marking the device available and resetting counter 2024-03-02 17:34:16.183 DEBUG (MainThread) [homeassistant.components.zha.core.device] [0x4085](RODRET Dimmer): Update device availability - device available: True - new availability: True - changed: False 2024-03-02 17:34:16.185 DEBUG (MainThread) [homeassistant.components.zha.core.device] [0x9BE7](JETSTROM 6060): Device seen - marking the device available and resetting counter 2024-03-02 17:34:16.185 DEBUG (MainThread) [homeassistant.components.zha.core.device] [0x9BE7](JETSTROM 6060): Update device availability - device available: True - new availability: True - changed: False 2024-03-02 17:34:17.094 DEBUG (MainThread) [zigpy_deconz.uart] Frame received: 0x0e90000700a600 2024-03-02 17:34:17.096 DEBUG (MainThread) [zigpy_deconz.api] Received command CommandId.device_state_changed{'status': , 'frame_length': 7, 'device_state': DeviceState(network_state=, device_state=), 'reserved': 0} (seq 144) 2024-03-02 17:34:17.099 DEBUG (MainThread) [zigpy_deconz.api] Sending CommandId.aps_data_confirm{} (seq=144) 2024-03-02 17:34:17.100 DEBUG (MainThread) [zigpy_deconz.uart] Send: 04900007000000 2024-03-02 17:34:17.105 DEBUG (MainThread) [zigpy_deconz.uart] Frame received: 0x04900013000c0022c902e6ca0101a700000000 2024-03-02 17:34:17.107 DEBUG (MainThread) [zigpy_deconz.api] Received command CommandId.aps_data_confirm{'status': , 'frame_length': 19, 'payload_length': 12, 'device_state': DeviceState(network_state=, device_state=), 'request_id': 201, 'dst_addr': DeconzAddressEndpoint(address_mode=, address=0xCAE6, endpoint=1), 'src_ep': 1, 'confirm_status': , 'reserved1': 0, 'reserved2': 0, 'reserved3': 0, 'reserved4': 0} (seq 144) 2024-03-02 17:34:17.109 DEBUG (MainThread) [zigpy.device] [0xcae6] OTA image_notify handler - exception: Failed to deliver packet: 2024-03-02 17:34:17.112 ERROR (MainThread) [homeassistant.components.websocket_api.http.connection] [547378589248] Update was not successful - result: Traceback (most recent call last): File "/usr/src/homeassistant/homeassistant/components/websocket_api/commands.py", line 240, in handle_call_service response = await hass.services.async_call( ^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^ File "/usr/src/homeassistant/homeassistant/core.py", line 2279, in async_call response_data = await coro ^^^^^^^^^^ File "/usr/src/homeassistant/homeassistant/core.py", line 2316, in _execute_service return await target(service_call) ^^^^^^^^^^^^^^^^^^^^^^^^^^ File "/usr/src/homeassistant/homeassistant/helpers/service.py", line 892, in entity_service_call single_response = await _handle_entity_call( ^^^^^^^^^^^^^^^^^^^^^^^^^^ File "/usr/src/homeassistant/homeassistant/helpers/service.py", line 962, in _handle_entity_call result = await task ^^^^^^^^^^ File "/usr/src/homeassistant/homeassistant/components/update/__init__.py", line 161, in async_install await entity.async_install_with_progress(version, backup) File "/usr/src/homeassistant/homeassistant/components/update/__init__.py", line 465, in async_install_with_progress await self.async_install(version, backup) File "/usr/src/homeassistant/homeassistant/components/zha/update.py", line 177, in async_install raise HomeAssistantError(f"Update was not successful - result: {results}") homeassistant.exceptions.HomeAssistantError: Update was not successful - result: 2024-03-02 17:34:24.190 DEBUG (MainThread) [homeassistant.components.zha.core.device] [0x10AA](TRADFRI remote control): Device seen - marking the device available and resetting counter 2024-03-02 17:34:24.191 DEBUG (MainThread) [homeassistant.components.zha.core.device] [0x10AA](TRADFRI remote control): Update device availability - device available: True - new availability: True - changed: False ```

Additional information

Also found here: https://community.home-assistant.io/t/zigbee-firmware-update-failed/687459/18

MattWestb commented 4 months ago

Duplicate of https://github.com/zigpy/zigpy/issues/1347 but good that im not alone !! I have one that was being updated but its in one test system with RCP coordinator and the tricky one is in my production system.

theincogtion commented 4 months ago

I am following this now: image And I am one step ahead now: image I removed the batteries, places it near my conbee and reinserted them.

MattWestb commented 4 months ago

Ping @puddly !!!

Looks being somthing broken with some unicast commands that working if the device is one direct child of the coordinator (my is blocked having direct children).

You can trying downgrading one IKEA light then its looks like there lights and plugs is also having the same problem.

puddly commented 4 months ago

What brand of router device is it joined through? It looks like a request is being sent to the device but it doesn't respond within 10s.

theincogtion commented 4 months ago

What brand of router device is it joined through? It looks like a request is being sent to the device but it doesn't respond within 10s. Conbee 2 (usb with mini cable on raspi 4) image

Live Ticker: image

MattWestb commented 4 months ago

For me the working one: Device info LEPTITER Recessed spot light by IKEA of Sweden Connected via [Billy RCP 7.4.0.0 RK3318 Firmware: 0x23087631 (Gen 1/2)

And the not working is on: Device info STOFTMOLN ceiling/wall lamp WW24 by IKEA of Sweden Firmware: 0x00010006 (Gen 3).

devosthomas commented 3 months ago

This also worked for me: remove batteries, put them back in near the Conbee II USB dongle and launched the update process. The update takes time so be patient.