Z-Wave Dimmer Switch Slow To Respond (HS-WD200+)

SpikeyGG · May 13, 2018, 6:33pm

Hello HA Folks, I have a small Z-Wave network currently as I’m experimenting with what I can do. I have a few GE switches that seem to work very well and I recently bought a HomeSeer HS-WD200+ dimmer switch. I found it on this thread.

With the GE switches I’ve found that the switch operates fairly fluidly. When you turn the light off using the HA controls: it flips the graphical switch image, the lightbulb icon toggles and everything seems to work very well. When using this new HS-WD200+ switch, if I try to hit the HA control switch, it will always control the physical light but the graphical HA stuff doesn’t seem to line up. For example:

Starting from lights off in the room, controls line up:
I click the little switch and I see it flip and turn blue for 10s of milliseconds, then it flips back to “off” but the physical light turns on inside the room and stays on. Now the pop up window looks like this:
I have found, if I close the pop up window and go into the Services area, I can force a refresh of that node and it will set the values correctly. Filling out the following and hitting the “CALL SERVICE” button.

image912×501 31.1 KB
Now the pop up lines up with reality:

This also happens with the Brightness slider, if I change the value on the slider it controls the physical light but the bulb and switch graphics won’t line up with reality until I call the refresh_node service.

Is there a way to make this more robust so that my switch doesn’t get out of sync? Seems like this is probably a lower-level change in the OpenZWave configuration or something… Maybe this device hasn’t been fully vetted yet?

One thing I have noticed is that flipping the light full-on from off (or vice versa), it takes about 4 seconds to get there. I wonder if this internal delay is working against the HA update software, like the software is polling the hardware too quickly to get an accurate response.

Thanks,
-Greg
Not sure it matters but I’m using the Aeotec ZW090 Z-Stick Gen5 US as my controller.

ceh · May 13, 2018, 8:08pm

At the end of the zwave docs, there is some information about status updates. You may need to enable polling for that device.

pnbruckner · May 13, 2018, 8:41pm

Or, especially for a dimmer, you probably need refresh_value & delay. E.g., for my GE plug-in dimmer (with default transition time configuration of 2.97 sec) I have this in my configuration.yaml:

zwave:
  usb_path: /dev/zwave
  network_key: !secret zwave_network_key
  device_config:
    light.family_room_lamp:
      refresh_value: true
      delay: 3

Normally HA will check the light’s status immediately after telling it to change. But since a dimmer can take time to fully transition, it will get the status too soon. Adding this to configuration.yaml causes HA to check the status again (3 sec in this case) after telling the dimmer to change.

SpikeyGG · May 18, 2018, 1:44pm

I tried to do this and even setting it to 10 seconds doesn’t solve the issue. In fact, I noticed that the dimmer-slider is always one step behind when I try to use it. If I set the slider to half-way when the bulb is off, within milliseconds it jumps back to off, then if I set it to full brightness within milliseconds it jumps to back to half-way. Then if I move the slider to half-way, within milliseconds it jumps to full brightness. I did all this testing with the delay set to 10:

zwave:
  usb_path: /dev/ttyACM0
  device_config:
    light.office_light_dimmer:
      refresh_value: true
      delay: 10

Is there anything else I need to enable to get the delay to function properly?

pnbruckner · May 18, 2018, 2:24pm

Not sure what to tell you. It worked for my z-wave dimmer.

I actually still have some OZW_Log.txt snippets from when I was figuring this out. This first one shows what happens when I just turn on the dimmer (without specifying a brightness level.) In this case the z-wave level “255” is sent, which is a special value that means “turn on to previous brightness level.” In this case the dimmer ramps up to it in 2.97 sec. If you look closely, you’ll see the immediate reading after sending the command (shown as SwitchMultiLevel report: level=xxx) shows a level of only 2. (Z-wave uses values from 0 for off to 99 for full on.) Then after 3 seconds, the refresh happens and it sees the dimmer is now full on (level 99.)

pi@raspberrypi:/home/homeassistant/.homeassistant $ tail -n 0 -f OZW_Log.txt | grep Info
2018-04-26 23:18:07.460 Info, Node007, Value::Set - COMMAND_CLASS_SWITCH_MULTILEVEL - Lamp - 0 - 1 - 255
2018-04-26 23:18:07.460 Info, Node007, SwitchMultilevel::Set - Setting to level 255
2018-04-26 23:18:07.461 Info, Node007, Sending (Send) message (Callback ID=0x3d, Expected Reply=0x13) - SwitchMultilevelCmd_Set (Node=7): 0x01, 0x0a, 0x00, 0x13, 0x07, 0x03, 0x26, 0x01, 0xff, 0x25, 0x3d, 0x22
2018-04-26 23:18:07.493 Info, Node007, Request RTT 31 Average Request RTT 30
2018-04-26 23:18:07.494 Info, Node007, Sending (Send) message (Callback ID=0x3e, Expected Reply=0x04) - SwitchMultilevelCmd_Get (Node=7): 0x01, 0x09, 0x00, 0x13, 0x07, 0x02, 0x26, 0x02, 0x25, 0x3e, 0xdf
2018-04-26 23:18:07.525 Info, Node007, Request RTT 30 Average Request RTT 30
2018-04-26 23:18:07.541 Info, Node007, Response RTT 47 Average Response RTT 46
2018-04-26 23:18:07.541 Info, Node007, Received SwitchMultiLevel report: level=2
2018-04-26 23:18:10.562 Info, mgr,     Refreshing node 7: COMMAND_CLASS_SWITCH_MULTILEVEL index = 0 instance = 1 (to confirm a reported change)
2018-04-26 23:18:10.564 Info, Node007, Sending (Send) message (Callback ID=0x3f, Expected Reply=0x04) - SwitchMultilevelCmd_Get (Node=7): 0x01, 0x09, 0x00, 0x13, 0x07, 0x02, 0x26, 0x02, 0x25, 0x3f, 0xde
2018-04-26 23:18:10.595 Info, Node007, Request RTT 30 Average Request RTT 30
2018-04-26 23:18:10.611 Info, Node007, Response RTT 46 Average Response RTT 46
2018-04-26 23:18:10.611 Info, Node007, Received SwitchMultiLevel report: level=99

And this one shows what happens when I turn on the dimmer with a brightness level specified. In this case I used a brightness_pct of 100 (which is equivalent to brightness 255, which is equivalent to a z-wave level of 99.)

2018-04-26 23:19:17.062 Info, Node007, Value::Set - COMMAND_CLASS_SWITCH_MULTILEVEL - Lamp - 0 - 1 - 99
2018-04-26 23:19:17.063 Info, Node007, SwitchMultilevel::Set - Setting to level 99
2018-04-26 23:19:17.063 Info, Node007, Sending (Send) message (Callback ID=0x45, Expected Reply=0x13) - SwitchMultilevelCmd_Set (Node=7): 0x01, 0x0a, 0x00, 0x13, 0x07, 0x03, 0x26, 0x01, 0x63, 0x25, 0x45, 0xc6
2018-04-26 23:19:17.095 Info, Node007, Request RTT 31 Average Request RTT 30
2018-04-26 23:19:17.096 Info, Node007, Sending (Send) message (Callback ID=0x46, Expected Reply=0x04) - SwitchMultilevelCmd_Get (Node=7): 0x01, 0x09, 0x00, 0x13, 0x07, 0x02, 0x26, 0x02, 0x25, 0x46, 0xa7
2018-04-26 23:19:17.127 Info, Node007, Request RTT 30 Average Request RTT 30
2018-04-26 23:19:17.143 Info, Node007, Response RTT 47 Average Response RTT 46
2018-04-26 23:19:17.143 Info, Node007, Received SwitchMultiLevel report: level=99
2018-04-26 23:19:20.164 Info, mgr,     Refreshing node 7: COMMAND_CLASS_SWITCH_MULTILEVEL index = 0 instance = 1 (to confirm a reported change)
2018-04-26 23:19:20.166 Info, Node007, Sending (Send) message (Callback ID=0x47, Expected Reply=0x04) - SwitchMultilevelCmd_Get (Node=7): 0x01, 0x09, 0x00, 0x13, 0x07, 0x02, 0x26, 0x02, 0x25, 0x47, 0xa6
2018-04-26 23:19:20.196 Info, Node007, Request RTT 30 Average Request RTT 30
2018-04-26 23:19:20.213 Info, Node007, Response RTT 46 Average Response RTT 46
2018-04-26 23:19:20.213 Info, Node007, Received SwitchMultiLevel report: level=99

You can see the level of 99 was sent, and the immediate read back (and, of course, the later refresh) showed it went immediately to full on (i.e., level 99.) This is because the way this dimmer works (or maybe they all do) is it ramps only when the special level of 255 is sent, otherwise it changes immediately.

So, the moral of the story is, you might want to check the OZW_Log.txt file to see what’s happening with your device.

SpikeyGG · May 20, 2018, 2:29pm

This is what the OZW_Log.txt looks like when I hit the software switch and the physical bulb goes from full on (100% brightness) to full off:

2018-05-20 08:18:22.894 Info, Node004, Value::Set - COMMAND_CLASS_SWITCH_MULTILEVEL - office - 0 - 1 - 0
2018-05-20 08:18:22.895 Info, Node004, SwitchMultilevel::Set - Setting to level 0
2018-05-20 08:18:22.895 Detail, Node004, Queuing (Send) SwitchMultilevelCmd_Set (Node=4): 0x01, 0x0a, 0x00, 0x13, 0x04, 0x03, 0x26, 0x01, 0x00, 0x25, 0x31, 0xd2
2018-05-20 08:18:22.896 Detail, Node004, Queuing (Send) SwitchMultilevelCmd_Get (Node=4): 0x01, 0x09, 0x00, 0x13, 0x04, 0x02, 0x26, 0x02, 0x25, 0x32, 0xd0
2018-05-20 08:18:22.896 Detail,
2018-05-20 08:18:22.896 Info, Node004, Sending (Send) message (Callback ID=0x31, Expected Reply=0x13) - SwitchMultilevelCmd_Set (Node=4): 0x01, 0x0a, 0x00, 0x13, 0x04, 0x03, 0x26, 0x01, 0x00, 0x25, 0x31, 0xd2
2018-05-20 08:18:22.905 Detail, Node004,   Received: 0x01, 0x04, 0x01, 0x13, 0x01, 0xe8
2018-05-20 08:18:22.905 Detail, Node004,   ZW_SEND_DATA delivered to Z-Wave stack
2018-05-20 08:18:22.921 Detail, Node004,   Received: 0x01, 0x07, 0x00, 0x13, 0x31, 0x00, 0x00, 0x02, 0xd8
2018-05-20 08:18:22.921 Detail, Node004,   ZW_SEND_DATA Request with callback ID 0x31 received (expected 0x31)
2018-05-20 08:18:22.921 Info, Node004, Request RTT 25 Average Request RTT 26
2018-05-20 08:18:22.921 Detail,   Expected callbackId was received
2018-05-20 08:18:22.921 Detail,   Expected reply was received
2018-05-20 08:18:22.922 Detail,   Message transaction complete
2018-05-20 08:18:22.922 Detail,
2018-05-20 08:18:22.922 Detail, Node004, Removing current message
2018-05-20 08:18:22.922 Detail,
2018-05-20 08:18:22.922 Info, Node004, Sending (Send) message (Callback ID=0x32, Expected Reply=0x04) - SwitchMultilevelCmd_Get (Node=4): 0x01, 0x09, 0x00, 0x13, 0x04, 0x02, 0x26, 0x02, 0x25, 0x32, 0xd0
2018-05-20 08:18:22.931 Detail, Node004,   Received: 0x01, 0x04, 0x01, 0x13, 0x01, 0xe8
2018-05-20 08:18:22.931 Detail, Node004,   ZW_SEND_DATA delivered to Z-Wave stack
2018-05-20 08:18:22.947 Detail, Node004,   Received: 0x01, 0x07, 0x00, 0x13, 0x32, 0x00, 0x00, 0x02, 0xdb
2018-05-20 08:18:22.948 Detail, Node004,   ZW_SEND_DATA Request with callback ID 0x32 received (expected 0x32)
2018-05-20 08:18:22.948 Info, Node004, Request RTT 25 Average Request RTT 25
2018-05-20 08:18:22.948 Detail,   Expected callbackId was received
2018-05-20 08:18:22.964 Detail, Node004,   Received: 0x01, 0x0b, 0x00, 0x04, 0x00, 0x04, 0x05, 0x26, 0x03, 0x62, 0x00, 0x00, 0xb6
2018-05-20 08:18:22.964 Detail,
2018-05-20 08:18:22.966 Info, Node004, Response RTT 44 Average Response RTT 52
2018-05-20 08:18:22.967 Info, Node004, Received SwitchMultiLevel report: level=98
2018-05-20 08:18:22.967 Detail, Node004, Refreshed Value: old value=98, new value=98, type=byte
2018-05-20 08:18:22.967 Detail, Node004, Changes to this value are not verified
2018-05-20 08:18:22.967 Detail, Node004,   Expected reply and command class was received
2018-05-20 08:18:22.967 Detail, Node004,   Message transaction complete
2018-05-20 08:18:22.967 Detail,
2018-05-20 08:18:22.968 Detail, Node004, Removing current message
2018-05-20 08:18:22.968 Detail, Node004, Notification: ValueChanged
2018-05-20 08:18:23.898 Info, mgr,     Refreshing node 4: COMMAND_CLASS_SWITCH_MULTILEVEL index = 0 instance = 1 (to confirm a reported change)
2018-05-20 08:18:23.898 Detail, Node004, Queuing (Send) SwitchMultilevelCmd_Get (Node=4): 0x01, 0x09, 0x00, 0x13, 0x04, 0x02, 0x26, 0x02, 0x25, 0x33, 0xd1
2018-05-20 08:18:23.899 Detail,
2018-05-20 08:18:23.899 Info, Node004, Sending (Send) message (Callback ID=0x33, Expected Reply=0x04) - SwitchMultilevelCmd_Get (Node=4): 0x01, 0x09, 0x00, 0x13, 0x04, 0x02, 0x26, 0x02, 0x25, 0x33, 0xd1
2018-05-20 08:18:23.908 Detail, Node004,   Received: 0x01, 0x04, 0x01, 0x13, 0x01, 0xe8
2018-05-20 08:18:23.909 Detail, Node004,   ZW_SEND_DATA delivered to Z-Wave stack
2018-05-20 08:18:23.924 Detail, Node004,   Received: 0x01, 0x07, 0x00, 0x13, 0x33, 0x00, 0x00, 0x03, 0xdb
2018-05-20 08:18:23.925 Detail, Node004,   ZW_SEND_DATA Request with callback ID 0x33 received (expected 0x33)
2018-05-20 08:18:23.925 Info, Node004, Request RTT 25 Average Request RTT 25
2018-05-20 08:18:23.925 Detail,   Expected callbackId was received
2018-05-20 08:18:23.941 Detail, Node004,   Received: 0x01, 0x0b, 0x00, 0x04, 0x00, 0x04, 0x05, 0x26, 0x03, 0x42, 0x00, 0x00, 0x96
2018-05-20 08:18:23.942 Detail,
2018-05-20 08:18:23.942 Info, Node004, Response RTT 42 Average Response RTT 47
2018-05-20 08:18:23.942 Info, Node004, Received SwitchMultiLevel report: level=66
2018-05-20 08:18:23.942 Detail, Node004, Refreshed Value: old value=98, new value=66, type=byte
2018-05-20 08:18:23.942 Detail, Node004, Changes to this value are not verified
2018-05-20 08:18:23.943 Detail, Node004,   Expected reply and command class was received
2018-05-20 08:18:23.943 Detail, Node004,   Message transaction complete
2018-05-20 08:18:23.943 Detail,
2018-05-20 08:18:23.943 Detail, Node004, Removing current message
2018-05-20 08:18:23.944 Detail, Node004, Notification: ValueChanged
2018-05-20 08:18:24.899 Info, mgr,     Refreshing node 4: COMMAND_CLASS_SWITCH_MULTILEVEL index = 0 instance = 1 (to confirm a reported change)
2018-05-20 08:18:24.900 Detail, Node004, Queuing (Send) SwitchMultilevelCmd_Get (Node=4): 0x01, 0x09, 0x00, 0x13, 0x04, 0x02, 0x26, 0x02, 0x25, 0x34, 0xd6
2018-05-20 08:18:24.900 Detail,
2018-05-20 08:18:24.900 Info, Node004, Sending (Send) message (Callback ID=0x34, Expected Reply=0x04) - SwitchMultilevelCmd_Get (Node=4): 0x01, 0x09, 0x00, 0x13, 0x04, 0x02, 0x26, 0x02, 0x25, 0x34, 0xd6
2018-05-20 08:18:24.909 Detail, Node004,   Received: 0x01, 0x04, 0x01, 0x13, 0x01, 0xe8
2018-05-20 08:18:24.910 Detail, Node004,   ZW_SEND_DATA delivered to Z-Wave stack
2018-05-20 08:18:24.925 Detail, Node004,   Received: 0x01, 0x07, 0x00, 0x13, 0x34, 0x00, 0x00, 0x03, 0xdc
2018-05-20 08:18:24.926 Detail, Node004,   ZW_SEND_DATA Request with callback ID 0x34 received (expected 0x34)
2018-05-20 08:18:24.926 Info, Node004, Request RTT 25 Average Request RTT 25
2018-05-20 08:18:24.926 Detail,   Expected callbackId was received
2018-05-20 08:18:24.943 Detail, Node004,   Received: 0x01, 0x0b, 0x00, 0x04, 0x00, 0x04, 0x05, 0x26, 0x03, 0x21, 0x00, 0x00, 0xf5
2018-05-20 08:18:24.943 Detail,
2018-05-20 08:18:24.943 Info, Node004, Response RTT 42 Average Response RTT 44
2018-05-20 08:18:24.943 Info, Node004, Received SwitchMultiLevel report: level=33
2018-05-20 08:18:24.943 Detail, Node004, Refreshed Value: old value=66, new value=33, type=byte
2018-05-20 08:18:24.944 Detail, Node004, Changes to this value are not verified
2018-05-20 08:18:24.944 Detail, Node004,   Expected reply and command class was received
2018-05-20 08:18:24.944 Detail, Node004,   Message transaction complete
2018-05-20 08:18:24.944 Detail,
2018-05-20 08:18:24.944 Detail, Node004, Removing current message
2018-05-20 08:18:24.945 Detail, Node004, Notification: ValueChanged

