Summary

When using esp_mqtt_client_publish with a message longer than the buffer size (MQTT_BUFFER_SIZE_BYTE), the client disconnects and Mosquitto receives garbage data.

Environment

• Tested with ESP-IDF: v4.1.2, v4.3 and [master] @ (espressif/esp-idf@279c8ae), (Issue not present on v4.1)

• Tested with selected esp-mqtt submobule and with 383e7e5.

• ESP32-WROOM-32D

• Mosquitto 2.0.14 with this config:

  allow_anonymous true
  
  listener 1883
  protocol mqtt
  
  listener 80
  protocol websockets
  

How to reproduce

1. Used this example https://github.com/espressif/esp-idf/tree/master/examples/protocols/mqtt/ws @ espressif/esp-idf@279c8ae

2. Configured example project with Wifi SSID and pass and MQTT server address.

3. Added this at line 63 (after sending topic/qos0/"data" (string with +1200 characters):

   case MQTT_EVENT_SUBSCRIBED:
       ESP_LOGI(TAG, "MQTT_EVENT_SUBSCRIBED, msg_id=%d", event->msg_id);
       msg_id = esp_mqtt_client_publish(client, "/topic/qos0", "data", 0, 0, 0);
       ESP_LOGI(TAG, "sent publish successful, msg_id=%d", msg_id);
       
   +   msg_id = esp_mqtt_client_publish(client, "/topic/long", "Lorem ipsum dolor sit amet, consectetur adipiscing elit. Suspendisse nibh nibh, tempus ut vulputate in, auctor eu quam. Suspendisse vel auctor nisi. Nam tellus erat, porta auctor vulputate vel, venenatis id arcu. Phasellus a viverra risus. Maecenas imperdiet nibh augue, ut malesuada sapien scelerisque eget. Donec iaculis dui ut ultrices interdum. Maecenas convallis mattis lobortis. Quisque ac congue ipsum, eu mollis est. Pellentesque nec ante leo. Nam a ipsum tristique, sagittis nunc non, mollis sapien. Cras quam urna, consectetur ut tellus vulputate, venenatis suscipit mi. Proin pretium arcu convallis, dictum dolor vitae, ultricies nulla. Integer id eleifend mauris. Integer iaculis, augue ut mattis tempor, est felis sodales justo, ac interdum lacus orci non eros. Nulla accumsan ut arcu sed ornare. Ut aliquet erat vel eleifend consequat. Ut sit amet tincidunt eros. Vivamus nec libero ut velit pretium molestie. Orci varius natoque penatibus et magnis dis parturient montes, nascetur ridiculus mus. Nullam rhoncus nisi ut interdum blandit. Fusce tincidunt dictum tellus, sit amet suscipit ex fermentum tempus. Integer feugiat iaculis volutpat. Pellentesque habitant morbi tristique posuere.", 0, 0, 0);
   +   ESP_LOGI(TAG, "sent long publish successful, msg_id=%d", msg_id);
       break;

4. Uploaded to ESP, got the following result:

   Click to see full verbose log

   I (5571) esp_netif_handlers: example_connect: sta ip: 192.168.5.126, mask: 255.255.255.0, gw: 192.168.5.1
   I (5571) example_connect: Got IPv4 event: Interface "example_connect: sta" address: 192.168.5.126
   I (5581) example_connect: Connected to example_connect: sta
   I (5581) example_connect: - IPv4 address: 192.168.5.126
   D (5591) MQTT_CLIENT: MQTT client_id=ESP32_2547D8
   D (5591) MQTT_CLIENT: Core selection disabled
   I (5601) MQTTWS_EXAMPLE: Other event id:7
   W (5641) wifi:<ba-add>idx:0 (ifx:0, 78:8a:20:8d:ec:be), tid:0, ssn:0, winSize:64
   D (5651) TRANSPORT_WS: sub_protocol: mqtt
   D (5651) TRANSPORT_WS: Write upgrade request
   GET / HTTP/1.1
   Connection: Upgrade
   Host: 192.168.5.119:80
   User-Agent: ESP32 Websocket Client
   Upgrade: websocket
   Sec-WebSocket-Version: 13
   Sec-WebSocket-Key: TDRus8asdaEKkZPR4P+T9Qg==
   Sec-WebSocket-Protocol: mqtt
   
   
   D (5801) TRANSPORT_WS: Read header chunk 159, current header size: 159
   D (5801) TRANSPORT_WS: server key=1kZasdd2xa++p1OP/LEiPTNOxmrI=, send_key=TDRus8asdaEKkZPR4P+T9Qg==,     expected_server_key=1kZasdd2xa++p1OP/LEiPTNOxmrI=
   D (5811) MQTT_CLIENT: Transport connected to ws://192.168.5.119:80
   D (5811) MQTT_CLIENT: Sending MQTT CONNECT message, type: 1, id: 0000
   D (5861) TRANSPORT_WS: Opcode: 2, mask: 0, len: 4
   
   D (5861) TRANSPORT_WS: Actual data to receive (4) are longer than ws buffer (1)
   D (5861) MQTT_CLIENT: mqtt_message_receive: first byte: 0x20
   D (5871) TRANSPORT_WS: Actual data to receive (3) are longer than ws buffer (1)
   D (5871) MQTT_CLIENT: mqtt_message_receive: read "remaining length" byte: 0x2
   D (5881) MQTT_CLIENT: mqtt_message_receive: total message length: 4 (already read: 2)
   D (5891) MQTT_CLIENT: mqtt_message_receive: read_len=2
   D (5891) MQTT_CLIENT: mqtt_message_receive: transport_read():4 4
   D (5901) MQTT_CLIENT: Connected
   I (5901) MQTTWS_EXAMPLE: MQTT_EVENT_CONNECTED
   D (5911) MQTT_CLIENT: mqtt_enqueue id: 29847, type=3 successful
   D (5911) OUTBOX: ENQUEUE msgid=29847, msg_type=3, len=23, size=23
   I (5921) MQTTWS_EXAMPLE: sent publish successful, msg_id=29847
   D (5931) MQTT_CLIENT: mqtt_enqueue id: 16553, type=8 successful
   D (5931) OUTBOX: ENQUEUE msgid=16553, msg_type=8, len=18, size=41
   D (5941) MQTT_CLIENT: Sent subscribe topic=/topic/qos0, id: 16553, type=8 successful
   I (5951) MQTTWS_EXAMPLE: sent subscribe successful, msg_id=16553
   D (5951) MQTT_CLIENT: mqtt_enqueue id: 26594, type=8 successful
   D (5961) OUTBOX: ENQUEUE msgid=26594, msg_type=8, len=18, size=59
   D (5971) MQTT_CLIENT: Sent subscribe topic=/topic/qos1, id: 26594, type=8 successful
   I (5971) MQTTWS_EXAMPLE: sent subscribe successful, msg_id=26594
   D (5981) MQTT_CLIENT: unsubscribe, topic"/topic/qos1", id: 62594
   D (5991) MQTT_CLIENT: mqtt_enqueue id: 62594, type=10 successful
   D (5991) OUTBOX: ENQUEUE msgid=62594, msg_type=10, len=17, size=76
   D (6001) MQTT_CLIENT: Sent Unsubscribe topic=/topic/qos1, id: 62594, successful
   I (6001) MQTTWS_EXAMPLE: sent unsubscribe successful, msg_id=62594
   D (6011) TRANSPORT_WS: Opcode: 2, mask: 0, len: 4
   
   D (6021) TRANSPORT_WS: Actual data to receive (4) are longer than ws buffer (1)
   D (6031) MQTT_CLIENT: mqtt_message_receive: first byte: 0x40
   D (6031) TRANSPORT_WS: Actual data to receive (3) are longer than ws buffer (1)
   D (6041) MQTT_CLIENT: mqtt_message_receive: read "remaining length" byte: 0x2
   D (6041) MQTT_CLIENT: mqtt_message_receive: total message length: 4 (already read: 2)
   D (6051) MQTT_CLIENT: mqtt_message_receive: read_len=2
   D (6061) MQTT_CLIENT: mqtt_message_receive: transport_read():4 4
   D (6061) MQTT_CLIENT: msg_type=4, msg_id=29847
   D (6071) MQTT_CLIENT: pending_id=62594, pending_msg_count = 4
   D (6071) OUTBOX: DELETED msgid=29847, msg_type=3, remain size=53
   D (6081) MQTT_CLIENT: received MQTT_MSG_TYPE_PUBACK, finish QoS1 publish
   I (6091) MQTTWS_EXAMPLE: MQTT_EVENT_PUBLISHED, msg_id=29847
   D (6101) TRANSPORT_WS: Opcode: 2, mask: 0, len: 5
   
   D (6101) TRANSPORT_WS: Actual data to receive (5) are longer than ws buffer (1)
   D (6111) MQTT_CLIENT: mqtt_message_receive: first byte: 0x90
   D (6111) TRANSPORT_WS: Actual data to receive (4) are longer than ws buffer (1)
   D (6121) MQTT_CLIENT: mqtt_message_receive: read "remaining length" byte: 0x3
   D (6131) MQTT_CLIENT: mqtt_message_receive: total message length: 5 (already read: 2)
   D (6131) MQTT_CLIENT: mqtt_message_receive: read_len=3
   D (6141) MQTT_CLIENT: mqtt_message_receive: transport_read():5 5
   D (6141) MQTT_CLIENT: msg_type=9, msg_id=16553
   D (6151) MQTT_CLIENT: pending_id=62594, pending_msg_count = 3
   D (6161) OUTBOX: DELETED msgid=16553, msg_type=8, remain size=35
   D (6161) MQTT_CLIENT: deliver_suback, message_length_read=5, message_length=5
   I (6171) MQTTWS_EXAMPLE: MQTT_EVENT_SUBSCRIBED, msg_id=16553
   I (6181) MQTTWS_EXAMPLE: sent publish successful, msg_id=0
   I (6181) MQTTWS_EXAMPLE: sent long publish successful, msg_id=0
   D (6221) TRANSPORT_WS: Opcode: 2, mask: 0, len: 5
   
   D (6221) TRANSPORT_WS: Actual data to receive (5) are longer than ws buffer (1)
   D (6221) MQTT_CLIENT: mqtt_message_receive: first byte: 0x90
   D (6221) TRANSPORT_WS: Actual data to receive (4) are longer than ws buffer (1)
   D (6231) MQTT_CLIENT: mqtt_message_receive: read "remaining length" byte: 0x3
   D (6241) MQTT_CLIENT: mqtt_message_receive: total message length: 5 (already read: 2)
   D (6251) MQTT_CLIENT: mqtt_message_receive: read_len=3
   D (6251) MQTT_CLIENT: mqtt_message_receive: transport_read():5 5
   D (6261) MQTT_CLIENT: msg_type=9, msg_id=26594
   D (6261) MQTT_CLIENT: pending_id=62594, pending_msg_count = 2
   D (6271) OUTBOX: DELETED msgid=26594, msg_type=8, remain size=17
   D (6281) MQTT_CLIENT: deliver_suback, message_length_read=5, message_length=5
   I (6281) MQTTWS_EXAMPLE: MQTT_EVENT_SUBSCRIBED, msg_id=26594
   I (6291) MQTTWS_EXAMPLE: sent publish successful, msg_id=0
   I (6301) MQTTWS_EXAMPLE: sent long publish successful, msg_id=0
   D (6301) TRANSPORT_WS: Opcode: 2, mask: 0, len: 4
   
   D (6311) TRANSPORT_WS: Actual data to receive (4) are longer than ws buffer (1)
   D (6321) MQTT_CLIENT: mqtt_message_receive: first byte: 0xb0
   D (6321) TRANSPORT_WS: Actual data to receive (3) are longer than ws buffer (1)
   D (6331) MQTT_CLIENT: mqtt_message_receive: read "remaining length" byte: 0x2
   D (6331) MQTT_CLIENT: mqtt_message_receive: total message length: 4 (already read: 2)
   D (6341) MQTT_CLIENT: mqtt_message_receive: read_len=2
   D (6351) MQTT_CLIENT: mqtt_message_receive: transport_read():4 4
   D (6351) MQTT_CLIENT: msg_type=11, msg_id=62594
   D (6361) MQTT_CLIENT: pending_id=62594, pending_msg_count = 1
   D (6361) OUTBOX: DELETED msgid=62594, msg_type=10, remain size=0
   D (6371) MQTT_CLIENT: UnSubscribe successful
   I (6371) MQTTWS_EXAMPLE: MQTT_EVENT_UNSUBSCRIBED, msg_id=62594
   D (6381) TRANSPORT_WS: Opcode: 2, mask: 0, len: 19
   
   D (6391) TRANSPORT_WS: Actual data to receive (19) are longer than ws buffer (1)
   D (6391) MQTT_CLIENT: mqtt_message_receive: first byte: 0x30
   D (6401) TRANSPORT_WS: Actual data to receive (18) are longer than ws buffer (1)
   D (6411) MQTT_CLIENT: mqtt_message_receive: read "remaining length" byte: 0x11
   D (6411) MQTT_CLIENT: mqtt_message_receive: total message length: 19 (already read: 2)
   D (6421) MQTT_CLIENT: mqtt_message_receive: read_len=17
   D (6431) MQTT_CLIENT: mqtt_message_receive: transport_read():19 19
   D (6431) MQTT_CLIENT: msg_type=3, msg_id=0
   D (6441) MQTT_CLIENT: deliver_publish, message_length_read=19, message_length=19
   D (6441) MQTT_CLIENT: deliver_publish: msg_topic_len=11
   D (6451) MQTT_CLIENT: Get data len= 4, topic len=11, total_data: 4 offset: 0
   I (6461) MQTTWS_EXAMPLE: MQTT_EVENT_DATA
   TOPIC=/topic/qos0
   DATA=data
   E (6471) TRANSPORT_WS: Error read data
   E (6471) MQTT_CLIENT: mqtt_message_receive: transport_read() error: errno=128
   I (6481) MQTTWS_EXAMPLE: MQTT_EVENT_ERROR
   E (6481) MQTTWS_EXAMPLE: Last error reported from esp-tls: 0x8008
   I (6491) MQTTWS_EXAMPLE: Last errno string (Success)
   E (6491) MQTT_CLIENT: mqtt_process_receive: mqtt_message_receive() returned -1
   D (6501) MQTT_CLIENT: Reconnect after 10000 ms
   I (6511) MQTTWS_EXAMPLE: MQTT_EVENT_DISCONNECTED
   

   I (5594) esp_netif_handlers: example_connect: sta ip: 192.168.5.126, mask: 255.255.255.0, gw: 192.168.5.1
   I (5594) example_connect: Got IPv4 event: Interface "example_connect: sta" address: 192.168.5.126
   I (5604) example_connect: Connected to example_connect: sta
   I (5604) example_connect: - IPv4 address: 192.168.5.126
   I (5614) MQTTWS_EXAMPLE: Other event id:7
   W (5674) wifi:<ba-add>idx:0 (ifx:0, 78:8a:20:8d:ec:be), tid:0, ssn:0, winSize:64
   I (5994) MQTTWS_EXAMPLE: MQTT_EVENT_CONNECTED
   I (6004) MQTTWS_EXAMPLE: sent publish successful, msg_id=28377
   I (6004) MQTTWS_EXAMPLE: sent subscribe successful, msg_id=15705
   I (6004) MQTTWS_EXAMPLE: sent subscribe successful, msg_id=20415
   I (6014) MQTTWS_EXAMPLE: sent unsubscribe successful, msg_id=57707
   I (6034) MQTTWS_EXAMPLE: MQTT_EVENT_PUBLISHED, msg_id=28377
   I (6034) MQTTWS_EXAMPLE: MQTT_EVENT_SUBSCRIBED, msg_id=15705
   I (6044) MQTTWS_EXAMPLE: sent publish successful, msg_id=0
   I (6044) MQTTWS_EXAMPLE: sent long publish successful, msg_id=0
   I (6054) MQTTWS_EXAMPLE: MQTT_EVENT_SUBSCRIBED, msg_id=20415
   I (6054) MQTTWS_EXAMPLE: sent publish successful, msg_id=0
   I (6064) MQTTWS_EXAMPLE: sent long publish successful, msg_id=0
   I (6074) MQTTWS_EXAMPLE: MQTT_EVENT_UNSUBSCRIBED, msg_id=57707
   I (6074) MQTTWS_EXAMPLE: MQTT_EVENT_DATA
   TOPIC=/topic/qos0
   DATA=data
   E (6084) TRANSPORT_WS: Error read data
   E (6084) MQTT_CLIENT: mqtt_message_receive: transport_read() error: errno=128
   I (6094) MQTTWS_EXAMPLE: MQTT_EVENT_ERROR
   E (6094) MQTTWS_EXAMPLE: Last error reported from esp-tls: 0x8008
   I (6104) MQTTWS_EXAMPLE: Last errno string (Success)
   E (6104) MQTT_CLIENT: mqtt_process_receive: mqtt_message_receive() returned -1
   I (6114) MQTTWS_EXAMPLE: MQTT_EVENT_DISCONNECTED
   

I've also subscribed to the topics to see the what is send (mosquitto_sub -v -h 192.168.5.119 -t '#'). Here you see that there is some weird characters being send (I think a missing null terminator).

/topic/qos1 data_3
/topic/qos0 data
/topic/long Lorem ipsum dolor sit amet, consectetur adipiscing elit. Suspendisse nibh nibh, tempus ut vulputate in, auctor eu quam. Suspendisse vel auctor nisi. Nam tellus erat, porta auctor vulputate vel, venenatis id arcu. Phasellus a viverra risus. Maecenas imperdiet nibh augue, ut malesuada sapien scelerisque eget. Donec iaculis dui ut ultrices interdum. Maecenas convallis mattis lobortis. Quisque ac congue ipsum, eu mollis est. Pellentesque nec ante leo. Nam a ipsum tristique, sagittis nunc non, mollis sapien. Cras quam urna, consectetur ut tellus vulputate, venenatis suscipit mi. Proin pretium arcu convallis, dictum dolor vitae, ultricies nulla. Integer id eleifend mauris. Integer iaculis, augue ut mattis tempor, est felis sodales justo, ac interdum lacus orci non eros. Nulla accumsan ut arcu sed ornare. Ut aliquet erat vel eleifend consequat. Ut sit amet tincidunt eros. Vivamus nec libero ut velit pretium molestie. Orci varius natoque penatibus et magnis dis parturient montes, nascetur ridiculus 0
                                                   /topic/qos0data0�
                                                                        /topic/longLorem ipsum dolor sit amet, consectetur adipiscing elit. Suspendisse nibh nibh, tempus ut vulputate in, auctor eu quam. Suspendisse vel auctor nisi. Nam tellus e