OH2 startup error in latest build

(Build #1098) works fine for me - all issues are gone - thanks a lot!

Hey Kai,
thanks for the update (1098) but my system is still out of order. Logs looking fine and also all things are online but my items are not initializing/responding. Unfortunately I can not switch to the last stable since I need the latest changes of the ESH repository (JS223).

My wife is already nervous and has set up candles in the whole apartment since the light is fully controlled via OpenHAB :grimacing:. I will breathe alot easier when stable 2.2 is out.

[Update]
Strange Behavior: Also my virtual items without binding relation does not fire any event messages. I don’t know how to track down this issue due to clean app log.

Well, if a broken OH has this fundamental impact, I would recommend to work with two environments. One is a production, and the other one is a test environment (can be a copy of your production), this allows you to test stuff before you put it in production.

I recognize the symptoms. Did you saw anything strange in your openhab.log? Something like this?

2017-11-25 13:48:11.172 [WARN ] [org.apache.karaf.services.eventadmin] - EventAdmin: Blacklisting ServiceReference [{org.osgi.service.event.EventHandler, org.eclipse.smarthome.core.events.EventPublisher}={event.topics=smarthome, component.name=org.eclipse.smarthome.core.internal.events.OSGiEventManager, component.id=52, service.id=149, service.bundleid=111, service.scope=bundle} | Bundle(org.eclipse.smarthome.core_0.9.0.201711242229 [111])] due to timeout!

Did you try to clear the cache?

I’m running OH 2.2 in a VM.
So I can easily switch between my snapshots.
In #1078 everything works fine (knx, zwave, hue…)
After upgrading to #1099 all Things were displayed as online - but none of them are executing commands to the real devices.
Is there a recommended way to upgrade in small steps to find the source of the errors?

@Philipp & @mashborn I have updated my productive system to the latest snapshot as well and had similar effects.

One major issue was that I had the HTTP binding on many items with requests that timed out. This cause the event handling to be black-listed and thus no events being processed anymore.
I don’t really know why the blacklisting happens now, if one binding isn’t returning quickly (which all of them are supposed to do, so we are actually talking about bugs in the bindings that now pop up) - I assume that something must have changed in Felix EventAdmin or Apache Karaf. I cannot rule out that it is due to some change in ESH (e.g. the new communication handling with profiles), though, but it is all a bit mysterious to me really…

@sjka is working on https://github.com/eclipse/smarthome/pull/4602, which should make sure that a single mis-behaving binding cannot impact the whole system anymore - we should have this in place next week.

Until then you can try to figure out what binding might cause the problem. I have removed the HTTP stuff in my case, which solved most of the problem for me. I still had a situation where no commands were processed after a start, but on a restart, everything was up normal again.

Hope this helps a bit for the moment!
Kai

Thanks for the information, @Kai.
For the moment I’ll stay at #1078 and try again when we crossed the #1100.

In #1098 - it seems that I now have an issue on the HUE binding:

Starting the system everything looks fine updates dropping in no errors…
After the following error in log - the system stops to send any output on the console:
(However If I remove the HUE things and restart everything is working. I’ll now double check with removing the HTTP binding which I’m using also.)

11:53:35.836 [INFO ] [smarthome.event.ThingUpdatedEvent    ] - Thing 'hue:bridge:001788406902' has been updated.
11:53:35.847 [INFO ] [ome.event.ThingStatusInfoChangedEvent] - 'hue:bridge:001788406902' changed from INITIALIZING to ONLINE
11:53:40.849 [WARN ] [org.apache.karaf.services.eventadmin ] - EventAdmin: Blacklisting ServiceReference [{org.osgi.service.event.EventHandler, org.eclipse.smarthome.core.events.EventPublisher}={event.topics=smarthome, component.name=org.eclipse.smarthome.core.internal.events.OSGiEventManager, component.id=37, service.id=140, service.bundleid=109, service.scope=bundle} | Bundle(org.eclipse.smarthome.core_0.9.0.201711242229 [109])] due to timeout!
11:53:40.867 [WARN ] [home.core.thing.internal.ThingManager] - Initializing handler for thing 'hue:0200:001788406902:1' takes more than 5000ms.
11:53:40.876 [WARN ] [home.core.thing.internal.ThingManager] - Initializing handler for thing 'hue:0200:001788406902:6' takes more than 5000ms.
11:53:40.890 [WARN ] [home.core.thing.internal.ThingManager] - Initializing handler for thing 'hue:0200:001788406902:4' takes more than 5000ms.
11:53:45.886 [WARN ] [home.core.thing.internal.ThingManager] - Initializing handler for thing 'hue:0100:001788406902:11' takes more than 5000ms.
11:53:45.921 [WARN ] [home.core.thing.internal.ThingManager] - Initializing handler for thing 'hue:0210:001788406902:3' takes more than 5000ms.
11:53:45.934 [WARN ] [home.core.thing.internal.ThingManager] - Initializing handler for thing 'hue:0100:001788406902:10' takes more than 5000ms.
11:53:46.008 [INFO ] [ome.event.ThingStatusInfoChangedEvent] - 'hue:0200:001788406902:1' changed from UNINITIALIZED (BRIDGE_UNINITIALIZED) to INITIALIZING
11:53:46.012 [INFO ] [smarthome.event.ThingUpdatedEvent    ] - Thing 'hue:0100:001788406902:7' has been updated.
11:53:46.027 [INFO ] [ome.event.ThingStatusInfoChangedEvent] - 'hue:0100:001788406902:7' changed from ONLINE to OFFLINE: Hue bridge reports light as not reachable.
11:53:46.038 [INFO ] [ome.event.ThingStatusInfoChangedEvent] - 'hue:0100:001788406902:7' changed from UNINITIALIZED (BRIDGE_UNINITIALIZED) to INITIALIZING
11:53:46.042 [INFO ] [ome.event.ThingStatusInfoChangedEvent] - 'hue:0200:001788406902:6' changed from UNINITIALIZED (BRIDGE_UNINITIALIZED) to INITIALIZING
11:53:46.045 [INFO ] [ome.event.ThingStatusInfoChangedEvent] - 'hue:0100:001788406902:9' changed from UNINITIALIZED (BRIDGE_UNINITIALIZED) to INITIALIZING
11:53:46.052 [INFO ] [ome.event.ThingStatusInfoChangedEvent] - 'hue:0100:001788406902:7' changed from INITIALIZING to ONLINE
11:53:46.059 [INFO ] [ome.event.ThingStatusInfoChangedEvent] - 'hue:0200:001788406902:4' changed from UNINITIALIZED (BRIDGE_UNINITIALIZED) to INITIALIZING
11:53:46.062 [INFO ] [ome.event.ThingStatusInfoChangedEvent] - 'hue:0200:001788406902:5' changed from UNINITIALIZED (BRIDGE_UNINITIALIZED) to INITIALIZING
11:53:50.904 [WARN ] [home.core.thing.internal.ThingManager] - Initializing handler for thing 'hue:0210:001788406902:8' takes more than 5000ms.

I did some analysis this morning as I also have the “Blacklisting”-Issue (right now on Build #1099)!
What I can say: In my setup it’s clearly because of the Hue-Binding. Adding 2 bulps are working, but as soon as I add one more and restart the system it doesn’t work anymore (Timeouts --> Blacklisting).

To still use the actual snapshot I have added this workaround to “org.apache.felix.eventadmin.impl.EventAdmin.cfg”:

org.apache.felix.eventadmin.Timeout=0

I know…not a nice solution but ok for me know :slight_smile:

Michael

4 Likes

@Dries: You are absolute right! Usually I use only stable builds on my production environment. However, version 2.1 has a bug that forces me to use the current snapshot, otherwise my JS223 rule will not work anymore. Issue is about invalid state for groups:

Tried to set invalid state 0.00000000 on item gAPT_LightBrightness of type DimmerItem, ignoring it

This error does not occur on every start, but yes, it does exist.

I use a stateless environment. Every restart is like a factory reset. See below:

@mashborn I use a docker environment for running my openhab stack (openhab, influxdb, grafana, chronograf, apache, watchtower, frontail). Like the official Docker image, I use the cloudbees builds as installation source. But as far I can see, only the last successful snapshot build is available for download. Is there any archive where I can find older builds?

Thanks for pushing me in this direction! I already disabled the HTTP Binding but I still getting a blacklisting message, sometimes :face_with_raised_eyebrow:. Regardless of whether the message appears or not, the event bus seems to be not working.

EventAdmin: Blacklisting ServiceReference [{org.osgi.service.event.EventHandler,org.eclipse.smarthome.core.events.EventPublisher}={event.topics=smarthome, component.name=org.eclipse.smarthome.core.internal.events.OSGiEventManager, component.id=50, service.id=137, service.bundleid=110, service.scope=bundle} | Bundle(org.eclipse.smarthome.core_0.9.0.201711242229 [110])] due to timeout!

Maybe not but it does the trick for now. Thank you very much for sharing!

Thanks for sharing!
I removed all HUE things - started the system - added the things (slowly) again.
Then I got the fault for every thing again.
Restarted the system - no more error - so far.

I’ve adopted your setting later - to play safe.

(HTTP binding seems to have no influence - I’ve only two items posting commands to a device.)

I’m trying to update from build 1073 to 1099 but I get error on startup.

2017-11-26 17:14:04.278 [ERROR] [core.karaf.internal.FeatureInstaller] - Failed installing 'openhab-package-"expert"': No matching features for openhab-package-"expert"/0.0.0
2017-11-26 17:14:04.372 [WARN ] [url.mvn.internal.AetherBasedResolver] - Error resolving artifact org.openhab.binding:org.openhab.binding.tellstick:jar:2.2.0-SNAPSHOT: [Could not find artifact org.openhab.binding:org.openhab.binding.tellstick:jar:2.2.0-SNAPSHOT]
java.io.IOException: Error resolving artifact org.openhab.binding:org.openhab.binding.tellstick:jar:2.2.0-SNAPSHOT: [Could not find artifact org.openhab.binding:org.openhab.binding.tellstick:jar:2.2.0-SNAPSHOT]
	at org.ops4j.pax.url.mvn.internal.AetherBasedResolver.resolve(AetherBasedResolver.java:720) [4:org.ops4j.pax.url.mvn:2.5.3]
	at org.ops4j.pax.url.mvn.internal.AetherBasedResolver.resolve(AetherBasedResolver.java:659) [4:org.ops4j.pax.url.mvn:2.5.3]
	at org.ops4j.pax.url.mvn.internal.AetherBasedResolver.resolve(AetherBasedResolver.java:600) [4:org.ops4j.pax.url.mvn:2.5.3]
	at org.ops4j.pax.url.mvn.internal.AetherBasedResolver.resolve(AetherBasedResolver.java:567) [4:org.ops4j.pax.url.mvn:2.5.3]
	at org.apache.karaf.features.internal.download.impl.MavenDownloadTask.download(MavenDownloadTask.java:47) [9:org.apache.karaf.features.core:4.1.3]
	at org.apache.karaf.features.internal.download.impl.AbstractRetryableDownloadTask.run(AbstractRetryableDownloadTask.java:60) [9:org.apache.karaf.features.core:4.1.3]
	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:1142) [?:?]
	at java.util.concurrent.ThreadPoolExecutor$Worker.run(ThreadPoolExecutor.java:617) [?:?]
	at java.lang.Thread.run(Thread.java:748) [?:?]
	Suppressed: shaded.org.eclipse.aether.transfer.ArtifactNotFoundException: Could not find artifact org.openhab.binding:org.openhab.binding.tellstick:jar:2.2.0-SNAPSHOT
		at shaded.org.eclipse.aether.internal.impl.DefaultArtifactResolver.resolve(DefaultArtifactResolver.java:434) [4:org.ops4j.pax.url.mvn:2.5.3]
		at shaded.org.eclipse.aether.internal.impl.DefaultArtifactResolver.resolveArtifacts(DefaultArtifactResolver.java:246) [4:org.ops4j.pax.url.mvn:2.5.3]
		at shaded.org.eclipse.aether.internal.impl.DefaultArtifactResolver.resolveArtifact(DefaultArtifactResolver.java:223) [4:org.ops4j.pax.url.mvn:2.5.3]
		at shaded.org.eclipse.aether.internal.impl.DefaultRepositorySystem.resolveArtifact(DefaultRepositorySystem.java:294) [4:org.ops4j.pax.url.mvn:2.5.3]
		at org.ops4j.pax.url.mvn.internal.AetherBasedResolver.resolve(AetherBasedResolver.java:705) [4:org.ops4j.pax.url.mvn:2.5.3]
		at org.ops4j.pax.url.mvn.internal.AetherBasedResolver.resolve(AetherBasedResolver.java:659) [4:org.ops4j.pax.url.mvn:2.5.3]
		at org.ops4j.pax.url.mvn.internal.AetherBasedResolver.resolve(AetherBasedResolver.java:600) [4:org.ops4j.pax.url.mvn:2.5.3]
		at org.ops4j.pax.url.mvn.internal.AetherBasedResolver.resolve(AetherBasedResolver.java:567) [4:org.ops4j.pax.url.mvn:2.5.3]
		at org.apache.karaf.features.internal.download.impl.MavenDownloadTask.download(MavenDownloadTask.java:47) [9:org.apache.karaf.features.core:4.1.3]
		at org.apache.karaf.features.internal.download.impl.AbstractRetryableDownloadTask.run(AbstractRetryableDownloadTask.java:60) [9:org.apache.karaf.features.core:4.1.3]
		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:1142) [?:?]
		at java.util.concurrent.ThreadPoolExecutor$Worker.run(ThreadPoolExecutor.java:617) [?:?]
		at java.lang.Thread.run(Thread.java:748) [?:?]
