search

openhab / openhab-addons

Add-ons for openHAB
https://www.openhab.org/
Eclipse Public License 2.0
1.86k stars 3.57k forks source link

[homematic] New Homematic Bridge always "OFFLINE - COMMUNICATION_ERROR" - "Read timed out" #3507

Closed Vermatic closed 6 years ago

Vermatic commented 6 years ago

I am new to OpenHAB2. I started with a fresh install of a 2.3.0-SNAPSHOT, installed the Homematic Binding and then wanted to add my CCU2.

Expected Behavior

The CCU2 is found correctly.

Current Behavior

The CCU2 is somehow found, but communication ceases at a certain point due reasons unknown to me. Please see the log file below. It seems the communication using XmlRpcRequest works fine, but then the communication using BinRpcResponse times out.

In the end the device is shown as "Status: OFFLINE - COMMUNICATION_ERROR Read timed out" and it cannot be used.

Steps to Reproduce (for Bugs)

  1. Install OpenHAB2 2.3.0-SNAPSHOT
  2. Install Homematic Binding
  3. Add new CCU2 with only specifying the IP address and increasing the timeout to 60s.

Your Environment

I admit that the CCU2 has lots of stuff installed, like XML-API, CUxD, E-Mail Plugin and lot of devices and scripts. I also modified the webserver configuration manually via SSH, I added https support and authentication via HTTPS, but this should not affect openHAB2 I guess.

I tried FEHM as well, which is able to communicate with my CCU2 just fine.

Log file - start of openHAB2

tecra@tecra:~/openhab/openhab$ ./start_debug.sh 
Launching the openHAB runtime...
Listening for transport dt_socket at address: 5005

                          __  _____    ____      
  ____  ____  ___  ____  / / / /   |  / __ )     
 / __ \/ __ \/ _ \/ __ \/ /_/ / /| | / __  | 
/ /_/ / /_/ /  __/ / / / __  / ___ |/ /_/ /      
\____/ .___/\___/_/ /_/_/ /_/_/  |_/_____/     
    /_/                        2.3.0-SNAPSHOT
                               Build #1257   

Hit '<tab>' for a list of available commands
and '[cmd] --help' for help on a specific command.
Hit '<ctrl-d>' or type 'system:shutdown' or 'logout' to shutdown openHAB.

openhab> stop org.openhab.binding.homematic
openhab> log:set TRACE org.openhab.binding.homematic
openhab> start org.openhab.binding.homematic
openhab> org.eclipse.jetty.server.Server@819b323 - STARTED                                                                                                                                                                                                                     
 += qtp939143465{STARTED,8<=8<=200,i=5,q=0} - STARTED
 |   +- 312 qtp939143465-312 TIMED_WAITING @ sun.misc.Unsafe.park(Native Method) IDLE
 |   +- 313 qtp939143465-313 TIMED_WAITING @ sun.misc.Unsafe.park(Native Method) IDLE
 |   +- 315 qtp939143465-315 TIMED_WAITING @ sun.misc.Unsafe.park(Native Method) IDLE
 |   +- 316 qtp939143465-316 TIMED_WAITING @ sun.misc.Unsafe.park(Native Method) IDLE
 |   +- 310 qtp939143465-310 RUNNABLE @ sun.nio.ch.EPollArrayWrapper.epollWait(Native Method)
 |   +- 311 qtp939143465-311-acceptor-0@5d1c5f6a-ServerConnector@53dbaab9{HTTP/1.1,[http/1.1]}{0.0.0.0:9125} RUNNABLE @ sun.nio.ch.ServerSocketChannelImpl.accept0(Native Method) prio=3
 |   +- 309 qtp939143465-309 RUNNABLE @ sun.nio.ch.EPollArrayWrapper.epollWait(Native Method)
 |   +- 314 qtp939143465-314 TIMED_WAITING @ sun.misc.Unsafe.park(Native Method) IDLE
 += ServerConnector@53dbaab9{HTTP/1.1,[http/1.1]}{0.0.0.0:9125} - STARTED
 |   +~ org.eclipse.jetty.server.Server@819b323 - STARTED
 |   +~ qtp939143465{STARTED,8<=8<=200,i=5,q=0} - STARTED
 |   += org.eclipse.jetty.util.thread.ScheduledExecutorScheduler@323236ad - STARTED
 |   +- org.eclipse.jetty.io.ArrayByteBufferPool@7ddb9cc0
 |   += HttpConnectionFactory@47d79415[HTTP/1.1] - STARTED
 |   |   +- HttpConfiguration@1c6d2654{32768/8192,8192/8192,https://:0,[]}
 |   += org.eclipse.jetty.server.ServerConnector$ServerConnectorManager@2b3406d6 - STARTED
 |   |   += org.eclipse.jetty.io.ManagedSelector@14e5457b id=0 keys=0 selected=0 id=0
 |   |   |   +- sun.nio.ch.EPollSelectorImpl@6a04834 keys=0
 |   |   += org.eclipse.jetty.io.ManagedSelector@75aacf21 id=1 keys=0 selected=0 id=1
 |   |       +- sun.nio.ch.EPollSelectorImpl@72b8171e keys=0
 |   +- sun.nio.ch.ServerSocketChannelImpl[/0:0:0:0:0:0:0:0:9125]
 |   +- qtp939143465-311-acceptor-0@5d1c5f6a-ServerConnector@53dbaab9{HTTP/1.1,[http/1.1]}{0.0.0.0:9125}
 += org.openhab.binding.homematic.internal.communicator.server.XmlRpcServer$ResponseHandler@f9ca301 - STARTED
 |
 +> org.eclipse.osgi.internal.loader.EquinoxClassLoader@3242a4c8[org.eclipse.jetty.server:9.3.21.v20170918(id=85)]
     +- java.net.URLClassLoader@3fee9989
         +- file:/home/tecra/openhab/openhab/runtime/system/org/eclipse/platform/org.eclipse.osgi/3.12.50/org.eclipse.osgi-3.12.50.jar
         +- file:/home/tecra/openhab/openhab/userdata/cache/org.eclipse.osgi/1/0/bundleFile
         +- sun.misc.Launcher$AppClassLoader@18b4aac2
             +- file:/home/tecra/openhab/openhab/runtime/lib/boot/org.apache.karaf.diagnostic.boot-4.1.5.jar
             +- file:/home/tecra/openhab/openhab/runtime/lib/boot/org.apache.karaf.jaas.boot-4.1.5.jar
             +- file:/home/tecra/openhab/openhab/runtime/lib/boot/org.apache.karaf.main-4.1.5.jar
             +- file:/home/tecra/openhab/openhab/runtime/lib/boot/org.osgi.core-6.0.0.jar
             +- sun.misc.Launcher$ExtClassLoader@352c0832
                 +- file:/usr/lib/jvm/java-8-openjdk-amd64/jre/lib/ext/icedtea-sound.jar
                 +- file:/usr/lib/jvm/java-8-openjdk-amd64/jre/lib/ext/sunjce_provider.jar
                 +- file:/usr/lib/jvm/java-8-openjdk-amd64/jre/lib/ext/localedata.jar
                 +- file:/usr/lib/jvm/java-8-openjdk-amd64/jre/lib/ext/java-atk-wrapper.jar
                 +- file:/usr/lib/jvm/java-8-openjdk-amd64/jre/lib/ext/nashorn.jar
                 +- file:/usr/lib/jvm/java-8-openjdk-amd64/jre/lib/ext/zipfs.jar
                 +- file:/usr/lib/jvm/java-8-openjdk-amd64/jre/lib/ext/cldrdata.jar
                 +- file:/usr/lib/jvm/java-8-openjdk-amd64/jre/lib/ext/libatk-wrapper.so
                 +- file:/usr/lib/jvm/java-8-openjdk-amd64/jre/lib/ext/dnsns.jar
                 +- file:/usr/lib/jvm/java-8-openjdk-amd64/jre/lib/ext/sunec.jar
                 +- file:/usr/lib/jvm/java-8-openjdk-amd64/jre/lib/ext/sunpkcs11.jar
                 +- file:/usr/lib/jvm/java-8-openjdk-amd64/jre/lib/ext/jaccess.jar
                 +- file:/home/tecra/openhab/openhab/runtime/lib/ext/README

Log file - openHAB log with TRACE enabled

tecra@tecra:~/openhab/openhab/userdata/logs$ tail -f openhab.log 
2018-04-22 20:56:33.708 [INFO ] [.dashboard.internal.DashboardService] - Started Dashboard at http://192.168.187.20:8080
2018-04-22 20:56:33.714 [INFO ] [.dashboard.internal.DashboardService] - Started Dashboard at https://192.168.187.20:8443
2018-04-22 20:56:36.194 [INFO ] [thome.model.lsp.internal.ModelServer] - Started Language Server Protocol (LSP) service on port 5007
2018-04-22 20:57:33.515 [INFO ] [er.internal.HomeBuilderDashboardTile] - Started Home Builder at /homebuilder
2018-04-22 20:57:33.544 [INFO ] [arthome.ui.paper.internal.PaperUIApp] - Started Paper UI at /paperui
2018-04-22 20:57:33.589 [INFO ] [panel.internal.HABPanelDashboardTile] - Started HABPanel at /habpanel
2018-04-22 20:57:33.747 [INFO ] [basic.internal.servlet.WebAppServlet] - Started Basic UI at /basicui/app
2018-04-22 20:58:25.837 [DEBUG] [org.openhab.binding.homematic       ] - BundleEvent INSTALLED - org.openhab.binding.homematic
2018-04-22 20:58:25.876 [DEBUG] [org.openhab.binding.homematic       ] - BundleEvent RESOLVED - org.openhab.binding.homematic
2018-04-22 20:58:25.878 [DEBUG] [org.openhab.binding.homematic       ] - BundleEvent STARTING - org.openhab.binding.homematic
2018-04-22 20:58:25.879 [DEBUG] [org.openhab.binding.homematic       ] - BundleEvent STARTED - org.openhab.binding.homematic
2018-04-22 20:58:25.889 [DEBUG] [org.openhab.binding.homematic       ] - ServiceEvent REGISTERED - {org.eclipse.smarthome.config.discovery.UpnpDiscoveryParticipant}={service.id=319, service.bundleid=202, service.scope=bundle, component.name=org.openhab.binding.homematic.internal.discovery.HomegearDiscoveryParticipant, component.id=188} - org.openhab.binding.homematic
2018-04-22 20:58:25.892 [DEBUG] [org.openhab.binding.homematic       ] - ServiceEvent REGISTERED - {org.openhab.binding.homematic.internal.type.HomematicThingTypeProvider, org.eclipse.smarthome.core.thing.binding.ThingTypeProvider}={service.id=320, service.bundleid=202, service.scope=bundle, component.name=org.openhab.binding.homematic.internal.type.HomematicThingTypeProviderImpl, component.id=189} - org.openhab.binding.homematic
2018-04-22 20:58:25.898 [DEBUG] [org.openhab.binding.homematic       ] - ServiceEvent REGISTERED - {org.openhab.binding.homematic.internal.type.HomematicChannelTypeProvider, org.eclipse.smarthome.core.thing.type.ChannelTypeProvider}={service.id=321, service.bundleid=202, service.scope=bundle, component.name=org.openhab.binding.homematic.internal.type.HomematicChannelTypeProviderImpl, component.id=190} - org.openhab.binding.homematic
2018-04-22 20:58:25.904 [DEBUG] [ternal.discovery.CcuDiscoveryService] - Starting Homematic CCU discovery scan
2018-04-22 20:58:25.904 [DEBUG] [org.openhab.binding.homematic       ] - ServiceEvent REGISTERED - {org.eclipse.smarthome.config.discovery.DiscoveryService}={service.id=322, service.bundleid=202, service.scope=bundle, component.name=org.openhab.binding.homematic.internal.discovery.CcuDiscoveryService, component.id=193} - org.openhab.binding.homematic
2018-04-22 20:58:25.907 [DEBUG] [org.openhab.binding.homematic       ] - ServiceEvent REGISTERED - {org.openhab.binding.homematic.internal.type.HomematicConfigDescriptionProvider, org.eclipse.smarthome.config.core.ConfigDescriptionProvider}={service.id=323, service.bundleid=202, service.scope=bundle, component.name=org.openhab.binding.homematic.internal.type.HomematicConfigDescriptionProviderImpl, component.id=194} - org.openhab.binding.homematic
2018-04-22 20:58:25.924 [DEBUG] [org.openhab.binding.homematic       ] - ServiceEvent REGISTERED - {org.openhab.binding.homematic.internal.type.HomematicTypeGenerator}={service.id=324, service.bundleid=202, service.scope=bundle, component.name=org.openhab.binding.homematic.internal.type.HomematicTypeGeneratorImpl, component.id=192} - org.openhab.binding.homematic
2018-04-22 20:58:25.928 [INFO ] [ttp.internal.SecureHttpClientFactory] - creating httpClient for endpoint null
2018-04-22 20:58:25.944 [INFO ] [ttp.internal.SecureHttpClientFactory] - jetty shared http client created
2018-04-22 20:58:25.949 [DEBUG] [org.openhab.binding.homematic       ] - ServiceEvent REGISTERED - {org.eclipse.smarthome.core.thing.binding.ThingHandlerFactory}={service.id=325, service.bundleid=202, service.scope=bundle, component.name=org.openhab.binding.homematic.handler.HomematicThingHandlerFactory, component.id=191} - org.openhab.binding.homematic
2018-04-22 20:58:38.794 [DEBUG] [org.openhab.binding.homematic       ] - BundleEvent STOPPING - org.openhab.binding.homematic
2018-04-22 20:58:38.808 [DEBUG] [org.openhab.binding.homematic       ] - ServiceEvent UNREGISTERING - {org.eclipse.smarthome.config.discovery.UpnpDiscoveryParticipant}={service.id=319, service.bundleid=202, service.scope=bundle, component.name=org.openhab.binding.homematic.internal.discovery.HomegearDiscoveryParticipant, component.id=188} - org.openhab.binding.homematic
2018-04-22 20:58:38.812 [DEBUG] [org.openhab.binding.homematic       ] - ServiceEvent UNREGISTERING - {org.openhab.binding.homematic.internal.type.HomematicThingTypeProvider, org.eclipse.smarthome.core.thing.binding.ThingTypeProvider}={service.id=320, service.bundleid=202, service.scope=bundle, component.name=org.openhab.binding.homematic.internal.type.HomematicThingTypeProviderImpl, component.id=189} - org.openhab.binding.homematic
2018-04-22 20:58:38.815 [DEBUG] [org.openhab.binding.homematic       ] - ServiceEvent UNREGISTERING - {org.openhab.binding.homematic.internal.type.HomematicTypeGenerator}={service.id=324, service.bundleid=202, service.scope=bundle, component.name=org.openhab.binding.homematic.internal.type.HomematicTypeGeneratorImpl, component.id=192} - org.openhab.binding.homematic
2018-04-22 20:58:38.823 [DEBUG] [org.openhab.binding.homematic       ] - ServiceEvent UNREGISTERING - {org.eclipse.smarthome.core.thing.binding.ThingHandlerFactory}={service.id=325, service.bundleid=202, service.scope=bundle, component.name=org.openhab.binding.homematic.handler.HomematicThingHandlerFactory, component.id=191} - org.openhab.binding.homematic
2018-04-22 20:58:38.841 [DEBUG] [org.openhab.binding.homematic       ] - ServiceEvent UNREGISTERING - {org.openhab.binding.homematic.internal.type.HomematicChannelTypeProvider, org.eclipse.smarthome.core.thing.type.ChannelTypeProvider}={service.id=321, service.bundleid=202, service.scope=bundle, component.name=org.openhab.binding.homematic.internal.type.HomematicChannelTypeProviderImpl, component.id=190} - org.openhab.binding.homematic
2018-04-22 20:58:38.847 [DEBUG] [org.openhab.binding.homematic       ] - ServiceEvent UNREGISTERING - {org.eclipse.smarthome.config.discovery.DiscoveryService}={service.id=322, service.bundleid=202, service.scope=bundle, component.name=org.openhab.binding.homematic.internal.discovery.CcuDiscoveryService, component.id=193} - org.openhab.binding.homematic
2018-04-22 20:58:38.851 [DEBUG] [org.openhab.binding.homematic       ] - ServiceEvent UNREGISTERING - {org.openhab.binding.homematic.internal.type.HomematicConfigDescriptionProvider, org.eclipse.smarthome.config.core.ConfigDescriptionProvider}={service.id=323, service.bundleid=202, service.scope=bundle, component.name=org.openhab.binding.homematic.internal.type.HomematicConfigDescriptionProviderImpl, component.id=194} - org.openhab.binding.homematic
2018-04-22 20:58:38.856 [DEBUG] [org.openhab.binding.homematic       ] - BundleEvent STOPPED - org.openhab.binding.homematic
2018-04-22 20:58:42.512 [DEBUG] [org.openhab.binding.homematic       ] - BundleEvent STARTING - org.openhab.binding.homematic
2018-04-22 20:58:42.514 [DEBUG] [org.openhab.binding.homematic       ] - BundleEvent STARTED - org.openhab.binding.homematic
2018-04-22 20:58:42.523 [DEBUG] [org.openhab.binding.homematic       ] - ServiceEvent REGISTERED - {org.eclipse.smarthome.config.discovery.UpnpDiscoveryParticipant}={service.id=328, service.bundleid=202, service.scope=bundle, component.name=org.openhab.binding.homematic.internal.discovery.HomegearDiscoveryParticipant, component.id=197} - org.openhab.binding.homematic
2018-04-22 20:58:42.525 [DEBUG] [org.openhab.binding.homematic       ] - ServiceEvent REGISTERED - {org.openhab.binding.homematic.internal.type.HomematicThingTypeProvider, org.eclipse.smarthome.core.thing.binding.ThingTypeProvider}={service.id=329, service.bundleid=202, service.scope=bundle, component.name=org.openhab.binding.homematic.internal.type.HomematicThingTypeProviderImpl, component.id=198} - org.openhab.binding.homematic
2018-04-22 20:58:42.528 [DEBUG] [org.openhab.binding.homematic       ] - ServiceEvent REGISTERED - {org.openhab.binding.homematic.internal.type.HomematicChannelTypeProvider, org.eclipse.smarthome.core.thing.type.ChannelTypeProvider}={service.id=330, service.bundleid=202, service.scope=bundle, component.name=org.openhab.binding.homematic.internal.type.HomematicChannelTypeProviderImpl, component.id=199} - org.openhab.binding.homematic
2018-04-22 20:58:42.533 [DEBUG] [ternal.discovery.CcuDiscoveryService] - Starting Homematic CCU discovery scan
2018-04-22 20:58:42.535 [DEBUG] [org.openhab.binding.homematic       ] - ServiceEvent REGISTERED - {org.eclipse.smarthome.config.discovery.DiscoveryService}={service.id=331, service.bundleid=202, service.scope=bundle, component.name=org.openhab.binding.homematic.internal.discovery.CcuDiscoveryService, component.id=202} - org.openhab.binding.homematic
2018-04-22 20:58:42.552 [DEBUG] [org.openhab.binding.homematic       ] - ServiceEvent REGISTERED - {org.openhab.binding.homematic.internal.type.HomematicConfigDescriptionProvider, org.eclipse.smarthome.config.core.ConfigDescriptionProvider}={service.id=332, service.bundleid=202, service.scope=bundle, component.name=org.openhab.binding.homematic.internal.type.HomematicConfigDescriptionProviderImpl, component.id=203} - org.openhab.binding.homematic
2018-04-22 20:58:42.572 [DEBUG] [org.openhab.binding.homematic       ] - ServiceEvent REGISTERED - {org.openhab.binding.homematic.internal.type.HomematicTypeGenerator}={service.id=333, service.bundleid=202, service.scope=bundle, component.name=org.openhab.binding.homematic.internal.type.HomematicTypeGeneratorImpl, component.id=201} - org.openhab.binding.homematic
2018-04-22 20:58:42.575 [DEBUG] [org.openhab.binding.homematic       ] - ServiceEvent REGISTERED - {org.eclipse.smarthome.core.thing.binding.ThingHandlerFactory}={service.id=334, service.bundleid=202, service.scope=bundle, component.name=org.openhab.binding.homematic.handler.HomematicThingHandlerFactory, component.id=200} - org.openhab.binding.homematic
2018-04-22 20:58:46.581 [DEBUG] [ternal.discovery.CcuDiscoveryService] - Starting Homematic CCU discovery scan
2018-04-22 20:59:00.388 [DEBUG] [matic.handler.HomematicBridgeHandler] - HomematicConfig[gatewayAddress=192.168.188.26,callbackHost=192.168.187.20,xmlCallbackPort=9125,binCallbackPort=9126,gatewayType=auto,rfPort=2001,wiredPort=2000,hmIpPort=2010,cuxdPort=8701,groupPort=9292,timeout=60,installModeDuration=60,socketMaxAlive=900]
2018-04-22 20:59:00.389 [TRACE] [matic.handler.HomematicBridgeHandler] - Registering HomematicDeviceDiscoveryService for bridge '9a3a6a07'
2018-04-22 20:59:00.391 [DEBUG] [org.openhab.binding.homematic       ] - ServiceEvent REGISTERED - {org.eclipse.smarthome.config.discovery.DiscoveryService}={service.id=335, service.bundleid=202, service.scope=singleton} - org.openhab.binding.homematic
2018-04-22 20:59:00.430 [TRACE] [nal.communicator.client.XmlRpcClient] - Client XmlRpcRequest (port 2001):
<?xml version="1.0" encoding="ISO-8859-1"?>
<methodCall><methodName>getDeviceDescription</methodName>
<params><param><value>BidCoS-RF</value></param></params></methodCall>
2018-04-22 20:59:00.662 [TRACE] [nal.communicator.client.XmlRpcClient] - Client XmlRpcResponse (port 2001):
<?xml version="1.0"?>
<methodResponse><params><param>
[...]
</param></params></methodResponse>

2018-04-22 20:59:00.668 [TRACE] [nal.communicator.client.XmlRpcClient] - Client XmlRpcRequest (port 2001):
<?xml version="1.0" encoding="ISO-8859-1"?>
<methodCall><methodName>listBidcosInterfaces</methodName>
<params></params></methodCall>
2018-04-22 20:59:00.676 [TRACE] [nal.communicator.client.XmlRpcClient] - Client XmlRpcResponse (port 2001):
<?xml version="1.0"?>
<methodResponse>
[...]
</methodResponse>
2018-04-22 20:59:00.679 [TRACE] [nal.communicator.client.XmlRpcClient] - Client XmlRpcRequest (port 2000):
<?xml version="1.0" encoding="ISO-8859-1"?>
<methodCall><methodName>init</methodName>
<params><param><value>http://openhab.validation:1000</value></param></params></methodCall>
2018-04-22 20:59:00.682 [INFO ] [ternal.communicator.client.RpcClient] - Interface 'WIRED' on gateway '9a3a6a07' not available, disabling support
2018-04-22 20:59:00.683 [TRACE] [nal.communicator.client.XmlRpcClient] - Client XmlRpcRequest (port 2010):
<?xml version="1.0" encoding="ISO-8859-1"?>
<methodCall><methodName>init</methodName>
<params><param><value>http://openhab.validation:1000</value></param></params></methodCall>
2018-04-22 20:59:00.737 [TRACE] [nal.communicator.client.XmlRpcClient] - Client XmlRpcResponse (port 2010):
<?xml version="1.0" encoding="ISO-8859-1"?><methodResponse><params><param><value></value></param></params></methodResponse>
2018-04-22 20:59:00.739 [TRACE] [nal.communicator.client.XmlRpcClient] - Client XmlRpcRequest (port 8701):
<?xml version="1.0" encoding="ISO-8859-1"?>
<methodCall><methodName>init</methodName>
<params><param><value>http://openhab.validation:1000</value></param></params></methodCall>
2018-04-22 20:59:00.745 [TRACE] [nal.communicator.client.XmlRpcClient] - Client XmlRpcResponse (port 8701):
<?xml version="1.0" ?><methodResponse><params><param><value></value></param></params></methodResponse>
2018-04-22 20:59:00.747 [TRACE] [nal.communicator.client.XmlRpcClient] - Client XmlRpcRequest (port 9292):
<?xml version="1.0" encoding="ISO-8859-1"?>
<methodCall><methodName>init</methodName>
<params><param><value>http://openhab.validation:1000</value></param></params></methodCall>
2018-04-22 20:59:00.815 [TRACE] [nal.communicator.client.XmlRpcClient] - Client XmlRpcResponse (port 9292):
<?xml version="1.0" encoding="ISO-8859-1"?><methodResponse><params><param><value></value></param></params></methodResponse>
2018-04-22 20:59:00.832 [DEBUG] [ommunicator.AbstractHomematicGateway] - Initializing gateway with id '9a3a6a07'
2018-04-22 20:59:00.833 [INFO ] [ommunicator.AbstractHomematicGateway] - HmGatewayInfo[id=CCU,type=CCU2,firmware=2.31.25,address=KEQ0643527,wired=false,hmip=true,cuxd=true,group=true]
2018-04-22 20:59:00.834 [DEBUG] [ommunicator.AbstractHomematicGateway] - Used Homematic transfer modes: RF:BIN_RPC, HMIP:XML_RPC, CUXD:BIN_RPC, GROUP:XML_RPC
2018-04-22 20:59:00.850 [DEBUG] [nal.communicator.server.BinRpcServer] - Initializing BIN-RPC server at port 9126
2018-04-22 20:59:00.856 [DEBUG] [nal.communicator.server.XmlRpcServer] - Initializing XML-RPC server at port 9125
2018-04-22 20:59:00.874 [TRACE] [nal.communicator.client.BinRpcClient] - Client BinRpcRequest:
init()
binary://192.168.187.20:9126
RF-9a3a6a07

2018-04-22 20:59:00.874 [TRACE] [al.communicator.client.SocketHandler] - Creating new socket for port 2001
2018-04-22 21:00:00.929 [TRACE] [nal.communicator.client.BinRpcClient] - Client BinRpcResponse:
null
2018-04-22 21:00:00.931 [ERROR] [matic.handler.HomematicBridgeHandler] - Homematic bridge was set to OFFLINE-COMMUNICATION_ERROR due to the following exception: Read timed out
java.net.SocketTimeoutException: Read timed out
    at java.net.SocketInputStream.socketRead0(Native Method) ~[?:?]
    at java.net.SocketInputStream.socketRead(SocketInputStream.java:116) ~[?:?]
    at java.net.SocketInputStream.read(SocketInputStream.java:171) ~[?:?]
    at java.net.SocketInputStream.read(SocketInputStream.java:141) ~[?:?]
    at org.openhab.binding.homematic.internal.communicator.message.BinRpcMessage.<init>(BinRpcMessage.java:74) ~[?:?]
    at org.openhab.binding.homematic.internal.communicator.client.BinRpcClient.sendMessage(BinRpcClient.java:77) ~[?:?]
    at org.openhab.binding.homematic.internal.communicator.client.BinRpcClient.sendMessage(BinRpcClient.java:66) ~[?:?]
    at org.openhab.binding.homematic.internal.communicator.client.RpcClient.init(RpcClient.java:87) ~[?:?]
    at org.openhab.binding.homematic.internal.communicator.client.BinRpcClient.init(BinRpcClient.java:54) ~[?:?]
    at org.openhab.binding.homematic.internal.communicator.AbstractHomematicGateway.startServers(AbstractHomematicGateway.java:249) ~[?:?]
    at org.openhab.binding.homematic.internal.communicator.AbstractHomematicGateway.initialize(AbstractHomematicGateway.java:183) ~[?:?]
    at org.openhab.binding.homematic.handler.HomematicBridgeHandler.lambda$0(HomematicBridgeHandler.java:86) ~[?:?]
    at java.util.concurrent.Executors$RunnableAdapter.call(Executors.java:511) [?:?]
    at java.util.concurrent.FutureTask.run(FutureTask.java:266) [?:?]
    at java.util.concurrent.ScheduledThreadPoolExecutor$ScheduledFutureTask.access$201(ScheduledThreadPoolExecutor.java:180) [?:?]
    at java.util.concurrent.ScheduledThreadPoolExecutor$ScheduledFutureTask.run(ScheduledThreadPoolExecutor.java:293) [?:?]
    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) [?:?]
2018-04-22 21:00:00.955 [DEBUG] [matic.handler.HomematicBridgeHandler] - Disposing bridge '9a3a6a07'
2018-04-22 21:00:00.956 [DEBUG] [very.HomematicDeviceDiscoveryService] - Stopping Homematic discovery scan
2018-04-22 21:00:00.956 [DEBUG] [very.HomematicDeviceDiscoveryService] - Waiting for finishing Homematic device discovery scan
2018-04-22 21:00:00.957 [DEBUG] [very.HomematicDeviceDiscoveryService] - Finished Homematic device discovery scan on gateway '9a3a6a07'
2018-04-22 21:00:00.957 [DEBUG] [org.openhab.binding.homematic       ] - ServiceEvent UNREGISTERING - {org.eclipse.smarthome.config.discovery.DiscoveryService}={service.id=335, service.bundleid=202, service.scope=singleton} - org.openhab.binding.homematic
2018-04-22 21:00:00.959 [TRACE] [nal.communicator.client.BinRpcClient] - Client BinRpcRequest:
init()
binary://192.168.187.20:9126

2018-04-22 21:00:00.959 [TRACE] [al.communicator.client.SocketHandler] - Returning socket for port 2001
MHerbst commented 6 years ago

It seems that the binding can connect to the CCU and receive at least information about the type and the firmware version. But then it seems to fail in retrieving the device infos.

At first I would recommend to check the "basics":

There may also be a problem with the build you have installed. There has been a fix in the Homematic binding I think in a later build. Maybe it helps to install a more current build.

gerrieg commented 6 years ago

@Vermatic Is this issue still valid with OH2.3 release?

mdicke2s commented 6 years ago

This issue was moved to eclipse/smarthome#5796

Vermatic commented 5 years ago

In the meantime I tried this again with OpenHAB 2.4 and initially I had the same problem getting it to run, even after the CCU2 was completely reset to factory defaults. Then I physically moved the CCU2 to a different location and then it magically worked. It turned out that there was a network topology problem in the original setup and that the CCU2 could not talk back to the device running OH2.4. I just wanted to confirm that there was never a problem with OH2.3/2.4, but it was a pure network issue.