Zwave controler is always offline

thefathefa · September 15, 2019, 4:21pm

Hello,

I had several problems with my openhab config a few weeks ago which I finally recovered for all but one thing : the zwave controller keeps appearing “offline”.
But before this, my zwave things have been running file for the last 12 months…

I have not been able to find the cause of my controller appearing offline, so I’m looking for some help on what other steps I could take that could highlight it…

One thing that I noticed is that in the past the USB zwave stick was (I’m almost sure on tty/ACM0 and it seems to show up now on tty/AMA0, not sure why).

Many thanks up-front,

My config:

###############################################################################
################# openHABianPi #################################### 7.05.170509
###############################################################################
##   Release = Raspbian GNU/Linux 9 (stretch)
##    Kernel = Linux 4.9.41-v7+
##  Platform = Raspberry Pi 3 Model B Rev 1.2
##    Uptime = 1 day(s). 4:59:27
## CPU Usage = 7.25 % avg over 4 cpu(s)  (4 core(s) x 1 socket(s))
##  CPU Load = 1m: 0.47, 5m: 0.22, 15m: 0.23
##    Memory = Free: 0.03GB (3%), Used: 0.92GB (97%), Total: 0.95GB
##      Swap = Free: 0.08GB (85%), Used: 0.01GB (15%), Total: 0.09GB
##      Root = Free: 16.67GB (61%), Used: 10.60GB (39%), Total: 28.46GB
###############################################################################

                  openHAB 2.5.0~M3-1 (Milestone Build)

Traces of the log with zwave keyword filter (afer having activated debug level for zwave module):

2019-09-15 17:30:54.144 [INFO ] [el.core.internal.ModelRepositoryImpl] - Loading model 'zwave.items'
2019-09-15 17:31:26.225 [DEBUG] [org.openhab.binding.zwave           ] - BundleEvent STARTING - org.openhab.binding.zwave
2019-09-15 17:31:26.311 [DEBUG] [org.openhab.binding.zwave           ] - BundleEvent STARTED - org.openhab.binding.zwave
2019-09-15 17:31:26.520 [DEBUG] [org.openhab.binding.zwave           ] - ServiceEvent REGISTERED - {org.eclipse.smarthome.config.core.ConfigDescriptionProvider, org.eclipse.smarthome.config.core.ConfigOptionProvider}={service.id=363, service.bundleid=247, service.scope=bundle, component.name=org.openhab.binding.zwave.internal.ZWaveConfigProvider, component.id=217} - org.openhab.binding.zwave
2019-09-15 17:31:28.598 [DEBUG] [org.openhab.binding.zwave           ] - ServiceEvent REGISTERED - {org.eclipse.smarthome.core.thing.binding.ThingHandlerFactory}={service.id=386, service.bundleid=247, service.scope=bundle, component.name=org.openhab.binding.zwave.internal.ZWaveHandlerFactory, component.id=218} - org.openhab.binding.zwave
2019-09-15 17:31:40.642 [hingStatusInfoChangedEvent] - 'zwave:device:512:node3' changed from UNINITIALIZED to UNINITIALIZED (BRIDGE_UNINITIALIZED)
2019-09-15 17:31:40.644 [hingStatusInfoChangedEvent] - 'zwave:device:512:node2' changed from UNINITIALIZED to UNINITIALIZED (BRIDGE_UNINITIALIZED)
2019-09-15 17:31:40.647 [hingStatusInfoChangedEvent] - 'zwave:device:512:node5' changed from UNINITIALIZED to UNINITIALIZED (BRIDGE_UNINITIALIZED)
2019-09-15 17:31:40.649 [hingStatusInfoChangedEvent] - 'zwave:device:512:node4' changed from UNINITIALIZED to UNINITIALIZED (BRIDGE_UNINITIALIZED)
2019-09-15 17:31:40.666 [DEBUG] [wave.discovery.ZWaveDiscoveryService] - Creating ZWave discovery service for zwave:serial_zstick:512 with scan time of 60
2019-09-15 17:31:40.670 [DEBUG] [wave.discovery.ZWaveDiscoveryService] - ZWave discovery: Active zwave:serial_zstick:512
2019-09-15 17:31:40.672 [INFO ] [zwave.handler.ZWaveControllerHandler] - Attempting to add listener when controller is null
2019-09-15 17:31:40.677 [DEBUG] [org.openhab.binding.zwave           ] - ServiceEvent REGISTERED - {org.eclipse.smarthome.config.discovery.DiscoveryService}={service.id=397, service.bundleid=247, service.scope=singleton} - org.openhab.binding.zwave
2019-09-15 17:31:40.975 [hingStatusInfoChangedEvent] - 'zwave:serial_zstick:512' changed from UNINITIALIZED to INITIALIZING
2019-09-15 17:31:40.993 [DEBUG] [ing.zwave.handler.ZWaveSerialHandler] - Initializing ZWave serial controller.
2019-09-15 17:31:40.996 [DEBUG] [zwave.handler.ZWaveControllerHandler] - Initializing ZWave Controller zwave:serial_zstick:512.
2019-09-15 17:31:41.002 [DEBUG] [zwave.handler.ZWaveControllerHandler] - Scheduling network mesh heal for 9 hours time.
2019-09-15 17:31:41.012 [hingStatusInfoChangedEvent] - 'zwave:serial_zstick:512' changed from INITIALIZING to OFFLINE (BRIDGE_OFFLINE): Controller is offline
2019-09-15 17:31:41.026 [INFO ] [ing.zwave.handler.ZWaveSerialHandler] - Connecting to serial port '/dev/ttyAMA0'
2019-09-15 17:31:41.086 [DEBUG] [org.openhab.binding.zwave           ] - ServiceEvent REGISTERED - {org.eclipse.smarthome.config.core.status.ConfigStatusProvider}={service.id=400, service.bundleid=247, service.scope=singleton} - org.openhab.binding.zwave
2019-09-15 17:31:41.089 [DEBUG] [org.openhab.binding.zwave           ] - ServiceEvent REGISTERED - {org.eclipse.smarthome.config.core.status.ConfigStatusProvider}={service.id=398, service.bundleid=247, service.scope=singleton} - org.openhab.binding.zwave
2019-09-15 17:31:41.088 [DEBUG] [org.openhab.binding.zwave           ] - ServiceEvent REGISTERED - {org.eclipse.smarthome.config.core.status.ConfigStatusProvider}={service.id=401, service.bundleid=247, service.scope=singleton} - org.openhab.binding.zwave
2019-09-15 17:31:41.086 [DEBUG] [org.openhab.binding.zwave           ] - ServiceEvent REGISTERED - {org.eclipse.smarthome.config.core.status.ConfigStatusProvider}={service.id=399, service.bundleid=247, service.scope=singleton} - org.openhab.binding.zwave
2019-09-15 17:31:41.108 [DEBUG] [org.openhab.binding.zwave           ] - ServiceEvent REGISTERED - {org.eclipse.smarthome.config.core.status.ConfigStatusProvider}={service.id=402, service.bundleid=247, service.scope=singleton} - org.openhab.binding.zwave
2019-09-15 17:31:41.110 [DEBUG] [ing.zwave.handler.ZWaveSerialHandler] - Starting receive thread
2019-09-15 17:31:41.138 [INFO ] [ing.zwave.handler.ZWaveSerialHandler] - Serial port is initialized
2019-09-15 17:31:41.140 [DEBUG] [zwave.handler.ZWaveControllerHandler] - Initialising ZWave controller
2019-09-15 17:31:41.164 [DEBUG] [WaveSerialHandler$ZWaveReceiveThread] - Starting ZWave thread: Receive
2019-09-15 17:31:41.194 [hingStatusInfoChangedEvent] - 'zwave:device:512:node9' changed from UNINITIALIZED to INITIALIZING
2019-09-15 17:31:41.198 [hingStatusInfoChangedEvent] - 'zwave:device:512:node7' changed from UNINITIALIZED to INITIALIZING
2019-09-15 17:31:41.213 [hingStatusInfoChangedEvent] - 'zwave:device:512:node8' changed from UNINITIALIZED to INITIALIZING
2019-09-15 17:31:41.212 [DEBUG] [ding.zwave.handler.ZWaveThingHandler] - Initializing ZWave thing handler zwave:device:512:node9.
2019-09-15 17:31:41.218 [hingStatusInfoChangedEvent] - 'zwave:device:512:node2' changed from UNINITIALIZED (BRIDGE_UNINITIALIZED) to INITIALIZING
2019-09-15 17:31:41.222 [hingStatusInfoChangedEvent] - 'zwave:device:512:node6' changed from UNINITIALIZED to INITIALIZING
2019-09-15 17:31:41.227 [hingStatusInfoChangedEvent] - 'zwave:device:512:node9' changed from INITIALIZING to OFFLINE (BRIDGE_OFFLINE): Controller is offline

I have ran the following checks on the USB / serial interfaces:

[17:59:27] openhabian@openHABianPi:~$ dmesg -T | grep tty
[Sat Sep 14 13:15:01 2019] Kernel command line: 8250.nr_uarts=0 bcm2708_fb.fbwidth=656 bcm2708_fb.fbheight=416 bcm2708_fb.fbdepth=16 bcm2708_fb.fbswap=1 vc_mem.mem_base=0x3f000000 vc_mem.mem_size=0x3f600000  dwc_otg.lpm_enable=0 console=tty1 root=PARTUUID=1c983187-02 rootfstype=ext4 elevator=deadline fsck.repair=yes rootwait
[Sat Sep 14 13:15:01 2019] console [tty1] enabled
[Sat Sep 14 13:15:01 2019] 3f201000.serial: ttyAMA0 at MMIO 0x3f201000 (irq = 87, base_baud = 0) is a PL011 rev2
[17:59:32] openhabian@openHABianPi:~$ dmesg -T | grep tty
[Sat Sep 14 13:15:01 2019] Kernel command line: 8250.nr_uarts=0 bcm2708_fb.fbwidth=656 bcm2708_fb.fbheight=416 bcm2708_fb.fbdepth=16 bcm2708_fb.fbswap=1 vc_mem.mem_base=0x3f000000 vc_mem.mem_size=0x3f600000  dwc_otg.lpm_enable=0 console=tty1 root=PARTUUID=1c983187-02 rootfstype=ext4 elevator=deadline fsck.repair=yes rootwait
[Sat Sep 14 13:15:01 2019] console [tty1] enabled
[Sat Sep 14 13:15:01 2019] 3f201000.serial: ttyAMA0 at MMIO 0x3f201000 (irq = 87, base_baud = 0) is a PL011 rev2
[18:17:07] openhabian@openHABianPi:~$ cat /etc/default/openhab2 | grep SerialPorts
##   EXTRA_JAVA_OPTS="-Dgnu.io.rxtx.SerialPorts=/dev/ttyAMA0"
##   EXTRA_JAVA_OPTS="-Dgnu.io.rxtx.SerialPorts=/dev/ttyUSB0:/dev/ttyS0:/dev/ttyS2:/dev/ttyACM0:/dev/ttyAMA0"
##   EXTRA_JAVA_OPTS="-Djna.library.path=/lib/arm-linux-gnueabihf/ -Duser.timezone=Europe/Berlin -Dgnu.io.rxtx.SerialPorts=/dev/ttyS0"
EXTRA_JAVA_OPTS="-Xms250m -Xmx350m -Dgnu.io.rxtx.SerialPorts=/dev/ttyUSB0:/dev/ttyS0:/dev/ttyS2:/dev/ttyACM0:/dev/ttyAMA0"
[18:17:47] openhabian@openHABianPi:~$ ls -l /dev/ttyAMA0
crw-rw---- 1 root dialout 204, 64 Sep 15 17:31 /dev/ttyAMA0
[18:17:55] openhabian@openHABianPi:~$ dmesg | grep -i usb
[    0.152177] usbcore: registered new interface driver usbfs
[    0.152280] usbcore: registered new interface driver hub
[    0.152395] usbcore: registered new device driver usb
[    0.300145] usbcore: registered new interface driver smsc95xx
[    0.754628] dwc_otg 3f980000.usb: DWC OTG Controller
[    0.755984] dwc_otg 3f980000.usb: new USB bus registered, assigned bus number 1
[    0.757370] dwc_otg 3f980000.usb: irq 62, io mem 0x00000000
[    0.761539] usb usb1: New USB device found, idVendor=1d6b, idProduct=0002
[    0.762887] usb usb1: New USB device strings: Mfr=3, Product=2, SerialNumber=1
[    0.764222] usb usb1: Product: DWC OTG Controller
[    0.765530] usb usb1: Manufacturer: Linux 4.9.41-v7+ dwc_otg_hcd
[    0.766850] usb usb1: SerialNumber: 3f980000.usb
[    0.768959] hub 1-0:1.0: USB hub found
[    0.772431] usbcore: registered new interface driver usb-storage
[    0.794654] usbcore: registered new interface driver usbhid
[    0.796084] usbhid: USB HID core driver
[    1.190513] usb 1-1: new high-speed USB device number 2 using dwc_otg
[    1.420803] usb 1-1: New USB device found, idVendor=0424, idProduct=9514
[    1.422268] usb 1-1: New USB device strings: Mfr=0, Product=0, SerialNumber=0
[    1.424564] hub 1-1:1.0: USB hub found
[    1.740536] usb 1-1.1: new high-speed USB device number 3 using dwc_otg
[    1.870798] usb 1-1.1: New USB device found, idVendor=0424, idProduct=ec00
[    1.872308] usb 1-1.1: New USB device strings: Mfr=0, Product=0, SerialNumber=0
[    1.964356] smsc95xx 1-1.1:1.0 eth0: register 'smsc95xx' at usb-3f980000.usb-1.1, smsc95xx USB 2.0 Ethernet, b8:27:eb:f6:31:21
[    2.260532] usb 1-1.5: new full-speed USB device number 4 using dwc_otg
[    2.393800] usb 1-1.5: New USB device found, idVendor=0658, idProduct=0200
[    2.395444] usb 1-1.5: New USB device strings: Mfr=0, Product=0, SerialNumber=0
[18:18:02] openhabian@openHABianPi:~$

ei_Gelb_Geek · September 15, 2019, 5:00pm

post the output from

ls -lah /dev/ttyA*

thefathefa · September 15, 2019, 5:41pm

Here it is, thanks for the quick answer.


[19:40:29] openhabian@openHABianPi:/etc/openhab2/items$ ls -lah /dev/ttyA*
crw-rw---- 1 root dialout 204, 64 Sep 15 17:31 /dev/ttyAMA0
[19:40:31] openhabian@openHABianPi:/etc/openhab2/items$

chris · September 15, 2019, 6:02pm

The log looks normal to me, but as it’s only the first 3 seconds following the binding startup, it’s what comes next that counts. Can you post more data or is that all there is?

thefathefa · September 16, 2019, 7:53pm

Hello Chris,

Thanks for taking a look. See the attached log, that should cover a bit longer (still filtered with “zwave”). I don’t have more than that because after this time, I have no more info showing up with this “zwave” filter… Do you see more usefull things here?

2019-09-16 21:36:51.433 [INFO ] [el.core.internal.ModelRepositoryImpl] - Loading model 'zwave.items'
2019-09-16 21:37:21.807 [DEBUG] [org.openhab.binding.zwave           ] - BundleEvent STARTING - org.openhab.binding.zwave
2019-09-16 21:37:21.884 [DEBUG] [org.openhab.binding.zwave           ] - ServiceEvent REGISTERED - {org.eclipse.smarthome.config.core.ConfigDescriptionProvider, org.eclipse.smarthome.config.core.ConfigOptionProvider}={service.id=363, service.bundleid=247, service.scope=bundle, component.name=org.openhab.binding.zwave.internal.ZWaveConfigProvider, component.id=217} - org.openhab.binding.zwave
2019-09-16 21:37:22.195 [DEBUG] [org.openhab.binding.zwave           ] - BundleEvent STARTED - org.openhab.binding.zwave
2019-09-16 21:37:22.994 [DEBUG] [org.openhab.binding.zwave           ] - ServiceEvent REGISTERED - {org.eclipse.smarthome.core.thing.binding.ThingHandlerFactory}={service.id=385, service.bundleid=247, service.scope=bundle, component.name=org.openhab.binding.zwave.internal.ZWaveHandlerFactory, component.id=218} - org.openhab.binding.zwave
2019-09-16 21:37:47.186 [hingStatusInfoChangedEvent] - 'zwave:device:512:node3' changed from UNINITIALIZED to UNINITIALIZED (BRIDGE_UNINITIALIZED)
2019-09-16 21:37:47.189 [hingStatusInfoChangedEvent] - 'zwave:device:512:node2' changed from UNINITIALIZED to UNINITIALIZED (BRIDGE_UNINITIALIZED)
2019-09-16 21:37:47.192 [hingStatusInfoChangedEvent] - 'zwave:device:512:node5' changed from UNINITIALIZED to UNINITIALIZED (BRIDGE_UNINITIALIZED)
2019-09-16 21:37:47.195 [hingStatusInfoChangedEvent] - 'zwave:device:512:node4' changed from UNINITIALIZED to UNINITIALIZED (BRIDGE_UNINITIALIZED)
2019-09-16 21:37:47.197 [DEBUG] [wave.discovery.ZWaveDiscoveryService] - Creating ZWave discovery service for zwave:serial_zstick:512 with scan time of 60
2019-09-16 21:37:47.200 [DEBUG] [wave.discovery.ZWaveDiscoveryService] - ZWave discovery: Active zwave:serial_zstick:512
2019-09-16 21:37:47.202 [INFO ] [zwave.handler.ZWaveControllerHandler] - Attempting to add listener when controller is null
2019-09-16 21:37:47.208 [DEBUG] [org.openhab.binding.zwave           ] - ServiceEvent REGISTERED - {org.eclipse.smarthome.config.discovery.DiscoveryService}={service.id=403, service.bundleid=247, service.scope=singleton} - org.openhab.binding.zwave
2019-09-16 21:37:50.561 [hingStatusInfoChangedEvent] - 'zwave:serial_zstick:512' changed from UNINITIALIZED to INITIALIZING
2019-09-16 21:37:50.584 [DEBUG] [ing.zwave.handler.ZWaveSerialHandler] - Initializing ZWave serial controller.
2019-09-16 21:37:50.587 [DEBUG] [zwave.handler.ZWaveControllerHandler] - Initializing ZWave Controller zwave:serial_zstick:512.
2019-09-16 21:37:50.592 [DEBUG] [zwave.handler.ZWaveControllerHandler] - Scheduling network mesh heal for 5 hours time.
2019-09-16 21:37:50.603 [hingStatusInfoChangedEvent] - 'zwave:serial_zstick:512' changed from INITIALIZING to OFFLINE (BRIDGE_OFFLINE): Controller is offline
2019-09-16 21:37:50.606 [INFO ] [ing.zwave.handler.ZWaveSerialHandler] - Connecting to serial port '/dev/ttyAMA0'
2019-09-16 21:37:50.656 [DEBUG] [org.openhab.binding.zwave           ] - ServiceEvent REGISTERED - {org.eclipse.smarthome.config.core.status.ConfigStatusProvider}={service.id=406, service.bundleid=247, service.scope=singleton} - org.openhab.binding.zwave
2019-09-16 21:37:50.656 [DEBUG] [org.openhab.binding.zwave           ] - ServiceEvent REGISTERED - {org.eclipse.smarthome.config.core.status.ConfigStatusProvider}={service.id=409, service.bundleid=247, service.scope=singleton} - org.openhab.binding.zwave
2019-09-16 21:37:50.660 [DEBUG] [org.openhab.binding.zwave           ] - ServiceEvent REGISTERED - {org.eclipse.smarthome.config.core.status.ConfigStatusProvider}={service.id=408, service.bundleid=247, service.scope=singleton} - org.openhab.binding.zwave
2019-09-16 21:37:50.660 [DEBUG] [org.openhab.binding.zwave           ] - ServiceEvent REGISTERED - {org.eclipse.smarthome.config.core.status.ConfigStatusProvider}={service.id=407, service.bundleid=247, service.scope=singleton} - org.openhab.binding.zwave
2019-09-16 21:37:50.668 [DEBUG] [org.openhab.binding.zwave           ] - ServiceEvent REGISTERED - {org.eclipse.smarthome.config.core.status.ConfigStatusProvider}={service.id=410, service.bundleid=247, service.scope=singleton} - org.openhab.binding.zwave
2019-09-16 21:37:50.756 [DEBUG] [ing.zwave.handler.ZWaveSerialHandler] - Starting receive thread
2019-09-16 21:37:50.802 [hingStatusInfoChangedEvent] - 'zwave:device:512:node2' changed from UNINITIALIZED (BRIDGE_UNINITIALIZED) to INITIALIZING
2019-09-16 21:37:50.805 [hingStatusInfoChangedEvent] - 'zwave:device:512:node9' changed from UNINITIALIZED to INITIALIZING
2019-09-16 21:37:50.808 [hingStatusInfoChangedEvent] - 'zwave:device:512:node6' changed from UNINITIALIZED to INITIALIZING
2019-09-16 21:37:50.811 [hingStatusInfoChangedEvent] - 'zwave:device:512:node7' changed from UNINITIALIZED to INITIALIZING
2019-09-16 21:37:50.815 [hingStatusInfoChangedEvent] - 'zwave:device:512:node8' changed from UNINITIALIZED to INITIALIZING
2019-09-16 21:37:50.826 [INFO ] [ing.zwave.handler.ZWaveSerialHandler] - Serial port is initialized
2019-09-16 21:37:50.827 [DEBUG] [zwave.handler.ZWaveControllerHandler] - Initialising ZWave controller
2019-09-16 21:37:50.832 [DEBUG] [WaveSerialHandler$ZWaveReceiveThread] - Starting ZWave thread: Receive
2019-09-16 21:37:50.851 [DEBUG] [ding.zwave.handler.ZWaveThingHandler] - Initializing ZWave thing handler zwave:device:512:node8.
2019-09-16 21:37:50.853 [DEBUG] [ding.zwave.handler.ZWaveThingHandler] - Initializing ZWave thing handler zwave:device:512:node7.
2019-09-16 21:37:50.858 [DEBUG] [ding.zwave.handler.ZWaveThingHandler] - NODE 8: Channel zwave:device:512:node8:thermostat_setpoint_heating linked - polling started.
2019-09-16 21:37:50.858 [DEBUG] [ding.zwave.handler.ZWaveThingHandler] - NODE 8: Channel zwave:device:512:node8:battery-level linked - polling started.
2019-09-16 21:37:50.862 [hingStatusInfoChangedEvent] - 'zwave:device:512:node8' changed from INITIALIZING to OFFLINE (BRIDGE_OFFLINE): Controller is offline
2019-09-16 21:37:50.864 [DEBUG] [org.openhab.binding.zwave           ] - ServiceEvent REGISTERED - {org.eclipse.smarthome.config.core.status.ConfigStatusProvider}={service.id=418, service.bundleid=247, service.scope=singleton} - org.openhab.binding.zwave
2019-09-16 21:37:50.867 [DEBUG] [ding.zwave.handler.ZWaveThingHandler] - Initializing ZWave thing handler zwave:device:512:node6.
2019-09-16 21:37:50.868 [DEBUG] [ding.zwave.handler.ZWaveThingHandler] - NODE 7: Channel zwave:device:512:node7:sensor_temperature linked - polling started.
2019-09-16 21:37:50.870 [DEBUG] [ding.zwave.handler.ZWaveThingHandler] - NODE 7: Channel zwave:device:512:node7:thermostat_setpoint_heating linked - polling started.
2019-09-16 21:37:50.872 [DEBUG] [ding.zwave.handler.ZWaveThingHandler] - NODE 7: Channel zwave:device:512:node7:battery-level linked - polling started.
2019-09-16 21:37:50.874 [hingStatusInfoChangedEvent] - 'zwave:device:512:node7' changed from INITIALIZING to OFFLINE (BRIDGE_OFFLINE): Controller is offline
2019-09-16 21:37:50.876 [DEBUG] [ding.zwave.handler.ZWaveThingHandler] - Initializing ZWave thing handler zwave:device:512:node2.
2019-09-16 21:37:50.880 [DEBUG] [ding.zwave.handler.ZWaveThingHandler] - NODE 8: Channel zwave:device:512:node8:sensor_temperature linked - polling started.
2019-09-16 21:37:50.883 [DEBUG] [ding.zwave.handler.ZWaveThingHandler] - NODE 6: Channel zwave:device:512:node6:thermostat_setpoint_heating linked - polling started.
2019-09-16 21:37:50.882 [DEBUG] [ding.zwave.handler.ZWaveThingHandler] - NODE 6: Channel zwave:device:512:node6:sensor_temperature linked - polling started.
2019-09-16 21:37:50.883 [DEBUG] [ding.zwave.handler.ZWaveThingHandler] - NODE 6: Channel zwave:device:512:node6:battery-level linked - polling started.
2019-09-16 21:37:50.891 [DEBUG] [org.openhab.binding.zwave           ] - ServiceEvent REGISTERED - {org.eclipse.smarthome.config.core.status.ConfigStatusProvider}={service.id=419, service.bundleid=247, service.scope=singleton} - org.openhab.binding.zwave
2019-09-16 21:37:50.891 [hingStatusInfoChangedEvent] - 'zwave:device:512:node6' changed from INITIALIZING to OFFLINE (BRIDGE_OFFLINE): Controller is offline
2019-09-16 21:37:50.896 [DEBUG] [org.openhab.binding.zwave           ] - ServiceEvent REGISTERED - {org.eclipse.smarthome.config.core.status.ConfigStatusProvider}={service.id=420, service.bundleid=247, service.scope=singleton} - org.openhab.binding.zwave
2019-09-16 21:37:50.906 [hingStatusInfoChangedEvent] - 'zwave:device:512:node2' changed from INITIALIZING to OFFLINE (BRIDGE_OFFLINE): Controller is offline
2019-09-16 21:37:50.908 [DEBUG] [ding.zwave.handler.ZWaveThingHandler] - NODE 2: Channel zwave:device:512:node2:sensor_temperature linked - polling started.
2019-09-16 21:37:50.908 [DEBUG] [ding.zwave.handler.ZWaveThingHandler] - NODE 2: Channel zwave:device:512:node2:time_offset linked - polling started.
2019-09-16 21:37:50.908 [DEBUG] [ding.zwave.handler.ZWaveThingHandler] - NODE 2: Channel zwave:device:512:node2:battery-level linked - polling started.
2019-09-16 21:37:50.910 [DEBUG] [ding.zwave.handler.ZWaveThingHandler] - NODE 2: Channel zwave:device:512:node2:thermostat_setpoint_heating linked - polling started.
2019-09-16 21:37:50.912 [DEBUG] [ding.zwave.handler.ZWaveThingHandler] - Initializing ZWave thing handler zwave:device:512:node9.
2019-09-16 21:37:50.924 [hingStatusInfoChangedEvent] - 'zwave:device:512:node9' changed from INITIALIZING to OFFLINE (BRIDGE_OFFLINE): Controller is offline
2019-09-16 21:37:50.935 [hingStatusInfoChangedEvent] - 'zwave:device:512:node4' changed from UNINITIALIZED (BRIDGE_UNINITIALIZED) to INITIALIZING
2019-09-16 21:37:50.939 [hingStatusInfoChangedEvent] - 'zwave:device:512:node3' changed from UNINITIALIZED (BRIDGE_UNINITIALIZED) to INITIALIZING
2019-09-16 21:37:50.953 [DEBUG] [ding.zwave.handler.ZWaveThingHandler] - Initializing ZWave thing handler zwave:device:512:node3.
2019-09-16 21:37:50.966 [DEBUG] [ding.zwave.handler.ZWaveThingHandler] - NODE 3: Channel zwave:device:512:node3:sensor_temperature linked - polling started.
2019-09-16 21:37:50.967 [DEBUG] [ding.zwave.handler.ZWaveThingHandler] - NODE 3: Channel zwave:device:512:node3:battery-level linked - polling started.
2019-09-16 21:37:50.967 [DEBUG] [ding.zwave.handler.ZWaveThingHandler] - NODE 3: Channel zwave:device:512:node3:thermostat_setpoint_heating linked - polling started.
2019-09-16 21:37:50.969 [DEBUG] [ding.zwave.handler.ZWaveThingHandler] - Initializing ZWave thing handler zwave:device:512:node4.
2019-09-16 21:37:50.966 [hingStatusInfoChangedEvent] - 'zwave:device:512:node3' changed from INITIALIZING to OFFLINE (BRIDGE_OFFLINE): Controller is offline
2019-09-16 21:37:50.976 [hingStatusInfoChangedEvent] - 'zwave:device:512:node5' changed from UNINITIALIZED (BRIDGE_UNINITIALIZED) to INITIALIZING
2019-09-16 21:37:50.978 [DEBUG] [ding.zwave.handler.ZWaveThingHandler] - NODE 4: Channel zwave:device:512:node4:sensor_temperature linked - polling started.
2019-09-16 21:37:50.979 [hingStatusInfoChangedEvent] - 'zwave:device:512:node4' changed from INITIALIZING to OFFLINE (BRIDGE_OFFLINE): Controller is offline
2019-09-16 21:37:50.980 [DEBUG] [ding.zwave.handler.ZWaveThingHandler] - NODE 4: Channel zwave:device:512:node4:thermostat_setpoint_heating linked - polling started.
2019-09-16 21:37:50.982 [DEBUG] [ding.zwave.handler.ZWaveThingHandler] - NODE 4: Channel zwave:device:512:node4:battery-level linked - polling started.
2019-09-16 21:37:51.003 [DEBUG] [ding.zwave.handler.ZWaveThingHandler] - Initializing ZWave thing handler zwave:device:512:node5.
2019-09-16 21:37:51.010 [hingStatusInfoChangedEvent] - 'zwave:device:512:node5' changed from INITIALIZING to OFFLINE (BRIDGE_OFFLINE): Controller is offline
2019-09-16 21:37:51.011 [DEBUG] [ding.zwave.handler.ZWaveThingHandler] - NODE 5: Channel zwave:device:512:node5:thermostat_setpoint_heating linked - polling started.
2019-09-16 21:37:51.011 [DEBUG] [ding.zwave.handler.ZWaveThingHandler] - NODE 5: Channel zwave:device:512:node5:battery-level linked - polling started.
2019-09-16 21:37:51.011 [DEBUG] [ding.zwave.handler.ZWaveThingHandler] - NODE 5: Channel zwave:device:512:node5:sensor_temperature linked - polling started.
2019-09-16 21:37:51.540 [INFO ] [ve.internal.protocol.ZWaveController] - Starting ZWave controller
2019-09-16 21:37:51.539 [DEBUG] [nal.protocol.ZWaveTransactionManager] - ZWaveReceiveThread queue empty
2019-09-16 21:37:51.558 [INFO ] [ve.internal.protocol.ZWaveController] - ZWave timeout is set to 5000ms. Soft reset is false.
2019-09-16 21:37:51.561 [DEBUG] [nal.protocol.ZWaveTransactionManager] - Transaction SendNextMessage 0 out at start. Holdoff false.
2019-09-16 21:37:51.574 [DEBUG] [ve.internal.protocol.ZWaveController] - Event listener added.
2019-09-16 21:37:51.581 [DEBUG] [ve.internal.protocol.ZWaveController] - Event listener added.
2019-09-16 21:37:54.577 [DEBUG] [.ZWaveController$InitializeDelayTask] - Initialising network
2019-09-16 21:37:54.607 [DEBUG] [nal.protocol.ZWaveTransactionManager] - NODE 255: Added 0 to queue - size 1
2019-09-16 21:37:54.609 [DEBUG] [nal.protocol.ZWaveTransactionManager] - Transaction SendNextMessage 0 out at start. Holdoff false.
2019-09-16 21:37:54.625 [DEBUG] [ing.zwave.handler.ZWaveSerialHandler] - NODE 255: Sending REQUEST Message = 01 03 00 15 E9 
2019-09-16 21:37:54.665 [DEBUG] [ing.zwave.handler.ZWaveSerialHandler] - Message SENT
2019-09-16 21:37:54.667 [DEBUG] [nal.protocol.ZWaveTransactionManager] - Transaction SendNextMessage started: TID 0: [WAIT_RESPONSE] priority=Controller, requiresResponse=true, callback: 0
2019-09-16 21:37:54.673 [DEBUG] [nal.protocol.ZWaveTransactionManager] - NODE 255: Added 1 to queue - size 1
2019-09-16 21:37:54.674 [DEBUG] [nal.protocol.ZWaveTransactionManager] - Transaction SendNextMessage 1 out at start. Holdoff false.
2019-09-16 21:37:54.679 [DEBUG] [nal.protocol.ZWaveTransactionManager] - NODE 255: Added 2 to queue - size 2
2019-09-16 21:37:54.680 [DEBUG] [nal.protocol.ZWaveTransactionManager] - Transaction SendNextMessage 1 out at start. Holdoff false.
2019-09-16 21:37:54.684 [DEBUG] [nal.protocol.ZWaveTransactionManager] - NODE 255: Added 3 to queue - size 3
2019-09-16 21:37:54.686 [DEBUG] [nal.protocol.ZWaveTransactionManager] - Transaction SendNextMessage 1 out at start. Holdoff false.
2019-09-16 21:37:54.691 [DEBUG] [nal.protocol.ZWaveTransactionManager] - NODE 255: Added 4 to queue - size 4
2019-09-16 21:37:54.693 [DEBUG] [nal.protocol.ZWaveTransactionManager] - Transaction SendNextMessage 1 out at start. Holdoff false.
2019-09-16 21:37:56.672 [DEBUG] [sactionManager$ZWaveTransactionTimer] - NODE 255: TID 0: Timeout at state WAIT_RESPONSE. 3 retries remaining.
2019-09-16 21:37:56.674 [DEBUG] [sactionManager$ZWaveTransactionTimer] - TID 0: Transaction is current transaction, so clearing!!!!!
2019-09-16 21:37:56.687 [DEBUG] [e.internal.protocol.ZWaveTransaction] - TID 0: Transaction CANCELLED
2019-09-16 21:37:56.695 [DEBUG] [nal.protocol.ZWaveTransactionManager] - NODE 255: notifyTransactionResponse TID:0 CANCELLED
2019-09-16 21:37:56.699 [DEBUG] [nal.protocol.ZWaveTransactionManager] - Transaction SendNextMessage 0 out at start. Holdoff false.
2019-09-16 21:37:56.705 [DEBUG] [ing.zwave.handler.ZWaveSerialHandler] - NODE 255: Sending REQUEST Message = 01 03 00 20 DC 
2019-09-16 21:37:56.735 [DEBUG] [ing.zwave.handler.ZWaveSerialHandler] - Message SENT
2019-09-16 21:37:56.738 [DEBUG] [nal.protocol.ZWaveTransactionManager] - Transaction SendNextMessage started: TID 1: [WAIT_RESPONSE] priority=Controller, requiresResponse=true, callback: 0
2019-09-16 21:37:58.741 [DEBUG] [sactionManager$ZWaveTransactionTimer] - NODE 255: TID 1: Timeout at state WAIT_RESPONSE. 3 retries remaining.
2019-09-16 21:37:58.745 [DEBUG] [sactionManager$ZWaveTransactionTimer] - TID 1: Transaction is current transaction, so clearing!!!!!
2019-09-16 21:37:58.747 [DEBUG] [e.internal.protocol.ZWaveTransaction] - TID 1: Transaction CANCELLED
2019-09-16 21:37:58.750 [DEBUG] [nal.protocol.ZWaveTransactionManager] - NODE 255: notifyTransactionResponse TID:1 CANCELLED
2019-09-16 21:37:58.755 [DEBUG] [nal.protocol.ZWaveTransactionManager] - Transaction SendNextMessage 0 out at start. Holdoff false.
2019-09-16 21:37:58.761 [DEBUG] [ing.zwave.handler.ZWaveSerialHandler] - NODE 255: Sending REQUEST Message = 01 03 00 07 FB 
2019-09-16 21:37:58.785 [DEBUG] [ing.zwave.handler.ZWaveSerialHandler] - Message SENT
2019-09-16 21:37:58.787 [DEBUG] [nal.protocol.ZWaveTransactionManager] - Transaction SendNextMessage started: TID 2: [WAIT_RESPONSE] priority=Controller, requiresResponse=true, callback: 0
2019-09-16 21:38:00.790 [DEBUG] [sactionManager$ZWaveTransactionTimer] - NODE 255: TID 2: Timeout at state WAIT_RESPONSE. 3 retries remaining.
2019-09-16 21:38:00.793 [DEBUG] [sactionManager$ZWaveTransactionTimer] - TID 2: Transaction is current transaction, so clearing!!!!!
2019-09-16 21:38:00.795 [DEBUG] [e.internal.protocol.ZWaveTransaction] - TID 2: Transaction CANCELLED
2019-09-16 21:38:00.798 [DEBUG] [nal.protocol.ZWaveTransactionManager] - NODE 255: notifyTransactionResponse TID:2 CANCELLED
2019-09-16 21:38:00.806 [DEBUG] [nal.protocol.ZWaveTransactionManager] - Transaction SendNextMessage 0 out at start. Holdoff false.
2019-09-16 21:38:00.813 [DEBUG] [ing.zwave.handler.ZWaveSerialHandler] - NODE 255: Sending REQUEST Message = 01 05 00 06 96 0F 65 
2019-09-16 21:38:00.818 [DEBUG] [WaveSerialHandler$ZWaveReceiveThread] - Protocol error (OOF). Got 0x04.
2019-09-16 21:38:00.821 [DEBUG] [WaveSerialHandler$ZWaveReceiveThread] - Protocol error (OOF). Got 0x0E.
2019-09-16 21:38:00.824 [DEBUG] [WaveSerialHandler$ZWaveReceiveThread] - Protocol error (OOF). Got 0x04.
2019-09-16 21:38:00.828 [DEBUG] [WaveSerialHandler$ZWaveReceiveThread] - Frame length is out of limits (3)
2019-09-16 21:38:00.831 [DEBUG] [WaveSerialHandler$ZWaveReceiveThread] - Frame length is out of limits (0)
2019-09-16 21:38:00.833 [DEBUG] [WaveSerialHandler$ZWaveReceiveThread] - Frame length is out of limits (1)
2019-09-16 21:38:00.845 [DEBUG] [ing.zwave.handler.ZWaveSerialHandler] - Message SENT2019-09-16 21:38:00.847 [DEBUG] [nal.protocol.ZWaveTransactionManager] - Transaction SendNextMessage started: TID 3: [WAIT_RESPONSE] priority=Controller, requiresResponse=true, callback: 0
2019-09-16 21:38:01.086 [DEBUG] [WaveSerialHandler$ZWaveReceiveThread] - Receive Timeout - Sending NAK
2019-09-16 21:38:02.851 [DEBUG] [sactionManager$ZWaveTransactionTimer] - NODE 255: TID 3: Timeout at state WAIT_RESPONSE. 3 retries remaining.
2019-09-16 21:38:02.853 [DEBUG] [sactionManager$ZWaveTransactionTimer] - TID 3: Transaction is current transaction, so clearing!!!!!
2019-09-16 21:38:02.856 [DEBUG] [e.internal.protocol.ZWaveTransaction] - TID 3: Transaction CANCELLED
2019-09-16 21:38:02.858 [DEBUG] [nal.protocol.ZWaveTransactionManager] - NODE 255: notifyTransactionResponse TID:3 CANCELLED
2019-09-16 21:38:02.861 [DEBUG] [nal.protocol.ZWaveTransactionManager] - Transaction SendNextMessage 0 out at start. Holdoff false.
2019-09-16 21:38:02.871 [DEBUG] [ing.zwave.handler.ZWaveSerialHandler] - NODE 255: Sending REQUEST Message = 01 03 00 56 AA 
2019-09-16 21:38:02.895 [DEBUG] [ing.zwave.handler.ZWaveSerialHandler] - Message SENT
2019-09-16 21:38:02.898 [DEBUG] [nal.protocol.ZWaveTransactionManager] - Transaction SendNextMessage started: TID 4: [WAIT_RESPONSE] priority=Controller, requiresResponse=true, callback: 0
2019-09-16 21:38:04.900 [DEBUG] [sactionManager$ZWaveTransactionTimer] - NODE 255: TID 4: Timeout at state WAIT_RESPONSE. 3 retries remaining.
2019-09-16 21:38:04.903 [DEBUG] [sactionManager$ZWaveTransactionTimer] - TID 4: Transaction is current transaction, so clearing!!!!!
2019-09-16 21:38:04.906 [DEBUG] [e.internal.protocol.ZWaveTransaction] - TID 4: Transaction CANCELLED
2019-09-16 21:38:04.909 [DEBUG] [nal.protocol.ZWaveTransactionManager] - NODE 255: notifyTransactionResponse TID:4 CANCELLED
2019-09-16 21:38:04.914 [DEBUG] [nal.protocol.ZWaveTransactionManager] - Transaction SendNextMessage 0 out at start. Holdoff false.```

thefathefa · September 20, 2019, 6:57pm

Hi @chris, does the log I posted above provide more info to you? Thanks in advance,

chris · September 21, 2019, 6:30am

The log doesn’t show any response from the controller at all, so there is something fundamentally wrong - either the serial port is wrong, or the controller is broken.

thefathefa · September 21, 2019, 12:45pm

After checking more, I am wondering if my problem could be related to the fact that it seems the zwave stick seems to be recognized as AMA0 instead of ACM0… I’m almost sure that it was ACM0 the first time I installed it (and it then worked for more than a year in a raw). And now I see only AMA0 appearing and no ACM0.
Reading a bit more, it seems that for everyone there are mentions of CDC-ACM module kicking in (visible in dmesg output) and for me there is nothing. Is there any recommendation on how I could re-install this?

thefathefa · September 21, 2019, 5:17pm

So, I have taken a fresh install of openhabian on a different Raspberry Pi 3 and when I plug the Zwave stick, I see this:

[ 2323.166115] usb 1-1.5: new full-speed USB device number 4 using dwc_otg
[ 2323.299411] usb 1-1.5: New USB device found, idVendor=0658, idProduct=0200, bcdDevice= 0.00
[ 2323.299428] usb 1-1.5: New USB device strings: Mfr=0, Product=0, SerialNumber=0

I believe that I should see CDC-ACM messages just after this and it does not show up…

@chris, please, does that sound enough to conclude that the stick is not working anymore?

Thanks in advance,

sihui · September 21, 2019, 6:41pm

Try

pi@rpi3openhab:~ $ dmesg -T | grep tty
[Do Aug 23 08:40:00 2018] cdc_acm 1-1.5:1.0: ttyACM0: USB ACM device

If nothing shows up on a fresh OS install your stick is probably broken.

thefathefa · September 21, 2019, 11:09pm

Thank you @sihui for your answer.

This is what I see:

openhabian@openhab:~$ dmesg -T | grep tty
[Sat Sep 21 18:35:42 2019] Kernel command line: coherent_pool=1M 8250.nr_uarts=0 bcm2708_fb.fbwidth=656 bcm2708_fb.fbheight=416 bcm2708_fb.fbswap=1 vc_mem.mem_base=0x3ec00000 vc_mem.mem_size=0x40000000  dwc_otg.lpm_enable=0 console=ttyS0,115200 console=tty1 root=PARTUUID=cc94f697-02 rootfstype=ext4 elevator=deadline fsck.repair=yes rootwait
[Sat Sep 21 18:35:42 2019] console [tty1] enabled
[Sat Sep 21 18:35:42 2019] 3f201000.serial: ttyAMA0 at MMIO 0x3f201000 (irq = 81, base_baud = 0) is a PL011 rev2
[01:06:21] openhabian@openhab:~$

Same as what I see on the other openhab install…

sihui · September 22, 2019, 6:33am

Maybe serial driver handling has changed from Stretch to Buster. I am not using any Raspberry’s anymore, so can’t be of any further help.

thefathefa · September 22, 2019, 9:14am

Ah, no, on the new setup, after I used openhabian-config to click “disable bluetooth” and “activate serial etc… on openhab Java machine”, now I see this:

[  202.332393] usb 1-1.5: new full-speed USB device number 4 using dwc_otg
[  202.465644] usb 1-1.5: New USB device found, idVendor=0658, idProduct=0200, bcdDevice= 0.00
[  202.465661] usb 1-1.5: New USB device strings: Mfr=0, Product=0, SerialNumber=0
[  202.530374] cdc_acm 1-1.5:1.0: ttyACM0: USB ACM device
[  202.531384] usbcore: registered new interface driver cdc_acm
[  202.531391] cdc_acm: USB Abstract Control Model driver for USB modems and ISDN adapters

So I think I have a problem with the config of my main openhab machine…
I guess I’ll have the opportunity to test the restore of a backup on the new machine and see where that takes me:-)

sihui · September 22, 2019, 9:20am

Yes.

javi007 · October 10, 2019, 10:15pm

Hi thefathefa
have you been able to fix issue?
I have same issue than you:

2019-10-10 23:34:26.679 [thome.event.ExtensionEvent] - Extension 'binding-zwave' has been installed.
2019-10-10 23:36:19.496 [.ItemChannelLinkAddedEvent] - Link 'zwave_serial_zstick_87d5069e_serial_sof-zwave:serial_zstick:87d5069e:serial_sof' has been added.
2019-10-10 23:36:19.511 [.ItemChannelLinkAddedEvent] - Link 'zwave_serial_zstick_87d5069e_serial_ack-zwave:serial_zstick:87d5069e:serial_ack' has been added.
2019-10-10 23:36:19.514 [.ItemChannelLinkAddedEvent] - Link 'zwave_serial_zstick_87d5069e_serial_nak-zwave:serial_zstick:87d5069e:serial_nak' has been added.
2019-10-10 23:36:19.517 [.ItemChannelLinkAddedEvent] - Link 'zwave_serial_zstick_87d5069e_serial_can-zwave:serial_zstick:87d5069e:serial_can' has been added.
2019-10-10 23:36:19.520 [.ItemChannelLinkAddedEvent] - Link 'zwave_serial_zstick_87d5069e_serial_oof-zwave:serial_zstick:87d5069e:serial_oof' has been added.
2019-10-10 23:36:19.523 [.ItemChannelLinkAddedEvent] - Link 'zwave_serial_zstick_87d5069e_serial_cse-zwave:serial_zstick:87d5069e:serial_cse' has been added.
2019-10-10 23:36:19.573 [hingStatusInfoChangedEvent] - 'zwave:serial_zstick:87d5069e' changed from UNINITIALIZED to INITIALIZING
2019-10-10 23:36:19.602 [me.event.ThingUpdatedEvent] - Thing 'zwave:serial_zstick:87d5069e' has been updated.

==> /var/log/openhab2/openhab.log <==
2019-10-10 23:36:19.607 [INFO ] [ing.zwave.handler.ZWaveSerialHandler] - Connecting to serial port '/dev/ttyAMA0'

==> /var/log/openhab2/events.log <==
2019-10-10 23:36:19.609 [hingStatusInfoChangedEvent] - 'zwave:serial_zstick:87d5069e' changed from INITIALIZING to OFFLINE (BRIDGE_OFFLINE): Controller is offline

==> /var/log/openhab2/openhab.log <==
2019-10-10 23:36:19.628 [INFO ] [ing.zwave.handler.ZWaveSerialHandler] - Serial port is initialized

==> /var/log/openhab2/events.log <==
2019-10-10 23:36:19.645 [vent.ItemStateChangedEvent] - zwave_serial_zstick_87d5069e_serial_sof changed from NULL to 0
2019-10-10 23:36:19.647 [vent.ItemStateChangedEvent] - zwave_serial_zstick_87d5069e_serial_ack changed from NULL to 0
2019-10-10 23:36:19.653 [vent.ItemStateChangedEvent] - zwave_serial_zstick_87d5069e_serial_nak changed from NULL to 0
2019-10-10 23:36:19.657 [vent.ItemStateChangedEvent] - zwave_serial_zstick_87d5069e_serial_can changed from NULL to 0
2019-10-10 23:36:19.665 [vent.ItemStateChangedEvent] - zwave_serial_zstick_87d5069e_serial_oof changed from NULL to 0
2019-10-10 23:36:19.668 [vent.ItemStateChangedEvent] - zwave_serial_zstick_87d5069e_serial_cse changed from NULL to 0

==> /var/log/openhab2/openhab.log <==
2019-10-10 23:36:19.672 [INFO ] [ve.internal.protocol.ZWaveController] - Starting ZWave controller
2019-10-10 23:36:19.674 [INFO ] [ve.internal.protocol.ZWaveController] - ZWave timeout is set to 5000ms. Soft reset is false.

but in my case I’m using a new Raspberry Pi 4 Model B Rev 1.1:

###############################################################################
###############  openhab  #####################################################
###############################################################################
##        Ip = 192.168.1.143
##   Release = Raspbian GNU/Linux 10 (buster)
##    Kernel = Linux 4.19.57-v7l+
##  Platform = Raspberry Pi 4 Model B Rev 1.1
##    Uptime = 0 day(s). 0:25:59
## CPU Usage = 0% avg over 4 cpu(s) (4 core(s) x 1 socket(s))
##  CPU Load = 1m: 0.00, 5m: 0.00, 15m: 0.00
##    Memory = Free: 3.23GB (84%), Used: 0.63GB (16%), Total: 3.86GB
##      Swap = Free: 0.09GB (100%), Used: 0.00GB (0%), Total: 0.09GB
##      Root = Free: 53.54GB (95%), Used: 2.36GB (5%), Total: 58.30GB
##   Updates = 0 apt updates available.
##  Sessions = 2 session(s)
## Processes = 119 running processes of 32768 maximum processes
###############################################################################

I have also checked serial port and tty:

[23:55:21] openhabian@openhab:~$ cat /etc/default/openhab2 | grep SerialPorts
##   EXTRA_JAVA_OPTS="-Dgnu.io.rxtx.SerialPorts=/dev/ttyAMA0"
##   EXTRA_JAVA_OPTS="-Dgnu.io.rxtx.SerialPorts=/dev/ttyUSB0:/dev/ttyS0:/dev/ttyS2:/dev/ttyACM0:/dev/ttyAMA0"
##   EXTRA_JAVA_OPTS="-Djna.library.path=/lib/arm-linux-gnueabihf/ -Duser.timezone=Europe/Berlin -Dgnu.io.rxtx.SerialPorts=/dev/ttyS0"
EXTRA_JAVA_OPTS="-Xms250m -Xmx350m -Dgnu.io.rxtx.SerialPorts=/dev/ttyUSB0:/dev/ttyS0:/dev/ttyS2:/dev/ttyACM0:/dev/ttyAMA0"

[23:58:08] openhabian@openhab:~$ dmesg -T | grep tty
[Thu Oct 10 23:29:19 2019] Kernel command line: coherent_pool=1M 8250.nr_uarts=0 cma=64M cma=256M  smsc95xx.macaddr=DC:A6:32:29:88:73 vc_mem.mem_base=0x3f000000 vc_mem.mem_size=0x3f600000  dwc_otg.lpm_enable=0 console=ttyS0,115200 console=tty1 root=PARTUUID=be1d5779-02 rootfstype=ext4 elevator=deadline fsck.repair=yes rootwait
[Thu Oct 10 23:29:19 2019] console [tty1] enabled
[Thu Oct 10 23:29:19 2019] fe201000.serial: ttyAMA0 at MMIO 0xfe201000 (irq = 34, base_baud = 0) is a PL011 rev2

[23:59:33] openhabian@openhab:~$ ls -lah /dev/ttyA*
crw-rw---- 1 root dialout 204, 64 Oct 10 23:29 /dev/ttyAMA0

I have also ran the following checks on the USB / serial interfaces:

[23:58:47] openhabian@openhab:~$ dmesg | grep -i usb
[    0.073137] usbcore: registered new interface driver usbfs
[    0.073203] usbcore: registered new interface driver hub
[    0.073312] usbcore: registered new device driver usb
[    0.392993] usbcore: registered new interface driver r8152
[    0.393070] usbcore: registered new interface driver lan78xx
[    0.393137] usbcore: registered new interface driver smsc95xx
[    0.393398] xhci_hcd 0000:01:00.0: new USB bus registered, assigned bus number 1
[    0.396307] usb usb1: New USB device found, idVendor=1d6b, idProduct=0002, bcdDevice= 4.19
[    0.396340] usb usb1: New USB device strings: Mfr=3, Product=2, SerialNumber=1
[    0.396369] usb usb1: Product: xHCI Host Controller
[    0.396392] usb usb1: Manufacturer: Linux 4.19.75-v7l+ xhci-hcd
[    0.396416] usb usb1: SerialNumber: 0000:01:00.0
[    0.396939] hub 1-0:1.0: USB hub found
[    0.397457] xhci_hcd 0000:01:00.0: new USB bus registered, assigned bus number 2
[    0.397495] xhci_hcd 0000:01:00.0: Host supports USB 3.0 SuperSpeed
[    0.397844] usb usb2: New USB device found, idVendor=1d6b, idProduct=0003, bcdDevice= 4.19
[    0.397876] usb usb2: New USB device strings: Mfr=3, Product=2, SerialNumber=1
[    0.397905] usb usb2: Product: xHCI Host Controller
[    0.397928] usb usb2: Manufacturer: Linux 4.19.75-v7l+ xhci-hcd
[    0.397952] usb usb2: SerialNumber: 0000:01:00.0
[    0.398444] hub 2-0:1.0: USB hub found
[    0.425187] dwc_otg fe980000.usb: base=(ptrval)
[    0.826959] dwc_otg fe980000.usb: DWC OTG Controller
[    0.827002] dwc_otg fe980000.usb: new USB bus registered, assigned bus number 3
[    0.827054] dwc_otg fe980000.usb: irq 37, io mem 0x00000000
[    0.827411] usb usb3: New USB device found, idVendor=1d6b, idProduct=0002, bcdDevice= 4.19
[    0.827443] usb usb3: New USB device strings: Mfr=3, Product=2, SerialNumber=1
[    0.827472] usb usb3: Product: DWC OTG Controller
[    0.827495] usb usb3: Manufacturer: Linux 4.19.75-v7l+ dwc_otg_hcd
[    0.827519] usb usb3: SerialNumber: fe980000.usb
[    0.828048] hub 3-0:1.0: USB hub found
[    0.828933] usbcore: registered new interface driver uas
[    0.829064] usbcore: registered new interface driver usb-storage
[    0.835368] usbcore: registered new interface driver usbhid
[    0.835391] usbhid: USB HID core driver
[    0.971642] usb 1-1: new high-speed USB device number 2 using xhci_hcd
[    1.153278] usb 1-1: New USB device found, idVendor=2109, idProduct=3431, bcdDevice= 4.20
[    1.153319] usb 1-1: New USB device strings: Mfr=0, Product=1, SerialNumber=0
[    1.153347] usb 1-1: Product: USB2.0 Hub
[    1.154917] hub 1-1:1.0: USB hub found
[    3.948873] usbcore: registered new interface driver brcmfmac

Were you able to fix issue?
If so, would you mind helping me with this issue
Thanks in advance

Bruce_Osborne · October 10, 2019, 10:22pm

I do not know about your version, but when this was first released there was a USB standards issue. You needed to connect the usb stick through a usb hub to be properly recognized.

thefathefa · October 11, 2019, 5:20am

Hello Javier,

I ended up rebuilding my openhabian config from scratch. It took a while but now back to normal.

I think that until your system will show you the ACM0 thing, it means there is a problem…

javi007 · October 11, 2019, 8:32am

Hi thefathefa
Yes I’ve tried several times to config my openhabian from scratch using the latest openHABian system image ( openHABian v1.5 based on Debian Buster that supports RPi4), but I always get the same issue.
After initial instalation, the first thing that I do, is try to instal Zwave, in order to avoid any other iconfig issue, but I’m not able to see where is the issue

I’m stuck and I’m starting to be desperate

Bruce_Osborne · October 11, 2019, 8:34am

The first installation of the zwave binding can take some time until all the dependencies are installed. I usually look at the logs to verify. Occasionally I have restarted OH.

I wait for the binding to finish installation before trying to add a controller.

javi007 · October 11, 2019, 8:37am

[Bruce_Osborne]
I do not know about your version, but when this was first released there was a USB standards issue. You needed to connect the usb stick through a usb hub to be properly recognized.

Thank for your answer

I’m Raspberry Pi 4 with openHABian v1.5. My bother is using same zwave stick in a Raspberry Pi 3B with openHABian v1.4.1 and he has not any issue. So I understand that is should be for first versions.