HomeMatic Binding failure

After a power outage all devices came back up as expected (CCU2, RPi4, Router, Switches…) but the binding refuses to connect to the CCU2. I had this happen before running OpenHab2 and I cannot get it fixed. I tried to play a bit with the thing but to no avail.

Thing

Bridge homematic:bridge:ccu "HomeMatic CCU2" @ "Erdgeschoss" [ gatewayAddress="192.168.2.10", callbackHost="192.168.2.10", gatewayType="auto" ]
{
    Thing HM-Sec-SCo           MEQ0031741    "CCU2 Optischer Fensterkontakt"
    Thing GATEWAY-EXTRAS-CCU   GWE00000000   "CCU2 GATEWAY-EXTRAS"
}

Debug Log

15:12:12.020 [DEBUG] [ternal.handler.HomematicBridgeHandler] - HomematicConfig[gatewayAddress=192.168.2.10,callbackHost=192.168.2.10,bindAddress=192.168.2.10,xmlCallbackPort=9125,binCallbackPort=9126,gatewayType=auto,rfPort=2001,wiredPort=2000,hmIpPort=2010,cuxdPort=8701,groupPort=9292,timeout=15,discoveryTimeToLive=-1,installModeDuration=60,socketMaxAlive=900]
15:12:12.269 [INFO ] [nternal.communicator.client.RpcClient] - Interface 'WIRED' on gateway 'ccu' not available, disabling support
15:12:12.422 [DEBUG] [communicator.AbstractHomematicGateway] - Initializing gateway with id 'ccu'
15:12:12.427 [INFO ] [communicator.AbstractHomematicGateway] - HmGatewayInfo[id=CCU,type=CCU2,firmware=2.53.27,address=LEQ1012597,rf=true,wired=false,hmip=true,cuxd=true,group=true]
15:12:12.433 [DEBUG] [communicator.AbstractHomematicGateway] - Used Homematic transfer modes: RF:XML_RPC, HMIP:XML_RPC, CUXD:BIN_RPC, GROUP:XML_RPC
15:12:12.450 [DEBUG] [rnal.communicator.server.XmlRpcServer] - Initializing XML-RPC server at port 9125
15:12:12.465 [DEBUG] [ternal.handler.HomematicBridgeHandler] - Homematic bridge was set to OFFLINE-COMMUNICATION_ERROR due to the following exception: Jetty start failed
java.io.IOException: Jetty start failed
        at org.openhab.binding.homematic.internal.communicator.server.XmlRpcServer.start(XmlRpcServer.java:92) ~[bundleFile:?]
        at org.openhab.binding.homematic.internal.communicator.AbstractHomematicGateway.startServers(AbstractHomematicGateway.java:254) ~[bundleFile:?]
        at org.openhab.binding.homematic.internal.communicator.AbstractHomematicGateway.initialize(AbstractHomematicGateway.java:192) ~[bundleFile:?]
        at org.openhab.binding.homematic.internal.handler.HomematicBridgeHandler.initializeInternal(HomematicBridgeHandler.java:111) [bundleFile:?]
        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) [?:?]
        at java.lang.Thread.run(Thread.java:834) [?:?]
Caused by: java.io.IOException: Failed to bind to /192.168.2.10:9125
        at org.eclipse.jetty.server.ServerConnector.openAcceptChannel(ServerConnector.java:346) ~[bundleFile:9.4.20.v20190813]
        at org.eclipse.jetty.server.ServerConnector.open(ServerConnector.java:307) ~[bundleFile:9.4.20.v20190813]
        at org.eclipse.jetty.server.AbstractNetworkConnector.doStart(AbstractNetworkConnector.java:80) ~[bundleFile:9.4.20.v20190813]
        at org.eclipse.jetty.server.ServerConnector.doStart(ServerConnector.java:231) ~[bundleFile:9.4.20.v20190813]
        at org.eclipse.jetty.util.component.AbstractLifeCycle.start(AbstractLifeCycle.java:72) ~[?:?]
        at org.eclipse.jetty.server.Server.doStart(Server.java:385) ~[bundleFile:9.4.20.v20190813]
        at org.eclipse.jetty.util.component.AbstractLifeCycle.start(AbstractLifeCycle.java:72) ~[?:?]
        at org.openhab.binding.homematic.internal.communicator.server.XmlRpcServer.start(XmlRpcServer.java:87) ~[bundleFile:?]
        ... 9 more
