Switch state too slow

[stevemann (Stephen Mann (YAML-challenged))]

I just installed an Aeotec Nano Z-Wave Switch. Works fine but the state reply is slow. The switch on Home Assistant gives up before receiving the state from the switch. Which looks like it takes sometimes up to ten seconds. (I am watching the state node in node red). In Home Assistant, I turn the switch on and the light controlled by the Nano turns on almost immediately. But since Home Assistant doesn’t see the state, it turns the switch off.

Can this state reply timeout be increase, or is there a way to get the Aeotec Nano Z-Wave switch to return its state faster? (I don’t have this problem with any of my Inovelli or GE Z-Wave devices).

[tom_l]

I was going to purchase some of these. 10 seconds is ages. 3 seconds is barely acceptable.

If you Tail the OZW log (zwave configuration panel), how busy is your zwave network?

What is your zwave mesh like?

What is your CPU load like and what are you running HA on?

[stevemann (Stephen Mann (YAML-challenged))]

@tom_l

I was going to purchase some of these. 10 seconds is ages. 3 seconds is barely acceptable.

If you Tail the OZW log (zwave configuration panel), how busy is your zwave network?

What is your zwave mesh like?

What is your CPU load like and what are you running HA on?

Ineresting questions

Ten seconds was the worst case and I was monitoring the state change on Node-Red, so there is some overhead in the path.

Here is the tail of my Z-Wave log. In this case I turned the light (Nano Switch) on from the Home Assistant screen. The light turned on almost instantly, but about two seconds later, the switch on the screen turned off, as though Home Assistant had not received the state quick enough. If you see something significant in this log, please tell me what I am missing. (Understanding the log files is slightly above my pay grade).

2018-09-27 10:10:55.374 Info, Node009, Value::Set - COMMAND_CLASS_SWITCH_BINARY - Switch - 0 - 1 - True
2018-09-27 10:10:55.374 Info, Node009, SwitchBinary::Set - Setting node 9 to On
2018-09-27 10:10:55.374 Detail, Node009, Queuing (Send) SwitchBinaryCmd_Set (Node=9): 0x01, 0x0a, 0x00, 0x13, 0x09, 0x03, 0x25, 0x01, 0xff, 0x25, 0x4e, 0x5c
2018-09-27 10:10:55.375 Detail, Node009, Queuing (Send) SwitchBinaryCmd_Get (Node=9): 0x01, 0x09, 0x00, 0x13, 0x09, 0x02, 0x25, 0x02, 0x25, 0x4f, 0xa3
2018-09-27 10:10:55.375 Detail,
2018-09-27 10:10:55.375 Info, Node009, Sending (Send) message (Callback ID=0x4e, Expected Reply=0x13) - SwitchBinaryCmd_Set (Node=9): 0x01, 0x0a, 0x00, 0x13, 0x09, 0x03, 0x25, 0x01, 0xff, 0x25, 0x4e, 0x5c
2018-09-27 10:10:55.384 Detail, Node009,   Received: 0x01, 0x04, 0x01, 0x13, 0x01, 0xe8
2018-09-27 10:10:55.384 Detail, Node009,   ZW_SEND_DATA delivered to Z-Wave stack
2018-09-27 10:10:55.401 Detail, Node009,   Received: 0x01, 0x07, 0x00, 0x13, 0x4e, 0x00, 0x00, 0x02, 0xa7
2018-09-27 10:10:55.401 Detail, Node009,   ZW_SEND_DATA Request with callback ID 0x4e received (expected 0x4e)
2018-09-27 10:10:55.401 Info, Node009, Request RTT 24 Average Request RTT 25
2018-09-27 10:10:55.401 Detail,   Expected callbackId was received
2018-09-27 10:10:55.401 Detail,   Expected reply was received
2018-09-27 10:10:55.401 Detail,   Message transaction complete
2018-09-27 10:10:55.401 Detail,
2018-09-27 10:10:55.402 Detail, Node009, Removing current message
2018-09-27 10:10:55.402 Detail,
2018-09-27 10:10:55.402 Info, Node009, Sending (Send) message (Callback ID=0x4f, Expected Reply=0x04) - SwitchBinaryCmd_Get (Node=9): 0x01, 0x09, 0x00, 0x13, 0x09, 0x02, 0x25, 0x02, 0x25, 0x4f, 0xa3
2018-09-27 10:10:55.412 Detail, Node009,   Received: 0x01, 0x04, 0x01, 0x13, 0x01, 0xe8
2018-09-27 10:10:55.412 Detail, Node009,   ZW_SEND_DATA delivered to Z-Wave stack
2018-09-27 10:10:55.428 Detail, Node009,   Received: 0x01, 0x07, 0x00, 0x13, 0x4f, 0x00, 0x00, 0x02, 0xa6
2018-09-27 10:10:55.428 Detail, Node009,   ZW_SEND_DATA Request with callback ID 0x4f received (expected 0x4f)
2018-09-27 10:10:55.429 Info, Node009, Request RTT 26 Average Request RTT 25
2018-09-27 10:10:55.429 Detail,   Expected callbackId was received
2018-09-27 10:10:55.437 Detail, Node009,   Received: 0x01, 0x09, 0x00, 0x04, 0x00, 0x09, 0x03, 0x25, 0x03, 0x00, 0xde
2018-09-27 10:10:55.438 Detail,
2018-09-27 10:10:55.438 Info, Node009, Response RTT 35 Average Response RTT 36
2018-09-27 10:10:55.438 Info, Node009, Received SwitchBinary report from node 9: level=Off
2018-09-27 10:10:55.438 Detail, Node009, Refreshed Value: old value=false, new value=false, type=bool
2018-09-27 10:10:55.438 Detail, Node009, Changes to this value are not verified
2018-09-27 10:10:55.438 Detail, Node009,   Expected reply and command class was received
2018-09-27 10:10:55.438 Detail, Node009,   Message transaction complete
2018-09-27 10:10:55.438 Detail,
2018-09-27 10:10:55.438 Detail, Node009, Removing current message
2018-09-27 10:10:55.438 Detail, Node009, Notification: ValueChanged

Z-Wave mesh- that’s a cool tool, thanks for the link.
Here’s what it looks like:

I don’t know what the failed node is- all of my Z-Wave devices are working. I suspect that Node 7 may be one of my desktop setups that got moved and renamed. I need to figure out how to remove it.

As you can see from the mesh image, the Aeotec Nano Switch is a direct hop to the Hub (an Aeotec Z-wave Stick). It’s literally ten feet away, so a weak signal is not an issue.

On your last question, I am running Home Assistant 0.72.1 on a Raspberry Pi3. Here’s a snapshot of the CPU load and programs running.

Here is a video that helps explain the problem I observed:
https://vimeo.com/292144829

[Crhass]

Does this still happen if you restart your pi? I have experienced the same issue with switches moving back and forth, getting slower the longer the pi has been running. A restart speeds it up for several days, then it gets slower again?

[tom_l]

There is an option to remove failed nodes in the zwave configuration panel.

You are getting excellent RTT (round trip times) to the switch node and your cpu is not overtaxed. So no problems there.

Your video was illuminating (pun intended).

You set the switch on using the tablet. The light turns on. Then the front-end switch returns to the off state but before waiting for the status to update to the correct state you hit the switch on the tablet again. And things get messy from there with multiple queued messages going back and forth.
The video did not demonstrate the behaviour you posted about initially though. What happens if you turn on the switch in the front end and wait? A OZW log of this would be handy too.

[stevemann (Stephen Mann (YAML-challenged))]

@tom_l

Then the front-end switch returns to the off state but before waiting for the status to update to the correct state you hit the switch on the tablet again.

@tom_l

What happens if you turn on the switch in the front end and wait? A OZW log of this would be handy too.

OK, I’m used to my switches responding really fast, but I did wait. I turned the light on then played a game of solitaire. As you said, the front-end switch was on.

Here’s the log from that action:

