Fix "Aborted connection" server errors

[bgrainger]

Run the NoPassword tests: dotnet test tests\SideBySide\SideBySide.csproj -f net462 --filter=FullyQualifiedName~NoPassword

The MySQL error log will contain output similar to the following:

2017-06-28T23:57:45.172394Z 282 [Note] Aborted connection 282 to db: 'unconnected' user: 'mysqltest' host: 'localhost' (Got an error reading communication packets)
2017-06-28T23:57:45.172394Z 281 [Note] Aborted connection 281 to db: 'unconnected' user: 'mysqltest' host: 'localhost' (Got an error reading communication packets)
2017-06-28T23:57:45.172394Z 283 [Note] Aborted connection 283 to db: 'unconnected' user: 'no_password' host: 'localhost' (Got an error reading communication packets)
2017-06-28T23:57:45.172394Z 285 [Note] Aborted connection 285 to db: 'unconnected' user: 'no_password' host: 'localhost' (Got an error reading communication packets)
2017-06-28T23:57:45.172394Z 284 [Note] Aborted connection 284 to db: 'unconnected' user: 'no_password' host: 'localhost' (Got an error reading communication packets)

Run the same tests with the baseline library: dotnet restore tests\SideBySide\SideBySide.csproj /p:Configuration=Baseline && dotnet test tests\SideBySide\SideBySide.csproj -c Baseline --filter=FullyQualifiedName~NoPassword

There are no errors in the error log.

Find out why the server is logging aborted connections and fix it.

[bgrainger]

The lack of these errors in Connector/Net may be due to clearing pools at exit.

However, MySqlConnector still logs errors during the test run, not only at the end.

Connector/Net logs during a test run:

2017-06-29T02:55:49.243361Z 33 [Note] Access denied for user 'mysqltest'@'localhost' (using password: YES)
2017-06-29T02:55:51.736886Z 56 [Note] Access denied for user 'mysqltest'@'localhost' (using password: YES)
2017-06-29T02:55:55.526099Z 30 [Note] Aborted connection 30 to db: 'mysqltest' user: 'mysqltest' host: 'localhost' (Got packets out of order)
2017-06-29T02:56:01.645343Z 28 [Note] Aborted connection 28 to db: 'mysqltest' user: 'mysqltest' host: 'localhost' (Got packets out of order)
2017-06-29T02:56:04.198823Z 67 [Note] Aborted connection 67 to db: 'mysqltest' user: 'mysqltest' host: 'localhost' (Got timeout reading communication packets)

(Interestingly, two appear to be a client error: "Got packets out of order")

MySqlConnector logs during a test run:

2017-06-29T02:59:01.219218Z 204 [Note] Access denied for user 'mysqltest'@'localhost' (using password: YES)
2017-06-29T02:59:03.208949Z 219 [Note] Access denied for user 'mysqltest'@'localhost' (using password: YES)
2017-06-29T02:59:04.173457Z 232 [Note] Aborted connection 232 to db: 'mysqltest' user: 'mysqltest' host: 'localhost' (Got an error reading communication packets)
2017-06-29T02:59:06.222640Z 248 [Note] Aborted connection 248 to db: 'mysqltest' user: 'mysqltest' host: 'localhost' (Got an error reading communication packets)
2017-06-29T02:59:06.232616Z 249 [Note] Aborted connection 249 to db: 'mysqltest' user: 'mysqltest' host: 'localhost' (Got an error reading communication packets)
2017-06-29T02:59:06.243117Z 250 [Note] Aborted connection 250 to db: 'mysqltest' user: 'mysqltest' host: 'localhost' (Got an error reading communication packets)
2017-06-29T02:59:06.253117Z 251 [Note] Aborted connection 251 to db: 'mysqltest' user: 'mysqltest' host: 'localhost' (Got an error reading communication packets)
2017-06-29T02:59:06.262614Z 252 [Note] Aborted connection 252 to db: 'mysqltest' user: 'mysqltest' host: 'localhost' (Got an error reading communication packets)
2017-06-29T02:59:06.273631Z 253 [Note] Aborted connection 253 to db: 'mysqltest' user: 'mysqltest' host: 'localhost' (Got an error reading communication packets)
2017-06-29T02:59:06.283649Z 254 [Note] Aborted connection 254 to db: 'mysqltest' user: 'mysqltest' host: 'localhost' (Got an error reading communication packets)
2017-06-29T02:59:10.990601Z 255 [Note] Aborted connection 255 to db: 'mysqltest' user: 'mysqltest' host: 'localhost' (Got an error reading communication packets)
2017-06-29T02:59:15.307296Z 261 [Note] Aborted connection 261 to db: 'mysqltest' user: 'mysqltest' host: 'localhost' (Got timeout reading communication packets)

Then when the tests finish, it logs 64 more "Aborted connection ... (Got an error reading communication packets)" lines.

Although the two test suites aren't exactly the same (BASELINE skips a lot of tests), the unique mid-test errors may indicate a problem.

[bgrainger]

Note that the mid-test errors do not include the "Aborted connection 283 to db: 'unconnected' user: 'no_password' host: 'localhost'" lines (in the OP), which are probably due to connections being left open in the pool when the tests shut down.

[bgrainger]

It's possible to run code after all tests, but it's not built into xUnit; you have to implement it yourself: https://twitter.com/xunit/status/625447539907518464

[bgrainger]

The errors are coming from the ConnectionPool.LeakConnections test. When the MySqlConnection is leaked, the associated MySqlSession is GCed and then its Socket/NetworkStream's native resource is finalized, causing a TCP reset (and MySQL Server logs an error).

I wonder if I have the logic backwards: instead of a WeakReference<MySqlSession>, maybe MySqlSession should have a WeakReference<MySqlConnection> to its owning connection; if that has been GCed, the (still valid) session can be returned to the pool.

[bgrainger]

Fixed in 0.22.0.

[miracles-happen]

Hi Bradley,

It seems that fix not working, and error can be reproduced with 0.31.0 and 0.25.1 versions of MySql Connector.
In order to reproduce, I'm using simple .Net Core Console application:

class Program
    {
        public static void Main(string[] args)
        {
            CancellationTokenSource cts = new CancellationTokenSource();

            Console.CancelKeyPress += (s, e) =>
            {
                e.Cancel = true;
                cts.Cancel();
            };

            MainAsync(args).Wait(cts.Token);
            //MySqlConnection.ClearAllPools();
        }

        private static async Task MainAsync(string[] args)
        {
            var connection = new MySqlConnection(<connectionString>);
            try
            {
                await connection.OpenAsync();
                await Task.Delay(1000);
                connection.Close();
                connection.Dispose();
            }
            catch (Exception ex)
            {
                Console.WriteLine(ex.ToString());
            }

        }
    }

After running it, real My SQL connection is not closed after executing connection.Close().
This can be checked with the following MySQL command:

show processlist;

This is normal, cause opened connection returned back to the Pool. But it seems, that Connection Pool is not cleared at exit. After the program running, aborted_clients variable incremented by 1 in MySQL (can be checked with show global status like '%abort%';) and MySQL error log contains new entry:

Aborted connection 6717 to db: '...' user: '...' host: '...' (Got an error reading communication packets)

If we uncomment MySqlConnection.ClearAllPools();, then real connection is closed right after executing it and Aborted_clients variable in MySQL is not increased on program exit.

Could you please advice on this?

[bgrainger]

But it seems, that Connection Pool is not cleared at exit.

This is correct. When the process exits, all open connections are aborted. If the application wants to avoid this, it should call ClearAllPools during process shutdown.

[BhavaniShankarReddy]

I solve this issue by commenting on the values of wait_timeout, interactive_timeout, connect_timeout on my mysql.sock. My warning message is stopped after commenting this lines.
By default, wait_time and interactive_timeout will be 28800, when installing MySQL 5.7 in my production server, MySQL added this lines, after commenting this 3 lines it worked without showing a warning message:
"
[Note] Aborted connection to db: '-----' user: '----' host: 'localhost' (Got timeout reading communication packets)"

[bgrainger]

But it seems, that Connection Pool is not cleared at exit.

See #545.

[bgrainger]

The fix in #545 addresses the "aborted connection" logging (for everything except netcoreapp1.1.2) except for specific tests that deliberately abort a connection.