Losing connection to Homematic gateway (Thing)

Hi all,

I had a running setup for several month (nearly 1,5 years) now but since some weeks I have an issue. (Unfortunately, I had no time to come here before)

I recognized that my graphs (e.g. temperature of last 24h) on Habpanel as well as the numerical display did not update anymore. The values just stayed constant (horizontal line in graphs).

While checking I figured out, that all things were offline (all things connected to my homematic bridge) in fact what was offline was the bridge itself. Offline from openhap point off view. Direct access to homematic still works fine. Also - and that was strange - all commands given via Amazon Alexa or in Habpanel were executed without issues.

I rebooted the Raspberry and for a certain time everything was ok but that it fell back in this strange behavior (things displayed as offline, measurements not updated but commands working). Rebooting again helped for some minutes again. Watching this several days revealed that the time on which everything was normal after reboot, got shorter and shorter. Now I lose the connection almost immediately.

I updated the system in the last days in the hope that it will help. But no success. Now since an update yesterday, also commands do not work anymore.

Remark: everything via Hue bridge is working fine!

My system: Openhabian with Openhab 2.3.0-1 (Release Build) on Raspberry Pi 3 Model B Rev 1.2

Homematic firmware: 2.35.16

Attached an extract from openhab.log:

2018-10-26 21:30:47.177 [INFO ] [basic.internal.servlet.WebAppServlet] - Stopped Basic UI
2018-10-26 21:31:07.873 [WARN ] [ome.core.thing.internal.ThingManager] - Disposing handler for thing 'homematic:bridge:homematic' takes more than 5000ms.
2018-10-26 21:31:09.220 [ERROR] [me.storage.json.internal.JsonStorage] - Error writing JsonDB to /var/lib/openhab2/jsondb/org.eclipse.smarthome.core.items.Item.json. Cause /var/lib/openhab2/jsondb/org.eclipse.smarthome.core.items.Item.json (Permission denied).
2018-10-26 21:31:09.392 [INFO ] [arthome.ui.paper.internal.PaperUIApp] - Stopped Paper UI
2018-10-26 21:31:09.427 [INFO ] [ttp.internal.SecureHttpClientFactory] - jetty shared http client stopped
2018-10-26 21:31:09.449 [INFO ] [panel.internal.HABPanelDashboardTile] - Stopped HABPanel
2018-10-26 21:31:09.483 [INFO ] [.dashboard.internal.DashboardService] - Stopped Dashboard
2018-10-26 21:31:48.004 [WARN ] [g.eclipse.smarthome.core.net.NetUtil] - Found multiple local interfaces - ignoring 192.168.178.55
2018-10-26 21:31:57.286 [INFO ] [el.core.internal.ModelRepositoryImpl] - Loading model 'denon.items'
2018-10-26 21:31:57.403 [INFO ] [el.core.internal.ModelRepositoryImpl] - Loading model 'alexa.items'
2018-10-26 21:31:57.482 [INFO ] [el.core.internal.ModelRepositoryImpl] - Loading model 'groups.items'
2018-10-26 21:31:57.544 [INFO ] [el.core.internal.ModelRepositoryImpl] - Loading model 'virtuell.items'
2018-10-26 21:31:57.588 [INFO ] [el.core.internal.ModelRepositoryImpl] - Loading model 'yahooweather.items'
2018-10-26 21:31:58.326 [INFO ] [el.core.internal.ModelRepositoryImpl] - Loading model 'mysql.persist'
2018-10-26 21:32:04.377 [INFO ] [el.core.internal.ModelRepositoryImpl] - Loading model 'autolight.rules'
2018-10-26 21:32:05.450 [INFO ] [thome.model.lsp.internal.ModelServer] - Started Language Server Protocol (LSP) service on port 5007
2018-10-26 21:32:06.223 [INFO ] [el.core.internal.ModelRepositoryImpl] - Loading model 'YahooWeather.things'
2018-10-26 21:32:08.888 [WARN ] [g.eclipse.smarthome.core.net.NetUtil] - Found multiple local interfaces - ignoring 192.168.178.55
2018-10-26 21:32:08.993 [INFO ] [.dashboard.internal.DashboardService] - Started Dashboard at http://192.168.178.58:8080
2018-10-26 21:32:08.996 [INFO ] [.dashboard.internal.DashboardService] - Started Dashboard at https://192.168.178.58:8443
2018-10-26 21:32:11.033 [INFO ] [basic.internal.servlet.WebAppServlet] - Started Basic UI at /basicui/app
2018-10-26 21:32:11.312 [INFO ] [arthome.ui.paper.internal.PaperUIApp] - Started Paper UI at /paperui
2018-10-26 21:32:11.577 [INFO ] [g.discovery.internal.PersistentInbox] - Added new thing 'homematic:bridge:MEQ0771853' to inbox.
2018-10-26 21:32:11.632 [INFO ] [ttp.internal.SecureHttpClientFactory] - creating httpClient for endpoint null
2018-10-26 21:32:11.661 [INFO ] [ttp.internal.SecureHttpClientFactory] - jetty shared http client created
2018-10-26 21:32:12.150 [INFO ] [ulation.internal.HueEmulationServlet] - Started Hue Emulation service at /api
2018-10-26 21:32:12.457 [INFO ] [ternal.communicator.client.RpcClient] - Interface 'WIRED' on gateway 'homematic' not available, disabling support
2018-10-26 21:32:13.341 [INFO ] [b.core.service.AbstractActiveService] - Denon Refresh Service has been started
2018-10-26 21:32:14.081 [INFO ] [panel.internal.HABPanelDashboardTile] - Started HABPanel at /habpanel
2018-10-26 21:32:27.472 [INFO ] [ternal.communicator.client.RpcClient] - Interface 'HMIP' on gateway 'homematic' not available, disabling support
2018-10-26 21:32:27.482 [INFO ] [ternal.communicator.client.RpcClient] - Interface 'CUXD' on gateway 'homematic' not available, disabling support
2018-10-26 21:32:27.771 [INFO ] [ommunicator.AbstractHomematicGateway] - HmGatewayInfo[id=CCU,type=CCU2,firmware=2.35.16,address=MEQ0771853,wired=false,hmip=false,cuxd=false,group=true]
2018-10-26 21:33:13.675 [ERROR] [very.HomematicDeviceDiscoveryService] - null
java.io.IOException: null
	at org.openhab.binding.homematic.internal.communicator.client.XmlRpcClient.sendMessage(XmlRpcClient.java:94) ~[?:?]
	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:63) ~[?:?]
	at org.openhab.binding.homematic.internal.communicator.client.RpcClient.listDevices(RpcClient.java:163) ~[?:?]
	at org.openhab.binding.homematic.internal.communicator.AbstractHomematicGateway.getDeviceDescriptions(AbstractHomematicGateway.java:439) ~[?:?]
	at org.openhab.binding.homematic.internal.communicator.AbstractHomematicGateway.loadAllDeviceMetadata(AbstractHomematicGateway.java:363) ~[?:?]
	at org.openhab.binding.homematic.internal.discovery.HomematicDeviceDiscoveryService.lambda$0(HomematicDeviceDiscoveryService.java:186) ~[?:?]
	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) [?:?]
