UNSOLVED MQTT - Cannot Parse ProtocolID / NodeRED crash / ESP32

[TwiggyG]

Guten Morgen,

nachdem ich schon sehr viel Wissen aus diesem Forum geholt habe, muss ich nun doch mal aktiv fragen, da ich echt nicht mehr weiter komme. Es sind eigentlich zwei Fehler, wo ich jedoch vermute, dass die zusammen gehören.

Kurz zu dem Setup, zu dem die Fehler gehören.

Auf ioBroker nutze ich unter anderem MQTT und NodeRed und ScriptJS. MQTT empfängt und verteilt, NodeRed schickt Daten von lokalen Sensoren an MQTT und Daten von MQTT zu MSSQL. ScriptJS erzeugt mir eine DateTime, die auch via NodeRED nach MQTT geht. Natürlich macht Script noch mehr, aber ich grenze es mal nach Interpretation des Logs ein.

Meine Sensoren sind ESP32, die direkt zum MQTT verbunden sind. Folgend die Fehlermeldungen der ESP32

2020-05-29 04:51:38.172  - info: mqtt.0 (1685) Client [esp3] connection closed: Error: Cannot parse protocolId
2020-05-29 04:51:45.419  - info: mqtt.0 (1685) Client [esp3] connected with secret 1590720705415_7513
2020-05-29 04:51:45.426  - info: mqtt.0 (1685) Client [esp3] subscribes on "mqtt.0.wetter.out.temperatur"
2020-05-29 04:51:45.426  - info: mqtt.0 (1685) Client [esp3] publishOnSubscribe
2020-05-29 04:51:45.430  - info: mqtt.0 (1685) Client [esp3] subscribes on "mqtt.0.wetter.out.luftfeuchte"
2020-05-29 04:51:45.430  - info: mqtt.0 (1685) Client [esp3] publishOnSubscribe
2020-05-29 04:51:45.433  - info: mqtt.0 (1685) Client [esp3] subscribes on "mqtt.0.system.current_datetime"
2020-05-29 04:51:45.433  - info: mqtt.0 (1685) Client [esp3] publishOnSubscribe

2020-05-29 04:33:30.081  - info: mqtt.0 (1685) Client [esp2] connection closed: Error: Cannot parse topic
2020-05-29 04:33:33.615  - info: mqtt.0 (1685) Client [esp2] connected with secret 1590719613613_7096
2020-05-29 04:33:33.649  - info: mqtt.0 (1685) Client [esp2] subscribes on "mqtt.0.wetter.out.temperatur"
2020-05-29 04:33:33.649  - info: mqtt.0 (1685) Client [esp2] publishOnSubscribe
2020-05-29 04:33:33.651  - info: mqtt.0 (1685) Client [esp2] subscribes on "mqtt.0.wetter.out.luftfeuchte"
2020-05-29 04:33:33.651  - info: mqtt.0 (1685) Client [esp2] publishOnSubscribe
2020-05-29 04:33:33.651  - info: mqtt.0 (1685) Client [esp2] subscribes on "mqtt.0.system.current_datetime"
2020-05-29 04:33:33.651  - info: mqtt.0 (1685) Client [esp2] publishOnSubscribe

