Two messages on Contact sensor state change instead of one

[rbswift]

What happened

After upgrading, contact sensors now send two messages for each state change: one for the previous state and one for the new state.

What did you expect to happen

Only send a message for the new state. Sending the old state breaks things that are triggered on that event. i.e. Door open event trigger when a door is actually closed. If consumers need the old state always available it can be set to retained. It seems inappropriate to send it when precisely the opposite is in fact what has occurred.

How to reproduce it (minimal and precise)

SONOFF SNZB-04 contact sensor:

Nov 26 09:55:20 alarm npm[4051]: Zigbee2MQTT:info  2021-11-26 09:55:20: MQTT publish: topic 'zigbee2mqtt/backgate', payload '{"battery":60,"battery_low":false,"contact":true,"linkquality":23,"tamper":false,"voltage":2900}'
Nov 26 09:55:20 alarm npm[4051]: Zigbee2MQTT:info  2021-11-26 09:55:20: MQTT publish: topic 'zigbee2mqtt/backgate', payload '{"battery":60,"battery_low":false,"contact":false,"linkquality":5,"tamper":false,"voltage":2900}'
Nov 26 09:56:04 alarm npm[4051]: Zigbee2MQTT:info  2021-11-26 09:56:04: MQTT publish: topic 'zigbee2mqtt/backgate', payload '{"battery":60,"battery_low":false,"contact":false,"linkquality":5,"tamper":false,"voltage":2900}'
Nov 26 09:56:04 alarm npm[4051]: Zigbee2MQTT:info  2021-11-26 09:56:04: MQTT publish: topic 'zigbee2mqtt/backgate', payload '{"battery":60,"battery_low":false,"contact":true,"linkquality":5,"tamper":false,"voltage":2900}'
Nov 26 13:55:41 alarm npm[4051]: Zigbee2MQTT:info  2021-11-26 13:55:41: MQTT publish: topic 'zigbee2mqtt/backgate', payload '{"battery":60,"battery_low":false,"contact":true,"linkquality":5,"tamper":false,"voltage":2900}'
Nov 26 13:55:41 alarm npm[4051]: Zigbee2MQTT:info  2021-11-26 13:55:41: MQTT publish: topic 'zigbee2mqtt/backgate', payload '{"battery":60,"battery_low":false,"contact":false,"linkquality":0,"tamper":false,"voltage":2900}'
Nov 26 13:56:25 alarm npm[4051]: Zigbee2MQTT:info  2021-11-26 13:56:25: MQTT publish: topic 'zigbee2mqtt/backgate', payload '{"battery":60,"battery_low":false,"contact":false,"linkquality":0,"tamper":false,"voltage":2900}'
Nov 26 13:56:25 alarm npm[4051]: Zigbee2MQTT:info  2021-11-26 13:56:25: MQTT publish: topic 'zigbee2mqtt/backgate', payload '{"battery":60,"battery_low":false,"contact":true,"linkquality":15,"tamper":false,"voltage":2900}'
Nov 26 17:15:25 alarm npm[4051]: Zigbee2MQTT:info  2021-11-26 17:15:25: MQTT publish: topic 'zigbee2mqtt/backgate', payload '{"battery":60,"battery_low":false,"contact":true,"linkquality":15,"tamper":false,"voltage":2900}'
Nov 26 17:15:25 alarm npm[4051]: Zigbee2MQTT:info  2021-11-26 17:15:25: MQTT publish: topic 'zigbee2mqtt/backgate', payload '{"battery":60,"battery_low":false,"contact":false,"linkquality":2,"tamper":false,"voltage":2900}'
Nov 26 17:16:23 alarm npm[4051]: Zigbee2MQTT:info  2021-11-26 17:16:23: MQTT publish: topic 'zigbee2mqtt/backgate', payload '{"battery":60,"battery_low":false,"contact":false,"linkquality":2,"tamper":false,"voltage":2900}'
Nov 26 17:16:23 alarm npm[4051]: Zigbee2MQTT:info  2021-11-26 17:16:23: MQTT publish: topic 'zigbee2mqtt/backgate', payload '{"battery":60,"battery_low":false,"contact":true,"linkquality":28,"tamper":false,"voltage":2900}'

