reyem / openhab2-addons

Add-ons for openHAB 2.x
Eclipse Public License 2.0
3 stars 1 forks source link

NullPointerException after restarting robonect binding #4

Closed DanielMalmgren closed 7 years ago

DanielMalmgren commented 7 years ago

I don't know if this is a one-time problem after upgrading, but I'd better file it here just in case. When I first installed the robonect I was on OH 2.0 and everything worked fine. Then I upgraded to 2.1 and after that the items connected to my robonect-thing didn't update at all. No errors in the log, just nothing happened. I restarted the binding and got the following error in the log:

21:14:58.962 [INFO ] [me.event.ThingStatusInfoChangedEvent] - 'robonect:mower:b9eb2b40' changed from ONLINE to UNINITIALIZED 21:14:58.964 [ERROR] [ome.core.thing.internal.ThingManager] - Exception occurred while disposing handler of thing 'robonect:mower:b9eb2b40': java.lang.NullPointerException java.util.concurrent.ExecutionException: java.lang.NullPointerException at java.util.concurrent.FutureTask.report(FutureTask.java:122)[:1.8.0_131] at java.util.concurrent.FutureTask.get(FutureTask.java:206)[:1.8.0_131] at org.eclipse.smarthome.core.common.SafeMethodCaller.callAsynchronous(SafeMethodCaller.java:194) at org.eclipse.smarthome.core.common.SafeMethodCaller.call(SafeMethodCaller.java:83) at org.eclipse.smarthome.core.common.SafeMethodCaller.call(SafeMethodCaller.java:67) at org.eclipse.smarthome.core.thing.internal.ThingManager.doDisposeHandler(ThingManager.java:831) at org.eclipse.smarthome.core.thing.internal.ThingManager.disposeHandler(ThingManager.java:819) at org.eclipse.smarthome.core.thing.internal.ThingManager.unregisterAndDisposeHandler(ThingManager.java:865) at org.eclipse.smarthome.core.thing.internal.ThingManager.removeThingHandlerFactory(ThingManager.java:1044) at sun.reflect.NativeMethodAccessorImpl.invoke0(Native Method)[:1.8.0_131] at sun.reflect.NativeMethodAccessorImpl.invoke(NativeMethodAccessorImpl.java:62)[:1.8.0_131] at sun.reflect.DelegatingMethodAccessorImpl.invoke(DelegatingMethodAccessorImpl.java:43)[:1.8.0_131] at java.lang.reflect.Method.invoke(Method.java:498)[:1.8.0_131] at org.apache.felix.scr.impl.inject.BaseMethod.invokeMethod(BaseMethod.java:224)[34:org.apache.felix.scr:2.0.6] at org.apache.felix.scr.impl.inject.BaseMethod.access$500(BaseMethod.java:39)[34:org.apache.felix.scr:2.0.6] at org.apache.felix.scr.impl.inject.BaseMethod$Resolved.invoke(BaseMethod.java:617)[34:org.apache.felix.scr:2.0.6] at org.apache.felix.scr.impl.inject.BaseMethod.invoke(BaseMethod.java:501)[34:org.apache.felix.scr:2.0.6] at org.apache.felix.scr.impl.inject.BindMethod.invoke(BindMethod.java:655)[34:org.apache.felix.scr:2.0.6] at org.apache.felix.scr.impl.manager.DependencyManager.invokeUnbindMethod(DependencyManager.java:1837)[34:org.apache.felix.scr:2.0.6] at org.apache.felix.scr.impl.manager.SingleComponentManager.invokeUnbindMethod(SingleComponentManager.java:394)[34:org.apache.felix.scr:2.0.6] at org.apache.felix.scr.impl.manager.DependencyManager$MultipleDynamicCustomizer.removedService(DependencyManager.java:375)[34:org.apache.felix.scr:2.0.6] at org.apache.felix.scr.impl.manager.DependencyManager$MultipleDynamicCustomizer.removedService(DependencyManager.java:291)[34:org.apache.felix.scr:2.0.6] at org.apache.felix.scr.impl.manager.ServiceTracker$Tracked.customizerRemoved(ServiceTracker.java:1241)[34:org.apache.felix.scr:2.0.6] at org.apache.felix.scr.impl.manager.ServiceTracker$Tracked.customizerRemoved(ServiceTracker.java:1136)[34:org.apache.felix.scr:2.0.6] at org.apache.felix.scr.impl.manager.ServiceTracker$AbstractTracked.untrack(ServiceTracker.java:996)[34:org.apache.felix.scr:2.0.6] at org.apache.felix.scr.impl.manager.ServiceTracker$Tracked.serviceChanged(ServiceTracker.java:1175)[34:org.apache.felix.scr:2.0.6] at org.apache.felix.scr.impl.BundleComponentActivator$ListenerInfo.serviceChanged(BundleComponentActivator.java:127)[34:org.apache.felix.scr:2.0.6] at org.eclipse.osgi.internal.serviceregistry.FilteredServiceListener.serviceChanged(FilteredServiceListener.java:109)[org.eclipse.osgi-3.10.101.v20150820-1432.jar:] at org.eclipse.osgi.internal.framework.BundleContextImpl.dispatchEvent(BundleContextImpl.java:914)[org.eclipse.osgi-3.10.101.v20150820-1432.jar:] at org.eclipse.osgi.framework.eventmgr.EventManager.dispatchEvent(EventManager.java:230)[org.eclipse.osgi-3.10.101.v20150820-1432.jar:] at org.eclipse.osgi.framework.eventmgr.ListenerQueue.dispatchEventSynchronous(ListenerQueue.java:148)[org.eclipse.osgi-3.10.101.v20150820-1432.jar:] at org.eclipse.osgi.internal.serviceregistry.ServiceRegistry.publishServiceEventPrivileged(ServiceRegistry.java:862)[org.eclipse.osgi-3.10.101.v20150820-1432.jar:] at org.eclipse.osgi.internal.serviceregistry.ServiceRegistry.publishServiceEvent(ServiceRegistry.java:801)[org.eclipse.osgi-3.10.101.v20150820-1432.jar:] at org.eclipse.osgi.internal.serviceregistry.ServiceRegistrationImpl.unregister(ServiceRegistrationImpl.java:222)[org.eclipse.osgi-3.10.101.v20150820-1432.jar:] at org.apache.felix.scr.impl.manager.AbstractComponentManager$3.unregister(AbstractComponentManager.java:908)[34:org.apache.felix.scr:2.0.6] at org.apache.felix.scr.impl.manager.AbstractComponentManager$3.unregister(AbstractComponentManager.java:873)[34:org.apache.felix.scr:2.0.6] at org.apache.felix.scr.impl.manager.RegistrationManager.changeRegistration(RegistrationManager.java:139)[34:org.apache.felix.scr:2.0.6] at org.apache.felix.scr.impl.manager.AbstractComponentManager.unregisterService(AbstractComponentManager.java:950)[34:org.apache.felix.scr:2.0.6] at org.apache.felix.scr.impl.manager.AbstractComponentManager.doDeactivate(AbstractComponentManager.java:805)[34:org.apache.felix.scr:2.0.6] at org.apache.felix.scr.impl.manager.AbstractComponentManager.deactivateInternal(AbstractComponentManager.java:787)[34:org.apache.felix.scr:2.0.6] at org.apache.felix.scr.impl.manager.AbstractComponentManager.dispose(AbstractComponentManager.java:579)[34:org.apache.felix.scr:2.0.6] at org.apache.felix.scr.impl.manager.ConfigurableComponentHolder.disposeComponents(ConfigurableComponentHolder.java:706)[34:org.apache.felix.scr:2.0.6] at org.apache.felix.scr.impl.BundleComponentActivator.dispose(BundleComponentActivator.java:523)[34:org.apache.felix.scr:2.0.6] at org.apache.felix.scr.impl.Activator.disposeComponents(Activator.java:452)[34:org.apache.felix.scr:2.0.6] at org.apache.felix.scr.impl.Activator.access$300(Activator.java:54)[34:org.apache.felix.scr:2.0.6] at org.apache.felix.scr.impl.Activator$ScrExtension.destroy(Activator.java:306)[34:org.apache.felix.scr:2.0.6] at org.apache.felix.utils.extender.AbstractExtender$2.run(AbstractExtender.java:290)[34:org.apache.felix.scr:2.0.6] at java.util.concurrent.Executors$RunnableAdapter.call(Executors.java:511)[:1.8.0_131] at java.util.concurrent.FutureTask.run(FutureTask.java:266)[:1.8.0_131] at org.apache.felix.utils.extender.AbstractExtender.destroyExtension(AbstractExtender.java:312)[34:org.apache.felix.scr:2.0.6] at org.apache.felix.utils.extender.AbstractExtender.bundleChanged(AbstractExtender.java:186)[34:org.apache.felix.scr:2.0.6] at org.eclipse.osgi.internal.framework.BundleContextImpl.dispatchEvent(BundleContextImpl.java:902)[org.eclipse.osgi-3.10.101.v20150820-1432.jar:] at org.eclipse.osgi.framework.eventmgr.EventManager.dispatchEvent(EventManager.java:230)[org.eclipse.osgi-3.10.101.v20150820-1432.jar:] at org.eclipse.osgi.framework.eventmgr.ListenerQueue.dispatchEventSynchronous(ListenerQueue.java:148)[org.eclipse.osgi-3.10.101.v20150820-1432.jar:] at org.eclipse.osgi.internal.framework.EquinoxEventPublisher.publishBundleEventPrivileged(EquinoxEventPublisher.java:165)[org.eclipse.osgi-3.10.101.v20150820-1432.jar:] at org.eclipse.osgi.internal.framework.EquinoxEventPublisher.publishBundleEvent(EquinoxEventPublisher.java:75)[org.eclipse.osgi-3.10.101.v20150820-1432.jar:] at org.eclipse.osgi.internal.framework.EquinoxEventPublisher.publishBundleEvent(EquinoxEventPublisher.java:67)[org.eclipse.osgi-3.10.101.v20150820-1432.jar:] at org.eclipse.osgi.internal.framework.EquinoxContainerAdaptor.publishModuleEvent(EquinoxContainerAdaptor.java:102)[org.eclipse.osgi-3.10.101.v20150820-1432.jar:] at org.eclipse.osgi.container.Module.publishEvent(Module.java:466)[org.eclipse.osgi-3.10.101.v20150820-1432.jar:] at org.eclipse.osgi.container.Module.doStop(Module.java:624)[org.eclipse.osgi-3.10.101.v20150820-1432.jar:] at org.eclipse.osgi.container.Module.stop(Module.java:488)[org.eclipse.osgi-3.10.101.v20150820-1432.jar:] at org.eclipse.osgi.internal.framework.EquinoxBundle.stop(EquinoxBundle.java:419)[org.eclipse.osgi-3.10.101.v20150820-1432.jar:] at org.apache.karaf.bundle.command.Restart.doExecute(Restart.java:44)[40:org.apache.karaf.bundle.core:4.0.8] at org.apache.karaf.bundle.command.BundlesCommand.execute(BundlesCommand.java:54)[40:org.apache.karaf.bundle.core:4.0.8] at org.apache.karaf.shell.impl.action.command.ActionCommand.execute(ActionCommand.java:83)[57:org.apache.karaf.shell.core:4.0.8] at org.apache.karaf.shell.impl.console.osgi.secured.SecuredCommand.execute(SecuredCommand.java:67)[57:org.apache.karaf.shell.core:4.0.8] at org.apache.karaf.shell.impl.console.osgi.secured.SecuredCommand.execute(SecuredCommand.java:87)[57:org.apache.karaf.shell.core:4.0.8] at org.apache.felix.gogo.runtime.Closure.executeCmd(Closure.java:480)[57:org.apache.karaf.shell.core:4.0.8] at org.apache.felix.gogo.runtime.Closure.executeStatement(Closure.java:406)[57:org.apache.karaf.shell.core:4.0.8] at org.apache.felix.gogo.runtime.Pipe.run(Pipe.java:108)[57:org.apache.karaf.shell.core:4.0.8] at org.apache.felix.gogo.runtime.Closure.execute(Closure.java:182)[57:org.apache.karaf.shell.core:4.0.8] at org.apache.felix.gogo.runtime.Closure.execute(Closure.java:119)[57:org.apache.karaf.shell.core:4.0.8] at org.apache.felix.gogo.runtime.CommandSessionImpl.execute(CommandSessionImpl.java:94)[57:org.apache.karaf.shell.core:4.0.8] at org.apache.karaf.shell.impl.console.ConsoleSessionImpl.run(ConsoleSessionImpl.java:274)[57:org.apache.karaf.shell.core:4.0.8] at java.lang.Thread.run(Thread.java:748)[:1.8.0_131] Caused by: java.lang.NullPointerException at org.openhab.binding.robonect.handler.RobonectHandler.dispose(RobonectHandler.java:377)[10:org.openhab.binding.robonect:2.1.0.201706272144] at org.eclipse.smarthome.core.thing.internal.ThingManager$11.call(ThingManager.java:836)[108:org.eclipse.smarthome.core.thing:0.9.0.b5] at org.eclipse.smarthome.core.thing.internal.ThingManager$11.call(ThingManager.java:1)[108:org.eclipse.smarthome.core.thing:0.9.0.b5] at org.eclipse.smarthome.core.common.SafeMethodCaller$CallableWrapper.call(SafeMethodCaller.java:181)[101:org.eclipse.smarthome.core:0.9.0.b5] at java.util.concurrent.FutureTask.run(FutureTask.java:266)[:1.8.0_131] at java.util.concurrent.ThreadPoolExecutor.runWorker(ThreadPoolExecutor.java:1142)[:1.8.0_131] at java.util.concurrent.ThreadPoolExecutor$Worker.run(ThreadPoolExecutor.java:617)[:1.8.0_131] ... 1 more 21:14:59.052 [INFO ] [me.event.ThingStatusInfoChangedEvent] - 'robonect:mower:b9eb2b40' changed from UNINITIALIZED to UNINITIALIZED (HANDLER_MISSING_ERROR) 21:14:59.227 [INFO ] [me.event.ThingStatusInfoChangedEvent] - 'robonect:mower:b9eb2b40' changed from UNINITIALIZED (HANDLER_MISSING_ERROR) to INITIALIZING 21:14:59.848 [WARN ] [jdbc.internal.JdbcPersistenceService] - JDBC::store: ignore Item 'RosenlundAutomower_Error_ErrorMessage' because it is UnDefType 21:14:59.850 [INFO ] [marthome.event.ItemStateChangedEvent] - RosenlundAutomower_Error_ErrorMessage changed from NULL to UNDEF 21:14:59.858 [INFO ] [marthome.event.ItemStateChangedEvent] - RosenlundAutomower_MowerStatus_MowerStatus changed from 2.00 to 4

After this everything seems to work again so it's maybe not a problem?

Oh, and a note about the decimals above... My persistence saves everything with two decimals and I have restoreOnStartup set, so the 2.00 just means that the value was 2 before the restart and upgrade of OH.

reyem commented 7 years ago

Thank you for reporting this. Although I think it is not critical it is still a bug in the code which I would not have found without your report. This will be fixed with the next larger commit.

DanielMalmgren commented 7 years ago

I've upgraded to the last snapshot. Not really sure how to test this though... I restarted the binding and got no error. Does that mean we're happy? :-)

reyem commented 7 years ago

well, I would say so :-) The issue can actually not appear anymore. This was a missing null check.