Caused by: java.net.BindException: Cannot assign requested address
        at sun.nio.ch.Net.bind0(Native Method) ~[?:?]
        at sun.nio.ch.Net.bind(Net.java:455) ~[?:?]
        at sun.nio.ch.Net.bind(Net.java:447) ~[?:?]
        at sun.nio.ch.ServerSocketChannelImpl.bind(ServerSocketChannelImpl.java:227) ~[?:?]
        at sun.nio.ch.ServerSocketAdaptor.bind(ServerSocketAdaptor.java:80) ~[?:?]
        at org.eclipse.jetty.server.ServerConnector.openAcceptChannel(ServerConnector.java:342) ~[bundleFile:9.4.20.v20190813]
        at org.eclipse.jetty.server.ServerConnector.open(ServerConnector.java:307) ~[bundleFile:9.4.20.v20190813]
        at org.eclipse.jetty.server.AbstractNetworkConnector.doStart(AbstractNetworkConnector.java:80) ~[bundleFile:9.4.20.v20190813]
        at org.eclipse.jetty.server.ServerConnector.doStart(ServerConnector.java:231) ~[bundleFile:9.4.20.v20190813]
        at org.eclipse.jetty.util.component.AbstractLifeCycle.start(AbstractLifeCycle.java:72) ~[?:?]
        at org.eclipse.jetty.server.Server.doStart(Server.java:385) ~[bundleFile:9.4.20.v20190813]
        at org.eclipse.jetty.util.component.AbstractLifeCycle.start(AbstractLifeCycle.java:72) ~[?:?]
        at org.openhab.binding.homematic.internal.communicator.server.XmlRpcServer.start(XmlRpcServer.java:87) ~[bundleFile:?]
        ... 9 more
15:12:12.489 [DEBUG] [ternal.handler.HomematicBridgeHandler] - Disposing bridge 'ccu'
15:12:12.492 [DEBUG] [overy.HomematicDeviceDiscoveryService] - Stopping Homematic discovery scan
15:12:12.494 [DEBUG] [overy.HomematicDeviceDiscoveryService] - Waiting for finishing Homematic device discovery scan
15:12:12.497 [DEBUG] [overy.HomematicDeviceDiscoveryService] - Finished Homematic device discovery scan on gateway 'ccu'
15:12:12.604 [DEBUG] [rnal.communicator.server.XmlRpcServer] - Stopping XML-RPC server

Ping

ping 192.168.2.10
PING 192.168.2.10 (192.168.2.10) 56(84) bytes of data.
64 bytes from 192.168.2.10: icmp_seq=1 ttl=64 time=0.428 ms
64 bytes from 192.168.2.10: icmp_seq=2 ttl=64 time=0.424 ms
64 bytes from 192.168.2.10: icmp_seq=3 ttl=64 time=0.454 ms
64 bytes from 192.168.2.10: icmp_seq=4 ttl=64 time=0.477 ms
64 bytes from 192.168.2.10: icmp_seq=5 ttl=64 time=0.458 ms
64 bytes from 192.168.2.10: icmp_seq=6 ttl=64 time=0.505 ms

