search

gitbock / fritzboxtr064

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

Authentification not stable? Could not read response from FritzBox. Unauthorized! Check User/PW in config. Create user for tr064 requests #23

Open jensihnow opened 8 years ago

jensihnow commented 8 years ago

Hi,

I'm using this pluing with custom user configured and for some reason it stops working after a while and gives:

==> events.log <==
2016-08-20 17:58:53 - fboxWifi24 state updated to OFF

==> openhab.log <==
2016-08-20 17:58:53.492 [ERROR] [o.o.b.f.i.FritzboxTr064Binding] - Could not read response from FritzBox. Unauthorized! Check User/PW in config. Create user for tr064 requests
2016-08-20 17:58:53.493 [ERROR] [o.o.b.f.i.FritzboxTr064Binding] - Error retrieving SOAP response from FritzBox

==> events.log <==
2016-08-20 17:58:53 - fboxMissedCalls state updated to -1

==> openhab.log <==
2016-08-20 17:58:53.551 [ERROR] [o.o.b.f.i.FritzboxTr064Binding] - Could not read response from FritzBox. Unauthorized! Check User/PW in config. Create user for tr064 requests
2016-08-20 17:58:53.554 [ERROR] [o.o.b.f.i.FritzboxTr064Binding] - Error retrieving SOAP response from FritzBox

==> events.log <==
2016-08-20 17:58:53 - fboxWanIP state updated to ERR

==> openhab.log <==
2016-08-20 17:58:53.598 [ERROR] [o.o.b.f.i.FritzboxTr064Binding] - Could not read response from FritzBox. Unauthorized! Check User/PW in config. Create user for tr064 requests
2016-08-20 17:58:53.600 [ERROR] [o.o.b.f.i.FritzboxTr064Binding] - Error retrieving SOAP response from FritzBox

==> events.log <==
2016-08-20 17:58:53 - fboxName state updated to ERR

==> openhab.log <==
2016-08-20 17:58:53.682 [ERROR] [o.o.b.f.i.FritzboxTr064Binding] - Could not read response from FritzBox. Unauthorized! Check User/PW in config. Create user for tr064 requests
2016-08-20 17:58:53.683 [ERROR] [o.o.b.f.i.FritzboxTr064Binding] - Error retrieving SOAP response from FritzBox

==> events.log <==
2016-08-20 17:58:53 - fboxTAM0NewMsg state updated to -1

==> openhab.log <==
2016-08-20 17:58:53.748 [ERROR] [o.o.b.f.i.FritzboxTr064Binding] - Could not read response from FritzBox. Unauthorized! Check User/PW in config. Create user for tr064 requests
2016-08-20 17:58:53.749 [ERROR] [o.o.b.f.i.FritzboxTr064Binding] - Error retrieving SOAP response from FritzBox

==> events.log <==
2016-08-20 17:58:53 - fboxGuestWifi state updated to OFF

==> openhab.log <==
2016-08-20 17:58:53.777 [ERROR] [o.o.b.f.i.FritzboxTr064Binding] - Could not read response from FritzBox. Unauthorized! Check User/PW in config. Create user for tr064 requests
2016-08-20 17:58:53.783 [ERROR] [o.o.b.f.i.FritzboxTr064Binding] - Error retrieving SOAP response from FritzBox

==> events.log <==
2016-08-20 17:58:53 - fboxWifi50 state updated to OFF

==> openhab.log <==
2016-08-20 17:58:53.838 [ERROR] [o.o.b.f.i.FritzboxTr064Binding] - Could not read response from FritzBox. Unauthorized! Check User/PW in config. Create user for tr064 requests
2016-08-20 17:58:53.839 [ERROR] [o.o.b.f.i.FritzboxTr064Binding] - Error retrieving SOAP response from FritzBox

Looking for output from the binding (fresh restart) I get this:

2016-08-20 18:07:52.182 [INFO ] [o.o.b.f.i.FritzboxTr064Binding] - Downloading phonebook ID 0
2016-08-20 18:08:03.990 [INFO ] [o.o.b.f.i.FritzboxTr064Binding] - Callmonitor Thread [217] attempting connection to FritzBox on 192.168.28.1:1012..
2016-08-20 18:08:03.992 [INFO ] [o.o.b.f.i.FritzboxTr064Binding] - Connected to FritzBox on 192.168.28.1:1012
2016-08-20 19:54:06.368 [ERROR] [o.o.b.f.i.FritzboxTr064Binding] - Cannot send/receive: Read timed out
2016-08-20 19:54:06.368 [ERROR] [o.o.b.f.i.FritzboxTr064Binding] - Releasing connection to FritzBox because of error!
2016-08-20 19:54:06.372 [ERROR] [o.o.b.f.i.FritzboxTr064Binding] - Error retrieving SOAP response from FritzBox
2016-08-20 19:54:10.385 [ERROR] [o.o.b.f.i.FritzboxTr064Binding] - Cannot send/receive: Connect to 192.168.28.1:49443 [/192.168.28.1] failed: connect timed out
2016-08-20 19:54:10.385 [ERROR] [o.o.b.f.i.FritzboxTr064Binding] - Releasing connection to FritzBox because of error!
2016-08-20 19:54:10.385 [ERROR] [o.o.b.f.i.FritzboxTr064Binding] - Error retrieving SOAP response from FritzBox
2016-08-20 20:00:00.032 [INFO ] [o.o.b.f.i.FritzboxTr064Binding] - Fritzbox Reconnect Job executed
2016-08-20 20:00:00.055 [INFO ] [o.o.b.f.i.FritzboxTr064Binding] - Lost connection to Fritzbox because of interrupt
2016-08-20 20:00:05.064 [INFO ] [o.o.b.f.i.FritzboxTr064Binding] - Callmonitor Thread [1511] attempting connection to FritzBox on 192.168.28.1:1012..
2016-08-20 20:00:05.066 [INFO ] [o.o.b.f.i.FritzboxTr064Binding] - Connected to FritzBox on 192.168.28.1:1012
2016-08-20 20:20:30.164 [ERROR] [o.o.b.f.i.FritzboxTr064Binding] - Cannot send/receive: Read timed out
2016-08-20 20:20:30.164 [ERROR] [o.o.b.f.i.FritzboxTr064Binding] - Releasing connection to FritzBox because of error!
2016-08-20 20:20:30.165 [ERROR] [o.o.b.f.i.FritzboxTr064Binding] - Error retrieving SOAP response from FritzBox
2016-08-20 20:20:30.685 [ERROR] [o.o.b.f.i.FritzboxTr064Binding] - Could not read response from FritzBox. Unauthorized! Check User/PW in config. Create user for tr064 requests
2016-08-20 20:20:30.686 [ERROR] [o.o.b.f.i.FritzboxTr064Binding] - Error retrieving SOAP response from FritzBox
2016-08-20 20:20:30.891 [ERROR] [o.o.b.f.i.FritzboxTr064Binding] - Could not read response from FritzBox. Unauthorized! Check User/PW in config. Create user for tr064 requests
2016-08-20 20:20:30.892 [ERROR] [o.o.b.f.i.FritzboxTr064Binding] - Error retrieving SOAP response from FritzBox
2016-08-20 20:20:30.970 [ERROR] [o.o.b.f.i.FritzboxTr064Binding] - Could not read response from FritzBox. Unauthorized! Check User/PW in config. Create user for tr064 requests

I'm not sure if this is an error of the fritz box or the binding not being able to reconnect correctly. Especially because first it works and at some point it seems to go into fancy state. When I restart everything works as usual.

As mentioned earlier I'm using a special user configured for this use case only.

I also wonder about the frequency of the log messages in some cases '(sometimes it looks like very 60 seconds, which should be ok in regards to the configured refresh). It seems to retry like crazy what might let the fritz box go impatient as well. ;-) If a time out or any type of connection error happened I wonder if there should be some sort of back off between the retries.

Sorry I didn't looked into the code yet, just wanted to capture the behavior I discovered while testing the binding.

jensihnow commented 8 years ago

I've restarted the Fritz Box and looking into the log of the box I see the following:

...
20.08.16    23:01:23    Anmeldung an der FRITZ!Box Benutzeroberfläche von IP-Adresse 192.168.28.40. [6 Meldungen seit 20.08.16 23:01:12]
...
20.08.16    23:00:59    Anmeldung an der FRITZ!Box Benutzeroberfläche von IP-Adresse 192.168.28.40.
...
20.08.16    23:00:47    Anmeldung an der FRITZ!Box Benutzeroberfläche von IP-Adresse 192.168.28.40.
...
20.08.16    23:00:44    Anmeldung an der FRITZ!Box Benutzeroberfläche von IP-Adresse 192.168.28.40.
...
20.08.16    23:00:37    Anmeldung an der FRITZ!Box Benutzeroberfläche von IP-Adresse 192.168.28.40. [4 Meldungen seit 20.08.16 23:00:29]
20.08.16    23:00:28    Anmeldung an der FRITZ!Box Benutzeroberfläche von IP-Adresse 192.168.28.40 gescheitert (ungültige Sitzungskennung). Zur Sicherheit werden alle noch gültigen Sitzungen zur IP-Adresse 192.168.28.40 beendet. [10 Meldungen seit 20.08.16 23:00:14]
...

The IP matches the host openhab is running on. For some reason the binding is

jensihnow commented 8 years ago

Turning Debug output on gives:

2016-08-21 00:56:08.516 [DEBUG] [o.o.b.f.i.FritzboxTr064Binding] - Downloading call list using url https://192.168.28.1:49443/calllist.lua?sid=7d4600603c1dd65b&days=5
2016-08-21 00:56:09.136 [DEBUG] [o.o.b.f.i.FritzboxTr064Binding] - Releasing connection
2016-08-21 00:56:09.139 [DEBUG] [o.o.b.f.i.FritzboxTr064Binding] - Parsing xml message call list info <?xml version="1.0" encoding="UTF-8"?>
2016-08-21 00:56:09.139 [DEBUG] [o.o.b.f.i.FritzboxTr064Binding] - Parsed new messages as: 1
2016-08-21 00:56:09.141 [DEBUG] [o.o.b.f.i.FritzboxTr064Binding] - Raw SOAP Request to be sent to FritzBox: <SOAP-ENV:Envelope xmlns:SOAP-ENV="http://schemas.xmlsoap.org/soap/envelope/"><SOAP-ENV:Header/><SOAP-ENV:Body><u:GetExternalIPAddress xmlns:u="urn:dslforum-org:service:WANPPPConnection:1"/></SOAP-ENV:Body></SOAP-ENV:Envelope>
2016-08-21 00:56:10.203 [DEBUG] [o.o.b.f.i.FritzboxTr064Binding] - Releasing connection
2016-08-21 00:56:10.203 [DEBUG] [o.o.b.f.i.FritzboxTr064Binding] - Raw SOAP Response from FritzBox: <?xml version="1.0"?>
2016-08-21 00:56:10.207 [DEBUG] [o.o.b.f.i.FritzboxTr064Binding] - Raw SOAP Request to be sent to FritzBox: <SOAP-ENV:Envelope xmlns:SOAP-ENV="http://schemas.xmlsoap.org/soap/envelope/"><SOAP-ENV:Header/><SOAP-ENV:Body><u:GetInfo xmlns:u="urn:dslforum-org:service:DeviceInfo:1"/></SOAP-ENV:Body></SOAP-ENV:Envelope>
2016-08-21 00:56:14.261 [ERROR] [o.o.b.f.i.FritzboxTr064Binding] - Cannot send/receive: Read timed out
2016-08-21 00:56:14.262 [ERROR] [o.o.b.f.i.FritzboxTr064Binding] - Releasing connection to FritzBox because of error!
2016-08-21 00:56:14.264 [DEBUG] [o.o.b.f.i.FritzboxTr064Binding] - Raw SOAP Response from FritzBox: 
2016-08-21 00:56:14.264 [ERROR] [o.o.b.f.i.FritzboxTr064Binding] - Error retrieving SOAP response from FritzBox
2016-08-21 00:56:14.269 [DEBUG] [o.o.b.f.i.FritzboxTr064Binding] - Raw SOAP Request to be sent to FritzBox: <SOAP-ENV:Envelope xmlns:SOAP-ENV="http://schemas.xmlsoap.org/soap/envelope/"><SOAP-ENV:Header/><SOAP-ENV:Body><u:GetMessageList xmlns:u="urn:dslforum-org:service:X_AVM-DE_TAM:1"><NewIndex>0</NewIndex></u:GetMessageList></SOAP-ENV:Body></SOAP-ENV:Envelope>
2016-08-21 00:56:18.278 [ERROR] [o.o.b.f.i.FritzboxTr064Binding] - Cannot send/receive: Connect to 192.168.28.1:49443 [/192.168.28.1] failed: connect timed out
2016-08-21 00:56:18.279 [ERROR] [o.o.b.f.i.FritzboxTr064Binding] - Releasing connection to FritzBox because of error!
2016-08-21 00:56:18.279 [DEBUG] [o.o.b.f.i.FritzboxTr064Binding] - Raw SOAP Response from FritzBox: 
2016-08-21 00:56:18.279 [ERROR] [o.o.b.f.i.FritzboxTr064Binding] - Error retrieving SOAP response from FritzBox
2016-08-21 00:56:18.281 [DEBUG] [o.o.b.f.i.FritzboxTr064Binding] - Raw SOAP Request to be sent to FritzBox: <SOAP-ENV:Envelope xmlns:SOAP-ENV="http://schemas.xmlsoap.org/soap/envelope/"><SOAP-ENV:Header/><SOAP-ENV:Body><u:GetInfo xmlns:u="urn:dslforum-org:service:WLANConfiguration:3"/></SOAP-ENV:Body></SOAP-ENV:Envelope>
2016-08-21 00:56:22.288 [ERROR] [o.o.b.f.i.FritzboxTr064Binding] - Cannot send/receive: Connect to 192.168.28.1:49443 [/192.168.28.1] failed: connect timed out
2016-08-21 00:56:22.288 [ERROR] [o.o.b.f.i.FritzboxTr064Binding] - Releasing connection to FritzBox because of error!
2016-08-21 00:56:22.289 [DEBUG] [o.o.b.f.i.FritzboxTr064Binding] - Raw SOAP Response from FritzBox: 
2016-08-21 00:56:22.289 [ERROR] [o.o.b.f.i.FritzboxTr064Binding] - Error retrieving SOAP response from FritzBox
2016-08-21 00:56:22.293 [DEBUG] [o.o.b.f.i.FritzboxTr064Binding] - Raw SOAP Request to be sent to FritzBox: <SOAP-ENV:Envelope xmlns:SOAP-ENV="http://schemas.xmlsoap.org/soap/envelope/"><SOAP-ENV:Header/><SOAP-ENV:Body><u:GetInfo xmlns:u="urn:dslforum-org:service:WLANConfiguration:2"/></SOAP-ENV:Body></SOAP-ENV:Envelope>
2016-08-21 00:56:26.301 [ERROR] [o.o.b.f.i.FritzboxTr064Binding] - Cannot send/receive: Connect to 192.168.28.1:49443 [/192.168.28.1] failed: connect timed out
2016-08-21 00:56:26.302 [ERROR] [o.o.b.f.i.FritzboxTr064Binding] - Releasing connection to FritzBox because of error!
2016-08-21 00:56:26.302 [DEBUG] [o.o.b.f.i.FritzboxTr064Binding] - Raw SOAP Response from FritzBox: 
2016-08-21 00:56:26.302 [ERROR] [o.o.b.f.i.FritzboxTr064Binding] - Error retrieving SOAP response from FritzBox
2016-08-21 00:56:26.304 [DEBUG] [o.o.b.f.i.FritzboxTr064Binding] - Raw SOAP Request to be sent to FritzBox: <SOAP-ENV:Envelope xmlns:SOAP-ENV="http://schemas.xmlsoap.org/soap/envelope/"><SOAP-ENV:Header/><SOAP-ENV:Body><u:GetInfo xmlns:u="urn:dslforum-org:service:X_AVM-DE_TAM:1"><NewIndex>0</NewIndex></u:GetInfo></SOAP-ENV:Body></SOAP-ENV:Envelope>
2016-08-21 00:56:30.311 [ERROR] [o.o.b.f.i.FritzboxTr064Binding] - Cannot send/receive: Connect to 192.168.28.1:49443 [/192.168.28.1] failed: connect timed out
2016-08-21 00:56:30.312 [ERROR] [o.o.b.f.i.FritzboxTr064Binding] - Releasing connection to FritzBox because of error!
2016-08-21 00:56:30.312 [DEBUG] [o.o.b.f.i.FritzboxTr064Binding] - Raw SOAP Response from FritzBox: 
2016-08-21 00:56:30.312 [ERROR] [o.o.b.f.i.FritzboxTr064Binding] - Error retrieving SOAP response from FritzBox
2016-08-21 00:57:30.314 [DEBUG] [o.o.b.f.i.FritzboxTr064Binding] - Raw SOAP Request to be sent to FritzBox: <SOAP-ENV:Envelope xmlns:SOAP-ENV="http://schemas.xmlsoap.org/soap/envelope/"><SOAP-ENV:Header/><SOAP-ENV:Body><u:GetInfo xmlns:u="urn:dslforum-org:service:WLANConfiguration:1"/></SOAP-ENV:Body></SOAP-ENV:Envelope>
2016-08-21 00:57:30.348 [ERROR] [o.o.b.f.i.FritzboxTr064Binding] - Could not read response from FritzBox. Unauthorized! Check User/PW in config. Create user for tr064 requests
2016-08-21 00:57:30.349 [DEBUG] [o.o.b.f.i.FritzboxTr064Binding] - Releasing connection
2016-08-21 00:57:30.350 [DEBUG] [o.o.b.f.i.FritzboxTr064Binding] - Raw SOAP Response from FritzBox: 
2016-08-21 00:57:30.350 [ERROR] [o.o.b.f.i.FritzboxTr064Binding] - Error retrieving SOAP response from FritzBox
2016-08-21 00:57:30.352 [DEBUG] [o.o.b.f.i.FritzboxTr064Binding] - Raw SOAP Request to be sent to FritzBox: <SOAP-ENV:Envelope xmlns:SOAP-ENV="http://schemas.xmlsoap.org/soap/envelope/"><SOAP-ENV:Header/><SOAP-ENV:Body><u:GetCallList xmlns:u="urn:dslforum-org:service:X_AVM-DE_OnTel:1"><NewDays>5</NewDays></u:GetCallList></SOAP-ENV:Body></SOAP-ENV:Envelope>
2016-08-21 00:57:30.381 [ERROR] [o.o.b.f.i.FritzboxTr064Binding] - Could not read response from FritzBox. Unauthorized! Check User/PW in config. Create user for tr064 requests
2016-08-21 00:57:30.382 [DEBUG] [o.o.b.f.i.FritzboxTr064Binding] - Releasing connection
2016-08-21 00:57:30.383 [DEBUG] [o.o.b.f.i.FritzboxTr064Binding] - Raw SOAP Response from FritzBox: 
2016-08-21 00:57:30.383 [ERROR] [o.o.b.f.i.FritzboxTr064Binding] - Error retrieving SOAP response from FritzBox
2016-08-21 00:57:30.385 [DEBUG] [o.o.b.f.i.FritzboxTr064Binding] - Raw SOAP Request to be sent to FritzBox: <SOAP-ENV:Envelope xmlns:SOAP-ENV="http://schemas.xmlsoap.org/soap/envelope/"><SOAP-ENV:Header/><SOAP-ENV:Body><u:GetExternalIPAddress xmlns:u="urn:dslforum-org:service:WANPPPConnection:1"/></SOAP-ENV:Body></SOAP-ENV:Envelope>

Unfortunately not much more evidence for root cause...