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.

Sign up for GitHub

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

Jump to bottom

Authentication failed because the remote party sent a TLS alert: 'ProtocolVersion' #1407

Open
jkuek opened this issue Dec 4, 2023 · 17 comments
Open

Authentication failed because the remote party sent a TLS alert: 'ProtocolVersion' #1407

jkuek opened this issue Dec 4, 2023 · 17 comments

Comments

@jkuek
Copy link

jkuek commented Dec 4, 2023 •
edited by bgrainger

Software versions
MySqlConnector version: 2.3.1
Application running on EC2 Windows Server 2022 10.0.20348 N/A Build 20348
Server type (MySQL, MariaDB, Aurora, etc.) and version: AWS Aurora MySQL 3.05.0
.NET version: 6.0.23

Describe the bug
I'm connecting to an Aurora cluster with a single instance.

Occasionally there is an exception when opening connections: Authentication failed because the remote party sent a TLS alert: 'ProtocolVersion'.

My connection string is as follows:

server=db.test.internal;uid=api-test;pwd=*redacted*;database=data;AllowUserVariables=True;SSLMode=required;Pooling=True;ConnectionLifeTime=15
;MaximumPoolsize=20;GuidFormat=Binary16;

I was previously on MySQLConnector 2.2.7 but have upgraded to 2.3.1 and the issue still exists.

This issue seems to be related to TLS v1.3. If I change the cluster parameter group "tls_version" setting to "TLSv1.2" then the issue doesn't occur. If I set it to "TLSv1.3" or leave it as default (which is both 1.2 and 1.3) then I get the occasional exception.

I am not certain this issue is MySqlConnector-related, but I'm not sure how to pursue it further. Is there some debug I can enable?

Exception

`MySqlConnector.MySqlException (0x80004005): SSL Authentication Error
 ---> System.Security.Authentication.AuthenticationException: Authentication failed because the remote party sent a TLS alert: 'ProtocolVersion'.
 ---> 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](TIOAdapter adapter, Boolean receiveFirst, Byte[] reAuthenticationData, Boolean isApm)
   at MySqlConnector.Core.ServerSession.InitSslAsync(ProtocolCapabilities serverCapabilities, ConnectionSettings cs, MySqlConnection connection, SslProtocols sslProtocols, IOBehavior ioBehavior, CancellationToken cancellationToken) in /_/src/MySqlConnector/Core/ServerSession.cs:line 1476
   at MySqlConnector.Core.ServerSession.InitSslAsync(ProtocolCapabilities serverCapabilities, ConnectionSettings cs, MySqlConnection connection, SslProtocols sslProtocols, IOBehavior ioBehavior, CancellationToken cancellationToken) in /_/src/MySqlConnector/Core/ServerSession.cs:line 1514
   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 542
   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 493
   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 493
   at MySqlConnector.Core.ConnectionPool.GetSessionAsync(MySqlConnection connection, Int64 startingTimestamp, Int32 timeoutMilliseconds, Activity activity, IOBehavior ioBehavior, CancellationToken cancellationToken) in /_/src/MySqlConnector/Core/ConnectionPool.cs:line 148
   at MySqlConnector.Core.ConnectionPool.GetSessionAsync(MySqlConnection connection, Int64 startingTimestamp, Int32 timeoutMilliseconds, Activity activity, IOBehavior ioBehavior, CancellationToken cancellationToken) in /_/src/MySqlConnector/Core/ConnectionPool.cs:line 148
   at MySqlConnector.MySqlConnection.CreateSessionAsync(ConnectionPool pool, Int64 startingTimestamp, Activity activity, Nullable`1 ioBehavior, CancellationToken cancellationToken) in /_/src/MySqlConnector/MySqlConnection.cs:line 964
   at MySqlConnector.MySqlConnection.OpenAsync(Nullable`1 ioBehavior, CancellationToken cancellationToken) in /_/src/MySqlConnector/MySqlConnection.cs:line 453
   at Dapper.SqlMapper.QueryAsync[T](IDbConnection cnn, Type effectiveType, CommandDefinition command) in /_/Dapper/SqlMapper.Async.cs:line 418
   at Midgard.Api.DataRepository.GetOnlineStateAsync(Int32 customerId) in D:\a\1\s\midgard\Midgard\Api\DataRepository.cs:line 213`
@bgrainger
Copy link
Member

Normally I'd say this sounds like it's probably more related to your client OS or .NET version than MySqlConnector. However, I would expect that to consistently fail. If it only fails occasionally, there could be a client-side bug in falling back to a supported TLS version when connecting fails.

I'm not sure how to pursue it further. Is there some debug I can enable?

Enabling logging (at Debug or even Trace) level may provide some useful information about what's happening with the connection that throws an exception. https://mysqlconnector.net/diagnostics/logging/

@jkuek
Copy link
Author

jkuek commented Dec 4, 2023

Yes the intermittent nature of this issue is confusing me.

I'll attempt to get some further details from logging.

@jkuek
Copy link
Author

jkuek commented Dec 5, 2023 •
edited

OK, some further info. It appears the ProtocolVersion error is because it falls back to TLS 1.1 which is no longer supported in Aurora MySQL 3.05.0. But why the initial attempt with TLS 1.3 fails, I don't yet know. As before, it works most of the time.

Here's an example of one session that fails:

timestamp,message
1701754344293,"{""Timestamp"":""2023-12-05T05:32:24.2937290+00:00"",""Level"":""Debug"",""MessageTemplate"":""Pool 2 has no pooled session available; created new session 2.314"",""Properties"":{""SourceContext"":""MySqlConnector.ConnectionPool""}}"
1701754344331,"{""Timestamp"":""2023-12-05T05:32:24.3314641+00:00"",""Level"":""Debug"",""MessageTemplate"":""Session 2.314 made connection; server version 8.0.32; connection ID 1142; supports: compression False, attributes True, deprecate EOF True, cached metadata False, SSL True, session track True, pipelining True, query attributes True"",""Properties"":{""SourceContext"":""MySqlConnector.MySqlConnection""}}"
1701754344334,"{""Timestamp"":""2023-12-05T05:32:24.3333041+00:00"",""Level"":""Error"",""MessageTemplate"":""Session 2.314 couldn't initialize TLS connection"",""Exception"":""System.Security.Authentication.AuthenticationException: Authentication failed because the remote party sent a TLS alert: 'DecryptError'.\r
 ---> System.ComponentModel.Win32Exception (0x80090326): The message received was unexpected or badly formatted.\r
   --- End of inner exception stack trace ---\r
   at System.Net.Security.SslStream.ForceAuthenticationAsync[TIOAdapter](TIOAdapter adapter, Boolean receiveFirst, Byte[] reAuthenticationData, Boolean isApm)\r
   at MySqlConnector.Core.ServerSession.InitSslAsync(ProtocolCapabilities serverCapabilities, ConnectionSettings cs, MySqlConnection connection, SslProtocols sslProtocols, IOBehavior ioBehavior, CancellationToken cancellationToken) in /_/src/MySqlConnector/Core/ServerSession.cs:line 1476"",""Properties"":{""SourceContext"":""MySqlConnector.MySqlConnection""}}"
1701754344334,"{""Timestamp"":""2023-12-05T05:32:24.3344814+00:00"",""Level"":""Debug"",""MessageTemplate"":""Session 2.314 closing stream/socket"",""Properties"":{""SourceContext"":""MySqlConnector.MySqlConnection""}}"
1701754344336,"{""Timestamp"":""2023-12-05T05:32:24.3346118+00:00"",""Level"":""Warning"",""MessageTemplate"":""Session 2.314 failed negotiating TLS; falling back to TLS 1.1"",""Exception"":""MySqlConnector.MySqlException (0x80004005): SSL Authentication Error\r
 ---> System.Security.Authentication.AuthenticationException: Authentication failed because the remote party sent a TLS alert: 'DecryptError'.\r
 ---> System.ComponentModel.Win32Exception (0x80090326): The message received was unexpected or badly formatted.\r
   --- End of inner exception stack trace ---\r
   at System.Net.Security.SslStream.ForceAuthenticationAsync[TIOAdapter](TIOAdapter adapter, Boolean receiveFirst, Byte[] reAuthenticationData, Boolean isApm)\r
   at MySqlConnector.Core.ServerSession.InitSslAsync(ProtocolCapabilities serverCapabilities, ConnectionSettings cs, MySqlConnection connection, SslProtocols sslProtocols, IOBehavior ioBehavior, CancellationToken cancellationToken) in /_/src/MySqlConnector/Core/ServerSession.cs:line 1476\r
   at MySqlConnector.Core.ServerSession.InitSslAsync(ProtocolCapabilities serverCapabilities, ConnectionSettings cs, MySqlConnection connection, SslProtocols sslProtocols, IOBehavior ioBehavior, CancellationToken cancellationToken) in /_/src/MySqlConnector/Core/ServerSession.cs:line 1514\r
   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 542"",""Properties"":{""SourceContext"":""MySqlConnector.MySqlConnection""}}"
