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

Hi @chris,

I updated to the latest snapshot build and restarted everything.
I have exceptions during startup, in idle mode and when try to switch one device since I upgraded to the latest snapshot today.
I attached a complete log for one server startup with one action on node10.

Here an extract of the two NPEs:

IDLE MODE:

2017-04-16 21:24:23.915 [TRACE] [WaveSerialHandler$ZWaveReceiveThread] - Received SOF
2017-04-16 21:24:23.935 [DEBUG] [WaveSerialHandler$ZWaveReceiveThread] - Receive Message = 01 1F 00 04 00 02 19 8F 01 04 03 80 03 64 04 30 03 FF 0C 05 31 05 03 01 05 06 31 05 01 0A 00 47 1D
2017-04-16 21:24:23.941 [TRACE] [wave.internal.protocol.SerialMessage] - NODE 255: Creating new SerialMessage from buffer = 01 1F 00 04 00 02 19 8F 01 04 03 80 03 64 04 30 03 FF 0C 05 31 05 03 01 05 06 31 05 01 0A 00 47 1D
2017-04-16 21:24:23.943 [TRACE] [wave.internal.protocol.SerialMessage] - Calculated checksum = 0x1D
2017-04-16 21:24:23.946 [TRACE] [wave.internal.protocol.SerialMessage] - NODE 255: Checksum matched
2017-04-16 21:24:23.951 [TRACE] [wave.internal.protocol.SerialMessage] - NODE 255: Message payload = 00 02 19 8F 01 04 03 80 03 64 04 30 03 FF 0C 05 31 05 03 01 05 06 31 05 01 0A 00 47
2017-04-16 21:24:23.953 [TRACE] [WaveSerialHandler$ZWaveReceiveThread] - Message is valid, sending ACK
2017-04-16 21:24:23.956 [TRACE] [WaveSerialHandler$ZWaveReceiveThread] - Response SENT
2017-04-16 21:24:23.958 [DEBUG] [ve.internal.protocol.ZWaveController] - Receive queue TAKE: Length=0
2017-04-16 21:24:23.959 [TRACE] [wave.internal.protocol.SerialMessage] - Calculated checksum = 0x1D
2017-04-16 21:24:23.964 [DEBUG] [wave.internal.protocol.SerialMessage] - Assembled message buffer = 01 1F 00 04 00 02 19 8F 01 04 03 80 03 64 04 30 03 FF 0C 05 31 05 03 01 05 06 31 05 01 0A 00 47 1D
2017-04-16 21:24:23.969 [DEBUG] [ve.internal.protocol.ZWaveController] - Process Message = 01 1F 00 04 00 02 19 8F 01 04 03 80 03 64 04 30 03 FF 0C 05 31 05 03 01 05 06 31 05 01 0A 00 47 1D
2017-04-16 21:24:23.972 [DEBUG] [ve.internal.protocol.ZWaveController] - Message: class=ApplicationCommandHandler[0x04], type=Request[0x00], priority=High, dest=255, callback=0, payload=00 02 19 8F 01 04 03 80 03 64 04 30 03 FF 0C 05 31 05 03 01 05 06 31 05 01 0A 00 47
2017-04-16 21:24:23.972 [TRACE] [ve.internal.protocol.ZWaveController] - Incoming Message type = REQUEST
2017-04-16 21:24:23.973 [TRACE] [ssage.ApplicationCommandMessageClass] - Handle Message Application Command Request
2017-04-16 21:24:23.973 [DEBUG] [ssage.ApplicationCommandMessageClass] - NODE 2: Application Command Request (INITIALIZING:FAILED_CHECK)
2017-04-16 21:24:23.974 [ERROR] [ve.internal.protocol.ZWaveController] - Exception during ZWave thread: Input 2. {}
java.lang.NullPointerException
at org.openhab.binding.zwave.internal.protocol.ZWaveNode.setNodeState(ZWaveNode.java:235)[196:org.openhab.binding.zwave:2.1.0.201704151452]
at org.openhab.binding.zwave.internal.protocol.serialmessage.ApplicationCommandMessageClass.handleRequest(ApplicationCommandMessageClass.java:46)[196:org.openhab.binding.zwave:2.1.0.201704151452]
at org.openhab.binding.zwave.internal.protocol.ZWaveController.handleIncomingRequestMessage(ZWaveController.java:248)[196:org.openhab.binding.zwave:2.1.0.201704151452]
at org.openhab.binding.zwave.internal.protocol.ZWaveController.handleIncomingMessage(ZWaveController.java:214)[196:org.openhab.binding.zwave:2.1.0.201704151452]
at org.openhab.binding.zwave.internal.protocol.ZWaveController.access$7(ZWaveController.java:208)[196:org.openhab.binding.zwave:2.1.0.201704151452]
at org.openhab.binding.zwave.internal.protocol.ZWaveController$ZWaveInputThread.run(ZWaveController.java:1324)[196:org.openhab.binding.zwave:2.1.0.201704151452]

SWITCH NODE10:

2017-04-16 21:24:41.466 [DEBUG] [ding.zwave.handler.ZWaveThingHandler] - NODE 10: Command received zwave:device:a62f5073:node10:switch_binary --> OFF
2017-04-16 21:24:41.469 [ERROR] [ome.core.thing.internal.ThingManager] - Exception occured while calling handler: java.lang.NullPointerException
java.util.concurrent.ExecutionException: java.lang.NullPointerException
at org.eclipse.smarthome.core.common.SafeMethodCaller.executeDirectly(SafeMethodCaller.java:220)[99:org.eclipse.smarthome.core:0.9.0.201704011656]
at org.eclipse.smarthome.core.common.SafeMethodCaller.callAsynchronous(SafeMethodCaller.java:189)[99:org.eclipse.smarthome.core:0.9.0.201704011656]
at org.eclipse.smarthome.core.common.SafeMethodCaller.call(SafeMethodCaller.java:83)[99:org.eclipse.smarthome.core:0.9.0.201704011656]
at org.eclipse.smarthome.core.common.SafeMethodCaller.call(SafeMethodCaller.java:67)[99:org.eclipse.smarthome.core:0.9.0.201704011656]
at org.eclipse.smarthome.core.thing.internal.ThingManager.receiveCommand(ThingManager.java:358)[106:org.eclipse.smarthome.core.thing:0.9.0.201704011656]
at org.eclipse.smarthome.core.items.events.AbstractItemEventSubscriber.receive(AbstractItemEventSubscriber.java:46)[99:org.eclipse.smarthome.core:0.9.0.201704011656]
at org.eclipse.smarthome.core.internal.events.OSGiEventManager$1.call(OSGiEventManager.java:192)[99:org.eclipse.smarthome.core:0.9.0.201704011656]
at org.eclipse.smarthome.core.internal.events.OSGiEventManager$1.call(OSGiEventManager.java:1)[99:org.eclipse.smarthome.core:0.9.0.201704011656]
at org.eclipse.smarthome.core.common.SafeMethodCaller$CallableWrapper.call(SafeMethodCaller.java:181)[99:org.eclipse.smarthome.core:0.9.0.201704011656]
at java.util.concurrent.FutureTask.run(FutureTask.java:266)[:1.8.0_121]
at java.util.concurrent.ThreadPoolExecutor.runWorker(ThreadPoolExecutor.java:1142)[:1.8.0_121]
at java.util.concurrent.ThreadPoolExecutor$Worker.run(ThreadPoolExecutor.java:617)[:1.8.0_121]
at java.lang.Thread.run(Thread.java:745)[:1.8.0_121]
Caused by: java.lang.NullPointerException
at org.openhab.binding.zwave.internal.protocol.commandclass.ZWaveBinarySwitchCommandClass.setValueMessage(ZWaveBinarySwitchCommandClass.java:144)[196:org.openhab.binding.zwave:2.1.0.201704151452]
at org.openhab.binding.zwave.internal.converter.ZWaveBinarySwitchConverter.receiveCommand(ZWaveBinarySwitchConverter.java:90)[196:org.openhab.binding.zwave:2.1.0.201704151452]
at org.openhab.binding.zwave.handler.ZWaveThingHandler.handleCommand(ZWaveThingHandler.java:911)[196:org.openhab.binding.zwave:2.1.0.201704151452]
at org.eclipse.smarthome.core.thing.internal.ThingManager$4.call(ThingManager.java:361)[106:org.eclipse.smarthome.core.thing:0.9.0.201704011656]
at org.eclipse.smarthome.core.thing.internal.ThingManager$4.call(ThingManager.java:1)[106:org.eclipse.smarthome.core.thing:0.9.0.201704011656]
at org.eclipse.smarthome.core.common.SafeMethodCaller.executeDirectly(SafeMethodCaller.java:218)[99:org.eclipse.smarthome.core:0.9.0.201704011656]
… 12 more

Unfortunately device where this eception occurs are no longer control-able via OH.

openhab_log.zip.xml (129.9 KB)

The xml file is a zip containing the log file

My best

Markus

Hi, exactly the same problem here…

Regards

What version have you upgraded from? What version of the runtime are you using - is it a complete update of absolutely everything?

Same problem here. A downgrade does not help, so I’m stuck with this error.

Upgrade was from the version before this (I do a regular apt-get upgrade).

EDIT: I’ve also uninstalled and installed the Z-Wave binding after upgrade in PaperUI but no help.

Did you just udate the zwave binding or the full runtime? If only the binding, what runtime are you using?

Good question. I installed OpenHAB2 on Debian according to the instructions here http://docs.openhab.org/installation/linux.html and used the snapshot repository.

I do an apt-get upgrade which upgrades the package openhab2. So I have a full updated OpenHab2 I suppose.

# apt-cache policy openhab2
openhab2:
  Installed: 2.1.0~20170416125827-1
  Candidate: 2.1.0~20170416125827-1
  Version table:
 *** 2.1.0~20170416125827-1 0
        500 http://openhab.jfrog.io/openhab/openhab-linuxpkg/ unstable/main armhf Packages
        100 /var/lib/dpkg/status
     2.1.0~20170416114151-1 0
        500 http://openhab.jfrog.io/openhab/openhab-linuxpkg/ unstable/main armhf Packages
     2.1.0~20170331113737-1 0
        500 http://openhab.jfrog.io/openhab/openhab-linuxpkg/ unstable/main armhf Packages

I guess if you’re updating ‘everything’ via apt-get and not just the binding through PaperUI, then it’s probably updating the runtime.

There’s only been one change to zwave in the past few weeks (other than database) and that simply changes loggers from static to non static.

Do you know the exact version you ran previously - or at least the last date you updated?

It was the 20170331 version (last in the list).

Ok, so there’s only 1 change then - and that was to change the loggers from static.

So that means that the problem is with openHAB in general? Just to mention: the binding for my RFXtrx433E still works after the update.

Unless it’s related to database problems. I’ll take a look.

I don’t have a full system configured for the master branch, but it does run ok without any exceptions. One thing I’ve noticed is that the XML files are now badly screwed - probably due to the logger change from static :frowning: . XStream is now writing them out into the XML which is making the files enormous. I’m not sure if this is causing the problem, but it’s the only thing I can see that’s wrong - other than this, it works ok here in the IDE.

I just did an apt-get update & upgrade as well. All my zwave components stopped working except virtual ones.
openhab is printing lots of java exceptions in the karaf logs

I’ve tried a few things in the last hour to try to fix the issue. I reinstalled the zwave binding and restarted the system.
No luck there.
Did a new apt-get update/upgrade. but that didnt change anything either.

Now I’ve turned on DEBUG for zwave to start gathering more logs.

Getting lots of this in the log everytime one of the nods try to communicate.

In the below snippit, I’m trying to turn on a power plug in the kitchen. (node 13) (it doesn’t turn on)

