Intermittent delay of minutes between ESP publish and receipt by mosquitto in a pi

[pat-2010]

I'm seeing an intermittent 6 minute or so delay between a publish on an ESP32 S3 and the message showing up in wireshark on the destination Raspberry Pi. My original program published a set of environmental data every minute. The program at the bottom is a modification of that program intended to focus in on this problem. It runs a loop and publishes a loop counter and some timing info to help debugging.

Specifically what I am seeing is an intermittent delay of all published messages of about 6 minutes. Then all the messages show up at once in wireshark. The publishes are typically delivered in one packet. The delay is often 6 min 22 sec but not always. Sometimes it is a single batch that is delayed with normal delivery after the one oversized and late packet. Sometimes there is a sequence of delayed oversized packets.

My setup is an ESP32-S3 for data collection. Mosquitto (v1.5.7) and Nodered are running on a raspberry pi 400. Using a pi zero to collect the data and publish it at the same frequency doesn't have a problem. Publishing to a Pi 4 with Mosquitto 2.0.11 doesn't have the same problem. Other ESPs do have the same problem. I'm suspecting a Mosquitto configuration problem on the pi, but I think I'm running a vanilla version of Mosquitto.

Here's wireshark output of a normal publish followed by one that was delayed. These are the messages from the ESP to the Pi captured on the Pi. Each cycle thru the loop publishes 4 times. The cycle time is 2 minutes. So the second batch would be expected as 12:18;11. Instead the publishes for times 12:18:11 and 12:20:11 show up at 12:21:21. And messages that were generated 2 minutes apart show up in the same packet. I have instrumented the code and have verified that the loop starts are exactly as expected.

Time len message
12:16:11.611 83 Publish Message [loop count ESP to 128]
12:16:11.613 217 Publish Message [t1], Publish Message [t2], Publish Message [debugstring]
12:21:21.851 83 Publish Message [loop count ESP to 128]
12:21:21.895 405 Publish Message [t1], Publish Message [t2], Publish Message [debugstring], Publish Message [loop count ESP to 128], Publish Message [t1], Publish Message [t2], Publish Message [debugstring]

I have more data. For example the code captures the duration of the first 3 publishes in the loop. That duration drops significantly (about half for the first publish) for messages that are delayed.

Hopefully someone has seen this before and knows what is happening.

Here is a version of the code. I've used 1 minute, 2 minute, 5 minute and 10 minute loop durations with no significant difference.
mqtt_delay_debug_r2.txt

[pat-2010]

Found a separate quirk. The one above I have only seen with Mosquitto running on my Raspberry Pi 400. When Mosquitto runs on a Pi zero or a Pi 4 (later version of mosquitto) I do not see the multi minute delay.

But I do see a delay of up to 0.6 seconds that follows a strange pattern. The program is a minor derivative of the one above. It publishes 4 topics at 60 second intervals. Several tests confirm that the loop timing is stable. When use Wireshark on the platform that is running Mosquitto I see the following pattern in the time of the MQTT protocol message containing the publish.