search

DrozmotiX / ioBroker.tado

Tado cloud connector to control Tado devices
MIT License
24 stars 13 forks source link

Timeout Exceptions nach jedem Neustart #808

Closed Mike1707 closed 2 months ago

Mike1707 commented 3 months ago

Hallo zusammen,

leider bekomme ich den Adapter nun schon seit mehreren Wochen nicht zum Laufen und habe mir das heute, nach einer Installation der neusten Stable, einmal genauer angeschaut. Ich finde leider in den Logs auf den ersten Blick keinen Grund, wieso die Requests immer in einen Timeout laufen. Ich habe schon meinen JS-Controller geupdated, Node bzw. mein Dockerimage geupdated und auch den Adapter aktualisiert. Auf ein erfolgreiches connecten: 

tado.0 | 17771 | 2024-05-07 11:10:35.466 | info | Initialisation finished, connected to Tado cloud service refreshing every 60 seconds
-- | -- | -- | -- | --
tado.0 | 17771 | 2024-05-07 11:10:27.124 | info | Connected to Tado cloud, initialyzing...

Folgt jedes mal eine Exception nach den konfigurierten Sekunden. Siehe bspw. hier: 

2024-05-07 10:48:01.863 - error: tado.0 (16431) AxiosError: timeout of 20000ms exceeded
--
2024-05-07 10:48:01.867 - error: tado.0 (16431) Unhandled promise rejection. This error originated either by throwing inside of an async function without a catch block, or by rejecting a promise which was not handled with .catch().
2024-05-07 10:48:01.868 - error: tado.0 (16431) unhandled promise rejection: timeout of 20000ms exceeded
2024-05-07 10:48:01.869 - error: tado.0 (16431) AxiosError: timeout of 20000ms exceeded
at RedirectableRequest.handleRequestTimeout (/opt/iobroker/node_modules/axios/dist/node/axios.cjs:3123:16)
at RedirectableRequest.emit (node:events:517:28)
at Timeout. (/opt/iobroker/node_modules/follow-redirects/index.js:210:12)
at listOnTimeout (node:internal/timers:569:17)
at process.processTimers (node:internal/timers:512:7)
at Axios.request (/opt/iobroker/node_modules/axios/dist/node/axios.cjs:3876:41)
at runNextTicks (node:internal/process/task_queues:60:5)
at listOnTimeout (node:internal/timers:538:9)
at process.processTimers (node:internal/timers:512:7)
2024-05-07 10:48:01.871 - error: tado.0 (16431) Exception-Code: ECONNABORTED: timeout of 20000ms exceeded
2024-05-07 10:48:01.885 - error: tado.0 (16431) AxiosError: timeout of 20000ms exceeded
2024-05-07 10:48:01.887 - error: tado.0 (16431) Unhandled promise rejection. This error originated either by throwing inside of an async function without a catch block, or by rejecting a promise which was not handled with .catch().
2024-05-07 10:48:01.888 - error: tado.0 (16431) unhandled promise rejection: timeout of 20000ms exceeded
2024-05-07 10:48:01.889 - error: tado.0 (16431) AxiosError: timeout of 20000ms exceeded
at RedirectableRequest.handleRequestTimeout (/opt/iobroker/node_modules/axios/dist/node/axios.cjs:3123:16)
at RedirectableRequest.emit (node:events:517:28)
at Timeout. (/opt/iobroker/node_modules/follow-redirects/index.js:210:12)
at listOnTimeout (node:internal/timers:569:17)
at process.processTimers (node:internal/timers:512:7)
at Axios.request (/opt/iobroker/node_modules/axios/dist/node/axios.cjs:3876:41)
at runNextTicks (node:internal/process/task_queues:60:5)
at listOnTimeout (node:internal/timers:538:9)
at process.processTimers (node:internal/timers:512:7)
2024-05-07 10:48:01.890 - error: tado.0 (16431) Exception-Code: ECONNABORTED: timeout of 20000ms exceeded
2024-05-07 10:48:01.900 - error: tado.0 (16431) AxiosError: timeout of 20000ms exceeded
2024-05-07 10:48:01.901 - error: tado.0 (16431) Error in data refresh at step DoZones: AxiosError: timeout of 20000ms exceeded
2024-05-07 10:48:01.903 - error: tado.0 (16431) Disconnected from Tado cloud service ..., retry in 30 seconds !
2024-05-07 10:48:01.914 - info: tado.0 (16431) cleaned everything up...
2024-05-07 10:48:01.915 - info: tado.0 (16431) terminating
2024-05-07 10:48:01.918 - warn: tado.0 (16431) Terminated (UNCAUGHT_EXCEPTION): Without reason
2024-05-07 10:48:02.420 - info: tado.0 (16431) terminating

