Using Hibernate v3.1.3, I am experiencing symptoms that sound like bug
HHH-876. Problem has been intermittent, may be related to timing/latency. Problem happens less frequently when lots of hibernate debug logging is turned on. Using JDBC drivers from jnetdirect, get com.jnetdirect.jsql.JSQLException with message of "The statement is closed".
Failure occurs on a variety of queries, but only occasionally for any given query. Once the problem has occurred for a particular query (prepared statement), problem will occur every time from that point on for that query.
Here is debug trace pattern of successful query:
10:05:40,099 DEBUG AbstractBatcher:311 - about to open PreparedStatement (open PreparedStatements: 0, globally: 0)
10:05:40,099 DEBUG ConnectionManager:358 - opening JDBC connection
10:05:40,109 DEBUG DBCPConnectionProvider:? - active: 1 (max: 20) idle: 0(max: 20)
Hibernate: select this_.id as id27_0_, this_.language as language27_0_, this_.enabled as enabled27_0_, this_.sourceID as sourceID27_0_, this_.focusQuestion as focusQue5_27_0_, this_.markedFocusQuestion as markedFo6_27_0_ from WebInquiryFocusQuestion this_ where this_.id=? and this_.enabled=? and this_.language=?
10:05:40,109 DEBUG AbstractBatcher:424 - preparing statement
10:05:40,109 DEBUG AbstractBatcher:327 - about to open ResultSet (open ResultSets: 0, globally: 0)
10:05:40,109 DEBUG AbstractBatcher:334 - about to close ResultSet (open ResultSets: 1, globally: 1)
10:05:40,109 DEBUG AbstractBatcher:319 - about to close PreparedStatement (open PreparedStatements: 1, globally: 1)
10:05:40,109 DEBUG AbstractBatcher:470 - closing statement
10:05:40,119 DEBUG JDBCContext:213 - after autocommit
10:05:40,119 DEBUG ConnectionManager:341 - aggressively releasing JDBC connection
10:05:40,119 DEBUG ConnectionManager:378 - releasing JDBC connection [ (open PreparedStatements: 0, globally: 0) (open ResultSets: 0, globally: 0)]
10:05:40,119 DEBUG DBCPConnectionProvider:? - active: 0 (max: 20) idle: 1(max: 20)
versus trace when error occurs:
10:05:41,481 DEBUG AbstractBatcher:311 - about to open PreparedStatement (open PreparedStatements: 0, globally: 0)
10:05:41,481 DEBUG ConnectionManager:358 - opening JDBC connection
10:05:41,481 DEBUG DBCPConnectionProvider:? - active: 1 (max: 20) idle: 0(max: 20)
Hibernate: select this_.id as id27_0_, this_.language as language27_0_, this_.enabled as enabled27_0_, this_.sourceID as sourceID27_0_, this_.focusQuestion as focusQue5_27_0_, this_.markedFocusQuestion as markedFo6_27_0_ from WebInquiryFocusQuestion this_ where this_.id=? and this_.enabled=? and this_.language=?
10:05:41,481 DEBUG AbstractBatcher:424 - preparing statement
10:05:41,481 DEBUG AbstractBatcher:319 - about to close PreparedStatement (open PreparedStatements: 1, globally: 1)
10:05:41,481 DEBUG AbstractBatcher:470 - closing statement
10:05:41,501 WARN JDBCExceptionReporter:71 - SQL Error: 0, SQLState: null
10:05:41,501 ERROR JDBCExceptionReporter:72 - The statement is closed
10:05:41,511 DEBUG JDBCContext:213 - after autocommit
10:05:41,511 DEBUG ConnectionManager:341 - aggressively releasing JDBC connection
10:05:41,511 DEBUG ConnectionManager:378 - releasing JDBC connection [ (open PreparedStatements: 0, globally: 0) (open ResultSets: 0, globally: 0)]
10:05:41,511 DEBUG DBCPConnectionProvider:? - active: 0 (max: 20) idle: 1(max: 20)
10:05:41,511 DEBUG ConnectionManager:312 - connection already null in cleanup : no action
Partial stack trace:
[0] com.jnetdirect.jsql.JSQLException.makeFromDriverError:70 (in file JSQLException.java)
[1] com.jnetdirect.jsql.JSQLStatement.setParam:1223 (in file JSQLStatement.java)
[2] com.jnetdirect.jsql.JSQLPreparedStatement.setInt:693 (in file JSQLPreparedStatement.java)
[3] org.apache.commons.dbcp.DelegatingPreparedStatement.setInt:116 (in file DelegatingPreparedStatement.java)
[4] org.apache.commons.dbcp.DelegatingPreparedStatement.setInt:116 (in file DelegatingPreparedStatement.java)
[5] org.hibernate.type.IntegerType.set:41 (in file IntegerType.java)
[6] org.hibernate.type.NullableType.nullSafeSet:85 (in file NullableType.java)
[7] org.hibernate.type.NullableType.nullSafeSet:63 (in file NullableType.java)
[8] org.hibernate.loader.Loader.bindPositionalParameters:1514 (in file Loader.java)
[9] org.hibernate.loader.Loader.prepareQueryStatement:1576 (in file Loader.java)
[10] org.hibernate.loader.Loader.doQuery:661 (in file Loader.java)
[11] org.hibernate.loader.Loader.doQueryAndInitializeNonLazyCollections:224 (in file Loader.java)
[12] org.hibernate.loader.Loader.doList:2145 (in file Loader.java)
[13] org.hibernate.loader.Loader.listIgnoreQueryCache:2029 (in file Loader.java)
[14] org.hibernate.loader.Loader.list:2024 (in file Loader.java)
[15] org.hibernate.loader.criteria.CriteriaLoader.list:94 (in file CriteriaLoader.java)
[16] org.hibernate.impl.SessionImpl.list:1552 (in file SessionImpl.java)
[17] org.hibernate.impl.CriteriaImpl.list:283 (in file CriteriaImpl.java)
[18] org.hibernate.impl.CriteriaImpl.uniqueResult:305 (in file CriteriaImpl.java)
Stack trace will differ depending on which query triggers the problem.
i can't describe it better than what was previously said :
Failure occurs on a variety of queries, but only occasionally for any given query. Once the problem has occurred for a particular query (prepared statement), problem will occur every time from that point on for that query.
I am on different environments though,
hibernate 3.2.6 - spring 2.0.6 - dbcp 1.2.2 - Oracle 10g
partial stacktrace :
java.sql.SQLException: Closed Statement
oracle.jdbc.driver.DatabaseError.throwSqlException(DatabaseError.java:112)
oracle.jdbc.driver.DatabaseError.throwSqlException(DatabaseError.java:146)
oracle.jdbc.driver.DatabaseError.throwSqlException(DatabaseError.java:208)
oracle.jdbc.driver.OracleStatement.ensureOpen(OracleStatement.java:3519)
oracle.jdbc.driver.OraclePreparedStatement.executeInternal(OraclePreparedStatement.java:3297)
oracle.jdbc.driver.OraclePreparedStatement.executeQuery(OraclePreparedStatement.java:3361)
org.apache.commons.dbcp.DelegatingPreparedStatement.executeQuery(DelegatingPreparedStatement.java:93)
org.apache.commons.dbcp.DelegatingPreparedStatement.executeQuery(DelegatingPreparedStatement.java:93)
org.hibernate.jdbc.AbstractBatcher.getResultSet(AbstractBatcher.java:186)
org.hibernate.loader.Loader.getResultSet(Loader.java:1787)
org.hibernate.loader.Loader.doQuery(Loader.java:674)
org.hibernate.loader.Loader.doQueryAndInitializeNonLazyCollections(Loader.java:236)
org.hibernate.loader.Loader.loadEntity(Loader.java:1860)
org.hibernate.loader.entity.AbstractEntityLoader.load(AbstractEntityLoader.java:48)
org.hibernate.loader.entity.AbstractEntityLoader.load(AbstractEntityLoader.java:42)
org.hibernate.persister.entity.AbstractEntityPersister.load(AbstractEntityPersister.java:3049)
org.hibernate.event.def.DefaultLoadEventListener.loadFromDatasource(DefaultLoadEventListener.java:399)
org.hibernate.event.def.DefaultLoadEventListener.doLoad(DefaultLoadEventListener.java:375)
org.hibernate.event.def.DefaultLoadEventListener.load(DefaultLoadEventListener.java:139)
org.hibernate.event.def.DefaultLoadEventListener.onLoad(DefaultLoadEventListener.java:98)
org.hibernate.impl.SessionImpl.fireLoad(SessionImpl.java:878)
org.hibernate.impl.SessionImpl.immediateLoad(SessionImpl.java:836)
org.hibernate.proxy.AbstractLazyInitializer.initialize(AbstractLazyInitializer.java:66)
org.hibernate.proxy.AbstractLazyInitializer.getImplementation(AbstractLazyInitializer.java:111)
org.hibernate.proxy.pojo.cglib.CGLIBLazyInitializer.invoke(CGLIBLazyInitializer.java:150)
I've never been able to reproduce this out of my production environment, which is pretty annoying... I've been loading my development environment with JMeter (a lot !) but with no results...
any fix i missed?