-->
These old forums are deprecated now and set to read-only. We are waiting for you on our new forums!
More modern, Discourse-based and with GitHub/Google/Twitter authentication built-in.

View unanswered posts | View active topics


Board index » Hibernate & Java Persistence » Hibernate Users

All times are UTC - 5 hours [ DST ]


Forum locked This topic is locked, you cannot edit posts or make further replies.  Page 1 of 1
  [ 7 posts ] 
  Previous topic | Next topic 
Author Message
cybrocop
 Post subject: Hibernate does not seem to release conn. after exception
PostPosted: Mon Oct 18, 2010 6:53 pm 
Newbie

Joined: Mon Sep 27, 2010 11:05 am
Posts: 6
I'm using Hibernate 3.5.5-Final

I'm using SQLite for Unit Testing, which only supports 1 writing thread.

In my UT, I try to find an object that doesn't exist. This raises ObjectNotFoundException

After this, my DB connection does not seem to get released. Is this because tx.commit() doesn't run?

Here is my UT code:
Code:
    /**
     * Tests makeTransient() method.
     */
    @Test (expected=ObjectNotFoundException.class)
    public void testMakeTransient() {
        Transaction tx = session_.beginTransaction();
        BaseHibernateDAO m = new UserManager(session_);

        User u1 = new User("testMakeTransient-u1", "FN1", "LN1", 0);

        m.makePersistent(u1);

        Long id = u1.getId();

        m.makeTransient(u1);

        // This should throw org.hibernate.ObjectNotFoundException
        m.findById(id);

        tx.commit();
    }


Here is my cfg file:
Code:
<?xml version="1.0" encoding="UTF-8"?>
<!DOCTYPE hibernate-configuration PUBLIC "-//Hibernate/Hibernate Configuration DTD 3.0//EN" "http://hibernate.sourceforge.net/hibernate-configuration-3.0.dtd">
<hibernate-configuration>
  <session-factory>
    <!-- Database configuration related properties -->
    <property name="connection.driver_class">org.sqlite.JDBC</property>
    <property name="connection.url">jdbc:sqlite:test/test.db</property>
    <property name="connection.username"/>
    <property name="connection.password"/>
    <property name="dialect">ams.dal.dialect.SQLiteDialect</property>
    <!-- Other properties -->
    <property name="show_sql">false</property>
    <property name="format_sql">false</property>
    <property name="hibernate.use_sql_comments">false</property>
    <property name="hibernate.generate_statistics">false</property>
    <property name="hibernate.current_session_context_class">thread</property>
    <property name="hibernate.connection.pool_size">1</property>
    <!--<property name="hibernate.connection.release_mode">after_transaction</property>-->
    <property name="hibernate.connection.release_mode">on_close</property>
    <!-- Mapping files -->
    <!-- Now defined in code. -->
  </session-factory>
</hibernate-configuration>


Please note that for hibernate.connection.release_mode I have tried auto, on_close, and after_transaction all with the same results..

Here are logs for the particular problematic UT and the following UT. Note that because the connection is not closed, the following UT has "database locked" problems and doesn't have a consistent DB (I do a SchemaExport before each test and the SchemaExport fails because of this).
Code:
03:39:37,836 DEBUG ams.dal.util.DalTestFixtureBase  - ========================= BEGIN TEST: testMakeTransient =========================
03:39:37,836 INFO  org.hibernate.dialect.Dialect  - Using dialect: ams.dal.dialect.SQLiteDialect
03:39:37,837 DEBUG org.hibernate.cfg.Configuration  - processing extends queue
03:39:37,837 DEBUG org.hibernate.cfg.Configuration  - processing collection mappings
03:39:37,837 DEBUG org.hibernate.cfg.Configuration  - processing native query and ResultSetMapping mappings
03:39:37,837 DEBUG org.hibernate.cfg.Configuration  - processing association property references
03:39:37,837 DEBUG org.hibernate.cfg.Configuration  - processing foreign key constraints
03:39:37,837 DEBUG org.hibernate.cfg.Configuration  - resolving reference to class: ams.dal.model.ResourceUrl
03:39:37,837 DEBUG org.hibernate.cfg.Configuration  - resolving reference to class: ams.dal.model.User
03:39:37,837 DEBUG org.hibernate.cfg.Configuration  - resolving reference to class: ams.dal.model.Resource
03:39:37,837 DEBUG org.hibernate.cfg.Configuration  - resolving reference to class: ams.dal.model.User
03:39:37,837 DEBUG org.hibernate.cfg.Configuration  - resolving reference to class: ams.dal.model.Tag
03:39:37,837 DEBUG org.hibernate.cfg.Configuration  - resolving reference to class: ams.dal.model.Resource
03:39:37,837 DEBUG org.hibernate.id.factory.DefaultIdentifierGeneratorFactory  - Setting dialect [ams.dal.dialect.SQLiteDialect]
03:39:37,837 DEBUG org.hibernate.id.factory.DefaultIdentifierGeneratorFactory  - Setting dialect [ams.dal.dialect.SQLiteDialect]
03:39:37,838 DEBUG org.hibernate.id.factory.DefaultIdentifierGeneratorFactory  - Setting dialect [ams.dal.dialect.SQLiteDialect]
03:39:37,838 DEBUG org.hibernate.id.factory.DefaultIdentifierGeneratorFactory  - Setting dialect [ams.dal.dialect.SQLiteDialect]
03:39:37,838 DEBUG org.hibernate.id.factory.DefaultIdentifierGeneratorFactory  - Setting dialect [ams.dal.dialect.SQLiteDialect]
03:39:37,838 DEBUG org.hibernate.cfg.Configuration  - processing extends queue
03:39:37,838 DEBUG org.hibernate.cfg.Configuration  - processing collection mappings
03:39:37,838 DEBUG org.hibernate.cfg.Configuration  - processing native query and ResultSetMapping mappings
03:39:37,838 DEBUG org.hibernate.cfg.Configuration  - processing association property references
03:39:37,838 DEBUG org.hibernate.cfg.Configuration  - processing foreign key constraints
03:39:37,838 DEBUG org.hibernate.cfg.Configuration  - resolving reference to class: ams.dal.model.ResourceUrl
03:39:37,838 DEBUG org.hibernate.cfg.Configuration  - resolving reference to class: ams.dal.model.User
03:39:37,838 DEBUG org.hibernate.cfg.Configuration  - resolving reference to class: ams.dal.model.Resource
03:39:37,838 DEBUG org.hibernate.cfg.Configuration  - resolving reference to class: ams.dal.model.User
03:39:37,838 DEBUG org.hibernate.cfg.Configuration  - resolving reference to class: ams.dal.model.Tag
03:39:37,838 DEBUG org.hibernate.cfg.Configuration  - resolving reference to class: ams.dal.model.Resource
03:39:37,838 DEBUG org.hibernate.id.factory.DefaultIdentifierGeneratorFactory  - Setting dialect [ams.dal.dialect.SQLiteDialect]
03:39:37,838 DEBUG org.hibernate.id.factory.DefaultIdentifierGeneratorFactory  - Setting dialect [ams.dal.dialect.SQLiteDialect]
03:39:37,838 DEBUG org.hibernate.id.factory.DefaultIdentifierGeneratorFactory  - Setting dialect [ams.dal.dialect.SQLiteDialect]
03:39:37,838 DEBUG org.hibernate.id.factory.DefaultIdentifierGeneratorFactory  - Setting dialect [ams.dal.dialect.SQLiteDialect]
03:39:37,838 DEBUG org.hibernate.id.factory.DefaultIdentifierGeneratorFactory  - Setting dialect [ams.dal.dialect.SQLiteDialect]
03:39:37,839 DEBUG org.hibernate.id.factory.DefaultIdentifierGeneratorFactory  - Setting dialect [ams.dal.dialect.SQLiteDialect]
03:39:37,839 DEBUG org.hibernate.id.factory.DefaultIdentifierGeneratorFactory  - Setting dialect [ams.dal.dialect.SQLiteDialect]
03:39:37,839 DEBUG org.hibernate.id.factory.DefaultIdentifierGeneratorFactory  - Setting dialect [ams.dal.dialect.SQLiteDialect]
03:39:37,839 DEBUG org.hibernate.id.factory.DefaultIdentifierGeneratorFactory  - Setting dialect [ams.dal.dialect.SQLiteDialect]
03:39:37,839 DEBUG org.hibernate.id.factory.DefaultIdentifierGeneratorFactory  - Setting dialect [ams.dal.dialect.SQLiteDialect]
03:39:37,839 INFO  org.hibernate.tool.hbm2ddl.SchemaExport  - Running hbm2ddl schema export
03:39:37,839 DEBUG org.hibernate.tool.hbm2ddl.SchemaExport  - import file not found: /import.sql
03:39:37,839 INFO  org.hibernate.tool.hbm2ddl.SchemaExport  - exporting generated schema to database
03:39:37,839 INFO  org.hibernate.connection.DriverManagerConnectionProvider  - Using Hibernate built-in connection pool (not for production use!)
03:39:37,839 INFO  org.hibernate.connection.DriverManagerConnectionProvider  - Hibernate connection pool size: 1
03:39:37,839 INFO  org.hibernate.connection.DriverManagerConnectionProvider  - autocommit mode: false
03:39:37,839 INFO  org.hibernate.connection.DriverManagerConnectionProvider  - using driver: org.sqlite.JDBC at URL: jdbc:sqlite:test/test.db
03:39:37,840 INFO  org.hibernate.connection.DriverManagerConnectionProvider  - connection properties: {user=, password=, release_mode=on_close}
03:39:37,840 TRACE org.hibernate.connection.DriverManagerConnectionProvider  - total checked-out connections: 0
03:39:37,840 DEBUG org.hibernate.connection.DriverManagerConnectionProvider  - opening new JDBC connection
03:39:37,840 DEBUG org.hibernate.connection.DriverManagerConnectionProvider  - created connection to: jdbc:sqlite:test/test.db, Isolation Level: 8
03:39:37,840 DEBUG org.hibernate.tool.hbm2ddl.SchemaExport  - drop table if exists Feed
03:39:38,036 DEBUG org.hibernate.tool.hbm2ddl.SchemaExport  - drop table if exists Resource
03:39:38,221 DEBUG org.hibernate.tool.hbm2ddl.SchemaExport  - drop table if exists ResourceUrl
03:39:38,431 DEBUG org.hibernate.tool.hbm2ddl.SchemaExport  - drop table if exists Tag
03:39:38,641 DEBUG org.hibernate.tool.hbm2ddl.SchemaExport  - drop table if exists User
03:39:38,850 DEBUG org.hibernate.tool.hbm2ddl.SchemaExport  - drop table if exists [ResourceTag]
03:39:39,035 INFO  org.hibernate.tool.hbm2ddl.SchemaExport  - schema export complete
03:39:39,035 TRACE org.hibernate.connection.DriverManagerConnectionProvider  - returning connection to pool, pool size: 1
03:39:39,035 INFO  org.hibernate.connection.DriverManagerConnectionProvider  - cleaning up connection pool: jdbc:sqlite:test/test.db
03:39:39,035 INFO  org.hibernate.tool.hbm2ddl.SchemaExport  - Running hbm2ddl schema export
03:39:39,035 DEBUG org.hibernate.tool.hbm2ddl.SchemaExport  - import file not found: /import.sql
03:39:39,035 INFO  org.hibernate.tool.hbm2ddl.SchemaExport  - exporting generated schema to database
03:39:39,035 INFO  org.hibernate.connection.DriverManagerConnectionProvider  - Using Hibernate built-in connection pool (not for production use!)
03:39:39,035 INFO  org.hibernate.connection.DriverManagerConnectionProvider  - Hibernate connection pool size: 1
03:39:39,035 INFO  org.hibernate.connection.DriverManagerConnectionProvider  - autocommit mode: false
03:39:39,035 INFO  org.hibernate.connection.DriverManagerConnectionProvider  - using driver: org.sqlite.JDBC at URL: jdbc:sqlite:test/test.db
03:39:39,036 INFO  org.hibernate.connection.DriverManagerConnectionProvider  - connection properties: {user=, password=, release_mode=on_close}
03:39:39,036 TRACE org.hibernate.connection.DriverManagerConnectionProvider  - total checked-out connections: 0
03:39:39,036 DEBUG org.hibernate.connection.DriverManagerConnectionProvider  - opening new JDBC connection
03:39:39,036 DEBUG org.hibernate.connection.DriverManagerConnectionProvider  - created connection to: jdbc:sqlite:test/test.db, Isolation Level: 8
03:39:39,036 DEBUG org.hibernate.tool.hbm2ddl.SchemaExport  - drop table if exists Feed
03:39:39,036 DEBUG org.hibernate.tool.hbm2ddl.SchemaExport  - drop table if exists Resource
03:39:39,036 DEBUG org.hibernate.tool.hbm2ddl.SchemaExport  - drop table if exists ResourceUrl
03:39:39,036 DEBUG org.hibernate.tool.hbm2ddl.SchemaExport  - drop table if exists Tag
03:39:39,036 DEBUG org.hibernate.tool.hbm2ddl.SchemaExport  - drop table if exists User
03:39:39,036 DEBUG org.hibernate.tool.hbm2ddl.SchemaExport  - drop table if exists [ResourceTag]
03:39:39,036 DEBUG org.hibernate.tool.hbm2ddl.SchemaExport  - create table Feed (id  integer, displayName varchar, uniqueId varchar, description varchar, adCapacity integer, isActive integer, resourceUrlId bigint not null, primary key (id))
03:39:39,202 DEBUG org.hibernate.tool.hbm2ddl.SchemaExport  - create table Resource (id  integer, name varchar, description varchar, isActive integer, userId bigint, primary key (id))
03:39:39,348 DEBUG org.hibernate.tool.hbm2ddl.SchemaExport  - create table ResourceUrl (id  integer, url varchar, pageRank integer, pageRankTime timestamp, isActive integer, resourceId bigint, primary key (id))
03:39:39,523 DEBUG org.hibernate.tool.hbm2ddl.SchemaExport  - create table Tag (id  integer, name varchar, userId bigint, primary key (id))
03:39:39,698 DEBUG org.hibernate.tool.hbm2ddl.SchemaExport  - create table User (id  integer, accountName varchar, firstName varchar, lastName varchar, role integer, passwordHash varchar, isActive integer, primary key (id))
03:39:39,864 DEBUG org.hibernate.tool.hbm2ddl.SchemaExport  - create table [ResourceTag] (ResourceId bigint not null, TagId bigint not null)
03:39:40,031 INFO  org.hibernate.tool.hbm2ddl.SchemaExport  - schema export complete
03:39:40,031 TRACE org.hibernate.connection.DriverManagerConnectionProvider  - returning connection to pool, pool size: 1
03:39:40,031 INFO  org.hibernate.connection.DriverManagerConnectionProvider  - cleaning up connection pool: jdbc:sqlite:test/test.db
03:39:40,031 DEBUG org.hibernate.impl.SessionImpl  - opened session at timestamp: 12874415800
03:39:40,031 DEBUG org.hibernate.transaction.JDBCTransaction  - begin
03:39:40,031 DEBUG org.hibernate.jdbc.ConnectionManager  - opening JDBC connection
03:39:40,031 TRACE org.hibernate.connection.DriverManagerConnectionProvider  - total checked-out connections: 1
03:39:40,031 TRACE org.hibernate.connection.DriverManagerConnectionProvider  - using pooled JDBC connection, pool size: 0
03:39:40,031 DEBUG org.hibernate.transaction.JDBCTransaction  - current autocommit status: false
03:39:40,031 TRACE org.hibernate.jdbc.JDBCContext  - after transaction begin
03:39:40,031 TRACE org.hibernate.engine.IdentifierValue  - id unsaved-value: 0
03:39:40,031 TRACE org.hibernate.event.def.AbstractSaveEventListener  - transient instance of: ams.dal.model.User
03:39:40,031 TRACE org.hibernate.event.def.DefaultSaveOrUpdateEventListener  - saving transient instance
03:39:40,031 TRACE org.hibernate.event.def.AbstractSaveEventListener  - saving [ams.dal.model.User#<null>]
03:39:40,031 TRACE org.hibernate.event.def.AbstractSaveEventListener  - executing insertions
03:39:40,032 TRACE org.hibernate.engine.Cascade  - processing cascade ACTION_SAVE_UPDATE for: ams.dal.model.User
03:39:40,032 TRACE org.hibernate.engine.Cascade  - done processing cascade ACTION_SAVE_UPDATE for: ams.dal.model.User
03:39:40,032 DEBUG org.hibernate.event.def.AbstractSaveEventListener  - executing identity-insert immediately
03:39:40,032 TRACE org.hibernate.persister.entity.AbstractEntityPersister  - Inserting entity: ams.dal.model.User (native id)
03:39:40,032 DEBUG org.hibernate.jdbc.AbstractBatcher  - about to open PreparedStatement (open PreparedStatements: 0, globally: 0)
03:39:40,032 DEBUG org.hibernate.SQL  - insert into User (accountName, firstName, lastName, role, passwordHash, isActive) values (?, ?, ?, ?, ?, ?)
03:39:40,032 TRACE org.hibernate.jdbc.AbstractBatcher  - preparing statement
03:39:40,032 TRACE org.hibernate.persister.entity.AbstractEntityPersister  - Dehydrating entity: [ams.dal.model.User#<null>]
03:39:40,032 TRACE org.hibernate.type.StringType  - binding 'testMakeTransient-u1' to parameter: 1
03:39:40,032 TRACE org.hibernate.type.StringType  - binding 'FN1' to parameter: 2
03:39:40,032 TRACE org.hibernate.type.StringType  - binding 'LN1' to parameter: 3
03:39:40,032 TRACE org.hibernate.type.IntegerType  - binding '0' to parameter: 4
03:39:40,032 TRACE org.hibernate.type.StringType  - binding null to parameter: 5
03:39:40,032 TRACE org.hibernate.type.BooleanType  - binding 'false' to parameter: 6
03:39:40,032 DEBUG org.hibernate.jdbc.AbstractBatcher  - about to close PreparedStatement (open PreparedStatements: 1, globally: 1)
03:39:40,032 TRACE org.hibernate.jdbc.AbstractBatcher  - closing statement
03:39:40,032 DEBUG org.hibernate.jdbc.AbstractBatcher  - about to open PreparedStatement (open PreparedStatements: 0, globally: 0)
03:39:40,032 DEBUG org.hibernate.SQL  - select last_insert_rowid()
03:39:40,033 TRACE org.hibernate.jdbc.AbstractBatcher  - preparing statement
03:39:40,033 DEBUG org.hibernate.id.IdentifierGeneratorHelper  - Natively generated identity: 1
03:39:40,033 DEBUG org.hibernate.jdbc.AbstractBatcher  - about to close PreparedStatement (open PreparedStatements: 1, globally: 1)
03:39:40,033 TRACE org.hibernate.jdbc.AbstractBatcher  - closing statement
03:39:40,033 TRACE org.hibernate.engine.Cascade  - processing cascade ACTION_SAVE_UPDATE for: ams.dal.model.User
03:39:40,033 TRACE org.hibernate.engine.Cascade  - done processing cascade ACTION_SAVE_UPDATE for: ams.dal.model.User
03:39:40,034 TRACE org.hibernate.event.def.DefaultDeleteEventListener  - deleting a persistent instance
03:39:40,034 TRACE org.hibernate.event.def.DefaultDeleteEventListener  - deleting [ams.dal.model.User#1]
03:39:40,034 TRACE org.hibernate.impl.SessionImpl  - setting cache mode to: GET
03:39:40,034 TRACE org.hibernate.engine.Cascade  - processing cascade ACTION_DELETE for: ams.dal.model.User
03:39:40,034 TRACE org.hibernate.engine.Cascade  - done processing cascade ACTION_DELETE for: ams.dal.model.User
03:39:40,034 TRACE org.hibernate.impl.SessionImpl  - setting cache mode to: NORMAL
03:39:40,035 TRACE org.hibernate.impl.SessionImpl  - setting cache mode to: GET
03:39:40,035 TRACE org.hibernate.engine.Cascade  - processing cascade ACTION_DELETE for: ams.dal.model.User
03:39:40,035 TRACE org.hibernate.engine.Cascade  - done processing cascade ACTION_DELETE for: ams.dal.model.User
03:39:40,035 TRACE org.hibernate.impl.SessionImpl  - setting cache mode to: NORMAL
03:39:40,035 TRACE org.hibernate.event.def.DefaultLoadEventListener  - attempting to resolve: [ams.dal.model.User#1]
03:39:40,035 DEBUG org.hibernate.event.def.DefaultLoadEventListener  - load request found matching entity in context, but it is scheduled for removal; returning null
03:39:40,036 INFO  org.hibernate.event.def.DefaultLoadEventListener  - Error performing load command
org.hibernate.ObjectNotFoundException: No row with the given identifier exists: [ams.dal.model.User#1]
        at org.hibernate.impl.SessionFactoryImpl$2.handleEntityNotFound(SessionFactoryImpl.java:449)
        at org.hibernate.event.def.DefaultLoadEventListener.load(DefaultLoadEventListener.java:233)
        at org.hibernate.event.def.DefaultLoadEventListener.lockAndLoad(DefaultLoadEventListener.java:403)
        at org.hibernate.event.def.DefaultLoadEventListener.onLoad(DefaultLoadEventListener.java:155)
        at org.hibernate.impl.SessionImpl.fireLoad(SessionImpl.java:1080)
        at org.hibernate.impl.SessionImpl.load(SessionImpl.java:1051)
        at org.hibernate.impl.SessionImpl.load(SessionImpl.java:1040)
        at ams.dal.manager.BaseHibernateDAO.findById(BaseHibernateDAO.java:108)
        at ams.dal.manager.BaseHibernateDAO.findById(BaseHibernateDAO.java:93)
        at ams.dal.manager.BaseHibernateDAOTest.testMakeTransient(BaseHibernateDAOTest.java:125)
        at sun.reflect.NativeMethodAccessorImpl.invoke0(Native Method)
        at sun.reflect.NativeMethodAccessorImpl.invoke(NativeMethodAccessorImpl.java:57)
        at sun.reflect.DelegatingMethodAccessorImpl.invoke(DelegatingMethodAccessorImpl.java:43)
        at java.lang.reflect.Method.invoke(Method.java:616)
        at org.junit.runners.model.FrameworkMethod$1.runReflectiveCall(FrameworkMethod.java:44)
        at org.junit.internal.runners.model.ReflectiveCallable.run(ReflectiveCallable.java:15)
        at org.junit.runners.model.FrameworkMethod.invokeExplosively(FrameworkMethod.java:41)
        at org.junit.internal.runners.statements.InvokeMethod.evaluate(InvokeMethod.java:20)
        at org.junit.internal.runners.statements.ExpectException.evaluate(ExpectException.java:21)
        at org.junit.internal.runners.statements.RunBefores.evaluate(RunBefores.java:28)
        at org.junit.internal.runners.statements.RunAfters.evaluate(RunAfters.java:31)
        at org.junit.rules.TestWatchman$1.evaluate(TestWatchman.java:48)
        at org.junit.runners.BlockJUnit4ClassRunner.runNotIgnored(BlockJUnit4ClassRunner.java:79)
        at org.junit.runners.BlockJUnit4ClassRunner.runChild(BlockJUnit4ClassRunner.java:71)
        at org.junit.runners.BlockJUnit4ClassRunner.runChild(BlockJUnit4ClassRunner.java:49)
        at org.junit.runners.ParentRunner$3.run(ParentRunner.java:193)
        at org.junit.runners.ParentRunner$1.schedule(ParentRunner.java:52)
        at org.junit.runners.ParentRunner.runChildren(ParentRunner.java:191)
        at org.junit.runners.ParentRunner.access$000(ParentRunner.java:42)
        at org.junit.runners.ParentRunner$2.evaluate(ParentRunner.java:184)
        at org.junit.internal.runners.statements.RunBefores.evaluate(RunBefores.java:28)
        at org.junit.internal.runners.statements.RunAfters.evaluate(RunAfters.java:31)
        at org.junit.runners.ParentRunner.run(ParentRunner.java:236)
        at junit.framework.JUnit4TestAdapter.run(JUnit4TestAdapter.java:39)
        at org.apache.tools.ant.taskdefs.optional.junit.JUnitTestRunner.run(JUnitTestRunner.java:518)
        at org.apache.tools.ant.taskdefs.optional.junit.JUnitTestRunner.launch(JUnitTestRunner.java:1052)
        at org.apache.tools.ant.taskdefs.optional.junit.JUnitTestRunner.main(JUnitTestRunner.java:906)
03:39:40,038 DEBUG ams.dal.util.DalTestFixtureBase  - ========================= ENDING TEST: testMakeTransient =========================
03:39:40,038 TRACE org.hibernate.impl.SessionImpl  - closing session
03:39:40,038 TRACE org.hibernate.jdbc.ConnectionManager  - performing cleanup
03:39:40,038 DEBUG org.hibernate.jdbc.ConnectionManager  - releasing JDBC connection [ (open PreparedStatements: 0, globally: 0) (open ResultSets: 0, globally: 0)]
03:39:40,038 TRACE org.hibernate.connection.DriverManagerConnectionProvider  - returning connection to pool, pool size: 1
03:39:40,038 TRACE org.hibernate.impl.SessionFactoryImpl  - already closed
03:39:40,039 DEBUG ams.dal.util.DalTestFixtureBase  - ========================= BEGIN TEST: testFindAll =========================
03:39:40,039 INFO  org.hibernate.dialect.Dialect  - Using dialect: ams.dal.dialect.SQLiteDialect
03:39:40,039 DEBUG org.hibernate.cfg.Configuration  - processing extends queue
03:39:40,039 DEBUG org.hibernate.cfg.Configuration  - processing collection mappings
03:39:40,039 DEBUG org.hibernate.cfg.Configuration  - processing native query and ResultSetMapping mappings
03:39:40,039 DEBUG org.hibernate.cfg.Configuration  - processing association property references
03:39:40,039 DEBUG org.hibernate.cfg.Configuration  - processing foreign key constraints
03:39:40,039 DEBUG org.hibernate.cfg.Configuration  - resolving reference to class: ams.dal.model.ResourceUrl
03:39:40,039 DEBUG org.hibernate.cfg.Configuration  - resolving reference to class: ams.dal.model.User
03:39:40,039 DEBUG org.hibernate.cfg.Configuration  - resolving reference to class: ams.dal.model.Resource
03:39:40,039 DEBUG org.hibernate.cfg.Configuration  - resolving reference to class: ams.dal.model.User
03:39:40,039 DEBUG org.hibernate.cfg.Configuration  - resolving reference to class: ams.dal.model.Tag
03:39:40,039 DEBUG org.hibernate.cfg.Configuration  - resolving reference to class: ams.dal.model.Resource
03:39:40,039 DEBUG org.hibernate.id.factory.DefaultIdentifierGeneratorFactory  - Setting dialect [ams.dal.dialect.SQLiteDialect]
03:39:40,039 DEBUG org.hibernate.id.factory.DefaultIdentifierGeneratorFactory  - Setting dialect [ams.dal.dialect.SQLiteDialect]
03:39:40,040 DEBUG org.hibernate.id.factory.DefaultIdentifierGeneratorFactory  - Setting dialect [ams.dal.dialect.SQLiteDialect]
03:39:40,040 DEBUG org.hibernate.id.factory.DefaultIdentifierGeneratorFactory  - Setting dialect [ams.dal.dialect.SQLiteDialect]
03:39:40,040 DEBUG org.hibernate.id.factory.DefaultIdentifierGeneratorFactory  - Setting dialect [ams.dal.dialect.SQLiteDialect]
03:39:40,040 DEBUG org.hibernate.cfg.Configuration  - processing extends queue
03:39:40,040 DEBUG org.hibernate.cfg.Configuration  - processing collection mappings
03:39:40,040 DEBUG org.hibernate.cfg.Configuration  - processing native query and ResultSetMapping mappings
03:39:40,040 DEBUG org.hibernate.cfg.Configuration  - processing association property references
03:39:40,040 DEBUG org.hibernate.cfg.Configuration  - processing foreign key constraints
03:39:40,040 DEBUG org.hibernate.cfg.Configuration  - resolving reference to class: ams.dal.model.ResourceUrl
03:39:40,040 DEBUG org.hibernate.cfg.Configuration  - resolving reference to class: ams.dal.model.User
03:39:40,040 DEBUG org.hibernate.cfg.Configuration  - resolving reference to class: ams.dal.model.Resource
03:39:40,040 DEBUG org.hibernate.cfg.Configuration  - resolving reference to class: ams.dal.model.User
03:39:40,040 DEBUG org.hibernate.cfg.Configuration  - resolving reference to class: ams.dal.model.Tag
03:39:40,040 DEBUG org.hibernate.cfg.Configuration  - resolving reference to class: ams.dal.model.Resource
03:39:40,040 DEBUG org.hibernate.id.factory.DefaultIdentifierGeneratorFactory  - Setting dialect [ams.dal.dialect.SQLiteDialect]
03:39:40,040 DEBUG org.hibernate.id.factory.DefaultIdentifierGeneratorFactory  - Setting dialect [ams.dal.dialect.SQLiteDialect]
03:39:40,040 DEBUG org.hibernate.id.factory.DefaultIdentifierGeneratorFactory  - Setting dialect [ams.dal.dialect.SQLiteDialect]
03:39:40,040 DEBUG org.hibernate.id.factory.DefaultIdentifierGeneratorFactory  - Setting dialect [ams.dal.dialect.SQLiteDialect]
03:39:40,040 DEBUG org.hibernate.id.factory.DefaultIdentifierGeneratorFactory  - Setting dialect [ams.dal.dialect.SQLiteDialect]
03:39:40,041 DEBUG org.hibernate.id.factory.DefaultIdentifierGeneratorFactory  - Setting dialect [ams.dal.dialect.SQLiteDialect]
03:39:40,041 DEBUG org.hibernate.id.factory.DefaultIdentifierGeneratorFactory  - Setting dialect [ams.dal.dialect.SQLiteDialect]
03:39:40,041 DEBUG org.hibernate.id.factory.DefaultIdentifierGeneratorFactory  - Setting dialect [ams.dal.dialect.SQLiteDialect]
03:39:40,041 DEBUG org.hibernate.id.factory.DefaultIdentifierGeneratorFactory  - Setting dialect [ams.dal.dialect.SQLiteDialect]
03:39:40,041 DEBUG org.hibernate.id.factory.DefaultIdentifierGeneratorFactory  - Setting dialect [ams.dal.dialect.SQLiteDialect]
03:39:40,041 INFO  org.hibernate.tool.hbm2ddl.SchemaExport  - Running hbm2ddl schema export
03:39:40,041 DEBUG org.hibernate.tool.hbm2ddl.SchemaExport  - import file not found: /import.sql
03:39:40,041 INFO  org.hibernate.tool.hbm2ddl.SchemaExport  - exporting generated schema to database
03:39:40,041 INFO  org.hibernate.connection.DriverManagerConnectionProvider  - Using Hibernate built-in connection pool (not for production use!)
03:39:40,041 INFO  org.hibernate.connection.DriverManagerConnectionProvider  - Hibernate connection pool size: 1
03:39:40,041 INFO  org.hibernate.connection.DriverManagerConnectionProvider  - autocommit mode: false
03:39:40,042 INFO  org.hibernate.connection.DriverManagerConnectionProvider  - using driver: org.sqlite.JDBC at URL: jdbc:sqlite:test/test.db
03:39:40,042 INFO  org.hibernate.connection.DriverManagerConnectionProvider  - connection properties: {user=, password=, release_mode=on_close}
03:39:40,042 TRACE org.hibernate.connection.DriverManagerConnectionProvider  - total checked-out connections: 0
03:39:40,042 DEBUG org.hibernate.connection.DriverManagerConnectionProvider  - opening new JDBC connection
03:39:40,043 DEBUG org.hibernate.connection.DriverManagerConnectionProvider  - created connection to: jdbc:sqlite:test/test.db, Isolation Level: 8
03:39:40,043 DEBUG org.hibernate.tool.hbm2ddl.SchemaExport  - drop table if exists Feed
03:39:43,044 DEBUG org.hibernate.tool.hbm2ddl.SchemaExport  - Unsuccessful: drop table if exists Feed
03:39:43,044 DEBUG org.hibernate.tool.hbm2ddl.SchemaExport  - database locked
03:39:43,044 DEBUG org.hibernate.tool.hbm2ddl.SchemaExport  - drop table if exists Resource
03:39:46,044 DEBUG org.hibernate.tool.hbm2ddl.SchemaExport  - Unsuccessful: drop table if exists Resource
03:39:46,045 DEBUG org.hibernate.tool.hbm2ddl.SchemaExport  - database locked
03:39:46,045 DEBUG org.hibernate.tool.hbm2ddl.SchemaExport  - drop table if exists ResourceUrl
03:39:49,045 DEBUG org.hibernate.tool.hbm2ddl.SchemaExport  - Unsuccessful: drop table if exists ResourceUrl
03:39:49,045 DEBUG org.hibernate.tool.hbm2ddl.SchemaExport  - database locked
03:39:49,045 DEBUG org.hibernate.tool.hbm2ddl.SchemaExport  - drop table if exists Tag
03:39:52,046 DEBUG org.hibernate.tool.hbm2ddl.SchemaExport  - Unsuccessful: drop table if exists Tag
03:39:52,046 DEBUG org.hibernate.tool.hbm2ddl.SchemaExport  - database locked
03:39:52,046 DEBUG org.hibernate.tool.hbm2ddl.SchemaExport  - drop table if exists User
03:39:55,046 DEBUG org.hibernate.tool.hbm2ddl.SchemaExport  - Unsuccessful: drop table if exists User
03:39:55,046 DEBUG org.hibernate.tool.hbm2ddl.SchemaExport  - database locked
03:39:55,046 DEBUG org.hibernate.tool.hbm2ddl.SchemaExport  - drop table if exists [ResourceTag]
03:39:58,047 DEBUG org.hibernate.tool.hbm2ddl.SchemaExport  - Unsuccessful: drop table if exists [ResourceTag]
03:39:58,047 DEBUG org.hibernate.tool.hbm2ddl.SchemaExport  - database locked
03:39:58,047 INFO  org.hibernate.tool.hbm2ddl.SchemaExport  - schema export complete
03:39:58,047 TRACE org.hibernate.connection.DriverManagerConnectionProvider  - returning connection to pool, pool size: 1
03:39:58,047 INFO  org.hibernate.connection.DriverManagerConnectionProvider  - cleaning up connection pool: jdbc:sqlite:test/test.db
03:39:58,047 INFO  org.hibernate.tool.hbm2ddl.SchemaExport  - Running hbm2ddl schema export
03:39:58,048 DEBUG org.hibernate.tool.hbm2ddl.SchemaExport  - import file not found: /import.sql
03:39:58,048 INFO  org.hibernate.tool.hbm2ddl.SchemaExport  - exporting generated schema to database
03:39:58,048 INFO  org.hibernate.connection.DriverManagerConnectionProvider  - Using Hibernate built-in connection pool (not for production use!)
03:39:58,048 INFO  org.hibernate.connection.DriverManagerConnectionProvider  - Hibernate connection pool size: 1
03:39:58,048 INFO  org.hibernate.connection.DriverManagerConnectionProvider  - autocommit mode: false
03:39:58,048 INFO  org.hibernate.connection.DriverManagerConnectionProvider  - using driver: org.sqlite.JDBC at URL: jdbc:sqlite:test/test.db
03:39:58,048 INFO  org.hibernate.connection.DriverManagerConnectionProvider  - connection properties: {user=, password=, release_mode=on_close}
03:39:58,048 TRACE org.hibernate.connection.DriverManagerConnectionProvider  - total checked-out connections: 0
03:39:58,048 DEBUG org.hibernate.connection.DriverManagerConnectionProvider  - opening new JDBC connection
03:39:58,048 DEBUG org.hibernate.connection.DriverManagerConnectionProvider  - created connection to: jdbc:sqlite:test/test.db, Isolation Level: 8
03:39:58,048 DEBUG org.hibernate.tool.hbm2ddl.SchemaExport  - drop table if exists Feed
03:40:01,049 DEBUG org.hibernate.tool.hbm2ddl.SchemaExport  - Unsuccessful: drop table if exists Feed
03:40:01,049 DEBUG org.hibernate.tool.hbm2ddl.SchemaExport  - database locked
03:40:01,049 DEBUG org.hibernate.tool.hbm2ddl.SchemaExport  - drop table if exists Resource
03:40:04,050 DEBUG org.hibernate.tool.hbm2ddl.SchemaExport  - Unsuccessful: drop table if exists Resource
03:40:04,050 DEBUG org.hibernate.tool.hbm2ddl.SchemaExport  - database locked
03:40:04,050 DEBUG org.hibernate.tool.hbm2ddl.SchemaExport  - drop table if exists ResourceUrl
03:40:07,050 DEBUG org.hibernate.tool.hbm2ddl.SchemaExport  - Unsuccessful: drop table if exists ResourceUrl
03:40:07,050 DEBUG org.hibernate.tool.hbm2ddl.SchemaExport  - database locked
03:40:07,050 DEBUG org.hibernate.tool.hbm2ddl.SchemaExport  - drop table if exists Tag
03:40:10,051 DEBUG org.hibernate.tool.hbm2ddl.SchemaExport  - Unsuccessful: drop table if exists Tag
03:40:10,051 DEBUG org.hibernate.tool.hbm2ddl.SchemaExport  - database locked
03:40:10,051 DEBUG org.hibernate.tool.hbm2ddl.SchemaExport  - drop table if exists User
03:40:13,051 DEBUG org.hibernate.tool.hbm2ddl.SchemaExport  - Unsuccessful: drop table if exists User
03:40:13,051 DEBUG org.hibernate.tool.hbm2ddl.SchemaExport  - database locked
03:40:13,051 DEBUG org.hibernate.tool.hbm2ddl.SchemaExport  - drop table if exists [ResourceTag]
03:40:16,052 DEBUG org.hibernate.tool.hbm2ddl.SchemaExport  - Unsuccessful: drop table if exists [ResourceTag]
03:40:16,052 DEBUG org.hibernate.tool.hbm2ddl.SchemaExport  - database locked
03:40:16,052 DEBUG org.hibernate.tool.hbm2ddl.SchemaExport  - create table Feed (id  integer, displayName varchar, uniqueId varchar, description varchar, adCapacity integer, isActive integer, resourceUrlId bigint not null, primary key (id))
03:40:16,052 ERROR org.hibernate.tool.hbm2ddl.SchemaExport  - Unsuccessful: create table Feed (id  integer, displayName varchar, uniqueId varchar, description varchar, adCapacity integer, isActive integer, resourceUrlId bigint not null, primary key (id))
03:40:16,052 ERROR org.hibernate.tool.hbm2ddl.SchemaExport  - table Feed already exists
03:40:16,052 DEBUG org.hibernate.tool.hbm2ddl.SchemaExport  - create table Resource (id  integer, name varchar, description varchar, isActive integer, userId bigint, primary key (id))
03:40:16,052 ERROR org.hibernate.tool.hbm2ddl.SchemaExport  - Unsuccessful: create table Resource (id  integer, name varchar, description varchar, isActive integer, userId bigint, primary key (id))
03:40:16,052 ERROR org.hibernate.tool.hbm2ddl.SchemaExport  - table Resource already exists
03:40:16,052 DEBUG org.hibernate.tool.hbm2ddl.SchemaExport  - create table ResourceUrl (id  integer, url varchar, pageRank integer, pageRankTime timestamp, isActive integer, resourceId bigint, primary key (id))
03:40:16,052 ERROR org.hibernate.tool.hbm2ddl.SchemaExport  - Unsuccessful: create table ResourceUrl (id  integer, url varchar, pageRank integer, pageRankTime timestamp, isActive integer, resourceId bigint, primary key (id))
03:40:16,052 ERROR org.hibernate.tool.hbm2ddl.SchemaExport  - table ResourceUrl already exists
03:40:16,052 DEBUG org.hibernate.tool.hbm2ddl.SchemaExport  - create table Tag (id  integer, name varchar, userId bigint, primary key (id))
03:40:16,052 ERROR org.hibernate.tool.hbm2ddl.SchemaExport  - Unsuccessful: create table Tag (id  integer, name varchar, userId bigint, primary key (id))
03:40:16,053 ERROR org.hibernate.tool.hbm2ddl.SchemaExport  - table Tag already exists
03:40:16,053 DEBUG org.hibernate.tool.hbm2ddl.SchemaExport  - create table User (id  integer, accountName varchar, firstName varchar, lastName varchar, role integer, passwordHash varchar, isActive integer, primary key (id))
03:40:16,053 ERROR org.hibernate.tool.hbm2ddl.SchemaExport  - Unsuccessful: create table User (id  integer, accountName varchar, firstName varchar, lastName varchar, role integer, passwordHash varchar, isActive integer, primary key (id))
03:40:16,053 ERROR org.hibernate.tool.hbm2ddl.SchemaExport  - table User already exists
03:40:16,053 DEBUG org.hibernate.tool.hbm2ddl.SchemaExport  - create table [ResourceTag] (ResourceId bigint not null, TagId bigint not null)
03:40:16,053 ERROR org.hibernate.tool.hbm2ddl.SchemaExport  - Unsuccessful: create table [ResourceTag] (ResourceId bigint not null, TagId bigint not null)
03:40:16,053 ERROR org.hibernate.tool.hbm2ddl.SchemaExport  - table [ResourceTag] already exists
03:40:16,053 INFO  org.hibernate.tool.hbm2ddl.SchemaExport  - schema export complete
03:40:16,053 TRACE org.hibernate.connection.DriverManagerConnectionProvider  - returning connection to pool, pool size: 1
03:40:16,053 INFO  org.hibernate.connection.DriverManagerConnectionProvider  - cleaning up connection pool: jdbc:sqlite:test/test.db
03:40:16,053 DEBUG org.hibernate.impl.SessionImpl  - opened session at timestamp: 12874416160
03:40:16,053 DEBUG org.hibernate.transaction.JDBCTransaction  - begin
03:40:16,053 DEBUG org.hibernate.jdbc.ConnectionManager  - opening JDBC connection
03:40:16,053 TRACE org.hibernate.connection.DriverManagerConnectionProvider  - total checked-out connections: 1
03:40:16,053 TRACE org.hibernate.connection.DriverManagerConnectionProvider  - using pooled JDBC connection, pool size: 0
03:40:16,053 DEBUG org.hibernate.transaction.JDBCTransaction  - current autocommit status: false
03:40:16,053 TRACE org.hibernate.jdbc.JDBCContext  - after transaction begin
03:40:16,053 TRACE org.hibernate.event.def.DefaultSaveOrUpdateEventListener  - saving transient instance
03:40:16,053 TRACE org.hibernate.event.def.AbstractSaveEventListener  - saving [ams.dal.model.User#<null>]
03:40:16,053 TRACE org.hibernate.event.def.AbstractSaveEventListener  - executing insertions
03:40:16,053 TRACE org.hibernate.engine.Cascade  - processing cascade ACTION_SAVE_UPDATE for: ams.dal.model.User
03:40:16,053 TRACE org.hibernate.engine.Cascade  - done processing cascade ACTION_SAVE_UPDATE for: ams.dal.model.User
03:40:16,054 DEBUG org.hibernate.event.def.AbstractSaveEventListener  - executing identity-insert immediately
03:40:16,054 TRACE org.hibernate.persister.entity.AbstractEntityPersister  - Inserting entity: ams.dal.model.User (native id)
03:40:16,054 DEBUG org.hibernate.jdbc.AbstractBatcher  - about to open PreparedStatement (open PreparedStatements: 0, globally: 0)
03:40:16,054 DEBUG org.hibernate.SQL  - insert into User (accountName, firstName, lastName, role, passwordHash, isActive) values (?, ?, ?, ?, ?, ?)
03:40:16,054 TRACE org.hibernate.jdbc.AbstractBatcher  - preparing statement
03:40:16,054 TRACE org.hibernate.persister.entity.AbstractEntityPersister  - Dehydrating entity: [ams.dal.model.User#<null>]
03:40:16,054 TRACE org.hibernate.type.StringType  - binding 'testFindAll-u1' to parameter: 1
03:40:16,054 TRACE org.hibernate.type.StringType  - binding 'FN1' to parameter: 2
03:40:16,054 TRACE org.hibernate.type.StringType  - binding 'LN1' to parameter: 3
03:40:16,054 TRACE org.hibernate.type.IntegerType  - binding '0' to parameter: 4
03:40:16,054 TRACE org.hibernate.type.StringType  - binding null to parameter: 5
03:40:16,054 TRACE org.hibernate.type.BooleanType  - binding 'false' to parameter: 6
03:40:16,054 DEBUG org.hibernate.jdbc.AbstractBatcher  - about to close PreparedStatement (open PreparedStatements: 1, globally: 1)
03:40:16,054 TRACE org.hibernate.jdbc.AbstractBatcher  - closing statement
03:40:16,054 DEBUG org.hibernate.jdbc.AbstractBatcher  - about to open PreparedStatement (open PreparedStatements: 0, globally: 0)
03:40:16,054 DEBUG org.hibernate.SQL  - select last_insert_rowid()
03:40:16,054 TRACE org.hibernate.jdbc.AbstractBatcher  - preparing statement
03:40:16,054 DEBUG org.hibernate.id.IdentifierGeneratorHelper  - Natively generated identity: 2
03:40:16,054 DEBUG org.hibernate.jdbc.AbstractBatcher  - about to close PreparedStatement (open PreparedStatements: 1, globally: 1)
03:40:16,054 TRACE org.hibernate.jdbc.AbstractBatcher  - closing statement
03:40:16,054 TRACE org.hibernate.engine.Cascade  - processing cascade ACTION_SAVE_UPDATE for: ams.dal.model.User
03:40:16,054 TRACE org.hibernate.engine.Cascade  - done processing cascade ACTION_SAVE_UPDATE for: ams.dal.model.User
03:40:16,054 TRACE org.hibernate.event.def.DefaultSaveOrUpdateEventListener  - saving transient instance
03:40:16,054 TRACE org.hibernate.event.def.AbstractSaveEventListener  - saving [ams.dal.model.User#<null>]
03:40:16,054 TRACE org.hibernate.event.def.AbstractSaveEventListener  - executing insertions
03:40:16,055 TRACE org.hibernate.engine.Cascade  - processing cascade ACTION_SAVE_UPDATE for: ams.dal.model.User
03:40:16,055 TRACE org.hibernate.engine.Cascade  - done processing cascade ACTION_SAVE_UPDATE for: ams.dal.model.User
03:40:16,055 DEBUG org.hibernate.event.def.AbstractSaveEventListener  - executing identity-insert immediately
03:40:16,055 TRACE org.hibernate.persister.entity.AbstractEntityPersister  - Inserting entity: ams.dal.model.User (native id)
03:40:16,056 DEBUG org.hibernate.jdbc.AbstractBatcher  - about to open PreparedStatement (open PreparedStatements: 0, globally: 0)
03:40:16,056 DEBUG org.hibernate.SQL  - insert into User (accountName, firstName, lastName, role, passwordHash, isActive) values (?, ?, ?, ?, ?, ?)
03:40:16,056 TRACE org.hibernate.jdbc.AbstractBatcher  - preparing statement
03:40:16,056 TRACE org.hibernate.persister.entity.AbstractEntityPersister  - Dehydrating entity: [ams.dal.model.User#<null>]
03:40:16,056 TRACE org.hibernate.type.StringType  - binding 'testFindAll-u2' to parameter: 1
03:40:16,056 TRACE org.hibernate.type.StringType  - binding 'FN2' to parameter: 2
03:40:16,056 TRACE org.hibernate.type.StringType  - binding 'LN2' to parameter: 3
03:40:16,056 TRACE org.hibernate.type.IntegerType  - binding '0' to parameter: 4
03:40:16,056 TRACE org.hibernate.type.StringType  - binding null to parameter: 5
03:40:16,056 TRACE org.hibernate.type.BooleanType  - binding 'false' to parameter: 6
03:40:16,056 DEBUG org.hibernate.jdbc.AbstractBatcher  - about to close PreparedStatement (open PreparedStatements: 1, globally: 1)
03:40:16,056 TRACE org.hibernate.jdbc.AbstractBatcher  - closing statement
03:40:16,056 DEBUG org.hibernate.jdbc.AbstractBatcher  - about to open PreparedStatement (open PreparedStatements: 0, globally: 0)
03:40:16,056 DEBUG org.hibernate.SQL  - select last_insert_rowid()
03:40:16,056 TRACE org.hibernate.jdbc.AbstractBatcher  - preparing statement
03:40:16,056 DEBUG org.hibernate.id.IdentifierGeneratorHelper  - Natively generated identity: 3
03:40:16,056 DEBUG org.hibernate.jdbc.AbstractBatcher  - about to close PreparedStatement (open PreparedStatements: 1, globally: 1)
03:40:16,056 TRACE org.hibernate.jdbc.AbstractBatcher  - closing statement
03:40:16,056 TRACE org.hibernate.engine.Cascade  - processing cascade ACTION_SAVE_UPDATE for: ams.dal.model.User
03:40:16,056 TRACE org.hibernate.engine.Cascade  - done processing cascade ACTION_SAVE_UPDATE for: ams.dal.model.User
03:40:16,056 TRACE org.hibernate.event.def.AbstractFlushingEventListener  - flushing session
03:40:16,056 DEBUG org.hibernate.event.def.AbstractFlushingEventListener  - processing flush-time cascades
03:40:16,056 TRACE org.hibernate.engine.Cascade  - processing cascade ACTION_SAVE_UPDATE for: ams.dal.model.User
03:40:16,056 TRACE org.hibernate.engine.Cascade  - done processing cascade ACTION_SAVE_UPDATE for: ams.dal.model.User
03:40:16,056 TRACE org.hibernate.engine.Cascade  - processing cascade ACTION_SAVE_UPDATE for: ams.dal.model.User
03:40:16,056 TRACE org.hibernate.engine.Cascade  - done processing cascade ACTION_SAVE_UPDATE for: ams.dal.model.User
03:40:16,056 DEBUG org.hibernate.event.def.AbstractFlushingEventListener  - dirty checking collections
03:40:16,057 TRACE org.hibernate.event.def.AbstractFlushingEventListener  - Flushing entities and processing referenced collections
03:40:16,057 TRACE org.hibernate.event.def.AbstractFlushingEventListener  - Processing unreferenced collections
03:40:16,057 TRACE org.hibernate.event.def.AbstractFlushingEventListener  - Scheduling collection removes/(re)creates/updates
03:40:16,057 DEBUG org.hibernate.event.def.AbstractFlushingEventListener  - Flushed: 0 insertions, 0 updates, 0 deletions to 2 objects
03:40:16,057 DEBUG org.hibernate.event.def.AbstractFlushingEventListener  - Flushed: 0 (re)creations, 0 updates, 0 removals to 0 collections
03:40:16,057 DEBUG org.hibernate.pretty.Printer  - listing entities:
03:40:16,057 DEBUG org.hibernate.pretty.Printer  - ams.dal.model.User{isActive=false, id=2, Tags=null, lastName=LN1, accountName=testFindAll-u1, role=0, firstName=FN1, passwordHash=null, Resources=null}
03:40:16,057 DEBUG org.hibernate.pretty.Printer  - ams.dal.model.User{isActive=false, id=3, Tags=null, lastName=LN2, accountName=testFindAll-u2, role=0, firstName=FN2, passwordHash=null, Resources=null}
03:40:16,057 TRACE org.hibernate.event.def.AbstractFlushingEventListener  - executing flush
03:40:16,057 TRACE org.hibernate.jdbc.ConnectionManager  - registering flush begin
03:40:16,057 TRACE org.hibernate.jdbc.ConnectionManager  - registering flush end
03:40:16,057 TRACE org.hibernate.event.def.AbstractFlushingEventListener  - post flush
03:40:16,063 DEBUG org.hibernate.jdbc.AbstractBatcher  - about to open PreparedStatement (open PreparedStatements: 0, globally: 0)
03:40:16,063 DEBUG org.hibernate.SQL  - select this_.id as id0_0_, this_.accountName as accountN2_0_0_, this_.firstName as firstName0_0_, this_.lastName as lastName0_0_, this_.role as role0_0_, this_.passwordHash as password6_0_0_, this_.isActive as isActive0_0_ from User this_
03:40:16,063 TRACE org.hibernate.jdbc.AbstractBatcher  - preparing statement
03:40:16,063 TRACE org.hibernate.loader.Loader  - Bound [1] parameters total
03:40:16,063 DEBUG org.hibernate.jdbc.AbstractBatcher  - about to open ResultSet (open ResultSets: 0, globally: 0)
03:40:16,063 TRACE org.hibernate.loader.Loader  - processing result set
03:40:16,064 DEBUG org.hibernate.loader.Loader  - result set row: 0
03:40:16,064 TRACE org.hibernate.type.LongType  - returning '1' as column: id0_0_
03:40:16,064 DEBUG org.hibernate.loader.Loader  - result row: EntityKey[ams.dal.model.User#1]
03:40:16,064 TRACE org.hibernate.loader.Loader  - Initializing object from ResultSet: [ams.dal.model.User#1]
03:40:16,065 TRACE org.hibernate.persister.entity.AbstractEntityPersister  - Hydrating entity: [ams.dal.model.User#1]
03:40:16,065 TRACE org.hibernate.type.StringType  - returning 'testMakeTransient-u1' as column: accountN2_0_0_
03:40:16,065 TRACE org.hibernate.type.StringType  - returning 'FN1' as column: firstName0_0_
03:40:16,065 TRACE org.hibernate.type.StringType  - returning 'LN1' as column: lastName0_0_
03:40:16,065 TRACE org.hibernate.type.IntegerType  - returning '0' as column: role0_0_
03:40:16,065 TRACE org.hibernate.type.StringType  - returning null as column: password6_0_0_
03:40:16,066 TRACE org.hibernate.type.BooleanType  - returning 'false' as column: isActive0_0_
03:40:16,066 DEBUG org.hibernate.loader.Loader  - result set row: 1
03:40:16,066 TRACE org.hibernate.type.LongType  - returning '2' as column: id0_0_
03:40:16,067 DEBUG org.hibernate.loader.Loader  - result row: EntityKey[ams.dal.model.User#2]
03:40:16,067 TRACE org.hibernate.loader.Loader  - Initializing object from ResultSet: [ams.dal.model.User#2]
03:40:16,067 TRACE org.hibernate.persister.entity.AbstractEntityPersister  - Hydrating entity: [ams.dal.model.User#2]
03:40:16,067 TRACE org.hibernate.type.StringType  - returning 'testFindAll-u1' as column: accountN2_0_0_
03:40:16,067 TRACE org.hibernate.type.StringType  - returning 'FN1' as column: firstName0_0_
03:40:16,067 TRACE org.hibernate.type.StringType  - returning 'LN1' as column: lastName0_0_
03:40:16,067 TRACE org.hibernate.type.IntegerType  - returning '0' as column: role0_0_
03:40:16,068 TRACE org.hibernate.type.StringType  - returning null as column: password6_0_0_
03:40:16,068 TRACE org.hibernate.type.BooleanType  - returning 'false' as column: isActive0_0_
03:40:16,068 DEBUG org.hibernate.loader.Loader  - result set row: 2
03:40:16,068 TRACE org.hibernate.type.LongType  - returning '3' as column: id0_0_
03:40:16,068 DEBUG org.hibernate.loader.Loader  - result row: EntityKey[ams.dal.model.User#3]
03:40:16,068 TRACE org.hibernate.loader.Loader  - Initializing object from ResultSet: [ams.dal.model.User#3]
03:40:16,068 TRACE org.hibernate.persister.entity.AbstractEntityPersister  - Hydrating entity: [ams.dal.model.User#3]
03:40:16,068 TRACE org.hibernate.type.StringType  - returning 'testFindAll-u2' as column: accountN2_0_0_
03:40:16,068 TRACE org.hibernate.type.StringType  - returning 'FN2' as column: firstName0_0_
03:40:16,068 TRACE org.hibernate.type.StringType  - returning 'LN2' as column: lastName0_0_
03:40:16,068 TRACE org.hibernate.type.IntegerType  - returning '0' as column: role0_0_
03:40:16,068 TRACE org.hibernate.type.StringType  - returning null as column: password6_0_0_
03:40:16,069 TRACE org.hibernate.type.BooleanType  - returning 'false' as column: isActive0_0_
03:40:16,069 TRACE org.hibernate.loader.Loader  - done processing result set (3 rows)
03:40:16,069 DEBUG org.hibernate.jdbc.AbstractBatcher  - about to close ResultSet (open ResultSets: 1, globally: 1)
03:40:16,069 DEBUG org.hibernate.jdbc.AbstractBatcher  - about to close PreparedStatement (open PreparedStatements: 1, globally: 1)
03:40:16,069 TRACE org.hibernate.jdbc.AbstractBatcher  - closing statement
03:40:16,070 TRACE org.hibernate.loader.Loader  - total objects hydrated: 3
03:40:16,070 DEBUG org.hibernate.engine.TwoPhaseLoad  - resolving associations for [ams.dal.model.User#1]
03:40:16,072 TRACE org.hibernate.engine.loading.LoadContexts  - creating collection wrapper:[ams.dal.model.User.Resources#1]
03:40:16,075 TRACE org.hibernate.engine.loading.LoadContexts  - creating collection wrapper:[ams.dal.model.User.Tags#1]
03:40:16,076 DEBUG org.hibernate.engine.TwoPhaseLoad  - done materializing entity [ams.dal.model.User#1]
03:40:16,076 DEBUG org.hibernate.engine.TwoPhaseLoad  - resolving associations for [ams.dal.model.User#2]
03:40:16,076 TRACE org.hibernate.engine.loading.LoadContexts  - creating collection wrapper:[ams.dal.model.User.Resources#2]
03:40:16,076 TRACE org.hibernate.engine.loading.LoadContexts  - creating collection wrapper:[ams.dal.model.User.Tags#2]
03:40:16,076 DEBUG org.hibernate.engine.TwoPhaseLoad  - done materializing entity [ams.dal.model.User#2]
03:40:16,076 DEBUG org.hibernate.engine.TwoPhaseLoad  - resolving associations for [ams.dal.model.User#3]
03:40:16,076 TRACE org.hibernate.engine.loading.LoadContexts  - creating collection wrapper:[ams.dal.model.User.Resources#3]
03:40:16,076 TRACE org.hibernate.engine.loading.LoadContexts  - creating collection wrapper:[ams.dal.model.User.Tags#3]
03:40:16,076 DEBUG org.hibernate.engine.TwoPhaseLoad  - done materializing entity [ams.dal.model.User#3]
03:40:16,076 DEBUG org.hibernate.engine.StatefulPersistenceContext  - initializing non-lazy collections
FILOSOSOS: testMakeTransient-u1
FILOSOSOS: testFindAll-u1
FILOSOSOS: testFindAll-u2
03:40:16,077 DEBUG ams.dal.util.DalTestFixtureBase  - ========================= ENDING TEST: testFindAll =========================
03:40:16,077 TRACE org.hibernate.impl.SessionImpl  - closing session
03:40:16,077 TRACE org.hibernate.jdbc.ConnectionManager  - performing cleanup
03:40:16,077 DEBUG org.hibernate.jdbc.ConnectionManager  - releasing JDBC connection [ (open PreparedStatements: 0, globally: 0) (open ResultSets: 0, globally: 0)]
03:40:16,077 TRACE org.hibernate.connection.DriverManagerConnectionProvider  - returning connection to pool, pool size: 1
03:40:16,077 TRACE org.hibernate.impl.SessionFactoryImpl  - already closed
Top
 Profile  
 
cybrocop
 Post subject: Re: Hibernate does not seem to release conn. after exception
PostPosted: Tue Oct 19, 2010 7:42 am 
Newbie

Joined: Mon Sep 27, 2010 11:05 am
Posts: 6
Anything I can do to help diagnose this better?

I forgot to add that after each UT, I close the session as is visible in the logs. I would expect that if I set the release mode to "on_close", then that would take care of things, but its not.
Top
 Profile  
 
r
 Post subject: Re: Hibernate does not seem to release conn. after exception
PostPosted: Tue Oct 19, 2010 9:35 am 
Senior
Senior

Joined: Fri Oct 08, 2010 8:44 am
Posts: 130
cybrocop wrote:
Anything I can do to help diagnose this better?

I forgot to add that after each UT, I close the session as is visible in the logs. I would expect that if I set the release mode to "on_close", then that would take care of things, but its not.


My quick guess is that connection was indeed released and it is just sitting in pool waiting for another hibernate query. Did you try the same test without that "m.findById(id);" line? I guess you will get exactly the same result :)
Top
 Profile  
 
cybrocop
 Post subject: Re: Hibernate does not seem to release conn. after exception
PostPosted: Tue Oct 19, 2010 9:46 am 
Newbie

Joined: Mon Sep 27, 2010 11:05 am
Posts: 6
Quote:
Did you try the same test without that "m.findById(id);" line? I guess you will get exactly the same result :)


Actually, m.findByID() is what is raising the exception. Without it the UT works fine (albeit it doesn't do the testing that I want) :)

--

I should add that my intention was to simulate a search for a non-existent item or basically to get confirmation that the item doesn't exist (because I made it transient just now)

But it seems the connection is getting leaked somehow... because even the UT doesn't get to access it. If my UT did have access to it, then after the UT threw the exception, my UT teardown method would get activated and it would try to close the session (which should also close the connection). But Session.close() seems not to find that connection to close it.
Top
 Profile  
 
r
 Post subject: Re: Hibernate does not seem to release conn. after exception
PostPosted: Tue Oct 19, 2010 10:08 am 
Senior
Senior

Joined: Fri Oct 08, 2010 8:44 am
Posts: 130
I guess the problem is in the transaction indeed. Did you try to put your commit statement into finally block?

Like this:

Code:
    /**
     * Tests makeTransient() method.
     */
    @Test (expected=ObjectNotFoundException.class)
    public void testMakeTransient() {
        Transaction tx = session_.beginTransaction();
        try {
            BaseHibernateDAO m = new UserManager(session_);

            User u1 = new User("testMakeTransient-u1", "FN1", "LN1", 0);

            m.makePersistent(u1);

            Long id = u1.getId();

            m.makeTransient(u1);

            // This should throw org.hibernate.ObjectNotFoundException
            m.findById(id);
        } finally {
            tx.commit();
        }
    }
Top
 Profile  
 
cybrocop
 Post subject: Re: Hibernate does not seem to release conn. after exception
PostPosted: Tue Oct 19, 2010 10:49 am 
Newbie

Joined: Mon Sep 27, 2010 11:05 am
Posts: 6
Yes, that is actually how I got around the issue, but it still weird to manually test for exception inside the unit test (as opposed to listing expected exception as an annotation).

Should I open a bug report or is there another explanation for what's happening?

Code:
    /**
     * Tests makeTransient() method.
     */
    @Test
    public void testMakeTransient() throws Exception {
        Transaction tx = null;
        try {
            tx = session_.beginTransaction();
            BaseHibernateDAO m = new UserManager(session_);

            User u1 = new User("testMakeTransient-u1", "FN1", "LN1", 0);

            m.makePersistent(u1);

            Long id = u1.getId();

            m.makeTransient(u1);

            // This should throw org.hibernate.ObjectNotFoundException
            m.findById(id);
        }
        catch (ObjectNotFoundException ex) {
            // Expected. Test should pass.
        }
        catch (Exception ex) {
            // Unexpected exception.
            throw ex;
        }
        finally {
            tx.commit();
        }
    }
Top
 Profile  
 
r
 Post subject: Re: Hibernate does not seem to release conn. after exception
PostPosted: Wed Oct 20, 2010 4:45 am 
Senior
Senior

Joined: Fri Oct 08, 2010 8:44 am
Posts: 130
You do not need to test for exception manually. Just throw out your "catch" blocks, only "finally" block is needed.
Top
 Profile  
 
Display posts from previous:  Sort by  
Forum locked This topic is locked, you cannot edit posts or make further replies.  Page 1 of 1
  [ 7 posts ] 

Board index » Hibernate & Java Persistence » Hibernate Users

All times are UTC - 5 hours [ DST ]

You cannot post new topics in this forum
You cannot reply to topics in this forum
You cannot edit your posts in this forum
You cannot delete your posts in this forum

Search for:
© Copyright 2014, Red Hat Inc. All rights reserved. JBoss and Hibernate are registered trademarks and servicemarks of Red Hat, Inc.