[avmfritz] Fritzbox looses connection after update to fritz!os 7.56

[tobiloeb]

I am using a Fritz!Box 7490 and everything worked fine until I updated to the new Fritz!OS Version 7.56. Now the Fritzbox looses the connection after ~ 12-24 hours.

I tried to remove all avmfritz Things and recreate all of them. But the problem still occurs. :(

When I restart the openhab docker container, Openhab can connect successfull to the fritzbox. But after some hours the fritzbox get an error.

Expected Behavior

avmfritz binding works all the time and not only a few hours after reboot of openhab.

Current Behavior

Openhab looses the connection to the Fritzbox but I couldn't find any errors in the log files. I changed the Loglevel to DEBUG for the avmfritz binding and currently waiting for the next error. The connection via tr064 is working fine and works without errors. Just the avmfritz binding looses the connection.

Possible Solution

Steps to Reproduce (for Bugs)

Just add a fritzbox thing with Version 7.56 installed. After some time it gets errors.

Context

Your Environment

Raspi4 4GB Docker container for openhab, zigbee2mqtt, mosquitto Openhab version 3.4.4 Fritzbox is connected via avmfritz and tr064 - just avmfritz binding fails

Maybe someone else have same issues or any ideas?

[peter12311]

Same Problem here, similar environment: Raspi4/4G with Docker, OH4.00, FritzBox 7590 with 7.56 Firmware. Restarting the Container helps for some time, restart of the fritzBox doesn't help, restarting only the bridge thing OH also doesn't help, so does changing between HTTP and HTTPS. A telnet connection to the Box always works. Is there a way to get some helpful logs to track this down? Maybe someone can give me a hint.

[tobiloeb]

Hi, thanks, so I am not the only one with this issue. I configured the log Level to Debug on my instance and hope to see more infos when the connection get lost next time. My feeling is, that something changed with the Sessions. I will dig into the Code this evening and write an update.

@peter12311 you can go the the console with: docker exec -it openhab /openhab/runtime/bin/client Default Password: habopen

Then enter: log:set DEBUG org.openhab.binding.avmfritz With log:get you can See all log Level configurations.

[ansorg]

Openhab version 3.4.4

in the debug log I find

2023-09-05 07:26:38.201 [DEBUG] [are.callbacks.FritzAhaUpdateCallback] - request is invalid: 403
2023-09-05 07:26:43.789 [DEBUG] [al.handler.AVMFritzBaseBridgeHandler] - Poll FRITZ!Box for updates avmfritz:fritzbox:192_168_178_109
2023-09-05 07:26:44.272 [DEBUG] [ternal.hardware.FritzAhaWebInterface] - GET response complete: <?xml version="1.0" encoding="utf-8"?><SessionInfo><SID>0000000000000000</SID><Challenge>f6dfbff6</Challenge><BlockTime>0</BlockTime><Rights></Rights><Users><User>a</User><User>b</User><User last="1">c</User></Users></SessionInfo>

2023-09-05 07:26:46.274 [DEBUG] [ternal.hardware.FritzAhaWebInterface] - GET response failed: Total timeout 2000 ms elapsed
java.util.concurrent.TimeoutException: Total timeout 2000 ms elapsed
	at org.eclipse.jetty.client.HttpConnection$RequestTimeouts.onExpired(HttpConnection.java:334) ~[?:?]
	at org.eclipse.jetty.client.HttpConnection$RequestTimeouts.onExpired(HttpConnection.java:314) ~[?:?]
	at org.eclipse.jetty.io.CyclicTimeouts.onTimeoutExpired(CyclicTimeouts.java:110) ~[?:?]
	at org.eclipse.jetty.io.CyclicTimeouts.access$100(CyclicTimeouts.java:50) ~[?:?]
	at org.eclipse.jetty.io.CyclicTimeouts$Timeouts.onTimeoutExpired(CyclicTimeouts.java:196) ~[?:?]
	at org.eclipse.jetty.io.CyclicTimeout$Wakeup.run(CyclicTimeout.java:298) ~[?:?]
	at java.util.concurrent.Executors$RunnableAdapter.call(Executors.java:515) [?:?]
	at java.util.concurrent.FutureTask.run(FutureTask.java:264) [?:?]
	at java.util.concurrent.ScheduledThreadPoolExecutor$ScheduledFutureTask.run(ScheduledThreadPoolExecutor.java:304) [?:?]
	at java.util.concurrent.ThreadPoolExecutor.runWorker(ThreadPoolExecutor.java:1128) [?:?]
	at java.util.concurrent.ThreadPoolExecutor$Worker.run(ThreadPoolExecutor.java:628) [?:?]
	at java.lang.Thread.run(Thread.java:829) [?:?]
2023-09-05 07:26:47.158 [DEBUG] [nal.hardware.FritzAhaContentExchange] - HTTPS response: 403
2023-09-05 07:26:47.159 [DEBUG] [nal.hardware.FritzAhaContentExchange] - HTTPS response: 403
2023-09-05 07:26:47.160 [DEBUG] [nal.hardware.FritzAhaContentExchange] - GET response complete: null

[Selters]

Probably the same issue here ...

tonight an automatic update was installed on my Fritzbox 7490. Now I have FRITZ!OS version 7.57. Since then the PushService "Change notice sending on selected events or setting changes" of the FB triggers constantly with the message: Login on 09/05/2023 at 09:57 by user "openha" to your FRITZ!Box 7490 from your home network device openhabian3 (IP address XXXXXX).

In addition, in the OH Log appears continuously:

[INFO ] [ab.event.ThingStatusInfoChangedEvent] - Thing 'avmfritz:fritzbox:1' changed from OFFLINE (COMMUNICATION_ERROR): Request is invalid to OFFLINE (COMMUNICATION_ERROR): FRITZ!Box does not respond.

[INFO ] [ab.event.ThingStatusInfoChangedEvent] - Thing 'avmfritz:fritzbox:1' changed from OFFLINE (COMMUNICATION_ERROR): FRITZ!Box does not respond. to OFFLINE (COMMUNICATION_ERROR): Request is invalid

I have already restarted Fritzbox and Openhab.Service - without success.

I am running openHAB 3.2.0 - Release Build; with the "old" FRITZ!OS version 7.29 I did not have these problems.

[lochmueller]

I also update from 7.29 to 7.57 because there is a critical security issue. Same problem described by @Selters . My OH version is the current one: 4.0.2. Also, same entries in the log. What can I do to support someone to solve this problem?

Regards, Tim

[Selters]

@lochmueller is your FB Pushservice also affected?

[lochmueller]

@Selters My bridge is completely offline. So there are no push information (incoming calls) at all.

[Selters]

@lochmueller No, this is a misunderstanding. I meant the PushService of the Fritzbox (System/PushService): "Änderungsnotiz Zusendung bei ausgewählten Ereignissen oder Einstellungsänderungen."

[lochmueller]

@Selters No I do not use this feature.

[lochmueller]

Hmm... upgrade to OH 4.0.3 looks good for me :) But there are no AVM/Fritz related changes in the logs. Perhaps it was another problem?!? Could you confirm the problem is solved after the upgrade?

