search

home-assistant / core

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

ZHA end device (Legrand 067773) OTA firmware update failing with `INVALID_IMAGE` preceded by `MAC_PAN_ACCESS_DENIED`. #114375

Closed smmoroz closed 2 months ago

smmoroz commented 8 months ago

The problem

OTA firmware update of my Legrand 067773 end device failing with INVALID_IMAGE preceded by MAC_PAN_ACCESS_DENIED.

My procedure:

  1. There is notification that a new firmware is available

CleanShot 2024-03-28 at 13 43 11

  1. I first press on/off button on a device to make it alive (you will see in the debug log)
  2. After that I press "INSTALL" button in the UI
  3. In a some seconds there is Update was not successful: <Status.INVALID_IMAGE: 150> error.

But in the logs there is a strange MAC_PAN_ACCESS_DENIED message (see below).

What version of Home Assistant Core has the issue?

core-2024.3.3

What was the last working version of Home Assistant Core?

No response

What type of installation are you running?

Home Assistant OS

Integration causing the issue

ZHA

Link to integration documentation on our website

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

Diagnostics information

zha-24f56eb317664354a00f2267a4963692- Legrand Remote switch-56a51c5084981cc44552a14fc0148244.json

Example YAML snippet

logger: 
  default: warning
  logs:
    homeassistant.components.zha: debug
    zigpy: debug

zha:
  database_path: zigbee.db
  zigpy_config:
    ota:
      # It's enabled by default
      enabled: true

      ikea_provider: true
      # Disable not needed providers
      inovelli_provider: false
      ledvance_provider: false
      salus_provider: false
      thirdreality_provider: false

      # Periodically send out a network-wide (including end devices!) image notification
      broadcast_enabled: true
      broadcast_initial_delay: 14400
      broadcast_interval: 14400

      # Points to Z2M OTA `index.json` URL
      z2m_remote_index: "https://raw.githubusercontent.com/Koenkk/zigbee-OTA/master/index.json"    
  custom_quirks_path: /config/custom_zha_quirks/

zha_toolkit:

Anything in the logs that might be useful for us?

2024-03-28 13:21:43.841 DEBUG (MainThread) [zigpy.application] Received a packet: ZigbeePacket(timestamp=datetime.datetime(2024, 3, 28, 10, 21, 43, 841153, tzinfo=datetime.timezone.utc), src=AddrModeAddress(addr_mode=<AddrMode.NWK: 2>, address=0x5B97), src_ep=1, dst=AddrModeAddress(addr_mode=<AddrMode.NWK: 2>, address=0x0000), dst_ep=1, source_route=None, extended_timeout=False, tsn=88, profile_id=260, cluster_id=6, data=Serialized[b'\x113\x01'], tx_options=<TransmitOptions.NONE: 0>, radius=0, non_member_radius=0, lqi=144, rssi=-64)
2024-03-28 13:21:43.843 DEBUG (MainThread) [zigpy.zcl] [0x5B97:1:0x0006] Received ZCL frame: b'\x113\x01'
2024-03-28 13:21:43.844 DEBUG (MainThread) [zigpy.zcl] [0x5B97:1:0x0006] Decoded ZCL frame header: ZCLHeader(frame_control=FrameControl<0x11>(frame_type=<FrameType.CLUSTER_COMMAND: 1>, is_manufacturer_specific=0, direction=<Direction.Client_to_Server: 0>, disable_default_response=1, reserved=0, *is_cluster=True, *is_general=False), tsn=51, command_id=1, *direction=<Direction.Client_to_Server: 0>)
2024-03-28 13:21:43.848 DEBUG (MainThread) [zigpy.zcl] [0x5B97:1:0x0006] Decoded ZCL frame: OnOff:on()
2024-03-28 13:21:43.848 DEBUG (MainThread) [zigpy.zcl] [0x5B97:1:0x0006] Received command 0x01 (TSN 51): on()
2024-03-28 13:21:43.849 DEBUG (MainThread) [zigpy.zcl] [0x5B97:1:0x0006] No explicit handler for cluster command 0x01: on()
2024-03-28 13:21:45.396 DEBUG (MainThread) [zigpy.zcl] [0x5B97:1:0x0019] Sending reply header: ZCLHeader(frame_control=FrameControl<0x19>(frame_type=<FrameType.CLUSTER_COMMAND: 1>, is_manufacturer_specific=False, direction=<Direction.Server_to_Client: 1>, disable_default_response=1, reserved=0, *is_cluster=True, *is_general=False), tsn=13, command_id=0, *direction=<Direction.Server_to_Client: 1>)
2024-03-28 13:21:45.398 DEBUG (MainThread) [zigpy.zcl] [0x5B97:1:0x0019] Sending reply: ImageNotifyCommand(payload_type=<PayloadType.QueryJitter: 0>, query_jitter=100)
2024-03-28 13:21:45.422 DEBUG (MainThread) [homeassistant.components.zha.core.device] [0x1D14]( Remote switch): last_seen is 42433054.931077 seconds ago and ping attempts have been exhausted, marking the device unavailable
2024-03-28 13:21:45.422 DEBUG (MainThread) [homeassistant.components.zha.core.device] [0x1D14]( Remote switch): Update device availability -  device available: False - new availability: False - changed: False
2024-03-28 13:21:45.694 DEBUG (MainThread) [zigpy.application] Received a packet: ZigbeePacket(timestamp=datetime.datetime(2024, 3, 28, 10, 21, 45, 694887, tzinfo=datetime.timezone.utc), src=AddrModeAddress(addr_mode=<AddrMode.NWK: 2>, address=0x5B97), src_ep=1, dst=AddrModeAddress(addr_mode=<AddrMode.NWK: 2>, address=0x0000), dst_ep=1, source_route=None, extended_timeout=False, tsn=90, profile_id=260, cluster_id=25, data=Serialized[b'\x014\x01\x00!\x10\x12\x00\x03B<\x00'], tx_options=<TransmitOptions.NONE: 0>, radius=0, non_member_radius=0, lqi=144, rssi=-64)
2024-03-28 13:21:45.696 DEBUG (MainThread) [zigpy.zcl] [0x5B97:1:0x0019] Received ZCL frame: b'\x014\x01\x00!\x10\x12\x00\x03B<\x00'
2024-03-28 13:21:45.697 DEBUG (MainThread) [zigpy.zcl] [0x5B97:1:0x0019] Decoded ZCL frame header: ZCLHeader(frame_control=FrameControl<0x01>(frame_type=<FrameType.CLUSTER_COMMAND: 1>, is_manufacturer_specific=0, direction=<Direction.Client_to_Server: 0>, disable_default_response=0, reserved=0, *is_cluster=True, *is_general=False), tsn=52, command_id=1, *direction=<Direction.Client_to_Server: 0>)
2024-03-28 13:21:45.699 DEBUG (MainThread) [zigpy.zcl] [0x5B97:1:0x0019] Decoded ZCL frame: Ota:QueryNextImageCommand(field_control=<FieldControl: 0>, manufacturer_code=4129, image_type=18, current_file_version=3949059)
2024-03-28 13:21:45.699 DEBUG (MainThread) [zigpy.zcl] [0x5B97:1:0x0019] Received command 0x01 (TSN 52): QueryNextImageCommand(field_control=<FieldControl: 0>, manufacturer_code=4129, image_type=18, current_file_version=3949059)
2024-03-28 13:21:45.700 DEBUG (MainThread) [homeassistant.components.zha.core.cluster_handlers] [0x5B97:1:0x0019]: cluster_handler[ota] attribute_updated - cluster[Ota] attr[current_file_version] value[3949059]
2024-03-28 13:21:45.705 DEBUG (MainThread) [zigpy.zcl] [0x5B97:1:0x0019] Sending reply header: ZCLHeader(frame_control=FrameControl<0x19>(frame_type=<FrameType.CLUSTER_COMMAND: 1>, is_manufacturer_specific=False, direction=<Direction.Server_to_Client: 1>, disable_default_response=1, reserved=0, *is_cluster=True, *is_general=False), tsn=52, command_id=2, *direction=<Direction.Server_to_Client: 1>)
2024-03-28 13:21:45.706 DEBUG (MainThread) [zigpy.zcl] [0x5B97:1:0x0019] Sending reply: query_next_image_response(status=<Status.SUCCESS: 0>, manufacturer_code=4129, image_type=18, file_version=4604419, image_size=203143)
2024-03-28 13:21:46.275 DEBUG (MainThread) [zigpy.application] Received a packet: ZigbeePacket(timestamp=datetime.datetime(2024, 3, 28, 10, 21, 46, 275747, tzinfo=datetime.timezone.utc), src=AddrModeAddress(addr_mode=<AddrMode.NWK: 2>, address=0x5B97), src_ep=1, dst=AddrModeAddress(addr_mode=<AddrMode.NWK: 2>, address=0x0000), dst_ep=1, source_route=None, extended_timeout=False, tsn=91, profile_id=260, cluster_id=25, data=Serialized[b'\x015\x03\x02!\x10\x12\x00\x03BF\x00(\x00\x00\x00\x16\x14\x00'], tx_options=<TransmitOptions.NONE: 0>, radius=0, non_member_radius=0, lqi=144, rssi=-64)
2024-03-28 13:21:46.277 DEBUG (MainThread) [zigpy.zcl] [0x5B97:1:0x0019] Received ZCL frame: b'\x015\x03\x02!\x10\x12\x00\x03BF\x00(\x00\x00\x00\x16\x14\x00'
2024-03-28 13:21:46.278 DEBUG (MainThread) [zigpy.zcl] [0x5B97:1:0x0019] Decoded ZCL frame header: ZCLHeader(frame_control=FrameControl<0x01>(frame_type=<FrameType.CLUSTER_COMMAND: 1>, is_manufacturer_specific=0, direction=<Direction.Client_to_Server: 0>, disable_default_response=0, reserved=0, *is_cluster=True, *is_general=False), tsn=53, command_id=3, *direction=<Direction.Client_to_Server: 0>)
2024-03-28 13:21:46.279 DEBUG (MainThread) [zigpy.zcl] [0x5B97:1:0x0019] Decoded ZCL frame: Ota:ImageBlockCommand(field_control=<FieldControl.MinimumBlockPeriod: 2>, manufacturer_code=4129, image_type=18, file_version=4604419, file_offset=40, maximum_data_size=22, minimum_block_period=20)
2024-03-28 13:21:46.280 DEBUG (MainThread) [zigpy.zcl] [0x5B97:1:0x0019] Received command 0x03 (TSN 53): ImageBlockCommand(field_control=<FieldControl.MinimumBlockPeriod: 2>, manufacturer_code=4129, image_type=18, file_version=4604419, file_offset=40, maximum_data_size=22, minimum_block_period=20)
2024-03-28 13:21:46.288 DEBUG (MainThread) [zigpy.zcl] [0x5B97:1:0x0019] Sending reply header: ZCLHeader(frame_control=FrameControl<0x19>(frame_type=<FrameType.CLUSTER_COMMAND: 1>, is_manufacturer_specific=False, direction=<Direction.Server_to_Client: 1>, disable_default_response=1, reserved=0, *is_cluster=True, *is_general=False), tsn=53, command_id=5, *direction=<Direction.Server_to_Client: 1>)
2024-03-28 13:21:46.289 DEBUG (MainThread) [zigpy.zcl] [0x5B97:1:0x0019] Sending reply: ImageBlockResponseCommand(status=<Status.SUCCESS: 0>, manufacturer_code=4129, image_type=18, file_version=4604419, file_offset=40, image_data=b'            \x87\x19\x03\x00\x00\x00I\x19\x03\x00')
2024-03-28 13:21:46.750 INFO (MainThread) [zigpy.device] [0x5b97] OTA upgrade progress: (62 / 203143): 0.0305%
2024-03-28 13:21:46.764 DEBUG (MainThread) [zigpy.application] Received a packet: ZigbeePacket(timestamp=datetime.datetime(2024, 3, 28, 10, 21, 46, 763949, tzinfo=datetime.timezone.utc), src=AddrModeAddress(addr_mode=<AddrMode.NWK: 2>, address=0x5B97), src_ep=1, dst=AddrModeAddress(addr_mode=<AddrMode.NWK: 2>, address=0x0000), dst_ep=1, source_route=None, extended_timeout=False, tsn=92, profile_id=260, cluster_id=25, data=Serialized[b'\x105\x0b\x05\x02'], tx_options=<TransmitOptions.NONE: 0>, radius=0, non_member_radius=0, lqi=144, rssi=-64)
2024-03-28 13:21:46.765 DEBUG (MainThread) [zigpy.zcl] [0x5B97:1:0x0019] Received ZCL frame: b'\x105\x0b\x05\x02'
2024-03-28 13:21:46.766 DEBUG (MainThread) [zigpy.zcl] [0x5B97:1:0x0019] Decoded ZCL frame header: ZCLHeader(frame_control=FrameControl<0x10>(frame_type=<FrameType.GLOBAL_COMMAND: 0>, is_manufacturer_specific=0, direction=<Direction.Client_to_Server: 0>, disable_default_response=1, reserved=0, *is_cluster=False, *is_general=True), tsn=53, command_id=11, *direction=<Direction.Client_to_Server: 0>)
2024-03-28 13:21:46.768 DEBUG (MainThread) [zigpy.zcl] [0x5B97:1:0x0019] Decoded ZCL frame: Ota:Default_Response(command_id=5, status=<Status.MAC_PAN_ACCESS_DENIED: 2>)
2024-03-28 13:21:46.769 DEBUG (MainThread) [zigpy.zcl] [0x5B97:1:0x0019] Received command 0x0B (TSN 53): Default_Response(command_id=5, status=<Status.MAC_PAN_ACCESS_DENIED: 2>)
2024-03-28 13:21:46.873 DEBUG (MainThread) [zigpy.application] Received a packet: ZigbeePacket(timestamp=datetime.datetime(2024, 3, 28, 10, 21, 46, 873777, tzinfo=datetime.timezone.utc), src=AddrModeAddress(addr_mode=<AddrMode.NWK: 2>, address=0x5B97), src_ep=1, dst=AddrModeAddress(addr_mode=<AddrMode.NWK: 2>, address=0x0000), dst_ep=1, source_route=None, extended_timeout=False, tsn=93, profile_id=260, cluster_id=25, data=Serialized[b'\x016\x06\x96!\x10\x12\x00\x03BF\x00'], tx_options=<TransmitOptions.NONE: 0>, radius=0, non_member_radius=0, lqi=144, rssi=-64)
2024-03-28 13:21:46.875 DEBUG (MainThread) [zigpy.zcl] [0x5B97:1:0x0019] Received ZCL frame: b'\x016\x06\x96!\x10\x12\x00\x03BF\x00'
2024-03-28 13:21:46.875 DEBUG (MainThread) [zigpy.zcl] [0x5B97:1:0x0019] Decoded ZCL frame header: ZCLHeader(frame_control=FrameControl<0x01>(frame_type=<FrameType.CLUSTER_COMMAND: 1>, is_manufacturer_specific=0, direction=<Direction.Client_to_Server: 0>, disable_default_response=0, reserved=0, *is_cluster=True, *is_general=False), tsn=54, command_id=6, *direction=<Direction.Client_to_Server: 0>)
2024-03-28 13:21:46.877 DEBUG (MainThread) [zigpy.zcl] [0x5B97:1:0x0019] Decoded ZCL frame: Ota:upgrade_end(status=<Status.INVALID_IMAGE: 150>, manufacturer_code=4129, image_type=18, file_version=4604419)
2024-03-28 13:21:46.877 DEBUG (MainThread) [zigpy.zcl] [0x5B97:1:0x0019] Received command 0x06 (TSN 54): upgrade_end(status=<Status.INVALID_IMAGE: 150>, manufacturer_code=4129, image_type=18, file_version=4604419)
2024-03-28 13:21:46.879 DEBUG (MainThread) [zigpy.zcl] [0x5B97:1:0x0019] Sending reply header: ZCLHeader(frame_control=FrameControl<0x19>(frame_type=<FrameType.CLUSTER_COMMAND: 1>, is_manufacturer_specific=False, direction=<Direction.Server_to_Client: 1>, disable_default_response=1, reserved=0, *is_cluster=True, *is_general=False), tsn=54, command_id=7, *direction=<Direction.Server_to_Client: 1>)
2024-03-28 13:21:46.880 DEBUG (MainThread) [zigpy.zcl] [0x5B97:1:0x0019] Sending reply: upgrade_end_response(manufacturer_code=4129, image_type=18, file_version=4604419, current_time=0, upgrade_time=0)
2024-03-28 13:21:47.309 ERROR (MainThread) [homeassistant.components.websocket_api.http.connection] [546331194432] Update was not successful: <Status.INVALID_IMAGE: 150>
Traceback (most recent call last):
  File "/usr/src/homeassistant/homeassistant/components/websocket_api/commands.py", line 239, in handle_call_service
    response = await hass.services.async_call(
               ^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^
  File "/usr/src/homeassistant/homeassistant/core.py", line 2319, in async_call
    response_data = await coro
                    ^^^^^^^^^^
  File "/usr/src/homeassistant/homeassistant/core.py", line 2356, in _execute_service
    return await target(service_call)
           ^^^^^^^^^^^^^^^^^^^^^^^^^^
  File "/usr/src/homeassistant/homeassistant/helpers/service.py", line 905, in entity_service_call
    single_response = await _handle_entity_call(
                      ^^^^^^^^^^^^^^^^^^^^^^^^^^
  File "/usr/src/homeassistant/homeassistant/helpers/service.py", line 975, 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 198, in async_install
    raise HomeAssistantError(f"Update was not successful: {result}")
homeassistant.exceptions.HomeAssistantError: Update was not successful: <Status.INVALID_IMAGE: 150>

Additional information

No response

home-assistant[bot] commented 8 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)

stevenwfoley commented 5 months ago

I'm experiencing the same thing. Below is my debug log output attempting to update a Legrand WNRR15 smart outlet.

2024-06-06 09:52:15.973 DEBUG (MainThread) [zigpy.zcl] [0xCD50:1:0x0019] Sending reply header: ZCLHeader(frame_control=FrameControl<0x19>(frame_type=<FrameType.CLUSTER_COMMAND: 1>, is_manufacturer_specific=False, direction=<Direction.Server_to_Client: 1>, disable_default_response=1, reserved=0, *is_cluster=True, *is_general=False), tsn=11, command_id=0, *direction=<Direction.Server_to_Client: 1>)
2024-06-06 09:52:15.974 DEBUG (MainThread) [zigpy.zcl] [0xCD50:1:0x0019] Sending reply: ImageNotifyCommand(payload_type=<PayloadType.QueryJitter: 0>, query_jitter=100)
2024-06-06 09:52:16.064 DEBUG (MainThread) [zigpy.application] Received a packet: ZigbeePacket(timestamp=datetime.datetime(2024, 6, 6, 13, 52, 16, 64336, tzinfo=datetime.timezone.utc), src=AddrModeAddress(addr_mode=<AddrMode.NWK: 2>, address=0xCD50), src_ep=1, dst=AddrModeAddress(addr_mode=<AddrMode.NWK: 2>, address=0x0000), dst_ep=1, source_route=None, extended_timeout=False, tsn=106, profile_id=260, cluster_id=25, data=Serialized[b'\x01\x87\x01\x00!\x10\x11\x00\xffCS\x00'], tx_options=<TransmitOptions.NONE: 0>, radius=0, non_member_radius=0, lqi=212, rssi=-47)
2024-06-06 09:52:16.065 DEBUG (MainThread) [zigpy.zcl] [0xCD50:1:0x0019] Received ZCL frame: b'\x01\x87\x01\x00!\x10\x11\x00\xffCS\x00'
2024-06-06 09:52:16.065 DEBUG (MainThread) [zigpy.zcl] [0xCD50:1:0x0019] Decoded ZCL frame header: ZCLHeader(frame_control=FrameControl<0x01>(frame_type=<FrameType.CLUSTER_COMMAND: 1>, is_manufacturer_specific=0, direction=<Direction.Client_to_Server: 0>, disable_default_response=0, reserved=0, *is_cluster=True, *is_general=False), tsn=135, command_id=1, *direction=<Direction.Client_to_Server: 0>)
2024-06-06 09:52:16.066 DEBUG (MainThread) [zigpy.zcl] [0xCD50:1:0x0019] Decoded ZCL frame: Ota:QueryNextImageCommand(field_control=<FieldControl: 0>, manufacturer_code=4129, image_type=17, current_file_version=5456895)
2024-06-06 09:52:16.066 DEBUG (MainThread) [zigpy.zcl] [0xCD50:1:0x0019] Received command 0x01 (TSN 135): QueryNextImageCommand(field_control=<FieldControl: 0>, manufacturer_code=4129, image_type=17, current_file_version=5456895)
2024-06-06 09:52:16.068 DEBUG (MainThread) [zigpy.zcl] [0xCD50:1:0x0019] Sending reply header: ZCLHeader(frame_control=FrameControl<0x19>(frame_type=<FrameType.CLUSTER_COMMAND: 1>, is_manufacturer_specific=False, direction=<Direction.Server_to_Client: 1>, disable_default_response=1, reserved=0, *is_cluster=True, *is_general=False), tsn=135, command_id=2, *direction=<Direction.Server_to_Client: 1>)
2024-06-06 09:52:16.068 DEBUG (MainThread) [zigpy.zcl] [0xCD50:1:0x0019] Sending reply: query_next_image_response(status=<Status.SUCCESS: 0>, manufacturer_code=4129, image_type=17, file_version=5915139, image_size=250775)
2024-06-06 09:52:21.892 DEBUG (MainThread) [zigpy.application] Received a packet: ZigbeePacket(timestamp=datetime.datetime(2024, 6, 6, 13, 52, 21, 892554, tzinfo=datetime.timezone.utc), src=AddrModeAddress(addr_mode=<AddrMode.NWK: 2>, address=0xCD50), src_ep=1, dst=AddrModeAddress(addr_mode=<AddrMode.NWK: 2>, address=0x0000), dst_ep=1, source_route=None, extended_timeout=False, tsn=107, profile_id=260, cluster_id=25, data=Serialized[b'\x01\x88\x03\x02!\x10\x11\x00\x03BZ\x00\x00\x00\x00\x00>\x14\x00'], tx_options=<TransmitOptions.NONE: 0>, radius=0, non_member_radius=0, lqi=212, rssi=-47)
2024-06-06 09:52:21.893 DEBUG (MainThread) [zigpy.zcl] [0xCD50:1:0x0019] Received ZCL frame: b'\x01\x88\x03\x02!\x10\x11\x00\x03BZ\x00\x00\x00\x00\x00>\x14\x00'
2024-06-06 09:52:21.894 DEBUG (MainThread) [zigpy.zcl] [0xCD50:1:0x0019] Decoded ZCL frame header: ZCLHeader(frame_control=FrameControl<0x01>(frame_type=<FrameType.CLUSTER_COMMAND: 1>, is_manufacturer_specific=0, direction=<Direction.Client_to_Server: 0>, disable_default_response=0, reserved=0, *is_cluster=True, *is_general=False), tsn=136, command_id=3, *direction=<Direction.Client_to_Server: 0>)
2024-06-06 09:52:21.894 DEBUG (MainThread) [zigpy.zcl] [0xCD50:1:0x0019] Decoded ZCL frame: Ota:ImageBlockCommand(field_control=<FieldControl.MinimumBlockPeriod: 2>, manufacturer_code=4129, image_type=17, file_version=5915139, file_offset=0, maximum_data_size=62, minimum_block_period=20)
2024-06-06 09:52:21.895 DEBUG (MainThread) [zigpy.zcl] [0xCD50:1:0x0019] Received command 0x03 (TSN 136): ImageBlockCommand(field_control=<FieldControl.MinimumBlockPeriod: 2>, manufacturer_code=4129, image_type=17, file_version=5915139, file_offset=0, maximum_data_size=62, minimum_block_period=20)
2024-06-06 09:52:21.896 DEBUG (MainThread) [zigpy.zcl] [0xCD50:1:0x0019] Sending reply header: ZCLHeader(frame_control=FrameControl<0x19>(frame_type=<FrameType.CLUSTER_COMMAND: 1>, is_manufacturer_specific=False, direction=<Direction.Server_to_Client: 1>, disable_default_response=1, reserved=0, *is_cluster=True, *is_general=False), tsn=136, command_id=5, *direction=<Direction.Server_to_Client: 1>)
2024-06-06 09:52:21.896 DEBUG (MainThread) [zigpy.zcl] [0xCD50:1:0x0019] Sending reply: ImageBlockResponseCommand(status=<Status.SUCCESS: 0>, manufacturer_code=4129, image_type=17, file_version=5915139, file_offset=0, image_data=b'\x1e\xf1\xee\x0b\x00\x018\x00\x00\x00!\x10\x11\x00\x03BZ\x00\x02\x00                    ')
2024-06-06 09:52:21.979 INFO (MainThread) [zigpy.device] [0xcd50] OTA upgrade progress: (40 / 250775): 0.0160%
2024-06-06 09:52:22.018 DEBUG (MainThread) [zigpy.application] Received a packet: ZigbeePacket(timestamp=datetime.datetime(2024, 6, 6, 13, 52, 22, 18091, tzinfo=datetime.timezone.utc), src=AddrModeAddress(addr_mode=<AddrMode.NWK: 2>, address=0xCD50), src_ep=1, dst=AddrModeAddress(addr_mode=<AddrMode.NWK: 2>, address=0x0000), dst_ep=1, source_route=None, extended_timeout=False, tsn=108, profile_id=260, cluster_id=25, data=Serialized[b'\x01\x89\x03\x02!\x10\x11\x00\x03BZ\x00(\x00\x00\x00\x16\x14\x00'], tx_options=<TransmitOptions.NONE: 0>, radius=0, non_member_radius=0, lqi=212, rssi=-47)
2024-06-06 09:52:22.019 DEBUG (MainThread) [zigpy.zcl] [0xCD50:1:0x0019] Received ZCL frame: b'\x01\x89\x03\x02!\x10\x11\x00\x03BZ\x00(\x00\x00\x00\x16\x14\x00'
2024-06-06 09:52:22.019 DEBUG (MainThread) [zigpy.zcl] [0xCD50:1:0x0019] Decoded ZCL frame header: ZCLHeader(frame_control=FrameControl<0x01>(frame_type=<FrameType.CLUSTER_COMMAND: 1>, is_manufacturer_specific=0, direction=<Direction.Client_to_Server: 0>, disable_default_response=0, reserved=0, *is_cluster=True, *is_general=False), tsn=137, command_id=3, *direction=<Direction.Client_to_Server: 0>)
2024-06-06 09:52:22.020 DEBUG (MainThread) [zigpy.zcl] [0xCD50:1:0x0019] Decoded ZCL frame: Ota:ImageBlockCommand(field_control=<FieldControl.MinimumBlockPeriod: 2>, manufacturer_code=4129, image_type=17, file_version=5915139, file_offset=40, maximum_data_size=22, minimum_block_period=20)
2024-06-06 09:52:22.020 DEBUG (MainThread) [zigpy.zcl] [0xCD50:1:0x0019] Received command 0x03 (TSN 137): ImageBlockCommand(field_control=<FieldControl.MinimumBlockPeriod: 2>, manufacturer_code=4129, image_type=17, file_version=5915139, file_offset=40, maximum_data_size=22, minimum_block_period=20)
2024-06-06 09:52:22.021 DEBUG (MainThread) [zigpy.zcl] [0xCD50:1:0x0019] Sending reply header: ZCLHeader(frame_control=FrameControl<0x19>(frame_type=<FrameType.CLUSTER_COMMAND: 1>, is_manufacturer_specific=False, direction=<Direction.Server_to_Client: 1>, disable_default_response=1, reserved=0, *is_cluster=True, *is_general=False), tsn=137, command_id=5, *direction=<Direction.Server_to_Client: 1>)
2024-06-06 09:52:22.022 DEBUG (MainThread) [zigpy.zcl] [0xCD50:1:0x0019] Sending reply: ImageBlockResponseCommand(status=<Status.SUCCESS: 0>, manufacturer_code=4129, image_type=17, file_version=5915139, file_offset=40, image_data=b'            \x97\xd3\x03\x00\x00\x00Y\xd3\x03\x00')
2024-06-06 09:52:22.097 INFO (MainThread) [zigpy.device] [0xcd50] OTA upgrade progress: (62 / 250775): 0.0247%
2024-06-06 09:52:22.110 DEBUG (MainThread) [zigpy.application] Received a packet: ZigbeePacket(timestamp=datetime.datetime(2024, 6, 6, 13, 52, 22, 110723, tzinfo=datetime.timezone.utc), src=AddrModeAddress(addr_mode=<AddrMode.NWK: 2>, address=0xCD50), src_ep=1, dst=AddrModeAddress(addr_mode=<AddrMode.NWK: 2>, address=0x0000), dst_ep=1, source_route=None, extended_timeout=False, tsn=109, profile_id=260, cluster_id=25, data=Serialized[b'\x10\x89\x0b\x05\x02'], tx_options=<TransmitOptions.NONE: 0>, radius=0, non_member_radius=0, lqi=212, rssi=-47)
2024-06-06 09:52:22.111 DEBUG (MainThread) [zigpy.zcl] [0xCD50:1:0x0019] Received ZCL frame: b'\x10\x89\x0b\x05\x02'
2024-06-06 09:52:22.112 DEBUG (MainThread) [zigpy.zcl] [0xCD50:1:0x0019] Decoded ZCL frame header: ZCLHeader(frame_control=FrameControl<0x10>(frame_type=<FrameType.GLOBAL_COMMAND: 0>, is_manufacturer_specific=0, direction=<Direction.Client_to_Server: 0>, disable_default_response=1, reserved=0, *is_cluster=False, *is_general=True), tsn=137, command_id=11, *direction=<Direction.Client_to_Server: 0>)
2024-06-06 09:52:22.112 DEBUG (MainThread) [zigpy.zcl] [0xCD50:1:0x0019] Decoded ZCL frame: Ota:Default_Response(command_id=5, status=<Status.MAC_PAN_ACCESS_DENIED: 2>)
2024-06-06 09:52:22.113 DEBUG (MainThread) [zigpy.zcl] [0xCD50:1:0x0019] Received command 0x0B (TSN 137): Default_Response(command_id=5, status=<Status.MAC_PAN_ACCESS_DENIED: 2>)
2024-06-06 09:52:22.207 DEBUG (MainThread) [zigpy.application] Received a packet: ZigbeePacket(timestamp=datetime.datetime(2024, 6, 6, 13, 52, 22, 207311, tzinfo=datetime.timezone.utc), src=AddrModeAddress(addr_mode=<AddrMode.NWK: 2>, address=0xCD50), src_ep=1, dst=AddrModeAddress(addr_mode=<AddrMode.NWK: 2>, address=0x0000), dst_ep=1, source_route=None, extended_timeout=False, tsn=110, profile_id=260, cluster_id=25, data=Serialized[b'\x01\x8a\x06\x96!\x10\x11\x00\x03BZ\x00'], tx_options=<TransmitOptions.NONE: 0>, radius=0, non_member_radius=0, lqi=212, rssi=-47)
2024-06-06 09:52:22.208 DEBUG (MainThread) [zigpy.zcl] [0xCD50:1:0x0019] Received ZCL frame: b'\x01\x8a\x06\x96!\x10\x11\x00\x03BZ\x00'
2024-06-06 09:52:22.208 DEBUG (MainThread) [zigpy.zcl] [0xCD50:1:0x0019] Decoded ZCL frame header: ZCLHeader(frame_control=FrameControl<0x01>(frame_type=<FrameType.CLUSTER_COMMAND: 1>, is_manufacturer_specific=0, direction=<Direction.Client_to_Server: 0>, disable_default_response=0, reserved=0, *is_cluster=True, *is_general=False), tsn=138, command_id=6, *direction=<Direction.Client_to_Server: 0>)
2024-06-06 09:52:22.209 DEBUG (MainThread) [zigpy.zcl] [0xCD50:1:0x0019] Decoded ZCL frame: Ota:upgrade_end(status=<Status.INVALID_IMAGE: 150>, manufacturer_code=4129, image_type=17, file_version=5915139)
2024-06-06 09:52:22.210 DEBUG (MainThread) [zigpy.zcl] [0xCD50:1:0x0019] Received command 0x06 (TSN 138): upgrade_end(status=<Status.INVALID_IMAGE: 150>, manufacturer_code=4129, image_type=17, file_version=5915139)
2024-06-06 09:52:22.210 DEBUG (MainThread) [zigpy.zcl] [0xCD50:1:0x0019] Sending reply header: ZCLHeader(frame_control=FrameControl<0x19>(frame_type=<FrameType.CLUSTER_COMMAND: 1>, is_manufacturer_specific=False, direction=<Direction.Server_to_Client: 1>, disable_default_response=1, reserved=0, *is_cluster=True, *is_general=False), tsn=138, command_id=7, *direction=<Direction.Server_to_Client: 1>)
2024-06-06 09:52:22.211 DEBUG (MainThread) [zigpy.zcl] [0xCD50:1:0x0019] Sending reply: upgrade_end_response(manufacturer_code=4129, image_type=17, file_version=5915139, current_time=0, upgrade_time=0)
2024-06-06 09:52:22.281 ERROR (MainThread) [homeassistant.components.websocket_api.http.connection] [140099642118288] Unexpected exception
Traceback (most recent call last):
  File "/usr/src/homeassistant/homeassistant/components/websocket_api/commands.py", line 241, in handle_call_service
    response = await hass.services.async_call(
               ^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^
  File "/usr/src/homeassistant/homeassistant/core.py", line 2741, in async_call
    response_data = await coro
                    ^^^^^^^^^^
  File "/usr/src/homeassistant/homeassistant/core.py", line 2784, in _execute_service
    return await target(service_call)
           ^^^^^^^^^^^^^^^^^^^^^^^^^^
  File "/usr/src/homeassistant/homeassistant/helpers/service.py", line 977, in entity_service_call
    single_response = await _handle_entity_call(
                      ^^^^^^^^^^^^^^^^^^^^^^^^^^
  File "/usr/src/homeassistant/homeassistant/helpers/service.py", line 1049, in _handle_entity_call
    result = await task
             ^^^^^^^^^^
  File "/usr/src/homeassistant/homeassistant/components/update/__init__.py", line 157, in async_install
    await entity.async_install_with_progress(version, backup)
  File "/usr/src/homeassistant/homeassistant/components/update/__init__.py", line 461, in async_install_with_progress
    await self.async_install(version, backup)
  File "/usr/src/homeassistant/homeassistant/components/zha/update.py", line 196, in async_install
    raise HomeAssistantError(f"Update was not successful: {result}")
homeassistant.exceptions.HomeAssistantError: Update was not successful: <Status.INVALID_IMAGE: 150>
puddly commented 5 months ago

Legrand devices have a broken OTA implementation and are not currently supported.

issue-triage-workflows[bot] commented 2 months ago

There hasn't been any activity on this issue recently. Due to the high number of incoming GitHub notifications, we have to clean some of the old issues, as many of them have already been resolved with the latest updates. Please make sure to update to the latest Home Assistant version and check if that solves the issue. Let us know if that works for you by adding a comment 👍 This issue has now been marked as stale and will be closed if no further activity occurs. Thank you for your contributions.