[Bug]: Client times out every 96 seconds

[lptr]

MQTTjs Version

5.5.5

Broker

Mosquitto 2.0.18

Environment

NodeJS

Description

My NestJS application works fine using MQTT.js 5.5.4, but when upgrading to 5.5.5, my connection keeps timing out.

Minimal Reproduction

I'm initializing the connection like this:

async function bootstrap() {
  const logger = new Logger('main');

  const app = await NestFactory.create<NestExpressApplication>(AppModule, {
    logger: ['fatal', 'error', 'warn', 'log', 'debug'],
  });

  const mqttUrl = app.get(ConfigService).get('MQTT_URL', 'mqtt://localhost:1883');
  logger.log(`Connecting to MQTT broker at ${mqttUrl}`);
  app.connectMicroservice<MicroserviceOptions>({
    transport: Transport.MQTT,
    options: { url: mqttUrl },
  });
  await app.startAllMicroservices();

  await app.listen(3000);
}
bootstrap();

There is nothing fancy I do here. The NestJS application keeps logging that it has restarted microservices every 96 seconds.

Debug logs

mosquitto-1  | 1715423490: New connection from 10.180.1.202:44188 on port 1883.
mosquitto-1  | 1715423490: New client connected from 10.180.1.202:44188 as mqttjs_617bdbe8 (p2, c1, k60).
mosquitto-1  | 1715423492: New connection from 10.180.1.202:44202 on port 1883.
mosquitto-1  | 1715423492: New client connected from 10.180.1.202:44202 as mqttjs_60b2f9b7 (p2, c1, k60).
mosquitto-1  | 1715423506: New connection from 127.0.0.1:53642 on port 1883.
mosquitto-1  | 1715423506: New client connected from 127.0.0.1:53642 as auto-FE0B77F7-6E76-B46C-635B-B0A5F2C34FBD (p2, c1, k60).
mosquitto-1  | 1715423506: Client auto-FE0B77F7-6E76-B46C-635B-B0A5F2C34FBD disconnected.
mosquitto-1  | 1715423536: New connection from 127.0.0.1:33478 on port 1883.
mosquitto-1  | 1715423536: New client connected from 127.0.0.1:33478 as auto-C2035B25-9FC2-7088-6DC1-C3B4995410A7 (p2, c1, k60).
mosquitto-1  | 1715423536: Client auto-C2035B25-9FC2-7088-6DC1-C3B4995410A7 disconnected.
mosquitto-1  | 1715423567: New connection from 127.0.0.1:38178 on port 1883.
mosquitto-1  | 1715423567: New client connected from 127.0.0.1:38178 as auto-5DB0DCCF-5B57-0577-0542-963CA2D6A0F1 (p2, c1, k60).
mosquitto-1  | 1715423567: Client auto-5DB0DCCF-5B57-0577-0542-963CA2D6A0F1 disconnected.
mosquitto-1  | 1715423583: Client mqttjs_617bdbe8 has exceeded timeout, disconnecting.
mosquitto-1  | 1715423587: New connection from 10.180.1.202:44287 on port 1883.
mosquitto-1  | 1715423587: New client connected from 10.180.1.202:44287 as mqttjs_617bdbe8 (p2, c1, k60).
mosquitto-1  | 1715423597: New connection from 127.0.0.1:53002 on port 1883.
mosquitto-1  | 1715423597: New client connected from 127.0.0.1:53002 as auto-6816911E-2532-1858-621A-08EA78769C57 (p2, c1, k60).
mosquitto-1  | 1715423597: Client auto-6816911E-2532-1858-621A-08EA78769C57 disconnected.
mosquitto-1  | 1715423627: New connection from 127.0.0.1:48890 on port 1883.
mosquitto-1  | 1715423627: New client connected from 127.0.0.1:48890 as auto-E7D347CF-6216-3948-C8D8-38E16D41B524 (p2, c1, k60).
mosquitto-1  | 1715423627: Client auto-E7D347CF-6216-3948-C8D8-38E16D41B524 disconnected.
mosquitto-1  | 1715423657: New connection from 127.0.0.1:51206 on port 1883.
mosquitto-1  | 1715423657: New client connected from 127.0.0.1:51206 as auto-4E212B57-53B7-FD6F-7FEE-01E0BB937C42 (p2, c1, k60).
mosquitto-1  | 1715423657: Client auto-4E212B57-53B7-FD6F-7FEE-01E0BB937C42 disconnected.
mosquitto-1  | 1715423679: Client mqttjs_617bdbe8 has exceeded timeout, disconnecting.
mosquitto-1  | 1715423683: New connection from 10.180.1.202:44465 on port 1883.
mosquitto-1  | 1715423683: New client connected from 10.180.1.202:44465 as mqttjs_617bdbe8 (p2, c1, k60).
mosquitto-1  | 1715423687: New connection from 127.0.0.1:49510 on port 1883.
mosquitto-1  | 1715423687: New client connected from 127.0.0.1:49510 as auto-8FA15F68-DCA0-1B05-50D7-207B0A57578C (p2, c1, k60).
mosquitto-1  | 1715423687: Client auto-8FA15F68-DCA0-1B05-50D7-207B0A57578C disconnected.
mosquitto-1  | 1715423718: New connection from 127.0.0.1:33114 on port 1883.
mosquitto-1  | 1715423718: New client connected from 127.0.0.1:33114 as auto-B7659D45-6F73-E0FC-F234-009037976EAD (p2, c1, k60).
mosquitto-1  | 1715423718: Client auto-B7659D45-6F73-E0FC-F234-009037976EAD disconnected.

It's the Client mqttjs_XXXXXXXX has exceeded timeout, disconnecting. that signals the problem.

[robertsLando]

Got mqttjs logs too?

[makoto-tsudo]

I have same problem.
It seems a client is connection timeout when received message at short interval than keepalive.

mosquitto-bug-client.log
mosquitto-bug-server.log

my client code as below and i executed command mosquitto_pub -t "DAT/debugger/foo" -m bar intervaly.

import mqtt from 'mqtt'

console.log(`Env:DEBUG = ${process.env.DEBUG}`)
const client = mqtt.connect('ws://localhost:8080', {
    keepalive: 30,
    will: {
        topic: "DAT/debugger/app",
        payload: Buffer.from("0"),
        qos: 0,
        retain: true,
    }
})
client.on('error', (err) => {
    // console.error("%O", err)
})
client.on('connect', () => {
    // console.log('connect')
    client.subscribe('DAT/debugger/#')
})
client.on('message', (topic, payload, packet) => {
    // console.log('%O:%O(%O)', topic, payload, packet)
})
client.on('close', () => {
    // console.log('close')
})

[makoto-tsudo]

v5.5.4 seems reschedule a pingTimer at send a control packet.
but v5.5.5 seems reschedule at receive a control packet.
Sorry if I misunderstood.

I think client like a mqtt.js need send a pingreq when have not sent control packet in keepalive interval.

[robertsLando]

In my last PR I have fixed an issue related to keepalive: #1855

Problem is that in previous implementation keepalive was shifetd on every packet sent and this is a problem as not only the pingreq packet is shifted but also the check. This means that if you have a client with a broken connection that keeps doing publish the connection is never closed as the keepalive never triggers by being always shifted...

I would need to see mqttjs logs not broker logs in order to understand what's going on here

[makoto-tsudo]

Here is mqttjs logs. I glad if it helps.
mosquitto-bug-client.log

I'm sorry for giving it a confusing log file name.

[robertsLando]

From your logs it seems that the broker is closing the stream:

mqttjs:client _reschedulePing :: rescheduling ping +0ms
  mqttjs:client _handlePacket :: emitting packetreceive +0ms
  mqttjs:client handlePublish: packet Packet { cmd: 'publish', retain: false, qos: 0, dup: false, length: 21, topic: 'DAT/debugger/foo', payload: <Buffer 62 61 72> } +0ms
  mqttjs:client handlePublish: qos 0 +0ms
  mqttjs:client (mqttjs_50c13719)stream :: on close +2s
  mqttjs:client _flushVolatile :: deleting volatile messages from the queue and setting their callbacks as error function +1ms  mqttjs:client stream: emit close to MqttClient +0ms
  mqttjs:client close :: connected set to `false` +0ms
  mqttjs:client close :: clearing connackTimer +1ms
  mqttjs:client _destroyPingTimer :: destroying ping timer +0ms
  mqttjs:client close :: calling _setupReconnect +0ms
  mqttjs:client _setupReconnect :: emit `offline` state +1ms
  mqttjs:client _setupReconnect :: set `reconnecting` to `true` +0ms

What broker are you using? Could it be that your broker is not respecting specs and it expects a pingreq even if you are actually sending other control packets?

[makoto-tsudo]

I use 'mosquitto' provided by the official Docker image. It's tagged as '2.0.18'.
eclipse-mosquitto

[makoto-tsudo]

In my understanding, the client is not sending packets until it's disconnected after send packets of subscribe.
It's just receiving published messages. Does mqttjs not reply with an ack packet because the QoS is 0.

I think mqttjs should send a pingreq in this scenario. However, the PingTimer is rescheduled every time a published message is received, preventing it from sending a pingreq.

[robertsLando]

@makoto-tsudo Thanks for your feedbacks, thanks to them I have been able to find the reason of the unwanted disconnections. The problem was that to fix the other issue related to keepalive where the ping was shifted on every message written to socket (cause the keepalive to not close the connection) now we was shifting on every message received from broker but in case of a client that only receives messages this causes the keepalive management to never send a pingreq thinking that we are already communicatig with the broker so we don't send the pingreq and the broker closes the connection after keepalive*1.5 seconds as per specs

I have a WIP to do lot of improvements to the keepalive management but you need to wait for that #1865

In the meanwhile I will create a new patch release to fix the issue

Fixed by #1866

[makoto-tsudo]

@robertsLando Thanks for the quick response.
I appreciate your contribution.