Homematic Communication Error

michaeljoos · November 1, 2016, 5:07pm

Hi

Homematic with OH2 was running well for weeks. A few days ago (I have updated nightly builds) the system became unstable. As soon as I restart OH all commends and states are working as expected…after a few minutes there is a big delay (30s) for sensors like window or motion.

OpenHAB-Log means:
2016-11-01 17:54:47.755 [INFO ] [ternal.communicator.HomematicGateway] - No event since 1379 seconds from gateway ‘ccu’, restarting RPC server
2016-11-01 17:56:53.080 [INFO ] [ternal.communicator.HomematicGateway] - No event since 1505 seconds from gateway ‘ccu’, restarting RPC server
2016-11-01 17:58:52.918 [INFO ] [ternal.communicator.HomematicGateway] - No event since 1624 seconds from gateway ‘ccu’, restarting RPC server
2016-11-01 18:00:55.257 [INFO ] [ternal.communicator.HomematicGateway] - No event since 1747 seconds from gateway ‘ccu’, restarting RPC server

and so on…

And in parallel CCU2-Logfile with a lot of RPC-Errors:

Nov 1 18:01:43 homematic-ccu2 user.err rfd: XmlRpc transport error
Nov 1 18:03:00 homematic-ccu2 user.err rfd: XmlRpc transport error calling system.listMethods({“RF-ccu”}) on binary://192.168.1.66:9126/RPC2:
Nov 1 18:03:00 homematic-ccu2 user.err rfd: XmlRpc transport error calling listDevices({“RF-ccu”}) on binary://192.168.1.66:9126/RPC2:
Nov 1 18:03:37 homematic-ccu2 user.err rfd: XmlRpcClient error calling event({[methodName:“event”,params:{“RF-ccu”,“NEQ0166447:1”,“LEVEL”,0.000000}],[methodName:“event”,params:{“RF-ccu”,“NEQ0166447:1”,“WORKING”,false}],[methodName:“event”,params:{“RF-ccu”,“NEQ0166447:1”,"DI
Nov 1 18:03:37 homematic-ccu2 user.err rfd: XmlRpc transport error
Nov 1 18:03:39 homematic-ccu2 user.err rfd: XmlRpcClient error calling event({[methodName:“event”,params:{“RF-ccu”,“MEQ0737879:1”,“STATE”,false}]}) on binary://192.168.1.66:9126/RPC2:
Nov 1 18:03:39 homematic-ccu2 user.err rfd: XmlRpc transport error
Nov 1 18:03:39 homematic-ccu2 user.err rfd: XmlRpcClient error calling event({[methodName:“event”,params:{“RF-ccu”,“MEQ0737879:1”,“WORKING”,false}]}) on binary://192.168.1.66:9126/RPC2:
Nov 1 18:03:39 homematic-ccu2 user.err rfd: XmlRpc transport error
Nov 1 18:03:43 homematic-ccu2 user.err rfd: XmlRpcClient error calling event({[methodName:“event”,params:{“RF-ccu”,“MEQ0738031:1”,“STATE”,false}],[methodName:“event”,params:{“RF-ccu”,“MEQ0738031:1”,“WORKING”,false}]}) on binary://192.168.1.66:9126/RPC2:
Nov 1 18:03:43 homematic-ccu2 user.err rfd: XmlRpc transport error
Nov 1 18:03:45 homematic-ccu2 user.err rfd: XmlRpcClient error calling event({[methodName:“event”,params:{“RF-ccu”,“MEQ0738529:1”,“STATE”,false}],[methodName:“event”,params:{“RF-ccu”,“MEQ0738529:1”,“WORKING”,false}]}) on binary://192.168.1.66:9126/RPC2:
Nov 1 18:03:45 homematic-ccu2 user.err rfd: XmlRpc transport error

Don’t know what happened here…I have also to say that I have added more and more actors the last weeks. But in my opinion it should be far away from the limit (28)

I hope that someone can help me… @gerrieg ?

Thanks
Michael

gerrieg · November 1, 2016, 7:12pm

Hi Michael!

There was a change in the communication in the nightly builds. Previously, the communication with the CCU was only XML-RPC. Now, the smaller and faster BIN-RPC and only for Homematic IP XML-RPC is used.
So there are now two callback ports, 9125 and 9126. Maybe, the CCU can not call your openHab server on port 9126 (Firewall, …)

Gerhard

michaeljoos · November 2, 2016, 5:52am

Mmmhh…not sure if this is the case as it is working for all sensors and actors as soon as I restart openhab. But after some time the error messages pop up again with the result that I have the big delay for status. Commands to wired actors (lights) are working all the time.

whph · November 2, 2016, 11:39am

Hi Gerhard,

I have the same problem with the actual OH2 Snapshot build communicating with Homegear as Gateway.

2016-11-02 12:24:26.020 [INFO ] [ternal.communicator.HomematicGateway] - No event since 1142 seconds from gateway ‘ccu’, restarting RPC server
2016-11-02 12:25:26.102 [INFO ] [ternal.communicator.HomematicGateway] - No event since 1202 seconds from gateway ‘ccu’, restarting RPC server
2016-11-02 12:26:26.184 [INFO ] [ternal.communicator.HomematicGateway] - No event since 1262 seconds from gateway ‘ccu’, restarting RPC server
2016-11-02 12:27:26.270 [INFO ] [ternal.communicator.HomematicGateway] - No event since 1322 seconds from gateway ‘ccu’, restarting RPC server
2016-11-02 12:28:26.348 [INFO ] [ternal.communicator.HomematicGateway] - No event since 1382 seconds from gateway ‘ccu’, restarting RPC server

The Homegear Log does show:

Error in file RPC/RpcClient.cpp line 519 in function void Rpc::RpcClient::sendRequest(Rpc::RemoteRpcServer*, std::vector&, std::vector&, bool, bool&): Could not connect to server x.x.x.x on port 9126. Poll failed with error code: 1.

The Homematic bridge is configured like this:
Bridge homematic:bridge:ccu [ gatewayAddress=“127.0.0.1”, callbackHost=“x.x.x.x”, callbackPort=“9125” ]

OH and Homegear are both on the same machine.

Though I have to say that I just started working with OH and Homegear (used Homematic and FHEM for years), so there could be some knowledge gaps

Thanks

Jochen

gerrieg · November 2, 2016, 3:20pm

I think this is the same problem as michael. The Homematic openHab BIN-RPC server can not be reached at port 9126.
I’ve updated the docs, callbackPort is now deprecated.

First, set the binding to DEBUG mode:

log:set DEBUG org.openhab.binding.homematic

Then switch the XML-/BIN-RPC ports:

Bridge homematic:bridge:ccu [ gatewayAddress="127.0.0.1", binCallbackPort=9125, xmlCallbackPort=9126]

post the startup log.
Also try to manually trigger a event (e.g switch on the light), it should appear in the logfile

whph · November 2, 2016, 3:45pm

Hi Gerhard,

seems to work now, running about 15 min. and no error so far.
Also, the hint for Debug-Logging is nice to know

After startup, the following entries in the OH log have been logged:

2016-11-02 16:33:55.832 [DEBUG] [org.openhab.binding.homematic       ] - BundleEvent STARTED - org.openhab.binding.homematic
2016-11-02 16:33:55.885 [DEBUG] [matic.handler.HomematicBridgeHandler] - HomematicConfig[gatewayAddress=127.0.0.1,callbackHost=x.x.x.x,xmlCallbackPort=9126,binCallbackPort=9125,gatewayType=auto,rfPort=2001,wiredPort=2000,hmIpPort=2010,cuxdPort=8701,aliveInterval=300,reconnectInterval=0,timeout=15,socketMaxAlive=900]
2016-11-02 16:33:56.043 [INFO ] [ternal.communicator.client.RpcClient] - Interface 'WIRED' on gateway 'ccu' not available, disabling support
2016-11-02 16:33:56.044 [INFO ] [ternal.communicator.client.RpcClient] - Interface 'HMIP' on gateway 'ccu' not available, disabling support
2016-11-02 16:33:56.045 [INFO ] [ternal.communicator.client.RpcClient] - Interface 'CUXD' on gateway 'ccu' not available, disabling support
2016-11-02 16:33:56.052 [DEBUG] [ternal.communicator.HomematicGateway] - Initializing gateway with id 'ccu'
2016-11-02 16:33:56.053 [INFO ] [ternal.communicator.HomematicGateway] - HmGatewayInfo[id=HOMEGEAR,type=Homegear,firmware=0.6.7-1545,address=VBC2461756,wired=false,hmip=false,cuxd=false]
2016-11-02 16:33:56.057 [INFO ] [ternal.communicator.HomematicGateway] - Used Homematic transfer modes: RF:BIN_RPC
2016-11-02 16:33:56.058 [DEBUG] [nal.communicator.server.BinRpcServer] - Initializing BIN-RPC server at port 9125
2016-11-02 16:33:56.067 [DEBUG] [ternal.communicator.HomematicGateway] - Starting event tracker for gateway with id 'ccu'
2016-11-02 16:33:56.075 [DEBUG] [ternal.communicator.HomematicGateway] - Starting connection tracker for gateway with id 'ccu'
2016-11-02 16:33:56.077 [DEBUG] [org.openhab.binding.homematic       ] - ServiceEvent REGISTERED - {org.eclipse.smarthome.config.discovery.DiscoveryService}={service.id=333, service.bundleid=197, service.scope=singleton} - org.openhab.binding.homematic
2016-11-02 16:33:56.077 [DEBUG] [very.HomematicDeviceDiscoveryService] - Stopping Homematic discovery scan
2016-11-02 16:33:56.087 [DEBUG] [very.HomematicDeviceDiscoveryService] - Starting Homematic discovery scan
2016-11-02 16:33:56.088 [DEBUG] [very.HomematicDeviceDiscoveryService] - Waiting for finishing Homematic device discovery scan

In the Homegear Log, there are also these lines:

11/02/16 16:39:06.005 RPC client: Info: Calling RPC method "system.multicall" on server x.x.x.x.
11/02/16 16:39:06.063 RPC client: Info: Calling RPC method "system.multicall" on server x.x.x.x.

Thanks

Jochen

whph · November 2, 2016, 4:33pm

Update:
Messages about missing event from ccu are coming in again.
Right now the counter is again at 1348 seconds:

2016-11-02 17:29:57.850 [INFO ] [ternal.communicator.HomematicGateway] - No event since 1348 seconds from gateway 'ccu', restarting RPC server

All switches and reads about Homematic devices are working though.

Update2:

In the Homegear Log I get an error again:

11/02/16 17:33:58.781 RPC client: Info: Calling RPC method "system.listMethods" on server binary://x.x.x.x.
Error in file RPC/RpcClient.cpp line 519 in function void Rpc::RpcClient::sendRequest(Rpc::RemoteRpcServer*, std::vector<char>&, std::vector<char>&, bool, bool&): Could not connect to server x.x.x.x on port 9125. Poll failed with error code: 1.
Removing server. Server has to send "init" again.

michaeljoos · November 2, 2016, 5:15pm

Hi Gerhard

This is what I get in Debug-Mode. Everything is working until this message:

2016-11-02 17:46:42.506 [DEBUG] [al.communicator.client.SocketHandler] - Max alive time reached for socket on port 2001

Hope this helps to solve this issue.

Thanks
Michael

Settings:

LOG:

2016-11-02 17:16:25.008 [DEBUG] [nal.communicator.server.XmlRpcServer] - Initializing XML-RPC server at port 9126
2016-11-02 17:16:25.065 [DEBUG] [nal.communicator.server.BinRpcServer] - Initializing BIN-RPC server at port 9125

2016-11-02 17:43:45.458 [DEBUG] [ternal.communicator.HomematicGateway] - Received new (Double) value ‘0.2’ for ‘000915698D62E0:1#ILLUMINATION’ from gateway with id ‘ccu’
2016-11-02 17:43:45.467 [DEBUG] [ternal.communicator.HomematicGateway] - Received new (Boolean) value ‘false’ for ‘000915698D62E0:1#MOTION’ from gateway with id ‘ccu’
2016-11-02 17:43:45.478 [DEBUG] [ternal.communicator.HomematicGateway] - Received new (Boolean) value ‘true’ for ‘000915698D62E0:1#MOTION_DETECTION_ACTIVE’ from gateway with id ‘ccu’
2016-11-02 17:46:42.506 [DEBUG] [al.communicator.client.SocketHandler] - Max alive time reached for socket on port 2001
2016-11-02 17:47:45.024 [DEBUG] [ematic.handler.HomematicThingHandler] - Received command ‘OFF’ for channel ‘homematic:HM-LC-Sw1-FM:ccu:MEQ0738031:1#STATE’
2016-11-02 17:47:45.030 [DEBUG] [ternal.communicator.HomematicGateway] - Sending datapoint ‘MEQ0738031:1#STATE’ with value ‘false’ to gateway with id ‘ccu’
2016-11-02 17:47:45.206 [DEBUG] [ternal.communicator.HomematicGateway] - Received new (Boolean) value ‘false’ for ‘MEQ0738031:1#STATE’ from gateway with id ‘ccu’
2016-11-02 17:47:45.226 [DEBUG] [ternal.communicator.HomematicGateway] - Received new (Boolean) value ‘false’ for ‘MEQ0738031:1#WORKING’ from gateway with id ‘ccu’
2016-11-02 17:52:53.606 [DEBUG] [ternal.communicator.HomematicGateway] - Received new (Boolean) value ‘false’ for ‘0000D3C9905CFC:0#SABOTAGE’ from gateway with id ‘ccu’
2016-11-02 17:52:53.610 [DEBUG] [ternal.communicator.HomematicGateway] - Received new (Boolean) value ‘false’ for ‘0000D3C9905CFC:0#DUTY_CYCLE’ from gateway with id ‘ccu’
2016-11-02 17:52:53.616 [DEBUG] [ternal.communicator.HomematicGateway] - Received new (Boolean) value ‘false’ for ‘0000D3C9905CFC:0#LOW_BAT’ from gateway with id ‘ccu’
2016-11-02 17:52:53.622 [DEBUG] [ternal.communicator.HomematicGateway] - Received new (Integer) value ‘0’ for ‘0000D3C9905CFC:0#ERROR_CODE’ from gateway with id ‘ccu’
2016-11-02 17:52:53.627 [DEBUG] [ternal.communicator.HomematicGateway] - Received new (Boolean) value ‘false’ for ‘0000D3C9905CFC:0#UNREACH’ from gateway with id ‘ccu’
2016-11-02 17:52:53.631 [DEBUG] [ternal.communicator.HomematicGateway] - Received new (Double) value ‘1.3’ for ‘0000D3C9905CFC:0#OPERATING_VOLTAGE’ from gateway with id ‘ccu’
2016-11-02 17:52:53.661 [DEBUG] [ternal.communicator.HomematicGateway] - Received new (Integer) value ‘0’ for ‘0000D3C9905CFC:1#STATE’ from gateway with id ‘ccu’
2016-11-02 17:54:07.086 [DEBUG] [ternal.communicator.HomematicGateway] - Received new (Boolean) value ‘false’ for ‘0000D3C9905FE8:0#SABOTAGE’ from gateway with id ‘ccu’
2016-11-02 17:54:07.092 [DEBUG] [ternal.communicator.HomematicGateway] - Received new (Boolean) value ‘false’ for ‘0000D3C9905FE8:0#DUTY_CYCLE’ from gateway with id ‘ccu’
2016-11-02 17:54:07.097 [DEBUG] [ternal.communicator.HomematicGateway] - Received new (Boolean) value ‘false’ for ‘0000D3C9905FE8:0#LOW_BAT’ from gateway with id ‘ccu’
2016-11-02 17:54:07.105 [DEBUG] [ternal.communicator.HomematicGateway] - Received new (Integer) value ‘0’ for ‘0000D3C9905FE8:0#ERROR_CODE’ from gateway with id ‘ccu’
2016-11-02 17:54:07.110 [DEBUG] [ternal.communicator.HomematicGateway] - Received new (Boolean) value ‘false’ for ‘0000D3C9905FE8:0#UNREACH’ from gateway with id ‘ccu’
2016-11-02 17:54:07.113 [DEBUG] [ternal.communicator.HomematicGateway] - Received new (Double) value ‘1.4’ for ‘0000D3C9905FE8:0#OPERATING_VOLTAGE’ from gateway with id ‘ccu’
2016-11-02 17:54:07.145 [DEBUG] [ternal.communicator.HomematicGateway] - Received new (Integer) value ‘0’ for ‘0000D3C9905FE8:1#STATE’ from gateway with id ‘ccu’
2016-11-02 17:59:26.831 [INFO ] [ternal.communicator.HomematicGateway] - No event since 319 seconds from gateway ‘ccu’, restarting RPC server
2016-11-02 17:59:26.866 [DEBUG] [nal.communicator.server.XmlRpcServer] - Stopping XML-RPC server
2016-11-02 17:59:26.886 [DEBUG] [nal.communicator.server.BinRpcServer] - Stopping BIN-RPC server
2016-11-02 17:59:26.922 [DEBUG] [ternal.communicator.HomematicGateway] - Triggering values reload for device ‘GWE00000000’
2016-11-02 17:59:26.924 [DEBUG] [atic.type.HomematicTypeGeneratorImpl] - Generating ThingType for device ‘GATEWAY-EXTRAS-CCU’ with 5 datapoints
2016-11-02 17:59:26.929 [DEBUG] [ematic.handler.HomematicThingHandler] - Initializing 0 channels of thing ‘homematic:GATEWAY-EXTRAS-CCU:ccu:GWE00000000’ from gateway ‘ccu’
2016-11-02 17:59:28.836 [DEBUG] [ternal.communicator.HomematicGateway] - Triggering values reload for device ‘NEQ0166447’
2016-11-02 17:59:28.841 [DEBUG] [ternal.communicator.HomematicGateway] - Loading values for channel HmChannel[number=0,type=MAINTENANCE,initialized=false] of device ‘NEQ0166447’
2016-11-02 17:59:28.852 [DEBUG] [ematic.handler.HomematicThingHandler] - Initializing 18 channels of thing ‘homematic:HM-LC-Dim1T-FM:ccu:NEQ0166447’ from gateway ‘ccu’
2016-11-02 17:59:28.862 [DEBUG] [ternal.communicator.HomematicGateway] - Loading values for channel HmChannel[number=1,type=DIMMER,initialized=false] of device ‘NEQ0166447’
2016-11-02 17:59:31.070 [DEBUG] [ternal.communicator.HomematicGateway] - Triggering values reload for device ‘MEQ0737879’

gerrieg · November 2, 2016, 7:13pm

@whph & @michaeljoos
Do you have devices which sends continually events (temperature sensors, …)?
If you don’t have continually events, you must raise the aliveInterval (or disable it with reconnectInterval)

The ‘Max alive time reached for socket on port 2001’ is only for sending events, not receiving. Sockets are refreshed after a certain period of time. That’s not the problem here

whph · November 2, 2016, 7:39pm

For me, I don’t have devices which send in regular intervals, so another detail here that I missed.
Have configured the “reconnectInterval” now.

OT but perhaps also easy to answer:
Is it best practice in OH2 to configure things with Paper UI (in DB directly) or with the things files?

Thanks

Jochen

michaeljoos · November 4, 2016, 5:32pm

I’m also only using window sensors and light actors. I’m somehow lost now as I tried a lot of settings.

Last things that I tried:

Deleted all Homematic-Devices from OH2 and CCU that I have added the last weeks --> No Success
Raising aliveInterval didn’t help and today I changed the setting to reconnectInterval=3600

Same result…

CCU-Log-File with an hourly error:
Nov 4 09:30:25 homematic-ccu2 user.err rfd: XmlRpc transport error calling listDevices({“RF-ccu”}) on binary://192.168.1.66:9125/RPC2:
Nov 4 10:30:26 homematic-ccu2 user.err rfd: XmlRpc transport error calling system.listMethods({“RF-ccu”}) on binary://192.168.1.66:9125/RPC2:
Nov 4 10:30:26 homematic-ccu2 user.err rfd: XmlRpc transport error calling listDevices({“RF-ccu”}) on binary://192.168.1.66:9125/RPC2:
Nov 4 11:30:26 homematic-ccu2 user.err rfd: XmlRpc transport error calling system.listMethods({“RF-ccu”}) on binary://192.168.1.66:9125/RPC2:
Nov 4 11:30:26 homematic-ccu2 user.err rfd: XmlRpc transport error calling listDevices({“RF-ccu”}) on binary://192.168.1.66:9125/RPC2:

And OH-Log:
2016-11-04 09:30:25.907 [DEBUG] [nal.communicator.server.XmlRpcServer] - Stopping XML-RPC server
2016-11-04 10:30:25.990 [DEBUG] [nal.communicator.server.XmlRpcServer] - Stopping XML-RPC server
2016-11-04 11:30:26.079 [DEBUG] [nal.communicator.server.XmlRpcServer] - Stopping XML-RPC server

Also Port 9125 or 9126 can’t be the issue as I have switched the ports with the same result. And in the past it was working with 9125?

Any other ideas?

Thanks
Michael

whph · November 4, 2016, 7:13pm

I’ still struggling, too.
After rebooting OH2 and Homegear, all Rules do work normally, but only 30-40 min. later, nothing.
I can’t see something in the logs either.
But I have some different errors in the OH2 Log, e.g.:

2016-11-04 18:32:14.304 [WARN ] [.smarthome.config.core.Configuration] - Could not set field value for field 'forceUpdate': Can not set java.lang.Boolean field org.openhab.binding.homematic.internal.model.HmDatapointConfig.forceUpdate to java.lang.String
2016-11-04 18:32:14.309 [WARN ] [.smarthome.config.core.Configuration] - Could not set field value for field 'delay': Can not set java.lang.Double field org.openhab.binding.homematic.internal.model.HmDatapointConfig.delay to java.lang.String

Thanks

Jochen

gerrieg · November 5, 2016, 9:24am

OK, so you both don’t have devices which sends events in regular intervals.

By default, the binding listens to events and if no message receives from the Homematic gateway, the binding thinks that something is wrong and restarts the RPC servers. That’s the aliveInterval setting.
In your case, you have to disable this setting and schedule a reconnect after a fixed period of time. That’s the reconnectInterval setting.

@michaeljoos
Previously, the communication was done with XML-RPC on port 9125. Now, RF, WIRED and CUxD is done with the faster BIN-RPC on port 9126 and only HomematicIP with XML-RPC on port 9125, because it does not support BIN-RPC. You can configure these ports in the bridge config.
What irritates me are the error messages in the CCU logfile. I will test the reconnect…

@whph
These warnings are from the core framework and looks like a config problem in the things file.

michaeljoos · November 5, 2016, 9:59am

Thanks for your help! Now I have inreased “aliveInterval” more from 600s to 900s and now it seems to be stable. At least the last 3 hours Reconnect I tried yesterday with a setting of 1 hour and this didn’t help. I will keep you informed!

gerrieg · November 5, 2016, 10:37am

I found it! After a reconnect to the gateway, the RPC servers are not started again.
Fixed with https://github.com/openhab/openhab2-addons/pull/1391