OH2 Z-Wave refactoring and testing... and SECURITY

Seeing the same thing with 2.1.0.20170617084706-1

Sorry.

Unfortunately ESH has made a breaking change that has broken the ZWave binding. I only found out about this merge after it was merged into OH so there was little I could do (other than apologise - sorry).

I wonā€™t be able to fix this probably until tomorrow night.

1 Like

No problems, good to hear you know about it!

Meanwhile, during the last couple of hours, I have received this excption three times;

openhab> java.lang.reflect.InvocationTargetException
        at sun.reflect.NativeMethodAccessorImpl.invoke0(Native Method)
        at sun.reflect.NativeMethodAccessorImpl.invoke(NativeMethodAccessorImpl.java:62)
        at sun.reflect.DelegatingMethodAccessorImpl.invoke(DelegatingMethodAccessorImpl.java:43)
        at java.lang.reflect.Method.invoke(Method.java:498)
        at org.openhab.binding.zwave.internal.protocol.commandclass.ZWaveCommandClass.handleApplicationCommandRequest(ZWaveCommandClass.java:245)
        at org.openhab.binding.zwave.internal.protocol.ZWaveNode.processCommand(ZWaveNode.java:1284)
        at org.openhab.binding.zwave.internal.protocol.ZWaveTransactionManager$ZWaveReceiveThread.run(ZWaveTransactionManager.java:414)
Caused by: java.lang.ArrayIndexOutOfBoundsException: 3
        at org.openhab.binding.zwave.internal.protocol.ZWaveCommandClassPayload.getPayloadByte(ZWaveCommandClassPayload.java:49)
        at org.openhab.binding.zwave.internal.protocol.commandclass.ZWaveThermostatSetpointCommandClass.handleThermostatSetpointReport(ZWaveThermostatSetpointCommandClass.java:138)

Since it is looks like a thermostat, I guess it could be my ZXT-120. But I am not 100%. Iā€™ll leave the karaf shell open to see if I can catch it in situ.

Edit: After leaving the karaf open for 10 hours, it never occurred again, so I guess it only appeared during startup of the device. Will leave the karaf session open for a couple of hours more just to be sure.

Iā€™ve just updated the binding - hopefully it solves the issue (Iā€™ve only just got home so only had limited time to test).

Hi Chris, I updated the .jar to the one from June 18, and my z-wave network stopped responding. Screenshot from Habmin below, and Iā€™ve emailed you logs. Iā€™m running OpenHab2 on a Pi, via Habmin, which I just used to upgrade all the software packages tonight.

I replaced the June 18 version with a .jar I downloaded on June 16. Iā€™m primarily using Z-wave for door locks, and I have those working with the June 16 version. The only thing missing, is I can no longer set user codes from Habmin, but I have the alarm number channel working to update the status of my lock.

For those interested, here is my .rules file to update my Yale deadbolt status based on the value of the alarm number. In addition to the zWaveLock and zWaveAlarm items, I have an Lutron RadioRA2 item associated with each lock, so I can use my Lutron keypads to trigger rules to function my locks, and a dummy item, Lock_Rules_Active, to guard against concurrency.

Thanks for all the work youā€™ve put into openHAB and the Z-Wave binding Chris.

//---------------------------------------------------------------------------------------------------------------
//start of lambda functions to allow code to be re-used
import org.eclipse.xtext.xbase.lib.Functions

//Function to update the both the physical Z-Wave and virtual Lutron lock items when they are functioned outside of OpenHAB
val Functions$Function3 zWaveAlarmDeadBolt = [
	NumberItem zWaveAlarm, 
	SwitchItem zWaveLock, 
	SwitchItem lutronVirLock|
		var int alarm = (zWaveAlarm.state as DecimalType).intValue
		if (Lock_Rules_Active.state == OFF) {
			Lock_Rules_Active.postUpdate(ON)
			if (alarm == 19 || alarm == 22 || alarm == 25 ) { 
				//Unlocked by keypad (19), RF (22), or key/inside (25)
				zWaveLock.postUpdate(OFF)
				lutronVirLock.sendCommand(ON)
			}
			if (alarm == 18 || alarm == 21 || alarm == 24 ) { 
				//Locked by keypad (18), RF (21), or key/inside (24)
				zWaveLock.postUpdate(ON)
				lutronVirLock.sendCommand(OFF)
			}
			Thread::sleep(1000)
			Lock_Rules_Active.postUpdate(OFF)	
		}	
]

// end of lambda functions
//---------------------------------------------------------------------------------------------------------------

rule "Back Deadbolt Lock Status"
when Item ZW_Lock_backAlarm received update
then zWaveAlarmDeadBolt.apply (ZW_Lock_backAlarm, ZW_Lock_backBolt, Lut_LR_LockBack)
end

rule "Front Deadbolt Lock Status"
when Item ZW_Lock_frontAlarm received update
then zWaveAlarmDeadBolt.apply (ZW_Lock_frontAlarm, ZW_Lock_frontBolt, Lut_LR_LockFront)
end

rule "Garage Deadbolt Lock Status"
when Item ZW_Lock_garageAlarm received update
then zWaveAlarmDeadBolt.apply (ZW_Lock_garageAlarm, ZW_Lock_garageBolt, Lut_LR_LockGarage)
end  

Same here (snapshot build #945). Reverting to previous dev binding solved the issue.

2017-06-20 10:48:10.111 [ERROR] [org.openhab.binding.zwave           ] - FrameworkEvent ERROR - org.openhab.binding.zwave
org.osgi.framework.ServiceException: Exception in org.apache.felix.scr.impl.manager.SingleComponentManager.getService()
	at org.eclipse.osgi.internal.serviceregistry.ServiceFactoryUse.factoryGetService(ServiceFactoryUse.java:222)[org.eclipse.osgi-3.10.101.v20150820-1432.jar:]
	at org.eclipse.osgi.internal.serviceregistry.ServiceFactoryUse.getService(ServiceFactoryUse.java:111)[org.eclipse.osgi-3.10.101.v20150820-1432.jar:]
	at org.eclipse.osgi.internal.serviceregistry.ServiceConsumer$2.getService(ServiceConsumer.java:45)[org.eclipse.osgi-3.10.101.v20150820-1432.jar:]
	at org.eclipse.osgi.internal.serviceregistry.ServiceRegistrationImpl.getService(ServiceRegistrationImpl.java:496)[org.eclipse.osgi-3.10.101.v20150820-1432.jar:]
	at org.eclipse.osgi.internal.serviceregistry.ServiceRegistry.getService(ServiceRegistry.java:461)[org.eclipse.osgi-3.10.101.v20150820-1432.jar:]
	at org.eclipse.osgi.internal.framework.BundleContextImpl.getService(BundleContextImpl.java:619)[org.eclipse.osgi-3.10.101.v20150820-1432.jar:]
	at org.apache.felix.scr.impl.manager.SingleRefPair.getServiceObject(SingleRefPair.java:72)[32:org.apache.felix.scr:2.0.6]
	at org.apache.felix.scr.impl.inject.BindMethod.getServiceObject(BindMethod.java:648)[32:org.apache.felix.scr:2.0.6]
	at org.apache.felix.scr.impl.manager.DependencyManager.getServiceObject(DependencyManager.java:2201)[32:org.apache.felix.scr:2.0.6]
	at org.apache.felix.scr.impl.manager.DependencyManager.doInvokeBindMethod(DependencyManager.java:1714)[32:org.apache.felix.scr:2.0.6]
	at org.apache.felix.scr.impl.manager.DependencyManager.invokeBindMethod(DependencyManager.java:1699)[32:org.apache.felix.scr:2.0.6]
	at org.apache.felix.scr.impl.manager.SingleComponentManager.invokeBindMethod(SingleComponentManager.java:371)[32:org.apache.felix.scr:2.0.6]
	at org.apache.felix.scr.impl.manager.DependencyManager$MultipleDynamicCustomizer.addedService(DependencyManager.java:320)[32:org.apache.felix.scr:2.0.6]
	at org.apache.felix.scr.impl.manager.DependencyManager$MultipleDynamicCustomizer.addedService(DependencyManager.java:291)[32:org.apache.felix.scr:2.0.6]
	at org.apache.felix.scr.impl.manager.ServiceTracker$Tracked.customizerAdded(ServiceTracker.java:1215)[32:org.apache.felix.scr:2.0.6]
	at org.apache.felix.scr.impl.manager.ServiceTracker$Tracked.customizerAdded(ServiceTracker.java:1136)[32:org.apache.felix.scr:2.0.6]
	at org.apache.felix.scr.impl.manager.ServiceTracker$AbstractTracked.trackAdding(ServiceTracker.java:945)[32:org.apache.felix.scr:2.0.6]
	at org.apache.felix.scr.impl.manager.ServiceTracker$AbstractTracked.track(ServiceTracker.java:881)[32:org.apache.felix.scr:2.0.6]
	at org.apache.felix.scr.impl.manager.ServiceTracker$Tracked.serviceChanged(ServiceTracker.java:1167)[32:org.apache.felix.scr:2.0.6]
	at org.apache.felix.scr.impl.BundleComponentActivator$ListenerInfo.serviceChanged(BundleComponentActivator.java:127)[32:org.apache.felix.scr:2.0.6]
	at org.eclipse.osgi.internal.serviceregistry.FilteredServiceListener.serviceChanged(FilteredServiceListener.java:109)[org.eclipse.osgi-3.10.101.v20150820-1432.jar:]
	at org.eclipse.osgi.internal.framework.BundleContextImpl.dispatchEvent(BundleContextImpl.java:914)[org.eclipse.osgi-3.10.101.v20150820-1432.jar:]
	at org.eclipse.osgi.framework.eventmgr.EventManager.dispatchEvent(EventManager.java:230)[org.eclipse.osgi-3.10.101.v20150820-1432.jar:]
	at org.eclipse.osgi.framework.eventmgr.ListenerQueue.dispatchEventSynchronous(ListenerQueue.java:148)[org.eclipse.osgi-3.10.101.v20150820-1432.jar:]
	at org.eclipse.osgi.internal.serviceregistry.ServiceRegistry.publishServiceEventPrivileged(ServiceRegistry.java:862)[org.eclipse.osgi-3.10.101.v20150820-1432.jar:]
	at org.eclipse.osgi.internal.serviceregistry.ServiceRegistry.publishServiceEvent(ServiceRegistry.java:801)[org.eclipse.osgi-3.10.101.v20150820-1432.jar:]
	at org.eclipse.osgi.internal.serviceregistry.ServiceRegistrationImpl.register(ServiceRegistrationImpl.java:127)[org.eclipse.osgi-3.10.101.v20150820-1432.jar:]
	at org.eclipse.osgi.internal.serviceregistry.ServiceRegistry.registerService(ServiceRegistry.java:225)[org.eclipse.osgi-3.10.101.v20150820-1432.jar:]
	at org.eclipse.osgi.internal.framework.BundleContextImpl.registerService(BundleContextImpl.java:464)[org.eclipse.osgi-3.10.101.v20150820-1432.jar:]
	at org.apache.felix.scr.impl.manager.AbstractComponentManager$3.register(AbstractComponentManager.java:886)[32:org.apache.felix.scr:2.0.6]
	at org.apache.felix.scr.impl.manager.AbstractComponentManager$3.register(AbstractComponentManager.java:873)[32:org.apache.felix.scr:2.0.6]
	at org.apache.felix.scr.impl.manager.RegistrationManager.changeRegistration(RegistrationManager.java:132)[32:org.apache.felix.scr:2.0.6]
	at org.apache.felix.scr.impl.manager.AbstractComponentManager.registerService(AbstractComponentManager.java:940)[32:org.apache.felix.scr:2.0.6]
	at org.apache.felix.scr.impl.manager.AbstractComponentManager.activateInternal(AbstractComponentManager.java:740)[32:org.apache.felix.scr:2.0.6]
	at org.apache.felix.scr.impl.manager.AbstractComponentManager.enableInternal(AbstractComponentManager.java:674)[32:org.apache.felix.scr:2.0.6]
	at org.apache.felix.scr.impl.manager.AbstractComponentManager.enable(AbstractComponentManager.java:429)[32:org.apache.felix.scr:2.0.6]
	at org.apache.felix.scr.impl.manager.ConfigurableComponentHolder.enableComponents(ConfigurableComponentHolder.java:657)[32:org.apache.felix.scr:2.0.6]
	at org.apache.felix.scr.impl.BundleComponentActivator.initialEnable(BundleComponentActivator.java:341)[32:org.apache.felix.scr:2.0.6]
	at org.apache.felix.scr.impl.Activator.loadComponents(Activator.java:403)[32:org.apache.felix.scr:2.0.6]
	at org.apache.felix.scr.impl.Activator.access$200(Activator.java:54)[32:org.apache.felix.scr:2.0.6]
	at org.apache.felix.scr.impl.Activator$ScrExtension.start(Activator.java:278)[32:org.apache.felix.scr:2.0.6]
	at org.apache.felix.utils.extender.AbstractExtender.createExtension(AbstractExtender.java:259)[32:org.apache.felix.scr:2.0.6]
	at org.apache.felix.utils.extender.AbstractExtender.modifiedBundle(AbstractExtender.java:232)[32:org.apache.felix.scr:2.0.6]
	at org.osgi.util.tracker.BundleTracker$Tracked.customizerModified(BundleTracker.java:482)[org.osgi.core-6.0.0.jar:]
	at org.osgi.util.tracker.BundleTracker$Tracked.customizerModified(BundleTracker.java:415)[org.osgi.core-6.0.0.jar:]
	at org.osgi.util.tracker.AbstractTracked.track(AbstractTracked.java:232)[org.osgi.core-6.0.0.jar:]
	at org.osgi.util.tracker.BundleTracker$Tracked.bundleChanged(BundleTracker.java:444)[org.osgi.core-6.0.0.jar:]
	at org.eclipse.osgi.internal.framework.BundleContextImpl.dispatchEvent(BundleContextImpl.java:902)[org.eclipse.osgi-3.10.101.v20150820-1432.jar:]
	at org.eclipse.osgi.framework.eventmgr.EventManager.dispatchEvent(EventManager.java:230)[org.eclipse.osgi-3.10.101.v20150820-1432.jar:]
	at org.eclipse.osgi.framework.eventmgr.ListenerQueue.dispatchEventSynchronous(ListenerQueue.java:148)[org.eclipse.osgi-3.10.101.v20150820-1432.jar:]
	at org.eclipse.osgi.internal.framework.EquinoxEventPublisher.publishBundleEventPrivileged(EquinoxEventPublisher.java:165)[org.eclipse.osgi-3.10.101.v20150820-1432.jar:]
	at org.eclipse.osgi.internal.framework.EquinoxEventPublisher.publishBundleEvent(EquinoxEventPublisher.java:75)[org.eclipse.osgi-3.10.101.v20150820-1432.jar:]
	at org.eclipse.osgi.internal.framework.EquinoxEventPublisher.publishBundleEvent(EquinoxEventPublisher.java:67)[org.eclipse.osgi-3.10.101.v20150820-1432.jar:]
	at org.eclipse.osgi.internal.framework.EquinoxContainerAdaptor.publishModuleEvent(EquinoxContainerAdaptor.java:102)[org.eclipse.osgi-3.10.101.v20150820-1432.jar:]
	at org.eclipse.osgi.container.Module.publishEvent(Module.java:466)[org.eclipse.osgi-3.10.101.v20150820-1432.jar:]
	at org.eclipse.osgi.container.Module.start(Module.java:457)[org.eclipse.osgi-3.10.101.v20150820-1432.jar:]
	at org.eclipse.osgi.container.ModuleContainer$ContainerStartLevel.incStartLevel(ModuleContainer.java:1582)[org.eclipse.osgi-3.10.101.v20150820-1432.jar:]
	at org.eclipse.osgi.container.ModuleContainer$ContainerStartLevel.incStartLevel(ModuleContainer.java:1562)[org.eclipse.osgi-3.10.101.v20150820-1432.jar:]
	at org.eclipse.osgi.container.ModuleContainer$ContainerStartLevel.doContainerStartLevel(ModuleContainer.java:1533)[org.eclipse.osgi-3.10.101.v20150820-1432.jar:]
	at org.eclipse.osgi.container.ModuleContainer$ContainerStartLevel.dispatchEvent(ModuleContainer.java:1476)[org.eclipse.osgi-3.10.101.v20150820-1432.jar:]
	at org.eclipse.osgi.container.ModuleContainer$ContainerStartLevel.dispatchEvent(ModuleContainer.java:1)[org.eclipse.osgi-3.10.101.v20150820-1432.jar:]
	at org.eclipse.osgi.framework.eventmgr.EventManager.dispatchEvent(EventManager.java:230)[org.eclipse.osgi-3.10.101.v20150820-1432.jar:]
	at org.eclipse.osgi.framework.eventmgr.EventManager$EventThread.run(EventManager.java:340)[org.eclipse.osgi-3.10.101.v20150820-1432.jar:]
Caused by: java.lang.NoClassDefFoundError: org/eclipse/smarthome/core/i18n/TranslationProvider
	at java.lang.Class.getDeclaredMethods0(Native Method)[:1.8.0_131]
	at java.lang.Class.privateGetDeclaredMethods(Class.java:2701)[:1.8.0_131]
	at java.lang.Class.getDeclaredMethods(Class.java:1975)[:1.8.0_131]
	at org.apache.felix.scr.impl.inject.ActivateMethod.getSortedMethods(ActivateMethod.java:196)
	at org.apache.felix.scr.impl.inject.ActivateMethod.doFindMethod(ActivateMethod.java:85)
	at org.apache.felix.scr.impl.inject.BaseMethod.findMethod(BaseMethod.java:173)
	at org.apache.felix.scr.impl.inject.BaseMethod.access$400(BaseMethod.java:39)
	at org.apache.felix.scr.impl.inject.BaseMethod$NotResolved.resolve(BaseMethod.java:560)
	at org.apache.felix.scr.impl.inject.BaseMethod$NotResolved.methodExists(BaseMethod.java:582)
	at org.apache.felix.scr.impl.inject.BaseMethod.methodExists(BaseMethod.java:515)
	at org.apache.felix.scr.impl.inject.ActivateMethod.invoke(ActivateMethod.java:300)
	at org.apache.felix.scr.impl.inject.ActivateMethod.invoke(ActivateMethod.java:294)
	at org.apache.felix.scr.impl.manager.SingleComponentManager.createImplementationObject(SingleComponentManager.java:297)
	at org.apache.felix.scr.impl.manager.SingleComponentManager.createComponent(SingleComponentManager.java:108)
	at org.apache.felix.scr.impl.manager.SingleComponentManager.getService(SingleComponentManager.java:906)
	at org.apache.felix.scr.impl.manager.SingleComponentManager.getServiceInternal(SingleComponentManager.java:879)
	at org.apache.felix.scr.impl.manager.SingleComponentManager.getService(SingleComponentManager.java:823)
	at org.eclipse.osgi.internal.serviceregistry.ServiceFactoryUse$1.run(ServiceFactoryUse.java:212)[org.eclipse.osgi-3.10.101.v20150820-1432.jar:]
	at java.security.AccessController.doPrivileged(Native Method)[:1.8.0_131]
	at org.eclipse.osgi.internal.serviceregistry.ServiceFactoryUse.factoryGetService(ServiceFactoryUse.java:210)[org.eclipse.osgi-3.10.101.v20150820-1432.jar:]
	... 62 more
Caused by: java.lang.ClassNotFoundException: org.eclipse.smarthome.core.i18n.TranslationProvider cannot be found by org.openhab.binding.zwave_2.1.0.201706182030
	at org.eclipse.osgi.internal.loader.BundleLoader.findClassInternal(BundleLoader.java:389)[org.eclipse.osgi-3.10.101.v20150820-1432.jar:]
	at org.eclipse.osgi.internal.loader.BundleLoader.findClass(BundleLoader.java:352)[org.eclipse.osgi-3.10.101.v20150820-1432.jar:]
	at org.eclipse.osgi.internal.loader.BundleLoader.findClass(BundleLoader.java:344)[org.eclipse.osgi-3.10.101.v20150820-1432.jar:]
	at org.eclipse.osgi.internal.loader.ModuleClassLoader.loadClass(ModuleClassLoader.java:160)[org.eclipse.osgi-3.10.101.v20150820-1432.jar:]
	at java.lang.ClassLoader.loadClass(ClassLoader.java:357)[:1.8.0_131]
	... 82 more

Note that the latest version will ONLY work with the latest runtime.

ESH made a breaking change and changed the name of the I18Provider to TranslationProvider - given that the error is TranslationProvider is not found, I expect you are still using an old version of ESH?

Sorry, but given the runtime has changed I canā€™t now provide versions that work with both the old and new runtime.

So from the 2017-06-18 version and forward it will only work on 2.1 snapshot, right? Guess it starts getting time for me to get my ass out of the 2.0 wagonā€¦

Yes - but to be a little clearer - it will only work with a version of 2.1 that is dated 16th June or later. This doesnā€™t impact people moving from 2.0, but for those already on 2.1, the runtime will need to be from after this date which is when the change was migrated from ESH.

1 Like

Sure, no problem.

Hi @chris
I caught a couple of these exceptions while upgrading to 18ā€™th binding;
(Node 58 is a Remotec ZXT-120)

20:49:08.260 [DEBUG] [nal.protocol.ZWaveTransactionManager] - NODE 77: Checking transaction : node  >> 61
20:49:08.260 [DEBUG] [nal.protocol.ZWaveTransactionManager] - NODE 77: Checking transaction : class >> 32 == 32.
20:49:08.260 [DEBUG] [nal.protocol.ZWaveTransactionManager] - NODE 77: Checking transaction : commd >> 3 == 3.
20:49:08.260 [DEBUG] [nal.protocol.ZWaveTransactionManager] - NODE 77: Ignoring transaction since not waiting for data.
20:49:08.260 [DEBUG] [nal.protocol.ZWaveTransactionManager] - Transaction completed - outstandingTransactions 1
20:49:08.260 [DEBUG] [nal.protocol.ZWaveTransactionManager] - Transaction completed - outstandingTransactions 1
20:49:08.260 [DEBUG] [nal.protocol.ZWaveTransactionManager] - ZWaveReceiveThread queue empty
20:49:08.260 [DEBUG] [nal.protocol.ZWaveTransactionManager] - Transaction SendNextMessage 1 out at start
20:49:08.261 [DEBUG] [nal.protocol.ZWaveTransactionManager] - Transaction lastTransaction outstanding...
20:49:08.261 [DEBUG] [nal.protocol.ZWaveTransactionManager] - STOP transaction timer
20:49:08.261 [DEBUG] [nal.protocol.ZWaveTransactionManager] - Start transaction timer to Thu Jun 22 20:49:12 CEST 2017 - 4596ms
20:49:08.313 [DEBUG] [WaveSerialHandler$ZWaveReceiveThread] - Receive Message = 01 09 00 04 00 3A 03 31 05 01 FE 
20:49:08.314 [DEBUG] [WaveSerialHandler$ZWaveReceiveThread] - Response SENT 6
20:49:08.314 [DEBUG] [nal.protocol.ZWaveTransactionManager] - processReceiveMessage inputMessage: class=ApplicationCommandHandler[0x04], type=Request[0x00], dest=58, callback=0, payload=00 3A 03 31 05 01 
20:49:08.314 [DEBUG] [nal.protocol.ZWaveTransactionManager] - processReceiveMessage past lockMessage: class=ApplicationCommandHandler[0x04], type=Request[0x00], dest=58, callback=0, payload=00 3A 03 31 05 01 
20:49:08.314 [DEBUG] [nal.protocol.ZWaveTransactionManager] - Received msg Message: class=ApplicationCommandHandler[0x04], type=Request[0x00], dest=58, callback=0, payload=00 3A 03 31 05 01 
20:49:08.314 [DEBUG] [nal.protocol.ZWaveTransactionManager] - lastTransaction TID 1889: [WAIT_REQUEST] requiresResponse=false callback: 51
20:49:08.314 [DEBUG] [nal.protocol.ZWaveTransactionManager] - NODE 58: Application Command Request (ALIVE:DONE)
20:49:08.314 [DEBUG] [ng.zwave.internal.protocol.ZWaveNode] - NODE 58: resetResendCount initComplete=true isDead=false
20:49:08.314 [DEBUG] [ng.zwave.internal.protocol.ZWaveNode] - NODE 58: Incoming command class COMMAND_CLASS_SENSOR_MULTILEVEL, endpoint 0
20:49:08.314 [DEBUG] [ng.zwave.internal.protocol.ZWaveNode] - NODE 58: SECURITY not supported
20:49:08.314 [DEBUG] [tocol.commandclass.ZWaveCommandClass] - NODE 58: Received COMMAND_CLASS_SENSOR_MULTILEVEL V1 SENSOR_MULTILEVEL_REPORT
java.lang.reflect.InvocationTargetException
        at sun.reflect.GeneratedMethodAccessor96.invoke(Unknown Source)
        at sun.reflect.DelegatingMethodAccessorImpl.invoke(DelegatingMethodAccessorImpl.java:43)
        at java.lang.reflect.Method.invoke(Method.java:498)
        at org.openhab.binding.zwave.internal.protocol.commandclass.ZWaveCommandClass.handleApplicationCommandRequest(ZWaveCommandClass.java:245)
        at org.openhab.binding.zwave.internal.protocol.ZWaveNode.processCommand(ZWaveNode.java:1284)
        at org.openhab.binding.zwave.internal.protocol.ZWaveTransactionManager$ZWaveReceiveThread.run(ZWaveTransactionManager.java:414)
Caused by: java.lang.ArrayIndexOutOfBoundsException: 3
        at org.openhab.binding.zwave.internal.protocol.ZWaveCommandClassPayload.getPayloadByte(ZWaveCommandClassPayload.java:49)
        at org.openhab.binding.zwave.internal.protocol.commandclass.ZWaveMultiLevelSensorCommandClass.handleSensorMultilevelReport(ZWaveMultiLevelSensorCommandClass.java:116)
        ... 6 more
20:49:08.315 [DEBUG] [nal.protocol.ZWaveTransactionManager] - NODE 58: Commands processed 1.
20:49:08.315 [DEBUG] [nal.protocol.ZWaveTransactionManager] - NODE 58: Checking command org.openhab.binding.zwave.internal.protocol.ZWaveCommandClassPayload@1fd2b061.
20:49:08.315 [DEBUG] [nal.protocol.ZWaveTransactionManager] - NODE 58: Checking transaction 1889  ApplicationCommandHandler.
20:49:08.315 [DEBUG] [nal.protocol.ZWaveTransactionManager] - NODE 58: Checking transaction : state >> WAIT_REQUEST
20:49:08.315 [DEBUG] [nal.protocol.ZWaveTransactionManager] - NODE 58: Checking transaction : node  >> 61
20:49:08.315 [DEBUG] [nal.protocol.ZWaveTransactionManager] - NODE 58: Checking transaction : class >> 49 == 32.
20:49:08.315 [DEBUG] [nal.protocol.ZWaveTransactionManager] - NODE 58: Checking transaction : commd >> 5 == 3.
20:49:08.315 [DEBUG] [nal.protocol.ZWaveTransactionManager] - NODE 58: Ignoring transaction since not waiting for data.
20:49:08.315 [DEBUG] [nal.protocol.ZWaveTransactionManager] - Transaction completed - outstandingTransactions 1
20:49:08.315 [DEBUG] [nal.protocol.ZWaveTransactionManager] - Transaction completed - outstandingTransactions 1
20:49:08.315 [DEBUG] [nal.protocol.ZWaveTransactionManager] - ZWaveReceiveThread queue empty
20:49:08.315 [DEBUG] [nal.protocol.ZWaveTransactionManager] - Transaction SendNextMessage 1 out at start
20:49:08.316 [DEBUG] [nal.protocol.ZWaveTransactionManager] - Transaction lastTransaction outstanding...
20:49:08.316 [DEBUG] [nal.protocol.ZWaveTransactionManager] - STOP transaction timer
20:49:08.316 [DEBUG] [nal.protocol.ZWaveTransactionManager] - Start transaction timer to Thu Jun 22 20:49:12 CEST 2017 - 4541ms
20:49:08.344 [DEBUG] [WaveSerialHandler$ZWaveReceiveThread] - Receive Message = 01 09 00 04 00 4D 03 20 03 00 9F 
20:49:08.344 [DEBUG] [WaveSerialHandler$ZWaveReceiveThread] - Response SENT 6

Chris,

I have been seeing various delays since a couple of weeks, it feels like the zwave tx/rx are stalled by some timeout, normally 15-45 seconds, but sometimes the command is also immediate.
Since the start of the new binding, thereā€™s a lot of timer debug outputs - could you share what the timer value in a row such as this;
Start transaction timer to Thu Jun 22 20:49:12 CEST 2017 - 4541ms actually means with respect to the timer value (4541 in this case)? I am seeing lots with about 5000ms, and 2000ms - will these casue delays? (on the stack in general or on the actual node being put into the transaction timer?)

Yes - thatā€™s correct. The OH2 binding is using lower timeouts than OH1 where possible. OH1 used 5 seconds at all times - in OH2 I try to use 2 seconds in some places, but there are some longer ones (10 seconds or so I think for some commands - but these are very few and only normally used on startup).

No - a timeout is there to recover in the event that a device doesnā€™t respond. It doesnā€™t mean there is a delay - only if there is an error with the device. This has always been the same.

Thanks for explaining the timers!
Did you also see the exception post above? It is rare to catch the exceptions in the karaf log, which is why I ask. And do you want me to enter a ticket instead?
Edit: I have added ticket!

hi, im on latest snapshot and want to install this binding

openhab> bundle:start org.openhab.binding.zwave
Error executing command: No matching bundles

bundle:list dont find it
the JAR file is in /usr/share/openhab2/addons
but oh2 dont find it also not after oh2 restart.

its an apt-get installation, the standard z-wave binding is uninstalled.
what im missing here ?

Just a guess, but have you tried a fresh download? I had a similar experience after mangling the jar.

Is anyone else having troubles downloading the latest .jar file?

I use the latest dev branch version (from 18.06.2017). It works fine so far, but only runs on OH snapshot 950 upwards, it is not compatible with older buildsā€¦

Sorry - we had a long power cut today and the UPS on the servers only ran for the first 4 hours or so - weā€™re back up now (thankfully - Iā€™m hungry!).