Unable to connect error with multithread

[josejg2906]

Software versions
MySqlConnector version: 2.1.6 (tested with multiple versions 1.3.13 - 2.1.2 - 2.1.6)
Server type (MySQL, MariaDB, Aurora, etc.) and version: MySQL 5.7.36
.NET version: Net Framework 4.7.2 / Net Core 3.1
ORM NuGet packages and versions: NHibernate 5.2.5

Describe the bug
Our approach involves a work context with several thousand of requests. Our solution design is open/close a connection for each request. When the number of request increases we receive faults according to the following Exception annex. To be more accurate we estimate the number of faults is around the 10% percent of request, A very bad figure. As addition information, we are using TLS 1.2 without setting any value referred to TLS connection mode. After seeing TLS errors we have allowed non TLS connection in data base server, addiontally we have updated the SSL paramenter from default to "NONE", but the result is the same one.

Exception
2022-02-18 08:43:26,793 [TRACE] MySqlConnector.ConnectionPool - Pool19 waiting for an available session
2022-02-18 08:43:26,793 [TRACE] MySqlConnector.ServerSession - Session19.198 created new session
2022-02-18 08:43:26,793 [DEBUG] MySqlConnector.ConnectionPool - Pool19 no pooled session available; created new Session19.198
2022-02-18 08:43:26,794 [TRACE] MySqlConnector.ServerSession - Session19.198 connecting to IpAddress XXXX for HostName 'XXXX'
2022-02-18 08:43:26,819 [TRACE] MySqlConnector.ConnectionPool - Pool1 waiting for an available session
2022-02-18 08:43:26,819 [TRACE] MySqlConnector.ServerSession - Session1.1670 created new session
2022-02-18 08:43:26,819 [DEBUG] MySqlConnector.ConnectionPool - Pool1 no pooled session available; created new Session1.1670
2022-02-18 08:43:26,820 [TRACE] MySqlConnector.ServerSession - Session1.1670 connecting to IpAddress XXXX for HostName 'XXXX'
2022-02-18 08:43:26,835 [TRACE] MySqlConnector.ServerSession - Session1.1670 connected to IpAddress XXXX for HostName 'XXXX' with local Port 57654
2022-02-18 08:43:26,836 [TRACE] MySqlConnector.ServerSession - Session1.1670 server sent AuthPluginName=mysql_native_password
2022-02-18 08:43:26,836 [DEBUG] MySqlConnector.ServerSession - Session1.1670 made connection; ServerVersion=5.7.36; ConnectionId=8743309; Compression=False; Attributes=True; DeprecateEof=True; Ssl=True; SessionTrack=True; Pipelining=True; QueryAttributes=False
2022-02-18 08:43:26,836 [TRACE] MySqlConnector.ServerSession - Session1.1670 initializing TLS connection
2022-02-18 08:43:26,840 [DEBUG] MySqlConnector.ServerSession - Session1.1670 connected TLS with SslProtocol=Tls12, CipherAlgorithm=Aes256, HashAlgorithm=Sha384, KeyExchangeAlgorithm=44550, KeyExchangeStrength=255
2022-02-18 08:43:26,841 [TRACE] MySqlConnector.ConnectionPool - Pool1 returning new Session1.1670 to caller; LeasedSessionsCount=1
2022-02-18 08:43:26,841 [TRACE] MySqlConnector.CommandExecutor - Session1.1670 ExecuteReader Synchronous CommandCount: 1
2022-02-18 08:43:26,841 [TRACE] MySqlConnector.SingleCommandPayloadCreator - Session1.1670 Preparing command payload; CommandText: SELECT XXXX
2022-02-18 08:43:26,842 [TRACE] MySqlConnector.ServerSession - Session1.1670 entering FinishQuerying; SessionState=Querying
2022-02-18 08:43:26,843 [TRACE] MySqlConnector.ConnectionPool - Pool9 waiting for an available session
2022-02-18 08:43:26,843 [TRACE] MySqlConnector.ServerSession - Session9.66 created new session
2022-02-18 08:43:26,843 [DEBUG] MySqlConnector.ConnectionPool - Pool9 no pooled session available; created new Session9.66
2022-02-18 08:43:26,843 [TRACE] MySqlConnector.ServerSession - Session9.66 connecting to IpAddress XXXX for HostName 'XXXX'
2022-02-18 08:43:26,852 [TRACE] MySqlConnector.ServerSession - Session9.66 connected to IpAddress XXXX for HostName 'XXXX' with local Port 57660
2022-02-18 08:43:26,853 [TRACE] MySqlConnector.ServerSession - Session9.66 server sent AuthPluginName=mysql_native_password
2022-02-18 08:43:26,853 [DEBUG] MySqlConnector.ServerSession - Session9.66 made connection; ServerVersion=5.7.36; ConnectionId=162415; Compression=False; Attributes=True; DeprecateEof=True; Ssl=True; SessionTrack=True; Pipelining=True; QueryAttributes=False
2022-02-18 08:43:26,853 [TRACE] MySqlConnector.ServerSession - Session9.66 initializing TLS connection
2022-02-18 08:43:26,855 [DEBUG] MySqlConnector.ServerSession - Session9.66 connected TLS with SslProtocol=Tls12, CipherAlgorithm=Aes256, HashAlgorithm=Sha384, KeyExchangeAlgorithm=44550, KeyExchangeStrength=255
2022-02-18 08:43:26,856 [ERROR] MySqlConnector.ServerSession - Session19.198 connecting failed
2022-02-18 08:43:26,856 [ERROR] WsGestionFlotasJaltest.WsJaltestFleet - MySQLException en el método InsertarInformacion -->
MySqlConnector.MySqlException (0x80004005): Unable to connect to any of the specified MySQL hosts.
en MySqlConnector.Core.ServerSession.d__83.MoveNext() en //src/MySqlConnector/Core/ServerSession.cs:línea 514
--- Fin del seguimiento de la pila de la ubicación anterior donde se produjo la excepción ---
en System.Runtime.ExceptionServices.ExceptionDispatchInfo.Throw()
en System.Runtime.CompilerServices.TaskAwaiter.HandleNonSuccessAndDebuggerNotification(Task task)
en MySqlConnector.Core.ConnectionPool.d__21.MoveNext() en //src/MySqlConnector/Core/ConnectionPool.cs:línea 363
--- Fin del seguimiento de la pila de la ubicación anterior donde se produjo la excepción ---
en System.Runtime.ExceptionServices.ExceptionDispatchInfo.Throw()
en System.Runtime.CompilerServices.TaskAwaiter.HandleNonSuccessAndDebuggerNotification(Task task)
en MySqlConnector.Core.ConnectionPool.d__10.MoveNext() en //src/MySqlConnector/Core/ConnectionPool.cs:línea 94
--- Fin del seguimiento de la pila de la ubicación anterior donde se produjo la excepción ---
en System.Runtime.ExceptionServices.ExceptionDispatchInfo.Throw()
en MySqlConnector.Core.ConnectionPool.d__10.MoveNext() en //src/MySqlConnector/Core/ConnectionPool.cs:línea 19
--- Fin del seguimiento de la pila de la ubicación anterior donde se produjo la excepción ---
en System.Runtime.ExceptionServices.ExceptionDispatchInfo.Throw()
en System.Runtime.CompilerServices.TaskAwaiter.HandleNonSuccessAndDebuggerNotification(Task task)
en MySqlConnector.MySqlConnection.d__124.MoveNext() en //src/MySqlConnector/MySqlConnection.cs:línea 919
--- Fin del seguimiento de la pila de la ubicación anterior donde se produjo la excepción ---
en System.Runtime.ExceptionServices.ExceptionDispatchInfo.Throw()
en System.Runtime.CompilerServices.TaskAwaiter.HandleNonSuccessAndDebuggerNotification(Task task)
en MySqlConnector.MySqlConnection.d__26.MoveNext() en //src/MySqlConnector/MySqlConnection.cs:línea 425
--- Fin del seguimiento de la pila de la ubicación anterior donde se produjo la excepción ---
en System.Runtime.ExceptionServices.ExceptionDispatchInfo.Throw()
en System.Runtime.CompilerServices.TaskAwaiter.HandleNonSuccessAndDebuggerNotification(Task task)
en MySqlConnector.MySqlConnection.Open() en /_/src/MySqlConnector/MySqlConnection.cs:línea 373
...
2022-02-18 08:43:26,960 [TRACE] MySqlConnector.ConnectionPool - Pool9 returning new Session9.66 to caller; LeasedSessionsCount=1
2022-02-18 08:43:26,960 [TRACE] MySqlConnector.ConnectionPool - Pool1 waiting for an available session
2022-02-18 08:43:26,960 [TRACE] MySqlConnector.ServerSession - Session1.1671 created new session
2022-02-18 08:43:26,960 [DEBUG] MySqlConnector.ConnectionPool - Pool1 no pooled session available; created new Session1.1671
2022-02-18 08:43:26,963 [TRACE] MySqlConnector.CommandExecutor - Session9.66 ExecuteReader Synchronous CommandCount: 1
2022-02-18 08:43:26,963 [TRACE] MySqlConnector.SingleCommandPayloadCreator - Session9.66 Preparing command payload; CommandText: INSERT INTO ...
2022-02-18 08:43:26,965 [TRACE] MySqlConnector.ServerSession - Session9.66 entering FinishQuerying; SessionState=Querying
2022-02-18 08:43:26,965 [TRACE] MySqlConnector.CommandExecutor - Session1.1670 ExecuteReader Synchronous CommandCount: 1
2022-02-18 08:43:26,965 [TRACE] MySqlConnector.SingleCommandPayloadCreator - Session1.1670 Preparing command payload; CommandText: set session transaction isolation level repeatable read;
2022-02-18 08:43:26,966 [TRACE] MySqlConnector.ServerSession - Session1.1670 entering FinishQuerying; SessionState=Querying
2022-02-18 08:43:26,966 [TRACE] MySqlConnector.CommandExecutor - Session1.1670 ExecuteReader Synchronous CommandCount: 1
2022-02-18 08:43:26,966 [TRACE] MySqlConnector.SingleCommandPayloadCreator - Session1.1670 Preparing command payload; CommandText: start transaction;
2022-02-18 08:43:26,966 [TRACE] MySqlConnector.ServerSession - Session1.1671 connecting to IpAddress XXXX for HostName 'XXXX'
2022-02-18 08:43:26,967 [TRACE] MySqlConnector.ServerSession - Session1.1670 entering FinishQuerying; SessionState=Querying
2022-02-18 08:43:26,967 [TRACE] MySqlConnector.ServerSession - Session1.1671 connected to IpAddress XXXX for HostName 'XXXX' with local Port 58387

[bgrainger]

MySqlConnector version: 2.1.6
2022-02-18 08:43:26,856 [ERROR] MySqlConnector.ServerSession - Session19.198 connecting failed
2022-02-18 08:43:26,856 [ERROR] WsGestionFlotasJaltest.WsJaltestFleet - MySQLException en el método InsertarInformacion -->
MySqlConnector.MySqlException (0x80004005): Unable to connect to any of the specified MySQL hosts.
en MySqlConnector.Core.ServerSession.d__83.MoveNext() en //src/MySqlConnector/Core/ServerSession.cs:línea 514

ServerSession.cs, line 514 should be logging an error "Session19.198 requires SSL but server doesn't support it"

Is that in your logs?

addiontally we have updated the SSL paramenter from default to "NONE", but the result is the same one.

Are these logs from MySqlConnector 2.1.6 with SSL Mode=None?

[josejg2906]

MySqlConnector version: 2.1.6
2022-02-18 08:43:26,856 [ERROR] MySqlConnector.ServerSession - Session19.198 connecting failed
2022-02-18 08:43:26,856 [ERROR] WsGestionFlotasJaltest.WsJaltestFleet - MySQLException en el método InsertarInformacion -->
MySqlConnector.MySqlException (0x80004005): Unable to connect to any of the specified MySQL hosts.
en MySqlConnector.Core.ServerSession.d__83.MoveNext() en //src/MySqlConnector/Core/ServerSession.cs:línea 514

