"Dropped a packet" when sending more than once per second

[pepijndevos]

• Arduino board: NodeMCU (ESP8266)
• Arduino IDE version: 1.8.5
• Library version: 0.20.3

On my Ubuntu 18.04 laptop, I installed mosquito and ran the following script:

while true; do mosquitto_pub -t robot/commands -m `date +%s%N`; sleep 0.5; done;

Then on the ESP8266 I'm pretty much running the mqtt_esp8266_callback example, modified to connect to my WiFi, my local Mosquito broker, and subscribe to my topic rather than then ones in the example.

If I run it at a one second interval, it's fine, but if I run it with anything less, I get the output below (debugging enabled). On Wireshark everything looks completely normal.

Read data:      0 [0x30], 
Packet Type:        0 [0x30], 
Read data:      # [0x23], 
Packet Length:  35
Read data:        [0x00],   [0x0E], r [0x72], o [0x6F], b [0x62], o [0x6F], t [0x74], / [0x2F], 
    c [0x63], o [0x6F], m [0x6D], m [0x6D], a [0x61], n [0x6E], d [0x64], s [0x73], 
    1 [0x31], 5 [0x35], 3 [0x33], 7 [0x37], 0 [0x30], 2 [0x32], 0 [0x30], 3 [0x33], 
    9 [0x39], 7 [0x37], 9 [0x39], 7 [0x37], 9 [0x39], 7 [0x37], 7 [0x37], 7 [0x37], 
    8 [0x38], 0 [0x30], 9 [0x39], 
Dropped a packet

For comparison, this is what it looks like with a correctly read packet:

Read data:      0 [0x30], 
Packet Type:        0 [0x30], 
Read data:      # [0x23], 
Packet Length:  35
Read data:        [0x00],   [0x0E], r [0x72], o [0x6F], b [0x62], o [0x6F], t [0x74], / [0x2F], 
    c [0x63], o [0x6F], m [0x6D], m [0x6D], a [0x61], n [0x6E], d [0x64], s [0x73], 
    1 [0x31], 5 [0x35], 3 [0x33], 7 [0x37], 0 [0x30], 2 [0x32], 0 [0x30], 9 [0x39], 
    4 [0x34], 3 [0x33], 9 [0x39], 2 [0x32], 4 [0x34], 1 [0x31], 4 [0x34], 7 [0x37], 
    0 [0x30], 0 [0x30], 6 [0x36], 
Packet len: 37
    0 [0x30], # [0x23],   [0x00],   [0x0E], r [0x72], o [0x6F], b [0x62], o [0x6F], 
    t [0x74], / [0x2F], c [0x63], o [0x6F], m [0x6D], m [0x6D], a [0x61], n [0x6E], 
    d [0x64], s [0x73], 1 [0x31], 5 [0x35], 3 [0x33], 7 [0x37], 0 [0x30], 2 [0x32], 
    0 [0x30], 9 [0x39], 4 [0x34], 3 [0x33], 9 [0x39], 2 [0x32], 4 [0x34], 1 [0x31], 
    4 [0x34], 7 [0x37], 0 [0x30], 0 [0x30], 6 [0x36], 
Looking for subscription len 14
Found sub #0
Data len: 19
Data: 1537020943924147006

[cls-nebadje]

I suspect this being a problem with the ping implementation, see https://forums.adafruit.com/viewtopic.php?f=19&t=101472 There's another issue which seems to be related, see #96. Most probably data gets lost due to a bad ping implementation. I hope they continue to maintain this library ...

[pepijndevos]

Fwiw, I ended up using another mqtt library which has been rock solid.

I think you could be right about the ping though. My experience with Adafruit is they maintain their libraries, but slowly. They'll definitely fix this within a decade. Time to merge a completely flawless PR can be a bit shorter.

On Thu, 11 Oct 2018, 18:42 cls-nebadje, notifications@github.com wrote:

I suspect this being a problem with the ping implementation, see https://forums.adafruit.com/viewtopic.php?f=19&t=101472 There's another issue which seems to be related, see #96 https://github.com/adafruit/Adafruit_MQTT_Library/issues/96. Most probably data gets lost due to a bad ping implementation. I hope they continue to maintain this library ...

