#123 "You can't operate on a closed Statement!!!" and "You can't operate on a closed Connection!!!"

v1.0 (example)
closed-invalid
nobody
None
7
2015-02-18
2013-09-26
pzak
No

Similar to:
https://sourceforge.net/p/c3p0/bugs/7/
https://sourceforge.net/p/c3p0/bugs/32/
https://sourceforge.net/p/c3p0/bugs/116/

Version: c3p0-0.9.2 (but I think that also in c3p0-0.9.5-pre4)

Steps to reproduce:
Happens during heavy loads, only on testing machines - it is very hard to reproduce this locally. I first thought that this is EclipseLink fault, but I tried with BoneCP instead of C3P0 and everything works as it should.

It happens in few places, here are stacktraces:

Exception [EclipseLink-4002] (Eclipse Persistence Services - 2.3.2.v20111125-r10461): org.eclipse.persistence.exceptions.DatabaseException
Internal Exception: java.sql.SQLException: You can't operate on a closed Connection!!!
Error Code: 0
Call: SELECT t0.temp_element, t0.element FROM table t0 WHERE (t0.id = ?)
bind => [162]
Query: DataReadQuery(name="tableNodes" sql="SELECT t0.temp_element, t0.element FROM table t0 WHERE (t0.id = ?)")
javax.persistence.PersistenceException: Exception [EclipseLink-4002] (Eclipse Persistence Services - 2.3.2.v20111125-r10461): org.eclipse.persistence.exceptions.DatabaseException
Internal Exception: java.sql.SQLException: You can't operate on a closed Connection!!!
Error Code: 0
Call: SELECT t0.temp_element, t0.element FROM table t0 WHERE (t0.id = ?)
bind => [162]
Query: DataReadQuery(name="tableNodes" sql="SELECT t0.temp_element, t0.element FROM table t0 WHERE (t0.id = ?)")
at org.eclipse.persistence.internal.jpa.EntityManagerImpl.flush(EntityManagerImpl.java:786)
at .....
Caused by: Exception [EclipseLink-4002] (Eclipse Persistence Services - 2.3.2.v20111125-r10461): org.eclipse.persistence.exceptions.DatabaseException
Internal Exception: java.sql.SQLException: You can't operate on a closed Connection!!!
Error Code: 0
Call: SELECT t0.temp_element, t0.element FROM table t0 WHERE (t0.id = ?)
bind => [162]
Query: DataReadQuery(name="tableNodes" sql="SELECT t0.temp_element, t0.element FROM table t0 WHERE (t0.id = ?)")
at org.eclipse.persistence.exceptions.DatabaseException.sqlException(DatabaseException.java:333)
at org.eclipse.persistence.internal.databaseaccess.DatabaseAccessor.basicExecuteCall(DatabaseAccessor.java:644)
at org.eclipse.persistence.internal.databaseaccess.DatabaseAccessor.executeCall(DatabaseAccessor.java:535)
at org.eclipse.persistence.internal.sessions.AbstractSession.basicExecuteCall(AbstractSession.java:1717)
at org.eclipse.persistence.sessions.server.ClientSession.executeCall(ClientSession.java:253)
at org.eclipse.persistence.internal.queries.DatasourceCallQueryMechanism.executeCall(DatasourceCallQueryMechanism.java:207)
at org.eclipse.persistence.internal.queries.DatasourceCallQueryMechanism.executeCall(DatasourceCallQueryMechanism.java:193)
at org.eclipse.persistence.internal.queries.DatasourceCallQueryMechanism.executeSelectCall(DatasourceCallQueryMechanism.java:264)
at org.eclipse.persistence.internal.queries.DatasourceCallQueryMechanism.executeSelect(DatasourceCallQueryMechanism.java:246)
at org.eclipse.persistence.queries.DataReadQuery.executeNonCursor(DataReadQuery.java:197)
at org.eclipse.persistence.queries.DataReadQuery.executeDatabaseQuery(DataReadQuery.java:152)
at org.eclipse.persistence.queries.DatabaseQuery.execute(DatabaseQuery.java:844)
at org.eclipse.persistence.queries.DataReadQuery.execute(DataReadQuery.java:137)
at org.eclipse.persistence.queries.DatabaseQuery.executeInUnitOfWork(DatabaseQuery.java:743)
at org.eclipse.persistence.internal.sessions.UnitOfWorkImpl.internalExecuteQuery(UnitOfWorkImpl.java:2885)
at org.eclipse.persistence.internal.sessions.AbstractSession.executeQuery(AbstractSession.java:1516)
at org.eclipse.persistence.internal.sessions.AbstractSession.executeQuery(AbstractSession.java:1498)
at org.eclipse.persistence.internal.indirection.QueryBasedValueHolder.instantiate(QueryBasedValueHolder.java:98)
at org.eclipse.persistence.internal.indirection.QueryBasedValueHolder.instantiate(QueryBasedValueHolder.java:88)
at org.eclipse.persistence.internal.indirection.DatabaseValueHolder.getValue(DatabaseValueHolder.java:88)
at org.eclipse.persistence.internal.indirection.UnitOfWorkValueHolder.instantiateImpl(UnitOfWorkValueHolder.java:161)
at org.eclipse.persistence.internal.indirection.UnitOfWorkValueHolder.instantiate(UnitOfWorkValueHolder.java:222)
at org.eclipse.persistence.internal.indirection.DatabaseValueHolder.getValue(DatabaseValueHolder.java:88)
at org.eclipse.persistence.indirection.IndirectMap.buildDelegate(IndirectMap.java:110)
at org.eclipse.persistence.indirection.IndirectMap.getDelegate(IndirectMap.java:329)
at org.eclipse.persistence.indirection.IndirectMap$1.<init>(IndirectMap.java:200)
at org.eclipse.persistence.indirection.IndirectMap.entrySet(IndirectMap.java:199)
at org.eclipse.persistence.internal.queries.MapContainerPolicy$MapContainerPolicyIterator.<init>(MapContainerPolicy.java:890)
at org.eclipse.persistence.internal.queries.MapContainerPolicy.iteratorFor(MapContainerPolicy.java:529)
at org.eclipse.persistence.mappings.DirectMapMapping.cascadeDiscoverAndPersistUnregisteredNewObjects(DirectMapMapping.java:186)
at org.eclipse.persistence.internal.descriptors.ObjectBuilder.cascadeDiscoverAndPersistUnregisteredNewObjects(ObjectBuilder.java:1917)
at org.eclipse.persistence.internal.sessions.UnitOfWorkImpl.discoverAndPersistUnregisteredNewObjects(UnitOfWorkImpl.java:4162)
at org.eclipse.persistence.internal.sessions.RepeatableWriteUnitOfWork.discoverUnregisteredNewObjects(RepeatableWriteUnitOfWork.java:299)
at org.eclipse.persistence.internal.sessions.UnitOfWorkImpl.calculateChanges(UnitOfWorkImpl.java:716)
at org.eclipse.persistence.internal.sessions.RepeatableWriteUnitOfWork.writeChanges(RepeatableWriteUnitOfWork.java:433)
at org.eclipse.persistence.internal.jpa.EntityManagerImpl.flush(EntityManagerImpl.java:780)
... 45 more
Caused by: java.sql.SQLException: You can't operate on a closed Connection!!!
at com.mchange.v2.sql.SqlUtils.toSQLException(SqlUtils.java:106)
at com.mchange.v2.sql.SqlUtils.toSQLException(SqlUtils.java:65)
at com.mchange.v2.c3p0.impl.NewProxyConnection.prepareStatement(NewProxyConnection.java:171)
at org.eclipse.persistence.internal.databaseaccess.DatabaseAccessor.prepareStatement(DatabaseAccessor.java:1474)
at org.eclipse.persistence.internal.databaseaccess.DatabaseAccessor.prepareStatement(DatabaseAccessor.java:1423)
at org.eclipse.persistence.internal.databaseaccess.DatabaseCall.prepareStatement(DatabaseCall.java:697)
at org.eclipse.persistence.internal.databaseaccess.DatabaseAccessor.basicExecuteCall(DatabaseAccessor.java:585)
... 79 more
Caused by: java.lang.NullPointerException
at com.mchange.v2.c3p0.impl.NewProxyConnection.prepareStatement(NewProxyConnection.java:135)
... 83 more

Exception [EclipseLink-4002] (Eclipse Persistence Services - 2.3.2.v20111125-r10461): org.eclipse.persistence.exceptions.DatabaseException
Internal Exception: java.sql.SQLException: You can't operate on a closed Statement!!!
Error Code: 0
Call: SELECT t0.temp_element, t0.element FROM table t0 WHERE (t0.id = ?)
bind => [162]
Query: DataReadQuery(name="tableNodes" sql="SELECT t0.temp_element, t0.element FROM table t0 WHERE (t0.id = ?)")
javax.persistence.PersistenceException: Exception [EclipseLink-4002] (Eclipse Persistence Services - 2.3.2.v20111125-r10461): org.eclipse.persistence.exceptions.DatabaseException
Internal Exception: java.sql.SQLException: You can't operate on a closed Statement!!!
Error Code: 0
Call: SELECT t0.temp_element, t0.element FROM table t0 WHERE (t0.id = ?)
bind => [162]
Query: DataReadQuery(name="tableNodes" sql="SELECT t0.temp_element, t0.element FROM table t0 WHERE (t0.id = ?)")
at org.eclipse.persistence.internal.jpa.EntityManagerImpl.flush(EntityManagerImpl.java:786)
at .....
Caused by: Exception [EclipseLink-4002] (Eclipse Persistence Services - 2.3.2.v20111125-r10461): org.eclipse.persistence.exceptions.DatabaseException
Internal Exception: java.sql.SQLException: You can't operate on a closed Statement!!!
Error Code: 0
Call: SELECT t0.temp_element, t0.element FROM table t0 WHERE (t0.id = ?)
bind => [162]
Query: DataReadQuery(name="tableNodes" sql="SELECT t0.temp_element, t0.element FROM table t0 WHERE (t0.id = ?)")
at org.eclipse.persistence.exceptions.DatabaseException.sqlException(DatabaseException.java:333)
at org.eclipse.persistence.internal.databaseaccess.DatabaseAccessor.basicExecuteCall(DatabaseAccessor.java:644)
at org.eclipse.persistence.internal.databaseaccess.DatabaseAccessor.executeCall(DatabaseAccessor.java:535)
at org.eclipse.persistence.internal.sessions.AbstractSession.basicExecuteCall(AbstractSession.java:1717)
at org.eclipse.persistence.sessions.server.ClientSession.executeCall(ClientSession.java:253)
at org.eclipse.persistence.internal.queries.DatasourceCallQueryMechanism.executeCall(DatasourceCallQueryMechanism.java:207)
at org.eclipse.persistence.internal.queries.DatasourceCallQueryMechanism.executeCall(DatasourceCallQueryMechanism.java:193)
at org.eclipse.persistence.internal.queries.DatasourceCallQueryMechanism.executeSelectCall(DatasourceCallQueryMechanism.java:264)
at org.eclipse.persistence.internal.queries.DatasourceCallQueryMechanism.executeSelect(DatasourceCallQueryMechanism.java:246)
at org.eclipse.persistence.queries.DataReadQuery.executeNonCursor(DataReadQuery.java:197)
at org.eclipse.persistence.queries.DataReadQuery.executeDatabaseQuery(DataReadQuery.java:152)
at org.eclipse.persistence.queries.DatabaseQuery.execute(DatabaseQuery.java:844)
at org.eclipse.persistence.queries.DataReadQuery.execute(DataReadQuery.java:137)
at org.eclipse.persistence.queries.DatabaseQuery.executeInUnitOfWork(DatabaseQuery.java:743)
at org.eclipse.persistence.internal.sessions.UnitOfWorkImpl.internalExecuteQuery(UnitOfWorkImpl.java:2885)
at org.eclipse.persistence.internal.sessions.AbstractSession.executeQuery(AbstractSession.java:1516)
at org.eclipse.persistence.internal.sessions.AbstractSession.executeQuery(AbstractSession.java:1498)
at org.eclipse.persistence.internal.indirection.QueryBasedValueHolder.instantiate(QueryBasedValueHolder.java:98)
at org.eclipse.persistence.internal.indirection.QueryBasedValueHolder.instantiate(QueryBasedValueHolder.java:88)
at org.eclipse.persistence.internal.indirection.DatabaseValueHolder.getValue(DatabaseValueHolder.java:88)
at org.eclipse.persistence.internal.indirection.UnitOfWorkValueHolder.instantiateImpl(UnitOfWorkValueHolder.java:161)
at org.eclipse.persistence.internal.indirection.UnitOfWorkValueHolder.instantiate(UnitOfWorkValueHolder.java:222)
at org.eclipse.persistence.internal.indirection.DatabaseValueHolder.getValue(DatabaseValueHolder.java:88)
at org.eclipse.persistence.indirection.IndirectMap.buildDelegate(IndirectMap.java:110)
at org.eclipse.persistence.indirection.IndirectMap.getDelegate(IndirectMap.java:329)
at org.eclipse.persistence.indirection.IndirectMap$1.<init>(IndirectMap.java:200)
at org.eclipse.persistence.indirection.IndirectMap.entrySet(IndirectMap.java:199)
at org.eclipse.persistence.internal.queries.MapContainerPolicy$MapContainerPolicyIterator.<init>(MapContainerPolicy.java:890)
at org.eclipse.persistence.internal.queries.MapContainerPolicy.iteratorFor(MapContainerPolicy.java:529)
at org.eclipse.persistence.mappings.DirectMapMapping.cascadeDiscoverAndPersistUnregisteredNewObjects(DirectMapMapping.java:186)
at org.eclipse.persistence.internal.descriptors.ObjectBuilder.cascadeDiscoverAndPersistUnregisteredNewObjects(ObjectBuilder.java:1917)
at org.eclipse.persistence.internal.sessions.UnitOfWorkImpl.discoverAndPersistUnregisteredNewObjects(UnitOfWorkImpl.java:4162)
at org.eclipse.persistence.internal.sessions.RepeatableWriteUnitOfWork.discoverUnregisteredNewObjects(RepeatableWriteUnitOfWork.java:299)
at org.eclipse.persistence.internal.sessions.UnitOfWorkImpl.calculateChanges(UnitOfWorkImpl.java:716)
at org.eclipse.persistence.internal.sessions.RepeatableWriteUnitOfWork.writeChanges(RepeatableWriteUnitOfWork.java:433)
at org.eclipse.persistence.internal.jpa.EntityManagerImpl.flush(EntityManagerImpl.java:780)
... 45 more
Caused by: java.sql.SQLException: You can't operate on a closed Statement!!!
at com.mchange.v2.sql.SqlUtils.toSQLException(SqlUtils.java:106)
at com.mchange.v2.sql.SqlUtils.toSQLException(SqlUtils.java:65)
at com.mchange.v2.c3p0.impl.NewProxyPreparedStatement.executeQuery(NewProxyPreparedStatement.java:134)
at org.eclipse.persistence.internal.databaseaccess.DatabaseAccessor.executeSelect(DatabaseAccessor.java:931)
at org.eclipse.persistence.internal.databaseaccess.DatabaseAccessor.basicExecuteCall(DatabaseAccessor.java:607)
... 79 more
Caused by: java.lang.NullPointerException
at com.mchange.v2.c3p0.impl.NewProxyPreparedStatement.executeQuery(NewProxyPreparedStatement.java:119)
... 81 more

