search

home-assistant / core

:house_with_garden: Open source home automation that puts local control and privacy first.
https://www.home-assistant.io
Apache License 2.0
73.8k stars 30.89k forks source link

Zigbee smart plugs turning off on their own randomly - Not Tuya TS001F Issue #101291

Closed Technoholic84 closed 1 year ago

Technoholic84 commented 1 year ago

The problem

Since upgrading to 2023.9.3, all my zigbee smart plugs have been turning themselves off randomly, but usually all within a few minutes of each other. All it shows in the logbook is this:

image

It does not show that it has been triggered by an automation or a manual button press, because it hasn't, it just turns off. This is with a Sonoff Dongle-P. I thought this was because I had migrated to a new machine but it seems that the actual problem is due to 2023.9.3 because when reverting to a backup of 2023.8.4, the problem is no longer there.

There was zero problems before I migrated, and the old machine was also running 2023.8.4. Since upgrading the old machine to 2023.9.3 and putting that back into use, the problem also occurs on that machine too, so it definitely seems to be something in 2023.9.3

What version of Home Assistant Core has the issue?

core-2023.9.3

What was the last working version of Home Assistant Core?

core-2023.8.4

What type of installation are you running?

Home Assistant OS

Integration causing the issue

Zigbee ZHA

Link to integration documentation on our website

No response

Diagnostics information

config_entry-zha-18c9e8603b58b3ffb5155c5df3d49529.json.txt

Example YAML snippet

No response

Anything in the logs that might be useful for us?

No response

Additional information

No response

kevinklinkmuller commented 1 year ago

Same exact issue since the new update. All zigbee plugs (in my case Woolley) turn off every 1.2 hours. All of them in roughly the same time. activity shows just “turned off” and that’s it.

Technoholic84 commented 1 year ago

Mine are Woolley too! I wonder what the issue is in the latest release. I’ve just reverted back to 2023.8.4 again and it’s gone away

Technoholic84 commented 1 year ago

Problem still exists in 2023.10, having to roll back to 2023.8.4 again

kevinklinkmuller commented 1 year ago

Same, roll back solved it

TheJulianJES commented 1 year ago

Please upload the device diagnostic information for the affected plugs.

Technoholic84 commented 1 year ago

Please upload the device diagnostic information for the affected plugs.

Not sure exactly how to get that, I'm a fairly new user but also, given that I've downgraded to 2023.8.4 where it's working, I guess the diagnostics will not be useful?

Technoholic84 commented 1 year ago

Please upload the device diagnostic information for the affected plugs.

@TheJulianJES

Hi, is there anything that we can do to get this investigated? I am stuck on an older version now, not a big problem at the moment but as things change more, it would be good to be able to upgrade

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

@Technoholic84 without diagnostic info there's no way to tell what device you're using. Can you upload it the same way you did for the whole integration?

Technoholic84 commented 1 year ago

zha-18c9e8603b58b3ffb5155c5df3d49529-Sonoff SA-030-1-f12d3f0f6f6db027e1ba2d3e4f1e8314.json-2.txt

Technoholic84 commented 1 year ago

Hopefully that works

TheJulianJES commented 1 year ago

So are only those "Sonoff SA-030-1" plugs affected or also plugs from other manufacturers?

It seems like Sonoff did wonders with their Zigbee implementation and Z2M needs to work around multiple issues:

I don't think these issues should cause the plug to randomly turn off though? (unless it maybe crashes and then turns off?) (And I'm also not sure if both fixes are actually needed for that plug. It seems like they were added without explanation in a PR)

Technoholic84 commented 1 year ago

Yes only those plugs and they are branded as “Woolley” over here but yes it’s only those. I don’t know if that would cause them to randomly turn off, I’m not using z2m. The only thing I can do to stop it is to downgrade to 2023.8.4, the moment I move back to 2023.9.3 it starts happening again

TheJulianJES commented 1 year ago

I just wanted to check Z2M implementation to see if they had fixed some issue regarding this. It doesn't look like there's anything that would affect the plug turning off randomly though.

Did you try updating to HA 2023.10.x to see if the issue is maybe resolved there? Also, you're running a ZBDongle-E with the stock firmware, right? The firmware should be fine, but you could also try updating the EZSP version of it: https://darkxst.github.io/silabs-firmware-builder/ (<- haven't tested this, but should be fine)

Also, you could try the following: turn on both plugs, unplug the Zigbee coordinator, see if the plugs still turn off. (Obviously, your Zigbee network wouldn't work for the time your stick is unplugged)

Lastly, debug logs (can be turned on using integration page) for when the plugs turn off could help too.

Technoholic84 commented 1 year ago

Yes 2023.10.1 does the same thing. It’s a Dongle -E yes with the firmware that came with it.

I’ll need to upstage the software again and then try those tests as there’s no point doing it now. Let me try that and see what happens. I’ll reply when I have some information.

Technoholic84 commented 1 year ago

I upgraded to 10.1 just after my last message. About 20 mins later and they turned off again. Debug logs to follow shortly…

Technoholic84 commented 1 year ago

config_entry-zha-18c9e8603b58b3ffb5155c5df3d49529.json-3.txt

here you go.

puddly commented 1 year ago

@Technoholic84 Debug logging is accessible from the integration's menu. Enable it, reproduce the problem, and then disable it:

image
Technoholic84 commented 1 year ago

Yes that’s what I did, and attached the logs above

puddly commented 1 year ago

You attached the diagnostics information for the config entry, which doesn't include any logs:

image

Debug logging is enabled with the option I have highlighted in the previous comment.

Technoholic84 commented 1 year ago

I have debug logging enabled but which file do I need to upload? The main home assistant log?

Technoholic84 commented 1 year ago

home-assistant_2023-10-11T20-47-45.750Z.log

Is this the right log? The time of the event was about 20:57

puddly commented 1 year ago

Interesting. The plug seems to crash/reboot after trying to ask for an OTA update.

This log looks like it's from 2023.10.x. Could you generate a similar debug log with 2023.9.3? If it doesn't do the same thing, just leave debug logging running for a few hours and ZIP up the resulting log file

Here's only the relevant info, with a few annotations:

# The plug periodically reports that it is on
2023-10-11 20:28:37.893 DEBUG (MainThread) [bellows.ezsp.protocol] Application frame received incomingMessageHandler: [<EmberIncomingMessageType.INCOMING_UNICAST: 0>, EmberApsFrame(profileId=260, clusterId=6, sourceEndpoint=1, destinationEndpoint=1, options=<EmberApsOption.APS_OPTION_ENABLE_ROUTE_DISCOVERY: 256>, groupId=0, sequence=105), 132, -67, 0xb9e9, 255, 255, b'\x18\x06\n\x00\x00\x10\x01']
2023-10-11 20:28:37.893 DEBUG (MainThread) [bellows.zigbee.application] Received incomingMessageHandler frame with [<EmberIncomingMessageType.INCOMING_UNICAST: 0>, EmberApsFrame(profileId=260, clusterId=6, sourceEndpoint=1, destinationEndpoint=1, options=<EmberApsOption.APS_OPTION_ENABLE_ROUTE_DISCOVERY: 256>, groupId=0, sequence=105), 132, -67, 0xb9e9, 255, 255, b'\x18\x06\n\x00\x00\x10\x01']
2023-10-11 20:28:37.894 DEBUG (MainThread) [zigpy.application] Received a packet: ZigbeePacket(src=AddrModeAddress(addr_mode=<AddrMode.NWK: 2>, address=0xB9E9), src_ep=1, dst=AddrModeAddress(addr_mode=<AddrMode.NWK: 2>, address=0x0000), dst_ep=1, source_route=None, extended_timeout=False, tsn=105, profile_id=260, cluster_id=6, data=Serialized[b'\x18\x06\n\x00\x00\x10\x01'], tx_options=<TransmitOptions.NONE: 0>, radius=0, non_member_radius=0, lqi=132, rssi=-67)
2023-10-11 20:28:37.894 DEBUG (MainThread) [zigpy.zcl] [0xB9E9:1:0x0006] Received ZCL frame: b'\x18\x06\n\x00\x00\x10\x01'
2023-10-11 20:28:37.895 DEBUG (MainThread) [zigpy.zcl] [0xB9E9: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=6, command_id=10, *direction=<Direction.Client_to_Server: 1>)
2023-10-11 20:28:37.896 DEBUG (MainThread) [zigpy.zcl] [0xB9E9:1:0x0006] Decoded ZCL frame: OnOff:Report_Attributes(attribute_reports=[Attribute(attrid=0x0000, value=TypeValue(type=Bool, value=<Bool.true: 1>))])
2023-10-11 20:28:37.896 DEBUG (MainThread) [zigpy.zcl] [0xB9E9:1:0x0006] Received command 0x0A (TSN 6): Report_Attributes(attribute_reports=[Attribute(attrid=0x0000, value=TypeValue(type=Bool, value=<Bool.true: 1>))])
2023-10-11 20:28:37.897 DEBUG (MainThread) [zigpy.zcl] [0xB9E9:1:0x0006] Attribute report received: on_off=<Bool.true: 1>

# Exactly 15 minutes later, it again reports that it is still on
2023-10-11 20:43:37.907 DEBUG (MainThread) [bellows.ezsp.protocol] Application frame received incomingMessageHandler: [<EmberIncomingMessageType.INCOMING_UNICAST: 0>, EmberApsFrame(profileId=260, clusterId=6, sourceEndpoint=1, destinationEndpoint=1, options=<EmberApsOption.APS_OPTION_ENABLE_ROUTE_DISCOVERY: 256>, groupId=0, sequence=106), 148, -63, 0xb9e9, 255, 255, b'\x18\x07\n\x00\x00\x10\x01']
2023-10-11 20:43:37.907 DEBUG (MainThread) [bellows.zigbee.application] Received incomingMessageHandler frame with [<EmberIncomingMessageType.INCOMING_UNICAST: 0>, EmberApsFrame(profileId=260, clusterId=6, sourceEndpoint=1, destinationEndpoint=1, options=<EmberApsOption.APS_OPTION_ENABLE_ROUTE_DISCOVERY: 256>, groupId=0, sequence=106), 148, -63, 0xb9e9, 255, 255, b'\x18\x07\n\x00\x00\x10\x01']
2023-10-11 20:43:37.908 DEBUG (MainThread) [zigpy.application] Received a packet: ZigbeePacket(src=AddrModeAddress(addr_mode=<AddrMode.NWK: 2>, address=0xB9E9), src_ep=1, dst=AddrModeAddress(addr_mode=<AddrMode.NWK: 2>, address=0x0000), dst_ep=1, source_route=None, extended_timeout=False, tsn=106, profile_id=260, cluster_id=6, data=Serialized[b'\x18\x07\n\x00\x00\x10\x01'], tx_options=<TransmitOptions.NONE: 0>, radius=0, non_member_radius=0, lqi=148, rssi=-63)
2023-10-11 20:43:37.908 DEBUG (MainThread) [zigpy.zcl] [0xB9E9:1:0x0006] Received ZCL frame: b'\x18\x07\n\x00\x00\x10\x01'
2023-10-11 20:43:37.909 DEBUG (MainThread) [zigpy.zcl] [0xB9E9: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=7, command_id=10, *direction=<Direction.Client_to_Server: 1>)
2023-10-11 20:43:37.910 DEBUG (MainThread) [zigpy.zcl] [0xB9E9:1:0x0006] Decoded ZCL frame: OnOff:Report_Attributes(attribute_reports=[Attribute(attrid=0x0000, value=TypeValue(type=Bool, value=<Bool.true: 1>))])
2023-10-11 20:43:37.910 DEBUG (MainThread) [zigpy.zcl] [0xB9E9:1:0x0006] Received command 0x0A (TSN 7): Report_Attributes(attribute_reports=[Attribute(attrid=0x0000, value=TypeValue(type=Bool, value=<Bool.true: 1>))])
2023-10-11 20:43:37.911 DEBUG (MainThread) [zigpy.zcl] [0xB9E9:1:0x0006] Attribute report received: on_off=<Bool.true: 1>

# Plug sends an active endpoint request to the coordinator??
2023-10-11 20:57:46.876 DEBUG (MainThread) [bellows.ezsp.protocol] Application frame received incomingMessageHandler: [<EmberIncomingMessageType.INCOMING_UNICAST: 0>, EmberApsFrame(profileId=0, clusterId=5, sourceEndpoint=0, destinationEndpoint=0, options=<EmberApsOption.APS_OPTION_RETRY|APS_OPTION_ENABLE_ROUTE_DISCOVERY: 320>, groupId=0, sequence=107), 144, -64, 0xb9e9, 255, 255, b'\x1d\x00\x00']
2023-10-11 20:57:46.877 DEBUG (MainThread) [bellows.zigbee.application] Received incomingMessageHandler frame with [<EmberIncomingMessageType.INCOMING_UNICAST: 0>, EmberApsFrame(profileId=0, clusterId=5, sourceEndpoint=0, destinationEndpoint=0, options=<EmberApsOption.APS_OPTION_RETRY|APS_OPTION_ENABLE_ROUTE_DISCOVERY: 320>, groupId=0, sequence=107), 144, -64, 0xb9e9, 255, 255, b'\x1d\x00\x00']
2023-10-11 20:57:46.877 DEBUG (MainThread) [zigpy.application] Received a packet: ZigbeePacket(src=AddrModeAddress(addr_mode=<AddrMode.NWK: 2>, address=0xB9E9), src_ep=0, dst=AddrModeAddress(addr_mode=<AddrMode.NWK: 2>, address=0x0000), dst_ep=0, source_route=None, extended_timeout=False, tsn=107, profile_id=0, cluster_id=5, data=Serialized[b'\x1d\x00\x00'], tx_options=<TransmitOptions.NONE: 0>, radius=0, non_member_radius=0, lqi=144, rssi=-64)
2023-10-11 20:57:46.878 DEBUG (MainThread) [zigpy.zdo] [0xb9e9:zdo] ZDO request ZDOCmd.Active_EP_req: [0x0000]
2023-10-11 20:57:46.878 DEBUG (MainThread) [zigpy.zdo] [0xb9e9:zdo] No handler for ZDO request:ZDOCmd.Active_EP_req([0x0000])

# Then tries to perform an OTA update
2023-10-11 20:57:54.758 DEBUG (MainThread) [bellows.ezsp.protocol] Application frame received incomingMessageHandler: [<EmberIncomingMessageType.INCOMING_UNICAST: 0>, EmberApsFrame(profileId=260, clusterId=25, sourceEndpoint=1, destinationEndpoint=255, options=<EmberApsOption.APS_OPTION_RETRY|APS_OPTION_ENABLE_ROUTE_DISCOVERY: 320>, groupId=0, sequence=58), 144, -64, 0xb9e9, 255, 255, b'\x01\x01\x01\x00\x86\x12\x00\x00\x01\x00\x00\x00']
2023-10-11 20:57:54.758 DEBUG (MainThread) [bellows.zigbee.application] Received incomingMessageHandler frame with [<EmberIncomingMessageType.INCOMING_UNICAST: 0>, EmberApsFrame(profileId=260, clusterId=25, sourceEndpoint=1, destinationEndpoint=255, options=<EmberApsOption.APS_OPTION_RETRY|APS_OPTION_ENABLE_ROUTE_DISCOVERY: 320>, groupId=0, sequence=58), 144, -64, 0xb9e9, 255, 255, b'\x01\x01\x01\x00\x86\x12\x00\x00\x01\x00\x00\x00']
2023-10-11 20:57:54.758 DEBUG (MainThread) [zigpy.application] Received a packet: ZigbeePacket(src=AddrModeAddress(addr_mode=<AddrMode.NWK: 2>, address=0xB9E9), src_ep=1, dst=AddrModeAddress(addr_mode=<AddrMode.NWK: 2>, address=0x0000), dst_ep=255, source_route=None, extended_timeout=False, tsn=58, profile_id=260, cluster_id=25, data=Serialized[b'\x01\x01\x01\x00\x86\x12\x00\x00\x01\x00\x00\x00'], tx_options=<TransmitOptions.NONE: 0>, radius=0, non_member_radius=0, lqi=144, rssi=-64)
2023-10-11 20:57:54.759 DEBUG (MainThread) [zigpy.zcl] [0xB9E9:1:0x0019] Received ZCL frame: b'\x01\x01\x01\x00\x86\x12\x00\x00\x01\x00\x00\x00'
2023-10-11 20:57:54.760 DEBUG (MainThread) [zigpy.zcl] [0xB9E9:1:0x0019] Decoded ZCL frame header: ZCLHeader(frame_control=FrameControl(frame_type=<FrameType.CLUSTER_COMMAND: 1>, is_manufacturer_specific=0, direction=<Direction.Server_to_Client: 0>, disable_default_response=0, reserved=0, *is_cluster=True, *is_general=False), tsn=1, command_id=1, *direction=<Direction.Server_to_Client: 0>)
2023-10-11 20:57:54.761 DEBUG (MainThread) [zigpy.zcl] [0xB9E9:1:0x0019] Decoded ZCL frame: Ota:QueryNextImageCommand(field_control=<FieldControl: 0>, manufacturer_code=4742, image_type=0, current_file_version=1)
2023-10-11 20:57:54.761 DEBUG (MainThread) [zigpy.zcl] [0xB9E9:1:0x0019] Received command 0x01 (TSN 1): QueryNextImageCommand(field_control=<FieldControl: 0>, manufacturer_code=4742, image_type=0, current_file_version=1)
2023-10-11 20:57:54.762 DEBUG (MainThread) [zigpy.zcl] [0xB9E9:1:0x0019] OTA query_next_image handler for 'Sonoff SA-030-1': field_control=0, manufacturer_id=4742, image_type=0, current_file_version=1, hardware_version=None, model='SA-030-1'

# There's no available image for the plug so we tell the plug there is no image
2023-10-11 20:57:54.762 DEBUG (MainThread) [zigpy.zcl] [0xB9E9:1:0x0019] No OTA image is available
2023-10-11 20:57:54.763 DEBUG (MainThread) [zigpy.zcl] [0xB9E9:1:0x0019] Sending reply header: ZCLHeader(frame_control=FrameControl(frame_type=<FrameType.CLUSTER_COMMAND: 1>, is_manufacturer_specific=False, direction=<Direction.Client_to_Server: 1>, disable_default_response=1, reserved=0, *is_cluster=True, *is_general=False), tsn=1, command_id=2, *direction=<Direction.Client_to_Server: 1>)
2023-10-11 20:57:54.764 DEBUG (MainThread) [zigpy.zcl] [0xB9E9:1:0x0019] Sending reply: query_next_image_response(status=<Status.NO_IMAGE_AVAILABLE: 152>, manufacturer_code=None, image_type=None, file_version=None, image_size=None)
2023-10-11 20:57:54.764 DEBUG (MainThread) [bellows.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=0xB9E9), dst_ep=1, source_route=None, extended_timeout=False, tsn=1, profile_id=260, cluster_id=25, data=Serialized[b'\x19\x01\x02\x98'], tx_options=<TransmitOptions.ACK: 1>, radius=0, non_member_radius=0, lqi=None, rssi=None)
2023-10-11 20:57:54.765 DEBUG (MainThread) [bellows.ezsp.protocol] Send command sendUnicast: (<EmberOutgoingMessageType.OUTGOING_DIRECT: 0>, 0xb9e9, EmberApsFrame(profileId=260, clusterId=25, sourceEndpoint=1, destinationEndpoint=1, options=<EmberApsOption.APS_OPTION_RETRY|APS_OPTION_ENABLE_ROUTE_DISCOVERY: 320>, groupId=0, sequence=1), 29, b'\x19\x01\x02\x98')

