Updating zha_new light took longer than the scheduled update interval

[walthowd]

HomeAssistant v0.63.1, latest master-0.61.plus zha_new, latest master of yoda-x/bellows release.

Every thirty seconds I receive the "Updating zha_new light took longer than the scheduled update interval 0:00:30" and this event is always preceded by the below log entries. This happens at all times, even when I'm not sending any on/off commands to any devices.

2018-02-12 19:23:18 DEBUG (MainThread) [bellows.uart] Data frame: b'6350b1ed502a15b459944a2dab5592d063f1ce8012316ec300396788fd673fa790567e'
2018-02-12 19:23:18 DEBUG (MainThread) [bellows.uart] Sending: b'87009f7e'
2018-02-12 19:23:18 DEBUG (MainThread) [bellows.zigbee.zdo] [0x2be9:zdo] ZDO request 0x0006: [65533, 260, [25], []]
2018-02-12 19:23:18 DEBUG (MainThread) [bellows.ezsp] Application frame 69 (incomingMessageHandler) received: [<EmberIncomingMessageType.INCOMING_BROADCAST: 4>, <EmberApsFrame profileId=0 clusterId=6 sourceEndpoint=0 destinationEndpoint=0 options=264 groupId=0 sequence=153>, 255, -65, 11241, 255, 255, b'H\xfd\xff\x04\x01\x01\x19\x00\x00']
2018-02-12 19:23:18 DEBUG (MainThread) [bellows.ezsp] Send command sendUnicast
2018-02-12 19:23:19 DEBUG (MainThread) [bellows.uart] Sending: b'3751219c54c33eb25992ca25aa1593499c3a53ad99ce678bfcc7718e7e'
2018-02-12 19:23:19 DEBUG (MainThread) [bellows.uart] Data frame: b'7451a19c549fd3f97e'
2018-02-12 19:23:19 DEBUG (MainThread) [bellows.uart] Sending: b'8070787e'
2018-02-12 19:23:19 DEBUG (MainThread) [bellows.ezsp] Application frame 52 (sendUnicast) received: [<EmberStatus.SUCCESS: 0>, 181]
2018-02-12 19:23:19 DEBUG (MainThread) [bellows.uart] Data frame: b'0451b19754c33eb25992ca25aa1593499cfb53abed547b7e'
2018-02-12 19:23:19 DEBUG (MainThread) [bellows.uart] Sending: b'8160597e'
2018-02-12 19:23:19 DEBUG (MainThread) [bellows.ezsp] Application frame 63 (messageSentHandler) received: [<EmberOutgoingMessageType.OUTGOING_DIRECT: 0>, 11241, <EmberApsFrame profileId=0 clusterId=32774 sourceEndpoint=0 destinationEndpoint=0 options=320 groupId=0 sequence=181>, 116, <EmberStatus.SUCCESS: 0>, b'']
2018-02-12 19:23:20 DEBUG (MainThread) [bellows.uart] Data frame: b'1451b1ed542e14ab59954b65aa5592d361f1ce8012316b8abcc763e9ed7d3fa4ebcddec8f67e'
2018-02-12 19:23:20 DEBUG (MainThread) [bellows.uart] Sending: b'82503a7e'
2018-02-12 19:23:20 DEBUG (MainThread) [bellows.zigbee.zcl] [0x2be9:1:0x0019] ZCL request 0x0101: [0, 4448, 3, 3, 0]
2018-02-12 19:23:20 DEBUG (MainThread) [bellows.zigbee.zcl] [0x2be9:1:0x0019] No handler for cluster command 1
2018-02-12 19:23:20 DEBUG (MainThread) [bellows.ezsp] Application frame 69 (incomingMessageHandler) received: [<EmberIncomingMessageType.INCOMING_UNICAST: 0>, <EmberApsFrame profileId=260 clusterId=25 sourceEndpoint=1 destinationEndpoint=1 options=64 groupId=0 sequence=154>, 253, -65, 11241, 255, 255, b'\x01A\x01\x00`\x11\x03\x00\x03\x00\x00\x00']
2018-02-12 19:23:23 DEBUG (MainThread) [bellows.uart] Data frame: b'2451b1ed542e14ab59954b65aa5592d263f1ce8012316b8abfc763e9ed7d3fa4ebcdde1d1a7e'
2018-02-12 19:23:23 DEBUG (MainThread) [bellows.uart] Sending: b'83401b7e'
2018-02-12 19:23:23 DEBUG (MainThread) [bellows.zigbee.zcl] [0x2be9:1:0x0019] ZCL request 0x0101: [0, 4448, 3, 3, 0]
2018-02-12 19:23:23 DEBUG (MainThread) [bellows.zigbee.zcl] [0x2be9:1:0x0019] No handler for cluster command 1
2018-02-12 19:23:23 DEBUG (MainThread) [bellows.ezsp] Application frame 69 (incomingMessageHandler) received: [<EmberIncomingMessageType.INCOMING_UNICAST: 0>, <EmberApsFrame profileId=260 clusterId=25 sourceEndpoint=1 destinationEndpoint=1 options=64 groupId=0 sequence=155>, 255, -65, 11241, 255, 255, b'\x01B\x01\x00`\x11\x03\x00\x03\x00\x00\x00']
2018-02-12 19:23:26 DEBUG (MainThread) [bellows.uart] Data frame: b'3451b1ed542e14ab59954b65aa5592d563f1ce8012316b8abec763e9ed7d3fa4ebcdde5edc7e'
2018-02-12 19:23:26 DEBUG (MainThread) [bellows.uart] Sending: b'8430fc7e'
2018-02-12 19:23:26 DEBUG (MainThread) [bellows.zigbee.zcl] [0x2be9:1:0x0019] ZCL request 0x0101: [0, 4448, 3, 3, 0]
2018-02-12 19:23:26 DEBUG (MainThread) [bellows.zigbee.zcl] [0x2be9:1:0x0019] No handler for cluster command 1
2018-02-12 19:23:26 DEBUG (MainThread) [bellows.ezsp] Application frame 69 (incomingMessageHandler) received: [<EmberIncomingMessageType.INCOMING_UNICAST: 0>, <EmberApsFrame profileId=260 clusterId=25 sourceEndpoint=1 destinationEndpoint=1 options=64 groupId=0 sequence=156>, 255, -65, 11241, 255, 255, b'\x01C\x01\x00`\x11\x03\x00\x03\x00\x00\x00']
2018-02-12 19:23:29 DEBUG (MainThread) [bellows.uart] Data frame: b'4451b1ed542e14ab59954b65aa5592d462f1ce8012316b8ab9c763e9ed7d3fa4ebcddee62f7e'
2018-02-12 19:23:29 DEBUG (MainThread) [bellows.uart] Sending: b'8520dd7e'
2018-02-12 19:23:29 DEBUG (MainThread) [bellows.zigbee.zcl] [0x2be9:1:0x0019] ZCL request 0x0101: [0, 4448, 3, 3, 0]
2018-02-12 19:23:29 DEBUG (MainThread) [bellows.zigbee.zcl] [0x2be9:1:0x0019] No handler for cluster command 1
2018-02-12 19:23:29 DEBUG (MainThread) [bellows.ezsp] Application frame 69 (incomingMessageHandler) received: [<EmberIncomingMessageType.INCOMING_UNICAST: 0>, <EmberApsFrame profileId=260 clusterId=25 sourceEndpoint=1 destinationEndpoint=1 options=64 groupId=0 sequence=157>, 254, -65, 11241, 255, 255, b'\x01D\x01\x00`\x11\x03\x00\x03\x00\x00\x00']
2018-02-12 19:23:32 DEBUG (MainThread) [bellows.uart] Data frame: b'5451b1ed542e14ab59954b65aa5592d763f1ce8012316b8ab8c763e9ed7d3fa4ebcddead3a7e'
2018-02-12 19:23:32 DEBUG (MainThread) [bellows.uart] Sending: b'8610be7e'
2018-02-12 19:23:32 DEBUG (MainThread) [bellows.zigbee.zcl] [0x2be9:1:0x0019] ZCL request 0x0101: [0, 4448, 3, 3, 0]
2018-02-12 19:23:32 DEBUG (MainThread) [bellows.zigbee.zcl] [0x2be9:1:0x0019] No handler for cluster command 1
2018-02-12 19:23:32 DEBUG (MainThread) [bellows.ezsp] Application frame 69 (incomingMessageHandler) received: [<EmberIncomingMessageType.INCOMING_UNICAST: 0>, <EmberApsFrame profileId=260 clusterId=25 sourceEndpoint=1 destinationEndpoint=1 options=64 groupId=0 sequence=158>, 255, -65, 11241, 255, 255, b'\x01E\x01\x00`\x11\x03\x00\x03\x00\x00\x00']
2018-02-12 19:23:45 WARNING (MainThread) [homeassistant.components.light] Updating zha_new light took longer than the scheduled update interval 0:00:30
2018-02-12 19:23:45 INFO (MainThread) [homeassistant.core] Bus:Handling <Event system_log_event[L]: timestamp=1518485025.2593348, level=WARNING, message=Updating zha_new light took longer than the scheduled update interval 0:00:30, exception=, source=helpers/entity_platform.py>
2018-02-12 19:23:45 DEBUG (MainThread) [homeassistant.components.api] STREAM 4572415504 FORWARDING <Event system_log_event[L]: timestamp=1518485025.2593348, level=WARNING, message=Updating zha_new light took longer than the scheduled update interval 0:00:30, exception=, source=helpers/entity_platform.py>
2018-02-12 19:23:45 DEBUG (MainThread) [homeassistant.components.api] STREAM 4572415504 WRITING data: {"event_type": "system_log_event", "data": {"timestamp": 1518485025.2593348, "level": "WARNING", "message": "Updating zha_new light took longer than the scheduled update interval 0:00:30", "exception": "", "source": "helpers/entity_platform.py"}, "origin": "LOCAL", "time_fired": "2018-02-13T01:23:45.261143+00:00"}

