Keepalive causes a reconnect loop when connection is lost

[frankforpresident]

When using the package I've noticed that the keepalive setting can cause a reconnect loop. Not sure if I misunderstand the setting or if it is bug.

How to reproduce:

1. Run a simple script with a keepalive lower than 60 seconds.
2. Interrupt your internet connection, For example, turning off the WiFi.
3. Observe that the package keeps on reconnecting for the set value of the keepalive.

Note: This only happens when the connection is lost.

output:

error Error: getaddrinfo ENOTFOUND test.mosquitto.org
    at GetAddrInfoReqWrap.onlookup [as oncomplete] (node:dns:108:26) {
  errno: -3008,
  code: 'ENOTFOUND',
  syscall: 'getaddrinfo',
  hostname: 'test.mosquitto.org'
}
close
reconnect
error Error: getaddrinfo ENOTFOUND test.mosquitto.org
    at GetAddrInfoReqWrap.onlookup [as oncomplete] (node:dns:108:26) {
  errno: -3008,
  code: 'ENOTFOUND',
  syscall: 'getaddrinfo',
  hostname: 'test.mosquitto.org'
}
close
reconnect
First hello
Hello at Mon, 22 Jan 2024 19:50:03 GMT
offline
close
reconnect
First hello
Hello at Mon, 22 Jan 2024 19:50:06 GMT
Hello at Mon, 22 Jan 2024 19:50:07 GMT
Hello at Mon, 22 Jan 2024 19:50:08 GMT
Hello at Mon, 22 Jan 2024 19:50:09 GMT
Hello at Mon, 22 Jan 2024 19:50:10 GMT
Hello at Mon, 22 Jan 2024 19:50:12 GMT
Hello at Mon, 22 Jan 2024 19:50:13 GMT
offline
close
reconnect
First hello
Hello at Mon, 22 Jan 2024 19:50:16 GMT
Hello at Mon, 22 Jan 2024 19:50:17 GMT
Hello at Mon, 22 Jan 2024 19:50:18 GMT
Hello at Mon, 22 Jan 2024 19:50:19 GMT
Hello at Mon, 22 Jan 2024 19:50:20 GMT
Hello at Mon, 22 Jan 2024 19:50:21 GMT
Hello at Mon, 22 Jan 2024 19:50:22 GMT
offline
close
reconnect
First hello
Hello at Mon, 22 Jan 2024 19:50:27 GMT
Hello at Mon, 22 Jan 2024 19:50:28 GMT
Hello at Mon, 22 Jan 2024 19:50:29 GMT
Hello at Mon, 22 Jan 2024 19:50:30 GMT
Hello at Mon, 22 Jan 2024 19:50:31 GMT
Hello at Mon, 22 Jan 2024 19:50:32 GMT
Hello at Mon, 22 Jan 2024 19:50:33 GMT
offline
close
reconnect

The code I've used:

https://codesandbox.io/p/devbox/mqtt-keepalive-bug-vr6fn5?file=%2Findex.js%3A7%2C29

Note: do not run this in the sandbox but locally otherwise the interrupt will not work. :)

[robertsLando]

Humm yeah it seems to be a bug, the next disconnections seems to don't have any reason. Could you try to set the log option to console.log ? so we will see more debug logs and maybe we understand what is causing the next disconnections.

If you are able to fix this please open a PR then 🙏🏼

[frankforpresident]

I've used log4js for the logging and prefixed mqtt logging with "mqtt".

output.log

[robertsLando]

[2024-01-23T09:19:12.190] [INFO] mqtt - _sendPacket :: (%s) ::  end
[2024-01-23T09:19:18.060] [INFO] mqtt - _checkPing :: checking ping...
[2024-01-23T09:19:18.061] [INFO] mqtt - _checkPing :: ping response received. Clearing flag and sending `pingreq`
[2024-01-23T09:19:18.061] [INFO] mqtt - _sendPacket :: (%s) ::  start
[2024-01-23T09:19:18.061] [INFO] mqtt - _writePacket :: packet: %O
[2024-01-23T09:19:18.061] [INFO] mqtt - _writePacket :: emitting `packetsend`
[2024-01-23T09:19:18.061] [INFO] mqtt - _writePacket :: writing to stream
[2024-01-23T09:19:18.061] [INFO] mqtt - _writePacket :: writeToStream result %s
[2024-01-23T09:19:18.061] [INFO] mqtt - _writePacket :: invoking cb
[2024-01-23T09:19:18.061] [INFO] mqtt - noop ::
[2024-01-23T09:19:28.062] [INFO] mqtt - _checkPing :: checking ping...
[2024-01-23T09:19:28.062] [INFO] mqtt - _checkPing :: calling _cleanUp with force true
[2024-01-23T09:19:28.063] [INFO] mqtt - _cleanUp :: forced? %s
[2024-01-23T09:19:28.063] [INFO] mqtt - _cleanUp :: (%s) :: destroying stream
[2024-01-23T09:19:28.063] [INFO] mqtt - _cleanUp :: client not disconnecting. Clearing and resetting reconnect.
[2024-01-23T09:19:28.063] [INFO] mqtt - _clearReconnect : clearing reconnect timer
[2024-01-23T09:19:28.063] [INFO] mqtt - _setupReconnect :: emit `offline` state
[2024-01-23T09:19:28.063] [WARN] default - offline
[2024-01-23T09:19:28.063] [INFO] mqtt - _setupReconnect :: set `reconnecting` to `true`
[2024-01-23T09:19:28.063] [INFO] mqtt - _setupReconnect :: setting reconnectTimer for %d ms
[2024-01-23T09:19:28.063] [INFO] mqtt - _cleanUp :: clearing pingTimer
[2024-01-23T09:19:28.064] [INFO] mqtt - _checkPing :: checking ping...
[2024-01-23T09:19:28.064] [INFO] mqtt - _checkPing :: calling _cleanUp with force true
[2024-01-23T09:19:28.064] [INFO] mqtt - _cleanUp :: forced? %s

The strange thing I notice here is that immediatly after calling clearing pingTimer that points to:

https://github.com/mqttjs/MQTT.js/blob/44a2f2f675c9211982244807dac78ed2e2956ccc/src/lib/client.ts

The ping timer is actually triggered (see next lines) and that causes a loop. Are you running it on nodejs or browser?

[robertsLando]

Found the issue, fix ready in #1779

[frankforpresident]

@robertsLando , Awesome work!

[someengineer-nordsec]

@robertsLando It seems this might have broken keepalive

In 5.3.5, keepalive is no longer being sent

Our server closes the connection after 60s, because there are no pings

Then new connection is opened

[robertsLando]

@olso-nordsec Could you tell me your environment? NodeJS? Browser? Could you send me a reproduction script and debug logs? Open a new issue with such info please

[someengineer-nordsec]

@robertsLando already opened a bug report here #1806

[robertsLando]

Sorry I was reading notifications one by one and I didn't see it