Hibernate Community • View topic - intermittend NULL entries in database

View unanswered posts | View active topics

Board index » Hibernate & Java Persistence » Hibernate Users

All times are UTC - 5 hours [ DST ]

intermittend NULL entries in database

Page 1 of 1

[ 6 posts ]

Previous topic | Next topic

Author

Message

draoi

Post subject: intermittend NULL entries in database

Posted: Tue Apr 19, 2005 9:50 am

Newbie

Joined: Tue Apr 19, 2005 7:34 am
Posts: 4

Hello,

I do not have much experience with Hibernate and encountered a problem I could not find a solution anywhere. The unpelasent thing is that it is an intermittent problem. It keeps occurring in version 2.1.8 as well as in 3.0.1.

I have two classes: WorkItem and WorkIssue. WorkItem has an array of WorkItems and and an array of WorkIssues. These classes are used to create a tree of items with every item having a list of issues. Generally everything is working fine. However, now and then a WorkIssue does not get correctly written to the DB. The columns WORK_ITEM_ID and ISSUE_IDX are both null (see mapping below). There is no exception from hibernate while saving. Only when trying to query the issue, a NullpointerException is thrown, as hibernate cannot resolve the parent.
A very interesting fact is that hibernate seems to be able to "fix" those wrong entries at a later time. Let me explain this: I once discovered two issues with null values. I deleted the first one via SQL and after refreshing my view of the database, the second one had the correct values inserted. It has to be said that the hibernate application is a server with several clients. My assumption is that after I deleted the first WorkIssue someone triggered the update of the parent WorkItem of the second issue and it was saved correctly this time. Unfortunately I do not have any outputs of this special incident or any other proof for my assumption. However, I have included below the hibernate debug output for two other issues. One has been saved with correct values, the other with incorrect values. The debug output is prepended with line numbers. I thought this might be helpful as you can get a rough idea how much was going on in the time not covered by the snippets I have included. As I have already mentioned, I have virtually no practical experience with hibernate and so I do not know whether the snippets are the ones needed to analyse this problem or not.

Could you please give me some advice how to get this problem solved?

Thank you very much
Jürgen

Hibernate version:
3.0.1 / 2.1.8

Mapping documents:
WorkItem class:

Code:

/**
 * @hibernate.class table="WORK_ITEM"
 *  lazy="false"  
 */
public class WorkItem {
 
    /**
     * @hibernate.many-to-one
     *  column="PARENT_ID"
     *  class="de.biotronik.timetracker.ws.WorkItem"
     */
    public WorkItem getParent() {...}
    
    /**
     * @hibernate.array
     *  cascade="all"
     * @hibernate.collection-key
     *  column="PARENT_ID"
     * @hibernate.collection-index
     *  column="CHILD_IDX"
     * @hibernate.collection-one-to-many  
     *  column="CHILD_ID"
     *  class="de.biotronik.timetracker.ws.WorkItem"
     */
    public WorkItem[] getChildren() {...}    
        
    /**
     * @hibernate.array
     *  cascade="all"
     * @hibernate.collection-key
     *  column="WORK_ITEM_ID"
     * @hibernate.collection-index
     *  column="ISSUE_IDX"
     * @hibernate.collection-one-to-many  
     *  column="ISSUE_ID"
     *  class="de.biotronik.timetracker.ws.WorkIssue"
     */
    public WorkIssue[] getWorkIssues() {...}
    
    /**
     * @hibernate.id 
     *  generator-class="increment"
     *  unsaved-value="-1"
     *  column="ID"
     */
    public long getId() {...}
}

WorkIssue class

Code:

/**
 * @hibernate.class table="WORK_ISSUE"
 */
public class WorkIssue {
   
    /**
     * @hibernate.id
     *  generator-class="increment"
     *  unsaved-value="-1"
     *  column="ID"
     */
    public long getId() {...}
    
    /**
     * @hibernate.many-to-one
     *  inverse="true"
     *  class="de.biotronik.timetracker.ws.WorkItem"
     *  column="WORK_ITEM_ID"
     */
    public WorkItem getWorkItem() {...}  
}

Code between sessionFactory.openSession() and session.close():

Code:

s = factory.openSession();
tx = s.beginTransaction();

synchronized (mItemLock) {

    // check if item exists
    WorkItem item = root.findItem(aWorkIssueBean.getWorkItemId());
                        
    issue = new WorkIssue(item, aWorkIssueBean);
    issue.setId(NEW_ISSUE_ID);
                                        
    item.addIssue(issue);

    s.saveOrUpdate(item);
    s.saveOrUpdate(issue);

}
tx.commit();
s.close();

Constructor of WorkIssue class:

Code:

public WorkIssue(WorkItem aWorkItem, WorkIssueBean aBean) throws HibernateException {
        
    mWorkItem = aWorkItem;
    ...
}

addIssue(...) method of WorkItem class:

Code:

public void addIssue(WorkIssue aIssue) {
            
    if (mIssues.indexOf(aIssue) != -1) {
            
        aIssue.setWorkItem(this);
        
    } else {
        
        // remove us from former work item (if any)
        if (aIssue.getWorkItem() != null) {
                
            aIssue.getWorkItem().mIssues.remove(aIssue);
        }
            
        // tell issue we are its new work item
        aIssue.setWorkItem(this);
            
        // add issue to our list
        mIssues.add(aIssue);            
    }
}

Name and version of the database you are using:
Oracle 9.2.0.5

Debug level Hibernate log excerpt:
WorkIssue that has been incorrectly saved to the DB:

Code:

12:09:37,722 DEBUG SessionImpl:789 - generated identifier: 585
12:09:37,724 DEBUG BatcherImpl:115 - reusing prepared statement
12:09:37,726 DEBUG SessionImpl:836 - saving [de.biotronik.timetracker.ws.WorkIssue#585]
12:09:37,729 DEBUG SQL:230 - update timetracker.WORK_ISSUE set WORK_ITEM_ID=?, ISSUE_IDX=? where ID=?
12:09:37,731 DEBUG Cascades:506 - done processing cascades for: de.biotronik.timetracker.ws.WorkItem
12:09:37,735 DEBUG BatcherImpl:115 - reusing prepared statement
12:09:37,736 DEBUG JDBCTransaction:59 - commit
...
12:09:38,094 DEBUG Printer:82 - de.biotronik.timetracker.ws.WorkIssue{startDate=2005-04-13 12:09:37, endDate=2005-04-13 13:09:37, workItem=WorkItem#92, id=585}
...
12:09:38,202 DEBUG EntityPersister:447 - Inserting entity: [de.biotronik.timetracker.ws.WorkIssue#585]
12:09:38,205 DEBUG BatcherImpl:211 - done closing: -2 open PreparedStatements, 0 open ResultSets
12:09:38,207 DEBUG BatcherImpl:204 - about to open: -2 open PreparedStatements, 0 open ResultSets
12:09:38,210 DEBUG BatcherImpl:275 - closing statement
12:09:38,212 DEBUG SQL:230 - insert into timetracker.WORK_ISSUE (WORK_ITEM_ID, START_DATE, END_DATE, ID) values (?, ?, ?, ?)
12:09:38,216 DEBUG BatcherImpl:204 - about to open: -1 open PreparedStatements, 0 open ResultSets
12:09:38,218 DEBUG BatcherImpl:253 - preparing statement
12:09:38,220 DEBUG SQL:230 - update timetracker.WORK_ITEM set PARENT_ID=?, CHILD_IDX=? where ID=?
12:09:38,223 DEBUG EntityPersister:382 - Dehydrating entity: [de.biotronik.timetracker.ws.WorkIssue#585]
12:09:38,225 DEBUG BatcherImpl:253 - preparing statement
12:09:38,232 DEBUG BatcherImpl:211 - done closing: -1 open PreparedStatements, 0 open ResultSets
12:09:38,234 DEBUG BasicCollectionPersister:532 - done inserting collection: 1 rows inserted
12:09:38,234 DEBUG BatcherImpl:275 - closing statement

WorkIssue that has been correctly saved to the DB:

Code:

12:06:32,257 DEBUG SessionImpl:789 - generated identifier: 584
12:06:32,259 DEBUG SessionImpl:836 - saving [de.biotronik.timetracker.ws.WorkIssue#584]
12:06:32,261 DEBUG Cascades:506 - done processing cascades for: de.biotronik.timetracker.ws.WorkItem
12:06:32,264 DEBUG JDBCTransaction:59 - commit
...
12:06:32,372 DEBUG Printer:82 - de.biotronik.timetracker.ws.WorkIssue{startDate=2005-04-13 12:06:32, endDate=2005-04-13 12:36:32, workItem=WorkItem#41, id=584}
...
12:06:32,376 DEBUG EntityPersister:447 - Inserting entity: [de.biotronik.timetracker.ws.WorkIssue#584]
12:06:32,378 DEBUG BatcherImpl:204 - about to open: -1 open PreparedStatements, 0 open ResultSets
12:06:32,381 DEBUG SQL:230 - insert into timetracker.WORK_ISSUE (WORK_ITEM_ID, START_DATE, END_DATE, ID) values (?, ?, ?, ?)
12:06:32,383 DEBUG BatcherImpl:253 - preparing statement
12:06:32,386 DEBUG EntityPersister:382 - Dehydrating entity: [de.biotronik.timetracker.ws.WorkIssue#584]
12:06:32,401 DEBUG BatcherImpl:211 - done closing: -1 open PreparedStatements, 0 open ResultSets
12:06:32,404 DEBUG BatcherImpl:275 - closing statement

Top

draoi

Post subject: Help anyone

Posted: Wed Apr 20, 2005 4:34 am

Newbie

Joined: Tue Apr 19, 2005 7:34 am
Posts: 4

Is there no one who has an idea what could be the problem?

Any help would be appreciated very much!!

Thank you

Top

yvijaykumar

Post subject: Null Values Save

Posted: Wed Apr 20, 2005 7:36 am

Beginner

Joined: Wed Apr 21, 2004 8:33 am
Posts: 27

I cudnt get teh DEBUG Trace . In the One that is saved wrong,
There is one Insert stateemnt and One Update Statement being generated.
Whereas the one in which is saved correclty there is only one Insert Statement. Can you tell why it is so?
Rgds
Vijay

Top

draoi

Post subject:

Posted: Wed Apr 20, 2005 11:24 am

Newbie

Joined: Tue Apr 19, 2005 7:34 am
Posts: 4

Hello Vijay,
thanks for your reply.

I am totally at a loss to explain what is going on. I just do not understand what hibernate is doing on the database layer and why it is doing what it is doing... :-(

In the meantime I used a JDBC spy to get the actual SQL statements that go to the database. Unfortunately I did not have the chance to log a one of the null-incidents, yet.

A correct issue insertion looks like this:

Code:

insert into timetrackerdev.WORK_ISSUE (WORK_ITEM_ID, START_DATE, END_DATE, ID) values (2, '2005-04-20 12:18:38.826', '2005-04-20 13:18:38.826', 1)
update timetrackerdev.WORK_ITEM set NAME='asdf', PARENT_ID=1, BOOKABLE='true', DELETABLE='true', REFERENCE_TIME=0 where ID=2
update timetrackerdev.WORK_ITEM set PARENT_ID=null, CHILD_IDX=null where PARENT_ID=2
update timetrackerdev.WORK_ISSUE set WORK_ITEM_ID=null, ISSUE_IDX=null where WORK_ITEM_ID=2
update timetrackerdev.WORK_ISSUE set WORK_ITEM_ID=2, ISSUE_IDX=0 where ID=1

The interesting fact is that the WORK_ITEM_ID and ISSUE_IDX are set to null prior to being set to the real values. Is it possible that some concurrent access to the DB in the wrong moment leads to the problem I am having?

Another thing that happened in the meantime is that there was one incident where the WORK_ISSUE.WORK_ITEM_ID has been set properly but the WORK_ISSUE.ISSUE_IDX has been set to NULL.

I hope that I will get a proper SQL trace for the problem tomorrow.

Top

yvijaykumar

Post subject: intermiddent null values

Posted: Thu Apr 21, 2005 4:43 am

Beginner

Joined: Wed Apr 21, 2004 8:33 am
Posts: 27

Hi Draoi,
Just synchronize the method where you are trying to save the stuff and check the log trace. And do post the enitre error trace, and probaly some explanation of what exaclty is the business logic. And also you can enable p6spy logging which will show you the exact SQL queries

Thanks

Top

draoi

Post subject:

Posted: Thu Apr 21, 2005 8:57 am

Newbie

Joined: Tue Apr 19, 2005 7:34 am
Posts: 4

I synchronize on a lock object whenever I do some hibernate action (mItemLock, see code above). Below is the complete hibernate debug output for the saving of two issues. The #585 fails, #584 is successful.
The hibernate application is a server that accepts requests from clients to associate issues with certain items. The items are stored as a tree. I open and close a new session for every incoming request.

The complete debug output for the failed saving of issue #585 is this:

Code:

12:09:37,722 DEBUG SessionImpl:789 - generated identifier: 585
12:09:37,724 DEBUG BatcherImpl:115 - reusing prepared statement
12:09:37,726 DEBUG SessionImpl:836 - saving [de.biotronik.timetracker.ws.WorkIssue#585]
12:09:37,729 DEBUG SQL:230 - update timetracker.WORK_ISSUE set WORK_ITEM_ID=?, ISSUE_IDX=? where ID=?
12:09:37,731 DEBUG Cascades:506 - done processing cascades for: de.biotronik.timetracker.ws.WorkItem
12:09:37,735 DEBUG BatcherImpl:115 - reusing prepared statement
12:09:37,736 DEBUG JDBCTransaction:59 - commit
12:09:37,738 DEBUG SQL:230 - update timetracker.WORK_ISSUE set WORK_ITEM_ID=?, ISSUE_IDX=? where ID=?
12:09:37,745 DEBUG SessionImpl:2267 - flushing session
12:09:37,749 DEBUG Cascades:497 - processing cascades for: de.biotronik.timetracker.ws.WorkItem
12:09:37,750 DEBUG BatcherImpl:115 - reusing prepared statement
12:09:37,752 DEBUG Cascades:524 - cascading to collection: de.biotronik.timetracker.ws.WorkItem.children
12:09:37,754 DEBUG SQL:230 - update timetracker.WORK_ISSUE set WORK_ITEM_ID=?, ISSUE_IDX=? where ID=?
12:09:37,758 DEBUG Cascades:524 - cascading to collection: de.biotronik.timetracker.ws.WorkItem.workIssues
12:09:37,762 DEBUG BatcherImpl:115 - reusing prepared statement
12:09:37,763 DEBUG Cascades:113 - cascading to saveOrUpdate()
12:09:37,765 DEBUG SQL:230 - update timetracker.WORK_ISSUE set WORK_ITEM_ID=?, ISSUE_IDX=? where ID=?
12:09:37,768 DEBUG SessionImpl:1382 - saveOrUpdate() persistent instance
12:09:37,773 DEBUG Cascades:113 - cascading to saveOrUpdate()
12:09:37,774 DEBUG BatcherImpl:115 - reusing prepared statement
12:09:37,776 DEBUG SessionImpl:1382 - saveOrUpdate() persistent instance
12:09:37,778 DEBUG SQL:230 - update timetracker.WORK_ISSUE set WORK_ITEM_ID=?, ISSUE_IDX=? where ID=?
12:09:37,781 DEBUG Cascades:113 - cascading to saveOrUpdate()
12:09:37,785 DEBUG BasicCollectionPersister:532 - done inserting collection: 5 rows inserted
12:09:37,786 DEBUG SessionImpl:1382 - saveOrUpdate() persistent instance
12:09:37,789 DEBUG BasicCollectionPersister:510 - Inserting collection: [de.biotronik.timetracker.ws.WorkItem.children#1]
12:09:37,791 DEBUG Cascades:113 - cascading to saveOrUpdate()
12:09:37,793 DEBUG BatcherImpl:211 - done closing: -2 open PreparedStatements, 0 open ResultSets
12:09:37,796 DEBUG SessionImpl:1382 - saveOrUpdate() persistent instance
12:09:37,798 DEBUG BatcherImpl:275 - closing statement
12:09:37,801 DEBUG Cascades:113 - cascading to saveOrUpdate()
12:09:37,804 DEBUG BatcherImpl:204 - about to open: -2 open PreparedStatements, 0 open ResultSets
12:09:37,806 DEBUG SessionImpl:1382 - saveOrUpdate() persistent instance
12:09:37,808 DEBUG SQL:230 - update timetracker.WORK_ITEM set PARENT_ID=?, CHILD_IDX=? where ID=?
12:09:37,811 DEBUG Cascades:113 - cascading to saveOrUpdate()
12:09:37,813 DEBUG BatcherImpl:253 - preparing statement
12:09:37,820 DEBUG SessionImpl:1382 - saveOrUpdate() persistent instance
12:09:37,825 DEBUG BatcherImpl:115 - reusing prepared statement
12:09:37,825 DEBUG Cascades:113 - cascading to saveOrUpdate()
12:09:37,828 DEBUG SQL:230 - update timetracker.WORK_ITEM set PARENT_ID=?, CHILD_IDX=? where ID=?
12:09:37,830 DEBUG SessionImpl:1382 - saveOrUpdate() persistent instance
12:09:37,834 DEBUG BatcherImpl:115 - reusing prepared statement
12:09:37,835 DEBUG Cascades:113 - cascading to saveOrUpdate()
12:09:37,837 DEBUG SQL:230 - update timetracker.WORK_ITEM set PARENT_ID=?, CHILD_IDX=? where ID=?
12:09:37,840 DEBUG SessionImpl:1382 - saveOrUpdate() persistent instance
12:09:37,844 DEBUG BatcherImpl:115 - reusing prepared statement
12:09:37,845 DEBUG Cascades:113 - cascading to saveOrUpdate()
12:09:37,847 DEBUG SQL:230 - update timetracker.WORK_ITEM set PARENT_ID=?, CHILD_IDX=? where ID=?
12:09:37,849 DEBUG SessionImpl:1382 - saveOrUpdate() persistent instance
12:09:37,853 DEBUG BatcherImpl:115 - reusing prepared statement
12:09:37,854 DEBUG Cascades:113 - cascading to saveOrUpdate()
12:09:37,856 DEBUG SQL:230 - update timetracker.WORK_ITEM set PARENT_ID=?, CHILD_IDX=? where ID=?
12:09:37,859 DEBUG SessionImpl:1382 - saveOrUpdate() persistent instance
12:09:37,863 DEBUG BatcherImpl:115 - reusing prepared statement
12:09:37,864 DEBUG Cascades:113 - cascading to saveOrUpdate()
12:09:37,866 DEBUG SQL:230 - update timetracker.WORK_ITEM set PARENT_ID=?, CHILD_IDX=? where ID=?
12:09:37,869 DEBUG SessionImpl:1382 - saveOrUpdate() persistent instance
12:09:37,873 DEBUG BatcherImpl:115 - reusing prepared statement
12:09:37,874 DEBUG Cascades:113 - cascading to saveOrUpdate()
12:09:37,876 DEBUG SQL:230 - update timetracker.WORK_ITEM set PARENT_ID=?, CHILD_IDX=? where ID=?
12:09:37,879 DEBUG SessionImpl:1382 - saveOrUpdate() persistent instance
12:09:37,882 DEBUG BatcherImpl:115 - reusing prepared statement
12:09:37,884 DEBUG Cascades:113 - cascading to saveOrUpdate()
12:09:37,891 DEBUG SQL:230 - update timetracker.WORK_ITEM set PARENT_ID=?, CHILD_IDX=? where ID=?
12:09:37,893 DEBUG SessionImpl:1382 - saveOrUpdate() persistent instance
12:09:37,897 DEBUG BatcherImpl:115 - reusing prepared statement
12:09:37,898 DEBUG Cascades:113 - cascading to saveOrUpdate()
12:09:37,903 DEBUG SQL:230 - update timetracker.WORK_ITEM set PARENT_ID=?, CHILD_IDX=? where ID=?
12:09:37,903 DEBUG SessionImpl:1382 - saveOrUpdate() persistent instance
12:09:37,908 DEBUG BatcherImpl:115 - reusing prepared statement
12:09:37,909 DEBUG Cascades:113 - cascading to saveOrUpdate()
12:09:37,912 DEBUG SQL:230 - update timetracker.WORK_ITEM set PARENT_ID=?, CHILD_IDX=? where ID=?
12:09:37,914 DEBUG SessionImpl:1382 - saveOrUpdate() persistent instance
12:09:37,919 DEBUG Cascades:113 - cascading to saveOrUpdate()
12:09:37,920 DEBUG BatcherImpl:115 - reusing prepared statement
12:09:37,921 DEBUG SessionImpl:1382 - saveOrUpdate() persistent instance
12:09:37,926 DEBUG SQL:230 - update timetracker.WORK_ITEM set PARENT_ID=?, CHILD_IDX=? where ID=?
12:09:37,927 DEBUG Cascades:113 - cascading to saveOrUpdate()
12:09:37,931 DEBUG BatcherImpl:115 - reusing prepared statement
12:09:37,932 DEBUG SessionImpl:1382 - saveOrUpdate() persistent instance
12:09:37,935 DEBUG SQL:230 - update timetracker.WORK_ITEM set PARENT_ID=?, CHILD_IDX=? where ID=?
12:09:37,937 DEBUG Cascades:113 - cascading to saveOrUpdate()
12:09:37,942 DEBUG SessionImpl:1382 - saveOrUpdate() persistent instance
12:09:37,942 DEBUG BasicCollectionPersister:532 - done inserting collection: 12 rows inserted
12:09:37,944 DEBUG Cascades:506 - done processing cascades for: de.biotronik.timetracker.ws.WorkItem
12:09:37,946 DEBUG BasicCollectionPersister:510 - Inserting collection: [de.biotronik.timetracker.ws.WorkItem.workIssues#1]
12:09:37,949 DEBUG SessionImpl:2467 - Flushing entities and processing referenced collections
12:09:37,954 DEBUG BatcherImpl:211 - done closing: -2 open PreparedStatements, 0 open ResultSets
12:09:37,954 DEBUG SessionImpl:2561 - Updating entity: [de.biotronik.timetracker.ws.WorkItem#92]
12:09:37,957 DEBUG BatcherImpl:275 - closing statement
12:09:37,964 DEBUG SessionImpl:2916 - Collection found: [de.biotronik.timetracker.ws.WorkItem.children#92], was: [<unreferenced>]
12:09:37,967 DEBUG BatcherImpl:204 - about to open: -2 open PreparedStatements, 0 open ResultSets
12:09:37,969 DEBUG SessionImpl:2916 - Collection found: [de.biotronik.timetracker.ws.WorkItem.workIssues#92], was: [<unreferenced>]
12:09:37,972 DEBUG SQL:230 - update timetracker.WORK_ISSUE set WORK_ITEM_ID=?, ISSUE_IDX=? where ID=?
12:09:37,974 DEBUG SessionImpl:2561 - Updating entity: [de.biotronik.timetracker.ws.WorkIssue#416]
12:09:37,977 DEBUG BatcherImpl:253 - preparing statement
12:09:37,980 DEBUG SessionImpl:2561 - Updating entity: [de.biotronik.timetracker.ws.WorkIssue#418]
12:09:37,985 DEBUG SessionImpl:2561 - Updating entity: [de.biotronik.timetracker.ws.WorkIssue#427]
12:09:37,985 DEBUG BasicCollectionPersister:532 - done inserting collection: 1 rows inserted
12:09:37,987 DEBUG SessionImpl:2561 - Updating entity: [de.biotronik.timetracker.ws.WorkIssue#436]
12:09:37,990 DEBUG BasicCollectionPersister:510 - Inserting collection: [de.biotronik.timetracker.ws.WorkItem.children#2]
12:09:37,992 DEBUG SessionImpl:2561 - Updating entity: [de.biotronik.timetracker.ws.WorkIssue#452]
12:09:37,995 DEBUG BatcherImpl:211 - done closing: -2 open PreparedStatements, 0 open ResultSets
12:09:37,998 DEBUG SessionImpl:2561 - Updating entity: [de.biotronik.timetracker.ws.WorkIssue#512]
12:09:38,001 DEBUG BatcherImpl:275 - closing statement
12:09:38,003 DEBUG SessionImpl:2561 - Updating entity: [de.biotronik.timetracker.ws.WorkIssue#516]
12:09:38,007 DEBUG BatcherImpl:204 - about to open: -2 open PreparedStatements, 0 open ResultSets
12:09:38,009 DEBUG SessionImpl:2561 - Updating entity: [de.biotronik.timetracker.ws.WorkIssue#521]
12:09:38,012 DEBUG SQL:230 - update timetracker.WORK_ITEM set PARENT_ID=?, CHILD_IDX=? where ID=?
12:09:38,014 DEBUG SessionImpl:2561 - Updating entity: [de.biotronik.timetracker.ws.WorkIssue#527]
12:09:38,017 DEBUG BatcherImpl:253 - preparing statement
12:09:38,019 DEBUG SessionImpl:2561 - Updating entity: [de.biotronik.timetracker.ws.WorkIssue#529]
12:09:38,025 DEBUG SessionImpl:2561 - Updating entity: [de.biotronik.timetracker.ws.WorkIssue#530]
12:09:38,027 DEBUG SessionImpl:2561 - Updating entity: [de.biotronik.timetracker.ws.WorkIssue#568]
12:09:38,027 DEBUG BatcherImpl:115 - reusing prepared statement
12:09:38,029 DEBUG SessionImpl:2561 - Updating entity: [de.biotronik.timetracker.ws.WorkIssue#570]
12:09:38,032 DEBUG SQL:230 - update timetracker.WORK_ITEM set PARENT_ID=?, CHILD_IDX=? where ID=?
12:09:38,039 DEBUG SessionImpl:2561 - Updating entity: [de.biotronik.timetracker.ws.WorkIssue#572]
12:09:38,044 DEBUG BatcherImpl:115 - reusing prepared statement
12:09:38,045 DEBUG SessionImpl:2561 - Updating entity: [de.biotronik.timetracker.ws.WorkIssue#574]
12:09:38,048 DEBUG SQL:230 - update timetracker.WORK_ITEM set PARENT_ID=?, CHILD_IDX=? where ID=?
12:09:38,049 DEBUG SessionImpl:2561 - Updating entity: [de.biotronik.timetracker.ws.WorkIssue#577]
12:09:38,054 DEBUG BatcherImpl:115 - reusing prepared statement
12:09:38,054 DEBUG SessionImpl:2561 - Updating entity: [de.biotronik.timetracker.ws.WorkIssue#580]
12:09:38,059 DEBUG SQL:230 - update timetracker.WORK_ITEM set PARENT_ID=?, CHILD_IDX=? where ID=?
12:09:38,059 DEBUG SessionImpl:2808 - Processing unreferenced collections
12:09:38,063 DEBUG BatcherImpl:115 - reusing prepared statement
12:09:38,064 DEBUG SessionImpl:2822 - Scheduling collection removes/(re)creates/updates
12:09:38,067 DEBUG SQL:230 - update timetracker.WORK_ITEM set PARENT_ID=?, CHILD_IDX=? where ID=?
12:09:38,069 DEBUG SessionImpl:2291 - Flushed: 1 insertions, 18 updates, 0 deletions to 19 objects
12:09:38,074 DEBUG BatcherImpl:115 - reusing prepared statement
12:09:38,074 DEBUG SessionImpl:2296 - Flushed: 2 (re)creations, 0 updates, 2 removals to 2 collections
12:09:38,077 DEBUG SQL:230 - update timetracker.WORK_ITEM set PARENT_ID=?, CHILD_IDX=? where ID=?
12:09:38,080 DEBUG Printer:75 - listing entities:
12:09:38,085 DEBUG BasicCollectionPersister:532 - done inserting collection: 6 rows inserted
12:09:38,089 DEBUG BasicCollectionPersister:510 - Inserting collection: [de.biotronik.timetracker.ws.WorkItem.workIssues#2]
12:09:38,089 DEBUG Printer:82 - de.biotronik.timetracker.ws.WorkIssue{startDate=2005-04-13 09:40:00, endDate=2005-04-13 09:43:14, workItem=WorkItem#92, id=568}
12:09:38,092 DEBUG BatcherImpl:211 - done closing: -2 open PreparedStatements, 0 open ResultSets
12:09:38,094 DEBUG Printer:82 - de.biotronik.timetracker.ws.WorkIssue{startDate=2005-04-13 12:09:37, endDate=2005-04-13 13:09:37, workItem=WorkItem#92, id=585}
12:09:38,097 DEBUG BatcherImpl:275 - closing statement
12:09:38,099 DEBUG Printer:82 - de.biotronik.timetracker.ws.WorkIssue{startDate=2005-04-11 17:43:58, endDate=2005-04-11 17:53:55, workItem=WorkItem#92, id=529}
12:09:38,103 DEBUG BatcherImpl:204 - about to open: -2 open PreparedStatements, 0 open ResultSets
12:09:38,105 DEBUG Printer:82 - de.biotronik.timetracker.ws.WorkIssue{startDate=2005-04-11 10:31:32, endDate=2005-04-11 11:31:32, workItem=WorkItem#92, id=512}
12:09:38,108 DEBUG SQL:230 - update timetracker.WORK_ISSUE set WORK_ITEM_ID=?, ISSUE_IDX=? where ID=?
12:09:38,116 DEBUG Printer:82 - de.biotronik.timetracker.ws.WorkIssue{startDate=2005-04-11 12:54:37, endDate=2005-04-11 13:54:37, workItem=WorkItem#92, id=521}
12:09:38,119 DEBUG BatcherImpl:253 - preparing statement
12:09:38,122 DEBUG Printer:82 - de.biotronik.timetracker.ws.WorkIssue{startDate=2005-04-07 12:04:57, endDate=2005-04-07 12:46:11, workItem=WorkItem#92, id=427}
12:09:38,127 DEBUG Printer:82 - de.biotronik.timetracker.ws.WorkIssue{startDate=2005-04-07 10:15:01, endDate=2005-04-07 11:07:46, workItem=WorkItem#92, id=418}
12:09:38,127 DEBUG BatcherImpl:115 - reusing prepared statement
12:09:38,130 DEBUG Printer:82 - de.biotronik.timetracker.ws.WorkIssue{startDate=2005-04-11 15:24:30, endDate=2005-04-11 15:24:49, workItem=WorkItem#92, id=527}
12:09:38,134 DEBUG SQL:230 - update timetracker.WORK_ISSUE set WORK_ITEM_ID=?, ISSUE_IDX=? where ID=?
12:09:38,136 DEBUG Printer:82 - de.biotronik.timetracker.ws.WorkIssue{startDate=2005-04-13 09:43:58, endDate=2005-04-13 09:44:09, workItem=WorkItem#92, id=570}
12:09:38,139 DEBUG BatcherImpl:115 - reusing prepared statement
12:09:38,141 DEBUG Printer:82 - de.biotronik.timetracker.ws.WorkItem{referenceTime=0, bookable=true, deletable=true, workIssues=[WorkIssue#416, WorkIssue#418, WorkIssue#427, WorkIssue#436, WorkIssue#452, WorkIssue#512, WorkIssue#516, WorkIssue#521, WorkIssue#527, WorkIssue#529, WorkIssue#530, WorkIssue#568, WorkIssue#570, WorkIssue#572, WorkIssue#574, WorkIssue#577, WorkIssue#580, WorkIssue#585], name=BugFixes, children=[], parent=WorkItem#7, id=92}
12:09:38,143 DEBUG SQL:230 - update timetracker.WORK_ISSUE set WORK_ITEM_ID=?, ISSUE_IDX=? where ID=?
12:09:38,146 DEBUG Printer:82 - de.biotronik.timetracker.ws.WorkIssue{startDate=2005-04-11 11:32:00, endDate=2005-04-11 12:32:00, workItem=WorkItem#92, id=516}
12:09:38,150 DEBUG BatcherImpl:115 - reusing prepared statement
12:09:38,151 DEBUG Printer:82 - de.biotronik.timetracker.ws.WorkIssue{startDate=2005-04-13 09:44:21, endDate=2005-04-13 09:45:09, workItem=WorkItem#92, id=572}
12:09:38,154 DEBUG SQL:230 - update timetracker.WORK_ISSUE set WORK_ITEM_ID=?, ISSUE_IDX=? where ID=?
12:09:38,157 DEBUG Printer:82 - de.biotronik.timetracker.ws.WorkIssue{startDate=2005-04-07 08:14:00, endDate=2005-04-07 10:14:42, workItem=WorkItem#92, id=416}
12:09:38,161 DEBUG BatcherImpl:115 - reusing prepared statement
12:09:38,162 DEBUG Printer:82 - de.biotronik.timetracker.ws.WorkIssue{startDate=2005-04-13 11:33:43, endDate=2005-04-13 11:36:12, workItem=WorkItem#92, id=580}
12:09:38,164 DEBUG SQL:230 - update timetracker.WORK_ISSUE set WORK_ITEM_ID=?, ISSUE_IDX=? where ID=?
12:09:38,167 DEBUG Printer:82 - de.biotronik.timetracker.ws.WorkIssue{startDate=2005-04-07 16:16:12, endDate=2005-04-07 16:25:07, workItem=WorkItem#92, id=452}
12:09:38,172 DEBUG BatcherImpl:115 - reusing prepared statement
12:09:38,172 DEBUG Printer:82 - de.biotronik.timetracker.ws.WorkIssue{startDate=2005-04-11 17:55:07, endDate=2005-04-11 18:55:07, workItem=WorkItem#92, id=530}
12:09:38,175 DEBUG SQL:230 - update timetracker.WORK_ISSUE set WORK_ITEM_ID=?, ISSUE_IDX=? where ID=?
12:09:38,178 DEBUG Printer:82 - de.biotronik.timetracker.ws.WorkIssue{startDate=2005-04-13 09:45:24, endDate=2005-04-13 10:00:00, workItem=WorkItem#92, id=574}
12:09:38,181 DEBUG BatcherImpl:115 - reusing prepared statement
12:09:38,183 DEBUG Printer:82 - de.biotronik.timetracker.ws.WorkIssue{startDate=2005-04-13 11:09:28, endDate=2005-04-13 12:09:28, workItem=WorkItem#92, id=577}
12:09:38,187 DEBUG SQL:230 - update timetracker.WORK_ISSUE set WORK_ITEM_ID=?, ISSUE_IDX=? where ID=?
12:09:38,192 DEBUG Printer:82 - de.biotronik.timetracker.ws.WorkIssue{startDate=2005-04-07 14:02:30, endDate=2005-04-07 14:54:00, workItem=WorkItem#92, id=436}
12:09:38,196 DEBUG BasicCollectionPersister:532 - done inserting collection: 7 rows inserted
12:09:38,197 DEBUG SessionImpl:2380 - executing flush
12:09:38,200 DEBUG BasicCollectionPersister:510 - Inserting collection: [de.biotronik.timetracker.ws.WorkItem.children#5]
12:09:38,202 DEBUG EntityPersister:447 - Inserting entity: [de.biotronik.timetracker.ws.WorkIssue#585]
12:09:38,205 DEBUG BatcherImpl:211 - done closing: -2 open PreparedStatements, 0 open ResultSets
12:09:38,207 DEBUG BatcherImpl:204 - about to open: -2 open PreparedStatements, 0 open ResultSets
12:09:38,210 DEBUG BatcherImpl:275 - closing statement
12:09:38,212 DEBUG SQL:230 - insert into timetracker.WORK_ISSUE (WORK_ITEM_ID, START_DATE, END_DATE, ID) values (?, ?, ?, ?)
12:09:38,216 DEBUG BatcherImpl:204 - about to open: -1 open PreparedStatements, 0 open ResultSets
12:09:38,218 DEBUG BatcherImpl:253 - preparing statement
12:09:38,220 DEBUG SQL:230 - update timetracker.WORK_ITEM set PARENT_ID=?, CHILD_IDX=? where ID=?
12:09:38,223 DEBUG EntityPersister:382 - Dehydrating entity: [de.biotronik.timetracker.ws.WorkIssue#585]
12:09:38,225 DEBUG BatcherImpl:253 - preparing statement
12:09:38,232 DEBUG BatcherImpl:211 - done closing: -1 open PreparedStatements, 0 open ResultSets
12:09:38,234 DEBUG BasicCollectionPersister:532 - done inserting collection: 1 rows inserted
12:09:38,234 DEBUG BatcherImpl:275 - closing statement

As reference here is another issue that did not fail (584):

Code:

12:06:32,257 DEBUG SessionImpl:789 - generated identifier: 584
12:06:32,259 DEBUG SessionImpl:836 - saving [de.biotronik.timetracker.ws.WorkIssue#584]
12:06:32,261 DEBUG Cascades:506 - done processing cascades for: de.biotronik.timetracker.ws.WorkItem
12:06:32,264 DEBUG JDBCTransaction:59 - commit
12:06:32,266 DEBUG SessionImpl:2267 - flushing session
12:06:32,268 DEBUG Cascades:497 - processing cascades for: de.biotronik.timetracker.ws.WorkItem
12:06:32,270 DEBUG Cascades:524 - cascading to collection: de.biotronik.timetracker.ws.WorkItem.children
12:06:32,273 DEBUG Cascades:524 - cascading to collection: de.biotronik.timetracker.ws.WorkItem.workIssues
12:06:32,275 DEBUG Cascades:113 - cascading to saveOrUpdate()
12:06:32,278 DEBUG SessionImpl:1382 - saveOrUpdate() persistent instance
12:06:32,285 DEBUG Cascades:113 - cascading to saveOrUpdate()
12:06:32,287 DEBUG SessionImpl:1382 - saveOrUpdate() persistent instance
12:06:32,290 DEBUG Cascades:113 - cascading to saveOrUpdate()
12:06:32,292 DEBUG SessionImpl:1382 - saveOrUpdate() persistent instance
12:06:32,294 DEBUG Cascades:113 - cascading to saveOrUpdate()
12:06:32,297 DEBUG SessionImpl:1382 - saveOrUpdate() persistent instance
12:06:32,299 DEBUG Cascades:113 - cascading to saveOrUpdate()
12:06:32,302 DEBUG SessionImpl:1382 - saveOrUpdate() persistent instance
12:06:32,304 DEBUG Cascades:506 - done processing cascades for: de.biotronik.timetracker.ws.WorkItem
12:06:32,306 DEBUG SessionImpl:2467 - Flushing entities and processing referenced collections
12:06:32,309 DEBUG SessionImpl:2561 - Updating entity: [de.biotronik.timetracker.ws.WorkItem#41]
12:06:32,311 DEBUG SessionImpl:2916 - Collection found: [de.biotronik.timetracker.ws.WorkItem.children#41], was: [<unreferenced>]
12:06:32,314 DEBUG SessionImpl:2916 - Collection found: [de.biotronik.timetracker.ws.WorkItem.workIssues#41], was: [<unreferenced>]
12:06:32,316 DEBUG SessionImpl:2561 - Updating entity: [de.biotronik.timetracker.ws.WorkIssue#60]
12:06:32,318 DEBUG SessionImpl:2561 - Updating entity: [de.biotronik.timetracker.ws.WorkIssue#156]
12:06:32,321 DEBUG SessionImpl:2561 - Updating entity: [de.biotronik.timetracker.ws.WorkIssue#185]
12:06:32,323 DEBUG SessionImpl:2561 - Updating entity: [de.biotronik.timetracker.ws.WorkIssue#372]
12:06:32,325 DEBUG SessionImpl:2808 - Processing unreferenced collections
12:06:32,328 DEBUG SessionImpl:2822 - Scheduling collection removes/(re)creates/updates
12:06:32,330 DEBUG SessionImpl:2291 - Flushed: 1 insertions, 5 updates, 0 deletions to 6 objects
12:06:32,332 DEBUG SessionImpl:2296 - Flushed: 2 (re)creations, 0 updates, 2 removals to 2 collections
12:06:32,334 DEBUG Printer:75 - listing entities:
12:06:32,340 DEBUG Printer:82 - de.biotronik.timetracker.ws.WorkItem{referenceTime=0, bookable=true, deletable=true, workIssues=[WorkIssue#60, WorkIssue#156, WorkIssue#185, WorkIssue#372, WorkIssue#584], name=User Help Desk, children=[], parent=WorkItem#20, id=41}
12:06:32,344 DEBUG SessionImpl:560 - opened session
12:06:32,355 DEBUG JDBCTransaction:37 - begin
12:06:32,356 DEBUG Printer:82 - de.biotronik.timetracker.ws.WorkIssue{startDate=2005-03-29 12:52:02, endDate=2005-03-29 13:16:21, workItem=WorkItem#41, id=185}
12:06:32,357 DEBUG DriverManagerConnectionProvider:84 - total checked-out connections: -3
12:06:32,360 DEBUG Printer:82 - de.biotronik.timetracker.ws.WorkIssue{startDate=2005-03-17 10:01:21, endDate=2005-03-17 11:01:21, workItem=WorkItem#41, id=60}
12:06:32,361 DEBUG DriverManagerConnectionProvider:100 - opening new JDBC connection
12:06:32,364 DEBUG Printer:82 - de.biotronik.timetracker.ws.WorkIssue{startDate=2005-03-23 17:19:07, endDate=2005-03-23 17:44:22, workItem=WorkItem#41, id=156}
12:06:32,369 DEBUG Printer:82 - de.biotronik.timetracker.ws.WorkIssue{startDate=2005-04-06 11:49:12, endDate=2005-04-06 18:28:00, workItem=WorkItem#41, id=372}
12:06:32,372 DEBUG Printer:82 - de.biotronik.timetracker.ws.WorkIssue{startDate=2005-04-13 12:06:32, endDate=2005-04-13 12:36:32, workItem=WorkItem#41, id=584}
12:06:32,374 DEBUG SessionImpl:2380 - executing flush
12:06:32,376 DEBUG EntityPersister:447 - Inserting entity: [de.biotronik.timetracker.ws.WorkIssue#584]
12:06:32,378 DEBUG BatcherImpl:204 - about to open: -1 open PreparedStatements, 0 open ResultSets
12:06:32,381 DEBUG SQL:230 - insert into timetracker.WORK_ISSUE (WORK_ITEM_ID, START_DATE, END_DATE, ID) values (?, ?, ?, ?)
12:06:32,383 DEBUG BatcherImpl:253 - preparing statement
12:06:32,386 DEBUG EntityPersister:382 - Dehydrating entity: [de.biotronik.timetracker.ws.WorkIssue#584]
12:06:32,401 DEBUG BatcherImpl:211 - done closing: -1 open PreparedStatements, 0 open ResultSets
12:06:32,404 DEBUG BatcherImpl:275 - closing statement

Top

Page 1 of 1

[ 6 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