History | Log In     View a printable version of the current page.  
Issue Details (XML | Word | Printable)

Key: HHH-1900
Type: Bug Bug
Status: Open Open
Priority: Critical Critical
Assignee: Unassigned
Reporter: Greg Burcher
Votes: 3
Watchers: 2
Operations

If you were logged in you would be able to see more operations.
Hibernate Core

Prepared Statement closed before executed by AbstractBatcher - similar to HHH-876

Created: 12/Jul/06 03:47 PM   Updated: 21/Aug/08 01:53 PM
Component/s: core
Affects Version/s: 3.1.3
Fix Version/s: None

Time Tracking:
Not Specified

Environment: hibernate 3.1.3, MS SQL Server, Apache DBCP, JSQLConnect


 Description  « Hide
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.

 All   Comments   Work Log   Change History   FishEye      Sort Order: Ascending order - Click to sort in descending order
Nicolas Savois - 24/Jul/08 11:50 AM
I am facing the exact same 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?

breako - 21/Aug/08 11:39 AM
Hi Nicolas,
I am experiencing similar issue, any idea for fix.
Thanks

Gail Badner - 21/Aug/08 01:53 PM
My guess is that a corrupt prepared statement gets cached and reused.

What version of Hibernate are you using?

Please attach mappings and any queries (e.g., criteria, HQL, named, native) that are involved with this exception.