Skip to content

Commit

Permalink
Add more logging for cancellation.
Browse files Browse the repository at this point in the history
  • Loading branch information
bgrainger committed Mar 7, 2021
1 parent 9b400ed commit 8b91dbe
Show file tree
Hide file tree
Showing 2 changed files with 15 additions and 3 deletions.
6 changes: 5 additions & 1 deletion src/MySqlConnector/Core/ServerSession.cs
Original file line number Diff line number Diff line change
Expand Up @@ -113,18 +113,22 @@ public bool TryStartCancel(ICancellableCommand command)

public void DoCancel(ICancellableCommand commandToCancel, MySqlCommand killCommand)
{
Log.Info("Session{0} canceling CommandId {1}: CommandText: {2}", m_logArguments[0], commandToCancel.CommandId, (commandToCancel as MySqlCommand)?.CommandText);
Log.Info("Session{0} canceling CommandId {1} from Session{2}; CommandText: {3}", m_logArguments[0], commandToCancel.CommandId, killCommand.Connection!.Session.Id, (commandToCancel as MySqlCommand)?.CommandText);
lock (m_lock)
{
if (ActiveCommandId != commandToCancel.CommandId)
{
Log.Info("Session{0} ActiveCommandId {1} is not the CommandId {2} being canceled; ignoring cancellation.", m_logArguments[0], ActiveCommandId, commandToCancel.CommandId);
return;
}

// NOTE: This command is executed while holding the lock to prevent race conditions during asynchronous cancellation.
// For example, if the lock weren't held, the current command could finish and the other thread could set ActiveCommandId
// to zero, then start executing a new command. By the time this "KILL QUERY" command reached the server, the wrong
// command would be killed (because "KILL QUERY" specifies the connection whose command should be killed, not
// a unique identifier of the command itself). As a mitigation, we set the CommandTimeout to a low value to avoid
// blocking the other thread for an extended duration.
Log.Info("Session{0} canceling CommandId {1} with CommandText {2}", killCommand.Connection!.Session.Id, commandToCancel.CommandId, killCommand.CommandText);
killCommand.ExecuteNonQuery();
}
}
Expand Down
12 changes: 10 additions & 2 deletions src/MySqlConnector/MySqlCommand.cs
Original file line number Diff line number Diff line change
Expand Up @@ -6,6 +6,7 @@
using System.Threading;
using System.Threading.Tasks;
using MySqlConnector.Core;
using MySqlConnector.Logging;
using MySqlConnector.Protocol.Serialization;
using MySqlConnector.Utilities;

Expand Down Expand Up @@ -94,7 +95,11 @@ private MySqlCommand(MySqlCommand other)
public new MySqlParameter CreateParameter() => (MySqlParameter) base.CreateParameter();

/// <inheritdoc/>
public override void Cancel() => Connection?.Cancel(this);
public override void Cancel()
{
Log.Info("CommandId {0} for Session{1} has been canceled via Cancel().", m_commandId, Connection?.Session.Id);
Connection?.Cancel(this);
}

/// <inheritdoc/>
public override int ExecuteNonQuery() => ExecuteNonQueryAsync(IOBehavior.Synchronous, CancellationToken.None).GetAwaiter().GetResult();
Expand Down Expand Up @@ -387,8 +392,9 @@ void ICancellableCommand.SetTimeout(int milliseconds)

private void CancelCommandForTimeout()
{
Log.Info("CommandId {0} for Session{1} has been canceled via command timeout.", m_commandId, Connection?.Session.Id);
Volatile.Write(ref m_commandTimedOut, true);
Cancel();
Connection?.Cancel(this);
}

private bool IsValid([NotNullWhen(false)] out Exception? exception)
Expand All @@ -414,6 +420,8 @@ private bool IsValid([NotNullWhen(false)] out Exception? exception)
MySqlParameterCollection? IMySqlCommand.OutParameters { get; set; }
MySqlParameter? IMySqlCommand.ReturnParameter { get; set; }

static readonly IMySqlConnectorLogger Log = MySqlConnectorLogManager.CreateLogger(nameof(MySqlCommand));

readonly int m_commandId;
bool m_isDisposed;
MySqlConnection? m_connection;
Expand Down

0 comments on commit 8b91dbe

Please sign in to comment.