0005637: Double Close on mysql pooled connection datasource

5637

minor

always

01-23-14 17:03

09-11-14 14:26

Reporter:

alex

Platform:

Assigned To:

ferg

OS:

Priority:

normal

OS Version:

Status:

closed

Product Version:

4.0.38

Product Build:

Resolution:

fixed

Projection:

none

ETA:

none

Fixed in Version:

4.0.41

Summary:

0005637: Double Close on mysql pooled connection datasource

Description:

rep by: Srikanth Pulikonda

ManagedConnectionImpl closes poolConn followed by closing driverConn.

MySQL's poolConn closes the underlying driverConn.

driverConn in non-autocommit mode attempts a rollback and checks if the underlying Connection Impl was already closed throwing exception if it already was.

Since mysql's poolConn already had closed the underlying ConnectionImpl error is thrown.

Steps To Reproduce:

Additional Information:

[14-01-23 15:58:32.234] {Simple Daemon} opening JDBC connection
[14-01-23 15:58:32.375] {Simple Daemon} create: ManagedPoolItem[jdbc/LMDB,0,ManagedConnectionImpl](active:0, total:0)
[14-01-23 15:58:32.378] {Simple Daemon} allocate ManagedPoolItem[jdbc/LMDB,0,ManagedConnectionImpl]
[14-01-23 15:58:32.378] {Simple Daemon} current autocommit status: false
iterating: Thu Jan 23 15:58:32 PST 2014
[14-01-23 15:58:32.380] {Simple Daemon} commit
[14-01-23 15:58:32.380] {Simple Daemon} committed JDBC Connection
[14-01-23 15:58:32.380] {Simple Daemon} aggressively releasing JDBC connection
[14-01-23 15:58:32.380] {Simple Daemon} releasing JDBC connection [ (open PreparedStatements: 0, globally: 0) (open ResultSets: 0, globally: 0)]
[14-01-23 15:58:32.383] {Simple Daemon} idle ManagedPoolItem[jdbc/LMDB,0,ManagedConnectionImpl]
[14-01-23 15:58:43.384] {Simple Daemon} opened session at timestamp: 5695576159780864
[14-01-23 15:58:43.384] {Simple Daemon} begin
[14-01-23 15:58:43.384] {Simple Daemon} opening JDBC connection
[14-01-23 15:58:43.385] {Simple Daemon} connection pool destroy ManagedPoolItem[jdbc/LMDB,0,null]
[14-01-23 15:58:43.385] {Simple Daemon} destroy ManagedConnectionImpl[jdbc/LMDB.d0.0]
java.lang.Exception: Stack trace
    at java.lang.Thread.dumpStack(Thread.java:1266)
    at com.mysql.jdbc.ConnectionImpl.realClose(ConnectionImpl.java:4723)
    at com.mysql.jdbc.ConnectionImpl.close(ConnectionImpl.java:1625)
    at com.mysql.jdbc.jdbc2.optional.MysqlPooledConnection.close(MysqlPooledConnection.java:204)
    at com.mysql.jdbc.jdbc2.optional.JDBC4MysqlPooledConnection.close(JDBC4MysqlPooledConnection.java:57)
    at com.caucho.sql.ManagedConnectionImpl.destroy(ManagedConnectionImpl.java:916)
    at com.caucho.env.dbpool.ManagedPoolItem.destroy(ManagedPoolItem.java:1167)
    at com.caucho.env.dbpool.ConnectionPool.allocateIdleConnection(ConnectionPool.java:959)
    at com.caucho.env.dbpool.ConnectionPool.allocatePoolConnection(ConnectionPool.java:839)
    at com.caucho.env.dbpool.ConnectionPool.allocateConnection(ConnectionPool.java:740)
    at com.caucho.env.dbpool.ConnectionPool.allocateConnection(ConnectionPool.java:714)
    at com.caucho.sql.UserDataSource.getConnection(UserDataSource.java:75)
    at com.caucho.sql.DBPool.getConnection(DBPool.java:808)
    at org.hibernate.connection.DatasourceConnectionProvider.getConnection(DatasourceConnectionProvider.java:92)
    at org.hibernate.jdbc.ConnectionManager.openConnection(ConnectionManager.java:446)
    at org.hibernate.jdbc.ConnectionManager.getConnection(ConnectionManager.java:167)
    at org.hibernate.jdbc.JDBCContext.connection(JDBCContext.java:160)
    at org.hibernate.transaction.JDBCTransaction.begin(JDBCTransaction.java:81)
    at org.hibernate.impl.SessionImpl.beginTransaction(SessionImpl.java:1473)
    at sun.reflect.NativeMethodAccessorImpl.invoke0(Native Method)
    at sun.reflect.NativeMethodAccessorImpl.invoke(NativeMethodAccessorImpl.java:57)
    at sun.reflect.DelegatingMethodAccessorImpl.invoke(DelegatingMethodAccessorImpl.java:43)
    at java.lang.reflect.Method.invoke(Method.java:616)
    at org.hibernate.context.ThreadLocalSessionContext$TransactionProtectionWrapper.invoke(ThreadLocalSessionContext.java:345)
    at $Proxy51.beginTransaction(Unknown Source)
    at com.lmsample.hibernate.HibernateSessionFactory.getSession(HibernateSessionFactory.java:57)
    at com.lmsample.hibernate.HibernateSessionFactory.getSession(HibernateSessionFactory.java:44)
    at com.lmsample.SimpleTest$SimpleDaemon.run(SimpleTest.java:36)
[14-01-23 15:58:43.389] {Simple Daemon} 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:57)
                           at sun.reflect.DelegatingConstructorAccessorImpl.newInstance(DelegatingConstructorAccessorImpl.java:45)
                           at java.lang.reflect.Constructor.newInstance(Constructor.java:532)
                           at com.mysql.jdbc.Util.handleNewInstance(Util.java:411)
                           at com.mysql.jdbc.Util.getInstance(Util.java:386)
                           at com.mysql.jdbc.SQLError.createSQLException(SQLError.java:1015)
                           at com.mysql.jdbc.SQLError.createSQLException(SQLError.java:989)
                           at com.mysql.jdbc.SQLError.createSQLException(SQLError.java:975)
                           at com.mysql.jdbc.SQLError.createSQLException(SQLError.java:920)
                           at com.mysql.jdbc.ConnectionImpl.throwConnectionClosedException(ConnectionImpl.java:1299)
                           at com.mysql.jdbc.ConnectionImpl.checkClosed(ConnectionImpl.java:1291)
                           at com.mysql.jdbc.ConnectionImpl.rollback(ConnectionImpl.java:5017)
                           at com.mysql.jdbc.jdbc2.optional.ConnectionWrapper.rollback(ConnectionWrapper.java:794)
                           at com.mysql.jdbc.jdbc2.optional.ConnectionWrapper.close(ConnectionWrapper.java:836)
                           at com.mysql.jdbc.jdbc2.optional.ConnectionWrapper.close(ConnectionWrapper.java:466)
                           at com.mysql.jdbc.jdbc2.optional.JDBC4ConnectionWrapper.close(JDBC4ConnectionWrapper.java:75)
                           at com.caucho.sql.ManagedConnectionImpl.destroy(ManagedConnectionImpl.java:926)
                           at com.caucho.env.dbpool.ManagedPoolItem.destroy(ManagedPoolItem.java:1167)
                           at com.caucho.env.dbpool.ConnectionPool.allocateIdleConnection(ConnectionPool.java:959)
                           at com.caucho.env.dbpool.ConnectionPool.allocatePoolConnection(ConnectionPool.java:839)
                           at com.caucho.env.dbpool.ConnectionPool.allocateConnection(ConnectionPool.java:740)
                           at com.caucho.env.dbpool.ConnectionPool.allocateConnection(ConnectionPool.java:714)
                           at com.caucho.sql.UserDataSource.getConnection(UserDataSource.java:75)
                           at com.caucho.sql.DBPool.getConnection(DBPool.java:808)
                           at org.hibernate.connection.DatasourceConnectionProvider.getConnection(DatasourceConnectionProvider.java:92)
                           at org.hibernate.jdbc.ConnectionManager.openConnection(ConnectionManager.java:446)
                           at org.hibernate.jdbc.ConnectionManager.getConnection(ConnectionManager.java:167)
                           at org.hibernate.jdbc.JDBCContext.connection(JDBCContext.java:160)
                           at org.hibernate.transaction.JDBCTransaction.begin(JDBCTransaction.java:81)
                           at org.hibernate.impl.SessionImpl.beginTransaction(SessionImpl.java:1473)
                           at sun.reflect.NativeMethodAccessorImpl.invoke0(Native Method)
                           at sun.reflect.NativeMethodAccessorImpl.invoke(NativeMethodAccessorImpl.java:57)
                           at sun.reflect.DelegatingMethodAccessorImpl.invoke(DelegatingMethodAccessorImpl.java:43)
                           at java.lang.reflect.Method.invoke(Method.java:616)
                           at org.hibernate.context.ThreadLocalSessionContext$TransactionProtectionWrapper.invoke(ThreadLocalSessionContext.java:345)
                           at $Proxy51.beginTransaction(Unknown Source)
                           at com.lmsample.hibernate.HibernateSessionFactory.getSession(HibernateSessionFactory.java:57)
                           at com.lmsample.hibernate.HibernateSessionFactory.getSession(HibernateSessionFactory.java:44)
                           at com.lmsample.SimpleTest$SimpleDaemon.run(SimpleTest.java:36)

