Error from MQTTAsync_cycle() when using SSL connection
gopaladhith opened this issue · 4 comments
Hello Team,
I am getting Error from MQTTAsync_cycle() error in paho trace and my client connection is getting terminated, and reconnection is attempted for the same.
Server is a private Mosquitto server running in private cloud.
paho.mqtt.c version - 1.3.9.
Keep alive interval is set to 10 seconds tried changing the keep alive interval to 30 secs but still the same issue.
MEDIUM tracing is enabled in paho and find below the trace that contains the error part,
Apr 16 09:16:08 xyzzyspoon-eved start.sh[7925]: 20240416 091608.741 m->c->connect_state = 0
Apr 16 09:16:08 xyzzyspoon-eved start.sh[7925]: 20240416 091608.741 4 abcd-device-mqtt-xyzzyspoon_1234 <- PINGRESP
Apr 16 09:16:17 xyzzyspoon-eved start.sh[7925]: 20240416 091608.741 sent 771 256 buflen 5
Apr 16 09:16:17 xyzzyspoon-eved start.sh[7925]: 20240416 091608.741 sent 771 257 buflen 1
Apr 16 09:16:17 xyzzyspoon-eved start.sh[7925]: 20240416 091608.741 5 iot-hub-xyzzyspoon_1713258656945 -> PINGREQ (0)
Apr 16 09:16:18 xyzzyspoon-eved start.sh[7925]: 20240416 091608.741 m->c->connect_state = 0
Apr 16 09:16:18 xyzzyspoon-eved start.sh[7925]: 20240416 091608.741 received 771 256 buflen 5
Apr 16 09:16:18 xyzzyspoon-eved start.sh[7925]: 20240416 091608.741 received 772 257 buflen 1
Apr 16 09:16:18 xyzzyspoon-eved start.sh[7925]: 20240416 091608.741 5 iot-hub-xyzzyspoon_1713258656945 <- PINGRESP
Apr 16 09:16:19 xyzzyspoon-eved start.sh[7925]: 20240416 091608.741 4 abcd-device-mqtt-xyzzyspoon_1234 -> PINGREQ (0)
Apr 16 09:16:19 xyzzyspoon-eved start.sh[7925]: 20240416 091608.741 m->c->connect_state = 0
Apr 16 09:16:19 xyzzyspoon-eved start.sh[7925]: 20240416 091608.741 4 abcd-device-mqtt-xyzzyspoon_1234 <- PINGRESP
Apr 16 09:16:28 xyzzyspoon-eved start.sh[7925]: 20240416 091608.741 sent 771 256 buflen 5
Apr 16 09:16:28 xyzzyspoon-eved start.sh[7925]: 20240416 091608.741 sent 771 257 buflen 1
Apr 16 09:16:28 xyzzyspoon-eved start.sh[7925]: 20240416 091608.741 5 iot-hub-xyzzyspoon_1713258656945 -> PINGREQ (0)
Apr 16 09:16:28 xyzzyspoon-eved systemd-journald[207]: Forwarding to syslog missed 30 messages.
Apr 16 09:16:29 xyzzyspoon-eved start.sh[7925]: 20240416 091608.741 m->c->connect_state = 0
Apr 16 09:16:29 xyzzyspoon-eved start.sh[7925]: 20240416 091608.741 received 771 256 buflen 5
Apr 16 09:16:29 xyzzyspoon-eved start.sh[7925]: 20240416 091608.741 received 772 257 buflen 1
Apr 16 09:16:29 xyzzyspoon-eved start.sh[7925]: 20240416 091629.605 5 iot-hub-xyzzyspoon_1713258656945 <- PINGRESP
Apr 16 09:16:30 xyzzyspoon-eved start.sh[7925]: 20240416 091629.605 4 abcd-device-mqtt-xyzzyspoon_1234 -> PINGREQ (0)
Apr 16 09:16:30 xyzzyspoon-eved start.sh[7925]: 20240416 091629.605 m->c->connect_state = 0
Apr 16 09:16:30 xyzzyspoon-eved start.sh[7925]: 20240416 091629.605 4 abcd-device-mqtt-xyzzyspoon_1234 <- PINGRESP
Apr 16 09:16:38 xyzzyspoon-eved start.sh[7925]: 20240416 091629.605 sent 771 256 buflen 5
Apr 16 09:16:38 xyzzyspoon-eved start.sh[7925]: 20240416 091629.605 sent 771 257 buflen 1
Apr 16 09:16:38 xyzzyspoon-eved start.sh[7925]: 20240416 091629.605 5 iot-hub-xyzzyspoon_1713258656945 -> PINGREQ (0)
Apr 16 09:16:41 xyzzyspoon-eved start.sh[7925]: 20240416 091629.605 4 abcd-device-mqtt-xyzzyspoon_1234 -> PINGREQ (0)
Apr 16 09:16:41 xyzzyspoon-eved start.sh[7925]: 20240416 091629.605 m->c->connect_state = 0
Apr 16 09:16:41 xyzzyspoon-eved start.sh[7925]: 20240416 091629.605 4 abcd-device-mqtt-xyzzyspoon_1234 <- PINGRESP
Apr 16 09:16:44 xyzzyspoon-eved start.sh[7925]: 20240416 091629.605 m->c->connect_state = 0
Apr 16 09:16:44 xyzzyspoon-eved start.sh[7925]: 20240416 091629.605 received 771 256 buflen 5
Apr 16 09:16:44 xyzzyspoon-eved start.sh[7925]: 20240416 091629.605 received 772 257 buflen 1
Apr 16 09:16:44 xyzzyspoon-eved start.sh[7925]: 20240416 091629.605 received 772 21 buflen 2
Apr 16 09:16:44 xyzzyspoon-eved start.sh[7925]: 20240416 091629.605 SSL alert read:warning:close notify
Apr 16 09:16:44 xyzzyspoon-eved start.sh[7925]: 20240416 091629.605 Error from MQTTAsync_cycle() - removing socket 5
Apr 16 09:16:44 xyzzyspoon-eved start.sh[7925]: 20240416 091629.605 sent 771 256 buflen 5
Apr 16 09:16:44 xyzzyspoon-eved start.sh[7925]: 20240416 091629.605 sent 771 257 buflen 1
Apr 16 09:16:44 xyzzyspoon-eved start.sh[7925]: 20240416 091629.605 5 iot-hub-xyzzyspoon_1713258656945 -> DISCONNECT (0)
Apr 16 09:16:44 xyzzyspoon-eved start.sh[7925]: 20240416 091629.605 sent 771 256 buflen 5
Apr 16 09:16:44 xyzzyspoon-eved start.sh[7925]: 20240416 091644.618 sent 771 257 buflen 1
Apr 16 09:16:44 xyzzyspoon-eved start.sh[7925]: 20240416 091644.618 sent 772 21 buflen 2
Apr 16 09:16:44 xyzzyspoon-eved start.sh[7925]: 20240416 091644.618 SSL alert write:warning:close notify
Apr 16 09:16:44 xyzzyspoon-eved start.sh[7925]: 20240416 091644.618 Removed socket 5
Apr 16 09:16:44 xyzzyspoon-eved start.sh[7925]: 20240416 091644.618 Calling connectionLost for client iot-hub-xyzzyspoon_1713258656945
Any help would be appreciated,
Thanks in Advance.
Presumably the Mosquitto server is closing the connection? Is there a console message from Mosquitto as to why it is doing it?
You should try the latest version, 1.3.13, to see if that helps. I'm pretty sure there have been some changes in that area.
@icraggs Thanks for your reply, chances of mosquitto server closing the connection is very slim. But anyway i will try to check the mosquitto logs and also will update the version to 1.3.13 and will feedback. I might take some time to feedback.
If the client were getting the keepalive processing wrong, then Mosquitto would close the connection, so I think the chances that Mosquitto is closing the connection as 50/50.
If you used MQTT 5.0, there is a possibility of getting a disconnect from Mosquitto with a reason code to say why, but in my experience so far, that isn't used very often, so unlikely to provide more information.
@icraggs with keepalive set to 30 seconds i am no longer facing connection error issue. So for now i will live with this and later will update dependencies to the latest versions and will observe and if i face any issues will open a new bug. For now will close this bug, thanks for your support :) .