Help identify root cause of "Packet received out-of-order" errors

[Feandil]

Is your feature request related to a problem? Please describe.

We are infrequently getting "Packet received out-of-order" errors, all of which seem to be coming from the same code path, but we haven't been able to identify what is causing it. From https://github.com/mysql-net/MySqlConnector/issues/496#issuecomment-391583852, I understand that it could be due to multiple in-flight async requests, but we can't identify were the error is coming from.

Describe the solution you'd like

As suggested in the comment mentioned above, a meaningful error in case of multiple in-flight async requests, or at least detailed information about the two requests that ended up being simultaneous when the error is triggered.

Describe alternatives you've considered

• Capturing network traces of the offending connection: impossible due to the irregularity of the error and the size of such capture given the activity
• Code review to identify the error: inconclusive for now
• Updating libraries/frameworks: pending

Additional context

We are using:

• Application:
  • MySqlConnector 2.1.13 (didn't find relevant change in the releases since)
  • Pomelo.EntityFrameworkCore.MySql 6.0.1
  • Microsoft.EntityFrameworkCore 6.0.1
• Server:
  • ProxySQL 2.3.2
  • MySQL Community Server 8.0.28

Here is a trace of the error we are seeing:

MySqlConnector.MySqlProtocolException: Packet received out-of-order. Expected 37; got 49.
   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 494
   at MySqlConnector.Core.ServerSession.ReceiveReplyAsyncAwaited(ValueTask`1 task) in /_/src/MySqlConnector/Core/ServerSession.cs:line 960
   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.Core.ResultSet.ReadEntireAsync(IOBehavior ioBehavior, CancellationToken cancellationToken) in /_/src/MySqlConnector/Core/ResultSet.cs:line 186
   at MySqlConnector.MySqlDataReader.NextResultAsync(IOBehavior ioBehavior, CancellationToken cancellationToken) in /_/src/MySqlConnector/MySqlDataReader.cs:line 61
   at MySqlConnector.MySqlDataReader.DisposeAsync(IOBehavior ioBehavior, CancellationToken cancellationToken) in /_/src/MySqlConnector/MySqlDataReader.cs:line 613
   at MySqlConnector.MySqlDataReader.Dispose(Boolean disposing) in /_/src/MySqlConnector/MySqlDataReader.cs:line 447
   at Microsoft.EntityFrameworkCore.Query.Internal.BufferedDataReader.Initialize(IReadOnlyList`1 columns)
   at Microsoft.EntityFrameworkCore.Storage.RelationalCommand.ExecuteReader(RelationalCommandParameterObject parameterObject)
   at Microsoft.EntityFrameworkCore.Query.Internal.SingleQueryingEnumerable`1.Enumerator.InitializeReader(Enumerator enumerator)
   at Microsoft.EntityFrameworkCore.Storage.ExecutionStrategy.<>c__DisplayClass31_0`2.<Execute>b__0(DbContext context, TState state)
   at Microsoft.EntityFrameworkCore.Storage.ExecutionStrategy.ExecuteImplementation[TState,TResult](Func`3 operation, Func`3 verifySucceeded, TState state)
   at Microsoft.EntityFrameworkCore.Storage.ExecutionStrategy.Execute[TState,TResult](TState state, Func`3 operation, Func`3 verifySucceeded)
   at Microsoft.EntityFrameworkCore.Query.Internal.SingleQueryingEnumerable`1.Enumerator.MoveNext()

The errors are then followed by "Can't replace active reader." errors, as I understand the exception is leaving the connection in a bad state.

[bgrainger]

Server:

• ProxySQL 2.3.2

Would it be possible to run your application connecting directly to MySQL Server, bypassing ProxySQL, for a sufficiently long period of time that you would normally expect to see this error?

There have been ProxySQL bugs reported before (e.g., https://github.com/mysql-net/MySqlConnector/issues/842#issuecomment-652234390) so it could be useful to rule that out as a variable. If the problem happens when connecting MySqlConnector directly to MySQL Server, then it definitely increases the likelihood that the error could be in the client code.

[Feandil]

Thanks for the recommendation and sorry for the long delay in answering... It took us time to deploy Sentry to monitor the situation better and then try without ProxySQL. Disabling ProxySQL for almost a week now seems to indicate the we have no error, which would indicate that it is indeed the root cause of our issues...

Do you think we could extend MySqlConnector to collect more information about the out-of-order errors? Is there any chance getting the exact last command that was run before the crash in that connection? Or getting any detail from the packets received out of order?

Has anyone ever integrated MySqlConnector with Sentry? e.g. adding breadcrumbs to better understand what had happened before a crash?

[bgrainger]

Enabling MySqlConnector logging (at Debug or Trace) level might produce some helpful information about what is happening on each physical connection before the failure.

If Sentry can consume .NET Activity objects from an ActivitySource, then you should be able to get good tracing from the functionality built into MySqlConnector (https://github.com/mysql-net/MySqlConnector/issues/1036).

There are also packages out there that can convert ActivitySource to OpenTelemetry (or other export formats) if Sentry needs that, but I don't have a link to documentation at hand.

[Feandil]

Sorry again for the very long delay in answering. I've logged into these options:

• For the logs, I can very easily enable it via MySqlConnectorLogManager.Provider = new MicrosoftExtensionsLoggingLoggerProvider, however this doesn't go into the Sentry events. I believe this is because the logger that MySqlConnector receives is not the one scoped to the request that triggers the error. We are using Pomelo.EntityFrameworkCore.MySql, not directly MySqlConnector, so we can't integrate more closely that the global logger I believe. :/
• For Activity, it's also possible to enable OpenTelemetry, have it consume Activity from MySqlConnector and passed to Sentry. However, Sentry only then uses it for tracing, not for exceptions, so I can't have it in the events. :/

Thanks again for your help.