# The plug instantly shuts off??
2023-10-11 20:57:54.770 DEBUG (MainThread) [bellows.ezsp.protocol] Application frame received incomingMessageHandler: [<EmberIncomingMessageType.INCOMING_UNICAST: 0>, EmberApsFrame(profileId=260, clusterId=6, sourceEndpoint=1, destinationEndpoint=1, options=<EmberApsOption.APS_OPTION_ENABLE_ROUTE_DISCOVERY: 256>, groupId=0, sequence=59), 144, -64, 0xb9e9, 255, 255, b'\x18\x02\n\x00\x00\x10\x00']
2023-10-11 20:57:54.770 DEBUG (MainThread) [bellows.zigbee.application] Received incomingMessageHandler frame with [<EmberIncomingMessageType.INCOMING_UNICAST: 0>, EmberApsFrame(profileId=260, clusterId=6, sourceEndpoint=1, destinationEndpoint=1, options=<EmberApsOption.APS_OPTION_ENABLE_ROUTE_DISCOVERY: 256>, groupId=0, sequence=59), 144, -64, 0xb9e9, 255, 255, b'\x18\x02\n\x00\x00\x10\x00']
2023-10-11 20:57:54.771 DEBUG (MainThread) [zigpy.application] Received a packet: ZigbeePacket(src=AddrModeAddress(addr_mode=<AddrMode.NWK: 2>, address=0xB9E9), src_ep=1, dst=AddrModeAddress(addr_mode=<AddrMode.NWK: 2>, address=0x0000), dst_ep=1, source_route=None, extended_timeout=False, tsn=59, profile_id=260, cluster_id=6, data=Serialized[b'\x18\x02\n\x00\x00\x10\x00'], tx_options=<TransmitOptions.NONE: 0>, radius=0, non_member_radius=0, lqi=144, rssi=-64)
2023-10-11 20:57:54.771 DEBUG (MainThread) [zigpy.zcl] [0xB9E9:1:0x0006] Received ZCL frame: b'\x18\x02\n\x00\x00\x10\x00'
2023-10-11 20:57:54.772 DEBUG (MainThread) [zigpy.zcl] [0xB9E9: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=2, command_id=10, *direction=<Direction.Client_to_Server: 1>)
2023-10-11 20:57:54.773 DEBUG (MainThread) [zigpy.zcl] [0xB9E9:1:0x0006] Decoded ZCL frame: OnOff:Report_Attributes(attribute_reports=[Attribute(attrid=0x0000, value=TypeValue(type=Bool, value=<Bool.false: 0>))])
2023-10-11 20:57:54.773 DEBUG (MainThread) [zigpy.zcl] [0xB9E9:1:0x0006] Received command 0x0A (TSN 2): Report_Attributes(attribute_reports=[Attribute(attrid=0x0000, value=TypeValue(type=Bool, value=<Bool.false: 0>))])
2023-10-11 20:57:54.773 DEBUG (MainThread) [zigpy.zcl] [0xB9E9:1:0x0006] Attribute report received: on_off=<Bool.false: 0>
Technoholic84 commented 1 year ago

Ok thank you for analysing that. I don’t have a 9.3 backup I don’t think so I need to restore the 8.4, then upgrade to 9.3 and then enable debug logging at that time. It’s nighttime here now so the lights will be off soon anyway so I will get this done and then upload a log asap.

Thanks again

Technoholic84 commented 1 year ago

Hi again,

So I upgraded to 9.3 yesterday, and this morning turned the lights on, as predicted, switched off not long after. Here's the (big) log, and the turn off happened at 09:16 approx.

home-assistant_2023-10-12T10-37-33.699Z.log.zip

Technoholic84 commented 1 year ago

Sorry I just realised I maybe misread your request. Did you want a log from a version where the problem DOES NOT happen? If so I need to do that on 8.4

Technoholic84 commented 1 year ago

home-assistant_2023-10-12T16-35-53.917Z.log

Ok here's a log from a few hours of running 8.4 with the issue not happening

puddly commented 1 year ago

So, to confirm: 2023.8.4 works but 2023.9.3 is broken? What about 2023.9.2, .1, and .0?

There's no difference between the two that I can see, the plug just decides not to crash:

# Plug reports it is on
2023-10-12 16:06:38.230 DEBUG (MainThread) [zigpy.application] Received a packet: ZigbeePacket(src=AddrModeAddress(addr_mode=<AddrMode.NWK: 2>, address=0xB9E9), src_ep=1, dst=AddrModeAddress(addr_mode=<AddrMode.NWK: 2>, address=0x0000), dst_ep=1, source_route=None, extended_timeout=False, tsn=25, profile_id=260, cluster_id=6, data=Serialized[b'\x18\x08\n\x00\x00\x10\x01'], tx_options=<TransmitOptions.NONE: 0>, radius=0, non_member_radius=0, lqi=136, rssi=-66)
2023-10-12 16:06:38.231 DEBUG (MainThread) [zigpy.zcl] [0xB9E9:1:0x0006] Received ZCL frame: b'\x18\x08\n\x00\x00\x10\x01'
2023-10-12 16:06:38.231 DEBUG (MainThread) [zigpy.zcl] [0xB9E9: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=8, command_id=10, *direction=<Direction.Client_to_Server: 1>)
2023-10-12 16:06:38.232 DEBUG (MainThread) [zigpy.zcl] [0xB9E9:1:0x0006] Decoded ZCL frame: OnOff:Report_Attributes(attribute_reports=[Attribute(attrid=0x0000, value=TypeValue(type=Bool, value=<Bool.true: 1>))])
2023-10-12 16:06:38.232 DEBUG (MainThread) [zigpy.zcl] [0xB9E9:1:0x0006] Received command 0x0A (TSN 8): Report_Attributes(attribute_reports=[Attribute(attrid=0x0000, value=TypeValue(type=Bool, value=<Bool.true: 1>))])
2023-10-12 16:06:38.233 DEBUG (MainThread) [zigpy.zcl] [0xB9E9:1:0x0006] Attribute report received: on_off=<Bool.true: 1>

# A minute later, sends a match descriptor request to the coordinator, checking for an OTA cluster
2023-10-12 16:07:56.302 DEBUG (MainThread) [zigpy.application] Received a packet: ZigbeePacket(src=AddrModeAddress(addr_mode=<AddrMode.NWK: 2>, address=0xB9E9), src_ep=0, dst=AddrModeAddress(addr_mode=<AddrMode.NWK: 2>, address=0x0000), dst_ep=0, source_route=None, extended_timeout=False, tsn=27, profile_id=0, cluster_id=6, data=Serialized[b'K\x00\x00\x04\x01\x01\x19\x00\x00'], tx_options=<TransmitOptions.NONE: 0>, radius=0, non_member_radius=0, lqi=124, rssi=-69)
2023-10-12 16:07:56.303 DEBUG (MainThread) [zigpy.zdo] [0xb9e9:zdo] ZDO request ZDOCmd.Match_Desc_req: [0x0000, 260, [25], []]

# A second later, it asks for another OTA image
2023-10-12 16:07:57.345 DEBUG (MainThread) [zigpy.application] Received a packet: ZigbeePacket(src=AddrModeAddress(addr_mode=<AddrMode.NWK: 2>, address=0xB9E9), src_ep=1, dst=AddrModeAddress(addr_mode=<AddrMode.NWK: 2>, address=0x0000), dst_ep=1, source_route=None, extended_timeout=False, tsn=28, profile_id=260, cluster_id=25, data=Serialized[b'\x01\n\x01\x00\x86\x12\x03\x00\x05\x10\x00\x00'], tx_options=<TransmitOptions.NONE: 0>, radius=0, non_member_radius=0, lqi=120, rssi=-70)
2023-10-12 16:07:57.346 DEBUG (MainThread) [zigpy.zcl] [0xB9E9:1:0x0019] Received ZCL frame: b'\x01\n\x01\x00\x86\x12\x03\x00\x05\x10\x00\x00'
2023-10-12 16:07:57.346 DEBUG (MainThread) [zigpy.zcl] [0xB9E9:1:0x0019] Decoded ZCL frame header: ZCLHeader(frame_control=FrameControl(frame_type=<FrameType.CLUSTER_COMMAND: 1>, is_manufacturer_specific=0, direction=<Direction.Server_to_Client: 0>, disable_default_response=0, reserved=0, *is_cluster=True, *is_general=False), tsn=10, command_id=1, *direction=<Direction.Server_to_Client: 0>)
2023-10-12 16:07:57.347 DEBUG (MainThread) [zigpy.zcl] [0xB9E9:1:0x0019] Decoded ZCL frame: Ota:QueryNextImageCommand(field_control=<FieldControl: 0>, manufacturer_code=4742, image_type=3, current_file_version=4101)
2023-10-12 16:07:57.348 DEBUG (MainThread) [zigpy.zcl] [0xB9E9:1:0x0019] Received command 0x01 (TSN 10): QueryNextImageCommand(field_control=<FieldControl: 0>, manufacturer_code=4742, image_type=3, current_file_version=4101)
2023-10-12 16:07:57.349 DEBUG (MainThread) [zigpy.zcl] [0xB9E9:1:0x0019] OTA query_next_image handler for 'Sonoff SA-030-1': field_control=0, manufacturer_id=4742, image_type=3, current_file_version=4101, hardware_version=None, model='SA-030-1'

# We don't have one so we reply as such
2023-10-12 16:07:57.349 DEBUG (MainThread) [zigpy.zcl] [0xB9E9:1:0x0019] No OTA image is available
2023-10-12 16:07:57.350 DEBUG (MainThread) [zigpy.zcl] [0xB9E9:1:0x0019] Sending reply header: ZCLHeader(frame_control=FrameControl(frame_type=<FrameType.CLUSTER_COMMAND: 1>, is_manufacturer_specific=False, direction=<Direction.Client_to_Server: 1>, disable_default_response=1, reserved=0, *is_cluster=True, *is_general=False), tsn=10, command_id=2, *direction=<Direction.Client_to_Server: 1>)
2023-10-12 16:07:57.350 DEBUG (MainThread) [zigpy.zcl] [0xB9E9:1:0x0019] Sending reply: query_next_image_response(status=<Status.NO_IMAGE_AVAILABLE: 152>, manufacturer_code=None, image_type=None, file_version=None, image_size=None)

# 15 minutes later, the plug reports it is still on
2023-10-12 16:21:38.170 DEBUG (MainThread) [zigpy.application] Received a packet: ZigbeePacket(src=AddrModeAddress(addr_mode=<AddrMode.NWK: 2>, address=0xB9E9), src_ep=1, dst=AddrModeAddress(addr_mode=<AddrMode.NWK: 2>, address=0x0000), dst_ep=1, source_route=None, extended_timeout=False, tsn=29, profile_id=260, cluster_id=6, data=Serialized[b'\x18\x0b\n\x00\x00\x10\x01'], tx_options=<TransmitOptions.NONE: 0>, radius=0, non_member_radius=0, lqi=128, rssi=-68)
2023-10-12 16:21:38.171 DEBUG (MainThread) [zigpy.zcl] [0xB9E9:1:0x0006] Received ZCL frame: b'\x18\x0b\n\x00\x00\x10\x01'
2023-10-12 16:21:38.171 DEBUG (MainThread) [zigpy.zcl] [0xB9E9: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=11, command_id=10, *direction=<Direction.Client_to_Server: 1>)
2023-10-12 16:21:38.172 DEBUG (MainThread) [zigpy.zcl] [0xB9E9:1:0x0006] Decoded ZCL frame: OnOff:Report_Attributes(attribute_reports=[Attribute(attrid=0x0000, value=TypeValue(type=Bool, value=<Bool.true: 1>))])
2023-10-12 16:21:38.173 DEBUG (MainThread) [zigpy.zcl] [0xB9E9:1:0x0006] Received command 0x0A (TSN 11): Report_Attributes(attribute_reports=[Attribute(attrid=0x0000, value=TypeValue(type=Bool, value=<Bool.true: 1>))])
2023-10-12 16:21:38.173 DEBUG (MainThread) [zigpy.zcl] [0xB9E9:1:0x0006] Attribute report received: on_off=<Bool.true: 1>
Technoholic84 commented 1 year ago

