Skip to main content
[Date Prev][Date Next][Thread Prev][Thread Next][Date Index][Thread Index] [List Home]
Re: [mosquitto-dev] in order guarantees when max_inflight_messages = 1
Hi Karl,

And thanks for your reply.

I am indeed expecting retries from the server (the PUBRELs in the log trace). The fact that they happen is fine. Part of the aim of the test is to check that retries do happen and that is the reason why the retry interval is set so low for Mosquitto.

What is not expected is the fact that 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 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 happening for message 1 though. Message 2 is published after PUBCOMP is received for message 1. Note the timestamp 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. ( is there a way to configure a higher precision in Mosquitto?).

1502390751: New client connected from 192.168.99.1 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.

They are a response to client_pub having published them during client_sub downtime at 2 sec intervals:

1502390742: Received PUBLISH from client_pub (d0, q2, r0, m1, 'iotgw2-1502390760800', ... (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, 'iotgw2-1502390760800', ... (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, 'iotgw2-1502390760800', ... (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)

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 PUBLISHED 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?

Thanks,
Martin

On Mon, Aug 14, 2017 at 10:32 AM, Karl Palsson <karlp@xxxxxxxxxxxx> wrote:


Surely this is "as expected" with your retry interval set so
short?

I presume that your subscriber is taking more than a second on
some processing, and so the broker is retrying as directed.

Just turn retry down/off/something reasonable and you should be
seeing behaviour more in line with your expectations.

Sincerely,
Karl P


Martin Eden <martineden131@xxxxxxxxx> wrote:
> 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)
> _______________________________________________ mosquitto-dev
> mailing list mosquitto-dev@xxxxxxxxxxx To change your delivery
> options, retrieve your password, or unsubscribe from this list,
> visit https://dev.eclipse.org/mailman/listinfo/mosquitto-dev
_______________________________________________
mosquitto-dev mailing list
mosquitto-dev@xxxxxxxxxxx
To change your delivery options, retrieve your password, or unsubscribe from this list, visit
https://dev.eclipse.org/mailman/listinfo/mosquitto-dev

Back to the top