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

fibu-freak · February 4, 2020, 2:57pm

Mine is running now stable without any breaks.

Do you still have the fritz-NAS mounted to your system ? Or do you have more than one OH-System communicating with the fritz-box ?

dk.mailbox · February 4, 2020, 2:59pm

No and no - nothing complicated…

fibu-freak · February 4, 2020, 3:03pm

That’s weird …!!!

dk.mailbox · February 23, 2020, 9:10am

Maybe last act in the saga, for me (but we’ll see): had to upgrade to a 7530 now, because of getting faster DSL. Put the new box in yesterday, no problems so far but let’s see how that develops.

fibu-freak · February 23, 2020, 7:11pm

That’s good news. At the moment I see problems with avm-binding and the exec-binding (with whitelist) in OH-Version 2.5.2.
As I only have two scripts running with the Exec-Binding I stopped it and problems were gone. I try to find another way to get the information I former got from Exec-Scripts (MQTT2 or REST).

I keep fingers crossed for you.

charlyx · February 24, 2020, 8:37pm

For the 2.5.2-EXEC-Binding-whitelist problem there is a interim fix available: EXEC-Binding errors after update to Openhab2 2.5.2-1
after 24h 2.5.2 up I still have the said problem with 7590.

fibu-freak · February 25, 2020, 10:32pm

After restarting the Pi twice or three times the errors with AVM were gone. As a workaround I saved the “exec.whiteliste” file after the restart and everything works fine now.

Logger:

2020-02-24 22:32:59.979 [WARN ] [pse.smarthome.model.script.Fritz-Box] - Fritz-Box Status hat sich verändert. Status Ist:INITIALIZING Detail:NONE Beschreibung:null
2020-02-24 22:33:00.981 [WARN ] [pse.smarthome.model.script.Fritz-Box] - Fritz-Box Status hat sich verändert. Status Ist:ONLINE Detail:NONE Beschreibung:Established FRITZ!Box connection with SID 88cd139c81d5ac33
2020-02-24 22:33:10.328 [INFO ] [.transport.mqtt.MqttBrokerConnection] - Starting MQTT broker connection to 'localhost' with clientid OH2_hans
2020-02-24 22:33:10.364 [WARN ] [ng.exec.internal.handler.ExecHandler] - Tried to execute '/bin/bash /etc/openhab2/scripts/test.sh', but it is not contained in whitelist.
2020-02-24 22:33:10.404 [WARN ] [ng.exec.internal.handler.ExecHandler] - Tried to execute '/bin/bash /etc/openhab2/scripts/cpu_temp.sh', but it is not contained in whitelist.
2020-02-24 22:33:13.417 [INFO ] [ui.habmin.internal.servlet.HABminApp] - Started HABmin servlet at /habmin
2020-02-24 22:33:13.598 [INFO ] [panel.internal.HABPanelDashboardTile] - Started HABPanel at /habpanel
2020-02-24 22:33:13.721 [INFO ] [openhab.ui.paper.internal.PaperUIApp] - Started Paper UI at /paperui
2020-02-24 22:33:31.040 [INFO ] [smarthome.model.script.sonoff_status] - Timer wird initialisiert null
2020-02-24 22:35:01.086 [INFO ] [smarthome.model.script.sonoff_status] - Device Id : sonoffs Command published
2020-02-24 22:35:01.093 [INFO ] [smarthome.model.script.sonoff_status] - Timer tSonoffState ist abgearbeitet und wird wieder auf "null" gesetzt: null

Restarted OH2 yesterday evening and as you can see, Fritz-Box started and is online and whitelist warned one time.

BTW: I know about the interim-fix, but I will wait 'til OH2.5.3 is online. For the moment I use the other “trick” with the “resave” of the whitelist-file. It takes a second and under normal circumstances it takes a longer period to restart openHAB

Marlow · March 9, 2020, 6:22pm

Merging OH2 AVM Fritz! and OH1 TR064 into one binding would be sweet. I’d say most that try to get the most out of their Fritz!box are using both.

/M

AlexKay · March 13, 2020, 8:55am

I face the same problem, too.
Deleting an creating a new avmfritz thing with a new name did not help.
It’s very annoying and I would love to see a sign towards a solution…

Do you still have the problem, too?

fibu-freak · March 13, 2020, 11:49pm

No more problems with my AVMFritz-Binding. Everything is working fine (Knock on wood).

mic007 · March 15, 2020, 3:05pm

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.

Seppel_Seppelhut · March 19, 2020, 7:11am

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

fibu-freak · March 19, 2020, 9:30am

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

mic007 · March 27, 2020, 2:59pm

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.

khb3bw2 · June 1, 2020, 5:49pm

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

mic007 · August 1, 2020, 9:26am

@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.

Bushido · November 7, 2020, 8:30am

@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

fibu-freak · November 7, 2020, 2:46pm

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

Bushido · November 7, 2020, 4:25pm

@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. 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

fibu-freak · November 7, 2020, 7:45pm

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 , but you can read it in Binding-Docs

Cheers,
Peter