Connection to AWS using WebSockets fails on Mono

[stefxx]

Describe the bug

Connection to AWS using WebSockets fails on Mono

Which component is your bug related to?

• Client

I am having a strange issue with MQTTnet on Ubuntu using Mono, when using WebSockets. I have tested a few different scenarios using Windows, Linux and WebSockets/WebSockets4Net:

Windows 11, WebSockets, to either test.mosquitto.org:8081 or AWS (succes):

>> [24-3-2023 15:47:38] [6] [MqttClient] [Verbose]: Trying to connect with server 'test.mosquitto.org:8081'.
>> [24-3-2023 15:47:41] [12] [MqttClient] [Verbose]: Connection with server established.
>> [24-3-2023 15:47:41] [10] [MqttClient] [Verbose]: Start receiving packets.
>> [24-3-2023 15:47:41] [12] [MqttChannelAdapter] [Verbose]: TX (69 bytes) >>> Connect: [ClientId=xx-redacted-xx] [Username=] [Password=] [KeepAlivePeriod=15] [CleanSession=True]
>> [24-3-2023 15:47:41] [11] [MqttChannelAdapter] [Verbose]: RX (4 bytes) <<< ConnAck: [ReturnCode=ConnectionAccepted] [ReasonCode=Success] [IsSessionPresent=False]
>> [24-3-2023 15:47:41] [10] [MqttClient] [Verbose]: Authenticated MQTT connection with server established.
>> [24-3-2023 15:47:41] [10] [MqttClient] [Info]: Connected.
>> [24-3-2023 15:47:41] [9] [MqttClient] [Verbose]: Start sending keep alive packets.

Windows 11, WebSockets4Net, to either test.mosquitto.org:8081 or AWS (succes):

>> [24-3-2023 15:48:45] [6] [MqttClient] [Verbose]: Trying to connect with server 'test.mosquitto.org:8081'.
>> [24-3-2023 15:48:47] [9] [MqttClient] [Verbose]: Connection with server established.
>> [24-3-2023 15:48:47] [13] [MqttClient] [Verbose]: Start receiving packets.
>> [24-3-2023 15:48:47] [9] [MqttChannelAdapter] [Verbose]: TX (69 bytes) >>> Connect: [ClientId=xx-redacted-xx] [Username=] [Password=] [KeepAlivePeriod=15] [CleanSession=True]
>> [24-3-2023 15:48:47] [13] [MqttChannelAdapter] [Verbose]: RX (4 bytes) <<< ConnAck: [ReturnCode=ConnectionAccepted] [ReasonCode=Success] [IsSessionPresent=False]
>> [24-3-2023 15:48:47] [14] [MqttClient] [Verbose]: Authenticated MQTT connection with server established.
>> [24-3-2023 15:48:47] [14] [MqttClient] [Info]: Connected.
>> [24-3-2023 15:48:47] [9] [MqttClient] [Verbose]: Start sending keep alive packets.

Ubuntu 22.04, Mono 6.8.0.105, WebSockets, to test.mosquitto.org:8081 (succes):

>> [3/24/2023 3:50:01 PM] [6] [MqttClient] [Verbose]: Trying to connect with server 'test.mosquitto.org:8081'
>> [3/24/2023 3:50:02 PM] [11] [MqttClient] [Verbose]: Connection with server established
>> [3/24/2023 3:50:02 PM] [9] [MqttClient] [Verbose]: Start receiving packets
>> [3/24/2023 3:50:02 PM] [11] [MqttChannelAdapter] [Verbose]: TX (69 bytes) >>> Connect: [ClientId=xx-redacted-xx] [Username=] [Password=] [KeepAlivePeriod=15] [CleanSession=True
>> [3/24/2023 3:50:02 PM] [9] [MqttChannelAdapter] [Verbose]: RX (4 bytes) <<< ConnAck: [ReturnCode=ConnectionAccepted] [ReasonCode=Success] [IsSessionPresent=False
>> [3/24/2023 3:50:02 PM] [8] [MqttClient] [Verbose]: Authenticated MQTT connection with server established
>> [3/24/2023 3:50:02 PM] [8] [MqttClient] [Info]: Connected
>> [3/24/2023 3:50:02 PM] [11] [MqttClient] [Verbose]: Start sending keep alive packets

Ubuntu 22.04, Mono 6.8.0.105, WebSockets, to AWS (fails):

>> [3/24/2023 3:52:50 PM] [6] [MqttClient] [Verbose]: Trying to connect with server 'iot.eu-west-1.xx-redacted-xx.com'
> [3/24/2023 3:52:50 PM] [8] [MqttClient] [Verbose]: Connection with server established
>> [3/24/2023 3:52:50 PM] [9] [MqttClient] [Verbose]: Start receiving packets
>> [3/24/2023 3:52:50 PM] [8] [MqttChannelAdapter] [Verbose]: TX (69 bytes) >>> Connect: [ClientId=xx-redacted-xx] [Username=] [Password=] [KeepAlivePeriod=15] [CleanSession=True
>> [3/24/2023 3:52:50 PM] [8] [MqttClient] [Verbose]: Disconnecting [Timeout=00:01:40
>> [3/24/2023 3:52:50 PM] [11] [MqttClient] [Warning]: Timeout while waiting for response packet (MqttConnAckPacket)
>> [3/24/2023 3:52:50 PM] [11] [MqttClient] [Error]: Error while connecting with server.
MQTTnet.Adapter.MqttConnectingFailedException: Error while authenticating. The operation has timed out. ---> MQTTnet.Exceptions.MqttCommunicationTimedOutException: The operation has timed out.
  at MQTTnet.PacketDispatcher.MqttPacketAwaitable`1[TPacket].WaitOneAsync (System.Threading.CancellationToken cancellationToken) [0x00092] in <1d26aa7eaa5a4094a08c8933437012f1>:0
  at MQTTnet.Client.MqttClient.SendAndReceiveAsync[TResponsePacket] (MQTTnet.Packets.MqttPacket requestPacket, System.Threading.CancellationToken cancellationToken) [0x001a3] in <1d26aa7eaa5a4094a08c8933437012f1>:0
  at MQTTnet.Client.MqttClient.AuthenticateAsync (MQTTnet.Client.MqttClientOptions options, System.Threading.CancellationToken cancellationToken) [0x0008f] in <1d26aa7eaa5a4094a08c8933437012f1>:0
   --- End of inner exception stack trace ---
  at MQTTnet.Client.MqttClient.AuthenticateAsync (MQTTnet.Client.MqttClientOptions options, System.Threading.CancellationToken cancellationToken) [0x000cd] in <1d26aa7eaa5a4094a08c8933437012f1>:0
  at MQTTnet.Client.MqttClient.ConnectAsync (MQTTnet.Client.MqttClientOptions options, System.Threading.CancellationToken cancellationToken) [0x00339] in <1d26aa7eaa5a4094a08c8933437012f1>:0
>> [3/24/2023 3:52:50 PM] [8] [MqttClient] [Verbose]: Disconnected from adapter
>> [3/24/2023 3:52:50 PM] [8] [MqttClient] [Info]: Disconnected
>> [3/24/2023 3:52:50 PM] [8] [MqttClient] [Verbose]: Stopped receiving packets

Ubuntu 22.04, Mono 6.8.0.105, WebSockets4Net, to test.mosquitto.org:8081 (fails):

>> [3/24/2023 3:54:06 PM] [6] [MqttClient] [Verbose]: Trying to connect with server 'test.mosquitto.org:8081'
>> [3/24/2023 3:54:06 PM] [11] [MqttClient] [Verbose]: Connection with server established
>> [3/24/2023 3:54:06 PM] [9] [MqttClient] [Verbose]: Start receiving packets
>> [3/24/2023 3:54:06 PM] [11] [MqttChannelAdapter] [Verbose]: TX (69 bytes) >>> Connect: [ClientId=xx-redacted-xx] [Username=] [Password=] [KeepAlivePeriod=15] [CleanSession=True

Ubuntu 22.04, Mono 6.8.0.105, WebSockets4Net, to AWS (fails):

>> [3/24/2023 3:55:10 PM] [6] [MqttClient] [Verbose]: Trying to connect with server 'iot.eu-west-1.xx-redacted-xx.com'
>> [3/24/2023 3:55:10 PM] [9] [MqttClient] [Verbose]: Connection with server established
>> [3/24/2023 3:55:10 PM] [9] [MqttChannelAdapter] [Verbose]: TX (69 bytes) >>> Connect: [ClientId=xx-redacted-xx] [Username=] [Password=] [KeepAlivePeriod=15] [CleanSession=True
>> [3/24/2023 3:55:10 PM] [8] [MqttClient] [Verbose]: Start receiving packets

Windows always works. But Mono only works with standard WebSockets and the mosquitto server. All other combinations do not (WebSockets to AWS fails, WebSockets4Net fails for both AWS and mosquitto).

Probably totally unrelated, but with Mono, the last ] is missing from the trace ("[CleanSession=True" instead of "[CleanSession=True]").

[logicaloud]

Just in case this is bumping into the same kind of problem, does it work with the change just mentioned in #1690?

[stefxx]

Unfortunately, the change in #1690 does not make any different for this issue.

[stefxx]

Anyone? I really appreciate any input on this. Thanks!

[logicaloud]

Can you try with the latest version of Mono?

[stefxx]

I've upgrade to mono 6.12.0.182. Unfortunately no difference.

Please let me know what else I can try. Thanks!

[chkr1011]

Please try attaching to the InspectPackage event. It will give you access to the binary packages which are sent over the wire.
After doing this please check if the packets are different than expected in terms of length etc. This binary data may contain sensitive information like username and passwords etc.

[chkr1011]

Also please check the URI you are using. I only see "test.mosquitto.org:8081" in your trace but I would expect something similar to "wss://test.mosquitto.org:8081/mqtt" etc. Please share the code you are using in order to prepare the web socket connection.

[stefxx]

Thanks!

Adding "wss://" or "/mqtt" to the server address doesn't seem to make any difference.

This is the (simplified) code I use to connect and test:

Dim TlsParameters As New MqttClientOptionsBuilderTlsParameters() With {
	.SslProtocol = SslProtocols.Tls12,
	.UseTls = True
}

Dim ClientWebSocketOptions As New MqttClientOptionsBuilderWebSocketParameters With {
	.PreferUnfragmentedMessages = True,
	.RequestHeaders = New Dictionary(Of String, String) From {
		{"jwt", Token},
		{"x-amz-customauthorizer-signature", Signature}
	}
}

Dim ClientOptions As New MqttClientOptionsBuilder()
ClientOptions.WithClientId("XX/USER/123456/bot/" & Cloud.uuid())
ClientOptions.WithWebSocketServer("wss://" & Cloud.mqtt_endpoint & "/mqtt", ClientWebSocketOptions)
ClientOptions.WithTls(TlsParameters)

Dim mqttFactory = New MqttFactory()
Dim mqttEventLogger = New MqttNetEventLogger()

AddHandler mqttEventLogger.LogMessagePublished, AddressOf MqttTrace
AddHandler mqttClient.ConnectedAsync, AddressOf MqttConnected
AddHandler mqttClient.DisconnectedAsync, AddressOf MqttDisconnected
AddHandler mqttClient.ApplicationMessageReceivedAsync, AddressOf MqttMessage

Dim MqttResult = mqttClient.ConnectAsync(ClientOptions.Build()).GetAwaiter().GetResult()

Not sure how to use the InspectPackage, but this is what I have:

AddHandler mqttClient.InspectPackage, AddressOf MqttInspect
Function MqttInspect(e As InspectMqttPacketEventArgs)
    Console.WriteLine("-> " & Encoding.UTF8.GetString(e.Buffer))
End Function

It is giving me quite a few errors, but also reveals some data. On Windows the connection is still working.

Using "Ubuntu 22.04, Mono 6.12.0.182, WebSockets, to AWS" this is what i see:

>> [4/10/2023 3:28:54 PM] [6] [MqttClient] [Verbose]: Trying to connect with server 'wss://iot.eu-west-1.x-redacted.com/mqtt'
>> [4/10/2023 3:28:54 PM] [8] [MqttClient] [Verbose]: Connection with server established
>> [4/10/2023 3:28:54 PM] [9] [MqttClient] [Verbose]: Start receiving packets
-> CMQTT7XX/USER/123456/bot/8082d8c5-2a70-4c4c-b376-4dc84035d27d
>> [4/10/2023 3:28:54 PM] [8] [MqttPacketInspector] [Error]: Error while inspecting packet.
System.NullReferenceException: Object reference not set to an instance of an object
  at MQTTnet.Internal.AsyncEvent`1[TEventArgs].InvokeAsync (TEventArgs eventArgs) [0x00050] in <11c8311afd094470a39f84850c2dc4da>:0
  at MQTTnet.Adapter.MqttPacketInspector.InspectPacket (System.Byte[] buffer, MQTTnet.Diagnostics.MqttPacketFlowDirection direction) [0x0001a] in <11c8311afd094470a39f84850c2dc4da>:0
>> [4/10/2023 3:28:54 PM] [8] [MqttChannelAdapter] [Verbose]: TX (69 bytes) >>> Connect: [ClientId=XX/USER/123456/bot/8082d8c5-2a70-4c4c-b376-4dc84035d27d] [Username=] [Password=] [KeepAlivePeriod=15] [CleanSession=True
>> [4/10/2023 3:28:54 PM] [9] [MqttClient] [Verbose]: Disconnecting [Timeout=00:01:40
>> [4/10/2023 3:28:54 PM] [11] [MqttClient] [Warning]: Timeout while waiting for response packet (MqttConnAckPacket)
>> [4/10/2023 3:28:54 PM] [11] [MqttClient] [Error]: Error while connecting with server.
MQTTnet.Adapter.MqttConnectingFailedException: Error while authenticating. The operation has timed out. ---> MQTTnet.Exceptions.MqttCommunicationTimedOutException: The operation has timed out.
  at MQTTnet.PacketDispatcher.MqttPacketAwaitable`1[TPacket].WaitOneAsync (System.Threading.CancellationToken cancellationToken) [0x00092] in <11c8311afd094470a39f84850c2dc4da>:0
  at MQTTnet.Client.MqttClient.SendAndReceiveAsync[TResponsePacket] (MQTTnet.Packets.MqttPacket requestPacket, System.Threading.CancellationToken cancellationToken) [0x001a3] in <11c8311afd094470a39f84850c2dc4da>:0
  at MQTTnet.Client.MqttClient.AuthenticateAsync (MQTTnet.Client.MqttClientOptions options, System.Threading.CancellationToken cancellationToken) [0x0008f] in <11c8311afd094470a39f84850c2dc4da>:0
   --- End of inner exception stack trace ---
  at MQTTnet.Client.MqttClient.AuthenticateAsync (MQTTnet.Client.MqttClientOptions options, System.Threading.CancellationToken cancellationToken) [0x000d2] in <11c8311afd094470a39f84850c2dc4da>:0
  at MQTTnet.Client.MqttClient.ConnectInternal (System.Threading.CancellationToken cancellationToken) [0x001e4] in <11c8311afd094470a39f84850c2dc4da>:0
  at MQTTnet.Client.MqttClient.ConnectAsync (MQTTnet.Client.MqttClientOptions options, System.Threading.CancellationToken cancellationToken) [0x0028d] in <11c8311afd094470a39f84850c2dc4da>:0
>> [4/10/2023 3:28:54 PM] [9] [MqttClient] [Verbose]: Disconnected from adapter
>> [4/10/2023 3:28:54 PM] [9] [MqttClient] [Info]: Disconnected
>> [4/10/2023 3:28:54 PM] [9] [MqttClient] [Verbose]: Stopped receiving packets

As you can see, the InspectPackage output ("CMQTT7XX/USER/123456/bot/8082d8c5-2a70-4c4c-b376-4dc84035d27d") includes the expected text for a connection. I assume the "CMQTT7" is part of the binary data, required for the actual communication?

[logicaloud]

Is your AWS server certificate trusted on Ubuntu?

For testing, you could try to always trust the server certificate, i.e. add a CertificateValidationHandler to the TlsParameters that always returns true .

[stefxx]

Is your AWS server certificate trusted on Ubuntu?

I am pretty sure it is. But I have tried to ignore any certificate errors anyway, by adding this to TlsParameters:

    .AllowUntrustedCertificates = True,
    .IgnoreCertificateChainErrors = True,
    .IgnoreCertificateRevocationErrors = True,
    .CertificateValidationHandler = Function() True
    

Unfortunately, that gave me an error:
MQTTnet.Exceptions.MqttCommunicationException: Remote certificate validation callback is not supported when using 'net461'.

So I remove the .CertificateValidationHandler and added this instead:

ServicePointManager.ServerCertificateValidationCallback = Function(s, c, h, e) True

However, the result still fails with the same error.

[logicaloud]

Can you see the ServerCertificateValidationCallback being hit?

There is an open issue here: mono/mono#8660

[stefxx]

No, the ServerCertificateValidationCallback is never being hit. However, I do believe the certificate is trusted. Any way I can check that?

Also, the log shows "Connection with server established" and "Start receiving packets", doesn't that mean the Certificate is already being validated?

[logicaloud]

Ah, yes, I think you are right; trust is probably not the issue.

[stefxx]

Thanks @logicaloud .

Open for any other suggestions to resolve this issue!