[rayb67]

Hmm... upgrade to OH 4.0.3 looks good for me :) But there are no AVM/Fritz related changes in the logs. Perhaps it was another problem?!? Could you confirm the problem is solved after the upgrade?

No, the problem still exist.

[lochmueller]

You are right. The Thing is online, but no events at all.

[tobiloeb]

The problem is still there, but since I activated the DEBUG Log for org.openhab.bundle.avmfritz, the issue is gone or less often. I don't know why and the heating season is coming. I am using avmfritz to control the heating. So it would be nice to get this issue fixed soon. My Stacktrace from yesterday: 2023-09-19 08:57:20.397 [DEBUG] [al.handler.AVMFritzBaseBridgeHandler] - Poll FRITZ!Box for updates avmfritz:fritzbox:3ef43737b7 at org.openhab.binding.avmfritz.internal.hardware.FritzAhaWebInterface.syncGet(FritzAhaWebInterface.java:247) ~[?:?] at org.openhab.binding.avmfritz.internal.hardware.FritzAhaWebInterface.authenticate(FritzAhaWebInterface.java:105) ~[?:?] at org.openhab.binding.avmfritz.internal.hardware.FritzAhaWebInterface.asyncGet(FritzAhaWebInterface.java:270) ~[?:?] at org.openhab.binding.avmfritz.internal.hardware.FritzAhaWebInterface.asyncGet(FritzAhaWebInterface.java:279) ~[?:?] at org.openhab.binding.avmfritz.internal.handler.AVMFritzBaseBridgeHandler.poll(AVMFritzBaseBridgeHandler.java:231) ~[?:?] at org.openhab.binding.avmfritz.internal.hardware.FritzAhaWebInterface.syncGet(FritzAhaWebInterface.java:247) ~[?:?] at org.openhab.binding.avmfritz.internal.hardware.FritzAhaWebInterface.authenticate(FritzAhaWebInterface.java:105) ~[?:?] at org.openhab.binding.avmfritz.internal.hardware.callbacks.FritzAhaReauthCallback.execute(FritzAhaReauthCallback.java:103) ~[?:?] at org.openhab.binding.avmfritz.internal.hardware.callbacks.FritzAhaUpdateCallback.execute(FritzAhaUpdateCallback.java:65) ~[?:?] at org.openhab.binding.avmfritz.internal.hardware.FritzAhaContentExchange.onComplete(FritzAhaContentExchange.java:67) ~[?:?] 2023-09-19 08:59:17.699 [DEBUG] [al.handler.AVMFritzBaseBridgeHandler] - Poll FRITZ!Box for updates avmfritz:fritzbox:3ef43737b7 at org.openhab.binding.avmfritz.internal.hardware.FritzAhaWebInterface.syncGet(FritzAhaWebInterface.java:247) ~[?:?] at org.openhab.binding.avmfritz.internal.hardware.FritzAhaWebInterface.authenticate(FritzAhaWebInterface.java:105) ~[?:?] at org.openhab.binding.avmfritz.internal.hardware.callbacks.FritzAhaReauthCallback.execute(FritzAhaReauthCallback.java:103) ~[?:?] at org.openhab.binding.avmfritz.internal.hardware.callbacks.FritzAhaUpdateCallback.execute(FritzAhaUpdateCallback.java:65) ~[?:?] at org.openhab.binding.avmfritz.internal.hardware.FritzAhaContentExchange.onComplete(FritzAhaContentExchange.java:67) ~[?:?]

