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.

Sign up for GitHub

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

Jump to bottom

App remains persistently with already closed connection while regular conn validation succeeds #139

Open
schwaiger opened this issue Oct 21, 2019 · 1 comment
Open

App remains persistently with already closed connection while regular conn validation succeeds #139

schwaiger opened this issue Oct 21, 2019 · 1 comment

Comments

@schwaiger
Copy link

We have a special setup, we use a pool size of 1, as we have 100 JVM instances writing to one single MariaDB with each only a single thread processing the queue of DB updates for all tables.

When the DB is shortly down due to a failover, most instances happily resume actions once db is back but a few (last time 4 out of 104) remain indefinitely in a state where the app gets returned an invalid connection and the validation checks every 2 min (visible in debug log mode) succeed. The jmx interface actually shows then 2 connections for this pool, also the logs contain i.e. "total size: 28; checked out: 1; num connections: 2;".

adding unreturnedConnectionTimeout didn't change the game (looks to me as if it doesn't kick in). a window for recovery seems to exist only when the db is down while validation is scheduled. last time db was taken down twice. at first invalidation of the connection (destroy connection) the problem continued. at second time (exact the same log entries as far as I could see) the stale connection was gone and the app got the good one again.

<dependency>
	<groupId>org.hibernate</groupId>
	<artifactId>hibernate-core</artifactId>
	<version>5.3.9.Final</version>
</dependency>
<dependency>
	<groupId>org.hibernate</groupId>
	<artifactId>hibernate-c3p0</artifactId>
	<version>5.3.9.Final</version>
</dependency>
<dependency>
	<groupId>mysql</groupId>
	<artifactId>mysql-connector-java</artifactId>
	<version>5.1.40</version>
</dependency>

<!-- Use the C3P0 connection pool provider -->
<property name="hibernate.c3p0.min_size"> 1 </property>
<property name="hibernate.c3p0.max_size"> 1 </property>
<property name="hibernate.c3p0.timeout"> 1800 </property>
<property name="hibernate.c3p0.max_statements"> 50 </property>	
<property name="hibernate.c3p0.automatictestTable"> c3p0-test </property>
<!-- Properties to handle connection problems (timeout after 30s, retry with next request) -->
<property name="hibernate.c3p0.acquireRetryAttempts"> 2 </property>
<property name="hibernate.c3p0.acquireRetryDelay"> 30000 </property>
<property name="hibernate.c3p0.idleConnectionTestPeriod"> 120 </property>

<!-- Oct 2019 - reduce threads, see if options fix stale unusable c3p0 connections 
               we see them from time to time on winsys or ard instances (lower process prio) after venus was gone for a moment 
               forcibly return check out connections after 4 minutes and log a stack trace -->
<property name="hibernate.c3p0.numHelperThreads"> 2 </property>
<property name="hibernate.c3p0.unreturnedConnectionTimeout"> 240 </property>  
<property name="hibernate.c3p0.debugUnreturnedConnectionStackTraces"> true </property>

symptom to the app:

17 Oct 2019 09:28:47,826  WARN [VenusInformer] (Slf4jMLog.java:220) - [c3p0] A PooledConnection that has already signalled a Connection error is still in use!
17 Oct 2019 09:28:47,827  WARN [VenusInformer] (Slf4jMLog.java:223) - [c3p0] Another error has occurred [ com.mysql.jdbc.exceptions.jdbc4.MySQLNonTransientConnectionException: No operations allowed after connection closed. ] which will not be reported to listeners!
com.mysql.jdbc.exceptions.jdbc4.MySQLNonTransientConnectionException: No operations allowed after connection closed.
	at sun.reflect.NativeConstructorAccessorImpl.newInstance0(Native Method)
	at sun.reflect.NativeConstructorAccessorImpl.newInstance(NativeConstructorAccessorImpl.java:62)
	at sun.reflect.DelegatingConstructorAccessorImpl.newInstance(DelegatingConstructorAccessorImpl.java:45)
	at java.lang.reflect.Constructor.newInstance(Constructor.java:423)
	at com.mysql.jdbc.Util.handleNewInstance(Util.java:425)
	at com.mysql.jdbc.Util.getInstance(Util.java:408)
	at com.mysql.jdbc.SQLError.createSQLException(SQLError.java:918)
	at com.mysql.jdbc.SQLError.createSQLException(SQLError.java:897)
	at com.mysql.jdbc.SQLError.createSQLException(SQLError.java:886)
	at com.mysql.jdbc.SQLError.createSQLException(SQLError.java:860)
	at com.mysql.jdbc.ConnectionImpl.throwConnectionClosedException(ConnectionImpl.java:1246)
	at com.mysql.jdbc.ConnectionImpl.checkClosed(ConnectionImpl.java:1241)
	at com.mysql.jdbc.ConnectionImpl.setAutoCommit(ConnectionImpl.java:4801)
	at com.mchange.v2.c3p0.impl.NewProxyConnection.setAutoCommit(NewProxyConnection.java:1059)
	at org.hibernate.resource.jdbc.internal.AbstractLogicalConnectionImplementor.begin(AbstractLogicalConnectionImplementor.java:67)
	at org.hibernate.resource.jdbc.internal.LogicalConnectionManagedImpl.begin(LogicalConnectionManagedImpl.java:263)
	at org.hibernate.resource.transaction.backend.jdbc.internal.JdbcResourceLocalTransactionCoordinatorImpl$TransactionDriverControlImpl.begin(JdbcResourceLocalTransactionCoordinatorImpl.java:236)
	at org.hibernate.engine.transaction.internal.TransactionImpl.begin(TransactionImpl.java:86)
	at org.hibernate.internal.AbstractSharedSessionContract.beginTransaction(AbstractSharedSessionContract.java:462)
	at sun.reflect.GeneratedMethodAccessor36.invoke(Unknown Source)
	at sun.reflect.DelegatingMethodAccessorImpl.invoke(DelegatingMethodAccessorImpl.java:43)
	at java.lang.reflect.Method.invoke(Method.java:498)
	at org.hibernate.context.internal.ThreadLocalSessionContext$TransactionProtectionWrapper.invoke(ThreadLocalSessionContext.java:350)
	at com.sun.proxy.$Proxy45.beginTransaction(Unknown Source)
	at inform.db.venus.AMRServerInfoDAO.updateAMRServerInfo(AMRServerInfoDAO.java:37)
	at inform.VenusInformer.dequeueMessage(VenusInformer.java:260)
	at inform.AbstractInformer.processQueue(AbstractInformer.java:245)
	at inform.AbstractInformer.processQueue(AbstractInformer.java:215)
	at inform.VenusInformer.run(VenusInformer.java:136)
	at java.lang.Thread.run(Thread.java:748)
Caused by: com.mysql.jdbc.exceptions.jdbc4.CommunicationsException: Communications link failure

The last packet successfully received from the server was 0 milliseconds ago.  The last packet sent successfully to the server was 0 milliseconds ago.
	at sun.reflect.NativeConstructorAccessorImpl.newInstance0(Native Method)
	at sun.reflect.NativeConstructorAccessorImpl.newInstance(NativeConstructorAccessorImpl.java:62)
	at sun.reflect.DelegatingConstructorAccessorImpl.newInstance(DelegatingConstructorAccessorImpl.java:45)
	at java.lang.reflect.Constructor.newInstance(Constructor.java:423)
	at com.mysql.jdbc.Util.handleNewInstance(Util.java:425)
	at com.mysql.jdbc.SQLError.createCommunicationsException(SQLError.java:989)
	at com.mysql.jdbc.MysqlIO.reuseAndReadPacket(MysqlIO.java:3556)
	at com.mysql.jdbc.MysqlIO.reuseAndReadPacket(MysqlIO.java:3456)
	at com.mysql.jdbc.MysqlIO.checkErrorPacket(MysqlIO.java:3897)
	at com.mysql.jdbc.MysqlIO.sendCommand(MysqlIO.java:2524)
	at com.mysql.jdbc.MysqlIO.sqlQueryDirect(MysqlIO.java:2677)
	at com.mysql.jdbc.ConnectionImpl.execSQL(ConnectionImpl.java:2545)
	at com.mysql.jdbc.ConnectionImpl.setAutoCommit(ConnectionImpl.java:4842)
	... 17 more
