Open Xento opened 6 years ago
htreu
commented
6 years ago Hi @Xento, what kind of CCU are you running? And what is the error/log when the problems start to occur?
After you restarted the CCU there a re also some Connection refused exceptions in the log, this also might be a network problem.
Xento
commented
6 years ago I'm running RaspberryMatic on a RPi3. The first part from the Log is where openhab is connected and I restart the CCU. The secondpart is from where the CCU is up again and openhab connects. As you can see it disconnects and connects again and after a few updates it disconnects again. In this state no programs are processed on the ccu and you can't use some functions on the ccu webui as they seem to timeout. When I do a bundle:restart nothing changes. Only when I do a bundle:stop and a bundle:start everything gets back to normal. I think the connection refused is a part of the problem. It seems that the ccu is overloaded somehow.
htreu
commented
6 years ago How is the CCU reacting without the openHAB connection? Can you mimic the openHAB binding behaviour manually through the web ui? Does it overload, too? Maybe the problem is entirely on the CCU side.
Xento
commented
6 years ago No the problem only happens when openhab is trying to connect. When I disable the binding and than restart the ccu everything is ok.
Xento
commented
6 years ago At the moment I get this errors. It seems that there is an ipv6 listener left open on the port. Stopping the binding doesn't help, the messages even then continue.
root@openhab2:/openhab# netstat -tulpen | grep 9126
tcp6 0 0 :::9126 :::* LISTEN 0 541411325 96/java11:06:44.664 [DEBUG] [ematic.handler.HomematicBridgeHandler] - Disposing bridge 'd33daba2'
11:06:45.335 [INFO ] [smarthome.event.ItemStateChangedEvent] - CO2_PPM2 changed from 452.00 to 451.00
11:06:45.341 [INFO ] [home.event.GroupItemStateChangedEvent] - CO2 changed from 1724629387.50 to 1724629387.00 through CO2_PPM2
11:06:54.695 [DEBUG] [ematic.handler.HomematicBridgeHandler] - HomematicConfig[gatewayAddress=192.168.158.102,callbackHost=192.168.158.43,xmlCallbackPort=9123,binCallbackPort=9126,gatewayType=ccu,rfPort=2001,wiredPort=2000,hmIpPort=2010,cuxdPort=8701,groupPort=9292,timeout=120,discoveryTimeToLive=-1,installModeDuration=60,socketMaxAlive=9000]
11:06:54.715 [INFO ] [nternal.communicator.client.RpcClient] - Interface 'WIRED' on gateway 'd33daba2' not available, disabling support
11:06:54.747 [DEBUG] [communicator.AbstractHomematicGateway] - Initializing gateway with id 'd33daba2'
11:06:54.752 [INFO ] [communicator.AbstractHomematicGateway] - HmGatewayInfo[id=CCU,type=CCU2,firmware=2.31.25.20180625,address=NEQ1327860,wired=false,hmip=true,cuxd=true,group=true]
11:06:54.760 [DEBUG] [communicator.AbstractHomematicGateway] - Used Homematic transfer modes: RF:BIN_RPC, HMIP:XML_RPC, CUXD:BIN_RPC, GROUP:XML_RPC
11:06:54.769 [DEBUG] [rnal.communicator.server.BinRpcServer] - Initializing BIN-RPC server at port 9126
11:06:54.774 [WARN ] [e.core.thing.binding.BaseThingHandler] - Handler HomematicBridgeHandler tried updating the thing status although the handler was already disposed.
11:06:54.781 [ERROR] [ematic.handler.HomematicBridgeHandler] - Homematic bridge was set to OFFLINE-COMMUNICATION_ERROR due to the following exception: Address already in use (Bind failed)
java.net.BindException: Address already in use (Bind failed)
at java.net.PlainSocketImpl.socketBind(Native Method) ~[?:?]
at java.net.AbstractPlainSocketImpl.bind(AbstractPlainSocketImpl.java:387) ~[?:?]
at java.net.ServerSocket.bind(ServerSocket.java:375) ~[?:?]
at java.net.ServerSocket.bind(ServerSocket.java:329) ~[?:?]
at org.openhab.binding.homematic.internal.communicator.server.BinRpcNetworkService.<init>(BinRpcNetworkService.java:46) ~[?:?]
at org.openhab.binding.homematic.internal.communicator.server.BinRpcServer.start(BinRpcServer.java:39) ~[?:?]
at org.openhab.binding.homematic.internal.communicator.AbstractHomematicGateway.startServers(AbstractHomematicGateway.java:245) ~[?:?]
at org.openhab.binding.homematic.internal.communicator.AbstractHomematicGateway.initialize(AbstractHomematicGateway.java:183) ~[?:?]
at org.openhab.binding.homematic.handler.HomematicBridgeHandler.lambda$0(HomematicBridgeHandler.java:87) ~[?:?]
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) [?:?]
11:06:54.844 [DEBUG] [ematic.handler.HomematicBridgeHandler] - Disposing bridge 'd33daba2'@mdicke2s please have a look.
Xento
commented
6 years ago Maybe it could be come problem with this because I'm on the stable 2.3 at the moment. https://github.com/eclipse/smarthome/pull/5928
At the moment I can't repoduce the first situation but I had it bevor. Maybe it takes some time of running.
mdicke2s
commented
6 years ago Hi @Xento
I also directly thought of #5928. Unfortunately it didn't make it into OH 2.3.0 (which was released just one week before the change).
I am not sure if the changes in that pull request would solve this problem, but it would definitely improve the logging of the ConnectionTrackerThread, to see what caused the binding to assume the connection as lost. Also it synchronizes calls to start/stop of servers and clients, which may help as well.
From your log I can see that at 21:38:20.903 the binding failed to call listDevices via XMLRpc. This fails because at exactly same time (which is actually very unlikely to happen) there was a call to de-register XMLRpcClient (because the ConnectionTrackerThread called stopServers()
From the error that you posted recently
11:06:54.781 [ERROR] [ematic.handler.HomematicBridgeHandler] - Homematic bridge was set to OFFLINE-COMMUNICATION_ERROR due to the following exception: Address already in use (Bind failed) java.net.BindException: Address already in use (Bind failed)
it is clear that there is an BinRpcServer which was not closed properly. But I cannot determine how this could happen.
My recommendation for you would be to try a SNAPSHOT release to see if the problem is solved by #5928
BTW: When you say overloaded, do you mean it doesn't respond? Did you check the logs on the other side?
Xento
commented
6 years ago Isn't it possible to just update the binding?
Xento
commented
6 years ago I updated to the latest 2.4 snapshot. When it is "overloaded" the ccu is unable to communicate with the devices. When you want to open the panel where you can add new devices, the page keeps loading and nothing happens. Then when you stop the binding everything works again. Maybe there are to many connections opened from openhab or such things.
mdicke2s
commented
6 years ago I updated to the latest 2.4 snapshot.
Good, I hope that this solves your problem already. If not would be great if you can share some log's again. You may think of increasing the log level to TRACE. That way we would be able to see all calls in the Rpc clients & servers.
When it is "overloaded" the ccu is unable to communicate with the devices. When you want to open the panel where you can add new devices, the page keeps loading and nothing happens. Then when you stop the binding everything works again.
ok, thx
I would guess that the frequent calls to listDevices are expensive and eat your CCU's performance
Maybe there are to many connections opened from openhab or such things.
If it is working correctly, there shouldn't be more than one. At least before #5928 it was possible that initialization of servers runs concurrently which can of cause lead to more than one server open.
Xento
commented
6 years ago How can I attach logfiles? It happened again but this time because my NAS where docker runs on had much todo.
Xento
commented
6 years ago I already stopped the binding but this doesn't seem to work:
21:50:18.369 [TRACE] [nal.communicator.client.SocketHandler] - Returning socket for port 2001
21:50:18.374 [WARN ] [e.core.thing.binding.BaseThingHandler] - Handler HomematicThingHandler tried updating the thing status although the handler was already disposed.
21:50:18.373 [INFO ] [ome.event.ThingStatusInfoChangedEvent] - 'homematic:HM-Sec-SCo:d33daba2:OEQ0222362' changed from OFFLINE (BRIDGE_OFFLINE) to UNINITIALIZED
21:50:18.393 [WARN ] [e.core.thing.binding.BaseThingHandler] - Handler HomematicThingHandler tried updating the thing status although the handler was already disposed.
21:50:18.401 [WARN ] [e.core.thing.binding.BaseThingHandler] - Handler HomematicThingHandler tried updating the thing status although the handler was already disposed.
21:50:18.408 [WARN ] [e.core.thing.binding.BaseThingHandler] - Handler HomematicThingHandler tried updating the thing status although the handler was already disposed.
21:50:18.411 [DEBUG] [rnal.communicator.client.BinRpcClient] - BinRpcMessage socket failure, sending message again 1/1
21:50:18.421 [TRACE] [nal.communicator.client.SocketHandler] - Closing Socket on port 2001
21:50:18.461 [WARN ] [e.core.thing.binding.BaseThingHandler] - Handler HomematicThingHandler tried updating the thing status although the handler was already disposed.
21:50:18.453 [TRACE] [nal.communicator.client.SocketHandler] - Creating new socket for port 2001
21:50:18.471 [WARN ] [e.core.thing.binding.BaseThingHandler] - Handler HomematicThingHandler tried updating the thing status although the handler was already disposed.
21:50:18.482 [WARN ] [e.core.thing.binding.BaseThingHandler] - Handler HomematicThingHandler tried updating the thing status although the handler was already disposed.
21:50:18.490 [WARN ] [e.core.thing.binding.BaseThingHandler] - Handler HomematicThingHandler tried updating the thing status although the handler was already disposed.
21:50:18.497 [WARN ] [e.core.thing.binding.BaseThingHandler] - Handler HomematicThingHandler tried updating the thing status although the handler was already disposed.
21:50:19.401 [INFO ] [ome.event.ThingStatusInfoChangedEvent] - 'homematic:HM-Sec-SCo:d33daba2:OEQ0222362' changed from UNINITIALIZED to UNINITIALIZED (HANDLER_MISSING_ERROR)
21:50:21.424 [INFO ] [ome.event.ThingStatusInfoChangedEvent] - 'homematic:HM-WS550STH-I:d33daba2:CUX1200027' changed from OFFLINE (BRIDGE_OFFLINE) to UNINITIALIZED
21:50:24.446 [INFO ] [ome.event.ThingStatusInfoChangedEvent] - 'homematic:HM-WS550STH-I:d33daba2:CUX1200027' changed from UNINITIALIZED to UNINITIALIZED (HANDLER_MISSING_ERROR)
21:50:24.454 [INFO ] [ome.event.ThingStatusInfoChangedEvent] - 'homematic:HM-LC-Sw1PBU-FM:d33daba2:NEQ0273400' changed from OFFLINE (BRIDGE_OFFLINE) to UNINITIALIZED
21:50:24.464 [INFO ] [ome.event.ThingStatusInfoChangedEvent] - 'homematic:HM-LC-Sw1PBU-FM:d33daba2:NEQ0273400' changed from UNINITIALIZED to UNINITIALIZED (HANDLER_MISSING_ERROR)
21:50:24.478 [INFO ] [ome.event.ThingStatusInfoChangedEvent] - 'homematic:HM-TC-IT-WM-W-EU:d33daba2:NEQ1523374' changed from OFFLINE (BRIDGE_OFFLINE) to UNINITIALIZED
21:50:25.488 [INFO ] [ome.event.ThingStatusInfoChangedEvent] - 'homematic:HM-TC-IT-WM-W-EU:d33daba2:NEQ1523374' changed from UNINITIALIZED to UNINITIALIZED (HANDLER_MISSING_ERROR)
21:50:25.500 [INFO ] [ome.event.ThingStatusInfoChangedEvent] - 'homematic:HM-Sec-SCo:d33daba2:NEQ0627982' changed from ONLINE to UNINITIALIZED
21:50:25.506 [INFO ] [ome.event.ThingStatusInfoChangedEvent] - 'homematic:HM-Sec-SCo:d33daba2:NEQ0627982' changed from UNINITIALIZED to UNINITIALIZED (HANDLER_MISSING_ERROR)
21:50:25.520 [INFO ] [ome.event.ThingStatusInfoChangedEvent] - 'homematic:HM-LC-Bl1PBU-FM:d33daba2:NEQ0393620' changed from ONLINE to UNINITIALIZED
21:50:25.533 [INFO ] [ome.event.ThingStatusInfoChangedEvent] - 'homematic:bridge:d33daba2' changed from OFFLINE (COMMUNICATION_ERROR): Connection lost to UNINITIALIZED
21:50:25.607 [INFO ] [ome.event.ThingStatusInfoChangedEvent] - 'homematic:HM-Sec-SD-2-Team:d33daba2:T-NEQ0243098' changed from UNINITIALIZED to UNINITIALIZED (HANDLER_MISSING_ERROR)
21:50:26.637 [INFO ] [ome.event.ThingStatusInfoChangedEvent] - 'homematic:HM-Sec-SD-2:d33daba2:NEQ0244130' changed from UNINITIALIZED to UNINITIALIZED (HANDLER_MISSING_ERROR)
21:50:26.645 [INFO ] [ome.event.ThingStatusInfoChangedEvent] - 'homematic:bridge:d33daba2' changed from UNINITIALIZED to UNINITIALIZED (HANDLER_MISSING_ERROR)without being into the code this line caught my eye:
21:50:18.471 [WARN ] [e.core.thing.binding.BaseThingHandler] - Handler HomematicThingHandler tried updating the thing status although the handler was already disposed.In HomematicThingHandler#initialize the initFuture is created and submitted to do the handler initialisation. This task is however not stopped during #dispose.
Xento
commented
6 years ago Maybe this is the problem in HomematicThingHandler:
/**
* Schedules a reinitialization, if the Homematic gateway is not reachable at bridge startup.
*/
private void scheduleReinitialize() {
scheduler.schedule(() -> {
initialize();
}, REINITIALIZE_DELAY_SECONDS, TimeUnit.SECONDS);
}Here is a more compelte log snippet. This time I had to restart openhab to get my ccu back working. https://pastebin.com/rY8jHkA8
Xento
commented
5 years ago It happened again. The log did't gives much information
The open connections on the ccu to openhab: https://pastebin.com/JuYUuf57
Here is the log after I wanted to stop the bundle: https://pastebin.com/D76N94Uc
Open connections from openhab after trying to restart the bundle https://pastebin.com/DSVsuNhs
Connections on CCU after stopping dockercontainer from openhab: https://pastebin.com/nH05Rm85
Connections after restart of openhab: CCU: https://pastebin.com/Ck4LDYaa Openhab: https://pastebin.com/kpvDw2rW
Hello, I have the problem that there is an issue when openhab wants to reconnect to the ccu. The ccu becomes unresponsive in some functions until I stop the bundle and start it again. A restart of the bundle with bundle:restart is not enough.
Here is the part of the logfile when I restarted the ccu
And here is the next part of the log file when the connection is reestablished after the ccu is online again: