search

gitbock / fritzboxtr064

Binding for openHAB for communicating with AVM FritzBox
16 stars 12 forks source link

Connection errors and issues #41

Open hartmood opened 4 years ago

hartmood commented 4 years ago

I constantly receive errors and warnings. I have no idea as the DEBUG log doesn’t really give an information what causes the time outs. I am on 2.5 M4 with a openhabian install.

tail -f /var/log/openhab2/openhab.log /var/log/openhab2/events.log ing.fritzboxtr064.internal.Tr064Comm 2019-11-05 09:57:09.038 [ERROR] [ing.fritzboxtr064.internal.Tr064Comm] - Cannot send/receive: Read timed out 2019-11-05 09:57:09.040 [WARN ] [ing.fritzboxtr064.internal.Tr064Comm] - Releasing connection to FritzBox because of error. 2019-11-05 09:57:09.043 [WARN ] [ing.fritzboxtr064.internal.Tr064Comm] - Error retrieving SOAP response from FritzBox 2019-11-05 09:57:09.528 [vent.ItemStateChangedEvent] - logreader_reader_dc3aa754_lastErrorEvent changed from 2019-11-05 09:10:22.756 [ERROR] [ing.fritzboxtr064.internal.Tr064Comm] - Cannot send/receive: Read timed out to 2019-11-05 09:57:09.038 [ERROR] [ing.fritzboxtr064.internal.Tr064Comm] - Cannot send/receive: Read timed out 2019-11-05 09:57:09.530 [vent.ChannelTriggeredEvent] - logreader:reader:dc3aa754:newErrorEvent triggered 2019-11-05 09:57:09.038 [ERROR] [ing.fritzboxtr064.internal.Tr064Comm] - Cannot send/receive: Read timed out 2019-11-05 09:57:09.531 [vent.ChannelTriggeredEvent] - logreader:reader:dc3aa754:newWarningEvent triggered 2019-11-05 09:57:09.040 [WARN ] [ing.fritzboxtr064.internal.Tr064Comm] - Releasing connection to FritzBox because of error. 2019-11-05 09:57:09.533 [vent.ChannelTriggeredEvent] - logreader:reader:dc3aa754:newWarningEvent triggered 2019-11-05 09:57:09.043 [WARN ] [ing.fritzboxtr064.internal.Tr064Comm] - Error retrieving SOAP response from FritzBox 2019-11-05 09:59:11.869 [DEBUG] [ing.fritzboxtr064.internal.Tr064Comm] - Releasing connection 2019-11-05 09:59:12.603 [DEBUG] [ing.fritzboxtr064.internal.Tr064Comm] - Releasing connection 2019-11-05 09:59:13.342 [DEBUG] [ing.fritzboxtr064.internal.Tr064Comm] - Releasing connection 2019-11-05 10:01:13.439 [DEBUG] [ing.fritzboxtr064.internal.Tr064Comm] - Releasing connection 2019-11-05 10:01:14.151 [DEBUG] [ing.fritzboxtr064.internal.Tr064Comm] - Releasing connection 2019-11-05 10:01:14.672 [DEBUG] [ing.fritzboxtr064.internal.Tr064Comm] - Releasing connection 2019-11-05 10:03:14.763 [DEBUG] [ing.fritzboxtr064.internal.Tr064Comm] - Releasing connection 2019-11-05 10:03:15.279 [DEBUG] [ing.fritzboxtr064.internal.Tr064Comm] - Releasing connection 2019-11-05 10:03:15.795 [DEBUG] [ing.fritzboxtr064.internal.Tr064Comm] - Releasing connection 2019-11-05 10:05:15.902 [DEBUG] [ing.fritzboxtr064.internal.Tr064Comm] - Releasing connection 2019-11-05 10:05:16.591 [DEBUG] [ing.fritzboxtr064.internal.Tr064Comm] - Releasing connection 2019-11-05 10:05:17.113 [DEBUG] [ing.fritzboxtr064.internal.Tr064Comm] - Releasing connection 2019-11-05 10:07:21.252 [DEBUG] [ing.fritzboxtr064.internal.Tr064Comm] - Releasing connection 2019-11-05 10:07:21.975 [DEBUG] [ing.fritzboxtr064.internal.Tr064Comm] - Releasing connection 2019-11-05 10:07:22.492 [DEBUG] [ing.fritzboxtr064.internal.Tr064Comm] - Releasing connection 2019-11-05 10:07:51.046 [DEBUG] [ing.fritzboxtr064.internal.Tr064Comm] - SOAP Msg to send to FritzBox for setting data: <SOAP-ENV:Envelope xmlns:SOAP-ENV="http://schemas.xmlsoap.org/soap/envelope/"><SOAP-ENV:Header/><SOAP-ENV:Body><u:SetEnable xmlns:u="urn:dslforum-org:service:WLANConfiguration:1"><NewEnable>0</NewEnable></u:SetEnable></SOAP-ENV:Body></SOAP-ENV:Envelope> 2019-11-05 10:07:51.111 [DEBUG] [ing.fritzboxtr064.internal.Tr064Comm] - Releasing connection 2019-11-05 10:07:51.113 [DEBUG] [ing.fritzboxtr064.internal.Tr064Comm] - SOAP response from FritzBox: <?xml version="1.0"?> 2019-11-05 10:07:51.172 [DEBUG] [ing.fritzboxtr064.internal.Tr064Comm] - SOAP Msg to send to FritzBox for setting data: <SOAP-ENV:Envelope xmlns:SOAP-ENV="http://schemas.xmlsoap.org/soap/envelope/"><SOAP-ENV:Header/><SOAP-ENV:Body><u:SetEnable xmlns:u="urn:dslforum-org:service:WLANConfiguration:2"><NewEnable>0</NewEnable></u:SetEnable></SOAP-ENV:Body></SOAP-ENV:Envelope> 2019-11-05 10:07:53.147 [DEBUG] [ing.fritzboxtr064.internal.Tr064Comm] - Releasing connection 2019-11-05 10:07:53.152 [DEBUG] [ing.fritzboxtr064.internal.Tr064Comm] - SOAP response from FritzBox: <?xml version="1.0"?> 2019-11-05 10:11:24.317 [DEBUG] [ing.fritzboxtr064.internal.Tr064Comm] - Releasing connection 2019-11-05 10:11:25.045 [DEBUG] [ing.fritzboxtr064.internal.Tr064Comm] - Releasing connection 2019-11-05 10:11:25.572 [DEBUG] [ing.fritzboxtr064.internal.Tr064Comm] - Releasing connection 2019-11-05 10:13:25.657 [DEBUG] [ing.fritzboxtr064.internal.Tr064Comm] - Releasing connection 2019-11-05 10:13:26.182 [DEBUG] [ing.fritzboxtr064.internal.Tr064Comm] - Releasing connection 2019-11-05 10:13:26.715 [DEBUG] [ing.fritzboxtr064.internal.Tr064Comm] - Releasing connection 2019-11-05 10:15:26.846 [DEBUG] [ing.fritzboxtr064.internal.Tr064Comm] - Releasing connection 2019-11-05 10:15:27.566 [DEBUG] [ing.fritzboxtr064.internal.Tr064Comm] - Releasing connection 2019-11-05 10:15:28.071 [DEBUG] [ing.fritzboxtr064.internal.Tr064Comm] - Releasing connection 2019-11-05 10:17:05.090 [DEBUG] [ing.fritzboxtr064.internal.Tr064Comm] - SOAP Msg to send to FritzBox for setting data: <SOAP-ENV:Envelope xmlns:SOAP-ENV="http://schemas.xmlsoap.org/soap/envelope/"><SOAP-ENV:Header/><SOAP-ENV:Body><u:SetEnable xmlns:u="urn:dslforum-org:service:WLANConfiguration:2"><NewEnable>1</NewEnable></u:SetEnable></SOAP-ENV:Body></SOAP-ENV:Envelope> 2019-11-05 10:17:05.135 [DEBUG] [ing.fritzboxtr064.internal.Tr064Comm] - Releasing connection 2019-11-05 10:17:05.138 [DEBUG] [ing.fritzboxtr064.internal.Tr064Comm] - SOAP response from FritzBox: <?xml version="1.0"?> 2019-11-05 10:17:28.147 [DEBUG] [ing.fritzboxtr064.internal.Tr064Comm] - Releasing connection 2019-11-05 10:17:31.642 [DEBUG] [ing.fritzboxtr064.internal.Tr064Comm] - Releasing connection 2019-11-05 10:17:32.188 [DEBUG] [ing.fritzboxtr064.internal.Tr064Comm] - Releasing connection 2019-11-05 10:17:59.090 [DEBUG] [ing.fritzboxtr064.internal.Tr064Comm] - SOAP Msg to send to FritzBox for setting data: <SOAP-ENV:Envelope xmlns:SOAP-ENV="http://schemas.xmlsoap.org/soap/envelope/"><SOAP-ENV:Header/><SOAP-ENV:Body><u:SetEnable xmlns:u="urn:dslforum-org:service:WLANConfiguration:2"><NewEnable>0</NewEnable></u:SetEnable></SOAP-ENV:Body></SOAP-ENV:Envelope> 2019-11-05 10:18:02.968 [DEBUG] [ing.fritzboxtr064.internal.Tr064Comm] - Releasing connection 2019-11-05 10:18:02.970 [DEBUG] [ing.fritzboxtr064.internal.Tr064Comm] - SOAP response from FritzBox: <?xml version="1.0"?> 2019-11-05 10:19:32.281 [DEBUG] [ing.fritzboxtr064.internal.Tr064Comm] - Releasing connection 2019-11-05 10:19:32.972 [DEBUG] [ing.fritzboxtr064.internal.Tr064Comm] - Releasing connection 2019-11-05 10:19:33.489 [DEBUG] [ing.fritzboxtr064.internal.Tr064Comm] - Releasing connection 2019-11-05 10:21:33.589 [DEBUG] [ing.fritzboxtr064.internal.Tr064Comm] - Releasing connection 2019-11-05 10:21:34.272 [DEBUG] [ing.fritzboxtr064.internal.Tr064Comm] - Releasing connection 2019-11-05 10:21:34.810 [DEBUG] [ing.fritzboxtr064.internal.Tr064Comm] - Releasing connection 2019-11-05 10:23:35.088 [DEBUG] [ing.fritzboxtr064.internal.Tr064Comm] - Releasing connection 2019-11-05 10:23:35.575 [DEBUG] [ing.fritzboxtr064.internal.Tr064Comm] - Releasing connection 2019-11-05 10:23:36.061 [DEBUG] [ing.fritzboxtr064.internal.Tr064Comm] - Releasing connection 2019-11-05 10:21:33.589 [DEBUG] [ing.fritzboxtr064.internal.Tr064Comm] - Releasing connection 2019-11-05 10:21:34.272 [DEBUG] [ing.fritzboxtr064.internal.Tr064Comm] - Releasing connection 2019-11-05 10:21:34.810 [DEBUG] [ing.fritzboxtr064.internal.Tr064Comm] - Releasing connection 2019-11-05 10:23:35.088 [DEBUG] [ing.fritzboxtr064.internal.Tr064Comm] - Releasing connection 2019-11-05 10:23:35.575 [DEBUG] [ing.fritzboxtr064.internal.Tr064Comm] - Releasing connection 2019-11-05 10:23:36.061 [DEBUG] [ing.fritzboxtr064.internal.Tr064Comm] - Releasing connection 2019-11-05 10:25:36.179 [DEBUG] [ing.fritzboxtr064.internal.Tr064Comm] - Releasing connection 2019-11-05 10:25:37.076 [DEBUG] [ing.fritzboxtr064.internal.Tr064Comm] - Releasing connection 2019-11-05 10:25:37.365 [DEBUG] [ing.fritzboxtr064.internal.Tr064Comm] - Releasing connection 2019-11-05 10:27:37.458 [DEBUG] [ing.fritzboxtr064.internal.Tr064Comm] - Releasing connection 2019-11-05 10:27:38.166 [DEBUG] [ing.fritzboxtr064.internal.Tr064Comm] - Releasing connection 2019-11-05 10:27:43.152 [ERROR] [ing.fritzboxtr064.internal.Tr064Comm] - Cannot send/receive: Read timed out 2019-11-05 10:27:43.153 [WARN ] [ing.fritzboxtr064.internal.Tr064Comm] - Releasing connection to FritzBox because of error. 2019-11-05 10:27:43.160 [DEBUG] [ing.fritzboxtr064.internal.Tr064Comm] - Not able to parse SOAP message: null at org.openhab.binding.fritzboxtr064.internal.Tr064Comm.soapToString(Tr064Comm.java:436) [253:org.openhab.binding.fritzboxtr064:1.14.0.M4] at org.openhab.binding.fritzboxtr064.internal.Tr064Comm.getTr064Values(Tr064Comm.java:259) [253:org.openhab.binding.fritzboxtr064:1.14.0.M4] 2019-11-05 10:27:43.161 [WARN ] [ing.fritzboxtr064.internal.Tr064Comm] - Error retrieving SOAP response from FritzBox 2019-11-05 10:27:43.595 [vent.ChannelTriggeredEvent] - logreader:reader:dc3aa754:newErrorEvent triggered 2019-11-05 10:27:43.152 [ERROR] [ing.fritzboxtr064.internal.Tr064Comm] - Cannot send/receive: Read timed out 2019-11-05 10:27:43.598 [vent.ChannelTriggeredEvent] - logreader:reader:dc3aa754:newWarningEvent triggered 2019-11-05 10:27:43.153 [WARN ] [ing.fritzboxtr064.internal.Tr064Comm] - Releasing connection to FritzBox because of error. 2019-11-05 10:27:43.601 [vent.ChannelTriggeredEvent] - logreader:reader:dc3aa754:newWarningEvent triggered 2019-11-05 10:27:43.161 [WARN ] [ing.fritzboxtr064.internal.Tr064Comm] - Error retrieving SOAP response from FritzBox 2019-11-05 10:27:43.604 [vent.ItemStateChangedEvent] - logreader_reader_dc3aa754_lastErrorEvent changed from 2019-11-05 09:57:09.038 [ERROR] [ing.fritzboxtr064.internal.Tr064Comm] - Cannot send/receive: Read timed out to 2019-11-05 10:27:43.152 [ERROR] [ing.fritzboxtr064.internal.Tr064Comm] - Cannot send/receive: Read timed out 2019-11-05 10:29:43.237 [DEBUG] [ing.fritzboxtr064.internal.Tr064Comm] - Releasing connection 2019-11-05 10:29:44.124 [DEBUG] [ing.fritzboxtr064.internal.Tr064Comm] - Releasing connection 2019-11-05 10:29:44.431 [DEBUG] [ing.fritzboxtr064.internal.Tr064Comm] - Releasing connection 2019-11-05 10:25:36.179 [DEBUG] [ing.fritzboxtr064.internal.Tr064Comm] - Releasing connection 2019-11-05 10:25:37.076 [DEBUG] [ing.fritzboxtr064.internal.Tr064Comm] - Releasing connection 2019-11-05 10:25:37.365 [DEBUG] [ing.fritzboxtr064.internal.Tr064Comm] - Releasing connection 2019-11-05 10:27:37.458 [DEBUG] [ing.fritzboxtr064.internal.Tr064Comm] - Releasing connection 2019-11-05 10:27:38.166 [DEBUG] [ing.fritzboxtr064.internal.Tr064Comm] - Releasing connection 2019-11-05 10:27:43.152 [ERROR] [ing.fritzboxtr064.internal.Tr064Comm] - Cannot send/receive: Read timed out 2019-11-05 10:27:43.153 [WARN ] [ing.fritzboxtr064.internal.Tr064Comm] - Releasing connection to FritzBox because of error. 2019-11-05 10:27:43.160 [DEBUG] [ing.fritzboxtr064.internal.Tr064Comm] - Not able to parse SOAP message: null at org.openhab.binding.fritzboxtr064.internal.Tr064Comm.soapToString(Tr064Comm.java:436) [253:org.openhab.binding.fritzboxtr064:1.14.0.M4] at org.openhab.binding.fritzboxtr064.internal.Tr064Comm.getTr064Values(Tr064Comm.java:259) [253:org.openhab.binding.fritzboxtr064:1.14.0.M4] 2019-11-05 10:27:43.161 [WARN ] [ing.fritzboxtr064.internal.Tr064Comm] - Error retrieving SOAP response from FritzBox 2019-11-05 10:27:43.595 [vent.ChannelTriggeredEvent] - logreader:reader:dc3aa754:newErrorEvent triggered 2019-11-05 10:27:43.152 [ERROR] [ing.fritzboxtr064.internal.Tr064Comm] - Cannot send/receive: Read timed out 2019-11-05 10:27:43.598 [vent.ChannelTriggeredEvent] - logreader:reader:dc3aa754:newWarningEvent triggered 2019-11-05 10:27:43.153 [WARN ] [ing.fritzboxtr064.internal.Tr064Comm] - Releasing connection to FritzBox because of error. 2019-11-05 10:27:43.601 [vent.ChannelTriggeredEvent] - logreader:reader:dc3aa754:newWarningEvent triggered 2019-11-05 10:27:43.161 [WARN ] [ing.fritzboxtr064.internal.Tr064Comm] - Error retrieving SOAP response from FritzBox 2019-11-05 10:27:43.604 [vent.ItemStateChangedEvent] - logreader_reader_dc3aa754_lastErrorEvent changed from 2019-11-05 09:57:09.038 [ERROR] [ing.fritzboxtr064.internal.Tr064Comm] - Cannot send/receive: Read timed out to 2019-11-05 10:27:43.152 [ERROR] [ing.fritzboxtr064.internal.Tr064Comm] - Cannot send/receive: Read timed out 2019-11-05 10:29:43.237 [DEBUG] [ing.fritzboxtr064.internal.Tr064Comm] - Releasing connection 2019-11-05 10:29:44.124 [DEBUG] [ing.fritzboxtr064.internal.Tr064Comm] - Releasing connection 2019-11-05 10:29:44.431 [DEBUG] [ing.fritzboxtr064.internal.Tr064Comm] - Releasing connection 2019-11-05 10:31:44.540 [DEBUG] [ing.fritzboxtr064.internal.Tr064Comm] - Releasing connection 2019-11-05 10:31:45.227 [DEBUG] [ing.fritzboxtr064.internal.Tr064Comm] - Releasing connection 2019-11-05 10:31:45.755 [DEBUG] [ing.fritzboxtr064.internal.Tr064Comm] - Releasing connection 2019-11-05 10:33:45.842 [DEBUG] [ing.fritzboxtr064.internal.Tr064Comm] - Releasing connection 2019-11-05 10:33:46.569 [DEBUG] [ing.fritzboxtr064.internal.Tr064Comm] - Releasing connection 2019-11-05 10:33:47.100 [DEBUG] [ing.fritzboxtr064.internal.Tr064Comm] - Releasing connection

KenkiCK commented 4 years ago

Same with version 2.5.0-1 - found a hint to install Java 8 but nor really know how - is outdated what I know. Use a raspberry

hartmood commented 4 years ago

In my case my openhab had connection issues because of using powerLan (PLC) with lots of lost packets. Switched to WiFi and reduced this FritzBox issues dramatically although not solved it completely. Try to ping your openhab. If you have lots of packet losses and fix this problem first. Nevertheless this binding is pretty susceptible for packet loss. Other network bindings don’t show errors in the log.