Entity state not updated properly (especially for dimmers)

[kevinkahn]

With the existing integration you can specify a refresh delay and this handles the case of dimmers that respond to a light.on with their current state which still shows "off". With this new version I don't see this capability or an alternative. For human interactions you just notice that the visual toggle in HA is still showing off and turn it on again and now, of course, it works. However, for scripts it is a more serious issue. I thought homeassistant.update_entity might do the trick but that doesn't seem to do anything for zwave. What I currently do is reissue the light.on after a short delay which causes HA to again try to turn on the light since it thinks it is still off but now the response indeed shows it is on. Ok work-around but needs a real solution at some point.

[Fishwaldo]

Please consider testing the "Level" value against the "target" value (for devices that support target level). This will mean that for newer devices, the refresh will only be triggered if the two do not match.

[semlethe3rd]

I have 20+ Homeseer WD100+ dimmer switches and am experiencing the same problem. It leads to the lights being out of sync with reality, and makes for a poor user experience. In HA's native z-wave implementation this can be resolved a number of ways (polling, refresh delay, setting the devices parameters for faster transitions), but I've tried all of them on this implementation and they aren't working. Let me know if there is any additional information I can provide to help resolve this problem.

[Fishwaldo]

If these switches support the SwitchMultiLevel command class version 4, the integration should use the “Target” value as the display rather than the “Level” value. This will mean that no refresh is required as target will display the final value the switch is transitioning too.

Versions prior to 4 do not have this target value and will probably require a refresh.

[Fishwaldo]

Ooops. I see I’m repeating myself.

[kevinkahn]

This turns out to be a more annoying issue that I first thought. Pretty much any script that touches a dimmer needs to double clutch so I'd view this as a real bug. I have some all off type scripts and it turned out that those left HA with the wrong state. So this really is a bug. Seems like using Justin's proposal to honor the target value for dimmers that provide that would be the right answer, with an option to add a refresh interval for old ones that don't.

[marcelveldt]

Please remember that this implementation is still in a very early stage, only basic stuff is implemented and we still need to do a lot of work to make it prime time ready. We're already using the target value so looks like we need to re-implement polling too I'm afraid.

@Fishwaldo any way to determine if a device needs polling ?

[kevinkahn]

Understood about the early stage - just reporting the issue. The particular switch is a Homeseer WD100+ dimmer. Interestingly, if switched from the paddle, HA handles it correctly. I.e, shows on immediately after on press, and on off press appears to show off at the completion of the transition to off (not instantly). So something seems to get set at the end of the transition. However, if turned off from HA it flips back to on even though it goes off. A second click at HA gets it off in HA. The same behavior appears in scripts. I.e., must reissue the turn off after a delay or HA doesn't see it as off. The Homeseer 100 line isn't their most recent but it is zwave+ and I would have thought it would be up to date on a spec for setting target. How can you tell if a dimmer issues a target value?

ETA: Well now I am confused. I just captured the mqtt stream for when HA issues a turn on to the dimmer and there is definitely a Target Value in there but HA doesn't keep its state on. So if you are actually looking at Target Value then something else is causing you to undo that. Here are the 3 mqtt messages that come from a turnon from HA to the dimmer: OpenZWave/1/node/17/instance/1/commandclass/38/value/1407375181971473/ { "Label": "Dimming Duration", "Value": 255, "Units": "", "Min": 0, "Max": 255, "Type": "Byte", "Instance": 1, "CommandClass": "COMMAND_CLASS_SWITCH_MULTILEVEL", "Index": 5, "Node": 17, "Genre": "System", "Help": "Duration taken when changing the Level of a Device", "ValueIDKey": 1407375181971473, "ReadOnly": false, "WriteOnly": false, "ValueSet": false, "ValuePolled": false, "ChangeVerified": false, "Event": "valueChanged", "TimeStamp": 1584376690 } OpenZWave/1/node/17/instance/1/commandclass/38/value/2533275088814097/ { "Label": "Target Value", "Value": 99, "Units": "", "Min": 0, "Max": 255, "Type": "Byte", "Instance": 1, "CommandClass": "COMMAND_CLASS_SWITCH_MULTILEVEL", "Index": 9, "Node": 17, "Genre": "System", "Help": "", "ValueIDKey": 2533275088814097, "ReadOnly": false, "WriteOnly": false, "ValueSet": false, "ValuePolled": false, "ChangeVerified": false, "Event": "valueChanged", "TimeStamp": 1584376691 } OpenZWave/1/node/17/instance/1/commandclass/38/value/1407375181971473/ { "Label": "Dimming Duration", "Value": 3, "Units": "", "Min": 0, "Max": 255, "Type": "Byte", "Instance": 1, "CommandClass": "COMMAND_CLASS_SWITCH_MULTILEVEL", "Index": 5, "Node": 17, "Genre": "System", "Help": "Duration taken when changing the Level of a Device", "ValueIDKey": 1407375181971473, "ReadOnly": false, "WriteOnly": false, "ValueSet": false, "ValuePolled": false, "ChangeVerified": false, "Event": "valueChanged", "TimeStamp": 1584376691 }

[Fishwaldo]

@marcelveldt Unfortunately not - Prior to Version 4 (I think) the specifications was not clear what the "Level" value should actually represent (either final value or instant value) so different vendors did different things.

But leave this with me... I am going to see what I can do to address this in https://github.com/OpenZWave/open-zwave/issues/1321

[Fishwaldo]

@kevinkahn: You should be seeing Both a "Level" value and a "Target Value" value published when there is a change. (Index 0 and Index 9). Do you not see the Level Value?

[kevinkahn]

@Fishwaldo I had been filtering the mqtt stream on the node id for the above. So I just did the following with no filtering: started a sub to the stream, turned on the light from HA. What I see in the mqtt stream is the initial dump of what I assume are the retained messages that define all the devices. This is followed by series of statistics messages one per device. This is then followed by:

OpenZWave/1/command/setvalue/ {"ValueIDKey": 1407375181971473, "Value": 255} OpenZWave/1/command/setvalue/ {"ValueIDKey": 290029585, "Value": 255} OpenZWave/1/event/setvalue/ { "status": "ok", "TimeStamp": 1584463597 } OpenZWave/1/node/17/instance/1/commandclass/38/value/1407375181971473/ { "Label": "Dimming Duration", "Value": 255, "Units": "", "Min": 0, "Max": 255, "Type": "Byte", "Instance": 1, "CommandClass": "COMMAND_CLASS_SWITCH_MULTILEVEL", "Index": 5, "Node": 17, "Genre": "System", "Help": "Duration taken when changing the Level of a Device", "ValueIDKey": 1407375181971473, "ReadOnly": false, "WriteOnly": false, "ValueSet": false, "ValuePolled": false, "ChangeVerified": false, "Event": "valueChanged", "TimeStamp": 1584463597 } OpenZWave/1/event/setvalue/ { "status": "ok", "TimeStamp": 1584463597 } OpenZWave/1/node/17/instance/1/commandclass/38/value/2533275088814097/ { "Label": "Target Value", "Value": 99, "Units": "", "Min": 0, "Max": 255, "Type": "Byte", "Instance": 1, "CommandClass": "COMMAND_CLASS_SWITCH_MULTILEVEL", "Index": 9, "Node": 17, "Genre": "System", "Help": "", "ValueIDKey": 2533275088814097, "ReadOnly": false, "WriteOnly": false, "ValueSet": false, "ValuePolled": false, "ChangeVerified": false, "Event": "valueChanged", "TimeStamp": 1584463597 } OpenZWave/1/node/17/instance/1/commandclass/38/value/1407375181971473/ { "Label": "Dimming Duration", "Value": 3, "Units": "", "Min": 0, "Max": 255, "Type": "Byte", "Instance": 1, "CommandClass": "COMMAND_CLASS_SWITCH_MULTILEVEL", "Index": 5, "Node": 17, "Genre": "System", "Help": "Duration taken when changing the Level of a Device", "ValueIDKey": 1407375181971473, "ReadOnly": false, "WriteOnly": false, "ValueSet": false, "ValuePolled": false, "ChangeVerified": false, "Event": "valueChanged", "TimeStamp": 1584463597 }

I do not see a specific command to node 17 for index 0. I do see those 2 early messages with out a specific node where I assume the node etc is encoded in the id key? That is the complete traffic that results in the light being physically turned on but HA initially showing the light toggle on and then quickly return its displayed status to off. If I repeat the turnon in HA then, of course, it then displays on correctly. What is interesting is that if I continue to capture the mqtt stream when I do that second turnon, then I get a Level message but not a Target Level message. So it would seem that while the switch is "in motion" the system returns the Target Level but once stable returns the Level - but not both. Here is the message that appears between the 2 Dimming Duration messages for the second toggling:

OpenZWave/1/node/17/instance/1/commandclass/38/value/290029585/ { "Label": "Level", "Value": 99, "Units": "", "Min": 0, "Max": 255, "Type": "Byte", "Instance": 1, "CommandClass": "COMMAND_CLASS_SWITCH_MULTILEVEL", "Index": 0, "Node": 17, "Genre": "User", "Help": "The Current Level of the Device", "ValueIDKey": 290029585, "ReadOnly": false, "WriteOnly": false, "ValueSet": false, "ValuePolled": false, "ChangeVerified": false, "Event": "valueChanged", "TimeStamp": 1584465100 }

Hope this helps - if you want me to run any other scenarios let me know.

[kevinkahn]

@Fishwaldo @marcelveldt OK - A bit more analysis (caveat - I am a very competent programmer but not familiar with the HA architecture). I poked around in the implementation a bit. The method to return the brightness value of a light does indeed try to check if there is a target value. However, from what I can tell there is never a recorded target value because in the discovery module where lights are defined "Target Value" is not established as a value that lights have that is of interest. It appears that we would need to add it there (but actually trying to do that is beyond my architectural understanding at the moment). I suspect, also, that the test in returning brightness might need to be a bit more complex since the target would only be meaningful when the switch was in motion. It may be that it's ok to always look at target since either target is the right answer or primary value has become target so looking at target is still ok. But I'm not sure if at startup target would have already been set so HA might not have a current value for target and looking at value would be the right answer. I'm sure you guys would know so I'm just pointing it out.

ETA: I jury-rigged discovery.py to add Target Value. BTW - the definitions in openzwavemqtt const.py don't define the index for Target Value (9). With this I get the value update in the integration. However, it doesn't seem to trigger core HA to ask for an update to get the new brightness and since for the moment I've reached the limit of figuring out the detailed flow in the integration, that's as far as I get. Also, I think that the check for a target value will also need to go into the code for is_on in the light module.

ETA2: I played around more with the code and was able to hack a way to look at the Target Value only when it had been communicated at least once to the integration from OZW (otherwise it always starts as 0 and you can't tell that isn't a real value). It seems though that the ozwdaemon does its own caching of the values of switches. Thus I can turn on the light and get HA to reflect that immediately/correctly by noticing the Target Value change message. However, since there doesn't seem to have been a Level message I think OZW still believes internally that the light is off. Thus when HA next issues a turn off (which generates the correct mqtt command) OZW doesn't appear to send that out on the zwave side. I.e., since it doesn't think the command is going to cause a change it doesn't send it. So, once the light is on in HA you can't turn it off from HA. Since I do see the setvalue for the dimmer with a value of 0 I am pretty sure it is the daemon side that is suppressing the actual command. Further evidence of this is that I can manually send the off mqtt command via an mosquitto_pub and it has no effect. However, if I then send an on that way and then an off the light turns off. So basically HA knows (correctly now with my TargetLevel hack that the light is on and sends and off but the ozwdaemon seems to "know" the light is off and so sends nothing on zwave. I think I am pretty much at the limit of what I can play with given my limited understanding of the internal architectures of both the HA side and the ozwdaemon side. However, happy to try anything else that would help you guys.

[Fishwaldo]

I need to investigate - What you describe is something fundamentally broken and would have been noticed long ago - So something is off.

[kevinkahn]

I certainly believe you regarding this not being a general issue or it would have been seen. So to help you look at it I constructed a minimal set of operations based on what the HA integration issues. To capture the mqtt stream I subscribed on OpenZWave/# with a filter to not report the node specific statistics messages (if these are of use I can rerun without the filter but if makes seeing the issue more cluttered), i.e., mosquitto_sub -v -t OpenZWave/# -T OpenZWave/1/node/+/statistics/ > mbon. I looked at what the HA integration sends for a turn on and it sends a "set dimming duration" to 255 (which I believe is the code for last used) followed by a send of the level to 255. For a turn off it also sends the set dimming and then the set level to 0. To make sure I'm not doing something incorrectly I'm attaching the mbon and mboff scripts as well as the resulting captured mqtt stream. Also, to guard against some sort of previous cache corruption, I stopped OZW, deleted the cache file, and started OZW. I waited for the zwave network to stabilize with all the powered nodes showing Complete (there are 2 battery nodes that were still in Probe). I also shut down HA to avoid extraneous commands. The initial condition had the target node (17) on. You will see in the mqtt log that the retained messages dumped for that file indeed show Level 99 and Target Level 99. I then ran mboff to turn off the light. You will see that this indeed issued an off that got a response of Target Level 0 and the light did turn off. Next I ran mbon. This got a response of Level 0 - I assume due to the slow ramp. The light turned on. I next issued an mboff. This got no response - presumably because OZW still believed the light to be off. I next issued an mbon. This got a Level 255 response (the light was on previously and so full bright). Now an mboff did turn off the light (but strangely did not seem to report either a Level or Target Level associated with the turn off). Despite this missing another mbon will turn on the light. I hope this helps focus where you look at things and again - if I can do anything else to help let me know Zwave.zip

ETA: Realized that the actual OZW daemon debug log would have been useful. It is now attached also but for a repeat run (not the original). It corresponds to a turnon, turnoff (fails), turnon (dummy since light already on), turnoff (works). ZWave2.zip

[marcelveldt]

Hi @kevinkahn and @Fishwaldo sorry for the late reply. Last weekend I've been properly testing these scenarios myself and I can confirm the behaviour @kevinkahn is seeing for various zwaves nodes, both fibaro and qubino ones. From time to time (hard to tell when) he value doesn't match. Only sending a "requestnodestate" fixes this issue.

The workaround for this would be sending the requestnodestate command every X interval or X seconds after each command from the hass implementation but that doesn't feel right. Offcourse if needed, I can make some optional toggle for it but somehow I believe this shouldn't be needed or at least should be implemented at the right place: the daemon itself. The individual clients should not implement all kind of quirks

[marcelveldt]

@Fishwaldo any ideas about this yet ? I have a feeling that the refresh setting should be implemented in the daemon and not in the client application (as that would bring us back to the old implementation again). Issues need to be fixed as much upstream as possible to prevent each client application has it's own quirks/workarounds implemented.

[towerhand]

I have a GE 14294 In-Wall Smart Dimmer and I believe it also shows this behavior.

[bollewolle]

Below was initially logged in a different issue but seems to be the same problem as described here:

• Home Assistant version: 0.108.3
• ozwdaemon version or add-on version: 1.0.14
• homeassistant-zwave_mqtt version: v0.0.9

To control a light I have a Fibaro Dimmer 2 installed. All seems to be recognized well with zwave over mqtt, all relevant enitities are there. To turn on and turn off the light the entity "FIBARO System FGD212 Dimmer 2: Instance 1: Level" needs to be used.

However, when I click the button from Off to On, the light does turn on, but directly after the button turns Off again while the light still remains on. Each time I click the button again to On it just goes to Off again while the light remains on. Only a quick succession from Off to On to Off again eventually turns the light off.

So, I've made a quick screen recording as it probably explains better what I mean than just describing in: https://youtu.be/fb4K9kvy7vw I tried to describe in the comments what seems to be happening: As you can see the initial state in hass is turned off and in MQTT Explorer you can see that the relevant entities value is 0. When I turn the entity On you can see that the state indeed changes to value 99 and stays on it, but that the button in Home Assistant updates and shows it as turned off. Each time you turn it on again the value in MQTT Explorer does not changed and each time the button turns off again. Only when you quickly click the button on and off again the value is updated to 0 and the light indeed turns off.

I couldn't find this as a known issue so thought I'd log it. If there's something I can check then please let me know.

[kpine]

Setting verify_changes="true" (hand editing the ozwcache file) for my GE 14294 Dimmer solves this issue for me. YMMV.

[towerhand]

Changing that setting in the .xml file fixed the behavior of my switch too. Thanks.

[kpine]

The internal polling by OZW when VerifyChanges is enabled might be a little too aggressive though.

