[SOLVED] Zwave stops working after a few minutes

iMars · November 30, 2017, 6:33pm

I’ve installed Home Assistant on a virtual machine (ESXi). It’s running Ubuntu 16.04.3 LTS and installed Home Assistant via this way: https://home-assistant.io/docs/installation/virtualenv/.

Everything is working and have no issues,… till I started with zwave.

I’ve bought an Aeotec USB zwave 5gen stick. This was connected without any zwave devices. No issues so far.
This is connected to my ESX server and via usb-passthrough to my vm. This is also no problem. I’m using udev to always get the right pathname:

marcel@HomeAssistant:~$ cat /etc/udev/rules.d/99-usb-serial.rules 
SUBSYSTEM=="tty", ATTRS{idVendor}=="0658", ATTRS{idProduct}=="0200", SYMLINK+="ttyUSB-ZStick-5G"
marcel@HomeAssistant:~$ ls /dev/ttyUSB-ZStick-5G -lah
lrwxrwxrwx 1 root root 7 Nov 29 18:39 /dev/ttyUSB-ZStick-5G -> ttyACM1

Sometimes it shows up as ttyACM0 and sometimes as ttyACM1, but this is working (always ttyUSB-ZStick-5G).

My configuration.yaml is:

zwave:
  usb_path: /dev/ttyUSB-ZStick-5G
  network_key: "my key here"
  new_entity_ids: true

Recently I bought some Neo Coolcam door-/windowsensors. When I restart homeassistent I can add these devices. And they’re working… for a few minutes.

After a few minutes the whole zwave doesn’t work anymore. When I restart homeassistant, than it works again, for a few minutes. Every command afterwards gives an error/timeout in the OZW_log.

Start OZW_log:

2017-11-30 19:22:27.801 Always, OpenZwave Version 1.4.2586 Starting Up
2017-11-30 19:22:31.352 Info, Setting Up Provided Network Key for Secure Communications
2017-11-30 19:22:31.352 Info, mgr,     Added driver for controller /dev/ttyUSB-ZStick-5G
2017-11-30 19:22:31.352 Info,   Opening controller /dev/ttyUSB-ZStick-5G
2017-11-30 19:22:31.353 Info, Trying to open serial port /dev/ttyUSB-ZStick-5G (attempt 1)
2017-11-30 19:22:31.563 Info, Serial port /dev/ttyUSB-ZStick-5G opened (attempt 1)
2017-11-30 19:22:31.563 Detail, contrlr, Queuing (Command) FUNC_ID_ZW_GET_VERSION: 0x01, 0x03, 0x00, 0x15, 0xe9
2017-11-30 19:22:31.563 Detail, contrlr, Queuing (Command) FUNC_ID_ZW_MEMORY_GET_ID: 0x01, 0x03, 0x00, 0x20, 0xdc
2017-11-30 19:22:31.563 Detail, contrlr, Queuing (Command) FUNC_ID_ZW_GET_CONTROLLER_CAPABILITIES: 0x01, 0x03, 0x00, 0x05, 0xf9
2017-11-30 19:22:31.564 Detail, contrlr, Queuing (Command) FUNC_ID_SERIAL_API_GET_CAPABILITIES: 0x01, 0x03, 0x00, 0x07, 0xfb
2017-11-30 19:22:31.564 Detail, contrlr, Queuing (Command) FUNC_ID_ZW_GET_SUC_NODE_ID: 0x01, 0x03, 0x00, 0x56, 0xaa
2017-11-30 19:22:31.564 Detail, 
2017-11-30 19:22:31.564 Info, contrlr, Sending (Command) message (Callback ID=0x00, Expected Reply=0x15) - FUNC_ID_ZW_GET_VERSION: 0x01, 0x03, 0x00, 0x15, 0xe9
2017-11-30 19:22:31.569 Detail, contrlr,   Received: 0x01, 0x10, 0x01, 0x15, 0x5a, 0x2d, 0x57, 0x61, 0x76, 0x65, 0x20, 0x33, 0x2e, 0x39, 0x35, 0x00, 0x01, 0x99
2017-11-30 19:22:31.569 Detail, 
2017-11-30 19:22:31.569 Info, contrlr, Received reply to FUNC_ID_ZW_GET_VERSION:
2017-11-30 19:22:31.569 Info, contrlr,     Static Controller library, version Z-Wave 3.95
2017-11-30 19:22:31.569 Detail, Node045,   Expected reply was received
2017-11-30 19:22:31.569 Detail, Node045,   Message transaction complete
2017-11-30 19:22:31.569 Detail, 
2017-11-30 19:22:31.569 Detail, contrlr, Removing current message
2017-11-30 19:22:31.569 Detail, 
2017-11-30 19:22:31.569 Info, contrlr, Sending (Command) message (Callback ID=0x00, Expected Reply=0x20) - FUNC_ID_ZW_MEMORY_GET_ID: 0x01, 0x03, 0x00, 0x20, 0xdc
2017-11-30 19:22:31.573 Detail, contrlr,   Received: 0x01, 0x08, 0x01, 0x20, 0xfb, 0x24, 0xba, 0x5a, 0x01, 0xe8
2017-11-30 19:22:31.573 Detail, 
2017-11-30 19:22:31.573 Info, contrlr, Received reply to FUNC_ID_ZW_MEMORY_GET_ID. Home ID = 0xfb24ba5a.  Our node ID = 1
2017-11-30 19:22:31.574 Detail, Node036,   Expected reply was received
2017-11-30 19:22:31.574 Detail, Node036,   Message transaction complete
2017-11-30 19:22:31.574 Detail, 
2017-11-30 19:22:31.574 Detail, contrlr, Removing current message
2017-11-30 19:22:31.574 Detail, 
2017-11-30 19:22:31.574 Info, contrlr, Sending (Command) message (Callback ID=0x00, Expected Reply=0x05) - FUNC_ID_ZW_GET_CONTROLLER_CAPABILITIES: 0x01, 0x03, 0x00, 0x05, 0xf9
2017-11-30 19:22:31.578 Detail, contrlr,   Received: 0x01, 0x04, 0x01, 0x05, 0x08, 0xf7
2017-11-30 19:22:31.578 Detail, 
2017-11-30 19:22:31.578 Info, contrlr, Received reply to FUNC_ID_ZW_GET_CONTROLLER_CAPABILITIES:
2017-11-30 19:22:31.578 Info, contrlr,     There is no SUC ID Server (SIS) in this network.
2017-11-30 19:22:31.578 Info, contrlr,     The PC controller is a primary controller.
2017-11-30 19:22:31.578 Detail, Node247,   Expected reply was received
2017-11-30 19:22:31.578 Detail, Node247,   Message transaction complete
2017-11-30 19:22:31.578 Detail, 
2017-11-30 19:22:31.578 Detail, contrlr, Removing current message
2017-11-30 19:22:31.578 Detail, 
2017-11-30 19:22:31.578 Info, contrlr, Sending (Command) message (Callback ID=0x00, Expected Reply=0x07) - FUNC_ID_SERIAL_API_GET_CAPABILITIES: 0x01, 0x03, 0x00, 0x07, 0xfb
2017-11-30 19:22:31.590 Detail, contrlr,   Received: 0x01, 0x2b, 0x01, 0x07, 0x01, 0x00, 0x00, 0x86, 0x00, 0x01, 0x00, 0x5a, 0xfe, 0x81, 0xff, 0x88, 0x4f, 0x1f, 0x00, 0x00, 0xfb, 0x9f, 0x7d, 0xa0, 0x67, 0x00, 0x00, 0x80, 0x00, 0x80, 0x86, 0x00, 0x00, 0x00, 0xe8, 0x73, 0x00, 0x00, 0x0e, 0x00, 0x00, 0x60, 0x00, 0x00, 0xfb
2017-11-30 19:22:31.590 Detail, 
2017-11-30 19:22:31.590 Info, contrlr,  Received reply to FUNC_ID_SERIAL_API_GET_CAPABILITIES
2017-11-30 19:22:31.590 Info, contrlr,     Serial API Version:   1.0
2017-11-30 19:22:31.590 Info, contrlr,     Manufacturer ID:      0x0086
2017-11-30 19:22:31.590 Info, contrlr,     Product Type:         0x0001
2017-11-30 19:22:31.590 Info, contrlr,     Product ID:           0x005a
2017-11-30 19:22:31.590 Detail, contrlr, Queuing (Command) FUNC_ID_ZW_GET_RANDOM: 0x01, 0x04, 0x00, 0x1c, 0x20, 0xc7
2017-11-30 19:22:31.590 Detail, contrlr, Queuing (Command) FUNC_ID_SERIAL_API_GET_INIT_DATA: 0x01, 0x03, 0x00, 0x02, 0xfe
2017-11-30 19:22:31.590 Detail, contrlr, Queuing (Command) FUNC_ID_SERIAL_API_SET_TIMEOUTS: 0x01, 0x05, 0x00, 0x06, 0x64, 0x0f, 0x97
2017-11-30 19:22:31.590 Detail, contrlr, Queuing (Command) FUNC_ID_SERIAL_API_APPL_NODE_INFORMATION: 0x01, 0x07, 0x00, 0x03, 0x01, 0x02, 0x01, 0x00, 0xf9
2017-11-30 19:22:31.590 Detail,   Expected reply was received
2017-11-30 19:22:31.590 Detail,   Message transaction complete

The error messages after a few minutes.
Add Node Secure:

2017-11-30 19:28:43.292 Detail, Queuing (Controller) Add Device
2017-11-30 19:28:43.292 Info, Add Device
2017-11-30 19:28:43.292 Detail, contrlr, Queuing (Command) ControllerCommand_AddDevice: 0x01, 0x05, 0x00, 0x4a, 0xc1, 0x0c, 0x7d
2017-11-30 19:28:43.292 Detail, Notification: ControllerCommand - Starting
2017-11-30 19:28:43.292 Detail, 
2017-11-30 19:28:43.292 Info, contrlr, Sending (Command) message (Callback ID=0x0c, Expected Reply=0x4a) - ControllerCommand_AddDevice: 0x01, 0x05, 0x00, 0x4a, 0xc1, 0x0c, 0x7d
2017-11-30 19:28:44.293 Error, contrlr, ERROR: Dropping command, expected response not received after 1 attempt(s)
2017-11-30 19:28:44.293 Detail, contrlr, Removing current message
2017-11-30 19:28:44.293 Detail, contrlr, Notification: Notification - TimeOut
2017-11-30 19:28:44.293 Detail, Notification: ControllerCommand - Error - Failed

