First Connection Attempt Fails Everytime

[nathanschrope]

Describe the bug

The very first ConnectAsync call fails and goes into DisconnectedAsync. It fails with error "Error while authenticating. The MQTT client is disconnected". My code then triggers a retry connection attempt and succeeds (I do rebuild the ClientOptions but with the same values).

I cannot replicate this in a unit test. It only happens in a production environment.

Which component is your bug related to?

• Client

Code example

                   BuildClientOptions();
                    mqttClient.ApplicationMessageReceivedAsync += e => ReceivingMessage(e);
                    mqttClient.ConnectedAsync += e => OnConnecting(e);
                    mqttClient.DisconnectedAsync += e => Disconnecting(e);

                    logger.Log(LogLevel.Trace, "Finished configuring.");

                    await ConnectInner();

private async Task<bool> ConnectInner()
        {
            var response = await mqttClient.ConnectAsync(mqttClientOptions);


            if (response != null)
            {
                if (response.ResultCode == MqttClientConnectResultCode.Success)
                {
                    logger.Log(LogLevel.Trace, "Attempted Connection resulted with: " + response.ResultCode.ToString());
                }
                else
                {
                    logger.Log(LogLevel.Error, "Attempted Connection resulted with: " + response.ResultCode.ToString());
                    return false;
                }
            }
            else
            {
                return false;
            }

            return true;

        }

private void BuildClientOptions()
        {
            logger.Log(LogLevel.Trace, $"Building Client Options; Broker Number: {BrokerCounter}, Broker: {settings.ConnectionInfo.Broker[BrokerCounter].server}, Port: {settings.ConnectionInfo.Broker[BrokerCounter].portNumber}");
            logger.Log(LogLevel.Trace, $"Building Client Options; UserName: {settings.ConnectionInfo.Credentials.userName}");
            mqttClientOptions = mqttFactory.CreateClientOptionsBuilder()
                .WithClientId($"HiveMQ_{guid}")
                .WithTcpServer(settings.ConnectionInfo.Broker[BrokerCounter].server, settings.ConnectionInfo.Broker[BrokerCounter].portNumber)
                .WithCredentials(settings.ConnectionInfo.Credentials.userName, settings.ConnectionInfo.Credentials.protectedPassword)
                .WithTls(new MqttClientOptionsBuilderTlsParameters()
                {
                    UseTls = true,
                    AllowUntrustedCertificates = true,
                    IgnoreCertificateChainErrors = true,
                    IgnoreCertificateRevocationErrors = true
                })
                .WithProtocolVersion(MQTTnet.Formatter.MqttProtocolVersion.V500)
                .WithCleanSession(false).WithKeepAlivePeriod(TimeSpan.FromSeconds(60)).WithTimeout(TimeSpan.FromSeconds(30))
                .Build();
        }

[chkr1011]

Please share the trace (see samples for enabling this).

[nathanschrope]

15:42:53.827|131|Debug|ClientQueryServiceEndpoint|BCD650BC358847D8B37B3D6659031AB9||||||Trying to connect with server '{0}'. 15:43:08.842|147|Debug|ClientQueryServiceEndpoint|BCD650BC358847D8B37B3D6659031AB9||||||Connection with server established. 15:43:08.842|147|Debug|ClientQueryServiceEndpoint|BCD650BC358847D8B37B3D6659031AB9||||||TX ({0} bytes) >>> {1} 15:43:08.842|99|Debug|ClientQueryServiceEndpoint|BCD650BC358847D8B37B3D6659031AB9||||||Start receiving packets. 15:43:08.842|149|Debug|ClientQueryServiceEndpoint|BCD650BC358847D8B37B3D6659031AB9||||||Disconnecting [Timeout={0}] 15:43:08.842|149|Debug|ClientQueryServiceEndpoint|BCD650BC358847D8B37B3D6659031AB9||||||Disconnected from adapter. 15:43:08.842|149|Debug|ClientQueryServiceEndpoint|BCD650BC358847D8B37B3D6659031AB9||||||Disconnected. 15:43:08.842|149|Debug|ClientQueryServiceEndpoint|BCD650BC358847D8B37B3D6659031AB9||||||Stopped receiving packets. 15:43:08.842|38|Debug|ClientQueryServiceEndpoint|BCD650BC358847D8B37B3D6659031AB9||||||Timeout while waiting for response packet ({0}). 15:43:08.842|38|Debug|ClientQueryServiceEndpoint|BCD650BC358847D8B37B3D6659031AB9||||||Error while connecting with server. 15:43:08.842|131|Exception|ClientQueryServiceEndpoint|BCD650BC358847D8B37B3D6659031AB9|||NetLogger.Log [TRY/CATCH]||UPS.POS.Util.dll|Exception Type: AggregateException 15:43:08.842|131|Exception|ClientQueryServiceEndpoint|BCD650BC358847D8B37B3D6659031AB9|||NetLogger.Log [TRY/CATCH]||UPS.POS.Util.dll| Source: mscorlib 15:43:08.842|131|Exception|ClientQueryServiceEndpoint|BCD650BC358847D8B37B3D6659031AB9|||NetLogger.Log [TRY/CATCH]||UPS.POS.Util.dll| Text: One or more errors occurred. 15:43:08.842|131|Exception|ClientQueryServiceEndpoint|BCD650BC358847D8B37B3D6659031AB9|||NetLogger.Log [TRY/CATCH]||UPS.POS.Util.dll| Caught In: NetLogger.Log(System.Exception ex) 15:43:08.842|131|Exception|ClientQueryServiceEndpoint|BCD650BC358847D8B37B3D6659031AB9|||NetLogger.Log [TRY/CATCH]||UPS.POS.Util.dll| Stack Trace: at System.Threading.Tasks.Task.ThrowIfExceptional(Boolean includeTaskCanceledExceptions) at System.Threading.Tasks.Task.Wait(Int32 millisecondsTimeout, CancellationToken cancellationToken) at System.Threading.Tasks.Task.Wait() at HiveMQ.HiveMQClient.Disconnecting(MqttClientDisconnectedEventArgs obj) 15:43:08.842|131|Exception|ClientQueryServiceEndpoint|BCD650BC358847D8B37B3D6659031AB9|||NetLogger.Log [TRY/CATCH]||UPS.POS.Util.dll|INNER EXCEPTION: 15:43:08.842|131|Exception|ClientQueryServiceEndpoint|BCD650BC358847D8B37B3D6659031AB9|||NetLogger.Log [TRY/CATCH]||UPS.POS.Util.dll|Exception Type: MqttConnectingFailedException 15:43:08.842|131|Exception|ClientQueryServiceEndpoint|BCD650BC358847D8B37B3D6659031AB9|||NetLogger.Log [TRY/CATCH]||UPS.POS.Util.dll| Source: MQTTnet 15:43:08.842|131|Exception|ClientQueryServiceEndpoint|BCD650BC358847D8B37B3D6659031AB9|||NetLogger.Log [TRY/CATCH]||UPS.POS.Util.dll| Text: Error while authenticating. The operation has timed out. 15:43:08.842|131|Exception|ClientQueryServiceEndpoint|BCD650BC358847D8B37B3D6659031AB9|||NetLogger.Log [TRY/CATCH]||UPS.POS.Util.dll| Stack Trace: at MQTTnet.Client.MqttClient.<AuthenticateAsync>d__58.MoveNext() --- End of stack trace from previous location where exception was thrown --- at System.Runtime.ExceptionServices.ExceptionDispatchInfo.Throw() at System.Runtime.CompilerServices.TaskAwaiter.HandleNonSuccessAndDebuggerNotification(Task task) at MQTTnet.Client.MqttClient.<ConnectAsync>d__49.MoveNext() --- End of stack trace from previous location where exception was thrown --- at System.Runtime.ExceptionServices.ExceptionDispatchInfo.Throw() at MQTTnet.Client.MqttClient.<ConnectAsync>d__49.MoveNext() --- End of stack trace from previous location where exception was thrown --- at System.Runtime.ExceptionServices.ExceptionDispatchInfo.Throw() at System.Runtime.CompilerServices.TaskAwaiter.HandleNonSuccessAndDebuggerNotification(Task task) at System.Runtime.CompilerServices.TaskAwaiter1.GetResult() at HiveMQ.HiveMQClient.<ConnectInner>d__19.MoveNext() 15:43:08.842|131|Exception|ClientQueryServiceEndpoint|BCD650BC358847D8B37B3D6659031AB9|||NetLogger.Log [TRY/CATCH]||UPS.POS.Util.dll|INNER EXCEPTION: 15:43:08.842|131|Exception|ClientQueryServiceEndpoint|BCD650BC358847D8B37B3D6659031AB9|||NetLogger.Log [TRY/CATCH]||UPS.POS.Util.dll|Exception Type: MqttCommunicationTimedOutException 15:43:08.842|131|Exception|ClientQueryServiceEndpoint|BCD650BC358847D8B37B3D6659031AB9|||NetLogger.Log [TRY/CATCH]||UPS.POS.Util.dll| Source: mscorlib 15:43:08.842|131|Exception|ClientQueryServiceEndpoint|BCD650BC358847D8B37B3D6659031AB9|||NetLogger.Log [TRY/CATCH]||UPS.POS.Util.dll| Text: The operation has timed out. 15:43:08.842|131|Exception|ClientQueryServiceEndpoint|BCD650BC358847D8B37B3D6659031AB9|||NetLogger.Log [TRY/CATCH]||UPS.POS.Util.dll| Stack Trace: at System.Runtime.ExceptionServices.ExceptionDispatchInfo.Throw() at System.Runtime.CompilerServices.TaskAwaiter.HandleNonSuccessAndDebuggerNotification(Task task) at MQTTnet.PacketDispatcher.MqttPacketAwaitable1.<WaitOneAsync>d__6.MoveNext() --- End of stack trace from previous location where exception was thrown --- at System.Runtime.ExceptionServices.ExceptionDispatchInfo.Throw() at System.Runtime.CompilerServices.TaskAwaiter.HandleNonSuccessAndDebuggerNotification(Task task) at MQTTnet.Client.MqttClient.<SendAndReceiveAsync>d__74`1.MoveNext() --- End of stack trace from previous location where exception was thrown --- at System.Runtime.ExceptionServices.ExceptionDispatchInfo.Throw() at System.Runtime.CompilerServices.TaskAwaiter.HandleNonSuccessAndDebuggerNotification(Task task) at MQTTnet.Client.MqttClient.<AuthenticateAsync>d__58.MoveNext() 15:43:38.856|126|Trace|ClientQueryServiceEndpoint|BCD650BC358847D8B37B3D6659031AB9||||||HiveMQ Disconnected 15:43:38.856|126|Debug|ClientQueryServiceEndpoint|BCD650BC358847D8B37B3D6659031AB9||||||Trying to connect with server '{0}'. 15:43:38.856|148|Debug|ClientQueryServiceEndpoint|BCD650BC358847D8B37B3D6659031AB9||||||Connection with server established. 15:43:38.856|160|Debug|ClientQueryServiceEndpoint|BCD650BC358847D8B37B3D6659031AB9||||||Start receiving packets. 15:43:38.856|148|Debug|ClientQueryServiceEndpoint|BCD650BC358847D8B37B3D6659031AB9||||||TX ({0} bytes) >>> {1} 15:43:38.903|148|Debug|ClientQueryServiceEndpoint|BCD650BC358847D8B37B3D6659031AB9||||||RX ({0} bytes) <<< {1} 15:43:38.903|143|Debug|ClientQueryServiceEndpoint|BCD650BC358847D8B37B3D6659031AB9||||||Authenticated MQTT connection with server established.

[nathanschrope]

HiveMQ_20221213_34004.Eventually.Works.log

[nathanschrope]

@chkr1011 I see a new version is out.

Here is some more logs

1. One that breaks |||Adapter.ReadFixedHeaderAsync entered ||| -- Adapter._channel .. endpoint is: [::ffff:156.134.251.130]:9883 ||Adapter.ReadFixedHeaderAsync bytesRead == 0 |||ReceivePacketAsync Await ||ReceiveAsync - ReadFixedHeaderResult.IsConnectionclosed = true - return empty |||Await packet task. ||ReceivePacketAsync returning null ||receivedPacket.TotalLength: 0, cancellationToken.IsCancellationRequested: False

2. One that works |||Adapter.ReadFixedHeaderAsync entered ||| -- Adapter._channel .. endpoint is: [::ffff:156.134.251.130]:9883 |||ReceivePacketAsync Await |||Await packet task. |||TX (89 bytes) >>> Connect: [ClientId=HiveMQ_44742f36-82b6-48a0-b4df-bdde79752887] [Username=timmMqUser] [Pa ||Adapter.ReadFixedHeaderAsync returning fixedheader with length: 11 ||ReceivePacketAsync EndReceive ||ReceivePacketAsync Decode ||RX (11 bytes) <<< ConnAck: [ReturnCode=ConnectionAccepted] [ReasonCode=Success] [IsSessionPresent=False] ||Try Receiving Packets.

3. Another that breaks |||||Adapter.ReadFixedHeaderAsync entered ||||||AuthenticateAsync calling SendAndReceive for MqttConnAckPacket ||||| -- Adapter._channel .. endpoint is: [::ffff:156.134.251.130]:9883 - ReadAsync - offset: 0 - ||||||TX (89 bytes) >>> Connect: [ClientId=HiveMQ_d9d72b9e-cb7e-4e6e-bc16-d97c0e2aa409] [Username |||||TcpChannel.ReadAsync - offset: 0 count: 2 |||||TcpChannel.ReadAynsc --- asking stream to ReadAsync |||||ReceivePacketAsync Await |||||Await packet task. ||||||Adapter.ReadFixedHeaderAsync bytesRead == 0 ||||||ReceiveAsync - ReadFixedHeaderResult.IsConnectionclosed = true - return empty ||||||ReceivePacketAsync returning null ||||||receivedPacket.TotalLength: 0, cancellationToken.IsCancellationRequested: False ||||||No Packets. Disconnect.

[chkr1011]

What broker do you use? Some product with a public test instance?

[nathanschrope]

We tried this on HiveMQ and also ActiveMQ with the same results. Latest version of each. It seems like the first handshake with the broker succeeds, but the tls handshake takes 30 seconds and is timing out. TLS is set to true and SSL protocol is set to Tls12. We tried on a server with TLS and it worked perfectly.

[nathanschrope]

I also converted to ManagedClient and that has the same issue.

[nathanschrope]

@chkr1011 We have been experiencing some issues with cipher suites. The only time we experience this issue with older devices, but it is using older cipher suites than expected.

[asymetrixs]

@nathanschrope can you show me how you configure the SSL/TLS part in MQTTNet?

I am trying like this:

// Read certificate and it's key file and password (optional)
var certificateKeyFile = File.ReadAllText(mqttServerSettings.TlsCertificate!.KeyPath);
using var rsa = RSA.Create();
rsa.ImportFromPem(certificateKeyFile.ToArray());
var x509Certificate2 = new X509Certificate2(File.ReadAllBytes(mqttServerSettings.TlsCertificate.CertificatePath), mqttServerSettings.TlsCertificate.Password).CopyWithPrivateKey(rsa);

// Endpoint
mqttServerOptionsBuilder = mqttServerOptionsBuilder
    .WithEncryptedEndpoint()
    .WithEncryptionCertificate(x509Certificate2)
    .WithEncryptionSslProtocol(SslProtocols.Tls12)
    .WithEncryptedEndpointBoundIPAddress(System.Net.IPAddress.Any)
    .WithEncryptedEndpointPort(mqttServerSettings.EncryptedTcpEndPoint!.Port);

var mqttServerOptions = mqttServerOptionsBuilder.Build();

return services.AddHostedMqttServer(mqttServerOptions)
            .AddMqttConnectionHandler();

The web host is set up like this:

var host = Host.CreateDefaultBuilder(args)
            .UseSerilog((hostingContext, loggerConfiguration) =>
                loggerConfiguration.ReadFrom.Configuration(hostingContext.Configuration))
            .ConfigureWebHostDefaults(
            webBuilder =>
            {
                webBuilder.UseKestrel(
                    o =>
                    {
                        // Get MQTT server settings
                        var mqttServerSettings = Startup.Configuration.GetSection("MqttServer").Get<MqttServerSettings>();
                        
                        if (mqttServerSettings.IsTcpEndPointValid)
                        {
                            o.ListenAnyIP(mqttServerSettings.TcpEndPoint!.Port, (configure) =>
                            {
                                configure.UseMqtt();
                            });
                        }
                        else
                        {
                            Log.Logger.Information("Unencrypted TCP Endpoint is not configured.");
                        }

                        if (mqttServerSettings.IsEncryptedTcpEndpointValid)
                        {
                            // Add Kestrel endpoint
                            o.ListenAnyIP(mqttServerSettings.EncryptedTcpEndPoint!.Port, l => l.UseMqtt());
                        }
                        else
                        {
                            Log.Logger.Warning("Encrypted TCP Endpoint is not configured or certificate file cannot be found.");
                        }
                    });

                webBuilder.UseStartup<Startup>();
            });

However, when I connect to port 8883 using MQTT Explorer I can only connect when I disable Encryption (tls). As soon as it is enabled, I get the following error in MQTTNet Server. So it looks like port 8883 is expecting an unencrypted connection. Somewhere inbetween Kestrel is exposing port 8883 but connecting it to an unencrypted MQTTNet server endpoint (probably l => l.UseMqtt()

[17:27:09 DBG] Connection id "0HMPA54E5IUCN" accepted.
[17:27:09 DBG] Connection id "0HMPA54E5IUCN" started.
[17:27:09 DBG] Connection id "0HMPA54E5IUCN" communication error.
MQTTnet.Exceptions.MqttProtocolViolationException: CONNECT packet must have at least 7 bytes.
   at MQTTnet.Formatter.MqttPacketFormatterAdapter.ParseProtocolVersion(ReceivedMqttPacket receivedMqttPacket)
   at MQTTnet.AspNetCore.ReaderExtensions.TryDecode(MqttPacketFormatterAdapter formatter, ReadOnlySequence`1& input, MqttPacket& packet, SequencePosition& consumed, SequencePosition& observed, Int32& bytesRead)
   at MQTTnet.AspNetCore.MqttConnectionContext.ReceivePacketAsync(CancellationToken cancellationToken)
   at System.IO.Pipelines.Pipe.GetReadResult(ReadResult& result)
   at System.IO.Pipelines.Pipe.GetReadAsyncResult()
   at System.IO.Pipelines.Pipe.DefaultPipeReader.GetResult(Int16 token)
   at Microsoft.AspNetCore.Server.Kestrel.Transport.Sockets.Internal.SocketConnection.DoSend()
[17:27:09 DBG] Connection id "0HMPA54E5IUCN" sending FIN because: "CONNECT packet must have at least 7 bytes."

Can it be that this part l => l.UseMqtt() ignore the encryption and sets up an unencrypted endpoint?

[nathanschrope]

I've only dealt with client side. The only tls info is way I'm feeding mqttnet in my first comment.

We were able to fix this issue with cipher suites. For some reason the first connection tries with an unexpected cipher suite but then switched after that.

[chkr1011]

Closing the issue because it was fixed by using a different cypher suite.