search

Koenkk / zigbee2mqtt

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

QBKG12LM power state wrong when debounce is use #3572

Closed tyjtyj closed 4 years ago

tyjtyj commented 4 years ago

Bug Report

What happened

I reported here but I believe this is a BUG. https://zigbee2mqtt.discourse.group/t/qbkg12lm-spamming-power-non-stop/1195 Wall switch keep sending power update every seconds

I try to stop it by enabling debounce function but introduce a bug.

Initial state off/off

info  2020-05-09 17:27:37: MQTT publish: topic 'zigbee2mqtt/switch_kitchen1', payload '{"power":40.72,"consumption":57.27,"temperature":41,"linkquality":107,"state_left":"OFF","state_right":"OFF"}

Action turn on light. Receive state_left: On <- Correct

info  2020-05-09 17:27:39: MQTT publish: topic 'zigbee2mqtt/switch_kitchen1', payload '{"power":40.72,"consumption":57.27,"temperature":41,"linkquality":107,"state_left":"ON","state_right":"OFF"}'

However receive another wrong test right after that <- Wrong

info  2020-05-09 17:27:39: MQTT publish: topic 'zigbee2mqtt/switch_kitchen1', payload '{"power":0,"consumption":57.27,"temperature":41,"linkquality":102,"state_left":"OFF","state_right":"OFF"}'

What did you expect to happen

Wrong state should not be sent

How to reproduce it (minimal and precise)

turn on the light via mqtt several time within 1 mins.

Debug Info

Zigbee2mqtt version: 1.13.0 Adapter hardware: CC2531, CC2530, CC26X2R1 or CC1352P-2: CC2531 Adapter firmware version: Coordinator version 20190608

Possible cause by File receiver.js. line 31