Add Node:

2017-11-30 19:29:33.145 Detail, Queuing (Controller) Add Device
2017-11-30 19:29:33.146 Info, Add Device
2017-11-30 19:29:33.146 Detail, contrlr, Queuing (Command) ControllerCommand_AddDevice: 0x01, 0x05, 0x00, 0x4a, 0xc1, 0x0d, 0x7c
2017-11-30 19:29:33.146 Detail, Notification: ControllerCommand - Starting
2017-11-30 19:29:33.146 Detail, 
2017-11-30 19:29:33.146 Info, contrlr, Sending (Command) message (Callback ID=0x0d, Expected Reply=0x4a) - ControllerCommand_AddDevice: 0x01, 0x05, 0x00, 0x4a, 0xc1, 0x0d, 0x7c
2017-11-30 19:29:34.146 Error, contrlr, ERROR: Dropping command, expected response not received after 1 attempt(s)
2017-11-30 19:29:34.146 Detail, contrlr, Removing current message
2017-11-30 19:29:34.146 Detail, contrlr, Notification: Notification - TimeOut
2017-11-30 19:29:34.147 Detail, Notification: ControllerCommand - Error - Failed

Remove Node:

2017-11-30 19:29:58.100 Detail, Queuing (Controller) Remove Device
2017-11-30 19:29:58.100 Info, Remove Device
2017-11-30 19:29:58.100 Detail, contrlr, Queuing (Command) ControllerCommand_RemoveDevice: 0x01, 0x05, 0x00, 0x4b, 0x81, 0x0e, 0x3e
2017-11-30 19:29:58.100 Detail, Notification: ControllerCommand - Starting
2017-11-30 19:29:58.101 Detail, 
2017-11-30 19:29:58.101 Info, contrlr, Sending (Command) message (Callback ID=0x0e, Expected Reply=0x4b) - ControllerCommand_RemoveDevice: 0x01, 0x05, 0x00, 0x4b, 0x81, 0x0e, 0x3e
2017-11-30 19:29:59.101 Error, contrlr, ERROR: Dropping command, expected response not received after 1 attempt(s)
2017-11-30 19:29:59.101 Detail, contrlr, Removing current message
2017-11-30 19:29:59.101 Detail, contrlr, Notification: Notification - TimeOut
2017-11-30 19:29:59.102 Detail, Notification: ControllerCommand - Error - Failed

I havent got a clue where to search or what the problem is.

silvrr · November 30, 2017, 6:45pm

I had the same issue with zwave and esxi. Never got it sorted. If you do find the issue please report back with the fix.

firstof9 · November 30, 2017, 6:59pm

Try this @silvrr & @iMars

Enable the SSH service on your VMware host and log in to the SSH console.
Execute the following command: esxcli system module set -m=vmkusb -e=FALSE
Reboot your VMware host.
Edit your VM and re-add the Z-Stick.

iMars · November 30, 2017, 8:56pm

I’ll try it first thing tomorrow. Yet can you explain what exactly is going on? I mean, it is working… Linux is recognizing the hardware.

Edit: found this…
In ESXi 6.5, the legacy USB drivers, including xhci, ehci-hcd, usb-uhci, usb, usb-storage, and so on, are replaced with a single USB driver named vmkusb. The vmkusb driver is loaded by default and it is applied to all the USB Host Controllers (XHCI/EHCI/UHCI/OHCI), USB Keyboard, Mass Storage, and supported USB NIC devices connected to the host.

sebk-666 · November 30, 2017, 11:00pm

Not too much of help here, but I’m also using the Aeotec Gen5 stick plugged into an ESXi 5.5 host and passed through to a (Centos 7) VM running HA.
This has been stable for more than a year now, so it sure looks like an ESXi 6.x issue.

Sebastian

firstof9 · November 30, 2017, 11:33pm

Correct VMware implemented a new USB driver for the kernel in 6.5 that causes issues, the steps posted will disable the new driver and use the legacy drivers. This should resolve the issue.

iMars · December 1, 2017, 9:41am

So far so good It’s working longer than before…

30 minutes after starting zwave, I could add secure a node, which was impossible before

silvrr · January 10, 2018, 8:08pm

Thanks so much for posting this fix. Back up and running on my virtual instance again. Has been stable for a month or so with no zwave issues.

firstof9 · January 10, 2018, 8:49pm

Not sure why VMware decided to break something that works lol but good to hear it’s working solid for you.

gravyflex · August 3, 2018, 4:55pm

@firstof9 You my hero, I was going crazy trying to add a secure device.

firstof9 · August 3, 2018, 5:09pm

I can’t take the credit, I read it on another post but i’ve since lost the link