client goes offline on publish on mac

[meilon]

Hi,
I'm developing an app on my MacBook Pro and I have a problem with MQTT.js 1.0.10 on it. The client should receive a message on one QoS 2 topic, do some stuff with it and publish it on another QoS 2 topic.

After the message reaches the client at first nothing happens on the console. Then, after the keepalive timeout occurs, the client reconnects and publishes the message. The general error event doesn't get called and the err object in the publish callback doesn't contain anything.

This happens with mosquitto 1.3.5, iot.eclipse.org and test.mosquitto.org without TLS on my MacBook Pro with current OSX 10.10.2 and node 0.12.0. Because the same script works on a Raspberry Pi with note 0.10.26 I'm guessing it's an issue with my Mac or it's generally Mac reladed. Node is installed via brew

Here the code I'm testing with:

var mqtt = require('mqtt');

var mqttOptions = {
    clientId: 'delayed-demo', 
    clean: false, 
    keepalive: 10
}

mqttClient = mqtt.connect('mqtt://test.mosquitto.org', mqttOptions);
mqttClient.on('connect', function() {
    console.log(new Date().toTimeString() + ' [MQTT] connected!');
    mqttClient.subscribe('/poke', { qos: 2}, function(err, granted) {
        if (err) {
            console.log(new Date().toTimeString() + ' [MQTT] ERROR: ' + err);
        } else {
            console.log(new Date().toTimeString() + ' [MQTT] Subscribed to topic ' + granted[0].topic + ' with QoS ' + granted[0].qos);
        }
    });
});

mqttClient.on('offline', function() {
    console.log(new Date().toTimeString() + ' [MQTT] now offline!');
});

mqttClient.on('error', function(error) {
    console.error(new Date().toTimeString() + ' [MQTT] general error: ' + error);
});


mqttClient.on('message', function (topic, message) {
    console.log(new Date().toTimeString() + ' [MQTT] Topic: ' + topic + ', message: ' + message);

    mqttClient.publish("/ping", "pong!", {qos:2, retain:false}, function(err) {
        if (err) console.log(new Date().toTimeString() + ' [MQTT] publish error: ' + err);
        console.log(new Date().toTimeString() + ' [MQTT] Published alarm to "/ping"');
    });
});

And here's the console output:

19:23:50 GMT+0100 (CET) [MQTT] connected!
19:23:50 GMT+0100 (CET) [MQTT] Subscribed to topic /poke with QoS 2
19:23:57 GMT+0100 (CET) [MQTT] Topic: /poke, message: hi
19:24:10 GMT+0100 (CET) [MQTT] now offline!
19:24:11 GMT+0100 (CET) [MQTT] connected!
19:24:11 GMT+0100 (CET) [MQTT] Subscribed to topic /poke with QoS 2
19:24:11 GMT+0100 (CET) [MQTT] Published to "/ping"

[hellish]

Had same problem with the 1.x and mosquitto 1.3.5
Solved it by providing extra options

protocolId: 'MQIsdp',
protocolVersion: 3

[meilon]

Just tried that, still the same.

[mcollina]

@256dpi @mdickens @RogerMauve any of you has time to look into this? I am very low bandwidth at the moment, and this looks like a complex bug.

Or if @meilon would like to understand what the problem is and provide a fix, we would be grateful.

[meilon]

This is what I tried since opening this issue:
If I send a publish (no matter what QoS) directly after the connect, it goes through. The publish on message received still fails on the first try, every time. So while I keep the app running, every on message triggered publish seems to trigger a disconnect.

After adding some console log I can't get any further than the sendPacket function. The buffer generated from mqttPacket.generate(packet); is the same before and after the reconnect. The console.log('func_sendPacket_cb'); gets called the second time.

if (!client.stream.write(buf) && cb) {
        console.log('func_sendPacket_no_client.stream.write_and_cb');
      client.stream.once('drain', cb);
    } else if (cb) {
        console.log('func_sendPacket_cb');
      cb();

so it ends in the client.stream.write function for the pubcomp for me. I tried to connect via TLS, but it's just the same.

Here's the full verbose output:

func_sendPacket, cmd:connect
<Buffer 10 1a 00 06 4d 51 49 73 64 70 03 00 00 0a 00 0c 64 65 6c 61 79 65 64 2d 64 65 6d 6f>
func_sendPacket_eof
23:56:51 GMT+0100 (CET) [MQTT] connected!
prot__sendPacket, cmd:subscribe
func_storeAndSend, cmd:subscribe
func_sendPacket, cmd:subscribe
<Buffer 82 0a 9b e6 00 05 2f 70 6f 6b 65 02>
func_sendPacket_eof
prot_publish
prot__sendPacket, cmd:publish
func_storeAndSend, cmd:publish
func_sendPacket, cmd:publish
<Buffer 32 18 00 05 2f 70 69 6e 67 9b e7 70 69 6e 67 20 6f 6e 20 63 6f 6e 6e 65 63 74>
func_sendPacket_eof
23:56:51 GMT+0100 (CET) [MQTT] Subscribed to topic /poke with QoS 2
23:56:51 GMT+0100 (CET) [MQTT] Published to "/ping" on connect
prot__sendPacket, cmd:pubrec
func_sendPacket, cmd:pubrec
<Buffer 50 02 00 01>
func_sendPacket_cb
func_sendPacket_eof
23:56:53 GMT+0100 (CET) [MQTT] Topic: /poke, message: hi
prot_publish
prot__sendPacket, cmd:publish
func_storeAndSend, cmd:publish
func_sendPacket, cmd:publish
<Buffer 32 18 00 05 2f 70 69 6e 67 9b e8 70 69 6e 67 20 6f 6e 20 6d 65 73 73 61 67 65>
func_sendPacket_eof
prot__sendPacket, cmd:pubcomp
func_sendPacket, cmd:pubcomp
<Buffer 74 02 00 01>
func_sendPacket_eof
----------------------------- This line is where nothing happens until the ping request comes on
prot__sendPacket, cmd:pingreq
func_sendPacket, cmd:pingreq
<Buffer c0 00>
func_sendPacket_eof
23:57:11 GMT+0100 (CET) [MQTT] now offline!
func_sendPacket, cmd:connect
<Buffer 10 1a 00 06 4d 51 49 73 64 70 03 00 00 0a 00 0c 64 65 6c 61 79 65 64 2d 64 65 6d 6f>
func_sendPacket_eof
prot__sendPacket, cmd:publish
prot__sendPacket, cmd:publish
func_storeAndSend, cmd:publish
func_sendPacket, cmd:publish
<Buffer 32 18 00 05 2f 70 69 6e 67 9b e8 70 69 6e 67 20 6f 6e 20 6d 65 73 73 61 67 65>
func_sendPacket_cb
func_sendPacket_eof
23:57:12 GMT+0100 (CET) [MQTT] connected!
prot__sendPacket, cmd:subscribe
func_storeAndSend, cmd:subscribe
func_sendPacket, cmd:subscribe
<Buffer 82 0a 9b e9 00 05 2f 70 6f 6b 65 02>
func_sendPacket_eof
prot_publish
prot__sendPacket, cmd:publish
func_storeAndSend, cmd:publish
func_sendPacket, cmd:publish
<Buffer 32 18 00 05 2f 70 69 6e 67 9b ea 70 69 6e 67 20 6f 6e 20 63 6f 6e 6e 65 63 74>
func_sendPacket_eof
23:57:12 GMT+0100 (CET) [MQTT] Published to "/ping"
23:57:12 GMT+0100 (CET) [MQTT] Subscribed to topic /poke with QoS 2
23:57:12 GMT+0100 (CET) [MQTT] Published to "/ping" on connect

I'm definitely not that familiar with the MQTT Protocol and the way MQTT.js works, but shouldn't there be a PUBREL instead of a PUBCOMP? And why is there no PUBREL on the on-connect publish with QoS 2, but a PUBREC? PUBCOMP and PUBREC are packages that should come from the server, like described here: http://public.dhe.ibm.com/software/dw/webservices/ws-mqtt/mqtt-v3r1.html#qos-flows

Tomorrow I'll do some more debugging, having a closer look on the actual message flow.

BTW: Could you document the possible options a little bit better? When trying to connect via TLS (only encryption, no authentication) you have to set protocol to mqtts, but I had to look into the code to find this option. Also, the client says Error: self signed certificate in certificate chain even though I used the certificate supplied from the website. Only a rejectUnauthorized to false would let me connect!

[mcollina]

The diagram you linked explain the the exchange poorly, replace 'client' with 'sender' and 'server' with 'receiver'. As the two roles can be exchanged if a client does a qos2 subscription.

I think you should try to debug it

Regarding options, send a PR against the README, I'll get that merged :D.

[meilon]

I'm at a miss, I don't know how to debug any further. I have created a wireshark capture you can find here: https://www.dropbox.com/s/07wml3sfnj5knh9/delayed-publish.pcapng?dl=0

The output for this is as follows:

func_sendPacket, msgid:undefined, cmd:connect
<Buffer 10 1a 00 06 4d 51 49 73 64 70 03 00 00 0a 00 0c 64 65 6c 61 79 65 64 2d 64 65 6d 6f>
func_sendPacket_eof, msgid:undefined, cmd:connect
prot_handlePacket, msgid:undefined, cmd:connack
17:13:13 GMT+0100 (CET) [MQTT] connected!
prot__sendPacket, msgid:28100, cmd:subscribe
func_storeAndSend, msgid:28100, cmd:subscribe
func_sendPacket, msgid:28100, cmd:subscribe
<Buffer 82 0a 6d c4 00 05 2f 70 6f 6b 65 02>
func_sendPacket_eof, msgid:28100, cmd:subscribe
prot_handlePacket, msgid:1, cmd:publish
prot__sendPacket, msgid:1, cmd:pubrec
func_sendPacket, msgid:1, cmd:pubrec
<Buffer 50 02 00 01>
func_sendPacket_cb, msgid:1, cmd:pubrec
func_sendPacket_eof, msgid:1, cmd:pubrec
prot_handlePacket, msgid:28100, cmd:suback
17:13:13 GMT+0100 (CET) [MQTT] Subscribed to topic /poke with QoS 2
prot_handlePacket, msgid:56105, cmd:pubrec
prot_handlePacket, msgid:64413, cmd:pubrec
prot_handlePacket, msgid:1, cmd:pubrel
17:13:13 GMT+0100 (CET) [MQTT] Topic: /poke, message: hi
prot_publish
prot__sendPacket, msgid:28101, cmd:publish
func_storeAndSend, msgid:28101, cmd:publish
func_sendPacket, msgid:28101, cmd:publish
<Buffer 32 18 00 05 2f 70 69 6e 67 6d c5 70 69 6e 67 20 6f 6e 20 6d 65 73 73 61 67 65>
func_sendPacket_eof, msgid:28101, cmd:publish
prot__sendPacket, msgid:1, cmd:pubcomp
func_sendPacket, msgid:1, cmd:pubcomp
<Buffer 74 02 00 01>
func_sendPacket_eof, msgid:1, cmd:pubcomp
prot__sendPacket, msgid:undefined, cmd:pingreq
func_sendPacket, msgid:undefined, cmd:pingreq
<Buffer c0 00>
func_sendPacket_eof, msgid:undefined, cmd:pingreq
17:13:33 GMT+0100 (CET) [MQTT] now offline!
func_sendPacket, msgid:undefined, cmd:connect
<Buffer 10 1a 00 06 4d 51 49 73 64 70 03 00 00 0a 00 0c 64 65 6c 61 79 65 64 2d 64 65 6d 6f>
func_sendPacket_eof, msgid:undefined, cmd:connect
prot__sendPacket, msgid:28101, cmd:publish
prot_handlePacket, msgid:undefined, cmd:connack
prot__sendPacket, msgid:28101, cmd:publish
func_storeAndSend, msgid:28101, cmd:publish
func_sendPacket, msgid:28101, cmd:publish
<Buffer 32 18 00 05 2f 70 69 6e 67 6d c5 70 69 6e 67 20 6f 6e 20 6d 65 73 73 61 67 65>
func_sendPacket_cb, msgid:28101, cmd:publish
func_sendPacket_eof, msgid:28101, cmd:publish
17:13:34 GMT+0100 (CET) [MQTT] connected!
prot__sendPacket, msgid:28102, cmd:subscribe
func_storeAndSend, msgid:28102, cmd:subscribe
func_sendPacket, msgid:28102, cmd:subscribe
<Buffer 82 0a 6d c6 00 05 2f 70 6f 6b 65 02>
func_sendPacket_eof, msgid:28102, cmd:subscribe
prot_handlePacket, msgid:1, cmd:publish
prot__sendPacket, msgid:1, cmd:pubrec
func_sendPacket, msgid:1, cmd:pubrec
<Buffer 50 02 00 01>
func_sendPacket_cb, msgid:1, cmd:pubrec
prot_handlePacket, msgid:56105, cmd:pubrec
prot_handlePacket, msgid:64413, cmd:pubrec
func_sendPacket_eof, msgid:1, cmd:pubrec
prot_handlePacket, msgid:28101, cmd:puback
17:13:34 GMT+0100 (CET) [MQTT] Published to "/ping"
prot_handlePacket, msgid:28102, cmd:suback
17:13:34 GMT+0100 (CET) [MQTT] Subscribed to topic /poke with QoS 2
prot_handlePacket, msgid:1, cmd:pubrel
17:13:34 GMT+0100 (CET) [MQTT] Topic: /poke, message: hi
prot_publish
prot__sendPacket, msgid:28103, cmd:publish
func_storeAndSend, msgid:28103, cmd:publish
func_sendPacket, msgid:28103, cmd:publish
<Buffer 32 18 00 05 2f 70 69 6e 67 6d c7 70 69 6e 67 20 6f 6e 20 6d 65 73 73 61 67 65>
func_sendPacket_eof, msgid:28103, cmd:publish
prot__sendPacket, msgid:1, cmd:pubcomp
func_sendPacket, msgid:1, cmd:pubcomp
<Buffer 74 02 00 01>
func_sendPacket_eof, msgid:1, cmd:pubcomp

I have no idea what should happen and what not. If you could tell me what to do I'll try. QoS 0 clients get the message twice, once before and once after the disconnect. QoS 2 clients obviously only once because of the missing PUBREL. I also have this problem on another Windows machine, so it isn't just Mac related.

EDIT: So I made a mistake, now ALL devices where I installed node and used mqtt.js, the delayed publish is now occuring. I don't have any "clean" systems now. what should I try?

[jpolaroid1978]

Hi,

I took a look at it, Could @meilon document exactly the steps to recreate? I tried with the above sample and it seemed to work for me on x86. Here are my steps: (note mqtt.252b.js is the exact same code as originally posted)

1 node mqtt.252b.js
this.options.clean is false
this.options.qos is undefined end
13:09:29 GMT-0600 (CST) [MQTT] connected!
13:09:30 GMT-0600 (CST) [MQTT] Subscribed to topic /poke with QoS 2

< next output showed up after step 2>
13:09:39 GMT-0600 (CST) [MQTT] Topic: /poke, message: hi
13:09:39 GMT-0600 (CST) [MQTT] Published alarm to "/ping"

2 ./mqtt.js publish -v --host test.mosquitto.org -t /poke -m "hi"
this.options.clean is true
this.options.qos is 0 end

With those above steps i didn't see the offline part. What steps do you do in order to get the offline?

[jpolaroid1978]

Hi I think i would like to work on this. Do the issues get assigned to prevent someone else from duplicating the effort at the same time?

[meilon]

I just tried it again in a blank directory, still the same. But what I tried additionally after seeing you did the poke with QoS 0, I did the same on my system: The message gets pubbed right away on a QoS 0 and 1 message!

So it seems it is related how the message got sent in the first place!

A received QoS 2 message in a QoS 2 subscription causes a disconnect on a following QoS 2 publish.
A received QoS 0 or 1 message in a QoS 2 subscription doesn't impact a following QoS 2 publish

[mcollina]

@mdickens it is all yours, thank so much in helping out!

[jpolaroid1978]

I just recreated it on a local setup with mosquitto. It seems that the client does not receive the PINGRESP sent by the server in this particular usage pattern.

---

client trace

generate:pingreq
{ cmd: 'pingreq' }
15:58:08 GMT-0600 (CST) [MQTT] now offline!

---

mosquitto trace

1424210278: Received PINGREQ from delayed-demo
1424210278: Sending PINGRESP to delayed-demo
1424210288: Socket error on client delayed-demo, disconnecting.

[mcollina]

I think I found the bug

handlePubrel should accept two parameters, one packet and a callback, in particular the callback should be passed to sendPacket here https://github.com/mqttjs/MQTT.js/blob/master/lib/client.js#L766

In fact, here https://github.com/mqttjs/MQTT.js/blob/master/lib/client.js#L219 it is called with two arguments.

You should be able to write a unit test by sending any packet after a PUBREL, it will not get processed.

@mdickens It's still on you to assemble a PR :P. Thank so much for debugging it!!

[jpolaroid1978]

ok i will work on it , thank you

[jpolaroid1978]

My apologies, i got distracted with some other work, including having to move all of my furniture, but I still plan to do this if the delay is not too much trouble for everyone. Thanks!

[mcollina]

No worries, I have been busy myself :(.

[jpolaroid1978]

Hi,

I got the mocha test running, but could use some advice about where you think the test would be best placed. Do you think it should go in the abstract_client.js file or where is the best place?

Thanks,

Marc

[jpolaroid1978]

is there another test that you think is close to what we need that would be a good starting point for me to check that pattern

[jpolaroid1978]

i sent a pr with what i have done, hope it helps!

[RangerMauve]

@mcollina Ha ha, I just noticed you tried to tag me. It's ranger not roger :p

[mcollina]

ahahah yes :D.