HomeMatic binding not listing any new items known to the CCU3 despite the log showing data of said devices

Interaktiv · January 30, 2020, 1:28pm

I am trying to setup OpenHAB with a CCU3 and numerous other HomeMatic devices, both wired and wireless.
I am using a Raspberry Pi 4 Model B with the latest Openhabian installed ([master]v1.5-541(5158a5f)) with OpenHAB 2.5.1 (Build) and the HomeMatic binding 2.5.1.

OpenHab has no problem finding the CCU but that’s it. During my tests a few months ago, scanning with a connected CCU3 resulted in all devices known to the CCU being listed as new items. But now the list stays empty despite the CCU knowing like 80 switches/lights/whatever.

I tried disconnecting the CCU from the internet and using a network that only consisted of the Rasbpi, CCU and my computer with no results.
Multiple restarts of all devices didn’t help either.

This is the firewall configuration of the CCU:

Summary

Authentication is disabled.

This is the full startup log of the HomeMatic binding (to my best knowledge) as described in the documentation of said binding. During this startup the CCU3 was not connected to the internet:

Summary

2020-01-30 12:30:24.985 [DEBUG] [nal.communicator.server.XmlRpcServer] - Stopping XML-RPC server
2020-01-30 12:31:17.755 [DEBUG] [ternal.discovery.CcuDiscoveryService] - Starting Homematic CCU discovery scan
2020-01-30 12:31:17.847 [DEBUG] [ernal.handler.HomematicBridgeHandler] - HomematicConfig[gatewayAddress=192.168.1.87,callbackHost=192.168.1.80,bindAddress=192.168.1.80,xmlCallbackPort=9125,binCallbackPort=9126,gatewayType=auto,rfPort=2001,wiredPort=2000,hmIpPort=2010,cuxdPort=8701,groupPort=9292,timeout=15,discoveryTimeToLive=-1,installModeDuration=60,socketMaxAlive=900]
2020-01-30 12:31:17.850 [TRACE] [nal.communicator.client.XmlRpcClient] - Client XmlRpcRequest (port 2001):

<?xml version="1.0" encoding="ISO-8859-1"?>

getDeviceDescription
BidCoS-RF
2020-01-30 12:31:20.958 [DEBUG] [nal.communicator.client.XmlRpcClient] - XmlRpcMessage failure, sending message again 1/1
2020-01-30 12:31:24.078 [TRACE] [nal.communicator.client.XmlRpcClient] - Client XmlRpcRequest (port 2001):

<?xml version="1.0" encoding="ISO-8859-1"?>

listBidcosInterfaces

2020-01-30 12:31:27.198 [DEBUG] [nal.communicator.client.XmlRpcClient] - XmlRpcMessage failure, sending message again 1/1
2020-01-30 12:31:30.318 [TRACE] [nal.communicator.client.XmlRpcClient] - Client XmlRpcRequest (port 2010):

<?xml version="1.0" encoding="ISO-8859-1"?>

listBidcosInterfaces

