search

mysql-net / MySqlConnector

MySQL Connector for .NET
https://mysqlconnector.net
MIT License
1.4k stars 335 forks source link

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 3 days ago

Junghobeom commented 3 days ago

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 commented 3 days ago

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

Junghobeom commented 3 days ago

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 commented 3 days ago

4

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

bgrainger commented 2 days ago

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 commented 2 days ago

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 commented 6 hours ago

I am using Amazon RDS proxy.

I will ask aws for COM_RESET_CONNECTION

Junghobeom commented 6 hours ago

5

In the case of ConnectionPool, 5 existing (2.2.1) versions have been confirmed, but if you upload to the new version (2.4.0), I think so