2018-09-27 22:39:22.438 Detail, Node009,   Received: 0x01, 0x08, 0x00, 0x04, 0x00, 0x09, 0x02, 0x82, 0x01, 0x7b
2018-09-27 22:39:22.438 Detail,
2018-09-27 22:39:22.438 Info, Node009, Received Hail command from node 9
2018-09-27 22:39:22.438 Detail, Node009, Queuing (Send) SwitchBinaryCmd_Get (Node=9): 0x01, 0x09, 0x00, 0x13, 0x09, 0x02, 0x25, 0x02, 0x25, 0x0c, 0xe0
2018-09-27 22:39:22.438 Detail, Node009, Queuing (Send) AlarmCmd_Get (Node=9): 0x01, 0x0c, 0x00, 0x13, 0x09, 0x05, 0x71, 0x04, 0x00, 0x04, 0x01, 0x25, 0x0d, 0xb4
2018-09-27 22:39:22.439 Detail, Node009, Queuing (Send) ClockCmd_Get (Node=9): 0x01, 0x09, 0x00, 0x13, 0x09, 0x02, 0x81, 0x05, 0x25, 0x0e, 0x41
2018-09-27 22:39:22.439 Detail,
2018-09-27 22:39:22.439 Info, Node009, Sending (Send) message (Callback ID=0x0c, Expected Reply=0x04) - SwitchBinaryCmd_Get (Node=9): 0x01, 0x09, 0x00, 0x13, 0x09, 0x02, 0x25, 0x02, 0x25, 0x0c, 0xe0
2018-09-27 22:39:22.448 Detail, Node009,   Received: 0x01, 0x04, 0x01, 0x13, 0x01, 0xe8
2018-09-27 22:39:22.448 Detail, Node009,   ZW_SEND_DATA delivered to Z-Wave stack
2018-09-27 22:39:22.463 Detail, Node009,   Received: 0x01, 0x07, 0x00, 0x13, 0x0c, 0x00, 0x00, 0x02, 0xe5
2018-09-27 22:39:22.463 Detail, Node009,   ZW_SEND_DATA Request with callback ID 0x0c received (expected 0x0c)
2018-09-27 22:39:22.469 Info, Node009, Request RTT 29 Average Request RTT 37
2018-09-27 22:39:22.469 Detail,   Expected callbackId was received
2018-09-27 22:39:22.477 Detail, Node009,   Received: 0x01, 0x09, 0x00, 0x04, 0x00, 0x09, 0x03, 0x25, 0x03, 0xff, 0x21
2018-09-27 22:39:22.478 Detail,
2018-09-27 22:39:22.478 Info, Node009, Response RTT 38 Average Response RTT 52
2018-09-27 22:39:22.478 Info, Node009, Received SwitchBinary report from node 9: level=On
2018-09-27 22:39:22.478 Detail, Node009, Refreshed Value: old value=true, new value=true, type=bool
2018-09-27 22:39:22.478 Detail, Node009, Changes to this value are not verified
2018-09-27 22:39:22.479 Detail, Node009,   Expected reply and command class was received
2018-09-27 22:39:22.479 Detail, Node009,   Message transaction complete
2018-09-27 22:39:22.479 Detail,
2018-09-27 22:39:22.479 Detail, Node009, Removing current message
2018-09-27 22:39:22.480 Detail, Node009, Notification: ValueChanged
2018-09-27 22:39:22.496 Detail,
2018-09-27 22:39:22.497 Info, Node009, Sending (Send) message (Callback ID=0x0d, Expected Reply=0x04) - AlarmCmd_Get (Node=9): 0x01, 0x0c, 0x00, 0x13, 0x09, 0x05, 0x71, 0x04, 0x00, 0x04, 0x01, 0x25, 0x0d, 0xb4
2018-09-27 22:39:22.505 Detail, Node009,   Received: 0x01, 0x04, 0x01, 0x13, 0x01, 0xe8
2018-09-27 22:39:22.505 Detail, Node009,   ZW_SEND_DATA delivered to Z-Wave stack
2018-09-27 22:39:22.522 Detail, Node009,   Received: 0x01, 0x07, 0x00, 0x13, 0x0d, 0x00, 0x00, 0x02, 0xe4
2018-09-27 22:39:22.522 Detail, Node009,   ZW_SEND_DATA Request with callback ID 0x0d received (expected 0x0d)
2018-09-27 22:39:22.522 Info, Node009, Request RTT 25 Average Request RTT 31
2018-09-27 22:39:22.522 Detail,   Expected callbackId was received
2018-09-27 22:39:22.538 Detail, Node009,   Received: 0x01, 0x10, 0x00, 0x04, 0x00, 0x09, 0x0a, 0x71, 0x05, 0x00, 0x00, 0x00, 0xff, 0x04, 0xfe, 0x00, 0x00, 0x99
2018-09-27 22:39:22.539 Detail,
2018-09-27 22:39:22.539 Info, Node009, Response RTT 41 Average Response RTT 46
2018-09-27 22:39:22.539 Info, Node009, Received Alarm report: type=0, level=0, sensorSrcID=0, type:Heat event:254, status=255
2018-09-27 22:39:22.539 Detail, Node009, Refreshed Value: old value=0, new value=0, type=byte
2018-09-27 22:39:22.540 Detail, Node009, Changes to this value are not verified
2018-09-27 22:39:22.540 Detail, Node009, Refreshed Value: old value=0, new value=0, type=byte
2018-09-27 22:39:22.540 Detail, Node009, Changes to this value are not verified
2018-09-27 22:39:22.540 Detail, Node009, Refreshed Value: old value=0, new value=0, type=byte
2018-09-27 22:39:22.540 Detail, Node009, Changes to this value are not verified
2018-09-27 22:39:22.541 Detail, Node009, Refreshed Value: old value=254, new value=254, type=byte
2018-09-27 22:39:22.541 Detail, Node009, Changes to this value are not verified
2018-09-27 22:39:22.541 Detail, Node009,   Expected reply and command class was received
2018-09-27 22:39:22.541 Detail, Node009,   Message transaction complete
2018-09-27 22:39:22.541 Detail,
2018-09-27 22:39:22.541 Detail, Node009, Removing current message
2018-09-27 22:39:22.542 Detail, Node009, Notification: ValueChanged
2018-09-27 22:39:22.555 Detail, Node009, Notification: ValueChanged
2018-09-27 22:39:22.569 Detail, Node009, Notification: ValueChanged
2018-09-27 22:39:22.582 Detail, Node009, Notification: ValueChanged
2018-09-27 22:39:22.597 Detail,
2018-09-27 22:39:22.598 Info, Node009, Sending (Send) message (Callback ID=0x0e, Expected Reply=0x04) - ClockCmd_Get (Node=9): 0x01, 0x09, 0x00, 0x13, 0x09, 0x02, 0x81, 0x05, 0x25, 0x0e, 0x41
2018-09-27 22:39:22.606 Detail, Node009,   Received: 0x01, 0x04, 0x01, 0x13, 0x01, 0xe8
2018-09-27 22:39:22.607 Detail, Node009,   ZW_SEND_DATA delivered to Z-Wave stack
2018-09-27 22:39:22.623 Detail, Node009,   Received: 0x01, 0x07, 0x00, 0x13, 0x0e, 0x00, 0x00, 0x02, 0xe7
2018-09-27 22:39:22.623 Detail, Node009,   ZW_SEND_DATA Request with callback ID 0x0e received (expected 0x0e)
2018-09-27 22:39:22.624 Info, Node009, Request RTT 26 Average Request RTT 28
2018-09-27 22:39:22.625 Detail,   Expected callbackId was received
2018-09-27 22:39:22.638 Detail, Node009,   Received: 0x01, 0x0a, 0x00, 0x04, 0x00, 0x09, 0x04, 0x81, 0x06, 0x07, 0x17, 0x6b
2018-09-27 22:39:22.639 Detail,
2018-09-27 22:39:22.640 Info, Node009, Response RTT 41 Average Response RTT 43
2018-09-27 22:39:22.640 Info, Node009, Received Clock report: Invalid 07:23
2018-09-27 22:39:22.642 Detail, Node009, Refreshed Value: old value=7, new value=7, type=byte
2018-09-27 22:39:22.643 Detail, Node009, Changes to this value are not verified
2018-09-27 22:39:22.643 Detail, Node009, Refreshed Value: old value=19, new value=23, type=byte
2018-09-27 22:39:22.643 Detail, Node009, Changes to this value are not verified
2018-09-27 22:39:22.643 Detail, Node009,   Expected reply and command class was received
2018-09-27 22:39:22.644 Detail, Node009,   Message transaction complete
2018-09-27 22:39:22.644 Detail,
2018-09-27 22:39:22.645 Detail, Node009, Removing current message
2018-09-27 22:39:22.645 Detail, Node009, Notification: ValueChanged
2018-09-27 22:39:22.670 Detail, Node009, Notification: ValueChanged
2018-09-27 22:43:38.439 Detail, Node009,   Received: 0x01, 0x08, 0x00, 0x04, 0x00, 0x09, 0x02, 0x82, 0x01, 0x7b
2018-09-27 22:43:38.439 Detail,
2018-09-27 22:43:38.439 Info, Node009, Received Hail command from node 9
2018-09-27 22:43:38.439 Detail, Node009, Queuing (Send) SwitchBinaryCmd_Get (Node=9): 0x01, 0x09, 0x00, 0x13, 0x09, 0x02, 0x25, 0x02, 0x25, 0x0f, 0xe3
2018-09-27 22:43:38.439 Detail, Node009, Queuing (Send) AlarmCmd_Get (Node=9): 0x01, 0x0c, 0x00, 0x13, 0x09, 0x05, 0x71, 0x04, 0x00, 0x04, 0x01, 0x25, 0x10, 0xa9
2018-09-27 22:43:38.439 Detail, Node009, Queuing (Send) ClockCmd_Get (Node=9): 0x01, 0x09, 0x00, 0x13, 0x09, 0x02, 0x81, 0x05, 0x25, 0x11, 0x5e
2018-09-27 22:43:38.439 Detail,
2018-09-27 22:43:38.439 Info, Node009, Sending (Send) message (Callback ID=0x0f, Expected Reply=0x04) - SwitchBinaryCmd_Get (Node=9): 0x01, 0x09, 0x00, 0x13, 0x09, 0x02, 0x25, 0x02, 0x25, 0x0f, 0xe3
2018-09-27 22:43:38.448 Detail, Node009,   Received: 0x01, 0x04, 0x01, 0x13, 0x01, 0xe8
2018-09-27 22:43:38.448 Detail, Node009,   ZW_SEND_DATA delivered to Z-Wave stack
2018-09-27 22:43:38.464 Detail, Node009,   Received: 0x01, 0x07, 0x00, 0x13, 0x0f, 0x00, 0x00, 0x02, 0xe6
2018-09-27 22:43:38.464 Detail, Node009,   ZW_SEND_DATA Request with callback ID 0x0f received (expected 0x0f)
2018-09-27 22:43:38.464 Info, Node009, Request RTT 24 Average Request RTT 26
2018-09-27 22:43:38.464 Detail,   Expected callbackId was received
2018-09-27 22:43:38.478 Detail, Node009,   Received: 0x01, 0x09, 0x00, 0x04, 0x00, 0x09, 0x03, 0x25, 0x03, 0xff, 0x21
2018-09-27 22:43:38.479 Detail,
2018-09-27 22:43:38.479 Info, Node009, Response RTT 39 Average Response RTT 41
2018-09-27 22:43:38.479 Info, Node009, Received SwitchBinary report from node 9: level=On
2018-09-27 22:43:38.479 Detail, Node009, Refreshed Value: old value=true, new value=true, type=bool
2018-09-27 22:43:38.480 Detail, Node009, Changes to this value are not verified
2018-09-27 22:43:38.480 Detail, Node009,   Expected reply and command class was received
2018-09-27 22:43:38.480 Detail, Node009,   Message transaction complete
2018-09-27 22:43:38.480 Detail,
2018-09-27 22:43:38.480 Detail, Node009, Removing current message
2018-09-27 22:43:38.480 Detail, Node009, Notification: ValueChanged
2018-09-27 22:43:38.498 Detail,
2018-09-27 22:43:38.498 Info, Node009, Sending (Send) message (Callback ID=0x10, Expected Reply=0x04) - AlarmCmd_Get (Node=9): 0x01, 0x0c, 0x00, 0x13, 0x09, 0x05, 0x71, 0x04, 0x00, 0x04, 0x01, 0x25, 0x10, 0xa9
2018-09-27 22:43:38.506 Detail, Node009,   Received: 0x01, 0x04, 0x01, 0x13, 0x01, 0xe8
2018-09-27 22:43:38.506 Detail, Node009,   ZW_SEND_DATA delivered to Z-Wave stack
2018-09-27 22:43:38.522 Detail, Node009,   Received: 0x01, 0x07, 0x00, 0x13, 0x10, 0x00, 0x00, 0x02, 0xf9
2018-09-27 22:43:38.523 Detail, Node009,   ZW_SEND_DATA Request with callback ID 0x10 received (expected 0x10)
2018-09-27 22:43:38.523 Info, Node009, Request RTT 24 Average Request RTT 25
2018-09-27 22:43:38.523 Detail,   Expected callbackId was received
2018-09-27 22:43:38.535 Detail, Node009,   Received: 0x01, 0x10, 0x00, 0x04, 0x00, 0x09, 0x0a, 0x71, 0x05, 0x00, 0x00, 0x00, 0xff, 0x04, 0xfe, 0x00, 0x00, 0x99
2018-09-27 22:43:38.535 Detail,
2018-09-27 22:43:38.535 Info, Node009, Response RTT 37 Average Response RTT 39
2018-09-27 22:43:38.535 Info, Node009, Received Alarm report: type=0, level=0, sensorSrcID=0, type:Heat event:254, status=255
2018-09-27 22:43:38.535 Detail, Node009, Refreshed Value: old value=0, new value=0, type=byte
2018-09-27 22:43:38.535 Detail, Node009, Changes to this value are not verified
2018-09-27 22:43:38.535 Detail, Node009, Refreshed Value: old value=0, new value=0, type=byte
2018-09-27 22:43:38.535 Detail, Node009, Changes to this value are not verified
2018-09-27 22:43:38.535 Detail, Node009, Refreshed Value: old value=0, new value=0, type=byte
2018-09-27 22:43:38.535 Detail, Node009, Changes to this value are not verified
2018-09-27 22:43:38.535 Detail, Node009, Refreshed Value: old value=254, new value=254, type=byte
2018-09-27 22:43:38.535 Detail, Node009, Changes to this value are not verified
2018-09-27 22:43:38.535 Detail, Node009,   Expected reply and command class was received
2018-09-27 22:43:38.535 Detail, Node009,   Message transaction complete
2018-09-27 22:43:38.535 Detail,
2018-09-27 22:43:38.535 Detail, Node009, Removing current message
2018-09-27 22:43:38.536 Detail, Node009, Notification: ValueChanged
2018-09-27 22:43:38.543 Detail, Node009, Notification: ValueChanged
2018-09-27 22:43:38.550 Detail, Node009, Notification: ValueChanged
2018-09-27 22:43:38.557 Detail, Node009, Notification: ValueChanged
2018-09-27 22:43:38.564 Detail,
2018-09-27 22:43:38.564 Info, Node009, Sending (Send) message (Callback ID=0x11, Expected Reply=0x04) - ClockCmd_Get (Node=9): 0x01, 0x09, 0x00, 0x13, 0x09, 0x02, 0x81, 0x05, 0x25, 0x11, 0x5e
2018-09-27 22:43:38.573 Detail, Node009,   Received: 0x01, 0x04, 0x01, 0x13, 0x01, 0xe8
2018-09-27 22:43:38.573 Detail, Node009,   ZW_SEND_DATA delivered to Z-Wave stack
2018-09-27 22:43:38.589 Detail, Node009,   Received: 0x01, 0x07, 0x00, 0x13, 0x11, 0x00, 0x00, 0x03, 0xf9
2018-09-27 22:43:38.589 Detail, Node009,   ZW_SEND_DATA Request with callback ID 0x11 received (expected 0x11)
2018-09-27 22:43:38.589 Info, Node009, Request RTT 24 Average Request RTT 24
2018-09-27 22:43:38.589 Detail,   Expected callbackId was received
2018-09-27 22:43:38.601 Detail, Node009,   Received: 0x01, 0x0a, 0x00, 0x04, 0x00, 0x09, 0x04, 0x81, 0x06, 0x07, 0x1b, 0x67
2018-09-27 22:43:38.601 Detail,
2018-09-27 22:43:38.601 Info, Node009, Response RTT 36 Average Response RTT 37
2018-09-27 22:43:38.601 Info, Node009, Received Clock report: Invalid 07:27
2018-09-27 22:43:38.601 Detail, Node009, Refreshed Value: old value=7, new value=7, type=byte
2018-09-27 22:43:38.601 Detail, Node009, Changes to this value are not verified
2018-09-27 22:43:38.601 Detail, Node009, Refreshed Value: old value=23, new value=27, type=byte
2018-09-27 22:43:38.601 Detail, Node009, Changes to this value are not verified
2018-09-27 22:43:38.601 Detail, Node009,   Expected reply and command class was received
2018-09-27 22:43:38.601 Detail, Node009,   Message transaction complete
2018-09-27 22:43:38.601 Detail,
2018-09-27 22:43:38.601 Detail, Node009, Removing current message
2018-09-27 22:43:38.602 Detail, Node009, Notification: ValueChanged
2018-09-27 22:43:38.610 Detail, Node009, Notification: ValueChanged