Debug info

Zigbee2MQTT version: 1.22.0 commit: df0543d
Coordinator type zStack12
Frontend version 0.6.30
Adapter hardware: CC2531
Adapter firmware version: 20201127

[francisp2]

#9519

[Koenkk]

@rbswift could you provide the debug log of this?

See https://www.zigbee2mqtt.io/guide/usage/debug.html on how to enable debug logging.

[rbswift]

Sure no problem. This example is with log_level: debug

Nov 29 14:28:06 alarm npm[23001]: Zigbee2MQTT:info  2021-11-29 14:28:06: MQTT publish: topic 'zigbee2mqtt/frontgate', payload '{"battery":100,"battery_low":false,"contact":true,"last_seen":"2021-11-29T14:28:06+11:00","linkquality":39,"tamper":false,"voltage":3200}'
Nov 29 14:28:06 alarm npm[23001]: Zigbee2MQTT:debug 2021-11-29 14:28:06: Received Zigbee message from 'frontgate', type 'commandStatusChangeNotification', cluster 'ssIasZone', data '{"extendedstatus":0,"zonestatus":1}' from endpoint 1 with groupID 0
Nov 29 14:28:06 alarm npm[23001]: Zigbee2MQTT:info  2021-11-29 14:28:06: MQTT publish: topic 'zigbee2mqtt/frontgate', payload '{"battery":100,"battery_low":false,"contact":false,"last_seen":"2021-11-29T14:28:06+11:00","linkquality":31,"tamper":false,"voltage":3200}'




Nov 29 14:28:21 alarm npm[23001]: Zigbee2MQTT:info  2021-11-29 14:28:21: MQTT publish: topic 'zigbee2mqtt/frontgate', payload '{"battery":100,"battery_low":false,"contact":false,"last_seen":"2021-11-29T14:28:21+11:00","linkquality":31,"tamper":false,"voltage":3200}'
Nov 29 14:28:22 alarm npm[23001]: Zigbee2MQTT:debug 2021-11-29 14:28:21: Received Zigbee message from 'frontgate', type 'commandStatusChangeNotification', cluster 'ssIasZone', data '{"extendedstatus":0,"zonestatus":0}' from endpoint 1 with groupID 0
Nov 29 14:28:22 alarm npm[23001]: Zigbee2MQTT:info  2021-11-29 14:28:21: MQTT publish: topic 'zigbee2mqtt/frontgate', payload '{"battery":100,"battery_low":false,"contact":true,"last_seen":"2021-11-29T14:28:21+11:00","linkquality":47,"tamper":false,"voltage":3200}'

[Koenkk]

What is logged before: Nov 29 14:28:06 alarm npm[23001]: Zigbee2MQTT:info 2021-11-29 14:28:06: MQTT publish: topic 'zigbee2mqtt/frontgate', payload '{"battery":100,"battery_low":false,"contact":true,"last_seen":"2021-11-29T14:28:06+11:00","linkquality":39,"tamper":false,"voltage":3200}' ?

[rbswift]

Nothing really immediately before except the service startup I think...

