ZWave Controller Offline After Reboot

Setup, Configuration and Use Beginners
,
1

Platform Information

Hardware: 
* Raspberry Pi 3 Model B version 1.2 (ARMv8, with 1GB RAM, and 64 GB microSD card)
* ZMEUUZB - ZWave.Me USB Z-Wave dongle
* Insteon 2413U PLM

OS: Raspbian 9 (Stretch)
Java Runtime Environment: java version “1.8.0_181”, Java™ SE Runtime Environment (build 1.8.0_181-b13), Java HotSpot™ Client VM (build 25.181-b13, mixed mode)
openHAB version: 2.3.0-1 wth openhab2-addons 2.3.0-1
Also tried: ZWave binding - 2.4.0.201810061304

Hello openHAB Community,

I’ve been running openhab2 with an Insteon setup for a while, and I’ve decided to add ZWave components. I added a ZWave.ME UZB USB controller under openHAB 2.3, and saw it came up. However, after a reboot the controller went offline, and I was unable to bring it up. I was however able to delete the controller and add it fresh, after which it came up. In an effort to fix this, I’ve installed the latest ZWave snapshot, but now I can’t bring the controller up at all. Does anyone have any suggestions? There are similar threads in the community, and I’ve reviewed them, but I still can’t resolve the issue.

The USB dongle is recognized by the OS

pi@openhab2:~ $ lsusb
Bus 001 Device 005: ID 0658:0200 Sigma Designs, Inc.
Bus 001 Device 004: ID 0403:6001 Future Technology Devices International, Ltd FT232 USB-Serial (UART) IC
Bus 001 Device 003: ID 0424:ec00 Standard Microsystems Corp. SMSC9512/9514 Fast Ethernet Adapter
Bus 001 Device 002: ID 0424:9514 Standard Microsystems Corp. SMC9514 Hub
Bus 001 Device 001: ID 1d6b:0002 Linux Foundation 2.0 root hub

Permission appear to be okay…

pi@openhab2:~ $ ls -l /dev/ttyACM0*
crw-rw-r-- 1 root dialout 166, 0 Oct  7 20:48 /dev/ttyACM0
pi@openhab2:~ $ grep dialout /etc/group
dialout:x:20:pi,openhab

Java EXTRA_OPTIONS are set…

pi@openhab2:~ $ cat /etc/default/openhab2 | grep EXTRA_JAVA_OPTS
EXTRA_JAVA_OPTS="-Dgnu.io.rxtx.SerialPorts=/dev/ttyUSB0:/dev/ttyS0:/dev/ttyS2:/dev/ttyACM0:/dev/ttyAMA0"

The openHAB events log shows this upon a restart

2018-10-07 21:40:03.889 [hingStatusInfoChangedEvent] - 'zwave:serial_zstick:512' changed from OFFLINE (BRIDGE_OFFLINE): Controller is offline to UNINITIALIZED
2018-10-07 21:40:07.068 [hingStatusInfoChangedEvent] - 'zwave:serial_zstick:512' changed from UNINITIALIZED to UNINITIALIZED (HANDLER_MISSING_ERROR)
2018-10-07 21:40:07.101 [hingStatusInfoChangedEvent] - 'astro:sun:home' changed from ONLINE to UNINITIALIZED
2018-10-07 21:40:07.107 [hingStatusInfoChangedEvent] - 'astro:sun:home' changed from UNINITIALIZED to UNINITIALIZED (HANDLER_MISSING_ERROR)
2018-10-07 21:40:07.111 [hingStatusInfoChangedEvent] - 'astro:moon:local' changed from ONLINE to UNINITIALIZED
2018-10-07 21:40:07.119 [hingStatusInfoChangedEvent] - 'astro:moon:local' changed from UNINITIALIZED to UNINITIALIZED (HANDLER_MISSING_ERROR)
2018-10-07 21:40:07.123 [hingStatusInfoChangedEvent] - 'astro:moon:home' changed from ONLINE to UNINITIALIZED
2018-10-07 21:40:07.131 [hingStatusInfoChangedEvent] - 'astro:moon:home' changed from UNINITIALIZED to UNINITIALIZED (HANDLER_MISSING_ERROR)
2018-10-07 21:40:07.138 [hingStatusInfoChangedEvent] - 'astro:sun:local' changed from ONLINE to UNINITIALIZED
2018-10-07 21:40:07.144 [hingStatusInfoChangedEvent] - 'astro:sun:local' changed from UNINITIALIZED to UNINITIALIZED (HANDLER_MISSING_ERROR)
2018-10-07 21:40:07.152 [hingStatusInfoChangedEvent] - 'ntp:ntp:local' changed from ONLINE to UNINITIALIZED
2018-10-07 21:40:07.156 [hingStatusInfoChangedEvent] - 'ntp:ntp:local' changed from UNINITIALIZED to UNINITIALIZED (HANDLER_MISSING_ERROR)
2018-10-07 21:40:08.582 [temChannelLinkRemovedEvent] - Link 'Elevation => astro:sun:home:position#elevation' has been removed.
2018-10-07 21:40:08.584 [temChannelLinkRemovedEvent] - Link 'MoonPhase => astro:moon:home:phase#name' has been removed.
2018-10-07 21:40:08.586 [temChannelLinkRemovedEvent] - Link 'Azimuth => astro:sun:home:position#azimuth' has been removed.
2018-10-07 21:40:08.589 [temChannelLinkRemovedEvent] - Link 'Sunset_Time => astro:sun:home:set#start' has been removed.
2018-10-07 21:40:08.590 [temChannelLinkRemovedEvent] - Link 'Diffuse_Radiation => astro:sun:home:radiation#diffuse' has been removed.
2018-10-07 21:40:08.592 [temChannelLinkRemovedEvent] - Link 'Sunrise_Time => astro:sun:home:rise#start' has been removed.
2018-10-07 21:40:08.594 [temChannelLinkRemovedEvent] - Link 'Total_Radiation => astro:sun:home:radiation#total' has been removed.

