Zwave dimmer slow state report when using web sockets

Hello,

i recently started playing with ZWaveJS and noticed that my dimmers are very slow to report the correct state to the UI when turning on the light. I switched my ZWaveJS to use MQTT instead of web sockets and the issue goes away.

The logs show a 5 second delay when using web sockets, and the value is reported as 255 not 99.
When using MQTT the state is reflected instantly and the value is set to 99.

I did not find those differences discussed in the forums yet, and was wondering why web sockets is using 255 instead of 99. Could that cause the delay?

Web Sockets:

2022-04-15 20:53:33.504 INFO ZWAVE: Node 8: value updated: 38-0-targetValue 0 => 255
2022-04-15 20:53:38.660 INFO ZWAVE: Node 8: value updated: 38-0-targetValue 255 => 99
2022-04-15 20:53:38.665 INFO ZWAVE: Node 8: value updated: 38-0-duration 0s => 0s
2022-04-15 20:53:38.668 INFO ZWAVE: Node 8: value updated: 38-0-currentValue 0 => 99

MQTT:

2022-04-15 20:57:34.176 INFO MQTT: Message received on zwave/Office_Main_Light/38/0/targetValue/set: '99'
2022-04-15 20:57:34.178 INFO ZWAVE: Writing 99 to 8-38-0-targetValue
2022-04-15 20:57:34.368 INFO ZWAVE: Node 8: value updated: 38-0-currentValue 0 => 99
2022-04-15 20:57:34.373 INFO ZWAVE: Node 8: value updated: 38-0-targetValue 0 => 99

I played some more with the dimmer. When using the service “light: turn_on” without brightness, the state is updated after 5 seconds. When setting the brightness to 255, in the “light: turn_on” the state for the dimmer is showing instantly in the UI.

Is there a way to override default service behavior for all dimmers to always include brightness?

2022-04-15 21:32:39.992 INFO ZWAVE: Node 8: value updated: 38-0-currentValue 0 => 99
2022-04-15 21:32:39.996 INFO ZWAVE: Node 8: value updated: 38-0-targetValue 0 => 99

I saw a similar issue with a fan zwave switch. In that case zwavejs was cancelling the poll after set, I opened a bug report and it should be getting fixed.

Capture the zwavejs log files and post the excerpt here

I see the same behavior on my HeatIt Z-Wave dimmers.
Home Assistant do not report light on until 4-5 seconds has passed when brightness is not set.

Turn on without brightness

2022-05-12 09:01:12.078 INFO ZWAVE: Node 23: value updated: 38-0-targetValue 0 => 255
2022-05-12 09:01:13.608 INFO ZWAVE: Node 23: value updated: 50-0-value-66049 0 => 9.9
2022-05-12 09:01:17.133 INFO ZWAVE: Node 23: value updated: 38-0-targetValue 255 => 34
2022-05-12 09:01:17.137 INFO ZWAVE: Node 23: value updated: 38-0-duration 0s => 0s
2022-05-12 09:01:17.140 INFO ZWAVE: Node 23: value updated: 38-0-currentValue 0 => 34

Turn on with brightness set

2022-05-12 09:03:32.855 INFO ZWAVE: Node 23: value updated: 38-0-currentValue 0 => 50
2022-05-12 09:03:32.858 INFO ZWAVE: Node 23: value updated: 38-0-targetValue 0 => 50
2022-05-12 09:03:34.734 INFO ZWAVE: Node 23: value updated: 50-0-value-66049 0 => 12.9
2022-05-12 09:03:47.437 INFO ZWAVE: Node 23: value updated: 50-0-value-65537 2.98 => 2.98

Here are the Z-wave logs:

Without brightness set

2022-05-12T07:36:32.491Z DRIVER » [Node 023] [REQ] [SendData]
                                  │ transmit options: 0x25
                                  │ callback id:      9
                                  └─[SupervisionCCGet]
                                    │ session id:      27
                                    │ request updates: true
                                    └─[MultilevelSwitchCCSet]
                                        target value: 255
                                        duration:     default
