[Bug]: MQTT JSON Bug

[arduionoGP]

Category

Other

Hardware

T-Beam, Heltec v2.1

Firmware Version

1.3.42.9bd9252

Description

Environments and settings:
1.3.42.9bd9252 firmware, heltec and t-beam devices, android 1.3.41, windows chrome web, node-red mqtt broker, using default channel for this example. One device is connected to wifi with Settings for default channel uplink and downlink ENABLED. Settings module, MQTT config, encryption off, JSON output enabled ON.

Issue:
When a sequence of LORA message packets is sent to a lora module connected to a mqtt broker, the broker responds by repeatedly sending out only the first message received from that particular client. The correct text messages in the sequence correctly display on the receiving OLED.

Example:
Device one which is connected by bluetooth via android sends three messages: “Let’s stay another message”, “I meant try”,
“It doesn’t increment”.
Device two is connected via wifi network to a mqtt broker. The broker responds to each message but the payloads sent all only contain the first message's text. The three messages are published by the broker on topic:
“msh/1/json/LongFast/!7efec08c”
and all look like:

{“channel”: 0, “from”: 2130621128, “id”: -1175740138, “payload”: {“text”: “Let’s stay another message”}, “sender”: “!7efec08c”, “timestamp”: 0, “to”: -1, “type”: “text”}

Reset via button on the receiving lora device doesn't fix it. Pulling power on that device to reset allows a fresh message to be sent via mqtt. Two different sending devices will send two different packets to the receiving device connected via mqtt. Those two different messages will then continue to repeat depending on the sending machine.

Relevant log output

No response

[caveman99]

the MQTT stuff is quite verbose in debug logging. Can you attach a serial debug log of the device (meshtastic --noproto if you got CLI installed) so we can have a look what is actually transmitted? There should be lines like 'publish json message to...' in there

[arduionoGP]

Sure. While doing this I noticed another issue.
When I am connected directly via CLI or via the web client the messages published by the MQQT Broker are either missing the "text" field in the JSON payload or are not even being sent to the broker. This only resolves by disconnecting all serial and a reset of the Heltec. The broker I was using is Aedes running in nod-red on Win10 local network. I just duplicated this behavior running a mosquito broker on a Pi so it's not a broker issue.

When NOT connected via CLI the payload of the packets on topic msh/1/json/LongFast/!7efec08c look like:
"{"channel": 0, "from": 2130621128, "id": 1932318822, "payload": {"text": "Super long message reo"}, "sender": "!7efec08c", "timestamp": 0, "to": -1, "type": "text"}"
These are usable but they duplicate the first message only.

When connected via CLI or via the web client there are either no MQTT JSON packets or the packet forwarded by the broker looks like:
"{"channel": 0, "from": 2130624652, "id": 526666665, "payload": {"hardware": 10, "id": "!7efec08c", "longname": "Meshtastic c08c", "shortname": "c08c"}, "sender": "!7efec08c", "timestamp": 0, "to": -1, "type": "nodeinfo"}"

The enclosed file is the debug output of the MQQT-connected heltec 2.1 from reset until three messages are received and displayed on the OLED. The messages were sent from an android app connected to second Heltec. (A T-beam is also on the mesh.)
The sent messages were: Message number one. | Message number two. | Message number three.

The debug file seems to be somewhat unhelpful as the MQQT doesn't seem to work properly when the device is connecting to something via the usb.

HeltecMQTTdebug.txt

[arduionoGP]

Further observations. Duplicated the behavior on a t-beam connected to the network. Findings are: the JSON topic will not publish to MQTT if the device has been connected to the Web client or the CLI even after disconnect. An unencrypted protobuf packet will publish after disconnect under the topic - msh/1/c/LongFast/!deviceName.
This behavior will not change on a reset but will change on a full power cycle. The JSON msh/1/json/LongFast/!deviceName topic will then repeatedly send only the initial message it first saw while the OLED will show the correct message.

[caveman99]