Exception [EclipseLink-4002] (Eclipse Persistence Services - 2.3.2.v20111125-r10461): org.eclipse.persistence.exceptions.DatabaseException
Internal Exception: java.sql.SQLException: You can't operate on a closed Statement!!!
Error Code: 0
Call: SELECT t0.temp_element, t0.element FROM table t0 WHERE (t0.id = ?)
bind => [162]
Query: DataReadQuery(name="tableNodes" sql="SELECT t0.temp_element, t0.element FROM table t0 WHERE (t0.id = ?)")
javax.persistence.PersistenceException: Exception [EclipseLink-4002] (Eclipse Persistence Services - 2.3.2.v20111125-r10461): org.eclipse.persistence.exceptions.DatabaseException
Internal Exception: java.sql.SQLException: You can't operate on a closed Statement!!!
Error Code: 0
Call: SELECT t0.temp_element, t0.element FROM table t0 WHERE (t0.id = ?)
bind => [162]
Query: DataReadQuery(name="tableNodes" sql="SELECT t0.temp_element, t0.element FROM table t0 WHERE (t0.id = ?)")
at org.eclipse.persistence.internal.jpa.EntityManagerImpl.flush(EntityManagerImpl.java:786)
at .....
Caused by: Exception [EclipseLink-4002] (Eclipse Persistence Services - 2.3.2.v20111125-r10461): org.eclipse.persistence.exceptions.DatabaseException
Internal Exception: java.sql.SQLException: You can't operate on a closed Statement!!!
Error Code: 0
Call: SELECT t0.temp_element, t0.element FROM table t0 WHERE (t0.id = ?)
bind => [162]
Query: DataReadQuery(name="tableNodes" sql="SELECT t0.temp_element, t0.element FROM table t0 WHERE (t0.id = ?)")
at org.eclipse.persistence.exceptions.DatabaseException.sqlException(DatabaseException.java:333)
at org.eclipse.persistence.internal.databaseaccess.DatabaseAccessor.basicExecuteCall(DatabaseAccessor.java:644)
at org.eclipse.persistence.internal.databaseaccess.DatabaseAccessor.executeCall(DatabaseAccessor.java:535)
at org.eclipse.persistence.internal.sessions.AbstractSession.basicExecuteCall(AbstractSession.java:1717)
at org.eclipse.persistence.sessions.server.ClientSession.executeCall(ClientSession.java:253)
at org.eclipse.persistence.internal.queries.DatasourceCallQueryMechanism.executeCall(DatasourceCallQueryMechanism.java:207)
at org.eclipse.persistence.internal.queries.DatasourceCallQueryMechanism.executeCall(DatasourceCallQueryMechanism.java:193)
at org.eclipse.persistence.internal.queries.DatasourceCallQueryMechanism.executeSelectCall(DatasourceCallQueryMechanism.java:264)
at org.eclipse.persistence.internal.queries.DatasourceCallQueryMechanism.executeSelect(DatasourceCallQueryMechanism.java:246)
at org.eclipse.persistence.queries.DataReadQuery.executeNonCursor(DataReadQuery.java:197)
at org.eclipse.persistence.queries.DataReadQuery.executeDatabaseQuery(DataReadQuery.java:152)
at org.eclipse.persistence.queries.DatabaseQuery.execute(DatabaseQuery.java:844)
at org.eclipse.persistence.queries.DataReadQuery.execute(DataReadQuery.java:137)
at org.eclipse.persistence.queries.DatabaseQuery.executeInUnitOfWork(DatabaseQuery.java:743)
at org.eclipse.persistence.internal.sessions.UnitOfWorkImpl.internalExecuteQuery(UnitOfWorkImpl.java:2885)
at org.eclipse.persistence.internal.sessions.AbstractSession.executeQuery(AbstractSession.java:1516)
at org.eclipse.persistence.internal.sessions.AbstractSession.executeQuery(AbstractSession.java:1498)
at org.eclipse.persistence.internal.indirection.QueryBasedValueHolder.instantiate(QueryBasedValueHolder.java:98)
at org.eclipse.persistence.internal.indirection.QueryBasedValueHolder.instantiate(QueryBasedValueHolder.java:88)
at org.eclipse.persistence.internal.indirection.DatabaseValueHolder.getValue(DatabaseValueHolder.java:88)
at org.eclipse.persistence.internal.indirection.UnitOfWorkValueHolder.instantiateImpl(UnitOfWorkValueHolder.java:161)
at org.eclipse.persistence.internal.indirection.UnitOfWorkValueHolder.instantiate(UnitOfWorkValueHolder.java:222)
at org.eclipse.persistence.internal.indirection.DatabaseValueHolder.getValue(DatabaseValueHolder.java:88)
at org.eclipse.persistence.indirection.IndirectMap.buildDelegate(IndirectMap.java:110)
at org.eclipse.persistence.indirection.IndirectMap.getDelegate(IndirectMap.java:329)
at org.eclipse.persistence.indirection.IndirectMap$1.<init>(IndirectMap.java:200)
at org.eclipse.persistence.indirection.IndirectMap.entrySet(IndirectMap.java:199)
at org.eclipse.persistence.internal.queries.MapContainerPolicy$MapContainerPolicyIterator.<init>(MapContainerPolicy.java:890)
at org.eclipse.persistence.internal.queries.MapContainerPolicy.iteratorFor(MapContainerPolicy.java:529)
at org.eclipse.persistence.mappings.DirectMapMapping.cascadeDiscoverAndPersistUnregisteredNewObjects(DirectMapMapping.java:186)
at org.eclipse.persistence.internal.descriptors.ObjectBuilder.cascadeDiscoverAndPersistUnregisteredNewObjects(ObjectBuilder.java:1917)
at org.eclipse.persistence.internal.sessions.UnitOfWorkImpl.discoverAndPersistUnregisteredNewObjects(UnitOfWorkImpl.java:4162)
at org.eclipse.persistence.internal.sessions.RepeatableWriteUnitOfWork.discoverUnregisteredNewObjects(RepeatableWriteUnitOfWork.java:299)
at org.eclipse.persistence.internal.sessions.UnitOfWorkImpl.calculateChanges(UnitOfWorkImpl.java:716)
at org.eclipse.persistence.internal.sessions.RepeatableWriteUnitOfWork.writeChanges(RepeatableWriteUnitOfWork.java:433)
at org.eclipse.persistence.internal.jpa.EntityManagerImpl.flush(EntityManagerImpl.java:780)
... 45 more
Caused by: java.sql.SQLException: You can't operate on a closed Statement!!!
at com.mchange.v2.sql.SqlUtils.toSQLException(SqlUtils.java:106)
at com.mchange.v2.sql.SqlUtils.toSQLException(SqlUtils.java:65)
at com.mchange.v2.c3p0.impl.NewProxyPreparedStatement.executeQuery(NewProxyPreparedStatement.java:147)
at org.eclipse.persistence.internal.databaseaccess.DatabaseAccessor.executeSelect(DatabaseAccessor.java:931)
at org.eclipse.persistence.internal.databaseaccess.DatabaseAccessor.basicExecuteCall(DatabaseAccessor.java:607)
... 79 more
Caused by: java.lang.NullPointerException
at com.mchange.v2.c3p0.impl.NewProxyPreparedStatement.executeQuery(NewProxyPreparedStatement.java:137)
... 81 more

So i patched a NewProxyPreparedStatement class a little:
- I introduced this field: private Throwable parentPooledConnectionDetachThrowable = null; (every usage of this field is synchronized)
- I cleaining it in attach()
- In detach I save there new Throwable with some info:
- this.toString()
- current time
- current thread name
- hashCode of current EntityManager (we have mechanism for saving this hash code for every open EntityManager for every thread)
- hashCode of current Transaction (similar mechanism as above)

In executeQuery(), just before "if ( this.isDetached() )" in catch, I write down current stacktrace with: this.toString(), hashCode of current EntityManager and hashCode of current Transaction (time and name thread are provided by log4j). Additionally I also log parentPooledConnectionDetachThrowable.

Here is example:

2013-09-23 10:34:19,460 [MdFixedThread-3] WARN - NewProxyPreparedStatement.executeQuery() this: com.mchange.v2.c3p0.impl.NewProxyPreparedStatement@163c43c
emID: [29431910], trID: [18720804]
Current stacktrace:
java.lang.Throwable
at com.mchange.v2.c3p0.impl.NewProxyPreparedStatement.additionalLog(NewProxyPreparedStatement.java:119)
at com.mchange.v2.c3p0.impl.NewProxyPreparedStatement.executeQuery(NewProxyPreparedStatement.java:144)
at org.eclipse.persistence.internal.databaseaccess.DatabaseAccessor.executeSelect(DatabaseAccessor.java:931)
at org.eclipse.persistence.internal.databaseaccess.DatabaseAccessor.basicExecuteCall(DatabaseAccessor.java:607)
at org.eclipse.persistence.internal.databaseaccess.DatabaseAccessor.executeCall(DatabaseAccessor.java:535)
at org.eclipse.persistence.internal.sessions.AbstractSession.basicExecuteCall(AbstractSession.java:1717)
at org.eclipse.persistence.sessions.server.ClientSession.executeCall(ClientSession.java:253)
at org.eclipse.persistence.internal.queries.DatasourceCallQueryMechanism.executeCall(DatasourceCallQueryMechanism.java:207)
at org.eclipse.persistence.internal.queries.DatasourceCallQueryMechanism.executeCall(DatasourceCallQueryMechanism.java:193)
at org.eclipse.persistence.internal.queries.DatasourceCallQueryMechanism.executeSelectCall(DatasourceCallQueryMechanism.java:264)
at org.eclipse.persistence.internal.queries.DatasourceCallQueryMechanism.executeSelect(DatasourceCallQueryMechanism.java:246)
at org.eclipse.persistence.queries.DataReadQuery.executeNonCursor(DataReadQuery.java:197)
at org.eclipse.persistence.queries.DataReadQuery.executeDatabaseQuery(DataReadQuery.java:152)
at org.eclipse.persistence.queries.DatabaseQuery.execute(DatabaseQuery.java:844)
at org.eclipse.persistence.queries.DataReadQuery.execute(DataReadQuery.java:137)
at org.eclipse.persistence.queries.DatabaseQuery.executeInUnitOfWork(DatabaseQuery.java:743)
at org.eclipse.persistence.internal.sessions.UnitOfWorkImpl.internalExecuteQuery(UnitOfWorkImpl.java:2885)
at org.eclipse.persistence.internal.sessions.AbstractSession.executeQuery(AbstractSession.java:1516)
at org.eclipse.persistence.internal.sessions.AbstractSession.executeQuery(AbstractSession.java:1498)
at org.eclipse.persistence.internal.indirection.QueryBasedValueHolder.instantiate(QueryBasedValueHolder.java:98)
at org.eclipse.persistence.internal.indirection.QueryBasedValueHolder.instantiate(QueryBasedValueHolder.java:88)
at org.eclipse.persistence.internal.indirection.DatabaseValueHolder.getValue(DatabaseValueHolder.java:88)
at org.eclipse.persistence.internal.indirection.UnitOfWorkValueHolder.instantiateImpl(UnitOfWorkValueHolder.java:161)
at org.eclipse.persistence.internal.indirection.UnitOfWorkValueHolder.instantiate(UnitOfWorkValueHolder.java:222)
at org.eclipse.persistence.internal.indirection.DatabaseValueHolder.getValue(DatabaseValueHolder.java:88)
at org.eclipse.persistence.indirection.IndirectMap.buildDelegate(IndirectMap.java:110)
at org.eclipse.persistence.indirection.IndirectMap.getDelegate(IndirectMap.java:329)
at org.eclipse.persistence.indirection.IndirectMap$1.<init>(IndirectMap.java:200)
at org.eclipse.persistence.indirection.IndirectMap.entrySet(IndirectMap.java:199)
at org.eclipse.persistence.internal.queries.MapContainerPolicy$MapContainerPolicyIterator.<init>(MapContainerPolicy.java:890)
at org.eclipse.persistence.internal.queries.MapContainerPolicy.iteratorFor(MapContainerPolicy.java:529)
at org.eclipse.persistence.mappings.DirectMapMapping.cascadeDiscoverAndPersistUnregisteredNewObjects(DirectMapMapping.java:186)
at org.eclipse.persistence.internal.descriptors.ObjectBuilder.cascadeDiscoverAndPersistUnregisteredNewObjects(ObjectBuilder.java:1917)
at org.eclipse.persistence.internal.sessions.UnitOfWorkImpl.discoverAndPersistUnregisteredNewObjects(UnitOfWorkImpl.java:4162)
at org.eclipse.persistence.internal.sessions.RepeatableWriteUnitOfWork.discoverUnregisteredNewObjects(RepeatableWriteUnitOfWork.java:299)
at org.eclipse.persistence.internal.sessions.UnitOfWorkImpl.calculateChanges(UnitOfWorkImpl.java:716)
at org.eclipse.persistence.internal.sessions.RepeatableWriteUnitOfWork.writeChanges(RepeatableWriteUnitOfWork.java:433)
at org.eclipse.persistence.internal.jpa.EntityManagerImpl.flush(EntityManagerImpl.java:780)
at ...
2013-09-23 10:34:19,474 [MdFixedThread-3] WARN - Detach stacktrace:
java.lang.Throwable: parentPooledConnectionDetachThrowable - this: com.mchange.v2.c3p0.impl.NewProxyPreparedStatement@163c43c, Time: 2013-09-23 10:34:19,448, Thread: FNM:MdFixedThread-5
emID: [20640819], trID: [20528945]
at com.mchange.v2.c3p0.impl.NewProxyPreparedStatement.detach(NewProxyPreparedStatement.java:2793)
at com.mchange.v2.c3p0.impl.NewProxyPreparedStatement.access$000(NewProxyPreparedStatement.java:44)
at com.mchange.v2.c3p0.impl.NewProxyPreparedStatement$1.connectionClosed(NewProxyPreparedStatement.java:2767)
at com.mchange.v2.c3p0.util.ConnectionEventSupport.fireConnectionClosed(ConnectionEventSupport.java:61)
at com.mchange.v2.c3p0.impl.NewPooledConnection.fireConnectionClosed(NewPooledConnection.java:558)
at com.mchange.v2.c3p0.impl.NewPooledConnection.markClosedProxyConnection(NewPooledConnection.java:427)
at com.mchange.v2.c3p0.impl.NewProxyConnection.close(NewProxyConnection.java:1225)
at org.eclipse.persistence.internal.databaseaccess.DatabaseAccessor.closeDatasourceConnection(DatabaseAccessor.java:473)
at org.eclipse.persistence.internal.databaseaccess.DatasourceAccessor.closeConnection(DatasourceAccessor.java:504)
at org.eclipse.persistence.internal.databaseaccess.DatabaseAccessor.closeConnection(DatabaseAccessor.java:496)
at org.eclipse.persistence.sessions.server.ExternalConnectionPool.releaseConnection(ExternalConnectionPool.java:111)
at org.eclipse.persistence.sessions.server.ServerSession.releaseClientSession(ServerSession.java:792)
at org.eclipse.persistence.sessions.server.ClientSession.releaseWriteConnection(ClientSession.java:602)
at org.eclipse.persistence.sessions.server.ClientSession.basicCommitTransaction(ClientSession.java:139)
at org.eclipse.persistence.internal.sessions.AbstractSession.commitTransaction(AbstractSession.java:762)
at org.eclipse.persistence.internal.sessions.UnitOfWorkImpl.commitTransaction(UnitOfWorkImpl.java:1588)
at org.eclipse.persistence.internal.sessions.RepeatableWriteUnitOfWork.commitTransaction(RepeatableWriteUnitOfWork.java:649)
at org.eclipse.persistence.internal.sessions.UnitOfWorkImpl.commitTransactionAfterWriteChanges(UnitOfWorkImpl.java:1603)
at org.eclipse.persistence.internal.sessions.RepeatableWriteUnitOfWork.commitRootUnitOfWork(RepeatableWriteUnitOfWork.java:275)
at org.eclipse.persistence.internal.sessions.UnitOfWorkImpl.commitAndResume(UnitOfWorkImpl.java:1157)
at org.eclipse.persistence.internal.jpa.transaction.EntityTransactionImpl.commitInternal(EntityTransactionImpl.java:84)
at org.eclipse.persistence.internal.jpa.transaction.EntityTransactionImpl.commit(EntityTransactionImpl.java:63)
at ...

