These old forums are deprecated now and set to read-only. We are waiting for you on our new forums!
More modern, Discourse-based and with GitHub/Google/Twitter authentication built-in.

All times are UTC - 5 hours [ DST ]



Forum locked This topic is locked, you cannot edit posts or make further replies.  [ 2 posts ] 
Author Message
 Post subject: predictable, but not consistent nonUniqueObjectException
PostPosted: Wed Sep 03, 2008 7:31 pm 
Beginner
Beginner

Joined: Wed Apr 20, 2005 9:30 am
Posts: 39
I'm having an issue with a cascaded save that doesn't really have to happen. Essentially, the StockKeepingUnit (SKU) has a List of associated Media which is managed elsewhere. We're just modifying simple things (description, weight, price) in the core object and not its mapped collections. When updating certain SKUs with certain collections of Media, we get a nonUniqueObjectException. I've included the mapping files of the objects in question.

What is odd about this is that it 1) happens predictably with one particular list of items. Other SKUs with different lists of media don't have this problem. And 2) the list of media is not being modified, in fact, it's not even touched other than to get a size from it - and that's the same for all instances of our 'update' method.

I'm curious to know if anyone else has experienced this. I've been googling for an answer and find many instances where the object(s) reference is being used over an extended/open Hibernate Session but we close sessions pretty aggressively between HTTP requests and then open new ones to do a save/update like this. Likewise, if the problem were transient objects that need to be merged, why does this only happen with certain arrangements (one particular sku and its assocaited media list) and not with others?

Any help would be most appreciated.

Cheers,

J --

PS: I posted elsewhere about a cache issue which we encountered when trying to see if newer version of Hibernate would fix the problem. Never got there so I don't have a definitive answer on whether a new version would fix the problem.

Hibernate version: 3.2.6 GA

Mapping documents:

<hibernate-mapping>
<class name="com.declivis.pos.dao.StockKeepingUnit" table="skus">
<cache usage="read-write" />
<id name="id" type="int">
<column name="id" />
<generator class="identity" />
</id>
<many-to-one name="category" class="com.declivis.pos.dao.SKUCategory">
<column name="category" not-null="false" />
</many-to-one>
<snip... />
<list name="bullets" table="sku_bullets" lazy="true" cascade="all-delete-orphan">
<key column="sku_id"/>
<list-index column="sort_order" base="1"/>
<element type="string" column="bullet"/>
</list>
<list name="media" table="sku_media" lazy="false" cascade="all-delete-orphan">
<key column="sku_id"/>
<list-index column="sort_order" base="1"/>
<many-to-many column="media_id" class="com.declivis.pos.dao.Media" not-found="ignore"/>
</list>
</class>
</hibernate-mapping>

<hibernate-mapping>
<class name="com.declivis.pos.dao.Media" table="media">
<cache usage="read-write" />
<id name="id" type="integer">
<column name="id" />
<generator class="identity" />
</id>
<property name="filename" type="string">
<column name="filename" length="128" />
</property>
<property name="fileHeightL" type="integer">
<column name="fileheight_l" />
</property>
<property name="fileWidthL" type="integer">
<column name="filewidth_l" />
</property>
<property name="fileHeightM" type="integer">
<column name="fileheight_m" />
</property>
<property name="fileWidthM" type="integer">
<column name="filewidth_m" />
</property>
<property name="fileHeightH" type="integer">
<column name="fileheight_h" />
</property>
<property name="fileWidthH" type="integer">
<column name="filewidth_h" />
</property>
<property name="description" type="string">
<column name="description" />
</property>
<property name="createdDate" type="timestamp">
<column name="created_date" />
</property>
<property name="modifiedDate" type="timestamp">
<column name="modified_date" />
</property>
</class>
</hibernate-mapping>

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

SessionFactory sf = getSessionFactory();
Session ds = null;
Transaction tx = null;
try {
ds = sf.openSession();
/* this next line gets a previously looked up StockKeepingUnit in the HttpSession, modifies it and gets us to here */
StockKeepingUnit sku = getPhaseTwoRequest(request, ds);
sku.setModifiedDate(new Date());
tx = ds.beginTransaction();
ds.update(sku);
tx.commit();
Query q = ds.createQuery("from StockKeepingUnit");
List list = q.list();
ds.flush();
if (list.size() > 0)
context.put(CONTEXT_SKU_ARRAY, list);
} catch (HibernateException he) {
log.warn(he.toString());
if (tx != null)
tx.rollback();
throw new ServletException(he);
} finally {
if (ds != null)
ds.close();
}

