search

sidoh / esp8266_milight_hub

Replacement for a Milight/LimitlessLED hub hosted on an ESP8266
MIT License
947 stars 219 forks source link

Update MQTT client to not send PUBACK when queue is full #652

Open jnordberg opened 4 years ago

jnordberg commented 4 years ago

Describe the bug

When publishing to a lot of topics simultaneously some updates are lost, different MQTT queue debounce/delay values does not seem to affect it. And the weird part is that only parts of the update is lost. An example:

[2020-8-19 02:24:04] [MiLightHub] Publish lights/rgb_cct/0x6/1 {"hue":240,"saturation":100,"state":"ON"}
[2020-8-19 02:24:04] [MiLightHub] Publish lights/rgb_cct/0x4/0 {"hue":240,"saturation":100,"state":"ON"}
[2020-8-19 02:24:04] [MiLightHub] Publish lights/rgb_cct/0x2/1 {"hue":240,"saturation":100,"state":"ON"}
[2020-8-19 02:24:04] [MiLightHub] Publish lights/rgb_cct/0x8/1 {"hue":240,"saturation":100,"state":"ON"}
[2020-8-19 02:24:04] [MiLightHub] Publish lights/rgb_cct/0x1/0 {"hue":240,"saturation":100,"state":"ON"}
[2020-8-19 02:24:04] [MiLightHub] Publish lights/rgb_cct/0x3/1 {"hue":240,"saturation":100,"state":"ON"}
[2020-8-19 02:24:04] [MiLightHub] Publish lights/rgb_cct/0x7/1 {"hue":240,"saturation":100,"state":"ON"}
[2020-8-19 02:24:04] [MiLightHub] Publish lights/rgb_cct/0x5/0 {"hue":240,"saturation":100,"state":"ON"}
[2020-8-19 02:24:06] [MiLightHub] Topic update/rgb_cct/0x6/1 update: {"state":"ON","hue":240,"saturation":100}
[2020-8-19 02:24:07] [MiLightHub] Topic update/rgb_cct/0x4/0 update: {"state":"ON","hue":240,"saturation":100}
[2020-8-19 02:24:08] [MiLightHub] Topic update/rgb_cct/0x2/1 update: {"state":"ON","hue":240,"saturation":100}
[2020-8-19 02:24:08] [MiLightHub] Topic update/rgb_cct/0x8/1 update: {"state":"ON","hue":240,"saturation":100}
[2020-8-19 02:24:09] [MiLightHub] Topic update/rgb_cct/0x1/0 update: {"state":"ON","hue":240,"saturation":100}
[2020-8-19 02:24:10] [MiLightHub] Topic update/rgb_cct/0x3/1 update: {"state":"ON","hue":240,"saturation":100}
[2020-8-19 02:24:11] [MiLightHub] Topic update/rgb_cct/0x7/1 update: {"state":"ON","hue":240,"saturation":100}
[2020-8-19 02:24:11] [MiLightHub] Topic update/rgb_cct/0x5/0 update: {"saturation":100}

I can reliably reproduce this with 8 topics or more and it's always the last published topic that looses information. The info is not just lost when publishing back to the update topic, the commands are never sent to the bulb.

Setup information

{
    "firmware": "milight-hub",
    "version": "1.10.6",
    "ip_address": "10.149.1.251",
    "reset_reason": "Software/System restart",
    "variant": "nodemcuv2",
    "free_heap": 15640,
    "arduino_version": "2_4_2",
    "queue_stats": {"length": 0, "dropped_packets": 6}
}
{
    "admin_username": "",
    "admin_password": "",
    "ce_pin": 16,
    "csn_pin": 15,
    "reset_pin": 0,
    "led_pin": -2,
    "radio_interface_type": "nRF24",
    "packet_repeats": 50,
    "http_repeat_factor": 1,
    "auto_restart_period": 0,
    "mqtt_server": "10.149.1.229:1883",
    "mqtt_username": "",
    "mqtt_password": "",
    "mqtt_topic_pattern": "lights/:device_type/:device_id/:group_id",
    "mqtt_update_topic_pattern": "update/:device_type/:device_id/:group_id",
    "mqtt_state_topic_pattern": "",
    "mqtt_client_status_topic": "",
    "simple_mqtt_client_status": true,
    "discovery_port": 0,
    "listen_repeats": 0,
    "state_flush_interval": 20000,
    "mqtt_state_rate_limit": 500,
    "mqtt_debounce_delay": 1000,
    "packet_repeat_throttle_sensitivity": 50,
    "packet_repeat_throttle_threshold": 200,
    "packet_repeat_minimum": 10,
    "enable_automatic_mode_switching": false,
    "led_mode_wifi_config": "Fast toggle",
    "led_mode_wifi_failed": "On",
    "led_mode_operating": "Off",
    "led_mode_packet": "Flicker",
    "led_mode_packet_count": 3,
    "hostname": "milight-hub",
    "rf24_power_level": "MAX",
    "rf24_listen_channel": "LOW",
    "wifi_static_ip": "",
    "wifi_static_ip_gateway": "",
    "wifi_static_ip_netmask": "",
    "packet_repeats_per_loop": 10,
    "home_assistant_discovery_prefix": "",
    "wifi_mode": "n",
    "default_transition_period": 500,
    "rf24_channels": ["LOW", "MID", "HIGH"],
    "device_ids": [1, 2, 3, 4, 5, 6, 7, 8, 128],
    "gateway_configs": [],
    "group_state_fields": [
        "state",
        "brightness",
        "hue",
        "saturation",
        "mode",
        "kelvin",
        "color_temp",
        "bulb_mode"
    ],
    "group_id_aliases": {
        // redacted
    }
}
sidoh commented 4 years ago

Thanks for posting all of this info up front, very helpful!

From your /about stats, you can see there are some dropped packets:

    "queue_stats": {"length": 0, "dropped_packets": 6}

When a packet is received while another is being processed, it's put into a queue. The queue is not allowed to grow beyond 20 entries -- packets are dropped after that.

The size of this queue is unfortunately not configurable, but you can recompile with this constant changed if you want to experiment:

https://github.com/sidoh/esp8266_milight_hub/blob/master/lib/MiLight/PacketQueue.h#L10

jnordberg commented 4 years ago

Ah, that makes sense. I can confirm that I'm seeing the queue length at 20 when this happens.

Would it be possible to solve this in the MQTT listener? E.g. when the queue is full don't send the PUBACK, then senders can use the QoS setting to have the broker repeat until the queue has drained and the packet can be accepted.

Edit: Had a quick look and it seems like it could be doable but would require changes to the PubSubClient here and a change to the callback signature so it can decide whether to ack it or not

sidoh commented 4 years ago

Excellent idea.

I can look into this when I have more time, but would be very happy to collaborate on a PR if you're open to it. :)

DigiH commented 4 years ago

Following this closely, as I had the same dropped packets issue. Currently solved by recompling with higher MILIGHT_MAX_QUEUED_PACKETS. Thanks

Erriez commented 3 years ago

I've a similar issue with Homeassistant changing multiple lights from a Scene. The problem is as follows:

When running a scene in Homeassistant, it transmits all light commands after each other in a burst. MiLight-Hub cannot handle receiving a large burst of MQTT commands when it is busy with Milight RF transmission. The MQTT state acknowledge is sent much later in time and Homeassistant does not wait for state changes.

In my case only the first 7 lights are handled from a Homeassistant scene, others are lost. I don't prefer to increase MILIGHT_MAX_QUEUED_PACKETS as it increases memory usage.

Erriez commented 3 years ago

Update:

Qos=2 is already defined in the connect for subscribe:

https://github.com/sidoh/esp8266_milight_hub/blob/83cc3ae909b4f08d9b9be84c1fdbc0253734ee31/lib/MQTT/MqttClient.cpp#L57

    return mqttClient.connect(
      nameBuffer,
      settings.mqttUsername.c_str(),
      settings.mqttPassword.c_str(),
      settings.mqttClientStatusTopic.c_str(),
      2,  // <== Qos=2
      true,
      generateConnectionStatusMessage(STATUS_LWT_DISCONNECTED).c_str()
    );

All MQTT light commands are received correctly on the MiLight Hub, but are not processed in a burst.

MILIGHT_MAX_QUEUED_PACKETS Increasing this macro is eating up memory, so default 20 can only be increased to 30, then memory is full. In my case it is not sufficient to change 8 lights in one single Scene, because Homeassistant sends all light states in a burst after each other.

MQTT testcase without Homeassistant I've created the following reproducible sh script on Linux to transmit a burst of light commands to the MiLight Hub without delays between pubs:

mosquitto_pub -h host -u user -P pass -t "milight/cmd/fut089/0x1234/1" -m "{\"state\":\"ON\",\"brightness\":15,\"color_temp\":275"}
mosquitto_pub -h host -u user -P pass -t "milight/cmd/fut089/0x1234/2" -m "{\"state\":\"ON\",\"brightness\":15,\"color_temp\":275"}
mosquitto_pub -h host -u user -P pass -t "milight/cmd/fut089/0x1234/3" -m "{\"state\":\"ON\",\"brightness\":15,\"color_temp\":275"}
mosquitto_pub -h host -u user -P pass -t "milight/cmd/fut089/0x1234/4" -m "{\"state\":\"ON\",\"brightness\":15,\"color_temp\":275"}
mosquitto_pub -h host -u user -P pass -t "milight/cmd/fut089/0x1234/5" -m "{\"state\":\"ON\",\"brightness\":15,\"color_temp\":275"}
mosquitto_pub -h host -u user -P pass -t "milight/cmd/fut089/0x1234/6" -m "{\"state\":\"ON\",\"brightness\":15,\"color_temp\":275"}
mosquitto_pub -h host -u user -P pass -t "milight/cmd/fut089/0x1234/7" -m "{\"state\":\"ON\",\"brightness\":15,\"color_temp\":275"}
mosquitto_pub -h host -u user -P pass -t "milight/cmd/fut089/0x1234/8" -m "{\"state\":\"ON\",\"brightness\":15,\"color_temp\":275"}

mosquitto_pub -h host -u user -P pass -t "milight/cmd/fut089/0xABCD/1" -m "{\"state\":\"ON\",\"brightness\":15,\"color_temp\":275"}
mosquitto_pub -h host -u user -P pass -t "milight/cmd/fut089/0xABCD/2" -m "{\"state\":\"ON\",\"brightness\":15,\"color_temp\":275"}
mosquitto_pub -h host -u user -P pass -t "milight/cmd/fut089/0xABCD/3" -m "{\"state\":\"ON\",\"brightness\":15,\"color_temp\":275"}
mosquitto_pub -h host -u user -P pass -t "milight/cmd/fut089/0xABCD/4" -m "{\"state\":\"ON\",\"brightness\":15,\"color_temp\":275"}
mosquitto_pub -h host -u user -P pass -t "milight/cmd/fut089/0xABCD/5" -m "{\"state\":\"ON\",\"brightness\":15,\"color_temp\":275"}
mosquitto_pub -h host -u user -P pass -t "milight/cmd/fut089/0xABCD/6" -m "{\"state\":\"ON\",\"brightness\":15,\"color_temp\":275"}
mosquitto_pub -h host -u user -P pass -t "milight/cmd/fut089/0xABCD/7" -m "{\"state\":\"ON\",\"brightness\":15,\"color_temp\":275"}
mosquitto_pub -h host -u user -P pass -t "milight/cmd/fut089/0xABCD/8" -m "{\"state\":\"ON\",\"brightness\":15,\"color_temp\":275"}

The output on the ESP8266 serial port:

MqttClient - device 1234, group 1
MqttClient - device 1234, group 2
MqttClient - device 1234, group 3
MqttClient - device 1234, group 4
MqttClient - device 1234, group 5
MqttClient - device 1234, group 6
MqttClient - device 1234, group 7
MqttClient - device 1234, group 8
MqttClient - device ABCD, group 1
MqttClient - device ABCD, group 2
MqttClient - device ABCD, group 3
MqttClient - device ABCD, group 4
MqttClient - device ABCD, group 5
MqttClient - device ABCD, group 6
MqttClient - device ABCD, group 7
MqttClient - device ABCD, group 8

This indicates that all light commands are received correctly. MiLight Hub starts transmitting RF commands to the lights.

None of the lights with device address 0xABCD are changed. All packets are dropped and dropped_packets counter increases in /about.

The MiLight Hub does not return any state, verified with command:

mosquitto_sub -h host -u user -P pass -d -t "milight/state/fut089/+/+". No state messages.

Adding delays after each mosquitto_pub light command is a workaround, but I'm not sure if this can be configured in Homeassistant.

At the moment I'm not sure how to resolve this in MiLight Hub.

As a result, Homeassistant Scenes can only be used to control around 4 lights in a Scene which is not sufficient for me.

Erriez commented 3 years ago

Related to https://community.home-assistant.io/t/slow-down-mqtt-light-transmits-in-scene-for-milight-hub/265091