Failed to publish topic - MQTT

[raebbaer]

The Problem

Das ESP32 Modul läuft ohne Probleme, setzt die aufgenommenen Bilder auch 100% korrekt in Zahlenwerte um und bringt nach einer Zeit X (und ich habe noch keinen zeitlichen Zusammenhang feststellen können) folgende Fehlermeldung:

[0d21h46m41s] 2023-02-06T18:40:18 [MQTT IF] Failed to publish topic 'gas/freeMem', skipping all MQTT publishings in this round!

Danach bleiben die MQTT Pakete aus, auch wenn der ESP32 nach wie vor Bilder macht und digitalisiert. Von daher bekommt der Home Assistant keine neuen Daten mehr geliefert. Ich verwende die neuste HA-Version mit mosquitto broker.

Herzlichen Dank im Voraus.

Version

14.0.3

Logfile

[0d21h46m41s] 2023-02-06T18:40:18	<ERR>	[MQTT IF] Failed to publish topic 'gas/freeMem', skipping all MQTT publishings in this round!

Expected Behavior

Der ESP32 sollte seinen Dienst im Bereich MQTT nicht nach einer undefinierten Zeit einstellen. Und wenn der Fehler auftritt, sollte der MQTT-Dienst automatisiert neugestartet werden. Ich muss allerdings händisch rebooten, um wieder neue Pakete zu erhalten.

Screenshots

No response

Additional Context

No response

[Slider0007]

Aus welchen Gründen auch immer scheint der MQTT Service nicht der stabilste zu sein. Ein automatischer Reconnect ist bereits implementiert. Der Dienst versucht sich alle 15s neu zu verbinden. In der Regel klappt das bisher auch immer, wodurch die Daten in der Folgerunde wieder übermittelt werden. Warum dies bei dir nicht passiert ist, ist schwer zu sagen. Gab es im Log irgendwelche weitere Fehlermeldungen bzw. sonstiges Auffälligkeiten? Ist die WLAN Verbindung stabil?

[raebbaer]

Ich habe das Verhalten jetzt einen Tag lang beobachtet. Die WLAN-Verbindung ist stabil. Ich habe einen AP direkt neben das Modul gehängt, um Verbindungsprobleme auszuschließen. Ich habe im Protokoll allerdings in der Tat eine Auffälligkeit gefunden. Der MQTT Fehler tritt immer dann auf, wenn der aktuell gelesene Wert kleiner als der vorherige Wert war und "negative Werte nicht zulassen" eingestellt ist. Schaut man sich aber händisch den aktuell gelesenen Wert an, ist er wieder höher und wird auch richtig erkannt. Es scheint aber einen Zusammenhang zwischen dem Abfangen des negativen Wertes und dem MQTT Service zu geben.

[Slider0007]

Der MQTT Fehler tritt immer dann auf, wenn der aktuell gelesene Wert kleiner als der vorherige Wert war und "negative Werte nicht zulassen" eingestellt ist. Schaut man sich aber händisch den aktuell gelesenen Wert an, ist er wieder höher und wird auch richtig erkannt. Es scheint aber einen Zusammenhang zwischen dem Abfangen des negativen Wertes und dem MQTT Service zu geben.

Meinst du hierbei Fehler im Sinne des Fehlers im Log wie oben beschrieben <ERR> [MQTT IF] Failed to publish topic 'gas/freeMem', skipping all MQTT publishings in this round! oder einfach den "Fehler", dass in diesem Fall keine Werte über MQTT gesendet werden?

[raebbaer]

Es tritt in der Tat beides ein. Die Zeile mit dem steht im Log und danach werden auch keine Werte mehr gesendet. Ich lasse parallel den MQTT Explorer mitlaufen und auch der sieht keine Übergabe der Werte mehr.

[raebbaer]

Ich habe jetzt noch ein bisschen gespielt. Wenn ich beim MQTT Dienst alles abstelle, das ich abstellen kann (z.B. HA Pakete) und im HA die Definition des Sensors händisch in die configuration.yaml eintrage, läuft das System signifikant stabiler. Dann funktioniert auch der Neustart des MQTT Dienstes. Zumindest läuft er jetzt schon seit 12 Stunden, was vorher nicht möglich war. Kann es sein, dass das Device einfach zu viele MQTT Informationen im Standard schickt? Könnte man einstellbar machen, wie das MQTT Paket aussehen soll?

[Slider0007]

raebbaer: Danke für die weitere Investigation. Es ist in der Tat so, dass bei aktiviertem HA Discovery aktuell bei jedem MQTT Verbindungsaufbau sehr viele MQTT Pakete gesendet werden. Dies kannst du nur unterbinden, indem, wie bereits getan hast, das HA Discovery in der Config deaktivierst. Mit deaktivertem Discovery werden nur noch die Resultate und Systeminfos nach erfolger Auswertung in jeder Runde einmalig gesendet. Hier sollte die "Systemlast" nicht allzu hoch sein und vor allem es wird deterministisch immer erst nach der Bildauswertung gesendet.

@jomjol: FYI
@caco3: Das HA Discovery wird doch nur für die Ersteinrichtung des Systems in HA einmalig benötigt und dann nicht mehr? Ist das korrekt? Wenn ja, dann würde es meines Erachtens Sinn machen, das HA Discovery wirklich nur direkt einmalig nach dem Start zu versenden bzw. ggf. sogar den Versand nur über einen Button auslösen. Das würde dem System in vielerlei Hinsicht gut tun. Aktuell muss zu jedem Zeitpunkt min. 15kB-20kB wertvoller interner RAM freigehalten werden, da ein MQTT Verbindungsaufbau zu jeder Zeit auftreten kann und die Pakete dann versendet werden müssen. Ein deterministischer Ansatz könnte zumindest sicherstellen, dass ein Versenden während der Bildauswertung vermieden werden könnte und z.B. nur gesendet wird, wenn nichts / wenig prozessiert werden muss.

[raebbaer]

@Slider0007: Sehr gerne. Ich habe heute weiter beobachtet. Das System läuft jetzt sehr stabil. Ab und zu fehlt ein Messwert - aber das kann auch an veränderten Lichtbedingungen liegen. Das System läuft aber bereits seit über einem Tag stabil durch. Aus meiner Sicht ist das ein sehr guter Ansatz: Ein Knopf mit dem man die HA Anmeldung senden kann. Ansonsten raus aus dem Speicher. Herzlichen Dank für dieses tolle Projekt!

[caco3]

@Slider0007 Ja, die HA Discovery Pakete braucht es eigentlich nur beim Einrichten.
meine Überlegung war wie folgt:
Wenn ich den ESP starte, während HA nicht läuft, erfährt HA nie etwas vom Device, deshalb wähle ich den radikalen Weg mit dem Discovery Topics senden nach jedem Connect ging.
Dabei war ich mir der Komplexität und Auslastung noch zuwenig bewusst.

Es macht aus meiner Sicht Sinn, dass wir das so umbauen, dass es nur nach dem ersten Connect gesendet wird und danach vom Anwende rgetriggert werden muss. Dazu hat es ja schon einen Link in der Config. Das könnte man sicher noch schöner machen mit einem Button.

Grundsätzlich gilt: Wenn HA das Gerät mal discovered hat, braucht es die Discovery Topics nicht mehr..

Aktuell muss zu jedem Zeitpunkt min. 15kB-20kB wertvoller interner RAM freigehalten werden, da ein MQTT Verbindungsaufbau zu jeder Zeit auftreten kann und die Pakete dann versendet werden müssen.

Wie kommst Du auf diese Werte? Die HA Discovery Topics werden doch on-the-fly generiert!

[Slider0007]

Es macht aus meiner Sicht Sinn, dass wir das so umbauen, dass es nur nach dem ersten Connect gesendet wird und danach vom Anwender getriggert werden muss.

Ich denke auch, dass dies für das System sicher besser wäre. Der Nachteil sollte dadurch nicht allzu groß sein. Ich würde empfehlen das manuelle Antriggern zusätzlich noch so verriegeln, dass dies nicht bei aktivem Flow ausgelöst werden kann, z.B. nur im State "Flow finished", um das System während des Processings nicht unnötig zu belasten.

Aktuell muss zu jedem Zeitpunkt min. 15kB-20kB wertvoller interner RAM freigehalten werden, da ein MQTT Verbindungsaufbau zu jeder Zeit auftreten kann und die Pakete dann versendet werden müssen.

Wie kommst Du auf diese Werte? Die HA Discovery Topics werden doch on-the-fly generiert!

Es ist richtig, dass die Pakete in der Applikationsschicht on-the-fly generiert werden. Die Daten müssen aber noch versandt werden (durch IP und Wifi Layer Schicht). Dort wird der notwendige RAM teilweise dynamisch im DMA Bereich allokiert. Zusätzlich kommt worst case noch die Protokollierung der Pakete im DEBUG Level dazu, welches auch zusätzlich DMA benötigt, um über die Schnittstelle zur SD zu gelangen. Eine grobe Abschätzung des RAM Einsatzes kannst du durch Aufruf von http://IP/heap jederzeit zur Laufzeit anschauen (hier interessant -> Int Min Free). Hierbei ergibt es bei mir ein Delta von ca. 12-15kB bei aktiviertem HA Discovery und dann deaktivierter Funktion (restliche Konfig unverändert, DEBUG level). Inkl. Sicherheitsmarge ergibt sich somit der hier genannte Wert von 15kB-20kB.

Details sind hier zu finden: https://docs.espressif.com/projects/esp-idf/en/latest/esp32/api-guides/wifi.html
https://docs.espressif.com/projects/esp-idf/en/latest/esp32/api-guides/lwip.html

für WiFi z.B.

[fhb]

Habe das gleiche oder ein ähnliches Problem, lief tagelang problemlos, dann ab 19:00 Uhr ging das Device bei HA offline. Neustart von HA hat nicht geholfen. Mit dem Reboot des Aiontheedge-ESP32 ging es gleich wieder. Release: v14.0.3 (Commit: 6c891ab+). Errorlog auf dem AIOTE:
d[1d14h26m27s] 2023-02-19T19:00:22 <ERR> [MQTT IF] Failed to publish topic 'aiontheedge-water-meter/status', skipping all MQTT publishings in this round!

Interessanterweise werden die Daten weiter erkannt und auch bei mqtt hochgeladen, wenn auch der status auf "connection lost" bleibt, vielleicht liegt das Problem am fehlenden status update?:

bei HA offline:

bei Grafana wird auch der Wert weiter registriert (über Telegraf):

[caco3]

Interessanterweise werden die Daten weiter erkannt und auch bei mqtt hochgeladen, wenn auch der status auf "connection lost" bleibt, vielleicht liegt das Problem am fehlenden status update?:

Kannst Du das etwas genauer erläutern?

[fhb]

Um 19:00:22 erscheint im Log der MQTT-Publish Fehler, woraufhin bei Home-Assistant (man beachte den Hinweis "vor 5 Stunden" ) das Gerät auf "nicht verfügbar" geht. Es wurden aber weiter per MQTT-Werte veröffentlicht, wie ich mit MQTT-Explorer () und Grafana/InfluxDB prüfen konnte. Hierbei ist mir aufgefallen, dass trotz der weiter veröffentlichten Werte der wert "connection" auf "connection lost" stehen blieb:

[fhb]

Tatsächlich ist das die Ursache, das Problem ist zumindest zum Teil reproduzierbar: Wenn ich connection auf "connection lost" setze, geht das Gerät bei Home Assistant auf "nicht verfügbar", sobald ich "connected" publishe, werden wieder sämtliche Werte bei HA angezeigt.

[caco3]

Zeig doch bitte mal das DEBUG Log von der Situation.
MQTT läuft nicht 100% stabil. Es könnte z.B. sein, dass das Device mal disconnected und dann wieder connected. Das "connection" topic wird nur nach einem connect gesendet. Wenn das da gerade fehlgeschlagen ist, steht es halt leider noch auch "disconnected", die meisten anderen topics werden aber nach jeder Runde normal gesendet.

[fhb]

Log war nur auf error level gesetzt in der configuration. Mehr als den einen Eintrag gibt es somit leider nicht. Die connect message scheint ja beim reconnect nicht gesendet worden zu sein, jedenfalls nicht angekommen zu sein? Ein Update des connection status erfolgte dann über Stunden nicht. Der reconnect muss ja inklusive Authentifizierung erfolgt sein, sonst können doch keine Daten hochgeladen werden? Den Fehler müsste man doch durch eine Kontrollabfrage oder (blindes) Updaten korrigieren können?

[caco3]

Ich habe schon Tage und Abende investiert um MQTT besser zum laufen zu kriegen. Irgendwie scheint in der Bibliothek der Hund drin zu sein.
Da ich die Probleme selber nicht nachvollziehen kann, ist eine weitere Verbesserung von meiner Seite sehr schwierig!

[simonwes]

Ich habe das Phänomen auch gerade bei 14.0.3. Ich habe ziemlich schlechtes WLAN Signal am Wasserzähler. Hatte es zum Teil darauf geschoben. Mit 13.0.8 lief das aber noch runder.

Es kommt aktuell in jeder Runde ca. 40 Sekunden nach der Statusmeldung "Digitalization of ROIs" ein "connection lost". Ich habe jetzt seit fast einer Stunde den Loglevel auf DEBUG stehen. Log hängt an.

logfileact.txt

[Slider0007]