Full stack trace of any exception that occurs:
javax.servlet.ServletException: javax.servlet.ServletException: org.hibernate.NonUniqueObjectException: a different object with the same identifier value was already associated with the session: [com.declivis.pos.dao.Media#36] at com.declivis.pos.servlets.AdminServlet.service(AdminServlet.java:202) at javax.servlet.http.HttpServlet.service(HttpServlet.java:91) at com.caucho.server.dispatch.ServletFilterChain.doFilter(ServletFilterChain.java:103) at com.declivis.pos.servlets.filters.TimerFilter.doFilter(TimerFilter.java:47) at com.caucho.server.dispatch.FilterFilterChain.doFilter(FilterFilterChain.java:87) at com.hyperworx.servlet.MultipartRequestFilter.doFilter(MultipartRequestFilter.java:118) at com.caucho.server.dispatch.FilterFilterChain.doFilter(FilterFilterChain.java:87) at com.caucho.server.webapp.WebAppFilterChain.doFilter(WebAppFilterChain.java:187) at com.caucho.server.dispatch.ServletInvocation.service(ServletInvocation.java:266) at com.caucho.server.hmux.HmuxRequest.handleRequest(HmuxRequest.java:435) at com.caucho.server.port.TcpConnection.run(TcpConnection.java:678) at com.caucho.util.ThreadPool$Item.runTasks(ThreadPool.java:721) at com.caucho.util.ThreadPool$Item.run(ThreadPool.java:643) at java.lang.Thread.run(Thread.java:619) Caused by: javax.servlet.ServletException: org.hibernate.NonUniqueObjectException: a different object with the same identifier value was already associated with the session: [com.declivis.pos.dao.Media#36] at com.declivis.pos.servlets.dispatchers.SKUHandler.modifySku(SKUHandler.java:555) at com.declivis.pos.servlets.dispatchers.SKUHandler.dispatch(SKUHandler.java:181) at com.declivis.pos.servlets.AdminServlet.service(AdminServlet.java:167) ... 13 more Caused by: org.hibernate.NonUniqueObjectException: a different object with the same identifier value was already associated with the session: [com.declivis.pos.dao.Media#36] at org.hibernate.engine.StatefulPersistenceContext.checkUniqueness(StatefulPersistenceContext.java:587) at org.hibernate.event.def.DefaultSaveOrUpdateEventListener.performUpdate(DefaultSaveOrUpdateEventListener.java:284) at org.hibernate.event.def.DefaultSaveOrUpdateEventListener.entityIsDetached(DefaultSaveOrUpdateEventListener.java:223) at org.hibernate.event.def.DefaultSaveOrUpdateEventListener.performSaveOrUpdate(DefaultSaveOrUpdateEventListener.java:89) at org.hibernate.event.def.DefaultSaveOrUpdateEventListener.onSaveOrUpdate(DefaultSaveOrUpdateEventListener.java:70) at org.hibernate.impl.SessionImpl.fireSaveOrUpdate(SessionImpl.java:507) at org.hibernate.impl.SessionImpl.saveOrUpdate(SessionImpl.java:499) at org.hibernate.engine.CascadingAction$1.cascade(CascadingAction.java:218) at org.hibernate.engine.Cascade.cascadeToOne(Cascade.java:268) at org.hibernate.engine.Cascade.cascadeAssociation(Cascade.java:216) at org.hibernate.engine.Cascade.cascadeProperty(Cascade.java:169) at org.hibernate.engine.Cascade.cascadeCollectionElements(Cascade.java:296) at org.hibernate.engine.Cascade.cascadeCollection(Cascade.java:242) at org.hibernate.engine.Cascade.cascadeAssociation(Cascade.java:219) at org.hibernate.engine.Cascade.cascadeProperty(Cascade.java:169) at org.hibernate.engine.Cascade.cascade(Cascade.java:130) at org.hibernate.engine.Cascade.cascade(Cascade.java:97) at org.hibernate.event.def.DefaultSaveOrUpdateEventListener.cascadeOnUpdate(DefaultSaveOrUpdateEventListener.java:357) at org.hibernate.event.def.DefaultSaveOrUpdateEventListener.performUpdate(DefaultSaveOrUpdateEventListener.java:329) at org.hibernate.event.def.DefaultSaveOrUpdateEventListener.entityIsDetached(DefaultSaveOrUpdateEventListener.java:223) at org.hibernate.event.def.DefaultUpdateEventListener.performSaveOrUpdate(DefaultUpdateEventListener.java:33) at org.hibernate.event.def.DefaultSaveOrUpdateEventListener.onSaveOrUpdate(DefaultSaveOrUpdateEventListener.java:70) at org.hibernate.impl.SessionImpl.fireUpdate(SessionImpl.java:564) at org.hibernate.impl.SessionImpl.update(SessionImpl.java:552) at org.hibernate.impl.SessionImpl.update(SessionImpl.java:544) at
Name and version of the database you are using:

The generated SQL (show_sql=true):

Can turn this on if needed but didn't think this is a problem with SQL.

Debug level Hibernate log excerpt:

18:18:53 DEBUG org.hibernate.impl.SessionImpl: opened session at timestamp: 4999102191550464
18:18:53 DEBUG org.hibernate.impl.SessionImpl: opened session at timestamp: 4999102191562752
18:18:53 DEBUG org.hibernate.engine.StatefulPersistenceContext: initializing non-lazy collections
18:18:53 DEBUG org.hibernate.engine.StatefulPersistenceContext: initializing non-lazy collections
18:18:53 DEBUG org.hibernate.event.def.AbstractFlushingEventListener: processing flush-time cascades
18:18:53 DEBUG org.hibernate.event.def.AbstractFlushingEventListener: dirty checking collections
18:18:53 DEBUG org.hibernate.event.def.AbstractFlushingEventListener: Flushed: 0 insertions, 0 updates, 0 deletions to 2 objects
18:18:53 DEBUG org.hibernate.event.def.AbstractFlushingEventListener: Flushed: 0 (re)creations, 0 updates, 0 removals to 0 collections
18:18:53 DEBUG org.hibernate.pretty.Printer: listing entities:
18:18:53 DEBUG org.hibernate.pretty.Printer: com.declivis.pos.dao.SKUCategory{shippingClass=null, id=3, parentId=1, taxable=false, description=You can help creativity grow in your community by launching a compelling, energizing, arts enrichment program that teachers, students and parents will love! With Play-Ground Theatre&apos;s step by step curriculum, students choose their own characters to perform and sing with teachers for families and friends to enjoy. Each class incorporates acting games, dance, music, singing, performance, teamwork and self expression in a safe, positive environment. Play-Ground Theatre Preschool Drama Programs include everything teachers need to easily make theatre a regular part of their classroom., name=Preschool, active=true, media=com.declivis.pos.dao.Media#36}
18:18:53 DEBUG org.hibernate.pretty.Printer: com.declivis.pos.dao.Media{id=36, fileHeightL=212, description=Preschool Drama Programs, fileWidthM=150, fileHeightM=212, fileWidthL=150, fileWidthH=150, fileHeightH=212, filename=pdp_vol1.jpg, createdDate=2008-05-27 08:12:00, modifiedDate=2008-05-27 08:12:00}
18:18:53 DEBUG org.hibernate.jdbc.ConnectionManager: aggressively releasing JDBC connection
18:18:53 DEBUG org.hibernate.engine.StatefulPersistenceContext: initializing non-lazy collections
18:18:53 DEBUG org.hibernate.event.def.AbstractFlushingEventListener: processing flush-time cascades
18:18:53 DEBUG org.hibernate.event.def.AbstractFlushingEventListener: dirty checking collections
18:18:53 DEBUG org.hibernate.engine.Collections: Collection found: [com.declivis.pos.dao.ShippingClass.containerFitInfo#4], was: [com.declivis.pos.dao.ShippingClass.containerFitInfo#4] (uninitialized)
18:18:53 DEBUG org.hibernate.event.def.AbstractFlushingEventListener: Flushed: 0 insertions, 0 updates, 0 deletions to 3 objects
18:18:53 DEBUG org.hibernate.event.def.AbstractFlushingEventListener: Flushed: 0 (re)creations, 0 updates, 0 removals to 1 collections
18:18:53 DEBUG org.hibernate.pretty.Printer: listing entities:
18:18:53 DEBUG org.hibernate.pretty.Printer: com.declivis.pos.dao.SKUCategory{shippingClass=null, id=3, parentId=1, taxable=false, description=You can help creativity grow in your community by launching a compelling, energizing, arts enrichment program that teachers, students and parents will love! With Play-Ground Theatre&apos;s step by step curriculum, students choose their own characters to perform and sing with teachers for families and friends to enjoy. Each class incorporates acting games, dance, music, singing, performance, teamwork and self expression in a safe, positive environment. Play-Ground Theatre Preschool Drama Programs include everything teachers need to easily make theatre a regular part of their classroom., name=Preschool, active=true, media=com.declivis.pos.dao.Media#36}
18:18:53 DEBUG org.hibernate.pretty.Printer: com.declivis.pos.dao.Media{id=36, fileHeightL=212, description=Preschool Drama Programs, fileWidthM=150, fileHeightM=212, fileWidthL=150, fileWidthH=150, fileHeightH=212, filename=pdp_vol1.jpg, createdDate=2008-05-27 08:12:00, modifiedDate=2008-05-27 08:12:00}
18:18:53 DEBUG org.hibernate.pretty.Printer: com.declivis.pos.dao.ShippingClass{containerFitInfo=<uninitialized>, weightAdjustment=0.000, asQuoted=false, FOB=false, shippingNote=, coldStatus=-1, fragile=false, softGoods=false, RTF=false, id=4, overSized=false, description=Pre-School or School Age, name=Drama Program, active=true, hazardous=false}
18:18:53 DEBUG org.hibernate.jdbc.ConnectionManager: aggressively releasing JDBC connection
18:18:53 DEBUG org.hibernate.loader.Loader: loading entity: [com.declivis.pos.dao.OriginAddress#1]
18:18:53 DEBUG org.hibernate.jdbc.AbstractBatcher: about to open PreparedStatement (open PreparedStatements: 0, globally: 0)
18:18:53 DEBUG org.hibernate.jdbc.ConnectionManager: opening JDBC connection
18:18:53 DEBUG org.hibernate.SQL: select originaddr0_.id as id30_0_, originaddr0_.name as name30_0_, originaddr0_.addr1 as addr3_30_0_, originaddr0_.addr2 as addr4_30_0_, originaddr0_.city as city30_0_, originaddr0_.state as state30_0_, originaddr0_.zip as zip30_0_, originaddr0_.country as country30_0_, originaddr0_.active as active30_0_ from origin_addr originaddr0_ where originaddr0_.id=?
18:18:53 DEBUG org.hibernate.jdbc.AbstractBatcher: about to open ResultSet (open ResultSets: 0, globally: 0)
18:18:53 DEBUG org.hibernate.loader.Loader: result row: EntityKey[com.declivis.pos.dao.OriginAddress#1]
18:18:53 DEBUG org.hibernate.jdbc.AbstractBatcher: about to close ResultSet (open ResultSets: 1, globally: 1)
18:18:53 DEBUG org.hibernate.jdbc.AbstractBatcher: about to close PreparedStatement (open PreparedStatements: 1, globally: 1)
18:18:53 DEBUG org.hibernate.jdbc.ConnectionManager: aggressively releasing JDBC connection
18:18:53 DEBUG org.hibernate.jdbc.ConnectionManager: releasing JDBC connection [ (open PreparedStatements: 0, globally: 0) (open ResultSets: 0, globally: 0)]
18:18:53 DEBUG org.hibernate.engine.TwoPhaseLoad: resolving associations for [com.declivis.pos.dao.OriginAddress#1]
18:18:53 DEBUG org.hibernate.engine.TwoPhaseLoad: done materializing entity [com.declivis.pos.dao.OriginAddress#1]
18:18:53 DEBUG org.hibernate.engine.StatefulPersistenceContext: initializing non-lazy collections
18:18:53 DEBUG org.hibernate.loader.Loader: done entity load
18:18:53 DEBUG org.hibernate.event.def.AbstractFlushingEventListener: processing flush-time cascades
18:18:53 DEBUG org.hibernate.event.def.AbstractFlushingEventListener: dirty checking collections
18:18:53 DEBUG org.hibernate.engine.Collections: Collection found: [com.declivis.pos.dao.ShippingClass.containerFitInfo#4], was: [com.declivis.pos.dao.ShippingClass.containerFitInfo#4] (uninitialized)
18:18:53 DEBUG org.hibernate.event.def.AbstractFlushingEventListener: Flushed: 0 insertions, 0 updates, 0 deletions to 4 objects
18:18:53 DEBUG org.hibernate.event.def.AbstractFlushingEventListener: Flushed: 0 (re)creations, 0 updates, 0 removals to 1 collections
18:18:53 DEBUG org.hibernate.pretty.Printer: listing entities:
18:18:53 DEBUG org.hibernate.pretty.Printer: com.declivis.pos.dao.OriginAddress{id=1, zip=80474, addr1=169 Albert Drive, addr2=PO Box 58, name=Rollinsville, state=CO, active=true, country=US, city=Rollinsville}
18:18:53 DEBUG org.hibernate.pretty.Printer: com.declivis.pos.dao.SKUCategory{shippingClass=null, id=3, parentId=1, taxable=false, description=You can help creativity grow in your community by launching a compelling, energizing, arts enrichment program that teachers, students and parents will love! With Play-Ground Theatre&apos;s step by step curriculum, students choose their own characters to perform and sing with teachers for families and friends to enjoy. Each class incorporates acting games, dance, music, singing, performance, teamwork and self expression in a safe, positive environment. Play-Ground Theatre Preschool Drama Programs include everything teachers need to easily make theatre a regular part of their classroom., name=Preschool, active=true, media=com.declivis.pos.dao.Media#36}
18:18:53 DEBUG org.hibernate.pretty.Printer: com.declivis.pos.dao.Media{id=36, fileHeightL=212, description=Preschool Drama Programs, fileWidthM=150, fileHeightM=212, fileWidthL=150, fileWidthH=150, fileHeightH=212, filename=pdp_vol1.jpg, createdDate=2008-05-27 08:12:00, modifiedDate=2008-05-27 08:12:00}
18:18:53 DEBUG org.hibernate.pretty.Printer: com.declivis.pos.dao.ShippingClass{containerFitInfo=<uninitialized>, weightAdjustment=0.000, asQuoted=false, FOB=false, shippingNote=, coldStatus=-1, fragile=false, softGoods=false, RTF=false, id=4, overSized=false, description=Pre-School or School Age, name=Drama Program, active=true, hazardous=false}
18:18:53 DEBUG org.hibernate.jdbc.ConnectionManager: aggressively releasing JDBC connection
18:18:53 DEBUG org.hibernate.transaction.JTATransaction: Looking for UserTransaction under: java:comp/UserTransaction
18:18:53 DEBUG org.hibernate.transaction.JTATransaction: Obtained UserTransaction
18:18:53 DEBUG org.hibernate.transaction.JTATransaction: begin
18:18:53 DEBUG org.hibernate.transaction.JTATransaction: Began a new JTA transaction
18:18:53 DEBUG org.hibernate.jdbc.JDBCContext: successfully registered Synchronization
18:18:53 DEBUG org.hibernate.transaction.JTATransaction: rollback
18:18:53 DEBUG org.hibernate.transaction.JTATransaction: Rolled back JTA UserTransaction


Top
 Profile  
 
 Post subject:
PostPosted: Thu Sep 04, 2008 12:58 pm 
Beginner
Beginner

Joined: Wed Apr 20, 2005 9:30 am
Posts: 39
After watching this more and more, and turning on log trace:

11:17:44 TRACE org.hibernate.event.def.AbstractSaveEventListener: detached instance of: com.declivis.pos.dao.Media
11:17:44 TRACE org.hibernate.event.def.DefaultSaveOrUpdateEventListener: updating detached instance
11:17:44 TRACE org.hibernate.event.def.DefaultSaveOrUpdateEventListener: updating [com.declivis.pos.dao.Media#15]
11:17:44 TRACE org.hibernate.event.def.DefaultSaveOrUpdateEventListener: updating [com.declivis.pos.dao.Media#15]
11:17:44 TRACE org.hibernate.engine.CascadingAction: cascading to saveOrUpdate: com.declivis.pos.dao.Media
11:17:44 TRACE org.hibernate.engine.IdentifierValue: id unsaved-value: 0
11:17:44 TRACE org.hibernate.event.def.AbstractSaveEventListener: detached instance of: com.declivis.pos.dao.Media
11:17:44 TRACE org.hibernate.event.def.DefaultSaveOrUpdateEventListener: updating detached instance
11:17:44 TRACE org.hibernate.event.def.DefaultSaveOrUpdateEventListener: updating [com.declivis.pos.dao.Media#36]
11:17:44 DEBUG org.hibernate.transaction.JTATransaction: rollback

I have focused more than too much time on Media #36 and can find nothing odd about it, but for sanity's sake, I made a new media object which has identical information in it. I changed the media_id in the association table and the exception stops happening...

I've tried running this through a debugger, but the coding style is such that's impossible to see the actual moment of failure. For certain it occurs with this method:

org.hibernate.engine.StatefulPersistenceContext.checkUniqueness(StatefulPersistenceContext.java:587)

That's from the exception stack trace (see previous post). After watching this in the debugger, it sure does seem that identical objects are being compared and being found not-equal. This is made more odd that I can create an identical DB entry that does not exhibit this behavior.

Any thoughts? Anyone? Please?


Top
 Profile  
 
Display posts from previous:  Sort by  
Forum locked This topic is locked, you cannot edit posts or make further replies.  [ 2 posts ] 

All times are UTC - 5 hours [ DST ]


You cannot post new topics in this forum
You cannot reply to topics in this forum
You cannot edit your posts in this forum
You cannot delete your posts in this forum

Search for:
© Copyright 2014, Red Hat Inc. All rights reserved. JBoss and Hibernate are registered trademarks and servicemarks of Red Hat, Inc.