Skip to content
New issue

Have a question about this project? Sign up for a free GitHub account to open an issue and contact its maintainers and the community.

By clicking “Sign up for GitHub”, you agree to our terms of service and privacy statement. We’ll occasionally send you account related emails.

Already on GitHub? Sign in to your account

SSL Authentication error thrown when opening many connections in parallel #1448

Closed
madelson opened this issue Feb 10, 2024 · 8 comments
Closed
Labels

Comments

@madelson
Copy link

madelson commented Feb 10, 2024

Software versions
MySqlConnector version: 2.3.5
Server type (MySQL, MariaDB, Aurora, etc.) and version: MySQL Community Edition 8.2.0 on Windows
.NET version: 8

Describe the bug
When I try to open a large number of connections in parallel, I get SSL Authentication Error failures.

Exception

MySqlConnector.MySqlException (0x80004005): SSL Authentication Error
 ---> System.Security.Authentication.AuthenticationException: Authentication failed because the remote party sent a TLS alert: 'IllegalParameter'.
 ---> System.ComponentModel.Win32Exception (0x80090326): The message received was unexpected or badly formatted.
   --- End of inner exception stack trace ---
   at System.Net.Security.SslStream.ForceAuthenticationAsync[TIOAdapter](Boolean receiveFirst, Byte[] reAuthenticationData, CancellationToken cancellationToken)
   at System.Net.Security.SslStream.AuthenticateAsClient(SslClientAuthenticationOptions sslClientAuthenticationOptions)
   at MySqlConnector.Core.ServerSession.InitSslAsync(ProtocolCapabilities serverCapabilities, ConnectionSettings cs, MySqlConnection connection, SslProtocols sslProtocols, IOBehavior ioBehavior, CancellationToken cancellationToken) in /_/src/MySqlConnector/Core/ServerSession.cs:line 1445
   at MySqlConnector.Core.ServerSession.InitSslAsync(ProtocolCapabilities serverCapabilities, ConnectionSettings cs, MySqlConnection connection, SslProtocols sslProtocols, IOBehavior ioBehavior, CancellationToken cancellationToken) in /_/src/MySqlConnector/Core/ServerSession.cs:line 1472
   at MySqlConnector.Core.ServerSession.ConnectAsync(ConnectionSettings cs, MySqlConnection connection, Int64 startingTimestamp, ILoadBalancer loadBalancer, Activity activity, IOBehavior ioBehavior, CancellationToken cancellationToken) in /_/src/MySqlConnector/Core/ServerSession.cs:line 523
   at MySqlConnector.Core.ConnectionPool.ConnectSessionAsync(MySqlConnection connection, Action`4 logMessage, Int64 startingTimestamp, Activity activity, IOBehavior ioBehavior, CancellationToken cancellationToken) in /_/src/MySqlConnector/Core/ConnectionPool.cs:line 428
   at MySqlConnector.Core.ConnectionPool.ConnectSessionAsync(MySqlConnection connection, Action`4 logMessage, Int64 startingTimestamp, Activity activity, IOBehavior ioBehavior, CancellationToken cancellationToken) in /_/src/MySqlConnector/Core/ConnectionPool.cs:line 433
   at MySqlConnector.Core.ConnectionPool.GetSessionAsync(MySqlConnection connection, Int64 startingTimestamp, Int32 timeoutMilliseconds, Activity activity, IOBehavior ioBehavior, CancellationToken cancellationToken) in /_/src/MySqlConnector/Core/ConnectionPool.cs:line 111
   at MySqlConnector.Core.ConnectionPool.GetSessionAsync(MySqlConnection connection, Int64 startingTimestamp, Int32 timeoutMilliseconds, Activity activity, IOBehavior ioBehavior, CancellationToken cancellationToken) in /_/src/MySqlConnector/Core/ConnectionPool.cs:line 144
   at MySqlConnector.MySqlConnection.CreateSessionAsync(ConnectionPool pool, Int64 startingTimestamp, Activity activity, Nullable`1 ioBehavior, CancellationToken cancellationToken) in /_/src/MySqlConnector/MySqlConnection.cs:line 919
   at MySqlConnector.MySqlConnection.OpenAsync(Nullable`1 ioBehavior, CancellationToken cancellationToken) in /_/src/MySqlConnector/MySqlConnection.cs:line 419
   at MySqlConnector.MySqlConnection.Open() in /_/src/MySqlConnector/MySqlConnection.cs:line 381