— You are receiving this because you authored the thread. Reply to this email directly, view it on GitHub https://github.com/adafruit/Adafruit_MQTT_Library/issues/132#issuecomment-429029000, or mute the thread https://github.com/notifications/unsubscribe-auth/AAKSoXf463APPBlrQgZvLaB0PwKULo1sks5uj3UDgaJpZM4WqYl4 .

[Barabba11]

pepijndevos which library you used instead? Thank you

[SharkPolo]

I can confirm that the problem could be the ping. I stop calling the ping function on the loop and it stop dropping. If you need a library for MQTT to use with another Broker that is not Adrafuit IO you can use: https://github.com/knolleary/pubsubclient I use Mosquitto as a local broker on my Raspberry Pi.

[brentru]

After analyzing - it seems the call to ping(), which calls processPacketsUntil, discards the packet if its not the MQTT_CTRL_PING_RESP type.

Possibly we should implement something similar to #170 where the packet's type is checked within processPacketsUntil and a callback is executed depending on which packet type is detected.

---

Receiving a publish packet within a ping call, instead of a ping. (NOTE: I added a line to check if the packet is MQTT_CTRL_PUBLISH type, instead of printing "dropped a packet")

-- CHECKING PING --
Read data:      0 [0x30], 
Packet Type:        0 [0x30], 
Read data:      # [0x23], 
Packet Length:  35
Read data:        [0x00],   [0x17], d [0x64], e [0x65], v [0x76], i [0x69], c [0x63], e [0x65], 
    s [0x73], / [0x2F], p [0x70], y [0x79], p [0x70], o [0x6F], r [0x72], t [0x74], 
    a [0x61], l [0x6C], / [0x2F], s [0x73], i [0x69], g [0x67], n [0x6E], a [0x61], 
    l [0x6C],   [0x12],   [0x08],   [0x0A],   [0x03], D [0x44], 1 [0x31], 3 [0x33], 
      [0x12],   [0x01], 1 [0x31], 
Got PUBLISH packet instead
-- CHECKED PING --

Successfully executing an incoming publish packet to a subscription callback. Note that this happens outside of the ping.

-- CHECKED PING --
Read data:      0 [0x30], 
Packet Type:        0 [0x30], 
Read data:      # [0x23], 
Packet Length:  35
Read data:        [0x00],   [0x17], d [0x64], e [0x65], v [0x76], i [0x69], c [0x63], e [0x65], 
    s [0x73], / [0x2F], p [0x70], y [0x79], p [0x70], o [0x6F], r [0x72], t [0x74], 
    a [0x61], l [0x6C], / [0x2F], s [0x73], i [0x69], g [0x67], n [0x6E], a [0x61], 
    l [0x6C],   [0x12],   [0x08],   [0x0A],   [0x03], D [0x44], 1 [0x31], 3 [0x33], 
      [0x12],   [0x01], 0 [0x30], 
Packet len: 37
    0 [0x30], # [0x23],   [0x00],   [0x17], d [0x64], e [0x65], v [0x76], i [0x69], 
    c [0x63], e [0x65], s [0x73], / [0x2F], p [0x70], y [0x79], p [0x70], o [0x6F], 
    r [0x72], t [0x74], a [0x61], l [0x6C], / [0x2F], s [0x73], i [0x69], g [0x67], 
    n [0x6E], a [0x61], l [0x6C],   [0x12],   [0x08],   [0x0A],   [0x03], D [0x44], 
    1 [0x31], 3 [0x33],   [0x12],   [0x01], 0 [0x30], 
Looking for subscription len 23
Found sub #1
Data len: 10
Data: 
D13
0
Received data from signalTopic topic:
      [0x12],   [0x08],   [0x0A],   [0x03], D [0x44], 1 [0x31], 3 [0x33],   [0x12], 
      [0x01], 0 [0x30], 
DEBUG: Pin event callback
Pin: 13
Value: 0

[brentru]

Another solution (possibly simpler) would to only execute a PINGREQ/PINGRESP every MQTT_CONN_KEEPALIVE seconds (example in a related Adafruit MQTT library: https://github.com/adafruit/Adafruit_CircuitPython_MiniMQTT/blob/master/adafruit_minimqtt/adafruit_minimqtt.py#L712), or otherwise return.

[lynema]

Is there any testing that needs to happen to get a fix for this through? Retained messages are triggering this issue on application startup.

[brentru]

This issue has been fixed in the latest release, 2.1.0.