Hibernate version: 3.0RC1

Hi,

I'am using the new event system, which is a great feature for us.

I have created my own listeners (extending hibernate default listeners) in order to implement generic behaviour in our home made framework.


Configuration cfg = new Configuration();

PreUpdateListener preUpdateListener = new PreUpdateListener();
PostUpdateListener postUpdateListener = new PostUpdateListener();
PreInsertListener preInsertListener = new PreInsertListener();
PostInsertListener postInsertListener = new PostInsertListener();
PreDeleteListener preDeleteListener = new PreDeleteListener();
PostDeleteListener postDeleteListener = new PostDeleteListener();
SaveOrUpdateListener saveOrUpdateListener = new SaveOrUpdateListener();

cfg.setListener("pre-update",preUpdateListener);
cfg.setListener("post-update",postUpdateListener);
cfg.setListener("pre-insert",preInsertListener);
cfg.setListener("post-insert",postInsertListener);
cfg.setListener("pre-delete",preDeleteListener);
cfg.setListener("post-delete",postDeleteListener);
cfg.setListener("save-update",saveOrUpdateListener);


Code excerpts from <b>my PreUpdateListener implementation</b> :


...
public boolean preUpdate(PreUpdateEvent event) {

PersistentEntity persistentEntity = (PersistentEntity ) event.getEntity();
validate(persistentEntity);
super.preUpdate(event);

}

...

In my DAO :

Transaction transaction = this.session.beginTransaction();
this.session.saveOrUpdate(agriculteur);
// preUpdate is called during flush() !!!!
this.session.flush();
transaction.commit();


Before updating a row i want to validate the entity.

I get the following error when the object was detached and reattached by saveAndUpdate:


16:40:41,182 ERROR AssertionFailure:22 - an assertion failure occured (this may indicate a bug in Hibernate, but is more likely due to unsafe use of the session)
org.hibernate.AssertionFailure: collection was not processed by flush()
at org.hibernate.engine.CollectionEntry.postFlush(CollectionEntry.java:144)
at org.hibernate.event.def.AbstractFlushingEventListener.postFlush(AbstractFlushingEventListener.java:305)
at org.hibernate.event.def.DefaultFlushEventListener.onFlush(DefaultFlushEventListener.java:28)
at org.hibernate.impl.SessionImpl.flush(SessionImpl.java:669)


mapping files are :

Agriculteur stands for Farmer
Parcelle stands for Parcel
Production stands for Production (Soja, Maize, Wheat, Grass, ....)

Farmer <- 1-N -> Parcel <- 1-N -> Production

<class name="demo.business.agriculteur.Agriculteur"
table="T_AGRICULTEUR"
dynamic-update="true"
optimistic-lock="dirty"
lazy="false"
>


<id name="id" type="int" column="AGR_CDN">
<generator class="increment" />
</id>
...
<!-- bi-directional one-to-many association to Parcelle -->
<bag name="parcelles" lazy="true" inverse="true"
cascade="all">
<key>
<column name="AGR_CDN" />
</key>
<one-to-many class="demo.business.agriculteur.Parcelle" />
</bag>
...

</class>

<class
name="demo.business.agriculteur.Parcelle"
table="T_PARCELLE"
dynamic-update="true"
optimistic-lock="dirty"
>

<id name="id" type="int" column="PAR_CDN">
<generator class="increment" />
</id>
...
<!-- bi-directional one-to-many association to Production -->
<bag name="productions" lazy="true" inverse="true"
cascade="all">
<key>
<column name="PAR_CDN" />
</key>
<one-to-many class="demo.business.agriculteur.Production" />
</bag>

</class>



<class
name="demo.business.agriculteur.Production"
table="T_PRODUCTION"
dynamic-update="true"
optimistic-lock="dirty"
lazy="false"
>


<id
name="id"
type="int"
column="PROD_CDN"
>
<generator class="increment" />
</id>

....
<!-- associations -->
<!-- bi-directional many-to-one association to Parcelle -->
<many-to-one
name="parcelle"
class="demo.business.agriculteur.Parcelle"
not-null="true"
>
<column name="PAR_CDN" />
</many-to-one>


</class>

The Agriculteur validate() method check if the Agriculteur owns one Parcelle at least. The collection of Parcelle is loaded in the preUpdate method via validate() (the transaction is already opened).

When i save or update the Farmer object the assertion failed when Hibernate try to save "demo.agriculteur.parcelles.productions" (CollectionEntry.role) .


Transaction transaction = this.session.beginTransaction();
this.session.saveOrUpdate(agriculteur);
// preUpdate is called !!!!
this.session.flush();
transaction.commit();

If i load the bags manually with the debugger before the flush() and after saveOrUpdate() : no errors at all !!!!!


