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.
Using JDBC drivers from jnetdirect, get com.jnetdirect.jsql.JSQLException with message of "The statement is closed".
Failure occurs in a method that performs a series of queries using a single Session. All queries are made with transient Criteria objects. When I turn on lots of tracing, error takes longer to appear. With log4j tracing turned off, error occurs less frequently.
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)
We are using MS SQL Server, Apache DBCP, and JNETDIRECT driver. Can anyone offer assistance with this problem?
|