Homematic "Read Timeout" CCU2

michaeljoos · August 23, 2016, 6:26am

Hi

Whatever I change in the settings (timeout, callbackHost, aliveInterval, reconnectInterval) I run into this timeout.

My setup:

CCU2 FW 2.21.10 with 20 connected devices
Openhab2 running on Raspi3

So performance should not be an issue here. Any help on that?

Log:

2016-08-23 04:07:24.064 [ERROR] [nal.communicator.server.XmlRpcServer] - Read timed out
java.net.SocketTimeoutException: Read timed out
at java.net.SocketInputStream.socketRead0(Native Method)[:1.8.0_101]
at java.net.SocketInputStream.socketRead(SocketInputStream.java:116)[:1.8.0_101]
at java.net.SocketInputStream.read(SocketInputStream.java:170)[:1.8.0_101]
at java.net.SocketInputStream.read(SocketInputStream.java:141)[:1.8.0_101]
at java.io.BufferedInputStream.fill(BufferedInputStream.java:246)[:1.8.0_101]
at java.io.BufferedInputStream.read1(BufferedInputStream.java:286)[:1.8.0_101]
at java.io.BufferedInputStream.read(BufferedInputStream.java:345)[:1.8.0_101]
at fi.iki.elonen.NanoHTTPD$HTTPSession.parseBody(NanoHTTPD.java:1113)[194:org.openhab.binding.homematic:2.0.0.201608180103]
at org.openhab.binding.homematic.internal.communicator.server.XmlRpcServer$XmlRpcHTTPD.serve(XmlRpcServer.java:95)[194:org.openhab.binding.homematic:2.0.0.201608180103]
at fi.iki.elonen.NanoHTTPD$HTTPSession.execute(NanoHTTPD.java:925)[194:org.openhab.binding.homematic:2.0.0.201608180103]
at fi.iki.elonen.NanoHTTPD$ClientHandler.run(NanoHTTPD.java:192)[194:org.openhab.binding.homematic:2.0.0.201608180103]
at java.lang.Thread.run(Thread.java:745)[:1.8.0_101]
2016-08-23 04:10:54.325 [ERROR] [nal.communicator.server.XmlRpcServer] - Read timed out
java.net.SocketTimeoutException: Read timed out
at java.net.SocketInputStream.socketRead0(Native Method)[:1.8.0_101]
at java.net.SocketInputStream.socketRead(SocketInputStream.java:116)[:1.8.0_101]
at java.net.SocketInputStream.read(SocketInputStream.java:170)[:1.8.0_101]
at java.net.SocketInputStream.read(SocketInputStream.java:141)[:1.8.0_101]
at java.io.BufferedInputStream.fill(BufferedInputStream.java:246)[:1.8.0_101]
at java.io.BufferedInputStream.read1(BufferedInputStream.java:286)[:1.8.0_101]
at java.io.BufferedInputStream.read(BufferedInputStream.java:345)[:1.8.0_101]
at fi.iki.elonen.NanoHTTPD$HTTPSession.parseBody(NanoHTTPD.java:1113)[194:org.openhab.binding.homematic:2.0.0.201608180103]
at org.openhab.binding.homematic.internal.communicator.server.XmlRpcServer$XmlRpcHTTPD.serve(XmlRpcServer.java:95)[194:org.openhab.binding.homematic:2.0.0.201608180103]
at fi.iki.elonen.NanoHTTPD$HTTPSession.execute(NanoHTTPD.java:925)[194:org.openhab.binding.homematic:2.0.0.201608180103]
at fi.iki.elonen.NanoHTTPD$ClientHandler.run(NanoHTTPD.java:192)[194:org.openhab.binding.homematic:2.0.0.201608180103]
at java.lang.Thread.run(Thread.java:745)[:1.8.0_101]
2016-08-23 04:15:14.022 [ERROR] [nal.communicator.server.XmlRpcServer] - Read timed out
java.net.SocketTimeoutException: Read timed out
at java.net.SocketInputStream.socketRead0(Native Method)[:1.8.0_101]
at java.net.SocketInputStream.socketRead(SocketInputStream.java:116)[:1.8.0_101]
at java.net.SocketInputStream.read(SocketInputStream.java:170)[:1.8.0_101]
at java.net.SocketInputStream.read(SocketInputStream.java:141)[:1.8.0_101]
at java.io.BufferedInputStream.fill(BufferedInputStream.java:246)[:1.8.0_101]
at java.io.BufferedInputStream.read1(BufferedInputStream.java:286)[:1.8.0_101]
at java.io.BufferedInputStream.read(BufferedInputStream.java:345)[:1.8.0_101]
at fi.iki.elonen.NanoHTTPD$HTTPSession.parseBody(NanoHTTPD.java:1113)[194:org.openhab.binding.homematic:2.0.0.201608180103]
at org.openhab.binding.homematic.internal.communicator.server.XmlRpcServer$XmlRpcHTTPD.serve(XmlRpcServer.java:95)[194:org.openhab.binding.homematic:2.0.0.201608180103]
at fi.iki.elonen.NanoHTTPD$HTTPSession.execute(NanoHTTPD.java:925)[194:org.openhab.binding.homematic:2.0.0.201608180103]
at fi.iki.elonen.NanoHTTPD$ClientHandler.run(NanoHTTPD.java:192)[194:org.openhab.binding.homematic:2.0.0.201608180103]
at java.lang.Thread.run(Thread.java:745)[:1.8.0_101]

peter_juenger · August 23, 2016, 7:04am

Hi,

I have the same log-messages since I switched to OH2.
I also tried different settings to get rid of them.

As far as I unterstand there are two different possibilities for OH to communicate with the CCU: XMLRpc and BINRpc.

Obviously OH2 communicates via BINRpc.

For my system those log messages don’t hurt, everything works as expected,

But because those messages flood the log over time, I’m also interested to get rid of them.

michaeljoos · August 23, 2016, 7:27am

OK, thanks. Good to know that I’m not the only one
I’m using motion sensors to switch on lights and there I see a lag as soon as I have these timeouts. Or in other words not really usable for this.

gerrieg · August 25, 2016, 5:33pm

i forgot to set the configured timeout for the XML-RPC server. It was fixed at 5 seconds, now it’s 15 seconds and configurable.

PR: https://github.com/openhab/openhab2-addons/pull/1205

peter_juenger · August 26, 2016, 5:06pm

Thanks @gerrieg for fast providing a fix for this issue, I’m eagerly waiting for it to be merged.

michaeljoos · August 28, 2016, 4:25am

Hi Gerhard

Thanks for the update. Yesterday I updated to latest snapshot and tried timeout with different settings. Unfortunately I still have this messages in my Logfile. It’s not only the log…as soon as I have these logs the update in openHAB is somehow lagged.

Hope you can help in this!

2016-08-28 06:09:05.154 [ERROR] [nal.communicator.server.XmlRpcServer] - Read timed out
java.net.SocketTimeoutException: Read timed out
at java.net.SocketInputStream.socketRead0(Native Method)[:1.8.0_101]
at java.net.SocketInputStream.socketRead(SocketInputStream.java:116)[:1.8.0_101]
at java.net.SocketInputStream.read(SocketInputStream.java:170)[:1.8.0_101]
at java.net.SocketInputStream.read(SocketInputStream.java:141)[:1.8.0_101]
at java.io.BufferedInputStream.fill(BufferedInputStream.java:246)[:1.8.0_101]
at java.io.BufferedInputStream.read1(BufferedInputStream.java:286)[:1.8.0_101]
at java.io.BufferedInputStream.read(BufferedInputStream.java:345)[:1.8.0_101]
at fi.iki.elonen.NanoHTTPD$HTTPSession.parseBody(NanoHTTPD.java:1113)[193:org.openhab.binding.homematic:2.0.0.201608210102]
at org.openhab.binding.homematic.internal.communicator.server.XmlRpcServer$XmlRpcHTTPD.serve(XmlRpcServer.java:95)[193:org.openhab.binding.homematic:2.0.0.201608210102]
at fi.iki.elonen.NanoHTTPD$HTTPSession.execute(NanoHTTPD.java:925)[193:org.openhab.binding.homematic:2.0.0.201608210102]
at fi.iki.elonen.NanoHTTPD$ClientHandler.run(NanoHTTPD.java:192)[193:org.openhab.binding.homematic:2.0.0.201608210102]
at java.lang.Thread.run(Thread.java:745)[:1.8.0_101]
2016-08-28 06:11:19.659 [ERROR] [nal.communicator.server.XmlRpcServer] - Read timed out
java.net.SocketTimeoutException: Read timed out
at java.net.SocketInputStream.socketRead0(Native Method)[:1.8.0_101]
at java.net.SocketInputStream.socketRead(SocketInputStream.java:116)[:1.8.0_101]
at java.net.SocketInputStream.read(SocketInputStream.java:170)[:1.8.0_101]
at java.net.SocketInputStream.read(SocketInputStream.java:141)[:1.8.0_101]
at java.io.BufferedInputStream.fill(BufferedInputStream.java:246)[:1.8.0_101]
at java.io.BufferedInputStream.read1(BufferedInputStream.java:286)[:1.8.0_101]
at java.io.BufferedInputStream.read(BufferedInputStream.java:345)[:1.8.0_101]
at fi.iki.elonen.NanoHTTPD$HTTPSession.parseBody(NanoHTTPD.java:1113)[193:org.openhab.binding.homematic:2.0.0.201608210102]
at org.openhab.binding.homematic.internal.communicator.server.XmlRpcServer$XmlRpcHTTPD.serve(XmlRpcServer.java:95)[193:org.openhab.binding.homematic:2.0.0.201608210102]
at fi.iki.elonen.NanoHTTPD$HTTPSession.execute(NanoHTTPD.java:925)[193:org.openhab.binding.homematic:2.0.0.201608210102]
at fi.iki.elonen.NanoHTTPD$ClientHandler.run(NanoHTTPD.java:192)[193:org.openhab.binding.homematic:2.0.0.201608210102]
at java.lang.Thread.run(Thread.java:745)[:1.8.0_101]
2016-08-28 06:11:35.670 [ERROR] [nal.communicator.server.XmlRpcServer] - Read timed out
java.net.SocketTimeoutException: Read timed out
at java.net.SocketInputStream.socketRead0(Native Method)[:1.8.0_101]
at java.net.SocketInputStream.socketRead(SocketInputStream.java:116)[:1.8.0_101]
at java.net.SocketInputStream.read(SocketInputStream.java:170)[:1.8.0_101]
at java.net.SocketInputStream.read(SocketInputStream.java:141)[:1.8.0_101]
at java.io.BufferedInputStream.fill(BufferedInputStream.java:246)[:1.8.0_101]
at java.io.BufferedInputStream.read1(BufferedInputStream.java:286)[:1.8.0_101]
at java.io.BufferedInputStream.read(BufferedInputStream.java:345)[:1.8.0_101]
at fi.iki.elonen.NanoHTTPD$HTTPSession.parseBody(NanoHTTPD.java:1113)[193:org.openhab.binding.homematic:2.0.0.201608210102]
at org.openhab.binding.homematic.internal.communicator.server.XmlRpcServer$XmlRpcHTTPD.serve(XmlRpcServer.java:95)[193:org.openhab.binding.homematic:2.0.0.201608210102]
at fi.iki.elonen.NanoHTTPD$HTTPSession.execute(NanoHTTPD.java:925)[193:org.openhab.binding.homematic:2.0.0.201608210102]
at fi.iki.elonen.NanoHTTPD$ClientHandler.run(NanoHTTPD.java:192)[193:org.openhab.binding.homematic:2.0.0.201608210102]
at java.lang.Thread.run(Thread.java:745)[:1.8.0_101]

peter_juenger · August 28, 2016, 11:34am

I also tried out the last build (thanks for quick merging).
I’am not sure if it changes something, but I’ve found a solution for myself now.

After the update and a restart of OH the situation was unchanged, I was getting exceptions as michaeljoos describes.

I then logged into the ccu, deinstalled the XML-API Addon under “Zusatzsofware” and restarted both systems.

Since that time no more XmlRpcServer timeout exceptions so far …

gerrieg · August 28, 2016, 1:15pm

after reading the source code of NANOHTTPD, i think i can disable the timeout for the server completely. Can you please try this build and let me know: https://drive.google.com/open?id=0Bw7zjCgsXYnHTUxsUExLYTJzSVU

peter_juenger · August 28, 2016, 6:28pm

Hi @gerrieg

thanks for the new build.

First of all I have to revise my statement that the execptions are fixed for me after deletion of the XML-Api addon on the homematic.

I had peace for four or five hours and then the exeptions were back again.
So I think that the short periode of “silence” was the result of rebooting the homematic.

Second, I tried the new build you provided: For around two hours no exception (normally I have them every one or two minutes), so that looks really good, but maybe I should be a little careful with this statement

Last of all I’m interested in the technical background here.

As far as I understood, there are two Interfaces to communicate with homematic and homegear.
Homematic supports BIN-Rpc and XML-Rpc, whereas Homegear (and older Homematics?) supports only XML-Rpc.

So if I configure the homematic-binding for a CCU, why does it even try to communicate via XML-Rpc. Is it for backwards compability for older homematics?

michaeljoos · August 29, 2016, 3:26pm

My system is running now 8 hours without any timeouts. So it looks very good Thanks for this update!

I use homematic motion sensor to wake up my tablet (rotini). With this update it reacts fast and as expected. No lag anymore.

Lets see the next 24 hours. But for now I’m happy!

Michael

gerrieg · August 29, 2016, 3:53pm

Great to hear that it’s working now.

The Homematic binding for OH2 supports two communication modes, BIN-RPC and XML-RPC. Homegear supports both methods, if a Homegear gateway is detected, the binding uses BIN-RPC.

For the CCU (or BidCos Service, OCCU, …) it’s different, it depends on the firmware. The RF and WIRED services also supports both methods, the newer HomematicIP service only XML-RPC. So if the binding detects a CCU (or another gateway) with HomematicIP support, it uses XML-RPC, otherwise BIN-RPC.

XML-RPC is documented by EQ-3, BIN-RPC not. So i think XML-RPC is also more future-proof.

peter_juenger · August 29, 2016, 6:43pm

Thanks for the update, no more issues here since yesterday.
I saw that it is already merged.

One more thanks for the brief explanation about BIN-RPC and XML-RPC.

One last question:
Are these (now suppressed) timeout exceptions something to worry about?
Are we loosing information / messages?

gerrieg · August 30, 2016, 6:04am

The XML-RPC server listens for messages from the gateway. Previously, if a connection is open for a certain period of time, the server closes the connection and opens a new one. That’s the timeout exception you saw.

But that’s not necessarry, now the connection stays open and listens “forever” for new messages. So no timeout anymore and no lost messages.

peter_juenger · August 30, 2016, 6:13am

@gerrieg: that gives me an idea how it works.

Thanks for your patience with me

gerrieg · August 30, 2016, 3:22pm

@peter_juenger
No problem, i also want to know exactly how things work