Device(s) become unresponsive and unavailable - ZHA

JHurk commented 1 year ago

The problem

Similar to some of the other current bugs that are reported but I can not find the exact same bug. Therefor made this new bug, just to be sure. If double then sorry for this and feel free to close this one.

Have ZHA running with a Skyconnect stick and migrated from Z2M a few months ago. Every thing worked great until a few days ago (say 5-6 days ago), at least that was when I found out one of the lights I have in my 'night time automation' stopped working. At that moment I tried finding a solution to the problem but nothing helped.

The problem; Some of my Zigbee devices (e.g. Sonoff ZBMini-01) became unresponsive and unavailable so I could not control them anymore and automation stopped working for them. I tried it manually and the switch button in HA is responsive, but nothing happens with the light. The button in HA switches back to 'off' and becomes unavailable. After that I can not control the button at all in HA. When I walk to the physical switch in the wall and use that, the light does turn on or off. The status light of the ZBMini-01 is flashing green which indicates that it is not connected to the network. When I look in the visualization of ZHA the ZBMini-01 is there. And the ZBMini-01 is in the middle of various other zigbee devices (all routers connected to mains). The other devices within that area are all responsive.

When I remove and re-add the device the same problem happens almost instantly. I have tried setting the channel to a different channel. I have tried to add a new device (Sonoff ZBMini-01) and even with the new, out of the box device, this happens within a few minutes/moments when I add it to the network.

This setup has been working flawless the last months so I am counting towards it being a bug from one of the latest releases. I added the device diagnostics and the debug loggin of the last time a tried adding this device until it became unavailable (within a few seconds after joining).

What version of Home Assistant Core has the issue?

core-2023.6.3

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

zha-7f792b9c484b39e82b9979f9b77a7c48-SONOFF 01MINIZB-9c5dc8c69280bdf38bdd4148b273a255.json-3.txt

Example YAML snippet

No response

Anything in the logs that might be useful for us?

Debug logging of the periode is available if needed, please DM

Additional information

Here is the log when I try to add a new device (it adds 2 devices; the switch that is constantly dropping and a same switch which is new that I have lying around). It constantly changes from 'added to the network' to 'configuring' on both devices. And trying to add a third device (MOES smart dimmer MS-105Z) which doesn't show up at when adding devices. While I already have one of those devices as part of my network, so it should identify the device. ZHA_log adding new devices.txt

home-assistant[bot] commented 1 year ago

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!

Code owner commands

Code owners of `zha` can trigger bot actions by commenting: - `@home-assistant close` Closes the issue. - `@home-assistant rename Awesome new title` Renames the issue. - `@home-assistant reopen` Reopen the issue. - `@home-assistant unassign zha` Removes the current integration label and assignees on the issue, add the integration domain after the command.

_{^{(message by CodeOwnersMention)}}

zha documentation zha source _{^{(message by IssueLinks)}}

puddly commented 1 year ago

Debug logging of the periode is available if needed, please DM

