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

State reported twice #1155

Closed
GForce2010 opened this Issue Feb 24, 2019 · 11 comments

Comments

Projects
None yet
3 participants
@GForce2010
Copy link

GForce2010 commented Feb 24, 2019

I just wanted to check to see if the behaviour I am seeing is what is supposed to happen.

I have zigbee2mqtt setup and I am controlling it via OpenHab.

When I send a command to change the brightness of a lamp I get two responses in the state topic, the first one is the current brightness and the second one is the new brightness I have requested. Everything is working but it causes the on screen control in OpenHab to flicker during the state change.

If that's how it works then fine but is there a way to disable to first state report?

Thanks.

@Koenkk

This comment has been minimized.

Copy link
Owner

Koenkk commented Feb 25, 2019

Can you post the log of this?

@Kryzek

This comment has been minimized.

Copy link

Kryzek commented Feb 25, 2019

I experience this too so I think I can also provide some log:

  zigbee2mqtt:debug 2/25/2019, 12:08:30 PM Received MQTT message on 'zigbee2mqtt/0x00158d0001cded1c/set' with data '{"state": "ON"}'
  zigbee2mqtt:info 2/25/2019, 12:08:30 PM Zigbee publish to device '0x00158d0001cded1c', genOnOff - on - {} - {"manufSpec":0,"disDefaultRsp":0} - null
  zigbee2mqtt:info 2/25/2019, 12:08:30 PM MQTT publish: topic 'zigbee2mqtt/0x00158d0001cded1c', payload '{"brightness":108,"linkquality":34,"state":"ON","last_seen":"2019-01-18T08:31:49.504Z"}'
  zigbee2mqtt:debug 2/25/2019, 12:08:30 PM Received zigbee message of type 'attReport' with data '{"cid":"genOnOff","data":{"onOff":1}}' of device 'ZBT-DimmableLight' (0x00158d0001cded1c)
  zigbee2mqtt:info 2/25/2019, 12:08:30 PM MQTT publish: topic 'zigbee2mqtt/0x00158d0001cded1c', payload '{"brightness":108,"linkquality":34,"state":"ON","last_seen":"2019-01-18T08:31:49.504Z"}'
  zigbee2mqtt:debug 2/25/2019, 12:08:30 PM Received zigbee message of type 'devChange' with data '{"cid":"genOnOff","data":{"onOff":1}}' of device 'ZBT-DimmableLight' (0x00158d0001cded1c)
  zigbee2mqtt:info 2/25/2019, 12:08:30 PM MQTT publish: topic 'zigbee2mqtt/0x00158d0001cded1c', payload '{"brightness":108,"linkquality":34,"state":"ON","last_seen":"2019-01-18T08:31:49.504Z"}'
  zigbee2mqtt:debug 2/25/2019, 12:08:30 PM Received zigbee message of type 'devChange' with data '{"cid":"genOnOff","data":{"onOff":1}}' of device 'ZBT-DimmableLight' (0x00158d0001cded1c)
  zigbee2mqtt:info 2/25/2019, 12:08:30 PM MQTT publish: topic 'zigbee2mqtt/0x00158d0001cded1c', payload '{"brightness":108,"linkquality":34,"state":"ON","last_seen":"2019-01-18T08:31:49.504Z"}'
  zigbee2mqtt:debug 2/25/2019, 12:08:50 PM Received MQTT message on 'zigbee2mqtt/0x00158d0001cded1c/set' with data '{"state": "ON", "brightness": 93}'
  zigbee2mqtt:debug 2/25/2019, 12:08:50 PM Skipping 'state' because of 'brightness'
  zigbee2mqtt:info 2/25/2019, 12:08:50 PM Zigbee publish to device '0x00158d0001cded1c', genLevelCtrl - moveToLevelWithOnOff - {"level":93,"transtime":0} - {"manufSpec":0,"disDefaultRsp":0} - null
  zigbee2mqtt:info 2/25/2019, 12:08:50 PM MQTT publish: topic 'zigbee2mqtt/0x00158d0001cded1c', payload '{"brightness":108,"linkquality":34,"state":"ON","last_seen":"2019-01-18T08:31:49.504Z"}'
  zigbee2mqtt:debug 2/25/2019, 12:08:50 PM Received zigbee message of type 'attReport' with data '{"cid":"genLevelCtrl","data":{"currentLevel":93}}' of device 'ZBT-DimmableLight' (0x00158d0001cded1c)
  zigbee2mqtt:info 2/25/2019, 12:08:50 PM MQTT publish: topic 'zigbee2mqtt/0x00158d0001cded1c', payload '{"brightness":93,"linkquality":36,"state":"ON","last_seen":"2019-01-18T08:31:49.504Z"}'
  zigbee2mqtt:debug 2/25/2019, 12:08:50 PM Received zigbee message of type 'devChange' with data '{"cid":"genLevelCtrl","data":{"currentLevel":93}}' of device 'ZBT-DimmableLight' (0x00158d0001cded1c)
  zigbee2mqtt:info 2/25/2019, 12:08:50 PM MQTT publish: topic 'zigbee2mqtt/0x00158d0001cded1c', payload '{"brightness":93,"linkquality":36,"state":"ON","last_seen":"2019-01-18T08:31:49.504Z"}'
  zigbee2mqtt:info 2/25/2019, 12:08:50 PM Zigbee publish to device '0x00158d0001cded1c', genLevelCtrl - read - [{"attrId":0}] - {"manufSpec":0,"disDefaultRsp":0} - null
  zigbee2mqtt:debug 2/25/2019, 12:08:50 PM Received zigbee message of type 'devChange' with data '{"cid":"genLevelCtrl","data":{"currentLevel":93}}' of device 'ZBT-DimmableLight' (0x00158d0001cded1c)
  zigbee2mqtt:info 2/25/2019, 12:08:50 PM MQTT publish: topic 'zigbee2mqtt/0x00158d0001cded1c', payload '{"brightness":93,"linkquality":36,"state":"ON","last_seen":"2019-01-18T08:31:49.504Z"}'
  zigbee2mqtt:debug 2/25/2019, 12:09:02 PM Received MQTT message on 'zigbee2mqtt/0x00158d0001cded1c/set' with data '{"state": "OFF"}'
  zigbee2mqtt:info 2/25/2019, 12:09:02 PM Zigbee publish to device '0x00158d0001cded1c', genOnOff - off - {} - {"manufSpec":0,"disDefaultRsp":0} - null
  zigbee2mqtt:info 2/25/2019, 12:09:02 PM MQTT publish: topic 'zigbee2mqtt/0x00158d0001cded1c', payload '{"brightness":93,"linkquality":36,"state":"OFF","last_seen":"2019-01-18T08:31:49.504Z"}'
  zigbee2mqtt:debug 2/25/2019, 12:09:02 PM Received zigbee message of type 'attReport' with data '{"cid":"genOnOff","data":{"onOff":0}}' of device 'ZBT-DimmableLight' (0x00158d0001cded1c)
  zigbee2mqtt:info 2/25/2019, 12:09:02 PM MQTT publish: topic 'zigbee2mqtt/0x00158d0001cded1c', payload '{"brightness":93,"linkquality":34,"state":"OFF","last_seen":"2019-01-18T08:31:49.504Z"}'
  zigbee2mqtt:debug 2/25/2019, 12:09:02 PM Received zigbee message of type 'devChange' with data '{"cid":"genOnOff","data":{"onOff":0}}' of device 'ZBT-DimmableLight' (0x00158d0001cded1c)
  zigbee2mqtt:info 2/25/2019, 12:09:02 PM MQTT publish: topic 'zigbee2mqtt/0x00158d0001cded1c', payload '{"brightness":93,"linkquality":34,"state":"OFF","last_seen":"2019-01-18T08:31:49.504Z"}'
  zigbee2mqtt:debug 2/25/2019, 12:09:02 PM Received zigbee message of type 'devChange' with data '{"cid":"genOnOff","data":{"onOff":0}}' of device 'ZBT-DimmableLight' (0x00158d0001cded1c)
  zigbee2mqtt:info 2/25/2019, 12:09:02 PM MQTT publish: topic 'zigbee2mqtt/0x00158d0001cded1c', payload '{"brightness":93,"linkquality":34,"state":"OFF","last_seen":"2019-01-18T08:31:49.504Z"}'
