mqtt_client: esp_mqtt_handle_transport_read_error: (IDFGH-14316)

[michaelsimp]

Answers checklist.

• I have read the documentation ESP-IDF Programming Guide and the issue is not addressed there.
• I have updated my IDF branch (master or release) to the latest version and checked that the issue is present there.
• I have searched the issue tracker for a similar issue and not found a similar issue.

IDF version.

5.3.2

Espressif SoC revision.

ESP32-S3 (QFN56) (revision v0.2)

Operating System used.

Windows

How did you build your project?

VSCode

If you are using Windows, please specify command line type.

PowerShell

Development Kit.

ESP32-S3-WROOM-1

Power Supply used.

USB

What is the expected behavior?

I am using MQTT5 over WiFi Mesh. Currently I am debugging a problem using only one ESP32 devboard connected as MESH_ROOT to my WiFi Router.

I am

• publishing messages to a Mosquito Broker for another Paho MQTT test client using esp_mqtt_client_enqueue rather than esp_mqtt_client_enqueue so the library determines when to send.
• receiving messages from the Mosquito Broker published by a Paho MQTT test client

For testing I am currently using TCP without TLS
mqtt5_cfg.broker.address.hostname = "192.168.1.2";
mqtt5_cfg.broker.address.port = 1883;
mqtt5_cfg.broker.address.transport = MQTT_TRANSPORT_OVER_TCP;
I have tested TLS successfully with HiveMQ
mqtt5_cfg.broker.address.uri = "mqtts://d72b0b51da08402e86d06db5db25f244.s1.eu.hivemq.cloud:8883",
mqtt5_cfg.broker.verification.certificate = (const char *)mqtt5_HiveHQ_io_pem_start,

What is the actual behavior?

It works for a while without errors and then I get the following errors:

E (18:02:38.125) mqtt_client: esp_mqtt_handle_transport_read_error: transport_read(): EOF
E (18:02:38.126) mqtt_client: esp_mqtt_handle_transport_read_error: transport_read() error: errno=128
E (18:02:38.127) aMQTT: MQTT_EVENT_ERROR
E (18:02:38.128) aMQTT: MQTT5 return code is 0
E (18:02:38.128) aMQTT: Last error reported from esp-tls: 0x8008
E (18:02:38.129) aMQTT: Last errno string (Success)
E (18:02:38.129) mqtt_client: mqtt_process_receive: mqtt_message_receive() returned -2
W (18:02:38.132) aMQTT: Broker disconnected

The messages are no large length wise and are not that frequent as you can see in the logs. I have been padding delays between receiving and send messages but it still occurs.
I am not getting msg_id < 0 errors when calling esp_mqtt_client_enqueue

Steps to reproduce.

It just occurs after a minute or so.
MQTT disconnects from the Broker, and I establish a new connection and resubscribe to my topics.

Debug Logs.

I (18:02:32.847) aMQTT: SiteID/00004827E21839D4/Pump/1/Status status=9/state=13/type=2/hose=2/product=2/seqNum=7/money=75.40/volume=7.52
I (18:02:33.058) aMQTT: SiteID/00004827E21839D4/Pump/8/Status status=0/state=0
I (18:02:33.686) aMQTT: /pump/2/command/resume
I (18:02:33.687) aMQTT: Correl: 419015
I (18:02:33.696) aMQTT: SiteID/00004827E21839D4/Pump/2/Response/Resume appRespCode=0/ 419015
I (18:02:34.196) aMQTT: POST DELAY
I (18:02:34.303) aMQTT: SiteID/00004827E21839D4/Pump/2/Status status=7/state=8/type=2/hose=1/product=1/seqNum=8/money=58.11/volume=5.81
I (18:02:34.408) aMQTT: SiteID/00004827E21839D4/Pump/2/Flow status=7/money=60.26/volume=6.02
I (18:02:35.032) aMQTT: /pump/1/command/resume
I (18:02:35.033) aMQTT: Correl: 419016
I (18:02:35.034) aMQTT: SiteID/00004827E21839D4/Pump/1/Response/Resume appRespCode=0/ 419016
I (18:02:35.531) aMQTT: POST DELAY
I (18:02:35.639) aMQTT: SiteID/00004827E21839D4/Pump/1/Status status=7/state=8/type=2/hose=2/product=2/seqNum=7/money=81.86/volume=8.17
I (18:02:35.749) aMQTT: SiteID/00004827E21839D4/Pump/9/Status status=0/state=0
I (18:02:36.078) aMQTT: SiteID/00004827E21839D4/Pump/1/Flow status=7/money=84.02/volume=8.39
I (18:02:37.088) aMQTT: /command/allstop
I (18:02:37.089) aMQTT: stopcode = 11
I (18:02:37.089) aMQTT: Correl: 419017
I (18:02:37.091) aMQTT: SiteID/00004827E21839D4/Response/AllStop appRespCode=0 419017
I (18:02:37.587) aMQTT: POST DELAY
I (18:02:37.690) aMQTT: SiteID/00004827E21839D4/Pump/1/Status status=9/state=13/type=2/hose=2/product=2/seqNum=7/money=101.25/volume=10.10
I (18:02:37.897) aMQTT: SiteID/00004827E21839D4/Pump/2/Status status=9/state=13/type=2/hose=1/product=1/seqNum=8/money=94.69/volume=9.46
E (18:02:38.125) mqtt_client: esp_mqtt_handle_transport_read_error: transport_read(): EOF
E (18:02:38.126) mqtt_client: esp_mqtt_handle_transport_read_error: transport_read() error: errno=128
E (18:02:38.127) aMQTT: MQTT_EVENT_ERROR
E (18:02:38.128) aMQTT: MQTT5 return code is 0
E (18:02:38.128) aMQTT: Last error reported from esp-tls: 0x8008
E (18:02:38.129) aMQTT: Last errno string (Success)
E (18:02:38.129) mqtt_client: mqtt_process_receive: mqtt_message_receive() returned -2
W (18:02:38.132) aMQTT: Broker disconnected
W (18:02:38.133) aMQTT: MQTT5 Broker reconnect
I (18:02:38.135) mqtt_client: Client force reconnect requested
I (18:02:38.136) aMQTT: Other event id:7
W (18:02:38.157) aMQTT: Broker connected
I (18:02:38.205) aMQTT: Resubscribe to our 4 Topics
I (18:02:38.212) aMQTT: Sent subscribe successful, Topic: SiteID/00004827E21839D4/Pump/+/Command/#  msg_id: 208
I (18:02:38.222) aMQTT: Sent subscribe successful, Topic: SiteID/00004827E21839D4/Pump/+/TransactionResponse  msg_id: 209
I (18:02:38.223) mqtt5_client: MQTT_MSG_TYPE_SUBACK return code is 1
I (18:02:38.224) aMQTT: MQTT_EVENT_SUBSCRIBED, msg_id=208  inFlightCounter: 1
I (18:02:38.233) mqtt5_client: MQTT_MSG_TYPE_SUBACK return code is 1
I (18:02:38.234) aMQTT: MQTT_EVENT_SUBSCRIBED, msg_id=209  inFlightCounter: 1
I (18:02:38.259) aMQTT: Sent subscribe successful, Topic: SiteID/00004827E21839D4/Command/#  msg_id: 210
I (18:02:38.269) mqtt5_client: MQTT_MSG_TYPE_SUBACK return code is 1
I (18:02:38.271) aMQTT: MQTT_EVENT_SUBSCRIBED, msg_id=210  inFlightCounter: 0
I (18:02:38.265) aMQTT: Sent subscribe successful, Topic: SiteID/00004827E21839D4/ConsoleCmd  msg_id: 211
I (18:02:38.277) mqtt5_client: MQTT_MSG_TYPE_SUBACK return code is 1
I (18:02:38.278) aMQTT: MQTT_EVENT_SUBSCRIBED, msg_id=211  inFlightCounter: 0
I (18:02:38.290) aMQTT: SiteID/00004827E21839D4/Status status=0/eStopStatus=1/runTime=000220
I (18:02:39.188) aMQTT: /command/liftallstop
I (18:02:39.189) aMQTT: liftcode = 1
I (18:02:39.189) aMQTT: Correl: 419025
I (18:02:39.191) aMQTT: SiteID/00004827E21839D4/Response/LiftAllStop appRespCode=0 419025
E (18:02:39.426) mqtt_client: esp_mqtt_handle_transport_read_error: transport_read(): EOF
E (18:02:39.427) mqtt_client: esp_mqtt_handle_transport_read_error: transport_read() error: errno=128
E (18:02:39.428) aMQTT: MQTT_EVENT_ERROR
E (18:02:39.429) aMQTT: MQTT5 return code is 0
E (18:02:39.429) aMQTT: Last error reported from esp-tls: 0x8008
E (18:02:39.430) aMQTT: Last errno string (Success)
E (18:02:39.431) mqtt_client: mqtt_process_receive: mqtt_message_receive() returned -2
W (18:02:39.434) aMQTT: Broker disconnected
W (18:02:39.435) aMQTT: MQTT5 Broker reconnect
I (18:02:39.436) mqtt_client: Client force reconnect requested
I (18:02:39.438) aMQTT: Other event id:7
W (18:02:39.463) aMQTT: Broker connected
I (18:02:39.687) aMQTT: POST DELAY
I (18:02:39.787) aMQTT: Resubscribe to our 4 Topics
I (18:02:39.796) aMQTT: Sent subscribe successful, Topic: SiteID/00004827E21839D4/Pump/+/Command/#  msg_id: 214
I (18:02:39.809) mqtt5_client: MQTT_MSG_TYPE_SUBACK return code is 1
I (18:02:39.810) aMQTT: MQTT_EVENT_SUBSCRIBED, msg_id=214  inFlightCounter: 1
I (18:02:39.819) aMQTT: Sent subscribe successful, Topic: SiteID/00004827E21839D4/Pump/+/TransactionResponse  msg_id: 215
I (18:02:39.819) mqtt5_client: MQTT_MSG_TYPE_SUBACK return code is 1
I (18:02:39.821) aMQTT: MQTT_EVENT_SUBSCRIBED, msg_id=215  inFlightCounter: 0
E (18:02:39.823) mqtt_client: esp_mqtt_handle_transport_read_error: transport_read(): EOF
E (18:02:39.825) mqtt_client: esp_mqtt_handle_transport_read_error: transport_read() error: errno=128
E (18:02:39.827) aMQTT: MQTT_EVENT_ERROR
E (18:02:39.827) aMQTT: MQTT5 return code is 0
E (18:02:39.828) aMQTT: Last error reported from esp-tls: 0x8008
E (18:02:39.828) aMQTT: Last errno string (Success)
E (18:02:39.829) mqtt_client: mqtt_process_receive: mqtt_message_receive() returned -2
W (18:02:39.832) aMQTT: Broker disconnected
I (18:02:39.832) aLED: connectionStatus: 1
W (18:02:39.834) aMQTT: MQTT5 Broker reconnect
I (18:02:39.834) mqtt_client: Client force reconnect requested
I (18:02:39.836) aMQTT: Other event id:7
W (18:02:39.858) aMQTT: Broker connected
I (18:02:39.859) aLED: connectionStatus: 0
I (18:02:39.878) mqtt5_client: MQTT_MSG_TYPE_SUBACK return code is 1
I (18:02:39.880) aMQTT: MQTT_EVENT_SUBSCRIBED, msg_id=216  inFlightCounter: 0
I (18:02:39.885) aMQTT: Sent subscribe successful, Topic: SiteID/00004827E21839D4/Command/#  msg_id: 216
I (18:02:39.899) mqtt5_client: MQTT_MSG_TYPE_SUBACK return code is 1
I (18:02:39.901) aMQTT: MQTT_EVENT_SUBSCRIBED, msg_id=217  inFlightCounter: 0
I (18:02:39.903) aMQTT: Sent subscribe successful, Topic: SiteID/00004827E21839D4/ConsoleCmd  msg_id: 217
I (18:02:39.905) aMQTT: /command/liftallstop
I (18:02:39.905) aMQTT: liftcode = 1
I (18:02:39.906) aMQTT: Correl: 419033
I (18:02:39.907) aMQTT: SiteID/00004827E21839D4/Response/LiftAllStop appRespCode=0 419033
I (18:02:40.410) aMQTT: POST DELAY
I (18:02:40.528) aMQTT: SiteID/00004827E21839D4/Pump/1/Status status=7/state=8/type=2/hose=2/product=2/seqNum=7/money=114.18/volume=11.40
I (18:02:40.742) aMQTT: SiteID/00004827E21839D4/Pump/2/Status status=7/state=8/type=2/hose=1/product=1/seqNum=8/money=109.76/volume=10.97
E (18:02:40.914) mqtt_client: esp_mqtt_handle_transport_read_error: transport_read(): EOF
E (18:02:40.915) mqtt_client: esp_mqtt_handle_transport_read_error: transport_read() error: errno=128
E (18:02:40.916) aMQTT: MQTT_EVENT_ERROR
E (18:02:40.917) aMQTT: MQTT5 return code is 0
E (18:02:40.917) aMQTT: Last error reported from esp-tls: 0x8008
E (18:02:40.918) aMQTT: Last errno string (Success)
E (18:02:40.918) mqtt_client: mqtt_process_receive: mqtt_message_receive() returned -2
W (18:02:40.921) aMQTT: Broker disconnected
W (18:02:40.922) aMQTT: MQTT5 Broker reconnect
I (18:02:40.922) mqtt_client: Client force reconnect requested
I (18:02:40.923) aMQTT: Other event id:7
W (18:02:40.943) aMQTT: Broker connected
I (18:02:40.946) aMQTT: Resubscribe to our 4 Topics
I (18:02:40.953) aMQTT: Sent subscribe successful, Topic: SiteID/00004827E21839D4/Pump/+/Command/#  msg_id: 221
I (18:02:40.966) mqtt5_client: MQTT_MSG_TYPE_SUBACK return code is 1
I (18:02:40.968) aMQTT: MQTT_EVENT_SUBSCRIBED, msg_id=221  inFlightCounter: 1
I (18:02:40.976) mqtt5_client: MQTT_MSG_TYPE_SUBACK return code is 1
I (18:02:40.978) aMQTT: MQTT_EVENT_SUBSCRIBED, msg_id=222  inFlightCounter: 0
I (18:02:40.985) aMQTT: Sent subscribe successful, Topic: SiteID/00004827E21839D4/Pump/+/TransactionResponse  msg_id: 222
E (18:02:41.000) mqtt_client: esp_mqtt_handle_transport_read_error: transport_read(): EOF
E (18:02:41.001) mqtt_client: esp_mqtt_handle_transport_read_error: transport_read() error: errno=128
E (18:02:41.003) aMQTT: MQTT_EVENT_ERROR
E (18:02:41.003) aMQTT: MQTT5 return code is 0
E (18:02:41.004) aMQTT: Last error reported from esp-tls: 0x8008
E (18:02:41.004) aMQTT: Last errno string (Success)
E (18:02:41.005) mqtt_client: mqtt_process_receive: mqtt_message_receive() returned -2
W (18:02:41.009) aMQTT: Broker disconnected
I (18:02:41.010) aLED: connectionStatus: 1
W (18:02:41.010) aMQTT: MQTT5 Broker reconnect
I (18:02:41.011) mqtt_client: Client force reconnect requested
I (18:02:41.012) aMQTT: Other event id:7
W (18:02:41.034) aMQTT: Broker connected
I (18:02:41.034) aLED: connectionStatus: 0
I (18:02:41.057) mqtt5_client: MQTT_MSG_TYPE_SUBACK return code is 1
I (18:02:41.058) aMQTT: MQTT_EVENT_SUBSCRIBED, msg_id=223  inFlightCounter: 0
I (18:02:41.060) aMQTT: Sent subscribe successful, Topic: SiteID/00004827E21839D4/Command/#  msg_id: 223
I (18:02:41.066) aMQTT: Sent subscribe successful, Topic: SiteID/00004827E21839D4/ConsoleCmd  msg_id: 224
I (18:02:41.073) mqtt5_client: MQTT_MSG_TYPE_SUBACK return code is 1
I (18:02:41.075) aMQTT: MQTT_EVENT_SUBSCRIBED, msg_id=224  inFlightCounter: 1
I (18:02:41.082) aMQTT: SiteID/00004827E21839D4/Pump/1/Flow status=7/money=120.64/volume=12.04
I (18:02:41.280) aMQTT: SiteID/00004827E21839D4/Pump/1/Status status=7/state=8/type=2/hose=2/product=2/seqNum=7/money=122.80/volume=12.26
E (18:02:42.118) mqtt_client: esp_mqtt_handle_transport_read_error: transport_read(): EOF
E (18:02:42.119) mqtt_client: esp_mqtt_handle_transport_read_error: transport_read() error: errno=128
E (18:02:42.120) aMQTT: MQTT_EVENT_ERROR
E (18:02:42.121) aMQTT: MQTT5 return code is 0
E (18:02:42.121) aMQTT: Last error reported from esp-tls: 0x8008
E (18:02:42.122) aMQTT: Last errno string (Success)
E (18:02:42.123) mqtt_client: mqtt_process_receive: mqtt_message_receive() returned -2
W (18:02:42.127) aMQTT: Broker disconnected
W (18:02:42.128) aMQTT: MQTT5 Broker reconnect
I (18:02:42.129) mqtt_client: Client force reconnect requested
I (18:02:42.131) aMQTT: Other event id:7
W (18:02:42.151) aMQTT: Broker connected
I (18:02:42.156) aMQTT: SiteID/00004827E21839D4/Pump/2/Flow status=7/money=124.82/volume=12.47
I (18:02:42.265) aMQTT: Resubscribe to our 4 Topics
I (18:02:42.277) mqtt5_client: MQTT_MSG_TYPE_SUBACK return code is 1
I (18:02:42.279) aMQTT: MQTT_EVENT_SUBSCRIBED, msg_id=228  inFlightCounter: 0
I (18:02:42.280) aMQTT: Sent subscribe successful, Topic: SiteID/00004827E21839D4/Pump/+/Command/#  msg_id: 228

More Information.

I want to know what these error message mean and how I can prevent them from occurring.
I have tried increasing the MQTT buffer sizes as follows but this does not help

        mqtt5_cfg.outbox.limit = 10 * 1024;
        mqtt5_cfg.buffer.size = 5 * 1024; // default MQTT_BUFFER_SIZE_BYTE = 1024
        mqtt5_cfg.buffer.out_size = 5 * 1024; // default MQTT_BUFFER_SIZE_BYTE = 1024
client = esp_mqtt_client_init(&mqtt5_cfg);

[michaelsimp]

I found looking at my Broker logs and analyzing with Wireshark that occasionally the publish_Response_property.response_topic was not loaded correctly causing a mis-formed publish message. This caused the broker to disconnect and my client to reconnect.
My bug, fixed now.