OH 2.2.0 Snapshots 1025-1028 / ZWave NPE

Dim · August 29, 2017, 6:09am

It maybe something wrong with my system… just checking if anyone else is seeing the same…
I didn’t have time to perform my own troubleshooting, so this could be a false alert…

Using: openHAB 2.2.0 Snapshot build #1025 with the “mainstream” Z-Wave binding 2.2.0.201708281802 on a Debian Jessie with Oracle’s 1.8.0_144-b01 JVM)

My openhab.log logs an NPE ERROR:

29-Aug-2017 09:05:51.819 [INFO ] [g.openhab.binding.zwave.handler.ZWaveSerialHandler] - Connecting to serial port '/dev/ttyACM0'
29-Aug-2017 09:05:51.953 [INFO ] [g.openhab.binding.zwave.handler.ZWaveSerialHandler] - Serial port is initialized
29-Aug-2017 09:05:51.969 [INFO ] [al.protocol.commandclass.ZWaveSecurityCommandClass] - Update networkKey
29-Aug-2017 09:05:51.993 [INFO ] [ab.binding.zwave.internal.protocol.ZWaveController] - Starting ZWave controller
29-Aug-2017 09:05:51.993 [INFO ] [ab.binding.zwave.internal.protocol.ZWaveController] - ZWave timeout is set to 5000ms. Soft reset is false.
29-Aug-2017 09:05:55.181 [INFO ] [col.serialmessage.SerialApiGetInitDataMessageClass] - NODE 1: Node found
29-Aug-2017 09:05:55.182 [INFO ] [col.serialmessage.SerialApiGetInitDataMessageClass] - NODE 2: Node found
29-Aug-2017 09:05:55.182 [INFO ] [col.serialmessage.SerialApiGetInitDataMessageClass] - NODE 3: Node found
29-Aug-2017 09:05:55.182 [INFO ] [col.serialmessage.SerialApiGetInitDataMessageClass] - NODE 4: Node found
29-Aug-2017 09:05:55.182 [INFO ] [col.serialmessage.SerialApiGetInitDataMessageClass] - NODE 6: Node found
29-Aug-2017 09:05:55.182 [INFO ] [col.serialmessage.SerialApiGetInitDataMessageClass] - NODE 8: Node found
29-Aug-2017 09:05:55.182 [INFO ] [col.serialmessage.SerialApiGetInitDataMessageClass] - NODE 9: Node found
29-Aug-2017 09:05:55.183 [INFO ] [col.serialmessage.SerialApiGetInitDataMessageClass] - ZWave Controller using Controller API
29-Aug-2017 09:05:55.183 [INFO ] [col.serialmessage.SerialApiGetInitDataMessageClass] - ZWave Controller is Primary Controller
29-Aug-2017 09:05:55.183 [INFO ] [col.serialmessage.SerialApiGetInitDataMessageClass] - ------------Number of Nodes Found Registered to ZWave Controller------------
29-Aug-2017 09:05:55.183 [INFO ] [col.serialmessage.SerialApiGetInitDataMessageClass] - # Nodes = 7
29-Aug-2017 09:05:55.183 [INFO ] [col.serialmessage.SerialApiGetInitDataMessageClass] - ----------------------------------------------------------------------------
29-Aug-2017 09:06:00.745 [ERROR] [ab.binding.zwave.internal.protocol.ZWaveController] - Exception during ZWave thread: Input 2. {}
java.lang.NullPointerException: null
	at org.eclipse.smarthome.core.thing.i18n.ThingTypeI18nLocalizationService.createLocalizedThingType(ThingTypeI18nLocalizationService.java:67) [108:org.eclipse.smarthome.core.thing:0.9.0.201708281632]
	at org.eclipse.smarthome.core.thing.xml.internal.XmlThingTypeProvider.localize(XmlThingTypeProvider.java:128) [109:org.eclipse.smarthome.core.thing.xml:0.9.0.201708281632]
	at org.eclipse.smarthome.core.thing.xml.internal.XmlThingTypeProvider.localize(XmlThingTypeProvider.java:1) [109:org.eclipse.smarthome.core.thing.xml:0.9.0.201708281632]
	at org.eclipse.smarthome.config.xml.AbstractXmlBasedProvider.acquireLocalizedObject(AbstractXmlBasedProvider.java:211) [100:org.eclipse.smarthome.config.xml:0.9.0.201708281632]
	at org.eclipse.smarthome.config.xml.AbstractXmlBasedProvider.getAll(AbstractXmlBasedProvider.java:165) [100:org.eclipse.smarthome.config.xml:0.9.0.201708281632]
	at org.eclipse.smarthome.core.thing.xml.internal.XmlThingTypeProvider.getThingTypes(XmlThingTypeProvider.java:82) [109:org.eclipse.smarthome.core.thing.xml:0.9.0.201708281632]
	at org.eclipse.smarthome.core.thing.type.ThingTypeRegistry.getThingTypes(ThingTypeRegistry.java:48) [108:org.eclipse.smarthome.core.thing:0.9.0.201708281632]
	at org.eclipse.smarthome.core.thing.type.ThingTypeRegistry.getThingTypes(ThingTypeRegistry.java:59) [108:org.eclipse.smarthome.core.thing:0.9.0.201708281632]
	at org.openhab.binding.zwave.internal.ZWaveConfigProvider.initialiseZWaveThings(ZWaveConfigProvider.java:310) [203:org.openhab.binding.zwave:2.2.0.201708281802]
	at org.openhab.binding.zwave.internal.ZWaveConfigProvider.getProductIndex(ZWaveConfigProvider.java:355) [203:org.openhab.binding.zwave:2.2.0.201708281802]
	at org.openhab.binding.zwave.internal.ZWaveConfigProvider.getThingType(ZWaveConfigProvider.java:382) [203:org.openhab.binding.zwave:2.2.0.201708281802]
	at org.openhab.binding.zwave.internal.protocol.initialization.ZWaveNodeInitStageAdvancer.advanceNodeStage(ZWaveNodeInitStageAdvancer.java:968) [203:org.openhab.binding.zwave:2.2.0.201708281802]
	at org.openhab.binding.zwave.internal.protocol.initialization.ZWaveNodeInitStageAdvancer.handleNodeQueue(ZWaveNodeInitStageAdvancer.java:230) [203:org.openhab.binding.zwave:2.2.0.201708281802]
	at org.openhab.binding.zwave.internal.protocol.initialization.ZWaveNodeInitStageAdvancer.ZWaveIncomingEvent(ZWaveNodeInitStageAdvancer.java:1306) [203:org.openhab.binding.zwave:2.2.0.201708281802]
	at org.openhab.binding.zwave.internal.protocol.ZWaveController.notifyEventListeners(ZWaveController.java:567) [203:org.openhab.binding.zwave:2.2.0.201708281802]
	at org.openhab.binding.zwave.internal.protocol.ZWaveController.handleIncomingRequestMessage(ZWaveController.java:250) [203:org.openhab.binding.zwave:2.2.0.201708281802]
	at org.openhab.binding.zwave.internal.protocol.ZWaveController.handleIncomingMessage(ZWaveController.java:214) [203:org.openhab.binding.zwave:2.2.0.201708281802]
	at org.openhab.binding.zwave.internal.protocol.ZWaveController.access$7(ZWaveController.java:208) [203:org.openhab.binding.zwave:2.2.0.201708281802]
	at org.openhab.binding.zwave.internal.protocol.ZWaveController$ZWaveInputThread.run(ZWaveController.java:1324) [203:org.openhab.binding.zwave:2.2.0.201708281802]
