Z-Wave crashes after first action

danikauf · March 21, 2018, 8:49pm

Platform information:
- Hardware: HP Microserver Gen8
- OS: Debian 9 VM on ESXi 6.5
- Java Runtime Environment: Oracle 1.8.0_161
- OpenHAB version: 2.2.0
Issue of the topic: I have an Aeotec Z-Stick Gen5 plugged into my server and mapped to the OpenHAB VM. It shows up as eighter /dev/ttyACM0 or /dev/ttyACM1. I have freshly installed Openhab 2.2, added the Z-Wave Binding, added the Stick as Controller and configured the port. Then I scanned for Things and found my Z-Wave wall plug as “Z-Wave Node 2: TZ69 Smart meter switch”. Both Things came online normal. I added and linked a Switch Item and pressed it. The wall plug turned on. But then it died. It somehow overloaded itself. After some minutes it may work again but the wall plug remains as “Offline” in Paper UI and Habmin.

Here is the log:


                          __  _____    ____      
  ____  ____  ___  ____  / / / /   |  / __ )     
 / __ \/ __ \/ _ \/ __ \/ /_/ / /| | / __  | 
/ /_/ / /_/ /  __/ / / / __  / ___ |/ /_/ /      
\____/ .___/\___/_/ /_/_/ /_/_/  |_/_____/     
    /_/                        2.2.0
                               Release Build   

Hit '<tab>' for a list of available commands
and '[cmd] --help' for help on a specific command.
Hit '<ctrl-d>' or type 'system:shutdown' or 'logout' to shutdown openHAB.

openhab> log:tail
20:47:39.671 [INFO ] [i.dashboard.internal.DashboardService] - Started dashboard at http://192.168.1.5:8080
20:47:39.697 [INFO ] [i.dashboard.internal.DashboardService] - Started dashboard at https://192.168.1.5:8443
20:47:45.441 [INFO ] [rthome.model.lsp.internal.ModelServer] - Started Language Server Protocol (LSP) service on port 5007
20:47:49.664 [INFO ] [smarthome.event.ExtensionEvent       ] - Extension 'package-expert' has been installed.
20:48:46.550 [INFO ] [lassic.internal.servlet.WebAppServlet] - Started Classic UI at /classicui/app
20:48:46.641 [INFO ] [marthome.ui.paper.internal.PaperUIApp] - Started Paper UI at /paperui
20:48:46.710 [INFO ] [bpanel.internal.HABPanelDashboardTile] - Started HABPanel at /habpanel
20:48:47.132 [INFO ] [.basic.internal.servlet.WebAppServlet] - Started Basic UI at /basicui/app
20:48:47.279 [INFO ] [.ui.habmin.internal.servlet.HABminApp] - Started HABmin servlet at /habmin
20:48:47.361 [INFO ] [smarthome.event.ExtensionEvent       ] - Extension 'misc-restdocs' has been installed.
20:48:47.389 [INFO ] [smarthome.event.ExtensionEvent       ] - Extension 'transformation-javascript' has been installed.
20:48:47.394 [INFO ] [smarthome.event.ExtensionEvent       ] - Extension 'ui-habpanel' has been installed.
20:48:47.396 [INFO ] [smarthome.event.ExtensionEvent       ] - Extension 'transformation-regex' has been installed.
20:48:47.398 [INFO ] [smarthome.event.ExtensionEvent       ] - Extension 'transformation-jsonpath' has been installed.
20:48:47.400 [INFO ] [smarthome.event.ExtensionEvent       ] - Extension 'binding-zwave' has been installed.
20:48:47.408 [INFO ] [smarthome.event.ExtensionEvent       ] - Extension 'transformation-xpath' has been installed.
20:48:47.411 [INFO ] [smarthome.event.ExtensionEvent       ] - Extension 'ui-basic' has been installed.
20:48:47.413 [INFO ] [smarthome.event.ExtensionEvent       ] - Extension 'transformation-map' has been installed.
20:48:47.416 [INFO ] [smarthome.event.ExtensionEvent       ] - Extension 'ui-classic' has been installed.
20:48:47.417 [INFO ] [smarthome.event.ExtensionEvent       ] - Extension 'ui-habmin' has been installed.
20:48:47.420 [INFO ] [smarthome.event.ExtensionEvent       ] - Extension 'transformation-xslt' has been installed.
20:48:47.422 [INFO ] [smarthome.event.ExtensionEvent       ] - Extension 'transformation-exec' has been installed.
20:48:47.424 [INFO ] [smarthome.event.ExtensionEvent       ] - Extension 'ui-paper' has been installed.
20:48:47.426 [INFO ] [smarthome.event.ExtensionEvent       ] - Extension 'transformation-scale' has been installed.
20:48:49.450 [INFO ] [ome.event.ThingStatusInfoChangedEvent] - 'zwave:serial_zstick:b8932750' changed from UNINITIALIZED to INITIALIZING
20:48:49.487 [INFO ] [ome.event.ThingStatusInfoChangedEvent] - 'zwave:serial_zstick:b8932750' changed from INITIALIZING to OFFLINE (BRIDGE_OFFLINE): Controller is offline
20:48:49.493 [INFO ] [ding.zwave.handler.ZWaveSerialHandler] - Connecting to serial port '/dev/ttyACM0'
20:48:49.532 [INFO ] [ding.zwave.handler.ZWaveSerialHandler] - Serial port is initialized
20:48:49.542 [INFO ] [ommandclass.ZWaveSecurityCommandClass] - Update networkKey
20:48:49.558 [INFO ] [ome.event.ThingStatusInfoChangedEvent] - 'zwave:device:b8932750:node2' changed from UNINITIALIZED to INITIALIZING
20:48:49.572 [INFO ] [ome.event.ThingStatusInfoChangedEvent] - 'zwave:device:b8932750:node2' changed from INITIALIZING to OFFLINE (BRIDGE_OFFLINE): Controller is offline
20:48:49.579 [INFO ] [ave.internal.protocol.ZWaveController] - Starting ZWave controller
20:48:49.583 [INFO ] [ave.internal.protocol.ZWaveController] - ZWave timeout is set to 5000ms. Soft reset is false.
20:48:53.820 [INFO ] [sage.SerialApiGetInitDataMessageClass] - NODE 1: Node found
20:48:53.826 [INFO ] [sage.SerialApiGetInitDataMessageClass] - NODE 2: Node found
20:48:53.834 [INFO ] [sage.SerialApiGetInitDataMessageClass] - ZWave Controller using Controller API
20:48:53.844 [INFO ] [sage.SerialApiGetInitDataMessageClass] - ZWave Controller is Primary Controller
20:48:53.847 [INFO ] [sage.SerialApiGetInitDataMessageClass] - ------------Number of Nodes Found Registered to ZWave Controller------------
20:48:53.852 [INFO ] [sage.SerialApiGetInitDataMessageClass] - # Nodes = 2
20:48:53.856 [INFO ] [sage.SerialApiGetInitDataMessageClass] - ----------------------------------------------------------------------------
20:48:56.041 [INFO ] [ome.event.ThingStatusInfoChangedEvent] - 'zwave:serial_zstick:b8932750' changed from OFFLINE (BRIDGE_OFFLINE): Controller is offline to ONLINE
20:48:56.044 [INFO ] [ome.event.ThingStatusInfoChangedEvent] - 'zwave:device:b8932750:node2' changed from OFFLINE (BRIDGE_OFFLINE): Controller is offline to ONLINE
20:48:56.087 [INFO ] [smarthome.event.ThingUpdatedEvent    ] - Thing 'zwave:device:b8932750:node2' has been updated.
20:48:56.112 [INFO ] [smarthome.event.ConfigStatusInfoEvent] - ConfigStatusInfo [configStatusMessages=[]]
20:49:00.352 [INFO ] [ome.event.ThingStatusInfoChangedEvent] - 'zwave:device:b8932750:node2' changed from ONLINE to ONLINE: Node initialising: PROTOINFO
20:49:00.367 [INFO ] [ome.event.ThingStatusInfoChangedEvent] - 'zwave:device:b8932750:node2' changed from ONLINE: Node initialising: PROTOINFO to ONLINE: Node initialising: INIT_NEIGHBORS
20:49:00.403 [INFO ] [ome.event.ThingStatusInfoChangedEvent] - 'zwave:device:b8932750:node2' changed from ONLINE: Node initialising: INIT_NEIGHBORS to ONLINE: Node initialising: FAILED_CHECK
20:49:00.417 [INFO ] [ome.event.ThingStatusInfoChangedEvent] - 'zwave:device:b8932750:node2' changed from ONLINE: Node initialising: FAILED_CHECK to ONLINE: Node initialising: WAIT
20:49:00.424 [INFO ] [ome.event.ThingStatusInfoChangedEvent] - 'zwave:device:b8932750:node2' changed from ONLINE: Node initialising: WAIT to ONLINE: Node initialising: PING
20:49:00.458 [INFO ] [ome.event.ThingStatusInfoChangedEvent] - 'zwave:device:b8932750:node2' changed from ONLINE: Node initialising: PING to ONLINE: Node initialising: DETAILS
20:49:00.460 [INFO ] [ome.event.ThingStatusInfoChangedEvent] - 'zwave:device:b8932750:node2' changed from ONLINE: Node initialising: DETAILS to ONLINE: Node initialising: GET_CONFIGURATION
20:49:00.469 [INFO ] [ome.event.ThingStatusInfoChangedEvent] - 'zwave:device:b8932750:node2' changed from ONLINE: Node initialising: GET_CONFIGURATION to ONLINE: Node initialising: DYNAMIC_VALUES
20:49:00.533 [INFO ] [smarthome.event.ThingUpdatedEvent    ] - Thing 'zwave:device:b8932750:node2' has been updated.
20:49:00.537 [INFO ] [smarthome.event.ConfigStatusInfoEvent] - ConfigStatusInfo [configStatusMessages=[]]
20:49:00.634 [INFO ] [smarthome.event.ItemStateChangedEvent] - TV_Switch changed from NULL to OFF
20:49:00.857 [INFO ] [ome.event.ThingStatusInfoChangedEvent] - 'zwave:device:b8932750:node2' changed from ONLINE: Node initialising: DYNAMIC_VALUES to ONLINE: Node initialising: DYNAMIC_END
20:49:00.894 [INFO ] [ome.event.ThingStatusInfoChangedEvent] - 'zwave:device:b8932750:node2' changed from ONLINE: Node initialising: DYNAMIC_END to ONLINE: Node initialising: HEAL_START
20:49:00.909 [INFO ] [ome.event.ThingStatusInfoChangedEvent] - 'zwave:device:b8932750:node2' changed from ONLINE: Node initialising: HEAL_START to ONLINE: Node initialising: DELETE_ROUTES
20:49:01.082 [INFO ] [ome.event.ThingStatusInfoChangedEvent] - 'zwave:device:b8932750:node2' changed from ONLINE: Node initialising: DELETE_ROUTES to ONLINE: Node initialising: RETURN_ROUTES
20:49:01.416 [INFO ] [ome.event.ThingStatusInfoChangedEvent] - 'zwave:device:b8932750:node2' changed from ONLINE: Node initialising: RETURN_ROUTES to ONLINE: Node initialising: NEIGHBORS
20:49:01.451 [INFO ] [ome.event.ThingStatusInfoChangedEvent] - 'zwave:device:b8932750:node2' changed from ONLINE: Node initialising: NEIGHBORS to ONLINE
20:49:30.005 [INFO ] [smarthome.event.ItemCommandEvent     ] - Item 'TV_Switch' received command ON
20:49:30.015 [INFO ] [smarthome.event.ItemStateChangedEvent] - TV_Switch changed from OFF to ON
20:50:40.688 [INFO ] [smarthome.event.ItemCommandEvent     ] - Item 'TV_Switch' received command OFF
20:50:40.698 [DEBUG] [nding.zwave.handler.ZWaveThingHandler] - NODE 2: Command received zwave:device:b8932750:node2:switch_binary --> OFF
20:50:40.704 [DEBUG] [ndclass.ZWaveBinarySwitchCommandClass] - NODE 2: Creating new message for application command SWITCH_BINARY_SET
20:50:40.715 [DEBUG] [tocol.ZWaveController$ZWaveSendThread] - Took message from queue for sending. Queue length = 0
20:50:40.720 [DEBUG] [ave.internal.protocol.ZWaveController] - Message queued. Queue length = 1. Queue={}
20:50:40.723 [INFO ] [smarthome.event.ItemStateChangedEvent] - TV_Switch changed from ON to OFF
20:50:40.722 [DEBUG] [zwave.internal.protocol.SerialMessage] - Assembled message buffer = 01 0A 00 13 02 03 25 01 00 25 10 F6 
20:50:40.734 [DEBUG] [ding.zwave.handler.ZWaveSerialHandler] - NODE 2: Sending REQUEST Message = 01 0A 00 13 02 03 25 01 00 25 10 F6 
20:50:45.740 [DEBUG] [zwave.internal.protocol.SerialMessage] - Assembled message buffer = 01 03 00 16 EA 
20:50:45.744 [DEBUG] [tocol.ZWaveController$ZWaveSendThread] - NODE 2: Sending ABORT Message = 01 03 00 16 EA 
20:50:45.746 [DEBUG] [zwave.internal.protocol.SerialMessage] - Assembled message buffer = 01 03 00 16 EA 
20:50:45.748 [DEBUG] [ding.zwave.handler.ZWaveSerialHandler] - NODE 255: Sending REQUEST Message = 01 03 00 16 EA 
20:50:45.751 [DEBUG] [tocol.ZWaveController$ZWaveSendThread] - NODE 2: Timeout while sending message. Requeueing - 2 attempts left!
20:50:45.753 [DEBUG] [ol.serialmessage.SendDataMessageClass] - NODE 2: Got an error while sending data. Resending message.
20:50:45.755 [DEBUG] [ave.internal.protocol.ZWaveController] - Message queued. Queue length = 1. Queue={}
20:50:45.757 [DEBUG] [tocol.ZWaveController$ZWaveSendThread] - Took message from queue for sending. Queue length = 0
20:50:45.759 [DEBUG] [zwave.internal.protocol.SerialMessage] - Assembled message buffer = 01 0A 00 13 02 03 25 01 00 25 11 F7 
20:50:45.761 [DEBUG] [ding.zwave.handler.ZWaveSerialHandler] - NODE 2: Sending REQUEST Message = 01 0A 00 13 02 03 25 01 00 25 11 F7 
20:50:50.764 [DEBUG] [zwave.internal.protocol.SerialMessage] - Assembled message buffer = 01 03 00 16 EA 
20:50:50.767 [DEBUG] [tocol.ZWaveController$ZWaveSendThread] - NODE 2: Sending ABORT Message = 01 03 00 16 EA 
20:50:50.770 [DEBUG] [zwave.internal.protocol.SerialMessage] - Assembled message buffer = 01 03 00 16 EA 
20:50:50.772 [DEBUG] [ding.zwave.handler.ZWaveSerialHandler] - NODE 255: Sending REQUEST Message = 01 03 00 16 EA 
20:50:50.775 [DEBUG] [tocol.ZWaveController$ZWaveSendThread] - NODE 2: Timeout while sending message. Requeueing - 1 attempts left!
20:50:50.778 [DEBUG] [ol.serialmessage.SendDataMessageClass] - NODE 2: Got an error while sending data. Resending message.
20:50:50.780 [DEBUG] [ave.internal.protocol.ZWaveController] - Message queued. Queue length = 1. Queue={}
20:50:50.782 [DEBUG] [tocol.ZWaveController$ZWaveSendThread] - Took message from queue for sending. Queue length = 0
20:50:50.783 [DEBUG] [zwave.internal.protocol.SerialMessage] - Assembled message buffer = 01 0A 00 13 02 03 25 01 00 25 12 F4 
20:50:50.785 [DEBUG] [ding.zwave.handler.ZWaveSerialHandler] - NODE 2: Sending REQUEST Message = 01 0A 00 13 02 03 25 01 00 25 12 F4 
20:50:55.789 [DEBUG] [zwave.internal.protocol.SerialMessage] - Assembled message buffer = 01 03 00 16 EA 
20:50:55.792 [DEBUG] [tocol.ZWaveController$ZWaveSendThread] - NODE 2: Sending ABORT Message = 01 03 00 16 EA 
20:50:55.794 [DEBUG] [zwave.internal.protocol.SerialMessage] - Assembled message buffer = 01 03 00 16 EA 
20:50:55.796 [DEBUG] [ding.zwave.handler.ZWaveSerialHandler] - NODE 255: Sending REQUEST Message = 01 03 00 16 EA 
20:50:55.909 [DEBUG] [tocol.ZWaveController$ZWaveSendThread] - NODE 2: Timeout while sending message. Requeueing - 0 attempts left!
20:50:55.912 [DEBUG] [ing.zwave.internal.protocol.ZWaveNode] - NODE 2: Node is DEAD.
20:50:55.914 [DEBUG] [ave.internal.protocol.ZWaveController] - Notifying event listeners: ZWaveNodeStatusEvent
20:50:55.917 [DEBUG] [nding.zwave.handler.ZWaveThingHandler] - NODE 2: Got an event from Z-Wave network: ZWaveNodeStatusEvent
20:50:55.919 [DEBUG] [nding.zwave.handler.ZWaveThingHandler] - NODE 2: Setting OFFLINE
20:50:55.925 [DEBUG] [ave.internal.protocol.ZWaveController] - NODE 2: Node Status event - Node is DEAD
20:50:55.925 [INFO ] [ome.event.ThingStatusInfoChangedEvent] - 'zwave:device:b8932750:node2' changed from ONLINE to OFFLINE (COMMUNICATION_ERROR): Node is not communicating with controller
20:50:55.930 [DEBUG] [ol.serialmessage.SendDataMessageClass] - NODE 2: Node is DEAD. Dropping message.

