[hibernate-issues] [Hibernate-JIRA] Commented: (HHH-1900) Prepared Statement closed before executed by AbstractBatcher - similar to HHH-876

Prepared Statement closed before executed by AbstractBatcher - similar to HHH-876 --------------------------------------------------------------------------------- Key: HHH-1900 URL: http://opensource.atlassian.com/projects/hibernate/browse/HHH-1900 Project: Hibernate Core Issue Type: Bug Components: core Affects Versions: 3.1.3 Environment: hibernate 3.1.3, MS SQL Server, Apache DBCP, JSQLConnect Reporter: Greg Burcher Priority: Critical 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.