i install newly this installation of openhab, i change it from sd-karte to ssd and make all new; so installation was fine but the last two days the AVM Fritz Binding stop working in the middle of the night around 1am. I have some Dect200 and with a roule i transmitted the power of my fridge to another raspi with a “Volkszähler” middleware with a http post; this rule stops around 1am or the day befor 2am, because the power of the fridge doesn’t change anymore. In the PaperUI the Fritzbox has a communication error and all thinks with AVM can’t communicate since i restart openhab with a
sudo systemctl restart openhab.service
this is the log entry at the time around 1 am
Blockquote
2020-07-20 20:04:48.436 [INFO ] [o.internal.handler.AstroThingHandler] - Scheduled Positional job astro:moon:home every 300 seconds
2020-07-20 20:07:42.253 [INFO ] [.eclipse.smarthome.model.script.INFO] - Waschmaschine: MODE_OFF
2020-07-20 23:09:31.786 [INFO ] [rnal.service.RemoteControllerService] - Using SecureWebSocket interface
2020-07-20 23:20:27.287 [ERROR] [.smarthome.model.script.actions.HTTP] - Fatal transport error: java.util.concurrent.TimeoutException: Total timeout 3000 ms elapsed
2020-07-21 00:33:27.700 [ERROR] [.smarthome.model.script.actions.HTTP] - Fatal transport error: java.uti
Blockquote
The transport Error is sometime in the log, because i think the other raspi need sometimes more time with the post request…
There are no more logs??
Has somebody a first idea to find the problem?
I don’t know. You said you can see something “the Fritzbox” in PaperUI with a communication error.
I’m guessing that is a Thing.
When a Thing status changes like that, it leaves a record in your logs.
Usually in openhab.log, but you should check events.log too.
These are not hidden but I don’t know what viewer filter you might be using.
Most likely it’ll just say communication error as well but let’s find out, and see what else is going on at that time.
Yes, but after restart at the moment there is no communication error;
I looked into the event-log, there is something strange for me: 2020-07-21 06:54:05.013 [hingStatusInfoChangedEvent] - 'avmfritz:fritzbox:192_168_2_1' changed from ONLINE to OFFLINE (COMMUNICATION_ERROR): FRITZ!Box does not respond 2020-07-21 06:54:05.017 [hingStatusInfoChangedEvent] - 'avmfritz:FRITZ_DECT_200:192_168_2_1:087610482237' changed from ONLINE to OFFLINE (BRIDGE_OFFLINE) 2020-07-21 06:54:05.019 [hingStatusInfoChangedEvent] - 'avmfritz:FRITZ_DECT_200:192_168_2_1:087610374072' changed from ONLINE to OFFLINE (BRIDGE_OFFLINE) 2020-07-21 06:54:05.020 [hingStatusInfoChangedEvent] - 'avmfritz:FRITZ_DECT_200:192_168_2_1:087610295984' changed from ONLINE to OFFLINE (BRIDGE_OFFLINE) 2020-07-21 06:54:05.022 [hingStatusInfoChangedEvent] - 'avmfritz:FRITZ_DECT_200:192_168_2_1:087610463439' changed from ONLINE to OFFLINE (BRIDGE_OFFLINE) 2020-07-21 06:54:05.023 [hingStatusInfoChangedEvent] - 'avmfritz:FRITZ_DECT_200:192_168_2_1:087610448215' changed from ONLINE to OFFLINE (BRIDGE_OFFLINE) 2020-07-21 06:54:05.025 [hingStatusInfoChangedEvent] - 'avmfritz:Comet_DECT:192_168_2_1:109710386448' changed from ONLINE to OFFLINE (BRIDGE_OFFLINE) 2020-07-21 06:54:05.028 [hingStatusInfoChangedEvent] - 'avmfritz:fritzbox:192_168_2_1' changed from OFFLINE (COMMUNICATION_ERROR): FRITZ!Box does not respond to OFFLINE
But the last successful log-entry was that: 2020-07-21 01:10:24.858 [vent.ItemStateChangedEvent] - Kamera_Energy changed from 48.228 kWh to 48.229 kWh
After that timestamps, there are nothing from the AVM-Fritz-Binding;
so why should openhab wait so long with a log entry? and could this happen after upgrade the Fritzbox to Firmware version 7.2?
Are you expecting anything to happen between 0110 and 0700 ?
I don’t know if the binding will notice anything wrong until it comes to actually do something.
Anyway we’ve got to a basic error message now, “Fritzbox does not respond”. Which isn’t very helpful, but there may not be much more to say.
As a further diagnostic move, try setting the Thing back online in PaperUI next time, see if is recoverable error.
i also have a connection problem to my Fritz!Box 7590 after the update to fw 7.2, but with the tr064-binding. Maybe there was a major change?
Since the update i get the following message to the logs:
19:11:23.456 [WARN ] [ding.fritzboxtr064.internal.Tr064Comm] - No tr064 service found for service id urn:WANDSLIfConfig-com:serviceId:WANDSLInterfaceConfig1
19:11:23.459 [WARN ] [ding.fritzboxtr064.internal.Tr064Comm] - Error constructing request SOAP msg for getting parameter. null
19:11:23.462 [WARN ] [ding.fritzboxtr064.internal.Tr064Comm] - Could not determine data to be sent to FritzBox!
19:11:23.464 [ERROR] [ab.core.service.AbstractActiveService] - Error while executing background thread FritzboxTr064 Refresh Service
java.lang.NullPointerException: null
Hello,
next Day, next error of communication; in the evening the Fritbox make his last update to openhab…
in the openhab.log there is nothing to see, why there would be a communication error, in the event.log i find :
2020-07-22 00:02:25.422 [hingStatusInfoChangedEvent] - ‘avmfritz:fritzbox:192_168_2_1’ changed from ONLINE to OFFLINE (COMMUNICATION_ERROR): FRITZ!Box does not respond
and this ist the last Item update :
2020-07-21 18:19:25.345 [vent.ItemStateChangedEvent] - Laptop_Leistung changed from 10.720 W to 11.510 W
so, i cant see what happened and why the only log is about 6 hours later?
In the log of my fritzbox there are nothing special to see, no wrong login or something like that.
Fritzbox is the same as Alex 7590 with Firmware 7.2
There’s no reason that openHAB will ‘discover’ a communication failure until it actually tries to communicate.
I’ve no idea how often it might do that, but will guess most of the time it is just listening for incoming messages and is not worried if none come.
I am suspicious of the time this seems to happen, Do you have automated backups? (including at Fritz) Do you have zwave doing a network heal?
You might turn on debug logging to see if anything else comes out. It’ll make a lot of logs.
No, I have no automatic backup and no zwave things ; only some power plugs with mqtt; I switch the log to debug in the Kara-console for the binding.avmfritz ; maybe I can see something …
2020-07-23 01:03:28.550 [DEBUG] [al.handler.AVMFritzBaseBridgeHandler] - Poll FRITZ!Box for updates avmfritz:fritzbox:192_168_2_1
2020-07-23 01:03:48.554 [DEBUG] [al.handler.AVMFritzBaseBridgeHandler] - Poll FRITZ!Box for updates avmfritz:fritzbox:192_168_2_1
2020-07-23 01:04:08.555 [DEBUG] [al.handler.AVMFritzBaseBridgeHandler] - Poll FRITZ!Box for updates avmfritz:fritzbox:192_168_2_1
2020-07-23 01:04:28.557 [DEBUG] [al.handler.AVMFritzBaseBridgeHandler] - Poll FRITZ!Box for updates avmfritz:fritzbox:192_168_2_1
and than after 1024 attempts:
2020-07-23 06:45:10.696 [DEBUG] [nal.hardware.FritzAhaContentExchange] - response failed: Max requests queued per destination 1024 exceeded for HttpDestination[https://192.168.2.1]@2552e4,queue=1024,pool=DuplexConnectionPool@1ac278[c=2/2,a=2,i=0]
java.util.concurrent.RejectedExecutionException: Max requests queued per destination 1024 exceeded for HttpDestination[https://192.168.2.1]@2552e4,queue=1024,pool=DuplexConnectionPool@1ac278[c=2/2,a=2,i=0]
at org.eclipse.jetty.client.HttpDestination.send(HttpDestination.java:276) ~[?:?]
at org.eclipse.jetty.client.HttpDestination.send(HttpDestination.java:246) ~[?:?]
at org.eclipse.jetty.client.HttpClient.send(HttpClient.java:580) ~[?:?]
at org.eclipse.jetty.client.HttpRequest.send(HttpRequest.java:728) ~[?:?]
at org.eclipse.jetty.client.HttpRequest.send(HttpRequest.java:720) ~[?:?]
at org.openhab.binding.avmfritz.internal.hardware.FritzAhaWebInterface.asyncGet(FritzAhaWebInterface.java:265) ~[?:?]
at org.openhab.binding.avmfritz.internal.hardware.FritzAhaWebInterface.asyncGet(FritzAhaWebInterface.java:270) ~[?:?]
at org.openhab.binding.avmfritz.internal.handler.AVMFritzBaseBridgeHandler.poll(AVMFritzBaseBridgeHandler.java:216) ~[?:?]
at java.util.concurrent.Executors$RunnableAdapter.call(Executors.java:511) [?:1.8.0_152]
at java.util.concurrent.FutureTask.runAndReset(FutureTask.java:308) [?:1.8.0_152]
at java.util.concurrent.ScheduledThreadPoolExecutor$ScheduledFutureTask.access$301(ScheduledThreadPoolExecutor.java:180) [?:1.8.0_152]
at java.util.concurrent.ScheduledThreadPoolExecutor$ScheduledFutureTask.run(ScheduledThreadPoolExecutor.java:294) [?:1.8.0_152]
at java.util.concurrent.ThreadPoolExecutor.runWorker(ThreadPoolExecutor.java:1149) [?:1.8.0_152]
at java.util.concurrent.ThreadPoolExecutor$Worker.run(ThreadPoolExecutor.java:624) [?:1.8.0_152]
at java.lang.Thread.run(Thread.java:748) [?:1.8.0_152]
A little further forward. I can interpret two problems here.
The Fritzbox stops responding to openHAB HTTP polling.
We cannot tell why; is FB not seeing OH messages, or is FB not answering?
That’s your real problem, and I don’t know where to go with it next, that’s the end of my knowledge.
Looking at the “working” debug log from earlier, it looks like it’s already in trouble - no response from 01:02:48 poll? Then perhaps two responses to 01:03:08 poll? Possibly a sequence problem leads on to …
As a completely separate problem, the binding messes up after a thousand failures. That’s probably a binding bug, it should handle error management more gracefully. Maybe some kind of timeout and queue tidy up is needed.
Did you get to find out if you can recover by setting OFFLINE Thing back ONLINE in PaperUI?
I’m guessing the point where you see the “Max requests” error is also when the Thing status change is logged.
Yes, you showed us this.
What’s new is we can see that a “working” poll seems to get two responses, that’s fine.
So looking again at 01:02:48, there’s a missing response.
After next poll at 01:03:08, two responses come, but that is when it stops working.
Complete speculation on my part, something gets out of sequence where a poll-response cycle is missed.
I’ll also speculate the one HTTP is missed because openHAB or Fritz is busy doing something like a backup or housekeeping at 0100
And new is, I can’t reactivated FB in the PaperUI; when I change the communication protocol from HTTPS to HTTP, openhab get a new SID and than the communication would be fine; when I change back to HTTPS, than I get the old communication Error again …
In my FB there is no rule or something like “housekeeping”, at 0400 there is the disconnect / reconnect DSL Internet setting…
In the FB-log, there is one entry “connecting user:openhab on 1330”, this is the time, I restart openhab…
NEW time slot:
after a little time, there would be no response from FB again:
Until now I have no idea why the AVM Binding stays in a bad state (OH 2.5.8/2.5.10/3.0.0M2) after a connection loss between binding and fritzbox which can only be solved by a complete restart of the openhab instance.
I want to dig a little deeper so any hint/idea is appreciated.