1701754344343,"{""Timestamp"":""2023-12-05T05:32:24.3433281+00:00"",""Level"":""Debug"",""MessageTemplate"":""Session 2.314 made connection; server version 8.0.32; connection ID 1143; supports: compression False, attributes True, deprecate EOF True, cached metadata False, SSL True, session track True, pipelining True, query attributes True"",""Properties"":{""SourceContext"":""MySqlConnector.MySqlConnection""}}"
1701754344344,"{""Timestamp"":""2023-12-05T05:32:24.3441688+00:00"",""Level"":""Error"",""MessageTemplate"":""Session 2.314 couldn't initialize TLS connection"",""Exception"":""System.Security.Authentication.AuthenticationException: Authentication failed because the remote party sent a TLS alert: 'ProtocolVersion'.\r
 ---> System.ComponentModel.Win32Exception (0x80090326): The message received was unexpected or badly formatted.\r
   --- End of inner exception stack trace ---\r
   at System.Net.Security.SslStream.ForceAuthenticationAsync[TIOAdapter](TIOAdapter adapter, Boolean receiveFirst, Byte[] reAuthenticationData, Boolean isApm)\r
   at MySqlConnector.Core.ServerSession.InitSslAsync(ProtocolCapabilities serverCapabilities, ConnectionSettings cs, MySqlConnection connection, SslProtocols sslProtocols, IOBehavior ioBehavior, CancellationToken cancellationToken) in /_/src/MySqlConnector/Core/ServerSession.cs:line 1476"",""Properties"":{""SourceContext"":""MySqlConnector.MySqlConnection""}}"
1701754344344,"{""Timestamp"":""2023-12-05T05:32:24.3446948+00:00"",""Level"":""Debug"",""MessageTemplate"":""Session 2.314 closing stream/socket"",""Properties"":{""SourceContext"":""MySqlConnector.MySqlConnection""}}"
1701754344344,"{""Timestamp"":""2023-12-05T05:32:24.3448650+00:00"",""Level"":""Debug"",""MessageTemplate"":""Session 2.314 closing stream/socket"",""Properties"":{""SourceContext"":""MySqlConnector.MySqlConnection""}}"

Note that the previous session 2.313 (which is actually happening at the same time) works as expected:

timestamp,message
1701754344293,"{""Timestamp"":""2023-12-05T05:32:24.2936253+00:00"",""Level"":""Debug"",""MessageTemplate"":""Pool 2 has no pooled session available; created new session 2.313"",""Properties"":{""SourceContext"":""MySqlConnector.ConnectionPool""}}"
1701754344327,"{""Timestamp"":""2023-12-05T05:32:24.3276289+00:00"",""Level"":""Debug"",""MessageTemplate"":""Session 2.313 made connection; server version 8.0.32; connection ID 1140; supports: compression False, attributes True, deprecate EOF True, cached metadata False, SSL True, session track True, pipelining True, query attributes True"",""Properties"":{""SourceContext"":""MySqlConnector.MySqlConnection""}}"
1701754344331,"{""Timestamp"":""2023-12-05T05:32:24.3312972+00:00"",""Level"":""Debug"",""MessageTemplate"":""Session 2.313 connected TLS using Tls13 and TLS_AES_256_GCM_SHA384"",""Properties"":{""SourceContext"":""MySqlConnector.MySqlConnection""}}"
1701754404640,"{""Timestamp"":""2023-12-05T05:33:24.6404598+00:00"",""Level"":""Debug"",""MessageTemplate"":""Pool 2 received expired session 2.313; destroying it"",""Properties"":{""SourceContext"":""MySqlConnector.ConnectionPool""}}"
1701754404640,"{""Timestamp"":""2023-12-05T05:33:24.6405207+00:00"",""Level"":""Debug"",""MessageTemplate"":""Session 2.313 closing stream/socket"",""Properties"":{""SourceContext"":""MySqlConnector.MySqlConnection""}}"

For more context, this is an ASP.NET Core app.

@bgrainger bgrainger mentioned this issue Dec 5, 2023
Closed
@jkuek
Copy link
Author

jkuek commented Dec 6, 2023

What could be the cause of the failed negotiation (i.e. the initial issue)?

Given it doesn't happen when TLS1.2 is used, that would rule out issues of connectivity or connection limits being hit.

Maybe there's a bug somewhere in the MySqlConnector/ASP .NET Core/Windows Server/Aurora chain. Is it possible that it's related to threading? (e.g. something about the TLS1.3 implementation that only rears its head when multiple connections are being made)

@bgrainger
Copy link
Member

But why the initial attempt with TLS 1.3 fails, I don't yet know. ... What could be the cause of the failed negotiation (i.e. the initial issue)?

Did you show logs from the initial failure, or just from the retry? Is Authentication failed because the remote party sent a TLS alert: 'DecryptError' the initial failure message?

@jkuek
Copy link
Author

jkuek commented Dec 6, 2023

