Hibernate updating when it shouldn't.

FBueckert · **Joined:** Mon Jan 16, 2006 2:38 pm **Posts:** 4

Need help with Hibernate? Read this first:
http://www.hibernate.org/ForumMailingli ... AskForHelp

My problem is for some reason, Hibernate is trying to update a table it shouldn't. So, it gives me an AbstractFlushingEventListener - Could not synchronize database state with session.

Hibernate version:
3

Mapping documents:
Inquiry:

Code:

<?xml version="1.0"?>
<!DOCTYPE hibernate-mapping PUBLIC
"-//Hibernate/Hibernate Mapping DTD 3.0//EN"
"http://hibernate.sourceforge.net/hibernate-mapping-3.0.dtd">
<hibernate-mapping>
   <class name="mb.edu.segue.itt.domain.model.Inquiry" table="sfadb.dbo.INQUIRY">
      <id name="inquiryId" column="INQUIRY_ID">
         <generator class="identity"/>
      </id>
      <property name="date" type="timestamp" column="INQUIRY_DATE"/>
      <many-to-one name="escalation" column="INQUIRY_ESCALATION_ID" class="mb.edu.segue.itt.domain.model.Escalation"/>
      <property name="student" column="STUD_ID" />
      <many-to-one name="inquirer" column="INQUIRER_ID" class="mb.edu.segue.itt.domain.model.Inquirer"/>
      <property name="staff" column="INQUIRY_STAFF_ID" />
      <many-to-one name="priority" column="INQUIRY_PRIORITY_ID" class="mb.edu.segue.itt.domain.model.Priority"/>
      <many-to-one name="type" column="INQUIRY_TYPE_ID" class="mb.edu.segue.itt.domain.model.InquiryType"/>
      <property name="details" column="DETAILS"/>
      <bag name="reasons" table="sfadb.dbo.INQUIRY_REASONS">
        <key column="INQUIRY_ID" />
        <many-to-many column="INQUIRY_REASON_ID" class="mb.edu.segue.itt.domain.model.InquiryReason"/>
      </bag>
   </class>
</hibernate-mapping>

ApplnVerif:

Code:

<?xml version="1.0"?>
<!DOCTYPE hibernate-mapping PUBLIC "-//Hibernate/Hibernate Mapping DTD 3.0//EN"
  "http://hibernate.sourceforge.net/hibernate-mapping-3.0.dtd">
<hibernate-mapping package="mb.edu.segue.itt.domain.model.Sybase">
  <class name="ApplnVerif" table="APPLN_VERIF">
    <id name="applnid" column="APPLN_ID">
      <generator class="native" />
    </id>
    <many-to-one name="vid" column="VERIF_ID" class="VerifType" />
    <many-to-one name="status" column="VERIF_STATUS_TYPE_ID" class="VerifStatusType" />
    <property name="requestdate" column="REQUEST_DATE" />
    <property name="staff" column="USER_ID" />
    <property name="verifieddate" column="VERIF_DATE" />
    <property name="message" column="MSG_TEXT" />
    <property name="sentdate" column="SENT_DATE" />
    <property name="manual" column="MANUAL_REQ_IND" type="yes_no" />
  </class>
</hibernate-mapping>

I have a HibernateFilter that closes the session, regardless of anything that happens, so I guess I'll print the code that does the actual grabbing.
Code between sessionFactory.openSession() and session.close():

Code:

    List results = new ArrayList();
    Session session = HibernateUtil.getSession();
    String q = " from Inquiry inquiry, Student student " +
               "where student.SIN = :sin" +
               "  and inquiry.student = student.studentId";
    Query query = session.createQuery(q);
    query.setParameter("sin", sin);
    try {
      results = query.list();
    } catch (StaleStateException f) {}
    if (results.size() > 0) {
      return true;
    } else {
      return false;
    }

It errors at the .list() line.

Full stack trace of any exception that occurs:

Code:

24854 [TP-Processor2] ERROR org.hibernate.event.def.AbstractFlushingEventListener  - Could not synchronize database state with session
org.hibernate.StaleStateException: Unexpected row count: 4 expected: 1
   at org.hibernate.jdbc.NonBatchingBatcher.addToBatch(NonBatchingBatcher.java:26)
   at org.hibernate.persister.entity.BasicEntityPersister.update(BasicEntityPersister.java:1972)
   at org.hibernate.persister.entity.BasicEntityPersister.updateOrInsert(BasicEntityPersister.java:1899)
   at org.hibernate.persister.entity.BasicEntityPersister.update(BasicEntityPersister.java:2139)
   at org.hibernate.action.EntityUpdateAction.execute(EntityUpdateAction.java:75)
   at org.hibernate.engine.ActionQueue.execute(ActionQueue.java:239)
   at org.hibernate.engine.ActionQueue.executeActions(ActionQueue.java:223)
   at org.hibernate.engine.ActionQueue.executeActions(ActionQueue.java:137)
   at org.hibernate.event.def.AbstractFlushingEventListener.performExecutions(AbstractFlushingEventListener.java:274)
   at org.hibernate.event.def.DefaultAutoFlushEventListener.onAutoFlush(DefaultAutoFlushEventListener.java:48)
   at org.hibernate.impl.SessionImpl.autoFlushIfRequired(SessionImpl.java:707)
   at org.hibernate.impl.SessionImpl.prepareQueries(SessionImpl.java:891)
   at org.hibernate.impl.SessionImpl.getQueries(SessionImpl.java:881)
   at org.hibernate.impl.SessionImpl.list(SessionImpl.java:830)
   at org.hibernate.impl.QueryImpl.list(QueryImpl.java:74)
   at mb.edu.segue.itt.database.HibernateInquiryDAO.checkHistory(HibernateInquiryDAO.java:149)
   at mb.edu.segue.itt.domain.services.InquiryService.checkHistory(InquiryService.java:43)
   at mb.edu.segue.itt.database.Doc.execute(Doc.java:68)
   at org.apache.struts.action.RequestProcessor.processActionPerform(RequestProcessor.java:421)
   at org.apache.struts.action.RequestProcessor.process(RequestProcessor.java:226)
   at org.apache.struts.action.ActionServlet.process(ActionServlet.java:1164)
   at org.apache.struts.action.ActionServlet.doGet(ActionServlet.java:397)
   at javax.servlet.http.HttpServlet.service(HttpServlet.java:696)
   at javax.servlet.http.HttpServlet.service(HttpServlet.java:809)
   at org.apache.catalina.core.ApplicationDispatcher.invoke(ApplicationDispatcher.java:627)
   at org.apache.catalina.core.ApplicationDispatcher.doForward(ApplicationDispatcher.java:382)
   at org.apache.catalina.core.ApplicationDispatcher.forward(ApplicationDispatcher.java:306)
   at org.apache.struts.action.RequestProcessor.doForward(RequestProcessor.java:1056)
   at org.apache.struts.tiles.TilesRequestProcessor.doForward(TilesRequestProcessor.java:261)
   at org.apache.struts.action.RequestProcessor.processForwardConfig(RequestProcessor.java:388)
   at org.apache.struts.tiles.TilesRequestProcessor.processForwardConfig(TilesRequestProcessor.java:316)
   at org.apache.struts.action.RequestProcessor.process(RequestProcessor.java:231)
   at org.apache.struts.action.ActionServlet.process(ActionServlet.java:1164)
   at org.apache.struts.action.ActionServlet.doGet(ActionServlet.java:397)
   at javax.servlet.http.HttpServlet.service(HttpServlet.java:696)
   at javax.servlet.http.HttpServlet.service(HttpServlet.java:809)
   at org.apache.catalina.core.ApplicationFilterChain.internalDoFilter(ApplicationFilterChain.java:200)
   at org.apache.catalina.core.ApplicationFilterChain.doFilter(ApplicationFilterChain.java:146)
   at mb.edu.segue.itt.utility.HibernateFilter.doFilter(HibernateFilter.java:46)
   at org.apache.catalina.core.ApplicationFilterChain.internalDoFilter(ApplicationFilterChain.java:166)
   at org.apache.catalina.core.ApplicationFilterChain.doFilter(ApplicationFilterChain.java:146)
   at mb.edu.segue.itt.utility.EnvironmentSetupFilter.doFilter(EnvironmentSetupFilter.java:68)
   at org.apache.catalina.core.ApplicationFilterChain.internalDoFilter(ApplicationFilterChain.java:166)
   at org.apache.catalina.core.ApplicationFilterChain.doFilter(ApplicationFilterChain.java:146)
   at org.apache.catalina.core.StandardWrapperValve.invoke(StandardWrapperValve.java:209)
   at org.apache.catalina.core.StandardPipeline$StandardPipelineValveContext.invokeNext(StandardPipeline.java:596)
   at org.apache.catalina.core.StandardPipeline.invoke(StandardPipeline.java:433)
   at org.apache.catalina.core.ContainerBase.invoke(ContainerBase.java:948)
   at org.apache.catalina.core.StandardContextValve.invoke(StandardContextValve.java:144)
   at org.apache.catalina.core.StandardPipeline$StandardPipelineValveContext.invokeNext(StandardPipeline.java:596)
   at org.apache.catalina.core.StandardPipeline.invoke(StandardPipeline.java:433)
   at org.apache.catalina.core.ContainerBase.invoke(ContainerBase.java:948)
   at org.apache.catalina.core.StandardContext.invoke(StandardContext.java:2358)
   at org.apache.catalina.core.StandardHostValve.invoke(StandardHostValve.java:133)
   at org.apache.catalina.core.StandardPipeline$StandardPipelineValveContext.invokeNext(StandardPipeline.java:596)
   at org.apache.catalina.valves.ErrorDispatcherValve.invoke(ErrorDispatcherValve.java:118)
   at org.apache.catalina.core.StandardPipeline$StandardPipelineValveContext.invokeNext(StandardPipeline.java:594)
   at org.apache.catalina.valves.ErrorReportValve.invoke(ErrorReportValve.java:116)
   at org.apache.catalina.core.StandardPipeline$StandardPipelineValveContext.invokeNext(StandardPipeline.java:594)
   at org.apache.catalina.core.StandardPipeline.invoke(StandardPipeline.java:433)
   at org.apache.catalina.core.ContainerBase.invoke(ContainerBase.java:948)
   at org.apache.catalina.core.StandardEngineValve.invoke(StandardEngineValve.java:127)
   at org.apache.catalina.core.StandardPipeline$StandardPipelineValveContext.invokeNext(StandardPipeline.java:596)
   at org.apache.catalina.core.StandardPipeline.invoke(StandardPipeline.java:433)
   at org.apache.catalina.core.ContainerBase.invoke(ContainerBase.java:948)
   at org.apache.coyote.tomcat4.CoyoteAdapter.service(CoyoteAdapter.java:152)
   at org.apache.coyote.http11.Http11Processor.process(Http11Processor.java:799)
   at org.apache.coyote.http11.Http11Protocol$Http11ConnectionHandler.processConnection(Http11Protocol.java:705)
   at org.apache.tomcat.util.net.TcpWorkerThread.runIt(PoolTcpEndpoint.java:577)
   at org.apache.tomcat.util.threads.ThreadPool$ControlRunnable.run(ThreadPool.java:683)
   at java.lang.Thread.run(Thread.java:534)