It looks to me like it gets a SwitchMultilevelCmd_Set when I click the switch at 8:18:22, then it does three SwitchMultilevelCmd_Get commands:

8:18:22 returns level=98
8:18:23 returns level=66
8:18:24 returns level=33

That’s where it stops, and my HA popup window looks like this:

Again, this is with the following in my configuration.yaml file:

zwave:
  usb_path: /dev/ttyACM0
  device_config:
    light.office_light_dimmer:
      refresh_value: true
      delay: 10

I see my OZW log file hit the light switch with “get” commands three times, one time each second for a total of three seconds. It seems that the delay: 10 value is totally ignored.

Would you possibly verify that if you blow your delay value out to 10 seconds that you see a “get” command in your OZW log file happen 10 seconds after a software trigger? I’m not sure how else to troubleshoot this.

Thanks,
-Greg

pnbruckner · May 20, 2018, 3:14pm

Interesting. I just turned the dimmer on, and then back off, and watched the corresponding Info messages. This is with the current refresh delay of 3 seconds. This time when it turned off it refreshed a couple of times a second apart, then waited 3 seconds and refreshed one last time. I’ll try changing the delay to 10 and let you know how that goes. Here are the log messages for the test I just ran:

pi@raspberrypi:/home/homeassistant/.homeassistant $ tail -f OZW_Log.txt | grep -e 'Info, mgr' -e 'Info, Node007'
2018-05-20 10:08:56.726 Info, Node007, Value::Set - COMMAND_CLASS_SWITCH_MULTILEVEL - Lamp - 0 - 1 - 255
2018-05-20 10:08:56.727 Info, Node007, SwitchMultilevel::Set - Setting to level 255
2018-05-20 10:08:56.728 Info, Node007, Sending (Send) message (Callback ID=0x45, Expected Reply=0x13) - SwitchMultilevelCmd_Set (Node=7): 0x01, 0x0a, 0x00, 0x13, 0x07, 0x03, 0x26, 0x01, 0xff, 0x25, 0x45, 0x5a
2018-05-20 10:08:56.759 Info, Node007, Request RTT 30 Average Request RTT 29
2018-05-20 10:08:56.762 Info, Node007, Sending (Send) message (Callback ID=0x46, Expected Reply=0x04) - SwitchMultilevelCmd_Get (Node=7): 0x01, 0x09, 0x00, 0x13, 0x07, 0x02, 0x26, 0x02, 0x25, 0x46, 0xa7
2018-05-20 10:08:56.792 Info, Node007, Request RTT 29 Average Request RTT 29
2018-05-20 10:08:56.808 Info, Node007, Response RTT 44 Average Response RTT 44
2018-05-20 10:08:56.808 Info, Node007, Received SwitchMultiLevel report: level=2
2018-05-20 10:08:59.835 Info, mgr,     Refreshing node 7: COMMAND_CLASS_SWITCH_MULTILEVEL index = 0 instance = 1 (to confirm a reported change)
2018-05-20 10:08:59.836 Info, Node007, Sending (Send) message (Callback ID=0x48, Expected Reply=0x04) - SwitchMultilevelCmd_Get (Node=7): 0x01, 0x09, 0x00, 0x13, 0x07, 0x02, 0x26, 0x02, 0x25, 0x48, 0xa9
2018-05-20 10:08:59.867 Info, Node007, Request RTT 30 Average Request RTT 29
2018-05-20 10:08:59.882 Info, Node007, Response RTT 45 Average Response RTT 44
2018-05-20 10:08:59.882 Info, Node007, Received SwitchMultiLevel report: level=99
^C
pi@raspberrypi:/home/homeassistant/.homeassistant $ tail -f OZW_Log.txt | grep -e 'Info, mgr' -e 'Info, Node007'
2018-05-20 10:09:19.823 Info, Node007, Value::Set - COMMAND_CLASS_SWITCH_MULTILEVEL - Lamp - 0 - 1 - 0
2018-05-20 10:09:19.823 Info, Node007, SwitchMultilevel::Set - Setting to level 0
2018-05-20 10:09:19.824 Info, Node007, Sending (Send) message (Callback ID=0x4b, Expected Reply=0x13) - SwitchMultilevelCmd_Set (Node=7): 0x01, 0x0a, 0x00, 0x13, 0x07, 0x03, 0x26, 0x01, 0x00, 0x25, 0x4b, 0xab
2018-05-20 10:09:19.855 Info, Node007, Request RTT 30 Average Request RTT 29
2018-05-20 10:09:19.856 Info, Node007, Sending (Send) message (Callback ID=0x4c, Expected Reply=0x04) - SwitchMultilevelCmd_Get (Node=7): 0x01, 0x09, 0x00, 0x13, 0x07, 0x02, 0x26, 0x02, 0x25, 0x4c, 0xad
2018-05-20 10:09:19.887 Info, Node007, Request RTT 30 Average Request RTT 29
2018-05-20 10:09:19.902 Info, Node007, Response RTT 46 Average Response RTT 45
2018-05-20 10:09:19.902 Info, Node007, Received SwitchMultiLevel report: level=98
2018-05-20 10:09:20.825 Info, mgr,     Refreshing node 7: COMMAND_CLASS_SWITCH_MULTILEVEL index = 0 instance = 1 (to confirm a reported change)
2018-05-20 10:09:20.826 Info, Node007, Sending (Send) message (Callback ID=0x4d, Expected Reply=0x04) - SwitchMultilevelCmd_Get (Node=7): 0x01, 0x09, 0x00, 0x13, 0x07, 0x02, 0x26, 0x02, 0x25, 0x4d, 0xac
2018-05-20 10:09:20.857 Info, Node007, Request RTT 31 Average Request RTT 30
2018-05-20 10:09:20.873 Info, Node007, Response RTT 46 Average Response RTT 45
2018-05-20 10:09:20.873 Info, Node007, Received SwitchMultiLevel report: level=66
2018-05-20 10:09:21.830 Info, mgr,     Refreshing node 7: COMMAND_CLASS_SWITCH_MULTILEVEL index = 0 instance = 1 (to confirm a reported change)
2018-05-20 10:09:21.830 Info, Node007, Sending (Send) message (Callback ID=0x4e, Expected Reply=0x04) - SwitchMultilevelCmd_Get (Node=7): 0x01, 0x09, 0x00, 0x13, 0x07, 0x02, 0x26, 0x02, 0x25, 0x4e, 0xaf
2018-05-20 10:09:21.859 Info, Node007, Request RTT 28 Average Request RTT 29
2018-05-20 10:09:21.876 Info, Node007, Response RTT 45 Average Response RTT 45
2018-05-20 10:09:21.876 Info, Node007, Received SwitchMultiLevel report: level=33
2018-05-20 10:09:24.897 Info, mgr,     Refreshing node 7: COMMAND_CLASS_SWITCH_MULTILEVEL index = 0 instance = 1 (to confirm a reported change)
2018-05-20 10:09:24.898 Info, Node007, Sending (Send) message (Callback ID=0x4f, Expected Reply=0x04) - SwitchMultilevelCmd_Get (Node=7): 0x01, 0x09, 0x00, 0x13, 0x07, 0x02, 0x26, 0x02, 0x25, 0x4f, 0xae
2018-05-20 10:09:24.929 Info, Node007, Request RTT 30 Average Request RTT 29
2018-05-20 10:09:24.944 Info, Node007, Response RTT 45 Average Response RTT 45
2018-05-20 10:09:24.945 Info, Node007, Received SwitchMultiLevel report: level=0
^C

