[Solved] NPEs in zwave binding with latest sanpshot build 2.1.0.201704151452

Add-ons Bindings
21

Yay!

Okay - it seems the “workaround” I posted above works! It just missed to delete all the .xml files.

So steps to do is:

  • Go to PaperUI
  • Delete Z-Wave Controller
  • Delete Z-Wave Deices in PaperUI (sorry - no bulk delete there, so one by one to do)
  • Restart OpenHAB2
  • Add Z-Wave Controller
  • Go to Habmin
  • Add (bulk) all nodes
  • Change channel in your .items files to reflect new controller ID (you can use sed -i -e 's/oldID/newID/' *.items)
  • Delete all nodeY.xml files in /var/lib/openhab2/zwave directory.
  • Restart OpenHAB

Now some of my devices have come back (not yet all, but I suppose it takes time for the network to rebuild).

22

My system seems to be working again now after:

  • Stopping the openhab2 service
  • Deleting the zwave XML files
  • Starting the openhab2 service

Although I see a lot of red stuff flash past in the karaf log every RL test I do to the system works. Gonna download the logs and look a little more on what those red parts are saying.

23

Now I get those:

2017-04-17 00:34:20.753 [ERROR] [ve.internal.protocol.ZWaveController] - Exception during ZWave thread: Input 2. {}
java.lang.IllegalStateException: Timer already cancelled.
	at java.util.Timer.sched(Timer.java:397)[:1.8.0_121]
	at java.util.Timer.schedule(Timer.java:193)[:1.8.0_121]
	at org.openhab.binding.zwave.internal.protocol.initialization.ZWaveNodeInitStageAdvancer.startIdleTimer(ZWaveNodeInitStageAdvancer.java:1421)[207:org.openhab.binding.zwave:2.1.0.201704151452]
	at org.openhab.binding.zwave.internal.protocol.initialization.ZWaveNodeInitStageAdvancer.advanceNodeStage(ZWaveNodeInitStageAdvancer.java:297)[207:org.openhab.binding.zwave:2.1.0.201704151452]
	at org.openhab.binding.zwave.internal.protocol.initialization.ZWaveNodeInitStageAdvancer.ZWaveIncomingEvent(ZWaveNodeInitStageAdvancer.java:1340)[207:org.openhab.binding.zwave:2.1.0.201704151452]
	at org.openhab.binding.zwave.internal.protocol.ZWaveController.notifyEventListeners(ZWaveController.java:567)[207:org.openhab.binding.zwave:2.1.0.201704151452]
	at org.openhab.binding.zwave.internal.protocol.ZWaveNode.setNodeState(ZWaveNode.java:257)[207:org.openhab.binding.zwave:2.1.0.201704151452]
	at org.openhab.binding.zwave.internal.protocol.serialmessage.ApplicationCommandMessageClass.handleRequest(ApplicationCommandMessageClass.java:46)[207:org.openhab.binding.zwave:2.1.0.201704151452]
	at org.openhab.binding.zwave.internal.protocol.ZWaveController.handleIncomingRequestMessage(ZWaveController.java:248)[207:org.openhab.binding.zwave:2.1.0.201704151452]
	at org.openhab.binding.zwave.internal.protocol.ZWaveController.handleIncomingMessage(ZWaveController.java:214)[207:org.openhab.binding.zwave:2.1.0.201704151452]
	at org.openhab.binding.zwave.internal.protocol.ZWaveController.access$7(ZWaveController.java:208)[207:org.openhab.binding.zwave:2.1.0.201704151452]
	at org.openhab.binding.zwave.internal.protocol.ZWaveController$ZWaveInputThread.run(ZWaveController.java:1324)[207:org.openhab.binding.zwave:2.1.0.201704151452]
24

How about a reduced version - just delete the XML files and see if that works. Obviously you can’t do this, but others can try it and I can only think that the problem must have been related to the fix I’ve just merged.

25

The build I ran has completed although there are some test failures so I’m not sure if it’s used downstream. This might fix the problem - it’s the only thing I can think might have caused this.

26

I suppose deleting .xml files would have been sufficient (obviously I cannot try that any more). Thanks for that hint!

27

XML deleting option worked for me.
Thanks for the quick help. :slight_smile:

28

Phew :slight_smile:

I would strongly suggest to upgrade to the next version as it will hopefully solve the issue properly.

29

How do I do the update? Just uninstall and reinstall the binding in PaperUI?

30

I did controller remove, removed all things in karaf console, restarted OH2, deleted all XML files.
Recreated controller and things…

I have around 8 zwave devices, 50% of them still unknown… and I still see strange exceptions in the log… (“IllegalStateException timer already cancelled” this time)

hopefully it is just that network recreation takes some time?

31

Same Exceptions here… some devices unknown. I hope tomorrow morning the network will look better…

32

I just did apt-get update/upgrade…
nothing new atm.

How long does this build takes you recommend to upgrade to?

MArkus

33

Normally this should work.

I don’t know - the build of the binding is done already, but I don’t know when other packages downstream are rebuilt. I don’t know if packaged use the binding directly (in which case it should be available), or if it’s through something else.

34

I just checked my xml files… they are very big and do not contain what I expected (a device description) but stuff like this:

org.openhab.binding.zwave.internal.protocol.ZWaveDeviceClass karaf.startlevel.bundle 80 karaf.framework.felix mvn:org.apache.felix/org.apache.felix.framework/5.6.1 eecap-1.8 osgi.ee; osgi.ee="OSGi/Minimum"; version:List<Version>="1.0,1.1,1.2", osgi.ee; osgi.ee="JavaSE"; version:List<Version>="1.0,1.1,1.2,1.3,1.4,1.5,1.6,1.7,1.8" karaf.version 4.0.8 felix.fileinstall.dir /var/lib/openhab2/etc felix.fileinstall.log.default jul ...

Is this known?

35

This is what I mentioned earlier, and why I suggested to update to the newer version :wink:

36

I should add - the ‘real’ information is in there as well - it’s just a load of rubbish at the top that is the problem.

37

Ok.
I did a zwave binding uninstall / install and checked the bundle in karaf console.

But it is still 2.1.0.201704151452 which it was already this morning…

so obviously the new build is not yet available

38

Some test failed in the feed binding - I don’t know if this stops the whole build from being used downstream or not - hopefully not.

https://openhab.ci.cloudbees.com/job/openHAB2-Bundles/33/

39

I still get exceptions… now like these (looks like an endless loop somehow?)

2017-04-17 01:18:04.982 [DEBUG] [alization.ZWaveNodeInitStageAdvancer] - NODE 12: Stage DYNAMIC_END. Initialisation retry timer triggered. Increased to 10000
2017-04-17 01:18:04.983 [DEBUG] [alization.ZWaveNodeInitStageAdvancer] - NODE 12: Node advancer - DYNAMIC_END: queue length(0), free to send(true)
2017-04-17 01:18:04.983 [DEBUG] [alization.ZWaveNodeInitStageAdvancer] - NODE 12: Initialisation retry timer started 10000
2017-04-17 01:18:04.984 [DEBUG] [alization.ZWaveNodeInitStageAdvancer] - NODE 12: Node advancer: loop - DYNAMIC_END try 1: stageAdvanced(false)
2017-04-17 01:18:06.551 [ERROR] [ve.internal.protocol.ZWaveController] - Exception during ZWave thread: Input 2. {}
com.thoughtworks.xstream.converters.ConversionException: Could not call com.google.common.collect.Synchronized$SynchronizedSetMultimap.writeObject() : Could not call com.google.common.collect.HashMultimap.writeObject() : Could not call java.util.concurrent.ConcurrentLinkedQueue.writeObject() : null
---- Debugging information ----
message : Could not call java.util.concurrent.ConcurrentLinkedQueue.writeObject()
cause-exception : java.lang.StackOverflowError
cause-message : null

