Much slower automations after renaming Zigbee devices via z2m

Configuration Zigbee
1

I’ve been using HA/z2m combination successfully for over a year. Automation is simple, single press on Tradfri remote E1524 should toggle 3 lights: 2 tradfri bulbs and one Sonoff switch. This used to work quite instantly - less than 1s delay between tapping the button and all lights becoming on/off. Excellent.

However, I recently decided to tidy up my z2m configuration by assigning friendly names to bulbs and remotes. Up until recently, automations were made using generic entity names, like light.0x000d6ffffefc2b71_light and now this is renamed to light.ikea_minibar. I have used the “Rename device” option from zigbee2mqtt GUI and have left “Update Home Assistant entity ID” option checked. I have replaced all the references to old entity ID with a new one in the automations.yaml. There is now a significant 2 second delay between pressing the button and lights turning on/off. It is not radio nor z2m problem because remote’s action attribute changes instantly to toggle after pressing a button and also lights are immediately turned on after running the automation action manually. There simply seems to be a delay between automation’s trigger and executing action.

How should I approach troubleshooting this? HA log does not complain about some referenced entities not found. Also, the described behavior can be seen in z2m log. There is just too long delay between mqtt messages indicating pressing a button and receiving a command from HA to turn the lights on.

- id: '1580763366585'
  alias: Toggle-all
  description: ''
  trigger:
  - entity_id: sensor.0x90fd9ffffef5c2dd_action
    platform: state
    to: toggle
  condition: []
  action:
  - entity_id: light.ikea_minibar
    service: light.toggle
  - entity_id: light.ikea_woofer
    service: light.toggle
  - entity_id: switch.sonoff_lampa
    service: switch.toggle
  mode: single
2

Still having the same issue, but now, I’m able to share the automation trace, courtesy of 2021.4 release.

image
image540×934 92.4 KB

The 2 second delay is what is causing my issues. Subsequent calls of the same automation don’t have that delay. However, delay is again present after ~15 minutes of “cooldown” period.

The z2m log clearly shows the 2 second delay between publishing mqtt command from the remote and receiving back the command to toggle the first of three lights.

debug 2021-04-08 15:51:07: Received Zigbee message from '0x90fd9ffffef5c2dd', type 'commandToggle', cluster 'genOnOff', data '{}' from endpoint 1 with groupID 47363
info  2021-04-08 15:51:07: MQTT publish: topic 'zigbee2mqtt/0x90fd9ffffef5c2dd', payload '{"action":"toggle","battery":47,"linkquality":78,"update":{"state":"available"},"update_available":true}'
info  2021-04-08 15:51:07: MQTT publish: topic 'zigbee2mqtt/0x90fd9ffffef5c2dd', payload '{"action":"","battery":47,"linkquality":78,"update":{"state":"available"},"update_available":true}'
info  2021-04-08 15:51:07: MQTT publish: topic 'zigbee2mqtt/0x90fd9ffffef5c2dd/action', payload 'toggle'
debug 2021-04-08 15:51:09: Received MQTT message on 'zigbee2mqtt/0x000d6ffffefc2b71/set' with data '{"state": "ON"}'
debug 2021-04-08 15:51:09: Publishing 'set' 'state' to '0x000d6ffffefc2b71'
debug 2021-04-08 15:51:09: Received MQTT message on 'zigbee2mqtt/ikea_woofer/set' with data '{"state": "ON"}'
debug 2021-04-08 15:51:09: Publishing 'set' 'state' to 'ikea_woofer'
info  2021-04-08 15:51:09: MQTT publish: topic 'zigbee2mqtt/dnevna_soba', payload '{"brightness":254,"color":{"x":0.3855,"y":0.1546},"color_temp":44,"state":"ON"}'
info  2021-04-08 15:51:09: MQTT publish: topic 'zigbee2mqtt/ikea_woofer', payload '{"brightness":254,"color":{"x":0.3855,"y":0.1546},"color_temp":44,"linkquality":139,"state":"ON","update":{"state":"idle"},"update_available":false}'
debug 2021-04-08 15:51:09: Received MQTT message on 'zigbee2mqtt/sonoff_lampa/set' with data 'ON'
debug 2021-04-08 15:51:09: Publishing 'set' 'state' to 'sonoff_lampa'
debug 2021-04-08 15:51:09: Received Zigbee message from 'sonoff_lampa', type 'attributeReport', cluster 'genOnOff', data '{"onOff":1}' from endpoint 1 with groupID 0
info  2021-04-08 15:51:09: MQTT publish: topic 'zigbee2mqtt/dnevna_soba', payload '{"brightness":10,"color":{"x":0.3855,"y":0.1546},"color_temp":44,"state":"ON"}'
info  2021-04-08 15:51:09: MQTT publish: topic 'zigbee2mqtt/sonoff_lampa', payload '{"brightness":10,"color":{"x":0.3855,"y":0.1546},"color_temp":44,"linkquality":39,"state":"ON"}'
debug 2021-04-08 15:51:09: Received Zigbee message from 'sonoff_lampa', type 'attributeReport', cluster 'genOnOff', data '{"onOff":1}' from endpoint 1 with groupID 0
debug 2021-04-08 15:51:09: Received Zigbee message from 'sonoff_lampa', type 'attributeReport', cluster 'genOnOff', data '{"onOff":1}' from endpoint 1 with groupID 0
debug 2021-04-08 15:51:09: Received Zigbee message from 'sonoff_lampa', type 'attributeReport', cluster 'genOnOff', data '{"onOff":1}' from endpoint 1 with groupID 0
debug 2021-04-08 15:51:09: Received Zigbee message from 'sonoff_lampa', type 'attributeReport', cluster 'genOnOff', data '{"onOff":1}' from endpoint 1 with groupID 0
debug 2021-04-08 15:51:09: Received Zigbee message from 'sonoff_lampa', type 'attributeReport', cluster 'genOnOff', data '{"onOff":1}' from endpoint 1 with groupID 0
debug 2021-04-08 15:51:09: Received Zigbee message from 'sonoff_lampa', type 'attributeReport', cluster 'genOnOff', data '{"onOff":1}' from endpoint 1 with groupID 0
info  2021-04-08 15:51:09: MQTT publish: topic 'zigbee2mqtt/sonoff_lampa', payload '{"brightness":10,"color":{"x":0.3855,"y":0.1546},"color_temp":44,"linkquality":39,"state":"ON"}'
info  2021-04-08 15:51:09: MQTT publish: topic 'zigbee2mqtt/dnevna_soba', payload '{"brightness":254,"color":{"x":0.3855,"y":0.1546},"color_temp":44,"state":"ON"}'
info  2021-04-08 15:51:09: MQTT publish: topic 'zigbee2mqtt/0x000d6ffffefc2b71', payload '{"brightness":254,"linkquality":78,"state":"ON","update":{"state":"available"},"update_available":true}'