@Koenkk

This comment has been minimized.

Copy link
Owner

Koenkk commented Feb 25, 2019

@Kryzek in your case it's expected behaviour, see explanation below:

# Zigbee2mqtt receives command to turn device ON
  zigbee2mqtt:debug 2/25/2019, 12:08:30 PM Received MQTT message on 'zigbee2mqtt/0x00158d0001cded1c/set' with data '{"state": "ON"}'

# Zigbee2mqtt executes this command successfully
  zigbee2mqtt:info 2/25/2019, 12:08:30 PM Zigbee publish to device '0x00158d0001cded1c', genOnOff - on - {} - {"manufSpec":0,"disDefaultRsp":0} - null

# Because the command executed successfully, zigbee2mqtt assumes that the state of this device has been changed to ON, as not all devices report this, zigbee2mqtt publishes this 'assumed' state
  zigbee2mqtt:info 2/25/2019, 12:08:30 PM MQTT publish: topic 'zigbee2mqtt/0x00158d0001cded1c', payload '{"brightness":108,"linkquality":34,"state":"ON","last_seen":"2019-01-18T08:31:49.504Z"}'

# The device itself reports that is has turned on via a zigbee message (which is something not all devices do!)
  zigbee2mqtt:debug 2/25/2019, 12:08:30 PM Received zigbee message of type 'attReport' with data '{"cid":"genOnOff","data":{"onOff":1}}' of device 'ZBT-DimmableLight' (0x00158d0001cded1c)