These are the ZWave logged events in openhab.log

2018-10-07 21:40:02.923 [DEBUG] [org.openhab.binding.zwave           ] - BundleEvent STOPPING - org.openhab.binding.zwave
2018-10-07 21:40:03.843 [DEBUG] [org.openhab.binding.zwave           ] - ServiceEvent UNREGISTERING - {org.eclipse.smarthome.config.core.ConfigDescriptionProvider, org.eclipse.smarthome.config.core.ConfigOptionProvider}={service.id=190, service.bundleid=220, service.scope=bundle, component.name=org.openhab.binding.zwave.internal.ZWaveConfigProvider, component.id=11} - org.openhab.binding.zwave
2018-10-07 21:40:03.855 [DEBUG] [org.openhab.binding.zwave           ] - ServiceEvent UNREGISTERING - {org.eclipse.smarthome.config.discovery.usbserial.UsbSerialDiscoveryParticipant}={service.id=112, service.bundleid=220, service.scope=bundle, component.name=org.openhab.binding.zwave.discovery.ZWaveUsbSerialDiscoveryParticipant, component.id=12} - org.openhab.binding.zwave
2018-10-07 21:40:03.862 [DEBUG] [org.openhab.binding.zwave           ] - ServiceEvent UNREGISTERING - {org.eclipse.smarthome.core.events.EventFactory}={service.id=139, service.bundleid=220, service.scope=bundle, component.name=org.openhab.binding.zwave.event.BindingEventFactory, component.id=13} - org.openhab.binding.zwave
2018-10-07 21:40:03.870 [DEBUG] [org.openhab.binding.zwave           ] - ServiceEvent UNREGISTERING - {org.eclipse.smarthome.core.thing.binding.ThingHandlerFactory}={service.id=113, service.bundleid=220, service.scope=bundle, component.name=org.openhab.binding.zwave.internal.ZWaveHandlerFactory, component.id=15} - org.openhab.binding.zwave
2018-10-07 21:40:03.997 [DEBUG] [WaveSerialHandler$ZWaveReceiveThread] - Stopped ZWave thread: Receive
2018-10-07 21:40:07.003 [INFO ] [ing.zwave.handler.ZWaveSerialHandler] - Stopped ZWave serial handler
2018-10-07 21:40:07.007 [DEBUG] [wave.discovery.ZWaveDiscoveryService] - ZWave discovery: Deactivate zwave:serial_zstick:512
2018-10-07 21:40:07.012 [DEBUG] [org.openhab.binding.zwave           ] - ServiceEvent UNREGISTERING - {org.eclipse.smarthome.config.discovery.DiscoveryService}={service.id=279, service.bundleid=220, service.scope=singleton} - org.openhab.binding.zwave
2018-10-07 21:40:07.017 [DEBUG] [nal.protocol.ZWaveTransactionManager] - Interrupted taking message from recvQueue
	at org.openhab.binding.zwave.internal.protocol.ZWaveTransactionManager$ZWaveReceiveThread.run(ZWaveTransactionManager.java:427) [220:org.openhab.binding.zwave:2.4.0.201810061304]
2018-10-07 21:40:07.048 [DEBUG] [nal.protocol.ZWaveTransactionManager] - ZWaveReceiveThread queue empty
2018-10-07 21:40:07.050 [DEBUG] [nal.protocol.ZWaveTransactionManager] - Transaction SendNextMessage 0 out at start. Holdoff false.
2018-10-07 21:40:07.071 [DEBUG] [inding.zwave.internal.ZWaveActivator] - ZWave binding stopped.
2018-10-07 21:40:07.075 [DEBUG] [org.openhab.binding.zwave           ] - BundleEvent STOPPED - org.openhab.binding.zwave
2018-10-07 21:40:20.791 [DEBUG] [org.openhab.binding.zwave           ] - BundleEvent [unknown:512] - org.openhab.binding.zwave
2018-10-07 21:40:20.846 [DEBUG] [org.openhab.binding.zwave           ] - ServiceEvent REGISTERED - {org.eclipse.smarthome.config.discovery.usbserial.UsbSerialDiscoveryParticipant}={service.id=112, service.bundleid=220, service.scope=bundle, component.name=org.openhab.binding.zwave.discovery.ZWaveUsbSerialDiscoveryParticipant, component.id=12} - org.openhab.binding.zwave
2018-10-07 21:40:20.855 [DEBUG] [org.openhab.binding.zwave           ] - ServiceEvent REGISTERED - {org.eclipse.smarthome.core.thing.binding.ThingHandlerFactory}={service.id=113, service.bundleid=220, service.scope=bundle, component.name=org.openhab.binding.zwave.internal.ZWaveHandlerFactory, component.id=15} - org.openhab.binding.zwave
2018-10-07 21:40:20.864 [DEBUG] [org.openhab.binding.zwave           ] - BundleEvent STARTING - org.openhab.binding.zwave
2018-10-07 21:40:20.873 [DEBUG] [inding.zwave.internal.ZWaveActivator] - Z-Wave binding started. Version 2.4.0.201810061304
2018-10-07 21:40:20.876 [DEBUG] [org.openhab.binding.zwave           ] - BundleEvent STARTED - org.openhab.binding.zwave
2018-10-07 21:40:22.361 [DEBUG] [org.openhab.binding.zwave           ] - ServiceEvent REGISTERED - {org.eclipse.smarthome.core.events.EventFactory}={service.id=137, service.bundleid=220, service.scope=bundle, component.name=org.openhab.binding.zwave.event.BindingEventFactory, component.id=13} - org.openhab.binding.zwave
2018-10-07 21:40:24.943 [DEBUG] [org.openhab.binding.zwave           ] - ServiceEvent REGISTERED - {org.eclipse.smarthome.config.core.ConfigDescriptionProvider, org.eclipse.smarthome.config.core.ConfigOptionProvider}={service.id=190, service.bundleid=220, service.scope=bundle, component.name=org.openhab.binding.zwave.internal.ZWaveConfigProvider, component.id=11} - org.openhab.binding.zwave
2018-10-07 21:40:46.268 [DEBUG] [ing.zwave.handler.ZWaveSerialHandler] - Initializing ZWave serial controller.
2018-10-07 21:40:46.270 [DEBUG] [zwave.handler.ZWaveControllerHandler] - Initializing ZWave Controller zwave:serial_zstick:512.
2018-10-07 21:40:46.275 [DEBUG] [zwave.handler.ZWaveControllerHandler] - Scheduling network mesh heal for 5 hours time.
2018-10-07 21:40:46.283 [INFO ] [ing.zwave.handler.ZWaveSerialHandler] - Connecting to serial port '/dev/ttyACM0'
2018-10-07 21:40:46.340 [DEBUG] [ing.zwave.handler.ZWaveSerialHandler] - Starting receive thread
2018-10-07 21:40:46.350 [INFO ] [ing.zwave.handler.ZWaveSerialHandler] - Serial port is initialized
2018-10-07 21:40:46.350 [DEBUG] [WaveSerialHandler$ZWaveReceiveThread] - Starting ZWave thread: Receive
2018-10-07 21:40:46.351 [DEBUG] [zwave.handler.ZWaveControllerHandler] - Initialising ZWave controller
2018-10-07 21:40:46.397 [INFO ] [ve.internal.protocol.ZWaveController] - Starting ZWave controller
2018-10-07 21:40:46.397 [DEBUG] [nal.protocol.ZWaveTransactionManager] - ZWaveReceiveThread queue empty
2018-10-07 21:40:46.399 [DEBUG] [nal.protocol.ZWaveTransactionManager] - Transaction SendNextMessage 0 out at start. Holdoff false.
2018-10-07 21:40:46.399 [INFO ] [ve.internal.protocol.ZWaveController] - ZWave timeout is set to 5000ms. Soft reset is false.
2018-10-07 21:40:46.402 [DEBUG] [ve.internal.protocol.ZWaveController] - Event listener added.
2018-10-07 21:40:46.407 [DEBUG] [wave.discovery.ZWaveDiscoveryService] - Creating ZWave discovery service for zwave:serial_zstick:512 with scan time of 30
2018-10-07 21:40:46.409 [DEBUG] [wave.discovery.ZWaveDiscoveryService] - ZWave discovery: Active zwave:serial_zstick:512
2018-10-07 21:40:46.413 [DEBUG] [org.openhab.binding.zwave           ] - ServiceEvent REGISTERED - {org.eclipse.smarthome.config.discovery.DiscoveryService}={service.id=279, service.bundleid=220, service.scope=singleton} - org.openhab.binding.zwave
2018-10-07 21:40:49.616 [DEBUG] [.ZWaveController$InitializeDelayTask] - Initialising network
2018-10-07 21:40:49.650 [DEBUG] [nal.protocol.ZWaveTransactionManager] - NODE 255: Added 0 to queue - size 1
2018-10-07 21:40:49.652 [DEBUG] [nal.protocol.ZWaveTransactionManager] - Transaction SendNextMessage 0 out at start. Holdoff false.
2018-10-07 21:40:49.681 [DEBUG] [wave.internal.protocol.SerialMessage] - Assembled message buffer = 01 03 00 15 E9
2018-10-07 21:40:49.683 [DEBUG] [ing.zwave.handler.ZWaveSerialHandler] - NODE 255: Sending REQUEST Message = 01 03 00 15 E9
2018-10-07 21:40:49.692 [DEBUG] [ing.zwave.handler.ZWaveSerialHandler] - Message SENT
2018-10-07 21:40:49.696 [DEBUG] [WaveSerialHandler$ZWaveReceiveThread] - Frame length is out of limits (1)
2018-10-07 21:40:49.700 [DEBUG] [WaveSerialHandler$ZWaveReceiveThread] - Receive Message = 01 15 5A 2D 57 61 76 65 20 34 2E 36 31 00 01 95 01 10 01 15 5A 2D 57
2018-10-07 21:40:49.703 [DEBUG] [WaveSerialHandler$ZWaveReceiveThread] - Message is invalid, discarding
2018-10-07 21:40:49.717 [DEBUG] [nal.protocol.ZWaveTransactionManager] - Transaction SendNextMessage started: TID 0: [WAIT_RESPONSE] priority=Controller, requiresResponse=true, callback: 0
2018-10-07 21:40:49.722 [DEBUG] [nal.protocol.ZWaveTransactionManager] - NODE 255: Added 1 to queue - size 1
2018-10-07 21:40:49.724 [DEBUG] [nal.protocol.ZWaveTransactionManager] - Transaction SendNextMessage 1 out at start. Holdoff false.
2018-10-07 21:40:49.728 [DEBUG] [nal.protocol.ZWaveTransactionManager] - NODE 255: Added 2 to queue - size 2
2018-10-07 21:40:49.730 [DEBUG] [nal.protocol.ZWaveTransactionManager] - Transaction SendNextMessage 1 out at start. Holdoff false.
2018-10-07 21:40:49.733 [DEBUG] [nal.protocol.ZWaveTransactionManager] - NODE 255: Added 3 to queue - size 3
2018-10-07 21:40:49.735 [DEBUG] [nal.protocol.ZWaveTransactionManager] - Transaction SendNextMessage 1 out at start. Holdoff false.
2018-10-07 21:40:49.740 [DEBUG] [nal.protocol.ZWaveTransactionManager] - NODE 255: Added 4 to queue - size 4
2018-10-07 21:40:49.742 [DEBUG] [nal.protocol.ZWaveTransactionManager] - Transaction SendNextMessage 1 out at start. Holdoff false.
2018-10-07 21:40:49.970 [DEBUG] [WaveSerialHandler$ZWaveReceiveThread] - Receive Timeout - Sending NAK
2018-10-07 21:40:50.023 [DEBUG] [WaveSerialHandler$ZWaveReceiveThread] - Receive Message = 18
2018-10-07 21:40:50.026 [DEBUG] [nal.protocol.ZWaveTransactionManager] - processReceiveMessage input 0<>128 : Message: class=null[0], type=CAN[4], dest=255, callback=0, payload=
2018-10-07 21:40:50.028 [DEBUG] [nal.protocol.ZWaveTransactionManager] - Received msg (0): Message: class=null[0], type=CAN[4], dest=255, callback=0, payload=
2018-10-07 21:40:50.031 [DEBUG] [nal.protocol.ZWaveTransactionManager] - lastTransaction TID 0: [WAIT_RESPONSE] priority=Controller, requiresResponse=true, callback: 0
2018-10-07 21:40:50.034 [DEBUG] [nal.protocol.ZWaveTransactionManager] - Holdoff Timer started...
2018-10-07 21:40:50.037 [DEBUG] [nal.protocol.ZWaveTransactionManager] - TID 0: Resetting transaction
2018-10-07 21:40:50.040 [DEBUG] [nal.protocol.ZWaveTransactionManager] - NODE 255: notifyTransactionResponse TID:0 WAIT_RESPONSE
2018-10-07 21:40:50.044 [DEBUG] [nal.protocol.ZWaveTransactionManager] - NODE 255: Added 0 to queue - size 5
2018-10-07 21:40:50.056 [DEBUG] [nal.protocol.ZWaveTransactionManager] - Transaction SendNextMessage 0 out at start. Holdoff true.
2018-10-07 21:40:50.057 [DEBUG] [nal.protocol.ZWaveTransactionManager] - ZWaveReceiveThread queue empty
2018-10-07 21:40:50.058 [DEBUG] [nal.protocol.ZWaveTransactionManager] - Transaction SendNextMessage 0 out at start. Holdoff true.
2018-10-07 21:40:50.287 [DEBUG] [nal.protocol.ZWaveTransactionManager] - Transaction SendNextMessage 0 out at start. Holdoff false.
2018-10-07 21:40:50.290 [DEBUG] [wave.internal.protocol.SerialMessage] - Assembled message buffer = 01 03 00 15 E9
2018-10-07 21:40:50.292 [DEBUG] [ing.zwave.handler.ZWaveSerialHandler] - NODE 255: Sending REQUEST Message = 01 03 00 15 E9
2018-10-07 21:40:50.294 [DEBUG] [ing.zwave.handler.ZWaveSerialHandler] - Message SENT
2018-10-07 21:40:50.297 [DEBUG] [WaveSerialHandler$ZWaveReceiveThread] - Receive Message = 18
2018-10-07 21:40:50.299 [DEBUG] [nal.protocol.ZWaveTransactionManager] - processReceiveMessage input 0<>128 : Message: class=null[0], type=CAN[4], dest=255, callback=0, payload=
2018-10-07 21:40:50.301 [DEBUG] [nal.protocol.ZWaveTransactionManager] - Transaction SendNextMessage started: TID 0: [WAIT_RESPONSE] priority=Controller, requiresResponse=true, callback: 0
2018-10-07 21:40:50.301 [DEBUG] [nal.protocol.ZWaveTransactionManager] - Received msg (0): Message: class=null[0], type=CAN[4], dest=255, callback=0, payload=
2018-10-07 21:40:50.302 [DEBUG] [nal.protocol.ZWaveTransactionManager] - lastTransaction null
2018-10-07 21:40:50.304 [DEBUG] [nal.protocol.ZWaveTransactionManager] - Holdoff Timer started...
2018-10-07 21:40:50.306 [DEBUG] [nal.protocol.ZWaveTransactionManager] - TID 0: Resetting transaction
2018-10-07 21:40:50.308 [DEBUG] [nal.protocol.ZWaveTransactionManager] - NODE 255: notifyTransactionResponse TID:0 WAIT_RESPONSE
2018-10-07 21:40:50.310 [DEBUG] [nal.protocol.ZWaveTransactionManager] - NODE 255: Added 0 to queue - size 5
2018-10-07 21:40:50.312 [DEBUG] [nal.protocol.ZWaveTransactionManager] - Transaction SendNextMessage 0 out at start. Holdoff true.
2018-10-07 21:40:50.314 [DEBUG] [nal.protocol.ZWaveTransactionManager] - ZWaveReceiveThread queue empty
2018-10-07 21:40:50.316 [DEBUG] [nal.protocol.ZWaveTransactionManager] - Transaction SendNextMessage 0 out at start. Holdoff true.
2018-10-07 21:40:50.557 [DEBUG] [nal.protocol.ZWaveTransactionManager] - Transaction SendNextMessage 0 out at start. Holdoff false.
2018-10-07 21:40:50.558 [DEBUG] [wave.internal.protocol.SerialMessage] - Assembled message buffer = 01 03 00 15 E9
2018-10-07 21:40:50.561 [DEBUG] [ing.zwave.handler.ZWaveSerialHandler] - NODE 255: Sending REQUEST Message = 01 03 00 15 E9
2018-10-07 21:40:50.562 [DEBUG] [ing.zwave.handler.ZWaveSerialHandler] - Message SENT
2018-10-07 21:40:50.564 [DEBUG] [nal.protocol.ZWaveTransactionManager] - Transaction SendNextMessage started: TID 0: [WAIT_RESPONSE] priority=Controller, requiresResponse=true, callback: 0
2018-10-07 21:40:51.210 [DEBUG] [WaveSerialHandler$ZWaveReceiveThread] - Protocol error (OOF). Got 0x20.
2018-10-07 21:40:51.212 [DEBUG] [WaveSerialHandler$ZWaveReceiveThread] - Protocol error (OOF). Got 0x34.
2018-10-07 21:40:51.213 [DEBUG] [WaveSerialHandler$ZWaveReceiveThread] - Protocol error (OOF). Got 0x2E.
2018-10-07 21:40:51.215 [DEBUG] [WaveSerialHandler$ZWaveReceiveThread] - Protocol error (OOF). Got 0x36.
2018-10-07 21:40:51.217 [DEBUG] [WaveSerialHandler$ZWaveReceiveThread] - Protocol error (OOF). Got 0x31.
2018-10-07 21:40:52.567 [DEBUG] [sactionManager$ZWaveTransactionTimer] - NODE 255: TID 0: Timeout at state WAIT_RESPONSE. 3 retries remaining.
2018-10-07 21:40:52.569 [DEBUG] [sactionManager$ZWaveTransactionTimer] - TID 0: Transaction is current transaction, so clearing!!!!!
2018-10-07 21:40:52.571 [DEBUG] [e.internal.protocol.ZWaveTransaction] - TID 0: Transaction CANCELLED
2018-10-07 21:40:52.579 [DEBUG] [nal.protocol.ZWaveTransactionManager] - NODE 255: notifyTransactionResponse TID:0 CANCELLED
2018-10-07 21:40:52.586 [DEBUG] [nal.protocol.ZWaveTransactionManager] - Transaction SendNextMessage 0 out at start. Holdoff false.
2018-10-07 21:40:52.590 [DEBUG] [wave.internal.protocol.SerialMessage] - Assembled message buffer = 01 03 00 20 DC
2018-10-07 21:40:52.599 [DEBUG] [ing.zwave.handler.ZWaveSerialHandler] - NODE 255: Sending REQUEST Message = 01 03 00 20 DC
2018-10-07 21:40:52.603 [DEBUG] [ing.zwave.handler.ZWaveSerialHandler] - Message SENT
2018-10-07 21:40:52.607 [DEBUG] [nal.protocol.ZWaveTransactionManager] - Transaction SendNextMessage started: TID 1: [WAIT_RESPONSE] priority=Controller, requiresResponse=true, callback: 0
2018-10-07 21:40:54.608 [DEBUG] [sactionManager$ZWaveTransactionTimer] - NODE 255: TID 1: Timeout at state WAIT_RESPONSE. 3 retries remaining.
2018-10-07 21:40:54.611 [DEBUG] [sactionManager$ZWaveTransactionTimer] - TID 1: Transaction is current transaction, so clearing!!!!!
2018-10-07 21:40:54.625 [DEBUG] [e.internal.protocol.ZWaveTransaction] - TID 1: Transaction CANCELLED
2018-10-07 21:40:54.627 [DEBUG] [nal.protocol.ZWaveTransactionManager] - NODE 255: notifyTransactionResponse TID:1 CANCELLED
2018-10-07 21:40:54.630 [DEBUG] [nal.protocol.ZWaveTransactionManager] - Transaction SendNextMessage 0 out at start. Holdoff false.
2018-10-07 21:40:54.636 [DEBUG] [wave.internal.protocol.SerialMessage] - Assembled message buffer = 01 03 00 07 FB
2018-10-07 21:40:54.639 [DEBUG] [ing.zwave.handler.ZWaveSerialHandler] - NODE 255: Sending REQUEST Message = 01 03 00 07 FB
2018-10-07 21:40:54.641 [DEBUG] [ing.zwave.handler.ZWaveSerialHandler] - Message SENT
2018-10-07 21:40:54.643 [DEBUG] [WaveSerialHandler$ZWaveReceiveThread] - Receive Message = 15
2018-10-07 21:40:54.645 [DEBUG] [nal.protocol.ZWaveTransactionManager] - processReceiveMessage input 0<>128 : Message: class=null[0], type=NAK[3], dest=255, callback=0, payload=
2018-10-07 21:40:54.645 [DEBUG] [nal.protocol.ZWaveTransactionManager] - Transaction SendNextMessage started: TID 2: [WAIT_RESPONSE] priority=Controller, requiresResponse=true, callback: 0
2018-10-07 21:40:54.648 [DEBUG] [nal.protocol.ZWaveTransactionManager] - Received msg (0): Message: class=null[0], type=NAK[3], dest=255, callback=0, payload=
2018-10-07 21:40:54.650 [DEBUG] [nal.protocol.ZWaveTransactionManager] - lastTransaction TID 2: [WAIT_RESPONSE] priority=Controller, requiresResponse=true, callback: 0
2018-10-07 21:40:54.654 [DEBUG] [nal.protocol.ZWaveTransactionManager] - Holdoff Timer started...
2018-10-07 21:40:54.658 [DEBUG] [nal.protocol.ZWaveTransactionManager] - TID 2: Resetting transaction
2018-10-07 21:40:54.661 [DEBUG] [nal.protocol.ZWaveTransactionManager] - NODE 255: notifyTransactionResponse TID:2 WAIT_RESPONSE
2018-10-07 21:40:54.667 [DEBUG] [nal.protocol.ZWaveTransactionManager] - NODE 255: Added 2 to queue - size 3
2018-10-07 21:40:54.671 [DEBUG] [nal.protocol.ZWaveTransactionManager] - Transaction SendNextMessage 0 out at start. Holdoff true.
2018-10-07 21:40:54.674 [DEBUG] [nal.protocol.ZWaveTransactionManager] - ZWaveReceiveThread queue empty
2018-10-07 21:40:54.677 [DEBUG] [nal.protocol.ZWaveTransactionManager] - Transaction SendNextMessage 0 out at start. Holdoff true.
2018-10-07 21:40:54.907 [DEBUG] [nal.protocol.ZWaveTransactionManager] - Transaction SendNextMessage 0 out at start. Holdoff false.
2018-10-07 21:40:54.912 [DEBUG] [wave.internal.protocol.SerialMessage] - Assembled message buffer = 01 03 00 07 FB
2018-10-07 21:40:54.917 [DEBUG] [ing.zwave.handler.ZWaveSerialHandler] - NODE 255: Sending REQUEST Message = 01 03 00 07 FB
2018-10-07 21:40:54.920 [DEBUG] [ing.zwave.handler.ZWaveSerialHandler] - Message SENT
2018-10-07 21:40:54.923 [DEBUG] [WaveSerialHandler$ZWaveReceiveThread] - Receive Message = 18
2018-10-07 21:40:54.923 [DEBUG] [nal.protocol.ZWaveTransactionManager] - Transaction SendNextMessage started: TID 2: [WAIT_RESPONSE] priority=Controller, requiresResponse=true, callback: 0
2018-10-07 21:40:54.925 [DEBUG] [nal.protocol.ZWaveTransactionManager] - processReceiveMessage input 0<>128 : Message: class=null[0], type=CAN[4], dest=255, callback=0, payload=
2018-10-07 21:40:54.928 [DEBUG] [nal.protocol.ZWaveTransactionManager] - Received msg (0): Message: class=null[0], type=CAN[4], dest=255, callback=0, payload=
2018-10-07 21:40:54.930 [DEBUG] [nal.protocol.ZWaveTransactionManager] - lastTransaction TID 2: [WAIT_RESPONSE] priority=Controller, requiresResponse=true, callback: 0
2018-10-07 21:40:54.932 [DEBUG] [nal.protocol.ZWaveTransactionManager] - Holdoff Timer started...
2018-10-07 21:40:54.935 [DEBUG] [nal.protocol.ZWaveTransactionManager] - TID 2: Resetting transaction
2018-10-07 21:40:54.937 [DEBUG] [nal.protocol.ZWaveTransactionManager] - NODE 255: notifyTransactionResponse TID:2 WAIT_RESPONSE
2018-10-07 21:40:54.942 [DEBUG] [nal.protocol.ZWaveTransactionManager] - NODE 255: Added 2 to queue - size 3
2018-10-07 21:40:54.944 [DEBUG] [nal.protocol.ZWaveTransactionManager] - Transaction SendNextMessage 0 out at start. Holdoff true.
2018-10-07 21:40:54.947 [DEBUG] [nal.protocol.ZWaveTransactionManager] - ZWaveReceiveThread queue empty
2018-10-07 21:40:54.949 [DEBUG] [nal.protocol.ZWaveTransactionManager] - Transaction SendNextMessage 0 out at start. Holdoff true.
2018-10-07 21:40:55.184 [DEBUG] [nal.protocol.ZWaveTransactionManager] - Transaction SendNextMessage 0 out at start. Holdoff false.
2018-10-07 21:40:55.189 [DEBUG] [wave.internal.protocol.SerialMessage] - Assembled message buffer = 01 03 00 07 FB
2018-10-07 21:40:55.193 [DEBUG] [ing.zwave.handler.ZWaveSerialHandler] - NODE 255: Sending REQUEST Message = 01 03 00 07 FB
2018-10-07 21:40:55.198 [DEBUG] [ing.zwave.handler.ZWaveSerialHandler] - Message SENT
2018-10-07 21:40:55.202 [DEBUG] [nal.protocol.ZWaveTransactionManager] - Transaction SendNextMessage started: TID 2: [WAIT_RESPONSE] priority=Controller, requiresResponse=true, callback: 0
2018-10-07 21:40:56.140 [DEBUG] [WaveSerialHandler$ZWaveReceiveThread] - Receive Message = 01 07 05 1B 01 15 04 00 00
2018-10-07 21:40:56.144 [DEBUG] [WaveSerialHandler$ZWaveReceiveThread] - Message is invalid, discarding
2018-10-07 21:40:56.156 [DEBUG] [WaveSerialHandler$ZWaveReceiveThread] - Receive Message = 01 2B 01 07 05 1B 01 15 04 00 00 01 FE 87 7F 88 CF 3F C0 47 FB DF FD E0 67 00 80 80 00 80 86 00 00 00 E8 73 00 80 0F 00 00 60 5A 00 52
2018-10-07 21:40:56.165 [DEBUG] [nal.protocol.ZWaveTransactionManager] - processReceiveMessage input 0<>128 : Message: class=SerialApiGetCapabilities[7], type=Response[1], dest=255, callback=0, payload=05 1B 01 15 04 00 00 01 FE 87 7F 88 CF 3F C0 47 FB DF FD E0 67 00 80 80 00 80 86 00 00 00 E8 73 00 80 0F 00 00 60 5A 00
2018-10-07 21:40:56.171 [DEBUG] [nal.protocol.ZWaveTransactionManager] - Received msg (0): Message: class=SerialApiGetCapabilities[7], type=Response[1], dest=255, callback=0, payload=05 1B 01 15 04 00 00 01 FE 87 7F 88 CF 3F C0 47 FB DF FD E0 67 00 80 80 00 80 86 00 00 00 E8 73 00 80 0F 00 00 60 5A 00
2018-10-07 21:40:56.174 [DEBUG] [nal.protocol.ZWaveTransactionManager] - lastTransaction TID 2: [WAIT_RESPONSE] priority=Controller, requiresResponse=true, callback: 0
2018-10-07 21:40:56.176 [DEBUG] [nal.protocol.ZWaveTransactionManager] - Checking outstanding transactions: 1
2018-10-07 21:40:56.178 [DEBUG] [nal.protocol.ZWaveTransactionManager] - Last transaction: TID 2: [WAIT_RESPONSE] priority=Controller, requiresResponse=true, callback: 0
2018-10-07 21:40:56.182 [DEBUG] [ve.internal.protocol.ZWaveController] - Incoming Message: Message: class=SerialApiGetCapabilities[7], type=Response[1], dest=255, callback=0, payload=05 1B 01 15 04 00 00 01 FE 87 7F 88 CF 3F C0 47 FB DF FD E0 67 00 80 80 00 80 86 00 00 00 E8 73 00 80 0F 00 00 60 5A 00
2018-10-07 21:40:56.232 [DEBUG] [e.internal.protocol.ZWaveTransaction] - TID 2: Transaction COMPLETED
2018-10-07 21:40:56.238 [DEBUG] [nal.protocol.ZWaveTransactionManager] - NODE 255: Added 5 to queue - size 3
2018-10-07 21:40:56.240 [DEBUG] [nal.protocol.ZWaveTransactionManager] - Transaction SendNextMessage 1 out at start. Holdoff false.
2018-10-07 21:40:56.242 [DEBUG] [nal.protocol.ZWaveTransactionManager] - NODE 255: Response processed after 1040ms
2018-10-07 21:40:56.244 [DEBUG] [nal.protocol.ZWaveTransactionManager] - NODE 255: TID 2: Transaction completed
2018-10-07 21:40:56.245 [DEBUG] [nal.protocol.ZWaveTransactionManager] - NODE 255: notifyTransactionResponse TID:2 DONE
2018-10-07 21:40:56.248 [DEBUG] [nal.protocol.ZWaveTransactionManager] - ZWaveReceiveThread queue empty
2018-10-07 21:40:56.249 [DEBUG] [nal.protocol.ZWaveTransactionManager] - Transaction SendNextMessage 0 out at start. Holdoff false.
2018-10-07 21:40:56.251 [DEBUG] [wave.internal.protocol.SerialMessage] - Assembled message buffer = 01 05 00 06 96 0F 65
2018-10-07 21:40:56.252 [DEBUG] [ing.zwave.handler.ZWaveSerialHandler] - NODE 255: Sending REQUEST Message = 01 05 00 06 96 0F 65
2018-10-07 21:40:56.254 [DEBUG] [ing.zwave.handler.ZWaveSerialHandler] - Message SENT
2018-10-07 21:40:56.256 [DEBUG] [nal.protocol.ZWaveTransactionManager] - Transaction SendNextMessage started: TID 3: [WAIT_RESPONSE] priority=Controller, requiresResponse=true, callback: 0
2018-10-07 21:40:56.256 [DEBUG] [WaveSerialHandler$ZWaveReceiveThread] - Receive Message = 06
2018-10-07 21:40:56.259 [DEBUG] [nal.protocol.ZWaveTransactionManager] - processReceiveMessage input 0<>128 : Message: class=null[0], type=ACK[2], dest=255, callback=0, payload=
2018-10-07 21:40:56.261 [DEBUG] [nal.protocol.ZWaveTransactionManager] - Received msg (0): Message: class=null[0], type=ACK[2], dest=255, callback=0, payload=
2018-10-07 21:40:56.263 [DEBUG] [nal.protocol.ZWaveTransactionManager] - lastTransaction TID 3: [WAIT_RESPONSE] priority=Controller, requiresResponse=true, callback: 0
2018-10-07 21:40:56.264 [DEBUG] [nal.protocol.ZWaveTransactionManager] - Received msg: ACK
2018-10-07 21:40:56.265 [DEBUG] [nal.protocol.ZWaveTransactionManager] - ZWaveReceiveThread queue empty
2018-10-07 21:40:56.266 [DEBUG] [nal.protocol.ZWaveTransactionManager] - Transaction SendNextMessage 1 out at start. Holdoff false.
2018-10-07 21:40:58.258 [DEBUG] [sactionManager$ZWaveTransactionTimer] - NODE 255: TID 3: Timeout at state WAIT_RESPONSE. 3 retries remaining.
2018-10-07 21:40:58.261 [DEBUG] [sactionManager$ZWaveTransactionTimer] - TID 3: Transaction is current transaction, so clearing!!!!!
2018-10-07 21:40:58.262 [DEBUG] [e.internal.protocol.ZWaveTransaction] - TID 3: Transaction CANCELLED
2018-10-07 21:40:58.264 [DEBUG] [nal.protocol.ZWaveTransactionManager] - NODE 255: notifyTransactionResponse TID:3 CANCELLED
2018-10-07 21:40:58.266 [DEBUG] [nal.protocol.ZWaveTransactionManager] - Transaction SendNextMessage 0 out at start. Holdoff false.
2018-10-07 21:40:58.273 [DEBUG] [wave.internal.protocol.SerialMessage] - Assembled message buffer = 01 03 00 56 AA
2018-10-07 21:40:58.275 [DEBUG] [ing.zwave.handler.ZWaveSerialHandler] - NODE 255: Sending REQUEST Message = 01 03 00 56 AA
2018-10-07 21:40:58.277 [DEBUG] [ing.zwave.handler.ZWaveSerialHandler] - Message SENT
2018-10-07 21:40:58.279 [DEBUG] [nal.protocol.ZWaveTransactionManager] - Transaction SendNextMessage started: TID 4: [WAIT_RESPONSE] priority=Controller, requiresResponse=true, callback: 0
2018-10-07 21:40:58.279 [DEBUG] [WaveSerialHandler$ZWaveReceiveThread] - Receive Message = 18
2018-10-07 21:40:58.284 [DEBUG] [nal.protocol.ZWaveTransactionManager] - processReceiveMessage input 0<>128 : Message: class=null[0], type=CAN[4], dest=255, callback=0, payload=
2018-10-07 21:40:58.288 [DEBUG] [nal.protocol.ZWaveTransactionManager] - Received msg (0): Message: class=null[0], type=CAN[4], dest=255, callback=0, payload=
2018-10-07 21:40:58.290 [DEBUG] [nal.protocol.ZWaveTransactionManager] - lastTransaction TID 4: [WAIT_RESPONSE] priority=Controller, requiresResponse=true, callback: 0
2018-10-07 21:40:58.292 [DEBUG] [nal.protocol.ZWaveTransactionManager] - Holdoff Timer started...

