GE Z-Wave dimmer state flipping in UI

kal_el · May 31, 2019, 4:12pm

I just installed Home Assistant using the current Getting Started guide. I am trying to make the switch from SmartThings. Install was easy and quick. I brought over a couple of my zwave devices to test out before I switch everything. Now for the issue:

In the lovelace web UI, when I interact with my GE Z-Wave dimmer (14294) the state keeps toggling in the UI (gif below)

2019-05-31_10-17-57

I’ve search for solutions and found others with this issue, but nothing with anything that actually solves the issue.

Related threads:

My question:
Is this just standard behavior for these zwave dimmers? Does everyone just deal with this? Or is there something in my configuration I can change to solve this?

I have tried changing the polling_interval and delay, as well as the dim step/rate in the Z-Wave Configuration for the dimmer.

If the answer is “yes, that’s just the way it is”, then that is pretty unfortunate and I will need to continue using SmartThings (which I really don’t want to). Other than this issue, I am really enjoying Home Assistant.

Additional information regarding my configuration:

Home Assistant Version: 0.93.2
Dimmer: GE 14294 Z-Wave Dimmer

configuration.yaml

zwave:
  usb_path: /dev/ttyACM0
  network_key: !secret zwave_network_key
  device_config: !include zwave_device_config.yaml
  polling_interval: 60000

zwave_device_config.yaml

light.office_dimmer:
  ignored: false
  polling_intensity: 1
  refresh_value: true
  delay: 3
light.kitchen_counter_dimmer:
  ignored: false
  polling_intensity: 1
  refresh_value: true
  delay: 3

obrienlabs · May 31, 2019, 5:51pm

Does everyone just deal with this?

Yep. At least I have been since I left ST about a year or two ago. As I understand it has something to do with the polling interval on the light switch itself (not hass) and it’s only cosmetic.

The flipping is because it’s a dimmer switch, so when it polls while it’s dimming, the light is technically still on, so the switch reverts back to the On state. Then it polls again and the light is off so the toggle flips to off.

lights

obrienlabs · May 31, 2019, 6:10pm

Forgot to address this part. I had the same feeling that the UI wasn’t baked enough. But once you start playing with scripts and automations, you’ll soon forget the hassle that was ST. Don’t let something like the toggler flipping deter you. It’s minor compared to the rest of the power within Home Assistant.

kal_el · May 31, 2019, 6:24pm

Thanks obrienlab and I do appreciate the advice. I do think I can overlook this assuming it is only cosmetic like you say. I have on a couple of occasions had the status get out of sync and it actually not ever flip back to the actual state of the light.

Another thing I notice is that yours only seems to toggle when going from on -> off. Odd, because mine does it in both directions.

I will keep testing and if everything else is stable, I will definitely just overlook this flip flopping and move everything else over to HA. The reason I am so hesitant is because in my 3 years of running SmartThings, I honestly haven’t had a single issue or device show an incorrect status. I am just looking to switch from it to get more control over the devices and begin the “automation” stage. Before now, I was mostly just using SmartThings to “control” devices and there is no doubt HA is better for automating.

freshcoast · May 31, 2019, 6:54pm

I also have the GE switches. My UI will toggle on<->off in both cases, but with refresh_value on the state always gets synchronized. I left my delay at the default of 5 seconds, for me going less was not always reliable. If you say you are getting out of sync sometimes, you might want to stay with the default and just live with the longer delay in the UI. If you have both refresh value and polling enabled, they should never be out of sync. Remember, a polling intensity of 1 and an interval of 60,000 means the value will be checked every 1 minute, so you might have to wait that long for an update.

Even with the refresh enabled, there are situations where the UI can still get out of sync. This is not solvable unless you enable polling (or HA code is updated to handle it). If you use a transition value that is longer than the refresh delay (say a 30 minute dim transition), the brightness will never update until the next state change. I’m not using any long transitions, just on/off, so I keep polling disabled. It has a negative effect on the Z-Wave network so you want to avoid it if at all possible. If it’s necessary though, I would increase the polling intensity as high as tolerable.

For the transition problem, HA could probably work around this by refreshing the value every so often during the transition phase. Newer versions of Z-Wave dimmers could work a little better. They support the ability for the switch to report the target dim level, but this is only available for the new version of OpenZWave, and support would need to be added to HA to use it. In theory, HA could just update the UI to show the target dim level (but with transitions it would still not be 100% accurate).

I would agree that this is (in most cases) this is just a cosmetic issue. Once you start utilizing automations the UI becomes less important. If your automations for some reason rely on knowing the dim level, then maybe you might have issues. All my automations are just turning on and off the lights.

firstof9 · May 31, 2019, 8:28pm

Try setting your On/Off Command Dim Step to 99 and the On/Off Command Dim Rate to 1 or 2 in the Zwave config options for the switch.

kal_el · May 31, 2019, 9:13pm

Those are actually my current settings. See screenshots below. Is there any way to view/modify these inside a file or is using the Z-Wave Configuration the only way to modify those values?

Also, I have been toggling back and forth a few times over the last couple hours. It is currenly in a state where the UI is showing the light as OFF, yet the light is actually ON. I left it for about an hour to see if it would eventually heal/poll itself and pull the correct state, but it is not happening.

Below is the output of the ozw log. The dimmer in the wrong state at the moment is node 6. When this has happened in the past, it will get back in sync if I toggle it a couple more times in the UI or if I physically touch the dimmer.

tail of OZW_Log.txt

2019-05-31 16:57:38.077 Detail, Node006, Polling: COMMAND_CLASS_SWITCH_MULTILEVEL index = 0 instance = 1 (poll queue has 0 messages)
2019-05-31 16:57:38.077 Detail, Node006, Queuing (Poll) SwitchMultilevelCmd_Get (Node=6): 0x01, 0x09, 0x00, 0x13, 0x06, 0x02, 0x26, 0x02, 0x25, 0x8e, 0x6e
2019-05-31 16:57:38.077 Detail, 
2019-05-31 16:57:38.078 Info, Node006, Sending (Poll) message (Callback ID=0x8e, Expected Reply=0x04) - SwitchMultilevelCmd_Get (Node=6): 0x01, 0x09, 0x00, 0x13, 0x06, 0x02, 0x26, 0x02, 0x25, 0x8e, 0x6e
2019-05-31 16:57:38.089 Detail, Node006,   Received: 0x01, 0x04, 0x01, 0x13, 0x01, 0xe8
2019-05-31 16:57:38.089 Detail, Node006,   ZW_SEND_DATA delivered to Z-Wave stack
2019-05-31 16:57:38.105 Detail, Node006,   Received: 0x01, 0x07, 0x00, 0x13, 0x8e, 0x00, 0x00, 0x02, 0x67
2019-05-31 16:57:38.105 Detail, Node006,   ZW_SEND_DATA Request with callback ID 0x8e received (expected 0x8e)
2019-05-31 16:57:38.106 Info, Node006, Request RTT 27 Average Request RTT 57
2019-05-31 16:57:38.106 Detail,   Expected callbackId was received
2019-05-31 16:57:38.117 Detail, Node006,   Received: 0x01, 0x09, 0x00, 0x04, 0x00, 0x06, 0x03, 0x26, 0x03, 0x00, 0xd2
2019-05-31 16:57:38.117 Detail, 
2019-05-31 16:57:38.117 Info, Node006, Response RTT 39 Average Response RTT 108
2019-05-31 16:57:38.117 Info, Node006, Received SwitchMultiLevel report: level=0
2019-05-31 16:57:38.117 Detail, Node006, Refreshed Value: old value=0, new value=0, type=byte
2019-05-31 16:57:38.117 Detail, Node006, Changes to this value are not verified
2019-05-31 16:57:38.117 Detail, Node006,   Expected reply and command class was received
2019-05-31 16:57:38.117 Detail, Node006,   Message transaction complete
2019-05-31 16:57:38.117 Detail, 
2019-05-31 16:57:38.118 Detail, Node006, Removing current message
2019-05-31 16:57:38.118 Detail, Node006, Notification: ValueChanged
2019-05-31 16:57:41.127 Info, mgr,     Refreshing node 6: COMMAND_CLASS_SWITCH_MULTILEVEL index = 0 instance = 1 (to confirm a reported change)
2019-05-31 16:57:41.128 Detail, Node006, Queuing (Send) SwitchMultilevelCmd_Get (Node=6): 0x01, 0x09, 0x00, 0x13, 0x06, 0x02, 0x26, 0x02, 0x25, 0x8f, 0x6f
2019-05-31 16:57:41.128 Detail, 
2019-05-31 16:57:41.128 Info, Node006, Sending (Send) message (Callback ID=0x8f, Expected Reply=0x04) - SwitchMultilevelCmd_Get (Node=6): 0x01, 0x09, 0x00, 0x13, 0x06, 0x02, 0x26, 0x02, 0x25, 0x8f, 0x6f
2019-05-31 16:57:41.136 Detail, Node006,   Received: 0x01, 0x04, 0x01, 0x13, 0x01, 0xe8
2019-05-31 16:57:41.136 Detail, Node006,   ZW_SEND_DATA delivered to Z-Wave stack
2019-05-31 16:57:41.152 Detail, Node006,   Received: 0x01, 0x07, 0x00, 0x13, 0x8f, 0x00, 0x00, 0x02, 0x66
2019-05-31 16:57:41.152 Detail, Node006,   ZW_SEND_DATA Request with callback ID 0x8f received (expected 0x8f)
2019-05-31 16:57:41.152 Info, Node006, Request RTT 24 Average Request RTT 40
2019-05-31 16:57:41.153 Detail,   Expected callbackId was received
2019-05-31 16:57:41.164 Detail, Node006,   Received: 0x01, 0x09, 0x00, 0x04, 0x00, 0x06, 0x03, 0x26, 0x03, 0x00, 0xd2
2019-05-31 16:57:41.164 Detail, 
2019-05-31 16:57:41.164 Info, Node006, Response RTT 35 Average Response RTT 71
2019-05-31 16:57:41.164 Info, Node006, Received SwitchMultiLevel report: level=0
2019-05-31 16:57:41.164 Detail, Node006, Refreshed Value: old value=0, new value=0, type=byte
2019-05-31 16:57:41.164 Detail, Node006, Changes to this value are not verified
2019-05-31 16:57:41.164 Detail, Node006,   Expected reply and command class was received
2019-05-31 16:57:41.164 Detail, Node006,   Message transaction complete
2019-05-31 16:57:41.164 Detail, 
2019-05-31 16:57:41.164 Detail, Node006, Removing current message
2019-05-31 16:57:41.165 Detail, Node006, Notification: ValueChanged
2019-05-31 16:58:38.126 Detail, Node005, Polling: COMMAND_CLASS_SWITCH_MULTILEVEL index = 0 instance = 1 (poll queue has 0 messages)
2019-05-31 16:58:38.126 Detail, Node005, Queuing (Poll) SwitchMultilevelCmd_Get (Node=5): 0x01, 0x09, 0x00, 0x13, 0x05, 0x02, 0x26, 0x02, 0x25, 0x90, 0x73
2019-05-31 16:58:38.126 Detail, 
2019-05-31 16:58:38.126 Info, Node005, Sending (Poll) message (Callback ID=0x90, Expected Reply=0x04) - SwitchMultilevelCmd_Get (Node=5): 0x01, 0x09, 0x00, 0x13, 0x05, 0x02, 0x26, 0x02, 0x25, 0x90, 0x73
2019-05-31 16:58:38.135 Detail, Node005,   Received: 0x01, 0x04, 0x01, 0x13, 0x01, 0xe8
2019-05-31 16:58:38.135 Detail, Node005,   ZW_SEND_DATA delivered to Z-Wave stack
2019-05-31 16:58:38.174 Detail, Node005,   Received: 0x01, 0x07, 0x00, 0x13, 0x90, 0x00, 0x00, 0x04, 0x7f
2019-05-31 16:58:38.174 Detail, Node005,   ZW_SEND_DATA Request with callback ID 0x90 received (expected 0x90)
2019-05-31 16:58:38.174 Info, Node005, Request RTT 47 Average Request RTT 101
2019-05-31 16:58:38.174 Detail,   Expected callbackId was received
2019-05-31 16:58:38.247 Detail, Node005,   Received: 0x01, 0x09, 0x00, 0x04, 0x00, 0x05, 0x03, 0x26, 0x03, 0x00, 0xd1
2019-05-31 16:58:38.247 Detail, 
2019-05-31 16:58:38.247 Info, Node005, Response RTT 120 Average Response RTT 173
2019-05-31 16:58:38.247 Info, Node005, Received SwitchMultiLevel report: level=0
2019-05-31 16:58:38.247 Detail, Node005, Refreshed Value: old value=0, new value=0, type=byte
2019-05-31 16:58:38.247 Detail, Node005, Changes to this value are not verified
2019-05-31 16:58:38.247 Detail, Node005,   Expected reply and command class was received
2019-05-31 16:58:38.247 Detail, Node005,   Message transaction complete
2019-05-31 16:58:38.248 Detail, 
2019-05-31 16:58:38.248 Detail, Node005, Removing current message
2019-05-31 16:58:38.248 Detail, Node005, Notification: ValueChanged
2019-05-31 16:58:41.253 Info, mgr,     Refreshing node 5: COMMAND_CLASS_SWITCH_MULTILEVEL index = 0 instance = 1 (to confirm a reported change)
2019-05-31 16:58:41.253 Detail, Node005, Queuing (Send) SwitchMultilevelCmd_Get (Node=5): 0x01, 0x09, 0x00, 0x13, 0x05, 0x02, 0x26, 0x02, 0x25, 0x91, 0x72
2019-05-31 16:58:41.253 Detail, 
2019-05-31 16:58:41.254 Info, Node005, Sending (Send) message (Callback ID=0x91, Expected Reply=0x04) - SwitchMultilevelCmd_Get (Node=5): 0x01, 0x09, 0x00, 0x13, 0x05, 0x02, 0x26, 0x02, 0x25, 0x91, 0x72
2019-05-31 16:58:41.262 Detail, Node005,   Received: 0x01, 0x04, 0x01, 0x13, 0x01, 0xe8
2019-05-31 16:58:41.262 Detail, Node005,   ZW_SEND_DATA delivered to Z-Wave stack
2019-05-31 16:58:41.302 Detail, Node005,   Received: 0x01, 0x07, 0x00, 0x13, 0x91, 0x00, 0x00, 0x05, 0x7f
2019-05-31 16:58:41.302 Detail, Node005,   ZW_SEND_DATA Request with callback ID 0x91 received (expected 0x91)
2019-05-31 16:58:41.302 Info, Node005, Request RTT 48 Average Request RTT 74
2019-05-31 16:58:41.302 Detail,   Expected callbackId was received
2019-05-31 16:58:41.377 Detail, Node005,   Received: 0x01, 0x09, 0x00, 0x04, 0x00, 0x05, 0x03, 0x26, 0x03, 0x00, 0xd1
2019-05-31 16:58:41.377 Detail, 
2019-05-31 16:58:41.377 Info, Node005, Response RTT 123 Average Response RTT 148
2019-05-31 16:58:41.377 Info, Node005, Received SwitchMultiLevel report: level=0
2019-05-31 16:58:41.378 Detail, Node005, Refreshed Value: old value=0, new value=0, type=byte
2019-05-31 16:58:41.378 Detail, Node005, Changes to this value are not verified
2019-05-31 16:58:41.378 Detail, Node005,   Expected reply and command class was received
2019-05-31 16:58:41.378 Detail, Node005,   Message transaction complete
2019-05-31 16:58:41.378 Detail, 
2019-05-31 16:58:41.378 Detail, Node005, Removing current message
2019-05-31 16:58:41.378 Detail, Node005, Notification: ValueChanged
2019-05-31 16:59:38.258 Detail, Node006, Polling: COMMAND_CLASS_SWITCH_MULTILEVEL index = 0 instance = 1 (poll queue has 0 messages)
2019-05-31 16:59:38.258 Detail, Node006, Queuing (Poll) SwitchMultilevelCmd_Get (Node=6): 0x01, 0x09, 0x00, 0x13, 0x06, 0x02, 0x26, 0x02, 0x25, 0x92, 0x72
2019-05-31 16:59:38.258 Detail, 
2019-05-31 16:59:38.258 Info, Node006, Sending (Poll) message (Callback ID=0x92, Expected Reply=0x04) - SwitchMultilevelCmd_Get (Node=6): 0x01, 0x09, 0x00, 0x13, 0x06, 0x02, 0x26, 0x02, 0x25, 0x92, 0x72
2019-05-31 16:59:38.266 Detail, Node006,   Received: 0x01, 0x04, 0x01, 0x13, 0x01, 0xe8
2019-05-31 16:59:38.266 Detail, Node006,   ZW_SEND_DATA delivered to Z-Wave stack
2019-05-31 16:59:38.283 Detail, Node006,   Received: 0x01, 0x07, 0x00, 0x13, 0x92, 0x00, 0x00, 0x02, 0x7b
2019-05-31 16:59:38.283 Detail, Node006,   ZW_SEND_DATA Request with callback ID 0x92 received (expected 0x92)
2019-05-31 16:59:38.283 Info, Node006, Request RTT 24 Average Request RTT 32
2019-05-31 16:59:38.283 Detail,   Expected callbackId was received
2019-05-31 16:59:38.294 Detail, Node006,   Received: 0x01, 0x09, 0x00, 0x04, 0x00, 0x06, 0x03, 0x26, 0x03, 0x00, 0xd2
2019-05-31 16:59:38.294 Detail, 
2019-05-31 16:59:38.294 Info, Node006, Response RTT 35 Average Response RTT 53
2019-05-31 16:59:38.294 Info, Node006, Received SwitchMultiLevel report: level=0
2019-05-31 16:59:38.294 Detail, Node006, Refreshed Value: old value=0, new value=0, type=byte
2019-05-31 16:59:38.294 Detail, Node006, Changes to this value are not verified
2019-05-31 16:59:38.294 Detail, Node006,   Expected reply and command class was received
2019-05-31 16:59:38.295 Detail, Node006,   Message transaction complete
2019-05-31 16:59:38.295 Detail, 
2019-05-31 16:59:38.295 Detail, Node006, Removing current message
2019-05-31 16:59:38.295 Detail, Node006, Notification: ValueChanged
2019-05-31 16:59:41.304 Info, mgr,     Refreshing node 6: COMMAND_CLASS_SWITCH_MULTILEVEL index = 0 instance = 1 (to confirm a reported change)
2019-05-31 16:59:41.305 Detail, Node006, Queuing (Send) SwitchMultilevelCmd_Get (Node=6): 0x01, 0x09, 0x00, 0x13, 0x06, 0x02, 0x26, 0x02, 0x25, 0x93, 0x73
2019-05-31 16:59:41.305 Detail, 
2019-05-31 16:59:41.305 Info, Node006, Sending (Send) message (Callback ID=0x93, Expected Reply=0x04) - SwitchMultilevelCmd_Get (Node=6): 0x01, 0x09, 0x00, 0x13, 0x06, 0x02, 0x26, 0x02, 0x25, 0x93, 0x73
2019-05-31 16:59:41.314 Detail, Node006,   Received: 0x01, 0x04, 0x01, 0x13, 0x01, 0xe8
2019-05-31 16:59:41.314 Detail, Node006,   ZW_SEND_DATA delivered to Z-Wave stack
2019-05-31 16:59:41.329 Detail, Node006,   Received: 0x01, 0x07, 0x00, 0x13, 0x93, 0x00, 0x00, 0x03, 0x7b
2019-05-31 16:59:41.330 Detail, Node006,   ZW_SEND_DATA Request with callback ID 0x93 received (expected 0x93)
2019-05-31 16:59:41.330 Info, Node006, Request RTT 24 Average Request RTT 28
2019-05-31 16:59:41.330 Detail,   Expected callbackId was received
2019-05-31 16:59:41.341 Detail, Node006,   Received: 0x01, 0x09, 0x00, 0x04, 0x00, 0x06, 0x03, 0x26, 0x03, 0x00, 0xd2
2019-05-31 16:59:41.341 Detail, 
2019-05-31 16:59:41.341 Info, Node006, Response RTT 35 Average Response RTT 44
2019-05-31 16:59:41.341 Info, Node006, Received SwitchMultiLevel report: level=0
2019-05-31 16:59:41.341 Detail, Node006, Refreshed Value: old value=0, new value=0, type=byte
2019-05-31 16:59:41.341 Detail, Node006, Changes to this value are not verified
2019-05-31 16:59:41.341 Detail, Node006,   Expected reply and command class was received
2019-05-31 16:59:41.341 Detail, Node006,   Message transaction complete
2019-05-31 16:59:41.341 Detail, 
2019-05-31 16:59:41.341 Detail, Node006, Removing current message
2019-05-31 16:59:41.342 Detail, Node006, Notification: ValueChanged
2019-05-31 17:00:38.299 Detail, Node005, Polling: COMMAND_CLASS_SWITCH_MULTILEVEL index = 0 instance = 1 (poll queue has 0 messages)
2019-05-31 17:00:38.299 Detail, Node005, Queuing (Poll) SwitchMultilevelCmd_Get (Node=5): 0x01, 0x09, 0x00, 0x13, 0x05, 0x02, 0x26, 0x02, 0x25, 0x94, 0x77
2019-05-31 17:00:38.299 Detail, 
2019-05-31 17:00:38.299 Info, Node005, Sending (Poll) message (Callback ID=0x94, Expected Reply=0x04) - SwitchMultilevelCmd_Get (Node=5): 0x01, 0x09, 0x00, 0x13, 0x05, 0x02, 0x26, 0x02, 0x25, 0x94, 0x77
2019-05-31 17:00:38.307 Detail, Node005,   Received: 0x01, 0x04, 0x01, 0x13, 0x01, 0xe8
2019-05-31 17:00:38.307 Detail, Node005,   ZW_SEND_DATA delivered to Z-Wave stack
2019-05-31 17:00:38.347 Detail, Node005,   Received: 0x01, 0x07, 0x00, 0x13, 0x94, 0x00, 0x00, 0x04, 0x7b
2019-05-31 17:00:38.347 Detail, Node005,   ZW_SEND_DATA Request with callback ID 0x94 received (expected 0x94)
2019-05-31 17:00:38.348 Info, Node005, Request RTT 48 Average Request RTT 61
2019-05-31 17:00:38.348 Detail,   Expected callbackId was received
2019-05-31 17:00:38.426 Detail, Node005,   Received: 0x01, 0x09, 0x00, 0x04, 0x00, 0x05, 0x03, 0x26, 0x03, 0x00, 0xd1
2019-05-31 17:00:38.427 Detail, 
2019-05-31 17:00:38.427 Info, Node005, Response RTT 127 Average Response RTT 137
2019-05-31 17:00:38.427 Info, Node005, Received SwitchMultiLevel report: level=0
2019-05-31 17:00:38.427 Detail, Node005, Refreshed Value: old value=0, new value=0, type=byte
2019-05-31 17:00:38.427 Detail, Node005, Changes to this value are not verified
2019-05-31 17:00:38.427 Detail, Node005,   Expected reply and command class was received
2019-05-31 17:00:38.427 Detail, Node005,   Message transaction complete
2019-05-31 17:00:38.427 Detail, 
2019-05-31 17:00:38.427 Detail, Node005, Removing current message
2019-05-31 17:00:38.427 Detail, Node005, Notification: ValueChanged
2019-05-31 17:00:41.436 Info, mgr,     Refreshing node 5: COMMAND_CLASS_SWITCH_MULTILEVEL index = 0 instance = 1 (to confirm a reported change)
2019-05-31 17:00:41.437 Detail, Node005, Queuing (Send) SwitchMultilevelCmd_Get (Node=5): 0x01, 0x09, 0x00, 0x13, 0x05, 0x02, 0x26, 0x02, 0x25, 0x95, 0x76
2019-05-31 17:00:41.437 Detail, 
2019-05-31 17:00:41.437 Info, Node005, Sending (Send) message (Callback ID=0x95, Expected Reply=0x04) - SwitchMultilevelCmd_Get (Node=5): 0x01, 0x09, 0x00, 0x13, 0x05, 0x02, 0x26, 0x02, 0x25, 0x95, 0x76
2019-05-31 17:00:41.445 Detail, Node005,   Received: 0x01, 0x04, 0x01, 0x13, 0x01, 0xe8
2019-05-31 17:00:41.446 Detail, Node005,   ZW_SEND_DATA delivered to Z-Wave stack
2019-05-31 17:00:41.486 Detail, Node005,   Received: 0x01, 0x07, 0x00, 0x13, 0x95, 0x00, 0x00, 0x04, 0x7a
2019-05-31 17:00:41.486 Detail, Node005,   ZW_SEND_DATA Request with callback ID 0x95 received (expected 0x95)
2019-05-31 17:00:41.486 Info, Node005, Request RTT 48 Average Request RTT 54
2019-05-31 17:00:41.486 Detail,   Expected callbackId was received
2019-05-31 17:00:41.557 Detail, Node005,   Received: 0x01, 0x09, 0x00, 0x04, 0x00, 0x05, 0x03, 0x26, 0x03, 0x00, 0xd1
2019-05-31 17:00:41.557 Detail, 
2019-05-31 17:00:41.557 Info, Node005, Response RTT 119 Average Response RTT 128
2019-05-31 17:00:41.557 Info, Node005, Received SwitchMultiLevel report: level=0
2019-05-31 17:00:41.557 Detail, Node005, Refreshed Value: old value=0, new value=0, type=byte
2019-05-31 17:00:41.557 Detail, Node005, Changes to this value are not verified
2019-05-31 17:00:41.557 Detail, Node005,   Expected reply and command class was received
2019-05-31 17:00:41.558 Detail, Node005,   Message transaction complete
2019-05-31 17:00:41.558 Detail, 
2019-05-31 17:00:41.558 Detail, Node005, Removing current message
2019-05-31 17:00:41.558 Detail, Node005, Notification: ValueChanged