if (this.isPayloadConflicted(payload, this.debouncers[ieeeAddr].payload, debounceIgnore)) { // publish previous payload immediately this.debouncers[ieeeAddr].publish.flush(); }

Koenkk commented 4 years ago

Please attach the debug logging of this issue.

To enable debug logging set in configuration.yaml:

advanced:
  log_level: debug
tyjtyj commented 4 years ago

See 5th line show off again.

Please note this not always happen.. means like 50%.

debug 2020-05-28 04:47:18: Received MQTT message on 'zigbee2mqtt/switch_kitchen1/left/set' with data 'ON'
debug 2020-05-28 04:47:18: Publishing 'set' 'state' to 'switch_kitchen1'
info  2020-05-28 04:47:18: MQTT publish: topic 'zigbee2mqtt/switch_kitchen1', payload '{"power":37.33,"consumption":59.82,"temperature":39,"linkquality":99,"state_left":"ON","state_right":"ON"}'
debug 2020-05-28 04:47:18: Received Zigbee message from 'switch_kitchen1', type 'attributeReport', cluster 'genOnOff', data '{"61440":117440523,"onOff":1}' from endpoint 1 with groupID 0
info  2020-05-28 04:47:18: newPayload[key] = state_left ON | oldPayload[key] =OFF | Type of string
info  2020-05-28 04:47:18: MQTT publish: topic 'zigbee2mqtt/switch_kitchen1', payload '{"power":28,"consumption":59.82,"temperature":39,"linkquality":99,"state_left":"OFF","state_right":"ON"}'
debug 2020-05-28 04:47:19: Received Zigbee message from 'switch_kitchen1', type 'attributeReport', cluster 'genAnalogInput', data '{"presentValue":37.33000183105469}' from endpoint 3 with groupID 0
info  2020-05-28 04:47:19: newPayload[key] = state_left undefined | oldPayload[key] =ON | Type of undefined
debug 2020-05-28 04:47:22: Received Zigbee message from 'switch_kitchen1', type 'attributeReport', cluster 'genAnalogInput', data '{"presentValue":40.720001220703125}' from endpoint 3 with groupID 0
info  2020-05-28 04:47:22: newPayload[key] = state_left undefined | oldPayload[key] =ON | Type of undefined
debug 2020-05-28 04:47:23: Received Zigbee message from 'switch_kitchen1', type 'attributeReport', cluster 'genAnalogInput', data '{"presentValue":37.33000183105469}' from endpoint 3 with groupID 0
info  2020-05-28 04:47:23: newPayload[key] = state_left undefined | oldPayload[key] =ON | Type of undefined
debug 2020-05-28 04:47:24: Received Zigbee message from 'switch_kitchen1', type 'attributeReport', cluster 'genAnalogInput', data '{"presentValue":40.720001220703125}' from endpoint 3 with groupID 0
info  2020-05-28 04:47:24: newPayload[key] = state_left undefined | oldPayload[key] =ON | Type of undefined
tyjtyj commented 4 years ago

More logs 

debug 2020-05-28 04:51:22: Received MQTT message on 'zigbee2mqtt/switch_kitchen1/left/set' with data 'OFF'
debug 2020-05-28 04:51:22: Publishing 'set' 'state' to 'switch_kitchen1'
info  2020-05-28 04:51:22: MQTT publish: topic 'zigbee2mqtt/switch_kitchen1', payload '{"power":0,"consumption":59.82,"temperature":39,"linkquality":99,"state_left":"OFF","state_right":"OFF"}'
debug 2020-05-28 04:51:22: Received MQTT message on 'zigbee2mqtt/switch_kitchen1/right/set' with data 'OFF'
debug 2020-05-28 04:51:22: Publishing 'set' 'state' to 'switch_kitchen1'
debug 2020-05-28 04:51:22: Received Zigbee message from 'switch_kitchen1', type 'attributeReport', cluster 'genOnOff', data '{"61440":117440541,"onOff":0}' from endpoint 1 with groupID 0
info  2020-05-28 04:51:22: newPayload[key] = state_right undefined | oldPayload[key] =ON | Type of undefined
info  2020-05-28 04:51:22: MQTT publish: topic 'zigbee2mqtt/switch_kitchen1', payload '{"power":0,"consumption":59.82,"temperature":39,"linkquality":99,"state_left":"OFF","state_right":"OFF"}'
debug 2020-05-28 04:51:22: Received Zigbee message from 'switch_kitchen1', type 'attributeReport', cluster 'genOnOff', data '{"61440":117440542,"onOff":0}' from endpoint 2 with groupID 0
info  2020-05-28 04:51:22: newPayload[key] = state_right OFF | oldPayload[key] =ON | Type of string
info  2020-05-28 04:51:22: newPayload[key] = state_left undefined | oldPayload[key] =OFF | Type of undefined
info  2020-05-28 04:51:22: MQTT publish: topic 'zigbee2mqtt/switch_kitchen1', payload '{"power":0,"consumption":59.82,"temperature":39,"linkquality":99,"state_left":"OFF","state_right":"ON"}'
debug 2020-05-28 04:51:25: Received Zigbee message from 'master_bathrm_light', type 'read', cluster 'genTime', data '["time"]' from endpoint 1 with groupID 0
debug 2020-05-28 04:51:25: No converter available for 'QBKG04LM' with cluster 'genTime' and type 'read' and data '["time"]'
debug 2020-05-28 04:51:27: Received Zigbee message from 'mi_repeater_plug1', type 'read', cluster 'genTime', data '["time"]' from endpoint 1 with groupID 0
debug 2020-05-28 04:51:27: No converter available for 'ZNCZ02LM' with cluster 'genTime' and type 'read' and data '["time"]'
debug 2020-05-28 04:51:28: Received MQTT message on 'zigbee2mqtt/switch_kitchen1/left/set' with data 'ON'
debug 2020-05-28 04:51:28: Publishing 'set' 'state' to 'switch_kitchen1'
info  2020-05-28 04:51:28: MQTT publish: topic 'zigbee2mqtt/switch_kitchen1', payload '{"power":0,"consumption":59.82,"temperature":39,"linkquality":99,"state_left":"ON","state_right":"ON"}'
debug 2020-05-28 04:51:28: Received Zigbee message from 'switch_kitchen1', type 'attributeReport', cluster 'genOnOff', data '{"61440":117440543,"onOff":1}' from endpoint 1 with groupID 0
info  2020-05-28 04:51:28: newPayload[key] = state_right undefined | oldPayload[key] =OFF | Type of undefined
debug 2020-05-28 04:51:29: Received MQTT message on 'zigbee2mqtt/switch_kitchen1/right/set' with data 'OFF'
debug 2020-05-28 04:51:29: Publishing 'set' 'state' to 'switch_kitchen1'
info  2020-05-28 04:51:29: MQTT publish: topic 'zigbee2mqtt/switch_kitchen1', payload '{"power":0,"consumption":59.82,"temperature":39,"linkquality":99,"state_left":"ON","state_right":"OFF"}'
debug 2020-05-28 04:51:29: Received Zigbee message from 'switch_kitchen1', type 'attributeReport', cluster 'genOnOff', data '{"61440":117440544,"onOff":0}' from endpoint 2 with groupID 0
info  2020-05-28 04:51:29: newPayload[key] = state_right OFF | oldPayload[key] =OFF | Type of string
info  2020-05-28 04:51:29: newPayload[key] = state_left undefined | oldPayload[key] =ON | Type of undefined
debug 2020-05-28 04:51:29: Received MQTT message on 'zigbee2mqtt/switch_kitchen1/left/set' with data 'OFF'
debug 2020-05-28 04:51:30: Publishing 'set' 'state' to 'switch_kitchen1'
info  2020-05-28 04:51:30: MQTT publish: topic 'zigbee2mqtt/switch_kitchen1', payload '{"power":0,"consumption":59.82,"temperature":39,"linkquality":99,"state_left":"OFF","state_right":"OFF"}'
debug 2020-05-28 04:51:30: Received MQTT message on 'zigbee2mqtt/switch_kitchen1/right/set' with data 'OFF'
debug 2020-05-28 04:51:30: Publishing 'set' 'state' to 'switch_kitchen1'
debug 2020-05-28 04:51:30: Received Zigbee message from 'switch_kitchen1', type 'attributeReport', cluster 'genOnOff', data '{"61440":117440545,"onOff":0}' from endpoint 1 with groupID 0
info  2020-05-28 04:51:30: newPayload[key] = state_right undefined | oldPayload[key] =OFF | Type of undefined
info  2020-05-28 04:51:30: newPayload[key] = state_left OFF | oldPayload[key] =ON | Type of string
info  2020-05-28 04:51:30: MQTT publish: topic 'zigbee2mqtt/switch_kitchen1', payload '{"power":0,"consumption":59.82,"temperature":39,"linkquality":99,"state_left":"ON","state_right":"OFF"}'
info  2020-05-28 04:51:30: MQTT publish: topic 'zigbee2mqtt/switch_kitchen1', payload '{"power":0,"consumption":59.82,"temperature":39,"linkquality":99,"state_left":"ON","state_right":"OFF"}'
debug 2020-05-28 04:51:30: Received Zigbee message from 'switch_kitchen1', type 'attributeReport', cluster 'genOnOff', data '{"61440":117440546,"onOff":0}' from endpoint 2 with groupID 0
info  2020-05-28 04:51:30: newPayload[key] = state_left undefined | oldPayload[key] =OFF | Type of undefined
debug 2020-05-28 04:51:31: Received MQTT message on 'zigbee2mqtt/switch_kitchen1/right/set' with data 'ON'
debug 2020-05-28 04:51:31: Publishing 'set' 'state' to 'switch_kitchen1'
info  2020-05-28 04:51:31: MQTT publish: topic 'zigbee2mqtt/switch_kitchen1', payload '{"power":0,"consumption":59.82,"temperature":39,"linkquality":99,"state_left":"ON","state_right":"ON"}'
debug 2020-05-28 04:51:31: Received Zigbee message from 'switch_kitchen1', type 'attributeReport', cluster 'genOnOff', data '{"61440":117440547,"onOff":1}' from endpoint 2 with groupID 0
info  2020-05-28 04:51:31: newPayload[key] = state_left undefined | oldPayload[key] =OFF | Type of undefined
info  2020-05-28 04:51:31: newPayload[key] = state_right ON | oldPayload[key] =OFF | Type of string
info  2020-05-28 04:51:31: MQTT publish: topic 'zigbee2mqtt/switch_kitchen1', payload '{"power":0,"consumption":59.82,"temperature":39,"linkquality":99,"state_left":"OFF","state_right":"OFF"}'
debug 2020-05-28 04:51:31: Received MQTT message on 'zigbee2mqtt/switch_kitchen1/left/set' with data 'OFF'
debug 2020-05-28 04:51:31: Publishing 'set' 'state' to 'switch_kitchen1'
info  2020-05-28 04:51:31: MQTT publish: topic 'zigbee2mqtt/switch_kitchen1', payload '{"power":0,"consumption":59.82,"temperature":39,"linkquality":99,"state_left":"OFF","state_right":"OFF"}'
debug 2020-05-28 04:51:31: Received MQTT message on 'zigbee2mqtt/switch_kitchen1/right/set' with data 'OFF'
debug 2020-05-28 04:51:31: Publishing 'set' 'state' to 'switch_kitchen1'
debug 2020-05-28 04:51:31: Received Zigbee message from 'switch_kitchen1', type 'attributeReport', cluster 'genOnOff', data '{"61440":117440548,"onOff":0}' from endpoint 1 with groupID 0
info  2020-05-28 04:51:31: newPayload[key] = state_right undefined | oldPayload[key] =ON | Type of undefined
info  2020-05-28 04:51:31: MQTT publish: topic 'zigbee2mqtt/switch_kitchen1', payload '{"power":0,"consumption":59.82,"temperature":39,"linkquality":99,"state_left":"OFF","state_right":"OFF"}'
debug 2020-05-28 04:51:31: Received Zigbee message from 'switch_kitchen1', type 'attributeReport', cluster 'genOnOff', data '{"61440":117440549,"onOff":0}' from endpoint 2 with groupID 0
info  2020-05-28 04:51:31: newPayload[key] = state_right OFF | oldPayload[key] =ON | Type of string
info  2020-05-28 04:51:31: newPayload[key] = state_left undefined | oldPayload[key] =OFF | Type of undefined
info  2020-05-28 04:51:31: MQTT publish: topic 'zigbee2mqtt/switch_kitchen1', payload '{"power":0,"consumption":59.82,"temperature":39,"linkquality":99,"state_left":"OFF","state_right":"ON"}'
Koenkk commented 4 years ago

I think you should ignore the debounce of the state, this is typically something you want to publish immediately. Example config:


devices:
  '0x12345678':
    friendly_name: "my_switch"
    debounce: 60
    debounce_ignore:
      - state_left
      - state_right
tyjtyj commented 4 years ago

I think you should ignore the debounce of the state, this is typically something you want to publish immediately. Example config:

devices:
  '0x12345678':
    friendly_name: "my_switch"
    debounce: 60
    debounce_ignore:
      - state_left
      - state_right

This is my config

'0x00158d00023b2823':
  friendly_name: switch_kitchen1
  debounce: 600
  debounce_ignore:
    - state_right
    - state_left
tyjtyj commented 4 years ago

Let me break down the issue on the log

debug 2020-05-28 04:51:29: Received MQTT message on 'zigbee2mqtt/switch_kitchen1/left/set' with data 'OFF'
debug 2020-05-28 04:51:30: Publishing 'set' 'state' to 'switch_kitchen1'
info  2020-05-28 04:51:30: MQTT publish: topic 'zigbee2mqtt/switch_kitchen1', payload '{"power":0,"consumption":59.82,"temperature":39,"linkquality":99,"state_left":"OFF","state_right":"OFF"}'
debug 2020-05-28 04:51:30: Received MQTT message on 'zigbee2mqtt/switch_kitchen1/right/set' with data 'OFF'
debug 2020-05-28 04:51:30: Publishing 'set' 'state' to 'switch_kitchen1'
debug 2020-05-28 04:51:30: Received Zigbee message from 'switch_kitchen1', type 'attributeReport', cluster 'genOnOff', data '{"61440":117440545,"onOff":0}' from endpoint 1 with groupID 0
info  2020-05-28 04:51:30: newPayload[key] = state_right undefined | oldPayload[key] =OFF | Type of undefined
info  2020-05-28 04:51:30: newPayload[key] = state_left OFF | oldPayload[key] =ON | Type of string
info  2020-05-28 04:51:30: MQTT publish: topic 'zigbee2mqtt/switch_kitchen1', payload '{"power":0,"consumption":59.82,"temperature":39,"linkquality":99,"state_left":"ON","state_right":"OFF"}'
info  2020-05-28 04:51:30: MQTT publish: topic 'zigbee2mqtt/switch_kitchen1', payload '{"power":0,"consumption":59.82,"temperature":39,"linkquality":99,"state_left":"ON","state_right":"OFF"}'
debug 2020-05-28 04:51:30: Received Zigbee message from 'switch_kitchen1', type 'attributeReport', cluster 'genOnOff', data '{"61440":117440546,"onOff":0}' from endpoint 2 with groupID 0
info  2020-05-28 04:51:30: newPayload[key] = state_left undefined | oldPayload[key] =OFF | Type of undefined

Previous state "state_left":"ON","state_right":"OFF"} MQTT RECEIVED set to right ON