29-Aug-2017 09:07:26.373 [ERROR] [ab.binding.zwave.internal.protocol.ZWaveController] - Exception during ZWave thread: Input 2. {}
java.lang.NullPointerException: null
	at org.eclipse.smarthome.core.thing.i18n.ThingTypeI18nLocalizationService.createLocalizedThingType(ThingTypeI18nLocalizationService.java:67) [108:org.eclipse.smarthome.core.thing:0.9.0.201708281632]
	at org.eclipse.smarthome.core.thing.xml.internal.XmlThingTypeProvider.localize(XmlThingTypeProvider.java:128) [109:org.eclipse.smarthome.core.thing.xml:0.9.0.201708281632]
	at org.eclipse.smarthome.core.thing.xml.internal.XmlThingTypeProvider.localize(XmlThingTypeProvider.java:1) [109:org.eclipse.smarthome.core.thing.xml:0.9.0.201708281632]
	at org.eclipse.smarthome.config.xml.AbstractXmlBasedProvider.acquireLocalizedObject(AbstractXmlBasedProvider.java:211) [100:org.eclipse.smarthome.config.xml:0.9.0.201708281632]
	at org.eclipse.smarthome.config.xml.AbstractXmlBasedProvider.getAll(AbstractXmlBasedProvider.java:165) [100:org.eclipse.smarthome.config.xml:0.9.0.201708281632]
	at org.eclipse.smarthome.core.thing.xml.internal.XmlThingTypeProvider.getThingTypes(XmlThingTypeProvider.java:82) [109:org.eclipse.smarthome.core.thing.xml:0.9.0.201708281632]
	at org.eclipse.smarthome.core.thing.type.ThingTypeRegistry.getThingTypes(ThingTypeRegistry.java:48) [108:org.eclipse.smarthome.core.thing:0.9.0.201708281632]
	at org.eclipse.smarthome.core.thing.type.ThingTypeRegistry.getThingTypes(ThingTypeRegistry.java:59) [108:org.eclipse.smarthome.core.thing:0.9.0.201708281632]
	at org.openhab.binding.zwave.internal.ZWaveConfigProvider.initialiseZWaveThings(ZWaveConfigProvider.java:310) [203:org.openhab.binding.zwave:2.2.0.201708281802]
	at org.openhab.binding.zwave.internal.ZWaveConfigProvider.getProductIndex(ZWaveConfigProvider.java:355) [203:org.openhab.binding.zwave:2.2.0.201708281802]
	at org.openhab.binding.zwave.internal.ZWaveConfigProvider.getThingType(ZWaveConfigProvider.java:382) [203:org.openhab.binding.zwave:2.2.0.201708281802]
	at org.openhab.binding.zwave.internal.protocol.initialization.ZWaveNodeInitStageAdvancer.advanceNodeStage(ZWaveNodeInitStageAdvancer.java:968) [203:org.openhab.binding.zwave:2.2.0.201708281802]
	at org.openhab.binding.zwave.internal.protocol.initialization.ZWaveNodeInitStageAdvancer.handleNodeQueue(ZWaveNodeInitStageAdvancer.java:230) [203:org.openhab.binding.zwave:2.2.0.201708281802]
	at org.openhab.binding.zwave.internal.protocol.initialization.ZWaveNodeInitStageAdvancer.ZWaveIncomingEvent(ZWaveNodeInitStageAdvancer.java:1306) [203:org.openhab.binding.zwave:2.2.0.201708281802]
	at org.openhab.binding.zwave.internal.protocol.ZWaveController.notifyEventListeners(ZWaveController.java:567) [203:org.openhab.binding.zwave:2.2.0.201708281802]
	at org.openhab.binding.zwave.internal.protocol.ZWaveController.handleIncomingRequestMessage(ZWaveController.java:250) [203:org.openhab.binding.zwave:2.2.0.201708281802]
	at org.openhab.binding.zwave.internal.protocol.ZWaveController.handleIncomingMessage(ZWaveController.java:214) [203:org.openhab.binding.zwave:2.2.0.201708281802]
	at org.openhab.binding.zwave.internal.protocol.ZWaveController.access$7(ZWaveController.java:208) [203:org.openhab.binding.zwave:2.2.0.201708281802]
	at org.openhab.binding.zwave.internal.protocol.ZWaveController$ZWaveInputThread.run(ZWaveController.java:1324) [203:org.openhab.binding.zwave:2.2.0.201708281802]

