MQTTnet
MQTTnet copied to clipboard
Published
20 hours ago •
dotnet
dotnet
SynchronizingSubscriptionsFailedHandler fires endlessly
Hi!
Last week I upgraded MQTTnet from v2.8.5 to v3.0.4.
Running my first long-term test, after a few hours the system ran into something looking like an endless loop firing the SynchronizingSubscriptionsFailedHandler event over and over again.
I am using the ManagedMqttClient and my test was running on linux on arm.
The log file looks as follows (I added some comments to let you know which message is printed in which handler):
...
[2019-06-28 06:28:59 INF Mqtt ] DISCONNECTED from MQTT server: Received packet 'PubAck: [PacketIdentifier=19] [ReasonCode=]' at an unexpected time.
[2019-06-28 06:29:00 INF Mqtt ] DISCONNECTED from MQTT server.
[2019-06-28 06:29:10 INF Mqtt ] CONNECTING FAILED to MQTT server (timeout).
[2019-06-28 06:29:40 INF Mqtt ] CONNECTED to MQTT server
[2019-06-28 06:47:39 INF Mqtt ] DISCONNECTED from MQTT server: Received packet 'PubAck: [PacketIdentifier=20] [ReasonCode=]' at an unexpected time.
[2019-06-28 06:47:50 INF Mqtt ] CONNECTING FAILED to MQTT server (timeout).
[2019-06-28 06:47:50 INF Mqtt ] DISCONNECTED from MQTT server (timeout).
[2019-06-28 06:48:31 INF Mqtt ] DISCONNECTED from MQTT server (timeout). // <- This is logged in the DisconnectedHandler (with exception type MqttCommunicationTimedOutException)
[2019-06-28 06:48:31 INF Mqtt ] CONNECTING FAILED to MQTT server (timeout). // <- This is logged in the ConnectingFailedHandler (with exception type MqttCommunicationTimedOutException)
[2019-06-28 06:49:01 INF Mqtt ] CONNECTED to MQTT server
[2019-06-28 07:04:01 INF Mqtt ] DISCONNECTED from MQTT server: Received packet 'PubAck: [PacketIdentifier=21] [ReasonCode=]' at an unexpected time.
[2019-06-28 07:04:02 INF Mqtt ] DISCONNECTED from MQTT server.
[2019-06-28 07:04:12 INF Mqtt ] CONNECTING FAILED to MQTT server (timeout).
[2019-06-28 07:04:42 INF Mqtt ] CONNECTED to MQTT server
[2019-06-28 07:08:28 INF Mqtt ] DISCONNECTED from MQTT server: Received packet 'PubAck: [PacketIdentifier=22] [ReasonCode=]' at an unexpected time.
[2019-06-28 07:08:33 INF Mqtt ] CONNECTED to MQTT server
[2019-06-28 07:08:35 INF Mqtt ] DISCONNECTED from MQTT server: Received packet 'PubAck: [PacketIdentifier=24] [ReasonCode=]' at an unexpected time.
[2019-06-28 07:08:36 INF Mqtt ] CONNECTED to MQTT server
[2019-06-28 07:08:37 INF Mqtt ] DISCONNECTED from MQTT server: Received packet 'PubAck: [PacketIdentifier=25] [ReasonCode=]' at an unexpected time.
[2019-06-28 07:08:38 INF Mqtt ] CONNECTED to MQTT server
[2019-06-28 07:08:39 INF Mqtt ] DISCONNECTED from MQTT server: Received packet 'PubAck: [PacketIdentifier=26] [ReasonCode=]' at an unexpected time.
[2019-06-28 07:08:40 INF Mqtt ] CONNECTED to MQTT server
[2019-06-28 07:08:41 INF Mqtt ] DISCONNECTED from MQTT server: Received packet 'PubAck: [PacketIdentifier=27] [ReasonCode=]' at an unexpected time.
[2019-06-28 07:08:42 INF Mqtt ] CONNECTED to MQTT server
[2019-06-28 07:08:43 INF Mqtt ] DISCONNECTED from MQTT server: Received packet 'PubAck: [PacketIdentifier=28] [ReasonCode=]' at an unexpected time.
[2019-06-28 07:08:44 INF Mqtt ] CONNECTED to MQTT server
[2019-06-28 07:08:46 INF Mqtt ] DISCONNECTED from MQTT server: Received packet 'PubAck: [PacketIdentifier=30] [ReasonCode=]' at an unexpected time.
[2019-06-28 07:08:47 INF Mqtt ] CONNECTED to MQTT server
[2019-06-28 07:08:48 INF Mqtt ] DISCONNECTED from MQTT server: Received packet 'PubAck: [PacketIdentifier=31] [ReasonCode=]' at an unexpected time.
[2019-06-28 07:08:49 INF Mqtt ] CONNECTED to MQTT server
[2019-06-28 07:08:50 INF Mqtt ] DISCONNECTED from MQTT server: Received packet 'PubAck: [PacketIdentifier=32] [ReasonCode=]' at an unexpected time.
[2019-06-28 07:08:52 INF Mqtt ] CONNECTED to MQTT server // <- This is logged in the ConnectedHandler
[2019-06-28 07:08:52 INF Mqtt ] DISCONNECTED from MQTT server: Received packet 'PubAck: [PacketIdentifier=33] [ReasonCode=]' at an unexpected time. // <- This is logged in the DisconnectedHandler ("Received packet 'PubAck: [PacketIdentifier=33] [ReasonCode=]' at an unexpected time." is the exception message)
[2019-06-28 07:08:52 WRN Mqtt ] MQTT synchronizing subscriptions failed: The client is not connected.' // <- This is logged in the SynchronizingSubscriptionsFailedHandler ("The client is not connected." is the exception message)
[2019-06-28 07:08:52 WRN Mqtt ] MQTT synchronizing subscriptions failed: The client is not connected.'
[2019-06-28 07:08:52 WRN Mqtt ] MQTT synchronizing subscriptions failed: The client is not connected.'
[2019-06-28 07:08:52 WRN Mqtt ] MQTT synchronizing subscriptions failed: The client is not connected.'
[2019-06-28 07:08:52 WRN Mqtt ] MQTT synchronizing subscriptions failed: The client is not connected.'
[2019-06-28 07:08:52 WRN Mqtt ] MQTT synchronizing subscriptions failed: The client is not connected.'
[2019-06-28 07:08:52 WRN Mqtt ] MQTT synchronizing subscriptions failed: The client is not connected.'
[2019-06-28 07:08:52 WRN Mqtt ] MQTT synchronizing subscriptions failed: The client is not connected.'
[2019-06-28 07:08:52 WRN Mqtt ] MQTT synchronizing subscriptions failed: The client is not connected.'
[2019-06-28 07:08:52 WRN Mqtt ] MQTT synchronizing subscriptions failed: The client is not connected.'
[2019-06-28 07:08:52 WRN Mqtt ] MQTT synchronizing subscriptions failed: The client is not connected.'
[2019-06-28 07:08:52 WRN Mqtt ] MQTT synchronizing subscriptions failed: The client is not connected.'
[2019-06-28 07:08:52 WRN Mqtt ] MQTT synchronizing subscriptions failed: The client is not connected.'
[2019-06-28 07:08:52 WRN Mqtt ] MQTT synchronizing subscriptions failed: The client is not connected.'
[2019-06-28 07:08:52 WRN Mqtt ] MQTT synchronizing subscriptions failed: The client is not connected.'
[2019-06-28 07:08:52 WRN Mqtt ] MQTT synchronizing subscriptions failed: The client is not connected.'
[2019-06-28 07:08:52 WRN Mqtt ] MQTT synchronizing subscriptions failed: The client is not connected.'
[2019-06-28 07:08:52 WRN Mqtt ] MQTT synchronizing subscriptions failed: The client is not connected.'
[2019-06-28 07:08:52 WRN Mqtt ] MQTT synchronizing subscriptions failed: The client is not connected.'
... (this is repeated many times per second for days)
Do you have any idea what is going wrong here? Did I something wrong when upgrading? The only things I changed were the event handlers and some namespaces.
Please let me know if you need some more information. Unfortunately I cannot reproduce the behavior at the moment. Before the upgrade it was running fine for month.
Hi, sorry but I never saw this before. Which transport to you use? WebSockets? Even if the disconnect happens the following tries to subscribe are wrong.
Is it possible to share a small snipped? Then I can see how you setup everything.
Best regards Christian
Hi Christan,
thank you for your reply! I am using TCP+TLS as transport layer.
Please find my setup code here:
ManagedMqttClientOptions options = new ManagedMqttClientOptionsBuilder()
.WithAutoReconnectDelay(TimeSpan.FromSeconds(30))
.WithClientOptions(new MqttClientOptionsBuilder()
.WithClientId(...)
.WithTcpServer(..., ...)
.WithTls()
.WithCredentials(..., ...)
.WithCommunicationTimeout(TimeSpan.FromSeconds(10))
.WithKeepAlivePeriod(TimeSpan.FromSeconds(15))
.WithKeepAliveSendInterval(TimeSpan.FromSeconds(10))
.Build())
.Build();
mqttClient = new MqttFactory().CreateManagedMqttClient();
mqttClient.ApplicationMessageProcessedHandler = new ApplicationMessageProcessedHandlerDelegate((Action<ApplicationMessageProcessedEventArgs>)OnApplicationMessageProcessed);
mqttClient.ApplicationMessageSkippedHandler = new ApplicationMessageSkippedHandlerDelegate((Action<ApplicationMessageSkippedEventArgs>)OnApplicationMessageSkipped);
mqttClient.SynchronizingSubscriptionsFailedHandler = new SynchronizingSubscriptionsFailedHandlerDelegate((Action<ManagedProcessFailedEventArgs>)OnSynchronizingSubscriptionsFailed);
mqttClient.ApplicationMessageReceivedHandler = new MqttApplicationMessageReceivedHandlerDelegate((Action<MqttApplicationMessageReceivedEventArgs>)ReceivedMessageHandler);
mqttClient.ConnectedHandler = new MqttClientConnectedHandlerDelegate((Action<MqttClientConnectedEventArgs>)OnConnected);
mqttClient.DisconnectedHandler = new MqttClientDisconnectedHandlerDelegate((Action<MqttClientDisconnectedEventArgs>)OnDisconnected);
mqttClient.ConnectingFailedHandler = new ConnectingFailedHandlerDelegate((Action<ManagedProcessFailedEventArgs>)OnConnectingFailed);
await mqttClient.StartAsync(options).ConfigureAwait(false);
await mqttClient.SubscribeAsync("topic1").ConfigureAwait(false);
await mqttClient.SubscribeAsync("topic2").ConfigureAwait(false);
In the first call of the OnConnected event I subscribe to more topics after a short waiting period (due to a server issue I cannot subscribe to them before connecting):
private async void OnConnected(MqttClientConnectedEventArgs e)
{
logger.LogInformation("CONNECTED to MQTT server");
if (isConnectedFirst) { RegisterCommandSubscriptions(); }
isConnectedFirst = false;
}
public void RegisterCommandSubscriptions()
{
new System.Threading.Thread(() =>
{
System.Threading.Thread.CurrentThread.IsBackground = true;
System.Threading.Thread.Sleep(10000);
mqttClient.SubscribeAsync("topic3").ConfigureAwait(false);
mqttClient.SubscribeAsync("topic4").ConfigureAwait(false);
}).Start();
}
Thank you for your help!
Best regards Stefan
First of all: Please do not mix async (Tasks) with Threads. So please change new Thread... to Task.Run using proper await statements.
What are you doing here is that you start a thread and that thread starts 2(!) tasks for the subscriptions. These tasks are not awaited. This means they run in parallel. So when the client is disconnected they are still running and throwing exceptions. And you are starting them on every connect. So every connect starts 2 tasks which are not awaited.
Hi Christan,
I agree with you that it is no good idea mixing aync with threads. This is a remainder of the former v2 implementation and I will fix that. But apart from being bad style it should still work, shouldn't it? Or do I run into some synchronization problems inside your lib?
What I can't see is that I start the command registrations on every connect. This should be prevented due to the isConnectedFirst flag. Therefore I don't think that the cause of my initial problem lays here.
Best regards Stefan
I agree that this is probably not the root cause but wrong usage of async/await leads to lot of unexpected behavior. And you are the very first person with this problem. I also have Xamarin Apps etc. using this Lib and this is the first time I see this. So there is a big chance that this is the problem.
But I will also try to find a another reason...l
About five weeks ago I finally had the chance to test the changes I made (no longer mixing async with threads, updating to MQTTnet 3.0.5). I set up two long term tests, one on linux on arm and the other on windows ten, both communicating with the same mqtt server. For five weeks everything went fine, but on friday both of my test set-ups failed with the symptoms as described above.
Part of the first log file (linux on arm):
[2019-08-30 13:02:29 INF Mqtt ] CONNECTED to MQTT server
[2019-08-30 13:02:30 INF Mqtt ] DISCONNECTED from MQTT server: 'Received packet 'PubAck: [PacketIdentifier=3] [ReasonCode=]' at an unexpected time.'
[2019-08-30 13:02:30 WRN Mqtt ] MQTT synchronizing subscriptions failed: 'Received packet 'PubAck: [PacketIdentifier=3] [ReasonCode=]' at an unexpected time.'
[2019-08-30 13:02:31 INF Mqtt ] CONNECTED to MQTT server
[2019-08-30 13:02:41 WRN Mqtt ] MQTT synchronizing subscriptions failed: 'Exception of type 'MQTTnet.Exceptions.MqttCommunicationTimedOutException' was thrown.'
[2019-08-30 13:02:51 WRN Mqtt ] MQTT synchronizing subscriptions failed: 'Exception of type 'MQTTnet.Exceptions.MqttCommunicationTimedOutException' was thrown.'
[2019-08-30 13:03:01 WRN Mqtt ] MQTT synchronizing subscriptions failed: 'Exception of type 'MQTTnet.Exceptions.MqttCommunicationTimedOutException' was thrown.'
[2019-08-30 13:03:11 WRN Mqtt ] MQTT synchronizing subscriptions failed: 'Exception of type 'MQTTnet.Exceptions.MqttCommunicationTimedOutException' was thrown.'
[2019-08-30 13:03:21 WRN Mqtt ] MQTT synchronizing subscriptions failed: 'Exception of type 'MQTTnet.Exceptions.MqttCommunicationTimedOutException' was thrown.'
[2019-08-30 13:03:31 WRN Mqtt ] MQTT synchronizing subscriptions failed: 'Exception of type 'MQTTnet.Exceptions.MqttCommunicationTimedOutException' was thrown.'
[2019-08-30 13:03:41 WRN Mqtt ] MQTT synchronizing subscriptions failed: 'Exception of type 'MQTTnet.Exceptions.MqttCommunicationTimedOutException' was thrown.'
[2019-08-30 13:03:51 WRN Mqtt ] MQTT synchronizing subscriptions failed: 'Exception of type 'MQTTnet.Exceptions.MqttCommunicationTimedOutException' was thrown.'
[2019-08-30 13:04:01 WRN Mqtt ] MQTT synchronizing subscriptions failed: 'Exception of type 'MQTTnet.Exceptions.MqttCommunicationTimedOutException' was thrown.'
[2019-08-30 13:04:11 WRN Mqtt ] MQTT synchronizing subscriptions failed: 'Exception of type 'MQTTnet.Exceptions.MqttCommunicationTimedOutException' was thrown.'
[2019-08-30 13:04:21 WRN Mqtt ] MQTT synchronizing subscriptions failed: 'Exception of type 'MQTTnet.Exceptions.MqttCommunicationTimedOutException' was thrown.'
[2019-08-30 13:04:31 WRN Mqtt ] MQTT synchronizing subscriptions failed: 'Exception of type 'MQTTnet.Exceptions.MqttCommunicationTimedOutException' was thrown.'
[2019-08-30 13:04:41 WRN Mqtt ] MQTT synchronizing subscriptions failed: 'Exception of type 'MQTTnet.Exceptions.MqttCommunicationTimedOutException' was thrown.'
[2019-08-30 13:04:46 INF Mqtt ] DISCONNECTED from MQTT server: 'Received packet 'PubAck: [PacketIdentifier=23] [ReasonCode=]' at an unexpected time.'
[2019-08-30 13:04:46 WRN Mqtt ] MQTT synchronizing subscriptions failed: 'Received packet 'PubAck: [PacketIdentifier=23] [ReasonCode=]' at an unexpected time.'
[2019-08-30 13:04:53 INF Mqtt ] CONNECTED to MQTT server
[2019-08-30 13:10:40 INF Mqtt ] DISCONNECTED from MQTT server: 'Received packet 'PubAck: [PacketIdentifier=30] [ReasonCode=]' at an unexpected time.'
[2019-08-30 13:10:47 INF Mqtt ] CONNECTED to MQTT server
[2019-08-30 13:13:30 INF Mqtt ] DISCONNECTED from MQTT server: 'Received packet 'PubAck: [PacketIdentifier=13] [ReasonCode=]' at an unexpected time.'
[2019-08-30 13:13:36 INF Mqtt ] CONNECTED to MQTT server
[2019-08-30 13:16:23 INF Mqtt ] DISCONNECTED from MQTT server: 'Received packet 'PubAck: [PacketIdentifier=15] [ReasonCode=]' at an unexpected time.'
[2019-08-30 13:16:25 INF Mqtt ] CONNECTED to MQTT server
[2019-08-30 13:16:26 INF Mqtt ] DISCONNECTED from MQTT server: 'Received packet 'PubAck: [PacketIdentifier=16] [ReasonCode=]' at an unexpected time.'
[2019-08-30 13:16:28 INF Mqtt ] CONNECTED to MQTT server
[2019-08-30 13:16:29 INF Mqtt ] DISCONNECTED from MQTT server: 'Received packet 'PubAck: [PacketIdentifier=2] [ReasonCode=]' at an unexpected time.'
[2019-08-30 13:16:31 INF Mqtt ] CONNECTED to MQTT server
[2019-08-30 13:18:48 INF Mqtt ] DISCONNECTED from MQTT server (timeout).
[2019-08-30 13:18:50 INF Mqtt ] CONNECTED to MQTT server
[2019-08-30 13:21:26 INF Mqtt ] DISCONNECTED from MQTT server: 'Received packet 'PubAck: [PacketIdentifier=15] [ReasonCode=]' at an unexpected time.'
[2019-08-30 13:21:27 INF Mqtt ] CONNECTED to MQTT server
[2019-08-30 13:21:31 INF Mqtt ] DISCONNECTED from MQTT server: 'Received packet 'PubAck: [PacketIdentifier=16] [ReasonCode=]' at an unexpected time.'
[2019-08-30 13:21:33 INF Mqtt ] CONNECTED to MQTT server
[2019-08-30 13:21:38 INF Mqtt ] DISCONNECTED from MQTT server: 'Received packet 'PubAck: [PacketIdentifier=2] [ReasonCode=]' at an unexpected time.'
[2019-08-30 13:21:38 INF Mqtt ] DISCONNECTED from MQTT server: 'Object reference not set to an instance of an object.'
[2019-08-30 13:21:38 ERR Mqtt ] CONNECTING FAILED to MQTT server: 'Object reference not set to an instance of an object.'
[2019-08-30 13:22:12 INF Mqtt ] CONNECTED to MQTT server
[2019-08-30 13:23:55 INF Mqtt ] DISCONNECTED from MQTT server: 'Received packet 'PubAck: [PacketIdentifier=15] [ReasonCode=]' at an unexpected time.'
[2019-08-30 13:24:05 INF Mqtt ] DISCONNECTED from MQTT server (timeout).
[2019-08-30 13:24:05 INF Mqtt ] CONNECTING FAILED to MQTT server (timeout).
[2019-08-30 13:24:37 INF Mqtt ] CONNECTED to MQTT server
[2019-08-30 13:29:26 INF Mqtt ] DISCONNECTED from MQTT server: 'Received packet 'PubAck: [PacketIdentifier=28] [ReasonCode=]' at an unexpected time.'
[2019-08-30 13:29:31 INF Mqtt ] CONNECTED to MQTT server
[2019-08-30 13:29:35 INF Mqtt ] DISCONNECTED from MQTT server: 'Received packet 'PubAck: [PacketIdentifier=29] [ReasonCode=]' at an unexpected time.'
[2019-08-30 13:29:41 INF Mqtt ] CONNECTED to MQTT server
[2019-08-30 13:55:41 INF Mqtt ] DISCONNECTED from MQTT server: 'Received packet 'PubAck: [PacketIdentifier=98] [ReasonCode=]' at an unexpected time.'
[2019-08-30 13:55:45 INF Mqtt ] CONNECTED to MQTT server
[2019-08-30 13:55:59 INF Mqtt ] DISCONNECTED from MQTT server: 'Received packet 'PubAck: [PacketIdentifier=2] [ReasonCode=]' at an unexpected time.'
[2019-08-30 13:56:01 INF Mqtt ] CONNECTED to MQTT server
[2019-08-30 13:56:02 INF Mqtt ] DISCONNECTED from MQTT server: 'Received packet 'PubAck: [PacketIdentifier=3] [ReasonCode=]' at an unexpected time.'
[2019-08-30 13:56:03 INF Mqtt ] CONNECTED to MQTT server
[2019-08-30 13:56:05 INF Mqtt ] DISCONNECTED from MQTT server: 'Received packet 'PubAck: [PacketIdentifier=2] [ReasonCode=]' at an unexpected time.'
[2019-08-30 13:56:05 INF Mqtt ] DISCONNECTED from MQTT server: 'Object reference not set to an instance of an object.'
[2019-08-30 13:56:05 ERR Mqtt ] CONNECTING FAILED to MQTT server: 'Object reference not set to an instance of an object.'
[2019-08-30 13:56:38 INF Mqtt ] CONNECTED to MQTT server
[2019-08-30 14:01:42 INF Mqtt ] DISCONNECTED from MQTT server: 'Received packet 'PubAck: [PacketIdentifier=27] [ReasonCode=]' at an unexpected time.'
[2019-08-30 14:01:46 INF Mqtt ] CONNECTED to MQTT server
[2019-08-30 14:04:42 INF Mqtt ] DISCONNECTED from MQTT server: 'Received packet 'PubAck: [PacketIdentifier=14] [ReasonCode=]' at an unexpected time.'
[2019-08-30 14:04:45 INF Mqtt ] CONNECTED to MQTT server
[2019-08-30 14:04:52 INF Mqtt ] DISCONNECTED from MQTT server: 'Received packet 'PubAck: [PacketIdentifier=15] [ReasonCode=]' at an unexpected time.'
[2019-08-30 14:04:53 INF Mqtt ] CONNECTED to MQTT server
[2019-08-30 14:04:56 INF Mqtt ] DISCONNECTED from MQTT server: 'Received packet 'PubAck: [PacketIdentifier=2] [ReasonCode=]' at an unexpected time.'
[2019-08-30 14:04:57 INF Mqtt ] CONNECTED to MQTT server
[2019-08-30 14:05:40 INF Mqtt ] CONNECTING FAILED to MQTT server (timeout).
[2019-08-30 14:06:10 INF Mqtt ] CONNECTED to MQTT server
[2019-08-30 14:07:12 INF Mqtt ] DISCONNECTED from MQTT server: 'Received packet 'PubAck: [PacketIdentifier=12] [ReasonCode=]' at an unexpected time.'
[2019-08-30 14:07:18 INF Mqtt ] CONNECTED to MQTT server
[2019-08-30 14:10:11 INF Mqtt ] DISCONNECTED from MQTT server: 'Received packet 'PubAck: [PacketIdentifier=19] [ReasonCode=]' at an unexpected time.'
[2019-08-30 14:10:13 INF Mqtt ] CONNECTED to MQTT server
[2019-08-30 14:10:14 INF Mqtt ] DISCONNECTED from MQTT server: 'Received packet 'PubAck: [PacketIdentifier=20] [ReasonCode=]' at an unexpected time.'
[2019-08-30 14:10:14 WRN Mqtt ] MQTT synchronizing subscriptions failed: 'Received packet 'PubAck: [PacketIdentifier=20] [ReasonCode=]' at an unexpected time.'
[2019-08-30 14:10:15 INF Mqtt ] CONNECTED to MQTT server
[2019-08-30 14:13:13 INF Mqtt ] DISCONNECTED from MQTT server: 'Received packet 'PubAck: [PacketIdentifier=20] [ReasonCode=]' at an unexpected time.'
[2019-08-30 14:13:14 INF Mqtt ] CONNECTED to MQTT server
[2019-08-30 14:13:26 INF Mqtt ] DISCONNECTED from MQTT server: 'Received packet 'PubAck: [PacketIdentifier=21] [ReasonCode=]' at an unexpected time.'
[2019-08-30 14:13:33 INF Mqtt ] CONNECTED to MQTT server
[2019-08-30 14:16:28 INF Mqtt ] DISCONNECTED from MQTT server (timeout).
[2019-08-30 14:16:30 INF Mqtt ] CONNECTED to MQTT server
[2019-08-30 14:18:51 INF Mqtt ] DISCONNECTED from MQTT server (timeout).
[2019-08-30 14:18:54 INF Mqtt ] CONNECTED to MQTT server
[2019-08-30 14:19:04 INF Mqtt ] DISCONNECTED from MQTT server: 'Received packet 'PubAck: [PacketIdentifier=17] [ReasonCode=]' at an unexpected time.'
[2019-08-30 14:19:06 INF Mqtt ] CONNECTED to MQTT server
[2019-08-30 14:19:07 INF Mqtt ] DISCONNECTED from MQTT server: 'Received packet 'PubAck: [PacketIdentifier=2] [ReasonCode=]' at an unexpected time.'
[2019-08-30 14:19:07 WRN Mqtt ] MQTT synchronizing subscriptions failed: 'Received packet 'PubAck: [PacketIdentifier=2] [ReasonCode=]' at an unexpected time.'
[2019-08-30 14:19:09 INF Mqtt ] CONNECTED to MQTT server
[2019-08-30 14:21:33 INF Mqtt ] DISCONNECTED from MQTT server (timeout).
[2019-08-30 14:21:35 INF Mqtt ] CONNECTED to MQTT server
[2019-08-30 14:29:57 INF Mqtt ] DISCONNECTED from MQTT server: 'Received packet 'PubAck: [PacketIdentifier=50] [ReasonCode=]' at an unexpected time.'
[2019-08-30 14:29:58 INF Mqtt ] CONNECTED to MQTT server
[2019-08-30 14:30:00 INF Mqtt ] DISCONNECTED from MQTT server: 'Received packet 'PubAck: [PacketIdentifier=51] [ReasonCode=]' at an unexpected time.'
[2019-08-30 14:30:00 WRN Mqtt ] MQTT synchronizing subscriptions failed: 'Object reference not set to an instance of an object.'
[2019-08-30 14:30:02 INF Mqtt ] CONNECTED to MQTT server
[2019-08-30 14:35:42 INF Mqtt ] DISCONNECTED from MQTT server: 'Received packet 'PubAck: [PacketIdentifier=37] [ReasonCode=]' at an unexpected time.'
[2019-08-30 14:35:50 INF Mqtt ] CONNECTED to MQTT server
[2019-08-30 14:36:22 INF Mqtt ] DISCONNECTED from MQTT server: 'Received packet 'PubAck: [PacketIdentifier=2] [ReasonCode=]' at an unexpected time.'
[2019-08-30 14:36:26 INF Mqtt ] CONNECTED to MQTT server
[2019-08-30 14:36:27 WRN Mqtt ] MQTT synchronizing subscriptions failed: 'Received packet 'PubAck: [PacketIdentifier=4] [ReasonCode=]' at an unexpected time.'
[2019-08-30 14:36:27 INF Mqtt ] DISCONNECTED from MQTT server: 'Received packet 'PubAck: [PacketIdentifier=4] [ReasonCode=]' at an unexpected time.'
[2019-08-30 14:36:27 INF Mqtt ] DISCONNECTED from MQTT server: 'Object reference not set to an instance of an object.'
[2019-08-30 14:36:27 ERR Mqtt ] CONNECTING FAILED to MQTT server: 'Object reference not set to an instance of an object.'
[2019-08-30 14:36:58 INF Mqtt ] CONNECTED to MQTT server
[2019-08-30 14:39:27 INF Mqtt ] DISCONNECTED from MQTT server: 'Received packet 'PubAck: [PacketIdentifier=26] [ReasonCode=]' at an unexpected time.'
[2019-08-30 14:39:30 INF Mqtt ] DISCONNECTED from MQTT server: 'Received packet 'PubAck: [PacketIdentifier=27] [ReasonCode=]' at an unexpected time.'
[2019-08-30 14:39:30 INF Mqtt ] CONNECTED to MQTT server
[2019-08-30 14:39:30 WRN Mqtt ] MQTT synchronizing subscriptions failed: 'The client is not connected.'
[2019-08-30 14:39:30 WRN Mqtt ] MQTT synchronizing subscriptions failed: 'The client is not connected.'
[2019-08-30 14:39:30 WRN Mqtt ] MQTT synchronizing subscriptions failed: 'The client is not connected.'
[2019-08-30 14:39:30 WRN Mqtt ] MQTT synchronizing subscriptions failed: 'The client is not connected.'
[2019-08-30 14:39:30 WRN Mqtt ] MQTT synchronizing subscriptions failed: 'The client is not connected.'
[2019-08-30 14:39:30 WRN Mqtt ] MQTT synchronizing subscriptions failed: 'The client is not connected.'
[2019-08-30 14:39:30 WRN Mqtt ] MQTT synchronizing subscriptions failed: 'The client is not connected.'
[2019-08-30 14:39:30 WRN Mqtt ] MQTT synchronizing subscriptions failed: 'The client is not connected.'
[2019-08-30 14:39:30 WRN Mqtt ] MQTT synchronizing subscriptions failed: 'The client is not connected.'
Part of the second log file (windows 10):
[2019-08-30 06:14:15 INF Mqtt ] CONNECTED to MQTT server
[2019-08-30 06:14:16 WRN Mqtt ] MQTT synchronizing subscriptions failed: 'Received packet 'PubAck: [PacketIdentifier=3] [ReasonCode=]' at an unexpected time.'
[2019-08-30 06:14:16 INF Mqtt ] DISCONNECTED from MQTT server: 'Received packet 'PubAck: [PacketIdentifier=3] [ReasonCode=]' at an unexpected time.'
[2019-08-30 06:14:17 INF Mqtt ] CONNECTED to MQTT server
[2019-08-30 06:14:27 WRN Mqtt ] MQTT synchronizing subscriptions failed: 'Exception of type 'MQTTnet.Exceptions.MqttCommunicationTimedOutException' was thrown.'
[2019-08-30 06:14:37 WRN Mqtt ] MQTT synchronizing subscriptions failed: 'Exception of type 'MQTTnet.Exceptions.MqttCommunicationTimedOutException' was thrown.'
[2019-08-30 06:14:47 WRN Mqtt ] MQTT synchronizing subscriptions failed: 'Exception of type 'MQTTnet.Exceptions.MqttCommunicationTimedOutException' was thrown.'
[2019-08-30 06:14:57 WRN Mqtt ] MQTT synchronizing subscriptions failed: 'Exception of type 'MQTTnet.Exceptions.MqttCommunicationTimedOutException' was thrown.'
[2019-08-30 06:15:07 WRN Mqtt ] MQTT synchronizing subscriptions failed: 'Exception of type 'MQTTnet.Exceptions.MqttCommunicationTimedOutException' was thrown.'
[2019-08-30 06:15:17 WRN Mqtt ] MQTT synchronizing subscriptions failed: 'Exception of type 'MQTTnet.Exceptions.MqttCommunicationTimedOutException' was thrown.'
[2019-08-30 06:15:27 WRN Mqtt ] MQTT synchronizing subscriptions failed: 'Exception of type 'MQTTnet.Exceptions.MqttCommunicationTimedOutException' was thrown.'
[2019-08-30 06:15:37 WRN Mqtt ] MQTT synchronizing subscriptions failed: 'Exception of type 'MQTTnet.Exceptions.MqttCommunicationTimedOutException' was thrown.'
[2019-08-30 06:15:47 WRN Mqtt ] MQTT synchronizing subscriptions failed: 'Exception of type 'MQTTnet.Exceptions.MqttCommunicationTimedOutException' was thrown.'
[2019-08-30 06:15:57 WRN Mqtt ] MQTT synchronizing subscriptions failed: 'Exception of type 'MQTTnet.Exceptions.MqttCommunicationTimedOutException' was thrown.'
[2019-08-30 06:16:07 WRN Mqtt ] MQTT synchronizing subscriptions failed: 'Exception of type 'MQTTnet.Exceptions.MqttCommunicationTimedOutException' was thrown.'
[2019-08-30 06:16:17 WRN Mqtt ] MQTT synchronizing subscriptions failed: 'Exception of type 'MQTTnet.Exceptions.MqttCommunicationTimedOutException' was thrown.'
[2019-08-30 06:16:27 WRN Mqtt ] MQTT synchronizing subscriptions failed: 'Exception of type 'MQTTnet.Exceptions.MqttCommunicationTimedOutException' was thrown.'
[2019-08-30 06:16:32 WRN Mqtt ] MQTT synchronizing subscriptions failed: 'Received packet 'PubAck: [PacketIdentifier=66] [ReasonCode=]' at an unexpected time.'
[2019-08-30 06:16:42 INF Mqtt ] CONNECTING FAILED to MQTT server (timeout).
[2019-08-30 06:17:13 INF Mqtt ] CONNECTED to MQTT server
[2019-08-30 06:19:11 INF Mqtt ] DISCONNECTED from MQTT server: 'Received packet 'PubAck: [PacketIdentifier=51] [ReasonCode=]' at an unexpected time.'
[2019-08-30 06:19:13 INF Mqtt ] CONNECTED to MQTT server
[2019-08-30 06:19:14 INF Mqtt ] DISCONNECTED from MQTT server: 'Received packet 'PubAck: [PacketIdentifier=52] [ReasonCode=]' at an unexpected time.'
[2019-08-30 06:19:16 INF Mqtt ] CONNECTED to MQTT server
[2019-08-30 06:19:18 INF Mqtt ] DISCONNECTED from MQTT server: 'Received packet 'PubAck: [PacketIdentifier=2] [ReasonCode=]' at an unexpected time.'
[2019-08-30 06:19:19 INF Mqtt ] CONNECTED to MQTT server
[2019-08-30 06:19:20 INF Mqtt ] DISCONNECTED from MQTT server: 'Received packet 'PubAck: [PacketIdentifier=3] [ReasonCode=]' at an unexpected time.'
[2019-08-30 06:19:21 INF Mqtt ] CONNECTED to MQTT server
[2019-08-30 06:21:30 INF Mqtt ] DISCONNECTED from MQTT server (timeout).
[2019-08-30 06:21:32 INF Mqtt ] CONNECTED to MQTT server
[2019-08-30 06:24:04 INF Mqtt ] DISCONNECTED from MQTT server: 'Received packet 'PubAck: [PacketIdentifier=46] [ReasonCode=]' at an unexpected time.'
[2019-08-30 06:24:05 INF Mqtt ] CONNECTED to MQTT server
[2019-08-30 06:26:05 INF Mqtt ] DISCONNECTED from MQTT server: 'Received packet 'PubAck: [PacketIdentifier=43] [ReasonCode=]' at an unexpected time.'
[2019-08-30 06:26:08 INF Mqtt ] CONNECTED to MQTT server
[2019-08-30 06:26:10 INF Mqtt ] DISCONNECTED from MQTT server: 'Received packet 'PubAck: [PacketIdentifier=44] [ReasonCode=]' at an unexpected time.'
[2019-08-30 06:26:11 INF Mqtt ] CONNECTED to MQTT server
[2019-08-30 06:26:15 INF Mqtt ] DISCONNECTED from MQTT server: 'Received packet 'PubAck: [PacketIdentifier=2] [ReasonCode=]' at an unexpected time.'
[2019-08-30 06:26:15 WRN Mqtt ] MQTT synchronizing subscriptions failed: 'Received packet 'PubAck: [PacketIdentifier=2] [ReasonCode=]' at an unexpected time.'
[2019-08-30 06:26:23 INF Mqtt ] CONNECTED to MQTT server
[2019-08-30 06:31:23 INF Mqtt ] DISCONNECTED from MQTT server: 'Received packet 'PubAck: [PacketIdentifier=103] [ReasonCode=]' at an unexpected time.'
[2019-08-30 06:31:30 INF Mqtt ] CONNECTED to MQTT server
[2019-08-30 06:38:49 INF Mqtt ] DISCONNECTED from MQTT server: 'Received packet 'PubAck: [PacketIdentifier=145] [ReasonCode=]' at an unexpected time.'
[2019-08-30 06:38:50 INF Mqtt ] CONNECTED to MQTT server
[2019-08-30 06:41:38 INF Mqtt ] DISCONNECTED from MQTT server: 'Received packet 'PubAck: [PacketIdentifier=58] [ReasonCode=]' at an unexpected time.'
[2019-08-30 06:41:42 INF Mqtt ] CONNECTED to MQTT server
[2019-08-30 06:41:46 INF Mqtt ] DISCONNECTED from MQTT server: 'Received packet 'PubAck: [PacketIdentifier=59] [ReasonCode=]' at an unexpected time.'
[2019-08-30 06:41:50 INF Mqtt ] CONNECTED to MQTT server
[2019-08-30 06:46:24 INF Mqtt ] DISCONNECTED from MQTT server: 'Received packet 'PubAck: [PacketIdentifier=95] [ReasonCode=]' at an unexpected time.'
[2019-08-30 06:46:26 INF Mqtt ] CONNECTED to MQTT server
[2019-08-30 06:46:30 INF Mqtt ] DISCONNECTED from MQTT server: 'Received packet 'PubAck: [PacketIdentifier=96] [ReasonCode=]' at an unexpected time.'
[2019-08-30 06:46:34 INF Mqtt ] CONNECTED to MQTT server
[2019-08-30 06:46:39 INF Mqtt ] DISCONNECTED from MQTT server: 'Received packet 'PubAck: [PacketIdentifier=2] [ReasonCode=]' at an unexpected time.'
[2019-08-30 06:46:41 INF Mqtt ] CONNECTED to MQTT server
[2019-08-30 06:48:38 INF Mqtt ] DISCONNECTED from MQTT server: 'Received packet 'PubAck: [PacketIdentifier=44] [ReasonCode=]' at an unexpected time.'
[2019-08-30 06:48:44 INF Mqtt ] CONNECTED to MQTT server
[2019-08-30 06:48:56 INF Mqtt ] DISCONNECTED from MQTT server: 'Received packet 'PubAck: [PacketIdentifier=2] [ReasonCode=]' at an unexpected time.'
[2019-08-30 06:49:05 INF Mqtt ] CONNECTED to MQTT server
[2019-08-30 06:49:09 INF Mqtt ] DISCONNECTED from MQTT server: 'Received packet 'PubAck: [PacketIdentifier=3] [ReasonCode=]' at an unexpected time.'
[2019-08-30 06:49:10 INF Mqtt ] CONNECTED to MQTT server
[2019-08-30 06:51:24 INF Mqtt ] DISCONNECTED from MQTT server: 'Received packet 'PubAck: [PacketIdentifier=54] [ReasonCode=]' at an unexpected time.'
[2019-08-30 06:51:28 INF Mqtt ] CONNECTED to MQTT server
[2019-08-30 06:51:36 INF Mqtt ] DISCONNECTED from MQTT server: 'Received packet 'PubAck: [PacketIdentifier=55] [ReasonCode=]' at an unexpected time.'
[2019-08-30 06:51:37 INF Mqtt ] CONNECTED to MQTT server
[2019-08-30 06:51:41 INF Mqtt ] DISCONNECTED from MQTT server: 'Received packet 'PubAck: [PacketIdentifier=2] [ReasonCode=]' at an unexpected time.'
[2019-08-30 06:51:43 INF Mqtt ] CONNECTED to MQTT server
[2019-08-30 06:54:20 INF Mqtt ] DISCONNECTED from MQTT server: 'Received packet 'PubAck: [PacketIdentifier=53] [ReasonCode=]' at an unexpected time.'
[2019-08-30 06:54:29 INF Mqtt ] CONNECTED to MQTT server
[2019-08-30 06:56:41 INF Mqtt ] DISCONNECTED from MQTT server: 'Received packet 'PubAck: [PacketIdentifier=54] [ReasonCode=]' at an unexpected time.'
[2019-08-30 06:56:50 INF Mqtt ] CONNECTED to MQTT server
[2019-08-30 06:57:13 INF Mqtt ] DISCONNECTED from MQTT server: 'Received packet 'PubAck: [PacketIdentifier=2] [ReasonCode=]' at an unexpected time.'
[2019-08-30 06:57:21 INF Mqtt ] CONNECTED to MQTT server
[2019-08-30 06:59:22 INF Mqtt ] DISCONNECTED from MQTT server: 'Received packet 'PubAck: [PacketIdentifier=50] [ReasonCode=]' at an unexpected time.'
[2019-08-30 06:59:28 INF Mqtt ] CONNECTED to MQTT server
[2019-08-30 06:59:30 INF Mqtt ] DISCONNECTED from MQTT server: 'Received packet 'PubAck: [PacketIdentifier=51] [ReasonCode=]' at an unexpected time.'
[2019-08-30 06:59:37 INF Mqtt ] CONNECTED to MQTT server
[2019-08-30 07:00:08 INF Mqtt ] DISCONNECTED from MQTT server: 'Received packet 'PubAck: [PacketIdentifier=2] [ReasonCode=]' at an unexpected time.'
[2019-08-30 07:00:09 INF Mqtt ] CONNECTED to MQTT server
[2019-08-30 07:00:10 INF Mqtt ] DISCONNECTED from MQTT server: 'Received packet 'PubAck: [PacketIdentifier=4] [ReasonCode=]' at an unexpected time.'
[2019-08-30 07:00:11 INF Mqtt ] CONNECTED to MQTT server
[2019-08-30 07:02:21 INF Mqtt ] DISCONNECTED from MQTT server: 'Received packet 'PubAck: [PacketIdentifier=59] [ReasonCode=]' at an unexpected time.'
[2019-08-30 07:02:24 INF Mqtt ] CONNECTED to MQTT server
[2019-08-30 07:02:36 INF Mqtt ] DISCONNECTED from MQTT server: 'Received packet 'PubAck: [PacketIdentifier=60] [ReasonCode=]' at an unexpected time.'
[2019-08-30 07:02:47 INF Mqtt ] DISCONNECTED from MQTT server (timeout).
[2019-08-30 07:02:47 INF Mqtt ] CONNECTING FAILED to MQTT server (timeout).
[2019-08-30 07:03:18 INF Mqtt ] CONNECTED to MQTT server
[2019-08-30 07:05:15 INF Mqtt ] DISCONNECTED from MQTT server: 'Received packet 'PubAck: [PacketIdentifier=54] [ReasonCode=]' at an unexpected time.'
[2019-08-30 07:05:18 INF Mqtt ] CONNECTED to MQTT server
[2019-08-30 07:05:39 INF Mqtt ] DISCONNECTED from MQTT server: 'Received packet 'PubAck: [PacketIdentifier=2] [ReasonCode=]' at an unexpected time.'
[2019-08-30 07:05:46 INF Mqtt ] CONNECTED to MQTT server
[2019-08-30 07:05:47 INF Mqtt ] DISCONNECTED from MQTT server: 'Received packet 'PubAck: [PacketIdentifier=3] [ReasonCode=]' at an unexpected time.'
[2019-08-30 07:05:48 INF Mqtt ] CONNECTED to MQTT server
[2019-08-30 07:05:49 INF Mqtt ] DISCONNECTED from MQTT server: 'Received packet 'PubAck: [PacketIdentifier=2] [ReasonCode=]' at an unexpected time.'
[2019-08-30 07:05:51 INF Mqtt ] CONNECTED to MQTT server
[2019-08-30 07:05:52 INF Mqtt ] DISCONNECTED from MQTT server: 'Received packet 'PubAck: [PacketIdentifier=2] [ReasonCode=]' at an unexpected time.'
[2019-08-30 07:05:57 INF Mqtt ] CONNECTED to MQTT server
[2019-08-30 07:05:57 WRN Mqtt ] MQTT synchronizing subscriptions failed: 'The client is not connected.'
[2019-08-30 07:05:57 WRN Mqtt ] MQTT synchronizing subscriptions failed: 'The client is not connected.'
[2019-08-30 07:05:57 WRN Mqtt ] MQTT synchronizing subscriptions failed: 'The client is not connected.'
[2019-08-30 07:05:57 WRN Mqtt ] MQTT synchronizing subscriptions failed: 'The client is not connected.'
[2019-08-30 07:05:57 WRN Mqtt ] MQTT synchronizing subscriptions failed: 'The client is not connected.'
[2019-08-30 07:05:57 WRN Mqtt ] MQTT synchronizing subscriptions failed: 'The client is not connected.'
[2019-08-30 07:05:57 WRN Mqtt ] MQTT synchronizing subscriptions failed: 'The client is not connected.'
[2019-08-30 07:05:57 WRN Mqtt ] MQTT synchronizing subscriptions failed: 'The client is not connected.'
[2019-08-30 07:05:57 WRN Mqtt ] MQTT synchronizing subscriptions failed: 'The client is not connected.'
Please note, that both failures occur at the same date, but not the same time.
This is my current initialization and subscription code:
ManagedMqttClientOptions options = new ManagedMqttClientOptionsBuilder()
.WithAutoReconnectDelay(TimeSpan.FromSeconds(30))
.WithClientOptions(new MqttClientOptionsBuilder()
.WithClientId(cfg.ClientId)
.WithTcpServer(cfg.BrokerAddress, (int)cfg.BrokerPort)
.WithTls()
.WithCredentials(cfg.Credentials.User, cfg.Credentials.Password)
.WithCommunicationTimeout(TimeSpan.FromSeconds(10))
.WithKeepAlivePeriod(TimeSpan.FromSeconds(15))
.WithKeepAliveSendInterval(TimeSpan.FromSeconds(10))
.Build())
.Build();
mqttClient = new MqttFactory().CreateManagedMqttClient();
mqttClient.ApplicationMessageSkippedHandler = new ApplicationMessageSkippedHandlerDelegate((Action<ApplicationMessageSkippedEventArgs>)OnApplicationMessageSkipped);
mqttClient.SynchronizingSubscriptionsFailedHandler = new SynchronizingSubscriptionsFailedHandlerDelegate((Action<ManagedProcessFailedEventArgs>)OnSynchronizingSubscriptionsFailed);
mqttClient.ApplicationMessageReceivedHandler = new MqttApplicationMessageReceivedHandlerDelegate((Action<MqttApplicationMessageReceivedEventArgs>)ReceivedMessageHandlerAsync);
mqttClient.ConnectedHandler = new MqttClientConnectedHandlerDelegate((Action<MqttClientConnectedEventArgs>)OnConnectedAsync);
mqttClient.DisconnectedHandler = new MqttClientDisconnectedHandlerDelegate((Action<MqttClientDisconnectedEventArgs>)OnDisconnected);
mqttClient.ConnectingFailedHandler = new ConnectingFailedHandlerDelegate((Action<ManagedProcessFailedEventArgs>)OnConnectingFailed);
logger.LogDebug("Trying to connect to MQTT server");
await mqttClient.StartAsync(options).ConfigureAwait(false);
await mqttClient.SubscribeAsync("topic").ConfigureAwait(false);
private async void OnConnectedAsync(MqttClientConnectedEventArgs e)
{
logger.LogInformation("CONNECTED to MQTT server");
if (isConnectedFirst)
{
isConnectedFirst = false;
await RegisterCommandSubscriptionsAsync().ConfigureAwait(false);
}
}
public async Task RegisterCommandSubscriptionsAsync()
{
logger.LogDebug("RegisterCommandSubscriptions called");
await Task.Delay(10000).ConfigureAwait(false);
logger.LogDebug("Registering subscriptions for receiving commands");
if (CallbackCommandReceived != null || CallbackLogfileRequestReceived != null || CallbackSendValuesRequestReceived != null || CallbackConfigurationRequestReceived != null)
{
await mqttClient.SubscribeAsync("s/ds").ConfigureAwait(false);
}
if (CallbackNewValueReceived != null)
{
await mqttClient.SubscribeAsync("topic2").ConfigureAwait(false);
}
}
I noticed that in the meantime you released two other versions of your lib. Do you see a chance that the issue is fixed there and should I give them a try? And do you have advises where I should add more debug output for the case the problem occurs again?
Best regards Stefan
I just noticed the problem again, but this time on my development machine (win10), so I had the possibility to dig into it a bit further. The log output looks as follows:
[2019-10-24 16:41:53 VRB Mqtt ] MQTT message processed: <topic> | Payload: '<message 1>' // -> In ApplicationMessageProcessedHandler
[2019-10-24 16:42:13 INF Mqtt ] DISCONNECTED from MQTT server (timeout). // -> In DisconnectedHandler (with MqttCommunicationTimedOutException)
[2019-10-24 16:42:13 VRB Mqtt ] MQTT message processed: <topic> | Payload: '<message 2>' // -> In ApplicationMessageProcessedHandler
[2019-10-24 16:42:17 INF Mqtt ] CONNECTED to MQTT server, subscribing to topics... // -> In ConnectedHandler
[2019-10-24 16:42:17 INF Mqtt ] DISCONNECTED from MQTT server: 'Received packet 'PubAck: [PacketIdentifier=35] [ReasonCode=]' at an unexpected time.' // -> In DisconnectedHandler (with other exception)
[2019-10-24 16:42:17 DBG Mqtt ] Registering subscriptions for receiving commands // -> In ConnectedHandler
[2019-10-24 16:42:17 WRN Mqtt ] MQTT synchronizing subscriptions failed: 'The client is not connected.' // -> SynchronizingSubscriptionsFailedHandler
[2019-10-24 16:42:17 WRN Mqtt ] MQTT synchronizing subscriptions failed: 'The client is not connected.'
[2019-10-24 16:42:17 VRB Mqtt ] MQTT message processed: <topic> | Payload: '<message 2>'
[2019-10-24 16:42:17 WRN Mqtt ] MQTT synchronizing subscriptions failed: 'The client is not connected.'
[2019-10-24 16:42:17 VRB Mqtt ] MQTT message processed: <topic> | Payload: '<message 2>'
[2019-10-24 16:42:17 WRN Mqtt ] MQTT synchronizing subscriptions failed: 'The client is not connected.'
[2019-10-24 16:42:17 VRB Mqtt ] MQTT message processed: <topic> | Payload: '<message 2>'
[2019-10-24 16:42:17 WRN Mqtt ] MQTT synchronizing subscriptions failed: 'The client is not connected.'
[2019-10-24 16:42:17 VRB Mqtt ] MQTT message processed: <topic> | Payload: '<message 2>'
[2019-10-24 16:42:17 WRN Mqtt ] MQTT synchronizing subscriptions failed: 'The client is not connected.'
[2019-10-24 16:42:17 VRB Mqtt ] MQTT message processed: <topic> | Payload: '<message 2>'
[2019-10-24 16:42:17 WRN Mqtt ] MQTT synchronizing subscriptions failed: 'The client is not connected.'
[2019-10-24 16:42:17 VRB Mqtt ] MQTT message processed: <topic> | Payload: '<message 2>'
[2019-10-24 16:42:17 WRN Mqtt ] MQTT synchronizing subscriptions failed: 'The client is not connected.'
I added comments where the output happens, please refer to my code above.
Due to more debug output, you can see that there are alternating messages from the SynchronizingSubscriptionsFailedHandler and the ApplicationMessageProcessedHandler. It is the same message which is reported as processed over and over again.
Some additional information for the case it helps:
- The MqttClient's
IsConnectedproperty statestrueall the time, but no connection is established and the message queue constantly grows. - The
ApplicationMessageProcessedEventArgsin theApplicationMessageProcessedHandlerhas the exception property set with an exception of the typeMqttCommunictaionException("The client is not connected."). It's stack trace is
at MQTTnet.Client.MqttClient.ThrowIfNotConnected()
at MQTTnet.Client.MqttClient.PublishAsync(MqttApplicationMessage applicationMessage, CancellationToken cancellationToken)
at MQTTnet.Client.MqttClientExtensions.PublishAsync(IMqttClient client, MqttApplicationMessage applicationMessage)
at MQTTnet.Extensions.ManagedClient.ManagedMqttClient.<TryPublishQueuedMessageAsync>d__59.MoveNext()
- The
ManagedProcessFailedEventArgsin theSynchronizingSubscriptionsFailedHandlerhas the exception property set with an exception of the typeMqttCommunictaionException("The client is not connected."). It's stack trace is
at MQTTnet.Client.MqttClient.ThrowIfNotConnected()
at MQTTnet.Client.MqttClient.<SubscribeAsync>d__36.MoveNext()
at System.Runtime.ExceptionServices.ExceptionDispatchInfo.Throw()
at System.Runtime.CompilerServices.TaskAwaiter.HandleNonSuccessAndDebuggerNotification(Task task)
at MQTTnet.Extensions.ManagedClient.ManagedMqttClient.<SynchronizeSubscriptionsAsync>d__60.MoveNext()
- Screenshot of the internal state of the mqttClient:
Edit: I will let the program sitting in the breakpoint over the weekend, so if you need further information, please let me know and I will provide it on Monday.
This weekend, I had the issue on another testing system (.net core 2, win 10):
// Everything works fine until here
[2019-10-26 05:40:04 INF Mqtt ] DISCONNECTED from MQTT server: 'Received packet 'PubAck: [PacketIdentifier=1487] [ReasonCode=]' at an unexpected time.'
[2019-10-26 05:40:08 INF Mqtt ] CONNECTED to MQTT server
[2019-10-26 05:40:08 WRN Mqtt ] MQTT synchronizing subscriptions failed: 'The client is not connected.'
[2019-10-26 05:40:08 WRN Mqtt ] MQTT synchronizing subscriptions failed: 'The client is not connected.'
[2019-10-26 05:40:08 WRN Mqtt ] MQTT synchronizing subscriptions failed: 'The client is not connected.'
[2019-10-26 05:40:08 WRN Mqtt ] MQTT synchronizing subscriptions failed: 'The client is not connected.'
[2019-10-26 05:40:08 WRN Mqtt ] MQTT synchronizing subscriptions failed: 'The client is not connected.'
[2019-10-26 05:40:08 WRN Mqtt ] MQTT synchronizing subscriptions failed: 'The client is not connected.'
[2019-10-26 05:40:08 WRN Mqtt ] MQTT synchronizing subscriptions failed: 'The client is not connected.'
[2019-10-26 05:40:08 WRN Mqtt ] MQTT synchronizing subscriptions failed: 'The client is not connected.'
...
It's the same behavior - a disconnection due to an unexpected packet followed be a reportedly successful re-connection which brings the lib into an inconsistent state.
@chkr1011 and @SeppPenner , may I ask you if I can provide anything helping you to investigate this issue? As our MQTT broker seems to send these unexpected packets from time to time (which is out of our scope) this issue occurs frequently and is quite annoying as you can image. I have workarounded it with a watchdog inspecting the packet queue and resetting the service when a specific number of unsent packets is reached, but this is obviously not a good solution. A comparative test with the former main version of your library (2.8.x) connected to the same MQTT broker runs without interruptions for month. Please let me know if I can help you in any ways, for example by beta-testing a fix or by providing more information.
Best regards Stefan
Please test again with the latest version of the library and reopen this ticket if the issue persists.