Can you enable ZHA debug logging (https://www.home-assistant.io/integrations/zha/#debug-logging) and upload/email me the entire /config/home-assistant.log file? In the log, make sure to let ZHA run for a while and then try adding/controlling the Sonoff device.

There were no recent changes to ZHA, especially ones that would affect device availability (for only a specific device).

JHurk commented 1 year ago

Thanks for the reply. Here is the Debug log I saved from the time I was testing on the 26th of June. I have cut this so only the time frame of testing is in it (started at about 19:30h). Is this enough or do you need the complete logfile? Because that file is almost 180mb.

Regards JHurk

Op 28 jun. 2023, om 06:38 heeft puddly @.***> het volgende geschreven:

Debug logging of the periode is available if needed, please DM

Can you enable ZHA debug logging (https://www.home-assistant.io/integrations/zha/#debug-logging) and upload/email me the entire /config/home-assistant.log file? In the log, make sure to let ZHA run for a while and then try adding/controlling the Sonoff device.

There were no recent changes to ZHA, especially ones that would affect device availability (for only a specific device).

— Reply to this email directly, view it on GitHub https://github.com/home-assistant/core/issues/95288#issuecomment-1610707623, or unsubscribe https://github.com/notifications/unsubscribe-auth/AB3Y52VSGHCUI3TN54PBCTTXNOYM3ANCNFSM6AAAAAAZUQLQXQ. You are receiving this because you authored the thread.

Device 0x9acf (00:12:4b:00:24:c1:fb:24) joined the network [0x9ACF:1:0x0004] Sending request header: ZCLHeader(frame_control=FrameControl(frame_type=<FrameType.CLUSTER_COMMAND: 1>, is_manufacturer_specific=False, direction=<Direction.Server_to_Client: 0>, disable_default_response=0, reserved=0, is_cluster=True, is_general=False), tsn=122, command_id=2, direction=<Direction.Server_to_Client: 0>) [0x9ACF:1:0x0004] Sending request: get_membership(groups=[]) Device 0x9acf (00:12:4b:00:24:c1:fb:24) joined the network [0x9acf] Cancelling old group rescan [0x9ACF:1:0x0004] Sending request header: ZCLHeader(frame_control=FrameControl(frame_type=<FrameType.CLUSTER_COMMAND: 1>, is_manufacturer_specific=False, direction=<Direction.Server_to_Client: 0>, disable_default_response=0, reserved=0, is_cluster=True, is_general=False), tsn=124, command_id=2, direction=<Direction.Server_to_Client: 0>) [0x9ACF:1:0x0004] Sending request: get_membership(groups=[]) Received a packet: ZigbeePacket(src=AddrModeAddress(addr_mode=<AddrMode.NWK: 2>, address=0x9ACF), src_ep=0, dst=AddrModeAddress(addr_mode=<AddrMode.Broadcast: 15>, address=<BroadcastAddress.ALL_ROUTERS_AND_COORDINATOR: 65532>), dst_ep=0, source_route=None, extended_timeout=False, tsn=0, profile_id=0, cluster_id=19, data=Serialized[b'\x00\xcf\x9a$\xfb\xc1$\x00K\x12\x00\x8e'], tx_options=<TransmitOptions.NONE: 0>, radius=0, non_member_radius=0, lqi=68, rssi=-83) Device 0x9acf (00:12:4b:00:24:c1:fb:24) joined the network [0x9acf] Cancelling old group rescan 0x9acf: Update device availability - device available: False - new availability: True - changed: True 0x9acf: Device availability changed and device became available, reinitializing cluster handlers [0x9acf:zdo] ZDO request ZDOCmd.Device_annce: [0x9ACF, 00:12:4b:00:24:c1:fb:24, 142] [0x9ACF:1:0x0004] Sending request header: ZCLHeader(frame_control=FrameControl(frame_type=<FrameType.CLUSTER_COMMAND: 1>, is_manufacturer_specific=False, direction=<Direction.Server_to_Client: 0>, disable_default_response=0, reserved=0, is_cluster=True, is_general=False), tsn=126, command_id=2, direction=<Direction.Server_to_Client: 0>) [0x9ACF:1:0x0004] Sending request: get_membership(groups=[]) 0x9acf: started initialization 0x9acf:ZDO: 'async_initialize' stage succeeded [0x9acf:1:0x0006]: initializing cluster handler: from_cache: False [0x9acf:1:0x0006]: initializing cached cluster handler attributes: ['start_up_on_off'] [0x9acf:1:0x0006]: Reading attributes in chunks: ['start_up_on_off'] [0x9acf:1:0x0006]: initializing uncached cluster handler attributes: ['on_off'] - from cache[False] [0x9acf:1:0x0006]: Reading attributes in chunks: ['on_off'] [0x9ACF: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), tsn=128, command_id=<GeneralCommand.Read_Attributes: 0>, direction=<Direction.Server_to_Client: 0>) [0x9ACF:1:0x0006] Sending request: Read_Attributes(attribute_ids=[0]) [0x9acf:1:0x0000]: initializing cluster handler: from_cache: False [0x9acf:1:0x0000]: finished cluster handler initialization [0x9acf:1:0x0003]: initializing cluster handler: from_cache: False [0x9acf:1:0x0003]: finished cluster handler initialization [0x9acf:1:0x0019]: initializing cluster handler: from_cache: False [0x9acf:1:0x0019]: finished cluster handler initialization Received a packet: ZigbeePacket(src=AddrModeAddress(addr_mode=<AddrMode.NWK: 2>, address=0x8DAD), src_ep=1, dst=AddrModeAddress(addr_mode=<AddrMode.NWK: 2>, address=0x0000), dst_ep=1, source_route=None, extended_timeout=False, tsn=149, profile_id=260, cluster_id=2820, data=Serialized[b'\x08R\n\x05\x05!\x08\x01'], tx_options=<TransmitOptions.NONE: 0>, radius=0, non_member_radius=0, lqi=188, rssi=-53) 0x8DAD:1:0x0b04 Received ZCL frame: b'\x08R\n\x05\x05!\x08\x01' 0x8DAD:1:0x0b04 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), tsn=82, command_id=10, direction=<Direction.Client_to_Server: 1>) 0x8DAD:1:0x0b04 Decoded ZCL frame: ElectricalMeasurement:Report_Attributes(attribute_reports=[Attribute(attrid=0x0505, value=TypeValue(type=uint16_t, value=264))]) 0x8DAD:1:0x0b04 Received command 0x0A (TSN 82): Report_Attributes(attribute_reports=[Attribute(attrid=0x0505, value=TypeValue(type=uint16_t, value=264))]) 0x8DAD:1:0x0b04 Attribute report received: rms_voltage=264 0x8DAD:1:0x0b04 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), tsn=82, command_id=<GeneralCommand.Default_Response: 11>, direction=<Direction.Client_to_Server: 1>) 0x8DAD:1:0x0b04 Sending reply: Default_Response(command_id=10, status=<Status.SUCCESS: 0>) Received a packet: ZigbeePacket(src=AddrModeAddress(addr_mode=<AddrMode.NWK: 2>, address=0xE6C2), src_ep=8, dst=AddrModeAddress(addr_mode=<AddrMode.NWK: 2>, address=0x0000), dst_ep=1, source_route=None, extended_timeout=False, tsn=132, profile_id=260, cluster_id=6, data=Serialized[b'\x00\xc6\n\x00\x00 \x00'], tx_options=<TransmitOptions.NONE: 0>, radius=0, non_member_radius=0, lqi=124, rssi=-69) [0xE6C2:8:0x0006] Received ZCL frame: b'\x00\xc6\n\x00\x00 \x00' [0xE6C2:8:0x0006] Decoded ZCL frame header: ZCLHeader(frame_control=FrameControl(frame_type=<FrameType.GLOBAL_COMMAND: 0>, is_manufacturer_specific=0, direction=<Direction.Server_to_Client: 0>, disable_default_response=0, reserved=0, is_cluster=False, is_general=True), tsn=198, command_id=10, direction=<Direction.Server_to_Client: 0>) [0xE6C2:8:0x0006] Decoded ZCL frame: OnOff:Report_Attributes(attribute_reports=[Attribute(attrid=0x0000, value=TypeValue(type=uint8_t, value=0))]) [0xE6C2:8:0x0006] Received command 0x0A (TSN 198): Report_Attributes(attribute_reports=[Attribute(attrid=0x0000, value=TypeValue(type=uint8_t, value=0))]) [0xE6C2:8:0x0006] Attribute report received: on_off=0 [0xE6C2:8: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), tsn=198, command_id=<GeneralCommand.Default_Response: 11>, direction=<Direction.Client_to_Server: 1>) [0xE6C2:8:0x0006] Sending reply: Default_Response(command_id=10, status=<Status.SUCCESS: 0>) Received a packet: ZigbeePacket(src=AddrModeAddress(addr_mode=<AddrMode.NWK: 2>, address=0x9ACF), src_ep=1, dst=AddrModeAddress(addr_mode=<AddrMode.NWK: 2>, address=0x0000), dst_ep=1, source_route=None, extended_timeout=False, tsn=2, profile_id=260, cluster_id=4, data=Serialized[b'\x19|\x02\x10\x00'], tx_options=<TransmitOptions.NONE: 0>, radius=0, non_member_radius=0, lqi=96, rssi=-76) [0x9ACF:1:0x0004] Received ZCL frame: b'\x19|\x02\x10\x00' [0x9ACF:1:0x0004] 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=1, reserved=0, is_cluster=True, is_general=False), tsn=124, command_id=2, direction=<Direction.Client_to_Server: 1>) [0x9ACF:1:0x0004] Decoded ZCL frame: Groups:get_membership_response(capacity=16, groups=[]) [0x9ACF:1:0x0004] Received command 0x02 (TSN 124): get_membership_response(capacity=16, groups=[]) [0x9ACF:1:0x0004] No explicit handler for cluster command 0x02: get_membership_response(capacity=16, groups=[]) Received a packet: ZigbeePacket(src=AddrModeAddress(addr_mode=<AddrMode.NWK: 2>, address=0x9ACF), src_ep=0, dst=AddrModeAddress(addr_mode=<AddrMode.NWK: 2>, address=0x0000), dst_ep=0, source_route=None, extended_timeout=False, tsn=3, profile_id=0, cluster_id=2, data=Serialized[b'\x01\x00\x00'], tx_options=<TransmitOptions.NONE: 0>, radius=0, non_member_radius=0, lqi=104, rssi=-74) [0x9acf:zdo] ZDO request ZDOCmd.Node_Desc_req: [0x0000] [0x9acf:zdo] No handler for ZDO request:ZDOCmd.Node_Desc_req([0x0000]) Received a packet: ZigbeePacket(src=AddrModeAddress(addr_mode=<AddrMode.NWK: 2>, address=0x9ACF), src_ep=1, dst=AddrModeAddress(addr_mode=<AddrMode.NWK: 2>, address=0x0000), dst_ep=1, source_route=None, extended_timeout=False, tsn=1, profile_id=260, cluster_id=4, data=Serialized[b'\x19z\x02\x10\x00'], tx_options=<TransmitOptions.NONE: 0>, radius=0, non_member_radius=0, lqi=100, rssi=-75) [0x9ACF:1:0x0004] Received ZCL frame: b'\x19z\x02\x10\x00' [0x9ACF:1:0x0004] 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=1, reserved=0, is_cluster=True, is_general=False), tsn=122, command_id=2, direction=<Direction.Client_to_Server: 1>) [0x9ACF:1:0x0004] Decoded ZCL frame: Groups:get_membership_response(capacity=16, groups=[]) [0x9ACF:1:0x0004] Received command 0x02 (TSN 122): get_membership_response(capacity=16, groups=[]) [0x9ACF:1:0x0004] No explicit handler for cluster command 0x02: get_membership_response(capacity=16, groups=[]) Received a packet: ZigbeePacket(src=AddrModeAddress(addr_mode=<AddrMode.NWK: 2>, address=0x9ACF), src_ep=1, dst=AddrModeAddress(addr_mode=<AddrMode.NWK: 2>, address=0x0000), dst_ep=1, source_route=None, extended_timeout=False, tsn=5, profile_id=260, cluster_id=4, data=Serialized[b'\x19~\x02\x10\x00'], tx_options=<TransmitOptions.NONE: 0>, radius=0, non_member_radius=0, lqi=108, rssi=-73) [0x9ACF:1:0x0004] Received ZCL frame: b'\x19~\x02\x10\x00' [0x9ACF:1:0x0004] 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=1, reserved=0, is_cluster=True, is_general=False), tsn=126, command_id=2, direction=<Direction.Client_to_Server: 1>) [0x9ACF:1:0x0004] Decoded ZCL frame: Groups:get_membership_response(capacity=16, groups=[]) Received a packet: ZigbeePacket(src=AddrModeAddress(addr_mode=<AddrMode.NWK: 2>, address=0x43FC), src_ep=1, dst=AddrModeAddress(addr_mode=<AddrMode.NWK: 2>, address=0x0000), dst_ep=1, source_route=None, extended_timeout=False, tsn=154, profile_id=260, cluster_id=2820, data=Serialized[b'\x08h\n\x05\x05!\x16\x00'], tx_options=<TransmitOptions.NONE: 0>, radius=0, non_member_radius=0, lqi=116, rssi=-71) 0x43FC:1:0x0b04 Received ZCL frame: b'\x08h\n\x05\x05!\x16\x00' 0x43FC:1:0x0b04 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), tsn=104, command_id=10, direction=<Direction.Client_to_Server: 1>) 0x43FC:1:0x0b04 Decoded ZCL frame: ElectricalMeasurement:Report_Attributes(attribute_reports=[Attribute(attrid=0x0505, value=TypeValue(type=uint16_t, value=22))]) 0x43FC:1:0x0b04 Received command 0x0A (TSN 104): Report_Attributes(attribute_reports=[Attribute(attrid=0x0505, value=TypeValue(type=uint16_t, value=22))]) 0x43FC:1:0x0b04 Attribute report received: rms_voltage=22 0x43FC:1:0x0b04 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), tsn=104, command_id=<GeneralCommand.Default_Response: 11>, direction=<Direction.Client_to_Server: 1>) 0x43FC:1:0x0b04 Sending reply: Default_Response(command_id=10, status=<Status.SUCCESS: 0>) Received a packet: ZigbeePacket(src=AddrModeAddress(addr_mode=<AddrMode.NWK: 2>, address=0x70D4), src_ep=1, dst=AddrModeAddress(addr_mode=<AddrMode.NWK: 2>, address=0x0000), dst_ep=1, source_route=None, extended_timeout=False, tsn=115, profile_id=260, cluster_id=8, data=Serialized[b'\x08>\n\x00\x00 \xfe'], tx_options=<TransmitOptions.NONE: 0>, radius=0, non_member_radius=0, lqi=136, rssi=-66) [0x70D4:1:0x0008] Received ZCL frame: b'\x08>\n\x00\x00 \xfe' [0x70D4: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), tsn=62, command_id=10, direction=<Direction.Client_to_Server: 1>) [0x70D4:1:0x0008] Decoded ZCL frame: LevelControl:Report_Attributes(attribute_reports=[Attribute(attrid=0x0000, value=TypeValue(type=uint8_t, value=254))]) [0x70D4:1:0x0008] Received command 0x0A (TSN 62): Report_Attributes(attribute_reports=[Attribute(attrid=0x0000, value=TypeValue(type=uint8_t, value=254))]) [0x70D4:1:0x0008] Attribute report received: current_level=254 [0x70D4:1:0x0008]: received attribute: 0 update with value: 254 [0x70D4: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), tsn=62, command_id=<GeneralCommand.Default_Response: 11>, direction=<Direction.Client_to_Server: 1>) [0x70D4:1:0x0008] Sending reply: Default_Response(command_id=10, status=<Status.SUCCESS: 0>) [0xDAF9](SP 120): Device seen - marking the device available and resetting counter [0xDAF9](SP 120): Update device availability - device available: True - new availability: True - changed: False 0x8110: Device seen - marking the device available and resetting counter 0x8110: Update device availability - device available: True - new availability: True - changed: False 0xE6C2: Device seen - marking the device available and resetting counter 0xE6C2: Update device availability - device available: True - new availability: True - changed: False [0x0ACD](SP 120): last_seen is 2244678.46625638 seconds ago and ping attempts have been exhausted, marking the device unavailable [0x0ACD](SP 120): Update device availability - device available: False - new availability: False - changed: False [0x9153](TRADFRI bulb E27 WW clear 250lm): Device seen - marking the device available and resetting counter [0x9153](TRADFRI bulb E27 WW clear 250lm): Update device availability - device available: True - new availability: True - changed: False [0x04EB](TRADFRI bulb E27 WW 806lm): last_seen is 232642.12163066864 seconds ago and ping attempts have been exhausted, marking the device unavailable [0x04EB](TRADFRI bulb E27 WW 806lm): Update device availability - device available: False - new availability: False - changed: False Received a packet: ZigbeePacket(src=AddrModeAddress(addr_mode=<AddrMode.NWK: 2>, address=0x8DAD), src_ep=1, dst=AddrModeAddress(addr_mode=<AddrMode.NWK: 2>, address=0x0000), dst_ep=1, source_route=None, extended_timeout=False, tsn=150, profile_id=260, cluster_id=2820, data=Serialized[b'\x08S\n\x05\x05!\n\x01'], tx_options=<TransmitOptions.NONE: 0>, radius=0, non_member_radius=0, lqi=188, rssi=-53) 0x8DAD:1:0x0b04 Received ZCL frame: b'\x08S\n\x05\x05!\n\x01' 0x8DAD:1:0x0b04 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), tsn=83, command_id=10, direction=<Direction.Client_to_Server: 1>) 0x8DAD:1:0x0b04 Decoded ZCL frame: ElectricalMeasurement:Report_Attributes(attribute_reports=[Attribute(attrid=0x0505, value=TypeValue(type=uint16_t, value=266))]) 0x8DAD:1:0x0b04 Received command 0x0A (TSN 83): Report_Attributes(attribute_reports=[Attribute(attrid=0x0505, value=TypeValue(type=uint16_t, value=266))]) 0x8DAD:1:0x0b04 Attribute report received: rms_voltage=266 0x8DAD:1:0x0b04 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), tsn=83, command_id=<GeneralCommand.Default_Response: 11>, direction=<Direction.Client_to_Server: 1>) 0x8DAD:1:0x0b04 Sending reply: Default_Response(command_id=10, status=<Status.SUCCESS: 0>) [0x9acf:1:0x0006]: failed to get attributes '['on_off']' on 'on_off' cluster: [0x9acf:1:0x0006]: async_initialize: retryable request #1 failed: . Retrying in 0.8s Received a packet: ZigbeePacket(src=AddrModeAddress(addr_mode=<AddrMode.NWK: 2>, address=0x43FC), src_ep=1, dst=AddrModeAddress(addr_mode=<AddrMode.NWK: 2>, address=0x0000), dst_ep=1, source_route=None, extended_timeout=False, tsn=155, profile_id=260, cluster_id=2820, data=Serialized[b'\x08i\n\x05\x05!\x15\x00'], tx_options=<TransmitOptions.NONE: 0>, radius=0, non_member_radius=0, lqi=120, rssi=-70) 0x43FC:1:0x0b04 Received ZCL frame: b'\x08i\n\x05\x05!\x15\x00' 0x43FC:1:0x0b04 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), tsn=105, command_id=10, direction=<Direction.Client_to_Server: 1>) 0x43FC:1:0x0b04 Decoded ZCL frame: ElectricalMeasurement:Report_Attributes(attribute_reports=[Attribute(attrid=0x0505, value=TypeValue(type=uint16_t, value=21))]) 0x43FC:1:0x0b04 Received command 0x0A (TSN 105): Report_Attributes(attribute_reports=[Attribute(attrid=0x0505, value=TypeValue(type=uint16_t, value=21))]) 0x43FC:1:0x0b04 Attribute report received: rms_voltage=21 0x43FC:1:0x0b04 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), tsn=105, command_id=<GeneralCommand.Default_Response: 11>, direction=<Direction.Client_to_Server: 1>) 0x43FC:1:0x0b04 Sending reply: Default_Response(command_id=10, status=<Status.SUCCESS: 0>) [0x9acf:1:0x0006]: initializing cluster handler: from_cache: False [0x9acf:1:0x0006]: initializing cached cluster handler attributes: ['start_up_on_off'] [0x9acf:1:0x0006]: Reading attributes in chunks: ['start_up_on_off'] [0x9acf:1:0x0006]: initializing uncached cluster handler attributes: ['on_off'] - from cache[False] [0x9acf:1:0x0006]: Reading attributes in chunks: ['on_off'] [0x9ACF: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), tsn=136, command_id=<GeneralCommand.Read_Attributes: 0>, direction=<Direction.Server_to_Client: 0>) [0x9ACF:1:0x0006] Sending request: Read_Attributes(attribute_ids=[0]) Received a packet: ZigbeePacket(src=AddrModeAddress(addr_mode=<AddrMode.NWK: 2>, address=0x9ACF), src_ep=1, dst=AddrModeAddress(addr_mode=<AddrMode.NWK: 2>, address=0x0000), dst_ep=1, source_route=None, extended_timeout=False, tsn=7, profile_id=260, cluster_id=6, data=Serialized[b'\x18\x88\x01\x00\x00\x00\x10\x00'], tx_options=<TransmitOptions.NONE: 0>, radius=0, non_member_radius=0, lqi=120, rssi=-70) [0x9ACF:1:0x0006] Received ZCL frame: b'\x18\x88\x01\x00\x00\x00\x10\x00' [0x9ACF: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=1, reserved=0, is_cluster=False, is_general=True), tsn=136, command_id=1, direction=<Direction.Client_to_Server: 1>) [0x9ACF:1: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>))]) [0x9acf:1:0x0006]: finished cluster handler initialization [0x9acf:1:0x0006]: 'async_initialize' stage succeeded [0x9acf:1:0x0000]: 'async_initialize' stage succeeded [0x9acf:1:0x0003]: 'async_initialize' stage succeeded [0x9acf:1:0x0019]: 'async_initialize' stage succeeded 0x9acf: power source: Mains 0x9acf: completed initialization 0x9acf: Device seen - marking the device available and resetting counter 0x9acf: Update device availability - device available: True - new availability: True - changed: False Received a packet: ZigbeePacket(src=AddrModeAddress(addr_mode=<AddrMode.NWK: 2>, address=0x8DAD), src_ep=1, dst=AddrModeAddress(addr_mode=<AddrMode.NWK: 2>, address=0x0000), dst_ep=1, source_route=None, extended_timeout=False, tsn=151, profile_id=260, cluster_id=2820, data=Serialized[b'\x08T\n\x05\x05!\x0f\x01'], tx_options=<TransmitOptions.NONE: 0>, radius=0, non_member_radius=0, lqi=188, rssi=-53) 0x8DAD:1:0x0b04 Received ZCL frame: b'\x08T\n\x05\x05!\x0f\x01' 0x8DAD:1:0x0b04 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), tsn=84, command_id=10, direction=<Direction.Client_to_Server: 1>) 0x8DAD:1:0x0b04 Decoded ZCL frame: ElectricalMeasurement:Report_Attributes(attribute_reports=[Attribute(attrid=0x0505, value=TypeValue(type=uint16_t, value=271))]) 0x8DAD:1:0x0b04 Received command 0x0A (TSN 84): Report_Attributes(attribute_reports=[Attribute(attrid=0x0505, value=TypeValue(type=uint16_t, value=271))]) 0x8DAD:1:0x0b04 Attribute report received: rms_voltage=271 0x8DAD:1:0x0b04 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), tsn=84, command_id=<GeneralCommand.Default_Response: 11>, direction=<Direction.Client_to_Server: 1>) 0x8DAD:1:0x0b04 Sending reply: Default_Response(command_id=10, status=<Status.SUCCESS: 0>) 0x43FC: Device seen - marking the device available and resetting counter 0x43FC: Update device availability - device available: True - new availability: True - changed: False 0x12F5: last_seen is 9911901.861353159 seconds ago and ping attempts have been exhausted, marking the device unavailable 0x12F5: Update device availability - device available: False - new availability: False - changed: False Received a packet: ZigbeePacket(src=AddrModeAddress(addr_mode=<AddrMode.NWK: 2>, address=0x8DAD), src_ep=1, dst=AddrModeAddress(addr_mode=<AddrMode.NWK: 2>, address=0x0000), dst_ep=1, source_route=None, extended_timeout=False, tsn=153, profile_id=260, cluster_id=2820, data=Serialized[b'\x08U\n\x05\x05!\x1a\x01'], tx_options=<TransmitOptions.NONE: 0>, radius=0, non_member_radius=0, lqi=188, rssi=-53) 0x8DAD:1:0x0b04 Received ZCL frame: b'\x08U\n\x05\x05!\x1a\x01' 0x8DAD:1:0x0b04 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), tsn=85, command_id=10, direction=<Direction.Client_to_Server: 1>) 0x8DAD:1:0x0b04 Decoded ZCL frame: ElectricalMeasurement:Report_Attributes(attribute_reports=[Attribute(attrid=0x0505, value=TypeValue(type=uint16_t, value=282))]) 0x8DAD:1:0x0b04 Received command 0x0A (TSN 85): Report_Attributes(attribute_reports=[Attribute(attrid=0x0505, value=TypeValue(type=uint16_t, value=282))]) 0x8DAD:1:0x0b04 Attribute report received: rms_voltage=282 0x8DAD:1:0x0b04 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), tsn=85, command_id=<GeneralCommand.Default_Response: 11>, direction=<Direction.Client_to_Server: 1>) 0x8DAD:1:0x0b04 Sending reply: Default_Response(command_id=10, status=<Status.SUCCESS: 0>) Received a packet: ZigbeePacket(src=AddrModeAddress(addr_mode=<AddrMode.NWK: 2>, address=0x8CEB), src_ep=1, dst=AddrModeAddress(addr_mode=<AddrMode.NWK: 2>, address=0x0000), dst_ep=1, source_route=None, extended_timeout=False, tsn=215, profile_id=260, cluster_id=8, data=Serialized[b'\x18.\n\x00\x00 \x14'], tx_options=<TransmitOptions.NONE: 0>, radius=0, non_member_radius=0, lqi=136, rssi=-66) [0x8CEB:1:0x0008] Received ZCL frame: b'\x18.\n\x00\x00 \x14' [0x8CEB: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=1, reserved=0, is_cluster=False, is_general=True), tsn=46, command_id=10, direction=<Direction.Client_to_Server: 1>) [0x8CEB:1:0x0008] Decoded ZCL frame: LevelControl:Report_Attributes(attribute_reports=[Attribute(attrid=0x0000, value=TypeValue(type=uint8_t, value=20))]) [0x8CEB:1:0x0008] Received command 0x0A (TSN 46): Report_Attributes(attribute_reports=[Attribute(attrid=0x0000, value=TypeValue(type=uint8_t, value=20))]) [0x8CEB:1:0x0008] Attribute report received: current_level=20 [0x8CEB:1:0x0008]: received attribute: 0 update with value: 20 [0xF922](EcoDim-Zigbee 3.0): Device seen - marking the device available and resetting counter [0xF922](EcoDim-Zigbee 3.0): Update device availability - device available: True - new availability: True - changed: False 0x4329: Device seen - marking the device available and resetting counter 0x4329: Update device availability - device available: True - new availability: True - changed: False 0xA301: Device seen - marking the device available and resetting counter 0xA301: Update device availability - device available: True - new availability: True - changed: False [0x7CF8](TRADFRI control outlet): last_seen is 9248553.45407629 seconds ago and ping attempts have been exhausted, marking the device unavailable [0x7CF8](TRADFRI control outlet): Update device availability - device available: False - new availability: False - changed: False 0xA8EB: Device seen - marking the device available and resetting counter 0xA8EB: Update device availability - device available: True - new availability: True - changed: False 0x0F81: Device seen - marking the device available and resetting counter 0x0F81: Update device availability - device available: True - new availability: True - changed: False 0x20D4: Device seen - marking the device available and resetting counter 0x20D4: Update device availability - device available: True - new availability: True - changed: False Received a packet: ZigbeePacket(src=AddrModeAddress(addr_mode=<AddrMode.NWK: 2>, address=0x8CEB), src_ep=1, dst=AddrModeAddress(addr_mode=<AddrMode.NWK: 2>, address=0x0000), dst_ep=1, source_route=None, extended_timeout=False, tsn=216, profile_id=260, cluster_id=6, data=Serialized[b'\x180\n\x00\x00\x10\x00'], tx_options=<TransmitOptions.NONE: 0>, radius=0, non_member_radius=0, lqi=132, rssi=-67) [0x8CEB:1:0x0006] Received ZCL frame: b'\x180\n\x00\x00\x10\x00' [0x8CEB: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=1, reserved=0, is_cluster=False, is_general=True), tsn=48, command_id=10, *direction=<Direction.Client_to_Server: 1>) [0x8CEB:1:0x0006] Decoded ZCL frame: OnOff:Report_Attributes(attribute_reports=[Attribute(attrid=0x0000, value=TypeValue(type=Bool, value=<Bool.false: 0>))]) [0x8CEB:1:0x0006] Received command 0x0A (TSN 48): Report_Attributes(attribute_reports=[Attribute(attrid=0x0000, value=TypeValue(type=Bool, value=<Bool.false: 0>))]) [0x8CEB:1:0x0006] Attribute report received: on_off=<Bool.false: 0>

