Skip to content
New issue

Have a question about this project? Sign up for a free GitHub account to open an issue and contact its maintainers and the community.

By clicking “Sign up for GitHub”, you agree to our terms of service and privacy statement. We’ll occasionally send you account related emails.

Already on GitHub? Sign in to your account

LWT emitted on clean disconnect. #1367

Closed
fpagliughi opened this issue Aug 2, 2019 · 8 comments

Comments

@fpagliughi
Copy link

commented Aug 2, 2019

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

This comment has been minimized.

Copy link
Contributor

commented Aug 4, 2019

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

This comment has been minimized.

Copy link
Author

commented Aug 5, 2019

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

This comment has been minimized.

Copy link
Contributor

commented Aug 5, 2019

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

@fpagliughi

This comment has been minimized.

Copy link
Author

commented Aug 5, 2019

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

This comment has been minimized.

Copy link
Author

commented Aug 5, 2019

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 added a commit that referenced this issue Aug 5, 2019
These were being treated as a protocol error.

Closes #1367. Thanks to Frank Pagliughi.
@ralight

This comment has been minimized.

Copy link
Contributor

commented Aug 5, 2019

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

This comment has been minimized.

Copy link
Author

commented Aug 6, 2019

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

@wlisac

This comment has been minimized.

Copy link

commented Aug 16, 2019

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?

ralight added a commit that referenced this issue Sep 18, 2019
These were being treated as a protocol error.

Closes #1367. Thanks to Frank Pagliughi.
Sign up for free to join this conversation on GitHub. Already have an account? Sign in to comment
Projects
None yet
3 participants
You can’t perform that action at this time.