Exception when adding device using Home Assistant ZHA.

[hbjorgo]

I get an exception when adding a Zigbee device to my network. When discovering the new device, it reaches the "Configuring" state in Home Assistant, but then it just hangs. The network already has multiple other devices that work fine. I try to add a Frient SMSZB-120, HW: 5.2.0 Smoke Alarm. As far as I can see, it is a Develco device. I'm running Home Assistant 2025.3.1 with the latest ZHA integration and Home Assistant Connect ZBT-1 Zigbee dongle.

Logger: bellows.ezsp
Source: /usr/local/lib/python3.13/site-packages/bellows/ezsp/__init__.py:533
First occurred: 3:12:16 PM (6 occurrences)
Last logged: 3:25:41 PM

Exception running handler
Traceback (most recent call last):
  File "/usr/local/lib/python3.13/site-packages/bellows/ezsp/__init__.py", line 531, in handle_callback
    handler(*args)
    ~~~~~~~^^^^^^^
  File "/usr/local/lib/python3.13/site-packages/bellows/zigbee/application.py", line 493, in ezsp_callback_handler
    self._handle_frame(
    ~~~~~~~~~~~~~~~~~~^
        message_type=message_type,
        ^^^^^^^^^^^^^^^^^^^^^^^^^^
    ...<6 lines>...
        message=message,
        ^^^^^^^^^^^^^^^^
    )
    ^
  File "/usr/local/lib/python3.13/site-packages/bellows/zigbee/application.py", line 574, in _handle_frame
    self.packet_received(
    ~~~~~~~~~~~~~~~~~~~~^
        zigpy.types.ZigbeePacket(
        ^^^^^^^^^^^^^^^^^^^^^^^^^
    ...<13 lines>...
        )
        ^
    )
    ^
  File "/usr/local/lib/python3.13/site-packages/zigpy/application.py", line 1031, in packet_received
    return device.packet_received(packet)
           ~~~~~~~~~~~~~~~~~~~~~~^^^^^^^^
  File "/usr/local/lib/python3.13/site-packages/zigpy/device.py", line 476, in packet_received
    hdr, _ = foundation.ZCLHeader.deserialize(data)
             ~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~^^^^^^
  File "/usr/local/lib/python3.13/site-packages/zigpy/types/struct.py", line 319, in deserialize
    value, data = field_type.deserialize(data)
                  ~~~~~~~~~~~~~~~~~~~~~~^^^^^^
  File "/usr/local/lib/python3.13/site-packages/zigpy/types/basic.py", line 199, in deserialize
    raise ValueError(f"Data is too short to contain {byte_size} bytes")
ValueError: Data is too short to contain 1 bytes

And this one:

Logger: homeassistant
Source: /usr/src/homeassistant/homeassistant/runner.py:112
First occurred: 3:23:01 PM (1 occurrences)
Last logged: 3:23:01 PM

Error doing job: Task exception was never retrieved (None)
Traceback (most recent call last):
  File "/usr/local/lib/python3.13/site-packages/zigpy/device.py", line 381, in request
    return await req.result
           ^^^^^^^^^^^^^^^^
asyncio.exceptions.CancelledError

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

Traceback (most recent call last):
  File "/usr/local/lib/python3.13/site-packages/zha/zigbee/cluster_handlers/__init__.py", line 68, in wrap_zigpy_exceptions
    yield
  File "/usr/local/lib/python3.13/site-packages/zha/zigbee/cluster_handlers/__init__.py", line 86, in wrapper
    return await RETRYABLE_REQUEST_DECORATOR(func)(*args, **kwargs)
           ^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^
  File "/usr/local/lib/python3.13/site-packages/zigpy/util.py", line 136, in retry
    return await func()
           ^^^^^^^^^^^^
  File "/usr/local/lib/python3.13/site-packages/zigpy/zcl/__init__.py", line 378, in request
    return await self._endpoint.request(
           ^^^^^^^^^^^^^^^^^^^^^^^^^^^^^
    ...<9 lines>...
    )
    ^
  File "/usr/local/lib/python3.13/site-packages/zigpy/endpoint.py", line 270, in request
    return await self.device.request(
           ^^^^^^^^^^^^^^^^^^^^^^^^^^
    ...<11 lines>...
    )
    ^
  File "/usr/local/lib/python3.13/site-packages/zigpy/device.py", line 380, in request
    async with asyncio_timeout(timeout):
               ~~~~~~~~~~~~~~~^^^^^^^^^
  File "/usr/local/lib/python3.13/asyncio/timeouts.py", line 116, in __aexit__
    raise TimeoutError from exc_val
TimeoutError

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

Traceback (most recent call last):
  File "/usr/local/lib/python3.13/site-packages/zha/application/gateway.py", line 600, in async_device_initialized
    await self._async_device_joined(zha_device)
  File "/usr/local/lib/python3.13/site-packages/zha/application/gateway.py", line 615, in _async_device_joined
    await zha_device.async_configure()
  File "/usr/local/lib/python3.13/site-packages/zha/zigbee/device.py", line 771, in async_configure
    await self.identify_ch.trigger_effect(
    ...<2 lines>...
    )
  File "/usr/local/lib/python3.13/site-packages/zha/zigbee/cluster_handlers/__init__.py", line 85, in wrapper
    with wrap_zigpy_exceptions():
         ~~~~~~~~~~~~~~~~~~~~~^^
  File "/usr/local/lib/python3.13/contextlib.py", line 162, in __exit__
    self.gen.throw(value)
    ~~~~~~~~~~~~~~^^^^^^^
  File "/usr/local/lib/python3.13/site-packages/zha/zigbee/cluster_handlers/__init__.py", line 70, in wrap_zigpy_exceptions
    raise ZHAException("Failed to send request: device did not respond") from exc
zha.exceptions.ZHAException: Failed to send request: device did not respond

Some logs:

2025-03-10 15:25:41.229 DEBUG (MainThread) [bellows.zigbee.application] Processing route record request: (0x341A, 00:15:bc:00:31:02:c5:40, 168, -58, [0x8A7C])
2025-03-10 15:25:41.232 DEBUG (Thread-3) [aiosqlite] executing functools.partial(<built-in method commit of sqlite3.Connection object at 0x7ff0576dcd60>)
2025-03-10 15:25:41.233 DEBUG (Thread-3) [aiosqlite] operation functools.partial(<built-in method commit of sqlite3.Connection object at 0x7ff0576dcd60>) completed
2025-03-10 15:25:41.236 DEBUG (Thread-3) [aiosqlite] executing functools.partial(<built-in method execute of sqlite3.Connection object at 0x7ff0576dcd60>, 'INSERT INTO relays_v13 VALUES (:ieee, :relays)\n                        ON CONFLICT (ieee)\n                        DO UPDATE SET relays=excluded.relays WHERE relays != :relays', {'ieee': 00:15:bc:00:31:02:c5:40, 'relays': b'\x01|\x8a'})
2025-03-10 15:25:41.242 DEBUG (Thread-3) [aiosqlite] operation functools.partial(<built-in method execute of sqlite3.Connection object at 0x7ff0576dcd60>, 'INSERT INTO relays_v13 VALUES (:ieee, :relays)\n                        ON CONFLICT (ieee)\n                        DO UPDATE SET relays=excluded.relays WHERE relays != :relays', {'ieee': 00:15:bc:00:31:02:c5:40, 'relays': b'\x01|\x8a'}) completed
2025-03-10 15:25:41.244 DEBUG (Thread-3) [aiosqlite] executing functools.partial(<built-in method commit of sqlite3.Connection object at 0x7ff0576dcd60>)
2025-03-10 15:25:41.245 DEBUG (Thread-3) [aiosqlite] operation functools.partial(<built-in method commit of sqlite3.Connection object at 0x7ff0576dcd60>) completed
2025-03-10 15:25:41.247 DEBUG (Thread-3) [aiosqlite] executing functools.partial(<built-in method execute of sqlite3.Connection object at 0x7ff0576dcd60>, 'INSERT INTO relays_v13 VALUES (:ieee, :relays)\n                        ON CONFLICT (ieee)\n                        DO UPDATE SET relays=excluded.relays WHERE relays != :relays', {'ieee': 00:15:bc:00:31:02:c5:40, 'relays': b'\x01|\x8a'})
2025-03-10 15:25:41.248 DEBUG (Thread-3) [aiosqlite] operation functools.partial(<built-in method execute of sqlite3.Connection object at 0x7ff0576dcd60>, 'INSERT INTO relays_v13 VALUES (:ieee, :relays)\n                        ON CONFLICT (ieee)\n                        DO UPDATE SET relays=excluded.relays WHERE relays != :relays', {'ieee': 00:15:bc:00:31:02:c5:40, 'relays': b'\x01|\x8a'}) completed
2025-03-10 15:25:41.250 DEBUG (Thread-3) [aiosqlite] executing functools.partial(<built-in method commit of sqlite3.Connection object at 0x7ff0576dcd60>)
2025-03-10 15:25:41.251 DEBUG (Thread-3) [aiosqlite] operation functools.partial(<built-in method commit of sqlite3.Connection object at 0x7ff0576dcd60>) completed
2025-03-10 15:25:41.253 DEBUG (Thread-3) [aiosqlite] executing functools.partial(<built-in method execute of sqlite3.Connection object at 0x7ff0576dcd60>, 'INSERT INTO relays_v13 VALUES (:ieee, :relays)\n                        ON CONFLICT (ieee)\n                        DO UPDATE SET relays=excluded.relays WHERE relays != :relays', {'ieee': 00:15:bc:00:31:02:c5:40, 'relays': b'\x01|\x8a'})
2025-03-10 15:25:41.255 DEBUG (Thread-3) [aiosqlite] operation functools.partial(<built-in method execute of sqlite3.Connection object at 0x7ff0576dcd60>, 'INSERT INTO relays_v13 VALUES (:ieee, :relays)\n                        ON CONFLICT (ieee)\n                        DO UPDATE SET relays=excluded.relays WHERE relays != :relays', {'ieee': 00:15:bc:00:31:02:c5:40, 'relays': b'\x01|\x8a'}) completed
2025-03-10 15:25:41.257 DEBUG (Thread-3) [aiosqlite] executing functools.partial(<built-in method commit of sqlite3.Connection object at 0x7ff0576dcd60>)
2025-03-10 15:25:41.258 DEBUG (Thread-3) [aiosqlite] operation functools.partial(<built-in method commit of sqlite3.Connection object at 0x7ff0576dcd60>) completed
2025-03-10 15:25:41.274 DEBUG (bellows.thread_0) [bellows.ash] Received data 0767b1a96b2a15a86d5d8a26aa5493099d4e27d625ce670cc07e
2025-03-10 15:25:41.275 DEBUG (bellows.thread_0) [bellows.ash] Received frame DataFrame(frm_num=0, re_tx=0, ack_num=7, ezsp_frame=b'%\x90\x01?\x00\x00\x1a4\xc9\xc0\x03\x00\x01\x01@\x01\x00\x00}\xc8\x00\x00')
2025-03-10 15:25:41.275 DEBUG (bellows.thread_0) [bellows.ash] Sending frame AckFrame(res=0, ncp_ready=0, ack_num=1) + FLAG
2025-03-10 15:25:41.276 DEBUG (bellows.thread_0) [bellows.ash] Sending data  8160597e
2025-03-10 15:25:41.281 DEBUG (MainThread) [bellows.ezsp.protocol] Received command messageSentHandler: {'type': <EmberOutgoingMessageType.OUTGOING_DIRECT: 0>, 'indexOrDestination': 13338, 'apsFrame': EmberApsFrame(profileId=49353, clusterId=3, sourceEndpoint=1, destinationEndpoint=1, options=<EmberApsOption.APS_OPTION_RETRY|APS_OPTION_ENABLE_ROUTE_DISCOVERY: 320>, groupId=0, sequence=125), 'messageTag': 200, 'status': <EmberStatus.SUCCESS: 0>, 'messageContents': b''}
2025-03-10 15:25:41.281 DEBUG (MainThread) [bellows.zigbee.application] Received messageSentHandler frame with [<EmberOutgoingMessageType.OUTGOING_DIRECT: 0>, 13338, EmberApsFrame(profileId=49353, clusterId=3, sourceEndpoint=1, destinationEndpoint=1, options=<EmberApsOption.APS_OPTION_RETRY|APS_OPTION_ENABLE_ROUTE_DISCOVERY: 320>, groupId=0, sequence=125), 200, <EmberStatus.SUCCESS: 0>, b'']
2025-03-10 15:25:41.284 DEBUG (bellows.thread_0) [bellows.ash] Received data 1767b1a97d312a157b99974a24ab5593499c178f6df7fa9886ffc7818d93b07e
2025-03-10 15:25:41.285 DEBUG (bellows.thread_0) [bellows.ash] Received frame DataFrame(frm_num=1, re_tx=0, ack_num=7, ezsp_frame=b'%\x90\x01E\x00\x00\xc9\xc0\x03\x00\x01\x01\x00\x01\x00\x00Y\xa8\xc6\x1a4\xff\r\x02\x01\xe2\x04')
2025-03-10 15:25:41.285 DEBUG (bellows.thread_0) [bellows.ash] Sending frame AckFrame(res=0, ncp_ready=0, ack_num=2) + FLAG
2025-03-10 15:25:41.286 DEBUG (bellows.thread_0) [bellows.ash] Sending data  82503a7e
2025-03-10 15:25:41.289 DEBUG (MainThread) [bellows.ezsp.protocol] Received command incomingMessageHandler: {'type': <EmberIncomingMessageType.INCOMING_UNICAST: 0>, 'apsFrame': EmberApsFrame(profileId=49353, clusterId=3, sourceEndpoint=1, destinationEndpoint=1, options=<EmberApsOption.APS_OPTION_ENABLE_ROUTE_DISCOVERY: 256>, groupId=0, sequence=89), 'lastHopLqi': 168, 'lastHopRssi': -58, 'sender': 0x341A, 'bindingIndex': 255, 'addressIndex': 13, 'messageContents': b'\x01\xe2'}
2025-03-10 15:25:41.290 DEBUG (MainThread) [bellows.ezsp.protocol] Frame contains trailing data: b'\x04'
2025-03-10 15:25:41.290 DEBUG (MainThread) [bellows.zigbee.application] Received incomingMessageHandler frame with [<EmberIncomingMessageType.INCOMING_UNICAST: 0>, EmberApsFrame(profileId=49353, clusterId=3, sourceEndpoint=1, destinationEndpoint=1, options=<EmberApsOption.APS_OPTION_ENABLE_ROUTE_DISCOVERY: 256>, groupId=0, sequence=89), 168, -58, 0x341A, 255, 13, b'\x01\xe2']
2025-03-10 15:25:41.291 DEBUG (MainThread) [zigpy.application] Received a packet: ZigbeePacket(timestamp=datetime.datetime(2025, 3, 10, 14, 25, 41, 291484, tzinfo=datetime.timezone.utc), priority=0, src=AddrModeAddress(addr_mode=<AddrMode.NWK: 2>, address=0x341A), src_ep=1, dst=AddrModeAddress(addr_mode=<AddrMode.NWK: 2>, address=0x0000), dst_ep=1, source_route=None, extended_timeout=False, tsn=89, profile_id=49353, cluster_id=3, data=Serialized[b'\x01\xe2'], tx_options=<TransmitOptions.NONE: 0>, radius=0, non_member_radius=0, lqi=168, rssi=-58)
2025-03-10 15:25:41.293 ERROR (MainThread) [bellows.ezsp] Exception running handler
Traceback (most recent call last):
  File "/usr/local/lib/python3.13/site-packages/bellows/ezsp/__init__.py", line 531, in handle_callback
    handler(*args)
    ~~~~~~~^^^^^^^
  File "/usr/local/lib/python3.13/site-packages/bellows/zigbee/application.py", line 493, in ezsp_callback_handler
    self._handle_frame(
    ~~~~~~~~~~~~~~~~~~^
        message_type=message_type,
        ^^^^^^^^^^^^^^^^^^^^^^^^^^
    ...<6 lines>...
        message=message,
        ^^^^^^^^^^^^^^^^
    )
    ^
  File "/usr/local/lib/python3.13/site-packages/bellows/zigbee/application.py", line 574, in _handle_frame
    self.packet_received(
    ~~~~~~~~~~~~~~~~~~~~^
        zigpy.types.ZigbeePacket(
        ^^^^^^^^^^^^^^^^^^^^^^^^^
    ...<13 lines>...
        )
        ^
    )
    ^
  File "/usr/local/lib/python3.13/site-packages/zigpy/application.py", line 1031, in packet_received
    return device.packet_received(packet)
           ~~~~~~~~~~~~~~~~~~~~~~^^^^^^^^
  File "/usr/local/lib/python3.13/site-packages/zigpy/device.py", line 476, in packet_received
    hdr, _ = foundation.ZCLHeader.deserialize(data)
             ~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~^^^^^^
  File "/usr/local/lib/python3.13/site-packages/zigpy/types/struct.py", line 319, in deserialize
    value, data = field_type.deserialize(data)
                  ~~~~~~~~~~~~~~~~~~~~~~^^^^^^
  File "/usr/local/lib/python3.13/site-packages/zigpy/types/basic.py", line 199, in deserialize
    raise ValueError(f"Data is too short to contain {byte_size} bytes")
ValueError: Data is too short to contain 1 bytes
2025-03-10 15:25:41.310 DEBUG (Thread-3) [aiosqlite] executing functools.partial(<built-in method execute of sqlite3.Connection object at 0x7ff0576dcd60>, 'UPDATE devices_v13\n                    SET last_seen=:ts\n                    WHERE ieee=:ieee AND :ts - last_seen > :min_update_delta', {'ts': 1741616741.291484, 'ieee': 00:15:bc:00:31:02:c5:40, 'min_update_delta': 30.0})
2025-03-10 15:25:41.311 DEBUG (Thread-3) [aiosqlite] operation functools.partial(<built-in method execute of sqlite3.Connection object at 0x7ff0576dcd60>, 'UPDATE devices_v13\n                    SET last_seen=:ts\n                    WHERE ieee=:ieee AND :ts - last_seen > :min_update_delta', {'ts': 1741616741.291484, 'ieee': 00:15:bc:00:31:02:c5:40, 'min_update_delta': 30.0}) completed
2025-03-10 15:25:41.315 DEBUG (Thread-3) [aiosqlite] executing functools.partial(<built-in method commit of sqlite3.Connection object at 0x7ff0576dcd60>)
2025-03-10 15:25:41.316 DEBUG (Thread-3) [aiosqlite] operation functools.partial(<built-in method commit of sqlite3.Connection object at 0x7ff0576dcd60>) completed
2025-03-10 15:25:41.318 DEBUG (Thread-3) [aiosqlite] executing functools.partial(<built-in method execute of sqlite3.Connection object at 0x7ff0576dcd60>, 'UPDATE devices_v13\n                    SET last_seen=:ts\n                    WHERE ieee=:ieee AND :ts - last_seen > :min_update_delta', {'ts': 1741616741.291484, 'ieee': 00:15:bc:00:31:02:c5:40, 'min_update_delta': 30.0})
2025-03-10 15:25:41.319 DEBUG (Thread-3) [aiosqlite] operation functools.partial(<built-in method execute of sqlite3.Connection object at 0x7ff0576dcd60>, 'UPDATE devices_v13\n                    SET last_seen=:ts\n                    WHERE ieee=:ieee AND :ts - last_seen > :min_update_delta', {'ts': 1741616741.291484, 'ieee': 00:15:bc:00:31:02:c5:40, 'min_update_delta': 30.0}) completed
2025-03-10 15:25:41.321 DEBUG (Thread-3) [aiosqlite] executing functools.partial(<built-in method commit of sqlite3.Connection object at 0x7ff0576dcd60>)
2025-03-10 15:25:41.323 DEBUG (Thread-3) [aiosqlite] operation functools.partial(<built-in method commit of sqlite3.Connection object at 0x7ff0576dcd60>) completed