message : Could not call com.google.common.collect.HashMultimap.writeObject()
cause-exception : com.thoughtworks.xstream.converters.ConversionException
cause-message : Could not call java.util.concurrent.ConcurrentLinkedQueue.writeObject() : null

message : Could not call com.google.common.collect.Synchronized$SynchronizedSetMultimap.writeObject()
cause-exception : com.thoughtworks.xstream.converters.ConversionException
cause-message : Could not call com.google.common.collect.HashMultimap.writeObject() : Could not call java.util.concurrent.ConcurrentLinkedQueue.writeObject() : null
---- Debugging information ----
message : Could not call java.util.concurrent.ConcurrentLinkedQueue.writeObject()
cause-exception : java.lang.StackOverflowError
cause-message : null

at com.thoughtworks.xstream.converters.reflection.SerializationMethodInvoker.callWriteObject(SerializationMethodInvoker.java:140)[98:org.eclipse.smarthome.config.xml:0.9.0.201704011656]
at com.thoughtworks.xstream.converters.reflection.SerializableConverter.doMarshal(SerializableConverter.java:259)[98:org.eclipse.smarthome.config.xml:0.9.0.201704011656]
at com.thoughtworks.xstream.converters.reflection.AbstractReflectionConverter.marshal(AbstractReflectionConverter.java:83)[98:org.eclipse.smarthome.config.xml:0.9.0.201704011656]
at com.thoughtworks.xstream.core.AbstractReferenceMarshaller.convert(AbstractReferenceMarshaller.java:69)[98:org.eclipse.smarthome.config.xml:0.9.0.201704011656]
at com.thoughtworks.xstream.core.TreeMarshaller.convertAnother(TreeMarshaller.java:58)[98:org.eclipse.smarthome.config.xml:0.9.0.201704011656]
at com.thoughtworks.xstream.core.AbstractReferenceMarshaller$1.convertAnother(AbstractReferenceMarshaller.java:84)[98:org.eclipse.smarthome.config.xml:0.9.0.201704011656]
at com.thoughtworks.xstream.converters.reflection.AbstractReflectionConverter.marshallField(AbstractReflectionConverter.java:250)[98:org.eclipse.smarthome.config.xml:0.9.0.201704011656]
at com.thoughtworks.xstream.converters.reflection.AbstractReflectionConverter$2.writeField(AbstractReflectionConverter.java:226)[98:org.eclipse.smarthome.config.xml:0.9.0.201704011656]
at com.thoughtworks.xstream.converters.reflection.AbstractReflectionConverter$2.<init>(AbstractReflectionConverter.java:189)[98:org.eclipse.smarthome.config.xml:0.9.0.201704011656]
at com.thoughtworks.xstream.converters.reflection.AbstractReflectionConverter.doMarshal(AbstractReflectionConverter.java:135)[98:org.eclipse.smarthome.config.xml:0.9.0.201704011656]
at com.thoughtworks.xstream.converters.reflection.AbstractReflectionConverter.marshal(AbstractReflectionConverter.java:83)[98:org.eclipse.smarthome.config.xml:0.9.0.201704011656]
at com.thoughtworks.xstream.core.AbstractReferenceMarshaller.convert(AbstractReferenceMarshaller.java:69)[98:org.eclipse.smarthome.config.xml:0.9.0.201704011656]
at com.thoughtworks.xstream.core.TreeMarshaller.convertAnother(TreeMarshaller.java:58)[98:org.eclipse.smarthome.config.xml:0.9.0.201704011656]
at com.thoughtworks.xstream.core.AbstractReferenceMarshaller$1.convertAnother(AbstractReferenceMarshaller.java:84)[98:org.eclipse.smarthome.config.xml:0.9.0.201704011656]
at com.thoughtworks.xstream.converters.reflection.AbstractReflectionConverter.marshallField(AbstractReflectionConverter.java:250)[98:org.eclipse.smarthome.config.xml:0.9.0.201704011656]
at com.thoughtworks.xstream.converters.reflection.AbstractReflectionConverter$2.writeField(AbstractReflectionConverter.java:226)[98:org.eclipse.smarthome.config.xml:0.9.0.201704011656]
at com.thoughtworks.xstream.converters.reflection.AbstractReflectionConverter$2.<init>(AbstractReflectionConverter.java:189)[98:org.eclipse.smarthome.config.xml:0.9.0.201704011656]
at com.thoughtworks.xstream.converters.reflection.AbstractReflectionConverter.doMarshal(AbstractReflectionConverter.java:135)[98:org.eclipse.smarthome.config.xml:0.9.0.201704011656]
at com.thoughtworks.xstream.converters.reflection.AbstractReflectionConverter.marshal(AbstractReflectionConverter.java:83)[98:org.eclipse.smarthome.config.xml:0.9.0.201704011656]
at com.thoughtworks.xstream.core.AbstractReferenceMarshaller.convert(AbstractReferenceMarshaller.java:69)[98:org.eclipse.smarthome.config.xml:0.9.0.201704011656]
at com.thoughtworks.xstream.core.TreeMarshaller.convertAnother(TreeMarshaller.java:58)[98:org.eclipse.smarthome.config.xml:0.9.0.201704011656]