Yes DecryptError looks like the initial failure:

  1. initial connection attempt
  2. DecryptError failure
  3. Fail over to TLS 1.1
  4. Retry connection attempt
  5. ProtocolVersion failure (server doesn't support TLS 1.1)

@bgrainger
Copy link
Member

I'd like to eliminate steps 3-5 above: #1409

However, that won't fix the failure in step 2. My general advice is to add retry support (e.g., with Polly); networks and database connections are unreliable (e.g., packets can be dropped or a server may have a transient error such as too many existing connections), so it often is best to retry for a certain number of attempts or a certain duration before definitively failing and raising an error.

@jkuek
Copy link
Author

jkuek commented Dec 10, 2023

Given both application server and database are in the same VPC, I would hope that reliability of network connections aren't to blame. If it was the case, why would switching to TLS1.2 "fix" the issue?

I'm happy to test again when #1409 is resolved.

@mikethea1
Copy link

I'm hitting this as well, also intermittently. Running MYSQL 8 community edition locally and connecting to it from local.

@bgrainger
Copy link
Member

I'm happy to test again when #1409 is resolved.

That's now fixed in 2.3.4.

@jkuek
Copy link
Author

jkuek commented Jan 16, 2024

@bgrainger I upgraded from 2.3.1 to 2.3.4 and the issue seems to be resolved. I no longer get any exceptions and can see in the logs that TLS1.3 connections are successfully made, .e.g. "Session 2.2044 connected TLS using Tls13 and TLS_AES_256_GCM_SHA384". So I suspect there was some bad code affecting the earlier versions when connecting to TLS 1.3, that only reared its head sometimes.

@mikethea1 Can you re-test with 2.3.4?

@jkuek
Copy link
Author

jkuek commented Feb 1, 2024 •
edited by bgrainger

I'm still seeing some DecryptError failures in my logs with MySqlConnector 2.3.4:

MySqlConnector.MySqlException (0x80004005): SSL Authentication Error
 ---> System.Security.Authentication.AuthenticationException: Authentication failed because the remote party sent a TLS alert: 'DecryptError'.
 ---> 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](TIOAdapter adapter, Boolean receiveFirst, Byte[] reAuthenticationData, Boolean isApm)
   at MySqlConnector.Core.ServerSession.InitSslAsync(ProtocolCapabilities serverCapabilities, ConnectionSettings cs, MySqlConnection connection, SslProtocols sslProtocols, IOBehavior ioBehavior, CancellationToken cancellationToken) in /_/src/MySqlConnector/Core/ServerSession.cs:line 1434
   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 493
   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 493
   at MySqlConnector.Core.ConnectionPool.GetSessionAsync(MySqlConnection connection, Int64 startingTimestamp, Int32 timeoutMilliseconds, Activity activity, IOBehavior ioBehavior, CancellationToken cancellationToken) in /_/src/MySqlConnector/Core/ConnectionPool.cs:line 146
   at MySqlConnector.Core.ConnectionPool.GetSessionAsync(MySqlConnection connection, Int64 startingTimestamp, Int32 timeoutMilliseconds, Activity activity, IOBehavior ioBehavior, CancellationToken cancellationToken) in /_/src/MySqlConnector/Core/ConnectionPool.cs:line 146
   at MySqlConnector.MySqlConnection.CreateSessionAsync(ConnectionPool pool, Int64 startingTimestamp, Activity activity, Nullable`1 ioBehavior, CancellationToken cancellationToken) in /_/src/MySqlConnector/MySqlConnection.cs:line 964
   at MySqlConnector.MySqlConnection.OpenAsync(Nullable`1 ioBehavior, CancellationToken cancellationToken) in /_/src/MySqlConnector/MySqlConnection.cs:line 453

I'll see if I can get some more information

@jkuek
Copy link
Author

jkuek commented Feb 2, 2024

Here's the debug-level logs from a failing connection:

timestamp message
1706835177240 {"Timestamp":"2024-02-02T00:52:57.2407737+00:00","Level":"Debug","MessageTemplate":"Pool 2 has no pooled session available; created new session 2.305","TraceId":"68e34878809360c935180044080ab64e","SpanId":"cfa91f6e807584f5","Properties":{"SourceContext":"MySqlConnector.ConnectionPool"}}
1706835177274 {"Timestamp":"2024-02-02T00:52:57.2746665+00:00","Level":"Debug","MessageTemplate":"Session 2.305 made connection; server version 8.0.32; connection ID 11102626; supports: compression False, attributes True, deprecate EOF True, cached metadata False, SSL True, session track True, pipelining True, query attributes True","TraceId":"68e34878809360c935180044080ab64e","SpanId":"cfa91f6e807584f5","Properties":{"SourceContext":"MySqlConnector.MySqlConnection"}}
1706835177277 {"Timestamp":"2024-02-02T00:52:57.2763719+00:00","Level":"Error","MessageTemplate":"Session 2.305 couldn't initialize TLS connection","TraceId":"68e34878809360c935180044080ab64e","SpanId":"cfa91f6e807584f5","Exception":"System.Security.Authentication.AuthenticationException: Authentication failed because the remote party sent a TLS alert: 'DecryptError'.\r\n ---> System.ComponentModel.Win32Exception (0x80090326): The message received was unexpected or badly formatted.\r\n --- End of inner exception stack trace ---\r\n at System.Net.Security.SslStream.ForceAuthenticationAsync[TIOAdapter](TIOAdapter adapter, Boolean receiveFirst, Byte[] reAuthenticationData, Boolean isApm)\r\n at MySqlConnector.Core.ServerSession.InitSslAsync(ProtocolCapabilities serverCapabilities, ConnectionSettings cs, MySqlConnection connection, SslProtocols sslProtocols, IOBehavior ioBehavior, CancellationToken cancellationToken) in /_/src/MySqlConnector/Core/ServerSession.cs:line 1434","Properties":{"SourceContext":"MySqlConnector.MySqlConnection"}}
1706835177277 {"Timestamp":"2024-02-02T00:52:57.2775160+00:00","Level":"Debug","MessageTemplate":"Session 2.305 closing stream/socket","TraceId":"68e34878809360c935180044080ab64e","SpanId":"cfa91f6e807584f5","Properties":{"SourceContext":"MySqlConnector.MySqlConnection"}}
1706835177277 {"Timestamp":"2024-02-02T00:52:57.2778059+00:00","Level":"Debug","MessageTemplate":"Session 2.305 closing stream/socket","TraceId":"68e34878809360c935180044080ab64e","SpanId":"cfa91f6e807584f5","Properties":{"SourceContext":"MySqlConnector.MySqlConnection"}}
1706835177287 {"Timestamp":"2024-02-02T00:52:57.2788197+00:00","Level":"Error","MessageTemplate":"Connection id "{ConnectionId}", Request id "{TraceIdentifier}": An unhandled exception was thrown by the application.","TraceId":"68e34878809360c935180044080ab64e","SpanId":"cfa91f6e807584f5","Exception":"MySqlConnector.MySqlException (0x80004005): SSL Authentication Error\r\n ---> System.Security.Authentication.AuthenticationException: Authentication failed because the remote party sent a TLS alert: 'DecryptError'.\r\n ---> System.ComponentModel.Win32Exception (0x80090326): The message received was unexpected or badly formatted.\r\n --- End of inner exception stack trace ---\r\n at System.Net.Security.SslStream.ForceAuthenticationAsync[TIOAdapter](TIOAdapter adapter, Boolean receiveFirst, Byte[] reAuthenticationData, Boolean isApm)\r\n at MySqlConnector.Core.ServerSession.InitSslAsync(ProtocolCapabilities serverCapabilities, ConnectionSettings cs, MySqlConnection connection, SslProtocols sslProtocols, IOBehavior ioBehavior, CancellationToken cancellationToken) in //src/MySqlConnector/Core/ServerSession.cs:line 1434\r\n 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\r\n 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\r\n at MySqlConnector.Core.ConnectionPool.ConnectSessionAsync(MySqlConnection connection, Action4 logMessage, Int64 startingTimestamp, Activity activity, IOBehavior ioBehavior, CancellationToken cancellationToken) in /_/src/MySqlConnector/Core/ConnectionPool.cs:line 493\r\n at MySqlConnector.Core.ConnectionPool.ConnectSessionAsync(MySqlConnection connection, Action4 logMessage, Int64 startingTimestamp, Activity activity, IOBehavior ioBehavior, CancellationToken cancellationToken) in //src/MySqlConnector/Core/ConnectionPool.cs:line 493\r\n at MySqlConnector.Core.ConnectionPool.GetSessionAsync(MySqlConnection connection, Int64 startingTimestamp, Int32 timeoutMilliseconds, Activity activity, IOBehavior ioBehavior, CancellationToken cancellationToken) in //src/MySqlConnector/Core/ConnectionPool.cs:line 146\r\n at MySqlConnector.Core.ConnectionPool.GetSessionAsync(MySqlConnection connection, Int64 startingTimestamp, Int32 timeoutMilliseconds, Activity activity, IOBehavior ioBehavior, CancellationToken cancellationToken) in //src/MySqlConnector/Core/ConnectionPool.cs:line 146\r\n at MySqlConnector.MySqlConnection.CreateSessionAsync(ConnectionPool pool, Int64 startingTimestamp, Activity activity, Nullable1 ioBehavior, CancellationToken cancellationToken) in /_/src/MySqlConnector/MySqlConnection.cs:line 964\r\n at MySqlConnector.MySqlConnection.OpenAsync(Nullable1 ioBehavior, CancellationToken cancellationToken) in //src/MySqlConnector/MySqlConnection.cs:line 453\r\n at Dapper.SqlMapper.QueryAsync[T](IDbConnection cnn, Type effectiveType, CommandDefinition command) in //Dapper/SqlMapper.Async.cs:line 433\r\n at Midgard.CRUD.EntityAdapter1.GetByColumnAsync(String colName, String colValue) in D:\\a\\1\\s\\midgard\\Midgard\\CRUD\\EntityAdapter.cs:line 94\r\n at Midgard.CRUD.EntityAdapter1.GetByColumnAsync(String colName, String colValue) in D:\a\1\s\midgard\Midgard\CRUD\EntityAdapter.cs:line 94\r\n at Midgard.Api.AccessRepository.GetSessionAsync(String token) in D:\a\1\s\midgard\Midgard\Api\AccessRepository.cs:line 166\r\n at WebApi.Auth.BearerAuthHandler.HandleAuthenticateAsync() in D:\a\1\s\webapi\WebApi\Auth\BearerAuthHandler.cs:line 175\r\n at Microsoft.AspNetCore.Authentication.AuthenticationHandler1.AuthenticateAsync()\r\n at Microsoft.AspNetCore.Authentication.AuthenticationService.AuthenticateAsync(HttpContext context, String scheme)\r\n at Microsoft.AspNetCore.Authentication.AuthenticationMiddleware.Invoke(HttpContext context)\r\n at Swashbuckle.AspNetCore.SwaggerUI.SwaggerUIMiddleware.Invoke(HttpContext httpContext)\r\n at Swashbuckle.AspNetCore.Swagger.SwaggerMiddleware.Invoke(HttpContext httpContext, ISwaggerProvider swaggerProvider)\r\n at Microsoft.AspNetCore.Server.Kestrel.Core.Internal.Http.HttpProtocol.ProcessRequests[TContext](IHttpApplication1 application)","Properties":{"ConnectionId":"0HN13GLDDK3D0","TraceIdentifier":"0HN13GLDDK3D0:0000001F","EventId":{"Id":13,"Name":"ApplicationError"},"SourceContext":"Microsoft.AspNetCore.Server.Kestrel","RequestId":"0HN13GLDDK3D0:0000001F","RequestPath":"/api/v2/devices/poke"}}

