Received packet 'PubAck: [PacketIdentifier=6538] [ReasonCode=Success]' at an unexpected time.

mkb-mb commented 2 weeks ago

Describe the bug

When I publish a relatively large number of messages on the same topic (the number varies) a small percentage of publish calls fail with MqttProtocolViolationException as described in the title. For example, if I send 100,000 messages less than 100 fail, but they all fail with this exception.

I tried updating from 4.3.3.952 to 4.3.7.1207 but the problem persists.

Which component is your bug related to?

Client

To Reproduce

Steps to reproduce the behavior:

Using this version of MQTTnet '...'. 4.3.7.1207
Run this code '....'. I have created a small test program, but it relies on some "wrapper" code that encapsulats the MQTTnet client. I may be able to reproduce the problem without that wrapper code if it would help.

With these arguments '....'. MQTT client construction:

 _mqttFactory = new MqttFactory();
 _mqttClient = _mqttFactory.CreateMqttClient();

 var clientOptions = new MqttClientOptionsBuilder()
    .WithClientId("test program")
    .WithTcpServer("localhost")
    .WithProtocolVersion(MQTTnet.Formatter.MqttProtocolVersion.V500)
    .WithCleanSession()
    .WithWillTopic("test program/status")
    .WithWillQualityOfServiceLevel(MQTTnet.Protocol.MqttQualityOfServiceLevel.AtLeastOnce)
    .WithWillPayload(UTF8Encoding.UTF8.GetBytes("offline"))
    .WithWillRetain(true)
    .Build();

I am running the Mosquitto broker (version 2.0.14) locally.

The specific method that fails is IMqttClient.PublishAsync(MqttApplicationMessage)

Exception details:

2024-09-12 18:16:59.287 -07:00 [ERR] Unexpected exception occurred when publishing message to topic: notification/foo/bar error: Received packet 'PubAck: [PacketIdentifier=6538] [ReasonCode=Success]' at an unexpected time., will try again. MQTTnet.Exceptions.MqttProtocolViolationException: Received packet 'PubAck: [PacketIdentifier=6538] [ReasonCode=Success]' at an unexpected time. at MQTTnet.Client.MqttClient.TryProcessReceivedPacket(MqttPacket packet, CancellationToken cancellationToken) at MQTTnet.PacketDispatcher.MqttPacketAwaitable1.WaitOneAsync(CancellationToken cancellationToken) at MQTTnet.Client.MqttClient.Request[TResponsePacket](MqttPacket requestPacket, CancellationToken cancellationToken) at MQTTnet.Client.MqttClient.Request[TResponsePacket](MqttPacket requestPacket, CancellationToken cancellationToken) at MQTTnet.PacketDispatcher.MqttPacketAwaitable1.WaitOneAsync(CancellationToken cancellationToken) at MQTTnet.Client.MqttClient.Request[TResponsePacket](MqttPacket requestPacket, CancellationToken cancellationToken) at MQTTnet.PacketDispatcher.MqttPacketAwaitable1.WaitOneAsync(CancellationToken cancellationToken) at MQTTnet.Client.MqttClient.Request[TResponsePacket](MqttPacket requestPacket, CancellationToken cancellationToken) at MQTTnet.PacketDispatcher.MqttPacketAwaitable1.WaitOneAsync(CancellationToken cancellationToken) at MQTTnet.PacketDispatcher.MqttPacketAwaitable1.WaitOneAsync(CancellationToken cancellationToken) at MQTTnet.PacketDispatcher.MqttPacketAwaitable1.WaitOneAsync(CancellationToken cancellationToken) at MQTTnet.PacketDispatcher.MqttPacketAwaitable1.WaitOneAsync(CancellationToken cancellationToken) at MQTTnet.PacketDispatcher.MqttPacketAwaitable1.WaitOneAsync(CancellationToken cancellationToken) at MQTTnet.Client.MqttClient.Request[TResponsePacket](MqttPacket requestPacket, CancellationToken cancellationToken) at MQTTnet.Client.MqttClient.Request[TResponsePacket](MqttPacket requestPacket, CancellationToken cancellationToken) at MQTTnet.Client.MqttClient.Request[TResponsePacket](MqttPacket requestPacket, CancellationToken cancellationToken) at MQTTnet.Client.MqttClient.Request[TResponsePacket](MqttPacket requestPacket, CancellationToken cancellationToken) at MQTTnet.PacketDispatcher.MqttPacketAwaitable`1.WaitOneAsync(CancellationToken cancellationToken) at MQTTnet.Client.MqttClient.Request[TResponsePacket](MqttPacket requestPacket, CancellationToken cancellationToken) at MQTTnet.Client.MqttClient.Request[TResponsePacket](MqttPacket requestPacket, CancellationToken cancellationToken) at MQTTnet.Client.MqttClient.Request[TResponsePacket](MqttPacket requestPacket, CancellationToken cancellationToken) at MQTTnet.Client.MqttClient.PublishAtLeastOnce(MqttPublishPacket publishPacket, CancellationToken cancellationToken)

See error.

Expected behavior

I expect all published messages to be published (so they can be received by subscribers).

mkb-mb commented 2 weeks ago

I created a smaller sample program (see attached code). I updated to MQTTnet 4.3.7.1207 and Mosquitto 2.0.18a.

Behavior is inconsistent. Without debugger (VS 2022 Pro) the code runs reasonably quick with no recorded errors even if I run 500,000 messages through the broker. With debugger the code runs much more slowly.

I tried enabling broker logging, but even when errors were common there was nothing in the broker log that indicated there were any problems.

The attached code is built as a C# .NET6 console application. The MQTT broker runs locally (same laptop). Program.cs.txt

mkb-mb commented 2 weeks ago

I also observed the same errors when I tried self-hosting the broker using MQTTnet.

mkb-mb commented 1 week ago

The attached code triggers at least one disconnect and eventually stops receiving messages.

Program.cs.txt

mkb-mb commented 4 days ago

Seems to be related to #2078

dotnet / MQTTnet