Inverter hängt, DTU wird nicht aktiv

[uli-bs]

What happened?

Der Inverter (HM-600) und openDTU (onBattery) läuft zunächst einwandfrei und wie konfiguriert.
Nachts (0:00) wird der Inverter über die DTU neu gestartet, was auch im Log vermerkt ist.
Danach treten zeitlich versetzt lt.. Log Fehler (DTU command failed / Error 2) auf (15x)
Am nächsten Morgen, genügend Ladung ist bereits im Akku, startet, trotz entsprechender Anforderung (480W), der Inverter nicht.

Um wieder normalen Betrieb zu erreichen muss sowohl der Inverter, wie auch openDTU, über die Oberfläche neu gestartet werden.
Der Neustart nur einer der beiden Komponente löst das Problem nicht.

To Reproduce Bug

Tritt nicht jeden Tag auf, daher eher schlecht zu reproduzieren.

Expected Behavior

event eine Art Watchdog implementieren?

Install Method

Pre-Compiled binary from GitHub

What git-hash/version of OpenDTU?

fd58ad2

Relevant log/trace output

No response

Anything else?

No response

[spcqike]

Ich weiß nicht, obs zu deinem Problem passt, aber ich hab in letzter Zeit auch vermehrt DTU command failed. heute bereits mindestens 15 mal. (zumindest war das das letzte, was ich gesehen habe... )
bei mir zeigt sich das teilweise auch in Neustarts der DTU, in fehlenden Daten in der Aufzeichnung und, wie jetzt grade, im nicht laufenden Webinterface

wobei die webkonsole aktuell geht

Dabei habe ich weder einen Akku, noch habe ich aktuell den DPL aktiv. im Moment läuft die DTU nur zum auslesen des Inverters.

[uli-bs]

Den Aufbau des Logs habe ich noch nicht verstanden.
Anscheinend werden max. 15 Einträge gespeichert, aber es sind weder die ersten 15, noch die letzten 15?
Es sind ohnehin nur "Inverter starts" , "...commnd failed" und "shut down by remote.." enthalten, kein "Power up/down" o.ä
Der "Inverter starts" scheint permanent im Log zu sein, die anderen haben anscheinend irgendwelche "TTLs"

In der Konsole werde ich mein Problem vermutlich nicht finden, da ja aktuelle Daten und keine History
Was mich aber dort auch irritiert, sind die ganzen "missing" Einträge
...
13:21:32.528 > RX Period End
13:21:32.528 > Middle missing
13:21:32.528 > Request retransmit: 3
...
13:21:34.780 > RX Period End
13:21:34.780 > Last missing
13:21:34.780 > Request retransmit: 2

[uli-bs]

Auf welcher Basis beruht eigentlich die aktuelle Version (23.06.14.post2)?

Hier https://github.com/tbnobody/OpenDTU/issues/1032 wird nämlich ein ähnliches Problem beschrieben, was angeblich mit der 23.6.14 nicht mehr auftrat.

[helgeerbe]

23.6.13 Findest du auch immer in der Readme als Badge. Ich habe da eine Action laufen, die immer in der Readme die Version der originalen OpenDTU für die aktuelle Version angibt

[helgeerbe]

Werde mal schauen, ob ich Zeit habe gleich mal zu mergen und eine neue Realease freizugeben

[uli-bs]

Erstmal vielen Dank für die schnelle Reaktion und das neue Build

Als erste Feststellung an den "missing" in der Konsole hat sich nichts geändert, oder muss das so?
Die DTU (Leistung auf "min.") hängt ca. 30cm neben dem WR, ein Übertragungsproblem dürfte da ja wohl nicht sein

Ob sich an dem Kernproblem etwas geändert hat wird sich erst in ein paar Tagen zeigen.

[helgeerbe]

Also das "missing" habe ich auch. Habe mir den Code dazu aber nie angeschaut, da ich funktionell keine Probleme habe. Will sagen, ich habe keine Ahnung was diese Logausgabe wirklich aussagt.

[helgeerbe]

Das die DTU neustartet sollte eigentlich nicht sein. Das deutet auf irgendwelche Bugs hin. Bei mir lief jetzt alles über 6 Tage total stabil.

Welche Komponenten sind bei euch aktiviert?
Bei mir

• VeDirect an
• PowerMeter (https) an
• PowerLimiter (solar passthrough) an
• Batterie aus
• AC Charger aus

[spcqike]

In meinem Fall aktuell nur MQTT, powermeter (https) und das oled.

Ich werde meine DTU morgen updaten und dann beobachten

[uli-bs]

MQTT ohne HA
Powermeter (http)
Limiter (ohne pt)
Display

VE -off-
Batterie -off-
AC-Lader -off-

[spcqike]

kurzes Update:

nach dem Update hat die DTU sich erfolgreich neugestartet. kurze Zeit später sehe ich wieder das Bild vom Log mit den 15 Fehlern, komme allerdings nicht mehr drauf zum öffnen, da sie sich wieder aufgehängt hat. so halb.

ich sehe auch wieder unregelmäßige Leistungsdaten, die ja per MQTT verschickt und weggespeichert werden. die kommen noch, sie läuft also, aber nicht richtig :D

bin leider nicht vor Ort, so dass ich kein Hardreset am Netzteil machen kann. mal gucken, vielleicht triggert ja ein Watchdog und sie startet sich von selbst neu 😄

Update:
anders als gestern, scheint die API heute zu laufen. nur das eigentliche Interface kommt nicht, sondern bleibt leer. er sagt mir dass er 2200s läuft, also gegen 8:38 einen neustart hingelegt hat.

Update2:
über die API konnte ich doch einen Neustart erzwingen. danach geht auch das WebUI wieder.
ich sehe den Log vom Inverter, 15 Fehler. (kann es sein, dass nicht mehr angezeigt oder ausgelesen werden können?)

Seit dem Neustart (10 Minuten her) sind keine weiteren Fehler gekommen.

[uli-bs]

Bei mit hat das System den WR geplant um 0:00 nu gestartet, Error 2 ist bisher noch nicht aufgetreten, allerdings kommt aktuell auch keine Leistung in den Akku, sodass er auch nicht freigegeben wird.

@spcqike
meine Beobachtungen zum Log hatte ich weiter oben ausgeführt

Update 13:12:
jetzt läuft auch die Produktion, ohne mein Zutun. Weiterhin kein Error 2

[helgeerbe]

Bei mir sieht alles gut aus

Geplanter Neustart des Inverters um 23 Uhr und Abschalten des Invertes, wenn das andere Kraftwerk genug Leistung hat, dass keine Batterieunterstützung benötigt wird.

Ich habe aber auch gar keine Idee, was Fehler 2 sein soll.

[helgeerbe]

ich sehe den Log vom Inverter, 15 Fehler. (kann es sein, dass nicht mehr angezeigt oder ausgelesen werden können?)

Ich glaube größer ist der interne Fehlerspeicher des Inverters nicht. Und er überschreibt auch Meldungen mit unterschiedlichen Prios. Soweit ich mich erinnere.

[uli-bs]

Error 2 war "...Command failed", flutete in der Vorgängerversion auch mein Log

Allerding muss ich dazu sagen, dass ich den empfohlenen "Stützelko" am Funkmodul im Rahmen des Updates auch von bisher 10uF auf 100uF Tantal getauscht habe, auch wenn ich hier die Lösung nicht drin vermute.

[spcqike]

ich sehe den Log vom Inverter, 15 Fehler. (kann es sein, dass nicht mehr angezeigt oder ausgelesen werden können?)

Ich glaube größer ist der interne Fehlerspeicher des Inverters nicht. Und er überschreibt auch Meldungen mit unterschiedlichen Prios. Soweit ich mich erinnere.

Macht Sinn. Denn der Start (Code 1) ist ja noch vorhanden.

Bisher ist auch nichts weiter passiert.

Ich hab auch keine Ahnung, welcher Command da hängen geblieben sein soll. Die openDTU sollte bei mir ja aktuell nichts schicken. Oder werden die aktuellen Leistungsdaten ebenfalls gepollt?

die Konsole sieht aktuell wie folgt aus:

12:31:49.917 > [PowerLimiterClass::loop] ******************* ENTER **********************
12:31:49.917 > [PowerLimiterClass::loop] ******************* PL disabled
12:31:54.197 > PowerMeterClass: TotalPower: 69.00
12:31:54.197 > Fetch inverter: xxxx
12:31:54.302 > TX RealTimeRunData Channel: 61 --> 15 83 72 27 49 80 17 12 76 80 0B 00 64 94 23 1A 00 00 00 00 00 00 00 00 B2 7A F3 
12:31:54.412 > Interrupt received
12:31:54.610 > RX Channel: 3 --> 95 83 72 27 49 83 72 27 49 02 77 5D 00 00 E6 D7 01 3E 02 2E 09 3F 13 89 06 2B 1E | -80 dBm
12:31:54.711 > Interrupt received
12:31:54.814 > RX Channel: 75 --> 95 83 72 27 49 83 72 27 49 83 00 00 00 43 03 E8 01 69 00 54 6D 03 EC | -30 dBm
12:31:54.898 > RX Period End
12:31:54.898 > Middle missing
12:31:54.898 > Request retransmit: 1
12:31:54.898 > TX RequestFrame Channel: 75 --> 15 83 72 27 49 80 17 12 76 81 F8 
12:31:54.989 > Interrupt received
12:31:55.076 > RX Channel: 40 --> 95 83 72 27 49 83 72 27 49 01 00 01 01 83 00 BB 02 D2 01 8A 00 ED 03 A4 00 00 BD | -80 dBm
12:31:55.222 > RX Period End
12:31:55.222 > Success

12:32:21.456 > [PowerLimiterClass::loop] ******************* ENTER **********************
12:32:21.456 > [PowerLimiterClass::loop] ******************* PL disabled
12:32:21.456 > Fetch inverter: xxxx
12:32:21.626 > TX RealTimeRunData Channel: 23 --> 15 83 72 27 49 80 17 12 76 80 0B 00 64 94 23 35 00 00 00 00 00 00 00 00 83 A2 35 
12:32:21.728 > Interrupt received
12:32:21.829 > RX Channel: 3 --> 95 83 72 27 49 83 72 27 49 01 00 01 01 83 00 BC 02 D8 01 8A 00 ED 03 A6 00 00 B2 | -80 dBm
12:32:21.933 > Interrupt received
12:32:22.027 > RX Channel: 75 --> 95 83 72 27 49 83 72 27 49 02 77 5E 00 00 E6 D8 01 3F 02 2F 09 49 13 8A 06 33 7F | -80 dBm
12:32:22.132 > Interrupt received
12:32:22.205 > RX Channel: 61 --> 95 83 72 27 49 83 72 27 49 83 00 01 00 43 03 E8 01 69 00 54 52 0C DD | -30 dBm
12:32:22.344 > RX Period End
12:32:22.344 > Success

gelegentlich mit "Middle missing", aber auch oft ohne. die Kanäle ändern sich gelegentlich.

[helgeerbe]

Die Daten werden immer gepollt. Allerdings habe ich mir das genaue Protokoll nicht angeschaut.
Das "Missing" habe ich auch gelegentlich, meine Annahme bisher, das ggf. wegen Störungen usw. etwas nicht korrekt empfangen werden kann. Es wird ja auch ein retransmit angestoßen. Sieht für mich aber ganz normal aus.

[spcqike]

Kurzes Update. Bisher läuft es dann ohne Auffälligkeiten. Keine Fehler Meldungen, keine erkennbaren Lücken in der Aufzeichnung.

Laufzeit 21:11 h.
Heap sagt 50%. (137, 134, 271 kB)

Nachtrag.

In der Zwischenzeit ist der Fehler 2 mal aufgetreten. Steht aber nur im log. Aufgehängt hat sich nichts

Update.
rein informativ.
nachdem gestern 0 dieser DTU command failed Fehler kamen, sind es heute bisher 11. teilweise wieder 2 in der gleichen Sekunde.

Die DTU läuft ohne dass ich sie neu gestartet hätte aktuell 1tag 2h 54min Und hat einen heap Von 126/144/270.

können die Fehler von nicht erfolgreichen Antworten stammen? Wenn dieses“middle missing“ passiert?

[spcqike]

Update:
Heute war wieder so ein Tag.
nach knapp 24h (genaue Laufzeit weiß ich nicht) gab es wieder diesen Fehler 2 im log. 15 Einträge. Das werden ja wahrscheinlich nicht alle gewesen sein.

Danach war die DTU irgendwann völlig weg. Ich bin nicht drauf gekommen. Kein Ping, keine IP, kein MQTT, keine api.

Zwischenzeitlich kam ich auf die api. Es gab aber immer nur null als Antwort.

Jetzt komme ich wieder auf die Info Seite. Die DTU läuft aktuell seit 1 Tag 3 Stunden. Sie hat sich also nicht neu gestartet. MQTT geht wieder. Ebenso die api.

Heap steht bei 69% (82/186/267 kB)

kann man irgendwie auslesen / herausfinden, was den heap füllt?

[helgeerbe]

@spcqike doofe Frage: Netzwerkprobleme kannst du ausschliessen? Kein Mesh-Netzwerk oder ähnliches?
Da würde mir jetzt nur ein Log über USB einfallen. Dann kann man genau sehen, was der esp treibt, wenn er nicht verfügbar ist.

[spcqike]

100%ig auschließen kann man sowas nie :) Mein Heimnetzwerk ist schon .... größer und komplexer als eine FritzBox :) aber da ich alle anderen Geräte (und ihre Daten) aus dem IoT Netzwerk einwandfrei erreichen konnte (bzw. die anderen Daten ohne Lücken protokolliert wurden, also bspw. Tasmota Sensoren die ebenfalls MQTT nutzen), würd ich sagen da lag kein Problem vor.

spätestens, als ich die OpenDTU wieder per Ping erreicht habe, und auch per "http:///api/livedata/status", dort aber nur "null" zurück kam, würd ich sagen das Problem liegt bei der DTU.

wie gesagt, später ging dann die API wieder (der Neustart allerdings nicht. der gab weiterhin im Webinterface ein "Parsen nicht möglich" und direkt per API aufruf ein "null") ebenso hatte sich MQTT von alleine gefangen. Dabei war der HEAP dann recht belegt, siehe oben.

zum HEAP, da du es in einem anderen Post meintest, dass das Maximum sich nicht ändern sollte. Ich kann sagen, es ändert sich. wie geschrieben, gestern im "halb aufgehangenen Zustand" lag er bei 267kB Max. nach dem Neustart (am Netzteil) ging es hoch auf 271, aktuell sind es 270.

Meinst du, es würde zum Debuggen etwas bringen, den Seriellen Log mal ein paar Tage aufzuzeichnen? Dann würd ich mir mal was einfallen lassen, wie ich das hinbekomme....

[helgeerbe]

Bringen würde es mit sicherheit etwas. Ich würde erwarten, dass wenn der liveview nicht funktioniert du im Log sowas sehen würdest: "Call to /api/livedata/status temporarely out of resources."

Generell tippe ich auf ein Speicherproblem. LiveView ist immer das, wo es am schnellsten auffällt. Dort wird versucht den größten zusammenhängenden Memory-Block zu bekommen (für den Status-Report). In Summe mag zwar genug Speicher verfügbar sein, aber durch Fragmentierungen im Speicher gibt es keinen zusammenhängenden Block mehr. Das kann passieren, wenn kleinere Speicher-Blöcke nicht sauber freigegeben werden. Dann fallen irgendwann weitere Funktionen aus und am Ende bootet der ESP neu.
Meine Installation läuft über stabil und ich habe die Probleme nicht. Da es ja anscheinend immer bei euch auftritt, müsst ihr irgendetwas konfiguriert haben, was die Probleme verursacht, und was die die meisten anderen so nicht verwenden.

Mein Problem ist es, dass ich es nicht nachstellen kann.

[spcqike]

na, ich gucke mal und lasse mir was einfallen. wird schon irgendwie gehen mit dem Log :)

zu meiner config:
esp32 dev board, oled mit sh1106, nrf24l01+ mit externer Antenne, gelötet auf nen perfboard (keine extra Kondensatoren, die sollten ja aber den Speicher nicht beeinflussen, oder?)