Regards,
Burzin

2

Have you set your serial to persistent? See this link https://community.openhab.org/t/raspberry-pi-make-serial-usb-ports-persistent-via-symlinks/35847?u=h102

3

Your log shows differently…

Autodiscovery of USB devices is a new ESH feature. You may have two controllers showing up, and you are looking at the one that is not configured.

4

@H102,

Thanks. The Z-Wave dongle is a new device, but I’ve been using the Insteon PLM for a while and haven’t had any such problems. In fact, I don’t have multiple ttyACM ports. However, I’ll take a look at making the ports persistent anyway. It may save me grief in the future.

Regards,
Burzin

5

Hi @5iver,

Thanks. I was wondering about the ZWave messages I saw in the logs and if I actually had something going on. I don’t have multiple controllers showing up in openHAB-- at least not that I can see in the PaperUI and Habmin. In fact, I’ve deleted the controller that I see several times and re-added it. So, from what you are saying, I suspect a phantom controller is in play. How do I purge all the ZWave devices from my openHAB system? Is it as simple as deleting from the PaperUI and HABmin, deleting the binding, and rebooting?

Regards,
Burzin

6

You’ve done a manual install of the zwave binding. I’d double check you only have one binding installed, as this can cause some irregularities. It’s easy to check… in Karaf, do a…

