Warp1: FW 2.1.3 Lastmanagement

[Doncarlos]

Hallo,

mein Setup besteht aus zwei WARP1, beide natürlich per WLAN angebunden. Einer (West) hat nicht die stabilste WLAN Verbindung, der LM-Main (Ost) ist da ganz gut angebunden. Auf meinem Laptop läuft ein Python in Endlosschleife , frag den Stromzähler im Keller wieviel Solarstrom da ist und setz das via "charge_manager/availabe_current_update"  als verfügbaren Strom. Der Minimalstrom ist auf 6A konfiguriert.

Bis zum meinem letzten Update von 2.0.8 auf 2.1.3 hat das super funktioniert. Jetzt aber funktioniert irgendwas nicht mehr richtig. Am LM-Main ist ein Plugin Hybrid angeschlossen. Via Python werden 19A zugewiesen, das kommt auch im Webinterface an, es wird aber nur 6A an das einzige Fahrzeug verteilt. Die 19A stehen dort minutenlang und es ändert sich nichts.

Wenn ich jetzt raten müsste, würde ich sagen, dass die WLAN Verbindung schlechter geworden its, ich bekomme via Python Script nun öfter Timeouts beim Abfragen der Ströme.

Wie kann ich das weiter debuggen ?

[rtrbt]

Aktiviere unter Wallbox -> Lastmanagement in den Experteneinstellungen mal das Stromverteilungsprotokoll. Dann schreibt der Lastmanager jedes Mal wenn er Strom verteilt in sein Ereignislog, was er tut. Dann erzeuge das Problem nochmal und zieh einen Debug-Report. Damit sollten wir sehen wo der Strom hin ist.

[Doncarlos]

Einen Nachtrag nach zu meinem ersten Post. Mit der schlechten WLAN Verbindung meint ich eine vielleicht etwas weniger kulante oder aktivere Kommunikation zwischen den beiden Wallboxen.

Ein komplettes Debug Log sende ich gleich via Mail. Aber einen Auszug mit interessanten Sachen poste ich mal hier:

Zitat

2023-07-27 16:11:48,661  Received packet from unknown 192.168.1.75. Is the config complete?
2023-07-27 16:11:49,673  Received packet from unknown 192.168.1.75. Is the config complete?
2023-07-27 16:11:56,874  Resolved warp-um6-west.local to 192.168.1.75 (via mDNS scan)
2023-07-27 16:12:04,203  Redistributing current
2023-07-27 16:12:04,203      1 charger requests current. 16900 mA available.
2023-07-27 16:12:04,203      stage 0: Calculated target for warp-ULS-Ost (127.0.0.1) of 6000 mA. 10900 mA left.
2023-07-27 16:12:04,214      stage 0: 10900 mA still available. Recalculating targets.
2023-07-27 16:12:04,224      stage 0: Recalculated target for warp-ULS-Ost (127.0.0.1) of 16000 mA. 900 mA left.
2023-07-27 16:12:04,234      stage 0: 900 mA still available. Attempting to wake up chargers that already charged their vehicle once.
2023-07-27 16:12:04,245      stage 2: Unthrottled warp-ULS-Ost (127.0.0.1) to 16000 mA.
2023-07-27 16:12:05,352  Charger state changed from 1 to 2
2023-07-27 16:12:07,384  Charger state changed from 2 to 3

Die 1.75 ist die Slave Box ( warp WEST)

bearbeitet July 27, 2023 at 14:34 von Doncarlos

[rtrbt]

Aus dem vollständigen Log sehe ich folgendes:

• Es dauert nach Start der Wallbox ~ eine Minute, bis die Slave-Box per MDNS aufgelöst wird. Das erklärt

  2023-07-27 16:11:48,661  Received packet from unknown 192.168.1.75. Is the config complete?
  2023-07-27 16:11:49,673  Received packet from unknown 192.168.1.75. Is the config complete?
  2023-07-27 16:11:56,874  Resolved warp-um6-west.local to 192.168.1.75 (via mDNS scan)