[walthowd]

Bellows devices attached.

bellows-devices.txt

[Yoda-x]

With HA 0.63 you pulled also bellows/zigbee 0.50+ You can try if the build-in zha+bellows works for you and switch away from my spin-off or downgrade bellows to 0.40. But mixing both not works

[Yoda-x]

Sorry, I misread your ticket. What comes every 30 sec? And why not just disable debugging? This comes from a device asking for an OTA upgrade. 2018-02-12 19:23:32 DEBUG (MainThread) [bellows.zigbee.zcl] [0x2be9:1:0x0019] ZCL request 0x0101: [0, 4448, 3, 3, 0] 2018-02-12 19:23:32 DEBUG (MainThread) [bellows.zigbee.zcl] [0x2be9:1:0x0019] No handler for cluster command 1 Are you sure this is new and the device is properly paired? If yes to both, can you rejoin it. Also what kind of device is it?

Many thanks

[Yoda-x]

Just reading you ticket again. Sorry. But is the bulb powered on? Are you able to switch the light on and off for this bulb? I need to catch the error and send something like "state unknow" to HA for bulbs that not answer anymore. Thus, it's easier to see, which ones loose the network

[walthowd]

Do you see the IEEE ID of the device in the log? I'm missing it, but can start turning devices off to find what is misbehaving.

[walthowd]

Looks like the "ZCL request 0x0101: [0, 4448, 3, 3, 0]" is coming from two SmartThings multi sensors (24:fd:5b:00:01:04:01:b2 & 24:fd:5b:00:01:04:01:4c) and "ZCL request 0x0101: [0, 4174, 34, 537415696, 0]" is coming from a Iris (Centralite) Smart Plug 3210-L (00:0d:6f:00:0b:4f:95:72)

[walthowd]

The SmartThing sensors are not showing as entities in HA. Also chasing an issue where lights are turned on with a random brightness level -- not sure how to submit any useful debugging information for that yet.

[Yoda-x]

Please check what logs show up 30 sec before. Your log starts to late to see what command was send 30 sec before. Also helpful: click through your list of bulbs and see which one has null RSS/LQI values. This one was never online after your restart. the lqi/rssi values are updated with any incoming packet

The OTA updates are a pain in the back but not realy do any harm. But are also usless. Maybe I should filter the cluster.

What kind of bulbs make the problem. All or only a specific brand? your zigbee.db would be helpful to see what clusters your devices support and what device_id they use.

[walthowd]

Attached is the full log file. The "updating zha_new light took longer than the scheduled update interval" begins at 10:35:39 and then repeats every 30 seconds.

Also attached is the full zigbee.db (binary sqlite3 file, just renamed to upload)

All bulbs were reporting non null RSSI/LQI values when these errors were occurring. For what it's worth, my smartthings multisensors were not showing as binary_sensors and my Centralight switch is not showing as a valid switch anymore. (EDIT: Though after a HA restart, the Centralight switch will sometimes appear)

home-assistant.log

zigbee.db.txt

[Yoda-x]

It looks for me your Zigbee device has not enough buffer sapce. HA triggers at 10:35:09 an update for all of your zigbee bulbs the same time. Did you used my code also with HA versions before? Just to understand if it started with 63.1 and was ok before? In general it only affects the cababilty to have a current state of your light. And switching will not work persistent during such an 'update cycle' During HA start I added 1 sec wait between each device init to not run in this problem. But this comes from the HA scheduler. One option is to reduce the the source route table (32) on the controller, this frees some memory. You can change in <HA-Dir>/lib/python3.5/site-packages/bellows/zigbee/application.py

this line yield from self._cfg(c.CONFIG_SOURCE_ROUTE_TABLE_SIZE, 32 ) to 16 and if it not helps yield from self._cfg(c.CONFIG_MAX_END_DEVICE_CHILDREN, 32 ) to 28

[Yoda-x]

no update here, so I close the issue