ZW4002 erroring out with latest build

Mike_Bagdanoff · January 10, 2017, 6:11am

I updated my OH2 to use the new Distro method and it looks like something may have gone wrong or there is a bug in the latest ZWave build. My Fan module, which was working previously reverted to “UNINITIALIZED - HANDLER_INITIALIZING_ERROR” and when I try to turn it on/off from a Rule or HabPanel I get this in the logs:

22:09:49.584 [INFO ] [ome.core.thing.internal.ThingManager] - Not delegating command 'ON' for item 'SwitchMasterFan_Dimmer' to handler for channel 'zwave:device:db95ddc3:node66:switch_dimmer', because handler is not initialized (thing must be in status UNKNOWN, ONLINE or OFFLINE).
22:09:49.589 [INFO ] [ome.core.thing.internal.ThingManager] - Not delegating update 'ON' for item 'SwitchMasterFan_Dimmer' to handler for channel 'zwave:device:db95ddc3:node66:switch_dimmer', because handler is not initialized (thing must be in status UNKNOWN, ONLINE or OFFLINE).

Removing and re-adding the Thing gives this:

22:03:43.190 [DEBUG] [ding.zwave.handler.ZWaveThingHandler] - Initializing ZWave thing handler.
22:03:43.190 [INFO ] [me.event.ThingStatusInfoChangedEvent] - 'zwave:device:db95ddc3:node66' changed from UNINITIALIZED (HANDLER_MISSING_ERROR) to INITIALIZING
22:03:43.193 [DEBUG] [ding.zwave.handler.ZWaveThingHandler] - NODE 66: Controller status changed to ONLINE.
22:03:43.194 [DEBUG] [ding.zwave.handler.ZWaveThingHandler] - NODE 66: Controller is ONLINE. Starting device initialisation.
22:03:43.196 [INFO ] [me.event.ThingStatusInfoChangedEvent] - 'zwave:device:db95ddc3:node66' changed from INITIALIZING to OFFLINE (BRIDGE_OFFLINE): Controller is offline
22:03:43.199 [DEBUG] [ding.zwave.handler.ZWaveThingHandler] - NODE 66: Updating node properties.
22:03:43.200 [DEBUG] [ding.zwave.handler.ZWaveThingHandler] - NODE 66: Updating node properties. MAN=99
22:03:43.200 [INFO ] [me.event.ThingStatusInfoChangedEvent] - 'zwave:device:db95ddc3:node66' changed from OFFLINE (BRIDGE_OFFLINE): Controller is offline to ONLINE
22:03:43.201 [DEBUG] [ding.zwave.handler.ZWaveThingHandler] - NODE 66: Updating node properties. MAN=99. SET. Was 99
22:03:43.202 [DEBUG] [ding.zwave.handler.ZWaveThingHandler] - NODE 66: Config about to update 2 parameters...
22:03:43.202 [DEBUG] [ding.zwave.handler.ZWaveThingHandler] - NODE 66: Processing config_3_1
22:03:43.203 [DEBUG] [ding.zwave.handler.ZWaveThingHandler] - NODE 66: Processing config_3_1 len=3
22:03:43.203 [DEBUG] [ding.zwave.handler.ZWaveThingHandler] - NODE 66: Processing config_3_1 - id = '3'
22:03:43.204 [DEBUG] [ding.zwave.handler.ZWaveThingHandler] - NODE 66: Processing config_3_1 - size = '1'
22:03:43.204 [DEBUG] [ding.zwave.handler.ZWaveThingHandler] - NODE 66: Sub-parameter config_3_1 is 00000000
22:03:43.205 [DEBUG] [ding.zwave.handler.ZWaveThingHandler] - NODE 66: Pre-processing  00000000>>FFFFFFFF
22:03:43.206 [DEBUG] [ding.zwave.handler.ZWaveThingHandler] - NODE 66: Post-processing 00000000>>FFFFFFFF
22:03:43.208 [INFO ] [smarthome.event.ThingUpdatedEvent   ] - Thing 'zwave:device:db95ddc3:node66' has been updated.
22:03:43.209 [DEBUG] [ding.zwave.handler.ZWaveThingHandler] - NODE 66: Sub-parameter setting config_3_1 is 00000000 [0]
22:03:43.210 [DEBUG] [ding.zwave.handler.ZWaveThingHandler] - NODE 66: Processing config_4_1
22:03:43.210 [DEBUG] [ding.zwave.handler.ZWaveThingHandler] - NODE 66: Processing config_4_1 len=3
22:03:43.211 [DEBUG] [ding.zwave.handler.ZWaveThingHandler] - NODE 66: Processing config_4_1 - id = '4'
22:03:43.211 [DEBUG] [ding.zwave.handler.ZWaveThingHandler] - NODE 66: Config about to update 2 parameters...
22:03:43.211 [DEBUG] [ding.zwave.handler.ZWaveThingHandler] - NODE 66: Processing config_3_1
22:03:43.212 [DEBUG] [ding.zwave.handler.ZWaveThingHandler] - NODE 66: Processing config_3_1 len=3
22:03:43.212 [DEBUG] [ding.zwave.handler.ZWaveThingHandler] - NODE 66: Processing config_3_1 - id = '3'
22:03:43.212 [DEBUG] [ding.zwave.handler.ZWaveThingHandler] - NODE 66: Processing config_4_1
22:03:43.213 [DEBUG] [ding.zwave.handler.ZWaveThingHandler] - NODE 66: Processing config_4_1 len=3
22:03:43.213 [DEBUG] [ding.zwave.handler.ZWaveThingHandler] - NODE 66: Processing config_4_1 - id = '4'
22:03:43.213 [DEBUG] [ding.zwave.handler.ZWaveThingHandler] - NODE 66: Processing config_4_1 - size = '1'
22:03:43.214 [DEBUG] [ding.zwave.handler.ZWaveThingHandler] - NODE 66: Sub-parameter config_4_1 is 00000000
22:03:43.214 [DEBUG] [ding.zwave.handler.ZWaveThingHandler] - NODE 66: Pre-processing  00000000>>FFFFFFFF
22:03:43.215 [DEBUG] [ding.zwave.handler.ZWaveThingHandler] - NODE 66: Post-processing 00000000>>FFFFFFFF
22:03:43.215 [DEBUG] [ding.zwave.handler.ZWaveThingHandler] - NODE 66: Sub-parameter setting config_4_1 is 00000000 [0]
22:03:43.223 [INFO ] [me.event.ThingStatusInfoChangedEvent] - 'zwave:device:db95ddc3:node66' changed from ONLINE to UNINITIALIZED (HANDLER_INITIALIZING_ERROR)
22:03:43.217 [ERROR] [ome.core.thing.internal.ThingManager] - Exception occured while initializing handler of thing 'zwave:device:db95ddc3:node66': java.lang.NullPointerException
java.util.concurrent.ExecutionException: java.lang.NullPointerException
        at java.util.concurrent.FutureTask.report(FutureTask.java:122)[:1.8.0_111]
        at java.util.concurrent.FutureTask.get(FutureTask.java:206)[:1.8.0_111]
        at org.eclipse.smarthome.core.common.SafeMethodCaller.callAsynchronous(SafeMethodCaller.java:188)[99:org.eclipse.smarthome.core:0.9.0.201701090931]
        at org.eclipse.smarthome.core.common.SafeMethodCaller.call(SafeMethodCaller.java:81)[99:org.eclipse.smarthome.core:0.9.0.201701090931]
        at org.eclipse.smarthome.core.common.SafeMethodCaller.call(SafeMethodCaller.java:65)[99:org.eclipse.smarthome.core:0.9.0.201701090931]
        at org.eclipse.smarthome.core.thing.internal.ThingManager$9.run(ThingManager.java:710)[106:org.eclipse.smarthome.core.thing:0.9.0.201701090931]
        at java.util.concurrent.Executors$RunnableAdapter.call(Executors.java:511)[:1.8.0_111]
        at java.util.concurrent.FutureTask.run(FutureTask.java:266)[:1.8.0_111]
        at java.util.concurrent.ScheduledThreadPoolExecutor$ScheduledFutureTask.access$201(ScheduledThreadPoolExecutor.java:180)[:1.8.0_111]
        at java.util.concurrent.ScheduledThreadPoolExecutor$ScheduledFutureTask.run(ScheduledThreadPoolExecutor.java:293)[: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.handler.ZWaveThingHandler.updateNodeProperties(ZWaveThingHandler.java:1346)[204:org.openhab.binding.zwave:2.0.0.201701091302]
        at org.openhab.binding.zwave.handler.ZWaveThingHandler.bridgeStatusChanged(ZWaveThingHandler.java:454)[204:org.openhab.binding.zwave:2.0.0.201701091302]
        at org.openhab.binding.zwave.handler.ZWaveThingHandler.initialize(ZWaveThingHandler.java:147)[204:org.openhab.binding.zwave:2.0.0.201701091302]
        at org.eclipse.smarthome.core.thing.internal.ThingManager$9$1.call(ThingManager.java:713)[106:org.eclipse.smarthome.core.thing:0.9.0.201701090931]
        at org.eclipse.smarthome.core.thing.internal.ThingManager$9$1.call(ThingManager.java:1)[106:org.eclipse.smarthome.core.thing:0.9.0.201701090931]
        at org.eclipse.smarthome.core.common.SafeMethodCaller$CallableWrapper.call(SafeMethodCaller.java:179)[99:org.eclipse.smarthome.core:0.9.0.201701090931]
        at java.util.concurrent.FutureTask.run(FutureTask.java:266)[:1.8.0_111]
        ... 3 more

Has anyone else seen anything like this?

Mike_Bagdanoff · January 11, 2017, 4:47am

@chris, any thoughts on what this might be? Device problem? Binding issue? Do any of the responses in the log look weird ?

I’ve thought about removing a similar device Thing (this is the only fan controller that I have) but they all work and I’m concerned that they also won’t come back right.

chris · January 11, 2017, 1:10pm

I will try and take a look as soon as I get a chance - I’m on holiday in India at the moment… if I get time I’ll have a look tonight.

Mike_Bagdanoff · January 11, 2017, 3:44pm

ahh, enjoy.

chris · January 11, 2017, 4:41pm

I’ve had a quick look at the code - I don’t think anything has changed in this area for a while…

Can you post the node66.xml file? I’d be interested to see what’s in it. You could try deleting this file to see if it helps in the short term - I probably need to add some protection here…

Mike_Bagdanoff · January 11, 2017, 6:51pm

Chris,

Bah, I thought I had tried that, but for due diligence I did it again and now it came back fine. I must not have restarted OH2 after deleting it last time and I made sure to do that this time. Also I didn’t search for it this time, once OH2 started it appeared in the inbox rather than me clicking on the + icon to enter the inclusion mode so that may have had something to do with it. I may fiddle with this and try to reproduce the failure, but it may have just been a piece of upgrade kruft.

I’ve attached the file for future reference, now stop working and enjoy your vacation.

node66.xml (4.7 KB)

Thanks,

Mike