Name and version of the database you are using:
Sybase SQL Server. Version 10 or 11, not sure which.

The generated SQL (show_sql=true):
Hibernate: update sfadb.dbo.STUD set SIN=?, FIRST_NAME=?, LAST_NAME=?, WARNING_IND=? where STUD_ID=?
Hibernate: update APPLN_VERIF set VERIF_ID=?, VERIF_STATUS_TYPE_ID=?, REQUEST_DATE=?, USER_ID=?, VERIF_DATE=?, MSG_TEXT=?, SENT_DATE=?, MANUAL_REQ_IND=? where APPLN_ID=?

Debug level Hibernate log excerpt:
I'm not exactly sure how to do this. If someone can tell me how, I'll gladly add it.

kochcp · **Posted:** Thu Jul 27, 2006 4:44 pm

enable log4j logging.

hibernate will then generate tons of log files if you set it to debug lvl

FBueckert · **Joined:** Mon Jan 16, 2006 2:38 pm **Posts:** 4

Ok. My Hibernate debug log file:

Code:

[TP-Processor1] DEBUG org.hibernate.hql.ast.QueryTranslatorImpl  - HQL:  from mb.edu.segue.itt.domain.model.Inquiry inquiry, mb.edu.segue.itt.domain.model.Student student where student.SIN = :sin  and inquiry.student = student.studentId
[TP-Processor1] DEBUG org.hibernate.hql.ast.QueryTranslatorImpl  - SQL: select inquiry0_.INQUIRY_ID as INQUIRY1_0_, student1_.STUD_ID as STUD1_1_, inquiry0_.INQUIRY_DATE as INQUIRY2_0_0_, inquiry0_.INQUIRY_ESCALATION_ID as INQUIRY3_0_0_, inquiry0_.STUD_ID as STUD4_0_0_, inquiry0_.INQUIRER_ID as INQUIRER5_0_0_, inquiry0_.INQUIRY_STAFF_ID as INQUIRY6_0_0_, inquiry0_.INQUIRY_PRIORITY_ID as INQUIRY7_0_0_, inquiry0_.INQUIRY_TYPE_ID as INQUIRY8_0_0_, inquiry0_.DETAILS as DETAILS0_0_, student1_.SIN as SIN2_1_, student1_.FIRST_NAME as FIRST3_2_1_, student1_.LAST_NAME as LAST4_2_1_, student1_.WARNING_IND as WARNING5_2_1_ from sfadb.dbo.INQUIRY inquiry0_, sfadb.dbo.STUD student1_ where student1_.SIN=? and inquiry0_.STUD_ID=student1_.STUD_ID
[TP-Processor1] DEBUG org.hibernate.hql.ast.ErrorCounter  - throwQueryException() : no errors
[TP-Processor1] DEBUG org.hibernate.event.def.AbstractFlushingEventListener  - flushing session
[TP-Processor1] DEBUG org.hibernate.event.def.AbstractFlushingEventListener  - processing flush-time cascades
[TP-Processor1] DEBUG org.hibernate.event.def.AbstractFlushingEventListener  - dirty checking collections
[TP-Processor1] DEBUG org.hibernate.event.def.AbstractFlushingEventListener  - Flushing entities and processing referenced collections
[TP-Processor1] DEBUG org.hibernate.persister.entity.BasicEntityPersister  - mb.edu.segue.itt.domain.model.Student.firstName is dirty
[TP-Processor1] DEBUG org.hibernate.persister.entity.BasicEntityPersister  - mb.edu.segue.itt.domain.model.Student.lastName is dirty
[TP-Processor1] DEBUG org.hibernate.event.def.DefaultFlushEntityEventListener  - Updating entity: [mb.edu.segue.itt.domain.model.Student#1055314]
[TP-Processor1] DEBUG org.hibernate.persister.entity.BasicEntityPersister  - mb.edu.segue.itt.domain.model.Sybase.ApplnVerif.requestdate is dirty
[TP-Processor1] DEBUG org.hibernate.persister.entity.BasicEntityPersister  - mb.edu.segue.itt.domain.model.Sybase.ApplnVerif.verifieddate is dirty
[TP-Processor1] DEBUG org.hibernate.event.def.DefaultFlushEntityEventListener  - Updating entity: [mb.edu.segue.itt.domain.model.Sybase.ApplnVerif#1138910]
[TP-Processor1] DEBUG org.hibernate.event.def.AbstractFlushingEventListener  - Processing unreferenced collections
[TP-Processor1] DEBUG org.hibernate.event.def.AbstractFlushingEventListener  - Scheduling collection removes/(re)creates/updates
[TP-Processor1] DEBUG org.hibernate.event.def.AbstractFlushingEventListener  - Flushed: 0 insertions, 2 updates, 0 deletions to 9 objects
[TP-Processor1] DEBUG org.hibernate.event.def.AbstractFlushingEventListener  - Flushed: 0 (re)creations, 0 updates, 0 removals to 0 collections
[TP-Processor1] DEBUG org.hibernate.pretty.Printer  - listing entities:
[TP-Processor1] DEBUG org.hibernate.pretty.Printer  - mb.edu.segue.itt.domain.model.Sybase.VerifStatusType{vid=2, desc=Verified                      }
[TP-Processor1] DEBUG org.hibernate.pretty.Printer  - mb.edu.segue.itt.domain.model.Student{studentId=1055314, warning=N, SIN=#########, firstName=######, lastName=######}
[TP-Processor1] DEBUG org.hibernate.pretty.Printer  - mb.edu.segue.itt.domain.model.Sybase.Student2{sex=M, lname=######                      , bdate=######, warning=false, fname=######                       , sin=#########, disdate=null, disabilityind=false, postdate=false, aid=1130224, studid=1055314, cifind=Y}
[TP-Processor1] DEBUG org.hibernate.pretty.Printer  - mb.edu.segue.itt.domain.model.Sybase.Province2{abbr=MB, name=######                    , cid=1, pid=1}
[TP-Processor1] DEBUG org.hibernate.pretty.Printer  - mb.edu.segue.itt.domain.model.Sybase.Country2{name=######                        , cid=1}
[TP-Processor1] DEBUG org.hibernate.pretty.Printer  - mb.edu.segue.itt.domain.model.Sybase.ApplnStatusType{sid=19, desc=######    }
[TP-Processor1] DEBUG org.hibernate.pretty.Printer  - mb.edu.segue.itt.domain.model.Sybase.VerifType{vid=2, desc=Declaration - Single - 1st    }
[TP-Processor1] DEBUG org.hibernate.pretty.Printer  - mb.edu.segue.itt.domain.model.Sybase.Address_Ver{www=null, phone=######     , currverind=true, postalcode=######      , workphone=null, cid=mb.edu.segue.itt.domain.model.Sybase.Country2#1, pid=mb.edu.segue.itt.domain.model.Sybase.Province2#1, fax=null, street2=null, userid=NOBURW  , effdate=2004-06-30 20:06:51, street1=##########               , aid=1130224, addressverid=2383211, email=null, city=#######                                }
[TP-Processor1] DEBUG org.hibernate.pretty.Printer  - mb.edu.segue.itt.domain.model.Sybase.ApplnVerif{requestdate=2004-07-05, manual=false, sentdate=null, message=######, staff=TAVAND  , status=mb.edu.segue.itt.domain.model.Sybase.VerifStatusType#2, verifieddate=2004-08-11, vid=mb.edu.segue.itt.domain.model.Sybase.VerifType#2, applnid=1138910}
[TP-Processor1] DEBUG org.hibernate.engine.ActionQueue  - changes must be flushed to space: sfadb.dbo.STUD
[TP-Processor1] DEBUG org.hibernate.event.def.DefaultAutoFlushEventListener  - Need to execute flush
[TP-Processor1] DEBUG org.hibernate.event.def.AbstractFlushingEventListener  - executing flush
[TP-Processor1] DEBUG org.hibernate.persister.entity.BasicEntityPersister  - Updating entity: [mb.edu.segue.itt.domain.model.Student#1055314]
[TP-Processor1] DEBUG org.hibernate.jdbc.AbstractBatcher  - about to open PreparedStatement (open PreparedStatements: 0, globally: 0)
[TP-Processor1] DEBUG org.hibernate.SQL  - update sfadb.dbo.STUD set SIN=?, FIRST_NAME=?, LAST_NAME=?, WARNING_IND=? where STUD_ID=?
Hibernate: update sfadb.dbo.STUD set SIN=?, FIRST_NAME=?, LAST_NAME=?, WARNING_IND=? where STUD_ID=?
[TP-Processor1] DEBUG org.hibernate.jdbc.AbstractBatcher  - preparing statement
[TP-Processor1] DEBUG org.hibernate.persister.entity.BasicEntityPersister  - Dehydrating entity: [mb.edu.segue.itt.domain.model.Student#1055314]
[TP-Processor1] DEBUG org.hibernate.persister.entity.BasicEntityPersister  - Updating entity: [mb.edu.segue.itt.domain.model.Sybase.ApplnVerif#1138910]
[TP-Processor1] DEBUG org.hibernate.jdbc.AbstractBatcher  - about to close PreparedStatement (open PreparedStatements: 1, globally: 1)
[TP-Processor1] DEBUG org.hibernate.jdbc.AbstractBatcher  - closing statement
[TP-Processor1] DEBUG org.hibernate.jdbc.AbstractBatcher  - about to open PreparedStatement (open PreparedStatements: 0, globally: 0)
[TP-Processor1] DEBUG org.hibernate.SQL  - update APPLN_VERIF set VERIF_ID=?, VERIF_STATUS_TYPE_ID=?, REQUEST_DATE=?, USER_ID=?, VERIF_DATE=?, MSG_TEXT=?, SENT_DATE=?, MANUAL_REQ_IND=? where APPLN_ID=?
Hibernate: update APPLN_VERIF set VERIF_ID=?, VERIF_STATUS_TYPE_ID=?, REQUEST_DATE=?, USER_ID=?, VERIF_DATE=?, MSG_TEXT=?, SENT_DATE=?, MANUAL_REQ_IND=? where APPLN_ID=?
[TP-Processor1] DEBUG org.hibernate.jdbc.AbstractBatcher  - preparing statement
[TP-Processor1] DEBUG org.hibernate.persister.entity.BasicEntityPersister  - Dehydrating entity: [mb.edu.segue.itt.domain.model.Sybase.ApplnVerif#1138910]
[TP-Processor1] ERROR org.hibernate.event.def.AbstractFlushingEventListener  - Could not synchronize database state with session

There was some personal information in the debug stuff, so I've replaced it with #s. I do not think this information is required.

kochcp · **Posted:** Fri Jul 28, 2006 12:00 pm

all those '... is Dirty' lines means the values in the objects are different from what is returned. That is why it is running those update statements.

Somewhere you're changing the value so when hibernate checks the getter methods for those values it sees different data from what it expects. Hibernate keeps track of what is returned in the session to check dirtiness

FBueckert · **Joined:** Mon Jan 16, 2006 2:38 pm **Posts:** 4

Great! I was changing the data, mainly to strip the timestamp off of dates, and extra spaces after actual data returned.

So I changed that back to the original data, and it works fine. Another question is: is there a way still do this, without triggering Hibernate's dirty collection?

EDIT: Never mind. I figured it out myself. Thanks again!