• Es wird zwei Mal Strom umverteilt:

  2023-07-27 16:12:04,203  Redistributing current
  2023-07-27 16:12:04,203      1 charger requests current. 16900 mA available.
  2023-07-27 16:12:04,203      stage 0: Calculated target for warp-ULS-Ost (127.0.0.1) of 6000 mA. 10900 mA left.
  2023-07-27 16:12:04,214      stage 0: 10900 mA still available. Recalculating targets.
  2023-07-27 16:12:04,224      stage 0: Recalculated target for warp-ULS-Ost (127.0.0.1) of 16000 mA. 900 mA left.
  2023-07-27 16:12:04,234      stage 0: 900 mA still available. Attempting to wake up chargers that already charged their vehicle once.
  2023-07-27 16:12:04,245      stage 2: Unthrottled warp-ULS-Ost (127.0.0.1) to 16000 mA.
  2023-07-27 16:12:05,352  Charger state changed from 1 to 2
  2023-07-27 16:12:07,384  Charger state changed from 2 to 3
  2023-07-27 16:13:14,269  Redistributing current
  2023-07-27 16:13:14,270      1 charger requests current. 17500 mA available.
  2023-07-27 16:13:14,270      stage 0: Calculated target for warp-ULS-Ost (127.0.0.1) of 6000 mA. 11500 mA left.
  2023-07-27 16:13:14,280      stage 0: 11500 mA still available. Recalculating targets.
  2023-07-27 16:13:14,291      stage 0: Recalculated target for warp-ULS-Ost (127.0.0.1) of 6000 mA. 11500 mA left.
  2023-07-27 16:13:14,301      stage 0: 11500 mA still available. Attempting to wake up chargers that already charged their vehicle once.
  2023-07-27 16:13:14,311      stage 1: Throttled warp-ULS-Ost (127.0.0.1) to 6000 mA.
  2023-07-27 16:13:14,321      stage 1: Throttled a charger. Skipping stage 2
  2023-07-27 16:13:14,332      Skipping stage 2

Am Anfang macht der Verteilungsalgorithmus alles richtig, bei der zweiten Verteilung gibt er der Box aber nur 6 Ampere. Ich vermute, dass das mit einer der Lastmanagement-Änderungen in 2.1.3 zusammenhängt. Kannst du testweise in den Experteneinstellungen die Länge der Start­phase auf z.B. 120 Sekunden umstellen? Wenn dann erst nach zwei Minuten der Strom auf 6 Ampere geregelt wird, weiß ich, wo ich suchen muss.

[Doncarlos]

Hallo, neues Ereignislog ist per Email raus.

In der Tat ist das "Anstartverhalten" recht interessant. Direkt nach dem Neustart des LM Masters , sind erst mal das Maximum an Strom erlaubt, bevor er dann merkt dass er die zweite Box nicht findet und auf "Blockiert durch Lastmanagement" wechselt. Nach einer Weile gibt es wieder das Maximum, bevor dann nach ca 2 Minuten er wieder in den Default fällt.

Also, insofern eigentlich auch nochmal ein zweiter Bug, dass er ohne Test auf die andere(n) Boxen gleich das Maximum freigibt. Es wird zwar kaum ein Auto geben , dass so schnell reagiert ....

[rtrbt]

Der zweite Bug entsteht (auch) dadurch, dass die Namensauflösung per mDNS relativ lange dauert. Das ist ein bekanntes Problem. Ein Ansatz das zu lösen wäre, die Pakete, die diese Meldungen auslösen: 

 Received packet from unknown 192.168.1.75. Is the config complete?

zu akzeptieren. Das hat noch ein paar Fallstricke, steht aber auf der Liste. Aus Ubersichtsgründen habe ich ein eigenes Issue dafür aufgemacht: https://github.com/Tinkerforge/esp32-firmware/issues/264 (davor war das Teil von #225)

Prinzipiell gebe ich dir aber recht, dass überhaupt schon 20 Sekunden nach Neustart Strom umverteilt wird, wenn noch nicht alle Wallboxen wieder aufgetaucht sind, ist definitiv nicht gut. Habe dafür auch ein Issue aufgemacht:https://github.com/Tinkerforge/esp32-firmware/issues/263 und den Debug-Report anonymisiert angehangen.

 

Noch eine Sache aus dem Log:

2023-08-01 15:58:19,628  Charge manager watchdog triggered! Received no available current update for 30000 ms. Setting available current to 10000 mA

Der Watchdog hat einmal ausgelöst, danach kommt aber nicht sofort eine Stromumverteilung. D.h. zwischen dem Ablaufen der 30 Sekunden des Watchdogs und der nächsten Stromverteilung (das kann zwischen 0 und 10 Sekunden später passieren) kam dann doch noch ein neuer Stromwert an. Würde ich erstmal auf den WLAN-Empfang schieben. Wobei du einen RSSI-Wert von -61 hast. Das ist nicht so schlecht.

 

Unabhängig von den anderen Sachen ist das ursprüngliche Problem gut sichtbar:

2023-08-01 15:57:19,494  Redistributing current
2023-08-01 15:57:19,495      1 charger requests current. 19950 mA available.
2023-08-01 15:57:19,495      stage 0: Calculated target for eins (127.0.0.1) of 6000 mA. 13950 mA left.
2023-08-01 15:57:19,505      stage 0: 13950 mA still available. Recalculating targets.
2023-08-01 15:57:19,516      stage 0: Recalculated target for eins (127.0.0.1) of 16000 mA. 3950 mA left.
2023-08-01 15:57:19,526      stage 0: 3950 mA still available. Attempting to wake up chargers that already charged their vehicle once.
2023-08-01 15:57:19,536      stage 2: Unthrottled eins (127.0.0.1) to 16000 mA.
2023-08-01 15:57:20,696  Charger state changed from 1 to 2
2023-08-01 15:57:21,727  Charger state changed from 2 to 3
2023-08-01 15:58:19,628  Charge manager watchdog triggered! Received no available current update for 30000 ms. Setting available current to 10000 mA
2023-08-01 15:59:29,573  Redistributing current
2023-08-01 15:59:29,573      1 charger requests current. 19950 mA available.
2023-08-01 15:59:29,573      stage 0: Calculated target for eins (127.0.0.1) of 6000 mA. 13950 mA left.
2023-08-01 15:59:29,584      stage 0: 13950 mA still available. Recalculating targets.
2023-08-01 15:59:29,594      stage 0: Recalculated target for eins (127.0.0.1) of 6000 mA. 13950 mA left.
2023-08-01 15:59:29,604      stage 0: 13950 mA still available. Attempting to wake up chargers that already charged their vehicle once.
2023-08-01 15:59:29,615      stage 1: Throttled eins (127.0.0.1) to 6000 mA.
2023-08-01 15:59:29,625      stage 1: Throttled a charger. Skipping stage 2
2023-08-01 15:59:29,635      Skipping stage 2

Um 15:57 wird Strom verteilt, das führt dazu, dass die eine Wallbox (habe die in eins und zwei umbenannt) anfängt zu laden. Deshalb startet der 120 Sekunden-Countdown der Startphase. Die erste Stromverteilung danach (15:59) gibt dann wieder nur 6 Ampere frei.

Ich melde mich nochmal, wenn ich mehr weiß. Danke schonmal für die Hilfe bei der Fehlersuche :)

[gollum]

Ich habe in diesem Zusammenhang übrigens noch ein weiteres Problem festgestellt.

Wenn man das Stromverteilungsprotokoll aktiviert, ist das Ereignis-Log viel zu klein. Es läuft bei mir schon nach ein paar Minuten über.
Was natürlich sehr hinderlich ist, da man dann auch nicht mehr die Startphase sehen kann.
Bei mir läuft das Lastmanagment zwar auf einer WARP2-pro mit insgesamt 6 WARP2-pro. Denke aber, da es auch die FW 2.1.3 ist, dass es immer so ist.

[rtrbt]

Habe das Problem gefunden und behoben. Fix kommt mit der nächsten Firmware.

On 8/3/2023 at 3:21 PM, gollum said:

Wenn man das Stromverteilungsprotokoll aktiviert, ist das Ereignis-Log viel zu klein. Es läuft bei mir schon nach ein paar Minuten über.

Das stimmt. Deshalb ist das Verteilungsprotokoll normalerweise deaktiviert. Da wir inzwischen auch einige andere relativ "gesprächige" Komponenten in der Firmware haben, müssen wir das mal angehen.

[Doncarlos]

Am 3.8.2023 um 09:55 schrieb rtrbt:

Noch eine Sache aus dem Log:

2023-08-01 15:58:19,628  Charge manager watchdog triggered! Received no available current update for 30000 ms. Setting available current to 10000 mA

Der Watchdog hat einmal ausgelöst, danach kommt aber nicht sofort eine Stromumverteilung. D.h. zwischen dem Ablaufen der 30 Sekunden des Watchdogs und der nächsten Stromverteilung (das kann zwischen 0 und 10 Sekunden später passieren) kam dann doch noch ein neuer Stromwert an. Würde ich erstmal auf den WLAN-Empfang schieben. Wobei du einen RSSI-Wert von -61 hast. Das ist nicht so schlecht.

 

Ja, der WLAN Empfang ist so eine Sache.

Ich frage meine Smart Meter nach der Einspeisung, danach frag ich die den Lastmanager-Master welche Wallboxen im Verbund sind und dann muss ich jede Wallbox nach der aktuellen Ladeleistung fragen. Nett wäre es, wenn der Lastmanager Master das schon selbst wüsste. Mit diesen Daten kann man dann Solar-Only laden oder Wetterprognosen einbeziehen oder oder oder.

Dabei kommt es dann doch öfter als gewünscht zu Timeouts. Scheint so, als wäre die Wallbox zu Wallbox Kommunikation mehr "graceful" als meine. Jetzt kann man bei Python die Timeouts wohl nicht so frei einfach einstellen, aber das ist eine andere Geschichte.

[MatzeTF]

Statt alle Wallboxen ständig selbst abzufragen, könntest du vielleicht auch einen MQTT-Server aufsetzen und dein Python-Script lässt sich die Werte darüber zuschicken. Die MQTT-Verbindung zwischen Wallbox und MQTT-Server ist erfahrungsgemäß auch bei schlechter WLAN-Verbindung meist noch nutzbar.

[Doncarlos]

@rtrbt

Ich hab das letzte Versionsupdate gelesen, bin mir aber nicht sicher ob mein Thema nun erledigt ist ?

[rtrbt]

Das primäre Problem, dass der Lastmanager dir nur 6 Ampere zuteilt ist behoben, ja (schon in 2.1.4). Issues 263 und 264 sind leider noch offen.