Code sample

	var cs = new MySqlConnectionStringBuilder
	{
		Port = 3307,
		Server = "localhost",
		Database = "mysql",
		UserID = "...",
		Password = "...",
                //TlsVersion = "Tls12", // setting this seems to fix it as well
	}.ConnectionString;
	var connections = Enumerable.Range(0, 100).Select(c => new MySqlConnection(cs)).ToArray();
        // NOTE: lowering MaxDOP to 1 eliminates the error
	Parallel.ForEach(connections, new ParallelOptions { MaxDegreeOfParallelism = 1000 }, c =>
	{
		c.Open(); // throws
	});

Expected behavior
I would expect this code to run without error.

Additional context
I also tested this with some older versions of MySqlConnector (1.x, 2.2.x) and all seemed to exhibit the issue.

EDIT: I realized that setting Tls12 specifically also seems to fix it. There are some other issues floating around in the repo regarding that so apologies if this is a dupe.

@bgrainger
Copy link
Member

I tried using mysql:8.3 Docker image and downloading MySQL Community Edition for Windows 8.2.0 from https://downloads.mysql.com/archives/community/ but couldn't reproduce a TLS failure with the sample code provided.

Do you have any server-side logs from when this fails?

We might need to see a Wireshark packet capture of the TLS negotiation failure (although with 100 concurrent connections it might be difficult to identify the one exhibiting the problem).

@madelson
Copy link
Author

Do you have any server-side logs from when this fails?

I turned on verbose error logging and here's what I see in C:\ProgramData\MySQL\MySQL Server 8.2\Data\<MACHINENAME>.err:

