LWT emitted on clean disconnect.

[fpagliughi]

Hey. I'm writing a little chat sample app for the next Paho C++ release, using an MQTT v5 connection. I believe I'm disconnecting cleanly, but the broker is still emitting the LWT message.

I tried it with Mosquitto v1.6.3 and 1.6.4. Both behave the same. This is on an x86_64, running Mint 19.

I'm connecting with a clean start, then subscribing to a single topic using the "no local" option. I can publish messages fine. But then when I disconnect, the LWT is emitted.

I also tested my client app against the Paho "testing" broker and VerneMQ. They behave in the way I expect.

Thanks.

[ralight]

I've written a test to try and reproduce this, but it is working as expected. Can you share some code that shows what you are seeing?

Thanks

[fpagliughi]

It's a sample I recently put up in the develop branch of the C++ library:
https://github.com/eclipse/paho.mqtt.cpp/blob/develop/src/samples/mqttpp_chat.cpp

I can try to do a smaller example or repeat with a different client, since it could be on the client side. But it's completely consistent. I see this for the log:

1564971188: New connection from 127.0.0.1 on port 1883.
1564971188: New client connected from 127.0.0.1 as auto-B29716DE-A826-D405-E922-2BB8D93C2D8B (p5, c1, k20).
1564971188: Will message specified (28 bytes) (r0, q1).
1564971188: 	chat/mygroup
1564971188: Sending CONNACK to auto-B29716DE-A826-D405-E922-2BB8D93C2D8B (0, 0)
1564971188: Received SUBSCRIBE from auto-B29716DE-A826-D405-E922-2BB8D93C2D8B
1564971188: 	chat/mygroup (QoS 1)
1564971188: auto-B29716DE-A826-D405-E922-2BB8D93C2D8B 1 chat/mygroup
1564971188: Sending SUBACK to auto-B29716DE-A826-D405-E922-2BB8D93C2D8B
1564971188: Received PUBLISH from auto-B29716DE-A826-D405-E922-2BB8D93C2D8B (d0, q1, r0, m2, 'chat/mygroup', ... (26 bytes))
1564971188: Sending PUBACK to auto-B29716DE-A826-D405-E922-2BB8D93C2D8B (m2, rc0)
1564971188: Sending PUBLISH to fa26b3f7-18af-487f-ab18-40249a5ff6dd (d0, q0, r0, m0, 'chat/mygroup', ... (26 bytes))
1564971189: Received PUBLISH from auto-B29716DE-A826-D405-E922-2BB8D93C2D8B (d0, q1, r0, m3, 'chat/mygroup', ... (24 bytes))
1564971189: Sending PUBACK to auto-B29716DE-A826-D405-E922-2BB8D93C2D8B (m3, rc0)
1564971189: Sending PUBLISH to fa26b3f7-18af-487f-ab18-40249a5ff6dd (d0, q0, r0, m0, 'chat/mygroup', ... (24 bytes))
1564971189: Socket error on client auto-B29716DE-A826-D405-E922-2BB8D93C2D8B, disconnecting.
1564971189: Sending PUBLISH to fa26b3f7-18af-487f-ab18-40249a5ff6dd (d0, q0, r0, m0, 'chat/mygroup', ... (28 bytes))

When I call disconnect, Mosquitto reports a socket error, then the last "Sending PUBLISH" is it emitting the LWT.

[ralight]

Thanks. I had a quick look in the repo but didn't spot that. I'll take a look later.

[fpagliughi]

The only new/different things with this example:

• It's making an MQTT v5 connection with "clean start" set. It supplies a blank Client ID and gets an "auto-..." ID assigned by the broker.
• It's subscribing to a single topic with the new "no local" option set. (This works in that the client doesn't receive its own messages).
• It publishes a few messages to the same topic on which it is subscribed, and it waits for the last message PUBLISH to be acknowledged (QoS=1) before attempting the disconnect.
• It disconnects without unsubscribing.

[fpagliughi]

Wireshark shows the Disconnect Request going on the wire after the last publish is ACK'ed:

Frame 13: 105 bytes on wire (840 bits), 105 bytes captured (840 bits) on interface 0
Ethernet II, Src: 00:00:00_00:00:00 (00:00:00:00:00:00), Dst: 00:00:00_00:00:00 (00:00:00:00:00:00)
Internet Protocol Version 4, Src: 127.0.0.1, Dst: 127.0.0.1
Transmission Control Protocol, Src Port: 56408, Dst Port: 1883, Seq: 116, Ack: 63, Len: 39
MQ Telemetry Transport Protocol, Publish Message
    Header Flags: 0x32, Message Type: Publish Message, QoS Level: At least once delivery (Acknowledged deliver)
    Msg Len: 37
    Topic Length: 10
    Topic: chat/group
    Message Identifier: 3
    Properties
        Total Length: 0
    Message: <<fmp left the group>>

No.     Time               Source                Destination           Protocol Length Info
     14 11:53:12.240195030 127.0.0.1             127.0.0.1             MQTT     70     Publish Ack (id=3)[Malformed Packet]

Frame 14: 70 bytes on wire (560 bits), 70 bytes captured (560 bits) on interface 0
Ethernet II, Src: 00:00:00_00:00:00 (00:00:00:00:00:00), Dst: 00:00:00_00:00:00 (00:00:00:00:00:00)
Internet Protocol Version 4, Src: 127.0.0.1, Dst: 127.0.0.1
Transmission Control Protocol, Src Port: 1883, Dst Port: 56408, Seq: 63, Ack: 155, Len: 4
MQ Telemetry Transport Protocol, Publish Ack
    Header Flags: 0x40, Message Type: Publish Ack
    Msg Len: 2
    Message Identifier: 3
[Malformed Packet: MQTT]

No.     Time               Source                Destination           Protocol Length Info
     16 11:53:12.241424198 127.0.0.1             127.0.0.1             MQTT     70     Disconnect Req

Frame 16: 70 bytes on wire (560 bits), 70 bytes captured (560 bits) on interface 0
Ethernet II, Src: 00:00:00_00:00:00 (00:00:00:00:00:00), Dst: 00:00:00_00:00:00 (00:00:00:00:00:00)
Internet Protocol Version 4, Src: 127.0.0.1, Dst: 127.0.0.1
Transmission Control Protocol, Src Port: 56408, Dst Port: 1883, Seq: 155, Ack: 67, Len: 4
MQ Telemetry Transport Protocol, Disconnect Req
    Header Flags: 0xe0, Message Type: Disconnect Req
    Msg Len: 2
    Reason Code: Normal disconnection (0)
    Properties
        Total Length: 0

But Mosquitto is hitting case MOSQ_ERR_CONN_LOST in loop.c:671, indicating, I believe, that it has not received/processed the disconnect before the connection was closed?

[ralight]

That's sorted now thanks! It was being treated as a protocol error due to an incorrect check, and the test for it wasn't sufficient either.

[fpagliughi]

That fixed it on my end. Thanks! The V5 stuff looks great. Can't wait to get the client libs wrapped up.

[wlisac]

I recently ran into this issue, too. I tested the fixes branch and it's now working as expected.

Thanks for the quick turnaround. Any estimate for when this will be in a tagged release?