Testing MQTT resilience to disconnections

[vallettea]

I'm not sure mqttjs really handles correctly reconnection and the sending process of messages that could not be delivered. Here is some code to test this out:

"use strict";

var mqtt = require('mqtt');

var PRIVATE = require('./PRIVATE.json');

var client;
var simId = "0000"

function mqttConnect() {

    client = mqtt.connect('mqtt://' + PRIVATE.host + ':' + PRIVATE.port,
        {
            username: simId,
            password: PRIVATE.mqttToken,
            clientId: simId,
            keepalive: 0,
            clean: false,
            // Do not set to a value > 29 until this bug is fixed : https://github.com/mqttjs/MQTT.js/issues/346
            reconnectPeriod: 1000 * 29
        }
    );

    client.on('connect', function(){
        console.log('connected to the server. ID :', simId);
    });

    client.on('message', function(topic, message) {
        // message is a Buffer
        console.log("data received : " + message.toString());
    });
}

function send(topic, message, options) {
    if (client)
        client.publish(topic, message, options);
    else {
        debug("mqtt client not ready");
        setTimeout(function() {
            send(topic, message, options);
        }, 10000);
    }
}

setTimeout(function(){
   client.subscribe('test'); 
}, 3000)

//start sending
var i = 0;
setInterval(
    function(){
        send("test", i.toString(), {qos: 1})
        i += 1;
    },
60*1000)

mqttConnect();

I send a message each minute and from times to times I turn off the connectivity off and back again and check if i reconnect and receive all I sent. It works good on my laptop using the wifi.

However, it doesn't seem to reconnect when it work through the 3G with pppd.

[vallettea]

ok moving on. In fact my test on the laptop with the wifi was not complete because the client never noticed it was disconnected and it maybe tcp was sending back the messages. After adding the offline and reconnect message, I see that the messages are not sent back after reconnection:

data received : 9
data received : 10
data received : 11
offline:
offline:
reconnect:
offline:
offline:
reconnect:
connected to the server. ID : 0000

[vallettea]

BTW the offline is triggered with a non null heartbeat

[vallettea]

Setting clean to true or false doesn't change anything... even though the doc says: "clean: true, set to false to receive QoS 1 and 2 messages while offline"

[vallettea]

this code

"use strict";

var mqtt = require('mqtt');

var PRIVATE = require('./PRIVATE.json');

var simId = "0000"

var client = mqtt.connect('mqtt://' + PRIVATE.host + ':' + PRIVATE.port,
    {
        username: simId,
        password: PRIVATE.mqttToken,
        clientId: simId,
        keepalive: 0,
        clean: false,
        // Do not set to a value > 29 until this bug is fixed : https://github.com/mqttjs/MQTT.js/issues/346
        reconnectPeriod: 1000 * 29
    }
);

client.on('connect', function(){
    console.log('connected to the server. ID :', simId);
});

client.on('message', function(topic, message) {
    // message is a Buffer
    console.log("data received : " + message.toString());
});

client.on("error", function(error) {
    console.log("ERROR: ", error);
});

client.on('offline', function() {
    console.log("offline");
});

client.on('reconnect', function() {
    console.log("reconnect");
});

setTimeout(function(){
   client.subscribe('test'); 
}, 3000)

//start sending
var i = 0;
setInterval(
    function(){
        var message = i.toString();
        console.log("sending ", message)
        client.publish("test", message, {qos: 1}, function(){
            console.log("sent ", message)
        });
        i += 1;
    },
3000)

with a qos of 1 produces:

sending  0
sent  0
sending  1
sent  1
sending  2
sent  2
data received : 2
sending  3
sent  3
data received : 3
sending  4
sent  4
data received : 4
sending  5
sent  5
data received : 5
sending  6
sent  6
data received : 6
sending  7
sent  7
data received : 7
sending  8
sent  8
data received : 8
sending  9
sent  9
data received : 9
sending  10
sent  10
data received : 10
sending  11
sent  11
data received : 11
sending  12
sent  12
data received : 12
sending  13
sent  13
data received : 13
sending  14
sent  14
data received : 14
sending  15
sent  15
data received : 15
sending  16
sending  17
sending  18
sending  19
sending  20
sending  21
sending  22
sending  23
sending  24
sending  25
sending  26
sending  27
sending  28
sending  29
offline
offline
sending  30
sending  31
sending  32
sending  33
sending  34
sending  35
sending  36
sending  37
sending  38
sending  39
sending  40
sending  41
sending  42
sending  43
sending  44
sending  45
sending  46
sending  47
sending  48
sending  49
sending  50
sending  51
sending  52
sending  53
sending  54
sending  55
sending  56
sending  57
reconnect
sending  58
connected to the server. ID : 0000
sent  30
sent  31
sent  32
sent  33
sent  34
sent  35
sent  36
sent  37
sent  38
sent  39
sent  40
sent  41
sent  42
sent  43
sent  44
sent  45
sent  46
sent  47
sent  48
sent  49
sent  50
sent  51
sent  52
sent  53
sent  54
sent  55
sent  56
sent  57
sent  58
sending  59
sent  59
sending  60
sent  60
sending  61
sent  61
sending  62

