Zigbee2mqtt: Aqara switch click received multiple times

[WalterWampe]

Messages from my switch are received and translated to mqtt several times, thus making it impossible to toggle entities reliably.
Is there any setting I overlooked to debounce?

'2018-08-21T10:16:37.785Z - info: MQTT publish, topic: 'zigbee2mqtt/zigbee_switch_bad', payload: '{"battery":"100.00","voltage":3065,"click":"single"}'

'2018-08-21T10:16:38.194Z - info: MQTT publish, topic: 'zigbee2mqtt/zigbee_switch_bad', payload: '{"battery":"100.00","voltage":3065,"click":"single"}'

'2018-08-21T10:16:39.030Z - info: MQTT publish, topic: 'zigbee2mqtt/zigbee_switch_bad', payload: '{"battery":"100.00","voltage":3065,"click":"single"}'

[Koenkk]

Could you provide your complete zigbee2mqtt (post it on: https://pastebin.com).

[WalterWampe]

log:
https://pastebin.com/L3XwpEH9
config:
https://pastebin.com/2DJ0scqY

[Koenkk]

Could you set log_level to debug and provide the log when the error happens? (in the current log I dont see any "click":"single")

[WalterWampe]

Sure! My fault, here it is, freshly from restart with debug log_level:

https://pastebin.com/XdSvsTui

[Koenkk]

From the logs I don't see any weird behaviour. The switch report that is has been clicked and zigbee2mqtt passes this through:

2018-08-22T08:30:37.432Z - debug: Recieved zigbee message with data {"cid":"genOnOff","data":{"onOff":1}}    <---- Message from switch that it has been clicked
2018-08-22T08:30:37.437Z - info: MQTT publish, topic: 'zigbee2mqtt/zigbee_switch_bad', payload: '{"click":"single"}'

Can you try repairing?

[Ton1965]

I have an idea on how this problem can appear (though probably I am wrong).

I believe the problem is related to how zigbee2mqtt handles mqtt messages when it is reporting to HA. It needs to report the full data set (all the attributes) in each message but the device sends at least sometimes sends just a subset of all attributes in a single message. I think the initial log fragment was taken with reporting to HA enabled and the device sent three separate messages to the bridge (for battery level, for voltage and for click itself), but the bridge reported to HA the full data set with each mqtt message replacing missing attributes with their cached values. So three separate identical messages were sent.

The last log was probably written with reporting to HA switched off, so only click message got sent with mqtt.

I observe some similar behavior with Xiaomi presense and illumination: the sensor sends two different messages in a quick sequence: one for illumination, another for motion. zigbee2mqtt sends two messages with full attribute set so the first message goes with the new illumination value and old presense value (usually false) and immediately a new message is sent with the same illumination and new presense (true). In many cases both illumination values are the same.

[lolorc]

yep that happens also with aqara sensors (temp/hum/press), wondering if it's a linkquality issue as it does not happen with all my sensors

[WalterWampe]

Can you try repairing?

I was away for a few days - just repaired - unchanged!

The last log was probably written with reporting to HA switched off, so only click message got sent with mqtt.

negative - configuration unchanged despite debug level.

[Ton1965]

I do not quite understand then. Your initial log contains the following:

> 2018-08-21T10:16:37.785Z - info: MQTT publish, topic: 'zigbee2mqtt/zigbee_switch_bad', payload: '{"battery":"100.00","voltage":3065,"click":"single"}'

You last log shows the following:

2018-08-22T08:30:37.432Z - debug: Recieved zigbee message with data {"cid":"genOnOff","data":{"onOff":1}}    <---- Message from switch that it has been clicked
2018-08-22T08:30:37.437Z - info: MQTT publish, topic: 'zigbee2mqtt/zigbee_switch_bad', payload: '{"click":"single"}'

The format of the MQTT message looks very different. The last message does not have any info about the battery and voltage.

Probably zigbee2mqtt formats messages differently depending on whether the debug mode is set. But then the question arises which message exactly will be sent to HA in both cases?

[Koenkk]

Could you share your log when you see these duplicate events? (with debug on)

[WalterWampe]

Sure, anything to help!

https://pastebin.com/wizWKmFE

I marked one of those events at the end.

The format of the MQTT message looks very different. The last message does not have any info about the battery and voltage.

It might be that it is what you said above:

It needs to report the full data set (all the attributes) in each message but the device sends at least sometimes sends just a subset of all attributes in a single message.

I guess after restarting the container ( I run it in docker) the attributes for battery and voltage have not been submitted to zigbee2mqtt before and with pressing the button and thus have not been cached and are not transmitted via the mqtt payload.

But guys....
If I am the only one with this problem, don't bother yourself too much with it.
zigbee2mqtt is very nice and flawlessly working despite this bouncy problem I have here.

I managed to implement a debounce in my home assistant instance in the meantime.

[Ton1965]

@Koenkk
I do not no the exact reason for the problem @WalterWampe has but I can show something similar that probably should also be taken care of.

Here is a piece of the debug log obtained from my RTCGQ11LM device:

2018-8-28 21:49:46 - info: MQTT publish, topic: 'zigbee2mqtt/bridge/state', payload: 'online'
2018-8-28 21:49:47 - info: MQTT publish, topic: 'zigbee2mqtt/test_aqara', payload: '{"illuminance":213,"linkquality":98,"occupancy":true,"battery":"100.00","voltage":3035}'
2018-8-28 21:50:03 - debug: Recieved zigbee message with data {"cid":"msIlluminanceMeasurement","data":{"measuredValue":221}}
2018-8-28 21:50:03 - info: MQTT publish, topic: 'zigbee2mqtt/test_aqara', payload: '{"illuminance":221,"linkquality":96,"occupancy":true,"battery":"100.00","voltage":3035}'
2018-8-28 21:50:03 - debug: Recieved zigbee message with data {"cid":"msOccupancySensing","data":{"occupancy":1}}
2018-8-28 21:50:03 - info: MQTT publish, topic: 'zigbee2mqtt/test_aqara', payload: '{"illuminance":221,"linkquality":96,"occupancy":true,"battery":"100.00","voltage":3035}'
2018-8-28 21:50:03 - debug: Recieved zigbee message with data {"cid":"msIlluminanceMeasurement","data":{"measuredValue":221}}
2018-8-28 21:50:03 - debug: Recieved zigbee message with data {"cid":"msOccupancySensing","data":{"occupancy":1}}
2018-8-28 21:51:04 - info: MQTT publish, topic: 'zigbee2mqtt/test_aqara', payload: '{"illuminance":221,"linkquality":96,"occupancy":false,"battery":"100.00","voltage":3035}'

At the start zigbee2mqtt announces that it is online, then immediately it sends the cached state of the device with all the attributes. After that it gets two zigbee messages in a quick succession: one for an illuminance measurement, another for occupancy. On each of these messages the bridge immediately publishes corresponding mqtt messages with the full state. In this particular case there some minor differences (like different illuminance values and link quality) but in general we have three almost identical messages sent to HA.

The first one of these messages (the cached state) is probably ok since it only happens at the very start of the operation but later when any movement is detected the device sends two zigbee messages and the bridge translates them into two full mqtt messages. Probably at least for this device type these two zigbee messages should be combined into one mqtt message.

What do you think?

[Koenkk]

The idea of zigbee2mqtt is that each zigbee message will produce one mqtt message. I don't want to wait for the device to check if it will send anymore updates, as this may introduce lag.

[Ton1965]

I would agree to that but... :-)