tagging @chris also (I hope it’s not a false alert )

sihui · August 29, 2017, 6:13am

Upgraded this morning to #1025, saw the same.
The “usual” tmp and cache deletion (although done during installation of #1025) and restart solved it.

Dim · August 29, 2017, 6:16am

just tried that step… still getting the same NPE… testing more now

sihui · August 29, 2017, 6:18am

At the moment I too have some weird things with #1025 going on:
-500 internal server error within PaperUI
-No things shown in HABmin

Will try to solve during the day (I hope) …

Dim · August 29, 2017, 6:21am

I am also putting 1025 to the test
seeing the same strange stuff also here (500s in PaperUI, no things in HABmin) and the NPE with the Z-Wave binding is still there. Also, the Control tab in PaperUI is empty and it spits the same 500 error.
Snapsho(o)ting is nice

From PaperUI, using Chrome’s developer console:

Failed to load resource: the server responded with a status of 500 (Internal Server Error)  :8080/rest/thing-types

when browsing to http://OH2_IP:8080/rest/thing-types, I get:

{"error":{"http-code":500,"exception":{"class":"java.lang.NullPointerException"}}}

sihui · August 29, 2017, 6:42am

Same here.

I upgraded because I wanted my earliest/latest from astro back: did not work either

I have the development version in place, no NPE anymore, works great so far.

But all of the other stuff makes me mad

Edit: not one single error in openhab.log, though …

chris · August 29, 2017, 8:17am

@kai has there been a breaking change here somewhere? I see in ESH that there have been some changes to the DS declarations in ThingTypeI18nLocalizationService. Since this isn’t used directly by bindings I guess it’s a framework issue?

Kai · August 29, 2017, 8:40am

No, there hasn’t been any (deliberate) breaking change. The last change in that code was this - so maybe this has introduced an issue.
The only NPE I can imagine in there is if it fails to resolve a channel type - but how could that happen? Do you have a chance to step through the code with the debugger?

chris · August 29, 2017, 9:01am

Thanks @kai - that might explain it as I think there may have been a PR merged with an undefined channel in a thing. I guess it might be useful to protect this case?

I’ll take a better look later anyway, but that probably explains it - thanks.

Kai · August 29, 2017, 9:04am

I have entered https://github.com/eclipse/smarthome/issues/4152 to harden the code for such cases.

sihui · August 29, 2017, 3:26pm

Did a clean install again, still

no things in HABmin
500 server error in PaperUI

#1025 is not usable for me, reverting back …

Dim · August 29, 2017, 3:47pm

I uped to 1026… same issues appear
I will also fall back to 1024 or earlier

mhilbush · August 29, 2017, 6:54pm

I can confirm the same behavior in 1026.

Lots of these on the console:

Exception in thread "Timer-26" java.lang.NullPointerException
	at org.eclipse.smarthome.core.thing.i18n.ThingTypeI18nLocalizationService.createLocalizedThingType(ThingTypeI18nLocalizationService.java:67)
	at org.eclipse.smarthome.core.thing.xml.internal.XmlThingTypeProvider.localize(XmlThingTypeProvider.java:128)
	at org.eclipse.smarthome.core.thing.xml.internal.XmlThingTypeProvider.localize(XmlThingTypeProvider.java:1)
	at org.eclipse.smarthome.config.xml.AbstractXmlBasedProvider.acquireLocalizedObject(AbstractXmlBasedProvider.java:211)
	at org.eclipse.smarthome.config.xml.AbstractXmlBasedProvider.getAll(AbstractXmlBasedProvider.java:165)
	at org.eclipse.smarthome.core.thing.xml.internal.XmlThingTypeProvider.getThingTypes(XmlThingTypeProvider.java:82)
	at org.eclipse.smarthome.core.thing.type.ThingTypeRegistry.getThingTypes(ThingTypeRegistry.java:48)
	at org.eclipse.smarthome.core.thing.type.ThingTypeRegistry.getThingTypes(ThingTypeRegistry.java:59)
	at org.openhab.binding.zwave.internal.ZWaveConfigProvider.initialiseZWaveThings(ZWaveConfigProvider.java:310)
	at org.openhab.binding.zwave.internal.ZWaveConfigProvider.getProductIndex(ZWaveConfigProvider.java:355)
	at org.openhab.binding.zwave.internal.ZWaveConfigProvider.getThingType(ZWaveConfigProvider.java:382)
	at org.openhab.binding.zwave.internal.protocol.initialization.ZWaveNodeInitStageAdvancer.advanceNodeStage(ZWaveNodeInitStageAdvancer.java:968)
	at org.openhab.binding.zwave.internal.protocol.initialization.ZWaveNodeInitStageAdvancer$IdleTimerTask.run(ZWaveNodeInitStageAdvancer.java:1395)
	at java.util.TimerThread.mainLoop(Timer.java:555)
	at java.util.TimerThread.run(Timer.java:505)

And lots of 500 Internal Server Errors in Paper UI.

mstormi · August 29, 2017, 7:42pm

FWIW, I’m running #1025 with the development zwave binding, and I have not seen any such error to date (knock on wood).

Dim · August 29, 2017, 7:43pm

yeah, it seems that the refactored/development/security version of the Z-Wave binding works fine under S1025

the “standard/mainstream” one is throwing the NPE
but it seems that the issue is not with the Z-Wave binding itself but with the ThingTypeI18nLocalizationService

chris · August 29, 2017, 7:49pm

I’ve just made a PR that will hopefully fix this - I’ll merge tonight so tomorrows build should fix it I hope.

sihui · August 29, 2017, 8:06pm

Disregard: worked fine this evening, needed some extra time I guess …

sihui · August 29, 2017, 8:07pm

Is there any chance that

this will fix that problem too?

chris · August 29, 2017, 8:09pm

Does “no things shown” mean just ZWave or other bindings as well?

sihui · August 29, 2017, 8:10pm

Completely empty: