Skip to content
New issue

Have a question about this project? Sign up for a free GitHub account to open an issue and contact its maintainers and the community.

By clicking “Sign up for GitHub”, you agree to our terms of service and privacy statement. We’ll occasionally send you account related emails.

Already on GitHub? Sign in to your account

Z2M sending multiple MQTT messages for a single sensor payload (last_seen enabled now sends 2 separate mqtt messages) #9519

Closed
marc-gist opened this issue Nov 5, 2021 · 41 comments
Labels
problem Something isn't working stale Stale issues

Comments

@marc-gist
Copy link

What happened

Aquara door sensor when triggered, z2m sends out two MQTT messages, one for the current/previous state, then one for the new state. The sensor is only sending one message. not sure why z2m sends out two messages.

What did you expect to happen

Only one MQTT message with the new state of the sensor.

How to reproduce it (minimal and precise)

Pair an Aquara door sensor and watch the logs/mqtt for that sensor on v1.22

Open Door:

Info MQTT publish: topic 'zigbee/device/0x00158d000273bae6', payload '{"contact":true,"device":{"applicationVersion":3,"dateCode":"20161128","friendlyName":"0x00158d000273bae6","hardwareVersion":2,"ieeeAddr":"0x00158d000273bae6","manufacturerID":4151,"manufacturerName":"LUMI","model":"MCCGQ11LM","networkAddress":21031,"powerSource":"Battery","softwareBuildID":"3000-0001","stackVersion":2,"type":"EndDevice","zclVersion":1},"last_seen":"2021-11-05T13:49:07.800Z","linkquality":141}'
Debug Received Zigbee message from '0x00158d000273bae6', type 'attributeReport', cluster 'genOnOff', data '{"onOff":1}' from endpoint 1 with groupID 0
Info MQTT publish: topic 'zigbee/device/0x00158d000273bae6', payload '{"contact":false,"device":{"applicationVersion":3,"dateCode":"20161128","friendlyName":"0x00158d000273bae6","hardwareVersion":2,"ieeeAddr":"0x00158d000273bae6","manufacturerID":4151,"manufacturerName":"LUMI","model":"MCCGQ11LM","networkAddress":21031,"powerSource":"Battery","softwareBuildID":"3000-0001","stackVersion":2,"type":"EndDevice","zclVersion":1},"last_seen":"2021-11-05T13:49:07.800Z","linkquality":123}'

Close Door:

Info MQTT publish: topic 'zigbee/device/0x00158d000273bae6', payload '{"contact":false,"device":{"applicationVersion":3,"dateCode":"20161128","friendlyName":"0x00158d000273bae6","hardwareVersion":2,"ieeeAddr":"0x00158d000273bae6","manufacturerID":4151,"manufacturerName":"LUMI","model":"MCCGQ11LM","networkAddress":21031,"powerSource":"Battery","softwareBuildID":"3000-0001","stackVersion":2,"type":"EndDevice","zclVersion":1},"last_seen":"2021-11-05T13:51:37.902Z","linkquality":123}'
Debug Received Zigbee message from '0x00158d000273bae6', type 'attributeReport', cluster 'genOnOff', data '{"onOff":0}' from endpoint 1 with groupID 0
Info MQTT publish: topic 'zigbee/device/0x00158d000273bae6', payload '{"contact":true,"device":{"applicationVersion":3,"dateCode":"20161128","friendlyName":"0x00158d000273bae6","hardwareVersion":2,"ieeeAddr":"0x00158d000273bae6","manufacturerID":4151,"manufacturerName":"LUMI","model":"MCCGQ11LM","networkAddress":21031,"powerSource":"Battery","softwareBuildID":"3000-0001","stackVersion":2,"type":"EndDevice","zclVersion":1},"last_seen":"2021-11-05T13:51:37.902Z","linkquality":120}'

Debug info

Zigbee2MQTT version; 1.22.0 commit: 0a1fccf
Coordinator type; zStack3x0
Coordinator revision; 20210120
Frontend version; 0.6.30

@marc-gist marc-gist added the problem Something isn't working label Nov 5, 2021
@marc-gist
Copy link
Author

As an update, I noted that buttons do the same thing, except the "old state" messages for buttons, don't include the action:

