MySqlConnector
MySqlConnector copied to clipboard
mysql-net
query running after CommandTimeout expired
Software versions MySqlConnector version: 2.1.0 Server type (MySQL, MariaDB, Aurora, etc.) and version: Azure MySQL 8.0 .NET version: (Optional) ORM NuGet packages and versions: 4.7.2
Describe the bug
We have a query with 30 second commandTimeout. At times it takes more than 30 seconds to run the query, which results in getting a MySQL exception with inner exception error code = MySqlErrorCode.CommandTimeoutExpired. We haven't modified the CancellationTimeout in our connection string, so I expect it to have a Hard cancellation resulting in connection to be closed (https://mysqlconnector.net/overview/command-cancellation/). But when I check the connections in Workbench, I can still see the connections active and they are running the query even if our application has died. We have a using block for our commands and in our finally section, we explicitly dispose the connection. I expect the connections that hit the commandTimeout should be killed after 30 + 2 secs and not run the query anymore. Is that correct from my understanding?
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 76
--- End of stack trace from previous location where exception was thrown ---
at System.Runtime.ExceptionServices.ExceptionDispatchInfo.Throw()
at MySqlConnector.Protocol.Serialization.BufferedByteReader.<ReadBytesAsync>d__2.MoveNext() in /_/src/MySqlConnector/Protocol/Serialization/BufferedByteReader.cs:line 34
--- 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 409
--- 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 476
--- 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__93.MoveNext() in /_/src/MySqlConnector/Core/ServerSession.cs:line 950
--- End of stack trace from previous location where exception was thrown ---
at System.Runtime.ExceptionServices.ExceptionDispatchInfo.Throw()
at MySqlConnector.Core.ResultSet.<ReadResultSetHeaderAsync>d__2.MoveNext() in /_/src/MySqlConnector/Core/ResultSet.cs:line 44
--- 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 127
at MySqlConnector.MySqlDataReader.<CreateAsync>d__102.MoveNext() in /_/src/MySqlConnector/MySqlDataReader.cs:line 471
--- 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 56
--- 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.<ExecuteReaderAsync>d__84.MoveNext() in /_/src/MySqlConnector/MySqlCommand.cs:line 330
--- 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.<ExecuteDbDataReaderAsync>d__83.MoveNext() in /_/src/MySqlConnector/MySqlCommand.cs:line 323
--- 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__DisplayClass50_0`1.<<ExecuteAsync>b__0>d.MoveNext() in C:\__w\1\s\Product\Source\Microsoft.Migration.Queries\Execution\QueryBase.cs:line 347
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.Write(Byte[] buffer, Int32 offset, Int32 count)
at MySqlConnector.Utilities.Utility.Write(Stream stream, ReadOnlyMemory`1 data) in /_/src/MySqlConnector/Utilities/Utility.cs:line 545
at MySqlConnector.Protocol.Serialization.StreamByteHandler.WriteBytesAsync(ReadOnlyMemory`1 data, IOBehavior ioBehavior) in /_/src/MySqlConnector/Protocol/Serialization/StreamByteHandler.cs:line 96
--- 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.<<WritePacketAsync>g__WritePacketAsyncAwaited|8_0>d.MoveNext() in /_/src/MySqlConnector/Protocol/Serialization/ProtocolUtility.cs:line 543
--- 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.<DisposeAsync>d__82.MoveNext() in /_/src/MySqlConnector/Core/ServerSession.cs:line 371"
Code sample
var connection = GetConnection(cancellationToken);
try
{
try
{
if (connection.State != ConnectionState.Open)
{
await connection.OpenAsync(cancellationToken);
}
}
catch (TException exc)
{
// custom exception
throw;
}
try
{
using (var command = connection.CreateCommand())
{
command.CommandText = queryText;
command.CommandType = CommandType.Text;
command.CommandTimeout = 2;
try
{
// Execute command and process result
using (var reader = await command.ExecuteReaderAsync(cancellationToken))
{
return await resultHandler(reader, cancellationToken).ConfigureAwait(false);
}
}
catch (Exception exc)
{
throw;
}
}
}
catch (Exception e)
{
throw;
}
}
finally
{
if (connection != null)
{
connection.Dispose();
}
}
Expected behavior
I expect a hard cancellation, query should stop running and the underlying connection to close.
Additional context Add any other context about the problem here.
MySqlConnector version: 2.1.0
This is a little old; can you update to 2.2.5 to verify you have the latest code?
Inner exception type: System.ObjectDisposedException... at MySqlConnector.Core.ServerSession.<DisposeAsync>d__82.MoveNext() in /_/src/MySqlConnector/Core/ServerSession.cs:line 371
This inner exception doesn't make sense to me. There is a catch (ObjectDisposedException) block immediately afterwards, so this exception should never propagate. https://github.com/mysql-net/MySqlConnector/blob/2.1.0/src/MySqlConnector/Core/ServerSession.cs#L367-L381
Something similar has been reported in the past: https://github.com/mysql-net/MySqlConnector/issues/873#issuecomment-675521275
But when I check the connections in Workbench, I can still see the connections active and they are running the query even if our application has died.
If a KILL QUERY has not occurred, MySQL Server may keep running the query. AFAIK, it does not poll the socket to see if the client has disconnected, to know if it should cancel the query. It's likely it will keep running until the result set is ready, then it will only notice that the client has disconnected when it tries to write to the socket.
I expect the connections that hit the commandTimeout should be killed after 30 + 2 secs and not run the query anymore. Is that correct from my understanding?
That is correct. Are you getting the MySqlException (that you pasted above) after 32 seconds? If so, it sounds like MySqlConnector is working as designed.
The part that might not be working is sending the KILL QUERY to cancel the query server-side? Are you using any kind of load-balancing or proxy or replication?
It might help to attach Trace-level logs from MySqlConnector for this process to try to track down what's happening with cancellation.
"If a KILL QUERY has not occurred, MySQL Server may keep running the query. AFAIK, it does not poll the socket to see if the client has disconnected, to know if it should cancel the query. It's likely it will keep running until the result set is ready, then it will only notice that the client has disconnected when it tries to write to the socket."
How should we make sure that KILL QUERY happens?
"That is correct. Are you getting the MySqlException (that you pasted above) after 32 seconds? If so, it sounds like MySqlConnector is working as designed."
Yes, it is getting the exception after 32 seconds and I tried with the latest version 2.2.5 as well and got the same result. No, not using any load-balancing or proxy/replication.
I have attached the mysqlConnector logs. mysqlLogs.txt
How should we make sure that KILL QUERY happens?
It looks like it is happening, according to the logs.
One thing I can't see in the logs is the timing of any event. Are you able to recreate the logs with a timestamp (with at least millisecond precision) and reattach them?
KILL QUERY nnn is definitely being sent to the server, but I can't tell if it's having any effect. (Maybe we can infer that it isn't.) It's a statement, so AFAIK we can't get a "return value" from it of whether it succeeded or not.
I'm pretty sure the KILL command is being sent to the same server that's running the other command, so perhaps the thread ID value is wrong somehow? This is given to us in the initial handshake packet, and I've never know it to be wrong before (for Azure Database for MySQL Flexible Server; it can be wrong in a MySQL proxying scenario).
You could try executing SELECT CONNECTION_ID(); and logging the results (immediately before executing your long/slow SQL statement on the same MySqlConnection instance); that would let us know if there's some discrepancy in connection IDs.