2.1.2: `Expected to read 7907 payload bytes but only received 636`.

[danielgindi]

Software versions MySqlConnector version: 2.1.2 Server type (MySQL, MariaDB, Aurora, etc.) and version: MySql 8.0.24 .NET version: .NET 5.0

Describe the bug An hour after upgrading from 2.1.0 to 2.1.2, we got flooded with these logs: Expected to read 7907 payload bytes but only received 636.

Exception

at MySqlConnector.Protocol.Serialization.ProtocolUtility.<DoReadPayloadAsync>g__AddContinuation|5_0(ValueTask`1 readPacketTask, BufferedByteReader bufferedByteReader, IByteHandler byteHandler, Func`1 getNextSequenceNumber, ArraySegmentHolder`1 previousPayloads, ProtocolErrorBehavior protocolErrorBehavior, IOBehavior ioBehavior) in /_/src/MySqlConnector/Protocol/Serialization/ProtocolUtility.cs:line 480
   at MySqlConnector.Core.ServerSession.ReceiveReplyAsyncAwaited(ValueTask`1 task) in /_/src/MySqlConnector/Core/ServerSession.cs:line 956
   at MySqlConnector.Core.ResultSet.<ScanRowAsync>g__ScanRowAsyncAwaited|9_0(ResultSet resultSet, Task`1 payloadTask, Row row, CancellationToken token) in /_/src/MySqlConnector/Core/ResultSet.cs:line 252
   at MySqlConnector.Core.ResultSet.ReadAsync(IOBehavior ioBehavior, CancellationToken cancellationToken) in /_/src/MySqlConnector/Core/ResultSet.cs:line 211
   at MySqlConnector.MySqlDataReader.ReadAsync(CancellationToken cancellationToken) in /_/src/MySqlConnector/MySqlDataReader.cs:line 36
   at eyedo.api.agent.EntityHandler.<>c.<<-cctor>b__6_2>d.MoveNext() in C:\Users\Daniel\Desktop\git\eyedo-server\agent-api\Handlers\Entities\EntityHandler_Get.cs:line 621
--- End of stack trace from previous location ---

Code sample I don't have yet a reproduction code or a sample, as I don't event know what query triggers it. The stack trace is cut for some reason at the point of application code. Working on it.

Additional context In the meanwhile, we're reverting to 2.1.0.

[bgrainger]

That's quite unexpected, since the changes from 2.1.0 to 2.1.2 are pretty small.

Do you happen to be using prepared commands (i.e., MySqlCommand.Prepare)? There was a change in 2.1.2 to treat MySQL Server 8.0.24 slightly differently, so it would be interesting to see if 2.1.1 works. (OTOH, it doesn't seem like this would be the problem since prepared statements wouldn't have worked correctly in 2.1.0 according to https://github.com/mysql-net/MySqlConnector/issues/1106.)

[danielgindi]

Not using any prepared commands :)

[danielgindi]

Does not happen since downgrading... weird

[bgrainger]

To clarify: are you saying that you switched back to 2.1.2 and the exception is no longer happening?

[danielgindi]

Nope, I am saying that on 2.1.0 it does not happen... on 2.1.2 it happens. I think that it happens on large columns that are the result of a GROUP_CONCAT

[bradyoo]

I'm hearing similar reports as well when we upgraded from 2.1.0 -> 2.1.5 though this is on Aurora Mysql Database.

System.IO.EndOfStreamException: Expected to read 358 payload bytes but only received 124.
   at MySqlConnector.Protocol.Serialization.ProtocolUtility.<DoReadPayloadAsync>g__AddContinuation|5_0(ValueTask`1 readPacketTask, BufferedByteReader bufferedByteReader, IByteHandler byteHandler, Func`1 getNextSequenceNumber, ArraySegmentHolder`1 previousPayloads, ProtocolErrorBehavior protocolErrorBehavior, IOBehavior ioBehavior) in /_/src/MySqlConnector/Protocol/Serialization/ProtocolUtility.cs:line 476
   at MySqlConnector.Core.ServerSession.ReceiveReplyAsyncAwaited(ValueTask`1 task) in /_/src/MySqlConnector/Core/ServerSession.cs:line 943
   at MySqlConnector.Core.ResultSet.<ScanRowAsync>g__ScanRowAsyncAwaited|9_0(ResultSet resultSet, Task`1 payloadTask, Row row, CancellationToken token) in /_/src/MySqlConnector/Core/ResultSet.cs:line 244
   at MySqlConnector.Core.ResultSet.ReadAsync(IOBehavior ioBehavior, CancellationToken cancellationToken) in /_/src/MySqlConnector/Core/ResultSet.cs:line 215
   at MySqlConnector.MySqlDataReader.Read() in /_/src/MySqlConnector/MySqlDataReader.cs:line 27
(below this trace is our code)

[bgrainger]

Are you able to construct a consistent repro that demonstrates the problem, or does it seem to happen "randomly"?

[bradyoo]

The software is part of a deployed software that is part of an environment that I have no control over so I can't actually describe how it happens. :(

[danielgindi]

I have new information: It seems like this happens at least with timed out queries, when iterating over an async Reader.

[bgrainger]

I'm not sure how to proceed with diagnosing this unless someone is able to provide:

• a self-contained repro, or
• a packet capture of unencrypted network traffic (i.e., SslMode = None) from when the problem happens

[danielgindi]

I'm not sure how to proceed with diagnosing this unless someone is able to provide:

• a self-contained repro, or

• a packet capture of unencrypted network traffic (i.e., SslMode = None) from when the problem happens

I don't think it's something that we can stabely reproduce. It looks like a race condition while timing out. I'll look at the code, it is probably an issue that we can see in the source.

[danielgindi]

Here: https://github.com/mysql-net/MySqlConnector/blob/000f586ce78e7c858b697d6e3b94cfcc68ac3162/src/MySqlConnector/Protocol/Serialization/ProtocolUtility.cs#L434 We need to somehow test for an aborted/disconnected connection. Otherwise it goes on to throw that error.

[danielgindi]

@bgrainger what say you?

[bgrainger]

Are you essentially proposing that (in this scenario) the library throw a MySqlException (with appropriate ErrorCode) instead of an EndOfStreamException?

[danielgindi]

Are you essentially proposing that (in this scenario) the library throw a MySqlException (with appropriate ErrorCode) instead of an EndOfStreamException?

It would be best if we can determine the stream end reason. Then if it's timeout, we could throw a timeout exception like we do anyway when we are not in the middle of a read/write operation. And if it's a simple cancellation, we could rethrow an OperationCanecelledException

[tsaiggo]

Same issue in the v2.1.6

[tsaiggo]

Are you essentially proposing that (in this scenario) the library throw a (with appropriate ) instead of an ?MySqlException``ErrorCode``EndOfStreamException

It would be best if we can determine the stream end reason. Then if it's timeout, we could throw a timeout exception like we do anyway when we are not in the middle of a read/write operation. And if it's a simple cancellation, we could rethrow an OperationCanecelledException

Hey @danielgindi , may I ask if you already know the root cause of this issue?

[tsaiggo]

@danielgindi @bradyoo Maybe you can set Pooling=false, I found this property has been set as true by default

[danielgindi]

Are you essentially proposing that (in this scenario) the library throw a (with appropriate ) instead of an ? MySqlExceptionErrorCodeEndOfStreamException

It would be best if we can determine the stream end reason. Then if it's timeout, we could throw a timeout exception like we do anyway when we are not in the middle of a read/write operation. And if it's a simple cancellation, we could rethrow an OperationCanecelledException

Hey @danielgindi , may I ask if you already know the root cause of this issue?

Yeah, it looks like cancellation tokens in action! The current connector code does not handle that well...