MySqlException: Too Many Connections

[thefringeninja]

From my pull request here: SQLStreamStore/SQLStreamStore#270 I occasionally see 'Too Many Connections.' Here are the logs and stacktrace:

2019-03-27 11:09:37.976 +01:00 [Debug] Pool"1" waiting for an available session
2019-03-27 11:09:37.978 +01:00 [Debug] Pool"1" found an existing session; checking it for validity
2019-03-27 11:09:37.978 +01:00 [Debug] Session"1.1" ServerVersion="5.6.43" doesn't support reset connection; sending change user request
2019-03-27 11:09:37.978 +01:00 [Debug] Session"1.1" optimistic reauthentication failed; logging in again
2019-03-27 11:09:37.978 +01:00 [Debug] Session"1.1" switching to AuthenticationMethod '"mysql_native_password"'
2019-03-27 11:09:37.979 +01:00 [Debug] Pool"1" returning pooled Session"1.1" to caller; LeasedSessionsCount=1
2019-03-27 11:09:37.979 +01:00 [Debug] Session"1.1" returning to Pool1
2019-03-27 11:09:37.979 +01:00 [Debug] Pool"1" receiving Session"1.1" back
2019-03-27 11:09:37.979 +01:00 [Debug] Pool"1" waiting for an available session
2019-03-27 11:09:37.979 +01:00 [Debug] Pool"1" found an existing session; checking it for validity
2019-03-27 11:09:37.979 +01:00 [Debug] Session"1.1" ServerVersion="5.6.43" doesn't support reset connection; sending change user request
2019-03-27 11:09:37.979 +01:00 [Debug] Session"1.1" optimistic reauthentication failed; logging in again
2019-03-27 11:09:37.979 +01:00 [Debug] Session"1.1" switching to AuthenticationMethod '"mysql_native_password"'
2019-03-27 11:09:37.979 +01:00 [Debug] Pool"1" returning pooled Session"1.1" to caller; LeasedSessionsCount=1
2019-03-27 11:09:37.979 +01:00 [Debug] Session"1.1" ExecuteBehavior Asynchronous CommandText: "CREATE DATABASE IF NOT EXISTS `test_ff0a0407b3a24ea399e73dc587c2b4bc`"
2019-03-27 11:09:37.980 +01:00 [Debug] Session"1.1" entering FinishQuerying; SessionState=Querying
2019-03-27 11:09:37.980 +01:00 [Debug] Session"1.1" returning to Pool1
2019-03-27 11:09:37.980 +01:00 [Debug] Pool"1" receiving Session"1.1" back
2019-03-27 11:09:37.980 +01:00 [Information] System.Data.StateChangeEventArgs
2019-03-27 11:09:37.980 +01:00 [Information] Pool"142" creating new connection pool for ConnectionString: "Database=test_ff0a0407b3a24ea399e73dc587c2b4bc;Port=3306;User Id=root;Pooling=True;Maximum Pool Size=500;GuidFormat=Binary16;Connection Reset=True;Compress=True"
2019-03-27 11:09:37.980 +01:00 [Debug] Pool"142" waiting for an available session
2019-03-27 11:09:37.980 +01:00 [Debug] Session"142.1" created new session
2019-03-27 11:09:37.980 +01:00 [Debug] Pool"142" reaping connection pool
2019-03-27 11:09:37.980 +01:00 [Information] Pool"142" no pooled session available; created new Session"142.1"
2019-03-27 11:09:37.980 +01:00 [Debug] Pool"142" recovered no sessions
2019-03-27 11:09:37.980 +01:00 [Information] Session"142.1" connecting to IpAddress "127.0.1.1" for HostName '""'
2019-03-27 11:09:37.981 +01:00 [Debug] Session"142.1" connected to IpAddress "127.0.1.1" for HostName '""' with local Port 44451
2019-03-27 11:09:37.981 +01:00 [Debug] Session"142.1" got error payload: Code=1040, State="HY000", Message="Too many connections"
2019-03-27 11:09:37.981 +01:00 [Debug] Pool"142" disposing created Session"142.1" due to exception: "Too many connections"
MySql.Data.MySqlClient.MySqlException (0x80004005): Too many connections
   at MySqlConnector.Core.ServerSession.TryAsyncContinuation(Task`1 task) in C:\projects\mysqlconnector\src\MySqlConnector\Core\ServerSession.cs:line 1250
   at System.Threading.Tasks.ContinuationResultTaskFromResultTask`2.InnerInvoke()
   at System.Threading.ExecutionContext.RunInternal(ExecutionContext executionContext, ContextCallback callback, Object state)
--- End of stack trace from previous location where exception was thrown ---
   at System.Threading.Tasks.Task.ExecuteWithThreadLocal(Task& currentTaskSlot)
--- End of stack trace from previous location where exception was thrown ---
   at MySqlConnector.Core.ServerSession.ConnectAsync(ConnectionSettings cs, ILoadBalancer loadBalancer, IOBehavior ioBehavior, CancellationToken cancellationToken) in C:\projects\mysqlconnector\src\MySqlConnector\Core\ServerSession.cs:line 290
   at MySqlConnector.Core.ConnectionPool.GetSessionAsync(MySqlConnection connection, IOBehavior ioBehavior, CancellationToken cancellationToken) in C:\projects\mysqlconnector\src\MySqlConnector\Core\ConnectionPool.cs:line 112

2019-03-27 11:09:37.981 +01:00 [Information] Session"142.1" sending QUIT command
2019-03-27 11:09:37.981 +01:00 [Information] Session"142.1" closing stream/socket
2019-03-27 11:09:37.982 +01:00 [Information] System.Data.StateChangeEventArgs

The odd thing is that except for a couple of tests, there should never be more than 2-3 connections. As all the tests are in the same xunit test collection, they are not running in parallel. The only way I can fix it for our tests is to KILL all the connections. The good news is that eventually the sever closes those zombie connections, but this is not something we want to go to production with.

When the MySqlStreamStore is disposed, it will cancel a CancellationTokenSource for a background process (subscription). That's why I believe that this is related to #495 and #469.

[bgrainger]

Pool"142" creating new connection pool

This seems like a red flag; having over 100 connection pools in an application is unusual. I'm going to guess it's due to Database=test_ff0a0407b3a24ea399e73dc587c2b4bc in the connection string; are there are lot of unique test databases being created?

Without looking further, what I suspect happens is that hundreds of connection pools are created in a short amount of time, and each of those has one or more idle connections in it. Eventually those connections will be cleaned up, but until they are, there are hundreds of (useless) open connections to the server, which prevent new connections from being created.

Possible workarounds:

• Add ConnectionIdleTimeout=5 to your connection string. This will force idle connections to be cleaned up much more quickly.
• Add Pooling=false to your connection string. If you're only creating one or two connections per test database, there's not much benefit to pooling; disabling pooling means the connections will be closed immediately.

(In both cases, you need to be sure you'll calling MySqlConnection.Close() or .Dispose() (ideally via a using statement), so that connections go back to the pool, or get cleaned up deterministically.)

[thefringeninja]

Making that change seems to have worked. I will run the tests a few more times on travis to be sure, but for now I can close the issue. Thanks!

[karamokoisrael]

Pool"142" creating new connection pool

This seems like a red flag; having over 100 connection pools in an application is unusual. I'm going to guess it's due to Database=test_ff0a0407b3a24ea399e73dc587c2b4bc in the connection string; are there are lot of unique test databases being created?

Without looking further, what I suspect happens is that hundreds of connection pools are created in a short amount of time, and each of those has one or more idle connections in it. Eventually those connections will be cleaned up, but until they are, there are hundreds of (useless) open connections to the server, which prevent new connections from being created.

Possible workarounds:

* Add `ConnectionIdleTimeout=5` to your connection string. This will force idle connections to be cleaned up much more quickly.

* Add `Pooling=false` to your connection string. If you're only creating one or two connections per test database, there's not much benefit to pooling; disabling pooling means the connections will be closed immediately.

(In both cases, you need to be sure you'll calling MySqlConnection.Close() or .Dispose() (ideally via a using statement), so that connections go back to the pool, or get cleaned up deterministically.)

It also seems to be working for me. Thanks.