[puddly]

Can you record a debug log of the whole joining process?

[hbjorgo]

Here you are:
home-assistant_zha_2025-03-10T16-23-18.517Z.log

[Hedda]

@hbjorgo is it still the same problem or can this issue be closed? I have seen/heard such symtoms when got interference problems

• https://www.home-assistant.io/integrations/zha#zigbee-interference-avoidance-and-network-rangecoverage-optimization

  • https://www.home-assistant.io/integrations/zha#best-practices-to-avoid-pairingconnection-difficulties

FYI, the frient Intelligent Smoke Alarm (Model number: SMSZB-120) has is now a certified device in Home Assistant's Works With
Home Assistant partnership program, but there looks to be one open issue, however it sounds as if that is unrelated:

• https://www.home-assistant.io/blog/2025/09/02/frient-joins-works-with-home-assistant

  • https://community.home-assistant.io/t/frient-joins-works-with-home-assistant/926758/

    • Zigbee Frient smoke detector integration is incomplete home-assistant/core#151967

      • [Device Support Request] frient A/S SMSZB-120 smoke detector zha-device-handlers#4336

PS: Regardless, recommend try following these best-practice Zigbee network optimization tips to get a more stable Zigbee network:

• https://community.home-assistant.io/t/zigbee-network-optimization-a-how-to-guide-for-avoiding-radio-frequency-interference-adding-zigbee-router-devices-repeaters-extenders-to-get-a-stable-zigbee-network-mesh-with-best-possible-range-and-coverage-by-fully-utilizing-zigbee-mesh-networking/515752