Closed Jogobo closed 2 years ago
Please provide the debug log of this.
See https://www.zigbee2mqtt.io/guide/usage/debug.html on how to enable debug logging.
Looks to be a home assistant issue, the on is directly published after the off, HA should use the latest message only.
Dec 29 18:39:47 jogolinux npm[5968]: 2021-12-29T17:39:47.437Z zigbee-herdsman:controller:log Received 'zcl' data '{"frame":{"Header":{"frameControl":{"frameType":0,"manufacturerSpecific":false,"direction":1,"disableDefaultResponse":false,"reservedBits":0},"transactionSequenceNumber":8,"manufacturerCode":null,"commandIdentifier":11},"Payload":{"cmdId":1,"statusCode":0},"Command":{"ID":11,"name":"defaultRsp","parameters":[{"name":"cmdId","type":32},{"name":"statusCode","type":32}]}},"address":3842,"endpoint":1,"linkquality":15,"groupID":0,"wasBroadcast":false,"destinationEndpoint":1}'
Dec 29 18:39:47 jogolinux npm[5968]: [32mZigbee2MQTT:info [39m 2021-12-29 18:39:47: MQTT publish: topic 'zigbee2mqtt/mqtt_Dimmer01', payload '{"brightness":254,"last_seen":"2021-12-29T17:39:47.437Z","linkquality":15,"state":"OFF"}'
Dec 29 18:39:47 jogolinux npm[5968]: 2021-12-29T17:39:47.439Z zigbee-herdsman:adapter:zStack:unpi:parser --- parseNext []
Dec 29 18:39:47 jogolinux npm[5968]: [32mZigbee2MQTT:info [39m 2021-12-29 18:39:47: MQTT publish: topic 'zigbee2mqtt/mqtt_Dimmer01', payload '{"brightness":254,"last_seen":"2021-12-29T17:39:47.437Z","linkquality":15,"state":"ON"}'
Dec 29 18:39:47 jogolinux npm[5968]: 2021-12-29T17:39:47.642Z zigbee-herdsman:adapter:zStack:unpi:parser <-- [254,3,69,196,42,243,0,91]
@emontnemery could you check this?
As you can see below a state change of the device results in three messages:
Dec 31 11:51:51 jogolinux npm[7414]: ^[[32mZigbee2MQTT:info ^[[39m 2021-12-31 11:51:51: MQTT publish: topic 'zigbee2mqtt/mqtt_Dimmer01', payload '{"brightness":254,"last_seen":"2021-12-31T10:51:51.767Z","linkquality":24,"state":"OFF"}'
Dec 31 11:51:51 jogolinux npm[7414]: ^[[32mZigbee2MQTT:info ^[[39m 2021-12-31 11:51:51: MQTT publish: topic 'zigbee2mqtt/mqtt_Dimmer01', payload '{"brightness":254,"last_seen":"2021-12-31T10:51:51.767Z","linkquality":24,"state":"ON"}'
Message no. 2 and 3 have exactly the same timestamp.
I'm using openHAB for my smarthome and I have a rule which says "lower the blind in the bathroom when it's dark outside and the light turns on". Another rule says 'open the blind in the bathroom when the light is turned off". The message of the publisher, which sends '{"state":"ON"}', results in a state change event in OH. The blinds start to lower. Then message no. 2 results in a state change event to "OFF" which starts to open the blinds again and because of message no. 3 there is a state change to "ON" again. Until then the predicted blind height in OH is at target level so that message no. 3 does not result in lowering the blind to the target level again.
This was definitely different before 1.22.1 as the blind acted as expected.
I see, I cannot explain the duplicate messages yet, could you share me your configuration.yaml
? (with passwords removed)
Here you are...
configuration.yaml homeassistant: false permit_join: false mqtt: base_topic: zigbee2mqtt server: mqtt://192.168.... user: unknown password: secret serial: port: /dev/ttyUSB0 availability: active: timeout: 10 passive: timeout: 1500 advanced: pan_id: 6755 cache_state: true channel: 11 log_level: info log_output:
devices.yaml
'0x7cb03eaa0a046444': friendly_name: mqtt_Licht_Stall retain: true '0x8418260000dace3a': friendly_name: mqtt_Licht_Blumenfenster retain: true '0x7cb03eaa00a7c301': friendly_name: mqtt_Licht_Wohnzimmerfenster retain: true '0x84182600000f6bff': friendly_name: mqtt_LichtKellertreppeMitte retain: true '0x84182600000fa2a9': friendly_name: mqtt_LichtKellertreppeUnten retain: true '0x84182600000f890a': friendly_name: mqtt_LichtKellergangMitte retain: true '0x7cb03eaa00a7bf26': friendly_name: mqtt_Weihnachtsstern retain: true '0x7cb03eaa0a01301f': friendly_name: mqtt_Switch_AP_Arbeitszimmer retain: true '0x84182600000d8729': friendly_name: mqtt_Switch_Stehleuchte retain: true '0x7cb03eaa00b1ba9b': friendly_name: mqtt_Switch_Lichterkette retain: true '0x84182600000d30f1': friendly_name: mqtt_Switch_Sofalicht retain: true '0x7cb03eaa0a017172': friendly_name: mqtt_Switch_AP_Schlafzimmer retain: true '0x84182600000a8e76': friendly_name: mqtt_Switch_AP_Keller retain: true '0x7cb03eaa00a7bf62': friendly_name: mqtt_Stehlampe_top retain: true '0x7cb03eaa00a7bfb8': friendly_name: mqtt_Stehlampe_bottom retain: true '0x8418260000067b29': friendly_name: mqtt_Licht_Flur_Eingang retain: true '0x00124b0018e1f6c6': friendly_name: mqtt_Router retain: true '0x90fd9ffffedc6229': friendly_name: mqtt_Licht_Kueche '0x90fd9ffffed8c4e0': friendly_name: mqtt_IKEA_Switch_Kueche '0x7cb03eaa00a3c262': friendly_name: mqtt_Switch_AP_Wohnzimmer retain: true '0x7cb03eaa00ad3467': friendly_name: mqtt_Switch_Pavillon retain: true '0x7cb03eaa0a0451f8': friendly_name: mqtt_Licht_Betriebsraum '0x8418260000002c88': friendly_name: mqtt_Kugelleuchte '0x00124b0018e1f479': friendly_name: mqtt_Router2 '0x804b50fffebbf21f': friendly_name: mqtt_Dimmer01 debounce: 0 optimistic: true '0x7cb03eaa0a041524': friendly_name: mqtt_LichtKellertreppeOben '0x804b50fffebfa91b': friendly_name: mqtt_Dimmer03 '0x7cb03eaa00ad7266': friendly_name: mqtt_DeckenlichtFlur '0x7cb03eaa0a05923e': friendly_name: mqtt_Tischlampe '0x804b50fffe0a6acf': friendly_name: mqtt_zbmini02 '0x00124b0023ad5e12': friendly_name: mqtt_snzb03_02 '0x00124b0023ad9c75': friendly_name: mqtt_snzb03_01 '0x00124b0023ac5b4e': friendly_name: mqtt_snzb03_03 '0x842e14fffe655093': friendly_name: mqtt_zbmini01 '0x804b50fffe08deab': friendly_name: mqtt_zbmini03 '0x84182600000f79f3': friendly_name: mqtt_LichtKellergang '0x7cb03eaa00a35705': friendly_name: mqtt_BildKueche_unten '0x7cb03eaa00a90aed': friendly_name: mqtt_BildKueche_oben '0x7cb03eaa00a11647': friendly_name: mqtt_Licht_Kuechenschrank '0x8418260000dab3d6': friendly_name: mqtt_Licht_Arbeitsflaeche '0x000d6f000e05a06b': friendly_name: mqtt_Motion_Stall '0x7cb03eaa00a9b9a7': friendly_name: mqtt_Pavillon_LED_2 '0x7cb03eaa00a9b956': friendly_name: mqtt_Pavillon_LED_1 '0x000d6f000d12ff6a': friendly_name: mqtt_Motion_KellertreppeOben occupancy_timeout: 30 '0x000d6f000d9f68ea': friendly_name: mqtt_SwitchBildKueche '0x000d6f000d5793b6': friendly_name: mqtt_SwitchSchrankKueche '0x000d6f000e059937': friendly_name: mqtt_Motion_Betriebsraum '0x000d6f0011b414d8': friendly_name: mqtt_4xSwitchBuero '0x000d6f000e0592b3': friendly_name: mqtt_Motion_Kellertreppe '0xf0d1b8000014980b': friendly_name: mqtt_DeckenlichtBuero '0x7cb03eaa00a7c03a': friendly_name: mqtt_Stehlampe_middle '0x000d6f000d12fed3': friendly_name: mqtt_Motion_Kellergang
It maybe be due to the debounce: 0
, please remove it from your devices.yaml
.
Oh, that's just a leftover from some tests I did before I opened the issue. The settings were the same as with "mqtt_Dimmer03", which is the same type of device. A quick test showed the same result:
{"brightness":102,"last_seen":"2022-01-01T13:02:19.048Z","linkquality":21,"state":"OFF"} {"brightness":102,"last_seen":"2022-01-01T13:02:19.048Z","linkquality":21,"state":"ON"} {"brightness":102,"last_seen":"2022-01-01T13:02:29.526Z","linkquality":21,"state":"ON"} {"brightness":102,"last_seen":"2022-01-01T13:02:29.526Z","linkquality":21,"state":"OFF"} {"brightness":102,"last_seen":"2022-01-01T13:03:20.629Z","linkquality":24,"state":"OFF"}
Switching from "OFF" to "ON" and back to "OFF" results in two messages with same timestamp and different states.
Just did another test with a Sonoff ZBMINI. Turning it on and off again results in
{"last_seen":"2022-01-01T13:08:05.959Z","linkquality":21,"state":"ON"}
{"last_seen":"2022-01-01T13:08:07.740Z","linkquality":21,"state":"ON"}
{"last_seen":"2022-01-01T13:08:07.743Z","linkquality":21,"state":"ON"}
{"last_seen":"2022-01-01T13:08:07.743Z","linkquality":21,"state":"ON"}
{"last_seen":"2022-01-01T13:08:22.887Z","linkquality":21,"state":"OFF"}
{"last_seen":"2022-01-01T13:08:22.889Z","linkquality":21,"state":"OFF"}
{"last_seen":"2022-01-01T13:08:22.889Z","linkquality":21,"state":"OFF"}
At least all the states are correct but the number of messages seams way too many.
Can you provide the debug log again now? Without it I cannot determine where these messages come from.
Just checked, it indeed provides 3 updates per state change:
last_seen
to update -> published to MQTT (can be avoided by disabling last_seen
)optimistic: false
for this device)Thank you for your update. Just tested the Iluminize device with last_seen=disabled and I only get one message per state change. So it looks like it's all "last_seen" related. When message no 2. is generated, shouldn't it reflect the state change from message no. 1 as well? Three messages in a row, all with the same state, do not bother openHAB as already the first message causes the state changed event.
What are the side effects of disabling last_seen? Will "availability" still work?
What are the side effects of disabling last_seen? Will "availability" still work?
last_seen
is just for adding last seen to the state, doesn't affect availability
So, is disabling "last_seen" just a workaround or the final solution? As the Iluminize device sends "ON", "OFF", "ON" and the ZBMINI sends three times "ON" in a row, the behaviour of different devices is not consistent.
So, is disabling "last_seen" just a workaround or the final solution?
It is not a workaround, you should decide for yourself if you want this option or not, but depending on the device this could produce an additional message.
As the Iluminize device sends "ON", "OFF", "ON"
could you provide me the debug log of this? (let me know if last seen was enabled or disabled in this log)
It's in the debug log from 5 days ago. Device is mqtt_Dimmer01 and "last_seen" was enabled. You quoted the log entries in your answer to the debug log.
@Koenkk do you still need me to check from a HA perspective?
@emontnemery no, thanks!
@Jogobo
As the Iluminize device sends "ON", "OFF", "ON"
I don't see the ON, OFF, ON, just OFF, ON which seems to be correct in this case, I've annotated the log:
# Request received to turn on mqtt_Dimmer01
Dec 29 18:39:46 jogolinux npm[5968]: [34mZigbee2MQTT:debug[39m 2021-12-29 18:39:46: Received MQTT message on 'zigbee2mqtt/mqtt_Dimmer01/set' with data '{"state":"ON"}'
Dec 29 18:39:46 jogolinux npm[5968]: [34mZigbee2MQTT:debug[39m 2021-12-29 18:39:46: Publishing 'set' 'state' to 'mqtt_Dimmer01'
# On command is send
Dec 29 18:39:46 jogolinux npm[5968]: 2021-12-29T17:39:46.977Z zigbee-herdsman:controller:endpoint Command 0x804b50fffebbf21f/1 genOnOff.on({}, {"timeout":10000,"disableResponse":false,"disableRecovery":false,"disableDefaultResponse":false,"direction":0,"srcEndpoint":null,"reservedBits":0,"manufacturerCode":null,"transactionSequenceNumber":null,"writeUndiv":false})
...
# Acknowledge to the on command is received -> this causes the last seen to change -> published to MQTT
Dec 29 18:39:47 jogolinux npm[5968]: 2021-12-29T17:39:47.437Z zigbee-herdsman:adapter:zStack:znp:AREQ <-- AF - incomingMsg - {"groupid":0,"clusterid":6,"srcaddr":3842,"srcendpoint":1,"dstendpoint":1,"wasbroadcast":0,"linkquality":15,"securityuse":0,"timestamp":1723915,"transseqnumber":0,"len":5,"data":{"type":"Buffer","data":[8,8,11,1,0]}}
Dec 29 18:39:47 jogolinux npm[5968]: 2021-12-29T17:39:47.437Z zigbee-herdsman:controller:log Received 'zcl' data '{"frame":{"Header":{"frameControl":{"frameType":0,"manufacturerSpecific":false,"direction":1,"disableDefaultResponse":false,"reservedBits":0},"transactionSequenceNumber":8,"manufacturerCode":null,"commandIdentifier":11},"Payload":{"cmdId":1,"statusCode":0},"Command":{"ID":11,"name":"defaultRsp","parameters":[{"name":"cmdId","type":32},{"name":"statusCode","type":32}]}},"address":3842,"endpoint":1,"linkquality":15,"groupID":0,"wasBroadcast":false,"destinationEndpoint":1}'
# State publish because of the acknowledge updated the last seen
Dec 29 18:39:47 jogolinux npm[5968]: [32mZigbee2MQTT:info [39m 2021-12-29 18:39:47: MQTT publish: topic 'zigbee2mqtt/mqtt_Dimmer01', payload '{"brightness":254,"last_seen":"2021-12-29T17:39:47.437Z","linkquality":15,"state":"OFF"}'
Dec 29 18:39:47 jogolinux npm[5968]: 2021-12-29T17:39:47.439Z zigbee-herdsman:adapter:zStack:unpi:parser --- parseNext []
# On commands succeeds so zigbee2mqtt assumes state changed (optimistic publish)
Dec 29 18:39:47 jogolinux npm[5968]: [32mZigbee2MQTT:info [39m 2021-12-29 18:39:47: MQTT publish: topic 'zigbee2mqtt/mqtt_Dimmer01', payload '{"brightness":254,"last_seen":"2021-12-29T17:39:47.437Z","linkquality":15,"state":"ON"}'
If you would disable last_seen the first STATE: OFF publish should be gone. (so only 1 publish with STATE: ON)
Note that you see different behaviour between the mqtt_Dimmer01 and the ZBMINI because they report in differently; the ZBMINI confirms its state with an additional message while mqtt_Dimmer01 doesn't.
Here is an example event log from openHAB:
2021-12-31 08:47:37.122 [vent.ItemStateChangedEvent] - TasterBad_1_PressShort changed from OFF to ON
2021-12-31 08:47:37.147 [ome.event.ItemCommandEvent] - Item 'mqtt_DimmerBad_OnOff' received command ON
2021-12-31 08:47:37.149 [nt.ItemStatePredictedEvent] - mqtt_DimmerBad_OnOff predicted to become ON
2021-12-31 08:47:37.173 [vent.ItemStateChangedEvent] - mqtt_DimmerBad_OnOff changed from OFF to ON
2021-12-31 08:47:37.531 [vent.ItemStateChangedEvent] - mqtt_DimmerBad_OnOff changed from ON to OFF
2021-12-31 08:47:37.545 [vent.ItemStateChangedEvent] - mqtt_DimmerBad_OnOff changed from OFF to ON
As you can see "TasterBad_1_PressShort" initiates to publish {"state":"ON"} to "mqtt_DimmerBad_OnOff" and then you see changing the state from "ON" to "OFF" and back to "ON" again.
z2m.log shows only two entries
Dec 31 08:47:37 jogolinux npm[7414]: Zigbee2MQTT:info 2021-12-31 08:47:37: MQTT publish: topic 'zigbee2mqtt/mqtt_Dimmer01', payload '{"brightness":254,"last_seen":"2021-12-31T07:47:37.522Z","linkquality":0,"state":"OFF"}'
Dec 31 08:47:37 jogolinux npm[7414]: Zigbee2MQTT:info 2021-12-31 08:47:37: MQTT publish: topic 'zigbee2mqtt/mqtt_Dimmer01', payload '{"brightness":254,"last_seen":"2021-12-31T07:47:37.522Z","linkquality":0,"state":"ON"}'
It looks like the (wrong) state "OFF" (first entry in z2m.log) is processed before the (right) state "ON" (2nd entry in z2m.log) in openHAB. According to the rules behind the PressShort action openHAB sends "ON" to mqtt_DimmerBad_OnOff, which is a generic mqtt item in openHAB. openHAB should send the state change to mosquitto, which publishes the new state to all subscribers. z2m seems to receive the state change, but "answers", due to the implementation of "last_seen" with the old state "OFF" and then with the new state "ON". These "answers" to the state change, initiated by openHAB, lead to an "ON", "OFF", "ON" action in openHAB.
I found the openHAB event.log entries corresponding to your quotes. Looks like this:
2021-12-29 18:39:46.924 [vent.ItemStateChangedEvent] - TasterBad_1_PressShort changed from OFF to ON
2021-12-29 18:39:46.957 [ome.event.ItemCommandEvent] - Item 'mqtt_DimmerBad_OnOff' received command ON
2021-12-29 18:39:46.958 [nt.ItemStatePredictedEvent] - mqtt_DimmerBad_OnOff predicted to become ON
2021-12-29 18:39:46.971 [vent.ItemStateChangedEvent] - mqtt_DimmerBad_OnOff changed from OFF to ON
2021-12-29 18:39:47.449 [vent.ItemStateChangedEvent] - mqtt_DimmerBad_OnOff changed from ON to OFF
2021-12-29 18:39:47.462 [vent.ItemStateChangedEvent] - mqtt_DimmerBad_OnOff changed from OFF to ON
2021-12-29 18:39:48.925 [vent.ItemStateChangedEvent] - TasterBad_1_PressShort changed from ON to OFF
Koenkk wrote:
# Acknowledge to the on command is received -> this causes the last seen to change -> published to MQTT
This should either contain the new state or the payload should only be {"last_seen":"xxxxxxxxx"}. Updating last seen but sending the state being set before receiving the actual command seems a little bit confusing. Or you should at least update the documentation that "last_seen" updates do not always reflect the actual state of some devices.
@Jogobo if you don't want to have the complete state send on every state update, you can set advanced: cache_state: false
in configuration.yaml
(see https://www.zigbee2mqtt.io/guide/configuration/mqtt.html#mqtt-behaviour)
Made some more tests with different settings for cache_state
and last_seen
. Seems that cache_state: false
and last_seen: ISO_8601_local
does the trick.
openHAB receives only one state change.
2022-01-05 15:49:42.903 [ome.event.ItemCommandEvent] - Item 'mqtt_DimmerBad_OnOff' received command ON
2022-01-05 15:49:42.942 [nt.ItemStatePredictedEvent] - mqtt_DimmerBad_OnOff predicted to become ON
2022-01-05 15:49:42.951 [vent.ItemStateChangedEvent] - mqtt_DimmerBad_OnOff changed from OFF to ON
Every press on the switch produces 2 messages
{"last_seen":"2022-01-05T15:49:59+01:00","linkquality":0}
{"last_seen":"2022-01-05T15:49:59+01:00","linkquality":0,"state":"OFF"}
Had to go back to cache_state: true
and last_seen: disabled
because OH log filled with "unrecognized command" messages. As different OH items subscribe to the same subject and filter the payload they are looking for, missing payloads lead to empty commands.
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
I am consistently running into this issue:
Apr 23 10:38:24 homie1 npm[320195]: Zigbee2MQTT:debug 2022-04-23 10:38:24: Received MQTT message on 'zigbee2mqtt/0x7cb03eaa00ae5ff1/set' with data '{"state":"ON"}'
Apr 23 10:38:24 homie1 npm[320195]: Zigbee2MQTT:debug 2022-04-23 10:38:24: Publishing 'set' 'state' to 'osram_plug1'
Apr 23 10:38:24 homie1 npm[320195]: Zigbee2MQTT:info 2022-04-23 10:38:24: MQTT publish: topic 'zigbee2mqtt/osram_plug1', payload '{"last_seen":"2022-04-23T10:38:24+00:00","linkquality":76,"state":"OFF","update":{"state":"idle"}}'
Apr 23 10:38:24 homie1 npm[320195]: Zigbee2MQTT:info 2022-04-23 10:38:24: MQTT publish: topic 'zigbee2mqtt/osram_plug1', payload '{"last_seen":"2022-04-23T10:38:24+00:00","linkquality":76,"state":"ON","update":{"state":"idle"}}'
Apr 23 10:38:24 homie1 npm[320195]: Zigbee2MQTT:debug 2022-04-23 10:38:24: Received Zigbee message from 'osram_plug1', type 'attributeReport', cluster 'genOnOff', data '{"onOff":1}' from endpoint 3 with groupID 0
Apr 23 10:38:24 homie1 npm[320195]: Zigbee2MQTT:info 2022-04-23 10:38:24: MQTT publish: topic 'zigbee2mqtt/osram_plug1', payload '{"last_seen":"2022-04-23T10:38:24+00:00","linkquality":76,"state":"ON","update":{"state":"idle"}}'
Apr 23 10:38:30 homie1 npm[320195]: Zigbee2MQTT:debug 2022-04-23 10:38:30: Received MQTT message on 'zigbee2mqtt/0x7cb03eaa00ae5ff1/set' with data '{"state":"OFF"}'
Apr 23 10:38:30 homie1 npm[320195]: Zigbee2MQTT:debug 2022-04-23 10:38:30: Publishing 'set' 'state' to 'osram_plug1'
Apr 23 10:38:30 homie1 npm[320195]: Zigbee2MQTT:info 2022-04-23 10:38:30: MQTT publish: topic 'zigbee2mqtt/osram_plug1', payload '{"last_seen":"2022-04-23T10:38:30+00:00","linkquality":72,"state":"ON","update":{"state":"idle"}}'
Apr 23 10:38:30 homie1 npm[320195]: Zigbee2MQTT:info 2022-04-23 10:38:30: MQTT publish: topic 'zigbee2mqtt/osram_plug1', payload '{"last_seen":"2022-04-23T10:38:30+00:00","linkquality":72,"state":"OFF","update":{"state":"idle"}}'
Apr 23 10:38:30 homie1 npm[320195]: Zigbee2MQTT:debug 2022-04-23 10:38:30: Received Zigbee message from 'osram_plug1', type 'attributeReport', cluster 'genOnOff', data '{"onOff":0}' from endpoint 3 with groupID 0
Apr 23 10:38:30 homie1 npm[320195]: Zigbee2MQTT:info 2022-04-23 10:38:30: MQTT publish: topic 'zigbee2mqtt/osram_plug1', payload '{"last_seen":"2022-04-23T10:38:30+00:00","linkquality":72,"state":"OFF","update":{"state":"idle"}}'
For me it started with upgrading z2m (1.22.2 -> 1.23.0) and hb (v1.3.9 -> v1.4.0) Related issues
What happened?
Since the last update I have a problem with my dimmer. When I publish the payload '{"state":"ON"}' to the device the subscriber receives the following two messages: {"state":"ON"} {"brightness":254,"last_seen":"2021-12-28T16:25:29.267Z","linkquality":18,"state":"OFF"}
The device reacts as expected and the light turns on. Rules which check for a state change receive "ON" and immediately after that "OFF" from the long message. Thus resulting in performing the "OFF" action instead of "ON".
What did you expect to happen?
I would expect the get message to show the state which has been set before.
How to reproduce it (minimal and precise)
Just subscribe to the device and send the payload.
Zigbee2MQTT version
1.22.1
Adapter firmware version
20210708
Adapter
Slaesh's CC2652RB stick
Debug log
No debug log available