MQTT Adapter macht Probleme

[shadesh]

Ich habe das selbe Problem, betrifft nur MQTT Clients. Nach einiger Zeit: "connection closed: Error: Invalid messageId" in den Logs.

NPM 6.4.1

Node 8.12.0

Raspi 3 Image.

Edit: Nach einem Reload des MQTT Adapters tut es wieder für einige Zeit.

[arteck]

das geht vom client aus .. der geht in standby.. welche Tasmota Version hast du drauf ??

es gibt eine Einstellung am Client um Energie zu sparen.. die mukt ab und an

[shadesh]

Tasmota v6.2.1

Es betrifft allerdings auch EasyESP Geräte mit R120, selbe Meldung.

[Mazdaracer121]

Bei mir aktuell genau das gleiche… Gibt's schon Lösungsansatz?

[nox]

Bei mir das gleiche.

Wird der Adapter neu gestartet, ist wieder eine ganze Weile ruhe.

[polocup100]

Hallo,

ich habe ebanfalls das Problem mit "invalid Message ID"

Vorwiegend bei den kürzlich hinzugefügten Sonoffs. Dabei spielt es keine Rolle ob 5.11.1 oder 6.3.0, auch deutsch oder englisch mach Firmwaretechnisch keinen Unterschied.

Sleepmode ist auch deaktiviert.

Manchmal sind es nur 2, mancmal 4 oder mehr Clients.

Ich habe die Fulltopic wie folgt geändert : %topic%/%prefix%/

Das sollte aber doch nichts machen oder?

Habe erstmal ein Script erstellt, dass bei mehr als 50 "connection" Aktualiesierungen pro Minute, den MQTT Adapter neustartet.

Aber das sollte ja kein Dauerzustand sein.

Hat schon jemand eine Lösung gefunden?

VG Sascha

[Skydream]

Moin,

ich hänge mich hier mal mit dran, da ich das gleiche Problem habe. Manchmal nach ein paar Tagen, manchmal nach zwei oder drei Wochen zickt der MQTT Adapter rum:

<size size="85">2018-12-28 16:15:27.803 - [32minfo[39m: javascript.0 script.js.common.KatzenhausSensor: [object Object]

2018-12-28 16:20:27.799 - [32minfo[39m: javascript.0 script.js.common.KatzenhausSensor: [object Object]

2018-12-28 16:25:27.808 - [32minfo[39m: javascript.0 script.js.common.KatzenhausSensor: [object Object]

2018-12-28 16:26:19.990 - [32minfo[39m: mqtt.0 Client [Bambus] connection closed: Error: read EHOSTUNREACH

2018-12-28 16:26:23.564 - [32minfo[39m: mqtt.0 Client [Switsch1] connection closed: Error: Invalid messageId

2018-12-28 16:26:24.278 - [32minfo[39m: mqtt.0 Client [Switsch1] connected with secret 1546010784278_6005

2018-12-28 16:26:24.335 - [32minfo[39m: mqtt.0 Client [Switsch1] subscribes on "cmnd/switch1/#" with regex /^cmnd.switch1..*/

2018-12-28 16:26:24.335 - [32minfo[39m: mqtt.0 Client [Switsch1] subscribes on "cmnd/switch1/#" with regex /^mqtt.0.cmnd.switch1..*/

2018-12-28 16:26:24.335 - [32minfo[39m: mqtt.0 Client [Switsch1] publishOnSubscribe send all known states

2018-12-28 16:26:24.380 - [32minfo[39m: mqtt.0 Client [Switsch1] connection closed: Error: Invalid messageId</size>

Nach einem neustart des Adapters ist wieder alles OK. Die MQTT Clients sind überwiegend Sonoff-Tasmota Devices aber auch ein paar selbstgebaute Geräte mit der passenden Arduino ESP Library ( <esp8266wifi.h>& <pubsubclient.h>)

Die liefen aber so wie sie sind sehr lange mit einem Cloud MQTT Broker und Home Automation.

Den MQTT Adapter habe ich auf dem aktuellen stand….das Verhalten hat sich aber auch nicht verändert über die letzen Versionen.

Node v6.14.3

Ist eine Docker Image

ioBroker läuft dort unter einem Alpine Linux 3.4

WAS genau ist die messageID?

Kann man sich anzeigen lassen was er hat/bekommt und was erwartet wird?

Jemand eine Idee, bzw. wie kann ich helfen den "fehler" zu finden?

Gruss</pubsubclient.h></esp8266wifi.h>

[Fischler]

Es liegt an den Clients. Im Tasmota-Wiki ist beschrieben wie man die Prefixe richtig verwendet.

https://github.com/arendst/Sonoff-Tasmo … T-Features

MQTT Topic definition

Until version 5.0.5 the MQTT topic was defined rigidly by using the commands Prefix <x>and Topic resulting in a command topic string like cmnd/sonoff/Power.

Starting with version 5.0.5 the MQTT topic is more flexible using command FullTopic and tokens to be placed within the user definable string up to 100 characters in size. The provided tokens are:

%prefix% to be dynamically substituted by one of three prefixes as defined by commands Prefix1 (default: "cmnd"), Prefix2 (default: "stat") and Prefix3 (default: "tele").

%topic% to be dynamically substituted by one of five topics as defined by commands Topic, GroupTopic, ButtonTopic, SwitchTopic and MqttClient.

Using the tokens the following example topics can be made:

FullTopic %prefix%/%topic%/ being the legacy situation up to version 5.0.5

FullTopic tasmota/%topic%/%prefix%/

FullTopic tasmota/bedroom/%topic%/%prefix%/

FullTopic penthouse/bedroom1/bathroom2/%topic%/%prefix%/

To solve possible MQTT topic loops I strongly suggest to use the %prefix% token in all of your FullTopics. It may work without %prefix% as I implemented some validation by forcing the use of a prefix in commands send to the device but status and telemetry do not need a prefix. Just play with it and report strange problems I might solve in the future.

The use of the %topic% token is also mandatory in case you want to use ButtonTopic and/or SwitchTopic. It also provides for grouptopic and fallback topic functionality.

<size size="150">Recommendation: Use both tokens at all time within your FullTopic string</size></x>

[Skydream]

Hi,

ich benutze Topic und prefix wie angegeben:

[attachment=0]~~MQTT.JPG[/attachment]" />

Sieht man auch im Log, oder meinst du noch was anderes?

Wie gesagt das passiert NICHT nur mit Tasmota Clients.

Gruss~~

[romgen]

Ich habe das gleiche Problem mit dem MQTT Adapter, auch mehrfach täglich.

Mein FullTopic ist einfach nur einfach "%prefix%/%topic%", wie auch bei Tasmota vorgegeben.

Ein Neustart des Adapter löst das Problem meistens. Vielleicht kann ich ja selbst helfen.

Leider konnte ich noch nicht herausfinden welche MQTT Message jetzt eigentlich das Problem ist.

Update:

Dank eines alten Post von Bluefox (mit Tipps zum Debuggen) komme ich weiter.

Hier ein output mit debug enabled, trace kommt später:

2018-12-31 01:47:03.286  - info: mqtt.0 Client [DVES_6B3BFF] connected with secret 1546217223283_4092
2018-12-31 01:47:03.290  - debug: mqtt.0 stateChange mqtt.0.info.connection: {"val":"DVES_9C67D9,DVES_6B3BFF","ack":true,"ts":1546217223287,"q":0,"from":"system.adapter.mqtt.0","lc":1546217223287}
2018-12-31 01:47:03.297  - debug: mqtt.0 stateChange mqtt.0.tele.sonoff3.LWT: {"val":"Online","ack":true,"ts":1546217223296,"q":0,"from":"system.adapter.mqtt.0","lc":1546217223296}
2018-12-31 01:47:03.343  - info: mqtt.0 Client [DVES_6B3BFF] subscribes on "cmnd/sonoff3/#" with regex /^cmnd\.sonoff3\..*/
2018-12-31 01:47:03.343  - info: mqtt.0 Client [DVES_6B3BFF] subscribes on "cmnd/sonoff3/#"  with regex /^mqtt\.0\.cmnd\.sonoff3\..*/
2018-12-31 01:47:03.343  - info: mqtt.0 Client [DVES_6B3BFF] publishOnSubscribe send all known states
2018-12-31 01:47:03.343  - info: mqtt.0 Client [DVES_6B3BFF] subscribes on "cmnd/sonoffs/#" with regex /^cmnd\.sonoffs\..*/
2018-12-31 01:47:03.344  - info: mqtt.0 Client [DVES_6B3BFF] subscribes on "cmnd/sonoffs/#"  with regex /^mqtt\.0\.cmnd\.sonoffs\..*/
2018-12-31 01:47:03.344  - info: mqtt.0 Client [DVES_6B3BFF] publishOnSubscribe send all known states
2018-12-31 01:47:03.344  - info: mqtt.0 Client [DVES_6B3BFF] subscribes on "cmnd/DVES_6B3BFF_fb/#" with regex /^cmnd\.DVES_6B3BFF_fb\..*/
2018-12-31 01:47:03.344  - info: mqtt.0 Client [DVES_6B3BFF] subscribes on "cmnd/DVES_6B3BFF_fb/#"  with regex /^mqtt\.0\.cmnd\.DVES_6B3BFF_fb\..*/
2018-12-31 01:47:03.344  - info: mqtt.0 Client [DVES_6B3BFF] publishOnSubscribe send all known states
2018-12-31 01:47:03.344  - debug: mqtt.0 stateChange mqtt.0.cmnd.sonoff3.POWER: {"val":"","ack":true,"ts":1546217223342,"q":0,"from":"system.adapter.mqtt.0","lc":1546211354064}
2018-12-31 01:47:03.371  - debug: mqtt.0 stateChange mqtt.0.stat.sonoff3.RESULT: {"val":"{\"POWER\":\"ON\"}","ack":true,"ts":1546217223370,"q":0,"from":"system.adapter.mqtt.0","lc":1546183229931}
2018-12-31 01:47:03.389  - debug: mqtt.0 Client [DVES_6B3BFF] Resend messages on connect: tele/sonoff1/LWT = [object Object]
2018-12-31 01:47:03.389  - info: mqtt.0 Client [DVES_6B3BFF] connection closed: Error: Invalid messageId
2018-12-31 01:47:03.397  - debug: mqtt.0 stateChange mqtt.0.info.connection: {"val":"DVES_9C67D9","ack":true,"ts":1546217223390,"q":0,"from":"system.adapter.mqtt.0","lc":1546217223390}
2018-12-31 01:47:03.399  - debug: mqtt.0 stateChange mqtt.0.tele.sonoff3.LWT: {"val":"[object Object]","ack":true,"ts":1546217223398,"q":0,"from":"system.adapter.mqtt.0","lc":1546217223398}
2018-12-31 01:47:03.407  - debug: mqtt.0 Client [DVES_6B3BFF] Resend messages on connect: tele/sonoff2/LWT = [object Object]
2018-12-31 01:47:03.417  - debug: mqtt.0 Client [DVES_6B3BFF] Resend messages on connect: tele/sonoff1/LWT = [object Object]
2018-12-31 01:47:03.427  - debug: mqtt.0 Client [DVES_6B3BFF] Resend messages on connect: tele/sonoff2/LWT = [object Object]

Update2:

Ok, Ich glaube, dass ich den Fehler gefunden habe.

Und zwar kommt iobroker / mqtt nicht damit klar, wenn der client ein LWT message-topic mit einem "object" payload schickt. Im Falle von Tasmota ist der "LWT" = '{"POWER":"ON"}' (bzw OFF).

Für alle interessierten: Ich habe mal einen Bug report aufgemacht. https://github.com/ioBroker/ioBroker.mqtt/issues/31

romgen created this issue in ioBroker/ioBroker.mqtt

closed MQTT Adapter "Invalid messageId" (possible reason inside) #31

[Fischler]

Ich habe Tasmota Version 6.4.1 installiert und es läuft mittlerweile ohne Probleme.

Laut dem Debug scheint das Prefix und Topic noch vertauscht zu sein.

> stateChange mqtt.0.cmnd.sonoff3.POWER

richtig wäre allerdings:

> stateChange mqtt.0.sonoff3.cmnd.POWER

Postet doch mal das gesamte "aufgeklappte" Objekt <u>eines</u> Sonoff-Devices und die Infoseite von dem Sonoff-Device Hauptmenü -> Informationen

[Skydream]

Hi,

Warum soll das eine “richtig” und das andere “falsch” sein?

Laut beschreibung sind beide varianten gültig.

Ich kann mir auch schlecht vorstellen dass das Problem so trivial ist….mein letzter Neustart war am 28.12,

Seitdem läuft wieder alles ohne Problem.....mit 10 mqtt Clients, welche auch benutzt werden.

Es währe spannend zu sehen ob es User gubt die auch cmnd.NAME.Power etc benutzen aber trotzdem keine Probleme haben.

Gruss

Sky

[romgen]

Hey,

Ja, mal schauen, ich probiere natürlich alles aus.

Angefangen habe ich mit dem Sonoff MQTT Adapter, aber der ist ja sehr sensibel. :lol: Der braucht ja auch eine ganz spezielle Reihenfolge von prefix und topic. Ich will da nichts aussschließen ^^

Im Moment habe ich den code einfach angepasst, dass alle Messages ohne gültige id einfach gelöscht werden. Läuft auch ohne Probleme ist aber auch nur ein "hack". Nur doof für alle anderen, die nicht eben mal den Code anpassen können.

Vielen Dank für das Feedback!

[Lazybone]

Gibt es eine Lösung. Ich habe mittlerweile selbst nach einen Neustart von MQTT den Fehler nach wenigen Minuten erneut.

Mehrere Sonoff Geräte mit Tasmota 6.4.1 im Einsatz.

[Hhjung16]

@romgen:

Hey,

Ja, mal schauen, ich probiere natürlich alles aus.

Angefangen habe ich mit dem Sonoff MQTT Adapter, aber der ist ja sehr sensibel. [emoji38] Der braucht ja auch eine ganz spezielle Reihenfolge von prefix und topic. Ich will da nichts aussschließen ^^

Im Moment habe ich den code einfach angepasst, dass alle Messages ohne gültige id einfach gelöscht werden. Läuft auch ohne Probleme ist aber auch nur ein "hack". Nur doof für alle anderen, die nicht eben mal den Code anpassen können.

Vielen Dank für das Feedback! ` Moin

Ich muss sagen, ich bin auf den Sonoff Adapter umgestiegen und habe die Probleme seitdem nicht mehr, Tasmota 6.4.1 auf GosundSp111 und Sonoff Basic.

[gami82]

Bei mir gleichen Problem, sporadisch "connection closed: Error: Invalid messageId"

Konnte zumindest den Fehler bewusst herbeiführen. Sieht so aus, sobald der Client die (WLAN)Verbindung verliert (auch wenn nur kurz, ausgehend vom Client? oder Router->checked), kommt es zum Fehler.

Hatte Wlan Einstellungen meiner Fritzbox geändert ("WLAN-Zugang auf die bekannten WLAN-Geräte beschränken" auf "Alle neuen WLAN-Geräte zulassen"), dabei wurde die Verbindung kurz unterbrochen, danach Fehler "connection closed: Error: Invalid messageId" im Log.

Nach Neustart MQTT Adapter lief wieder alles.

MQTT 2.04

Node.js: v8.15.0

NPM: 6.4.1

Tasmota: 6.4.1

[Skydream]

Ich habe das mal Testweise ausprobiert. Beim Umstellen von "Alle neuen WLAN-Geräte zulassen" auf "WLAN-Zugang auf die bekanten WLAN-Geräte beschränken" ist es nicht zu ausfällen gekommen.

Als ich aber nach ein paar Minuten wider zurück auf "Alle neuen WLAN-Geräte zulassen" gestellt hat

ist mir sofort der MQTT Adapter um die Ohren geflogen.

Also lässt ich der Fehler reproduzieren….das ist ja schon mal gut.

Gruss

Sky

Nachtrag: Dieses mal war es kein sonoff Tasmota device, sondern eine "Eigenkreation". Allerdings auch ein esp8266

[gami82]

node_modules/iobroker.mqtt/lib/server.js

Funtkion function clientClose(client, reason)

Zeile receivedTopic(client._will, client, () => client.destroy()); erstmal auskommentiert. Ergebnis: läuft ohne Fehler.

Mich würde interessieren, wie oft ein "Verbindungsabbruch" Clientseitig, also ohne bewusstes herbeiführen vorkommt. Liegt es evtl. an Tasmota 6.4.x? Soweit mir bekannt ist, wurde doch dort eine dynamic Sleep implementiert (Add command SetOption60 0/1 to select dynamic sleep (0) or sleep (1) (#4497)). Ist also Sleep nicht mehr deaktiviertbar? Weiß das jemand?

[Skydream]

Werde ich morgen mal ausprobieren, danke für die Info.

Zur Häufigkeit….bei mir geschätzt alle 2-4 Wochen.

So das es nervt, aber noch kein KO Kriterium ist.

Bei meinem letzten Test war der Client, welcher als erstest in den Fehlermeldungen auftauchte, kein Tasmota Device!

Daher denke ich eher an ein Problem zwischen den Mqtt/WiFi Modulen für die ESP Bausteine und dem Mqtt Modul von iobroker.

Gruss

Sky

[romgen]

Ich bin jetzt auch auf den Sonoff Adapter wieder umgestiegen, seitdem keine Probleme mehr.

Dennoch ist das natürlich nicht die beste Lösung. Ich teste mal den Patch mit dem "will", da hatte ich ja auch gepatcht. Sonst einfach github mit in meinen issue reinposten.

Ist ja keine Lösung, dass der "generelle" MQTT Adapter hier mehr Fehler hat, als der Sonoff MQTT Adapter, der schon extrem simplifiziert ist (von wegen prefix/topic Reihenfolge usw).

Die Abbrüche kann man im Prinzip auch gut simulieren, indem man eine wackelige Wifi Verbindung hat, so war das bei mir. Vermutlich sind die Abbrüche dann schneller, als der Adapter das handlen kann - und stirbt dann an der "will" Message. Keine Ahnung

Zum Patch:

Ganz korrekt müsste es so ein, oder?

anstatt dem von dir komplett kommentierten Zeile:

// receivedTopic(...)

sollte man diese besser ersetzen durch

client.destroy();

Das Problem ist meiner Meinung nach nämlich nicht das client.destroy, sondern dass dabei die "client._will" verschickt wird. Feedback dazu? :idea: