Bug #109846 .Net connector fails to kill query
Submitted: 30 Jan 2023 15:22 Modified: 9 Feb 2023 10:51
Reporter: Sami Ahlroos Email Updates:
Status: Verified Impact on me:
None 
Category:Connector / NET Severity:S3 (Non-critical)
Version:8.0.32 OS:Any
Assigned to: CPU Architecture:Any

[30 Jan 2023 15:22] Sami Ahlroos
Description:
When a query times out, Connector opens a new connection to kill the query.
Starting with version 8.0.31 this fails.

How to repeat:
Example program:
----
using System;
using System.Data;
using MySql.Data;
using MySql.Data.MySqlClient;
using System.Diagnostics;
using System.Collections;
using System.Collections.Generic;

namespace z
{
    class Program
    {
    const string connectionString = "SERVER=localhost;UID=sami;password=Ab12_6543!;database=test;logging=true;";
    static void Main(string[] args)
    {
        Console.WriteLine("Hello World?");
        var mySqlAssembly = typeof(MySqlConnection).Assembly;
        Console.WriteLine(mySqlAssembly.GetName());

        // Configure Logging
        MySql.Data.MySqlClient.MySqlTrace.Switch.Level = SourceLevels.All;
        MySql.Data.MySqlClient.MySqlTrace.Listeners.Add(new TextWriterTraceListener(Console.Out));

        // Try the test
        Console.WriteLine("Running Non-Query version");
        RunNonQuery();

        // Wait before ending the application and closing the pool.
        Console.WriteLine("Press Enter to close the application and the Connection Pool");
        Console.ReadLine();
    }

    static void LogException(Exception ex)
    {
        var messages = new List<string>();
        var exception = ex;
        do
        {
            messages.Add(exception.GetType().Name + ": " + exception.Message);
            exception = exception.InnerException;
        } while (exception != null && exception is MySqlException);

        Console.WriteLine();
        Console.WriteLine(String.Join("\r\n\t", messages));
    }

    /// <summary>Run an ExecuteNonQuery </summary>
    static void RunNonQuery()
    {
        const string query = @"
        INSERT INTO t1 values(42);
        SELECT SLEEP(20);";

        using (var connection = new MySql.Data.MySqlClient.MySqlConnection(connectionString))
        {
            connection.Open();

            using (var transaction = connection.BeginTransaction())
            {
                var command = new MySql.Data.MySqlClient.MySqlCommand(query, connection);
                command.Transaction = transaction;
                command.CommandTimeout = 5;

                try
                {
                    command.ExecuteNonQuery();
                }
                catch (Exception ex)
                {
                    LogException(ex);
                }
            }
        }
    }
  }
}
----

Running the program with Connector version 8.0.30:
----

[root@sami-ahlroos-default b]# dotnet run
Hello World?
MySql.Data, Version=8.0.30.0, Culture=neutral, PublicKeyToken=c5687fc88969c44d
Running Non-Query version
mysql Information: 1 : 1: Connection Opened: connection string = 'server=localhost;user id=sami;password=Ab12_6543!;database=test;logging=True'
mysql Information: 3 : 1: Query Opened: SELECT @@max_allowed_packet, @@character_set_client,
        @@character_set_connection, @@license, @@sql_mode, @@lower_case_table_names, @@autocommit
mysql Information: 4 : 1: Resultset Opened: field(s) = 7, affected rows = -1, inserted id = -1
mysql Information: 5 : 1: Resultset Closed. Total rows=1, skipped rows=0, size (bytes)=164
mysql Information: 6 : 1: Query Closed
mysql Information: 3 : 1: Query Opened: SELECT TIMEDIFF(NOW(), UTC_TIMESTAMP())
mysql Information: 4 : 1: Resultset Opened: field(s) = 1, affected rows = -1, inserted id = -1
mysql Information: 5 : 1: Resultset Closed. Total rows=1, skipped rows=0, size (bytes)=9
mysql Information: 6 : 1: Query Closed
mysql Information: 3 : 1: Query Opened: SHOW COLLATION
mysql Information: 4 : 1: Resultset Opened: field(s) = 6, affected rows = -1, inserted id = -1
mysql Information: 5 : 1: Resultset Closed. Total rows=222, skipped rows=0, size (bytes)=7487
mysql Information: 6 : 1: Query Closed
mysql Information: 3 : 1: Query Opened: SET NAMES latin1
mysql Information: 4 : 1: Resultset Opened: field(s) = 0, affected rows = 0, inserted id = 0
mysql Information: 5 : 1: Resultset Closed. Total rows=0, skipped rows=0, size (bytes)=0
mysql Information: 6 : 1: Query Closed
mysql Information: 3 : 1: Query Opened: SET character_set_results=NULL
mysql Information: 4 : 1: Resultset Opened: field(s) = 0, affected rows = 0, inserted id = 0
mysql Information: 5 : 1: Resultset Closed. Total rows=0, skipped rows=0, size (bytes)=0
mysql Information: 6 : 1: Query Closed
mysql Information: 10 : 1: Set Database: test
mysql Information: 3 : 1: Query Opened: SET  TRANSACTION ISOLATION LEVEL REPEATABLE READ
mysql Information: 4 : 1: Resultset Opened: field(s) = 0, affected rows = 0, inserted id = 0
mysql Information: 5 : 1: Resultset Closed. Total rows=0, skipped rows=0, size (bytes)=0
mysql Information: 6 : 1: Query Closed
mysql Information: 3 : 1: Query Opened: BEGIN
mysql Information: 4 : 1: Resultset Opened: field(s) = 0, affected rows = 0, inserted id = 0
mysql Information: 5 : 1: Resultset Closed. Total rows=0, skipped rows=0, size (bytes)=0
mysql Information: 6 : 1: Query Closed
mysql Information: 3 : 1: Query Opened: INSERT INTO t1 values(42);
SELECT SLEEP(20)
mysql Information: 4 : 1: Resultset Opened: field(s) = 0, affected rows = 1, inserted id = 0
mysql Information: 5 : 1: Resultset Closed. Total rows=0, skipped rows=0, size (bytes)=0
mysql Information: 13 : 1: Error encountered attempting to open result: Number=0, Message=Reading from the stream has failed.
mysql Information: 2 : 1: Connection Closed

MySqlException: Fatal error encountered during command execution.
	MySqlException: Fatal error encountered attempting to read the resultset.
	MySqlException: Reading from the stream has failed.
Press Enter to close the application and the Connection Pool
----

And starting with 8.0.31:
----
[root@sami-ahlroos-default b]# dotnet run
Hello World?
MySql.Data, Version=8.0.31.0, Culture=neutral, PublicKeyToken=c5687fc88969c44d
Running Non-Query version
mysql Information: 1 : 1: Connection Opened: connection string = 'server=localhost;user id=sami;password=Ab12_6543!;database=test;logging=True'
mysql Information: 3 : 1: Query Opened: SELECT @@max_allowed_packet, @@character_set_client,
        @@character_set_connection, @@license, @@sql_mode, @@lower_case_table_names, @@autocommit
mysql Information: 4 : 1: Resultset Opened: field(s) = 7, affected rows = -1, inserted id = -1
mysql Information: 5 : 1: Resultset Closed. Total rows=1, skipped rows=0, size (bytes)=164
mysql Information: 6 : 1: Query Closed
mysql Information: 3 : 1: Query Opened: SELECT TIMEDIFF(NOW(), UTC_TIMESTAMP())
mysql Information: 4 : 1: Resultset Opened: field(s) = 1, affected rows = -1, inserted id = -1
mysql Information: 5 : 1: Resultset Closed. Total rows=1, skipped rows=0, size (bytes)=9
mysql Information: 6 : 1: Query Closed
mysql Information: 3 : 1: Query Opened: SHOW COLLATION
mysql Information: 4 : 1: Resultset Opened: field(s) = 6, affected rows = -1, inserted id = -1
mysql Information: 5 : 1: Resultset Closed. Total rows=222, skipped rows=0, size (bytes)=7487
mysql Information: 6 : 1: Query Closed
mysql Information: 3 : 1: Query Opened: SET NAMES latin1
mysql Information: 4 : 1: Resultset Opened: field(s) = 0, affected rows = 0, inserted id = 0
mysql Information: 5 : 1: Resultset Closed. Total rows=0, skipped rows=0, size (bytes)=0
mysql Information: 6 : 1: Query Closed
mysql Information: 3 : 1: Query Opened: SET character_set_results=NULL
mysql Information: 4 : 1: Resultset Opened: field(s) = 0, affected rows = 0, inserted id = 0
mysql Information: 5 : 1: Resultset Closed. Total rows=0, skipped rows=0, size (bytes)=0
mysql Information: 6 : 1: Query Closed
mysql Information: 10 : 1: Set Database: test
mysql Information: 3 : 1: Query Opened: SET  TRANSACTION ISOLATION LEVEL REPEATABLE READ
mysql Information: 4 : 1: Resultset Opened: field(s) = 0, affected rows = 0, inserted id = 0
mysql Information: 5 : 1: Resultset Closed. Total rows=0, skipped rows=0, size (bytes)=0
mysql Information: 6 : 1: Query Closed
mysql Information: 3 : 1: Query Opened: BEGIN
mysql Information: 4 : 1: Resultset Opened: field(s) = 0, affected rows = 0, inserted id = 0
mysql Information: 5 : 1: Resultset Closed. Total rows=0, skipped rows=0, size (bytes)=0
mysql Information: 6 : 1: Query Closed
mysql Information: 3 : 1: Query Opened: INSERT INTO t1 values(42);
SELECT SLEEP(20)
mysql Information: 4 : 1: Resultset Opened: field(s) = 0, affected rows = 1, inserted id = 0
mysql Information: 5 : 1: Resultset Closed. Total rows=0, skipped rows=0, size (bytes)=0
mysql Information: 13 : 1: Error encountered attempting to open result: Number=0, Message=Reading from the stream has failed.
mysql Warning: 31 : Error occurred aborting the connection. Exception was: Authentication to host 'localhost' for user 'sami' using method 'mysql_native_password' failed with message: Access denied for user 'sami'@'localhost' (using password: NO)
mysql Information: 6 : 1: Query Closed

MySqlException: Fatal error encountered during command execution.
	MySqlException: Fatal error encountered attempting to read the resultset.
	MySqlException: Reading from the stream has failed.
Press Enter to close the application and the Connection Pool
---

Note the "using password: NO" at the end. Looks like the connector somehow forgets the password to use.

Suggested fix:
The connection for executing "KILL QUERY" should succeed.
I suspect the fix to https://bugs.mysql.com/bug.php?id=107110 is somehow related, but could not come up with any good explanation as to how.
[9 Feb 2023 10:51] MySQL Verification Team
Hello Sami Ahlroos.

Thank you for the bug report.
Verified as described.

Regards,
Ashwini Patil
[18 Apr 2023 1:35] Matthew Stubblefield
We've been having some issues relating to entity framework while using the .net connector.
Specifically, errors that seem to be relating to transactions and likely connection pooling.
After reading through some patch notes, I had the same suspicions that Sami mentioned (that the fix for https://bugs.mysql.com/bug.php?id=107110 caused something messy with the way connections were being handled).

More specifically, I get errors like the following:
System.Data.Entity.Core.EntityException: The underlying provider failed on Rollback. ---> System.InvalidOperationException: Connection must be valid and open to rollback transaction
   at MySql.Data.MySqlClient.MySqlTransaction.Rollback()

The experience is pretty tragic too in that these bad connections seem to be holding locks that eventually crash the db server.

Needless to say we're going to roll back to 8.0.30 tomorrow to see if that improves things.
[20 Apr 2023 12:02] MySQL Verification Team
Bug #110737 marked as duplicate of this one.
[20 Apr 2023 14:00] Matthew Stubblefield
I could see it being a duplicate, but would suggest that the severity be increased. Running 8.0.31 in production crashes our apps by poisoning the connection pool with these bad open connections.
[11 Jul 2023 16:31] Matt Stubblefield
Any progress on this one? Like I said, this bug is a production system killer.
[19 Jul 2023 16:38] Trevor Pike
We have this bug, exactly as described.  It caused a catastrophic outage on our production database before we were able to figure out it was the recently upgraded .NET connector at fault.

When a query timeout happens, the .NET connector leaks the TCP connection to the database and leaves it open.  This holds the server-side session, transaction, and any locks open until the client application is closed.

Everything was fine through our testing and after we went live with the upgraded .NET connector, until the database load caused a single, transactioned query to timeout.  That left a zombie connection holding locks on tables, which then caused other connections to timeout, and this rapidly snowballed until the entire database was inaccessible.

This is much more severe than an S3.  Until this is resolved, any systems using MySql database transactions with connector 8.0.31 or above are likely susceptible to this.  Can we have this fixed, please.
[19 Jul 2023 16:49] Trevor Pike
We've been testing each of the versions and everything from 8.0.31 upward, including the new 8.1.0 connector, has the same issue.  We have to stick with 8.0.30 as the last version that works properly.
[5 Sep 2023 19:34] Matt Stubblefield
Any updates on this? We're pinned to 8.0.30 and can't move up any higher without causing production outages.

I'm worried about this with .net 8 right around the corner.
[2 Oct 2023 16:31] Trevor Pike
Is there anything new on this?  

This appears to be the same issue as in bugs https://bugs.mysql.com/bug.php?id=109390 and https://bugs.mysql.com/bug.php?id=112123

Both describe a new issue in 8.0.31 where an error within a transaction causes a connection to leak and hold the locks.  Those two bugs are rated S1 and S2 as they cause a complete lack of service in the production environments.  Please can we have the severity of this suitably upgraded and the issue resolved?
[3 Nov 2023 20:36] Matthew Stubblefield
Any updates on this? We're pinned to 8.0.30 and can't move up any higher without causing production outages.

I'm worried about this with .net 9 right around the corner.