list -s |grep zwave

If you see more than one, remove it through Paper UI. You’ll likely need the serial transport installed then…

feature:install openhab-transport-serial

Or just use this, which will take care of uninstalling, upgrading the binding, and installing the serial transport. Select Master (not development)…

7

Hi @5iver,

I noticed this on GitHub

This script is interactive and will prompt for input. It requires to be executed from the addons directory on the openHAB server, using the same account that runs openHAB .

Is this account typically openhab?

Regards,
Burzin

8

Hello @5iver and @H102,

Thanks for all the help. Problem solved. Here’s a recap

  1. After installing the 2.4.0 Z-Wave binding via Scott’s script, configuring the controller and rebooting, the Z-Wave controller came up (and it automatically discovered my second Z-Wave device!) However, after another reboot the controller reported offline. I was able to fix this by changing the USB port and saving the result and then changing the port back again to the correct setting and saving the configuration. After these gyrations, the controller and the second device both reported online. Of course, another reboot resulted in them being offline again.

  2. I think I traced the source of my original issue with the 2.3.0 Z-Wave binding and the 2.4.0 Z-Wave binding to the following ZWave.me services

zbw_connect
z-way-server

I stopped them and then disabled them. After this and another reboot, everything worked properly. (I don’t recall if I needed to reconfigure the controller. However, after multiple reboots Z-Wave comes up properly every time.)

  1. The Z-Wave controller offline after reboot appears to have been caused by an improperly installed Z-Wave binding

  2. Although strictly unnecessary in my case, I added the UDEV rules to my Raspberry Pi per H102’s suggestion. The advantage in my case is that it makes identifying the ports to use clearer as I now have symlinks to /dev/ttyUSB-Insteon and /dev/ttyUSB-W-Zave

