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

Key: HHH-2694
Type: Bug Bug
Status: Resolved Resolved
Resolution: Fixed
Priority: Major Major
Assignee: Chris Bredesen
Reporter: Chris Redekop
Votes: 5
Watchers: 5
Operations

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

create-drop with c3p0 causes SQLException

Created: 27/Jun/07 09:48 AM   Updated: 27/Oct/08 11:46 AM
Component/s: None
Affects Version/s: 3.2.4.sp1
Fix Version/s: 3.4, 3.2.x, 3.3.1

Time Tracking:
Not Specified

File Attachments: 1. GZip Archive c3p0Test.tar.gz (2 kb)

Environment: hibernate-entitymanager 3.2.1.ga, c3p0 0.9.0, and postgreSQL 8.1.8 or hsqldb 1.8.7


 Description  « Hide
In the attached test application, an EntityManagerFactory is created and then closed.

Closing the EMF causes line 801 of org.hibernate.impl.SessionFactoryImpl to call getConnectionProvider().close(), which eventually results in c3p0's PooledDataSource being closed.

Line 808 of org.hibernate.impl.SessionFactoryImpl the calls schemaExport.drop(), which attempts to acquire a connection from the data source and causes the following SQLException.

java.sql.SQLException: com.mchange.v2.c3p0.PoolBackedDataSource@fced4 [ connectionPoolDataSource -> com.mchange.v2.c3p0.WrapperConnectionPoolDataSource@9505f [ acquireIncrement -> 1, acquireRetryAttempts -> 30, acquireRetryDelay -> 1000, autoCommitOnClose -> false, automaticTestTable -> null, breakAfterAcquireFailure -> false, checkoutTimeout -> 0, connectionTesterClassName -> com.mchange.v2.c3p0.impl.DefaultConnectionTester, factoryClassLocation -> null, forceIgnoreUnresolvedTransactions -> false, identityToken -> 9505f, idleConnectionTestPeriod -> 100, initialPoolSize -> 10, maxIdleTime -> 100, maxPoolSize -> 100, maxStatements -> 0, maxStatementsPerConnection -> 0, minPoolSize -> 10, nestedDataSource -> com.mchange.v2.c3p0.DriverManagerDataSource@80cac9 [ description -> null, driverClass -> null, factoryClassLocation -> null, identityToken -> 80cac9, jdbcUrl -> jdbc:hsqldb:., properties -> {user=******, password=******, autocommit=true, release_mode=auto} ], preferredTestQuery -> null, propertyCycle -> 300, testConnectionOnCheckin -> false, testConnectionOnCheckout -> false, usesTraditionalReflectiveProxies -> false ], factoryClassLocation -> null, identityToken -> fced4, numHelperThreads -> 3 ] has been closed() -- you can no longer use it.

This exception is swallowed so it does not cause a test error, but it does appear in the console output.

 All   Comments   Work Log   Change History   FishEye      Sort Order: Ascending order - Click to sort in descending order
Emmanuel Bernard - 28/Jun/07 08:09 AM
Seems like a race condition on shutdown.

hugo - 05/Dec/07 04:03 AM
I do experiment the same problem:

Hibernate: 3.1.3
c3p0: 0.9.1
MySQL: 5.0.26-standard

INFO [main] org.hibernate.impl.SessionFactoryImpl () - 2007-12-04 18:52:55,342 - closing
INFO [main] org.hibernate.tool.hbm2ddl.SchemaExport () - 2007-12-04 18:52:55,357 - Running hbm2ddl schema export
INFO [main] org.hibernate.tool.hbm2ddl.SchemaExport () - 2007-12-04 18:52:55,363 - exporting generated schema to database
ERROR [main] org.hibernate.tool.hbm2ddl.SchemaExport () - 2007-12-04 18:52:55,386 - schema export unsuccessful
java.sql.SQLException: com.mchange.v2.c3p0.PoolBackedDataSource@7b071780 [ connectionPoolDataSource -> com.mchange.v2.c3p0.WrapperConnectionPoolDataSource@ca707eb9 [ acquireIncrement -> 1, acquireRetryAttempts -> 3, acquireRetryDelay -> 1000, autoCommitOnClose -> false, automaticTestTable -> C3P0TestTable, breakAfterAcquireFailure -> true, checkoutTimeout -> 0, connectionCustomizerClassName -> null, connectionTesterClassName -> com.mchange.v2.c3p0.impl.DefaultConnectionTester, debugUnreturnedConnectionStackTraces -> false, factoryClassLocation -> null, forceIgnoreUnresolvedTransactions -> false, identityToken -> z8kflt7q1a4scfrwaxp0b|6a1fbe, idleConnectionTestPeriod -> 600, initialPoolSize -> 1, maxAdministrativeTaskTime -> 0, maxConnectionAge -> 0, maxIdleTime -> 1200, maxIdleTimeExcessConnections -> 0, maxPoolSize -> 75, maxStatements -> 0, maxStatementsPerConnection -> 0, minPoolSize -> 1, nestedDataSource -> com.mchange.v2.c3p0.DriverManagerDataSource@d53284ee [ description -> null, driverClass -> null, factoryClassLocation -> null, identityToken -> z8kflt7q1a4scfrwaxp0b|1685be9, jdbcUrl -> jdbc:mysql://10.0.0.43:3306/ks_hugo, properties -> {user=******, password=******} ], preferredTestQuery -> null, propertyCycle -> 0, testConnectionOnCheckin -> false, testConnectionOnCheckout -> false, unreturnedConnectionTimeout -> 0, usesTraditionalReflectiveProxies -> false; userOverrides: {} ], dataSourceName -> null, factoryClassLocation -> null, identityToken -> z8kflt7q1a4scfrwaxp0b|f2db2d, numHelperThreads -> 3 ] has been closed() -- you can no longer use it.
        at com.mchange.v2.c3p0.impl.AbstractPoolBackedDataSource.assertCpds(AbstractPoolBackedDataSource.java:447)
        at com.mchange.v2.c3p0.impl.AbstractPoolBackedDataSource.getPoolManager(AbstractPoolBackedDataSource.java:459)
        at com.mchange.v2.c3p0.impl.AbstractPoolBackedDataSource.getConnection(AbstractPoolBackedDataSource.java:128)
        at org.hibernate.connection.C3P0ConnectionProvider.getConnection(C3P0ConnectionProvider.java:35)
        at org.hibernate.tool.hbm2ddl.SuppliedConnectionProviderConnectionHelper.prepare(SuppliedConnectionProviderConnectionHelper.java:27)
        at org.hibernate.tool.hbm2ddl.SchemaExport.execute(SchemaExport.java:178)
        at org.hibernate.tool.hbm2ddl.SchemaExport.drop(SchemaExport.java:141)
        at org.hibernate.impl.SessionFactoryImpl.close(SessionFactoryImpl.java:765)

Indeed, I do not have the problem anymore if I deactivate c3p0.

Does someone know if the fix is more likely to be found in future release of hibernate, or in future version of c3p0 ?

Sergey Proskurnya - 02/Apr/08 05:41 AM
This is definitely a Hibernate issue.
Looking into code:

SessionFactoryImpl.close() {
...
    try {
  settings.getConnectionProvider().close();
   }
   finally {
SessionFactoryObjectFactory.removeInstance(uuid, name, properties);
   }

   if ( settings.isAutoDropSchema() ) {
schemaExport.drop( false, true );
   }
}

The C3p0 (and proxool) connection providers are not able to create/give a new connection after calling ConnectionProvider.close() method
because they have honest close(), which release all occupied resources.
As opposed to them, the DatasourceConnectionProvider and "native" Hibernate DriverManagerConnectionProvider don't really close,
making possible to acquire a new Connection after calling ConnectionProvider .close() method.
The DatasourceConnectionProvider couldn't be closed by Hibernate, because there is no way to close external supplied DataSource,
because luck of close() method in javax.sql.DataSource interface.
And DriverManagerConnectionProvider simply does not have a "closed" state, thus, creating a new Connection on demand regadless
of calling DriverManagerConnectionProvider.close().

Experience the same bug with:
hibernate core 3.2.6 and c3p0 configured via Hibernate (not as external DataSource).

Chris Bredesen - 02/Apr/08 09:28 AM
Switching the order of the two operations (drop schema THEN close connection provider) seems to have no ill effects. I'm going to do a little more testing and look for Steve's blessing before I commit it.

Stephen Pickett - 29/Jul/08 11:21 AM
Hello, first of all I'm new here so I apologise in advance if I doing/say anything stupid :) Secondly, I'm getting the same error when closing the factory whether or not I use hbm2ddl (I used create, rather than create-drop). Have commented out my close factory part of code and it removes the problem. Whilst it's not essential that I close it, I'd rather do so.

Miro Bezjak - 17/Aug/08 03:47 PM
Although you already concluded that this is a hibernate issue and not c3p0 I would just like to add (so others can google it easily) that I can confirm this with dbcp and org.hibernate.connection.DBCPConnectionProvider.

Stack trace:
java.lang.NullPointerException
at org.hibernate.connection.DBCPConnectionProvider.logStatistics(DBCPConnectionProvider.java:247)
at org.hibernate.connection.DBCPConnectionProvider.getConnection(DBCPConnectionProvider.java:197)
at org.hibernate.tool.hbm2ddl.SuppliedConnectionProviderConnectionHelper.prepare(SuppliedConnectionProviderConnectionHelper.java:27)
at org.hibernate.tool.hbm2ddl.SchemaExport.execute(SchemaExport.java:180)
at org.hibernate.tool.hbm2ddl.SchemaExport.drop(SchemaExport.java:143)
at org.hibernate.impl.SessionFactoryImpl.close(SessionFactoryImpl.java:810)
at org.hibernate.ejb.EntityManagerFactoryImpl.close(EntityManagerFactoryImpl.java:46)
at hr.fer.zemris.vhdllab.dao.impl.EntityManagerUtil.shutdown(EntityManagerUtil.java:95)
at hr.fer.zemris.vhdllab.dao.impl.EntityManagerFactoryLifecycle.contextDestroyed(EntityManagerFactoryLifecycle.java:35)
at org.apache.catalina.core.StandardContext.listenerStop(StandardContext.java:3866)
at org.apache.catalina.core.StandardContext.stop(StandardContext.java:4500)
at org.apache.catalina.manager.ManagerServlet.undeploy(ManagerServlet.java:1351)
at org.apache.catalina.manager.HTMLManagerServlet.undeploy(HTMLManagerServlet.java:538)
at org.apache.catalina.manager.HTMLManagerServlet.doGet(HTMLManagerServlet.java:115)
at javax.servlet.http.HttpServlet.service(HttpServlet.java:690)
at javax.servlet.http.HttpServlet.service(HttpServlet.java:803)
at org.apache.catalina.core.ApplicationFilterChain.internalDoFilter(ApplicationFilterChain.java:290)
at org.apache.catalina.core.ApplicationFilterChain.doFilter(ApplicationFilterChain.java:206)
at org.apache.catalina.core.StandardWrapperValve.invoke(StandardWrapperValve.java:230)
at org.apache.catalina.core.StandardContextValve.invoke(StandardContextValve.java:175)
at org.apache.catalina.authenticator.AuthenticatorBase.invoke(AuthenticatorBase.java:525)
at org.apache.catalina.core.StandardHostValve.invoke(StandardHostValve.java:128)
at org.apache.catalina.valves.ErrorReportValve.invoke(ErrorReportValve.java:104)
at org.apache.catalina.valves.AccessLogValve.invoke(AccessLogValve.java:563)
at org.apache.catalina.core.StandardEngineValve.invoke(StandardEngineValve.java:109)
at org.apache.catalina.connector.CoyoteAdapter.service(CoyoteAdapter.java:261)
at org.apache.coyote.http11.Http11Processor.process(Http11Processor.java:844)
at org.apache.coyote.http11.Http11Protocol$Http11ConnectionHandler.process(Http11Protocol.java:581)
at org.apache.tomcat.util.net.JIoEndpoint$Worker.run(JIoEndpoint.java:447)
at java.lang.Thread.run(Thread.java:619)

Chris Bredesen - 18/Aug/08 09:54 PM
fixed in 3.2 / 3.3 / trunk

Stephen Pickett - 24/Oct/08 11:53 AM
Has this fix been confirmed? I've recently started getting this error again. Am still looking in to it to see if it's caused by something else that I've done but would be interested to see if anyone else still has the issue?

Chris Bredesen - 24/Oct/08 12:02 PM
What version did you see the issue resurface on? Best I can tell, 3.3.1 is the only version released with this fix.

Stephen Pickett - 27/Oct/08 06:16 AM
Apologies, I should've mentioned. I tested on Core 3.3.1, Annotations 3.4.0 GA and EntityManager 3.4.0 GA. I shall do some more testing today and try to determine whether this is my own programming error or if it definitely is the same problem as before.

Thanks.

Stephen Pickett - 27/Oct/08 11:46 AM
Ok, I've confirmed that this fix is definitely working and the error was my own fault. I realised that I was closing the EntityManagerFactory early hence C3P0 was having trouble reusing the connections. Apologies for bringing this up again, but at least it confirms that the fix works.

Thanks very much for the help.