Constant exceptions thrown/caught in header handling logic

[peppy]

trafficstars

I'm seeing thousands of exception thrown then caught in my production application. I do intend to debug this further myself but would appreciate any insight into whether this is expected or not.

ExceptionType	System.IO.EndOfStreamException
ExceptionMessage	Expected to read 4 header bytes but only received 0.
ExceptionEIP	0x7fc2c73c754c
ExceptionHRESULT	-2,147,024,858
ExceptionFlags	CLSCompliant

Seems to be this one:

https://github.com/mysql-net/MySqlConnector/blob/2cbc4ddcdf52cbdd9a705d8c9ff6c8be5cc335d5/src/MySqlConnector/Protocol/Serialization/ProtocolUtility.cs#L420

Look to be caught in:

MethodName instance void [MySqlConnector] MySqlConnector.Core.ServerSession+TryResetConnectionAsync>d__69::MoveNext()

This may be another ProxySQL related issue (similar to #842). Or it may just be expected behaviour when a pooled connection "goes away"?

[bgrainger]

thousands of exception ... whether this is expected or not

No, that is definitely not expected.

My guess would be that the server is closing the connection when a "reset connection" packet is sent? This would likely manifest as a performance problem since that connection will be closed, and a new one will have to be opened, the client has to log in, etc. (Besides the (comparatively) small overhead of exception handling and logging.) It will be eliminating the benefits of connection pooling.

[peppy]

Thanks for the response. Is there a way for me to surface connection pooling stats from the connector itself or would it be best I check on this using OS-level (or mysql-side) diagnostics?

[bgrainger]

Is there a way for me to surface connection pooling stats from the connector itself

There's nothing built-in. This should probably be implemented long-term with Event Counters, but no work's been started on that yet. (The closest issue is probably #471.)

You could fork the library and compile a custom version that emits statistics. Or, if you just want a way to see if/how many connections are being created, enabling logging will show that. You probably can't graph it or do anything like that, but could search the logs for created new Session.

[bgrainger]

Assuming you're using ProxySQL, does it output any diagnostic logs that might be relevant? E.g., is it logging errors coming from the client (MySqlConnector) and closing connections? Or showing anything else anomalous?

[peppy]

I can definitely see that it's resetting connections when using ProxySQL (just using tcptrack to view :3306 connections on the application server). I've switched to hitting one of my MySQL instances directly and it pools as expected. Very weird.. I can confirm other services not using this connector are successfully pooling.

Will look into this further.

[bgrainger]

Can you get more details on the exception, e.g., which line number it's being thrown from, or the full call stack?

It seems possible that the ProxySQL version isn't detected (by MySqlConnector) as supporting the COM_RESET_CONNECTION command (although I believe it does), so it could be going through a fallback code path: https://github.com/mysql-net/MySqlConnector/blob/57947630a2a9587e511dfd312f1e058ad8124d2f/src/MySqlConnector/Core/ServerSession.cs#L501

[bgrainger]

It might help to set the mysql-server_version ProxySQL variable to something newer than the default of 5.5.30, e.g., try setting it to 5.7.31 (or the actual version of MySQL Server you're using).

[peppy]

I have checked and we're already setting 8.0.20 for that variable, so that can't be it..

ProxySQLAdmin> show variables like '%version%';
+----------------------+---------------------+
| Variable_name        | Value               |
+----------------------+---------------------+
| mysql-server_version | 8.0.20              |
| admin-version        | 2.0.12-38-g58a909a0 |
+----------------------+---------------------+

One thing I have noticed which may be relevant, is this warning in proxysql logs:

2020-08-21 10:07:56 MySQL_Session.cpp:4895:handler___status_WAITING_CLIENT_DATA___STATE_SLEEP___MYSQL_COM_QUERY_qpo(): [WARNING] Unable to parse multi-statements command with SET statement: setting lock hostgroup . Command: SET sql_select_limit=1;

This is being tracked here, and seems to possibly bypass multiplexing (proxysql's terminology for connection pooling from proxy to user, as far as i can tell). I wonder if statements executing these unsupported commands are triggering connection resets. I'm going to need to setup an isolated environment to test this though, as my production one is too noisy to properly understand it.

[bgrainger]

SET sql_select_limit=1; is being sent because you're specifying `CommandBehavior.SingleRow.

You could try not specifying that flag (maybe in conjunction with adding LIMIT 1 to your queries) to see if it improves matters.

[peppy]

I figured out a solution to this: Adding ConnectionReset=false to my connection string solves the issue completely and restored pooling.

I also did remove the SingleRow behaviour (I was using ExecuteScalar and had to remove this usage):

I haven't tested if just the connection string change was enough to resolve the issue or not.

[bgrainger]

Since the exception was caught in MySqlConnector.Core.ServerSession+TryResetConnectionAsync>d__69::MoveNext(), adding ConnectionReset=false to the connection string will bypass that whole method.

The downside is that temporary tables, user variables, etc. won't be cleared, so a newly-opened connection may be polluted by those items from a previous (pooled) connection. This may not be a problem if you're not using those MySQL features.

[peppy]

I see, that explains a lot, thanks. Luckily I am not using anything which would pollute the session so this is a win-win for me. Probably not the answer to this issue though, since it really should work out-of-the-box.

As a result, I have things in a working state right now but will leave it to your discretion as to whether to close the issue. I would hope to investigate further but have very limited time currently, so not sure when that will happen.

[peppy]

One thing I have noticed is that if using Dapper with QuerySingle / QueryFirst, it's adding the CommandBehavior.SingleRow internally, which makes it very hard to disable without avoiding using dapper at all. Just documenting here in case it is useful to someone else.

[alexkozler]

I don't use ProxySQL, but I do use MySQL via RDS and track exceptions with Stackify Retrace and I get thousands of this same error. I'd be curious to try ConnectionReset=false but I know several of my frequently used queries take advantage of temp tables.

I don't think this error has actually broken any of my queries or code, rather it happens in the background. I also don't usually run into this when debugging, only in production.

Edit: ConnectionReset is False by default in the stock Connector, is it also False by default in MySqlConnector? https://dev.mysql.com/doc/dev/connector-net/8.0/html/P_MySql_Data_MySqlClient_MySqlConnectionStringBuilder_ConnectionReset.htm

[bgrainger]

ConnectionReset is False by default in the stock Connector, is it also False by default in MySqlConnector?

IIRC, it was false because there was a significant performance issue when it was set to true. (But I can't find that bug right now.)

Their default of false has led to a number of bug reports, e.g., https://bugs.mysql.com/bug.php?id=77421; IMO it's unexpected that opening a "new" connection from the pool might sometimes be "contaminated" with temp tables, user variables, and session settings from a previous connection. That's why MySqlConnector defaults to true (and implements that as efficiently as possible).