0x43FC:1:0x0b04: Reading attributes in chunks: 'active_power', 'rms_current', 'rms_voltage' 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), tsn=140, command_id=<GeneralCommand.Read_Attributes: 0>, *direction=<Direction.Server_to_Client: 0>) 0x43FC:1:0x0b04 Sending request: Read_Attributes(attribute_ids=[1291, 1288, 1285])

0x8DAD:1:0x0b04: Reading attributes in chunks: 'active_power', 'rms_current', 'rms_voltage' 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), tsn=142, command_id=<GeneralCommand.Read_Attributes: 0>, *direction=<Direction.Server_to_Client: 0>) 0x8DAD:1:0x0b04 Sending request: Read_Attributes(attribute_ids=[1291, 1288, 1285])

0xDAF9:1:0x0b04: Reading attributes in chunks: 'active_power', 'rms_current', 'rms_voltage' 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), tsn=144, command_id=<GeneralCommand.Read_Attributes: 0>, direction=<Direction.Server_to_Client: 0>) 0xDAF9:1:0x0b04 Sending request: Read_Attributes(attribute_ids=[1291, 1288, 1285]) Received a packet: ZigbeePacket(src=AddrModeAddress(addr_mode=<AddrMode.NWK: 2>, address=0xDAF9), src_ep=1, dst=AddrModeAddress(addr_mode=<AddrMode.NWK: 2>, address=0x0000), dst_ep=1, source_route=None, extended_timeout=False, tsn=211, profile_id=260, cluster_id=2820, data=Serialized[b'\x18\x90\x01\x0b\x05\x00)\x00\x00\x08\x05\x00!\x00\x00\x05\x05\x00!\xe9\x00'], tx_options=<TransmitOptions.NONE: 0>, radius=0, non_member_radius=0, lqi=120, rssi=-70) 0xDAF9:1:0x0b04 Received ZCL frame: b'\x18\x90\x01\x0b\x05\x00)\x00\x00\x08\x05\x00!\x00\x00\x05\x05\x00!\xe9\x00' 0xDAF9:1:0x0b04 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), tsn=144, command_id=1, direction=<Direction.Client_to_Server: 1>) 0xDAF9:1:0x0b04 Decoded ZCL frame: ElectricalMeasurementCluster:Read_Attributes_rsp(status_records=[ReadAttributeRecord(attrid=0x050B, status=<Status.SUCCESS: 0>, value=TypeValue(type=int16s, value=0)), ReadAttributeRecord(attrid=0x0508, status=<Status.SUCCESS: 0>, value=TypeValue(type=uint16_t, value=0)), ReadAttributeRecord(attrid=0x0505, status=<Status.SUCCESS: 0>, value=TypeValue(type=uint16_t, value=233))]) Received a packet: ZigbeePacket(src=AddrModeAddress(addr_mode=<AddrMode.NWK: 2>, address=0x43FC), src_ep=1, dst=AddrModeAddress(addr_mode=<AddrMode.NWK: 2>, address=0x0000), dst_ep=1, source_route=None, extended_timeout=False, tsn=156, profile_id=260, cluster_id=2820, data=Serialized[b'\x18\x8c\x01\x0b\x05\x00)\x00\x00\x08\x05\x00!\x00\x00\x05\x05\x00!\x15\x00'], tx_options=<TransmitOptions.NONE: 0>, radius=0, non_member_radius=0, lqi=120, rssi=-70) 0x43FC:1:0x0b04 Received ZCL frame: b'\x18\x8c\x01\x0b\x05\x00)\x00\x00\x08\x05\x00!\x00\x00\x05\x05\x00!\x15\x00' 0x43FC:1:0x0b04 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), tsn=140, command_id=1, direction=<Direction.Client_to_Server: 1>) 0x43FC:1:0x0b04 Decoded ZCL frame: ElectricalMeasurement:Read_Attributes_rsp(status_records=[ReadAttributeRecord(attrid=0x050B, status=<Status.SUCCESS: 0>, value=TypeValue(type=int16s, value=0)), ReadAttributeRecord(attrid=0x0508, status=<Status.SUCCESS: 0>, value=TypeValue(type=uint16_t, value=0)), ReadAttributeRecord(attrid=0x0505, status=<Status.SUCCESS: 0>, value=TypeValue(type=uint16_t, value=21))]) Received a packet: ZigbeePacket(src=AddrModeAddress(addr_mode=<AddrMode.NWK: 2>, address=0x8DAD), src_ep=1, dst=AddrModeAddress(addr_mode=<AddrMode.NWK: 2>, address=0x0000), dst_ep=1, source_route=None, extended_timeout=False, tsn=154, profile_id=260, cluster_id=2820, data=Serialized[b'\x18\x8e\x01\x0b\x05\x00)\x00\x00\x08\x05\x00!\x00\x00\x05\x05\x00!\x10\x01'], tx_options=<TransmitOptions.NONE: 0>, radius=0, non_member_radius=0, lqi=188, rssi=-53) 0x8DAD:1:0x0b04 Received ZCL frame: b'\x18\x8e\x01\x0b\x05\x00)\x00\x00\x08\x05\x00!\x00\x00\x05\x05\x00!\x10\x01' 0x8DAD:1:0x0b04 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), tsn=142, command_id=1, direction=<Direction.Client_to_Server: 1>) 0x8DAD:1:0x0b04 Decoded ZCL frame: ElectricalMeasurement:Read_Attributes_rsp(status_records=[ReadAttributeRecord(attrid=0x050B, status=<Status.SUCCESS: 0>, value=TypeValue(type=int16s, value=0)), ReadAttributeRecord(attrid=0x0508, status=<Status.SUCCESS: 0>, value=TypeValue(type=uint16_t, value=0)), ReadAttributeRecord(attrid=0x0505, status=<Status.SUCCESS: 0>, value=TypeValue(type=uint16_t, value=272))]) Received a packet: ZigbeePacket(src=AddrModeAddress(addr_mode=<AddrMode.NWK: 2>, address=0x8DAD), src_ep=1, dst=AddrModeAddress(addr_mode=<AddrMode.NWK: 2>, address=0x0000), dst_ep=1, source_route=None, extended_timeout=False, tsn=155, profile_id=260, cluster_id=2820, data=Serialized[b'\x08V\n\x05\x05!\x10\x01'], tx_options=<TransmitOptions.NONE: 0>, radius=0, non_member_radius=0, lqi=188, rssi=-53) 0x8DAD:1:0x0b04 Received ZCL frame: b'\x08V\n\x05\x05!\x10\x01' 0x8DAD:1:0x0b04 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), tsn=86, command_id=10, direction=<Direction.Client_to_Server: 1>) 0x8DAD:1:0x0b04 Decoded ZCL frame: ElectricalMeasurement:Report_Attributes(attribute_reports=[Attribute(attrid=0x0505, value=TypeValue(type=uint16_t, value=272))]) 0x8DAD:1:0x0b04 Received command 0x0A (TSN 86): Report_Attributes(attribute_reports=[Attribute(attrid=0x0505, value=TypeValue(type=uint16_t, value=272))]) 0x8DAD:1:0x0b04 Attribute report received: rms_voltage=272 0x8DAD:1:0x0b04 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), tsn=86, command_id=<GeneralCommand.Default_Response: 11>, direction=<Direction.Client_to_Server: 1>) 0x8DAD:1:0x0b04 Sending reply: Default_Response(command_id=10, status=<Status.SUCCESS: 0>) Received a packet: ZigbeePacket(src=AddrModeAddress(addr_mode=<AddrMode.NWK: 2>, address=0x8DAD), src_ep=1, dst=AddrModeAddress(addr_mode=<AddrMode.NWK: 2>, address=0x0000), dst_ep=1, source_route=None, extended_timeout=False, tsn=156, profile_id=260, cluster_id=2820, data=Serialized[b'\x08W\n\x05\x05!\x14\x01'], tx_options=<TransmitOptions.NONE: 0>, radius=0, non_member_radius=0, lqi=188, rssi=-53) 0x8DAD:1:0x0b04 Received ZCL frame: b'\x08W\n\x05\x05!\x14\x01' 0x8DAD:1:0x0b04 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), tsn=87, command_id=10, direction=<Direction.Client_to_Server: 1>) 0x8DAD:1:0x0b04 Decoded ZCL frame: ElectricalMeasurement:Report_Attributes(attribute_reports=[Attribute(attrid=0x0505, value=TypeValue(type=uint16_t, value=276))]) 0x8DAD:1:0x0b04 Received command 0x0A (TSN 87): Report_Attributes(attribute_reports=[Attribute(attrid=0x0505, value=TypeValue(type=uint16_t, value=276))]) 0x8DAD:1:0x0b04 Attribute report received: rms_voltage=276 0x8DAD:1:0x0b04 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), tsn=87, command_id=<GeneralCommand.Default_Response: 11>, direction=<Direction.Client_to_Server: 1>) 0x8DAD:1:0x0b04 Sending reply: Default_Response(command_id=10, status=<Status.SUCCESS: 0>) Device 0x9acf (00:12:4b:00:24:c1:fb:24) left the network 0x9acf: Update device availability - device available: True - new availability: False - changed: True 0x9acf: Device availability changed and device became unavailable Received a packet: ZigbeePacket(src=AddrModeAddress(addr_mode=<AddrMode.NWK: 2>, address=0x8DAD), src_ep=1, dst=AddrModeAddress(addr_mode=<AddrMode.NWK: 2>, address=0x0000), dst_ep=1, source_route=None, extended_timeout=False, tsn=157, profile_id=260, cluster_id=2820, data=Serialized[b'\x08X\n\x05\x05!\x04\x01'], tx_options=<TransmitOptions.NONE: 0>, radius=0, non_member_radius=0, lqi=188, rssi=-53) 0x8DAD:1:0x0b04 Received ZCL frame: b'\x08X\n\x05\x05!\x04\x01' 0x8DAD:1:0x0b04 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), tsn=88, command_id=10, direction=<Direction.Client_to_Server: 1>) 0x8DAD:1:0x0b04 Decoded ZCL frame: ElectricalMeasurement:Report_Attributes(attribute_reports=[Attribute(attrid=0x0505, value=TypeValue(type=uint16_t, value=260))]) 0x8DAD:1:0x0b04 Received command 0x0A (TSN 88): Report_Attributes(attribute_reports=[Attribute(attrid=0x0505, value=TypeValue(type=uint16_t, value=260))]) 0x8DAD:1:0x0b04 Attribute report received: rms_voltage=260 0x8DAD:1:0x0b04 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), tsn=88, command_id=<GeneralCommand.Default_Response: 11>, direction=<Direction.Client_to_Server: 1>) 0x8DAD:1:0x0b04 Sending reply: Default_Response(command_id=10, status=<Status.SUCCESS: 0>) 0x655B: Device seen - marking the device available and resetting counter 0x655B: Update device availability - device available: True - new availability: True - changed: False 0x1478: Device seen - marking the device available and resetting counter 0x1478: Update device availability - device available: True - new availability: True - changed: False 0x9E49: Device seen - marking the device available and resetting counter 0x9E49: Update device availability - device available: True - new availability: True - changed: False 0x8CEB: Device seen - marking the device available and resetting counter 0x8CEB: Update device availability - device available: True - new availability: True - changed: False 0x8827: Device seen - marking the device available and resetting counter 0x8827: Update device availability - device available: True - new availability: True - changed: False 0x5D93: last_seen is 3011170.165057659 seconds ago and ping attempts have been exhausted, marking the device unavailable 0x5D93: Update device availability - device available: False - new availability: False - changed: False 0x2659: Device seen - marking the device available and resetting counter 0x2659: Update device availability - device available: True - new availability: True - changed: False [0x51B6](TRADFRI control outlet): last_seen is 9991334.313723087 seconds ago and ping attempts have been exhausted, marking the device unavailable [0x51B6](TRADFRI control outlet): Update device availability - device available: False - new availability: False - changed: False Device 0x9acf (00:12:4b:00:24:c1:fb:24) joined the network [0x9ACF:1:0x0004] Sending request header: ZCLHeader(frame_control=FrameControl(frame_type=<FrameType.CLUSTER_COMMAND: 1>, is_manufacturer_specific=False, direction=<Direction.Server_to_Client: 0>, disable_default_response=0, reserved=0, is_cluster=True, is_general=False), tsn=149, command_id=2, direction=<Direction.Server_to_Client: 0>) [0x9ACF:1:0x0004] Sending request: get_membership(groups=[]) Device 0x9acf (00:12:4b:00:24:c1:fb:24) joined the network [0x9acf] Cancelling old group rescan [0x9ACF:1:0x0004] Sending request header: ZCLHeader(frame_control=FrameControl(frame_type=<FrameType.CLUSTER_COMMAND: 1>, is_manufacturer_specific=False, direction=<Direction.Server_to_Client: 0>, disable_default_response=0, reserved=0, is_cluster=True, is_general=False), tsn=151, command_id=2, direction=<Direction.Server_to_Client: 0>) [0x9ACF:1:0x0004] Sending request: get_membership(groups=[]) Received a packet: ZigbeePacket(src=AddrModeAddress(addr_mode=<AddrMode.NWK: 2>, address=0x9ACF), src_ep=0, dst=AddrModeAddress(addr_mode=<AddrMode.Broadcast: 15>, address=<BroadcastAddress.ALL_ROUTERS_AND_COORDINATOR: 65532>), dst_ep=0, source_route=None, extended_timeout=False, tsn=0, profile_id=0, cluster_id=19, data=Serialized[b'\x00\xcf\x9a$\xfb\xc1$\x00K\x12\x00\x8e'], tx_options=<TransmitOptions.NONE: 0>, radius=0, non_member_radius=0, lqi=56, rssi=-86) Device 0x9acf (00:12:4b:00:24:c1:fb:24) joined the network [0x9acf] Cancelling old group rescan 0x9acf: Update device availability - device available: False - new availability: True - changed: True 0x9acf: Device availability changed and device became available, reinitializing cluster handlers [0x9acf:zdo] ZDO request ZDOCmd.Device_annce: [0x9ACF, 00:12:4b:00:24:c1:fb:24, 142] [0x9ACF:1:0x0004] Sending request header: ZCLHeader(frame_control=FrameControl(frame_type=<FrameType.CLUSTER_COMMAND: 1>, is_manufacturer_specific=False, direction=<Direction.Server_to_Client: 0>, disable_default_response=0, reserved=0, is_cluster=True, is_general=False), tsn=153, command_id=2, direction=<Direction.Server_to_Client: 0>) [0x9ACF:1:0x0004] Sending request: get_membership(groups=[]) 0x9acf: started initialization 0x9acf:ZDO: 'async_initialize' stage succeeded [0x9acf:1:0x0006]: initializing cluster handler: from_cache: False [0x9acf:1:0x0006]: initializing cached cluster handler attributes: ['start_up_on_off'] [0x9acf:1:0x0006]: Reading attributes in chunks: ['start_up_on_off'] [0x9acf:1:0x0006]: initializing uncached cluster handler attributes: ['on_off'] - from cache[False] [0x9acf:1:0x0006]: Reading attributes in chunks: ['on_off'] [0x9ACF: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), tsn=155, command_id=<GeneralCommand.Read_Attributes: 0>, direction=<Direction.Server_to_Client: 0>) [0x9ACF:1:0x0006] Sending request: Read_Attributes(attribute_ids=[0]) [0x9acf:1:0x0000]: initializing cluster handler: from_cache: False [0x9acf:1:0x0000]: finished cluster handler initialization [0x9acf:1:0x0003]: initializing cluster handler: from_cache: False [0x9acf:1:0x0003]: finished cluster handler initialization [0x9acf:1:0x0019]: initializing cluster handler: from_cache: False [0x9acf:1:0x0019]: finished cluster handler initialization 0x8EE9: Device seen - marking the device available and resetting counter 0x8EE9: Update device availability - device available: True - new availability: True - changed: False 0x8DAD: Device seen - marking the device available and resetting counter 0x8DAD: Update device availability - device available: True - new availability: True - changed: False 0xBA79: Device seen - marking the device available and resetting counter 0xBA79: Update device availability - device available: True - new availability: True - changed: False Received a packet: ZigbeePacket(src=AddrModeAddress(addr_mode=<AddrMode.NWK: 2>, address=0x8DAD), src_ep=1, dst=AddrModeAddress(addr_mode=<AddrMode.NWK: 2>, address=0x0000), dst_ep=1, source_route=None, extended_timeout=False, tsn=158, profile_id=260, cluster_id=2820, data=Serialized[b'\x08Y\n\x05\x05!\x12\x01'], tx_options=<TransmitOptions.NONE: 0>, radius=0, non_member_radius=0, lqi=188, rssi=-53) 0x8DAD:1:0x0b04 Received ZCL frame: b'\x08Y\n\x05\x05!\x12\x01' 0x8DAD:1:0x0b04 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), tsn=89, command_id=10, direction=<Direction.Client_to_Server: 1>) 0x8DAD:1:0x0b04 Decoded ZCL frame: ElectricalMeasurement:Report_Attributes(attribute_reports=[Attribute(attrid=0x0505, value=TypeValue(type=uint16_t, value=274))]) 0x8DAD:1:0x0b04 Received command 0x0A (TSN 89): Report_Attributes(attribute_reports=[Attribute(attrid=0x0505, value=TypeValue(type=uint16_t, value=274))]) 0x8DAD:1:0x0b04 Attribute report received: rms_voltage=274 0x8DAD:1:0x0b04 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), tsn=89, command_id=<GeneralCommand.Default_Response: 11>, direction=<Direction.Client_to_Server: 1>) 0x8DAD:1:0x0b04 Sending reply: Default_Response(command_id=10, status=<Status.SUCCESS: 0>) Received a packet: ZigbeePacket(src=AddrModeAddress(addr_mode=<AddrMode.NWK: 2>, address=0x43FC), src_ep=1, dst=AddrModeAddress(addr_mode=<AddrMode.NWK: 2>, address=0x0000), dst_ep=1, source_route=None, extended_timeout=False, tsn=157, profile_id=260, cluster_id=2820, data=Serialized[b'\x08j\n\x05\x05!\x16\x00'], tx_options=<TransmitOptions.NONE: 0>, radius=0, non_member_radius=0, lqi=132, rssi=-67) 0x43FC:1:0x0b04 Received ZCL frame: b'\x08j\n\x05\x05!\x16\x00' 0x43FC:1:0x0b04 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), tsn=106, command_id=10, direction=<Direction.Client_to_Server: 1>) 0x43FC:1:0x0b04 Decoded ZCL frame: ElectricalMeasurement:Report_Attributes(attribute_reports=[Attribute(attrid=0x0505, value=TypeValue(type=uint16_t, value=22))]) 0x43FC:1:0x0b04 Received command 0x0A (TSN 106): Report_Attributes(attribute_reports=[Attribute(attrid=0x0505, value=TypeValue(type=uint16_t, value=22))]) 0x43FC:1:0x0b04 Attribute report received: rms_voltage=22 0x43FC:1:0x0b04 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), tsn=106, command_id=<GeneralCommand.Default_Response: 11>, direction=<Direction.Client_to_Server: 1>) 0x43FC:1:0x0b04 Sending reply: Default_Response(command_id=10, status=<Status.SUCCESS: 0>) [0x9acf:1] Failed to sync-up group membership [0x9acf:1:0x0006]: failed to get attributes '['on_off']' on 'on_off' cluster: [0x9acf:1:0x0006]: async_initialize: retryable request #1 failed: . Retrying in 1.0s [0x9acf:1:0x0006]: initializing cluster handler: from_cache: False [0x9acf:1:0x0006]: initializing cached cluster handler attributes: ['start_up_on_off'] [0x9acf:1:0x0006]: Reading attributes in chunks: ['start_up_on_off'] [0x9acf:1:0x0006]: initializing uncached cluster handler attributes: ['on_off'] - from cache[False] [0x9acf:1:0x0006]: Reading attributes in chunks: ['on_off'] [0x9ACF: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), tsn=159, command_id=<GeneralCommand.Read_Attributes: 0>, direction=<Direction.Server_to_Client: 0>) [0x9ACF:1:0x0006] Sending request: Read_Attributes(attribute_ids=[0]) 0x7363: Device seen - marking the device available and resetting counter 0x7363: Update device availability - device available: True - new availability: True - changed: False Received a packet: ZigbeePacket(src=AddrModeAddress(addr_mode=<AddrMode.NWK: 2>, address=0x8DAD), src_ep=1, dst=AddrModeAddress(addr_mode=<AddrMode.NWK: 2>, address=0x0000), dst_ep=1, source_route=None, extended_timeout=False, tsn=159, profile_id=260, cluster_id=2820, data=Serialized[b"\x08Z\n\x05\x05!'\x01"], tx_options=<TransmitOptions.NONE: 0>, radius=0, non_member_radius=0, lqi=188, rssi=-53) 0x8DAD:1:0x0b04 Received ZCL frame: b"\x08Z\n\x05\x05!'\x01" 0x8DAD:1:0x0b04 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), tsn=90, command_id=10, direction=<Direction.Client_to_Server: 1>) 0x8DAD:1:0x0b04 Decoded ZCL frame: ElectricalMeasurement:Report_Attributes(attribute_reports=[Attribute(attrid=0x0505, value=TypeValue(type=uint16_t, value=295))]) 0x8DAD:1:0x0b04 Received command 0x0A (TSN 90): Report_Attributes(attribute_reports=[Attribute(attrid=0x0505, value=TypeValue(type=uint16_t, value=295))]) 0x8DAD:1:0x0b04 Attribute report received: rms_voltage=295 0x8DAD:1:0x0b04 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), tsn=90, command_id=<GeneralCommand.Default_Response: 11>, direction=<Direction.Client_to_Server: 1>) 0x8DAD:1:0x0b04 Sending reply: Default_Response(command_id=10, status=<Status.SUCCESS: 0>) [0x7792](TRADFRI Signal Repeater): last_seen is 169151.31433033943 seconds ago and ping attempts have been exhausted, marking the device unavailable [0x7792](TRADFRI Signal Repeater): Update device availability - device available: False - new availability: False - changed: False Received a packet: ZigbeePacket(src=AddrModeAddress(addr_mode=<AddrMode.NWK: 2>, address=0x43FC), src_ep=1, dst=AddrModeAddress(addr_mode=<AddrMode.NWK: 2>, address=0x0000), dst_ep=1, source_route=None, extended_timeout=False, tsn=158, profile_id=260, cluster_id=2820, data=Serialized[b'\x08k\n\x05\x05!\x15\x00'], tx_options=<TransmitOptions.NONE: 0>, radius=0, non_member_radius=0, lqi=124, rssi=-69) 0x43FC:1:0x0b04 Received ZCL frame: b'\x08k\n\x05\x05!\x15\x00' 0x43FC:1:0x0b04 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), tsn=107, command_id=10, direction=<Direction.Client_to_Server: 1>) 0x43FC:1:0x0b04 Decoded ZCL frame: ElectricalMeasurement:Report_Attributes(attribute_reports=[Attribute(attrid=0x0505, value=TypeValue(type=uint16_t, value=21))]) 0x43FC:1:0x0b04 Received command 0x0A (TSN 107): Report_Attributes(attribute_reports=[Attribute(attrid=0x0505, value=TypeValue(type=uint16_t, value=21))]) 0x43FC:1:0x0b04 Attribute report received: rms_voltage=21 0x43FC:1:0x0b04 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), tsn=107, command_id=<GeneralCommand.Default_Response: 11>, direction=<Direction.Client_to_Server: 1>) 0x43FC:1:0x0b04 Sending reply: Default_Response(command_id=10, status=<Status.SUCCESS: 0>) [0x70D4](TRADFRI control outlet): Device seen - marking the device available and resetting counter [0x70D4](TRADFRI control outlet): Update device availability - device available: True - new availability: True - changed: False 0x4A93: Device seen - marking the device available and resetting counter 0x4A93: Update device availability - device available: True - new availability: True - changed: False [0x9acf:1:0x0006]: failed to get attributes '['on_off']' on 'on_off' cluster: [0x9acf:1:0x0006]: async_initialize: retryable request #2 failed: . Retrying in 1.1s [0x9acf:1:0x0006]: initializing cluster handler: from_cache: False [0x9acf:1:0x0006]: initializing cached cluster handler attributes: ['start_up_on_off'] [0x9acf:1:0x0006]: Reading attributes in chunks: ['start_up_on_off'] [0x9acf:1:0x0006]: initializing uncached cluster handler attributes: ['on_off'] - from cache[False] [0x9acf:1:0x0006]: Reading attributes in chunks: ['on_off'] [0x9ACF: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), tsn=163, command_id=<GeneralCommand.Read_Attributes: 0>, direction=<Direction.Server_to_Client: 0>) [0x9ACF:1:0x0006] Sending request: Read_Attributes(attribute_ids=[0]) Received a packet: ZigbeePacket(src=AddrModeAddress(addr_mode=<AddrMode.NWK: 2>, address=0x8DAD), src_ep=0, dst=AddrModeAddress(addr_mode=<AddrMode.Broadcast: 15>, address=<BroadcastAddress.ALL_ROUTERS_AND_COORDINATOR: 65532>), dst_ep=0, source_route=None, extended_timeout=False, tsn=164, profile_id=0, cluster_id=0, data=Serialized[b'\xe7<\xf1\xcb!\x00K\x12\x00\x00\x00'], tx_options=<TransmitOptions.NONE: 0>, radius=0, non_member_radius=0, lqi=188, rssi=-53) [0x8dad:zdo] ZDO request ZDOCmd.NWK_addr_req: [00:12:4b:00:21:cb:f1:3c, <AddrRequestType.Single: 0>, 0]

