MySqlConnector icon indicating copy to clipboard operation
MySqlConnector copied to clipboard

Connect Timeout expired, All pooled connections are in use

Open swjain23 opened this issue 2 years ago • 27 comments

Hi,

We are getting this error "Connect Timeout expired. All pooled connections are in use" periodically. We only start getting these errors after some other exceptions from the server like:

Inner exception type: MySqlConnector.MySqlException Message: "Server is not ready for incoming connections."

Inner exception type: MySqlConnector.MySqlException Message: Connect Timeout expired. All pooled connections are in use.

Inner exception type: MySqlConnector.MySqlException Message: An error occurred when accessing your server. Please retry or report your issues.

We get many of the above exceptions and then we start seeing "Connect Timeout expired. All pooled connections are in use" and never recover until we kill our process and start again. We think there is some connection leak as we do not create more than 30 connections and have a pool size of 100 connections.

This is how we handle the connections in our code:

using (var connection = new MySqlConnection())
{
    connection.ConnectionString = ConnectionString;

    try
    {
        connection.Open();
    }
    catch (TException exc)
    {
        // Handle exception
    }

    using (var command = connection.CreateCommand())
    {
        command.CommandText = statementText;
        command.CommandType = CommandType.Text;

        try
        {
            return await command.ExecuteNonQueryAsync(cancellationToken).ConfigureAwait(false);
        }
        catch (TException exc)
        {
            // Handle exception
        }
    }
}

As we are handling the connection via a using statement, it should close and dispose the connection. Is there something that we are missing and need to do to make sure that the connection is returned to the pool after getting some of the command timeout or server errors? We are using MySqlConnector 1.3.8.

Stack Trace:

Inner exception type: MySqlConnector.MySqlException Message: Connect Timeout expired. All pooled connections are in use. HResult : 0x80004005 FacilityCode : 0 (000) ErrorCode : 16389 (4005) Data: Server Error Code = 1042 Stack: at MySqlConnector.MySqlConnection.<CreateSessionAsync>d__117.MoveNext() in //src/MySqlConnector/MySqlConnection.cs:line 881 --- End of stack trace from previous location where exception was thrown --- at System.Runtime.ExceptionServices.ExceptionDispatchInfo.Throw() at System.Runtime.CompilerServices.TaskAwaiter.HandleNonSuccessAndDebuggerNotification(Task task) at MySqlConnector.MySqlConnection.<OpenAsync>d__27.MoveNext() in //src/MySqlConnector/MySqlConnection.cs:line 423 --- End of stack trace from previous location where exception was thrown --- at System.Runtime.ExceptionServices.ExceptionDispatchInfo.Throw() at System.Runtime.CompilerServices.TaskAwaiter.HandleNonSuccessAndDebuggerNotification(Task task) at Microsoft.Migration.Data.Movement.Queries.MySql.Execution.MySqlQueryExecutor.<>c__DisplayClass5_0.<<GetReaderAsync>g__ConnectExecute|1>d.MoveNext() in C:\source\Product\Source\Microsoft.Migration.Data.Movement.Queries.MySql\Execution\MySqlQueryExecutor.cs:line 161 Inner exception type: System.OperationCanceledException Message: The operation was canceled. HResult : 0x8013153B FacilityCode : 19 (013) ErrorCode : 5435 (153b) Stack: at System.Threading.CancellationToken.ThrowOperationCanceledException() at System.Threading.SemaphoreSlim.<WaitUntilCountOrTimeoutAsync>d__31.MoveNext() --- End of stack trace from previous location where exception was thrown --- at System.Runtime.ExceptionServices.ExceptionDispatchInfo.Throw() at System.Runtime.CompilerServices.TaskAwaiter.ThrowForNonSuccess(Task task) at System.Runtime.CompilerServices.TaskAwaiter.HandleNonSuccessAndDebuggerNotification(Task task) at MySqlConnector.Core.ConnectionPool.<GetSessionAsync>d__10.MoveNext() in //src/MySqlConnector/Core/ConnectionPool.cs:line 41 --- End of stack trace from previous location where exception was thrown --- at System.Runtime.ExceptionServices.ExceptionDispatchInfo.Throw() at System.Runtime.CompilerServices.TaskAwaiter.ThrowForNonSuccess(Task task) at System.Runtime.CompilerServices.TaskAwaiter.HandleNonSuccessAndDebuggerNotification(Task task) at MySqlConnector.MySqlConnection.<CreateSessionAsync>d__117.MoveNext() in //src/MySqlConnector/MySqlConnection.cs:line 863

swjain23 avatar Sep 14 '21 07:09 swjain23

Is that all the relevant code as it looks like in prod? bc you are mixing sync (connection.Open) and async code (ExecuteAsync(token)); this is a recipe for long nights and loss of hair.

Also, it might help others if you reformat your code snippet a little for readability.

ghost avatar Sep 14 '21 07:09 ghost

We are using MySqlConnector 1.3.8

Firstly, please update to 1.3.10 or later; this fixes some bugs with connection resetting that may be contributing to this problem.

Secondly, do you have any more information on this exception, e.g., exception type and full call stack? I don't recognise the message:

Inner exception type: MySqlConnector.MySqlException Message: An error occurred when accessing your server. Please retry or report your issues.

bgrainger avatar Sep 14 '21 14:09 bgrainger

