"Could not load the client key from..." on 2.2.0

[nowakca]

Software versions
MySqlConnector version:
Server type (MySQL, MariaDB, Aurora, etc.) and version: MySQL 8.0.29-21 (per show variables like ‘%version%’;)
.NET version: 6.0.8 (as reported by [environment]::Version in Powershell 7.2.6)
(Optional) ORM NuGet packages and versions:

Describe the bug

When I attempt to connect to a MySQL database using a certificate for authentication, I get the below exception. (variables substituted in to avoid exposing info). This works normally in 2.1.13, but not 2.2.0.

Exception
MethodInvocationException: Exception calling "Open" with "0" argument(s): "Could not load the client key from $KEYPATH"

Code sample

$connectionString = "ConvertZeroDateTime=True;SslMode=VerifyCA;host=$HOSTNAME;user=$USERNAME;SslKey=$KEYPATH;port=3306;database=grmp;SslCa=$CAPATH;SslCert=$CERTPATH;AllowLoadLocalInfile=True"
$conn = [MySqlConnector.MySqlConnection]::New($connectionString)
$conn.open()

Expected behavior
I expected to get a populated connection record.

Additional context
This works as expected on 2.1.13, it only started failing on 2.2.0. My test containers were built within a minute of each other, with the only difference being the MySqlConnector version... both had same access to the key. So the issue seems to be how 2.2.0 is parsing the key, not its access to the key or changes in OS libraries.

[bgrainger]

It seems like the connection string has the literal text SslKey=$KEYPATH; in it, instead of that variable being substituted in before the string is passed to MySqlConnection. Can you double-check what the contents of $connectionString actually are?

[nowakca]

I manually replaced the file path with that variable-looking-bit because I didn't want to share the actual filepath (since it includes internal info in the path, but it starts with "/var/lib/")... the real value is definitely a valid path. Also note that it works perfectly without any changes at all on 2.1.13, and only fails on 2.2.0, if it was a simple issue like that, both would have failed.

Also to note, if I put in an invalid server name, the error I get changes to Could not load client key file: <the path to a key file that doesn't exist>. instead of the one I got: Could not load the client key from <the path to the key .PEM file>.. So it gets far enough to actually reading a file, it just seems to choke on how it processes the contents of the file. (And yes, that same file is the one used in the 2.1.13 test, it hasn't changed)

Ideas on what to look for? Any extra debugging I can turn on?

[bgrainger]

Sorry, I got confused by how you were obfuscating the path in your bug report.

Any extra debugging I can turn on?

You can enable verbose logging with:

MySqlConnector.Logging.MySqlConnectorLogManager.Provider = new MySqlConnector.Logging.ConsoleLoggerProvider(MySqlConnector.Logging.MySqlConnectorLogLevel.Trace);

[bgrainger]

There should also be an inner exception with more details on what caused the problem. Can you paste in the full exception message and call stack (with line numbers), obfuscating any sensitive details as necessary?

[nowakca]

No worries, random complaints with little context don't always create the smoothest environment for initial troubleshooting =)

Here's the more complete exception:

System.Management.Automation.MethodInvocationException: Exception calling "Open" with "0" argument(s): "Could not load the client key from $KEYPATH"
 ---> MySqlConnector.MySqlException (0x80004005): Could not load the client key from $KEYPATH
 ---> System.FormatException: Couldn't read zero.
   at MySqlConnector.Utilities.Utility.GetRsaParameters(ReadOnlySpan`1 data, Boolean isPrivate) in /_/src/MySqlConnector/Utilities/Utility.cs:line 218
   at MySqlConnector.Utilities.Utility.GetRsaParameters(String key) in /_/src/MySqlConnector/Utilities/Utility.cs:line 157
   at MySqlConnector.Core.ServerSession.<>c__DisplayClass102_0.<InitSslAsync>g__LoadCertificate|2(String sslKeyFile, String sslCertificateFile) in /_/src/MySqlConnector/Core/ServerSession.cs:line 1606
   at MySqlConnector.Core.ServerSession.<>c__DisplayClass102_0.<InitSslAsync>g__LoadCertificate|2(String sslKeyFile, String sslCertificateFile) in /_/src/MySqlConnector/Core/ServerSession.cs:line 1611
   at MySqlConnector.Core.ServerSession.InitSslAsync(ProtocolCapabilities serverCapabilities, ConnectionSettings cs, MySqlConnection connection, SslProtocols sslProtocols, IOBehavior ioBehavior, CancellationToken cancellationToken) in /_/src/MySqlConnector/Core/ServerSession.cs:line 1348
   at MySqlConnector.Core.ServerSession.ConnectAsync(ConnectionSettings cs, MySqlConnection connection, Int32 startTickCount, ILoadBalancer loadBalancer, Activity activity, IOBehavior ioBehavior, CancellationToken cancellationToken) in /_/src/MySqlConnector/Core/ServerSession.cs:line 539
   at MySqlConnector.Core.ConnectionPool.ConnectSessionAsync(MySqlConnection connection, String logMessage, Int32 startTickCount, Activity activity, IOBehavior ioBehavior, CancellationToken cancellationToken) in /_/src/MySqlConnector/Core/ConnectionPool.cs:line 386
   at MySqlConnector.Core.ConnectionPool.GetSessionAsync(MySqlConnection connection, Int32 startTickCount, Activity activity, IOBehavior ioBehavior, CancellationToken cancellationToken) in /_/src/MySqlConnector/Core/ConnectionPool.cs:line 97
   at MySqlConnector.Core.ConnectionPool.GetSessionAsync(MySqlConnection connection, Int32 startTickCount, Activity activity, IOBehavior ioBehavior, CancellationToken cancellationToken) in /_/src/MySqlConnector/Core/ConnectionPool.cs:line 127
   at MySqlConnector.MySqlConnection.CreateSessionAsync(ConnectionPool pool, Int32 startTickCount, Activity activity, Nullable`1 ioBehavior, CancellationToken cancellationToken) in /_/src/MySqlConnector/MySqlConnection.cs:line 923
   at MySqlConnector.MySqlConnection.OpenAsync(Nullable`1 ioBehavior, CancellationToken cancellationToken) in /_/src/MySqlConnector/MySqlConnection.cs:line 422
   at MySqlConnector.MySqlConnection.Open() in /_/src/MySqlConnector/MySqlConnection.cs:line 381
   at CallSite.Target(Closure , CallSite , Object )
   --- End of inner exception stack trace ---
   at System.Management.Automation.ExceptionHandlingOps.ConvertToMethodInvocationException(Exception exception, Type typeToThrow, String methodName, Int32 numArgs, MemberInfo memberInfo)
   at CallSite.Target(Closure , CallSite , Object )
   at System.Dynamic.UpdateDelegates.UpdateAndExecute1[T0,TRet](CallSite site, T0 arg0)
   at System.Management.Automation.Interpreter.DynamicInstruction`2.Run(InterpretedFrame frame)
   at System.Management.Automation.Interpreter.EnterTryCatchFinallyInstruction.Run(InterpretedFrame frame)

And the innerException:

MySqlConnector.MySqlException (0x80004005): Could not load the client key from $KEYPATH
 ---> System.FormatException: Couldn't read zero.
   at MySqlConnector.Utilities.Utility.GetRsaParameters(ReadOnlySpan`1 data, Boolean isPrivate) in /_/src/MySqlConnector/Utilities/Utility.cs:line 218
   at MySqlConnector.Utilities.Utility.GetRsaParameters(String key) in /_/src/MySqlConnector/Utilities/Utility.cs:line 157
   at MySqlConnector.Core.ServerSession.<>c__DisplayClass102_0.<InitSslAsync>g__LoadCertificate|2(String sslKeyFile, String sslCertificateFile) in /_/src/MySqlConnector/Core/ServerSession.cs:line 1606
   at MySqlConnector.Core.ServerSession.<>c__DisplayClass102_0.<InitSslAsync>g__LoadCertificate|2(String sslKeyFile, String sslCertificateFile) in /_/src/MySqlConnector/Core/ServerSession.cs:line 1611
   at MySqlConnector.Core.ServerSession.InitSslAsync(ProtocolCapabilities serverCapabilities, ConnectionSettings cs, MySqlConnection connection, SslProtocols sslProtocols, IOBehavior ioBehavior, CancellationToken cancellationToken) in /_/src/MySqlConnector/Core/ServerSession.cs:line 1348
   at MySqlConnector.Core.ServerSession.ConnectAsync(ConnectionSettings cs, MySqlConnection connection, Int32 startTickCount, ILoadBalancer loadBalancer, Activity activity, IOBehavior ioBehavior, CancellationToken cancellationToken) in /_/src/MySqlConnector/Core/ServerSession.cs:line 539
   at MySqlConnector.Core.ConnectionPool.ConnectSessionAsync(MySqlConnection connection, String logMessage, Int32 startTickCount, Activity activity, IOBehavior ioBehavior, CancellationToken cancellationToken) in /_/src/MySqlConnector/Core/ConnectionPool.cs:line 386
   at MySqlConnector.Core.ConnectionPool.GetSessionAsync(MySqlConnection connection, Int32 startTickCount, Activity activity, IOBehavior ioBehavior, CancellationToken cancellationToken) in /_/src/MySqlConnector/Core/ConnectionPool.cs:line 97
   at MySqlConnector.Core.ConnectionPool.GetSessionAsync(MySqlConnection connection, Int32 startTickCount, Activity activity, IOBehavior ioBehavior, CancellationToken cancellationToken) in /_/src/MySqlConnector/Core/ConnectionPool.cs:line 127
   at MySqlConnector.MySqlConnection.CreateSessionAsync(ConnectionPool pool, Int32 startTickCount, Activity activity, Nullable`1 ioBehavior, CancellationToken cancellationToken) in /_/src/MySqlConnector/MySqlConnection.cs:line 923
   at MySqlConnector.MySqlConnection.OpenAsync(Nullable`1 ioBehavior, CancellationToken cancellationToken) in /_/src/MySqlConnector/MySqlConnection.cs:line 422
   at MySqlConnector.MySqlConnection.Open() in /_/src/MySqlConnector/MySqlConnection.cs:line 381
   at CallSite.Target(Closure , CallSite , Object )

For reference: Translated to Powershell, the log trace config is done via

[MySqlConnector.Logging.MySqlConnectorLogManager]::Provider = new-object MySqlConnector.Logging.ConsoleLoggerProvider([MySqlConnector.Logging.MySqlConnectorLogLevel]::Trace)

Here's the trace :

[INFO]	ConnectionPool	Pool1 creating new connection pool for ConnectionString: Server=gp-002-rw.yds.g00.yahoodns.net;Port=3306;User ID=grmpbotuser;Database=grmp;SSL Mode=VerifyCA;SSL Cert=$CERTPATH;SSL Key=$KEYPATH;SSL CA=$CAPATH;Allow Load Local Infile=True;Convert Zero DateTime=True
[TRACE]	ConnectionPool	Pool1 waiting for an available session
[TRACE]	ServerSession	Session1.1 created new session
[DEBUG]	ConnectionPool	Pool1 no pooled session available; created new Session1.1
[TRACE]	ServerSession	Session1.1 connecting to IpAddress $HOSTIP (1 of 1) for HostName '$HOSTNAME' (1 of 1)
[TRACE]	ServerSession	Session1.1 connected to IpAddress $HOSTIP for HostName '$HOSTNAME' with local Port 37164
[TRACE]	ServerSession	Session1.1 server sent AuthPluginName=caching_sha2_password
[DEBUG]	ServerSession	Session1.1 made connection; ServerVersion=8.0.29-21; ConnectionId=4004314; Compression=False; Attributes=True; DeprecateEof=True; Ssl=True; SessionTrack=True; Pipelining=True; QueryAttributes=True
[TRACE]	ServerSession	Session1.1 initializing TLS connection
[TRACE]	ServerSession	Session1.1 loading client key from KeyFile '$KEYFILE'
[ERROR]	ServerSession	Session1.1 couldn't load client key from KeyFile $KEYFILE'
System.FormatException: Couldn't read zero.
   at MySqlConnector.Utilities.Utility.GetRsaParameters(ReadOnlySpan`1 data, Boolean isPrivate) in /_/src/MySqlConnector/Utilities/Utility.cs:line 218
   at MySqlConnector.Utilities.Utility.GetRsaParameters(String key) in /_/src/MySqlConnector/Utilities/Utility.cs:line 157
   at MySqlConnector.Core.ServerSession.<>c__DisplayClass102_0.<InitSslAsync>g__LoadCertificate|2(String sslKeyFile, String sslCertificateFile) in /_/src/MySqlConnector/Core/ServerSession.cs:line 1606
MethodInvocationException: Exception calling "Open" with "0" argument(s): "Could not load the client key from $KEYPATH"

Not a ton of extra value from the trace, it really looks like it's choking on parsing the keyfile.

[nowakca]

OK, I got this working... so I'm happy to close this now. Thank you for your help!

The fix: Use the net6.0 version of the library.

The background:
The Nuget package includes many versions of the compiled library: net461, net471, net6.0, net7.0, netcoreapp3.1, netstandard2.0, and netstandard2.1.
My scripts have been loading the netstandard2.1 for ages.
Updating to version 2.2.0 of this package starts to fail.
But switching to using the net6.0 version of the lib makes things work again.

Further digging for curiosity:
I reran the successful test with tracing enabled and compared outputs, I'm not sure how much of it I can share, but everything up to the [TRACE] ServerSession Session2.1 initializing TLS connection line was identical.

The next line in the successful test was [TRACE] ServerSession Session2.1 loading CA certificate(s) from CertificateFile '$CAFILE'

So it appears the netstandard2.1 library wasn't doing CA validations, the net6.0 one does, and something that changed from 2.1.13 to 2.2.0 actually causes that to matter, which seems like a good thing. Just not obvious.

If you want more info from me on this, I'm happy to continue. But from what I sit, the issue is resolved

[bgrainger]

Thanks; this is really helpful information.

There are platform-specific branches in the code (based on new APIs that .NET 6.0 supports but netstandard2.1 doesn't, for example). There may be a bug in the following section that needs further investigation:

MySqlConnector/src/MySqlConnector/Core/ServerSession.cs

Lines 1584 to 1612 in 41aa751

	#if NETSTANDARD2_0
	throw new NotSupportedException("SslCert and SslKey connection string options are not supported in netstandard2.0.");
	#elif NET5_0_OR_GREATER
	m_clientCertificate = X509Certificate2.CreateFromPemFile(sslCertificateFile, sslKeyFile);
	return new() { m_clientCertificate };
	#else
	m_logArguments[1] = sslKeyFile;
	Log.Trace("Session{0} loading client key from KeyFile '{1}'", m_logArguments);
	string keyPem;
	try
	{
	keyPem = File.ReadAllText(sslKeyFile);
	}
	catch (Exception ex)
	{
	Log.Error(ex, "Session{0} couldn't load client key from KeyFile '{1}'", m_logArguments);
	throw new MySqlException("Could not load client key file: " + sslKeyFile, ex);
	}
	RSAParameters rsaParameters;
	try
	{
	rsaParameters = Utility.GetRsaParameters(keyPem);
	}
	catch (FormatException ex)
	{
	Log.Error(ex, "Session{0} couldn't load client key from KeyFile '{1}'", m_logArguments);
	throw new MySqlException("Could not load the client key from " + sslKeyFile, ex);
	}

[nowakca]

If I'm following correctly (I only looked at the exception there, I didn't go back track the call tree), it looks like the bug would be that the originating exception is getting shadowed. That highlighted exception would have made a ton more sense to have received. I wouldn't have made immediate sense to me, but would have matched to the library loading and jumped straight to the issue. Nice find.

[bgrainger]

This was a regression introduced in 0bb5885#diff-5241314214d7d3cbf2c0e9abe9d16662d192838238ea9fa4b0dd9ee73046c8ceL716-R717.

[bgrainger]

Fixed in 2.2.1.