[Date Prev][Date Next][Thread Prev][Thread Next][Date Index][Thread Index] [List Home]
[paho-dev] in order guarantees when max_inflight_messages = 1 on the broker

Hi all,

http://docs.oasis-open.org/mqtt/mqtt/v3.1.1/os/mqtt-v3.1.1-os.html#_Toc398718105Âseems to suggest that MQTT guarantees in order delivery for a window size of 1 on the broker and all clients involved with QOS 2.

Does this apply to:
a. Messages published by the broker to a client with a persistent session that is coming back up after a period of downtime?
b. Messages replayed by the broker (PUBLISH, PUBREL etc) because the response did not come before the retry interval setting on the broker (processing took longer)?

I am asking this because I am observing out of order deliveries on some tests.ÂSee the details below.

Martin

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 / sec to topic_1 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. To achieve this delayed ack I am enabling manual acks on the client (setManualAcks(true)).

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

With this setup I see the following unexpected behavior:
1. Multiple messages in flight coming from the broker
2. Re-ordering retried messages from the server.

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.

Mesasges 1,2 and 3 have been published duringÂclient_subÂdowntime at 2 sec intervals:

mosquitto.log
1502390742: Received PUBLISH from client_pubÂ(d0, q2, r0, m1, 'topic_1', ... (666 bytes))
1502390742: Sending PUBREC to client_pubÂ(Mid: 1)
1502390742: Received PUBREL from client_pubÂ(Mid: 1)
1502390742: Sending PUBCOMP to client_pubÂ(Mid: 1)
1502390744: Received PUBLISH from client_pub (d0, q2, r0, m2,Âtopic_1', ... (665 bytes))
1502390744: Sending PUBREC to client_pub (Mid: 2)
1502390744: Received PUBREL from client_pub (Mid: 2)
1502390744: Sending PUBCOMP to client_pub (Mid: 2)
1502390746: Received PUBLISH from client_pub (d0, q2, r0, m3,Âtopic_1', ... (668 bytes))
1502390746: Sending PUBREC to client_pub (Mid: 3)
1502390746: Received PUBREL from client_pub (Mid: 3)
1502390746: Sending PUBCOMP to client_pub (Mid: 3)

I am seeing a retry of an older message (2) after a publish of a newer message (3). This should not be happening not matter how long the retry interval is, in my understanding of the MQTT ordering guarantees at QOS 2 and max in flight 1.

This could be happening because the two messages were both in flight from the get go, which is also not expected.

As you can see from the next log trace the messages 2 and 3 are published by Mosquitto to client_sub one after the other without waiting for the QOS 2 PUBCOMP ack for msg 2 before publishing msg 3.

This is however happening for message 1. Message 2 is published after PUBCOMP is received for message 1.

Note the timestamps have second precision so there is some uncertainty of the ordering in the logs. Either way my tests is failing so re-ordering is real.

mosquitto.log
1502390751: New client connected from x.x.x.x asÂclient_subÂ(c0, k60).
1502390751: Sending CONNACK to client_subÂ(1, 0)
1502390751: Received SUBSCRIBE from client_sub
1502390751: Â Â topic_1 (QoS 2)
1502390751: Sending PUBLISH to client_subÂ(d0, q2, r0, m1, 'topic_1', ... (666 bytes))
...
1502390752: Received PUBREC from client_subÂ(Mid: 1)
1502390752: Sending PUBREL to client_subÂ(Mid: 1)
...
1502390753: ReceivedÂPUBCOMPÂfrom client_sub (Mid: 1)
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)

The above trace occurs onceÂclient_subÂcame back to life.

So is the QOS 2 PUBCOMP ack not the trigger for Mosquitto (or any MQTT broker) with max inflight window set to 1 to send the next message PUBLISH on a particular topic for a particular subscriber of that topic? If not what is? Is it the PUBREC? How can I obtain this expected behaviour with Mosquitto and Paho?

What about when retries do happen because processing finishes (i.e. PUBCOMP is sent) later than the retry interval set o Mosquitto (or any MQTT broker)? How can we make sure ordering is still guaranteed?

Martin

P.S.

Complete logs:

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)