Mqttnet: Client xxxx has exceeded timeout, disconnecting

[snice1981]

I'm using ManagedClient with Mosquitto, it works well but after a certain time, the client get disconnected due to missing ping request. I have different apps (Xamarin Forms app) that connects to mosquitto. One seems to work well (Screenxxx) but not the other one (CashDesk)

As you can see in the following log, there is no pingreq from cashdesk

Here is a sample of mosquitto log file:

Mon Dec 16 08:08:43 2019: New connection from 192.168.1.60 on port 1883.
Mon Dec 16 08:08:43 2019: New client connected from 192.168.1.60 as CashDesk1166313646 (p2, c1, k15).
Mon Dec 16 08:08:43 2019: No will message specified.
Mon Dec 16 08:08:43 2019: Sending CONNACK to CashDesk1166313646 (0, 0)
Mon Dec 16 08:08:51 2019: Received PINGREQ from Screen336176334
Mon Dec 16 08:08:51 2019: Sending PINGRESP to Screen336176334
Mon Dec 16 08:09:02 2019: Received PINGREQ from Screen336176334
Mon Dec 16 08:09:02 2019: Sending PINGRESP to Screen336176334
Mon Dec 16 08:09:05 2019: Client CashDesk1166313646 has exceeded timeout, disconnecting.
Mon Dec 16 08:09:13 2019: Received PINGREQ from Screen336176334
Mon Dec 16 08:09:13 2019: Sending PINGRESP to Screen336176334
Mon Dec 16 08:09:25 2019: Received PINGREQ from Screen336176334
Mon Dec 16 08:09:25 2019: Sending PINGRESP to Screen336176334
Mon Dec 16 08:09:34 2019: New connection from 192.168.1.60 on port 1883.
Mon Dec 16 08:09:34 2019: New client connected from 192.168.1.60 as CashDesk1166313646 (p2, c1, k15).
Mon Dec 16 08:09:34 2019: No will message specified.
Mon Dec 16 08:09:34 2019: Sending CONNACK to CashDesk1166313646 (0, 0)
Mon Dec 16 08:09:36 2019: Received PINGREQ from Screen336176334
Mon Dec 16 08:09:36 2019: Sending PINGRESP to Screen336176334
Mon Dec 16 08:09:47 2019: Received PINGREQ from Screen336176334
Mon Dec 16 08:09:47 2019: Sending PINGRESP to Screen336176334
Mon Dec 16 08:09:57 2019: Client CashDesk1166313646 has exceeded timeout, disconnecting.
Mon Dec 16 08:09:59 2019: Received PINGREQ from Screen336176334
Mon Dec 16 08:09:59 2019: Sending PINGRESP to Screen336176334
Mon Dec 16 08:10:10 2019: Received PINGREQ from Screen336176334
Mon Dec 16 08:10:10 2019: Sending PINGRESP to Screen336176334
Mon Dec 16 08:10:21 2019: Received PINGREQ from Screen336176334
Mon Dec 16 08:10:21 2019: Sending PINGRESP to Screen336176334
Mon Dec 16 08:10:33 2019: Received PINGREQ from Screen336176334
Mon Dec 16 08:10:33 2019: Sending PINGRESP to Screen336176334
Mon Dec 16 08:10:44 2019: Received PINGREQ from Screen336176334
Mon Dec 16 08:10:44 2019: Sending PINGRESP to Screen336176334
Mon Dec 16 08:10:55 2019: Received PINGREQ from Screen336176334
Mon Dec 16 08:10:55 2019: Sending PINGRESP to Screen336176334
Mon Dec 16 08:10:58 2019: New connection from 192.168.1.60 on port 1883.
Mon Dec 16 08:10:58 2019: New client connected from 192.168.1.60 as CashDesk1166313646 (p2, c1, k15).
Mon Dec 16 08:10:58 2019: No will message specified.
Mon Dec 16 08:10:58 2019: Sending CONNACK to CashDesk1166313646 (0, 0)
Mon Dec 16 08:11:06 2019: Received PINGREQ from Screen336176334
Mon Dec 16 08:11:06 2019: Sending PINGRESP to Screen336176334

It disconnect at least 100 times a day. And it's only when the app is not used (no publish to mosquitto)

[SeppPenner]

The managed client doesn't have the WithKeepAlivePeriod(TimeSpan value) method like the normal client, I guess?

About hundred times a day means every 15 minutes or so? Personally, I would just reconnect the client if it's inactive for a longer time...

[snice1981]

Hi @SeppPenner

It deconnect more often when the app is not used (between 20h and 8h AM). As you can see in the sample log, it deconnected 52 seconds after reconnection.

I think there is a keepalive as per what I see in the log file: New client connected from 192.168.1.60 as CashDesk1166313646 (p2, c1, k15) K15, means Keep alive 15s if'm not wrong.

[SeppPenner]

It deconnect more often when the app is not used (between 20h and 8h AM). As you can see in the sample log, it deconnected 52 seconds after reconnection.

Sure, I understand that, but do you really think this is an issue?

I think there is a keepalive as per what I see in the log file: New client connected from 192.168.1.60 as CashDesk1166313646 (p2, c1, k15) K15, means Keep alive 15s if'm not wrong.

I guess, you're right. I don't know if it's possible to set this interval to a higher number @chkr1011?

[chriswue]

We just ran into the same issue and we're not using the ManagedClient just the plain MqttClient which should take care of it (the ManagedClient ctor requires an instance of IMqttClient anyway).
Seems like a bug in MqttClient but having a brief look at the code it seems like it should work.

MqttClient has options to set the KeepAlivePeriod which is 15sec by default and if KeepAliveSendInterval it is not specified it defaults to 75% of that.

[chriswue]

Actually I think I found the bug. The main keepalive loop is:

while (!cancellationToken.IsCancellationRequested)
{
    // Values described here: [MQTT-3.1.2-24].
    var keepAliveSendInterval = TimeSpan.FromSeconds(Options.KeepAlivePeriod.TotalSeconds * 0.75);
    if (Options.KeepAliveSendInterval.HasValue)
    {
        keepAliveSendInterval = Options.KeepAliveSendInterval.Value;
    }

    var waitTimeSend = keepAliveSendInterval - _sendTracker.Elapsed;
    var waitTimeReceive = keepAliveSendInterval - _receiveTracker.Elapsed;
    if (waitTimeSend <= TimeSpan.Zero || waitTimeReceive <= TimeSpan.Zero)
    {
        await SendAndReceiveAsync<MqttPingRespPacket>(new MqttPingReqPacket(), cancellationToken).ConfigureAwait(false);
    }

    await Task.Delay(keepAliveSendInterval, cancellationToken).ConfigureAwait(false);
}

Let's say period is 15sec and send interval is 11.25sec (default values).
If the task happens to check 10sec since the last send/receive then it will see that waitTimeSend/waitTimeReceive is greater than TimeSpan.Zero and it will not send out a ping and sleep for an entire interval which is another 11.25sec.
This means if no other send/receive activity happens within 5sec then the keepalive window on the server will expire and the client gets disconnected.

The fix would be to sleep Math.Min(waitTimeSend, waitTimeReceive) in the case where no ping has been sent - probably a little bit less than that to account for task scheduling overheads.

[bretternst]

We are seeing the same issue, frequent missed pings and disconnects on a simple client that only subscribes. Can confirm that the patch above from chriswue fixes the problem.

[snice1981]

Hi

any news about that problem? Not yet fixed in the latest version (even RC).