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

Connection pooling broken since 0.40.0 release #486

Closed
Bio2hazard opened this issue Apr 19, 2018 · 3 comments
Closed

Connection pooling broken since 0.40.0 release #486

Bio2hazard opened this issue Apr 19, 2018 · 3 comments
Assignees
Labels

Comments

@Bio2hazard
Copy link

Bio2hazard commented Apr 19, 2018

After updating to 0.40.0 my application stopped working entirely. It freezes when trying to reset the connection retrieved from the pool.

I am connecting to a AuroraDb instance.
Turning off connection pooling or turning off connection reset in the connection string both fixes the issue ( but is of course not desirable ).

Platform: Windows 10 x64
Runtime: Issue is present in both .net 4.6.2 and .net core 2.0.x

The minimal code to reproduce the issue:

MySqlConnector.Logging.MySqlConnectorLogManager.Provider = new MySqlConnector.Logging.ConsoleLoggerProvider(MySqlConnector.Logging.MySqlConnectorLogLevel.Trace);
var connection = new MySqlConnection(...);
connection.State.Dump();
connection.Open();
connection.State.Dump();
connection.Close();
connection.State.Dump();
connection.Open();
connection.State.Dump();
connection.Close();
connection.State.Dump();

Output for 0.40.1:

Closed
[INFO]  ConnectionPool  Pool1 creating new connection pool for ConnectionString: ...
[DEBUG]  ConnectionPool  Pool1 reaping connection pool
[DEBUG]  ConnectionPool  Pool1 recovered no sessions
[DEBUG]  ConnectionPool  Pool1 waiting for an available session
[DEBUG]  ServerSession  Session1.1 created new session
[INFO]  ConnectionPool  Pool1 no pooled session available; created new Session1.1
[INFO]  ServerSession  Session1.1 connecting to IpAddress ...
[DEBUG]  ServerSession  Session1.1 connected to IpAddress ... with local Port 65499
[DEBUG]  ServerSession  Session1.1 server sent AuthPluginName=mysql_native_password
[INFO]  ServerSession  Session1.1 made connection; ServerVersion=5.7.12; ConnectionId=101532; Compression=False; Attributes=True; DeprecateEof=True; Ssl=True
[INFO]  ServerSession  Session1.1 initializing TLS connection
[INFO]  ServerSession  Session1.1 connected TLS with Protocol Tls12
[DEBUG]  ServerSession  Session1.1 creating connection attributes
[DEBUG]  ConnectionPool  Pool1 returning new Session1.1 to caller; LeasedSessionsCount=1

Open
[DEBUG]  ServerSession  Session1.1 returning to Pool1
[DEBUG]  ConnectionPool  Pool1 receiving Session1.1 back

Closed
[DEBUG]  ConnectionPool  Pool1 waiting for an available session
[DEBUG]  ConnectionPool  Pool1 found an existing session; checking it for validity
[DEBUG]  ServerSession  Session1.1 ServerVersion=5.7.12 supports reset connection; sending reset connection request

< At this point it sits forever and outputs the following messages every minute >
[DEBUG]  ConnectionPool  Pool1 reaping connection pool
[DEBUG]  ConnectionPool  Pool1 recovered no sessions

Output for 0.39.0:

Closed
[INFO]  ConnectionPool  Pool1 creating new connection pool for ConnectionString: ...
[DEBUG]  ConnectionPool  Pool1 reaping connection pool
[DEBUG]  ConnectionPool  Pool1 recovered no sessions
[DEBUG]  ConnectionPool  Pool1 waiting for an available session
[DEBUG]  ServerSession  Session1.1 created new session
[INFO]  ConnectionPool  Pool1 no pooled session available; created new Session1.1
[INFO]  ServerSession  Session1.1 connecting to IpAddress ...
[DEBUG]  ServerSession  Session1.1 connected to IpAddress ... with local Port 65469
[DEBUG]  ServerSession  Session1.1 server sent AuthPluginName=mysql_native_password
[INFO]  ServerSession  Session1.1 made connection; ServerVersion=5.7.12; ConnectionId=101523; Compression=False; Attributes=True; DeprecateEof=True; Ssl=True
[INFO]  ServerSession  Session1.1 initializing TLS connection
[INFO]  ServerSession  Session1.1 connected TLS with Protocol Tls12
[DEBUG]  ServerSession  Session1.1 creating connection attributes
[DEBUG]  ConnectionPool  Pool1 returning new Session1.1 to caller; LeasedSessionsCount=1

Open
[DEBUG]  ServerSession  Session1.1 returning to Pool1
[DEBUG]  ConnectionPool  Pool1 receiving Session1.1 back

Closed
[DEBUG]  ConnectionPool  Pool1 waiting for an available session
[DEBUG]  ConnectionPool  Pool1 found an existing session; checking it for validity
[DEBUG]  ServerSession  Session1.1 ServerVersion=5.7.12 supports reset connection; sending reset connection request
[DEBUG]  ConnectionPool  Pool1 returning pooled Session1.1 to caller; LeasedSessionsCount=1

Open
[DEBUG]  ServerSession  Session1.1 returning to Pool1
[DEBUG]  ConnectionPool  Pool1 receiving Session1.1 back

Closed
@bgrainger
Copy link
Member

bgrainger commented Apr 19, 2018

I'm guessing that the optimisation added in #483 is not compatible with Aurora (which unfortunately isn't included in our integration tests).

@bgrainger bgrainger self-assigned this Apr 19, 2018
@bgrainger bgrainger added the bug label Apr 19, 2018
@bgrainger
Copy link
Member

bgrainger commented Apr 19, 2018

Fixed in 0.40.2.

@vaintroub
Copy link
Contributor

vaintroub commented Apr 30, 2018

If someone knows how to file Aurora bugs, this would be a good one to file. Looks like they are pre-read more than a single query from network, but discard everything after the first query. MariaDB JDBC driver, which makes use of pipelining technique during connection and in batches, even documents not compatible with Aurora whenever batches are involved https://mariadb.com/kb/en/library/about-mariadb-connector-j/

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

No branches or pull requests

3 participants