debug 2020-05-28 04:51:31: Received MQTT message on 'zigbee2mqtt/switch_kitchen1/right/set' with data 'ON'
debug 2020-05-28 04:51:31: Publishing 'set' 'state' to 'switch_kitchen1'
info  2020-05-28 04:51:31: MQTT publish: topic 'zigbee2mqtt/switch_kitchen1', payload '{"power":0,"consumption":59.82,"temperature":39,"linkquality":99,"state_left":"ON","state_right":"ON"}'

Received "state_left":"ON","state_right":"ON"}. which is correct

debug 2020-05-28 04:51:31: Received Zigbee message from 'switch_kitchen1', type 'attributeReport', cluster 'genOnOff', data '{"61440":117440547,"onOff":1}' from endpoint 2 with groupID 0
info  2020-05-28 04:51:31: newPayload[key] = state_left undefined | oldPayload[key] =OFF | Type of undefined
info  2020-05-28 04:51:31: newPayload[key] = state_right ON | oldPayload[key] =OFF | Type of string
info  2020-05-28 04:51:31: MQTT publish: topic 'zigbee2mqtt/switch_kitchen1', payload '{"power":0,"consumption":59.82,"temperature":39,"linkquality":99,"state_left":"OFF","state_right":"OFF"}'

For unknown reason this wrong state published "state_left":"OFF","state_right":"OFF"}'