2020-05-29 00:59:24.056  - info: mqtt.0 (1685) Client [esp2] connection closed: Error: Cannot parse protocolId
2020-05-29 00:59:31.294  - info: mqtt.0 (1685) Client [esp2] connected with secret 1590706771293_3451
2020-05-29 00:59:31.299  - info: mqtt.0 (1685) Client [esp2] subscribes on "mqtt.0.wetter.out.temperatur"
2020-05-29 00:59:31.299  - info: mqtt.0 (1685) Client [esp2] publishOnSubscribe
2020-05-29 00:59:31.301  - info: mqtt.0 (1685) Client [esp2] subscribes on "mqtt.0.wetter.out.luftfeuchte"
2020-05-29 00:59:31.301  - info: mqtt.0 (1685) Client [esp2] publishOnSubscribe
2020-05-29 00:59:31.304  - info: mqtt.0 (1685) Client [esp2] subscribes on "mqtt.0.system.current_datetime"
2020-05-29 00:59:31.304  - info: mqtt.0 (1685) Client [esp2] publishOnSubscribe
2020-05-29 00:59:31.305  - info: mqtt.0 (1685) Client [esp2] connection closed: closed
2020-05-29 00:59:38.550  - info: mqtt.0 (1685) Client [esp2] connected with secret 1590706778547_4203
2020-05-29 00:59:38.555  - info: mqtt.0 (1685) Client [esp2] subscribes on "mqtt.0.wetter.out.temperatur"
2020-05-29 00:59:38.555  - info: mqtt.0 (1685) Client [esp2] publishOnSubscribe
2020-05-29 00:59:38.557  - info: mqtt.0 (1685) Client [esp2] subscribes on "mqtt.0.wetter.out.luftfeuchte"
2020-05-29 00:59:38.557  - info: mqtt.0 (1685) Client [esp2] publishOnSubscribe
2020-05-29 00:59:38.559  - info: mqtt.0 (1685) Client [esp2] subscribes on "mqtt.0.system.current_datetime"
2020-05-29 00:59:38.559  - info: mqtt.0 (1685) Client [esp2] publishOnSubscribe
2020-05-29 00:59:38.560  - info: mqtt.0 (1685) Client [esp2] connection closed: closed
2020-05-29 00:59:45.805  - info: mqtt.0 (1685) Client [esp2] connected with secret 1590706785803_7275
2020-05-29 00:59:45.810  - info: mqtt.0 (1685) Client [esp2] subscribes on "mqtt.0.wetter.out.temperatur"
2020-05-29 00:59:45.810  - info: mqtt.0 (1685) Client [esp2] publishOnSubscribe
2020-05-29 00:59:45.814  - info: mqtt.0 (1685) Client [esp2] subscribes on "mqtt.0.wetter.out.luftfeuchte"
2020-05-29 00:59:45.814  - info: mqtt.0 (1685) Client [esp2] publishOnSubscribe
2020-05-29 00:59:45.816  - info: mqtt.0 (1685) Client [esp2] subscribes on "mqtt.0.system.current_datetime"
2020-05-29 00:59:45.816  - info: mqtt.0 (1685) Client [esp2] publishOnSubscribe

ESP2 und 3 sind, was die connection angeht herb am flattern, was aber auch nicht in der lokalen Console der ESP auftauch. Es muss vermutlich am Subscribe der Clients liegen, da ESP1 nicht im Log auftaucht. Er sendet nur. Der Code ist natürlich anders, was die Basiskomponenten angeht aber identisch. Code kommt am Ende. ABER: wenn ich ausschließlich in den Objekten von ioBroker schaue ist alles io. Daten kommen. Kann ich auch mit leben, wenn Fehler zwei nicht wäre.

INFO: Natürlich habe ich auch meine WiFi Protokolle ausgewertet. Von den Permanenten DCs der ESP sind ca. 10% auch mit einem WiFi DC verbunden. Somit würde ich die WiFi Verbindung ioBroker <-> ESP ignorieren.

NodeRED

Wenn ich die VM durchgestartet habe läuft alles super 1 bis 2 Tage. Dann kommt folgender irgendwann spontan folgender Fehler