Firewall Settings (because I know you will ask, but it was working for a week so this isn’t the problem here

Homematic XML-RPC API: Full Access
Remote Homematic-Script API: Full Access
IP-Addresses (just to be sure):
  192.168.0.1;
  192.168.0.0/16;
  192.168.2.20

sudo netstat -tulpn | grep LISTEN

tcp        0      0 0.0.0.0:22              0.0.0.0:*               LISTEN      557/sshd
tcp        0      0 127.0.0.1:631           0.0.0.0:*               LISTEN      364/cupsd
tcp        0      0 0.0.0.0:5900            0.0.0.0:*               LISTEN      517/vncserver-x11-c
tcp6       0      0 127.0.0.1:45301         :::*                    LISTEN      480/java
tcp6       0      0 :::22                   :::*                    LISTEN      557/sshd
tcp6       0      0 ::1:631                 :::*                    LISTEN      364/cupsd
tcp6       0      0 :::8443                 :::*                    LISTEN      480/java
tcp6       0      0 127.0.0.1:8101          :::*                    LISTEN      480/java
tcp6       0      0 :::5900                 :::*                    LISTEN      517/vncserver-x11-c
tcp6       0      0 :::5007                 :::*                    LISTEN      480/java
tcp6       0      0 :::8080                 :::*                    LISTEN      480/java

EDIT: Oh and at the time of posting my callbackHost was wrong (set to the CCU for testing). I changed it back to 192.168.2.20 (RPi4 openhab)

After several binding restarts it looks like it connected but still is not fully functional as the refresh script does not respond as it seems

2021-03-21 15:42:00.600 [INFO ] [openhab.event.ItemCommandEvent      ] - Item 'CCU_Reload_Datapoints' received command REFRESH

Refresh rule

import org.eclipse.smarthome.core.types.RefreshType

rule "HomeMatic: Reload Datapoints on startup or cron interval"
when
    System started or
    Time cron "0 0/1 * ? * * *" //https://www.freeformatter.com/cron-expression-generator-quartz.html
then
    logInfo("RULE.SystemStarted","CRON / System started - Reload HomeMatic Datapoints")
    CCU_Reload_Datapoints.sendCommand(REFRESH)
end

Nothing happens in log. Is the rule even running?

EDIT: Still not up correctly as it seems

I did some modification in the connection handling. You can try a test version of the binding: GitHub - MHerbst/openhab-addons-test Please use the one with version 3.1 (will also work with 3.01).

Installed the binding. As per guide I had to install the two additional bundles. Did a clean-cache again just to be sure and started the service.

Had to withdraw first reply. openhab-transport-upnp did not get installed properly and I had to use the command again.

After another restart everything seems to have loaded properly. Could be coincidence, I don’t know. Gateway-Extras is now working properly, too (meaning it is not only Online but also found the Channels).

Hello Martin,

FYI - I installed the latest version but get the following warning when I restart OH3.1.0M2, however the binding seems to work so far.

2021-03-22 19:11:00.090 [WARN ] [org.apache.felix.fileinstall        ] - Error while starting bundle: file:/openhab/addons/org.openhab.binding.homematic-3.1.0-SNAPSHOT.jar
org.osgi.framework.BundleException: Could not resolve module: org.openhab.binding.homematic [208]
  Unresolved requirement: Import-Package: org.openhab.core.config.discovery.upnp
	at org.eclipse.osgi.container.Module.start(Module.java:444) ~[org.eclipse.osgi-3.12.100.jar:?]
	at org.eclipse.osgi.internal.framework.EquinoxBundle.start(EquinoxBundle.java:383) ~[org.eclipse.osgi-3.12.100.jar:?]
	at org.apache.felix.fileinstall.internal.DirectoryWatcher.startBundle(DirectoryWatcher.java:1260) [bundleFile:3.6.4]
	at org.apache.felix.fileinstall.internal.DirectoryWatcher.startBundles(DirectoryWatcher.java:1233) [bundleFile:3.6.4]
	at org.apache.felix.fileinstall.internal.DirectoryWatcher.doProcess(DirectoryWatcher.java:520) [bundleFile:3.6.4]
	at org.apache.felix.fileinstall.internal.DirectoryWatcher.process(DirectoryWatcher.java:365) [bundleFile:3.6.4]
	at org.apache.felix.fileinstall.internal.DirectoryWatcher.run(DirectoryWatcher.java:316) [bundleFile:3.6.4]

Please read my remarks in README.md regarding the manual installation of the upnp component :-).

1 Like