Tibber 429 too many requests Schleife

[Andi1887]

Describe the bug

Die Tibber-API, welche auch von evcc genutzt wird, hat ein Rate-Limit von 100 Abfragen pro 5 Minuten (https://developer.tibber.com/docs/overview). Wenn dieses Limit erreicht wurde, egal ob durch evcc oder einen anderen Dienst, kommt es zu folgendem Verhalten:

Nach einem 429 Status Code wird jeweils eine Sekunde später ein erneuter Versuch gestartet. Das führt dazu, dass die Sperre aufrecht erhalten bleibt, bis man evcc für einige Minuten ausschaltet.

Steps to reproduce

1. evcc mit Tibber-Anbindung nutzen
2. Das API-Limit von Tibber überschreiten

Configuration details

meters:
  - name: mygridmeter
    type: template
    template: tibber-pulse
    usage: grid
    token: xxxxxxxxxxxxxxxxx 
    timeout: 1m

Log details

[pulse ] TRACE 2025/02/01 06:44:16 failed to WebSocket dial: expected handshake response status code 101 but got 429. retry in 1 second... client
[pulse ] TRACE 2025/02/01 06:44:17 failed to WebSocket dial: expected handshake response status code 101 but got 429. retry in 1 second... client
[pulse ] TRACE 2025/02/01 06:44:18 failed to WebSocket dial: expected handshake response status code 101 but got 429. retry in 1 second... client
[pulse ] TRACE 2025/02/01 06:44:19 failed to WebSocket dial: expected handshake response status code 101 but got 429. retry in 1 second... client
[pulse ] TRACE 2025/02/01 06:44:20 failed to WebSocket dial: expected handshake response status code 101 but got 429. retry in 1 second... client

What type of operating system or environment does evcc run on?

Docker container

External automation

• I have made sure that no external automation like HomeAssistant or Node-RED is active or accessing any of the mentioned devices when this issue occurs.

Nightly build

• I have verified that the issue is reproducible with the latest nightly build

Version

evcc version 0.133.0 (b7a9abb)

[phrozen77]

Siehe auch #17706 - "einfach" exponential backoff implementieren bei allem anderen als 200 - schon wärs gut?

[Andi1887]

Ja, das sollte das Problem lösen. Theoretisch könnte man aber auch mit fixen 30 Sekunden Wartezeit arbeiten, zumindest für diesen konkreten Fall.

[andig]

Der Logschnipsel ist leider nichtssagend. Mal wieder ist unklar wie es dazu kommt. These: das passiert nur im Fehlerfall.
Dann ist Tibber ja schon sehr lustig. Erst droppen sie die subscription fehlerhafterweise und dann beschweren sie sich wenn man die wieder haben will. Aber ja...

/cc @GrimmiMeloni

[GrimmiMeloni]

Ein exponentielles Backoff einzubauen ist leider so ohne weiteres nicht möglich, das gibt die Client Library nicht her.
Wir können aber sehr einfach das Default Retry Delay von 1s überschreiben.
Ich habe mal 5s angesetzt, damit bleiben wir auf jeden Fall unter den 100 Req / 300s

[Andi1887]

Der Logschnipsel ist leider nichtssagend. Mal wieder ist unklar wie es dazu kommt.

Verstehe ich, aber hier ging es mir erstmal nur darum, wie evcc damit umgeht, wenn das Rate Limit bereits überschritten wurde. Das muss ja nicht durch evcc passiert sein, sondern kann auch durch einen anderen Dienst oder irgendein ausgeartetes Script passieren. Und dann ist evcc halt aktuell der bad player, der dafür sorgt, dass die Sperre nie aufgehoben wird - auch wenn er das Problem gar nicht ursprünglich verursacht hat.

Zu der Frage wie es dazu kam (was in meinem Fall vermutlich tatsächlich evcc ist) würde ich ein eigenes Issue aufmachen, oder soll das hier beides zusammen behandelt werden?

[Andi1887]

Ich habe jetzt Logs, anhand derer sich die Entstehung der Limitüberschreitung bei Tibber nachvollziehen können lassen sollte. Wie kann ich sie euch am besten zukommen lassen @andig ?

[GrimmiMeloni]

@Andi1887 das Thema ist doch schon mit #18646 erledigt. Das Problem (retries jede Sekunde) ist verstanden und gefixt (retries nur noch alle 5s). Wozu sollen die neuen Logs dienen?

[Andi1887]

Damit wird aber doch "nur" dafür gesorgt, das man wieder aus der Sperre rauskommt. Wäre es nicht grundsätzlich besser, gar nicht erst in die Sperre reinzulaufen? @andig schrieb ja auch "Der Logschnipsel ist leider nichtssagend. Mal wieder ist unklar wie es dazu kommt. " - daher dachte ich der Bedarf nach mehr Infos zur eigentlichen Entstehung ist vorhanden. Vielleicht geben die Logs darüber Aufschluss und es lässt sich verhindern, dass die Sperre überhaupt erst entsteht.

[GrimmiMeloni]

Hmmm. Ich dachte das grundsätzliche Dilemma hätte ich bereits hier erklärt. Insbesondere wenn nicht nur evcc auf dem Tibber Account angemeldet ist, kann von evcc Seite nicht mit absoluter Sicherheit garantiert werden, daß es nicht zum Throttling kommt. Evcc kann lediglich sicherstellen nicht selbst mehr als die 100req/300s zu senden. Wenn andere Systeme im Spiel sind ist es nicht deterministisch was passiert.

Der Change in #18646 sorgt dafür, daß im Connection Fehlerfall evcc nicht sekündlich auf der API anfragt. Das sollte zumindest dafür sorgen, daß wenn der Fehlerfall eintritt, Tibber aus dem Status wieder herauskommt. Oder anders ausgedrückt. Wenn dieser Fehler auftritt, steuert evcc nur noch 60 von 300 Requests bei.

Ob das vorherige Verhalten von evcc für das Throttling verantwortlich war ist schwer zu beurteilen. Eigentlich müsste ja irgendein anderer Effekt erstmal zum Überschreiten der 100req/300s führen. Selbst in der pre-Patch Version des Codes sehe ich das erstmal nicht so ohne weiteres das evcc das tut. evcc meldet an, subscribed, und ab dann ist es kein API call mehr, weil der Stream steht.

[Andi1887]

Genau deswegen würde ich euch ja gerne die Logs zur Verfügung stellen - es sieht für mich schon so aus, als wäre evcc ursächlich für die Limitüberschreitung. Und bei mir kann ich auch ausschließen, dass irgendein anderer Dienst die Limitüberschreitung herbeiführt. Hier ein Auszug aus den Logs:

[pulse ] TRACE 2025/02/05 09:48:35 {"type":"connection_init","payload":{"token":"***"}} client
|stdout|2025-02-05T08:48:35.517454334Z
[pulse ] TRACE 2025/02/05 09:48:35 {"type":"connection_init","payload":{"token":"***"}} client
|stdout|2025-02-05T08:48:35.682042344Z
[pulse ] TRACE 2025/02/05 09:48:35 {"type":"connection_init","payload":{"token":"***"}} client
|stdout|2025-02-05T08:48:35.823137208Z
[ocpp  ] TRACE 2025/02/05 09:48:35 recv LE006XXX: [3,"1111409772",{"status":"Accepted"}]
|stdout|2025-02-05T08:48:35.841951771Z
[pulse ] TRACE 2025/02/05 09:48:36 {"type":"connection_init","payload":{"token":"***"}} client
|stdout|2025-02-05T08:48:36.080110018Z
[pulse ] TRACE 2025/02/05 09:48:36 {"type":"connection_init","payload":{"token":"***"}} client
|stdout|2025-02-05T08:48:36.229653325Z
[pulse ] TRACE 2025/02/05 09:48:36 {"type":"connection_init","payload":{"token":"***"}} client
|stdout|2025-02-05T08:48:36.387030044Z
[pulse ] TRACE 2025/02/05 09:48:36 {"type":"connection_init","payload":{"token":"***"}} client

Das sind schon relativ viele Verbindungsversuche in kurzer Zeit.. Und irgendwann kommt dann halt der 429 Fehler.

[GrimmiMeloni]

OK, dann her damit. Ich schau es mir an.
--> [email protected]

[GrimmiMeloni]

Ich habe mir das Log von @Andi1887 heute morgen näher angeschaut.

Ich habe die Vermutung, daß der graph-ql client ein Problem hat, und resourcen / go-routines länger als nötig am Leben hält.
Ich vermute das sich durch den rekursiven Aufruf von Run() innerhalb des Subscription Clients irgendwas aufstaut.

Dies mache ich unter anderem an der Beobachtung fest, daß ab dem Moment in dem der aktuell laufende Run() mit der folgenden Meldung aussteigt:

[pulse ] TRACE 2025/02/05 09:46:45 no running subscription. exiting... client

sich eine Kaskade von "use of closed network connection" ins Log ergießt.

Ich kann das leider in keiner Weise belegen, da die Log Einträge alle gleich aussehen. @andig kennst du irgendeine Möglichkeit in GoLang ThreadIds/RoutineIds/ContextIds ins Log zu bekommen, so daß wir diese Ausgaben ggf. irgendwie voneinander unterscheiden können? Wenn nein, sehe ich hier erstmal kein Weiterkommen.

[andig]

Ich habe die Vermutung, daß der graph-ql client ein Problem hat, und resourcen / go-routines länger als nötig am Leben hält.

Das sagte ich ja (siehe graphql issue)- die go Routinen werden nicht beendet da sie in den error Channel schreiben wollen der mangels Reader blockiert is.

kennst du irgendeine Möglichkeit in GoLang ThreadIds/RoutineIds/ContextIds ins Log zu bekommen

Das ist im PProf erkennbar.

[GrimmiMeloni]

Ich habe jetzt nochmal intensiv den Fall der hängenden Go Routine angeschaut. Die ist nur Beiwerk vom Client shutdown (nach dem der subscripe scheitert). Ich würde sagen der go-graphql client leaked pro client exit eine go routine.

Ich vermute auch das diese es sind, die die Kaskade an Log Nachrichten erzeugen. Eine andere Theorie habe ich nicht.

@Andi1887 wie lang wäre das längste Log das Du mir senden kannst? Hast Du zufällig das Log das Du mir gesendet hast ab Start von evcc?

[Andi1887]

Das Log von dem Fall, den ich dir geschickt habe, könnte ich dir ab "2025/02/04 19:33:30" zur Verfügung stellen. Allerdings ist da der Start von evcc nicht mit drauf, das lief schon länger. Wenn du ein vollständiges Log ab Start brauchst, müssen wir bis zum nächsten Auftreten warten.