Hello everyone,

I've been using Hibernate for half a year now and am very happy with it. But now I'm stuck with a problem that I just seem unable to solve. I'm really baffled about this one and think I've tried everything, and re-read all documentation available (including the book).

The situation is this: I have a User object that references among other things, a UserPreferences object (mapped as one-to-one to the User object). I store the User object in a user's HttpSession and reassociate it with lock(user, LockMode.NONE) before using it, this lock also cascades to the UserPreferences object. Now I have one place where this throws a NonUniqueObject exception that I just don't understand. In all other situations it seems to work fine.

In the debug log below this happens right after "reassociating transient instance: [net.dummy.domain.UserPreferences#164586]" (the exception is caught and logged after the connection has been closed, but it really does happen before).

What I don't understand at all, is that I happen to reassociate a different user object just before, and THAT works perfectly well. The two objects are not linked in any way.

Any help about this is greatly appreciated, I really don't know where else to look. I expect it to be some silly error on my side, but I just can't find it.

Thanks for every little hint!

Bernd


Hibernate version:
2.1.8

Mapping documents:

Mapping of "User":
==================

<?xml version="1.0" encoding="UTF-8"?>
<!DOCTYPE hibernate-mapping PUBLIC
"-//Hibernate/Hibernate Mapping DTD 2.0//EN"
"http://hibernate.sourceforge.net/hibernate-mapping-2.0.dtd">

<hibernate-mapping
package="net.dummy.domain"
auto-import="true">

<class name="User" table="users" dynamic-update="true">

<id name="id" column="user_id" type="long">
<generator class="sequence">
<param name="sequence">users_user_id_seq</param>
</generator>
</id>

[... lots of other unrelated properties and associations ...]

<one-to-one name="preferences" class="UserPreferences" cascade="all" />

</class>

</hibernate-mapping>


Mapping of "UserPreferences":
=============================

<?xml version="1.0" encoding="UTF-8"?>
<!DOCTYPE hibernate-mapping PUBLIC
"-//Hibernate/Hibernate Mapping DTD 2.0//EN"
"http://hibernate.sourceforge.net/hibernate-mapping-2.0.dtd">

<hibernate-mapping
package="net.dummy.domain"
auto-import="true">

<class name="UserPreferences" table="user_preferences" dynamic-update="true" lazy="true">

<id name="id" column="user_id" type="long">
<generator class="foreign">
<param name="property">user</param>
</generator>
</id>

<one-to-one name="user" class="User" constrained="true" />

<property name="locale" column="preferred_language" type="locale"/>
<property name="timezone" column="preferred_timezone" type="timezone"/>
<property name="lengthUnits" column="preferred_length_units" type="net.dummy.domain.fields.LengthUnits$Enum"/>
<property name="weightUnits" column="preferred_weight_units" type="net.dummy.domain.fields.WeightUnits$Enum"/>
<property name="forwardPrivateMessages" column="forward_private_messages" type="boolean"/>
<property name="sendEmailNotificationForInterests" column="interested_notification_email" type="boolean"/>
<property name="searchResultsPerPage" column="search_results_per_page" type="integer"/>

</class>

</hibernate-mapping>


Debug level Hibernate log excerpt:

