openhab / org.openhab.binding.zwave

openHAB binding for Z-Wave
Eclipse Public License 2.0
170 stars 202 forks source link

NPE when excluding Aeotec Multisensor 6 #419

Closed jvolkman closed 6 years ago

jvolkman commented 7 years ago

This exception is logged when I remove my Aeotec Multisensor 6 from my ZWave network using the exclusion procedure.

07:56:35.335 [ERROR] [ome.core.thing.internal.ThingManager] - Exception occured while disposing handler of thing 'zwave:device:d3d50f00:node19': java.lang.NullPointerException
java.util.concurrent.ExecutionException: java.lang.NullPointerException
    at java.util.concurrent.FutureTask.report(FutureTask.java:122)[:1.8.0_121]
    at java.util.concurrent.FutureTask.get(FutureTask.java:206)[:1.8.0_121]
    at org.eclipse.smarthome.core.common.SafeMethodCaller.callAsynchronous(SafeMethodCaller.java:188)[98:org.eclipse.smarthome.core:0.9.0.b4]
    at org.eclipse.smarthome.core.common.SafeMethodCaller.call(SafeMethodCaller.java:81)[98:org.eclipse.smarthome.core:0.9.0.b4]
    at org.eclipse.smarthome.core.common.SafeMethodCaller.call(SafeMethodCaller.java:65)[98:org.eclipse.smarthome.core:0.9.0.b4]
    at org.eclipse.smarthome.core.thing.internal.ThingManager.doDisposeHandler(ThingManager.java:802)[105:org.eclipse.smarthome.core.thing:0.9.0.b4]
    at org.eclipse.smarthome.core.thing.internal.ThingManager.disposeHandler(ThingManager.java:792)[105:org.eclipse.smarthome.core.thing:0.9.0.b4]
    at org.eclipse.smarthome.core.thing.internal.ThingManager.thingRemoved(ThingManager.java:480)[105:org.eclipse.smarthome.core.thing:0.9.0.b4]
    at org.eclipse.smarthome.core.thing.internal.ThingRegistryImpl.notifyTrackers(ThingRegistryImpl.java:224)[105:org.eclipse.smarthome.core.thing:0.9.0.b4]
    at org.eclipse.smarthome.core.thing.internal.ThingRegistryImpl.notifyListenersAboutRemovedElement(ThingRegistryImpl.java:143)[105:org.eclipse.smarthome.core.thing:0.9.0.b4]
    at org.eclipse.smarthome.core.thing.internal.ThingRegistryImpl.notifyListenersAboutRemovedElement(ThingRegistryImpl.java:1)[105:org.eclipse.smarthome.core.thing:0.9.0.b4]
    at org.eclipse.smarthome.core.common.registry.AbstractRegistry.removed(AbstractRegistry.java:147)[98:org.eclipse.smarthome.core:0.9.0.b4]
    at org.eclipse.smarthome.core.common.registry.AbstractProvider.notifyListeners(AbstractProvider.java:54)[98:org.eclipse.smarthome.core:0.9.0.b4]
    at org.eclipse.smarthome.core.common.registry.AbstractProvider.notifyListeners(AbstractProvider.java:70)[98:org.eclipse.smarthome.core:0.9.0.b4]
    at org.eclipse.smarthome.core.common.registry.AbstractProvider.notifyListenersAboutRemovedElement(AbstractProvider.java:78)[98:org.eclipse.smarthome.core:0.9.0.b4]
    at org.eclipse.smarthome.core.common.registry.AbstractManagedProvider.remove(AbstractManagedProvider.java:114)[98:org.eclipse.smarthome.core:0.9.0.b4]
    at org.eclipse.smarthome.core.common.registry.AbstractRegistry.remove(AbstractRegistry.java:196)[98:org.eclipse.smarthome.core:0.9.0.b4]
    at org.eclipse.smarthome.core.thing.internal.ThingRegistryImpl.forceRemove(ThingRegistryImpl.java:110)[105:org.eclipse.smarthome.core.thing:0.9.0.b4]
    at org.eclipse.smarthome.core.thing.internal.ThingManager$16$1.run(ThingManager.java:939)[105:org.eclipse.smarthome.core.thing:0.9.0.b4]
    at org.eclipse.smarthome.core.thing.internal.ThingManager$16$1.run(ThingManager.java:1)[105:org.eclipse.smarthome.core.thing:0.9.0.b4]
    at java.security.AccessController.doPrivileged(Native Method)[:1.8.0_121]
    at org.eclipse.smarthome.core.thing.internal.ThingManager$16.run(ThingManager.java:936)[105:org.eclipse.smarthome.core.thing:0.9.0.b4]
    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.initialization.ZWaveNodeSerializer.SerializeNode(ZWaveNodeSerializer.java:97)[212:org.openhab.binding.zwave:2.1.0.201703190837]
    at org.openhab.binding.zwave.handler.ZWaveThingHandler.dispose(ZWaveThingHandler.java:479)[212:org.openhab.binding.zwave:2.1.0.201703190837]
    at org.eclipse.smarthome.core.thing.internal.ThingManager$11.call(ThingManager.java:805)[105:org.eclipse.smarthome.core.thing:0.9.0.b4]
    at org.eclipse.smarthome.core.thing.internal.ThingManager$11.call(ThingManager.java:1)[105:org.eclipse.smarthome.core.thing:0.9.0.b4]
    at org.eclipse.smarthome.core.common.SafeMethodCaller$CallableWrapper.call(SafeMethodCaller.java:179)[98:org.eclipse.smarthome.core:0.9.0.b4]
    at java.util.concurrent.FutureTask.run(FutureTask.java:266)[:1.8.0_121]
    ... 3 more

I did have debug logging on at the time. I'll try to grab some contextual logs when I get back to my OpenHAB device.

cdjackson commented 7 years ago

Thanks - the logs would be useful when you get them...

jvolkman commented 7 years ago

I've attached two files.

The first is exclusion of node 15. At this point the device had been part of the network for a while. The second is exclusion of node 19, after I re-added it. Notably, there's a message in the second log that says "Device excluded during initialisation!", presumably due to not letting the init phase finish. The stack trace seems the same in both cases, though.

A fallout of this, I think, was that a bunch of entries were left in the ItemChannelLink jsondb that I had to clean up manually. I was getting messages such as:

2017-03-21 08:12:11.286 [WARN ] [ome.core.thing.internal.ThingManager] - Cannot delegate update '0' for item 'FrontSensor_BatteryLevel' to handler for channel 'zwave:device:d3d50f00:node15:battery-level', because no thing with the UID 'zwave:device:d3d50f00:node15' could be found.

exception1.txt exception2.txt

cdjackson commented 6 years ago

This is fixed in the development version. It's caused by the node being removed, then the handler being disposed but the handler still tried to serialise the node. null check is now in place to avoid this.