Unexpected error: pubrec_packetId_not_found

[YraganTron]

Hi! I have a client that receives and sends messages. I started to notice that sometimes some of the messages qos 2 were not being processed. I recorded a log trace for the client and saw this

2024-04-15T13:52:12.236883+00:00 [MQTT] 9db7964d-d93b-4cd7-b675-de41ce0d425d@10.5.151.4:53158 
[error_pubrec_not_found_id.txt](https://github.com/emqx/emqx/files/14983177/error_pubrec_not_found_id.txt)
msg: mqtt_packet_sent, packet: PUBLISH(Q2, R0, D0, Topic=vehicles/v1/9db7964d-d93b-4cd7-b675-de41ce0d425d/commands/videoCall, PacketId=6, Payload={"headers": {"correlationUuid": "f27dee2e-1c77-44e5-94ae-b0cc19207512", "messageId": "3fe388a1-5d5b-... The 5966 bytes of this log are truncated)
2024-04-15T13:52:18.348032+00:00 [MQTT] 9db7964d-d93b-4cd7-b675-de41ce0d425d@10.5.151.4:53158 msg: mqtt_packet_sent, packet: PUBLISH(Q2, R0, D0, Topic=vehicles/v1/9db7964d-d93b-4cd7-b675-de41ce0d425d/commands/commandStatus, PacketId=7, Payload={"headers": {"correlationUuid": "c5633abd-d837-4718-a8f3-e7386033bf8a", "messageId": "0743d242-4772-441a-9a4d-a6d7ca1cefea", "protocolVersion": "1.5.0", "sysTimestamp": "2024-04-15T13:52:18.335090", "vehicleId": "9db7964d-d93b-4cd7-b675-de41ce0d425d"}, "payload": {"action": "GetCommandStatus", "arguments": {"targetCommandCorrelationId": "f27dee2e-1c77-44e5-94ae-b0cc19207512"}}})
2024-04-15T13:53:40.505182+00:00 [MQTT] 9db7964d-d93b-4cd7-b675-de41ce0d425d@10.5.151.4:53158 msg: mqtt_packet_received, packet: PUBREC(Q0, R0, D0, PacketId=6, ReasonCode=0)
2024-04-15T13:53:40.505420+00:00 [warning] msg: pubrec_packetId_not_found, mfa: emqx_channel:handle_in/2(440), peername: 10.5.151.4:53158, clientid: 9db7964d-d93b-4cd7-b675-de41ce0d425d, packetId: 6
2024-04-15T13:53:40.505793+00:00 [MQTT] 9db7964d-d93b-4cd7-b675-de41ce0d425d@10.5.151.4:53158 msg: mqtt_packet_received, packet: PUBREC(Q0, R0, D0, PacketId=7, ReasonCode=0)
2024-04-15T13:53:40.505848+00:00 [warning] msg: pubrec_packetId_not_found, mfa: emqx_channel:handle_in/2(440), peername: 10.5.151.4:53158, clientid: 9db7964d-d93b-4cd7-b675-de41ce0d425d, packetId: 7
2024-04-15T13:53:40.506120+00:00 [MQTT] 9db7964d-d93b-4cd7-b675-de41ce0d425d@10.5.151.4:53158 msg: mqtt_packet_received, packet: PUBREC(Q0, R0, D0, PacketId=8, ReasonCode=0)
2024-04-15T13:53:40.506157+00:00 [warning] msg: pubrec_packetId_not_found, mfa: emqx_channel:handle_in/2(440), peername: 10.5.151.4:53158, clientid: 9db7964d-d93b-4cd7-b675-de41ce0d425d, packetId: 8
2024-04-15T13:53:40.506374+00:00 [MQTT] 9db7964d-d93b-4cd7-b675-de41ce0d425d@10.5.151.4:53158 msg: mqtt_packet_received, packet: PUBREC(Q0, R0, D0, PacketId=9, ReasonCode=0)
2024-04-15T13:53:40.506411+00:00 [warning] msg: pubrec_packetId_not_found, mfa: emqx_channel:handle_in/2(440), peername: 10.5.151.4:53158, clientid: 9db7964d-d93b-4cd7-b675-de41ce0d425d, packetId: 9

(I will attach the whole log as a file)

From the log I understood that the broker sends a message to the client via qos 2 and after a minute and twenty seconds the client sends a pubrec to the broker. But for some reason the broker responds with an error to this.
Can you tell me what could be the reason for this behavior?

[keynslug]

Hi @YraganTron,

Looks pretty suspicious indeed. Just to clarify:

1. Do those QoS2 messages carry Message-Expiry-Interval header?
2. Have you configured mqtt.message_expiry_interval parameter to something other than infinity (which is the default)?
3. EMQX version?

[YraganTron]

1. My messages contain this property(Message-Expiry-Interval) with the value 5 seconds
2. I can't change any settings broker
3. 5.3.0

Did I understand correctly that Message-Expiry-Interval is the cause of pubrec_packetId_not_found?

In this case, it is not clear how this should work. If we drop a message using Message-Expiry-Interval, then it shouldn’t continue to hang in the queue, right?

[keynslug]

Did I understand correctly that Message-Expiry-Interval is the cause of pubrec_packetId_not_found?

Most likely, yes.

If we drop a message using Message-Expiry-Interval, then it shouldn’t continue to hang in the queue, right?

I believe it actually doesn't hang in the queue. The message gets allocated Packet ID and delivered right away, skipping any queues, likely because there is still enough space according to the Client's Receive Maximum. Then it expires once these 5 seconds timeout pass, thereby freeing the Packet ID, this is probably why there are warnings when PUBRECs arrive later.