[SOLVED] AVM FRITZ! Binding loses Connection a day after restart OH2.5.0.M3

I had the same problem and I am currently working on a fix in the code. Already running stable for a few days now, I will let you know once I got a clean solution, also because some more testing might be useful.

1 Like

Dear all,

I would like to confirm the above mentioned root cause.

After switching on a detailed logging I was able to isolate it:
My OH is sending multiple requests to my fritzbox
[…]
2020-03-19 00:59:06.325 [DEBUG] [nal.hardware.FritzAhaContentExchange] - response failed: Max requests queued per destination 1024 exceeded for HttpDestination[http://192.168.229.90]@9dbbb,queue=1024,pool=DuplexConnectionPool@1037de4[c=2/2,a=2,i=0]
[…]

After that the Java Errors are starting:
[…]
2020-03-19 00:59:16.388 [DEBUG] [ternal.hardware.FritzAhaWebInterface] - Failed to GET url ‘http://192.168.229.90/login_sid.lua’: java.util.concurrent.RejectedExecutionException: Max requests queued per destination 1024 exceeded for HttpDestination[http://192.168.229.90]@9dbbb,queue=1024,pool=DuplexConnectionPool@1037de4[c=2/2,a=2,i=0]
java.util.concurrent.ExecutionException: java.util.concurrent.RejectedExecutionException: Max requests queued per destination 1024 exceeded for HttpDestination[http://192.168.229.90]@9dbbb,queue=1024,pool=DuplexConnectionPool@1037de4[c=2/2,a=2,i=0]
[…]

My only workaround is to re-start the openHAB service.
After the re-start, all works fine for approx. a day.

My assumption is, that the queue is piling up on outbound OH side.
Are there any tips from you, how to further analyze the problem?

BR
Lars

2 Likes

Hi Lars,
that’s what I observed too, and of course what are the findings of Daniel (@dk.mailbox).

Now my AVM-Binding runs quite fine (OH2.5.2).

In my case the problem was, that I had running a shell-script via Exec-Binding, which tries to get (read) information from a Fritz-NAS-File (Usb-Stick) which gets(write) the information from another RPi, but the Stick was locked by the Fritz-Box after a while (don’t know why-maybe read/write) and after a while the overflow came.

I stopped this Exec-Thing(s) and no more problems came up. Meanwhile I make the data-exchange via MQTT.
Pls. look if you are sending requests to the Fritz-Box with no responses.

I think that the Fritz-Box got the request, but can not answer, so there was an overflow

1 Like

Since I’m still running stable after some adjustments to the code, please contact me via PM if you have the problem described in this thread and want to beta test my solution.
Once tested I will open a pull request for the addon, but it will probably take some weeks until it is included in the next version of OH.

@fibu-freak your theory that the fritz box is somehow overloaded is correct, but in my case i’m not using the exec binding and have no communication with it apart from the AVM binding. Nonetheless, the binding should not break even if the fritz box has one of those slow downs, whatever causes them.

Hi,

I also face regular problems with my AVM Items since some time, even with latest stable OH 2.5.5.1. The AVM binding had worked really fine for me since a long time and was 100% stable in the past. As I did no modify anything within OH in that area for quite some time I could easily affiliate my issues to my latest modification of my home network arrangement. I recently added a fallback LTE internet connection to my home network hardware and now I’m suffering from not responding AVM plugs on a daily basis.

After some testing I understood that all is related to my nightly LTE-router restart which is located in the middle between my FritzBox 7490 (for wired internet + AVM Dect plugs) and the Raspberry PI with OH installed.
So according my analysis the problem starts right after the reboot of that LTE router in the middle. During that 2 minutes reboot OH can not reach the FritzBox.
From that time on OH behaves weird: AVM items are not responding any more. My HUE motion sensor items as well as my HUE Dimmer Switches and Taps do no longer work (no values were updated, related events are no longer triggered) also my rules for opening and closing my zwave rollershutters fail.

So according my experience this 2 minutes communication break between OH AVM Binding and the Fritzbox finally crashes my whole OH environment. After a OH service restart everything is again fine until the next time my Fritzbox is not reachable for just a moment. Could all this be related to that OH outbound issue you mentioned before? Is there a chance to possibly share that workaround?

I would also be happy to support any further analysis or share my data to help to fix this issue.

Regards,
Chris

2 Likes

@khb3bw2
Hey Christoph,

sorry for the late answer. Since you did not mention me, I haven’t received any notification. As I was busy with work for the past months, I wasn’t able to request a merge into the official repo yet but I will do that in the upcoming days. If you are still interested to test my build, feel free to contact me.

@fibu-freak
Can the AVM binding reconnect to the fritzbox when your FB is restarted (in case of freeze oder update). For me the binding (OH 2.5.8/2.5.10/3.0.0M2) stays in a “bad state” which can’t be solved via UI. Only after a restart of the complete openhab instance the FB comes online again.

If it’s working in your environment what did you do to “stabilize” the binding.

Thanks and regards

Sorry I can’t give you a definitive answer what to do tostabilize the Binding. But I just made a test and a restart(Neustart) of my Fritzbox while my openHAB (2.5.10) are running (in Standard Version and in my test-Version with jsr223/Jython)
Here is the logger of my Standard(DSL-Rules)Version when it goes offline and online again:

2020-11-07 14:52:56.244 [WARN ] [pse.smarthome.model.script.Fritz-Box] - Fritz-Box Status hat sich verändert. Status Ist:OFFLINE Detail:COMMUNICATION_ERROR Beschreibung:FRITZ!Box does not respond.
2020-11-07 14:53:16.510 [INFO ] [ome.model.script.sonoff_gLWT_Logging] - Ausgabe-Gerät: ESP8266_Mini-1 LWT-Erreichbarkeit: OFF : esp_mini_01_Unreach IP: 192.168.178.xxx
.....
2020-11-07 14:55:30.528 [WARN ] [pse.smarthome.model.script.Fritz-Box] - Fritz-Box Status hat sich verändert. Status Ist:ONLINE Detail:NONE Beschreibung:null
2020-11-07 14:55:32.001 [INFO ] [ome.model.script.sonoff_gLWT_Logging] - Ausgabe-Gerät: Stehlampe Ereichbarkeit: ON : Sonoff_Pow_02_Unreach IP: 192.168.178.xxx
....

and the logger of my jsr223/jython shows:

2020-11-07 14:52:44.729 [WARN ] [jsr223.ohtest.avm status check      ] - Fritz-Box - Thing Status changed to : OFFLINE (COMMUNICATION_ERROR): FRITZ!Box does not respond., Thing Detail is : OFFLINE  
2020-11-07 14:52:44.745 [WARN ] [jsr223.ohtest.avm status check      ] - Fritz-Box - Thing Status changed to : OFFLINE (COMMUNICATION_ERROR): Request is invalid, Thing Detail is : OFFLINE  
2020-11-07 14:52:59.026 [WARN ] [jsr223.ohtest.avm status check      ] - Fritz-Box - Thing Status changed to : OFFLINE (COMMUNICATION_ERROR): FRITZ!Box does not respond., Thing Detail is : OFFLINE  
2020-11-07 14:53:01.038 [WARN ] [jsr223.ohtest.avm status check      ] - Fritz-Box - Thing Status changed to : OFFLINE (COMMUNICATION_ERROR): Request is invalid, Thing Detail is : OFFLINE  
2020-11-07 14:53:14.035 [WARN ] [jsr223.ohtest.avm status check      ] - Fritz-Box - Thing Status changed to : OFFLINE (COMMUNICATION_ERROR): FRITZ!Box does not respond., Thing Detail is : OFFLINE  
2020-11-07 14:53:16.048 [WARN ] [jsr223.ohtest.avm status check      ] - Fritz-Box - Thing Status changed to : OFFLINE (COMMUNICATION_ERROR): Request is invalid, Thing Detail is : OFFLINE  
2020-11-07 14:53:16.490 [INFO ] [jsr223.ohtest.tasmota LWT monitoring] - Ausgabe-Item: esp_mini_01_Unreach Ausgabe item-Status: OFF Test Item Variable: mega-20191108 
.........
2020-11-07 14:53:29.046 [WARN ] [jsr223.ohtest.avm status check      ] - Fritz-Box - Thing Status changed to : OFFLINE (COMMUNICATION_ERROR): FRITZ!Box does not respond., Thing Detail is : OFFLINE  
2020-11-07 14:53:29.060 [WARN ] [jsr223.ohtest.avm status check      ] - Fritz-Box - Thing Status changed to : OFFLINE (COMMUNICATION_ERROR): Request is invalid, Thing Detail is : OFFLINE  
2020-11-07 14:53:44.041 [WARN ] [jsr223.ohtest.avm status check      ] - Fritz-Box - Thing Status changed to : OFFLINE (COMMUNICATION_ERROR): FRITZ!Box does not respond., Thing Detail is : OFFLINE  
2020-11-07 14:53:44.054 [WARN ] [jsr223.ohtest.avm status check      ] - Fritz-Box - Thing Status changed to : OFFLINE (COMMUNICATION_ERROR): Request is invalid, Thing Detail is : OFFLINE  
2020-11-07 14:53:57.611 [INFO ] [s.internal.handler.ZonePlayerHandler] - UPnP device RINCON_5CAAFD54DF8801400 is absent (thing sonos:PLAY3:RINCON_5CAAFD54DF8801400)
2020-11-07 14:53:57.619 [INFO ] [s.internal.handler.ZonePlayerHandler] - UPnP device RINCON_949F3E157B8401400 is absent (thing sonos:PLAY1:RINCON_949F3E157B8401400)
2020-11-07 14:53:57.625 [INFO ] [s.internal.handler.ZonePlayerHandler] - UPnP device RINCON_5CAAFDC29C0201400 is absent (thing sonos:PLAY1:RINCON_5CAAFDC29C0201400)
2020-11-07 14:53:59.056 [WARN ] [jsr223.ohtest.avm status check      ] - Fritz-Box - Thing Status changed to : OFFLINE (COMMUNICATION_ERROR): FRITZ!Box does not respond., Thing Detail is : OFFLINE  
2020-11-07 14:53:59.069 [WARN ] [jsr223.ohtest.avm status check      ] - Fritz-Box - Thing Status changed to : OFFLINE (COMMUNICATION_ERROR): Request is invalid, Thing Detail is : OFFLINE  
2020-11-07 14:54:14.058 [WARN ] [jsr223.ohtest.avm status check      ] - Fritz-Box - Thing Status changed to : OFFLINE (COMMUNICATION_ERROR): FRITZ!Box does not respond., Thing Detail is : OFFLINE  
2020-11-07 14:54:14.069 [WARN ] [jsr223.ohtest.avm status check      ] - Fritz-Box - Thing Status changed to : OFFLINE (COMMUNICATION_ERROR): Request is invalid, Thing Detail is : OFFLINE  
2020-11-07 14:54:29.060 [WARN ] [jsr223.ohtest.avm status check      ] - Fritz-Box - Thing Status changed to : OFFLINE (COMMUNICATION_ERROR): FRITZ!Box does not respond., Thing Detail is : OFFLINE  
2020-11-07 14:54:29.082 [WARN ] [jsr223.ohtest.avm status check      ] - Fritz-Box - Thing Status changed to : OFFLINE (COMMUNICATION_ERROR): Request is invalid, Thing Detail is : OFFLINE  
2020-11-07 14:54:44.073 [WARN ] [jsr223.ohtest.avm status check      ] - Fritz-Box - Thing Status changed to : OFFLINE (COMMUNICATION_ERROR): FRITZ!Box does not respond., Thing Detail is : OFFLINE  
2020-11-07 14:54:44.091 [WARN ] [jsr223.ohtest.avm status check      ] - Fritz-Box - Thing Status changed to : OFFLINE (COMMUNICATION_ERROR): Request is invalid, Thing Detail is : OFFLINE  
2020-11-07 14:55:01.077 [WARN ] [jsr223.ohtest.avm status check      ] - Fritz-Box - Thing Status changed to : OFFLINE (COMMUNICATION_ERROR): FRITZ!Box does not respond., Thing Detail is : OFFLINE  
2020-11-07 14:55:23.606 [WARN ] [jsr223.ohtest.avm status check      ] - Fritz-Box - Thing Status changed to : OFFLINE (COMMUNICATION_ERROR): Request is invalid, Thing Detail is : OFFLINE  
2020-11-07 14:55:26.362 [WARN ] [jsr223.ohtest.avm status check      ] - Fritz-Box - Thing Status changed to : ONLINE, Thing Detail is : ONLINE  
2020-11-07 14:55:26.386 [WARN ] [jsr223.ohtest.avm status check      ] - Fritz-Box - Thing Status changed to : OFFLINE (COMMUNICATION_ERROR): Request is invalid, Thing Detail is : OFFLINE  
2020-11-07 14:55:27.833 [WARN ] [jsr223.ohtest.avm status check      ] - Fritz-Box - Thing Status changed to : ONLINE, Thing Detail is : ONLINE  
2020-11-07 14:55:28.405 [INFO ] [jsr223.ohtest.tasmota LWT monitoring] - Ausgabe-Item: Sonoff_socket_08_Unreach Ausgabe item-Status: ON Test Item Variable: 8.5.1(tasmota) 
.........

The Log of my jsr223/jython looks a bit different, but shows the same at the very end.

Both Bindings went offline when restarting Fritzbox, and came online again, when Fritz-Box was present again.

I have to say, that I have a little rule to monitor this:

DSL-Version:

rule "Fritz-Box Online Check"

 when
  Thing "avmfritz:fritzbox:7490" changed
 then
   var Status            = getThingStatusInfo("avmfritz:fritzbox:7490").getStatus()
   var StatusDetail      = getThingStatusInfo("avmfritz:fritzbox:7490").getStatusDetail()
   var StatusDescription = getThingStatusInfo("avmfritz:fritzbox:7490").getDescription()
  logWarn ("Fritz-Box","Fritz-Box Status hat sich verändert. Status Ist:{} Detail:{} Beschreibung:{}", Status, StatusDetail, StatusDescription)
end

Jython-Version:

from core.rules import rule
from core.triggers import when

@rule("avm status check", description="monitoring AVM-Thing Status", tags=["monitor", "status", "avm"])
@when("Thing avmfritz:fritzbox:7490 changed")  # not installed yet
#@when("Thing exec:command:cpu_temp changed") # test

def avm_monitor(event):
    '''
    #
     Monitoring AVM-Binding Thing-Status
     Überwachung der AVM-Bridge auf Unregelmässigkeiten (offline, terminated, etc.)
     Monitoring AVM-Bridge for failures (offline, terminated, etc.)
     '''
    status = event.getStatusInfo().getStatus().toString()
    avm_monitor.log.warn(u"Fritz-Box - Thing Status changed to : {}, Thing Detail is : {}  ".format(event.getStatusInfo(), status))
#----------------------------------------------------------------------------------------------------------------------------------

I have a OH3-Pi running too for testing and tinkering, but no AVM-Binding installed yet.

Just a silly question from my side. We are talking about this binding:

Maybe there are other purposes which causes your errors.
What about the time-differences between freeze and restart (Minutes, Hours,…)?
Do you have freezes or updates often ?
How is your AVM-Thing installed ? By PaperUI or as textual Thing ?
Maybe we find a solution if we make a deeper dive in your configuration

Cheers,
Peter

@fibu-freak
Hey Peter,

thank you very much for your detailed response - I really appreciate it.

Concerning your questions:

Your screenshot shows the binding I experience trouble with. In contrast to your configuration I do use a FritzBox 7590. Freezes and updates are maybe once or twice a month but that makes it problematic as I do realize it very late - often too late. :wink: All things are present in a file, but approved from PaperUI INBOX after the first start.

At the moment I’m concentrating on OH 3.0.0 M2 as it seems to be stable for me except the binding function, but with the same behaviour like the 2.5.x-iterations. I’m running OH in a docker container on my synology disk station DS 220+.

Today I have been experiencing a very weird behaviour:
When running the debian docker container and setting the log level for org.openhab.binding.avmfritz explicitly to TRACE/DEBUG - I have no “reconnect problems”. When I change to “DEFAULT” (the entry from log:list disappears) the problem persists. When setting back to TRACE/DEBUG it seems to be working again.

(Maybe the change of the log level made it stable for your too.)

Thanks and regards,
B

If there are often freezes and updates in your Fritzbox, I think the problem is not on the OH-Side but on the Fritz-Box. Are you using other features on the Fritz-Box, e.g NAS or Data-Exchange via Fritz-Box-USB ?

A USB-Stick in the Fritz-Box was my Problem, which I used to send information from one Pi to another.

What updates are made in the Fritz-Box ? My last Firmware-Update was, I believe, a year ago (Firmware 7.12.) and it was not automatic, but under my control.

Have you tried to set the log-level to “info” ? Mine is in that state (never was “default”, only “info, trace and debug”

openhab> log:list | grep -i avm
org.openhab.binding.avmfritz                       x INFO
openhab> bundle:list -s |grep -i avm
241 x Active x  80 x 2.5.10                  x org.openhab.binding.avmfritz
openhab>

I have to say that my OH is running not in Docker-Containers, but in RasPis (Pi4/4Gb, Pi4/2Gb and Pi3b+)

If you don’t want to see your AVM-Thing in the INBOX you can add this line to your runtime.cfg

#
# AVM Parameterset by Peter 06.12.2019
discovery.avmfritz:background=false

This is not from me :wink:, but you can read it in Binding-Docs

Cheers,
Peter

Hi Peter,

thank you for your response.

Concerning FB Updates: Maybe the frequency was above average because of the 7.20 and 7.21 rollouts in the last months. In contrary to my 7490 the 7590 runs perfectly stable - with USB/NAS and UPNP deactivated.

Thanks for the background scan hint. :wink:

Yesterday I did create two rules watching my AVM and Harmony bindings and sending an e-mail in case of some states. So I should get a better feeling for the issue.

At the moment I do not use security relevant home automation components so nothing really happens when the FireTV power outlet does not turn on after remote action, but I want to expand my home network and thats why I do prioritize stability (for some rare cases too) over functions.

Regards

I hope that e-mail will reach you :innocent:, if Fritz-Box goes down, even I can’t believe :wink:

:rofl: Indeed I checked that case yesterday because I had doubts too… :wink: But it was working because of the state change after the reboot. As the FB runs stable at the moment it’s more likely that the connection breaks down due to other reasons and these should be covered too. Otherwise I will have a look into my (additionally created) log entries. I’m curious about it. :wink:

Hi all, I have the same issue with increasing criticality. The binding-avmfritz - 2.5.10 never was totally stable. I had connection losses every couple of weeks or months which always required a restart of openhab to re-establish the connection once again.
In most cases the connection drop was in context of a fritz.box restart for whatever reason. So far so good, not the best solution but somehow manageable.

I think, the main problem is the implementation of authentication of openhab at the fritz.box. It asks only once at openhab startup for a session ID and tries to maintain that ID for the never ending future. In case this session ID ist dropped by the fritz.box due to a restart or due to security protection meassures, the openhab-binding is not able to ask for a new session ID but instead insists on the old one. This leads to the non-recoverable disconnects.

In my case, during the last two weeks the situation became much worse: Unpredictable disconnects after about 12 hours. The binding was useless and the log was flooded with red lines.

After long and crazy investigations I discovered one configuration issue in my fritz.box. The hint was coming from @fibu-freak. Thanks!
Long time ago a had an USB-stick connected to the fritz box for some experiments which was removed before I installed openhab with the binding. But there was one hidden leftover in the fritz.box from that time: I had configured a (Telekom-)cloud access for the fritz box mirroring the content of that USB stick to the cloud. After removing the stick this was obsolete but the configuration of the cloud-link was still there and maybe the box desperately tried to mirror something in the background. In addition, the configuration settings for the cloud access were invisible in the menu after unplugging the stick. It only said “USB stick missing”. After yesterday plugging in a USB stick again, I discovered the whole issue. After cleaning up the config-mess (no stick, no cloud config), I hope to end up with a stable fritz-binding and peaceful Xmas days.

Big thanks for the community here for guiding me to the right direction!

1 Like

:pray: :+1: :crossed_fingers:

Now more than 36h up and running. :grinning:
For me it is proven that the USB-Stick at the fritz-box and related services (cloud connection) may neagtively influence the fritzbox-binding.

Hi,

I have to intervene here. That is not true. The binding tries to reauthorization before each request. If you identified an issue in the code regarding this approach please point me to the lines of code. I really like to discuss a better solution than the current implementation. Thanks for your help.

Christoph

1 Like

Hi Christoph,
the one and only thing I can see (or better what I’m missing) in the code, is the missing handling of the value “BlockTime” from the answer to login_sid.lua request. This can lead into re-connecting trouble, but not sure if this is an issue here.
I run a little JS rule which in parallel holds a connection to the fritzbox since a few days. From first glance it looks more stable then the binding connection but that can be random.

Br,
Stefan

PS: I’m running OH3 stable at the moment but my problems with fritzbox connection starts approx. after upgrade from 2.4 to 2.5 (not sure if this is from the upgrade or maybe also from a fritzbox FW upgrade in this period).

Yes, you got a point here. The binding does ignore the “BlockTime”. We might add an improvement for it some day.

In general I am thinking about a complete refactoring of the binding as the implementation of communication between binding and FRITZ!Box is kind of clumsy these days. There is a lot of potential to reduce the number of lines of code by switching to a modern approach. But as you know - time is limited …

Yes you are right, time is limited :wink: From first look it is maybe the best to handle the authentication in a kind of monitoring thread (like it is done for the CallMonitor) but to oversee any side-effects is not easy.
Btw. there is a github issue now …

Br,
Stefan