Not sure it matters, but I have updated HA since those original log messages I showed above.

pnbruckner · May 20, 2018, 3:18pm

With refresh delay set to 10 sec, same as above, but 10 sec before last refresh:

pi@raspberrypi:/home/homeassistant/.homeassistant $ tail -f OZW_Log.txt | grep -e 'Info, mgr' -e 'Info, Node007'
2018-05-20 10:17:26.560 Info, Node007, Value::Set - COMMAND_CLASS_SWITCH_MULTILEVEL - Lamp - 0 - 1 - 255
2018-05-20 10:17:26.560 Info, Node007, SwitchMultilevel::Set - Setting to level 255
2018-05-20 10:17:26.561 Info, Node007, Sending (Send) message (Callback ID=0x32, Expected Reply=0x13) - SwitchMultilevelCmd_Set (Node=7): 0x01, 0x0a, 0x00, 0x13, 0x07, 0x03, 0x26, 0x01, 0xff, 0x25, 0x32, 0x2d
2018-05-20 10:17:26.593 Info, Node007, Request RTT 31 Average Request RTT 30
2018-05-20 10:17:26.594 Info, Node007, Sending (Send) message (Callback ID=0x33, Expected Reply=0x04) - SwitchMultilevelCmd_Get (Node=7): 0x01, 0x09, 0x00, 0x13, 0x07, 0x02, 0x26, 0x02, 0x25, 0x33, 0xd2
2018-05-20 10:17:26.624 Info, Node007, Request RTT 30 Average Request RTT 30
2018-05-20 10:17:26.641 Info, Node007, Response RTT 46 Average Response RTT 45
2018-05-20 10:17:26.641 Info, Node007, Received SwitchMultiLevel report: level=2
2018-05-20 10:17:36.671 Info, mgr,     Refreshing node 7: COMMAND_CLASS_SWITCH_MULTILEVEL index = 0 instance = 1 (to confirm a reported change)
2018-05-20 10:17:36.672 Info, Node007, Sending (Send) message (Callback ID=0x35, Expected Reply=0x04) - SwitchMultilevelCmd_Get (Node=7): 0x01, 0x09, 0x00, 0x13, 0x07, 0x02, 0x26, 0x02, 0x25, 0x35, 0xd4
2018-05-20 10:17:36.704 Info, Node007, Request RTT 30 Average Request RTT 30
2018-05-20 10:17:36.720 Info, Node007, Response RTT 47 Average Response RTT 46
2018-05-20 10:17:36.720 Info, Node007, Received SwitchMultiLevel report: level=99
^C
pi@raspberrypi:/home/homeassistant/.homeassistant $ tail -f OZW_Log.txt | grep -e 'Info, mgr' -e 'Info, Node007'
2018-05-20 10:17:47.769 Info, Node007, Value::Set - COMMAND_CLASS_SWITCH_MULTILEVEL - Lamp - 0 - 1 - 0
2018-05-20 10:17:47.769 Info, Node007, SwitchMultilevel::Set - Setting to level 0
2018-05-20 10:17:47.770 Info, Node007, Sending (Send) message (Callback ID=0x37, Expected Reply=0x13) - SwitchMultilevelCmd_Set (Node=7): 0x01, 0x0a, 0x00, 0x13, 0x07, 0x03, 0x26, 0x01, 0x00, 0x25, 0x37, 0xd7
2018-05-20 10:17:47.801 Info, Node007, Request RTT 30 Average Request RTT 30
2018-05-20 10:17:47.802 Info, Node007, Sending (Send) message (Callback ID=0x38, Expected Reply=0x04) - SwitchMultilevelCmd_Get (Node=7): 0x01, 0x09, 0x00, 0x13, 0x07, 0x02, 0x26, 0x02, 0x25, 0x38, 0xd9
2018-05-20 10:17:47.831 Info, Node007, Request RTT 29 Average Request RTT 29
2018-05-20 10:17:47.847 Info, Node007, Response RTT 44 Average Response RTT 45
2018-05-20 10:17:47.847 Info, Node007, Received SwitchMultiLevel report: level=98
2018-05-20 10:17:48.771 Info, mgr,     Refreshing node 7: COMMAND_CLASS_SWITCH_MULTILEVEL index = 0 instance = 1 (to confirm a reported change)
2018-05-20 10:17:48.773 Info, Node007, Sending (Send) message (Callback ID=0x39, Expected Reply=0x04) - SwitchMultilevelCmd_Get (Node=7): 0x01, 0x09, 0x00, 0x13, 0x07, 0x02, 0x26, 0x02, 0x25, 0x39, 0xd8
2018-05-20 10:17:48.802 Info, Node007, Request RTT 29 Average Request RTT 29
2018-05-20 10:17:48.816 Info, Node007, Response RTT 43 Average Response RTT 44
2018-05-20 10:17:48.816 Info, Node007, Received SwitchMultiLevel report: level=66
2018-05-20 10:17:49.775 Info, mgr,     Refreshing node 7: COMMAND_CLASS_SWITCH_MULTILEVEL index = 0 instance = 1 (to confirm a reported change)
2018-05-20 10:17:49.775 Info, Node007, Sending (Send) message (Callback ID=0x3a, Expected Reply=0x04) - SwitchMultilevelCmd_Get (Node=7): 0x01, 0x09, 0x00, 0x13, 0x07, 0x02, 0x26, 0x02, 0x25, 0x3a, 0xdb
2018-05-20 10:17:49.806 Info, Node007, Request RTT 29 Average Request RTT 29
2018-05-20 10:17:49.821 Info, Node007, Response RTT 45 Average Response RTT 44
2018-05-20 10:17:49.821 Info, Node007, Received SwitchMultiLevel report: level=33
2018-05-20 10:17:59.845 Info, mgr,     Refreshing node 7: COMMAND_CLASS_SWITCH_MULTILEVEL index = 0 instance = 1 (to confirm a reported change)
2018-05-20 10:17:59.856 Info, Node007, Sending (Send) message (Callback ID=0x3c, Expected Reply=0x04) - SwitchMultilevelCmd_Get (Node=7): 0x01, 0x09, 0x00, 0x13, 0x07, 0x02, 0x26, 0x02, 0x25, 0x3c, 0xdd
2018-05-20 10:17:59.886 Info, Node007, Request RTT 29 Average Request RTT 29
2018-05-20 10:17:59.900 Info, Node007, Response RTT 43 Average Response RTT 43
2018-05-20 10:17:59.901 Info, Node007, Received SwitchMultiLevel report: level=0
^C

Jon123 · May 29, 2018, 6:01pm

Thanks for this! I was running in to this same issue with a Linear (GoControl) WD500Z-1 dimmer and this got things working much better.

In case anyone else is having this problem, here is what I was seeing:
Light is off, switch is off. Turn it on in HA, the light turns on and the switch shows On in HA, checking the brightness level though shows it at 0 (slider is all the way to to the left).
Starting from that state if I set the switch to Off in HA, the light turns off, but the brightness level shows up as 33% and the switch UI turns back to On even though the physical light is off.
If I then turn switch to Off again, the UI updates to show the switch as off, nothing changes to the actual lights.
Checking the OZW logs, it backs this up as well - the last command received is the value change to 33% when the light starts from On. Turning it off again (because HA shows the UI as the switch being on), refreshes the value from 33% down to 0%.

LeBlaanc · July 9, 2018, 1:45am

Did we get an actual solution to this? Setting a refresh delay seems like a workaround.

SpikeyGG · December 2, 2018, 11:19pm

I got the 10 second delay that pnbruckner shared working and I haven’t messed with it since. Not sure there is a “positive confirmation” handshake that will make this work seamlessly and perfectly every time using zWave. That would be nice!

iDVB · September 5, 2019, 1:05am

I agree with @LeBlaanc, this has been an issue with these devices since they came out.
Meanwhile, I bought a $75 Smart Things hub and it works flawlessly with it. Immediate feedback in the app. Not to mention a ROCK_SOLID node adding interface. Just as you would expect with visual notification on the app the moment a successful add happens. As compared to needing to reboot HA to see if it worked.

The MAJOR downside to using the SmartThings Hub was that in order to integrate it with HA it requires you send the signals out to the internet and then back down to HA. At that point the delay is now the issue, not to mention privacy. But I’m still amazed at how well they have it pairing and working on that platform. I’m sure there is a way to do the same with OpenZWave/HA.

knallle · November 5, 2019, 11:03pm

Has anyone managed to solve this yet?

I’ve integrated a NEXA ZV-9101 (shows up in HA as Tronika Dimmer ZV-9101) and experience the same out-of-sync behaviours discussed earlier in this thread:

When I change the brightness level for the first time in a while, the change is immediate. If I wait a few seconds before changing the level again, the change is immediate. If I don’t wait a few seconds, the change is delayed several seconds.

I run the most up to date release of Hass.io (2019-11-06)
I use the Aeon Z-Stick 5
I have added my z-wave configuration via Configuration -> Integrations, not configuration.yaml.
My mesh has only two devices: an on/off switch and the dimmer.

haydon · February 6, 2020, 12:48am

I’m another +1 on this feature.

Setting the Z wave delay works, but it doesn’t fix the UI side of things. It does seem to fix my homekit issue where it would also show on when the device was off.

I have a Smartthings, and a pi running homebridge as my current home automation setup which works pretty well (except when homebridge crashes).

Testing with HomeAssistant, using Z-wave and Homekit initially i gave up because I coudln’t get home app on ios to reflect the correct state of the light, but now it does seem to be ok… Need to do more testing before switching the whole house over.

Now it does work a lot better, but the Web UI doesn’t. Keep up the great work!

mamssw · September 5, 2020, 10:45pm

Having the same problem with Jasco dimmer’s slow response time and inaccurate status report in the UI. For some reason, the Smartthings hub works with these devices flawlessly. Is anyone aware of a particular USB dongle that works with Jasco dimmers and other Z-Wave devices? Right now I am using the HUSBZB-1 USB Hub for z-wave. Thanks to all those smart developers!