[Solved: Homematic] CCU1 BinRpcMessage socket failure

Setup, Configuration and Use Installation
, ,
1

I have a migrated from OH1.8 OH2.2 instance with homematic binding running.
But I had problems loading variables and scripts from my homematic CCU1.
So I decided to start with a new clean installation using snapshot openHAB 2.2.0 Build #1039.
Now the homematic variables and programs are loaded to the GATEWAY-EXTRAS thing.
But a few minutes after loading homematic devices the homematic binding will stop working with athe attached error.
I allready tried to increase the default timeout value:
2017-09-17 20:17:09.900 [DEBUG] [matic.handler.HomematicBridgeHandler] - HomematicConfig[gatewayAddress=192.168.0.160,callbackHost=192.168.0.41,xmlCallbackPort=9125,binCallbackPort=9126,gatewayType=ccu,rfPort=2001,wiredPort=2000,hmIpPort=2010,cuxdPort=8701,groupPort=9292,timeout=60,socketMaxAlive=900]

In this case my CCU1 is frozen, I can’t open the CCU1 user interface.

Any idea whats wrong?

Error:

2017-09-17 20:19:20.758 [DEBUG] [ommunicator.AbstractHomematicGateway] - New device ‘HEQ0104695’ detected on gateway with id ‘ccu’
2017-09-17 20:19:20.808 [DEBUG] [ommunicator.AbstractHomematicGateway] - New device ‘HEQ0362998’ detected on gateway with id ‘ccu’
2017-09-17 20:19:23.373 [DEBUG] [ommunicator.AbstractHomematicGateway] - New device ‘HEQ0031687’ detected on gateway with id ‘ccu’
2017-09-17 20:19:23.630 [DEBUG] [nal.communicator.client.BinRpcClient] - BinRpcMessage socket failure, sending message again 1/1
2017-09-17 20:20:34.341 [ERROR] [ommunicator.AbstractHomematicGateway] - null
java.io.IOException: null
at org.openhab.binding.homematic.internal.communicator.CcuGateway.sendScript(CcuGateway.java:255) [187:org.openhab.binding.homematic:2.2.0.201709152241]
at org.openhab.binding.homematic.internal.communicator.CcuGateway.sendScriptByName(CcuGateway.java:225) [187:org.openhab.binding.homematic:2.2.0.201709152241]
at org.openhab.binding.homematic.internal.communicator.CcuGateway.sendScriptByName(CcuGateway.java:213) [187:org.openhab.binding.homematic:2.2.0.201709152241]
at org.openhab.binding.homematic.internal.communicator.CcuGateway.loadDeviceNames(CcuGateway.java:126) [187:org.openhab.binding.homematic:2.2.0.201709152241]
at org.openhab.binding.homematic.internal.communicator.AbstractHomematicGateway.getDeviceDescriptions(AbstractHomematicGateway.java:439) [187:org.openhab.binding.homematic:2.2.0.201709152241]
at org.openhab.binding.homematic.internal.communicator.AbstractHomematicGateway.newDevices(AbstractHomematicGateway.java:677) [187:org.openhab.binding.homematic:2.2.0.201709152241]
at org.openhab.binding.homematic.internal.communicator.server.RpcResponseHandler.handleNewDevice(RpcResponseHandler.java:101) [187:org.openhab.binding.homematic:2.2.0.201709152241]
at org.openhab.binding.homematic.internal.communicator.server.RpcResponseHandler.handleMethodCall(RpcResponseHandler.java:52) [187:org.openhab.binding.homematic:2.2.0.201709152241]
at org.openhab.binding.homematic.internal.communicator.server.BinRpcResponseHandler.run(BinRpcResponseHandler.java:46) [187:org.openhab.binding.homematic:2.2.0.201709152241]
at java.util.concurrent.ThreadPoolExecutor.runWorker(ThreadPoolExecutor.java:1142) [?:?]
at java.util.concurrent.ThreadPoolExecutor$Worker.run(ThreadPoolExecutor.java:617) [?:?]
at java.lang.Thread.run(Thread.java:745) [?:?]
Caused by: java.util.concurrent.TimeoutException
at org.eclipse.jetty.client.util.FutureResponseListener.get(FutureResponseListener.java:109) ~[?:?]
at org.eclipse.jetty.client.HttpRequest.send(HttpRequest.java:654) ~[?:?]
at org.openhab.binding.homematic.internal.communicator.CcuGateway.sendScript(CcuGateway.java:245) ~[?:?]
… 11 more
2017-09-17 20:20:34.363 [DEBUG] [ommunicator.AbstractHomematicGateway] - New device ‘HEQ0363098’ detected on gateway with id ‘ccu’
2017-09-17 20:21:34.353 [ERROR] [ommunicator.AbstractHomematicGateway] - null
java.io.IOException: null
at org.openhab.binding.homematic.internal.communicator.CcuGateway.sendScript(CcuGateway.java:255) [187:org.openhab.binding.homematic:2.2.0.201709152241]
at org.openhab.binding.homematic.internal.communicator.CcuGateway.sendScriptByName(CcuGateway.java:225) [187:org.openhab.binding.homematic:2.2.0.201709152241]
at org.openhab.binding.homematic.internal.communicator.CcuGateway.sendScriptByName(CcuGateway.java:213) [187:org.openhab.binding.homematic:2.2.0.201709152241]
at org.openhab.binding.homematic.internal.communicator.CcuGateway.loadDeviceNames(CcuGateway.java:126) [187:org.openhab.binding.homematic:2.2.0.201709152241]
at org.openhab.binding.homematic.internal.communicator.AbstractHomematicGateway.getDeviceDescriptions(AbstractHomematicGateway.java:439) [187:org.openhab.binding.homematic:2.2.0.201709152241]
at org.openhab.binding.homematic.internal.communicator.AbstractHomematicGateway.newDevices(AbstractHomematicGateway.java:677) [187:org.openhab.binding.homematic:2.2.0.201709152241]
at org.openhab.binding.homematic.internal.communicator.server.RpcResponseHandler.handleNewDevice(RpcResponseHandler.java:101) [187:org.openhab.binding.homematic:2.2.0.201709152241]
at org.openhab.binding.homematic.internal.communicator.server.RpcResponseHandler.handleMethodCall(RpcResponseHandler.java:52) [187:org.openhab.binding.homematic:2.2.0.201709152241]
at org.openhab.binding.homematic.internal.communicator.server.BinRpcResponseHandler.run(BinRpcResponseHandler.java:46) [187:org.openhab.binding.homematic:2.2.0.201709152241]
at java.util.concurrent.ThreadPoolExecutor.runWorker(ThreadPoolExecutor.java:1142) [?:?]
at java.util.concurrent.ThreadPoolExecutor$Worker.run(ThreadPoolExecutor.java:617) [?:?]
at java.lang.Thread.run(Thread.java:745) [?:?]
Caused by: java.util.concurrent.TimeoutException
at org.eclipse.jetty.client.util.FutureResponseListener.get(FutureResponseListener.java:109) ~[?:?]
at org.eclipse.jetty.client.HttpRequest.send(HttpRequest.java:654) ~[?:?]
at org.openhab.binding.homematic.internal.communicator.CcuGateway.sendScript(CcuGateway.java:245) ~[?:?]
… 11 more

2

Added TRACE log information:

2017-09-18 19:09:54.222 [TRACE] [al.communicator.client.SocketHandler] - Returning socket for port 2000
2017-09-18 19:10:46.222 [TRACE] [tic.internal.communicator.CcuGateway] - TclRegaScript: string dev_id;
Write(‘<?xml version="1.0" encoding="ISO-8859-1" standalone="yes"?>\n’);
Write(“\n”);
foreach (dev_id, root.Devices().EnumUsedIDs()) {
object dev_obj = dom.GetObject(dev_id);
Write(" <entry");
Write(" name=‘“); WriteXML(dev_obj.Address());
Write(”’ value=‘“); WriteXML(dev_obj.Name());
Write(”’ />\n");
}
Write(“”);
2017-09-18 19:10:46.222 [ERROR] [ommunicator.AbstractHomematicGateway] - null
java.io.IOException: null
at org.openhab.binding.homematic.internal.communicator.CcuGateway.sendScript(CcuGateway.java:255) [187:org.openhab.binding.homematic:2.2.0.201709152241]
at org.openhab.binding.homematic.internal.communicator.CcuGateway.sendScriptByName(CcuGateway.java:225) [187:org.openhab.binding.homematic:2.2.0.201709152241]
at org.openhab.binding.homematic.internal.communicator.CcuGateway.sendScriptByName(CcuGateway.java:213) [187:org.openhab.binding.homematic:2.2.0.201709152241]
at org.openhab.binding.homematic.internal.communicator.CcuGateway.loadDeviceNames(CcuGateway.java:126) [187:org.openhab.binding.homematic:2.2.0.201709152241]
at org.openhab.binding.homematic.internal.communicator.AbstractHomematicGateway.getDeviceDescriptions(AbstractHomematicGateway.java:439) [187:org.openhab.binding.homematic:2.2.0.201709152241]
at org.openhab.binding.homematic.internal.communicator.AbstractHomematicGateway.newDevices(AbstractHomematicGateway.java:677) [187:org.openhab.binding.homematic:2.2.0.201709152241]
at org.openhab.binding.homematic.internal.communicator.server.RpcResponseHandler.handleNewDevice(RpcResponseHandler.java:101) [187:org.openhab.binding.homematic:2.2.0.201709152241]
at org.openhab.binding.homematic.internal.communicator.server.RpcResponseHandler.handleMethodCall(RpcResponseHandler.java:52) [187:org.openhab.binding.homematic:2.2.0.201709152241]
at org.openhab.binding.homematic.internal.communicator.server.BinRpcResponseHandler.run(BinRpcResponseHandler.java:46) [187:org.openhab.binding.homematic:2.2.0.201709152241]
at java.util.concurrent.ThreadPoolExecutor.runWorker(ThreadPoolExecutor.java:1142) [?:?]
at java.util.concurrent.ThreadPoolExecutor$Worker.run(ThreadPoolExecutor.java:617) [?:?]
at java.lang.Thread.run(Thread.java:745) [?:?]
Caused by: java.util.concurrent.TimeoutException
at org.eclipse.jetty.client.util.FutureResponseListener.get(FutureResponseListener.java:109) ~[?:?]
at org.eclipse.jetty.client.HttpRequest.send(HttpRequest.java:654) ~[?:?]
at org.openhab.binding.homematic.internal.communicator.CcuGateway.sendScript(CcuGateway.java:245) ~[?:?]
… 11 more
2017-09-18 19:10:46.242 [DEBUG] [ommunicator.AbstractHomematicGateway] - New device ‘HEQ0104695’ detected on gateway with id ‘ccu’
2017-09-18 19:10:54.284 [TRACE] [nal.communicator.client.BinRpcClient] - Client BinRpcResponse:
null
2017-09-18 19:10:54.285 [TRACE] [nal.communicator.client.BinRpcClient] - Client BinRpcRequest:
listDevices()

2017-09-18 19:10:54.289 [TRACE] [al.communicator.client.SocketHandler] - Returning socket for port 2001
2017-09-18 19:10:56.352 [TRACE] [nal.communicator.client.BinRpcClient] - Client BinRpcResponse:
[
{
ADDRESS=BidCoS-RF
CHILDREN=
[
BidCoS-RF:0
BidCoS-RF:1
…

2017-09-18 19:13:00.839 [TRACE] [nal.communicator.client.BinRpcClient] - Client BinRpcRequest:
ping()
ccu

2017-09-18 19:13:00.840 [TRACE] [al.communicator.client.SocketHandler] - Returning socket for port 2001
2017-09-18 19:13:00.846 [DEBUG] [nal.communicator.client.BinRpcClient] - BinRpcMessage socket failure, sending message again 1/1
2017-09-18 19:13:00.847 [TRACE] [al.communicator.client.SocketHandler] - Closing Socket on port 2001
2017-09-18 19:13:00.852 [TRACE] [al.communicator.client.SocketHandler] - Creating new socket for port 2001
2017-09-18 19:13:00.859 [TRACE] [nal.communicator.client.BinRpcClient] - Client BinRpcResponse:
{
faultCode=-1
faultString=ping: unknown method name
}

2017-09-18 19:13:00.861 [TRACE] [nal.communicator.client.BinRpcClient] - Client BinRpcResponse:
{
faultCode=-1
faultString=ping: unknown method name
}

2017-09-18 19:13:00.862 [TRACE] [nal.communicator.client.BinRpcClient] - Client BinRpcRequest:
listDevices()

2017-09-18 19:13:00.863 [TRACE] [al.communicator.client.SocketHandler] - Returning socket for port 2000

3

Finally I tiered of problems with CCU1.
I kicked out the CCU1 and replaced it with a CCU2.
All problems are gone!