Nov 29 14:27:18 alarm systemd[1]: Started zigbee2mqtt.
Nov 29 14:27:20 alarm npm[23001]: > zigbee2mqtt@1.22.0 start
Nov 29 14:27:20 alarm npm[23001]: > node index.js
Nov 29 14:27:26 alarm npm[23001]: Zigbee2MQTT:debug 2021-11-29 14:27:26: Loaded state from file /opt/zigbee2mqtt/data/state.json
Nov 29 14:27:26 alarm npm[23001]: Zigbee2MQTT:info  2021-11-29 14:27:26: Logging to console and directory: '/opt/zigbee2mqtt/data/log/2021-11-29.14-27-23' filename: log.txt
Nov 29 14:27:26 alarm npm[23001]: Zigbee2MQTT:debug 2021-11-29 14:27:26: Removing old log directory '/opt/zigbee2mqtt/data/log/2021-10-15.12-55-21'
Nov 29 14:27:26 alarm npm[23001]: Zigbee2MQTT:info  2021-11-29 14:27:26: Starting Zigbee2MQTT version 1.22.0 (commit #df0543d4)
Nov 29 14:27:26 alarm npm[23001]: Zigbee2MQTT:info  2021-11-29 14:27:26: Starting zigbee-herdsman (0.13.164)
Nov 29 14:27:26 alarm npm[23001]: Zigbee2MQTT:debug 2021-11-29 14:27:26: Using zigbee-herdsman with settings: '{"adapter":{"concurrent":null,"delay":null,"disableLED":false},"backup
Nov 29 14:27:27 alarm npm[23001]: Zigbee2MQTT:info  2021-11-29 14:27:27: zigbee-herdsman started (resumed)
Nov 29 14:27:27 alarm npm[23001]: Zigbee2MQTT:info  2021-11-29 14:27:27: Coordinator firmware version: '{"meta":{"maintrel":3,"majorrel":2,"minorrel":6,"product":0,"revision":202011
Nov 29 14:27:27 alarm npm[23001]: Zigbee2MQTT:debug 2021-11-29 14:27:27: Zigbee network parameters: {"channel":11,"extendedPanID":"0xdddddddddddddddd","panID":6754}
Nov 29 14:27:27 alarm npm[23001]: Zigbee2MQTT:info  2021-11-29 14:27:27: Currently 13 devices are joined:
Nov 29 14:27:27 alarm npm[23001]: Zigbee2MQTT:info  2021-11-29 14:27:27: toiletbutton (0x00124b0022292eab): SNZB-01 - SONOFF Wireless button (EndDevice)
Nov 29 14:27:27 alarm npm[23001]: Zigbee2MQTT:info  2021-11-29 14:27:27: frontgate (0x00124b0022361804): SNZB-04 - SONOFF Contact sensor (EndDevice)
Nov 29 14:27:27 alarm npm[23001]: Zigbee2MQTT:info  2021-11-29 14:27:27: dogflap (0x00124b0022362a05): SNZB-04 - SONOFF Contact sensor (EndDevice)
Nov 29 14:27:27 alarm npm[23001]: Zigbee2MQTT:info  2021-11-29 14:27:27: ikearoundbutton (0xccccccfffe972c89): E1524/E1810 - IKEA TRADFRI remote control (EndDevice)
Nov 29 14:27:28 alarm npm[23001]: Zigbee2MQTT:info  2021-11-29 14:27:28: backgate (0x00124b0022362717): SNZB-04 - SONOFF Contact sensor (EndDevice)
Nov 29 14:27:28 alarm npm[23001]: Zigbee2MQTT:info  2021-11-29 14:27:28: sonofftemperature (0x00124b00222e93d3): SNZB-02 - SONOFF Temperature and humidity sensor (EndDevice)
Nov 29 14:27:28 alarm npm[23001]: Zigbee2MQTT:info  2021-11-29 14:27:28: lightsensor (0x04cf8cdf3c78d6d5): GZCGQ01LM - Xiaomi MiJia light intensity sensor (EndDevice)
Nov 29 14:27:28 alarm npm[23001]: Zigbee2MQTT:info  2021-11-29 14:27:28: bed1smoke (0x000d6f00161f9317): HS3SA - HEIMAN Smoke detector (EndDevice)
Nov 29 14:27:28 alarm npm[23001]: Zigbee2MQTT:info  2021-11-29 14:27:28: bed2smoke (0x000d6f00161f96d4): HS3SA - HEIMAN Smoke detector (EndDevice)
Nov 29 14:27:28 alarm npm[23001]: Zigbee2MQTT:info  2021-11-29 14:27:28: loungesmoke (0x000d6f00161f9539): HS3SA - HEIMAN Smoke detector (EndDevice)
Nov 29 14:27:28 alarm npm[23001]: Zigbee2MQTT:info  2021-11-29 14:27:28: bedsidebutton (0x60a423fffee29c40): TS0043 - TuYa Wireless switch with 3 buttons (EndDevice)
Nov 29 14:27:28 alarm npm[23001]: Zigbee2MQTT:info  2021-11-29 14:27:28: frontdoorlock (0x000d6f0010feb56e): YDD-D4F0-TSDB - Yale Assure lock (EndDevice)
Nov 29 14:27:28 alarm npm[23001]: Zigbee2MQTT:info  2021-11-29 14:27:28: ikeaswitch1 (0x680ae2fffe78a868): E1743 - IKEA TRADFRI ON/OFF switch (EndDevice)
Nov 29 14:27:28 alarm npm[23001]: Zigbee2MQTT:info  2021-11-29 14:27:28: Zigbee: disabling joining new devices.
Nov 29 14:27:28 alarm npm[23001]: Zigbee2MQTT:info  2021-11-29 14:27:28: Connecting to MQTT server at mqtt://localhost
Nov 29 14:27:28 alarm npm[23001]: Zigbee2MQTT:debug 2021-11-29 14:27:28: Using MQTT anonymous login
Nov 29 14:27:28 alarm npm[23001]: Zigbee2MQTT:info  2021-11-29 14:27:28: Connected to MQTT server
Nov 29 14:27:28 alarm npm[23001]: Zigbee2MQTT:info  2021-11-29 14:27:28: MQTT publish: topic 'zigbee2mqtt/bridge/state', payload 'online'
Nov 29 14:27:28 alarm npm[23001]: Zigbee2MQTT:debug 2021-11-29 14:27:28: Received MQTT message on 'zigbee2mqtt/bridge/config' with data '{"commit":"41b67fdd","coordinator":{"meta":{
Nov 29 14:27:28 alarm npm[23001]: Zigbee2MQTT:debug 2021-11-29 14:27:28: Received MQTT message on 'zigbee2mqtt/bridge/info' with data '{"commit":"df0543d4","config":{"advanced":{"ad
Nov 29 14:27:28 alarm npm[23001]: Zigbee2MQTT:debug 2021-11-29 14:27:28: Received MQTT message on 'zigbee2mqtt/bridge/devices' with data '[{"definition":null,"endpoints":{"1":{"bind
Nov 29 14:27:28 alarm npm[23001]: Zigbee2MQTT:debug 2021-11-29 14:27:28: Received MQTT message on 'zigbee2mqtt/bridge/groups' with data '[{"friendly_name":"default_bind_group","id":
Nov 29 14:27:28 alarm npm[23001]: Zigbee2MQTT:debug 2021-11-29 14:27:28: Received MQTT message on 'zigbee2mqtt/bridge/extensions' with data '[]'
Nov 29 14:27:28 alarm npm[23001]: Zigbee2MQTT:debug 2021-11-29 14:27:28: Received MQTT message on 'zigbee2mqtt/sonofftemperature' with data '{"last_seen":"2021-11-25T18:22:36+11:00"
Nov 29 14:27:28 alarm npm[23001]: Zigbee2MQTT:debug 2021-11-29 14:27:28: Received MQTT message on 'zigbee2mqtt/frontdoorlock/set' with data '{"state":"LOCK"}'
Nov 29 14:27:29 alarm npm[23001]: Zigbee2MQTT:warn  2021-11-29 14:27:29: Using experimental new availability feature
Nov 29 14:27:29 alarm npm[23001]: Zigbee2MQTT:info  2021-11-29 14:27:29: Started frontend on port 0.0.0.0:8088
Nov 29 14:27:29 alarm npm[23001]: Zigbee2MQTT:info  2021-11-29 14:27:29: MQTT publish: topic 'zigbee2mqtt/toiletbutton', payload '{"battery":100,"last_seen":"2021-11-29T13:50:39+11:
Nov 29 14:27:29 alarm npm[23001]: Zigbee2MQTT:info  2021-11-29 14:27:29: MQTT publish: topic 'zigbee2mqtt/frontgate', payload '{"battery":100,"battery_low":false,"contact":true,"las
Nov 29 14:27:29 alarm npm[23001]: Zigbee2MQTT:info  2021-11-29 14:27:29: MQTT publish: topic 'zigbee2mqtt/dogflap', payload '{"battery":100,"battery_low":false,"contact":true,"last_
Nov 29 14:27:29 alarm npm[23001]: Zigbee2MQTT:info  2021-11-29 14:27:29: MQTT publish: topic 'zigbee2mqtt/ikearoundbutton', payload '{"battery":87,"last_seen":"2021-11-29T10:44:47+1
Nov 29 14:27:29 alarm npm[23001]: Zigbee2MQTT:info  2021-11-29 14:27:29: MQTT publish: topic 'zigbee2mqtt/backgate', payload '{"battery":60,"battery_low":false,"contact":true,"last_
Nov 29 14:27:29 alarm npm[23001]: Zigbee2MQTT:info  2021-11-29 14:27:29: MQTT publish: topic 'zigbee2mqtt/sonofftemperature', payload '{"last_seen":"2021-11-25T18:22:36+11:00"}'
Nov 29 14:27:29 alarm npm[23001]: Zigbee2MQTT:info  2021-11-29 14:27:29: MQTT publish: topic 'zigbee2mqtt/lightsensor', payload '{"battery":100,"illuminance":38886,"illuminance_lux"
Nov 29 14:27:29 alarm npm[23001]: Zigbee2MQTT:info  2021-11-29 14:27:29: MQTT publish: topic 'zigbee2mqtt/bed1smoke', payload '{"ac_status":false,"battery":100,"battery_low":false,"
Nov 29 14:27:29 alarm npm[23001]: Zigbee2MQTT:info  2021-11-29 14:27:29: MQTT publish: topic 'zigbee2mqtt/bed2smoke', payload '{"ac_status":false,"battery":100,"battery_low":false,"
Nov 29 14:27:29 alarm npm[23001]: Zigbee2MQTT:info  2021-11-29 14:27:29: MQTT publish: topic 'zigbee2mqtt/loungesmoke', payload '{"ac_status":false,"battery":100,"battery_low":false
Nov 29 14:27:29 alarm npm[23001]: Zigbee2MQTT:info  2021-11-29 14:27:29: MQTT publish: topic 'zigbee2mqtt/bedsidebutton', payload '{"last_seen":"2021-11-29T10:57:09+11:00"}'
Nov 29 14:27:29 alarm npm[23001]: Zigbee2MQTT:info  2021-11-29 14:27:29: MQTT publish: topic 'zigbee2mqtt/frontdoorlock', payload '{"battery":95,"last_seen":"2021-11-29T14:26:04+11:
Nov 29 14:27:29 alarm npm[23001]: Zigbee2MQTT:info  2021-11-29 14:27:29: MQTT publish: topic 'zigbee2mqtt/ikeaswitch1', payload '{"battery":87,"last_seen":"2021-11-29T11:09:10+11:00
Nov 29 14:28:06 alarm npm[23001]: Zigbee2MQTT:info  2021-11-29 14:28:06: MQTT publish: topic 'zigbee2mqtt/frontgate', payload '{"battery":100,"battery_low":false,"contact":true,"las

[rbswift]

I'm wondering if this might be related to the last_seen attribute functionality. I can't quite pin it down but it seems to work better with that disabled. Is that possible? Unfortunately I do use that field a lot.

[Koenkk]

Yes, see #9519 , this problem should already be fixed in the dev branch (and tomorrows new release)

[rbswift]

Thanks closing as duplicate of #9519