2022-05-12T07:36:32.513Z SERIAL « [ACK]                                                                   (0x06)
2022-05-12T07:36:32.516Z SERIAL « 0x0104011301e8                                                       (6 bytes)
2022-05-12T07:36:32.516Z SERIAL » [ACK]                                                                   (0x06)
2022-05-12T07:36:32.517Z DRIVER « [RES] [SendData]
                                    was sent: true
2022-05-12T07:36:32.521Z SERIAL « 0x0107001309000003e1                                                 (9 bytes)
2022-05-12T07:36:32.522Z SERIAL » [ACK]                                                                   (0x06)
2022-05-12T07:36:32.523Z DRIVER « [REQ] [SendData]
                                    callback id:     9
                                    transmit status: OK
2022-05-12T07:36:32.531Z SERIAL « 0x010b00040017056c021bff0068                                        (13 bytes)
2022-05-12T07:36:32.533Z SERIAL » [ACK]                                                                   (0x06)
2022-05-12T07:36:32.535Z DRIVER « [Node 023] [REQ] [ApplicationCommand]
                                  └─[SupervisionCCReport]
                                      session id:          27
                                      more updates follow: false
                                      status:              Success
                                      duration:            0s
2022-05-12T07:36:32.716Z DRIVER   Usage statistics sent - next transmission scheduled in 23 hours.
2022-05-12T07:36:34.243Z SERIAL « 0x0110000400170a3202215201fe000000004a                              (18 bytes)
2022-05-12T07:36:34.246Z CNTRLR   [Node 023] [~] [Meter] value[66049]: 0 => 5.1                     [Endpoint 0]
2022-05-12T07:36:34.253Z SERIAL » [ACK]                                                                   (0x06)
2022-05-12T07:36:34.258Z DRIVER « [Node 023] [REQ] [ApplicationCommand]
                                  └─[MeterCCReport]
                                      type:       Electric
                                      scale:      W
                                      rate type:  Consumed
                                      value:      5.1
                                      time delta: 0 seconds
2022-05-12T07:36:37.563Z SERIAL » 0x0109001317022602250afb                                            (11 bytes)
2022-05-12T07:36:37.564Z DRIVER » [Node 023] [REQ] [SendData]
                                  │ transmit options: 0x25
                                  │ callback id:      10
                                  └─[MultilevelSwitchCCGet]
2022-05-12T07:36:37.567Z SERIAL « [ACK]                                                                   (0x06)
2022-05-12T07:36:37.572Z SERIAL « 0x0104011301e8                                                       (6 bytes)
2022-05-12T07:36:37.575Z SERIAL » [ACK]                                                                   (0x06)
2022-05-12T07:36:37.576Z DRIVER « [RES] [SendData]
                                    was sent: true
2022-05-12T07:36:37.588Z SERIAL « 0x010700130a000002e3                                                 (9 bytes)
2022-05-12T07:36:37.589Z SERIAL » [ACK]                                                                   (0x06)
2022-05-12T07:36:37.590Z DRIVER « [REQ] [SendData]
                                    callback id:     10
                                    transmit status: OK
2022-05-12T07:36:37.602Z SERIAL « 0x010b00040017052603080800c7                                        (13 bytes)
2022-05-12T07:36:37.605Z CNTRLR   [Node 023] [~] [Multilevel Switch] targetValue: 255 => 8          [Endpoint 0]
2022-05-12T07:36:37.608Z CNTRLR   [Node 023] [~] [Multilevel Switch] duration: {"value":0,"unit":"s [Endpoint 0]
                                  econds"} => {"value":0,"unit":"seconds"}
2022-05-12T07:36:37.612Z CNTRLR   [Node 023] [~] [Multilevel Switch] currentValue: 0 => 8           [Endpoint 0]
2022-05-12T07:36:37.614Z SERIAL » [ACK]                                                                   (0x06)
2022-05-12T07:36:37.620Z DRIVER « [Node 023] [REQ] [ApplicationCommand]
                                  └─[MultilevelSwitchCCReport]
                                      current value: 8
                                      target value:  8
                                      duration:      0s

With brightness set

2022-05-12T07:47:03.052Z SERIAL » 0x010f001317086c019d04260132ff2509ce                                (17 bytes)
2022-05-12T07:47:03.054Z DRIVER » [Node 023] [REQ] [SendData]
                                  │ transmit options: 0x25
                                  │ callback id:      9
                                  └─[SupervisionCCGet]
                                    │ session id:      29
                                    │ request updates: true
                                    └─[MultilevelSwitchCCSet]
                                        target value: 50
                                        duration:     default
2022-05-12T07:47:03.056Z SERIAL « [ACK]                                                                   (0x06)
2022-05-12T07:47:03.061Z SERIAL « 0x0104011301e8                                                       (6 bytes)
2022-05-12T07:47:03.064Z SERIAL » [ACK]                                                                   (0x06)
2022-05-12T07:47:03.066Z DRIVER « [RES] [SendData]
                                    was sent: true
2022-05-12T07:47:03.078Z SERIAL « 0x0107001309000002e0                                                 (9 bytes)
2022-05-12T07:47:03.079Z SERIAL » [ACK]                                                                   (0x06)
2022-05-12T07:47:03.080Z DRIVER « [REQ] [SendData]
                                    callback id:     9
                                    transmit status: OK
2022-05-12T07:47:03.093Z SERIAL « 0x010b00040017056c021dff006e                                        (13 bytes)
2022-05-12T07:47:03.095Z SERIAL » [ACK]                                                                   (0x06)
2022-05-12T07:47:03.097Z DRIVER « [Node 023] [REQ] [ApplicationCommand]
                                  └─[SupervisionCCReport]
                                      session id:          29
                                      more updates follow: false
                                      status:              Success
                                      duration:            0s
2022-05-12T07:47:03.102Z CNTRLR   [Node 023] [~] [Multilevel Switch] currentValue: 0 => 50          [Endpoint 0]
2022-05-12T07:47:04.986Z SERIAL « 0x0110000400170a32022152050a00000000ba                              (18 bytes)
2022-05-12T07:47:04.988Z CNTRLR   [Node 023] [~] [Meter] value[66049]: 0 => 12.9                    [Endpoint 0]
2022-05-12T07:47:04.996Z SERIAL » [ACK]                                                                   (0x06)
2022-05-12T07:47:05.000Z DRIVER « [Node 023] [REQ] [ApplicationCommand]
                                  └─[MeterCCReport]
                                      type:       Electric
                                      scale:      W
                                      rate type:  Consumed
                                      value:      12.9
                                      time delta: 0 seconds

Has this been acknowledged as a problem?

I just migrated my z-wave dimmers from the Vera integration to Zwave JS with an Aeotec Z-stick 7, and now all my dimmers take 5 seconds to update on my dashboard when I turn on the light or fan from Home Assistant.

Yep.

I believe the way it works is zwavejs will poll the device after 4 seconds after performing a setpoint if the device hasn’t sent the value yet. Well behaved devices should be sending it. But I have several that don’t…… It would be helpful if the 4 seconds was configurable……

What you can do as a workaround is poll it from an automation. I do this for many devices. For the variable speed fan controller I was able to trigger off of the switch state changing to the poll the level.

Later on I discovered that an automation can trigger from the service call event. I haven’t tried that since the current cludge has been reliable.

The automation delays for 500ms, then poll, then delay for another 1second and poll again just for good measure.

- id: "loft_fan_1 refresh switch state"
  alias: loft_fan_1 refresh switch state
  description: "Automation to refresh switch after state changes usually caused by switch control"
  mode: queued
  trigger:
    - platform: state
      entity_id: fan.loft_fan_1_level
  condition: "{{ trigger.to_state.state != trigger.from_state.state }}"
  action:
    - service: system_log.write
      data:
        level: info
        message: "Polling fan.loft_fan_1_level state change from {{ trigger.from_state.state }} to {{ trigger.to_state.state }}"
        logger: hvac
    - service: zwave_js.refresh_value
      data:
        entity_id: fan.loft_fan_1_level
    - delay: "00:00:01"
    - service: zwave_js.refresh_value
      data:
        entity_id: fan.loft_fan_1_level

I wonder if your automation solves a different problem that what I’m facing.

I applied it exactly, with the exception of the entity (I changed fan.loft_fan_1_level to light.living_room_light). It still takes about 6 seconds for the status to update on my dashboard when I turn the light on, but now it also takes 6 seconds when I turn the light off. Without the automation it’s almost instantaneous when turning the light off.

This is with HomeSeer HS-WD200+ dimmers and HS-FC200+ fan controllers.

Here’s what I get in the Debug window of Zwave JS UI (formerly known as zwavejs2mqtt).

Turning light on to a specific level (updates immediately):

2022-09-28 17:41:29.827 INFO Z-WAVE: Node 2: value updated: 38-0-currentValue 0 => 43
2022-09-28 17:41:29.827 INFO Z-WAVE: Node 2: value updated: 38-0-targetValue 0 => 43
2022-09-28 17:41:34.864 INFO Z-WAVE: Node 2: value updated: 38-0-targetValue 43 => 43
2022-09-28 17:41:34.865 INFO Z-WAVE: Node 2: value updated: 38-0-duration 0s => 0s
2022-09-28 17:41:34.865 INFO Z-WAVE: Node 2: value updated: 38-0-currentValue 43 => 43

Turning light off (updates immediately):

2022-09-28 17:41:47.640 INFO Z-WAVE: Node 2: value updated: 38-0-currentValue 43 => 0
2022-09-28 17:41:47.644 INFO Z-WAVE: Node 2: value updated: 38-0-targetValue 43 => 0
2022-09-28 17:41:52.680 INFO Z-WAVE: Node 2: value updated: 38-0-targetValue 0 => 0
2022-09-28 17:41:52.681 INFO Z-WAVE: Node 2: value updated: 38-0-duration 0s => 0s
2022-09-28 17:41:52.681 INFO Z-WAVE: Node 2: value updated: 38-0-currentValue 0 => 0

Turning light on (updates after 5 seconds):

2022-09-28 17:41:59.475 INFO Z-WAVE: Node 2: value updated: 38-0-targetValue 0 => 255
2022-09-28 17:42:04.514 INFO Z-WAVE: Node 2: value updated: 38-0-targetValue 255 => 43
2022-09-28 17:42:04.515 INFO Z-WAVE: Node 2: value updated: 38-0-duration 0s => 0s
2022-09-28 17:42:04.515 INFO Z-WAVE: Node 2: value updated: 38-0-currentValue 0 => 43

In the first two cases, it looks like we’re setting the currentValue before setting the targetValue. In the third case, we don’t set the currentValue (presumably because we don’t know what the value should be) and the dashboard doesn’t get updated.

When I ran the automation suggested above, it didn’t trigger until after the currentValue was updated (after the 5 second delay in the third case).

This “issue” has been reported dozens of times in this forum and on also on GitHub for many years, over multiple drivers. Some attempts to address this in HA haven’t been accepted, and they have not been good solutions. I’d suggest either live with the UI issue, or set a specific brightness level when you turn it on to avoid it. Polling the device to avoid a temporary UI issue seems like overkill to me. If you really wanted to do that, you could try using the value updated trigger to react to the targetValue property change (to 255), instead of the entity state.

When you turn on the switch w/o a set level, the driver does not know what the expected level will be, so it doesn’t update until 5 seconds later (+ N duration). This delay is not configurable unless you run the driver yourself, and it applies globally, not per-device. The UI reverts to the previous state if it doesn’t get an update before 2 seconds. When you turn on a device with a specific level, the driver sends an immediate optimistic response, which updates the state in HA.

This automation for a fan controller works for me. After turning on the fan via HA (255 level), it waits 500 ms then refreshes the device. I used device triggers because it was too easy that way. You can convert to non-device triggers if that suits you. The delay should be personalized to account for the device ramp rate and network performance. If the refresh occurs after 2 seconds, it won’t be effective and the UI will revert. If it occurs too quickly, Z-Wave JS will cancel the 5 second refresh and you may get the wrong value back if it’s still transitioning (this was the problem with OZW).

alias: Fan Switch On Refresh
description: Quick refresh of fan switch when toggled on (last known level)
trigger:
  - platform: device
    device_id: b95ebbd62ac901ed77c3d5c7305f9f76
    domain: zwave_js
    type: zwave_js.value_updated.value
    command_class: 38
    property: targetValue
    to: "255"
condition: []
action:
  - delay:
      hours: 0
      minutes: 0
      seconds: 0
      milliseconds: 500
  - device_id: b95ebbd62ac901ed77c3d5c7305f9f76
    domain: zwave_js
    entity_id: fan.in_wall_fan_speed_control_300s
    type: refresh_value
mode: single

On more option would be to use an event trigger with the call_service event type, which is triggered whenever the UI is used to turn on/off the light. You would want to condition on the service turn_one, and probably check for no service call data (or more explicitly, no brightness value), otherwise you would poll unnecessarily. A downside is it wouldn’t trigger if you were using zwave-js-ui to turn it on (which the above handles, it even works with multiple HA instances), which probably isn’t a big deal. An upside is that this event would be triggered before the driver returns the targetValue updated event, so there’s no reliance on that message being received.

event_type: call_service
data:
  domain: fan
  service: turn_on
  service_data:
    entity_id: fan.in_wall_fan_speed_control_300s
origin: LOCAL
time_fired: "2022-09-29T15:39:46.525939+00:00"
context:
  id: 01GE4YERYX798S29J7NBDGNS4A
  parent_id: null
  user_id: 2adbde13cbdb4585884819c0565afbdd

@freshcoast, this is some great info.

I had the same idea as your first suggestion and came up with the following before I saw your post.

alias: Dimmer Fix
description: ""
trigger:
  - platform: zwave_js.value_updated
    command_class: 38
    property: targetValue
    entity_id: light.bedroom_light
condition:
  - condition: template
    value_template: "{{ trigger.previous_value == 0 and trigger.current_value == 255 }}"
action:
  - service: zwave_js.refresh_value
    data:
      entity_id: light.bedroom_light
      refresh_all_values: false
  - delay: "00:00:03"
  - service: zwave_js.refresh_value
    data:
      entity_id: light.bedroom_light
      refresh_all_values: false
mode: single

I could make it trigger on any one of my dimmers, but I couldn’t find a way to only poll the entity that changed, so I would have to use a separate automation for each dimmer (I have 5 of these so far).

I’ll play around with the call_service event trigger as well. That sounds promising, and I like to learn new things. Thanks for the advice.

I think you should be able to use a template in the refresh action with trigger.device_id trigger data.

That’s what I thought, but trigger.device_id was always empty. I tested with trigger.node_id and trigger.device_id and those had values, but trigger.device_id didn’t. I suppose I could poll all 5 devices, but that’s definitely overkill.

Triggering on the call_service event is just what I needed. Now I can reference the entity_id and everything works with one automation.

One drawback is that I couldn’t trigger on multiple values of entity_id so I had to move that to a condition.

Here’s what I have, and it appears to work flawlessly (so far).

alias: Dimmer Fix
description: ""
trigger:
  - platform: event
    event_type: call_service
    event_data:
      domain: light
      service: turn_on
  - platform: event
    event_type: call_service
    event_data:
      domain: fan
      service: turn_on
condition:
  - condition: template
    value_template: "{{ not trigger.event.data.service_data.brightness_pct }}"
  - condition: template
    value_template: >-
      {{ trigger.event.data.service_data.entity_id in ["light.bedroom_light",
      "light.living_room_lights", "light.media_room_lights",
      "fan.living_room_fan", "fan.bedroom_fan"] }}
action:
  - delay:
      milliseconds: 500
  - service: zwave_js.refresh_value
    data:
      entity_id: "{{ trigger.event.data.service_data.entity_id }}"
      refresh_all_values: false
  - delay: "00:00:02"
  - service: zwave_js.refresh_value
    data:
      entity_id: "{{ trigger.event.data.service_data.entity_id }}"
      refresh_all_values: false
mode: parallel
max: 3

Thanks for all your help!

2 Likes

Excellent, I had expected that to work better - thanks for moving it forward. I’ll retrofit my fan poller with this.