MySensors Ethernet Gateway goes to OFFLINE state

[pentti12]

OK, I will try to debug. It will take some time to done. I'll be back later on.

[TimO]

@pentti12 This is a bug in the binding. Please restart OH2 (or just the binding as @jogant suggested) after discovery of a new device till I was able to fix the issue . After the restart it should work.

[pentti12]

Hi

I switched from win7 laptop to pine64 in order to continue searching problem.
What I did:

I started Karaf Console and restarted mysensors binding --> no help
I restarted Arduino UNO Ethernet Gateway --> no help
I restarted Arduino UNO Node 9 (which has temperature and humidity sensor) --> no help

Here is the listing of the DEBUG:

10:15:32.075 [ERROR] [ome.core.thing.internal.ThingManager] - Exception occured while disposing handler of thing 'mysensors:humidity:a9d5757b': java.lang.NullPointerException
java.util.concurrent.ExecutionException: java.lang.NullPointerException
at java.util.concurrent.FutureTask.report(FutureTask.java:122)[:1.8.0_101]
at java.util.concurrent.FutureTask.get(FutureTask.java:206)[:1.8.0_101]
at org.eclipse.smarthome.core.common.SafeMethodCaller.callAsynchronous(SafeMethodCaller.java:186)
at org.eclipse.smarthome.core.common.SafeMethodCaller.call(SafeMethodCaller.java:79)
at org.eclipse.smarthome.core.common.SafeMethodCaller.call(SafeMethodCaller.java:63)
at org.eclipse.smarthome.core.thing.internal.ThingManager.disposeHandler(ThingManager.java:857)
at org.eclipse.smarthome.core.thing.internal.ThingManager.handlerRemoved(ThingManager.java:311)
at org.eclipse.smarthome.core.thing.internal.ThingManager$ThingHandlerTracker.removedService(ThingManager.java:138)
at org.eclipse.smarthome.core.thing.internal.ThingManager$ThingHandlerTracker.removedService(ThingManager.java:1)
at org.osgi.util.tracker.ServiceTracker$Tracked.customizerRemoved(ServiceTracker.java:967)[org.osgi.core-6.0.0.jar:]
at org.osgi.util.tracker.ServiceTracker$Tracked.customizerRemoved(ServiceTracker.java:870)[org.osgi.core-6.0.0.jar:]
at org.osgi.util.tracker.AbstractTracked.untrack(AbstractTracked.java:341)[org.osgi.core-6.0.0.jar:]
at org.osgi.util.tracker.ServiceTracker$Tracked.serviceChanged(ServiceTracker.java:909)[org.osgi.core-6.0.0.jar:]
at org.eclipse.osgi.internal.serviceregistry.FilteredServiceListener.serviceChanged(FilteredServiceListener.java:109)[org.eclipse.osgi-3.10.2.v20150203-1939.jar:]
at org.eclipse.osgi.internal.framework.BundleContextImpl.dispatchEvent(BundleContextImpl.java:914)[org.eclipse.osgi-3.10.2.v20150203-1939.jar:]
at org.eclipse.osgi.framework.eventmgr.EventManager.dispatchEvent(EventManager.java:230)[org.eclipse.osgi-3.10.2.v20150203-1939.jar:]
at org.eclipse.osgi.framework.eventmgr.ListenerQueue.dispatchEventSynchronous(ListenerQueue.java:148)[org.eclipse.osgi-3.10.2.v20150203-1939.jar:]
at org.eclipse.osgi.internal.serviceregistry.ServiceRegistry.publishServiceEventPrivileged(ServiceRegistry.java:862)[org.eclipse.osgi-3.10.2.v20150203-1939.jar:]
at org.eclipse.osgi.internal.serviceregistry.ServiceRegistry.publishServiceEvent(ServiceRegistry.java:801)[org.eclipse.osgi-3.10.2.v20150203-1939.jar:]
at org.eclipse.osgi.internal.serviceregistry.ServiceRegistrationImpl.unregister(ServiceRegistrationImpl.java:222)[org.eclipse.osgi-3.10.2.v20150203-1939.jar:]
at org.eclipse.smarthome.core.thing.binding.BaseThingHandlerFactory.unregisterHandler(BaseThingHandlerFactory.java:125)
at org.eclipse.smarthome.core.thing.binding.BaseThingHandlerFactory.deactivate(BaseThingHandlerFactory.java:79)
at sun.reflect.NativeMethodAccessorImpl.invoke0(Native Method)[:1.8.0_101]
at sun.reflect.NativeMethodAccessorImpl.invoke(NativeMethodAccessorImpl.java:62)[:1.8.0_101]
at sun.reflect.DelegatingMethodAccessorImpl.invoke(DelegatingMethodAccessorImpl.java:43)[:1.8.0_101]
at java.lang.reflect.Method.invoke(Method.java:498)[:1.8.0_101]
at org.apache.felix.scr.impl.helper.BaseMethod.invokeMethod(BaseMethod.java:222)[33:org.apache.felix.scr:2.0.2]
at org.apache.felix.scr.impl.helper.BaseMethod.access$500(BaseMethod.java:37)[33:org.apache.felix.scr:2.0.2]
at org.apache.felix.scr.impl.helper.BaseMethod$Resolved.invoke(BaseMethod.java:615)[33:org.apache.felix.scr:2.0.2]
at org.apache.felix.scr.impl.helper.BaseMethod.invoke(BaseMethod.java:499)[33:org.apache.felix.scr:2.0.2]
at org.apache.felix.scr.impl.helper.ActivateMethod.invoke(ActivateMethod.java:295)[33:org.apache.felix.scr:2.0.2]
at org.apache.felix.scr.impl.manager.SingleComponentManager.disposeImplementationObject(SingleComponentManager.java:342)[33:org.apache.felix.scr:2.0.2]
at org.apache.felix.scr.impl.manager.SingleComponentManager.deleteComponent(SingleComponentManager.java:157)[33:org.apache.felix.scr:2.0.2]
at org.apache.felix.scr.impl.manager.AbstractComponentManager.doDeactivate(AbstractComponentManager.java:783)[33:org.apache.felix.scr:2.0.2]
at org.apache.felix.scr.impl.manager.AbstractComponentManager.deactivateInternal(AbstractComponentManager.java:757)[33:org.apache.felix.scr:2.0.2]
at org.apache.felix.scr.impl.manager.AbstractComponentManager.dispose(AbstractComponentManager.java:550)[33:org.apache.felix.scr:2.0.2]
at org.apache.felix.scr.impl.config.ConfigurableComponentHolder.disposeComponents(ConfigurableComponentHolder.java:725)[33:org.apache.felix.scr:2.0.2]
at org.apache.felix.scr.impl.BundleComponentActivator.dispose(BundleComponentActivator.java:530)[33:org.apache.felix.scr:2.0.2]
at org.apache.felix.scr.impl.Activator.disposeComponents(Activator.java:414)[33:org.apache.felix.scr:2.0.2]
at org.apache.felix.scr.impl.Activator.access$300(Activator.java:53)[33:org.apache.felix.scr:2.0.2]
at org.apache.felix.scr.impl.Activator$ScrExtension.destroy(Activator.java:273)[33:org.apache.felix.scr:2.0.2]
at org.apache.felix.utils.extender.AbstractExtender$2.run(AbstractExtender.java:290)[33:org.apache.felix.scr:2.0.2]
at java.util.concurrent.Executors$RunnableAdapter.call(Executors.java:511)[:1.8.0_101]
at java.util.concurrent.FutureTask.run(FutureTask.java:266)[:1.8.0_101]
at org.apache.felix.utils.extender.AbstractExtender.destroyExtension(AbstractExtender.java:312)[33:org.apache.felix.scr:2.0.2]
at org.apache.felix.utils.extender.AbstractExtender.bundleChanged(AbstractExtender.java:186)[33:org.apache.felix.scr:2.0.2]
at org.eclipse.osgi.internal.framework.BundleContextImpl.dispatchEvent(BundleContextImpl.java:902)[org.eclipse.osgi-3.10.2.v20150203-1939.jar:]
at org.eclipse.osgi.framework.eventmgr.EventManager.dispatchEvent(EventManager.java:230)[org.eclipse.osgi-3.10.2.v20150203-1939.jar:]
at org.eclipse.osgi.framework.eventmgr.ListenerQueue.dispatchEventSynchronous(ListenerQueue.java:148)[org.eclipse.osgi-3.10.2.v20150203-1939.jar:]
at org.eclipse.osgi.internal.framework.EquinoxEventPublisher.publishBundleEventPrivileged(EquinoxEventPublisher.java:165)[org.eclipse.osgi-3.10.2.v20150203-1939.jar:]
at org.eclipse.osgi.internal.framework.EquinoxEventPublisher.publishBundleEvent(EquinoxEventPublisher.java:75)[org.eclipse.osgi-3.10.2.v20150203-1939.jar:]
at org.eclipse.osgi.internal.framework.EquinoxEventPublisher.publishBundleEvent(EquinoxEventPublisher.java:67)[org.eclipse.osgi-3.10.2.v20150203-1939.jar:]
at org.eclipse.osgi.internal.framework.EquinoxContainerAdaptor.publishModuleEvent(EquinoxContainerAdaptor.java:102)[org.eclipse.osgi-3.10.2.v20150203-1939.jar:]
at org.eclipse.osgi.container.Module.publishEvent(Module.java:466)[org.eclipse.osgi-3.10.2.v20150203-1939.jar:]
at org.eclipse.osgi.container.Module.doStop(Module.java:624)[org.eclipse.osgi-3.10.2.v20150203-1939.jar:]
at org.eclipse.osgi.container.Module.stop(Module.java:488)[org.eclipse.osgi-3.10.2.v20150203-1939.jar:]
at org.eclipse.osgi.internal.framework.EquinoxBundle.stop(EquinoxBundle.java:420)[org.eclipse.osgi-3.10.2.v20150203-1939.jar:]
at org.apache.karaf.bundle.command.Restart.doExecute(Restart.java:44)[39:org.apache.karaf.bundle.core:4.0.4]
at org.apache.karaf.bundle.command.BundlesCommand.execute(BundlesCommand.java:54)[39:org.apache.karaf.bundle.core:4.0.4]
at org.apache.karaf.shell.impl.action.command.ActionCommand.execute(ActionCommand.java:83)[54:org.apache.karaf.shell.core:4.0.4]
at org.apache.karaf.shell.impl.console.osgi.secured.SecuredCommand.execute(SecuredCommand.java:67)[54:org.apache.karaf.shell.core:4.0.4]
at org.apache.karaf.shell.impl.console.osgi.secured.SecuredCommand.execute(SecuredCommand.java:87)[54:org.apache.karaf.shell.core:4.0.4]
at org.apache.felix.gogo.runtime.Closure.executeCmd(Closure.java:480)[54:org.apache.karaf.shell.core:4.0.4]
at org.apache.felix.gogo.runtime.Closure.executeStatement(Closure.java:406)[54:org.apache.karaf.shell.core:4.0.4]
at org.apache.felix.gogo.runtime.Pipe.run(Pipe.java:108)[54:org.apache.karaf.shell.core:4.0.4]
at org.apache.felix.gogo.runtime.Closure.execute(Closure.java:182)[54:org.apache.karaf.shell.core:4.0.4]
at org.apache.felix.gogo.runtime.Closure.execute(Closure.java:119)[54:org.apache.karaf.shell.core:4.0.4]
at org.apache.felix.gogo.runtime.CommandSessionImpl.execute(CommandSessionImpl.java:94)[54:org.apache.karaf.shell.core:4.0.4]
at org.apache.karaf.shell.impl.console.ConsoleSessionImpl.run(ConsoleSessionImpl.java:270)[54:org.apache.karaf.shell.core:4.0.4]
at java.lang.Thread.run(Thread.java:745)[:1.8.0_101]
Caused by: java.lang.NullPointerException
at org.openhab.binding.mysensors.handler.MySensorsHandler.getBridgeHandler(MySensorsHandler.java:207)[201:org.openhab.binding.mysensors:2.0.0.201601251249]
at org.openhab.binding.mysensors.handler.MySensorsHandler.dispose(MySensorsHandler.java:67)[201:org.openhab.binding.mysensors:2.0.0.201601251249]
at org.eclipse.smarthome.core.thing.internal.ThingManager$12.call(ThingManager.java:860)[103:org.eclipse.smarthome.core.thing:0.9.0.201611102032]
at org.eclipse.smarthome.core.thing.internal.ThingManager$12.call(ThingManager.java:1)[103:org.eclipse.smarthome.core.thing:0.9.0.201611102032]
at org.eclipse.smarthome.core.common.SafeMethodCaller$CallableWrapper.call(SafeMethodCaller.java:177)[96:org.eclipse.smarthome.core:0.9.0.201611102032]
at java.util.concurrent.FutureTask.run(FutureTask.java:266)[:1.8.0_101]
at java.util.concurrent.ThreadPoolExecutor.runWorker(ThreadPoolExecutor.java:1142)[:1.8.0_101]
at java.util.concurrent.ThreadPoolExecutor$Worker.run(ThreadPoolExecutor.java:617)[:1.8.0_101]
... 1 more
10:15:32.165 [INFO ] [me.event.ThingStatusInfoChangedEvent] - 'mysensors:temperature:9d001ab8' changed from ONLINE to UNINITIALIZED (HANDLER_MISSING_ERROR)
10:15:32.167 [ERROR] [ome.core.thing.internal.ThingManager] - Exception occured while disposing handler of thing 'mysensors:temperature:9d001ab8': java.lang.NullPointerException
java.util.concurrent.ExecutionException: java.lang.NullPointerException
at java.util.concurrent.FutureTask.report(FutureTask.java:122)[:1.8.0_101]
at java.util.concurrent.FutureTask.get(FutureTask.java:206)[:1.8.0_101]
at org.eclipse.smarthome.core.common.SafeMethodCaller.callAsynchronous(SafeMethodCaller.java:186)
at org.eclipse.smarthome.core.common.SafeMethodCaller.call(SafeMethodCaller.java:79)
at org.eclipse.smarthome.core.common.SafeMethodCaller.call(SafeMethodCaller.java:63)
at org.eclipse.smarthome.core.thing.internal.ThingManager.disposeHandler(ThingManager.java:857)
at org.eclipse.smarthome.core.thing.internal.ThingManager.handlerRemoved(ThingManager.java:311)
at org.eclipse.smarthome.core.thing.internal.ThingManager$ThingHandlerTracker.removedService(ThingManager.java:138)
at org.eclipse.smarthome.core.thing.internal.ThingManager$ThingHandlerTracker.removedService(ThingManager.java:1)
at org.osgi.util.tracker.ServiceTracker$Tracked.customizerRemoved(ServiceTracker.java:967)[org.osgi.core-6.0.0.jar:]
at org.osgi.util.tracker.ServiceTracker$Tracked.customizerRemoved(ServiceTracker.java:870)[org.osgi.core-6.0.0.jar:]
at org.osgi.util.tracker.AbstractTracked.untrack(AbstractTracked.java:341)[org.osgi.core-6.0.0.jar:]
at org.osgi.util.tracker.ServiceTracker$Tracked.serviceChanged(ServiceTracker.java:909)[org.osgi.core-6.0.0.jar:]
at org.eclipse.osgi.internal.serviceregistry.FilteredServiceListener.serviceChanged(FilteredServiceListener.java:109)[org.eclipse.osgi-3.10.2.v20150203-1939.jar:]
at org.eclipse.osgi.internal.framework.BundleContextImpl.dispatchEvent(BundleContextImpl.java:914)[org.eclipse.osgi-3.10.2.v20150203-1939.jar:]
at org.eclipse.osgi.framework.eventmgr.EventManager.dispatchEvent(EventManager.java:230)[org.eclipse.osgi-3.10.2.v20150203-1939.jar:]
at org.eclipse.osgi.framework.eventmgr.ListenerQueue.dispatchEventSynchronous(ListenerQueue.java:148)[org.eclipse.osgi-3.10.2.v20150203-1939.jar:]
at org.eclipse.osgi.internal.serviceregistry.ServiceRegistry.publishServiceEventPrivileged(ServiceRegistry.java:862)[org.eclipse.osgi-3.10.2.v20150203-1939.jar:]
at org.eclipse.osgi.internal.serviceregistry.ServiceRegistry.publishServiceEvent(ServiceRegistry.java:801)[org.eclipse.osgi-3.10.2.v20150203-1939.jar:]
at org.eclipse.osgi.internal.serviceregistry.ServiceRegistrationImpl.unregister(ServiceRegistrationImpl.java:222)[org.eclipse.osgi-3.10.2.v20150203-1939.jar:]
at org.eclipse.smarthome.core.thing.binding.BaseThingHandlerFactory.unregisterHandler(BaseThingHandlerFactory.java:125)
at org.eclipse.smarthome.core.thing.binding.BaseThingHandlerFactory.deactivate(BaseThingHandlerFactory.java:79)
at sun.reflect.NativeMethodAccessorImpl.invoke0(Native Method)[:1.8.0_101]
at sun.reflect.NativeMethodAccessorImpl.invoke(NativeMethodAccessorImpl.java:62)[:1.8.0_101]
at sun.reflect.DelegatingMethodAccessorImpl.invoke(DelegatingMethodAccessorImpl.java:43)[:1.8.0_101]
at java.lang.reflect.Method.invoke(Method.java:498)[:1.8.0_101]
at org.apache.felix.scr.impl.helper.BaseMethod.invokeMethod(BaseMethod.java:222)[33:org.apache.felix.scr:2.0.2]
at org.apache.felix.scr.impl.helper.BaseMethod.access$500(BaseMethod.java:37)[33:org.apache.felix.scr:2.0.2]
at org.apache.felix.scr.impl.helper.BaseMethod$Resolved.invoke(BaseMethod.java:615)[33:org.apache.felix.scr:2.0.2]
at org.apache.felix.scr.impl.helper.BaseMethod.invoke(BaseMethod.java:499)[33:org.apache.felix.scr:2.0.2]
at org.apache.felix.scr.impl.helper.ActivateMethod.invoke(ActivateMethod.java:295)[33:org.apache.felix.scr:2.0.2]
at org.apache.felix.scr.impl.manager.SingleComponentManager.disposeImplementationObject(SingleComponentManager.java:342)[33:org.apache.felix.scr:2.0.2]
at org.apache.felix.scr.impl.manager.SingleComponentManager.deleteComponent(SingleComponentManager.java:157)[33:org.apache.felix.scr:2.0.2]
at org.apache.felix.scr.impl.manager.AbstractComponentManager.doDeactivate(AbstractComponentManager.java:783)[33:org.apache.felix.scr:2.0.2]
at org.apache.felix.scr.impl.manager.AbstractComponentManager.deactivateInternal(AbstractComponentManager.java:757)[33:org.apache.felix.scr:2.0.2]
at org.apache.felix.scr.impl.manager.AbstractComponentManager.dispose(AbstractComponentManager.java:550)[33:org.apache.felix.scr:2.0.2]
at org.apache.felix.scr.impl.config.ConfigurableComponentHolder.disposeComponents(ConfigurableComponentHolder.java:725)[33:org.apache.felix.scr:2.0.2]
at org.apache.felix.scr.impl.BundleComponentActivator.dispose(BundleComponentActivator.java:530)[33:org.apache.felix.scr:2.0.2]
at org.apache.felix.scr.impl.Activator.disposeComponents(Activator.java:414)[33:org.apache.felix.scr:2.0.2]
at org.apache.felix.scr.impl.Activator.access$300(Activator.java:53)[33:org.apache.felix.scr:2.0.2]
at org.apache.felix.scr.impl.Activator$ScrExtension.destroy(Activator.java:273)[33:org.apache.felix.scr:2.0.2]
at org.apache.felix.utils.extender.AbstractExtender$2.run(AbstractExtender.java:290)[33:org.apache.felix.scr:2.0.2]
at java.util.concurrent.Executors$RunnableAdapter.call(Executors.java:511)[:1.8.0_101]
at java.util.concurrent.FutureTask.run(FutureTask.java:266)[:1.8.0_101]
at org.apache.felix.utils.extender.AbstractExtender.destroyExtension(AbstractExtender.java:312)[33:org.apache.felix.scr:2.0.2]
at org.apache.felix.utils.extender.AbstractExtender.bundleChanged(AbstractExtender.java:186)[33:org.apache.felix.scr:2.0.2]
at org.eclipse.osgi.internal.framework.BundleContextImpl.dispatchEvent(BundleContextImpl.java:902)[org.eclipse.osgi-3.10.2.v20150203-1939.jar:]
at org.eclipse.osgi.framework.eventmgr.EventManager.dispatchEvent(EventManager.java:230)[org.eclipse.osgi-3.10.2.v20150203-1939.jar:]
at org.eclipse.osgi.framework.eventmgr.ListenerQueue.dispatchEventSynchronous(ListenerQueue.java:148)[org.eclipse.osgi-3.10.2.v20150203-1939.jar:]
at org.eclipse.osgi.internal.framework.EquinoxEventPublisher.publishBundleEventPrivileged(EquinoxEventPublisher.java:165)[org.eclipse.osgi-3.10.2.v20150203-1939.jar:]
at org.eclipse.osgi.internal.framework.EquinoxEventPublisher.publishBundleEvent(EquinoxEventPublisher.java:75)[org.eclipse.osgi-3.10.2.v20150203-1939.jar:]
at org.eclipse.osgi.internal.framework.EquinoxEventPublisher.publishBundleEvent(EquinoxEventPublisher.java:67)[org.eclipse.osgi-3.10.2.v20150203-1939.jar:]
at org.eclipse.osgi.internal.framework.EquinoxContainerAdaptor.publishModuleEvent(EquinoxContainerAdaptor.java:102)[org.eclipse.osgi-3.10.2.v20150203-1939.jar:]
at org.eclipse.osgi.container.Module.publishEvent(Module.java:466)[org.eclipse.osgi-3.10.2.v20150203-1939.jar:]
at org.eclipse.osgi.container.Module.doStop(Module.java:624)[org.eclipse.osgi-3.10.2.v20150203-1939.jar:]
at org.eclipse.osgi.container.Module.stop(Module.java:488)[org.eclipse.osgi-3.10.2.v20150203-1939.jar:]
at org.eclipse.osgi.internal.framework.EquinoxBundle.stop(EquinoxBundle.java:420)[org.eclipse.osgi-3.10.2.v20150203-1939.jar:]
at org.apache.karaf.bundle.command.Restart.doExecute(Restart.java:44)[39:org.apache.karaf.bundle.core:4.0.4]
at org.apache.karaf.bundle.command.BundlesCommand.execute(BundlesCommand.java:54)[39:org.apache.karaf.bundle.core:4.0.4]
at org.apache.karaf.shell.impl.action.command.ActionCommand.execute(ActionCommand.java:83)[54:org.apache.karaf.shell.core:4.0.4]
at org.apache.karaf.shell.impl.console.osgi.secured.SecuredCommand.execute(SecuredCommand.java:67)[54:org.apache.karaf.shell.core:4.0.4]
at org.apache.karaf.shell.impl.console.osgi.secured.SecuredCommand.execute(SecuredCommand.java:87)[54:org.apache.karaf.shell.core:4.0.4]
at org.apache.felix.gogo.runtime.Closure.executeCmd(Closure.java:480)[54:org.apache.karaf.shell.core:4.0.4]
at org.apache.felix.gogo.runtime.Closure.executeStatement(Closure.java:406)[54:org.apache.karaf.shell.core:4.0.4]
at org.apache.felix.gogo.runtime.Pipe.run(Pipe.java:108)[54:org.apache.karaf.shell.core:4.0.4]
at org.apache.felix.gogo.runtime.Closure.execute(Closure.java:182)[54:org.apache.karaf.shell.core:4.0.4]
at org.apache.felix.gogo.runtime.Closure.execute(Closure.java:119)[54:org.apache.karaf.shell.core:4.0.4]
at org.apache.felix.gogo.runtime.CommandSessionImpl.execute(CommandSessionImpl.java:94)[54:org.apache.karaf.shell.core:4.0.4]
at org.apache.karaf.shell.impl.console.ConsoleSessionImpl.run(ConsoleSessionImpl.java:270)[54:org.apache.karaf.shell.core:4.0.4]
at java.lang.Thread.run(Thread.java:745)[:1.8.0_101]
Caused by: java.lang.NullPointerException
at org.openhab.binding.mysensors.handler.MySensorsHandler.dispose(MySensorsHandler.java:67)[201:org.openhab.binding.mysensors:2.0.0.201601251249]
at org.eclipse.smarthome.core.thing.internal.ThingManager$12.call(ThingManager.java:860)[103:org.eclipse.smarthome.core.thing:0.9.0.201611102032]
at org.eclipse.smarthome.core.thing.internal.ThingManager$12.call(ThingManager.java:1)[103:org.eclipse.smarthome.core.thing:0.9.0.201611102032]
at org.eclipse.smarthome.core.common.SafeMethodCaller$CallableWrapper.call(SafeMethodCaller.java:177)[96:org.eclipse.smarthome.core:0.9.0.201611102032]
at java.util.concurrent.FutureTask.run(FutureTask.java:266)[:1.8.0_101]
at java.util.concurrent.ThreadPoolExecutor.runWorker(ThreadPoolExecutor.java:1142)[:1.8.0_101]
at java.util.concurrent.ThreadPoolExecutor$Worker.run(ThreadPoolExecutor.java:617)[:1.8.0_101]
... 1 more
10:15:32.485 [INFO ] [me.event.ThingStatusInfoChangedEvent] - 'mysensors:temperature:9d001ab8' changed from UNINITIALIZED (HANDLER_MISSING_ERROR) to INITIALIZING
10:15:32.488 [INFO ] [me.event.ThingStatusInfoChangedEvent] - 'mysensors:temperature:9d001ab8' changed from INITIALIZING to ONLINE
10:15:32.494 [INFO ] [me.event.ThingStatusInfoChangedEvent] - 'mysensors:bridge-eth:a8641691' changed from UNINITIALIZED (HANDLER_MISSING_ERROR) to INITIALIZING
10:15:32.513 [INFO ] [me.event.ThingStatusInfoChangedEvent] - 'mysensors:bridge-eth:a8641691' changed from INITIALIZING to ONLINE
10:15:32.542 [INFO ] [me.event.ThingStatusInfoChangedEvent] - 'mysensors:humidity:a9d5757b' changed from UNINITIALIZED (HANDLER_MISSING_ERROR) to INITIALIZING
10:15:32.548 [INFO ] [me.event.ThingStatusInfoChangedEvent] - 'mysensors:humidity:a9d5757b' changed from INITIALIZING to ONLINE

So lot of stuff, which are unclear to me.

[jogant]

@pentti12

At least the last 6 lines suggest that the initialization was successful. Seems that before mysensors has not been initialized completely and therefore dispose failed. Dispose is invoked through binding restart I think. So you can ignore theses failures.
Are you now able to link items? Do you see incoming mysensors messages in the cycle you defined in the node?

[pentti12]

If I look at the configuration from HABmin side, I see for example this:

Channels [1 active, 2 total]
Temperature

Linked Items
Temperature

So there is some linked items!

[jogant]

@pentti12

ok, but you have to see mysensor messages in the log file on a regularly basis. At least the default sketch for temperature and humidity sends updates every minute. Maybe your temperature is very constant then you will see updates every hour I think. Try to heat the node and let it cool down again.
And connect your node or the gateway to the serial monitor. There you will see the mysensors activity. You should see OK for status updates and not to much NACK. Then you have a problem with your mysensors network.

good luck ...

[pentti12]

Here is the serial monitor printout from MySensors W5100 Gateway. I think that this listing is OK, but still there is no actual temperature nor humidity values at control screen of OH2 .

0;255;3;0;9;Starting gateway (RNNGA-, 2.0.0)
0;255;3;0;9;TSM:INIT
0;255;3;0;9;TSM:RADIO:OK
0;255;3;0;9;TSM:GW MODE
0;255;3;0;9;TSM:READY
IP: 192.168.1.201
0;255;3;0;9;No registration required
0;255;3;0;9;Init complete, id=0, parent=0, distance=0, registration=1
0;255;3;0;9;TSP:SANCHK:OK
0;255;3;0;9;TSP:MSG:READ 9-9-0 s=11,c=1,t=0,pt=7,l=5,sg=0:22.6
0;255;3;0;9;TSP:SANCHK:OK
0;255;3;0;9;TSP:SANCHK:OK
0;255;3;0;9;TSP:MSG:READ 9-9-0 s=10,c=1,t=1,pt=7,l=5,sg=0:37.9
0;255;3;0;9;TSP:SANCHK:OK
0;255;3;0;9;TSP:MSG:READ 9-9-0 s=11,c=1,t=0,pt=7,l=5,sg=0:22.7
0;255;3;0;9;TSP:SANCHK:OK
0;255;3;0;9;TSP:SANCHK:OK
0;255;3;0;9;TSP:SANCHK:OK
0;255;3;0;9;TSP:MSG:READ 9-9-255 s=255,c=3,t=7,pt=0,l=0,sg=0:
0;255;3;0;9;TSP:MSG:BC
0;255;3;0;9;TSP:MSG:FPAR REQ (sender=9)
0;255;3;0;9;TSP:CHKUPL:OK
0;255;3;0;9;TSP:MSG:GWL OK
0;255;3;0;9;TSP:MSG:SEND 0-0-9-9 s=255,c=3,t=8,pt=1,l=1,sg=0,ft=0,st=ok:0
0;255;3;0;9;TSP:MSG:READ 9-9-255 s=255,c=3,t=7,pt=0,l=0,sg=0:
0;255;3;0;9;TSP:MSG:BC
0;255;3;0;9;TSP:MSG:FPAR REQ (sender=9)
0;255;3;0;9;TSP:CHKUPL:OK
0;255;3;0;9;TSP:MSG:GWL OK
0;255;3;0;9;TSP:MSG:SEND 0-0-9-9 s=255,c=3,t=8,pt=1,l=1,sg=0,ft=0,st=ok:0
0;255;3;0;9;TSP:MSG:READ 9-9-255 s=255,c=3,t=7,pt=0,l=0,sg=0:
0;255;3;0;9;TSP:MSG:BC
0;255;3;0;9;TSP:MSG:FPAR REQ (sender=9)
0;255;3;0;9;TSP:CHKUPL:OK (FLDCTRL)
0;255;3;0;9;TSP:MSG:GWL OK
0;255;3;0;9;TSP:MSG:SEND 0-0-9-9 s=255,c=3,t=8,pt=1,l=1,sg=0,ft=0,st=ok:0
0;255;3;0;9;TSP:MSG:READ 9-9-255 s=255,c=3,t=7,pt=0,l=0,sg=0:
0;255;3;0;9;TSP:MSG:BC
0;255;3;0;9;TSP:MSG:FPAR REQ (sender=9)
0;255;3;0;9;TSP:CHKUPL:OK (FLDCTRL)
0;255;3;0;9;TSP:MSG:GWL OK
0;255;3;0;9;TSP:MSG:SEND 0-0-9-9 s=255,c=3,t=8,pt=1,l=1,sg=0,ft=0,st=ok:0
0;255;3;0;9;TSP:MSG:READ 9-9-255 s=255,c=3,t=7,pt=0,l=0,sg=0:
0;255;3;0;9;TSP:MSG:BC
0;255;3;0;9;TSP:MSG:FPAR REQ (sender=9)
0;255;3;0;9;TSP:CHKUPL:OK (FLDCTRL)
0;255;3;0;9;TSP:MSG:GWL OK
0;255;3;0;9;TSP:MSG:SEND 0-0-9-9 s=255,c=3,t=8,pt=1,l=1,sg=0,ft=0,st=ok:0
0;255;3;0;9;TSP:MSG:READ 9-9-255 s=255,c=3,t=7,pt=0,l=0,sg=0:
0;255;3;0;9;TSP:MSG:BC
0;255;3;0;9;TSP:MSG:FPAR REQ (sender=9)
0;255;3;0;9;TSP:CHKUPL:OK
0;255;3;0;9;TSP:MSG:GWL OK
0;255;3;0;9;TSP:MSG:SEND 0-0-9-9 s=255,c=3,t=8,pt=1,l=1,sg=0,ft=0,st=ok:0
0;255;3;0;9;TSP:SANCHK:OK
0;255;3;0;9;TSP:MSG:READ 9-9-255 s=255,c=3,t=7,pt=0,l=0,sg=0:
0;255;3;0;9;TSP:MSG:BC
0;255;3;0;9;TSP:MSG:FPAR REQ (sender=9)
0;255;3;0;9;TSP:CHKUPL:OK
0;255;3;0;9;TSP:MSG:GWL OK
0;255;3;0;9;TSP:MSG:SEND 0-0-9-9 s=255,c=3,t=8,pt=1,l=1,sg=0,ft=0,st=ok:0
0;255;3;0;9;TSP:SANCHK:OK
0;255;3;0;9;TSP:MSG:READ 9-9-255 s=255,c=3,t=7,pt=0,l=0,sg=0:
0;255;3;0;9;TSP:MSG:BC
0;255;3;0;9;TSP:MSG:FPAR REQ (sender=9)
0;255;3;0;9;TSP:CHKUPL:OK
0;255;3;0;9;TSP:MSG:GWL OK
0;255;3;0;9;TSP:MSG:SEND 0-0-9-9 s=255,c=3,t=8,pt=1,l=1,sg=0,ft=0,st=ok:0
0;255;3;0;9;TSP:MSG:READ 9-9-255 s=255,c=3,t=7,pt=0,l=0,sg=0:
0;255;3;0;9;TSP:MSG:BC
0;255;3;0;9;TSP:MSG:FPAR REQ (sender=9)
0;255;3;0;9;TSP:CHKUPL:OK
0;255;3;0;9;TSP:MSG:GWL OK
0;255;3;0;9;TSP:MSG:SEND 0-0-9-9 s=255,c=3,t=8,pt=1,l=1,sg=0,ft=0,st=ok:0
0;255;3;0;9;TSP:MSG:READ 9-9-0 s=255,c=3,t=24,pt=1,l=1,sg=0:1
0;255;3;0;9;TSP:MSG:PINGED (ID=9, hops=1)
0;255;3;0;9;TSP:MSG:SEND 0-0-9-9 s=255,c=3,t=25,pt=1,l=1,sg=0,ft=0,st=ok:1
0;255;3;0;9;TSP:MSG:READ 9-9-0 s=10,c=1,t=1,pt=7,l=5,sg=0:37.9
0;255;3;0;9;TSP:SANCHK:OK
0;255;3;0;9;TSP:MSG:READ 9-9-0 s=10,c=1,t=1,pt=7,l=5,sg=0:38.0
0;255;3;0;9;TSP:SANCHK:OK
0;255;3;0;9;TSP:SANCHK:OK
0;255;3;0;9;TSP:SANCHK:OK
0;255;3;0;9;TSP:SANCHK:OK
0;255;3;0;9;TSP:SANCHK:OK
0;255;3;0;9;TSP:SANCHK:OK
0;255;3;0;9;TSP:SANCHK:OK
0;255;3;0;9;TSP:MSG:READ 9-9-0 s=10,c=1,t=1,pt=7,l=5,sg=0:38.0
0;255;3;0;9;TSP:SANCHK:OK
0;255;3;0;9;TSP:SANCHK:OK
0;255;3;0;9;TSP:SANCHK:OK

The problem must be on OpenHAB2 side. What to do next?

[jogant]

@pentti12
you are right, your serial log looks ok. So at least your mysensors network is up and running. In the moment the gateway receives an update from a sensor you should also see an incoming message in OH log. If this is not the case there might be something wrong with your binding config. You know https://github.com/tobof/openhab2-addons/wiki? There are valuable hints. Only difference to my setup is that I'm using mysensors 2.0.1 beta. No idea whether this makes any difference. Besides that I have no further idea. Sorry.

[pentti12]

I see from OH2 event log:

2016-11-22 06:17:43.911 [hingStatusInfoChangedEvent] - 'mysensors:bridge-eth:19d1e911' changed from UNINITIALIZED to INITIALIZING
2016-11-22 06:17:43.937 [hingStatusInfoChangedEvent] - 'mysensors:bridge-eth:19d1e911' changed from INITIALIZING to ONLINE
2016-11-22 06:19:49.491 [ItemCommandEvent ] - Item 'mysensors_temperature_9d001ab8_battery' received command REFRESH
2016-11-22 06:20:05.658 [ItemCommandEvent ] - Item 'mysensors_temperature_9d001ab8_temp' received command REFRESH
2016-11-22 06:21:08.469 [ItemCommandEvent ] - Item 'mysensors_temperature_9d001ab8_battery' received command REFRESH

And from OH2 log:

2016-11-22 06:11:11.125 [WARN ] [el.core.internal.ModelRepositoryImpl] - Configuration model 'test.things' is either empty or cannot be parsed correctly!
2016-11-22 06:11:11.194 [INFO ] [el.core.internal.ModelRepositoryImpl] - Loading model 'test.things'
2016-11-22 06:11:11.251 [ERROR] [rs.protocol.ip.MySensorsIpConnection] - Error while trying to connect InputStreamReader
2016-11-22 06:11:11.255 [ERROR] [rs.protocol.ip.MySensorsIpConnection] - Something went wrong!
2016-11-22 06:11:11.322 [INFO ] [el.core.internal.ModelRepositoryImpl] - Refreshing model 'test.things'
2016-11-22 06:12:08.388 [INFO ] [ome.io.rest.core.thing.ThingResource] - Received HTTP PUT request for update configuration at 'things/mysensors:bridge-eth:gateway/config' for an unmanaged thing 'mysensors:bridge-eth:gateway'.
2016-11-22 06:12:32.535 [INFO ] [ome.io.rest.core.thing.ThingResource] - Received HTTP PUT request for update at 'things/mysensors:bridge-eth:gateway' for an unmanaged thing 'mysensors:bridge-eth:gateway'.
2016-11-22 06:12:51.983 [INFO ] [el.core.internal.ModelRepositoryImpl] - Refreshing model 'test.things'
2016-11-22 06:12:51.990 [WARN ] [el.core.internal.ModelRepositoryImpl] - Configuration model 'test.things' is either empty or cannot be parsed correctly!
2016-11-22 06:12:52.016 [INFO ] [el.core.internal.ModelRepositoryImpl] - Loading model 'test.things'
2016-11-22 06:12:52.072 [INFO ] [el.core.internal.ModelRepositoryImpl] - Refreshing model 'test.things'
2016-11-22 06:14:46.978 [INFO ] [el.core.internal.ModelRepositoryImpl] - Refreshing model 'test.things'
2016-11-22 06:14:46.986 [WARN ] [el.core.internal.ModelRepositoryImpl] - Configuration model 'test.things' is either empty or cannot be parsed correctly!
2016-11-22 06:14:47.045 [INFO ] [el.core.internal.ModelRepositoryImpl] - Loading model 'test.things'

So there are some problems at least on test.things file:

Bridge mysensors:bridge-eth:gateway [ ipAddress="192.168.1.201", tcpPort=5003, sendDelay=200, imperial=false ] {
/** define things connected to that bridge here */
humidity hum01 [ nodeId="9", childId="10" ]
temperature temp01 [ nodeId="9", childId="11" ]
}

Any advice?

[jogant]

@pentti12

ahh, try to leave out thing definition in config file and let OH discover things. After discovery remember to restart mysensors binding like @TimO explained. Then link discovered things to items and see if that works.
Are you shure about your sonsor IDs? Usually they are numbered starting with 0.

[pentti12]

No success!

I ended up to the same situation, no real values of temperature nor humidity.
OH2 cannot search things automatically. I added them manually after I configured the MySensors Gateway.

[jogant]

@pentti12

here you see a snippet from my log while in DEBUG mode for mysensors binding:

10:57:19.269 [DEBUG] [al.protocol.ip.MySensorsIpConnection] - Bridge is connected, connection skipped
10:57:29.271 [DEBUG] [al.protocol.ip.MySensorsIpConnection] - Bridge is connected, connection skipped
10:57:39.273 [DEBUG] [al.protocol.ip.MySensorsIpConnection] - Bridge is connected, connection skipped
10:57:39.820 [INFO ] [marthome.event.ItemStateChangedEvent] - RTemp_EG_WZ_R_signal changed from -50 to -51
10:57:42.145 [DEBUG] [rs.internal.protocol.MySensorsReader] - 2;255;3;0;21;0
10:57:42.171 [DEBUG] [ternal.handler.MySensorsThingHandler] - Setting last update for node 2 to 2016-11-22T10:57:42.169+0100
10:57:42.174 [DEBUG] [ternal.handler.MySensorsThingHandler] - Setting last update for node 2 to 2016-11-22T10:57:42.172+0100
10:57:49.274 [DEBUG] [al.protocol.ip.MySensorsIpConnection] - Bridge is connected, connection skipped
10:57:50.476 [INFO ] [marthome.event.ItemStateChangedEvent] - RTemp_UG_Ki_Li_signal changed from -61 to -60
10:57:59.276 [DEBUG] [al.protocol.ip.MySensorsIpConnection] - Bridge is connected, connection skipped
10:57:59.465 [INFO ] [marthome.event.ItemStateChangedEvent] - RTemp_UG_SZ_signal changed from -68 to -67
10:58:09.278 [DEBUG] [al.protocol.ip.MySensorsIpConnection] - Bridge is connected, connection skipped
10:58:19.280 [DEBUG] [al.protocol.ip.MySensorsIpConnection] - Bridge is connected, connection skipped
10:58:29.282 [DEBUG] [al.protocol.ip.MySensorsIpConnection] - Bridge is connected, connection skipped
10:58:30.810 [DEBUG] [rs.internal.protocol.MySensorsReader] - 1;0;1;0;23;80
10:58:30.817 [DEBUG] [ternal.handler.MySensorsThingHandler] - Setting last update for node 1 to 2016-11-22T10:58:30.815+0100
10:58:30.824 [DEBUG] [ternal.handler.MySensorsThingHandler] - Setting last update for node 1 to 2016-11-22T10:58:30.822+0100
10:58:30.833 [DEBUG] [ternal.handler.MySensorsThingHandler] - Setting last update for node 1 to 2016-11-22T10:58:30.831+0100
10:58:30.837 [INFO ] [marthome.event.ItemStateChangedEvent] - Lightlevel changed from 81 to 80
10:58:39.284 [DEBUG] [al.protocol.ip.MySensorsIpConnection] - Bridge is connected, connection skipped