ozwd_1  | [20200413 18:21:12.321 PDT] [ozw.library] [info]: Info - Node: 0 mgr,     Refreshing node 11: COMMAND_CLASS_SWITCH_MULTILEVEL index = 0 instance = 1 (to confirm a reported change)
ozwd_1  | [20200413 18:21:12.379 PDT] [ozw.library] [info]: Info - Node: 0 mgr,     Refreshing node 11: COMMAND_CLASS_SWITCH_MULTILEVEL index = 0 instance = 1 (to confirm a reported change)
ozwd_1  | [20200413 18:21:12.433 PDT] [ozw.library] [info]: Info - Node: 0 mgr,     Refreshing node 11: COMMAND_CLASS_SWITCH_MULTILEVEL index = 0 instance = 1 (to confirm a reported change)
ozwd_1  | [20200413 18:21:12.487 PDT] [ozw.library] [info]: Info - Node: 0 mgr,     Refreshing node 11: COMMAND_CLASS_SWITCH_MULTILEVEL index = 0 instance = 1 (to confirm a reported change)
ozwd_1  | [20200413 18:21:12.542 PDT] [ozw.library] [info]: Info - Node: 0 mgr,     Refreshing node 11: COMMAND_CLASS_SWITCH_MULTILEVEL index = 0 instance = 1 (to confirm a reported change)
ozwd_1  | [20200413 18:21:12.596 PDT] [ozw.library] [info]: Info - Node: 0 mgr,     Refreshing node 11: COMMAND_CLASS_SWITCH_MULTILEVEL index = 0 instance = 1 (to confirm a reported change)
ozwd_1  | [20200413 18:21:12.651 PDT] [ozw.library] [info]: Info - Node: 0 mgr,     Refreshing node 11: COMMAND_CLASS_SWITCH_MULTILEVEL index = 0 instance = 1 (to confirm a reported change)
ozwd_1  | [20200413 18:21:12.707 PDT] [ozw.library] [info]: Info - Node: 0 mgr,     Refreshing node 11: COMMAND_CLASS_SWITCH_MULTILEVEL index = 0 instance = 1 (to confirm a reported change)
ozwd_1  | [20200413 18:21:12.761 PDT] [ozw.library] [info]: Info - Node: 0 mgr,     Refreshing node 11: COMMAND_CLASS_SWITCH_MULTILEVEL index = 0 instance = 1 (to confirm a reported change)
ozwd_1  | [20200413 18:21:12.816 PDT] [ozw.library] [info]: Info - Node: 0 mgr,     Refreshing node 11: COMMAND_CLASS_SWITCH_MULTILEVEL index = 0 instance = 1 (to confirm a reported change)
ozwd_1  | [20200413 18:21:12.873 PDT] [ozw.library] [info]: Info - Node: 0 mgr,     Refreshing node 11: COMMAND_CLASS_SWITCH_MULTILEVEL index = 0 instance = 1 (to confirm a reported change)
ozwd_1  | [20200413 18:21:12.927 PDT] [ozw.library] [info]: Info - Node: 0 mgr,     Refreshing node 11: COMMAND_CLASS_SWITCH_MULTILEVEL index = 0 instance = 1 (to confirm a reported change)
ozwd_1  | [20200413 18:21:12.982 PDT] [ozw.library] [info]: Info - Node: 0 mgr,     Refreshing node 11: COMMAND_CLASS_SWITCH_MULTILEVEL index = 0 instance = 1 (to confirm a reported change)
ozwd_1  | [20200413 18:21:13.037 PDT] [ozw.library] [info]: Info - Node: 0 mgr,     Refreshing node 11: COMMAND_CLASS_SWITCH_MULTILEVEL index = 0 instance = 1 (to confirm a reported change)
ozwd_1  | [20200413 18:21:13.092 PDT] [ozw.library] [info]: Info - Node: 0 mgr,     Refreshing node 11: COMMAND_CLASS_SWITCH_MULTILEVEL index = 0 instance = 1 (to confirm a reported change)
ozwd_1  | [20200413 18:21:13.147 PDT] [ozw.library] [info]: Info - Node: 0 mgr,     Refreshing node 11: COMMAND_CLASS_SWITCH_MULTILEVEL index = 0 instance = 1 (to confirm a reported change)
ozwd_1  | [20200413 18:21:13.201 PDT] [ozw.library] [info]: Info - Node: 0 mgr,     Refreshing node 11: COMMAND_CLASS_SWITCH_MULTILEVEL index = 0 instance = 1 (to confirm a reported change)
ozwd_1  | [20200413 18:21:13.256 PDT] [ozw.library] [info]: Info - Node: 0 mgr,     Refreshing node 11: COMMAND_CLASS_SWITCH_MULTILEVEL index = 0 instance = 1 (to confirm a reported change)
ozwd_1  | [20200413 18:21:13.311 PDT] [ozw.library] [info]: Info - Node: 0 mgr,     Refreshing node 11: COMMAND_CLASS_SWITCH_MULTILEVEL index = 0 instance = 1 (to confirm a reported change)
ozwd_1  | [20200413 18:21:13.364 PDT] [ozw.library] [info]: Info - Node: 0 mgr,     Refreshing node 11: COMMAND_CLASS_SWITCH_MULTILEVEL index = 0 instance = 1 (to confirm a reported change)
ozwd_1  | [20200413 18:21:13.419 PDT] [ozw.library] [info]: Info - Node: 0 mgr,     Refreshing node 11: COMMAND_CLASS_SWITCH_MULTILEVEL index = 0 instance = 1 (to confirm a reported change)

[kpine]

Unfortunately, the VerifyChange compat flag does not work when turning on the light with a transition. I used the service call light.turn_on with:

entity_id: light.ge_jasco_products_14294_in_wall_smart_dimmer_level
brightness_pct: 100
transition: 30

The switch did transition to full brightness in about 30 seconds, but the HA state was not updated, and OZW only attempted a single Get. OZW bug perhaps?

• ozwd_level_transition_log.txt
• ozwcache_0xf4e76156.xml.txt
• 14294-dimmer.xml.txt
• mqtt_dump.zip

[marcelveldt]

The internal polling by OZW when VerifyChanges is enabled might be a little too aggressive though.

Yeah it's actively polling the device, something to avoid as much as you can, it can and will slow down your mesh to a disaster if you have a lot of devices. Only when really needed (the device does not send status updates) polling should be considered.

[kpine]

Just clarify, I did not enable the polling (full-time polling). I enabled the VerifyChanges compatibility flag on the dimmer's Level Value, which is a suggestion at https://github.com/OpenZWave/open-zwave/issues/1321#issuecomment-441017900. This causes OZW to refresh (poll) the value when it is set, until it reaches the desired value. It does not actually poll until that specific value has been Set.

It is basically the exact feature you are asking for in this comment. https://github.com/cgarwood/homeassistant-zwave_mqtt/issues/72#issuecomment-602815441 😄

[marcelveldt]

Yeah, I know but in my understanding even that should only be needed for devices that don't report their state correctly. Using this feature and setting a new value for a few devices at once can make your network unresponsive for minutes.

So, we will have to wait what can be fixed upstream and if there's any polling needed (unavoidable) that should be done in the daemon itself.

[marcelveldt]

I will close this one for now here as it's an issue that needs fixing upstream. If the values are incorrect in MQTT, they will be incorrect in hass as well.

Progress can be tracked here: https://github.com/OpenZWave/open-zwave/issues/1321

[kpine]

Just curious how transitions are supposed to work. Example: switch is off, turn on light to 100% brightness with a 30 second transition. Assume the switch supports the Target value. When the on command is sent, will this result in the switch entity reporting 100% brightness almost immediately. Is that the expected behavior? What is the behavior in other integrations?

[marcelveldt]

Behaviour is different in every integration. And yes if the device supports the target value (most do not) it will report back 100%. There is no reliable way (as far as I can tell) to show the value it actually is at while transitioning, at least it's not accurate/reliable in case of Z-Wave.

[towerhand]

@kpine Do you know if we need to revert the verify_changes="true" change you suggested? (GE dimmers)

[kpine]

@towerhand This change does not support the older GE switches. Only V4 and up for the Switch Multilevel command class.

[Dinth]

Ive got same issue with my Fibaro Dimmer 2s. Weirdly i had same issue earlier with Zwave2MQTT by robertsLando but after few updates it stopped happening, so maybe its not upstream?