2020-01-30 12:31:33.438 [DEBUG] [nal.communicator.client.XmlRpcClient] - XmlRpcMessage failure, sending message again 1/1
2020-01-30 12:31:36.564 [DEBUG] [ernal.handler.HomematicBridgeHandler] - Refreshing bridge ‘3014F711A0001F98A9AA0C75’
2020-01-30 12:31:36.560 [DEBUG] [ernal.handler.HomematicBridgeHandler] - Homematic bridge was set to OFFLINE-COMMUNICATION_ERROR due to the following exception: java.net.NoRouteToHostException: No route to host
java.io.IOException: java.net.NoRouteToHostException: No route to host
at org.openhab.binding.homematic.internal.communicator.client.XmlRpcClient.sendMessage(XmlRpcClient.java:98) ~[?:?]
at org.openhab.binding.homematic.internal.communicator.client.XmlRpcClient.sendMessage(XmlRpcClient.java:102) ~[?:?]
at org.openhab.binding.homematic.internal.communicator.client.XmlRpcClient.sendMessage(XmlRpcClient.java:67) ~[?:?]
at org.openhab.binding.homematic.internal.communicator.client.RpcClient.listBidcosInterfaces(RpcClient.java:118) ~[?:?]
at org.openhab.binding.homematic.internal.communicator.client.RpcClient.getGatewayInfo(RpcClient.java:244) ~[?:?]
at org.openhab.binding.homematic.internal.communicator.HomematicGatewayFactory.loadGatewayInfo(HomematicGatewayFactory.java:51) ~[?:?]
at org.openhab.binding.homematic.internal.communicator.HomematicGatewayFactory.createGateway(HomematicGatewayFactory.java:35) ~[?:?]
at org.openhab.binding.homematic.internal.handler.HomematicBridgeHandler.initializeInternal(HomematicBridgeHandler.java:108) ~[?:?]
at java.util.concurrent.Executors$RunnableAdapter.call(Executors.java:511) [?:1.8.0_222]
at java.util.concurrent.FutureTask.run(FutureTask.java:266) [?:1.8.0_222]
at java.util.concurrent.ScheduledThreadPoolExecutor$ScheduledFutureTask.access$201(ScheduledThreadPoolExecutor.java:180) [?:1.8.0_222]
at java.util.concurrent.ScheduledThreadPoolExecutor$ScheduledFutureTask.run(ScheduledThreadPoolExecutor.java:293) [?:1.8.0_222]
at java.util.concurrent.ThreadPoolExecutor.runWorker(ThreadPoolExecutor.java:1149) [?:1.8.0_222]
at java.util.concurrent.ThreadPoolExecutor$Worker.run(ThreadPoolExecutor.java:624) [?:1.8.0_222]
at java.lang.Thread.run(Thread.java:748) [?:1.8.0_222]
Caused by: java.util.concurrent.ExecutionException: java.net.NoRouteToHostException: No route to host
at org.eclipse.jetty.client.util.FutureResponseListener.getResult(FutureResponseListener.java:118) ~[?:?]
at org.eclipse.jetty.client.util.FutureResponseListener.get(FutureResponseListener.java:101) ~[?:?]
at org.eclipse.jetty.client.HttpRequest.send(HttpRequest.java:685) ~[?:?]
at org.openhab.binding.homematic.internal.communicator.client.XmlRpcClient.sendMessage(XmlRpcClient.java:84) ~[?:?]
… 14 more
Caused by: java.net.NoRouteToHostException: No route to host
at sun.nio.ch.SocketChannelImpl.checkConnect(Native Method) ~[?:1.8.0_222]
at sun.nio.ch.SocketChannelImpl.finishConnect(SocketChannelImpl.java:717) ~[?:1.8.0_222]
at org.eclipse.jetty.io.SelectorManager.doFinishConnect(SelectorManager.java:355) ~[?:?]
at org.eclipse.jetty.io.ManagedSelector.processConnect(ManagedSelector.java:223) ~[?:?]
at org.eclipse.jetty.io.ManagedSelector.access$1500(ManagedSelector.java:61) ~[?:?]
at org.eclipse.jetty.io.ManagedSelector$SelectorProducer.processSelected(ManagedSelector.java:533) ~[?:?]
at org.eclipse.jetty.io.ManagedSelector$SelectorProducer.produce(ManagedSelector.java:395) ~[?:?]
at org.eclipse.jetty.util.thread.strategy.EatWhatYouKill.produceTask(EatWhatYouKill.java:360) ~[?:?]
at org.eclipse.jetty.util.thread.strategy.EatWhatYouKill.doProduce(EatWhatYouKill.java:184) ~[?:?]
at org.eclipse.jetty.util.thread.strategy.EatWhatYouKill.tryProduce(EatWhatYouKill.java:171) ~[?:?]
at org.eclipse.jetty.util.thread.strategy.EatWhatYouKill.run(EatWhatYouKill.java:129) ~[?:?]
at org.eclipse.jetty.util.thread.ReservedThreadExecutor$ReservedThread.run(ReservedThreadExecutor.java:367) ~[?:?]
at org.eclipse.jetty.util.thread.QueuedThreadPool.runJob(QueuedThreadPool.java:782) ~[?:?]
at org.eclipse.jetty.util.thread.QueuedThreadPool$Runner.run(QueuedThreadPool.java:918) ~[?:?]
… 1 more
2020-01-30 12:31:36.604 [DEBUG] [ernal.handler.HomematicBridgeHandler] - Disposing bridge ‘3014F711A0001F98A9AA0C75’
2020-01-30 12:31:36.606 [DEBUG] [very.HomematicDeviceDiscoveryService] - Stopping Homematic discovery scan
2020-01-30 12:31:36.608 [DEBUG] [very.HomematicDeviceDiscoveryService] - Waiting for finishing Homematic device discovery scan
2020-01-30 12:31:36.609 [DEBUG] [very.HomematicDeviceDiscoveryService] - Finished Homematic device discovery scan on gateway ‘UNKNOWN’
2020-01-30 12:31:46.614 [DEBUG] [ernal.handler.HomematicBridgeHandler] - HomematicConfig[gatewayAddress=192.168.1.87,callbackHost=192.168.1.80,bindAddress=192.168.1.80,xmlCallbackPort=9125,binCallbackPort=9126,gatewayType=auto,rfPort=2001,wiredPort=2000,hmIpPort=2010,cuxdPort=8701,groupPort=9292,timeout=15,discoveryTimeToLive=-1,installModeDuration=60,socketMaxAlive=900]
2020-01-30 12:31:46.617 [TRACE] [nal.communicator.client.XmlRpcClient] - Client XmlRpcRequest (port 2001):

<?xml version="1.0" encoding="ISO-8859-1"?>

getDeviceDescription
BidCoS-RF
2020-01-30 12:31:49.758 [DEBUG] [nal.communicator.client.XmlRpcClient] - XmlRpcMessage failure, sending message again 1/1
2020-01-30 12:31:52.878 [TRACE] [nal.communicator.client.XmlRpcClient] - Client XmlRpcRequest (port 2001):

<?xml version="1.0" encoding="ISO-8859-1"?>

listBidcosInterfaces

2020-01-30 12:31:55.998 [DEBUG] [nal.communicator.client.XmlRpcClient] - XmlRpcMessage failure, sending message again 1/1
2020-01-30 12:31:59.118 [TRACE] [nal.communicator.client.XmlRpcClient] - Client XmlRpcRequest (port 2010):

<?xml version="1.0" encoding="ISO-8859-1"?>

listBidcosInterfaces