Here is the mysensors part my default.things

Bridge mysensors:bridge-eth:gateway [ ipAddress="192.168.96.9", tcpPort=5003, sendDelay=200 ] {
     /** define things connected to that bridge here */
  }

and the mysensors part of my items:

/* mysensors Licht/Temp/Hum */
Number Lightlevel "Helligkeit [%.0f %%]" <sun> (gLicht)                         { channel="mysensors:light-level:gateway:Light_level_1_0:light-level" }
Number mySensors1Hum "Luftfeuchte [%.1f %%]" <water>                            { channel="mysensors:humidity:gateway:Humidity_1_1:hum" }
Number mySensors1Temp "Temperatur [%.1f °C]" <temperature>                      { channel="mysensors:temperature:gateway:Temperature_1_2:temp" }

Maybe this is of any help as I don't have an idea what's wrong with your config.

[TimO]

Hi @pentti12 !
Stop searching, there is a bug in the binding. I'm working on it. ;-)

[pentti12]

OK, TimO!

I will wait for the new version until I continue!

Pentti

[jogant]

@TimO
funny that it works for me :smiley:

[TimO]

@jogant Sadly it works fine in my devolpment and test environment, too. ;-)
If you are using a OH2 snapshot that is older than 11 days there is a chance that it still works but it's not predictable.

[jogant]

@TimO
ok, I'm using OH2 b4, that is definitely older than 11 days.

[TimO]

@pentti12 I've pushed a new version of the binding to github, please try it out and let me know if it helps.

[pentti12]

Now I got only MySensors Ethernet Gateway into ONLINE state. The Humidity and Temperature Sensors (Things) stay UNINITIALIZED state.

[TimO]

@pentti12 Have you deleted the things and newly discovered them? When the binding changes the mapdb (where discovered devices are stored) isn't updated as well. That's why I'm using the *.things files instead. If you try to remove the items errors could occure, this is another hint that this is the problem. After restart of OH2 the things should disappear.

Another way to do this is:

1. stop OH2
2. rm /var/lib/openhab2/mapdb/*
3. start OH2

But this will delete all discovered things (not only MySensors)!