Caused by: java.util.concurrent.TimeoutException
	at org.eclipse.jetty.client.util.FutureResponseListener.get(FutureResponseListener.java:109) ~[?:?]
	at org.eclipse.jetty.client.HttpRequest.send(HttpRequest.java:676) ~[?:?]
	at org.openhab.binding.homematic.internal.communicator.client.XmlRpcClient.sendMessage(XmlRpcClient.java:80) ~[?:?]
	... 13 more
2018-10-26 21:33:59.037 [WARN ] [ommunicator.AbstractHomematicGateway] - Connection lost on gateway 'homematic'
2018-10-27 11:28:38.099 [WARN ] [ematic.handler.HomematicThingHandler] - Device with address 'NEQ0129651' not found on gateway 'homematic'
2018-10-27 20:04:03.723 [WARN ] [ematic.handler.HomematicThingHandler] - Device with address 'MEQ1561731' not found on gateway 'homematic'
2018-10-27 20:04:03.789 [WARN ] [ematic.handler.HomematicThingHandler] - Device with address 'MEQ1436574' not found on gateway 'homematic'
2018-10-27 20:04:09.611 [WARN ] [ematic.handler.HomematicThingHandler] - Device with address 'MEQ1436574' not found on gateway 'homematic'
2018-10-27 20:04:09.670 [WARN ] [ematic.handler.HomematicThingHandler] - Device with address 'MEQ1561731' not found on gateway 'homematic'
2018-10-27 20:11:18.571 [WARN ] [ematic.handler.HomematicThingHandler] - Device with address 'MEQ1436574' not found on gateway 'homematic'
2018-10-27 20:11:18.570 [WARN ] [ematic.handler.HomematicThingHandler] - Device with address 'MEQ1561731' not found on gateway 'homematic'

