Homematic Jetty tries to bind to non existing ip in docker container

hashlog · October 19, 2020, 12:37pm

I noticed a very weird behaviour during the initalisation of the bridge, when adding a homematic ccu3 to openhab via the homematic binding.

I was running openhab successfully for nearly a year on a raspberry pi on docker. I upgraded my single raspberry now to a stack of raspberry pi and also changed my deployment from a single docker instance to a docker swarm. As long as openhab was my only stack on docker, everything worked like a charm.

Yesterday, I added a new deployment in my docker stack and after a restart of openhab, suddenly the homematic ccu gateway could not be reached any more. The error shown was Jetty start failed.

After increasing the log level with log:set DEBUG org.openhab.binding.homematic the java stack trace revealed the true error:

2020-10-19 13:57:44.486 [DEBUG] [ernal.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) ~[?:?]
	at org.openhab.binding.homematic.internal.communicator.AbstractHomematicGateway.startServers(AbstractHomematicGateway.java:254) ~[?:?]
	at org.openhab.binding.homematic.internal.communicator.AbstractHomematicGateway.initialize(AbstractHomematicGateway.java:192) ~[?:?]
	at org.openhab.binding.homematic.internal.handler.HomematicBridgeHandler.initializeInternal(HomematicBridgeHandler.java:111) ~[?:?]
	at java.util.concurrent.Executors$RunnableAdapter.call(Executors.java:511) [?:1.8.0_265]
	at java.util.concurrent.FutureTask.run(FutureTask.java:266) [?:1.8.0_265]
	at java.util.concurrent.ScheduledThreadPoolExecutor$ScheduledFutureTask.access$201(ScheduledThreadPoolExecutor.java:180) [?:1.8.0_265]
	at java.util.concurrent.ScheduledThreadPoolExecutor$ScheduledFutureTask.run(ScheduledThreadPoolExecutor.java:293) [?:1.8.0_265]
	at java.util.concurrent.ThreadPoolExecutor.runWorker(ThreadPoolExecutor.java:1149) [?:1.8.0_265]
	at java.util.concurrent.ThreadPoolExecutor$Worker.run(ThreadPoolExecutor.java:624) [?:1.8.0_265]
	at java.lang.Thread.run(Thread.java:748) [?:1.8.0_265]
Caused by: java.io.IOException: Failed to bind to 15ac3e7b197e/10.0.5.5: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) ~[bundleFile:9.4.20.v20190813]
	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) ~[bundleFile:9.4.20.v20190813]
	at org.openhab.binding.homematic.internal.communicator.server.XmlRpcServer.start(XmlRpcServer.java:87) ~[?:?]
	... 10 more
Caused by: java.net.BindException: Cannot assign requested address
	at sun.nio.ch.Net.bind0(Native Method) ~[?:1.8.0_265]
	at sun.nio.ch.Net.bind(Net.java:433) ~[?:1.8.0_265]
	at sun.nio.ch.Net.bind(Net.java:425) ~[?:1.8.0_265]
	at sun.nio.ch.ServerSocketChannelImpl.bind(ServerSocketChannelImpl.java:220) ~[?:1.8.0_265]
	at sun.nio.ch.ServerSocketAdaptor.bind(ServerSocketAdaptor.java:85) ~[?:1.8.0_265]
	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) ~[bundleFile:9.4.20.v20190813]
	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) ~[bundleFile:9.4.20.v20190813]
	at org.openhab.binding.homematic.internal.communicator.server.XmlRpcServer.start(XmlRpcServer.java:87) ~[?:?]
	... 10 more

The line Caused by: java.io.IOException: Failed to bind to 15ac3e7b197e/10.0.5.5:9125 catched my attention because that ip address is not even available in the openhab container.

openhab$ ip -br addr
lo               UNKNOWN        127.0.0.1/8 
eth0@if148       UP             10.0.0.19/24 
eth2@if150       UP             172.18.0.3/16 
eth1@if152       UP             10.0.4.11/24

The ip address 10.0.5.5 belongs to a container running on another node.

My openhab bridge configuration is the following: HomematicConfig[gatewayAddress=192.168.123.128,callbackHost=192.168.123.142,bindAddress=0.0.0.0,xmlCallbackPort=9125,binCallbackPort=9126,gatewayType=auto,rfPort=2001,wiredPort=2000,hmIpPort=2010,cuxdPort=8701,groupPort=9292,timeout=15,discoveryTimeToLive=-1,installModeDuration=60,socketMaxAlive=900]

Does anyone know how java/jetty was able to discover the 10.0.5.5 address and how it is possible to prevent this from happening?

Using 10.0.0.19 as callback address is not possible, since the ip address changes on every creation of the openhab container.

MHerbst · October 19, 2020, 5:44pm

As far as I remember the jetty binding uses the IP address that can be configured in Paper UI under Configuration / System / Network. You can also configure it in runtime.cfg.

hashlog · October 19, 2020, 9:00pm

@MHerbst Thank you for the hint, but the runtime.cfg is default and no IP address is set.

I dug further and deployed openhab on a docker swarm with only a single node. On this node, no network in the range of 10.0.5.0/24 exists, but the error message is still the same.

Caused by: java.io.IOException: Failed to bind to 15ac3e7b197e/10.0.5.5:9125

I have no idea where this IP address is coming from and why the binding fails. If I change the bindAddress parameter to one of the existing IPs, there is no error. But - as I said before - this is not an option, since at every start of the openhab container, the IP changes.

Using the host network mode of docker is not available in swarm mode.

MHerbst · October 20, 2020, 5:46pm

@hashlog Can have have look into openhab.log. The log file normally contains information about the found interfaces and IP addresses. It also shows the address that is used for the dashboard.

Would be interesting whether the wrong IP address appears here, too. As far as I know the Homematic binding asks the openHAB core for the IP address it should use, but I have to verify it.