2020-01-30 12:32:02.238 [DEBUG] [nal.communicator.client.XmlRpcClient] - XmlRpcMessage failure, sending message again 1/1
2020-01-30 12:32:05.359 [DEBUG] [ernal.handler.HomematicBridgeHandler] - Homematic bridge was set to OFFLINE-COMMUNICATION_ERROR due to the following exception: java.net.NoRouteToHostException: No route to host
java.io.IOException: java.net.NoRouteToHostException: No route to host
at org.openhab.binding.homematic.internal.communicator.client.XmlRpcClient.sendMessage(XmlRpcClient.java:98) ~[?:?]
at org.openhab.binding.homematic.internal.communicator.client.XmlRpcClient.sendMessage(XmlRpcClient.java:102) ~[?:?]
at org.openhab.binding.homematic.internal.communicator.client.XmlRpcClient.sendMessage(XmlRpcClient.java:67) ~[?:?]
at org.openhab.binding.homematic.internal.communicator.client.RpcClient.listBidcosInterfaces(RpcClient.java:118) ~[?:?]
at org.openhab.binding.homematic.internal.communicator.client.RpcClient.getGatewayInfo(RpcClient.java:244) ~[?:?]
at org.openhab.binding.homematic.internal.communicator.HomematicGatewayFactory.loadGatewayInfo(HomematicGatewayFactory.java:51) ~[?:?]
at org.openhab.binding.homematic.internal.communicator.HomematicGatewayFactory.createGateway(HomematicGatewayFactory.java:35) ~[?:?]
at org.openhab.binding.homematic.internal.handler.HomematicBridgeHandler.initializeInternal(HomematicBridgeHandler.java:108) ~[?:?]
at java.util.concurrent.Executors$RunnableAdapter.call(Executors.java:511) [?:1.8.0_222]
at java.util.concurrent.FutureTask.run(FutureTask.java:266) [?:1.8.0_222]
at java.util.concurrent.ScheduledThreadPoolExecutor$ScheduledFutureTask.access$201(ScheduledThreadPoolExecutor.java:180) [?:1.8.0_222]
at java.util.concurrent.ScheduledThreadPoolExecutor$ScheduledFutureTask.run(ScheduledThreadPoolExecutor.java:293) [?:1.8.0_222]
at java.util.concurrent.ThreadPoolExecutor.runWorker(ThreadPoolExecutor.java:1149) [?:1.8.0_222]
at java.util.concurrent.ThreadPoolExecutor$Worker.run(ThreadPoolExecutor.java:624) [?:1.8.0_222]
at java.lang.Thread.run(Thread.java:748) [?:1.8.0_222]
Caused by: java.util.concurrent.ExecutionException: java.net.NoRouteToHostException: No route to host
at org.eclipse.jetty.client.util.FutureResponseListener.getResult(FutureResponseListener.java:118) ~[?:?]
at org.eclipse.jetty.client.util.FutureResponseListener.get(FutureResponseListener.java:101) ~[?:?]
at org.eclipse.jetty.client.HttpRequest.send(HttpRequest.java:685) ~[?:?]
at org.openhab.binding.homematic.internal.communicator.client.XmlRpcClient.sendMessage(XmlRpcClient.java:84) ~[?:?]
… 14 more
Caused by: java.net.NoRouteToHostException: No route to host
at sun.nio.ch.SocketChannelImpl.checkConnect(Native Method) ~[?:1.8.0_222]
at sun.nio.ch.SocketChannelImpl.finishConnect(SocketChannelImpl.java:717) ~[?:1.8.0_222]
at org.eclipse.jetty.io.SelectorManager.doFinishConnect(SelectorManager.java:355) ~[?:?]
at org.eclipse.jetty.io.ManagedSelector.processConnect(ManagedSelector.java:223) ~[?:?]
at org.eclipse.jetty.io.ManagedSelector.access$1500(ManagedSelector.java:61) ~[?:?]
at org.eclipse.jetty.io.ManagedSelector$SelectorProducer.processSelected(ManagedSelector.java:533) ~[?:?]
at org.eclipse.jetty.io.ManagedSelector$SelectorProducer.produce(ManagedSelector.java:395) ~[?:?]
at org.eclipse.jetty.util.thread.strategy.EatWhatYouKill.produceTask(EatWhatYouKill.java:360) ~[?:?]
at org.eclipse.jetty.util.thread.strategy.EatWhatYouKill.doProduce(EatWhatYouKill.java:184) ~[?:?]
at org.eclipse.jetty.util.thread.strategy.EatWhatYouKill.tryProduce(EatWhatYouKill.java:171) ~[?:?]
at org.eclipse.jetty.util.thread.strategy.EatWhatYouKill.run(EatWhatYouKill.java:129) ~[?:?]
at org.eclipse.jetty.util.thread.ReservedThreadExecutor$ReservedThread.run(ReservedThreadExecutor.java:367) ~[?:?]
at org.eclipse.jetty.util.thread.QueuedThreadPool.runJob(QueuedThreadPool.java:782) ~[?:?]
at org.eclipse.jetty.util.thread.QueuedThreadPool$Runner.run(QueuedThreadPool.java:918) ~[?:?]
… 1 more
2020-01-30 12:32:05.398 [DEBUG] [ernal.handler.HomematicBridgeHandler] - Disposing bridge ‘3014F711A0001F98A9AA0C75’
2020-01-30 12:32:05.399 [DEBUG] [very.HomematicDeviceDiscoveryService] - Stopping Homematic discovery scan
2020-01-30 12:32:05.401 [DEBUG] [very.HomematicDeviceDiscoveryService] - Waiting for finishing Homematic device discovery scan
2020-01-30 12:32:05.402 [DEBUG] [very.HomematicDeviceDiscoveryService] - Finished Homematic device discovery scan on gateway ‘UNKNOWN’

Interestingly during a startup with internet connection I see this:

Summary

2020-01-30 12:47:48.926 [TRACE] [nal.communicator.client.XmlRpcClient] - Client XmlRpcResponse (port 2001):

<?xml version="1.0" encoding="iso-8859-1"?>

2020-01-30 12:47:48.927 [DEBUG] [ommunicator.AbstractHomematicGateway] - Received new (Boolean) value ‘true’ for ‘KEQ0802039:0#STICKY_UNREACH’ from gateway with id ‘3014F711A0001F98A9AA0C75’
2020-01-30 12:47:48.929 [DEBUG] [ommunicator.AbstractHomematicGateway] - Received new (Boolean) value ‘true’ for ‘KEQ0802039:0#UNREACH’ from gateway with id ‘3014F711A0001F98A9AA0C75’
2020-01-30 12:47:48.930 [TRACE] [nal.communicator.client.XmlRpcClient] - Client XmlRpcRequest (port 2010):

<?xml version="1.0" encoding="ISO-8859-1"?>

init
http://192.168.1.80:9125HMIP-3014F711A0001F98A9AA0C75
2020-01-30 12:47:48.930 [TRACE] [nal.communicator.server.XmlRpcServer] - Server XmlRpcResponse:

<?xml version="1.0" encoding="ISO-8859-1"?>

event
2020-01-30 12:47:48.952 [TRACE] [nal.communicator.client.XmlRpcClient] - Client XmlRpcResponse (port 2010):

<?xml version="1.0" encoding="ISO-8859-1"?>

2020-01-30 12:47:48.956 [TRACE] [nal.communicator.client.XmlRpcClient] - Client XmlRpcRequest (port 9292):

<?xml version="1.0" encoding="ISO-8859-1"?>

init
http://192.168.1.80:9125GROUP-3014F711A0001F98A9AA0C75
2020-01-30 12:47:49.004 [TRACE] [nal.communicator.server.XmlRpcServer] - Server parsed XmlRpcMessage:
newDevices()
RF-3014F711A0001F98A9AA0C75
[
{
PARAMSETS=
[
MASTER
]
RF_ADDRESS=12209091
CHILDREN=
[
BidCoS-RF:0
BidCoS-RF:1
BidCoS-RF:2
BidCoS-RF:3
BidCoS-RF:4
BidCoS-RF:5
BidCoS-RF:6
BidCoS-RF:7
BidCoS-RF:8
BidCoS-RF:9
BidCoS-RF:10
BidCoS-RF:11
BidCoS-RF:12
BidCoS-RF:13
BidCoS-RF:14
BidCoS-RF:15
BidCoS-RF:16
BidCoS-RF:17
BidCoS-RF:18
BidCoS-RF:19
BidCoS-RF:20
BidCoS-RF:21
BidCoS-RF:22
BidCoS-RF:23
BidCoS-RF:24
BidCoS-RF:25
BidCoS-RF:26
BidCoS-RF:27
BidCoS-RF:28
BidCoS-RF:29
BidCoS-RF:30
BidCoS-RF:31
BidCoS-RF:32
BidCoS-RF:33
BidCoS-RF:34
BidCoS-RF:35
BidCoS-RF:36
BidCoS-RF:37
BidCoS-RF:38
BidCoS-RF:39
BidCoS-RF:40
BidCoS-RF:41
BidCoS-RF:42
BidCoS-RF:43
BidCoS-RF:44
BidCoS-RF:45
BidCoS-RF:46
BidCoS-RF:47
BidCoS-RF:48
BidCoS-RF:49
BidCoS-RF:50
]
UPDATABLE=0
INTERFACE=PEQ2139253
RX_MODE=1
ADDRESS=BidCoS-RF
FIRMWARE=3.49.17
PARENT=
VERSION=6
FLAGS=9
ROAMING=0
TYPE=HM-RCV-50
}
{
PARAMSETS=
[
MASTER
VALUES
]
PARENT_TYPE=HM-RCV-50
ADDRESS=BidCoS-RF:0
DIRECTION=0
PARENT=BidCoS-RF
VERSION=6
FLAGS=3
INDEX=0
LINK_SOURCE_ROLES=
LINK_TARGET_ROLES=
AES_ACTIVE=0
TYPE=MAINTENANCE
}
{
PARAMSETS=
[
LINK
MASTER
VALUES
]
PARENT_TYPE=HM-RCV-50
ADDRESS=BidCoS-RF:1
DIRECTION=1
PARENT=BidCoS-RF
VERSION=6
FLAGS=1
INDEX=1
LINK_SOURCE_ROLES=KEYMATIC REMOTECONTROL_RECEIVER SWITCH WINMATIC
LINK_TARGET_ROLES=
AES_ACTIVE=0
TYPE=VIRTUAL_KEY
}
{
PARAMSETS=
[
LINK
MASTER
VALUES
]
PARENT_TYPE=HM-RCV-50
ADDRESS=BidCoS-RF:2
DIRECTION=1
PARENT=BidCoS-RF
VERSION=6
FLAGS=1
INDEX=2
LINK_SOURCE_ROLES=KEYMATIC REMOTECONTROL_RECEIVER SWITCH WINMATIC
LINK_TARGET_ROLES=
AES_ACTIVE=0
TYPE=VIRTUAL_KEY
}
{
PARAMSETS=
[
LINK
MASTER
VALUES
]
PARENT_TYPE=HM-RCV-50
ADDRESS=BidCoS-RF:3
DIRECTION=1
PARENT=BidCoS-RF
VERSION=6
FLAGS=1
INDEX=3
LINK_SOURCE_ROLES=KEYMATIC REMOTECONTROL_RECEIVER SWITCH WINMATIC
LINK_TARGET_ROLES=
AES_ACTIVE=0
TYPE=VIRTUAL_KEY
}
{
PARAMSETS=
[
LINK
MASTER
VALUES
]
PARENT_TYPE=HM-RCV-50
ADDRESS=BidCoS-RF:4
DIRECTION=1
PARENT=BidCoS-RF
VERSION=6
FLAGS=1
INDEX=4
LINK_SOURCE_ROLES=KEYMATIC REMOTECONTROL_RECEIVER SWITCH WINMATIC
LINK_TARGET_ROLES=
AES_ACTIVE=0
TYPE=VIRTUAL_KEY
}
{
PARAMSETS=
[
LINK
MASTER
VALUES
]
PARENT_TYPE=HM-RCV-50
ADDRESS=BidCoS-RF:5
DIRECTION=1
PARENT=BidCoS-RF
VERSION=6
FLAGS=1
INDEX=5
LINK_SOURCE_ROLES=KEYMATIC REMOTECONTROL_RECEIVER SWITCH WINMATIC
LINK_TARGET_ROLES=
AES_ACTIVE=0
TYPE=VIRTUAL_KEY
}

[SNIP]

]

2020-01-30 12:47:49.006 [TRACE] [nal.communicator.server.XmlRpcServer] - Server XmlRpcResponse:

<?xml version="1.0" encoding="ISO-8859-1"?>