Now on to washing machine notifications via my Z-Wave switch.

Regards,
Burzin

2 Likes
9

Thanks @Burzin_Sumariwalla for sharing your solution, I’m sure others will find this helpful.
Click the square box on your post to mark as solved.

Thanks again

10

Hi, where and how did find these both services: zbw_connect and z-way-server?

11

I think I found reference to them in the Z Wave.ME documentation (which is awful). As for finding the service on Linux, try

ps -ef | grep -i zbw_connect
ps -ef | grep -i z-way-server

Regards,
Burzin

12

Thanks, I cannot find either of them, so in my case it must be something else. I’ve already spent hours on this issue and cannot get it done… I installed Z-Wave binding 2.4.0 via OH2/PaperUI, I configured UDEV and symlinks and this part works fine, i cannot figure out why after reboot Z-wave controller cannot connect and it is required to press soft-restart to get it back online.

Does anyone have any other hints perhaps? Where to look for.
I installed the OH2 on Linux Ubuntu 18.4 LTS via the automatic setup. I tried to clear the tmp and cache folders and it did the trick but only for the first restart, subsequent restarts gave negative outcome.

13

I have the same issue. Did you discover anything?
My problem started after moving to the 2.4.0 SNAPSHOT build.

14

Unsure if I solved the issue permanently, however after reinstalling OH2 via OpenHABIAN last two reboots were successful, meaning Zwave controller got attached properly.