@simonwes: Es scheint, dass du kurzzeitig kein WIFI hast, daher ggf. auch der Verbindungsabbruch von MQTT
[0d00h01m13s] 2023-02-20T17:58:41 <DBG> [TFLITE SERVER] WIFI Signal (RSSI): 0dBm

0dBm --> keine Wifi Verbindung

Vermutung:
Ggf. beeinflusst das Processing der CPU oder die grenzwertige Stromversorgung die Signalqualität des WLANs etwas. Bei schlechtem WLAN bricht diese dann ggf. kurzzeitig ab und baut sich nach Reduktion der Prozessorlast wieder auf.

[raebbaer]

Der MQTT Service in der 14.0.3 funktioniert meines Erachtens sehr stabil, wenn man die HA Pakete deaktiviert und kein Fritz-WLAN-Mesh verwendet.

Hier meine config.ini bzgl. MQTT:
[MQTT]
Uri = mqtt://192.168.178.57:1883
MainTopic = gas
;ClientID = gasmeter
user = mqttdevice
password = PASSWORT
;SetRetainFlag = false
;HomeassistantDiscovery = true
MeterType = gas_m3

Im HA habe ich den Sensor selbst definiert:
- name: "Gasfluss Wert"
unique_id: "GasflussWert"
state_topic: "gas/main/value"
unit_of_measurement: m³
state_class: total
device_class: gas

Auf diese Weise kommen alle 5 Minuten saubere Werte an:

Im Diagramm steht die Zeit bis zur letzten Änderung des Wertes - hier 1 Stunde.

Der ESP32 hängt dabei direkt über WLAN an einer Fritzbox. Trotz ausgezeichneter Empfangsqualität hat es über einen WLAN Mesh-Repeater von Fritz nicht funktioniert.

[fhb]

Das Problem ist ja oben benannt. Der connection status wird nicht zuverlässig aktualisiert. Da dieser bei manueller Definition der Sensoren in der config.yaml nicht beachtet wird, kommt es bei dieser auch nicht zu Fehlern. Nur HA auto discovery mqtt führt zu dem beschriebenen 'Nicht verfügbar'. Ansonsten funktioniert mqtt grundsätzlich ja und der Wert wird weiter aktualisiert, mal schauen wie häufig das Problem auftritt.

[friedpa]

Ich verwende meinen Wasser & Gaszähler seit Beginn des Projektes über ein FritzBox Mesh-WLAN und hatte noch kein Problem damit:

[raebbaer]

@friedpa: Ich habe einen FRITZ!Repeater 1200 AX im Einsatz. Vielleicht liegt es ja an dem Modell? Was verwendest Du denn für einen Typ? Mit der LAN-Brücke funktioniert es:

@fhb: Ja, korrekt. Allerdings hat er bei mir mit aktivierter HomeassistantDiscovery nicht wirklich funktioniert. Da sendet der ESP32 schlichtweg keine bzw. nur sehr selten MQTT Pakete. Ich habe parallel den MQTT Explorer mitlaufen lassen, um das unabhängig von der HA-Visualisierung zu prüfen.

[friedpa]

Das eine Gerät hängt an einem 310er der andere an einem 600er. Nicht vergessen, dass man das 2,4Ghz Band aufdreht.

[caco3]

Gemäss #2020 (comment) funktioniert das Wifi Roaming noch gar nicht! @Slider0007 schaut sich das mal noch an.

[caco3]

Das Problem ist ja oben benannt. Der connection status wird nicht zuverlässig aktualisiert.

Es wurde bis jetzt nur nach dem connect aktualisiert. Falls das schief lief, wurde es später nicht mehr aktualisiert.
Ich habe das in #2091 nun so aktualisiert, dass auch der status in jeder Runde aktualisiert wird.

Da dieser bei manueller Definition der Sensoren in der config.yaml nicht beachtet wird, kommt es bei dieser auch nicht zu Fehlern. Nur HA auto discovery mqtt führt zu dem beschriebenen 'Nicht verfügbar'. Ansonsten funktioniert mqtt grundsätzlich ja und der Wert wird weiter aktualisiert, mal schauen wie häufig das Problem auftritt.

HA verwendet den status nur mit dem Discovery.

Ich schliesse diesen issue daher mal.

Die ganze Problematik mit dem Wifi Roaming sollten wir in einem separaten issue diskutieren: #2092. Resp. es ist schon bekannt, dass es noch nicht funktioniert.

[mihail4anov]

Hello.
I have the same problem. ESP boots up. Pushes the values to HA. Several minutes. The sensors is unavalble.

[caco3]

@mihail4anov this issue is quite old and related to an older version.

Please create a a separate bug with additional information. Eg. is the wifi link stable? Whats the RSSI?