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.

Sign up for GitHub

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

Jump to bottom

QBKG12LM power state wrong when debounce is use #3572

Closed
tyjtyj opened this issue May 19, 2020 · 11 comments
Closed

QBKG12LM power state wrong when debounce is use #3572

tyjtyj opened this issue May 19, 2020 · 11 comments
Labels
stale Stale issues

Comments

@tyjtyj
Copy link

tyjtyj commented May 19, 2020

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();
}
@tyjtyj tyjtyj changed the title QBKG12LM spamming power change QBKG12LM power state wrong when debounce is use May 19, 2020
@Koenkk
Copy link
Owner

Koenkk commented May 20, 2020

Please attach the debug logging of this issue.

To enable debug logging set in configuration.yaml:

advanced:
  log_level: debug

@tyjtyj
Copy link
Author

tyjtyj commented May 27, 2020

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
Copy link
Author

tyjtyj commented May 27, 2020

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
Copy link
Owner

Koenkk commented May 28, 2020 •
edited
Loading

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
Copy link
Author

tyjtyj commented May 28, 2020

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
Copy link
Author

tyjtyj commented May 28, 2020

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 added a commit that referenced this issue May 29, 2020
@Koenkk
Fix old state being published due to debounce. #3572
5f63dcb
@Koenkk
Copy link
Owner

Koenkk commented May 29, 2020

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

@mvjt
Copy link

mvjt commented Jun 4, 2020 •
edited
Loading

@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:
- action

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
Copy link
Owner

Koenkk commented Jun 6, 2020

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

@tyjtyj
Copy link
Author

tyjtyj commented Jun 6, 2020 •
edited
Loading

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
Copy link

stale bot commented Jul 19, 2020

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.

@stale stale bot added the stale Stale issues label Jul 19, 2020
@stale stale bot closed this as completed Jul 26, 2020
Sign up for free to join this conversation on GitHub. Already have an account? Sign in to comment
Assignees
No one assigned
Labels
stale Stale issues
Projects
None yet
Milestone
No milestone
Development

No branches or pull requests
3 participants
@Koenkk @tyjtyj @mvjt