Problems with the Z-Wave binding

Hi

I have a Aeon Z-Stick Gen5 and a MultiSensor 6 and I wanted to use it with my openHAB on Debian. Using ozwcp everything works fine, I see both devices, get the correct the values, etc.

But openHAB doesn’t work. My openhab.cfg is:

zwave:port = /dev/ttyACM0
zwave:healtime = 2
zwave:setSUC = true
zwave:masterController = true

The zwave.log says:

2016-05-21 18:27:26.427 [DEBUG] [.zwave.internal.ZWaveActivator:36 ]-Z-Wave binding started. Version 1.8.2
2016-05-21 18:27:26.437 [TRACE] [.i.ZWaveGenericBindingProvider:48 ]-validateItemType(sensor_1_temp, 2:1:command=sensor_multilevel,sensor_type=1)
2016-05-21 18:27:26.437 [TRACE] [.i.ZWaveGenericBindingProvider:57 ]-processBindingConfiguration(sensor_1_temp, 2:1:command=sensor_multilevel,sensor_type=1)
2016-05-21 18:27:26.447 [TRACE] [.i.ZWaveGenericBindingProvider:48 ]-validateItemType(sensor_1_humidity, 2:1:command=sensor_multilevel,sensor_type=5)
2016-05-21 18:27:26.447 [TRACE] [.i.ZWaveGenericBindingProvider:57 ]-processBindingConfiguration(sensor_1_humidity, 2:1:command=sensor_multilevel,sensor_type=5)
2016-05-21 18:27:26.447 [TRACE] [.i.ZWaveGenericBindingProvider:48 ]-validateItemType(sensor_1_luminance, 2:1:command=sensor_multilevel,sensor_type=3)
2016-05-21 18:27:26.448 [TRACE] [.i.ZWaveGenericBindingProvider:57 ]-processBindingConfiguration(sensor_1_luminance, 2:1:command=sensor_multilevel,sensor_type=3)
2016-05-21 18:27:26.448 [TRACE] [.i.ZWaveGenericBindingProvider:48 ]-validateItemType(sensor_1_motion, 2:1:command=sensor_binary,respond_to_basic=true)
2016-05-21 18:27:26.448 [TRACE] [.i.ZWaveGenericBindingProvider:57 ]-processBindingConfiguration(sensor_1_motion, 2:1:command=sensor_binary,respond_to_basic=true)
2016-05-21 18:27:26.449 [TRACE] [.i.ZWaveGenericBindingProvider:48 ]-validateItemType(sensor_1_battery, 2:command=battery)
2016-05-21 18:27:26.449 [TRACE] [.i.ZWaveGenericBindingProvider:57 ]-processBindingConfiguration(sensor_1_battery, 2:command=battery)
2016-05-21 18:27:26.451 [TRACE] [.z.internal.ZWaveActiveBinding:157 ]-allBindingsChanged
2016-05-21 18:27:26.451 [DEBUG] [.z.internal.ZWaveActiveBinding:175 ]-ConverterHandler not initialised. Polling disabled.
2016-05-21 18:27:26.461 [INFO ] [.z.internal.ZWaveActiveBinding:325 ]-Update config, port = /dev/ttyACM0
2016-05-21 18:27:26.461 [INFO ] [.z.internal.ZWaveActiveBinding:330 ]-Update config, healtime = 2
2016-05-21 18:27:26.461 [INFO ] [.z.internal.ZWaveActiveBinding:375 ]-Update config, setSUC = true
2016-05-21 18:27:26.461 [INFO ] [.z.internal.ZWaveActiveBinding:393 ]-Update config, masterController = true
2016-05-21 18:27:26.461 [DEBUG] [.z.internal.ZWaveActiveBinding:282 ]-Initialising zwave binding

Within the openhab.cfg I have only one line:

18:27:26.482 [INFO ] [.service.AbstractActiveService:169 ] - ZWave Refresh Service has been started

The version of the zwave binding is 1.8.2.

In the Habmin menu I don’t see any devices, when I click e.g. on “Heal” I get “Error sending action to server”. I added some example items:

Number sensor_1_temp “Temperature [%.1f °F]” (Motion,Temps) {zwave=“2:1:command=sensor_multilevel,sensor_type=1”}
Number sensor_1_humidity “Humidity [%.0f %%]” (Motion) {zwave=“2:1:command=sensor_multilevel,sensor_type=5”}
Number sensor_1_luminance “Luminance [%.0f Lux]” (Motion) {zwave=“2:1:command=sensor_multilevel,sensor_type=3”}
Contact sensor_1_motion “sensor [MAP(motion.map):%s]” (Motion) {zwave=“2:1:command=sensor_binary,respond_to_basic=true”}
Number sensor_1_battery “Battery [%s %%]” (Motion) {zwave=“2:command=battery”}