2024-02-11T02:20:03.552024Z 171 [Note] [MY-010914] [Server] Aborted connection 171 to db: 'mysql' user: 'MyDatabase' host: 'localhost' (Got an error reading communication packets).
2024-02-11T02:20:03.552533Z 163 [Note] [MY-010914] [Server] Aborted connection 163 to db: 'mysql' user: 'MyDatabase' host: 'localhost' (Got an error reading communication packets).
2024-02-11T02:20:03.552476Z 169 [Note] [MY-010914] [Server] Aborted connection 169 to db: 'mysql' user: 'MyDatabase' host: 'localhost' (Got an error reading communication packets).
2024-02-11T02:20:03.552764Z 167 [Note] [MY-010914] [Server] Aborted connection 167 to db: 'mysql' user: 'MyDatabase' host: 'localhost' (Got an error reading communication packets).
2024-02-11T02:20:03.552769Z 172 [Note] [MY-010914] [Server] Aborted connection 172 to db: 'mysql' user: 'MyDatabase' host: 'localhost' (Got an error reading communication packets).
2024-02-11T02:20:03.552812Z 160 [Note] [MY-010914] [Server] Aborted connection 160 to db: 'mysql' user: 'MyDatabase' host: 'localhost' (Got an error reading communication packets).
2024-02-11T02:20:03.552815Z 161 [Note] [MY-010914] [Server] Aborted connection 161 to db: 'mysql' user: 'MyDatabase' host: 'localhost' (Got an error reading communication packets).
2024-02-11T02:20:03.552921Z 165 [Note] [MY-010914] [Server] Aborted connection 165 to db: 'mysql' user: 'MyDatabase' host: 'localhost' (Got an error reading communication packets).
2024-02-11T02:20:03.552945Z 168 [Note] [MY-010914] [Server] Aborted connection 168 to db: 'mysql' user: 'MyDatabase' host: 'localhost' (Got an error reading communication packets).
2024-02-11T02:20:03.556516Z 152 [Note] [MY-010914] [Server] Aborted connection 152 to db: 'mysql' user: 'MyDatabase' host: 'localhost' (Got an error reading communication packets).
2024-02-11T02:20:03.556968Z 149 [Note] [MY-010914] [Server] Aborted connection 149 to db: 'mysql' user: 'MyDatabase' host: 'localhost' (Got an error reading communication packets).
2024-02-11T02:20:03.553217Z 116 [Note] [MY-010914] [Server] Aborted connection 116 to db: 'mysql' user: 'MyDatabase' host: 'localhost' (Got an error reading communication packets).
2024-02-11T02:20:03.553252Z 164 [Note] [MY-010914] [Server] Aborted connection 164 to db: 'mysql' user: 'MyDatabase' host: 'localhost' (Got an error reading communication packets).
2024-02-11T02:20:03.553288Z 122 [Note] [MY-010914] [Server] Aborted connection 122 to db: 'mysql' user: 'MyDatabase' host: 'localhost' (Got an error reading communication packets).
2024-02-11T02:20:03.553319Z 115 [Note] [MY-010914] [Server] Aborted connection 115 to db: 'mysql' user: 'MyDatabase' host: 'localhost' (Got an error reading communication packets).
2024-02-11T02:20:03.553447Z 114 [Note] [MY-010914] [Server] Aborted connection 114 to db: 'mysql' user: 'MyDatabase' host: 'localhost' (Got an error reading communication packets).
2024-02-11T02:20:03.553681Z 109 [Note] [MY-010914] [Server] Aborted connection 109 to db: 'mysql' user: 'MyDatabase' host: 'localhost' (Got an error reading communication packets).
2024-02-11T02:20:03.553851Z 119 [Note] [MY-010914] [Server] Aborted connection 119 to db: 'mysql' user: 'MyDatabase' host: 'localhost' (Got an error reading communication packets).
2024-02-11T02:20:03.553870Z 123 [Note] [MY-010914] [Server] Aborted connection 123 to db: 'mysql' user: 'MyDatabase' host: 'localhost' (Got an error reading communication packets).
2024-02-11T02:20:03.553919Z 117 [Note] [MY-010914] [Server] Aborted connection 117 to db: 'mysql' user: 'MyDatabase' host: 'localhost' (Got an error reading communication packets).
2024-02-11T02:20:03.553962Z 120 [Note] [MY-010914] [Server] Aborted connection 120 to db: 'mysql' user: 'MyDatabase' host: 'localhost' (Got an error reading communication packets).
2024-02-11T02:20:03.554003Z 124 [Note] [MY-010914] [Server] Aborted connection 124 to db: 'mysql' user: 'MyDatabase' host: 'localhost' (Got an error reading communication packets).
2024-02-11T02:20:03.554086Z 112 [Note] [MY-010914] [Server] Aborted connection 112 to db: 'mysql' user: 'MyDatabase' host: 'localhost' (Got an error reading communication packets).
2024-02-11T02:20:03.554121Z 118 [Note] [MY-010914] [Server] Aborted connection 118 to db: 'mysql' user: 'MyDatabase' host: 'localhost' (Got an error reading communication packets).
2024-02-11T02:20:03.554173Z 111 [Note] [MY-010914] [Server] Aborted connection 111 to db: 'mysql' user: 'MyDatabase' host: 'localhost' (Got an error reading communication packets).
2024-02-11T02:20:03.554320Z 108 [Note] [MY-010914] [Server] Aborted connection 108 to db: 'mysql' user: 'MyDatabase' host: 'localhost' (Got an error reading communication packets).
2024-02-11T02:20:03.554374Z 110 [Note] [MY-010914] [Server] Aborted connection 110 to db: 'mysql' user: 'MyDatabase' host: 'localhost' (Got an error reading communication packets).
2024-02-11T02:20:03.554446Z 113 [Note] [MY-010914] [Server] Aborted connection 113 to db: 'mysql' user: 'MyDatabase' host: 'localhost' (Got an error reading communication packets).
2024-02-11T02:20:03.554691Z 159 [Note] [MY-010914] [Server] Aborted connection 159 to db: 'mysql' user: 'MyDatabase' host: 'localhost' (Got an error reading communication packets).
2024-02-11T02:20:03.555041Z 128 [Note] [MY-010914] [Server] Aborted connection 128 to db: 'mysql' user: 'MyDatabase' host: 'localhost' (Got an error reading communication packets).
2024-02-11T02:20:03.555049Z 125 [Note] [MY-010914] [Server] Aborted connection 125 to db: 'mysql' user: 'MyDatabase' host: 'localhost' (Got an error reading communication packets).
2024-02-11T02:20:03.555182Z 129 [Note] [MY-010914] [Server] Aborted connection 129 to db: 'mysql' user: 'MyDatabase' host: 'localhost' (Got an error reading communication packets).
2024-02-11T02:20:03.555190Z 150 [Note] [MY-010914] [Server] Aborted connection 150 to db: 'mysql' user: 'MyDatabase' host: 'localhost' (Got an error reading communication packets).
2024-02-11T02:20:03.555269Z 140 [Note] [MY-010914] [Server] Aborted connection 140 to db: 'mysql' user: 'MyDatabase' host: 'localhost' (Got an error reading communication packets).
2024-02-11T02:20:03.555341Z 141 [Note] [MY-010914] [Server] Aborted connection 141 to db: 'mysql' user: 'MyDatabase' host: 'localhost' (Got an error reading communication packets).
2024-02-11T02:20:03.555449Z 126 [Note] [MY-010914] [Server] Aborted connection 126 to db: 'mysql' user: 'MyDatabase' host: 'localhost' (Got an error reading communication packets).
2024-02-11T02:20:03.555598Z 145 [Note] [MY-010914] [Server] Aborted connection 145 to db: 'mysql' user: 'MyDatabase' host: 'localhost' (Got an error reading communication packets).
2024-02-11T02:20:03.555766Z 138 [Note] [MY-010914] [Server] Aborted connection 138 to db: 'mysql' user: 'MyDatabase' host: 'localhost' (Got an error reading communication packets).
2024-02-11T02:20:03.555833Z 130 [Note] [MY-010914] [Server] Aborted connection 130 to db: 'mysql' user: 'MyDatabase' host: 'localhost' (Got an error reading communication packets).
2024-02-11T02:20:03.555875Z 137 [Note] [MY-010914] [Server] Aborted connection 137 to db: 'mysql' user: 'MyDatabase' host: 'localhost' (Got an error reading communication packets).
2024-02-11T02:20:03.555942Z 139 [Note] [MY-010914] [Server] Aborted connection 139 to db: 'mysql' user: 'MyDatabase' host: 'localhost' (Got an error reading communication packets).
2024-02-11T02:20:03.556044Z 133 [Note] [MY-010914] [Server] Aborted connection 133 to db: 'mysql' user: 'MyDatabase' host: 'localhost' (Got an error reading communication packets).
2024-02-11T02:20:03.556150Z 131 [Note] [MY-010914] [Server] Aborted connection 131 to db: 'mysql' user: 'MyDatabase' host: 'localhost' (Got an error reading communication packets).
2024-02-11T02:20:03.556219Z 127 [Note] [MY-010914] [Server] Aborted connection 127 to db: 'mysql' user: 'MyDatabase' host: 'localhost' (Got an error reading communication packets).
2024-02-11T02:20:03.556328Z 136 [Note] [MY-010914] [Server] Aborted connection 136 to db: 'mysql' user: 'MyDatabase' host: 'localhost' (Got an error reading communication packets).
2024-02-11T02:20:03.556333Z 134 [Note] [MY-010914] [Server] Aborted connection 134 to db: 'mysql' user: 'MyDatabase' host: 'localhost' (Got an error reading communication packets).
2024-02-11T02:20:03.556529Z 147 [Note] [MY-010914] [Server] Aborted connection 147 to db: 'mysql' user: 'MyDatabase' host: 'localhost' (Got an error reading communication packets).
2024-02-11T02:20:03.556617Z 153 [Note] [MY-010914] [Server] Aborted connection 153 to db: 'mysql' user: 'MyDatabase' host: 'localhost' (Got an error reading communication packets).
2024-02-11T02:20:03.556639Z 135 [Note] [MY-010914] [Server] Aborted connection 135 to db: 'mysql' user: 'MyDatabase' host: 'localhost' (Got an error reading communication packets).
2024-02-11T02:20:03.553103Z 162 [Note] [MY-010914] [Server] Aborted connection 162 to db: 'mysql' user: 'MyDatabase' host: 'localhost' (Got an error reading communication packets).
2024-02-11T02:20:03.556685Z 154 [Note] [MY-010914] [Server] Aborted connection 154 to db: 'mysql' user: 'MyDatabase' host: 'localhost' (Got an error reading communication packets).
2024-02-11T02:20:03.556720Z 132 [Note] [MY-010914] [Server] Aborted connection 132 to db: 'mysql' user: 'MyDatabase' host: 'localhost' (Got an error reading communication packets).
2024-02-11T02:20:03.556767Z 157 [Note] [MY-010914] [Server] Aborted connection 157 to db: 'mysql' user: 'MyDatabase' host: 'localhost' (Got an error reading communication packets).
2024-02-11T02:20:03.556808Z 146 [Note] [MY-010914] [Server] Aborted connection 146 to db: 'mysql' user: 'MyDatabase' host: 'localhost' (Got an error reading communication packets).
2024-02-11T02:20:03.556825Z 156 [Note] [MY-010914] [Server] Aborted connection 156 to db: 'mysql' user: 'MyDatabase' host: 'localhost' (Got an error reading communication packets).
2024-02-11T02:20:03.556860Z 148 [Note] [MY-010914] [Server] Aborted connection 148 to db: 'mysql' user: 'MyDatabase' host: 'localhost' (Got an error reading communication packets).
2024-02-11T02:20:03.556892Z 155 [Note] [MY-010914] [Server] Aborted connection 155 to db: 'mysql' user: 'MyDatabase' host: 'localhost' (Got an error reading communication packets).
2024-02-11T02:20:03.556947Z 158 [Note] [MY-010914] [Server] Aborted connection 158 to db: 'mysql' user: 'MyDatabase' host: 'localhost' (Got an error reading communication packets).
2024-02-11T02:20:03.557050Z 170 [Note] [MY-010914] [Server] Aborted connection 170 to db: 'mysql' user: 'MyDatabase' host: 'localhost' (Got an error reading communication packets).
2024-02-11T02:20:03.557069Z 151 [Note] [MY-010914] [Server] Aborted connection 151 to db: 'mysql' user: 'MyDatabase' host: 'localhost' (Got an error reading communication packets).
2024-02-11T02:20:03.553188Z 121 [Note] [MY-010914] [Server] Aborted connection 121 to db: 'mysql' user: 'MyDatabase' host: 'localhost' (Got an error reading communication packets).
2024-02-11T02:20:03.557180Z 174 [Note] [MY-010914] [Server] Aborted connection 174 to db: 'mysql' user: 'MyDatabase' host: 'localhost' (Got an error reading communication packets).
2024-02-11T02:20:03.557216Z 166 [Note] [MY-010914] [Server] Aborted connection 166 to db: 'mysql' user: 'MyDatabase' host: 'localhost' (Got an error reading communication packets).
2024-02-11T02:20:03.557278Z 173 [Note] [MY-010914] [Server] Aborted connection 173 to db: 'mysql' user: 'MyDatabase' host: 'localhost' (Got an error reading communication packets).
2024-02-11T02:20:03.557324Z 175 [Note] [MY-010914] [Server] Aborted connection 175 to db: 'mysql' user: 'MyDatabase' host: 'localhost' (Got an error reading communication packets).
2024-02-11T02:20:03.557382Z 178 [Note] [MY-010914] [Server] Aborted connection 178 to db: 'mysql' user: 'MyDatabase' host: 'localhost' (Got an error reading communication packets).
2024-02-11T02:20:03.557391Z 177 [Note] [MY-010914] [Server] Aborted connection 177 to db: 'mysql' user: 'MyDatabase' host: 'localhost' (Got an error reading communication packets).
2024-02-11T02:20:03.978410Z 210 [Note] [MY-010914] [Server] Bad handshake
2024-02-11T02:20:03.980998Z 213 [Note] [MY-010914] [Server] Bad handshake