0x43FC:1:0x0b04: Reading attributes in chunks: 'active_power', 'rms_current', 'rms_voltage' 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), tsn=166, command_id=<GeneralCommand.Read_Attributes: 0>, *direction=<Direction.Server_to_Client: 0>) 0x43FC:1:0x0b04 Sending request: Read_Attributes(attribute_ids=[1291, 1288, 1285])

0x8DAD:1:0x0b04: Reading attributes in chunks: 'active_power', 'rms_current', 'rms_voltage' 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), tsn=168, command_id=<GeneralCommand.Read_Attributes: 0>, *direction=<Direction.Server_to_Client: 0>) 0x8DAD:1:0x0b04 Sending request: Read_Attributes(attribute_ids=[1291, 1288, 1285])

0xDAF9:1:0x0b04: Reading attributes in chunks: 'active_power', 'rms_current', 'rms_voltage' 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), tsn=170, command_id=<GeneralCommand.Read_Attributes: 0>, direction=<Direction.Server_to_Client: 0>) 0xDAF9:1:0x0b04 Sending request: Read_Attributes(attribute_ids=[1291, 1288, 1285]) Received a packet: ZigbeePacket(src=AddrModeAddress(addr_mode=<AddrMode.NWK: 2>, address=0x43FC), src_ep=1, dst=AddrModeAddress(addr_mode=<AddrMode.NWK: 2>, address=0x0000), dst_ep=1, source_route=None, extended_timeout=False, tsn=159, profile_id=260, cluster_id=2820, data=Serialized[b'\x18\xa6\x01\x0b\x05\x00)\x00\x00\x08\x05\x00!\x00\x00\x05\x05\x00!\x15\x00'], tx_options=<TransmitOptions.NONE: 0>, radius=0, non_member_radius=0, lqi=124, rssi=-69) 0x43FC:1:0x0b04 Received ZCL frame: b'\x18\xa6\x01\x0b\x05\x00)\x00\x00\x08\x05\x00!\x00\x00\x05\x05\x00!\x15\x00' 0x43FC:1:0x0b04 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), tsn=166, command_id=1, direction=<Direction.Client_to_Server: 1>) 0x43FC:1:0x0b04 Decoded ZCL frame: ElectricalMeasurement:Read_Attributes_rsp(status_records=[ReadAttributeRecord(attrid=0x050B, status=<Status.SUCCESS: 0>, value=TypeValue(type=int16s, value=0)), ReadAttributeRecord(attrid=0x0508, status=<Status.SUCCESS: 0>, value=TypeValue(type=uint16_t, value=0)), ReadAttributeRecord(attrid=0x0505, status=<Status.SUCCESS: 0>, value=TypeValue(type=uint16_t, value=21))]) Received a packet: ZigbeePacket(src=AddrModeAddress(addr_mode=<AddrMode.NWK: 2>, address=0x8DAD), src_ep=1, dst=AddrModeAddress(addr_mode=<AddrMode.NWK: 2>, address=0x0000), dst_ep=1, source_route=None, extended_timeout=False, tsn=165, profile_id=260, cluster_id=2820, data=Serialized[b'\x18\xa8\x01\x0b\x05\x00)\x00\x00\x08\x05\x00!\x00\x00\x05\x05\x00!\x06\x01'], tx_options=<TransmitOptions.NONE: 0>, radius=0, non_member_radius=0, lqi=188, rssi=-53) 0x8DAD:1:0x0b04 Received ZCL frame: b'\x18\xa8\x01\x0b\x05\x00)\x00\x00\x08\x05\x00!\x00\x00\x05\x05\x00!\x06\x01' 0x8DAD:1:0x0b04 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), tsn=168, command_id=1, direction=<Direction.Client_to_Server: 1>) 0x8DAD:1:0x0b04 Decoded ZCL frame: ElectricalMeasurement:Read_Attributes_rsp(status_records=[ReadAttributeRecord(attrid=0x050B, status=<Status.SUCCESS: 0>, value=TypeValue(type=int16s, value=0)), ReadAttributeRecord(attrid=0x0508, status=<Status.SUCCESS: 0>, value=TypeValue(type=uint16_t, value=0)), ReadAttributeRecord(attrid=0x0505, status=<Status.SUCCESS: 0>, value=TypeValue(type=uint16_t, value=262))]) Received a packet: ZigbeePacket(src=AddrModeAddress(addr_mode=<AddrMode.NWK: 2>, address=0xDAF9), src_ep=1, dst=AddrModeAddress(addr_mode=<AddrMode.NWK: 2>, address=0x0000), dst_ep=1, source_route=None, extended_timeout=False, tsn=212, profile_id=260, cluster_id=2820, data=Serialized[b'\x18\xaa\x01\x0b\x05\x00)\x00\x00\x08\x05\x00!\x00\x00\x05\x05\x00!\xe9\x00'], tx_options=<TransmitOptions.NONE: 0>, radius=0, non_member_radius=0, lqi=120, rssi=-70) 0xDAF9:1:0x0b04 Received ZCL frame: b'\x18\xaa\x01\x0b\x05\x00)\x00\x00\x08\x05\x00!\x00\x00\x05\x05\x00!\xe9\x00' 0xDAF9:1:0x0b04 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), tsn=170, command_id=1, direction=<Direction.Client_to_Server: 1>) 0xDAF9:1:0x0b04 Decoded ZCL frame: ElectricalMeasurementCluster:Read_Attributes_rsp(status_records=[ReadAttributeRecord(attrid=0x050B, status=<Status.SUCCESS: 0>, value=TypeValue(type=int16s, value=0)), ReadAttributeRecord(attrid=0x0508, status=<Status.SUCCESS: 0>, value=TypeValue(type=uint16_t, value=0)), ReadAttributeRecord(attrid=0x0505, status=<Status.SUCCESS: 0>, value=TypeValue(type=uint16_t, value=233))]) [0x9acf:1:0x0006]: failed to get attributes '['on_off']' on 'on_off' cluster: [0x9acf:1:0x0006]: async_initialize: retryable request #3 failed: . Retrying in 2.3s 0x65E3: last_seen is 9911896.77047348 seconds ago and ping attempts have been exhausted, marking the device unavailable 0x65E3: Update device availability - device available: False - new availability: False - changed: False Received a packet: ZigbeePacket(src=AddrModeAddress(addr_mode=<AddrMode.NWK: 2>, address=0x8DAD), src_ep=1, dst=AddrModeAddress(addr_mode=<AddrMode.NWK: 2>, address=0x0000), dst_ep=1, source_route=None, extended_timeout=False, tsn=166, profile_id=260, cluster_id=2820, data=Serialized[b'\x08\\n\x05\x05!\x06\x01'], tx_options=<TransmitOptions.NONE: 0>, radius=0, non_member_radius=0, lqi=188, rssi=-53) 0x8DAD:1:0x0b04 Received ZCL frame: b'\x08\\n\x05\x05!\x06\x01' 0x8DAD:1:0x0b04 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), tsn=92, command_id=10, direction=<Direction.Client_to_Server: 1>) 0x8DAD:1:0x0b04 Decoded ZCL frame: ElectricalMeasurement:Report_Attributes(attribute_reports=[Attribute(attrid=0x0505, value=TypeValue(type=uint16_t, value=262))]) 0x8DAD:1:0x0b04 Received command 0x0A (TSN 92): Report_Attributes(attribute_reports=[Attribute(attrid=0x0505, value=TypeValue(type=uint16_t, value=262))]) 0x8DAD:1:0x0b04 Attribute report received: rms_voltage=262 0x8DAD:1:0x0b04 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), tsn=92, command_id=<GeneralCommand.Default_Response: 11>, direction=<Direction.Client_to_Server: 1>) 0x8DAD:1:0x0b04 Sending reply: Default_Response(command_id=10, status=<Status.SUCCESS: 0>) Received a packet: ZigbeePacket(src=AddrModeAddress(addr_mode=<AddrMode.NWK: 2>, address=0x8DAD), src_ep=1, dst=AddrModeAddress(addr_mode=<AddrMode.NWK: 2>, address=0x0000), dst_ep=1, source_route=None, extended_timeout=False, tsn=167, profile_id=260, cluster_id=1794, data=Serialized[b'\x08]\n\x00\x02\x18\x00'], tx_options=<TransmitOptions.NONE: 0>, radius=0, non_member_radius=0, lqi=188, rssi=-53) [0x8DAD:1:0x0702] Received ZCL frame: b'\x08]\n\x00\x02\x18\x00' [0x8DAD:1:0x0702] Decoded ZCL frame header: ZCLHeader(frame_control=FrameControl(frame_type=<FrameType.GLOBAL_COMMAND: 0>, is_manufacturer_specific=0, direction=<Direction.Client_to_Server: 1>, disa