ServerSession.cs, line 514 should be logging an error "Session19.198 requires SSL but server doesn't support it"

Is that in your logs?

No, we don't see that in logs

addiontally we have updated the SSL paramenter from default to "NONE", but the result is the same one.

Are these logs from MySqlConnector 2.1.6 with SSL Mode=None?

This log is with SSL Mode = Preferred.

Do you think is a TLS problem? We could generate the log with SSL Mode = None

[bgrainger]

The line number implies it's a TLS problem, although the missing logs are an anomaly.

Yes, please post logs from SSL Mode = None.

[josejg2906]

Hello,

We have done the test with SSL Mode = None and the results are similar.

First, indicate that the test had been done in another different service of the original log (because the original service is very critical), but the behavior is the same.

1º In the attached file "DebugTLS.log" you can see the result of SSLMode = "Preffered". You can see "connecting failed" errors.
2º In the attached file "DebugSSLModeNone.log" you can see the result of SSLMode = "None". There are "connection failed" errors too.

A very curious behavior is:
If we activate the log in mode = "ALL" all the connections are ok, there is no error. However, if we change the mode to "DEBUG", the errors start (the attached files are in DEBUG mode)

We hope these files help you to understand the error better.
Note: the number line we see in the file log doesn't seem to match with the Github code.

