I have one of the following in my error logs almost every other minute (HA Yellow, SSD)
i managed to capture some debug logs containing similar errors but couldnt make too much info out of it. Which device is the culprit, is my foremost question.
Would be grateful for practical advice on how to make best use of the logs, what to look for etc.
2024-03-06 20:03:38.845 ERROR (MainThread) [zigpy.zcl] [0x9030:1:0x0020] 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 326, in request
with self._pending.new(sequence) as req:
^^^^^^^^^^^^^^^^^^^^^^^^^^^
File "/usr/local/lib/python3.12/site-packages/zigpy/util.py", line 290, in new
raise ControllerException(f"Duplicate TSN: {sequence}")
zigpy.exceptions.ControllerException: Duplicate TSN: 97
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 634, 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 83, 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 75, in wrap_zigpy_exceptions
raise HomeAssistantError(message) from exc
homeassistant.exceptions.HomeAssistantError: Failed to send request: Duplicate TSN: 97
When debugs is enabled (I dont even know where to start),
2024-03-06 20:02:10.663 DEBUG (MainThread) [bellows.ezsp.protocol] Application frame received incomingMessageHandler: [<EmberIncomingMessageType.INCOMING_UNICAST: 0>, EmberApsFrame(profileId=260, clusterId=32, sourceEndpoint=1, destinationEndpoint=1, options=<EmberApsOption.APS_OPTION_RETRY|APS_OPTION_ENABLE_ROUTE_DISCOVERY: 320>, groupId=0, sequence=144), 172, -57, 0xe196, 255, 255, b'\x19H\x00']
2024-03-06 20:02:10.664 DEBUG (MainThread) [bellows.ezsp.protocol] Frame contains trailing data: b'\x04'
2024-03-06 20:02:10.664 DEBUG (MainThread) [bellows.zigbee.application] Received incomingMessageHandler frame with [<EmberIncomingMessageType.INCOMING_UNICAST: 0>, EmberApsFrame(profileId=260, clusterId=32, sourceEndpoint=1, destinationEndpoint=1, options=<EmberApsOption.APS_OPTION_RETRY|APS_OPTION_ENABLE_ROUTE_DISCOVERY: 320>, groupId=0, sequence=144), 172, -57, 0xe196, 255, 255, b'\x19H\x00']
2024-03-06 20:02:10.664 DEBUG (MainThread) [zigpy.application] Received a packet: ZigbeePacket(timestamp=datetime.datetime(2024, 3, 6, 19, 2, 10, 664779, tzinfo=datetime.timezone.utc), src=AddrModeAddress(addr_mode=<AddrMode.NWK: 2>, address=0xE196), src_ep=1, dst=AddrModeAddress(addr_mode=<AddrMode.NWK: 2>, address=0x0000), dst_ep=1, source_route=None, extended_timeout=False, tsn=144, profile_id=260, cluster_id=32, data=Serialized[b'\x19H\x00'], tx_options=<TransmitOptions.NONE: 0>, radius=0, non_member_radius=0, lqi=172, rssi=-57)
2024-03-06 20:02:10.666 DEBUG (MainThread) [zigpy.zcl] [0xE196:1:0x0020] Received ZCL frame: b'\x19H\x00'
2024-03-06 20:02:10.666 DEBUG (MainThread) [zigpy.zcl] [0xE196:1:0x0020] Decoded ZCL frame header: ZCLHeader(frame_control=FrameControl<0x19>(frame_type=<FrameType.CLUSTER_COMMAND: 1>, is_manufacturer_specific=0, direction=<Direction.Server_to_Client: 1>, disable_default_response=1, reserved=0, *is_cluster=True, *is_general=False), tsn=72, command_id=0, *direction=<Direction.Server_to_Client: 1>)
2024-03-06 20:02:10.669 DEBUG (MainThread) [zigpy.zcl] [0xE196:1:0x0020] Decoded ZCL frame: PollControl:checkin()
2024-03-06 20:02:10.669 DEBUG (MainThread) [zigpy.zcl] [0xE196:1:0x0020] Received command 0x00 (TSN 72): checkin()
2024-03-06 20:02:10.670 DEBUG (MainThread) [zigpy.zcl] [0xE196:1:0x0020] No explicit handler for cluster command 0x00: checkin()
2024-03-06 20:02:10.670 DEBUG (MainThread) [homeassistant.components.zha.core.cluster_handlers] [0xE196:1:0x0020]: Received 72 tsn command 'checkin': checkin()
2024-03-06 20:02:10.676 DEBUG (MainThread) [zigpy.util] Tries remaining: 3
2024-03-06 20:02:10.677 DEBUG (MainThread) [zigpy.zcl] [0xE196:1:0x0020] 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=72, command_id=0, *direction=<Direction.Client_to_Server: 0>)
2024-03-06 20:02:10.678 DEBUG (MainThread) [zigpy.zcl] [0xE196:1:0x0020] Sending request: checkin_response(start_fast_polling=<Bool.true: 1>, fast_poll_timeout=8)
2024-03-06 20:02:10.678 DEBUG (MainThread) [zigpy.device] [0xe196] Extending timeout for 0x48 request
2024-03-06 20:02:10.678 DEBUG (MainThread) [zigpy.util] Duplicate 72 TSN: pending {72: <zigpy.util.Request object at 0x7f55b66360>}
2024-03-06 20:02:10.678 DEBUG (MainThread) [homeassistant.components.zha.core.device] [0xCD6A](LYWSD03MMC): Device seen - marking the device available and resetting counter
2024-03-06 20:02:10.679 DEBUG (MainThread) [homeassistant.components.zha.core.device] [0xCD6A](LYWSD03MMC): Update device availability - device available: True - new availability: True - changed: False
2024-03-06 20:02:10.680 DEBUG (Thread-5) [aiosqlite] executing functools.partial(<built-in method commit of sqlite3.Connection object at 0x7f74fdc220>)
2024-03-06 20:02:10.680 DEBUG (Thread-5) [aiosqlite] operation functools.partial(<built-in method commit of sqlite3.Connection object at 0x7f74fdc220>) completed
2024-03-06 20:02:10.681 DEBUG (MainThread) [homeassistant.components.zha.core.device] [0xC9C0](SML004): Device seen - marking the device available and resetting counter
2024-03-06 20:02:10.681 DEBUG (MainThread) [homeassistant.components.zha.core.device] [0xC9C0](SML004): Update device availability - device available: True - new availability: True - changed: False
2024-03-06 20:02:10.684 DEBUG (MainThread) [homeassistant.components.zha.core.device] [0xD9A2](TRADFRI bulb E27 WW globe 806lm): Device seen - marking the device available and resetting counter
2024-03-06 20:02:10.684 DEBUG (MainThread) [homeassistant.components.zha.core.device] [0xD9A2](TRADFRI bulb E27 WW globe 806lm): Update device availability - device available: True - new availability: True - changed: False
2024-03-06 20:02:10.685 DEBUG (MainThread) [homeassistant.components.zha.core.device] [0x8B0E](TRADFRI on/off switch): Device seen - marking the device available and resetting counter
2024-03-06 20:02:10.685 DEBUG (MainThread) [homeassistant.components.zha.core.device] [0x8B0E](TRADFRI on/off switch): Update device availability - device available: True - new availability: True - changed: False
2024-03-06 20:02:10.686 DEBUG (MainThread) [homeassistant.components.zha.core.device] [0xE923](LST002): Device seen - marking the device available and resetting counter
2024-03-06 20:02:10.686 DEBUG (MainThread) [homeassistant.components.zha.core.device] [0xE923](LST002): Update device availability - device available: True - new availability: True - changed: False
2024-03-06 20:02:10.688 DEBUG (MainThread) [homeassistant.components.zha.core.device] [0xD5CE](TS011F): Device seen - marking the device available and resetting counter
2024-03-06 20:02:10.688 DEBUG (MainThread) [homeassistant.components.zha.core.device] [0xD5CE](TS011F): Update device availability - device available: True - new availability: True - changed: False
2024-03-06 20:02:10.691 DEBUG (Thread-5) [aiosqlite] executing functools.partial(<built-in method execute of sqlite3.Connection object at 0x7f74fdc220>, '\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': a4:c1:38:98:dd:f0:4c:6c, 'endpoint_id': 1, 'cluster_id': 2820, 'attrid': 1291, 'value': 66, 'timestamp': 1709751730.638731, 'min_update_delta': 30.0})
2024-03-06 20:02:10.693 DEBUG (Thread-5) [aiosqlite] operation functools.partial(<built-in method execute of sqlite3.Connection object at 0x7f74fdc220>, '\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': a4:c1:38:98:dd:f0:4c:6c, 'endpoint_id': 1, 'cluster_id': 2820, 'attrid': 1291, 'value': 66, 'timestamp': 1709751730.638731, 'min_update_delta': 30.0}) completed
2024-03-06 20:02:10.694 DEBUG (Thread-5) [aiosqlite] executing functools.partial(<built-in method commit of sqlite3.Connection object at 0x7f74fdc220>)
2024-03-06 20:02:10.694 DEBUG (Thread-5) [aiosqlite] operation functools.partial(<built-in method commit of sqlite3.Connection object at 0x7f74fdc220>) completed
2024-03-06 20:02:10.696 DEBUG (Thread-5) [aiosqlite] executing functools.partial(<built-in method execute of sqlite3.Connection object at 0x7f74fdc220>, 'UPDATE devices_v12\n SET last_seen=:ts\n WHERE ieee=:ieee AND :ts - last_seen > :min_update_delta', {'ts': 1709751730.646077, 'ieee': a4:c1:38:98:dd:f0:4c:6c, 'min_update_delta': 30.0})
2024-03-06 20:02:10.696 DEBUG (Thread-5) [aiosqlite] operation functools.partial(<built-in method execute of sqlite3.Connection object at 0x7f74fdc220>, 'UPDATE devices_v12\n SET last_seen=:ts\n WHERE ieee=:ieee AND :ts - last_seen > :min_update_delta', {'ts': 1709751730.646077, 'ieee': a4:c1:38:98:dd:f0:4c:6c, 'min_update_delta': 30.0}) completed
2024-03-06 20:02:10.697 DEBUG (Thread-5) [aiosqlite] executing functools.partial(<built-in method commit of sqlite3.Connection object at 0x7f74fdc220>)
2024-03-06 20:02:10.698 DEBUG (Thread-5) [aiosqlite] operation functools.partial(<built-in method commit of sqlite3.Connection object at 0x7f74fdc220>) completed
2024-03-06 20:02:10.701 DEBUG (Thread-5) [aiosqlite] executing functools.partial(<built-in method execute of sqlite3.Connection object at 0x7f74fdc220>, '\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': a4:c1:38:98:dd:f0:4c:6c, 'endpoint_id': 1, 'cluster_id': 2820, 'attrid': 1288, 'value': 347, 'timestamp': 1709751730.651369, 'min_update_delta': 30.0})
2024-03-06 20:02:10.702 DEBUG (Thread-5) [aiosqlite] operation functools.partial(<built-in method execute of sqlite3.Connection object at 0x7f74fdc220>, '\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': a4:c1:38:98:dd:f0:4c:6c, 'endpoint_id': 1, 'cluster_id': 2820, 'attrid': 1288, 'value': 347, 'timestamp': 1709751730.651369, 'min_update_delta': 30.0}) completed
2024-03-06 20:02:10.705 DEBUG (Thread-5) [aiosqlite] executing functools.partial(<built-in method commit of sqlite3.Connection object at 0x7f74fdc220>)
2024-03-06 20:02:10.706 DEBUG (Thread-5) [aiosqlite] operation functools.partial(<built-in method commit of sqlite3.Connection object at 0x7f74fdc220>) completed
2024-03-06 20:02:10.708 DEBUG (Thread-5) [aiosqlite] executing functools.partial(<built-in method execute of sqlite3.Connection object at 0x7f74fdc220>, 'UPDATE devices_v12\n SET last_seen=:ts\n WHERE ieee=:ieee AND :ts - last_seen > :min_update_delta', {'ts': 1709751730.664779, 'ieee': 5c:c7:c1:ff:fe:88:4c:7e, 'min_update_delta': 30.0})
2024-03-06 20:02:10.711 DEBUG (Thread-5) [aiosqlite] operation functools.partial(<built-in method execute of sqlite3.Connection object at 0x7f74fdc220>, 'UPDATE devices_v12\n SET last_seen=:ts\n WHERE ieee=:ieee AND :ts - last_seen > :min_update_delta', {'ts': 1709751730.664779, 'ieee': 5c:c7:c1:ff:fe:88:4c:7e, 'min_update_delta': 30.0}) completed
2024-03-06 20:02:10.712 DEBUG (Thread-5) [aiosqlite] executing functools.partial(<built-in method commit of sqlite3.Connection object at 0x7f74fdc220>)
2024-03-06 20:02:10.712 DEBUG (Thread-5) [aiosqlite] operation functools.partial(<built-in method commit of sqlite3.Connection object at 0x7f74fdc220>) completed
2024-03-06 20:02:10.779 DEBUG (MainThread) [zigpy.util] Tries remaining: 2
2024-03-06 20:02:10.780 DEBUG (MainThread) [zigpy.zcl] [0xE196:1:0x0020] 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=72, command_id=0, *direction=<Direction.Client_to_Server: 0>)
2024-03-06 20:02:10.780 DEBUG (MainThread) [zigpy.zcl] [0xE196:1:0x0020] Sending request: checkin_response(start_fast_polling=<Bool.true: 1>, fast_poll_timeout=8)
2024-03-06 20:02:10.781 DEBUG (MainThread) [zigpy.device] [0xe196] Extending timeout for 0x48 request
2024-03-06 20:02:10.781 DEBUG (MainThread) [zigpy.util] Duplicate 72 TSN: pending {72: <zigpy.util.Request object at 0x7f55b66360>}
2024-03-06 20:02:10.882 DEBUG (MainThread) [zigpy.util] Tries remaining: 1
2024-03-06 20:02:10.884 DEBUG (MainThread) [zigpy.zcl] [0xE196:1:0x0020] 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=72, command_id=0, *direction=<Direction.Client_to_Server: 0>)
2024-03-06 20:02:10.886 DEBUG (MainThread) [zigpy.zcl] [0xE196:1:0x0020] Sending request: checkin_response(start_fast_polling=<Bool.true: 1>, fast_poll_timeout=8)
2024-03-06 20:02:10.887 DEBUG (MainThread) [zigpy.device] [0xe196] Extending timeout for 0x48 request
2024-03-06 20:02:10.887 DEBUG (MainThread) [zigpy.util] Duplicate 72 TSN: pending {72: <zigpy.util.Request object at 0x7f55b66360>}
2024-03-06 20:02:10.895 ERROR (MainThread) [zigpy.zcl] [0xE196:1:0x0020] 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 326, in request
with self._pending.new(sequence) as req:
^^^^^^^^^^^^^^^^^^^^^^^^^^^
File "/usr/local/lib/python3.12/site-packages/zigpy/util.py", line 290, in new
raise ControllerException(f"Duplicate TSN: {sequence}")
zigpy.exceptions.ControllerException: Duplicate TSN: 72
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 634, 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 83, 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 75, in wrap_zigpy_exceptions
raise HomeAssistantError(message) from exc
homeassistant.exceptions.HomeAssistantError: Failed to send request: Duplicate TSN: 72
2024-03-06 20:02:10.952 DEBUG (bellows.thread_0) [bellows.uart] Data frame: b'0521b1a9112a15b658904124ab1593499c6e8b6c63369874f5deea83f97b1e45eb349e7e'
2024-03-06 20:02:10.953 DEBUG (bellows.thread_0) [bellows.uart] Sending: b'8160597e'
2024-03-06 20:02:10.957 DEBUG (MainThread) [bellows.ezsp.protocol] Application frame received incomingMessageHandler: [<EmberIncomingMessageType.INCOMING_UNICAST: 0>, EmberApsFrame(profileId=260, clusterId=2820, sourceEndpoint=1, destinationEndpoint=1, options=<EmberApsOption.APS_OPTION_RETRY|APS_OPTION_ENABLE_ROUTE_DISCOVERY: 320>, groupId=0, sequence=32), 172, -57, 0xf88e, 255, 255, b'\x18\x89\n\x05\x05!\xe2\x00']
2024-03-06 20:02:10.958 DEBUG (MainThread) [bellows.zigbee.application] Received incomingMessageHandler frame with [<EmberIncomingMessageType.INCOMING_UNICAST: 0>, EmberApsFrame(profileId=260, clusterId=2820, sourceEndpoint=1, destinationEndpoint=1, options=<EmberApsOption.APS_OPTION_RETRY|APS_OPTION_ENABLE_ROUTE_DISCOVERY: 320>, groupId=0, sequence=32), 172, -57, 0xf88e, 255, 255, b'\x18\x89\n\x05\x05!\xe2\x00']
2024-03-06 20:02:10.958 DEBUG (MainThread) [zigpy.application] Received a packet: ZigbeePacket(timestamp=datetime.datetime(2024, 3, 6, 19, 2, 10, 958800, tzinfo=datetime.timezone.utc), src=AddrModeAddress(addr_mode=<AddrMode.NWK: 2>, address=0xF88E), src_ep=1, dst=AddrModeAddress(addr_mode=<AddrMode.NWK: 2>, address=0x0000), dst_ep=1, source_route=None, extended_timeout=False, tsn=32, profile_id=260, cluster_id=2820, data=Serialized[b'\x18\x89\n\x05\x05!\xe2\x00'], tx_options=<TransmitOptions.NONE: 0>, radius=0, non_member_radius=0, lqi=172, rssi=-57)
2024-03-06 20:02:10.960 DEBUG (MainThread) [zigpy.zcl] [0xF88E:1:0x0b04] Received ZCL frame: b'\x18\x89\n\x05\x05!\xe2\x00'
2024-03-06 20:02:10.962 DEBUG (MainThread) [zigpy.zcl] [0xF88E:1:0x0b04] 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=137, command_id=10, *direction=<Direction.Server_to_Client: 1>)
2024-03-06 20:02:10.963 DEBUG (MainThread) [zigpy.zcl] [0xF88E:1:0x0b04] Decoded ZCL frame: TuyaZBElectricalMeasurement:Report_Attributes(attribute_reports=[Attribute(attrid=0x0505, value=TypeValue(type=uint16_t, value=226))])
2024-03-06 20:02:10.964 DEBUG (MainThread) [zigpy.zcl] [0xF88E:1:0x0b04] Received command 0x0A (TSN 137): Report_Attributes(attribute_reports=[Attribute(attrid=0x0505, value=TypeValue(type=uint16_t, value=226))])
2024-03-06 20:02:10.964 DEBUG (MainThread) [zigpy.zcl] [0xF88E:1:0x0b04] Attribute report received: rms_voltage=226
2024-03-06 20:02:10.964 DEBUG (MainThread) [homeassistant.components.zha.core.cluster_handlers] [0xF88E:1:0x0b04]: cluster_handler[electrical_measurement] attribute_updated - cluster[Electrical Measurement] attr[rms_voltage] value[226]
2024-03-06 20:02:10.967 DEBUG (Thread-5) [aiosqlite] executing functools.partial(<built-in method execute of sqlite3.Connection object at 0x7f74fdc220>, 'UPDATE devices_v12\n SET last_seen=:ts\n WHERE ieee=:ieee AND :ts - last_seen > :min_update_delta', {'ts': 1709751730.9588, 'ieee': a4:c1:38:96:87:fb:67:99, 'min_update_delta': 30.0})
2024-03-06 20:02:10.969 DEBUG (Thread-5) [aiosqlite] operation functools.partial(<built-in method execute of sqlite3.Connection object at 0x7f74fdc220>, 'UPDATE devices_v12\n SET last_seen=:ts\n WHERE ieee=:ieee AND :ts - last_seen > :min_update_delta', {'ts': 1709751730.9588, 'ieee': a4:c1:38:96:87:fb:67:99, 'min_update_delta': 30.0}) completed
2024-03-06 20:02:10.973 DEBUG (Thread-5) [aiosqlite] executing functools.partial(<built-in method commit of sqlite3.Connection object at 0x7f74fdc220>)
2024-03-06 20:02:10.973 DEBUG (Thread-5) [aiosqlite] operation functools.partial(<built-in method commit of sqlite3.Connection object at 0x7f74fdc220>) completed
2024-03-06 20:02:10.976 DEBUG (Thread-5) [aiosqlite] executing functools.partial(<built-in method execute of sqlite3.Connection object at 0x7f74fdc220>, '\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': a4:c1:38:96:87:fb:67:99, 'endpoint_id': 1, 'cluster_id': 2820, 'attrid': 1285, 'value': 226, 'timestamp': 1709751730.964861, 'min_update_delta': 30.0})
2024-03-06 20:02:10.976 DEBUG (Thread-5) [aiosqlite] operation functools.partial(<built-in method execute of sqlite3.Connection object at 0x7f74fdc220>, '\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': a4:c1:38:96:87:fb:67:99, 'endpoint_id': 1, 'cluster_id': 2820, 'attrid': 1285, 'value': 226, 'timestamp': 1709751730.964861, 'min_update_delta': 30.0}) completed
2024-03-06 20:02:10.978 DEBUG (Thread-5) [aiosqlite] executing functools.partial(<built-in method commit of sqlite3.Connection object at 0x7f74fdc220>)
2024-03-06 20:02:10.979 DEBUG (Thread-5) [aiosqlite] operation functools.partial(<built-in method commit of sqlite3.Connection object at 0x7f74fdc220>) completed
2024-03-06 20:02:10.986 DEBUG (bellows.thread_0) [bellows.uart] Data frame: b'1521b5a9902a1e24b8ef1e7e'
2024-03-06 20:02:10.986 DEBUG (bellows.thread_0) [bellows.uart] Sending: b'82503a7e'
2024-03-06 20:02:10.987 DEBUG (MainThread) [bellows.ezsp.protocol] Application frame received changeSourceRouteHandler: [0x960b, 0x00e1, <Bool.false: 0>]
2024-03-06 20:02:10.988 DEBUG (MainThread) [bellows.zigbee.application] Received changeSourceRouteHandler frame with [0x960b, 0x00e1, <Bool.false: 0>]
2024-03-06 20:02:10.991 DEBUG (bellows.thread_0) [bellows.uart] Data frame: b'2521b1a9d42abc24b891487e'
2024-03-06 20:02:10.991 DEBUG (bellows.thread_0) [bellows.uart] Sending: b'83401b7e'
2024-03-06 20:02:10.993 DEBUG (MainThread) [bellows.ezsp.protocol] Application frame received incomingRouteErrorHandler: [<EmberStatus.SOURCE_ROUTE_FAILURE: 169>, 0xe196]
2024-03-06 20:02:10.993 DEBUG (MainThread) [bellows.zigbee.application] Received incomingRouteErrorHandler frame with [<EmberStatus.SOURCE_ROUTE_FAILURE: 169>, 0xe196]
2024-03-06 20:02:10.993 DEBUG (MainThread) [bellows.zigbee.application] Processing route error: status=EmberStatus.SOURCE_ROUTE_FAILURE, nwk=0xe196
2024-03-06 20:02:10.994 DEBUG (Thread-5) [aiosqlite] executing functools.partial(<built-in method execute of sqlite3.Connection object at 0x7f74fdc220>, 'DELETE FROM relays_v12 WHERE ieee = ?', (5c:c7:c1:ff:fe:88:4c:7e,))
2024-03-06 20:02:10.995 DEBUG (Thread-5) [aiosqlite] operation functools.partial(<built-in method execute of sqlite3.Connection object at 0x7f74fdc220>, 'DELETE FROM relays_v12 WHERE ieee = ?', (5c:c7:c1:ff:fe:88:4c:7e,)) completed
2024-03-06 20:02:10.996 DEBUG (Thread-5) [aiosqlite] executing functools.partial(<built-in method commit of sqlite3.Connection object at 0x7f74fdc220>)
2024-03-06 20:02:10.996 DEBUG (Thread-5) [aiosqlite] operation functools.partial(<built-in method commit of sqlite3.Connection object at 0x7f74fdc220>) completed
2024-03-06 20:02:11.511 DEBUG (bellows.thread_0) [bellows.uart] Data frame: b'3521b1a96b2a157270904b27ad5493099d4e271be5ce67a8b97e'
2024-03-06 20:02:11.511 DEBUG (bellows.thread_0) [bellows.uart] Sending: b'8430fc7e'
2024-03-06 20:02:11.513 DEBUG (MainThread) [bellows.ezsp.protocol] Application frame received messageSentHandler: [<EmberOutgoingMessageType.OUTGOING_DIRECT: 0>, 10688, EmberApsFrame(profileId=260, clusterId=1794, sourceEndpoint=1, destinationEndpoint=1, options=<EmberApsOption.APS_OPTION_RETRY|APS_OPTION_ENABLE_ROUTE_DISCOVERY: 320>, groupId=0, sequence=176), 8, <EmberStatus.SUCCESS: 0>, b'']
2024-03-06 20:02:11.513 DEBUG (MainThread) [bellows.zigbee.application] Received messageSentHandler frame with [<EmberOutgoingMessageType.OUTGOING_DIRECT: 0>, 10688, EmberApsFrame(profileId=260, clusterId=1794, sourceEndpoint=1, destinationEndpoint=1, options=<EmberApsOption.APS_OPTION_RETRY|APS_OPTION_ENABLE_ROUTE_DISCOVERY: 320>, groupId=0, sequence=176), 8, <EmberStatus.SUCCESS: 0>, b'']
2024-03-06 20:02:11.517 DEBUG (MainThread) [homeassistant.components.zha.core.cluster_handlers] [0x29C0:1:0x0702]: cluster_handler[smartenergy_metering] attribute_updated - cluster[TuyaZBMeteringCluster] attr[current_summ_delivered] value[1126]
2024-03-06 20:02:11.518 DEBUG (MainThread) [homeassistant.components.zha.core.cluster_handlers] [0x29C0:1:0x0702]: cluster_handler[smartenergy_metering] attribute_updated - cluster[TuyaZBMeteringCluster] attr[status] value[0]
2024-03-06 20:02:11.521 DEBUG (Thread-5) [aiosqlite] executing functools.partial(<built-in method execute of sqlite3.Connection object at 0x7f74fdc220>, '\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': a4:c1:38:98:dd:f0:4c:6c, 'endpoint_id': 1, 'cluster_id': 1794, 'attrid': 0, 'value': 1126, 'timestamp': 1709751731.517241, 'min_update_delta': 30.0})
2024-03-06 20:02:11.522 DEBUG (Thread-5) [aiosqlite] operation functools.partial(<built-in method execute of sqlite3.Connection object at 0x7f74fdc220>, '\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': a4:c1:38:98:dd:f0:4c:6c, 'endpoint_id': 1, 'cluster_id': 1794, 'attrid': 0, 'value': 1126, 'timestamp': 1709751731.517241, 'min_update_delta': 30.0}) completed
2024-03-06 20:02:11.525 DEBUG (Thread-5) [aiosqlite] executing functools.partial(<built-in method commit of sqlite3.Connection object at 0x7f74fdc220>)
2024-03-06 20:02:11.526 DEBUG (Thread-5) [aiosqlite] operation functools.partial(<built-in method commit of sqlite3.Connection object at 0x7f74fdc220>) completed
2024-03-06 20:02:11.529 DEBUG (Thread-5) [aiosqlite] executing functools.partial(<built-in method execute of sqlite3.Connection object at 0x7f74fdc220>, '\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': a4:c1:38:98:dd:f0:4c:6c, 'endpoint_id': 1, 'cluster_id': 1794, 'attrid': 512, 'value': <bitmap8: 0>, 'timestamp': 1709751731.518444, 'min_update_delta': 30.0})
2024-03-06 20:02:11.530 DEBUG (Thread-5) [aiosqlite] operation functools.partial(<built-in method execute of sqlite3.Connection object at 0x7f74fdc220>, '\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': a4:c1:38:98:dd:f0:4c:6c, 'endpoint_id': 1, 'cluster_id': 1794, 'attrid': 512, 'value': <bitmap8: 0>, 'timestamp': 1709751731.518444, 'min_update_delta': 30.0}) completed
2024-03-06 20:02:11.531 DEBUG (Thread-5) [aiosqlite] executing functools.partial(<built-in method commit of sqlite3.Connection object at 0x7f74fdc220>)
2024-03-06 20:02:11.531 DEBUG (Thread-5) [aiosqlite] operation functools.partial(<built-in method commit of sqlite3.Connection object at 0x7f74fdc220>) completed
2024-03-06 20:02:11.847 DEBUG (bellows.thread_0) [bellows.uart] Data frame: b'4521b1a9902a173ca1b5ac7e'
2024-03-06 20:02:11.847 DEBUG (bellows.thread_0) [bellows.uart] Sending: b'8520dd7e'
2024-03-06 20:02:11.849 DEBUG (MainThread) [bellows.ezsp.protocol] Application frame received changeSourceRouteHandler: [0x8e02, 0x00f8, <Bool.false: 0>]
2024-03-06 20:02:11.849 DEBUG (MainThread) [bellows.zigbee.application] Received changeSourceRouteHandler frame with [0x8e02, 0x00f8, <Bool.false: 0>]
2024-03-06 20:02:12.117 DEBUG (bellows.thread_0) [bellows.uart] Data frame: b'5521b5a9902a1e24b8b0c77e'
2024-03-06 20:02:12.117 DEBUG (bellows.thread_0) [bellows.uart] Sending: b'8610be7e'
2024-03-06 20:02:12.119 DEBUG (MainThread) [bellows.ezsp.protocol] Application frame received changeSourceRouteHandler: [0x960b, 0x00e1, <Bool.false: 0>]
Thanks in advance,
Best