Caused by: shaded.org.eclipse.aether.resolution.ArtifactResolutionException: Error resolving artifact org.openhab.binding:org.openhab.binding.tellstick:jar:2.2.0-SNAPSHOT
	at shaded.org.eclipse.aether.internal.impl.DefaultArtifactResolver.resolve(DefaultArtifactResolver.java:444) ~[?:?]
	at shaded.org.eclipse.aether.internal.impl.DefaultArtifactResolver.resolveArtifacts(DefaultArtifactResolver.java:246) ~[?:?]
	at shaded.org.eclipse.aether.internal.impl.DefaultArtifactResolver.resolveArtifact(DefaultArtifactResolver.java:223) ~[?:?]
	at shaded.org.eclipse.aether.internal.impl.DefaultRepositorySystem.resolveArtifact(DefaultRepositorySystem.java:294) ~[?:?]
	at org.ops4j.pax.url.mvn.internal.AetherBasedResolver.resolve(AetherBasedResolver.java:705) ~[?:?]
	... 12 more
2017-11-26 17:14:04.450 [ERROR] [core.karaf.internal.FeatureInstaller] - Failed installing 'openhab-transformation-javascript, openhab-misc-"restdocs, openhab-ui-habpanel, openhab-transformation-"map, openhab-transformation-regex, openhab-binding-zwave, openhab-ui-"classic, openhab-transformation-xpath, openhab-ui-basic, openhab-misc-hueemulation", openhab-binding-sonos", openhab-binding-tellstick, openhab-binding-astro, openhab-ui-habmin", openhab-transformation-xslt, openhab-transformation-exec, openhab-transformation-jsonpath", openhab-ui-paper, openhab-binding-"tradfri, openhab-transformation-scale': Error:
	Error downloading mvn:org.openhab.binding/org.openhab.binding.tellstick/2.2.0-SNAPSHOT
2017-11-26 17:14:23.091 [INFO ] [el.core.internal.ModelRepositoryImpl] - Loading model 'alexa.items'
2017-11-26 17:14:23.169 [INFO ] [el.core.internal.ModelRepositoryImpl] - Loading model 'astro.items'
2017-11-26 17:14:23.216 [INFO ] [el.core.internal.ModelRepositoryImpl] - Loading model 'bedroom.items'
2017-11-26 17:14:23.231 [INFO ] [el.core.internal.ModelRepositoryImpl] - Loading model 'general.items'
2017-11-26 17:14:23.278 [INFO ] [el.core.internal.ModelRepositoryImpl] - Loading model 'hallway.items'
2017-11-26 17:14:23.294 [INFO ] [el.core.internal.ModelRepositoryImpl] - Loading model 'hobbyroom.items'
2017-11-26 17:14:23.310 [INFO ] [el.core.internal.ModelRepositoryImpl] - Loading model 'kitchen.items'
2017-11-26 17:14:23.310 [INFO ] [el.core.internal.ModelRepositoryImpl] - Loading model 'livingroom.items'
2017-11-26 17:14:23.356 [INFO ] [el.core.internal.ModelRepositoryImpl] - Loading model 'office.items'
2017-11-26 17:14:23.388 [INFO ] [el.core.internal.ModelRepositoryImpl] - Loading model 'recreationroom.items'
2017-11-26 17:14:23.403 [INFO ] [el.core.internal.ModelRepositoryImpl] - Loading model 'test.items'
2017-11-26 17:14:28.981 [INFO ] [thome.model.lsp.internal.ModelServer] - Language Server started on port 5007
2017-11-26 17:14:31.325 [INFO ] [el.core.internal.ModelRepositoryImpl] - Loading model 'alexa.rules'
2017-11-26 17:14:31.606 [INFO ] [el.core.internal.ModelRepositoryImpl] - Loading model 'test.rules'
2017-11-26 17:14:31.669 [INFO ] [el.core.internal.ModelRepositoryImpl] - Loading model 'recreationroom_tv_power.rules'
2017-11-26 17:14:31.731 [INFO ] [el.core.internal.ModelRepositoryImpl] - Loading model 'cron.rules'
2017-11-26 17:14:31.981 [INFO ] [el.core.internal.ModelRepositoryImpl] - Loading model 'astro.rules'
2017-11-26 17:14:32.794 [INFO ] [el.core.internal.ModelRepositoryImpl] - Loading model 'juppes.sitemap'
2017-11-26 17:14:33.106 [INFO ] [el.core.internal.ModelRepositoryImpl] - Loading model 'ikea_tradfri.things'
2017-11-26 17:14:35.169 [INFO ] [.dashboard.internal.DashboardService] - Started dashboard at http://X.X.X.X:8080
2017-11-26 17:14:35.169 [INFO ] [.dashboard.internal.DashboardService] - Started dashboard at https://>X.X.X.X:8443