…
many hundred lines looking the same

40

After uninstall / install of the binding I don*t get any device any more and this exception:

2017-04-17 01:21:37.867 [ERROR] [ig.xml.osgi.XmlDocumentBundleTracker] - Could not send adding finished event for the module 'org.openhab.binding.zwave'!
java.lang.IllegalArgumentException: UID must have at least 2 segments.
	at org.eclipse.smarthome.core.thing.UID.<init>(UID.java:65)[106:org.eclipse.smarthome.core.thing:0.9.0.201704011656]
	at org.eclipse.smarthome.core.thing.UID.<init>(UID.java:43)[106:org.eclipse.smarthome.core.thing:0.9.0.201704011656]
	at org.eclipse.smarthome.core.thing.type.ChannelTypeUID.<init>(ChannelTypeUID.java:35)[106:org.eclipse.smarthome.core.thing:0.9.0.201704011656]
	at org.eclipse.smarthome.core.thing.xml.internal.ChannelXmlResult.toChannelDefinition(ChannelXmlResult.java:116)[107:org.eclipse.smarthome.core.thing.xml:0.9.0.201704011656]
	at org.eclipse.smarthome.core.thing.xml.internal.ThingTypeXmlResult.toChannelDefinitions(ThingTypeXmlResult.java:81)[107:org.eclipse.smarthome.core.thing.xml:0.9.0.201704011656]
	at org.eclipse.smarthome.core.thing.xml.internal.ThingTypeXmlResult.toThingType(ThingTypeXmlResult.java:129)[107:org.eclipse.smarthome.core.thing.xml:0.9.0.201704011656]
	at org.eclipse.smarthome.core.thing.xml.internal.ThingTypeXmlProvider.addingFinished(ThingTypeXmlProvider.java:145)[107:org.eclipse.smarthome.core.thing.xml:0.9.0.201704011656]
	at org.eclipse.smarthome.config.xml.osgi.XmlDocumentBundleTracker.addingFinished(XmlDocumentBundleTracker.java:220)[98:org.eclipse.smarthome.config.xml:0.9.0.201704011656]
	at org.eclipse.smarthome.config.xml.osgi.XmlDocumentBundleTracker.access$6(XmlDocumentBundleTracker.java:215)[98:org.eclipse.smarthome.config.xml:0.9.0.201704011656]
	at org.eclipse.smarthome.config.xml.osgi.XmlDocumentBundleTracker$1.processBundle(XmlDocumentBundleTracker.java:141)[98:org.eclipse.smarthome.config.xml:0.9.0.201704011656]
	at org.eclipse.smarthome.config.xml.osgi.AbstractAsyncBundleProcessor$1.run(AbstractAsyncBundleProcessor.java:231)[98:org.eclipse.smarthome.config.xml:0.9.0.201704011656]
	at java.lang.Thread.run(Thread.java:745)[:1.8.0_121]