@pealmeid
Copy link

I'm having a similar issue when connecting an ASPNET Core (version 8) solution to a MySQL server (version 8.0.36) using the Pomelo EF provider (version 8.0.2) and MySqlConnector version 2.3.5 (loaded transitively by the Pomelo provider), but it happens intermittently and for fewer connections than described by @madelson (sometimes as few as 6 parallel requests).

When the error occurs, ASPNET Core throws an exception with the following message:

MySqlConnector.MySqlException: 'SSL Authentication Error'
AuthenticationException: Authentication failed because the remote party sent a TLS alert: 'IllegalParameter'.

I did some research and came across a similar issue described in dotnet/runtime#77393 (comment), and following their solution I was able to prevent the error from happening by disabling TLS 1.3 in the Windows system running the solution, but that is not a permanent solution. Also, please note we were not able to reproduce the error in a Mac machine.

I hope this can provide some insight into the issue and I'm looking forward to a solution. Thanks in advance.

@bgrainger
Copy link
Member

I was able to prevent the error from happening by disabling TLS 1.3

Can you try reverting that registry change and using ;TlsVersion = TLS 1.2 in your connection string (see TlsVersion) to force MySqlConnector to only use TLS 1.2, and see if that also works around the issue?

@pealmeid
Copy link

Yes it works. I did as you suggested (reverted the registry change and modified the connection string) and the error stopped happening. This is a much less intrusive solution, thanks for the help.

