Hi,
I am trying to add my Bosch Smoke Alarm devices to ZHA. Using the “manual” way with zha:permit worked for 6 devices. Now I have three more and they fail.
I am not sure, what exactly the problem is, but the devices do not show up in the devices list. I have captured the following traces from trying “zha:permit”. Can anyone give me a hint, what is going wrong?
Thanks and Best Regards,
Tobias
2024-11-16 23:02:21.877 INFO (MainThread) [homeassistant.components.zha.websocket_api] Allowing join for 70:ac:08:ff:fe:65:23:60 device with link key
2024-11-16 23:02:21.878 DEBUG (MainThread) [zigpy_znp.api] Sending request: AppConfig.BDBAddInstallCode.Req(InstallCodeFormat=<InstallCodeFormat.KeyDerivedFromInstallCode: 2>, IEEE=70:ac:08:ff:fe:65:23:60, InstallCode=b'\x4F\x08\xEC\x50\x4F\x15\xBF\x9B\xE0\x83\x12\x58\x96\xBA\x87\x3E')
2024-11-16 23:02:21.894 DEBUG (MainThread) [zigpy_znp.api] Received command: AppConfig.BDBAddInstallCode.Rsp(Status=<Status.SUCCESS: 0>)
2024-11-16 23:02:21.896 DEBUG (MainThread) [zigpy_znp.api] Sending request: AppConfig.BDBSetJoinUsesInstallCodeKey.Req(BdbJoinUsesInstallCodeKey=<Bool.true: 1>)
2024-11-16 23:02:21.902 DEBUG (MainThread) [zigpy_znp.api] Received command: AppConfig.BDBSetJoinUsesInstallCodeKey.Rsp(Status=<Status.SUCCESS: 0>)
2024-11-16 23:02:21.904 INFO (MainThread) [zigpy_znp.zigbee.application] Permitting joins for 60 seconds
2024-11-16 23:02:21.905 DEBUG (MainThread) [zigpy_znp.zigbee.application] Sending packet ZigbeePacket(timestamp=datetime.datetime(2024, 11, 16, 22, 2, 21, 905423, tzinfo=datetime.timezone.utc), priority=<PacketPriority.NORMAL: 0>, src=AddrModeAddress(addr_mode=<AddrMode.NWK: 2>, address=0x0000), src_ep=0, dst=AddrModeAddress(addr_mode=<AddrMode.Broadcast: 15>, address=<BroadcastAddress.ALL_ROUTERS_AND_COORDINATOR: 65532>), dst_ep=0, source_route=None, extended_timeout=False, tsn=18, profile_id=0, cluster_id=<ZDOCmd.Mgmt_Permit_Joining_req: 0x0036>, data=Serialized[b'\x12<\x00'], tx_options=<TransmitOptions.NONE: 0>, radius=0, non_member_radius=0, lqi=None, rssi=None)
2024-11-16 23:02:21.908 DEBUG (MainThread) [zigpy_znp.api] Sending request: ZDO.MgmtPermitJoinReq.Req(AddrMode=<AddrMode.Broadcast: 15>, Dst=0xFFFC, Duration=60, TCSignificance=0)
2024-11-16 23:02:21.931 DEBUG (MainThread) [zigpy_znp.api] Received command: ZDO.MgmtPermitJoinReq.Rsp(Status=<Status.SUCCESS: 0>)
2024-11-16 23:02:21.932 DEBUG (MainThread) [zigpy_znp.api] Received command: ZDO.MgmtPermitJoinRsp.Callback(Src=0x0000, Status=<Status.SUCCESS: 0>)
2024-11-16 23:02:21.934 DEBUG (MainThread) [zigpy_znp.api] Received command: ZDO.MsgCbIncoming.Callback(Src=0x0000, IsBroadcast=<Bool.false: 0>, ClusterId=32822, SecurityUse=0, TSN=31, MacDst=0x0000, Data=b'\x00')
2024-11-16 23:02:21.935 DEBUG (MainThread) [zigpy_znp.api] Sending request: AF.DataRequestExt.Req(DstAddrModeAddress=AddrModeAddress(mode=<AddrMode.Broadcast: 15>, address=0xFFFC), DstEndpoint=0, DstPanId=0x0000, SrcEndpoint=0, ClusterId=54, TSN=18, Options=<TransmitOptions.SUPPRESS_ROUTE_DISC_NETWORK: 32>, Radius=0, Data=b'\x12\x3C\x00')
2024-11-16 23:02:21.939 DEBUG (MainThread) [zigpy.application] Received a packet: ZigbeePacket(timestamp=datetime.datetime(2024, 11, 16, 22, 2, 21, 938995, tzinfo=datetime.timezone.utc), priority=0, src=AddrModeAddress(addr_mode=<AddrMode.NWK: 2>, address=0x0000), src_ep=0, dst=AddrModeAddress(addr_mode=<AddrMode.NWK: 2>, address=0x0000), dst_ep=0, source_route=None, extended_timeout=False, tsn=31, profile_id=0, cluster_id=32822, data=Serialized[b'\x1f\x00'], tx_options=<TransmitOptions.NONE: 0>, radius=0, non_member_radius=0, lqi=None, rssi=None)
2024-11-16 23:02:21.941 DEBUG (MainThread) [zigpy.zdo] [0x0000:zdo] ZDO request ZDOCmd.Mgmt_Permit_Joining_rsp: [<Status.SUCCESS: 0>]
2024-11-16 23:02:21.941 DEBUG (MainThread) [zigpy.zdo] [0x0000:zdo] No handler for ZDO request:ZDOCmd.Mgmt_Permit_Joining_rsp([<Status.SUCCESS: 0>])
2024-11-16 23:02:21.942 DEBUG (Thread-4) [aiosqlite] executing functools.partial(<built-in method execute of sqlite3.Connection object at 0x5517f228>, 'UPDATE devices_v13\n SET last_seen=:ts\n WHERE ieee=:ieee AND :ts - last_seen > :min_update_delta', {'ts': 1731794541.938995, 'ieee': 04:87:27:ff:fe:1e:a3:75, 'min_update_delta': 30.0})
2024-11-16 23:02:21.946 DEBUG (Thread-4) [aiosqlite] operation functools.partial(<built-in method execute of sqlite3.Connection object at 0x5517f228>, 'UPDATE devices_v13\n SET last_seen=:ts\n WHERE ieee=:ieee AND :ts - last_seen > :min_update_delta', {'ts': 1731794541.938995, 'ieee': 04:87:27:ff:fe:1e:a3:75, 'min_update_delta': 30.0}) completed
2024-11-16 23:02:21.948 DEBUG (Thread-4) [aiosqlite] executing functools.partial(<built-in method commit of sqlite3.Connection object at 0x5517f228>)
2024-11-16 23:02:21.950 DEBUG (Thread-4) [aiosqlite] operation functools.partial(<built-in method commit of sqlite3.Connection object at 0x5517f228>) completed
2024-11-16 23:02:21.952 DEBUG (Thread-4) [aiosqlite] executing functools.partial(<built-in method execute of sqlite3.Connection object at 0x5517f228>, 'UPDATE devices_v13\n SET last_seen=:ts\n WHERE ieee=:ieee AND :ts - last_seen > :min_update_delta', {'ts': 1731794541.938995, 'ieee': 04:87:27:ff:fe:1e:a3:75, 'min_update_delta': 30.0})
2024-11-16 23:02:21.954 DEBUG (Thread-4) [aiosqlite] operation functools.partial(<built-in method execute of sqlite3.Connection object at 0x5517f228>, 'UPDATE devices_v13\n SET last_seen=:ts\n WHERE ieee=:ieee AND :ts - last_seen > :min_update_delta', {'ts': 1731794541.938995, 'ieee': 04:87:27:ff:fe:1e:a3:75, 'min_update_delta': 30.0}) completed
2024-11-16 23:02:21.959 DEBUG (Thread-4) [aiosqlite] executing functools.partial(<built-in method commit of sqlite3.Connection object at 0x5517f228>)
2024-11-16 23:02:21.960 DEBUG (Thread-4) [aiosqlite] operation functools.partial(<built-in method commit of sqlite3.Connection object at 0x5517f228>) completed
2024-11-16 23:02:22.098 DEBUG (MainThread) [zigpy_znp.api] Received command: AF.DataRequestExt.Rsp(Status=<Status.SUCCESS: 0>)
2024-11-16 23:02:23.671 DEBUG (MainThread) [zha.decorators] [<Task pending name='sensor_state_poller_8c:65:a3:ff:fe:3d:9e:71-1-2820_PolledElectricalMeasurement' coro=<periodic.<locals>.scheduler.<locals>.wrapper() running at /usr/local/lib/python3.12/site-packages/zha/decorators.py:78> cb=[set.remove()]>] executing periodic task [zha.application.platforms.sensor::PollableSensor._refresh]
2024-11-16 23:02:23.672 DEBUG (MainThread) [zha.application.platforms] 8c:65:a3:ff:fe:3d:9e:71-1-2820: skipping polling for updated state, available: False, allow polled requests: True
2024-11-16 23:02:24.471 DEBUG (MainThread) [zigpy_znp.api] Received command: ZDO.SrcRtgInd.Callback(DstAddr=0xE677, Relays=[])
2024-11-16 23:02:24.474 DEBUG (Thread-4) [aiosqlite] executing functools.partial(<built-in method execute of sqlite3.Connection object at 0x5517f228>, 'INSERT INTO relays_v13 VALUES (:ieee, :relays)\n ON CONFLICT (ieee)\n DO UPDATE SET relays=excluded.relays WHERE relays != :relays', {'ieee': 90:fd:9f:ff:fe:65:07:af, 'relays': b'\x00'})
2024-11-16 23:02:24.478 DEBUG (Thread-4) [aiosqlite] operation functools.partial(<built-in method execute of sqlite3.Connection object at 0x5517f228>, 'INSERT INTO relays_v13 VALUES (:ieee, :relays)\n ON CONFLICT (ieee)\n DO UPDATE SET relays=excluded.relays WHERE relays != :relays', {'ieee': 90:fd:9f:ff:fe:65:07:af, 'relays': b'\x00'}) completed
2024-11-16 23:02:24.482 DEBUG (Thread-4) [aiosqlite] executing functools.partial(<built-in method commit of sqlite3.Connection object at 0x5517f228>)
2024-11-16 23:02:24.483 DEBUG (Thread-4) [aiosqlite] operation functools.partial(<built-in method commit of sqlite3.Connection object at 0x5517f228>) completed
2024-11-16 23:02:24.536 DEBUG (MainThread) [zigpy_znp.api] Received command: AF.IncomingMsg.Callback(GroupId=0x0000, ClusterId=768, SrcAddr=0xE677, SrcEndpoint=1, DstEndpoint=1, WasBroadcast=<Bool.false: 0>, LQI=69, SecurityUse=<Bool.false: 0>, TimeStamp=6140778, TSN=0, Data=b'\x08\x30\x0A\x00\x00\x20\xD3\x01\x00\x20\xFE\x03\x00\x21\x0E\x65\x04\x00\x21\x83\x2B\x07\x00\x21\x0A\x01', MacSrcAddr=0xE677, MsgResultRadius=29)
2024-11-16 23:02:24.540 DEBUG (MainThread) [zigpy.application] Received a packet: ZigbeePacket(timestamp=datetime.datetime(2024, 11, 16, 22, 2, 24, 540011, tzinfo=datetime.timezone.utc), priority=0, src=AddrModeAddress(addr_mode=<AddrMode.NWK: 2>, address=0xE677), src_ep=1, dst=AddrModeAddress(addr_mode=<AddrMode.NWK: 2>, address=0x0000), dst_ep=1, source_route=None, extended_timeout=False, tsn=0, profile_id=260, cluster_id=768, data=Serialized[b'\x080\n\x00\x00 \xd3\x01\x00 \xfe\x03\x00!\x0ee\x04\x00!\x83+\x07\x00!\n\x01'], tx_options=<TransmitOptions.NONE: 0>, radius=29, non_member_radius=0, lqi=69, rssi=None)
2024-11-16 23:02:24.543 DEBUG (MainThread) [zigpy.zcl] [0xE677:1:0x0300] Received ZCL frame: b'\x080\n\x00\x00 \xd3\x01\x00 \xfe\x03\x00!\x0ee\x04\x00!\x83+\x07\x00!\n\x01'
2024-11-16 23:02:24.545 DEBUG (MainThread) [zigpy.zcl] [0xE677:1:0x0300] Decoded ZCL frame header: ZCLHeader(frame_control=FrameControl<0x08>(frame_type=<FrameType.GLOBAL_COMMAND: 0>, is_manufacturer_specific=0, direction=<Direction.Server_to_Client: 1>, disable_default_response=0, reserved=0, *is_cluster=False, *is_general=True), tsn=48, command_id=10, *direction=<Direction.Server_to_Client: 1>)
2024-11-16 23:02:24.551 DEBUG (MainThread) [zigpy.zcl] [0xE677:1:0x0300] Decoded ZCL frame: Color:Report_Attributes(attribute_reports=[Attribute(attrid=0x0000, value=TypeValue(type=uint8_t, value=211)), Attribute(attrid=0x0001, value=TypeValue(type=uint8_t, value=254)), Attribute(attrid=0x0003, value=TypeValue(type=uint16_t, value=25870)), Attribute(attrid=0x0004, value=TypeValue(type=uint16_t, value=11139)), Attribute(attrid=0x0007, value=TypeValue(type=uint16_t, value=266))])
2024-11-16 23:02:24.554 DEBUG (MainThread) [zigpy.zcl] [0xE677:1:0x0300] Received command 0x0A (TSN 48): Report_Attributes(attribute_reports=[Attribute(attrid=0x0000, value=TypeValue(type=uint8_t, value=211)), Attribute(attrid=0x0001, value=TypeValue(type=uint8_t, value=254)), Attribute(attrid=0x0003, value=TypeValue(type=uint16_t, value=25870)), Attribute(attrid=0x0004, value=TypeValue(type=uint16_t, value=11139)), Attribute(attrid=0x0007, value=TypeValue(type=uint16_t, value=266))])
2024-11-16 23:02:24.558 DEBUG (MainThread) [zigpy.zcl] [0xE677:1:0x0300] Attribute report received: current_hue=211, current_saturation=254, current_x=25870, current_y=11139, color_temperature=266
2024-11-16 23:02:24.559 DEBUG (MainThread) [zha.zigbee.cluster_handlers] [0xE677:1:0x0300]: cluster_handler[light_color] attribute_updated - cluster[Color Control] attr[current_hue] value[211]
2024-11-16 23:02:24.559 DEBUG (MainThread) [zha] Emitting event cluster_handler_attribute_updated with data ClusterAttributeUpdatedEvent(attribute_id=0, attribute_name='current_hue', attribute_value=211, cluster_handler_unique_id='90:fd:9f:ff:fe:65:07:af:1:0x0300', cluster_id=768, event_type='cluster_handler_event', event='cluster_handler_attribute_updated') (1 listeners)
2024-11-16 23:02:24.560 DEBUG (MainThread) [zha.zigbee.cluster_handlers] [0xE677:1:0x0300]: cluster_handler[light_color] attribute_updated - cluster[Color Control] attr[current_saturation] value[254]
2024-11-16 23:02:24.560 DEBUG (MainThread) [zha] Emitting event cluster_handler_attribute_updated with data ClusterAttributeUpdatedEvent(attribute_id=1, attribute_name='current_saturation', attribute_value=254, cluster_handler_unique_id='90:fd:9f:ff:fe:65:07:af:1:0x0300', cluster_id=768, event_type='cluster_handler_event', event='cluster_handler_attribute_updated') (1 listeners)
2024-11-16 23:02:24.560 DEBUG (MainThread) [zha.zigbee.cluster_handlers] [0xE677:1:0x0300]: cluster_handler[light_color] attribute_updated - cluster[Color Control] attr[current_x] value[25870]
2024-11-16 23:02:24.561 DEBUG (MainThread) [zha] Emitting event cluster_handler_attribute_updated with data ClusterAttributeUpdatedEvent(attribute_id=3, attribute_name='current_x', attribute_value=25870, cluster_handler_unique_id='90:fd:9f:ff:fe:65:07:af:1:0x0300', cluster_id=768, event_type='cluster_handler_event', event='cluster_handler_attribute_updated') (1 listeners)
2024-11-16 23:02:24.561 DEBUG (MainThread) [zha.zigbee.cluster_handlers] [0xE677:1:0x0300]: cluster_handler[light_color] attribute_updated - cluster[Color Control] attr[current_y] value[11139]
2024-11-16 23:02:24.561 DEBUG (MainThread) [zha] Emitting event cluster_handler_attribute_updated with data ClusterAttributeUpdatedEvent(attribute_id=4, attribute_name='current_y', attribute_value=11139, cluster_handler_unique_id='90:fd:9f:ff:fe:65:07:af:1:0x0300', cluster_id=768, event_type='cluster_handler_event', event='cluster_handler_attribute_updated') (1 listeners)
2024-11-16 23:02:24.562 DEBUG (MainThread) [zha.zigbee.cluster_handlers] [0xE677:1:0x0300]: cluster_handler[light_color] attribute_updated - cluster[Color Control] attr[color_temperature] value[266]
2024-11-16 23:02:24.562 DEBUG (MainThread) [zha] Emitting event cluster_handler_attribute_updated with data ClusterAttributeUpdatedEvent(attribute_id=7, attribute_name='color_temperature', attribute_value=266, cluster_handler_unique_id='90:fd:9f:ff:fe:65:07:af:1:0x0300', cluster_id=768, event_type='cluster_handler_event', event='cluster_handler_attribute_updated') (1 listeners)
2024-11-16 23:02:24.564 DEBUG (MainThread) [zigpy.zcl] [0xE677:1:0x0300] Sending reply header: ZCLHeader(frame_control=FrameControl<0x10>(frame_type=<FrameType.GLOBAL_COMMAND: 0>, is_manufacturer_specific=False, direction=<Direction.Client_to_Server: 0>, disable_default_response=1, reserved=0, *is_cluster=False, *is_general=True), tsn=48, command_id=<GeneralCommand.Default_Response: 11>, *direction=<Direction.Client_to_Server: 0>)
2024-11-16 23:02:24.566 DEBUG (MainThread) [zigpy.zcl] [0xE677:1:0x0300] Sending reply: Default_Response(command_id=10, status=<Status.SUCCESS: 0>)
2024-11-16 23:02:24.567 DEBUG (MainThread) [zigpy_znp.zigbee.application] Sending packet ZigbeePacket(timestamp=datetime.datetime(2024, 11, 16, 22, 2, 24, 567265, tzinfo=datetime.timezone.utc), priority=<PacketPriority.LOW: -1>, src=AddrModeAddress(addr_mode=<AddrMode.NWK: 2>, address=0x0000), src_ep=1, dst=AddrModeAddress(addr_mode=<AddrMode.NWK: 2>, address=0xE677), dst_ep=1, source_route=None, extended_timeout=False, tsn=48, profile_id=260, cluster_id=768, data=Serialized[b'\x100\x0b\n\x00'], tx_options=<TransmitOptions.ACK: 1>, radius=0, non_member_radius=0, lqi=None, rssi=None)
2024-11-16 23:02:24.568 DEBUG (Thread-4) [aiosqlite] executing functools.partial(<built-in method execute of sqlite3.Connection object at 0x5517f228>, 'UPDATE devices_v13\n SET last_seen=:ts\n WHERE ieee=:ieee AND :ts - last_seen > :min_update_delta', {'ts': 1731794544.540011, 'ieee': 90:fd:9f:ff:fe:65:07:af, 'min_update_delta': 30.0})
2024-11-16 23:02:24.569 DEBUG (MainThread) [zigpy_znp.api] Sending request: AF.DataRequestExt.Req(DstAddrModeAddress=AddrModeAddress(mode=<AddrMode.NWK: 2>, address=0xE677), DstEndpoint=1, DstPanId=0x0000, SrcEndpoint=1, ClusterId=768, TSN=48, Options=<TransmitOptions.ACK_REQUEST|SUPPRESS_ROUTE_DISC_NETWORK: 48>, Radius=0, Data=b'\x10\x30\x0B\x0A\x00')
2024-11-16 23:02:24.579 DEBUG (Thread-4) [aiosqlite] operation functools.partial(<built-in method execute of sqlite3.Connection object at 0x5517f228>, 'UPDATE devices_v13\n SET last_seen=:ts\n WHERE ieee=:ieee AND :ts - last_seen > :min_update_delta', {'ts': 1731794544.540011, 'ieee': 90:fd:9f:ff:fe:65:07:af, 'min_update_delta': 30.0}) completed
2024-11-16 23:02:24.583 DEBUG (Thread-4) [aiosqlite] executing functools.partial(<built-in method commit of sqlite3.Connection object at 0x5517f228>)
2024-11-16 23:02:24.583 DEBUG (Thread-4) [aiosqlite] operation functools.partial(<built-in method commit of sqlite3.Connection object at 0x5517f228>) completed
2024-11-16 23:02:24.586 DEBUG (Thread-4) [aiosqlite] executing functools.partial(<built-in method execute of sqlite3.Connection object at 0x5517f228>, '\n INSERT INTO attributes_cache_v13\n VALUES (:ieee, :endpoint_id, :cluster_type, :cluster_id, :attr_id, :value, :timestamp)\n ON CONFLICT (ieee, endpoint_id, cluster_type, cluster_id, attr_id) 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': 90:fd:9f:ff:fe:65:07:af, 'endpoint_id': 1, 'cluster_type': <ClusterType.Server: 0>, 'cluster_id': 768, 'attr_id': 0, 'value': 211, 'timestamp': 1731794544.558983, 'min_update_delta': 30.0})
2024-11-16 23:02:24.587 DEBUG (Thread-4) [aiosqlite] operation functools.partial(<built-in method execute of sqlite3.Connection object at 0x5517f228>, '\n INSERT INTO attributes_cache_v13\n VALUES (:ieee, :endpoint_id, :cluster_type, :cluster_id, :attr_id, :value, :timestamp)\n ON CONFLICT (ieee, endpoint_id, cluster_type, cluster_id, attr_id) 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': 90:fd:9f:ff:fe:65:07:af, 'endpoint_id': 1, 'cluster_type': <ClusterType.Server: 0>, 'cluster_id': 768, 'attr_id': 0, 'value': 211, 'timestamp': 1731794544.558983, 'min_update_delta': 30.0}) completed
2024-11-16 23:02:24.590 DEBUG (MainThread) [zigpy_znp.api] Received command: AF.DataRequestExt.Rsp(Status=<Status.SUCCESS: 0>)
2024-11-16 23:02:24.593 DEBUG (Thread-4) [aiosqlite] executing functools.partial(<built-in method commit of sqlite3.Connection object at 0x5517f228>)
2024-11-16 23:02:24.596 DEBUG (Thread-4) [aiosqlite] operation functools.partial(<built-in method commit of sqlite3.Connection object at 0x5517f228>) completed
2024-11-16 23:02:24.600 DEBUG (Thread-4) [aiosqlite] executing functools.partial(<built-in method execute of sqlite3.Connection object at 0x5517f228>, '\n INSERT INTO attributes_cache_v13\n VALUES (:ieee, :endpoint_id, :cluster_type, :cluster_id, :attr_id, :value, :timestamp)\n ON CONFLICT (ieee, endpoint_id, cluster_type, cluster_id, attr_id) 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': 90:fd:9f:ff:fe:65:07:af, 'endpoint_id': 1, 'cluster_type': <ClusterType.Server: 0>, 'cluster_id': 768, 'attr_id': 1, 'value': 254, 'timestamp': 1731794544.559977, 'min_update_delta': 30.0})
2024-11-16 23:02:24.607 DEBUG (Thread-4) [aiosqlite] operation functools.partial(<built-in method execute of sqlite3.Connection object at 0x5517f228>, '\n INSERT INTO attributes_cache_v13\n VALUES (:ieee, :endpoint_id, :cluster_type, :cluster_id, :attr_id, :value, :timestamp)\n ON CONFLICT (ieee, endpoint_id, cluster_type, cluster_id, attr_id) 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': 90:fd:9f:ff:fe:65:07:af, 'endpoint_id': 1, 'cluster_type': <ClusterType.Server: 0>, 'cluster_id': 768, 'attr_id': 1, 'value': 254, 'timestamp': 1731794544.559977, 'min_update_delta': 30.0}) completed
2024-11-16 23:02:24.610 DEBUG (MainThread) [zigpy_znp.api] Received command: ZDO.SrcRtgInd.Callback(DstAddr=0xE677, Relays=[])
2024-11-16 23:02:24.612 DEBUG (Thread-4) [aiosqlite] executing functools.partial(<built-in method commit of sqlite3.Connection object at 0x5517f228>)
2024-11-16 23:02:24.614 DEBUG (Thread-4) [aiosqlite] operation functools.partial(<built-in method commit of sqlite3.Connection object at 0x5517f228>) completed
2024-11-16 23:02:24.616 DEBUG (Thread-4) [aiosqlite] executing functools.partial(<built-in method execute of sqlite3.Connection object at 0x5517f228>, '\n INSERT INTO attributes_cache_v13\n VALUES (:ieee, :endpoint_id, :cluster_type, :cluster_id, :attr_id, :value, :timestamp)\n ON CONFLICT (ieee, endpoint_id, cluster_type, cluster_id, attr_id) 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': 90:fd:9f:ff:fe:65:07:af, 'endpoint_id': 1, 'cluster_type': <ClusterType.Server: 0>, 'cluster_id': 768, 'attr_id': 3, 'value': 25870, 'timestamp': 1731794544.560676, 'min_update_delta': 30.0})
2024-11-16 23:02:24.617 DEBUG (Thread-4) [aiosqlite] operation functools.partial(<built-in method execute of sqlite3.Connection object at 0x5517f228>, '\n INSERT INTO attributes_cache_v13\n VALUES (:ieee, :endpoint_id, :cluster_type, :cluster_id, :attr_id, :value, :timestamp)\n ON CONFLICT (ieee, endpoint_id, cluster_type, cluster_id, attr_id) 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': 90:fd:9f:ff:fe:65:07:af, 'endpoint_id': 1, 'cluster_type': <ClusterType.Server: 0>, 'cluster_id': 768, 'attr_id': 3, 'value': 25870, 'timestamp': 1731794544.560676, 'min_update_delta': 30.0}) completed
2024-11-16 23:02:24.620 DEBUG (Thread-4) [aiosqlite] executing functools.partial(<built-in method commit of sqlite3.Connection object at 0x5517f228>)
2024-11-16 23:02:24.622 DEBUG (Thread-4) [aiosqlite] operation functools.partial(<built-in method commit of sqlite3.Connection object at 0x5517f228>) completed
2024-11-16 23:02:24.624 DEBUG (Thread-4) [aiosqlite] executing functools.partial(<built-in method execute of sqlite3.Connection object at 0x5517f228>, '\n INSERT INTO attributes_cache_v13\n VALUES (:ieee, :endpoint_id, :cluster_type, :cluster_id, :attr_id, :value, :timestamp)\n ON CONFLICT (ieee, endpoint_id, cluster_type, cluster_id, attr_id) 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': 90:fd:9f:ff:fe:65:07:af, 'endpoint_id': 1, 'cluster_type': <ClusterType.Server: 0>, 'cluster_id': 768, 'attr_id': 4, 'value': 11139, 'timestamp': 1731794544.561343, 'min_update_delta': 30.0})
2024-11-16 23:02:24.626 DEBUG (Thread-4) [aiosqlite] operation functools.partial(<built-in method execute of sqlite3.Connection object at 0x5517f228>, '\n INSERT INTO attributes_cache_v13\n VALUES (:ieee, :endpoint_id, :cluster_type, :cluster_id, :attr_id, :value, :timestamp)\n ON CONFLICT (ieee, endpoint_id, cluster_type, cluster_id, attr_id) 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': 90:fd:9f:ff:fe:65:07:af, 'endpoint_id': 1, 'cluster_type': <ClusterType.Server: 0>, 'cluster_id': 768, 'attr_id': 4, 'value': 11139, 'timestamp': 1731794544.561343, 'min_update_delta': 30.0}) completed
2024-11-16 23:02:24.628 DEBUG (Thread-4) [aiosqlite] executing functools.partial(<built-in method commit of sqlite3.Connection object at 0x5517f228>)
2024-11-16 23:02:24.630 DEBUG (Thread-4) [aiosqlite] operation functools.partial(<built-in method commit of sqlite3.Connection object at 0x5517f228>) completed
2024-11-16 23:02:24.632 DEBUG (Thread-4) [aiosqlite] executing functools.partial(<built-in method execute of sqlite3.Connection object at 0x5517f228>, '\n INSERT INTO attributes_cache_v13\n VALUES (:ieee, :endpoint_id, :cluster_type, :cluster_id, :attr_id, :value, :timestamp)\n ON CONFLICT (ieee, endpoint_id, cluster_type, cluster_id, attr_id) 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': 90:fd:9f:ff:fe:65:07:af, 'endpoint_id': 1, 'cluster_type': <ClusterType.Server: 0>, 'cluster_id': 768, 'attr_id': 7, 'value': 266, 'timestamp': 1731794544.562001, 'min_update_delta': 30.0})
2024-11-16 23:02:24.634 DEBUG (Thread-4) [aiosqlite] operation functools.partial(<built-in method execute of sqlite3.Connection object at 0x5517f228>, '\n INSERT INTO attributes_cache_v13\n VALUES (:ieee, :endpoint_id, :cluster_type, :cluster_id, :attr_id, :value, :timestamp)\n ON CONFLICT (ieee, endpoint_id, cluster_type, cluster_id, attr_id) 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': 90:fd:9f:ff:fe:65:07:af, 'endpoint_id': 1, 'cluster_type': <ClusterType.Server: 0>, 'cluster_id': 768, 'attr_id': 7, 'value': 266, 'timestamp': 1731794544.562001, 'min_update_delta': 30.0}) completed
2024-11-16 23:02:24.636 DEBUG (Thread-4) [aiosqlite] executing functools.partial(<built-in method commit of sqlite3.Connection object at 0x5517f228>)
2024-11-16 23:02:24.638 DEBUG (Thread-4) [aiosqlite] operation functools.partial(<built-in method commit of sqlite3.Connection object at 0x5517f228>) completed
2024-11-16 23:02:24.640 DEBUG (Thread-4) [aiosqlite] executing functools.partial(<built-in method execute of sqlite3.Connection object at 0x5517f228>, 'INSERT INTO relays_v13 VALUES (:ieee, :relays)\n ON CONFLICT (ieee)\n DO UPDATE SET relays=excluded.relays WHERE relays != :relays', {'ieee': 90:fd:9f:ff:fe:65:07:af, 'relays': b'\x00'})
2024-11-16 23:02:24.642 DEBUG (Thread-4) [aiosqlite] operation functools.partial(<built-in method execute of sqlite3.Connection object at 0x5517f228>, 'INSERT INTO relays_v13 VALUES (:ieee, :relays)\n ON CONFLICT (ieee)\n DO UPDATE SET relays=excluded.relays WHERE relays != :relays', {'ieee': 90:fd:9f:ff:fe:65:07:af, 'relays': b'\x00'}) completed
2024-11-16 23:02:24.644 DEBUG (Thread-4) [aiosqlite] executing functools.partial(<built-in method commit of sqlite3.Connection object at 0x5517f228>)
2024-11-16 23:02:24.645 DEBUG (Thread-4) [aiosqlite] operation functools.partial(<built-in method commit of sqlite3.Connection object at 0x5517f228>) completed
2024-11-16 23:02:24.657 DEBUG (MainThread) [zigpy_znp.api] Received command: AF.DataConfirm.Callback(Status=<Status.SUCCESS: 0>, Endpoint=1, TSN=48)
2024-11-16 23:02:28.866 DEBUG (MainThread) [zha.decorators] [<Task pending name='global-updater_GlobalUpdater' coro=<periodic.<locals>.scheduler.<locals>.wrapper() running at /usr/local/lib/python3.12/site-packages/zha/decorators.py:78> cb=[set.remove()]>] executing periodic task [zha.application.helpers::GlobalUpdater.update_listeners]