search

eclipse-archived / smarthome

Eclipse SmartHome™ project
https://www.eclipse.org/smarthome/
Eclipse Public License 2.0
864 stars 782 forks source link

Binding initialization stalls during startup (intermittently) #1847

Closed mhilbush closed 8 years ago

mhilbush commented 8 years ago

There have been numerous reports of bindings "stalling" (for lack of a better word) at startup. I have experienced the problem with the zwave and systeminfo bindings. Others have reported similar behavior with knx, rfxcom, meteostick, and max.

I first noticed this behavior with the 6/19 build, and it continues through the most current build (#399). At the time I was installing builds on almost a daily basis, and I do not recall seeing this behavior in the 6/17 and prior builds (I think I skipped installing the 6/18 build, so I don't know about that one). I started this forum thread, which has now become quite long. https://community.openhab.org/t/binding-not-starting-consistently-since-6-19-build/11741

There are other forum threads describing similar behavior.
Here. https://community.openhab.org/t/z-wave-binding-things-initializing-after-restart/12173 And here. https://community.openhab.org/t/testing-z-wave-binding-on-openhab-2/7522/1372

This originally was thought to be related to the circular reference issue. However, the problem continues even after the circular reference fix.

There may be some relationship to the XML file loading issue, but perhaps not. https://github.com/eclipse/smarthome/issues/1796

Here's the summary of what I'm seeing:

Start openhab. Things start out pretty normal.

2016-06-20 10:38:47.723 [INFO ] [smarthome.event.ThingAddedEvent     ] - Thing 'zwave:device:1556e3ab04f:node3' has been added.
2016-06-20 10:38:47.800 [INFO ] [smarthome.event.ThingAddedEvent     ] - Thing 'zwave:device:1556e3ab04f:node6' has been added.
2016-06-20 10:38:47.807 [INFO ] [smarthome.event.ThingAddedEvent     ] - Thing 'zwave:serial_zstick:1556e3ab04f' has been added.
2016-06-20 10:38:47.870 [INFO ] [smarthome.event.ItemAddedEvent      ] - Item 'zwave_device_1556e3ab04f_node3_scene_number' has been added.
2016-06-20 10:38:47.872 [INFO ] [home.event.ItemChannelLinkAddedEvent] - Link 'zwave_device_1556e3ab04f_node3_scene_number-zwave:device:1556e3ab04f:node3:scene_number' has been added.
2016-06-20 10:38:47.875 [INFO ] [smarthome.event.ItemAddedEvent      ] - Item 'zwave_device_1556e3ab04f_node6_scene_number' has been added.
2016-06-20 10:38:47.878 [INFO ] [home.event.ItemChannelLinkAddedEvent] - Link 'zwave_device_1556e3ab04f_node6_scene_number-zwave:device:1556e3ab04f:node6:scene_number' has been added.
2016-06-20 10:38:47.886 [INFO ] [smarthome.event.ItemAddedEvent      ] - Item 'zwave_device_1556e3ab04f_node6_switch_dimmer' has been added.
2016-06-20 10:38:47.889 [INFO ] [home.event.ItemChannelLinkAddedEvent] - Link 'zwave_device_1556e3ab04f_node6_switch_dimmer-zwave:device:1556e3ab04f:node6:switch_dimmer' has been added.
2016-06-20 10:38:47.894 [INFO ] [smarthome.event.ItemAddedEvent      ] - Item 'zwave_serial_zstick_1556e3ab04f_serial_ack' has been added.
2016-06-20 10:38:47.896 [INFO ] [home.event.ItemChannelLinkAddedEvent] - Link 'zwave_serial_zstick_1556e3ab04f_serial_ack-zwave:serial_zstick:1556e3ab04f:serial_ack' has been added.
2016-06-20 10:38:47.902 [INFO ] [smarthome.event.ItemAddedEvent      ] - Item 'zwave_serial_zstick_1556e3ab04f_serial_can' has been added.
2016-06-20 10:38:47.908 [INFO ] [home.event.ItemChannelLinkAddedEvent] - Link 'zwave_serial_zstick_1556e3ab04f_serial_can-zwave:serial_zstick:1556e3ab04f:serial_can' has been added.
2016-06-20 10:38:47.917 [INFO ] [smarthome.event.ItemAddedEvent      ] - Item 'zwave_serial_zstick_1556e3ab04f_serial_nak' has been added.
2016-06-20 10:38:47.921 [INFO ] [home.event.ItemChannelLinkAddedEvent] - Link 'zwave_serial_zstick_1556e3ab04f_serial_nak-zwave:serial_zstick:1556e3ab04f:serial_nak' has been added.
2016-06-20 10:38:47.932 [INFO ] [smarthome.event.ItemAddedEvent      ] - Item 'zwave_serial_zstick_1556e3ab04f_serial_oof' has been added.
2016-06-20 10:38:47.934 [INFO ] [home.event.ItemChannelLinkAddedEvent] - Link 'zwave_serial_zstick_1556e3ab04f_serial_oof-zwave:serial_zstick:1556e3ab04f:serial_oof' has been added.
2016-06-20 10:38:47.936 [INFO ] [smarthome.event.ItemAddedEvent      ] - Item 'zwave_serial_zstick_1556e3ab04f_serial_sof' has been added.
2016-06-20 10:38:47.938 [INFO ] [home.event.ItemChannelLinkAddedEvent] - Link 'zwave_serial_zstick_1556e3ab04f_serial_sof-zwave:serial_zstick:1556e3ab04f:serial_sof' has been added.
2016-06-20 10:38:50.530 [INFO ] [arthome.ui.paper.internal.PaperUIApp] - Started Paper UI at /ui
2016-06-20 10:38:50.744 [INFO ] [.dashboard.internal.DashboardService] - Started dashboard at /start
2016-06-20 10:38:50.755 [DEBUG] [org.openhab.binding.zwave           ] - BundleEvent STARTING - org.openhab.binding.zwave
2016-06-20 10:38:50.760 [DEBUG] [inding.zwave.internal.ZWaveActivator] - ZWave binding started. Version 2.0.0.201606200830
2016-06-20 10:38:51.019 [DEBUG] [org.openhab.binding.zwave           ] - ServiceEvent REGISTERED - {org.eclipse.smarthome.config.core.ConfigOptionProvider, org.eclipse.smarthome.config.core.ConfigDescriptionProvider}={component.name=org.openhab.binding.zwave.ConfigDescription, component.id=156, service.id=274, service.bundleid=188, service.scope=bundle} - org.openhab.binding.zwave
2016-06-20 10:38:51.029 [DEBUG] [org.openhab.binding.zwave           ] - ServiceEvent REGISTERED - {org.eclipse.smarthome.core.thing.binding.ThingHandlerFactory}={component.name=org.openhab.binding.zwave.internal.ZWaveHandlerFactory, component.id=157, service.id=275, service.bundleid=188, service.scope=bundle} - org.openhab.binding.zwave
2016-06-20 10:38:51.094 [DEBUG] [org.openhab.binding.zwave           ] - ServiceEvent REGISTERED - {org.eclipse.smarthome.core.thing.binding.ThingHandler}={thing.type=zwave:aeon_dsa03202_00_000, thing.id=zwave:device:1556e3ab04f:node3, service.id=276, service.bundleid=188, service.scope=singleton} - org.openhab.binding.zwave
2016-06-20 10:38:51.106 [INFO ] [me.event.ThingStatusInfoChangedEvent] - 'zwave:device:1556e3ab04f:node3' changed from UNINITIALIZED to INITIALIZING
2016-06-20 10:38:51.118 [DEBUG] [org.openhab.binding.zwave           ] - ServiceEvent REGISTERED - {org.eclipse.smarthome.config.core.status.ConfigStatusProvider}={service.id=277, service.bundleid=188, service.scope=singleton} - org.openhab.binding.zwave
2016-06-20 10:38:51.147 [DEBUG] [org.openhab.binding.zwave           ] - ServiceEvent REGISTERED - {org.eclipse.smarthome.core.thing.binding.ThingHandler}={thing.type=zwave:leviton_vrp03_00_000, thing.id=zwave:device:1556e3ab04f:node6, service.id=278, service.bundleid=188, service.scope=singleton} - org.openhab.binding.zwave
2016-06-20 10:38:51.153 [DEBUG] [org.openhab.binding.zwave           ] - ServiceEvent REGISTERED - {org.eclipse.smarthome.config.core.status.ConfigStatusProvider}={service.id=279, service.bundleid=188, service.scope=singleton} - org.openhab.binding.zwave
2016-06-20 10:38:51.158 [INFO ] [me.event.ThingStatusInfoChangedEvent] - 'zwave:device:1556e3ab04f:node6' changed from UNINITIALIZED to INITIALIZING
2016-06-20 10:38:51.195 [DEBUG] [org.openhab.binding.zwave           ] - ServiceEvent REGISTERED - {org.eclipse.smarthome.core.thing.binding.ThingHandler}={thing.type=zwave:serial_zstick, thing.id=zwave:serial_zstick:1556e3ab04f, service.id=280, service.bundleid=188, service.scope=singleton} - org.openhab.binding.zwave
2016-06-20 10:38:51.213 [DEBUG] [org.openhab.binding.zwave           ] - BundleEvent STARTED - org.openhab.binding.zwave
2016-06-20 10:38:51.215 [INFO ] [me.event.ThingStatusInfoChangedEvent] - 'zwave:serial_zstick:1556e3ab04f' changed from UNINITIALIZED to INITIALIZING

But at this point there's nothing. Initialization of the zwave stick and nodes never starts.

When things start normally I would see messages like this.

2016-06-20 09:35:30.622 [DEBUG] [ding.zwave.handler.ZWaveThingHandler] - Initializing ZWave thing handler.
2016-06-20 09:35:30.631 [INFO ] [me.event.ThingStatusInfoChangedEvent] - 'zwave:device:1556de5cdb3:node3' changed from INITIALIZING to OFFLINE
2016-06-20 09:35:30.633 [DEBUG] [ding.zwave.handler.ZWaveThingHandler] - NODE 3: Controller initialised.

The "Initializing ZWave thing handler" message is the first thing called in the ThingHandler's initialize() method, so I'm assuming that the initialize() method is never being called.

@Override
public void initialize() {
    logger.debug("Initializing ZWave thing handler.");

@cdjackson, please feel free to add to this if you have any additional information.

kaikreuzer commented 8 years ago

All cases that you mention refer to the Z-Wave binding. Does the same problem occur with e.g. any of the ESH bindings or anything "simpler" than Z-Wave?

mhilbush commented 8 years ago

I experienced it with zwave and systeminfo. I'm unable to provide specific details on systeminfo because systeminfo was not in debugging mode at the time.

In the forum topics cited above, others have commented that they've seen similar behavior with other bindings, including as knx, rfxcom, meteostick, max, and ntp. I referenced those in this issue, but I don't have any specific log detail, such as what I provided for zwave.

cdjackson commented 8 years ago

Yes - This is the same issue that I periodically have with the meteostick binding. There are also reports on the MAX binding and RFXCOM binding and Astro. I wouldn’t like to say if it’s all ‘exactly’ the same as there aren’t logs for all these instances.

I don’t believe this is anything to do with zwave - it started happening with no changes to the binding - of course, I could be wrong...

kaikreuzer commented 8 years ago

Does this only happen on Karaf or did anyone see this happening when being started from within the IDE?

cdjackson commented 8 years ago

I’ve personally never seen any of these issues in the IDE.

marcelrv commented 8 years ago

@kaikreuzer installed today complete clean fresh version. Indeed stalling issue still occurs, at least with the MAX! binding.

Discovery services work fine, but seems like something goes haywire with the initialize method. I think it may be at the time the status update is done (as the thing goes never online) I also see that once the issue occurs, the logout command in karaf goes very slow.

openhab> log:tail
19:47:03.569 [DEBUG] [org.openhab.binding.max             ] - BundleEvent INSTALLED - org.openhab.binding.max
19:47:03.942 [DEBUG] [org.openhab.binding.max             ] - BundleEvent RESOLVED - org.openhab.binding.max
19:47:03.955 [DEBUG] [org.openhab.binding.max             ] - BundleEvent STARTING - org.openhab.binding.max
19:47:03.973 [DEBUG] [org.openhab.binding.max             ] - ServiceEvent REGISTERED - {org.eclipse.smarthome.config.discovery.DiscoveryService}={component.name=org.ope                    nhab.binding.max.internal.discovery, component.id=7, service.id=117, service.bundleid=190, service.scope=bundle} - org.openhab.binding.max
19:47:04.008 [DEBUG] [nal.discovery.MaxCubeBridgeDiscovery] - Start MAX! Cube background discovery
19:47:04.014 [DEBUG] [org.openhab.binding.max             ] - ServiceEvent REGISTERED - {org.eclipse.smarthome.core.thing.binding.ThingHandlerFactory}={component.name=or                    g.openhab.binding.max.internal.factory.MaxCubeHandlerFactory, component.id=8, service.id=118, service.bundleid=190, service.scope=bundle} - org.openhab.binding.max
19:47:04.021 [DEBUG] [nal.discovery.MaxCubeBridgeDiscovery] - Run MAX! Cube discovery
19:47:04.078 [DEBUG] [org.openhab.binding.max             ] - BundleEvent STARTED - org.openhab.binding.max
19:47:04.783 [DEBUG] [nal.discovery.MaxCubeBridgeDiscovery] - MAX! Cube found on network
19:47:04.790 [DEBUG] [nal.discovery.MaxCubeBridgeDiscovery] - Found at  : 192.168.3.9
19:47:04.793 [DEBUG] [nal.discovery.MaxCubeBridgeDiscovery] - Serial    : KEQ0565026
19:47:04.802 [DEBUG] [nal.discovery.MaxCubeBridgeDiscovery] - RF Address: 0b5951
19:47:04.812 [DEBUG] [nal.discovery.MaxCubeBridgeDiscovery] - Firmware  : 01.13
19:47:04.857 [INFO ] [ui.habmin.internal.servlet.HABminApp] - Started HABmin servlet at /habmin
19:47:04.928 [DEBUG] [nal.discovery.MaxCubeBridgeDiscovery] - MAX! Cube found on network
19:47:04.929 [DEBUG] [nal.discovery.MaxCubeBridgeDiscovery] - Found at  : 192.168.3.191
19:47:04.930 [DEBUG] [nal.discovery.MaxCubeBridgeDiscovery] - Serial    : KEQ1069808
19:47:04.931 [DEBUG] [nal.discovery.MaxCubeBridgeDiscovery] - RF Address: 0d9763
19:47:04.932 [DEBUG] [nal.discovery.MaxCubeBridgeDiscovery] - Firmware  : 01.13
19:47:09.992 [DEBUG] [nal.discovery.MaxCubeBridgeDiscovery] - Done receiving discovery messages.
19:47:20.155 [INFO ] [g.discovery.internal.PersistentInbox] - Added new thing 'max:bridge:KEQ1069808' to inbox.
19:47:20.595 [DEBUG] [org.openhab.binding.max             ] - ServiceEvent REGISTERED - {org.eclipse.smarthome.config.discovery.DiscoveryService}={service.id=210, servic                    e.bundleid=190, service.scope=singleton} - org.openhab.binding.max
19:47:20.607 [DEBUG] [org.openhab.binding.max             ] - ServiceEvent REGISTERED - {org.eclipse.smarthome.core.thing.binding.ThingHandler}={thing.type=max:bridge, t                    hing.id=max:bridge:KEQ1069808, service.id=211, service.bundleid=190, service.scope=singleton} - org.openhab.binding.max
19:47:20.648 [DEBUG] [nternal.handler.MaxCubeBridgeHandler] - Initializing MAX! Cube bridge handler.
19:47:20.700 [DEBUG] [nternal.handler.MaxCubeBridgeHandler] - Cube IP         192.168.3.191.
19:47:20.702 [DEBUG] [nternal.handler.MaxCubeBridgeHandler] - Port            62910.
19:47:20.705 [DEBUG] [nternal.handler.MaxCubeBridgeHandler] - RefreshInterval 30.
19:47:20.708 [DEBUG] [nternal.handler.MaxCubeBridgeHandler] - Exclusive mode  true.
19:47:20.710 [DEBUG] [nternal.handler.MaxCubeBridgeHandler] - Max Requests    1000.
19:47:24.833 [INFO ] [arthome.ui.paper.internal.PaperUIApp] - Started Paper UI at /ui
19:47:25.145 [INFO ] [.dashboard.internal.DashboardService] - Started dashboard at /start
19:47:25.349 [INFO ] [assic.internal.servlet.WebAppServlet] - Started Classic UI at /classicui/app
19:47:25.382 [INFO ] [basic.internal.servlet.WebAppServlet] - Started Basic UI at /basicui/app
19:48:08.588 [DEBUG] [nternal.handler.MaxCubeBridgeHandler] - MAX! Cube max:bridge: Configuration update received
19:48:08.591 [DEBUG] [nternal.handler.MaxCubeBridgeHandler] - MAX! Cube max:bridge: Configuration update rfAddress to 0d9763
19:48:08.594 [DEBUG] [nternal.handler.MaxCubeBridgeHandler] - MAX! Cube max:bridge: Configuration update serialNumber to KEQ1069808
19:48:08.599 [DEBUG] [nternal.handler.MaxCubeBridgeHandler] - MAX! Cube max:bridge: Configuration update action-cubeReset to -1
19:48:08.603 [DEBUG] [nternal.handler.MaxCubeBridgeHandler] - MAX! Cube max:bridge: Configuration update action-cubeReboot to -1
19:48:08.607 [DEBUG] [nternal.handler.MaxCubeBridgeHandler] - MAX! Cube max:bridge: Configuration update ntpServer1 to ntp.homematic.com
19:48:08.652 [DEBUG] [nternal.handler.MaxCubeBridgeHandler] - Handler disposed.
19:48:08.653 [DEBUG] [nternal.handler.MaxCubeBridgeHandler] - Initializing MAX! Cube bridge handler.
19:48:08.655 [DEBUG] [nternal.handler.MaxCubeBridgeHandler] - Cube IP         192.168.3.191.
19:48:08.655 [DEBUG] [nternal.handler.MaxCubeBridgeHandler] - Port            62910.
19:48:08.656 [DEBUG] [nternal.handler.MaxCubeBridgeHandler] - RefreshInterval 30.
19:48:08.657 [DEBUG] [nternal.handler.MaxCubeBridgeHandler] - Exclusive mode  true.
19:48:08.658 [DEBUG] [nternal.handler.MaxCubeBridgeHandler] - Max Requests    1000.
19:48:13.665 [ERROR] [ome.core.thing.internal.ThingManager] - Exception occured while calling thing updated at ThingHandler 'org.openhab.binding.max.internal.handler.Max                    CubeBridgeHandler@5a02b: null
java.util.concurrent.TimeoutException
        at java.util.concurrent.FutureTask.get(FutureTask.java:205)[:1.8.0_91]
        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.thingUpdated(ThingManager.java:538)
        at org.eclipse.smarthome.core.thing.internal.ThingRegistryImpl.notifyTrackers(ThingRegistryImpl.java:218)
        at org.eclipse.smarthome.core.thing.internal.ThingRegistryImpl.notifyListenersAboutUpdatedElement(ThingRegistryImpl.java:141)
        at org.eclipse.smarthome.core.thing.internal.ThingRegistryImpl.notifyListenersAboutUpdatedElement(ThingRegistryImpl.java:1)
        at org.eclipse.smarthome.core.common.registry.AbstractRegistry.updated(AbstractRegistry.java:102)
        at org.eclipse.smarthome.core.common.registry.AbstractProvider.notifyListeners(AbstractProvider.java:57)
        at org.eclipse.smarthome.core.common.registry.AbstractProvider.notifyListenersAboutUpdatedElement(AbstractProvider.java:82)
        at org.eclipse.smarthome.core.common.registry.AbstractManagedProvider.update(AbstractManagedProvider.java:134)
        at org.eclipse.smarthome.io.rest.core.thing.ThingResource.update(ThingResource.java:399)
        at sun.reflect.NativeMethodAccessorImpl.invoke0(Native Method)[:1.8.0_91]
        at sun.reflect.NativeMethodAccessorImpl.invoke(NativeMethodAccessorImpl.java:62)[:1.8.0_91]
        at sun.reflect.DelegatingMethodAccessorImpl.invoke(DelegatingMethodAccessorImpl.java:43)[:1.8.0_91]
        at java.lang.reflect.Method.invoke(Method.java:498)[:1.8.0_91]
        at org.glassfish.jersey.server.model.internal.ResourceMethodInvocationHandlerFactory$1.invoke(ResourceMethodInvocationHandlerFactory.java:81)[152:org.glassfish.j                    ersey.core.jersey-server:2.22.2]
        at org.glassfish.jersey.server.model.internal.AbstractJavaResourceMethodDispatcher$1.run(AbstractJavaResourceMethodDispatcher.java:144)[152:org.glassfish.jersey.                    core.jersey-server:2.22.2]
        at org.glassfish.jersey.server.model.internal.AbstractJavaResourceMethodDispatcher.invoke(AbstractJavaResourceMethodDispatcher.java:161)[152:org.glassfish.jersey                    .core.jersey-server:2.22.2]
        at org.glassfish.jersey.server.model.internal.JavaResourceMethodDispatcherProvider$ResponseOutInvoker.doDispatch(JavaResourceMethodDispatcherProvider.java:160)[1                    52:org.glassfish.jersey.core.jersey-server:2.22.2]
        at org.glassfish.jersey.server.model.internal.AbstractJavaResourceMethodDispatcher.dispatch(AbstractJavaResourceMethodDispatcher.java:99)[152:org.glassfish.jerse                    y.core.jersey-server:2.22.2]
        at org.glassfish.jersey.server.model.ResourceMethodInvoker.invoke(ResourceMethodInvoker.java:389)[152:org.glassfish.jersey.core.jersey-server:2.22.2]
        at org.glassfish.jersey.server.model.ResourceMethodInvoker.apply(ResourceMethodInvoker.java:347)[152:org.glassfish.jersey.core.jersey-server:2.22.2]
        at org.glassfish.jersey.server.model.ResourceMethodInvoker.apply(ResourceMethodInvoker.java:102)[152:org.glassfish.jersey.core.jersey-server:2.22.2]
        at org.glassfish.jersey.server.ServerRuntime$2.run(ServerRuntime.java:326)[152:org.glassfish.jersey.core.jersey-server:2.22.2]
        at org.glassfish.jersey.internal.Errors$1.call(Errors.java:271)[151:org.glassfish.jersey.core.jersey-common:2.22.2]
        at org.glassfish.jersey.internal.Errors$1.call(Errors.java:267)[151:org.glassfish.jersey.core.jersey-common:2.22.2]
        at org.glassfish.jersey.internal.Errors.process(Errors.java:315)[151:org.glassfish.jersey.core.jersey-common:2.22.2]
        at org.glassfish.jersey.internal.Errors.process(Errors.java:297)[151:org.glassfish.jersey.core.jersey-common:2.22.2]
        at org.glassfish.jersey.internal.Errors.process(Errors.java:267)[151:org.glassfish.jersey.core.jersey-common:2.22.2]
        at org.glassfish.jersey.process.internal.RequestScope.runInScope(RequestScope.java:317)[151:org.glassfish.jersey.core.jersey-common:2.22.2]
        at org.glassfish.jersey.server.ServerRuntime.process(ServerRuntime.java:305)[152:org.glassfish.jersey.core.jersey-server:2.22.2]
        at org.glassfish.jersey.server.ApplicationHandler.handle(ApplicationHandler.java:1154)[152:org.glassfish.jersey.core.jersey-server:2.22.2]
        at org.glassfish.jersey.servlet.WebComponent.serviceImpl(WebComponent.java:473)[149:org.glassfish.jersey.containers.jersey-container-servlet-core:2.22.2]
        at org.glassfish.jersey.servlet.WebComponent.service(WebComponent.java:427)[149:org.glassfish.jersey.containers.jersey-container-servlet-core:2.22.2]
        at org.glassfish.jersey.servlet.ServletContainer.service(ServletContainer.java:388)[149:org.glassfish.jersey.containers.jersey-container-servlet-core:2.22.2]
        at org.glassfish.jersey.servlet.ServletContainer.service(ServletContainer.java:341)[149:org.glassfish.jersey.containers.jersey-container-servlet-core:2.22.2]
        at org.glassfish.jersey.servlet.ServletContainer.service(ServletContainer.java:228)[149:org.glassfish.jersey.containers.jersey-container-servlet-core:2.22.2]
        at com.eclipsesource.jaxrs.publisher.internal.ServletContainerBridge.service(ServletContainerBridge.java:76)[12:com.eclipsesource.jaxrs.publisher:5.3.1.201602281                    253]
        at org.eclipse.jetty.servlet.ServletHolder.handle(ServletHolder.java:812)[80:org.eclipse.jetty.servlet:9.2.14.v20151106]
        at org.eclipse.jetty.servlet.ServletHandler.doHandle(ServletHandler.java:587)[80:org.eclipse.jetty.servlet:9.2.14.v20151106]
        at org.ops4j.pax.web.service.jetty.internal.HttpServiceServletHandler.doHandle(HttpServiceServletHandler.java:70)[165:org.ops4j.pax.web.pax-web-jetty:4.2.4]
        at org.eclipse.jetty.server.handler.ScopedHandler.handle(ScopedHandler.java:143)[79:org.eclipse.jetty.server:9.2.14.v20151106]
        at org.eclipse.jetty.security.SecurityHandler.handle(SecurityHandler.java:577)[78:org.eclipse.jetty.security:9.2.14.v20151106]
        at org.eclipse.jetty.server.session.SessionHandler.doHandle(SessionHandler.java:223)[79:org.eclipse.jetty.server:9.2.14.v20151106]
        at org.eclipse.jetty.server.handler.ContextHandler.doHandle(ContextHandler.java:1127)[79:org.eclipse.jetty.server:9.2.14.v20151106]
        at org.ops4j.pax.web.service.jetty.internal.HttpServiceContext.doHandle(HttpServiceContext.java:271)[165:org.ops4j.pax.web.pax-web-jetty:4.2.4]
        at org.eclipse.jetty.servlet.ServletHandler.doScope(ServletHandler.java:515)[80:org.eclipse.jetty.servlet:9.2.14.v20151106]
        at org.eclipse.jetty.server.session.SessionHandler.doScope(SessionHandler.java:185)[79:org.eclipse.jetty.server:9.2.14.v20151106]
        at org.eclipse.jetty.server.handler.ContextHandler.doScope(ContextHandler.java:1061)[79:org.eclipse.jetty.server:9.2.14.v20151106]
        at org.eclipse.jetty.server.handler.ScopedHandler.handle(ScopedHandler.java:141)[79:org.eclipse.jetty.server:9.2.14.v20151106]
        at org.ops4j.pax.web.service.jetty.internal.JettyServerHandlerCollection.handle(JettyServerHandlerCollection.java:80)[165:org.ops4j.pax.web.pax-web-jetty:4.2.4]
        at org.eclipse.jetty.server.handler.HandlerWrapper.handle(HandlerWrapper.java:97)[79:org.eclipse.jetty.server:9.2.14.v20151106]
        at org.eclipse.jetty.server.Server.handle(Server.java:499)[79:org.eclipse.jetty.server:9.2.14.v20151106]
        at org.eclipse.jetty.server.HttpChannel.handle(HttpChannel.java:311)[79:org.eclipse.jetty.server:9.2.14.v20151106]
        at org.eclipse.jetty.server.HttpConnection.onFillable(HttpConnection.java:257)[79:org.eclipse.jetty.server:9.2.14.v20151106]
        at org.eclipse.jetty.io.AbstractConnection$2.run(AbstractConnection.java:544)[71:org.eclipse.jetty.io:9.2.14.v20151106]
        at org.eclipse.jetty.util.thread.QueuedThreadPool.runJob(QueuedThreadPool.java:635)[82:org.eclipse.jetty.util:9.2.14.v20151106]
        at org.eclipse.jetty.util.thread.QueuedThreadPool$3.run(QueuedThreadPool.java:555)[82:org.eclipse.jetty.util:9.2.14.v20151106]
        at java.lang.Thread.run(Thread.java:745)[:1.8.0_91]
19:49:28.047 [DEBUG] [nternal.handler.MaxCubeBridgeHandler] - Connection timed out on 192.168.3.191 port 62910
19:49:28.063 [DEBUG] [nternal.handler.MaxCubeBridgeHandler] - Command queued id 0 (Cube(KEQ1069808)-F_Command:Update NTP info).
19:49:28.065 [DEBUG] [nternal.handler.MaxCubeBridgeHandler] - MAX! Cube max:bridge: Configuration update port to 62910
19:49:28.066 [DEBUG] [nternal.handler.MaxCubeBridgeHandler] - Command 0 (Cube(KEQ1069808)-F_Command:Update NTP info) sent to MAX! Cube at IP: 192.168.3.191
19:49:28.073 [DEBUG] [nternal.handler.MaxCubeBridgeHandler] - MAX! Cube max:bridge: Configuration update refreshInterval to 30
19:49:28.075 [DEBUG] [nternal.handler.MaxCubeBridgeHandler] - MAX! Cube max:bridge: Configuration update ntpServer2 to ntp.homematic.com
19:50:52.896 [DEBUG] [nternal.handler.MaxCubeBridgeHandler] - MAX! Cube max:bridge: Configuration update received
19:50:52.906 [DEBUG] [nternal.handler.MaxCubeBridgeHandler] - MAX! Cube max:bridge: Configuration update rfAddress to 0d9763
19:50:52.908 [DEBUG] [nternal.handler.MaxCubeBridgeHandler] - MAX! Cube max:bridge: Configuration update serialNumber to KEQ1069808
19:50:52.912 [DEBUG] [nternal.handler.MaxCubeBridgeHandler] - MAX! Cube max:bridge: Configuration update action-cubeReset to -1
19:50:52.914 [DEBUG] [nternal.handler.MaxCubeBridgeHandler] - MAX! Cube max:bridge: Configuration update action-cubeReboot to -1
19:50:52.917 [DEBUG] [nternal.handler.MaxCubeBridgeHandler] - MAX! Cube max:bridge: Configuration update ntpServer1 to ntp.homematic.com
19:50:52.945 [DEBUG] [nternal.handler.MaxCubeBridgeHandler] - Handler disposed.
19:50:52.947 [DEBUG] [nternal.handler.MaxCubeBridgeHandler] - Initializing MAX! Cube bridge handler.
19:50:52.950 [DEBUG] [nternal.handler.MaxCubeBridgeHandler] - Cube IP         192.168.3.191.
19:50:52.952 [DEBUG] [nternal.handler.MaxCubeBridgeHandler] - Port            62910.
19:50:52.953 [DEBUG] [nternal.handler.MaxCubeBridgeHandler] - RefreshInterval 30.
19:50:52.955 [DEBUG] [nternal.handler.MaxCubeBridgeHandler] - Exclusive mode  true.
19:50:52.956 [DEBUG] [nternal.handler.MaxCubeBridgeHandler] - Max Requests    1000.
19:50:57.950 [ERROR] [ome.core.thing.internal.ThingManager] - Exception occured while calling thing updated at ThingHandler 'org.openhab.binding.max.internal.handler.Max                    CubeBridgeHandler@5a02b: null
java.util.concurrent.TimeoutException
        at java.util.concurrent.FutureTask.get(FutureTask.java:205)[:1.8.0_91]
        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.thingUpdated(ThingManager.java:538)
        at org.eclipse.smarthome.core.thing.internal.ThingRegistryImpl.notifyTrackers(ThingRegistryImpl.java:218)
        at org.eclipse.smarthome.core.thing.internal.ThingRegistryImpl.notifyListenersAboutUpdatedElement(ThingRegistryImpl.java:141)
        at org.eclipse.smarthome.core.thing.internal.ThingRegistryImpl.notifyListenersAboutUpdatedElement(ThingRegistryImpl.java:1)
        at org.eclipse.smarthome.core.common.registry.AbstractRegistry.updated(AbstractRegistry.java:102)
        at org.eclipse.smarthome.core.common.registry.AbstractProvider.notifyListeners(AbstractProvider.java:57)
        at org.eclipse.smarthome.core.common.registry.AbstractProvider.notifyListenersAboutUpdatedElement(AbstractProvider.java:82)
        at org.eclipse.smarthome.core.common.registry.AbstractManagedProvider.update(AbstractManagedProvider.java:134)
        at org.eclipse.smarthome.io.rest.core.thing.ThingResource.update(ThingResource.java:399)
        at sun.reflect.NativeMethodAccessorImpl.invoke0(Native Method)[:1.8.0_91]
        at sun.reflect.NativeMethodAccessorImpl.invoke(NativeMethodAccessorImpl.java:62)[:1.8.0_91]
        at sun.reflect.DelegatingMethodAccessorImpl.invoke(DelegatingMethodAccessorImpl.java:43)[:1.8.0_91]
        at java.lang.reflect.Method.invoke(Method.java:498)[:1.8.0_91]
        at org.glassfish.jersey.server.model.internal.ResourceMethodInvocationHandlerFactory$1.invoke(ResourceMethodInvocationHandlerFactory.java:81)[152:org.glassfish.j                    ersey.core.jersey-server:2.22.2]
        at org.glassfish.jersey.server.model.internal.AbstractJavaResourceMethodDispatcher$1.run(AbstractJavaResourceMethodDispatcher.java:144)[152:org.glassfish.jersey.                    core.jersey-server:2.22.2]
        at org.glassfish.jersey.server.model.internal.AbstractJavaResourceMethodDispatcher.invoke(AbstractJavaResourceMethodDispatcher.java:161)[152:org.glassfish.jersey                    .core.jersey-server:2.22.2]
        at org.glassfish.jersey.server.model.internal.JavaResourceMethodDispatcherProvider$ResponseOutInvoker.doDispatch(JavaResourceMethodDispatcherProvider.java:160)[1                    52:org.glassfish.jersey.core.jersey-server:2.22.2]
        at org.glassfish.jersey.server.model.internal.AbstractJavaResourceMethodDispatcher.dispatch(AbstractJavaResourceMethodDispatcher.java:99)[152:org.glassfish.jerse                    y.core.jersey-server:2.22.2]
        at org.glassfish.jersey.server.model.ResourceMethodInvoker.invoke(ResourceMethodInvoker.java:389)[152:org.glassfish.jersey.core.jersey-server:2.22.2]
        at org.glassfish.jersey.server.model.ResourceMethodInvoker.apply(ResourceMethodInvoker.java:347)[152:org.glassfish.jersey.core.jersey-server:2.22.2]
        at org.glassfish.jersey.server.model.ResourceMethodInvoker.apply(ResourceMethodInvoker.java:102)[152:org.glassfish.jersey.core.jersey-server:2.22.2]
        at org.glassfish.jersey.server.ServerRuntime$2.run(ServerRuntime.java:326)[152:org.glassfish.jersey.core.jersey-server:2.22.2]
        at org.glassfish.jersey.internal.Errors$1.call(Errors.java:271)[151:org.glassfish.jersey.core.jersey-common:2.22.2]
        at org.glassfish.jersey.internal.Errors$1.call(Errors.java:267)[151:org.glassfish.jersey.core.jersey-common:2.22.2]
        at org.glassfish.jersey.internal.Errors.process(Errors.java:315)[151:org.glassfish.jersey.core.jersey-common:2.22.2]
        at org.glassfish.jersey.internal.Errors.process(Errors.java:297)[151:org.glassfish.jersey.core.jersey-common:2.22.2]
        at org.glassfish.jersey.internal.Errors.process(Errors.java:267)[151:org.glassfish.jersey.core.jersey-common:2.22.2]
        at org.glassfish.jersey.process.internal.RequestScope.runInScope(RequestScope.java:317)[151:org.glassfish.jersey.core.jersey-common:2.22.2]
        at org.glassfish.jersey.server.ServerRuntime.process(ServerRuntime.java:305)[152:org.glassfish.jersey.core.jersey-server:2.22.2]
        at org.glassfish.jersey.server.ApplicationHandler.handle(ApplicationHandler.java:1154)[152:org.glassfish.jersey.core.jersey-server:2.22.2]
        at org.glassfish.jersey.servlet.WebComponent.serviceImpl(WebComponent.java:473)[149:org.glassfish.jersey.containers.jersey-container-servlet-core:2.22.2]
        at org.glassfish.jersey.servlet.WebComponent.service(WebComponent.java:427)[149:org.glassfish.jersey.containers.jersey-container-servlet-core:2.22.2]
        at org.glassfish.jersey.servlet.ServletContainer.service(ServletContainer.java:388)[149:org.glassfish.jersey.containers.jersey-container-servlet-core:2.22.2]
        at org.glassfish.jersey.servlet.ServletContainer.service(ServletContainer.java:341)[149:org.glassfish.jersey.containers.jersey-container-servlet-core:2.22.2]
        at org.glassfish.jersey.servlet.ServletContainer.service(ServletContainer.java:228)[149:org.glassfish.jersey.containers.jersey-container-servlet-core:2.22.2]
        at com.eclipsesource.jaxrs.publisher.internal.ServletContainerBridge.service(ServletContainerBridge.java:76)[12:com.eclipsesource.jaxrs.publisher:5.3.1.201602281                    253]
        at org.eclipse.jetty.servlet.ServletHolder.handle(ServletHolder.java:812)[80:org.eclipse.jetty.servlet:9.2.14.v20151106]
        at org.eclipse.jetty.servlet.ServletHandler.doHandle(ServletHandler.java:587)[80:org.eclipse.jetty.servlet:9.2.14.v20151106]
        at org.ops4j.pax.web.service.jetty.internal.HttpServiceServletHandler.doHandle(HttpServiceServletHandler.java:70)[165:org.ops4j.pax.web.pax-web-jetty:4.2.4]
        at org.eclipse.jetty.server.handler.ScopedHandler.handle(ScopedHandler.java:143)[79:org.eclipse.jetty.server:9.2.14.v20151106]
        at org.eclipse.jetty.security.SecurityHandler.handle(SecurityHandler.java:577)[78:org.eclipse.jetty.security:9.2.14.v20151106]
        at org.eclipse.jetty.server.session.SessionHandler.doHandle(SessionHandler.java:223)[79:org.eclipse.jetty.server:9.2.14.v20151106]
        at org.eclipse.jetty.server.handler.ContextHandler.doHandle(ContextHandler.java:1127)[79:org.eclipse.jetty.server:9.2.14.v20151106]
        at org.ops4j.pax.web.service.jetty.internal.HttpServiceContext.doHandle(HttpServiceContext.java:271)[165:org.ops4j.pax.web.pax-web-jetty:4.2.4]
        at org.eclipse.jetty.servlet.ServletHandler.doScope(ServletHandler.java:515)[80:org.eclipse.jetty.servlet:9.2.14.v20151106]
        at org.eclipse.jetty.server.session.SessionHandler.doScope(SessionHandler.java:185)[79:org.eclipse.jetty.server:9.2.14.v20151106]
        at org.eclipse.jetty.server.handler.ContextHandler.doScope(ContextHandler.java:1061)[79:org.eclipse.jetty.server:9.2.14.v20151106]
        at org.eclipse.jetty.server.handler.ScopedHandler.handle(ScopedHandler.java:141)[79:org.eclipse.jetty.server:9.2.14.v20151106]
        at org.ops4j.pax.web.service.jetty.internal.JettyServerHandlerCollection.handle(JettyServerHandlerCollection.java:80)[165:org.ops4j.pax.web.pax-web-jetty:4.2.4]
        at org.eclipse.jetty.server.handler.HandlerWrapper.handle(HandlerWrapper.java:97)[79:org.eclipse.jetty.server:9.2.14.v20151106]
        at org.eclipse.jetty.server.Server.handle(Server.java:499)[79:org.eclipse.jetty.server:9.2.14.v20151106]
        at org.eclipse.jetty.server.HttpChannel.handle(HttpChannel.java:311)[79:org.eclipse.jetty.server:9.2.14.v20151106]
        at org.eclipse.jetty.server.HttpConnection.onFillable(HttpConnection.java:257)[79:org.eclipse.jetty.server:9.2.14.v20151106]
        at org.eclipse.jetty.io.AbstractConnection$2.run(AbstractConnection.java:544)[71:org.eclipse.jetty.io:9.2.14.v20151106]
        at org.eclipse.jetty.util.thread.QueuedThreadPool.runJob(QueuedThreadPool.java:635)[82:org.eclipse.jetty.util:9.2.14.v20151106]
        at org.eclipse.jetty.util.thread.QueuedThreadPool$3.run(QueuedThreadPool.java:555)[82:org.eclipse.jetty.util:9.2.14.v20151106]
        at java.lang.Thread.run(Thread.java:745)[:1.8.0_91]
marcelrv commented 8 years ago

btw, I can also confirm that in the IDE this issue does not happen

ghost commented 8 years ago

Guys, I have just installed snapshot number 402 and have now restarted 6 times in a row without problems

https://community.openhab.org/t/binding-not-starting-consistently-since-6-19-build/11741/49

Please let me know if there is anything I can provide to help track down the problem.

maggu2810 commented 8 years ago

I am using Eclipse SmartHome based distributions myself that differ from openHAB. So I am willing to do some tests if I can reproduce it there, too.

Is there any scenario that should be tested that triggers the failure very frequently? Can I use Eclipse SmartHome bindings e.g. Sonos (hardare for this binding available), YahooWeather or NTP? I assume I can also add the Z-Wave binding to the runtime if an USB stick without devices is enough to test it.

kaikreuzer commented 8 years ago

All, good news! I think I have found the issue - it had been introduced by https://github.com/eclipse/smarthome/pull/1419.

Will work now on a fix and provide you an update soon.

maggu2810 commented 8 years ago

All, good news! I think I have found the issue - it had been introduced by #1847.

As I am very interested in, could you please fix the reference?

Will work now on a fix and provide you an update soon.

Thanks

kaikreuzer commented 8 years ago

As I am very interested in, could you please fix the reference?

It is a recursive bug ;-) Fixed the link!

kaikreuzer commented 8 years ago

All, please have a look at #1856 - I hope it solves the issue once and for all!

kaikreuzer commented 8 years ago

Unfortunately, #1856 does not fully solve the issue yet :-( I wonder, why I only ever notice it on the officially build OH distro and never on my local test builds before...? Anyhow, I just have this in my log, which leaves the Things in uninitialized status:

14:37:05.286 [DEBUG] [ig.xml.osgi.XmlDocumentBundleTracker] - Reading the XML document '/ESH-INF/thing/fibaro_fgs212_0_0.xml' in module 'org.openhab.binding.zwave'...
14:37:05.288 [DEBUG] [ig.xml.osgi.XmlDocumentBundleTracker] - Reading the XML document '/ESH-INF/thing/popp_005107_0_0.xml' in module 'org.openhab.binding.zwave'...
14:37:05.289 [DEBUG] [ig.xml.osgi.XmlDocumentBundleTracker] - Reading the XML document '/ESH-INF/thing/yale_yrd210_0_0.xml' in module 'org.openhab.binding.zwave'...
14:37:05.312 [DEBUG] [ome.core.thing.internal.ThingManager] - 'org.openhab.binding.zwave' still vetoed by '[org.eclipse.smarthome.config.xml.osgi.XmlDocumentBundleTracker$1@445ff462(/ESH-INF/thing/)]'
14:37:05.313 [DEBUG] [ome.core.thing.internal.ThingManager] - 'org.openhab.binding.zwave' queued '[org.openhab.binding.zwave.handler.ZWaveThingHandler@6f00219f, org.openhab.binding.zwave.handler.ZWaveSerialHandler@2a02a21b]'
kgoderis commented 8 years ago

@kaikreuzer @maggu2810 @cdjackson I was away on holidays, just upgraded the runtime here, and ran in the same problems. My findings are:

  1. I see a lot of errors similar to

[ome.core.thing.internal.ThingManager] - Meta-data of bundle 'org.openhab.binding.systeminfo' is not fully loaded ([org.eclipse.smarthome.config.xml.osgi.XmlDocumentBundleTracker$1@4dd96849(/ESH-INF/thing/), org.eclipse.smarthome.config.xml.osgi.XmlDocumentBundleTracker$1@779b2abf(/ESH-INF/config/), org.eclipse.smarthome.config.xml.osgi.XmlDocumentBundleTracker$1@3e3645fd(/ESH-INF/binding/)]), deferring handler initialization for thing 'systeminfo:computer:work'

after which the thing is either initialised, or either not. It is random behaviour, and seems to be linked to a timing issue (e.g. workload issue). I do have a lot of bindings, and some with '00's of Things. They tend to take a while to get processed, and have an effect on the overall environment

  1. When the issue gets "resolved", there are some lines like:
2016-08-23 21:06:20.178 [DEBUG] [ome.core.thing.internal.ThingManager] - 'org.openhab.binding.systeminfo' still vetoed by '[org.eclipse.smarthome.config.xml.osgi.XmlDocumentBundleTracker$1@4dd96849(/ESH-INF/thing/)]'
2016-08-23 21:06:20.183 [DEBUG] [ome.core.thing.internal.ThingManager] - 'org.openhab.binding.systeminfo' queued '[org.openhab.binding.systeminfo.handler.SysteminfoHandler@1ea54d9d, org.openhab.binding.systeminfo.handler.SysteminfoHandler@62b1f856]'
2016-08-23 21:06:20.183 [DEBUG] [ome.core.thing.internal.ThingManager] - 'org.openhab.binding.systeminfo' queued '[org.openhab.binding.systeminfo.handler.SysteminfoHandler@1ea54d9d, org.openhab.binding.systeminfo.handler.SysteminfoHandler@62b1f856]'

and then life goes on normally.

  1. The issue can be resolved by doing a "bundle:restart" on the offending bundle
  2. It happens at random, and mostly on my "small" bindings, e.g. the ones starting up "interleaved" with some "big" bindings going through massive amounts of handler initialisations. Systeminfo is always impacted, strongly enough. Does that have to do with start-levels?
  3. I often see lines related to XmlDocumentBundleTracker
  4. A new problem I see is with the KNX 2.0 binding. That binding defines a number of dynamic channels in the ESH-INF/*.xml. When declaring these kind of channels on a Thing through the DSL, then randomly at startup these channels are NOT created and added to the Thing (only the pre-defined "fixed" channels are), and sometimes they get added correctly. Again, random and hard to reproduce
  5. The problems only occur with Karaf, not in the IDE
maggu2810 commented 8 years ago

@kgoderis I assume I don't understand the problem. The "deferring handler initialization" is no error itself, it is only a log message that the XML files are not fully processed yet and the handler initialization will be done later.

Do you want to say, that the handler initialization not done at all?

maggu2810 commented 8 years ago

I think we should split your problem. "Deferred Handler initialization" and "missing dynamic channels". (I replied to the first one above)

kgoderis commented 8 years ago

Do you want to say, that the handler initialization not done at all?

is it initialised, but part of the channels as defined in the XML are not added to the Thing. I have created https://github.com/eclipse/smarthome/issues/2042

cdjackson commented 8 years ago

This all works ok in the zwave binding. Karel - have you changed the definition to add new channels to the XML? If so, they won’t be added unless you delete the thing and add it again (at this stage anyway - I think there’s moves to change this with the thing migration service).

kgoderis commented 8 years ago

@cdjackson Did a bundle:restart a few times. Will try your suggestion.

err... openhab> things remove knx:ip:ip1 Could not delete thing knx:ip:ip1.

guess that is a no no

kgoderis commented 8 years ago

@cdjackson Not sure what you mean by "adding" in this context (@ runtime?), but cold starting the runtime generates the problem, with the correct definition in place.

cdjackson commented 8 years ago

By ‘adding’ I meant to recreate the thing so that it re-read all the definitions. If the correct definition is already in place then it’s probably broken.

kgoderis commented 8 years ago

@kaikreuzer @maggu2810 shall we continue in this thread, or open an new issue? the issue of some bindings not initiliazing is still there

kaikreuzer commented 8 years ago

I'd suggest to first review and merge https://github.com/eclipse/smarthome/pull/2087 as this is anyhow changing a lot of the underlying infrastructure.

maggu2810 commented 8 years ago

@kgoderis Is it okay for you to create a new one after #2087 has been merged?

kgoderis commented 8 years ago

ok