Exception when reading TEXT type from ProxySQL

[peppy]

I have recently switched to using ProxySQL in front of my mysql database instances, and noticed that one of many of my deployed projects using MySqlConnector started to intermittently fail.

A query SELECTing a field of type text COLLATE utf8_bin NOT NULL is hitting the following exception:

code:

using (var connection = new MySqlConnection($"...")
{
    connection.Open();
    connection.QueryFirstOrDefault<string>(@"SELECT group_desc FROM phpbb_groups");
}

exception:

Unhandled exception. System.AggregateException: One or more errors occurred. (Failed to read the result set.)
 ---> MySql.Data.MySqlClient.MySqlException (0x80004005): Failed to read the result set.
 ---> System.IndexOutOfRangeException: Index was outside the bounds of the array.
   at MySqlConnector.Protocol.Serialization.ByteArrayReader.ReadLengthEncodedInteger() in /_/src/MySqlConnector/Protocol/Serialization/ByteArrayReader.cs:line 124
   at MySqlConnector.Protocol.Serialization.ByteArrayReader.ReadLengthEncodedByteString() in /_/src/MySqlConnector/Protocol/Serialization/ByteArrayReader.cs:line 149
   at MySqlConnector.Protocol.Payloads.OkPayload.Create(ReadOnlySpan`1 span, Boolean deprecateEof, Boolean clientSessionTrack) in /_/src/MySqlConnector/Protocol/Payloads/OkPayload.cs:line 45
   at MySqlConnector.Core.ResultSet.ReadResultSetHeaderAsync(IOBehavior ioBehavior)
   at MySql.Data.MySqlClient.MySqlDataReader.ActivateResultSet() in /_/src/MySqlConnector/MySql.Data.MySqlClient/MySqlDataReader.cs:line 130
   at MySql.Data.MySqlClient.MySqlDataReader.CreateAsync(CommandListPosition commandListPosition, ICommandPayloadCreator payloadCreator, IDictionary`2 cachedProcedures, IMySqlCommand command, CommandBehavior behavior, IOBehavior ioBehavior, CancellationToken cancellationToken) in /_/src/MySqlConnector/MySql.Data.MySqlClient/MySqlDataReader.cs:line 391
   at MySqlConnector.Core.CommandExecutor.ExecuteReaderAsync(IReadOnlyList`1 commands, ICommandPayloadCreator payloadCreator, CommandBehavior behavior, IOBehavior ioBehavior, CancellationToken cancellationToken) in /_/src/MySqlConnector/Core/CommandExecutor.cs:line 62
   at MySql.Data.MySqlClient.MySqlCommand.ExecuteDbDataReader(CommandBehavior behavior) in /_/src/MySqlConnector/MySql.Data.MySqlClient/MySqlCommand.cs:line 210
   at System.Data.Common.DbCommand.System.Data.IDbCommand.ExecuteReader(CommandBehavior behavior)
   at Dapper.SqlMapper.ExecuteReaderWithFlagsFallback(IDbCommand cmd, Boolean wasClosed, CommandBehavior behavior) in /_/Dapper/SqlMapper.cs:line 1051
   at Dapper.SqlMapper.QueryRowImpl[T](IDbConnection cnn, Row row, CommandDefinition& command, Type effectiveType) in /_/Dapper/SqlMapper.cs:line 1177
   at Dapper.SqlMapper.QueryFirstOrDefault[T](IDbConnection cnn, String sql, Object param, IDbTransaction transaction, Nullable`1 commandTimeout, Nullable`1 commandType) in /_/Dapper/SqlMapper.cs:line 761

To make things more interesting, this only happens when using a specific mysql database user. The user which causes the issue is also in use on a different high load application which also uses MySqlConnector (latest version in both cases).

Running the same query from a CLI mysql client does not seem to cause any unexpected issue. The other application using the same user makes use of MySqlDataAdapter and MySqlCommand, if that helps pinpoint in any way.

To reiterate, this only happens with the text type. Other queries accessing varchar or number types never hit this same issue.

I understand this is likely going to take a bit of investigating, but am posting before I have a complete grasp of the situation in case anyone is able to more easily understand what is going on. My next step will be to get MySqlConnector in a debuggable state to see what the underlying data looks like.

[bgrainger]

If you're able to make a non-SSL connection to ProxySQL (SslMode=None), grabbing a packet capture with Wireshark would probably help pinpoint the problem.

It looks like the SERVER_SESSION_STATE_CHANGED flag is set in the OK payload, but there's no session state data following it.

This code could certainly be a bit more defensive towards unexpected/malformed data, but I'd be interested in knowing more details before simply ignoring what's there (or not there, in this case).

[peppy]

I've attached a tcpdump which ends with the exception being thrown. It is running a simple SELECT query many times until crash.

cap.pcap.zip

Please let me know if you need further diagnostics or logs.

[bgrainger]

This looks like a protocol bug in ProxySQL.

In packet 268, the server sends an initial handshake and sets the CLIENT_SESSION_TRACK flag; MySqlConnector replies in packet 270 and confirms that flag.

In packet 278, ProxySQL sends an OK packet that sets 0x4000 (SERVER_SESSION_STATE_CHANGED) in the server status. This isn't typical; compare to packet 254.

According to the OK payload documentation, if CLIENT_SESSION_TRACK is enabled, we should see a string<lenenc> info field that's not present (bug 1 Edit: based on other servers, this data can be omitted if empty, although that's not explicitly called out in the documentation). Then, if SERVER_SESSION_STATE_CHANGED is set, we should see a string<lenenc> session_state_changes field that's also not present (bug 2).

MySqlConnector reads past the end of the packet, and crashes. MySqlConnector could certainly be more robust in the face of bad server data, but I would like to get this bug reported and confirmed upstream, just to confirm that I'm reading the protocol documentation correctly.

[bgrainger]

The client implementation in mysql-server protects all reads of this extra OK packet information by checking the length of the packet, despite the server flags: https://github.com/mysql/mysql-server/blob/7d10c82196c8e45554f27c00681474a9fb86d137/sql-common/client.cc#L809-L831

[peppy]

Thanks so much for investigating. Based on your edit/followup, it sounds like this could (should, if favouring compatibility) be "fixed" locally, but may be something ProxySQL should be made aware of regardless.

Let me know if you would prefer I report it to ProxySQL or if you are planning to do so yourself (your better knowledge of the protocol may put you in a better position to submit a bug report if you are willing!).

[bgrainger]

@peppy I just finished writing up a ProxySQL bug report: sysown/proxysql#2915. Please do add any supporting info there that you think might be helpful (OS info/distribution, ProxySQL version, MySQL version, etc.).

[bgrainger]

@peppy I've added a potential fix for this in 0.69.5; please test it and let me know if it works for you.

[peppy]

Can confirm it's fixed in 0.69.5, thanks again!