Avmfritz loses connection after 2 days

thesummer · January 24, 2019, 8:33pm

Hi,

after around 2 days openhab loses the connection to my fritzbox using the avmfritz binding.
Then in the log I get error messages every 15 s.
I turned on debug level for the binding and got the following:

2019-01-24 21:24:40.165 [hingStatusInfoChangedEvent] - 'avmfritz:fritzbox:ef9daf9e' changed from OFFLINE (COMMUNICATION_ERROR): Request is invalid to ONLINE: Resuming FRITZ!Box connection with SID a51030855403d401
2019-01-24 21:24:40.168 [hingStatusInfoChangedEvent] - 'avmfritz:Comet_DECT:ef9daf9e:119600737984' changed from OFFLINE (BRIDGE_OFFLINE) to ONLINE
2019-01-24 21:24:40.169 [DEBUG] [nal.hardware.FritzAhaContentExchange] - Max requests per destination 1024 exceeded for HttpDestination[http://192.168.178.1]@17d7cdf,queue=1024,pool=DuplexConnectionPool[c=2/2,a=2,i=0]
2019-01-24 21:24:40.173 [DEBUG] [nal.hardware.FritzAhaContentExchange] - Max requests per destination 1024 exceeded for HttpDestination[http://192.168.178.1]@17d7cdf,queue=1024,pool=DuplexConnectionPool[c=2/2,a=2,i=0]
2019-01-24 21:24:40.176 [hingStatusInfoChangedEvent] - 'avmfritz:Comet_DECT:ef9daf9e:119590394120' changed from OFFLINE (BRIDGE_OFFLINE) to ONLINE
2019-01-24 21:24:40.178 [DEBUG] [nal.hardware.FritzAhaContentExchange] - response complete: null
2019-01-24 21:24:40.181 [DEBUG] [.callbacks.FritzAhaDiscoveryCallback] - request is invalid: 0
2019-01-24 21:24:40.184 [DEBUG] [ternal.hardware.FritzAhaWebInterface] - GETting URL http://192.168.178.1/webservices/homeautoswitch.lua?switchcmd=getdevicelistinfos&sid=a51030855403d401
2019-01-24 21:24:40.187 [DEBUG] [.callbacks.FritzAhaDiscoveryCallback] - request is invalid: 0
2019-01-24 21:24:40.190 [DEBUG] [ternal.hardware.FritzAhaWebInterface] - GETting URL http://192.168.178.1/webservices/homeautoswitch.lua?switchcmd=getdevicelistinfos&sid=a51030855403d401
2019-01-24 21:24:43.593 [DEBUG] [tz.handler.AVMFritzBaseBridgeHandler] - polling FRITZ!Box avmfritz:fritzbox:ef9daf9e
2019-01-24 21:24:43.598 [DEBUG] [nal.hardware.FritzAhaContentExchange] - Max requests per destination 1024 exceeded for HttpDestination[http://192.168.178.1]@17d7cdf,queue=1024,pool=DuplexConnectionPool[c=2/2,a=2,i=0]
2019-01-24 21:24:43.601 [DEBUG] [nal.hardware.FritzAhaContentExchange] - Max requests per destination 1024 exceeded for HttpDestination[http://192.168.178.1]@17d7cdf,queue=1024,pool=DuplexConnectionPool[c=2/2,a=2,i=0]
2019-01-24 21:24:43.603 [DEBUG] [nal.hardware.FritzAhaContentExchange] - response complete: null
2019-01-24 21:24:43.937 [DEBUG] [ternal.hardware.FritzAhaWebInterface] - response complete: <?xml version="1.0" encoding="utf-8"?><SessionInfo><SID>a51030855403d401</SID><Challenge>728224ba</Challenge><BlockTime>0</BlockTime><Rights><Name>HomeAuto</Name><Access>2</Access></Rights></SessionInfo>
2019-01-24 21:24:43.944 [DEBUG] [nal.hardware.FritzAhaContentExchange] - Max requests per destination 1024 exceeded for HttpDestination[http://192.168.178.1]@17d7cdf,queue=1024,pool=DuplexConnectionPool[c=2/2,a=2,i=0]
2019-01-24 21:24:43.947 [DEBUG] [nal.hardware.FritzAhaContentExchange] - Max requests per destination 1024 exceeded for HttpDestination[http://192.168.178.1]@17d7cdf,queue=1024,pool=DuplexConnectionPool[c=2/2,a=2,i=0]
2019-01-24 21:24:43.950 [DEBUG] [nal.hardware.FritzAhaContentExchange] - response complete: null
2019-01-24 21:24:43.952 [DEBUG] [.callbacks.FritzAhaUpdateXmlCallback] - request is invalid: 0
2019-01-24 21:24:43.958 [DEBUG] [ternal.hardware.FritzAhaWebInterface] - GETting URL http://192.168.178.1/webservices/homeautoswitch.lua?switchcmd=getdevicelistinfos&sid=a51030855403d401
2019-01-24 21:24:43.963 [hingStatusInfoChangedEvent] - 'avmfritz:fritzbox:ef9daf9e' changed from ONLINE: Resuming FRITZ!Box connection with SID a51030855403d401 to OFFLINE (COMMUNICATION_ERROR): Request is invalid
2019-01-24 21:24:43.964 [DEBUG] [.callbacks.FritzAhaUpdateXmlCallback] - request is invalid: 0
2019-01-24 21:24:43.968 [DEBUG] [ternal.hardware.FritzAhaWebInterface] - GETting URL http://192.168.178.1/webservices/homeautoswitch.lua?switchcmd=getdevicelistinfos&sid=a51030855403d401
2019-01-24 21:24:43.969 [hingStatusInfoChangedEvent] - 'avmfritz:Comet_DECT:ef9daf9e:119590394120' changed from ONLINE to OFFLINE (BRIDGE_OFFLINE)
2019-01-24 21:24:43.975 [hingStatusInfoChangedEvent] - 'avmfritz:Comet_DECT:ef9daf9e:119600737984' changed from ONLINE to OFFLINE (BRIDGE_OFFLINE)
2019-01-24 21:24:58.972 [DEBUG] [tz.handler.AVMFritzBaseBridgeHandler] - polling FRITZ!Box avmfritz:fritzbox:ef9daf9e
2019-01-24 21:24:58.977 [DEBUG] [nal.hardware.FritzAhaContentExchange] - Max requests per destination 1024 exceeded for HttpDestination[http://192.168.178.1]@17d7cdf,queue=1024,pool=DuplexConnectionPool[c=2/2,a=2,i=0]
2019-01-24 21:24:58.980 [DEBUG] [nal.hardware.FritzAhaContentExchange] - Max requests per destination 1024 exceeded for HttpDestination[http://192.168.178.1]@17d7cdf,queue=1024,pool=DuplexConnectionPool[c=2/2,a=2,i=0]
2019-01-24 21:24:58.983 [DEBUG] [nal.hardware.FritzAhaContentExchange] - response complete: null
2019-01-24 21:24:59.317 [DEBUG] [ternal.hardware.FritzAhaWebInterface] - response complete: <?xml version="1.0" encoding="utf-8"?><SessionInfo><SID>a51030855403d401</SID><Challenge>a4a1945a</Challenge><BlockTime>0</BlockTime><Rights><Name>HomeAuto</Name><Access>2</Access></Rights></SessionInfo>
2019-01-24 21:24:59.324 [hingStatusInfoChangedEvent] - 'avmfritz:fritzbox:ef9daf9e' changed from OFFLINE (COMMUNICATION_ERROR): Request is invalid to ONLINE: Resuming FRITZ!Box connection with SID a51030855403d401

Looks like the http connection to the fritzbox gets blocked somehow and then a waiting queue fills until it is full.
Has someone else experienced this?
Is there maybe a way to reset the connection to the fritzbox from within a rule?

Platform information:
- Hardware: Raspberry 3
- OS: Raspbian
- openHAB version: 2.3.0 (in docker container)

thesummer · February 4, 2019, 7:04pm

I updated now to openhab 2.4.0 hoping that this might fix the issue.
However, the log messages change slightly, but the issue stays the same:

2019-02-04 19:56:28.692 [hingStatusInfoChangedEvent] - 'avmfritz:fritzbox:ef9daf9e' changed from OFFLINE (COMMUNICATION_ERROR): FRITZ!Box does not respond to OFFLINE (COMMUNICATION_ERROR): Request is invalid
2019-02-04 19:56:43.692 [DEBUG] [al.handler.AVMFritzBaseBridgeHandler] - polling FRITZ!Box avmfritz:fritzbox:ef9daf9e
2019-02-04 19:56:43.697 [DEBUG] [nal.hardware.FritzAhaContentExchange] - Max requests queued per destination 1024 exceeded for HttpDestination[http://192.168.178.1]@4d7506,queue=1024,pool=DuplexConnectionPool@c93c74[c=2/2,a=2,i=0]
2019-02-04 19:56:43.700 [DEBUG] [nal.hardware.FritzAhaContentExchange] - Max requests queued per destination 1024 exceeded for HttpDestination[http://192.168.178.1]@4d7506,queue=1024,pool=DuplexConnectionPool@c93c74[c=2/2,a=2,i=0]
2019-02-04 19:56:43.702 [DEBUG] [nal.hardware.FritzAhaContentExchange] - response complete: null
2019-02-04 19:56:43.707 [DEBUG] [ternal.hardware.FritzAhaWebInterface] - Failed to GET url 'http://192.168.178.1/login_sid.lua?sid=9a8274cd6525ced3': &#160;
==&gt; /var/lib/docker/volumes/iot_openhab-userdata/_data/logs/events.log &lt;==
2019-02-04 19:56:43.791 [hingStatusInfoChangedEvent] - 'avmfritz:fritzbox:ef9daf9e' changed from OFFLINE (COMMUNICATION_ERROR): Request is invalid to OFFLINE (COMMUNICATION_ERROR): FRITZ!Box does not respond
==&gt; /var/lib/docker/volumes/iot_openhab-userdata/_data/logs/openhab.log &lt;==
2019-02-04 19:56:43.792 [DEBUG] [nal.hardware.FritzAhaContentExchange] - Max requests queued per destination 1024 exceeded for HttpDestination[http://192.168.178.1]@4d7506,queue=1024,pool=DuplexConnectionPool@c93c74[c=2/2,a=2,i=0]
2019-02-04 19:56:43.794 [DEBUG] [nal.hardware.FritzAhaContentExchange] - Max requests queued per destination 1024 exceeded for HttpDestination[http://192.168.178.1]@4d7506,queue=1024,pool=DuplexConnectionPool@c93c74[c=2/2,a=2,i=0]
2019-02-04 19:56:43.796 [DEBUG] [nal.hardware.FritzAhaContentExchange] - response complete: null
2019-02-04 19:56:43.798 [DEBUG] [.callbacks.FritzAhaUpdateXmlCallback] - request is invalid: 0
2019-02-04 19:56:43.802 [DEBUG] [.callbacks.FritzAhaUpdateXmlCallback] - request is invalid: 0
==&gt; /var/lib/docker/volumes/iot_openhab-userdata/_data/logs/events.log &lt;==
2019-02-04 19:56:43.812 [hingStatusInfoChangedEvent] - 'avmfritz:fritzbox:ef9daf9e' changed from OFFLINE (COMMUNICATION_ERROR): FRITZ!Box does not respond to OFFLINE (COMMUNICATION_ERROR): Request is invalid
==&gt; /var/lib/docker/volumes/iot_openhab-userdata/_data/logs/openhab.log &lt;==
2019-02-04 19:56:58.805 [DEBUG] [al.handler.AVMFritzBaseBridgeHandler] - polling FRITZ!Box avmfritz:fritzbox:ef9daf9e
2019-02-04 19:56:58.813 [DEBUG] [nal.hardware.FritzAhaContentExchange] - Max requests queued per destination 1024 exceeded for HttpDestination[http://192.168.178.1]@4d7506,queue=1024,pool=DuplexConnectionPool@c93c74[c=2/2,a=2,i=0]
2019-02-04 19:56:58.815 [DEBUG] [nal.hardware.FritzAhaContentExchange] - Max requests queued per destination 1024 exceeded for HttpDestination[http://192.168.178.1]@4d7506,queue=1024,pool=DuplexConnectionPool@c93c74[c=2/2,a=2,i=0]
2019-02-04 19:56:58.818 [DEBUG] [nal.hardware.FritzAhaContentExchange] - response complete: null
2019-02-04 19:56:58.823 [DEBUG] [ternal.hardware.FritzAhaWebInterface] - Failed to GET url 'http://192.168.178.1/login_sid.lua?sid=9a8274cd6525ced3': &#160;
==&gt; /var/lib/docker/volumes/iot_openhab-userdata/_data/logs/events.log &lt;==
2019-02-04 19:56:58.949 [hingStatusInfoChangedEvent] - 'avmfritz:fritzbox:ef9daf9e' changed from OFFLINE (COMMUNICATION_ERROR): Request is invalid to OFFLINE (COMMUNICATION_ERROR): FRITZ!Box does not respond
==&gt; /var/lib/docker/volumes/iot_openhab-userdata/_data/logs/openhab.log &lt;==
2019-02-04 19:56:58.953 [DEBUG] [nal.hardware.FritzAhaContentExchange] - Max requests queued per destination 1024 exceeded for HttpDestination[http://192.168.178.1]@4d7506,queue=1024,pool=DuplexConnectionPool@c93c74[c=2/2,a=2,i=0]
2019-02-04 19:56:58.957 [DEBUG] [nal.hardware.FritzAhaContentExchange] - Max requests queued per destination 1024 exceeded for HttpDestination[http://192.168.178.1]@4d7506,queue=1024,pool=DuplexConnectionPool@c93c74[c=2/2,a=2,i=0]
2019-02-04 19:56:58.960 [DEBUG] [nal.hardware.FritzAhaContentExchange] - response complete: null
2019-02-04 19:56:58.965 [DEBUG] [.callbacks.FritzAhaUpdateXmlCallback] - request is invalid: 0
2019-02-04 19:56:58.973 [DEBUG] [.callbacks.FritzAhaUpdateXmlCallback] - request is invalid: 0
==&gt; /var/lib/docker/volumes/iot_openhab-userdata/_data/logs/events.log &lt;==
2019-02-04 19:56:58.980 [hingStatusInfoChangedEvent] - 'avmfritz:fritzbox:ef9daf9e' changed from OFFLINE (COMMUNICATION_ERROR): FRITZ!Box does not respond to OFFLINE (COMMUNICATION_ERROR): Request is invalid

HomeAutomation · February 4, 2019, 7:36pm

Same here.

cweitkamp · February 4, 2019, 8:46pm

Hi all,

We have a similar topic here, I am working on a solution:

thesummer · February 4, 2019, 9:02pm

Hi Christoph,

Thank you very much.
I subscribed to the ticket at github now.
If you need some beta testing for a patch of similar, just let me know.