Current Z-Wave config settings.

freshcoast · May 31, 2019, 9:48pm

ALL ON/ALL OFF setting is different than Z-Wave Command Dim. The former is I believe the “All Switch” command that is not used all that often. The latter is the Dim rate for the usual case when you send the COMMAND_CLASS_SWITCH_MULTILEVEL command. Probably parameters 7 and 8.

kal_el · May 31, 2019, 9:55pm

@freshcoast Thanks for the reply and help. Those are also set to the same values. I set config 7/11 to 99 and 8/12 to 1. All other config settings left to defaults. Any idea how the state can get in the incorrect state it is in now? I don’t see errors in the OZW_Log file, but also don’t really know how to read the replies. What does Received: 0x01, 0x09, 0x00, 0x04, 0x00, 0x06, 0x03, 0x26, 0x03, 0x63, 0xb1 mean for example? What reply is that?

I see it polling the node, yet is still shows the incorrect state in Home Assistant

edit: adding in logs and screenshot of current state of node 6 (light.office_dimmer). It is currently off (and has been for at least 30 min), but HA is showing it as on:

office_current_state

OZW_Log.txt

2019-05-31 17:53:36.949 Detail, Node006, Polling: COMMAND_CLASS_SWITCH_MULTILEVEL index = 0 instance = 1 (poll queue has 0 messages)
2019-05-31 17:53:36.950 Detail, Node006, Queuing (Poll) SwitchMultilevelCmd_Get (Node=6): 0x01, 0x09, 0x00, 0x13, 0x06, 0x02, 0x26, 0x02, 0x25, 0x6c, 0x8c
2019-05-31 17:53:36.950 Detail, 
2019-05-31 17:53:36.950 Info, Node006, Sending (Poll) message (Callback ID=0x6c, Expected Reply=0x04) - SwitchMultilevelCmd_Get (Node=6): 0x01, 0x09, 0x00, 0x13, 0x06, 0x02, 0x26, 0x02, 0x25, 0x6c, 0x8c
2019-05-31 17:53:36.958 Detail, Node006,   Received: 0x01, 0x04, 0x01, 0x13, 0x01, 0xe8
2019-05-31 17:53:36.959 Detail, Node006,   ZW_SEND_DATA delivered to Z-Wave stack
2019-05-31 17:53:36.975 Detail, Node006,   Received: 0x01, 0x07, 0x00, 0x13, 0x6c, 0x00, 0x00, 0x02, 0x85
2019-05-31 17:53:36.975 Detail, Node006,   ZW_SEND_DATA Request with callback ID 0x6c received (expected 0x6c)
2019-05-31 17:53:36.975 Info, Node006, Request RTT 25 Average Request RTT 24
2019-05-31 17:53:36.975 Detail,   Expected callbackId was received
2019-05-31 17:53:36.985 Detail, Node006,   Received: 0x01, 0x09, 0x00, 0x04, 0x00, 0x06, 0x03, 0x26, 0x03, 0x63, 0xb1
2019-05-31 17:53:36.985 Detail, 
2019-05-31 17:53:36.985 Info, Node006, Response RTT 35 Average Response RTT 35
2019-05-31 17:53:36.986 Info, Node006, Received SwitchMultiLevel report: level=99
2019-05-31 17:53:36.986 Detail, Node006, Refreshed Value: old value=99, new value=99, type=byte
2019-05-31 17:53:36.986 Detail, Node006, Changes to this value are not verified
2019-05-31 17:53:36.986 Detail, Node006,   Expected reply and command class was received
2019-05-31 17:53:36.986 Detail, Node006,   Message transaction complete
2019-05-31 17:53:36.986 Detail, 
2019-05-31 17:53:36.986 Detail, Node006, Removing current message
2019-05-31 17:53:36.986 Detail, Node006, Notification: ValueChanged
2019-05-31 17:53:41.997 Info, mgr,     Refreshing node 6: COMMAND_CLASS_SWITCH_MULTILEVEL index = 0 instance = 1 (to confirm a reported change)
2019-05-31 17:53:41.997 Detail, Node006, Queuing (Send) SwitchMultilevelCmd_Get (Node=6): 0x01, 0x09, 0x00, 0x13, 0x06, 0x02, 0x26, 0x02, 0x25, 0x6d, 0x8d
2019-05-31 17:53:41.997 Detail, 
2019-05-31 17:53:41.997 Info, Node006, Sending (Send) message (Callback ID=0x6d, Expected Reply=0x04) - SwitchMultilevelCmd_Get (Node=6): 0x01, 0x09, 0x00, 0x13, 0x06, 0x02, 0x26, 0x02, 0x25, 0x6d, 0x8d
2019-05-31 17:53:42.005 Detail, Node006,   Received: 0x01, 0x04, 0x01, 0x13, 0x01, 0xe8
2019-05-31 17:53:42.006 Detail, Node006,   ZW_SEND_DATA delivered to Z-Wave stack
2019-05-31 17:53:42.022 Detail, Node006,   Received: 0x01, 0x07, 0x00, 0x13, 0x6d, 0x00, 0x00, 0x02, 0x84
2019-05-31 17:53:42.022 Detail, Node006,   ZW_SEND_DATA Request with callback ID 0x6d received (expected 0x6d)
2019-05-31 17:53:42.022 Info, Node006, Request RTT 25 Average Request RTT 24
2019-05-31 17:53:42.022 Detail,   Expected callbackId was received
2019-05-31 17:53:42.034 Detail, Node006,   Received: 0x01, 0x09, 0x00, 0x04, 0x00, 0x06, 0x03, 0x26, 0x03, 0x63, 0xb1
2019-05-31 17:53:42.034 Detail, 
2019-05-31 17:53:42.034 Info, Node006, Response RTT 37 Average Response RTT 36
2019-05-31 17:53:42.034 Info, Node006, Received SwitchMultiLevel report: level=99
2019-05-31 17:53:42.034 Detail, Node006, Refreshed Value: old value=99, new value=99, type=byte
2019-05-31 17:53:42.034 Detail, Node006, Changes to this value are not verified
2019-05-31 17:53:42.034 Detail, Node006,   Expected reply and command class was received
2019-05-31 17:53:42.034 Detail, Node006,   Message transaction complete
2019-05-31 17:53:42.034 Detail, 
2019-05-31 17:53:42.035 Detail, Node006, Removing current message
2019-05-31 17:53:42.035 Detail, Node006, Notification: ValueChanged

firstof9 · May 31, 2019, 10:03pm

Sorry my dim rate is set to 3 not 99.
I also don’t have any polling set.

freshcoast · May 31, 2019, 10:26pm

Are these the correct logs? It is showing that the switch is on, from the Z-Wave network perspective. So HA would seem to be in sync with the network. Obviously you are the one that can see if the light is on or off, so I can’t argue that, I can just explain what I see in the logs you posted.

This message show the polling, it is sending a Get command to read the dim level value:

2019-05-31 17:53:36.949 Detail, Node006, Polling: COMMAND_CLASS_SWITCH_MULTILEVEL index = 0 instance = 1 (poll queue has 0 messages)
2019-05-31 17:53:36.950 Detail, Node006, Queuing (Poll) SwitchMultilevelCmd_Get (Node=6): 0x01, 0x09, 0x00, 0x13, 0x06, 0x02, 0x26, 0x02, 0x25, 0x6c, 0x8c
2019-05-31 17:53:36.950 Detail, 
2019-05-31 17:53:36.950 Info, Node006, Sending (Poll) message (Callback ID=0x6c, Expected Reply=0x04) - SwitchMultilevelCmd_Get (Node=6): 0x01, 0x09, 0x00, 0x13, 0x06, 0x02, 0x26, 0x02, 0x25, 0x6c, 0x8c

Milliseconds later it receives the reply (or report in z-wave terminology).

2019-05-31 17:53:36.986 Info, Node006, Received SwitchMultiLevel report: level=99
2019-05-31 17:53:36.986 Detail, Node006, Refreshed Value: old value=99, new value=99, type=byte
2019-05-31 17:53:36.986 Detail, Node006, Changes to this value are not verified
2019-05-31 17:53:36.986 Detail, Node006,   Expected reply and command class was received
2019-05-31 17:53:36.986 Detail, Node006,   Message transaction complete
2019-05-31 17:53:36.986 Detail, 
2019-05-31 17:53:36.986 Detail, Node006, Removing current message
2019-05-31 17:53:36.986 Detail, Node006, Notification: ValueChanged

The switch says the dim level is 99, which is on and full brightness. “old value” just means the value OZW had cached before the reply, “new value” is the value it just read, so it is the same value as before the poll. The last message “Notificatoin: ValueChanged” means it’s sending a notification to the application (HA) about the value changing. It didn’t really change, so HA won’t update anything.

The next set of logs is just a refresh, not sure what triggered it, but it’s another Get and it still reports the same dim level of 99.

2019-05-31 17:53:41.997 Info, mgr,     Refreshing node 6: COMMAND_CLASS_SWITCH_MULTILEVEL index = 0 instance = 1 (to confirm a reported change)
2019-05-31 17:53:41.997 Detail, Node006, Queuing (Send) SwitchMultilevelCmd_Get (Node=6): 0x01, 0x09, 0x00, 0x13, 0x06, 0x02, 0x26, 0x02, 0x25, 0x6d, 0x8d
<snip>
2019-05-31 17:53:42.034 Info, Node006, Received SwitchMultiLevel report: level=99
2019-05-31 17:53:42.034 Detail, Node006, Refreshed Value: old value=99, new value=99, type=byte

Maybe you could post a set of logs while toggling the switch? I’m actually seeing something weird with my setup so I’m a little curious if there is more to this than I thought.

kal_el · May 31, 2019, 10:39pm

@freshcoast again, thanks for the reply and help. Hopefully my experience/logs below will help what you are debugging on your own network.

Those are definitely the correct logs. What you said got me to pay closer attention while I went to physically toggle the switch. This is what I experienced (and logs)

Light is off (or at least looks off)
Hit “on” on the switch - nothing happened
Hit “on” again - nothing happened
I realize it may just be dimmed all the way, so I hold the “on” and it “snapped” on to full brightness. What I mean is that there was no slow stepping that normally happens when controlled locally. Also confirmed after that it is definitely slow stepping locally, so not sure how it could have snapped to full brightness.
Hit “off” - light turns off
Hit “on” - light turns on

So the odd part is how it could have been “on” but just dimmed all the way. The way I got it into that state was by just hitting the on/off toggle in the lovelace UI, never touched the brightness setting. You can even see in the log and the screenshot that HA thought the brightness was at 99, which it should have been.

OZW_Log.txt:

2019-05-31 18:28:40.815 Detail, Node006,   Received: 0x01, 0x17, 0x00, 0x49, 0x84, 0x06, 0x11, 0x04, 0x11, 0x01, 0x5e, 0x56, 0x86, 0x72, 0x5a, 0x85, 0x59, 0x73, 0x26, 0x27, 0x70, 0x2c, 0x2b, 0x7a, 0x23
2019-05-31 18:28:40.816 Detail, 
2019-05-31 18:28:40.816 Info, Node006, UPDATE_STATE_NODE_INFO_RECEIVED from node 6
2019-05-31 18:28:40.816 Detail, Node006, AdvanceQueries queryPending=0 queryRetries=0 queryStage=Dynamic live=1
2019-05-31 18:28:40.816 Detail, Node006, QueryStage_Dynamic
2019-05-31 18:28:40.816 Detail, Node006, Queuing (Send) SwitchMultilevelCmd_Get (Node=6): 0x01, 0x09, 0x00, 0x13, 0x06, 0x02, 0x26, 0x02, 0x25, 0x90, 0x70
2019-05-31 18:28:40.816 Detail, Node006, Queuing (Query) Query Stage Complete (Dynamic)
2019-05-31 18:28:40.816 Detail, 
2019-05-31 18:28:40.816 Info, Node006, Sending (Send) message (Callback ID=0x90, Expected Reply=0x04) - SwitchMultilevelCmd_Get (Node=6): 0x01, 0x09, 0x00, 0x13, 0x06, 0x02, 0x26, 0x02, 0x25, 0x90, 0x70
2019-05-31 18:28:40.825 Detail, Node006,   Received: 0x01, 0x04, 0x01, 0x13, 0x01, 0xe8
2019-05-31 18:28:40.825 Detail, Node006,   ZW_SEND_DATA delivered to Z-Wave stack
2019-05-31 18:28:40.833 Detail, Node006,   Received: 0x01, 0x09, 0x00, 0x04, 0x00, 0x06, 0x03, 0x26, 0x03, 0x63, 0xb1
2019-05-31 18:28:40.834 Detail, 
2019-05-31 18:28:40.834 Info, Node006, Response RTT 17 Average Response RTT 31
2019-05-31 18:28:40.834 Info, Node006, Received SwitchMultiLevel report: level=99
2019-05-31 18:28:40.834 Detail, Node006, Refreshed Value: old value=99, new value=99, type=byte
2019-05-31 18:28:40.834 Detail, Node006, Changes to this value are not verified
2019-05-31 18:28:40.834 Detail, Node006, Notification: ValueChanged
2019-05-31 18:28:40.851 Detail, Node006,   Received: 0x01, 0x07, 0x00, 0x13, 0x90, 0x00, 0x00, 0x03, 0x78
2019-05-31 18:28:40.851 Detail, Node006,   ZW_SEND_DATA Request with callback ID 0x90 received (expected 0x90)
2019-05-31 18:28:40.851 Info, Node006, Request RTT 34 Average Request RTT 36
2019-05-31 18:28:40.852 Detail,   Expected callbackId was received
2019-05-31 18:28:40.862 Detail, Node006,   Received: 0x01, 0x09, 0x00, 0x04, 0x00, 0x06, 0x03, 0x26, 0x03, 0x63, 0xb1
2019-05-31 18:28:40.862 Detail, 
2019-05-31 18:28:40.862 Info, Node006, Response RTT 45 Average Response RTT 38
2019-05-31 18:28:40.862 Info, Node006, Received SwitchMultiLevel report: level=99
2019-05-31 18:28:40.862 Detail, Node006, Refreshed Value: old value=99, new value=99, type=byte
2019-05-31 18:28:40.862 Detail, Node006, Changes to this value are not verified
2019-05-31 18:28:40.862 Detail, Node006,   Expected reply and command class was received
2019-05-31 18:28:40.862 Detail, Node006,   Message transaction complete
2019-05-31 18:28:40.862 Detail, 
2019-05-31 18:28:40.862 Detail, Node006, Removing current message
2019-05-31 18:28:40.863 Detail, Node006, Notification: ValueChanged
2019-05-31 18:28:40.878 Detail, Node006, Query Stage Complete (Dynamic)
2019-05-31 18:28:40.878 Detail, Node006, AdvanceQueries queryPending=0 queryRetries=0 queryStage=Configuration live=1
2019-05-31 18:28:40.878 Detail, Node006, QueryStage_Configuration
2019-05-31 18:28:40.879 Detail, Node006, QueryStage_Complete
2019-05-31 18:28:40.879 Warning, CheckCompletedNodeQueries m_allNodesQueried=1 m_awakeNodesQueried=1
2019-05-31 18:28:40.879 Detail, Node006, Notification: NodeQueriesComplete
2019-05-31 18:28:45.717 Detail, Node006,   Received: 0x01, 0x17, 0x00, 0x49, 0x84, 0x06, 0x11, 0x04, 0x11, 0x01, 0x5e, 0x56, 0x86, 0x72, 0x5a, 0x85, 0x59, 0x73, 0x26, 0x27, 0x70, 0x2c, 0x2b, 0x7a, 0x23
2019-05-31 18:28:45.718 Detail, 
2019-05-31 18:28:45.718 Info, Node006, UPDATE_STATE_NODE_INFO_RECEIVED from node 6
2019-05-31 18:28:45.718 Detail, Node006, AdvanceQueries queryPending=0 queryRetries=0 queryStage=Dynamic live=1
2019-05-31 18:28:45.718 Detail, Node006, QueryStage_Dynamic
2019-05-31 18:28:45.718 Detail, Node006, Queuing (Send) SwitchMultilevelCmd_Get (Node=6): 0x01, 0x09, 0x00, 0x13, 0x06, 0x02, 0x26, 0x02, 0x25, 0x91, 0x71
2019-05-31 18:28:45.718 Detail, Node006, Queuing (Query) Query Stage Complete (Dynamic)
2019-05-31 18:28:45.718 Detail, 
2019-05-31 18:28:45.719 Info, Node006, Sending (Send) message (Callback ID=0x91, Expected Reply=0x04) - SwitchMultilevelCmd_Get (Node=6): 0x01, 0x09, 0x00, 0x13, 0x06, 0x02, 0x26, 0x02, 0x25, 0x91, 0x71
2019-05-31 18:28:45.728 Detail, Node006,   Received: 0x01, 0x04, 0x01, 0x13, 0x01, 0xe8
2019-05-31 18:28:45.728 Detail, Node006,   ZW_SEND_DATA delivered to Z-Wave stack
2019-05-31 18:28:45.735 Detail, Node006,   Received: 0x01, 0x09, 0x00, 0x04, 0x00, 0x06, 0x03, 0x26, 0x03, 0x63, 0xb1
2019-05-31 18:28:45.736 Detail, 
2019-05-31 18:28:45.736 Info, Node006, Response RTT 16 Average Response RTT 27
2019-05-31 18:28:45.736 Info, Node006, Received SwitchMultiLevel report: level=99
2019-05-31 18:28:45.736 Detail, Node006, Refreshed Value: old value=99, new value=99, type=byte
2019-05-31 18:28:45.736 Detail, Node006, Changes to this value are not verified
2019-05-31 18:28:45.736 Detail, Node006, Notification: ValueChanged
2019-05-31 18:28:45.753 Detail, Node006,   Received: 0x01, 0x07, 0x00, 0x13, 0x91, 0x00, 0x00, 0x03, 0x79
2019-05-31 18:28:45.753 Detail, Node006,   ZW_SEND_DATA Request with callback ID 0x91 received (expected 0x91)
2019-05-31 18:28:45.753 Info, Node006, Request RTT 34 Average Request RTT 35
2019-05-31 18:28:45.753 Detail,   Expected callbackId was received
2019-05-31 18:28:45.765 Detail, Node006,   Received: 0x01, 0x09, 0x00, 0x04, 0x00, 0x06, 0x03, 0x26, 0x03, 0x63, 0xb1
2019-05-31 18:28:45.765 Detail, 
2019-05-31 18:28:45.765 Info, Node006, Response RTT 46 Average Response RTT 36
2019-05-31 18:28:45.765 Info, Node006, Received SwitchMultiLevel report: level=99
2019-05-31 18:28:45.765 Detail, Node006, Refreshed Value: old value=99, new value=99, type=byte
2019-05-31 18:28:45.765 Detail, Node006, Changes to this value are not verified
2019-05-31 18:28:45.765 Detail, Node006,   Expected reply and command class was received
2019-05-31 18:28:45.765 Detail, Node006,   Message transaction complete
2019-05-31 18:28:45.765 Detail, 
2019-05-31 18:28:45.765 Detail, Node006, Removing current message
2019-05-31 18:28:45.766 Detail, Node006, Notification: ValueChanged
2019-05-31 18:28:45.775 Detail, Node006, Query Stage Complete (Dynamic)
2019-05-31 18:28:45.775 Detail, Node006, AdvanceQueries queryPending=0 queryRetries=0 queryStage=Configuration live=1
2019-05-31 18:28:45.775 Detail, Node006, QueryStage_Configuration
2019-05-31 18:28:45.775 Detail, Node006, QueryStage_Complete
2019-05-31 18:28:45.775 Warning, CheckCompletedNodeQueries m_allNodesQueried=1 m_awakeNodesQueried=1
2019-05-31 18:28:45.775 Detail, Node006, Notification: NodeQueriesComplete
2019-05-31 18:28:47.978 Detail, Node006,   Received: 0x01, 0x17, 0x00, 0x49, 0x84, 0x06, 0x11, 0x04, 0x11, 0x01, 0x5e, 0x56, 0x86, 0x72, 0x5a, 0x85, 0x59, 0x73, 0x26, 0x27, 0x70, 0x2c, 0x2b, 0x7a, 0x23
2019-05-31 18:28:47.978 Detail, 
2019-05-31 18:28:47.978 Info, Node006, UPDATE_STATE_NODE_INFO_RECEIVED from node 6
2019-05-31 18:28:47.978 Detail, Node006, AdvanceQueries queryPending=0 queryRetries=0 queryStage=Dynamic live=1
2019-05-31 18:28:47.978 Detail, Node006, QueryStage_Dynamic
2019-05-31 18:28:47.978 Detail, Node006, Queuing (Send) SwitchMultilevelCmd_Get (Node=6): 0x01, 0x09, 0x00, 0x13, 0x06, 0x02, 0x26, 0x02, 0x25, 0x92, 0x72
2019-05-31 18:28:47.978 Detail, Node006, Queuing (Query) Query Stage Complete (Dynamic)
2019-05-31 18:28:47.978 Detail, 
2019-05-31 18:28:47.979 Info, Node006, Sending (Send) message (Callback ID=0x92, Expected Reply=0x04) - SwitchMultilevelCmd_Get (Node=6): 0x01, 0x09, 0x00, 0x13, 0x06, 0x02, 0x26, 0x02, 0x25, 0x92, 0x72
2019-05-31 18:28:47.987 Detail, Node006,   Received: 0x01, 0x04, 0x01, 0x13, 0x01, 0xe8
2019-05-31 18:28:47.987 Detail, Node006,   ZW_SEND_DATA delivered to Z-Wave stack
2019-05-31 18:28:47.995 Detail, Node006,   Received: 0x01, 0x09, 0x00, 0x04, 0x00, 0x06, 0x03, 0x26, 0x03, 0x63, 0xb1
2019-05-31 18:28:47.995 Detail, 
2019-05-31 18:28:47.995 Info, Node006, Response RTT 16 Average Response RTT 26
2019-05-31 18:28:47.995 Info, Node006, Received SwitchMultiLevel report: level=99
2019-05-31 18:28:47.995 Detail, Node006, Refreshed Value: old value=99, new value=99, type=byte
2019-05-31 18:28:47.995 Detail, Node006, Changes to this value are not verified
2019-05-31 18:28:47.995 Detail, Node006, Notification: ValueChanged
2019-05-31 18:28:48.013 Detail, Node006,   Received: 0x01, 0x07, 0x00, 0x13, 0x92, 0x00, 0x00, 0x03, 0x7a
2019-05-31 18:28:48.013 Detail, Node006,   ZW_SEND_DATA Request with callback ID 0x92 received (expected 0x92)
2019-05-31 18:28:48.013 Info, Node006, Request RTT 35 Average Request RTT 35
2019-05-31 18:28:48.013 Detail,   Expected callbackId was received
2019-05-31 18:28:48.024 Detail, Node006,   Received: 0x01, 0x09, 0x00, 0x04, 0x00, 0x06, 0x03, 0x26, 0x03, 0x63, 0xb1
2019-05-31 18:28:48.024 Detail, 
2019-05-31 18:28:48.024 Info, Node006, Response RTT 46 Average Response RTT 36
2019-05-31 18:28:48.024 Info, Node006, Received SwitchMultiLevel report: level=99
2019-05-31 18:28:48.024 Detail, Node006, Refreshed Value: old value=99, new value=99, type=byte
2019-05-31 18:28:48.024 Detail, Node006, Changes to this value are not verified
2019-05-31 18:28:48.025 Detail, Node006,   Expected reply and command class was received
2019-05-31 18:28:48.025 Detail, Node006,   Message transaction complete
2019-05-31 18:28:48.025 Detail, 
2019-05-31 18:28:48.025 Detail, Node006, Removing current message
2019-05-31 18:28:48.025 Detail, Node006, Notification: ValueChanged
2019-05-31 18:28:48.035 Detail, Node006, Query Stage Complete (Dynamic)
2019-05-31 18:28:48.035 Detail, Node006, AdvanceQueries queryPending=0 queryRetries=0 queryStage=Configuration live=1
2019-05-31 18:28:48.035 Detail, Node006, QueryStage_Configuration
2019-05-31 18:28:48.035 Detail, Node006, QueryStage_Complete
2019-05-31 18:28:48.035 Warning, CheckCompletedNodeQueries m_allNodesQueried=1 m_awakeNodesQueried=1
2019-05-31 18:28:48.035 Detail, Node006, Notification: NodeQueriesComplete
2019-05-31 18:28:53.034 Info, mgr,     Refreshing node 6: COMMAND_CLASS_SWITCH_MULTILEVEL index = 0 instance = 1 (to confirm a reported change)
2019-05-31 18:28:53.034 Detail, Node006, Queuing (Send) SwitchMultilevelCmd_Get (Node=6): 0x01, 0x09, 0x00, 0x13, 0x06, 0x02, 0x26, 0x02, 0x25, 0x93, 0x73
2019-05-31 18:28:53.034 Detail, 
2019-05-31 18:28:53.034 Info, Node006, Sending (Send) message (Callback ID=0x93, Expected Reply=0x04) - SwitchMultilevelCmd_Get (Node=6): 0x01, 0x09, 0x00, 0x13, 0x06, 0x02, 0x26, 0x02, 0x25, 0x93, 0x73
2019-05-31 18:28:53.043 Detail, Node006,   Received: 0x01, 0x04, 0x01, 0x13, 0x01, 0xe8
2019-05-31 18:28:53.043 Detail, Node006,   ZW_SEND_DATA delivered to Z-Wave stack
2019-05-31 18:28:53.059 Detail, Node006,   Received: 0x01, 0x07, 0x00, 0x13, 0x93, 0x00, 0x00, 0x02, 0x7a
2019-05-31 18:28:53.059 Detail, Node006,   ZW_SEND_DATA Request with callback ID 0x93 received (expected 0x93)
2019-05-31 18:28:53.060 Info, Node006, Request RTT 24 Average Request RTT 29
2019-05-31 18:28:53.060 Detail,   Expected callbackId was received
2019-05-31 18:28:53.070 Detail, Node006,   Received: 0x01, 0x09, 0x00, 0x04, 0x00, 0x06, 0x03, 0x26, 0x03, 0x63, 0xb1
2019-05-31 18:28:53.070 Detail, 
2019-05-31 18:28:53.070 Info, Node006, Response RTT 35 Average Response RTT 35
2019-05-31 18:28:53.070 Info, Node006, Received SwitchMultiLevel report: level=99
2019-05-31 18:28:53.070 Detail, Node006, Refreshed Value: old value=99, new value=99, type=byte
2019-05-31 18:28:53.070 Detail, Node006, Changes to this value are not verified
2019-05-31 18:28:53.070 Detail, Node006,   Expected reply and command class was received
2019-05-31 18:28:53.070 Detail, Node006,   Message transaction complete
2019-05-31 18:28:53.070 Detail, 
2019-05-31 18:28:53.071 Detail, Node006, Removing current message
2019-05-31 18:28:53.071 Detail, Node006, Notification: ValueChanged
2019-05-31 18:28:53.479 Detail, Node006,   Received: 0x01, 0x09, 0x00, 0x04, 0x00, 0x06, 0x03, 0x26, 0x03, 0x63, 0xb1
2019-05-31 18:28:53.479 Detail, 
2019-05-31 18:28:53.479 Info, Node006, Received SwitchMultiLevel report: level=99
2019-05-31 18:28:53.479 Detail, Node006, Refreshed Value: old value=99, new value=99, type=byte
2019-05-31 18:28:53.480 Detail, Node006, Changes to this value are not verified
2019-05-31 18:28:53.480 Detail, Node006, Notification: ValueChanged
2019-05-31 18:28:58.489 Info, mgr,     Refreshing node 6: COMMAND_CLASS_SWITCH_MULTILEVEL index = 0 instance = 1 (to confirm a reported change)
2019-05-31 18:28:58.489 Detail, Node006, Queuing (Send) SwitchMultilevelCmd_Get (Node=6): 0x01, 0x09, 0x00, 0x13, 0x06, 0x02, 0x26, 0x02, 0x25, 0x94, 0x74
2019-05-31 18:28:58.489 Detail, 
2019-05-31 18:28:58.490 Info, Node006, Sending (Send) message (Callback ID=0x94, Expected Reply=0x04) - SwitchMultilevelCmd_Get (Node=6): 0x01, 0x09, 0x00, 0x13, 0x06, 0x02, 0x26, 0x02, 0x25, 0x94, 0x74
2019-05-31 18:28:58.498 Detail, Node006,   Received: 0x01, 0x04, 0x01, 0x13, 0x01, 0xe8
2019-05-31 18:28:58.498 Detail, Node006,   ZW_SEND_DATA delivered to Z-Wave stack
2019-05-31 18:28:58.513 Detail, Node006,   Received: 0x01, 0x07, 0x00, 0x13, 0x94, 0x00, 0x00, 0x02, 0x7d
2019-05-31 18:28:58.514 Detail, Node006,   ZW_SEND_DATA Request with callback ID 0x94 received (expected 0x94)
2019-05-31 18:28:58.514 Info, Node006, Request RTT 23 Average Request RTT 26
2019-05-31 18:28:58.514 Detail,   Expected callbackId was received
2019-05-31 18:28:58.525 Detail, Node006,   Received: 0x01, 0x09, 0x00, 0x04, 0x00, 0x06, 0x03, 0x26, 0x03, 0x63, 0xb1
2019-05-31 18:28:58.525 Detail, 
2019-05-31 18:28:58.525 Info, Node006, Response RTT 35 Average Response RTT 35
2019-05-31 18:28:58.525 Info, Node006, Received SwitchMultiLevel report: level=99
2019-05-31 18:28:58.525 Detail, Node006, Refreshed Value: old value=99, new value=99, type=byte
2019-05-31 18:28:58.526 Detail, Node006, Changes to this value are not verified
2019-05-31 18:28:58.526 Detail, Node006,   Expected reply and command class was received
2019-05-31 18:28:58.526 Detail, Node006,   Message transaction complete
2019-05-31 18:28:58.526 Detail, 
2019-05-31 18:28:58.526 Detail, Node006, Removing current message
2019-05-31 18:28:58.526 Detail, Node006, Notification: ValueChanged
2019-05-31 18:29:07.926 Detail, Node006,   Received: 0x01, 0x17, 0x00, 0x49, 0x84, 0x06, 0x11, 0x04, 0x11, 0x01, 0x5e, 0x56, 0x86, 0x72, 0x5a, 0x85, 0x59, 0x73, 0x26, 0x27, 0x70, 0x2c, 0x2b, 0x7a, 0x23
2019-05-31 18:29:07.927 Detail, 
2019-05-31 18:29:07.927 Info, Node006, UPDATE_STATE_NODE_INFO_RECEIVED from node 6
2019-05-31 18:29:07.927 Detail, Node006, AdvanceQueries queryPending=0 queryRetries=0 queryStage=Dynamic live=1
2019-05-31 18:29:07.927 Detail, Node006, QueryStage_Dynamic
2019-05-31 18:29:07.927 Detail, Node006, Queuing (Send) SwitchMultilevelCmd_Get (Node=6): 0x01, 0x09, 0x00, 0x13, 0x06, 0x02, 0x26, 0x02, 0x25, 0x95, 0x75
2019-05-31 18:29:07.927 Detail, Node006, Queuing (Query) Query Stage Complete (Dynamic)
2019-05-31 18:29:07.927 Detail, 
2019-05-31 18:29:07.927 Info, Node006, Sending (Send) message (Callback ID=0x95, Expected Reply=0x04) - SwitchMultilevelCmd_Get (Node=6): 0x01, 0x09, 0x00, 0x13, 0x06, 0x02, 0x26, 0x02, 0x25, 0x95, 0x75
2019-05-31 18:29:07.936 Detail, Node006,   Received: 0x01, 0x04, 0x01, 0x13, 0x01, 0xe8
2019-05-31 18:29:07.936 Detail, Node006,   ZW_SEND_DATA delivered to Z-Wave stack
2019-05-31 18:29:07.952 Detail, Node006,   Received: 0x01, 0x07, 0x00, 0x13, 0x95, 0x00, 0x00, 0x02, 0x7c
2019-05-31 18:29:07.952 Detail, Node006,   ZW_SEND_DATA Request with callback ID 0x95 received (expected 0x95)
2019-05-31 18:29:07.952 Info, Node006, Request RTT 24 Average Request RTT 25
2019-05-31 18:29:07.952 Detail,   Expected callbackId was received
2019-05-31 18:29:07.963 Detail, Node006,   Received: 0x01, 0x09, 0x00, 0x04, 0x00, 0x06, 0x03, 0x26, 0x03, 0x5d, 0x8f
2019-05-31 18:29:07.964 Detail, 
2019-05-31 18:29:07.964 Info, Node006, Response RTT 35 Average Response RTT 35
2019-05-31 18:29:07.964 Info, Node006, Received SwitchMultiLevel report: level=93
2019-05-31 18:29:07.964 Detail, Node006, Refreshed Value: old value=99, new value=93, type=byte
2019-05-31 18:29:07.964 Detail, Node006, Changes to this value are not verified
2019-05-31 18:29:07.964 Detail, Node006,   Expected reply and command class was received
2019-05-31 18:29:07.964 Detail, Node006,   Message transaction complete
2019-05-31 18:29:07.964 Detail, 
2019-05-31 18:29:07.964 Detail, Node006, Removing current message
2019-05-31 18:29:07.964 Detail, Node006, Notification: ValueChanged
2019-05-31 18:29:07.974 Detail, Node006, Query Stage Complete (Dynamic)
2019-05-31 18:29:07.975 Detail, Node006, AdvanceQueries queryPending=0 queryRetries=0 queryStage=Configuration live=1
2019-05-31 18:29:07.975 Detail, Node006, QueryStage_Configuration
2019-05-31 18:29:07.975 Detail, Node006, QueryStage_Complete
2019-05-31 18:29:07.975 Warning, CheckCompletedNodeQueries m_allNodesQueried=1 m_awakeNodesQueried=1
2019-05-31 18:29:07.975 Detail, Node006, Notification: NodeQueriesComplete
2019-05-31 18:29:08.888 Detail, Node006,   Received: 0x01, 0x09, 0x00, 0x04, 0x00, 0x06, 0x03, 0x26, 0x03, 0x00, 0xd2
2019-05-31 18:29:08.888 Detail, 
2019-05-31 18:29:08.888 Info, Node006, Received SwitchMultiLevel report: level=0
2019-05-31 18:29:08.888 Detail, Node006, Refreshed Value: old value=93, new value=0, type=byte
2019-05-31 18:29:08.888 Detail, Node006, Changes to this value are not verified
2019-05-31 18:29:08.888 Detail, Node006, Notification: ValueChanged
2019-05-31 18:29:13.904 Info, mgr,     Refreshing node 6: COMMAND_CLASS_SWITCH_MULTILEVEL index = 0 instance = 1 (to confirm a reported change)
2019-05-31 18:29:13.905 Detail, Node006, Queuing (Send) SwitchMultilevelCmd_Get (Node=6): 0x01, 0x09, 0x00, 0x13, 0x06, 0x02, 0x26, 0x02, 0x25, 0x96, 0x76
2019-05-31 18:29:13.905 Detail, 
2019-05-31 18:29:13.905 Info, Node006, Sending (Send) message (Callback ID=0x96, Expected Reply=0x04) - SwitchMultilevelCmd_Get (Node=6): 0x01, 0x09, 0x00, 0x13, 0x06, 0x02, 0x26, 0x02, 0x25, 0x96, 0x76
2019-05-31 18:29:13.914 Detail, Node006,   Received: 0x01, 0x04, 0x01, 0x13, 0x01, 0xe8
2019-05-31 18:29:13.914 Detail, Node006,   ZW_SEND_DATA delivered to Z-Wave stack
2019-05-31 18:29:13.929 Detail, Node006,   Received: 0x01, 0x07, 0x00, 0x13, 0x96, 0x00, 0x00, 0x02, 0x7f
2019-05-31 18:29:13.929 Detail, Node006,   ZW_SEND_DATA Request with callback ID 0x96 received (expected 0x96)
2019-05-31 18:29:13.929 Info, Node006, Request RTT 24 Average Request RTT 24
2019-05-31 18:29:13.929 Detail,   Expected callbackId was received
2019-05-31 18:29:13.940 Detail, Node006,   Received: 0x01, 0x09, 0x00, 0x04, 0x00, 0x06, 0x03, 0x26, 0x03, 0x00, 0xd2
2019-05-31 18:29:13.941 Detail, 
2019-05-31 18:29:13.941 Info, Node006, Response RTT 35 Average Response RTT 35
2019-05-31 18:29:13.941 Info, Node006, Received SwitchMultiLevel report: level=0
2019-05-31 18:29:13.941 Detail, Node006, Refreshed Value: old value=0, new value=0, type=byte
2019-05-31 18:29:13.941 Detail, Node006, Changes to this value are not verified
2019-05-31 18:29:13.941 Detail, Node006,   Expected reply and command class was received
2019-05-31 18:29:13.941 Detail, Node006,   Message transaction complete
2019-05-31 18:29:13.941 Detail, 
2019-05-31 18:29:13.941 Detail, Node006, Removing current message
2019-05-31 18:29:13.941 Detail, Node006, Notification: ValueChanged
2019-05-31 18:29:15.760 Detail, Node006,   Received: 0x01, 0x17, 0x00, 0x49, 0x84, 0x06, 0x11, 0x04, 0x11, 0x01, 0x5e, 0x56, 0x86, 0x72, 0x5a, 0x85, 0x59, 0x73, 0x26, 0x27, 0x70, 0x2c, 0x2b, 0x7a, 0x23
2019-05-31 18:29:15.760 Detail, 
2019-05-31 18:29:15.760 Info, Node006, UPDATE_STATE_NODE_INFO_RECEIVED from node 6
2019-05-31 18:29:15.760 Detail, Node006, AdvanceQueries queryPending=0 queryRetries=0 queryStage=Dynamic live=1
2019-05-31 18:29:15.760 Detail, Node006, QueryStage_Dynamic
2019-05-31 18:29:15.760 Detail, Node006, Queuing (Send) SwitchMultilevelCmd_Get (Node=6): 0x01, 0x09, 0x00, 0x13, 0x06, 0x02, 0x26, 0x02, 0x25, 0x97, 0x77
2019-05-31 18:29:15.760 Detail, Node006, Queuing (Query) Query Stage Complete (Dynamic)
2019-05-31 18:29:15.761 Detail, 
2019-05-31 18:29:15.761 Info, Node006, Sending (Send) message (Callback ID=0x97, Expected Reply=0x04) - SwitchMultilevelCmd_Get (Node=6): 0x01, 0x09, 0x00, 0x13, 0x06, 0x02, 0x26, 0x02, 0x25, 0x97, 0x77
2019-05-31 18:29:15.769 Detail, Node006,   Received: 0x01, 0x04, 0x01, 0x13, 0x01, 0xe8
2019-05-31 18:29:15.769 Detail, Node006,   ZW_SEND_DATA delivered to Z-Wave stack
2019-05-31 18:29:15.785 Detail, Node006,   Received: 0x01, 0x07, 0x00, 0x13, 0x97, 0x00, 0x00, 0x02, 0x7e
2019-05-31 18:29:15.785 Detail, Node006,   ZW_SEND_DATA Request with callback ID 0x97 received (expected 0x97)
2019-05-31 18:29:15.785 Info, Node006, Request RTT 24 Average Request RTT 24
2019-05-31 18:29:15.785 Detail,   Expected callbackId was received
2019-05-31 18:29:15.796 Detail, Node006,   Received: 0x01, 0x09, 0x00, 0x04, 0x00, 0x06, 0x03, 0x26, 0x03, 0x07, 0xd5
2019-05-31 18:29:15.797 Detail, 
2019-05-31 18:29:15.797 Info, Node006, Response RTT 35 Average Response RTT 35
2019-05-31 18:29:15.797 Info, Node006, Received SwitchMultiLevel report: level=7
2019-05-31 18:29:15.797 Detail, Node006, Refreshed Value: old value=0, new value=7, type=byte
2019-05-31 18:29:15.797 Detail, Node006, Changes to this value are not verified
2019-05-31 18:29:15.797 Detail, Node006,   Expected reply and command class was received
2019-05-31 18:29:15.797 Detail, Node006,   Message transaction complete
2019-05-31 18:29:15.797 Detail, 
2019-05-31 18:29:15.797 Detail, Node006, Removing current message
2019-05-31 18:29:15.797 Detail, Node006, Notification: ValueChanged
2019-05-31 18:29:15.807 Detail, Node006, Query Stage Complete (Dynamic)
2019-05-31 18:29:15.807 Detail, Node006, AdvanceQueries queryPending=0 queryRetries=0 queryStage=Configuration live=1
2019-05-31 18:29:15.808 Detail, Node006, QueryStage_Configuration
2019-05-31 18:29:15.808 Detail, Node006, QueryStage_Complete
2019-05-31 18:29:15.808 Warning, CheckCompletedNodeQueries m_allNodesQueried=1 m_awakeNodesQueried=1
2019-05-31 18:29:15.808 Detail, Node006, Notification: NodeQueriesComplete
2019-05-31 18:29:16.713 Detail, Node006,   Received: 0x01, 0x09, 0x00, 0x04, 0x00, 0x06, 0x03, 0x26, 0x03, 0x63, 0xb1
2019-05-31 18:29:16.713 Detail, 
2019-05-31 18:29:16.713 Info, Node006, Received SwitchMultiLevel report: level=99
2019-05-31 18:29:16.713 Detail, Node006, Refreshed Value: old value=7, new value=99, type=byte
2019-05-31 18:29:16.713 Detail, Node006, Changes to this value are not verified
2019-05-31 18:29:16.714 Detail, Node006, Notification: ValueChanged
2019-05-31 18:29:21.724 Info, mgr,     Refreshing node 6: COMMAND_CLASS_SWITCH_MULTILEVEL index = 0 instance = 1 (to confirm a reported change)
2019-05-31 18:29:21.724 Detail, Node006, Queuing (Send) SwitchMultilevelCmd_Get (Node=6): 0x01, 0x09, 0x00, 0x13, 0x06, 0x02, 0x26, 0x02, 0x25, 0x98, 0x78
2019-05-31 18:29:21.724 Detail, 
2019-05-31 18:29:21.724 Info, Node006, Sending (Send) message (Callback ID=0x98, Expected Reply=0x04) - SwitchMultilevelCmd_Get (Node=6): 0x01, 0x09, 0x00, 0x13, 0x06, 0x02, 0x26, 0x02, 0x25, 0x98, 0x78
2019-05-31 18:29:21.733 Detail, Node006,   Received: 0x01, 0x04, 0x01, 0x13, 0x01, 0xe8
2019-05-31 18:29:21.733 Detail, Node006,   ZW_SEND_DATA delivered to Z-Wave stack
2019-05-31 18:29:21.749 Detail, Node006,   Received: 0x01, 0x07, 0x00, 0x13, 0x98, 0x00, 0x00, 0x02, 0x71
2019-05-31 18:29:21.750 Detail, Node006,   ZW_SEND_DATA Request with callback ID 0x98 received (expected 0x98)
2019-05-31 18:29:21.750 Info, Node006, Request RTT 24 Average Request RTT 24
2019-05-31 18:29:21.750 Detail,   Expected callbackId was received
2019-05-31 18:29:21.760 Detail, Node006,   Received: 0x01, 0x09, 0x00, 0x04, 0x00, 0x06, 0x03, 0x26, 0x03, 0x63, 0xb1
2019-05-31 18:29:21.760 Detail, 
2019-05-31 18:29:21.760 Info, Node006, Response RTT 35 Average Response RTT 35
2019-05-31 18:29:21.760 Info, Node006, Received SwitchMultiLevel report: level=99
2019-05-31 18:29:21.760 Detail, Node006, Refreshed Value: old value=99, new value=99, type=byte
2019-05-31 18:29:21.760 Detail, Node006, Changes to this value are not verified
2019-05-31 18:29:21.760 Detail, Node006,   Expected reply and command class was received
2019-05-31 18:29:21.760 Detail, Node006,   Message transaction complete
2019-05-31 18:29:21.760 Detail, 
2019-05-31 18:29:21.760 Detail, Node006, Removing current message
2019-05-31 18:29:21.761 Detail, Node006, Notification: ValueChanged