Keine Aktualisierung im Sunny-Portal nach MQTT-Broker Down/Up

[J0EK3R]

Erst mal ein großes Lob an Dich Axel, für das Erstellen dieses kleinen Software-Juwels! :)

...dann zu meinem Problem:

Bei mir läuft folgende Konstellation:

• MQTT-Broker (Mosquitto) als Docker-Container auf anderem Rechner (QNAP NAS)
• SAE (V2.1.0) auf einem Raspberry - manuelle Installation -> Mehrere Geräte im SAE, die nur messen (u.A. Energy mehrerer Shellys über http)

Die Konstellation funktioniert soweit prima - im Sunny-Portal wird der aktuelle Verbrauch der Geräte aufgezeichnet und angezeigt (-> Reiter "Aktuell").

Stoppe ich nun den MQTT-Broker und starte ihn neu, dann werden die Werte im Sunny-Portal nicht mehr aktualisiert, die "alten Werte" bleiben stehen. Erst ein Neustart des SAE behebt das Problem.

---

Der SAE macht nach dem Neustart des MQTT-Brokers einen Reconnect auf diesen, es werden neue Messages mit aktualisierten Werten vom SAE verschickt. Dennoch muss sich da intern etwas verhaken, es kommen keine aktualisierten Werte nicht im Sunny-Portal an. ...oder ich mach was falsch. ;)

[J0EK3R]

Ich versuch mal, mehr Infos zu liefern...

Hier die Ausgabe aus dem aktuellen rolling.log nach dem Aus-Ein des MQTT-Brokers.

HTTP-Abfrage 2023-01-25 15:47:30,802 DEBUG [Timer-0] d.a.s.h.HttpTransactionExecutor [HttpTransactionExecutor.java:78] F-00000000-000000000008-00: HTTP request: method=GET url=http://nous06.fritz.box/cm?user=user&password=passwort&cmnd=Status%208 data=null 2023-01-25 15:47:30,836 DEBUG [Timer-0] d.a.s.h.HttpTransactionExecutor [HttpTransactionExecutor.java:150] F-00000000-000000000008-00: Response code is 200

HTTPHandler 2023-01-25 15:47:30,843 DEBUG [Timer-0] d.a.s.h.HttpHandler [HttpHandler.java:99] F-00000000-000000000008-00: url=http://nous06.fritz.box/cm?user=user&password=passwort&cmnd=Status%208 method=GET data=null path=$.StatusSNS.ENERGY.Total 2023-01-25 15:47:30,843 DEBUG [Timer-0] d.a.s.h.HttpHandler [HttpHandler.java:101] F-00000000-000000000008-00: Response: {"StatusSNS":{"Time":"2023-01-25T15:47:31","ENERGY":{"TotalStartTime":"2022-12-25T13:31:53","Total":18.74432,"Yesterday":2.00594,"Today":0.07682,"Power":150,"ApparentPower":179,"ReactivePower":97,"Factor":0.84,"Voltage":231,"Current":0.773}}} 2023-01-25 15:47:30,844 DEBUG [Timer-0] d.a.s.h.HttpHandler [HttpHandler.java:67] F-00000000-000000000008-00: value=18.74432 protocolHandlerValue=18.74432 valueExtractionRegex=null extractedValue=null factorToValue=null

Berechnung Leistung -> Ergebnis 150 Watt 2023-01-25 15:47:30,845 DEBUG [Timer-0] d.a.s.m.PollEnergyMeter [PollEnergyMeter.java:105] F-00000000-000000000008-00: Calculating power from energy: power=150 currentEnergyCounter=18.74432 previousEnergyCounter=18.74181 diffEnergy=0.00251 diffTime=60000 2023-01-25 15:47:30,845 TRACE [Timer-0] d.a.s.m.PollEnergyMeter [PollEnergyMeter.java:127] F-00000000-000000000008-00: energy=0.07681999999999789kWh totalEnergy=null startEnergyCounter=18.6675 currentEnergyCounter=18.74432 started=true

