Hmm, mine is doing exactly the same. I’m also seeing this timeout in the logs:
2021-11-15 22:24:05 DEBUG (MainThread) [homeassistant.core] Bus:Handling <Event call_service[L]: domain=climate, service=set_temperature, service_data=target_temp_high=25, target_temp_low=23, hvac_mode=heat, temperature=25, area_id=['office']>
2021-11-15 22:24:05 DEBUG (MainThread) [zigpy.device] [0xab2f] Extending timeout for 0x16 request
2021-11-15 22:24:05 DEBUG (MainThread) [zigpy_deconz.zigbee.application] Sending Zigbee request with tsn 22 under 23 request id, data: b'0016021c003004'
2021-11-15 22:24:05 DEBUG (MainThread) [zigpy_deconz.api] Command Command.aps_data_request (22, 23, 0, <DeconzAddressEndpoint address_mode=2 address=0xAB2F endpoint=1>, 260, 513, 1, b'\x00\x16\x02\x1c\x000\x04', 2, 0)
2021-11-15 22:24:06 DEBUG (MainThread) [zigpy_deconz.api] APS data request response: [2, <DeviceState.APSDE_DATA_REQUEST_SLOTS_AVAILABLE|2: 34>, 23]
2021-11-15 22:24:06 DEBUG (MainThread) [zigpy_deconz.api] Device state changed response: [<DeviceState.128|APSDE_DATA_REQUEST_SLOTS_AVAILABLE|APSDE_DATA_CONFIRM|2: 166>, 0]
2021-11-15 22:24:06 DEBUG (MainThread) [zigpy_deconz.api] Command Command.aps_data_confirm (0,)
2021-11-15 22:24:06 DEBUG (MainThread) [zigpy_deconz.api] APS data confirm response for request with id 23: 00
2021-11-15 22:24:06 DEBUG (MainThread) [zigpy_deconz.api] Request id: 0x17 'aps_data_confirm' for <DeconzAddressEndpoint address_mode=ADDRESS_MODE.NWK address=0xab2f endpoint=1>, status: 0x00
2021-11-15 22:24:08 DEBUG (MainThread) [zigpy_deconz.api] Command Command.write_parameter (5, <NetworkParameter.watchdog_ttl: 38>, b'X\x02\x00\x00')
2021-11-15 22:24:08 DEBUG (MainThread) [zigpy_deconz.api] Write parameter watchdog_ttl: SUCCESS
2021-11-15 22:24:09 DEBUG (MainThread) [homeassistant.core] Bus:Handling <Event state_changed[L]: entity_id=sensor.arris_tg3492lg_packets_received, old_state=<state sensor.arris_tg3492lg_packets_received=89390990; unit_of_measurement=packets, friendly_name=ARRIS TG3492LG packets received, icon=mdi:server-network @ 2021-11-15T22:23:39.037881+00:00>, new_state=<state sensor.arris_tg3492lg_packets_received=89391527; unit_of_measurement=packets, friendly_name=ARRIS TG3492LG packets received, icon=mdi:server-network @ 2021-11-15T22:24:09.039497+00:00>>
2021-11-15 22:24:09 DEBUG (MainThread) [homeassistant.core] Bus:Handling <Event state_changed[L]: entity_id=sensor.arris_tg3492lg_packets_sent, old_state=<state sensor.arris_tg3492lg_packets_sent=32434489; unit_of_measurement=packets, friendly_name=ARRIS TG3492LG packets sent, icon=mdi:server-network @ 2021-11-15T22:23:39.038744+00:00>, new_state=<state sensor.arris_tg3492lg_packets_sent=32434672; unit_of_measurement=packets, friendly_name=ARRIS TG3492LG packets sent, icon=mdi:server-network @ 2021-11-15T22:24:09.040400+00:00>>
2021-11-15 22:24:09 DEBUG (MainThread) [homeassistant.core] Bus:Handling <Event state_changed[L]: entity_id=sensor.arris_tg3492lg_packets_s_received, old_state=<state sensor.arris_tg3492lg_packets_s_received=16.3; unit_of_measurement=packets/s, friendly_name=ARRIS TG3492LG packets/s received, icon=mdi:server-network @ 2021-11-15T22:23:39.039831+00:00>, new_state=<state sensor.arris_tg3492lg_packets_s_received=17.9; unit_of_measurement=packets/s, friendly_name=ARRIS TG3492LG packets/s received, icon=mdi:server-network @ 2021-11-15T22:24:09.041338+00:00>>
2021-11-15 22:24:09 DEBUG (MainThread) [homeassistant.core] Bus:Handling <Event state_changed[L]: entity_id=sensor.arris_tg3492lg_packets_s_sent, old_state=<state sensor.arris_tg3492lg_packets_s_sent=5.9; unit_of_measurement=packets/s, friendly_name=ARRIS TG3492LG packets/s sent, icon=mdi:server-network @ 2021-11-15T22:23:39.040441+00:00>, new_state=<state sensor.arris_tg3492lg_packets_s_sent=6.1; unit_of_measurement=packets/s, friendly_name=ARRIS TG3492LG packets/s sent, icon=mdi:server-network @ 2021-11-15T22:24:09.042156+00:00>>
2021-11-15 22:24:15 INFO (MainThread) [homeassistant.components.websocket_api.http.connection] [547239845648] Connection closed by client
2021-11-15 22:24:15 DEBUG (MainThread) [homeassistant.core] Service did not complete before timeout: <ServiceCall automation.trigger (c:7e1fd3bd9d68369557f4b7cacb2af647): entity_id=['automation.turn_on_the_heat_in_the_morning_2'], skip_condition=True, variables=>
2021-11-15 22:24:15 DEBUG (MainThread) [homeassistant.core] Service did not complete before timeout: <ServiceCall climate.set_temperature (c:e8d27f07725072b31c3956a2491ded64): target_temp_high=25.0, target_temp_low=23.0, hvac_mode=heat, temperature=25.0, area_id=['office']>
2021-11-15 22:24:16 DEBUG (MainThread) [homeassistant.core] Bus:Handling <Event state_changed[L]: entity_id=automation.turn_on_the_heat_in_the_morning_2, old_state=<state automation.turn_on_the_heat_in_the_morning_2=on; last_triggered=2021-11-15T22:24:05.973300+00:00, mode=single, current=1, id=office_heat_on, friendly_name=office: heat in the morning @ 2021-11-15T22:14:44.161207+00:00>, new_state=<state automation.turn_on_the_heat_in_the_morning_2=on; last_triggered=2021-11-15T22:24:05.973300+00:00, mode=single, current=0, id=office_heat_on, friendly_name=office: heat in the morning @ 2021-11-15T22:14:44.161207+00:00>>
2021-11-15 22:24:16 DEBUG (MainThread) [zigpy_deconz.api] Device state changed response: [<DeviceState.128|APSDE_DATA_REQUEST_SLOTS_AVAILABLE|APSDE_DATA_INDICATION|2: 170>, 0]
2021-11-15 22:24:16 DEBUG (MainThread) [zigpy_deconz.api] Command Command.aps_data_indication (1, 1)
2021-11-15 22:24:16 DEBUG (MainThread) [zigpy_deconz.api] APS data indication response: [28, <DeviceState.APSDE_DATA_REQUEST_SLOTS_AVAILABLE|2: 34>, <DeconzAddress address_mode=ADDRESS_MODE.NWK address=0x0000>, 1, <DeconzAddress address_mode=ADDRESS_MODE.NWK address=0xab2f>, 1, 260, 0, b'\x00\x05\x00\x00\x00', 0, 175, 199, 92, 32, 0, 0, -69]
2021-11-15 22:24:16 DEBUG (MainThread) [zigpy.zcl] [0xab2f:1:0x0000] ZCL deserialize: <ZCLHeader frame_control=<FrameControl frame_type=GLOBAL_COMMAND manufacturer_specific=False is_reply=False disable_default_response=False> manufacturer=None tsn=5 command_id=Command.Read_Attributes>
2021-11-15 22:24:16 DEBUG (MainThread) [zigpy.zcl] [0xab2f:1:0x0000] ZCL request 0x0000: [[0]]
2021-11-15 22:24:16 DEBUG (MainThread) [zigpy_deconz.api] 'aps_data_indication' response from <DeconzAddress address_mode=ADDRESS_MODE.NWK address=0xab2f>, ep: 1, profile: 0x0104, cluster_id: 0x0000, data: b'0005000000'
2021-11-15 22:24:18 DEBUG (MainThread) [zigpy_deconz.api] Device state changed response: [<DeviceState.128|APSDE_DATA_REQUEST_SLOTS_AVAILABLE|APSDE_DATA_INDICATION|2: 170>, 0]
2021-11-15 22:24:18 DEBUG (MainThread) [zigpy_deconz.api] Command Command.aps_data_indication (1, 1)
2021-11-15 22:24:18 DEBUG (MainThread) [zigpy_deconz.api] APS data indication response: [83, <DeviceState.APSDE_DATA_REQUEST_SLOTS_AVAILABLE|APSDE_DATA_INDICATION|2: 42>, <DeconzAddress address_mode=ADDRESS_MODE.NWK address=0x0000>, 1, <DeconzAddress address_mode=ADDRESS_MODE.NWK address=0xab2f>, 1, 260, 65027, b'\x1c^\x10\x06\n \x00B3ADC,1354,1357,2,233,-32768,2000,0,0,100,233,232,236', 0, 175, 199, 92, 32, 0, 0, -69]
2021-11-15 22:24:18 DEBUG (MainThread) [zigpy.zcl] [0xab2f:1:0xfe03] ZCL deserialize: <ZCLHeader frame_control=<FrameControl frame_type=GLOBAL_COMMAND manufacturer_specific=True is_reply=True disable_default_response=True> manufacturer=4190 tsn=6 command_id=Command.Report_Attributes>
2021-11-15 22:24:18 DEBUG (MainThread) [zigpy.zcl] [0xab2f:1:0xfe03] ZCL request 0x000a: [[Attribute(attrid=32, value=<TypeValue type=CharacterString, value=ADC,1354,1357,2,233,-32768,2000,0,0,100,233,232,236>)]]
2021-11-15 22:24:18 DEBUG (MainThread) [zigpy.zcl] [0xab2f:1:0xfe03] Attribute report received: 32=ADC,1354,1357,2,233,-32768,2000,0,0,100,233,232,236
2021-11-15 22:24:18 DEBUG (MainThread) [zigpy_deconz.api] 'aps_data_indication' response from <DeconzAddress address_mode=ADDRESS_MODE.NWK address=0xab2f>, ep: 1, profile: 0x0104, cluster_id: 0xfe03, data: b'1c5e10060a200042334144432c313335342c313335372c322c3233332c2d33323736382c323030302c302c302c3130302c3233332c3233322c323336'
2021-11-15 22:24:18 DEBUG (MainThread) [zigpy_deconz.api] APS data indication response: [34, <DeviceState.APSDE_DATA_REQUEST_SLOTS_AVAILABLE|2: 34>, <DeconzAddress address_mode=ADDRESS_MODE.NWK address=0x0000>, 1, <DeconzAddress address_mode=ADDRESS_MODE.NWK address=0xab2f>, 1, 260, 2821, b'\x18\x08\n\x1c\x01 \x00\x1d\x01(\x00', 0, 175, 199, 92, 32, 0, 0, -69]
2021-11-15 22:24:18 DEBUG (MainThread) [zigpy.zcl] [0xab2f:1:0x0b05] ZCL deserialize: <ZCLHeader frame_control=<FrameControl frame_type=GLOBAL_COMMAND manufacturer_specific=False is_reply=True disable_default_response=True> manufacturer=None tsn=8 command_id=Command.Report_Attributes>
2021-11-15 22:24:18 DEBUG (MainThread) [zigpy.zcl] [0xab2f:1:0x0b05] ZCL request 0x000a: [[Attribute(attrid=284, value=<TypeValue type=uint8_t, value=0>), Attribute(attrid=285, value=<TypeValue type=int8s, value=0>)]]
2021-11-15 22:24:18 DEBUG (MainThread) [zigpy.zcl] [0xab2f:1:0x0b05] Attribute report received: last_message_lqi=0, last_message_rssi=0
2021-11-15 22:24:18 DEBUG (MainThread) [zigpy_deconz.api] 'aps_data_indication' response from <DeconzAddress address_mode=ADDRESS_MODE.NWK address=0xab2f>, ep: 1, profile: 0x0104, cluster_id: 0x0b05, data: b'18080a1c0120001d012800'
2021-11-15 22:24:18 DEBUG (MainThread) [zigpy_deconz.api] APS data indication response: [66, <DeviceState.APSDE_DATA_REQUEST_SLOTS_AVAILABLE|2: 34>, <DeconzAddress address_mode=ADDRESS_MODE.NWK address=0x0000>, 1, <DeconzAddress address_mode=ADDRESS_MODE.NWK address=0xab2f>, 1, 260, 65027, b'\x1c^\x10\x07\n \x00B"ALG,11,1,200,233,-33,0,0,0,0,0,100', 0, 175, 199, 92, 32, 0, 0, -69]
2021-11-15 22:24:18 DEBUG (MainThread) [zigpy.zcl] [0xab2f:1:0xfe03] ZCL deserialize: <ZCLHeader frame_control=<FrameControl frame_type=GLOBAL_COMMAND manufacturer_specific=True is_reply=True disable_default_response=True> manufacturer=4190 tsn=7 command_id=Command.Report_Attributes>
2021-11-15 22:24:18 DEBUG (MainThread) [zigpy.zcl] [0xab2f:1:0xfe03] ZCL request 0x000a: [[Attribute(attrid=32, value=<TypeValue type=CharacterString, value=ALG,11,1,200,233,-33,0,0,0,0,0,100>)]]
2021-11-15 22:24:18 DEBUG (MainThread) [zigpy.zcl] [0xab2f:1:0xfe03] Attribute report received: 32=ALG,11,1,200,233,-33,0,0,0,0,0,100
2021-11-15 22:24:18 DEBUG (MainThread) [zigpy_deconz.api] 'aps_data_indication' response from <DeconzAddress address_mode=ADDRESS_MODE.NWK address=0xab2f>, ep: 1, profile: 0x0104, cluster_id: 0xfe03, data: b'1c5e10070a20004222414c472c31312c312c3230302c3233332c2d33332c302c302c302c302c302c313030'
2021-11-15 22:24:18 DEBUG (MainThread) [zigpy_deconz.api] APS data indication response: [33, <DeviceState.APSDE_DATA_REQUEST_SLOTS_AVAILABLE|2: 34>, <DeconzAddress address_mode=ADDRESS_MODE.NWK address=0x0000>, 1, <DeconzAddress address_mode=ADDRESS_MODE.NWK address=0xab2f>, 1, 260, 2821, b'\x1c^\x10\t\n\x01\xe0!\xdfl', 0, 175, 199, 92, 32, 0, 0, -69]
2021-11-15 22:24:18 DEBUG (MainThread) [zigpy.zcl] [0xab2f:1:0x0b05] ZCL deserialize: <ZCLHeader frame_control=<FrameControl frame_type=GLOBAL_COMMAND manufacturer_specific=True is_reply=True disable_default_response=True> manufacturer=4190 tsn=9 command_id=Command.Report_Attributes>
2021-11-15 22:24:18 DEBUG (MainThread) [zigpy.zcl] [0xab2f:1:0x0b05] ZCL request 0x000a: [[Attribute(attrid=57345, value=<TypeValue type=uint16_t, value=27871>)]]
2021-11-15 22:24:18 DEBUG (MainThread) [zigpy.zcl] [0xab2f:1:0x0b05] Attribute report received: 57345=27871
2021-11-15 22:24:18 DEBUG (MainThread) [zigpy_deconz.api] 'aps_data_indication' response from <DeconzAddress address_mode=ADDRESS_MODE.NWK address=0xab2f>, ep: 1, profile: 0x0104, cluster_id: 0x0b05, data: b'1c5e10090a01e021df6c'
2021-11-15 22:24:34 ERROR (MainThread) [homeassistant.core] Error executing service: <ServiceCall climate.set_temperature (c:e8d27f07725072b31c3956a2491ded64): target_temp_high=25.0, target_temp_low=23.0, hvac_mode=heat, temperature=25.0, area_id=['office']>
Traceback (most recent call last):
File "/usr/local/lib/python3.9/asyncio/tasks.py", line 492, in wait_for
fut.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/core.py", line 1511, in catch_exceptions
await coro_or_task
File "/usr/src/homeassistant/homeassistant/core.py", line 1530, in _execute_service
await handler.job.target(service_call)
File "/usr/src/homeassistant/homeassistant/helpers/entity_component.py", line 213, in handle_service
await self.hass.helpers.service.entity_service_call(
File "/usr/src/homeassistant/homeassistant/helpers/service.py", line 667, in entity_service_call
future.result() # pop exception if have
File "/usr/src/homeassistant/homeassistant/helpers/entity.py", line 863, in async_request_call
await coro
File "/usr/src/homeassistant/homeassistant/helpers/service.py", line 704, in _handle_entity_call
await result
File "/usr/src/homeassistant/homeassistant/components/climate/__init__.py", line 586, in async_service_temperature_set
await entity.async_set_temperature(**kwargs)
File "/usr/src/homeassistant/homeassistant/components/zha/climate.py", line 474, in async_set_temperature
await self.async_set_hvac_mode(hvac_mode)
File "/usr/src/homeassistant/homeassistant/components/zha/climate.py", line 438, in async_set_hvac_mode
if await self._thrm.async_set_operation_mode(HVAC_MODE_2_SYSTEM[hvac_mode]):
File "/usr/src/homeassistant/homeassistant/components/zha/core/channels/hvac.py", line 243, in async_set_operation_mode
if not await self.write_attributes({"system_mode": mode}):
File "/usr/src/homeassistant/homeassistant/components/zha/core/channels/hvac.py", line 292, in write_attributes
res = await self.cluster.write_attributes(data, **kwargs)
File "/usr/local/lib/python3.9/site-packages/zigpy/zcl/__init__.py", line 378, in write_attributes
result = await self._write_attributes(args, manufacturer=manufacturer)
File "/usr/local/lib/python3.9/site-packages/zigpy/device.py", line 296, in request
result = await asyncio.wait_for(req.result, timeout)
File "/usr/local/lib/python3.9/asyncio/tasks.py", line 494, in wait_for
raise exceptions.TimeoutError() from exc
asyncio.exceptions.TimeoutError
all the while it (mostly) was reporting at least some values back (e.g. current temperature)
I’m using the deCONZ ConBee II as coordinator