Some mqtt messages are not sent if many consecutive ".setProperty().send()" calls are made

[bodiroga]

Hi guys!

I'm making some tests with the latest developer branch and I would like to know if anyone is able to confirm one issue that I'm seeing. Here you have the minimum sketch that I'm using to replicate the issue:

#include <Homie.h>

HomieNode temperatureNode("temperature", "ESH:Temperature");
HomieNode humidityNode("humidity", "ESH:Humidity");
HomieNode relayNode("relay", "ESH:Switch");

void setupHandler() {
  int wait_time = 0;
  delay(wait_time);
  humidityNode.setProperty("unit").send("%");
  delay(wait_time);
  relayNode.setProperty("itemtype").send("Switch");
  delay(wait_time);
  temperatureNode.setProperty("unit").send("ºC");
  delay(wait_time);
  temperatureNode.setProperty("itemtype").send("Number");
  delay(wait_time);
  humidityNode.setProperty("itemtype").send("Number");
  delay(wait_time);
}

void setup() {
  Serial.begin(115200);
  Serial << endl << endl;

  Homie_setFirmware("awesome-device", "1.0.0");
  Homie.setSetupFunction(setupHandler);

  temperatureNode.advertise("value");
  temperatureNode.advertise("itemtype");
  temperatureNode.advertise("unit");

  humidityNode.advertise("value");
  humidityNode.advertise("itemtype");
  humidityNode.advertise("unit");

  relayNode.advertise("value");
  relayNode.advertise("itemtype");

  Homie.setup();

}

void loop() {
  Homie.loop();

Nothing strange or complicated, right? Three HomieNodes, 2-3 properties in each node and, as some values are static, I send the properties values in the setupHandler() function.

The problem is that, if I don't insert a wait_time greater than 10ms between the calls, the last (and sometimes even the previous one) message is not send to the broker. In this case it's the HumidityNode's 'itemtype' value, but it's not related to the topic or payload value, because rearranging the calls doesn't change anything: the last value is lost.

I'm using a local mosquitto installation as a broker and I can replicate my issue in both a Raspberry Pi and in my development computer (i5, 8Gb RAM...).

Has anyone seen something like this before? Inserting a 10ms delay time solves the problem, but that's very weird and not a proper solution. Can someone try it at home and confirm the results? @timpur, I would love to hear your opinion, of course ;)

Many thanks as always for your help and support and best regards,

Aitor

[timpur]

Looks all g to me, will do some testing and get back to you.

[kpishere]

Yes. I use 2.0.0 code, overclocked esp8288-12e, mosquitto on macos. with publish of just two properties i see it. wifi connection quality is typically 35%

[bertmelis]

I'm having the same issue, with the develop-v3 branch. When sending 2 consecutive messages, the first one is missing. I'm setting 2 properties on one node. Wemos D1 mini (so esp8266), default settings, up-to-date dependencies

  sds011.onData([](float pm25Value, float pm10Value) {
    char payload[10] = {"\0"};
    snprintf(payload, sizeof(payload), "%.0f", pm25Value);
    particlematterNode.setProperty("pm2_5").send(payload);
    snprintf(payload, sizeof(payload), "%.0f", pm10Value);
    particlematterNode.setProperty("pm10").send(payload);
  });

onData is called from the loop(). It used to work untill a few days ago but I can't remember all the things I've changed meanwhile.

[luebbe]

I had a similar issue in my homie node collection when setting three properties like this:

void BME280Node::onReadyToOperate()
{
  setProperty(cTemperatureUnit).send("°C");
  setProperty(cHumidityUnit).send("%");
  setProperty(cPressureUnit).send("hPa");
};

When I didn't send the temperature property as the first item, it was missing completely. I blamed it on the '°' character. I only found out when I cleared all MQTT topics before starting the device. Will try to reproduce ASAP

[kleini]

The following documentation link of AsyncMqttClient reveals the cause of the issue: http://marvinroger.viewdocs.io/async-mqtt-client/3.-Memory-management/ So we need to think, how we can resolve this issue. I will try to find out, where this 3-4KB size of the TCP window is defined and whether I can check how full it is. Then we can limit the data transfer accordingly.

[kleini]

https://github.com/marvinroger/async-mqtt-client/blob/0605524875dd4bf3004282812a203f8189d83005/src/AsyncMqttClient.cpp#L827 I will check the AsyncMqttClient::publish() return values whether I get 0.

[kleini]

And there it is

Triggering WIFI_CONNECTED event...
↕ Attempting to connect to MQTT...
Sending initial information...
• BME280 sensor:
  ◦ Temperature: 20.50 °C
  ◦ Temperature (after offset): 20.30 °C
  ◦ Humidity: 50.81 %
  ◦ Pressure: 973.68 hPa
✔ MQTT ready
Triggering MQTT_READY event...
MQTT packet send 28
MQTT packet send 29
MQTT packet send 30
MQTT packet send 31
MQTT packet send 32
Calling setup function...
MQTT packet send 33
MQTT packet send 34
MQTT packet send 35
MQTT packet send 0
• ADC measurement:
MQTT packet send 0
MQTT packet send 0

The code generates too much MQTT messages, which do not fit into TCP buffers.

[jimtng]

I'm also affected by this limitation, two folds, because I have a lot of properties to advertise, it got stuck in the initial announcement, and also during normal operation when I'm publishing values to those properties.

I'm using https://github.com/homieiot/homie-esp8266.git#develop-v3

A very simple example demonstrating the issue in the announcement stage:

#include <Homie.h>

HomieNode homieNode("test", "test", "test");

void setup() {
  Serial.begin(115200);
  Homie_setFirmware("test", "TEST");
  for (int i = 0; i< 100; i++) {
    homieNode.advertise(String("testxxxxx-" + String(i)).c_str()).settable();
  }
  Homie.setup();
}

void loop() {
  Homie.loop();
}

[jimtng]

Suggestion: use https://github.com/jeroenst/async-mqtt-client/commit/f066f6da2eb131db6118e7e1227aec7e7106befc

[stritti]

Long time no progress. Could we close this issue?

[kleini]

We should keep this issue for now. I did not see yet any significant changes, that would solve this problem. So it should still be reproducible and I will do so the next days.

[luebbe]

Isn't this caused by the asyncmqtt problems that @bertmelis is working on right now?

[kleini]

Isn't this caused by the asyncmqtt problems that @bertmelis is working on right now?

Looks like he is working on that and I try to verify whether his solutions work for the problems, I can reproduce. But I think, we should keep this issue open here just for documentation purposes.

[luebbe]

My comment was more directed at @stritti :)

[stritti]

Okay, maybe @bertmelis could tell us more.

[bertmelis]

First, the dangling pointer problem is solved by the PR in the async MQTT lib. Next, at the moment you cannot send more than the TCP window/frame size allows. So as soon as you reach 1500bytes, the next message will fail.

You know this by checking the return value.

I'm currently working out an 'outbox' which queues the messages and only fails when (almost) running out of heap space. Then this issue could be solved. I'm not setting a deadline though. It's still Christmas time after all.

[bertmelis]

For the record: maybe a semantic discussion. By failing I do not mean "crash". I should say "not succeeding".

[kleini]

@bertmelis I use this fix to publish more than what fits into TCP window. If you have the structure for the outbox classes on some branch, I would like to help to get things implemented.