MQTT-Publish -> mit korrektem Wert für Power = 150 2023-01-25 15:47:30,846 TRACE [pool-3-thread-1] d.a.s.m.MqttClient [MqttClient.java:237] F-00000000-000000000008-00-MQTT-HttpElectricityMeter: Publish message: topic=sae/F-00000000-000000000008-00/Meter payload={"energy":0.07681999999999789,"power":150,"time":"2023-01-25T15:47:30.802252","type":"MeterMessage"}

TimeframeInterval 2023-01-25 15:47:35,924 TRACE [Timer-0] d.a.s.u.GuardedTimerTask [GuardedTimerTask.java:54] F-00000000-000000000008-00: Executing timer task name=UpdateActiveTimeframeInterval id=27650392 2023-01-25 15:47:35,925 DEBUG [Timer-0] d.a.s.s.TimeframeIntervalHandler [TimeframeIntervalHandler.java:199] F-00000000-000000000008-00: Current Queue is empty

MQTT-Publish TimeframeIntervalQueue 2023-01-25 15:47:35,926 TRACE [pool-3-thread-1] d.a.s.m.MqttClient [MqttClient.java:237] F-00000000-000000000008-00-MQTT-Appliance: Publish message: topic=sae/F-00000000-000000000008-00/TimeframeIntervalQueue payload={"entries":[],"time":"2023-01-25T15:47:35.925422","type":"TimeframeIntervalQueueMessage"}

MqttPublish-MeterReportingSwitch 2023-01-25 15:47:35,989 TRACE [Timer-0] d.a.s.u.GuardedTimerTask [GuardedTimerTask.java:54] F-00000000-000000000008-00: Executing timer task name=MqttPublish-MeterReportingSwitch id=8629392 2023-01-25 15:47:55,989 TRACE [Timer-0] d.a.s.u.GuardedTimerTask [GuardedTimerTask.java:54] F-00000000-000000000008-00: Executing timer task name=MqttPublish-MeterReportingSwitch id=8629392

SempController-DeviceInfo 2023-01-25 15:47:56,639 DEBUG [http-nio-8080-exec-9] d.a.s.s.w.SempController [SempController.java:162] F-00000000-000000000008-00: DeviceInfo{characteristics=Characteristics{maxPowerConsumption=1000, minPowerConsumption=null, minOnTime=null, maxOnTime=null, minOffTime=null, maxOffTime=null}, capabilities=Capabilities{currentPowerMethod=Measurement, absoluteTimestamps=false, interruptionsAllowed=false, optionalEnergy=false}}

SempController-DeviceStatus 2023-01-25 15:47:56,654 DEBUG [http-nio-8080-exec-9] d.a.s.s.w.SempController [SempController.java:333] F-00000000-000000000008-00: Reporting device status from control 2023-01-25 15:47:56,655 DEBUG [http-nio-8080-exec-9] d.a.s.s.w.SempController [SempController.java:342] F-00000000-000000000008-00: DeviceStatus{eMSignalsAccepted=false, status=On, errorCode=null}

SempController-PowerInfo - und hier ist das Problem: der Wert für averagePower wurde nicht auf 150 aktualisiert! 149 ist der "alte" Werte vor dem Aus-An des MQTT-Brokers 2023-01-25 15:47:56,655 DEBUG [http-nio-8080-exec-9] d.a.s.s.w.SempController [SempController.java:348] F-00000000-000000000008-00: Reporting power info from meter. 2023-01-25 15:47:56,656 DEBUG [http-nio-8080-exec-9] d.a.s.s.w.SempController [SempController.java:362] F-00000000-000000000008-00: PowerInfo{averagePower=149, minPower=null, maxPower=null, timestamp=0, averagingInterval=60}

[camueller]

Wie oft startest Du den Mosquitto neu? Es ist zwar unschön, wenn man den SAE neu starten muss, nachdem der MQTT-Broker neu gestartet wurde, aber in der Praxis sollte es kaum eine Rolle spielen, weil der MQTT-Broker nie restartet wird.

[J0EK3R]

...momentan starte ich den MQTT-Broker häufiger, um den Bug im SAE einzugrenzen ;)

Mosquitto läuft bei mir auf dem NAS im Docker. Du hast recht, oft wird er nicht neu gestartet - aber wenn, dann sollte sich doch alles wieder richtig einhängen...

SAE macht das ja auch - die verschickten MQTT-Nachrichten passen ja. Nur nicht die per SEMP verschickten.

[camueller]

Habe diesen Hinweis zum Verhalten von Eclipse Paho gefunden (MQTT-Bibliothek, welche auch der SAE verwendet): https://github.com/eclipse/paho.mqtt.golang/issues/238

Ich habe testweise das CleanSession=false gesetzt und eine modifzierte 2.1.0 gebaut: https://drive.google.com/file/d/1bNQuNkFTF6O9aL-4Jh3Sze1_YXXxreAE/view?usp=share_link

Kannst Du bitte testen, ob das Dein Problem löst?

[J0EK3R]

Klar, mach ich gerne. Meld' mich die Tage.

Vielen Dank schon mal und beste Grüße :)

[J0EK3R]

Moin Axel, habe die Testversion ausprobiert. Leider ohne Erfolg - die Werte im Sunny-Portal ändern sich nach einem MQTT-Broker off/on nicht mehr.

Ich hab mir mal Deinen Code angeschaut - das Problem scheinen wirklich die ausgehängten Subscriptions im SempController zu sein. Wenn die nicht mehr kommen, werden die "meterMessages" nicht mehr aktualisiert:

mqttClient.subscribe(meterTopic, false, (topic, message) -> { this.meterMessages.put(topic, (MeterMessage) message); }); Das entspricht genau dem Fehlerbild.

In https://github.com/eclipse/paho.mqtt.golang/issues/238 werden ja zwei Lösungen angeboten:

To resolve this either set cleansession to false (but be aware that when you disconnect for the final time your session information may still be left on the server), or do your subscriptions in the OnConnect handler, as this is called every time you are connected even if autoreconnect does it.

Die erste - cleansession to false - hat bei uns wohl nicht so funktioniert. Die bevorzugte Lösung ist wohl die zweite, "OnConnect" - die allerdings mit Mehraufwand von Dir verbunden ist: Deine Klasse "MqttClient" müsste das OnConnect durchreichen, damit der SempController die Subscriptions erneuern könnte...

[camueller]

Ich hatte gestern schon vermutet, dass das cleansession nicht reicht. Daraufhin hatte ich zunächst daran gedacht, den asynchronen MQTT-Client von Paho zu verwenden, aber habe eine Lösung für den synchronen Client gefunden, den ich aktuell verwende.

Anders als von Dir vorgeschlagen wollte ich aber möglichst die MQTT-Logik weiterhin in der Klasse MqttClient kapseln. Das ist mir gelungen und nach einem Reconnect werden die Subscriptions erneuert - das habe ich erfolgreich getestet. Im Ergebnis kommen neue Werte im SempController an. Falls es Dich interessiert - hier ist der modifizierte MqttClient.

Hier nochmals eine Test-Version für Dich: https://drive.google.com/file/d/1N3wiGa-aWe7oIeMxwjzYOjcMZS1XMT20/view?usp=share_link

[camueller]

Habe die Testversion auf meinen Produktiv-Raspi eingespielt. Da kommt es teilweise zu Fehlern - ich schaue mir das nochmal an ...

[J0EK3R]

Habe gerade Deine Änderung im MqttClient angeschaut. Auf den ersten Blick sieht das gut aus. Vielleicht komm ich morgen zum Testen.

Wäre eine Log-Ausgabe in der Methode "connectComplete", in der die subscriptions eingehängt werden, zum Debuggen nicht sinnvoll? Und vielleicht auch in "connectionLost"?

[camueller]

Ich denke, der Fehler sollte gefixt sein. Zumindest gibt es keine Fehler mehr auf meinem Produktiv-Raspi.

Hier die neue Test-Version (der Link von vorhin ist nicht mehr gültig): https://drive.google.com/file/d/1O6XbH-82TdpkBB2pZhAcyWIYJi0q91jT/view?usp=share_link

[camueller]

Wäre eine Log-Ausgabe in der Methode "connectComplete", in der die subscriptions eingehängt werden, zum Debuggen nicht sinnvoll? Und vielleicht auch in "connectionLost"?

In "connectionLost" hatte ich das schon gemacht. Habe es jetzt auch in "connectComplete" ergänzt (allerdings mit Log-Level TRACE).

Also hier nochmal eine neue Testversion (der Link von vorhin ist nicht mehr gültig): https://drive.google.com/file/d/1jotT5zSm4cjh12j5_0-1bVGgI7MZFKbH/view?usp=share_link

[J0EK3R]

Hallo Axel,

hab die Testversion ausprobiert: prinzipiell funktioniert der Reconnect am MQTT-Broker - das ist gut.

Ich habe den MQTT-Broker mehrfach aus/an geschaltet und mir dabei die Log-Ausgabe angeschaut... Da kommt mir etwas seltsam vor: warum macht z.B. Gerät A eine Subscription auf das Topic von Gerät B? 2023-01-27 15:06:47,868 DEBUG [MQTT Call: F-00000000-000000000008-00-MeterReportingSwitch-0] d.a.s.m.MqttClient [MqttClient.java:307] F-00000000-000000000008-00-MQTT-MeterReportingSwitch: Messages subscribed: topic=sae/F-00000000-000000000005-00/Event/DisableRuntimeRequest

Außerdem habe ich den Eindruck, dass mit jedem Stop/Start des Mqtt-Brokers immer mehr Subsriptions gemacht werden...?

Ich denke, es liegt an dem statischen messageHandlerForSubscribedTopic. Die Map gehört doch in die Instanz des MqttClient - also nicht statisch...?!

[camueller]

Da hast Du völlig Recht!! Ich hatte die Map-Zeile von der darüberstehen Map-Zeile kopiert, die statisch sein soll, aber messageHandlerForSubscribedTopic soll nicht statisch sein. Es ist schön, wenn man mal mit Jemandem zu tun hat, der den Code versteht :-)

Hier eine neue Testversion: https://drive.google.com/file/d/1hjDZ2_ncvgQucdFlA_bnHXAHkCV9TxJh/view?usp=share_link

[J0EK3R]

Es ist schön, wenn man mal mit Jemandem zu tun hat, der den Code versteht :-)

Dito ;) ...und Fehlersuchen in Firmware ist auch noch mein Job - bin aber eher bei C# daheim :)

Dann freu ich mich auf die nächste Testversion. - Ist ja schon da...

[camueller]

Fehlersuchen in Firmware ist auch noch mein Job

Deine Erfahrung darin war hier auf jeden Fall hilfreich.

Eigentlich hatte ich Deinem Issue zunächst aus meiner Sicht keine hohe Prio gegeben, aber nachdem Du die Logs so sorgfältig analysiert hast, hat mich das motiviert, der Sache auf den Grund zu gehen. Und zugegebenermassen macht es den SAE stabiler und vermeidet sicher den einen oder anderen Hilferuf mit weniger guter Fehleranalyse.

Eigentlich sollte es wesentlich mehr Unit-Tests für den SAE geben, aber solange der SAE für mich produktiv funktioniert, habe ich nicht allzuviel Motivation dazu. Die Web-Oberfläche wird durch automatisierte e2e-Tests weitgehend getestet, damit sichergestellt ist, dass die Konfigurationen vorgenommen werden können und gespeichert werden.

[J0EK3R]

Eigentlich hatte ich Deinem Issue zunächst aus meiner Sicht keine hohe Prio gegeben, aber nachdem Du die Logs so sorgfältig analysiert hast, hat mich das motiviert, der Sache auf den Grund zu gehen. Und zugegebenermassen macht es den SAE stabiler und vermeidet sicher den einen oder anderen Hilferuf mit weniger guter Fehleranalyse.

Vielen Dank, das freut mich! Und auch, dass Deine Änderungen immer ruckzuck kamen.

Und: Auf den ersten und auch den zweiten Blick passt es jetzt. Die Log-Ausgaben sind auch nicht mehr auffällig.

Ich sag schon mal vielen Dank! :)

[camueller]

Kommt mit SAE 2.2.0.

[J0EK3R]

Hallo Axel,

ich habe mir die Änderung mit dem Zwischenspeichern der Subscriptions in messageHandlerForSubscribedTopic nochmal in Ruhe angeschaut...

Ich denke, Put und auch Remove von Topic und Handler sollten nicht von connect() abhängig sein, sollten also aus dem if(connect())-Block raus.

Dann ist mir noch was aufgefallen: kann es sein, dass das "messageHandlerForSubscribedTopic.put" eher in die private Methode subscribe gehört? Also die, die auch client.subscribe aufruft?!

[camueller]

Ich denke, Put und auch Remove von Topic und Handler sollten nicht von connect() abhängig sein, sollten also aus dem if(connect())-Block raus.

Ja, dann klappt es auch, wenn die Verbindung verzögert hergestellt werden kann.

Dann ist mir noch was aufgefallen: kann es sein, dass das "messageHandlerForSubscribedTopic.put" eher in die private Methode subscribe gehört? Also die, die auch client.subscribe aufruft?!

Diese private subscribe-Methode unterstellt, dass der MessageHandler bereits im Cache ist. Es würde zwar nciht schaden, das put hierhin zu verlagern, aber dann wäre das beabsichtige Verhalten nicht so klar. Um das zu verdeutlichen, habe ich die Methode umbenannt und sie bekommt nur noch das Topic übergeben und sucht sich den MessageHandler selbst im Cache.

Habe die modifizierte Version auf meinen Produktiv-Raspi gespielt. Wäre gut, wenn Du auch nochmal testen könntest, da ich demnächst die 2.2.0 releasen möchte: https://drive.google.com/file/d/1fqj_2WmZngoGW1lZgvQez8lTPebtUeRB/view?usp=share_link

[J0EK3R]

Moinmoin Axel,

habe die neuste Version getestet und die Änderungen angeschaut: sieht gut aus! :)

Ich habe den SAE sogar auf den ausgeschalteten MQTT-Broker gestartet und er hat sich gefangen und läuft! MQTT-Broker aus/an hat folglich auch funktioniert.

Eine Kleinigkeit könnte man noch verbessern:

Folgende Exception wird geloggt; sieht immer unschön aus - die Exception könnte man noch abfangen und durch eine "normale" Log-Ausgabe ersetzen...

2023-01-29 07:14:14,689 ERROR [pool-3-thread-1] d.a.s.m.MqttClient [MqttClient.java:189] F-00000000-000000000010-00-MQTT-Appliance: Error connecting to MQTT broker org.eclipse.paho.client.mqttv3.MqttException: Verbindungsherstellung wird ausgeführt at org.eclipse.paho.client.mqttv3.MqttAsyncClient.connect(MqttAsyncClient.java:726) at org.eclipse.paho.client.mqttv3.MqttClient.connect(MqttClient.java:331) at de.avanux.smartapplianceenabler.mqtt.MqttClient.connect(MqttClient.java:179) at de.avanux.smartapplianceenabler.mqtt.MqttClient.lambda$publishMessage$0(MqttClient.java:262) at java.base/java.util.concurrent.Executors$RunnableAdapter.call(Executors.java:515) at java.base/java.util.concurrent.FutureTask.run(FutureTask.java:264) at java.base/java.util.concurrent.ThreadPoolExecutor.runWorker(ThreadPoolExecutor.java:1128) at java.base/java.util.concurrent.ThreadPoolExecutor$Worker.run(ThreadPoolExecutor.java:628) at java.base/java.lang.Thread.run(Thread.java:829)

Beste Grüße und nen schönen Sonntag Jochen

[camueller]

Die Log-Ausgabe ist unschön, aber sollte eigentlich nicht auftreten und deutet auf einen Fehler in der MQTT-Bibliothek hin. Allerdings scheint Eclipse Paho nicht wirklich aktiv weiterentwickelt zu werden ...