I think the biggest issue is that the backup/restore script is kept up to date with the changing needs of the OH. As the versions change, some files move around in userdata, some files need to be preserved, some files need to be replaced. The backup/restore scripts manages all of this and essentially will do the same things to your manually installed OH that an apt-get/yum install will do to upgrade and installed OH.
3 Likes
Ok, last night, right before bedtime I decided to turn off the workaround (I commented out org.apache.felix.eventadmin.Timeout=0).
Approximately one hour later, this appeared in my logs:
2017-12-02 01:05:15.916 [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=51, service.id=150, service.bundleid=111, service.scope=bundle} | Bundle(org.eclipse.smarthome.core_0.9.0.201712011551 [111])] due to timeout!
2017-12-02 01:05:16.705 [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=51, service.id=150, service.bundleid=111, service.scope=bundle} | Bundle(org.eclipse.smarthome.core_0.9.0.201712011551 [111])] due to timeout!
Which froze the entire system.
Iām on build #1103
Iām going to put back the workaround.
@Kai: if you need more info to troubleshoot this, let me know what you need.
[EDIT]
I think the cause of the blacklisting is my LG TV binding (Connect SDK). Right before blacklisting happened, I saw this in my events.log:
2017-12-02 01:05:15.853 [hingStatusInfoChangedEvent] - 'connectsdk:WebOSTV:192_168_3_20' changed from ONLINE: Device Ready to OFFLINE
2017-12-02 01:05:15.853 [vent.ItemStateChangedEvent] - LGTV_GV_Living_Power changed from ON to OFF
I would need to do additional checks to see if it is a coincidence.
Anyway, one binding should not be able to trigger a blacklist of the OH code.
[/EDIT]
I can confirm that my setup with Build #1103 is working without the workaround! No issues anymore 
Thx!!
Ok, I upgraded now, from 1073 to 1104. When I first started after the upgrade I got error message like
2017-12-02 10:28:13.328 [ERROR] [core.karaf.internal.FeatureInstaller] - Failed installing 'openhab-package-"standard"': No matching features for openhab-package-"standard"/0.0.0
in my log. So I stopped, manually removed the quotation marks from my org.openhag.addons.cfg and started again and after that things seem to work just fine!
Still struggling with something strange happening to some of my rules (I think itās complaining about ānowā being null), guess Iāll get back to that in a separate thread if I donāt solve it 
Anyway, one binding should not be able to trigger a blacklist of the OH code.
Fully ACK! Thatās why the whole event processing now works asynchronously.
For that very reason your case puzzles me! As I donāt know which way of installing OH your are using: Are you sure the tmp & cache folder were deleted while upgrading? The log at least shows the correct version numbers, but I just wanna be sure itās actually also running the correct code.
I would need to do additional checks to see if it is a coincidence.
That would be awesome, thanks for your help! Anything towards tracking down the mechanism how it happened is highly appreciated, as currently I canāt make any sense of it.
I can also confirm that the workaround is not needed anymore, even though the hue binding is still creating warnings at startup:
2017-12-03 12:05:23.441 [WARN ] [ome.core.thing.internal.ThingManager] - Initializing handler for thing 'hue:0210:0017884a3074:5' takes more than 5000ms.
2017-12-03 12:05:23.452 [WARN ] [nal.common.AbstractInvocationHandler] - Timeout of 5000ms exceeded while calling method 'ThingHandler.initialize()' on 'org.eclipse.smarthome.binding.hue.handler.HueLightHandler@189a57'. Thread 'safeCall-3' (101) is in state 'WAITING'
2017-12-03 12:05:23.460 [WARN ] [nal.common.AbstractInvocationHandler] - Timeout of 5000ms exceeded while calling method 'ThingHandler.initialize()' on 'org.eclipse.smarthome.binding.hue.handler.HueLightHandler@771cc0'. The task was still queued.
2017-12-03 12:05:23.461 [WARN ] [nal.common.AbstractInvocationHandler] - Timeout of 5000ms exceeded while calling method 'ThingHandler.initialize()' on 'org.eclipse.smarthome.binding.hue.handler.HueLightHandler@1ca466d'. Thread 'safeCall-2' (99) is in state 'WAITING'
Furthermore I also face the issue that after each upgrade via apt-get my bindings from the eclipse market place are gone.
I opened an issue yesterday about the hue initialization taking more than 5s.
I think this could be due to a bottleneck in the thread pool size, which currently only has 3 threads - I have created this PR in order to increase the pool.
If the HueLightHandler is causing a delay, 3 of them suffice to exhaust the pool, which would explain the effect.
@Dries and everybody else who still run into the blacklisting (not individual handler timeouts) issue: could you please switch the log level of org.eclipse.smarthome.core.internal.common to TRACE, i.e.
log:set TRACE org.eclipse.smarthome.core.internal.common
It would be interesting to see what happens there during the approx. 30 seconds before the blacklisting log entry occurs.
And no, an exhausted thread-pool should not cause this issue anymore. Although it for sure canāt hurt to increase its size anyway because it would result in a more responsive system at peak times on most hardware.
Hi Simon,
My upgrade from #1098 to #1103 was done via apt-get. So /tmp and /cache should be deleted automatically (I didnāt check).
I switched the workaround off this morning after upgrading to #1106. I just set the log level to what you suggested. Iāll keep an eye on it. My log is filling at a pretty high pace now. BTW, how to I set the level back to normal?
So far (10h later), I didnāt encounter the Blacklisting issue.
Although my Chromecast binding is sometimes generating this:
2017-12-03 13:59:50.441 [WARN ] [nal.common.AbstractInvocationHandler] - Timeout of 5000ms exceeded while calling method 'StateProfile.onCommandFromItem()' on 'org.eclipse.smarthome.core.thing.internal.profiles.SystemDefaultProfile@34e9c15d'. Thread 'safeCall-13' (414) is in state 'TIMED_WAITING'
at java.lang.Object.wait(Native Method)
at su.litvak.chromecast.api.v2.Channel$ResultProcessor.get(Channel.java:239)
at su.litvak.chromecast.api.v2.Channel.send(Channel.java:367)
at su.litvak.chromecast.api.v2.Channel.sendStandard(Channel.java:336)
at su.litvak.chromecast.api.v2.Channel.getMediaStatus(Channel.java:508)
at su.litvak.chromecast.api.v2.ChromeCast.getMediaStatus(ChromeCast.java:295)
at org.openhab.binding.chromecast.internal.ChromecastCommander.handleControl(ChromecastCommander.java:151)
at org.openhab.binding.chromecast.internal.ChromecastCommander.handleCommand(ChromecastCommander.java:61)
at org.openhab.binding.chromecast.handler.ChromecastHandler.handleCommand(ChromecastHandler.java:147)
at sun.reflect.GeneratedMethodAccessor188.invoke(Unknown Source)
at sun.reflect.DelegatingMethodAccessorImpl.invoke(DelegatingMethodAccessorImpl.java:43)
at java.lang.reflect.Method.invoke(Method.java:498)
at org.eclipse.smarthome.core.internal.common.AbstractInvocationHandler.invokeDirect(AbstractInvocationHandler.java:157)
at org.eclipse.smarthome.core.internal.common.InvocationHandlerSync.invoke(InvocationHandlerSync.java:56)
at com.sun.proxy.$Proxy144.handleCommand(Unknown Source)
...
Iāll post an update if I have new findings.
[EDIT]
Okay, logs are filling REALLY fast. I just generated 8Mb of data on openhab.log, and that includes just 3 minutes of TRACE. That will be about 160Mb/hour. Last time the system blacklisted something was during the night. Since OH just keeps a limited number of log-data, Iām not sure Iāll be able to see the trace info.
Ok, I have my Blacklist experience.
The 30 seconds before the Blacklist event holds 15Mb of data, so you can download it here:
https://goo.gl/gzsyXb
Below you can find what happens the last 0.2 second:
2017-12-03 22:01:16.243 [TRACE] [.internal.common.SafeCallManagerImpl] - Submitted invocation of 'receive()' on 'org.openhab.core.events.internal.EventBridge@983a679' for asynchronous execution
2017-12-03 22:01:16.243 [TRACE] [.internal.common.SafeCallManagerImpl] - Finished invocation of 'receive()' on 'org.openhab.core.events.internal.EventBridge@983a679'
2017-12-03 22:01:16.244 [TRACE] [.internal.common.SafeCallManagerImpl] - Triggering submissions for 'org.openhab.core.events.internal.EventBridge@983a679'
2017-12-03 22:01:16.244 [TRACE] [.internal.common.SafeCallManagerImpl] - Triggering submissions for 'org.eclipse.smarthome.core.autoupdate.internal.AutoUpdateBinding@46266bc'
2017-12-03 22:01:16.244 [TRACE] [.internal.common.SafeCallManagerImpl] - Scheduling invocation of 'receive()' on 'org.eclipse.smarthome.core.autoupdate.internal.AutoUpdateBinding@46266bc' for asynchronous execution
2017-12-03 22:01:16.245 [TRACE] [.internal.common.SafeCallManagerImpl] - Scheduling timeout watcher in 5000ms
2017-12-03 22:01:16.245 [TRACE] [.internal.common.SafeCallManagerImpl] - Submitted invocation of 'receive()' on 'org.eclipse.smarthome.core.autoupdate.internal.AutoUpdateBinding@46266bc' for asynchronous execution
2017-12-03 22:01:16.246 [TRACE] [.internal.common.SafeCallManagerImpl] - Finished invocation of 'receive()' on 'org.eclipse.smarthome.core.autoupdate.internal.AutoUpdateBinding@46266bc'
2017-12-03 22:01:16.246 [TRACE] [.internal.common.SafeCallManagerImpl] - Triggering submissions for 'org.eclipse.smarthome.core.autoupdate.internal.AutoUpdateBinding@46266bc'
2017-12-03 22:01:16.246 [TRACE] [.internal.common.SafeCallManagerImpl] - Triggering submissions for 'org.openhab.io.openhabcloud.internal.CloudService@82bd794'
2017-12-03 22:01:16.247 [TRACE] [.internal.common.SafeCallManagerImpl] - Scheduling invocation of 'receive()' on 'org.openhab.io.openhabcloud.internal.CloudService@82bd794' for asynchronous execution
2017-12-03 22:01:16.247 [TRACE] [.internal.common.SafeCallManagerImpl] - Scheduling timeout watcher in 5000ms
2017-12-03 22:01:24.258 [TRACE] [.internal.common.SafeCallManagerImpl] - Submitted invocation of 'receive()' on 'org.openhab.io.openhabcloud.internal.CloudService@82bd794' for asynchronous execution
2017-12-03 22:01:24.258 [TRACE] [.internal.common.SafeCallManagerImpl] - Triggering submissions for 'org.eclipse.smarthome.io.monitor.internal.EventLogger@35869479'
2017-12-03 22:01:24.259 [TRACE] [.internal.common.SafeCallManagerImpl] - Finished invocation of 'receive()' on 'org.openhab.io.openhabcloud.internal.CloudService@82bd794'
2017-12-03 22:01:24.259 [TRACE] [.internal.common.SafeCallManagerImpl] - Scheduling invocation of 'receive()' on 'org.eclipse.smarthome.io.monitor.internal.EventLogger@35869479' for asynchronous execution
2017-12-03 22:01:24.259 [TRACE] [.internal.common.SafeCallManagerImpl] - Triggering submissions for 'org.openhab.io.openhabcloud.internal.CloudService@82bd794'
2017-12-03 22:01:24.259 [TRACE] [.internal.common.SafeCallManagerImpl] - Submitted invocation of 'receive()' on 'org.eclipse.smarthome.io.monitor.internal.EventLogger@35869479' for asynchronous execution
2017-12-03 22:01:24.260 [TRACE] [.internal.common.SafeCallManagerImpl] - Scheduling timeout watcher in 5000ms
2017-12-03 22:01:24.260 [TRACE] [.internal.common.SafeCallManagerImpl] - Finished invocation of 'receive()' on 'org.eclipse.smarthome.io.monitor.internal.EventLogger@35869479'
2017-12-03 22:01:24.260 [TRACE] [.internal.common.SafeCallManagerImpl] - Triggering submissions for 'org.eclipse.smarthome.io.monitor.internal.EventLogger@35869479'
2017-12-03 22:01:24.260 [TRACE] [.internal.common.SafeCallManagerImpl] - Triggering submissions for 'org.eclipse.smarthome.model.rule.runtime.internal.engine.RuleEngineImpl@381081c0'
2017-12-03 22:01:24.261 [TRACE] [.internal.common.SafeCallManagerImpl] - Scheduling invocation of 'receive()' on 'org.eclipse.smarthome.model.rule.runtime.internal.engine.RuleEngineImpl@381081c0' for asynchronous execution
2017-12-03 22:01:24.261 [TRACE] [.internal.common.SafeCallManagerImpl] - Submitted invocation of 'receive()' on 'org.eclipse.smarthome.model.rule.runtime.internal.engine.RuleEngineImpl@381081c0' for asynchronous execution
2017-12-03 22:01:24.261 [TRACE] [.internal.common.SafeCallManagerImpl] - Triggering submissions for 'org.eclipse.smarthome.core.internal.items.ItemUpdater@2a1a16a8'
2017-12-03 22:01:24.261 [TRACE] [.internal.common.SafeCallManagerImpl] - Scheduling invocation of 'receive()' on 'org.eclipse.smarthome.core.internal.items.ItemUpdater@2a1a16a8' for asynchronous execution
2017-12-03 22:01:24.262 [TRACE] [.internal.common.SafeCallManagerImpl] - Submitted invocation of 'receive()' on 'org.eclipse.smarthome.core.internal.items.ItemUpdater@2a1a16a8' for asynchronous execution
2017-12-03 22:01:24.262 [TRACE] [.internal.common.SafeCallManagerImpl] - Triggering submissions for 'org.eclipse.smarthome.io.rest.sse.internal.listeners.SseEventSubscriber@22e5d4d0'
2017-12-03 22:01:24.262 [TRACE] [.internal.common.SafeCallManagerImpl] - Scheduling invocation of 'receive()' on 'org.eclipse.smarthome.io.rest.sse.internal.listeners.SseEventSubscriber@22e5d4d0' for asynchronous execution
2017-12-03 22:01:24.262 [TRACE] [.internal.common.SafeCallManagerImpl] - Scheduling timeout watcher in 5000ms
2017-12-03 22:01:24.262 [TRACE] [.internal.common.SafeCallManagerImpl] - Submitted invocation of 'receive()' on 'org.eclipse.smarthome.io.rest.sse.internal.listeners.SseEventSubscriber@22e5d4d0' for asynchronous execution
2017-12-03 22:01:24.263 [TRACE] [.internal.common.SafeCallManagerImpl] - Finished invocation of 'receive()' on 'org.eclipse.smarthome.io.rest.sse.internal.listeners.SseEventSubscriber@22e5d4d0'
2017-12-03 22:01:24.263 [TRACE] [.internal.common.SafeCallManagerImpl] - Triggering submissions for 'org.eclipse.smarthome.io.rest.sse.internal.listeners.SseEventSubscriber@22e5d4d0'
2017-12-03 22:01:24.264 [TRACE] [.internal.common.SafeCallManagerImpl] - Scheduling timeout watcher in 5000ms
2017-12-03 22:01:24.265 [TRACE] [.internal.common.SafeCallManagerImpl] - Finished invocation of 'receive()' on 'org.eclipse.smarthome.core.internal.items.ItemUpdater@2a1a16a8'
2017-12-03 22:01:24.265 [TRACE] [.internal.common.SafeCallManagerImpl] - Triggering submissions for 'org.eclipse.smarthome.core.internal.items.ItemUpdater@2a1a16a8'
2017-12-03 22:01:24.266 [TRACE] [.internal.common.SafeCallManagerImpl] - Scheduling timeout watcher in 5000ms
2017-12-03 22:01:24.266 [TRACE] [.internal.common.SafeCallManagerImpl] - Finished invocation of 'receive()' on 'org.eclipse.smarthome.model.rule.runtime.internal.engine.RuleEngineImpl@381081c0'
2017-12-03 22:01:24.267 [TRACE] [.internal.common.SafeCallManagerImpl] - Triggering submissions for 'org.eclipse.smarthome.model.rule.runtime.internal.engine.RuleEngineImpl@381081c0'
2017-12-03 22:01:24.263 [TRACE] [.internal.common.SafeCallManagerImpl] - Triggering submissions for 'org.eclipse.smarthome.core.thing.internal.CommunicationManager@573b4ad2'
2017-12-03 22:01:24.268 [TRACE] [.internal.common.SafeCallManagerImpl] - Scheduling invocation of 'receive()' on 'org.eclipse.smarthome.core.thing.internal.CommunicationManager@573b4ad2' for asynchronous execution
2017-12-03 22:01:24.269 [TRACE] [.internal.common.SafeCallManagerImpl] - Submitted invocation of 'receive()' on 'org.eclipse.smarthome.core.thing.internal.CommunicationManager@573b4ad2' for asynchronous execution
2017-12-03 22:01:24.269 [TRACE] [.internal.common.SafeCallManagerImpl] - Scheduling timeout watcher in 5000ms
2017-12-03 22:01:24.269 [TRACE] [.internal.common.SafeCallManagerImpl] - Triggering submissions for 'org.openhab.core.events.internal.EventBridge@983a679'
2017-12-03 22:01:24.269 [TRACE] [.internal.common.SafeCallManagerImpl] - Finished invocation of 'receive()' on 'org.eclipse.smarthome.core.thing.internal.CommunicationManager@573b4ad2'
2017-12-03 22:01:24.270 [TRACE] [.internal.common.SafeCallManagerImpl] - Triggering submissions for 'org.eclipse.smarthome.core.thing.internal.CommunicationManager@573b4ad2'
2017-12-03 22:01:24.270 [TRACE] [.internal.common.SafeCallManagerImpl] - Scheduling invocation of 'receive()' on 'org.openhab.core.events.internal.EventBridge@983a679' for asynchronous execution
2017-12-03 22:01:24.270 [TRACE] [.internal.common.SafeCallManagerImpl] - Submitted invocation of 'receive()' on 'org.openhab.core.events.internal.EventBridge@983a679' for asynchronous execution
2017-12-03 22:01:24.270 [TRACE] [.internal.common.SafeCallManagerImpl] - Scheduling timeout watcher in 5000ms
2017-12-03 22:01:24.271 [TRACE] [.internal.common.SafeCallManagerImpl] - Triggering submissions for 'org.eclipse.smarthome.core.autoupdate.internal.AutoUpdateBinding@46266bc'
2017-12-03 22:01:24.271 [TRACE] [.internal.common.SafeCallManagerImpl] - Finished invocation of 'receive()' on 'org.openhab.core.events.internal.EventBridge@983a679'
2017-12-03 22:01:24.271 [TRACE] [.internal.common.SafeCallManagerImpl] - Triggering submissions for 'org.openhab.core.events.internal.EventBridge@983a679'
2017-12-03 22:01:24.271 [TRACE] [.internal.common.SafeCallManagerImpl] - Scheduling invocation of 'receive()' on 'org.eclipse.smarthome.core.autoupdate.internal.AutoUpdateBinding@46266bc' for asynchronous execution
2017-12-03 22:01:24.271 [TRACE] [.internal.common.SafeCallManagerImpl] - Submitted invocation of 'receive()' on 'org.eclipse.smarthome.core.autoupdate.internal.AutoUpdateBinding@46266bc' for asynchronous execution
2017-12-03 22:01:24.271 [TRACE] [.internal.common.SafeCallManagerImpl] - Scheduling timeout watcher in 5000ms
2017-12-03 22:01:24.272 [TRACE] [.internal.common.SafeCallManagerImpl] - Triggering submissions for 'org.openhab.io.openhabcloud.internal.CloudService@82bd794'
2017-12-03 22:01:24.272 [TRACE] [.internal.common.SafeCallManagerImpl] - Finished invocation of 'receive()' on 'org.eclipse.smarthome.core.autoupdate.internal.AutoUpdateBinding@46266bc'
2017-12-03 22:01:24.272 [TRACE] [.internal.common.SafeCallManagerImpl] - Scheduling invocation of 'receive()' on 'org.openhab.io.openhabcloud.internal.CloudService@82bd794' for asynchronous execution
2017-12-03 22:01:24.272 [TRACE] [.internal.common.SafeCallManagerImpl] - Triggering submissions for 'org.eclipse.smarthome.core.autoupdate.internal.AutoUpdateBinding@46266bc'
2017-12-03 22:01:24.273 [TRACE] [.internal.common.SafeCallManagerImpl] - Scheduling timeout watcher in 5000ms
2017-12-03 22:01:24.273 [TRACE] [.internal.common.SafeCallManagerImpl] - Submitted invocation of 'receive()' on 'org.openhab.io.openhabcloud.internal.CloudService@82bd794' for asynchronous execution
2017-12-03 22:01:24.273 [TRACE] [.internal.common.SafeCallManagerImpl] - Finished invocation of 'receive()' on 'org.openhab.io.openhabcloud.internal.CloudService@82bd794'
2017-12-03 22:01:24.273 [TRACE] [.internal.common.SafeCallManagerImpl] - Triggering submissions for 'org.eclipse.smarthome.io.monitor.internal.EventLogger@35869479'
2017-12-03 22:01:24.273 [TRACE] [.internal.common.SafeCallManagerImpl] - Triggering submissions for 'org.openhab.io.openhabcloud.internal.CloudService@82bd794'
2017-12-03 22:01:24.273 [TRACE] [.internal.common.SafeCallManagerImpl] - Scheduling invocation of 'receive()' on 'org.eclipse.smarthome.io.monitor.internal.EventLogger@35869479' for asynchronous execution
2017-12-03 22:01:24.273 [TRACE] [.internal.common.SafeCallManagerImpl] - Scheduling timeout watcher in 5000ms
2017-12-03 22:01:24.285 [TRACE] [.internal.common.SafeCallManagerImpl] - Submitted invocation of 'receive()' on 'org.eclipse.smarthome.io.monitor.internal.EventLogger@35869479' for asynchronous execution
2017-12-03 22:01:24.286 [TRACE] [.internal.common.SafeCallManagerImpl] - Finished invocation of 'receive()' on 'org.eclipse.smarthome.io.monitor.internal.EventLogger@35869479'
2017-12-03 22:01:24.286 [TRACE] [.internal.common.SafeCallManagerImpl] - Triggering submissions for 'org.eclipse.smarthome.io.monitor.internal.EventLogger@35869479'
2017-12-03 22:01:24.384 [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=68, service.id=157, service.bundleid=111, service.scope=bundle} | Bundle(org.eclipse.smarthome.core_0.9.0.201712011551 [111])] due to timeout!
2017-12-03 22:01:24.422 [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=68, service.id=157, service.bundleid=111, service.scope=bundle} | Bundle(org.eclipse.smarthome.core_0.9.0.201712011551 [111])] due to timeout!
2017-12-03 22:01:24.449 [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=68, service.id=157, service.bundleid=111, service.scope=bundle} | Bundle(org.eclipse.smarthome.core_0.9.0.201712011551 [111])] due to timeout!
[EDIT]
One more blacklist event (while trace was switched off):
2017-12-03 22:51:18.769 [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=68, service.id=157, service.bundleid=111, service.scope=bundle} | Bundle(org.eclipse.smarthome.core_0.9.0.201712011551 [111])] due to timeout!
2017-12-03 22:51:19.913 [WARN ] [nal.common.AbstractInvocationHandler] - Timeout of 5000ms exceeded while calling method 'EventSubscriber.receive()' on 'org.eclipse.smarthome.io.monitor.internal.EventLogger@5318b8d6'. Thread 'safeCall-1' (131) is in state 'RUNNABLE'
at sun.misc.Unsafe.park(Native Method)
at java.util.concurrent.locks.LockSupport.parkNanos(LockSupport.java:215)
at java.util.concurrent.SynchronousQueue$TransferStack.awaitFulfill(SynchronousQueue.java:460)
at java.util.concurrent.SynchronousQueue$TransferStack.transfer(SynchronousQueue.java:362)
at java.util.concurrent.SynchronousQueue.poll(SynchronousQueue.java:941)
at java.util.concurrent.ThreadPoolExecutor.getTask(ThreadPoolExecutor.java:1073)
at java.util.concurrent.ThreadPoolExecutor.runWorker(ThreadPoolExecutor.java:1134)
at java.util.concurrent.ThreadPoolExecutor$Worker.run(ThreadPoolExecutor.java:624)
at java.lang.Thread.run(Thread.java:748)
2017-12-03 22:51:19.984 [WARN ] [ore.internal.events.OSGiEventManager] - Dispatching event to subscriber 'org.eclipse.smarthome.io.monitor.internal.EventLogger@5318b8d6' takes more than 5000ms.
2017-12-03 22:51:21.845 [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=68, service.id=157, service.bundleid=111, service.scope=bundle} | Bundle(org.eclipse.smarthome.core_0.9.0.201712011551 [111])] due to timeout!
2017-12-03 22:51:22.136 [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=68, service.id=157, service.bundleid=111, service.scope=bundle} | Bundle(org.eclipse.smarthome.core_0.9.0.201712011551 [111])] due to timeout!
2017-12-03 22:51:22.336 [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=68, service.id=157, service.bundleid=111, service.scope=bundle} | Bundle(org.eclipse.smarthome.core_0.9.0.201712011551 [111])] due to timeout!
2017-12-03 22:51:37.392 [WARN ] [org.apache.karaf.services.eventadmin] - EventAdmin: Blacklisting ServiceReference [{org.osgi.service.event.EventHandler, tuwien.auto.calimero.process.ProcessListener}={event.topics=openhab/*, component.name=org.openhab.binding.knx, component.id=219, service.id=358, service.bundleid=222, service.scope=bundle} | Bundle(org.openhab.binding.knx_1.11.0.201712030210 [222])] due to timeout!
2017-12-03 23:11:17.124 [ERROR] [com.connectsdk.core.Log ] - Connect SDK - Operation not permitted (sendto failed)
2017-12-03 23:11:35.737 [ERROR] [io.openhabcloud.internal.CloudClient] - Socket.IO error: {}
io.socket.engineio.client.EngineIOException: websocket error
at io.socket.engineio.client.Transport.onError(Transport.java:71) [228:org.openhab.io.openhabcloud:2.2.0.201712022337]
at io.socket.engineio.client.transports.WebSocket.access$500(WebSocket.java:28) [228:org.openhab.io.openhabcloud:2.2.0.201712022337]
at io.socket.engineio.client.transports.WebSocket$2$5.run(WebSocket.java:150) [228:org.openhab.io.openhabcloud:2.2.0.201712022337]
at io.socket.thread.EventThread$2.run(EventThread.java:80) [228:org.openhab.io.openhabcloud:2.2.0.201712022337]
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) [?:?]
Caused by: java.io.EOFException
at okio.RealBufferedSource.require(RealBufferedSource.java:59) ~[?:?]
at okio.RealBufferedSource.readByte(RealBufferedSource.java:72) ~[?:?]
at okhttp3.internal.ws.WebSocketReader.readHeader(WebSocketReader.java:115) ~[?:?]
at okhttp3.internal.ws.WebSocketReader.processNextFrame(WebSocketReader.java:104) ~[?:?]
at okhttp3.internal.ws.RealWebSocket.readMessage(RealWebSocket.java:97) ~[?:?]
at okhttp3.ws.WebSocketCall.createWebSocket(WebSocketCall.java:152) ~[?:?]
at okhttp3.ws.WebSocketCall.access$000(WebSocketCall.java:41) ~[?:?]
at okhttp3.ws.WebSocketCall$1.onResponse(WebSocketCall.java:97) ~[?:?]
at okhttp3.RealCall$AsyncCall.execute(RealCall.java:126) ~[?:?]
at okhttp3.internal.NamedRunnable.run(NamedRunnable.java:32) ~[?:?]
... 3 more
Iām now putting back in place the workaround, just to have a stable OH again. Let me know if you need more.
1 Like
Just updated to the latest build: openHAB 2.2.0 Build #1108
2017-12-04 15:51:42.933 [ERROR] [org.openhab.binding.network ] - Component descriptor entry 'OSGI-INF/*.xml' not found
I asked the question a couple of times, but I did not get an answer, Iām sorry that I will repeat, but it worries me very much. When I updated from # 1073 to # 1081 in the log, I received the following warnings:
2017-12-04 15:49:06.235 [WARN ] [org.eclipse.jetty.http.HttpParser ] - Illegal character 0x7F in state=HEADER_IN_VALUE for buffer DirectByteBuffer@20881805[p=188,l=2414,c=16384,r=2226]={HTTP/1.1 200 OK\r\n... 2017 07:49:06<<<\r\nEXT:\r\n\r\n<?xml v.../device></root>>>>\x00\x00\x00\x00\x00\x00\x00\x00\x00\x00\x00\x00\x00\x00\x00\x00\x00...\x00\x00\x00\x00\x00\x00\x00\x00\x00\x00\x00\x00\x00\x00\x00}
2017-12-04 15:49:06.250 [WARN ] [org.eclipse.jetty.http.HttpParser ] - bad HTTP parsed: 400 Illegal character 0x7F for HttpReceiverOverHTTP@658a8270(rsp=HEADER,failure=null)[HttpParser{s=HEADER_IN_VALUE,0 of 2216}]
2017-12-04 15:49:06.641 [WARN ] [org.eclipse.jetty.http.HttpParser ] - Illegal character 0x7F in state=HEADER_IN_VALUE for buffer DirectByteBuffer@6b6e997c[p=188,l=2414,c=16384,r=2226]={HTTP/1.1 200 OK\r\n... 2017 07:49:06<<<\r\nEXT:\r\n\r\n<?xml v.../device></root>>>>s="yes"><name>Phy...\x00\x00\x00\x00\x00\x00\x00\x00\x00\x00\x00\x00\x00\x00\x00}
2017-12-04 15:49:06.650 [WARN ] [org.eclipse.jetty.http.HttpParser ] - bad HTTP parsed: 400 Illegal character 0x7F for HttpReceiverOverHTTP@2e6c0a75(rsp=HEADER,failure=null)[HttpParser{s=HEADER_IN_VALUE,0 of 2216}]
2017-12-04 15:49:06.993 [INFO ] [basic.internal.servlet.WebAppServlet] - Started Basic UI at /basicui/app
2017-12-04 15:49:07.105 [INFO ] [arthome.ui.paper.internal.PaperUIApp] - Started Paper UI at /paperui
2017-12-04 15:49:07.153 [WARN ] [org.eclipse.jetty.http.HttpParser ] - Illegal character 0x7F in state=HEADER_IN_VALUE for buffer DirectByteBuffer@6b6e997c[p=188,l=2414,c=16384,r=2226]={HTTP/1.1 200 OK\r\n... 2017 07:49:07<<<\r\nEXT:\r\n\r\n<?xml v.../device></root>>>>tedStateVariable>...\x00\x00\x00\x00\x00\x00\x00\x00\x00\x00\x00\x00\x00\x00\x00}
2017-12-04 15:49:07.160 [WARN ] [org.eclipse.jetty.http.HttpParser ] - bad HTTP parsed: 400 Illegal character 0x7F for HttpReceiverOverHTTP@1bb613b9(rsp=HEADER,failure=null)[HttpParser{s=HEADER_IN_VALUE,0 of 2216}]
2017-12-04 15:49:07.529 [ERROR] [org.openhab.binding.network ] - Component descriptor entry 'OSGI-INF/*.xml' not found
2017-12-04 15:49:07.648 [WARN ] [org.eclipse.jetty.http.HttpParser ] - Illegal character 0x7F in state=HEADER_IN_VALUE for buffer DirectByteBuffer@6b6e997c[p=188,l=2414,c=16384,r=2226]={HTTP/1.1 200 OK\r\n... 2017 07:49:07<<<\r\nEXT:\r\n\r\n<?xml v.../device></root>>>>tedStateVariable>...\x00\x00\x00\x00\x00\x00\x00\x00\x00\x00\x00\x00\x00\x00\x00}
2017-12-04 15:49:07.651 [WARN ] [org.eclipse.jetty.http.HttpParser ] - bad HTTP parsed: 400 Illegal character 0x7F for HttpReceiverOverHTTP@4bdcfbbe(rsp=HEADER,failure=null)[HttpParser{s=HEADER_IN_VALUE,0 of 2216}]
On subsequent updates, up to #1108, warnings are present.
I reinstalled the ubuntu, mosquitto, java, openHAB2, influxDB, grafana. When the system was restarted, there were no warnings. I copied the files from the configuration folder /etc/openhab2 (I did not copy from the folder /var/lib/openhab2). I installed my bindings through paperUI, rebooted and received these warnings again.
To find, after which I receive these warnings, I deleted the openHAB completely (apt remove openhab2 --purge). Then, again, I installed: apt install openhab2 and again received warnings, on a clean installation, nothing yet tuning.
I ask for help, how to find, from what these warnings? What am I doing wrong?
Can you explain exactly what you mean by the update script?
Are you talking about the update function in openHABian? Is it possible to upgrade or downgrade to a certain distro with the update script?
That said if youāre using openHABian (apt) then you use the usual way of updating apps. As this covers what is in the update script.
I took a look at the actual artifacts. In the 1108, the generated descriptors were indeed missing. Taking a look at last two builds in cloudbees of the addons bundle (https://openhab.ci.cloudbees.com/job/openHAB2-Bundles/206/), the descriptors are there, but 1108 was based on an older build of openhab2-bundles (202), which is not available in Cloudbees anymore.
However, the newest build (1109, from an hour ago) again contains the necessary descriptors, so that problem should be solved.
Speaking of Update Scriptsā¦
Is there a reliable update solution for Windows based installs? The manual instructions are out of date as changes have been made in the logging files and others.
I know there has been a PowerShell based update script but the last time I checked it only worked moving to a stable version and not to any of the snapshots.
Is there a clean scripted way to update a Windows based install currently?
Thanks,
Squid
updated to # 1112
more openHAB does not work 
openhab.log:
2017-12-05 12:10:56.718 [INFO ] [.dashboard.internal.DashboardService] - Started dashboard at http://192.168.215.111:8080
2017-12-05 12:10:56.750 [INFO ] [.dashboard.internal.DashboardService] - Started dashboard at https://192.168.215.111:8443
2017-12-05 12:11:03.406 [INFO ] [el.core.internal.ModelRepositoryImpl] - Loading model 'sonoff.rules'
2017-12-05 12:11:03.904 [INFO ] [el.core.internal.ModelRepositoryImpl] - Loading model 'audio.rules'
2017-12-05 12:11:05.772 [INFO ] [el.core.internal.ModelRepositoryImpl] - Loading model 'climate.rules'
2017-12-05 12:11:09.729 [INFO ] [el.core.internal.ModelRepositoryImpl] - Loading model 'hiaomi.rules'
2017-12-05 12:11:10.362 [INFO ] [el.core.internal.ModelRepositoryImpl] - Loading model 'astro.rules'
2017-12-05 12:11:10.854 [INFO ] [el.core.internal.ModelRepositoryImpl] - Loading model 'scena.rules'
2017-12-05 12:11:11.647 [INFO ] [el.core.internal.ModelRepositoryImpl] - Loading model 'network.rules'
2017-12-05 12:11:12.729 [INFO ] [el.core.internal.ModelRepositoryImpl] - Loading model 'milights.rules'
2017-12-05 12:11:12.897 [INFO ] [el.core.internal.ModelRepositoryImpl] - Loading model 'lightbox.rules'
2017-12-05 12:11:13.832 [INFO ] [el.core.internal.ModelRepositoryImpl] - Loading model 'co2.rules'
2017-12-05 12:11:15.704 [WARN ] [org.eclipse.jetty.http.HttpParser ] - Illegal character 0x7F in state=HEADER_IN_VALUE for buffer DirectByteBuffer@6e3ec3b[p=188,l=2414,c=16384,r=2226]={HTTP/1.1 200 OK\r\n... 2017 04:11:15<<<\r\nEXT:\r\n\r\n<?xml v.../device></root>>>>\x00\x00\x00\x00\x00\x00\x00\x00\x00\x00\x00\x00\x00\x00\x00\x00\x00...\x00\x00\x00\x00\x00\x00\x00\x00\x00\x00\x00\x00\x00\x00\x00}
2017-12-05 12:11:15.718 [WARN ] [org.eclipse.jetty.http.HttpParser ] - bad HTTP parsed: 400 Illegal character 0x7F for HttpReceiverOverHTTP@11147589(rsp=HEADER,failure=null)[HttpParser{s=HEADER_IN_VALUE,0 of 2216}]
2017-12-05 12:11:16.255 [WARN ] [org.eclipse.jetty.http.HttpParser ] - Illegal character 0x7F in state=HEADER_IN_VALUE for buffer DirectByteBuffer@11233eb7[p=188,l=2414,c=16384,r=2226]={HTTP/1.1 200 OK\r\n... 2017 04:11:16<<<\r\nEXT:\r\n\r\n<?xml v.../device></root>>>>ype></stateVariab...\x00\x00\x00\x00\x00\x00\x00\x00\x00\x00\x00\x00\x00\x00\x00}
2017-12-05 12:11:16.258 [WARN ] [org.eclipse.jetty.http.HttpParser ] - bad HTTP parsed: 400 Illegal character 0x7F for HttpReceiverOverHTTP@5421b2f7(rsp=HEADER,failure=null)[HttpParser{s=HEADER_IN_VALUE,0 of 2216}]
2017-12-05 12:11:16.770 [WARN ] [org.eclipse.jetty.http.HttpParser ] - Illegal character 0x7F in state=HEADER_IN_VALUE for buffer DirectByteBuffer@11233eb7[p=188,l=2414,c=16384,r=2226]={HTTP/1.1 200 OK\r\n... 2017 04:11:16<<<\r\nEXT:\r\n\r\n<?xml v.../device></root>>>>ype></stateVariab...\x00\x00\x00\x00\x00\x00\x00\x00\x00\x00\x00\x00\x00\x00\x00}
2017-12-05 12:11:16.782 [WARN ] [org.eclipse.jetty.http.HttpParser ] - bad HTTP parsed: 400 Illegal character 0x7F for HttpReceiverOverHTTP@72ed6f63(rsp=HEADER,failure=null)[HttpParser{s=HEADER_IN_VALUE,0 of 2216}]
2017-12-05 12:11:17.257 [WARN ] [org.eclipse.jetty.http.HttpParser ] - Illegal character 0x7F in state=HEADER_IN_VALUE for buffer DirectByteBuffer@6e3ec3b[p=188,l=2414,c=16384,r=2226]={HTTP/1.1 200 OK\r\n... 2017 04:11:17<<<\r\nEXT:\r\n\r\n<?xml v.../device></root>>>>tedStateVariable>...\x00\x00\x00\x00\x00\x00\x00\x00\x00\x00\x00\x00\x00\x00\x00}
2017-12-05 12:11:17.259 [WARN ] [org.eclipse.jetty.http.HttpParser ] - bad HTTP parsed: 400 Illegal character 0x7F for HttpReceiverOverHTTP@efbf6d3(rsp=HEADER,failure=null)[HttpParser{s=HEADER_IN_VALUE,0 of 2216}]
2017-12-05 12:11:19.575 [INFO ] [el.core.internal.ModelRepositoryImpl] - Loading model 'mapdb.persist'
2017-12-05 12:11:19.604 [INFO ] [el.core.internal.ModelRepositoryImpl] - Loading model 'influxdb.persist'
2017-12-05 12:11:20.204 [INFO ] [el.core.internal.ModelRepositoryImpl] - Loading model 'monitor.items'
2017-12-05 12:11:20.398 [INFO ] [el.core.internal.ModelRepositoryImpl] - Loading model 'network.items'
2017-12-05 12:11:20.585 [INFO ] [el.core.internal.ModelRepositoryImpl] - Loading model 'astro.items'
2017-12-05 12:11:20.814 [INFO ] [el.core.internal.ModelRepositoryImpl] - Loading model 'plex.items'
2017-12-05 12:11:20.944 [INFO ] [el.core.internal.ModelRepositoryImpl] - Loading model 'co2.items'
2017-12-05 12:11:20.986 [INFO ] [el.core.internal.ModelRepositoryImpl] - Loading model 'main.items'
2017-12-05 12:11:21.202 [INFO ] [el.core.internal.ModelRepositoryImpl] - Loading model 'climate.items'
2017-12-05 12:11:21.433 [INFO ] [el.core.internal.ModelRepositoryImpl] - Loading model 'hiaomi.items'
2017-12-05 12:11:21.914 [INFO ] [el.core.internal.ModelRepositoryImpl] - Loading model 'sonoff.items'
2017-12-05 12:11:22.373 [INFO ] [el.core.internal.ModelRepositoryImpl] - Loading model 'bell.items'
2017-12-05 12:11:22.396 [INFO ] [el.core.internal.ModelRepositoryImpl] - Loading model 'audio.items'
2017-12-05 12:11:22.427 [INFO ] [el.core.internal.ModelRepositoryImpl] - Loading model 'milight.items'
2017-12-05 12:11:22.970 [INFO ] [el.core.internal.ModelRepositoryImpl] - Loading model 'network.things'
2017-12-05 12:11:23.015 [INFO ] [el.core.internal.ModelRepositoryImpl] - Loading model 'astro.things'
2017-12-05 12:11:23.389 [INFO ] [thome.model.lsp.internal.ModelServer] - Started Language Server Protocol (LSP) service on port 5007
2017-12-05 12:11:24.335 [INFO ] [el.core.internal.ModelRepositoryImpl] - Loading model 'garage.sitemap'
2017-12-05 12:11:24.411 [INFO ] [el.core.internal.ModelRepositoryImpl] - Loading model 'telefon.sitemap'
2017-12-05 12:11:24.461 [INFO ] [el.core.internal.ModelRepositoryImpl] - Loading model 'plex.sitemap'
2017-12-05 12:11:29.254 [WARN ] [.core.transform.TransformationHelper] - Cannot get service reference for transformation service of type MAP
2017-12-05 12:11:29.258 [WARN ] [.core.transform.TransformationHelper] - Couldn't transform value because transformation service of type 'MAP' is not available.
2017-12-05 12:11:35.738 [INFO ] [home.model.script.RULE.SystemStarted] - <-- System Started
2017-12-05 12:11:37.942 [ERROR] [core.voice.internal.VoiceManagerImpl] - Error saying 'system started': No TTS service can be found for voice voicerss:enEN
Removed #1112, installed # 1109 (apt remove openhab2, apt install openhab2=2.2.0~20171204120242-1)
Also, it does not start.
removed #1109, installed # 1108 (apt remove openhab2, apt install openhab2=2.2.0~20171204033232-1)
Also, it does not start.
Tried it on another computer, #1112 works if the previous installation is removed completely (apt purge openhab2)
if the update (apt upgrade) is not started.