search

eclipse-archived / smarthome

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

[homematic] java.io.EOFException if slow connection between CCU and openHAB2 (vpn) #5782

Closed mdicke2s closed 6 years ago

mdicke2s commented 6 years ago

From @BOFH90 on July 5, 2017 14:7

When running OpenHAB2 2.1.0 (Stable) with installed homematic-binding and a CCU2 (Raspberrymatic) via a slow Connection (e.g. openVPN) with response-times avg. 200-8000ms a java.io-EOFException is shown and the RPC-Server is not restarting anymore & binding to the port failed as the address is already in use. Therefore the Commands are not executed and states are not received after the Exeption. Below you can see the log-file for this case:

2017-07-05 10:44:40.813 [INFO ] [.dashboard.internal.DashboardService] - Started dashboard at http://x.x.x.x:8080
2017-07-05 10:44:40.813 [INFO ] [.dashboard.internal.DashboardService] - Started dashboard at https://x.x.x.x:8443
2017-07-05 10:44:41.105 [INFO ] [basic.internal.servlet.WebAppServlet] - Started Basic UI at /basicui/app
2017-07-05 10:44:41.175 [INFO ] [arthome.ui.paper.internal.PaperUIApp] - Started Paper UI at /paperui
2017-07-05 10:44:41.674 [INFO ] [panel.internal.HABPanelDashboardTile] - Started HABPanel at /habpanel
2017-07-05 10:44:41.949 [INFO ] [ternal.communicator.client.RpcClient] - Interface 'WIRED' on gateway '12df991b' not available, disabling support
2017-07-05 10:44:42.239 [INFO ] [ternal.communicator.client.RpcClient] - Interface 'CUXD' on gateway '12df991b' not available, disabling support
2017-07-05 10:44:42.467 [INFO ] [ommunicator.AbstractHomematicGateway] - HmGatewayInfo[id=CCU,type=CCU2,firmware=2.27.8.20170620,address=NEQxxxxxx,wired=false,hmip=true,cuxd=false,group=true]
2017-07-05 10:46:13.233 [INFO ] [ng.homematic.internal.misc.MiscUtils] - Datapoint name '${sysVarPresence}' contains invalid characters, new Datapoint name '__sysVarPresence_'
2017-07-05 10:46:19.736 [WARN ] [ore.internal.events.OSGiEventManager] - Dispatching event to subscriber 'org.eclipse.smarthome.core.thing.link.ThingLinkManager@1211a3b3' takes more than 5000ms.
2017-07-05 10:53:13.445 [INFO ] [ommunicator.AbstractHomematicGateway] - No event since 337 seconds from gateway '12df991b', restarting RPC server
2017-07-05 10:54:46.618 [INFO ] [ommunicator.AbstractHomematicGateway] - No event since 430 seconds from gateway '12df991b', restarting RPC server
2017-07-05 10:55:31.959 [WARN ] [ommunicator.AbstractHomematicGateway] - java.io.EOFException: HttpConnectionOverHTTP@6b0b27cd(l:/x.x.y.194:52112 <-> r:/x.x.x.241:9292,closed=false)[HttpChannelOverHTTP@65ccd4dc(exchange=HttpExchange@61f34cbd req=TERMINATED/null@null res=PENDING/null@null)[send=HttpSenderOverHTTP@24f1dee7(req=QUEUED,snd=COMPLETED,failure=null)[HttpGenerator{s=START}],recv=HttpReceiverOverHTTP@16f6b0fb(rsp=IDLE,failure=null)[HttpParser{s=CLOSED,0 of -1}]]]
java.io.IOException: java.io.EOFException: HttpConnectionOverHTTP@6b0b27cd(l:/x.x.y.194:52112 <-> r:/x.x.x.241:9292,closed=false)[HttpChannelOverHTTP@65ccd4dc(exchange=HttpExchange@61f34cbd req=TERMINATED/null@null res=PENDING/null@null)[send=HttpSenderOverHTTP@24f1dee7(req=QUEUED,snd=COMPLETED,failure=null)[HttpGenerator{s=START}],recv=HttpReceiverOverHTTP@16f6b0fb(rsp=IDLE,failure=null)[HttpParser{s=CLOSED,0 of -1}]]]
        at org.openhab.binding.homematic.internal.communicator.client.XmlRpcClient.sendMessage(XmlRpcClient.java:113)[180:org.openhab.binding.homematic:2.1.0]
        at org.openhab.binding.homematic.internal.communicator.client.XmlRpcClient.sendMessage(XmlRpcClient.java:82)[180:org.openhab.binding.homematic:2.1.0]
        at org.openhab.binding.homematic.internal.communicator.client.RpcClient.release(RpcClient.java:91)[180:org.openhab.binding.homematic:2.1.0]
        at org.openhab.binding.homematic.internal.communicator.AbstractHomematicGateway.stopServers(AbstractHomematicGateway.java:241)[180:org.openhab.binding.homematic:2.1.0]
        at org.openhab.binding.homematic.internal.communicator.AbstractHomematicGateway.access$3(AbstractHomematicGateway.java:238)[180:org.openhab.binding.homematic:2.1.0]
        at org.openhab.binding.homematic.internal.communicator.AbstractHomematicGateway$EventTrackerThread.run(AbstractHomematicGateway.java:823)[180:org.openhab.binding.homematic:2.1.0]
        at java.util.concurrent.Executors$RunnableAdapter.call(Executors.java:511)[:1.8.0_131]
        at java.util.concurrent.FutureTask.runAndReset(FutureTask.java:308)[:1.8.0_131]
        at java.util.concurrent.ScheduledThreadPoolExecutor$ScheduledFutureTask.access$301(ScheduledThreadPoolExecutor.java:180)[:1.8.0_131]
        at java.util.concurrent.ScheduledThreadPoolExecutor$ScheduledFutureTask.run(ScheduledThreadPoolExecutor.java:294)[:1.8.0_131]
        at java.util.concurrent.ThreadPoolExecutor.runWorker(ThreadPoolExecutor.java:1142)[:1.8.0_131]
        at java.util.concurrent.ThreadPoolExecutor$Worker.run(ThreadPoolExecutor.java:617)[:1.8.0_131]
        at java.lang.Thread.run(Thread.java:748)[:1.8.0_131]
Caused by: java.util.concurrent.ExecutionException: java.io.EOFException: HttpConnectionOverHTTP@6b0b27cd(l:/x.x.y.194:52112 <-> r:/x.x.x.241:9292,closed=false)[HttpChannelOverHTTP@65ccd4dc(exchange=HttpExchange@61f34cbd req=TERMINATED/null@null res=PENDING/null@null)[send=HttpSenderOverHTTP@24f1dee7(req=QUEUED,snd=COMPLETED,failure=null)[HttpGenerator{s=START}],recv=HttpReceiverOverHTTP@16f6b0fb(rsp=IDLE,failure=null)[HttpParser{s=CLOSED,0 of -1}]]]
        at org.eclipse.jetty.client.util.FutureResponseListener.getResult(FutureResponseListener.java:118)[69:org.eclipse.jetty.client:9.2.19.v20160908]
        at org.eclipse.jetty.client.util.FutureResponseListener.get(FutureResponseListener.java:110)[69:org.eclipse.jetty.client:9.2.19.v20160908]
        at org.eclipse.jetty.client.HttpRequest.send(HttpRequest.java:655)[69:org.eclipse.jetty.client:9.2.19.v20160908]
        at org.openhab.binding.homematic.internal.communicator.client.XmlRpcClient.sendMessage(XmlRpcClient.java:99)[180:org.openhab.binding.homematic:2.1.0]
        ... 12 more
Caused by: java.io.EOFException: HttpConnectionOverHTTP@6b0b27cd(l:/x.x.y.194:52112 <-> r:/x.x.x.241:9292,closed=false)[HttpChannelOverHTTP@65ccd4dc(exchange=HttpExchange@61f34cbd req=TERMINATED/null@null res=PENDING/null@null)[send=HttpSenderOverHTTP@24f1dee7(req=QUEUED,snd=COMPLETED,failure=null)[HttpGenerator{s=START}],recv=HttpReceiverOverHTTP@16f6b0fb(rsp=IDLE,failure=null)[HttpParser{s=CLOSED,0 of -1}]]]
        at org.eclipse.jetty.client.http.HttpReceiverOverHTTP.earlyEOF(HttpReceiverOverHTTP.java:277)[69:org.eclipse.jetty.client:9.2.19.v20160908]
        at org.eclipse.jetty.http.HttpParser.parseNext(HttpParser.java:1282)[71:org.eclipse.jetty.http:9.2.19.v20160908]
        at org.eclipse.jetty.client.http.HttpReceiverOverHTTP.shutdown(HttpReceiverOverHTTP.java:182)[69:org.eclipse.jetty.client:9.2.19.v20160908]
        at org.eclipse.jetty.client.http.HttpReceiverOverHTTP.process(HttpReceiverOverHTTP.java:129)[69:org.eclipse.jetty.client:9.2.19.v20160908]
        at org.eclipse.jetty.client.http.HttpReceiverOverHTTP.receive(HttpReceiverOverHTTP.java:69)[69:org.eclipse.jetty.client:9.2.19.v20160908]
        at org.eclipse.jetty.client.http.HttpChannelOverHTTP.receive(HttpChannelOverHTTP.java:89)[69:org.eclipse.jetty.client:9.2.19.v20160908]
        at org.eclipse.jetty.client.http.HttpConnectionOverHTTP.onFillable(HttpConnectionOverHTTP.java:123)[69:org.eclipse.jetty.client:9.2.19.v20160908]
        at org.eclipse.jetty.io.AbstractConnection$2.run(AbstractConnection.java:544)[72:org.eclipse.jetty.io:9.2.19.v20160908]
        at org.eclipse.jetty.util.thread.QueuedThreadPool.runJob(QueuedThreadPool.java:635)[84:org.eclipse.jetty.util:9.2.19.v20160908]
        at org.eclipse.jetty.util.thread.QueuedThreadPool$3.run(QueuedThreadPool.java:555)[84:org.eclipse.jetty.util:9.2.19.v20160908]
2017-07-05 10:56:01.966 [WARN ] [e.jetty.util.thread.QueuedThreadPool] - qtp342573009{STOPPING,8<=8<=200,i=0,q=1} Couldn't stop Thread[qtp342573009-306,5,main]
**2017-07-05 10:56:01.967 [WARN ] [ommunicator.AbstractHomematicGateway] - Die Adresse wird bereits verwendet (Bind failed)**
2017-07-05 10:57:01.968 [INFO ] [ommunicator.AbstractHomematicGateway] - No event since 565 seconds from gateway '12df991b', restarting RPC server

Copied from original issue: openhab/openhab2-addons#2436

mdicke2s commented 6 years ago

@BOFH90 There were recent changes related to Jetty (see https://github.com/openhab/openhab2-addons/pull/3390). Could you please check if this issue is still valid in OpenHab 2.3.0?

mdicke2s commented 6 years ago

@BOFH90 your issue was moved to eclipse smarthome project. I saw your comment on the original issue, that your problem seems to be solved. Therefore I will close this issue.

Thanks :+1: