[ESP32 mqtt-client] Print No PING_RESP, disconnected

EricKiao
Posts: 2
Joined: Fri Aug 18, 2023 1:52 am

[ESP32 mqtt-client] Print No PING_RESP, disconnected

Postby EricKiao » Fri Aug 18, 2023 2:40 am

Hi everyone

My mqtt-client will always issue a ping request but fail to receive a ping response,
resulting in repeated disconnection of the device.
Is there any solution to this problem?
The information captured by ESP-IDF is as follows:

D (106239) transport_base: poll_read: select - Timeout before any socket was ready!
D (106239) transport_base: poll_read: select - Timeout before any socket was ready!
D (106239) mqtt_client: esp_mqtt_handle_transport_read_error: transport_read(): call timed out before data was ready!
D (106249) mqtt_client: Sent PING successful
D (106259) mqtt_client: mqtt_message_receive: first byte: 0xd0
D (106259) mqtt_client: mqtt_message_receive: read "remaining length" byte: 0x0
D (106269) mqtt_client: mqtt_message_receive: total message length: 2 (already read: 2)
D (106279) mqtt_client: mqtt_message_receive: transport_read():2 2
D (106279) mqtt_client: msg_type=13, msg_id=0
D (106289) mqtt_client: MQTT_MSG_TYPE_PINGRESP
D (107299) transport_base: poll_read: select - Timeout before any socket was ready!
D (107299) transport_base: poll_read: select - Timeout before any socket was ready!
D (107299) mqtt_client: esp_mqtt_handle_transport_read_error: transport_read(): call timed out before data was ready!
D (108319) transport_base: poll_read: select - Timeout before any socket was ready!
D (108319) transport_base: poll_read: select - Timeout before any socket was ready!
D (108319) mqtt_client: esp_mqtt_handle_transport_read_error: transport_read(): call timed out before data was ready!
D (108329) mqtt_client: Sent PING successful
D (109349) transport_base: poll_read: select - Timeout before any socket was ready!
D (109349) transport_base: poll_read: select - Timeout before any socket was ready!
D (109349) mqtt_client: esp_mqtt_handle_transport_read_error: transport_read(): call timed out before data was ready!
E (109359) mqtt_client: No PING_RESP, disconnected
D (109369) mqtt_client: Reconnect after 10000 ms
D (109369) event: running post MQTT_EVENTS:2 with handler 0x400d51d8 and context 0x3ffdcf6c on loop 0x3ffdce50
D (109379) myMQTT: Event dispatched from event loop base=MQTT_EVENTS, event_id=2
I (109389) myMQTT: MQTT_EVENT_DISCONNECTED 1
D (119389) mqtt_client: Reconnecting...
D (119389) event: running post MQTT_EVENTS:7 with handler 0x400d51d8 and context 0x3ffdcf6c on loop 0x3ffdce50
D (119389) myMQTT: Event dispatched from event loop base=MQTT_EVENTS, event_id=7
I (119399) myMQTT: MQTT_EVENT_BEFORE_CONNECT
D (119399) esp-tls: host:192.168.31.26: strlen 13
D (119409) esp-tls: [sock=51] Resolved IPv4 address: 192.168.31.26
D (119409) esp-tls: [sock=51] Connecting to server. HOST: 192.168.31.26, Port: 1883
D (119429) mqtt_client: Transport connected to mqtt://192.168.31.26:1883
D (119429) mqtt_client: Sending MQTT CONNECT message, type: 1, id: 0000
D (119499) mqtt_client: mqtt_message_receive: first byte: 0x20
D (119509) mqtt_client: mqtt_message_receive: read "remaining length" byte: 0x2
D (119509) mqtt_client: mqtt_message_receive: total message length: 4 (already read: 2)
D (119519) mqtt_client: mqtt_message_receive: read_len=2
D (119519) mqtt_client: mqtt_message_receive: transport_read():4 4
D (119529) mqtt_client: Connected
D (119529) event: running post MQTT_EVENTS:1 with handler 0x400d51d8 and context 0x3ffdcf6c on loop 0x3ffdce50
D (119539) myMQTT: Event dispatched from event loop base=MQTT_EVENTS, event_id=1
I (119549) myMQTT: MQTT_EVENT_CONNECTED
D (119549) mqtt_client: mqtt_enqueue id: 31646, type=8 successful
D (119559) outbox: ENQUEUE msgid=31646, msg_type=8, len=17, size=17
D (119569) mqtt_client: Sent subscribe topic=Y5mJL/PING, id: 31646, type=8 successful
D (119599) mqtt_client: mqtt_message_receive: first byte: 0x90
D (119599) mqtt_client: mqtt_message_receive: read "remaining length" byte: 0x3
D (119599) mqtt_client: mqtt_message_receive: total message length: 5 (already read: 2)
D (119609) mqtt_client: mqtt_message_receive: read_len=3
D (119609) mqtt_client: mqtt_message_receive: transport_read():5 5
D (119619) mqtt_client: msg_type=9, msg_id=31646
D (119619) mqtt_client: pending_id=31646, pending_msg_count = 1
D (119629) outbox: DELETED msgid=31646, msg_type=8, remain size=0
D (119639) mqtt_client: deliver_suback, message_length_read=5, message_length=5
D (119639) event: running post MQTT_EVENTS:3 with handler 0x400d51d8 and context 0x3ffdcf6c on loop 0x3ffdce50
D (119649) myMQTT: Event dispatched from event loop base=MQTT_EVENTS, event_id=3
I (119659) myMQTT: MQTT_EVENT_SUBSCRIBED, msg_id=31646
D (119669) mqtt_client: mqtt_enqueue id: 48336, type=3 successful
D (119669) outbox: ENQUEUE msgid=48336, msg_type=3, len=20, size=20
I (119679) MyAgri: mqtt_event_handler => dataRefresh
D (119689) mqtt_client: mqtt_enqueue id: 27541, type=3 successful
D (119689) outbox: ENQUEUE msgid=27541, msg_type=3, len=73, size=93
I (119699) MyAgri: wf8098 00000000,0.000,0,2,0,info,M207,2,1692253651,unsaved[58]
D (119699) mqtt_client: mqtt_message_receive: first byte: 0x40
D (119709) mqtt_client: mqtt_message_receive: read "remaining length" byte: 0x2
D (119719) mqtt_client: mqtt_message_receive: total message length: 4 (already read: 2)
D (119729) mqtt_client: mqtt_message_receive: read_len=2
D (119729) mqtt_client: mqtt_message_receive: transport_read():4 4
D (119739) mqtt_client: msg_type=4, msg_id=48336
D (119739) mqtt_client: pending_id=27541, pending_msg_count = 2
D (119749) outbox: DELETED msgid=48336, msg_type=3, remain size=73
D (119759) mqtt_client: received MQTT_MSG_TYPE_PUBACK, finish QoS1 publish
D (119759) event: running post MQTT_EVENTS:5 with handler 0x400d51d8 and context 0x3ffdcf6c on loop 0x3ffdce50
D (119769) myMQTT: Event dispatched from event loop base=MQTT_EVENTS, event_id=5
D (119779) mqtt_client: mqtt_message_receive: first byte: 0x40
D (119789) mqtt_client: mqtt_message_receive: read "remaining length" byte: 0x2
D (119789) mqtt_client: mqtt_message_receive: total message length: 4 (already read: 2)
D (119799) mqtt_client: mqtt_message_receive: read_len=2
D (119809) mqtt_client: mqtt_message_receive: transport_read():4 4
D (119809) mqtt_client: msg_type=4, msg_id=27541
D (119819) mqtt_client: pending_id=27541, pending_msg_count = 1
D (119819) outbox: DELETED msgid=27541, msg_type=3, remain size=0
D (119829) mqtt_client: received MQTT_MSG_TYPE_PUBACK, finish QoS1 publish
D (119839) event: running post MQTT_EVENTS:5 with handler 0x400d51d8 and context 0x3ffdcf6c on loop 0x3ffdce50
D (119849) myMQTT: Event dispatched from event loop base=MQTT_EVENTS, event_id=5
D (120869) transport_base: poll_read: select - Timeout before any socket was ready!
D (120869) transport_base: poll_read: select - Timeout before any socket was ready!
D (120869) mqtt_client: esp_mqtt_handle_transport_read_error: transport_read(): call timed out before data was ready!
D (121889) transport_base: poll_read: select - Timeout before any socket was ready!
D (121889) transport_base: poll_read: select - Timeout before any socket was ready!
D (121889) mqtt_client: esp_mqtt_handle_transport_read_error: transport_read(): call timed out before data was ready!
D (121899) mqtt_client: Sent PING successful
D (121969) mqtt_client: mqtt_enqueue id: 33971, type=3 successful
D (121969) outbox: ENQUEUE msgid=33971, msg_type=3, len=65, size=65
I (121969) MyAgri: wf8098 00000000,0.000,0,2,0,info,M207,2,1692253653[50]
D (121979) mqtt_client: mqtt_message_receive: first byte: 0xd0
D (121979) mqtt_client: mqtt_message_receive: read "remaining length" byte: 0x0
D (121989) mqtt_client: mqtt_message_receive: total message length: 2 (already read: 2)
D (121999) mqtt_client: mqtt_message_receive: transport_read():2 2
D (121999) mqtt_client: msg_type=13, msg_id=0
D (122009) mqtt_client: MQTT_MSG_TYPE_PINGRESP
D (122019) mqtt_client: mqtt_message_receive: first byte: 0x40
D (122019) mqtt_client: mqtt_message_receive: read "remaining length" byte: 0x2
D (122029) mqtt_client: mqtt_message_receive: total message length: 4 (already read: 2)
D (122039) mqtt_client: mqtt_message_receive: read_len=2
D (122039) mqtt_client: mqtt_message_receive: transport_read():4 4
D (122049) mqtt_client: msg_type=4, msg_id=33971
D (122049) mqtt_client: pending_id=33971, pending_msg_count = 1
D (122059) outbox: DELETED msgid=33971, msg_type=3, remain size=0
D (122059) mqtt_client: received MQTT_MSG_TYPE_PUBACK, finish QoS1 publish
D (122069) event: running post MQTT_EVENTS:5 with handler 0x400d51d8 and context 0x3ffdcf6c on loop 0x3ffdce50
D (122079) myMQTT: Event dispatched from event loop base=MQTT_EVENTS, event_id=5
D (123099) transport_base: poll_read: select - Timeout before any socket was ready!
D (123099) transport_base: poll_read: select - Timeout before any socket was ready!
D (123099) mqtt_client: esp_mqtt_handle_transport_read_error: transport_read(): call timed out before data was ready!