[14-01-23 15:58:43.398] {Simple Daemon} create: ManagedPoolItem[jdbc/LMDB,2,ManagedConnectionImpl](active:0, total:0)
[14-01-23 15:58:43.398] {Simple Daemon} allocate ManagedPoolItem[jdbc/LMDB,2,ManagedConnectionImpl]
[14-01-23 15:58:43.398] {Simple Daemon} current autocommit status: false
iterating: Thu Jan 23 15:58:43 PST 2014

Relationships

Attached Files:

Mantis - Resin
Viewing Issue Advanced Details

ID:	Category:	Severity:	Reproducibility:	Date Submitted:	Last Update:
5637		minor	always	01-23-14 17:03	09-11-14 14:26

Reporter:	alex	Platform:
Assigned To:	ferg	OS:
Priority:	normal	OS Version:
Status:	closed	Product Version:	4.0.38
Product Build:		Resolution:	fixed
Projection:	none
ETA:	none	Fixed in Version:	4.0.41

Summary:	0005637: Double Close on mysql pooled connection datasource
Description:	rep by: Srikanth Pulikonda ManagedConnectionImpl closes poolConn followed by closing driverConn. MySQL's poolConn closes the underlying driverConn. driverConn in non-autocommit mode attempts a rollback and checks if the underlying Connection Impl was already closed throwing exception if it already was. Since mysql's poolConn already had closed the underlying ConnectionImpl error is thrown.
Steps To Reproduce:
Additional Information:	[14-01-23 15:58:32.234] {Simple Daemon} opening JDBC connection [14-01-23 15:58:32.375] {Simple Daemon} create: ManagedPoolItem[jdbc/LMDB,0,ManagedConnectionImpl](active:0, total:0) [14-01-23 15:58:32.378] {Simple Daemon} allocate ManagedPoolItem[jdbc/LMDB,0,ManagedConnectionImpl] [14-01-23 15:58:32.378] {Simple Daemon} current autocommit status: false iterating: Thu Jan 23 15:58:32 PST 2014 [14-01-23 15:58:32.380] {Simple Daemon} commit [14-01-23 15:58:32.380] {Simple Daemon} committed JDBC Connection [14-01-23 15:58:32.380] {Simple Daemon} aggressively releasing JDBC connection [14-01-23 15:58:32.380] {Simple Daemon} releasing JDBC connection [ (open PreparedStatements: 0, globally: 0) (open ResultSets: 0, globally: 0)] [14-01-23 15:58:32.383] {Simple Daemon} idle ManagedPoolItem[jdbc/LMDB,0,ManagedConnectionImpl] [14-01-23 15:58:43.384] {Simple Daemon} opened session at timestamp: 5695576159780864 [14-01-23 15:58:43.384] {Simple Daemon} begin [14-01-23 15:58:43.384] {Simple Daemon} opening JDBC connection [14-01-23 15:58:43.385] {Simple Daemon} connection pool destroy ManagedPoolItem[jdbc/LMDB,0,null] [14-01-23 15:58:43.385] {Simple Daemon} destroy ManagedConnectionImpl[jdbc/LMDB.d0.0] java.lang.Exception: Stack trace at java.lang.Thread.dumpStack(Thread.java:1266) at com.mysql.jdbc.ConnectionImpl.realClose(ConnectionImpl.java:4723) at com.mysql.jdbc.ConnectionImpl.close(ConnectionImpl.java:1625) at com.mysql.jdbc.jdbc2.optional.MysqlPooledConnection.close(MysqlPooledConnection.java:204) at com.mysql.jdbc.jdbc2.optional.JDBC4MysqlPooledConnection.close(JDBC4MysqlPooledConnection.java:57) at com.caucho.sql.ManagedConnectionImpl.destroy(ManagedConnectionImpl.java:916) at com.caucho.env.dbpool.ManagedPoolItem.destroy(ManagedPoolItem.java:1167) at com.caucho.env.dbpool.ConnectionPool.allocateIdleConnection(ConnectionPool.java:959) at com.caucho.env.dbpool.ConnectionPool.allocatePoolConnection(ConnectionPool.java:839) at com.caucho.env.dbpool.ConnectionPool.allocateConnection(ConnectionPool.java:740) at com.caucho.env.dbpool.ConnectionPool.allocateConnection(ConnectionPool.java:714) at com.caucho.sql.UserDataSource.getConnection(UserDataSource.java:75) at com.caucho.sql.DBPool.getConnection(DBPool.java:808) at org.hibernate.connection.DatasourceConnectionProvider.getConnection(DatasourceConnectionProvider.java:92) at org.hibernate.jdbc.ConnectionManager.openConnection(ConnectionManager.java:446) at org.hibernate.jdbc.ConnectionManager.getConnection(ConnectionManager.java:167) at org.hibernate.jdbc.JDBCContext.connection(JDBCContext.java:160) at org.hibernate.transaction.JDBCTransaction.begin(JDBCTransaction.java:81) at org.hibernate.impl.SessionImpl.beginTransaction(SessionImpl.java:1473) at sun.reflect.NativeMethodAccessorImpl.invoke0(Native Method) at sun.reflect.NativeMethodAccessorImpl.invoke(NativeMethodAccessorImpl.java:57) at sun.reflect.DelegatingMethodAccessorImpl.invoke(DelegatingMethodAccessorImpl.java:43) at java.lang.reflect.Method.invoke(Method.java:616) at org.hibernate.context.ThreadLocalSessionContext$TransactionProtectionWrapper.invoke(ThreadLocalSessionContext.java:345) at $Proxy51.beginTransaction(Unknown Source) at com.lmsample.hibernate.HibernateSessionFactory.getSession(HibernateSessionFactory.java:57) at com.lmsample.hibernate.HibernateSessionFactory.getSession(HibernateSessionFactory.java:44) at com.lmsample.SimpleTest$SimpleDaemon.run(SimpleTest.java:36) [14-01-23 15:58:43.389] {Simple Daemon} 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:57) at sun.reflect.DelegatingConstructorAccessorImpl.newInstance(DelegatingConstructorAccessorImpl.java:45) at java.lang.reflect.Constructor.newInstance(Constructor.java:532) at com.mysql.jdbc.Util.handleNewInstance(Util.java:411) at com.mysql.jdbc.Util.getInstance(Util.java:386) at com.mysql.jdbc.SQLError.createSQLException(SQLError.java:1015) at com.mysql.jdbc.SQLError.createSQLException(SQLError.java:989) at com.mysql.jdbc.SQLError.createSQLException(SQLError.java:975) at com.mysql.jdbc.SQLError.createSQLException(SQLError.java:920) at com.mysql.jdbc.ConnectionImpl.throwConnectionClosedException(ConnectionImpl.java:1299) at com.mysql.jdbc.ConnectionImpl.checkClosed(ConnectionImpl.java:1291) at com.mysql.jdbc.ConnectionImpl.rollback(ConnectionImpl.java:5017) at com.mysql.jdbc.jdbc2.optional.ConnectionWrapper.rollback(ConnectionWrapper.java:794) at com.mysql.jdbc.jdbc2.optional.ConnectionWrapper.close(ConnectionWrapper.java:836) at com.mysql.jdbc.jdbc2.optional.ConnectionWrapper.close(ConnectionWrapper.java:466) at com.mysql.jdbc.jdbc2.optional.JDBC4ConnectionWrapper.close(JDBC4ConnectionWrapper.java:75) at com.caucho.sql.ManagedConnectionImpl.destroy(ManagedConnectionImpl.java:926) at com.caucho.env.dbpool.ManagedPoolItem.destroy(ManagedPoolItem.java:1167) at com.caucho.env.dbpool.ConnectionPool.allocateIdleConnection(ConnectionPool.java:959) at com.caucho.env.dbpool.ConnectionPool.allocatePoolConnection(ConnectionPool.java:839) at com.caucho.env.dbpool.ConnectionPool.allocateConnection(ConnectionPool.java:740) at com.caucho.env.dbpool.ConnectionPool.allocateConnection(ConnectionPool.java:714) at com.caucho.sql.UserDataSource.getConnection(UserDataSource.java:75) at com.caucho.sql.DBPool.getConnection(DBPool.java:808) at org.hibernate.connection.DatasourceConnectionProvider.getConnection(DatasourceConnectionProvider.java:92) at org.hibernate.jdbc.ConnectionManager.openConnection(ConnectionManager.java:446) at org.hibernate.jdbc.ConnectionManager.getConnection(ConnectionManager.java:167) at org.hibernate.jdbc.JDBCContext.connection(JDBCContext.java:160) at org.hibernate.transaction.JDBCTransaction.begin(JDBCTransaction.java:81) at org.hibernate.impl.SessionImpl.beginTransaction(SessionImpl.java:1473) at sun.reflect.NativeMethodAccessorImpl.invoke0(Native Method) at sun.reflect.NativeMethodAccessorImpl.invoke(NativeMethodAccessorImpl.java:57) at sun.reflect.DelegatingMethodAccessorImpl.invoke(DelegatingMethodAccessorImpl.java:43) at java.lang.reflect.Method.invoke(Method.java:616) at org.hibernate.context.ThreadLocalSessionContext$TransactionProtectionWrapper.invoke(ThreadLocalSessionContext.java:345) at $Proxy51.beginTransaction(Unknown Source) at com.lmsample.hibernate.HibernateSessionFactory.getSession(HibernateSessionFactory.java:57) at com.lmsample.hibernate.HibernateSessionFactory.getSession(HibernateSessionFactory.java:44) at com.lmsample.SimpleTest$SimpleDaemon.run(SimpleTest.java:36) [14-01-23 15:58:43.398] {Simple Daemon} create: ManagedPoolItem[jdbc/LMDB,2,ManagedConnectionImpl](active:0, total:0) [14-01-23 15:58:43.398] {Simple Daemon} allocate ManagedPoolItem[jdbc/LMDB,2,ManagedConnectionImpl] [14-01-23 15:58:43.398] {Simple Daemon} current autocommit status: false iterating: Thu Jan 23 15:58:43 PST 2014
Relationships
Attached Files: