Intermittent connection issues, CONNECT message not sent in time

[RiaanSDivigraph]

Hi MQTTNet community

I'm raising this in a Discussion rather than an Issue, since I have no reproduction steps yet - nothing for you (or even us) to go on at this stage other than what we observe on the machine in question.

We are using HiveMQ Community Edition 2023.9 with a relatively old MQTTNet client (3.0.16) with mutual TLS (certificates broker-side and client-side).

The MQTTNet client is running on .NET Framework 4.6.2.

This works swimmingly on almost all systems where we have tested it. However, on a single VM running Windows Server 2016 we are encountering issues maintaining a stable connection.

I see this in the HiveMQ event.log:

2024-02-20 09:12:24,178 - Client ID: S1X-13444, IP: 127.0.0.1, Clean Start: true, Session Expiry: 0 connected.

2024-02-20 09:23:28,479 - Client ID: S1X-12880 session has expired at 2024-02-20 15:08:23. All persistent data for this client has been removed.

2024-02-20 09:38:05,699 - Client ID: S1X-13444, IP: 127.0.0.1 disconnected ungracefully from TCP Listener with TLS on port: 8883.

2024-02-20 09:38:53,869 - Client ID: UNKNOWN, IP: 127.0.0.1 was disconnected. reason: No CONNECT sent in time.

2024-02-20 09:39:17,710 - Client ID: UNKNOWN, IP: 127.0.0.1 was disconnected. reason: No CONNECT sent in time.

2024-02-20 09:39:42,222 - Client ID: UNKNOWN, IP: 127.0.0.1 was disconnected. reason: No CONNECT sent in time.

2024-02-20 09:40:06,036 - Client ID: UNKNOWN, IP: 127.0.0.1 was disconnected. reason: No CONNECT sent in time.

2024-02-20 09:40:31,337 - Client ID: UNKNOWN, IP: 127.0.0.1 was disconnected. reason: No CONNECT sent in time.

2024-02-20 09:40:55,521 - Client ID: UNKNOWN, IP: 127.0.0.1 was disconnected. reason: No CONNECT sent in time.

2024-02-20 09:41:19,418 - Client ID: UNKNOWN, IP: 127.0.0.1 was disconnected. reason: No CONNECT sent in time.

2024-02-20 09:41:43,922 - Client ID: UNKNOWN, IP: 127.0.0.1 was disconnected. reason: No CONNECT sent in time.

2024-02-20 09:42:08,221 - Client ID: UNKNOWN, IP: 127.0.0.1 was disconnected. reason: No CONNECT sent in time.

2024-02-20 09:42:32,218 - Client ID: UNKNOWN, IP: 127.0.0.1 was disconnected. reason: No CONNECT sent in time.

2024-02-20 09:42:56,146 - Client ID: UNKNOWN, IP: 127.0.0.1 was disconnected. reason: No CONNECT sent in time.

2024-02-20 09:43:20,259 - Client ID: UNKNOWN, IP: 127.0.0.1 was disconnected. reason: No CONNECT sent in time.

2024-02-20 09:44:03,893 - Client ID: UNKNOWN, IP: 127.0.0.1 was disconnected. reason: No CONNECT sent in time.

2024-02-20 09:44:28,039 - Client ID: UNKNOWN, IP: 127.0.0.1 was disconnected. reason: No CONNECT sent in time.

2024-02-20 09:44:33,051 - Client ID: S1X-13444 session has expired at 2024-02-20 15:38:05. All persistent data for this client has been removed.

So it seems our old MQTTnet client might have issues sending a CONNECT message in time. I am setting up a test run with logging from inside that client, so we can see if there was an exception that killed a CONNECT keepalive thread.

The client and the broker are on the same machine, hence the IP address of 127.0.0.1. The VM is running on a VMWare VM.

We've tried to reproduce this on a VMWare VM with the same OS running (not sure about Service Packs or updates), with a different BIOS. The problematic machine reported a Phoenix BIOS, where our test machine reports a VMWare UEFI BIOS. But we were unable to reproduce on our test VM - it works fine for us.

We are also working on doing a test run with an upgraded MQTTNet (3.1.2) on a newer .NET Framework (4.8).

Do you have any experience with anything similar?

Thanks!

[chkr1011]

The CONNECT packet is the very first packet when a connection is made. So, it might not be affected by huge traffic of PUBLISH packets etc. The CONNECT packet is also usually very small because it has no custom payload, so we are talking about a few bytes here.

My assumption is that the issue may be located at socket or network level and not in this library at all.