[Hibernate-issues] [Hibernate-JIRA] Updated: (HHH-1564) Possible bug with deleting versioned object

SourceForge Headquarters 1320 Columbia Street Suite 310 San Diego, CA 92101 +1 (858) 422-6466

     [ http://opensource.atlassian.com/projects/hibernate/browse/HHH-1564?page=all ]

Christian Bauer updated HHH-1564:
---------------------------------

    Attachment: onetomanydelete_test.tar.gz

I can confirm that there is a problem with unnecessary updates for Parent, if cascading to Children collection is enabled. This is related to versioning of the Parent. Test case against latest SVN is attached.

The UPDATE shouldn't happen, it also sets the version from 0 to 0:

10:49:50,751 DEBUG SessionImpl:222 - opened session at timestamp: 4705864051712000
10:49:50,752 DEBUG JDBCTransaction:54 - begin
10:49:50,753 DEBUG ConnectionManager:415 - opening JDBC connection
10:49:50,754 DEBUG DriverManagerConnectionProvider:93 - total checked-out connections: 0
10:49:50,758 DEBUG DriverManagerConnectionProvider:99 - using pooled JDBC connection, pool size: 0
10:49:50,766 DEBUG JDBCTransaction:59 - current autocommit status: false
10:49:50,772 DEBUG JDBCContext:203 - after transaction begin
#### LOADIG PARENT
10:49:50,781 DEBUG DefaultLoadEventListener:154 - loading entity: [org.hibernate.test.onetomanydelete.Parent#1]
10:49:50,783 DEBUG DefaultLoadEventListener:309 - attempting to resolve: [org.hibernate.test.onetomanydelete.Parent#1]
10:49:50,785 DEBUG NonstrictReadWriteCache:41 - Cache lookup: org.hibernate.test.onetomanydelete.Parent#1
10:49:50,789 DEBUG NonstrictReadWriteCache:49 - Cache miss
10:49:50,790 DEBUG DefaultLoadEventListener:345 - object not resolved in any cache: [org.hibernate.test.onetomanydelete.Parent#1]
10:49:50,792 DEBUG AbstractEntityPersister:2814 - Fetching entity: [org.hibernate.test.onetomanydelete.Parent#1]
10:49:50,801 DEBUG Loader:1777 - loading entity: [org.hibernate.test.onetomanydelete.Parent#1]
10:49:50,808 DEBUG AbstractBatcher:358 - about to open PreparedStatement (open PreparedStatements: 0, globally: 0)
10:49:50,810 DEBUG SQL:393 - 
    select
        parent0_.parent_id as parent1_0_0_,
        parent0_.obj_version as obj2_0_0_,
        parent0_.name as name0_0_ 
    from
        Parent parent0_ 
    where
        parent0_.parent_id=?
10:49:50,812 DEBUG AbstractBatcher:476 - preparing statement
10:49:50,818 DEBUG AbstractBatcher:374 - about to open ResultSet (open ResultSets: 0, globally: 0)
10:49:50,820 DEBUG Loader:682 - processing result set
10:49:50,821 DEBUG Loader:687 - result set row: 0
10:49:50,823 DEBUG Loader:1164 - result row: EntityKey[org.hibernate.test.onetomanydelete.Parent#1]
10:49:50,825 DEBUG Loader:1347 - Initializing object from ResultSet: [org.hibernate.test.onetomanydelete.Parent#1]
10:49:50,830 DEBUG AbstractEntityPersister:1944 - Hydrating entity: [org.hibernate.test.onetomanydelete.Parent#1]
10:49:50,832 DEBUG TwoPhaseLoad:75 - Version: 0
10:49:50,835 DEBUG Loader:709 - done processing result set (1 rows)
10:49:50,837 DEBUG AbstractBatcher:381 - about to close ResultSet (open ResultSets: 1, globally: 1)
10:49:50,838 DEBUG AbstractBatcher:366 - about to close PreparedStatement (open PreparedStatements: 1, globally: 1)
10:49:50,840 DEBUG AbstractBatcher:525 - closing statement
10:49:50,845 DEBUG Loader:839 - total objects hydrated: 1
10:49:50,846 DEBUG TwoPhaseLoad:107 - resolving associations for [org.hibernate.test.onetomanydelete.Parent#1]
10:49:50,853 DEBUG CollectionLoadContext:141 - creating collection wrapper:[org.hibernate.test.onetomanydelete.Parent.children#1]
10:49:50,856 DEBUG TwoPhaseLoad:135 - adding entity to second-level cache: [org.hibernate.test.onetomanydelete.Parent#1]
10:49:50,859 DEBUG NonstrictReadWriteCache:71 - Caching: org.hibernate.test.onetomanydelete.Parent#1
10:49:50,861 DEBUG TwoPhaseLoad:206 - done materializing entity [org.hibernate.test.onetomanydelete.Parent#1]
10:49:50,862 DEBUG StatefulPersistenceContext:748 - initializing non-lazy collections
10:49:50,865 DEBUG Loader:1808 - done entity load
#### DELETING PARENT
10:49:50,868 DEBUG DefaultDeleteEventListener:90 - deleting a persistent instance
10:49:50,870 DEBUG DefaultDeleteEventListener:127 - deleting [org.hibernate.test.onetomanydelete.Parent#1]
10:49:50,874 DEBUG SessionImpl:1301 - setting cache mode to: GET
10:49:50,875 DEBUG Cascade:237 - processing cascade ACTION_DELETE for: org.hibernate.test.onetomanydelete.Parent
10:49:50,877 DEBUG Cascade:285 - cascade ACTION_DELETE for collection: org.hibernate.test.onetomanydelete.Parent.children
10:49:50,880 DEBUG DefaultInitializeCollectionEventListener:41 - initializing collection [org.hibernate.test.onetomanydelete.Parent.children#1]
10:49:50,882 DEBUG DefaultInitializeCollectionEventListener:47 - checking second-level cache
10:49:50,884 DEBUG NonstrictReadWriteCache:41 - Cache lookup: org.hibernate.test.onetomanydelete.Parent.children#1
10:49:50,885 DEBUG NonstrictReadWriteCache:49 - Cache miss
10:49:50,889 DEBUG DefaultInitializeCollectionEventListener:59 - collection not cached
10:49:50,891 DEBUG Loader:1911 - loading collection: [org.hibernate.test.onetomanydelete.Parent.children#1]
10:49:50,896 DEBUG AbstractBatcher:358 - about to open PreparedStatement (open PreparedStatements: 0, globally: 0)
10:49:50,903 DEBUG SQL:393 - 
    select
        children0_.parent_id as parent3_1_,
        children0_.child_id as child1_1_,
        children0_.child_id as child1_1_0_,
        children0_.name as name1_0_,
        children0_.parent_id as parent3_1_0_ 
    from
        Child children0_ 
    where
        children0_.parent_id=?
10:49:50,914 DEBUG AbstractBatcher:476 - preparing statement
10:49:50,924 DEBUG AbstractBatcher:374 - about to open ResultSet (open ResultSets: 0, globally: 0)
10:49:50,928 DEBUG Loader:1040 - result set contains (possibly empty) collection: [org.hibernate.test.onetomanydelete.Parent.children#1]
10:49:50,930 DEBUG CollectionLoadContext:84 - uninitialized collection: initializing
10:49:50,933 DEBUG Loader:682 - processing result set
10:49:50,934 DEBUG Loader:687 - result set row: 0
10:49:50,936 DEBUG Loader:1164 - result row: EntityKey[org.hibernate.test.onetomanydelete.Child#1]
10:49:50,939 DEBUG Loader:1347 - Initializing object from ResultSet: [org.hibernate.test.onetomanydelete.Child#1]
10:49:50,941 DEBUG AbstractEntityPersister:1944 - Hydrating entity: [org.hibernate.test.onetomanydelete.Child#1]
10:49:50,944 DEBUG Loader:972 - found row of collection: [org.hibernate.test.onetomanydelete.Parent.children#1]
10:49:50,946 DEBUG CollectionLoadContext:112 - reading row
10:49:50,948 DEBUG DefaultLoadEventListener:154 - loading entity: [org.hibernate.test.onetomanydelete.Child#1]
10:49:50,951 DEBUG DefaultLoadEventListener:309 - attempting to resolve: [org.hibernate.test.onetomanydelete.Child#1]
10:49:50,954 DEBUG DefaultLoadEventListener:318 - resolved object in session cache: [org.hibernate.test.onetomanydelete.Child#1]
10:49:50,956 DEBUG Loader:709 - done processing result set (1 rows)
10:49:50,958 DEBUG AbstractBatcher:381 - about to close ResultSet (open ResultSets: 1, globally: 1)
10:49:50,960 DEBUG AbstractBatcher:366 - about to close PreparedStatement (open PreparedStatements: 1, globally: 1)
10:49:50,961 DEBUG AbstractBatcher:525 - closing statement
10:49:50,965 DEBUG Loader:839 - total objects hydrated: 1
10:49:50,967 DEBUG TwoPhaseLoad:107 - resolving associations for [org.hibernate.test.onetomanydelete.Child#1]
10:49:50,969 DEBUG DefaultLoadEventListener:154 - loading entity: [org.hibernate.test.onetomanydelete.Parent#1]
10:49:50,970 DEBUG DefaultLoadEventListener:227 - entity found in session cache
10:49:50,972 DEBUG TwoPhaseLoad:206 - done materializing entity [org.hibernate.test.onetomanydelete.Child#1]
10:49:50,981 DEBUG CollectionLoadContext:262 - 1 collections were found in result set for role: org.hibernate.test.onetomanydelete.Parent.children
10:49:50,991 DEBUG CollectionLoadContext:206 - collection fully initialized: [org.hibernate.test.onetomanydelete.Parent.children#1]
10:49:50,993 DEBUG CollectionLoadContext:272 - 1 collections initialized for role: org.hibernate.test.onetomanydelete.Parent.children
10:49:51,001 DEBUG StatefulPersistenceContext:748 - initializing non-lazy collections
10:49:51,003 DEBUG Loader:1935 - done loading collection
10:49:51,005 DEBUG DefaultInitializeCollectionEventListener:61 - collection initialized
10:49:51,015 DEBUG CascadingAction:45 - cascading to delete: org.hibernate.test.onetomanydelete.Child
10:49:51,016 DEBUG DefaultDeleteEventListener:90 - deleting a persistent instance
10:49:51,018 DEBUG DefaultDeleteEventListener:127 - deleting [org.hibernate.test.onetomanydelete.Child#1]
10:49:51,020 DEBUG SessionImpl:1301 - setting cache mode to: GET
10:49:51,021 DEBUG SessionImpl:1301 - setting cache mode to: GET
10:49:51,025 DEBUG SessionImpl:1301 - setting cache mode to: GET
10:49:51,028 DEBUG SessionImpl:1301 - setting cache mode to: GET
10:49:51,029 DEBUG Cascade:300 - done cascade ACTION_DELETE for collection: org.hibernate.test.onetomanydelete.Parent.children
10:49:51,031 DEBUG Cascade:259 - done processing cascade ACTION_DELETE for: org.hibernate.test.onetomanydelete.Parent
10:49:51,032 DEBUG SessionImpl:1301 - setting cache mode to: NORMAL
10:49:51,034 DEBUG SessionImpl:1301 - setting cache mode to: GET
10:49:51,035 DEBUG Cascade:237 - processing cascade ACTION_DELETE for: org.hibernate.test.onetomanydelete.Parent
10:49:51,037 DEBUG Cascade:259 - done processing cascade ACTION_DELETE for: org.hibernate.test.onetomanydelete.Parent
10:49:51,038 DEBUG SessionImpl:1301 - setting cache mode to: NORMAL
#### FLUSHING
10:49:51,040 DEBUG AbstractFlushingEventListener:58 - flushing session
10:49:51,042 DEBUG AbstractFlushingEventListener:111 - processing flush-time cascades
10:49:51,043 DEBUG AbstractFlushingEventListener:153 - dirty checking collections
10:49:51,045 DEBUG AbstractFlushingEventListener:170 - Flushing entities and processing referenced collections
10:49:51,047 DEBUG AbstractEntityPersister:2960 - org.hibernate.test.onetomanydelete.Parent.children is dirty
10:49:51,049 DEBUG DefaultFlushEntityEventListener:223 - Updating deleted entity: [org.hibernate.test.onetomanydelete.Parent#1]
10:49:51,053 DEBUG AbstractFlushingEventListener:209 - Processing unreferenced collections
10:49:51,055 DEBUG Collections:52 - Collection dereferenced: [org.hibernate.test.onetomanydelete.Parent.children#1]
10:49:51,057 DEBUG AbstractFlushingEventListener:223 - Scheduling collection removes/(re)creates/updates
10:49:51,060 DEBUG AbstractFlushingEventListener:85 - Flushed: 0 insertions, 1 updates, 2 deletions to 2 objects
10:49:51,063 DEBUG AbstractFlushingEventListener:91 - Flushed: 0 (re)creations, 0 updates, 1 removals to 1 collections
10:49:51,065 DEBUG Printer:83 - listing entities:
10:49:51,067 DEBUG Printer:90 - org.hibernate.test.onetomanydelete.Child{name=Child One, parent=org.hibernate.test.onetomanydelete.Parent#1, id=1}
10:49:51,069 DEBUG Printer:90 - org.hibernate.test.onetomanydelete.Parent{name=Parent, children=[org.hibernate.test.onetomanydelete.Child#1], id=1, version=0}
10:49:51,071 DEBUG AbstractFlushingEventListener:289 - executing flush
10:49:51,072 DEBUG ConnectionManager:463 - registering flush begin
10:49:51,074 DEBUG AbstractEntityPersister:2211 - Updating entity: [org.hibernate.test.onetomanydelete.Parent#1]
10:49:51,076 DEBUG AbstractEntityPersister:2213 - Existing version: 0 -> New version: 0
10:49:51,077 DEBUG AbstractBatcher:358 - about to open PreparedStatement (open PreparedStatements: 0, globally: 0)
10:49:51,081 DEBUG SQL:393 - 
    update
        Parent 
    set
        obj_version=?,
        name=? 
    where
        parent_id=? 
        and obj_version=?
10:49:51,083 DEBUG AbstractBatcher:476 - preparing statement
10:49:51,085 DEBUG AbstractEntityPersister:1905 - Dehydrating entity: [org.hibernate.test.onetomanydelete.Parent#1]
10:49:51,087 DEBUG AbstractBatcher:28 - Adding to batch
10:49:51,088 DEBUG NonstrictReadWriteCache:116 - Invalidating: org.hibernate.test.onetomanydelete.Parent#1
10:49:51,090 DEBUG AbstractBatcher:55 - Executing batch size: 1
10:49:51,092 DEBUG AbstractBatcher:366 - about to close PreparedStatement (open PreparedStatements: 1, globally: 1)
10:49:51,094 DEBUG AbstractBatcher:525 - closing statement
10:49:51,100 DEBUG NonstrictReadWriteCache:116 - Invalidating: org.hibernate.test.onetomanydelete.Parent.children#1
10:49:51,106 DEBUG AbstractEntityPersister:2319 - Deleting entity: [org.hibernate.test.onetomanydelete.Child#1]
10:49:51,109 DEBUG AbstractBatcher:358 - about to open PreparedStatement (open PreparedStatements: 0, globally: 0)
10:49:51,111 DEBUG SQL:393 - 
    delete 
    from
        Child 
    where
        child_id=?
10:49:51,113 DEBUG AbstractBatcher:476 - preparing statement
10:49:51,115 DEBUG AbstractBatcher:28 - Adding to batch
10:49:51,116 DEBUG NonstrictReadWriteCache:116 - Invalidating: org.hibernate.test.onetomanydelete.Child#1
10:49:51,118 DEBUG AbstractEntityPersister:2319 - Deleting entity: [org.hibernate.test.onetomanydelete.Parent#1]
10:49:51,121 DEBUG AbstractEntityPersister:2321 - Version: 0
10:49:51,122 DEBUG AbstractBatcher:55 - Executing batch size: 1
10:49:51,124 DEBUG AbstractBatcher:366 - about to close PreparedStatement (open PreparedStatements: 1, globally: 1)
10:49:51,126 DEBUG AbstractBatcher:525 - closing statement
10:49:51,127 DEBUG AbstractBatcher:358 - about to open PreparedStatement (open PreparedStatements: 0, globally: 0)
10:49:51,130 DEBUG SQL:393 - 
    delete 
    from
        Parent 
    where
        parent_id=? 
        and obj_version=?
10:49:51,132 DEBUG AbstractBatcher:476 - preparing statement
10:49:51,134 DEBUG AbstractBatcher:28 - Adding to batch
10:49:51,137 DEBUG NonstrictReadWriteCache:116 - Invalidating: org.hibernate.test.onetomanydelete.Parent#1
10:49:51,138 DEBUG AbstractBatcher:55 - Executing batch size: 1
10:49:51,139 DEBUG AbstractBatcher:366 - about to close PreparedStatement (open PreparedStatements: 1, globally: 1)
10:49:51,141 DEBUG AbstractBatcher:525 - closing statement
10:49:51,142 DEBUG ConnectionManager:472 - registering flush end
10:49:51,143 DEBUG AbstractFlushingEventListener:320 - post flush
10:49:51,145 DEBUG JDBCTransaction:103 - commit
10:49:51,148 DEBUG SessionImpl:339 - automatically flushing session
10:49:51,149 DEBUG AbstractFlushingEventListener:58 - flushing session
10:49:51,152 DEBUG AbstractFlushingEventListener:111 - processing flush-time cascades
10:49:51,153 DEBUG AbstractFlushingEventListener:153 - dirty checking collections
10:49:51,155 DEBUG AbstractFlushingEventListener:170 - Flushing entities and processing referenced collections
10:49:51,156 DEBUG AbstractFlushingEventListener:209 - Processing unreferenced collections
10:49:51,158 DEBUG AbstractFlushingEventListener:223 - Scheduling collection removes/(re)creates/updates
10:49:51,159 DEBUG AbstractFlushingEventListener:85 - Flushed: 0 insertions, 0 updates, 0 deletions to 0 objects
10:49:51,161 DEBUG AbstractFlushingEventListener:91 - Flushed: 0 (re)creations, 0 updates, 0 removals to 0 collections
10:49:51,162 DEBUG AbstractFlushingEventListener:289 - executing flush
10:49:51,165 DEBUG ConnectionManager:463 - registering flush begin
10:49:51,166 DEBUG ConnectionManager:472 - registering flush end
10:49:51,168 DEBUG AbstractFlushingEventListener:320 - post flush
10:49:51,170 DEBUG JDBCContext:194 - before transaction completion
10:49:51,171 DEBUG SessionImpl:395 - before transaction completion
10:49:51,172 DEBUG JDBCTransaction:116 - committed JDBC Connection
10:49:51,173 DEBUG JDBCContext:208 - after transaction completion
10:49:51,174 DEBUG ConnectionManager:398 - aggressively releasing JDBC connection
10:49:51,176 DEBUG ConnectionManager:435 - releasing JDBC connection [ (open PreparedStatements: 0, globally: 0) (open ResultSets: 0, globally: 0)]
10:49:51,177 DEBUG DriverManagerConnectionProvider:129 - returning connection to pool, pool size: 1
10:49:51,179 DEBUG SessionImpl:424 - after transaction completion
10:49:51,180 DEBUG NonstrictReadWriteCache:142 - Invalidating (again): org.hibernate.test.onetomanydelete.Parent#1
10:49:51,182 DEBUG NonstrictReadWriteCache:142 - Invalidating (again): org.hibernate.test.onetomanydelete.Parent.children#1
10:49:51,184 DEBUG NonstrictReadWriteCache:142 - Invalidating (again): org.hibernate.test.onetomanydelete.Child#1
10:49:51,186 DEBUG NonstrictReadWriteCache:142 - Invalidating (again): org.hibernate.test.onetomanydelete.Parent#1
10:49:51,187 DEBUG SessionImpl:275 - closing session
10:49:51,188 DEBUG ConnectionManager:369 - connection already null in cleanup : no action

> Possible bug with deleting versioned object (patch included)
> ------------------------------------------------------------
>
>          Key: HHH-1564
>          URL: http://opensource.atlassian.com/projects/hibernate/browse/HHH-1564
>      Project: Hibernate3
>         Type: Bug

>   Components: core
>     Versions: 3.1.2
>  Environment: 3.1rc2
>     Reporter: N Clayton
>  Attachments: onetomanydelete_test.tar.gz
>
>
> We're seeing an odd problem when trying to delete a row. The code that does this simply creates a new object, commits it, starts a new session, finds the object, deletes it. It dies with a constraint violation on an audit table, because hibernate is issuing an unnecessary update operation (and not incrementing the version either). Further debugging shows that Hibernate thinks that three properties on the object are 'modified'. These three are collections. One is the points collection, one owners and the other is systems. Hibernate seems to think that they are 'different' because null != an empty collection. So, it thinks it needs to update the object.  However; later on - it doesn't increment the version number - because it knows the object is to be deleted. Thus - a problem. 
> A complete description is here:
> http://forum.hibernate.org/viewtopic.php?t=950225&highlight=collectiontype+isdirty
> This appears to be fixed if we change CollectionType.isDirty() to be:
>    public boolean isDirty(Object old, Object current, boolean[] checkable, SessionImplementor session)
>          throws HibernateException {
>         if(checkable.length == 0) {
>             // Assume not checkable
>             return false;
>         }
>       return isDirty(old, current, session);
>    } 

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

[Hibernate-issues] [Hibernate-JIRA] Updated: (HHH-1564) Possible bug with deleting versioned object

An object relational-mapping (ORM) library for Java

[Hibernate-issues] [Hibernate-JIRA] Updated: (HHH-1564) Possible bug with deleting versioned object (patch included)