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.
This is what I got with the update script this morning:
pi@raspberrypi3:/opt/openhab2 $ sudo runtime/bin/update 2.2.0-SNAPSHOT
#########################################
openHAB 2.x.x update script
#########################################
Making Temporary Directory
Downloading openHAB 2.2.0-SNAPSHOT...
###################################################### 75,9%
curl: (23) Failed writing body (2129 != 16384)
Download failed, version 2.2.0-SNAPSHOT does not exist.
If you believe this to be an error, please check the openHAB website. (www.openhab.org)
Instead the previous used script worked right out of the box.
It took a little while but #1112 is up and running. 
Only error still left:
2017-12-05 09:09:39.331 [WARN ] [nal.common.AbstractInvocationHandler] - Timeout of 5000ms exceeded while calling method 'EventSubscriber.receive()' on 'org.eclipse.smarthome.io.monitor.internal.EventLogger@56033'. Thread 'safeCall-36' (1504) is in state 'RUNNABLE'
but as far as I understand this was not part of the latest fixes.
I’m not sure if there’s much I can do about another process cancelling the download half-way through. Did this happen every time?
0
Hi @Olymp, did you have any addons installed in /usr/share/openhab2 or had the openhab2-addons package installed? ? I’m trying to get to the bottom of this.
I tried twice with the same result (stopped at 75,9%).
One minute later I tried the mentioned script which pulls the zip via
wget -N https://openhab.ci.cloudbees.com/job/openHAB-Distribution/lastSuccessfulBuild/artifact/distributions/openhab/target/openhab-$vHAB-SNAPSHOT.zip || (echo "failure downloading OH2";exit 1)
and it worked without any issues …
This is actually a very interesting one that might give us a clue of what’s happening in @Dries setup: The EventLogger is the simplest code, which should normally never ever take more than 5 seconds (but which seems to be the case according to your log entry).
So my assumption is that the logger itself blocks. Interestingly, @Dries’ log shows a gap of 8 seconds shortly before the blacklisting. The only good explanation for me is that during that time the log rollover is happening, which is done synchronously by log4j2 and thus zipping 16MB blocks the whole logging framework for more than 5 seconds, which pauses all our activity and thus leads to blacklisting even our event handling.
@Dries Does this sound plausible? Could you check if any log rollover has happened at that time?
Same question to @sihui here - was there any log rollover near the moment when you saw that timeout message?
1 Like
Nope, I always clean the logs after an upgrade to get a better overview what is going on. So at the time of the timout it was only a couple of kBytes in size.
But I’m using a custom log entry for the zwave logging. Just to make sure I will revert that and use the standard logging configuration for testing … but no time left today, will report tomorrow the results.