I did get the same error but for Sonos the first time I tried, then I removed the Sonos binding and now I get this error.

I have followed the steps on this page to update: http://docs.openhab.org/installation/windows.html

Am I missing something or why is this happening?

I can add that nothing is happening and openHAB is never started. In the Web-interface all I get is a spinning waiting icon in the welcome screen. I never come to the place where I can choose PaperUI or the other. So after this error everything is stopped.

Thanks Michael. My Setup is working again with this fix, i am not using the HUE-Binding.

same here

Issue back again on 2.2 stable and latest 2.3 snapshot

2017-12-20 10:09:04.266 [ERROR] [org.openhab.binding.avmfritz ] - Component descriptor entry ‘OSGI-INF/.xml’ not found
2017-12-20 10:09:04.279 [ERROR] [org.openhab.binding.homematic ] - Component descriptor entry 'OSGI-INF/
.xml’ not found

Any chance to resolve this issue?

For the 2.3 snapshot I also get

2017-12-20 08:15:01.851 [ERROR] [org.openhab.binding.harmonyhub      ] - Component descriptor entry 'OSGI-INF/*.xml' not found
2017-12-20 08:15:02.319 [ERROR] [org.openhab.binding.network         ] - Component descriptor entry 'OSGI-INF/*.xml' not found

temporary solution: switch back to latest stable via command:

apt -y install openhab2=2.2.0-1 --force-yes

Is there now a solution to the problem? Ich have the same Issue on the actually 2.2 snapshot!