Introduction

I had a weird problem with a collection and would like to find out:
- why it only happened in one specific use case
- whether my fix is valid

Background

I have a Person class with a many-to-many relationship to the PersonKeyword class, i.e. people can have one or more keywords assigned to them. This is modelled by each Person having a SortedSet of PersonKeywords. This set is implemented as a TreeSet that sorts using my own KeywordComparator class.

Problem

When I ask Hibernate to update a Person, if the person has changed from having one assigned keyword to exactly one other assigned keyword, I get the error "org.hibernate.AssertionFailure: collection [au.com.bisinfo.cmgr.logic.keyword.KeywordType.keywords] was not processed by flush()". Every other combination of keywords works fine, e.g. going from zero to one keyword, one to zero, one to two, two to one, two to two, etc.

This problem happens both in production (it's a web application using OSIV) and in my functional tests (where I invoke the keyword service directly and manually flush the Hibernate session afterwards, in order to inspect the database within the same transaction).

Because the association is many-to-many, I have to maintain both ends of it when making any changes, so my Person method for changing the assigned keywords looks something like this:



My Fix (not sure why it works)

If I change the line marked "***" above to "keywords = null;", my app works properly for all combinations of before & after keywords.

My Questions

1. Why did this problem only happen when changing from exactly one keyword to exactly one other, and not in any other case?
2. Why does my fix work?

Thanks for any answers anyone can give ... my config is below.

Cheers,

Andrew

-------------------------------------------------------------------

Hibernate version: 3.1.3

Mapping documents:

Hopefully you only need the Person mapping document (I can add the others if necessary):



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

My DAO has a reference to the SessionFactory. My DAO's update method looks like this:



Full stack trace of any exception that occurs:



Name and version of the database you are using: HSQLDB 1.8.0.1 in test, MS SQL Server 2000 in production (same problem in both)

The generated SQL (show_sql=true):



Debug level Hibernate log excerpt:

[code]
10:01:47,142 DEBUG [EntityLoader] Static select for entity au.com.bisinfo.cmgr.logic.keyword.EventKeywordType: select eventkeywo0_.id as id8_0_, eventkeywo0_.name as name8_0_ from keyword_type eventkeywo0_ where eventkeywo0_.id=? and eventkeywo0_.class='event'
10:01:47,142 DEBUG [EntityLoader] Static select for entity au.com.bisinfo.cmgr.logic.keyword.EventKeywordType: select eventkeywo0_.id as id8_0_, eventkeywo0_.name as name8_0_ from keyword_type eventkeywo0_ where eventkeywo0_.id=? and eventkeywo0_.class='event'
10:01:47,142 DEBUG [EntityLoader] Static select for entity au.com.bisinfo.cmgr.logic.keyword.EventKeywordType: select eventkeywo0_.id as id8_0_, eventkeywo0_.name as name8_0_ from keyword_type eventkeywo0_ where eventkeywo0_.id=? and eventkeywo0_.class='event'
10:01:47,142 DEBUG [EntityLoader] Static select for entity au.com.bisinfo.cmgr.logic.keyword.EventKeywordType: select eventkeywo0_.id as id8_0_, eventkeywo0_.name as name8_0_ from keyword_type eventkeywo0_ where eventkeywo0_.id=? and eventkeywo0_.class='event'
10:01:47,142 DEBUG [CascadeEntityLoader] Static select for action ACTION_MERGE on entity au.com.bisinfo.cmgr.logic.keyword.EventKeywordType: select eventkeywo0_.id as id8_1_, eventkeywo0_.name as name8_1_, keywords1_.keyword_type_fk as keyword5_3_, keywords1_.id as id3_, keywords1_.id as id5_0_, keywords1_.name as name5_0_, keywords1_.special as special5_0_, keywords1_.keyword_type_fk as keyword5_5_0_, keywords1_.class as class5_0_ from keyword_type eventkeywo0_ left outer join keyword keywords1_ on eventkeywo0_.id=keywords1_.keyword_type_fk where eventkeywo0_.id=? and eventkeywo0_.class='event' order by keywords1_.name
10:01:47,142 DEBUG [CascadeEntityLoader] Static select for action ACTION_REFRESH on entity au.com.bisinfo.cmgr.logic.keyword.EventKeywordType: select eventkeywo0_.id as id8_1_, eventkeywo0_.name as name8_1_, keywords1_.keyword_type_fk as keyword5_3_, keywords1_.id as id3_, keywords1_.id as id5_0_, keywords1_.name as name5_0_, keywords1_.special as special5_0_, keywords1_.keyword_type_fk as keyword5_5_0_, keywords1_.class as class5_0_ from keyword_type eventkeywo0_ left outer join keyword keywords1_ on eventkeywo0_.id=keywords1_.keyword_type_fk where eventkeywo0_.id=? and eventkeywo0_.class='event' order by keywords1_.name
10:01:47,142 DEBUG [EntityLoader] Static select for entity au.com.bisinfo.cmgr.logic.org.Organisation: select organisati0_.id as id9_0_, organisati0_.name as name9_0_, organisati0_.active as active9_0_, organisati0_.mainPhone as mainPhone9_0_, organisati0_.url as url9_0_, organisati0_.otherUrl as otherUrl9_0_, organisati0_.comments as comments9_0_, organisati0_.date_added as date8_9_0_, organisati0_.date_changed as date9_9_0_, organisati0_.added_by_fk as added10_9_0_, organisati0_.changed_by_fk as changed11_9_0_, organisati0_.street_address_fk as street12_9_0_, organisati0_.postal_address_fk as postal13_9_0_ from organisation organisati0_ where organisati0_.id=?
10:01:47,158 DEBUG [EntityLoader] Static select for entity au.com.bisinfo.cmgr.logic.org.Organisation: select organisati0_.id as id9_0_, organisati0_.name as name9_0_, organisati0_.active as active9_0_, organisati0_.mainPhone as mainPhone9_0_, organisati0_.url as url9_0_, organisati0_.otherUrl as otherUrl9_0_, organisati0_.comments as comments9_0_, organisati0_.date_added as date8_9_0_, organisati0_.date_changed as date9_9_0_, organisati0_.added_by_fk as added10_9_0_, organisati0_.changed_by_fk as changed11_9_0_, organisati0_.street_address_fk as street12_9_0_, organisati0_.postal_address_fk as postal13_9_0_ from organisation organisati0_ where organisati0_.id=?
10:01:47,158 DEBUG [EntityLoader] Static select for entity au.com.bisinfo.cmgr.logic.org.Organisation: select organisati0_.id as id9_0_, organisati0_.name as name9_0_, organisati0_.active as active9_0_, organisati0_.mainPhone as mainPhone9_0_, organisati0_.url as url9_0_, organisati0_.otherUrl as otherUrl9_0_, organisati0_.comments as comments9_0_, organisati0_.date_added as date8_9_0_, organisati0_.date_changed as date9_9_0_, organisati0_.added_by_fk as added10_9_0_, organisati0_.changed_by_fk as changed11_9_0_, organisati0_.street_address_fk as street12_9_0_, organisati0_.postal_address_fk as postal13_9_0_ from organisation organisati0_ where organisati0_.id=?
10:01:47,158 DEBUG [EntityLoader] Static select for entity au.com.bisinfo.cmgr.logic.org.Organisation: select organisati0_.id as id9_0_, organisati0_.name as name9_0_, organisati0_.active as active9_0_, organisati0_.mainPhone as mainPhone9_0_, organisati0_.url as url9_0_, organisati0_.otherUrl as otherUrl9_0_, organisati0_.comments as comments9_0_, organisati0_.date_added as date8_9_0_, organisati0_.date_changed as date9_9_0_, organisati0_.added_by_fk as added10_9_0_, organisati0_.changed_by_fk as changed11_9_0_, organisati0_.street_address_fk as street12_9_0_, organisati0_.postal_address_fk as postal13_9_0_ from organisation organisati0_ where organisati0_.id=?
10:01:47,158 DEBUG [CascadeEntityLoader] Static select for action ACTION_MERGE on entity au.com.bisinfo.cmgr.logic.org.Organisation: select organisati0_.id as id9_2_, organisati0_.name as name9_2_, organisati0_.active as active9_2_, organisati0_.mainPhone as mainPhone9_2_, organisati0_.url as url9_2_, organisati0_.otherUrl as otherUrl9_2_, organisati0_.comments as comments9_2_, organisati0_.date_added as date8_9_2_, organisati0_.date_changed as date9_9_2_, organisati0_.added_by_fk as added10_9_2_, organisati0_.changed_by_fk as changed11_9_2_, organisati0_.street_address_fk as street12_9_2_, organisati0_.postal_address_fk as postal13_9_2_, address1_.id as id0_0_, address1_.address1 as address2_0_0_, address1_.address2 as address3_0_0_, address1_.suburb as suburb0_0_, address1_.postcode as postcode0_0_, address1_.state as state0_0_, address1_.country_fk as country7_0_0_, address2_.id as id0_1_, address2_.address1 as address2_0_1_, address2_.address2 as address3_0_1_, address2_.suburb as suburb0_1_, address2_.postcode as postcode0_1_, address2_.state as state0_1_, address2_.country_fk as country7_0_1_ from organisation organisati0_ left outer join address address1_ on organisati0_.street_address_fk=address1_.id left outer join address address2_ on organisati0_.postal_address_fk=address2_.id where organisati0_.id=?
10:01:47,158 DEBUG [CascadeEntityLoader] Static select for action ACTION_REFRESH on entity au.com.bisinfo.cmgr.logic.org.Organisation: select organisati0_.id as id9_2_, organisati0_.name as name9_2_, organisati0_.active as active9_2_, organisati0_.mainPhone as mainPhone9_2_, organisati0_.url as url9_2_, organisati0_.otherUrl as otherUrl9_2_, organisati0_.comments as comments9_2_, organisati0_.date_added as date8_9_2_, organisati0_.date_changed as date9_9_2_, organisati0_.added_by_fk as added10_9_2_, organisati0_.changed_by_fk as changed11_9_2_, organisati0_.street_address_fk as street12_9_2_, organisati0_.postal_address_fk as postal13_9_2_, address1_.id as id0_0_, address1_.address1 as address2_0_0_, address1_.address2 as address3_0_0_, address1_.suburb as suburb0_0_, address1_.postcode as postcode0_0_, address1_.state as state0_0_, address1_.country_fk as country7_0_0_, address2_.id as id0_1_, address2_.address1 as address2_0_1_, address2_.address2 as address3_0_1_, address2_.suburb as suburb0_1_, address2_.postcode as postcode0_1_, address2_.state as state0_1_, address2_.country_fk as country7_0_1_ from organisation organisati0_ left outer join address address1_ on organisati0_.street_address_fk=address1_.id left outer join address address2_ on organisati0_.postal_address_fk=address2_.id where organisati0_.id=?
10:01:47,158 DEBUG [EntityLoader] Static select for entity au.com.bisinfo.cmgr.logic.keyword.PersonKeywordType: select personkeyw0_.id as id8_0_, personkeyw0_.name as name8_0_ from keyword_type personkeyw0_ where personkeyw0_.id=? and personkeyw0_.class='person'
10:01:47,174 DEBUG [EntityLoader] Static select for entity au.com.bisinfo.cmgr.logic.keyword.PersonKeywordType: select personkeyw0_.id as id8_0_, personkeyw0_.name as name8_0_ from keyword_type personkeyw0_ where personkeyw0_.id=? and personkeyw0_.class='person'
10:01:47,174 DEBUG [EntityLoader] Static select for entity au.com.bisinfo.cmgr.logic.keyword.PersonKeywordType: select personkeyw0_.id as id8_0_, personkeyw0_.name as name8_0_ from keyword_type personkeyw0_ where personkeyw0_.id=? and personkeyw0_.class='person'
10:01:47,174 DEBUG [EntityLoader] Static select for entity au.com.bisinfo.cmgr.logic.keyword.PersonKeywordType: select personkeyw0_.id as id8_0_, personkeyw0_.name as name8_0_ from keyword_type personkeyw0_ where personkeyw0_.id=? and personkeyw0_.class='person'
10:01:47,174 DEBUG [CascadeEntityLoader] Static select for action ACTION_MERGE on entity au.com.bisinfo.cmgr.logic.keyword.PersonKeywordType: select personkeyw0_.id as id8_1_, personkeyw0_.name as name8_1_, keywords1_.keyword_type_fk as keyword5_3_, keywords1_.id as id3_, keywords1_.id as id5_0_, keywords1_.name as name5_0_, keywords1_.special as special5_0_, keywords1_.keyword_type_fk as keyword5_5_0_, keywords1_.class as class5_0_ from keyword_type personkeyw0_ left outer join keyword keywords1_ on personkeyw0_.id=keywords1_.keyword_type_fk where personkeyw0_.id=? and personkeyw0_.class='person' order by keywords1_.name
10:01:47,174 DEBUG [CascadeEntityLoader] Static select for action ACTION_REFRESH on entity au.com.bisinfo.cmgr.logic.keyword.PersonKeywordType: select personkeyw0_.id as id8_1_, personkeyw0_.name as name8_1_, keywords1_.keyword_type_fk as keyword5_3_, keywords1_.id as id3_, keywords1_.id as id5_0_, keywords1_.name as name5_0_, keywords1_.special as special5_0_, keywords1_.keyword_type_fk as keyword5_5_0_, keywords1_.class as class5_0_ from keyword_type personkeyw0_ left outer join keyword keywords1_ on personkeyw0_.id=keywords1_.keyword_type_fk where personkeyw0_.id=? and personkeyw0_.class='person' order by keywords1_.name
10:01:47,174 DEBUG [EntityLoader] Static select for entity au.com.bisinfo.cmgr.logic.keyword.OrganisationKeyword: select organisati0_.id as id5_0_, organisati0_.name as name5_0_, organisati0_.special as special5_0_, organisati0_.keyword_type_fk as keyword5_5_0_ from keyword organisati0_ where organisati0_.id=? and organisati0_.class='org'
10:01:47,174 DEBUG [EntityLoader] Static select for entity au.com.bisinfo.cmgr.logic.keyword.OrganisationKeyword: select organisati0_.id as id5_0_, organisati0_.name as name5_0_, organisati0_.special as special5_0_, organisati0_.keyword_type_fk as keyword5_5_0_ from keyword organisati0_ where organisati0_.id=? and organisati0_.class='org'
10:01:47,174 DEBUG [EntityLoader] Static select for entity au.com.bisinfo.cmgr.logic.keyword.OrganisationKeyword: select organisati0_.id as id5_0_, organisati0_.name as name5_0_, organisati0_.special as special5_0_, organisati0_.keyword_type_fk as keyword5_5_0_ from keyword organisati0_ where organisati0_.id=? and organisati0_.class='org'
10:01:47,174 DEBUG [EntityLoader] Static select for entity au.com.bisinfo.cmgr.logic.keyword.OrganisationKeyword: select organisati0_.id as id5_0_, organisati0_.name as name5_0_, organisati0_.special as special5_0_, organisati0_.keyword_type_fk as keyword5_5_0_ from keyword organisati0_ where organisati0_.id=? and organisati0_.class='org'
10:01:47,174 DEBUG [CascadeEntityLoader] Static select for action ACTION_MERGE on entity au.com.bisinfo.cmgr.logic.keyword.OrganisationKeyword: select organisati0_.id as id5_1_, organisati0_.name as name5_1_, organisati0_.special as special5_1_, organisati0_.keyword_type_fk as keyword5_5_1_, keywordtyp1_.id as id8_0_, keywordtyp1_.name as name8_0_, keywordtyp1_.class as class8_0_ from keyword organisati0_ inner join keyword_type keywordtyp1_ on organisati0_.keyword_type_fk=keywordtyp1_.id where organisati0_.id=? and organisati0_.class='org'
10:01:47,174 DEBUG [CascadeEntityLoader] Static select for action ACTION_REFRESH on entity au.com.bisinfo.cmgr.logic.keyword.OrganisationKeyword: select organisati0_.id as id5_1_, organisati0_.name as name5_1_, organisati0_.special as special5_1_, organisati0_.keyword_type_fk as keyword5_5_1_, keywordtyp1_.id as id8_0_, keywordtyp1_.name as name8_0_, keywordtyp1_.class as class8_0_ from keyword organisati0_ inner join keyword_type keywordtyp1_ on organisati0_.keyword_type_fk=keywordtyp1_.id where organisati0_.id=? and organisati0_.class='org'
10:01:47,174 DEBUG [EntityLoader] Static select for entity au.com.bisinfo.cmgr.logic.address.Address: select address0_.id as id0_0_, address0_.address1 as address2_0_0_, address0_.address2 as address3_0_0_, address0_.suburb as suburb0_0_, address0_.postcode as postcode0_0_, address0_.state as state0_0_, address0_.country_fk as country7_0_0_ from address address0_ where address0_.id=?
10:01:47,174 DEBUG [EntityLoader] Static select for entity au.com.bisinfo.cmgr.logic.address.Address: select address0_.id as id0_0_, address0_.address1 as address2_0_0_, address0_.address2 as address3_0_0_, address0_.suburb as suburb0_0_, address0_.postcode as postcode0_0_, address0_.state as state0_0_, address0_.country_fk as country7_0_0_ from address address0_ where address0_.id=?
10:01:47,174 DEBUG [EntityLoader] Static select for entity au.com.bisinfo.cmgr.logic.address.Address: select address0_.id as id0_0_, address0_.address1 as address2_0_0_, address0_.address2 as address3_0_0_, address0_.suburb as suburb0_0_, address0_.postcode as postcode0_0_, address0_.state as state0_0_, address0_.country_fk as country7_0_0_ from address address0_ where address0_.id=?
10:01:47,174 DEBUG [EntityLoader] Static select for entity au.com.bisinfo.cmgr.logic.address.Address: select address0_.id as id0_0_, address0_.address1 as address2_0_0_, address0_.address2 as address3_0_0_, address0_.suburb as suburb0_0_, address0_.postcode as postcode0_0_, address0_.state as state0_0_, address0_.country_fk as country7_0_0_ from address address0_ where address0_.id=?
10:01:47,174 DEBUG [CascadeEntityLoader] Static select for action ACTION_MERGE on entity au.com.bisinfo.cmgr.logic.address.Address: select address0_.id as id0_0_, address0_.address1 as address2_0_0_, address0_.address2 as address3_0_0_, address0_.suburb as suburb0_0_, address0_.postcode as postcode0_0_, address0_.state as state0_0_, address0_.country_fk as country7_0_0_ from address address0_ where address0_.id=?
10:01:47,189 DEBUG [CascadeEntityLoader] Static select for action ACTION_REFRESH on entity au.com.bisinfo.cmgr.logic.address.Address: select address0_.id as id0_0_, address0_.address1 as address2_0_0_, address0_.address2 as address3_0_0_, address0_.suburb as suburb0_0_, address0_.postcode as postcode0_0_, address0_.state as state0_0_, address0_.country_fk as country7_0_0_ from address address0_ where address0_.id=?
10:01:47,189 DEBUG [BasicCollectionLoader] Static select for collection au.com.bisinfo.cmgr.logic.keyword.EventKeyword.keywordOwners: select keywordown0_.keyword_fk as keyword2_1_, keywordown0_.event_fk as event1_1_, event1_.id as id2_0_, event1_.comments as comments2_0_, event1_.date as date2_0_ from event_keyword keywordown0_ left outer join event event1_ on keywordown0_.event_fk=event1_.id where keywordown0_.keyword_fk=?
10:01:47,189 DEBUG [BasicCollectionLoader] Static select for collection au.com.bisinfo.cmgr.logic.person.Person.keywords: select keywords0_.person_fk as person2_1_, keywords0_.keyword_fk as keyword1_1_, personkeyw1_.id as id5_0_, personkeyw1_.name as name5_0_, personkeyw1_.special as special5_0_, personkeyw1_.keyword_type_fk as keyword5_5_0_ from person_keyword keywords0_ left outer join keyword personkeyw1_ on keywords0_.keyword_fk=personkeyw1_.id where keywords0_.person_fk=?
10:01:47,189 DEBUG [OneToManyLoader] Static select for one-to-many au.com.bisinfo.cmgr.logic.person.User.grantedAuthorities: select grantedaut0_.granted_to_fk as granted5_1_, grantedaut0_.id as id1_, grantedaut0_.id as id11_0_, grantedaut0_.date_granted as date2_11_0_, grantedaut0_.authority_fk as authority3_11_0_, grantedaut0_.granted_by_fk as granted4_11_0_ from granted_authority grantedaut0_ where grantedaut0_.granted_to_fk=?
10:01:47,205 DEBUG [BasicCollectionLoader] Static select for collection au.com.bisinfo.cmgr.logic.org.Organisation.keywords: select keywords0_.organisation_fk as organisa2_1_, keywords0_.keyword_fk as keyword1_1_, organisati1_.id as id5_0_, organisati1_.name as name5_0_, organisati1_.special as special5_0_, organisati1_.keyword_type_fk as keyword5_5_0_ from organisation_keyword keywords0_ left outer join keyword organisati1_ on keywords0_.keyword_fk=organisati1_.id where keywords0_.organisation_fk=?
10:01:47,205 DEBUG [BasicCollectionLoader] Static select for collection au.com.bisinfo.cmgr.logic.event.Event.keywords: select keywords0_.event_fk as event1_1_, keywords0_.keyword_fk as keyword2_1_, eventkeywo1_.id as id5_0_, eventkeywo1_.name as name5_0_, eventkeywo1_.special as special5_0_, eventkeywo1_.keyword_type_fk as keyword5_5_0_ from event_keyword keywords0_ left outer join keyword eventkeywo1_ on keywords0_.keyword_fk=eventkeywo1_.id where keywords0_.event_fk=?
10:01:47,205 DEBUG [BasicCollectionLoader] Static select for collection au.com.bisinfo.cmgr.logic.keyword.OrganisationKeyword.keywordOwners: select keywordown0_.keyword_fk as keyword1_1_, keywordown0_.organisation_fk as organisa2_1_, organisati1_.id as id9_0_, organisati1_.name as name9_0_, organisati1_.active as active9_0_, organisati1_.mainPhone as mainPhone9_0_, organisati1_.url as url9_0_, organisati1_.otherUrl as otherUrl9_0_, organisati1_.comments as comments9_0_, organisati1_.date_added as date8_9_0_, organisati1_.date_changed as date9_9_0_, organisati1_.added_by_fk as added10_9_0_, organisati1_.changed_by_fk as changed11_9_0_, organisati1_.street_address_fk as street12_9_0_, organisati1_.postal_address_fk as postal13_9_0_ from organisation_keyword keywordown0_ left outer join organisation organisati1_ on keywordown0_.organisation_fk=organisati1_.id where keywordown0_.keyword_fk=?
10:01:47,205 DEBUG [OneToManyLoader] Static select for one-to-many au.com.bisinfo.cmgr.logic.org.Organisation.people: select people0_.organisation_fk as organis17_1_, people0_.id as id1_, people0_.id as id12_0_, people0_.first_name as first3_12_0_, people0_.last_name as last4_12_0_, people0_.email as email12_0_, people0_.active as active12_0_, people0_.date_added as date7_12_0_, people0_.comments as comments12_0_, people0_.date_changed as date9_12_0_, people0_.male as male12_0_, people0_.job_title as job11_12_0_, people0_.work_phone as work12_12_0_, people0_.fax as fax12_0_, people0_.mobile as mobile12_0_, people0_.home_phone as home15_12_0_, people0_.work_address_fk as work16_12_0_, people0_.organisation_fk as organis17_12_0_, people0_.added_by_fk as added18_12_0_, people0_.changed_by_fk as changed19_12_0_, people0_.username as username12_0_, people0_.password as password12_0_, people0_.last_login as last22_12_0_, people0_.deactivate_reason as deactivate23_12_0_, people0_.class as class12_0_ from person people0_ where people0_.active = 1 and people0_.organisation_fk=?
10:01:47,205 DEBUG [BasicCollectionLoader] Static select for collection au.com.bisinfo.cmgr.logic.event.Event.attendees: select attendees0_.event_fk as event1_0_, attendees0_.person_fk as person2_0_ from attendee attendees0_ where attendees0_.event_fk=?
10:01:47,205 DEBUG [BasicCollectionLoader] Static select for collection au.com.bisinfo.cmgr.logic.keyword.PersonKeyword.keywordOwners: select keywordown0_.keyword_fk as keyword1_1_, keywordown0_.person_fk as person2_1_, person1_.id as id12_0_, person1_.first_name as first3_12_0_, person1_.last_name as last4_12_0_, person1_.email as email12_0_, person1_.active as active12_0_, person1_.date_added as date7_12_0_, person1_.comments as comments12_0_, person1_.date_changed as date9_12_0_, person1_.male as male12_0_, person1_.job_title as job11_12_0_, person1_.work_phone as work12_12_0_, person1_.fax as fax12_0_, person1_.mobile as mobile12_0_, person1_.home_phone as home15_12_0_, person1_.work_address_fk as work16_12_0_, person1_.organisation_fk as organis17_12_0_, person1_.added_by_fk as added18_12_0_, person1_.changed_by_fk as changed19_12_0_, person1_.username as username12_0_, person1_.password as password12_0_, person1_.last_login as last22_12_0_, person1_.deactivate_reason as deactivate23_12_0_, person1_.class as class12_0_ from person_keyword keywordown0_ left outer join person person1_ on keywordown0_.person_fk=person1_.id where keywordown0_.keyword_fk=?
10:01:47,205 DEBUG [OneToManyLoader] Static select for one-to-many au.com.bisinfo.cmgr.logic.keyword.KeywordType.keywords: select keywords0_.keyword_type_fk as keyword5_1_, keywords0_.id as id1_, keywords0_.id as id5_0_, keywords0_.name as name5_0_, keywords0_.special as special5_0_, keywords0_.keyword_type_fk as keyword5_5_0_, keywords0_.class as class5_0_ from keyword keywords0_ where keywords0_.keyword_type_fk=? order by keywords0_.name
10:01:47,205 DEBUG [SessionFactoryObjectFactory] initializing class SessionFactoryObjectFactory
10:01:47,205 DEBUG [SessionFactoryObjectFactory] registered: 4028801a0a811a9e010a811aa2c50000 (unnamed)
10:01:47,205 INFO [SessionFactoryObjectFactory] Not binding factory to JNDI, no JNDI name configured
10:01:47,220 DEBUG [SessionFactoryImpl] instantiated session factory
10:01:47,220 DEBUG [Configuration] processing extends queue
10:01:47,220 DEBUG [Configuration] processing collection mappings
10:01:47,220 DEBUG [Configuration] processing native query and ResultSetMapping mappings
10:01:47,220 DEBUG [Configuration] processing association property references
10:01:47,220 DEBUG [Configuration] processing foreign key constraints
10:01:47,220 DEBUG [Configuration] resolving reference to class: au.com.bisinfo.cmgr.logic.country.Country
10:01:47,236 DEBUG [Configuration] resolving reference to class: au.com.bisinfo.cmgr.logic.person.Person
10:01:47,236 DEBUG [Configuration] resolving reference to class: au.com.bisinfo.cmgr.logic.event.Event
10:01:47,236 DEBUG [Configuration] resolving reference to class: au.com.bisinfo.cmgr.logic.keyword.EventKeyword
10:01:47,236 DEBUG [Configuration] resolving reference to class: au.com.bisinfo.cmgr.logic.event.Event
10:01:47,236 DEBUG [Configuration] resolving reference to class: au.com.bisinfo.cmgr.logic.person.User
10:01:47,236 DEBUG [Configuration] resolving reference to class: au.com.bisinfo.cmgr.logic.person.Authority
10:01:47,236 DEBUG [Configuration] resolving reference to class: au.com.bisinfo.cmgr.logic.person.User
10:01:47,236 DEBUG [Configuration] resolving reference to class: au.com.bisinfo.cmgr.logic.keyword.KeywordType
10:01:47,236 DEBUG [Configuration] resolving reference to class: au.com.bisinfo.cmgr.logic.address.Address
10:01:47,236 DEBUG [Configuration] resolving reference to class: au.com.bisinfo.cmgr.logic.person.User
10:01:47,236 DEBUG [Configuration] resolving reference to class: au.com.bisinfo.cmgr.logic.address.Address
10:01:47,236 DEBUG [Configuration] resolving reference to class: au.com.bisinfo.cmgr.logic.person.User
10:01:47,236 DEBUG [Configuration] resolving reference to class: au.com.bisinfo.cmgr.logic.keyword.OrganisationKeyword
10:01:47,236 DEBUG [Configuration] resolving reference to class: au.com.bisinfo.cmgr.logic.org.Organisation
10:01:47,236 DEBUG [Configuration] resolving reference to class: au.com.bisinfo.cmgr.logic.person.User
10:01:47,236 DEBUG [Configuration] resolving reference to class: au.com.bisinfo.cmgr.logic.address.Address
10:01:47,236 DEBUG [Configuration] resolving reference to class: au.com.bisinfo.cmgr.logic.person.User
10:01:47,236 DEBUG [Configuration] resolving reference to class: au.com.bisinfo.cmgr.logic.org.Organisation
10:01:47,236 DEBUG [Configuration] resolving reference to class: au.com.bisinfo.cmgr.logic.keyword.PersonKeyword
10:01:47,252 DEBUG [Configuration] resolving reference to class: au.com.bisinfo.cmgr.logic.person.Person
10:01:47,252 DEBUG [Configuration] processing extends queue
10:01:47,252 DEBUG [Configuration] processing collection mappings
10:01:47,252 DEBUG [Configuration] processing native query and ResultSetMapping mappings
10:01:47,252 DEBUG [Configuration] processing association property references
10:01:47,252 DEBUG [Configuration] processing foreign key constraints
10:01:47,252 DEBUG [Configuration] resolving reference to class: au.com.bisinfo.cmgr.logic.country.Country
10:01:47,252 DEBUG [Configuration] resolving reference to class: au.com.bisinfo.cmgr.logic.person.Person
10:01:47,252 DEBUG [Configuration] resolving reference to class: au.com.bisinfo.cmgr.logic.event.Event
10:01:47,252 DEBUG [Configuration] resolving reference to class: au.com.bisinfo.cmgr.logic.keyword.EventKeyword
10:01:47,252 DEBUG [Configuration] resolving reference to class: au.com.bisinfo.cmgr.logic.event.Event
10:01:47,252 DEBUG [Configuration] resolving reference to class: au.com.bisinfo.cmgr.logic.person.User
10:01:47,252 DEBUG [Configuration] resolving reference to class: au.com.bisinfo.cmgr.logic.person.Authority
10:01:47,252 DEBUG [Configuration] resolving reference to class: au.com.bisinfo.cmgr.logic.person.User
10:01:47,267 DEBUG [Configuration] resolving reference to class: au.com.bisinfo.cmgr.logic.keyword.KeywordType
10:01:47,267 DEBUG [Configuration] resolving reference to class: au.com.bisinfo.cmgr.logic.address.Address
10:01:47,267 DEBUG [Configuration] resolving reference to class: au.com.bisinfo.cmgr.logic.person.User
10:01:47,267 DEBUG [Configuration] resolving reference to class: au.com.bisinfo.cmgr.logic.address.Address
10:01:47,267 DEBUG [Configuration] resolving reference to class: au.com.bisinfo.cmgr.logic.person.User
10:01:47,267 DEBUG [Configuration] resolving reference to class: au.com.bisinfo.cmgr.logic.keyword.OrganisationKeyword
10:01:47,267 DEBUG [Configuration] resolving reference to class: au.com.bisinfo.cmgr.logic.org.Organisation
10:01:47,267 DEBUG [Configuration] resolving reference to class: au.com.bisinfo.cmgr.logic.person.User
10:01:47,267 DEBUG [Configuration] resolving reference to class: au.com.bisinfo.cmgr.logic.address.Address
10:01:47,267 DEBUG [Configuration] resolving reference to class: au.com.bisinfo.cmgr.logic.person.User
10:01:47,267 DEBUG [Configuration] resolving reference to class: au.com.bisinfo.cmgr.logic.org.Organisation
10:01:47,267 DEBUG [Configuration] resolving reference to class: au.com.bisinfo.cmgr.logic.keyword.PersonKeyword
10:01:47,267 DEBUG [Configuration] resolving reference to class: au.com.bisinfo.cmgr.logic.person.Person
10:01:47,283 INFO [SchemaExport] Running hbm2ddl schema export
10:01:47,283 INFO [SchemaExport] exporting generated schema to database
10:01:47,330 INFO [SchemaExport] schema export complete
10:01:47,330 DEBUG [Configuration] processing extends queue
10:01:47,345 DEBUG [Configuration] processing collection mappings
10:01:47,345 DEBUG [Configuration] processing native query and ResultSetMapping mappings
10:01:47,345 DEBUG [Configuration] processing association property references
10:01:47,345 DEBUG [Configuration] processing foreign key constraints
10:01:47,345 DEBUG [Configuration] resolving reference to class: au.com.bisinfo.cmgr.logic.country.Country
10:01:47,345 DEBUG [Configuration] resolving reference to class: au.com.bisinfo.cmgr.logic.person.Person
10:01:47,345 DEBUG [Configuration] resolving reference to class: au.com.bisinfo.cmgr.logic.event.Event
10:01:47,345 DEBUG [Configuration] resolving reference to class: au.com.bisinfo.cmgr.logic.keyword.EventKeyword
10:01:47,345 DEBUG [Configuration] resolving reference to class: au.com.bisinfo.cmgr.logic.event.Event
10:01:47,345 DEBUG [Configuration] resolving reference to class: au.com.bisinfo.cmgr.logic.person.User
10:01:47,345 DEBUG [Configuration] resolving reference to class: au.com.bisinfo.cmgr.logic.person.Authority
10:01:47,345 DEBUG [Configuration] resolving reference to class: au.com.bisinfo.cmgr.logic.person.User
10:01:47,345 DEBUG [Configuration] resolving reference to class: au.com.bisinfo.cmgr.logic.keyword.KeywordType
10:01:47,345 DEBUG [Configuration] resolving reference to class: au.com.bisinfo.cmgr.logic.address.Address
10:01:47,345 DEBUG [Configuration] resolving reference to class: au.com.bisinfo.cmgr.logic.person.User
10:01:47,345 DEBUG [Configuration] resolving reference to class: au.com.bisinfo.cmgr.logic.address.Address
10:01:47,345 DEBUG [Configuration] resolving reference to class: au.com.bisinfo.cmgr.logic.person.User
10:01:47,345 DEBUG [Configuration] resolving reference to class: au.com.bisinfo.cmgr.logic.keyword.OrganisationKeyword
10:01:47,361 DEBUG [Configuration] resolving reference to class: au.com.bisinfo.cmgr.logic.org.Organisation
10:01:47,361 DEBUG [Configuration] resolving reference to class: au.com.bisinfo.cmgr.logic.person.User
10:01:47,361 DEBUG [Configuration] resolving reference to class: au.com.bisinfo.cmgr.logic.address.Address
10:01:47,361 DEBUG [Configuration] resolving reference to class: au.com.bisinfo.cmgr.logic.person.User
10:01:47,361 DEBUG [Configuration] resolving reference to class: au.com.bisinfo.cmgr.logic.org.Organisation
10:01:47,361 DEBUG [Configuration] resolving reference to class: au.com.bisinfo.cmgr.logic.keyword.PersonKeyword
10:01:47,361 DEBUG [Configuration] resolving reference to class: au.com.bisinfo.cmgr.logic.person.Person
10:01:47,361 DEBUG [Configuration] processing extends queue
10:01:47,361 DEBUG [Configuration] processing collection mappings
10:01:47,361 DEBUG [Configuration] processing native query and ResultSetMapping mappings
10:01:47,361 DEBUG [Configuration] processing association property references
10:01:47,361 DEBUG [Configuration] processing foreign key constraints
10:01:47,361 DEBUG [Configuration] resolving reference to class: au.com.bisinfo.cmgr.logic.country.Country
10:01:47,361 DEBUG [Configuration] resolving reference to class: au.com.bisinfo.cmgr.logic.person.Person
10:01:47,361 DEBUG [Configuration] resolving reference to class: au.com.bisinfo.cmgr.logic.event.Event
10:01:47,361 DEBUG [Configuration] resolving reference to class: au.com.bisinfo.cmgr.logic.keyword.EventKeyword
10:01:47,361 DEBUG [Configuration] resolving reference to class: au.com.bisinfo.cmgr.logic.event.Event
10:01:47,377 DEBUG [Configuration] resolving reference to class: au.com.bisinfo.cmgr.logic.person.User
10:01:47,377 DEBUG [Configuration] resolving reference to class: au.com.bisinfo.cmgr.logic.person.Authority
10:01:47,377 DEBUG [Configuration] resolving reference to class: au.com.bisinfo.cmgr.logic.person.User
10:01:47,377 DEBUG [Configuration] resolving reference to class: au.com.bisinfo.cmgr.logic.keyword.KeywordType
10:01:47,377 DEBUG [Configuration] resolving reference to class: au.com.bisinfo.cmgr.logic.address.Address
10:01:47,377 DEBUG [Configuration] resolving reference to class: au.com.bisinfo.cmgr.logic.person.User
10:01:47,377 DEBUG [Configuration] resolving reference to class: au.com.bisinfo.cmgr.logic.address.Address
10:01:47,377 DEBUG [Configuration] resolving reference to class: au.com.bisinfo.cmgr.logic.person.User
10:01:47,377 DEBUG [Configuration] resolving reference to class: au.com.bisinfo.cmgr.logic.keyword.OrganisationKeyword
10:01:47,377 DEBUG [Configuration] resolving reference to class: au.com.bisinfo.cmgr.logic.org.Organisation
10:01:47,377 DEBUG [Configuration] resolving reference to class: au.com.bisinfo.cmgr.logic.person.User
10:01:47,377 DEBUG [Configuration] resolving reference to class: au.com.bisinfo.cmgr.logic.address.Address
10:01:47,377 DEBUG [Configuration] resolving reference to class: au.com.bisinfo.cmgr.logic.person.User
10:01:47,377 DEBUG [Configuration] resolving reference to class: au.com.bisinfo.cmgr.logic.org.Organisation
10:01:47,377 DEBUG [Configuration] resolving reference to class: au.com.bisinfo.cmgr.logic.keyword.PersonKeyword
10:01:47,377 DEBUG [Configuration] resolving reference to class: au.com.bisinfo.cmgr.logic.person.Person
10:01:47,392 DEBUG [SessionFactoryImpl] Checking 0 named HQL queries
10:01:47,392 DEBUG [SessionFactoryImpl] Checking 0 named SQL queries
10:01:47,799 DEBUG [SessionImpl] opened session at timestamp: 4688393452552192
10:01:47,814 DEBUG [JDBCTransaction] begin
10:01:47,814 DEBUG [ConnectionManager] opening JDBC connection
10:01:47,814 DEBUG [JDBCTransaction] current autocommit status: true
10:01:47,814 DEBUG [JDBCTransaction] disabling autocommit
10:01:47,814 DEBUG [JDBCContext] after transaction begin
10:01:47,830 INFO [AbstractTransactionalSpringContextTests] Began transaction (1): transaction manager [org.springframework.orm.hibernate3.HibernateTransactionManager@1f2cea2]; default rollback = true
10:01:47,955 DEBUG [DefaultLoadEventListener] loading entity: [au.com.bisinfo.cmgr.logic.person.Person#2]
10:01:47,955 DEBUG [DefaultLoadEventListener] attempting to resolve: [au.com.bisinfo.cmgr.logic.person.Person#2]
10:01:47,955 DEBUG [DefaultLoadEventListener] object not resolved in any cache: [au.com.bisinfo.cmgr.logic.person.Person#2]
10:01:47,955 DEBUG [AbstractEntityPersister] Fetching entity: [au.com.bisinfo.cmgr.logic.person.Person#2]
10:01:47,955 DEBUG [Loader] loading entity: [au.com.bisinfo.cmgr.logic.person.Person#2]
10:01:47,970 DEBUG [AbstractBatcher] about to open PreparedStatement (open PreparedStatements: 0, globally: 0)
10:01:47,970 DEBUG [AbstractBatcher] select person0_.id as id12_0_, person0_.first_name as first3_12_0_, person0_.last_name as last4_12_0_, person0_.email as email12_0_, person0_.active as active12_0_, person0_.date_added as date7_12_0_, person0_.comments as comments12_0_, person0_.date_changed as date9_12_0_, person0_.male as male12_0_, person0_.job_title as job11_12_0_, person0_.work_phone as work12_12_0_, person0_.fax as fax12_0_, person0_.mobile as mobile12_0_, person0_.home_phone as home15_12_0_, person0_.work_address_fk as work16_12_0_, person0_.organisation_fk as organis17_12_0_, person0_.added_by_fk as added18_12_0_, person0_.changed_by_fk as changed19_12_0_, person0_.username as username12_0_, person0_.password as password12_0_, person0_.last_login as last22_12_0_, person0_.deactivate_reason as deactivate23_12_0_, person0_.class as class12_0_ from person person0_ where person0_.id=?
10:01:47,970 DEBUG [AbstractBatcher] preparing statement
10:01:47,970 DEBUG [NullableType] binding '2' to parameter: 1
10:01:47,970 DEBUG [AbstractBatcher] about to open ResultSet (open ResultSets: 0, globally: 0)
10:01:47,970 DEBUG [Loader] processing result set
10:01:47,970 DEBUG [Loader] result set row: 0
10:01:47,986 DEBUG [Loader] result row: EntityKey[au.com.bisinfo.cmgr.logic.person.Person#2]
10:01:47,986 DEBUG [NullableType] returning 'Person' as column: class12_0_
10:01:47,986 DEBUG [Loader] Initializing object from ResultSet: [au.com.bisinfo.cmgr.logic.person.Person#2]
10:01:47,986 DEBUG [AbstractEntityPersister] Hydrating entity: [au.com.bisinfo.cmgr.logic.person.Person#2]
10:01:47,986 DEBUG [NullableType] returning 'Allan' as column: first3_12_0_
10:01:47,986 DEBUG [NullableType] returning 'Davis' as column: last4_12_0_
10:01:47,986 DEBUG [NullableType] returning null as column: email12_0_
10:01:48,002 DEBUG [NullableType] returning 'true' as column: active12_0_
10:01:48,002 DEBUG [NullableType] returning '10 April 2006' as column: date7_12_0_
10:01:48,002 DEBUG [NullableType] returning null as column: comments12_0_
10:01:48,002 DEBUG [NullableType] returning null as column: date9_12_0_
10:01:48,002 DEBUG [NullableType] returning null as column: male12_0_
10:01:48,002 DEBUG [NullableType] returning null as column: job11_12_0_
10:01:48,002 DEBUG [NullableType] returning null as column: work12_12_0_
10:01:48,002 DEBUG [NullableType] returning null as column: fax12_0_
10:01:48,002 DEBUG [NullableType] returning null as column: mobile12_0_
10:01:48,002 DEBUG [NullableType] returning null as column: home15_12_0_
10:01:48,002 DEBUG [NullableType] returning null as column: work16_12_0_
10:01:48,002 DEBUG [NullableType] returning null as column: organis17_12_0_
10:01:48,002 DEBUG [NullableType] returning null as column: added18_12_0_
10:01:48,002 DEBUG [NullableType] returning null as column: changed19_12_0_
10:01:48,017 DEBUG [Loader] done processing result set (1 rows)
10:01:48,017 DEBUG [AbstractBatcher] about to close ResultSet (open ResultSets: 1, globally: 1)
10:01:48,017 DEBUG [AbstractBatcher] about to close PreparedStatement (open PreparedStatements: 1, globally: 1)
10:01:48,017 DEBUG [AbstractBatcher] closing statement
10:01:48,017 DEBUG [Loader] total objects hydrated: 1
10:01:48,017 DEBUG [TwoPhaseLoad] resolving associations for [au.com.bisinfo.cmgr.logic.person.Person#2]
10:01:48,033 DEBUG [CollectionLoadContext] creating collection wrapper:[au.com.bisinfo.cmgr.logic.person.Person.keywords#2]
10:01:48,033 DEBUG [TwoPhaseLoad] done materializing entity [au.com.bisinfo.cmgr.logic.person.Person#2]
10:01:48,033 DEBUG [StatefulPersistenceContext] initializing non-lazy collections
10:01:48,033 DEBUG [Loader] done entity load
10:01:48,049 DEBUG [DefaultInitializeCollectionEventListener] initializing collection [au.com.bisinfo.cmgr.logic.person.Person.keywords#2]
10:01:48,049 DEBUG [DefaultInitializeCollectionEventListener] checking second-level cache
10:01:48,049 DEBUG [DefaultInitializeCollectionEventListener] collection not cached
10:01:48,049 DEBUG [Loader] loading collection: [au.com.bisinfo.cmgr.logic.person.Person.keywords#2]
10:01:48,049 DEBUG [AbstractBatcher] about to open PreparedStatement (open PreparedStatements: 0, globally: 0)
10:01:48,049 DEBUG [AbstractBatcher] select keywords0_.person_fk as person2_1_, keywords0_.keyword_fk as keyword1_1_, personkeyw1_.id as id5_0_, personkeyw1_.name as name5_0_, personkeyw1_.special as special5_0_, personkeyw1_.keyword_type_fk as keyword5_5_0_ from person_keyword keywords0_ left outer join keyword personkeyw1_ on keywords0_.keyword_fk=personkeyw1_.id where keywords0_.person_fk=?
10:01:48,049 DEBUG [AbstractBatcher] preparing statement
10:01:48,049 DEBUG [NullableType] binding '2' to parameter: 1
10:01:48,049 DEBUG [AbstractBatcher] about to open ResultSet (open ResultSets: 0, globally: 0)
10:01:48,049 DEBUG [Loader] result set contains (possibly empty) collection: [au.com.bisinfo.cmgr.logic.person.Person.keywords#2]
10:01:48,049 DEBUG [CollectionLoadContext] uninitialized collection: initializing
10:01:48,049 DEBUG [Loader] processing result set
10:01:48,049 DEBUG [Loader] result set row: 0
10:01:48,049 DEBUG [NullableType] returning '1' as column: id5_0_
10:01:48,049 DEBUG [Loader] result row: EntityKey[au.com.bisinfo.cmgr.logic.keyword.PersonKeyword#1]
10:01:48,064 DEBUG [Loader] Initializing object from ResultSet: [au.com.bisinfo.cmgr.logic.keyword.PersonKeyword#1]
10:01:48,064 DEBUG [AbstractEntityPersister] Hydrating entity: [au.com.bisinfo.cmgr.logic.keyword.PersonKeyword#1]
10:01:48,064 DEBUG [NullableType] returning 'Climber' as column: name5_0_
10:01:48,064 DEBUG [NullableType] returning 'false' as column: special5_0_
10:01:48,064 DEBUG [NullableType] returning '1' as column: keyword5_5_0_
10:01:48,064 DEBUG [NullableType] returning '2' as column: person2_1_
10:01:48,064 DEBUG [Loader] found row of collection: [au.com.bisinfo.cmgr.logic.person.Person.keywords#2]
10:01:48,064 DEBUG [CollectionLoadContext] reading row
10:01:48,064 DEBUG [NullableType] returning '1' as column: keyword1_1_
10:01:48,064 DEBUG [DefaultLoadEventListener] loading entity: [au.com.bisinfo.cmgr.logic.keyword.PersonKeyword#1]
10:01:48,064 DEBUG [DefaultLoadEventListener] attempting to resolve: [au.com.bisinfo.cmgr.logic.keyword.PersonKeyword#1]
10:01:48,080 DEBUG [DefaultLoadEventListener] resolved object in session cache: [au.com.bisinfo.cmgr.logic.keyword.PersonKeyword#1]
10:01:48,080 DEBUG [Loader] done processing result set (1 rows)
10:01:48,080 DEBUG [AbstractBatcher] about to close ResultSet (open ResultSets: 1, globally: 1)
10:01:48,080 DEBUG [AbstractBatcher] about to close PreparedStatement (open PreparedStatements: 1, globally: 1)
10:01:48,080 DEBUG [AbstractBatcher] closing statement
10:01:48,080 DEBUG [Loader] total objects hydrated: 1
10:01:48,080 DEBUG [TwoPhaseLoad] resolving associations for [au.com.bisinfo.cmgr.logic.keyword.PersonKeyword#1]
10:01:48,080 DEBUG [DefaultLoadEventListener] loading entity: [au.com.bisinfo.cmgr.logic.keyword.KeywordType#1]
10:01:48,080 DEBUG [DefaultLoadEventListener] creating new proxy for entity
10:01:48,142 DEBUG [CollectionLoadContext] creating collection wrapper:[au.com.bisinfo.cmgr.logic.keyword.PersonKeyword.keywordOwners#1]
10:01:48,142 DEBUG [TwoPhaseLoad] done materializing entity [au.com.bisinfo.cmgr.logic.keyword.PersonKeyword#1]
10:01:48,142 DEBUG [CollectionLoadContext] 1 collections were found in result set for role: au.com.bisinfo.cmgr.logic.person.Person.keywords
10:01:48,158 DEBUG [CollectionLoadContext] collection fully initialized: [au.com.bisinfo.cmgr.logic.person.Person.keywords#2]
10:01:48,158 DEBUG [CollectionLoadContext] 1 collections initialized for role: au.com.bisinfo.cmgr.logic.person.Person.keywords
10:01:48,158 DEBUG [StatefulPersistenceContext] initializing non-lazy collections
10:01:48,158 DEBUG [Loader] done loading collection
10:01:48,158 DEBUG [DefaultInitializeCollectionEventListener] collection initialized
10:01:48,158 DEBUG [DefaultInitializeCollectionEventListener] initializing collection [au.com.bisinfo.cmgr.logic.keyword.PersonKeyword.keywordOwners#1]
10:01:48,158 DEBUG [DefaultInitializeCollectionEventListener] checking second-level cache
10:01:48,158 DEBUG [DefaultInitializeCollectionEventListener] collection not cached
10:01:48,158 DEBUG [Loader] loading collection: [au.com.bisinfo.cmgr.logic.keyword.PersonKeyword.keywordOwners#1]
10:01:48,158 DEBUG [AbstractBatcher] about to open PreparedStatement (open PreparedStatements: 0, globally: 0)
10:01:48,158 DEBUG [AbstractBatcher] select keywordown0_.keyword_fk as keyword1_1_, keywordown0_.person_fk as person2_1_, person1_.id as id12_0_, person1_.first_name as first3_12_0_, person1_.last_name as last4_12_0_, person1_.email as email12_0_, person1_.active as active12_0_, person1_.date_added as date7_12_0_, person1_.comments as comments12_0_, person1_.date_changed as date9_12_0_, person1_.male as male12_0_, person1_.job_title as job11_12_0_, person1_.work_phone as work12_12_0_, person1_.fax as fax12_0_, person1_.mobile as mobile12_0_, person1_.home_phone as home15_12_0_, person1_.work_address_fk as work16_12_0_, person1_.organisation_fk as organis17_12_0_, person1_.added_by_fk as added18_12_0_, person1_.changed_by_fk as changed19_12_0_, person1_.username as username12_0_, person1_.password as password12_0_, person1_.last_login as last22_12_0_, person1_.deactivate_reason as deactivate23_12_0_, person1_.class as class12_0_ from person_keyword keywordown0_ left outer join person person1_ on keywordown0_.person_fk=person1_.id where keywordown0_.keyword_fk=?
10:01:48,158 DEBUG [AbstractBatcher] preparing statement
10:01:48,158 DEBUG [NullableType] binding '1' to parameter: 1
10:01:48,174 DEBUG [AbstractBatcher] about to open ResultSet (open ResultSets: 0, globally: 0)
10:01:48,174 DEBUG [Loader] result set contains (possibly empty) collection: [au.com.bisinfo.cmgr.logic.keyword.PersonKeyword.keywordOwners#1]
10:01:48,174 DEBUG [CollectionLoadContext] uninitialized collection: initializing
10:01:48,174 DEBUG [Loader] processing result set
10:01:48,174 DEBUG [Loader] result set row: 0
10:01:48,174 DEBUG [NullableType] returning '2' as column: id12_0_
10:01:48,174 DEBUG [Loader] result row: EntityKey[au.com.bisinfo.cmgr.logic.person.Person#2]
10:01:48,174 DEBUG [NullableType] returning '1' as column: keyword1_1_
10:01:48,174 DEBUG [Loader] found row of collection: [a

This has the hallmarks of field access to a mapped property. Only two methods are allowed access the keywords field: getKeywords() and setKeywords(Collection<Keyword> colKeyword). Change changeKeywords to use "getKeywords()" everywhere it currently access the field.

Remember: hibernate proxies stuff. When you access a proxied field, you're bypassing the proxy, so you're looking at the wrong values. Until you call getKeywords(), keywords will be whatever empty default you set it up as in the constructor, or in the field declaration. You must call getKeywords() to get CGlib to tell hibernate to load the keywords collection.

Dear tenwit,

Thanks for the insight into how Hibernate works, I hadn't fully appreciated the ramifications of accessing a field directly.

Anyhow, I changed the code as you said - the only references to the keywords field are now in the getter and setter. Unfortunately this didn't fix the problem.

Also, if accessing the field directly is invalid, why wasn't I having problems in any other situations apart from the problematic one (i.e. person has exactly one keyword before the update and exactly one different keyword after the update).

Any ideas?

Andrew

P.S. I really appreciate your help, but because your suggestion didn't fix the problem, I chose the "this post didn't solve my problem" option ... unfortunately this has been translated by the forum into "this post wasn't helpful to me", which isn't the case at all! Sorry about that ... :-)

The most likely reason that you didn't see problems at other times would be because you usually/always eagerly load the collection. The problem only arises when accessing a field that hasn't yet been deproxied: for the default access="property", you have to call getKeywords() to deproxy the collection.

Another possible reason that your having this problem is that your hashCode/equals methods are flawed. You say that you've implemented the persistent collection as a SortedSet, but you don't actually get a SortedSet when you load it from Hibernate: you get a PersistentSet. PersistentSets can be sorted if you add the sort="natural" or sort="<comparatorName>" attribute to the <set> element in the mapping, but defining the set in your java code as "Set keywords = new TreeSet();" doesn't do anything, except when you're creating a new Person.

With the keywords.clear() version of code, if Keyword's hashCode method is wrong, you'll end up with the PersistentSet that was loaded by hibernate having one element, possibly with the same hashCode as before. This will cause hibernate to do nothing. When you changed the code to "keywords = null;", the next chunk of code created a new collection, and hibernate dutifully persisted it correctly: the old collection is fully deleted, and the new colleciton, with the new keyword, gets saved. You're just masking the problem, not fixing it.

You haven't posted the code for the Keyword class, but I'm guessing that the hashCode method should reutrn the hashCode of the string inside the object. Equals should compare only the strings. Do not use the database identifier when computing the hashCode or equals.

P.S. No worries about the vote. "Did not help" is the same as not voting, it doesn't take a credit away, or anything like that.

This pointed me in the right direction. The fields of a Keyword include:
- Integer id
- String name
- KeywordType type

My equals() method was checking the name and the type. However the hashCode() method was only checking the former. Changing it to also include the latter fixed the problem (and now the app works if I clear() the collection instead of setting it to null). But this puzzles me a bit. Normally Java doesn't require hashCode() to use exactly the same logic as equals(); it's only necessary that two equal objects have the same hashcode, not the other way around. Hibernate seems to require non-equal objects to have different hash codes.

Now that I read it again, Section 4.3 of the Reference does say that both equals() and hashCode() should be implemented based on "Business key equality", which I guess means they should both be looking at the same fields. So I've learned something, which is always good.

Thanks so much for your help, tenwit! If only I could give you an extra credit! :)

Cheers,

Andrew