I see a big time gap around lines 75-76 (15-seconds). Is this where the switch on the front-end changes?

I tried waiting a few more times and the front-end switch does eventually catch up with the Nano state. I guess there’s nothing I can do about it.

Where can I learn more about reading the OZW log file? Is there a way to use the OZW Utilities Log analyzer with my log file?

[tom_l]

@stevemann

I tried waiting a few more times and the front-end switch does eventually catch up with the Nano state. I guess there’s nothing I can do about it.

It really shouldn’t take that long. I thought it might be because the nano does not support the hail command class but I see hail messages in your log,

@stevemann

Where can I learn more about reading the OZW log file? Is there a way to use the OZW Utilities Log analyzer with my log file?

I don’t know but if you find out let me know. I’m just learning this too.

I’ll get a nano in a week or so (probably the dimmer version though) and will let you know how it performs.

[stevemann (Stephen Mann (YAML-challenged))]

@tom_l

I’ll get a nano in a week or so

One more issue I noticed after installing the Nano into the wall box.

If I turn the light on via Z-Wave (Home Assistant front-end), I can’t turn it off at the external switch by simply toggling the switch. I have to turn the external switch on then off again, then the light goes off. It worked on the bench testing, but not when installed. I am wondering if the switch mode somehow changed during the installation.

