[bug] Dimmer won't turn off in Home Assisstant UI

[CWSpear]

Version

Build/Run method

• [x] Docker
• [ ] PKG
• [ ] Manually built (git clone - npm install - npm run build )

Zwave2Mqtt version: I don't know... latest tag from Docker as of 29 July 2020 at ~10pm PDT. Openzwave Version: 1.6.1210

(I couldn't find a version for Zwave2Mqtt... might be nice to have one in the app somewhere like Openzwave's version is. Well, it is 2am and I've been at Smart Home frustrations for the last 8 hours, so maybe it was in plain sight and I missed it!)

Describe the bug

If the light is on at say 48 brightness, when I turn off the light in Home Assistant, I sometimes get this (which is expected):

(This is from logs dumping my MQTT messages for debugging. zwave is my prefix.)

2020-07-30T08:27:38.593049351Z [Debug] zwave/office_lights/38/1/0/set = 0
2020-07-30T08:27:39.435080555Z [Debug] zwave/office_lights/38/1/0 = {"time":1596097659434,"value":0}

It works fine when this happens.

But more often than not, this is what happens:

2020-07-30T08:27:52.001829759Z [Debug] zwave/office_lights/38/1/0/set = 0
2020-07-30T08:27:52.065765754Z [Debug] zwave/office_lights/38/1/0 = {"time":1596097672064,"value":48}

(Notice the timestamps: it usually updates the state before it's even started to turn off, which becuase the dimmers I have (HomeSeer WD-100+) transition to off.)

That causes Home Assistant to show the light as on, even tho the lights are off, and I have to toggle them off and then back on again to actually turn them on.

This is what it looks like in the UI:

Note that the lights are on in the office at the start of the video, and they are off at the end, even tho the toggle shows they are on. Also note that the toggle stays off for a second or two. I'm pretty sure this is a feature of Home Assistant. That it tries to show that it was turned off, but then waits a second to show that it got the state update that it's actually still on (which that part in this case is incorrect behavior).

(I just realized cuz the gif loops, it can be hard to know when it starts... it starts when the mouse comes up from beneath the frame and ends when the mouse goes off the right side.)

To Reproduce Steps to reproduce the behavior:

1. Add a dimmer that transitions to target brightness (e.g. HomeSeer WD-100+).
2. Add it to Home Assistant via MQTT discovery.
3. Turn the light on in Home Assistant. Turn it off, then on. Next time you turn it off, you should trigger this issue.

Expected behavior Home Assistant should show that the light is off.

Actual behavior Home Assistant shows that the light is on, even tho the light is actually off.

[robertsLando]

@chilicheech @jshridha Have you ever expected this kind of issue?

[CWSpear]

I can see from other comments, you don't use Home Assistant. It seems like this may be an issue when Zwave2Mqtt specifically, tho, in that it is sending the update of its level too soon instead of waiting until it reached it's destination or something alone those lines...

If I turn it on, I don't get the update of the brightness value until after it's reached the target value a second or so later:

2020-07-30T16:47:58.987264351Z [Debug] zwave/office_lights/38/1/0/set = 255
2020-07-30T16:48:00.530956434Z [Debug] zwave/office_lights/38/1/0 = {"time":1596127680530,"value":48}

I event sometimes get multiple updates, but the last one is always the end value:

[Debug] zwave/office_lights/38/1/0/set = 255
[Debug] zwave/office_lights/38/1/0 = {"time":1596129476451,"value":13}
[Debug] zwave/office_lights/38/1/0 = {"time":1596129477519,"value":48}

Contrast that with when I turn it off, it reports it's state immediately after getting the call to change it to zero, even tho the light hasn't had time to actually change, and I never get an update for the final value (0).

(I assume just turning it out has it call it with 255, but it does set it to 48, which was the previous brightness I had. Not sure what that's about.)

[CWSpear]

In a little further testing, I don't always get the final value when turning them on either.

Turning them on, I just got this:

[Debug] zwave/office_lights/38/1/0/set = 255
[Debug] zwave/office_lights/38/1/0 = {"time":1596129630538,"value":14}

But it should have turned it on to 99 (and that's what the lights are at: 99% brightness). The UI incorrectly reports 14%.

[jshridha]

You may have to turn on polling to repeatedly ask the device to report its brightness level. Not all Z-Wave dimmers will send their brightness instantly. This is due to an old Lutron patent that I believe has now expired.

You also may want to look into updating the firmware on your dimmer. According to this post, updating the firmware will give you the instant status updates required to update the state immediately.

[CWSpear]

When I manually press up or down on the paddle, I get a bunch of updates and everything works fine.

If the light is on full brightness and I turn it off via the paddle, this is my logs (all of this is just from one press of the down part of the paddle):

[Debug] zwave/office_lights/91/1/2 = {"time":1596135708400,"value":1}
[Debug] zwave/office_lights/91/1/2 = {"time":1596135709400,"value":0}
[Debug] zwave/office_lights/38/1/0 = {"time":1596135711371,"value":0}
[Debug] zwave/office_lights/38/1/0 = {"time":1596135711408,"value":0}
[Debug] zwave/office_lights/38/1/0 = {"time":1596135711412,"value":0}
[Debug] zwave/office_lights/38/1/1 = {"time":1596135711412}
[Debug] zwave/office_lights/38/1/2 = {"time":1596135711412}
[Debug] zwave/office_lights/38/1/3 = {"time":1596135711412,"value":true}
[Debug] zwave/office_lights/38/1/4 = {"time":1596135711413,"value":0}
[Debug] zwave/office_lights/39/1/0 = {"time":1596135711413,"value":3}
[Debug] zwave/office_lights/43/1/0 = {"time":1596135711413,"value":0}
[Debug] zwave/office_lights/43/1/1 = {"time":1596135711413,"value":0}
[Debug] zwave/office_lights/91/1/1 = {"time":1596135711413,"value":0}
[Debug] zwave/office_lights/91/1/2 = {"time":1596135711413,"value":0}
[Debug] zwave/office_lights/91/1/256 = {"time":1596135711413,"value":2}
[Debug] zwave/office_lights/91/1/257 = {"time":1596135711413,"value":1000}
[Debug] zwave/office_lights/94/1/0 = {"time":1596135711413,"value":1}
[Debug] zwave/office_lights/94/1/1 = {"time":1596135711413,"value":1536}
[Debug] zwave/office_lights/94/1/2 = {"time":1596135711413,"value":1536}
[Debug] zwave/office_lights/112/1/4 = {"time":1596135711413,"value":0}
[Debug] zwave/office_lights/112/1/7 = {"time":1596135711413,"value":99}
[Debug] zwave/office_lights/112/1/8 = {"time":1596135711413,"value":22}
[Debug] zwave/office_lights/112/1/9 = {"time":1596135711413,"value":99}
[Debug] zwave/office_lights/112/1/10 = {"time":1596135711413,"value":22}
[Debug] zwave/office_lights/114/1/0 = {"time":1596135711413,"value":8}
[Debug] zwave/office_lights/114/1/1 = {"time":1596135711413,"value":8}
[Debug] zwave/office_lights/114/1/2 = {"time":1596135711413,"value":8}
[Debug] zwave/office_lights/115/1/0 = {"time":1596135711413,"value":0}
[Debug] zwave/office_lights/115/1/1 = {"time":1596135711413,"value":0}
[Debug] zwave/office_lights/115/1/2 = {"time":1596135711413}
[Debug] zwave/office_lights/115/1/3 = {"time":1596135711413,"value":0}
[Debug] zwave/office_lights/115/1/4 = {"time":1596135711414,"value":0}
[Debug] zwave/office_lights/115/1/5 = {"time":1596135711414,"value":0}
[Debug] zwave/office_lights/115/1/6 = {"time":1596135711414}
[Debug] zwave/office_lights/115/1/7 = {"time":1596135711414}
[Debug] zwave/office_lights/115/1/8 = {"time":1596135711414,"value":0}
[Debug] zwave/office_lights/115/1/9 = {"time":1596135711414,"value":0}
[Debug] zwave/office_lights/134/1/0 = {"time":1596135711414,"value":"3"}
[Debug] zwave/office_lights/134/1/1 = {"time":1596135711414,"value":"4.34"}
[Debug] zwave/office_lights/134/1/2 = {"time":1596135711414,"value":"5.17"}

So yeah. Everything works fine if I update via the actual physical paddle. As I move stuff around it shows the correct values in Home Assistant. It's just updating via Home Assistant that I get this.

I noticed that it also doesn't do a /set call if I press the paddle. Just that I hit "up" basically.

[taylormia]

I'm on zwave2mqtt 3.4.1 and I have the same behavior described above on my HS WD100+ dimmers. When the dimmer is turned off with an automation - the light actually does turn off but the UI shows "On". If the automation is run again..then the UI changes to "Off". I have the latest firmware on the dimmer i.e. 5.19. When the dimmer is turned off by tapping the paddle - the UI reflects the change correctly.The only way to guarantee that the UI reflects the actual state of the light when its turned off by any method is by polling the device - which I'm not willing to do because it creates a huge amount of "noise" since I have 17 these dimmers.

[robertsLando]

@CWSpear To debug such things I would need to have your device and your hass settings, the things that could cause this kind of behaviour are multiple (device firmware, incorrect discovery template, hass doing weird things for example). From a z2m side I don't think there is a "bug", If you see z2m receives and sends mqtt updates it is working, I publish everything I receive from the device, if you don't see a publish it means the device is not sending me the value change event

[CWSpear]

Ok, so I was investigating it more on the z2m side.

For example, if I'm at Level 13, and I try to go to 55 via the z2m interface, e.g. change the value to 55 and hit the submit button:

And try to capture what happens in the logs, I see this:

z2m:App Zwave api call: setValue [ 30, 38, 1, 0, '55' ] +27s
z2m:Zwave Success zwave api call setValue +26s
OpenZWave Info, Node030, Value::Set - COMMAND_CLASS_SWITCH_MULTILEVEL - Level - 0 - 1 - 55
OpenZWave Info, Node030, SwitchMultilevel::Set - Setting to level 55
OpenZWave Detail, Node030, Queuing (Send) SwitchMultilevelCmd_Set (Node=30): 0x01, 0x0a, 0x00, 0x13, 0x1e, 0x03, 0x26, 0x01, 0x37, 0x25, 0x71, 0xbf
OpenZWave Detail, Node030, Queuing (Send) SwitchMultilevelCmd_Get (Node=30): 0x01, 0x09, 0x00, 0x13, 0x1e, 0x02, 0x26, 0x02, 0x25, 0x72, 0x8a
OpenZWave Detail,
OpenZWave Info, Node030, Sending (Send) message (Callback ID=0x71, Expected Reply=0x13) - SwitchMultilevelCmd_Set (Node=30): 0x01, 0x0a, 0x00, 0x13, 0x1e, 0x03, 0x26, 0x01, 0x37, 0x25, 0x71, 0xbf
OpenZWave Info, Node030, Encrypted Flag is 0
OpenZWave Detail, Node030, Received: 0x01, 0x04, 0x01, 0x13, 0x01, 0xe8
OpenZWave Detail, Node030, ZW_SEND_DATA delivered to Z-Wave stack
OpenZWave Detail, Node030, Received: 0x01, 0x07, 0x00, 0x13, 0x71, 0x00, 0x00, 0x02, 0x98
OpenZWave Detail, Node030, ZW_SEND_DATA Request with callback ID 0x71 received (expected 0x71)
OpenZWave Info, Node030, Request RTT 23 Average Request RTT 23
OpenZWave Detail, Node030, Expected callbackId was received
OpenZWave Detail, Node030, Expected reply was received
OpenZWave Detail, Node030, Message transaction complete
OpenZWave Detail,
OpenZWave Detail, Node030, Removing current message
OpenZWave Detail,
OpenZWave Info, Node030, Sending (Send) message (Callback ID=0x72, Expected Reply=0x04) - SwitchMultilevelCmd_Get (Node=30): 0x01, 0x09, 0x00, 0x13, 0x1e, 0x02, 0x26, 0x02, 0x25, 0x72, 0x8a
OpenZWave Info, Node030, Encrypted Flag is 0
OpenZWave Detail, Node030, Received: 0x01, 0x04, 0x01, 0x13, 0x01, 0xe8
OpenZWave Detail, Node030, ZW_SEND_DATA delivered to Z-Wave stack
OpenZWave Detail, Node030, Received: 0x01, 0x07, 0x00, 0x13, 0x72, 0x00, 0x00, 0x02, 0x9b
OpenZWave Detail, Node030, ZW_SEND_DATA Request with callback ID 0x72 received (expected 0x72)
OpenZWave Info, Node030, Request RTT 25 Average Request RTT 24
OpenZWave Detail, Node030, Expected callbackId was received
OpenZWave Detail, Node030, Received: 0x01, 0x09, 0x00, 0x04, 0x00, 0x1e, 0x03, 0x26, 0x03, 0x0d, 0xc7
OpenZWave Detail,
z2m:Zwave zwave node 30: changed: 38-1-0:Level:13 -> 13 +62ms
OpenZWave Info, Node030, Response RTT 36 Average Response RTT 35
OpenZWave Info, Node030, Received SwitchMultiLevel report: level=13
OpenZWave Detail, Node030, Value Updated: old value=13, new value=13, type=byte
OpenZWave Detail, Node030, Changes to this value are verified
OpenZWave Detail, Node030, Expected reply and command class was received
OpenZWave Detail, Node030, Message transaction complete
OpenZWave Detail,
OpenZWave Detail, Node030, Removing current message

It immediately sets it back to 13. And in the UI, (e.g. screenshot above), it immediately changes back to 13. But the lights actually change to 55. And if I change it to 55 again and do it, it of course works.

It doesn't do this every time, but it does do it most times.

I updated the Firmware just to be case, and then removed/added the device, but it didn't make a difference.

Device: HS-WD100+ Wall Dimmer from HomeSeer Firmware (aka Application) Version: 5.19 Procol Version: 4.34 Library Version: 3 OpenZWave Version: 1.6.1210 ZWave2MQTT Version: latest Docker tag as of today

Specifically... it doesn't seem like an issue with z2m as maybe openzwave in general? (Or of course, it could be the Switch or the Z-Stick I'm using (Aeotec Z-Stick Gen5), but other hubs (SmartThings, Hubitat) seem to handle it just fine.)

[robertsLando]

Specifically... it doesn't seem like an issue with z2m as maybe openzwave in general

Based on your logs I don't see any error/bug with z2m, what you see there are messages coming from ozw, and there are no errors. It also could be a device firmware bug

[chilicheech]

In the old home assistant zwave integration there's a setting to have it poll for the value a few seconds after turning on/off the light. I'm not sure if z2m has something similar, although polling should solve this issue.

[robertsLando]

You can enable polling of specific values using gateway values table in settings

---

Daniel

On 12 Aug 2020, at 18:51, Thiago Oliveira notifications@github.com wrote:

 In the old home assistant zwave integration there's a setting to have it poll for the value a few seconds after turning on/off the light. I'm not sure if z2m has something similar, although polling should solve this issue.

— You are receiving this because you were assigned. Reply to this email directly, view it on GitHub, or unsubscribe.

[chilicheech]

@CWSpear another thing you can try is setting the Verify Changes setting on node types that don't send unsolicited state reports. I believe what this will do is when you turn the dimmer on or off z2m will keep polling until the value stops changing. That way you get faster feedback in the home assistant UI. When you flip the switch you'll still see it go back to the original position and then, as z2m polls the value, you'll see it go to the final value in a few seconds.