It's clear that statement was detached few milliseconds before by different thread which use different EntityManager and Transaction.

c3p0 settings:
cpds.setDriverClass(org.postgresql.Driver);
cpds.setPreferredTestQuery(SELECT 1);

cpds.setMinPoolSize(3);
cpds.setMaxPoolSize(145);
cpds.setInitialPoolSize(10);

cpds.setMaxStatements(100000);
cpds.setMaxIdleTime(600);
cpds.setMaxIdleTimeExcessConnections(300);
cpds.setIdleConnectionTestPeriod(660);
cpds.setAcquireRetryAttempts(5);
cpds.setCheckoutTimeout(60000);
cpds.setMaxAdministrativeTaskTime(600);
cpds.setNumHelperThreads(10);

Discussion

  • Steve Waldman
    Steve Waldman
    2013-09-26

    hi,

    first thank you for your work in tracing down the issue and producing a detailed report.

    it seems to me, though, that what you have done is documented that it is not a c3p0 bug at all. that is, how would you like for c3p0 to behave if your application tries to access a Statement a few milliseconds after, as you have documented, it (in the very same Thread) has close()ed the Connection that owns the Statement? shouldn't c3p0 do exactly what it does, and throw an Exception indicating that you are operating on a close()ed Statement? (Statements are children of Connections -- per JDBC at its most basic level, a Statement of an invalid Connection is invalid.)

    it seems to me that the issue is that other Connection pools may be a bit less strict. that is, c3p0 is very, very careful to clean up child resources upon Connection close(). other pools may not be so strict. since the physical Connection is not actually close()ed, if the pooling library does not actively close() child resources, a should-be-orphaned Statement would still be "live" after Connection close(). per the spec, this is a bug: Connection pooling is supposed to fully respect the semantics of an unpooled Connection. but if other pools fail to close() the Statement, the query execution would "work". it would work in a very strange transactional context -- do you really know what JDBC transaction you are running in if the parent Connection, on which the transaction has been defined, has been "close()ed"? but it would not throw an Exception.

    so my sense is that this is not a c3p0 bug, but a bug in your JPA implementation getting hidden by a bug in other pooling libraries. that sounds a bit lame, blaming everybody else, but it seems to be what's going on. am i wrong?

     
  • pzak
    pzak
    2013-09-26

    Yes. Connection has been closed, but in different thread (MdFixedThread-3 is current thread, MdFixedThread-5 is thread in which Connection has been closed).

    Decisions to open new Connections and close this specific Connection are made by EclipseLink exclusively. So maybe it is their fault.
    But as you see in my links, people have similar problem with Hibernate too.

    So there are my questions:
    - are two of the most popular JPA implementations have the same bug or
    something is not right with ConnectionPooling?
    - is Connection thread-safe?
    - if not, which fault is that it is used by different threads at (almost) the same time?

     
  • Steve Waldman
    Steve Waldman
    2013-09-26

    Per the original JDBC 1.0 spec (by memory, I can't even find it now!), the rules were that a Connection should be thread-safe, but its subsidiary objects (e.g. Statements) need not be and should not be used concurrently by multiple Threads. A later spec (1.3, would have been JDBC2) said all java.sql objects should be Thread safe [ http://docs.oracle.com/javase/1.3/docs/guide/jdbc/spec/jdbc-spec.frame9.html ] . More recent specs say nothing at all about thread-safety. (They do misleading use the word "concurrent" to describe a case where multiple Statement objects are open and used within a single Thread.)

    In practice, many JDBC drivers have problems with any concurrent use of Connections, and it should simply not be done. There is not, never was, and never would be behavior specified such that says while a Statement is outstanding, access to the parent Connection should be blocked by all but the Thread that created the Statement. That's the semantics you'd require to prevent this issue if a client is calling close() in one Thread while executing a Statement in another. It is not specified, and could not reasonably be enforced unless clients do so with their own locking.

    Ultimately this is not a thread safety issue per se, except to the extent that a clients ought to have been more careful about the sequencing of operations across Threads. A Connection can be perfectly Thread-safe, in the sense that all of its methods are synchronized and concurrent access never corrupts to object or violates internal invariants, but if one Thread calls close() before another Thread performs an operation, that won't work. [For example, a java.util.Hashtable is Thread-safe. But if one Thread deletes a key before another Thread has put() it, unexpected behavior will result.]

    What semantics would you like for c3p0 to support if, as you have documented, one Thread has already close()ed the connection on which operations are subsequently requested? I'm certainly open to a solution, but it seems to me that "resolving" the problem would amount to breaking the library so that it hides client misuse.

    c3p0 is very widely used in JPA contexts, and these reports are rare. I won't cast aspersions. Maybe there are rare race conditions in some JPA libraries, sufficiently rare that they've never been resolved. Maybe these events are caused misconfigurations somewhere in the stack. I don't know. But if, as has usually been the case, already-closed Exceptions turn out to be due to some client having already close()ed the Connection, I really don't know how c3p0 can help.

    Do you have any ideas? How should c3p0 behave in this case?

     
  • pzak
    pzak
    2013-10-08

    I guess you are right.
    It happened to me once with BoneCP too.

    I reported bug to EclipseLink: https://bugs.eclipse.org/bugs/show_bug.cgi?id=418909

    Thank you for your help.

     
  • Steve Waldman
    Steve Waldman
    2013-12-04

    • status: open --> closed-invalid