search

mdeweerd / zha-toolkit

🧰 Zigbee Home Assistant Toolkit - service for "rare" Zigbee operations using ZHA on Home Assistant
GNU General Public License v3.0
171 stars 17 forks source link

Fehler beim Aufrufen des Diensts zha_toolkit.scan_device. Unknown error #215

Closed SimonIT closed 7 months ago

SimonIT commented 7 months ago

Hi, when I try to scan a device I'm getting this error:

Exception '' for service call with data '{'zha_toolkit_version': 'v1.1.7', 'zigpy_version': '0.59.0', 'zigpy_rf_version': '0.21.1', 'ieee_org': 8c:f6:81:ff:fe:08:ed:fd, 'ieee': '8c:f6:81:ff:fe:08:ed:fd', 'command': 'scan_device', 'command_data': None, 'start_time': '2023-12-04T13:15:13.433358+00:00', 'errors': ['ParsingError()'], 'params': {'dir': 0, 'tries': 1, 'expect_reply': True, 'args': [], 'read_before_write': True, 'read_after_write': True}, 'success': False}'

It worked some time ago, but I don't know what changed since then

mdeweerd commented 7 months ago

Which HA version are you using?

Is it failing with all devices, or just one in particular (there is a bug in zigpy when you are reading an array).

Is this from /*/home-assistant.log ? Is there a backtrace (indicating the line that failed)?

I would still expect a non empty exception.

SimonIT commented 7 months ago

Core 2023.11.3 Supervisor 2023.11.6 Operating System 11.1 Frontend 20231030.2

2023-12-04 14:15:35.585 DEBUG (MainThread) [zigpy_deconz.api] Received command device_state_changed[<DeviceState.APSDE_DATA_CONFIRM|APSDE_DATA_REQUEST_SLOTS_AVAILABLE|130: 166>, 0]
2023-12-04 14:15:35.585 DEBUG (MainThread) [zigpy_deconz.api] Device state changed response: [<DeviceState.APSDE_DATA_CONFIRM|APSDE_DATA_REQUEST_SLOTS_AVAILABLE|130: 166>, 0]
2023-12-04 14:15:35.586 DEBUG (MainThread) [zigpy_deconz.api] Command Command.aps_data_confirm (0,)
2023-12-04 14:15:35.592 DEBUG (MainThread) [zigpy_deconz.api] Received command mac_poll[5, <DeconzAddress address_mode=AddressMode.NWK address=0x4718>, 255, -55]
2023-12-04 14:15:35.593 DEBUG (MainThread) [zigpy_deconz.api] Received command mac_poll[5, <DeconzAddress address_mode=AddressMode.NWK address=0x4718>, 255, -55]
2023-12-04 14:15:35.594 DEBUG (MainThread) [zigpy_deconz.api] Received command aps_data_confirm[12, <DeviceState.APSDE_DATA_REQUEST_SLOTS_AVAILABLE|2: 34>, 14, <DeconzAddressEndpoint address_mode=AddressMode.NWK address=0x4718 endpoint=1>, 1, <TXStatus.SUCCESS: 0>, 0, 0, 0, 0]
2023-12-04 14:15:35.595 DEBUG (MainThread) [zigpy_deconz.api] APS data confirm response for request with id 14: 00
2023-12-04 14:15:35.596 DEBUG (MainThread) [zigpy_deconz.api] Request id: 0x0e 'aps_data_confirm' for <DeconzAddressEndpoint address_mode=AddressMode.NWK address=0x4718 endpoint=1>, status: 0x00
2023-12-04 14:15:35.598 DEBUG (MainThread) [zigpy_deconz.api] Received command device_state_changed[<DeviceState.APSDE_DATA_INDICATION|APSDE_DATA_REQUEST_SLOTS_AVAILABLE|130: 170>, 0]
2023-12-04 14:15:35.599 DEBUG (MainThread) [zigpy_deconz.api] Device state changed response: [<DeviceState.APSDE_DATA_INDICATION|APSDE_DATA_REQUEST_SLOTS_AVAILABLE|130: 170>, 0]
2023-12-04 14:15:35.600 DEBUG (MainThread) [zigpy_deconz.api] Command Command.aps_data_indication (1, <DataIndicationFlags.Always_Use_NWK_Source_Addr: 1>)
2023-12-04 14:15:35.607 DEBUG (MainThread) [zigpy_deconz.api] Received command aps_data_indication[87, <DeviceState.APSDE_DATA_REQUEST_SLOTS_AVAILABLE|2: 34>, <DeconzAddress address_mode=AddressMode.NWK address=0x0000>, 1, <DeconzAddress address_mode=AddressMode.NWK address=0x4718>, 1, 260, 0, b'\x18\r\x01\xde\xff\x00 \x0b\xe0\xff\x00H(\xdb\xfb\xa61\xd1\x8c0\xa4T&\x9a"\xfdB\x86?\xe8\xceO&\xe1m\x96\x7fG\xf9\x1d/9\x178\rJ\x14\xd4\xf2\x8b\xfc\xbdt\xfd\xff\x00!\x02\x00\xfe\xff\x000\x00', 0, 175, 255, 17, 62, 156, 0, -56]
2023-12-04 14:15:35.608 DEBUG (MainThread) [zigpy_deconz.api] APS data indication response: [87, <DeviceState.APSDE_DATA_REQUEST_SLOTS_AVAILABLE|2: 34>, <DeconzAddress address_mode=AddressMode.NWK address=0x0000>, 1, <DeconzAddress address_mode=AddressMode.NWK address=0x4718>, 1, 260, 0, b'\x18\r\x01\xde\xff\x00 \x0b\xe0\xff\x00H(\xdb\xfb\xa61\xd1\x8c0\xa4T&\x9a"\xfdB\x86?\xe8\xceO&\xe1m\x96\x7fG\xf9\x1d/9\x178\rJ\x14\xd4\xf2\x8b\xfc\xbdt\xfd\xff\x00!\x02\x00\xfe\xff\x000\x00', 0, 175, 255, 17, 62, 156, 0, -56]
2023-12-04 14:15:35.609 DEBUG (MainThread) [zigpy.application] Received a packet: ZigbeePacket(timestamp=datetime.datetime(2023, 12, 4, 13, 15, 35, 608963, tzinfo=datetime.timezone.utc), src=AddrModeAddress(addr_mode=<AddrMode.NWK: 2>, address=0x4718), src_ep=1, dst=AddrModeAddress(addr_mode=<AddrMode.NWK: 2>, address=0x0000), dst_ep=1, source_route=None, extended_timeout=False, tsn=None, profile_id=260, cluster_id=0, data=Serialized[b'\x18\r\x01\xde\xff\x00 \x0b\xe0\xff\x00H(\xdb\xfb\xa61\xd1\x8c0\xa4T&\x9a"\xfdB\x86?\xe8\xceO&\xe1m\x96\x7fG\xf9\x1d/9\x178\rJ\x14\xd4\xf2\x8b\xfc\xbdt\xfd\xff\x00!\x02\x00\xfe\xff\x000\x00'], tx_options=<TransmitOptions.NONE: 0>, radius=0, non_member_radius=0, lqi=255, rssi=-56)
2023-12-04 14:15:35.610 DEBUG (MainThread) [zigpy.zcl] [0x4718:1:0x0000] Received ZCL frame: b'\x18\r\x01\xde\xff\x00 \x0b\xe0\xff\x00H(\xdb\xfb\xa61\xd1\x8c0\xa4T&\x9a"\xfdB\x86?\xe8\xceO&\xe1m\x96\x7fG\xf9\x1d/9\x178\rJ\x14\xd4\xf2\x8b\xfc\xbdt\xfd\xff\x00!\x02\x00\xfe\xff\x000\x00'
2023-12-04 14:15:35.611 DEBUG (MainThread) [zigpy.zcl] [0x4718:1:0x0000] Decoded ZCL frame header: ZCLHeader(frame_control=FrameControl(frame_type=<FrameType.GLOBAL_COMMAND: 0>, is_manufacturer_specific=0, direction=<Direction.Client_to_Server: 1>, disable_default_response=1, reserved=0, *is_cluster=False, *is_general=True), tsn=13, command_id=1, *direction=<Direction.Client_to_Server: 1>)
2023-12-04 14:15:35.615 DEBUG (MainThread) [zigpy.device] [0x4718] Failed to parse packet ZigbeePacket(timestamp=datetime.datetime(2023, 12, 4, 13, 15, 35, 608963, tzinfo=datetime.timezone.utc), src=AddrModeAddress(addr_mode=<AddrMode.NWK: 2>, address=0x4718), src_ep=1, dst=AddrModeAddress(addr_mode=<AddrMode.NWK: 2>, address=0x0000), dst_ep=1, source_route=None, extended_timeout=False, tsn=None, profile_id=260, cluster_id=0, data=Serialized[b'\x18\r\x01\xde\xff\x00 \x0b\xe0\xff\x00H(\xdb\xfb\xa61\xd1\x8c0\xa4T&\x9a"\xfdB\x86?\xe8\xceO&\xe1m\x96\x7fG\xf9\x1d/9\x178\rJ\x14\xd4\xf2\x8b\xfc\xbdt\xfd\xff\x00!\x02\x00\xfe\xff\x000\x00'], tx_options=<TransmitOptions.NONE: 0>, radius=0, non_member_radius=0, lqi=255, rssi=-56)
Traceback (most recent call last):
  File "/usr/local/lib/python3.11/site-packages/zigpy/device.py", line 413, in packet_received
    hdr, args = endpoint.deserialize(packet.cluster_id, data)
                ^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^
  File "/usr/local/lib/python3.11/site-packages/zigpy/endpoint.py", line 215, in deserialize
    return cluster.deserialize(data)
           ^^^^^^^^^^^^^^^^^^^^^^^^^
  File "/usr/local/lib/python3.11/site-packages/zigpy/zcl/__init__.py", line 288, in deserialize
    response, data = command.schema.deserialize(data)
                     ^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^
  File "/usr/local/lib/python3.11/site-packages/zigpy/types/struct.py", line 302, in deserialize
    value, data = field.type.deserialize(data)
                  ^^^^^^^^^^^^^^^^^^^^^^^^^^^^
  File "/usr/local/lib/python3.11/site-packages/zigpy/types/basic.py", line 870, in deserialize
    item, data = cls._item_type.deserialize(data)
                 ^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^
  File "/usr/local/lib/python3.11/site-packages/zigpy/types/struct.py", line 302, in deserialize
    value, data = field.type.deserialize(data)
                  ^^^^^^^^^^^^^^^^^^^^^^^^^^^^
  File "/usr/local/lib/python3.11/site-packages/zigpy/zcl/foundation.py", line 108, in deserialize
    value, data = python_type.deserialize(data)
                  ^^^^^^^^^^^^^^^^^^^^^^^^^^^^^
  File "/usr/local/lib/python3.11/site-packages/zigpy/zcl/foundation.py", line 125, in deserialize
    values, data = t.LVList[python_type, t.uint16_t].deserialize(data)
                   ^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^
  File "/usr/local/lib/python3.11/site-packages/zigpy/types/basic.py", line 894, in deserialize
    item, data = cls._item_type.deserialize(data)
                 ^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^
  File "/usr/local/lib/python3.11/site-packages/zigpy/types/basic.py", line 193, in deserialize
    raise ValueError(f"Data is too short to contain {byte_size} bytes")
ValueError: Data is too short to contain 1 bytes

The above exception was the direct cause of the following exception:

zigpy.exceptions.ParsingError
2023-12-04 14:15:35.623 DEBUG (MainThread) [zigpy_deconz.api] 'aps_data_indication' response from <DeconzAddress address_mode=AddressMode.NWK address=0x4718>, ep: 1, profile: 0x0104, cluster_id: 0x0000, data: b'180d01deff00200be0ff004828dbfba631d18c30a454269a22fd42863fe8ce4f26e16d967f47f91d2f3917380d4a14d4f28bfcbd74fdff00210200feff003000'
2023-12-04 14:15:35.624 ERROR (MainThread) [custom_components.zha_toolkit] Exception '' for service call with data '{'zha_toolkit_version': 'v1.1.7', 'zigpy_version': '0.59.0', 'zigpy_rf_version': '0.21.1', 'ieee_org': 8c:f6:81:ff:fe:08:ed:fd, 'ieee': '8c:f6:81:ff:fe:08:ed:fd', 'command': 'scan_device', 'command_data': None, 'start_time': '2023-12-04T13:15:13.433358+00:00', 'errors': ['ParsingError()'], 'params': {'dir': 0, 'tries': 1, 'expect_reply': True, 'args': [], 'read_before_write': True, 'read_after_write': True}, 'success': False}'

Is this enough log?

It works with my Philips Hue light, but with another device, I get this:

2023-12-04 16:07:05.093 ERROR (MainThread) [custom_components.zha_toolkit.scan_device] Failed 'discover_attributes_extended' starting 0x0003/0x0000. Error:
mdeweerd commented 7 months ago

This is an issue in zigpy.

Reading arrays was resolved, but seems to give issues again. See https://github.com/zigpy/zigpy/issues/1292 .

What I can do is try (harder) to ignore errors while scanning.

mdeweerd commented 7 months ago

I made a release that should catch more errors and skip them. You can just update zha-toolkit - no need to reload home-assistant for this change.

mdeweerd commented 7 months ago

Closing - supposedly fixed.