Automation turns light on, but state doesn't get updated in hass

rct · November 24, 2019, 11:44pm

I’ve got a sunset automation that works to turn a light on, but the state of the light doesn’t get updated. After the light is on, both the GUI and the state of the light.* device in developer tools shows state == off.

The light is a HomeSeer HS-WD200+ Zwave dimmer.

There is nothing in home-assistant.log around the time when the automation is triggered
Logbook shows an entry for the automation.
Any manual updates to this or other zwave switches show up immediately.

Here’s the activity from OZW_log:

2019-11-24 16:57:19.038 Info, Node005, Value::Set - COMMAND_CLASS_SWITCH_MULTILEVEL - Level - 0 - 1 - 255
2019-11-24 16:57:19.038 Info, Node005, SwitchMultilevel::Set - Setting to level 255
2019-11-24 16:57:19.038 Detail, Node005, Queuing (Send) SwitchMultilevelCmd_Set (Node=5): 0x01, 0x0a, 0x00, 0x13, 0x05, 0x03, 0x26, 0x01, 0xff,
 0x25, 0xb5, 0xa8
2019-11-24 16:57:19.038 Detail, Node005, Queuing (Send) SwitchMultilevelCmd_Get (Node=5): 0x01, 0x09, 0x00, 0x13, 0x05, 0x02, 0x26, 0x02, 0x25,
 0xb6, 0x55
2019-11-24 16:57:19.039 Detail,
2019-11-24 16:57:19.039 Info, Node005, Sending (Send) message (Callback ID=0xb5, Expected Reply=0x13) - SwitchMultilevelCmd_Set (Node=5): 0x01,
 0x0a, 0x00, 0x13, 0x05, 0x03, 0x26, 0x01, 0xff, 0x25, 0xb5, 0xa8
2019-11-24 16:57:19.048 Detail, Node005,   Received: 0x01, 0x04, 0x01, 0x13, 0x01, 0xe8
2019-11-24 16:57:19.048 Detail, Node005,   ZW_SEND_DATA delivered to Z-Wave stack
2019-11-24 16:57:19.068 Detail, Node005,   Received: 0x01, 0x07, 0x00, 0x13, 0xb5, 0x00, 0x00, 0x02, 0x5c
2019-11-24 16:57:19.068 Detail, Node005,   ZW_SEND_DATA Request with callback ID 0xb5 received (expected 0xb5)
2019-11-24 16:57:19.068 Info, Node005, Request RTT 29 Average Request RTT 28
2019-11-24 16:57:19.069 Detail,   Expected callbackId was received
2019-11-24 16:57:19.069 Detail,   Expected reply was received
2019-11-24 16:57:19.069 Detail,   Message transaction complete
2019-11-24 16:57:19.069 Detail,
2019-11-24 16:57:19.069 Detail, Node005, Removing current message
2019-11-24 16:57:19.069 Detail,
2019-11-24 16:57:19.069 Info, Node005, Sending (Send) message (Callback ID=0xb6, Expected Reply=0x04) - SwitchMultilevelCmd_Get (Node=5): 0x01,
 0x09, 0x00, 0x13, 0x05, 0x02, 0x26, 0x02, 0x25, 0xb6, 0x55
2019-11-24 16:57:19.078 Detail, Node005,   Received: 0x01, 0x04, 0x01, 0x13, 0x01, 0xe8
2019-11-24 16:57:19.078 Detail, Node005,   ZW_SEND_DATA delivered to Z-Wave stack
2019-11-24 16:57:19.098 Detail, Node005,   Received: 0x01, 0x07, 0x00, 0x13, 0xb6, 0x00, 0x00, 0x02, 0x5f
2019-11-24 16:57:19.103 Detail, Node005,   ZW_SEND_DATA Request with callback ID 0xb6 received (expected 0xb6)
2019-11-24 16:57:19.103 Info, Node005, Request RTT 33 Average Request RTT 30
2019-11-24 16:57:19.103 Detail,   Expected callbackId was received
2019-11-24 16:57:19.117 Detail, Node005,   Received: 0x01, 0x0b, 0x00, 0x04, 0x00, 0x05, 0x05, 0x26, 0x03, 0x00, 0x00, 0x00, 0xd5
2019-11-24 16:57:19.118 Detail,
2019-11-24 16:57:19.118 Info, Node005, Response RTT 48 Average Response RTT 47
2019-11-24 16:57:19.118 Info, Node005, Received SwitchMultiLevel report: level=0
2019-11-24 16:57:19.118 Detail, Node005, Refreshed Value: old value=0, new value=0, type=byte
2019-11-24 16:57:19.118 Detail, Node005, Changes to this value are not verified
2019-11-24 16:57:19.118 Detail, Node005,   Expected reply and command class was received
2019-11-24 16:57:19.118 Detail, Node005,   Message transaction complete
2019-11-24 16:57:19.118 Detail,
2019-11-24 16:57:19.118 Detail, Node005, Removing current message
2019-11-24 16:57:19.118 Detail, Node005, Notification: ValueChanged

Making some big guesses since I don’t know much about Z-wave/OZW – A SwitchMultilevelCmd_Set and SwitchMultilevelCmd_Get look like the relevant z-wave commands. They are queued back-to-back as soon as the automation fires.

The SwitchMultilevelCmd_Get got back Received SwitchMultiLevel report: level=0 which makes it look like the dimmer is off because it hasn’t had enough time to transition to on.

If I go into Configuration->Zwave->refresh the node, home assistant’s state gets updated. Possibly because as part of the refresh it got back Received SwitchMultiLevel report: level=35

Another curiousity, while the hass state and GUI did get updates, this doesn’t trigger an entry in logbook so there is no record of the light now being on.

System Details:

version 0.101.3 on rpi 3, 32 bit, installed via Hassbian buster
Aeotec Gen 5 Z-stick

Automation that turns the light on:

- id: '1571141653154'
  alias: Sunset Outside Lights turn on
  description: Automation test
  trigger:
  - below: '-6.0'
    entity_id: sun.sun
    platform: numeric_state
    value_template: '{{ state.attributes.elevation }}'
  condition: []
  action:
  - data:
      entity_id: light.outside_main_entrance_light
    service: light.turn_on

jwelter · November 25, 2019, 1:17am

I had the same issue with a bunch of HS WD100+ series dimmers. They were fine and then had the issue with updating like you mention.

I never could get it stable and tore them out and moved to Lutron and been very happy.

rct · November 25, 2019, 2:14pm

@jwelter. Thanks for the reply. I’d rather not giving up on 15-20 homeseer dimmers I have installed if I can avoid it. So what dimmers did you wind up using.

If my guess is right, it seems like there is a race going on due to the dimmer’s fade up transition. The transition seems to make the results timing dependent. An on/off switch, or a dimmer that doesn’t do fade-on/off transitions would probably not have this problem.

Alternatively, if more switches were involved in the automation, or it took longer to get the Get command out to the switch after the Set, by the time the multi-level Get command was received by the switch, the level might not be zero.

When the automation turns off, in logbook I see a similar “race”, The timer based automation is logged as triggered, the light is then logged turned on instead of off, but then there is a 3rd log entry showing the light turned off. However, in this case, a 3rd command was sent to the dimmer after the Set/Get transaction. See the Info, mgr, Refreshing node 5: which occurred a little less than a second after the get transaction finished.

2019-11-23 22:20:00.015 Info, Node005, Value::Set - COMMAND_CLASS_SWITCH_MULTILEVEL - Level - 0 - 1 - 0
2019-11-23 22:20:00.016 Info, Node005, SwitchMultilevel::Set - Setting to level 0
2019-11-23 22:20:00.016 Detail, Node005, Queuing (Send) SwitchMultilevelCmd_Set (Node=5): 0x01, 0x0a, 0x00, 0x13, 0x05, 0x03, 0x26, 0x01, 0x00, 0x25, 0xbe, 0x5c
2019-11-23 22:20:00.016 Detail, Node005, Queuing (Send) SwitchMultilevelCmd_Get (Node=5): 0x01, 0x09, 0x00, 0x13, 0x05, 0x02, 0x26, 0x02, 0x25, 0xbf, 0x5c
2019-11-23 22:20:00.016 Detail,
2019-11-23 22:20:00.016 Info, Node005, Sending (Send) message (Callback ID=0xbe, Expected Reply=0x13) - SwitchMultilevelCmd_Set (Node=5): 0x01, 0x0a, 0x00, 0x13, 0x05, 0x03, 0x26, 0x01, 0x00, 0x25, 0xbe, 0x5c
2019-11-23 22:20:00.025 Detail, Node005,   Received: 0x01, 0x04, 0x01, 0x13, 0x01, 0xe8
2019-11-23 22:20:00.026 Detail, Node005,   ZW_SEND_DATA delivered to Z-Wave stack
2019-11-23 22:20:00.046 Detail, Node005,   Received: 0x01, 0x07, 0x00, 0x13, 0xbe, 0x00, 0x00, 0x02, 0x57
2019-11-23 22:20:00.046 Detail, Node005,   ZW_SEND_DATA Request with callback ID 0xbe received (expected 0xbe)
2019-11-23 22:20:00.046 Info, Node005, Request RTT 29 Average Request RTT 29
2019-11-23 22:20:00.046 Detail,   Expected callbackId was received
2019-11-23 22:20:00.046 Detail,   Expected reply was received
2019-11-23 22:20:00.046 Detail,   Message transaction complete
2019-11-23 22:20:00.046 Detail,
2019-11-23 22:20:00.046 Detail, Node005, Removing current message
2019-11-23 22:20:00.047 Detail,
2019-11-23 22:20:00.047 Info, Node005, Sending (Send) message (Callback ID=0xbf, Expected Reply=0x04) - SwitchMultilevelCmd_Get (Node=5): 0x01, 0x09, 0x00, 0x13, 0x05, 0x02, 0x26, 0x02, 0x25, 0xbf, 0x5c
2019-11-23 22:20:00.055 Detail, Node005,   Received: 0x01, 0x04, 0x01, 0x13, 0x01, 0xe8
2019-11-23 22:20:00.055 Detail, Node005,   ZW_SEND_DATA delivered to Z-Wave stack
2019-11-23 22:20:00.075 Detail, Node005,   Received: 0x01, 0x07, 0x00, 0x13, 0xbf, 0x00, 0x00, 0x02, 0x56
2019-11-23 22:20:00.075 Detail, Node005,   ZW_SEND_DATA Request with callback ID 0xbf received (expected 0xbf)
2019-11-23 22:20:00.075 Info, Node005, Request RTT 28 Average Request RTT 28
2019-11-23 22:20:00.075 Detail,   Expected callbackId was received
2019-11-23 22:20:00.094 Detail, Node005,   Received: 0x01, 0x0b, 0x00, 0x04, 0x00, 0x05, 0x05, 0x26, 0x03, 0x23, 0x00, 0x00, 0xf6
2019-11-23 22:20:00.095 Detail,
2019-11-23 22:20:00.095 Info, Node005, Response RTT 47 Average Response RTT 47
2019-11-23 22:20:00.095 Info, Node005, Received SwitchMultiLevel report: level=35
2019-11-23 22:20:00.095 Detail, Node005, Refreshed Value: old value=0, new value=35, type=byte
2019-11-23 22:20:00.095 Detail, Node005, Changes to this value are not verified
2019-11-23 22:20:00.095 Detail, Node005,   Expected reply and command class was received
2019-11-23 22:20:00.095 Detail, Node005,   Message transaction complete
2019-11-23 22:20:00.095 Detail,
2019-11-23 22:20:00.095 Detail, Node005, Removing current message
2019-11-23 22:20:00.095 Detail, Node005, Notification: ValueChanged
2019-11-23 22:20:01.027 Info, mgr,     Refreshing node 5: COMMAND_CLASS_SWITCH_MULTILEVEL index = 0 instance = 1 (to confirm a reported change)
2019-11-23 22:20:01.027 Detail, Node005, Queuing (Send) SwitchMultilevelCmd_Get (Node=5): 0x01, 0x09, 0x00, 0x13, 0x05, 0x02, 0x26, 0x02, 0x25, 0xc0, 0x23
2019-11-23 22:20:01.028 Detail,
2019-11-23 22:20:01.028 Info, Node005, Sending (Send) message (Callback ID=0xc0, Expected Reply=0x04) - SwitchMultilevelCmd_Get (Node=5): 0x01, 0x09, 0x00, 0x13, 0x05, 0x02, 0x26, 0x02, 0x25, 0xc0, 0x23
2019-11-23 22:20:01.036 Detail, Node005,   Received: 0x01, 0x04, 0x01, 0x13, 0x01, 0xe8
2019-11-23 22:20:01.036 Detail, Node005,   ZW_SEND_DATA delivered to Z-Wave stack
2019-11-23 22:20:01.056 Detail, Node005,   Received: 0x01, 0x07, 0x00, 0x13, 0xc0, 0x00, 0x00, 0x03, 0x28
2019-11-23 22:20:01.056 Detail, Node005,   ZW_SEND_DATA Request with callback ID 0xc0 received (expected 0xc0)
2019-11-23 22:20:01.056 Info, Node005, Request RTT 28 Average Request RTT 28
2019-11-23 22:20:01.057 Detail,   Expected callbackId was received
2019-11-23 22:20:01.075 Detail, Node005,   Received: 0x01, 0x0b, 0x00, 0x04, 0x00, 0x05, 0x05, 0x26, 0x03, 0x03, 0x00, 0x00, 0xd6
2019-11-23 22:20:01.075 Detail,
2019-11-23 22:20:01.075 Info, Node005, Response RTT 47 Average Response RTT 47
2019-11-23 22:20:01.076 Info, Node005, Received SwitchMultiLevel report: level=3
2019-11-23 22:20:01.076 Detail, Node005, Refreshed Value: old value=35, new value=3, type=byte
2019-11-23 22:20:01.076 Detail, Node005, Changes to this value are not verified
2019-11-23 22:20:01.076 Detail, Node005,   Expected reply and command class was received
2019-11-23 22:20:01.076 Detail, Node005,   Message transaction complete
2019-11-23 22:20:01.076 Detail,
2019-11-23 22:20:01.076 Detail, Node005, Removing current message
2019-11-23 22:20:01.076 Detail, Node005, Notification: ValueChanged
2019-11-23 22:20:02.030 Info, mgr,     Refreshing node 5: COMMAND_CLASS_SWITCH_MULTILEVEL index = 0 instance = 1 (to confirm a reported change)
2019-11-23 22:20:02.030 Detail, Node005, Queuing (Send) SwitchMultilevelCmd_Get (Node=5): 0x01, 0x09, 0x00, 0x13, 0x05, 0x02, 0x26, 0x02, 0x25, 0xc1, 0x22
2019-11-23 22:20:02.030 Detail,
2019-11-23 22:20:02.030 Info, Node005, Sending (Send) message (Callback ID=0xc1, Expected Reply=0x04) - SwitchMultilevelCmd_Get (Node=5): 0x01, 0x09, 0x00, 0x13, 0x05, 0x02, 0x26, 0x02, 0x25, 0xc1, 0x22
2019-11-23 22:20:02.039 Detail, Node005,   Received: 0x01, 0x04, 0x01, 0x13, 0x01, 0xe8
2019-11-23 22:20:02.039 Detail, Node005,   ZW_SEND_DATA delivered to Z-Wave stack
2019-11-23 22:20:02.059 Detail, Node005,   Received: 0x01, 0x07, 0x00, 0x13, 0xc1, 0x00, 0x00, 0x03, 0x29
2019-11-23 22:20:02.059 Detail, Node005,   ZW_SEND_DATA Request with callback ID 0xc1 received (expected 0xc1)
2019-11-23 22:20:02.059 Info, Node005, Request RTT 28 Average Request RTT 28
2019-11-23 22:20:02.059 Detail,   Expected callbackId was received
2019-11-23 22:20:02.077 Detail, Node005,   Received: 0x01, 0x0b, 0x00, 0x04, 0x00, 0x05, 0x05, 0x26, 0x03, 0x00, 0x00, 0x00, 0xd5
2019-11-23 22:20:02.077 Detail,
2019-11-23 22:20:02.077 Info, Node005, Response RTT 46 Average Response RTT 46
2019-11-23 22:20:02.077 Info, Node005, Received SwitchMultiLevel report: level=0
2019-11-23 22:20:02.077 Detail, Node005, Refreshed Value: old value=3, new value=0, type=byte
2019-11-23 22:20:02.077 Detail, Node005, Changes to this value are not verified
2019-11-23 22:20:02.077 Detail, Node005,   Expected reply and command class was received
2019-11-23 22:20:02.078 Detail, Node005,   Message transaction complete
2019-11-23 22:20:02.078 Detail,
2019-11-23 22:20:02.078 Detail, Node005, Removing current message
2019-11-23 22:20:02.078 Detail, Node005, Notification: ValueChanged

If I’m understanding some of what it says in OZW_log, for some reason the off sequence that was triggered by the automation is verified by sending a 2nd Get request

2019-11-23 22:20:02.030 Info, mgr,     Refreshing node 5: COMMAND_CLASS_SWITCH_MULTILEVEL index = 0 instance = 1 (to confirm a reported change)

However this seems to indicate that no verification happens for the turn on automation:

2019-11-24 16:57:19.118 Detail, Node005, Changes to this value are not verified

rct · November 25, 2019, 4:44pm

So I’m wondering why the automation for the turn off triggers a verification (extra zwave transaction to check the level) but the automation to turn the light on does not trigger a verification?

I don’t see anything different in the two automations, see below.

- id: '1571141653154'
  alias: Sunset Outside Lights turn on
  description: Automation test
  trigger:
  - below: '-6.0'
    entity_id: sun.sun
    platform: numeric_state
    value_template: '{{ state.attributes.elevation }}'
  condition: []
  action:
  - data:
      entity_id: light.outside_main_entrance_light
    service: light.turn_on


- id: '1572210118089'
  alias: Outside light turn off
  description: 'Turn outside lights off around bedtime '
  trigger:
  - at: '22:20:00'
    platform: time
  condition: []
  action:
  - data:
      entity_id: light.outside_main_entrance_light
    service: light.turn_off

jwelter · November 26, 2019, 12:37am

In your zwave settings for these devices do you have the “refresh:” option set?

rct · November 26, 2019, 1:04am

No. Is this something I should be doing? I actually have no non-default settings for these devices. The GUI has worked well enough that the only thing I’ve had to do configuration wise is customize the entity names.

Are you referring to the refresh_value option that is part of device_config described in
Z-wave Installation

refresh_value

(boolean)(Optional)

Enable refreshing of the node value. Only the light integration uses this.

Default value:
false

That looks like it could be relevant. At first I thought you were referring to polling, but this looks different and light specific.

Looking at the docs, I’m not sure how to enable this.