-->
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
  [ 1 post ] 
  Previous topic | Next topic 
Author Message
bfreis
 Post subject: Bug? Duplicate insert: @OneToMay with cascade "all" & merge
PostPosted: Fri Dec 17, 2010 10:21 am 
Newbie

Joined: Wed Sep 09, 2009 6:05 am
Posts: 2
I have encountered a strange behavior of Hibernate. Either I have misunderstood the JPA specification, or it might be a bug.

The symptom is a duplicate insert, where I'd expect only one insert. At the company where I work, we were using Hibernate 3.5.4 when we stumbled upon this behavior. After that, I verified the same thing happens with Hibernate 3.6.0.

To reproduce the bug, I created an entity A which has a relationship of type one-to-many with an entity B:

Code:
@Entity
public class A {
    @Id @GeneratedValue(strategy = GenerationType.AUTO)
    private int id;

    @OneToMany(mappedBy = "a", cascade = CascadeType.ALL, fetch = FetchType.LAZY)
    private List<B> bs = new ArrayList();

    // getters and setters
}

@Entity
public class B {
    @Id @GeneratedValue(strategy = GenerationType.AUTO)
    private int id;

    @ManyToOne
    private A a;

    // getters and setters
}


The bug is triggered when I retrieve an entity A from the database, add something to its list o Bs, then merge the instance of A to the persistence unit, and then commit the transaction, as in the following example:

Code:
public class App {
    private static EntityManagerFactory pu = Persistence.createEntityManagerFactory("PU");

    public static void main(String[] args) {
        System.out.println("select count(*) from B: " + countBs());
        System.out.println("createA()");
        int id = createA();
        System.out.println("id = " + id);
        int bsBefore = countBs();
        System.out.println("select count(*) from B: " + bsBefore);
        System.out.println("bug()");
        bug(id);
        int bsAfter = countBs();
        System.out.println("select count(*) from B: " + bsAfter);
        System.out.println("Bs created: " + (bsAfter - bsBefore));
        System.out.println("Expected: 1");
    }

    private static int createA() {
        EntityManager em = null;
        int id = 0;
        try {
            em = pu.createEntityManager();
            em.getTransaction().begin();
            A a = new A();
            em.persist(a);
            em.getTransaction().commit();
            id = a.getId();
        } catch (Exception e) {
            if (em.getTransaction().isActive()) em.getTransaction().rollback();
        } finally {
            if (em != null && em.isOpen()) em.close();
        }
        return id;
    }

    private static void bug(int id) {
        EntityManager em = null;
        try {
            em = pu.createEntityManager();
            em.getTransaction().begin();

            A a = em.find(A.class, id);

            B b = new B();
            a.getBs().add(b);

            // The following line triggers the bug:
            em.merge(a);

            em.getTransaction().commit();
        } catch (Exception e) {
            if (em.getTransaction().isActive()) em.getTransaction().rollback();
        } finally {
            if (em != null && em.isOpen()) em.close();
        }
    }

    private static int countBs() {
        EntityManager em = null;
        try {
            em = pu.createEntityManager();
            return ((Number) em.createQuery("select count(*) from B").getSingleResult()).intValue();
        } finally {
            if (em != null && em.isOpen()) em.close();
        }
    }
}



The output is the following:

Code:
Hibernate: select count(*) as col_0_0_ from B b0_ limit ?
select count(*) from B: 0
createA()
Hibernate: insert into A values ( )
id = 1
Hibernate: select count(*) as col_0_0_ from B b0_ limit ?
select count(*) from B: 0
bug()
Hibernate: select a0_.id as id0_0_ from A a0_ where a0_.id=?
Hibernate: insert into B (a_id) values (?)
Hibernate: insert into B (a_id) values (?)
Hibernate: select count(*) as col_0_0_ from B b0_ limit ?
select count(*) from B: 2
Bs created: 2
Expected: 1



As you can see, hibernate made 2 insertions.

If I comment the line
Code:
em.merge(a);
, Hibernate will only make 1 insertion.


Is this a bug?



EDIT

As some additional info, if I step through the code, the first insert occurs right after I execute the "em.merge(...)", and the second one occurs right after the "commit()".

If I turn on the Hibernate logging, this is what I get (the most relevant lines are bold, as the output of my System.out.println()s):

select count(*) from B: 4
createA()
12:33:35.176 [main] DEBUG org.hibernate.impl.SessionImpl - opened session at timestamp: 12925964151
12:33:35.176 [main] TRACE org.hibernate.impl.SessionImpl - setting flush mode to: AUTO
12:33:35.176 [main] TRACE org.hibernate.impl.SessionImpl - setting cache mode to: NORMAL
12:33:35.178 [main] DEBUG o.h.transaction.JDBCTransaction - begin
12:33:35.179 [main] DEBUG org.hibernate.jdbc.ConnectionManager - opening JDBC connection
12:33:35.179 [main] TRACE o.h.c.DriverManagerConnectionProvider - total checked-out connections: 0
12:33:35.179 [main] TRACE o.h.c.DriverManagerConnectionProvider - using pooled JDBC connection, pool size: 0
12:33:35.179 [main] DEBUG o.h.transaction.JDBCTransaction - current autocommit status: true
12:33:35.179 [main] DEBUG o.h.transaction.JDBCTransaction - disabling autocommit
12:33:35.179 [main] TRACE org.hibernate.jdbc.JDBCContext - after transaction begin
12:33:35.181 [main] TRACE org.hibernate.engine.IdentifierValue - id unsaved-value: 0
12:33:35.181 [main] TRACE o.h.e.def.AbstractSaveEventListener - transient instance of: com.brunoreis.hibernate.bug.A
12:33:35.181 [main] TRACE o.h.e.d.DefaultPersistEventListener - saving transient instance
12:33:35.184 [main] TRACE o.h.e.def.AbstractSaveEventListener - saving [com.brunoreis.hibernate.bug.A#<null>]
12:33:35.188 [main] TRACE org.hibernate.engine.Cascade - processing cascade ACTION_PERSIST_SKIPLAZY for: com.brunoreis.hibernate.bug.A
12:33:35.188 [main] TRACE org.hibernate.engine.Cascade - done processing cascade ACTION_PERSIST_SKIPLAZY for: com.brunoreis.hibernate.bug.A
12:33:35.188 [main] TRACE o.h.e.def.AbstractSaveEventListener - executing insertions
12:33:35.194 [main] TRACE org.hibernate.event.def.WrapVisitor - Wrapped collection in role: com.brunoreis.hibernate.bug.A.bs
12:33:35.198 [main] DEBUG o.h.e.def.AbstractSaveEventListener - executing identity-insert immediately
12:33:35.198 [main] TRACE o.h.p.entity.AbstractEntityPersister - Inserting entity: com.brunoreis.hibernate.bug.A (native id)
12:33:35.198 [main] DEBUG org.hibernate.jdbc.AbstractBatcher - about to open PreparedStatement (open PreparedStatements: 0, globally: 0)
12:33:35.199 [main] DEBUG org.hibernate.SQL - insert into A values ( )
Hibernate: insert into A values ( )
12:33:35.199 [main] TRACE org.hibernate.jdbc.AbstractBatcher - preparing statement
12:33:35.199 [main] TRACE o.h.p.entity.AbstractEntityPersister - Dehydrating entity: [com.brunoreis.hibernate.bug.A#<null>]
12:33:35.200 [main] DEBUG o.h.id.IdentifierGeneratorHelper - Natively generated identity: 3
12:33:35.201 [main] DEBUG org.hibernate.jdbc.AbstractBatcher - about to close PreparedStatement (open PreparedStatements: 1, globally: 1)
12:33:35.201 [main] TRACE org.hibernate.jdbc.AbstractBatcher - closing statement
12:33:35.203 [main] TRACE org.hibernate.engine.Cascade - processing cascade ACTION_PERSIST_SKIPLAZY for: com.brunoreis.hibernate.bug.A
12:33:35.203 [main] TRACE org.hibernate.engine.Cascade - cascade ACTION_PERSIST_SKIPLAZY for collection: com.brunoreis.hibernate.bug.A.bs
12:33:35.204 [main] TRACE org.hibernate.engine.Cascade - done cascade ACTION_PERSIST_SKIPLAZY for collection: com.brunoreis.hibernate.bug.A.bs
12:33:35.204 [main] TRACE org.hibernate.engine.Cascade - done processing cascade ACTION_PERSIST_SKIPLAZY for: com.brunoreis.hibernate.bug.A
12:33:35.204 [main] DEBUG o.h.transaction.JDBCTransaction - commit
12:33:35.204 [main] TRACE org.hibernate.impl.SessionImpl - automatically flushing session
12:33:35.204 [main] TRACE o.h.e.d.AbstractFlushingEventListener - flushing session
12:33:35.204 [main] DEBUG o.h.e.d.AbstractFlushingEventListener - processing flush-time cascades
12:33:35.205 [main] TRACE org.hibernate.engine.Cascade - processing cascade ACTION_PERSIST_ON_FLUSH for: com.brunoreis.hibernate.bug.A
12:33:35.205 [main] TRACE org.hibernate.engine.Cascade - cascade ACTION_PERSIST_ON_FLUSH for collection: com.brunoreis.hibernate.bug.A.bs
12:33:35.205 [main] TRACE org.hibernate.engine.Cascade - done cascade ACTION_PERSIST_ON_FLUSH for collection: com.brunoreis.hibernate.bug.A.bs
12:33:35.205 [main] TRACE org.hibernate.engine.Cascade - done processing cascade ACTION_PERSIST_ON_FLUSH for: com.brunoreis.hibernate.bug.A
12:33:35.205 [main] DEBUG o.h.e.d.AbstractFlushingEventListener - dirty checking collections
12:33:35.205 [main] TRACE o.h.e.d.AbstractFlushingEventListener - Flushing entities and processing referenced collections
12:33:35.208 [main] DEBUG org.hibernate.engine.Collections - Collection found: [com.brunoreis.hibernate.bug.A.bs#3], was: [<unreferenced>] (initialized)
12:33:35.208 [main] TRACE o.h.e.d.AbstractFlushingEventListener - Processing unreferenced collections
12:33:35.208 [main] TRACE o.h.e.d.AbstractFlushingEventListener - Scheduling collection removes/(re)creates/updates
12:33:35.210 [main] DEBUG o.h.e.d.AbstractFlushingEventListener - Flushed: 0 insertions, 0 updates, 0 deletions to 1 objects
12:33:35.210 [main] DEBUG o.h.e.d.AbstractFlushingEventListener - Flushed: 1 (re)creations, 0 updates, 0 removals to 1 collections
12:33:35.210 [main] DEBUG org.hibernate.pretty.Printer - listing entities:
12:33:35.210 [main] DEBUG org.hibernate.pretty.Printer - com.brunoreis.hibernate.bug.A{id=3, bs=[]}
12:33:35.210 [main] TRACE o.h.e.d.AbstractFlushingEventListener - executing flush
12:33:35.210 [main] TRACE org.hibernate.jdbc.ConnectionManager - registering flush begin
12:33:35.210 [main] TRACE org.hibernate.jdbc.ConnectionManager - registering flush end
12:33:35.210 [main] TRACE o.h.e.d.AbstractFlushingEventListener - post flush
12:33:35.211 [main] TRACE org.hibernate.jdbc.JDBCContext - before transaction completion
12:33:35.211 [main] TRACE org.hibernate.impl.SessionImpl - before transaction completion
12:33:35.211 [main] DEBUG o.h.transaction.JDBCTransaction - re-enabling autocommit
12:33:35.212 [main] DEBUG o.h.transaction.JDBCTransaction - committed JDBC Connection
12:33:35.212 [main] TRACE org.hibernate.jdbc.JDBCContext - after transaction completion
12:33:35.212 [main] DEBUG org.hibernate.jdbc.ConnectionManager - aggressively releasing JDBC connection
12:33:35.212 [main] DEBUG org.hibernate.jdbc.ConnectionManager - releasing JDBC connection [ (open PreparedStatements: 0, globally: 0) (open ResultSets: 0, globally: 0)]
12:33:35.212 [main] TRACE o.h.c.DriverManagerConnectionProvider - returning connection to pool, pool size: 1
12:33:35.212 [main] TRACE org.hibernate.impl.SessionImpl - after transaction completion
12:33:35.212 [main] TRACE org.hibernate.impl.SessionImpl - closing session
12:33:35.212 [main] TRACE org.hibernate.jdbc.ConnectionManager - connection already null in cleanup : no action
id = 3
12:33:35.212 [main] DEBUG org.hibernate.impl.SessionImpl - opened session at timestamp: 12925964152
12:33:35.212 [main] TRACE org.hibernate.impl.SessionImpl - setting flush mode to: AUTO
12:33:35.212 [main] TRACE org.hibernate.impl.SessionImpl - setting cache mode to: NORMAL
12:33:35.212 [main] TRACE o.h.engine.query.QueryPlanCache - located HQL query plan in cache (select count(*) from B)
12:33:35.212 [main] TRACE o.h.engine.query.QueryPlanCache - located HQL query plan in cache (select count(*) from B)
12:33:35.212 [main] TRACE o.h.engine.query.HQLQueryPlan - find: select count(*) from B
12:33:35.212 [main] TRACE org.hibernate.engine.QueryParameters - named parameters: {}
12:33:35.213 [main] DEBUG org.hibernate.jdbc.AbstractBatcher - about to open PreparedStatement (open PreparedStatements: 0, globally: 0)
12:33:35.213 [main] DEBUG org.hibernate.jdbc.ConnectionManager - opening JDBC connection
12:33:35.213 [main] TRACE o.h.c.DriverManagerConnectionProvider - total checked-out connections: 0
12:33:35.213 [main] TRACE o.h.c.DriverManagerConnectionProvider - using pooled JDBC connection, pool size: 0
12:33:35.213 [main] DEBUG org.hibernate.SQL - select count(*) as col_0_0_ from B b0_ limit ?
Hibernate: select count(*) as col_0_0_ from B b0_ limit ?
12:33:35.213 [main] TRACE org.hibernate.jdbc.AbstractBatcher - preparing statement
12:33:35.213 [main] TRACE org.hibernate.loader.Loader - Bound [2] parameters total
12:33:35.213 [main] DEBUG org.hibernate.jdbc.AbstractBatcher - about to open ResultSet (open ResultSets: 0, globally: 0)
12:33:35.213 [main] TRACE org.hibernate.loader.Loader - processing result set
12:33:35.213 [main] DEBUG org.hibernate.loader.Loader - result set row: 0
12:33:35.213 [main] DEBUG org.hibernate.loader.Loader - result row:
12:33:35.213 [main] TRACE o.h.t.descriptor.sql.BasicExtractor - found [4] as column [col_0_0_]
12:33:35.213 [main] TRACE org.hibernate.loader.Loader - done processing result set (1 rows)
12:33:35.214 [main] DEBUG org.hibernate.jdbc.AbstractBatcher - about to close ResultSet (open ResultSets: 1, globally: 1)
12:33:35.214 [main] DEBUG org.hibernate.jdbc.AbstractBatcher - about to close PreparedStatement (open PreparedStatements: 1, globally: 1)
12:33:35.214 [main] TRACE org.hibernate.jdbc.AbstractBatcher - closing statement
12:33:35.214 [main] DEBUG org.hibernate.jdbc.ConnectionManager - aggressively releasing JDBC connection
12:33:35.214 [main] DEBUG org.hibernate.jdbc.ConnectionManager - releasing JDBC connection [ (open PreparedStatements: 0, globally: 0) (open ResultSets: 0, globally: 0)]
12:33:35.214 [main] TRACE o.h.c.DriverManagerConnectionProvider - returning connection to pool, pool size: 1
12:33:35.214 [main] DEBUG o.h.e.StatefulPersistenceContext - initializing non-lazy collections
12:33:35.214 [main] TRACE org.hibernate.jdbc.JDBCContext - after autocommit
12:33:35.214 [main] DEBUG org.hibernate.jdbc.ConnectionManager - aggressively releasing JDBC connection
12:33:35.214 [main] TRACE org.hibernate.impl.SessionImpl - after transaction completion
12:33:35.214 [main] TRACE org.hibernate.impl.SessionImpl - closing session
12:33:35.214 [main] TRACE org.hibernate.jdbc.ConnectionManager - connection already null in cleanup : no action
select count(*) from B: 4
bug()
12:33:35.214 [main] DEBUG org.hibernate.impl.SessionImpl - opened session at timestamp: 12925964152
12:33:35.214 [main] TRACE org.hibernate.impl.SessionImpl - setting flush mode to: AUTO
12:33:35.214 [main] TRACE org.hibernate.impl.SessionImpl - setting cache mode to: NORMAL
12:33:35.214 [main] DEBUG o.h.transaction.JDBCTransaction - begin
12:33:35.214 [main] DEBUG org.hibernate.jdbc.ConnectionManager - opening JDBC connection
12:33:35.214 [main] TRACE o.h.c.DriverManagerConnectionProvider - total checked-out connections: 0
12:33:35.214 [main] TRACE o.h.c.DriverManagerConnectionProvider - using pooled JDBC connection, pool size: 0
12:33:35.214 [main] DEBUG o.h.transaction.JDBCTransaction - current autocommit status: true
12:33:35.214 [main] DEBUG o.h.transaction.JDBCTransaction - disabling autocommit
12:33:35.215 [main] TRACE org.hibernate.jdbc.JDBCContext - after transaction begin
12:33:35.215 [main] TRACE org.hibernate.impl.SessionImpl - setting cache mode to: NORMAL
12:33:35.216 [main] TRACE o.h.e.def.DefaultLoadEventListener - loading entity: [com.brunoreis.hibernate.bug.A#3]
12:33:35.216 [main] TRACE o.h.e.def.DefaultLoadEventListener - attempting to resolve: [com.brunoreis.hibernate.bug.A#3]
12:33:35.216 [main] TRACE o.h.e.def.DefaultLoadEventListener - object not resolved in any cache: [com.brunoreis.hibernate.bug.A#3]
12:33:35.217 [main] TRACE o.h.p.entity.AbstractEntityPersister - Fetching entity: [com.brunoreis.hibernate.bug.A#3]
12:33:35.217 [main] DEBUG org.hibernate.loader.Loader - loading entity: [com.brunoreis.hibernate.bug.A#3]
12:33:35.217 [main] DEBUG org.hibernate.jdbc.AbstractBatcher - about to open PreparedStatement (open PreparedStatements: 0, globally: 0)
12:33:35.217 [main] DEBUG org.hibernate.SQL - select a0_.id as id0_0_ from A a0_ where a0_.id=?
Hibernate: select a0_.id as id0_0_ from A a0_ where a0_.id=?
12:33:35.217 [main] TRACE org.hibernate.jdbc.AbstractBatcher - preparing statement
12:33:35.222 [main] TRACE o.h.type.descriptor.sql.BasicBinder - binding parameter [1] as [INTEGER] - 3
12:33:35.222 [main] TRACE org.hibernate.loader.Loader - Bound [2] parameters total
12:33:35.222 [main] DEBUG org.hibernate.jdbc.AbstractBatcher - about to open ResultSet (open ResultSets: 0, globally: 0)
12:33:35.222 [main] TRACE org.hibernate.loader.Loader - processing result set
12:33:35.222 [main] DEBUG org.hibernate.loader.Loader - result set row: 0
12:33:35.223 [main] DEBUG org.hibernate.loader.Loader - result row: EntityKey[com.brunoreis.hibernate.bug.A#3]
12:33:35.223 [main] TRACE org.hibernate.loader.Loader - Initializing object from ResultSet: [com.brunoreis.hibernate.bug.A#3]
12:33:35.224 [main] TRACE o.h.p.entity.AbstractEntityPersister - Hydrating entity: [com.brunoreis.hibernate.bug.A#3]
12:33:35.224 [main] TRACE org.hibernate.loader.Loader - done processing result set (1 rows)
12:33:35.224 [main] DEBUG org.hibernate.jdbc.AbstractBatcher - about to close ResultSet (open ResultSets: 1, globally: 1)
12:33:35.224 [main] DEBUG org.hibernate.jdbc.AbstractBatcher - about to close PreparedStatement (open PreparedStatements: 1, globally: 1)
12:33:35.224 [main] TRACE org.hibernate.jdbc.AbstractBatcher - closing statement
12:33:35.224 [main] TRACE org.hibernate.loader.Loader - total objects hydrated: 1
12:33:35.224 [main] DEBUG org.hibernate.engine.TwoPhaseLoad - resolving associations for [com.brunoreis.hibernate.bug.A#3]
12:33:35.226 [main] TRACE o.h.engine.loading.LoadContexts - creating collection wrapper:[com.brunoreis.hibernate.bug.A.bs#3]
12:33:35.227 [main] DEBUG org.hibernate.engine.TwoPhaseLoad - done materializing entity [com.brunoreis.hibernate.bug.A#3]
12:33:35.227 [main] DEBUG o.h.e.StatefulPersistenceContext - initializing non-lazy collections
12:33:35.227 [main] DEBUG org.hibernate.loader.Loader - done entity load
12:33:35.227 [main] TRACE org.hibernate.impl.SessionImpl - setting cache mode to: NORMAL
12:33:35.229 [main] TRACE o.h.e.def.AbstractSaveEventListener - persistent instance of: com.brunoreis.hibernate.bug.A
12:33:35.230 [main] TRACE o.h.e.def.DefaultMergeEventListener - ignoring persistent instance
12:33:35.230 [main] TRACE org.hibernate.engine.Cascade - processing cascade ACTION_MERGE for: com.brunoreis.hibernate.bug.A
12:33:35.230 [main] TRACE org.hibernate.engine.Cascade - cascade ACTION_MERGE for collection: com.brunoreis.hibernate.bug.A.bs
12:33:35.230 [main] TRACE org.hibernate.engine.CascadingAction - cascading to merge: com.brunoreis.hibernate.bug.B
12:33:35.231 [main] TRACE org.hibernate.engine.IdentifierValue - id unsaved-value: 0
12:33:35.231 [main] TRACE o.h.e.def.AbstractSaveEventListener - transient instance of: com.brunoreis.hibernate.bug.B
12:33:35.231 [main] TRACE o.h.e.def.DefaultMergeEventListener - merging transient instance
12:33:35.231 [main] TRACE o.h.e.def.DefaultMergeEventListener - merging transient instance
12:33:35.231 [main] TRACE o.h.e.def.AbstractSaveEventListener - saving [com.brunoreis.hibernate.bug.B#<null>]
12:33:35.231 [main] TRACE o.h.e.def.AbstractSaveEventListener - executing insertions
12:33:35.231 [main] DEBUG o.h.e.def.AbstractSaveEventListener - executing identity-insert immediately
12:33:35.231 [main] TRACE o.h.p.entity.AbstractEntityPersister - Inserting entity: com.brunoreis.hibernate.bug.B (native id)
12:33:35.231 [main] DEBUG org.hibernate.jdbc.AbstractBatcher - about to open PreparedStatement (open PreparedStatements: 0, globally: 0)
12:33:35.231 [main] DEBUG org.hibernate.SQL - insert into B (a_id) values (?)
Hibernate: insert into B (a_id) values (?)
12:33:35.231 [main] TRACE org.hibernate.jdbc.AbstractBatcher - preparing statement
12:33:35.232 [main] TRACE o.h.p.entity.AbstractEntityPersister - Dehydrating entity: [com.brunoreis.hibernate.bug.B#<null>]
12:33:35.232 [main] TRACE o.h.type.descriptor.sql.BasicBinder - binding parameter [1] as [INTEGER] - <null>
12:33:35.232 [main] DEBUG o.h.id.IdentifierGeneratorHelper - Natively generated identity: 5
12:33:35.232 [main] DEBUG org.hibernate.jdbc.AbstractBatcher - about to close PreparedStatement (open PreparedStatements: 1, globally: 1)
12:33:35.232 [main] TRACE org.hibernate.jdbc.AbstractBatcher - closing statement
12:33:35.232 [main] TRACE org.hibernate.engine.Cascade - done cascade ACTION_MERGE for collection: com.brunoreis.hibernate.bug.A.bs
12:33:35.232 [main] TRACE org.hibernate.engine.Cascade - done processing cascade ACTION_MERGE for: com.brunoreis.hibernate.bug.A
12:33:35.233 [main] DEBUG o.h.transaction.JDBCTransaction - commit
12:33:35.233 [main] TRACE org.hibernate.impl.SessionImpl - automatically flushing session
12:33:35.233 [main] TRACE o.h.e.d.AbstractFlushingEventListener - flushing session
12:33:35.233 [main] DEBUG o.h.e.d.AbstractFlushingEventListener - processing flush-time cascades
12:33:35.233 [main] TRACE org.hibernate.engine.Cascade - processing cascade ACTION_PERSIST_ON_FLUSH for: com.brunoreis.hibernate.bug.A
12:33:35.233 [main] TRACE org.hibernate.engine.Cascade - cascade ACTION_PERSIST_ON_FLUSH for collection: com.brunoreis.hibernate.bug.A.bs
12:33:35.233 [main] TRACE org.hibernate.engine.CascadingAction - cascading to persistOnFlush: com.brunoreis.hibernate.bug.B
12:33:35.233 [main] TRACE org.hibernate.engine.IdentifierValue - id unsaved-value: 0
12:33:35.233 [main] TRACE o.h.e.def.AbstractSaveEventListener - transient instance of: com.brunoreis.hibernate.bug.B
12:33:35.233 [main] TRACE o.h.e.d.DefaultPersistEventListener - saving transient instance
12:33:35.233 [main] TRACE o.h.e.def.AbstractSaveEventListener - saving [com.brunoreis.hibernate.bug.B#<null>]
12:33:35.233 [main] TRACE org.hibernate.engine.Cascade - processing cascade ACTION_PERSIST_ON_FLUSH for: com.brunoreis.hibernate.bug.B
12:33:35.233 [main] TRACE org.hibernate.engine.Cascade - done processing cascade ACTION_PERSIST_ON_FLUSH for: com.brunoreis.hibernate.bug.B
12:33:35.233 [main] TRACE o.h.e.def.AbstractSaveEventListener - executing insertions
12:33:35.233 [main] DEBUG o.h.e.def.AbstractSaveEventListener - executing identity-insert immediately
12:33:35.233 [main] TRACE o.h.p.entity.AbstractEntityPersister - Inserting entity: com.brunoreis.hibernate.bug.B (native id)
12:33:35.233 [main] DEBUG org.hibernate.jdbc.AbstractBatcher - about to open PreparedStatement (open PreparedStatements: 0, globally: 0)
12:33:35.233 [main] DEBUG org.hibernate.SQL - insert into B (a_id) values (?)
Hibernate: insert into B (a_id) values (?)
12:33:35.233 [main] TRACE org.hibernate.jdbc.AbstractBatcher - preparing statement
12:33:35.234 [main] TRACE o.h.p.entity.AbstractEntityPersister - Dehydrating entity: [com.brunoreis.hibernate.bug.B#<null>]
12:33:35.234 [main] TRACE o.h.type.descriptor.sql.BasicBinder - binding parameter [1] as [INTEGER] - <null>
12:33:35.234 [main] DEBUG o.h.id.IdentifierGeneratorHelper - Natively generated identity: 6
12:33:35.234 [main] DEBUG org.hibernate.jdbc.AbstractBatcher - about to close PreparedStatement (open PreparedStatements: 1, globally: 1)
12:33:35.234 [main] TRACE org.hibernate.jdbc.AbstractBatcher - closing statement
12:33:35.234 [main] TRACE org.hibernate.engine.Cascade - processing cascade ACTION_PERSIST_ON_FLUSH for: com.brunoreis.hibernate.bug.B
12:33:35.234 [main] TRACE org.hibernate.engine.Cascade - done processing cascade ACTION_PERSIST_ON_FLUSH for: com.brunoreis.hibernate.bug.B
12:33:35.234 [main] TRACE org.hibernate.engine.Cascade - done cascade ACTION_PERSIST_ON_FLUSH for collection: com.brunoreis.hibernate.bug.A.bs
12:33:35.234 [main] TRACE org.hibernate.engine.Cascade - done processing cascade ACTION_PERSIST_ON_FLUSH for: com.brunoreis.hibernate.bug.A
12:33:35.234 [main] TRACE org.hibernate.engine.Cascade - processing cascade ACTION_PERSIST_ON_FLUSH for: com.brunoreis.hibernate.bug.B
12:33:35.234 [main] TRACE org.hibernate.engine.Cascade - done processing cascade ACTION_PERSIST_ON_FLUSH for: com.brunoreis.hibernate.bug.B
12:33:35.234 [main] DEBUG o.h.e.d.AbstractFlushingEventListener - dirty checking collections
12:33:35.235 [main] DEBUG org.hibernate.engine.CollectionEntry - Collection dirty: [com.brunoreis.hibernate.bug.A.bs#3]
12:33:35.235 [main] TRACE o.h.e.d.AbstractFlushingEventListener - Flushing entities and processing referenced collections
12:33:35.235 [main] DEBUG org.hibernate.engine.Collections - Collection found: [com.brunoreis.hibernate.bug.A.bs#3], was: [com.brunoreis.hibernate.bug.A.bs#3] (uninitialized)
12:33:35.235 [main] TRACE o.h.e.d.AbstractFlushingEventListener - Processing unreferenced collections
12:33:35.235 [main] TRACE o.h.e.d.AbstractFlushingEventListener - Scheduling collection removes/(re)creates/updates
12:33:35.236 [main] DEBUG o.h.e.d.AbstractFlushingEventListener - Flushed: 0 insertions, 0 updates, 0 deletions to 3 objects
12:33:35.236 [main] DEBUG o.h.e.d.AbstractFlushingEventListener - Flushed: 0 (re)creations, 1 updates, 0 removals to 1 collections
12:33:35.236 [main] DEBUG org.hibernate.pretty.Printer - listing entities:
12:33:35.236 [main] DEBUG org.hibernate.pretty.Printer - com.brunoreis.hibernate.bug.B{id=5, a=null}
12:33:35.236 [main] DEBUG org.hibernate.pretty.Printer - com.brunoreis.hibernate.bug.B{id=6, a=null}
12:33:35.236 [main] DEBUG org.hibernate.pretty.Printer - com.brunoreis.hibernate.bug.A{id=3, bs=<uninitialized>}
12:33:35.237 [main] TRACE o.h.e.d.AbstractFlushingEventListener - executing flush
12:33:35.237 [main] TRACE org.hibernate.jdbc.ConnectionManager - registering flush begin
12:33:35.237 [main] TRACE org.hibernate.jdbc.ConnectionManager - registering flush end
12:33:35.237 [main] TRACE o.h.e.d.AbstractFlushingEventListener - post flush
12:33:35.237 [main] TRACE org.hibernate.jdbc.JDBCContext - before transaction completion
12:33:35.237 [main] TRACE org.hibernate.impl.SessionImpl - before transaction completion
12:33:35.237 [main] DEBUG o.h.transaction.JDBCTransaction - re-enabling autocommit
12:33:35.237 [main] DEBUG o.h.transaction.JDBCTransaction - committed JDBC Connection
12:33:35.237 [main] TRACE org.hibernate.jdbc.JDBCContext - after transaction completion
12:33:35.237 [main] DEBUG org.hibernate.jdbc.ConnectionManager - aggressively releasing JDBC connection
12:33:35.237 [main] DEBUG org.hibernate.jdbc.ConnectionManager - releasing JDBC connection [ (open PreparedStatements: 0, globally: 0) (open ResultSets: 0, globally: 0)]
12:33:35.237 [main] TRACE o.h.c.DriverManagerConnectionProvider - returning connection to pool, pool size: 1
12:33:35.237 [main] TRACE org.hibernate.impl.SessionImpl - after transaction completion
12:33:35.237 [main] TRACE org.hibernate.impl.SessionImpl - closing session
12:33:35.238 [main] TRACE org.hibernate.jdbc.ConnectionManager - connection already null in cleanup : no action
12:33:35.238 [main] DEBUG org.hibernate.impl.SessionImpl - opened session at timestamp: 12925964152
12:33:35.238 [main] TRACE org.hibernate.impl.SessionImpl - setting flush mode to: AUTO
12:33:35.238 [main] TRACE org.hibernate.impl.SessionImpl - setting cache mode to: NORMAL
12:33:35.238 [main] TRACE o.h.engine.query.QueryPlanCache - located HQL query plan in cache (select count(*) from B)
12:33:35.238 [main] TRACE o.h.engine.query.QueryPlanCache - located HQL query plan in cache (select count(*) from B)
12:33:35.238 [main] TRACE o.h.engine.query.HQLQueryPlan - find: select count(*) from B
12:33:35.238 [main] TRACE org.hibernate.engine.QueryParameters - named parameters: {}
12:33:35.238 [main] DEBUG org.hibernate.jdbc.AbstractBatcher - about to open PreparedStatement (open PreparedStatements: 0, globally: 0)
12:33:35.238 [main] DEBUG org.hibernate.jdbc.ConnectionManager - opening JDBC connection
12:33:35.238 [main] TRACE o.h.c.DriverManagerConnectionProvider - total checked-out connections: 0
12:33:35.238 [main] TRACE o.h.c.DriverManagerConnectionProvider - using pooled JDBC connection, pool size: 0
12:33:35.238 [main] DEBUG org.hibernate.SQL - select count(*) as col_0_0_ from B b0_ limit ?
Hibernate: select count(*) as col_0_0_ from B b0_ limit ?
12:33:35.238 [main] TRACE org.hibernate.jdbc.AbstractBatcher - preparing statement
12:33:35.239 [main] TRACE org.hibernate.loader.Loader - Bound [2] parameters total
12:33:35.239 [main] DEBUG org.hibernate.jdbc.AbstractBatcher - about to open ResultSet (open ResultSets: 0, globally: 0)
12:33:35.239 [main] TRACE org.hibernate.loader.Loader - processing result set
12:33:35.239 [main] DEBUG org.hibernate.loader.Loader - result set row: 0
12:33:35.239 [main] DEBUG org.hibernate.loader.Loader - result row:
12:33:35.239 [main] TRACE o.h.t.descriptor.sql.BasicExtractor - found [6] as column [col_0_0_]
12:33:35.239 [main] TRACE org.hibernate.loader.Loader - done processing result set (1 rows)
12:33:35.239 [main] DEBUG org.hibernate.jdbc.AbstractBatcher - about to close ResultSet (open ResultSets: 1, globally: 1)
12:33:35.239 [main] DEBUG org.hibernate.jdbc.AbstractBatcher - about to close PreparedStatement (open PreparedStatements: 1, globally: 1)
12:33:35.239 [main] TRACE org.hibernate.jdbc.AbstractBatcher - closing statement
12:33:35.239 [main] DEBUG org.hibernate.jdbc.ConnectionManager - aggressively releasing JDBC connection
12:33:35.239 [main] DEBUG org.hibernate.jdbc.ConnectionManager - releasing JDBC connection [ (open PreparedStatements: 0, globally: 0) (open ResultSets: 0, globally: 0)]
12:33:35.240 [main] TRACE o.h.c.DriverManagerConnectionProvider - returning connection to pool, pool size: 1
12:33:35.240 [main] DEBUG o.h.e.StatefulPersistenceContext - initializing non-lazy collections
12:33:35.240 [main] TRACE org.hibernate.jdbc.JDBCContext - after autocommit
12:33:35.240 [main] DEBUG org.hibernate.jdbc.ConnectionManager - aggressively releasing JDBC connection
12:33:35.240 [main] TRACE org.hibernate.impl.SessionImpl - after transaction completion
12:33:35.240 [main] TRACE org.hibernate.impl.SessionImpl - closing session
12:33:35.240 [main] TRACE org.hibernate.jdbc.ConnectionManager - connection already null in cleanup : no action
select count(*) from B: 6
Bs created: 2
Expected: 1







Thanks,
Bruno
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
  [ 1 post ] 

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.