Is that all the relevant code as it looks like in prod? bc you are mixing sync (connection.Open) and async code (ExecuteAsync(token)); this is a recipe for long nights and loss of hair.

Also, it might help others if you reformat your code snippet a little for readability.

This is the relevant part for the connections. We do have some retry logic baked into this. The method itself with this code is async and is awaited, should it be a problem to use it this way? What issues can we hit?

swjain23 avatar Sep 14 '21 17:09 swjain23

We are using MySqlConnector 1.3.8

Firstly, please update to 1.3.10 or later; this fixes some bugs with connection resetting that may be contributing to this problem.

Secondly, do you have any more information on this exception, e.g., exception type and full call stack? I don't recognise the message:

Inner exception type: MySqlConnector.MySqlException Message: An error occurred when accessing your server. Please retry or report your issues.

Okay, we can update the version. We are connecting to an Azure MySQL server, I think it is a custom exception coming directly from the server when it is rejecting connections and there is no stack trace.

We did get a stack trace for the command timeout exception.

Inner exception type: MySqlConnector.MySqlException Message: The Command Timeout expired before the operation completed. AdditionalMessage: IsTransient: False HResult : 0x80004005 FacilityCode : 0 (000) ErrorCode : 16389 (4005) Data: Server Error Code = -1 Stack: at MySqlConnector.Protocol.Serialization.StreamByteHandler.<<ReadBytesAsync>g__DoReadBytesAsync|6_2>d.MoveNext() in //src/MySqlConnector/Protocol/Serialization/StreamByteHandler.cs:line 80 --- End of stack trace from previous location where exception was thrown --- at System.Runtime.ExceptionServices.ExceptionDispatchInfo.Throw() at System.Runtime.CompilerServices.TaskAwaiter.HandleNonSuccessAndDebuggerNotification(Task task) at MySqlConnector.Protocol.Serialization.BufferedByteReader.<ReadBytesAsync>d__2.MoveNext() in //src/MySqlConnector/Protocol/Serialization/BufferedByteReader.cs:line 36 --- End of stack trace from previous location where exception was thrown --- at System.Runtime.ExceptionServices.ExceptionDispatchInfo.Throw() at System.Runtime.CompilerServices.TaskAwaiter.HandleNonSuccessAndDebuggerNotification(Task task) at MySqlConnector.Protocol.Serialization.ProtocolUtility.<<ReadPacketAsync>g__AddContinuation|1_0>d.MoveNext() in //src/MySqlConnector/Protocol/Serialization/ProtocolUtility.cs:line 412 --- End of stack trace from previous location where exception was thrown --- at System.Runtime.ExceptionServices.ExceptionDispatchInfo.Throw() at System.Runtime.CompilerServices.TaskAwaiter.HandleNonSuccessAndDebuggerNotification(Task task) at MySqlConnector.Protocol.Serialization.ProtocolUtility.<<DoReadPayloadAsync>g__AddContinuation|5_0>d.MoveNext() in //src/MySqlConnector/Protocol/Serialization/ProtocolUtility.cs:line 479 --- End of stack trace from previous location where exception was thrown --- at System.Runtime.ExceptionServices.ExceptionDispatchInfo.Throw() at System.Runtime.CompilerServices.TaskAwaiter.HandleNonSuccessAndDebuggerNotification(Task task) at MySqlConnector.Core.ServerSession.<ReceiveReplyAsyncAwaited>d__86.MoveNext() in //src/MySqlConnector/Core/ServerSession.cs:line 884 --- End of stack trace from previous location where exception was thrown --- at System.Runtime.ExceptionServices.ExceptionDispatchInfo.Throw() at System.Runtime.CompilerServices.TaskAwaiter.HandleNonSuccessAndDebuggerNotification(Task task) at MySqlConnector.Core.ResultSet.<ReadResultSetHeaderAsync>d__2.MoveNext() in //src/MySqlConnector/Core/ResultSet.cs:line 50 --- End of stack trace from previous location where exception was thrown --- at System.Runtime.ExceptionServices.ExceptionDispatchInfo.Throw() at MySqlConnector.MySqlDataReader.ActivateResultSet(CancellationToken cancellationToken) in //src/MySqlConnector/MySqlDataReader.cs:line 137 at MySqlConnector.MySqlDataReader.<CreateAsync>d__97.MoveNext() in //src/MySqlConnector/MySqlDataReader.cs:line 459 --- End of stack trace from previous location where exception was thrown --- at System.Runtime.ExceptionServices.ExceptionDispatchInfo.Throw() at System.Runtime.CompilerServices.TaskAwaiter.HandleNonSuccessAndDebuggerNotification(Task task) at MySqlConnector.Core.CommandExecutor.<ExecuteReaderAsync>d__0.MoveNext() in //src/MySqlConnector/Core/CommandExecutor.cs:line 60 --- End of stack trace from previous location where exception was thrown --- at System.Runtime.ExceptionServices.ExceptionDispatchInfo.Throw() at System.Runtime.CompilerServices.TaskAwaiter.HandleNonSuccessAndDebuggerNotification(Task task) at MySqlConnector.MySqlCommand.<ExecuteNonQueryAsync>d__69.MoveNext() in //src/MySqlConnector/MySqlCommand.cs:line 266 --- End of stack trace from previous location where exception was thrown --- at System.Runtime.ExceptionServices.ExceptionDispatchInfo.Throw() at System.Runtime.CompilerServices.TaskAwaiter.HandleNonSuccessAndDebuggerNotification(Task task) at Microsoft.Migration.Queries.Execution.QueryBase`4.<>c__DisplayClass2b.<<ExecuteAsyncNonQuery>b__28>d__2d.MoveNext() in f:_work\8\s\Product\Source\Microsoft.Migration.Queries\Execution\QueryBase.cs:line 494