-das Modul ist im WLAN
-Dammerung standard (90.8)
-MQTT standard ohne HA oder AUthentifizierung, aller 5 sekunden updates
-ein HM-600 (nachts keine befehle, sonst alle Felder am Wechselrichter befüllt, also Leistung und Namen der Module
-DTU 5s intervall, Sendeleistung minimum
-VE.direct aus
-Powermeter HTTP+JSON eines Tasmota Geräts, 1000ms timeout, nur Phase 1 als Summe aller
-DPL aktuell inaktiv
-keine Batterie
-kein AC Charger
-hardware profil standard aus dem Repo, generic esp32 mit sh1106
-display mit powersave und screensaver, deutsch, keine rotation, 51% kontrast

Dann fallen irgendwann weitere Funktionen aus und am Ende bootet der ESP neu.

das ist gestern nicht passiert. er hat sich wieder halbwegs gefangen. MQTT ging wieder, ebenso einige API aufrufe (neustart bspw. nicht), LiveView weiterhin nicht. Das wird schon am belegten HEAP liegen, es waren dann ja nur 82kB frei.

Ich habe noch 2 ähnliche Systeme installiert bei Bekannten, allerdings ohne MQTT und PM (und auch ohne DPL, den ich ja seit ner Woche zum beobachten auch nicht nutze). die laufen unauffällig. (da wird aber auch weniger oft drauf geguckt.... vielleicht kommt das HEAP Problem ja erst durch das Öffnen des LiveView? Mir kommt es auch so vor, als käme das Problem bevorzugt, wenn ich mit dem iPhone drauf gucke. Auf der anderen Seite läuft es auch Tage stabil, und irgendwann häufen sich diese komischen Fehler 2 im InverterLog. Und irgendwann steigt das WebUI aus. die zwei PRobleme müssen ja aber nicht zwingend zusammen hängen (ich kann aber schlecht überprüfen ob VOR dem vollen HEAP und den Abstürzen Fehler da waren. gestern jedenfalls war es so))

[uli-bs]

Bisher läuft die Version f018a01 vom Jun 21, 2023 relativ problemlos,
"Relativ" bedeutet, der Inverter wird nicht immer zeitnah zum Bedarf gestartet/gesteuert (trotz 5 sec Polltime), die ominösen Error2 (DTU...) tauchen sporadisch auf, und anscheinend startet auch die DTU ab und an unmotiviert neu. Da Teile dieser Fehler auch im originalem openDTU berichtet werden, dürfte das Problem von dort stammen.

Was mich aber jetzt zusätzlich irritiert, sind die neu verfügbaren Versionen mit "ESP32" im Namen?
Ich ging bisher immer davon aus, dass ein ESP32 die Grundanforderung des Programmes ist?!
Laufen tut hier ein ESP32-D0WD-V3, welche Version wäre hier nun richtig, und kann die entsprechende *.bin einfach als Update geflashed werden?

[uli-bs]

Heute war der Fehler leider wieder da :(
Im Akku ist genug Power, Startbedingungen erfüllt, Leistungsanforderung: 128W (40W unter akt.Verbrauch) - nur der Inverter startet nicht

[schlimmchen]

@uli-bs Scheinbar hast du noch kein Log (Console) geteilt. Kannst du einmal einen Auszug kopieren und uns zeigen? Gerade bist du ja scheinbar im Fehlerzustand, da wäre der Log vermutlich sehr hilfreich.

Was hast du im Kontext das Power Limiter als "lower power limit" für den inverter eingestellt?

[uli-bs]

Wie das immer so ist... aktuell liefert er wieder

Eingestellt ist:

Und 250W pro Kanal beim WR

[uli-bs]

Jetzt mit weniger Müll und mit Fehler:

`

Websocket: [/livedata][20] disconnect
18:03:16.822 > Websocket: [/vedirectlivedata][20] disconnect
18:03:16.822 > Websocket: [/huaweilivedata][20] disconnect
18:03:16.976 > Websocket: [/batterylivedata][20] disconnect
18:03:18.611 > RX Period End
18:03:18.611 > All missing
18:03:18.611 > Nothing received, resend whole request
18:03:18.611 > TX PowerControl Channel: 40 --> 51 82 92 24 50 80 18 30 88 81 00 00 B0 01 25 
18:03:18.732 > Interrupt received
18:03:18.798 > RX Channel: 3 --> D1 82 92 24 50 82 92 24 50 81 00 00 00 00 24 00 74 | -80 dBm
18:03:19.117 > PowerMeterClass: TotalPower: 136.00
18:03:20.628 > RX Period End
18:03:20.628 > Success
18:03:20.763 > TX ActivePowerControl Channel: 61 --> 51 82 92 24 50 80 18 30 88 81 0B 00 03 E8 00 00 10 81 E5 
18:03:20.880 > Interrupt received
18:03:20.968 > RX Channel: 3 --> D1 82 92 24 50 82 92 24 50 81 00 00 0B 00 14 07 48 | -80 dBm
18:03:22.699 > RX Period End
18:03:22.700 > Success
18:03:22.700 > Fetch inverter: 114182922450
18:03:22.811 > TX RealTimeRunData Channel: 75 --> 15 82 92 24 50 80 18 30 88 80 0B 00 64 A4 42 CA 00 00 00 00 00 00 00 00 0C 4A D4 
18:03:22.927 > Interrupt received
18:03:23.015 > RX Channel: 3 --> 95 82 92 24 50 82 92 24 50 83 00 00 00 00 00 00 01 28 00 39 BA 93 2F | -80 dBm
18:03:23.217 > RX Period End
18:03:23.217 > Middle missing
18:03:23.217 > Request retransmit: 1
18:03:23.217 > TX RequestFrame Channel: 3 --> 15 82 92 24 50 80 18 30 88 81 D0 
18:03:23.324 > RX Period End
18:03:23.324 > Middle missing
18:03:23.324 > Request retransmit: 1
18:03:23.324 > TX RequestFrame Channel: 23 --> 15 82 92 24 50 80 18 30 88 81 D0 
18:03:23.442 > RX Period End
18:03:23.442 > Middle missing
18:03:23.442 > Request retransmit: 1
18:03:23.442 > TX RequestFrame Channel: 40 --> 15 82 92 24 50 80 18 30 88 81 D0 
18:03:23.545 > Interrupt received
18:03:23.631 > RX Channel: 23 --> 95 82 92 24 50 82 92 24 50 01 00 01 01 09 00 03 00 07 01 08 00 03 00 07 00 00 94 | -80 dBm
18:03:23.683 > RX Period End
18:03:23.683 > Middle missing
18:03:23.683 > Request retransmit: 2
18:03:23.683 > TX RequestFrame Channel: 61 --> 15 82 92 24 50 80 18 30 88 82 D3 
18:03:23.747 > RX Period End
18:03:23.747 > Middle missing
18:03:23.747 > Request retransmit: 2
18:03:23.747 > TX RequestFrame Channel: 75 --> 15 82 92 24 50 80 18 30 88 82 D3 
18:03:23.835 > RX Period End
18:03:23.835 > Middle missing
18:03:23.835 > Retransmit timeout
18:03:24.358 > PowerMeterClass: TotalPower: 139.00
18:03:26.367 > [PowerLimiterClass::loop] ******************* ENTER **********************
18:03:26.367 > [PowerLimiterClass::loop] ******************* PL inverter updates PM: 4747, Inverter: -385 
18:03:27.679 > Fetch inverter: 114182922450
18:03:27.873 > TX RealTimeRunData Channel: 3 --> 15 82 92 24 50 80 18 30 88 80 0B 00 64 A4 42 CF 00 00 00 00 00 00 00 00 5C 75 BE 
18:03:28.045 > Interrupt received
18:03:28.132 > RX Channel: 23 --> 95 82 92 24 50 82 92 24 50 01 00 01 01 09 00 03 00 07 01 08 00 03 00 07 00 00 94 | -80 dBm
18:03:28.198 > Interrupt received
18:03:28.254 > RX Channel: 3 --> 95 82 92 24 50 82 92 24 50 83 00 00 00 00 00 00 01 28 00 39 BF 5E E7 | -80 dBm
18:03:28.309 > RX Period End
18:03:28.309 > Middle missing
18:03:28.309 > Request retransmit: 2
18:03:28.309 > TX RequestFrame Channel: 23 --> 15 82 92 24 50 80 18 30 88 82 D3 
18:03:28.381 > Interrupt received
18:03:28.543 > RX Channel: 40 --> 95 82 92 24 50 82 92 24 50 02 4D 09 00 00 4D D3 00 15 00 15 09 36 13 8F 00 00 EE | -80 dBm
18:03:28.608 > RX Period End
18:03:28.608 > Success
18:03:29.645 > PowerMeterClass: TotalPower: 138.00
18:03:32.669 > Fetch inverter: 114182922450
18:03:32.737 > TX RealTimeRunData Channel: 40 --> 15 82 92 24 50 80 18 30 88 80 0B 00 64 A4 42 D4 00 00 00 00 00 00 00 00 AC CB EB 
18:03:32.821 > Interrupt received
18:03:32.943 > RX Channel: 40 --> 95 82 92 24 50 82 92 24 50 83 00 00 00 00 00 00 01 28 00 39 3A D2 EE | -80 dBm
18:03:33.201 > RX Period End
18:03:33.201 > Middle missing
18:03:33.201 > Request retransmit: 1
18:03:33.201 > TX RequestFrame Channel: 61 --> 15 82 92 24 50 80 18 30 88 81 D0 
18:03:33.269 > Interrupt received
18:03:33.453 > RX Channel: 40 --> 95 82 92 24 50 82 92 24 50 01 00 01 01 09 00 03 00 07 01 08 00 03 00 07 00 00 94 | -80 dBm
18:03:33.503 > RX Period End
18:03:33.503 > Middle missing
18:03:33.503 > Request retransmit: 2
18:03:33.503 > TX RequestFrame Channel: 75 --> 15 82 92 24 50 80 18 30 88 82 D3 
18:03:33.567 > RX Period End
18:03:33.567 > Middle missing
18:03:33.567 > Request retransmit: 2
18:03:33.567 > TX RequestFrame Channel: 3 --> 15 82 92 24 50 80 18 30 88 82 D3 
18:03:33.644 > Interrupt received
18:03:33.763 > RX Channel: 40 --> 95 82 92 24 50 82 92 24 50 02 4D 09 00 00 4D D3 00 15 00 15 09 38 13 8E 00 00 E1 | -80 dBm
18:03:33.833 > RX Period End
18:03:33.833 > Success
18:03:34.908 > PowerMeterClass: TotalPower: 138.00
18:03:36.878 > [PowerLimiterClass::loop] ******************* ENTER **********************
18:03:36.878 > [PowerLimiterClass::loop] dcVoltage: 26.50 Voltage Start Threshold: 24.60 Voltage Stop Threshold: 24.10 inverter->isProducing(): 0
18:03:36.878 > [PowerLimiterClass::loop] newPowerLimit: 98
18:03:36.878 > [PowerLimiterClass::loop] Starting up inverter...
18:03:36.878 > [PowerLimiterClass::loop] Limit Non-Persistent: 98 W
18:03:36.878 > [PowerLimiterClass::loop] Status: SolarPT enabled 0, Drain Strategy: 0, canUseDirectSolarPower: 0, Batt discharge: 1
18:03:36.878 > [PowerLimiterClass::loopInterrupt received
18:03:37.036 > RX Channel: 23 --> D1 82 92 24 50 82 92 24 50 81 00 00 00 00 24 00 74 | -80 dBm
18:03:38.897 > RX Period End
18:03:38.897 > Success
18:03:38.979 > TX ActivePowerControl Channel: 40 --> 51 82 92 24 50 80 18 30 88 81 0B 00 03 D4 00 00 1C 41 15 
18:03:39.044 > Interrupt received
18:03:39.184 > RX Channel: 23 --> D1 82 92 24 50 82 92 24 50 81 00 00 0B 00 14 07 48 | -80 dBm
18:03:40.157 > PowerMeterClass: TotalPower: 139.00
18:03:40.910 > RX Period End
18:03:40.910 > Success
18:03:40.910 > Fetch inverter: 114182922450
18:03:40.965 > TX RealTimeRunData Channel: 61 --> 15 82 92 24 50 80 18 30 88 80 0B 00 64 A4 42 DC 00 00 00 00 00 00 00 00 6C AC 44 
18:03:41.141 > Interrupt received
18:03:41.232 > RX Channel: 40 --> 95 82 92 24 50 82 92 24 50 01 00 01 01 09 00 03 00 07 01 08 00 03 00 07 00 00 94 | -80 dBm
18:03:41.460 > RX Period End
18:03:41.460 > Last missing
18:03:41.460 > Request retransmit: 2
18:03:41.460 > TX RequestFrame Channel: 75 --> 15 82 92 24 50 80 18 30 88 82 D3 
18:03:41.591 > RX Period End
18:03:41.591 > Last missing
18:03:41.591 > Request retransmit: 2
18:03:41.591 > TX RequestFrame Channel: 3 --> 15 82 92 24 50 80 18 30 88 82 D3 
18:03:41.743 > RX Period End
18:03:41.743 > Last missing
18:03:41.743 > Request retransmit: 2
18:03:41.743 > TX RequestFrame Channel: 23 --> 15 82 92 24 50 80 18 30 88 82 D3 
18:03:41.808 > Interrupt received
18:03:41.946 > RX Channel: 40 --> 95 82 92 24 50 82 92 24 50 02 4D 09 00 00 4D D3 00 15 00 15 09 37 13 8F 00 00 EF | -80 dBm
18:03:41.999 > RX Period End
18:03:41.999 > Last missing
18:03:41.999 > Request retransmit: 3
18:03:41.999 > TX RequestFrame Channel: 40 --> 15 82 92 24 50 80 18 30 88 83 D2 
18:03:42.073 > Interrupt received
18:03:42.152 > RX Channel: 75 --> 95 82 92 24 50 82 92 24 50 83 00 00 00 00 00 00 01 29 00 39 7F CE B6 | -80 dBm
18:03:42.220 > RX Period End
18:03:42.220 > Success

[schlimmchen]

Hm... Ganz schön zerhackstückelt. Da kannst du natürlich nichts dafür.

Also immerhin sehen wir, dass er den Wechselrichter einschalten möchte: "Starting up inverter...". Danach sehen wir ein "TX ActivePowerControl", aber keine Indikation, dass ein PowerControl (nicht Active-) gesendet wird. Allerdings weiß ich auch nicht sicher, ob man da so sieht, wie ich es jetzt erwarte. Zu wenig Erfahrung...

Es ist natürlich möglich, dass versucht wird, den Inverter zu starten (Hoymiles Bibliothek), aber dass das Kommando nicht ankommt (zeitweise Probleme auf der Funkstrecke). Wenn deine Hysterese groß ist (30 W ist eher viel) und dein Netzbezug eher "ruhig", dann kann es sein, dass kein weiteres Einschalten versucht wird.

Auf welchem Release bist du denn gerade unterwegs, und könntest du auf das heutige aktualisieren? Da kenn ich mich jedenfalls besser aus 😁 Wenn du aktualisierst, dann lass nach Möglichkeit ansonsten mal alles, wie es ist, wenns du es einrichten kannst.

[uli-bs]

Version f018a01 vom Jun 21, 2023
Anfassen möchte ich heute allerdings nichts mehr, die Koffer stehen hier schon rum... ;)

Mittlerweile produziert er auch wieder, ohne dass ich etwas gemacht habe.
Event. gibt es aber eine "Vorgeschichte", dass der WR möglicherweise "beleidigt" war - im Log standen innerhalb weniger Minuten mehrere Stop-Vorgänge, durch entsprechende Lastwechsel, ich weiß nicht, ob es ein (zeitabhängiges?) Limit gibt, bei der Anzahl der Kommandos, bis ggf. ein Überlauf stattfindet.

[schlimmchen]

@uli-bs Kann das Issue geschlossen werden, oder hast du noch Probleme, die damit zusammenhängen?

[uli-bs]

An den Problem hat sich nichts geändert, mittlerweile läuft wieder die z.Z. aktuellste Version.
Die DTU / der WR hängt zeitweise leistungsmäßig direkt am Zähler und regelt wunderbar, dann wieder startet der WR, trotz gefülltem Akku, nicht, obwohl die Anforderung bei einigen 100W liegt.

[the-lonely-one]

Hallo, habe ein ähnliches Problem und hoffe das ich bei der Fehlersuche behilflich sein kann!

Meine Daten:
Firmwareversion: 43e836a
Chip-Modell: ESP32
Display: SSD1306
Inverter: Hoymiles HM-800

MQTT: aktiviert
DTU-Abfrageintervall: 5 Sekunden
VE.Direct: aktiviert
Power Meter: aktiviert HTTP(S) + JSON
Dynamic Power Limiter: deaktiviert
Batterie CAN Bus Schnittstelle: deaktiviert
AC Ladegerät: deaktiviert

Ich lasse über MQTT ca. alle 20 bis 30 Sekunden ein Limit für den Inverter mit dem Topic "limit_nonpersistent_absolute" setzen.
Die OpenDTU-OnBattery empfängt auch den Wert (ersichtlich über Debug-Konsole) und gibt diesen an den Inverter weiter (ebenfalls ersichtlich über Debug-Konsole).

Irgendwann (nach 1, 2, 10, 15, ... Stunden Laufzeit, ganz unterschiedlich) wird dieser Wert aber nicht mehr an den Inverter weitergeben!
Die OpenDTU-OnBattery empfängt zwar den Limit-Wert über MQTT, gibt diesen aber dann nicht mehr an den Inverter weiter!

Auch ein manuelles Limit-setzen über die Live-Ansicht: -> Limit-Einstellungen funktioniert dann nicht mehr!

Das aktuell gemeldete Limit vom Inverter bleibt unverändert!

Verbindungsprobleme zum Inverter bestehen eigentlich nicht, da ich die aktuellen Werte vom Inverter in der OpenDTU-OnBattery angezeigt bekomme!

Hier ein Auszug aus der Debug-Konsole, wenn alles funktioniert:

19:23:13.656 > Fetch inverter: 1234567890
19:23:13.708 > TX RealTimeRunData Channel: 3 --> 15 84 23 75 07 80 18 02 96 80 0B 00 64 C3 F9 80 00 00 00 00 00 00 00 00 E8 97 E6 
19:23:13.767 > Interrupt received
19:23:13.865 > RX Channel: 40 --> 95 84 23 75 07 84 23 75 07 01 00 01 01 2C 00 43 00 C8 01 F4 01 3E 06 32 00 01 CC | -80 dBm
19:23:13.924 > Interrupt received
19:23:13.972 > RX Channel: 61 --> 95 84 23 75 07 84 23 75 07 02 34 C3 00 02 3A 95 00 0E 00 7E 08 F8 13 87 06 A4 7B | -80 dBm
19:23:14.022 > Interrupt received
19:23:14.076 > RX Channel: 40 --> 95 84 23 75 07 84 23 75 07 83 00 01 00 4A 03 E8 01 6E 00 01 40 A6 3E | -80 dBm
19:23:14.172 > RX Period End
19:23:14.172 > Success
19:23:22.879 > Limit Non-Persistent: 300 W
19:23:22.929 > TX ActivePowerControl Channel: 23 --> 51 84 23 75 07 80 18 02 96 81 0B 00 0B B8 00 00 61 83 53 
19:23:22.977 > Interrupt received
19:23:23.031 > RX Channel: 40 --> D1 84 23 75 07 84 23 75 07 81 00 00 0B 00 14 07 48 | -80 dBm
19:23:23.662 > PowerMeterClass: TotalPower: 186.00
19:23:24.947 > RX Period End
19:23:24.947 > Success
19:23:28.643 > Fetch inverter: 1234567890
19:23:28.713 > TX RealTimeRunData Channel: 40 --> 15 84 23 75 07 80 18 02 96 80 0B 00 64 C3 F9 8F 00 00 00 00 00 00 00 00 18 D6 58 
19:23:28.815 > Interrupt received
19:23:28.917 > RX Channel: 40 --> 95 84 23 75 07 84 23 75 07 01 00 01 01 2C 00 44 00 CB 01 F4 01 3E 06 32 00 01 C8 | -80 dBm
19:23:28.964 > Interrupt received
19:23:29.122 > RX Channel: 40 --> 95 84 23 75 07 84 23 75 07 02 34 C3 00 02 3A 96 00 0E 00 7F 08 F6 13 86 06 A7 75 | -80 dBm
19:23:29.177 > Interrupt received
19:23:29.233 > RX Channel: 40 --> 95 84 23 75 07 84 23 75 07 83 00 01 00 4A 03 E8 01 6D 00 01 12 91 58 | -80 dBm
19:23:29.283 > RX Period End
19:23:29.283 > Success
19:23:34.151 > PowerMeterClass: TotalPower: 180.00
19:23:43.643 > Fetch inverter: 1234567890
19:23:43.705 > TX RealTimeRunData Channel: 61 --> 15 84 23 75 07 80 18 02 96 80 0B 00 64 C3 F9 9E 00 00 00 00 00 00 00 00 48 16 D9 
19:23:43.868 > Interrupt received
19:23:43.918 > RX Channel: 40 --> 95 84 23 75 07 84 23 75 07 83 00 00 00 4B 03 E8 01 6E 00 01 19 17 D6 | -80 dBm
19:23:44.452 > PowerMeterClass: TotalPower: 185.00
19:23:44.453 > RX Period End
19:23:44.453 > Middle missing
19:23:44.453 > Request retransmit: 1
19:23:44.453 > TX RequestFrame Channel: 75 --> 15 84 23 75 07 80 18 02 96 81 4D 
19:23:44.508 > Interrupt received
19:23:44.688 > RX Channel: 75 --> 95 84 23 75 07 84 23 75 07 01 00 01 01 2C 00 45 00 CE 01 F4 01 43 06 47 00 01 C4 | -80 dBm
19:23:44.789 > RX Period End
19:23:44.789 > Middle missing
19:23:44.789 > Request retransmit: 2
19:23:44.789 > TX RequestFrame Channel: 3 --> 15 84 23 75 07 80 18 02 96 82 4E 
19:23:44.850 > Interrupt received
19:23:44.994 > RX Channel: 61 --> 95 84 23 75 07 84 23 75 07 02 34 C3 00 02 3A 96 00 0E 00 7F 08 F6 13 86 06 BF 6D | -80 dBm
19:23:45.071 > RX Period End
19:23:45.071 > Success
19:23:52.823 > Limit Non-Persistent: 300 W
19:23:52.878 > TX ActivePowerControl Channel: 23 --> 51 84 23 75 07 80 18 02 96 81 0B 00 0B B8 00 00 61 83 53 
19:23:52.981 > Interrupt received
19:23:53.027 > RX Channel: 61 --> D1 84 23 75 07 84 23 75 07 81 00 00 0B 00 14 07 48 | -80 dBm
19:23:57.840 > [HttpPowerMeter] Getting the power of phase 1 failed. Error: Error(http://192.168.11.31/cm?cmnd=status%208): read Timeout
19:23:57.840 > [HttpPowerMeter] Couldn't find a value with Json query "StatusSNS/MT681/Power_cur"
19:23:57.840 > [HttpPowerMeter] Getting the power of phase 1 failed. Error: Error(http://192.168.11.31/cm?cmnd=status%208): read Timeout
19:23:57.840 > [HttpPowerMeter] Couldn't find a value with Json query "StatusSNS/MT681/Power_cur"
19:23:57.840 > PowerMeterClass: TotalPower: 185.00
19:23:57.840 > [HttpPowerMeter] Getting the power of phase 1 faiFetch inverter: 1234567890
19:23:58.693 > TX RealTimeRunData Channel: 40 --> 15 84 23 75 07 80 18 02 96 80 0B 00 64 C3 F9 AD 00 00 00 00 00 00 00 00 B9 56 5B 
19:23:58.818 > Interrupt received
19:23:58.866 > RX Channel: 61 --> 95 84 23 75 07 84 23 75 07 01 00 01 01 2C 00 46 00 D1 01 F4 01 40 06 37 00 01 AB | -80 dBm
19:23:59.023 > Interrupt received
19:23:59.127 > RX Channel: 75 --> 95 84 23 75 07 84 23 75 07 02 34 C3 00 02 3A 97 00 0E 00 80 08 F8 13 86 06 B2 90 | -80 dBm
19:23:59.181 > Interrupt received
19:23:59.230 > RX Channel: 75 --> 95 84 23 75 07 84 23 75 07 83 00 01 00 4B 03 E8 01 6D 00 01 56 D3 5F | -80 dBm
19:23:59.330 > RX Period End
19:23:59.330 > Success
19:24:07.966 > PowerMeterClass: TotalPower: 180.00
19:24:13.664 > Fetch inverter: 1234567890
19:24:13.676 > TX RealTimeRunData Channel: 61 --> 15 84 23 75 07 80 18 02 96 80 0B 00 64 C3 F9 BC 00 00 00 00 00 00 00 00 E9 96 DA 
19:24:13.766 > Interrupt received
19:24:13.869 > RX Channel: 3 --> 95 84 23 75 07 84 23 75 07 01 00 01 01 2D 00 46 00 D3 01 F4 01 3E 06 31 00 01 D0 | -80 dBm
19:24:13.971 > Interrupt received
19:24:14.018 > RX Channel: 3 --> 95 84 23 75 07 84 23 75 07 83 00 01 00 4A 03 E8 01 6E 00 01 C5 00 1D | -80 dBm
19:24:14.192 > RX Period End
19:24:14.192 > Middle missing
19:24:14.192 > Request retransmit: 2
19:24:14.192 > TX RequestFrame Channel: 75 --> 15 84 23 75 07 80 18 02 96 82 4E 
19:24:14.240 > Interrupt received
19:24:14.381 > RX Channel: 40 --> 95 84 23 75 07 84 23 75 07 02 34 C3 00 02 3A 98 00 0E 00 81 08 F9 13 86 06 AF 82 | -80 dBm
19:24:14.430 > RX Period End
19:24:14.430 > Success
19:24:18.451 > PowerMeterClass: TotalPower: 188.00
19:24:22.844 > Limit Non-Persistent: 300 W
19:24:22.920 > TX ActivePowerControl Channel: 3 --> 51 84 23 75 07 80 18 02 96 81 0B 00 0B B8 00 00 61 83 53 
19:24:23.085 > Interrupt received
19:24:23.133 > RX Channel: 61 --> D1 84 23 75 07 84 23 75 07 81 00 00 0B 00 14 07 48 | -80 dBm
19:24:25.027 > RX Period End
19:24:25.027 > Success

Und hier ein Auszug aus der Debug-Konsole, wenn das Limit nicht mehr an den Inverter weitergegeben wird:

11:51:14.219 > Fetch inverter: 1234567890
11:51:14.305 > TX RealTimeRunData Channel: 40 --> 15 84 23 75 07 80 18 02 96 80 0B 00 64 C4 E1 12 00 00 00 00 00 00 00 00 85 B8 29 
11:51:14.370 > Interrupt received
11:51:14.432 > RX Channel: 40 --> 95 84 23 75 07 84 23 75 07 01 00 01 01 3B 00 89 01 AF 01 F4 01 43 06 47 00 01 7F | -80 dBm
11:51:14.483 > Interrupt received
11:51:14.541 > RX Channel: 23 --> 95 84 23 75 07 84 23 75 07 02 35 F0 00 02 3F 6C 00 08 00 1A 09 0B 13 86 07 95 14 | -80 dBm
11:51:14.715 > Interrupt received
11:51:14.767 > RX Channel: 23 --> 95 84 23 75 07 84 23 75 07 83 00 00 00 54 03 E8 01 4C 00 01 60 E3 66 | -80 dBm
11:51:14.817 > RX Period End
11:51:14.817 > Success
11:51:18.412 > Limit Non-Persistent: 300 W
11:51:22.713 > PowerMeterClass: TotalPower: 202.00
11:51:29.253 > Fetch inverter: 1234567890
11:51:29.358 > TX RealTimeRunData Channel: 61 --> 15 84 23 75 07 80 18 02 96 80 0B 00 64 C4 E1 21 00 00 00 00 00 00 00 00 74 F8 AB 
11:51:29.410 > Interrupt received
11:51:29.465 > RX Channel: 23 --> 95 84 23 75 07 84 23 75 07 01 00 01 01 3A 00 86 01 A3 01 F4 01 43 06 47 00 01 7D | -80 dBm
11:51:29.516 > Interrupt received
11:51:29.565 > RX Channel: 40 --> 95 84 23 75 07 84 23 75 07 02 35 F0 00 02 3F 6D 00 08 00 1B 09 00 13 86 07 89 03 | -80 dBm
11:51:29.615 > Interrupt received
11:51:29.667 > RX Channel: 40 --> 95 84 23 75 07 84 23 75 07 83 00 00 00 54 03 E8 01 4C 00 01 EB E8 E6 | -80 dBm
11:51:29.786 > RX Period End
11:51:29.786 > Success
11:51:37.386 > [HttpPowerMeter] Getting the power of phase 1 failed. Error: Error(http://192.168.11.31/cm?cmnd=status%208): read Timeout
11:51:37.386 > [HttpPowerMeter] Couldn't find a value with Json query "StatusSNS/MT681/Power_cur"
11:51:37.386 > [HttpPowerMeter] Getting the power of phase 1 failed. Error: Error(http://192.168.11.31/cm?cmnd=status%208): read Timeout
11:51:37.386 > [HttpPowerMeter] Couldn't find a value with Json query "StatusSNS/MT681/Power_cur"
11:51:37.386 > PowerMeterClass: TotalPower: 202.00
11:51:38.373 > Limit Non-Persistent: 300 W
11:51:44.250 > Fetch inverter: 1234567890
11:51:44.307 > TX RealTimeRunData Channel: 75 --> 15 84 23 75 07 80 18 02 96 80 0B 00 64 C4 E1 30 00 00 00 00 00 00 00 00 24 38 2A 
11:51:44.364 > Interrupt received
11:51:44.418 > RX Channel: 23 --> 95 84 23 75 07 84 23 75 07 01 00 01 01 3A 00 81 01 96 01 F4 01 43 06 47 00 01 4F | -80 dBm
11:51:44.476 > Interrupt received
11:51:44.537 > RX Channel: 23 --> 95 84 23 75 07 84 23 75 07 02 35 F0 00 02 3F 6D 00 08 00 1B 08 FD 13 87 07 7D 0A | -80 dBm
11:51:44.615 > Interrupt received
11:51:44.674 > RX Channel: 40 --> 95 84 23 75 07 84 23 75 07 83 00 00 00 53 03 E8 01 4E 00 01 BF 6F 30 | -80 dBm
11:51:44.778 > RX Period End
11:51:44.778 > Success
11:51:47.619 > PowerMeterClass: TotalPower: 175.00
11:51:48.407 > Limit Non-Persistent: 300 W
11:51:57.767 > PowerMeterClass: TotalPower: 181.00
11:51:59.252 > Fetch inverter: 1234567890
11:51:59.329 > TX RealTimeRunData Channel: 3 --> 15 84 23 75 07 80 18 02 96 80 0B 00 64 C4 E1 3F 00 00 00 00 00 00 00 00 D4 79 94 
11:51:59.464 > Interrupt received
11:51:59.524 > RX Channel: 61 --> 95 84 23 75 07 84 23 75 07 01 00 01 01 3A 00 7E 01 8C 01 F4 01 43 06 47 00 01 AA | -80 dBm
11:51:59.586 > Interrupt received
11:51:59.662 > RX Channel: 40 --> 95 84 23 75 07 84 23 75 07 02 35 F0 00 02 3F 6E 00 08 00 1C 09 0C 13 87 07 73 F0 | -80 dBm
11:51:59.727 > Interrupt received
11:51:59.791 > RX Channel: 61 --> 95 84 23 75 07 84 23 75 07 83 00 02 00 52 03 E8 01 4E 00 01 19 8A 70 | -80 dBm
11:51:59.867 > RX Period End
11:51:59.867 > Success
11:52:08.096 > PowerMeterClass: TotalPower: 183.00
11:52:08.378 > Limit Non-Persistent: 300 W
11:52:14.254 > Fetch inverter: 1234567890
11:52:14.316 > TX RealTimeRunData Channel: 23 --> 15 84 23 75 07 80 18 02 96 80 0B 00 64 C4 E1 4E 00 00 00 00 00 00 00 00 86 11 DF 
11:52:14.382 > Interrupt received
11:52:14.440 > RX Channel: 40 --> 95 84 23 75 07 84 23 75 07 83 00 02 00 53 03 E8 01 4D 00 01 6A 6F E4 | -80 dBm
11:52:14.798 > RX Period End
11:52:14.798 > Middle missing
11:52:14.798 > Request retransmit: 1
11:52:14.798 > TX RequestFrame Channel: 40 --> 15 84 23 75 07 80 18 02 96 81 4D 
11:52:14.858 > Interrupt received
11:52:14.918 > RX Channel: 40 --> 95 84 23 75 07 84 23 75 07 01 00 01 01 39 00 7D 01 86 01 F4 01 43 06 47 00 01 A0 | -80 dBm
11:52:14.983 > RX Period End
11:52:14.983 > Middle missing
11:52:14.983 > Request retransmit: 2
11:52:14.983 > TX RequestFrame Channel: 61 --> 15 84 23 75 07 80 18 02 96 82 4E 
11:52:15.043 > Interrupt received
11:52:15.093 > RX Channel: 61 --> 95 84 23 75 07 84 23 75 07 02 35 F0 00 02 3F 6F 00 08 00 1D 08 FC 13 88 07 6E 13 | -30 dBm
11:52:15.154 > RX Period End
11:52:15.154 > Success

In diesem Auszug ist mir aufgefallen, das nach dem "Limit Non-Persistent" das "TX ActivePowerControl" fehlt und auch kein zugehöriges "Interrupt received" vorhanden ist!

Ich habe zum Test auch mal das originale openDTU-Image (v23.7.22) installiert!
Hier besteht das Problem nicht!

Hier ein Auszug aus der Debug-Konsole, wenn das originale openDTU-Image installiert ist:

18:47:09.537 > Fetch inverter: 1234567890
18:47:09.617 > TX RealTimeRunData Channel: 23 --> 15 84 23 75 07 80 18 02 96 80 0B 00 64 C6 94 0D 00 00 00 00 00 00 00 00 36 2D 67 
18:47:09.666 > Interrupt received
18:47:09.727 > RX Channel: 75 --> 95 84 23 75 07 84 23 75 07 01 00 01 01 32 00 6B 01 49 01 F4 01 3F 06 32 00 01 7B | -80 dBm
18:47:09.821 > Interrupt received
18:47:09.871 > RX Channel: 23 --> 95 84 23 75 07 84 23 75 07 02 3B 1F 00 02 4D 53 04 CE 07 19 08 FF 13 86 07 1F 01 | -30 dBm
18:47:10.028 > Interrupt received
18:47:10.079 > RX Channel: 75 --> 95 84 23 75 07 84 23 75 07 83 00 00 00 4F 03 E8 01 A9 00 0F 6A 29 56 | -80 dBm
18:47:10.131 > RX Period End
18:47:10.131 > Success
18:47:10.546 > Received MQTT message on topic: solar/1234567890/cmd/limit_nonpersistent_absolute
18:47:10.546 > Limit Non-Persistent: 300 W
18:47:10.596 > TX ActivePowerControl Channel: 40 --> 51 84 23 75 07 80 18 02 96 81 0B 00 0B B8 00 00 61 83 53 
18:47:12.616 > RX Period End
18:47:12.616 > All missing
18:47:12.616 > Nothing received, resend whole request
18:47:12.616 > TX ActivePowerControl Channel: 61 --> 51 84 23 75 07 80 18 02 96 81 0B 00 0B B8 00 00 61 83 53 
18:47:12.791 > Interrupt received
18:47:12.848 > RX Channel: 23 --> D1 84 23 75 07 84 23 75 07 81 00 00 0B 00 14 07 48 | -80 dBm
18:47:14.844 > RX Period End
18:47:14.844 > Success
18:47:14.844 > Fetch inverter: 1234567890
18:47:14.943 > TX RealTimeRunData Channel: 75 --> 15 84 23 75 07 80 18 02 96 80 0B 00 64 C6 94 12 00 00 00 00 00 00 00 00 06 A1 C4 
18:47:14.993 > Interrupt received
18:47:15.044 > RX Channel: 40 --> 95 84 23 75 07 84 23 75 07 01 00 01 01 33 00 6C 01 4A 01 F4 01 3F 06 32 00 01 7E | -80 dBm
18:47:15.094 > Interrupt received
18:47:15.146 > RX Channel: 23 --> 95 84 23 75 07 84 23 75 07 02 3B 1F 00 02 4D 53 04 CE 07 19 09 01 13 85 07 20 C2 | -80 dBm
18:47:15.249 > Interrupt received
18:47:15.300 > RX Channel: 75 --> 95 84 23 75 07 84 23 75 07 83 00 00 00 4F 03 E8 01 A9 00 0F F1 72 96 | -80 dBm
18:47:15.355 > RX Period End
18:47:15.355 > Success
18:47:19.620 > Fetch inverter: 1234567890
18:47:19.676 > TX RealTimeRunData Channel: 3 --> 15 84 23 75 07 80 18 02 96 80 0B 00 64 C6 94 17 00 00 00 00 00 00 00 00 56 9E AE 
18:47:19.730 > Interrupt received
18:47:19.857 > RX Channel: 75 --> 95 84 23 75 07 84 23 75 07 01 00 01 01 32 00 6C 01 4C 01 F4 01 43 06 47 00 01 70 | -80 dBm
18:47:19.912 > Interrupt received
18:47:20.062 > RX Channel: 23 --> 95 84 23 75 07 84 23 75 07 02 3B 1F 00 02 4D 53 04 CE 07 19 09 00 13 85 07 36 D5 | -80 dBm
18:47:20.160 > RX Period End
18:47:20.160 > Last missing
18:47:20.160 > Request retransmit: 3
18:47:20.160 > TX RequestFrame Channel: 23 --> 15 84 23 75 07 80 18 02 96 83 4F 
18:47:20.272 > RX Period End
18:47:20.272 > Last missing
18:47:20.272 > Request retransmit: 3
18:47:20.272 > TX RequestFrame Channel: 40 --> 15 84 23 75 07 80 18 02 96 83 4F 
18:47:20.393 > RX Period End
18:47:20.393 > Last missing
18:47:20.393 > Request retransmit: 3
18:47:20.393 > TX RequestFrame Channel: 61 --> 15 84 23 75 07 80 18 02 96 83 4F 
18:47:20.451 > Interrupt received
18:47:20.521 > RX Channel: 23 --> 95 84 23 75 07 84 23 75 07 83 00 02 00 50 03 E8 01 A9 00 0F 1F E9 FE | -80 dBm
18:47:20.672 > RX Period End
18:47:20.672 > Success
18:47:24.623 > Fetch inverter: 1234567890
18:47:24.671 > TX RealTimeRunData Channel: 75 --> 15 84 23 75 07 80 18 02 96 80 0B 00 64 C6 94 1C 00 00 00 00 00 00 00 00 66 ED E6 
18:47:24.726 > Interrupt received
18:47:24.875 > RX Channel: 75 --> 95 84 23 75 07 84 23 75 07 01 00 01 01 33 00 6D 01 4D 01 F4 01 43 06 47 00 01 71 | -80 dBm
18:47:24.932 > Interrupt received
18:47:25.081 > RX Channel: 40 --> 95 84 23 75 07 84 23 75 07 02 3B 1F 00 02 4D 53 04 CE 07 19 08 FF 13 86 07 37 29 | -80 dBm
18:47:25.184 > RX Period End
18:47:25.184 > Last missing
18:47:25.184 > Request retransmit: 3
18:47:25.184 > TX RequestFrame Channel: 3 --> 15 84 23 75 07 80 18 02 96 83 4F 
18:47:25.236 > Interrupt received
18:47:25.289 > RX Channel: 75 --> 95 84 23 75 07 84 23 75 07 83 00 02 00 50 03 E8 01 A9 00 0F 0C AE AA | -80 dBm
18:47:25.337 > RX Period End
18:47:25.337 > Success
18:47:29.625 > Fetch inverter: 1234567890
18:47:29.891 > TX RealTimeRunData Channel: 23 --> 15 84 23 75 07 80 18 02 96 80 0B 00 64 C6 94 21 00 00 00 00 00 00 00 00 F7 E1 46 
18:47:29.944 > Interrupt received
18:47:30.098 > RX Channel: 23 --> 95 84 23 75 07 84 23 75 07 01 00 01 01 33 00 6D 01 4F 01 F4 01 3F 06 32 00 01 7A | -80 dBm
18:47:30.154 > Interrupt received
18:47:30.302 > RX Channel: 23 --> 95 84 23 75 07 84 23 75 07 02 3B 1F 00 02 4D 53 04 CE 07 19 08 FF 13 86 07 25 3B | -30 dBm
18:47:30.355 > Interrupt received
18:47:30.405 > Interrupt received
18:47:30.456 > RX Channel: 23 --> 95 84 23 75 07 84 23 75 07 83 00 00 00 4F 03 E8 01 A9 00 0F BE 5C F7 | -30 dBm
18:47:30.521 > RX Period End
18:47:30.521 > Success
18:47:30.570 > Received MQTT message on topic: solar/1234567890/cmd/limit_nonpersistent_absolute
18:47:30.570 > Limit Non-Persistent: 300 W
18:47:30.711 > TX ActivePowerControl Channel: 40 --> 51 84 23 75 07 80 18 02 96 81 0B 00 0B B8 00 00 61 83 53 
18:47:30.813 > Interrupt received
18:47:30.915 > RX Channel: 75 --> D1 84 23 75 07 84 23 75 07 81 00 00 0B 00 14 07 48 | -80 dBm
18:47:32.676 > RX Period End
18:47:32.676 > Success
18:47:34.629 > Fetch inverter: 1234567890
18:47:34.680 > TX RealTimeRunData Channel: 61 --> 15 84 23 75 07 80 18 02 96 80 0B 00 64 C6 94 26 00 00 00 00 00 00 00 00 C7 C7 57 
18:47:34.909 > Interrupt received
18:47:34.963 > RX Channel: 40 --> 95 84 23 75 07 84 23 75 07 01 00 01 01 33 00 6E 01 50 01 F4 01 3F 06 32 00 01 66 | -80 dBm
18:47:35.009 > Interrupt received
18:47:35.120 > RX Channel: 40 --> 95 84 23 75 07 84 23 75 07 02 3B 1F 00 02 4D 54 04 CE 07 1A 08 FE 13 86 07 26 3D | -80 dBm
18:47:35.216 > Interrupt received
18:47:35.320 > RX Channel: 75 --> 95 84 23 75 07 84 23 75 07 83 00 00 00 50 03 E8 01 A9 00 0F 4F A7 E2 | -80 dBm
18:47:35.421 > RX Period End
18:47:35.421 > Success

Die Meldungen sind ähnlich zur OpenDTU-OnBattery!
Aufgefallen ist mir aber, das hier zusätzlich noch die Meldung: "Received MQTT message on topic: solar/1234567890/cmd/limit_nonpersistent_absolute" vorhanden ist,
die es bei OpenDTU-OnBattery nicht gibt!

Bevor ich es noch vergesse!

Finde das Projekt: "OpenDTU-OnBattery" echt genial und ziehe meinen Hut!

[helgeerbe]

@schlimmchen kann das irgendwas mit #287 zu tun haben, wenn sich die originalDTU und -onBattery unterschiedlich verhalten? Allerdings ist bei mir noch nicht aufgetreten.

[uli-bs]

Mir sieht das nach einer Art "Überlauf" aus:
Nach dem Start funktioniert alles und nach unterschiedlicher Zeit eben nicht mehr, bis es irgendwann, nach Neustart, oder auch ohne Eingriff, wieder funktioniert.

[schlimmchen]

Hallo, habe ein ähnliches Problem und hoffe das ich bei der Fehlersuche behilflich sein kann!

@the-lonely-one Danke für deine ausführliche Beschreibung.

Mir fäll auf, dass der espMqttClient scheinbar in einem eigenen Task läuft, weil wir den Konstruktor ohne Argumente verwenden (kann man im Code nachschauen). Das würde bedeuten, dass der MQTT Client asynchron zur loop() läuft. Das heißt wohl wiederum, dass alle Subscriber asynchron zur loop() laufen. Dass das immer reibungslos ist, wage ich anzuzweifeln.

Mein Gefühl ist es, dass meine Änderung 8b23324 womöglich Teil des hier diskutierten Problems ist. Das würde allerdings bedeuten, dass bereits ein anderes Problem vorliegt, nämlich dass CMD_PENDING gesetzt wird nachdem das Kommando bereits verarbeitet wurde.

Das ist theoretisch möglich: Der MQTT Task benutzt sendActivePowerControlRequest und wird unterbrochen, nachdem das Kommando in der Queue gelandet ist und bevor setLastLimitCommandSuccess(CMD_PENDING) im Kontext des MQTT Task aufgerufen wird. In dieser Unterbrechung läuft die loop() und verarbeitet das Kommando (oder wirft es weg, weil die Seriennummer noch nicht gesetzt wurde...) und die Antwort des Inverters wird notiert: CMD_OK (oder CMD_NOK). Das Scheduling wechselt wieder und der MQTT Task setzt in seinem Kontext setLastLimitCommandSuccess(CMD_PENDING). Dann ist sendActivePowerControlRequest für immer gesperrt, denn es gibt kein weiteres Kommando in der Queue, das CMD_PENDING zurücksetzen würde und es kann auch keins mehr reinkommen weil CMD_PENDING gesetzt ist.

Man könnte ein Pflaster basteln, aber das macht natürlich keinen Sinn, weil meiner Einschätzung nach alle Leute immer davon ausgehen, dass ihr Code synchron in der loop() läuft, was wegen des MQTT Clients aber nicht der Fall zu sein scheint.

Der MQTT Client darf keinen internen Task benutzen, um seine loop() aufzurufen. Stattdessen muss die MQTT loop() synchron im Kontext der main loop() aufgerufen werden.

Eine enstprechende Änderung habe ich vorbereitet und grundsätzlich auf meiner Platform verifiziert (MQTT funktioniert wie gewohnt). @the-lonely-one welchen Typ Firmware brauchst du? Ich würde dir gerne eine Vorabversion bauen, die du testen könntest. Wenn ich es richtig verstanden habe, tritt das Problem bei dir ja recht zuverlässig auf, da könnten wir nach 24h ohne dein Problem schon davon ausgehen, dass es in der Tat behoben wurde.

Es macht übrigens Sinn, dass viele Leute dieses Problem nie sehen, weil sie selten oder gar nicht MQTT nutzen, um den Inverter zu steuern. Es braucht schon meine oben verlinkte Änderung und ein häufiges Steuern des Inverters durch MQTT, um diese Race Condition zu treffen.

[schlimmchen]

kann das irgendwas mit #287 zu tun haben, wenn sich die originalDTU und -onBattery unterschiedlich verhalten? Allerdings ist bei mir noch nicht aufgetreten.

@helgeerbe Benutzt du MQTT, um deine Inverter zu steuern?

Meiner Einschätzung nach reden wir in diesem Issue jetzt von mindestens zwei Problemen. Wenn ich @the-lonely-one richtig verstanden habe, dann hat meine Änderung, nur Commands vom selben Typ in die Queue zu lassen, wenn noch keins drin ist, dazu geführt, dass der MQTT Client Task zu einem realen Problem wird. Das hab ich ja im vorherigen Kommentar ausführlich beschrieben.

@uli-bs schreibt aber davon, dass er lauter DTU command failed / Error 2 sieht und den Inverter neu starten muss. Damit hab ich hoffentlich nichts zu tun. Also ich hoffe es nicht nur, sondern ich hab da schon drüber nachgedacht, und ich sehe es nicht, dass ich da helfen kann.

[the-lonely-one]

@schlimmchen Die Antwort ging ja echt schnell

Ich habe einen ESP32 und hatte zuletzt die OpenDTU-OnBattery Firmwareversion: 43e836a drauf, bei der aktuell auch das Problem vorhanden ist.
Somit bräuchte ich eine neu "opendtu-onbattery-generic_esp32.bin" oder eine neue "opendtu-onbattery-generic_esp32.factory.bin"

[schlimmchen]

@the-lonely-one Dann freue ich mich, wenn du für uns einmal die Firmware aus https://github.com/schlimmchen/OpenDTU-OnBattery/releases/tag/mqtt-no-task ausprobieren könntest und berichtest.

[the-lonely-one]

@schlimmchen Test läuft

Schaut aktuell gut aus! Meldungen in der Debug-Konsole sind jetzt ähnlich zur originalen OpenDTU!
Lasse das Ganze mal einen Tag durchlaufen und melde mich dann morgen Abend nochmal!

[helgeerbe]

Sollte mit der 2023.08.01 gefixt sein. Ich lasse das Ticket noch offen, damit @the-lonely-one seine Rückmeldung geben kann.

[the-lonely-one]

@schlimmchen Und läuft und läuft und läuft!!!

Nach dem ich gestern Abend meine DTU mit der von dir bereitgestellten Firmwareversion "aca46f2" aktualisiert habe, ist das von mir beschriebene Problem nicht mehr aufgetreten!

Aktuell läuft meine DTU seit ca. 22 Stunden durchgehend ohne Probleme!

Die Randbedingungen waren in diesem Zeitraum gleich:
Habe über MQTT alle 20 Sekunden ein Limit für den Inverter mit dem Topic "limit_nonpersistent_absolute" setzen lassen.

Danke dir nochmal, für die schnelle Bearbeitung!

[schlimmchen]

@the-lonely-one Sehr gerne, war ein spannender Fehler.

Also nehmen wir mal an, dass es in der Tat ein Problem/Fehler war und dass das Problem bei dir nicht mehr auftritt, weil du es bisher mindestens nach 15h beobachtet hast. Ich erstelle dann noch einen Pull-Request gegen das Upstream-Projekt und verlinkte deine ausführliche Fehlerbeschreibung.

[the-lonely-one]

@schlimmchen Limit Vorgabe für meinen Inverter über MQTT funktioniert bisher immer noch ohne Probleme!

Mir ist nun aber etwas anderes aufgefallen.
Und zwar wird mir der Wert: "Inverter Gesamtertrag Heute" mehrmals am Tag auf 0 zurückgesetzt!

Siehe Chart:
(Y-Achse sind "Wh")

Vom 31.07. bis zum 02.08. hatte ich die von dir bereitgestellte Firmware-Version zum testen installiert. Aktuell ist die Firmware: 81864b3 installiert, bei der aber ebenfalls das Problem besteht!
An den bisher genannten Einstellungen an der OpenDTU-OnBattery habe ich nichts geändert!
Selben Bedingungen wie bisher!

Laut dem Webinterface von meiner OpenDTU-OnBattery kann ich weder Neustarts von meiner DTU selbst noch von meinem Hoymiles-Inverter nachvollziehen.
Wird eigentlich der Wert: "Inverter Gesamtertrag Heute" in der OpenDTU berechnet oder vom Hoymiles-Inverter bereitgestellt?

Ich vermute mal, das mein Problem etwas mit der Web-API bzw. mit der Webserver-Implementierung zu tun, das aktuell bei OpenDTU als Pull Request #1201 diskutiert wird!

[schlimmchen]

Limit Vorgabe für meinen Inverter über MQTT funktioniert bisher immer noch ohne Probleme!

Das freut mich zu lesen!

Kopierst du deine Frage nach dem Zurücksetzen der Inverter-Tagesleistung bitte in ein neues Issue?

[schlimmchen]

@the-lonely-one Ich würde mich freuen, wenn du uns erfahren lässt, ob dein Problem mit dem Release aus Dezember 2023 oder neuer wieder auftritt. Halt da doch mal ein Auge drauf, bitte.

[github-actions]

This issue has been automatically locked since there has not been any recent activity after it was closed. Please open a new discussion or issue for related concerns.