This is the quintessence of a week research and trying out everything. It’s just not working.
Things I tried:

Installed OpenHAB 2.2 on Ubuntu
Installed Openhab 2.2 and 2.1 on Debian
Installed Azul Java (initial)
Installed Open JDK
Installed Oracle (current, looks somehow as the most reliable)
Tried 4 different USB ports on the server for the Stick
- Tried also USB 3.0
- Tried with and without USB extension cable
Excluded and Included everything (I have two more Fibaro Double Switch 2 with the same problem but have them excluded until the problem can be resolved)
Soft reseted the Stick
Hard reseted the Stick
- Via OpenHAB PaperUI
- Directly with a Paperclip on the stick
Healed the network
Synchronized the network
Moved the wall plug directly in front of the plugged in stick
- It’s for sure no connection problem

Additional Notes
I have OpenHAB 2.1 installed on my MacBook and there, with the same Stick I can switch the wallplug without the slightest delay. So it can’t be the Stick, the wall plug or the network itself.
I also had installed OpenHAB 2.1 before as Docker Image running on OMV (Linux Open Source NAS distro) also on my HP Microserver. First it worked ok but with some time it got laggy and rule execution was not working. It looks to me as the beginning of this problems. But now on the freshly installed and virtualized server I never got it it to work normal. I also installed the OpenZwave library and the control panel on another Debian VM. Kind of the same problem. It switched the wall plug but somehow tried again and again and again and then it overflowed or someting.
Maybe the problem is deeper, below the OpenHAB Java and the Openzwave library. Something deep in Linux which both use.

I really don’t know what to try anymore, help much! appreciated.

danikauf · March 22, 2018, 9:34am

I found something very promising and gonna try this out this evening:

http://floating.io/2017/02/openhab-a-z-stick-and-esxi-6-5

danikauf · March 22, 2018, 8:26pm

Success!
It was indeed the ESX 6.5 USB driver. Now I see a lot more and uninterrupted communication on the controller and everything is working without delay. Also the other nodes.

I dont know but this is maybe worth a note in the installation docs.