# Zigbee2mqtt publishes the above zigbee message to MQTT
  zigbee2mqtt:info 2/25/2019, 12:08:30 PM MQTT publish: topic 'zigbee2mqtt/0x00158d0001cded1c', payload '{"brightness":108,"linkquality":34,"state":"ON","last_seen":"2019-01-18T08:31:49.504Z"}'
@GForce2010

This comment has been minimized.

Copy link
Author

GForce2010 commented Feb 25, 2019

As you can see from the log below I send a command to "Her_Lamp" to set brightness to 255. I then receive a state update with it's current state then a second state report with it's new state.

 2/25/2019, 5:22:45 PM - debug: Ping 0x00158d00020a5a56
2/25/2019, 5:22:45 PM - debug: Successfully pinged 0x00158d00020a5a56
2/25/2019, 5:22:45 PM - info: MQTT publish: topic 'zigbee2mqtt/Her_Lamp/availability', payload 'online'
2/25/2019, 5:22:50 PM - debug: Received zigbee message of type 'attReport' with data '{"cid":"genBasic","data":{"65282":[{"elmType":16,"elmVal":1},{"elmType":33,"elmVal":3002},{"elmType":33,"elmVal":9128},{"elmType":36,"elmVal":[0,1]},{"elmType":33,"elmVal":403},{"elmType":32,"elmVal":95}]}}' of device 'lumi.sensor_switch' (0x00158d0002c8caf6)
2/25/2019, 5:22:50 PM - info: MQTT publish: topic 'zigbee2mqtt/Butt_Her_Lamp', payload '{"battery":100,"voltage":3002,"linkquality":118}'
2/25/2019, 5:22:50 PM - debug: Received zigbee message of type 'devChange' with data '{"cid":"genBasic","data":{"65282":[{"elmType":16,"elmVal":1},{"elmType":33,"elmVal":3002},{"elmType":33,"elmVal":9128},{"elmType":36,"elmVal":[0,1]},{"elmType":33,"elmVal":403},{"elmType":32,"elmVal":95}]}}' of device 'lumi.sensor_switch' (0x00158d0002c8caf6)
2/25/2019, 5:22:54 PM - debug: Received MQTT message on 'zigbee2mqtt/Her_Lamp/set' with data '{   "brightness": 255.0 }'
2/25/2019, 5:22:54 PM - info: Zigbee publish to device '0x00158d00020a5a56', genLevelCtrl - moveToLevelWithOnOff - {"level":255,"transtime":0} - {"manufSpec":0,"disDefaultRsp":0} - null
2/25/2019, 5:22:54 PM - info: MQTT publish: topic 'zigbee2mqtt/Her_Lamp', payload '{"state":"ON","brightness":1}'
2/25/2019, 5:22:55 PM - debug: Received zigbee message of type 'devChange' with data '{"cid":"genLevelCtrl","data":{"currentLevel":254}}' of device 'RB 145' (0x00158d00020a5a56)
2/25/2019, 5:22:55 PM - info: MQTT publish: topic 'zigbee2mqtt/Her_Lamp', payload '{"state":"ON","brightness":254}'
2/25/2019, 5:22:55 PM - info: Zigbee publish to device '0x00158d00020a5a56', genLevelCtrl - read - [{"attrId":0}] - {"manufSpec":0,"disDefaultRsp":0} - null
2/25/2019, 5:22:57 PM - debug: Received MQTT message on 'zigbee2mqtt/Her_Lamp/set' with data '{   "brightness": 1.0 }'
2/25/2019, 5:22:57 PM - info: Zigbee publish to device '0x00158d00020a5a56', genLevelCtrl - moveToLevelWithOnOff - {"level":1,"transtime":0} - {"manufSpec":0,"disDefaultRsp":0} - null
2/25/2019, 5:22:57 PM - info: MQTT publish: topic 'zigbee2mqtt/Her_Lamp', payload '{"state":"ON","brightness":254}'
2/25/2019, 5:22:57 PM - debug: Received zigbee message of type 'devChange' with data '{"cid":"genLevelCtrl","data":{"currentLevel":1}}' of device 'RB 145' (0x00158d00020a5a56)
2/25/2019, 5:22:57 PM - info: MQTT publish: topic 'zigbee2mqtt/Her_Lamp', payload '{"state":"ON","brightness":1}'
2/25/2019, 5:22:57 PM - info: Zigbee publish to device '0x00158d00020a5a56', genLevelCtrl - read - [{"attrId":0}] - {"manufSpec":0,"disDefaultRsp":0} - null
2/25/2019, 5:23:03 PM - debug: Received MQTT message on 'zigbee2mqtt/bridge/config/log_level' with data 'info'
2/25/2019, 5:23:03 PM - info: Switching log level to 'info'
2/25/2019, 5:23:03 PM - info: MQTT publish: topic 'zigbee2mqtt/bridge/config', payload '{"log_level":"info","permit_join":true}'
2/25/2019, 5:23:08 PM - info: MQTT publish: topic 'zigbee2mqtt/Main_Study_1/availability', payload 'online'
2/25/2019, 5:23:08 PM - info: MQTT publish: topic 'zigbee2mqtt/Main_Study_2/availability', payload 'online'
2/25/2019, 5:23:09 PM - info: MQTT publish: topic 'zigbee2mqtt/Main_Study_3/availability', payload 'online'

Koenkk added a commit that referenced this issue Feb 26, 2019

@Koenkk

This comment has been minimized.

Copy link
Owner

Koenkk commented Feb 26, 2019

Fixed, please checkout the latest dev branch.

@Kryzek

This comment has been minimized.

Copy link

Kryzek commented Feb 27, 2019

@Kryzek in your case it's expected behaviour, see explanation below:

Oh, I see. Could this self-reporting behaviour be learned (or set via configuration) per device so M2Z wouldn't need to do these publishes for the device that do this themself?

@Koenkk

This comment has been minimized.

Copy link
Owner

Koenkk commented Feb 27, 2019

@Kryzek technically this is possible, but this will increase the delay between the state acknowledge. I don't see much benefit in adding this.

@GForce2010

This comment has been minimized.

Copy link
Author

GForce2010 commented Feb 27, 2019

I'm afraid I'm all rather new to Raspberry Pi's.

I can see this instruction in the documentation but I am assuming that the update of the dev version would require a slightly different download command.

# Stop zigbee2mqtt and go to directory
sudo systemctl stop zigbee2mqtt
cd /opt/zigbee2mqtt

# Backup configuration
cp -R data data-backup

# Update
git checkout HEAD -- npm-shrinkwrap.json
git pull
rm -rf node_modules
npm install

# Restore configuration
cp -R data-backup/* data
rm -rf data-backup

# Start zigbee2mqtt
sudo systemctl start zigbee2mqtt 

Any help greatly appreciated.

Thanks.

@Koenkk

This comment has been minimized.

Copy link
Owner

Koenkk commented Feb 27, 2019

Replace the update section with:

# Update
git checkout HEAD -- npm-shrinkwrap.json
git fetch
git checkout dev
git pull
rm -rf node_modules
npm install
@GForce2010

This comment has been minimized.

Copy link
Author

GForce2010 commented Feb 28, 2019

I've just updated, I am still seeing two state reports but now both state reports have the same values so it has cured the flickering on the control.

Should there still be two state reports or should there only be one?

@Koenkk

This comment has been minimized.

Copy link
Owner

Koenkk commented Feb 28, 2019

@GForce2010 two is expected, see #1155 (comment), thanks for verifying!

Sign up for free to join this conversation on GitHub. Already have an account? Sign in to comment
You can’t perform that action at this time.