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

[Greg B. (JIRA) <no...@at...>]

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: Hibernate3
        Type: Bug

  Components: core  
    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.

-- 
This message is automatically generated by JIRA.
-
If you think it was sent incorrectly contact one of the administrators:
   http://opensource.atlassian.com/projects/hibernate/secure/Administrators.jspa
-
For more information on JIRA, see:
   http://www.atlassian.com/software/jira