But I don’t get any values.

Any ideas? Many thanks in advance.

Best regards
Michael

Have you checked in the main log to see if there are any exceptions - such as port not found or something like that? If the log you attach above is the only thing logged, then the initialisation of the port is just about to happen, so I would suspect an exception might be thrown?

I have an exception in the main log, but it is before the zwave initialisation:

18:27:21.193 [WARN ] [sphere.cpr.AtmosphereFramework:1097 ] -
java.lang.ClassNotFoundException: org.atmosphere.interceptor.DefaultHeadersInterceptor
at org.eclipse.osgi.internal.loader.BundleLoader.findClassInternal(BundleLoader.java:501) ~[org.eclipse.osgi_3.8.2.v20130124-134944.jar:na]
at org.eclipse.osgi.internal.loader.BundleLoader.findClass(BundleLoader.java:421) ~[org.eclipse.osgi_3.8.2.v20130124-134944.jar:na]
at org.eclipse.osgi.internal.loader.BundleLoader.findClass(BundleLoader.java:412) ~[org.eclipse.osgi_3.8.2.v20130124-134944.jar:na]
at org.eclipse.osgi.internal.baseadaptor.DefaultClassLoader.loadClass(DefaultClassLoader.java:107) ~[org.eclipse.osgi_3.8.2.v20130124-134944.jar:na]
at java.lang.ClassLoader.loadClass(ClassLoader.java:268) ~[na:1.6.0_38]
at org.atmosphere.util.IOUtils.loadClass(IOUtils.java:309) ~[atmosphere-runtime-2.2.5.jar:2.2.5]
at org.atmosphere.cpr.AtmosphereFramework.configureAtmosphereInterceptor(AtmosphereFramework.java:1094) [atmosphere-runtime-2.2.5.jar:2.2.5]
at org.atmosphere.cpr.AtmosphereFramework.init(AtmosphereFramework.java:892) [atmosphere-runtime-2.2.5.jar:2.2.5]
at org.atmosphere.cpr.AtmosphereFramework.init(AtmosphereFramework.java:780) [atmosphere-runtime-2.2.5.jar:2.2.5]
at org.atmosphere.cpr.AtmosphereServlet.configureFramework(AtmosphereServlet.java:101) ~[atmosphere-runtime-2.2.5.jar:2.2.5]
at org.atmosphere.cpr.AtmosphereServlet.init(AtmosphereServlet.java:80) ~[atmosphere-runtime-2.2.5.jar:2.2.5]
at org.eclipse.equinox.http.servlet.internal.ServletRegistration.init(ServletRegistration.java:49) ~[na:na]
at org.eclipse.equinox.http.servlet.internal.ProxyServlet.registerServlet(ProxyServlet.java:179) ~[na:na]
at org.eclipse.equinox.http.servlet.internal.HttpServiceImpl.registerServlet(HttpServiceImpl.java:66) ~[na:na]
at org.openhab.io.habmin.HABminApplication.activate(HABminApplication.java:179) ~[bundlefile:na]
at sun.reflect.NativeMethodAccessorImpl.invoke0(Native Method) ~[na:1.6.0_38]
at sun.reflect.NativeMethodAccessorImpl.invoke(NativeMethodAccessorImpl.java:57) ~[na:1.6.0_38]
at sun.reflect.DelegatingMethodAccessorImpl.invoke(DelegatingMethodAccessorImpl.java:43) ~[na:1.6.0_38]
at java.lang.reflect.Method.invoke(Method.java:622) ~[na:1.6.0_38]
at org.eclipse.equinox.internal.ds.model.ServiceComponent.activate(ServiceComponent.java:235) ~[org.eclipse.equinox.ds_1.4.1.v20120926-201320.jar:na]
at org.eclipse.equinox.internal.ds.model.ServiceComponentProp.activate(ServiceComponentProp.java:146) ~[org.eclipse.equinox.ds_1.4.1.v20120926-201320.jar:na]
at org.eclipse.equinox.internal.ds.model.ServiceComponentProp.build(ServiceComponentProp.java:345) ~[org.eclipse.equinox.ds_1.4.1.v20120926-201320.jar:na]
at org.eclipse.equinox.internal.ds.InstanceProcess.buildComponent(InstanceProcess.java:620) ~[org.eclipse.equinox.ds_1.4.1.v20120926-201320.jar:na]
at org.eclipse.equinox.internal.ds.InstanceProcess.buildComponents(InstanceProcess.java:197) ~[org.eclipse.equinox.ds_1.4.1.v20120926-201320.jar:na]
at org.eclipse.equinox.internal.ds.Resolver.buildNewlySatisfied(Resolver.java:473) ~[org.eclipse.equinox.ds_1.4.1.v20120926-201320.jar:na]
at org.eclipse.equinox.internal.ds.Resolver.enableComponents(Resolver.java:217) ~[org.eclipse.equinox.ds_1.4.1.v20120926-201320.jar:na]
at org.eclipse.equinox.internal.ds.SCRManager.performWork(SCRManager.java:816) ~[org.eclipse.equinox.ds_1.4.1.v20120926-201320.jar:na]
at org.eclipse.equinox.internal.ds.SCRManager$QueuedJob.dispatch(SCRManager.java:783) ~[org.eclipse.equinox.ds_1.4.1.v20120926-201320.jar:na]
at org.eclipse.equinox.internal.ds.WorkThread.run(WorkThread.java:89) ~[org.eclipse.equinox.ds_1.4.1.v20120926-201320.jar:na]
at org.eclipse.equinox.internal.util.impl.tpt.threadpool.Executor.run(Executor.java:70) ~[org.eclipse.equinox.util_1.0.400.v20120917-192807.jar:na]

The rest is just mqtt, persistence and systeminfo:

18:27:21.197 [INFO ] [.o.io.habmin.HABminApplication:182 ] - Started HABmin REST API at /services/habmin
18:27:21.198 [DEBUG] [o.o.i.s.i.DiscoveryServiceImpl:66 ] - Registering new service _openhab-server._tcp.local. at port 8080
18:27:23.795 [DEBUG] [o.o.i.s.i.DiscoveryServiceImpl:66 ] - Registering new service _openhab-server-ssl._tcp.local. at port 8443
18:27:26.414 [DEBUG] [s.internal.SysteminfoActivator:33 ] - Systeminfo Binding has been started.
18:27:26.420 [DEBUG] [i.internal.GenericItemProvider:341 ] - Start processing binding configuration of Item ‘loadAverage1min (Type=NumberItem, State=Uninitialized)’ with ‘SysteminfoGenericBindingProvider’ reader.
18:27:26.421 [DEBUG] [i.internal.GenericItemProvider:341 ] - Start processing binding configuration of Item ‘loadAverage5min (Type=NumberItem, State=Uninitialized)’ with ‘SysteminfoGenericBindingProvider’ reader.
18:27:26.421 [DEBUG] [i.internal.GenericItemProvider:341 ] - Start processing binding configuration of Item ‘loadAverage15min (Type=NumberItem, State=Uninitialized)’ with ‘SysteminfoGenericBindingProvider’ reader.
18:27:26.437 [DEBUG] [i.internal.GenericItemProvider:341 ] - Start processing binding configuration of Item ‘sensor_1_temp (Type=NumberItem, State=Uninitialized)’ with ‘ZWaveGenericBindingProvider’ reader.
18:27:26.446 [DEBUG] [i.internal.GenericItemProvider:341 ] - Start processing binding configuration of Item ‘sensor_1_humidity (Type=NumberItem, State=Uninitialized)’ with ‘ZWaveGenericBindingProvider’ reader.
18:27:26.447 [DEBUG] [i.internal.GenericItemProvider:341 ] - Start processing binding configuration of Item ‘sensor_1_luminance (Type=NumberItem, State=Uninitialized)’ with ‘ZWaveGenericBindingProvider’ reader.
18:27:26.448 [DEBUG] [i.internal.GenericItemProvider:341 ] - Start processing binding configuration of Item ‘sensor_1_motion (Type=ContactItem, State=Uninitialized)’ with ‘ZWaveGenericBindingProvider’ reader.
18:27:26.448 [DEBUG] [i.internal.GenericItemProvider:341 ] - Start processing binding configuration of Item ‘sensor_1_battery (Type=NumberItem, State=Uninitialized)’ with ‘ZWaveGenericBindingProvider’ reader.
18:27:26.451 [INFO ] [b.s.internal.SysteminfoBinding:416 ] - Using Sigar version 1.6.4.129
18:27:26.452 [DEBUG] [b.s.internal.SysteminfoBinding:420 ] - valid net interfaces: [lo, eth0]
18:27:26.457 [DEBUG] [b.s.internal.SysteminfoBinding:423 ] - file systems: [/, /sys, /proc, /dev, /dev/pts, /run, /, /run/lock, /run/shm, /boot/efi, /var/lib/nfs/rpc_pipefs, /sys/kernel/security, /media/timecapsule]
18:27:26.457 [DEBUG] [b.s.internal.SysteminfoBinding:433 ] - valid disk names: [/dev/disk/by-uuid/9b8d56cf-7b50-4a76-8c75-14f0bbf3c274, /dev/sdb1]
18:27:26.461 [INFO ] [.service.AbstractActiveService:169 ] - Systeminfo Refresh Service has been started
18:27:26.463 [DEBUG] [b.s.internal.SysteminfoBinding:102 ] - item ‘loadAverage5min’ is about to be refreshed now
18:27:26.464 [DEBUG] [sqlPersistenceServiceActivator:32 ] - mySQL persistence bundle has been started.
18:27:26.482 [INFO ] [.service.AbstractActiveService:169 ] - ZWave Refresh Service has been started
18:27:26.482 [DEBUG] [b.s.internal.SysteminfoBinding:102 ] - item ‘loadAverage1min’ is about to be refreshed now
18:27:26.483 [DEBUG] [b.s.internal.SysteminfoBinding:102 ] - item ‘loadAverage15min’ is about to be refreshed now
18:27:26.483 [DEBUG] [.p.m.i.MysqlPersistenceService:475 ] - mySQL: Attempting to connect to database jdbc:mysql://127.0.0.1/openhab
18:27:26.597 [DEBUG] [.p.m.i.MysqlPersistenceService:478 ] - mySQL: Connected to database jdbc:mysql://127.0.0.1/openhab
18:27:26.600 [DEBUG] [.p.m.i.MysqlPersistenceService:184 ] - mySQL configuration complete.
18:27:26.602 [DEBUG] [.p.internal.PersistenceManager:146 ] - Initializing mysql persistence service.
18:27:26.624 [DEBUG] [.p.internal.PersistenceManager:428 ] - Scheduled strategy mysql.everyMinute with cron expression 0 * * * * ?
18:27:26.626 [DEBUG] [.p.internal.PersistenceManager:428 ] - Scheduled strategy mysql.everyHour with cron expression 0 0 * * * ?
18:27:26.627 [DEBUG] [.p.internal.PersistenceManager:428 ] - Scheduled strategy mysql.everyDay with cron expression 0 0 0 * * ?
18:27:26.629 [DEBUG] [.b.mqtt.internal.MqttActivator:34 ] - MQTT binding has been started.
18:27:26.645 [DEBUG] [i.internal.GenericItemProvider:341 ] - Start processing binding configuration of Item ‘Heizungskeller_Temp (Type=NumberItem, State=Uninitialized)’ with ‘MqttGenericBindingProvider’ reader.
18:27:26.650 [DEBUG] [b.mqtt.internal.MqttItemConfig:72 ] - Loaded MQTT config for item ‘Heizungskeller_Temp’ : 1 subscribers, 0 publishers
18:27:26.650 [DEBUG] [o.i.t.m.i.MqttBrokerConnection:476 ] - Starting message consumer for broker ‘broker’ on topic 'openhab/keller/heizungskeller/temp’
18:27:26.655 [DEBUG] [m.internal.MqttEventBusBinding:68 ] - MQTT: Activating event bus binding.

I’m not sure then. I would suggest to upgrade to the latest version, but I’m not sure that will help unfortunately.

I’m going to ask a dumb question here… Normally you go about adding things by seeing the device in habmin (or the log), then making the device entry in an items file. But it sounds like you went the other way around (added them into the items file and then went to go see them in habmin). Can you clarify the order of events?

In addition try temporarily moving everything out of (openhab)/items and restart openhab. Then check out what you have in habmin after a minute or two as far as zwave devices are concerned.

I added them first to the items file, since I saw them in ozwcp and I thought habmin is not mandatory, just an alternative to ozwcp for finding the node id, etc. Is that not correct? I just went to habmin, since it wasn’t displaying any values.

I removed all item files and restarted openhab, but even after 5 minutes of waiting, unfortunately it’s still the same.

@chris: Which version do you mean? Is 1.8.2 not the latest version or do you mean openhab2?

That’s correct - you don’t need to use HABmin, although by having to change between OZWCP and OH, you must keep stopping and starting OH to make config changes to devices or find their status.

No - I mean version 1.9. This is basically the same as 1.8, but with some bugs fixed and database updates.

Thanks, that helped. Now I see all the devices. Many thanks!