The captured network packets are as follows:

Image

My development environment is as follows:

I (29) boot: ESP-IDF 5.0.2 2nd stage bootloader
I (29) boot: compile time 13:56:48
I (29) boot: chip revision: v3.0
I (32) boot.esp32: SPI Speed : 40MHz
I (37) boot.esp32: SPI Mode : DIO
I (41) boot.esp32: SPI Flash Size : 8MB
I (46) boot: Enabling RNG early entropy source...
I (516) boot: Loaded app from partition at offset 0x10000
I (516) boot: Disabling RNG early entropy source...
I (528) cpu_start: Pro cpu up.
I (528) cpu_start: Starting app cpu, entry point is 0x40081be0
I (0) cpu_start: App cpu up.
D (536) clk: RTC_SLOW_CLK calibration value: 3321498
I (549) cpu_start: Pro cpu start user code
I (549) cpu_start: cpu freq: 160000000 Hz
I (550) cpu_start: Application information:
I (554) cpu_start: Project name: controller
I (559) cpu_start: App version: 18b9876-dirty
I (565) cpu_start: Compile time: Aug 17 2023 13:56:24
I (571) cpu_start: ELF file SHA256: 81f5676df903c66e...
I (577) cpu_start: ESP-IDF: 5.0.2
I (582) cpu_start: Min chip rev: v0.0
I (586) cpu_start: Max chip rev: v3.99
I (591) cpu_start: Chip rev: v3.0
Attachments
wf8098.pcb.zip
captured network packets
(16.93 KiB) Downloaded 285 times

MicroController
Posts: 1708
Joined: Mon Oct 17, 2022 7:38 pm
Location: Europe, Germany

Re: [ESP32 mqtt-client] Print No PING_RESP, disconnected

Postby MicroController » Fri Aug 18, 2023 8:53 am

Your keepalive interval (2 seconds?) is unusually short.
This interval not only defines how often a ping will be sent, but also how long the client will wait for a response to the ping.
Try increasing the keepalive to something like 15 or 30 seconds and see if that helps.

EricKiao
Posts: 2
Joined: Fri Aug 18, 2023 1:52 am

Re: [ESP32 mqtt-client] Print No PING_RESP, disconnected

Postby EricKiao » Mon Aug 21, 2023 1:23 am

I have tested it for 13 to 30 seconds, and the same problem will occur. The purpose of using 2 seconds is to speed up the frequency of occurrence and to clarify the cause of the occurrence

Who is online

Users browsing this forum: Majestic-12 [Bot] and 88 guests