[tom_l]

You can check the parameter values in the zwave control panel.

Also try the advice in the first reply to this reddit post: https://www.reddit.com/r/homeautomation/comments/6cb70j/aeotec_nano_dimmer_not_working_via_switch/ not sure if it only applies to the dimmer version though.

[stevemann (Stephen Mann (YAML-challenged))]

Thanks. I’ve never looked at that tool before.
I changed Parameter 80 from Hail CC to Basic per the notes in the Reddit post. This appears to have fixed the state reporting issue at the top of this thread. It appears to have fixed the slow reporting because in my brief testing this morning the original problem has not recurred.

I did not find this information before because I didn’t know what to search for. But I have discovered this post:

Setting parameter 80 to basic reports is probably best. Hail CC floods the z-wave network with reports on every little change and can cause communication issues.
Hail = device notifies hub that something happened, hub polls, device gives status
Basic = device sends status

On the new problem, I checked Parameter 120, the switch type. It was correctly set as a 2-state switch (on/off). I set the parameter to “Automatic Detection”, then flipped the external switch. This reset the parameter back to 2-state switch. But the problem remains that if I turn on the light over Z-Wave, flipping the external switch does not turn it off. Turning the external switch on then off does turn the light off, so it’s just a minor nuisance

Again, thanks for nudging me into using the tool on Home Assistant.
.

[tom_l]

I have no idea how you check which firmware your nano switch has but if it’s less than 2.01 there’s a firmware update that looks like it will fix this:

For the one with energy monitoring:

(ZW116 - V3.00) How to update Nano Switch with energy reading Z-Wave firmware.

Without energy monitoring:

(ZW139) How to update Nano Switch Z-Wave firmware.

Make sure you get the right one!

Read and follow the instructions carefully. Make sure you remove the device from HA first.

[abmantis]

Have you ever found a fix for the 3 second delay updating state? I’m having this issue with Nano Switches with the latest (3.0) firmware.
I’ve already changed the report mode to Basic.