Ich habe mir den Bearer Token mal angeschaut, der für den obigen Request genutzt wurde (ist ja Teil des Logs). Er war nicht expired und in Postman bekomme ich auch einen passenden 200 Response für bspw. https://my.tado.com/api/v2/homes/XXXX/zones/1/state oder andere Endpunkte.

Ich würde mich über Hilfe oder Tipps, wo ich noch einsteigen könnte, freuen. Das Logfile gibt es anbei.

Versions:

tado-logs.log

HGlab01 commented 3 months ago

Hallo Mike, kann dir gerne helfen das Ding zum Laufen zu bringen!

Soweit ich aus dem Log erkenne, ist der Login-Prozess erfolgreich abgeschlossen worden --> Requests zu https://auth.tado.com gehen durch Wo ich mir nicht sicher bin auf Basis des Logs ob ein erstes Abfragen der Daten funktioniert hat. Ich vermute das ist der Fall. Kannst du bitte mal checken, ob die States unter tado.0.* aufgebaubt wurden, also ob es zumindest ein paar States unter tado.0.######.Home bzw. tado.0.######.Rooms.1 gibt? Wenn ja, dann wurde zumindest ein erstes Mal eine Verbindung zu https://my.tado.com aufgebaut und Daten geholt.

Wen dem so ist: Kann es sein, dass du eine Komponente hast die vor DoS oder ähnlichem auf Netzwerkebene einen Schutz aufbaut und die Responses beim zweiten Mal abfragen (also nach 60 Sekunden bei Standardconfig) blocked? Eventuell mal das Intervall auf 6000 (10 Min erhöhen und sehen was dann passiert?

Wen dem nicht so ist: Kannst du mal im Docker mit zB telnet checken ob du auf https://my.tado.com kommst?

Kannst du bitte auch mal das Log im Debug-Mode anhängen, damit klarer ist was alles funktioniert und wann/wo/was nicht? Danke!

Mike1707 commented 3 months ago

Moin HGlab01,

ich danke dir für deine sehr schnelle Antwort. Der Auth-Request funktionierte in meinen bisherigen Tests jedes Mal. Daten erhalte ich ebenfalls:

Bildschirmfoto 2024-05-13 um 16 49 30

Die Config war zwischenzeitlich auf 600 (10 Minuten) gestellt und die ersten zwei Requests haben funktioniert. Ich wollte jedoch die Exception im Debug-Mode sehen, daher habe ich es für diesen Zweck einmal auf 60 zurückgestellt. Siehe im Anhang. Ich lasse 10 Minuten jedoch jetzt aktiv und beobachte es.

Ich habe mit den Intervallen jedoch schon ein wenig herumgespielt und noch kein Muster erkannt. Mir ist zudem aufgefallen, dass es auch bei 60 Sekunden erfolgreiche Requests gab.

Der Raspberry ist bezüglich DoS-Protection nicht besonders abgesichert und iobroker wird diesbezüglich auch im Standard im Docker betrieben - jedoch nutze ich ein Docker host Netzwerk für iobroker, falls das relevant ist. Es hängt alles einfach hinter einer normalen FritzBox - ich habe nichts besonderes auf Netzwerkebene konfiguriert, von dem ich wüsste. Läuft so seit ca. 3 Jahren.

Vielleicht noch einmal zum besseren Verständnis... ich nutze dein Plugin schon seit mehreren Jahren aktiv und seit 2-3 Monaten funktioniert es leider nicht mehr aufgrund dieser Timeout-Abstürze. Ich habe an meiner Infrastruktur jedoch nichts geändert, nur Updates installiert. Vielleicht hast du ja eine Idee, was ich prüfen könnte...

Beste Grüße Mike

tado-logs-debug.log

HGlab01 commented 3 months ago

Hallo, danke für die Details! Log sehe ich mir noch im Detail an, aber im drüberfliegen und auch mit deiner Beschreibung bestätigt sich, dass alle Calls im ersten Umlauf sauber funktionieren und dann irgendwann nicht mehr. Dass es in älteren Versionen funktioniert hat, ist ein wichtiger Input, den hatte ich zuvor nicht so verstanden. Seit v0.4.1 (Nov. 2022) nutzt der Adapter eine neue Majorversion von Axios. Da hat sich bei Axos sehr viel getan. Das passt jedoch nicht zu deinem 2-3 Monaten. Haben die Abstürze beim Upgrade zu einer neuen Adapter-Version begonnen oder einfach so ohne neue Version?

Du könntest zum Testen auch mal die 0.4.0 installieren - wäre gespant ob der Fehler dort auch auftritt. Und das 600s Delay-Thema wäre auch interessant

Mike1707 commented 3 months ago

Hallo,

also die 600s Delays haben leider nicht geholfen. Irgendwann kamen die Exceptions wieder.

Je nachdem wann die Versionen im stable iobroker repository released wurde, habe ich letztes Jahr definitiv eine funktionierende Version genutzt und auch regelmäßig deine Updates installiert. Ich würde daher ausschließen, dass die November 2022 Version die zuletzt funktionierende war. Aber ich probiere mich mal durch die Versionen durch und schaue, bis zu welcher es funktioniert.

Grüße

Mike1707 commented 3 months ago

Ich bin gerade irgendwie unfähig eine spezifische Version übers Frontend zu installieren. Kannst du mir mal gerade sagen, was ich falsch mache?

Ich wollte via Github-Quelle installieren. Dann erhalte ich jedoch folgenden Log: 

$ iobroker url https://github.com/DrozmotiX/ioBroker.tado@0.4.2 --host raspberrypi --debug

Info: Can not get current GitHub commit, only remember that we installed from GitHub: Request failed with status code 404

install DrozmotiX/ioBroker.tado@0.4.2

NPM version: 10.5.2

Installing DrozmotiX/ioBroker.tado@0.4.2... (System call)

npm ERR! code ENOENT

npm ERR! syscall opennpm ERR! path /opt/iobroker/DrozmotiX/ioBroker.tado@0.4.2/package.jsonnpm ERR! errno -2

npm ERR! enoent ENOENT: no such file or directory, open '/opt/iobroker/DrozmotiX/ioBroker.tado@0.4.2/package.json'npm ERR! enoent This is related to npm not being able to find a file.npm ERR! enoent

npm ERR! A complete log of this run can be found in: /opt/iobroker/.npm/_logs/2024-05-15T08_52_38_171Z-debug-0.log

npm ERR! code ENOENTnpm ERR! syscall opennpm ERR! path /opt/iobroker/DrozmotiX/ioBroker.tado@0.4.2/package.jsonnpm ERR! errno -2npm ERR! enoent ENOENT: no such file or directory, open '/opt/iobroker/DrozmotiX/ioBroker.tado@0.4.2/package.json'npm ERR! enoent This is related to npm not being able to find a file.npm ERR! enoent npm ERR! A complete log of this run can be found in: /opt/iobroker/.npm/_logs/2024-05-15T08_52_38_171Z-debug-0.log

host.raspberrypi Cannot install DrozmotiX/ioBroker.tado@0.4.2: 254

ERROR: Process exited with code 25
HGlab01 commented 3 months ago

einfachste Weg ist über die Console mit iob upgrade iobroker.tado@0.4.2

HGlab01 commented 3 months ago

Wenn es mit keiner Adapter-Version zusammenhängt, wird es wirklich tricky! Du hast sicher schon mal alle Netzwerkkomponenten wie Frotz!Box und ähnliches rebootet, oder?

Die Fehlermeldung sagt eigentlich aus, dass ein Request zum Server (erfolgreich) gesendet werden konnte, es kam aber innerhalb 20 Sekunden keine Response. Eigentlich sollte so ein Fehler auch sauber abgefangen werden und nicht zu einer unschönen Exception führen, aber das passiert tief in der Axios-Library, da kann ich auch den Fehler leider nicht abfangen