2005-03-13 23:54:29,395 DEBUG net.dummy.dao.hibernate.UserDAOImpl - reassociating user User(id=164586,name=golduser)
2005-03-13 23:54:29,395 DEBUG net.sf.hibernate.engine.Cascades - id unsaved-value strategy NULL
2005-03-13 23:54:29,395 DEBUG net.sf.hibernate.impl.SessionImpl - reassociating transient instance: [net.dummy.domain.User#164586]
2005-03-13 23:54:29,395 DEBUG net.sf.hibernate.engine.Cascades - processing cascades for: net.dummy.domain.User
2005-03-13 23:54:29,395 DEBUG net.sf.hibernate.engine.Cascades - cascading to collection: net.dummy.domain.User.membershipStack.membershipPeriods
2005-03-13 23:54:29,395 DEBUG net.sf.hibernate.engine.Cascades - cascading to lock()
2005-03-13 23:54:29,396 DEBUG net.sf.hibernate.impl.SessionImpl - attempting to resolve [net.dummy.domain.MembershipPeriod#150014]
2005-03-13 23:54:29,396 DEBUG net.sf.hibernate.impl.SessionImpl - object not resolved in any cache [net.dummy.domain.MembershipPeriod#150014]
2005-03-13 23:54:29,396 DEBUG net.sf.hibernate.persister.EntityPersister - Materializing entity: [net.dummy.domain.MembershipPeriod#150014]
2005-03-13 23:54:29,396 DEBUG net.sf.hibernate.impl.BatcherImpl - about to open: 0 open PreparedStatements, 0 open ResultSets
2005-03-13 23:54:29,396 DEBUG net.sf.hibernate.SQL - select membership0_.membership_period_id as membersh1_6_, membership0_._version as _version6_, ...
2005-03-13 23:54:29,398 DEBUG net.sf.hibernate.impl.BatcherImpl - preparing statement
2005-03-13 23:54:29,404 DEBUG net.sf.hibernate.type.LongType - binding '150014' to parameter: 1
2005-03-13 23:54:29,506 DEBUG net.sf.hibernate.loader.Loader - processing result set
2005-03-13 23:54:29,507 DEBUG net.sf.hibernate.type.LongType - returning '164586' as column: user_id0_
2005-03-13 23:54:29,507 DEBUG net.sf.hibernate.type.LongType - returning '164586' as column: user_id1_
2005-03-13 23:54:29,508 DEBUG net.sf.hibernate.type.LongType - returning '164586' as column: user_id2_
2005-03-13 23:54:29,508 DEBUG net.sf.hibernate.type.StringType - returning 'GM' as column: country_1_3_
2005-03-13 23:54:29,508 DEBUG net.sf.hibernate.type.StringType - returning '' as column: state_code3_
2005-03-13 23:54:29,508 DEBUG net.sf.hibernate.type.LongType - returning '110438' as column: search_q1_4_
2005-03-13 23:54:29,508 DEBUG net.sf.hibernate.type.LongType - returning '164586' as column: user_id5_
2005-03-13 23:54:29,508 DEBUG net.sf.hibernate.loader.Loader - result row: 164586, 164586, 164586, Country GM (null), 110438, 164586, 150014
2005-03-13 23:54:29,508 DEBUG net.sf.hibernate.loader.Loader - Initializing object from ResultSet: 164586
2005-03-13 23:54:29,509 DEBUG net.sf.hibernate.loader.Loader - Hydrating entity: net.dummy.domain.UserPreferences#164586
2005-03-13 23:54:29,509 DEBUG net.sf.hibernate.type.LocaleType - returning 'en_AU' as column: preferre2_1_
2005-03-13 23:54:29,509 DEBUG net.sf.hibernate.type.StringType - returning 'Etc/GMT' as column: preferre3_1_
2005-03-13 23:54:29,509 DEBUG net.sf.hibernate.type.TimeZoneType - returning 'Etc/GMT' as column: preferre3_1_
2005-03-13 23:54:29,509 DEBUG net.sf.hibernate.type.BooleanType - returning 'true' as column: forward_6_1_
2005-03-13 23:54:29,509 DEBUG net.sf.hibernate.type.BooleanType - returning 'true' as column: interest7_1_
2005-03-13 23:54:29,510 DEBUG net.sf.hibernate.type.IntegerType - returning '10' as column: search_r8_1_
2005-03-13 23:54:29,510 DEBUG net.sf.hibernate.loader.Loader - Initializing object from ResultSet: 164586
2005-03-13 23:54:29,510 DEBUG net.sf.hibernate.loader.Loader - Hydrating entity: net.dummy.domain.Profile#164586
2005-03-13 23:54:29,510 DEBUG net.sf.hibernate.type.IntegerType - returning '5' as column: max_find2_2_
2005-03-13 23:54:29,510 DEBUG net.sf.hibernate.type.IntegerType - returning '5' as column: max_find3_2_
2005-03-13 23:54:29,510 DEBUG net.sf.hibernate.type.BooleanType - returning 'false' as column: hide_fro4_2_
2005-03-13 23:54:29,511 DEBUG net.sf.hibernate.type.BooleanType - returning 'false' as column: hide_fro5_2_
2005-03-13 23:54:29,512 DEBUG net.sf.hibernate.type.CalendarType - returning '1973-01-01 01:00:00' as column: birthdate2_
2005-03-13 23:54:29,512 DEBUG net.sf.hibernate.type.DoubleType - returning '1.7018' as column: height2_
2005-03-13 23:54:29,512 DEBUG net.sf.hibernate.type.DoubleType - returning '88.335' as column: weight2_
2005-03-13 23:54:29,513 DEBUG net.sf.hibernate.type.BooleanType - returning 'false' as column: wants_x51_2_
2005-03-13 23:54:29,513 DEBUG net.sf.hibernate.type.StringType - returning 'Happy Golddigger' as column: name2_
2005-03-13 23:54:29,513 DEBUG net.sf.hibernate.type.StringType - returning '' as column: headline2_
2005-03-13 23:54:29,513 DEBUG net.sf.hibernate.type.StringType - returning '' as column: about_me2_
2005-03-13 23:54:29,513 DEBUG net.sf.hibernate.type.StringType - returning 'GM' as column: country2_
2005-03-13 23:54:29,513 DEBUG net.sf.hibernate.type.StringType - returning '' as column: state2_
2005-03-13 23:54:29,513 DEBUG net.sf.hibernate.type.StringType - returning '' as column: city2_
2005-03-13 23:54:29,513 DEBUG net.sf.hibernate.type.StringType - returning '' as column: locatio64_2_
2005-03-13 23:54:29,514 DEBUG net.sf.hibernate.type.StringType - returning '' as column: profess65_2_
2005-03-13 23:54:29,514 DEBUG net.sf.hibernate.type.StringType - returning '' as column: appeara66_2_
2005-03-13 23:54:29,514 DEBUG net.sf.hibernate.type.StringType - returning '' as column: hobbies67_2_
2005-03-13 23:54:29,514 DEBUG net.sf.hibernate.type.StringType - returning '' as column: favorit68_2_
2005-03-13 23:54:29,514 DEBUG net.sf.hibernate.type.StringType - returning '' as column: favorit69_2_
2005-03-13 23:54:29,514 DEBUG net.sf.hibernate.type.StringType - returning '' as column: favorit70_2_
2005-03-13 23:54:29,514 DEBUG net.sf.hibernate.type.StringType - returning '' as column: favorit71_2_
2005-03-13 23:54:29,514 DEBUG net.sf.hibernate.type.StringType - returning '' as column: favorit72_2_
2005-03-13 23:54:29,514 DEBUG net.sf.hibernate.type.StringType - returning '' as column: favorit73_2_
2005-03-13 23:54:29,514 DEBUG net.sf.hibernate.type.StringType - returning '' as column: favorit74_2_
2005-03-13 23:54:29,514 DEBUG net.sf.hibernate.type.StringType - returning '' as column: favorit75_2_
2005-03-13 23:54:29,514 DEBUG net.sf.hibernate.type.StringType - returning '' as column: favorit76_2_
2005-03-13 23:54:29,514 DEBUG net.sf.hibernate.type.StringType - returning '' as column: favorit77_2_
2005-03-13 23:54:29,514 DEBUG net.sf.hibernate.type.StringType - returning '' as column: favorit78_2_
2005-03-13 23:54:29,515 DEBUG net.sf.hibernate.loader.Loader - Initializing object from ResultSet: 110438
2005-03-13 23:54:29,515 DEBUG net.sf.hibernate.loader.Loader - Hydrating entity: net.dummy.domain.SearchQuery#110438
2005-03-13 23:54:29,515 DEBUG net.sf.hibernate.type.IntegerType - returning '7' as column: _version4_
2005-03-13 23:54:29,515 DEBUG net.sf.hibernate.type.LongType - returning '164586' as column: user_id4_
2005-03-13 23:54:29,515 DEBUG net.sf.hibernate.type.StringType - returning null as column: name4_
2005-03-13 23:54:29,515 DEBUG net.sf.hibernate.type.TimestampType - returning null as column: creation5_4_
2005-03-13 23:54:29,515 DEBUG net.sf.hibernate.type.TimestampType - returning null as column: purge_date4_
2005-03-13 23:54:29,516 DEBUG net.sf.hibernate.type.BooleanType - returning 'false' as column: is_advan7_4_
2005-03-13 23:54:29,516 DEBUG net.sf.hibernate.type.BooleanType - returning 'true' as column: is_ideal8_4_
2005-03-13 23:54:29,517 DEBUG net.sf.hibernate.type.IntegerType - returning '75' as column: min_age4_
2005-03-13 23:54:29,517 DEBUG net.sf.hibernate.type.IntegerType - returning '85' as column: max_age4_
2005-03-13 23:54:29,518 DEBUG net.sf.hibernate.type.DoubleType - returning '0.0' as column: min_height4_
2005-03-13 23:54:29,518 DEBUG net.sf.hibernate.type.DoubleType - returning '0.0' as column: max_height4_
2005-03-13 23:54:29,518 DEBUG net.sf.hibernate.type.DoubleType - returning '0.0' as column: min_weight4_
2005-03-13 23:54:29,518 DEBUG net.sf.hibernate.type.DoubleType - returning '0.0' as column: max_weight4_
2005-03-13 23:54:29,518 DEBUG net.sf.hibernate.type.DoubleType - returning '0.0' as column: max_di148_4_
2005-03-13 23:54:29,518 DEBUG net.sf.hibernate.type.IntegerType - returning '0' as column: max_me150_4_
2005-03-13 23:54:29,518 DEBUG net.sf.hibernate.type.IntegerType - returning '0' as column: max_id152_4_
2005-03-13 23:54:29,518 DEBUG net.sf.hibernate.type.BooleanType - returning 'true' as column: mutual154_4_
2005-03-13 23:54:29,519 DEBUG net.sf.hibernate.type.BooleanType - returning 'false' as column: pictur155_4_
2005-03-13 23:54:29,519 DEBUG net.sf.hibernate.impl.SessionImpl - Version: 7
2005-03-13 23:54:29,519 DEBUG net.sf.hibernate.loader.Loader - Initializing object from ResultSet: 164586
2005-03-13 23:54:29,519 DEBUG net.sf.hibernate.loader.Loader - Hydrating entity: net.dummy.domain.UserStatistics#164586
2005-03-13 23:54:29,519 DEBUG net.sf.hibernate.type.TimestampType - returning '2005-03-13 14:39:56' as column: last_log2_5_
2005-03-13 23:54:29,520 DEBUG net.sf.hibernate.type.IntegerType - returning '207' as column: login_co3_5_
2005-03-13 23:54:29,520 DEBUG net.sf.hibernate.type.CalendarType - returning '2005-03-13 23:54:16' as column: profile_4_5_
2005-03-13 23:54:29,520 DEBUG net.sf.hibernate.type.IntegerType - returning '26' as column: profile_5_5_
2005-03-13 23:54:29,520 DEBUG net.sf.hibernate.type.IntegerType - returning '13' as column: view_cou6_5_
2005-03-13 23:54:29,520 DEBUG net.sf.hibernate.type.IntegerType - returning '0' as column: view_cou7_5_
2005-03-13 23:54:29,520 DEBUG net.sf.hibernate.type.IntegerType - returning '5' as column: view_cou8_5_
2005-03-13 23:54:29,520 DEBUG net.sf.hibernate.type.IntegerType - returning '0' as column: view_cou9_5_
2005-03-13 23:54:29,520 DEBUG net.sf.hibernate.type.IntegerType - returning '0' as column: view_co10_5_
2005-03-13 23:54:29,521 DEBUG net.sf.hibernate.type.IntegerType - returning '0' as column: view_co11_5_
2005-03-13 23:54:29,521 DEBUG net.sf.hibernate.type.IntegerType - returning '0' as column: view_co12_5_
2005-03-13 23:54:29,521 DEBUG net.sf.hibernate.type.IntegerType - returning '0' as column: view_co13_5_
2005-03-13 23:54:29,521 DEBUG net.sf.hibernate.type.IntegerType - returning '0' as column: view_co14_5_
2005-03-13 23:54:29,521 DEBUG net.sf.hibernate.type.IntegerType - returning '0' as column: view_co15_5_
2005-03-13 23:54:29,521 DEBUG net.sf.hibernate.type.IntegerType - returning '0' as column: view_co16_5_
2005-03-13 23:54:29,521 DEBUG net.sf.hibernate.type.IntegerType - returning '0' as column: view_co17_5_
2005-03-13 23:54:29,521 DEBUG net.sf.hibernate.type.IntegerType - returning '0' as column: view_co18_5_
2005-03-13 23:54:29,521 DEBUG net.sf.hibernate.type.IntegerType - returning '0' as column: view_co19_5_
2005-03-13 23:54:29,521 DEBUG net.sf.hibernate.type.IntegerType - returning '0' as column: view_co20_5_
2005-03-13 23:54:29,521 DEBUG net.sf.hibernate.type.IntegerType - returning '0' as column: view_co21_5_
2005-03-13 23:54:29,521 DEBUG net.sf.hibernate.type.IntegerType - returning '0' as column: view_co22_5_
2005-03-13 23:54:29,522 DEBUG net.sf.hibernate.type.IntegerType - returning '0' as column: view_co23_5_
2005-03-13 23:54:29,522 DEBUG net.sf.hibernate.type.IntegerType - returning '8' as column: view_co24_5_
2005-03-13 23:54:29,522 DEBUG net.sf.hibernate.type.IntegerType - returning '0' as column: view_co25_5_
2005-03-13 23:54:29,522 DEBUG net.sf.hibernate.type.IntegerType - returning '0' as column: view_co26_5_
2005-03-13 23:54:29,522 DEBUG net.sf.hibernate.type.IntegerType - returning '0' as column: view_co27_5_
2005-03-13 23:54:29,522 DEBUG net.sf.hibernate.type.IntegerType - returning '0' as column: view_co28_5_
2005-03-13 23:54:29,522 DEBUG net.sf.hibernate.type.IntegerType - returning '0' as column: view_co29_5_
2005-03-13 23:54:29,522 DEBUG net.sf.hibernate.type.IntegerType - returning '0' as column: view_co30_5_
2005-03-13 23:54:29,522 DEBUG net.sf.hibernate.type.IntegerType - returning '0' as column: view_co31_5_
2005-03-13 23:54:29,522 DEBUG net.sf.hibernate.type.IntegerType - returning '0' as column: view_co32_5_
2005-03-13 23:54:29,522 DEBUG net.sf.hibernate.type.IntegerType - returning '10' as column: view_co33_5_
2005-03-13 23:54:29,522 DEBUG net.sf.hibernate.type.IntegerType - returning '0' as column: view_co34_5_
2005-03-13 23:54:29,522 DEBUG net.sf.hibernate.type.IntegerType - returning '0' as column: view_co35_5_
2005-03-13 23:54:29,522 DEBUG net.sf.hibernate.type.IntegerType - returning '0' as column: view_co36_5_
2005-03-13 23:54:29,522 DEBUG net.sf.hibernate.type.IntegerType - returning '0' as column: view_co37_5_
2005-03-13 23:54:29,522 DEBUG net.sf.hibernate.type.IntegerType - returning '0' as column: view_co38_5_
2005-03-13 23:54:29,523 DEBUG net.sf.hibernate.type.IntegerType - returning '0' as column: view_co39_5_
2005-03-13 23:54:29,523 DEBUG net.sf.hibernate.type.IntegerType - returning '0' as column: view_co40_5_
2005-03-13 23:54:29,523 DEBUG net.sf.hibernate.type.IntegerType - returning '0' as column: view_co41_5_
2005-03-13 23:54:29,523 DEBUG net.sf.hibernate.type.IntegerType - returning '3' as column: view_co42_5_
2005-03-13 23:54:29,523 DEBUG net.sf.hibernate.type.IntegerType - returning '0' as column: view_co43_5_
2005-03-13 23:54:29,523 DEBUG net.sf.hibernate.type.IntegerType - returning '0' as column: view_co44_5_
2005-03-13 23:54:29,523 DEBUG net.sf.hibernate.type.IntegerType - returning '0' as column: view_co45_5_
2005-03-13 23:54:29,523 DEBUG net.sf.hibernate.type.IntegerType - returning '8' as column: view_co46_5_
2005-03-13 23:54:29,523 DEBUG net.sf.hibernate.type.IntegerType - returning '0' as column: view_co47_5_
2005-03-13 23:54:29,523 DEBUG net.sf.hibernate.type.IntegerType - returning '0' as column: view_co48_5_
2005-03-13 23:54:29,523 DEBUG net.sf.hibernate.type.IntegerType - returning '0' as column: view_co49_5_
2005-03-13 23:54:29,523 DEBUG net.sf.hibernate.type.IntegerType - returning '0' as column: view_co50_5_
2005-03-13 23:54:29,523 DEBUG net.sf.hibernate.type.IntegerType - returning '0' as column: view_co51_5_
2005-03-13 23:54:29,523 DEBUG net.sf.hibernate.type.IntegerType - returning '0' as column: view_co52_5_
2005-03-13 23:54:29,523 DEBUG net.sf.hibernate.type.IntegerType - returning '0' as column: view_co53_5_
2005-03-13 23:54:29,524 DEBUG net.sf.hibernate.type.IntegerType - returning '0' as column: view_co54_5_
2005-03-13 23:54:29,524 DEBUG net.sf.hibernate.type.IntegerType - returning '0' as column: view_co55_5_
2005-03-13 23:54:29,524 DEBUG net.sf.hibernate.type.IntegerType - returning '0' as column: view_co56_5_
2005-03-13 23:54:29,524 DEBUG net.sf.hibernate.type.IntegerType - returning '0' as column: view_co57_5_
2005-03-13 23:54:29,524 DEBUG net.sf.hibernate.type.IntegerType - returning '0' as column: view_co58_5_
2005-03-13 23:54:29,524 DEBUG net.sf.hibernate.type.IntegerType - returning '0' as column: view_co59_5_
2005-03-13 23:54:29,524 DEBUG net.sf.hibernate.type.IntegerType - returning '0' as column: view_co60_5_
2005-03-13 23:54:29,524 DEBUG net.sf.hibernate.type.IntegerType - returning '0' as column: view_co61_5_
2005-03-13 23:54:29,524 DEBUG net.sf.hibernate.type.IntegerType - returning '0' as column: view_co62_5_
2005-03-13 23:54:29,524 DEBUG net.sf.hibernate.type.IntegerType - returning '0' as column: view_co63_5_
2005-03-13 23:54:29,524 DEBUG net.sf.hibernate.type.IntegerType - returning '0' as column: view_co64_5_
2005-03-13 23:54:29,524 DEBUG net.sf.hibernate.type.IntegerType - returning '13' as column: view_co65_5_
2005-03-13 23:54:29,524 DEBUG net.sf.hibernate.type.IntegerType - returning '2' as column: view_co66_5_
2005-03-13 23:54:29,524 DEBUG net.sf.hibernate.type.IntegerType - returning '0' as column: view_co67_5_
2005-03-13 23:54:29,524 DEBUG net.sf.hibernate.type.IntegerType - returning '0' as column: view_co68_5_
2005-03-13 23:54:29,525 DEBUG net.sf.hibernate.type.IntegerType - returning '0' as column: view_co69_5_
2005-03-13 23:54:29,525 DEBUG net.sf.hibernate.type.IntegerType - returning '0' as column: view_co70_5_
2005-03-13 23:54:29,525 DEBUG net.sf.hibernate.type.IntegerType - returning '0' as column: view_co71_5_
2005-03-13 23:54:29,525 DEBUG net.sf.hibernate.type.IntegerType - returning '0' as column: view_co72_5_
2005-03-13 23:54:29,525 DEBUG net.sf.hibernate.type.IntegerType - returning '0' as column: view_co73_5_
2005-03-13 23:54:29,525 DEBUG net.sf.hibernate.type.IntegerType - returning '0' as column: view_co74_5_
2005-03-13 23:54:29,525 DEBUG net.sf.hibernate.type.IntegerType - returning '0' as column: view_co75_5_
2005-03-13 23:54:29,525 DEBUG net.sf.hibernate.type.IntegerType - returning '0' as column: view_co76_5_
2005-03-13 23:54:29,525 DEBUG net.sf.hibernate.type.LongType - returning '0' as column: view_co77_5_
2005-03-13 23:54:29,525 DEBUG net.sf.hibernate.type.LongType - returning '0' as column: view_co78_5_
2005-03-13 23:54:29,525 DEBUG net.sf.hibernate.type.LongType - returning '0' as column: view_co79_5_
2005-03-13 23:54:29,525 DEBUG net.sf.hibernate.type.LongType - returning '0' as column: view_co80_5_
2005-03-13 23:54:29,525 DEBUG net.sf.hibernate.type.LongType - returning '0' as column: view_co81_5_
2005-03-13 23:54:29,525 DEBUG net.sf.hibernate.loader.Loader - Initializing object from ResultSet: 150014
2005-03-13 23:54:29,526 DEBUG net.sf.hibernate.loader.Loader - Hydrating entity: net.dummy.domain.MembershipPeriod#150014
2005-03-13 23:54:29,526 DEBUG net.sf.hibernate.type.IntegerType - returning '0' as column: _version6_
2005-03-13 23:54:29,526 DEBUG net.sf.hibernate.type.LongType - returning '164586' as column: user_id6_
2005-03-13 23:54:29,526 DEBUG net.sf.hibernate.type.LongType - returning '3' as column: membersh4_6_
2005-03-13 23:54:29,526 DEBUG net.sf.hibernate.type.IntegerType - returning '0' as column: type6_
2005-03-13 23:54:29,527 DEBUG net.sf.hibernate.type.DateType - returning '01 January 2005' as column: activati6_6_
2005-03-13 23:54:29,527 DEBUG net.sf.hibernate.type.DateType - returning null as column: end_date6_
2005-03-13 23:54:29,527 DEBUG net.sf.hibernate.type.BooleanType - returning 'false' as column: is_cance8_6_
2005-03-13 23:54:29,528 DEBUG net.sf.hibernate.type.BooleanType - returning 'true' as column: is_current6_
2005-03-13 23:54:29,528 DEBUG net.sf.hibernate.impl.SessionImpl - Version: 0
2005-03-13 23:54:29,528 DEBUG net.sf.hibernate.loader.Loader - done processing result set (1 rows)
2005-03-13 23:54:29,528 DEBUG net.sf.hibernate.impl.BatcherImpl - done closing: 0 open PreparedStatements, 0 open ResultSets
2005-03-13 23:54:29,528 DEBUG net.sf.hibernate.impl.BatcherImpl - closing statement
2005-03-13 23:54:29,528 DEBUG net.sf.hibernate.loader.Loader - total objects hydrated: 5
2005-03-13 23:54:29,528 DEBUG net.sf.hibernate.impl.SessionImpl - resolving associations for [net.dummy.domain.UserPreferences#164586]
2005-03-13 23:54:29,528 DEBUG net.sf.hibernate.impl.SessionImpl - loading [net.dummy.domain.User#164586]
2005-03-13 23:54:29,528 DEBUG net.sf.hibernate.impl.SessionImpl - attempting to resolve [net.dummy.domain.User#164586]
2005-03-13 23:54:29,529 DEBUG net.sf.hibernate.impl.SessionImpl - resolved object in session cache [net.dummy.domain.User#164586]
2005-03-13 23:54:29,529 DEBUG net.sf.hibernate.impl.SessionImpl - done materializing entity [net.dummy.domain.UserPreferences#164586]
2005-03-13 23:54:29,529 DEBUG net.sf.hibernate.impl.SessionImpl - resolving associations for [net.dummy.domain.Profile#164586]
2005-03-13 23:54:29,529 DEBUG net.sf.hibernate.impl.SessionImpl - loading [net.dummy.domain.User#164586]
2005-03-13 23:54:29,529 DEBUG net.sf.hibernate.impl.SessionImpl - attempting to resolve [net.dummy.domain.User#164586]
2005-03-13 23:54:29,529 DEBUG net.sf.hibernate.impl.SessionImpl - resolved object in session cache [net.dummy.domain.User#164586]
2005-03-13 23:54:29,529 DEBUG net.sf.hibernate.impl.SessionImpl - loading [net.dummy.domain.Country#Country GM (null)]
2005-03-13 23:54:29,529 DEBUG net.sf.hibernate.impl.SessionImpl - attempting to resolve [net.dummy.domain.Country#Country GM (null)]
2005-03-13 23:54:29,529 DEBUG net.sf.hibernate.impl.SessionImpl - resolved object in session cache [net.dummy.domain.Country#Country GM (null)]
2005-03-13 23:54:29,530 DEBUG net.sf.hibernate.impl.SessionImpl - done materializing entity [net.dummy.domain.Profile#164586]
2005-03-13 23:54:29,530 DEBUG net.sf.hibernate.impl.SessionImpl - resolving associations for [net.dummy.domain.SearchQuery#110438]
2005-03-13 23:54:29,530 DEBUG net.sf.hibernate.impl.SessionImpl - loading [net.dummy.domain.User#164586]
2005-03-13 23:54:29,530 DEBUG net.sf.hibernate.impl.SessionImpl - attempting to resolve [net.dummy.domain.User#164586]
2005-03-13 23:54:29,530 DEBUG net.sf.hibernate.impl.SessionImpl - resolved object in session cache [net.dummy.domain.User#164586]
2005-03-13 23:54:29,531 DEBUG net.sf.hibernate.impl.SessionImpl - done materializing entity [net.dummy.domain.SearchQuery#110438]
2005-03-13 23:54:29,531 DEBUG net.sf.hibernate.impl.SessionImpl - resolving associations for [net.dummy.domain.UserStatistics#164586]
2005-03-13 23:54:29,531 DEBUG net.sf.hibernate.impl.SessionImpl - loading [net.dummy.domain.User#164586]
2005-03-13 23:54:29,531 DEBUG net.sf.hibernate.impl.SessionImpl - attempting to resolve [net.dummy.domain.User#164586]
2005-03-13 23:54:29,533 DEBUG net.sf.hibernate.impl.SessionImpl - resolved object in session cache [net.dummy.domain.User#164586]
2005-03-13 23:54:29,533 DEBUG net.sf.hibernate.impl.SessionImpl - creating collection wrapper:[net.dummy.domain.UserStatistics.latestViewers#164586]
2005-03-13 23:54:29,533 DEBUG net.sf.hibernate.impl.SessionImpl - creating collection wrapper:[net.dummy.domain.UserStatistics.latestViews#164586]
2005-03-13 23:54:29,534 DEBUG net.sf.hibernate.impl.SessionImpl - done materializing entity [net.dummy.domain.UserStatistics#164586]
2005-03-13 23:54:29,534 DEBUG net.sf.hibernate.impl.SessionImpl - resolving associations for [net.dummy.domain.MembershipPeriod#150014]
2005-03-13 23:54:29,534 DEBUG net.sf.hibernate.impl.SessionImpl - loading [net.dummy.domain.User#164586]
2005-03-13 23:54:29,534 DEBUG net.sf.hibernate.impl.SessionImpl - attempting to resolve [net.dummy.domain.User#164586]
2005-03-13 23:54:29,534 DEBUG net.sf.hibernate.impl.SessionImpl - resolved object in session cache [net.dummy.domain.User#164586]
2005-03-13 23:54:29,534 DEBUG net.sf.hibernate.impl.SessionImpl - loading [net.dummy.domain.Membership#3]
2005-03-13 23:54:29,535 DEBUG net.sf.hibernate.impl.SessionImpl - done materializing entity [net.dummy.domain.MembershipPeriod#150014]
2005-03-13 23:54:29,535 DEBUG net.sf.hibernate.impl.SessionImpl - initializing non-lazy collections
2005-03-13 23:54:29,535 DEBUG net.sf.hibernate.engine.Cascades - cascading to lock()
2005-03-13 23:54:29,536 DEBUG net.sf.hibernate.engine.Cascades - id unsaved-value strategy NULL
2005-03-13 23:54:29,536 DEBUG net.sf.hibernate.impl.SessionImpl - reassociating transient instance: [net.dummy.domain.UserPreferences#164586]
2005-03-13 23:54:29,537 DEBUG net.dummy.dao.hibernate.HibernateManager - Tyring to rollback database transaction of thread Thread[http-8080-Processor25,5,main]
2005-03-13 23:54:29,537 DEBUG net.sf.hibernate.transaction.JDBCTransaction - rollback
2005-03-13 23:54:29,541 DEBUG net.sf.hibernate.impl.SessionImpl - transaction completion
2005-03-13 23:54:29,541 DEBUG net.sf.hibernate.impl.SessionImpl - closing session
2005-03-13 23:54:29,541 DEBUG net.sf.hibernate.impl.SessionImpl - disconnecting session
2005-03-13 23:54:29,542 DEBUG net.sf.hibernate.impl.SessionImpl - transaction completion
2005-03-13 23:54:29,542 DEBUG net.dummy.dao.hibernate.HibernateManager - Closed Hibernate session net.sf.hibernate.impl.SessionImpl@cf26f3 in thread Thread[http-8080-Processor25,5,main]
2005-03-13 23:54:29,615 DEBUG net.dummy.web.Engine - an exception occured: setting transaction to rollback only
2005-03-13 23:54:29,630 ERROR net.dummy.web.Engine - Unexpected Exception
org.apache.tapestry.ApplicationRuntimeException: Unable to invoke method tellImInterested on net.dummy.web.pages.ViewProfile$Enhance_0@e6646[ViewProfile]: a different object with the same identifier value was already associated with the session: 164586, of class: net.dummy.domain.UserPreferences; nested exception is net.sf.hibernate.NonUniqueObjectException: a different object with the same identifier value was already associated with the session: 164586, of class: net.dummy.domain.UserPreferences
at org.apache.tapestry.listener.ListenerMap.invokeTargetMethod(ListenerMap.java:283)
at org.apache.tapestry.listener.ListenerMap.access$100(ListenerMap.java:46)
at org.apache.tapestry.listener.ListenerMap$SyntheticListener.invoke(ListenerMap.java:97)
at org.apache.tapestry.listener.ListenerMap$SyntheticListener.actionTriggered(ListenerMap.java:102)
at org.apache.tapestry.link.DirectLink.trigger(DirectLink.java:119)
at org.apache.tapestry.engine.DirectService.service(DirectService.java:169)
at org.apache.tapestry.engine.AbstractEngine.service(AbstractEngine.java:872)
at net.dummy.web.Engine.service(Engine.java:145)
at org.apache.tapestry.ApplicationServlet.doService(ApplicationServlet.java:197)
at org.apache.tapestry.ApplicationServlet.doGet(ApplicationServlet.java:158)
at javax.servlet.http.HttpServlet.service(HttpServlet.java:689)
at javax.servlet.http.HttpServlet.service(HttpServlet.java:802)
at org.apache.catalina.core.ApplicationFilterChain.internalDoFilter(ApplicationFilterChain.java:237)
at org.apache.catalina.core.ApplicationFilterChain.doFilter(ApplicationFilterChain.java:157)
at org.apache.catalina.core.StandardWrapperValve.invoke(StandardWrapperValve.java:214)
at org.apache.catalina.core.StandardContextValve.invoke(StandardContextValve.java:178)
at org.apache.catalina.core.StandardHostValve.invoke(StandardHostValve.java:126)
at org.apache.catalina.valves.ErrorReportValve.invoke(ErrorReportValve.java:105)
at org.apache.catalina.core.StandardEngineValve.invoke(StandardEngineValve.java:107)
at org.apache.catalina.connector.CoyoteAdapter.service(CoyoteAdapter.java:148)
at org.apache.coyote.http11.Http11Processor.process(Http11Processor.java:825)
at org.apache.coyote.http11.Http11Protocol$Http11ConnectionHandler.processConnection(Http11Protocol.java:731)
at org.apache.tomcat.util.net.PoolTcpEndpoint.processSocket(PoolTcpEndpoint.java:526)
at org.apache.tomcat.util.net.LeaderFollowerWorkerThread.runIt(LeaderFollowerWorkerThread.java:80)
at org.apache.tomcat.util.threads.ThreadPool$ControlRunnable.run(ThreadPool.java:684)
at java.lang.Thread.run(Thread.java:552)
Caused by: org.springframework.orm.hibernate.HibernateSystemException: a different object with the same identifier value was already associated with the session: 164586, of class: net.dummy.domain.UserPreferences; nested exception is net.sf.hibernate.NonUniqueObjectException: a different object with the same identifier value was already associated with the session: 164586, of class: net.dummy.domain.UserPreferences
at org.springframework.orm.hibernate.SessionFactoryUtils.convertHibernateAccessException(SessionFactoryUtils.java:539)
at net.dummy.dao.hibernate.HibernateDAO.convertHibernateAccessException(HibernateDAO.java:120)
at net.dummy.dao.hibernate.UserDAOImpl.reassociateUser(UserDAOImpl.java:275)
at net.dummy.domain.logic.UserServiceImpl.confessInterestForUser(UserServiceImpl.java:487)
at net.dummy.web.pages.ViewProfile.tellImInterested(ViewProfile.java:130)
at sun.reflect.NativeMethodAccessorImpl.invoke0(Native Method)
at sun.reflect.NativeMethodAccessorImpl.invoke(NativeMethodAccessorImpl.java:39)
at sun.reflect.DelegatingMethodAccessorImpl.invoke(DelegatingMethodAccessorImpl.java:25)
at java.lang.reflect.Method.invoke(Method.java:324)
at org.apache.tapestry.listener.ListenerMap.invokeTargetMethod(ListenerMap.java:257)
... 25 more
Caused by: net.sf.hibernate.NonUniqueObjectException: a different object with the same identifier value was already associated with the session: 164586, of class: net.dummy.domain.UserPreferences
at net.sf.hibernate.impl.SessionImpl.checkUniqueness(SessionImpl.java:1687)
at net.sf.hibernate.impl.SessionImpl.reassociate(SessionImpl.java:1693)
at net.sf.hibernate.impl.SessionImpl.lock(SessionImpl.java:1719)
at net.sf.hibernate.engine.Cascades$2.cascade(Cascades.java:79)
at net.sf.hibernate.engine.Cascades.cascade(Cascades.java:436)
at net.sf.hibernate.engine.Cascades.cascade(Cascades.java:503)
at net.sf.hibernate.impl.SessionImpl.lock(SessionImpl.java:1723)
at net.dummy.dao.hibernate.UserDAOImpl.reassociateUser(UserDAOImpl.java:263)
... 32 more
2005-03-13 23:54:30,209 DEBUG net.dummy.dao.hibernate.HibernateManager - Session is closed. Ignoring committing database transaction of thread Thread[http-8080-Processor25,5,main]
2005-03-13 23:54:30,254 DEBUG net.sf.hibernate.impl.SessionImpl - opened session
2005-03-13 23:54:30,254 DEBUG net.dummy.dao.hibernate.HibernateManager - Opened new Hibernate session net.sf.hibernate.impl.SessionImpl@51f78b in thread Thread[http-8080-Processor25,5,main]
2005-03-13 23:54:30,256 DEBUG net.dummy.dao.hibernate.HibernateManager - Starting new database transaction in thread Thread[http-8080-Processor25,5,main]
2005-03-13 23:54:30,256 DEBUG net.sf.hibernate.transaction.JDBCTransaction - begin
2005-03-13 23:54:30,260 DEBUG net.sf.hibernate.transaction.JDBCTransaction - current autocommit status:false
2005-03-13 23:54:30,272 DEBUG net.dummy.dao.hibernate.HibernateManager - Tyring to rollback database transaction of thread Thread[http-8080-Processor25,5,main]
2005-03-13 23:54:30,272 DEBUG net.sf.hibernate.transaction.JDBCTransaction - rollback
2005-03-13 23:54:30,273 DEBUG net.sf.hibernate.impl.SessionImpl - transaction completion
2005-03-13 23:54:30,273 DEBUG net.sf.hibernate.impl.SessionImpl - closing session
2005-03-13 23:54:30,273 DEBUG net.sf.hibernate.impl.SessionImpl - disconnecting session
2005-03-13 23:54:30,273 DEBUG net.sf.hibernate.impl.SessionImpl - transaction completion
2005-03-13 23:54:30,273 DEBUG net.dummy.dao.hibernate.HibernateManager - Closed Hibernate session net.sf.hibernate.impl.SessionImpl@51f78b in thread Thread[http-8080-Processor25,5,main]

I know whenever a user says "this might be a bug" the developer rolls his eyes and thinks "most likely NOT" - I'm doing that too ;-). But I tried some more things and found out something rather odd, and I think some hibernate guru should at least have a look and judge himself.

I have

<property name="max_fetch_depth">3</property>

in my hibernate configuration, and have not specified any explicit outer-join attributes in my mapping documents, so hibernate's defaults should apply. with this setting the described exception is thrown.

But when I disable this kind of fetching with

<property name="max_fetch_depth">0</property>

everything is working fine. No exceptions whatsoever.

My theory is this (bear with me, I've only minor understanding of what's hibernate doing during a lock()):
- I lock the root object of class User
- hibernate traverses the hierarchy and tries to reassociate all elements it finds
- the debug log seems to imply that the UserPreferences object is hydrated as part of some outer-join-query during this process
- at a later point the hierarchy traversal hits the detached UserPreferences object that's a child of User and when it tries to reassociate that one, it finds the instance that it hydrated itself just before
=> NonUniqueObject

Anyone any ideas? For now I can work around this by disabling outer-join-fetching, but I want to keep that route open for performance tuning.

I'd be glad if some expert could have a look at this.

Thanks,
Bernd

Where is your mapping for the membershipPeriods collection?

Ah sorry, I initially thought it was a prob centered on those two classes/mappings. Here are the full ones now:

<?xml version="1.0" encoding="UTF-8"?>
<!DOCTYPE hibernate-mapping PUBLIC
"-//Hibernate/Hibernate Mapping DTD 2.0//EN"
"http://hibernate.sourceforge.net/hibernate-mapping-2.0.dtd">

<hibernate-mapping
package="net.dummy.domain"
auto-import="true">

<class name="User" table="users" dynamic-update="true">

<id name="id" column="user_id" type="long">
<generator class="sequence">
<param name="sequence">users_user_id_seq</param>
</generator>
</id>

<property name="name" column="username" type="string" update="false"/>
<property name="email" column="email" type="string"/>
<property name="password" column="password" type="string"/>

<property name="registrationIP" column="registration_ip" type="net.dummy.dao.hibernate.PostgresqlInetUserType" update="false"/>

<property name="publicUUID" column="public_uuid" type="string" update="false"/>
<property name="privateUUID" column="private_uuid" type="string" update="false"/>

<property name="dateJoined" column="date_joined" type="timestamp" update="false"/>
<property name="dateSuspended" column="date_suspended" type="timestamp"/>
<property name="dateLastModified" column="date_last_modified" type="timestamp"/>

<component name="membershipStack" class="MembershipStack">
<set name="membershipPeriods" cascade="save-update" lazy="true" inverse="true" order-by="activation_date desc">
<key column="user_id" />
<one-to-many class="MembershipPeriod"/>
</set>
</component>
<many-to-one name="currentMembershipPeriod" class="MembershipPeriod" column="current_membership_period_id" cascade="save-update" />

<one-to-one name="preferences" class="UserPreferences" cascade="all" />

<one-to-one name="profile" class="Profile" cascade="all" />

<many-to-one name="idealMatchQuery" class="SearchQuery" column="ideal_match_search_query_id" cascade="all" />

<set name="searchQueries" cascade="all-delete-orphan" lazy="true" inverse="true" order-by="name asc" where="is_ideal_match_query = 'false'">
<key column="user_id" />
<one-to-many class="SearchQuery" />
</set>

<!-- defaultImage must not change the database, it's just a reference to one of the images -->
<many-to-one name="defaultImage" class="Image" column="default_image_id" cascade="none" />
<set name="images" cascade="delete" lazy="true" inverse="true" order-by="image_id desc">
<key column="user_id" />
<one-to-many class="Image" />
</set>

<one-to-one name="statistics" class="UserStatistics" cascade="delete" />

<many-to-one name="inMailbox" class="Mailbox" column="in_mailbox_id" cascade="all" />
<many-to-one name="sentMailbox" class="Mailbox" column="sent_mailbox_id" cascade="all" />
<many-to-one name="trashMailbox" class="Mailbox" column="trash_mailbox_id" cascade="all" />
<set name="customMailboxes" lazy="true" cascade="all-delete-orphan" inverse="true" where="customizable = 'true'" order-by="title asc">
<key column="user_id" />
<one-to-many class="Mailbox" />
</set>

<set name="interestedUsers" table="users_interested" order-by="date desc" cascade="none" lazy="true">
<key column="interesting_user_id" />
<composite-element class="User$InterestedUserEntry">
<many-to-one name="interestedUser" column="interested_user_id" unique="true" />
<property name="date" column="date" type="timestamp" />
</composite-element>
</set>

<set name="blockedUsers" table="users_blocked" cascade="none" lazy="true">
<key column="user_id" />
<composite-element class="User$BlockedUserEntry">
<many-to-one name="blockedUser" column="blocked_user_id" unique="true" />
<property name="date" column="date_blocked" type="timestamp" />
</composite-element>
</set>

<set name="subscribedNewsletters" table="newsletter_subscriptions" cascade="all" lazy="true">
<key column="user_id" />
<many-to-many class="Newsletter" column="newsletter_id"/>
</set>

</class>

</hibernate-mapping>


<?xml version="1.0" encoding="UTF-8"?>
<!DOCTYPE hibernate-mapping PUBLIC
"-//Hibernate/Hibernate Mapping DTD 2.0//EN"
"http://hibernate.sourceforge.net/hibernate-mapping-2.0.dtd">

<hibernate-mapping
package="net.dummy.domain"
auto-import="true">

<class name="UserPreferences" table="user_preferences" dynamic-update="true" lazy="true">

<id name="id" column="user_id" type="long">
<generator class="foreign">
<param name="property">user</param>
</generator>
</id>

<one-to-one name="user" class="User" constrained="true" />

<property name="locale" column="preferred_language" type="locale"/>
<property name="timezone" column="preferred_timezone" type="timezone"/>
<property name="lengthUnits" column="preferred_length_units" type="net.dummy.domain.fields.LengthUnits$Enum"/>
<property name="weightUnits" column="preferred_weight_units" type="net.dummy.domain.fields.WeightUnits$Enum"/>
<property name="forwardPrivateMessages" column="forward_private_messages" type="boolean"/>
<property name="sendEmailNotificationForInterests" column="interested_notification_email" type="boolean"/>
<property name="searchResultsPerPage" column="search_results_per_page" type="integer"/>

</class>

</hibernate-mapping>


<?xml version="1.0" encoding="UTF-8"?>
<!DOCTYPE hibernate-mapping PUBLIC
"-//Hibernate/Hibernate Mapping DTD 2.0//EN"
"http://hibernate.sourceforge.net/hibernate-mapping-2.0.dtd">

<hibernate-mapping
package="net.dummy.domain"
auto-import="true">

<class name="MembershipPeriod" table="user_membershipperiods" dynamic-update="true" lazy="true">

<id name="id" column="membership_period_id" type="long">
<generator class="sequence">
<param name="sequence">user_membershipperiods_membership_period_id_seq</param>
</generator>
</id>

<version name="version" column="_version" type="integer"/>

<many-to-one name="user" class="User" column="user_id" not-null="true"/>
<many-to-one name="membership" class="Membership" column="membership_id" not-null="true"/>
<property name="membershipPeriodType" column="type" type="int"/>
<property name="activationDate" column="activation_date" type="date"/>
<property name="endDate" column="end_date" type="date"/>
<property name="cancelled" column="is_cancelled" type="boolean"/>
<property name="current" column="is_current" type="boolean"/>

</class>

</hibernate-mapping>

<?xml version="1.0" encoding="UTF-8"?>
<!DOCTYPE hibernate-mapping PUBLIC
"-//Hibernate/Hibernate Mapping DTD 2.0//EN"
"http://hibernate.sourceforge.net/hibernate-mapping-2.0.dtd">

<hibernate-mapping
package="net.dummy.domain"
auto-import="true">

<class name="Membership" table="memberships" dynamic-update="true" lazy="true">

<id name="id" column="membership_id" type="long">
<generator class="sequence">
<param name="sequence">memberships_membership_id_seq</param>
</generator>
</id>

<property name="name" column="name" type="string"/>
<property name="startDate" column="start_date" type="date"/>
<property name="endDate" column="end_date" type="date"/>
<property name="relativeValue" column="relative_value" type="integer"/>

<property name="mailboxCount" column="mailbox_count" type="integer"/>
<property name="searchQueryCount" column="search_query_count" type="integer"/>
<property name="softPrivateMessageLimit" column="private_message_count" type="integer"/>
<property name="imageCount" column="image_count" type="integer"/>
<property name="canSeeInterestedUsers" column="can_see_interested_users" type="boolean"/>
<property name="canSeeLastProfileVisitors" column="can_see_last_profile_visitors" type="boolean"/>
<property name="canSeeDetailedStatistics" column="can_see_detailed_statistics" type="boolean"/>
<property name="canUseSimpleSearch" column="can_use_simple_search" type="boolean"/>
<property name="canUseAdvancedSearch" column="can_use_advanced_search" type="boolean"/>
<property name="canGetInterestEmailNotification" column="can_get_interest_email_notification" type="boolean"/>
<property name="canGetPrivateMessageEmailForward" column="can_get_private_message_email_forward" type="boolean"/>

</class>

</hibernate-mapping>