Skip to content
New issue

Have a question about this project? Sign up for a free GitHub account to open an issue and contact its maintainers and the community.

Sign up for GitHub

By clicking “Sign up for GitHub”, you agree to our terms of service and privacy statement. We’ll occasionally send you account related emails.

Already on GitHub? Sign in to your account

Jump to bottom

ZHA: Offline devices recognized as on every 4 hours #80519

Closed
steffen890 opened this issue Oct 18, 2022 · 13 comments · Fixed by zigpy/zigpy#1082
Closed

ZHA: Offline devices recognized as on every 4 hours #80519

steffen890 opened this issue Oct 18, 2022 · 13 comments · Fixed by zigpy/zigpy#1082
Assignees
@dmulcahey @Adminiuga @puddly
Labels
integration: zha

Comments

@steffen890
Copy link

steffen890 commented Oct 18, 2022 •
edited by Quentame
Loading

The problem

Hi,

I have a few IKEA bulbs which switches from unavilable to on every 4 hours, while they are still turned off by the wall switch. This happens simultanously for all unavailable devices. After five minutes they switch back to unavailable.

I would like to resolve issue this since I use this event (unavailable / on) for triggering other lights.

Thanks
Steffen

What version of Home Assistant Core has the issue?

core-2022.10.4

What was the last working version of Home Assistant Core?

No response

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

No response

Example YAML snippet

No response

Anything in the logs that might be useful for us?

No response

Additional information

Zigbee coordinator is "Texas Instruments Z-Stack ZNP protocol: CC253x, CC26x2, CC13x2".
@home-assistant
Copy link

Hey there @dmulcahey, @Adminiuga, @puddly, 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!
(message by CodeOwnersMention)

zha documentation
zha source
(message by IssueLinks)

@dmulcahey
Copy link
Contributor

Can you enable full debug logging (instructions in the zha docs) and capture logs. Please share them without filtering them in any way.

@steffen890
Copy link
Author

steffen890 commented Oct 18, 2022 •
edited
Loading

Here are the logs from today, which were already recorded with my current log settings (didn't checked how to enable full debug logging until now). I hope that they are also helpful. The IKEA bulb was offline all the time.

The affected device is:

IEEE: 04:cd:15:ff:fe:8c:ae:a9
Nwk: 0x5340

2022-10-18 14:35:28.244 DEBUG (MainThread) [zigpy.topology] Scanning neighbors of 04:cd:15:ff:fe:8c:ae:a9/0x5340 device
2022-10-18 14:35:28.245 DEBUG (MainThread) [zigpy.util] Tries remaining: 3
2022-10-18 14:35:28.246 DEBUG (MainThread) [zigpy_znp.zigbee.application] Sending packet ZigbeePacket(src=AddrModeAddress(addr_mode=<AddrMode.NWK: 2>, address=0x0000), src_ep=0, dst=AddrModeAddress(addr_mode=<AddrMode.NWK: 2>, address=0x5340), dst_ep=0, source_route=None, extended_timeout=False, tsn=235, profile_id=0, cluster_id=<ZDOCmd.Mgmt_Lqi_req: 0x0031>, data=Serialized[b'\xeb\x00'], tx_options=<TransmitOptions.ACK: 1>, radius=0, non_member_radius=0, lqi=None, rssi=None)
2022-10-18 14:35:28.249 DEBUG (MainThread) [zigpy_znp.api] Sending request: ZDO.ExtRouteChk.Req(Dst=0x5340, RtStatus=<RouteStatus.ACTIVE: 1>, Options=<RouteOptions.NO_ROUTE_CACHE|MTO_ROUTE: 3>)
2022-10-18 14:35:28.264 DEBUG (MainThread) [zigpy_znp.api] Received command: ZDO.ExtRouteChk.Rsp(Status=<RoutingStatus.FAIL: 1>)
2022-10-18 14:35:28.266 DEBUG (MainThread) [zigpy_znp.api] Sending request: ZDO.ExtRouteDisc.Req(Dst=0x5340, Options=<RouteDiscoveryOptions.UNICAST: 0>, Radius=30)
2022-10-18 14:35:28.284 DEBUG (MainThread) [zigpy_znp.api] Received command: ZDO.ExtRouteDisc.Rsp(Status=<Status.SUCCESS: 0>)
2022-10-18 14:35:29.591 DEBUG (MainThread) [zigpy_znp.api] Sending request: AF.DataRequestExt.Req(DstAddrModeAddress=AddrModeAddress(mode=<AddrMode.NWK: 2>, address=0x5340), DstEndpoint=0, DstPanId=0x0000, SrcEndpoint=0, ClusterId=49, TSN=235, Options=<TransmitOptions.SUPPRESS_ROUTE_DISC_NETWORK|ACK_REQUEST: 48>, Radius=0, Data=b'\xEB\x00')
2022-10-18 14:35:29.614 DEBUG (MainThread) [zigpy_znp.api] Received command: AF.DataRequestExt.Rsp(Status=<Status.SUCCESS: 0>)
2022-10-18 14:35:31.543 DEBUG (MainThread) [zigpy_znp.api] Received command: ZDO.SrcRtgInd.Callback(DstAddr=0x00B1, Relays=[0xFA52])
2022-10-18 14:35:31.605 DEBUG (MainThread) [zigpy_znp.api] Received command: AF.IncomingMsg.Callback(GroupId=0x0000, ClusterId=1280, SrcAddr=0x00B1, SrcEndpoint=1, DstEndpoint=1, WasBroadcast=<Bool.false: 0>, LQI=36, SecurityUse=<Bool.false: 0>, TimeStamp=12310741, TSN=0, Data=b'\x09\x3A\x00\x21\x00\x00\x00\x00\x00', MacSrcAddr=0xFA52, MsgResultRadius=28)
2022-10-18 14:35:31.610 DEBUG (MainThread) [zigpy.application] Received a packet: ZigbeePacket(src=AddrModeAddress(addr_mode=<AddrMode.NWK: 2>, address=0x00B1), 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=1280, data=Serialized[b'\t:\x00!\x00\x00\x00\x00\x00'], tx_options=<TransmitOptions.NONE: 0>, radius=28, non_member_radius=0, lqi=36, rssi=None)
2022-10-18 14:35:31.612 DEBUG (MainThread) [zigpy.zcl] [0x00B1:1:0x0500] Received ZCL frame: b'\t:\x00!\x00\x00\x00\x00\x00'
2022-10-18 14:35:31.616 DEBUG (MainThread) [zigpy.zcl] [0x00B1:1:0x0500] Decoded ZCL frame header: ZCLHeader(frame_control=FrameControl(frame_type=<FrameType.CLUSTER_COMMAND: 1>, is_manufacturer_specific=0, direction=<Direction.Client_to_Server: 1>, disable_default_response=0, reserved=0, *is_cluster=True, *is_general=False, *is_reply=True), tsn=58, command_id=0, *direction=<Direction.Client_to_Server: 1>, *is_reply=True)
2022-10-18 14:35:31.619 DEBUG (MainThread) [zigpy.zcl] [0x00B1:1:0x0500] Decoded ZCL frame: IasZone:status_change_notification(zone_status=<ZoneStatus.Restore_reports|Alarm_1: 33>, extended_status=<bitmap8.0: 0>, zone_id=0, delay=0)
2022-10-18 14:35:31.621 DEBUG (MainThread) [zigpy.zcl] [0x00B1:1:0x0500] Received command 0x00 (TSN 58): status_change_notification(zone_status=<ZoneStatus.Restore_reports|Alarm_1: 33>, extended_status=<bitmap8.0: 0>, zone_id=0, delay=0)
2022-10-18 14:35:31.624 DEBUG (MainThread) [homeassistant.components.zha.core.channels.base] [0x00B1:1:0x0500]: Updated alarm state: ZoneStatus.Alarm_1
2022-10-18 14:35:31.629 DEBUG (MainThread) [zigpy.zcl] [0x00B1:1:0x0500] Sending reply header: ZCLHeader(frame_control=FrameControl(frame_type=<FrameType.GLOBAL_COMMAND: 0>, is_manufacturer_specific=False, direction=<Direction.Client_to_Server: 1>, disable_default_response=1, reserved=0, *is_cluster=False, *is_general=True, *is_reply=True), tsn=58, command_id=<GeneralCommand.Default_Response: 11>, *direction=<Direction.Client_to_Server: 1>, *is_reply=True)
2022-10-18 14:35:31.630 DEBUG (MainThread) [zigpy.zcl] [0x00B1:1:0x0500] Sending reply: Default_Response(command_id=0, status=<Status.SUCCESS: 0>)
2022-10-18 14:35:31.631 DEBUG (MainThread) [zigpy_znp.zigbee.application] Sending packet ZigbeePacket(src=AddrModeAddress(addr_mode=<AddrMode.NWK: 2>, address=0x0000), src_ep=1, dst=AddrModeAddress(addr_mode=<AddrMode.NWK: 2>, address=0x00B1), dst_ep=1, source_route=None, extended_timeout=False, tsn=58, profile_id=260, cluster_id=1280, data=Serialized[b'\x18:\x0b\x00\x00'], tx_options=<TransmitOptions.NONE: 0>, radius=0, non_member_radius=0, lqi=None, rssi=None)
2022-10-18 14:35:31.635 DEBUG (MainThread) [zigpy_znp.api] Sending request: AF.DataRequestExt.Req(DstAddrModeAddress=AddrModeAddress(mode=<AddrMode.NWK: 2>, address=0x00B1), DstEndpoint=1, DstPanId=0x0000, SrcEndpoint=1, ClusterId=1280, TSN=58, Options=<TransmitOptions.SUPPRESS_ROUTE_DISC_NETWORK: 32>, Radius=0, Data=b'\x18\x3A\x0B\x00\x00')
2022-10-18 14:35:31.664 DEBUG (MainThread) [zigpy_znp.api] Received command: AF.DataRequestExt.Rsp(Status=<Status.SUCCESS: 0>)
2022-10-18 14:35:31.666 DEBUG (MainThread) [zigpy_znp.api] Received command: AF.DataConfirm.Callback(Status=<Status.SUCCESS: 0>, Endpoint=1, TSN=58)
2022-10-18 14:35:34.521 DEBUG (MainThread) [zigpy_znp.api] Received command: AF.IncomingMsg.Callback(GroupId=0x0000, ClusterId=6, SrcAddr=0x383E, SrcEndpoint=1, DstEndpoint=1, WasBroadcast=<Bool.false: 0>, LQI=76, SecurityUse=<Bool.false: 0>, TimeStamp=12493454, TSN=0, Data=b'\x08\x16\x0A\x00\x00\x10\x00', MacSrcAddr=0x383E, MsgResultRadius=29)
2022-10-18 14:35:34.525 DEBUG (MainThread) [zigpy.application] Received a packet: ZigbeePacket(src=AddrModeAddress(addr_mode=<AddrMode.NWK: 2>, address=0x383E), 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=6, data=Serialized[b'\x08\x16\n\x00\x00\x10\x00'], tx_options=<TransmitOptions.NONE: 0>, radius=29, non_member_radius=0, lqi=76, rssi=None)
2022-10-18 14:35:34.526 DEBUG (MainThread) [zigpy.zcl] [0x383E:1:0x0006] Received ZCL frame: b'\x08\x16\n\x00\x00\x10\x00'
2022-10-18 14:35:34.529 DEBUG (MainThread) [zigpy.zcl] [0x383E:1:0x0006] Decoded ZCL frame header: ZCLHeader(frame_control=FrameControl(frame_type=<FrameType.GLOBAL_COMMAND: 0>, is_manufacturer_specific=0, direction=<Direction.Client_to_Server: 1>, disable_default_response=0, reserved=0, *is_cluster=False, *is_general=True, *is_reply=True), tsn=22, command_id=10, *direction=<Direction.Client_to_Server: 1>, *is_reply=True)
2022-10-18 14:35:34.531 DEBUG (MainThread) [zigpy.zcl] [0x383E:1:0x0006] Decoded ZCL frame: OnOff:Report_Attributes(attribute_reports=[Attribute(attrid=0x0000, value=TypeValue(type=Bool, value=<Bool.false: 0>))])
2022-10-18 14:35:34.532 DEBUG (MainThread) [zigpy.zcl] [0x383E:1:0x0006] Received command 0x0A (TSN 22): Report_Attributes(attribute_reports=[Attribute(attrid=0x0000, value=TypeValue(type=Bool, value=<Bool.false: 0>))])
2022-10-18 14:35:34.533 DEBUG (MainThread) [zigpy.zcl] [0x383E:1:0x0006] Attribute report received: on_off=<Bool.false: 0>
2022-10-18 14:35:34.538 DEBUG (MainThread) [zigpy.zcl] [0x383E:1:0x0006] Sending reply header: ZCLHeader(frame_control=FrameControl(frame_type=<FrameType.GLOBAL_COMMAND: 0>, is_manufacturer_specific=False, direction=<Direction.Client_to_Server: 1>, disable_default_response=1, reserved=0, *is_cluster=False, *is_general=True, *is_reply=True), tsn=22, command_id=<GeneralCommand.Default_Response: 11>, *direction=<Direction.Client_to_Server: 1>, *is_reply=True)
2022-10-18 14:35:34.540 DEBUG (MainThread) [zigpy.zcl] [0x383E:1:0x0006] Sending reply: Default_Response(command_id=10, status=<Status.SUCCESS: 0>)
2022-10-18 14:35:34.542 DEBUG (MainThread) [zigpy_znp.zigbee.application] Sending packet ZigbeePacket(src=AddrModeAddress(addr_mode=<AddrMode.NWK: 2>, address=0x0000), src_ep=1, dst=AddrModeAddress(addr_mode=<AddrMode.NWK: 2>, address=0x383E), dst_ep=1, source_route=None, extended_timeout=False, tsn=22, profile_id=260, cluster_id=6, data=Serialized[b'\x18\x16\x0b\n\x00'], tx_options=<TransmitOptions.NONE: 0>, radius=0, non_member_radius=0, lqi=None, rssi=None)
2022-10-18 14:35:34.546 DEBUG (MainThread) [zigpy_znp.api] Sending request: AF.DataRequestExt.Req(DstAddrModeAddress=AddrModeAddress(mode=<AddrMode.NWK: 2>, address=0x383E), DstEndpoint=1, DstPanId=0x0000, SrcEndpoint=1, ClusterId=6, TSN=22, Options=<TransmitOptions.SUPPRESS_ROUTE_DISC_NETWORK: 32>, Radius=0, Data=b'\x18\x16\x0B\x0A\x00')
2022-10-18 14:35:34.578 DEBUG (MainThread) [zigpy_znp.api] Received command: AF.DataRequestExt.Rsp(Status=<Status.SUCCESS: 0>)
2022-10-18 14:35:34.581 DEBUG (MainThread) [zigpy_znp.api] Received command: AF.DataConfirm.Callback(Status=<Status.SUCCESS: 0>, Endpoint=1, TSN=22)
2022-10-18 14:35:34.756 DEBUG (MainThread) [zigpy_znp.api] Received command: AF.IncomingMsg.Callback(GroupId=0x0000, ClusterId=1280, SrcAddr=0x7213, SrcEndpoint=1, DstEndpoint=1, WasBroadcast=<Bool.false: 0>, LQI=149, SecurityUse=<Bool.false: 0>, TimeStamp=12508266, TSN=0, Data=b'\x09\x60\x00\x21\x00\x00\x00\x00\x00', MacSrcAddr=0x7213, MsgResultRadius=29)
2022-10-18 14:35:34.761 DEBUG (MainThread) [zigpy.application] Received a packet: ZigbeePacket(src=AddrModeAddress(addr_mode=<AddrMode.NWK: 2>, address=0x7213), 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=1280, data=Serialized[b'\t`\x00!\x00\x00\x00\x00\x00'], tx_options=<TransmitOptions.NONE: 0>, radius=29, non_member_radius=0, lqi=149, rssi=None)
2022-10-18 14:35:34.763 DEBUG (MainThread) [zigpy.zcl] [0x7213:1:0x0500] Received ZCL frame: b'\t`\x00!\x00\x00\x00\x00\x00'
2022-10-18 14:35:34.765 DEBUG (MainThread) [zigpy.zcl] [0x7213:1:0x0500] Decoded ZCL frame header: ZCLHeader(frame_control=FrameControl(frame_type=<FrameType.CLUSTER_COMMAND: 1>, is_manufacturer_specific=0, direction=<Direction.Client_to_Server: 1>, disable_default_response=0, reserved=0, *is_cluster=True, *is_general=False, *is_reply=True), tsn=96, command_id=0, *direction=<Direction.Client_to_Server: 1>, *is_reply=True)
2022-10-18 14:35:34.768 DEBUG (MainThread) [zigpy.zcl] [0x7213:1:0x0500] Decoded ZCL frame: IasZone:status_change_notification(zone_status=<ZoneStatus.Restore_reports|Alarm_1: 33>, extended_status=<bitmap8.0: 0>, zone_id=0, delay=0)
2022-10-18 14:35:34.769 DEBUG (MainThread) [zigpy.zcl] [0x7213:1:0x0500] Received command 0x00 (TSN 96): status_change_notification(zone_status=<ZoneStatus.Restore_reports|Alarm_1: 33>, extended_status=<bitmap8.0: 0>, zone_id=0, delay=0)
2022-10-18 14:35:34.772 DEBUG (MainThread) [homeassistant.components.zha.core.channels.base] [0x7213:1:0x0500]: Updated alarm state: ZoneStatus.Alarm_1
2022-10-18 14:35:34.774 DEBUG (MainThread) [zigpy.zcl] [0x7213:1:0x0500] Sending reply header: ZCLHeader(frame_control=FrameControl(frame_type=<FrameType.GLOBAL_COMMAND: 0>, is_manufacturer_specific=False, direction=<Direction.Client_to_Server: 1>, disable_default_response=1, reserved=0, *is_cluster=False, *is_general=True, *is_reply=True), tsn=96, command_id=<GeneralCommand.Default_Response: 11>, *direction=<Direction.Client_to_Server: 1>, *is_reply=True)
2022-10-18 14:35:34.775 DEBUG (MainThread) [zigpy.zcl] [0x7213:1:0x0500] Sending reply: Default_Response(command_id=0, status=<Status.SUCCESS: 0>)
2022-10-18 14:35:34.777 DEBUG (MainThread) [zigpy_znp.zigbee.application] Sending packet ZigbeePacket(src=AddrModeAddress(addr_mode=<AddrMode.NWK: 2>, address=0x0000), src_ep=1, dst=AddrModeAddress(addr_mode=<AddrMode.NWK: 2>, address=0x7213), dst_ep=1, source_route=None, extended_timeout=False, tsn=96, profile_id=260, cluster_id=1280, data=Serialized[b'\x18`\x0b\x00\x00'], tx_options=<TransmitOptions.NONE: 0>, radius=0, non_member_radius=0, lqi=None, rssi=None)
2022-10-18 14:35:34.782 DEBUG (MainThread) [zigpy_znp.api] Sending request: AF.DataRequestExt.Req(DstAddrModeAddress=AddrModeAddress(mode=<AddrMode.NWK: 2>, address=0x7213), DstEndpoint=1, DstPanId=0x0000, SrcEndpoint=1, ClusterId=1280, TSN=96, Options=<TransmitOptions.SUPPRESS_ROUTE_DISC_NETWORK: 32>, Radius=0, Data=b'\x18\x60\x0B\x00\x00')
2022-10-18 14:35:34.797 DEBUG (MainThread) [zigpy_znp.api] Received command: AF.DataRequestExt.Rsp(Status=<Status.SUCCESS: 0>)
2022-10-18 14:35:35.323 DEBUG (MainThread) [zigpy_znp.api] Received command: AF.IncomingMsg.Callback(GroupId=0x0000, ClusterId=8, SrcAddr=0x383E, SrcEndpoint=1, DstEndpoint=1, WasBroadcast=<Bool.false: 0>, LQI=72, SecurityUse=<Bool.false: 0>, TimeStamp=12543688, TSN=0, Data=b'\x08\x17\x0A\x00\x00\x20\x01', MacSrcAddr=0x383E, MsgResultRadius=29)
2022-10-18 14:35:35.329 DEBUG (MainThread) [zigpy.application] Received a packet: ZigbeePacket(src=AddrModeAddress(addr_mode=<AddrMode.NWK: 2>, address=0x383E), 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=8, data=Serialized[b'\x08\x17\n\x00\x00 \x01'], tx_options=<TransmitOptions.NONE: 0>, radius=29, non_member_radius=0, lqi=72, rssi=None)
2022-10-18 14:35:35.331 DEBUG (MainThread) [zigpy.zcl] [0x383E:1:0x0008] Received ZCL frame: b'\x08\x17\n\x00\x00 \x01'
2022-10-18 14:35:35.333 DEBUG (MainThread) [zigpy.zcl] [0x383E:1:0x0008] Decoded ZCL frame header: ZCLHeader(frame_control=FrameControl(frame_type=<FrameType.GLOBAL_COMMAND: 0>, is_manufacturer_specific=0, direction=<Direction.Client_to_Server: 1>, disable_default_response=0, reserved=0, *is_cluster=False, *is_general=True, *is_reply=True), tsn=23, command_id=10, *direction=<Direction.Client_to_Server: 1>, *is_reply=True)
2022-10-18 14:35:35.335 DEBUG (MainThread) [zigpy.zcl] [0x383E:1:0x0008] Decoded ZCL frame: LevelControl:Report_Attributes(attribute_reports=[Attribute(attrid=0x0000, value=TypeValue(type=uint8_t, value=1))])
2022-10-18 14:35:35.336 DEBUG (MainThread) [zigpy.zcl] [0x383E:1:0x0008] Received command 0x0A (TSN 23): Report_Attributes(attribute_reports=[Attribute(attrid=0x0000, value=TypeValue(type=uint8_t, value=1))])
2022-10-18 14:35:35.338 DEBUG (MainThread) [zigpy.zcl] [0x383E:1:0x0008] Attribute report received: current_level=1
2022-10-18 14:35:35.338 DEBUG (MainThread) [homeassistant.components.zha.core.channels.base] [0x383E:1:0x0008]: received attribute: 0 update with value: 1
2022-10-18 14:35:35.343 DEBUG (MainThread) [zigpy.zcl] [0x383E:1:0x0008] Sending reply header: ZCLHeader(frame_control=FrameControl(frame_type=<FrameType.GLOBAL_COMMAND: 0>, is_manufacturer_specific=False, direction=<Direction.Client_to_Server: 1>, disable_default_response=1, reserved=0, *is_cluster=False, *is_general=True, *is_reply=True), tsn=23, command_id=<GeneralCommand.Default_Response: 11>, *direction=<Direction.Client_to_Server: 1>, *is_reply=True)
2022-10-18 14:35:35.344 DEBUG (MainThread) [zigpy.zcl] [0x383E:1:0x0008] Sending reply: Default_Response(command_id=10, status=<Status.SUCCESS: 0>)
2022-10-18 14:35:35.345 DEBUG (MainThread) [zigpy_znp.zigbee.application] Sending packet ZigbeePacket(src=AddrModeAddress(addr_mode=<AddrMode.NWK: 2>, address=0x0000), src_ep=1, dst=AddrModeAddress(addr_mode=<AddrMode.NWK: 2>, address=0x383E), dst_ep=1, source_route=None, extended_timeout=False, tsn=23, profile_id=260, cluster_id=8, data=Serialized[b'\x18\x17\x0b\n\x00'], tx_options=<TransmitOptions.NONE: 0>, radius=0, non_member_radius=0, lqi=None, rssi=None)
2022-10-18 14:35:35.351 DEBUG (MainThread) [zigpy_znp.api] Sending request: AF.DataRequestExt.Req(DstAddrModeAddress=AddrModeAddress(mode=<AddrMode.NWK: 2>, address=0x383E), DstEndpoint=1, DstPanId=0x0000, SrcEndpoint=1, ClusterId=8, TSN=23, Options=<TransmitOptions.SUPPRESS_ROUTE_DISC_NETWORK: 32>, Radius=0, Data=b'\x18\x17\x0B\x0A\x00')
2022-10-18 14:35:35.373 DEBUG (MainThread) [zigpy_znp.api] Received command: AF.DataRequestExt.Rsp(Status=<Status.SUCCESS: 0>)
2022-10-18 14:35:35.378 DEBUG (MainThread) [zigpy_znp.api] Received command: AF.DataConfirm.Callback(Status=<Status.SUCCESS: 0>, Endpoint=1, TSN=23)
2022-10-18 14:35:35.620 DEBUG (MainThread) [zigpy.util] Tries remaining: 2
2022-10-18 14:35:35.622 DEBUG (MainThread) [zigpy_znp.zigbee.application] Sending packet ZigbeePacket(src=AddrModeAddress(addr_mode=<AddrMode.NWK: 2>, address=0x0000), src_ep=0, dst=AddrModeAddress(addr_mode=<AddrMode.NWK: 2>, address=0x5340), dst_ep=0, source_route=None, extended_timeout=False, tsn=236, profile_id=0, cluster_id=<ZDOCmd.Mgmt_Lqi_req: 0x0031>, data=Serialized[b'\xec\x00'], tx_options=<TransmitOptions.ACK: 1>, radius=0, non_member_radius=0, lqi=None, rssi=None)
2022-10-18 14:35:35.624 DEBUG (MainThread) [zigpy_znp.api] Sending request: ZDO.ExtRouteChk.Req(Dst=0x5340, RtStatus=<RouteStatus.ACTIVE: 1>, Options=<RouteOptions.NO_ROUTE_CACHE|MTO_ROUTE: 3>)
2022-10-18 14:35:35.637 DEBUG (MainThread) [zigpy_znp.api] Received command: ZDO.ExtRouteChk.Rsp(Status=<RoutingStatus.FAIL: 1>)
2022-10-18 14:35:35.640 DEBUG (MainThread) [zigpy_znp.api] Sending request: ZDO.ExtRouteDisc.Req(Dst=0x5340, Options=<RouteDiscoveryOptions.UNICAST: 0>, Radius=30)
2022-10-18 14:35:35.649 DEBUG (MainThread) [zigpy_znp.api] Received command: ZDO.ExtRouteDisc.Rsp(Status=<Status.SUCCESS: 0>)
2022-10-18 14:35:36.262 DEBUG (MainThread) [zigpy_znp.api] Received command: AF.DataConfirm.Callback(Status=<Status.SUCCESS: 0>, Endpoint=1, TSN=96)
2022-10-18 14:35:36.328 DEBUG (MainThread) [zigpy_znp.api] Sending request: SYS.Ping.Req()
2022-10-18 14:35:36.338 DEBUG (MainThread) [zigpy_znp.api] Received command: SYS.Ping.Rsp(Capabilities=<MTCapabilities.APP_CNF|GP|UTIL|ZDO|AF|SYS: 1625>)
2022-10-18 14:35:36.955 DEBUG (MainThread) [zigpy_znp.api] Sending request: AF.DataRequestExt.Req(DstAddrModeAddress=AddrModeAddress(mode=<AddrMode.NWK: 2>, address=0x5340), DstEndpoint=0, DstPanId=0x0000, SrcEndpoint=0, ClusterId=49, TSN=236, Options=<TransmitOptions.SUPPRESS_ROUTE_DISC_NETWORK|ACK_REQUEST: 48>, Radius=0, Data=b'\xEC\x00')
2022-10-18 14:35:36.979 DEBUG (MainThread) [zigpy_znp.api] Received command: AF.DataRequestExt.Rsp(Status=<Status.SUCCESS: 0>)
2022-10-18 14:35:37.637 DEBUG (MainThread) [homeassistant.components.zha.core.device] [0x1D65](TY0202): Device seen - marking the device available and resetting counter
2022-10-18 14:35:37.638 DEBUG (MainThread) [homeassistant.components.zha.core.device] [0x1D65](TY0202): Update device availability -  device available: True - new availability: True - changed: False
2022-10-18 14:35:42.984 DEBUG (MainThread) [zigpy.util] Tries remaining: 1
2022-10-18 14:35:42.986 DEBUG (MainThread) [zigpy_znp.zigbee.application] Sending packet ZigbeePacket(src=AddrModeAddress(addr_mode=<AddrMode.NWK: 2>, address=0x0000), src_ep=0, dst=AddrModeAddress(addr_mode=<AddrMode.NWK: 2>, address=0x5340), dst_ep=0, source_route=None, extended_timeout=False, tsn=237, profile_id=0, cluster_id=<ZDOCmd.Mgmt_Lqi_req: 0x0031>, data=Serialized[b'\xed\x00'], tx_options=<TransmitOptions.ACK: 1>, radius=0, non_member_radius=0, lqi=None, rssi=None)
2022-10-18 14:35:42.987 DEBUG (MainThread) [zigpy_znp.api] Sending request: ZDO.ExtRouteChk.Req(Dst=0x5340, RtStatus=<RouteStatus.ACTIVE: 1>, Options=<RouteOptions.NO_ROUTE_CACHE|MTO_ROUTE: 3>)
2022-10-18 14:35:43.000 DEBUG (MainThread) [zigpy_znp.api] Received command: ZDO.ExtRouteChk.Rsp(Status=<RoutingStatus.FAIL: 1>)
2022-10-18 14:35:43.004 DEBUG (MainThread) [zigpy_znp.api] Sending request: ZDO.ExtRouteDisc.Req(Dst=0x5340, Options=<RouteDiscoveryOptions.UNICAST: 0>, Radius=30)
2022-10-18 14:35:43.022 DEBUG (MainThread) [zigpy_znp.api] Received command: ZDO.ExtRouteDisc.Rsp(Status=<Status.SUCCESS: 0>)
2022-10-18 14:35:44.328 DEBUG (MainThread) [zigpy_znp.api] Sending request: AF.DataRequestExt.Req(DstAddrModeAddress=AddrModeAddress(mode=<AddrMode.NWK: 2>, address=0x5340), DstEndpoint=0, DstPanId=0x0000, SrcEndpoint=0, ClusterId=49, TSN=237, Options=<TransmitOptions.SUPPRESS_ROUTE_DISC_NETWORK|ACK_REQUEST: 48>, Radius=0, Data=b'\xED\x00')
2022-10-18 14:35:44.351 DEBUG (MainThread) [zigpy_znp.api] Received command: AF.DataRequestExt.Rsp(Status=<Status.SUCCESS: 0>)
2022-10-18 14:35:45.506 DEBUG (MainThread) [homeassistant.components.zha.core.device] [0x00B1](TY0202): Device seen - marking the device available and resetting counter
2022-10-18 14:35:45.507 DEBUG (MainThread) [homeassistant.components.zha.core.device] [0x00B1](TY0202): Update device availability -  device available: True - new availability: True - changed: False
2022-10-18 14:35:45.532 DEBUG (MainThread) [homeassistant.components.zha.core.device] [0x7213](TY0202): Device seen - marking the device available and resetting counter
2022-10-18 14:35:45.532 DEBUG (MainThread) [homeassistant.components.zha.core.device] [0x7213](TY0202): Update device availability -  device available: True - new availability: True - changed: False
2022-10-18 14:35:45.728 DEBUG (MainThread) [homeassistant.components.zha.core.device] [0x5340](TRADFRIbulbE27WSglobeopal1055lm): Device seen - marking the device available and resetting counter
2022-10-18 14:35:45.729 DEBUG (MainThread) [homeassistant.components.zha.core.device] [0x5340](TRADFRIbulbE27WSglobeopal1055lm): Update device availability -  device available: False - new availability: True - changed: True
2022-10-18 14:35:45.730 DEBUG (MainThread) [homeassistant.components.zha.core.device] [0x5340](TRADFRIbulbE27WSglobeopal1055lm): Device availability changed and device became available, reinitializing channels
2022-10-18 14:35:45.730 DEBUG (MainThread) [homeassistant.components.zha.core.device] [0x5340](TRADFRIbulbE27WSglobeopal1055lm): started initialization
2022-10-18 14:35:45.731 DEBUG (MainThread) [homeassistant.components.zha.core.channels.base] [0x5340:ZDO](TRADFRIbulbE27WSglobeopal1055lm): 'async_initialize' stage succeeded
2022-10-18 14:35:45.733 DEBUG (MainThread) [homeassistant.components.zha.core.channels.base] [0x5340:1:0x0006]: initializing channel: from_cache: False
2022-10-18 14:35:45.734 DEBUG (MainThread) [homeassistant.components.zha.core.channels.base] [0x5340:1:0x0006]: initializing cached channel attributes: ['start_up_on_off']
2022-10-18 14:35:45.734 DEBUG (MainThread) [homeassistant.components.zha.core.channels.base] [0x5340:1:0x0006]: Reading attributes in chunks: ['start_up_on_off']
2022-10-18 14:35:45.735 DEBUG (MainThread) [homeassistant.components.zha.core.channels.base] [0x5340:1:0x0006]: initializing uncached channel attributes: ['on_off'] - from cache[False]
2022-10-18 14:35:45.735 DEBUG (MainThread) [homeassistant.components.zha.core.channels.base] [0x5340:1:0x0006]: Reading attributes in chunks: ['on_off']
2022-10-18 14:35:45.737 DEBUG (MainThread) [zigpy.zcl] [0x5340:1:0x0006] Sending request header: ZCLHeader(frame_control=FrameControl(frame_type=<FrameType.GLOBAL_COMMAND: 0>, is_manufacturer_specific=False, direction=<Direction.Server_to_Client: 0>, disable_default_response=0, reserved=0, *is_cluster=False, *is_general=True, *is_reply=False), tsn=238, command_id=<GeneralCommand.Read_Attributes: 0>, *direction=<Direction.Server_to_Client: 0>, *is_reply=False)
2022-10-18 14:35:45.741 DEBUG (MainThread) [zigpy.zcl] [0x5340:1:0x0006] Sending request: Read_Attributes(attribute_ids=[0])
2022-10-18 14:35:45.743 DEBUG (MainThread) [zigpy_znp.zigbee.application] Sending packet ZigbeePacket(src=AddrModeAddress(addr_mode=<AddrMode.NWK: 2>, address=0x0000), src_ep=1, dst=AddrModeAddress(addr_mode=<AddrMode.NWK: 2>, address=0x5340), dst_ep=1, source_route=None, extended_timeout=False, tsn=238, profile_id=260, cluster_id=6, data=Serialized[b'\x00\xee\x00\x00\x00'], tx_options=<TransmitOptions.ACK: 1>, radius=0, non_member_radius=0, lqi=None, rssi=None)
2022-10-18 14:35:45.745 DEBUG (MainThread) [homeassistant.components.zha.core.channels.base] [0x5340:1:0x0300]: initializing channel: from_cache: False
2022-10-18 14:35:45.746 DEBUG (MainThread) [homeassistant.components.zha.core.channels.base] [0x5340:1:0x0300]: initializing cached channel attributes: ['color_temp_physical_min', 'color_temp_physical_max', 'color_capabilities']
2022-10-18 14:35:45.746 DEBUG (MainThread) [homeassistant.components.zha.core.channels.base] [0x5340:1:0x0300]: Reading attributes in chunks: ['color_temp_physical_min', 'color_temp_physical_max', 'color_capabilities']
2022-10-18 14:35:45.747 DEBUG (MainThread) [homeassistant.components.zha.core.channels.base] [0x5340:1:0x0300]: initializing uncached channel attributes: ['color_mode', 'color_loop_active', 'current_x', 'current_y', 'current_hue', 'enhanced_current_hue', 'current_saturation', 'color_temperature'] - from cache[False]
2022-10-18 14:35:45.747 DEBUG (MainThread) [homeassistant.components.zha.core.channels.base] [0x5340:1:0x0300]: Reading attributes in chunks: ['color_mode', 'color_loop_active', 'current_x', 'current_y', 'current_hue']
2022-10-18 14:35:45.749 DEBUG (MainThread) [zigpy.zcl] [0x5340:1:0x0300] Sending request header: ZCLHeader(frame_control=FrameControl(frame_type=<FrameType.GLOBAL_COMMAND: 0>, is_manufacturer_specific=False, direction=<Direction.Server_to_Client: 0>, disable_default_response=0, reserved=0, *is_cluster=False, *is_general=True, *is_reply=False), tsn=239, command_id=<GeneralCommand.Read_Attributes: 0>, *direction=<Direction.Server_to_Client: 0>, *is_reply=False)
2022-10-18 14:35:45.751 DEBUG (MainThread) [zigpy.zcl] [0x5340:1:0x0300] Sending request: Read_Attributes(attribute_ids=[8, 16386, 3, 4, 0])
2022-10-18 14:35:45.753 DEBUG (MainThread) [zigpy_znp.zigbee.application] Sending packet ZigbeePacket(src=AddrModeAddress(addr_mode=<AddrMode.NWK: 2>, address=0x0000), src_ep=1, dst=AddrModeAddress(addr_mode=<AddrMode.NWK: 2>, address=0x5340), dst_ep=1, source_route=None, extended_timeout=False, tsn=239, profile_id=260, cluster_id=768, data=Serialized[b'\x00\xef\x00\x08\x00\x02@\x03\x00\x04\x00\x00\x00'], tx_options=<TransmitOptions.ACK: 1>, radius=0, non_member_radius=0, lqi=None, rssi=None)
2022-10-18 14:35:45.755 DEBUG (MainThread) [homeassistant.components.zha.core.channels.base] [0x5340:1:0x0008]: initializing channel: from_cache: False
2022-10-18 14:35:45.755 DEBUG (MainThread) [homeassistant.components.zha.core.channels.base] [0x5340:1:0x0008]: initializing cached channel attributes: ['on_off_transition_time', 'on_level', 'on_transition_time', 'off_transition_time', 'default_move_rate', 'start_up_current_level']
2022-10-18 14:35:45.755 DEBUG (MainThread) [homeassistant.components.zha.core.channels.base] [0x5340:1:0x0008]: Reading attributes in chunks: ['on_off_transition_time', 'on_level', 'on_transition_time', 'off_transition_time', 'default_move_rate']
2022-10-18 14:35:45.757 DEBUG (MainThread) [homeassistant.components.zha.core.channels.base] [0x5340:1:0x0008]: Reading attributes in chunks: ['start_up_current_level']
2022-10-18 14:35:45.758 DEBUG (MainThread) [homeassistant.components.zha.core.channels.base] [0x5340:1:0x0008]: initializing uncached channel attributes: ['current_level'] - from cache[False]
2022-10-18 14:35:45.758 DEBUG (MainThread) [homeassistant.components.zha.core.channels.base] [0x5340:1:0x0008]: Reading attributes in chunks: ['current_level']
2022-10-18 14:35:45.763 DEBUG (MainThread) [zigpy.zcl] [0x5340:1:0x0008] Sending request header: ZCLHeader(frame_control=FrameControl(frame_type=<FrameType.GLOBAL_COMMAND: 0>, is_manufacturer_specific=False, direction=<Direction.Server_to_Client: 0>, disable_default_response=0, reserved=0, *is_cluster=False, *is_general=True, *is_reply=False), tsn=240, command_id=<GeneralCommand.Read_Attributes: 0>, *direction=<Direction.Server_to_Client: 0>, *is_reply=False)
2022-10-18 14:35:45.764 DEBUG (MainThread) [zigpy.zcl] [0x5340:1:0x0008] Sending request: Read_Attributes(attribute_ids=[0])
2022-10-18 14:35:45.766 DEBUG (MainThread) [zigpy_znp.zigbee.application] Sending packet ZigbeePacket(src=AddrModeAddress(addr_mode=<AddrMode.NWK: 2>, address=0x0000), src_ep=1, dst=AddrModeAddress(addr_mode=<AddrMode.NWK: 2>, address=0x5340), dst_ep=1, source_route=None, extended_timeout=False, tsn=240, profile_id=260, cluster_id=8, data=Serialized[b'\x00\xf0\x00\x00\x00'], tx_options=<TransmitOptions.ACK: 1>, radius=0, non_member_radius=0, lqi=None, rssi=None)
2022-10-18 14:35:45.768 DEBUG (MainThread) [homeassistant.components.zha.core.channels.base] [0x5340:1:0x0003]: initializing channel: from_cache: False
2022-10-18 14:35:45.769 DEBUG (MainThread) [homeassistant.components.zha.core.channels.base] [0x5340:1:0x0003]: finished channel initialization
2022-10-18 14:35:45.769 DEBUG (MainThread) [homeassistant.components.zha.core.channels.base] [0x5340:1:0x0000]: initializing channel: from_cache: False
2022-10-18 14:35:45.769 DEBUG (MainThread) [homeassistant.components.zha.core.channels.base] [0x5340:1:0x0000]: finished channel initialization
2022-10-18 14:35:45.770 DEBUG (MainThread) [homeassistant.components.zha.core.channels.base] [0x5340:1:0x1000]: initializing channel: from_cache: False
2022-10-18 14:35:45.770 DEBUG (MainThread) [homeassistant.components.zha.core.channels.base] [0x5340:1:0x1000]: finished channel initialization
2022-10-18 14:35:45.770 DEBUG (MainThread) [homeassistant.components.zha.core.channels.base] [0x5340:1:0x0019]: initializing channel: from_cache: False
2022-10-18 14:35:45.771 DEBUG (MainThread) [homeassistant.components.zha.core.channels.base] [0x5340:1:0x0019]: finished channel initialization
2022-10-18 14:35:45.772 DEBUG (MainThread) [zigpy_znp.api] Sending request: AF.DataRequestExt.Req(DstAddrModeAddress=AddrModeAddress(mode=<AddrMode.NWK: 2>, address=0x5340), DstEndpoint=1, DstPanId=0x0000, SrcEndpoint=1, ClusterId=6, TSN=238, Options=<TransmitOptions.SUPPRESS_ROUTE_DISC_NETWORK|ACK_REQUEST: 48>, Radius=0, Data=b'\x00\xEE\x00\x00\x00')
2022-10-18 14:35:45.795 DEBUG (MainThread) [zigpy_znp.api] Received command: AF.DataRequestExt.Rsp(Status=<Status.SUCCESS: 0>)
2022-10-18 14:35:45.797 DEBUG (MainThread) [zigpy_znp.api] Sending request: AF.DataRequestExt.Req(DstAddrModeAddress=AddrModeAddress(mode=<AddrMode.NWK: 2>, address=0x5340), DstEndpoint=1, DstPanId=0x0000, SrcEndpoint=1, ClusterId=768, TSN=239, Options=<TransmitOptions.SUPPRESS_ROUTE_DISC_NETWORK|ACK_REQUEST: 48>, Radius=0, Data=b'\x00\xEF\x00\x08\x00\x02\x40\x03\x00\x04\x00\x00\x00')
2022-10-18 14:35:45.829 DEBUG (MainThread) [zigpy_znp.api] Received command: AF.DataRequestExt.Rsp(Status=<Status.SUCCESS: 0>)
2022-10-18 14:35:45.832 DEBUG (MainThread) [zigpy_znp.api] Sending request: AF.DataRequestExt.Req(DstAddrModeAddress=AddrModeAddress(mode=<AddrMode.NWK: 2>, address=0x5340), DstEndpoint=1, DstPanId=0x0000, SrcEndpoint=1, ClusterId=8, TSN=240, Options=<TransmitOptions.SUPPRESS_ROUTE_DISC_NETWORK|ACK_REQUEST: 48>, Radius=0, Data=b'\x00\xF0\x00\x00\x00')
2022-10-18 14:35:45.868 DEBUG (MainThread) [zigpy_znp.api] Received command: AF.DataRequestExt.Rsp(Status=<Status.SUCCESS: 0>)
2022-10-18 14:35:45.913 DEBUG (MainThread) [zigpy_znp.api] Received command: AF.DataConfirm.Callback(Status=<Status.MAC_NO_ACK: 233>, Endpoint=1, TSN=238)
2022-10-18 14:35:45.920 DEBUG (MainThread) [zigpy_znp.zigbee.application] Request failed (Unsuccessful request status code: <Status.MAC_NO_ACK: 233>), retry attempt 1 of 5
2022-10-18 14:35:45.931 DEBUG (MainThread) [zigpy_znp.api] Received command: AF.DataConfirm.Callback(Status=<Status.MAC_NO_ACK: 233>, Endpoint=1, TSN=239)
2022-10-18 14:35:45.934 DEBUG (MainThread) [zigpy_znp.zigbee.application] Request failed (Unsuccessful request status code: <Status.MAC_NO_ACK: 233>), retry attempt 1 of 5
2022-10-18 14:35:45.978 DEBUG (MainThread) [zigpy_znp.api] Received command: AF.DataConfirm.Callback(Status=<Status.MAC_NO_ACK: 233>, Endpoint=1, TSN=240)
2022-10-18 14:35:45.984 DEBUG (MainThread) [zigpy_znp.zigbee.application] Request failed (Unsuccessful request status code: <Status.MAC_NO_ACK: 233>), retry attempt 1 of 5
2022-10-18 14:35:47.425 DEBUG (MainThread) [zigpy_znp.api] Sending request: AF.DataRequestExt.Req(DstAddrModeAddress=AddrModeAddress(mode=<AddrMode.NWK: 2>, address=0x5340), DstEndpoint=1, DstPanId=0x0000, SrcEndpoint=1, ClusterId=6, TSN=238, Options=<TransmitOptions.SUPPRESS_ROUTE_DISC_NETWORK|ACK_REQUEST: 48>, Radius=0, Data=b'\x00\xEE\x00\x00\x00')
2022-10-18 14:35:47.446 DEBUG (MainThread) [zigpy_znp.api] Received command: AF.DataRequestExt.Rsp(Status=<Status.SUCCESS: 0>)
2022-10-18 14:35:47.449 DEBUG (MainThread) [zigpy_znp.api] Sending request: AF.DataRequestExt.Req(DstAddrModeAddress=AddrModeAddress(mode=<AddrMode.NWK: 2>, address=0x5340), DstEndpoint=1, DstPanId=0x0000, SrcEndpoint=1, ClusterId=768, TSN=239, Options=<TransmitOptions.SUPPRESS_ROUTE_DISC_NETWORK|ACK_REQUEST: 48>, Radius=0, Data=b'\x00\xEF\x00\x08\x00\x02\x40\x03\x00\x04\x00\x00\x00')
2022-10-18 14:35:47.482 DEBUG (MainThread) [zigpy_znp.api] Received command: AF.DataRequestExt.Rsp(Status=<Status.SUCCESS: 0>)
2022-10-18 14:35:47.490 DEBUG (MainThread) [zigpy_znp.api] Sending request: AF.DataRequestExt.Req(DstAddrModeAddress=AddrModeAddress(mode=<AddrMode.NWK: 2>, address=0x5340), DstEndpoint=1, DstPanId=0x0000, SrcEndpoint=1, ClusterId=8, TSN=240, Options=<TransmitOptions.SUPPRESS_ROUTE_DISC_NETWORK|ACK_REQUEST: 48>, Radius=0, Data=b'\x00\xF0\x00\x00\x00')
2022-10-18 14:35:47.521 DEBUG (MainThread) [zigpy_znp.api] Received command: AF.DataRequestExt.Rsp(Status=<Status.SUCCESS: 0>)
2022-10-18 14:35:47.568 DEBUG (MainThread) [zigpy_znp.api] Received command: AF.DataConfirm.Callback(Status=<Status.MAC_NO_ACK: 233>, Endpoint=1, TSN=238)
2022-10-18 14:35:47.573 DEBUG (MainThread) [zigpy_znp.zigbee.application] Request failed (Unsuccessful request status code: <Status.MAC_NO_ACK: 233>), retry attempt 2 of 5
2022-10-18 14:35:47.584 DEBUG (MainThread) [zigpy_znp.api] Received command: AF.DataConfirm.Callback(Status=<Status.MAC_NO_ACK: 233>, Endpoint=1, TSN=239)
2022-10-18 14:35:47.588 DEBUG (MainThread) [zigpy_znp.zigbee.application] Request failed (Unsuccessful request status code: <Status.MAC_NO_ACK: 233>), retry attempt 2 of 5
2022-10-18 14:35:47.633 DEBUG (MainThread) [zigpy_znp.api] Received command: AF.DataConfirm.Callback(Status=<Status.MAC_NO_ACK: 233>, Endpoint=1, TSN=240)
2022-10-18 14:35:47.639 DEBUG (MainThread) [zigpy_znp.zigbee.application] Request failed (Unsuccessful request status code: <Status.MAC_NO_ACK: 233>), retry attempt 2 of 5
2022-10-18 14:35:47.966 DEBUG (MainThread) [zigpy_znp.api] Received command: ZDO.SrcRtgInd.Callback(DstAddr=0x1D65, Relays=[0xFA52])
2022-10-18 14:35:48.027 DEBUG (MainThread) [zigpy_znp.api] Received command: AF.IncomingMsg.Callback(GroupId=0x0000, ClusterId=1, SrcAddr=0x1D65, SrcEndpoint=1, DstEndpoint=1, WasBroadcast=<Bool.false: 0>, LQI=36, SecurityUse=<Bool.false: 0>, TimeStamp=13337093, TSN=0, Data=b'\x08\x6A\x0A\x21\x00\x20\xC8', MacSrcAddr=0xFA52, MsgResultRadius=28)
2022-10-18 14:35:48.032 DEBUG (MainThread) [zigpy.application] Received a packet: ZigbeePacket(src=AddrModeAddress(addr_mode=<AddrMode.NWK: 2>, address=0x1D65), 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=1, data=Serialized[b'\x08j\n!\x00 \xc8'], tx_options=<TransmitOptions.NONE: 0>, radius=28, non_member_radius=0, lqi=36, rssi=None)
2022-10-18 14:35:48.034 DEBUG (MainThread) [zigpy.zcl] [0x1D65:1:0x0001] Received ZCL frame: b'\x08j\n!\x00 \xc8'
2022-10-18 14:35:48.037 DEBUG (MainThread) [zigpy.zcl] [0x1D65:1:0x0001] Decoded ZCL frame header: ZCLHeader(frame_control=FrameControl(frame_type=<FrameType.GLOBAL_COMMAND: 0>, is_manufacturer_specific=0, direction=<Direction.Client_to_Server: 1>, disable_default_response=0, reserved=0, *is_cluster=False, *is_general=True, *is_reply=True), tsn=106, command_id=10, *direction=<Direction.Client_to_Server: 1>, *is_reply=True)
2022-10-18 14:35:48.040 DEBUG (MainThread) [zigpy.zcl] [0x1D65:1:0x0001] Decoded ZCL frame: PowerConfiguration:Report_Attributes(attribute_reports=[Attribute(attrid=0x0021, value=TypeValue(type=uint8_t, value=200))])
2022-10-18 14:35:48.041 DEBUG (MainThread) [zigpy.zcl] [0x1D65:1:0x0001] Received command 0x0A (TSN 106): Report_Attributes(attribute_reports=[Attribute(attrid=0x0021, value=TypeValue(type=uint8_t, value=200))])
2022-10-18 14:35:48.042 DEBUG (MainThread) [zigpy.zcl] [0x1D65:1:0x0001] Attribute report received: battery_percentage_remaining=200
2022-10-18 14:35:48.045 DEBUG (MainThread) [zigpy.zcl] [0x1D65:1:0x0001] Sending reply header: ZCLHeader(frame_control=FrameControl(frame_type=<FrameType.GLOBAL_COMMAND: 0>, is_manufacturer_specific=False, direction=<Direction.Client_to_Server: 1>, disable_default_response=1, reserved=0, *is_cluster=False, *is_general=True, *is_reply=True), tsn=106, command_id=<GeneralCommand.Default_Response: 11>, *direction=<Direction.Client_to_Server: 1>, *is_reply=True)
2022-10-18 14:35:48.046 DEBUG (MainThread) [zigpy.zcl] [0x1D65:1:0x0001] Sending reply: Default_Response(command_id=10, status=<Status.SUCCESS: 0>)
2022-10-18 14:35:48.048 DEBUG (MainThread) [zigpy_znp.zigbee.application] Sending packet ZigbeePacket(src=AddrModeAddress(addr_mode=<AddrMode.NWK: 2>, address=0x0000), src_ep=1, dst=AddrModeAddress(addr_mode=<AddrMode.NWK: 2>, address=0x1D65), dst_ep=1, source_route=None, extended_timeout=False, tsn=106, profile_id=260, cluster_id=1, data=Serialized[b'\x18j\x0b\n\x00'], tx_options=<TransmitOptions.NONE: 0>, radius=0, non_member_radius=0, lqi=None, rssi=None)
2022-10-18 14:35:48.052 DEBUG (MainThread) [zigpy_znp.api] Sending request: AF.DataRequestExt.Req(DstAddrModeAddress=AddrModeAddress(mode=<AddrMode.NWK: 2>, address=0x1D65), DstEndpoint=1, DstPanId=0x0000, SrcEndpoint=1, ClusterId=1, TSN=106, Options=<TransmitOptions.SUPPRESS_ROUTE_DISC_NETWORK: 32>, Radius=0, Data=b'\x18\x6A\x0B\x0A\x00')
2022-10-18 14:35:48.073 DEBUG (MainThread) [zigpy_znp.api] Received command: AF.DataRequestExt.Rsp(Status=<Status.SUCCESS: 0>)
2022-10-18 14:35:48.077 DEBUG (MainThread) [zigpy_znp.api] Sending request: AF.DataRequestSrcRtg.Req(DstAddr=0x5340, DstEndpoint=1, SrcEndpoint=1, ClusterId=6, TSN=238, Options=<TransmitOptions.SUPPRESS_ROUTE_DISC_NETWORK|ACK_REQUEST: 48>, Radius=0, SourceRoute=[], Data=b'\x00\xEE\x00\x00\x00')
2022-10-18 14:35:48.082 DEBUG (MainThread) [zigpy_znp.api] Received command: AF.DataConfirm.Callback(Status=<Status.SUCCESS: 0>, Endpoint=1, TSN=106)
2022-10-18 14:35:48.103 DEBUG (MainThread) [zigpy_znp.api] Received command: AF.DataRequestSrcRtg.Rsp(Status=<Status.SUCCESS: 0>)
2022-10-18 14:35:48.106 DEBUG (MainThread) [zigpy_znp.api] Sending request: AF.DataRequestSrcRtg.Req(DstAddr=0x5340, DstEndpoint=1, SrcEndpoint=1, ClusterId=768, TSN=239, Options=<TransmitOptions.SUPPRESS_ROUTE_DISC_NETWORK|ACK_REQUEST: 48>, Radius=0, SourceRoute=[], Data=b'\x00\xEF\x00\x08\x00\x02\x40\x03\x00\x04\x00\x00\x00')
2022-10-18 14:35:48.137 DEBUG (MainThread) [zigpy_znp.api] Received command: AF.DataRequestSrcRtg.Rsp(Status=<Status.SUCCESS: 0>)
2022-10-18 14:35:48.145 DEBUG (MainThread) [zigpy_znp.api] Sending request: AF.DataRequestSrcRtg.Req(DstAddr=0x5340, DstEndpoint=1, SrcEndpoint=1, ClusterId=8, TSN=240, Options=<TransmitOptions.SUPPRESS_ROUTE_DISC_NETWORK|ACK_REQUEST: 48>, Radius=0, SourceRoute=[], Data=b'\x00\xF0\x00\x00\x00')
2022-10-18 14:35:48.176 DEBUG (MainThread) [zigpy_znp.api] Received command: AF.DataRequestSrcRtg.Rsp(Status=<Status.SUCCESS: 0>)
2022-10-18 14:35:48.184 DEBUG (MainThread) [zigpy_znp.api] Received command: AF.DataConfirm.Callback(Status=<Status.MAC_NO_ACK: 233>, Endpoint=1, TSN=238)
2022-10-18 14:35:48.190 DEBUG (MainThread) [zigpy_znp.api] Sending request: ZDO.ExtRouteDisc.Req(Dst=0x5340, Options=<RouteDiscoveryOptions.UNICAST: 0>, Radius=30)
2022-10-18 14:35:48.198 DEBUG (MainThread) [zigpy_znp.api] Received command: ZDO.ExtRouteDisc.Rsp(Status=<Status.SUCCESS: 0>)
2022-10-18 14:35:48.257 DEBUG (MainThread) [zigpy_znp.api] Received command: AF.DataConfirm.Callback(Status=<Status.MAC_NO_ACK: 233>, Endpoint=1, TSN=239)
2022-10-18 14:35:48.274 DEBUG (MainThread) [zigpy_znp.api] Received command: AF.DataConfirm.Callback(Status=<Status.MAC_NO_ACK: 233>, Endpoint=1, TSN=240)
2022-10-18 14:35:49.503 DEBUG (MainThread) [zigpy_znp.zigbee.application] Request failed (Unsuccessful request status code: <Status.MAC_NO_ACK: 233>), retry attempt 3 of 5
2022-10-18 14:35:49.504 DEBUG (MainThread) [zigpy_znp.zigbee.application] Request failed (Unsuccessful request status code: <Status.MAC_NO_ACK: 233>), retry attempt 3 of 5
2022-10-18 14:35:49.505 DEBUG (MainThread) [zigpy_znp.zigbee.application] Request failed (Unsuccessful request status code: <Status.MAC_NO_ACK: 233>), retry attempt 3 of 5
2022-10-18 14:35:50.007 DEBUG (MainThread) [zigpy_znp.api] Sending request: AF.DataRequestExt.Req(DstAddrModeAddress=AddrModeAddress(mode=<AddrMode.NWK: 2>, address=0x5340), DstEndpoint=1, DstPanId=0x0000, SrcEndpoint=1, ClusterId=6, TSN=238, Options=<TransmitOptions.SUPPRESS_ROUTE_DISC_NETWORK|ACK_REQUEST: 48>, Radius=0, Data=b'\x00\xEE\x00\x00\x00')
2022-10-18 14:35:50.033 DEBUG (MainThread) [zigpy_znp.api] Received command: AF.DataRequestExt.Rsp(Status=<Status.SUCCESS: 0>)
2022-10-18 14:35:50.037 DEBUG (MainThread) [zigpy_znp.api] Sending request: AF.DataRequestExt.Req(DstAddrModeAddress=AddrModeAddress(mode=<AddrMode.NWK: 2>, address=0x5340), DstEndpoint=1, DstPanId=0x0000, SrcEndpoint=1, ClusterId=768, TSN=239, Options=<TransmitOptions.SUPPRESS_ROUTE_DISC_NETWORK|ACK_REQUEST: 48>, Radius=0, Data=b'\x00\xEF\x00\x08\x00\x02\x40\x03\x00\x04\x00\x00\x00')
2022-10-18 14:35:50.071 DEBUG (MainThread) [zigpy_znp.api] Received command: AF.DataRequestExt.Rsp(Status=<Status.SUCCESS: 0>)
2022-10-18 14:35:50.076 DEBUG (MainThread) [zigpy_znp.api] Sending request: AF.DataRequestExt.Req(DstAddrModeAddress=AddrModeAddress(mode=<AddrMode.NWK: 2>, address=0x5340), DstEndpoint=1, DstPanId=0x0000, SrcEndpoint=1, ClusterId=8, TSN=240, Options=<TransmitOptions.SUPPRESS_ROUTE_DISC_NETWORK|ACK_REQUEST: 48>, Radius=0, Data=b'\x00\xF0\x00\x00\x00')
2022-10-18 14:35:50.113 DEBUG (MainThread) [zigpy_znp.api] Received command: AF.DataRequestExt.Rsp(Status=<Status.SUCCESS: 0>)
2022-10-18 14:35:50.122 DEBUG (MainThread) [zigpy_znp.api] Received command: AF.DataConfirm.Callback(Status=<Status.MAC_NO_ACK: 233>, Endpoint=1, TSN=238)
2022-10-18 14:35:50.131 DEBUG (MainThread) [zigpy_znp.zigbee.application] Request failed (Unsuccessful request status code: <Status.MAC_NO_ACK: 233>), retry attempt 4 of 5
2022-10-18 14:35:50.192 DEBUG (MainThread) [zigpy_znp.api] Received command: AF.DataConfirm.Callback(Status=<Status.MAC_NO_ACK: 233>, Endpoint=1, TSN=239)
2022-10-18 14:35:50.199 DEBUG (MainThread) [zigpy_znp.zigbee.application] Request failed (Unsuccessful request status code: <Status.MAC_NO_ACK: 233>), retry attempt 4 of 5
2022-10-18 14:35:50.211 DEBUG (MainThread) [zigpy_znp.api] Received command: AF.DataConfirm.Callback(Status=<Status.MAC_NO_ACK: 233>, Endpoint=1, TSN=240)
2022-10-18 14:35:50.217 DEBUG (MainThread) [zigpy_znp.zigbee.application] Request failed (Unsuccessful request status code: <Status.MAC_NO_ACK: 233>), retry attempt 4 of 5
2022-10-18 14:35:50.636 DEBUG (MainThread) [zigpy_znp.api] Sending request: AF.DataRequestExt.Req(DstAddrModeAddress=AddrModeAddress(mode=<AddrMode.IEEE: 3>, address=04:cd:15:ff:fe:8c:ae:a9), DstEndpoint=1, DstPanId=0x0000, SrcEndpoint=1, ClusterId=6, TSN=238, Options=<TransmitOptions.SUPPRESS_ROUTE_DISC_NETWORK|ACK_REQUEST: 48>, Radius=0, Data=b'\x00\xEE\x00\x00\x00')
2022-10-18 14:35:50.661 DEBUG (MainThread) [zigpy_znp.api] Received command: AF.DataRequestExt.Rsp(Status=<Status.SUCCESS: 0>)
2022-10-18 14:35:50.706 DEBUG (MainThread) [zigpy_znp.api] Sending request: AF.DataRequestExt.Req(DstAddrModeAddress=AddrModeAddress(mode=<AddrMode.IEEE: 3>, address=04:cd:15:ff:fe:8c:ae:a9), DstEndpoint=1, DstPanId=0x0000, SrcEndpoint=1, ClusterId=768, TSN=239, Options=<TransmitOptions.SUPPRESS_ROUTE_DISC_NETWORK|ACK_REQUEST: 48>, Radius=0, Data=b'\x00\xEF\x00\x08\x00\x02\x40\x03\x00\x04\x00\x00\x00')
2022-10-18 14:35:50.733 DEBUG (MainThread) [zigpy_znp.api] Received command: AF.DataRequestExt.Rsp(Status=<Status.SUCCESS: 0>)
2022-10-18 14:35:50.735 DEBUG (MainThread) [zigpy_znp.api] Received command: AF.DataConfirm.Callback(Status=<Status.MAC_NO_ACK: 233>, Endpoint=1, TSN=238)
2022-10-18 14:35:50.739 DEBUG (MainThread) [zigpy_znp.api] Sending request: AF.DataRequestExt.Req(DstAddrModeAddress=AddrModeAddress(mode=<AddrMode.IEEE: 3>, address=04:cd:15:ff:fe:8c:ae:a9), DstEndpoint=1, DstPanId=0x0000, SrcEndpoint=1, ClusterId=8, TSN=240, Options=<TransmitOptions.SUPPRESS_ROUTE_DISC_NETWORK|ACK_REQUEST: 48>, Radius=0, Data=b'\x00\xF0\x00\x00\x00')
2022-10-18 14:35:50.742 DEBUG (MainThread) [zigpy_znp.zigbee.application] Request failed (Unsuccessful request status code: <Status.MAC_NO_ACK: 233>), retry attempt 5 of 5
2022-10-18 14:35:50.771 DEBUG (MainThread) [zigpy_znp.api] Received command: AF.DataRequestExt.Rsp(Status=<Status.SUCCESS: 0>)
2022-10-18 14:35:50.817 DEBUG (MainThread) [zigpy_znp.api] Received command: AF.DataConfirm.Callback(Status=<Status.MAC_NO_ACK: 233>, Endpoint=1, TSN=239)
2022-10-18 14:35:50.822 DEBUG (MainThread) [zigpy_znp.zigbee.application] Request failed (Unsuccessful request status code: <Status.MAC_NO_ACK: 233>), retry attempt 5 of 5
2022-10-18 14:35:50.861 DEBUG (MainThread) [zigpy_znp.api] Received command: AF.DataConfirm.Callback(Status=<Status.MAC_NO_ACK: 233>, Endpoint=1, TSN=240)
2022-10-18 14:35:50.866 DEBUG (MainThread) [zigpy_znp.zigbee.application] Request failed (Unsuccessful request status code: <Status.MAC_NO_ACK: 233>), retry attempt 5 of 5
2022-10-18 14:35:50.974 DEBUG (MainThread) [homeassistant.components.zha.entity] light.philips_llc014_71e91c00_level_light_color_on_off: polling current state
2022-10-18 14:35:50.977 DEBUG (MainThread) [zigpy.zcl] [0xD6AE:11:0x0006] Sending request header: ZCLHeader(frame_control=FrameControl(frame_type=<FrameType.GLOBAL_COMMAND: 0>, is_manufacturer_specific=False, direction=<Direction.Server_to_Client: 0>, disable_default_response=0, reserved=0, *is_cluster=False, *is_general=True, *is_reply=False), tsn=241, command_id=<GeneralCommand.Read_Attributes: 0>, *direction=<Direction.Server_to_Client: 0>, *is_reply=False)
2022-10-18 14:35:50.981 DEBUG (MainThread) [zigpy.zcl] [0xD6AE:11:0x0006] Sending request: Read_Attributes(attribute_ids=[0])
2022-10-18 14:35:50.985 DEBUG (MainThread) [zigpy_znp.zigbee.application] Sending packet ZigbeePacket(src=AddrModeAddress(addr_mode=<AddrMode.NWK: 2>, address=0x0000), src_ep=11, dst=AddrModeAddress(addr_mode=<AddrMode.NWK: 2>, address=0xD6AE), dst_ep=11, source_route=None, extended_timeout=False, tsn=241, profile_id=260, cluster_id=6, data=Serialized[b'\x00\xf1\x00\x00\x00'], tx_options=<TransmitOptions.ACK: 1>, radius=0, non_member_radius=0, lqi=None, rssi=None)
2022-10-18 14:35:50.988 DEBUG (MainThread) [zigpy_znp.api] Sending request: AF.DataRequestExt.Req(DstAddrModeAddress=AddrModeAddress(mode=<AddrMode.NWK: 2>, address=0xD6AE), DstEndpoint=11, DstPanId=0x0000, SrcEndpoint=1, ClusterId=6, TSN=241, Options=<TransmitOptions.SUPPRESS_ROUTE_DISC_NETWORK|ACK_REQUEST: 48>, Radius=0, Data=b'\x00\xF1\x00\x00\x00')
2022-10-18 14:35:51.008 DEBUG (MainThread) [zigpy_znp.api] Received command: AF.DataRequestExt.Rsp(Status=<Status.SUCCESS: 0>)
2022-10-18 14:35:51.053 DEBUG (MainThread) [zigpy_znp.api] Received command: ZDO.SrcRtgInd.Callback(DstAddr=0xD6AE, Relays=[0xDAB9])
2022-10-18 14:35:51.065 DEBUG (MainThread) [zigpy_znp.api] Received command: AF.DataConfirm.Callback(Status=<Status.SUCCESS: 0>, Endpoint=1, TSN=241)
2022-10-18 14:35:51.082 DEBUG (MainThread) [zigpy_znp.api] Received command: AF.IncomingMsg.Callback(GroupId=0x0000, ClusterId=6, SrcAddr=0xD6AE, SrcEndpoint=11, DstEndpoint=1, WasBroadcast=<Bool.false: 0>, LQI=40, SecurityUse=<Bool.false: 0>, TimeStamp=13528789, TSN=0, Data=b'\x18\xF1\x01\x00\x00\x00\x10\x00', MacSrcAddr=0xDAB9, MsgResultRadius=28)
2022-10-18 14:35:51.086 DEBUG (MainThread) [zigpy.application] Received a packet: ZigbeePacket(src=AddrModeAddress(addr_mode=<AddrMode.NWK: 2>, address=0xD6AE), src_ep=11, 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=6, data=Serialized[b'\x18\xf1\x01\x00\x00\x00\x10\x00'], tx_options=<TransmitOptions.NONE: 0>, radius=28, non_member_radius=0, lqi=40, rssi=None)
2022-10-18 14:35:51.088 DEBUG (MainThread) [zigpy.zcl] [0xD6AE:11:0x0006] Received ZCL frame: b'\x18\xf1\x01\x00\x00\x00\x10\x00'
2022-10-18 14:35:51.091 DEBUG (MainThread) [zigpy.zcl] [0xD6AE:11:0x0006] Decoded ZCL frame header: ZCLHeader(frame_control=FrameControl(frame_type=<FrameType.GLOBAL_COMMAND: 0>, is_manufacturer_specific=0, direction=<Direction.Client_to_Server: 1>, disable_default_response=1, reserved=0, *is_cluster=False, *is_general=True, *is_reply=True), tsn=241, command_id=1, *direction=<Direction.Client_to_Server: 1>, *is_reply=True)
2022-10-18 14:35:51.094 DEBUG (MainThread) [zigpy.zcl] [0xD6AE: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>))])
2022-10-18 14:35:51.099 DEBUG (MainThread) [zigpy.zcl] [0xD6AE:11:0x0008] Sending request header: ZCLHeader(frame_control=FrameControl(frame_type=<FrameType.GLOBAL_COMMAND: 0>, is_manufacturer_specific=False, direction=<Direction.Server_to_Client: 0>, disable_default_response=0, reserved=0, *is_cluster=False, *is_general=True, *is_reply=False), tsn=242, command_id=<GeneralCommand.Read_Attributes: 0>, *direction=<Direction.Server_to_Client: 0>, *is_reply=False)
2022-10-18 14:35:51.100 DEBUG (MainThread) [zigpy.zcl] [0xD6AE:11:0x0008] Sending request: Read_Attributes(attribute_ids=[0])
2022-10-18 14:35:51.101 DEBUG (MainThread) [zigpy_znp.zigbee.application] Sending packet ZigbeePacket(src=AddrModeAddress(addr_mode=<AddrMode.NWK: 2>, address=0x0000), src_ep=11, dst=AddrModeAddress(addr_mode=<AddrMode.NWK: 2>, address=0xD6AE), dst_ep=11, source_route=None, extended_timeout=False, tsn=242, profile_id=260, cluster_id=8, data=Serialized[b'\x00\xf2\x00\x00\x00'], tx_options=<TransmitOptions.ACK: 1>, radius=0, non_member_radius=0, lqi=None, rssi=None)
2022-10-18 14:35:51.105 DEBUG (MainThread) [zigpy_znp.api] Sending request: AF.DataRequestExt.Req(DstAddrModeAddress=AddrModeAddress(mode=<AddrMode.NWK: 2>, address=0xD6AE), DstEndpoint=11, DstPanId=0x0000, SrcEndpoint=1, ClusterId=8, TSN=242, Options=<TransmitOptions.SUPPRESS_ROUTE_DISC_NETWORK|ACK_REQUEST: 48>, Radius=0, Data=b'\x00\xF2\x00\x00\x00')
2022-10-18 14:35:51.129 DEBUG (MainThread) [zigpy_znp.api] Received command: AF.DataRequestExt.Rsp(Status=<Status.SUCCESS: 0>)
2022-10-18 14:35:51.168 DEBUG (MainThread) [zigpy_znp.api] Received command: AF.DataConfirm.Callback(Status=<Status.SUCCESS: 0>, Endpoint=1, TSN=242)
2022-10-18 14:35:51.188 DEBUG (MainThread) [zigpy_znp.api] Received command: AF.IncomingMsg.Callback(GroupId=0x0000, ClusterId=8, SrcAddr=0xD6AE, SrcEndpoint=11, DstEndpoint=1, WasBroadcast=<Bool.false: 0>, LQI=40, SecurityUse=<Bool.false: 0>, TimeStamp=13535361, TSN=0, Data=b'\x18\xF2\x01\x00\x00\x00\x20\x01', MacSrcAddr=0xDAB9, MsgResultRadius=28)
2022-10-18 14:35:51.191 DEBUG (MainThread) [zigpy.application] Received a packet: ZigbeePacket(src=AddrModeAddress(addr_mode=<AddrMode.NWK: 2>, address=0xD6AE), src_ep=11, 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=8, data=Serialized[b'\x18\xf2\x01\x00\x00\x00 \x01'], tx_options=<TransmitOptions.NONE: 0>, radius=28, non_member_radius=0, lqi=40, rssi=None)
2022-10-18 14:35:51.193 DEBUG (MainThread) [zigpy.zcl] [0xD6AE:11:0x0008] Received ZCL frame: b'\x18\xf2\x01\x00\x00\x00 \x01'
2022-10-18 14:35:51.195 DEBUG (MainThread) [zigpy.zcl] [0xD6AE:11:0x0008] Decoded ZCL frame header: ZCLHeader(frame_control=FrameControl(frame_type=<FrameType.GLOBAL_COMMAND: 0>, is_manufacturer_specific=0, direction=<Direction.Client_to_Server: 1>, disable_default_response=1, reserved=0, *is_cluster=False, *is_general=True, *is_reply=True), tsn=242, command_id=1, *direction=<Direction.Client_to_Server: 1>, *is_reply=True)
2022-10-18 14:35:51.198 DEBUG (MainThread) [zigpy.zcl] [0xD6AE:11:0x0008] Decoded ZCL frame: LevelControl:Read_Attributes_rsp(status_records=[ReadAttributeRecord(attrid=0x0000, status=<Status.SUCCESS: 0>, value=TypeValue(type=uint8_t, value=1))])
2022-10-18 14:35:51.202 DEBUG (MainThread) [homeassistant.components.zha.core.channels.base] [0xD6AE:11:0x0008]: received attribute: 0 update with value: 1
2022-10-18 14:35:51.203 DEBUG (MainThread) [homeassistant.components.zha.core.channels.base] [0xD6AE:11:0x0300]: Reading attributes in chunks: ['color_mode', 'current_x', 'current_y', 'color_loop_active']
2022-10-18 14:35:51.205 DEBUG (MainThread) [zigpy.zcl] [0xD6AE:11:0x0300] Sending request header: ZCLHeader(frame_control=FrameControl(frame_type=<FrameType.GLOBAL_COMMAND: 0>, is_manufacturer_specific=False, direction=<Direction.Server_to_Client: 0>, disable_default_response=0, reserved=0, *is_cluster=False, *is_general=True, *is_reply=False), tsn=243, command_id=<GeneralCommand.Read_Attributes: 0>, *direction=<Direction.Server_to_Client: 0>, *is_reply=False)
2022-10-18 14:35:51.207 DEBUG (MainThread) [zigpy.zcl] [0xD6AE:11:0x0300] Sending request: Read_Attributes(attribute_ids=[8, 3, 4, 16386])
2022-10-18 14:35:51.209 DEBUG (MainThread) [zigpy_znp.zigbee.application] Sending packet ZigbeePacket(src=AddrModeAddress(addr_mode=<AddrMode.NWK: 2>, address=0x0000), src_ep=11, dst=AddrModeAddress(addr_mode=<AddrMode.NWK: 2>, address=0xD6AE), dst_ep=11, source_route=None, extended_timeout=False, tsn=243, profile_id=260, cluster_id=768, data=Serialized[b'\x00\xf3\x00\x08\x00\x03\x00\x04\x00\x02@'], tx_options=<TransmitOptions.ACK: 1>, radius=0, non_member_radius=0, lqi=None, rssi=None)
2022-10-18 14:35:51.214 DEBUG (MainThread) [zigpy_znp.api] Sending request: AF.DataRequestExt.Req(DstAddrModeAddress=AddrModeAddress(mode=<AddrMode.NWK: 2>, address=0xD6AE), DstEndpoint=11, DstPanId=0x0000, SrcEndpoint=1, ClusterId=768, TSN=243, Options=<TransmitOptions.SUPPRESS_ROUTE_DISC_NETWORK|ACK_REQUEST: 48>, Radius=0, Data=b'\x00\xF3\x00\x08\x00\x03\x00\x04\x00\x02\x40')
2022-10-18 14:35:51.239 DEBUG (MainThread) [zigpy_znp.api] Received command: AF.DataRequestExt.Rsp(Status=<Status.SUCCESS: 0>)
2022-10-18 14:35:51.247 DEBUG (MainThread) [homeassistant.components.zha.core.channels.base] [0x5340:1:0x0006]: failed to get attributes '['on_off']' on 'on_off' cluster: Request failed after 5 attempts: <Status.MAC_NO_ACK: 233>
2022-10-18 14:35:51.247 DEBUG (MainThread) [homeassistant.components.zha.core.channels.base] [0x5340:1:0x0006]: async_initialize: retryable request #1 failed: Request failed after 5 attempts: <Status.MAC_NO_ACK: 233>. Retrying in 1.1s
2022-10-18 14:35:51.279 DEBUG (MainThread) [zigpy_znp.api] Received command: AF.DataConfirm.Callback(Status=<Status.SUCCESS: 0>, Endpoint=1, TSN=243)
2022-10-18 14:35:51.318 DEBUG (MainThread) [zigpy_znp.api] Received command: AF.IncomingMsg.Callback(GroupId=0x0000, ClusterId=768, SrcAddr=0xD6AE, SrcEndpoint=11, DstEndpoint=1, WasBroadcast=<Bool.false: 0>, LQI=36, SecurityUse=<Bool.false: 0>, TimeStamp=13542716, TSN=0, Data=b'\x18\xF3\x01\x08\x00\x00\x30\x01\x03\x00\x00\x21\x67\x52\x04\x00\x00\x21\x4E\x54\x02\x40\x00\x20\x00', MacSrcAddr=0xDAB9, MsgResultRadius=28)
2022-10-18 14:35:51.323 DEBUG (MainThread) [zigpy.application] Received a packet: ZigbeePacket(src=AddrModeAddress(addr_mode=<AddrMode.NWK: 2>, address=0xD6AE), src_ep=11, 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'\x18\xf3\x01\x08\x00\x000\x01\x03\x00\x00!gR\x04\x00\x00!NT\x02@\x00 \x00'], tx_options=<TransmitOptions.NONE: 0>, radius=28, non_member_radius=0, lqi=36, rssi=None)
2022-10-18 14:35:51.324 DEBUG (MainThread) [zigpy.zcl] [0xD6AE:11:0x0300] Received ZCL frame: b'\x18\xf3\x01\x08\x00\x000\x01\x03\x00\x00!gR\x04\x00\x00!NT\x02@\x00 \x00'
2022-10-18 14:35:51.327 DEBUG (MainThread) [zigpy.zcl] [0xD6AE:11:0x0300] Decoded ZCL frame header: ZCLHeader(frame_control=FrameControl(frame_type=<FrameType.GLOBAL_COMMAND: 0>, is_manufacturer_specific=0, direction=<Direction.Client_to_Server: 1>, disable_default_response=1, reserved=0, *is_cluster=False, *is_general=True, *is_reply=True), tsn=243, command_id=1, *direction=<Direction.Client_to_Server: 1>, *is_reply=True)
2022-10-18 14:35:51.331 DEBUG (MainThread) [zigpy.zcl] [0xD6AE:11:0x0300] Decoded ZCL frame: Color:Read_Attributes_rsp(status_records=[ReadAttributeRecord(attrid=0x0008, status=<Status.SUCCESS: 0>, value=TypeValue(type=enum8, value=<enum8.undefined_0x01: 1>)), ReadAttributeRecord(attrid=0x0003, status=<Status.SUCCESS: 0>, value=TypeValue(type=uint16_t, value=21095)), ReadAttributeRecord(attrid=0x0004, status=<Status.SUCCESS: 0>, value=TypeValue(type=uint16_t, value=21582)), ReadAttributeRecord(attrid=0x4002, status=<Status.SUCCESS: 0>, value=TypeValue(type=uint8_t, value=0))])
2022-10-18 14:35:51.336 DEBUG (MainThread) [homeassistant.components.zha.core.channels.base] [0x5340:1:0x0300]: failed to get attributes '['color_mode', 'color_loop_active', 'current_x', 'current_y', 'current_hue']' on 'light_color' cluster: Request failed after 5 attempts: <Status.MAC_NO_ACK: 233>
2022-10-18 14:35:51.336 DEBUG (MainThread) [homeassistant.components.zha.core.channels.base] [0x5340:1:0x0300]: async_initialize: retryable request #1 failed: Request failed after 5 attempts: <Status.MAC_NO_ACK: 233>. Retrying in 1.2s
2022-10-18 14:35:51.368 DEBUG (MainThread) [homeassistant.components.zha.core.channels.base] [0x5340:1:0x0008]: failed to get attributes '['current_level']' on 'level' cluster: Request failed after 5 attempts: <Status.MAC_NO_ACK: 233>
2022-10-18 14:35:51.368 DEBUG (MainThread) [homeassistant.components.zha.core.channels.base] [0x5340:1:0x0008]: async_initialize: retryable request #1 failed: Request failed after 5 attempts: <Status.MAC_NO_ACK: 233>. Retrying in 1.0s
2022-10-18 14:35:52.332 DEBUG (MainThread) [homeassistant.components.zha.core.channels.base] [0x5340:1:0x0006]: initializing channel: from_cache: False
2022-10-18 14:35:52.333 DEBUG (MainThread) [homeassistant.components.zha.core.channels.base] [0x5340:1:0x0006]: initializing cached channel attributes: ['start_up_on_off']
2022-10-18 14:35:52.334 DEBUG (MainThread) [homeassistant.components.zha.core.channels.base] [0x5340:1:0x0006]: Reading attributes in chunks: ['start_up_on_off']
2022-10-18 14:35:52.334 DEBUG (MainThread) [homeassistant.components.zha.core.channels.base] [0x5340:1:0x0006]: initializing uncached channel attributes: ['on_off'] - from cache[False]
2022-10-18 14:35:52.335 DEBUG (MainThread) [homeassistant.components.zha.core.channels.base] [0x5340:1:0x0006]: Reading attributes in chunks: ['on_off']
2022-10-18 14:35:52.340 DEBUG (MainThread) [zigpy.zcl] [0x5340:1:0x0006] Sending request header: ZCLHeader(frame_control=FrameControl(frame_type=<FrameType.GLOBAL_COMMAND: 0>, is_manufacturer_specific=False, direction=<Direction.Server_to_Client: 0>, disable_default_response=0, reserved=0, *is_cluster=False, *is_general=True, *is_reply=False), tsn=244, command_id=<GeneralCommand.Read_Attributes: 0>, *direction=<Direction.Server_to_Client: 0>, *is_reply=False)
2022-10-18 14:35:52.343 DEBUG (MainThread) [zigpy.zcl] [0x5340:1:0x0006] Sending request: Read_Attributes(attribute_ids=[0])
2022-10-18 14:35:52.344 DEBUG (MainThread) [zigpy_znp.zigbee.application] Sending packet ZigbeePacket(src=AddrModeAddress(addr_mode=<AddrMode.NWK: 2>, address=0x0000), src_ep=1, dst=AddrModeAddress(addr_mode=<AddrMode.NWK: 2>, address=0x5340), dst_ep=1, source_route=None, extended_timeout=False, tsn=244, profile_id=260, cluster_id=6, data=Serialized[b'\x00\xf4\x00\x00\x00'], tx_options=<TransmitOptions.ACK: 1>, radius=0, non_member_radius=0, lqi=None, rssi=None)
2022-10-18 14:35:52.348 DEBUG (MainThread) [zigpy_znp.api] Sending request: AF.DataRequestExt.Req(DstAddrModeAddress=AddrModeAddress(mode=<AddrMode.NWK: 2>, address=0x5340), DstEndpoint=1, DstPanId=0x0000, SrcEndpoint=1, ClusterId=6, TSN=244, Options=<TransmitOptions.SUPPRESS_ROUTE_DISC_NETWORK|ACK_REQUEST: 48>, Radius=0, Data=b'\x00\xF4\x00\x00\x00')
2022-10-18 14:35:52.360 DEBUG (MainThread) [zigpy.topology] Scanning neighbors of 04:cd:15:ff:fe:35:ec:ac/0x383e device
2022-10-18 14:35:52.360 DEBUG (MainThread) [zigpy.util] Tries remaining: 3
2022-10-18 14:35:52.361 DEBUG (MainThread) [zigpy_znp.zigbee.application] Sending packet ZigbeePacket(src=AddrModeAddress(addr_mode=<AddrMode.NWK: 2>, address=0x0000), src_ep=0, dst=AddrModeAddress(addr_mode=<AddrMode.NWK: 2>, address=0x383E), dst_ep=0, source_route=None, extended_timeout=False, tsn=245, profile_id=0, cluster_id=<ZDOCmd.Mgmt_Lqi_req: 0x0031>, data=Serialized[b'\xf5\x00'], tx_options=<TransmitOptions.ACK: 1>, radius=0, non_member_radius=0, lqi=None, rssi=None)
2022-10-18 14:35:52.372 DEBUG (MainThread) [zigpy_znp.api] Received command: AF.DataRequestExt.Rsp(Status=<Status.SUCCESS: 0>)
2022-10-18 14:35:52.373 DEBUG (MainThread) [zigpy_znp.api] Sending request: ZDO.ExtRouteChk.Req(Dst=0x383E, RtStatus=<RouteStatus.ACTIVE: 1>, Options=<RouteOptions.NO_ROUTE_CACHE|MTO_ROUTE: 3>)
2022-10-18 14:35:52.386 DEBUG (MainThread) [zigpy_znp.api] Received command: ZDO.ExtRouteChk.Rsp(Status=<RoutingStatus.SUCCESS: 0>)
2022-10-18 14:35:52.389 DEBUG (MainThread) [zigpy_znp.api] Sending request: AF.DataRequestExt.Req(DstAddrModeAddress=AddrModeAddress(mode=<AddrMode.NWK: 2>, address=0x383E), DstEndpoint=0, DstPanId=0x0000, SrcEndpoint=0, ClusterId=49, TSN=245, Options=<TransmitOptions.SUPPRESS_ROUTE_DISC_NETWORK|ACK_REQUEST: 48>, Radius=0, Data=b'\xF5\x00')
2022-10-18 14:35:52.413 DEBUG (MainThread) [homeassistant.components.zha.core.channels.base] [0x5340:1:0x0008]: initializing channel: from_cache: False
2022-10-18 14:35:52.413 DEBUG (MainThread) [homeassistant.components.zha.core.channels.base] [0x5340:1:0x0008]: initializing cached channel attributes: ['on_off_transition_time', 'on_level', 'on_transition_time', 'off_transition_time', 'default_move_rate', 'start_up_current_level']
2022-10-18 14:35:52.414 DEBUG (MainThread) [homeassistant.components.zha.core.channels.base] [0x5340:1:0x0008]: Reading attributes in chunks: ['on_off_transition_time', 'on_level', 'on_transition_time', 'off_transition_time', 'default_move_rate']
2022-10-18 14:35:52.414 DEBUG (MainThread) [homeassistant.components.zha.core.channels.base] [0x5340:1:0x0008]: Reading attributes in chunks: ['start_up_current_level']
2022-10-18 14:35:52.414 DEBUG (MainThread) [homeassistant.components.zha.core.channels.base] [0x5340:1:0x0008]: initializing uncached channel attributes: ['current_level'] - from cache[False]
2022-10-18 14:35:52.415 DEBUG (MainThread) [homeassistant.components.zha.core.channels.base] [0x5340:1:0x0008]: Reading attributes in chunks: ['current_level']
2022-10-18 14:35:52.416 DEBUG (MainThread) [zigpy.zcl] [0x5340:1:0x0008] Sending request header: ZCLHeader(frame_control=FrameControl(frame_type=<FrameType.GLOBAL_COMMAND: 0>, is_manufacturer_specific=False, direction=<Direction.Server_to_Client: 0>, disable_default_response=0, reserved=0, *is_cluster=False, *is_general=True, *is_reply=False), tsn=246, command_id=<GeneralCommand.Read_Attributes: 0>, *direction=<Direction.Server_to_Client: 0>, *is_reply=False)
2022-10-18 14:35:52.418 DEBUG (MainThread) [zigpy.zcl] [0x5340:1:0x0008] Sending request: Read_Attributes(attribute_ids=[0])
2022-10-18 14:35:52.420 DEBUG (MainThread) [zigpy_znp.zigbee.application] Sending packet ZigbeePacket(src=AddrModeAddress(addr_mode=<AddrMode.NWK: 2>, address=0x0000), src_ep=1, dst=AddrModeAddress(addr_mode=<AddrMode.NWK: 2>, address=0x5340), dst_ep=1, source_route=None, extended_timeout=False, tsn=246, profile_id=260, cluster_id=8, data=Serialized[b'\x00\xf6\x00\x00\x00'], tx_options=<TransmitOptions.ACK: 1>, radius=0, non_member_radius=0, lqi=None, rssi=None)
2022-10-18 14:35:52.425 DEBUG (MainThread) [zigpy_znp.api] Received command: AF.DataRequestExt.Rsp(Status=<Status.SUCCESS: 0>)
2022-10-18 14:35:52.427 DEBUG (MainThread) [zigpy_znp.api] Sending request: AF.DataRequestExt.Req(DstAddrModeAddress=AddrModeAddress(mode=<AddrMode.NWK: 2>, address=0x5340), DstEndpoint=1, DstPanId=0x0000, SrcEndpoint=1, ClusterId=8, TSN=246, Options=<TransmitOptions.SUPPRESS_ROUTE_DISC_NETWORK|ACK_REQUEST: 48>, Radius=0, Data=b'\x00\xF6\x00\x00\x00')
2022-10-18 14:35:52.459 DEBUG (MainThread) [zigpy_znp.api] Received command: AF.DataConfirm.Callback(Status=<Status.MAC_NO_ACK: 233>, Endpoint=1, TSN=244)
2022-10-18 14:35:52.473 DEBUG (MainThread) [zigpy_znp.api] Received command: ZDO.MgmtLqiRsp.Callback(Src=0x383E, Status=<Status.SUCCESS: 0>, Neighbors=Neighbors(entries=6, start_index=0, neighbor_table_list=[Neighbor(extended_pan_id=c9:66:37:6e:15:e1:f3:57, ieee=00:12:4b:00:24:c0:84:e6, nwk=0x0000, device_type=<DeviceType.Coordinator: 0>, rx_on_when_idle=<RxOnWhenIdle.On: 1>, relationship=<RelationShip.Parent: 0>, reserved1=0, permit_joining=<PermitJoins.Unknown: 2>, reserved2=0, depth=0, lqi=143), Neighbor(extended_pan_id=c9:66:37:6e:15:e1:f3:57, ieee=5c:02:72:ff:fe:22:82:27, nwk=0x0CA2, device_type=<DeviceType.Router: 1>, rx_on_when_idle=<RxOnWhenIdle.On: 1>, relationship=<RelationShip.Sibling: 2>, reserved1=0, permit_joining=<PermitJoins.Unknown: 2>, reserved2=0, depth=15, lqi=152), Neighbor(extended_pan_id=c9:66:37:6e:15:e1:f3:57, ieee=04:cd:15:ff:fe:c1:f8:1f, nwk=0x31E7, device_type=<DeviceType.Router: 1>, rx_on_when_idle=<RxOnWhenIdle.On: 1>, relationship=<RelationShip.Sibling: 2>, reserved1=0, permit_joining=<PermitJoins.Unknown: 2>, reserved2=0, depth=15, lqi=151)]))
2022-10-18 14:35:52.475 DEBUG (MainThread) [zigpy_znp.api] Command was not handled
2022-10-18 14:35:52.477 DEBUG (MainThread) [zigpy_znp.zigbee.application] Request failed (Unsuccessful request status code: <Status.MAC_NO_ACK: 233>), retry attempt 1 of 5
2022-10-18 14:35:52.480 DEBUG (MainThread) [zigpy_znp.api] Received command: ZDO.MsgCbIncoming.Callback(Src=0x383E, IsBroadcast=<Bool.false: 0>, ClusterId=32817, SecurityUse=0, TSN=245, MacDst=0x0000, Data=b'\x00\x06\x00\x03\x57\xF3\xE1\x15\x6E\x37\x66\xC9\xE6\x84\xC0\x24\x00\x4B\x12\x00\x00\x00\x04\x02\x00\x8F\x57\xF3\xE1\x15\x6E\x37\x66\xC9\x27\x82\x22\xFE\xFF\x72\x02\x5C\xA2\x0C\x25\x02\x0F\x98\x57\xF3\xE1\x15\x6E\x37\x66\xC9\x1F\xF8\xC1\xFE\xFF\x15\xCD\x04\xE7\x31\x25\x02\x0F\x97')
2022-10-18 14:35:52.481 DEBUG (MainThread) [zigpy_znp.api] Received command: AF.DataRequestExt.Rsp(Status=<Status.SUCCESS: 0>)
2022-10-18 14:35:52.487 DEBUG (MainThread) [zigpy.application] Received a packet: ZigbeePacket(src=AddrModeAddress(addr_mode=<AddrMode.NWK: 2>, address=0x383E), src_ep=0, dst=AddrModeAddress(addr_mode=<AddrMode.NWK: 2>, address=0x0000), dst_ep=0, source_route=None, extended_timeout=False, tsn=245, profile_id=0, cluster_id=32817, data=Serialized[b'\xf5\x00\x06\x00\x03W\xf3\xe1\x15n7f\xc9\xe6\x84\xc0$\x00K\x12\x00\x00\x00\x04\x02\x00\x8fW\xf3\xe1\x15n7f\xc9\'\x82"\xfe\xffr\x02\\\xa2\x0c%\x02\x0f\x98W\xf3\xe1\x15n7f\xc9\x1f\xf8\xc1\xfe\xff\x15\xcd\x04\xe71%\x02\x0f\x97'], tx_options=<TransmitOptions.NONE: 0>, radius=0, non_member_radius=0, lqi=None, rssi=None)
2022-10-18 14:35:52.498 DEBUG (MainThread) [zigpy.neighbor] [0x383e] request status: Status.SUCCESS. response: Neighbors(entries=6, start_index=0, neighbor_table_list=[Neighbor(extended_pan_id=c9:66:37:6e:15:e1:f3:57, ieee=00:12:4b:00:24:c0:84:e6, nwk=0x0000, device_type=<DeviceType.Coordinator: 0>, rx_on_when_idle=<RxOnWhenIdle.On: 1>, relationship=<RelationShip.Parent: 0>, reserved1=0, permit_joining=<PermitJoins.Unknown: 2>, reserved2=0, depth=0, lqi=143), Neighbor(extended_pan_id=c9:66:37:6e:15:e1:f3:57, ieee=5c:02:72:ff:fe:22:82:27, nwk=0x0CA2, device_type=<DeviceType.Router: 1>, rx_on_when_idle=<RxOnWhenIdle.On: 1>, relationship=<RelationShip.Sibling: 2>, reserved1=0, permit_joining=<PermitJoins.Unknown: 2>, reserved2=0, depth=15, lqi=152), Neighbor(extended_pan_id=c9:66:37:6e:15:e1:f3:57, ieee=04:cd:15:ff:fe:c1:f8:1f, nwk=0x31E7, device_type=<DeviceType.Router: 1>, rx_on_when_idle=<RxOnWhenIdle.On: 1>, relationship=<RelationShip.Sibling: 2>, reserved1=0, permit_joining=<PermitJoins.Unknown: 2>, reserved2=0, depth=15, lqi=151)])
2022-10-18 14:35:52.542 DEBUG (MainThread) [zigpy_znp.api] Received command: AF.DataConfirm.Callback(Status=<Status.MAC_NO_ACK: 233>, Endpoint=1, TSN=246)
2022-10-18 14:35:52.545 DEBUG (MainThread) [zigpy_znp.zigbee.application] Request failed (Unsuccessful request status code: <Status.MAC_NO_ACK: 233>), retry attempt 1 of 5
2022-10-18 14:35:52.574 DEBUG (MainThread) [homeassistant.components.zha.core.channels.base] [0x5340:1:0x0300]: initializing channel: from_cache: False
2022-10-18 14:35:52.575 DEBUG (MainThread) [homeassistant.components.zha.core.channels.base] [0x5340:1:0x0300]: initializing cached channel attributes: ['color_temp_physical_min', 'color_temp_physical_max', 'color_capabilities']
2022-10-18 14:35:52.575 DEBUG (MainThread) [homeassistant.components.zha.core.channels.base] [0x5340:1:0x0300]: Reading attributes in chunks: ['color_temp_physical_min', 'color_temp_physical_max', 'color_capabilities']
2022-10-18 14:35:52.576 DEBUG (MainThread) [homeassistant.components.zha.core.channels.base] [0x5340:1:0x0300]: initializing uncached channel attributes: ['color_mode', 'color_loop_active', 'current_x', 'current_y', 'current_hue', 'enhanced_current_hue', 'current_saturation', 'color_temperature'] - from cache[False]
2022-10-18 14:35:52.577 DEBUG (MainThread) [homeassistant.components.zha.core.channels.base] [0x5340:1:0x0300]: Reading attributes in chunks: ['color_mode', 'color_loop_active', 'current_x', 'current_y', 'current_hue']
2022-10-18 14:35:52.580 DEBUG (MainThread) [zigpy.zcl] [0x5340:1:0x0300] Sending request header: ZCLHeader(frame_control=FrameControl(frame_type=<FrameType.GLOBAL_COMMAND: 0>, is_manufacturer_specific=False, direction=<Direction.Server_to_Client: 0>, disable_default_response=0, reserved=0, *is_cluster=False, *is_general=True, *is_reply=False), tsn=247, command_id=<GeneralCommand.Read_Attributes: 0>, *direction=<Direction.Server_to_Client: 0>, *is_reply=False)
2022-10-18 14:35:52.584 DEBUG (MainThread) [zigpy.zcl] [0x5340:1:0x0300] Sending request: Read_Attributes(attribute_ids=[8, 16386, 3, 4, 0])
2022-10-18 14:35:52.586 DEBUG (MainThread) [zigpy_znp.zigbee.application] Sending packet ZigbeePacket(src=AddrModeAddress(addr_mode=<AddrMode.NWK: 2>, address=0x0000), src_ep=1, dst=AddrModeAddress(addr_mode=<AddrMode.NWK: 2>, address=0x5340), dst_ep=1, source_route=None, extended_timeout=False, tsn=247, profile_id=260, cluster_id=768, data=Serialized[b'\x00\xf7\x00\x08\x00\x02@\x03\x00\x04\x00\x00\x00'], tx_options=<TransmitOptions.ACK: 1>, radius=0, non_member_radius=0, lqi=None, rssi=None)
2022-10-18 14:35:52.590 DEBUG (MainThread) [zigpy_znp.api] Sending request: AF.DataRequestExt.Req(DstAddrModeAddress=AddrModeAddress(mode=<AddrMode.NWK: 2>, address=0x5340), DstEndpoint=1, DstPanId=0x0000, SrcEndpoint=1, ClusterId=768, TSN=247, Options=<TransmitOptions.SUPPRESS_ROUTE_DISC_NETWORK|ACK_REQUEST: 48>, Radius=0, Data=b'\x00\xF7\x00\x08\x00\x02\x40\x03\x00\x04\x00\x00\x00')
2022-10-18 14:35:52.614 DEBUG (MainThread) [zigpy_znp.api] Received command: AF.DataRequestExt.Rsp(Status=<Status.SUCCESS: 0>)
2022-10-18 14:35:52.690 DEBUG (MainThread) [zigpy_znp.api] Received command: AF.DataConfirm.Callback(Status=<Status.MAC_NO_ACK: 233>, Endpoint=1, TSN=247)
2022-10-18 14:35:52.696 DEBUG (MainThread) [zigpy_znp.zigbee.application] Request failed (Unsuccessful request status code: <Status.MAC_NO_ACK: 233>), retry attempt 1 of 5
2022-10-18 14:35:53.971 DEBUG (MainThread) [zigpy.neighbor] [0x383e] Querying next starting at 3
2022-10-18 14:35:53.972 DEBUG (MainThread) [zigpy.util] Tries remaining: 3
2022-10-18 14:35:53.973 DEBUG (MainThread) [zigpy_znp.zigbee.application] Sending packet ZigbeePacket(src=AddrModeAddress(addr_mode=<AddrMode.NWK: 2>, address=0x0000), src_ep=0, dst=AddrModeAddress(addr_mode=<AddrMode.NWK: 2>, address=0x383E), dst_ep=0, source_route=None, extended_timeout=False, tsn=248, profile_id=0, cluster_id=<ZDOCmd.Mgmt_Lqi_req: 0x0031>, data=Serialized[b'\xf8\x03'], tx_options=<TransmitOptions.ACK: 1>, radius=0, non_member_radius=0, lqi=None, rssi=None)
2022-10-18 14:35:53.975 DEBUG (MainThread) [zigpy_znp.api] Sending request: ZDO.ExtRouteChk.Req(Dst=0x383E, RtStatus=<RouteStatus.ACTIVE: 1>, Options=<RouteOptions.NO_ROUTE_CACHE|MTO_ROUTE: 3>)
2022-10-18 14:35:53.987 DEBUG (MainThread) [zigpy_znp.api] Received command: ZDO.ExtRouteChk.Rsp(Status=<RoutingStatus.SUCCESS: 0>)
2022-10-18 14:35:53.990 DEBUG (MainThread) [zigpy_znp.api] Sending request: AF.DataRequestExt.Req(DstAddrModeAddress=AddrModeAddress(mode=<AddrMode.NWK: 2>, address=0x5340), DstEndpoint=1, DstPanId=0x0000, SrcEndpoint=1, ClusterId=6, TSN=244, Options=<TransmitOptions.SUPPRESS_ROUTE_DISC_NETWORK|ACK_REQUEST: 48>, Radius=0, Data=b'\x00\xF4\x00\x00\x00')
2022-10-18 14:35:54.019 DEBUG (MainThread) [zigpy_znp.api] Received command: AF.DataRequestExt.Rsp(Status=<Status.SUCCESS: 0>)
2022-10-18 14:35:54.023 DEBUG (MainThread) [zigpy_znp.api] Sending request: AF.DataRequestExt.Req(DstAddrModeAddress=AddrModeAddress(mode=<AddrMode.NWK: 2>, address=0x383E), DstEndpoint=0, DstPanId=0x0000, SrcEndpoint=0, ClusterId=49, TSN=248, Options=<TransmitOptions.SUPPRESS_ROUTE_DISC_NETWORK|ACK_REQUEST: 48>, Radius=0, Data=b'\xF8\x03')
2022-10-18 14:35:54.055 DEBUG (MainThread) [zigpy_znp.api] Received command: AF.DataRequestExt.Rsp(Status=<Status.SUCCESS: 0>)
2022-10-18 14:35:54.059 DEBUG (MainThread) [zigpy_znp.api] Sending request: AF.DataRequestExt.Req(DstAddrModeAddress=AddrModeAddress(mode=<AddrMode.NWK: 2>, address=0x5340), DstEndpoint=1, DstPanId=0x0000, SrcEndpoint=1, ClusterId=8, TSN=246, Options=<TransmitOptions.SUPPRESS_ROUTE_DISC_NETWORK|ACK_REQUEST: 48>, Radius=0, Data=b'\x00\xF6\x00\x00\x00')
2022-10-18 14:35:54.114 DEBUG (MainThread) [zigpy_znp.api] Received command: ZDO.MgmtLqiRsp.Callback(Src=0x383E, Status=<Status.SUCCESS: 0>, Neighbors=Neighbors(entries=6, start_index=3, neighbor_table_list=[Neighbor(extended_pan_id=c9:66:37:6e:15:e1:f3:57, ieee=00:17:88:01:00:1c:e9:71, nwk=0xD6AE, device_type=<DeviceType.Router: 1>, rx_on_when_idle=<RxOnWhenIdle.On: 1>, relationship=<RelationShip.Sibling: 2>, reserved1=0, permit_joining=<PermitJoins.Unknown: 2>, reserved2=0, depth=15, lqi=164), Neighbor(extended_pan_id=c9:66:37:6e:15:e1:f3:57, ieee=b4:e3:f9:ff:fe:ba:7e:a2, nwk=0xDAB9, device_type=<DeviceType.Router: 1>, rx_on_when_idle=<RxOnWhenIdle.On: 1>, relationship=<RelationShip.Sibling: 2>, reserved1=0, permit_joining=<PermitJoins.Unknown: 2>, reserved2=0, depth=15, lqi=166), Neighbor(extended_pan_id=c9:66:37:6e:15:e1:f3:57, ieee=04:cd:15:ff:fe:32:99:4d, nwk=0xFA52, device_type=<DeviceType.Router: 1>, rx_on_when_idle=<RxOnWhenIdle.On: 1>, relationship=<RelationShip.Sibling: 2>, reserved1=0, permit_joining=<PermitJoins.Unknown: 2>, reserved2=0, depth=15, lqi=211)]))
2022-10-18 14:35:54.116 DEBUG (MainThread) [zigpy_znp.api] Command was not handled
2022-10-18 14:35:54.120 DEBUG (MainThread) [zigpy_znp.api] Received command: ZDO.MsgCbIncoming.Callback(Src=0x383E, IsBroadcast=<Bool.false: 0>, ClusterId=32817, SecurityUse=0, TSN=248, MacDst=0x0000, Data=b'\x00\x06\x03\x03\x57\xF3\xE1\x15\x6E\x37\x66\xC9\x71\xE9\x1C\x00\x01\x88\x17\x00\xAE\xD6\x25\x02\x0F\xA4\x57\xF3\xE1\x15\x6E\x37\x66\xC9\xA2\x7E\xBA\xFE\xFF\xF9\xE3\xB4\xB9\xDA\x25\x02\x0F\xA6\x57\xF3\xE1\x15\x6E\x37\x66\xC9\x4D\x99\x32\xFE\xFF\x15\xCD\x04\x52\xFA\x25\x02\x0F\xD3')
2022-10-18 14:35:54.122 DEBUG (MainThread) [zigpy_znp.api] Received command: AF.DataRequestExt.Rsp(Status=<Status.SUCCESS: 0>)
2022-10-18 14:35:54.123 DEBUG (MainThread) [zigpy_znp.api] Received command: AF.DataConfirm.Callback(Status=<Status.MAC_NO_ACK: 233>, Endpoint=1, TSN=244)
2022-10-18 14:35:54.128 DEBUG (MainThread) [zigpy.application] Received a packet: ZigbeePacket(src=AddrModeAddress(addr_mode=<AddrMode.NWK: 2>, address=0x383E), src_ep=0, dst=AddrModeAddress(addr_mode=<AddrMode.NWK: 2>, address=0x0000), dst_ep=0, source_route=None, extended_timeout=False, tsn=248, profile_id=0, cluster_id=32817, data=Serialized[b'\xf8\x00\x06\x03\x03W\xf3\xe1\x15n7f\xc9q\xe9\x1c\x00\x01\x88\x17\x00\xae\xd6%\x02\x0f\xa4W\xf3\xe1\x15n7f\xc9\xa2~\xba\xfe\xff\xf9\xe3\xb4\xb9\xda%\x02\x0f\xa6W\xf3\xe1\x15n7f\xc9M\x992\xfe\xff\x15\xcd\x04R\xfa%\x02\x0f\xd3'], tx_options=<TransmitOptions.NONE: 0>, radius=0, non_member_radius=0, lqi=None, rssi=None)
2022-10-18 14:35:54.140 DEBUG (MainThread) [zigpy.neighbor] [0x383e] request status: Status.SUCCESS. response: Neighbors(entries=6, start_index=3, neighbor_table_list=[Neighbor(extended_pan_id=c9:66:37:6e:15:e1:f3:57, ieee=00:17:88:01:00:1c:e9:71, nwk=0xD6AE, device_type=<DeviceType.Router: 1>, rx_on_when_idle=<RxOnWhenIdle.On: 1>, relationship=<RelationShip.Sibling: 2>, reserved1=0, permit_joining=<PermitJoins.Unknown: 2>, reserved2=0, depth=15, lqi=164), Neighbor(extended_pan_id=c9:66:37:6e:15:e1:f3:57, ieee=b4:e3:f9:ff:fe:ba:7e:a2, nwk=0xDAB9, device_type=<DeviceType.Router: 1>, rx_on_when_idle=<RxOnWhenIdle.On: 1>, relationship=<RelationShip.Sibling: 2>, reserved1=0, permit_joining=<PermitJoins.Unknown: 2>, reserved2=0, depth=15, lqi=166), Neighbor(extended_pan_id=c9:66:37:6e:15:e1:f3:57, ieee=04:cd:15:ff:fe:32:99:4d, nwk=0xFA52, device_type=<DeviceType.Router: 1>, rx_on_when_idle=<RxOnWhenIdle.On: 1>, relationship=<RelationShip.Sibling: 2>, reserved1=0, permit_joining=<PermitJoins.Unknown: 2>, reserved2=0, depth=15, lqi=211)])
2022-10-18 14:35:54.142 DEBUG (MainThread) [zigpy.neighbor] [0x383e] Done scanning. Total 6 neighbours
2022-10-18 14:35:54.143 DEBUG (MainThread) [zigpy_znp.zigbee.application] Request failed (Unsuccessful request status code: <Status.MAC_NO_ACK: 233>), retry attempt 2 of 5
2022-10-18 14:35:54.191 DEBUG (MainThread) [zigpy_znp.api] Received command: AF.DataConfirm.Callback(Status=<Status.MAC_NO_ACK: 233>, Endpoint=1, TSN=246)
2022-10-18 14:35:54.195 DEBUG (MainThread) [zigpy_znp.zigbee.application] Request failed (Unsuccessful request status code: <Status.MAC_NO_ACK: 233>), retry attempt 2 of 5
2022-10-18 14:35:54.203 DEBUG (MainThread) [zigpy_znp.api] Sending request: AF.DataRequestExt.Req(DstAddrModeAddress=AddrModeAddress(mode=<AddrMode.NWK: 2>, address=0x5340), DstEndpoint=1, DstPanId=0x0000, SrcEndpoint=1, ClusterId=768, TSN=247, Options=<TransmitOptions.SUPPRESS_ROUTE_DISC_NETWORK|ACK_REQUEST: 48>, Radius=0, Data=b'\x00\xF7\x00\x08\x00\x02\x40\x03\x00\x04\x00\x00\x00')
2022-10-18 14:35:54.224 DEBUG (MainThread) [zigpy_znp.api] Received command: AF.DataRequestExt.Rsp(Status=<Status.SUCCESS: 0>)
2022-10-18 14:35:54.309 DEBUG (MainThread) [zigpy_znp.api] Received command: AF.DataConfirm.Callback(Status=<Status.MAC_NO_ACK: 233>, Endpoint=1, TSN=247)
2022-10-18 14:35:54.312 DEBUG (MainThread) [zigpy_znp.zigbee.application] Request failed (Unsuccessful request status code: <Status.MAC_NO_ACK: 233>), retry attempt 2 of 5
2022-10-18 14:35:54.648 DEBUG (MainThread) [zigpy_znp.api] Sending request: AF.DataRequestSrcRtg.Req(DstAddr=0x5340, DstEndpoint=1, SrcEndpoint=1, ClusterId=6, TSN=244, Options=<TransmitOptions.SUPPRESS_ROUTE_DISC_NETWORK|ACK_REQUEST: 48>, Radius=0, SourceRoute=[], Data=b'\x00\xF4\x00\x00\x00')
2022-10-18 14:35:54.670 DEBUG (MainThread) [zigpy_znp.api] Received command: AF.DataRequestSrcRtg.Rsp(Status=<Status.SUCCESS: 0>)
2022-10-18 14:35:54.701 DEBUG (MainThread) [zigpy_znp.api] Sending request: AF.DataRequestSrcRtg.Req(DstAddr=0x5340, DstEndpoint=1, SrcEndpoint=1, ClusterId=8, TSN=246, Options=<TransmitOptions.SUPPRESS_ROUTE_DISC_NETWORK|ACK_REQUEST: 48>, Radius=0, SourceRoute=[], Data=b'\x00\xF6\x00\x00\x00')
2022-10-18 14:35:54.733 DEBUG (MainThread) [zigpy_znp.api] Received command: AF.DataRequestSrcRtg.Rsp(Status=<Status.SUCCESS: 0>)
2022-10-18 14:35:54.759 DEBUG (MainThread) [zigpy_znp.api] Received command: AF.DataConfirm.Callback(Status=<Status.MAC_NO_ACK: 233>, Endpoint=1, TSN=244)
2022-10-18 14:35:54.765 DEBUG (MainThread) [zigpy_znp.api] Sending request: ZDO.ExtRouteDisc.Req(Dst=0x5340, Options=<RouteDiscoveryOptions.UNICAST: 0>, Radius=30)
2022-10-18 14:35:54.773 DEBUG (MainThread) [zigpy_znp.api] Received command: ZDO.ExtRouteDisc.Rsp(Status=<Status.SUCCESS: 0>)
2022-10-18 14:35:54.802 DEBUG (MainThread) [zigpy_znp.api] Received command: AF.DataConfirm.Callback(Status=<Status.MAC_NO_ACK: 233>, Endpoint=1, TSN=246)
2022-10-18 14:35:54.816 DEBUG (MainThread) [zigpy_znp.api] Sending request: AF.DataRequestSrcRtg.Req(DstAddr=0x5340, DstEndpoint=1, SrcEndpoint=1, ClusterId=768, TSN=247, Options=<TransmitOptions.SUPPRESS_ROUTE_DISC_NETWORK|ACK_REQUEST: 48>, Radius=0, SourceRoute=[], Data=b'\x00\xF7\x00\x08\x00\x02\x40\x03\x00\x04\x00\x00\x00')
2022-10-18 14:35:54.838 DEBUG (MainThread) [zigpy_znp.api] Received command: AF.DataRequestSrcRtg.Rsp(Status=<Status.SUCCESS: 0>)
2022-10-18 14:35:54.923 DEBUG (MainThread) [zigpy_znp.api] Received command: AF.DataConfirm.Callback(Status=<Status.MAC_NO_ACK: 233>, Endpoint=1, TSN=247)
2022-10-18 14:35:56.077 DEBUG (MainThread) [zigpy_znp.zigbee.application] Request failed (Unsuccessful request status code: <Status.MAC_NO_ACK: 233>), retry attempt 3 of 5
2022-10-18 14:35:56.079 DEBUG (MainThread) [zigpy_znp.zigbee.application] Request failed (Unsuccessful request status code: <Status.MAC_NO_ACK: 233>), retry attempt 3 of 5
2022-10-18 14:35:56.079 DEBUG (MainThread) [zigpy_znp.zigbee.application] Request failed (Unsuccessful request status code: <Status.MAC_NO_ACK: 233>), retry attempt 3 of 5
2022-10-18 14:35:56.583 DEBUG (MainThread) [zigpy_znp.api] Sending request: AF.DataRequestExt.Req(DstAddrModeAddress=AddrModeAddress(mode=<AddrMode.NWK: 2>, address=0x5340), DstEndpoint=1, DstPanId=0x0000, SrcEndpoint=1, ClusterId=6, TSN=244, Options=<TransmitOptions.SUPPRESS_ROUTE_DISC_NETWORK|ACK_REQUEST: 48>, Radius=0, Data=b'\x00\xF4\x00\x00\x00')
2022-10-18 14:35:56.610 DEBUG (MainThread) [zigpy_znp.api] Received command: AF.DataRequestExt.Rsp(Status=<Status.SUCCESS: 0>)
2022-10-18 14:35:56.613 DEBUG (MainThread) [zigpy_znp.api] Sending request: AF.DataRequestExt.Req(DstAddrModeAddress=AddrModeAddress(mode=<AddrMode.NWK: 2>, address=0x5340), DstEndpoint=1, DstPanId=0x0000, SrcEndpoint=1, ClusterId=8, TSN=246, Options=<TransmitOptions.SUPPRESS_ROUTE_DISC_NETWORK|ACK_REQUEST: 48>, Radius=0, Data=b'\x00\xF6\x00\x00\x00')
2022-10-18 14:35:56.645 DEBUG (MainThread) [zigpy_znp.api] Received command: AF.DataRequestExt.Rsp(Status=<Status.SUCCESS: 0>)
2022-10-18 14:35:56.649 DEBUG (MainThread) [zigpy_znp.api] Sending request: AF.DataRequestExt.Req(DstAddrModeAddress=AddrModeAddress(mode=<AddrMode.NWK: 2>, address=0x5340), DstEndpoint=1, DstPanId=0x0000, SrcEndpoint=1, ClusterId=768, TSN=247, Options=<TransmitOptions.SUPPRESS_ROUTE_DISC_NETWORK|ACK_REQUEST: 48>, Radius=0, Data=b'\x00\xF7\x00\x08\x00\x02\x40\x03\x00\x04\x00\x00\x00')
2022-10-18 14:35:56.684 DEBUG (MainThread) [zigpy_znp.api] Received command: AF.DataRequestExt.Rsp(Status=<Status.SUCCESS: 0>)
2022-10-18 14:35:56.729 DEBUG (MainThread) [zigpy_znp.api] Received command: AF.DataConfirm.Callback(Status=<Status.MAC_NO_ACK: 233>, Endpoint=1, TSN=244)
2022-10-18 14:35:56.734 DEBUG (MainThread) [zigpy_znp.zigbee.application] Request failed (Unsuccessful request status code: <Status.MAC_NO_ACK: 233>), retry attempt 4 of 5
2022-10-18 14:35:56.747 DEBUG (MainThread) [zigpy_znp.api] Received command: AF.DataConfirm.Callback(Status=<Status.MAC_NO_ACK: 233>, Endpoint=1, TSN=246)
2022-10-18 14:35:56.751 DEBUG (MainThread) [zigpy_znp.zigbee.application] Request failed (Unsuccessful request status code: <Status.MAC_NO_ACK: 233>), retry attempt 4 of 5
2022-10-18 14:35:56.793 DEBUG (MainThread) [zigpy_znp.api] Received command: AF.DataConfirm.Callback(Status=<Status.MAC_NO_ACK: 233>, Endpoint=1, TSN=247)
2022-10-18 14:35:56.798 DEBUG (MainThread) [zigpy_znp.zigbee.application] Request failed (Unsuccessful request status code: <Status.MAC_NO_ACK: 233>), retry attempt 4 of 5
2022-10-18 14:35:57.144 DEBUG (MainThread) [zigpy.topology] Scanning neighbors of 04:cd:15:ff:fe:32:99:4d/0xfa52 device
2022-10-18 14:35:57.145 DEBUG (MainThread) [zigpy.util] Tries remaining: 3
2022-10-18 14:35:57.146 DEBUG (MainThread) [zigpy_znp.zigbee.application] Sending packet ZigbeePacket(src=AddrModeAddress(addr_mode=<AddrMode.NWK: 2>, address=0x0000), src_ep=0, dst=AddrModeAddress(addr_mode=<AddrMode.NWK: 2>, address=0xFA52), dst_ep=0, source_route=None, extended_timeout=False, tsn=249, profile_id=0, cluster_id=<ZDOCmd.Mgmt_Lqi_req: 0x0031>, data=Serialized[b'\xf9\x00'], tx_options=<TransmitOptions.ACK: 1>, radius=0, non_member_radius=0, lqi=None, rssi=None)
2022-10-18 14:35:57.149 DEBUG (MainThread) [zigpy_znp.api] Sending request: ZDO.ExtRouteChk.Req(Dst=0xFA52, RtStatus=<RouteStatus.ACTIVE: 1>, Options=<RouteOptions.NO_ROUTE_CACHE|MTO_ROUTE: 3>)
2022-10-18 14:35:57.163 DEBUG (MainThread) [zigpy_znp.api] Received command: ZDO.ExtRouteChk.Rsp(Status=<RoutingStatus.SUCCESS: 0>)
2022-10-18 14:35:57.165 DEBUG (MainThread) [zigpy_znp.api] Sending request: AF.DataRequestExt.Req(DstAddrModeAddress=AddrModeAddress(mode=<AddrMode.NWK: 2>, address=0xFA52), DstEndpoint=0, DstPanId=0x0000, SrcEndpoint=0, ClusterId=49, TSN=249, Options=<TransmitOptions.SUPPRESS_ROUTE_DISC_NETWORK|ACK_REQUEST: 48>, Radius=0, Data=b'\xF9\x00')
2022-10-18 14:35:57.185 DEBUG (MainThread) [zigpy_znp.api] Received command: AF.DataRequestExt.Rsp(Status=<Status.SUCCESS: 0>)
2022-10-18 14:35:57.240 DEBUG (MainThread) [zigpy_znp.api] Sending request: AF.DataRequestExt.Req(DstAddrModeAddress=AddrModeAddress(mode=<AddrMode.IEEE: 3>, address=04:cd:15:ff:fe:8c:ae:a9), DstEndpoint=1, DstPanId=0x0000, SrcEndpoint=1, ClusterId=6, TSN=244, Options=<TransmitOptions.SUPPRESS_ROUTE_DISC_NETWORK|ACK_REQUEST: 48>, Radius=0, Data=b'\x00\xF4\x00\x00\x00')
2022-10-18 14:35:57.254 DEBUG (MainThread) [zigpy_znp.api] Received command: ZDO.MgmtLqiRsp.Callback(Src=0xFA52, Status=<Status.SUCCESS: 0>, Neighbors=Neighbors(entries=9, start_index=0, neighbor_table_list=[Neighbor(extended_pan_id=c9:66:37:6e:15:e1:f3:57, ieee=00:12:4b:00:24:c0:84:e6, nwk=0x0000, device_type=<DeviceType.Coordinator: 0>, rx_on_when_idle=<RxOnWhenIdle.On: 1>, relationship=<RelationShip.Sibling: 2>, reserved1=0, permit_joining=<PermitJoins.Unknown: 2>, reserved2=0, depth=0, lqi=101), Neighbor(extended_pan_id=c9:66:37:6e:15:e1:f3:57, ieee=5c:02:72:ff:fe:22:82:27, nwk=0x0CA2, device_type=<DeviceType.Router: 1>, rx_on_when_idle=<RxOnWhenIdle.On: 1>, relationship=<RelationShip.Sibling: 2>, reserved1=0, permit_joining=<PermitJoins.Unknown: 2>, reserved2=0, depth=15, lqi=164), Neighbor(extended_pan_id=c9:66:37:6e:15:e1:f3:57, ieee=04:cd:15:ff:fe:c1:f8:1f, nwk=0x31E7, device_type=<DeviceType.Router: 1>, rx_on_when_idle=<RxOnWhenIdle.On: 1>, relationship=<RelationShip.Sibling: 2>, reserved1=0, permit_joining=<PermitJoins.Unknown: 2>, reserved2=0, depth=15, lqi=213)]))
2022-10-18 14:35:57.256 DEBUG (MainThread) [zigpy_znp.api] Command was not handled
2022-10-18 14:35:57.258 DEBUG (MainThread) [zigpy_znp.api] Received command: ZDO.MsgCbIncoming.Callback(Src=0xFA52, IsBroadcast=<Bool.false: 0>, ClusterId=32817, SecurityUse=0, TSN=249, MacDst=0x0000, Data=b'\x00\x09\x00\x03\x57\xF3\xE1\x15\x6E\x37\x66\xC9\xE6\x84\xC0\x24\x00\x4B\x12\x00\x00\x00\x24\x02\x00\x65\x57\xF3\xE1\x15\x6E\x37\x66\xC9\x27\x82\x22\xFE\xFF\x72\x02\x5C\xA2\x0C\x25\x02\x0F\xA4\x57\xF3\xE1\x15\x6E\x37\x66\xC9\x1F\xF8\xC1\xFE\xFF\x15\xCD\x04\xE7\x31\x25\x02\x0F\xD5')
2022-10-18 14:35:57.264 DEBUG (MainThread) [zigpy.application] Received a packet: ZigbeePacket(src=AddrModeAddress(addr_mode=<AddrMode.NWK: 2>, address=0xFA52), src_ep=0, dst=AddrModeAddress(addr_mode=<AddrMode.NWK: 2>, address=0x0000), dst_ep=0, source_route=None, extended_timeout=False, tsn=249, profile_id=0, cluster_id=32817, data=Serialized[b'\xf9\x00\t\x00\x03W\xf3\xe1\x15n7f\xc9\xe6\x84\xc0$\x00K\x12\x00\x00\x00$\x02\x00eW\xf3\xe1\x15n7f\xc9\'\x82"\xfe\xffr\x02\\\xa2\x0c%\x02\x0f\xa4W\xf3\xe1\x15n7f\xc9\x1f\xf8\xc1\xfe\xff\x15\xcd\x04\xe71%\x02\x0f\xd5'], tx_options=<TransmitOptions.NONE: 0>, radius=0, non_member_radius=0, lqi=None, rssi=None)
2022-10-18 14:35:57.283 DEBUG (MainThread) [zigpy.neighbor] [0xfa52] request status: Status.SUCCESS. response: Neighbors(entries=9, start_index=0, neighbor_table_list=[Neighbor(extended_pan_id=c9:66:37:6e:15:e1:f3:57, ieee=00:12:4b:00:24:c0:84:e6, nwk=0x0000, device_type=<DeviceType.Coordinator: 0>, rx_on_when_idle=<RxOnWhenIdle.On: 1>, relationship=<RelationShip.Sibling: 2>, reserved1=0, permit_joining=<PermitJoins.Unknown: 2>, reserved2=0, depth=0, lqi=101), Neighbor(extended_pan_id=c9:66:37:6e:15:e1:f3:57, ieee=5c:02:72:ff:fe:22:82:27, nwk=0x0CA2, device_type=<DeviceType.Router: 1>, rx_on_when_idle=<RxOnWhenIdle.On: 1>, relationship=<RelationShip.Sibling: 2>, reserved1=0, permit_joining=<PermitJoins.Unknown: 2>, reserved2=0, depth=15, lqi=164), Neighbor(extended_pan_id=c9:66:37:6e:15:e1:f3:57, ieee=04:cd:15:ff:fe:c1:f8:1f, nwk=0x31E7, device_type=<DeviceType.Router: 1>, rx_on_when_idle=<RxOnWhenIdle.On: 1>, relationship=<RelationShip.Sibling: 2>, reserved1=0, permit_joining=<PermitJoins.Unknown: 2>, reserved2=0, depth=15, lqi=213)])
2022-10-18 14:35:57.291 DEBUG (MainThread) [zigpy_znp.api] Received command: AF.DataRequestExt.Rsp(Status=<Status.SUCCESS: 0>)
2022-10-18 14:35:57.293 DEBUG (MainThread) [zigpy_znp.api] Sending request: AF.DataRequestExt.Req(DstAddrModeAddress=AddrModeAddress(mode=<AddrMode.IEEE: 3>, address=04:cd:15:ff:fe:8c:ae:a9), DstEndpoint=1, DstPanId=0x0000, SrcEndpoint=1, ClusterId=8, TSN=246, Options=<TransmitOptions.SUPPRESS_ROUTE_DISC_NETWORK|ACK_REQUEST: 48>, Radius=0, Data=b'\x00\xF6\x00\x00\x00')
2022-10-18 14:35:57.313 DEBUG (MainThread) [zigpy_znp.api] Received command: AF.DataRequestExt.Rsp(Status=<Status.SUCCESS: 0>)
2022-10-18 14:35:57.316 DEBUG (MainThread) [zigpy_znp.api] Sending request: AF.DataRequestExt.Req(DstAddrModeAddress=AddrModeAddress(mode=<AddrMode.IEEE: 3>, address=04:cd:15:ff:fe:8c:ae:a9), DstEndpoint=1, DstPanId=0x0000, SrcEndpoint=1, ClusterId=768, TSN=247, Options=<TransmitOptions.SUPPRESS_ROUTE_DISC_NETWORK|ACK_REQUEST: 48>, Radius=0, Data=b'\x00\xF7\x00\x08\x00\x02\x40\x03\x00\x04\x00\x00\x00')
2022-10-18 14:35:57.350 DEBUG (MainThread) [zigpy_znp.api] Received command: AF.DataRequestExt.Rsp(Status=<Status.SUCCESS: 0>)
2022-10-18 14:35:57.414 DEBUG (MainThread) [zigpy_znp.api] Received command: AF.DataConfirm.Callback(Status=<Status.MAC_NO_ACK: 233>, Endpoint=1, TSN=244)
2022-10-18 14:35:57.419 DEBUG (MainThread) [zigpy_znp.zigbee.application] Request failed (Unsuccessful request status code: <Status.MAC_NO_ACK: 233>), retry attempt 5 of 5
2022-10-18 14:35:57.450 DEBUG (MainThread) [zigpy_znp.api] Received command: AF.DataConfirm.Callback(Status=<Status.MAC_NO_ACK: 233>, Endpoint=1, TSN=246)
2022-10-18 14:35:57.455 DEBUG (MainThread) [homeassistant.components.zha.core.device] [0xD6AE](LLC014): Device seen - marking the device available and resetting counter
2022-10-18 14:35:57.456 DEBUG (MainThread) [homeassistant.components.zha.core.device] [0xD6AE](LLC014): Update device availability -  device available: True - new availability: True - changed: False
2022-10-18 14:35:57.459 DEBUG (MainThread) [zigpy_znp.zigbee.application] Request failed (Unsuccessful request status code: <Status.MAC_NO_ACK: 233>), retry attempt 5 of 5
2022-10-18 14:35:57.469 DEBUG (MainThread) [zigpy_znp.api] Received command: AF.DataConfirm.Callback(Status=<Status.MAC_NO_ACK: 233>, Endpoint=1, TSN=247)
2022-10-18 14:35:57.482 DEBUG (MainThread) [zigpy_znp.zigbee.application] Request failed (Unsuccessful request status code: <Status.MAC_NO_ACK: 233>), retry attempt 5 of 5
2022-10-18 14:35:57.609 DEBUG (MainThread) [homeassistant.components.zha.core.device] [0xDAB9](TS0505B): Device seen - marking the device available and resetting counter
2022-10-18 14:35:57.610 DEBUG (MainThread) [homeassistant.components.zha.core.device] [0xDAB9](TS0505B): Update device availability -  device available: True - new availability: True - changed: False
2022-10-18 14:35:57.922 DEBUG (MainThread) [homeassistant.components.zha.core.channels.base] [0x5340:1:0x0006]: failed to get attributes '['on_off']' on 'on_off' cluster: Request failed after 5 attempts: <Status.MAC_NO_ACK: 233>
2022-10-18 14:35:57.923 DEBUG (MainThread) [homeassistant.components.zha.core.channels.base] [0x5340:1:0x0006]: async_initialize: retryable request #2 failed: Request failed after 5 attempts: <Status.MAC_NO_ACK: 233>. Retrying in 1.0s
2022-10-18 14:35:57.962 DEBUG (MainThread) [homeassistant.components.zha.core.channels.base] [0x5340:1:0x0008]: failed to get attributes '['current_level']' on 'level' cluster: Request failed after 5 attempts: <Status.MAC_NO_ACK: 233>
2022-10-18 14:35:57.963 DEBUG (MainThread) [homeassistant.components.zha.core.channels.base] [0x5340:1:0x0008]: async_initialize: retryable request #2 failed: Request failed after 5 attempts: <Status.MAC_NO_ACK: 233>. Retrying in 1.1s
2022-10-18 14:35:57.984 DEBUG (MainThread) [homeassistant.components.zha.core.channels.base] [0x5340:1:0x0300]: failed to get attributes '['color_mode', 'color_loop_active', 'current_x', 'current_y', 'current_hue']' on 'light_color' cluster: Request failed after 5 attempts: <Status.MAC_NO_ACK: 233>
2022-10-18 14:35:57.985 DEBUG (MainThread) [homeassistant.components.zha.core.channels.base] [0x5340:1:0x0300]: async_initialize: retryable request #2 failed: Request failed after 5 attempts: <Status.MAC_NO_ACK: 233>. Retrying in 1.2s
2022-10-18 14:35:58.574 DEBUG (MainThread) [zigpy.neighbor] [0xfa52] Querying next starting at 3
2022-10-18 14:35:58.575 DEBUG (MainThread) [zigpy.util] Tries remaining: 3
2022-10-18 14:35:58.576 DEBUG (MainThread) [zigpy_znp.zigbee.application] Sending packet ZigbeePacket(src=AddrModeAddress(addr_mode=<AddrMode.NWK: 2>, address=0x0000), src_ep=0, dst=AddrModeAddress(addr_mode=<AddrMode.NWK: 2>, address=0xFA52), dst_ep=0, source_route=None, extended_timeout=False, tsn=250, profile_id=0, cluster_id=<ZDOCmd.Mgmt_Lqi_req: 0x0031>, data=Serialized[b'\xfa\x03'], tx_options=<TransmitOptions.ACK: 1>, radius=0, non_member_radius=0, lqi=None, rssi=None)
2022-10-18 14:35:58.578 DEBUG (MainThread) [zigpy_znp.api] Sending request: ZDO.ExtRouteChk.Req(Dst=0xFA52, RtStatus=<RouteStatus.ACTIVE: 1>, Options=<RouteOptions.NO_ROUTE_CACHE|MTO_ROUTE: 3>)
2022-10-18 14:35:58.594 DEBUG (MainThread) [zigpy_znp.api] Received command: ZDO.ExtRouteChk.Rsp(Status=<RoutingStatus.SUCCESS: 0>)
2022-10-18 14:35:58.596 DEBUG (MainThread) [zigpy_znp.api] Sending request: AF.DataRequestExt.Req(DstAddrModeAddress=AddrModeAddress(mode=<AddrMode.NWK: 2>, address=0xFA52), DstEndpoint=0, DstPanId=0x0000, SrcEndpoint=0, ClusterId=49, TSN=250, Options=<TransmitOptions.SUPPRESS_ROUTE_DISC_NETWORK|ACK_REQUEST: 48>, Radius=0, Data=b'\xFA\x03')
2022-10-18 14:35:58.616 DEBUG (MainThread) [zigpy_znp.api] Received command: AF.DataRequestExt.Rsp(Status=<Status.SUCCESS: 0>)
2022-10-18 14:35:58.681 DEBUG (MainThread) [zigpy_znp.api] Received command: ZDO.MgmtLqiRsp.Callback(Src=0xFA52, Status=<Status.SUCCESS: 0>, Neighbors=Neighbors(entries=9, start_index=3, neighbor_table_list=[Neighbor(extended_pan_id=c9:66:37:6e:15:e1:f3:57, ieee=04:cd:15:ff:fe:35:ec:ac, nwk=0x383E, device_type=<DeviceType.Router: 1>, rx_on_when_idle=<RxOnWhenIdle.On: 1>, relationship=<RelationShip.Sibling: 2>, reserved1=0, permit_joining=<PermitJoins.Unknown: 2>, reserved2=0, depth=15, lqi=209), Neighbor(extended_pan_id=c9:66:37:6e:15:e1:f3:57, ieee=00:17:88:01:00:1c:e9:71, nwk=0xD6AE, device_type=<DeviceType.Router: 1>, rx_on_when_idle=<RxOnWhenIdle.On: 1>, relationship=<RelationShip.Sibling: 2>, reserved1=0, permit_joining=<PermitJoins.Unknown: 2>, reserved2=0, depth=15, lqi=149), Neighbor(extended_pan_id=c9:66:37:6e:15:e1:f3:57, ieee=b4:e3:f9:ff:fe:ba:7e:a2, nwk=0xDAB9, device_type=<DeviceType.Router: 1>, rx_on_when_idle=<RxOnWhenIdle.On: 1>, relationship=<RelationShip.Parent: 0>, reserved1=0, permit_joining=<PermitJoins.Unknown: 2>, reserved2=0, depth=15, lqi=212)]))
2022-10-18 14:35:58.683 DEBUG (MainThread) [zigpy_znp.api] Command was not handled
2022-10-18 14:35:58.686 DEBUG (MainThread) [zigpy_znp.api] Received command: ZDO.MsgCbIncoming.Callback(Src=0xFA52, IsBroadcast=<Bool.false: 0>, ClusterId=32817, SecurityUse=0, TSN=250, MacDst=0x0000, Data=b'\x00\x09\x03\x03\x57\xF3\xE1\x15\x6E\x37\x66\xC9\xAC\xEC\x35\xFE\xFF\x15\xCD\x04\x3E\x38\x25\x02\x0F\xD1\x57\xF3\xE1\x15\x6E\x37\x66\xC9\x71\xE9\x1C\x00\x01\x88\x17\x00\xAE\xD6\x25\x02\x0F\x95\x57\xF3\xE1\x15\x6E\x37\x66\xC9\xA2\x7E\xBA\xFE\xFF\xF9\xE3\xB4\xB9\xDA\x05\x02\x0F\xD4')
2022-10-18 14:35:58.692 DEBUG (MainThread) [zigpy.application] Received a packet: ZigbeePacket(src=AddrModeAddress(addr_mode=<AddrMode.NWK: 2>, address=0xFA52), src_ep=0, dst=AddrModeAddress(addr_mode=<AddrMode.NWK: 2>, address=0x0000), dst_ep=0, source_route=None, extended_timeout=False, tsn=250, profile_id=0, cluster_id=32817, data=Serialized[b'\xfa\x00\t\x03\x03W\xf3\xe1\x15n7f\xc9\xac\xec5\xfe\xff\x15\xcd\x04>8%\x02\x0f\xd1W\xf3\xe1\x15n7f\xc9q\xe9\x1c\x00\x01\x88\x17\x00\xae\xd6%\x02\x0f\x95W\xf3\xe1\x15n7f\xc9\xa2~\xba\xfe\xff\xf9\xe3\xb4\xb9\xda\x05\x02\x0f\xd4'], tx_options=<TransmitOptions.NONE: 0>, radius=0, non_member_radius=0, lqi=None, rssi=None)
2022-10-18 14:35:58.702 DEBUG (MainThread) [zigpy.neighbor] [0xfa52] request status: Status.SUCCESS. response: Neighbors(entries=9, start_index=3, neighbor_table_list=[Neighbor(extended_pan_id=c9:66:37:6e:15:e1:f3:57, ieee=04:cd:15:ff:fe:35:ec:ac, nwk=0x383E, device_type=<DeviceType.Router: 1>, rx_on_when_idle=<RxOnWhenIdle.On: 1>, relationship=<RelationShip.Sibling: 2>, reserved1=0, permit_joining=<PermitJoins.Unknown: 2>, reserved2=0, depth=15, lqi=209), Neighbor(extended_pan_id=c9:66:37:6e:15:e1:f3:57, ieee=00:17:88:01:00:1c:e9:71, nwk=0xD6AE, device_type=<DeviceType.Router: 1>, rx_on_when_idle=<RxOnWhenIdle.On: 1>, relationship=<RelationShip.Sibling: 2>, reserved1=0, permit_joining=<PermitJoins.Unknown: 2>, reserved2=0, depth=15, lqi=149), Neighbor(extended_pan_id=c9:66:37:6e:15:e1:f3:57, ieee=b4:e3:f9:ff:fe:ba:7e:a2, nwk=0xDAB9, device_type=<DeviceType.Router: 1>, rx_on_when_idle=<RxOnWhenIdle.On: 1>, relationship=<RelationShip.Parent: 0>, reserved1=0, permit_joining=<PermitJoins.Unknown: 2>, reserved2=0, depth=15, lqi=212)])
2022-10-18 14:35:58.975 DEBUG (MainThread) [homeassistant.components.zha.core.channels.base] [0x5340:1:0x0006]: initializing channel: from_cache: False
2022-10-18 14:35:58.976 DEBUG (MainThread) [homeassistant.components.zha.core.channels.base] [0x5340:1:0x0006]: initializing cached channel attributes: ['start_up_on_off']
2022-10-18 14:35:58.976 DEBUG (MainThread) [homeassistant.components.zha.core.channels.base] [0x5340:1:0x0006]: Reading attributes in chunks: ['start_up_on_off']
2022-10-18 14:35:58.977 DEBUG (MainThread) [homeassistant.components.zha.core.channels.base] [0x5340:1:0x0006]: initializing uncached channel attributes: ['on_off'] - from cache[False]
2022-10-18 14:35:58.978 DEBUG (MainThread) [homeassistant.components.zha.core.channels.base] [0x5340:1:0x0006]: Reading attributes in chunks: ['on_off']
2022-10-18 14:35:58.983 DEBUG (MainThread) [zigpy.zcl] [0x5340:1:0x0006] Sending request header: ZCLHeader(frame_control=FrameControl(frame_type=<FrameType.GLOBAL_COMMAND: 0>, is_manufacturer_specific=False, direction=<Direction.Server_to_Client: 0>, disable_default_response=0, reserved=0, *is_cluster=False, *is_general=True, *is_reply=False), tsn=251, command_id=<GeneralCommand.Read_Attributes: 0>, *direction=<Direction.Server_to_Client: 0>, *is_reply=False)
2022-10-18 14:35:58.985 DEBUG (MainThread) [zigpy.zcl] [0x5340:1:0x0006] Sending request: Read_Attributes(attribute_ids=[0])
2022-10-18 14:35:58.987 DEBUG (MainThread) [zigpy_znp.zigbee.application] Sending packet ZigbeePacket(src=AddrModeAddress(addr_mode=<AddrMode.NWK: 2>, address=0x0000), src_ep=1, dst=AddrModeAddress(addr_mode=<AddrMode.NWK: 2>, address=0x5340), dst_ep=1, source_route=None, extended_timeout=False, tsn=251, profile_id=260, cluster_id=6, data=Serialized[b'\x00\xfb\x00\x00\x00'], tx_options=<TransmitOptions.ACK: 1>, radius=0, non_member_radius=0, lqi=None, rssi=None)
2022-10-18 14:35:58.991 DEBUG (MainThread) [zigpy_znp.api] Sending request: AF.DataRequestExt.Req(DstAddrModeAddress=AddrModeAddress(mode=<AddrMode.NWK: 2>, address=0x5340), DstEndpoint=1, DstPanId=0x0000, SrcEndpoint=1, ClusterId=6, TSN=251, Options=<TransmitOptions.SUPPRESS_ROUTE_DISC_NETWORK|ACK_REQUEST: 48>, Radius=0, Data=b'\x00\xFB\x00\x00\x00')
2022-10-18 14:35:59.005 DEBUG (MainThread) [zigpy_znp.api] Received command: AF.DataRequestExt.Rsp(Status=<Status.SUCCESS: 0>)
2022-10-18 14:35:59.029 DEBUG (MainThread) [homeassistant.components.zha.core.channels.base] [0x5340:1:0x0008]: initializing channel: from_cache: False
2022-10-18 14:35:59.029 DEBUG (MainThread) [homeassistant.components.zha.core.channels.base] [0x5340:1:0x0008]: initializing cached channel attributes: ['on_off_transition_time', 'on_level', 'on_transition_time', 'off_transition_time', 'default_move_rate', 'start_up_current_level']
2022-10-18 14:35:59.030 DEBUG (MainThread) [homeassistant.components.zha.core.channels.base] [0x5340:1:0x0008]: Reading attributes in chunks: ['on_off_transition_time', 'on_level', 'on_transition_time', 'off_transition_time', 'default_move_rate']
2022-10-18 14:35:59.030 DEBUG (MainThread) [homeassistant.components.zha.core.channels.base] [0x5340:1:0x0008]: Reading attributes in chunks: ['start_up_current_level']
2022-10-18 14:35:59.030 DEBUG (MainThread) [homeassistant.components.zha.core.channels.base] [0x5340:1:0x0008]: initializing uncached channel attributes: ['current_level'] - from cache[False]
2022-10-18 14:35:59.031 DEBUG (MainThread) [homeassistant.components.zha.core.channels.base] [0x5340:1:0x0008]: Reading attributes in chunks: ['current_level']
2022-10-18 14:35:59.033 DEBUG (MainThread) [zigpy.zcl] [0x5340:1:0x0008] Sending request header: ZCLHeader(frame_control=FrameControl(frame_type=<FrameType.GLOBAL_COMMAND: 0>, is_manufacturer_specific=False, direction=<Direction.Server_to_Client: 0>, disable_default_response=0, reserved=0, *is_cluster=False, *is_general=True, *is_reply=False), tsn=252, command_id=<GeneralCommand.Read_Attributes: 0>, *direction=<Direction.Server_to_Client: 0>, *is_reply=False)
2022-10-18 14:35:59.037 DEBUG (MainThread) [zigpy.zcl] [0x5340:1:0x0008] Sending request: Read_Attributes(attribute_ids=[0])
2022-10-18 14:35:59.039 DEBUG (MainThread) [zigpy_znp.zigbee.application] Sending packet ZigbeePacket(src=AddrModeAddress(addr_mode=<AddrMode.NWK: 2>, address=0x0000), src_ep=1, dst=AddrModeAddress(addr_mode=<AddrMode.NWK: 2>, address=0x5340), dst_ep=1, source_route=None, extended_timeout=False, tsn=252, profile_id=260, cluster_id=8, data=Serialized[b'\x00\xfc\x00\x00\x00'], tx_options=<TransmitOptions.ACK: 1>, radius=0, non_member_radius=0, lqi=None, rssi=None)
2022-10-18 14:35:59.043 DEBUG (MainThread) [zigpy_znp.api] Sending request: AF.DataRequestExt.Req(DstAddrModeAddress=AddrModeAddress(mode=<AddrMode.NWK: 2>, address=0x5340), DstEndpoint=1, DstPanId=0x0000, SrcEndpoint=1, ClusterId=8, TSN=252, Options=<TransmitOptions.SUPPRESS_ROUTE_DISC_NETWORK|ACK_REQUEST: 48>, Radius=0, Data=b'\x00\xFC\x00\x00\x00')
2022-10-18 14:35:59.073 DEBUG (MainThread) [zigpy_znp.api] Received command: AF.DataRequestExt.Rsp(Status=<Status.SUCCESS: 0>)
2022-10-18 14:35:59.099 DEBUG (MainThread) [zigpy_znp.api] Received command: AF.DataConfirm.Callback(Status=<Status.MAC_NO_ACK: 233>, Endpoint=1, TSN=251)
2022-10-18 14:35:59.104 DEBUG (MainThread) [zigpy_znp.zigbee.application] Request failed (Unsuccessful request status code: <Status.MAC_NO_ACK: 233>), retry attempt 1 of 5
2022-10-18 14:35:59.142 DEBUG (MainThread) [zigpy_znp.api] Received command: AF.DataConfirm.Callback(Status=<Status.MAC_NO_ACK: 233>, Endpoint=1, TSN=252)
2022-10-18 14:35:59.149 DEBUG (MainThread) [zigpy_znp.zigbee.application] Request failed (Unsuccessful request status code: <Status.MAC_NO_ACK: 233>), retry attempt 1 of 5
2022-10-18 14:35:59.172 DEBUG (MainThread) [homeassistant.components.zha.core.channels.base] [0x5340:1:0x0300]: initializing channel: from_cache: False
2022-10-18 14:35:59.172 DEBUG (MainThread) [homeassistant.components.zha.core.channels.base] [0x5340:1:0x0300]: initializing cached channel attributes: ['color_temp_physical_min', 'color_temp_physical_max', 'color_capabilities']
2022-10-18 14:35:59.173 DEBUG (MainThread) [homeassistant.components.zha.core.channels.base] [0x5340:1:0x0300]: Reading attributes in chunks: ['color_temp_physical_min', 'color_temp_physical_max', 'color_capabilities']
2022-10-18 14:35:59.174 DEBUG (MainThread) [homeassistant.components.zha.core.channels.base] [0x5340:1:0x0300]: initializing uncached channel attributes: ['color_mode', 'color_loop_active', 'current_x', 'current_y', 'current_hue', 'enhanced_current_hue', 'current_saturation', 'color_temperature'] - from cache[False]
2022-10-18 14:35:59.174 DEBUG (MainThread) [homeassistant.components.zha.core.channels.base] [0x5340:1:0x0300]: Reading attributes in chunks: ['color_mode', 'color_loop_active', 'current_x', 'current_y', 'current_hue']
2022-10-18 14:35:59.179 DEBUG (MainThread) [zigpy.zcl] [0x5340:1:0x0300] Sending request header: ZCLHeader(frame_control=FrameControl(frame_type=<FrameType.GLOBAL_COMMAND: 0>, is_manufacturer_specific=False, direction=<Direction.Server_to_Client: 0>, disable_default_response=0, reserved=0, *is_cluster=False, *is_general=True, *is_reply=False), tsn=253, command_id=<GeneralCommand.Read_Attributes: 0>, *direction=<Direction.Server_to_Client: 0>, *is_reply=False)
2022-10-18 14:35:59.182 DEBUG (MainThread) [zigpy.zcl] [0x5340:1:0x0300] Sending request: Read_Attributes(attribute_ids=[8, 16386, 3, 4, 0])
2022-10-18 14:35:59.185 DEBUG (MainThread) [zigpy_znp.zigbee.application] Sending packet ZigbeePacket(src=AddrModeAddress(addr_mode=<AddrMode.NWK: 2>, address=0x0000), src_ep=1, dst=AddrModeAddress(addr_mode=<AddrMode.NWK: 2>, address=0x5340), dst_ep=1, source_route=None, extended_timeout=False, tsn=253, profile_id=260, cluster_id=768, data=Serialized[b'\x00\xfd\x00\x08\x00\x02@\x03\x00\x04\x00\x00\x00'], tx_options=<TransmitOptions.ACK: 1>, radius=0, non_member_radius=0, lqi=None, rssi=None)
2022-10-18 14:35:59.188 DEBUG (MainThread) [zigpy_znp.api] Sending request: AF.DataRequestExt.Req(DstAddrModeAddress=AddrModeAddress(mode=<AddrMode.NWK: 2>, address=0x5340), DstEndpoint=1, DstPanId=0x0000, SrcEndpoint=1, ClusterId=768, TSN=253, Options=<TransmitOptions.SUPPRESS_ROUTE_DISC_NETWORK|ACK_REQUEST: 48>, Radius=0, Data=b'\x00\xFD\x00\x08\x00\x02\x40\x03\x00\x04\x00\x00\x00')
2022-10-18 14:35:59.210 DEBUG (MainThread) [zigpy_znp.api] Received command: AF.DataRequestExt.Rsp(Status=<Status.SUCCESS: 0>)
2022-10-18 14:35:59.283 DEBUG (MainThread) [zigpy_znp.api] Received command: AF.DataConfirm.Callback(Status=<Status.MAC_NO_ACK: 233>, Endpoint=1, TSN=253)
2022-10-18 14:35:59.289 DEBUG (MainThread) [zigpy_znp.zigbee.application] Request failed (Unsuccessful request status code: <Status.MAC_NO_ACK: 233>), retry attempt 1 of 5
2022-10-18 14:35:59.864 DEBUG (MainThread) [zigpy.neighbor] [0xfa52] Querying next starting at 6
2022-10-18 14:35:59.865 DEBUG (MainThread) [zigpy.util] Tries remaining: 3
2022-10-18 14:35:59.867 DEBUG (MainThread) [zigpy_znp.zigbee.application] Sending packet ZigbeePacket(src=AddrModeAddress(addr_mode=<AddrMode.NWK: 2>, address=0x0000), src_ep=0, dst=AddrModeAddress(addr_mode=<AddrMode.NWK: 2>, address=0xFA52), dst_ep=0, source_route=None, extended_timeout=False, tsn=254, profile_id=0, cluster_id=<ZDOCmd.Mgmt_Lqi_req: 0x0031>, data=Serialized[b'\xfe\x06'], tx_options=<TransmitOptions.ACK: 1>, radius=0, non_member_radius=0, lqi=None, rssi=None)
2022-10-18 14:35:59.869 DEBUG (MainThread) [zigpy_znp.api] Sending request: ZDO.ExtRouteChk.Req(Dst=0xFA52, RtStatus=<RouteStatus.ACTIVE: 1>, Options=<RouteOptions.NO_ROUTE_CACHE|MTO_ROUTE: 3>)
2022-10-18 14:35:59.884 DEBUG (MainThread) [zigpy_znp.api] Received command: ZDO.ExtRouteChk.Rsp(Status=<RoutingStatus.SUCCESS: 0>)
2022-10-18 14:35:59.886 DEBUG (MainThread) [zigpy_znp.api] Sending request: AF.DataRequestExt.Req(DstAddrModeAddress=AddrModeAddress(mode=<AddrMode.NWK: 2>, address=0xFA52), DstEndpoint=0, DstPanId=0x0000, SrcEndpoint=0, ClusterId=49, TSN=254, Options=<TransmitOptions.SUPPRESS_ROUTE_DISC_NETWORK|ACK_REQUEST: 48>, Radius=0, Data=b'\xFE\x06')
2022-10-18 14:35:59.908 DEBUG (MainThread) [zigpy_znp.api] Received command: AF.DataRequestExt.Rsp(Status=<Status.SUCCESS: 0>)
2022-10-18 14:35:59.971 DEBUG (MainThread) [zigpy_znp.api] Received command: ZDO.MgmtLqiRsp.Callback(Src=0xFA52, Status=<Status.SUCCESS: 0>, Neighbors=Neighbors(entries=9, start_index=6, neighbor_table_list=[Neighbor(extended_pan_id=c9:66:37:6e:15:e1:f3:57, ieee=00:17:88:01:00:1c:e9:66, nwk=0xE65B, device_type=<DeviceType.Router: 1>, rx_on_when_idle=<RxOnWhenIdle.On: 1>, relationship=<RelationShip.Sibling: 2>, reserved1=0, permit_joining=<PermitJoins.Unknown: 2>, reserved2=0, depth=15, lqi=106), Neighbor(extended_pan_id=c9:66:37:6e:15:e1:f3:57, ieee=ec:1b:bd:ff:fe:79:cf:bc, nwk=0x00B1, device_type=<DeviceType.EndDevice: 2>, rx_on_when_idle=<RxOnWhenIdle.Off: 0>, relationship=<RelationShip.Child: 1>, reserved1=0, permit_joining=<PermitJoins.NotAccepting: 0>, reserved2=0, depth=2, lqi=197), Neighbor(extended_pan_id=c9:66:37:6e:15:e1:f3:57, ieee=ec:1b:bd:ff:fe:a2:59:98, nwk=0x1D65, device_type=<DeviceType.EndDevice: 2>, rx_on_when_idle=<RxOnWhenIdle.Off: 0>, relationship=<RelationShip.Child: 1>, reserved1=0, permit_joining=<PermitJoins.NotAccepting: 0>, reserved2=0, depth=2, lqi=212)]))
2022-10-18 14:35:59.973 DEBUG (MainThread) [zigpy_znp.api] Command was not handled
2022-10-18 14:35:59.977 DEBUG (MainThread) [zigpy_znp.api] Received command: ZDO.MsgCbIncoming.Callback(Src=0xFA52, IsBroadcast=<Bool.false: 0>, ClusterId=32817, SecurityUse=0, TSN=254, MacDst=0x0000, Data=b'\x00\x09\x06\x03\x57\xF3\xE1\x15\x6E\x37\x66\xC9\x66\xE9\x1C\x00\x01\x88\x17\x00\x5B\xE6\x25\x02\x0F\x6A\x57\xF3\xE1\x15\x6E\x37\x66\xC9\xBC\xCF\x79\xFE\xFF\xBD\x1B\xEC\xB1\x00\x12\x00\x02\xC5\x57\xF3\xE1\x15\x6E\x37\x66\xC9\x98\x59\xA2\xFE\xFF\xBD\x1B\xEC\x65\x1D\x12\x00\x02\xD4')
2022-10-18 14:35:59.982 DEBUG (MainThread) [zigpy.application] Received a packet: ZigbeePacket(src=AddrModeAddress(addr_mode=<AddrMode.NWK: 2>, address=0xFA52), src_ep=0, dst=AddrModeAddress(addr_mode=<AddrMode.NWK: 2>, address=0x0000), dst_ep=0, source_route=None, extended_timeout=False, tsn=254, profile_id=0, cluster_id=32817, data=Serialized[b'\xfe\x00\t\x06\x03W\xf3\xe1\x15n7f\xc9f\xe9\x1c\x00\x01\x88\x17\x00[\xe6%\x02\x0fjW\xf3\xe1\x15n7f\xc9\xbc\xcfy\xfe\xff\xbd\x1b\xec\xb1\x00\x12\x00\x02\xc5W\xf3\xe1\x15n7f\xc9\x98Y\xa2\xfe\xff\xbd\x1b\xece\x1d\x12\x00\x02\xd4'], tx_options=<TransmitOptions.NONE: 0>, radius=0, non_member_radius=0, lqi=None, rssi=None)
2022-10-18 14:35:59.993 DEBUG (MainThread) [zigpy.neighbor] [0xfa52] request status: Status.SUCCESS. response: Neighbors(entries=9, start_index=6, neighbor_table_list=[Neighbor(extended_pan_id=c9:66:37:6e:15:e1:f3:57, ieee=00:17:88:01:00:1c:e9:66, nwk=0xE65B, device_type=<DeviceType.Router: 1>, rx_on_when_idle=<RxOnWhenIdle.On: 1>, relationship=<RelationShip.Sibling: 2>, reserved1=0, permit_joining=<PermitJoins.Unknown: 2>, reserved2=0, depth=15, lqi=106), Neighbor(extended_pan_id=c9:66:37:6e:15:e1:f3:57, ieee=ec:1b:bd:ff:fe:79:cf:bc, nwk=0x00B1, device_type=<DeviceType.EndDevice: 2>, rx_on_when_idle=<RxOnWhenIdle.Off: 0>, relationship=<RelationShip.Child: 1>, reserved1=0, permit_joining=<PermitJoins.NotAccepting: 0>, reserved2=0, depth=2, lqi=197), Neighbor(extended_pan_id=c9:66:37:6e:15:e1:f3:57, ieee=ec:1b:bd:ff:fe:a2:59:98, nwk=0x1D65, device_type=<DeviceType.EndDevice: 2>, rx_on_when_idle=<RxOnWhenIdle.Off: 0>, relationship=<RelationShip.Child: 1>, reserved1=0, permit_joining=<PermitJoins.NotAccepting: 0>, reserved2=0, depth=2, lqi=212)])
2022-10-18 14:35:59.995 DEBUG (MainThread) [zigpy.neighbor] [0xfa52] Done scanning. Total 9 neighbours
2022-10-18 14:36:00.609 DEBUG (MainThread) [zigpy_znp.api] Sending request: AF.DataRequestExt.Req(DstAddrModeAddress=AddrModeAddress(mode=<AddrMode.NWK: 2>, address=0x5340), DstEndpoint=1, DstPanId=0x0000, SrcEndpoint=1, ClusterId=6, TSN=251, Options=<TransmitOptions.SUPPRESS_ROUTE_DISC_NETWORK|ACK_REQUEST: 48>, Radius=0, Data=b'\x00\xFB\x00\x00\x00')
2022-10-18 14:36:00.623 DEBUG (MainThread) [zigpy_znp.api] Received command: AF.DataRequestExt.Rsp(Status=<Status.SUCCESS: 0>)
2022-10-18 14:36:00.654 DEBUG (MainThread) [zigpy_znp.api] Sending request: AF.DataRequestExt.Req(DstAddrModeAddress=AddrModeAddress(mode=<AddrMode.NWK: 2>, address=0x5340), DstEndpoint=1, DstPanId=0x0000, SrcEndpoint=1, ClusterId=8, TSN=252, Options=<TransmitOptions.SUPPRESS_ROUTE_DISC_NETWORK|ACK_REQUEST: 48>, Radius=0, Data=b'\x00\xFC\x00\x00\x00')
2022-10-18 14:36:00.678 DEBUG (MainThread) [zigpy_znp.api] Received command: AF.DataRequestExt.Rsp(Status=<Status.SUCCESS: 0>)
2022-10-18 14:36:00.718 DEBUG (MainThread) [zigpy_znp.api] Received command: AF.DataConfirm.Callback(Status=<Status.MAC_NO_ACK: 233>, Endpoint=1, TSN=251)
2022-10-18 14:36:00.721 DEBUG (MainThread) [zigpy_znp.zigbee.application] Request failed (Unsuccessful request status code: <Status.MAC_NO_ACK: 233>), retry attempt 2 of 5
2022-10-18 14:36:00.761 DEBUG (MainThread) [zigpy_znp.api] Received command: AF.DataConfirm.Callback(Status=<Status.MAC_NO_ACK: 233>, Endpoint=1, TSN=252)
2022-10-18 14:36:00.766 DEBUG (MainThread) [zigpy_znp.zigbee.application] Request failed (Unsuccessful request status code: <Status.MAC_NO_ACK: 233>), retry attempt 2 of 5
2022-10-18 14:36:00.794 DEBUG (MainThread) [zigpy_znp.api] Sending request: AF.DataRequestExt.Req(DstAddrModeAddress=AddrModeAddress(mode=<AddrMode.NWK: 2>, address=0x5340), DstEndpoint=1, DstPanId=0x0000, SrcEndpoint=1, ClusterId=768, TSN=253, Options=<TransmitOptions.SUPPRESS_ROUTE_DISC_NETWORK|ACK_REQUEST: 48>, Radius=0, Data=b'\x00\xFD\x00\x08\x00\x02\x40\x03\x00\x04\x00\x00\x00')
2022-10-18 14:36:00.818 DEBUG (MainThread) [zigpy_znp.api] Received command: AF.DataRequestExt.Rsp(Status=<Status.SUCCESS: 0>)
2022-10-18 14:36:00.895 DEBUG (MainThread) [zigpy_znp.api] Received command: AF.DataConfirm.Callback(Status=<Status.MAC_NO_ACK: 233>, Endpoint=1, TSN=253)
2022-10-18 14:36:00.900 DEBUG (MainThread) [zigpy_znp.zigbee.application] Request failed (Unsuccessful request status code: <Status.MAC_NO_ACK: 233>), retry attempt 2 of 5
2022-10-18 14:36:01.232 DEBUG (MainThread) [zigpy_znp.api] Sending request: AF.DataRequestSrcRtg.Req(DstAddr=0x5340, DstEndpoint=1, SrcEndpoint=1, ClusterId=6, TSN=251, Options=<TransmitOptions.SUPPRESS_ROUTE_DISC_NETWORK|ACK_REQUEST: 48>, Radius=0, SourceRoute=[], Data=b'\x00\xFB\x00\x00\x00')
2022-10-18 14:36:01.258 DEBUG (MainThread) [zigpy_znp.api] Received command: AF.DataRequestSrcRtg.Rsp(Status=<Status.SUCCESS: 0>)
2022-10-18 14:36:01.270 DEBUG (MainThread) [zigpy_znp.api] Sending request: AF.DataRequestSrcRtg.Req(DstAddr=0x5340, DstEndpoint=1, SrcEndpoint=1, ClusterId=8, TSN=252, Options=<TransmitOptions.SUPPRESS_ROUTE_DISC_NETWORK|ACK_REQUEST: 48>, Radius=0, SourceRoute=[], Data=b'\x00\xFC\x00\x00\x00')
2022-10-18 14:36:01.298 DEBUG (MainThread) [zigpy_znp.api] Received command: AF.DataRequestSrcRtg.Rsp(Status=<Status.SUCCESS: 0>)
2022-10-18 14:36:01.336 DEBUG (MainThread) [zigpy_znp.api] Received command: AF.DataConfirm.Callback(Status=<Status.MAC_NO_ACK: 233>, Endpoint=1, TSN=251)
2022-10-18 14:36:01.346 DEBUG (MainThread) [zigpy_znp.api] Sending request: ZDO.ExtRouteDisc.Req(Dst=0x5340, Options=<RouteDiscoveryOptions.UNICAST: 0>, Radius=30)
2022-10-18 14:36:01.375 DEBUG (MainThread) [zigpy_znp.api] Received command: ZDO.ExtRouteDisc.Rsp(Status=<Status.SUCCESS: 0>)
2022-10-18 14:36:01.383 DEBUG (MainThread) [zigpy_znp.api] Received command: AF.DataConfirm.Callback(Status=<Status.MAC_NO_ACK: 233>, Endpoint=1, TSN=252)
2022-10-18 14:36:01.404 DEBUG (MainThread) [zigpy_znp.api] Sending request: AF.DataRequestSrcRtg.Req(DstAddr=0x5340, DstEndpoint=1, SrcEndpoint=1, ClusterId=768, TSN=253, Options=<TransmitOptions.SUPPRESS_ROUTE_DISC_NETWORK|ACK_REQUEST: 48>, Radius=0, SourceRoute=[], Data=b'\x00\xFD\x00\x08\x00\x02\x40\x03\x00\x04\x00\x00\x00')
2022-10-18 14:36:01.427 DEBUG (MainThread) [zigpy_znp.api] Received command: AF.DataRequestSrcRtg.Rsp(Status=<Status.SUCCESS: 0>)
2022-10-18 14:36:01.536 DEBUG (MainThread) [zigpy_znp.api] Received command: AF.DataConfirm.Callback(Status=<Status.MAC_NO_ACK: 233>, Endpoint=1, TSN=253)
2022-10-18 14:36:02.679 DEBUG (MainThread) [zigpy_znp.zigbee.application] Request failed (Unsuccessful request status code: <Status.MAC_NO_ACK: 233>), retry attempt 3 of 5
2022-10-18 14:36:02.679 DEBUG (MainThread) [zigpy_znp.zigbee.application] Request failed (Unsuccessful request status code: <Status.MAC_NO_ACK: 233>), retry attempt 3 of 5
2022-10-18 14:36:02.680 DEBUG (MainThread) [zigpy_znp.zigbee.application] Request failed (Unsuccessful request status code: <Status.MAC_NO_ACK: 233>), retry attempt 3 of 5
2022-10-18 14:36:02.997 DEBUG (MainThread) [zigpy.topology] Finished scanning neighbors for all devices
2022-10-18 14:36:03.188 DEBUG (MainThread) [zigpy_znp.api] Sending request: AF.DataRequestExt.Req(DstAddrModeAddress=AddrModeAddress(mode=<AddrMode.NWK: 2>, address=0x5340), DstEndpoint=1, DstPanId=0x0000, SrcEndpoint=1, ClusterId=6, TSN=251, Options=<TransmitOptions.SUPPRESS_ROUTE_DISC_NETWORK|ACK_REQUEST: 48>, Radius=0, Data=b'\x00\xFB\x00\x00\x00')
2022-10-18 14:36:03.210 DEBUG (MainThread) [zigpy_znp.api] Received command: AF.DataRequestExt.Rsp(Status=<Status.SUCCESS: 0>)
2022-10-18 14:36:03.215 DEBUG (MainThread) [zigpy_znp.api] Sending request: AF.DataRequestExt.Req(DstAddrModeAddress=AddrModeAddress(mode=<AddrMode.NWK: 2>, address=0x5340), DstEndpoint=1, DstPanId=0x0000, SrcEndpoint=1, ClusterId=8, TSN=252, Options=<TransmitOptions.SUPPRESS_ROUTE_DISC_NETWORK|ACK_REQUEST: 48>, Radius=0, Data=b'\x00\xFC\x00\x00\x00')
2022-10-18 14:36:03.247 DEBUG (MainThread) [zigpy_znp.api] Received command: AF.DataRequestExt.Rsp(Status=<Status.SUCCESS: 0>)
2022-10-18 14:36:03.249 DEBUG (MainThread) [zigpy_znp.api] Sending request: AF.DataRequestExt.Req(DstAddrModeAddress=AddrModeAddress(mode=<AddrMode.NWK: 2>, address=0x5340), DstEndpoint=1, DstPanId=0x0000, SrcEndpoint=1, ClusterId=768, TSN=253, Options=<TransmitOptions.SUPPRESS_ROUTE_DISC_NETWORK|ACK_REQUEST: 48>, Radius=0, Data=b'\x00\xFD\x00\x08\x00\x02\x40\x03\x00\x04\x00\x00\x00')
2022-10-18 14:36:03.286 DEBUG (MainThread) [zigpy_znp.api] Received command: AF.DataRequestExt.Rsp(Status=<Status.SUCCESS: 0>)
2022-10-18 14:36:03.331 DEBUG (MainThread) [zigpy_znp.api] Received command: AF.DataConfirm.Callback(Status=<Status.MAC_NO_ACK: 233>, Endpoint=1, TSN=251)
2022-10-18 14:36:03.335 DEBUG (MainThread) [zigpy_znp.zigbee.application] Request failed (Unsuccessful request status code: <Status.MAC_NO_ACK: 233>), retry attempt 4 of 5
2022-10-18 14:36:03.350 DEBUG (MainThread) [zigpy_znp.api] Received command: AF.DataConfirm.Callback(Status=<Status.MAC_NO_ACK: 233>, Endpoint=1, TSN=252)
2022-10-18 14:36:03.354 DEBUG (MainThread) [zigpy_znp.zigbee.application] Request failed (Unsuccessful request status code: <Status.MAC_NO_ACK: 233>), retry attempt 4 of 5
2022-10-18 14:36:03.395 DEBUG (MainThread) [zigpy_znp.api] Received command: AF.DataConfirm.Callback(Status=<Status.MAC_NO_ACK: 233>, Endpoint=1, TSN=253)
2022-10-18 14:36:03.397 DEBUG (MainThread) [zigpy_znp.zigbee.application] Request failed (Unsuccessful request status code: <Status.MAC_NO_ACK: 233>), retry attempt 4 of 5
2022-10-18 14:36:03.529 DEBUG (MainThread) [homeassistant.components.zha.core.device] [0xFB5F](TS011F): Device seen - marking the device available and resetting counter
2022-10-18 14:36:03.530 DEBUG (MainThread) [homeassistant.components.zha.core.device] [0xFB5F](TS011F): Update device availability -  device available: True - new availability: True - changed: False
2022-10-18 14:36:03.841 DEBUG (MainThread) [zigpy_znp.api] Sending request: AF.DataRequestExt.Req(DstAddrModeAddress=AddrModeAddress(mode=<AddrMode.IEEE: 3>, address=04:cd:15:ff:fe:8c:ae:a9), DstEndpoint=1, DstPanId=0x0000, SrcEndpoint=1, ClusterId=6, TSN=251, Options=<TransmitOptions.SUPPRESS_ROUTE_DISC_NETWORK|ACK_REQUEST: 48>, Radius=0, Data=b'\x00\xFB\x00\x00\x00')
2022-10-18 14:36:03.864 DEBUG (MainThread) [zigpy_znp.api] Received command: AF.DataRequestExt.Rsp(Status=<Status.SUCCESS: 0>)
2022-10-18 14:36:03.866 DEBUG (MainThread) [zigpy_znp.api] Sending request: AF.DataRequestExt.Req(DstAddrModeAddress=AddrModeAddress(mode=<AddrMode.IEEE: 3>, address=04:cd:15:ff:fe:8c:ae:a9), DstEndpoint=1, DstPanId=0x0000, SrcEndpoint=1, ClusterId=8, TSN=252, Options=<TransmitOptions.SUPPRESS_ROUTE_DISC_NETWORK|ACK_REQUEST: 48>, Radius=0, Data=b'\x00\xFC\x00\x00\x00')
2022-10-18 14:36:03.898 DEBUG (MainThread) [zigpy_znp.api] Received command: AF.DataRequestExt.Rsp(Status=<Status.SUCCESS: 0>)
2022-10-18 14:36:03.906 DEBUG (MainThread) [zigpy_znp.api] Sending request: AF.DataRequestExt.Req(DstAddrModeAddress=AddrModeAddress(mode=<AddrMode.IEEE: 3>, address=04:cd:15:ff:fe:8c:ae:a9), DstEndpoint=1, DstPanId=0x0000, SrcEndpoint=1, ClusterId=768, TSN=253, Options=<TransmitOptions.SUPPRESS_ROUTE_DISC_NETWORK|ACK_REQUEST: 48>, Radius=0, Data=b'\x00\xFD\x00\x08\x00\x02\x40\x03\x00\x04\x00\x00\x00')
2022-10-18 14:36:03.955 DEBUG (MainThread) [zigpy_znp.api] Received command: AF.DataRequestExt.Rsp(Status=<Status.SUCCESS: 0>)
2022-10-18 14:36:03.984 DEBUG (MainThread) [zigpy_znp.api] Received command: AF.DataConfirm.Callback(Status=<Status.MAC_NO_ACK: 233>, Endpoint=1, TSN=251)
2022-10-18 14:36:03.988 DEBUG (MainThread) [zigpy_znp.zigbee.application] Request failed (Unsuccessful request status code: <Status.MAC_NO_ACK: 233>), retry attempt 5 of 5
2022-10-18 14:36:04.011 DEBUG (MainThread) [zigpy_znp.api] Received command: AF.DataConfirm.Callback(Status=<Status.MAC_NO_ACK: 233>, Endpoint=1, TSN=252)
2022-10-18 14:36:04.014 DEBUG (MainThread) [zigpy_znp.zigbee.application] Request failed (Unsuccessful request status code: <Status.MAC_NO_ACK: 233>), retry attempt 5 of 5
2022-10-18 14:36:04.063 DEBUG (MainThread) [zigpy_znp.api] Received command: AF.DataConfirm.Callback(Status=<Status.MAC_NO_ACK: 233>, Endpoint=1, TSN=253)
2022-10-18 14:36:04.067 DEBUG (MainThread) [zigpy_znp.zigbee.application] Request failed (Unsuccessful request status code: <Status.MAC_NO_ACK: 233>), retry attempt 5 of 5
2022-10-18 14:36:04.491 DEBUG (MainThread) [homeassistant.components.zha.core.channels.base] [0x5340:1:0x0006]: failed to get attributes '['on_off']' on 'on_off' cluster: Request failed after 5 attempts: <Status.MAC_NO_ACK: 233>
2022-10-18 14:36:04.491 DEBUG (MainThread) [homeassistant.components.zha.core.channels.base] [0x5340:1:0x0006]: async_initialize: retryable request #3 failed: Request failed after 5 attempts: <Status.MAC_NO_ACK: 233>. Retrying in 3.0s
2022-10-18 14:36:04.516 DEBUG (MainThread) [homeassistant.components.zha.core.channels.base] [0x5340:1:0x0008]: failed to get attributes '['current_level']' on 'level' cluster: Request failed after 5 attempts: <Status.MAC_NO_ACK: 233>
2022-10-18 14:36:04.517 DEBUG (MainThread) [homeassistant.components.zha.core.channels.base] [0x5340:1:0x0008]: async_initialize: retryable request #3 failed: Request failed after 5 attempts: <Status.MAC_NO_ACK: 233>. Retrying in 2.4s
2022-10-18 14:36:04.570 DEBUG (MainThread) [homeassistant.components.zha.core.channels.base] [0x5340:1:0x0300]: failed to get attributes '['color_mode', 'color_loop_active', 'current_x', 'current_y', 'current_hue']' on 'light_color' cluster: Request failed after 5 attempts: <Status.MAC_NO_ACK: 233>
2022-10-18 14:36:04.571 DEBUG (MainThread) [homeassistant.components.zha.core.channels.base] [0x5340:1:0x0300]: async_initialize: retryable request #3 failed: Request failed after 5 attempts: <Status.MAC_NO_ACK: 233>. Retrying in 2.9s
2022-10-18 14:36:06.342 DEBUG (MainThread) [zigpy_znp.api] Sending request: SYS.Ping.Req()
2022-10-18 14:36:06.354 DEBUG (MainThread) [zigpy_znp.api] Received command: SYS.Ping.Rsp(Capabilities=<MTCapabilities.APP_CNF|GP|UTIL|ZDO|AF|SYS: 1625>)
2022-10-18 14:36:06.878 DEBUG (MainThread) [homeassistant.components.zha.core.channels.base] [0x5340:1:0x0008]: initializing channel: from_cache: False
2022-10-18 14:36:06.879 DEBUG (MainThread) [homeassistant.components.zha.core.channels.base] [0x5340:1:0x0008]: initializing cached channel attributes: ['on_off_transition_time', 'on_level', 'on_transition_time', 'off_transition_time', 'default_move_rate', 'start_up_current_level']
2022-10-18 14:36:06.879 DEBUG (MainThread) [homeassistant.components.zha.core.channels.base] [0x5340:1:0x0008]: Reading attributes in chunks: ['on_off_transition_time', 'on_level', 'on_transition_time', 'off_transition_time', 'default_move_rate']
2022-10-18 14:36:06.880 DEBUG (MainThread) [homeassistant.components.zha.core.channels.base] [0x5340:1:0x0008]: Reading attributes in chunks: ['start_up_current_level']
2022-10-18 14:36:06.881 DEBUG (MainThread) [homeassistant.components.zha.core.channels.base] [0x5340:1:0x0008]: initializing uncached channel attributes: ['current_level'] - from cache[False]
2022-10-18 14:36:06.881 DEBUG (MainThread) [homeassistant.components.zha.core.channels.base] [0x5340:1:0x0008]: Reading attributes in chunks: ['current_level']
2022-10-18 14:36:06.885 DEBUG (MainThread) [zigpy.zcl] [0x5340:1:0x0008] Sending request header: ZCLHeader(frame_control=FrameControl(frame_type=<FrameType.GLOBAL_COMMAND: 0>, is_manufacturer_specific=False, direction=<Direction.Server_to_Client: 0>, disable_default_response=0, reserved=0, *is_cluster=False, *is_general=True, *is_reply=False), tsn=255, command_id=<GeneralCommand.Read_Attributes: 0>, *direction=<Direction.Server_to_Client: 0>, *is_reply=False)
2022-10-18 14:36:06.888 DEBUG (MainThread) [zigpy.zcl] [0x5340:1:0x0008] Sending request: Read_Attributes(attribute_ids=[0])
2022-10-18 14:36:06.891 DEBUG (MainThread) [zigpy_znp.zigbee.application] Sending packet ZigbeePacket(src=AddrModeAddress(addr_mode=<AddrMode.NWK: 2>, address=0x0000), src_ep=1, dst=AddrModeAddress(addr_mode=<AddrMode.NWK: 2>, address=0x5340), dst_ep=1, source_route=None, extended_timeout=False, tsn=255, profile_id=260, cluster_id=8, data=Serialized[b'\x00\xff\x00\x00\x00'], tx_options=<TransmitOptions.ACK: 1>, radius=0, non_member_radius=0, lqi=None, rssi=None)
2022-10-18 14:36:06.894 DEBUG (MainThread) [zigpy_znp.api] Sending request: AF.DataRequestExt.Req(DstAddrModeAddress=AddrModeAddress(mode=<AddrMode.NWK: 2>, address=0x5340), DstEndpoint=1, DstPanId=0x0000, SrcEndpoint=1, ClusterId=8, TSN=255, Options=<TransmitOptions.SUPPRESS_ROUTE_DISC_NETWORK|ACK_REQUEST: 48>, Radius=0, Data=b'\x00\xFF\x00\x00\x00')
2022-10-18 14:36:06.916 DEBUG (MainThread) [zigpy_znp.api] Received command: AF.DataRequestExt.Rsp(Status=<Status.SUCCESS: 0>)
2022-10-18 14:36:06.987 DEBUG (MainThread) [zigpy_znp.api] Received command: AF.DataConfirm.Callback(Status=<Status.MAC_NO_ACK: 233>, Endpoint=1, TSN=255)
2022-10-18 14:36:06.992 DEBUG (MainThread) [zigpy_znp.zigbee.application] Request failed (Unsuccessful request status code: <Status.MAC_NO_ACK: 233>), retry attempt 1 of 5
2022-10-18 14:36:07.452 DEBUG (MainThread) [homeassistant.components.zha.core.channels.base] [0x5340:1:0x0300]: initializing channel: from_cache: False
2022-10-18 14:36:07.453 DEBUG (MainThread) [homeassistant.components.zha.core.channels.base] [0x5340:1:0x0300]: initializing cached channel attributes: ['color_temp_physical_min', 'color_temp_physical_max', 'color_capabilities']
2022-10-18 14:36:07.454 DEBUG (MainThread) [homeassistant.components.zha.core.channels.base] [0x5340:1:0x0300]: Reading attributes in chunks: ['color_temp_physical_min', 'color_temp_physical_max', 'color_capabilities']
2022-10-18 14:36:07.454 DEBUG (MainThread) [homeassistant.components.zha.core.channels.base] [0x5340:1:0x0300]: initializing uncached channel attributes: ['color_mode', 'color_loop_active', 'current_x', 'current_y', 'current_hue', 'enhanced_current_hue', 'current_saturation', 'color_temperature'] - from cache[False]
2022-10-18 14:36:07.455 DEBUG (MainThread) [homeassistant.components.zha.core.channels.base] [0x5340:1:0x0300]: Reading attributes in chunks: ['color_mode', 'color_loop_active', 'current_x', 'current_y', 'current_hue']
2022-10-18 14:36:07.460 DEBUG (MainThread) [zigpy.zcl] [0x5340:1:0x0300] Sending request header: ZCLHeader(frame_control=FrameControl(frame_type=<FrameType.GLOBAL_COMMAND: 0>, is_manufacturer_specific=False, direction=<Direction.Server_to_Client: 0>, disable_default_response=0, reserved=0, *is_cluster=False, *is_general=True, *is_reply=False), tsn=0, command_id=<GeneralCommand.Read_Attributes: 0>, *direction=<Direction.Server_to_Client: 0>, *is_reply=False)
2022-10-18 14:36:07.463 DEBUG (MainThread) [zigpy.zcl] [0x5340:1:0x0300] Sending request: Read_Attributes(attribute_ids=[8, 16386, 3, 4, 0])
2022-10-18 14:36:07.465 DEBUG (MainThread) [zigpy_znp.zigbee.application] Sending packet ZigbeePacket(src=AddrModeAddress(addr_mode=<AddrMode.NWK: 2>, address=0x0000), src_ep=1, dst=AddrModeAddress(addr_mode=<AddrMode.NWK: 2>, address=0x5340), dst_ep=1, source_route=None, extended_timeout=False, tsn=0, profile_id=260, cluster_id=768, data=Serialized[b'\x00\x00\x00\x08\x00\x02@\x03\x00\x04\x00\x00\x00'], tx_options=<TransmitOptions.ACK: 1>, radius=0, non_member_radius=0, lqi=None, rssi=None)
2022-10-18 14:36:07.468 DEBUG (MainThread) [zigpy_znp.api] Sending request: AF.DataRequestExt.Req(DstAddrModeAddress=AddrModeAddress(mode=<AddrMode.NWK: 2>, address=0x5340), DstEndpoint=1, DstPanId=0x0000, SrcEndpoint=1, ClusterId=768, TSN=0, Options=<TransmitOptions.SUPPRESS_ROUTE_DISC_NETWORK|ACK_REQUEST: 48>, Radius=0, Data=b'\x00\x00\x00\x08\x00\x02\x40\x03\x00\x04\x00\x00\x00')
2022-10-18 14:36:07.486 DEBUG (MainThread) [homeassistant.components.zha.core.channels.base] [0x5340:1:0x0006]: initializing channel: from_cache: False
2022-10-18 14:36:07.487 DEBUG (MainThread) [homeassistant.components.zha.core.channels.base] [0x5340:1:0x0006]: initializing cached channel attributes: ['start_up_on_off']
2022-10-18 14:36:07.488 DEBUG (MainThread) [homeassistant.components.zha.core.channels.base] [0x5340:1:0x0006]: Reading attributes in chunks: ['start_up_on_off']
2022-10-18 14:36:07.488 DEBUG (MainThread) [homeassistant.components.zha.core.channels.base] [0x5340:1:0x0006]: initializing uncached channel attributes: ['on_off'] - from cache[False]
2022-10-18 14:36:07.489 DEBUG (MainThread) [homeassistant.components.zha.core.channels.base] [0x5340:1:0x0006]: Reading attributes in chunks: ['on_off']
2022-10-18 14:36:07.490 DEBUG (MainThread) [zigpy.zcl] [0x5340:1:0x0006] Sending request header: ZCLHeader(frame_control=FrameControl(frame_type=<FrameType.GLOBAL_COMMAND: 0>, is_manufacturer_specific=False, direction=<Direction.Server_to_Client: 0>, disable_default_response=0, reserved=0, *is_cluster=False, *is_general=True, *is_reply=False), tsn=1, command_id=<GeneralCommand.Read_Attributes: 0>, *direction=<Direction.Server_to_Client: 0>, *is_reply=False)
2022-10-18 14:36:07.492 DEBUG (MainThread) [zigpy.zcl] [0x5340:1:0x0006] Sending request: Read_Attributes(attribute_ids=[0])
2022-10-18 14:36:07.494 DEBUG (MainThread) [zigpy_znp.zigbee.application] Sending packet ZigbeePacket(src=AddrModeAddress(addr_mode=<AddrMode.NWK: 2>, address=0x0000), src_ep=1, dst=AddrModeAddress(addr_mode=<AddrMode.NWK: 2>, address=0x5340), dst_ep=1, source_route=None, extended_timeout=False, tsn=1, profile_id=260, cluster_id=6, data=Serialized[b'\x00\x01\x00\x00\x00'], tx_options=<TransmitOptions.ACK: 1>, radius=0, non_member_radius=0, lqi=None, rssi=None)
2022-10-18 14:36:07.514 DEBUG (MainThread) [zigpy_znp.api] Received command: AF.DataRequestExt.Rsp(Status=<Status.SUCCESS: 0>)
2022-10-18 14:36:07.516 DEBUG (MainThread) [zigpy_znp.api] Sending request: AF.DataRequestExt.Req(DstAddrModeAddress=AddrModeAddress(mode=<AddrMode.NWK: 2>, address=0x5340), DstEndpoint=1, DstPanId=0x0000, SrcEndpoint=1, ClusterId=6, TSN=1, Options=<TransmitOptions.SUPPRESS_ROUTE_DISC_NETWORK|ACK_REQUEST: 48>, Radius=0, Data=b'\x00\x01\x00\x00\x00')
2022-10-18 14:36:07.552 DEBUG (MainThread) [zigpy_znp.api] Received command: AF.DataRequestExt.Rsp(Status=<Status.SUCCESS: 0>)
2022-10-18 14:36:07.599 DEBUG (MainThread) [zigpy_znp.api] Received command: AF.DataConfirm.Callback(Status=<Status.MAC_NO_ACK: 233>, Endpoint=1, TSN=0)
2022-10-18 14:36:07.604 DEBUG (MainThread) [zigpy_znp.zigbee.application] Request failed (Unsuccessful request status code: <Status.MAC_NO_ACK: 233>), retry attempt 1 of 5
2022-10-18 14:36:07.643 DEBUG (MainThread) [zigpy_znp.api] Received command: AF.DataConfirm.Callback(Status=<Status.MAC_NO_ACK: 233>, Endpoint=1, TSN=1)
2022-10-18 14:36:07.653 DEBUG (MainThread) [zigpy_znp.zigbee.application] Request failed (Unsuccessful request status code: <Status.MAC_NO_ACK: 233>), retry attempt 1 of 5
2022-10-18 14:36:08.499 DEBUG (MainThread) [zigpy_znp.api] Sending request: AF.DataRequestExt.Req(DstAddrModeAddress=AddrModeAddress(mode=<AddrMode.NWK: 2>, address=0x5340), DstEndpoint=1, DstPanId=0x0000, SrcEndpoint=1, ClusterId=8, TSN=255, Options=<TransmitOptions.SUPPRESS_ROUTE_DISC_NETWORK|ACK_REQUEST: 48>, Radius=0, Data=b'\x00\xFF\x00\x00\x00')
2022-10-18 14:36:08.520 DEBUG (MainThread) [zigpy_znp.api] Received command: AF.DataRequestExt.Rsp(Status=<Status.SUCCESS: 0>)
2022-10-18 14:36:08.594 DEBUG (MainThread) [zigpy_znp.api] Received command: AF.DataConfirm.Callback(Status=<Status.MAC_NO_ACK: 233>, Endpoint=1, TSN=255)
2022-10-18 14:36:08.599 DEBUG (MainThread) [zigpy_znp.zigbee.application] Request failed (Unsuccessful request status code: <Status.MAC_NO_ACK: 233>), retry attempt 2 of 5
2022-10-18 14:36:08.775 DEBUG (MainThread) [homeassistant.components.zha.core.device] [0x383E](TRADFRI bulb E27 CWS 806lm): Device seen - marking the device available and resetting counter
2022-10-18 14:36:08.775 DEBUG (MainThread) [homeassistant.components.zha.core.device] [0x383E](TRADFRI bulb E27 CWS 806lm): Update device availability -  device available: True - new availability: True - changed: False
2022-10-18 14:36:09.104 DEBUG (MainThread) [zigpy_znp.api] Sending request: AF.DataRequestSrcRtg.Req(DstAddr=0x5340, DstEndpoint=1, SrcEndpoint=1, ClusterId=8, TSN=255, Options=<TransmitOptions.SUPPRESS_ROUTE_DISC_NETWORK|ACK_REQUEST: 48>, Radius=0, SourceRoute=[], Data=b'\x00\xFF\x00\x00\x00')
2022-10-18 14:36:09.126 DEBUG (MainThread) [zigpy_znp.api] Received command: AF.DataRequestSrcRtg.Rsp(Status=<Status.SUCCESS: 0>)
2022-10-18 14:36:09.130 DEBUG (MainThread) [zigpy_znp.api] Sending request: AF.DataRequestExt.Req(DstAddrModeAddress=AddrModeAddress(mode=<AddrMode.NWK: 2>, address=0x5340), DstEndpoint=1, DstPanId=0x0000, SrcEndpoint=1, ClusterId=768, TSN=0, Options=<TransmitOptions.SUPPRESS_ROUTE_DISC_NETWORK|ACK_REQUEST: 48>, Radius=0, Data=b'\x00\x00\x00\x08\x00\x02\x40\x03\x00\x04\x00\x00\x00')
2022-10-18 14:36:09.164 DEBUG (MainThread) [zigpy_znp.api] Received command: AF.DataRequestExt.Rsp(Status=<Status.SUCCESS: 0>)
2022-10-18 14:36:09.167 DEBUG (MainThread) [zigpy_znp.api] Sending request: AF.DataRequestExt.Req(DstAddrModeAddress=AddrModeAddress(mode=<AddrMode.NWK: 2>, address=0x5340), DstEndpoint=1, DstPanId=0x0000, SrcEndpoint=1, ClusterId=6, TSN=1, Options=<TransmitOptions.SUPPRESS_ROUTE_DISC_NETWORK|ACK_REQUEST: 48>, Radius=0, Data=b'\x00\x01\x00\x00\x00')
2022-10-18 14:36:09.200 DEBUG (MainThread) [zigpy_znp.api] Received command: AF.DataRequestExt.Rsp(Status=<Status.SUCCESS: 0>)
2022-10-18 14:36:09.211 DEBUG (MainThread) [zigpy_znp.api] Received command: AF.DataConfirm.Callback(Status=<Status.MAC_NO_ACK: 233>, Endpoint=1, TSN=255)
2022-10-18 14:36:09.216 DEBUG (MainThread) [zigpy_znp.api] Sending request: ZDO.ExtRouteDisc.Req(Dst=0x5340, Options=<RouteDiscoveryOptions.UNICAST: 0>, Radius=30)
2022-10-18 14:36:09.226 DEBUG (MainThread) [zigpy_znp.api] Received command: ZDO.ExtRouteDisc.Rsp(Status=<Status.SUCCESS: 0>)
2022-10-18 14:36:09.282 DEBUG (MainThread) [zigpy_znp.api] Received command: AF.DataConfirm.Callback(Status=<Status.MAC_NO_ACK: 233>, Endpoint=1, TSN=0)
2022-10-18 14:36:09.287 DEBUG (MainThread) [zigpy_znp.zigbee.application] Request failed (Unsuccessful request status code: <Status.MAC_NO_ACK: 233>), retry attempt 2 of 5
2022-10-18 14:36:09.302 DEBUG (MainThread) [zigpy_znp.api] Received command: AF.DataConfirm.Callback(Status=<Status.MAC_NO_ACK: 233>, Endpoint=1, TSN=1)
2022-10-18 14:36:09.304 DEBUG (MainThread) [zigpy_znp.zigbee.application] Request failed (Unsuccessful request status code: <Status.MAC_NO_ACK: 233>), retry attempt 2 of 5
2022-10-18 14:36:09.793 DEBUG (MainThread) [zigpy_znp.api] Sending request: AF.DataRequestSrcRtg.Req(DstAddr=0x5340, DstEndpoint=1, SrcEndpoint=1, ClusterId=768, TSN=0, Options=<TransmitOptions.SUPPRESS_ROUTE_DISC_NETWORK|ACK_REQUEST: 48>, Radius=0, SourceRoute=[], Data=b'\x00\x00\x00\x08\x00\x02\x40\x03\x00\x04\x00\x00\x00')
2022-10-18 14:36:09.816 DEBUG (MainThread) [zigpy_znp.api] Received command: AF.DataRequestSrcRtg.Rsp(Status=<Status.SUCCESS: 0>)
2022-10-18 14:36:09.819 DEBUG (MainThread) [zigpy_znp.api] Sending request: AF.DataRequestSrcRtg.Req(DstAddr=0x5340, DstEndpoint=1, SrcEndpoint=1, ClusterId=6, TSN=1, Options=<TransmitOptions.SUPPRESS_ROUTE_DISC_NETWORK|ACK_REQUEST: 48>, Radius=0, SourceRoute=[], Data=b'\x00\x01\x00\x00\x00')
2022-10-18 14:36:09.870 DEBUG (MainThread) [zigpy_znp.api] Received command: AF.DataRequestSrcRtg.Rsp(Status=<Status.SUCCESS: 0>)
2022-10-18 14:36:09.932 DEBUG (MainThread) [zigpy_znp.api] Received command: AF.DataConfirm.Callback(Status=<Status.MAC_NO_ACK: 233>, Endpoint=1, TSN=0)
2022-10-18 14:36:09.947 DEBUG (MainThread) [zigpy_znp.api] Received command: AF.DataConfirm.Callback(Status=<Status.MAC_NO_ACK: 233>, Endpoint=1, TSN=1)
2022-10-18 14:36:10.531 DEBUG (MainThread) [zigpy_znp.zigbee.application] Request failed (Unsuccessful request status code: <Status.MAC_NO_ACK: 233>), retry attempt 3 of 5
2022-10-18 14:36:10.532 DEBUG (MainThread) [zigpy_znp.zigbee.application] Request failed (Unsuccessful request status code: <Status.MAC_NO_ACK: 233>), retry attempt 3 of 5
2022-10-18 14:36:10.533 DEBUG (MainThread) [zigpy_znp.zigbee.application] Request failed (Unsuccessful request status code: <Status.MAC_NO_ACK: 233>), retry attempt 3 of 5
2022-10-18 14:36:10.661 DEBUG (MainThread) [zigpy_znp.api] Received command: AF.IncomingMsg.Callback(GroupId=0x0000, ClusterId=6, SrcAddr=0xFA52, SrcEndpoint=1, DstEndpoint=1, WasBroadcast=<Bool.false: 0>, LQI=36, SecurityUse=<Bool.false: 0>, TimeStamp=14752394, TSN=0, Data=b'\x08\x35\x0A\x00\x00\x10\x00', MacSrcAddr=0xFA52, MsgResultRadius=29)
2022-10-18 14:36:10.666 DEBUG (MainThread) [zigpy.application] Received a packet: ZigbeePacket(src=AddrModeAddress(addr_mode=<AddrMode.NWK: 2>, address=0xFA52), 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=6, data=Serialized[b'\x085\n\x00\x00\x10\x00'], tx_options=<TransmitOptions.NONE: 0>, radius=29, non_member_radius=0, lqi=36, rssi=None)
2022-10-18 14:36:10.668 DEBUG (MainThread) [zigpy.zcl] [0xFA52:1:0x0006] Received ZCL frame: b'\x085\n\x00\x00\x10\x00'
2022-10-18 14:36:10.671 DEBUG (MainThread) [zigpy.zcl] [0xFA52:1:0x0006] Decoded ZCL frame header: ZCLHeader(frame_control=FrameControl(frame_type=<FrameType.GLOBAL_COMMAND: 0>, is_manufacturer_specific=0, direction=<Direction.Client_to_Server: 1>, disable_default_response=0, reserved=0, *is_cluster=False, *is_general=True, *is_reply=True), tsn=53, command_id=10, *direction=<Direction.Client_to_Server: 1>, *is_reply=True)
2022-10-18 14:36:10.673 DEBUG (MainThread) [zigpy.zcl] [0xFA52:1:0x0006] Decoded ZCL frame: OnOff:Report_Attributes(attribute_reports=[Attribute(attrid=0x0000, value=TypeValue(type=Bool, value=<Bool.false: 0>))])
2022-10-18 14:36:10.674 DEBUG (MainThread) [zigpy.zcl] [0xFA52:1:0x0006] Received command 0x0A (TSN 53): Report_Attributes(attribute_reports=[Attribute(attrid=0x0000, value=TypeValue(type=Bool, value=<Bool.false: 0>))])
2022-10-18 14:36:10.676 DEBUG (MainThread) [zigpy.zcl] [0xFA52:1:0x0006] Attribute report received: on_off=<Bool.false: 0>
2022-10-18 14:36:10.679 DEBUG (MainThread) [zigpy.zcl] [0xFA52:1:0x0006] Sending reply header: ZCLHeader(frame_control=FrameControl(frame_type=<FrameType.GLOBAL_COMMAND: 0>, is_manufacturer_specific=False, direction=<Direction.Client_to_Server: 1>, disable_default_response=1, reserved=0, *is_cluster=False, *is_general=True, *is_reply=True), tsn=53, command_id=<GeneralCommand.Default_Response: 11>, *direction=<Direction.Client_to_Server: 1>, *is_reply=True)
2022-10-18 14:36:10.680 DEBUG (MainThread) [zigpy.zcl] [0xFA52:1:0x0006] Sending reply: Default_Response(command_id=10, status=<Status.SUCCESS: 0>)
2022-10-18 14:36:10.681 DEBUG (MainThread) [zigpy_znp.zigbee.application] Sending packet ZigbeePacket(src=AddrModeAddress(addr_mode=<AddrMode.NWK: 2>, address=0x0000), src_ep=1, dst=AddrModeAddress(addr_mode=<AddrMode.NWK: 2>, address=0xFA52), dst_ep=1, source_route=None, extended_timeout=False, tsn=53, profile_id=260, cluster_id=6, data=Serialized[b'\x185\x0b\n\x00'], tx_options=<TransmitOptions.NONE: 0>, radius=0, non_member_radius=0, lqi=None, rssi=None)
2022-10-18 14:36:10.685 DEBUG (MainThread) [zigpy_znp.api] Sending request: AF.DataRequestExt.Req(DstAddrModeAddress=AddrModeAddress(mode=<AddrMode.NWK: 2>, address=0xFA52), DstEndpoint=1, DstPanId=0x0000, SrcEndpoint=1, ClusterId=6, TSN=53, Options=<TransmitOptions.SUPPRESS_ROUTE_DISC_NETWORK: 32>, Radius=0, Data=b'\x18\x35\x0B\x0A\x00')
2022-10-18 14:36:10.708 DEBUG (MainThread) [zigpy_znp.api] Received command: AF.DataRequestExt.Rsp(Status=<Status.SUCCESS: 0>)
2022-10-18 14:36:10.714 DEBUG (MainThread) [zigpy_znp.api] Received command: AF.DataConfirm.Callback(Status=<Status.SUCCESS: 0>, Endpoint=1, TSN=53)
2022-10-18 14:36:11.036 DEBUG (MainThread) [zigpy_znp.api] Sending request: AF.DataRequestExt.Req(DstAddrModeAddress=AddrModeAddress(mode=<AddrMode.NWK: 2>, address=0x5340), DstEndpoint=1, DstPanId=0x0000, SrcEndpoint=1, ClusterId=8, TSN=255, Options=<TransmitOptions.SUPPRESS_ROUTE_DISC_NETWORK|ACK_REQUEST: 48>, Radius=0, Data=b'\x00\xFF\x00\x00\x00')
2022-10-18 14:36:11.063 DEBUG (MainThread) [zigpy_znp.api] Received command: AF.DataRequestExt.Rsp(Status=<Status.SUCCESS: 0>)
2022-10-18 14:36:11.067 DEBUG (MainThread) [zigpy_znp.api] Sending request: AF.DataRequestExt.Req(DstAddrModeAddress=AddrModeAddress(mode=<AddrMode.NWK: 2>, address=0x5340), DstEndpoint=1, DstPanId=0x0000, SrcEndpoint=1, ClusterId=768, TSN=0, Options=<TransmitOptions.SUPPRESS_ROUTE_DISC_NETWORK|ACK_REQUEST: 48>, Radius=0, Data=b'\x00\x00\x00\x08\x00\x02\x40\x03\x00\x04\x00\x00\x00')
2022-10-18 14:36:11.100 DEBUG (MainThread) [zigpy_znp.api] Received command: AF.DataRequestExt.Rsp(Status=<Status.SUCCESS: 0>)
2022-10-18 14:36:11.104 DEBUG (MainThread) [zigpy_znp.api] Sending request: AF.DataRequestExt.Req(DstAddrModeAddress=AddrModeAddress(mode=<AddrMode.NWK: 2>, address=0x5340), DstEndpoint=1, DstPanId=0x0000, SrcEndpoint=1, ClusterId=6, TSN=1, Options=<TransmitOptions.SUPPRESS_ROUTE_DISC_NETWORK|ACK_REQUEST: 48>, Radius=0, Data=b'\x00\x01\x00\x00\x00')
2022-10-18 14:36:11.138 DEBUG (MainThread) [zigpy_znp.api] Received command: AF.DataRequestExt.Rsp(Status=<Status.SUCCESS: 0>)
2022-10-18 14:36:11.145 DEBUG (MainThread) [zigpy_znp.api] Received command: AF.DataConfirm.Callback(Status=<Status.MAC_NO_ACK: 233>, Endpoint=1, TSN=255)
2022-10-18 14:36:11.150 DEBUG (MainThread) [zigpy_znp.zigbee.application] Request failed (Unsuccessful request status code: <Status.MAC_NO_ACK: 233>), retry attempt 4 of 5
2022-10-18 14:36:11.221 DEBUG (MainThread) [zigpy_znp.api] Received command: AF.DataConfirm.Callback(Status=<Status.MAC_NO_ACK: 233>, Endpoint=1, TSN=0)
2022-10-18 14:36:11.226 DEBUG (MainThread) [zigpy_znp.zigbee.application] Request failed (Unsuccessful request status code: <Status.MAC_NO_ACK: 233>), retry attempt 4 of 5
2022-10-18 14:36:11.236 DEBUG (MainThread) [zigpy_znp.api] Received command: AF.DataConfirm.Callback(Status=<Status.MAC_NO_ACK: 233>, Endpoint=1, TSN=1)
2022-10-18 14:36:11.240 DEBUG (MainThread) [zigpy_znp.zigbee.application] Request failed (Unsuccessful request status code: <Status.MAC_NO_ACK: 233>), retry attempt 4 of 5
2022-10-18 14:36:11.637 DEBUG (MainThread) [zigpy_znp.api] Received command: AF.IncomingMsg.Callback(GroupId=0x0000, ClusterId=8, SrcAddr=0xFA52, SrcEndpoint=1, DstEndpoint=1, WasBroadcast=<Bool.false: 0>, LQI=36, SecurityUse=<Bool.false: 0>, TimeStamp=14813393, TSN=0, Data=b'\x08\x36\x0A\x00\x00\x20\x01', MacSrcAddr=0xFA52, MsgResultRadius=29)
2022-10-18 14:36:11.642 DEBUG (MainThread) [zigpy.application] Received a packet: ZigbeePacket(src=AddrModeAddress(addr_mode=<AddrMode.NWK: 2>, address=0xFA52), 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=8, data=Serialized[b'\x086\n\x00\x00 \x01'], tx_options=<TransmitOptions.NONE: 0>, radius=29, non_member_radius=0, lqi=36, rssi=None)
2022-10-18 14:36:11.643 DEBUG (MainThread) [zigpy.zcl] [0xFA52:1:0x0008] Received ZCL frame: b'\x086\n\x00\x00 \x01'
2022-10-18 14:36:11.645 DEBUG (MainThread) [zigpy.zcl] [0xFA52:1:0x0008] Decoded ZCL frame header: ZCLHeader(frame_control=FrameControl(frame_type=<FrameType.GLOBAL_COMMAND: 0>, is_manufacturer_specific=0, direction=<Direction.Client_to_Server: 1>, disable_default_response=0, reserved=0, *is_cluster=False, *is_general=True, *is_reply=True), tsn=54, command_id=10, *direction=<Direction.Client_to_Server: 1>, *is_reply=True)
2022-10-18 14:36:11.648 DEBUG (MainThread) [zigpy.zcl] [0xFA52:1:0x0008] Decoded ZCL frame: LevelControl:Report_Attributes(attribute_reports=[Attribute(attrid=0x0000, value=TypeValue(type=uint8_t, value=1))])
2022-10-18 14:36:11.649 DEBUG (MainThread) [zigpy.zcl] [0xFA52:1:0x0008] Received command 0x0A (TSN 54): Report_Attributes(attribute_reports=[Attribute(attrid=0x0000, value=TypeValue(type=uint8_t, value=1))])
2022-10-18 14:36:11.650 DEBUG (MainThread) [zigpy.zcl] [0xFA52:1:0x0008] Attribute report received: current_level=1
2022-10-18 14:36:11.651 DEBUG (MainThread) [homeassistant.components.zha.core.channels.base] [0xFA52:1:0x0008]: received attribute: 0 update with value: 1
2022-10-18 14:36:11.654 DEBUG (MainThread) [zigpy.zcl] [0xFA52:1:0x0008] Sending reply header: ZCLHeader(frame_control=FrameControl(frame_type=<FrameType.GLOBAL_COMMAND: 0>, is_manufacturer_specific=False, direction=<Direction.Client_to_Server: 1>, disable_default_response=1, reserved=0, *is_cluster=False, *is_general=True, *is_reply=True), tsn=54, command_id=<GeneralCommand.Default_Response: 11>, *direction=<Direction.Client_to_Server: 1>, *is_reply=True)
2022-10-18 14:36:11.655 DEBUG (MainThread) [zigpy.zcl] [0xFA52:1:0x0008] Sending reply: Default_Response(command_id=10, status=<Status.SUCCESS: 0>)
2022-10-18 14:36:11.657 DEBUG (MainThread) [zigpy_znp.zigbee.application] Sending packet ZigbeePacket(src=AddrModeAddress(addr_mode=<AddrMode.NWK: 2>, address=0x0000), src_ep=1, dst=AddrModeAddress(addr_mode=<AddrMode.NWK: 2>, address=0xFA52), dst_ep=1, source_route=None, extended_timeout=False, tsn=54, profile_id=260, cluster_id=8, data=Serialized[b'\x186\x0b\n\x00'], tx_options=<TransmitOptions.NONE: 0>, radius=0, non_member_radius=0, lqi=None, rssi=None)
2022-10-18 14:36:11.661 DEBUG (MainThread) [zigpy_znp.api] Sending request: AF.DataRequestExt.Req(DstAddrModeAddress=AddrModeAddress(mode=<AddrMode.NWK: 2>, address=0xFA52), DstEndpoint=1, DstPanId=0x0000, SrcEndpoint=1, ClusterId=8, TSN=54, Options=<TransmitOptions.SUPPRESS_ROUTE_DISC_NETWORK: 32>, Radius=0, Data=b'\x18\x36\x0B\x0A\x00')
2022-10-18 14:36:11.689 DEBUG (MainThread) [zigpy_znp.api] Received command: AF.DataRequestExt.Rsp(Status=<Status.SUCCESS: 0>)
2022-10-18 14:36:11.690 DEBUG (MainThread) [zigpy_znp.api] Received command: AF.DataConfirm.Callback(Status=<Status.SUCCESS: 0>, Endpoint=1, TSN=54)
2022-10-18 14:36:11.694 DEBUG (MainThread) [zigpy_znp.api] Sending request: AF.DataRequestExt.Req(DstAddrModeAddress=AddrModeAddress(mode=<AddrMode.IEEE: 3>, address=04:cd:15:ff:fe:8c:ae:a9), DstEndpoint=1, DstPanId=0x0000, SrcEndpoint=1, ClusterId=8, TSN=255, Options=<TransmitOptions.SUPPRESS_ROUTE_DISC_NETWORK|ACK_REQUEST: 48>, Radius=0, Data=b'\x00\xFF\x00\x00\x00')
2022-10-18 14:36:11.716 DEBUG (MainThread) [zigpy_znp.api] Received command: AF.DataRequestExt.Rsp(Status=<Status.SUCCESS: 0>)
2022-10-18 14:36:11.731 DEBUG (MainThread) [zigpy_znp.api] Sending request: AF.DataRequestExt.Req(DstAddrModeAddress=AddrModeAddress(mode=<AddrMode.IEEE: 3>, address=04:cd:15:ff:fe:8c:ae:a9), DstEndpoint=1, DstPanId=0x0000, SrcEndpoint=1, ClusterId=768, TSN=0, Options=<TransmitOptions.SUPPRESS_ROUTE_DISC_NETWORK|ACK_REQUEST: 48>, Radius=0, Data=b'\x00\x00\x00\x08\x00\x02\x40\x03\x00\x04\x00\x00\x00')
2022-10-18 14:36:11.755 DEBUG (MainThread) [zigpy_znp.api] Received command: AF.DataRequestExt.Rsp(Status=<Status.SUCCESS: 0>)
2022-10-18 14:36:11.759 DEBUG (MainThread) [zigpy_znp.api] Sending request: AF.DataRequestExt.Req(DstAddrModeAddress=AddrModeAddress(mode=<AddrMode.IEEE: 3>, address=04:cd:15:ff:fe:8c:ae:a9), DstEndpoint=1, DstPanId=0x0000, SrcEndpoint=1, ClusterId=6, TSN=1, Options=<TransmitOptions.SUPPRESS_ROUTE_DISC_NETWORK|ACK_REQUEST: 48>, Radius=0, Data=b'\x00\x01\x00\x00\x00')
2022-10-18 14:36:11.790 DEBUG (MainThread) [zigpy_znp.api] Received command: AF.DataRequestExt.Rsp(Status=<Status.SUCCESS: 0>)
2022-10-18 14:36:11.799 DEBUG (MainThread) [zigpy_znp.api] Received command: AF.DataConfirm.Callback(Status=<Status.MAC_NO_ACK: 233>, Endpoint=1, TSN=255)
2022-10-18 14:36:11.803 DEBUG (MainThread) [zigpy_znp.zigbee.application] Request failed (Unsuccessful request status code: <Status.MAC_NO_ACK: 233>), retry attempt 5 of 5
2022-10-18 14:36:11.872 DEBUG (MainThread) [zigpy_znp.api] Received command: AF.DataConfirm.Callback(Status=<Status.MAC_NO_ACK: 233>, Endpoint=1, TSN=0)
2022-10-18 14:36:11.877 DEBUG (MainThread) [zigpy_znp.zigbee.application] Request failed (Unsuccessful request status code: <Status.MAC_NO_ACK: 233>), retry attempt 5 of 5
2022-10-18 14:36:11.887 DEBUG (MainThread) [zigpy_znp.api] Received command: AF.DataConfirm.Callback(Status=<Status.MAC_NO_ACK: 233>, Endpoint=1, TSN=1)
2022-10-18 14:36:11.891 DEBUG (MainThread) [zigpy_znp.zigbee.application] Request failed (Unsuccessful request status code: <Status.MAC_NO_ACK: 233>), retry attempt 5 of 5
2022-10-18 14:36:12.305 DEBUG (MainThread) [homeassistant.components.zha.core.channels.base] [0x5340:1:0x0008]: failed to get attributes '['current_level']' on 'level' cluster: Request failed after 5 attempts: <Status.MAC_NO_ACK: 233>
2022-10-18 14:36:12.306 WARNING (MainThread) [homeassistant.components.zha.core.channels.base] [0x5340:1:0x0008]: async_initialize: all attempts have failed: [DeliveryError('Request failed after 5 attempts: <Status.MAC_NO_ACK: 233>'), DeliveryError('Request failed after 5 attempts: <Status.MAC_NO_ACK: 233>'), DeliveryError('Request failed after 5 attempts: <Status.MAC_NO_ACK: 233>'), DeliveryError('Request failed after 5 attempts: <Status.MAC_NO_ACK: 233>')]
2022-10-18 14:36:12.381 DEBUG (MainThread) [homeassistant.components.zha.core.channels.base] [0x5340:1:0x0300]: failed to get attributes '['color_mode', 'color_loop_active', 'current_x', 'current_y', 'current_hue']' on 'light_color' cluster: Request failed after 5 attempts: <Status.MAC_NO_ACK: 233>
2022-10-18 14:36:12.382 WARNING (MainThread) [homeassistant.components.zha.core.channels.base] [0x5340:1:0x0300]: async_initialize: all attempts have failed: [DeliveryError('Request failed after 5 attempts: <Status.MAC_NO_ACK: 233>'), DeliveryError('Request failed after 5 attempts: <Status.MAC_NO_ACK: 233>'), DeliveryError('Request failed after 5 attempts: <Status.MAC_NO_ACK: 233>'), DeliveryError('Request failed after 5 attempts: <Status.MAC_NO_ACK: 233>')]
2022-10-18 14:36:12.393 DEBUG (MainThread) [homeassistant.components.zha.core.channels.base] [0x5340:1:0x0006]: failed to get attributes '['on_off']' on 'on_off' cluster: Request failed after 5 attempts: <Status.MAC_NO_ACK: 233>
2022-10-18 14:36:12.394 WARNING (MainThread) [homeassistant.components.zha.core.channels.base] [0x5340:1:0x0006]: async_initialize: all attempts have failed: [DeliveryError('Request failed after 5 attempts: <Status.MAC_NO_ACK: 233>'), DeliveryError('Request failed after 5 attempts: <Status.MAC_NO_ACK: 233>'), DeliveryError('Request failed after 5 attempts: <Status.MAC_NO_ACK: 233>'), DeliveryError('Request failed after 5 attempts: <Status.MAC_NO_ACK: 233>')]
2022-10-18 14:36:12.400 DEBUG (MainThread) [homeassistant.components.zha.core.channels.base] [0x5340:1:0x0006]: 'async_initialize' stage succeeded
2022-10-18 14:36:12.401 DEBUG (MainThread) [homeassistant.components.zha.core.channels.base] [0x5340:1:0x0300]: 'async_initialize' stage succeeded
2022-10-18 14:36:12.401 DEBUG (MainThread) [homeassistant.components.zha.core.channels.base] [0x5340:1:0x0008]: 'async_initialize' stage succeeded
2022-10-18 14:36:12.402 DEBUG (MainThread) [homeassistant.components.zha.core.channels.base] [0x5340:1:0x0003]: 'async_initialize' stage succeeded
2022-10-18 14:36:12.402 DEBUG (MainThread) [homeassistant.components.zha.core.channels.base] [0x5340:1:0x0000]: 'async_initialize' stage succeeded
2022-10-18 14:36:12.402 DEBUG (MainThread) [homeassistant.components.zha.core.channels.base] [0x5340:1:0x1000]: 'async_initialize' stage succeeded
2022-10-18 14:36:12.402 DEBUG (MainThread) [homeassistant.components.zha.core.channels.base] [0x5340:1:0x0019]: 'async_initialize' stage succeeded
2022-10-18 14:36:12.403 DEBUG (MainThread) [homeassistant.components.zha.core.device] [0x5340](TRADFRIbulbE27WSglobeopal1055lm): power source: Mains
2022-10-18 14:36:12.404 DEBUG (MainThread) [homeassistant.components.zha.core.device] [0x5340](TRADFRIbulbE27WSglobeopal1055lm): completed initialization

@Adminiuga
Copy link
Contributor

There's no homeassistant.core module logging present. Can tell the status of the device, other than zha failed to read that device.

Is the log from a HACore restart?

@steffen890
Copy link
Author

I have enabled homeassistant.core debug logging and restarted.
Right from the start the bulb is considered as offline.
Now I'll have to wait for the next occurence to collect the logs then.

@dmulcahey
Copy link
Contributor

What is your logging configuration?

@steffen890
Copy link
Author

steffen890 commented Oct 18, 2022 •
edited
Loading

Now it is:

logger:
  default: info
  logs:
    homeassistant.core: debug
    homeassistant.components.zha: debug
    bellows.zigbee.application: debug
    bellows.ezsp: debug
    zigpy: debug
    zigpy_deconz.zigbee.application: debug
    zigpy_deconz.api: debug
    zigpy_xbee.zigbee.application: debug
    zigpy_xbee.api: debug
    zigpy_zigate: debug
    zigpy_znp: debug
    zhaquirks: debug

Correct?

By the way: The Zigbee setting "consider device as unavailable after ..." is set to 60 seconds. Maybe this is causing a timing issue with other components..

@steffen890
Copy link
Author

Here is more. "Lampe Bad" changed from unavailable to on at 03:16:14.

2022-10-19 03:16:09.359 DEBUG (MainThread) [zigpy_znp.zigbee.application] Request failed (Unsuccessful request status code: <Status.MAC_NO_ACK: 233>), retry attempt 1 of 5
2022-10-19 03:16:09.487 DEBUG (MainThread) [homeassistant.components.zha.core.channels.base] [0x5340:1:0x0008]: initializing channel: from_cache: False
2022-10-19 03:16:09.488 DEBUG (MainThread) [homeassistant.components.zha.core.channels.base] [0x5340:1:0x0008]: initializing cached channel attributes: ['on_off_transition_time', 'on_level', 'on_transition_time', 'off_transition_time', 'default_move_rate', 'start_up_current_level']
2022-10-19 03:16:09.489 DEBUG (MainThread) [homeassistant.components.zha.core.channels.base] [0x5340:1:0x0008]: Reading attributes in chunks: ['on_off_transition_time', 'on_level', 'on_transition_time', 'off_transition_time', 'default_move_rate']
2022-10-19 03:16:09.490 DEBUG (MainThread) [homeassistant.components.zha.core.channels.base] [0x5340:1:0x0008]: Reading attributes in chunks: ['start_up_current_level']
2022-10-19 03:16:09.490 DEBUG (MainThread) [homeassistant.components.zha.core.channels.base] [0x5340:1:0x0008]: initializing uncached channel attributes: ['current_level'] - from cache[False]
2022-10-19 03:16:09.491 DEBUG (MainThread) [homeassistant.components.zha.core.channels.base] [0x5340:1:0x0008]: Reading attributes in chunks: ['current_level']
2022-10-19 03:16:09.496 DEBUG (MainThread) [zigpy.zcl] [0x5340:1:0x0008] Sending request header: ZCLHeader(frame_control=FrameControl(frame_type=<FrameType.GLOBAL_COMMAND: 0>, is_manufacturer_specific=False, direction=<Direction.Server_to_Client: 0>, disable_default_response=0, reserved=0, *is_cluster=False, *is_general=True, *is_reply=False), tsn=70, command_id=<GeneralCommand.Read_Attributes: 0>, *direction=<Direction.Server_to_Client: 0>, *is_reply=False)
2022-10-19 03:16:09.499 DEBUG (MainThread) [zigpy.zcl] [0x5340:1:0x0008] Sending request: Read_Attributes(attribute_ids=[0])
2022-10-19 03:16:09.501 DEBUG (MainThread) [zigpy_znp.zigbee.application] Sending packet ZigbeePacket(src=AddrModeAddress(addr_mode=<AddrMode.NWK: 2>, address=0x0000), src_ep=1, dst=AddrModeAddress(addr_mode=<AddrMode.NWK: 2>, address=0x5340), dst_ep=1, source_route=None, extended_timeout=False, tsn=70, profile_id=260, cluster_id=8, data=Serialized[b'\x00F\x00\x00\x00'], tx_options=<TransmitOptions.ACK: 1>, radius=0, non_member_radius=0, lqi=None, rssi=None)
2022-10-19 03:16:09.504 DEBUG (MainThread) [zigpy_znp.api] Sending request: AF.DataRequestExt.Req(DstAddrModeAddress=AddrModeAddress(mode=<AddrMode.NWK: 2>, address=0x5340), DstEndpoint=1, DstPanId=0x0000, SrcEndpoint=1, ClusterId=8, TSN=70, Options=<TransmitOptions.SUPPRESS_ROUTE_DISC_NETWORK|ACK_REQUEST: 48>, Radius=0, Data=b'\x00\x46\x00\x00\x00')
2022-10-19 03:16:09.524 DEBUG (MainThread) [zigpy_znp.api] Received command: AF.DataRequestExt.Rsp(Status=<Status.SUCCESS: 0>)
2022-10-19 03:16:09.592 DEBUG (MainThread) [zigpy_znp.api] Received command: AF.DataConfirm.Callback(Status=<Status.MAC_NO_ACK: 233>, Endpoint=1, TSN=70)
2022-10-19 03:16:09.597 DEBUG (MainThread) [zigpy_znp.zigbee.application] Request failed (Unsuccessful request status code: <Status.MAC_NO_ACK: 233>), retry attempt 1 of 5
2022-10-19 03:16:10.351 DEBUG (MainThread) [zigpy_znp.api] Sending request: AF.DataRequestExt.Req(DstAddrModeAddress=AddrModeAddress(mode=<AddrMode.NWK: 2>, address=0x5340), DstEndpoint=1, DstPanId=0x0000, SrcEndpoint=1, ClusterId=6, TSN=68, Options=<TransmitOptions.SUPPRESS_ROUTE_DISC_NETWORK|ACK_REQUEST: 48>, Radius=0, Data=b'\x00\x44\x00\x00\x00')
2022-10-19 03:16:10.374 DEBUG (MainThread) [zigpy_znp.api] Received command: AF.DataRequestExt.Rsp(Status=<Status.SUCCESS: 0>)
2022-10-19 03:16:10.446 DEBUG (MainThread) [zigpy_znp.api] Received command: AF.DataConfirm.Callback(Status=<Status.MAC_NO_ACK: 233>, Endpoint=1, TSN=68)
2022-10-19 03:16:10.452 DEBUG (MainThread) [zigpy_znp.zigbee.application] Request failed (Unsuccessful request status code: <Status.MAC_NO_ACK: 233>), retry attempt 2 of 5
2022-10-19 03:16:10.866 DEBUG (MainThread) [zigpy_znp.api] Sending request: AF.DataRequestExt.Req(DstAddrModeAddress=AddrModeAddress(mode=<AddrMode.NWK: 2>, address=0x5340), DstEndpoint=1, DstPanId=0x0000, SrcEndpoint=1, ClusterId=768, TSN=69, Options=<TransmitOptions.SUPPRESS_ROUTE_DISC_NETWORK|ACK_REQUEST: 48>, Radius=0, Data=b'\x00\x45\x00\x08\x00\x02\x40\x03\x00\x04\x00\x00\x00')
2022-10-19 03:16:10.889 DEBUG (MainThread) [zigpy_znp.api] Received command: AF.DataRequestExt.Rsp(Status=<Status.SUCCESS: 0>)
2022-10-19 03:16:10.957 DEBUG (MainThread) [zigpy_znp.api] Sending request: AF.DataRequestSrcRtg.Req(DstAddr=0x5340, DstEndpoint=1, SrcEndpoint=1, ClusterId=6, TSN=68, Options=<TransmitOptions.SUPPRESS_ROUTE_DISC_NETWORK|ACK_REQUEST: 48>, Radius=0, SourceRoute=[], Data=b'\x00\x44\x00\x00\x00')
2022-10-19 03:16:10.967 DEBUG (MainThread) [zigpy_znp.api] Received command: AF.DataConfirm.Callback(Status=<Status.MAC_NO_ACK: 233>, Endpoint=1, TSN=69)
2022-10-19 03:16:10.970 DEBUG (MainThread) [zigpy_znp.zigbee.application] Request failed (Unsuccessful request status code: <Status.MAC_NO_ACK: 233>), retry attempt 2 of 5
2022-10-19 03:16:10.978 DEBUG (MainThread) [zigpy_znp.api] Received command: AF.DataRequestSrcRtg.Rsp(Status=<Status.SUCCESS: 0>)
2022-10-19 03:16:11.050 DEBUG (MainThread) [zigpy_znp.api] Received command: AF.DataConfirm.Callback(Status=<Status.MAC_NO_ACK: 233>, Endpoint=1, TSN=68)
2022-10-19 03:16:11.057 DEBUG (MainThread) [zigpy_znp.api] Sending request: ZDO.ExtRouteDisc.Req(Dst=0x5340, Options=<RouteDiscoveryOptions.UNICAST: 0>, Radius=30)
2022-10-19 03:16:11.066 DEBUG (MainThread) [zigpy_znp.api] Received command: ZDO.ExtRouteDisc.Rsp(Status=<Status.SUCCESS: 0>)
2022-10-19 03:16:11.102 DEBUG (MainThread) [zigpy_znp.api] Sending request: AF.DataRequestExt.Req(DstAddrModeAddress=AddrModeAddress(mode=<AddrMode.NWK: 2>, address=0x5340), DstEndpoint=1, DstPanId=0x0000, SrcEndpoint=1, ClusterId=8, TSN=70, Options=<TransmitOptions.SUPPRESS_ROUTE_DISC_NETWORK|ACK_REQUEST: 48>, Radius=0, Data=b'\x00\x46\x00\x00\x00')
2022-10-19 03:16:11.125 DEBUG (MainThread) [zigpy_znp.api] Received command: AF.DataRequestExt.Rsp(Status=<Status.SUCCESS: 0>)
2022-10-19 03:16:11.195 DEBUG (MainThread) [zigpy_znp.api] Received command: AF.DataConfirm.Callback(Status=<Status.MAC_NO_ACK: 233>, Endpoint=1, TSN=70)
2022-10-19 03:16:11.200 DEBUG (MainThread) [zigpy_znp.zigbee.application] Request failed (Unsuccessful request status code: <Status.MAC_NO_ACK: 233>), retry attempt 2 of 5
2022-10-19 03:16:11.476 DEBUG (MainThread) [zigpy_znp.api] Sending request: AF.DataRequestSrcRtg.Req(DstAddr=0x5340, DstEndpoint=1, SrcEndpoint=1, ClusterId=768, TSN=69, Options=<TransmitOptions.SUPPRESS_ROUTE_DISC_NETWORK|ACK_REQUEST: 48>, Radius=0, SourceRoute=[], Data=b'\x00\x45\x00\x08\x00\x02\x40\x03\x00\x04\x00\x00\x00')
2022-10-19 03:16:11.498 DEBUG (MainThread) [zigpy_znp.api] Received command: AF.DataRequestSrcRtg.Rsp(Status=<Status.SUCCESS: 0>)
2022-10-19 03:16:11.573 DEBUG (MainThread) [zigpy_znp.api] Received command: AF.DataConfirm.Callback(Status=<Status.MAC_NO_ACK: 233>, Endpoint=1, TSN=69)
2022-10-19 03:16:11.706 DEBUG (MainThread) [zigpy_znp.api] Sending request: AF.DataRequestSrcRtg.Req(DstAddr=0x5340, DstEndpoint=1, SrcEndpoint=1, ClusterId=8, TSN=70, Options=<TransmitOptions.SUPPRESS_ROUTE_DISC_NETWORK|ACK_REQUEST: 48>, Radius=0, SourceRoute=[], Data=b'\x00\x46\x00\x00\x00')
2022-10-19 03:16:11.727 DEBUG (MainThread) [zigpy_znp.api] Received command: AF.DataRequestSrcRtg.Rsp(Status=<Status.SUCCESS: 0>)
2022-10-19 03:16:11.800 DEBUG (MainThread) [zigpy_znp.api] Received command: AF.DataConfirm.Callback(Status=<Status.MAC_NO_ACK: 233>, Endpoint=1, TSN=70)
2022-10-19 03:16:12.370 DEBUG (MainThread) [zigpy_znp.zigbee.application] Request failed (Unsuccessful request status code: <Status.MAC_NO_ACK: 233>), retry attempt 3 of 5
2022-10-19 03:16:12.371 DEBUG (MainThread) [zigpy_znp.zigbee.application] Request failed (Unsuccessful request status code: <Status.MAC_NO_ACK: 233>), retry attempt 3 of 5
2022-10-19 03:16:12.372 DEBUG (MainThread) [zigpy_znp.zigbee.application] Request failed (Unsuccessful request status code: <Status.MAC_NO_ACK: 233>), retry attempt 3 of 5
2022-10-19 03:16:12.875 DEBUG (MainThread) [zigpy_znp.api] Sending request: AF.DataRequestExt.Req(DstAddrModeAddress=AddrModeAddress(mode=<AddrMode.NWK: 2>, address=0x5340), DstEndpoint=1, DstPanId=0x0000, SrcEndpoint=1, ClusterId=6, TSN=68, Options=<TransmitOptions.SUPPRESS_ROUTE_DISC_NETWORK|ACK_REQUEST: 48>, Radius=0, Data=b'\x00\x44\x00\x00\x00')
2022-10-19 03:16:12.901 DEBUG (MainThread) [zigpy_znp.api] Received command: AF.DataRequestExt.Rsp(Status=<Status.SUCCESS: 0>)
2022-10-19 03:16:12.905 DEBUG (MainThread) [zigpy_znp.api] Sending request: AF.DataRequestExt.Req(DstAddrModeAddress=AddrModeAddress(mode=<AddrMode.NWK: 2>, address=0x5340), DstEndpoint=1, DstPanId=0x0000, SrcEndpoint=1, ClusterId=768, TSN=69, Options=<TransmitOptions.SUPPRESS_ROUTE_DISC_NETWORK|ACK_REQUEST: 48>, Radius=0, Data=b'\x00\x45\x00\x08\x00\x02\x40\x03\x00\x04\x00\x00\x00')
2022-10-19 03:16:12.937 DEBUG (MainThread) [zigpy_znp.api] Received command: AF.DataRequestExt.Rsp(Status=<Status.SUCCESS: 0>)
2022-10-19 03:16:12.940 DEBUG (MainThread) [zigpy_znp.api] Sending request: AF.DataRequestExt.Req(DstAddrModeAddress=AddrModeAddress(mode=<AddrMode.NWK: 2>, address=0x5340), DstEndpoint=1, DstPanId=0x0000, SrcEndpoint=1, ClusterId=8, TSN=70, Options=<TransmitOptions.SUPPRESS_ROUTE_DISC_NETWORK|ACK_REQUEST: 48>, Radius=0, Data=b'\x00\x46\x00\x00\x00')
2022-10-19 03:16:12.963 DEBUG (MainThread) [zigpy_znp.api] Received command: AF.DataRequestExt.Rsp(Status=<Status.SUCCESS: 0>)
2022-10-19 03:16:12.982 DEBUG (MainThread) [zigpy_znp.api] Received command: AF.DataConfirm.Callback(Status=<Status.MAC_NO_ACK: 233>, Endpoint=1, TSN=68)
2022-10-19 03:16:12.987 DEBUG (MainThread) [zigpy_znp.zigbee.application] Request failed (Unsuccessful request status code: <Status.MAC_NO_ACK: 233>), retry attempt 4 of 5
2022-10-19 03:16:13.062 DEBUG (MainThread) [zigpy_znp.api] Received command: AF.DataConfirm.Callback(Status=<Status.MAC_NO_ACK: 233>, Endpoint=1, TSN=69)
2022-10-19 03:16:13.067 DEBUG (MainThread) [zigpy_znp.zigbee.application] Request failed (Unsuccessful request status code: <Status.MAC_NO_ACK: 233>), retry attempt 4 of 5
2022-10-19 03:16:13.078 DEBUG (MainThread) [zigpy_znp.api] Received command: AF.DataConfirm.Callback(Status=<Status.MAC_NO_ACK: 233>, Endpoint=1, TSN=70)
2022-10-19 03:16:13.080 DEBUG (MainThread) [zigpy_znp.zigbee.application] Request failed (Unsuccessful request status code: <Status.MAC_NO_ACK: 233>), retry attempt 4 of 5
2022-10-19 03:16:13.493 DEBUG (MainThread) [zigpy_znp.api] Sending request: AF.DataRequestExt.Req(DstAddrModeAddress=AddrModeAddress(mode=<AddrMode.IEEE: 3>, address=04:cd:15:ff:fe:8c:ae:a9), DstEndpoint=1, DstPanId=0x0000, SrcEndpoint=1, ClusterId=6, TSN=68, Options=<TransmitOptions.SUPPRESS_ROUTE_DISC_NETWORK|ACK_REQUEST: 48>, Radius=0, Data=b'\x00\x44\x00\x00\x00')
2022-10-19 03:16:13.515 DEBUG (MainThread) [zigpy_znp.api] Received command: AF.DataRequestExt.Rsp(Status=<Status.SUCCESS: 0>)
2022-10-19 03:16:13.573 DEBUG (MainThread) [zigpy_znp.api] Sending request: AF.DataRequestExt.Req(DstAddrModeAddress=AddrModeAddress(mode=<AddrMode.IEEE: 3>, address=04:cd:15:ff:fe:8c:ae:a9), DstEndpoint=1, DstPanId=0x0000, SrcEndpoint=1, ClusterId=768, TSN=69, Options=<TransmitOptions.SUPPRESS_ROUTE_DISC_NETWORK|ACK_REQUEST: 48>, Radius=0, Data=b'\x00\x45\x00\x08\x00\x02\x40\x03\x00\x04\x00\x00\x00')
2022-10-19 03:16:13.586 DEBUG (MainThread) [zigpy_znp.api] Received command: AF.DataConfirm.Callback(Status=<Status.MAC_NO_ACK: 233>, Endpoint=1, TSN=68)
2022-10-19 03:16:13.590 DEBUG (MainThread) [zigpy_znp.zigbee.application] Request failed (Unsuccessful request status code: <Status.MAC_NO_ACK: 233>), retry attempt 5 of 5
2022-10-19 03:16:13.596 DEBUG (MainThread) [zigpy_znp.api] Received command: AF.DataRequestExt.Rsp(Status=<Status.SUCCESS: 0>)
2022-10-19 03:16:13.599 DEBUG (MainThread) [zigpy_znp.api] Sending request: AF.DataRequestExt.Req(DstAddrModeAddress=AddrModeAddress(mode=<AddrMode.IEEE: 3>, address=04:cd:15:ff:fe:8c:ae:a9), DstEndpoint=1, DstPanId=0x0000, SrcEndpoint=1, ClusterId=8, TSN=70, Options=<TransmitOptions.SUPPRESS_ROUTE_DISC_NETWORK|ACK_REQUEST: 48>, Radius=0, Data=b'\x00\x46\x00\x00\x00')
2022-10-19 03:16:13.628 DEBUG (MainThread) [zigpy_znp.api] Received command: AF.DataRequestExt.Rsp(Status=<Status.SUCCESS: 0>)
2022-10-19 03:16:13.692 DEBUG (MainThread) [zigpy_znp.api] Received command: AF.DataConfirm.Callback(Status=<Status.MAC_NO_ACK: 233>, Endpoint=1, TSN=69)
2022-10-19 03:16:13.697 DEBUG (MainThread) [zigpy_znp.zigbee.application] Request failed (Unsuccessful request status code: <Status.MAC_NO_ACK: 233>), retry attempt 5 of 5
2022-10-19 03:16:13.708 DEBUG (MainThread) [zigpy_znp.api] Received command: AF.DataConfirm.Callback(Status=<Status.MAC_NO_ACK: 233>, Endpoint=1, TSN=70)
2022-10-19 03:16:13.713 DEBUG (MainThread) [zigpy_znp.zigbee.application] Request failed (Unsuccessful request status code: <Status.MAC_NO_ACK: 233>), retry attempt 5 of 5
2022-10-19 03:16:14.093 DEBUG (MainThread) [homeassistant.components.zha.core.channels.base] [0x5340:1:0x0006]: failed to get attributes '['on_off']' on 'on_off' cluster: Request failed after 5 attempts: <Status.MAC_NO_ACK: 233>
2022-10-19 03:16:14.094 WARNING (MainThread) [homeassistant.components.zha.core.channels.base] [0x5340:1:0x0006]: async_initialize: all attempts have failed: [DeliveryError('Request failed after 5 attempts: <Status.MAC_NO_ACK: 233>'), DeliveryError('Request failed after 5 attempts: <Status.MAC_NO_ACK: 233>'), DeliveryError('Request failed after 5 attempts: <Status.MAC_NO_ACK: 233>'), DeliveryError('Request failed after 5 attempts: <Status.MAC_NO_ACK: 233>')]
2022-10-19 03:16:14.173 DEBUG (MainThread) [homeassistant.core] Bus:Handling <Event state_changed[L]: entity_id=binary_sensor.internet, old_state=<state binary_sensor.internet=on; round_trip_time_avg=14.829, round_trip_time_max=14.949, round_trip_time_mdev=, round_trip_time_min=14.699, device_class=connectivity, friendly_name=Internet @ 2022-10-18T19:10:59.329086+02:00>, new_state=<state binary_sensor.internet=on; round_trip_time_avg=14.653, round_trip_time_max=15.261, round_trip_time_mdev=, round_trip_time_min=14.164, device_class=connectivity, friendly_name=Internet @ 2022-10-18T19:10:59.329086+02:00>>
2022-10-19 03:16:14.199 DEBUG (MainThread) [homeassistant.components.zha.core.channels.base] [0x5340:1:0x0300]: failed to get attributes '['color_mode', 'color_loop_active', 'current_x', 'current_y', 'current_hue']' on 'light_color' cluster: Request failed after 5 attempts: <Status.MAC_NO_ACK: 233>
2022-10-19 03:16:14.200 WARNING (MainThread) [homeassistant.components.zha.core.channels.base] [0x5340:1:0x0300]: async_initialize: all attempts have failed: [DeliveryError('Request failed after 5 attempts: <Status.MAC_NO_ACK: 233>'), DeliveryError('Request failed after 5 attempts: <Status.MAC_NO_ACK: 233>'), DeliveryError('Request failed after 5 attempts: <Status.MAC_NO_ACK: 233>'), DeliveryError('Request failed after 5 attempts: <Status.MAC_NO_ACK: 233>')]
2022-10-19 03:16:14.214 DEBUG (MainThread) [homeassistant.components.zha.core.channels.base] [0x5340:1:0x0008]: failed to get attributes '['current_level']' on 'level' cluster: Request failed after 5 attempts: <Status.MAC_NO_ACK: 233>
2022-10-19 03:16:14.215 WARNING (MainThread) [homeassistant.components.zha.core.channels.base] [0x5340:1:0x0008]: async_initialize: all attempts have failed: [DeliveryError('Request failed after 5 attempts: <Status.MAC_NO_ACK: 233>'), DeliveryError('Request failed after 5 attempts: <Status.MAC_NO_ACK: 233>'), DeliveryError('Request failed after 5 attempts: <Status.MAC_NO_ACK: 233>'), DeliveryError('Request failed after 5 attempts: <Status.MAC_NO_ACK: 233>')]
2022-10-19 03:16:14.222 DEBUG (MainThread) [homeassistant.components.zha.core.channels.base] [0x5340:1:0x0006]: 'async_initialize' stage succeeded
2022-10-19 03:16:14.223 DEBUG (MainThread) [homeassistant.components.zha.core.channels.base] [0x5340:1:0x0300]: 'async_initialize' stage succeeded
2022-10-19 03:16:14.223 DEBUG (MainThread) [homeassistant.components.zha.core.channels.base] [0x5340:1:0x0008]: 'async_initialize' stage succeeded
2022-10-19 03:16:14.223 DEBUG (MainThread) [homeassistant.components.zha.core.channels.base] [0x5340:1:0x0003]: 'async_initialize' stage succeeded
2022-10-19 03:16:14.224 DEBUG (MainThread) [homeassistant.components.zha.core.channels.base] [0x5340:1:0x0000]: 'async_initialize' stage succeeded
2022-10-19 03:16:14.224 DEBUG (MainThread) [homeassistant.components.zha.core.channels.base] [0x5340:1:0x1000]: 'async_initialize' stage succeeded
2022-10-19 03:16:14.224 DEBUG (MainThread) [homeassistant.components.zha.core.channels.base] [0x5340:1:0x0019]: 'async_initialize' stage succeeded
2022-10-19 03:16:14.225 DEBUG (MainThread) [homeassistant.components.zha.core.device] [0x5340](TRADFRIbulbE27WSglobeopal1055lm): power source: Mains
2022-10-19 03:16:14.226 DEBUG (MainThread) [homeassistant.components.zha.core.device] [0x5340](TRADFRIbulbE27WSglobeopal1055lm): completed initialization
2022-10-19 03:16:14.227 DEBUG (MainThread) [homeassistant.core] Bus:Handling <Event state_changed[L]: entity_id=button.lampe_bad_a9ae8cfe_identify, old_state=<state button.lampe_bad_a9ae8cfe_identify=unavailable; device_class=update, friendly_name=Lampe Bad a9ae8cfe identify @ 2022-10-18T23:16:50.965379+02:00>, new_state=<state button.lampe_bad_a9ae8cfe_identify=unknown; device_class=update, friendly_name=Lampe Bad a9ae8cfe identify @ 2022-10-19T03:16:14.226741+02:00>>
2022-10-19 03:16:14.229 DEBUG (MainThread) [homeassistant.core] Bus:Handling <Event state_changed[L]: entity_id=light.lampe_bad_a9ae8cfe_level_light_color_on_off, old_state=<state light.lampe_bad_a9ae8cfe_level_light_color_on_off=unavailable; min_mireds=250, max_mireds=454, supported_color_modes=[<ColorMode.COLOR_TEMP: 'color_temp'>], friendly_name=Bad, supported_features=40 @ 2022-10-18T23:16:50.972253+02:00>, new_state=<state light.lampe_bad_a9ae8cfe_level_light_color_on_off=on; min_mireds=250, max_mireds=454, supported_color_modes=[<ColorMode.COLOR_TEMP: 'color_temp'>], color_mode=color_temp, brightness=254, color_temp=260, hs_color=(26.895, 37.733), rgb_color=(255, 201, 158), xy_color=(0.431, 0.367), off_with_transition=False, off_brightness=None, friendly_name=Bad, supported_features=40 @ 2022-10-19T03:16:14.228836+02:00>>
2022-10-19 03:16:14.233 DEBUG (MainThread) [homeassistant.core] Bus:Handling <Event state_changed[L]: entity_id=number.lampe_bad_a9ae8cfe_level_on_off_transition_time, old_state=<state number.lampe_bad_a9ae8cfe_level_on_off_transition_time=unavailable; min=0, max=65535, step=1.0, mode=auto, friendly_name=Lampe Bad a9ae8cfe level on_off_transition_time @ 2022-10-18T23:16:50.974821+02:00>, new_state=<state number.lampe_bad_a9ae8cfe_level_on_off_transition_time=5; min=0, max=65535, step=1.0, mode=auto, friendly_name=Lampe Bad a9ae8cfe level on_off_transition_time @ 2022-10-19T03:16:14.233565+02:00>>
2022-10-19 03:16:14.235 DEBUG (MainThread) [homeassistant.core] Bus:Handling <Event state_changed[L]: entity_id=number.lampe_bad_a9ae8cfe_level_on_level, old_state=<state number.lampe_bad_a9ae8cfe_level_on_level=unavailable; min=0, max=255, step=1.0, mode=auto, friendly_name=Lampe Bad a9ae8cfe level on_level @ 2022-10-18T23:16:50.976448+02:00>, new_state=<state number.lampe_bad_a9ae8cfe_level_on_level=255; min=0, max=255, step=1.0, mode=auto, friendly_name=Lampe Bad a9ae8cfe level on_level @ 2022-10-19T03:16:14.235315+02:00>>
2022-10-19 03:16:14.237 DEBUG (MainThread) [homeassistant.core] Bus:Handling <Event state_changed[L]: entity_id=number.lampe_bad_a9ae8cfe_level_start_up_current_level, old_state=<state number.lampe_bad_a9ae8cfe_level_start_up_current_level=unavailable; min=0, max=255, step=1.0, mode=auto, friendly_name=Lampe Bad a9ae8cfe level start_up_current_level @ 2022-10-18T23:16:50.980315+02:00>, new_state=<state number.lampe_bad_a9ae8cfe_level_start_up_current_level=255; min=0, max=255, step=1.0, mode=auto, friendly_name=Lampe Bad a9ae8cfe level start_up_current_level @ 2022-10-19T03:16:14.236793+02:00>>
2022-10-19 03:16:14.240 DEBUG (MainThread) [homeassistant.core] Bus:Handling <Event state_changed[L]: entity_id=select.lampe_bad_a9ae8cfe_on_off_startuponoff, old_state=<state select.lampe_bad_a9ae8cfe_on_off_startuponoff=unavailable; options=['Off', 'On', 'Toggle', 'PreviousValue'], friendly_name=Lampe Bad a9ae8cfe on_off StartUpOnOff @ 2022-10-18T23:16:50.981949+02:00>, new_state=<state select.lampe_bad_a9ae8cfe_on_off_startuponoff=On; options=['Off', 'On', 'Toggle', 'PreviousValue'], friendly_name=Lampe Bad a9ae8cfe on_off StartUpOnOff @ 2022-10-19T03:16:14.238245+02:00>>

@dmulcahey
Copy link
Contributor

I need unfiltered logs. Can you share the entire HA log file ?

@TheJulianJES
Copy link
Member

Just for completeness — this seems to be the same issue as:

@steffen890
Copy link
Author

I need unfiltered logs. Can you share the entire HA log file ?

The logfile is currently bigger than 50 MB and honestly I'm a bit concerned that sensitive information (MAC addresses, credentials,...) could be leaked by some of the integrations.

Do you need logs from a larger timeframe? Are the log settings as seen in my earlier post sufficient?

@Adminiuga
Copy link
Contributor

Send link to logs directly to devs then.

From the earlier logs, how long after restart was the 03:16:09.359 time?

Looks like the device changes the state right after all async_initialize attempts fail.

@steffen890 you are saying the device goes online every 4 hours (while physically offline) do you see attempts to do "async_initialize" for that device every 4 hours?

Question: does "device" availability takes precedence over entity's availability? In other words, when the device is marked unavailable, but the entity still tries to "initialize" in the background, fails to initialize but returns the "cashed" state. Would it mess up the "state" machine in the core?

This was referenced Oct 23, 2022
Closed
Merged
@steffen890
Copy link
Author

@steffen890 you are saying the device goes online every 4 hours (while physically offline) do you see attempts to do "async_initialize" for that device every 4 hours?

Yes, every 4 hours:

2022-10-20 19:27:10.073 DEBUG (MainThread) [homeassistant.components.zha.core.device] [0x5340](TRADFRIbulbE27WSglobeopal1055lm): started initialization
2022-10-20 19:27:10.074 DEBUG (MainThread) [homeassistant.components.zha.core.channels.base] [0x5340:ZDO](TRADFRIbulbE27WSglobeopal1055lm): 'async_initialize' stage succeeded
...
2022-10-20 23:28:39.981 DEBUG (MainThread) [homeassistant.components.zha.core.device] [0x5340](TRADFRIbulbE27WSglobeopal1055lm): started initialization
2022-10-20 23:28:39.982 DEBUG (MainThread) [homeassistant.components.zha.core.channels.base] [0x5340:ZDO](TRADFRIbulbE27WSglobeopal1055lm): 'async_initialize' stage succeeded
...
2022-10-21 03:31:20.333 DEBUG (MainThread) [homeassistant.components.zha.core.device] [0x5340](TRADFRIbulbE27WSglobeopal1055lm): started initialization
2022-10-21 03:31:20.333 DEBUG (MainThread) [homeassistant.components.zha.core.channels.base] [0x5340:ZDO](TRADFRIbulbE27WSglobeopal1055lm): 'async_initialize' stage succeeded

@dmulcahey dmulcahey mentioned this issue Oct 26, 2022
Merged
19 tasks
@github-actions github-actions bot locked and limited conversation to collaborators Nov 25, 2022
Sign up for free to subscribe to this conversation on GitHub. Already have an account? Sign in.
Assignees

@dmulcahey dmulcahey

@Adminiuga Adminiuga

@puddly puddly

Labels
integration: zha
Projects
None yet
Milestone
No milestone
6 participants
@dmulcahey @Adminiuga @TheJulianJES @Quentame @puddly @steffen890