@bgrainger
Copy link
Member

MySqlConnector just calls SslStream.AuthenticateAsClient(Async) to do all the "heavy lifting" of making a TLS connection, which in turn will delegate to Schannel (on Windows, or OpenSSL on Linux). If there's an System.Security.Authentication.AuthenticationException being thrown, that's coming from .NET or Windows. Being able to work around the problem by putting Tls Version in the connection string also seems like an indication that the problem may be somewhere within SslStream or Schannel.

A Wireshark packet capture (of successful and unsuccessful connections) may help isolate the problem, but we might need to pass the packet capture to the .NET team for deeper investigation; it seems unlikely to me that this is a MySqlConnector problem.

@TimMurphy
Copy link

I had the same problem running unit tests with ReSharper's test runner. I have it set to run 8 tests in parallel. The problem was interminent but if I choose "Run Test until Fail" it would fail within 5 or so runs.

Adding TlsVersion = TLS 1.2 to the connection string has solved the problem.

@bgrainger
Copy link
Member

This appears to be an issue with the underlying OS/.NET TLS implementation, and users have found a workaround.

@bgrainger bgrainger closed this as not planned Won't fix, can't repro, duplicate, stale Oct 20, 2024
Sign up for free to join this conversation on GitHub. Already have an account? Sign in to comment
Labels
Development

No branches or pull requests

4 participants