Nodemcu-firmware: MQTT subscribe - large messages get ignored quietly

[joysfera]

Expected behavior

NodeMCU should receive every message that has been published with a MQTT topic it is subscribed to.

Actual behavior

If the message is longer than 984 bytes (in my tests with 35 bytes long topic) then such message is not received, it gets ignored quietly.
Maybe the real limit is actually sum of topic length and message length, and it seems like it's less than 1024 bytes.
FYI, the topic max size is 64 kB and message max size is 256 MB per MQTT spec. Of course I don't want an ESP device with 20 kB free heap to process 256 MB message but a hidden/undocumented limit to less than 1 kB is not fun either.

The worst thing here is that no message is received at all, there's no indication that a message got lost. If would be far better (though still not ideal) if it at least returned first part of the message that fit into an internal buffer...

Test code

mqtt_client = mqtt.Client(1, 120, name, passwd)
mqtt_client:on("message", function(client, topic, data) print(#data) end)
mqtt_client:connect(broker, 1883, 0, 0, function(client)  mqtt_client:subscribe({["#"]=1}) end)

$ printf '%*s\n' 1024 | tr ' ' 'a' |  mosquitto_pub -t x -l

NodeMCU version

current master

Hardware

plain ESP8266-07

[joysfera]

Looking into app/modules/mqtt.c - this is suspicious:

#define MQTT_BUF_SIZE 1024

READPACKET:
  if(length > MQTT_BUF_SIZE || length <= 0)
          return;

This MQTT_BUF_SIZE define is used at six places (received, connected, timer, unsubscribe, subscribe, publish) to allocate a temporary buffer on the stack.

Would it be possible to increase the MQTT_BUF_SIZE to say 2048 or 4096? The 1kB limit on topic+payload is too severe and handling of messages larger than that is non-existent - they're just ignored on both publish and receive. Scary!

How much space is there left on stack normally? Wouldn't it cause random and hard to debug issues elsewhere?

[joysfera]

Weird things are happening there! I have just compiled my own firmware from the master branch and increased the MQTT_BUF_SIZE from 1024 to 2048 there. I was expecting to be able to receive packets up to 2042 bytes then. Imagine my surprise when I was able to receive packets longer than 10 kB, i.e. much larger than the MQTT_BUF_SIZE! Granted, the content of the message (the payload) is cut at 2042 bytes but larger messages do NOT get lost, contrary to the firmware I've been using.

I have quickly flashed back the "official" build (from nodemcu-build.com) to ensure that it is still stuck with 1018 bytes max (using the printf test outlined above). Indeed, MQTT packets with 1019+ bytes disappear (are not received by NodeMCU). Does it mean that the MQTT is broken in the "official build" while my own build can receive even large the MQTT packets properly?

BTW, what does @TerryE think about increasing the MQTT_BUF_SIZE?

EDIT: let me attach the headers of the builds to show you they're identical (apart from missing cron module):

NodeMCU custom build by frightanic.com
    branch: master
    commit: 8b84445aeff5de5fabf9963b4775f4d6195aa75d
    SSL: false
    modules: bit,cron,crypto,file,gpio,http,mdns,mqtt,net,node,ow,rtcmem,rtctime,sjson,sntp,tmr,uart,wifi
 build created on 2018-06-14 07:02
 powered by Lua 5.1.4 on SDK 2.2.1(cfd48f3)

NodeMCU 2.2.0.0 built with Docker provided by frightanic.com
    branch: master
    commit: 8181c3be7aed9f0a0ceb73ac8137c1a519e8a8e9
    SSL: false
    modules: bit,crypto,file,gpio,http,mdns,mqtt,net,node,ow,rtcmem,rtctime,sjson,sntp,tmr,uart,wifi
 build created on 2018-07-24 08:16
 powered by Lua 5.1.4 on SDK 2.2.1(cfd48f3)

[TerryE]

BTW, what does @TerryE think about increasing the MQTT_BUF_SIZE?

Sorry, I don't have an opinion at the moment. I am up to my neck if tweaking LFS functionality, :sweat:

[joysfera]

Understand. I just thought you'd know from top of your head (thanks to your deep knowledge of the internals) what stack size is available in NodeMCU and if it is safe at all to allocate 1kB - 2kB buffers on the stack.

[joysfera]

I have built several more configurations to find out which MQTT buffer size is necessary to stop losing MQTT packets. 1280 bytes is not enough. 1536 bytes is OK. So it seems to be pointing at TCP packet size. If the TCP packet fits into the MQTT buffer completely then the MQTT communication works even for much larger packets (beware: the MQTT messages still get truncated). However, if the first TCP packet does not fit to MQTT buffer then the message is not received at all. I tend to think it's better to get a truncated message than to get none (of course it would be better to receive the whole message).

The MQTT implementation in NodeMCU is in rather bad shape in many ways but if it was possible to increase the MQTT working buffer on stack from 1024 to 1536 bytes it would (at least partially) improved larger MQTT messages handling.

[stromnet]

Hi,

had some issues with small but rapidly sent messages getting dropped by my ESP12-F on NodeMCU 2.2.1.
The messages where just 52 bytes long (33 byte topic), but sent with 15 consecutive calls to mosquitto_pub (so at most some shell & connect overhead between msgs). Problem was that I was just getting the first one or two messages.

Raising MQTT_BUF_SIZE to 1536 removed this problem, which gives additional weight to the suggestion above that we are dealing with TCP packet size limitations.

Just my 2 cents, if it can help anyone :)

[marcelstoer]

PRs for the buffer increase are certainly welcome.

[stromnet]

@joysfera do you have the possibility to test out the #2571 fix, to see if this fixes the issues you are seeing properly?

[joysfera]

@joysfera do you have the possibility to test out the #2571 fix, to see if this fixes the issues you are seeing properly?

I have published a test code above in the issue description so anyone can test it. I myself have been using my own patched version for four months already but I went for 1536 bytes because I like round numbers :-) I will test your 1500 bytes version when I get a chance.

[stromnet]

2571 is a proper fix which does not rely on a specific local static buffer, and handles slot more scenarios where old code (regardless of buffer size) would fail.

See exact details in PR/commits :)

On November 30, 2018 12:46:36 PM GMT+01:00, "Petr Stehlík" [e-mail] wrote:

@joysfera do you have the possibility to test out the #2571 fix, to
see if this fixes the issues you are seeing properly?

I have published a test code above in the issue description so anyone
can test it. I myself have been using my own patched version for four
months already but I went for 1536 bytes because I like round
numbers :-) I will test your 1500 bytes version when I get a chance.

--
You are receiving this because you commented.
Reply to this email directly or view it on GitHub:
https://github.com/nodemcu/nodemcu-firmware/issues/2308#issuecomment-443179932

--
Sent from my Android device with K-9 Mail. Please excuse my brevity.

[joysfera]

Ah, sorry, my fault! I remember seeing somewhere a 1500 bytes buffer PR so I commented on that one. Will definitely check the proper fix because MQTT has (or used to have?) many weird issues in NodeMCU. Some of them might got fixed by #2571, hopefully?

[stromnet]

Right, my first fix was just changed size, then got around to fix it properly!

That might very well be the case, if it was related to dropped/missing messages at least. Quite a few cases which resulted in that..

On November 30, 2018 1:34:59 PM GMT+01:00, "Petr Stehlík" [e-mail] wrote:

Ah, sorry then, I remember seeing somewhere a 1500 bytes buffer PR so I
commented on that one. Will definitely check the proper fix because
MQTT has (or used to have) many weird issues in NodeMCU. Some of them
might got fixed but #2571, hopefully?

--
You are receiving this because you commented.
Reply to this email directly or view it on GitHub:
https://github.com/nodemcu/nodemcu-firmware/issues/2308#issuecomment-443190760

--
Sent from my Android device with K-9 Mail. Please excuse my brevity.

[joysfera]

@stromnet OK, got to testing this, at last. The #2571 does NOT fix this issue. My test code in the description above fails (= message not delivered) for 1019 characters long message (1018 is OK, so there's still a 1kB limit somewhere).

Using

NodeMCU custom build by frightanic.com
    branch: master
    commit: 11592951b90707cdcb6d751876170bf4da82850d
    SSL: false
    modules: bit,cron,crypto,ds18b20,file,gpio,http,mdns,mqtt,net,node,ow,rtcmem,rtctime,sjson,sntp,tmr,uart,wifi
 build created on 2018-12-25 18:09
 powered by Lua 5.1.4 on SDK 2.2.1(6ab97e9)

[stromnet]

@joysfera, if you where using the exact same code then I would expect it to fail. If you do not add the max_message_length param to the mqtt.Client constructor, it will default to 1024 (for full message, including headers & topic name).

It should not have been delivered to the regular .on('message', .. callback though, but rather to a overflow callback. Was it actually given to message callback?

[joysfera]

@stromnet I tried changing the max_message_length, as follows:

mqtt_client = mqtt.Client(1, 120, nil, nil, 1, 1536)

Didn't help, the on("message") still does not receive the message.

Adding the "overflow" callback does not make any sense to me. I could imagine a flag that a message is not complete because it was larger than max_message_length but why having two different callbacks for the same thing?

[stromnet]

Hm, I wonder if there perhaps is a bug in the mqtt.Client constructor, it checks if the third and fourth parameters are strings, so when using nil it might become confused.. Can you try with "" instead? And/or test without username/password params at all (1,120,1,1536).

As for the overflow method, that solution was suggested here: https://github.com/nodemcu/nodemcu-firmware/pull/2544#issuecomment-436424132
It makes sense to avoid giving known broken messages to the message callback imo.

[joysfera]

Damn, after rebooting the ESP8266 and re-trying identical set of commands (well, only changed nil for '' in the Client) it started working correctly. Now the on("message") receives messages up to 1530 bytes (for max_message_length=1536). So everything is awesome, thank you! :)

[joysfera]

Now I just have to try out if the older Client() can handle an additional parameter without going crazy.
EDIT: just tested, older Client() does not complain so it seems to be backward compatible solution to this issue. Thank you, @stromnet !

[stromnet]

Great!

Yes, older Client should just ignore it.
Calling client.on('overflow' on a older version will raise a LUA error though, method not supported.