corporategoth
commented
8 months ago @Koenkk
So I noticed with 1.36.0 that I could already keep logging at debug and have things start up. I also switched to the ember driver and updated my device's firmware accordingly. So that's a plus.
On the upside with the line commented, if I do a grep for '/config' now in the logs, I only see 13290 lines now, instead of 37106 before I commented out the line you requested.
Additionally, all '/config' messages end about 8 seconds after the start of the app now:
debug 2024-03-06 19:35:33: Loaded state from file /data/state.json
...
info 2024-03-06 19:35:41: MQTT publish: topic 'homeassistant/light/1221051039810110150109113116116_33/light/config', payload '{"availability":[{"topic":"zigbee2mqtt/bridge/state","value_template":"{{ value_json.state }}"}],"brightness":true,"brightness_scale":254,"color_mode":true,"command_topic":"zigbee2mqtt/driveway_6of6/set","device":{"identifiers":["zigbee2mqtt_1221051039810110150109113116116_33"],"manufacturer":"Zigbee2MQTT","model":"Group","name":"driveway_6of6","sw_version":"Zigbee2MQTT 1.36.0","via_device":"zigbee2mqtt_bridge_0xe0798dfffea88b0a"},"max_mireds":500,"min_mireds":154,"name":null,"object_id":"driveway_6of6","origin":{"name":"Zigbee2MQTT","sw":"1.36.0","url":"https://www.zigbee2mqtt.io"},"schema":"json","state_topic":"zigbee2mqtt/driveway_6of6","supported_color_modes":["xy","color_temp"],"unique_id":"33_light_zigbee2mqtt"}'As opposed to almost a full minute prior to commenting it out (with 1.36.0):
debug 2024-03-06 13:40:19: Loaded state from file /data/state.json
...
debug 2024-03-06 13:41:17: Received MQTT message on 'homeassistant/light/1221051039810110150109113116116_33/light/config' with data '{"availability":[{"topic":"zigbee2mqtt/bri
dge/state","value_template":"{{ value_json.state }}"}],"brightness":true,"brightness_scale":254,"color_mode":true,"command_topic":"zigbee2mqtt/driveway_6of6/set","device":{"id
entifiers":["zigbee2mqtt_1221051039810110150109113116116_33"],"manufacturer":"Zigbee2MQTT","model":"Group","name":"driveway_6of6","sw_version":"Zigbee2MQTT 1.36.0","via_device
":"zigbee2mqtt_bridge_0xe0798dfffea88b0a"},"max_mireds":500,"min_mireds":154,"name":null,"object_id":"driveway_6of6","origin":{"name":"Zigbee2MQTT","sw":"1.36.0","url":"https:
//www.zigbee2mqtt.io"},"schema":"json","state_topic":"zigbee2mqtt/driveway_6of6","supported_color_modes":["xy","color_temp"],"unique_id":"33_light_zigbee2mqtt"}'On the downside, something is going wrong. For example, on Z2M startup, I picked an entity ('Post 1 Light - Small'), it published these on startup:
info 2024-03-06 19:35:41: MQTT publish: topic 'homeassistant/light/0xb0ce1814001d4f3c/light/config', payload '{"availability":[{"topic":"zigbee2mqtt/bridge/state","value_template":"{{ value_json.state }}"}],"brightness":true,"brightness_scale":254,"color_mode":true,"command_topic":"zigbee2mqtt/Post 1 Light - Small/set","device":{"identifiers":["zigbee2mqtt_0xb0ce1814001d4f3c"],"manufacturer":"Sengled","model":"Element color plus E12 (E1F-N5E)","name":"Post 1 Light - Small","via_device":"zigbee2mqtt_bridge_0xe0798dfffea88b0a"},"max_mireds":500,"min_mireds":154,"name":null,"object_id":"post_1_light_-_small","origin":{"name":"Zigbee2MQTT","sw":"1.36.0","url":"https://www.zigbee2mqtt.io"},"schema":"json","state_topic":"zigbee2mqtt/Post 1 Light - Small","supported_color_modes":["xy","color_temp"],"unique_id":"0xb0ce1814001d4f3c_light_zigbee2mqtt"}'
info 2024-03-06 19:35:41: MQTT publish: topic 'homeassistant/sensor/0xb0ce1814001d4f3c/power/config', payload '{"availability":[{"topic":"zigbee2mqtt/bridge/state","value_template":"{{ value_json.state }}"}],"device":{"identifiers":["zigbee2mqtt_0xb0ce1814001d4f3c"],"manufacturer":"Sengled","model":"Element color plus E12 (E1F-N5E)","name":"Post 1 Light - Small","via_device":"zigbee2mqtt_bridge_0xe0798dfffea88b0a"},"device_class":"power","enabled_by_default":true,"entity_category":"diagnostic","object_id":"post_1_light_-_small_power","origin":{"name":"Zigbee2MQTT","sw":"1.36.0","url":"https://www.zigbee2mqtt.io"},"state_class":"measurement","state_topic":"zigbee2mqtt/Post 1 Light - Small","unique_id":"0xb0ce1814001d4f3c_power_zigbee2mqtt","unit_of_measurement":"W","value_template":"{{ value_json.power }}"}'
info 2024-03-06 19:35:41: MQTT publish: topic 'homeassistant/sensor/0xb0ce1814001d4f3c/energy/config', payload '{"availability":[{"topic":"zigbee2mqtt/bridge/state","value_template":"{{ value_json.state }}"}],"device":{"identifiers":["zigbee2mqtt_0xb0ce1814001d4f3c"],"manufacturer":"Sengled","model":"Element color plus E12 (E1F-N5E)","name":"Post 1 Light - Small","via_device":"zigbee2mqtt_bridge_0xe0798dfffea88b0a"},"device_class":"energy","enabled_by_default":true,"object_id":"post_1_light_-_small_energy","origin":{"name":"Zigbee2MQTT","sw":"1.36.0","url":"https://www.zigbee2mqtt.io"},"state_class":"total_increasing","state_topic":"zigbee2mqtt/Post 1 Light - Small","unique_id":"0xb0ce1814001d4f3c_energy_zigbee2mqtt","unit_of_measurement":"kWh","value_template":"{{ value_json.energy }}"}'
info 2024-03-06 19:35:41: MQTT publish: topic 'homeassistant/sensor/0xb0ce1814001d4f3c/linkquality/config', payload '{"availability":[{"topic":"zigbee2mqtt/bridge/state","value_template":"{{ value_json.state }}"}],"device":{"identifiers":["zigbee2mqtt_0xb0ce1814001d4f3c"],"manufacturer":"Sengled","model":"Element color plus E12 (E1F-N5E)","name":"Post 1 Light - Small","via_device":"zigbee2mqtt_bridge_0xe0798dfffea88b0a"},"enabled_by_default":false,"entity_category":"diagnostic","icon":"mdi:signal","name":"Linkquality","object_id":"post_1_light_-_small_linkquality","origin":{"name":"Zigbee2MQTT","sw":"1.36.0","url":"https://www.zigbee2mqtt.io"},"state_class":"measurement","state_topic":"zigbee2mqtt/Post 1 Light - Small","unique_id":"0xb0ce1814001d4f3c_linkquality_zigbee2mqtt","unit_of_measurement":"lqi","value_template":"{{ value_json.linkquality }}"}'
info 2024-03-06 19:35:41: MQTT publish: topic 'homeassistant/sensor/0xb0ce1814001d4f3c/last_seen/config', payload '{"availability":[{"topic":"zigbee2mqtt/bridge/state","value_template":"{{ value_json.state }}"}],"device":{"identifiers":["zigbee2mqtt_0xb0ce1814001d4f3c"],"manufacturer":"Sengled","model":"Element color plus E12 (E1F-N5E)","name":"Post 1 Light - Small","via_device":"zigbee2mqtt_bridge_0xe0798dfffea88b0a"},"device_class":"timestamp","enabled_by_default":false,"entity_category":"diagnostic","icon":"mdi:clock","name":"Last seen","object_id":"post_1_light_-_small_last_seen","origin":{"name":"Zigbee2MQTT","sw":"1.36.0","url":"https://www.zigbee2mqtt.io"},"state_topic":"zigbee2mqtt/Post 1 Light - Small","unique_id":"0xb0ce1814001d4f3c_last_seen_zigbee2mqtt","value_template":"{{ value_json.last_seen }}"}'
info 2024-03-06 19:35:41: MQTT publish: topic 'homeassistant/sensor/0xb0ce1814001d4f3c/update_state/config', payload '{"availability":[{"topic":"zigbee2mqtt/bridge/state","value_template":"{{ value_json.state }}"}],"device":{"identifiers":["zigbee2mqtt_0xb0ce1814001d4f3c"],"manufacturer":"Sengled","model":"Element color plus E12 (E1F-N5E)","name":"Post 1 Light - Small","via_device":"zigbee2mqtt_bridge_0xe0798dfffea88b0a"},"enabled_by_default":false,"entity_category":"diagnostic","icon":"mdi:update","name":"Update state","object_id":"post_1_light_-_small_update_state","origin":{"name":"Zigbee2MQTT","sw":"1.36.0","url":"https://www.zigbee2mqtt.io"},"state_topic":"zigbee2mqtt/Post 1 Light - Small","unique_id":"0xb0ce1814001d4f3c_update_state_zigbee2mqtt","value_template":"{{ value_json['update']['state'] }}"}'
info 2024-03-06 19:35:41: MQTT publish: topic 'homeassistant/binary_sensor/0xb0ce1814001d4f3c/update_available/config', payload '{"availability":[{"topic":"zigbee2mqtt/bridge/state","value_template":"{{ value_json.state }}"}],"device":{"identifiers":["zigbee2mqtt_0xb0ce1814001d4f3c"],"manufacturer":"Sengled","model":"Element color plus E12 (E1F-N5E)","name":"Post 1 Light - Small","via_device":"zigbee2mqtt_bridge_0xe0798dfffea88b0a"},"device_class":"update","enabled_by_default":false,"entity_category":"diagnostic","name":null,"object_id":"post_1_light_-_small_update_available","origin":{"name":"Zigbee2MQTT","sw":"1.36.0","url":"https://www.zigbee2mqtt.io"},"payload_off":false,"payload_on":true,"state_topic":"zigbee2mqtt/Post 1 Light - Small","unique_id":"0xb0ce1814001d4f3c_update_available_zigbee2mqtt","value_template":"{{ value_json['update']['state'] == \"available\" }}"}'
info 2024-03-06 19:35:41: MQTT publish: topic 'homeassistant/update/0xb0ce1814001d4f3c/update/config', payload '{"availability":[{"topic":"zigbee2mqtt/bridge/state","value_template":"{{ value_json.state }}"}],"command_topic":"zigbee2mqtt/bridge/request/device/ota_update/update","device":{"identifiers":["zigbee2mqtt_0xb0ce1814001d4f3c"],"manufacturer":"Sengled","model":"Element color plus E12 (E1F-N5E)","name":"Post 1 Light - Small","via_device":"zigbee2mqtt_bridge_0xe0798dfffea88b0a"},"device_class":"firmware","entity_category":"config","entity_picture":"https://github.com/Koenkk/zigbee2mqtt/raw/master/images/logo.png","json_attributes_template":"{\"in_progress\": {{ iif(value_json['update']['state'] == 'updating', 'true', 'false') }} }","json_attributes_topic":"zigbee2mqtt/Post 1 Light - Small","latest_version_template":"{{ value_json['update']['latest_version'] }}","latest_version_topic":"zigbee2mqtt/Post 1 Light - Small","name":null,"object_id":"post_1_light_-_small","origin":{"name":"Zigbee2MQTT","sw":"1.36.0","url":"https://www.zigbee2mqtt.io"},"payload_install":"{\"id\": \"0xb0ce1814001d4f3c\"}","state_topic":"zigbee2mqtt/Post 1 Light - Small","unique_id":"0xb0ce1814001d4f3c_update_zigbee2mqtt","value_template":"{{ value_json['update']['installed_version'] }}"}'If I look at my MQTT server, and run mosquitto_sub -u test -P '****' -v -t 'homeassistant/+/0xb0ce1814001d4f3c/#', they are all returning correctly (both when Z2M is down, showing retained messages, and getting updated on Z2M startup).
With the line commented, On Home Assistant, the device exists, but shows no entities - as if it didn't configure at all. It knows the device exists, but it completely ignored the /config entry published.
However, if I uncomment the line again (ie. revert to default 1.36.0 behavior), I get:
Koenkk
jbouwh
mundschenk-at
Is your feature request related to a problem? Please describe
High MQTT load (for example, when you have a LOT of HA devices, and HA configuration occurs) can cause actual zigbee traffic to be delayed/halted, and even time out (causing Z2M to crash). This can be because of either the MQTT traffic, OR the logging of such (if logging is set to debug).
To wit, if I have logging set to debug, and HA enabled, Z2M will almost always crash on startup for me, because the amount of work being done both to log things and communicate with HA's autoconfiguration causes enough delays in Zigbee comms to cause a timeout and crash. I have to either turn off HA integration before startup, or set logging to info to get a successful startup of Z2M.
Describe the solution you'd like
Although JavaScript is normally single-threaded, this is a prime candidate for investigating/using the means to do multi-threading in JS. Either through some existing means (there are a few) or by splitting things into multiple processes.
There would have to be a pair of queues between the threads (one going each direction). So that, for example, when you get a status from the Zigbee network, you put that status onto a queue, and a separate thread is responsible for publishing that to MQTT. Or you get a command from MQTT, it goes onto a queue, that the Zigbee thread can pick up and send to the zigbee device. This way, high load or concurrency limiting (on either side) will NOT affect the other.
The same is true for logging (though in this case only 1 queue is needed). Log messages are put on a queue, and a separate thread pulls from that queue to write the logs out (to disk, or wherever) - so that any I/O from logging doesn't delay core processing.
Describe alternatives you've considered
For now, I'm working around this by lowing log levels and disabling HA integration on startup. Not ideal, especially if a restart happens when I'm not around to change these values.
Additional context
All as described.