Caused by: java.io.EOFException: Can not read response from server. Expected to read 4 bytes, read 0 bytes before connection was unexpectedly lost.
	at com.mysql.jdbc.MysqlIO.readFully(MysqlIO.java:3008)
	at com.mysql.jdbc.MysqlIO.reuseAndReadPacket(MysqlIO.java:3466)
	... 23 more

last impact to App logged:
17 Oct 2019 09:51:47,570 ERROR [VenusInformer] (MonitorDAO.java:53) - failed to update monitor in DB: org.hibernate.TransactionException: JDBC begin transaction failed:

DB log
(2 times failover: ~40s downtime each)

2019-10-17 09:29:16 606564 [Note] Forcefully disconnecting 92 remaining clients
2019-10-17 09:29:58 103820 [Note] H:\MySQL Server 5.6\bin\mysqld.exe: ready for connections.
2019-10-17 09:42:24 103820 [Note] Forcefully disconnecting 47 remaining clients
2019-10-17 09:42:57 9716 [Note] H:\MySQL Server 5.6\bin\mysqld.exe: ready for connections.

validation results of the respective pool (1st downtime not noticed, trigger of last destruction unclear, but from then on app could write again)

17 Oct 2019 09:28:53,264 DEBUG [C3P0PooledConnectionPoolManager[identityToken->1br1htba51mtqkct100p2y5|368267e9]-HelperThread-#1] (Slf4jMLog.java:204) - Testing PooledConnection [com.mchange.v2.c3p0.impl.NewPooledConnection@402eda0f] on IDLE CHECK.
17 Oct 2019 09:28:53,264 DEBUG [C3P0PooledConnectionPoolManager[identityToken->1br1htba51mtqkct100p2y5|368267e9]-HelperThread-#1] (Slf4jMLog.java:204) - Test of PooledConnection [com.mchange.v2.c3p0.impl.NewPooledConnection@402eda0f] on IDLE CHECK has SUCCEEDED.
17 Oct 2019 09:30:53,273 DEBUG [C3P0PooledConnectionPoolManager[identityToken->1br1htba51mtqkct100p2y5|368267e9]-HelperThread-#0] (Slf4jMLog.java:204) - Testing PooledConnection [com.mchange.v2.c3p0.impl.NewPooledConnection@46cb36a1] on IDLE CHECK.
17 Oct 2019 09:30:53,273 DEBUG [C3P0PooledConnectionPoolManager[identityToken->1br1htba51mtqkct100p2y5|368267e9]-HelperThread-#0] (Slf4jMLog.java:204) - Test of PooledConnection [com.mchange.v2.c3p0.impl.NewPooledConnection@46cb36a1] on IDLE CHECK has SUCCEEDED.
17 Oct 2019 09:32:53,279 DEBUG [C3P0PooledConnectionPoolManager[identityToken->1br1htba51mtqkct100p2y5|368267e9]-HelperThread-#0] (Slf4jMLog.java:204) - Testing PooledConnection [com.mchange.v2.c3p0.impl.NewPooledConnection@46cb36a1] on IDLE CHECK.
17 Oct 2019 09:32:53,279 DEBUG [C3P0PooledConnectionPoolManager[identityToken->1br1htba51mtqkct100p2y5|368267e9]-HelperThread-#0] (Slf4jMLog.java:204) - Test of PooledConnection [com.mchange.v2.c3p0.impl.NewPooledConnection@46cb36a1] on IDLE CHECK has SUCCEEDED.
17 Oct 2019 09:34:53,294 DEBUG [C3P0PooledConnectionPoolManager[identityToken->1br1htba51mtqkct100p2y5|368267e9]-HelperThread-#1] (Slf4jMLog.java:204) - Testing PooledConnection [com.mchange.v2.c3p0.impl.NewPooledConnection@46cb36a1] on IDLE CHECK.
17 Oct 2019 09:34:53,294 DEBUG [C3P0PooledConnectionPoolManager[identityToken->1br1htba51mtqkct100p2y5|368267e9]-HelperThread-#1] (Slf4jMLog.java:204) - Test of PooledConnection [com.mchange.v2.c3p0.impl.NewPooledConnection@46cb36a1] on IDLE CHECK has SUCCEEDED.
17 Oct 2019 09:36:53,307 DEBUG [C3P0PooledConnectionPoolManager[identityToken->1br1htba51mtqkct100p2y5|368267e9]-HelperThread-#0] (Slf4jMLog.java:204) - Testing PooledConnection [com.mchange.v2.c3p0.impl.NewPooledConnection@46cb36a1] on IDLE CHECK.
17 Oct 2019 09:36:53,307 DEBUG [C3P0PooledConnectionPoolManager[identityToken->1br1htba51mtqkct100p2y5|368267e9]-HelperThread-#0] (Slf4jMLog.java:204) - Test of PooledConnection [com.mchange.v2.c3p0.impl.NewPooledConnection@46cb36a1] on IDLE CHECK has SUCCEEDED.
17 Oct 2019 09:38:53,315 DEBUG [C3P0PooledConnectionPoolManager[identityToken->1br1htba51mtqkct100p2y5|368267e9]-HelperThread-#1] (Slf4jMLog.java:204) - Testing PooledConnection [com.mchange.v2.c3p0.impl.NewPooledConnection@46cb36a1] on IDLE CHECK.
17 Oct 2019 09:38:53,315 DEBUG [C3P0PooledConnectionPoolManager[identityToken->1br1htba51mtqkct100p2y5|368267e9]-HelperThread-#1] (Slf4jMLog.java:204) - Test of PooledConnection [com.mchange.v2.c3p0.impl.NewPooledConnection@46cb36a1] on IDLE CHECK has SUCCEEDED.
17 Oct 2019 09:40:53,322 DEBUG [C3P0PooledConnectionPoolManager[identityToken->1br1htba51mtqkct100p2y5|368267e9]-HelperThread-#1] (Slf4jMLog.java:204) - Testing PooledConnection [com.mchange.v2.c3p0.impl.NewPooledConnection@46cb36a1] on IDLE CHECK.
17 Oct 2019 09:40:53,322 DEBUG [C3P0PooledConnectionPoolManager[identityToken->1br1htba51mtqkct100p2y5|368267e9]-HelperThread-#1] (Slf4jMLog.java:204) - Test of PooledConnection [com.mchange.v2.c3p0.impl.NewPooledConnection@46cb36a1] on IDLE CHECK has SUCCEEDED.
17 Oct 2019 09:42:53,328 DEBUG [C3P0PooledConnectionPoolManager[identityToken->1br1htba51mtqkct100p2y5|368267e9]-HelperThread-#0] (Slf4jMLog.java:204) - Testing PooledConnection [com.mchange.v2.c3p0.impl.NewPooledConnection@46cb36a1] on IDLE CHECK.
17 Oct 2019 09:42:53,328 DEBUG [C3P0PooledConnectionPoolManager[identityToken->1br1htba51mtqkct100p2y5|368267e9]-HelperThread-#0] (Slf4jMLog.java:207) - Test of PooledConnection [com.mchange.v2.c3p0.impl.NewPooledConnection@46cb36a1] on IDLE CHECK has FAILED.
17 Oct 2019 09:42:53,328 DEBUG [C3P0PooledConnectionPoolManager[identityToken->1br1htba51mtqkct100p2y5|368267e9]-HelperThread-#1] (Slf4jMLog.java:204) - Preparing to destroy PooledConnection: com.mchange.v2.c3p0.impl.NewPooledConnection@46cb36a1
17 Oct 2019 09:42:53,328 DEBUG [C3P0PooledConnectionPoolManager[identityToken->1br1htba51mtqkct100p2y5|368267e9]-HelperThread-#1] (Slf4jMLog.java:204) - Successfully destroyed PooledConnection: com.mchange.v2.c3p0.impl.NewPooledConnection@46cb36a1
17 Oct 2019 09:44:53,337 DEBUG [C3P0PooledConnectionPoolManager[identityToken->1br1htba51mtqkct100p2y5|368267e9]-HelperThread-#1] (Slf4jMLog.java:204) - Testing PooledConnection [com.mchange.v2.c3p0.impl.NewPooledConnection@3139c3e] on IDLE CHECK.
17 Oct 2019 09:44:53,337 DEBUG [C3P0PooledConnectionPoolManager[identityToken->1br1htba51mtqkct100p2y5|368267e9]-HelperThread-#1] (Slf4jMLog.java:204) - Test of PooledConnection [com.mchange.v2.c3p0.impl.NewPooledConnection@3139c3e] on IDLE CHECK has SUCCEEDED.
17 Oct 2019 09:46:53,352 DEBUG [C3P0PooledConnectionPoolManager[identityToken->1br1htba51mtqkct100p2y5|368267e9]-HelperThread-#0] (Slf4jMLog.java:204) - Testing PooledConnection [com.mchange.v2.c3p0.impl.NewPooledConnection@3139c3e] on IDLE CHECK.
17 Oct 2019 09:46:53,352 DEBUG [C3P0PooledConnectionPoolManager[identityToken->1br1htba51mtqkct100p2y5|368267e9]-HelperThread-#0] (Slf4jMLog.java:204) - Test of PooledConnection [com.mchange.v2.c3p0.impl.NewPooledConnection@3139c3e] on IDLE CHECK has SUCCEEDED.
17 Oct 2019 09:48:53,363 DEBUG [C3P0PooledConnectionPoolManager[identityToken->1br1htba51mtqkct100p2y5|368267e9]-HelperThread-#1] (Slf4jMLog.java:204) - Testing PooledConnection [com.mchange.v2.c3p0.impl.NewPooledConnection@3139c3e] on IDLE CHECK.
17 Oct 2019 09:48:53,363 DEBUG [C3P0PooledConnectionPoolManager[identityToken->1br1htba51mtqkct100p2y5|368267e9]-HelperThread-#1] (Slf4jMLog.java:204) - Test of PooledConnection [com.mchange.v2.c3p0.impl.NewPooledConnection@3139c3e] on IDLE CHECK has SUCCEEDED.
17 Oct 2019 09:50:53,375 DEBUG [C3P0PooledConnectionPoolManager[identityToken->1br1htba51mtqkct100p2y5|368267e9]-HelperThread-#1] (Slf4jMLog.java:204) - Testing PooledConnection [com.mchange.v2.c3p0.impl.NewPooledConnection@3139c3e] on IDLE CHECK.
17 Oct 2019 09:50:53,375 DEBUG [C3P0PooledConnectionPoolManager[identityToken->1br1htba51mtqkct100p2y5|368267e9]-HelperThread-#1] (Slf4jMLog.java:204) - Test of PooledConnection [com.mchange.v2.c3p0.impl.NewPooledConnection@3139c3e] on IDLE CHECK has SUCCEEDED.
17 Oct 2019 09:51:47,571 DEBUG [C3P0PooledConnectionPoolManager[identityToken->1br1htba51mtqkct100p2y5|368267e9]-HelperThread-#0] (Slf4jMLog.java:204) - Preparing to destroy PooledConnection: com.mchange.v2.c3p0.impl.NewPooledConnection@402eda0f
17 Oct 2019 09:51:47,572 DEBUG [C3P0PooledConnectionPoolManager[identityToken->1br1htba51mtqkct100p2y5|368267e9]-HelperThread-#0] (Slf4jMLog.java:204) - Successfully destroyed PooledConnection: com.mchange.v2.c3p0.impl.NewPooledConnection@402eda0f

once an error is detected, the app throws away writes for 30 seconds before it tries the next DB update.
A test on borrow should be avoided for performance reasons (some instances do 100 updates per second).
Is the described scenario a bug or the configuration settings could be improved?
@swaldman
Copy link
Owner

You might customize the connection test (use preferredTestQuery or a custom ConnectionTester) to understand why validation seems to succeed when your real logic fails? You might, for example, hit one of your real tables in a test Connection test.

unreturnedConnectionTimeout doesn't seem so relevant here.

c3p0 is definitely noticing problems — Connection errors are signalled during your sessions. That ought to have provoked c3p0 to exclude from the pool and then replace those bad Connections.

Sign up for free to join this conversation on GitHub. Already have an account? Sign in to comment
Assignees
No one assigned
Labels
None yet
Projects
None yet
Milestone
No milestone
Development

No branches or pull requests
2 participants
@swaldman @schwaiger