debug 2020-05-28 04:51:31: Received MQTT message on 'zigbee2mqtt/switch_kitchen1/left/set' with data 'OFF'
debug 2020-05-28 04:51:31: Publishing 'set' 'state' to 'switch_kitchen1'
info  2020-05-28 04:51:31: MQTT publish: topic 'zigbee2mqtt/switch_kitchen1', payload '{"power":0,"consumption":59.82,"temperature":39,"linkquality":99,"state_left":"OFF","state_right":"OFF"}'
debug 2020-05-28 04:51:31: Received MQTT message on 'zigbee2mqtt/switch_kitchen1/right/set' with data 'OFF'
debug 2020-05-28 04:51:31: Publishing 'set' 'state' to 'switch_kitchen1'
debug 2020-05-28 04:51:31: Received Zigbee message from 'switch_kitchen1', type 'attributeReport', cluster 'genOnOff', data '{"61440":117440548,"onOff":0}' from endpoint 1 with groupID 0
info  2020-05-28 04:51:31: newPayload[key] = state_right undefined | oldPayload[key] =ON | Type of undefined
info  2020-05-28 04:51:31: MQTT publish: topic 'zigbee2mqtt/switch_kitchen1', payload '{"power":0,"consumption":59.82,"temperature":39,"linkquality":99,"state_left":"OFF","state_right":"OFF"}'
debug 2020-05-28 04:51:31: Received Zigbee message from 'switch_kitchen1', type 'attributeReport', cluster 'genOnOff', data '{"61440":117440549,"onOff":0}' from endpoint 2 with groupID 0
info  2020-05-28 04:51:31: newPayload[key] = state_right OFF | oldPayload[key] =ON | Type of string
info  2020-05-28 04:51:31: newPayload[key] = state_left undefined | oldPayload[key] =OFF | Type of undefined
info  2020-05-28 04:51:31: MQTT publish: topic 'zigbee2mqtt/switch_kitchen1', payload '{"power":0,"consumption":59.82,"temperature":39,"linkquality":99,"state_left":"OFF","state_right":"ON"}'
Koenkk commented 4 years ago

Found the issue, should be fixed in latest dev branch, please confirm.

mvjt commented 4 years ago

@Koenkk first of all thank you for all your work with this project. I´ve just moved from Conbee/Deconz to Z2M and it looks promising.

I have debounce issues with latest version inc. dev-branch using Symfonisk Volume controller.

When not using debounce, everything looks like it should in the log.

When using the following settings, I get rotate_left and rotate_stop at the same time after 10s when I stop rotating. I´m expecting to get rotate_left when I start rotating and rotate_stop after 10s when I stop rotating: '0x14b457fffe6b2899': friendly_name: kok_volume_control debounce: 0.5 debounce_ignore:

When I use the following settings, I don´t get rotate_left at all, only rotate_stop '0x14b457fffe6b2899': friendly_name: kok_volume_control debounce: 0.5

Shows the behaviour https://hastebin.com/ozawesudit.http

Without debounce it looks fine https://hastebin.com/owagotuvit.apache

Should I create a new issue or is it related to this one?

Koenkk commented 4 years ago

@mvjt it's not related to this issue so please create a new one

tyjtyj commented 4 years ago

Found the issue, should be fixed in latest dev branch, please confirm.

Sorry, i dont chance to test on production system yet. Please allow until next week. Thanks for the fix.

stale[bot] commented 4 years ago

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.