Koenkk / zigbee2mqtt

Zigbee 🐝 to MQTT bridge 🌉, get rid of your proprietary Zigbee bridges 🔨
https://www.zigbee2mqtt.io
GNU General Public License v3.0
11.86k stars 1.65k forks source link

Zigbee messages are sent out of order #20969

Closed Flavien closed 1 month ago

Flavien commented 8 months ago

What happened?

The Zigbee messages are sent by Z2M out of order from the order they are consumed from MQTT.

What did you expect to happen?

See detailed logs below, the Zigbee messages should be sent in the same order as they are received from the MQTT broker. As you can see below, the messages got consumed in order 1, 2, 3, 4 but the Zigbee messages were sent in order 1, 3, 4, 2.

Ideally, the order should be preserved:

How to reproduce it (minimal and precise)

Here is an extract of my Zigbee2MQTT logs:

 1  2024-01-23T17:00:17.523629503Z Zigbee2MQTT:debug 2024-01-23 17:00:17: Received MQTT message on 'zigbee2mqtt/entrance/set' with data '{"scene_recall":1}'
 2  2024-01-23T17:00:17.525128068Z Zigbee2MQTT:debug 2024-01-23 17:00:17: Publishing 'set' 'scene_recall' to 'entrance'
 3  2024-01-23T17:00:17.772864147Z Zigbee2MQTT:info  2024-01-23 17:00:17: Successfully recalled group scene
 4  2024-01-23T17:00:17.779407543Z Zigbee2MQTT:info  2024-01-23 17:00:17: MQTT publish: topic 'zigbee2mqtt/entrance/ceiling', payload '{"brightness":254,"color":{"h":32,"hue":32,"s":82,"saturation":82,"x":0.4599,"y":0.4106},"color_mode":"color_temp","color_temp":370,"last_seen":"2024-01-23T15:08:24+00:00","linkquality":138,"power_on_behavior":"previous","state":"ON","update":{"installed_version":16785162,"latest_version":16785162,"state":"idle"},"update_available":null}'

 5  2024-01-23T17:00:17.994246776Z Zigbee2MQTT:debug 2024-01-23 17:00:17: Received MQTT message on 'zigbee2mqtt/entrance/set' with data '{"scene_recall":2}'
 6  2024-01-23T17:00:17.995912782Z Zigbee2MQTT:debug 2024-01-23 17:00:17: Publishing 'set' 'scene_recall' to 'entrance'

 7  2024-01-23T17:00:18.874496782Z Zigbee2MQTT:debug 2024-01-23 17:00:18: Received MQTT message on 'zigbee2mqtt/entrance/set' with data '{"scene_recall":1}'
 8  2024-01-23T17:00:18.876433375Z Zigbee2MQTT:debug 2024-01-23 17:00:18: Publishing 'set' 'scene_recall' to 'entrance'
 9  2024-01-23T17:00:19.168387535Z Zigbee2MQTT:info  2024-01-23 17:00:19: Successfully recalled group scene
 10 2024-01-23T17:00:19.170650493Z Zigbee2MQTT:info  2024-01-23 17:00:19: MQTT publish: topic 'zigbee2mqtt/entrance/ceiling', payload '{"brightness":254,"color":{"h":32,"hue":32,"s":82,"saturation":82,"x":0.4599,"y":0.4106},"color_mode":"color_temp","color_temp":370,"last_seen":"2024-01-23T15:08:24+00:00","linkquality":138,"power_on_behavior":"previous","state":"ON","update":{"installed_version":16785162,"latest_version":16785162,"state":"idle"},"update_available":null}'

 11 2024-01-23T17:00:19.557180937Z Zigbee2MQTT:debug 2024-01-23 17:00:19: Received MQTT message on 'zigbee2mqtt/entrance/set' with data '{"state":"OFF"}'
 12 2024-01-23T17:00:19.557249454Z Zigbee2MQTT:debug 2024-01-23 17:00:19: Publishing 'set' 'state' to 'entrance'
 13 2024-01-23T17:00:19.777748749Z Zigbee2MQTT:info  2024-01-23 17:00:19: MQTT publish: topic 'zigbee2mqtt/entrance/ceiling', payload '{"brightness":254,"color":{"h":32,"hue":32,"s":82,"saturation":82,"x":0.4599,"y":0.4106},"color_mode":"color_temp","color_temp":370,"last_seen":"2024-01-23T15:08:24+00:00","linkquality":138,"power_on_behavior":"previous","state":"OFF","update":{"installed_version":16785162,"latest_version":16785162,"state":"idle"},"update_available":null}'

 14 2024-01-23T17:00:20.399203034Z Zigbee2MQTT:info  2024-01-23 17:00:20: Successfully recalled group scene
 15 2024-01-23T17:00:20.402557453Z Zigbee2MQTT:info  2024-01-23 17:00:20: MQTT publish: topic 'zigbee2mqtt/entrance/ceiling', payload '{"brightness":77,"color":{"h":32,"hue":32,"s":82,"saturation":82,"x":0.4599,"y":0.4106},"color_mode":"color_temp","color_temp":370,"last_seen":"2024-01-23T15:08:24+00:00","linkquality":138,"power_on_behavior":"previous","state":"ON","update":{"installed_version":16785162,"latest_version":16785162,"state":"idle"},"update_available":null}'

Note this all happens very quickly (in the span of 3 seconds).

Zigbee2MQTT version

1.35.1

Adapter firmware version

20221226

Adapter

SONOFF Zigbee 3.0 USB Dongle Plus-P

Setup

Z2M on Docker on Raspberry Pi 4

Debug log

No response

Flavien commented 8 months ago

Doesn't this have a bug, or am I misreading it @Koenkk / @mikekap ?

public async execute<T>(func: () => Promise<T>, key: string | number = null): Promise<T> {
    const job : Job = {key, running: false, start: null};
    // Minor optimization/workaround: various tests like the idea that a job that is
    // immediately runnable is run without an event loop spin. This also helps with stack
    // traces in some cases, so avoid an `await` if we can help it.
    this.jobs.push(job);
    if (this.getNext() !== job) {
        await new Promise((resolve): void =>  {
            job.start = (): void => {
                job.running = true;
                resolve(null);
            };
            this.executeNext();
        });
    } else {
        job.running = true;
    }

    try {
        return await func();
    } finally {
        this.jobs.splice(this.jobs.indexOf(job), 1);
        this.executeNext();
    }
}

The first job to come in will be set as running = true, and gets suspended at await func(). Then assuming it doesn't finish running before the next message is received through MQTT, this function will re-enter with the new job, which gets added to this.jobs, getNext() returns null so job.running is set to true, and await func() is executed, even though the first job hasn't finished yet?

mikekap commented 8 months ago

If getNext() returns null, getNext() !== job will be true - so we await the promise to get a slot on the queue. The else clause doesn't get taken the second time.

github-actions[bot] commented 2 months ago

This issue is stale because it has been open 180 days with no activity. Remove stale label or comment or this will be closed in 30 days