3 Replies Latest reply on May 18, 2006 2:11 PM by Emmanuel Bernard

    exception when loading dependent objects

    Marco Novice

      hi all,
      i have written an app which contains 3 entity EJBs
      - Expense
      - Product
      - Item

      Expense has a 1ToMany CMR with Item, here's the code

      package com.myapp.econtrol.entities;
      
      
      import java.io.Serializable;
      import java.sql.Date;
      import java.util.ArrayList;
      import java.util.Collection;
      
      import javax.persistence.*;
      
      import org.jboss.seam.annotations.Name;
      import org.jboss.seam.annotations.Scope;
      
      
      
      @Entity
      // @Name("expense")
      @Table(name = "expense")
      
      @NamedQueries({
      @NamedQuery (
       name="findExpenseByDate",
       query="SELECT e FROM Expense e where e.date < :expenseDate"
       ),
      @NamedQuery (
       name="findAllExpenses",
       query="FROM Expense e"
       ),
      @NamedQuery (
       name="findExpenseBySite",
       query="SELECT e FROM Expense e where e.site = :site"
       )
      
      })
      
      
      
      public class Expense implements Serializable {
       private int id;
       private String site;
       private Date date;
       private Collection<Item> items = new ArrayList<Item>();
      
       public Expense () { }
      
       public Expense (String site, Date date, Collection items) {
       this.site = site;
       this.date = date;
       this.items = items;
       }
      
       @Id
       @GeneratedValue
       public int getId () {
       return id;
       }
      
       public void setId (int id) {
       this.id = id;
       }
      
       public String getSite () {
       return site;
       }
      
       public void setSite (String site) {
       this.site = site;
       }
      
       public Date getDate() {
       return date;
       }
      
       public void setDate (Date date) {
       this.date = date;
       }
      
       @OneToMany(cascade=(CascadeType.ALL))
       public Collection<Item> getItems() {
       return items;
       }
      
       public void setItems(Collection<Item> items) {
       this.items = items;
       }
      


      I have a JUnit tests which contains following code:

      Collection expenses = sessionFacade.getExpenseBySite("Sainsbury");
      
       assertEquals("We should have 1 expense here..", 1, expenses.size());
       Expense exp = (Expense)(expenses.iterator().next());
      
       Collection _items = exp.getItems();
       assertEquals("We should have 2 items in the expense", 2, _items.size());
      



      When i run my junit tests i get the following exception:

      2006-05-18 14:12:44,078 ERROR org.hibernate.LazyInitializationException [main] - failed to lazily initialize a collection of role: com.myapp.econtrol.entities.Expense.items, no session or session was closed
      org.hibernate.LazyInitializationException: failed to lazily initialize a collection of role: com.myapp.econtrol.entities.Expense.items, no session or session was closed
       at org.hibernate.collection.AbstractPersistentCollection.throwLazyInitializationException(AbstractPersistentCollection.java:358)
       at org.hibernate.collection.AbstractPersistentCollection.throwLazyInitializationExceptionIfNotConnected(AbstractPersistentCollection.java:350)
       at org.hibernate.collection.AbstractPersistentCollection.readSize(AbstractPersistentCollection.java:97)
       at org.hibernate.collection.PersistentBag.size(PersistentBag.java:222)
       at example1.TestExpense.testFindExpenseBySite(TestExpense.java:113)
       at sun.reflect.NativeMethodAccessorImpl.invoke0(Native Method)
       at sun.reflect.NativeMethodAccessorImpl.invoke(Unknown Source)
       at sun.reflect.DelegatingMethodAccessorImpl.invoke(Unknown Source)
       at java.lang.reflect.Method.invoke(Unknown Source)
       at org.testng.internal.MethodHelper.invokeMethod(MethodHelper.java:552)
       at org.testng.internal.Invoker.invokeMethod(Invoker.java:407)
       at org.testng.internal.Invoker.invokeTestMethods(Invoker.java:778)
       at org.testng.internal.TestMethodWorker.run(TestMethodWorker.java:105)
       at org.testng.TestRunner.privateRun(TestRunner.java:682)
       at org.testng.TestRunner.run(TestRunner.java:566)
       at org.testng.SuiteRunner.privateRun(SuiteRunner.java:220)
       at org.testng.SuiteRunner.run(SuiteRunner.java:146)
       at org.testng.TestNG.createAndRunSuiteRunners(TestNG.java:713)
       at org.testng.TestNG.runSuitesLocally(TestNG.java:676)
       at org.apache.maven.surefire.testng.TestNGExecutor.executeTestNG(TestNGExecutor.java:64)
       at org.apache.maven.surefire.testng.TestNGXmlTestSuite.execute(TestNGXmlTestSuite.java:75)
       at org.apache.maven.surefire.Surefire.run(Surefire.java:129)
       at sun.reflect.NativeMethodAccessorImpl.invoke0(Native Method)
       at sun.reflect.NativeMethodAccessorImpl.invoke(Unknown Source)
       at sun.reflect.DelegatingMethodAccessorImpl.invoke(Unknown Source)
       at java.lang.reflect.Method.invoke(Unknown Source)
       at org.apache.maven.surefire.booter.SurefireBooter.runSuitesInProcess(SurefireBooter.java:220)
       at org.apache.maven.surefire.booter.SurefireBooter.main(SurefireBooter.java:733)
      



      can anyone tell me wha'ts the problem? did i forgot to specify additional attributes in hte CMR annotation?

      i m currently running tests using jboss-embeddable-alpha5...

      here's an excerpt of jboss logs

      Persisting expense
      2006-05-18 14:12:43,953 DEBUG org.hibernate.jdbc.JDBCContext [main] - successfully registered Synchronization
      2006-05-18 14:12:43,953 DEBUG org.hibernate.impl.SessionImpl [main] - opened session at timestamp: 4702035820220416
      2006-05-18 14:12:43,953 DEBUG org.hibernate.engine.IdentifierValue [main] - id unsaved-value: 0
      2006-05-18 14:12:43,953 DEBUG org.hibernate.event.def.AbstractSaveEventListener [main] - transient instance of: com.myapp.econtrol.entities.Expense
      2006-05-18 14:12:43,953 DEBUG org.hibernate.event.def.DefaultPersistEventListener [main] - saving transient instance
      2006-05-18 14:12:43,968 DEBUG org.hibernate.event.def.AbstractSaveEventListener [main] - saving [com.myapp.econtrol.entities.Expense#<null>]
      2006-05-18 14:12:43,968 DEBUG org.hibernate.event.def.AbstractSaveEventListener [main] - executing insertions
      2006-05-18 14:12:43,968 DEBUG org.hibernate.engine.Cascade [main] - processing cascade ACTION_PERSIST for: com.myapp.econtrol.entities.Expense
      2006-05-18 14:12:43,968 DEBUG org.hibernate.engine.Cascade [main] - done processing cascade ACTION_PERSIST for: com.myapp.econtrol.entities.Expense
      2006-05-18 14:12:43,968 DEBUG org.hibernate.event.def.WrapVisitor [main] - Wrapped collection in role: com.myapp.econtrol.entities.Expense.items
      2006-05-18 14:12:43,984 DEBUG org.hibernate.persister.entity.AbstractEntityPersister [main] - Inserting entity: com.myapp.econtrol.entities.Expense (native id)
      2006-05-18 14:12:43,984 DEBUG org.hibernate.jdbc.AbstractBatcher [main] - about to open PreparedStatement (open PreparedStatements: 0, globally: 0)
      2006-05-18 14:12:43,984 DEBUG org.hibernate.jdbc.ConnectionManager [main] - opening JDBC connection
      2006-05-18 14:12:43,984 DEBUG org.hibernate.SQL [main] - insert into expense (site, date, id) values (?, ?, null)
      2006-05-18 14:12:43,984 DEBUG org.hibernate.jdbc.AbstractBatcher [main] - preparing statement
      2006-05-18 14:12:43,984 DEBUG org.hibernate.persister.entity.AbstractEntityPersister [main] - Dehydrating entity: [com.myapp.econtrol.entities.Expense#<null>]
      2006-05-18 14:12:43,984 DEBUG org.hibernate.type.StringType [main] - binding 'Sainsbury' to parameter: 1
      2006-05-18 14:12:43,984 DEBUG org.hibernate.type.DateType [main] - binding '18 May 2006' to parameter: 2
      2006-05-18 14:12:44,015 DEBUG org.hibernate.jdbc.AbstractBatcher [main] - about to close PreparedStatement (open PreparedStatements: 1, globally: 1)
      2006-05-18 14:12:44,015 DEBUG org.hibernate.jdbc.AbstractBatcher [main] - closing statement
      2006-05-18 14:12:44,015 DEBUG org.hibernate.jdbc.ConnectionManager [main] - aggressively releasing JDBC connection
      2006-05-18 14:12:44,015 DEBUG org.hibernate.jdbc.ConnectionManager [main] - releasing JDBC connection [ (open PreparedStatements: 0, globally: 0) (open ResultSets: 0, globally: 0)]
      2006-05-18 14:12:44,015 DEBUG org.hibernate.jdbc.AbstractBatcher [main] - about to open PreparedStatement (open PreparedStatements: 0, globally: 0)
      2006-05-18 14:12:44,015 DEBUG org.hibernate.jdbc.ConnectionManager [main] - opening JDBC connection
      2006-05-18 14:12:44,015 DEBUG org.hibernate.SQL [main] - call identity()
      2006-05-18 14:12:44,015 DEBUG org.hibernate.jdbc.AbstractBatcher [main] - preparing statement
      2006-05-18 14:12:44,015 DEBUG org.hibernate.id.IdentifierGeneratorFactory [main] - Natively generated identity: 1
      2006-05-18 14:12:44,015 DEBUG org.hibernate.jdbc.AbstractBatcher [main] - about to close PreparedStatement (open PreparedStatements: 1, globally: 1)
      2006-05-18 14:12:44,015 DEBUG org.hibernate.jdbc.AbstractBatcher [main] - closing statement
      2006-05-18 14:12:44,015 DEBUG org.hibernate.jdbc.ConnectionManager [main] - aggressively releasing JDBC connection
      2006-05-18 14:12:44,015 DEBUG org.hibernate.jdbc.ConnectionManager [main] - releasing JDBC connection [ (open PreparedStatements: 0, globally: 0) (open ResultSets: 0, globally: 0)]
      2006-05-18 14:12:44,015 DEBUG org.hibernate.engine.Cascade [main] - processing cascade ACTION_PERSIST for: com.myapp.econtrol.entities.Expense
      2006-05-18 14:12:44,015 DEBUG org.hibernate.engine.Cascade [main] - cascade ACTION_PERSIST for collection: com.myapp.econtrol.entities.Expense.items
      2006-05-18 14:12:44,015 DEBUG org.hibernate.engine.CascadingAction [main] - cascading to persist: com.myapp.econtrol.entities.Item
      2006-05-18 14:12:44,015 DEBUG org.hibernate.engine.IdentifierValue [main] - id unsaved-value: 0
      2006-05-18 14:12:44,015 DEBUG org.hibernate.event.def.AbstractSaveEventListener [main] - transient instance of: com.myapp.econtrol.entities.Item
      2006-05-18 14:12:44,015 DEBUG org.hibernate.event.def.DefaultPersistEventListener [main] - saving transient instance
      2006-05-18 14:12:44,015 DEBUG org.hibernate.event.def.AbstractSaveEventListener [main] - saving [com.myapp.econtrol.entities.Item#<null>]
      2006-05-18 14:12:44,015 DEBUG org.hibernate.event.def.AbstractSaveEventListener [main] - executing insertions
      2006-05-18 14:12:44,015 DEBUG org.hibernate.persister.entity.AbstractEntityPersister [main] - Inserting entity: com.myapp.econtrol.entities.Item (native id)
      2006-05-18 14:12:44,015 DEBUG org.hibernate.jdbc.AbstractBatcher [main] - about to open PreparedStatement (open PreparedStatements: 0, globally: 0)
      2006-05-18 14:12:44,015 DEBUG org.hibernate.jdbc.ConnectionManager [main] - opening JDBC connection
      2006-05-18 14:12:44,015 DEBUG org.hibernate.SQL [main] - insert into item (price, name, id) values (?, ?, null)
      2006-05-18 14:12:44,015 DEBUG org.hibernate.jdbc.AbstractBatcher [main] - preparing statement
      2006-05-18 14:12:44,015 DEBUG org.hibernate.persister.entity.AbstractEntityPersister [main] - Dehydrating entity: [com.myapp.econtrol.entities.Item#<null>]
      2006-05-18 14:12:44,015 DEBUG org.hibernate.type.DoubleType [main] - binding '1.75' to parameter: 1
      2006-05-18 14:12:44,015 DEBUG org.hibernate.type.StringType [main] - binding 'Banana' to parameter: 2
      2006-05-18 14:12:44,015 DEBUG org.hibernate.jdbc.AbstractBatcher [main] - about to close PreparedStatement (open PreparedStatements: 1, globally: 1)
      2006-05-18 14:12:44,015 DEBUG org.hibernate.jdbc.AbstractBatcher [main] - closing statement
      2006-05-18 14:12:44,015 DEBUG org.hibernate.jdbc.ConnectionManager [main] - aggressively releasing JDBC connection
      2006-05-18 14:12:44,015 DEBUG org.hibernate.jdbc.ConnectionManager [main] - releasing JDBC connection [ (open PreparedStatements: 0, globally: 0) (open ResultSets: 0, globally: 0)]
      2006-05-18 14:12:44,015 DEBUG org.hibernate.jdbc.AbstractBatcher [main] - about to open PreparedStatement (open PreparedStatements: 0, globally: 0)
      2006-05-18 14:12:44,015 DEBUG org.hibernate.jdbc.ConnectionManager [main] - opening JDBC connection
      2006-05-18 14:12:44,015 DEBUG org.hibernate.SQL [main] - call identity()
      2006-05-18 14:12:44,015 DEBUG org.hibernate.jdbc.AbstractBatcher [main] - preparing statement
      2006-05-18 14:12:44,015 DEBUG org.hibernate.id.IdentifierGeneratorFactory [main] - Natively generated identity: 1
      2006-05-18 14:12:44,015 DEBUG org.hibernate.jdbc.AbstractBatcher [main] - about to close PreparedStatement (open PreparedStatements: 1, globally: 1)
      2006-05-18 14:12:44,015 DEBUG org.hibernate.jdbc.AbstractBatcher [main] - closing statement
      2006-05-18 14:12:44,015 DEBUG org.hibernate.jdbc.ConnectionManager [main] - aggressively releasing JDBC connection
      2006-05-18 14:12:44,015 DEBUG org.hibernate.jdbc.ConnectionManager [main] - releasing JDBC connection [ (open PreparedStatements: 0, globally: 0) (open ResultSets: 0, globally: 0)]
      2006-05-18 14:12:44,015 DEBUG org.hibernate.engine.CascadingAction [main] - cascading to persist: com.myapp.econtrol.entities.Item
      2006-05-18 14:12:44,015 DEBUG org.hibernate.engine.IdentifierValue [main] - id unsaved-value: 0
      2006-05-18 14:12:44,015 DEBUG org.hibernate.event.def.AbstractSaveEventListener [main] - transient instance of: com.myapp.econtrol.entities.Item
      2006-05-18 14:12:44,015 DEBUG org.hibernate.event.def.DefaultPersistEventListener [main] - saving transient instance
      2006-05-18 14:12:44,015 DEBUG org.hibernate.event.def.AbstractSaveEventListener [main] - saving [com.myapp.econtrol.entities.Item#<null>]
      2006-05-18 14:12:44,015 DEBUG org.hibernate.event.def.AbstractSaveEventListener [main] - executing insertions
      2006-05-18 14:12:44,015 DEBUG org.hibernate.persister.entity.AbstractEntityPersister [main] - Inserting entity: com.myapp.econtrol.entities.Item (native id)
      2006-05-18 14:12:44,015 DEBUG org.hibernate.jdbc.AbstractBatcher [main] - about to open PreparedStatement (open PreparedStatements: 0, globally: 0)
      2006-05-18 14:12:44,015 DEBUG org.hibernate.jdbc.ConnectionManager [main] - opening JDBC connection
      2006-05-18 14:12:44,015 DEBUG org.hibernate.SQL [main] - insert into item (price, name, id) values (?, ?, null)
      2006-05-18 14:12:44,015 DEBUG org.hibernate.jdbc.AbstractBatcher [main] - preparing statement
      2006-05-18 14:12:44,015 DEBUG org.hibernate.persister.entity.AbstractEntityPersister [main] - Dehydrating entity: [com.myapp.econtrol.entities.Item#<null>]
      2006-05-18 14:12:44,015 DEBUG org.hibernate.type.DoubleType [main] - binding '0.75' to parameter: 1
      2006-05-18 14:12:44,015 DEBUG org.hibernate.type.StringType [main] - binding 'IceCream' to parameter: 2
      2006-05-18 14:12:44,015 DEBUG org.hibernate.jdbc.AbstractBatcher [main] - about to close PreparedStatement (open PreparedStatements: 1, globally: 1)
      2006-05-18 14:12:44,015 DEBUG org.hibernate.jdbc.AbstractBatcher [main] - closing statement
      2006-05-18 14:12:44,015 DEBUG org.hibernate.jdbc.ConnectionManager [main] - aggressively releasing JDBC connection
      2006-05-18 14:12:44,015 DEBUG org.hibernate.jdbc.ConnectionManager [main] - releasing JDBC connection [ (open PreparedStatements: 0, globally: 0) (open ResultSets: 0, globally: 0)]
      2006-05-18 14:12:44,015 DEBUG org.hibernate.jdbc.AbstractBatcher [main] - about to open PreparedStatement (open PreparedStatements: 0, globally: 0)
      2006-05-18 14:12:44,015 DEBUG org.hibernate.jdbc.ConnectionManager [main] - opening JDBC connection
      2006-05-18 14:12:44,015 DEBUG org.hibernate.SQL [main] - call identity()
      2006-05-18 14:12:44,015 DEBUG org.hibernate.jdbc.AbstractBatcher [main] - preparing statement
      2006-05-18 14:12:44,015 DEBUG org.hibernate.id.IdentifierGeneratorFactory [main] - Natively generated identity: 2
      2006-05-18 14:12:44,015 DEBUG org.hibernate.jdbc.AbstractBatcher [main] - about to close PreparedStatement (open PreparedStatements: 1, globally: 1)
      2006-05-18 14:12:44,015 DEBUG org.hibernate.jdbc.AbstractBatcher [main] - closing statement
      2006-05-18 14:12:44,015 DEBUG org.hibernate.jdbc.ConnectionManager [main] - aggressively releasing JDBC connection
      2006-05-18 14:12:44,015 DEBUG org.hibernate.jdbc.ConnectionManager [main] - releasing JDBC connection [ (open PreparedStatements: 0, globally: 0) (open ResultSets: 0, globally: 0)]
      2006-05-18 14:12:44,015 DEBUG org.hibernate.engine.Cascade [main] - done cascade ACTION_PERSIST for collection: com.myapp.econtrol.entities.Expense.items
      2006-05-18 14:12:44,015 DEBUG org.hibernate.engine.Cascade [main] - done processing cascade ACTION_PERSIST for: com.myapp.econtrol.entities.Expense
      Expense persisted..
      2006-05-18 14:12:44,015 DEBUG org.hibernate.transaction.CacheSynchronization [main] - transaction before completion callback
      2006-05-18 14:12:44,015 DEBUG org.hibernate.transaction.CacheSynchronization [main] - automatically flushing session
      2006-05-18 14:12:44,015 DEBUG org.hibernate.impl.SessionImpl [main] - automatically flushing session
      2006-05-18 14:12:44,015 DEBUG org.hibernate.event.def.AbstractFlushingEventListener [main] - flushing session
      2006-05-18 14:12:44,015 DEBUG org.hibernate.event.def.AbstractFlushingEventListener [main] - processing flush-time cascades
      2006-05-18 14:12:44,015 DEBUG org.hibernate.engine.Cascade [main] - processing cascade ACTION_PERSIST_ON_FLUSH for: com.myapp.econtrol.entities.Expense
      2006-05-18 14:12:44,015 DEBUG org.hibernate.engine.Cascade [main] - cascade ACTION_PERSIST_ON_FLUSH for collection: com.myapp.econtrol.entities.Expense.items
      2006-05-18 14:12:44,015 DEBUG org.hibernate.engine.CascadingAction [main] - cascading to persistOnFlush: com.myapp.econtrol.entities.Item
      2006-05-18 14:12:44,015 DEBUG org.hibernate.event.def.AbstractSaveEventListener [main] - persistent instance of: com.myapp.econtrol.entities.Item
      2006-05-18 14:12:44,015 DEBUG org.hibernate.event.def.DefaultPersistEventListener [main] - ignoring persistent instance
      2006-05-18 14:12:44,031 DEBUG org.hibernate.engine.CascadingAction [main] - cascading to persistOnFlush: com.myapp.econtrol.entities.Item
      2006-05-18 14:12:44,031 DEBUG org.hibernate.event.def.AbstractSaveEventListener [main] - persistent instance of: com.myapp.econtrol.entities.Item
      2006-05-18 14:12:44,031 DEBUG org.hibernate.event.def.DefaultPersistEventListener [main] - ignoring persistent instance
      2006-05-18 14:12:44,031 DEBUG org.hibernate.engine.Cascade [main] - done cascade ACTION_PERSIST_ON_FLUSH for collection: com.myapp.econtrol.entities.Expense.items
      2006-05-18 14:12:44,031 DEBUG org.hibernate.engine.Cascade [main] - done processing cascade ACTION_PERSIST_ON_FLUSH for: com.myapp.econtrol.entities.Expense
      2006-05-18 14:12:44,031 DEBUG org.hibernate.event.def.AbstractFlushingEventListener [main] - dirty checking collections
      2006-05-18 14:12:44,031 DEBUG org.hibernate.event.def.AbstractFlushingEventListener [main] - Flushing entities and processing referenced collections
      2006-05-18 14:12:44,031 DEBUG org.hibernate.engine.Collections [main] - Collection found: [com.myapp.econtrol.entities.Expense.items#1], was: [<unreferenced>] (initialized)
      2006-05-18 14:12:44,031 DEBUG org.hibernate.event.def.AbstractFlushingEventListener [main] - Processing unreferenced collections
      2006-05-18 14:12:44,031 DEBUG org.hibernate.event.def.AbstractFlushingEventListener [main] - Scheduling collection removes/(re)creates/updates
      2006-05-18 14:12:44,031 DEBUG org.hibernate.event.def.AbstractFlushingEventListener [main] - Flushed: 0 insertions, 0 updates, 0 deletions to 3 objects
      2006-05-18 14:12:44,031 DEBUG org.hibernate.event.def.AbstractFlushingEventListener [main] - Flushed: 1 (re)creations, 0 updates, 0 removals to 1 collections
      2006-05-18 14:12:44,031 DEBUG org.hibernate.pretty.Printer [main] - listing entities:
      2006-05-18 14:12:44,031 DEBUG org.hibernate.pretty.Printer [main] - com.myapp.econtrol.entities.Expense{site=Sainsbury, items=[com.myapp.econtrol.entities.Item#1, com.myapp.econtrol.entities.Item#2], date=18 May 2006, id=1}
      2006-05-18 14:12:44,031 DEBUG org.hibernate.pretty.Printer [main] - com.myapp.econtrol.entities.Item{price=0.75, name=IceCream, id=2}
      2006-05-18 14:12:44,031 DEBUG org.hibernate.pretty.Printer [main] - com.myapp.econtrol.entities.Item{price=1.75, name=Banana, id=1}
      2006-05-18 14:12:44,031 DEBUG org.hibernate.event.def.AbstractFlushingEventListener [main] - executing flush
      2006-05-18 14:12:44,031 DEBUG org.hibernate.persister.collection.AbstractCollectionPersister [main] - Inserting collection: [com.myapp.econtrol.entities.Expense.items#1]
      2006-05-18 14:12:44,031 DEBUG org.hibernate.jdbc.AbstractBatcher [main] - about to open PreparedStatement (open PreparedStatements: 0, globally: 0)
      2006-05-18 14:12:44,031 DEBUG org.hibernate.jdbc.ConnectionManager [main] - opening JDBC connection
      2006-05-18 14:12:44,031 DEBUG org.hibernate.SQL [main] - insert into expense_item (expense_id, items_id) values (?, ?)
      2006-05-18 14:12:44,031 DEBUG org.hibernate.jdbc.AbstractBatcher [main] - preparing statement
      2006-05-18 14:12:44,031 DEBUG org.hibernate.type.IntegerType [main] - binding '1' to parameter: 1
      2006-05-18 14:12:44,031 DEBUG org.hibernate.type.IntegerType [main] - binding '1' to parameter: 2
      2006-05-18 14:12:44,031 DEBUG org.hibernate.jdbc.AbstractBatcher [main] - Adding to batch
      2006-05-18 14:12:44,031 DEBUG org.hibernate.jdbc.AbstractBatcher [main] - reusing prepared statement
      2006-05-18 14:12:44,031 DEBUG org.hibernate.SQL [main] - insert into expense_item (expense_id, items_id) values (?, ?)
      2006-05-18 14:12:44,031 DEBUG org.hibernate.type.IntegerType [main] - binding '1' to parameter: 1
      2006-05-18 14:12:44,031 DEBUG org.hibernate.type.IntegerType [main] - binding '2' to parameter: 2
      2006-05-18 14:12:44,031 DEBUG org.hibernate.jdbc.AbstractBatcher [main] - Adding to batch
      2006-05-18 14:12:44,031 DEBUG org.hibernate.persister.collection.AbstractCollectionPersister [main] - done inserting collection: 2 rows inserted
      2006-05-18 14:12:44,031 DEBUG org.hibernate.jdbc.AbstractBatcher [main] - Executing batch size: 2
      2006-05-18 14:12:44,031 DEBUG org.hibernate.jdbc.AbstractBatcher [main] - about to close PreparedStatement (open PreparedStatements: 1, globally: 1)
      2006-05-18 14:12:44,031 DEBUG org.hibernate.jdbc.AbstractBatcher [main] - closing statement
      2006-05-18 14:12:44,031 DEBUG org.hibernate.jdbc.ConnectionManager [main] - aggressively releasing JDBC connection
      2006-05-18 14:12:44,031 DEBUG org.hibernate.jdbc.ConnectionManager [main] - releasing JDBC connection [ (open PreparedStatements: 0, globally: 0) (open ResultSets: 0, globally: 0)]
      2006-05-18 14:12:44,031 DEBUG org.hibernate.event.def.AbstractFlushingEventListener [main] - post flush
      2006-05-18 14:12:44,031 DEBUG org.hibernate.jdbc.JDBCContext [main] - before transaction completion
      2006-05-18 14:12:44,031 DEBUG org.hibernate.impl.SessionImpl [main] - before transaction completion
      2006-05-18 14:12:44,031 DEBUG org.jboss.ejb3.entity.ManagedEntityManagerFactory [main] - ************** closing entity managersession **************
      2006-05-18 14:12:44,031 DEBUG org.hibernate.impl.SessionImpl [main] - closing session
      2006-05-18 14:12:44,031 DEBUG org.hibernate.jdbc.ConnectionManager [main] - connection already null in cleanup : no action
      2006-05-18 14:12:44,031 DEBUG org.hibernate.transaction.CacheSynchronization [main] - transaction after completion callback, status: 3
      2006-05-18 14:12:44,031 DEBUG org.hibernate.jdbc.JDBCContext [main] - after transaction completion
      2006-05-18 14:12:44,031 DEBUG org.hibernate.impl.SessionImpl [main] - after transaction completion
      Persisting expense
      2006-05-18 14:12:44,031 DEBUG org.hibernate.jdbc.JDBCContext [main] - successfully registered Synchronization
      2006-05-18 14:12:44,031 DEBUG org.hibernate.impl.SessionImpl [main] - opened session at timestamp: 4702035820670976
      2006-05-18 14:12:44,031 DEBUG org.hibernate.engine.IdentifierValue [main] - id unsaved-value: 0
      2006-05-18 14:12:44,031 DEBUG org.hibernate.event.def.AbstractSaveEventListener [main] - transient instance of: com.myapp.econtrol.entities.Expense
      2006-05-18 14:12:44,031 DEBUG org.hibernate.event.def.DefaultPersistEventListener [main] - saving transient instance
      2006-05-18 14:12:44,031 DEBUG org.hibernate.event.def.AbstractSaveEventListener [main] - saving [com.myapp.econtrol.entities.Expense#<null>]
      2006-05-18 14:12:44,031 DEBUG org.hibernate.event.def.AbstractSaveEventListener [main] - executing insertions
      2006-05-18 14:12:44,031 DEBUG org.hibernate.engine.Cascade [main] - processing cascade ACTION_PERSIST for: com.myapp.econtrol.entities.Expense
      2006-05-18 14:12:44,031 DEBUG org.hibernate.engine.Cascade [main] - done processing cascade ACTION_PERSIST for: com.myapp.econtrol.entities.Expense
      2006-05-18 14:12:44,031 DEBUG org.hibernate.event.def.WrapVisitor [main] - Wrapped collection in role: com.myapp.econtrol.entities.Expense.items
      2006-05-18 14:12:44,031 DEBUG org.hibernate.persister.entity.AbstractEntityPersister [main] - Inserting entity: com.myapp.econtrol.entities.Expense (native id)
      2006-05-18 14:12:44,031 DEBUG org.hibernate.jdbc.AbstractBatcher [main] - about to open PreparedStatement (open PreparedStatements: 0, globally: 0)
      2006-05-18 14:12:44,031 DEBUG org.hibernate.jdbc.ConnectionManager [main] - opening JDBC connection
      2006-05-18 14:12:44,031 DEBUG org.hibernate.SQL [main] - insert into expense (site, date, id) values (?, ?, null)
      2006-05-18 14:12:44,031 DEBUG org.hibernate.jdbc.AbstractBatcher [main] - preparing statement
      2006-05-18 14:12:44,031 DEBUG org.hibernate.persister.entity.AbstractEntityPersister [main] - Dehydrating entity: [com.myapp.econtrol.entities.Expense#<null>]
      2006-05-18 14:12:44,031 DEBUG org.hibernate.type.StringType [main] - binding 'Sains' to parameter: 1
      2006-05-18 14:12:44,031 DEBUG org.hibernate.type.DateType [main] - binding '18 May 2006' to parameter: 2
      2006-05-18 14:12:44,031 DEBUG org.hibernate.jdbc.AbstractBatcher [main] - about to close PreparedStatement (open PreparedStatements: 1, globally: 1)
      2006-05-18 14:12:44,031 DEBUG org.hibernate.jdbc.AbstractBatcher [main] - closing statement
      2006-05-18 14:12:44,031 DEBUG org.hibernate.jdbc.ConnectionManager [main] - aggressively releasing JDBC connection
      2006-05-18 14:12:44,031 DEBUG org.hibernate.jdbc.ConnectionManager [main] - releasing JDBC connection [ (open PreparedStatements: 0, globally: 0) (open ResultSets: 0, globally: 0)]
      2006-05-18 14:12:44,031 DEBUG org.hibernate.jdbc.AbstractBatcher [main] - about to open PreparedStatement (open PreparedStatements: 0, globally: 0)
      2006-05-18 14:12:44,046 DEBUG org.hibernate.jdbc.ConnectionManager [main] - opening JDBC connection
      2006-05-18 14:12:44,046 DEBUG org.hibernate.SQL [main] - call identity()
      2006-05-18 14:12:44,046 DEBUG org.hibernate.jdbc.AbstractBatcher [main] - preparing statement
      2006-05-18 14:12:44,046 DEBUG org.hibernate.id.IdentifierGeneratorFactory [main] - Natively generated identity: 2
      2006-05-18 14:12:44,046 DEBUG org.hibernate.jdbc.AbstractBatcher [main] - about to close PreparedStatement (open PreparedStatements: 1, globally: 1)
      2006-05-18 14:12:44,046 DEBUG org.hibernate.jdbc.AbstractBatcher [main] - closing statement
      2006-05-18 14:12:44,046 DEBUG org.hibernate.jdbc.ConnectionManager [main] - aggressively releasing JDBC connection
      2006-05-18 14:12:44,046 DEBUG org.hibernate.jdbc.ConnectionManager [main] - releasing JDBC connection [ (open PreparedStatements: 0, globally: 0) (open ResultSets: 0, globally: 0)]
      2006-05-18 14:12:44,046 DEBUG org.hibernate.engine.Cascade [main] - processing cascade ACTION_PERSIST for: com.myapp.econtrol.entities.Expense
      2006-05-18 14:12:44,046 DEBUG org.hibernate.engine.Cascade [main] - cascade ACTION_PERSIST for collection: com.myapp.econtrol.entities.Expense.items
      2006-05-18 14:12:44,046 DEBUG org.hibernate.engine.Cascade [main] - done cascade ACTION_PERSIST for collection: com.myapp.econtrol.entities.Expense.items
      2006-05-18 14:12:44,046 DEBUG org.hibernate.engine.Cascade [main] - done processing cascade ACTION_PERSIST for: com.myapp.econtrol.entities.Expense
      Expense persisted..
      2006-05-18 14:12:44,046 DEBUG org.hibernate.transaction.CacheSynchronization [main] - transaction before completion callback
      2006-05-18 14:12:44,046 DEBUG org.hibernate.transaction.CacheSynchronization [main] - automatically flushing session
      2006-05-18 14:12:44,046 DEBUG org.hibernate.impl.SessionImpl [main] - automatically flushing session
      2006-05-18 14:12:44,046 DEBUG org.hibernate.event.def.AbstractFlushingEventListener [main] - flushing session
      2006-05-18 14:12:44,046 DEBUG org.hibernate.event.def.AbstractFlushingEventListener [main] - processing flush-time cascades
      2006-05-18 14:12:44,046 DEBUG org.hibernate.engine.Cascade [main] - processing cascade ACTION_PERSIST_ON_FLUSH for: com.myapp.econtrol.entities.Expense
      2006-05-18 14:12:44,046 DEBUG org.hibernate.engine.Cascade [main] - cascade ACTION_PERSIST_ON_FLUSH for collection: com.myapp.econtrol.entities.Expense.items
      2006-05-18 14:12:44,046 DEBUG org.hibernate.engine.Cascade [main] - done cascade ACTION_PERSIST_ON_FLUSH for collection: com.myapp.econtrol.entities.Expense.items
      2006-05-18 14:12:44,046 DEBUG org.hibernate.engine.Cascade [main] - done processing cascade ACTION_PERSIST_ON_FLUSH for: com.myapp.econtrol.entities.Expense
      2006-05-18 14:12:44,046 DEBUG org.hibernate.event.def.AbstractFlushingEventListener [main] - dirty checking collections
      2006-05-18 14:12:44,046 DEBUG org.hibernate.event.def.AbstractFlushingEventListener [main] - Flushing entities and processing referenced collections
      2006-05-18 14:12:44,046 DEBUG org.hibernate.engine.Collections [main] - Collection found: [com.myapp.econtrol.entities.Expense.items#2], was: [<unreferenced>] (initialized)
      2006-05-18 14:12:44,046 DEBUG org.hibernate.event.def.AbstractFlushingEventListener [main] - Processing unreferenced collections
      2006-05-18 14:12:44,046 DEBUG org.hibernate.event.def.AbstractFlushingEventListener [main] - Scheduling collection removes/(re)creates/updates
      2006-05-18 14:12:44,046 DEBUG org.hibernate.event.def.AbstractFlushingEventListener [main] - Flushed: 0 insertions, 0 updates, 0 deletions to 1 objects
      2006-05-18 14:12:44,046 DEBUG org.hibernate.event.def.AbstractFlushingEventListener [main] - Flushed: 1 (re)creations, 0 updates, 0 removals to 1 collections
      2006-05-18 14:12:44,046 DEBUG org.hibernate.pretty.Printer [main] - listing entities:
      2006-05-18 14:12:44,046 DEBUG org.hibernate.pretty.Printer [main] - com.myapp.econtrol.entities.Expense{site=Sains, items=[], date=18 May 2006, id=2}
      2006-05-18 14:12:44,046 DEBUG org.hibernate.event.def.AbstractFlushingEventListener [main] - executing flush
      2006-05-18 14:12:44,046 DEBUG org.hibernate.persister.collection.AbstractCollectionPersister [main] - Inserting collection: [com.myapp.econtrol.entities.Expense.items#2]
      2006-05-18 14:12:44,046 DEBUG org.hibernate.persister.collection.AbstractCollectionPersister [main] - collection was empty
      2006-05-18 14:12:44,046 DEBUG org.hibernate.event.def.AbstractFlushingEventListener [main] - post flush
      2006-05-18 14:12:44,046 DEBUG org.hibernate.jdbc.JDBCContext [main] - before transaction completion
      2006-05-18 14:12:44,046 DEBUG org.hibernate.impl.SessionImpl [main] - before transaction completion
      2006-05-18 14:12:44,046 DEBUG org.jboss.ejb3.entity.ManagedEntityManagerFactory [main] - ************** closing entity managersession **************
      2006-05-18 14:12:44,046 DEBUG org.hibernate.impl.SessionImpl [main] - closing session
      2006-05-18 14:12:44,046 DEBUG org.hibernate.jdbc.ConnectionManager [main] - connection already null in cleanup : no action
      2006-05-18 14:12:44,046 DEBUG org.hibernate.transaction.CacheSynchronization [main] - transaction after completion callback, status: 3
      2006-05-18 14:12:44,046 DEBUG org.hibernate.jdbc.JDBCContext [main] - after transaction completion
      2006-05-18 14:12:44,046 DEBUG org.hibernate.impl.SessionImpl [main] - after transaction completion
      ...gettign epxense by tyhpe..
      2006-05-18 14:12:44,046 DEBUG org.hibernate.jdbc.JDBCContext [main] - successfully registered Synchronization
      2006-05-18 14:12:44,046 DEBUG org.hibernate.impl.SessionImpl [main] - opened session at timestamp: 4702035820732416
      2006-05-18 14:12:44,046 DEBUG org.hibernate.engine.query.QueryPlanCache [main] - located HQL query plan in cache (SELECT e FROM Expense e where e.site = :site)
      2006-05-18 14:12:44,046 DEBUG org.hibernate.engine.query.QueryPlanCache [main] - located HQL query plan in cache (SELECT e FROM Expense e where e.site = :site)
      2006-05-18 14:12:44,046 DEBUG org.hibernate.engine.query.HQLQueryPlan [main] - find: SELECT e FROM Expense e where e.site = :site
      2006-05-18 14:12:44,046 DEBUG org.hibernate.engine.QueryParameters [main] - named parameters: {site=Sainsbury}
      2006-05-18 14:12:44,046 DEBUG org.hibernate.jdbc.AbstractBatcher [main] - about to open PreparedStatement (open PreparedStatements: 0, globally: 0)
      2006-05-18 14:12:44,046 DEBUG org.hibernate.jdbc.ConnectionManager [main] - opening JDBC connection
      2006-05-18 14:12:44,062 DEBUG org.hibernate.SQL [main] - select expense0_.id as id0_, expense0_.site as site0_, expense0_.date as date0_ from expense expense0_ where expense0_.site=?
      2006-05-18 14:12:44,062 DEBUG org.hibernate.jdbc.AbstractBatcher [main] - preparing statement
      2006-05-18 14:12:44,062 DEBUG org.hibernate.loader.hql.QueryLoader [main] - bindNamedParameters() Sainsbury -> site [1]
      2006-05-18 14:12:44,062 DEBUG org.hibernate.type.StringType [main] - binding 'Sainsbury' to parameter: 1
      2006-05-18 14:12:44,062 DEBUG org.hibernate.jdbc.AbstractBatcher [main] - about to open ResultSet (open ResultSets: 0, globally: 0)
      2006-05-18 14:12:44,062 DEBUG org.hibernate.loader.Loader [main] - processing result set
      2006-05-18 14:12:44,062 DEBUG org.hibernate.loader.Loader [main] - result set row: 0
      2006-05-18 14:12:44,062 DEBUG org.hibernate.type.IntegerType [main] - returning '1' as column: id0_
      2006-05-18 14:12:44,062 DEBUG org.hibernate.loader.Loader [main] - result row: EntityKey[com.myapp.econtrol.entities.Expense#1]
      2006-05-18 14:12:44,062 DEBUG org.hibernate.loader.Loader [main] - Initializing object from ResultSet: [com.myapp.econtrol.entities.Expense#1]
      2006-05-18 14:12:44,062 DEBUG org.hibernate.persister.entity.AbstractEntityPersister [main] - Hydrating entity: [com.myapp.econtrol.entities.Expense#1]
      2006-05-18 14:12:44,062 DEBUG org.hibernate.type.StringType [main] - returning 'Sainsbury' as column: site0_
      2006-05-18 14:12:44,062 DEBUG org.hibernate.type.DateType [main] - returning '18 May 2006' as column: date0_
      2006-05-18 14:12:44,062 DEBUG org.hibernate.loader.Loader [main] - done processing result set (1 rows)
      2006-05-18 14:12:44,062 DEBUG org.hibernate.jdbc.AbstractBatcher [main] - about to close ResultSet (open ResultSets: 1, globally: 1)
      2006-05-18 14:12:44,062 DEBUG org.hibernate.jdbc.AbstractBatcher [main] - about to close PreparedStatement (open PreparedStatements: 1, globally: 1)
      2006-05-18 14:12:44,062 DEBUG org.hibernate.jdbc.AbstractBatcher [main] - closing statement
      2006-05-18 14:12:44,062 DEBUG org.hibernate.jdbc.ConnectionManager [main] - aggressively releasing JDBC connection
      2006-05-18 14:12:44,062 DEBUG org.hibernate.jdbc.ConnectionManager [main] - releasing JDBC connection [ (open PreparedStatements: 0, globally: 0) (open ResultSets: 0, globally: 0)]
      2006-05-18 14:12:44,062 DEBUG org.hibernate.loader.Loader [main] - total objects hydrated: 1
      2006-05-18 14:12:44,062 DEBUG org.hibernate.engine.TwoPhaseLoad [main] - resolving associations for [com.myapp.econtrol.entities.Expense#1]
      2006-05-18 14:12:44,062 DEBUG org.hibernate.engine.CollectionLoadContext [main] - creating collection wrapper:[com.myapp.econtrol.entities.Expense.items#1]
      2006-05-18 14:12:44,062 DEBUG org.hibernate.engine.TwoPhaseLoad [main] - done materializing entity [com.myapp.econtrol.entities.Expense#1]
      2006-05-18 14:12:44,062 DEBUG org.hibernate.engine.StatefulPersistenceContext [main] - initializing non-lazy collections
      2006-05-18 14:12:44,062 DEBUG org.hibernate.transaction.CacheSynchronization [main] - transaction before completion callback
      2006-05-18 14:12:44,062 DEBUG org.hibernate.transaction.CacheSynchronization [main] - automatically flushing session
      2006-05-18 14:12:44,062 DEBUG org.hibernate.impl.SessionImpl [main] - automatically flushing session
      2006-05-18 14:12:44,062 DEBUG org.hibernate.event.def.AbstractFlushingEventListener [main] - flushing session
      2006-05-18 14:12:44,062 DEBUG org.hibernate.event.def.AbstractFlushingEventListener [main] - processing flush-time cascades
      2006-05-18 14:12:44,062 DEBUG org.hibernate.engine.Cascade [main] - processing cascade ACTION_PERSIST_ON_FLUSH for: com.myapp.econtrol.entities.Expense
      2006-05-18 14:12:44,062 DEBUG org.hibernate.engine.Cascade [main] - cascade ACTION_PERSIST_ON_FLUSH for collection: com.myapp.econtrol.entities.Expense.items
      2006-05-18 14:12:44,062 DEBUG org.hibernate.engine.Cascade [main] - done cascade ACTION_PERSIST_ON_FLUSH for collection: com.myapp.econtrol.entities.Expense.items
      2006-05-18 14:12:44,062 DEBUG org.hibernate.engine.Cascade [main] - done processing cascade ACTION_PERSIST_ON_FLUSH for: com.myapp.econtrol.entities.Expense
      2006-05-18 14:12:44,062 DEBUG org.hibernate.event.def.AbstractFlushingEventListener [main] - dirty checking collections
      2006-05-18 14:12:44,062 DEBUG org.hibernate.event.def.AbstractFlushingEventListener [main] - Flushing entities and processing referenced collections
      2006-05-18 14:12:44,062 DEBUG org.hibernate.engine.Collections [main] - Collection found: [com.myapp.econtrol.entities.Expense.items#1], was: [com.myapp.econtrol.entities.Expense.items#1] (uninitialized)
      2006-05-18 14:12:44,062 DEBUG org.hibernate.event.def.AbstractFlushingEventListener [main] - Processing unreferenced collections
      2006-05-18 14:12:44,062 DEBUG org.hibernate.event.def.AbstractFlushingEventListener [main] - Scheduling collection removes/(re)creates/updates
      2006-05-18 14:12:44,062 DEBUG org.hibernate.event.def.AbstractFlushingEventListener [main] - Flushed: 0 insertions, 0 updates, 0 deletions to 1 objects
      2006-05-18 14:12:44,062 DEBUG org.hibernate.event.def.AbstractFlushingEventListener [main] - Flushed: 0 (re)creations, 0 updates, 0 removals to 1 collections
      2006-05-18 14:12:44,062 DEBUG org.hibernate.pretty.Printer [main] - listing entities:
      2006-05-18 14:12:44,062 DEBUG org.hibernate.pretty.Printer [main] - com.myapp.econtrol.entities.Expense{site=Sainsbury, items=<uninitialized>, date=18 May 2006, id=1}
      2006-05-18 14:12:44,062 DEBUG org.hibernate.event.def.AbstractFlushingEventListener [main] - executing flush
      2006-05-18 14:12:44,062 DEBUG org.hibernate.event.def.AbstractFlushingEventListener [main] - post flush
      2006-05-18 14:12:44,062 DEBUG org.hibernate.jdbc.JDBCContext [main] - before transaction completion
      2006-05-18 14:12:44,062 DEBUG org.hibernate.impl.SessionImpl [main] - before transaction completion
      2006-05-18 14:12:44,062 DEBUG org.jboss.ejb3.entity.ManagedEntityManagerFactory [main] - ************** closing entity managersession **************
      2006-05-18 14:12:44,062 DEBUG org.hibernate.impl.SessionImpl [main] - closing session
      2006-05-18 14:12:44,062 DEBUG org.hibernate.jdbc.ConnectionManager [main] - connection already null in cleanup : no action
      2006-05-18 14:12:44,062 DEBUG org.hibernate.transaction.CacheSynchronization [main] - transaction after completion callback, status: 3
      2006-05-18 14:12:44,062 DEBUG org.hibernate.jdbc.JDBCContext [main] - after transaction completion
      2006-05-18 14:12:44,062 DEBUG org.hibernate.impl.SessionImpl [main] - after transaction completion
      2006-05-18 14:12:44,078 ERROR org.hibernate.LazyInitializationException [main] - failed to lazily initialize a collection of role: com.myapp.econtrol.entities.Expense.items, no session or session was closed
      org.hibernate.LazyInitializationException: failed to lazily initialize a collection of role: com.myapp.econtrol.entities.Expense.items, no session or session was closed
       at org.hiberna