so

• pakets 0 and 1 are not received because we are not yet subscribed
• why are packet 30 to 58 never received ?

[vallettea]

after the reconnection, message are received by the broker on the server.

[vallettea]

with two clients, both listening to test with one pushing data, we see that when the publishers pushes the stored messages after reconnection, the other client gets them.

[vallettea]

The morality here is that a client should resubscribe on reconnect

[vallettea]

I've opened an issue here: https://github.com/mqttjs/MQTT.js/issues/352

[vallettea]

if the heartbeat is long, the message that are emitted while the offline message is not yet received are correctly sent back after reconnection. Even with a heartbeat:0

[vallettea]

After a night with no connexion but with 6brain running, I started the wifi so there is a connectivity but mqtt doesn't seem to notice it and doesn't send the data.

[vallettea]

For this we should:

• log the mqtt connection messages
• either set a non null keepalive or modify the client so that messages are considered as ping

[4rzael]

Here's a link to the MQTT spec, it could be useful.

The part 4.4 explains the problem.

And anyway, if we modify the client, we would still need to set a non-null keepalive.

[vallettea]

I think @4rzael PR solves the pb.

[vallettea]

At 9am utc pheromon went down. On the sensor we get the offline 30 min after:

Dec 03 08:45:00 ant2 6brain[2887]: wifi measurements received
Dec 03 08:50:00 ant2 6brain[2887]: wifi measurements received
Dec 03 08:55:00 ant2 6brain[2887]: wifi measurements received
Dec 03 09:00:00 ant2 6brain[2887]: wifi measurements received
Dec 03 09:00:53 ant2 6brain[2887]: data received : status destination undefined
Dec 03 09:01:12 ant2 6brain[2887]: data received : opentunnel 2222 22 kerrigan destination undefined
Dec 03 09:05:00 ant2 6brain[2887]: wifi measurements received
Dec 03 09:10:00 ant2 6brain[2887]: wifi measurements received
Dec 03 09:15:00 ant2 6brain[2887]: wifi measurements received
Dec 03 09:20:00 ant2 6brain[2887]: wifi measurements received
Dec 03 09:25:00 ant2 6brain[2887]: wifi measurements received
Dec 03 09:30:00 ant2 6brain[2887]: wifi measurements received
Dec 03 09:35:00 ant2 6brain[2887]: wifi measurements received
Dec 03 09:40:00 ant2 6brain[2887]: wifi measurements received
Dec 03 09:45:00 ant2 6brain[2887]: wifi measurements received
Dec 03 09:50:00 ant2 6brain[2887]: wifi measurements received
Dec 03 09:55:01 ant2 6brain[2887]: wifi measurements received
Dec 03 10:00:01 ant2 6brain[2887]: wifi measurements received
Dec 03 10:05:01 ant2 6brain[2887]: wifi measurements received
Dec 03 10:10:01 ant2 6brain[2887]: wifi measurements received
Dec 03 10:15:01 ant2 6brain[2887]: wifi measurements received
Dec 03 10:20:01 ant2 6brain[2887]: wifi measurements received
Dec 03 10:25:01 ant2 6brain[2887]: wifi measurements received
Dec 03 10:30:01 ant2 6brain[2887]: wifi measurements received
Dec 03 10:32:42 ant2 6brain[2887]: offline
Dec 03 10:35:01 ant2 6brain[2887]: wifi measurements received
Dec 03 10:40:01 ant2 6brain[2887]: wifi measurements received
Dec 03 10:42:42 ant2 6brain[2887]: connected to the server. ID : 89332401000001798152

the reconnect is triggered 10 min after because here is the setting:

    client = mqtt.connect('mqtt://' + PRIVATE.host + ':' + PRIVATE.port,
        {
            username: simId,
            password: PRIVATE.mqttToken,
            clientId: simId,
            keepalive: 60*60,
            clean: false,
            reconnectPeriod: 1000 * 60 * 10
        }
    );

the problem is that messages between 9Am and the offline are never sent to the serve.

[vallettea]

When we receive offline and we wait reconnect, the reconnection happens and old data is sent.