@jkuek
Copy link
Author

jkuek commented Feb 2, 2024 •
edited

Here's an example with verbose logging. Not much new information. I don't believe this is a networking/transmission error given both the database server and the application server are in the same AZ in the VPC.

Client is ASP.NET Core 6.0, MySqlConnector 2.3.5
Database is Aurora MySQL 8.0.mysql_aurora.3.05.1

So the newer versions of MySqlConnector have resolved the secondary ProtocolVersion failure, but not the initial DecryptError failure. As originally reported, this is a sporadic failure.

timestamp message
1706846157183 {"Timestamp":"2024-02-02T03:55:57.1838292+00:00","Level":"Verbose","MessageTemplate":"Pool 1 waiting for an available session","TraceId":"d6df0aaee3023a1ffdd4e4d17eea2b46","SpanId":"f9c86ab5c41f6df0","Properties":{"SourceContext":"MySqlConnector.ConnectionPool"}}
1706846157183 {"Timestamp":"2024-02-02T03:55:57.1838484+00:00","Level":"Verbose","MessageTemplate":"Created new session 1.264","TraceId":"d6df0aaee3023a1ffdd4e4d17eea2b46","SpanId":"f9c86ab5c41f6df0","Properties":{"SourceContext":"MySqlConnector.MySqlConnection"}}
1706846157183 {"Timestamp":"2024-02-02T03:55:57.1838583+00:00","Level":"Debug","MessageTemplate":"Pool 1 has no pooled session available; created new session 1.264","TraceId":"d6df0aaee3023a1ffdd4e4d17eea2b46","SpanId":"f9c86ab5c41f6df0","Properties":{"SourceContext":"MySqlConnector.ConnectionPool"}}
1706846157205 {"Timestamp":"2024-02-02T03:55:57.2056921+00:00","Level":"Verbose","MessageTemplate":"Session 1.264 connecting to IP address 10.16.65.146 (1 of 1) for host name db.dev.internal (1 of 1)","TraceId":"d6df0aaee3023a1ffdd4e4d17eea2b46","SpanId":"f9c86ab5c41f6df0","Properties":{"SourceContext":"MySqlConnector.MySqlConnection"}}
1706846157208 {"Timestamp":"2024-02-02T03:55:57.2081463+00:00","Level":"Verbose","MessageTemplate":"Session 1.264 connected to IP address 10.16.65.146 for host name db.dev.internal with local port 52955","TraceId":"d6df0aaee3023a1ffdd4e4d17eea2b46","SpanId":"f9c86ab5c41f6df0","Properties":{"SourceContext":"MySqlConnector.MySqlConnection"}}
1706846157208 {"Timestamp":"2024-02-02T03:55:57.2083618+00:00","Level":"Verbose","MessageTemplate":"Session 1.264 server sent auth plugin name mysql_native_password","TraceId":"d6df0aaee3023a1ffdd4e4d17eea2b46","SpanId":"f9c86ab5c41f6df0","Properties":{"SourceContext":"MySqlConnector.MySqlConnection"}}
1706846157208 {"Timestamp":"2024-02-02T03:55:57.2083829+00:00","Level":"Debug","MessageTemplate":"Session 1.264 made connection; server version 8.0.32; connection ID 11110484; supports: compression False, attributes True, deprecate EOF True, cached metadata False, SSL True, session track True, pipelining True, query attributes True","TraceId":"d6df0aaee3023a1ffdd4e4d17eea2b46","SpanId":"f9c86ab5c41f6df0","Properties":{"SourceContext":"MySqlConnector.MySqlConnection"}}
1706846157208 {"Timestamp":"2024-02-02T03:55:57.2083959+00:00","Level":"Verbose","MessageTemplate":"Session 1.264 initializing TLS connection","TraceId":"d6df0aaee3023a1ffdd4e4d17eea2b46","SpanId":"f9c86ab5c41f6df0","Properties":{"SourceContext":"MySqlConnector.MySqlConnection"}}
1706846157242 {"Timestamp":"2024-02-02T03:55:57.2128056+00:00","Level":"Error","MessageTemplate":"Session 1.264 couldn't initialize TLS connection","TraceId":"d6df0aaee3023a1ffdd4e4d17eea2b46","SpanId":"f9c86ab5c41f6df0","Exception":"System.Security.Authentication.AuthenticationException: Authentication failed because the remote party sent a TLS alert: 'DecryptError'.\r\n ---> System.ComponentModel.Win32Exception (0x80090326): The message received was unexpected or badly formatted.\r\n --- End of inner exception stack trace ---\r\n at System.Net.Security.SslStream.ForceAuthenticationAsync[TIOAdapter](TIOAdapter adapter, Boolean receiveFirst, Byte[] reAuthenticationData, Boolean isApm)\r\n at MySqlConnector.Core.ServerSession.InitSslAsync(ProtocolCapabilities serverCapabilities, ConnectionSettings cs, MySqlConnection connection, SslProtocols sslProtocols, IOBehavior ioBehavior, CancellationToken cancellationToken) in /_/src/MySqlConnector/Core/ServerSession.cs:line 1434","Properties":{"SourceContext":"MySqlConnector.MySqlConnection"}}
1706846157243 {"Timestamp":"2024-02-02T03:55:57.2432984+00:00","Level":"Debug","MessageTemplate":"Session 1.264 closing stream/socket","TraceId":"d6df0aaee3023a1ffdd4e4d17eea2b46","SpanId":"f9c86ab5c41f6df0","Properties":{"SourceContext":"MySqlConnector.MySqlConnection"}}
1706846157244 {"Timestamp":"2024-02-02T03:55:57.2440532+00:00","Level":"Debug","MessageTemplate":"Session 1.264 closing stream/socket","TraceId":"d6df0aaee3023a1ffdd4e4d17eea2b46","SpanId":"f9c86ab5c41f6df0","Properties":{"SourceContext":"MySqlConnector.MySqlConnection"}}
1706846157302 {"Timestamp":"2024-02-02T03:55:57.2586108+00:00","Level":"Error","MessageTemplate":"Connection id "{ConnectionId}", Request id "{TraceIdentifier}": An unhandled exception was thrown by the application.","TraceId":"d6df0aaee3023a1ffdd4e4d17eea2b46","SpanId":"f9c86ab5c41f6df0","Exception":"MySqlConnector.MySqlException (0x80004005): SSL Authentication Error\r\n ---> System.Security.Authentication.AuthenticationException: Authentication failed because the remote party sent a TLS alert: 'DecryptError'.\r\n ---> System.ComponentModel.Win32Exception (0x80090326): The message received was unexpected or badly formatted.\r\n --- End of inner exception stack trace ---\r\n at System.Net.Security.SslStream.ForceAuthenticationAsync[TIOAdapter](TIOAdapter adapter, Boolean receiveFirst, Byte[] reAuthenticationData, Boolean isApm)\r\n at MySqlConnector.Core.ServerSession.InitSslAsync(ProtocolCapabilities serverCapabilities, ConnectionSettings cs, MySqlConnection connection, SslProtocols sslProtocols, IOBehavior ioBehavior, CancellationToken cancellationToken) in //src/MySqlConnector/Core/ServerSession.cs:line 1434\r\n 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\r\n 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\r\n at MySqlConnector.Core.ConnectionPool.ConnectSessionAsync(MySqlConnection connection, Action4 logMessage, Int64 startingTimestamp, Activity activity, IOBehavior ioBehavior, CancellationToken cancellationToken) in /_/src/MySqlConnector/Core/ConnectionPool.cs:line 493\r\n at MySqlConnector.Core.ConnectionPool.ConnectSessionAsync(MySqlConnection connection, Action4 logMessage, Int64 startingTimestamp, Activity activity, IOBehavior ioBehavior, CancellationToken cancellationToken) in //src/MySqlConnector/Core/ConnectionPool.cs:line 493\r\n at MySqlConnector.Core.ConnectionPool.GetSessionAsync(MySqlConnection connection, Int64 startingTimestamp, Int32 timeoutMilliseconds, Activity activity, IOBehavior ioBehavior, CancellationToken cancellationToken) in //src/MySqlConnector/Core/ConnectionPool.cs:line 146\r\n at MySqlConnector.Core.ConnectionPool.GetSessionAsync(MySqlConnection connection, Int64 startingTimestamp, Int32 timeoutMilliseconds, Activity activity, IOBehavior ioBehavior, CancellationToken cancellationToken) in //src/MySqlConnector/Core/ConnectionPool.cs:line 146\r\n at MySqlConnector.MySqlConnection.CreateSessionAsync(ConnectionPool pool, Int64 startingTimestamp, Activity activity, Nullable1 ioBehavior, CancellationToken cancellationToken) in /_/src/MySqlConnector/MySqlConnection.cs:line 964\r\n at MySqlConnector.MySqlConnection.OpenAsync(Nullable1 ioBehavior, CancellationToken cancellationToken) in //src/MySqlConnector/MySqlConnection.cs:line 453\r\n at Dapper.SqlMapper.QueryAsync[T](IDbConnection cnn, Type effectiveType, CommandDefinition command) in //Dapper/SqlMapper.Async.cs:line 433\r\n at Midgard.CRUD.EntityAdapter1.GetByColumnAsync(String colName, String colValue) in D:\\a\\1\\s\\midgard\\Midgard\\CRUD\\EntityAdapter.cs:line 94\r\n at Midgard.CRUD.EntityAdapter1.GetByColumnAsync(String colName, String colValue) in D:\a\1\s\midgard\Midgard\CRUD\EntityAdapter.cs:line 94\r\n at Midgard.Api.AccessRepository.GetSessionAsync(String token) in D:\a\1\s\midgard\Midgard\Api\AccessRepository.cs:line 166\r\n at WebApi.Auth.BearerAuthHandler.HandleAuthenticateAsync() in D:\a\1\s\webapi\WebApi\Auth\BearerAuthHandler.cs:line 175\r\n at Microsoft.AspNetCore.Authentication.AuthenticationHandler1.AuthenticateAsync()\r\n at Microsoft.AspNetCore.Authentication.AuthenticationService.AuthenticateAsync(HttpContext context, String scheme)\r\n at Microsoft.AspNetCore.Authentication.AuthenticationMiddleware.Invoke(HttpContext context)\r\n at Swashbuckle.AspNetCore.SwaggerUI.SwaggerUIMiddleware.Invoke(HttpContext httpContext)\r\n at Swashbuckle.AspNetCore.Swagger.SwaggerMiddleware.Invoke(HttpContext httpContext, ISwaggerProvider swaggerProvider)\r\n at Microsoft.AspNetCore.Server.Kestrel.Core.Internal.Http.HttpProtocol.ProcessRequests[TContext](IHttpApplication1 application)","Properties":{"ConnectionId":"0HN13JTFV5TEU","TraceIdentifier":"0HN13JTFV5TEU:00000022","EventId":{"Id":13,"Name":"ApplicationError"},"SourceContext":"Microsoft.AspNetCore.Server.Kestrel","RequestId":"0HN13JTFV5TEU:00000022","RequestPath":"/api/v2/events/run-scheduled"}}

@jkuek
Copy link
Author

jkuek commented Feb 28, 2024

The Cloudwatch RDS error log shows the following when the DecryptError occurs:

2024-02-27T22:51:53.787124Z 8833 [Note] [MY-010914] [Server] Bad handshake

@bgrainger
Copy link
Member

Possibly related to #1448, but that bug is IllegalParameter not DecryptError.

@jkuek
Copy link
Author

jkuek commented Apr 16, 2024

Possibly related, but note in my case the issue is somehow related to TLS1.3

Modifying the Aurora parameter group to only allow TLS1.2 "fixes" the problem

Sign up for free to join this conversation on GitHub. Already have an account? Sign in to comment
Assignees
No one assigned
Labels
None yet
Milestone
No milestone
Development

No branches or pull requests
3 participants
@bgrainger @jkuek @mikethea1