[Bug]: mqttjs:client _checkPing :: checking ping runs twice sometimes causes reconnect loop

[jayfry1077]

MQTTjs Version

5.3.4

Broker

AWS iot core

Environment

NodeJS

Description

Using "mqtt": "5.3.4"

I'm having an issue where my client is running mqttjs:client _checkPing :: checking ping... 3ms apart. The first one seems to be successful, and the second one fails

I think the failure is because my broker (awsIot core) only allows 1 ping request every 30 seconds ( I could be wrong amazons working is a little weird "Your device can ping as often as every 30 seconds at no charge for MQTT PINGREQ or PINGRESP messages" I don't know if this means I get charged for extras or if they're just not allowed.)

For over 12 hours the client was doing fine no issues

My keep alive is 1000 seconds.

Successful Ping 1000 seconds before issue
2024-04-18T10:16:24.193Z mqttjs:client _checkPing :: checking ping...
2024-04-18T10:16:24.193Z mqttjs:client _checkPing :: ping response received. Clearing flag and sending pingreq
2024-04-18T10:16:24.193Z mqttjs:client _sendPacket :: (redacted) :: start
2024-04-18T10:16:24.194Z mqttjs:client _writePacket :: packet: { cmd: 'pingreq' }
2024-04-18T10:16:24.194Z mqttjs:client _writePacket :: emitting packetsend
2024-04-18T10:16:24.194Z mqttjs:client _writePacket :: writing to stream
2024-04-18T10:16:24.194Z mqttjs:client _writePacket :: writeToStream result true
2024-04-18T10:16:24.194Z mqttjs:client _writePacket :: invoking cb
2024-04-18T10:16:24.195Z mqttjs:client noop :: undefined
2024-04-18T10:16:24.286Z mqttjs:client writable stream :: parsing buffer
2024-04-18T10:16:24.286Z mqttjs:client parser :: on packet push to packets array.
2024-04-18T10:16:24.286Z mqttjs:client work :: getting next packet in queue
2024-04-18T10:16:24.286Z mqttjs:client work :: packet pulled from queue
2024-04-18T10:16:24.286Z mqttjs:client _handlePacket :: emitting packetreceive

Then this occurs

2024-04-18T10:33:04.194Z mqttjs:client _checkPing :: checking ping...
2024-04-18T10:33:04.194Z mqttjs:client _checkPing :: ping response received. Clearing flag and sending pingreq
2024-04-18T10:33:04.194Z mqttjs:client _sendPacket :: (redacted) :: start
2024-04-18T10:33:04.195Z mqttjs:client _writePacket :: packet: { cmd: 'pingreq' }
2024-04-18T10:33:04.195Z mqttjs:client _writePacket :: emitting packetsend
2024-04-18T10:33:04.195Z mqttjs:client _writePacket :: writing to stream
2024-04-18T10:33:04.195Z mqttjs:client _writePacket :: writeToStream result true
2024-04-18T10:33:04.195Z mqttjs:client _writePacket :: invoking cb
2024-04-18T10:33:04.195Z mqttjs:client noop :: undefined
2024-04-18T10:33:04.197Z mqttjs:client _checkPing :: checking ping...
2024-04-18T10:33:04.197Z mqttjs:client _checkPing :: calling _cleanUp with force true
2024-04-18T10:33:04.197Z mqttjs:client _cleanUp :: forced? true
2024-04-18T10:33:04.197Z mqttjs:client _cleanUp :: (redacted) :: destroying stream
2024-04-18T10:33:04.197Z mqttjs:client _cleanUp :: client not disconnecting. Clearing and resetting reconnect.
2024-04-18T10:33:04.197Z mqttjs:client _clearReconnect : clearing reconnect timer
2024-04-18T10:33:04.197Z mqttjs:client _setupReconnect :: emit offline state
2024-04-18T10:33:04.197Z mqttjs:client _setupReconnect :: set reconnecting to true
2024-04-18T10:33:04.198Z mqttjs:client _setupReconnect :: setting reconnectTimer for 1000 ms
2024-04-18T10:33:04.198Z mqttjs:client _cleanUp :: clearing pingTimer
2024-04-18T10:33:04.198Z mqttjs:client (redacted)stream :: on close
2024-04-18T10:33:04.198Z mqttjs:client _flushVolatile :: deleting volatile messages from the queue and setting their callbacks as error function
2024-04-18T10:33:04.198Z mqttjs:client stream: emit close to MqttClient
2024-04-18T10:33:04.198Z mqttjs:client close :: connected set to false
2024-04-18T10:33:04.198Z mqttjs:client close :: clearing connackTimer
2024-04-18T10:33:04.199Z mqttjs:client close :: clearing ping timer
2024-04-18T10:33:04.199Z mqttjs:client close :: calling _setupReconnect
2024-04-18T10:33:04.199Z mqttjs:client _setupReconnect :: doing nothing...
2024-04-18T10:33:04.200Z | INFO | [] | [clients/iot/awsIoT.js:185] | Connection closed
2024-04-18T10:33:05.199Z mqttjs:client reconnectTimer :: reconnect triggered!
2024-04-18T10:33:05.199Z mqttjs:client _reconnect: emitting reconnect to client
2024-04-18T10:33:05.201Z | INFO | [] | [clients/iot/awsIoT.js:175] | Reconnecting to AWS IoT broker
2024-04-18T10:33:05.203Z mqttjs:client _reconnect: calling connect
2024-04-18T10:33:05.204Z mqttjs:client connect :: calling method to clear reconnect
2024-04-18T10:33:05.204Z mqttjs:client _clearReconnect : clearing reconnect timer
2024-04-18T10:33:05.204Z mqttjs:client connect :: using streamBuilder provided to client to create stream
2024-04-18T10:33:05.204Z mqttjs calling streambuilder for mqtts
2024-04-18T10:33:05.205Z mqttjs:tls port 8883 host redacted.iot.us-east-1.amazonaws.com rejectUnauthorized %b true
2024-04-18T10:33:05.213Z mqttjs:client connect :: pipe stream to writable stream
2024-04-18T10:33:05.213Z mqttjs:client connect: sending packet connect
2024-04-18T10:33:05.214Z mqttjs:client _writePacket :: packet: {
cmd: 'connect',
protocolId: 'MQTT',
protocolVersion: 5,
clean: true,
clientId: 'redacted',
keepalive: 1000,
username: undefined,
password: undefined,
properties: { maximumPacketSize: 149504 }
}

take special note of this

2024-04-18T10:33:04.194Z mqttjs:client _checkPing :: checking ping...
2024-04-18T10:33:04.197Z mqttjs:client _checkPing :: checking ping...

the two pings are going off 3ms apart.

I'm not sure if this means the client got garbage back and tried again, or if there is something else going on.

I noticed that when the issue occurred the first ping request did not show this

2024-04-18T10:16:24.286Z mqttjs:client writable stream :: parsing buffer
2024-04-18T10:16:24.286Z mqttjs:client parser :: on packet push to packets array.
2024-04-18T10:16:24.286Z mqttjs:client work :: getting next packet in queue
2024-04-18T10:16:24.286Z mqttjs:client work :: packet pulled from queue
2024-04-18T10:16:24.286Z mqttjs:client _handlePacket :: emitting packetreceive

where as other successful pingreq do

I'm trying to understand why after a network connection for whatever reason, MQTT just starts a reconnect loop of the pattern above that never ends.

It's almost like its had 2 reconnects going, first ones fine but second one fails (due possible to aws broker rejecting pings that are too fast) and then it triggers the whole reconnect process again.

I also noticed that after a reconnect it will pass the next ping check. Then it will fail the next one and reconnect again

always in that pattern

I checked the client and it doesn't have a connection. Is able to see my messages.

Minimal Reproduction

Happens randomly after a connection issue

Debug logs

In the Main post

[jayfry1077]

Just gonna switch to use aws sdk instead

[robertsLando]

Keep this open please as it seems a bug

[robertsLando]

@jayfry1077 If you hava a chance to give a try to latest version 5.5.3 and give me a feedback it would be more then welcome 🙏🏼

I also saw that your version was the one right before a fix in keepalive connect loop so it may be that even 5.5.2 could be working for you

[jayfry1077]

@robertsLando

sure. I have another lab with the same issue so I'll see if I can update that one and see if it resolves the issue.

Could you share a link to any issues that detail the keep alive connect loop issue. I'd love to see is it matches what I'm seeing

[robertsLando]

#1778

[jayfry1077]

I haven't seen the issue come back. It didn't always happen, so i'll let you know if i see it again.

Thanks for the help!

[robertsLando]

Thanks to you for the feedback 🙏🏻