MathiasEveraerts commented 1 year ago

i have the same issue, sometimes it happens after 4 hours, sometimes when debug log is enabled it just doesn't... it happened in the past before.

jmmit commented 1 year ago

Following this as I also have this issue starting in the last few days. Unplugging the stick, plugging it back in and reloading the integration seems to bring it back into life for a day and then it goes again. That's the quickest way I've found to restore it but even rebooting home assistant blue doesn't fix the issue.

ghost commented 1 year ago

Im getting this too

gioele-antoci commented 1 year ago

I am also having certain battery zha devices fall off the network inexplicably. For me it's specifically certain battery operated aqara devices that fall off the network. Few days (~3-4) this problem did not exist and those devices had been stable for weeks prior

asperger514 commented 1 year ago

Same here.

puddly commented 1 year ago

@JHurk the entire log file, please. If you compress it into a ZIP archive, it should attach to a comment here without issues. You can also email it to me instead.

JHurk commented 1 year ago

home-assistant_zha_2023-06-27T20-55-03.469Z.log.zip Thanks, here you go; the entire log file of that time and date.

puddly commented 1 year ago

Can you also include diagnostics information for the ZHA integration itself (not the device).

JHurk commented 1 year ago

config_entry-zha-7f792b9c484b39e82b9979f9b77a7c48.json.txt This is the one you asked for. Note; I just downloaded this one so it is not of the exact same timeframe as the device diagnostics and the debug log.

