eclipse-archived / smarthome

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

[startup] IllegalArgumentException: XmlConfigDescriptionProvider must not be null #6534

Closed mhilbush closed 5 years ago

mhilbush commented 5 years ago

I see this occasionally at system startup. I get one of these exceptions for every thing type defined across all the bindings installed in my system (which is somewhere near 1000 thing types, most of which come from zwave).

It doesn't happen all the time, so I suspect it's a timing issue related to order of startup. I'd estimate it happens maybe 30-40% of the time. It doesn't seem to have any adverse effect on system operation.

I'm running OH build 1431, which includes ESH build 316. However, I've been seeing this for a while, so it's not new in this build.

There was a similar issue logged back in May, but the problem still occurs. https://github.com/eclipse/smarthome/issues/5616

2018-11-18 07:52:17.576 [WARN ] [ig.xml.osgi.XmlDocumentBundleTracker] - The XML document '/ESH-INF/thing/sun.xml' in module 'org.eclipse.smarthome.binding.astro' could not be parsed: The XmlConfigDescriptionProvider must not be null!
java.lang.IllegalArgumentException: The XmlConfigDescriptionProvider must not be null!
    at org.eclipse.smarthome.core.thing.xml.internal.ThingTypeXmlProvider.<init>(ThingTypeXmlProvider.java:81) ~[?:?]
    at org.eclipse.smarthome.core.thing.xml.internal.XmlThingTypeProvider.createDocumentProvider(XmlThingTypeProvider.java:163) ~[?:?]
    at org.eclipse.smarthome.config.xml.osgi.XmlDocumentBundleTracker.acquireXmlDocumentProvider(XmlDocumentBundleTracker.java:180) ~[100:org.eclipse.smarthome.config.xml:0.10.0.201811171951]
    at org.eclipse.smarthome.config.xml.osgi.XmlDocumentBundleTracker.addingObject(XmlDocumentBundleTracker.java:205) ~[100:org.eclipse.smarthome.config.xml:0.10.0.201811171951]
    at org.eclipse.smarthome.config.xml.osgi.XmlDocumentBundleTracker.parseDocuments(XmlDocumentBundleTracker.java:351) [100:org.eclipse.smarthome.config.xml:0.10.0.201811171951]
    at org.eclipse.smarthome.config.xml.osgi.XmlDocumentBundleTracker.processBundle(XmlDocumentBundleTracker.java:337) [100:org.eclipse.smarthome.config.xml:0.10.0.201811171951]
    at org.eclipse.smarthome.config.xml.osgi.XmlDocumentBundleTracker.access$4(XmlDocumentBundleTracker.java:332) [100:org.eclipse.smarthome.config.xml:0.10.0.201811171951]
    at org.eclipse.smarthome.config.xml.osgi.XmlDocumentBundleTracker$2.run(XmlDocumentBundleTracker.java:307) [100:org.eclipse.smarthome.config.xml:0.10.0.201811171951]
    at java.util.concurrent.Executors$RunnableAdapter.call(Executors.java:511) [?:?]
    at java.util.concurrent.FutureTask.run(FutureTask.java:266) [?:?]
    at java.util.concurrent.ScheduledThreadPoolExecutor$ScheduledFutureTask.access$201(ScheduledThreadPoolExecutor.java:180) [?:?]
    at java.util.concurrent.ScheduledThreadPoolExecutor$ScheduledFutureTask.run(ScheduledThreadPoolExecutor.java:293) [?:?]
    at java.util.concurrent.ThreadPoolExecutor.runWorker(ThreadPoolExecutor.java:1149) [?:?]
    at java.util.concurrent.ThreadPoolExecutor$Worker.run(ThreadPoolExecutor.java:624) [?:?]
    at java.lang.Thread.run(Thread.java:748) [?:?]
maggu2810 commented 5 years ago

The #5617 makes reduces the exception by checking the marker variable "open" in front of asynchronous job execution. It is still possible that the instance is "closed" while the asynchronous job is executed. I assume this is the case on your system. You should add some logging statements to track it down. But the question is how it should be solved.

There is one change that should be applied first: call clearQueue as soon as possible in the close method (the next statement after open is set to false). This will ensure the futures are canceled in front of removing stuff.

After that the run() method -- so the asynchronous execution -- should be modified. Catch the exception and check if the component is still open. If it is not open anymore, there is nothing to do at all. We could perhaps hide the exception. If open is still true, re-throw the exception

maggu2810 commented 5 years ago

@mhilbush Let's give it another try: org.eclipse.smarthome.config.xml-0.10.0-SNAPSHOT.jar

mhilbush commented 5 years ago

Working on it now.

mhilbush commented 5 years ago

Unfortunately, this didn't resolve it either.

Running today's version.

261 x Active   x  80 x 0.10.0.201811262013    x org.eclipse.smarthome.config.xml

Sample from log file (with org.eclipse.smarthome.config.xml in DEBUG mode).

2018-11-26 16:15:28.020 [DEBUG] [ig.xml.osgi.XmlDocumentBundleTracker] - Reading the XML document '/ESH-INF/binding/binding.xml' in module 'org.eclipse.smarthome.binding.astro'...
2018-11-26 16:15:28.021 [DEBUG] [ig.xml.osgi.XmlDocumentBundleTracker] - Reading the XML document '/ESH-INF/binding/binding.xml' in module 'org.openhab.binding.zwave'...
2018-11-26 16:15:28.263 [DEBUG] [ig.xml.osgi.XmlDocumentBundleTracker] - Reading the XML document '/ESH-INF/thing/sun.xml' in module 'org.eclipse.smarthome.binding.astro'...
2018-11-26 16:15:28.281 [WARN ] [ig.xml.osgi.XmlDocumentBundleTracker] - The XML document '/ESH-INF/thing/sun.xml' in module 'org.eclipse.smarthome.binding.astro' could not be parsed: The XmlConfigDescriptionProvider must not be null!
java.lang.IllegalArgumentException: The XmlConfigDescriptionProvider must not be null!
    at org.eclipse.smarthome.core.thing.xml.internal.ThingTypeXmlProvider.<init>(ThingTypeXmlProvider.java:81) ~[?:?]
    at org.eclipse.smarthome.core.thing.xml.internal.XmlThingTypeProvider.createDocumentProvider(XmlThingTypeProvider.java:163) ~[?:?]
    at org.eclipse.smarthome.config.xml.osgi.XmlDocumentBundleTracker.acquireXmlDocumentProvider(XmlDocumentBundleTracker.java:199) ~[261:org.eclipse.smarthome.config.xml:0.10.0.201811262013]
    at org.eclipse.smarthome.config.xml.osgi.XmlDocumentBundleTracker.addingObject(XmlDocumentBundleTracker.java:224) ~[261:org.eclipse.smarthome.config.xml:0.10.0.201811262013]
    at org.eclipse.smarthome.config.xml.osgi.XmlDocumentBundleTracker.parseDocuments(XmlDocumentBundleTracker.java:388) [261:org.eclipse.smarthome.config.xml:0.10.0.201811262013]
    at org.eclipse.smarthome.config.xml.osgi.XmlDocumentBundleTracker.processBundle(XmlDocumentBundleTracker.java:374) [261:org.eclipse.smarthome.config.xml:0.10.0.201811262013]
    at org.eclipse.smarthome.config.xml.osgi.XmlDocumentBundleTracker.access$5(XmlDocumentBundleTracker.java:369) [261:org.eclipse.smarthome.config.xml:0.10.0.201811262013]
    at org.eclipse.smarthome.config.xml.osgi.XmlDocumentBundleTracker$2.run(XmlDocumentBundleTracker.java:337) [261:org.eclipse.smarthome.config.xml:0.10.0.201811262013]
    at java.util.concurrent.Executors$RunnableAdapter.call(Executors.java:511) [?:?]
    at java.util.concurrent.FutureTask.run(FutureTask.java:266) [?:?]
    at java.util.concurrent.ScheduledThreadPoolExecutor$ScheduledFutureTask.access$201(ScheduledThreadPoolExecutor.java:180) [?:?]
    at java.util.concurrent.ScheduledThreadPoolExecutor$ScheduledFutureTask.run(ScheduledThreadPoolExecutor.java:293) [?:?]
    at java.util.concurrent.ThreadPoolExecutor.runWorker(ThreadPoolExecutor.java:1149) [?:?]
    at java.util.concurrent.ThreadPoolExecutor$Worker.run(ThreadPoolExecutor.java:624) [?:?]
    at java.lang.Thread.run(Thread.java:748) [?:?]
2018-11-26 16:15:28.287 [DEBUG] [ig.xml.osgi.XmlDocumentBundleTracker] - Reading the XML document '/ESH-INF/thing/moon.xml' in module 'org.eclipse.smarthome.binding.astro'...
2018-11-26 16:15:28.292 [DEBUG] [ig.xml.osgi.XmlDocumentBundleTracker] - Reading the XML document '/ESH-INF/thing/aeotec/zwa005_0_0.xml' in module 'org.openhab.binding.zwave'...
2018-11-26 16:15:28.301 [WARN ] [ig.xml.osgi.XmlDocumentBundleTracker] - The XML document '/ESH-INF/thing/moon.xml' in module 'org.eclipse.smarthome.binding.astro' could not be parsed: The XmlConfigDescriptionProvider must not be null!
java.lang.IllegalArgumentException: The XmlConfigDescriptionProvider must not be null!
    at org.eclipse.smarthome.core.thing.xml.internal.ThingTypeXmlProvider.<init>(ThingTypeXmlProvider.java:81) ~[?:?]
    at org.eclipse.smarthome.core.thing.xml.internal.XmlThingTypeProvider.createDocumentProvider(XmlThingTypeProvider.java:163) ~[?:?]
    at org.eclipse.smarthome.config.xml.osgi.XmlDocumentBundleTracker.acquireXmlDocumentProvider(XmlDocumentBundleTracker.java:199) ~[261:org.eclipse.smarthome.config.xml:0.10.0.201811262013]
    at org.eclipse.smarthome.config.xml.osgi.XmlDocumentBundleTracker.addingObject(XmlDocumentBundleTracker.java:224) ~[261:org.eclipse.smarthome.config.xml:0.10.0.201811262013]
    at org.eclipse.smarthome.config.xml.osgi.XmlDocumentBundleTracker.parseDocuments(XmlDocumentBundleTracker.java:388) [261:org.eclipse.smarthome.config.xml:0.10.0.201811262013]
    at org.eclipse.smarthome.config.xml.osgi.XmlDocumentBundleTracker.processBundle(XmlDocumentBundleTracker.java:374) [261:org.eclipse.smarthome.config.xml:0.10.0.201811262013]
    at org.eclipse.smarthome.config.xml.osgi.XmlDocumentBundleTracker.access$5(XmlDocumentBundleTracker.java:369) [261:org.eclipse.smarthome.config.xml:0.10.0.201811262013]
    at org.eclipse.smarthome.config.xml.osgi.XmlDocumentBundleTracker$2.run(XmlDocumentBundleTracker.java:337) [261:org.eclipse.smarthome.config.xml:0.10.0.201811262013]
    at java.util.concurrent.Executors$RunnableAdapter.call(Executors.java:511) [?:?]
    at java.util.concurrent.FutureTask.run(FutureTask.java:266) [?:?]
    at java.util.concurrent.ScheduledThreadPoolExecutor$ScheduledFutureTask.access$201(ScheduledThreadPoolExecutor.java:180) [?:?]
    at java.util.concurrent.ScheduledThreadPoolExecutor$ScheduledFutureTask.run(ScheduledThreadPoolExecutor.java:293) [?:?]
    at java.util.concurrent.ThreadPoolExecutor.runWorker(ThreadPoolExecutor.java:1149) [?:?]
    at java.util.concurrent.ThreadPoolExecutor$Worker.run(ThreadPoolExecutor.java:624) [?:?]
    at java.lang.Thread.run(Thread.java:748) [?:?]
maggu2810 commented 5 years ago

There is the interface XmlDocumentProviderFactory.

It provides the method XmlDocumentProvider<T> createDocumentProvider(Bundle bundle)

There are three components that implement that interface:

There is also a class XmlDocumentBundleTracker (org.eclipse.smarthome.config.xml.osgi.XmlDocumentBundleTracker).

Class instances are created at the different places - all the time in the activate method of the correspondent service:

So, the XmlDocumentBundleTracker instances are created by that components.

The XmlDocumentBundleTracker takes an argument of type XmlDocumentProviderFactory<T> on its construction.

All components are using "this" on instance creation.

After the creation of the provider factory every component schedule a call to XmlDocumentProviderFactory::open (so still in its activate method).

If the components are deactivated (method deactivate is called), an enqueued call to open is canceled and XmlDocumentProviderFactory::close is called.

The XmlBindingInfoProvider uses a mandatory reference:

@Reference(target = "(esh.scope=core.xml.binding)")
public void setConfigDescriptionProvider(ConfigDescriptionProvider configDescriptionProvider) {
    this.configDescriptionProvider = (AbstractXmlConfigDescriptionProvider) configDescriptionProvider;
}

public void unsetConfigDescriptionProvider(ConfigDescriptionProvider configDescriptionProvider) {
    this.configDescriptionProvider = null;
}

The XmlThingTypeProvider is using a mandatory reference:

@Reference(target = "(esh.scope=core.xml.thing)")
public void setConfigDescriptionProvider(ConfigDescriptionProvider configDescriptionProvider) {
    this.configDescriptionProvider = (AbstractXmlConfigDescriptionProvider) configDescriptionProvider;
}

public void unsetConfigDescriptionProvider(ConfigDescriptionProvider configDescriptionProvider) {
    this.configDescriptionProvider = null;
}

As long as the respective provider is active the reference should be non null.

The exception you see in your log is caused the the following method of the XmlBindingInfoProvider

@Override
public XmlDocumentProvider<BindingInfoXmlResult> createDocumentProvider(Bundle bundle) {
    return new BindingInfoXmlProvider(bundle, this, configDescriptionProvider);
}

As long as this method is called for an activated component the configDescriptionProvider must not be null.

If configDescriptionProvider is null, the XmlBindingInfoProvider must not be active.

The job to call this method is scheduled by correspondent XmlDocumentBundleTracker instance and called asynchron. So, it could be the case that it is called and configDescriptionProvider is null and so XmlBindingInfoProvider is not active. But ...

If XmlBindingInfoProvider gets deactivated, XmlDocumentBundleTracker::close is called. The current handling of XmlDocumentBundleTracker::close and the current execution of the job should drop most of the queued calls and log nothing on an exception.

I assume we need to add further logging instructions to detect what is going wrong. Are you willing to test further bundles if I add more logging instructions?

maggu2810 commented 5 years ago

I added debug statements only. You need to update the following two bundles:

There should be output like this:

23:08:53.438 INFO [features-3-thread-1] XmlBindingInfoProvider::setConfigDescriptionProvider: me: 1989387283, thread: 61199879, configDescriptionProvider: 278442913
23:08:53.439 INFO [features-3-thread-1] XmlBindingInfoProvider::activate: me: 1989387283, thread: 61199879, configDescriptionProvider: 278442913
23:08:53.442 INFO [features-3-thread-1] XmlDocumentBundleTracker::new: me: 1914911759, thread: 61199879, xmlDocumentProviderFactory: 1989387283
23:08:53.444 INFO [ESH-file-processing-3] XmlDocumentBundleTracker::open: me: 1914911759, thread: 1996251119, xmlDocumentProviderFactory: 1989387283, openState: CREATED
23:08:53.444 INFO [features-3-thread-1] XmlBindingInfoProvider::deactivate: me: 1989387283, thread: 61199879, configDescriptionProvider: 278442913
23:08:53.455 INFO [features-3-thread-1] XmlDocumentBundleTracker::close: me: 1914911759, thread: 61199879, xmlDocumentProviderFactory: 1989387283, openState: OPENED
23:08:53.460 INFO [features-3-thread-1] XmlBindingInfoProvider::unsetConfigDescriptionProvider: me: 1989387283, thread: 61199879, configDescriptionProvider: 278442913
23:08:53.466 INFO [features-3-thread-1] XmlBindingInfoProvider::setConfigDescriptionProvider: me: 581537140, thread: 61199879, configDescriptionProvider: 278442913
23:08:53.469 INFO [features-3-thread-1] XmlBindingInfoProvider::activate: me: 581537140, thread: 61199879, configDescriptionProvider: 278442913
23:08:53.475 INFO [features-3-thread-1] XmlDocumentBundleTracker::new: me: 157827675, thread: 61199879, xmlDocumentProviderFactory: 581537140
23:08:53.477 INFO [ESH-file-processing-2] XmlDocumentBundleTracker::open: me: 157827675, thread: 1336988088, xmlDocumentProviderFactory: 581537140, openState: CREATED
mhilbush commented 5 years ago

I'll test with these new bundles later tonight.

mhilbush commented 5 years ago

I have not seen the problem yet, but wanted to make one observation. I'm not saying this is a problem, but I thought it worth noting.

262 x Active   x  80 x 0.10.0.201811262207    x org.eclipse.smarthome.config.xml
263 x Active   x  80 x 0.10.0.201811262207    x org.eclipse.smarthome.core.binding.xml

Sometimes at startup, I see this sequence of new-open (case 1a)

2018-11-26 18:58:18.399 [INFO ] [ig.xml.osgi.XmlDocumentBundleTracker] - XmlDocumentBundleTracker::new: me: 1056995797, thread: 1728422182, xmlDocumentProviderFactory: 1923037370
2018-11-26 18:58:18.400 [INFO ] [ig.xml.osgi.XmlDocumentBundleTracker] - XmlDocumentBundleTracker::open: me: 1056995797, thread: 38338574, xmlDocumentProviderFactory: 1923037370, openState: CREATED

While other times I see this sequence of new-open-close-new-open (case 1b)

2018-11-26 18:52:20.921 [INFO ] [ig.xml.osgi.XmlDocumentBundleTracker] - XmlDocumentBundleTracker::new: me: 203860176, thread: 783520647, xmlDocumentProviderFactory: 756591071
2018-11-26 18:52:20.923 [INFO ] [ig.xml.osgi.XmlDocumentBundleTracker] - XmlDocumentBundleTracker::open: me: 203860176, thread: 1405892578, xmlDocumentProviderFactory: 756591071, openState: CREATED
2018-11-26 18:52:21.006 [INFO ] [ig.xml.osgi.XmlDocumentBundleTracker] - XmlDocumentBundleTracker::close: me: 203860176, thread: 783520647, xmlDocumentProviderFactory: 756591071, openState: OPENED
2018-11-26 18:52:21.012 [INFO ] [ig.xml.osgi.XmlDocumentBundleTracker] - XmlDocumentBundleTracker::new: me: 187905372, thread: 783520647, xmlDocumentProviderFactory: 1322933092
2018-11-26 18:52:21.015 [INFO ] [ig.xml.osgi.XmlDocumentBundleTracker] - XmlDocumentBundleTracker::open: me: 187905372, thread: 1264585951, xmlDocumentProviderFactory: 1322933092, openState: CREATED

Then slightly later in the log, I see this sequence (case 2a)

2018-11-26 18:58:25.855 [INFO ] [ig.xml.osgi.XmlDocumentBundleTracker] - XmlDocumentBundleTracker::new: me: 573948206, thread: 1728422182, xmlDocumentProviderFactory: 185029054
2018-11-26 18:58:25.857 [INFO ] [ig.xml.osgi.XmlDocumentBundleTracker] - XmlDocumentBundleTracker::open: me: 573948206, thread: 38338574, xmlDocumentProviderFactory: 185029054, openState: CREATED
2018-11-26 18:58:25.884 [INFO ] [.xml.internal.XmlBindingInfoProvider] - XmlBindingInfoProvider::setConfigDescriptionProvider: me: 191895185, thread: 1728422182, configDescriptionProvider: 1448587391
2018-11-26 18:58:25.885 [INFO ] [.xml.internal.XmlBindingInfoProvider] - XmlBindingInfoProvider::activate: me: 191895185, thread: 1728422182, configDescriptionProvider: 1448587391
2018-11-26 18:58:25.897 [INFO ] [ig.xml.osgi.XmlDocumentBundleTracker] - XmlDocumentBundleTracker::new: me: 1270737133, thread: 1728422182, xmlDocumentProviderFactory: 191895185
2018-11-26 18:58:25.899 [INFO ] [ig.xml.osgi.XmlDocumentBundleTracker] - XmlDocumentBundleTracker::open: me: 1270737133, thread: 762660807, xmlDocumentProviderFactory: 191895185, openState: CREATED
2018-11-26 18:58:25.984 [INFO ] [.xml.internal.XmlBindingInfoProvider] - XmlBindingInfoProvider::createDocumentProvider: me: 191895185, thread: 38338574, configDescriptionProvider: 1448587391
2018-11-26 18:58:25.986 [INFO ] [.xml.internal.XmlBindingInfoProvider] - XmlBindingInfoProvider::createDocumentProvider: me: 191895185, thread: 762660807, configDescriptionProvider: 1448587391
2018-11-26 18:58:25.988 [INFO ] [.xml.internal.XmlBindingInfoProvider] - XmlBindingInfoProvider::createDocumentProvider: me: 191895185, thread: 1646163038, configDescriptionProvider: 1448587391
2018-11-26 18:58:25.992 [INFO ] [.xml.internal.XmlBindingInfoProvider] - XmlBindingInfoProvider::createDocumentProvider: me: 191895185, thread: 715990576, configDescriptionProvider: 1448587391

or this sequence: (case 2b)

2018-11-26 18:52:28.470 [INFO ] [ig.xml.osgi.XmlDocumentBundleTracker] - XmlDocumentBundleTracker::new: me: 2078264409, thread: 783520647, xmlDocumentProviderFactory: 483300021
2018-11-26 18:52:28.472 [INFO ] [ig.xml.osgi.XmlDocumentBundleTracker] - XmlDocumentBundleTracker::open: me: 2078264409, thread: 1299652359, xmlDocumentProviderFactory: 483300021, openState: CREATED
2018-11-26 18:52:28.491 [INFO ] [.xml.internal.XmlBindingInfoProvider] - XmlBindingInfoProvider::setConfigDescriptionProvider: me: 1287539442, thread: 783520647, configDescriptionProvider: 1089210455
2018-11-26 18:52:28.492 [INFO ] [.xml.internal.XmlBindingInfoProvider] - XmlBindingInfoProvider::activate: me: 1287539442, thread: 783520647, configDescriptionProvider: 1089210455
2018-11-26 18:52:28.495 [INFO ] [ig.xml.osgi.XmlDocumentBundleTracker] - XmlDocumentBundleTracker::new: me: 578130779, thread: 783520647, xmlDocumentProviderFactory: 1287539442
2018-11-26 18:52:28.496 [INFO ] [ig.xml.osgi.XmlDocumentBundleTracker] - XmlDocumentBundleTracker::open: me: 578130779, thread: 1264585951, xmlDocumentProviderFactory: 1287539442, openState: CREATED
2018-11-26 18:52:28.496 [INFO ] [.xml.internal.XmlBindingInfoProvider] - XmlBindingInfoProvider::deactivate: me: 1287539442, thread: 783520647, configDescriptionProvider: 1089210455
2018-11-26 18:52:28.559 [INFO ] [ig.xml.osgi.XmlDocumentBundleTracker] - XmlDocumentBundleTracker::close: me: 578130779, thread: 783520647, xmlDocumentProviderFactory: 1287539442, openState: OPENED
2018-11-26 18:52:28.563 [INFO ] [.xml.internal.XmlBindingInfoProvider] - XmlBindingInfoProvider::unsetConfigDescriptionProvider: me: 1287539442, thread: 783520647, configDescriptionProvider: 1089210455
2018-11-26 18:52:28.564 [INFO ] [.xml.internal.XmlBindingInfoProvider] - XmlBindingInfoProvider::setConfigDescriptionProvider: me: 1921020412, thread: 783520647, configDescriptionProvider: 1089210455
2018-11-26 18:52:28.564 [INFO ] [.xml.internal.XmlBindingInfoProvider] - XmlBindingInfoProvider::activate: me: 1921020412, thread: 783520647, configDescriptionProvider: 1089210455
2018-11-26 18:52:28.566 [INFO ] [ig.xml.osgi.XmlDocumentBundleTracker] - XmlDocumentBundleTracker::new: me: 832054501, thread: 783520647, xmlDocumentProviderFactory: 1921020412
2018-11-26 18:52:28.573 [INFO ] [ig.xml.osgi.XmlDocumentBundleTracker] - XmlDocumentBundleTracker::open: me: 832054501, thread: 1405892578, xmlDocumentProviderFactory: 1921020412, openState: CREATED
2018-11-26 18:52:28.639 [INFO ] [.xml.internal.XmlBindingInfoProvider] - XmlBindingInfoProvider::createDocumentProvider: me: 1921020412, thread: 1405892578, configDescriptionProvider: 1089210455
2018-11-26 18:52:28.648 [INFO ] [.xml.internal.XmlBindingInfoProvider] - XmlBindingInfoProvider::createDocumentProvider: me: 1921020412, thread: 1299652359, configDescriptionProvider: 1089210455
2018-11-26 18:52:28.648 [INFO ] [.xml.internal.XmlBindingInfoProvider] - XmlBindingInfoProvider::createDocumentProvider: me: 1921020412, thread: 1264585951, configDescriptionProvider: 1089210455
2018-11-26 18:52:28.649 [INFO ] [.xml.internal.XmlBindingInfoProvider] - XmlBindingInfoProvider::createDocumentProvider: me: 1921020412, thread: 2019760538, configDescriptionProvider: 1089210455

Again, in both cases, I don't see the exceptions at startup.

Back to testing...

mhilbush commented 5 years ago

And here's what's logged when the problem occurs.

Similar sequence as case 1b above, but the ordering of the threads are different.

It must be a very subtle timing issue, because I had to restart 19 times before the problem occurred. It seems that the changes you made previously (not this version because it's just additional debug) have reduced the frequency of occurrence. Before those changes I was seeing the problem 30-40 percent of the time.

2018-11-26 19:43:42.905 [INFO ] [ashboard.internal.HABotDashboardTile] - Started HABot at /habot
2018-11-26 19:43:42.940 [INFO ] [panel.internal.HABPanelDashboardTile] - Started HABPanel at /habpanel
2018-11-26 19:43:42.945 [INFO ] [.core.internal.i18n.I18nProviderImpl] - Time zone set to 'US/Eastern'.
2018-11-26 19:43:42.947 [INFO ] [.core.internal.i18n.I18nProviderImpl] - Location set to 'XXXXXXXXX'.
2018-11-26 19:43:42.948 [INFO ] [.core.internal.i18n.I18nProviderImpl] - Locale set to 'en_US'.
2018-11-26 19:43:43.398 [INFO ] [ig.xml.osgi.XmlDocumentBundleTracker] - XmlDocumentBundleTracker::new: me: 203860176, thread: 1876409947, xmlDocumentProviderFactory: 756591071
2018-11-26 19:43:43.400 [INFO ] [ig.xml.osgi.XmlDocumentBundleTracker] - XmlDocumentBundleTracker::open: me: 203860176, thread: 1075796975, xmlDocumentProviderFactory: 756591071, openState: CREATED
2018-11-26 19:43:43.470 [INFO ] [ig.xml.osgi.XmlDocumentBundleTracker] - XmlDocumentBundleTracker::close: me: 203860176, thread: 1876409947, xmlDocumentProviderFactory: 756591071, openState: OPENED
2018-11-26 19:43:43.478 [INFO ] [ig.xml.osgi.XmlDocumentBundleTracker] - XmlDocumentBundleTracker::new: me: 187905372, thread: 1876409947, xmlDocumentProviderFactory: 1322933092
2018-11-26 19:43:43.479 [INFO ] [ig.xml.osgi.XmlDocumentBundleTracker] - XmlDocumentBundleTracker::open: me: 187905372, thread: 1075796975, xmlDocumentProviderFactory: 1322933092, openState: CREATED
2018-11-26 19:43:43.491 [WARN ] [ig.xml.osgi.XmlDocumentBundleTracker] - The XML document '/ESH-INF/thing/sun.xml' in module 'org.eclipse.smarthome.binding.astro' could not be parsed: The XmlConfigDescriptionProvider must not be null!
java.lang.IllegalArgumentException: The XmlConfigDescriptionProvider must not be null!
    at org.eclipse.smarthome.core.thing.xml.internal.ThingTypeXmlProvider.<init>(ThingTypeXmlProvider.java:81) ~[?:?]
    at org.eclipse.smarthome.core.thing.xml.internal.XmlThingTypeProvider.createDocumentProvider(XmlThingTypeProvider.java:163) ~[?:?]
    at org.eclipse.smarthome.config.xml.osgi.XmlDocumentBundleTracker.acquireXmlDocumentProvider(XmlDocumentBundleTracker.java:213) ~[262:org.eclipse.smarthome.config.xml:0.10.0.201811262207]
    at org.eclipse.smarthome.config.xml.osgi.XmlDocumentBundleTracker.addingObject(XmlDocumentBundleTracker.java:238) ~[262:org.eclipse.smarthome.config.xml:0.10.0.201811262207]
    at org.eclipse.smarthome.config.xml.osgi.XmlDocumentBundleTracker.parseDocuments(XmlDocumentBundleTracker.java:407) [262:org.eclipse.smarthome.config.xml:0.10.0.201811262207]
    at org.eclipse.smarthome.config.xml.osgi.XmlDocumentBundleTracker.processBundle(XmlDocumentBundleTracker.java:393) [262:org.eclipse.smarthome.config.xml:0.10.0.201811262207]
    at org.eclipse.smarthome.config.xml.osgi.XmlDocumentBundleTracker.access$5(XmlDocumentBundleTracker.java:388) [262:org.eclipse.smarthome.config.xml:0.10.0.201811262207]
    at org.eclipse.smarthome.config.xml.osgi.XmlDocumentBundleTracker$2.run(XmlDocumentBundleTracker.java:351) [262:org.eclipse.smarthome.config.xml:0.10.0.201811262207]
    at java.util.concurrent.Executors$RunnableAdapter.call(Executors.java:511) [?:?]
    at java.util.concurrent.FutureTask.run(FutureTask.java:266) [?:?]
    at java.util.concurrent.ScheduledThreadPoolExecutor$ScheduledFutureTask.access$201(ScheduledThreadPoolExecutor.java:180) [?:?]
    at java.util.concurrent.ScheduledThreadPoolExecutor$ScheduledFutureTask.run(ScheduledThreadPoolExecutor.java:293) [?:?]
    at java.util.concurrent.ThreadPoolExecutor.runWorker(ThreadPoolExecutor.java:1149) [?:?]
    at java.util.concurrent.ThreadPoolExecutor$Worker.run(ThreadPoolExecutor.java:624) [?:?]
    at java.lang.Thread.run(Thread.java:748) [?:?]
2018-11-26 19:43:43.500 [WARN ] [ig.xml.osgi.XmlDocumentBundleTracker] - The XML document '/ESH-INF/thing/moon.xml' in module 'org.eclipse.smarthome.binding.astro' could not be parsed: The XmlConfigDescriptionProvider must not be null!
java.lang.IllegalArgumentException: The XmlConfigDescriptionProvider must not be null!
    at org.eclipse.smarthome.core.thing.xml.internal.ThingTypeXmlProvider.<init>(ThingTypeXmlProvider.java:81) ~[?:?]
    at org.eclipse.smarthome.core.thing.xml.internal.XmlThingTypeProvider.createDocumentProvider(XmlThingTypeProvider.java:163) ~[?:?]
    at org.eclipse.smarthome.config.xml.osgi.XmlDocumentBundleTracker.acquireXmlDocumentProvider(XmlDocumentBundleTracker.java:213) ~[262:org.eclipse.smarthome.config.xml:0.10.0.201811262207]
    at org.eclipse.smarthome.config.xml.osgi.XmlDocumentBundleTracker.addingObject(XmlDocumentBundleTracker.java:238) ~[262:org.eclipse.smarthome.config.xml:0.10.0.201811262207]
    at org.eclipse.smarthome.config.xml.osgi.XmlDocumentBundleTracker.parseDocuments(XmlDocumentBundleTracker.java:407) [262:org.eclipse.smarthome.config.xml:0.10.0.201811262207]
    at org.eclipse.smarthome.config.xml.osgi.XmlDocumentBundleTracker.processBundle(XmlDocumentBundleTracker.java:393) [262:org.eclipse.smarthome.config.xml:0.10.0.201811262207]
    at org.eclipse.smarthome.config.xml.osgi.XmlDocumentBundleTracker.access$5(XmlDocumentBundleTracker.java:388) [262:org.eclipse.smarthome.config.xml:0.10.0.201811262207]
    at org.eclipse.smarthome.config.xml.osgi.XmlDocumentBundleTracker$2.run(XmlDocumentBundleTracker.java:351) [262:org.eclipse.smarthome.config.xml:0.10.0.201811262207]
    at java.util.concurrent.Executors$RunnableAdapter.call(Executors.java:511) [?:?]
    at java.util.concurrent.FutureTask.run(FutureTask.java:266) [?:?]
    at java.util.concurrent.ScheduledThreadPoolExecutor$ScheduledFutureTask.access$201(ScheduledThreadPoolExecutor.java:180) [?:?]
    at java.util.concurrent.ScheduledThreadPoolExecutor$ScheduledFutureTask.run(ScheduledThreadPoolExecutor.java:293) [?:?]
    at java.util.concurrent.ThreadPoolExecutor.runWorker(ThreadPoolExecutor.java:1149) [?:?]
    at java.util.concurrent.ThreadPoolExecutor$Worker.run(ThreadPoolExecutor.java:624) [?:?]
    at java.lang.Thread.run(Thread.java:748) [?:?]
mhilbush commented 5 years ago

Successful

2018-11-26 18:52:20.921 [INFO ] [ig.xml.osgi.XmlDocumentBundleTracker] - XmlDocumentBundleTracker::new: me: 203860176, thread: 783520647, xmlDocumentProviderFactory: 756591071
2018-11-26 18:52:20.923 [INFO ] [ig.xml.osgi.XmlDocumentBundleTracker] - XmlDocumentBundleTracker::open: me: 203860176, thread: 1405892578, xmlDocumentProviderFactory: 756591071, openState: CREATED
2018-11-26 18:52:21.006 [INFO ] [ig.xml.osgi.XmlDocumentBundleTracker] - XmlDocumentBundleTracker::close: me: 203860176, thread: 783520647, xmlDocumentProviderFactory: 756591071, openState: OPENED
2018-11-26 18:52:21.012 [INFO ] [ig.xml.osgi.XmlDocumentBundleTracker] - XmlDocumentBundleTracker::new: me: 187905372, thread: 783520647, xmlDocumentProviderFactory: 1322933092
2018-11-26 18:52:21.015 [INFO ] [ig.xml.osgi.XmlDocumentBundleTracker] - XmlDocumentBundleTracker::open: me: 187905372, thread: 1264585951, xmlDocumentProviderFactory: 1322933092, openState: CREATED

Unsuccessful

2018-11-26 19:43:43.398 [INFO ] [ig.xml.osgi.XmlDocumentBundleTracker] - XmlDocumentBundleTracker::new: me: 203860176, thread: 1876409947, xmlDocumentProviderFactory: 756591071
2018-11-26 19:43:43.400 [INFO ] [ig.xml.osgi.XmlDocumentBundleTracker] - XmlDocumentBundleTracker::open: me: 203860176, thread: 1075796975, xmlDocumentProviderFactory: 756591071, openState: CREATED
2018-11-26 19:43:43.470 [INFO ] [ig.xml.osgi.XmlDocumentBundleTracker] - XmlDocumentBundleTracker::close: me: 203860176, thread: 1876409947, xmlDocumentProviderFactory: 756591071, openState: OPENED
2018-11-26 19:43:43.478 [INFO ] [ig.xml.osgi.XmlDocumentBundleTracker] - XmlDocumentBundleTracker::new: me: 187905372, thread: 1876409947, xmlDocumentProviderFactory: 1322933092
2018-11-26 19:43:43.479 [INFO ] [ig.xml.osgi.XmlDocumentBundleTracker] - XmlDocumentBundleTracker::open: me: 187905372, thread: 1075796975, xmlDocumentProviderFactory: 1322933092, openState: CREATED
maggu2810 commented 5 years ago

Hi @mhilbush, thank you for the log.

Can you give me a full log if the error occurs containing the start sequence from the beginning so I can look at all XmlDocumentBundleTracker and XmlBindingInfoProvider messages?

maggu2810 commented 5 years ago

Hm, I don't understand why you see this trace without a further message:

2018-11-26 19:43:43.479 [INFO ] [ig.xml.osgi.XmlDocumentBundleTracker] - XmlDocumentBundleTracker::open: me: 187905372, thread: 1075796975, xmlDocumentProviderFactory: 1322933092, openState: CREATED
2018-11-26 19:43:43.491 [WARN ] [ig.xml.osgi.XmlDocumentBundleTracker] - The XML document '/ESH-INF/thing/sun.xml' in module 'org.eclipse.smarthome.binding.astro' could not be parsed: The XmlConfigDescriptionProvider must not be null!
java.lang.IllegalArgumentException: The XmlConfigDescriptionProvider must not be null!
    at org.eclipse.smarthome.core.thing.xml.internal.ThingTypeXmlProvider.<init>(ThingTypeXmlProvider.java:81) ~[?:?]
    at org.eclipse.smarthome.core.thing.xml.internal.XmlThingTypeProvider.createDocumentProvider(XmlThingTypeProvider.java:163) ~[?:?]
    at org.eclipse.smarthome.config.xml.osgi.XmlDocumentBundleTracker.acquireXmlDocumentProvider(XmlDocumentBundleTracker.java:213) ~[262:org.eclipse.smarthome.config.xml:0.10.0.201811262207]
    at org.eclipse.smarthome.config.xml.osgi.XmlDocumentBundleTracker.addingObject(XmlDocumentBundleTracker.java:238) ~[262:org.eclipse.smarthome.config.xml:0.10.0.201811262207]
    at org.eclipse.smarthome.config.xml.osgi.XmlDocumentBundleTracker.parseDocuments(XmlDocumentBundleTracker.java:407) [262:org.eclipse.smarthome.config.xml:0.10.0.201811262207]
    at org.eclipse.smarthome.config.xml.osgi.XmlDocumentBundleTracker.processBundle(XmlDocumentBundleTracker.java:393) [262:org.eclipse.smarthome.config.xml:0.10.0.201811262207]
    at org.eclipse.smarthome.config.xml.osgi.XmlDocumentBundleTracker.access$5(XmlDocumentBundleTracker.java:388) [262:org.eclipse.smarthome.config.xml:0.10.0.201811262207]
    at org.eclipse.smarthome.config.xml.osgi.XmlDocumentBundleTracker$2.run(XmlDocumentBundleTracker.java:351) [262:org.eclipse.smarthome.config.xml:0.10.0.201811262207]
    at java.util.concurrent.Executors$RunnableAdapter.call(Executors.java:511) [?:?]
    at java.util.concurrent.FutureTask.run(FutureTask.java:266) [?:?]
    at java.util.concurrent.ScheduledThreadPoolExecutor$ScheduledFutureTask.access$201(ScheduledThreadPoolExecutor.java:180) [?:?]
    at java.util.concurrent.ScheduledThreadPoolExecutor$ScheduledFutureTask.run(ScheduledThreadPoolExecutor.java:293) [?:?]
    at java.util.concurrent.ThreadPoolExecutor.runWorker(ThreadPoolExecutor.java:1149) [?:?]
    at java.util.concurrent.ThreadPoolExecutor$Worker.run(ThreadPoolExecutor.java:624) [?:?]
    at java.lang.Thread.run(Thread.java:748) [?:?]

There should be a XmlDocumentBundleTracker::run message.

private void addingBundle(Bundle bundle) {
    synchronized (syncOpenState) {
        if (openState != OpenState.OPENED) {
            return;
        }
    }

    queue.put(bundle, scheduler.submit(new Runnable() {
        // this should remain an anonymous class and not be converted to a lambda because of
        // http://bugs.java.com/view_bug.do?bug_id=8073755
        @Override
        public void run() {
            synchronized (syncOpenState) {
                if (openState != OpenState.OPENED) {
                    return;
                }
            }
            try {
                processBundle(bundle);
            } catch (final RuntimeException ex) {
                // Check if our OSGi instance is still active.
                // If the component has been deactivated while the execution hide the exception.
                synchronized (syncOpenState) {
                    logger.info(
                            "XmlDocumentBundleTracker::run: me: {}, thread: {}, xmlDocumentProviderFactory: {}, openState: {}",
                            System.identityHashCode(this), System.identityHashCode(Thread.currentThread()),
                            System.identityHashCode(xmlDocumentProviderFactory), openState);

                    if (openState == OpenState.OPENED) {
                        throw ex;
                    }
                }
            }
        }
    }));
}
maggu2810 commented 5 years ago

Ah, there is a exception handler in XmlDocumentBundleTracker::parseDocuments. Didn't see it. So, it seems to be just about messages that are logged but should be hidden. Will update the code today or tomorrow.

maggu2810 commented 5 years ago

org.eclipse.smarthome.config.xml-0.10.0-SNAPSHOT.jar

The exception you see above should not be visible anymore. If the same situation occurs again you should see a message that starts with:

XmlDocumentBundleTracker::parseDocuments:

Then we check if the openState still is equal to OPENED and if not we break without the stacktrace and warning as in the other part.

So, if you see (after some restarts) the parseDocuments message but no Exception anymore, I will cleanup my code and create a new PR.

mhilbush commented 5 years ago

So, if you see (after some restarts) the parseDocuments message but no Exception anymore

You mean this? I saw it on the first start, but have not seen it since.

2018-11-27 07:51:43.785 [INFO ] [ig.xml.osgi.XmlDocumentBundleTracker] - XmlDocumentBundleTracker::new: me: 1240889773, thread: 1005137027, xmlDocumentProviderFactory: 1823877504
2018-11-27 07:51:43.787 [INFO ] [ig.xml.osgi.XmlDocumentBundleTracker] - XmlDocumentBundleTracker::open: me: 1240889773, thread: 741125421, xmlDocumentProviderFactory: 1823877504, openState: CREATED
2018-11-27 07:51:43.860 [INFO ] [ig.xml.osgi.XmlDocumentBundleTracker] - XmlDocumentBundleTracker::close: me: 1240889773, thread: 1005137027, xmlDocumentProviderFactory: 1823877504, openState: OPENED
2018-11-27 07:51:43.868 [INFO ] [ig.xml.osgi.XmlDocumentBundleTracker] - XmlDocumentBundleTracker::new: me: 346773770, thread: 1005137027, xmlDocumentProviderFactory: 793970272
2018-11-27 07:51:43.869 [INFO ] [ig.xml.osgi.XmlDocumentBundleTracker] - XmlDocumentBundleTracker::open: me: 346773770, thread: 741125421, xmlDocumentProviderFactory: 793970272, openState: CREATED
2018-11-27 07:51:43.880 [INFO ] [ig.xml.osgi.XmlDocumentBundleTracker] - XmlDocumentBundleTracker::parseDocuments: me: 1240889773, thread: 1222347787, xmlDocumentProviderFactory: 1823877504, openState: CLOSED
maggu2810 commented 5 years ago

@mhilbush Hopefully the last one (if I didn't added some failures in the logic):

org.eclipse.smarthome.config.xml-0.10.0-SNAPSHOT.jar

mhilbush commented 5 years ago

I'm having trouble getting the system running with these bundles.

They appear to be installed, but they never start.

258 │ Resolved │  80 │ 0.10.0.201811272051    │ org.eclipse.smarthome.config.xml
259 │ Resolved │  80 │ 0.10.0.201811262207    │ org.eclipse.smarthome.core.binding.xml

I see the dates are a day apart. Are you sure you gave me the right org.eclipse.smarthome.core.binding.xml

maggu2810 commented 5 years ago

I have downloaded the linked core.binding.xml file now myself. And checked the META-INF/MANIFEST.MF of that jar file:

Manifest-Version: 1.0
Automatic-Module-Name: org.eclipse.smarthome.core.binding.xml
Bundle-SymbolicName: org.eclipse.smarthome.core.binding.xml
Built-By: maggu2810
Bundle-ManifestVersion: 2
Bundle-RequiredExecutionEnvironment: JavaSE-1.8
Bundle-Vendor: Eclipse.org/SmartHome
Import-Package: com.thoughtworks.xstream,com.thoughtworks.xstream.conv
 erters,com.thoughtworks.xstream.io,org.eclipse.jdt.annotation;resolut
 ion:=optional,org.eclipse.smarthome.config.core,org.eclipse.smarthome
 .config.core.i18n,org.eclipse.smarthome.config.xml,org.eclipse.smarth
 ome.config.xml.osgi,org.eclipse.smarthome.config.xml.util,org.eclipse
 .smarthome.core.binding,org.eclipse.smarthome.core.common,org.eclipse
 .smarthome.core.common.osgi,org.eclipse.smarthome.core.common.registr
 y,org.eclipse.smarthome.core.i18n,org.eclipse.smarthome.core.service,
 org.osgi.framework,org.osgi.service.component,org.slf4j
Service-Component: OSGI-INF/*.xml
Bundle-Name: Eclipse SmartHome Core Binding XML
Bundle-Version: 0.10.0.201811272051
Created-By: Apache Maven 3.6.0
Build-Jdk: 1.8.0_192

As you can see the Bundle-Version is "0.10.0.201811272051".

mhilbush commented 5 years ago

Hmm. Not sure what I did wrong, but I got it sorted out.

I'm still seeing it hang at startup.

This is the state of the two bundles.

258 │ Resolved │  80 │ 0.10.0.201811272051    │ org.eclipse.smarthome.core.binding.xml
259 │ Resolved │  80 │ 0.10.0.201811272051    │ org.eclipse.smarthome.config.xml

I set TRACE level logging on both those bundles, which yielded this.

2018-11-28 07:15:22.567 [INFO ] [egram.internal.TelegramActionService] - Bot OHbot loaded from config file
2018-11-28 07:15:22.593 [INFO ] [.internal.GenericScriptEngineFactory] - Activated scripting support for ECMAScript
2018-11-28 07:15:22.662 [INFO ] [internal.ModuleHandlerFactoryStarter] - WebPushNotificationModuleHandlerFactory started by ModuleHandlerFactoryStarter
2018-11-28 07:15:23.010 [INFO ] [panel.internal.HABPanelDashboardTile] - Started HABPanel at /habpanel
2018-11-28 07:15:23.125 [INFO ] [.core.internal.i18n.I18nProviderImpl] - Time zone set to 'US/Eastern'.
2018-11-28 07:15:23.127 [INFO ] [ashboard.internal.HABotDashboardTile] - Started HABot at /habot
2018-11-28 07:15:23.127 [INFO ] [.core.internal.i18n.I18nProviderImpl] - Location set to 'XXXXXXX'.
2018-11-28 07:15:23.128 [INFO ] [.core.internal.i18n.I18nProviderImpl] - Locale set to 'en_US'.
2018-11-28 07:15:23.622 [TRACE] [ig.xml.osgi.XmlDocumentBundleTracker] - Remaining bundles with /ESH-INF/thing/: [org.eclipse.smarthome.binding.astro_0.10.0.201811171951 [226], org.openhab.binding.squeezebox_2.4.0.201811150132 [190], org.openhab.binding.zwave_2.4.0.201811241129 [241], org.eclipse.smarthome.binding.ntp_0.10.0.201811171951 [227]]
2018-11-28 07:15:23.623 [TRACE] [ig.xml.osgi.XmlDocumentBundleTracker] - Remaining bundles with /ESH-INF/thing/: [org.eclipse.smarthome.binding.astro_0.10.0.201811171951 [226], org.openhab.binding.squeezebox_2.4.0.201811150132 [190], org.openhab.binding.zwave_2.4.0.201811241129 [241], org.eclipse.smarthome.binding.ntp_0.10.0.201811171951 [227]]
2018-11-28 07:15:23.624 [TRACE] [ig.xml.osgi.XmlDocumentBundleTracker] - Remaining bundles with /ESH-INF/thing/: [org.eclipse.smarthome.binding.astro_0.10.0.201811171951 [226], org.openhab.binding.squeezebox_2.4.0.201811150132 [190], org.openhab.binding.zwave_2.4.0.201811241129 [241], org.eclipse.smarthome.binding.ntp_0.10.0.201811171951 [227]]
2018-11-28 07:15:23.625 [TRACE] [ig.xml.osgi.XmlDocumentBundleTracker] - Remaining bundles with /ESH-INF/thing/: [org.eclipse.smarthome.binding.astro_0.10.0.201811171951 [226], org.openhab.binding.squeezebox_2.4.0.201811150132 [190], org.openhab.binding.zwave_2.4.0.201811241129 [241], org.eclipse.smarthome.binding.ntp_0.10.0.201811171951 [227]]
2018-11-28 07:15:23.625 [TRACE] [ig.xml.osgi.XmlDocumentBundleTracker] - Remaining bundles with /ESH-INF/thing/: [org.eclipse.smarthome.binding.astro_0.10.0.201811171951 [226], org.openhab.binding.squeezebox_2.4.0.201811150132 [190], org.openhab.binding.zwave_2.4.0.201811241129 [241], org.eclipse.smarthome.binding.ntp_0.10.0.201811171951 [227]]
2018-11-28 07:15:23.626 [TRACE] [ig.xml.osgi.XmlDocumentBundleTracker] - Remaining bundles with /ESH-INF/thing/: [org.eclipse.smarthome.binding.astro_0.10.0.201811171951 [226], org.openhab.binding.squeezebox_2.4.0.201811150132 [190], org.openhab.binding.zwave_2.4.0.201811241129 [241], org.eclipse.smarthome.binding.ntp_0.10.0.201811171951 [227]]
2018-11-28 07:15:23.626 [TRACE] [ig.xml.osgi.XmlDocumentBundleTracker] - Remaining bundles with /ESH-INF/thing/: [org.eclipse.smarthome.binding.astro_0.10.0.201811171951 [226], org.openhab.binding.squeezebox_2.4.0.201811150132 [190], org.openhab.binding.zwave_2.4.0.201811241129 [241], org.eclipse.smarthome.binding.ntp_0.10.0.201811171951 [227]]
2018-11-28 07:15:23.627 [TRACE] [ig.xml.osgi.XmlDocumentBundleTracker] - Remaining bundles with /ESH-INF/thing/: [org.eclipse.smarthome.binding.astro_0.10.0.201811171951 [226], org.openhab.binding.squeezebox_2.4.0.201811150132 [190], org.openhab.binding.zwave_2.4.0.201811241129 [241], org.eclipse.smarthome.binding.ntp_0.10.0.201811171951 [227]]
2018-11-28 07:15:23.628 [TRACE] [ig.xml.osgi.XmlDocumentBundleTracker] - Remaining bundles with /ESH-INF/thing/: [org.eclipse.smarthome.binding.astro_0.10.0.201811171951 [226], org.openhab.binding.squeezebox_2.4.0.201811150132 [190], org.openhab.binding.zwave_2.4.0.201811241129 [241], org.eclipse.smarthome.binding.ntp_0.10.0.201811171951 [227]]
2018-11-28 07:15:23.629 [TRACE] [ig.xml.osgi.XmlDocumentBundleTracker] - Remaining bundles with /ESH-INF/thing/: [org.eclipse.smarthome.binding.astro_0.10.0.201811171951 [226], org.openhab.binding.squeezebox_2.4.0.201811150132 [190], org.openhab.binding.zwave_2.4.0.201811241129 [241], org.eclipse.smarthome.binding.ntp_0.10.0.201811171951 [227]]
2018-11-28 07:15:23.629 [TRACE] [ig.xml.osgi.XmlDocumentBundleTracker] - Remaining bundles with /ESH-INF/thing/: [org.eclipse.smarthome.binding.astro_0.10.0.201811171951 [226], org.openhab.binding.squeezebox_2.4.0.201811150132 [190], org.openhab.binding.zwave_2.4.0.201811241129 [241], org.eclipse.smarthome.binding.ntp_0.10.0.201811171951 [227]]
2018-11-28 07:15:23.630 [TRACE] [ig.xml.osgi.XmlDocumentBundleTracker] - Remaining bundles with /ESH-INF/thing/: [org.eclipse.smarthome.binding.astro_0.10.0.201811171951 [226], org.openhab.binding.squeezebox_2.4.0.201811150132 [190], org.openhab.binding.zwave_2.4.0.201811241129 [241], org.eclipse.smarthome.binding.ntp_0.10.0.201811171951 [227]]
2018-11-28 07:15:23.630 [TRACE] [ig.xml.osgi.XmlDocumentBundleTracker] - Remaining bundles with /ESH-INF/thing/: [org.eclipse.smarthome.binding.astro_0.10.0.201811171951 [226], org.openhab.binding.squeezebox_2.4.0.201811150132 [190], org.openhab.binding.zwave_2.4.0.201811241129 [241], org.eclipse.smarthome.binding.ntp_0.10.0.201811171951 [227]]
2018-11-28 07:15:23.631 [TRACE] [ig.xml.osgi.XmlDocumentBundleTracker] - Remaining bundles with /ESH-INF/thing/: [org.eclipse.smarthome.binding.astro_0.10.0.201811171951 [226], org.openhab.binding.squeezebox_2.4.0.201811150132 [190], org.openhab.binding.zwave_2.4.0.201811241129 [241], org.eclipse.smarthome.binding.ntp_0.10.0.201811171951 [227]]
2018-11-28 07:15:23.631 [TRACE] [ig.xml.osgi.XmlDocumentBundleTracker] - Remaining bundles with /ESH-INF/thing/: [org.eclipse.smarthome.binding.astro_0.10.0.201811171951 [226], org.openhab.binding.squeezebox_2.4.0.201811150132 [190], org.openhab.binding.zwave_2.4.0.201811241129 [241], org.eclipse.smarthome.binding.ntp_0.10.0.201811171951 [227]]
2018-11-28 07:15:23.632 [TRACE] [ig.xml.osgi.XmlDocumentBundleTracker] - Remaining bundles with /ESH-INF/thing/: [org.eclipse.smarthome.binding.astro_0.10.0.201811171951 [226], org.openhab.binding.squeezebox_2.4.0.201811150132 [190], org.openhab.binding.zwave_2.4.0.201811241129 [241], org.eclipse.smarthome.binding.ntp_0.10.0.201811171951 [227]]
2018-11-28 07:15:23.633 [TRACE] [ig.xml.osgi.XmlDocumentBundleTracker] - Remaining bundles with /ESH-INF/thing/: [org.eclipse.smarthome.binding.astro_0.10.0.201811171951 [226], org.openhab.binding.squeezebox_2.4.0.201811150132 [190], org.openhab.binding.zwave_2.4.0.201811241129 [241], org.eclipse.smarthome.binding.ntp_0.10.0.201811171951 [227]]
2018-11-28 07:15:23.634 [TRACE] [ig.xml.osgi.XmlDocumentBundleTracker] - Remaining bundles with /ESH-INF/thing/: [org.eclipse.smarthome.binding.astro_0.10.0.201811171951 [226], org.openhab.binding.squeezebox_2.4.0.201811150132 [190], org.openhab.binding.zwave_2.4.0.201811241129 [241], org.eclipse.smarthome.binding.ntp_0.10.0.201811171951 [227]]
2018-11-28 07:15:23.634 [TRACE] [ig.xml.osgi.XmlDocumentBundleTracker] - Remaining bundles with /ESH-INF/thing/: [org.eclipse.smarthome.binding.astro_0.10.0.201811171951 [226], org.openhab.binding.squeezebox_2.4.0.201811150132 [190], org.openhab.binding.zwave_2.4.0.201811241129 [241], org.eclipse.smarthome.binding.ntp_0.10.0.201811171951 [227]]
2018-11-28 07:15:23.634 [TRACE] [ig.xml.osgi.XmlDocumentBundleTracker] - Remaining bundles with /ESH-INF/thing/: [org.eclipse.smarthome.binding.astro_0.10.0.201811171951 [226], org.openhab.binding.squeezebox_2.4.0.201811150132 [190], org.openhab.binding.zwave_2.4.0.201811241129 [241], org.eclipse.smarthome.binding.ntp_0.10.0.201811171951 [227]]
2018-11-28 07:15:23.635 [TRACE] [ig.xml.osgi.XmlDocumentBundleTracker] - Remaining bundles with /ESH-INF/thing/: [org.eclipse.smarthome.binding.astro_0.10.0.201811171951 [226], org.openhab.binding.squeezebox_2.4.0.201811150132 [190], org.openhab.binding.zwave_2.4.0.201811241129 [241], org.eclipse.smarthome.binding.ntp_0.10.0.201811171951 [227]]
2018-11-28 07:15:23.636 [TRACE] [ig.xml.osgi.XmlDocumentBundleTracker] - Remaining bundles with /ESH-INF/thing/: [org.eclipse.smarthome.binding.astro_0.10.0.201811171951 [226], org.openhab.binding.squeezebox_2.4.0.201811150132 [190], org.openhab.binding.zwave_2.4.0.201811241129 [241], org.eclipse.smarthome.binding.ntp_0.10.0.201811171951 [227]]
2018-11-28 07:15:23.636 [TRACE] [ig.xml.osgi.XmlDocumentBundleTracker] - Remaining bundles with /ESH-INF/thing/: [org.eclipse.smarthome.binding.astro_0.10.0.201811171951 [226], org.openhab.binding.squeezebox_2.4.0.201811150132 [190], org.openhab.binding.zwave_2.4.0.201811241129 [241], org.eclipse.smarthome.binding.ntp_0.10.0.201811171951 [227]]
2018-11-28 07:15:23.636 [TRACE] [ig.xml.osgi.XmlDocumentBundleTracker] - Remaining bundles with /ESH-INF/thing/: [org.eclipse.smarthome.binding.astro_0.10.0.201811171951 [226], org.openhab.binding.squeezebox_2.4.0.201811150132 [190], org.openhab.binding.zwave_2.4.0.201811241129 [241], org.eclipse.smarthome.binding.ntp_0.10.0.201811171951 [227]]
2018-11-28 07:15:23.637 [TRACE] [ig.xml.osgi.XmlDocumentBundleTracker] - Remaining bundles with /ESH-INF/thing/: [org.eclipse.smarthome.binding.astro_0.10.0.201811171951 [226], org.openhab.binding.squeezebox_2.4.0.201811150132 [190], org.openhab.binding.zwave_2.4.0.201811241129 [241], org.eclipse.smarthome.binding.ntp_0.10.0.201811171951 [227]]
2018-11-28 07:15:23.637 [TRACE] [ig.xml.osgi.XmlDocumentBundleTracker] - Remaining bundles with /ESH-INF/thing/: [org.eclipse.smarthome.binding.astro_0.10.0.201811171951 [226], org.openhab.binding.squeezebox_2.4.0.201811150132 [190], org.openhab.binding.zwave_2.4.0.201811241129 [241], org.eclipse.smarthome.binding.ntp_0.10.0.201811171951 [227]]
2018-11-28 07:15:23.638 [TRACE] [ig.xml.osgi.XmlDocumentBundleTracker] - Remaining bundles with /ESH-INF/thing/: [org.eclipse.smarthome.binding.astro_0.10.0.201811171951 [226], org.openhab.binding.squeezebox_2.4.0.201811150132 [190], org.openhab.binding.zwave_2.4.0.201811241129 [241], org.eclipse.smarthome.binding.ntp_0.10.0.201811171951 [227]]
2018-11-28 07:15:23.638 [TRACE] [ig.xml.osgi.XmlDocumentBundleTracker] - Remaining bundles with /ESH-INF/thing/: [org.eclipse.smarthome.binding.astro_0.10.0.201811171951 [226], org.openhab.binding.squeezebox_2.4.0.201811150132 [190], org.openhab.binding.zwave_2.4.0.201811241129 [241], org.eclipse.smarthome.binding.ntp_0.10.0.201811171951 [227]]
2018-11-28 07:15:23.639 [TRACE] [ig.xml.osgi.XmlDocumentBundleTracker] - Remaining bundles with /ESH-INF/thing/: [org.eclipse.smarthome.binding.astro_0.10.0.201811171951 [226], org.openhab.binding.squeezebox_2.4.0.201811150132 [190], org.openhab.binding.zwave_2.4.0.201811241129 [241], org.eclipse.smarthome.binding.ntp_0.10.0.201811171951 [227]]
2018-11-28 07:15:23.639 [TRACE] [ig.xml.osgi.XmlDocumentBundleTracker] - Remaining bundles with /ESH-INF/thing/: [org.eclipse.smarthome.binding.astro_0.10.0.201811171951 [226], org.openhab.binding.squeezebox_2.4.0.201811150132 [190], org.openhab.binding.zwave_2.4.0.201811241129 [241], org.eclipse.smarthome.binding.ntp_0.10.0.201811171951 [227]]
2018-11-28 07:15:23.640 [TRACE] [ig.xml.osgi.XmlDocumentBundleTracker] - Remaining bundles with /ESH-INF/thing/: [org.eclipse.smarthome.binding.astro_0.10.0.201811171951 [226], org.openhab.binding.squeezebox_2.4.0.201811150132 [190], org.openhab.binding.zwave_2.4.0.201811241129 [241], org.eclipse.smarthome.binding.ntp_0.10.0.201811171951 [227]]
2018-11-28 07:15:23.640 [TRACE] [ig.xml.osgi.XmlDocumentBundleTracker] - Remaining bundles with /ESH-INF/thing/: [org.eclipse.smarthome.binding.astro_0.10.0.201811171951 [226], org.openhab.binding.squeezebox_2.4.0.201811150132 [190], org.openhab.binding.zwave_2.4.0.201811241129 [241], org.eclipse.smarthome.binding.ntp_0.10.0.201811171951 [227]]
2018-11-28 07:15:23.641 [TRACE] [ig.xml.osgi.XmlDocumentBundleTracker] - Remaining bundles with /ESH-INF/thing/: [org.eclipse.smarthome.binding.astro_0.10.0.201811171951 [226], org.openhab.binding.squeezebox_2.4.0.201811150132 [190], org.openhab.binding.zwave_2.4.0.201811241129 [241], org.eclipse.smarthome.binding.ntp_0.10.0.201811171951 [227]]
2018-11-28 07:15:23.641 [TRACE] [ig.xml.osgi.XmlDocumentBundleTracker] - Remaining bundles with /ESH-INF/thing/: [org.eclipse.smarthome.binding.astro_0.10.0.201811171951 [226], org.openhab.binding.squeezebox_2.4.0.201811150132 [190], org.openhab.binding.zwave_2.4.0.201811241129 [241], org.eclipse.smarthome.binding.ntp_0.10.0.201811171951 [227]]
2018-11-28 07:15:23.642 [TRACE] [ig.xml.osgi.XmlDocumentBundleTracker] - Remaining bundles with /ESH-INF/thing/: [org.eclipse.smarthome.binding.astro_0.10.0.201811171951 [226], org.openhab.binding.squeezebox_2.4.0.201811150132 [190], org.openhab.binding.zwave_2.4.0.201811241129 [241], org.eclipse.smarthome.binding.ntp_0.10.0.201811171951 [227]]
2018-11-28 07:15:23.642 [TRACE] [ig.xml.osgi.XmlDocumentBundleTracker] - Remaining bundles with /ESH-INF/thing/: [org.eclipse.smarthome.binding.astro_0.10.0.201811171951 [226], org.openhab.binding.squeezebox_2.4.0.201811150132 [190], org.openhab.binding.zwave_2.4.0.201811241129 [241], org.eclipse.smarthome.binding.ntp_0.10.0.201811171951 [227]]
2018-11-28 07:15:23.643 [TRACE] [ig.xml.osgi.XmlDocumentBundleTracker] - Remaining bundles with /ESH-INF/thing/: [org.eclipse.smarthome.binding.astro_0.10.0.201811171951 [226], org.openhab.binding.squeezebox_2.4.0.201811150132 [190], org.openhab.binding.zwave_2.4.0.201811241129 [241], org.eclipse.smarthome.binding.ntp_0.10.0.201811171951 [227]]
2018-11-28 07:15:23.643 [TRACE] [ig.xml.osgi.XmlDocumentBundleTracker] - Remaining bundles with /ESH-INF/thing/: [org.eclipse.smarthome.binding.astro_0.10.0.201811171951 [226], org.openhab.binding.squeezebox_2.4.0.201811150132 [190], org.openhab.binding.zwave_2.4.0.201811241129 [241], org.eclipse.smarthome.binding.ntp_0.10.0.201811171951 [227]]
2018-11-28 07:15:23.644 [TRACE] [ig.xml.osgi.XmlDocumentBundleTracker] - Remaining bundles with /ESH-INF/thing/: [org.eclipse.smarthome.binding.astro_0.10.0.201811171951 [226], org.openhab.binding.squeezebox_2.4.0.201811150132 [190], org.openhab.binding.zwave_2.4.0.201811241129 [241], org.eclipse.smarthome.binding.ntp_0.10.0.201811171951 [227]]
2018-11-28 07:15:23.644 [TRACE] [ig.xml.osgi.XmlDocumentBundleTracker] - Remaining bundles with /ESH-INF/thing/: [org.eclipse.smarthome.binding.astro_0.10.0.201811171951 [226], org.openhab.binding.squeezebox_2.4.0.201811150132 [190], org.openhab.binding.zwave_2.4.0.201811241129 [241], org.eclipse.smarthome.binding.ntp_0.10.0.201811171951 [227]]
2018-11-28 07:15:23.644 [TRACE] [ig.xml.osgi.XmlDocumentBundleTracker] - Remaining bundles with /ESH-INF/thing/: [org.eclipse.smarthome.binding.astro_0.10.0.201811171951 [226], org.openhab.binding.squeezebox_2.4.0.201811150132 [190], org.openhab.binding.zwave_2.4.0.201811241129 [241], org.eclipse.smarthome.binding.ntp_0.10.0.201811171951 [227]]
2018-11-28 07:15:23.645 [TRACE] [ig.xml.osgi.XmlDocumentBundleTracker] - Remaining bundles with /ESH-INF/thing/: [org.eclipse.smarthome.binding.astro_0.10.0.201811171951 [226], org.openhab.binding.squeezebox_2.4.0.201811150132 [190], org.openhab.binding.zwave_2.4.0.201811241129 [241], org.eclipse.smarthome.binding.ntp_0.10.0.201811171951 [227]]
2018-11-28 07:15:23.646 [TRACE] [ig.xml.osgi.XmlDocumentBundleTracker] - Remaining bundles with /ESH-INF/thing/: [org.eclipse.smarthome.binding.astro_0.10.0.201811171951 [226], org.openhab.binding.squeezebox_2.4.0.201811150132 [190], org.openhab.binding.zwave_2.4.0.201811241129 [241], org.eclipse.smarthome.binding.ntp_0.10.0.201811171951 [227]]
2018-11-28 07:15:23.646 [TRACE] [ig.xml.osgi.XmlDocumentBundleTracker] - Remaining bundles with /ESH-INF/thing/: [org.eclipse.smarthome.binding.astro_0.10.0.201811171951 [226], org.openhab.binding.squeezebox_2.4.0.201811150132 [190], org.openhab.binding.zwave_2.4.0.201811241129 [241], org.eclipse.smarthome.binding.ntp_0.10.0.201811171951 [227]]
2018-11-28 07:15:23.647 [TRACE] [ig.xml.osgi.XmlDocumentBundleTracker] - Remaining bundles with /ESH-INF/thing/: [org.eclipse.smarthome.binding.astro_0.10.0.201811171951 [226], org.openhab.binding.squeezebox_2.4.0.201811150132 [190], org.openhab.binding.zwave_2.4.0.201811241129 [241], org.eclipse.smarthome.binding.ntp_0.10.0.201811171951 [227]]
2018-11-28 07:15:23.647 [TRACE] [ig.xml.osgi.XmlDocumentBundleTracker] - Remaining bundles with /ESH-INF/thing/: [org.eclipse.smarthome.binding.astro_0.10.0.201811171951 [226], org.openhab.binding.squeezebox_2.4.0.201811150132 [190], org.openhab.binding.zwave_2.4.0.201811241129 [241], org.eclipse.smarthome.binding.ntp_0.10.0.201811171951 [227]]
2018-11-28 07:15:23.648 [TRACE] [ig.xml.osgi.XmlDocumentBundleTracker] - Remaining bundles with /ESH-INF/thing/: [org.eclipse.smarthome.binding.astro_0.10.0.201811171951 [226], org.openhab.binding.squeezebox_2.4.0.201811150132 [190], org.openhab.binding.zwave_2.4.0.201811241129 [241], org.eclipse.smarthome.binding.ntp_0.10.0.201811171951 [227]]
2018-11-28 07:15:23.648 [TRACE] [ig.xml.osgi.XmlDocumentBundleTracker] - Remaining bundles with /ESH-INF/thing/: [org.eclipse.smarthome.binding.astro_0.10.0.201811171951 [226], org.openhab.binding.squeezebox_2.4.0.201811150132 [190], org.openhab.binding.zwave_2.4.0.201811241129 [241], org.eclipse.smarthome.binding.ntp_0.10.0.201811171951 [227]]
2018-11-28 07:15:23.649 [TRACE] [ig.xml.osgi.XmlDocumentBundleTracker] - Remaining bundles with /ESH-INF/thing/: [org.eclipse.smarthome.binding.astro_0.10.0.201811171951 [226], org.openhab.binding.squeezebox_2.4.0.201811150132 [190], org.openhab.binding.zwave_2.4.0.201811241129 [241], org.eclipse.smarthome.binding.ntp_0.10.0.201811171951 [227]]
2018-11-28 07:15:23.649 [TRACE] [ig.xml.osgi.XmlDocumentBundleTracker] - Remaining bundles with /ESH-INF/thing/: [org.eclipse.smarthome.binding.astro_0.10.0.201811171951 [226], org.openhab.binding.squeezebox_2.4.0.201811150132 [190], org.openhab.binding.zwave_2.4.0.201811241129 [241], org.eclipse.smarthome.binding.ntp_0.10.0.201811171951 [227]]
2018-11-28 07:15:23.650 [TRACE] [ig.xml.osgi.XmlDocumentBundleTracker] - Remaining bundles with /ESH-INF/thing/: [org.eclipse.smarthome.binding.astro_0.10.0.201811171951 [226], org.openhab.binding.squeezebox_2.4.0.201811150132 [190], org.openhab.binding.zwave_2.4.0.201811241129 [241], org.eclipse.smarthome.binding.ntp_0.10.0.201811171951 [227]]
2018-11-28 07:15:23.650 [TRACE] [ig.xml.osgi.XmlDocumentBundleTracker] - Remaining bundles with /ESH-INF/thing/: [org.eclipse.smarthome.binding.astro_0.10.0.201811171951 [226], org.openhab.binding.squeezebox_2.4.0.201811150132 [190], org.openhab.binding.zwave_2.4.0.201811241129 [241], org.eclipse.smarthome.binding.ntp_0.10.0.201811171951 [227]]
2018-11-28 07:15:23.650 [TRACE] [ig.xml.osgi.XmlDocumentBundleTracker] - Remaining bundles with /ESH-INF/thing/: [org.eclipse.smarthome.binding.astro_0.10.0.201811171951 [226], org.openhab.binding.squeezebox_2.4.0.201811150132 [190], org.openhab.binding.zwave_2.4.0.201811241129 [241], org.eclipse.smarthome.binding.ntp_0.10.0.201811171951 [227]]
2018-11-28 07:15:23.651 [TRACE] [ig.xml.osgi.XmlDocumentBundleTracker] - Remaining bundles with /ESH-INF/thing/: [org.eclipse.smarthome.binding.astro_0.10.0.201811171951 [226], org.openhab.binding.squeezebox_2.4.0.201811150132 [190], org.openhab.binding.zwave_2.4.0.201811241129 [241], org.eclipse.smarthome.binding.ntp_0.10.0.201811171951 [227]]
2018-11-28 07:15:23.651 [TRACE] [ig.xml.osgi.XmlDocumentBundleTracker] - Remaining bundles with /ESH-INF/thing/: [org.eclipse.smarthome.binding.astro_0.10.0.201811171951 [226], org.openhab.binding.squeezebox_2.4.0.201811150132 [190], org.openhab.binding.zwave_2.4.0.201811241129 [241], org.eclipse.smarthome.binding.ntp_0.10.0.201811171951 [227]]
2018-11-28 07:15:23.652 [TRACE] [ig.xml.osgi.XmlDocumentBundleTracker] - Remaining bundles with /ESH-INF/thing/: [org.eclipse.smarthome.binding.astro_0.10.0.201811171951 [226], org.openhab.binding.squeezebox_2.4.0.201811150132 [190], org.openhab.binding.zwave_2.4.0.201811241129 [241], org.eclipse.smarthome.binding.ntp_0.10.0.201811171951 [227]]
2018-11-28 07:15:23.653 [TRACE] [ig.xml.osgi.XmlDocumentBundleTracker] - Remaining bundles with /ESH-INF/thing/: [org.eclipse.smarthome.binding.astro_0.10.0.201811171951 [226], org.openhab.binding.squeezebox_2.4.0.201811150132 [190], org.openhab.binding.zwave_2.4.0.201811241129 [241], org.eclipse.smarthome.binding.ntp_0.10.0.201811171951 [227]]
2018-11-28 07:15:23.653 [TRACE] [ig.xml.osgi.XmlDocumentBundleTracker] - Remaining bundles with /ESH-INF/thing/: [org.eclipse.smarthome.binding.astro_0.10.0.201811171951 [226], org.openhab.binding.squeezebox_2.4.0.201811150132 [190], org.openhab.binding.zwave_2.4.0.201811241129 [241], org.eclipse.smarthome.binding.ntp_0.10.0.201811171951 [227]]
2018-11-28 07:15:23.654 [TRACE] [ig.xml.osgi.XmlDocumentBundleTracker] - Remaining bundles with /ESH-INF/thing/: [org.eclipse.smarthome.binding.astro_0.10.0.201811171951 [226], org.openhab.binding.squeezebox_2.4.0.201811150132 [190], org.openhab.binding.zwave_2.4.0.201811241129 [241], org.eclipse.smarthome.binding.ntp_0.10.0.201811171951 [227]]
2018-11-28 07:15:23.655 [TRACE] [ig.xml.osgi.XmlDocumentBundleTracker] - Remaining bundles with /ESH-INF/thing/: [org.eclipse.smarthome.binding.astro_0.10.0.201811171951 [226], org.openhab.binding.squeezebox_2.4.0.201811150132 [190], org.openhab.binding.zwave_2.4.0.201811241129 [241], org.eclipse.smarthome.binding.ntp_0.10.0.201811171951 [227]]
2018-11-28 07:15:23.655 [TRACE] [ig.xml.osgi.XmlDocumentBundleTracker] - Remaining bundles with /ESH-INF/thing/: [org.eclipse.smarthome.binding.astro_0.10.0.201811171951 [226], org.openhab.binding.squeezebox_2.4.0.201811150132 [190], org.openhab.binding.zwave_2.4.0.201811241129 [241], org.eclipse.smarthome.binding.ntp_0.10.0.201811171951 [227]]
2018-11-28 07:15:23.655 [TRACE] [ig.xml.osgi.XmlDocumentBundleTracker] - Remaining bundles with /ESH-INF/thing/: [org.eclipse.smarthome.binding.astro_0.10.0.201811171951 [226], org.openhab.binding.squeezebox_2.4.0.201811150132 [190], org.openhab.binding.zwave_2.4.0.201811241129 [241], org.eclipse.smarthome.binding.ntp_0.10.0.201811171951 [227]]
2018-11-28 07:15:23.656 [TRACE] [ig.xml.osgi.XmlDocumentBundleTracker] - Remaining bundles with /ESH-INF/thing/: [org.eclipse.smarthome.binding.astro_0.10.0.201811171951 [226], org.openhab.binding.squeezebox_2.4.0.201811150132 [190], org.openhab.binding.zwave_2.4.0.201811241129 [241], org.eclipse.smarthome.binding.ntp_0.10.0.201811171951 [227]]
2018-11-28 07:15:23.656 [TRACE] [ig.xml.osgi.XmlDocumentBundleTracker] - Remaining bundles with /ESH-INF/thing/: [org.eclipse.smarthome.binding.astro_0.10.0.201811171951 [226], org.openhab.binding.squeezebox_2.4.0.201811150132 [190], org.openhab.binding.zwave_2.4.0.201811241129 [241], org.eclipse.smarthome.binding.ntp_0.10.0.201811171951 [227]]
2018-11-28 07:15:23.657 [TRACE] [ig.xml.osgi.XmlDocumentBundleTracker] - Remaining bundles with /ESH-INF/thing/: [org.eclipse.smarthome.binding.astro_0.10.0.201811171951 [226], org.openhab.binding.squeezebox_2.4.0.201811150132 [190], org.openhab.binding.zwave_2.4.0.201811241129 [241], org.eclipse.smarthome.binding.ntp_0.10.0.201811171951 [227]]
2018-11-28 07:15:23.657 [TRACE] [ig.xml.osgi.XmlDocumentBundleTracker] - Remaining bundles with /ESH-INF/thing/: [org.eclipse.smarthome.binding.astro_0.10.0.201811171951 [226], org.openhab.binding.squeezebox_2.4.0.201811150132 [190], org.openhab.binding.zwave_2.4.0.201811241129 [241], org.eclipse.smarthome.binding.ntp_0.10.0.201811171951 [227]]
2018-11-28 07:15:23.658 [TRACE] [ig.xml.osgi.XmlDocumentBundleTracker] - Remaining bundles with /ESH-INF/thing/: [org.eclipse.smarthome.binding.astro_0.10.0.201811171951 [226], org.openhab.binding.squeezebox_2.4.0.201811150132 [190], org.openhab.binding.zwave_2.4.0.201811241129 [241], org.eclipse.smarthome.binding.ntp_0.10.0.201811171951 [227]]
2018-11-28 07:15:23.658 [TRACE] [ig.xml.osgi.XmlDocumentBundleTracker] - Remaining bundles with /ESH-INF/thing/: [org.eclipse.smarthome.binding.astro_0.10.0.201811171951 [226], org.openhab.binding.squeezebox_2.4.0.201811150132 [190], org.openhab.binding.zwave_2.4.0.201811241129 [241], org.eclipse.smarthome.binding.ntp_0.10.0.201811171951 [227]]
2018-11-28 07:15:23.658 [TRACE] [ig.xml.osgi.XmlDocumentBundleTracker] - Remaining bundles with /ESH-INF/thing/: [org.eclipse.smarthome.binding.astro_0.10.0.201811171951 [226], org.openhab.binding.squeezebox_2.4.0.201811150132 [190], org.openhab.binding.zwave_2.4.0.201811241129 [241], org.eclipse.smarthome.binding.ntp_0.10.0.201811171951 [227]]
2018-11-28 07:15:23.659 [TRACE] [ig.xml.osgi.XmlDocumentBundleTracker] - Remaining bundles with /ESH-INF/thing/: [org.eclipse.smarthome.binding.astro_0.10.0.201811171951 [226], org.openhab.binding.squeezebox_2.4.0.201811150132 [190], org.openhab.binding.zwave_2.4.0.201811241129 [241], org.eclipse.smarthome.binding.ntp_0.10.0.201811171951 [227]]
2018-11-28 07:15:23.659 [TRACE] [ig.xml.osgi.XmlDocumentBundleTracker] - Remaining bundles with /ESH-INF/thing/: [org.eclipse.smarthome.binding.astro_0.10.0.201811171951 [226], org.openhab.binding.squeezebox_2.4.0.201811150132 [190], org.openhab.binding.zwave_2.4.0.201811241129 [241], org.eclipse.smarthome.binding.ntp_0.10.0.201811171951 [227]]
2018-11-28 07:15:23.660 [TRACE] [ig.xml.osgi.XmlDocumentBundleTracker] - Remaining bundles with /ESH-INF/thing/: [org.eclipse.smarthome.binding.astro_0.10.0.201811171951 [226], org.openhab.binding.squeezebox_2.4.0.201811150132 [190], org.openhab.binding.zwave_2.4.0.201811241129 [241], org.eclipse.smarthome.binding.ntp_0.10.0.201811171951 [227]]
2018-11-28 07:15:23.660 [TRACE] [ig.xml.osgi.XmlDocumentBundleTracker] - Remaining bundles with /ESH-INF/thing/: [org.eclipse.smarthome.binding.astro_0.10.0.201811171951 [226], org.openhab.binding.squeezebox_2.4.0.201811150132 [190], org.openhab.binding.zwave_2.4.0.201811241129 [241], org.eclipse.smarthome.binding.ntp_0.10.0.201811171951 [227]]
2018-11-28 07:15:23.661 [TRACE] [ig.xml.osgi.XmlDocumentBundleTracker] - Remaining bundles with /ESH-INF/thing/: [org.eclipse.smarthome.binding.astro_0.10.0.201811171951 [226], org.openhab.binding.squeezebox_2.4.0.201811150132 [190], org.openhab.binding.zwave_2.4.0.201811241129 [241], org.eclipse.smarthome.binding.ntp_0.10.0.201811171951 [227]]
2018-11-28 07:15:23.661 [TRACE] [ig.xml.osgi.XmlDocumentBundleTracker] - Remaining bundles with /ESH-INF/thing/: [org.eclipse.smarthome.binding.astro_0.10.0.201811171951 [226], org.openhab.binding.squeezebox_2.4.0.201811150132 [190], org.openhab.binding.zwave_2.4.0.201811241129 [241], org.eclipse.smarthome.binding.ntp_0.10.0.201811171951 [227]]
2018-11-28 07:15:23.661 [TRACE] [ig.xml.osgi.XmlDocumentBundleTracker] - Remaining bundles with /ESH-INF/thing/: [org.eclipse.smarthome.binding.astro_0.10.0.201811171951 [226], org.openhab.binding.squeezebox_2.4.0.201811150132 [190], org.openhab.binding.zwave_2.4.0.201811241129 [241], org.eclipse.smarthome.binding.ntp_0.10.0.201811171951 [227]]
2018-11-28 07:15:23.662 [TRACE] [ig.xml.osgi.XmlDocumentBundleTracker] - Remaining bundles with /ESH-INF/thing/: [org.eclipse.smarthome.binding.astro_0.10.0.201811171951 [226], org.openhab.binding.squeezebox_2.4.0.201811150132 [190], org.openhab.binding.zwave_2.4.0.201811241129 [241], org.eclipse.smarthome.binding.ntp_0.10.0.201811171951 [227]]
2018-11-28 07:15:23.662 [TRACE] [ig.xml.osgi.XmlDocumentBundleTracker] - Remaining bundles with /ESH-INF/thing/: [org.eclipse.smarthome.binding.astro_0.10.0.201811171951 [226], org.openhab.binding.squeezebox_2.4.0.201811150132 [190], org.openhab.binding.zwave_2.4.0.201811241129 [241], org.eclipse.smarthome.binding.ntp_0.10.0.201811171951 [227]]
2018-11-28 07:15:23.663 [TRACE] [ig.xml.osgi.XmlDocumentBundleTracker] - Remaining bundles with /ESH-INF/thing/: [org.eclipse.smarthome.binding.astro_0.10.0.201811171951 [226], org.openhab.binding.squeezebox_2.4.0.201811150132 [190], org.openhab.binding.zwave_2.4.0.201811241129 [241], org.eclipse.smarthome.binding.ntp_0.10.0.201811171951 [227]]
2018-11-28 07:15:23.663 [TRACE] [ig.xml.osgi.XmlDocumentBundleTracker] - Remaining bundles with /ESH-INF/thing/: [org.eclipse.smarthome.binding.astro_0.10.0.201811171951 [226], org.openhab.binding.squeezebox_2.4.0.201811150132 [190], org.openhab.binding.zwave_2.4.0.201811241129 [241], org.eclipse.smarthome.binding.ntp_0.10.0.201811171951 [227]]
2018-11-28 07:15:23.683 [TRACE] [ig.xml.osgi.XmlDocumentBundleTracker] - Remaining bundles with /ESH-INF/thing/: [org.eclipse.smarthome.binding.astro_0.10.0.201811171951 [226], org.openhab.binding.squeezebox_2.4.0.201811150132 [190], org.openhab.binding.zwave_2.4.0.201811241129 [241], org.eclipse.smarthome.binding.ntp_0.10.0.201811171951 [227]]
2018-11-28 07:15:23.684 [TRACE] [ig.xml.osgi.XmlDocumentBundleTracker] - Remaining bundles with /ESH-INF/thing/: [org.eclipse.smarthome.binding.astro_0.10.0.201811171951 [226], org.openhab.binding.squeezebox_2.4.0.201811150132 [190], org.openhab.binding.zwave_2.4.0.201811241129 [241], org.eclipse.smarthome.binding.ntp_0.10.0.201811171951 [227]]
2018-11-28 07:15:23.685 [TRACE] [ig.xml.osgi.XmlDocumentBundleTracker] - Remaining bundles with /ESH-INF/thing/: [org.eclipse.smarthome.binding.astro_0.10.0.201811171951 [226], org.openhab.binding.squeezebox_2.4.0.201811150132 [190], org.openhab.binding.zwave_2.4.0.201811241129 [241], org.eclipse.smarthome.binding.ntp_0.10.0.201811171951 [227]]
2018-11-28 07:15:23.685 [TRACE] [ig.xml.osgi.XmlDocumentBundleTracker] - Remaining bundles with /ESH-INF/thing/: [org.eclipse.smarthome.binding.astro_0.10.0.201811171951 [226], org.openhab.binding.squeezebox_2.4.0.201811150132 [190], org.openhab.binding.zwave_2.4.0.201811241129 [241], org.eclipse.smarthome.binding.ntp_0.10.0.201811171951 [227]]
2018-11-28 07:15:23.686 [TRACE] [ig.xml.osgi.XmlDocumentBundleTracker] - Remaining bundles with /ESH-INF/thing/: [org.eclipse.smarthome.binding.astro_0.10.0.201811171951 [226], org.openhab.binding.squeezebox_2.4.0.201811150132 [190], org.openhab.binding.zwave_2.4.0.201811241129 [241], org.eclipse.smarthome.binding.ntp_0.10.0.201811171951 [227]]
2018-11-28 07:15:23.686 [TRACE] [ig.xml.osgi.XmlDocumentBundleTracker] - Remaining bundles with /ESH-INF/thing/: [org.eclipse.smarthome.binding.astro_0.10.0.201811171951 [226], org.openhab.binding.squeezebox_2.4.0.201811150132 [190], org.openhab.binding.zwave_2.4.0.201811241129 [241], org.eclipse.smarthome.binding.ntp_0.10.0.201811171951 [227]]
2018-11-28 07:15:23.687 [TRACE] [ig.xml.osgi.XmlDocumentBundleTracker] - Remaining bundles with /ESH-INF/thing/: [org.eclipse.smarthome.binding.astro_0.10.0.201811171951 [226], org.openhab.binding.squeezebox_2.4.0.201811150132 [190], org.openhab.binding.zwave_2.4.0.201811241129 [241], org.eclipse.smarthome.binding.ntp_0.10.0.201811171951 [227]]
2018-11-28 07:15:23.687 [TRACE] [ig.xml.osgi.XmlDocumentBundleTracker] - Remaining bundles with /ESH-INF/thing/: [org.eclipse.smarthome.binding.astro_0.10.0.201811171951 [226], org.openhab.binding.squeezebox_2.4.0.201811150132 [190], org.openhab.binding.zwave_2.4.0.201811241129 [241], org.eclipse.smarthome.binding.ntp_0.10.0.201811171951 [227]]
2018-11-28 07:15:23.688 [TRACE] [ig.xml.osgi.XmlDocumentBundleTracker] - Remaining bundles with /ESH-INF/thing/: [org.eclipse.smarthome.binding.astro_0.10.0.201811171951 [226], org.openhab.binding.squeezebox_2.4.0.201811150132 [190], org.openhab.binding.zwave_2.4.0.201811241129 [241], org.eclipse.smarthome.binding.ntp_0.10.0.201811171951 [227]]
2018-11-28 07:15:23.688 [TRACE] [ig.xml.osgi.XmlDocumentBundleTracker] - Remaining bundles with /ESH-INF/thing/: [org.eclipse.smarthome.binding.astro_0.10.0.201811171951 [226], org.openhab.binding.squeezebox_2.4.0.201811150132 [190], org.openhab.binding.zwave_2.4.0.201811241129 [241], org.eclipse.smarthome.binding.ntp_0.10.0.201811171951 [227]]
2018-11-28 07:15:23.688 [TRACE] [ig.xml.osgi.XmlDocumentBundleTracker] - Remaining bundles with /ESH-INF/thing/: [org.eclipse.smarthome.binding.astro_0.10.0.201811171951 [226], org.openhab.binding.squeezebox_2.4.0.201811150132 [190], org.openhab.binding.zwave_2.4.0.201811241129 [241], org.eclipse.smarthome.binding.ntp_0.10.0.201811171951 [227]]
2018-11-28 07:15:23.689 [TRACE] [ig.xml.osgi.XmlDocumentBundleTracker] - Remaining bundles with /ESH-INF/thing/: [org.eclipse.smarthome.binding.astro_0.10.0.201811171951 [226], org.openhab.binding.squeezebox_2.4.0.201811150132 [190], org.openhab.binding.zwave_2.4.0.201811241129 [241], org.eclipse.smarthome.binding.ntp_0.10.0.201811171951 [227]]
2018-11-28 07:15:23.689 [TRACE] [ig.xml.osgi.XmlDocumentBundleTracker] - Remaining bundles with /ESH-INF/thing/: [org.eclipse.smarthome.binding.astro_0.10.0.201811171951 [226], org.openhab.binding.squeezebox_2.4.0.201811150132 [190], org.openhab.binding.zwave_2.4.0.201811241129 [241], org.eclipse.smarthome.binding.ntp_0.10.0.201811171951 [227]]
2018-11-28 07:15:23.710 [TRACE] [ig.xml.osgi.XmlDocumentBundleTracker] - Remaining bundles with /ESH-INF/thing/: [org.eclipse.smarthome.binding.astro_0.10.0.201811171951 [226], org.openhab.binding.squeezebox_2.4.0.201811150132 [190], org.openhab.binding.zwave_2.4.0.201811241129 [241], org.eclipse.smarthome.binding.ntp_0.10.0.201811171951 [227]]
2018-11-28 07:15:23.711 [TRACE] [ig.xml.osgi.XmlDocumentBundleTracker] - Remaining bundles with /ESH-INF/thing/: [org.eclipse.smarthome.binding.astro_0.10.0.201811171951 [226], org.openhab.binding.squeezebox_2.4.0.201811150132 [190], org.openhab.binding.zwave_2.4.0.201811241129 [241], org.eclipse.smarthome.binding.ntp_0.10.0.201811171951 [227]]
2018-11-28 07:15:23.711 [TRACE] [ig.xml.osgi.XmlDocumentBundleTracker] - Remaining bundles with /ESH-INF/thing/: [org.eclipse.smarthome.binding.astro_0.10.0.201811171951 [226], org.openhab.binding.squeezebox_2.4.0.201811150132 [190], org.openhab.binding.zwave_2.4.0.201811241129 [241], org.eclipse.smarthome.binding.ntp_0.10.0.201811171951 [227]]
2018-11-28 07:15:23.711 [TRACE] [ig.xml.osgi.XmlDocumentBundleTracker] - Remaining bundles with /ESH-INF/thing/: [org.eclipse.smarthome.binding.astro_0.10.0.201811171951 [226], org.openhab.binding.squeezebox_2.4.0.201811150132 [190], org.openhab.binding.zwave_2.4.0.201811241129 [241], org.eclipse.smarthome.binding.ntp_0.10.0.201811171951 [227]]
2018-11-28 07:15:23.712 [TRACE] [ig.xml.osgi.XmlDocumentBundleTracker] - Remaining bundles with /ESH-INF/thing/: [org.eclipse.smarthome.binding.astro_0.10.0.201811171951 [226], org.openhab.binding.squeezebox_2.4.0.201811150132 [190], org.openhab.binding.zwave_2.4.0.201811241129 [241], org.eclipse.smarthome.binding.ntp_0.10.0.201811171951 [227]]
2018-11-28 07:15:23.712 [TRACE] [ig.xml.osgi.XmlDocumentBundleTracker] - Remaining bundles with /ESH-INF/thing/: [org.eclipse.smarthome.binding.astro_0.10.0.201811171951 [226], org.openhab.binding.squeezebox_2.4.0.201811150132 [190], org.openhab.binding.zwave_2.4.0.201811241129 [241], org.eclipse.smarthome.binding.ntp_0.10.0.201811171951 [227]]
2018-11-28 07:15:23.713 [TRACE] [ig.xml.osgi.XmlDocumentBundleTracker] - Remaining bundles with /ESH-INF/thing/: [org.eclipse.smarthome.binding.astro_0.10.0.201811171951 [226], org.openhab.binding.squeezebox_2.4.0.201811150132 [190], org.openhab.binding.zwave_2.4.0.201811241129 [241], org.eclipse.smarthome.binding.ntp_0.10.0.201811171951 [227]]
2018-11-28 07:15:23.713 [TRACE] [ig.xml.osgi.XmlDocumentBundleTracker] - Remaining bundles with /ESH-INF/thing/: [org.eclipse.smarthome.binding.astro_0.10.0.201811171951 [226], org.openhab.binding.squeezebox_2.4.0.201811150132 [190], org.openhab.binding.zwave_2.4.0.201811241129 [241], org.eclipse.smarthome.binding.ntp_0.10.0.201811171951 [227]]
2018-11-28 07:15:23.713 [TRACE] [ig.xml.osgi.XmlDocumentBundleTracker] - Remaining bundles with /ESH-INF/thing/: [org.eclipse.smarthome.binding.astro_0.10.0.201811171951 [226], org.openhab.binding.squeezebox_2.4.0.201811150132 [190], org.openhab.binding.zwave_2.4.0.201811241129 [241], org.eclipse.smarthome.binding.ntp_0.10.0.201811171951 [227]]
2018-11-28 07:15:23.714 [TRACE] [ig.xml.osgi.XmlDocumentBundleTracker] - Remaining bundles with /ESH-INF/thing/: [org.eclipse.smarthome.binding.astro_0.10.0.201811171951 [226], org.openhab.binding.squeezebox_2.4.0.201811150132 [190], org.openhab.binding.zwave_2.4.0.201811241129 [241], org.eclipse.smarthome.binding.ntp_0.10.0.201811171951 [227]]
2018-11-28 07:15:23.714 [TRACE] [ig.xml.osgi.XmlDocumentBundleTracker] - Remaining bundles with /ESH-INF/thing/: [org.eclipse.smarthome.binding.astro_0.10.0.201811171951 [226], org.openhab.binding.squeezebox_2.4.0.201811150132 [190], org.openhab.binding.zwave_2.4.0.201811241129 [241], org.eclipse.smarthome.binding.ntp_0.10.0.201811171951 [227]]
2018-11-28 07:15:23.715 [TRACE] [ig.xml.osgi.XmlDocumentBundleTracker] - Remaining bundles with /ESH-INF/thing/: [org.eclipse.smarthome.binding.astro_0.10.0.201811171951 [226], org.openhab.binding.squeezebox_2.4.0.201811150132 [190], org.openhab.binding.zwave_2.4.0.201811241129 [241], org.eclipse.smarthome.binding.ntp_0.10.0.201811171951 [227]]
2018-11-28 07:15:23.715 [TRACE] [ig.xml.osgi.XmlDocumentBundleTracker] - Remaining bundles with /ESH-INF/thing/: [org.eclipse.smarthome.binding.astro_0.10.0.201811171951 [226], org.openhab.binding.squeezebox_2.4.0.201811150132 [190], org.openhab.binding.zwave_2.4.0.201811241129 [241], org.eclipse.smarthome.binding.ntp_0.10.0.201811171951 [227]]
2018-11-28 07:15:23.716 [TRACE] [ig.xml.osgi.XmlDocumentBundleTracker] - Remaining bundles with /ESH-INF/thing/: [org.eclipse.smarthome.binding.astro_0.10.0.201811171951 [226], org.openhab.binding.squeezebox_2.4.0.201811150132 [190], org.openhab.binding.zwave_2.4.0.201811241129 [241], org.eclipse.smarthome.binding.ntp_0.10.0.201811171951 [227]]
2018-11-28 07:15:23.716 [TRACE] [ig.xml.osgi.XmlDocumentBundleTracker] - Remaining bundles with /ESH-INF/thing/: [org.eclipse.smarthome.binding.astro_0.10.0.201811171951 [226], org.openhab.binding.squeezebox_2.4.0.201811150132 [190], org.openhab.binding.zwave_2.4.0.201811241129 [241], org.eclipse.smarthome.binding.ntp_0.10.0.201811171951 [227]]
2018-11-28 07:15:23.716 [TRACE] [ig.xml.osgi.XmlDocumentBundleTracker] - Remaining bundles with /ESH-INF/thing/: [org.eclipse.smarthome.binding.astro_0.10.0.201811171951 [226], org.openhab.binding.squeezebox_2.4.0.201811150132 [190], org.openhab.binding.zwave_2.4.0.201811241129 [241], org.eclipse.smarthome.binding.ntp_0.10.0.201811171951 [227]]
2018-11-28 07:15:23.717 [TRACE] [ig.xml.osgi.XmlDocumentBundleTracker] - Remaining bundles with /ESH-INF/thing/: [org.eclipse.smarthome.binding.astro_0.10.0.201811171951 [226], org.openhab.binding.squeezebox_2.4.0.201811150132 [190], org.openhab.binding.zwave_2.4.0.201811241129 [241], org.eclipse.smarthome.binding.ntp_0.10.0.201811171951 [227]]
2018-11-28 07:15:23.718 [TRACE] [ig.xml.osgi.XmlDocumentBundleTracker] - Remaining bundles with /ESH-INF/thing/: [org.eclipse.smarthome.binding.astro_0.10.0.201811171951 [226], org.openhab.binding.squeezebox_2.4.0.201811150132 [190], org.openhab.binding.zwave_2.4.0.201811241129 [241], org.eclipse.smarthome.binding.ntp_0.10.0.201811171951 [227]]
2018-11-28 07:15:23.719 [TRACE] [ig.xml.osgi.XmlDocumentBundleTracker] - Remaining bundles with /ESH-INF/thing/: [org.eclipse.smarthome.binding.astro_0.10.0.201811171951 [226], org.openhab.binding.squeezebox_2.4.0.201811150132 [190], org.openhab.binding.zwave_2.4.0.201811241129 [241], org.eclipse.smarthome.binding.ntp_0.10.0.201811171951 [227]]
2018-11-28 07:15:23.719 [TRACE] [ig.xml.osgi.XmlDocumentBundleTracker] - Remaining bundles with /ESH-INF/thing/: [org.eclipse.smarthome.binding.astro_0.10.0.201811171951 [226], org.openhab.binding.squeezebox_2.4.0.201811150132 [190], org.openhab.binding.zwave_2.4.0.201811241129 [241], org.eclipse.smarthome.binding.ntp_0.10.0.201811171951 [227]]
2018-11-28 07:15:23.720 [TRACE] [ig.xml.osgi.XmlDocumentBundleTracker] - Remaining bundles with /ESH-INF/thing/: [org.eclipse.smarthome.binding.astro_0.10.0.201811171951 [226], org.openhab.binding.squeezebox_2.4.0.201811150132 [190], org.openhab.binding.zwave_2.4.0.201811241129 [241], org.eclipse.smarthome.binding.ntp_0.10.0.201811171951 [227]]
2018-11-28 07:15:23.721 [TRACE] [ig.xml.osgi.XmlDocumentBundleTracker] - Remaining bundles with /ESH-INF/thing/: [org.eclipse.smarthome.binding.astro_0.10.0.201811171951 [226], org.openhab.binding.squeezebox_2.4.0.201811150132 [190], org.openhab.binding.zwave_2.4.0.201811241129 [241], org.eclipse.smarthome.binding.ntp_0.10.0.201811171951 [227]]
2018-11-28 07:15:23.721 [TRACE] [ig.xml.osgi.XmlDocumentBundleTracker] - Remaining bundles with /ESH-INF/thing/: [org.eclipse.smarthome.binding.astro_0.10.0.201811171951 [226], org.openhab.binding.squeezebox_2.4.0.201811150132 [190], org.openhab.binding.zwave_2.4.0.201811241129 [241], org.eclipse.smarthome.binding.ntp_0.10.0.201811171951 [227]]
2018-11-28 07:15:23.721 [TRACE] [ig.xml.osgi.XmlDocumentBundleTracker] - Remaining bundles with /ESH-INF/thing/: [org.eclipse.smarthome.binding.astro_0.10.0.201811171951 [226], org.openhab.binding.squeezebox_2.4.0.201811150132 [190], org.openhab.binding.zwave_2.4.0.201811241129 [241], org.eclipse.smarthome.binding.ntp_0.10.0.201811171951 [227]]
2018-11-28 07:15:23.722 [TRACE] [ig.xml.osgi.XmlDocumentBundleTracker] - Remaining bundles with /ESH-INF/thing/: [org.eclipse.smarthome.binding.astro_0.10.0.201811171951 [226], org.openhab.binding.squeezebox_2.4.0.201811150132 [190], org.openhab.binding.zwave_2.4.0.201811241129 [241], org.eclipse.smarthome.binding.ntp_0.10.0.201811171951 [227]]
2018-11-28 07:15:23.722 [TRACE] [ig.xml.osgi.XmlDocumentBundleTracker] - Remaining bundles with /ESH-INF/thing/: [org.eclipse.smarthome.binding.astro_0.10.0.201811171951 [226], org.openhab.binding.squeezebox_2.4.0.201811150132 [190], org.openhab.binding.zwave_2.4.0.201811241129 [241], org.eclipse.smarthome.binding.ntp_0.10.0.201811171951 [227]]
2018-11-28 07:15:23.723 [TRACE] [ig.xml.osgi.XmlDocumentBundleTracker] - Remaining bundles with /ESH-INF/thing/: [org.eclipse.smarthome.binding.astro_0.10.0.201811171951 [226], org.openhab.binding.squeezebox_2.4.0.201811150132 [190], org.openhab.binding.zwave_2.4.0.201811241129 [241], org.eclipse.smarthome.binding.ntp_0.10.0.201811171951 [227]]
2018-11-28 07:15:23.723 [TRACE] [ig.xml.osgi.XmlDocumentBundleTracker] - Remaining bundles with /ESH-INF/thing/: [org.eclipse.smarthome.binding.astro_0.10.0.201811171951 [226], org.openhab.binding.squeezebox_2.4.0.201811150132 [190], org.openhab.binding.zwave_2.4.0.201811241129 [241], org.eclipse.smarthome.binding.ntp_0.10.0.201811171951 [227]]
2018-11-28 07:15:23.724 [TRACE] [ig.xml.osgi.XmlDocumentBundleTracker] - Remaining bundles with /ESH-INF/thing/: [org.eclipse.smarthome.binding.astro_0.10.0.201811171951 [226], org.openhab.binding.squeezebox_2.4.0.201811150132 [190], org.openhab.binding.zwave_2.4.0.201811241129 [241], org.eclipse.smarthome.binding.ntp_0.10.0.201811171951 [227]]
2018-11-28 07:15:23.724 [TRACE] [ig.xml.osgi.XmlDocumentBundleTracker] - Remaining bundles with /ESH-INF/thing/: [org.eclipse.smarthome.binding.astro_0.10.0.201811171951 [226], org.openhab.binding.squeezebox_2.4.0.201811150132 [190], org.openhab.binding.zwave_2.4.0.201811241129 [241], org.eclipse.smarthome.binding.ntp_0.10.0.201811171951 [227]]
2018-11-28 07:15:23.725 [TRACE] [ig.xml.osgi.XmlDocumentBundleTracker] - Remaining bundles with /ESH-INF/thing/: [org.eclipse.smarthome.binding.astro_0.10.0.201811171951 [226], org.openhab.binding.squeezebox_2.4.0.201811150132 [190], org.openhab.binding.zwave_2.4.0.201811241129 [241], org.eclipse.smarthome.binding.ntp_0.10.0.201811171951 [227]]
2018-11-28 07:15:23.725 [TRACE] [ig.xml.osgi.XmlDocumentBundleTracker] - Remaining bundles with /ESH-INF/thing/: [org.eclipse.smarthome.binding.astro_0.10.0.201811171951 [226], org.openhab.binding.squeezebox_2.4.0.201811150132 [190], org.openhab.binding.zwave_2.4.0.201811241129 [241], org.eclipse.smarthome.binding.ntp_0.10.0.201811171951 [227]]
2018-11-28 07:15:23.725 [TRACE] [ig.xml.osgi.XmlDocumentBundleTracker] - Remaining bundles with /ESH-INF/thing/: [org.eclipse.smarthome.binding.astro_0.10.0.201811171951 [226], org.openhab.binding.squeezebox_2.4.0.201811150132 [190], org.openhab.binding.zwave_2.4.0.201811241129 [241], org.eclipse.smarthome.binding.ntp_0.10.0.201811171951 [227]]
2018-11-28 07:15:23.726 [TRACE] [ig.xml.osgi.XmlDocumentBundleTracker] - Remaining bundles with /ESH-INF/thing/: [org.eclipse.smarthome.binding.astro_0.10.0.201811171951 [226], org.openhab.binding.squeezebox_2.4.0.201811150132 [190], org.openhab.binding.zwave_2.4.0.201811241129 [241], org.eclipse.smarthome.binding.ntp_0.10.0.201811171951 [227]]
2018-11-28 07:15:23.726 [TRACE] [ig.xml.osgi.XmlDocumentBundleTracker] - Remaining bundles with /ESH-INF/thing/: [org.eclipse.smarthome.binding.astro_0.10.0.201811171951 [226], org.openhab.binding.squeezebox_2.4.0.201811150132 [190], org.openhab.binding.zwave_2.4.0.201811241129 [241], org.eclipse.smarthome.binding.ntp_0.10.0.201811171951 [227]]
2018-11-28 07:15:23.727 [DEBUG] [ig.xml.osgi.XmlDocumentBundleTracker] - Reading the XML document '/ESH-INF/thing/sun.xml' in module 'org.eclipse.smarthome.binding.astro'...
2018-11-28 07:15:23.746 [TRACE] [ig.xml.osgi.XmlDocumentBundleTracker] - Create an empty XmlDocumentProvider for the module 'org.eclipse.smarthome.binding.astro'.
2018-11-28 07:15:23.746 [DEBUG] [ig.xml.osgi.XmlDocumentBundleTracker] - Reading the XML document '/ESH-INF/thing/moon.xml' in module 'org.eclipse.smarthome.binding.astro'...
2018-11-28 07:15:23.749 [DEBUG] [ig.xml.osgi.XmlDocumentBundleTracker] - Reading the XML document '/ESH-INF/thing/channels.xml' in module 'org.eclipse.smarthome.binding.astro'...
2018-11-28 07:15:23.775 [TRACE] [ig.xml.osgi.XmlDocumentBundleTracker] - Remaining bundles with /ESH-INF/thing/: [org.openhab.binding.squeezebox_2.4.0.201811150132 [190], org.openhab.binding.zwave_2.4.0.201811241129 [241], org.eclipse.smarthome.binding.ntp_0.10.0.201811171951 [227]]
2018-11-28 07:15:23.776 [TRACE] [ig.xml.osgi.XmlDocumentBundleTracker] - Remaining bundles with /ESH-INF/thing/: [org.openhab.binding.squeezebox_2.4.0.201811150132 [190], org.openhab.binding.zwave_2.4.0.201811241129 [241], org.eclipse.smarthome.binding.ntp_0.10.0.201811171951 [227]]
2018-11-28 07:15:23.776 [TRACE] [ig.xml.osgi.XmlDocumentBundleTracker] - Remaining bundles with /ESH-INF/thing/: [org.openhab.binding.squeezebox_2.4.0.201811150132 [190], org.openhab.binding.zwave_2.4.0.201811241129 [241], org.eclipse.smarthome.binding.ntp_0.10.0.201811171951 [227]]
2018-11-28 07:15:23.777 [TRACE] [ig.xml.osgi.XmlDocumentBundleTracker] - Remaining bundles with /ESH-INF/thing/: [org.openhab.binding.squeezebox_2.4.0.201811150132 [190], org.openhab.binding.zwave_2.4.0.201811241129 [241], org.eclipse.smarthome.binding.ntp_0.10.0.201811171951 [227]]
2018-11-28 07:15:23.777 [TRACE] [ig.xml.osgi.XmlDocumentBundleTracker] - Remaining bundles with /ESH-INF/thing/: [org.openhab.binding.squeezebox_2.4.0.201811150132 [190], org.openhab.binding.zwave_2.4.0.201811241129 [241], org.eclipse.smarthome.binding.ntp_0.10.0.201811171951 [227]]
2018-11-28 07:15:23.787 [DEBUG] [ig.xml.osgi.XmlDocumentBundleTracker] - Reading the XML document '/ESH-INF/thing/aeotec/zwa001_0_0.xml' in module 'org.openhab.binding.zwave'...
2018-11-28 07:15:23.793 [TRACE] [ig.xml.osgi.XmlDocumentBundleTracker] - Create an empty XmlDocumentProvider for the module 'org.openhab.binding.zwave'.
2018-11-28 07:15:23.794 [DEBUG] [ig.xml.osgi.XmlDocumentBundleTracker] - Reading the XML document '/ESH-INF/thing/leviton/vrpd3_0_0.xml' in module 'org.openhab.binding.zwave'...
2018-11-28 07:15:23.796 [DEBUG] [ig.xml.osgi.XmlDocumentBundleTracker] - Reading the XML document '/ESH-INF/thing/leviton/dz1kd_0_0.xml' in module 'org.openhab.binding.zwave'...
2018-11-28 07:15:23.799 [DEBUG] [ig.xml.osgi.XmlDocumentBundleTracker] - Reading the XML document '/ESH-INF/thing/leviton/dzr15_0_0.xml' in module 'org.openhab.binding.zwave'...
2018-11-28 07:15:23.800 [DEBUG] [ig.xml.osgi.XmlDocumentBundleTracker] - Reading the XML document '/ESH-INF/thing/leviton/vre06_0_0.xml' in module 'org.openhab.binding.zwave'...
Many hundreds of zwave devices...
2018-11-28 07:15:24.922 [DEBUG] [ig.xml.osgi.XmlDocumentBundleTracker] - Reading the XML document '/ESH-INF/thing/everspring/st815_0_0.xml' in module 'org.openhab.binding.zwave'...
2018-11-28 07:15:24.923 [DEBUG] [ig.xml.osgi.XmlDocumentBundleTracker] - Reading the XML document '/ESH-INF/thing/homeseer/hsms100_0_0.xml' in module 'org.openhab.binding.zwave'...
2018-11-28 07:15:24.924 [DEBUG] [ig.xml.osgi.XmlDocumentBundleTracker] - Reading the XML document '/ESH-INF/thing/homeseer/hsls100_0_0.xml' in module 'org.openhab.binding.zwave'...
2018-11-28 07:15:24.925 [DEBUG] [ig.xml.osgi.XmlDocumentBundleTracker] - Reading the XML document '/ESH-INF/thing/rtc/ct101_0_0.xml' in module 'org.openhab.binding.zwave'...
2018-11-28 07:15:24.926 [DEBUG] [ig.xml.osgi.XmlDocumentBundleTracker] - Reading the XML document '/ESH-INF/thing/rtc/ct32_0_0.xml' in module 'org.openhab.binding.zwave'...
2018-11-28 07:15:24.928 [DEBUG] [ig.xml.osgi.XmlDocumentBundleTracker] - Reading the XML document '/ESH-INF/thing/vda/satellitevi_0_0.xml' in module 'org.openhab.binding.zwave'...
2018-11-28 07:15:24.929 [DEBUG] [ig.xml.osgi.XmlDocumentBundleTracker] - Reading the XML document '/ESH-INF/thing/vision/zl7101_0_0.xml' in module 'org.openhab.binding.zwave'...
2018-11-28 07:15:24.930 [DEBUG] [ig.xml.osgi.XmlDocumentBundleTracker] - Reading the XML document '/ESH-INF/thing/vision/zd2105_0_0.xml' in module 'org.openhab.binding.zwave'...
2018-11-28 07:15:24.930 [DEBUG] [ig.xml.osgi.XmlDocumentBundleTracker] - Reading the XML document '/ESH-INF/thing/vision/zw4101_0_0.xml' in module 'org.openhab.binding.zwave'...
2018-11-28 07:15:24.931 [DEBUG] [ig.xml.osgi.XmlDocumentBundleTracker] - Reading the XML document '/ESH-INF/thing/august/asl03_0_0.xml' in module 'org.openhab.binding.zwave'...
2018-11-28 07:15:24.971 [TRACE] [ig.xml.osgi.XmlDocumentBundleTracker] - Remaining bundles with /ESH-INF/thing/: [org.openhab.binding.squeezebox_2.4.0.201811150132 [190], org.eclipse.smarthome.binding.ntp_0.10.0.201811171951 [227]]
2018-11-28 07:15:24.971 [TRACE] [ig.xml.osgi.XmlDocumentBundleTracker] - Remaining bundles with /ESH-INF/thing/: [org.openhab.binding.squeezebox_2.4.0.201811150132 [190], org.eclipse.smarthome.binding.ntp_0.10.0.201811171951 [227]]
2018-11-28 07:15:24.972 [TRACE] [ig.xml.osgi.XmlDocumentBundleTracker] - Remaining bundles with /ESH-INF/thing/: [org.openhab.binding.squeezebox_2.4.0.201811150132 [190], org.eclipse.smarthome.binding.ntp_0.10.0.201811171951 [227]]
2018-11-28 07:15:24.973 [TRACE] [ig.xml.osgi.XmlDocumentBundleTracker] - Remaining bundles with /ESH-INF/thing/: [org.openhab.binding.squeezebox_2.4.0.201811150132 [190], org.eclipse.smarthome.binding.ntp_0.10.0.201811171951 [227]]
2018-11-28 07:15:24.973 [TRACE] [ig.xml.osgi.XmlDocumentBundleTracker] - Remaining bundles with /ESH-INF/thing/: [org.openhab.binding.squeezebox_2.4.0.201811150132 [190], org.eclipse.smarthome.binding.ntp_0.10.0.201811171951 [227]]
maggu2810 commented 5 years ago

Okay, but the IAE is gone. Correct?

If there are services "activated - deactivated - activated" the XML parsing procedure will restart. What I want to fix (here) is that this does not cause problems in the framework.

Identify WHY services are activated, deactivated and activated again is IMHO another story (that should be identified if it results in a hang).

mhilbush commented 5 years ago

Okay, but the IAE is gone. Correct?

I don't know because I can no longer start the system. My method of testing involved multiple restarts (sometimes as many as 20). Since the system no longer functions, I can't test it.

Identify WHY services are activated, deactivated and activated again is IMHO another story (that should be identified if it results in a hang).

I agree that the root cause of the activate-deactivate-activate is a separate issue. However, the hang was introduced when I installed the latest versions of these two bindings. If I reinstall the bindings from the build (I do this by deleting contents of tmp and cache), the system functions properly (except, of course, for the IAE).

maggu2810 commented 5 years ago

So, the best option would be if I am able to reproduce it myself. WDYT would it be enough to add the Z-Wave or do I also need to "use" the binding? Do I need a "slow" system (e.g. RPi)?

maggu2810 commented 5 years ago

Found it already while looking at the code.

Damn, I called lock twice (and unlock only once): https://github.com/eclipse/smarthome/compare/master...maggu2810:issue6534-part2?expand=1#diff-3e2d81b2cc44be09068b421658c754dfR75

mhilbush commented 5 years ago

I called lock twice (and unlock only once):

That'll do it.

So, the best option would be if I am able to reproduce it myself. WDYT would it be enough to add the Z-Wave or do I also need to "use" the binding?

I don't think you need to actually use the binding.

Do I need a "slow" system (e.g. RPi)?

Possibly the opposite. I seem to see it more frequently on a relatively old (but still fast at 3.7 GHz) 6-core AMD box. Maybe due to the opportunity for more concurrency?

maggu2810 commented 5 years ago

org.eclipse.smarthome.config.xml-0.10.0-SNAPSHOT.jar

mhilbush commented 5 years ago

Working again with this new version. Thank you!

I won't be able to do much testing tonight, but I'll get back on it in the morning.

mhilbush commented 5 years ago

Before I went out tonight I set it up so openHAB would restart every 5 minutes. When I got back there were 89 restarts, and there wasn't a single IAE in the log. I'm pretty comfortable saying you nailed it.

maggu2810 commented 5 years ago

Wow, thanks a lot for testing!