Inner exception type: System.ObjectDisposedException
Message: 
	Cannot access a disposed object.
	Object name: 'SslStream'.
HResult : 0x80131622
	FacilityCode : 19 (013)
	ErrorCode : 5666 (1622)
Stack: 
	at System.Net.Security.SslState.CheckThrow(Boolean authSuccessCheck, Boolean shutdownCheck)
	at System.Net.Security.SslState.get_SecureStream()
	at System.Net.Security.SslStream.EndRead(IAsyncResult asyncResult)
	at System.Threading.Tasks.TaskFactory`1.FromAsyncTrimPromise`1.Complete(TInstance thisRef, Func`3 endMethod, IAsyncResult asyncResult, Boolean requiresSynchronization)
	--- End of stack trace from previous location where exception was thrown ---
	at System.Runtime.ExceptionServices.ExceptionDispatchInfo.Throw()
	at System.Runtime.CompilerServices.TaskAwaiter.HandleNonSuccessAndDebuggerNotification(Task task)
	at MySqlConnector.Protocol.Serialization.StreamByteHandler.<<ReadBytesAsync>g__DoReadBytesAsync|6_2>d.MoveNext() in /_/src/MySqlConnector/Protocol/Serialization/StreamByteHandler.cs:line 70

swjain23 avatar Sep 14 '21 17:09 swjain23

Is that all the relevant code as it looks like in prod? bc you are mixing sync (connection.Open) and async code (ExecuteAsync(token)); this is a recipe for long nights and loss of hair. Also, it might help others if you reformat your code snippet a little for readability.

This is the relevant part for the connections. We do have some retry logic baked into this. The method itself with this code is async and is awaited, should it be a problem to use it this way? What issues can we hit?

That synchronous Open is definitely not ok; also check for aysnc using where needed. Mixing sync and async is definitely an anti-pattern that you should avoid.

ghost avatar Sep 14 '21 19:09 ghost

@bgrainger We are seeing the object disposed exception more frequently now. Is this a known issue? Here is another stack trace:

Inner exception type: MySqlConnector.MySqlException
Message:
    Connect Timeout expired.
AdditionalMessage:
    IsTransient: True
HResult : 0x80004005
    FacilityCode : 0 (000)
    ErrorCode : 16389 (4005)
Data:
    Server Error Code = 1042
Stack:
    at MySqlConnector.Core.ServerSession.<OpenTcpSocketAsync>d__91.MoveNext()
    --- End of stack trace from previous location where exception was thrown ---
    at System.Runtime.ExceptionServices.ExceptionDispatchInfo.Throw()
    at System.Runtime.CompilerServices.TaskAwaiter.HandleNonSuccessAndDebuggerNotification(Task task)
    at MySqlConnector.Core.ServerSession.<ConnectAsync>d__76.MoveNext() in /_/src/MySqlConnector/Core/ServerSession.cs:line 407
    --- End of stack trace from previous location where exception was thrown ---
    at System.Runtime.ExceptionServices.ExceptionDispatchInfo.Throw()
    at System.Runtime.CompilerServices.TaskAwaiter.HandleNonSuccessAndDebuggerNotification(Task task)
    at MySqlConnector.Core.ConnectionPool.<ConnectSessionAsync>d__21.MoveNext() in /_/src/MySqlConnector/Core/ConnectionPool.cs:line 376
    --- End of stack trace from previous location where exception was thrown ---
    at System.Runtime.ExceptionServices.ExceptionDispatchInfo.Throw()
    at System.Runtime.CompilerServices.TaskAwaiter.HandleNonSuccessAndDebuggerNotification(Task task)
    at MySqlConnector.Core.ConnectionPool.<GetSessionAsync>d__10.MoveNext() in /_/src/MySqlConnector/Core/ConnectionPool.cs:line 107
    --- End of stack trace from previous location where exception was thrown ---
    at System.Runtime.ExceptionServices.ExceptionDispatchInfo.Throw()
    at MySqlConnector.Core.ConnectionPool.<GetSessionAsync>d__10.MoveNext() in /_/src/MySqlConnector/Core/ConnectionPool.cs:line 137
    --- End of stack trace from previous location where exception was thrown ---
    at System.Runtime.ExceptionServices.ExceptionDispatchInfo.Throw()
    at System.Runtime.CompilerServices.TaskAwaiter.HandleNonSuccessAndDebuggerNotification(Task task)
    at MySqlConnector.MySqlConnection.<CreateSessionAsync>d__117.MoveNext() in /_/src/MySqlConnector/MySqlConnection.cs:line 863
Inner exception type: System.ObjectDisposedException
    Message:
        Cannot access a disposed object.
        Object name: 'System.Net.Sockets.Socket'.
    HResult : 0x80131622
        FacilityCode : 19 (013)
        ErrorCode : 5666 (1622)
    Stack:
        at System.Net.Sockets.Socket.InternalEndConnect(IAsyncResult asyncResult)
        at System.Net.Sockets.Socket.EndConnect(IAsyncResult asyncResult)
        at System.Net.Sockets.TcpClient.EndConnect(IAsyncResult asyncResult)
        at System.Threading.Tasks.TaskFactory`1.FromAsyncCoreLogic(IAsyncResult iar, Func`2 endFunction, Action`1 endAction, Task`1 promise, Boolean requiresSynchronization)
        --- End of stack trace from previous location where exception was thrown ---
        at System.Runtime.ExceptionServices.ExceptionDispatchInfo.Throw()
        at System.Runtime.CompilerServices.TaskAwaiter.HandleNonSuccessAndDebuggerNotification(Task task)
        at MySqlConnector.Core.ServerSession.<OpenTcpSocketAsync>d__91.MoveNext() in /_/src/MySqlConnector/Core/ServerSession.cs:line 986

swjain23 avatar Sep 16 '21 17:09 swjain23

This message (without "All pooled connections are in use.") and the inner exception means that opening a TCP socket to the MySQL Server timed out. That could indicate a problem with the remote server, or a firewall issue.

What do your server metrics show (in terms of open connections, number of active clients, etc.)?

bgrainger avatar Sep 16 '21 19:09 bgrainger

@bgrainger It cannot be a firewall issue as we were able to make the connection before and run various queries. It's in the middle that it started giving this error. It could be because the server had heavy transactions being applied. I do not have the connections metrics for the above exception (with disposed exception as inner exception) as we do not have access to the server.

But for the one with Inner exception type: MySqlConnector.MySqlException Message: An error occurred when accessing your server. Please retry or report your issues. These are the metrics with spike in number of connections when we started hitting the issue.

image

The exception above has a Server Error Code = 1042, but the inner exception is an object disposed exception. Can we assume that the connection is busted at this point? Or is it a transient command exception and we can retry?

swjain23 avatar Sep 17 '21 18:09 swjain23

the inner exception is an object disposed exception

You can (and should) ignore that: https://github.com/mysql-net/MySqlConnector/issues/1035

The exception above has a Server Error Code = 1042. Can we assume that the connection is busted at this point? Or is it a transient command exception and we can retry?

I'm still not sure exactly what causes that error message. The best information I can find seems to indicate that it comes from Azure Database for MySQL. It does seem to be a server-side problem, as confirmed by that "Due to System Error" graph. Was any failover occurring at this time?

That particular connection is likely unusable and should be disposed. I think your code should probably pause and retry after a short delay when this particular error code is received.

bgrainger avatar Sep 17 '21 22:09 bgrainger

@CatalinAdlerDF Moved to #1038.

bgrainger avatar Sep 19 '21 20:09 bgrainger

@bgrainger No failover was happening at that time. It still looks like there is some connection leak happening given that we only have 8 threads and we always have them in the using block. We did not have any high traffic on the server, but somehow the pool is expanding and hitting the limit.

"That particular connection is likely unusable and should be disposed. I think your code should probably pause and retry after a short delay when this particular error code is received." For the above comment, do we need to dispose it in any special manner? It is being used in the using block. Is there a way to discard a particular connection from the pool other than clearing the whole pool?

swjain23 avatar Sep 20 '21 21:09 swjain23

@bgrainger - As suggested by you to upgrade the connector, we started testing with 1.3.12 and are getting this exception from the connector on Connection.Open(). Should this not be wrapped in a MySQLException?

Inner exception type: System.ObjectDisposedException
Message: 
    Cannot access a disposed object.
    Object name: 'System.Net.Sockets.Socket'.
HResult : 0x80131622
    FacilityCode : 19 (013)
    ErrorCode : 5666 (1622)
Stack: 
    at System.Net.Sockets.Socket.SetSocketOption(SocketOptionLevel optionLevel, SocketOptionName optionName, Int32 optionValue)
    at MySqlConnector.Core.ServerSession.<OpenTcpSocketAsync>d__91.MoveNext() in /_/src/MySqlConnector/Core/ServerSession.cs:line 1036
    --- End of stack trace from previous location where exception was thrown ---
    at System.Runtime.ExceptionServices.ExceptionDispatchInfo.Throw()
    at MySqlConnector.Core.ServerSession.<ConnectAsync>d__76.MoveNext() in /_/src/MySqlConnector/Core/ServerSession.cs:line 407
    --- End of stack trace from previous location where exception was thrown ---
    at System.Runtime.ExceptionServices.ExceptionDispatchInfo.Throw()
    at System.Runtime.CompilerServices.TaskAwaiter.HandleNonSuccessAndDebuggerNotification(Task task)
    at MySqlConnector.Core.ConnectionPool.<ConnectSessionAsync>d__21.MoveNext() in /_/src/MySqlConnector/Core/ConnectionPool.cs:line 376
    --- End of stack trace from previous location where exception was thrown ---
    at System.Runtime.ExceptionServices.ExceptionDispatchInfo.Throw()
    at System.Runtime.CompilerServices.TaskAwaiter.HandleNonSuccessAndDebuggerNotification(Task task)
    at System.Runtime.CompilerServices.ConfiguredValueTaskAwaitable`1.ConfiguredValueTaskAwaiter.GetResult()
    at MySqlConnector.Core.ConnectionPool.<GetSessionAsync>d__10.MoveNext() in /_/src/MySqlConnector/Core/ConnectionPool.cs:line 107
    --- End of stack trace from previous location where exception was thrown ---
    at System.Runtime.ExceptionServices.ExceptionDispatchInfo.Throw()
    at MySqlConnector.Core.ConnectionPool.<GetSessionAsync>d__10.MoveNext() in /_/src/MySqlConnector/Core/ConnectionPool.cs:line 137
    --- End of stack trace from previous location where exception was thrown ---
    at System.Runtime.ExceptionServices.ExceptionDispatchInfo.Throw()
    at System.Runtime.CompilerServices.TaskAwaiter.HandleNonSuccessAndDebuggerNotification(Task task)
    at System.Runtime.CompilerServices.ConfiguredValueTaskAwaitable`1.ConfiguredValueTaskAwaiter.GetResult()
    at MySqlConnector.MySqlConnection.<CreateSessionAsync>d__117.MoveNext() in /_/src/MySqlConnector/MySqlConnection.cs:line 873
    --- End of stack trace from previous location where exception was thrown ---
    at System.Runtime.ExceptionServices.ExceptionDispatchInfo.Throw()
    at System.Runtime.CompilerServices.TaskAwaiter.HandleNonSuccessAndDebuggerNotification(Task task)
    at System.Runtime.CompilerServices.ConfiguredValueTaskAwaitable`1.ConfiguredValueTaskAwaiter.GetResult()
    at MySqlConnector.MySqlConnection.<OpenAsync>d__27.MoveNext() in /_/src/MySqlConnector/MySqlConnection.cs:line 414
    --- End of stack trace from previous location where exception was thrown ---
    at System.Runtime.ExceptionServices.ExceptionDispatchInfo.Throw()
    at System.Runtime.CompilerServices.TaskAwaiter.HandleNonSuccessAndDebuggerNotification(Task task)
    at MySqlConnector.MySqlConnection.Open() in /_/src/MySqlConnector/MySqlConnection.cs:line 380
    at Microsoft.Migration.Queries.Execution.QueryBase`4.<>c__DisplayClass57_0.<<ExecuteAsyncNonQuery>b__1>d.MoveNext()
    --- End of stack trace from previous location where exception was thrown ---
    at System.Runtime.ExceptionServices.ExceptionDispatchInfo.Throw()
    at System.Runtime.CompilerServices.TaskAwaiter.HandleNonSuccessAndDebuggerNotification(Task task)
    at Microsoft.Migration.Queries.Execution.QueryBaseRetryHandler.<RetryHandlerWithResult>d__9`1.MoveNext()
    --- End of stack trace from previous location where exception was thrown ---
    at System.Runtime.ExceptionServices.ExceptionDispatchInfo.Throw()
    at System.Runtime.CompilerServices.TaskAwaiter.HandleNonSuccessAndDebuggerNotification(Task task)
    at Microsoft.Migration.Queries.Execution.QueryBase`4.<ExecuteAsyncNonQuery>d__57.MoveNext()
    --- End of stack trace from previous location where exception was thrown ---
    at System.Runtime.ExceptionServices.ExceptionDispatchInfo.Throw()
    at System.Runtime.CompilerServices.TaskAwaiter.HandleNonSuccessAndDebuggerNotification(Task task)
    at Microsoft.Migration.Queries.Execution.QueryBase`4.<ExecuteAsyncNonQuery>d__47`1.MoveNext()
    --- End of stack trace from previous location where exception was thrown ---
    at System.Runtime.ExceptionServices.ExceptionDispatchInfo.Throw()
    at System.Runtime.CompilerServices.TaskAwaiter.HandleNonSuccessAndDebuggerNotification(Task task)
    at System.Runtime.CompilerServices.TaskAwaiter`1.GetResult()
    at Microsoft.MySql.Data.Movement.Writer.MySqlWriteRows.<ExecuteAsyncNonQueryParameterized>d__7.MoveNext()  

swjain23 avatar Sep 22 '21 06:09 swjain23

Should this not be wrapped in a MySQLException?

Are you sure it's not?

Inner exception type: System.ObjectDisposedException

That says "Inner exception". What's the outer exception?

FWIW, I'll be removing the inner exception, to fix this confusing problem: https://github.com/mysql-net/MySqlConnector/issues/1035

bgrainger avatar Sep 22 '21 14:09 bgrainger

@bgrainger - Yes, it is definitely not. Our pipeline failed because we were not expecting this error. We catch these exceptions from the connector and wrap them accordingly, this is an inner exception for our custom exception in which we wrapped it.

This is the full exception for reference, again it is further wrapped in another few exceptions, so removing that:

Inner exception type: Microsoft.Migration.DataMovement.Core.MySql.Contracts.MySqlDataMovementWriterUnhandledException
Message: 
    A batch could not be written to the table 
Stack: 
    at Microsoft.MySql.Data.Movement.DataMovementWriter.WriteBatch(IQueryTableDataRangeResult queryResult, DatabaseObjectName targetTableName, Guid activityId, Boolean useTableLock, Action`1 callback, Action`2 leakedConnectionCallback, Action`1 batchRetryCallback, CancellationToken cancelToken) in D:\GitHub\swjain\OSSDBDataMovementCommon\Product\Source\MySql.Data.Movement\DataMovementWriter.cs:line 203
    at Microsoft.SqlServer.Migration.Data.Movement.Steps.WriteDataRangeBatchStep.<>c__DisplayClass3_0.<OnNext>b__0(WriteDataRangeBatchWorkItem workItem)
    at Microsoft.SqlServer.Migration.Data.Movement.Steps.DataMovementErrorObservablePipelineStep`2.TryProcessWorkItem[WorkItemType](WorkItemType workItem, Action`1 workItemAction, Func`3 errorEventFactory, Func`2 canHandleExceptionPredicate)
    --- End of stack trace from previous location where exception was thrown ---
    at System.Runtime.ExceptionServices.ExceptionDispatchInfo.Throw()
    at Microsoft.SqlServer.Migration.Data.Movement.Steps.DataMovementErrorObservablePipelineStep`2.TryProcessWorkItem[WorkItemType](WorkItemType workItem, Action`1 workItemAction, Func`3 errorEventFactory, Func`2 canHandleExceptionPredicate)
    at Microsoft.SqlServer.Migration.Data.Movement.Steps.WriteDataRangeBatchStep.OnNext(WriteDataRangeBatchWorkItem writeDataRangeBatchWorkItem)
Inner exception type: System.ObjectDisposedException
    Message: 
        Cannot access a disposed object.
        Object name: 'System.Net.Sockets.Socket'.
    HResult : 0x80131622
        FacilityCode : 19 (013)
        ErrorCode : 5666 (1622)
    Stack: 
        at System.Net.Sockets.Socket.SetSocketOption(SocketOptionLevel optionLevel, SocketOptionName optionName, Int32 optionValue)
        at MySqlConnector.Core.ServerSession.<OpenTcpSocketAsync>d__91.MoveNext() in /_/src/MySqlConnector/Core/ServerSession.cs:line 1036
        --- End of stack trace from previous location where exception was thrown ---
        at System.Runtime.ExceptionServices.ExceptionDispatchInfo.Throw()
        at MySqlConnector.Core.ServerSession.<ConnectAsync>d__76.MoveNext() in /_/src/MySqlConnector/Core/ServerSession.cs:line 407
        --- End of stack trace from previous location where exception was thrown ---
        at System.Runtime.ExceptionServices.ExceptionDispatchInfo.Throw()
        at System.Runtime.CompilerServices.TaskAwaiter.HandleNonSuccessAndDebuggerNotification(Task task)
        at MySqlConnector.Core.ConnectionPool.<ConnectSessionAsync>d__21.MoveNext() in /_/src/MySqlConnector/Core/ConnectionPool.cs:line 376
        --- End of stack trace from previous location where exception was thrown ---
        at System.Runtime.ExceptionServices.ExceptionDispatchInfo.Throw()
        at System.Runtime.CompilerServices.TaskAwaiter.HandleNonSuccessAndDebuggerNotification(Task task)
        at System.Runtime.CompilerServices.ConfiguredValueTaskAwaitable`1.ConfiguredValueTaskAwaiter.GetResult()
        at MySqlConnector.Core.ConnectionPool.<GetSessionAsync>d__10.MoveNext() in /_/src/MySqlConnector/Core/ConnectionPool.cs:line 107
        --- End of stack trace from previous location where exception was thrown ---
        at System.Runtime.ExceptionServices.ExceptionDispatchInfo.Throw()
        at MySqlConnector.Core.ConnectionPool.<GetSessionAsync>d__10.MoveNext() in /_/src/MySqlConnector/Core/ConnectionPool.cs:line 137
        --- End of stack trace from previous location where exception was thrown ---
        at System.Runtime.ExceptionServices.ExceptionDispatchInfo.Throw()
        at System.Runtime.CompilerServices.TaskAwaiter.HandleNonSuccessAndDebuggerNotification(Task task)
        at System.Runtime.CompilerServices.ConfiguredValueTaskAwaitable`1.ConfiguredValueTaskAwaiter.GetResult()
        at MySqlConnector.MySqlConnection.<CreateSessionAsync>d__117.MoveNext() in /_/src/MySqlConnector/MySqlConnection.cs:line 873
        --- End of stack trace from previous location where exception was thrown ---
        at System.Runtime.ExceptionServices.ExceptionDispatchInfo.Throw()
        at System.Runtime.CompilerServices.TaskAwaiter.HandleNonSuccessAndDebuggerNotification(Task task)
        at System.Runtime.CompilerServices.ConfiguredValueTaskAwaitable`1.ConfiguredValueTaskAwaiter.GetResult()
        at MySqlConnector.MySqlConnection.<OpenAsync>d__27.MoveNext() in /_/src/MySqlConnector/MySqlConnection.cs:line 414
        --- End of stack trace from previous location where exception was thrown ---
        at System.Runtime.ExceptionServices.ExceptionDispatchInfo.Throw()
        at System.Runtime.CompilerServices.TaskAwaiter.HandleNonSuccessAndDebuggerNotification(Task task)
        at MySqlConnector.MySqlConnection.Open() in /_/src/MySqlConnector/MySqlConnection.cs:line 380
        at Microsoft.Migration.Queries.Execution.QueryBase`4.<>c__DisplayClass57_0.<<ExecuteAsyncNonQuery>b__1>d.MoveNext()
        --- End of stack trace from previous location where exception was thrown ---
        at System.Runtime.ExceptionServices.ExceptionDispatchInfo.Throw()
        at System.Runtime.CompilerServices.TaskAwaiter.HandleNonSuccessAndDebuggerNotification(Task task)
        at Microsoft.Migration.Queries.Execution.QueryBaseRetryHandler.<RetryHandlerWithResult>d__9`1.MoveNext()
        --- End of stack trace from previous location where exception was thrown ---
        at System.Runtime.ExceptionServices.ExceptionDispatchInfo.Throw()
        at System.Runtime.CompilerServices.TaskAwaiter.HandleNonSuccessAndDebuggerNotification(Task task)
        at Microsoft.Migration.Queries.Execution.QueryBase`4.<ExecuteAsyncNonQuery>d__57.MoveNext()
        --- End of stack trace from previous location where exception was thrown ---
        at System.Runtime.ExceptionServices.ExceptionDispatchInfo.Throw()
        at System.Runtime.CompilerServices.TaskAwaiter.HandleNonSuccessAndDebuggerNotification(Task task)
        at Microsoft.Migration.Queries.Execution.QueryBase`4.<ExecuteAsyncNonQuery>d__47`1.MoveNext()
        --- End of stack trace from previous location where exception was thrown ---
        at System.Runtime.ExceptionServices.ExceptionDispatchInfo.Throw()
        at System.Runtime.CompilerServices.TaskAwaiter.HandleNonSuccessAndDebuggerNotification(Task task)
        at System.Runtime.CompilerServices.TaskAwaiter`1.GetResult()
        at Microsoft.MySql.Data.Movement.Writer.MySqlWriteRows.<ExecuteAsyncNonQueryParameterized>d__7.MoveNext() in 

swjain23 avatar Sep 22 '21 17:09 swjain23

Thanks for the full exception. Assuming the line number is approximately correct, looks like the exception is being thrown from here: https://github.com/mysql-net/MySqlConnector/blob/1.3.12/src/MySqlConnector/Core/ServerSession.cs#L1036-L1037

Which is calling into this code: https://github.com/mysql-net/MySqlConnector/blob/1.3.12/src/MySqlConnector/Utilities/SocketExtensions.cs#L43-L46

It looks like an ObjectDisposedException thrown from this line would not be wrapped in a MySqlException, but I understand that you would expect it to be. I think this would indicate a connect timeout, but I'm not yet clear why it would manifest in this way.

Secondly, even if this were correctly wrapped in a MySqlException, I take it you are not expecting any exceptions to be thrown from MySqlConnection.Open, so we also still need to figure out why the connection is timing out?

bgrainger avatar Sep 22 '21 19:09 bgrainger

"That particular connection is likely unusable and should be disposed. I think your code should probably pause and retry after a short delay when this particular error code is received."

For the above comment, do we need to dispose it in any special manner? It is being used in the using block. Is there a way to discard a particular connection from the pool other than clearing the whole pool?

If all MySqlConnection objects are used with a using block (or declaration), that is sufficient. When a MySqlConnection is disposed, it will be put back in the pool if it's still usable, otherwise it will be discarded and the space in the pool should be freed up. If you're running out of pooled connections even though you're correctly disposing them, then it's plausible that there's a leak (that may only happen under failure conditions). As I mentioned before, unfortunately 1.3.8 had some bugs in connection resetting that should be fixed in 1.3.10 and later. Have you stopped getting "Connect Timeout expired. All pooled connections are in use" since updating to 1.3.12?

bgrainger avatar Sep 22 '21 19:09 bgrainger

@bgrainger - We are running some stress tests with 1.3.12 to make sure our performance is not affected before updating our product code, and that is when we hit the above ObjectDisposed exception. We were also running some perf tests and noticed that the performance of our application went significantly down with 1.3.12 vs 1.3.8. So we are still looking into that. It is not super easy to reproduce "Connect Timeout expired. All pooled connections are in use", it does not happen frequently. But once we figure out the perf issues, we will update to 1.3.12 and see if we hit the error again.

swjain23 avatar Sep 22 '21 21:09 swjain23

It looks like an ObjectDisposedException thrown from this line would not be wrapped in a MySqlException, but I understand that you would expect it to be. I think this would indicate a connect timeout, but I'm not yet clear why it would manifest in this way.

Secondly, even if this were correctly wrapped in a MySqlException, I take it you are not expecting any exceptions to be thrown from MySqlConnection.Open, so we also still need to figure out why the connection is timing out?

Do you need something from us for investigating this? Also, should we open a separate issue for this?

swjain23 avatar Sep 22 '21 21:09 swjain23

We were also running some perf tests and noticed that the performance of our application went significantly down with 1.3.12 vs 1.3.8. So we are still looking into that.

This is most likely due to DeferConnectionReset being removed as an option (due to bugginess).

The default behaviour of MySqlConnector is to reset every connection that is retrieved from the pool, to ensure it's in a good state. If your application has high performance needs, and you know you're not creating temporary tables, setting user variables, or doing anything else that affects session state, you could add Connection Reset=false to your connection string to opt out of connection resetting and likely improve performance.

EDIT: Connection Reset, not Reset Connection.

bgrainger avatar Sep 22 '21 21:09 bgrainger

Do you need something from us for investigating this?

Is it something that occurs frequently for you? When it happens, does it occur after 15 seconds (or whatever ConnectTimeout is set to in the connection string)? I.e., does it appear like it's a Connect Timeout exception, just with the wrong exception type?

bgrainger avatar Sep 22 '21 21:09 bgrainger

We were also running some perf tests and noticed that the performance of our application went significantly down with 1.3.12 vs 1.3.8. So we are still looking into that.

This is most likely due to DeferConnectionReset being removed as an option (due to bugginess).

The default behaviour of MySqlConnector is to reset every connection that is retrieved from the pool, to ensure it's in a good state. If your application has high performance needs, and you know you're not creating temporary tables, setting user variables, or doing anything else that affects session state, you could add Connection Reset=false to your connection string to opt out of connection resetting and likely improve performance.

EDIT: Connection Reset, not Reset Connection.

So, in 1.3.8 it was deferring connection reset by default? If we set Connection Reset = false, will we hit the buggy code? Also, we were wondering that given that there is likely some leak happening, does it make sense for us to clear the pool when we hit the error "Connect Timeout expired. All pooled connections are in use.". Given that this does not stop the running queries, it would not hamper our pipeline and the pool will be cleared to hand out new exceptions.

swjain23 avatar Sep 23 '21 17:09 swjain23

Do you need something from us for investigating this?

Is it something that occurs frequently for you? When it happens, does it occur after 15 seconds (or whatever ConnectTimeout is set to in the connection string)? I.e., does it appear like it's a Connect Timeout exception, just with the wrong exception type?

No, this did not happen frequently, out of few test runs we hit it only once so far. We ran this test overnight so I am not 100% sure it timed out after ConnectionTimeout (we use default 15 seconds), but looking at our telemetry, it does seem like it took 15 seconds.

swjain23 avatar Sep 23 '21 20:09 swjain23

So, in 1.3.8 it was deferring connection reset by default?

1.3.8 reset the connection on a background thread before returning it to the pool (so that no reset was needed when retrieving from the pool, which was intended to improve performance). However, it could get bottlenecked or (based on user reports) apparently leak connections. It was not robust enough to ship enabled by default, so it was disabled in 1.3.10 (and will be removed in 1.4.0).

If we set Connection Reset = false, will we hit the buggy code?

No, that code is controlled by a different setting (Defer Connection Reset).

Also, we were wondering that given that there is likely some leak happening, does it make sense for us to clear the pool when we hit the error "Connect Timeout expired. All pooled connections are in use.".

I haven't actually tested this, but I don't think it will help. Clearing a pool closes all the idle connections in the pool (there should be 0 if you're getting that error) and flags all open connections to be closed when they're returned (there should be 0 outstanding connections in your code if there's truly a leak). I'd love to know more details of how this leak manifests itself; there aren't currently any known conditions under which connections will leak (except for user code creating a MySqlConnection, calling Open, then never calling Dispose and also rooting the MySqlConnection object so it can't be GCed). If you're using every MySqlConnection in a using statement, and never opening more than Maximum Pool Size concurrent connections, you shouldn't ever see this message.

bgrainger avatar Sep 23 '21 20:09 bgrainger

No, this did not happen frequently ... it does seem like it took 15 seconds.

Based on the code, it seems like this could happen under (what I would assume is) an extremely rare race condition. I will try to make a stress test that could trigger it.

bgrainger avatar Sep 23 '21 20:09 bgrainger

We were also running some perf tests and noticed that the performance of our application went significantly down with 1.3.12 vs 1.3.8. So we are still looking into that.

This is most likely due to DeferConnectionReset being removed as an option (due to bugginess).

The default behaviour of MySqlConnector is to reset every connection that is retrieved from the pool, to ensure it's in a good state. If your application has high performance needs, and you know you're not creating temporary tables, setting user variables, or doing anything else that affects session state, you could add Connection Reset=false to your connection string to opt out of connection resetting and likely improve performance.

EDIT: Connection Reset, not Reset Connection.

Tried using the property in our connection string but did not help with the performance. It still takes almost double the amount of time that it takes with 1.3.8 to run.

swjain23 avatar Sep 27 '21 22:09 swjain23

I'm guessing that's probably due to https://github.com/mysql-net/MySqlConnector/issues/1042.

If you have the bandwidth to test an experiment, you could try adding Connection Idle Ping Time=10000; to your connection string, and see if that brings perf back to the expected/desired level. That said, I'd strongly advise against deploying that connection string option to production; it's documented as "experimental" and (as per the issue above) may be removed in the next release. (Confirmation from you that this does improve perf would be additional impetus to implement that case.)

bgrainger avatar Sep 27 '21 23:09 bgrainger

Thanks for the full exception. Assuming the line number is approximately correct, looks like the exception is being thrown from here: https://github.com/mysql-net/MySqlConnector/blob/1.3.12/src/MySqlConnector/Core/ServerSession.cs#L1036-L1037

I was never able to reproduce this, but I've added (what I think is) a fix for this exception based on the message and call stack: https://github.com/mysql-net/MySqlConnector/pull/1050.

bgrainger avatar Oct 02 '21 16:10 bgrainger