puddly commented 1 year ago

Channel 14 is not a good channel to pick: it's not only congested in your environment, but it also is a non-ZLL channel and overlaps WiFi channel 1 heavily.

I would migrate your network back to a normal channel by using the ZHA channel migration interface with auto. It will most likely pick channel 25.

JHurk commented 1 year ago

I understand what you mean and I have tried using different channels before. Settings were; Wifi channel - auto Zigbee channel - auto

But because I read that this could be the issue a few days ago I changed it to; Wifi channel - 11 Zigbee channel - 11

Because this also did not help I changed the settings to; (about two days ago) Wifi channel - 11 Zigbee channel - 14

Changing the channels did not seem to do any good (neither harm) so I did not change anything anymore. My Skyconnect stick is also connected to the Odroid with an extension cable, but nothing changed in that closet (where unifi and odroid, etc. are situated).

And to be sure I changed the zigbee to auto (= 25 indeed) but after connecting the device again, it automatically loses connection within a few seconds. Also another device which was connected loses contact in a few moments.

puddly commented 1 year ago

Here is what the channel utilization is for your environment, according to your debug log:

"11": 92.95  # your previous channel
"12": 96.64
"13": 95.12
"14": 93.76  # your current channel
"15": 98.62  # most likely your original channel
"16": 97.04
"17": 98.62
"18": 98.21
"19": 97.39
"20": 28.30
"21": 46.26
"22": 75.96
"23": 62.25
"24": 31.01
"25": 19.00  # a better choice, which is what `auto` will likely pick
"26": 99.06

I would also move your WiFi network back to channel 1 or 6.

JHurk commented 1 year ago

Ok, just switched the wifi channels to 1. Waited a few minutes and then restarted HA, just to be sure. But the device is still unavailable in HA.

puddly commented 1 year ago

WiFi and Zigbee channels overlap. If you move your WiFi network to channel 1 without moving the Zigbee network, it will likely make the interference problem worse. See the below graphic:

If the device has disconnected, you may need to re-join it to your network after the channel change.

JHurk commented 1 year ago

Sorry, I was not clear in my answer. I moved the wifi to 1 and the zigbee was already on 25 (via auto). So they should not overlap.

I just added both devices again with debug log on and after a few moments they went from available to unavailable.

Here is the new debug; home-assistant_zha_2023-06-29T19-54-18.688Z.log.zip

JHurk commented 1 year ago

And some device diagnostics; First of the ZHA integration itself. Then both devices that are not working ('Sonoff 01MINIZB' and 'Lantaarnpaal') And finally one device, same make and model (Sonoff ZBMINI01) which has always been working 'Terras' ZHA config_entry-zha-7f792b9c484b39e82b9979f9b77a7c48.json-2.txt

SONOFF 01MINIZB zha-7f792b9c484b39e82b9979f9b77a7c48-SONOFF 01MINIZB-caed7bdb0239b62c3f9ce7aedcfde2f7.json.txt