On the other hand, another problem with the connector is the following:
Very sporadically we have the error of the attached file TLSError.log when from a web service we try to connect to a database (it does not always happen to us with the same web service and the same database, but it is random) and the only way to solve that problem is by restarting the web service.
DebugSSLModeNone.log
DebugTLS.log
TLSError.log

[bgrainger]

There are a very high number of distinct Pool numbers present in the DebugSSLModeNone log: Pool26, Pool29, Pool41, Pool42, Pool253, Pool257, Pool258 (and that's just the ones I saw in one page).

Having hundreds of concurrently-active connection pools is not the typical use case of MySqlConnector, and would likely defeat the benefits of connection pooling. It could also lead to thousands (or tens of thousands) of client TCP sockets being opened, which might be causing your problems (if the underlying issue is socket exhaustion).

There are also very frequent instances of PoolNNN clearing connection pool being logged. Calling MySqlConnection.ClearPool(Async) frequently is also not typical expected behaviour.

Can you adjust your client code so that it only creates one pool (i.e., one unique connection string) and stops clearing the pool frequently?

[josejg2906]

Hello,

Sorry for the delay. We are making progress on this topic.

On the one hand, we are changing the methodology and not cleaning the connection pool in each request. The fear we have in applying this solution is that the number of active connections to the DB will now increase (and may even reach the limit established by the DB itself). What do you think about this?

On the other hand, we have doubts about applying this solution in other application. It is a website where each client has its own database schema within the same DB server.

Let's imagine a server with 100 schemas and a maximum allowed number of connections per DB server of 600. In this scenario, the maximum size of the connection pool that I can have for each schema is 6. Therefore, if I have 7 users performing a simultaneous query would give me an error for exceeding the size of the pool. This makes sense?

Best regards,

[bgrainger]

On the one hand, we are changing the methodology and not cleaning the connection pool in each request. The fear we have in applying this solution is that the number of active connections to the DB will now increase (and may even reach the limit established by the DB itself). What do you think about this?

You haven't explained why you think the number of active connections to the DB will increase. An active connection is only created when your code calls MySqlConnection.Open. When the connection is closed, it returns to the pool, where it lives for a short time (default, 3 minutes) until it's automatically closed.

Assuming that you Open and Close/Dispose connections just when you need them (i.e., don't keep them open for a long time), the number of active connections will be proportional to the number of concurrent requests you are serving. If each user is only making 1 or 2 requests at a time, you may only have one active connection per user/schema. This will likely not exhaust the maximum number of connections at the DB server.

Let's imagine a server with 100 schemas and a maximum allowed number of connections per DB server of 600. In this scenario, the maximum size of the connection pool that I can have for each schema is 6.

If you are anticipating that all 100 schemas will be in use concurrently, then yes the maximum number of connections you could have per schema (on average) would be 6.

Therefore, if I have 7 users performing a simultaneous query would give me an error for exceeding the size of the pool. This makes sense?

No, I'm not following that. Does each user open 100 connections to each of the 100 schemas? If so, that seems incredibly inefficient (when you could instead join across schemas if they're hosted on the same DB server).

MaximumPoolSize is a limit for an upper cap on active connections. It doesn't mean that that many connections have to be created. A pool with MaximumPoolSize = 100; might only have 2 or 3 active connections at any time, based on how many connections are being opened concurrently. Existing connections will always be reused whenever possible.

Finally, if you're really worried about pooling, you could add ; Pooling = false to your connection string, which will disable it entirely. I usually don't recommend that, but it may be appropriate in your case if you have hundreds (or thousands) of different schemas that you're connecting to.

[josejg2906]

Thank you for the quick response,

The fear we have in applying this solution is that the number of active connections to the DB will now increase (and may even reach the limit established by the DB itself). What do you think about this?

I was referring to "idle connections", that is, connections that, even if they are in "sleep" state, will add to the total number of simultaneous connections allowed by the DB server.

Therefore, if I have 7 users performing a simultaneous query would give me an error for exceeding the size of the pool. This makes sense?

I was referring to 7 users making simultaneous queries on the same schema, that is, if I have 600 maximum connections to the server and 100 schemas, each schema could be queried simultaneously by a maximum of 6 users, but the 7th user would already receive an error. Is it so?

Anyway, now I have a lot more clarity about the behavior and the way of working, thank you very much!

However, tonight we have had an anomalous behavior:

We have a service (with the logic of cleaning the pool for each connection) with the following behavior:

• First, the service makes a connection to database "A"
• Then, it makes a connection to DB "B"

The connection to DB "A" always works correctly. However, tonight, the connection to DB "B" gave a TLS1.2 connection error and started trying to connect (non-stop) over TLS1.1 (and our DB is not TLS1.1 enabled) , so it has not stopped failing until we have restarted the service.
I understand that the best way to resolve this is to specify the "TLS-Version" parameter in the connection string and set it to TLS.1.2, but I'd like to confirm this.

I attach the log in case you need to see more information.

TLS1_2.log

[bgrainger]

I was referring to 7 users making simultaneous queries on the same schema, that is, if I have 600 maximum connections to the server and 100 schemas, each schema could be queried simultaneously by a maximum of 6 users, but the 7th user would already receive an error. Is it so?

If you set MaximumPoolSize = 6 in your connection string (for that schema), then you can have six simultaneous open connections to the DB server. When the seventh request comes in, MySqlConnection.Open will block for up to Connect Timeout seconds (default 15) waiting for an existing connection to be closed/disposed. Only if the six open connections are kept open for 15+ seconds would the seventh connection get an error. (And that would be bad practice: a MySqlConnection should be opened just long enough to execute a query and read the results, then closed/disposed. The pool makes this very efficient.)

[bgrainger]

However, tonight, the connection to DB "B" gave a TLS1.2 connection error and started trying to connect (non-stop) over TLS1.1

Are you running MySqlConnector 2.1.6 or later? #1132 fixes a bug that allowed TLS downgrade. If not, please update to at least that version.

If you know your server doesn't support TLS 1.1 (and that you never want to use that TLS version), you can set TlsVersion=Tls12,Tls13 in your connection string, but that shouldn't be required (and it's recommended to leave that option unspecified to use OS defaults).

[josejg2906]

The previous TLS1_2,log file has been obtained with version 2.1.6 of the connector. Seeing #1132 the error occurs in different places. In that bug, the error appears in
"System.ComponentModel.Win32Exception (0x80090331): The client and server cannot communicate, because they do not possess a common algorithm."

However, in our case, the error appears at: "MySqlConnector.Core.ServerSession.ConnectAsync"

Do you think it is the same error in both cases?