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.57k stars 30.74k forks source link

Zigbee ZHA locks up and problems controlling #112843

Closed bymem closed 7 months ago

bymem commented 8 months ago

The problem

Af the update 2024.4 the zigbee/ZHA/Skyconnect 1.0 network have "locked" up several times, with the problem of not being able to control anything. Only a restart of HA got the integration running again.

Tonight the whole network seems to have problems, with problem sending command with 10-20 seconds with commands being sent, or not at all. With HA displaying errors.

several errors seems to present in the logs.

What version of Home Assistant Core has the issue?

core-2024.3.0

What was the last working version of Home Assistant Core?

core-2024.2.4

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

home-assistant_zha_2024-03-09T20-55-27.032Z.log

Example YAML snippet

No response

Anything in the logs that might be useful for us?

Logger: homeassistant.components.websocket_api.http.connection
Source: components/websocket_api/commands.py:239
integration: Home Assistant WebSocket API (documentation, issues)
First occurred: 21:43:39 (1 occurrences)
Last logged: 21:43:39

[140090215724224] Failed to send request: Failed to deliver message: <EmberStatus.DELIVERY_FAILED: 102>
Traceback (most recent call last):
  File "/usr/src/homeassistant/homeassistant/components/zha/core/cluster_handlers/__init__.py", line 63, in wrap_zigpy_exceptions
    yield
  File "/usr/src/homeassistant/homeassistant/components/zha/core/cluster_handlers/__init__.py", line 83, in wrapper
    return await RETRYABLE_REQUEST_DECORATOR(func)(*args, **kwargs)
           ^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^
  File "/usr/local/lib/python3.12/site-packages/zigpy/util.py", line 131, in retry
    return await func()
           ^^^^^^^^^^^^
  File "/usr/local/lib/python3.12/site-packages/zigpy/zcl/__init__.py", line 377, in request
    return await self._endpoint.request(
           ^^^^^^^^^^^^^^^^^^^^^^^^^^^^^
  File "/usr/local/lib/python3.12/site-packages/zigpy/endpoint.py", line 253, in request
    return await self.device.request(
           ^^^^^^^^^^^^^^^^^^^^^^^^^^
  File "/usr/local/lib/python3.12/site-packages/zigpy/device.py", line 339, in request
    await send_request()
  File "/usr/local/lib/python3.12/site-packages/zigpy/application.py", line 841, in request
    await self.send_packet(
  File "/usr/local/lib/python3.12/site-packages/bellows/zigbee/application.py", line 931, in send_packet
    raise zigpy.exceptions.DeliveryError(
zigpy.exceptions.DeliveryError: Failed to deliver message: <EmberStatus.DELIVERY_FAILED: 102>

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

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/light/__init__.py", line 628, in async_handle_light_on_service
    await light.async_turn_on(**filter_turn_on_params(light, params))
  File "/usr/src/homeassistant/homeassistant/components/zha/light.py", line 360, in async_turn_on
    result = await self._on_off_cluster_handler.on()
             ^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^
  File "/usr/src/homeassistant/homeassistant/components/zha/core/cluster_handlers/__init__.py", line 82, in wrapper
    with wrap_zigpy_exceptions():
  File "/usr/local/lib/python3.12/contextlib.py", line 158, in __exit__
    self.gen.throw(value)
  File "/usr/src/homeassistant/homeassistant/components/zha/core/cluster_handlers/__init__.py", line 74, in wrap_zigpy_exceptions
    raise HomeAssistantError(message) from exc
homeassistant.exceptions.HomeAssistantError: Failed to send request: Failed to deliver message: <EmberStatus.DELIVERY_FAILED: 102>

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)

puddly commented 8 months ago

According to your log, you have severe RF interference issues:

MAC_TX_UNICAST_SUCCESS = 943
MAC_TX_UNICAST_RETRY = 4294
MAC_TX_UNICAST_FAILED = 1634
PHY_CCA_FAIL_COUNT = 2784

The radio is unable to transmit packets because there is too much 2.4GHz interference.Is your SkyConnect near any USB 3.0 ports, SSDs, 2.4GHz routers, etc.?

bymem commented 8 months ago

It's on a extension cord taking it away from the main machine, but it is sitting in a area with the Tado gateway, behind a surround sound system, in like a "media" console (see attached image). But it's been sitting in that location in a year now. And never this mainy problem it before this update.

I now moved it away and set up on my desk as a test (See attached image). Still having problems.

Logger: homeassistant.components.websocket_api.http.connection
Source: components/websocket_api/commands.py:239
integration: Home Assistant WebSocket API (documentation, issues)
First occurred: 11:07:49 (1 occurrences)
Last logged: 11:07:49

[140387678314432] Failed to send request: Failed to deliver message: <EmberStatus.DELIVERY_FAILED: 102>
Traceback (most recent call last):
  File "/usr/src/homeassistant/homeassistant/components/zha/core/cluster_handlers/__init__.py", line 63, in wrap_zigpy_exceptions
    yield
  File "/usr/src/homeassistant/homeassistant/components/zha/core/cluster_handlers/__init__.py", line 83, in wrapper
    return await RETRYABLE_REQUEST_DECORATOR(func)(*args, **kwargs)
           ^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^
  File "/usr/local/lib/python3.12/site-packages/zigpy/util.py", line 131, in retry
    return await func()
           ^^^^^^^^^^^^
  File "/usr/local/lib/python3.12/site-packages/zigpy/zcl/__init__.py", line 377, in request
    return await self._endpoint.request(
           ^^^^^^^^^^^^^^^^^^^^^^^^^^^^^
  File "/usr/local/lib/python3.12/site-packages/zigpy/endpoint.py", line 253, in request
    return await self.device.request(
           ^^^^^^^^^^^^^^^^^^^^^^^^^^
  File "/usr/local/lib/python3.12/site-packages/zigpy/device.py", line 339, in request
    await send_request()
  File "/usr/local/lib/python3.12/site-packages/zigpy/application.py", line 841, in request
    await self.send_packet(
  File "/usr/local/lib/python3.12/site-packages/bellows/zigbee/application.py", line 931, in send_packet
    raise zigpy.exceptions.DeliveryError(
zigpy.exceptions.DeliveryError: Failed to deliver message: <EmberStatus.DELIVERY_FAILED: 102>

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

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/light/__init__.py", line 628, in async_handle_light_on_service
    await light.async_turn_on(**filter_turn_on_params(light, params))
  File "/usr/src/homeassistant/homeassistant/components/zha/light.py", line 360, in async_turn_on
    result = await self._on_off_cluster_handler.on()
             ^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^
  File "/usr/src/homeassistant/homeassistant/components/zha/core/cluster_handlers/__init__.py", line 82, in wrapper
    with wrap_zigpy_exceptions():
  File "/usr/local/lib/python3.12/contextlib.py", line 158, in __exit__
    self.gen.throw(value)
  File "/usr/src/homeassistant/homeassistant/components/zha/core/cluster_handlers/__init__.py", line 74, in wrap_zigpy_exceptions
    raise HomeAssistantError(message) from exc
homeassistant.exceptions.HomeAssistantError: Failed to send request: Failed to deliver message: <EmberStatus.DELIVERY_FAILED: 102>

home-assistant_zha_2024-03-10T10-14-57.424Z.log

IMG_5106

IMG_5107

bymem commented 8 months ago

Still having massive issues, where the system seems to be getting worse when it's been on for prolonged period. It had an okay period here with the move, but it seems like it degrades over time.

Logger: homeassistant.components.websocket_api.http.connection
Source: components/websocket_api/commands.py:239
integration: Home Assistant WebSocket API (documentation, issues)
First occurred: 18:05:36 (1 occurrences)
Last logged: 18:05:36

[139728937766848] Failed to send request: device did not respond
Traceback (most recent call last):
  File "/usr/local/lib/python3.12/site-packages/zigpy/device.py", line 342, 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/src/homeassistant/homeassistant/components/zha/core/cluster_handlers/__init__.py", line 63, in wrap_zigpy_exceptions
    yield
  File "/usr/src/homeassistant/homeassistant/components/zha/core/cluster_handlers/__init__.py", line 83, in wrapper
    return await RETRYABLE_REQUEST_DECORATOR(func)(*args, **kwargs)
           ^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^
  File "/usr/local/lib/python3.12/site-packages/zigpy/util.py", line 131, in retry
    return await func()
           ^^^^^^^^^^^^
  File "/usr/local/lib/python3.12/site-packages/zigpy/zcl/__init__.py", line 377, in request
    return await self._endpoint.request(
           ^^^^^^^^^^^^^^^^^^^^^^^^^^^^^
  File "/usr/local/lib/python3.12/site-packages/zigpy/endpoint.py", line 253, in request
    return await self.device.request(
           ^^^^^^^^^^^^^^^^^^^^^^^^^^
  File "/usr/local/lib/python3.12/site-packages/zigpy/device.py", line 341, in request
    async with asyncio_timeout(timeout):
  File "/usr/local/lib/python3.12/asyncio/timeouts.py", line 115, 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/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/scene/__init__.py", line 114, in _async_activate
    await self.async_activate(**kwargs)
  File "/usr/src/homeassistant/homeassistant/components/homeassistant/scene.py", line 371, in async_activate
    await async_reproduce_state(
  File "/usr/src/homeassistant/homeassistant/helpers/state.py", line 67, in async_reproduce_state
    await asyncio.gather(
  File "/usr/src/homeassistant/homeassistant/helpers/state.py", line 61, in worker
    await platform.async_reproduce_states(
  File "/usr/src/homeassistant/homeassistant/components/light/reproduce_state.py", line 158, in async_reproduce_states
    await asyncio.gather(
  File "/usr/src/homeassistant/homeassistant/components/light/reproduce_state.py", line 145, in _async_reproduce_state
    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/light/__init__.py", line 628, in async_handle_light_on_service
    await light.async_turn_on(**filter_turn_on_params(light, params))
  File "/usr/src/homeassistant/homeassistant/components/zha/light.py", line 336, in async_turn_on
    result = await self._level_cluster_handler.move_to_level_with_on_off(
             ^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^
  File "/usr/src/homeassistant/homeassistant/components/zha/core/cluster_handlers/__init__.py", line 82, in wrapper
    with wrap_zigpy_exceptions():
  File "/usr/local/lib/python3.12/contextlib.py", line 158, in __exit__
    self.gen.throw(value)
  File "/usr/src/homeassistant/homeassistant/components/zha/core/cluster_handlers/__init__.py", line 65, in wrap_zigpy_exceptions
    raise HomeAssistantError(
homeassistant.exceptions.HomeAssistantError: Failed to send request: device did not respond
bymem commented 8 months ago

After rolling back tp 2024.2.2 Zigbee has become more stable.

mikeymop commented 8 months ago

I don't recall the issue thread but I read in another issue that heavy interference could cause the ZHA integration to throw.

My yellow is near both a router and wifi printer. The printer uses 2.4ghz.

I instead switched the printer to Ethernet and things have been stable so far 🤞

bymem commented 8 months ago

So after many hours of work I'm really just back at square one.

I toke the decision reinstall the whole system, it was running on a Mac mini in vituralbox, and I decided reinstall the whole machine and install the hassOS directly onto the machine. Install the newest version os ha 2024.03 and after getting all my zigbee devices into the system it seemed stable last night. But after the night it's having problems sending commands again.

I would really appreciate some help with this.

Logger: homeassistant.components.websocket_api.http.connection
Source: components/websocket_api/commands.py:239
integration: Home Assistant WebSocket API (documentation, issues)
First occurred: 1:59:57 AM (15 occurrences)
Last logged: 8:21:37 AM

[140653619654720] Failed to send request: Failed to deliver message: <EmberStatus.DELIVERY_FAILED: 102>
[140653425952448] Failed to send request: Failed to deliver message: <EmberStatus.DELIVERY_FAILED: 102>
[140653376739520] Failed to send request: Failed to deliver message: <EmberStatus.DELIVERY_FAILED: 102>
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/components/homeassistant/__init__.py", line 138, in async_handle_turn_service
    await asyncio.gather(*tasks)
  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 930, in entity_service_call
    raise result from None
  File "/usr/src/homeassistant/homeassistant/helpers/entity.py", line 1570, in async_request_call
    return await coro
           ^^^^^^^^^^
  File "/usr/src/homeassistant/homeassistant/helpers/service.py", line 975, in _handle_entity_call
    result = await task
             ^^^^^^^^^^
  File "/usr/src/homeassistant/homeassistant/components/light/__init__.py", line 639, in async_handle_light_off_service
    await light.async_turn_off(**filter_turn_off_params(light, params))
  File "/usr/src/homeassistant/homeassistant/components/zha/light.py", line 471, in async_turn_off
    result = await self._on_off_cluster_handler.off()
             ^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^
  File "/usr/src/homeassistant/homeassistant/components/zha/core/cluster_handlers/__init__.py", line 82, in wrapper
    with wrap_zigpy_exceptions():
  File "/usr/local/lib/python3.12/contextlib.py", line 158, in __exit__
    self.gen.throw(value)
  File "/usr/src/homeassistant/homeassistant/components/zha/core/cluster_handlers/__init__.py", line 74, in wrap_zigpy_exceptions
    raise HomeAssistantError(message) from exc
homeassistant.exceptions.HomeAssistantError: Failed to send request: Failed to deliver message: <EmberStatus.DELIVERY_FAILED: 102>

more from the log

Logger: zigpy.zcl
Source: runner.py:188
First occurred: 9:03:36 AM (1 occurrences)
Last logged: 9:03:36 AM

[0x8D6B:1:0x0020] Traceback (most recent call last): File "/usr/local/lib/python3.12/site-packages/zigpy/endpoint.py", line 253, in request return await self.device.request( ^^^^^^^^^^^^^^^^^^^^^^^^^^ File "/usr/local/lib/python3.12/site-packages/zigpy/device.py", line 339, in request await send_request() File "/usr/local/lib/python3.12/site-packages/zigpy/application.py", line 841, in request await self.send_packet( File "/usr/local/lib/python3.12/site-packages/bellows/zigbee/application.py", line 931, in send_packet raise zigpy.exceptions.DeliveryError( zigpy.exceptions.DeliveryError: Failed to deliver message: <EmberStatus.DELIVERY_FAILED: 102> The above exception was the direct cause of the following exception: Traceback (most recent call last): File "/usr/src/homeassistant/homeassistant/components/zha/core/cluster_handlers/general.py", line 623, in check_in_response await self.checkin_response(True, self.CHECKIN_FAST_POLL_TIMEOUT, tsn=tsn) File "/usr/src/homeassistant/homeassistant/components/zha/core/cluster_handlers/__init__.py", line 82, in wrapper with wrap_zigpy_exceptions(): File "/usr/local/lib/python3.12/contextlib.py", line 158, in __exit__ self.gen.throw(value) File "/usr/src/homeassistant/homeassistant/components/zha/core/cluster_handlers/__init__.py", line 74, in wrap_zigpy_exceptions raise HomeAssistantError(message) from exc homeassistant.exceptions.HomeAssistantError: Failed to send request: Failed to deliver message: <EmberStatus.DELIVERY_FAILED: 102>

And the debug log, after enabling debug logging and trying to controll a "locked" device

2024-03-15 09:13:36.665 WARNING (SyncWorker_1) [homeassistant.loader] We found a custom integration hacs which has not been tested by Home Assistant. This component might cause stability problems, be sure to disable it if you experience issues with Home Assistant
2024-03-15 09:13:43.993 WARNING (MainThread) [homeassistant.helpers.frame] Detected that custom integration 'hacs' accesses hass.components.frontend. This is deprecated and will stop working in Home Assistant 2024.9, it should be updated to import functions used from frontend directly at custom_components/hacs/frontend.py, line 68: hass.components.frontend.async_register_built_in_panel(, please create a bug report at https://github.com/hacs/integration/issues
2024-03-15 09:13:49.468 ERROR (bellows.thread_0) [bellows.uart] CRC error in frame b'9129a355037425ba117d1d2c862601ceee927e' (b'ee92' != b'007f')
2024-03-15 09:20:04.210 WARNING (MainThread) [homeassistant.components.apple_tv] Connection lost to Apple TV "Dagligstue"
2024-03-15 09:20:55.747 WARNING (MainThread) [homeassistant.components.apple_tv] Connection lost to Apple TV "Dagligstue"
2024-03-15 09:21:44.991 WARNING (MainThread) [homeassistant.components.apple_tv] Connection lost to Apple TV "Dagligstue"
2024-03-15 09:21:49.627 ERROR (MainThread) [homeassistant.components.websocket_api.http.connection] [140240833731008] Failed to send request: Failed to deliver message: <EmberStatus.DELIVERY_FAILED: 102>
Traceback (most recent call last):
  File "/usr/src/homeassistant/homeassistant/components/zha/core/cluster_handlers/__init__.py", line 63, in wrap_zigpy_exceptions
    yield
  File "/usr/src/homeassistant/homeassistant/components/zha/core/cluster_handlers/__init__.py", line 83, in wrapper
    return await RETRYABLE_REQUEST_DECORATOR(func)(*args, **kwargs)
           ^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^
  File "/usr/local/lib/python3.12/site-packages/zigpy/util.py", line 131, in retry
    return await func()
           ^^^^^^^^^^^^
  File "/usr/local/lib/python3.12/site-packages/zigpy/zcl/__init__.py", line 377, in request
    return await self._endpoint.request(
           ^^^^^^^^^^^^^^^^^^^^^^^^^^^^^
  File "/usr/local/lib/python3.12/site-packages/zigpy/endpoint.py", line 253, in request
    return await self.device.request(
           ^^^^^^^^^^^^^^^^^^^^^^^^^^
  File "/usr/local/lib/python3.12/site-packages/zigpy/device.py", line 339, in request
    await send_request()
  File "/usr/local/lib/python3.12/site-packages/zigpy/application.py", line 841, in request
    await self.send_packet(
  File "/usr/local/lib/python3.12/site-packages/bellows/zigbee/application.py", line 931, in send_packet
    raise zigpy.exceptions.DeliveryError(
zigpy.exceptions.DeliveryError: Failed to deliver message: <EmberStatus.DELIVERY_FAILED: 102>

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

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/light/__init__.py", line 639, in async_handle_light_off_service
    await light.async_turn_off(**filter_turn_off_params(light, params))
  File "/usr/src/homeassistant/homeassistant/components/zha/light.py", line 471, in async_turn_off
    result = await self._on_off_cluster_handler.off()
             ^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^
  File "/usr/src/homeassistant/homeassistant/components/zha/core/cluster_handlers/__init__.py", line 82, in wrapper
    with wrap_zigpy_exceptions():
  File "/usr/local/lib/python3.12/contextlib.py", line 158, in __exit__
    self.gen.throw(value)
  File "/usr/src/homeassistant/homeassistant/components/zha/core/cluster_handlers/__init__.py", line 74, in wrap_zigpy_exceptions
    raise HomeAssistantError(message) from exc
homeassistant.exceptions.HomeAssistantError: Failed to send request: Failed to deliver message: <EmberStatus.DELIVERY_FAILED: 102>
2024-03-15 09:22:24.967 DEBUG (MainThread) [homeassistant.components.zha.entity] light.livingroom_white_small_pendant_01: polling for updated state
2024-03-15 09:22:24.967 DEBUG (MainThread) [homeassistant.components.zha.entity] light.livingroom_white_small_pendant_01: polling current state
2024-03-15 09:22:24.969 DEBUG (MainThread) [zigpy.zcl] [0x0C24:11:0x0006] Sending request header: ZCLHeader(frame_control=FrameControl<0x00>(frame_type=<FrameType.GLOBAL_COMMAND: 0>, is_manufacturer_specific=False, direction=<Direction.Client_to_Server: 0>, disable_default_response=0, reserved=0, *is_cluster=False, *is_general=True), tsn=6, command_id=<GeneralCommand.Read_Attributes: 0>, *direction=<Direction.Client_to_Server: 0>)
2024-03-15 09:22:24.970 DEBUG (MainThread) [zigpy.zcl] [0x0C24:11:0x0006] Sending request: Read_Attributes(attribute_ids=[0])
2024-03-15 09:22:24.971 DEBUG (MainThread) [bellows.zigbee.application] Sending packet ZigbeePacket(timestamp=datetime.datetime(2024, 3, 15, 8, 22, 24, 971018, tzinfo=datetime.timezone.utc), src=AddrModeAddress(addr_mode=<AddrMode.NWK: 2>, address=0x0000), src_ep=11, dst=AddrModeAddress(addr_mode=<AddrMode.NWK: 2>, address=0x0C24), dst_ep=11, source_route=None, extended_timeout=False, tsn=6, profile_id=260, cluster_id=6, data=Serialized[b'\x00\x06\x00\x00\x00'], tx_options=<TransmitOptions.NONE: 0>, radius=0, non_member_radius=0, lqi=None, rssi=None)
2024-03-15 09:22:24.974 DEBUG (MainThread) [bellows.ezsp.protocol] Send command sendUnicast: (<EmberOutgoingMessageType.OUTGOING_DIRECT: 0>, 0x0c24, EmberApsFrame(profileId=260, clusterId=6, sourceEndpoint=11, destinationEndpoint=11, options=<EmberApsOption.APS_OPTION_RETRY|APS_OPTION_ENABLE_ROUTE_DISCOVERY: 320>, groupId=0, sequence=6), 177, b'\x00\x06\x00\x00\x00')
2024-03-15 09:22:24.977 DEBUG (bellows.thread_0) [bellows.uart] Sending: b'66c721a9602a159655904b23aa5e99099d4e27ad5ccb678dfdc663dc2f7e'
2024-03-15 09:22:24.988 DEBUG (bellows.thread_0) [bellows.uart] Data frame: b'67c7a1a9602a1501c62d7e'
2024-03-15 09:22:24.988 DEBUG (bellows.thread_0) [bellows.uart] Sending: b'87009f7e'
2024-03-15 09:22:24.989 DEBUG (MainThread) [bellows.ezsp.protocol] Application frame received sendUnicast: [<EmberStatus.SUCCESS: 0>, 179]
2024-03-15 09:22:25.003 DEBUG (bellows.thread_0) [bellows.uart] Data frame: b'77c7b1a90d2a31be8464ce28abdd85497c9a27f0967e'
2024-03-15 09:22:25.004 DEBUG (bellows.thread_0) [bellows.uart] Sending: b'8070787e'
2024-03-15 09:22:25.005 DEBUG (MainThread) [bellows.ezsp.protocol] Application frame received incomingRouteRecordHandler: [0x0c24, 00:17:88:01:0d:84:f0:dd, 224, -44, []]
2024-03-15 09:22:25.005 DEBUG (MainThread) [bellows.zigbee.application] Received incomingRouteRecordHandler frame with [0x0c24, 00:17:88:01:0d:84:f0:dd, 224, -44, []]
2024-03-15 09:22:25.005 DEBUG (MainThread) [bellows.zigbee.application] Processing route record request: (0x0c24, 00:17:88:01:0d:84:f0:dd, 224, -44, [])
2024-03-15 09:22:25.008 DEBUG (Thread-10) [aiosqlite] executing functools.partial(<built-in method execute of sqlite3.Connection object at 0x7f8c623d6a70>, 'INSERT INTO relays_v12 VALUES (:ieee, :relays)\n                        ON CONFLICT (ieee)\n                        DO UPDATE SET relays=excluded.relays WHERE relays != :relays', {'ieee': 00:17:88:01:0d:84:f0:dd, 'relays': b'\x00'})
2024-03-15 09:22:25.010 DEBUG (bellows.thread_0) [bellows.uart] Data frame: b'07c7b1a90d2a31be8464ce28abdd8549789b278ef47e'
2024-03-15 09:22:25.011 DEBUG (bellows.thread_0) [bellows.uart] Sending: b'8160597e'
2024-03-15 09:22:25.012 DEBUG (MainThread) [bellows.ezsp.protocol] Application frame received incomingRouteRecordHandler: [0x0c24, 00:17:88:01:0d:84:f0:dd, 228, -43, []]
2024-03-15 09:22:25.012 DEBUG (MainThread) [bellows.zigbee.application] Received incomingRouteRecordHandler frame with [0x0c24, 00:17:88:01:0d:84:f0:dd, 228, -43, []]
2024-03-15 09:22:25.012 DEBUG (MainThread) [bellows.zigbee.application] Processing route record request: (0x0c24, 00:17:88:01:0d:84:f0:dd, 228, -43, [])
2024-03-15 09:22:25.014 DEBUG (Thread-10) [aiosqlite] operation functools.partial(<built-in method execute of sqlite3.Connection object at 0x7f8c623d6a70>, 'INSERT INTO relays_v12 VALUES (:ieee, :relays)\n                        ON CONFLICT (ieee)\n                        DO UPDATE SET relays=excluded.relays WHERE relays != :relays', {'ieee': 00:17:88:01:0d:84:f0:dd, 'relays': b'\x00'}) completed
2024-03-15 09:22:25.015 DEBUG (Thread-10) [aiosqlite] executing functools.partial(<built-in method commit of sqlite3.Connection object at 0x7f8c623d6a70>)
2024-03-15 09:22:25.016 DEBUG (Thread-10) [aiosqlite] operation functools.partial(<built-in method commit of sqlite3.Connection object at 0x7f8c623d6a70>) completed
2024-03-15 09:22:25.018 DEBUG (Thread-10) [aiosqlite] executing functools.partial(<built-in method execute of sqlite3.Connection object at 0x7f8c623d6a70>, 'INSERT INTO relays_v12 VALUES (:ieee, :relays)\n                        ON CONFLICT (ieee)\n                        DO UPDATE SET relays=excluded.relays WHERE relays != :relays', {'ieee': 00:17:88:01:0d:84:f0:dd, 'relays': b'\x00'})
2024-03-15 09:22:25.019 DEBUG (Thread-10) [aiosqlite] operation functools.partial(<built-in method execute of sqlite3.Connection object at 0x7f8c623d6a70>, 'INSERT INTO relays_v12 VALUES (:ieee, :relays)\n                        ON CONFLICT (ieee)\n                        DO UPDATE SET relays=excluded.relays WHERE relays != :relays', {'ieee': 00:17:88:01:0d:84:f0:dd, 'relays': b'\x00'}) completed
2024-03-15 09:22:25.022 DEBUG (Thread-10) [aiosqlite] executing functools.partial(<built-in method commit of sqlite3.Connection object at 0x7f8c623d6a70>)
2024-03-15 09:22:25.024 DEBUG (Thread-10) [aiosqlite] operation functools.partial(<built-in method commit of sqlite3.Connection object at 0x7f8c623d6a70>) completed
2024-03-15 09:22:25.053 DEBUG (bellows.thread_0) [bellows.uart] Data frame: b'17c7b1a9112a15b658924a2ea15593499c88c77fc9c29874f5de6588fc7e3fb7ebcf2e3b7e'
2024-03-15 09:22:25.053 DEBUG (bellows.thread_0) [bellows.uart] Sending: b'82503a7e'
2024-03-15 09:22:25.055 DEBUG (MainThread) [bellows.ezsp.protocol] Application frame received incomingMessageHandler: [<EmberIncomingMessageType.INCOMING_UNICAST: 0>, EmberApsFrame(profileId=260, clusterId=6, sourceEndpoint=11, destinationEndpoint=11, options=<EmberApsOption.APS_OPTION_ENABLE_ROUTE_DISCOVERY: 256>, groupId=0, sequence=198), 224, -44, 0x0c24, 255, 255, b'\x18\x06\x01\x00\x00\x00\x10\x00']
2024-03-15 09:22:25.056 DEBUG (MainThread) [bellows.ezsp.protocol] Frame contains trailing data: b'\x02'
2024-03-15 09:22:25.056 DEBUG (MainThread) [bellows.zigbee.application] Received incomingMessageHandler frame with [<EmberIncomingMessageType.INCOMING_UNICAST: 0>, EmberApsFrame(profileId=260, clusterId=6, sourceEndpoint=11, destinationEndpoint=11, options=<EmberApsOption.APS_OPTION_ENABLE_ROUTE_DISCOVERY: 256>, groupId=0, sequence=198), 224, -44, 0x0c24, 255, 255, b'\x18\x06\x01\x00\x00\x00\x10\x00']
2024-03-15 09:22:25.057 DEBUG (MainThread) [zigpy.application] Received a packet: ZigbeePacket(timestamp=datetime.datetime(2024, 3, 15, 8, 22, 25, 57061, tzinfo=datetime.timezone.utc), src=AddrModeAddress(addr_mode=<AddrMode.NWK: 2>, address=0x0C24), src_ep=11, dst=AddrModeAddress(addr_mode=<AddrMode.NWK: 2>, address=0x0000), dst_ep=11, source_route=None, extended_timeout=False, tsn=198, profile_id=260, cluster_id=6, data=Serialized[b'\x18\x06\x01\x00\x00\x00\x10\x00'], tx_options=<TransmitOptions.NONE: 0>, radius=0, non_member_radius=0, lqi=224, rssi=-44)
2024-03-15 09:22:25.058 DEBUG (MainThread) [zigpy.zcl] [0x0C24:11:0x0006] Received ZCL frame: b'\x18\x06\x01\x00\x00\x00\x10\x00'
2024-03-15 09:22:25.059 DEBUG (MainThread) [zigpy.zcl] [0x0C24:11:0x0006] Decoded ZCL frame header: ZCLHeader(frame_control=FrameControl<0x18>(frame_type=<FrameType.GLOBAL_COMMAND: 0>, is_manufacturer_specific=0, direction=<Direction.Server_to_Client: 1>, disable_default_response=1, reserved=0, *is_cluster=False, *is_general=True), tsn=6, command_id=1, *direction=<Direction.Server_to_Client: 1>)
2024-03-15 09:22:25.061 DEBUG (MainThread) [zigpy.zcl] [0x0C24:11:0x0006] Decoded ZCL frame: OnOff:Read_Attributes_rsp(status_records=[ReadAttributeRecord(attrid=0x0000, status=<Status.SUCCESS: 0>, value=TypeValue(type=Bool, value=<Bool.false: 0>))])
2024-03-15 09:22:25.062 DEBUG (bellows.thread_0) [bellows.uart] Data frame: b'27c7b1a96b2a159655904b23aa5e99099d4e27185cce67650d7e'
2024-03-15 09:22:25.062 DEBUG (bellows.thread_0) [bellows.uart] Sending: b'83401b7e'
2024-03-15 09:22:25.062 DEBUG (Thread-10) [aiosqlite] executing functools.partial(<built-in method execute of sqlite3.Connection object at 0x7f8c623d6a70>, 'UPDATE devices_v12\n                    SET last_seen=:ts\n                    WHERE ieee=:ieee AND :ts - last_seen > :min_update_delta', {'ts': 1710490945.057061, 'ieee': 00:17:88:01:0d:84:f0:dd, 'min_update_delta': 30.0})
2024-03-15 09:22:25.064 DEBUG (MainThread) [bellows.ezsp.protocol] Application frame received messageSentHandler: [<EmberOutgoingMessageType.OUTGOING_DIRECT: 0>, 3108, EmberApsFrame(profileId=260, clusterId=6, sourceEndpoint=11, destinationEndpoint=11, options=<EmberApsOption.APS_OPTION_RETRY|APS_OPTION_ENABLE_ROUTE_DISCOVERY: 320>, groupId=0, sequence=179), 177, <EmberStatus.SUCCESS: 0>, b'']
2024-03-15 09:22:25.064 DEBUG (MainThread) [bellows.zigbee.application] Received messageSentHandler frame with [<EmberOutgoingMessageType.OUTGOING_DIRECT: 0>, 3108, EmberApsFrame(profileId=260, clusterId=6, sourceEndpoint=11, destinationEndpoint=11, options=<EmberApsOption.APS_OPTION_RETRY|APS_OPTION_ENABLE_ROUTE_DISCOVERY: 320>, groupId=0, sequence=179), 177, <EmberStatus.SUCCESS: 0>, b'']
2024-03-15 09:22:25.066 DEBUG (MainThread) [zigpy.zcl] [0x0C24:11:0x0008] Sending request header: ZCLHeader(frame_control=FrameControl<0x00>(frame_type=<FrameType.GLOBAL_COMMAND: 0>, is_manufacturer_specific=False, direction=<Direction.Client_to_Server: 0>, disable_default_response=0, reserved=0, *is_cluster=False, *is_general=True), tsn=7, command_id=<GeneralCommand.Read_Attributes: 0>, *direction=<Direction.Client_to_Server: 0>)
2024-03-15 09:22:25.067 DEBUG (MainThread) [zigpy.zcl] [0x0C24:11:0x0008] Sending request: Read_Attributes(attribute_ids=[0])
2024-03-15 09:22:25.068 DEBUG (MainThread) [bellows.zigbee.application] Sending packet ZigbeePacket(timestamp=datetime.datetime(2024, 3, 15, 8, 22, 25, 68636, tzinfo=datetime.timezone.utc), src=AddrModeAddress(addr_mode=<AddrMode.NWK: 2>, address=0x0000), src_ep=11, dst=AddrModeAddress(addr_mode=<AddrMode.NWK: 2>, address=0x0C24), dst_ep=11, source_route=None, extended_timeout=False, tsn=7, profile_id=260, cluster_id=8, data=Serialized[b'\x00\x07\x00\x00\x00'], tx_options=<TransmitOptions.NONE: 0>, radius=0, non_member_radius=0, lqi=None, rssi=None)
2024-03-15 09:22:25.069 DEBUG (MainThread) [bellows.ezsp.protocol] Send command sendUnicast: (<EmberOutgoingMessageType.OUTGOING_DIRECT: 0>, 0x0c24, EmberApsFrame(profileId=260, clusterId=8, sourceEndpoint=11, destinationEndpoint=11, options=<EmberApsOption.APS_OPTION_RETRY|APS_OPTION_ENABLE_ROUTE_DISCOVERY: 320>, groupId=0, sequence=7), 178, b'\x00\x07\x00\x00\x00')
2024-03-15 09:22:25.071 DEBUG (bellows.thread_0) [bellows.uart] Sending: b'73c421a9602a159655904b2daa5e99099d4e27ac5fcb678cfdc66306c97e'
2024-03-15 09:22:25.071 DEBUG (Thread-10) [aiosqlite] operation functools.partial(<built-in method execute of sqlite3.Connection object at 0x7f8c623d6a70>, 'UPDATE devices_v12\n                    SET last_seen=:ts\n                    WHERE ieee=:ieee AND :ts - last_seen > :min_update_delta', {'ts': 1710490945.057061, 'ieee': 00:17:88:01:0d:84:f0:dd, 'min_update_delta': 30.0}) completed
2024-03-15 09:22:25.073 DEBUG (Thread-10) [aiosqlite] executing functools.partial(<built-in method commit of sqlite3.Connection object at 0x7f8c623d6a70>)
2024-03-15 09:22:25.074 DEBUG (Thread-10) [aiosqlite] operation functools.partial(<built-in method commit of sqlite3.Connection object at 0x7f8c623d6a70>) completed
2024-03-15 09:22:25.075 DEBUG (Thread-10) [aiosqlite] executing functools.partial(<built-in method execute of sqlite3.Connection object at 0x7f8c623d6a70>, '\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:17:88:01:0d:84:f0:dd, 'endpoint_id': 11, 'cluster_id': 6, 'attrid': 0, 'value': <Bool.false: 0>, 'timestamp': 1710490945.065676, 'min_update_delta': 30.0})
2024-03-15 09:22:25.077 DEBUG (Thread-10) [aiosqlite] operation functools.partial(<built-in method execute of sqlite3.Connection object at 0x7f8c623d6a70>, '\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:17:88:01:0d:84:f0:dd, 'endpoint_id': 11, 'cluster_id': 6, 'attrid': 0, 'value': <Bool.false: 0>, 'timestamp': 1710490945.065676, 'min_update_delta': 30.0}) completed
2024-03-15 09:22:25.081 DEBUG (Thread-10) [aiosqlite] executing functools.partial(<built-in method commit of sqlite3.Connection object at 0x7f8c623d6a70>)
2024-03-15 09:22:25.082 DEBUG (bellows.thread_0) [bellows.uart] Data frame: b'30c4a1a9602a150662347e'
2024-03-15 09:22:25.082 DEBUG (bellows.thread_0) [bellows.uart] Sending: b'8430fc7e'
2024-03-15 09:22:25.082 DEBUG (Thread-10) [aiosqlite] operation functools.partial(<built-in method commit of sqlite3.Connection object at 0x7f8c623d6a70>) completed
2024-03-15 09:22:25.083 DEBUG (MainThread) [bellows.ezsp.protocol] Application frame received sendUnicast: [<EmberStatus.SUCCESS: 0>, 180]
2024-03-15 09:22:25.099 DEBUG (bellows.thread_0) [bellows.uart] Data frame: b'40c4b1a90d2a31be8464ce28abdd85497c9a279a1c7e'
2024-03-15 09:22:25.099 DEBUG (bellows.thread_0) [bellows.uart] Sending: b'8520dd7e'
2024-03-15 09:22:25.101 DEBUG (MainThread) [bellows.ezsp.protocol] Application frame received incomingRouteRecordHandler: [0x0c24, 00:17:88:01:0d:84:f0:dd, 224, -44, []]
2024-03-15 09:22:25.102 DEBUG (MainThread) [bellows.zigbee.application] Received incomingRouteRecordHandler frame with [0x0c24, 00:17:88:01:0d:84:f0:dd, 224, -44, []]
2024-03-15 09:22:25.102 DEBUG (MainThread) [bellows.zigbee.application] Processing route record request: (0x0c24, 00:17:88:01:0d:84:f0:dd, 224, -44, [])
2024-03-15 09:22:25.103 DEBUG (Thread-10) [aiosqlite] executing functools.partial(<built-in method execute of sqlite3.Connection object at 0x7f8c623d6a70>, 'INSERT INTO relays_v12 VALUES (:ieee, :relays)\n                        ON CONFLICT (ieee)\n                        DO UPDATE SET relays=excluded.relays WHERE relays != :relays', {'ieee': 00:17:88:01:0d:84:f0:dd, 'relays': b'\x00'})
2024-03-15 09:22:25.104 DEBUG (Thread-10) [aiosqlite] operation functools.partial(<built-in method execute of sqlite3.Connection object at 0x7f8c623d6a70>, 'INSERT INTO relays_v12 VALUES (:ieee, :relays)\n                        ON CONFLICT (ieee)\n                        DO UPDATE SET relays=excluded.relays WHERE relays != :relays', {'ieee': 00:17:88:01:0d:84:f0:dd, 'relays': b'\x00'}) completed
2024-03-15 09:22:25.106 DEBUG (bellows.thread_0) [bellows.uart] Data frame: b'50c4b1a90d2a31be8464ce28abdd85497c9a27aa417e'
2024-03-15 09:22:25.106 DEBUG (bellows.thread_0) [bellows.uart] Sending: b'8610be7e'
2024-03-15 09:22:25.107 DEBUG (MainThread) [bellows.ezsp.protocol] Application frame received incomingRouteRecordHandler: [0x0c24, 00:17:88:01:0d:84:f0:dd, 224, -44, []]
2024-03-15 09:22:25.108 DEBUG (MainThread) [bellows.zigbee.application] Received incomingRouteRecordHandler frame with [0x0c24, 00:17:88:01:0d:84:f0:dd, 224, -44, []]
2024-03-15 09:22:25.108 DEBUG (MainThread) [bellows.zigbee.application] Processing route record request: (0x0c24, 00:17:88:01:0d:84:f0:dd, 224, -44, [])
2024-03-15 09:22:25.110 DEBUG (Thread-10) [aiosqlite] executing functools.partial(<built-in method commit of sqlite3.Connection object at 0x7f8c623d6a70>)
2024-03-15 09:22:25.111 DEBUG (Thread-10) [aiosqlite] operation functools.partial(<built-in method commit of sqlite3.Connection object at 0x7f8c623d6a70>) completed
2024-03-15 09:22:25.112 DEBUG (Thread-10) [aiosqlite] executing functools.partial(<built-in method execute of sqlite3.Connection object at 0x7f8c623d6a70>, 'INSERT INTO relays_v12 VALUES (:ieee, :relays)\n                        ON CONFLICT (ieee)\n                        DO UPDATE SET relays=excluded.relays WHERE relays != :relays', {'ieee': 00:17:88:01:0d:84:f0:dd, 'relays': b'\x00'})
2024-03-15 09:22:25.113 DEBUG (Thread-10) [aiosqlite] operation functools.partial(<built-in method execute of sqlite3.Connection object at 0x7f8c623d6a70>, 'INSERT INTO relays_v12 VALUES (:ieee, :relays)\n                        ON CONFLICT (ieee)\n                        DO UPDATE SET relays=excluded.relays WHERE relays != :relays', {'ieee': 00:17:88:01:0d:84:f0:dd, 'relays': b'\x00'}) completed
2024-03-15 09:22:25.115 DEBUG (Thread-10) [aiosqlite] executing functools.partial(<built-in method commit of sqlite3.Connection object at 0x7f8c623d6a70>)
2024-03-15 09:22:25.116 DEBUG (Thread-10) [aiosqlite] operation functools.partial(<built-in method commit of sqlite3.Connection object at 0x7f8c623d6a70>) completed
2024-03-15 09:22:25.147 DEBUG (bellows.thread_0) [bellows.uart] Data frame: b'60c4b1a9112a15b6589c4a2ea15593499c89c77fc9c29874f5de6488fc7e3f8715cfc6897e'
2024-03-15 09:22:25.147 DEBUG (bellows.thread_0) [bellows.uart] Sending: b'87009f7e'
2024-03-15 09:22:25.148 DEBUG (MainThread) [bellows.ezsp.protocol] Application frame received incomingMessageHandler: [<EmberIncomingMessageType.INCOMING_UNICAST: 0>, EmberApsFrame(profileId=260, clusterId=8, sourceEndpoint=11, destinationEndpoint=11, options=<EmberApsOption.APS_OPTION_ENABLE_ROUTE_DISCOVERY: 256>, groupId=0, sequence=199), 224, -44, 0x0c24, 255, 255, b'\x18\x07\x01\x00\x00\x00 \xfe']
2024-03-15 09:22:25.149 DEBUG (MainThread) [bellows.ezsp.protocol] Frame contains trailing data: b'\x02'
2024-03-15 09:22:25.149 DEBUG (MainThread) [bellows.zigbee.application] Received incomingMessageHandler frame with [<EmberIncomingMessageType.INCOMING_UNICAST: 0>, EmberApsFrame(profileId=260, clusterId=8, sourceEndpoint=11, destinationEndpoint=11, options=<EmberApsOption.APS_OPTION_ENABLE_ROUTE_DISCOVERY: 256>, groupId=0, sequence=199), 224, -44, 0x0c24, 255, 255, b'\x18\x07\x01\x00\x00\x00 \xfe']
2024-03-15 09:22:25.150 DEBUG (MainThread) [zigpy.application] Received a packet: ZigbeePacket(timestamp=datetime.datetime(2024, 3, 15, 8, 22, 25, 149979, tzinfo=datetime.timezone.utc), src=AddrModeAddress(addr_mode=<AddrMode.NWK: 2>, address=0x0C24), src_ep=11, dst=AddrModeAddress(addr_mode=<AddrMode.NWK: 2>, address=0x0000), dst_ep=11, source_route=None, extended_timeout=False, tsn=199, profile_id=260, cluster_id=8, data=Serialized[b'\x18\x07\x01\x00\x00\x00 \xfe'], tx_options=<TransmitOptions.NONE: 0>, radius=0, non_member_radius=0, lqi=224, rssi=-44)
2024-03-15 09:22:25.151 DEBUG (MainThread) [zigpy.zcl] [0x0C24:11:0x0008] Received ZCL frame: b'\x18\x07\x01\x00\x00\x00 \xfe'
2024-03-15 09:22:25.152 DEBUG (MainThread) [zigpy.zcl] [0x0C24:11:0x0008] Decoded ZCL frame header: ZCLHeader(frame_control=FrameControl<0x18>(frame_type=<FrameType.GLOBAL_COMMAND: 0>, is_manufacturer_specific=0, direction=<Direction.Server_to_Client: 1>, disable_default_response=1, reserved=0, *is_cluster=False, *is_general=True), tsn=7, command_id=1, *direction=<Direction.Server_to_Client: 1>)
2024-03-15 09:22:25.153 DEBUG (bellows.thread_0) [bellows.uart] Data frame: b'70c4b1a96b2a159655904b2daa5e99099d4e271f5fce6711307e'
2024-03-15 09:22:25.153 DEBUG (bellows.thread_0) [bellows.uart] Sending: b'8070787e'
2024-03-15 09:22:25.155 DEBUG (MainThread) [zigpy.zcl] [0x0C24:11:0x0008] Decoded ZCL frame: LevelControl:Read_Attributes_rsp(status_records=[ReadAttributeRecord(attrid=0x0000, status=<Status.SUCCESS: 0>, value=TypeValue(type=uint8_t, value=254))])
2024-03-15 09:22:25.156 DEBUG (MainThread) [bellows.ezsp.protocol] Application frame received messageSentHandler: [<EmberOutgoingMessageType.OUTGOING_DIRECT: 0>, 3108, EmberApsFrame(profileId=260, clusterId=8, sourceEndpoint=11, destinationEndpoint=11, options=<EmberApsOption.APS_OPTION_RETRY|APS_OPTION_ENABLE_ROUTE_DISCOVERY: 320>, groupId=0, sequence=180), 178, <EmberStatus.SUCCESS: 0>, b'']
2024-03-15 09:22:25.157 DEBUG (MainThread) [bellows.zigbee.application] Received messageSentHandler frame with [<EmberOutgoingMessageType.OUTGOING_DIRECT: 0>, 3108, EmberApsFrame(profileId=260, clusterId=8, sourceEndpoint=11, destinationEndpoint=11, options=<EmberApsOption.APS_OPTION_RETRY|APS_OPTION_ENABLE_ROUTE_DISCOVERY: 320>, groupId=0, sequence=180), 178, <EmberStatus.SUCCESS: 0>, b'']
2024-03-15 09:22:25.160 DEBUG (Thread-10) [aiosqlite] executing functools.partial(<built-in method execute of sqlite3.Connection object at 0x7f8c623d6a70>, 'UPDATE devices_v12\n                    SET last_seen=:ts\n                    WHERE ieee=:ieee AND :ts - last_seen > :min_update_delta', {'ts': 1710490945.149979, 'ieee': 00:17:88:01:0d:84:f0:dd, 'min_update_delta': 30.0})
2024-03-15 09:22:25.161 DEBUG (Thread-10) [aiosqlite] operation functools.partial(<built-in method execute of sqlite3.Connection object at 0x7f8c623d6a70>, 'UPDATE devices_v12\n                    SET last_seen=:ts\n                    WHERE ieee=:ieee AND :ts - last_seen > :min_update_delta', {'ts': 1710490945.149979, 'ieee': 00:17:88:01:0d:84:f0:dd, 'min_update_delta': 30.0}) completed
2024-03-15 09:22:25.162 DEBUG (MainThread) [homeassistant.components.zha.core.cluster_handlers] [0x0C24:11:0x0008]: received attribute: 0 update with value: 254
2024-03-15 09:22:25.164 DEBUG (Thread-10) [aiosqlite] executing functools.partial(<built-in method commit of sqlite3.Connection object at 0x7f8c623d6a70>)
2024-03-15 09:22:25.165 DEBUG (Thread-10) [aiosqlite] operation functools.partial(<built-in method commit of sqlite3.Connection object at 0x7f8c623d6a70>) completed
2024-03-15 09:22:25.167 DEBUG (Thread-10) [aiosqlite] executing functools.partial(<built-in method execute of sqlite3.Connection object at 0x7f8c623d6a70>, '\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:17:88:01:0d:84:f0:dd, 'endpoint_id': 11, 'cluster_id': 8, 'attrid': 0, 'value': 254, 'timestamp': 1710490945.162685, 'min_update_delta': 30.0})
2024-03-15 09:22:25.168 DEBUG (Thread-10) [aiosqlite] operation functools.partial(<built-in method execute of sqlite3.Connection object at 0x7f8c623d6a70>, '\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:17:88:01:0d:84:f0:dd, 'endpoint_id': 11, 'cluster_id': 8, 'attrid': 0, 'value': 254, 'timestamp': 1710490945.162685, 'min_update_delta': 30.0}) completed
2024-03-15 09:22:25.170 DEBUG (Thread-10) [aiosqlite] executing functools.partial(<built-in method commit of sqlite3.Connection object at 0x7f8c623d6a70>)
2024-03-15 09:22:25.171 DEBUG (Thread-10) [aiosqlite] operation functools.partial(<built-in method commit of sqlite3.Connection object at 0x7f8c623d6a70>) completed
2024-03-15 09:22:25.791 DEBUG (bellows.thread_0) [bellows.uart] Data frame: b'00c4b1a96b2a156f80904b23aa5e99099c4e27195da8679dc97e'
2024-03-15 09:22:25.792 DEBUG (bellows.thread_0) [bellows.uart] Sending: b'8160597e'
2024-03-15 09:22:25.794 DEBUG (MainThread) [bellows.ezsp.protocol] Application frame received messageSentHandler: [<EmberOutgoingMessageType.OUTGOING_DIRECT: 0>, 55773, EmberApsFrame(profileId=260, clusterId=6, sourceEndpoint=11, destinationEndpoint=11, options=<EmberApsOption.APS_OPTION_RETRY: 64>, groupId=0, sequence=178), 176, <EmberStatus.DELIVERY_FAILED: 102>, b'']
2024-03-15 09:22:25.794 DEBUG (MainThread) [bellows.zigbee.application] Received messageSentHandler frame with [<EmberOutgoingMessageType.OUTGOING_DIRECT: 0>, 55773, EmberApsFrame(profileId=260, clusterId=6, sourceEndpoint=11, destinationEndpoint=11, options=<EmberApsOption.APS_OPTION_RETRY: 64>, groupId=0, sequence=178), 176, <EmberStatus.DELIVERY_FAILED: 102>, b'']
2024-03-15 09:22:25.797 DEBUG (MainThread) [zigpy.zcl] [0xD9DD:11:0x0008] Sending request header: ZCLHeader(frame_control=FrameControl<0x00>(frame_type=<FrameType.GLOBAL_COMMAND: 0>, is_manufacturer_specific=False, direction=<Direction.Client_to_Server: 0>, disable_default_response=0, reserved=0, *is_cluster=False, *is_general=True), tsn=8, command_id=<GeneralCommand.Read_Attributes: 0>, *direction=<Direction.Client_to_Server: 0>)
2024-03-15 09:22:25.798 DEBUG (MainThread) [zigpy.zcl] [0xD9DD:11:0x0008] Sending request: Read_Attributes(attribute_ids=[0])
2024-03-15 09:22:25.799 DEBUG (MainThread) [bellows.zigbee.application] Sending packet ZigbeePacket(timestamp=datetime.datetime(2024, 3, 15, 8, 22, 25, 799600, tzinfo=datetime.timezone.utc), src=AddrModeAddress(addr_mode=<AddrMode.NWK: 2>, address=0x0000), src_ep=11, dst=AddrModeAddress(addr_mode=<AddrMode.NWK: 2>, address=0xD9DD), dst_ep=11, source_route=None, extended_timeout=False, tsn=8, profile_id=260, cluster_id=8, data=Serialized[b'\x00\x08\x00\x00\x00'], tx_options=<TransmitOptions.NONE: 0>, radius=0, non_member_radius=0, lqi=None, rssi=None)
2024-03-15 09:22:25.800 DEBUG (MainThread) [bellows.ezsp.protocol] Send command sendUnicast: (<EmberOutgoingMessageType.OUTGOING_DIRECT: 0>, 0xd9dd, EmberApsFrame(profileId=260, clusterId=8, sourceEndpoint=11, destinationEndpoint=11, options=<EmberApsOption.APS_OPTION_RETRY|APS_OPTION_ENABLE_ROUTE_DISCOVERY: 320>, groupId=0, sequence=8), 179, b'\x00\x08\x00\x00\x00')
2024-03-15 09:22:25.802 DEBUG (bellows.thread_0) [bellows.uart] Sending: b'01c521a9602a156f80904b2daa5e99099d4e27a35ecb6783fdc663e1467e'
2024-03-15 09:22:25.811 DEBUG (bellows.thread_0) [bellows.uart] Data frame: b'11c5a1a9602a1507f6cf7e'
2024-03-15 09:22:25.811 DEBUG (bellows.thread_0) [bellows.uart] Sending: b'82503a7e'
2024-03-15 09:22:25.813 DEBUG (MainThread) [bellows.ezsp.protocol] Application frame received sendUnicast: [<EmberStatus.SUCCESS: 0>, 181]
2024-03-15 09:22:26.742 DEBUG (MainThread) [homeassistant.components.zha.core.device] [0x0F25](FLEX RGBW Z3): Device seen - marking the device available and resetting counter
2024-03-15 09:22:26.742 DEBUG (MainThread) [homeassistant.components.zha.core.device] [0x0F25](FLEX RGBW Z3): Update device availability -  device available: True - new availability: True - changed: False
2024-03-15 09:22:26.764 DEBUG (MainThread) [homeassistant.components.zha.core.device] [0xF091](lumi.vibration.aq1): Device seen - marking the device available and resetting counter
2024-03-15 09:22:26.765 DEBUG (MainThread) [homeassistant.components.zha.core.device] [0xF091](lumi.vibration.aq1): Update device availability -  device available: True - new availability: True - changed: False
2024-03-15 09:22:27.636 DEBUG (MainThread) [homeassistant.components.zha.core.device] [0x63E6](LWB006): Device seen - marking the device available and resetting counter
2024-03-15 09:22:27.637 DEBUG (MainThread) [homeassistant.components.zha.core.device] [0x63E6](LWB006): Update device availability -  device available: True - new availability: True - changed: False
2024-03-15 09:22:27.774 DEBUG (MainThread) [homeassistant.components.zha.core.device] [0xF4AA](lumi.sensor_magnet): Device seen - marking the device available and resetting counter
2024-03-15 09:22:27.774 DEBUG (MainThread) [homeassistant.components.zha.core.device] [0xF4AA](lumi.sensor_magnet): Update device availability -  device available: True - new availability: True - changed: False
2024-03-15 09:22:27.831 DEBUG (MainThread) [homeassistant.components.zha.core.device] [0x4C12](lumi.sensor_magnet): Device seen - marking the device available and resetting counter
2024-03-15 09:22:27.832 DEBUG (MainThread) [homeassistant.components.zha.core.device] [0x4C12](lumi.sensor_magnet): Update device availability -  device available: True - new availability: True - changed: False
2024-03-15 09:22:28.647 DEBUG (MainThread) [homeassistant.components.zha.entity] light.bedroom_color_feather_pendant: setting transitioning flag to True
2024-03-15 09:22:28.648 DEBUG (MainThread) [zigpy.util] Tries remaining: 3
2024-03-15 09:22:28.650 DEBUG (MainThread) [zigpy.zcl] [0x5905:1:0x0006] Sending request header: ZCLHeader(frame_control=FrameControl<0x01>(frame_type=<FrameType.CLUSTER_COMMAND: 1>, is_manufacturer_specific=False, direction=<Direction.Client_to_Server: 0>, disable_default_response=0, reserved=0, *is_cluster=True, *is_general=False), tsn=9, command_id=0, *direction=<Direction.Client_to_Server: 0>)
2024-03-15 09:22:28.651 DEBUG (MainThread) [zigpy.zcl] [0x5905:1:0x0006] Sending request: off()
2024-03-15 09:22:28.652 DEBUG (MainThread) [bellows.zigbee.application] Sending packet ZigbeePacket(timestamp=datetime.datetime(2024, 3, 15, 8, 22, 28, 652668, tzinfo=datetime.timezone.utc), src=AddrModeAddress(addr_mode=<AddrMode.NWK: 2>, address=0x0000), src_ep=1, dst=AddrModeAddress(addr_mode=<AddrMode.NWK: 2>, address=0x5905), dst_ep=1, source_route=None, extended_timeout=False, tsn=9, profile_id=260, cluster_id=6, data=Serialized[b'\x01\t\x00'], tx_options=<TransmitOptions.NONE: 0>, radius=0, non_member_radius=0, lqi=None, rssi=None)
2024-03-15 09:22:28.656 DEBUG (MainThread) [bellows.ezsp.protocol] Send command sendUnicast: (<EmberOutgoingMessageType.OUTGOING_DIRECT: 0>, 0x5905, EmberApsFrame(profileId=260, clusterId=6, sourceEndpoint=1, destinationEndpoint=1, options=<EmberApsOption.APS_OPTION_RETRY|APS_OPTION_ENABLE_ROUTE_DISCOVERY: 320>, groupId=0, sequence=9), 180, b'\x01\t\x00')
2024-03-15 09:22:28.657 DEBUG (MainThread) [homeassistant.components.zha.core.device] [0x061E](TRADFRI Signal Repeater): Device seen - marking the device available and resetting counter
2024-03-15 09:22:28.657 DEBUG (MainThread) [homeassistant.components.zha.core.device] [0x061E](TRADFRI Signal Repeater): Update device availability -  device available: True - new availability: True - changed: False
2024-03-15 09:22:28.659 DEBUG (bellows.thread_0) [bellows.uart] Sending: b'12ca21a9602a15b700904b23aa5493099d4e27a259cd6682fd95447e'
2024-03-15 09:22:28.668 DEBUG (bellows.thread_0) [bellows.uart] Data frame: b'22caa1a9602a1504c2ec7e'
2024-03-15 09:22:28.669 DEBUG (bellows.thread_0) [bellows.uart] Sending: b'83401b7e'
2024-03-15 09:22:28.669 DEBUG (MainThread) [bellows.ezsp.protocol] Application frame received sendUnicast: [<EmberStatus.SUCCESS: 0>, 182]
2024-03-15 09:22:28.670 DEBUG (MainThread) [homeassistant.components.zha.core.device] [0x0665](RWL021): Device seen - marking the device available and resetting counter
2024-03-15 09:22:28.670 DEBUG (MainThread) [homeassistant.components.zha.core.device] [0x0665](RWL021): Update device availability -  device available: True - new availability: True - changed: False
2024-03-15 09:22:30.608 DEBUG (bellows.thread_0) [bellows.uart] Data frame: b'32cab1a96b2a156f80904b2daa5e99099c4e271e5ea8673dfc7e'
2024-03-15 09:22:30.609 DEBUG (bellows.thread_0) [bellows.uart] Sending: b'8430fc7e'
2024-03-15 09:22:30.611 DEBUG (MainThread) [bellows.ezsp.protocol] Application frame received messageSentHandler: [<EmberOutgoingMessageType.OUTGOING_DIRECT: 0>, 55773, EmberApsFrame(profileId=260, clusterId=8, sourceEndpoint=11, destinationEndpoint=11, options=<EmberApsOption.APS_OPTION_RETRY: 64>, groupId=0, sequence=181), 179, <EmberStatus.DELIVERY_FAILED: 102>, b'']
2024-03-15 09:22:30.612 DEBUG (MainThread) [bellows.zigbee.application] Received messageSentHandler frame with [<EmberOutgoingMessageType.OUTGOING_DIRECT: 0>, 55773, EmberApsFrame(profileId=260, clusterId=8, sourceEndpoint=11, destinationEndpoint=11, options=<EmberApsOption.APS_OPTION_RETRY: 64>, groupId=0, sequence=181), 179, <EmberStatus.DELIVERY_FAILED: 102>, b'']
2024-03-15 09:22:32.287 DEBUG (MainThread) [zigpy.application] Feeding watchdog
2024-03-15 09:22:32.287 DEBUG (MainThread) [bellows.ezsp.protocol] Send command readCounters: ()
2024-03-15 09:22:32.290 DEBUG (bellows.thread_0) [bellows.uart] Sending: b'24cb21a9a52ae7aa7e'
2024-03-15 09:22:32.308 DEBUG (bellows.thread_0) [bellows.uart] Data frame: b'43cba1a9a52a0ab99294b8266f5580499e4e25abefceca8b7fc66389d37e16a7f3cdde6f8fffc7dbd5d2698c4623a9ec763ba5ea758241984c2613b1e070381c0e07bbe5ca6583459a4d9e4f9ff7c3d9d46a35a251904824cc9b7e'
2024-03-15 09:22:32.309 DEBUG (bellows.thread_0) [bellows.uart] Sending: b'8520dd7e'
2024-03-15 09:22:32.312 DEBUG (MainThread) [bellows.ezsp.protocol] Application frame received readCounters: [[2847, 203, 1010, 197, 18, 2, 2, 2, 173, 130, 0, 47, 41, 24, 0, 0, 0, 0, 0, 0, 0, 0, 0, 0, 0, 0, 0, 0, 0, 0, 0, 0, 9, 0, 0, 0, 0, 0, 0, 0, 0]]
2024-03-15 09:22:32.314 DEBUG (MainThread) [bellows.ezsp.protocol] Send command getValue: (<EzspValueId.VALUE_FREE_BUFFERS: 3>,)
2024-03-15 09:22:32.315 DEBUG (bellows.thread_0) [bellows.uart] Sending: b'35c821a9fe2a16bafb7e'
2024-03-15 09:22:32.321 DEBUG (bellows.thread_0) [bellows.uart] Data frame: b'54c8a1a9fe2a15b3a290eb7e'
2024-03-15 09:22:32.321 DEBUG (bellows.thread_0) [bellows.uart] Sending: b'8610be7e'
2024-03-15 09:22:32.323 DEBUG (MainThread) [bellows.ezsp.protocol] Application frame received getValue: [<EzspStatus.SUCCESS: 0>, b'\xfb']
2024-03-15 09:22:32.324 DEBUG (MainThread) [bellows.zigbee.application] Free buffers status EzspStatus.SUCCESS, value: 251
2024-03-15 09:22:32.324 DEBUG (MainThread) [bellows.zigbee.application] ezsp_counters: [MAC_RX_BROADCAST = 2847, MAC_TX_BROADCAST = 203, MAC_RX_UNICAST = 1010, MAC_TX_UNICAST_SUCCESS = 197, MAC_TX_UNICAST_RETRY = 18, MAC_TX_UNICAST_FAILED = 2, APS_DATA_RX_BROADCAST = 2, APS_DATA_TX_BROADCAST = 2, APS_DATA_RX_UNICAST = 173, APS_DATA_TX_UNICAST_SUCCESS = 130, APS_DATA_TX_UNICAST_RETRY = 0, APS_DATA_TX_UNICAST_FAILED = 47, ROUTE_DISCOVERY_INITIATED = 41, NEIGHBOR_ADDED = 24, NEIGHBOR_REMOVED = 0, NEIGHBOR_STALE = 0, JOIN_INDICATION = 0, CHILD_REMOVED = 0, ASH_OVERFLOW_ERROR = 0, ASH_FRAMING_ERROR = 0, ASH_OVERRUN_ERROR = 0, NWK_FRAME_COUNTER_FAILURE = 0, APS_FRAME_COUNTER_FAILURE = 0, UTILITY = 0, APS_LINK_KEY_NOT_AUTHORIZED = 0, NWK_DECRYPTION_FAILURE = 0, APS_DECRYPTION_FAILURE = 0, ALLOCATE_PACKET_BUFFER_FAILURE = 0, RELAYED_UNICAST = 0, PHY_TO_MAC_QUEUE_LIMIT_REACHED = 0, PACKET_VALIDATE_LIBRARY_DROPPED_COUNT = 0, TYPE_NWK_RETRY_OVERFLOW = 0, PHY_CCA_FAIL_COUNT = 9, BROADCAST_TABLE_FULL = 0, PTA_LO_PRI_REQUESTED = 0, PTA_HI_PRI_REQUESTED = 0, PTA_LO_PRI_DENIED = 0, PTA_HI_PRI_DENIED = 0, PTA_LO_PRI_TX_ABORTED = 0, PTA_HI_PRI_TX_ABORTED = 0, ADDRESS_CONFLICT_SENT = 0, EZSP_FREE_BUFFERS = 251]
2024-03-15 09:22:32.664 DEBUG (MainThread) [homeassistant.components.zha.core.device] [0x0459](LWB010): Device seen - marking the device available and resetting counter
2024-03-15 09:22:32.664 DEBUG (MainThread) [homeassistant.components.zha.core.device] [0x0459](LWB010): Update device availability -  device available: True - new availability: True - changed: False
2024-03-15 09:22:32.680 DEBUG (MainThread) [homeassistant.components.zha.core.device] [0xD12E](LWG001): Device seen - marking the device available and resetting counter
2024-03-15 09:22:32.680 DEBUG (MainThread) [homeassistant.components.zha.core.device] [0xD12E](LWG001): Update device availability -  device available: True - new availability: True - changed: False
2024-03-15 09:22:32.704 DEBUG (MainThread) [homeassistant.components.zha.core.device] [0x6D18](LWB006): Device seen - marking the device available and resetting counter
2024-03-15 09:22:32.704 DEBUG (MainThread) [homeassistant.components.zha.core.device] [0x6D18](LWB006): Update device availability -  device available: True - new availability: True - changed: False
2024-03-15 09:22:32.807 DEBUG (MainThread) [homeassistant.components.zha.core.device] [0x8D6B](TRADFRI open/close remote): Device seen - marking the device available and resetting counter
2024-03-15 09:22:32.807 DEBUG (MainThread) [homeassistant.components.zha.core.device] [0x8D6B](TRADFRI open/close remote): Update device availability -  device available: True - new availability: True - changed: False
2024-03-15 09:22:32.833 DEBUG (MainThread) [homeassistant.components.zha.core.device] [0x1498](lumi.sensor_motion): Device seen - marking the device available and resetting counter
2024-03-15 09:22:32.833 DEBUG (MainThread) [homeassistant.components.zha.core.device] [0x1498](lumi.sensor_motion): Update device availability -  device available: True - new availability: True - changed: False
2024-03-15 09:22:33.464 DEBUG (bellows.thread_0) [bellows.uart] Data frame: b'64c8b1a96b2a15b700904b23aa5493099c4e271d59a867cebe7e'
2024-03-15 09:22:33.464 DEBUG (bellows.thread_0) [bellows.uart] Sending: b'87009f7e'
2024-03-15 09:22:33.466 DEBUG (MainThread) [bellows.ezsp.protocol] Application frame received messageSentHandler: [<EmberOutgoingMessageType.OUTGOING_DIRECT: 0>, 22789, EmberApsFrame(profileId=260, clusterId=6, sourceEndpoint=1, destinationEndpoint=1, options=<EmberApsOption.APS_OPTION_RETRY: 64>, groupId=0, sequence=182), 180, <EmberStatus.DELIVERY_FAILED: 102>, b'']
2024-03-15 09:22:33.467 DEBUG (MainThread) [bellows.zigbee.application] Received messageSentHandler frame with [<EmberOutgoingMessageType.OUTGOING_DIRECT: 0>, 22789, EmberApsFrame(profileId=260, clusterId=6, sourceEndpoint=1, destinationEndpoint=1, options=<EmberApsOption.APS_OPTION_RETRY: 64>, groupId=0, sequence=182), 180, <EmberStatus.DELIVERY_FAILED: 102>, b'']
2024-03-15 09:22:33.570 DEBUG (MainThread) [zigpy.util] Tries remaining: 2
2024-03-15 09:22:33.571 DEBUG (MainThread) [zigpy.zcl] [0x5905:1:0x0006] Sending request header: ZCLHeader(frame_control=FrameControl<0x01>(frame_type=<FrameType.CLUSTER_COMMAND: 1>, is_manufacturer_specific=False, direction=<Direction.Client_to_Server: 0>, disable_default_response=0, reserved=0, *is_cluster=True, *is_general=False), tsn=10, command_id=0, *direction=<Direction.Client_to_Server: 0>)
2024-03-15 09:22:33.572 DEBUG (MainThread) [zigpy.zcl] [0x5905:1:0x0006] Sending request: off()
2024-03-15 09:22:33.573 DEBUG (MainThread) [bellows.zigbee.application] Sending packet ZigbeePacket(timestamp=datetime.datetime(2024, 3, 15, 8, 22, 33, 573120, tzinfo=datetime.timezone.utc), src=AddrModeAddress(addr_mode=<AddrMode.NWK: 2>, address=0x0000), src_ep=1, dst=AddrModeAddress(addr_mode=<AddrMode.NWK: 2>, address=0x5905), dst_ep=1, source_route=None, extended_timeout=False, tsn=10, profile_id=260, cluster_id=6, data=Serialized[b'\x01\n\x00'], tx_options=<TransmitOptions.NONE: 0>, radius=0, non_member_radius=0, lqi=None, rssi=None)
2024-03-15 09:22:33.574 DEBUG (MainThread) [bellows.ezsp.protocol] Send command sendUnicast: (<EmberOutgoingMessageType.OUTGOING_DIRECT: 0>, 0x5905, EmberApsFrame(profileId=260, clusterId=6, sourceEndpoint=1, destinationEndpoint=1, options=<EmberApsOption.APS_OPTION_RETRY|APS_OPTION_ENABLE_ROUTE_DISCOVERY: 320>, groupId=0, sequence=10), 181, b'\x01\n\x00')
2024-03-15 09:22:33.576 DEBUG (bellows.thread_0) [bellows.uart] Sending: b'47c921a9602a15b700904b23aa5493099d4e27a158cd6681fdca327e'
2024-03-15 09:22:33.585 DEBUG (bellows.thread_0) [bellows.uart] Data frame: b'75c9a1a9602a150506337e'
2024-03-15 09:22:33.585 DEBUG (bellows.thread_0) [bellows.uart] Sending: b'8070787e'
2024-03-15 09:22:33.587 DEBUG (MainThread) [bellows.ezsp.protocol] Application frame received sendUnicast: [<EmberStatus.SUCCESS: 0>, 183]
2024-03-15 09:22:34.201 WARNING (MainThread) [homeassistant.components.apple_tv] Connection lost to Apple TV "Dagligstue"
2024-03-15 09:22:34.843 DEBUG (MainThread) [homeassistant.components.zha.core.device] [0xBFDC](TS0505A): Device seen - marking the device available and resetting counter
2024-03-15 09:22:34.844 DEBUG (MainThread) [homeassistant.components.zha.core.device] [0xBFDC](TS0505A): Update device availability -  device available: True - new availability: True - changed: False
2024-03-15 09:22:36.582 DEBUG (MainThread) [homeassistant.components.zha.core.device] [0x4E10](RWL021): Device seen - marking the device available and resetting counter
2024-03-15 09:22:36.582 DEBUG (MainThread) [homeassistant.components.zha.core.device] [0x4E10](RWL021): Update device availability -  device available: True - new availability: True - changed: False
2024-03-15 09:22:36.796 DEBUG (MainThread) [homeassistant.components.zha.core.device] [0x7B8B](lumi.sensor_motion.aq2): Device seen - marking the device available and resetting counter
2024-03-15 09:22:36.797 DEBUG (MainThread) [homeassistant.components.zha.core.device] [0x7B8B](lumi.sensor_motion.aq2): Update device availability -  device available: True - new availability: True - changed: False
2024-03-15 09:22:36.812 DEBUG (MainThread) [homeassistant.components.zha.core.device] [0xDC3A](lumi.sensor_magnet): Device seen - marking the device available and resetting counter
2024-03-15 09:22:36.812 DEBUG (MainThread) [homeassistant.components.zha.core.device] [0xDC3A](lumi.sensor_magnet): Update device availability -  device available: True - new availability: True - changed: False
2024-03-15 09:22:38.380 DEBUG (bellows.thread_0) [bellows.uart] Data frame: b'05c9b1a96b2a15b700904b23aa5493099c4e271c58a86726dd7e'
2024-03-15 09:22:38.381 DEBUG (bellows.thread_0) [bellows.uart] Sending: b'8160597e'
2024-03-15 09:22:38.383 DEBUG (MainThread) [bellows.ezsp.protocol] Application frame received messageSentHandler: [<EmberOutgoingMessageType.OUTGOING_DIRECT: 0>, 22789, EmberApsFrame(profileId=260, clusterId=6, sourceEndpoint=1, destinationEndpoint=1, options=<EmberApsOption.APS_OPTION_RETRY: 64>, groupId=0, sequence=183), 181, <EmberStatus.DELIVERY_FAILED: 102>, b'']
2024-03-15 09:22:38.383 DEBUG (MainThread) [bellows.zigbee.application] Received messageSentHandler frame with [<EmberOutgoingMessageType.OUTGOING_DIRECT: 0>, 22789, EmberApsFrame(profileId=260, clusterId=6, sourceEndpoint=1, destinationEndpoint=1, options=<EmberApsOption.APS_OPTION_RETRY: 64>, groupId=0, sequence=183), 181, <EmberStatus.DELIVERY_FAILED: 102>, b'']
2024-03-15 09:22:38.485 DEBUG (MainThread) [zigpy.util] Tries remaining: 1
2024-03-15 09:22:38.487 DEBUG (MainThread) [zigpy.zcl] [0x5905:1:0x0006] Sending request header: ZCLHeader(frame_control=FrameControl<0x01>(frame_type=<FrameType.CLUSTER_COMMAND: 1>, is_manufacturer_specific=False, direction=<Direction.Client_to_Server: 0>, disable_default_response=0, reserved=0, *is_cluster=True, *is_general=False), tsn=11, command_id=0, *direction=<Direction.Client_to_Server: 0>)
2024-03-15 09:22:38.488 DEBUG (MainThread) [zigpy.zcl] [0x5905:1:0x0006] Sending request: off()
2024-03-15 09:22:38.488 DEBUG (MainThread) [bellows.zigbee.application] Sending packet ZigbeePacket(timestamp=datetime.datetime(2024, 3, 15, 8, 22, 38, 488753, tzinfo=datetime.timezone.utc), src=AddrModeAddress(addr_mode=<AddrMode.NWK: 2>, address=0x0000), src_ep=1, dst=AddrModeAddress(addr_mode=<AddrMode.NWK: 2>, address=0x5905), dst_ep=1, source_route=None, extended_timeout=False, tsn=11, profile_id=260, cluster_id=6, data=Serialized[b'\x01\x0b\x00'], tx_options=<TransmitOptions.NONE: 0>, radius=0, non_member_radius=0, lqi=None, rssi=None)
2024-03-15 09:22:38.489 DEBUG (MainThread) [bellows.ezsp.protocol] Send command sendUnicast: (<EmberOutgoingMessageType.OUTGOING_DIRECT: 0>, 0x5905, EmberApsFrame(profileId=260, clusterId=6, sourceEndpoint=1, destinationEndpoint=1, options=<EmberApsOption.APS_OPTION_RETRY|APS_OPTION_ENABLE_ROUTE_DISCOVERY: 320>, groupId=0, sequence=11), 182, b'\x01\x0b\x00')
2024-03-15 09:22:38.491 DEBUG (bellows.thread_0) [bellows.uart] Sending: b'51ce21a9602a15b700904b23aa5493099d4e27a05bcd6680fd41257e'
2024-03-15 09:22:38.500 DEBUG (bellows.thread_0) [bellows.uart] Data frame: b'16cea1a9602a150aab557e'
2024-03-15 09:22:38.501 DEBUG (bellows.thread_0) [bellows.uart] Sending: b'82503a7e'
2024-03-15 09:22:38.502 DEBUG (MainThread) [bellows.ezsp.protocol] Application frame received sendUnicast: [<EmberStatus.SUCCESS: 0>, 184]
2024-03-15 09:22:38.819 DEBUG (MainThread) [homeassistant.components.zha.core.device] [0x4B16](lumi.sensor_motion): Device seen - marking the device available and resetting counter
2024-03-15 09:22:38.819 DEBUG (MainThread) [homeassistant.components.zha.core.device] [0x4B16](lumi.sensor_motion): Update device availability -  device available: True - new availability: True - changed: False
2024-03-15 09:22:40.976 DEBUG (MainThread) [homeassistant.components.zha.entity] light.hallway_white_spot_loft_03: polling for updated state
2024-03-15 09:22:40.977 DEBUG (MainThread) [homeassistant.components.zha.entity] light.hallway_white_spot_loft_03: polling current state
2024-03-15 09:22:40.978 DEBUG (MainThread) [zigpy.zcl] [0xD12E:11:0x0006] Sending request header: ZCLHeader(frame_control=FrameControl<0x00>(frame_type=<FrameType.GLOBAL_COMMAND: 0>, is_manufacturer_specific=False, direction=<Direction.Client_to_Server: 0>, disable_default_response=0, reserved=0, *is_cluster=False, *is_general=True), tsn=7, command_id=<GeneralCommand.Read_Attributes: 0>, *direction=<Direction.Client_to_Server: 0>)
2024-03-15 09:22:40.979 DEBUG (MainThread) [zigpy.zcl] [0xD12E:11:0x0006] Sending request: Read_Attributes(attribute_ids=[0])
2024-03-15 09:22:40.980 DEBUG (MainThread) [bellows.zigbee.application] Sending packet ZigbeePacket(timestamp=datetime.datetime(2024, 3, 15, 8, 22, 40, 980023, tzinfo=datetime.timezone.utc), src=AddrModeAddress(addr_mode=<AddrMode.NWK: 2>, address=0x0000), src_ep=11, dst=AddrModeAddress(addr_mode=<AddrMode.NWK: 2>, address=0xD12E), dst_ep=11, source_route=None, extended_timeout=False, tsn=7, profile_id=260, cluster_id=6, data=Serialized[b'\x00\x07\x00\x00\x00'], tx_options=<TransmitOptions.NONE: 0>, radius=0, non_member_radius=0, lqi=None, rssi=None)
2024-03-15 09:22:40.980 DEBUG (MainThread) [bellows.ezsp.protocol] Send command sendUnicast: (<EmberOutgoingMessageType.OUTGOING_DIRECT: 0>, 0xd12e, EmberApsFrame(profileId=260, clusterId=6, sourceEndpoint=11, destinationEndpoint=11, options=<EmberApsOption.APS_OPTION_RETRY|APS_OPTION_ENABLE_ROUTE_DISCOVERY: 320>, groupId=0, sequence=7), 183, b'\x00\x07\x00\x00\x00')
2024-03-15 09:22:40.983 DEBUG (bellows.thread_0) [bellows.uart] Sending: b'62cf21a9602a159c88904b23aa5e99099d4e27ac5acb678cfdc66399597e'
2024-03-15 09:22:40.992 DEBUG (bellows.thread_0) [bellows.uart] Data frame: b'27cfa1a9602a150b021a7e'
2024-03-15 09:22:40.992 DEBUG (bellows.thread_0) [bellows.uart] Sending: b'83401b7e'
2024-03-15 09:22:40.994 DEBUG (MainThread) [bellows.ezsp.protocol] Application frame received sendUnicast: [<EmberStatus.SUCCESS: 0>, 185]
2024-03-15 09:22:41.670 DEBUG (MainThread) [homeassistant.components.zha.core.device] [0x7014](LWG001): Device seen - marking the device available and resetting counter
2024-03-15 09:22:41.671 DEBUG (MainThread) [homeassistant.components.zha.core.device] [0x7014](LWG001): Update device availability -  device available: True - new availability: True - changed: False
2024-03-15 09:22:41.748 DEBUG (MainThread) [homeassistant.components.zha.core.device] [0x17F6](FYRTUR block-out roller blind): Device seen - marking the device available and resetting counter
2024-03-15 09:22:41.749 DEBUG (MainThread) [homeassistant.components.zha.core.device] [0x17F6](FYRTUR block-out roller blind): Update device availability -  device available: True - new availability: True - changed: False
2024-03-15 09:22:42.325 DEBUG (MainThread) [zigpy.application] Feeding watchdog
2024-03-15 09:22:42.326 DEBUG (MainThread) [bellows.ezsp.protocol] Send command readCounters: ()
2024-03-15 09:22:42.327 DEBUG (bellows.thread_0) [bellows.uart] Sending: b'73cc21a9a52a38ab7e'
2024-03-15 09:22:42.344 DEBUG (bellows.thread_0) [bellows.uart] Data frame: b'30cca1a9a52a8ab98d94b6266f5580499e4e25abefceca8b7fc66389cd7e14a7f3cdde6f8fffc7dbd5d2698c4623a9ec763ba5ea758241984c2613b1e070381c0e07bbe5ca6583459a4d9e4f9ff7c3d9d46a35a25190482402427e'
2024-03-15 09:22:42.345 DEBUG (bellows.thread_0) [bellows.uart] Sending: b'8430fc7e'
2024-03-15 09:22:42.346 DEBUG (MainThread) [bellows.ezsp.protocol] Application frame received readCounters: [[2975, 212, 1020, 197, 18, 2, 2, 2, 173, 130, 0, 49, 43, 24, 0, 0, 0, 0, 0, 0, 0, 0, 0, 0, 0, 0, 0, 0, 0, 0, 0, 0, 9, 0, 0, 0, 0, 0, 0, 0, 0]]
2024-03-15 09:22:42.347 DEBUG (MainThread) [bellows.ezsp.protocol] Send command getValue: (<EzspValueId.VALUE_FREE_BUFFERS: 3>,)
2024-03-15 09:22:42.349 DEBUG (bellows.thread_0) [bellows.uart] Sending: b'04cd21a9fe2a167d38167e'
2024-03-15 09:22:42.355 DEBUG (bellows.thread_0) [bellows.uart] Data frame: b'41cda1a9fe2a15b3a0dc257e'
2024-03-15 09:22:42.355 DEBUG (bellows.thread_0) [bellows.uart] Sending: b'8520dd7e'
2024-03-15 09:22:42.356 DEBUG (MainThread) [bellows.ezsp.protocol] Application frame received getValue: [<EzspStatus.SUCCESS: 0>, b'\xf9']
2024-03-15 09:22:42.357 DEBUG (MainThread) [bellows.zigbee.application] Free buffers status EzspStatus.SUCCESS, value: 249
2024-03-15 09:22:42.357 DEBUG (MainThread) [bellows.zigbee.application] ezsp_counters: [MAC_RX_BROADCAST = 2975, MAC_TX_BROADCAST = 212, MAC_RX_UNICAST = 1020, MAC_TX_UNICAST_SUCCESS = 197, MAC_TX_UNICAST_RETRY = 18, MAC_TX_UNICAST_FAILED = 2, APS_DATA_RX_BROADCAST = 2, APS_DATA_TX_BROADCAST = 2, APS_DATA_RX_UNICAST = 173, APS_DATA_TX_UNICAST_SUCCESS = 130, APS_DATA_TX_UNICAST_RETRY = 0, APS_DATA_TX_UNICAST_FAILED = 49, ROUTE_DISCOVERY_INITIATED = 43, NEIGHBOR_ADDED = 24, NEIGHBOR_REMOVED = 0, NEIGHBOR_STALE = 0, JOIN_INDICATION = 0, CHILD_REMOVED = 0, ASH_OVERFLOW_ERROR = 0, ASH_FRAMING_ERROR = 0, ASH_OVERRUN_ERROR = 0, NWK_FRAME_COUNTER_FAILURE = 0, APS_FRAME_COUNTER_FAILURE = 0, UTILITY = 0, APS_LINK_KEY_NOT_AUTHORIZED = 0, NWK_DECRYPTION_FAILURE = 0, APS_DECRYPTION_FAILURE = 0, ALLOCATE_PACKET_BUFFER_FAILURE = 0, RELAYED_UNICAST = 0, PHY_TO_MAC_QUEUE_LIMIT_REACHED = 0, PACKET_VALIDATE_LIBRARY_DROPPED_COUNT = 0, TYPE_NWK_RETRY_OVERFLOW = 0, PHY_CCA_FAIL_COUNT = 9, BROADCAST_TABLE_FULL = 0, PTA_LO_PRI_REQUESTED = 0, PTA_HI_PRI_REQUESTED = 0, PTA_LO_PRI_DENIED = 0, PTA_HI_PRI_DENIED = 0, PTA_LO_PRI_TX_ABORTED = 0, PTA_HI_PRI_TX_ABORTED = 0, ADDRESS_CONFLICT_SENT = 0, EZSP_FREE_BUFFERS = 249]
2024-03-15 09:22:43.297 DEBUG (bellows.thread_0) [bellows.uart] Data frame: b'51cdb1a96b2a15b700904b23aa5493099c4e27135ba86779817e'
2024-03-15 09:22:43.298 DEBUG (bellows.thread_0) [bellows.uart] Sending: b'8610be7e'
2024-03-15 09:22:43.299 DEBUG (MainThread) [bellows.ezsp.protocol] Application frame received messageSentHandler: [<EmberOutgoingMessageType.OUTGOING_DIRECT: 0>, 22789, EmberApsFrame(profileId=260, clusterId=6, sourceEndpoint=1, destinationEndpoint=1, options=<EmberApsOption.APS_OPTION_RETRY: 64>, groupId=0, sequence=184), 182, <EmberStatus.DELIVERY_FAILED: 102>, b'']
2024-03-15 09:22:43.299 DEBUG (MainThread) [bellows.zigbee.application] Received messageSentHandler frame with [<EmberOutgoingMessageType.OUTGOING_DIRECT: 0>, 22789, EmberApsFrame(profileId=260, clusterId=6, sourceEndpoint=1, destinationEndpoint=1, options=<EmberApsOption.APS_OPTION_RETRY: 64>, groupId=0, sequence=184), 182, <EmberStatus.DELIVERY_FAILED: 102>, b'']
2024-03-15 09:22:43.301 ERROR (MainThread) [homeassistant.components.websocket_api.http.connection] [140240833731008] Failed to send request: Failed to deliver message: <EmberStatus.DELIVERY_FAILED: 102>
Traceback (most recent call last):
  File "/usr/src/homeassistant/homeassistant/components/zha/core/cluster_handlers/__init__.py", line 63, in wrap_zigpy_exceptions
    yield
  File "/usr/src/homeassistant/homeassistant/components/zha/core/cluster_handlers/__init__.py", line 83, in wrapper
    return await RETRYABLE_REQUEST_DECORATOR(func)(*args, **kwargs)
           ^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^
  File "/usr/local/lib/python3.12/site-packages/zigpy/util.py", line 131, in retry
    return await func()
           ^^^^^^^^^^^^
  File "/usr/local/lib/python3.12/site-packages/zigpy/zcl/__init__.py", line 377, in request
    return await self._endpoint.request(
           ^^^^^^^^^^^^^^^^^^^^^^^^^^^^^
  File "/usr/local/lib/python3.12/site-packages/zigpy/endpoint.py", line 253, in request
    return await self.device.request(
           ^^^^^^^^^^^^^^^^^^^^^^^^^^
  File "/usr/local/lib/python3.12/site-packages/zigpy/device.py", line 339, in request
    await send_request()
  File "/usr/local/lib/python3.12/site-packages/zigpy/application.py", line 841, in request
    await self.send_packet(
  File "/usr/local/lib/python3.12/site-packages/bellows/zigbee/application.py", line 931, in send_packet
    raise zigpy.exceptions.DeliveryError(
zigpy.exceptions.DeliveryError: Failed to deliver message: <EmberStatus.DELIVERY_FAILED: 102>

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

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/light/__init__.py", line 639, in async_handle_light_off_service
    await light.async_turn_off(**filter_turn_off_params(light, params))
  File "/usr/src/homeassistant/homeassistant/components/zha/light.py", line 471, in async_turn_off
    result = await self._on_off_cluster_handler.off()
             ^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^
  File "/usr/src/homeassistant/homeassistant/components/zha/core/cluster_handlers/__init__.py", line 82, in wrapper
    with wrap_zigpy_exceptions():
  File "/usr/local/lib/python3.12/contextlib.py", line 158, in __exit__
    self.gen.throw(value)
  File "/usr/src/homeassistant/homeassistant/components/zha/core/cluster_handlers/__init__.py", line 74, in wrap_zigpy_exceptions
    raise HomeAssistantError(message) from exc
homeassistant.exceptions.HomeAssistantError: Failed to send request: Failed to deliver message: <EmberStatus.DELIVERY_FAILED: 102>
2024-03-15 09:22:44.636 DEBUG (MainThread) [homeassistant.components.zha.core.device] [0xA4B8](TRADFRI Signal Repeater): Device seen - marking the device available and resetting counter
2024-03-15 09:22:44.637 DEBUG (MainThread) [homeassistant.components.zha.core.device] [0xA4B8](TRADFRI Signal Repeater): Update device availability -  device available: True - new availability: True - changed: False
2024-03-15 09:22:44.717 DEBUG (MainThread) [homeassistant.components.zha.core.device] [0x1BE4](TRADFRI Signal Repeater): Device seen - marking the device available and resetting counter
2024-03-15 09:22:44.718 DEBUG (MainThread) [homeassistant.components.zha.core.device] [0x1BE4](TRADFRI Signal Repeater): Update device availability -  device available: True - new availability: True - changed: False
2024-03-15 09:22:44.805 DEBUG (MainThread) [homeassistant.components.zha.core.device] [0xB4C8](lumi.sens): Device seen - marking the device available and resetting counter
2024-03-15 09:22:44.806 DEBUG (MainThread) [homeassistant.components.zha.core.device] [0xB4C8](lumi.sens): Update device availability -  device available: True - new availability: True - changed: False
2024-03-15 09:22:45.787 DEBUG (bellows.thread_0) [bellows.uart] Data frame: b'61cdb1a96b2a159c88904b23aa5e99099c4e27125aa867df4d7e'
2024-03-15 09:22:45.788 DEBUG (bellows.thread_0) [bellows.uart] Sending: b'87009f7e'
2024-03-15 09:22:45.789 DEBUG (MainThread) [bellows.ezsp.protocol] Application frame received messageSentHandler: [<EmberOutgoingMessageType.OUTGOING_DIRECT: 0>, 53550, EmberApsFrame(profileId=260, clusterId=6, sourceEndpoint=11, destinationEndpoint=11, options=<EmberApsOption.APS_OPTION_RETRY: 64>, groupId=0, sequence=185), 183, <EmberStatus.DELIVERY_FAILED: 102>, b'']
2024-03-15 09:22:45.790 DEBUG (MainThread) [bellows.zigbee.application] Received messageSentHandler frame with [<EmberOutgoingMessageType.OUTGOING_DIRECT: 0>, 53550, EmberApsFrame(profileId=260, clusterId=6, sourceEndpoint=11, destinationEndpoint=11, options=<EmberApsOption.APS_OPTION_RETRY: 64>, groupId=0, sequence=185), 183, <EmberStatus.DELIVERY_FAILED: 102>, b'']
2024-03-15 09:22:45.792 DEBUG (MainThread) [zigpy.zcl] [0xD12E:11:0x0008] Sending request header: ZCLHeader(frame_control=FrameControl<0x00>(frame_type=<FrameType.GLOBAL_COMMAND: 0>, is_manufacturer_specific=False, direction=<Direction.Client_to_Server: 0>, disable_default_response=0, reserved=0, *is_cluster=False, *is_general=True), tsn=8, command_id=<GeneralCommand.Read_Attributes: 0>, *direction=<Direction.Client_to_Server: 0>)
2024-03-15 09:22:45.793 DEBUG (MainThread) [zigpy.zcl] [0xD12E:11:0x0008] Sending request: Read_Attributes(attribute_ids=[0])
2024-03-15 09:22:45.794 DEBUG (MainThread) [bellows.zigbee.application] Sending packet ZigbeePacket(timestamp=datetime.datetime(2024, 3, 15, 8, 22, 45, 794192, tzinfo=datetime.timezone.utc), src=AddrModeAddress(addr_mode=<AddrMode.NWK: 2>, address=0x0000), src_ep=11, dst=AddrModeAddress(addr_mode=<AddrMode.NWK: 2>, address=0xD12E), dst_ep=11, source_route=None, extended_timeout=False, tsn=8, profile_id=260, cluster_id=8, data=Serialized[b'\x00\x08\x00\x00\x00'], tx_options=<TransmitOptions.NONE: 0>, radius=0, non_member_radius=0, lqi=None, rssi=None)
2024-03-15 09:22:45.795 DEBUG (MainThread) [bellows.ezsp.protocol] Send command sendUnicast: (<EmberOutgoingMessageType.OUTGOING_DIRECT: 0>, 0xd12e, EmberApsFrame(profileId=260, clusterId=8, sourceEndpoint=11, destinationEndpoint=11, options=<EmberApsOption.APS_OPTION_RETRY|APS_OPTION_ENABLE_ROUTE_DISCOVERY: 320>, groupId=0, sequence=8), 184, b'\x00\x08\x00\x00\x00')
2024-03-15 09:22:45.797 DEBUG (bellows.thread_0) [bellows.uart] Sending: b'17d221a9602a159c88904b2daa5e99099d4e27a355cb6783fdc66325ea7e'
2024-03-15 09:22:45.806 DEBUG (bellows.thread_0) [bellows.uart] Data frame: b'72d2a1a9602a15086cd27e'
2024-03-15 09:22:45.807 DEBUG (bellows.thread_0) [bellows.uart] Sending: b'8070787e'
2024-03-15 09:22:45.807 DEBUG (MainThread) [bellows.ezsp.protocol] Application frame received sendUnicast: [<EmberStatus.SUCCESS: 0>, 186]
2024-03-15 09:22:46.359 DEBUG (bellows.thread_0) [bellows.uart] Data frame: b'02d2b1a9112a15b658944e24ab5593499c99d876a3219874f5deba83fc7e1e0a9e67907e'
2024-03-15 09:22:46.359 DEBUG (bellows.thread_0) [bellows.uart] Sending: b'8160597e'
2024-03-15 09:22:46.361 DEBUG (MainThread) [bellows.ezsp.protocol] Application frame received incomingMessageHandler: [<EmberIncomingMessageType.INCOMING_UNICAST: 0>, EmberApsFrame(profileId=260, clusterId=1024, sourceEndpoint=1, destinationEndpoint=1, options=<EmberApsOption.APS_OPTION_ENABLE_ROUTE_DISCOVERY: 256>, groupId=0, sequence=215), 255, -35, 0xef4e, 255, 255, b'\x18\xd9\n\x00\x00!\xadu']
2024-03-15 09:22:46.361 DEBUG (MainThread) [bellows.zigbee.application] Received incomingMessageHandler frame with [<EmberIncomingMessageType.INCOMING_UNICAST: 0>, EmberApsFrame(profileId=260, clusterId=1024, sourceEndpoint=1, destinationEndpoint=1, options=<EmberApsOption.APS_OPTION_ENABLE_ROUTE_DISCOVERY: 256>, groupId=0, sequence=215), 255, -35, 0xef4e, 255, 255, b'\x18\xd9\n\x00\x00!\xadu']
2024-03-15 09:22:46.362 DEBUG (MainThread) [zigpy.application] Received a packet: ZigbeePacket(timestamp=datetime.datetime(2024, 3, 15, 8, 22, 46, 361984, tzinfo=datetime.timezone.utc), src=AddrModeAddress(addr_mode=<AddrMode.NWK: 2>, address=0xEF4E), src_ep=1, dst=AddrModeAddress(addr_mode=<AddrMode.NWK: 2>, address=0x0000), dst_ep=1, source_route=None, extended_timeout=False, tsn=215, profile_id=260, cluster_id=1024, data=Serialized[b'\x18\xd9\n\x00\x00!\xadu'], tx_options=<TransmitOptions.NONE: 0>, radius=0, non_member_radius=0, lqi=255, rssi=-35)
2024-03-15 09:22:46.363 DEBUG (MainThread) [zigpy.zcl] [0xEF4E:1:0x0400] Received ZCL frame: b'\x18\xd9\n\x00\x00!\xadu'
2024-03-15 09:22:46.364 DEBUG (MainThread) [zigpy.zcl] [0xEF4E:1:0x0400] Decoded ZCL frame header: ZCLHeader(frame_control=FrameControl<0x18>(frame_type=<FrameType.GLOBAL_COMMAND: 0>, is_manufacturer_specific=0, direction=<Direction.Server_to_Client: 1>, disable_default_response=1, reserved=0, *is_cluster=False, *is_general=True), tsn=217, command_id=10, *direction=<Direction.Server_to_Client: 1>)
2024-03-15 09:22:46.365 DEBUG (MainThread) [zigpy.zcl] [0xEF4E:1:0x0400] Decoded ZCL frame: IlluminanceMeasurement:Report_Attributes(attribute_reports=[Attribute(attrid=0x0000, value=TypeValue(type=uint16_t, value=30125))])
2024-03-15 09:22:46.366 DEBUG (MainThread) [zigpy.zcl] [0xEF4E:1:0x0400] Received command 0x0A (TSN 217): Report_Attributes(attribute_reports=[Attribute(attrid=0x0000, value=TypeValue(type=uint16_t, value=30125))])
2024-03-15 09:22:46.366 DEBUG (MainThread) [zigpy.zcl] [0xEF4E:1:0x0400] Attribute report received: measured_value=30125
2024-03-15 09:22:46.367 DEBUG (MainThread) [homeassistant.components.zha.core.cluster_handlers] [0xEF4E:1:0x0400]: cluster_handler[illuminance] attribute_updated - cluster[Illuminance Measurement] attr[measured_value] value[30125]
2024-03-15 09:22:46.369 DEBUG (Thread-10) [aiosqlite] executing functools.partial(<built-in method execute of sqlite3.Connection object at 0x7f8c623d6a70>, 'UPDATE devices_v12\n                    SET last_seen=:ts\n                    WHERE ieee=:ieee AND :ts - last_seen > :min_update_delta', {'ts': 1710490966.361984, 'ieee': 04:cf:8c:df:3c:78:c0:24, 'min_update_delta': 30.0})
2024-03-15 09:22:46.372 DEBUG (Thread-10) [aiosqlite] operation functools.partial(<built-in method execute of sqlite3.Connection object at 0x7f8c623d6a70>, 'UPDATE devices_v12\n                    SET last_seen=:ts\n                    WHERE ieee=:ieee AND :ts - last_seen > :min_update_delta', {'ts': 1710490966.361984, 'ieee': 04:cf:8c:df:3c:78:c0:24, 'min_update_delta': 30.0}) completed
2024-03-15 09:22:46.375 DEBUG (Thread-10) [aiosqlite] executing functools.partial(<built-in method commit of sqlite3.Connection object at 0x7f8c623d6a70>)
2024-03-15 09:22:46.376 DEBUG (Thread-10) [aiosqlite] operation functools.partial(<built-in method commit of sqlite3.Connection object at 0x7f8c623d6a70>) completed
2024-03-15 09:22:46.378 DEBUG (Thread-10) [aiosqlite] executing functools.partial(<built-in method execute of sqlite3.Connection object at 0x7f8c623d6a70>, '\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': 04:cf:8c:df:3c:78:c0:24, 'endpoint_id': 1, 'cluster_id': 1024, 'attrid': 0, 'value': 30125, 'timestamp': 1710490966.367169, 'min_update_delta': 30.0})
2024-03-15 09:22:46.380 DEBUG (Thread-10) [aiosqlite] operation functools.partial(<built-in method execute of sqlite3.Connection object at 0x7f8c623d6a70>, '\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': 04:cf:8c:df:3c:78:c0:24, 'endpoint_id': 1, 'cluster_id': 1024, 'attrid': 0, 'value': 30125, 'timestamp': 1710490966.367169, 'min_update_delta': 30.0}) completed
2024-03-15 09:22:46.382 DEBUG (Thread-10) [aiosqlite] executing functools.partial(<built-in method commit of sqlite3.Connection object at 0x7f8c623d6a70>)
2024-03-15 09:22:46.383 DEBUG (Thread-10) [aiosqlite] operation functools.partial(<built-in method commit of sqlite3.Connection object at 0x7f8c623d6a70>) completed
bymem commented 7 months ago

And now after a restart HA seems to have thrown all sensors.

mikeymop commented 7 months ago

And now after a restart HA seems to have thrown all sensors.

I think a reasonable assumption can be made that if recreating from scratch demonstrates the same issue. That your issue may be the network / airwave conditions where your HA node is placed.

Would you be able to take any steps to reduce interference? Eg:

bymem commented 7 months ago

@mikeymop normally i would agree, and that as I stated earlier is also why a moved the machine running HA.

But as also stated earlier the system and network have been running more or less rock solid for year, nothing new introduced to the system, most of my smart devices are zigbee, which also why my whole house is not working right now.

I have minimal wifi devices mostly phone and tablets, computers are hardwired.

And would agree if I had over a longer period experience problems I would agree with interference, but this came at the exact moment of updating to 2024.3 and could be stabilized by downgrading.

dexheimer42 commented 7 months ago

Same here, 80+ Zigbee devices on ZHA/Conbee2, mostly stable for a long time now. But 2024.3 hit me hard. Error log fills up with errors belonging to zigbee devices, e.g.:

[0x5D69:1:0x0020] Traceback (most recent call last): File "/usr/local/lib/python3.12/site-packages/zigpy/device.py", line 342, 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.12/site-packages/zigpy/zcl/init.py", line 377, in request return await self._endpoint.request( ^^^^^^^^^^^^^^^^^^^^^^^^^^^^^ File "/usr/local/lib/python3.12/site-packages/zigpy/endpoint.py", line 253, in request return await self.device.request( ^^^^^^^^^^^^^^^^^^^^^^^^^^ File "/usr/local/lib/python3.12/site-packages/zigpy/device.py", line 341, in request async with asyncio_timeout(timeout): File "/usr/local/lib/python3.12/asyncio/timeouts.py", line 115, 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/src/homeassistant/homeassistant/components/zha/core/cluster_handlers/general.py", line 623, in check_in_response await self.checkin_response(True, self.CHECKIN_FAST_POLL_TIMEOUT, tsn=tsn) File "/usr/src/homeassistant/homeassistant/components/zha/core/cluster_handlers/init.py", line 82, in wrapper with wrap_zigpy_exceptions(): File "/usr/local/lib/python3.12/contextlib.py", line 158, in exit self.gen.throw(value) File "/usr/src/homeassistant/homeassistant/components/zha/core/cluster_handlers/init.py", line 65, in wrap_zigpy_exceptions raise HomeAssistantError( homeassistant.exceptions.HomeAssistantError:

I was able to fix broken zigbee groups with 2024.3.1, but the mesh is still instable.

I can confirm that it seems like it degrades over time. There is increasing delay in device reaction to commands.

Phileep commented 7 months ago

similar setup to dexheimer42. ConbeeII ~ 60 devices.

Stable until update to 2024.3 (currently on 2024.3.1)

multiple restarts and reloads of ZHA / devices. still unstable.

latest ZHA log entry attached

2024-03-19 12:35:07.550 ERROR (MainThread) [zigpy.zcl] [0x3EC0:1:0x0020] Traceback (most recent call last):
  File "/usr/local/lib/python3.12/site-packages/zigpy/device.py", line 342, 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.12/site-packages/zigpy/zcl/__init__.py", line 377, in request
    return await self._endpoint.request(
           ^^^^^^^^^^^^^^^^^^^^^^^^^^^^^
  File "/usr/local/lib/python3.12/site-packages/zigpy/endpoint.py", line 253, in request
    return await self.device.request(
           ^^^^^^^^^^^^^^^^^^^^^^^^^^
  File "/usr/local/lib/python3.12/site-packages/zigpy/device.py", line 341, in request
    async with asyncio_timeout(timeout):
  File "/usr/local/lib/python3.12/asyncio/timeouts.py", line 115, 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/src/homeassistant/homeassistant/components/zha/core/cluster_handlers/general.py", line 623, in check_in_response
    await self.checkin_response(True, self.CHECKIN_FAST_POLL_TIMEOUT, tsn=tsn)
  File "/usr/src/homeassistant/homeassistant/components/zha/core/cluster_handlers/__init__.py", line 82, in wrapper
    with wrap_zigpy_exceptions():
  File "/usr/local/lib/python3.12/contextlib.py", line 158, in __exit__
    self.gen.throw(value)
  File "/usr/src/homeassistant/homeassistant/components/zha/core/cluster_handlers/__init__.py", line 65, in wrap_zigpy_exceptions
    raise HomeAssistantError(
homeassistant.exceptions.HomeAssistantError: Failed to send request: device did not respond
bymem commented 7 months ago

Well after several attempts getting it fixed, i toke the plunged with zigbee2MQTT, and things are A LOT more stable. Then you can talk about interferences and all that, but if changing system helps, then there seems to something wrong with the system.

puddly commented 7 months ago

The statistics from the radio that were pulled from your diagnostics info don't lie:

MAC_TX_UNICAST_SUCCESS = 943
MAC_TX_UNICAST_RETRY = 4294
MAC_TX_UNICAST_FAILED = 1634
PHY_CCA_FAIL_COUNT = 2784

Over 40% of your requests outright fail because the radio's firmware refused to transmit due to noise. The integration can't control that, it's your environment.

Unless your network was loaded with a ton of Tuya devices, the only change that Z2M performs is moving Zigbee network to channel 11. ZHA generally avoids channel 11 when picking your network's channel.

mikeymop commented 7 months ago

@mikeymop normally i would agree, and that as I stated earlier is also why a moved the machine running HA.

But as also stated earlier the system and network have been running more or less rock solid for year, nothing new introduced to the system, most of my smart devices are zigbee, which also why my whole house is not working right now.

And would agree if I had over a longer period experience problems I would agree with interference, but this came at the exact moment of updating to 2024.3 and could be stabilized by downgrading.

I understand completely, and read your comment history very carefully.

The reason I brought it up is that our situations are almost identical.

The only difference being that I'm using a Ha Yellow with a skyconnect built in rather than a dongle.

My Ha Yellow has not moved in over a year, and I also primarily have only Ethernet devices aside from the cell phones and the wifi printer I mentioned.

The event that triggered my crashing issues I believe was the firmware update to ZHA. I put it off for several months as I read the warning it could be a breaking upgrade. Once I upgraded I started experiencing the crashes.

My belief (still reading through the commit history), is that the newer firmware enforces this failure due to noise and bubbles up the exception.

I argue the firmware could raise a more understandable exception to the user however it's entirely possible we have experienced these failures due to interference and the firmware just swallowed the exception and retried over and over producing even more interference.

The above reasoning aligns with my router reporting many dropped packets. Up until the point I remedied the interference.

I still stand by the issue being the network environment and the interference with in our homes and the best remediation being to make it clear to the user that the Firmware is throwing because of interference as Python stack traces tend to be very verbose.

puddly commented 7 months ago

I put it off for several months as I read the warning it could be a breaking upgrade.

Which one are you referring to?

My belief (still reading through the commit history), is that the newer firmware enforces this failure due to noise and bubbles up the exception.

We actually disabled (as much as possible) this firmware feature in August. If you haven't explicitly updated the firmware on your Yellow, you're running the firmware that it came with. ZHA won't flash new firmware.

make it clear to the user that the Firmware is throwing because of interference

Unfortunately, this isn't easily possible. The firmware just tells you SUCCESS or FAILURE. Why something failed isn't accessible to the application (ZHA) beyond the global counters I referenced above.

You are very right, however, that channel access failures should be reported better. It's something that's being worked on.

dexheimer42 commented 7 months ago

How can I get this diagnostic info with these specific statistics from? I pulled diag info from ZHA and from the coordinator device but couldn't find these counters (HA2024.2.2).

puddly @.***> schrieb am Di., 19. März 2024, 16:01:

The statistics from the radio that were pulled from your diagnostics info don't lie:

MAC_TX_UNICAST_SUCCESS = 943MAC_TX_UNICAST_RETRY = 4294MAC_TX_UNICAST_FAILED = 1634PHY_CCA_FAIL_COUNT = 2784

Over 40% of your requests outright fail because the radio's firmware refused to transmit due to noise. The integration can't control that, it's your environment.

Unless your network was loaded with a ton of Tuya devices, the only change that Z2M performs is moving Zigbee network to channel 11. ZHA generally avoids channel 11 when picking your network's channel.

— Reply to this email directly, view it on GitHub https://github.com/home-assistant/core/issues/112843#issuecomment-2007420754, or unsubscribe https://github.com/notifications/unsubscribe-auth/A4QOIEX44W4T4WWCTD64JKLYZBHMVAVCNFSM6AAAAABEOMDPDOVHI2DSMVQWIX3LMV43OSLTON2WKQ3PNVWWK3TUHMZDAMBXGQZDANZVGQ . You are receiving this because you commented.Message ID: @.***>

mikeymop commented 7 months ago

Which one are you referring

Good question. It came up end of year, is there an easy way I can view historical changelogs that I can try to back reference?

After some more time I noticed that I still experience this issue just much less frequently.

I'm noticing a strange correlation where this integration only crashes when an update becomes available for one of:

On any given day I noticed ZHA crashes I always have updates available these three.

dexheimer42 commented 6 months ago

In the meantime HA 2024.4 came out. So I hoped that this issue could have been fixed, since I rolled back to 2024.2 before, where this strange behavior didn't show up: zigbee devices / mesh is getting slow after time until it gets totally unusable. Unfortunately with 2024.4 my zigbee mesh continues to collapse over time. So I started a new investigation and found that this might has something to do with the latest deconz/firmware for my conbee II coordinator:

https://forum.phoscon.de/t/current-deconz-2-24-3-2-25-1-slow-in-response-after-time/4517

The timeframe stated in that topic somehow relates with the time when I started to notice these problems with my HA instance.

So I decided to give SkyConnect a try which I had on my desk. Et voilà, all issues gone. Explanation: Different chip, different firmware, different software stack in ZHA/zigpy. Good by conbee. We had a good time.

T.