I've check many times : my bags are bound to the current session which is opened.

Why does-it works when i preload the bags with the eclipse debugger before flushing the session ??

Any idea ???

do you listener stuff call the proper super.xxx methods ?

-max

yes.

I've checked this.
I've checked that the error occurs when i want to execute my validation rule on a detached Agriculteur objet inside the preUpdate method.

My Rule is executed by the preUdpate method :

public class ParcellesRule extends AbstractBusinessRule {

public ParcellesRule(){
setName("Parcelles");
}

/**
*
* @inheritDoc
*
*/
public RuleReport validate(Object object) {

RuleReport report = new RuleReport();
Agriculteur agriculteur = (Agriculteur) object;
if (CommonHelper.isEmpty(agriculteur.getParcelles())) {
report.addMessage(new RuleMessage("Un agriculteur doit posséder au moins une parcelle.", "parcelles"));
}
if(!CommonHelper.isEmpty(agriculteur.getParcelles())){
Map parcellesLibelle = new HashMap();
Iterator iterator = agriculteur.getParcelles().iterator();
while(iterator.hasNext()){
Parcelle parcelle = (Parcelle) iterator.next();
String libelle = parcelle.getLibelle();
if(parcellesLibelle.containsKey(parcelle.getLibelle())){
report.addMessage(new RuleMessage("Un agriculteur ne peut avoir deux parcelles avec le même libellé.", "parcelles"));
break;
}
else {
parcellesLibelle.put(libelle,libelle);
}
}
}
return report;
}
}


The same code works fine with a new transient Agriculteur object.


My domain model is :

Farmer <- 1-N -> Parcel <- 1-N -> Production

If i remove the association between Parcel and Production there is no errors, even with detached object.

Some code :

Agriculteur agriculteur1 = null;

// Step 1
this.session = createSession();
agriculteur1 = (Agriculteur) this.session.load(Agriculteur.class, new Integer(14));
this.session.close();

// Step 2
this.session = this.createSession();
Transaction transaction = null;
try {
transaction = this.session.beginTransaction();
agriculteur1.setName("TEST UNIT");
this.session.saveOrUpdate(agriculteur1);
// Oups !! This raises an error !!
this.session.flush();
transaction.commit();
} catch (HibernateException he) {
Logs.logError(getClass(), "Failed to save object.", he);
rollbackTransaction(transaction);
}
this.session.close();


Hibernate Debug for Step 1:


11:20:27,953 DEBUG SessionImpl:229 - opened session
11:20:30,156 DEBUG DefaultLoadEventListener:193 - loading entity: [demo.business.agriculteur.Agriculteur#14]
11:20:30,156 DEBUG DefaultLoadEventListener:326 - attempting to resolve: [demo.business.agriculteur.Agriculteur#14]
11:20:30,156 DEBUG DefaultLoadEventListener:362 - object not resolved in any cache: [demo.business.agriculteur.Agriculteur#14]
11:20:30,156 DEBUG BasicEntityPersister:2449 - Materializing entity: [demo.business.agriculteur.Agriculteur#14]
11:20:30,172 DEBUG Loader:1250 - loading entity: [demo.business.agriculteur.Agriculteur#14]
11:20:30,172 DEBUG AbstractBatcher:258 - about to open PreparedStatement (open PreparedStatements: 0, globally: 0)
11:20:30,172 DEBUG AbstractBatcher:379 - opening JDBC connection
11:20:30,187 DEBUG SQL:292 - select agriculteu0_.AGR_CDN as AGR1_4_, agriculteu0_.AGR_NOM_LB as AGR2_0_4_, agriculteu0_.AGR_PRENOM_LB as AGR3_0_4_, agriculteu0_.AGR_COM_LB as AGR4_0_4_, agriculteu0_.AGR_ADR1_LB as AGR5_0_4_, agriculteu0_.AGR_ADR2_LB as AGR6_0_4_, agriculteu0_.AGR_ACTIF_ON as AGR7_0_4_, agriculteu0_.AGR_CODPOS_LB as AGR8_0_4_, agriculteu0_.AGR_PERE_CDN as AGR9_0_4_, agriculteu0_.ETAT_CDN as ETAT10_0_4_, agriculteu0_.TYPE_CDN as TYPE11_0_4_, agriculteu0_.JUR_CDN as JUR12_0_4_, agriculteu1_.AGR_CDN as AGR1_0_, agriculteu1_.AGR_NOM_LB as AGR2_0_0_, agriculteu1_.AGR_PRENOM_LB as AGR3_0_0_, agriculteu1_.AGR_COM_LB as AGR4_0_0_, agriculteu1_.AGR_ADR1_LB as AGR5_0_0_, agriculteu1_.AGR_ADR2_LB as AGR6_0_0_, agriculteu1_.AGR_ACTIF_ON as AGR7_0_0_, agriculteu1_.AGR_CODPOS_LB as AGR8_0_0_, agriculteu1_.AGR_PERE_CDN as AGR9_0_0_, agriculteu1_.ETAT_CDN as ETAT10_0_0_, agriculteu1_.TYPE_CDN as TYPE11_0_0_, agriculteu1_.JUR_CDN as JUR12_0_0_, etatagricu2_.ETAT_CDN as ETAT1_1_, etatagricu2_.ETAT_LIB_LB as ETAT2_5_1_, etatagricu2_.ETA_RFA as ETA3_5_1_, typeagricu3_.TYPE_CDN as TYPE1_2_, typeagricu3_.TYPE_LIB_LB as TYPE2_4_2_, typeagricu3_.TYPE_RFA as TYPE3_4_2_, naturejuri4_.JUR_CDN as JUR1_3_, naturejuri4_.JUR_LB as JUR2_6_3_, naturejuri4_.JUR_RFA as JUR3_6_3_ from T_AGRICULTEUR agriculteu0_ left outer join T_AGRICULTEUR agriculteu1_ on agriculteu0_.AGR_PERE_CDN=agriculteu1_.AGR_CDN left outer join T_ETAT_AGRICULTEUR etatagricu2_ on agriculteu1_.ETAT_CDN=etatagricu2_.ETAT_CDN left outer join T_TYPE_AGRICULTEUR typeagricu3_ on agriculteu1_.TYPE_CDN=typeagricu3_.TYPE_CDN left outer join T_NATJURID naturejuri4_ on agriculteu1_.JUR_CDN=naturejuri4_.JUR_CDN where agriculteu0_.AGR_CDN=?
Hibernate: select agriculteu0_.AGR_CDN as AGR1_4_, agriculteu0_.AGR_NOM_LB as AGR2_0_4_, agriculteu0_.AGR_PRENOM_LB as AGR3_0_4_, agriculteu0_.AGR_COM_LB as AGR4_0_4_, agriculteu0_.AGR_ADR1_LB as AGR5_0_4_, agriculteu0_.AGR_ADR2_LB as AGR6_0_4_, agriculteu0_.AGR_ACTIF_ON as AGR7_0_4_, agriculteu0_.AGR_CODPOS_LB as AGR8_0_4_, agriculteu0_.AGR_PERE_CDN as AGR9_0_4_, agriculteu0_.ETAT_CDN as ETAT10_0_4_, agriculteu0_.TYPE_CDN as TYPE11_0_4_, agriculteu0_.JUR_CDN as JUR12_0_4_, agriculteu1_.AGR_CDN as AGR1_0_, agriculteu1_.AGR_NOM_LB as AGR2_0_0_, agriculteu1_.AGR_PRENOM_LB as AGR3_0_0_, agriculteu1_.AGR_COM_LB as AGR4_0_0_, agriculteu1_.AGR_ADR1_LB as AGR5_0_0_, agriculteu1_.AGR_ADR2_LB as AGR6_0_0_, agriculteu1_.AGR_ACTIF_ON as AGR7_0_0_, agriculteu1_.AGR_CODPOS_LB as AGR8_0_0_, agriculteu1_.AGR_PERE_CDN as AGR9_0_0_, agriculteu1_.ETAT_CDN as ETAT10_0_0_, agriculteu1_.TYPE_CDN as TYPE11_0_0_, agriculteu1_.JUR_CDN as JUR12_0_0_, etatagricu2_.ETAT_CDN as ETAT1_1_, etatagricu2_.ETAT_LIB_LB as ETAT2_5_1_, etatagricu2_.ETA_RFA as ETA3_5_1_, typeagricu3_.TYPE_CDN as TYPE1_2_, typeagricu3_.TYPE_LIB_LB as TYPE2_4_2_, typeagricu3_.TYPE_RFA as TYPE3_4_2_, naturejuri4_.JUR_CDN as JUR1_3_, naturejuri4_.JUR_LB as JUR2_6_3_, naturejuri4_.JUR_RFA as JUR3_6_3_ from T_AGRICULTEUR agriculteu0_ left outer join T_AGRICULTEUR agriculteu1_ on agriculteu0_.AGR_PERE_CDN=agriculteu1_.AGR_CDN left outer join T_ETAT_AGRICULTEUR etatagricu2_ on agriculteu1_.ETAT_CDN=etatagricu2_.ETAT_CDN left outer join T_TYPE_AGRICULTEUR typeagricu3_ on agriculteu1_.TYPE_CDN=typeagricu3_.TYPE_CDN left outer join T_NATJURID naturejuri4_ on agriculteu1_.JUR_CDN=naturejuri4_.JUR_CDN where agriculteu0_.AGR_CDN=?
11:20:30,187 DEBUG AbstractBatcher:343 - preparing statement
11:20:30,203 DEBUG IntegerType:59 - binding '14' to parameter: 1
11:20:30,203 DEBUG AbstractBatcher:274 - about to open ResultSet (open ResultSets: 0, globally: 0)
11:20:30,219 DEBUG Loader:377 - processing result set
11:20:30,219 DEBUG Loader:382 - result set row: 0
11:20:30,219 DEBUG IntegerType:80 - returning null as column: AGR1_0_
11:20:30,234 DEBUG IntegerType:80 - returning null as column: ETAT1_1_
11:20:30,234 DEBUG IntegerType:80 - returning null as column: TYPE1_2_
11:20:30,234 DEBUG IntegerType:80 - returning null as column: JUR1_3_
11:20:30,250 DEBUG Loader:719 - result row: null, null, null, null, EntityKey[demo.business.agriculteur.Agriculteur#14]
11:20:30,250 DEBUG Loader:864 - Initializing object from ResultSet: [demo.business.agriculteur.Agriculteur#14]
11:20:30,250 DEBUG BasicEntityPersister:1625 - Hydrating entity: [demo.business.agriculteur.Agriculteur#14]
11:20:30,265 DEBUG StringType:86 - returning 'JUNIT' as column: AGR2_0_4_
11:20:30,265 DEBUG StringType:86 - returning 'JUNIT' as column: AGR3_0_4_
11:20:30,281 DEBUG StringType:86 - returning 'JUNIT' as column: AGR4_0_4_
11:20:30,281 DEBUG StringType:86 - returning 'JUNIT' as column: AGR5_0_4_
11:20:30,297 DEBUG StringType:86 - returning 'JUNIT' as column: AGR6_0_4_
11:20:30,297 DEBUG IntegerType:86 - returning '0' as column: AGR7_0_4_
11:20:30,297 DEBUG StringType:86 - returning 'JUNIT' as column: AGR8_0_4_
11:20:30,312 DEBUG IntegerType:80 - returning null as column: AGR9_0_4_
11:20:30,312 DEBUG IntegerType:86 - returning '1' as column: ETAT10_0_4_
11:20:30,312 DEBUG IntegerType:86 - returning '1' as column: TYPE11_0_4_
11:20:30,328 DEBUG IntegerType:86 - returning '1' as column: JUR12_0_4_
11:20:30,328 DEBUG Loader:399 - done processing result set (1 rows)
11:20:30,343 DEBUG AbstractBatcher:281 - about to close ResultSet (open ResultSets: 1, globally: 1)
11:20:30,343 DEBUG AbstractBatcher:266 - about to close PreparedStatement (open PreparedStatements: 1, globally: 1)
11:20:30,343 DEBUG AbstractBatcher:363 - closing statement
11:20:30,359 DEBUG Loader:450 - total objects hydrated: 1
11:20:30,359 DEBUG TwoPhaseLoad:96 - resolving associations for [demo.business.agriculteur.Agriculteur#14]
11:20:30,375 DEBUG CollectionLoadContext:134 - creating collection wrapper:[demo.business.agriculteur.Agriculteur.visites#14]
11:20:30,375 DEBUG CollectionLoadContext:134 - creating collection wrapper:[demo.business.agriculteur.Agriculteur.parcelles#14]
11:20:30,375 DEBUG DefaultLoadEventListener:193 - loading entity: [demo.business.agriculteur.EtatAgriculteur#1]
11:20:30,390 DEBUG DefaultLoadEventListener:326 - attempting to resolve: [demo.business.agriculteur.EtatAgriculteur#1]
11:20:30,390 DEBUG DefaultLoadEventListener:514 - resolved object in second-level cache: [demo.business.agriculteur.EtatAgriculteur#1]
11:20:30,406 DEBUG DefaultLoadEventListener:536 - Cached Version: null
11:20:30,406 DEBUG DefaultLoadEventListener:353 - resolved object in second-level cache: [demo.business.agriculteur.EtatAgriculteur#1]
11:20:30,422 DEBUG DefaultLoadEventListener:193 - loading entity: [demo.business.agriculteur.TypeAgriculteur#1]
11:20:30,422 DEBUG DefaultLoadEventListener:326 - attempting to resolve: [demo.business.agriculteur.TypeAgriculteur#1]
11:20:30,422 DEBUG DefaultLoadEventListener:514 - resolved object in second-level cache: [demo.business.agriculteur.TypeAgriculteur#1]
11:20:30,437 DEBUG DefaultLoadEventListener:536 - Cached Version: null
11:20:30,437 DEBUG DefaultLoadEventListener:353 - resolved object in second-level cache: [demo.business.agriculteur.TypeAgriculteur#1]
11:20:30,437 DEBUG DefaultLoadEventListener:193 - loading entity: [demo.business.agriculteur.NatureJuridique#1]
11:20:30,468 DEBUG DefaultLoadEventListener:326 - attempting to resolve: [demo.business.agriculteur.NatureJuridique#1]
11:20:30,468 DEBUG DefaultLoadEventListener:514 - resolved object in second-level cache: [demo.business.agriculteur.NatureJuridique#1]
11:20:30,484 DEBUG DefaultLoadEventListener:536 - Cached Version: null
11:20:30,484 DEBUG DefaultLoadEventListener:353 - resolved object in second-level cache: [demo.business.agriculteur.NatureJuridique#1]
11:20:30,484 DEBUG TwoPhaseLoad:167 - done materializing entity [demo.business.agriculteur.Agriculteur#14]
11:20:30,500 DEBUG PersistenceContext:738 - initializing non-lazy collections
11:20:30,500 DEBUG Loader:1278 - done entity load
11:20:32,406 DEBUG SessionImpl:246 - closing session
11:20:32,406 DEBUG AbstractBatcher:394 - closing JDBC connection (open PreparedStatements: 0, globally: 0) (open ResultSets: 0, globally: 0)
11:20:32,421 DEBUG JDBCContext:213 - after transaction completion
11:20:32,421 DEBUG SessionImpl:353 - after transaction completion


Logs for Step 2 :

11:22:58,412 DEBUG SessionImpl:229 - opened session
11:23:00,537 DEBUG JDBCTransaction:46 - begin
11:23:00,537 DEBUG AbstractBatcher:379 - opening JDBC connection
11:23:00,552 DEBUG JDBCTransaction:50 - current autocommit status: false
11:23:03,396 DEBUG Cascades:525 - id unsaved-value: null
11:23:03,396 DEBUG AbstractSaveEventListener:412 - detached instance of: demo.business.agriculteur.Agriculteur
11:23:03,396 DEBUG DefaultSaveOrUpdateEventListener:200 - updating detached instance
11:23:03,427 DEBUG DefaultSaveOrUpdateEventListener:246 - updating [demo.business.agriculteur.Agriculteur#15]
11:23:03,443 DEBUG DefaultSaveOrUpdateEventListener:293 - updating [demo.business.agriculteur.Agriculteur#15]
11:23:03,443 DEBUG Cascades:806 - processing cascade ACTION_SAVE_UPDATE for: demo.business.agriculteur.Agriculteur
11:23:03,443 DEBUG Cascades:855 - cascade ACTION_SAVE_UPDATE for collection: demo.business.agriculteur.Agriculteur.visites
11:23:03,443 DEBUG Cascades:873 - done cascade ACTION_SAVE_UPDATE for collection: demo.business.agriculteur.Agriculteur.visites
11:23:03,458 DEBUG Cascades:855 - cascade ACTION_SAVE_UPDATE for collection: demo.business.agriculteur.Agriculteur.parcelles
11:23:03,458 DEBUG Cascades:873 - done cascade ACTION_SAVE_UPDATE for collection: demo.business.agriculteur.Agriculteur.parcelles
11:23:03,458 DEBUG Cascades:831 - done processing cascade ACTION_SAVE_UPDATE for: demo.business.agriculteur.Agriculteur
11:23:15,659 DEBUG AbstractFlushingEventListener:52 - flushing session
11:23:15,659 DEBUG AbstractFlushingEventListener:102 - processing flush-time cascades
11:23:15,675 DEBUG Cascades:806 - processing cascade ACTION_SAVE_UPDATE for: demo.business.agriculteur.Agriculteur
11:23:15,675 DEBUG Cascades:855 - cascade ACTION_SAVE_UPDATE for collection: demo.business.agriculteur.Agriculteur.visites
11:23:15,675 DEBUG Cascades:873 - done cascade ACTION_SAVE_UPDATE for collection: demo.business.agriculteur.Agriculteur.visites
11:23:15,675 DEBUG Cascades:855 - cascade ACTION_SAVE_UPDATE for collection: demo.business.agriculteur.Agriculteur.parcelles
11:23:15,691 DEBUG Cascades:873 - done cascade ACTION_SAVE_UPDATE for collection: demo.business.agriculteur.Agriculteur.parcelles
11:23:15,691 DEBUG Cascades:831 - done processing cascade ACTION_SAVE_UPDATE for: demo.business.agriculteur.Agriculteur
11:23:15,691 DEBUG AbstractFlushingEventListener:150 - dirty checking collections
11:23:15,691 DEBUG AbstractFlushingEventListener:167 - Flushing entities and processing referenced collections
11:23:15,691 DEBUG DefaultFlushEntityEventListener:121 - Updating entity: [demo.business.agriculteur.Agriculteur#15]
11:23:15,706 DEBUG Collections:108 - Collection found: [demo.business.agriculteur.Agriculteur.visites#15], was: [demo.business.agriculteur.Agriculteur.visites#15] (uninitialized)
11:23:15,706 DEBUG Collections:108 - Collection found: [demo.business.agriculteur.Agriculteur.parcelles#15], was: [demo.business.agriculteur.Agriculteur.parcelles#15] (uninitialized)
11:23:15,722 DEBUG AbstractFlushingEventListener:203 - Processing unreferenced collections
11:23:15,722 DEBUG AbstractFlushingEventListener:217 - Scheduling collection removes/(re)creates/updates
11:23:15,722 DEBUG AbstractFlushingEventListener:79 - Flushed: 0 insertions, 1 updates, 0 deletions to 1 objects
11:23:15,722 DEBUG AbstractFlushingEventListener:85 - Flushed: 0 (re)creations, 0 updates, 0 removals to 2 collections
11:23:15,737 DEBUG Printer:83 - listing entities:
11:23:15,737 DEBUG Printer:90 - demo.business.agriculteur.Agriculteur{visites=<uninitialized>, codePostal=JUNIT, etatAgriculteur=demo.business.agriculteur.EtatAgriculteur#1, adresse2=JUNIT, commune=JUNIT, prenom=JUNIT, id=15, nom=TEST UNIT, natureJuridique=demo.business.agriculteur.NatureJuridique#1, actif=0, parcelles=<uninitialized>, typeAgriculteur=demo.business.agriculteur.TypeAgriculteur#1, adresse1=JUNIT, agriculteur=null}
11:23:15,737 DEBUG AbstractFlushingEventListener:267 - executing flush
11:23:15,753 DEBUG DefaultPersistenceListener:25 - preUpdate :15,TEST UNIT
11:23:15,753 DEBUG DefaultPersistenceListener:25 - preValidate :TEST UNIT
11:23:15,753 DEBUG DefaultInitializeCollectionEventListener:42 - initializing collection [demo.business.agriculteur.Agriculteur.parcelles#15]
11:23:15,769 DEBUG DefaultInitializeCollectionEventListener:47 - checking second-level cache
11:23:15,769 DEBUG DefaultInitializeCollectionEventListener:59 - collection not cached
11:23:15,769 DEBUG Loader:1336 - batch loading collection: [demo.business.agriculteur.Agriculteur.parcelles#15]
11:23:15,784 DEBUG AbstractBatcher:258 - about to open PreparedStatement (open PreparedStatements: 0, globally: 0)
11:23:15,800 DEBUG SQL:292 - select parcelles0_.AGR_CDN as AGR5___, parcelles0_.PAR_CDN as PAR1___, parcelles0_.PAR_CDN as PAR1_0_, parcelles0_.PAR_LIB_LB as PAR2_1_0_, parcelles0_.PAR_SURFACE_INT as PAR3_1_0_, parcelles0_.PAR_CADAST_LB as PAR4_1_0_, parcelles0_.AGR_CDN as AGR5_1_0_ from T_PARCELLE parcelles0_ where parcelles0_.AGR_CDN=?
Hibernate: select parcelles0_.AGR_CDN as AGR5___, parcelles0_.PAR_CDN as PAR1___, parcelles0_.PAR_CDN as PAR1_0_, parcelles0_.PAR_LIB_LB as PAR2_1_0_, parcelles0_.PAR_SURFACE_INT as PAR3_1_0_, parcelles0_.PAR_CADAST_LB as PAR4_1_0_, parcelles0_.AGR_CDN as AGR5_1_0_ from T_PARCELLE parcelles0_ where parcelles0_.AGR_CDN=?
11:23:15,800 DEBUG AbstractBatcher:343 - preparing statement
11:23:15,800 DEBUG IntegerType:59 - binding '15' to parameter: 1
11:23:15,816 DEBUG AbstractBatcher:274 - about to open ResultSet (open ResultSets: 0, globally: 0)
11:23:15,816 DEBUG Loader:610 - result set contains (possibly empty) collection: [demo.business.agriculteur.Agriculteur.parcelles#15]
11:23:15,831 DEBUG CollectionLoadContext:78 - uninitialized collection: initializing
11:23:15,831 DEBUG Loader:377 - processing result set
11:23:15,831 DEBUG Loader:382 - result set row: 0
11:23:15,847 DEBUG IntegerType:86 - returning '28' as column: PAR1_0_
11:23:15,847 DEBUG Loader:719 - result row: EntityKey[demo.business.agriculteur.Parcelle#28]
11:23:15,862 DEBUG Loader:864 - Initializing object from ResultSet: [demo.business.agriculteur.Parcelle#28]
11:23:15,862 DEBUG BasicEntityPersister:1625 - Hydrating entity: [demo.business.agriculteur.Parcelle#28]
11:23:15,862 DEBUG StringType:86 - returning 'libelle 0' as column: PAR2_1_0_
11:23:15,878 DEBUG IntegerType:86 - returning '50' as column: PAR3_1_0_
11:23:15,878 DEBUG StringType:86 - returning 'libelle cadastre' as column: PAR4_1_0_
11:23:15,894 DEBUG IntegerType:86 - returning '15' as column: AGR5_1_0_
11:23:15,894 DEBUG IntegerType:86 - returning '15' as column: AGR5___
11:23:15,909 DEBUG Loader:551 - found row of collection: [demo.business.agriculteur.Agriculteur.parcelles#15]
11:23:15,909 DEBUG CollectionLoadContext:105 - reading row
11:23:15,925 DEBUG IntegerType:86 - returning '28' as column: PAR1___
11:23:15,925 DEBUG DefaultLoadEventListener:193 - loading entity: [demo.business.agriculteur.Parcelle#28]
11:23:15,925 DEBUG DefaultLoadEventListener:209 - entity found in session cache
11:23:15,941 DEBUG DefaultLoadEventListener:326 - attempting to resolve: [demo.business.agriculteur.Parcelle#28]
11:23:15,941 DEBUG DefaultLoadEventListener:335 - resolved object in session cache: [demo.business.agriculteur.Parcelle#28]
11:23:15,956 DEBUG Loader:399 - done processing result set (1 rows)
11:23:15,956 DEBUG AbstractBatcher:281 - about to close ResultSet (open ResultSets: 1, globally: 1)
11:23:15,956 DEBUG AbstractBatcher:266 - about to close PreparedStatement (open PreparedStatements: 1, globally: 1)
11:23:15,972 DEBUG AbstractBatcher:363 - closing statement
11:23:15,972 DEBUG Loader:450 - total objects hydrated: 1
11:23:15,972 DEBUG TwoPhaseLoad:96 - resolving associations for [demo.business.agriculteur.Parcelle#28]
11:23:15,987 DEBUG DefaultLoadEventListener:193 - loading entity: [demo.business.agriculteur.Agriculteur#15]
11:23:15,987 DEBUG DefaultLoadEventListener:326 - attempting to resolve: [demo.business.agriculteur.Agriculteur#15]
11:23:15,987 DEBUG DefaultLoadEventListener:335 - resolved object in session cache: [demo.business.agriculteur.Agriculteur#15]
11:23:16,003 DEBUG CollectionLoadContext:134 - creating collection wrapper:[demo.business.agriculteur.Parcelle.productions#28]
11:23:16,019 DEBUG TwoPhaseLoad:167 - done materializing entity [demo.business.agriculteur.Parcelle#28]
11:23:16,019 DEBUG CollectionLoadContext:239 - 1 collections were found in result set
11:23:16,019 DEBUG CollectionLoadContext:193 - collection fully initialized: [demo.business.agriculteur.Agriculteur.parcelles#15]
11:23:16,034 DEBUG CollectionLoadContext:247 - 1 collections initialized
11:23:16,034 DEBUG PersistenceContext:738 - initializing non-lazy collections
11:23:16,034 DEBUG Loader:1360 - done loading collection
11:23:16,050 DEBUG DefaultInitializeCollectionEventListener:61 - collection initialized
11:23:16,050 DEBUG BasicEntityPersister:1910 - Updating entity: [demo.business.agriculteur.Agriculteur#15]
11:23:16,050 DEBUG AbstractBatcher:258 - about to open PreparedStatement (open PreparedStatements: 0, globally: 0)
11:23:16,050 DEBUG SQL:292 - update T_AGRICULTEUR set AGR_NOM_LB=?, AGR_PRENOM_LB=?, AGR_COM_LB=?, AGR_ADR1_LB=?, AGR_ADR2_LB=?, AGR_ACTIF_ON=?, AGR_CODPOS_LB=?, AGR_PERE_CDN=?, ETAT_CDN=?, TYPE_CDN=?, JUR_CDN=? where AGR_CDN=?
Hibernate: update T_AGRICULTEUR set AGR_NOM_LB=?, AGR_PRENOM_LB=?, AGR_COM_LB=?, AGR_ADR1_LB=?, AGR_ADR2_LB=?, AGR_ACTIF_ON=?, AGR_CODPOS_LB=?, AGR_PERE_CDN=?, ETAT_CDN=?, TYPE_CDN=?, JUR_CDN=? where AGR_CDN=?
11:23:16,066 DEBUG AbstractBatcher:343 - preparing statement
11:23:16,066 DEBUG BasicEntityPersister:1587 - Dehydrating entity: [demo.business.agriculteur.Agriculteur#15]
11:23:16,066 DEBUG StringType:59 - binding 'TEST UNIT' to parameter: 1
11:23:16,081 DEBUG StringType:59 - binding 'JUNIT' to parameter: 2
11:23:16,081 DEBUG StringType:59 - binding 'JUNIT' to parameter: 3
11:23:16,081 DEBUG StringType:59 - binding 'JUNIT' to parameter: 4
11:23:16,097 DEBUG StringType:59 - binding 'JUNIT' to parameter: 5
11:23:16,097 DEBUG IntegerType:59 - binding '0' to parameter: 6
11:23:16,097 DEBUG StringType:59 - binding 'JUNIT' to parameter: 7
11:23:16,097 DEBUG IntegerType:52 - binding null to parameter: 8
11:23:16,112 DEBUG Cascades:525 - id unsaved-value: null
11:23:16,112 DEBUG IntegerType:59 - binding '1' to parameter: 9
11:23:16,128 DEBUG Cascades:525 - id unsaved-value: null
11:23:16,128 DEBUG IntegerType:59 - binding '1' to parameter: 10
11:23:16,128 DEBUG Cascades:525 - id unsaved-value: null
11:23:16,128 DEBUG IntegerType:59 - binding '1' to parameter: 11
11:23:16,144 DEBUG IntegerType:59 - binding '15' to parameter: 12
11:23:16,144 DEBUG AbstractBatcher:266 - about to close PreparedStatement (open PreparedStatements: 1, globally: 1)
11:23:16,144 DEBUG AbstractBatcher:363 - closing statement
11:23:16,159 DEBUG DefaultPersistenceListener:25 - postUpdate :15,TEST UNIT
11:23:16,159 DEBUG AbstractFlushingEventListener:294 - post flush
11:23:16,175 ERROR AssertionFailure:22 - an assertion failure occured (this may indicate a bug in Hibernate, but is more likely due to unsafe use of the session)
org.hibernate.AssertionFailure: collection was not processed by flush()
at org.hibernate.engine.CollectionEntry.postFlush(CollectionEntry.java:144)
at org.hibernate.event.def.AbstractFlushingEventListener.postFlush(AbstractFlushingEventListener.java:305)
at org.hibernate.event.def.DefaultFlushEventListener.onFlush(DefaultFlushEventListener.java:28)
at org.hibernate.impl.SessionImpl.flush(SessionImpl.java:669)
at demo.test.business.AgriculteurTest.testCutPaste(AgriculteurTest.java:97)
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 junit.framework.TestCase.runTest(TestCase.java:154)
at junit.framework.TestCase.runBare(TestCase.java:127)
at junit.framework.TestResult$1.protect(TestResult.java:106)
at junit.framework.TestResult.runProtected(TestResult.java:124)
at junit.framework.TestResult.run(TestResult.java:109)
at junit.framework.TestCase.run(TestCase.java:118)
at junit.framework.TestSuite.runTest(TestSuite.java:208)
at junit.framework.TestSuite.run(TestSuite.java:203)
at org.eclipse.jdt.internal.junit.runner.RemoteTestRunner.runTests(RemoteTestRunner.java:474)
at org.eclipse.jdt.internal.junit.runner.RemoteTestRunner.run(RemoteTestRunner.java:342)
at org.eclipse.jdt.internal.junit.runner.RemoteTestRunner.main(RemoteTestRunner.java:194)

It seems that the Production bag of Parcelle object is not correctly initialized.

I can't figure out why.

Any clue ?

Hi Schmitt31,

I've actually a similar problem. I have an entity, which has a set of history entries. In my PreUpdateListener, I'm check all changed values, and for each changed value a new instance of my HistoryEntry is added to the Set.

But these entries are never saved. I've tried also adding EntityUpdateAction's and so on but it doesn't work.

How did you solved your problem, if you have it?

Regards
Steffen....

Hi,

i find a new way to handle session.
In fact, i don't close the session between two HTTP Request.
The session is opened until the current view is closed.
Sometimes, the view is a form with tabs, the user can make many HTTP
request to see all the tabs.
When he saves the business object it triggers events to the listeners.
But the session is still opened.
When i find that the next view is not the same as the current, i close the session.

I've no problem with this pattern.