Lantaarnpaal zha-7f792b9c484b39e82b9979f9b77a7c48-SONOFF 01MINIZB-9c5dc8c69280bdf38bdd4148b273a255.json-2.txt

Terras zha-7f792b9c484b39e82b9979f9b77a7c48-SONOFF 01MINIZB-1c89abaa375cb716ce676b3f82b9d85b.json.txt

All diagnostics were just downloaded a few seconds after each other.

JKoehorst2 commented 1 year ago

Same here, 4 of my 8 plugs (TS011F -> Nous A1Z plug) are completely unusable and can't be paired anymore (SONOFF Zigbee 3.0 USB Dongle Plus V2). They are still available as entities and switching them on on the dashboard does not switch the device on, only the switch in the UI. 2 sec. later the switch in the UI will go back to it's original position. Deleting the device is possible, but pairing after that is not possible.

I opened this thread a few weeks ago: https://community.home-assistant.io/t/cant-pair-ts011f-plugs-anymore/578944

The devices becoming unresponsive seems to be happening after changing the name of the device. I'm willing to re-install ZHA and do some testing, but what should I test?

(Home Assistant 2023.5.3 Supervisor 2023.06.4 Operating System 10.1 Frontend-versie: 20230503.3 - latest)

puddly commented 1 year ago

@JHurk According to the log, it looks like your device joins the network successfully and is initialized properly. 25 seconds after this, however, it decides to leave the network on its own! This isn't something that ZHA can control or stop.

I'm unable to replicate this problem with a SkyConnect running the exact same firmware as yours and the same SONOFF ZBMINI01 and it's strange that only some of your ZBMINI01s experience this issue.

What other routing devices do you have on your network? Does this issue occur with other devices, or just the ZBMINI01?

JHurk commented 1 year ago

Here are some of the devices which are in the same network and closest to the device that has been causing trouble. Some are routers and some are end points, all of them work normally. So two Sonoff ZBMini01 cause trouble all the time (one of them came out straight out of the box). Another device which causes the same trouble is a Moes Dimmer Module MS-105Z, also out of the box.

Other devices (possibly not in the screen shot) that caused trouble before but are stable now (for as long as it lasts);

VIYU_GU10_350_RGBW_10297666 (which is al GU10 led light with color from Hornbach, a router), I have 2 and one was giving me trouble.
lumi.sensor_magnet.aq2 (which is a doorsensor from Aqara/Xiaomi, an end point), I have two of them and both have had problems.
lumi.sen_ill.mgl01 (which is a lux meter from Aqara/Xiaomi, an end point)
lumi.weather (which is a temp meter from Aqara/Xiaomi, an end point). With the end points I understand the connection sometimes drops. Usually a button press causes the device to respond again. The router devices are harder (or impossible) to connect again.

JHurk commented 1 year ago

Some additional information; I added the new, out of the box, Sonoff ZBMini to the network (called it 'Palen'). As soon as it joins the network it responds to the switch in HA. But as soon as I turn it off, it gives an unresponsive message after turning off.

For the 'non Dutch' readers; uitgeschakeld = turned off ingeschakeld = turned on niet meer beschikbaar = unavailable

JHurk commented 1 year ago

After some extended searching on the internet I think this issue is unrelated to ZHA. https://github.com/zigpy/zha-device-handlers/issues/1841 This describes the issue I am having. The device does not leave pairing mode after 'successful' pairing. So it becomes a pairing loop. Unfortunately there is no solution know at this time, or at least I haven't found it. Will search some more on 'zigbee device pairing loop', maybe this will give another lead.

Closed the issue because my initial problem has been identified (I think). I understand that it is possible that some of the other issues addressed in this thread by others are not the same. Maybe opening a separate issue for these is the best option.

Edit (4 days after closing): I added a brand new Moes ZRM-104MS (normal switch) to the network to test if this one would 'stick' and it does. Adding it to the network works and it doesn't get stuck in the endless pairing loop. And it keeps responding in HA even after a few hours/days. So the problem is still happening for the Sonoff ZBMini-01, but will stick to other devices than Sonoff for the moment.

home-assistant / core