[tobiloeb]

I add more debug logging, but I can't see why openhab can't reach the fritzbox anymore. The problem seems to be, that the call to http://192.168.178.1/login_sid.lua get a connection timeout. But the TR064 Binding can reach the FirtzBox and I am able to do the call with "wget" from within the docker container openhab is running in.

Here is my advanced logging, but it doesn't tell me why the GET call to login_sid.lua fails.

I can see that the TR064 connection get a Timeout as well, but this is happens only a few seconds (minutes) than everything works well again for TR064. But the avmfritz binding can't do the requests anymore until I restart openhab. :(

[ansorg]

Increasing the connection timeout (set both values to the max) fixed it for me.

[UlrichGitHub]

Had same problem. Changing from https to http fixed it for me together with the increase of timeouts to 15000. Al least for the moment.

[TheRocken]

I switched from an 7490 to an 7590 but still the problem remains. The bridge is online but does not find any new devices. Things like thermostats are sometimes shown as online or unknown. When shown as online, all their channels showing NULL and don't get any new values

[r33a]

Had same problem. 7590 FW 7.57 Changing the values in the settings and restart did not result in any improvement. Things always unknown.

[TheRocken]

Enabling the trace or debug output I do get some nice xml data from the FritzBox like this

2023-10-10 10:11:37.561 [DEBUG] [al.handler.AVMFritzBaseBridgeHandler] - Poll FRITZ!Box for updates avmfritz:fritzbox:192_168_2_1
2023-10-10 10:11:38.196 [DEBUG] [nal.hardware.FritzAhaContentExchange] - HTTP response: 200
2023-10-10 10:11:38.196 [DEBUG] [nal.hardware.FritzAhaContentExchange] - HTTP response: 200
2023-10-10 10:11:38.197 [DEBUG] [nal.hardware.FritzAhaContentExchange] - GET response complete: <devicelist version="1" fwversion="7.57"><device .....