Thank you for any ideas.

Greetings

Sven

Hi again,

no one any idea?

What else logs can be taken to check what is going on? I have deleted all homematic items and things including bridge and re configured everything on 28th October but since yesterday late I have the same behavior.

At the beginning from time to time I had a loss of connection

2018-10-31 21:31:57.360 [WARN ] [ommunicator.AbstractHomematicGateway] - Connection lost on gateway 'MEQ0771853'
2018-10-31 21:32:33.571 [INFO ] [ommunicator.AbstractHomematicGateway] - Connection resumed on gateway 'MEQ0771853'
2018-10-31 21:38:01.121 [WARN ] [ommunicator.AbstractHomematicGateway] - Connection lost on gateway 'MEQ0771853'
2018-10-31 21:38:36.002 [INFO ] [ommunicator.AbstractHomematicGateway] - Connection resumed on gateway 'MEQ0771853'

Then frequency increased until no connections at all anymore:

2018-11-02 22:49:13.360 [WARN ] [ommunicator.AbstractHomematicGateway] - Connection lost on gateway 'MEQ0771853'
2018-11-02 22:49:47.973 [INFO ] [ommunicator.AbstractHomematicGateway] - Connection resumed on gateway 'MEQ0771853'
2018-11-02 22:51:03.201 [WARN ] [ommunicator.AbstractHomematicGateway] - Connection lost on gateway 'MEQ0771853'
2018-11-02 22:51:35.938 [INFO ] [ommunicator.AbstractHomematicGateway] - Connection resumed on gateway 'MEQ0771853'
2018-11-02 22:57:05.447 [WARN ] [ommunicator.AbstractHomematicGateway] - Connection lost on gateway 'MEQ0771853'
2018-11-02 22:57:44.184 [INFO ] [ommunicator.AbstractHomematicGateway] - Connection resumed on gateway 'MEQ0771853'
2018-11-02 22:59:00.141 [WARN ] [ommunicator.AbstractHomematicGateway] - Connection lost on gateway 'MEQ0771853'
2018-11-02 23:00:25.017 [INFO ] [ommunicator.AbstractHomematicGateway] - Connection resumed on gateway 'MEQ0771853'
2018-11-02 23:01:32.355 [WARN ] [ommunicator.AbstractHomematicGateway] - Connection lost on gateway 'MEQ0771853'
2018-11-02 23:02:56.190 [INFO ] [ommunicator.AbstractHomematicGateway] - Connection resumed on gateway 'MEQ0771853'
2018-11-02 23:04:53.591 [WARN ] [ommunicator.AbstractHomematicGateway] - Connection lost on gateway 'MEQ0771853'

I would really appreciate ideas what is going on.

Greetings

Sven

did you see this? you should address this first