Info MQTT publish: topic 'zigbee/device/office_button_2a', payload '{"battery":100,"device":{"applicationVersion":2,"dateCode":"20170731","friendlyName":"office_button_2a","hardwareVersion":1,"ieeeAddr":"0x00158d0001b978b6","manufacturerID":4151,"manufacturerName":"LUMI","model":"WXKG12LM","networkAddress":21725,"powerSource":"Battery","softwareBuildID":"3000-0001","stackVersion":2,"type":"EndDevice","zclVersion":1},"last_seen":"2021-11-05T14:09:21.429Z","linkquality":126,"voltage":3015}'
Info MQTT publish: topic 'zigbee/device/office_button_2a', payload '{"action":"hold","battery":100,"device":{"applicationVersion":2,"dateCode":"20170731","friendlyName":"office_button_2a","hardwareVersion":1,"ieeeAddr":"0x00158d0001b978b6","manufacturerID":4151,"manufacturerName":"LUMI","model":"WXKG12LM","networkAddress":21725,"powerSource":"Battery","softwareBuildID":"3000-0001","stackVersion":2,"type":"EndDevice","zclVersion":1},"last_seen":"2021-11-05T14:09:21.429Z","linkquality":93,"voltage":3015}'

So I am assuming the door sensor issue i'm having is a bug :), or I hope and you can fix easily as my automations go screwy seeing multiple state messages that quickly :)

Thank you.

@z-x-f
Copy link
Contributor

z-x-f commented Nov 6, 2021

I have the same MCCGQ11LM, it works fine with me, the problem may be caused by your software environment.

Debug Received Zigbee message from '0x00158d000204ad5f', type 'attributeReport', cluster 'genOnOff', data '{"onOff":1}' from endpoint 1 with groupID 0
Info MQTT publish: topic 'zigbee2mqtt/0x00158d000204ad5f', payload '{"battery":100,"contact":false,"linkquality":75,"temperature":33,"voltage":3015}'

@marc-gist
Copy link
Author

marc-gist commented Nov 6, 2021

I have the same MCCGQ11LM, it works fine with me, the problem may be caused by your software environment.

Debug Received Zigbee message from '0x00158d000204ad5f', type 'attributeReport', cluster 'genOnOff', data '{"onOff":1}' from endpoint 1 with groupID 0
Info MQTT publish: topic 'zigbee2mqtt/0x00158d000204ad5f', payload '{"battery":100,"contact":false,"linkquality":75,"temperature":33,"voltage":3015}'

strange... what would my software environment have anything to do with it?
Is there a setting for this behaviour? It only started happening when I upgraded to the latest docker build 1.22.0

@z-x-f i assume you are on 1.22.0? do you have cache state set?

@marc-gist
Copy link
Author

@z-x-f could you try turning on "include_device_information" perhaps that is it... or share your configuration file. I need last seen as well in my payloads for automations.

@marc-gist
Copy link
Author

Found the issue! the last_seen: ISO_8601 is now causing duplicate messages. How can we remove this, yet leave the last_seen attribute in the payloads?

@z-x-f
Copy link
Contributor

z-x-f commented Nov 6, 2021

Ah, My last seen is disable.

@marc-gist
Copy link
Author

Ah, My last seen is disable.

enable and see... not sure when last_seen started to spit out separate messages, but hopefully is an easy fix back to old behavour. I have a 1.17.0 running in a remote location that doesn't have this issue :)

@marc-gist marc-gist changed the title Z2M sending multiple MQTT messages for a single Aqara door sensor payload Z2M sending multiple MQTT messages for a single sensor payload (last_seen enabled now sends 2 separate mqtt messages) Nov 6, 2021
@z-x-f
Copy link
Contributor

z-x-f commented Nov 6, 2021

@Koenkk Is this expected behavior ?

@marc-gist
Copy link
Author

@Koenkk Is this expected behavior ?

it wasn't in previous versions, this was added and I can't seem to find it in the release notes as a "new feature".

@marc-gist
Copy link
Author

Is this "fix" causing the extra message? 96657e1

@Koenkk
Copy link
Owner

Koenkk commented Nov 7, 2021

Yes this is expected behaviour

@marc-gist
Copy link
Author

marc-gist commented Nov 7, 2021

Yes this is expected behaviour

this is a breaking change :( Could the notes be updated to reflect this breaking change at a minimum. Ideally I would like this reversed, or an option to Not have the extra payload sent? My automations are now broken and I will have to work around no longer having the old behaviour. Also, the behaviour is inconsistent as I pointed out above.

@Koenkk
Copy link
Owner

Koenkk commented Nov 7, 2021

Why is this a breaking change?

@marc-gist
Copy link
Author

Why is this a breaking change?

With respect, how is it not? You have made a drastic change to how z2m functions. Now my automations fire in quick succession. For example, the door sensor; When opening, it fires the close (previous state) automation, then the open in quick succession. And the reverse when it closes. Why? Its never done that before in the 2 years I've used z2m!

Also, what is the point in sending two messages back to back, the last seen attribute in both?

@Koenkk
Copy link
Owner

Koenkk commented Nov 7, 2021

The reason for this is that the last seen is now based on the last seen event from zigbee-herdsman, previously it was only send when a messages was handled by z2m, but now it is done for every message or event from the device (even when not handled by z2m).

I understand that the double messages may cause troubles for your automations, but you can never assume that one state change produces one message. E.g. it could also be that the device just reports the battery before reporting the contact in that case you will also get 2 messages.

This is fixable but not very easy, I'm willing to fix it if more people experience it as an issue.

@marc-gist
Copy link
Author

I understand that the double messages may cause troubles for your automations, but you can never assume that one state change produces one message. E.g. it could also be that the device just reports the battery before reporting the contact in that case you will also get 2 messages.

I understand double messages. However, those never contain the state... I.e. When sensors report battery, z2m only sends out the information that the sensor sends... my sensors never send the last state/action with the battery or status messages. I have relied on that for years now.

This is fixable but not very easy, I'm willing to fix it if more people experience it as an issue.

Can we not have a simple flag with the last seen (or a new option under last seen), that just adds the last_seen time to the payload as in previous version? Then its hopefully a simple if statement before sending out a new/extra message via mqtt.

@Koenkk
Copy link
Owner

Koenkk commented Nov 7, 2021

Can we not have a simple flag with the last seen (or a new option under last seen), that just adds the last_seen time to the payload as in previous version?

That would be a hacky workaround in my opinion, since the last seen is not really the last seen then anymore. This was exactly the reason why this changed in the first place. Also adding options for these kinds of things would create too many options.

As a workaround you can consider disabling the last_seen option until this is fixed. I don't know where you use it for, but if you use it to determine if a device is offline for a long time you can consider using the improved availability functionality: https://www.zigbee2mqtt.io/guide/configuration/device-availability.html

@marc-gist
Copy link
Author

@Koenkk another issue with me disabling the last seen... now the web interface doesn't show the column for last message received. I rely on this to ensure the health of my network :( not a big deal, as I have worked around this issue by tracking last messages myself, but its very sad to lose such a great feature that worked for me well for so long :(

Could you send only the "last seen" field in the first MQTT message to solve the other issue (or whatever the reason is you added a second message with the old state information)?

@Koenkk
Copy link
Owner

Koenkk commented Nov 11, 2021

@marc-gist have you checked the availability feature? It sounds to me like this is what you want.

@marc-gist
Copy link
Author

marc-gist commented Nov 11, 2021

@marc-gist have you checked the availability feature? It sounds to me like this is what you want.

No offence, but its not, I have similar automations setup, but that feature is lacking. it also doesn't address breaking my automations which, if I enable last_seen, I would have to fix.

This "fix" of yours has changed a number of key, not often used but still key, ways in how I use z2m and is very frustrating/sad :(

@rodrigoscoelho
Copy link

I'm having some delays after migrated to CC2652 too. Specially when I do a local command on an interruptor, and the z2m takes like 4 seconds to receive and update the state... Maybe can be related to this as well..

@thunderboltp7
Copy link

I ran into the same issue with my motion sensors and it caused a lot of problems in my node-red automations until I found this. I disabled my last_seen and set the availability function as suggested by @Koenkk and all is functioning as normal again.

@marc-gist
Copy link
Author

I ran into the same issue with my motion sensors and it caused a lot of problems in my node-red automations until I found this. I disabled my last_seen and set the availability function as suggested by @Koenkk and all is functioning as normal again.

Thanks for the support... at least for my claim that this is a breaking change 😄

Koenkk added a commit to Koenkk/zigbee-herdsman that referenced this issue Nov 27, 2021
@Koenkk
Copy link
Owner

Koenkk commented Nov 27, 2021

Should be fixed now, can you confirm?

Changes will be available in the dev branch in a few hours from now. (https://www.zigbee2mqtt.io/advanced/more/switch-to-dev-branch.html)

Disclaimer: note that you still cannot rely on 1 MQTT message being published, it could be that the device reports two message consecutively as I explained in #9519 (comment). Therefore I still recommend to act on the state change instead of the action.

@thunderboltp7
Copy link

@Koenkk

Sorry, been out of town but just did a quick test using the dev branch. Still seeing the same problem. Did not have debug on but took a quick screenshot of the zigbee2mqtt frontend log.. Other than the occupancy I'm not seeing a difference between the 2 messages per motion sensor. It works fine with the last_seen disabled.

IMG_0003

@Koenkk
Copy link
Owner

Koenkk commented Nov 29, 2021

@thunderboltp7 could you provide the debug logging starting from the point where you start z2m until this happens? I cannot reproduce this locally.

@thunderboltp7
Copy link

thunderboltp7 commented Nov 29, 2021

@Koenkk

Here's the log. Hope it helps
log.txt

Edit:
I noticed that changing the last_seen attribute through the frontend (Settings->Settings->Advanced) does not produce the 2 messages when occupancy changes on my motion sensors. However if I restart zigbee2mqtt then the problem will start again.

@Koenkk
Copy link
Owner

Koenkk commented Nov 30, 2021

@thunderboltp7 you are using the dev version before the fix was added (#a170f30), please update to the latest dev branch

@thunderboltp7
Copy link

Hmmm, that's weird. I pulled it on Sunday night but I cleaned out my docker images and pulled it again. I am not seeing the motion sensor problem anymore, but I did notice my plugs (https://www.zigbee2mqtt.io/devices/SA-003-Zigbee.html#ewelink-sa-003-zigbee) now generate a slew of messages when I turn them on and off. I am attaching the log for you. The plug I turned on and off is the one named "Repeater - Living Room West".

log.txt

@rbswift
Copy link
Contributor

rbswift commented Dec 1, 2021

Thanks everyone for your work tracking this down. My issue #9846 is a duplicate of this so that can be closed. I'm not sure how I didn't find this issue when I searched before as the description is spot on.

I am pleased this is being fixed and agree it was a problematic change. Publishing the exact opposite state to the change that just occurred is quite misleading for subscribers even if the correct state is then published immediately afterwards. Kind of akin to shouting Fire! in a crowded cinema just as the smoke has cleared then shouting No Fire! :)

@rbswift
Copy link
Contributor

rbswift commented Dec 1, 2021

[One positive is I learnt about Device-Availability which I will put to good use but isn't a great substitute for last_seen in all contexts. For example I use a zigbee lux sensor to decide whether to lower blinds or not but if there hasn't been a lux update for a while I will use the calculated sun position instead. Deeming the sensor offline is a bit drastic in that case and would require a significant shortening of the default 25 hour timeout]

@Koenkk
Copy link
Owner

Koenkk commented Dec 1, 2021

@thunderboltp7 looking at your logs your device sends multiple zigbee messages so the behaviour from z2m is correct. If you want to prevent zigbee2mqtt publishing all messages from this device you could use the debounce functionality: https://www.zigbee2mqtt.io/guide/configuration/devices-groups.html#common-device-options

@thunderboltp7
Copy link

Ok, thanks. I guess that changed with this release because in 1.21.2 I only get 1 message.

@sstefanowski
Copy link

sstefanowski commented Dec 18, 2021

Hello @Koenkk,
Is this fixed in HA Addon? I'm using Z2M in HA Supervised container - the latest version of HA addon 1.22.1-1 containing Z2M 1.22.1

I searched thru the issue history and I think my situation is somehow strange

  • I've just bought Sonoff Zigbee 3.0 USB Dongle (came from Itead pre-flashed with latest stable firmware from you - "20210708").
  • I'm using setting last_seen: epoch and could see many MQTT publishes and many of them are duplicated - they are totally the same (including the value of last_seen in miliseconds).
  • Setting last_seen: disable fixes the issue, Z2M publishes single MQTT for many received payloads (I can see duplicated payloads in debug logs and single MQTT is in info log) but I really want to use last_seen: epoch information in my automations.
  • The problem is even worse as I'm using quite a few routers Sonoff BASICZBR3, which had and issue of duplicated logs solved in zigbee_herdsman_converted project here (Sending multiple/duplicate messages in groups of 6 #3687). I know this should be fixed and I don't know if this makes any difference for last_seen issue, but.... for BASICZBR3 routers I can see even 12 duplicated entries - this is a lot! (see part of log below). For the other devices I can see just two/three duplicated entries.

If this is fixed in 1.21.2 (as post above from @thunderboltp7 stated) then... is this possible the change in not in addon version 1.21.1-1?

The latest addon release note says:

Addon Version 1.22.1-1

  • Updated Zigbee2MQTT to version 1.22.1
Zigbee2MQTT:debug 2021-12-18 20:01:20: Received Zigbee message from 'Sonoff ZBR3 (Ewelina)', type 'attributeReport', cluster 'genOnOff', data '{"onOff":0}' from endpoint 1 with groupID 0
Zigbee2MQTT:debug 2021-12-18 20:01:20: Received Zigbee message from 'Sonoff ZBR3 (Ewelina)', type 'attributeReport', cluster 'genOnOff', data '{"onOff":0}' from endpoint 1 with groupID 0
Zigbee2MQTT:debug 2021-12-18 20:01:20: Received Zigbee message from 'Sonoff ZBR3 (Ewelina)', type 'attributeReport', cluster 'genOnOff', data '{"onOff":0}' from endpoint 1 with groupID 0
Zigbee2MQTT:debug 2021-12-18 20:01:20: Received Zigbee message from 'Sonoff ZBR3 (Ewelina)', type 'attributeReport', cluster 'genOnOff', data '{"onOff":0}' from endpoint 1 with groupID 0
Zigbee2MQTT:debug 2021-12-18 20:01:20: Received Zigbee message from 'Sonoff ZBR3 (Ewelina)', type 'attributeReport', cluster 'genOnOff', data '{"onOff":0}' from endpoint 1 with groupID 0
Zigbee2MQTT:debug 2021-12-18 20:01:20: Received Zigbee message from 'Sonoff ZBR3 (Ewelina)', type 'attributeReport', cluster 'genOnOff', data '{"onOff":0}' from endpoint 1 with groupID 0
Zigbee2MQTT:debug 2021-12-18 20:01:20: Received Zigbee message from 'Sonoff ZBR3 (Ewelina)', type 'attributeReport', cluster 'genOnOff', data '{"onOff":0}' from endpoint 1 with groupID 0
Zigbee2MQTT:debug 2021-12-18 20:01:20: Received Zigbee message from 'Sonoff ZBR3 (Ewelina)', type 'attributeReport', cluster 'genOnOff', data '{"onOff":0}' from endpoint 1 with groupID 0
Zigbee2MQTT:debug 2021-12-18 20:01:20: Received Zigbee message from 'Sonoff ZBR3 (Ewelina)', type 'attributeReport', cluster 'genOnOff', data '{"onOff":0}' from endpoint 1 with groupID 0
Zigbee2MQTT:debug 2021-12-18 20:01:20: Received Zigbee message from 'Sonoff ZBR3 (Ewelina)', type 'attributeReport', cluster 'genOnOff', data '{"onOff":0}' from endpoint 1 with groupID 0
Zigbee2MQTT:debug 2021-12-18 20:01:20: Received Zigbee message from 'Sonoff ZBR3 (Ewelina)', type 'attributeReport', cluster 'genOnOff', data '{"onOff":0}' from endpoint 1 with groupID 0
Zigbee2MQTT:debug 2021-12-18 20:01:20: Received Zigbee message from 'Sonoff ZBR3 (Ewelina)', type 'attributeReport', cluster 'genOnOff', data '{"onOff":0}' from endpoint 1 with groupID 0
Zigbee2MQTT:info  2021-12-18 20:01:20: MQTT publish: topic 'zigbee2mqtt/Sonoff ZBR3 (Ewelina)', payload '{"device":{"applicationVersion":4,"dateCode":"20201026","friendlyName":"Sonoff ZBR3 (Ewelina)","hardwareVersion":1,"ieeeAddr":"0x00124b0022678dd4","manufacturerID":0,"manufacturerName":"SONOFF","model":"BASICZBR3","networkAddress":28424,"powerSource":"Mains (single phase)","softwareBuildID":"1.0.3","type":"Router","zclVersion":1},"last_seen":1639854080310,"linkquality":60,"state":"OFF"}'
Zigbee2MQTT:info  2021-12-18 20:01:20: MQTT publish: topic 'zigbee2mqtt/Sonoff ZBR3 (Ewelina)', payload '{"device":{"applicationVersion":4,"dateCode":"20201026","friendlyName":"Sonoff ZBR3 (Ewelina)","hardwareVersion":1,"ieeeAddr":"0x00124b0022678dd4","manufacturerID":0,"manufacturerName":"SONOFF","model":"BASICZBR3","networkAddress":28424,"powerSource":"Mains (single phase)","softwareBuildID":"1.0.3","type":"Router","zclVersion":1},"last_seen":1639854080310,"linkquality":60,"state":"OFF"}'
Zigbee2MQTT:info  2021-12-18 20:01:20: MQTT publish: topic 'zigbee2mqtt/Sonoff ZBR3 (Ewelina)', payload '{"device":{"applicationVersion":4,"dateCode":"20201026","friendlyName":"Sonoff ZBR3 (Ewelina)","hardwareVersion":1,"ieeeAddr":"0x00124b0022678dd4","manufacturerID":0,"manufacturerName":"SONOFF","model":"BASICZBR3","networkAddress":28424,"powerSource":"Mains (single phase)","softwareBuildID":"1.0.3","type":"Router","zclVersion":1},"last_seen":1639854080310,"linkquality":60,"state":"OFF"}'
Zigbee2MQTT:info  2021-12-18 20:01:20: MQTT publish: topic 'zigbee2mqtt/Sonoff ZBR3 (Ewelina)', payload '{"device":{"applicationVersion":4,"dateCode":"20201026","friendlyName":"Sonoff ZBR3 (Ewelina)","hardwareVersion":1,"ieeeAddr":"0x00124b0022678dd4","manufacturerID":0,"manufacturerName":"SONOFF","model":"BASICZBR3","networkAddress":28424,"powerSource":"Mains (single phase)","softwareBuildID":"1.0.3","type":"Router","zclVersion":1},"last_seen":1639854080310,"linkquality":60,"state":"OFF"}'
Zigbee2MQTT:info  2021-12-18 20:01:20: MQTT publish: topic 'zigbee2mqtt/Sonoff ZBR3 (Ewelina)', payload '{"device":{"applicationVersion":4,"dateCode":"20201026","friendlyName":"Sonoff ZBR3 (Ewelina)","hardwareVersion":1,"ieeeAddr":"0x00124b0022678dd4","manufacturerID":0,"manufacturerName":"SONOFF","model":"BASICZBR3","networkAddress":28424,"powerSource":"Mains (single phase)","softwareBuildID":"1.0.3","type":"Router","zclVersion":1},"last_seen":1639854080310,"linkquality":60,"state":"OFF"}'
Zigbee2MQTT:info  2021-12-18 20:01:20: MQTT publish: topic 'zigbee2mqtt/Sonoff ZBR3 (Ewelina)', payload '{"device":{"applicationVersion":4,"dateCode":"20201026","friendlyName":"Sonoff ZBR3 (Ewelina)","hardwareVersion":1,"ieeeAddr":"0x00124b0022678dd4","manufacturerID":0,"manufacturerName":"SONOFF","model":"BASICZBR3","networkAddress":28424,"powerSource":"Mains (single phase)","softwareBuildID":"1.0.3","type":"Router","zclVersion":1},"last_seen":1639854080310,"linkquality":60,"state":"OFF"}'
Zigbee2MQTT:info  2021-12-18 20:01:20: MQTT publish: topic 'zigbee2mqtt/Sonoff ZBR3 (Ewelina)', payload '{"device":{"applicationVersion":4,"dateCode":"20201026","friendlyName":"Sonoff ZBR3 (Ewelina)","hardwareVersion":1,"ieeeAddr":"0x00124b0022678dd4","manufacturerID":0,"manufacturerName":"SONOFF","model":"BASICZBR3","networkAddress":28424,"powerSource":"Mains (single phase)","softwareBuildID":"1.0.3","type":"Router","zclVersion":1},"last_seen":1639854080310,"linkquality":60,"state":"OFF"}'
Zigbee2MQTT:info  2021-12-18 20:01:20: MQTT publish: topic 'zigbee2mqtt/Sonoff ZBR3 (Ewelina)', payload '{"device":{"applicationVersion":4,"dateCode":"20201026","friendlyName":"Sonoff ZBR3 (Ewelina)","hardwareVersion":1,"ieeeAddr":"0x00124b0022678dd4","manufacturerID":0,"manufacturerName":"SONOFF","model":"BASICZBR3","networkAddress":28424,"powerSource":"Mains (single phase)","softwareBuildID":"1.0.3","type":"Router","zclVersion":1},"last_seen":1639854080310,"linkquality":60,"state":"OFF"}'
Zigbee2MQTT:info  2021-12-18 20:01:20: MQTT publish: topic 'zigbee2mqtt/Sonoff ZBR3 (Ewelina)', payload '{"device":{"applicationVersion":4,"dateCode":"20201026","friendlyName":"Sonoff ZBR3 (Ewelina)","hardwareVersion":1,"ieeeAddr":"0x00124b0022678dd4","manufacturerID":0,"manufacturerName":"SONOFF","model":"BASICZBR3","networkAddress":28424,"powerSource":"Mains (single phase)","softwareBuildID":"1.0.3","type":"Router","zclVersion":1},"last_seen":1639854080310,"linkquality":60,"state":"OFF"}'
Zigbee2MQTT:info  2021-12-18 20:01:20: MQTT publish: topic 'zigbee2mqtt/Sonoff ZBR3 (Ewelina)', payload '{"device":{"applicationVersion":4,"dateCode":"20201026","friendlyName":"Sonoff ZBR3 (Ewelina)","hardwareVersion":1,"ieeeAddr":"0x00124b0022678dd4","manufacturerID":0,"manufacturerName":"SONOFF","model":"BASICZBR3","networkAddress":28424,"powerSource":"Mains (single phase)","softwareBuildID":"1.0.3","type":"Router","zclVersion":1},"last_seen":1639854080310,"linkquality":60,"state":"OFF"}'
Zigbee2MQTT:info  2021-12-18 20:01:20: MQTT publish: topic 'zigbee2mqtt/Sonoff ZBR3 (Ewelina)', payload '{"device":{"applicationVersion":4,"dateCode":"20201026","friendlyName":"Sonoff ZBR3 (Ewelina)","hardwareVersion":1,"ieeeAddr":"0x00124b0022678dd4","manufacturerID":0,"manufacturerName":"SONOFF","model":"BASICZBR3","networkAddress":28424,"powerSource":"Mains (single phase)","softwareBuildID":"1.0.3","type":"Router","zclVersion":1},"last_seen":1639854080310,"linkquality":60,"state":"OFF"}'
Zigbee2MQTT:info  2021-12-18 20:01:20: MQTT publish: topic 'zigbee2mqtt/Sonoff ZBR3 (Ewelina)', payload '{"device":{"applicationVersion":4,"dateCode":"20201026","friendlyName":"Sonoff ZBR3 (Ewelina)","hardwareVersion":1,"ieeeAddr":"0x00124b0022678dd4","manufacturerID":0,"manufacturerName":"SONOFF","model":"BASICZBR3","networkAddress":28424,"powerSource":"Mains (single phase)","softwareBuildID":"1.0.3","type":"Router","zclVersion":1},"last_seen":1639854080310,"linkquality":60,"state":"OFF"}'

@github-actions
Copy link
Contributor

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

@github-actions github-actions bot added the stale Stale issues label Jan 18, 2022
@rbswift
Copy link
Contributor

rbswift commented Mar 15, 2022

I'm seeing duplicate messages again on a newly joined Ikea LED1935C3:

Mar 15 15:26:12 zigbee2mqtt/lamp/set {"state":"OFF"}
Mar 15 15:26:12 zigbee2mqtt/lamp {"brightness":254,"last_seen":"2022-03-15T15:26:12+11:00","linkquality":54,"power_on_behavior":"previous","state":"ON","update":{"state":"idle"}}
Mar 15 15:26:12 zigbee2mqtt/lamp {"brightness":254,"last_seen":"2022-03-15T15:26:12+11:00","linkquality":54,"power_on_behavior":"previous","state":"OFF","update":{"state":"idle"}}

Any suggestions on how to stop the intermediate message with the incorrect state?
Thanks

@convicte
Copy link

convicte commented Aug 12, 2022

I'd like to kindly ask to have this issue reopened, or at least have it reviewed in the scope of issues I am facing with several Zigbee shutters in my system.
The outcome of the situation is very similar to other users above, where my NodeRed automations are being completely messed up by the shutter spamming MQTT with between 3 and 9 messages per every actuation. Furthermore, since there are so many messages, HA fails to correctly apply attributes to these messages (crucially user_id—for 'who actuated the shutter"), but also having messages that make little sense in general.

To give an example, a single switch from position 100 to position 70 results in this message stream:
image
Which when converted to HA/NodeRed is actually even worse because there are duplications and/or messages added at the beginning or the end of the sequence:
image
This is with last_seen disabled, because with this feature enabled, the number of messages increases by 1.5-2.0 times.
See below for a single actuation with last_seen: ISO8601_local:
image

In addition, chaotic messages published into HA information stream by shutters that actually did not move further exacerbate the problem.

My ultimate goal is to use the user_id attribute, attached to different service calls in HA, as the indication whom actuate the shutter. This is to determine if the automation should override this input next time around, because it was another automation task before it or shouldn't touch it, because one of the users and/or wall button changed the position.

This works flawlessly for my lights, with (also) a Zigbee switch from the same company (https://www.zigbee2mqtt.io/devices/X713A.html), but fails completely due to this message spam on devices such as https://www.zigbee2mqtt.io/devices/TS130F_dual.html.

I recognize the difference between the above and me—where in my case there are subtle changes in the device state, the states published are mostly redundant. The actuation starts from STOP, 100%, goes to STOP, in the next message, then to ,100%, then to STOP again. While this is happening in Z2m the HA and NodeRed produce a blast of messages within 1 second, with completely messed up attributes, where the old_state vs. new_state parameters change places or are listed as null.

Example of 2 consecutive messages from the same actuation done by 'Supervisor' which in other words is 'not by humane'.
The message above has a new_state - context.attribute of user_id assigned correctly with the ID of the supervisor. The next message, however, which is generated as a slight change in attributes (not the payload) is taking the new_state user_id and puts it as a old_state ID, while having nothing to put in the new_state, filling it in with null.
image

This super simple switch in NodeRed works perfectly for the lights described above, but for the shutters, it's a complete mess. The attribute listed is changing multiple times within a second for each actuation. Depending on the initial state (closed/open/who last actuated it) you cannot use filtration (RBE, Wait till, rate limiting), since the stochastic nature of the process is just too random to effectively capture all the possible combinations.
image

I know it's a lot of information and I may not have been clear in all areas, so please feel free to ask follow-up questions.
Thank you in advance for assistance!

@zen2
Copy link

zen2 commented Aug 12, 2022

Do you have try to use a debounce of 1s for this device ?

@convicte
Copy link

convicte commented Aug 12, 2022

Do you have try to use a debounce of 1s for this device ?

I did try it before, in the earlier stages of troubleshooting, when I didn't have the full picture.
At that time, everything was very chaotic, so I wasn't sure if I may have not understood how it should work.

I've tried it again just a second ago (with last_seen: ON), and it seems to either not work at all or have no effect:
image
image

Am I doing something wrong, or it's really not working?
There are clearly 4 messages in a single second.

@jjarven
Copy link

jjarven commented Jan 29, 2023

I have this issue too with Zigbee2MQTT version [1.29.2] - turning on the lights was pain, it would turn them on for a less than a second and turn them off again (even when doing the on-off cycle from the web-interface).

This could be circumvented by turning on the lights in a rapid succession and some point the light would just stay on (or by using the mosquitto_pub-command once or twice from CLI).

Currently I'm trying with the disabling the last seen option. Debounce setting did not help for me.

@Wielebny666
Copy link

Wielebny666 commented Oct 27, 2023

The issue still exists :-(
Regardless of whether the last_seen option is enabled or not...
Exactly the same behavior on RPi and docker
Wersja Zigbee2MQTT
1.33.1 commit: 7e63039

debug 2023-10-27 08:48:07: Received MQTT message on ‘zigbee2mqtt/hallway_outdoor_lights_triple_switch/set’ with data ‘{“state_l1”:“ON”}’ debug 2023-10-27 08:48:07: Publishing ‘set’ ‘state’ to ‘hallway_outdoor_lights_triple_switch’ info 2023-10-27 08:48:07: MQTT publish: topic ‘zigbee2mqtt/hallway_outdoor_lights_triple_switch’, payload ‘{“backlight_mode”:“OFF”,“last_seen”:“2023-10-27T08:48:07+02:00”,“linkquality”:142,“power_on_behavior”:“off”,“power_on_behavior_l1”:“off”,“state_l1”:“OFF”,“state_l2”:“OFF”,“state_l3”:“OFF”,“switch_type”:“toggle”}’ info 2023-10-27 08:48:07: MQTT publish: topic ‘zigbee2mqtt/hallway_outdoor_lights_triple_switch’, payload ‘{“backlight_mode”:“OFF”,“last_seen”:“2023-10-27T08:48:07+02:00”,“linkquality”:142,“power_on_behavior”:“off”,“power_on_behavior_l1”:“off”,“state_l1”:“ON”,“state_l2”:“OFF”,“state_l3”:“OFF”,“switch_type”:“toggle”}’ debug 2023-10-27 08:48:07: Received Zigbee message from ‘hallway_outdoor_lights_triple_switch’, type ‘attributeReport’, cluster ‘genOnOff’, data ‘{“onOff”:1}’ from endpoint 1 with groupID 0 info 2023-10-27 08:48:07: MQTT publish: topic ‘zigbee2mqtt/hallway_outdoor_lights_triple_switch’, payload ‘{“action”:“on_l1”,“backlight_mode”:“OFF”,“last_seen”:“2023-10-27T08:48:07+02:00”,“linkquality”:142,“power_on_behavior”:“off”,“power_on_behavior_l1”:“off”,“state_l1”:“ON”,“state_l2”:“OFF”,“state_l3”:“OFF”,“switch_type”:“toggle”}’ info 2023-10-27 08:48:07: MQTT publish: topic ‘zigbee2mqtt/hallway_outdoor_lights_triple_switch’, payload ‘{“action”:“”,“backlight_mode”:“OFF”,“last_seen”:“2023-10-27T08:48:07+02:00”,“linkquality”:142,“power_on_behavior”:“off”,“power_on_behavior_l1”:“off”,“state_l1”:“ON”,“state_l2”:“OFF”,“state_l3”:“OFF”,“switch_type”:“toggle”}’ info 2023-10-27 08:48:07: MQTT publish: topic ‘zigbee2mqtt/hallway_outdoor_lights_triple_switch/action’, payload ‘on_l1’ debug 2023-10-27 08:48:10: Received Zigbee message from ‘hallway_outdoor_lights_triple_switch’, type ‘attributeReport’, cluster ‘genOnOff’, data ‘{“onOff”:1}’ from endpoint 1 with groupID 0 info 2023-10-27 08:48:10: MQTT publish: topic ‘zigbee2mqtt/hallway_outdoor_lights_triple_switch’, payload ‘{“action”:“on_l1”,“backlight_mode”:“OFF”,“last_seen”:“2023-10-27T08:48:10+02:00”,“linkquality”:142,“power_on_behavior”:“off”,“power_on_behavior_l1”:“off”,“state_l1”:“ON”,“state_l2”:“OFF”,“state_l3”:“OFF”,“switch_type”:“toggle”}’ info 2023-10-27 08:48:10: MQTT publish: topic ‘zigbee2mqtt/hallway_outdoor_lights_triple_switch’, payload ‘{“action”:“”,“backlight_mode”:“OFF”,“last_seen”:“2023-10-27T08:48:10+02:00”,“linkquality”:142,“power_on_behavior”:“off”,“power_on_behavior_l1”:“off”,“state_l1”:“ON”,“state_l2”:“OFF”,“state_l3”:“OFF”,“switch_type”:“toggle”}’ info 2023-10-27 08:48:10: MQTT publish: topic ‘zigbee2mqtt/hallway_outdoor_lights_triple_switch/action’, payload ‘on_l1’

Sign up for free to join this conversation on GitHub. Already have an account? Sign in to comment
Labels
problem Something isn't working stale Stale issues
Projects
None yet
Development

No branches or pull requests