Issues with HomeMatic Bridge Online but devices offline

vie123 · December 29, 2020, 10:08am

Hi,
I have a weird issue trying to get HomeMatic Running with Openhab.
Background: I have a NAS with Openhab (running as network: host) and a ccu3, connected to some sensors.
I installed the binding, and added the brige via things file (…203 is my static ccu3 ip, …200 is my static NAS ip):
Bridge homematic:bridge:ccu [ gatewayAddress=“192.168.178.203”, callbackHost=“192.168.178.200” ]
Then the sensors showed up in paperui and I added them there.
What I see now: Bridge is showen as Online, all sensor are showen as Offline (java.util.concurrent.TimeoutException: Total timeout 15000 ms elapsed).
Logs in openhab look fine:

2020-12-29 09:58:11.207 [INFO ] [ternal.communicator.client.RpcClient] - Interface 'WIRED' on gateway 'ccu' not available, disabling support
2020-12-29 09:58:11.227 [INFO ] [ternal.communicator.client.RpcClient] - Interface 'CUXD' on gateway 'ccu' not available, disabling support
2020-12-29 09:58:11.245 [INFO ] [ommunicator.AbstractHomematicGateway] - HmGatewayInfo[id=CCU,type=CCU2,firmware=3.55.5,address=QEQ0704281,rf=true,wired=false,hmip=true,cuxd=false,group=true]

These are the ccu3 logs:

Dec 29 10:58:11 de.eq3.cbcs.legacy.bidcos.rpc.LegacyServiceHandler INFO  [vert.x-worker-thread-2] (un)registerCallback on LegacyServiceHandler called from url: http://openhab.validation:1000
Dec 29 10:58:11 de.eq3.ccu.virtualdevice.service.internal.rega.VirtualDeviceHandlerRega INFO  [vert.x-eventloop-thread-4] (un)registerCallback on VirtualDeviceHandlerRega called from url: http://openhab.validation:1000
Dec 29 10:58:11 de.eq3.cbcs.legacy.bidcos.rpc.LegacyServiceHandler INFO  [vert.x-worker-thread-3] (un)registerCallback on LegacyServiceHandler called from url: http://192.168.178.200:9125
Dec 29 10:58:11 de.eq3.cbcs.legacy.bidcos.rpc.LegacyServiceHandler INFO  [vert.x-worker-thread-3] init finished
Dec 29 10:58:11 de.eq3.ccu.virtualdevice.service.internal.rega.VirtualDeviceHandlerRega INFO  [vert.x-eventloop-thread-4] (un)registerCallback on VirtualDeviceHandlerRega called from url: http://192.168.178.200:9125
Dec 29 10:58:11 de.eq3.ccu.virtualdevice.service.internal.rega.VirtualDeviceHandlerRega INFO  [vert.x-eventloop-thread-4] Added InterfaceId: GROUP-ccu
Dec 29 10:58:38 de.eq3.ccu.virtualdevice.service.internal.rega.VirtualDeviceHandlerRega INFO  [vert.x-eventloop-thread-4] (un)registerCallback on VirtualDeviceHandlerRega called from url: http://192.168.178.200:9126
Dec 29 10:58:42 de.eq3.cbcs.legacy.bidcos.rpc.LegacyServiceHandler INFO  [vert.x-worker-thread-2] (un)registerCallback on LegacyServiceHandler called from url: http://192.168.178.200:9126
Dec 29 10:59:02 de.eq3.cbcs.legacy.bidcos.rpc.LegacyServiceHandler INFO  [vert.x-worker-thread-2] (un)registerCallback on LegacyServiceHandler called from url: http://192.168.178.200:9126
Dec 29 10:59:08 de.eq3.ccu.virtualdevice.service.internal.rega.VirtualDeviceHandlerRega INFO  [vert.x-eventloop-thread-4] (un)registerCallback on VirtualDeviceHandlerRega called from url: http://192.168.178.200:9126
Dec 29 10:59:22 de.eq3.cbcs.legacy.bidcos.rpc.LegacyServiceHandler INFO  [vert.x-worker-thread-2] (un)registerCallback on LegacyServiceHandler called from url: http://192.168.178.200:9126
Dec 29 10:59:22 de.eq3.cbcs.legacy.bidcos.rpc.LegacyServiceHandler INFO  [vert.x-worker-thread-2] Removed InterfaceId: HMIP-ccu
Dec 29 10:59:22 de.eq3.cbcs.legacy.bidcos.rpc.LegacyServiceHandler INFO  [vert.x-worker-thread-2] init finished
Dec 29 10:59:22 de.eq3.cbcs.legacy.bidcos.rpc.LegacyServiceHandler INFO  [vert.x-worker-thread-2] (un)registerCallback on LegacyServiceHandler called from url: http://192.168.178.200:9126
Dec 29 10:59:22 de.eq3.cbcs.legacy.bidcos.rpc.LegacyServiceHandler INFO  [vert.x-worker-thread-2] init finished
Dec 29 10:59:22 de.eq3.ccu.virtualdevice.service.internal.rega.VirtualDeviceHandlerRega INFO  [vert.x-eventloop-thread-4] (un)registerCallback on VirtualDeviceHandlerRega called from url: http://192.168.178.200:9126
Dec 29 10:59:22 de.eq3.ccu.virtualdevice.service.internal.rega.VirtualDeviceHandlerRega INFO  [vert.x-eventloop-thread-4] Added InterfaceId: GROUP-ccu
Dec 29 10:59:30 de.eq3.cbcs.legacy.bidcos.rpc.internal.InterfaceInitializer ERROR [vert.x-worker-thread-0] IO Exception: Could not add interface: HMIP-3014F711A0001F9A49942719
de.eq3.cbcs.legacy.communication.rpc.RpcIOException: java.net.ConnectException: Connection timed out (Connection timed out)
        at de.eq3.cbcs.legacy.communication.rpc.internal.transport.http.HttpTransport.sendRequest(HttpTransport.java:110)
        at de.eq3.cbcs.legacy.communication.rpc.internal.rpc.RpcClient.sendRequest(RpcClient.java:94)
        at de.eq3.cbcs.legacy.communication.rpc.internal.rpc.RpcClient.invoke(RpcClient.java:82)
        at com.sun.proxy.$Proxy20.listDevices(Unknown Source)
        at de.eq3.cbcs.legacy.bidcos.rpc.internal.LegacyBackendClient.listDevices(LegacyBackendClient.java:139)
        at de.eq3.cbcs.legacy.bidcos.rpc.internal.DeviceUtil.synchronizedBackendDevices(DeviceUtil.java:148)
        at de.eq3.cbcs.legacy.bidcos.rpc.internal.InterfaceInitializer.handle(InterfaceInitializer.java:109)
        at de.eq3.cbcs.legacy.bidcos.rpc.internal.InterfaceInitializer.handle(InterfaceInitializer.java:26)
        at io.vertx.core.eventbus.impl.HandlerRegistration.deliver(HandlerRegistration.java:212)
        at io.vertx.core.eventbus.impl.HandlerRegistration.handle(HandlerRegistration.java:191)
        at io.vertx.core.eventbus.impl.EventBusImpl.lambda$deliverToHandler$3(EventBusImpl.java:505)
        at io.vertx.core.impl.ContextImpl.lambda$wrapTask$2(ContextImpl.java:337)
        at io.vertx.core.impl.TaskQueue.lambda$new$0(TaskQueue.java:60)
        at java.util.concurrent.ThreadPoolExecutor.runWorker(ThreadPoolExecutor.java:1149)
        at java.util.concurrent.ThreadPoolExecutor$Worker.run(ThreadPoolExecutor.java:624)
        at java.lang.Thread.run(Thread.java:748)