So the box seems to communicate quite nice. The output is valid xml. and I don't get any errors in the log. But still the data I see in the xml is not putted in the corresponding things, nor are new things identified to be added

[TheRocken]

What I tried and did not work:

• reinstalling the Add-On
• deleting the Bridge-Thing (this is found again automatically each time)
• changing between HTTP & HTTPS
• changing the IP address between IP & fritz.box
• increasing the time out(s)

What DID work:

• deleting all things of this Add-on
• reinstalling the Add-On Now everythings works perfect again!

[peter12311]

Trying to do the same the following happened: I could delete all Fritz-Things using the UI, except one FritzDECT 200, this one remained in the status "removing" (maybe the cause of all this?). Somehow I managed to delete it finally (changing the code, rebooting etc,). Then deleted the binding. Reboot, newly installed the binding and all the related things. Will report if that fixed the error, since 5 hours it seems ok now.

[rayb67]

Hi, after a view weeks, I pick up these issue. I still use a AVM 7490 with FRITZ!OS: 7.57. Because I use text files for configuration, I gamble with the timeout settings - thx @UlrichGitHub . That's the solution.

I think this issue should close because it's only a parameter . Perhaps, someone should adjust the recommended defaults.

Best regards Ralf

avmfritz.things

Bridge avmfritz:fritzbox:avmfb7490 "AVMFRITZ FritzBox" 
[ ipAddress="192.168.1.1", 
	password="password", 
	user="user",
        protocol="https",
        port="443",
        pollingInterval=60, 
	asyncTimeout=15000, 
	syncTimeout=10000 ] 
{
    Thing FRITZ_Powerline_546E 08_96_D7_F3_8E_AA "FRITZ!Powerline 546E #x" [ ain="08:96:D7:F3:8E:AA" ]
}

[ebb75inTown]

Hey Ray67 – that solved the issue! The FRITZ!Box and all connected devices are now stable online and working without any issues. I'll report back if there are any further problems, but for now, thank you!

[peter12311]

Trying to do the same the following happened: I could delete all Fritz-Things using the UI, except one FritzDECT 200, this one remained in the status "removing" (maybe the cause of all this?). Somehow I managed to delete it finally (changing the code, rebooting etc,). Then deleted the binding. Reboot, newly installed the binding and all the related things. Will report if that fixed the error, since 5 hours it seems ok now.

After some weeks I can confirm that this solved the issue for me. cheers :)

[Selters]

Hi, after a view weeks, I pick up these issue. I still use a AVM 7490 with FRITZ!OS: 7.57. Because I use text files for configuration, I gamble with the timeout settings - thx @UlrichGitHub . That's the solution.

I think this issue should close because it's only a parameter . Perhaps, someone should adjust the recommended defaults.

Ray67's workaround solved the issue for me too :-) Many thanks!

[riegelbrau]

I face the same issue on OH 4.1.2. Unfortunately the workaround mentioned above, does not change anything. The problem persists.

Any new ideas?

[TheRocken]

A simple restart helped for me together with setting the timeout values higher. The same worked after updating to their latest beta release of the Fritz!OS

[riegelbrau]

I solved my problem. Sorry, it was my own mistake. I had a trailing blank in the password field, may be from copy/paste. After deleting the blank, all is running good again.