??:??:?? 114 [Router] serialized json message: {"channel": 0, "from": 2130624652 , "id": 1694546565, "payload": {"hardware": 10, "id": "!7efec08c", "longname": " Meshtastic c08c", "sh ??@? ?t???l????? 0?????@? ? ? ? hA?? ??? ? ? ??:??:?? 114 [Router] publish json message to msh/1/js on/LongFast/!7efec08c, 221 bytes: {"channel": 0, "from": 2130624652, "id": 16945 46565, "payload": {"hardware": 10, "id": "!7efe ??@? ?t???l????? 0?????@? ? ? ? hA?? ???? ?

Looks like some buffer is too small. Also please don't mix several issues in one bug report, it gets harder and harder to actually solve one issues... Lets focus on this buffer/garbling issue and retest the other observations after we get rid of this.

[arduionoGP]

Sounds good.
It does seem that the two behaviors might have a commonality.

[arduionoGP]

In case anyone comes here trying to figure out a way to get plain text messages while JSON is not working, I've put an interim solution on the discourse site:
https://meshtastic.discourse.group/t/here-is-a-newb-mqtt-tutorial-for-1-3/6583?u=gparduino

[arduionoGP]

Updated firmware test 1.3.44.4fa8d02 (there was a note that mqtt was worked on).

Similar errors, Serial debug file attached

Incidental observations:

1. first MQTT JSON message gets published to mqtt broker as long as the device has never been connected via serial-debug since the time of firmware re-install but only repeats the first message sent.
2. Once connected to debug JSON feature behaves as on the debug log. However, messages that look like msh/2/c/LongFast/!device correctly publish LORA received messages as unecrypted protobufs to the mqtt broker (but don't display to OLED).

tbeam.txt

[arduionoGP]

I have no experience with coding this language but I think at least one of the problems may be in the MQTT.cpp module, line 282:
msgPayload = Json::object({{"test", payloadStr}});
should it perhaps read -
msgPayload = Json::object{{"test", payloadStr}};

[thebentern]

I have no experience with coding this language but I think at least one of the problems may be in the MQTT.cpp module, line 282: msgPayload = Json::object({{"test", payloadStr}}); should it perhaps read - msgPayload = Json::object{{"test", payloadStr}};

Really great catch. That explains why we can easily blow out the buffer and why the text message payloads are coming through as json

[thebentern]

Closing, based on the fix in that latest PR. If any further issues occur, please open a new ticket with those.

[caveman99]

sorry, but that still doesn't cut it based on debug logging ...

17:54:12 450 [Router] serialized json message: {"channel": 0, "from": 633504868, "id": 941922293, "payload": {"air_util_tx": 0, "battery_level": 0, "channel_utilization": 0, "voltag?@??t??@p???|??P?????@??A?? ???
17:54:12 450 [Router] publish json message to msh/2/json/LongFast/!25c28464, 211 bytes: {"channel": 0, "from": 633504868, "id": 941922293, "payload": {"air_util_tx": 0, "battery_lev?@??t??@p???|??P?????@??A?? ???
17:54:12 450 [Router] Expanding short PSK #1
[...]

[caveman99]

and (which irks me more) that it doesn't seem to be able to deserialize the buffer it just sent and received back from MQTT.

17:54:12 450 [mqtt] Ignoring downlink message we originally sent.
17:54:12 451 [mqtt] Error: can't decode protobuf reason='invalid wire_type', pb_msgdesc 0x0x3f405a84
17:54:12 451 [mqtt] Received json payload on MQTT, parsing..
17:54:12 451 [mqtt] Ignoring downlink message we originally sent.

[arduionoGP]

Thank you very much for looking into this. I am new to this environment but got it loaded and am working through the mqtt code by adding debug statements.

I know there are other problems in this situation but in the section that converts a downstream packet to json (line 253).
It correctly gets through the "case" statement for case PortNum_TEXT_MESSAGE_APP and correctly returns the right msgPayload now (with the change above that makes it a json11 object.)

// if it isn't, then we need to create a json object
// with the string as the value
DEBUG_MSG("text message payload is of type plaintext\n");
msgPayload = Json::object{{"text", payloadStr}};
DEBUG_MSG(payloadStr);
DEBUG_MSG("\n");
DEBUG_MSG(msgPayload.dump().c_str());
DEBUG_MSG("\n");

It seems to not be agreeable with this statement that follows all the "cases" -->
Json jsonObj = Json::object{
{"id", Json((int)mp->id)},
{"timestamp", Json((int)mp->rx_time)},
{"to", Json((int)mp->to)},
{"from", Json((int)mp->from)},
{"channel", Json((int)mp->channel)},
{"type", msgType.c_str()},
{"sender", owner.id},
{"payload", msgPayload}
};

[caveman99]

that deserialization error was a red herrig which came from trying to feed the json payload to nanopb. i cleaned up a bit of debug printing there and changed the order of tests.

What caused the garbled output was the new fixed 160 char buffer in our debug print. I fixed that to truncate properly instead of just printing random areas of memory to the console. JSON and MQTT should work fine now.

[arduionoGP]

Almost there.

Remaining issue is that JSON text payload does not sent the latest message, it only repeatedly sends the first message received since reboot over and over.

The enclosed log is what happens when sending "Test message number one.", then "Test message number two.", then "Test message number three."

msh/2/c/channelID/nodeID sends correctly to mqtt
msh/2/json/channelID/nodeID does not update.

Here is a JPEG from the broker side with two messages. First one was: "Test package." Second one was: "Message one."
(Can't really tell from the log because of the truncated messages.)

teebeam.txt

[caveman99]

I have a possible fix building for that on https://github.com/meshtastic/Meshtastic-device/pull/1822/checks - can you verify once the PR build is done?

[arduionoGP]

Looks like it works!!! Thank you. Tested on a t-beam.
Broker side:

[thebentern]

Awesome!