Original Xiaomi hub sends just a single update message to clients with both illumination and occupancy. It looks like it is by design that at least this particular device measures illuminance and occupancy at the same time moment but for some reason splits the info into two zigbee messages.

My suggestion is to allow a device zigbee message converter to return an empty message (nothing is to be sent to mqtt). This way the converter for this particular device could just cache the illuminance and send nothing. On receive of occupancy message the converter would send the same message it sends now.

No wait time will be introduced in this way. It is documented for this particular device that it does not send anything before occupancy is triggered, collects both data pieces at the moment, sends them and after that it sleeps for a minute.

I do not propose to do this for all devices but it might give some additional flexibility.

[Koenkk]

That means that no illuminance updates will be send until the occupancy changes, I think that's also not a solution.

What is the problem of having 2 seperate MQTT messages?

[ryanbeaton]

@Koenkk is this behaviour new (because of the caching) or would it always have happened?

_{Sent with GitHawk}

[Ton1965]

@Koenkk,
Sorry for the delay, I just wanted to do some experiments. Here are the results:

This device (RTCGQ11LM) does not send any illuminance updates without occupancy changing. I set the log level to debug and had it run for several hours without triggering occupancy. The only message it sends is the general state every 55 minutes. As far as I understood from zigbee2mqtt code the only attribute that gets decoded from this message is battery voltage. There is no illuminance sent.

I am actually fine with the two messages. One just needs to keep in mind that not all values are really relevant when a message is received: you cannot rely on illuminance unless you have occupancy triggered. So you can run your automations only based on occupancy trigger and use illuminance only as a condition. This is actually why I am currently looking at some other illuminance sensors: I want to have the current illuminance in real time.

[ciotlosm]

@ryanbeaton the separate messages were always there. I think there is a config option to avoid resending previous values on new messages just because some didn't want the values resent.

[lolorc]

looks like https://github.com/Koenkk/zigbee2mqtt/commit/04b2f24d6b2d811ad31bb0b23d11f73e7067b391 is the culprit.
I think it's a good idea to store values in a cache, but it's not a good idea to update every mqtt messages with outdated data.
see my comments https://github.com/Koenkk/zigbee-shepherd-converters/pull/63#issuecomment-418763082

The idea of zigbee2mqtt is that each zigbee message will produce one mqtt message. I don't want to wait for the device to check if it will send anymore updates, as this may introduce lag.

agreed ! ;-) guess it's a tricky subject, I don't need the persistence of one mqtt message with all attributes merged from all the device's clusters.

[ryanbeaton]

@ciotlosm what @lolorc has written is what I was getting at. Happy to get seperate message for each attribute but each message should not have cached attributes put in to make a full set

_{Sent with GitHawk}

[KaiboshOz]

Not too sure if the thread has digressed away from OP's issue - but I'm experiencing the same issue intermittently, also with the Xiaomi/Aqara switch (WXKG11LM). Using CC2531 with firmware per the getting started wiki page in case that's relevant.

I have logs showing the double mqtt message, but none with debug on yet as every attempt I've made to force the issue to happen has failed (however it's happened numerous times when I haven't been trying to recreate it). In a previous log, linkquality was the same in the 2 messages, however in the most recent one, they differ.
zigbee2mqtt:info 2018-9-6 21:49:50 MQTT publish, topic: 'zigbee2mqtt/XButtonSquare1', payload: '{"battery":"100.00","voltage":3045,"linkquality":18,"click":"single"}' zigbee2mqtt:info 2018-9-6 21:49:50 MQTT publish, topic: 'zigbee2mqtt/XButtonSquare1', payload: '{"battery":"100.00","voltage":3045,"linkquality":31,"click":"single"}'

Leaving debug on over a couple of days - hopefully I'll catch one.

Edit - forgot something fairly important.. I'm using the hassio addon (hassio-zigbee2mqtt) - posting here because I assume that this relates to zigbee2mqtt rather than the addon specifically.

[KaiboshOz]

Got one.. https://pastebin.com/nxxsnikX

While this one is the result of me pressing the button quite a bit in a short time, the previous instances weren't.

The switch in question "WXKG11LM - Xiaomi Aqara wireless switch" (zigbee2mqtt/XButtonSquare1). There are 4 other devices (including the round buttons), but I've only had this happen with the square one.

Highlighted right at the bottom is 3 mqtt publishes, all identical. When that happened, I noticed the light go a bit weird (i.e. multiple actions - on/off/etc.) A little earlier in the log (about 20 minutes) there's another triple publish also from that button - however I didn't notice anything weird with the light that time..

I've turned debug off, but happy to switch it back on if needed.

[KaiboshOz]

I saw that there was an updated firmware version for the CC2531, so installed it and restarted everything..
Initially ended up with 3 actions being performed (light - on, off, on) per single press. Then the next day that dropped to 2 actions (light - on, off) per single press.
The next day it was a single action and has stayed that way since (now about 2 days). I didn't catch the duplicates in debug as it was off - however it was only happening on the WXKG11LM (Xiaomi Aqara square button). The multiple Xiaomi round buttons that I use didn't have the same issue (and they haven't had this duplication issue at any point).

[stale[bot]]

This issue has been automatically marked as stale because it has not had recent activity. It will be closed if no further activity occurs. Thank you for your contributions.

[thecomalley]

I have a similar issue, Xiaomi MiJia wireless switch (WXKG01LM) - CC2531 - hassio-zigbee2mqtt. I get only a single mqtt message in the addon's log that I can see, but in NodeRed i can see two MQTT messages for every click.

Not a huge deal as i am getting around it by using a deduplicate node.

[Koenkk]

@thecomalley can you check the message on your MQTT server?

[vogler]

~
12/22/2018, 1:09:17 AM - info: MQTT publish: topic 'zigbee2mqtt/Aqara_Temp_Bad', payload '{"temperature":21.51,"linkquality":47,"humidity":41.38,"pressure":949,"battery":99,"voltage":3025}'
12/22/2018, 1:09:17 AM - info: MQTT publish: topic 'zigbee2mqtt/Aqara_Temp_Bad', payload '{"temperature":21.51,"linkquality":47,"humidity":41.3,"pressure":949,"battery":99,"voltage":3025}'
12/22/2018, 1:09:17 AM - info: MQTT publish: topic 'zigbee2mqtt/Aqara_Temp_Bad', payload '{"temperature":21.51,"linkquality":47,"humidity":41.3,"pressure":949,"battery":99,"voltage":3025}'
~

Some option to only have one message would be really nice. Just started playing around, but this is very noisy. Maybe a per-device option for debounce time?
However, it looks like for this sensor humidity on the first message is often different - the other fields don't seem to change.

[Koenkk]

@vogler each zigbee message produces one mqtt message. I dont want to get into any debounce stuff because this add unnecessary delays and complexity.

[meisterlampe]

Observing the same behaviour with Xiaomi Aqara Temp/Humidity sensor. (No problem right now. I was just wondering what happens and found this thread)

The problem is filling up messages with old data isn't it?
Could not every zigbee message produce one mqtt message containing the exact same information from the original zigbee message? Or do Homeassistant and others expect full messages in general?

[Koenkk]

@meisterlampe I don't know about other, but at least home assistant expects this.

[vogler]

Could not every zigbee message produce one mqtt message containing the exact same information from the original zigbee message?

Setting cache_state to false should do this, no?

[Koenkk]

Yes cache_state will do that (but it won't work together with HA then).

[meisterlampe]

Ok. Thanks for the info. Using HA, so I'm loving the cache from now on 😉

So it's basically a HA bug/feature.. working around this for several sensors by debouncing is not the right way to go. I agree with you.

[stale[bot]]

This issue has been automatically marked as stale because it has not had recent activity. It will be closed if no further activity occurs. Thank you for your contributions.

[meisterlampe]

I guess this can be closed. A debounce Option hast landed in https://github.com/Koenkk/zigbee2mqtt/issues/1264