Received PUBREL for an unknown packet identifier

[zinid]

This was already reported in #374 but seems like the reason is different in my case.

I was able to catch the issue in a debug mode, here is the full log

TL;DR: The interesting part here is a PUBLISH packet with identifier 38300. Here is what happens:

1. A PUBLISH packet is received from the client at line 4:

1534280285: Received PUBLISH from rtb371 (d0, q2, r0, m38300, '/rtb/user991', ... (6 bytes))

2. The client gets reconnected, see lines 7-10
3. The client then resends the PUBLISH packet with the dup flag set, see line 12:

1534280288: Received PUBLISH from rtb371 (d1, q2, r0, m38300, '/rtb/user991', ... (6 bytes))

4. Mosquitto finally decides to send PUBREC, but does it twice: at line 13 and 15:

1534280288: Sending PUBREC to rtb371 (Mid: 38300)
1534280288: Sending PUBREC to rtb371 (Mid: 38300)

5. The client also decides to answer twice with PUBREL packet (because why not? I didn't find in the spec any defined behaviour in such situation). This can be seen at lines 16 and 18:

1534280288: Received PUBREL from rtb371 (Mid: 38300)
1534280288: Received PUBREL from rtb371 (Mid: 38300)

However, Mosquitto treats the later PUBREL as mismatched and logs the corresponding warning.
My question here: is this an expected behaviour? From the perspective of MQTT 3.1.1 spec the server MUST reply to any duplicated PUBLISH packets with PUBREC:

Until it has received the corresponding PUBREL packet, the Receiver MUST acknowledge any subsequent PUBLISH packet with the same Packet Identifier by sending a PUBREC

On the other hand in this case the server should be prepared to handle duplicated PUBREL packets and, most likely, should not log a warning.

Another concern is why actually Mosquitto replies with PUBREC twice? The original PUBLISH packet was received before disconnection, so Mosquitto should probably just queue the packet and only reply to duplicates.

Mosquitto version is 1.4.15 (the latest available in Debian testing).

[ralight]

This test replicates what you are seeing for 1.4.15, if you gunzip both files and put them in test/broker, then run ./928.py the bottom part of the log matches what you get.

928.conf.gz
928.py.gz

It seems as though it's related to a message being queued and I think it is already fixed in 1.5, I'm just making up that test now.

[zinid]

Indeed, I cannot reproduce the issue on master branch. I close it then.

[zinid]

Argh, just closed and got it again 😡

1534340701: Warning: Received PUBREL from rtb9032 for an unknown packet identifier 55872.
1534340711: Warning: Received PUBREL from rtb33436 for an unknown packet identifier 63939.
1534340727: Warning: Received PUBREL from rtb10646 for an unknown packet identifier 64610.

I will investigate it further, maybe the reason is different.

[zinid]

Yes, this is another case, here is the log:

1534341523: New client connected from 192.168.1.1 as rtb7262 (c0, k60, u'user7262').
1534341523: Sending CONNACK to rtb7262 (0, 0)
1534341523: Received SUBSCRIBE from rtb7262
1534341523: rtb7262 2 /rtb/user7262
1534341523: Sending SUBACK to rtb7262
1534341578: Received PUBLISH from rtb7262 (d0, q2, r0, m40551, '/rtb/user12582', ... (6 bytes))
1534341578: Sending PUBREC to rtb7262 (Mid: 40551)
1534341579: Received PUBREL from rtb7262 (Mid: 40551)
1534341579: Sending PUBCOMP to rtb7262 (Mid: 40551)
1534341579: Socket error on client rtb7262, disconnecting.
1534341602: New client connected from 192.168.1.1 as rtb7262 (c0, k60, u'user7262').
1534341602: Sending CONNACK to rtb7262 (1, 0)
1534341602: Received PUBREL from rtb7262 (Mid: 40551)
1534341602: Warning: Received PUBREL from rtb7262 for an unknown packet identifier 40551.
1534341602: Sending PUBCOMP to rtb7262 (Mid: 40551)
1534341608: Socket error on client rtb7262, disconnecting.

Seems like this "unexpected" PUBREL is just a client's repeat, because it didn't receive PUBCOMP prior to disconnection.

[ralight]

Can you say which client are you using, out of interest?

Like I said before, this isn't necessarily a problem, it's just mosquitto saying "by the way, a client has sent me a PUBREL that I'm not expecting, I'm going to complete the message flow anyway to keep the client happy".

[zinid]

Can you say which client are you using, out of interest?

It's my own tool for benchmarking MQTT brokers: RTB

Like I said before, this isn't necessarily a problem

You said that? 😁 OK, seems like I misread you

it's just mosquitto saying "by the way, a client has sent me a PUBREL that I'm not expecting, I'm going to complete the message flow anyway to keep the client happy"

Yes, this is now mostly a cosmetic issue (to me). However, a warning assumes admin's attention and I don't see what admin can do seeing this message. But this is up to you of course, I don't insist. At least admins now will google this warning and will read this thread 😁 Close the ticket if you feel it's irrelevant anymore.

[zinid]

Aaaand another problem with duplicated PUBREC (it's related, so I don't open a new issue):
The relevant part of the log:

1534347568: Received PUBLISH from rtb27134 (d0, q2, r0, m35962, '/rtb/user36337', ... (6 bytes))
...
1534347570: Socket error on client rtb27134, disconnecting.
1534347616: New client connected from 127.0.0.1 as rtb27134 (c0, k60, u'user27134').
...
1534347617: Received PUBLISH from rtb27134 (d1, q2, r0, m35962, '/rtb/user36337', ... (6 bytes))
...
1534347617: Sending PUBREC to rtb27134 (Mid: 35962)
1534347618: Received PUBREL from rtb27134 (Mid: 35962)
1534347618: Sending PUBCOMP to rtb27134 (Mid: 35962)
1534347619: Sending PUBREC to rtb27134 (Mid: 35962)

This one really looks like a bug: after a completion with PUBCOMP the server sends yet another PUBREC with the same identifier.

[zinid]

Note this one is on master branch: ebf4d3a

[ralight]

Could you post your broker configuration?

[ralight]

Would you be able to try the attached patch? I don't think this will solve the problem, but I'm interested in whether it changes the behaviour.

0001-Check-for-918.patch.gz

git clone https://github.com/eclipse/mosquitto
cd mosquitto
git checkout fixes
wget https://github.com/eclipse/mosquitto/files/2290972/0001-Check-for-918.patch.gz
gunzip  0001-Check-for-918.patch.gz
git am 0001-Check-for-918.patch
make

[zinid]

The config:

pid_file /var/run/mosquitto.pid
allow_anonymous false
password_file /tmp/passwd
max_inflight_messages 1
connection_messages true
log_type all
log_dest file /tmp/mosquitto.log

[zinid]

I don't think this will solve the problem

Actually it did. At least I cannot reproduce it anymore after several hours of benchmarking.

[zinid]

Sorry for annoyance, but after several benchmark restarts I got duplicated PUBREC again :/
It's just hard to reproduce, this time I only got first duplcate at 15th minute of benchmarking.

[zinid]

OK, after playing with benchmarking parameters a bit, I found the configuration where I can reproduce it within the first minute. And this time I see a bit different behaviour:

1534364561: Received PUBLISH from rtb2759 (d0, q2, r0, m23734, '/rtb/user552', ... (6 bytes))
1534364561: Socket error on client rtb2759, disconnecting.
1534364566: Expiring old client session rtb2759, disconnecting.
1534364566: New client connected from 192.168.1.1 as rtb2759 (c0, k60, u'user2759').
...
1534364566: Received PUBLISH from rtb2759 (d1, q2, r0, m23734, '/rtb/user552', ... (6 bytes))
1534364566: Sending PUBREC to rtb2759 (Mid: 23734)
...
1534364566: Received PUBREL from rtb2759 (Mid: 23734)
1534364566: Warning: Received PUBREL from rtb2759 for an unknown packet identifier 23734.
1534364566: Sending PUBCOMP to rtb2759 (Mid: 23734)
...
1534364567: Sending PUBREC to rtb2759 (Mid: 23734)
1534364567: Socket error on client rtb2759, disconnecting.

[ralight]

I've been looking at this again and noticed that the line Expiring old client session doesn't appear in the mosquitto source anywhere, was this your own patched version?