2020-05-29 07:02:11.861  - info: mqtt.0 (1685) Client [esp3] connection closed: Error: Cannot parse protocolId
2020-05-29 07:02:19.109  - info: mqtt.0 (1685) Client [esp3] connected with secret 1590728539106_8125
2020-05-29 07:02:19.116  - info: mqtt.0 (1685) Client [esp3] connection closed: closed
2020-05-29 07:02:19.126  - info: mqtt.0 (1685) Client [esp3] connected with secret 1590728539123_4439
2020-05-29 07:02:19.134  - info: mqtt.0 (1685) Client [esp3] subscribes on "mqtt.0.wetter.out.temperatur"
2020-05-29 07:02:19.134  - info: mqtt.0 (1685) Client [esp3] publishOnSubscribe
2020-05-29 07:02:19.137  - info: mqtt.0 (1685) Client [esp3] subscribes on "mqtt.0.wetter.out.luftfeuchte"
2020-05-29 07:02:19.137  - info: mqtt.0 (1685) Client [esp3] publishOnSubscribe
2020-05-29 07:02:19.137  - info: mqtt.0 (1685) Client [esp3] subscribes on "mqtt.0.system.current_datetime"
2020-05-29 07:02:19.138  - info: mqtt.0 (1685) Client [esp3] publishOnSubscribe
2020-05-29 07:02:22.450  - info: mqtt.0 (1685) Client [esp3] reconnected. Old secret 1590728539123_4439. New secret 1590728542447_7979
2020-05-29 07:02:22.487  - info: mqtt.0 (1685) Client [esp3] subscribes on "mqtt.0.wetter.out.temperatur"
2020-05-29 07:02:22.488  - info: mqtt.0 (1685) Client [esp3] publishOnSubscribe
2020-05-29 07:02:22.494  - info: mqtt.0 (1685) Client [esp3] subscribes on "mqtt.0.wetter.out.luftfeuchte"
2020-05-29 07:02:22.495  - info: mqtt.0 (1685) Client [esp3] publishOnSubscribe
2020-05-29 07:02:22.495  - info: mqtt.0 (1685) Client [esp3] subscribes on "mqtt.0.system.current_datetime"
2020-05-29 07:02:22.495  - info: mqtt.0 (1685) Client [esp3] publishOnSubscribe
2020-05-29 07:04:49.132  - info: mqtt.0 (1685) Client [nodeRED] connection closed: TypeError [ERR_INVALID_ARG_TYPE]: The "chunk" argument must be of type string or an instance of Buffer. Received undefined
2020-05-29 07:05:04.137  - info: mqtt.0 (1685) Client [nodeRED] connected with secret 1590728704137_3800
2020-05-29 07:05:04.140  - info: mqtt.0 (1685) Client [nodeRED] subscribes on "mqtt.0.wetter.out.temperatur"
2020-05-29 07:05:04.140  - info: mqtt.0 (1685) Client [nodeRED] publishOnSubscribe
2020-05-29 07:05:04.141  - info: mqtt.0 (1685) Client [nodeRED] connection closed: TypeError [ERR_INVALID_ARG_TYPE]: The "chunk" argument must be of type string or an instance of Buffer. Received undefined
2020-05-29 07:05:04.141  - info: mqtt.0 (1685) Client [nodeRED] subscribes on "mqtt.0.wetter.out.luftfeuchte"
2020-05-29 07:05:04.141  - info: mqtt.0 (1685) Client [nodeRED] publishOnSubscribe
2020-05-29 07:05:04.141  - info: mqtt.0 (1685) Client [nodeRED] subscribes on "mqtt.0.wetter.out.luftdruck"
2020-05-29 07:05:04.141  - info: mqtt.0 (1685) Client [nodeRED] publishOnSubscribe
2020-05-29 07:05:04.141  - info: mqtt.0 (1685) Client [nodeRED] subscribes on "mqtt.0.wetter.out.gas"
2020-05-29 07:05:04.141  - info: mqtt.0 (1685) Client [nodeRED] publishOnSubscribe

Ab 07:04 Uhr kommt dieser Fehler dann permanent. NodeRed ist tot, bzw GUI geht aber die die Nodes haben keine Verbindung mehr. NodeRED Neustart bringt nichts, da er vermutlich eine neue Instanz starten will, die Ports aber von der toten belegt sind. Ich muss den Server komplett durchstarten und dann geht das Spiel von vorn los.

2020-05-29 07:37:13.305  - info: host.iobroker stopInstance system.adapter.node-red.0 (force=false, process=true)
2020-05-29 07:37:13.308  - info: node-red.0 (2328) kill node-red task
2020-05-29 07:37:13.310  - warn: node-red.0 (2328) adapter.getMessage is deprecated and will be removed in js-controller 3.0. Please report this warning to the developer of this adapter!
2020-05-29 07:37:14.307  - info: host.iobroker stopInstance timeout 1000 system.adapter.node-red.0 killing pid  2328
2020-05-29 07:37:14.310  - info: node-red.0 (2328) Terminated (START_IMMEDIATELY_AFTER_STOP): Without reason
2020-05-29 07:37:14.829  - info: host.iobroker instance system.adapter.node-red.0 terminated with code 156 (156)
2020-05-29 07:37:16.819  - info: host.iobroker instance system.adapter.node-red.0 started with pid 21400
2020-05-29 07:37:16.821  - warn: node-red.0 (2343) Got terminate signal. Checking desired PID: 0 vs own PID 2343
2020-05-29 07:37:16.828  - warn: node-red.0 (2343) Got terminate signal. Checking desired PID: 21400 vs own PID 2343
2020-05-29 07:37:17.315  - info: node-red.0 (21400) starting. Version 1.13.0 in /opt/iobroker/node_modules/iobroker.node-red, node: v12.17.0
2020-05-29 07:37:17.626  - info: node-red.0 (21400) Starting node-red: --max-old-space-size=128 /opt/iobroker/node_modules/node-red/red.js -v --settings /opt/iobroker/iobroker-data/node-red/settings.js
2020-05-29 07:37:19.469  - warn: node-red.0 (21400) 29 May 07:37:19 - [warn] Projekte inaktiviert: editorTheme.projects.enabled=false

2020-05-29 07:37:19.481  - error: node-red.0 (21400) 29 May 07:37:19 - [error] Zuhören auf http://127.0.0.1:1880/ nicht möglich.

2020-05-29 07:37:19.481  - error: node-red.0 (21400) 29 May 07:37:19 - [error] Fehler: Port wird verwendet

2020-05-29 07:37:19.507  - info: node-red.0 (21400) node-red exited with 1

Google hat bei mir schon bestimmt die ersten 4 Seiten lila bei dem Thema ^^. Ich hoffe Ihr könnt mir helfen weil so macht das echt keinen Spaß. Ich Danke schon mal für die Mühen.

EDIT 29.05. 11Uhr
Ich habe mal DEBUG Logging aktiviert, das hatte ich bis jetzt nicht auf dem Schirm

Anbei noch ESP32 Code Snippest. Der MQTT Prozess läuft auf einem eigenen Core mit dem WiFi Prozess, der Rest der weiteren Verarbeitung auf dem anderen.

MQTT Connect

#include <PubSubClient.h>

void reconnect_mqqt() {
  while (!client.connected()) {
    Serial.println("Connecting to MQTT...");
 
    if (client.connect(geraet, mqttUser, mqttPassword )) {
 
      Serial.println("connected");  
 
    } else {
 
      Serial.print("failed with state ");
      Serial.println(client.state());
      delay(2000);
 
    }
  
  client.subscribe("wetter/out/temperatur");
  client.subscribe("wetter/out/luftfeuchte");
  client.subscribe("system/current_datetime");
  }
}

Systemdata	Bitte Ausfüllen
Hardwaresystem:	VM @ ESXi
Arbeitsspeicher:	2GB
Festplattenart:	vmdk (SSD RAID1)
Betriebssystem:	Ubuntu 20.04 LTS
Node-Version:	12.17.0
NPM-Version:	6.14.4
Installationsart:	Skript
Image genutzt:	Nein
Ort/Name der Imagedatei:	Link

[TwiggyG]

Nach einer Woche Debugging nun meine (vermutliche) Erkenntnis. Vielleicht stolpert ein Newbie (wie ich) mal irgendwann drüber.

Die beschrieben Auswirkungen wie oben Beschrieben waren da, ja, aber die Ursache woanders. Es ist alles Vermutung, da ESP32 und C neu für mich ist und was CHAR angeht ich nur zu 95% durchblicke.

Neben den oben beschriebenen Fehlern habe ich einen Vergessen, dass oft auch Topics angelegt wurden, die aus wild zusammen gesetzten Teilen der originalen Topics und Values ohne Systemanik bestehen.

Als ESP32 Newbie nimmt man natürlich erst mal Stumpf String und versucht alles irgendwie in einen String zu packen, weil man CHAR nicht versteht. Da ist aber beim ESP32 performancetechnisch ganz schnell Ende. Also 2 Tage intensiv mit CHAR beschäftgt. Und da bin ich mit mit einem Escapechar um eins verrutscht, wodurch er weggelassen wurde und somit ganz neues Messages entstanden sind. Mit den neuen konnte weder ioBroker, noch MQTT oder Node weiter arbeiten. (Mein erster Schritt war bei Node ein Function die prüft ob ein String rein kommt, somit war Node erst mal safe)

Nachdem ich das angepasst hatte und mich zuletzt auch noch mit Float zu Charkonvertierung beschäftigt habe und somit kein einziger String mehr im Code ist, läuft es (seit 2 Tagen). Dazu hab ich aus Node auch alles ausgelagert was ging und in jscript geschrieben, da Node bei solchen Problemen eine ekelhafte Blackbox ist.

Details zum ESP32 gehören hier weniger her, dazu gibts viel im Netz. Wenn wer Fragen hat, gerne eine PM.

Grüße

[TwiggyG]

Und aufeinmal war wieder alles Kacke. Ich habe dann als Vergleich mal auf einer Windowsmaschine mosquitto installiert und es lief, läuft immer noch. Logs sind sauber, ESPs empfangen keine Topics mehr die eine Panic auslösen. Also MQTT Adapter deinstalliert und Mosquitto auf der Linuxmaschine eingerichtet. Immer noch sind die Logs sind nicht nur sauber, sondern rein. Die Verbindung zum ioBroker übernimmt nun NodeRed. Ausser die IP zum Broker habe ich zuletzt nix mehr geändert.

Immerhin habe ich viel gelernt über Chars, non blocking delays und core handling während ich die Routinen für die ESPs 3 mal neu geschrieben habe ^^