00:14:35.052 [INFO ] [smarthome.event.ItemCommandEvent    ] - Item 'Switch_Uttag_Kok_Lampa' received command ON
00:14:35.056 [DEBUG] [ding.zwave.handler.ZWaveThingHandler] - NODE 13: Command received zwave:device:1593d34c72c:node13:switch_binary --> ON
00:14:35.058 [INFO ] [marthome.event.ItemStateChangedEvent] - Switch_Uttag_Kok_Lampa changed from NULL to ON
00:14:35.059 [ERROR] [ome.core.thing.internal.ThingManager] - Exception occured while calling handler: java.lang.NullPointerException
java.util.concurrent.ExecutionException: java.lang.NullPointerException
        at org.eclipse.smarthome.core.common.SafeMethodCaller.executeDirectly(SafeMethodCaller.java:220)[99:org.eclipse.smarthome.core:0.9.0.201704011656]
        at org.eclipse.smarthome.core.common.SafeMethodCaller.callAsynchronous(SafeMethodCaller.java:189)[99:org.eclipse.smarthome.core:0.9.0.201704011656]
        at org.eclipse.smarthome.core.common.SafeMethodCaller.call(SafeMethodCaller.java:83)[99:org.eclipse.smarthome.core:0.9.0.201704011656]
        at org.eclipse.smarthome.core.common.SafeMethodCaller.call(SafeMethodCaller.java:67)[99:org.eclipse.smarthome.core:0.9.0.201704011656]
        at org.eclipse.smarthome.core.thing.internal.ThingManager.receiveCommand(ThingManager.java:358)[106:org.eclipse.smarthome.core.thing:0.9.0.201704011656]
        at org.eclipse.smarthome.core.items.events.AbstractItemEventSubscriber.receive(AbstractItemEventSubscriber.java:46)[99:org.eclipse.smarthome.core:0.9.0.201704011656]
        at org.eclipse.smarthome.core.internal.events.OSGiEventManager$1.call(OSGiEventManager.java:192)[99:org.eclipse.smarthome.core:0.9.0.201704011656]
        at org.eclipse.smarthome.core.internal.events.OSGiEventManager$1.call(OSGiEventManager.java:1)[99:org.eclipse.smarthome.core:0.9.0.201704011656]
        at org.eclipse.smarthome.core.common.SafeMethodCaller$CallableWrapper.call(SafeMethodCaller.java:181)[99:org.eclipse.smarthome.core:0.9.0.201704011656]
        at java.util.concurrent.FutureTask.run(FutureTask.java:266)[:1.8.0_111]
        at java.util.concurrent.ThreadPoolExecutor.runWorker(ThreadPoolExecutor.java:1142)[:1.8.0_111]
        at java.util.concurrent.ThreadPoolExecutor$Worker.run(ThreadPoolExecutor.java:617)[:1.8.0_111]
        at java.lang.Thread.run(Thread.java:745)[:1.8.0_111]
Caused by: java.lang.NullPointerException
        at org.openhab.binding.zwave.internal.protocol.commandclass.ZWaveBinarySwitchCommandClass.setValueMessage(ZWaveBinarySwitchCommandClass.java:144)[216:org.openhab.binding.zwave:2.1.0.201704151452]
        at org.openhab.binding.zwave.internal.converter.ZWaveBinarySwitchConverter.receiveCommand(ZWaveBinarySwitchConverter.java:90)[216:org.openhab.binding.zwave:2.1.0.201704151452]
        at org.openhab.binding.zwave.handler.ZWaveThingHandler.handleCommand(ZWaveThingHandler.java:911)[216:org.openhab.binding.zwave:2.1.0.201704151452]
        at org.eclipse.smarthome.core.thing.internal.ThingManager$4.call(ThingManager.java:361)[106:org.eclipse.smarthome.core.thing:0.9.0.201704011656]
        at org.eclipse.smarthome.core.thing.internal.ThingManager$4.call(ThingManager.java:1)[106:org.eclipse.smarthome.core.thing:0.9.0.201704011656]
        at org.eclipse.smarthome.core.common.SafeMethodCaller.executeDirectly(SafeMethodCaller.java:218)[99:org.eclipse.smarthome.core:0.9.0.201704011656]
        ... 12 more

I had an idea for a workaround but it’s not working:

  • delete Z-Wave Controller
  • delete all Z-Wave devices in PaperUI (a bit tedious when having lots of devices)
  • create Z-Wave Controller again
  • add all devices again
  • change channel (for use new controller id) in .items file (I used a one-liner to do a bulk change: sed -i -e ‘s/oldID/newID/’ *.items)

The exceptions are gone, but all my devices are in PING or WAIT state and don’t react to commands.

I’ve just made a change to avoid writing the loggers into the XML - I’m not really sure it will make a difference since the system works ok here either way.

I think I read that someone downgraded to the older version, but that didn’t help - is this correct (anyone)?

Try deleting the XML files and see if that helps.

I downgraded with no luck. Which XMLs should I delete (the nodes.xml in /var/lib/openhab2/zwave directory?).

I’ve got to say that’s strange - so the version of the binding you downgraded to used to work previously?

Yes (although it sounds from your last that you might have done this already now?).

I’ve just kicked off another build of the addons - just in case something bad happened with the current one.

I downgraded openhab via apt-get. How can I downgrade the binding?

So you downgraded the whole system to the one that used to work, and it didn’t work still?

Probably not very easily. First we’d need to find a binding and I’m not sure it’s cached past the last 2 versions.