Skip to content
New issue

Have a question about this project? Sign up for a free GitHub account to open an issue and contact its maintainers and the community.

By clicking “Sign up for GitHub”, you agree to our terms of service and privacy statement. We’ll occasionally send you account related emails.

Already on GitHub? Sign in to your account

The message "Session 1.126 expected to read 4 bytes but only read 0" is being logged at the Error level every 5 minutes. #1526

Open
Junghobeom opened this issue Nov 28, 2024 · 13 comments

Comments

@Junghobeom
Copy link

Software versions
MySqlConnector version: 2.4.0
Server type (MySQL, MariaDB, Aurora, etc.) and version: Aurora, 8.0.mysql_aurora.3.04.3, rds proxy
.NET version: net6.0
(Optional) ORM NuGet packages and versions: Dapper 2.1.35

Describe the bug
A clear and concise description of what the bug is.

The message "Session 1.126 expected to read 4 bytes but only read 0" is being logged at the Error level every 5 minutes. This message does not appear in version 2.2.1.

image (7)

@bgrainger
Copy link
Member

Please enable "Trace"-level logging for MySqlConnector and upload a section of the logs that show this error.

@Junghobeom
Copy link
Author

Junghobeom commented Nov 29, 2024

3

The following message was printed out

15:52:23.0367|TRACE|MySqlConnection|Session 3.13 server version 8.0.28 supports reset connection; sending reset connection request||
15:52:23.0367|ERROR|MySqlConnection|Session 3.13 expected to read 4 bytes but only read 0||
15:52:23.0367|DEBUG|MySqlConnection|Session 3.13 setting state to Failed|An incomplete response was received from the server    at MySqlConnector.Protocol.Serialization.ProtocolUtility.ReadPayloadAsync(BufferedByteReader bufferedByteReader, IByteHandler byteHandler, Func`1 getNextSequenceNumber, ArraySegmentHolder`1 previousPayloads, ProtocolErrorBehavior protocolErrorBehavior, IOBehavior ioBehavior) in /_/src/MySqlConnector/Protocol/Serialization/ProtocolUtility.cs:line 423
   at MySqlConnector.Core.ServerSession.ReceiveReplyAsync(IOBehavior ioBehavior, CancellationToken cancellationToken) in /_/src/MySqlConnector/Core/ServerSession.cs:line 1082|MySqlConnector.MySqlEndOfStreamException: An incomplete response was received from the server
   at MySqlConnector.Protocol.Serialization.ProtocolUtility.ReadPayloadAsync(BufferedByteReader bufferedByteReader, IByteHandler byteHandler, Func`1 getNextSequenceNumber, ArraySegmentHolder`1 previousPayloads, ProtocolErrorBehavior protocolErrorBehavior, IOBehavior ioBehavior) in /_/src/MySqlConnector/Protocol/Serialization/ProtocolUtility.cs:line 423
   at MySqlConnector.Core.ServerSession.ReceiveReplyAsync(IOBehavior ioBehavior, CancellationToken cancellationToken) in /_/src/MySqlConnector/Core/ServerSession.cs:line 1082
15:52:23.0367|TRACE|MySqlConnection|Session 3.13 ignoring IOException in TryResetConnectionAsync|An incomplete response was received from the server    at MySqlConnector.Protocol.Serialization.ProtocolUtility.ReadPayloadAsync(BufferedByteReader bufferedByteReader, IByteHandler byteHandler, Func`1 getNextSequenceNumber, ArraySegmentHolder`1 previousPayloads, ProtocolErrorBehavior protocolErrorBehavior, IOBehavior ioBehavior) in /_/src/MySqlConnector/Protocol/Serialization/ProtocolUtility.cs:line 423
   at MySqlConnector.Core.ServerSession.ReceiveReplyAsync(IOBehavior ioBehavior, CancellationToken cancellationToken) in /_/src/MySqlConnector/Core/ServerSession.cs:line 1082
   at MySqlConnector.Core.ServerSession.TryResetConnectionAsync(ConnectionSettings cs, MySqlConnection connection, IOBehavior ioBehavior, CancellationToken cancellationToken) in /_/src/MySqlConnector/Core/ServerSession.cs:line 845|MySqlConnector.MySqlEndOfStreamException: An incomplete response was received from the server
   at MySqlConnector.Protocol.Serialization.ProtocolUtility.ReadPayloadAsync(BufferedByteReader bufferedByteReader, IByteHandler byteHandler, Func`1 getNextSequenceNumber, ArraySegmentHolder`1 previousPayloads, ProtocolErrorBehavior protocolErrorBehavior, IOBehavior ioBehavior) in /_/src/MySqlConnector/Protocol/Serialization/ProtocolUtility.cs:line 423
   at MySqlConnector.Core.ServerSession.ReceiveReplyAsync(IOBehavior ioBehavior, CancellationToken cancellationToken) in /_/src/MySqlConnector/Core/ServerSession.cs:line 1082
   at MySqlConnector.Core.ServerSession.TryResetConnectionAsync(ConnectionSettings cs, MySqlConnection connection, IOBehavior ioBehavior, CancellationToken cancellationToken) in /_/src/MySqlConnector/Core/ServerSession.cs:line 845
15:52:23.0367|INFO|ConnectionPool|Pool 3 session 3.13 is unusable; destroying it||
15:52:23.0367|TRACE|MySqlConnection|Session 3.13 sending QUIT command||
15:52:23.0367|DEBUG|MySqlConnection|Session 3.13 closing stream/socket||

@Junghobeom
Copy link
Author

4

The problem seems to be happening in the same location. Is it normal?

@bgrainger
Copy link
Member

This seems to be the crux of the issue:

MySqlConnection|Session 3.13 server version 8.0.28 supports reset connection; sending reset connection request||
MySqlConnection|Session 3.13 expected to read 4 bytes but only read 0||

The server advertises that it supports "reset connection", but it looks like it actually doesn't. Are you connecting directly to MySQL Server 8.0.28, or using ProxySQL or some other proxy? Looks like you might be using Amazon RDS Proxy; is that correct?

It claims to be "fully compatible with the protocols of supported database engines" but that may not actually be the case. I would recommend grabbing a Wireshark packet capture and opening a support ticket with AWS about failing to implement COM_RESET_CONNECTION properly.

@bgrainger
Copy link
Member

Secondly, the presence of "Pool 7" and "Pool 8" in your logs could be a potential red flags. It's certainly unusual to have that many distinct connection pools in one application. Why are so many separate pools being created?

@Junghobeom
Copy link
Author

I am using Amazon RDS proxy.

I will ask aws for COM_RESET_CONNECTION

@Junghobeom
Copy link
Author

Secondly, the presence of "Pool 7" and "Pool 8" in your logs could be a potential red flags. It's certainly unusual to have that many distinct connection pools in one application. Why are so many separate pools being created?

We are accessing 10 databases.

@Junghobeom
Copy link
Author

COM_RESET_CONNECTION

We are wondering when support for COM_RESET_CONNECTION began, and whether it was added after version 2.2.1. Through various tests, we have found that version 2.2.1 does not produce errors, while version 2.4.0 does.

@bgrainger
Copy link
Member

Connection resetting has been present since v0.x, but is conditional based on whether the server returns a version number that should support it (>= 5.7.3): https://github.com/mysql-net/MySqlConnector/blob/master/src/MySqlConnector/Core/ServerVersions.cs#L9

My guess is that your server/proxy recently started claiming to be MySQL 5.7 (or later) but doesn't actually support COM_RESET_CONNECTION.

@Junghobeom
Copy link
Author

Connection resetting has been present since v0.x, but is conditional based on whether the server returns a version number that should support it (>= 5.7.3): https://github.com/mysql-net/MySqlConnector/blob/master/src/MySqlConnector/Core/ServerVersions.cs#L9

My guess is that your server/proxy recently started claiming to be MySQL 5.7 (or later) but doesn't actually support COM_RESET_CONNECTION.

What is puzzling is that MySqlConnector version 2.2.1 does not produce any errors, while version 2.4.0 does. This difference occurs even though we are connecting to the same proxy. We suspect that there might be differences in protocol parsing between the versions.

@Junghobeom
Copy link
Author

This seems to be the crux of the issue:

MySqlConnection|Session 3.13 server version 8.0.28 supports reset connection; sending reset connection request||
MySqlConnection|Session 3.13 expected to read 4 bytes but only read 0||

The server advertises that it supports "reset connection", but it looks like it actually doesn't. Are you connecting directly to MySQL Server 8.0.28, or using ProxySQL or some other proxy? Looks like you might be using Amazon RDS Proxy; is that correct?

It claims to be "fully compatible with the protocols of supported database engines" but that may not actually be the case. I would recommend grabbing a Wireshark packet capture and opening a support ticket with AWS about failing to implement COM_RESET_CONNECTION properly.

I asked Amazon, and they said that they support COM_RESET_CONNECTION properly.

@bgrainger
Copy link
Member

If you can capture a Wireshark packet capture (of an unencrypted connection), that would show whether it does or not.

@Junghobeom
Copy link
Author

Wireshark

It seems difficult to use Wireshark on a server connected to an RDS proxy. Ultimately, the only option is to downgrade the version.

Sign up for free to join this conversation on GitHub. Already have an account? Sign in to comment
Labels
None yet
Development

No branches or pull requests

2 participants