Skip to main content

[Date Prev][Date Next][Thread Prev][Thread Next][Date Index][Thread Index] [List Home]
[mosquitto-dev] in order guarantees when max_inflight_messages = 1

Hi all,

I have the following setup:

1 Mosquitto server 1.4.12 using this docker image https://hub.docker.com/_/eclipse-mosquitto/. It has max_inflight_messages = 1 and retry_interval = 1.

2 x Paho 1.1.1 Java clients (client_pub and client_sub).

client_pub is publishing 1 msg a second to one topic using QOS 2 (in flight window 1).

client_sub is subscribing to the same topic using QOS 2 and persistent session enabled (clean session flag set to false). It receives the message and forwards it to a processor but only sends the last QOS 2 ack (PUBCOMP) once the processor finished processing the result, which happens on a separate thread.

With this setup I see multiple messages in flight coming from the broker which also leads to re-ordering of messages.

This happens in an integration test where I am simply stopping the consumer app (containing client_sub) and bringing it back again.

Basically that pattern of messages that I am observing (9 out of 10 times) is client_pub sends messages 1,2,3,4 and client_sub emits 1,2,3,2,3,4 from it's messageArrived Paho callback method. This pattern is possible with QOS 1 as it is stated here http://docs.oasis-open.org/mqtt/mqtt/v3.1.1/os/mqtt-v3.1.1-os.html#_Toc398718105 but should not be possible with QOS 2. I am definitely using QOS 2 for all clients.

Note that messages 1, 2 and 3 for which we get the unexpected behaviour are published to the topic during the app downtime (client_sub downtime).

I am not able to explain why this is happening, as my understanding is that with QOS 2 and max in flight set to 1 MQTT guarantees a topic is an ordered topic. See the detailed Paho client logs and Mosquitto server logs below showing the not expected messages sent by the server.

Martin

client_sub log (as printed by the paho messageArrived callback; timestamp format is HHMMssSSSS):
17-08-10 1946300446 DEBUG MQTTSource.messageArrived: MqttClient with id <client_sub> received and passed on this message from the MQTT broker: id <1>, qos <2>, body <...>, isDuplicate <false>.
17-08-10 1946320399 DEBUG MQTTSource.messageArrived: MqttClient with id <client_sub> received and passed on this message from the MQTT broker: id <2>, qos <2>, body <...>, isDuplicate <false>.
17-08-10 1946320400 DEBUG MQTTSource.messageArrived: MqttClient with id <client_sub> received and passed on this message from the MQTT broker: id <3>, qos <2>, body <...>, isDuplicate <false>.
NOT EXPECTED vvvv
17-08-10 1946330545 DEBUG MQTTSource.messageArrived: MqttClient with id <client_sub> received and passed on this message from the MQTT broker: id <2>, qos <2>, body <...>, isDuplicate <false>.
17-08-10 1946330545 DEBUG MQTTSource.messageArrived: MqttClient with id <client_sub> received and passed on this message from the MQTT broker: id <3>, qos <2>, body <...>, isDuplicate <false>.
NOT EXPECTED ^^^^
17-08-10 1946340439 DEBUG MQTTSource.messageArrived: MqttClient with id <client_sub> received and passed on this message from the MQTT broker: id <4>, qos <2>, body <...>, isDuplicate <false>.
17-08-10 1946360396 DEBUG MQTTSource.messageArrived: MqttClient with id <client_sub> received and passed on this message from the MQTT broker: id <5>, qos <2>, body <...>, isDuplicate <false>.
17-08-10 1946370583 DEBUG MQTTSource.messageArrived: MqttClient with id <client_sub> received and passed on this message from the MQTT broker: id <5>, qos <2>, body <...>, isDuplicate <false>.
17-08-10 1946380394 DEBUG MQTTSource.messageArrived: MqttClient with id <client_sub> received and passed on this message from the MQTT broker: id <6>, qos <2>, body <...>, isDuplicate <false>.
17-08-10 1946390591 DEBUG MQTTSource.messageArrived: MqttClient with id <client_sub> received and passed on this message from the MQTT broker: id <6>, qos <2>, body <...>, isDuplicate <false>.

mosquitto server log:
1502390751: Sending PUBLISH to client_sub (d0, q2, r0, m1, 'topic_1', ... (666 bytes))
1502390751: client_sub 2 topic_1
1502390752: Received PUBREC from client_sub (Mid: 1)
1502390752: Sending PUBREL to client_sub (Mid: 1)
1502390753: Received PUBCOMP from client_sub (Mid: 1)

NOT EXPECTED vvvv (sent 2 msgs at the same time - so 2 are in flight at the same time)
1502390753: Sending PUBLISH to client_sub (d0, q2, r0, m2, 'topic_1', ... (665 bytes))
1502390753: Sending PUBLISH to client_sub (d0, q2, r0, m3, 'topic_1', ... (668 bytes))
1502390753: Received PUBREC from client_sub (Mid: 2)
1502390753: Sending PUBREL to client_sub (Mid: 2)
1502390753: Received PUBREC from client_sub (Mid: 3)
1502390753: Sending PUBREL to client_sub (Mid: 3)
NOT EXPECTED ^^^^

NOT EXPECTED vvvv (PUBRELS are expected but because two msgs are sent at the same time before we have a PUBREL for msg 2 after the PUBLISH from msg 3 which is not expected)
1502390755: Sending PUBREL to client_sub (Mid: 2)
1502390755: Sending PUBREL to client_sub (Mid: 3)
1502390755: Received PUBCOMP from client_sub (Mid: 2)
1502390755: Received PUBCOMP from client_sub (Mid: 3)
NOT EXPECTED ^^^^

1502390755: Sending PUBLISH to client_sub (d0, q2, r0, m4, 'topic_1', ... (666 bytes))
1502390755: Received PUBREC from client_sub (Mid: 4)
1502390755: Sending PUBREL to client_sub (Mid: 4)
1502390757: Received PUBCOMP from client_sub (Mid: 4)
1502390757: Sending PUBLISH to client_sub (d0, q2, r0, m5, 'topic_1', ... (667 bytes))
1502390757: Received PUBREC from client_sub (Mid: 5)
1502390757: Sending PUBREL to client_sub (Mid: 5)
1502390759: Sending PUBREL to client_sub (Mid: 5)
1502390759: Received PUBCOMP from client_sub (Mid: 5)
1502390759: Sending PUBLISH to client_sub (d0, q2, r0, m6, 'topic_1', ... (667 bytes))
1502390759: Received PUBREC from client_sub (Mid: 6)
1502390759: Sending PUBREL to client_sub (Mid: 6)
1502390761: Sending PUBREL to client_sub (Mid: 6)
1502390761: Received PUBCOMP from client_sub (Mid: 6)

Back to the top