Caused by: java.net.ConnectException: Connection timed out (Connection timed out)
        at java.net.PlainSocketImpl.socketConnect(Native Method)
        at java.net.AbstractPlainSocketImpl.doConnect(AbstractPlainSocketImpl.java:350)
        at java.net.AbstractPlainSocketImpl.connectToAddress(AbstractPlainSocketImpl.java:206)
        at java.net.AbstractPlainSocketImpl.connect(AbstractPlainSocketImpl.java:188)
        at java.net.SocksSocketImpl.connect(SocksSocketImpl.java:392)
        at java.net.Socket.connect(Socket.java:589)
        at org.apache.http.conn.scheme.PlainSocketFactory.connectSocket(PlainSocketFactory.java:120)
        at org.apache.http.impl.conn.DefaultClientConnectionOperator.openConnection(DefaultClientConnectionOperator.java:179)
        at org.apache.http.impl.conn.AbstractPoolEntry.open(AbstractPoolEntry.java:144)
        at org.apache.http.impl.conn.AbstractPooledConnAdapter.open(AbstractPooledConnAdapter.java:134)
        at org.apache.http.impl.client.DefaultRequestDirector.tryConnect(DefaultRequestDirector.java:612)
        at org.apache.http.impl.client.DefaultRequestDirector.execute(DefaultRequestDirector.java:447)
        at org.apache.http.impl.client.AbstractHttpClient.doExecute(AbstractHttpClient.java:884)
        at org.apache.http.impl.client.CloseableHttpClient.execute(CloseableHttpClient.java:82)
        at org.apache.http.impl.client.CloseableHttpClient.execute(CloseableHttpClient.java:107)
        at org.apache.http.impl.client.CloseableHttpClient.execute(CloseableHttpClient.java:55)
        at de.eq3.cbcs.legacy.communication.rpc.internal.transport.http.HttpTransport.sendRequest(HttpTransport.java:106)
        ... 15 more
Dec 29 10:59:30 de.eq3.ccu.virtualdevice.service.internal.rega.BackendWorker INFO  [vert.x-worker-thread-2] Execute BackendCommand: de.eq3.ccu.virtualdevice.service.internal.rega.BackendUpdateDevicesCommand
Dec 29 10:59:30 de.eq3.cbcs.legacy.bidcos.rpc.internal.InterfaceInitializer INFO  [vert.x-worker-thread-0] Added InterfaceId: HMIP-3014F711A0001F9A49942719

I do not really understand what could be the issue, I did verify both ports are open on my NAS:

david@nas:/$  sudo netstat -tulpn | grep LISTEN | grep 912
tcp6       0      0 192.168.178.200:9125    :::*                    LISTEN      12864/java
tcp6       0      0 192.168.178.200:9126    :::*                    LISTEN      12864/java

Anyone has an idea what I could do?
Thx a lot in advance!
David

MHerbst · December 29, 2020, 10:34am

Your netstat output looks a bit strange. It shows protocol “tcp6” but with an IPv4 local address.

vie123 · December 29, 2020, 11:47am

As far as I understand it, this is just because the port is opend on both, ip v4 and v6, see: https://stackoverflow.com/a/30006034
I can reach the endpoint via its ipv4 adress

MHerbst · December 29, 2020, 11:53am

Hmm, I am not sure. I have tested it on my Raspi and there the IPv4 addresses are shown with protocol tcp.

According to your logs from the CCU it seems that both ports can not be reached by CCU. The bridge is shown as online because the binding contacts the CCU, so this way works. But in order to send data back to the binding the CCU must be able to communicate with ports 9125/9126. It seems that the communication is blocked somewhere. Did you check the firewall settings on your NAS?

I don’t have experience with running OH on a NAS (in a docker container) but I remember that others had similar problems. Maybe you can find some more information here in the forum.

vie123 · December 29, 2020, 12:21pm

I did disable the firewall on my NAS.
My NAS is directly connected to a FritzBox, maybe it is blocking the Port (I would assume it only blocks port for external connections?), but other ports are working fine.
Interessting observation: after a restart the bin-rpc server port is not opening anymore (even if i change it to a different port number). Again no errors in the logs.

MHerbst · December 29, 2020, 12:28pm

How is openHAB executed on your NAS (BTW: what kind of NAS is it)? If it is running within a Docker container just must make sure that all ports are correclty mapped and that the correct IP address is used. If openHAB is running within the container, than it has a different IP address-

vie123 · December 29, 2020, 12:41pm

It is a synology 718+.
The Openhab docker container is running in Networkmode=host so port mapping is not required.
Before I was running it in Networkmode=bridge, there I was not able to connect to the Bridge, this is why I changed it (also it is recommende to use the host mode in the Openhab install guide for Docker).
Because of the different IP issue, I did set NAS ip as callbackHost (I read here in the forum this is one issue, that openhab sends the docker ip instead of the host ip, and can be resolved this was).

*edit, it is finally working!

So now my thing defintion is like that:

Bridge homematic:bridge:ccu [ gatewayAddress="192.168.178.203", callbackHost="192.168.178.200", bindAddress="0.0.0.0" ]

system · February 9, 2021, 4:53am

This topic was automatically closed 41 days after the last reply. New replies are no longer allowed.