Long delays and switches getting out of sync - zwave

Installation Home Assistant OS
1

Hi all,

I have hass.io running on a NUC with a zstick USB device and 4 z-wave plus TKBhome sockets.

The switches all work, eventually, but they’re too slow for the family to approve and use.

I toggle the switch in my browser, it slides from off to on, then after about half a second back to off. Sometime between 2 and 20 seconds later, the target socket turns on and the switch in the browser goes back to on.

Sometimes the target device and the browser get out of sync with the browser showing an off switch while the device is on.

I’ve spaced the 4 devices around the house and run a heal.

Any ideas what I should be looking at to improve this?

For this solution to be usable, I really need the devices to switch within 1 - 2 seconds of the state being toggled.

Thanks,

2

What’s the physical distance between your controller and the devices? Which zstick specifically are you using?

3

Distance from controller to first socket is 5m horizontal (same floor).

The rest of the devices are on the ground floor, so call it 3m vertical. Second is 4m horizontal. Third is 12m horizontal and 4th is 11m horizontal.

Barriers from controller to 1st device are 3 x stud walls (no reflective coating / insulation on plasterboard). 2nd device is 1 brick wall and one glass window (conservatory roof) or 1 suspended floor and 1 UPVC door. Third is standard suspended floor. 4th is brick wall / window and wooden door (in shed).

Z-Stick is Z-STICK Gen 5 (model ZW090-C)

Thanks,

4

Hmm, do you see the same delays on all devices, or more often on the farther away ones? 5m for the first hop typically isn’t too far, although I’ve had sporadic problems with devices responding promptly when they’re only about 6-7m away (with 2 walls and one floor between) and no other devices exist to hop through.

Can you try temporarily moving one of your plugs closer to the controller, maybe within a couple meters, heal the network and see if that helps?

Also, are you sure the model of plugs you have support z-wave network extension? Most do, but I think some do not.

5

I can second this as well.

The switch delays are not always the same switch in my case, nore are their always delays.
In fact a reboot seems to clear up the issue for a bit.

I have an HUSBZB-1 and roughly 15 Z-wave devices, 11 are switches.
I also have 6 zigbee light bulbs, 6 zigbee motion detectors, and 6 lifx bulbs.

The delay is seen by just about every motion triggered animation, no matter the combination.

I have system monitor setup and it does not seem to be due to high utilization.

6

Should have read this before posting my own thread (Link.

To me it looks like tkb switches do not support polling the status. This is seen as a problem if you send two commands to the same device (e.g. dual switch) within 10 seconds. The latter one will get triggered only after the the status polling timeouts for the first one. In my tests if you send commands from HA to one device every >10 seconds, there are no problems.

anonymouslemming , if you send commands directly after each other to two different devices, are there delays?

7

This happened to me, today. Long, long delays from the moment I touched a light-switch toggle in the GUI and the moment the actual light reacts. … anywhere from >20s to 40s. I must say, I run my Home Assistant instance from a Docker container. Turns out the container had reached its maximum allowed amount of RAM. In my case I allocated 1GB. The problem was to identify the component(s) that were responsible for that behavior. It was the variable component, it’s a custom loaded component which I was playing with since yesterday. In 24 hours it managed to eat up all the RAM allocated for the HA container. As soon as I disabled it, it all came back to normal … normal meaning seating steady around ~650MB … ~700MB for days. Hope this helps somebody sometime.

8

I want to “reopen” this issue since this seems quite general one, at least to me.

I thought that this issue was related only to TKB switches, but now I continued testing of Z-wave and planned to use Telldus Mini switch to control my kitchen tabletop lights (https://products.z-wavealliance.org/products/2892/configs).

I have exactly the same problem with this. the device is able to handle a new command only after 10 seconds and meanwhile the status is incorrect in the web UI. I have no additional settings for zwave in configuration.yaml.

Below is the log from a situation where the device has been switihed on.

2018-08-02 09:38:50.729 Info, Node009, Value::Set - COMMAND_CLASS_SWITCH_BINARY - Switch - 0 - 1 - True
2018-08-02 09:38:50.730 Info, Node009, SwitchBinary::Set - Setting node 9 to On
2018-08-02 09:38:50.731 Detail, Node009, Setting Encryption Flag on Message For Command Class COMMAND_CLASS_SWITCH_BINARY
2018-08-02 09:38:50.731 Detail, Node009, Queuing (Send) SwitchBinaryCmd_Set (Node=9): 0x01, 0x0a, 0x00, 0x13, 0x09, 0x03, 0x25, 0x01, 0xff, 0x25, 0x49, 0x5b
2018-08-02 09:38:50.732 Detail, Node009, Setting Encryption Flag on Message For Command Class COMMAND_CLASS_SWITCH_BINARY
2018-08-02 09:38:50.732 Detail, Node009, Queuing (Send) SwitchBinaryCmd_Get (Node=9): 0x01, 0x09, 0x00, 0x13, 0x09, 0x02, 0x25, 0x02, 0x25, 0x4a, 0xa6
2018-08-02 09:38:50.733 Detail,
2018-08-02 09:38:50.733 Info, Node009, Processing (Send) Nonce Request message (Callback ID=0x49, Expected Reply=0x13)
2018-08-02 09:38:50.734 Info, Node009, Sending (Send) message (Callback ID=0x49, Expected Reply=0x13) - Nonce_Get(SwitchBinaryCmd_Set) - 0x01, 0x09, 0x00, 0x13, 0x09, 0x02, 0x98, 0x40, 0x05, 0x02:
2018-08-02 09:38:50.742 Detail, Node009,   Received: 0x01, 0x04, 0x01, 0x13, 0x01, 0xe8
2018-08-02 09:38:50.742 Detail, Node009,   ZW_SEND_DATA delivered to Z-Wave stack
2018-08-02 09:38:50.758 Detail, Node009,   Received: 0x01, 0x07, 0x00, 0x13, 0x02, 0x00, 0x00, 0x02, 0xeb
2018-08-02 09:38:50.758 Detail, Node009,   ZW_SEND_DATA Request with callback ID 0x02 received (expected 0x02)
2018-08-02 09:38:50.758 Info, Node009, Request RTT 23 Average Request RTT 71
2018-08-02 09:38:50.777 Detail, Node009,   Received: 0x01, 0x10, 0x00, 0x04, 0x00, 0x09, 0x0a, 0x98, 0x80, 0x43, 0xd6, 0x4f, 0xbd, 0x99, 0x7c, 0x68, 0x92, 0x88
2018-08-02 09:38:50.777 Info, Node009, Received SecurityCmd_NonceReport from node 9
2018-08-02 09:38:50.777 Info, Node009, Sending (Send) message (Callback ID=0x4b, Expected Reply=0x13) - SwitchBinaryCmd_Set (Node=9): 0x01, 0x0a, 0x00, 0x13, 0x09, 0x03, 0x25, 0x01, 0xff, 0x25, 0x4b, 0x59
2018-08-02 09:38:50.788 Detail, Node009,   Received: 0x01, 0x04, 0x01, 0x13, 0x01, 0xe8
2018-08-02 09:38:50.789 Detail, Node009,   ZW_SEND_DATA delivered to Z-Wave stack
2018-08-02 09:38:50.806 Detail, Node009,   Received: 0x01, 0x07, 0x00, 0x13, 0x4b, 0x00, 0x00, 0x02, 0xa2
2018-08-02 09:38:50.813 Detail, Node009,   ZW_SEND_DATA Request with callback ID 0x4b received (expected 0x4b)
2018-08-02 09:38:50.813 Info, Node009, Request RTT 78 Average Request RTT 74
2018-08-02 09:38:50.814 Detail,   Expected callbackId was received
2018-08-02 09:38:50.814 Detail,   Expected reply was received
2018-08-02 09:38:50.814 Detail,   Message transaction complete
2018-08-02 09:38:50.814 Detail,
2018-08-02 09:38:50.814 Detail, Node009, Removing current message
2018-08-02 09:38:50.814 Detail,
2018-08-02 09:38:50.814 Info, Node009, Processing (Send) Nonce Request message (Callback ID=0x4a, Expected Reply=0x04)
2018-08-02 09:38:50.814 Info, Node009, Sending (Send) message (Callback ID=0x4a, Expected Reply=0x04) - Nonce_Get(SwitchBinaryCmd_Get) - 0x01, 0x09, 0x00, 0x13, 0x09, 0x02, 0x98, 0x40, 0x05, 0x02:
2018-08-02 09:38:50.821 Detail, Node009,   Received: 0x01, 0x04, 0x01, 0x13, 0x01, 0xe8
2018-08-02 09:38:50.826 Detail, Node009,   ZW_SEND_DATA delivered to Z-Wave stack
2018-08-02 09:38:50.838 Detail, Node009,   Received: 0x01, 0x07, 0x00, 0x13, 0x02, 0x00, 0x00, 0x02, 0xeb
2018-08-02 09:38:50.840 Detail, Node009,   ZW_SEND_DATA Request with callback ID 0x02 received (expected 0x02)
2018-08-02 09:38:50.840 Info, Node009, Request RTT 25 Average Request RTT 49
2018-08-02 09:38:50.855 Detail, Node009,   Received: 0x01, 0x08, 0x00, 0x04, 0x00, 0x09, 0x02, 0x98, 0x40, 0x20
2018-08-02 09:38:50.856 Info, Node009, Received SecurityCmd_NonceGet from node 9
2018-08-02 09:38:50.856 Info, NONCES: 0x25, 0x6f, 0xf4, 0x57, 0x02, 0xd4, 0x38, 0x4c
2018-08-02 09:38:50.856 Info, NONCES: 0xc1, 0x5e, 0x83, 0x8e, 0xa3, 0xa7, 0x4f, 0x7f
2018-08-02 09:38:50.856 Info, NONCES: 0x4d, 0x3a, 0x0a, 0x4e, 0x0e, 0x43, 0x9b, 0xe8
2018-08-02 09:38:50.856 Info, NONCES: 0xf6, 0xda, 0x35, 0xca, 0xeb, 0xd6, 0x3f, 0x02
2018-08-02 09:38:50.856 Info, NONCES: 0xf3, 0x97, 0x21, 0x77, 0xab, 0xa5, 0xce, 0x4d
2018-08-02 09:38:50.856 Info, NONCES: 0x82, 0x1d, 0x9a, 0x87, 0x32, 0x92, 0xe0, 0xe1
2018-08-02 09:38:50.856 Info, NONCES: 0x4b, 0x05, 0x95, 0xbb, 0x44, 0x5b, 0xc1, 0x3a
2018-08-02 09:38:50.856 Info, NONCES: 0x37, 0xf7, 0x05, 0x22, 0xcd, 0x44, 0x24, 0xc1
2018-08-02 09:38:50.856 Info, Node009, Sending (Send) message (Callback ID=0x01, Expected Reply=0x04) - Nonce_Report - 0x01, 0x11, 0x00, 0x13, 0x09, 0x0a, 0x98, 0x80, 0x4d, 0x3a, 0x0a, 0x4e, 0x0e, 0x43, 0x9b, 0xe8, 0x05, 0x01, 0xef:
2018-08-02 09:38:50.864 Detail, Node009,   Received: 0x01, 0x04, 0x01, 0x13, 0x01, 0xe8
2018-08-02 09:38:50.865 Detail, Node009,   ZW_SEND_DATA delivered to Z-Wave stack
2018-08-02 09:38:50.874 Detail, Node009,   Received: 0x01, 0x10, 0x00, 0x04, 0x00, 0x09, 0x0a, 0x98, 0x80, 0xf4, 0xf1, 0x58, 0xd7, 0xe3, 0x47, 0x54, 0x16, 0x9c
2018-08-02 09:38:50.874 Info, Node009, Received SecurityCmd_NonceReport from node 9
2018-08-02 09:38:50.875 Info, Node009, Sending (Send) message (Callback ID=0x4c, Expected Reply=0x04) - SwitchBinaryCmd_Get (Node=9): 0x01, 0x09, 0x00, 0x13, 0x09, 0x02, 0x25, 0x02, 0x25, 0x4c, 0xa0
2018-08-02 09:38:50.888 Detail, Node009,   Received: 0x01, 0x04, 0x01, 0x13, 0x01, 0xe8
2018-08-02 09:38:50.888 Detail, Node009,   ZW_SEND_DATA delivered to Z-Wave stack
2018-08-02 09:38:50.903 Detail, Node009,   Received: 0x01, 0x07, 0x00, 0x13, 0x4c, 0x00, 0x00, 0x02, 0xa5
2018-08-02 09:38:50.905 Detail, Node009,   ZW_SEND_DATA Request with callback ID 0x4c received (expected 0x4c)
2018-08-02 09:38:50.906 Info, Node009, Request RTT 91 Average Request RTT 70
2018-08-02 09:38:50.906 Detail,   Expected callbackId was received
2018-08-02 09:38:50.989 Detail, Node009,   Received: 0x01, 0x07, 0x00, 0x13, 0x4c, 0x00, 0x00, 0x0b, 0xac
2018-08-02 09:38:50.990 Detail, Node009,   ZW_SEND_DATA Request with callback ID 0x4c received (expected 0x00)
2018-08-02 09:38:50.991 Warning, Node009, WARNING: Unexpected Callback ID received
2018-08-02 09:38:51.008 Detail, Node009,   Received: 0x01, 0x1d, 0x00, 0x04, 0x00, 0x09, 0x17, 0x98, 0x81, 0x5d, 0x4b, 0xc5, 0xd7, 0xca, 0xed, 0x25, 0x0b, 0x14, 0x82, 0x0b, 0xd0, 0x4d, 0xb2, 0x94, 0xeb, 0x79, 0x89, 0xbf, 0x54, 0x6c, 0x56
2018-08-02 09:38:51.008 Info, Raw: 0x98, 0x81, 0x5d, 0x4b, 0xc5, 0xd7, 0xca, 0xed, 0x25, 0x0b, 0x14, 0x82, 0x0b, 0xd0, 0x4d, 0xb2, 0x94, 0xeb, 0x79, 0x89, 0xbf, 0x54, 0x6c, 0x56
2018-08-02 09:38:51.008 Detail, Node009, Decrypted Packet: 0x00, 0x20, 0x03, 0xff
2018-08-02 09:38:51.009 Detail,
2018-08-02 09:38:51.009 Info, Node009, Response RTT 195 Average Response RTT 400
2018-08-02 09:38:51.009 Info, Node009, Received Basic report from node 9: level=255
2018-08-02 09:38:51.009 Detail, Node009, Setting Encryption Flag on Message For Command Class COMMAND_CLASS_SWITCH_BINARY
2018-08-02 09:38:51.009 Detail, Node009, Queuing (Send) SwitchBinaryCmd_Get (Node=9): 0x01, 0x09, 0x00, 0x13, 0x09, 0x02, 0x25, 0x02, 0x25, 0x4d, 0xa1
2018-08-02 09:38:53.841 Detail, Node009,   Received: 0x01, 0x08, 0x00, 0x04, 0x00, 0x09, 0x02, 0x98, 0x40, 0x20
2018-08-02 09:38:53.841 Info, Node009, Received SecurityCmd_NonceGet from node 9
2018-08-02 09:38:53.842 Info, NONCES: 0x25, 0x6f, 0xf4, 0x57, 0x02, 0xd4, 0x38, 0x4c
2018-08-02 09:38:53.842 Info, NONCES: 0xc1, 0x5e, 0x83, 0x8e, 0xa3, 0xa7, 0x4f, 0x7f
2018-08-02 09:38:53.842 Info, NONCES: 0x4d, 0x3a, 0x0a, 0x4e, 0x0e, 0x43, 0x9b, 0xe8
2018-08-02 09:38:53.842 Info, NONCES: 0xbe, 0x1f, 0xbb, 0x61, 0xc7, 0x0a, 0xe1, 0xb4
2018-08-02 09:38:53.842 Info, NONCES: 0xf3, 0x97, 0x21, 0x77, 0xab, 0xa5, 0xce, 0x4d
2018-08-02 09:38:53.843 Info, NONCES: 0x82, 0x1d, 0x9a, 0x87, 0x32, 0x92, 0xe0, 0xe1
2018-08-02 09:38:53.843 Info, NONCES: 0x4b, 0x05, 0x95, 0xbb, 0x44, 0x5b, 0xc1, 0x3a
2018-08-02 09:38:53.843 Info, NONCES: 0x37, 0xf7, 0x05, 0x22, 0xcd, 0x44, 0x24, 0xc1
2018-08-02 09:38:53.843 Info, Node009, Sending (Send) message (Callback ID=0x01, Expected Reply=0x04) - Nonce_Report - 0x01, 0x11, 0x00, 0x13, 0x09, 0x0a, 0x98, 0x80, 0xbe, 0x1f, 0xbb, 0x61, 0xc7, 0x0a, 0xe1, 0xb4, 0x05, 0x01, 0x01:
2018-08-02 09:38:53.852 Detail, Node009,   Received: 0x01, 0x04, 0x01, 0x13, 0x01, 0xe8
2018-08-02 09:38:53.853 Detail, Node009,   ZW_SEND_DATA delivered to Z-Wave stack
2018-08-02 09:38:53.869 Detail, Node009,   Received: 0x01, 0x07, 0x00, 0x13, 0x01, 0x00, 0x00, 0x02, 0xe8
2018-08-02 09:38:53.869 Detail, Node009,   ZW_SEND_DATA Request with callback ID 0x01 received (expected 0x01)
2018-08-02 09:38:53.869 Info, Node009, Request RTT 3055 Average Request RTT 1562
2018-08-02 09:38:53.894 Detail, Node009,   Received: 0x01, 0x24, 0x00, 0x04, 0x00, 0x09, 0x1e, 0x98, 0x81, 0xb3, 0x20, 0xa6, 0xab, 0x92, 0x68, 0xd3, 0xd3, 0xc7, 0xab, 0x61, 0xd7, 0x28, 0xec, 0xae, 0xbf, 0x22, 0xd4, 0x2d, 0xbe, 0xfe, 0x43, 0xb7, 0x93, 0xfe, 0x24, 0xeb, 0xed, 0x9a
2018-08-02 09:38:53.895 Info, Raw: 0x98, 0x81, 0xb3, 0x20, 0xa6, 0xab, 0x92, 0x68, 0xd3, 0xd3, 0xc7, 0xab, 0x61, 0xd7, 0x28, 0xec, 0xae, 0xbf, 0x22, 0xd4, 0x2d, 0xbe, 0xfe, 0x43, 0xb7, 0x93, 0xfe, 0x24, 0xeb, 0xed, 0x9a
2018-08-02 09:38:53.895 Detail, Node009, Decrypted Packet: 0x00, 0x32, 0x02, 0xa1, 0x6c, 0x00, 0x00, 0x00, 0x13, 0x00, 0x00
2018-08-02 09:38:53.896 Detail,
2018-08-02 09:38:53.896 Info, Node009, Response RTT 3081 Average Response RTT 1740
2018-08-02 09:38:53.896 Detail, Node009, Refreshed Value: old value=false, new value=false, type=bool
2018-08-02 09:38:53.896 Detail, Node009, Changes to this value are not verified
2018-08-02 09:38:53.897 Info, Node009, Received Meter report from node 9: Current=0.019A
2018-08-02 09:38:53.897 Detail, Node009, Refreshed Value: old value=0.000, new value=0.019, type=decimal
2018-08-02 09:38:53.897 Detail, Node009, Changes to this value are not verified
2018-08-02 09:38:53.897 Detail, Node009, Notification: ValueChanged
2018-08-02 09:38:53.923 Detail, Node009, Notification: ValueChanged
2018-08-02 09:38:56.141 Detail, Node009,   Received: 0x01, 0x08, 0x00, 0x04, 0x00, 0x09, 0x02, 0x98, 0x40, 0x20
2018-08-02 09:38:56.142 Info, Node009, Received SecurityCmd_NonceGet from node 9
2018-08-02 09:38:56.142 Info, NONCES: 0x25, 0x6f, 0xf4, 0x57, 0x02, 0xd4, 0x38, 0x4c
2018-08-02 09:38:56.142 Info, NONCES: 0xc1, 0x5e, 0x83, 0x8e, 0xa3, 0xa7, 0x4f, 0x7f
2018-08-02 09:38:56.142 Info, NONCES: 0x4d, 0x3a, 0x0a, 0x4e, 0x0e, 0x43, 0x9b, 0xe8
2018-08-02 09:38:56.143 Info, NONCES: 0xbe, 0x1f, 0xbb, 0x61, 0xc7, 0x0a, 0xe1, 0xb4
2018-08-02 09:38:56.143 Info, NONCES: 0x92, 0xe8, 0x8d, 0x21, 0xc5, 0xd2, 0xd4, 0x12
2018-08-02 09:38:56.143 Info, NONCES: 0x82, 0x1d, 0x9a, 0x87, 0x32, 0x92, 0xe0, 0xe1
2018-08-02 09:38:56.143 Info, NONCES: 0x4b, 0x05, 0x95, 0xbb, 0x44, 0x5b, 0xc1, 0x3a
2018-08-02 09:38:56.143 Info, NONCES: 0x37, 0xf7, 0x05, 0x22, 0xcd, 0x44, 0x24, 0xc1
2018-08-02 09:38:56.144 Info, Node009, Sending (Send) message (Callback ID=0x01, Expected Reply=0x04) - Nonce_Report - 0x01, 0x11, 0x00, 0x13, 0x09, 0x0a, 0x98, 0x80, 0x92, 0xe8, 0x8d, 0x21, 0xc5, 0xd2, 0xd4, 0x12, 0x05, 0x01, 0xe5:
2018-08-02 09:38:56.152 Detail, Node009,   Received: 0x01, 0x04, 0x01, 0x13, 0x01, 0xe8
2018-08-02 09:38:56.153 Detail, Node009,   ZW_SEND_DATA delivered to Z-Wave stack
2018-08-02 09:38:56.169 Detail, Node009,   Received: 0x01, 0x07, 0x00, 0x13, 0x01, 0x00, 0x00, 0x02, 0xe8
2018-08-02 09:38:56.184 Detail, Node009,   ZW_SEND_DATA Request with callback ID 0x01 received (expected 0x01)
2018-08-02 09:38:56.184 Info, Node009, Request RTT 5370 Average Request RTT 3466
2018-08-02 09:38:56.194 Detail, Node009,   Received: 0x01, 0x24, 0x00, 0x04, 0x00, 0x09, 0x1e, 0x98, 0x81, 0x57, 0x9c, 0x46, 0xf7, 0xa8, 0x8c, 0x9f, 0xfb, 0x3c, 0x5b, 0xca, 0xac, 0xa4, 0x0d, 0xf0, 0x88, 0x61, 0x41, 0xb7, 0x92, 0xd0, 0x36, 0x56, 0xad, 0xe7, 0x8a, 0xe7, 0xc0, 0x69
2018-08-02 09:38:56.197 Info, Raw: 0x98, 0x81, 0x57, 0x9c, 0x46, 0xf7, 0xa8, 0x8c, 0x9f, 0xfb, 0x3c, 0x5b, 0xca, 0xac, 0xa4, 0x0d, 0xf0, 0x88, 0x61, 0x41, 0xb7, 0x92, 0xd0, 0x36, 0x56, 0xad, 0xe7, 0x8a, 0xe7, 0xc0, 0x69
2018-08-02 09:38:56.197 Detail, Node009, Decrypted Packet: 0x00, 0x32, 0x02, 0xa1, 0x64, 0x00, 0x03, 0x99, 0xe7, 0x00, 0x00
2018-08-02 09:38:56.197 Detail,
2018-08-02 09:38:56.197 Info, Node009, Response RTT 5383 Average Response RTT 3561
2018-08-02 09:38:56.197 Detail, Node009, Refreshed Value: old value=false, new value=false, type=bool
2018-08-02 09:38:56.198 Detail, Node009, Changes to this value are not verified
2018-08-02 09:38:56.198 Info, Node009, Received Meter report from node 9: Voltage=236.007V
2018-08-02 09:38:56.198 Detail, Node009, Refreshed Value: old value=236.007, new value=236.007, type=decimal
2018-08-02 09:38:56.198 Detail, Node009, Changes to this value are not verified
2018-08-02 09:38:56.198 Detail, Node009, Notification: ValueChanged
2018-08-02 09:38:56.231 Detail, Node009, Notification: ValueChanged
2018-08-02 09:38:56.252 Detail, Node009,   Received: 0x01, 0x08, 0x00, 0x04, 0x00, 0x09, 0x02, 0x98, 0x40, 0x20
2018-08-02 09:38:56.252 Info, Node009, Received SecurityCmd_NonceGet from node 9
2018-08-02 09:38:56.253 Info, NONCES: 0x25, 0x6f, 0xf4, 0x57, 0x02, 0xd4, 0x38, 0x4c
2018-08-02 09:38:56.253 Info, NONCES: 0xc1, 0x5e, 0x83, 0x8e, 0xa3, 0xa7, 0x4f, 0x7f
2018-08-02 09:38:56.254 Info, NONCES: 0x4d, 0x3a, 0x0a, 0x4e, 0x0e, 0x43, 0x9b, 0xe8
2018-08-02 09:38:56.254 Info, NONCES: 0xbe, 0x1f, 0xbb, 0x61, 0xc7, 0x0a, 0xe1, 0xb4
2018-08-02 09:38:56.254 Info, NONCES: 0x92, 0xe8, 0x8d, 0x21, 0xc5, 0xd2, 0xd4, 0x12
2018-08-02 09:38:56.255 Info, NONCES: 0x0d, 0xdf, 0x60, 0x1b, 0x22, 0xfb, 0x04, 0x34
2018-08-02 09:38:56.255 Info, NONCES: 0x4b, 0x05, 0x95, 0xbb, 0x44, 0x5b, 0xc1, 0x3a
2018-08-02 09:38:56.256 Info, NONCES: 0x37, 0xf7, 0x05, 0x22, 0xcd, 0x44, 0x24, 0xc1
2018-08-02 09:38:56.256 Info, Node009, Sending (Send) message (Callback ID=0x01, Expected Reply=0x04) - Nonce_Report - 0x01, 0x11, 0x00, 0x13, 0x09, 0x0a, 0x98, 0x80, 0x0d, 0xdf, 0x60, 0x1b, 0x22, 0xfb, 0x04, 0x34, 0x05, 0x01, 0xa2:
2018-08-02 09:38:56.265 Detail, Node009,   Received: 0x01, 0x04, 0x01, 0x13, 0x01, 0xe8
2018-08-02 09:38:56.265 Detail, Node009,   ZW_SEND_DATA delivered to Z-Wave stack
2018-08-02 09:38:56.281 Detail, Node009,   Received: 0x01, 0x07, 0x00, 0x13, 0x01, 0x00, 0x00, 0x02, 0xe8
2018-08-02 09:38:56.282 Detail, Node009,   ZW_SEND_DATA Request with callback ID 0x01 received (expected 0x01)
2018-08-02 09:38:56.282 Info, Node009, Request RTT 5468 Average Request RTT 4467
2018-08-02 09:38:56.307 Detail, Node009,   Received: 0x01, 0x24, 0x00, 0x04, 0x00, 0x09, 0x1e, 0x98, 0x81, 0x20, 0xaa, 0x33, 0xad, 0x12, 0x0b, 0x40, 0x84, 0x7e, 0x98, 0x99, 0xf8, 0xbd, 0x60, 0xa9, 0x7d, 0x27, 0xc5, 0xfa, 0x0d, 0xd4, 0xb2, 0x82, 0x63, 0xcd, 0x90, 0x54, 0xf1, 0xfc
2018-08-02 09:38:56.308 Info, Raw: 0x98, 0x81, 0x20, 0xaa, 0x33, 0xad, 0x12, 0x0b, 0x40, 0x84, 0x7e, 0x98, 0x99, 0xf8, 0xbd, 0x60, 0xa9, 0x7d, 0x27, 0xc5, 0xfa, 0x0d, 0xd4, 0xb2, 0x82, 0x63, 0xcd, 0x90, 0x54, 0xf1, 0xfc
2018-08-02 09:38:56.308 Detail, Node009, Decrypted Packet: 0x00, 0x32, 0x02, 0x21, 0x74, 0x00, 0x00, 0x11, 0x15, 0x00, 0x00
2018-08-02 09:38:56.308 Detail,
2018-08-02 09:38:56.310 Info, Node009, Response RTT 5496 Average Response RTT 4528
2018-08-02 09:38:56.310 Detail, Node009, Refreshed Value: old value=false, new value=false, type=bool
2018-08-02 09:38:56.310 Detail, Node009, Changes to this value are not verified
2018-08-02 09:38:56.311 Info, Node009, Received Meter report from node 9: Power=4.373W
2018-08-02 09:38:56.311 Detail, Node009, Refreshed Value: old value=0.000, new value=4.373, type=decimal
2018-08-02 09:38:56.312 Detail, Node009, Changes to this value are not verified
2018-08-02 09:38:56.312 Detail, Node009, Notification: ValueChanged
2018-08-02 09:38:56.370 Detail, Node009, Notification: ValueChanged
2018-08-02 09:39:00.814 Error, Node009, ERROR: Dropping command, expected response not received after 1 attempt(s)
2018-08-02 09:39:00.814 Detail, Node009, Removing current message
2018-08-02 09:39:00.815 Detail, Node009, Notification: Notification - TimeOut
2018-08-02 09:39:00.831 Detail,
2018-08-02 09:39:00.831 Info, Node009, Processing (Send) Nonce Request message (Callback ID=0x4d, Expected Reply=0x04)
2018-08-02 09:39:00.831 Info, Node009, Sending (Send) message (Callback ID=0x4d, Expected Reply=0x04) - Nonce_Get(SwitchBinaryCmd_Get) - 0x01, 0x09, 0x00, 0x13, 0x09, 0x02, 0x98, 0x40, 0x05, 0x02:
2018-08-02 09:39:00.839 Detail, Node009,   Received: 0x01, 0x04, 0x01, 0x13, 0x01, 0xe8
2018-08-02 09:39:00.839 Detail, Node009,   ZW_SEND_DATA delivered to Z-Wave stack
2018-08-02 09:39:00.855 Detail, Node009,   Received: 0x01, 0x07, 0x00, 0x13, 0x02, 0x00, 0x00, 0x02, 0xeb
2018-08-02 09:39:00.855 Detail, Node009,   ZW_SEND_DATA Request with callback ID 0x02 received (expected 0x02)
2018-08-02 09:39:00.856 Info, Node009, Request RTT 23 Average Request RTT 2245
2018-08-02 09:39:00.873 Detail, Node009,   Received: 0x01, 0x10, 0x00, 0x04, 0x00, 0x09, 0x0a, 0x98, 0x80, 0x5c, 0xf9, 0x3a, 0x60, 0x3d, 0xb9, 0xdf, 0x53, 0x07
2018-08-02 09:39:00.874 Info, Node009, Received SecurityCmd_NonceReport from node 9
2018-08-02 09:39:00.874 Info, Node009, Sending (Send) message (Callback ID=0x4e, Expected Reply=0x04) - SwitchBinaryCmd_Get (Node=9): 0x01, 0x09, 0x00, 0x13, 0x09, 0x02, 0x25, 0x02, 0x25, 0x4e, 0xa2
2018-08-02 09:39:00.885 Detail, Node009,   Received: 0x01, 0x04, 0x01, 0x13, 0x01, 0xe8
2018-08-02 09:39:00.885 Detail, Node009,   ZW_SEND_DATA delivered to Z-Wave stack
2018-08-02 09:39:00.903 Detail, Node009,   Received: 0x01, 0x07, 0x00, 0x13, 0x4e, 0x00, 0x00, 0x02, 0xa7
2018-08-02 09:39:00.903 Detail, Node009,   ZW_SEND_DATA Request with callback ID 0x4e received (expected 0x4e)
2018-08-02 09:39:00.903 Info, Node009, Request RTT 71 Average Request RTT 1158
2018-08-02 09:39:00.903 Detail,   Expected callbackId was received
2018-08-02 09:39:00.921 Detail, Node009,   Received: 0x01, 0x08, 0x00, 0x04, 0x00, 0x09, 0x02, 0x98, 0x40, 0x20
2018-08-02 09:39:00.922 Info, Node009, Received SecurityCmd_NonceGet from node 9
2018-08-02 09:39:00.922 Info, NONCES: 0x25, 0x6f, 0xf4, 0x57, 0x02, 0xd4, 0x38, 0x4c
2018-08-02 09:39:00.922 Info, NONCES: 0xc1, 0x5e, 0x83, 0x8e, 0xa3, 0xa7, 0x4f, 0x7f
2018-08-02 09:39:00.922 Info, NONCES: 0x4d, 0x3a, 0x0a, 0x4e, 0x0e, 0x43, 0x9b, 0xe8
2018-08-02 09:39:00.923 Info, NONCES: 0xbe, 0x1f, 0xbb, 0x61, 0xc7, 0x0a, 0xe1, 0xb4
2018-08-02 09:39:00.923 Info, NONCES: 0x92, 0xe8, 0x8d, 0x21, 0xc5, 0xd2, 0xd4, 0x12
2018-08-02 09:39:00.923 Info, NONCES: 0x0d, 0xdf, 0x60, 0x1b, 0x22, 0xfb, 0x04, 0x34
2018-08-02 09:39:00.923 Info, NONCES: 0x2d, 0xf2, 0x8b, 0xf3, 0xfd, 0x6d, 0xa8, 0x8f
2018-08-02 09:39:00.923 Info, NONCES: 0x37, 0xf7, 0x05, 0x22, 0xcd, 0x44, 0x24, 0xc1
2018-08-02 09:39:00.924 Info, Node009, Sending (Send) message (Callback ID=0x01, Expected Reply=0x04) - Nonce_Report - 0x01, 0x11, 0x00, 0x13, 0x09, 0x0a, 0x98, 0x80, 0x2d, 0xf2, 0x8b, 0xf3, 0xfd, 0x6d, 0xa8, 0x8f, 0x05, 0x01, 0xf2:
2018-08-02 09:39:00.932 Detail, Node009,   Received: 0x01, 0x04, 0x01, 0x13, 0x01, 0xe8
2018-08-02 09:39:00.932 Detail, Node009,   ZW_SEND_DATA delivered to Z-Wave stack
2018-08-02 09:39:00.948 Detail, Node009,   Received: 0x01, 0x07, 0x00, 0x13, 0x01, 0x00, 0x00, 0x02, 0xe8
2018-08-02 09:39:00.948 Detail, Node009,   ZW_SEND_DATA Request with callback ID 0x01 received (expected 0x01)
2018-08-02 09:39:00.949 Info, Node009, Request RTT 117 Average Request RTT 637
2018-08-02 09:39:00.972 Detail, Node009,   Received: 0x01, 0x1d, 0x00, 0x04, 0x00, 0x09, 0x17, 0x98, 0x81, 0x7d, 0x99, 0xc7, 0xf5, 0x9b, 0xfa, 0xce, 0xbb, 0x72, 0x3b, 0x29, 0x01, 0x2d, 0x7f, 0x15, 0xd5, 0x21, 0xdf, 0xcb, 0x53, 0x80, 0x36
2018-08-02 09:39:00.973 Info, Raw: 0x98, 0x81, 0x7d, 0x99, 0xc7, 0xf5, 0x9b, 0xfa, 0xce, 0xbb, 0x72, 0x3b, 0x29, 0x01, 0x2d, 0x7f, 0x15, 0xd5, 0x21, 0xdf, 0xcb, 0x53, 0x80, 0x36
2018-08-02 09:39:00.973 Detail, Node009, Decrypted Packet: 0x00, 0x25, 0x03, 0xff
2018-08-02 09:39:00.973 Detail,
2018-08-02 09:39:00.973 Info, Node009, Response RTT 141 Average Response RTT 2334
2018-08-02 09:39:00.973 Info, Node009, Received SwitchBinary report from node 9: level=On
2018-08-02 09:39:00.973 Detail, Node009, Refreshed Value: old value=false, new value=true, type=bool
2018-08-02 09:39:00.974 Detail, Node009, Changes to this value are not verified
2018-08-02 09:39:00.974 Detail, Node009,   Expected reply and command class was received
2018-08-02 09:39:00.974 Detail, Node009,   Message transaction complete
2018-08-02 09:39:00.974 Detail,
2018-08-02 09:39:00.974 Detail, Node009, Removing current message
2018-08-02 09:39:00.975 Detail, Node009, Notification: ValueChanged
9

I have the same issue. Z-Wave switches are unreliable and unstable.
Tried using the same hardware with OpenHAB and things were snappy and stable.
I’ll gladly assist with debugging if someone wants a take on this.

10

Same Z-Wave problems here!

I ran HomeSeer for a couple of years and never had any problems using Z-Wave devices.

Now I’m moving to Home Assistant, factory resetted the Z-Wave stick (just to make a fresh start) and included a couple of existing devices (2 Fibaro Wall Plugs and 3 Forest Shuttle Group motorized curtainrails) to the stick.

When I start Home Assistant every device is beeing configged (name, sensors, etc) and I see 'em all in the frontend.

I can switch the Fibaro Wall Plug devices without any delay or lag, as often as I like, man, that works really great and quick :smiley:

But… after I first control 1 of the 3 motorized curtains it DOES react to my “position” and the rail is moving but after that first action my entire Z-wave network becomes very laggy and every single device, including the Fibaro Wall Plugs, takes too much time to react to every command :frowning:

Is there a way to disable polling the 3 rails so only the Z-Wave command is being sent to close or open the rails and no polling afterwards or something like that ?

Here’s some logging, if you need more, please ask, I really really REALLY want to use Home Assistant and continue to use the way expensive rails I bought a couple of years back, thnx man!

2018-10-04 20:55:51.544 Info, Node004, Value::Set - COMMAND_CLASS_SWITCH_MULTILEVEL - Level - 0 - 1 - 18

2018-10-04 20:55:51.545 Info, Node004, SwitchMultilevel::Set - Setting to level 18

2018-10-04 20:55:51.545 Detail, Node004, Queuing (Send) SwitchMultilevelCmd_Set (Node=4): 0x01, 0x0a, 0x00, 0x13, 0x04, 0x03, 0x26, 0x01, 0x12, 0x25, 0x7b, 0x8a

2018-10-04 20:55:51.545 Detail, Node004, Queuing (Send) SwitchMultilevelCmd_Get (Node=4): 0x01, 0x09, 0x00, 0x13, 0x04, 0x02, 0x26, 0x02, 0x25, 0x7c, 0x9e

2018-10-04 20:55:51.546 Info, Node004, Value::Set - COMMAND_CLASS_SWITCH_MULTILEVEL - Level - 0 - 1 - 18

2018-10-04 20:55:51.546 Info, Node004, SwitchMultilevel::Set - Setting to level 18

2018-10-04 20:55:51.546 Detail, Node004, Queuing (Send) SwitchMultilevelCmd_Set (Node=4): 0x01, 0x0a, 0x00, 0x13, 0x04, 0x03, 0x26, 0x01, 0x12, 0x25, 0x7d, 0x8c

2018-10-04 20:55:51.546 Detail, Node004, Queuing (Send) SwitchMultilevelCmd_Get (Node=4): 0x01, 0x09, 0x00, 0x13, 0x04, 0x02, 0x26, 0x02, 0x25, 0x7e, 0x9c

2018-10-04 20:55:53.212 Error, Node004, ERROR: Dropping command, expected response not received after 1 attempt(s)

2018-10-04 20:55:53.212 Detail, Node004, Removing current message

2018-10-04 20:55:53.212 Detail, Node004, Notification: Notification - TimeOut

2018-10-04 20:55:53.217 Info, Node004, Sending (Send) message (Callback ID=0x6e, Expected Reply=0x04) - SwitchMultilevelCmd_Get (Node=4): 0x01, 0x09, 0x00, 0x13, 0x04, 0x02, 0x26, 0x02, 0x25, 0x6e, 0x8c

2018-10-04 20:55:53.225 Detail, Node004, Received: 0x01, 0x04, 0x01, 0x13, 0x01, 0xe8

2018-10-04 20:55:53.225 Detail, Node004, ZW_SEND_DATA delivered to Z-Wave stack

2018-10-04 20:55:53.241 Detail, Node004, Received: 0x01, 0x07, 0x00, 0x13, 0x6e, 0x00, 0x00, 0x02, 0x87

2018-10-04 20:55:53.242 Detail, Node004, ZW_SEND_DATA Request with callback ID 0x6e received (expected 0x6e)

2018-10-04 20:55:53.242 Info, Node004, Request RTT 24 Average Request RTT 24

2018-10-04 20:55:53.252 Detail, Node004, Received: 0x01, 0x09, 0x00, 0x04, 0x00, 0x04, 0x03, 0x20, 0x03, 0x00, 0xd6

2018-10-04 20:55:53.252 Info, Node004, Response RTT 34 Average Response RTT 34

2018-10-04 20:55:53.252 Info, Node004, Received Basic report from node 4: level=0

2018-10-04 20:55:53.252 Detail, Node004, Queuing (Send) SwitchMultilevelCmd_Get (Node=4): 0x01, 0x09, 0x00, 0x13, 0x04, 0x02, 0x26, 0x02, 0x25, 0x7f, 0x9d

2018-10-04 20:56:03.217 Error, Node004, ERROR: Dropping command, expected response not received after 1 attempt(s)

2018-10-04 20:56:03.218 Detail, Node004, Removing current message

2018-10-04 20:56:03.218 Detail, Node004, Notification: Notification - TimeOut

2018-10-04 20:56:03.221 Info, Node004, Sending (Send) message (Callback ID=0x6f, Expected Reply=0x13) - SwitchMultilevelCmd_Set (Node=4): 0x01, 0x0a, 0x00, 0x13, 0x04, 0x03, 0x26, 0x01, 0x2b, 0x25, 0x6f, 0xa7

2018-10-04 20:56:03.228 Detail, Node004, Received: 0x01, 0x04, 0x01, 0x13, 0x01, 0xe8

2018-10-04 20:56:03.228 Detail, Node004, ZW_SEND_DATA delivered to Z-Wave stack

2018-10-04 20:56:03.246 Detail, Node004, Received: 0x01, 0x07, 0x00, 0x13, 0x6f, 0x00, 0x00, 0x03, 0x87

2018-10-04 20:56:03.246 Detail, Node004, ZW_SEND_DATA Request with callback ID 0x6f received (expected 0x6f)

2018-10-04 20:56:03.246 Info, Node004, Request RTT 25 Average Request RTT 24

2018-10-04 20:56:03.246 Detail, Node004, Removing current message

2018-10-04 20:56:03.246 Info, Node004, Sending (Send) message (Callback ID=0x70, Expected Reply=0x04) - SwitchMultilevelCmd_Get (Node=4): 0x01, 0x09, 0x00, 0x13, 0x04, 0x02, 0x26, 0x02, 0x25, 0x70, 0x92

2018-10-04 20:56:03.254 Detail, Node004, Received: 0x01, 0x04, 0x01, 0x13, 0x01, 0xe8

2018-10-04 20:56:03.254 Detail, Node004, ZW_SEND_DATA delivered to Z-Wave stack

2018-10-04 20:56:03.272 Detail, Node004, Received: 0x01, 0x07, 0x00, 0x13, 0x70, 0x00, 0x00, 0x02, 0x99

2018-10-04 20:56:03.272 Detail, Node004, ZW_SEND_DATA Request with callback ID 0x70 received (expected 0x70)

2018-10-04 20:56:03.272 Info, Node004, Request RTT 25 Average Request RTT 24

2018-10-04 20:56:03.282 Detail, Node004, Received: 0x01, 0x09, 0x00, 0x04, 0x00, 0x04, 0x03, 0x20, 0x03, 0x00, 0xd6

2018-10-04 20:56:03.282 Info, Node004, Response RTT 35 Average Response RTT 34

2018-10-04 20:56:03.282 Info, Node004, Received Basic report from node 4: level=0

2018-10-04 20:56:03.282 Detail, Node004, Queuing (Send) SwitchMultilevelCmd_Get (Node=4): 0x01, 0x09, 0x00, 0x13, 0x04, 0x02, 0x26, 0x02, 0x25, 0x80, 0x62

11

Okay some more digging.

When I observe the OZW_Log.txt I see the curtain is indeed causing the lag.
The controller or HA is trying to get it’s status I assume because every 10 seconds I see logging about that node (timeouts and so on).

When I queue another command, so lets say a light switch, It’ll queue that command until the curtain timeouts are over.

In the OpenZWave faq I read:

Your Network might have what I term “unhealthy” devices. When I say unhealthy, I mean that devices that might have quirks in the way they support Z-Wave, and thus, often don’t work reliably. The problem with this, is that these devices can “block” OZW for upto 120 seconds (by not acknowledging or sending correct replies). You can see if this is the case, by searching the OZW_Log.txt file for “Retries” or “Timeout”. If you see this happening often with a single device, you should check for updated versions of OZW (or at least the Device_Database) to see if these quirks have been fixed, and if not, report to our Mailing List.

To be continued…

12

Posted more information on Google Groups in the OpenZWave section:

https://groups.google.com/forum/#!topic/openzwave/8G3xQVeupn0

13

Hello @ambientsound, can you sustain this post today? I’m having a bit of trouble to make my network stable on a Gigabyte with ubuntu server, docker and hassio 0.91. The z-wave network has 32 nodes and they are all connected relays. It works, but at times the nodes are not very responsive. I am using the aeotec 5th gen stick and multiple brands for the switches (Aeotec, vision, qubino, philio).

1 Like
14

Hi @jmartinezcdo

I’m not sure what to tell you. I switched from Home Assistant to OpenHAB due to multiple reasons, one of them being this Z-Wave problem. The Z-Wave network is very much more responsive this way, so I’m convinced that it must either be a bug or design error with either Home Assistant or openzwave. Because of other annoyances with HA, I didn’t feel motivated to debug this further so I made the switch.

Hoping you’ll find a solution to this problem, because it definitely is an annoying issue.

2 Likes
15

@ambientsound Thanks for your response, it does answer a lot and opens more questions and ideas: I understand OpenHAB does not use openzwave, what they use? Is it open source? Is there a way to integrate what they have into HomeAssistant? What is the experience of openzwave in other systems different from HomeAssistant?

16

Yeah, well, I switched from Openhab after running it a little year with nothing but trouble and heartship.

Anyhow, could we stick to the topic? :wink:

17

I have the same issue here. A lot of people use zwave I assume, so what is it that we have this trouble?

1 Like
18

Having the same trouble since some days

19

+1

Having this with Fibaro Relais and Fibaro Roller Shutters.

Relais on/off has delays of ~8 seconds between multiple different modules.
For Roller Shutters, it happens when setting position. It does NOT happen when just toggling “up” or “down”. Seems to be different message types.

20

Can you create a graph of your zwave network ?

I had similar issues. When I looked at the map, I saw the majority of the nodes were routed via 2 slow nodes (non +). Moving the stick around a meter fixed all my issues.

Note: i have added all my lights non secure.