15

Yikes. Hoping to avoid having to do a full re-install. Are you on the snapshot, or the stable release?

16

stable release

17

I am experiencing this issue as well with 2.5.0 as of 20190709

openhab> bundle:list | grep -i wave
187 │ Active   │  80 │ 2.5.0.201907090433     │ openHAB Add-ons :: Bundles :: ZWave Binding

I have to

bundle:stop 187
bundle:start 187

to get it working. As far as I remember this is a known ESH issue: The serial code is loading too late.

I could workaround this by doing something like

mv /usr/share/openhab2/addons/org.openhab.binding.zwave-2.5.0-SNAPSHOT.jar /usr/share/openhab2/addons/org.openhab.binding.zwave-2.5.0-SNAPSHOT.jar.tmp
sleep 5
mv /usr/share/openhab2/addons/org.openhab.binding.zwave-2.5.0-SNAPSHOT.jar.tmp /usr/share/openhab2/addons/org.openhab.binding.zwave-2.5.0-SNAPSHOT.jar

Pretty much brute force - does anybody has a more elegant solution?

18

I found a more elegant solution now. Create a script called restartZwave.sh:

#!/bin/sh

OPENHABBIN=/usr/share/openhab2/runtime/bin/client

bid=`echo "bundle:list --no-format" | $OPENHABBIN | grep ZWave | cut -f 1`
echo "bundle:stop $bid \nbundle:start $bid " | $OPENHABBIN

This script will find the zwave bundle id and restart zwave.
Create the following rule:

rule "rgconf_1"
when Item viTimeEvent_System_Starting changed to OFF 
then
    // uncomment to reload jsr 223 scripts
    //executeCommandLine("/bin/sh@@-c@@/usr/bin/touch /etc/openhab2/automation/jsr223/*", 1000)
    //Thread.sleep(1000);
    executeCommandLine("/home/openhabian/restartZwave.sh")
end

viTimeEvent_System_Starting is a switch item which is set to ON at system start and 5 minutes later is switched to OFF. I use this to inhibit certain actions while the system is starting up.

19

This issue was solved for me with the Milestone build (starting at snapshot #1656)

20

I am a bit lost now. I can only locate a zwave binding build “#730” as of today. Is there somewhere a mapping between snapshot number and build number?

And what is your output of “bundle:list | grep -i wave”