MQTT Adapter "Invalid messageId" (possible reason inside)

[romgen]

Hey,
In the german iobroker forum, several people have complained about a bug in the mqtt adapter:
https://forum.iobroker.net/viewtopic.php?f=20&t=16349

The bug basicly renders the adapter useless and only a new start of the adapter fixes this problem.

I tried to find the root of the problem. Here is my debug enabled output:

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]

Here is a more detailed log with more debug output:
I renamed the error from "invalid messageId" to "Bad Paket" for my debug purposes.

2018-12-31 18:05:37.020  - �[34mdebug�[39m: mqtt.0 Client [DVES_6B3BFF] Resend message topic: tele/sonoff2/LWT, payload: [object Object]
2018-12-31 18:05:37.020  - �[32minfo�[39m: mqtt.0 Client [DVES_6B3BFF] connection closed: Error: Bad Paket: {"topic":"tele/sonoff2/LWT","qos":1,"retain":true,"ts":1546275937020,"payload":"[object Object]","count":1,"cmd":"publish"}

The error "Invalid messageId" comes from function publish (packet, stream, opts) in the file node_modules/mqtt-connection/node_modules/mqtt-packet/writeToStream.js .

Maybe there are better way and maybe I didn't even understand the real problem here but it seems to me that the mqtt adapter cannot handle LWT messages with an object payload.
Even though this might not be MQTT adapters fault, it should just disregard bad formated messages and not "crash" on them IMHO.

[berndmr]

Adapter Version? MQTT Client und verwendete Lib?

[Ditoxius]

Hi,
I have the same problem using several sonoff/shelly - Tasmota based devices.

It seems that a weak WIFI connection results in some kind of loop or failing in reconnect? A restart of the mqtt adapter resolves the problem.
It depends but I had to restart the adapter every 2 to 12 hours.

I am using adapter npm version 2.0.4.
The clients are tasmota based devices. I tried the combinations

v 6.4.1/Core/SDK Version | 2_4_2/2.2.1
v 6.4.1.17(dev)/Core/SDK Version | 2_5_0/3.0.0-dev

In both configuration the error ocurrs sooner or later (speaking of hours). Right now I am using the sonoff.adapter but I would love to use the mqtt.adapter due to its capabilities.

Do you have any idea what could cause this problem? Do you need any forther information?

[berndmr]

Please try install Master branch directly Git so you will get Version 2.0.6

(HowTo: https://www.smarthome-tricks.de/software-iobroker/adapter-von-github-installieren )

[Ditoxius]

Hi,
Thank you for the idea. I just tried it and no problems so far within the last 2 hours.

With the old version this would be different...I guess.

Let's hope the solution is that simple :)

[Ditoxius]

Sadly the problem still exists after a few hours. I have no idea :(
A restart of the adapter fixes the problem but I don't want to restart the adapter every 10 minutes.

mqtt.0 2019-02-20 15:32:55.817 info Client [Bad] connection closed: Error: Invalid messageId
mqtt.0 2019-02-20 15:32:55.803 info Client [Bad] publishOnSubscribe send all known states
mqtt.0 2019-02-20 15:32:55.803 info Client [Bad] subscribes on "cmnd/Bad_fb/#" with regex /^mqtt.0.cmnd.Bad_fb../
mqtt.0 2019-02-20 15:32:55.803 info Client [Bad] subscribes on "cmnd/Bad_fb/#" with regex /^cmnd.Bad_fb../
mqtt.0 2019-02-20 15:32:55.802 info Client [Bad] publishOnSubscribe send all known states
mqtt.0 2019-02-20 15:32:55.802 info Client [Bad] subscribes on "cmnd/sonoffs/#" with regex /^mqtt.0.cmnd.sonoffs../
mqtt.0 2019-02-20 15:32:55.802 info Client [Bad] subscribes on "cmnd/sonoffs/#" with regex /^cmnd.sonoffs../
mqtt.0 2019-02-20 15:32:55.800 info Client [Bad] publishOnSubscribe send all known states
mqtt.0 2019-02-20 15:32:55.800 info Client [Bad] subscribes on "cmnd/bad/#" with regex /^mqtt.0.cmnd.bad../
mqtt.0 2019-02-20 15:32:55.800 info Client [Bad] subscribes on "cmnd/bad/#" with regex /^cmnd.bad../
mqtt.0 2019-02-20 15:32:55.726 info Client [Badschrank] connection closed: Error: Invalid messageId
mqtt.0 2019-02-20 15:32:55.716 info Client [Bad] connected with secret 1550673175710_858
mqtt.0 2019-02-20 15:32:55.714 info Client [Badschrank] publishOnSubscribe send all known states
mqtt.0 2019-02-20 15:32:55.714 info Client [Badschrank] subscribes on "cmnd/Badschrank_fb/#" with regex /^mqtt.0.cmnd.Badschrank_fb../
mqtt.0 2019-02-20 15:32:55.714 info Client [Badschrank] subscribes on "cmnd/Badschrank_fb/#" with regex /^cmnd.Badschrank_fb../
mqtt.0 2019-02-20 15:32:55.712 info Client [Badschrank] publishOnSubscribe send all known states
mqtt.0 2019-02-20 15:32:55.712 info Client [Badschrank] subscribes on "cmnd/sonoffs/#" with regex /^mqtt.0.cmnd.sonoffs../
mqtt.0 2019-02-20 15:32:55.712 info Client [Badschrank] subscribes on "cmnd/sonoffs/#" with regex /^cmnd.sonoffs../
mqtt.0 2019-02-20 15:32:55.711 info Client [Badschrank] publishOnSubscribe send all known states
mqtt.0 2019-02-20 15:32:55.711 info Client [Badschrank] subscribes on "cmnd/badschrank/#" with regex /^mqtt.0.cmnd.badschrank../
mqtt.0 2019-02-20 15:32:55.711 info Client [Badschrank] subscribes on "cmnd/badschrank/#" with regex /^cmnd.badschrank../
mqtt.0 2019-02-20 15:32:55.624 info Client [Badschrank] connected with secret 1550673175623_4630

[berndmr]

Without further debugging, don´t know what happens. But for that, I must be able to reproduce it.

Try MQTT_ARDUINOMQTT instead of PubSub in the Client.

[Ditoxius]

I compiled a new version using the dev-branch of tasmota (v 6.4.1.17) and changed the client to MQTT_ARDUINOMQTT. No problems after reconnect so far.

To "reproduce" it in my case I simply have to turn off and on my wifi. When reconnecting, the device fails by 80%.
Can I provide you any further debugging information?

[berndmr]

Send Log of the initial connect with debug enabled.
But don´t have to much hope...

[Ditoxius]

This is the most recent log after I restarted the client and broker. Using the Arduino-MQTT-client didn't solve the problem. After a few hours the client was not able to conenct to the broker anymore.

mqtt.0	2019-02-22 07:52:52.179	debug	Client [Badschrank] pingreq
mqtt.0	2019-02-22 07:52:40.876	debug	Client [Badschrank] pingreq
mqtt.0	2019-02-22 07:52:29.579	debug	Client [Badschrank] pingreq
mqtt.0	2019-02-22 07:52:18.314	debug	Client [Badschrank] pingreq
mqtt.0	2019-02-22 07:52:07.023	debug	Client [Badschrank] pingreq
mqtt.0	2019-02-22 07:51:55.759	debug	Client [Badschrank] pingreq
mqtt.0	2019-02-22 07:51:44.504	debug	Client [Badschrank] pingreq
mqtt.0	2019-02-22 07:51:33.205	debug	Client [Badschrank] pingreq
mqtt.0	2019-02-22 07:51:21.807	debug	Client [Badschrank] send to this client "cmnd/badschrank/POWER": true
mqtt.0	2019-02-22 07:51:12.282	debug	Client [Badschrank] send to this client "cmnd/badschrank/POWER": true
mqtt.0	2019-02-22 07:51:12.282	info	Client [Badschrank] publishOnSubscribe send all known states
mqtt.0	2019-02-22 07:51:12.282	info	Client [Badschrank] subscribes on "cmnd/Badschrank_fb/#" with regex /^mqtt\.0\.cmnd\.Badschrank_fb\..*/
mqtt.0	2019-02-22 07:51:12.282	info	Client [Badschrank] subscribes on "cmnd/Badschrank_fb/#" with regex /^cmnd\.Badschrank_fb\..*/
mqtt.0	2019-02-22 07:51:12.259	debug	Client [Badschrank] send to this client "cmnd/badschrank/POWER": true
mqtt.0	2019-02-22 07:51:12.229	debug	Client [Badschrank] send to this client "cmnd/badschrank/POWER":
mqtt.0	2019-02-22 07:51:12.229	info	Client [Badschrank] publishOnSubscribe send all known states
mqtt.0	2019-02-22 07:51:12.229	info	Client [Badschrank] subscribes on "cmnd/sonoffs/#" with regex /^mqtt\.0\.cmnd\.sonoffs\..*/
mqtt.0	2019-02-22 07:51:12.228	info	Client [Badschrank] subscribes on "cmnd/sonoffs/#" with regex /^cmnd\.sonoffs\..*/
mqtt.0	2019-02-22 07:51:12.216	debug	Client [Badschrank] send to this client "cmnd/badschrank/POWER": true
mqtt.0	2019-02-22 07:51:12.215	info	Client [Badschrank] publishOnSubscribe send all known states
mqtt.0	2019-02-22 07:51:12.215	info	Client [Badschrank] subscribes on "cmnd/badschrank/#" with regex /^mqtt\.0\.cmnd\.badschrank\..*/
mqtt.0	2019-02-22 07:51:12.215	info	Client [Badschrank] subscribes on "cmnd/badschrank/#" with regex /^cmnd\.badschrank\..*/
mqtt.0	2019-02-22 07:51:12.215	debug	Client [Badschrank] with keepalive 15 set timeout to 22.5 seconds
mqtt.0	2019-02-22 07:51:12.215	debug	Client [Badschrank] with last will {"retain":true,"qos":1,"topic":"tele/badschrank/LWT","payload":{"type":"Buffer","data":[79,102,102,108,105,110,101]}}
mqtt.0	2019-02-22 07:51:12.215	info	Client [Badschrank] connected with secret 1550818272041_4780

[berndmr]

Can you fetch the first reconnect that is starting the endless loop? Please only one Client.

For me, it looks like the server is timeouting at the client and then something wired happens.
And the retained last will is not there anymore even the server thinks it is so.

But cannot find the part in the code where this could happen...

[Ditoxius]

Hm after I deleted all files and reinstalled the broker again from the scetch (latest commit from masater-branch), I tried to reproduce the failure....But "sadly" it works perfeclty fine for the last 24 hours. So maybe this could be a solution.

Another workaround for me was using a mosquitto-broker (docker based) and the iobroker-adapter as another client. This worked pretty well.

[futesta]

Hey there, is there more informations about this problem?!? Having here the same issue since today... :-(

mqtt.0 2019-10-17 21:01:10.379 info Client [DVES_939D97] connection closed: Error: Invalid messageId

restart the adapter works for seconds, minutes or hours... reinstall at all brings um the issue randomly... ony suggentions?!?

[nicomania]

Hello,
meanwhile many people (including me) are suffering from this pronblem. Some guys in another discussion may have found something. Please take a look at it:
https://forum.iobroker.net/topic/14657/mqtt-adapter-macht-probleme/27

Translated it means, that a connection loss and reconnect on client side causes this. The user commented out the line :
receivedTopic(client._will, client, () => client.destroy());
and the the problem seems to be gone. Maybe that helps.
Best regards

[capitaenz]

I have the same problem. It only occurred after I integrated devices with Tasmota. Is there a new version without a problem?
Tasmota 8.1.0
MQTT 2.0.4

[nicomania]

It may be that my Tasmota devices (even from version 6.x) cause this too. I tried to record some debug information, but at some point I switched to the sonoff adapter. it runs super stable and has a sensor parser built in. If this really is related to Tasmoata, then it would not be the first time in my observations, that iobroker or the mqtt adapter does not harmonize with Tasmota.

[capitaenz]

I have been using ioBroker for almost 1 year and the MQTT adapter for over half a year without any problems. So far I have only used two Easy ESP (Wemos D1 mini). After using Tasmota I had the problems for the first time, so it would be a big coincidence!