I don’t know about 9.1, 9.2 etc, I went straight from 8.4 to 9.3.

But literally nothing changes in hardware, only the software changes. There is a reply from someone else saying the same thing happens to them too, above

puddly commented 1 year ago

I don't doubt it but there are a lot of changes in each release so if you can narrow it down to a specific one, that would be very helpful.

Technoholic84 commented 1 year ago

Ok, I’ll have to try that but it will take me a while. What versions exist between 8.4 and 9.3? Can I see the list somewhere?

Technoholic84 commented 1 year ago

ok I found the list. Here's a log from 9.2. It did the same almost immediately. home-assistant_zha_2023-10-13T20-20-43.332Z-9.2.log

I've just installed 9.1 so I'll see what happens

Technoholic84 commented 1 year ago

home-assistant_zha_2023-10-14T11-11-49.388Z-9.1.log

here's the log for 9.1, also happened twice in this log I think. So the problem started in 9.1 it seems, if there was nothing between 8.4 and 9.1, which I can't find

zwack-am commented 1 year ago

I have a different Zigbee plug with what sounds like the same issue.

Device info CK-BL702-MSW-01(7010) by eWeLink Firmware: 0x00000001 Zigbee info IEEE: a8:17:10:b7:76:fd:00:00 Nwk: 0x5de8 Device Type: Router LQI: 164 RSSI: -59 Last seen: 2023-10-15T22:21:32 Power source: Mains

It turns off either 30 or 40 minutes after it is turned on.

I have just turned debug on zha

Technoholic84 commented 1 year ago

Ewelink is the same manufacturer as mine although it reports as a Sonoff. So could be related. @puddly and luck with looking at all the logs?

MattWestb commented 1 year ago

@puddly Ewelink / Sonoff with modern chips wad not having working OTA implanted for some device then they must updating them in the factory and user was getting updated ones. If this device is the same is it possible blocking OTA requests to the device so it not crashing ?

puddly commented 1 year ago

Of course. There were no real changes between 2023.8.x and 2023.9.x with radio libraries so I'd like to figure out where the regression happened and why the newer version's "there is no OTA image" response is causing it to crash.

Technoholic84 commented 1 year ago

Hi there, is there any update on this at all?

Technoholic84 commented 1 year ago

Hi @puddly i see this issue is closed now. Which is good, but Can someone explain how it was fixed and what the problem was? Thanks!

crameth commented 1 year ago

Had the same issue. Mine was about every 6-7 minutes on... you guessed it, Woolley smart plugs.

Using the dev release for HA Docker fixed the issue for me (2023.11.0). Prior to this I was using stable (2023.10.3), which I think was already identified as a problematic version on this thread.

Hope this helps.

EDIT: Thanks for bringing this up @Technoholic84, was crawling the internet in search of a solution and almost demanded a refund for the "faulty" plugs.

Technoholic84 commented 1 year ago

Had the same issue. Mine was about every 6-7 minutes on... you guessed it, Woolley smart plugs.

Using the dev release for HA Docker fixed the issue for me (2023.11.0). Prior to this I was using stable (2023.10.3), which I think was already identified as a problematic version on this thread.

Hope this helps.

EDIT: Thanks for bringing this up @Technoholic84, was crawling the internet in search of a solution and almost demanded a refund for the "faulty" plugs.

Thanks for sharing, I will try upgrading to the dev release later, see if that helps. I dont seem to be able to find a 10.4 beta which would be preferable but glad your issue is fixed, let's hope it does it for me too!

crameth commented 1 year ago

Sorry, I jumped the gun. My plugs are still turning themselves off with the latest version :/

I might want to downgrade if that's the case, see if it fixes the issue.

Technoholic84 commented 1 year ago

Yep I upgraded to 11.0 and it still happened. It looks like the fix, if it works, was put into 10.4 but I can’t find a way to install that

joostlek commented 1 year ago

10.4 will be released tomorrow

Technoholic84 commented 1 year ago

Ah that’s great. I assume this fix is in that version?

joostlek commented 1 year ago

The PR that closed this issue is in there. But this PR is also in 2023.11, so if you have issues on dev, it most likely won't be fixed by the next release

Technoholic84 commented 1 year ago

Oh that’s a shame. Yes it’s not working in 2023.11, turns off as it always has.

joostlek commented 1 year ago

I'll reopen the issue then

Technoholic84 commented 1 year ago

Thank you very much

puddly commented 1 year ago

I'll order a few of these plugs to test, as I'm out of ideas otherwise. Hopefully the US version has the same problem.