Homematic java.util.concurrent.TimeoutException

Simon_B · April 7, 2022, 10:48am

Hey guys,
since few days i receive some error logs related to my homematic. several items are not available and after few minutes everything seems to be fine.

Can you help me to identify the reason?

CCU3 (debmatic) and openHAB 3.3.0.M3
Binding Homematic 3.3.0.M3
are on the same PI
java -version
openjdk version “11.0.14” 2022-01-18
OpenJDK Runtime Environment (build 11.0.14+9-post-Raspbian-1deb11u1)
OpenJDK Server VM (build 11.0.14+9-post-Raspbian-1deb11u1, mixed mode)

```yaml
2022-04-07 12:33:19.801 [WARN ] [ternal.handler.HomematicThingHandler] - java.util.concurrent.TimeoutException

2022-04-07 12:33:49.822 [WARN ] [ternal.handler.HomematicThingHandler] - java.util.concurrent.ExecutionException: java.util.concurrent.TimeoutException: Total timeout 15000 ms elapsed

2022-04-07 12:34:40.593 [WARN ] [ternal.handler.HomematicThingHandler] - Could not reinitialize the device '00111BE99286E5': java.util.concurrent.TimeoutException

java.io.IOException: java.util.concurrent.TimeoutException

	at org.openhab.binding.homematic.internal.communicator.client.XmlRpcClient.send(XmlRpcClient.java:121) ~[?:?]

	at org.openhab.binding.homematic.internal.communicator.client.XmlRpcClient.sendMessage(XmlRpcClient.java:73) ~[?:?]

	at org.openhab.binding.homematic.internal.communicator.client.RpcClient.setChannelDatapointValues(RpcClient.java:244) ~[?:?]

	at org.openhab.binding.homematic.internal.communicator.AbstractHomematicGateway.setChannelDatapointValues(AbstractHomematicGateway.java:522) ~[?:?]

	at org.openhab.binding.homematic.internal.communicator.CcuGateway.setChannelDatapointValues(CcuGateway.java:109) ~[?:?]

	at org.openhab.binding.homematic.internal.communicator.AbstractHomematicGateway.loadChannelValues(AbstractHomematicGateway.java:492) ~[?:?]

	at org.openhab.binding.homematic.internal.handler.HomematicThingHandler.loadHomematicChannelValues(HomematicThingHandler.java:485) ~[?:?]

	at org.openhab.binding.homematic.internal.handler.HomematicThingHandler.updateStatus(HomematicThingHandler.java:503) ~[?:?]

	at org.openhab.binding.homematic.internal.handler.HomematicThingHandler.deviceLoaded(HomematicThingHandler.java:669) ~[?:?]

	at org.openhab.binding.homematic.internal.handler.HomematicBridgeHandler.onDeviceLoaded(HomematicBridgeHandler.java:339) ~[?:?]

	at org.openhab.binding.homematic.internal.handler.HomematicBridgeHandler.onNewDevice(HomematicBridgeHandler.java:301) ~[?:?]

	at org.openhab.binding.homematic.internal.communicator.AbstractHomematicGateway.newDevices(AbstractHomematicGateway.java:771) ~[?:?]

	at org.openhab.binding.homematic.internal.communicator.server.RpcResponseHandler.handleNewDevice(RpcResponseHandler.java:108) ~[?:?]

	at org.openhab.binding.homematic.internal.communicator.server.RpcResponseHandler.handleMethodCall(RpcResponseHandler.java:57) ~[?:?]

	at org.openhab.binding.homematic.internal.communicator.server.XmlRpcServer$ResponseHandler.handle(XmlRpcServer.java:125) ~[?:?]

	at org.eclipse.jetty.server.handler.HandlerWrapper.handle(HandlerWrapper.java:127) ~[bundleFile:9.4.43.v20210629]

	at org.eclipse.jetty.server.Server.handle(Server.java:516) ~[bundleFile:9.4.43.v20210629]

	at org.eclipse.jetty.server.HttpChannel.lambda$handle$1(HttpChannel.java:388) ~[bundleFile:9.4.43.v20210629]

	at org.eclipse.jetty.server.HttpChannel.dispatch(HttpChannel.java:633) [bundleFile:9.4.43.v20210629]

	at org.eclipse.jetty.server.HttpChannel.handle(HttpChannel.java:380) [bundleFile:9.4.43.v20210629]

	at org.eclipse.jetty.server.HttpConnection.onFillable(HttpConnection.java:277) [bundleFile:9.4.43.v20210629]

	at org.eclipse.jetty.io.AbstractConnection$ReadCallback.succeeded(AbstractConnection.java:311) [bundleFile:9.4.43.v20210629]

	at org.eclipse.jetty.io.FillInterest.fillable(FillInterest.java:105) [bundleFile:9.4.43.v20210629]

	at org.eclipse.jetty.io.ChannelEndPoint$1.run(ChannelEndPoint.java:104) [bundleFile:9.4.43.v20210629]

	at org.eclipse.jetty.util.thread.strategy.EatWhatYouKill.runTask(EatWhatYouKill.java:338) [bundleFile:9.4.43.v20210629]

	at org.eclipse.jetty.util.thread.strategy.EatWhatYouKill.doProduce(EatWhatYouKill.java:315) [bundleFile:9.4.43.v20210629]

	at org.eclipse.jetty.util.thread.strategy.EatWhatYouKill.tryProduce(EatWhatYouKill.java:173) [bundleFile:9.4.43.v20210629]

	at org.eclipse.jetty.util.thread.strategy.EatWhatYouKill.run(EatWhatYouKill.java:131) [bundleFile:9.4.43.v20210629]

	at org.eclipse.jetty.util.thread.ReservedThreadExecutor$ReservedThread.run(ReservedThreadExecutor.java:386) [bundleFile:9.4.43.v20210629]

	at org.eclipse.jetty.util.thread.QueuedThreadPool.runJob(QueuedThreadPool.java:883) [bundleFile:9.4.43.v20210629]

	at org.eclipse.jetty.util.thread.QueuedThreadPool$Runner.run(QueuedThreadPool.java:1034) [bundleFile:9.4.43.v20210629]

	at java.lang.Thread.run(Thread.java:829) [?:?]

Caused by: java.util.concurrent.TimeoutException

	at org.eclipse.jetty.client.util.FutureResponseListener.get(FutureResponseListener.java:109) ~[?:?]

	at org.openhab.binding.homematic.internal.communicator.client.XmlRpcClient.send(XmlRpcClient.java:111) ~[?:?]

	... 31 more

2022-04-07 12:34:40.673 [INFO ] [ng.homematic.internal.misc.MiscUtils] - Datapoint name '${sysVarAlarmZone1}' contains invalid characters, new Datapoint name '__sysVarAlarmZone1_'

2022-04-07 12:34:40.674 [INFO ] [ng.homematic.internal.misc.MiscUtils] - Datapoint name '${sysVarPresence}' contains invalid characters, new Datapoint name '__sysVarPresence_'

2022-04-07 12:34:40.688 [WARN ] [ternal.handler.HomematicThingHandler] - Datapoint 'GWE00000000:2#__ruleTmpProgramName_' not found on gateway '3014F711A0001F58A9A71BCE'

==> /var/log/openhab/events.log <==

2022-04-07 12:35:25.691 [INFO ] [ab.event.ThingStatusInfoChangedEvent] - Thing 'homematic:HmIP-BROLL:3014F711A0001F58A9A71BCE:00111BE99286E5' changed from ONLINE to OFFLINE (COMMUNICATION_ERROR): java.util.concurrent.TimeoutException

MHerbst · April 7, 2022, 5:47pm

Hi Simon,

does this alway happen for the same device or device type? Or for different devices?

What kind of Raspi is it?

Simon_B · April 14, 2022, 6:05pm

Hi this happens for some random devices.
Its an Raspberry 4 with 4gb RAM and Debianos.

MHerbst · April 24, 2022, 11:13am

This kind of problems is really hard to debug. I don’t know anything about debmatic. But I think that there are also log files in debmatic (maybe you have to increase a log level). Can you check these logs whether there are any entries at the same time(s) the problem in OH happens?

Simon_B · May 1, 2022, 8:38am

Some Logs from the CCU3

Mai 1 00:02:00 de.eq3.cbcs.server.core.otau.DeviceBackgroundUpdateSubsystem INFO  [vert.x-eventloop-thread-2] SYSTEM: Permanent-/Burstlistener Handler utilization: 0/50 used 
Mai 1 00:07:00 de.eq3.cbcs.server.core.otau.DeviceBackgroundUpdateSubsystem INFO  [vert.x-eventloop-thread-2] SYSTEM: Permanent-/Burstlistener Handler utilization: 0/50 used 
Mai 1 00:12:00 de.eq3.cbcs.server.core.otau.DeviceBackgroundUpdateSubsystem INFO  [vert.x-eventloop-thread-2] SYSTEM: Permanent-/Burstlistener Handler utilization: 0/50 used 
Mai 1 00:17:00 de.eq3.cbcs.server.core.otau.DeviceBackgroundUpdateSubsystem INFO  [vert.x-eventloop-thread-2] SYSTEM: Permanent-/Burstlistener Handler utilization: 0/50 used 
Mai 1 00:22:00 de.eq3.cbcs.server.core.otau.DeviceBackgroundUpdateSubsystem INFO  [vert.x-eventloop-thread-2] SYSTEM: Permanent-/Burstlistener Handler utilization: 0/50 used 
Mai 1 00:27:00 de.eq3.cbcs.server.core.otau.DeviceBackgroundUpdateSubsystem INFO  [vert.x-eventloop-thread-2] SYSTEM: Permanent-/Burstlistener Handler utilization: 0/50 used 
Mai 1 00:31:54 de.eq3.cbcs.legacy.bidcos.rpc.LegacyServiceHandler INFO  [vert.x-worker-thread-2] (un)registerCallback on LegacyServiceHandler called from url: http://192.168.1.119:9125 
Mai 1 00:31:54 de.eq3.cbcs.legacy.bidcos.rpc.internal.LegacyBackendNotificationHandler INFO  [f0364351-a82b-4e06-be95-5a8f8328d27e_WorkerPool-0] SYSTEM: LegacyBackendNotificationHandler Verticle or Worker started 
Mai 1 00:31:54 de.eq3.cbcs.legacy.bidcos.rpc.LegacyServiceHandler INFO  [vert.x-worker-thread-4] init finished 
Mai 1 00:31:54 de.eq3.cbcs.legacy.bidcos.rpc.internal.InterfaceInitializer INFO  [vert.x-worker-thread-4] Added InterfaceId: f0364351-a82b-4e06-be95-5a8f8328d27e 
Mai 1 00:31:54 de.eq3.ccu.virtualdevice.service.internal.rega.VirtualDeviceHandlerRega INFO  [vert.x-eventloop-thread-5] (un)registerCallback on VirtualDeviceHandlerRega called from url: http://192.168.1.119:9125 
Mai 1 00:31:54 de.eq3.ccu.virtualdevice.service.internal.rega.VirtualDeviceHandlerRega INFO  [vert.x-eventloop-thread-5] Added InterfaceId: f0364351-a82b-4e06-be95-5a8f8328d27e 
Mai 1 00:31:54 de.eq3.ccu.virtualdevice.service.internal.rega.BackendWorker INFO  [vert.x-worker-thread-16] Execute BackendCommand: de.eq3.ccu.virtualdevice.service.internal.rega.BackendUpdateDevicesCommand 
Mai 1 00:31:54 de.eq3.cbcs.legacy.bidcos.rpc.internal.DeviceUtil INFO  [vert.x-worker-thread-4] updateDevicesForClient f0364351-a82b-4e06-be95-5a8f8328d27e -> 205 device addresses will be added 
Mai 1 00:32:00 de.eq3.cbcs.server.core.otau.DeviceBackgroundUpdateSubsystem INFO  [vert.x-eventloop-thread-2] SYSTEM: Permanent-/Burstlistener Handler utilization: 0/50 used 
Mai 1 00:37:00 de.eq3.cbcs.server.core.otau.DeviceBackgroundUpdateSubsystem INFO  [vert.x-eventloop-thread-2] SYSTEM: Permanent-/Burstlistener Handler utilization: 0/50 used 
Mai 1 00:41:54 de.eq3.cbcs.legacy.bidcos.rpc.internal.InterfaceInitializer ERROR [vert.x-worker-thread-4] IO Exception: Could not add interface: f0364351-a82b-4e06-be95-5a8f8328d27e 
de.eq3.cbcs.legacy.communication.rpc.RpcIOException: java.net.SocketTimeoutException: Read timed out
	at de.eq3.cbcs.legacy.communication.rpc.internal.transport.http.HttpTransport.sendRequest(HttpTransport.java:110)
	at de.eq3.cbcs.legacy.communication.rpc.internal.rpc.RpcClient.sendRequest(RpcClient.java:94)
	at de.eq3.cbcs.legacy.communication.rpc.internal.rpc.RpcClient.invoke(RpcClient.java:82)
	at com.sun.proxy.$Proxy23.newDevices(Unknown Source)
	at de.eq3.cbcs.legacy.bidcos.rpc.internal.LegacyBackendClient.newDevices(LegacyBackendClient.java:157)
	at de.eq3.cbcs.legacy.bidcos.rpc.internal.DeviceUtil.synchronizedBackendDevices(DeviceUtil.java:230)
	at de.eq3.cbcs.legacy.bidcos.rpc.internal.InterfaceInitializer.handle(InterfaceInitializer.java:109)
	at de.eq3.cbcs.legacy.bidcos.rpc.internal.InterfaceInitializer.handle(InterfaceInitializer.java:26)
	at io.vertx.core.eventbus.impl.HandlerRegistration.deliver(HandlerRegistration.java:212)
	at io.vertx.core.eventbus.impl.HandlerRegistration.handle(HandlerRegistration.java:191)
	at io.vertx.core.eventbus.impl.EventBusImpl.lambda$deliverToHandler$3(EventBusImpl.java:505)
	at io.vertx.core.impl.ContextImpl.lambda$wrapTask$2(ContextImpl.java:337)
	at io.vertx.core.impl.TaskQueue.lambda$new$0(TaskQueue.java:60)
	at java.base/java.util.concurrent.ThreadPoolExecutor.runWorker(ThreadPoolExecutor.java:1128)
	at java.base/java.util.concurrent.ThreadPoolExecutor$Worker.run(ThreadPoolExecutor.java:628)
	at java.base/java.lang.Thread.run(Thread.java:829)
Caused by: java.net.SocketTimeoutException: Read timed out
	at java.base/java.net.SocketInputStream.socketRead0(Native Method)
	at java.base/java.net.SocketInputStream.socketRead(SocketInputStream.java:115)
	at java.base/java.net.SocketInputStream.read(SocketInputStream.java:168)
	at java.base/java.net.SocketInputStream.read(SocketInputStream.java:140)
	at org.apache.http.impl.io.AbstractSessionInputBuffer.fillBuffer(AbstractSessionInputBuffer.java:160)
	at org.apache.http.impl.io.SocketInputBuffer.fillBuffer(SocketInputBuffer.java:84)
	at org.apache.http.impl.io.AbstractSessionInputBuffer.readLine(AbstractSessionInputBuffer.java:273)
	at org.apache.http.impl.conn.DefaultHttpResponseParser.parseHead(DefaultHttpResponseParser.java:140)
	at org.apache.http.impl.conn.DefaultHttpResponseParser.parseHead(DefaultHttpResponseParser.java:57)
	at org.apache.http.impl.io.AbstractMessageParser.parse(AbstractMessageParser.java:261)
	at org.apache.http.impl.AbstractHttpClientConnection.receiveResponseHeader(AbstractHttpClientConnection.java:283)
	at org.apache.http.impl.conn.DefaultClientConnection.receiveResponseHeader(DefaultClientConnection.java:259)
	at org.apache.http.impl.conn.AbstractClientConnAdapter.receiveResponseHeader(AbstractClientConnAdapter.java:232)
	at org.apache.http.protocol.HttpRequestExecutor.doReceiveResponse(HttpRequestExecutor.java:272)
	at org.apache.http.protocol.HttpRequestExecutor.execute(HttpRequestExecutor.java:124)
	at org.apache.http.impl.client.DefaultRequestDirector.tryExecute(DefaultRequestDirector.java:686)
	at org.apache.http.impl.client.DefaultRequestDirector.execute(DefaultRequestDirector.java:488)
	at org.apache.http.impl.client.AbstractHttpClient.doExecute(AbstractHttpClient.java:884)
	at org.apache.http.impl.client.CloseableHttpClient.execute(CloseableHttpClient.java:82)
	at org.apache.http.impl.client.CloseableHttpClient.execute(CloseableHttpClient.java:107)
	at org.apache.http.impl.client.CloseableHttpClient.execute(CloseableHttpClient.java:55)
	at de.eq3.cbcs.legacy.communication.rpc.internal.transport.http.HttpTransport.sendRequest(HttpTransport.java:106)
	... 15 more
Mai 1 00:42:00 de.eq3.cbcs.server.core.otau.DeviceBackgroundUpdateSubsystem INFO  [vert.x-eventloop-thread-2] SYSTEM: Permanent-/Burstlistener Handler utilization: 0/50 used 
Mai 1 00:47:00 de.eq3.cbcs.server.core.otau.DeviceBackgroundUpdateSubsystem INFO  [vert.x-eventloop-thread-2] SYSTEM: Permanent-/Burstlistener Handler utilization: 0/50 used 
Mai 1 00:52:00 de.eq3.cbcs.server.core.otau.DeviceBackgroundUpdateSubsystem INFO  [vert.x-eventloop-thread-2] SYSTEM: Permanent-/Burstlistener Handler utilization: 0/50 used 
Mai 1 00:57:00 de.eq3.cbcs.server.core.otau.DeviceBackgroundUpdateSubsystem INFO  [vert.x-eventloop-thread-2] SYSTEM: Permanent-/Burstlistener Handler utilization: 0/50 used 
Mai 1 01:02:00 de.eq3.cbcs.server.core.otau.DeviceBackgroundUpdateSubsystem INFO  [vert.x-eventloop-thread-2] SYSTEM: Permanent-/Burstlistener Handler utilization: 0/50 used 
Mai 1 01:07:00 de.eq3.cbcs.server.core.otau.DeviceBackgroundUpdateSubsystem INFO  [vert.x-eventloop-thread-2] SYSTEM: Permanent-/Burstlistener Handler utilization: 0/50 used 
Mai 1 01:12:00 de.eq3.cbcs.server.core.otau.DeviceBackgroundUpdateSubsystem INFO  [vert.x-eventloop-thread-2] SYSTEM: Permanent-/Burstlistener Handler utilization: 0/50 used 
Mai 1 01:15:05 org.apache.http.impl.client.DefaultHttpClient INFO  [HmIP-RF_java_WorkerPool-1] I/O exception (java.net.SocketException) caught when processing request to {}->http://127.0.0.1:39292: Datenübergabe unterbrochen (broken pipe) (Write failed) 
Mai 1 01:15:05 org.apache.http.impl.client.DefaultHttpClient INFO  [HmIP-RF_java_WorkerPool-1] Retrying request to {}->http://127.0.0.1:39292

and the Logs from openhab:

2022-05-01 00:31:09.584 [WARN ] [ommunicator.AbstractHomematicGateway] - Connection lost on gateway '3014F711A0001F58A9A71BCE', cause: "IOException java.util.concurrent.ExecutionException: java.io.EOFException: HttpConnectionOverHTTP@11305d6::SocketChannelEndPoint@12aab27{l=/192.168.1.119:50214,r=/192.168.1.119:2001,ISHUT,fill=-,flush=-,to=12/0}{io=0/0,kio=0,kro=1}->HttpConnectionOverHTTP@11305d6(l:/192.168.1.119:50214 <-> r:/192.168.1.119:2001,closed=false)=>HttpChannelOverHTTP@12a6167(exchange=HttpExchange@86b632{req=HttpRequest[POST / HTTP/1.1]@1683fc1[TERMINATED/null] res=HttpResponse[null 0 null]@15fc498[PENDING/null]})[send=HttpSenderOverHTTP@1e6afcd(req=QUEUED,snd=COMPLETED,failure=null)[HttpGenerator@e8bea5{s=START}],recv=HttpReceiverOverHTTP@e0180e(rsp=IDLE,failure=null)[HttpParser{s=CLOSED,0 of -1}]]"
2022-05-01 00:31:54.669 [INFO ] [ommunicator.AbstractHomematicGateway] - Connection resumed on gateway '3014F711A0001F58A9A71BCE'
2022-05-01 00:32:04.759 [WARN ] [ernal.handler.HomematicBridgeHandler] - Device with address '0026DD89943172' not found on gateway '3014F711A0001F58A9A71BCE'
2022-05-01 00:34:25.098 [WARN ] [ternal.handler.HomematicThingHandler] - Value for datapoint HmDatapoint[name=CONF_BUTTON_TIME,value=255,defaultValue=255,type=INTEGER,minValue=1,maxValue=254,options=null,readOnly=false,readable=true,unit=minutes,description=CONF_BUTTON_TIME,info=null,paramsetType=MASTER,virtual=false,trigger=false] is outside of valid range, using default value for config.
2022-05-01 00:38:28.887 [WARN ] [ab.core.internal.events.EventHandler] - Dispatching event to subscriber 'org.openhab.core.io.monitor.internal.EventLogger@494b55' takes more than 5000ms.
2022-05-01 00:39:08.727 [INFO ] [ng.homematic.internal.misc.MiscUtils] - Datapoint name '${sysVarAlarmZone1}' contains invalid characters, new Datapoint name '__sysVarAlarmZone1_'
2022-05-01 00:39:08.728 [INFO ] [ng.homematic.internal.misc.MiscUtils] - Datapoint name '${sysVarPresence}' contains invalid characters, new Datapoint name '__sysVarPresence_'
2022-05-01 00:39:08.738 [INFO ] [ng.homematic.internal.misc.MiscUtils] - Datapoint name '${ruleTmpProgramName}' contains invalid characters, new Datapoint name '__ruleTmpProgramName_'
2022-05-01 00:39:55.169 [WARN ] [ternal.handler.HomematicThingHandler] - Could not reinitialize the device '00111BE99286E5': java.util.concurrent.ExecutionException: java.util.concurrent.TimeoutException: Total timeout 15000 ms elapsed
java.io.IOException: java.util.concurrent.ExecutionException: java.util.concurrent.TimeoutException: Total timeout 15000 ms elapsed
        at org.openhab.binding.homematic.internal.communicator.client.XmlRpcClient.send(XmlRpcClient.java:121) ~[?:?]
        at org.openhab.binding.homematic.internal.communicator.client.XmlRpcClient.sendMessage(XmlRpcClient.java:73) ~[?:?]
        at org.openhab.binding.homematic.internal.communicator.client.RpcClient.setChannelDatapointValues(RpcClient.java:244) ~[?:?]
        at org.openhab.binding.homematic.internal.communicator.AbstractHomematicGateway.setChannelDatapointValues(AbstractHomematicGateway.java:522) ~[?:?]
        at org.openhab.binding.homematic.internal.communicator.CcuGateway.setChannelDatapointValues(CcuGateway.java:109) ~[?:?]
        at org.openhab.binding.homematic.internal.communicator.AbstractHomematicGateway.loadChannelValues(AbstractHomematicGateway.java:492) ~[?:?]
        at org.openhab.binding.homematic.internal.handler.HomematicThingHandler.loadHomematicChannelValues(HomematicThingHandler.java:485) ~[?:?]
        at org.openhab.binding.homematic.internal.handler.HomematicThingHandler.updateStatus(HomematicThingHandler.java:503) ~[?:?]
        at org.openhab.binding.homematic.internal.handler.HomematicThingHandler.deviceLoaded(HomematicThingHandler.java:669) ~[?:?]
        at org.openhab.binding.homematic.internal.handler.HomematicBridgeHandler.onDeviceLoaded(HomematicBridgeHandler.java:339) ~[?:?]
        at org.openhab.binding.homematic.internal.handler.HomematicBridgeHandler.onNewDevice(HomematicBridgeHandler.java:301) ~[?:?]
        at org.openhab.binding.homematic.internal.communicator.AbstractHomematicGateway.newDevices(AbstractHomematicGateway.java:771) ~[?:?]
        at org.openhab.binding.homematic.internal.communicator.server.RpcResponseHandler.handleNewDevice(RpcResponseHandler.java:108) ~[?:?]
        at org.openhab.binding.homematic.internal.communicator.server.RpcResponseHandler.handleMethodCall(RpcResponseHandler.java:57) ~[?:?]
        at org.openhab.binding.homematic.internal.communicator.server.XmlRpcServer$ResponseHandler.handle(XmlRpcServer.java:125) ~[?:?]
        at org.eclipse.jetty.server.handler.HandlerWrapper.handle(HandlerWrapper.java:127) ~[bundleFile:9.4.43.v20210629]
        at org.eclipse.jetty.server.Server.handle(Server.java:516) ~[bundleFile:9.4.43.v20210629]
        at org.eclipse.jetty.server.HttpChannel.lambda$handle$1(HttpChannel.java:388) ~[bundleFile:9.4.43.v20210629]
        at org.eclipse.jetty.server.HttpChannel.dispatch(HttpChannel.java:633) [bundleFile:9.4.43.v20210629]
        at org.eclipse.jetty.server.HttpChannel.handle(HttpChannel.java:380) [bundleFile:9.4.43.v20210629]
        at org.eclipse.jetty.server.HttpConnection.onFillable(HttpConnection.java:277) [bundleFile:9.4.43.v20210629]
        at org.eclipse.jetty.io.AbstractConnection$ReadCallback.succeeded(AbstractConnection.java:311) [bundleFile:9.4.43.v20210629]
        at org.eclipse.jetty.io.FillInterest.fillable(FillInterest.java:105) [bundleFile:9.4.43.v20210629]
        at org.eclipse.jetty.io.ChannelEndPoint$1.run(ChannelEndPoint.java:104) [bundleFile:9.4.43.v20210629]
        at org.eclipse.jetty.util.thread.strategy.EatWhatYouKill.runTask(EatWhatYouKill.java:338) [bundleFile:9.4.43.v20210629]
        at org.eclipse.jetty.util.thread.strategy.EatWhatYouKill.doProduce(EatWhatYouKill.java:315) [bundleFile:9.4.43.v20210629]
        at org.eclipse.jetty.util.thread.strategy.EatWhatYouKill.tryProduce(EatWhatYouKill.java:173) [bundleFile:9.4.43.v20210629]
        at org.eclipse.jetty.util.thread.strategy.EatWhatYouKill.run(EatWhatYouKill.java:131) [bundleFile:9.4.43.v20210629]
        at org.eclipse.jetty.util.thread.ReservedThreadExecutor$ReservedThread.run(ReservedThreadExecutor.java:386) [bundleFile:9.4.43.v20210629]
        at org.eclipse.jetty.util.thread.QueuedThreadPool.runJob(QueuedThreadPool.java:883) [bundleFile:9.4.43.v20210629]
        at org.eclipse.jetty.util.thread.QueuedThreadPool$Runner.run(QueuedThreadPool.java:1034) [bundleFile:9.4.43.v20210629]
        at java.lang.Thread.run(Thread.java:829) [?:?]
Caused by: java.util.concurrent.ExecutionException: java.util.concurrent.TimeoutException: Total timeout 15000 ms elapsed
        at org.eclipse.jetty.client.util.FutureResponseListener.getResult(FutureResponseListener.java:118) ~[?:?]
        at org.eclipse.jetty.client.util.FutureResponseListener.get(FutureResponseListener.java:110) ~[?:?]
        at org.openhab.binding.homematic.internal.communicator.client.XmlRpcClient.send(XmlRpcClient.java:111) ~[?:?]
        ... 31 more
Caused by: java.util.concurrent.TimeoutException: Total timeout 15000 ms elapsed
        at org.eclipse.jetty.client.HttpConnection$RequestTimeouts.onExpired(HttpConnection.java:334) ~[?:?]
        at org.eclipse.jetty.client.HttpConnection$RequestTimeouts.onExpired(HttpConnection.java:314) ~[?:?]
        at org.eclipse.jetty.io.CyclicTimeouts.onTimeoutExpired(CyclicTimeouts.java:110) ~[?:?]
        at org.eclipse.jetty.io.CyclicTimeouts.access$100(CyclicTimeouts.java:50) ~[?:?]
        at org.eclipse.jetty.io.CyclicTimeouts$Timeouts.onTimeoutExpired(CyclicTimeouts.java:196) ~[?:?]
        at org.eclipse.jetty.io.CyclicTimeout$Wakeup.run(CyclicTimeout.java:298) ~[?:?]
        at java.util.concurrent.Executors$RunnableAdapter.call(Executors.java:515) ~[?:?]
        at java.util.concurrent.FutureTask.run(FutureTask.java:264) ~[?:?]
        at java.util.concurrent.ScheduledThreadPoolExecutor$ScheduledFutureTask.run(ScheduledThreadPoolExecutor.java:304) ~[?:?]
        at java.util.concurrent.ThreadPoolExecutor.runWorker(ThreadPoolExecutor.java:1128) ~[?:?]
        at java.util.concurrent.ThreadPoolExecutor$Worker.run(ThreadPoolExecutor.java:628) ~[?:?]
        ... 1 more
2022-05-01 00:41:55.861 [WARN ] [ternal.handler.HomematicThingHandler] - Value for datapoint HmDatapoint[name=CONF_BUTTON_TIME,value=255,defaultValue=255,type=INTEGER,minValue=1,maxValue=254,options=null,readOnly=false,readable=true,unit=minutes,description=CONF_BUTTON_TIME,info=null,paramsetType=MASTER,virtual=false,trigger=false] is outside of valid range, using default value for config.
2022-05-01 00:42:19.116 [ERROR] [ommunicator.AbstractHomematicGateway] - java.util.concurrent.ExecutionException: java.io.EOFException: HttpConnectionOverHTTP@60e87c::SocketChannelEndPoint@677f90{l=/192.168.1.119:56050,r=/192.168.1.119:9292,ISHUT,fill=-,flush=-,to=11533/0}{io=1/0,kio=1,kro=1}->HttpConnectionOverHTTP@60e87c(l:/192.168.1.119:56050 <-> r:/192.168.1.119:9292,closed=false)=>HttpChannelOverHTTP@d92344(exchange=HttpExchange@ea11b0{req=HttpRequest[POST /groups HTTP/1.1]@1943959[TERMINATED/null] res=HttpResponse[null 0 null]@285504[PENDING/null]})[send=HttpSenderOverHTTP@1ee9986(req=QUEUED,snd=COMPLETED,failure=null)[HttpGenerator@1c563da{s=START}],recv=HttpReceiverOverHTTP@17bc98a(rsp=IDLE,failure=null)[HttpParser{s=CLOSED,0 of -1}]]
java.io.IOException: java.util.concurrent.ExecutionException: java.io.EOFException: HttpConnectionOverHTTP@60e87c::SocketChannelEndPoint@677f90{l=/192.168.1.119:56050,r=/192.168.1.119:9292,ISHUT,fill=-,flush=-,to=11533/0}{io=1/0,kio=1,kro=1}->HttpConnectionOverHTTP@60e87c(l:/192.168.1.119:56050 <-> r:/192.168.1.119:9292,closed=false)=>HttpChannelOverHTTP@d92344(exchange=HttpExchange@ea11b0{req=HttpRequest[POST /groups HTTP/1.1]@1943959[TERMINATED/null] res=HttpResponse[null 0 null]@285504[PENDING/null]})[send=HttpSenderOverHTTP@1ee9986(req=QUEUED,snd=COMPLETED,failure=null)[HttpGenerator@1c563da{s=START}],recv=HttpReceiverOverHTTP@17bc98a(rsp=IDLE,failure=null)[HttpParser{s=CLOSED,0 of -1}]]
        at org.openhab.binding.homematic.internal.communicator.client.XmlRpcClient.send(XmlRpcClient.java:121) ~[?:?]
        at org.openhab.binding.homematic.internal.communicator.client.XmlRpcClient.sendMessage(XmlRpcClient.java:73) ~[?:?]
        at org.openhab.binding.homematic.internal.communicator.client.RpcClient.listDevices(RpcClient.java:211) ~[?:?]
        at org.openhab.binding.homematic.internal.communicator.AbstractHomematicGateway.getDeviceDescriptions(AbstractHomematicGateway.java:453) ~[?:?]
        at org.openhab.binding.homematic.internal.communicator.AbstractHomematicGateway.newDevices(AbstractHomematicGateway.java:763) ~[?:?]
        at org.openhab.binding.homematic.internal.communicator.server.RpcResponseHandler.handleNewDevice(RpcResponseHandler.java:108) ~[?:?]
        at org.openhab.binding.homematic.internal.communicator.server.RpcResponseHandler.handleMethodCall(RpcResponseHandler.java:57) ~[?:?]
        at org.openhab.binding.homematic.internal.communicator.server.XmlRpcServer$ResponseHandler.handle(XmlRpcServer.java:125) ~[?:?]
        at org.eclipse.jetty.server.handler.HandlerWrapper.handle(HandlerWrapper.java:127) ~[bundleFile:9.4.43.v20210629]
        at org.eclipse.jetty.server.Server.handle(Server.java:516) ~[bundleFile:9.4.43.v20210629]
        at org.eclipse.jetty.server.HttpChannel.lambda$handle$1(HttpChannel.java:388) ~[bundleFile:9.4.43.v20210629]
        at org.eclipse.jetty.server.HttpChannel.dispatch(HttpChannel.java:633) [bundleFile:9.4.43.v20210629]
        at org.eclipse.jetty.server.HttpChannel.handle(HttpChannel.java:380) [bundleFile:9.4.43.v20210629]
        at org.eclipse.jetty.server.HttpConnection.onFillable(HttpConnection.java:277) [bundleFile:9.4.43.v20210629]
        at org.eclipse.jetty.io.AbstractConnection$ReadCallback.succeeded(AbstractConnection.java:311) [bundleFile:9.4.43.v20210629]
        at org.eclipse.jetty.io.FillInterest.fillable(FillInterest.java:105) [bundleFile:9.4.43.v20210629]
        at org.eclipse.jetty.io.ChannelEndPoint$1.run(ChannelEndPoint.java:104) [bundleFile:9.4.43.v20210629]
        at org.eclipse.jetty.util.thread.strategy.EatWhatYouKill.runTask(EatWhatYouKill.java:338) [bundleFile:9.4.43.v20210629]
        at org.eclipse.jetty.util.thread.strategy.EatWhatYouKill.doProduce(EatWhatYouKill.java:315) [bundleFile:9.4.43.v20210629]
        at org.eclipse.jetty.util.thread.strategy.EatWhatYouKill.tryProduce(EatWhatYouKill.java:173) [bundleFile:9.4.43.v20210629]
        at org.eclipse.jetty.util.thread.strategy.EatWhatYouKill.run(EatWhatYouKill.java:131) [bundleFile:9.4.43.v20210629]
        at org.eclipse.jetty.util.thread.ReservedThreadExecutor$ReservedThread.run(ReservedThreadExecutor.java:386) [bundleFile:9.4.43.v20210629]
        at org.eclipse.jetty.util.thread.QueuedThreadPool.runJob(QueuedThreadPool.java:883) [bundleFile:9.4.43.v20210629]
        at org.eclipse.jetty.util.thread.QueuedThreadPool$Runner.run(QueuedThreadPool.java:1034) [bundleFile:9.4.43.v20210629]
        at java.lang.Thread.run(Thread.java:829) [?:?]
Caused by: java.util.concurrent.ExecutionException: java.io.EOFException: HttpConnectionOverHTTP@60e87c::SocketChannelEndPoint@677f90{l=/192.168.1.119:56050,r=/192.168.1.119:9292,ISHUT,fill=-,flush=-,to=11533/0}{io=1/0,kio=1,kro=1}->HttpConnectionOverHTTP@60e87c(l:/192.168.1.119:56050 <-> r:/192.168.1.119:9292,closed=false)=>HttpChannelOverHTTP@d92344(exchange=HttpExchange@ea11b0{req=HttpRequest[POST /groups HTTP/1.1]@1943959[TERMINATED/null] res=HttpResponse[null 0 null]@285504[PENDING/null]})[send=HttpSenderOverHTTP@1ee9986(req=QUEUED,snd=COMPLETED,failure=null)[HttpGenerator@1c563da{s=START}],recv=HttpReceiverOverHTTP@17bc98a(rsp=IDLE,failure=null)[HttpParser{s=CLOSED,0 of -1}]]
        at org.eclipse.jetty.client.util.FutureResponseListener.getResult(FutureResponseListener.java:118) ~[?:?]
        at org.eclipse.jetty.client.util.FutureResponseListener.get(FutureResponseListener.java:110) ~[?:?]
        at org.openhab.binding.homematic.internal.communicator.client.XmlRpcClient.send(XmlRpcClient.java:111) ~[?:?]
        ... 24 more
Caused by: java.io.EOFException: HttpConnectionOverHTTP@60e87c::SocketChannelEndPoint@677f90{l=/192.168.1.119:56050,r=/192.168.1.119:9292,ISHUT,fill=-,flush=-,to=11533/0}{io=1/0,kio=1,kro=1}->HttpConnectionOverHTTP@60e87c(l:/192.168.1.119:56050 <-> r:/192.168.1.119:9292,closed=false)=>HttpChannelOverHTTP@d92344(exchange=HttpExchange@ea11b0{req=HttpRequest[POST /groups HTTP/1.1]@1943959[TERMINATED/null] res=HttpResponse[null 0 null]@285504[PENDING/null]})[send=HttpSenderOverHTTP@1ee9986(req=QUEUED,snd=COMPLETED,failure=null)[HttpGenerator@1c563da{s=START}],recv=HttpReceiverOverHTTP@17bc98a(rsp=IDLE,failure=null)[HttpParser{s=CLOSED,0 of -1}]]
        at org.eclipse.jetty.client.http.HttpReceiverOverHTTP.earlyEOF(HttpReceiverOverHTTP.java:376) ~[?:?]
        at org.eclipse.jetty.http.HttpParser.parseNext(HttpParser.java:1614) ~[?:?]
        at org.eclipse.jetty.client.http.HttpReceiverOverHTTP.shutdown(HttpReceiverOverHTTP.java:259) ~[?:?]
        at org.eclipse.jetty.client.http.HttpReceiverOverHTTP.process(HttpReceiverOverHTTP.java:181) ~[?:?]
        at org.eclipse.jetty.client.http.HttpReceiverOverHTTP.receive(HttpReceiverOverHTTP.java:79) ~[?:?]
        at org.eclipse.jetty.client.http.HttpChannelOverHTTP.receive(HttpChannelOverHTTP.java:131) ~[?:?]
        at org.eclipse.jetty.client.http.HttpConnectionOverHTTP.onFillable(HttpConnectionOverHTTP.java:172) ~[?:?]
        ... 11 more

MHerbst · May 15, 2022, 5:23pm

Please excuse my late answer. I am quite busy currently.

The problem seems to happen deep in the communication between OH and the CCU. It is nearly impossible to debug. A possible solution could be to intercept this exception and retry again.

Simon_B · May 16, 2022, 9:11am

Hi martin, if you could explain to me what i should do, i could try to intercept it.

MHerbst · May 16, 2022, 5:40pm

This has to be implemented within the binding. There is already some sort of retry mechanism for the communication between OH and the CCU but it seems that it is not sufficient.

Simon_B · May 25, 2022, 3:36pm

I have installed new openhabian Image and the issue seems to be gone.

system · July 6, 2022, 7:36am

This topic was automatically closed 41 days after the last reply. New replies are no longer allowed.