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
72.18k stars 30.21k forks source link

ZHA: Lots of logs in a very short time. #49696

Closed f45tb00t closed 3 years ago

f45tb00t commented 3 years ago

The problem

Hello,

actually I'm migrating from my PI 3 B+ to a mini pc. Before I used a USB Dongle for zigbee, now I am using the Sonoff Zigbee Bridge with tasmota.

I realized that I get a whole lot of logs in a very short period of time. Means the logfile is flooded. The logs look fine to me, but I have no idea why they are generated in such a massive way.

What is version of Home Assistant Core has the issue?

2021.04.06

What was the last working version of Home Assistant Core?

none - clean install with recent version

What type of installation are you running?

Home Assistant Core

Integration causing the issue

ZHA

Link to integration documentation on our website

https://www.home-assistant.io/integrations/zha/

Example YAML snippet

No response

Anything in the logs that might be useful for us?

2021-04-26 08:53:22 DEBUG (bellows.thread_0) [bellows.uart] Data frame: b'rth456u6356utzj099874e1de6b88f47e3f97eacad'
2021-04-26 08:53:22 DEBUG (bellows.thread_0) [bellows.uart] Sending: b'80fgh4587e'
2021-04-26 08:53:22 DEBUG (MainThread) [bellows.ezsp.protocol] Application frame 69 (incomingMessageHandler) received: b'tghsrthsrthsrthrth5656685886004000021862a0240002000'
2021-04-26 08:53:22 DEBUG (MainThread) [bellows.zigbee.application] Received incomingMessageHandler frame with [<EmberIncomingMessageType.INCOMING_UNICAST: 0>, EmberApsFrame(profileId=260, clusterId=768, sourceEndpoint=11, destinationEndpoint=11, options=<EmberApsOption.APS_OPTION_ENABLE_ROUTE_DISCOVERY: 256>, groupId=0, sequence=184), 196, -51, 0xc7da, 255, 255, b'*REMOVED*']
2021-04-26 08:53:22 DEBUG (MainThread) [zigpy.zcl] [*REMOVED*:11:*REMOVED*] ZCL deserialize: <ZCLHeader frame_control=<FrameControl frame_type=GLOBAL_COMMAND manufacturer_specific=False is_reply=True disable_default_response=True> manufacturer=None tsn=8 command_id=Command.Read_Attributes_rsp>
2021-04-26 08:53:29 DEBUG (MainThread) [bellows.ezsp.protocol] Send command nop: ()
2021-04-26 08:53:29 DEBUG (bellows.thread_0) [bellows.uart] Sending: b'*REMOVED*'
2021-04-26 08:53:29 DEBUG (bellows.thread_0) [bellows.uart] Data frame: b'00eca1a9512ab95e7e'
2021-04-26 08:53:29 DEBUG (bellows.thread_0) [bellows.uart] Sending: b'*REMOVED*'
2021-04-26 08:53:29 DEBUG (MainThread) [bellows.ezsp.protocol] Application frame 5 (nop) received: b''
2021-04-26 08:53:33 DEBUG (MainThread) [homeassistant.components.zha.entity] light.philips_iris_1_schlafzimmer_links_level_light_color_on_off: polling current state
2021-04-26 08:53:33 DEBUG (MainThread) [bellows.ezsp.protocol] Send command sendUnicast: (<EmberOutgoingMessageType.OUTGOING_DIRECT: 0>, 0x516B, EmberApsFrame(profileId=260, clusterId=6, sourceEndpoint=11, destinationEndpoint=11, options=<EmberApsOption.APS_OPTION_ENABLE_ROUTE_DISCOVERY|APS_OPTION_RETRY: 320>, groupId=0, sequence=10), 11, b'*REMOVED*')
2021-04-26 08:53:33 DEBUG (bellows.thread_0) [bellows.uart] Sending: b'*REMOVED*'
2021-04-26 08:53:33 DEBUG (bellows.thread_0) [bellows.uart] Data frame: b'11eda1a9602a15d1a02f7e'
2021-04-26 08:53:33 DEBUG (bellows.thread_0) [bellows.uart] Sending: b'8*REMOVED*e'
2021-04-26 08:53:33 DEBUG (MainThread) [bellows.ezsp.protocol] Application frame 52 (sendUnicast) received: b'0063'
2021-04-26 08:53:33 DEBUG (bellows.thread_0) [bellows.uart] Data frame: b'*REMOVED*'
2021-04-26 08:53:33 DEBUG (bellows.thread_0) [bellows.uart] Sending: b'*REMOVED*'
2021-04-26 08:53:33 DEBUG (bellows.thread_0) [bellows.uart] Data frame: b'*REMOVED*'
2021-04-26 08:53:33 DEBUG (bellows.thread_0) [bellows.uart] Sending: b'*REMOVED*'
2021-04-26 08:53:33 DEBUG (MainThread) [bellows.ezsp.protocol] Application frame 63 (messageSentHandler) received: b'*REMOVED*'
2021-04-26 08:53:33 DEBUG (MainThread) [bellows.zigbee.application] Received messageSentHandler frame with [<EmberOutgoingMessageType.OUTGOING_DIRECT: 0>, 20843, EmberApsFrame(profileId=260, clusterId=6, sourceEndpoint=11, destinationEndpoint=11, options=<EmberApsOption.APS_OPTION_ENABLE_ROUTE_DISCOVERY|APS_OPTION_RETRY: 320>, groupId=0, sequence=99), 11, <EmberStatus.SUCCESS: 0>, b'']
2021-04-26 08:53:33 DEBUG (MainThread) [bellows.ezsp.protocol] Application frame 69 (incomingMessageHandler) received: b'0*REMOVED*'
2021-04-26 08:53:33 DEBUG (MainThread) [bellows.zigbee.application] Received incomingMessageHandler frame with [<EmberIncomingMessageType.INCOMING_UNICAST: 0>, EmberApsFrame(profileId=260, clusterId=6, sourceEndpoint=11, destinationEndpoint=11, options=<EmberApsOption.APS_OPTION_ENABLE_ROUTE_DISCOVERY: 256>, groupId=0, sequence=95), 124, -69, 0x516b, 255, 255, b'*REMOVED*']
2021-04-26 08:53:33 DEBUG (MainThread) [zigpy.zcl] [0x516b:11:0x0006] ZCL deserialize: <ZCLHeader frame_control=<FrameControl frame_type=GLOBAL_COMMAND manufacturer_specific=False is_reply=True disable_default_response=True> manufacturer=None tsn=10 command_id=Command.Read_Attributes_rsp>
2021-04-26 08:53:33 DEBUG (MainThread) [bellows.ezsp.protocol] Send command sendUnicast: (<EmberOutgoingMessageType.OUTGOING_DIRECT: 0>, 0x516B, EmberApsFrame(profileId=260, clusterId=8, sourceEndpoint=11, destinationEndpoint=11, options=<EmberApsOption.APS_OPTION_ENABLE_ROUTE_DISCOVERY|APS_OPTION_RETRY: 320>, groupId=0, sequence=12), 13, b'*REMOVED*')
2021-04-26 08:53:33 DEBUG (bellows.thread_0) [bellows.uart] Sending: b'*REMOVED*'
2021-04-26 08:53:33 DEBUG (bellows.thread_0) [bellows.uart] Data frame: b'42f2a1a9602a15d66e4b7e'
2021-04-26 08:53:33 DEBUG (bellows.thread_0) [bellows.uart] Sending: b'*REMOVED*'
2021-04-26 08:53:33 DEBUG (MainThread) [bellows.ezsp.protocol] Application frame 52 (sendUnicast) received: b'*REMOVED*'
2021-04-26 08:53:33 DEBUG (bellows.thread_0) [bellows.uart] Data frame: b'*REMOVED*'
2021-04-26 08:53:33 DEBUG (bellows.thread_0) [bellows.uart] Sending: b'*REMOVED*'
2021-04-26 08:53:33 DEBUG (MainThread) [bellows.ezsp.protocol] Application frame 63 (messageSentHandler) received: b'*REMOVED*'
2021-04-26 08:53:33 DEBUG (MainThread) [bellows.zigbee.application] Received messageSentHandler frame with [<EmberOutgoingMessageType.OUTGOING_DIRECT: 0>, 20843, EmberApsFrame(profileId=260, clusterId=8, sourceEndpoint=11, destinationEndpoint=11, options=<EmberApsOption.APS_OPTION_ENABLE_ROUTE_DISCOVERY|APS_OPTION_RETRY: 320>, groupId=0, sequence=100), 13, <EmberStatus.SUCCESS: 0>, b'']
2021-04-26 08:53:33 DEBUG (bellows.thread_0) [bellows.uart] Data frame: b'6*REMOVED*e'
2021-04-26 08:53:33 DEBUG (bellows.thread_0) [bellows.uart] Sending: b'*REMOVED*e'
2021-04-26 08:53:33 DEBUG (MainThread) [bellows.ezsp.protocol] Application frame 69 (incomingMessageHandler) received: b'*REMOVED*'
2021-04-26 08:53:33 DEBUG (MainThread) [bellows.zigbee.application] Received incomingMessageHandler frame with [<EmberIncomingMessageType.INCOMING_UNICAST: 0>, EmberApsFrame(profileId=260, clusterId=8, sourceEndpoint=11, destinationEndpoint=11, options=<EmberApsOption.APS_OPTION_ENABLE_ROUTE_DISCOVERY: 256>, groupId=0, sequence=96), *REMOVED*']
2021-04-26 08:53:33 DEBUG (MainThread) [zigpy.zcl] [0x516b:11:0x0008] ZCL deserialize: <ZCLHeader frame_control=<FrameControl frame_type=GLOBAL_COMMAND manufacturer_specific=False is_reply=True disable_default_response=True> manufacturer=None tsn=12 command_id=Command.Read_Attributes_rsp>
2021-04-26 08:53:33 DEBUG (MainThread) [homeassistant.components.zha.core.channels.base] [0x516B:11:0x0008]: received attribute: 0 update with value: 254
2021-04-26 08:53:33 DEBUG (MainThread) [bellows.ezsp.protocol] Send command sendUnicast: (<EmberOutgoingMessageType.OUTGOING_DIRECT: 0>, 0x516B, EmberApsFrame(profileId=260, clusterId=768, sourceEndpoint=11, destinationEndpoint=11, options=<EmberApsOption.APS_OPTION_ENABLE_ROUTE_DISCOVERY|APS_OPTION_RETRY: 320>, groupId=0, sequence=14), 15, b'*REMOVED*')
2021-04-26 08:53:33 DEBUG (bellows.thread_0) [bellows.uart] Sending: b'*REMOVED*'
2021-04-26 08:53:34 DEBUG (bellows.thread_0) [bellows.uart] Data frame: b'*REMOVED*'
2021-04-26 08:53:34 DEBUG (bellows.thread_0) [bellows.uart] Sending: b'*REMOVED*'
2021-04-26 08:53:34 DEBUG (MainThread) [bellows.ezsp.protocol] Application frame 52 (sendUnicast) received: b'0065'
2021-04-26 08:53:34 DEBUG (bellows.thread_0) [bellows.uart] Data frame: b'*REMOVED*'
2021-04-26 08:53:34 DEBUG (bellows.thread_0) [bellows.uart] Sending: b'8*REMOVED*e'
2021-04-26 08:53:34 DEBUG (MainThread) [bellows.ezsp.protocol] Application frame 63 (messageSentHandler) received: b'*REMOVED*'
2021-04-26 08:53:34 DEBUG (MainThread) [bellows.zigbee.application] Received messageSentHandler frame with [<EmberOutgoingMessageType.OUTGOING_DIRECT: 0>, 20843, EmberApsFrame(profileId=260, clusterId=768, sourceEndpoint=11, destinationEndpoint=11, options=<EmberApsOption.APS_OPTION_ENABLE_ROUTE_DISCOVERY|APS_OPTION_RETRY: 320>, groupId=0, sequence=101), 15, <EmberStatus.SUCCESS: 0>, b'']
2021-04-26 08:53:34 DEBUG (bellows.thread_0) [bellows.uart] Data frame: b'*REMOVED*'
2021-04-26 08:53:34 DEBUG (bellows.thread_0) [bellows.uart] Sending: b'82503a7e'
2021-04-26 08:53:34 DEBUG (MainThread) [bellows.ezsp.protocol] Application frame 69 (incomingMessageHandler) received: b'*REMOVED*'
2021-04-26 08:53:34 DEBUG (MainThread) [bellows.zigbee.application] Received incomingMessageHandler frame with [<EmberIncomingMessageType.INCOMING_UNICAST: 0>, EmberApsFrame(profileId=260, clusterId=768, sourceEndpoint=11, destinationEndpoint=11, options=<EmberApsOption.APS_OPTION_ENABLE_ROUTE_DISCOVERY: 256>, groupId=0, sequence=97), 148, -63, 0x516b, 255, 255, b'*REMOVED**REMOVED*']
2021-04-26 08:53:34 DEBUG (MainThread) [zigpy.zcl] [0x516b:11:0x0300] ZCL deserialize: <ZCLHeader frame_control=<FrameControl frame_type=GLOBAL_COMMAND manufacturer_specific=False is_reply=True disable_default_response=True> manufacturer=None tsn=14 command_id=Command.Read_Attributes_rsp>
2021-04-26 08:53:35 DEBUG (bellows.thread_0) [bellows.uart] Data frame: b'*REMOVED*'
2021-04-26 08:53:35 DEBUG (bellows.thread_0) [bellows.uart] Sending: b'83401b7e'
2021-04-26 08:53:35 DEBUG (MainThread) [bellows.ezsp.protocol] Application frame 69 (incomingMessageHandler) received: b'*REMOVED*'
2021-04-26 08:53:35 DEBUG (MainThread) [bellows.zigbee.application] Received incomingMessageHandler frame with [<EmberIncomingMessageType.INCOMING_UNICAST: 0>, EmberApsFrame(profileId=260, clusterId=25, sourceEndpoint=1, destinationEndpoint=1, options=<EmberApsOption.APS_OPTION_ENABLE_ROUTE_DISCOVERY|APS_OPTION_RETRY: 320>, groupId=0, sequence=82), 112, -72, *REMOVED*']
2021-04-26 08:53:35 DEBUG (MainThread) [zigpy.zcl] [0x48f1:1:0x0019] ZCL deserialize: <ZCLHeader frame_control=<FrameControl frame_type=CLUSTER_COMMAND manufacturer_specific=False is_reply=False disable_default_response=False> manufacturer=None tsn=223 command_id=1>
2021-04-26 08:53:35 DEBUG (MainThread) [zigpy.zcl] [*REMOVED*] ZCL request 0x0001: [0, 4454, 272, 268768615, None]
2021-04-26 08:53:35 DEBUG (MainThread) [zigpy.zcl] [*REMOVED*] OTA query_next_image handler for 'innr RS 225': field_control=0, manufacture_id=4454, image_type=272, current_file_version=268768615, hardware_version=None
2021-04-26 08:53:35 DEBUG (MainThread) [zigpy.zcl] [0*REMOVED*9] No OTA image is available
2021-04-26 08:53:35 DEBUG (MainThread) [bellows.ezsp.protocol] Send command sendUnicast: (<EmberOutgoingMessageType.OUTGOING_DIRECT: 0>, 0x48F1, EmberApsFrame(profileId=260, clusterId=25, sourceEndpoint=1, destinationEndpoint=1, options=<EmberApsOption.APS_OPTION_ENABLE_ROUTE_DISCOVERY|APS_OPTION_RETRY: 320>, groupId=0, sequence=223), 16, *REMOVED*)
2021-04-26 08:53:35 DEBUG (bellows.thread_0) [bellows.uart] Sending: b'*REMOVED*'
2021-04-26 08:53:36 DEBUG (bellows.thread_0) [bellows.uart] Data frame: b'34f0a1a9602a15d41e2d7e'
2021-04-26 08:53:36 DEBUG (bellows.thread_0) [bellows.uart] Sending: b'8430fc7e'
2021-04-26 08:53:36 DEBUG (MainThread) [bellows.ezsp.protocol] Application frame 52 (sendUnicast) received: b'0066'
2021-04-26 08:53:36 DEBUG (bellows.thread_0) [bellows.uart] Data frame: b'4*REMOVED*'
2021-04-26 08:53:36 DEBUG (bellows.thread_0) [bellows.uart] Sending: b'8*REMOVED*e'
2021-04-26 08:53:36 DEBUG (MainThread) [bellows.ezsp.protocol] Application frame 63 (messageSentHandler) received: b'0*REMOVED*0'
2021-04-26 08:53:36 DEBUG (MainThread) [bellows.zigbee.application] Received messageSentHandler frame with [<EmberOutgoingMessageType.OUTGOING_DIRECT: 0>, 18673, EmberApsFrame(profileId=260, clusterId=25, sourceEndpoint=1, destinationEndpoint=1, options=<EmberApsOption.APS_OPTION_ENABLE_ROUTE_DISCOVERY|APS_OPTION_RETRY: 320>, groupId=0, sequence=102), 16, <EmberStatus.SUCCESS: 0>, b'']
2021-04-26 08:53:39 DEBUG (MainThread) [bellows.ezsp.protocol] Send command nop: ()
2021-04-26 08:53:39 DEBUG (bellows.thread_0) [bellows.uart] Sending: b'4*REMOVED*
2021-04-26 08:53:39 DEBUG (bellows.thread_0) [bellows.uart] Data frame: b'55f1a1a9512aafeb7e'
2021-04-26 08:53:39 DEBUG (bellows.thread_0) [bellows.uart] Sending: b'*REMOVED*'
2021-04-26 08:53:39 DEBUG (MainThread) [bellows.ezsp.protocol] Application frame 5 (nop) received: b''
2021-04-26 08:53:49 DEBUG (MainThread) [bellows.ezsp.protocol] Send command nop: ()
2021-04-26 08:53:49 DEBUG (bellows.thread_0) [bellows.uart] Sending: b*REMOVED*'
2021-04-26 08:53:49 DEBUG (bellows.thread_0) [bellows.uart] Data frame: b'6*REMOVED*e'
2021-04-26 08:53:49 DEBUG (bellows.thread_0) [bellows.uart] Sending: b'87009f7e'
2021-04-26 08:53:49 DEBUG (MainThread) [bellows.ezsp.protocol] Application frame 5 (nop) received: b''
2021-04-26 08:53:59 DEBUG (MainThread) [bellows.ezsp.protocol] Send command nop: ()
2021-04-26 08:53:59 DEBUG (bellows.thread_0) [bellows.uart] Sending: b'6*REMOVED*'
2021-04-26 08:54:00 DEBUG (bellows.thread_0) [bellows.uart] Data frame: b'*REMOVED*'
2021-04-26 08:54:00 DEBUG (bellows.thread_0) [bellows.uart] Sending: b'8070787e'
2021-04-26 08:54:00 DEBUG (MainThread) [bellows.ezsp.protocol] Application frame 5 (nop) received: b''

Additional information

The Bridge is using v9.4.0 of tasmota. I reconfigured it to listen on port 8888 and connected ZHA to it. I added the bridge as followed in HA

HardwareDevice: Silicon Labs EZSP Connection via tcp to: :8888 Data flow control: software (hope that was correct?)

@puddly @Adminiuga: Hope they settings were correct? or do they cause this massive flood of logs?

Adminiuga commented 3 years ago

Disable debug logging.

f45tb00t commented 3 years ago

where? I haven't enable it?

edit: i added now logger: default: warn But its weird that it logged so much. Coze I never set up debug logging anywhere.. weird.

Adminiuga commented 3 years ago

does it still debug after restart?

f45tb00t commented 3 years ago

yes it did. now with the logger setting I dont see it anymore. But when I remove it and reboot it will start again to spam my logs file

puddly commented 3 years ago

ZHA does temporarily enable debug logging when permitting joins and I think when you click the "reconfigure" button on a device's page. Did you recently do either of those things?

f45tb00t commented 3 years ago

Hi @puddly

nice to talk to you again.

Yes I did that. Because I migrated all devices from the PI and its USB Stick to my new Mini PC and the connected Sonoff Bridge.

But even after all devices were added and I rebooted the system several times the logspam continued. I haven't added new devices now for several days. Let me try to remove logger option again from my config, restart HA and see what happens.

I'll keep you posted

MattWestb commented 3 years ago

Its some bugs in the "reconfigure device" that is being fixed and coming in the next release. Also it can being the one reconfigure is being repeated in the background and is not successful and is continuing trying do it all the time also after restarting AH.

I hope David have getting all things in right place and its working well :-))

f45tb00t commented 3 years ago

Hi,

the logs were gone for a short while. Yesterday I need to readd an Aqare Temperature Sensor, because it was not responding anymore. Now I have the logflood again. So yes I added a new device, but yesterday evening. The logflood continues.

Lets see if the new version fix that :)

f45tb00t commented 3 years ago

rebooted the machine now. flooding is gone, but this 2021-05-04 15:05:13 ERROR (MainThread) [homeassistant.components.websocket_api.http.connection] [139684149026768] Received invalid command: zha/devices/reconfigure 2021-05-04 15:05:13 ERROR (MainThread) [homeassistant.components.websocket_api.http.connection] [139684149026768] Received invalid command: zha/devices/reconfigure

MattWestb commented 3 years ago

I have the same problem that "reconfigure" is running also after one reboot but can also going away by it self. Wait some days and you can trying the new version in HA 2021.05

f45tb00t commented 3 years ago

@MattWestb "Reconfigure" = add device?

So this means its also the same when I click any device and hit the "reconfigure" button?

MattWestb commented 3 years ago

Nop !! From the device card "reconfigure device".

If you like you can installing the HA beat that is released but i have not looking on it i waiting for the real release.

dmulcahey commented 3 years ago

It releases tomorrow… I’d just wait

MattWestb commented 3 years ago

Thanks David and i hope you have getting all right ! And one more "patch day" in the pipe :-)))

f45tb00t commented 3 years ago

Nop !! From the device card "reconfigure device".

If you like you can installing the HA beat that is released but i have not looking on it i waiting for the real release.

So I guess then its a different issue. Because the spam starts also for me when I add new devices and do not hit the "reconfigure" button at all.

Adminiuga commented 3 years ago

Upgrade to beta or wait for new release

github-actions[bot] commented 3 years ago

There hasn't been any activity on this issue recently. Due to the high number of incoming GitHub notifications, we have to clean some of the old issues, as many of them have already been resolved with the latest updates. Please make sure to update to the latest Home Assistant version and check if that solves the issue. Let us know if that works for you by adding a comment 👍 This issue has now been marked as stale and will be closed if no further activity occurs. Thank you for your contributions.