2020-01-30 12:47:50.360 [TRACE] [nal.communicator.server.XmlRpcServer] - Server parsed XmlRpcMessage:
listDevices()
HMIP-3014F711A0001F98A9AA0C75

2020-01-30 12:47:50.362 [TRACE] [nal.communicator.server.XmlRpcServer] - Server XmlRpcResponse:

<?xml version="1.0" encoding="ISO-8859-1"?>

2020-01-30 12:47:51.300 [TRACE] [nal.communicator.server.XmlRpcServer] - Server parsed XmlRpcMessage:
newDevices()
HMIP-3014F711A0001F98A9AA0C75
[
{
FIRMWARE_UPDATE_STATE=UP_TO_DATE
TEAM_CHANNELS=
[
]
LINK_TARGET_ROLES=
AVAILABLE_FIRMWARE=0.0.0
GROUP=
INTERFACE=
PARENT=
FLAGS=1
INDEX=0
TYPE=HmIPW-WTH
AES_ACTIVE=1
TEAM_TAG=
SUBTYPE=HMIPW_WTH
PARAMSETS=
[
MASTER
SERVICE
]
RF_ADDRESS=11300355
DIRECTION=0
LINK_SOURCE_ROLES=
CHILDREN=
[
001CDA4990F53C:0
001CDA4990F53C:1
001CDA4990F53C:2
001CDA4990F53C:3
001CDA4990F53C:4
001CDA4990F53C:5
001CDA4990F53C:6
001CDA4990F53C:7
]
UPDATABLE=true
RX_MODE=12
PARENT_TYPE=
ADDRESS=001CDA4990F53C
FIRMWARE=2.4.6
VERSION=1
TEAM=
ROAMING=0
}
{
FIRMWARE_UPDATE_STATE=
TEAM_CHANNELS=
[
]
LINK_TARGET_ROLES=
AVAILABLE_FIRMWARE=
GROUP=
INTERFACE=
PARENT=001CDA4990F53C
FLAGS=1
INDEX=0
TYPE=MAINTENANCE
AES_ACTIVE=1
TEAM_TAG=
SUBTYPE=
PARAMSETS=
[
MASTER
VALUES
SERVICE
]
RF_ADDRESS=0
DIRECTION=0
LINK_SOURCE_ROLES=
CHILDREN=
[
]
UPDATABLE=true
RX_MODE=0
PARENT_TYPE=HmIPW-WTH
ADDRESS=001CDA4990F53C:0
FIRMWARE=
VERSION=1
TEAM=
ROAMING=0
}
{
FIRMWARE_UPDATE_STATE=
TEAM_CHANNELS=
[
]
LINK_TARGET_ROLES=
AVAILABLE_FIRMWARE=
GROUP=
INTERFACE=
PARENT=001CDA4990F53C
FLAGS=1
INDEX=1
TYPE=HEATING_CLIMATECONTROL_TRANSCEIVER
AES_ACTIVE=1
TEAM_TAG=
SUBTYPE=
PARAMSETS=
[
MASTER
VALUES
LINK
SERVICE
]
RF_ADDRESS=0
DIRECTION=1
LINK_SOURCE_ROLES=CLIMATE_CONTROL_WTH_TRV
CHILDREN=
[
]
UPDATABLE=true
RX_MODE=0
PARENT_TYPE=HmIPW-WTH
ADDRESS=001CDA4990F53C:1
FIRMWARE=
VERSION=1
TEAM=
ROAMING=0
}
{
FIRMWARE_UPDATE_STATE=
TEAM_CHANNELS=
[
]
LINK_TARGET_ROLES=CLIMATE_CONTROL_TRV_WTH
AVAILABLE_FIRMWARE=
GROUP=
INTERFACE=
PARENT=001CDA4990F53C
FLAGS=1
INDEX=2
TYPE=HEATING_CLIMATECONTROL_RECEIVER
AES_ACTIVE=1
TEAM_TAG=
SUBTYPE=
PARAMSETS=
[
MASTER
VALUES
LINK
SERVICE
]
RF_ADDRESS=0
DIRECTION=2
LINK_SOURCE_ROLES=
CHILDREN=
[
]
UPDATABLE=true
RX_MODE=0
PARENT_TYPE=HmIPW-WTH
ADDRESS=001CDA4990F53C:2
FIRMWARE=
VERSION=1
TEAM=
ROAMING=0
}
{
FIRMWARE_UPDATE_STATE=
TEAM_CHANNELS=
[
]
LINK_TARGET_ROLES=
AVAILABLE_FIRMWARE=
GROUP=
INTERFACE=
PARENT=001CDA4990F53C
FLAGS=1
INDEX=3
TYPE=HEATING_CLIMATECONTROL_CL_TRANSMITTER
AES_ACTIVE=1
TEAM_TAG=
SUBTYPE=
PARAMSETS=
[
MASTER
VALUES
LINK
SERVICE
]
RF_ADDRESS=0
DIRECTION=1
LINK_SOURCE_ROLES=CLIMATE_CONTROL_CL
CHILDREN=
[
]
UPDATABLE=true
RX_MODE=0
PARENT_TYPE=HmIPW-WTH
ADDRESS=001CDA4990F53C:3
FIRMWARE=
VERSION=1
TEAM=
ROAMING=0
}
{
FIRMWARE_UPDATE_STATE=
TEAM_CHANNELS=
[
]
LINK_TARGET_ROLES=WINDOW_SWITCH
AVAILABLE_FIRMWARE=
GROUP=
INTERFACE=
PARENT=001CDA4990F53C
FLAGS=1
INDEX=4
TYPE=HEATING_SHUTTER_CONTACT_RECEIVER
AES_ACTIVE=1
TEAM_TAG=
SUBTYPE=
PARAMSETS=
[
MASTER
VALUES
LINK
SERVICE
]
RF_ADDRESS=0
DIRECTION=2
LINK_SOURCE_ROLES=
CHILDREN=
[
]
UPDATABLE=true
RX_MODE=0
PARENT_TYPE=HmIPW-WTH
ADDRESS=001CDA4990F53C:4
FIRMWARE=
VERSION=1
TEAM=
ROAMING=0
}
{
FIRMWARE_UPDATE_STATE=
TEAM_CHANNELS=
[
]
LINK_TARGET_ROLES=
AVAILABLE_FIRMWARE=
GROUP=
INTERFACE=
PARENT=001CDA4990F53C
FLAGS=1
INDEX=5
TYPE=HEATING_CLIMATECONTROL_SWITCH_TRANSMITTER
AES_ACTIVE=1
TEAM_TAG=
SUBTYPE=
PARAMSETS=
[
MASTER
VALUES
LINK
SERVICE
]
RF_ADDRESS=0
DIRECTION=1
LINK_SOURCE_ROLES=SWITCH
CHILDREN=
[
]
UPDATABLE=true
RX_MODE=0
PARENT_TYPE=HmIPW-WTH
ADDRESS=001CDA4990F53C:5
FIRMWARE=
VERSION=1
TEAM=
ROAMING=0
}

[Snip]

To me it seems that the CCU is trying to communicate with OpenHAB but somehow fails?

Also during a manual device discovery I always get this error:

Summary

2020-01-30 13:22:47.503 [ERROR] [very.HomematicDeviceDiscoveryService] - java.lang.IllegalArgumentException: Buffering capacity 2097152 exceeded

java.io.IOException: java.lang.IllegalArgumentException: Buffering capacity 2097152 exceeded

at org.openhab.binding.homematic.internal.communicator.client.XmlRpcClient.sendMessage(XmlRpcClient.java:98) ~[?:?]

at org.openhab.binding.homematic.internal.communicator.client.XmlRpcClient.sendMessage(XmlRpcClient.java:102) ~[?:?]

at org.openhab.binding.homematic.internal.communicator.client.XmlRpcClient.sendMessage(XmlRpcClient.java:67) ~[?:?]

at org.openhab.binding.homematic.internal.communicator.client.RpcClient.listDevices(RpcClient.java:168) ~[?:?]

at org.openhab.binding.homematic.internal.communicator.AbstractHomematicGateway.getDeviceDescriptions(AbstractHomematicGateway.java:448) ~[?:?]

at org.openhab.binding.homematic.internal.communicator.AbstractHomematicGateway.loadAllDeviceMetadata(AbstractHomematicGateway.java:372) ~[?:?]

at org.openhab.binding.homematic.internal.discovery.HomematicDeviceDiscoveryService.lambda$0(HomematicDeviceDiscoveryService.java:210) ~[?:?]

at java.util.concurrent.Executors$RunnableAdapter.call(Executors.java:511) [?:1.8.0_222]

at java.util.concurrent.FutureTask.run(FutureTask.java:266) [?:1.8.0_222]

at java.util.concurrent.ScheduledThreadPoolExecutor$ScheduledFutureTask.access$201(ScheduledThreadPoolExecutor.java:180) [?:1.8.0_222]

at java.util.concurrent.ScheduledThreadPoolExecutor$ScheduledFutureTask.run(ScheduledThreadPoolExecutor.java:293) [?:1.8.0_222]

at java.util.concurrent.ThreadPoolExecutor.runWorker(ThreadPoolExecutor.java:1149) [?:1.8.0_222]

at java.util.concurrent.ThreadPoolExecutor$Worker.run(ThreadPoolExecutor.java:624) [?:1.8.0_222]

at java.lang.Thread.run(Thread.java:748) [?:1.8.0_222]

Caused by: java.util.concurrent.ExecutionException: java.lang.IllegalArgumentException: Buffering capacity 2097152 exceeded

at org.eclipse.jetty.client.util.FutureResponseListener.getResult(FutureResponseListener.java:118) ~[?:?]

at org.eclipse.jetty.client.util.FutureResponseListener.get(FutureResponseListener.java:101) ~[?:?]

at org.eclipse.jetty.client.HttpRequest.send(HttpRequest.java:685) ~[?:?]

at org.openhab.binding.homematic.internal.communicator.client.XmlRpcClient.sendMessage(XmlRpcClient.java:84) ~[?:?]

... 13 more

Caused by: java.lang.IllegalArgumentException: Buffering capacity 2097152 exceeded

at org.eclipse.jetty.client.util.BufferingResponseListener.onHeaders(BufferingResponseListener.java:83) ~[?:?]

at org.eclipse.jetty.client.ResponseNotifier.notifyHeaders(ResponseNotifier.java:98) ~[?:?]

at org.eclipse.jetty.client.ResponseNotifier.notifyHeaders(ResponseNotifier.java:90) ~[?:?]

at org.eclipse.jetty.client.HttpReceiver.responseHeaders(HttpReceiver.java:269) ~[?:?]

at org.eclipse.jetty.client.http.HttpReceiverOverHTTP.headerComplete(HttpReceiverOverHTTP.java:256) ~[?:?]

at org.eclipse.jetty.http.HttpParser.parseFields(HttpParser.java:1192) ~[?:?]

at org.eclipse.jetty.http.HttpParser.parseNext(HttpParser.java:1475) ~[?:?]

at org.eclipse.jetty.client.http.HttpReceiverOverHTTP.parse(HttpReceiverOverHTTP.java:172) ~[?:?]

at org.eclipse.jetty.client.http.HttpReceiverOverHTTP.process(HttpReceiverOverHTTP.java:135) ~[?:?]

at org.eclipse.jetty.client.http.HttpReceiverOverHTTP.receive(HttpReceiverOverHTTP.java:73) ~[?:?]

at org.eclipse.jetty.client.http.HttpChannelOverHTTP.receive(HttpChannelOverHTTP.java:133) ~[?:?]

at org.eclipse.jetty.client.http.HttpConnectionOverHTTP.onFillable(HttpConnectionOverHTTP.java:154) ~[?:?]

at org.eclipse.jetty.io.AbstractConnection$ReadCallback.succeeded(AbstractConnection.java:311) ~[?:?]

at org.eclipse.jetty.io.FillInterest.fillable(FillInterest.java:103) ~[?:?]

at org.eclipse.jetty.io.ChannelEndPoint$2.run(ChannelEndPoint.java:117) ~[?:?]

at org.eclipse.jetty.util.thread.strategy.EatWhatYouKill.runTask(EatWhatYouKill.java:336) ~[?:?]

at org.eclipse.jetty.util.thread.strategy.EatWhatYouKill.doProduce(EatWhatYouKill.java:313) ~[?:?]

at org.eclipse.jetty.util.thread.strategy.EatWhatYouKill.tryProduce(EatWhatYouKill.java:171) ~[?:?]

at org.eclipse.jetty.util.thread.strategy.EatWhatYouKill.run(EatWhatYouKill.java:129) ~[?:?]

at org.eclipse.jetty.util.thread.ReservedThreadExecutor$ReservedThread.run(ReservedThreadExecutor.java:367) ~[?:?]

at org.eclipse.jetty.util.thread.QueuedThreadPool.runJob(QueuedThreadPool.java:782) ~[?:?]

at org.eclipse.jetty.util.thread.QueuedThreadPool$Runner.run(QueuedThreadPool.java:918) ~[?:?]

... 1 more

Could this be relevant?

Is there anything I’m missing?

MHerbst · January 30, 2020, 6:27pm

In the firewall configuration you also have to add the following ports to “Port-Freigabe”:
2001;
2000;
2010;
8701;
8181;
9292;
43439

In my configuration I have also added my network to “IP-Adressen für den eingeschränkten” Zugriff, e.g.
192.168.2.0/24

This should normally work (at least it works in my installation). If it does not help, I will have a closer look into the log files.

Interaktiv · January 31, 2020, 7:43am

I have added the ports and IP ranges to the firewall configuration and restarted the CCU for good measure. OpenHAB still doesn’t list any devices though.

Summary

I forgot to mention that I tried adding devices by hand via a .things file. The devices show up and OpenHAB marks them as online but only if I restart the CCU. After that the things are online for about 10 minutes, just to go offline again. I have not added any channels so I have not tested whether I can control anything during the ~10 minute period.
I have also not checked the logs during this process.

MHerbst · January 31, 2020, 6:17pm

Firewall looks OK. I would recommend to make first a test with Paper UI configuration. The binding will detect the CCU, it`s type and possible communication protocols.

I am using a mixed configuration. I configure the things in Paper UI and items as text files.

Interaktiv · February 5, 2020, 1:18pm

I tried setting up an instance of OpenHAB on my local machine. To my surprise OpenHAB found two devices, one named “GATEWAY-EXTRAS” and a pluggable switch that wasn’t plugged in at the time but known to the CCU.
I got the switch, plugged it in and was able to control it with OpenHAB (PaperUI).

I then reinstalled OpenHAB (using ‘apt purge openhab2*’ to uninstall) as it still couldn’t find the other ~70 devices.
Now it’s the same as with the Raspi: CCU3 is found instantly after enabling the HomeMatic binding, that’s it. Same installation procedure as last time where OpenHAB found at least something.

I tried adding an item by hand but I am in no way experienced enough to do this without the help of PaperUI or HABmin.

I also still see messages like this in the log:

Summary

2020-02-05 12:58:38.846 [TRACE] [nal.communicator.server.XmlRpcServer] - Server XmlRpcResponse:
<?xml version="1.0" encoding="ISO-8859-1"?>
<methodResponse><params><param><value><array><data><value>event</value></data></array></value></param></params></methodResponse>
2020-02-05 12:58:38.864 [TRACE] [nal.communicator.server.XmlRpcServer] - Server parsed XmlRpcMessage:
system.multicall()
[
	{
		methodName=event
		params=
		[
			HMIP-cca80db3
			001C9A4990BE3B:2
			EMERGENCY_OPERATION
			false
		]
	}
	{
		methodName=event
		params=
		[
			HMIP-cca80db3
			001C9A4990BE3B:2
			FROST_PROTECTION
			false
		]
	}
	{
		methodName=event
		params=
		[
			HMIP-cca80db3
			001C9A4990BE3B:2
			STATE
			true
		]
	}
	{
		methodName=event
		params=
		[
			HMIP-cca80db3
			001C9A4990BE3B:2
			DEW_POINT_ALARM
			false
		]
	}
	{
		methodName=event
		params=
		[
			HMIP-cca80db3
			001C9A4990BE3B:2
			HUMIDITY_LIMITER
			false
		]
	}
	{
		methodName=event
		params=
		[
			HMIP-cca80db3
			001C9A4990BE3B:2
			EXTERNAL_CLOCK
			false
		]
	}
]
2020-02-05 12:58:38.866 [DEBUG] [ommunicator.AbstractHomematicGateway] - Received new (Boolean) value 'false' for '001C9A4990BE3B:2#EMERGENCY_OPERATION' from gateway with id 'cca80db3'
2020-02-05 12:58:38.868 [DEBUG] [ommunicator.AbstractHomematicGateway] - Received new (Boolean) value 'false' for '001C9A4990BE3B:2#FROST_PROTECTION' from gateway with id 'cca80db3'
2020-02-05 12:58:38.870 [DEBUG] [ommunicator.AbstractHomematicGateway] - Received new (Boolean) value 'true' for '001C9A4990BE3B:2#STATE' from gateway with id 'cca80db3'
2020-02-05 12:58:38.872 [DEBUG] [ommunicator.AbstractHomematicGateway] - Received new (Boolean) value 'false' for '001C9A4990BE3B:2#DEW_POINT_ALARM' from gateway with id 'cca80db3'
2020-02-05 12:58:38.873 [DEBUG] [ommunicator.AbstractHomematicGateway] - Received new (Boolean) value 'false' for '001C9A4990BE3B:2#HUMIDITY_LIMITER' from gateway with id 'cca80db3'
2020-02-05 12:58:38.875 [DEBUG] [ommunicator.AbstractHomematicGateway] - Received new (Boolean) value 'false' for '001C9A4990BE3B:2#EXTERNAL_CLOCK' from gateway with id 'cca80db3'
2020-02-05 12:58:38.876 [TRACE] [nal.communicator.server.XmlRpcServer] - Server XmlRpcResponse:
<?xml version="1.0" encoding="ISO-8859-1"?>
<methodResponse><params><param><value><array><data><value>event</value></data></array></value></param></params></methodResponse>
2020-02-05 12:58:40.543 [TRACE] [nal.communicator.client.XmlRpcClient] - Client XmlRpcRequest (port 2001):
<?xml version="1.0" encoding="ISO-8859-1"?>
<methodCall><methodName>ping</methodName>
<params><param><value>cca80db3</value></param></params></methodCall>
2020-02-05 12:58:40.551 [TRACE] [nal.communicator.client.XmlRpcClient] - Client XmlRpcResponse (port 2001):
<?xml version="1.0" encoding="iso-8859-1"?>
<methodResponse><params><param>
	<value><array><data><value><boolean>1</boolean></value></data></array></value>
</param></params></methodResponse>

which makes me think that the communication is happening but OpenHAB just doesn’t work.
I have no more ideas what I can try.

Interaktiv · February 5, 2020, 3:30pm

I also just connected to the CCU3 over SSH and took a look at netstat. I didn’t see any service using ports 9125, 9126 and 8701 which are listed in the bindings’ documentation as being used. Is this normal?

MHerbst · February 5, 2020, 6:47pm

Did you add the CCU (Homematic Bridge) as a thing? The connected devices can only be found after the CCU has been added and is Online. Then some seconds later the devices should appear in the INbox.

Which device is HMIP-cca80db3? It looks like the CCU itself or GATEWAY-EXTRAS.

9125 and 9126 are used by the HomeMatic openHAB binding, i.e. they must be open on your openHAB installation. 8701 is only used if CuxD is used on the CCU. You could try to stop the firewall on your openHAB machine temporarily to make sure that the CCU can reach the binding.
I have checked my firewall configuration and I have opened it for poth ports.

Do you only have HMIP devices or are also non HMIP connected to the CCU? I

Interaktiv · February 6, 2020, 10:12am

I have added the CCU once as a thing via PaperUI and via a .things file. Both didn’t work

It seems that I have misinterpreted the documentation then. I thought 9125/9126 needed to be open on the CCU.

Firewall configuration of my OpenHAB machine

Firewall of my CCU

I don’t see a device with the name HMIP-cca80db3 but the SGTIN in the log leads to this device:

As far as I know we only use HomeMatic IP devices. Mostly wired devices like HmIPW-FIO6, HmIPW-FAL230-C10, HmIPW-WTH, HmIPW-DRBL4, HmIPW-DRS4 and HmIPW-DRS8 but also HMIP-PS and one HM-LC-Sw1-Pl-2 (the latter I was briefly able to control via PaperUI on a local OH instance).
There will be more in the future.

MHerbst · February 6, 2020, 6:50pm

Firewall settings seem to be OK.
I have checked your logs again and saw this message that I overlooked before.

2020-01-30 13:22:47.503 [ERROR] [very.HomematicDeviceDiscoveryService] - java.lang.IllegalArgumentException: Buffering capacity 2097152 exceeded

This would explain your problems. The binding tries to retrieve information about all devices from the CCU to create the thing definitions. If this fails no things would be created. I have a similar error in this issue Jetty Buffer Exception / Homematic Discovery · Issue #6963 · openhab/openhab-addons · GitHub

Interaktiv · February 17, 2020, 1:34pm

Yes, that seems to be my problem as well. I have not found a way to increase the buffer size as that’s not really my field of expertise.
I’ll try setting up a RaspberryMatic with fewer devices and see if that makes a difference.

MHerbst · February 17, 2020, 6:35pm

Generally it should be possible to use a larger buffer. I have found some examples. Will try it within the next days.

This would be good to verify that this is really the cause of the problem.

Interaktiv · February 19, 2020, 8:46am

It turns out you can’t use RaspberryMatic with Homematic Wired without a RPI-RF-MOD (Source in German).
I’ll reset the CCU3 and add only a handful of devices to see if that works.

Interaktiv · March 2, 2020, 7:38am

In the meantime I have set up a second CCU3 with only a few Wireless HomeMatic devices and tried to add it to OpenHAB.
Everything works as expected.

I thought about resetting the first CCU3 and adding all devices one by one to get around the buffer overflow but that doesn’t seem to work.

MHerbst · March 3, 2020, 7:07pm

I hope to have some time this weekend to work on the buffer size problem. I will inform you as soon as I have a jar file ready that you could test.

Interaktiv · March 4, 2020, 7:36am

That would be greatly appreciated!

MHerbst · March 8, 2020, 5:47pm

Hi @Interaktiv

I have modified the binding and you can download a test version from here: https://github.com/MHerbst/openhab-addons-test/raw/master/org.openhab.binding.homematic-2.5.3-SNAPSHOT.jar
I would like to get some feedback before I create a PR because I can’t test it.

Interaktiv · March 9, 2020, 7:43am

Good morning Martin,

I have installed the binding and it works like a charm. All devices show up immediately after adding the CCU3. There are no error messages appearing in the logs.
I can control wired and wireless devices with no noticeable delay. Variables and scripts are also showing up.

You have saved me from having to learn how to use HomeAssistant!

Thanks a lot!

MHerbst · March 9, 2020, 6:25pm

Good to hear :-).

Can you mark this thread as solved?

The coding needs some additional polishing but then I will create a PR.

Martin