property lazy-loaded even if <many-to-one lazy="fals

freemant · **Posted:** Thu Apr 28, 2005 4:44 am

Hibernate version:
3.0

Mapping documents:
Foo.hbm.xml:

Code:

<hibernate-mapping package="mo.org.cpttm.school">
   <class name="Foo" table="Foo" lazy="false">
      <id name="id" column="Id" type="long">
         <generator class="hilo"/>
      </id>
      <many-to-one
         name="bar" 
         column="barId" 
         lazy="false"/>
   </class>      
</hibernate-mapping>

Bar.hbm.xml:

Code:

<hibernate-mapping>
   <class name="mo.org.cpttm.school.Bar" table="Bar">
      <id name="id" column="Id" type="long">
         <generator class="hilo"/>
      </id>
      <property name="name"/>
   </class>      
</hibernate-mapping>

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

Please see the JUnit Test case that fails at the last line in the assertCollectionLazy() method:

Code:

public class Test extends TestCase {
   private Foo thisFoo;

   private SessionFactory factory;

   protected void setUp() throws Exception {
      Configuration cfg = new Configuration().configure();
      factory = cfg.buildSessionFactory();
   }

   protected void tearDown() throws Exception {
      factory.close();
   }

   public void testLazyCollection() {
      Transaction tx = null;
      Session session = factory.openSession();
      try {
         tx = session.beginTransaction();
         deleteAll(session);
         initData(session);
         tx.commit();
      } catch (RuntimeException e) {
         if (tx != null) {
            tx.rollback();
         }
         throw e;
      } finally {
         session.close();
      }
      session = factory.openSession();
      try {
         assertCollectionLazy(session);
      } finally {
         session.close();
      }
   }

   private void assertCollectionLazy(Session session) {
      Query query = session.createQuery("from Foo");
      Iterator iter = query.iterate();
      assertTrue(iter.hasNext());
      thisFoo = (Foo) iter.next();
      assertTrue(Hibernate.isInitialized(thisFoo));
      assertTrue(Hibernate.isInitialized(thisFoo.getBar())); //FAILS!
   }

   private void initData(Session session) {
      Foo foo1 = new Foo();
      Bar bar1 = new Bar("bar1");
      Bar bar2 = new Bar("bar2");
      session.save(bar1);
      session.save(bar2);
      foo1.setBar(bar1);
      session.save(foo1);
   }

   private void deleteAll(Session session) {
      Query query = session.createQuery("from Bar");
      List bars = query.list();
      for (Iterator iter = bars.iterator(); iter.hasNext();) {
         Bar bar = (Bar) iter.next();
         session.delete(bar);
      }
      query = session.createQuery("from Foo");
      List foos = query.list();
      for (Iterator iter = foos.iterator(); iter.hasNext();) {
         Foo foo = (Foo) iter.next();
         session.delete(foo);
      }
   }

}

Full stack trace of any exception that occurs:

N/A.

Name and version of the database you are using:

hsqldb-1.7.3.3

The generated SQL (show_sql=true):

Code:

16:45:24,271  WARN Configurator:126 - No configuration found. Configuring ehcache from ehcache-failsafe.xml found in the classpath: jar:file:/C:/hibernate-3.0/lib/ehcache-1.1.jar!/ehcache-failsafe.xml
Hibernate: select bar0_.Id as Id, bar0_.name as name5_ from Bar bar0_
Hibernate: select foo0_.Id as Id, foo0_.barId as barId6_ from Foo foo0_
Hibernate: insert into Bar (name, Id) values (?, ?)
Hibernate: insert into Bar (name, Id) values (?, ?)
Hibernate: insert into Foo (barId, Id) values (?, ?)
Hibernate: update Foo set barId=? where Id=?
Hibernate: delete from Bar where Id=?
Hibernate: delete from Bar where Id=?
Hibernate: delete from Foo where Id=?
Hibernate: select foo0_.Id as col_0_0_ from Foo foo0_
Hibernate: select foo0_.Id as Id0_, foo0_.barId as barId6_0_ from Foo foo0_ where foo0_.Id=?

Debug level Hibernate log excerpt:

[code]
16:48:13,820 INFO Environment:460 - Hibernate 3.0
16:48:13,840 INFO Environment:473 - hibernate.properties not found
16:48:13,850 INFO Environment:506 - using CGLIB reflection optimizer
16:48:13,860 INFO Environment:536 - using JDK 1.4 java.sql.Timestamp handling
16:48:14,111 INFO Configuration:1159 - configuring from resource: /hibernate.cfg.xml
16:48:14,111 INFO Configuration:1130 - Configuration resource: /hibernate.cfg.xml
16:48:14,962 DEBUG DTDEntityResolver:42 - trying to locate http://hibernate.sourceforge.net/hibernate-configuration-3.0.dtd in classpath under org/hibernate/
16:48:14,972 DEBUG DTDEntityResolver:53 - found http://hibernate.sourceforge.net/hibernate-configuration-3.0.dtd in classpath
16:48:15,142 DEBUG Configuration:1116 - hibernate.dialect=org.hibernate.dialect.HSQLDialect
16:48:15,142 DEBUG Configuration:1116 - hibernate.connection.driver_class=org.hsqldb.jdbcDriver
16:48:15,152 DEBUG Configuration:1116 - hibernate.connection.username=sa
16:48:15,152 DEBUG Configuration:1116 - hibernate.connection.password=
16:48:15,152 DEBUG Configuration:1116 - hibernate.connection.url=jdbc:hsqldb:file:data/school
16:48:15,152 DEBUG Configuration:1116 - hibernate.show_sql=false
16:48:15,152 DEBUG Configuration:1116 - hibernate.hbm2ddl.auto=update
16:48:15,162 DEBUG Configuration:1311 - null<-org.dom4j.tree.DefaultAttribute@12cc95d [Attribute: name resource value "mo/org/cpttm/school/Course.hbm.xml"]
16:48:15,162 INFO Configuration:440 - Mapping resource: mo/org/cpttm/school/Course.hbm.xml
16:48:15,172 DEBUG DTDEntityResolver:42 - trying to locate http://hibernate.sourceforge.net/hibernate-mapping-3.0.dtd in classpath under org/hibernate/
16:48:15,172 DEBUG DTDEntityResolver:53 - found http://hibernate.sourceforge.net/hibernate-mapping-3.0.dtd in classpath
16:48:15,543 INFO HbmBinder:258 - Mapping class: mo.org.cpttm.school.Course -> Courses
16:48:15,563 DEBUG HbmBinder:1089 - Mapped property: id -> Id
16:48:15,643 DEBUG HbmBinder:1089 - Mapped property: code -> code
16:48:15,653 DEBUG HbmBinder:1089 - Mapped property: title -> title
16:48:15,653 DEBUG HbmBinder:1089 - Mapped property: size -> size
16:48:15,653 DEBUG HbmBinder:1089 - Mapped property: public -> public
16:48:15,663 INFO HbmBinder:1202 - Mapping collection: mo.org.cpttm.school.Course.schedule -> schedule
16:48:15,673 DEBUG HbmBinder:1089 - Mapped property: schedule
16:48:15,683 INFO HbmBinder:1202 - Mapping collection: mo.org.cpttm.school.Course.fees -> fees
16:48:15,683 DEBUG HbmBinder:1089 - Mapped property: fees
16:48:15,683 INFO HbmBinder:1202 - Mapping collection: mo.org.cpttm.school.Course.enrolledStudents -> enrollments
16:48:15,693 DEBUG HbmBinder:1089 - Mapped property: enrolledStudents
16:48:15,693 DEBUG Configuration:1311 - null<-org.dom4j.tree.DefaultAttribute@c980c9 [Attribute: name resource value "mo/org/cpttm/school/Student.hbm.xml"]
16:48:15,693 INFO Configuration:440 - Mapping resource: mo/org/cpttm/school/Student.hbm.xml
16:48:15,703 DEBUG DTDEntityResolver:42 - trying to locate http://hibernate.sourceforge.net/hibernate-mapping-3.0.dtd in classpath under org/hibernate/
16:48:15,713 DEBUG DTDEntityResolver:53 - found http://hibernate.sourceforge.net/hibernate-mapping-3.0.dtd in classpath
16:48:15,823 INFO HbmBinder:258 - Mapping class: mo.org.cpttm.school.Student -> Students
16:48:15,833 DEBUG HbmBinder:1089 - Mapped property: id -> Id
16:48:15,853 DEBUG HbmBinder:1089 - Mapped property: studentNo -> studentNo
16:48:15,853 DEBUG HbmBinder:1089 - Mapped property: name -> name
16:48:15,863 INFO HbmBinder:1202 - Mapping collection: mo.org.cpttm.school.Student.enrolledCourses -> enrollments
16:48:15,863 DEBUG HbmBinder:1089 - Mapped property: enrolledCourses
16:48:15,863 DEBUG Configuration:1311 - null<-org.dom4j.tree.DefaultAttribute@2a6f16 [Attribute: name resource value "mo/org/cpttm/school/Bar.hbm.xml"]
16:48:15,863 INFO Configuration:440 - Mapping resource: mo/org/cpttm/school/Bar.hbm.xml
16:48:15,883 DEBUG DTDEntityResolver:42 - trying to locate http://hibernate.sourceforge.net/hibernate-mapping-3.0.dtd in classpath under org/hibernate/
16:48:15,903 DEBUG DTDEntityResolver:53 - found http://hibernate.sourceforge.net/hibernate-mapping-3.0.dtd in classpath
16:48:15,984 INFO HbmBinder:258 - Mapping class: mo.org.cpttm.school.Bar -> Bar
16:48:15,984 DEBUG HbmBinder:1089 - Mapped property: id -> Id
16:48:15,994 DEBUG HbmBinder:1089 - Mapped property: name -> name
16:48:15,994 DEBUG Configuration:1311 - null<-org.dom4j.tree.DefaultAttribute@3b1d04 [Attribute: name resource value "mo/org/cpttm/school/Foo.hbm.xml"]
16:48:15,994 INFO Configuration:440 - Mapping resource: mo/org/cpttm/school/Foo.hbm.xml
16:48:16,014 DEBUG DTDEntityResolver:42 - trying to locate http://hibernate.sourceforge.net/hibernate-mapping-3.0.dtd in classpath under org/hibernate/
16:48:16,014 DEBUG DTDEntityResolver:53 - found http://hibernate.sourceforge.net/hibernate-mapping-3.0.dtd in classpath
16:48:16,104 INFO HbmBinder:258 - Mapping class: mo.org.cpttm.school.Foo -> Foo
16:48:16,114 DEBUG HbmBinder:1089 - Mapped property: id -> Id
16:48:16,314 DEBUG HbmBinder:1089 - Mapped property: bar -> barId
16:48:16,314 INFO Configuration:1271 - Configured SessionFactory: null
16:48:16,314 DEBUG Configuration:1272 - properties: {hibernate.connection.password=, java.runtime.name=Java(TM) 2 Runtime Environment, Standard Edition, sun.boot.library.path=C:\j2sdk1.4.2_04\jre\bin, java.vm.version=1.4.2_04-b05, hibernate.connection.username=sa, java.vm.vendor=Sun Microsystems Inc., java.vendor.url=http://java.sun.com/, path.separator=;, java.vm.name=Java HotSpot(TM) Client VM, file.encoding.pkg=sun.io, user.country=TW, sun.os.patch.level=Service Pack 4, java.vm.specification.name=Java Virtual Machine Specification, user.dir=c:\workspace\Associations, java.runtime.version=1.4.2_04-b05, java.awt.graphicsenv=sun.awt.Win32GraphicsEnvironment, java.endorsed.dirs=C:\j2sdk1.4.2_04\jre\lib\endorsed, os.arch=x86, java.io.tmpdir=C:\DOCUME~1\kent\LOCALS~1\Temp\, line.separator=
, java.vm.specification.vendor=Sun Microsystems Inc., user.variant=, os.name=Windows 2000, sun.java2d.fontpath=, java.library.path=C:\j2sdk1.4.2_04\bin;.;C:\WINNT\system32;C:\WINNT;C:\Program Files\Borland\Delphi7\Bin;C:\Program Files\Borland\Delphi7\Projects\Bpl\;C:\WINNT\system32;C:\WINNT;C:\WINNT\System32\Wbem;C:\j2sdk1.4.2_04\bin;c:\cygwin\bin, java.specification.name=Java Platform API Specification, java.class.version=48.0, java.util.prefs.PreferencesFactory=java.util.prefs.WindowsPreferencesFactory, os.version=5.0, user.home=C:\Documents and Settings\kent, user.timezone=Asia/Taipei, java.awt.printerjob=sun.awt.windows.WPrinterJob, file.encoding=MS950_HKSCS, java.specification.version=1.4, hibernate.connection.driver_class=org.hsqldb.jdbcDriver, user.name=kent, java.class.path=/c:/eclipse/plugins/org.eclipse.jdt.junit_3.0.1/junitsupport.jar;/c:/eclipse/plugins/org.eclipse.jdt.junit.runtime_3.0.0/junitruntime.jar;c:\workspace\Associations;C:\hibernate-3.0\hibernate3.jar;C:\hibernate-3.0\lib\xml-apis.jar;C:\hibernate-3.0\lib\ant-antlr-1.6.2.jar;C:\hibernate-3.0\lib\ant-junit-1.6.2.jar;C:\hibernate-3.0\lib\ant-launcher-1.6.2.jar;C:\hibernate-3.0\lib\antlr-2.7.5H3.jar;C:\hibernate-3.0\lib\ant-swing-1.6.2.jar;C:\hibernate-3.0\lib\asm.jar;C:\hibernate-3.0\lib\asm-attrs.jar;C:\hibernate-3.0\lib\c3p0-0.8.5.jar;C:\hibernate-3.0\lib\cglib-2.1.jar;C:\hibernate-3.0\lib\cleanimports.jar;C:\hibernate-3.0\lib\commons-collections-2.1.1.jar;C:\hibernate-3.0\lib\commons-logging-1.0.4.jar;C:\hibernate-3.0\lib\concurrent-1.3.2.jar;C:\hibernate-3.0\lib\connector.jar;C:\hibernate-3.0\lib\dom4j-1.5.2.jar;C:\hibernate-3.0\lib\ehcache-1.1.jar;C:\hibernate-3.0\lib\jaas.jar;C:\hibernate-3.0\lib\jacc-1_0-fr.jar;C:\hibernate-3.0\lib\jaxen-1.1-beta-4.jar;C:\hibernate-3.0\lib\jboss-cache.jar;C:\hibernate-3.0\lib\jboss-common.jar;C:\hibernate-3.0\lib\jboss-jmx.jar;C:\hibernate-3.0\lib\jboss-system.jar;C:\hibernate-3.0\lib\jdbc2_0-stdext.jar;C:\hibernate-3.0\lib\jgroups-2.2.7.jar;C:\hibernate-3.0\lib\jta.jar;C:\hibernate-3.0\lib\junit-3.8.1.jar;C:\hibernate-3.0\lib\log4j-1.2.9.jar;C:\hibernate-3.0\lib\oscache-2.1.jar;C:\hibernate-3.0\lib\proxool-0.8.3.jar;C:\hibernate-3.0\lib\swarmcache-1.0rc2.jar;C:\hibernate-3.0\lib\versioncheck.jar;C:\hibernate-3.0\lib\xerces-2.6.2.jar;C:\hibernate-3.0\lib\ant-1.6.2.jar;C:\hsqldb-1.7.3.3\lib\hsqldb.jar;C:\jars\junit.jar, hibernate.show_sql=false, java.vm.specification.version=1.0, java.home=C:\j2sdk1.4.2_04\jre, sun.arch.data.model=32, hibernate.connection.url=jdbc:hsqldb:file:data/school, hibernate.dialect=org.hibernate.dialect.HSQLDialect, user.language=zh, java.specification.vendor=Sun Microsystems Inc., awt.toolkit=sun.awt.windows.WToolkit, hibernate.cglib.use_reflection_optimizer=true, java.vm.info=mixed mode, java.version=1.4.2_04, java.ext.dirs=C:\j2sdk1.4.2_04\jre\lib\ext, sun.boot.class.path=C:\j2sdk1.4.2_04\jre\lib\rt.jar;C:\j2sdk1.4.2_04\jre\lib\i18n.jar;C:\j2sdk1.4.2_04\jre\lib\sunrsasign.jar;C:\j2sdk1.4.2_04\jre\lib\jsse.jar;C:\j2sdk1.4.2_04\jre\lib\jce.jar;C:\j2sdk1.4.2_04\jre\lib\charsets.jar;C:\j2sdk1.4.2_04\jre\classes, java.vendor=Sun Microsystems Inc., file.separator=\, hibernate.hbm2ddl.auto=update, java.vendor.url.bug=http://java.sun.com/cgi-bin/bugreport.cgi, sun.io.unicode.encoding=UnicodeLittle, sun.cpu.endian=little, sun.cpu.isalist=pentium i486 i386}
16:48:16,324 DEBUG Configuration:1047 - Preparing to build session factory with filters : {}
16:48:16,324 INFO Configuration:851 - processing extends queue
16:48:16,324 INFO Configuration:855 - processing collection mappings
16:48:16,324 DEBUG HbmBinder:2333 - Second pass for collection: mo.org.cpttm.school.Course.schedule
16:48:16,334 DEBUG HbmBinder:2349 - Mapped collection key: courseId, element: elt
16:48:16,334 DEBUG HbmBinder:2333 - Second pass for collection: mo.org.cpttm.school.Course.fees
16:48:16,344 DEBUG HbmBinder:2349 - Mapped collection key: courseId, index: idx, element: elt
16:48:16,344 DEBUG HbmBinder:2333 - Second pass for collection: mo.org.cpttm.school.Course.enrolledStudents
16:48:16,344 DEBUG HbmBinder:2349 - Mapped collection key: courseId, element: studentId
16:48:16,344 DEBUG HbmBinder:2333 - Second pass for collection: mo.org.cpttm.school.Student.enrolledCourses
16:48:16,374 DEBUG HbmBinder:2349 - Mapped collection key: studentId, element: courseId
16:48:16,374 INFO Configuration:864 - processing association property references
16:48:16,384 INFO Configuration:893 - processing foreign key constraints
16:48:16,384 DEBUG Configuration:940 - resolving reference to class: mo.org.cpttm.school.Bar
16:48:16,384 DEBUG Configuration:940 - resolving reference to class: mo.org.cpttm.school.Student
16:48:16,384 DEBUG Configuration:940 - resolving reference to class: mo.org.cpttm.school.Course
16:48:16,394 DEBUG Configuration:940 - resolving reference to class: mo.org.cpttm.school.Course
16:48:16,394 DEBUG Configuration:940 - resolving reference to class: mo.org.cpttm.school.Course
16:48:16,444 INFO Dialect:91 - Using dialect: org.hibernate.dialect.HSQLDialect
16:48:16,464 DEBUG SQLExceptionConverterFactory:52 - Using dialect defined converter
16:48:16,494 INFO SettingsFactory:90 - Default batch fetch size: 1
16:48:16,494 INFO SettingsFactory:94 - Generate SQL with comments: disabled
16:48:16,494 INFO SettingsFactory:98 - Order SQL updates by primary key: disabled
16:48:16,504 INFO SettingsFactory:273 - Query translator: org.hibernate.hql.ast.ASTQueryTranslatorFactory
16:48:16,514 INFO ASTQueryTranslatorFactory:21 - Using ASTQueryTranslatorFactory
16:48:16,514 INFO SettingsFactory:106 - Query language substitutions: {}
16:48:16,534 INFO DriverManagerConnectionProvider:41 - Using Hibernate built-in connection pool (not for production use!)
16:48:16,534 INFO DriverManagerConnectionProvider:42 - Hibernate connection pool size: 20
16:48:16,534 INFO DriverManagerConnectionProvider:45 - autocommit mode: false
16:48:16,544 INFO DriverManagerConnectionProvider:80 - using driver: org.hsqldb.jdbcDriver at URL: jdbc:hsqldb:file:data/school
16:48:16,544 INFO DriverManagerConnectionProvider:83 - connection properties: {user=sa, password=}
16:48:16,554 DEBUG DriverManagerConnectionProvider:93 - total checked-out connections: 0
16:48:16,554 DEBUG DriverManagerConnectionProvider:109 - opening new JDBC connection
16:48:18,117 DEBUG DriverManagerConnectionProvider:115 - created connection to: jdbc:hsqldb:file:data/school, Isolation Level: 1
16:48:18,137 DEBUG DriverManagerConnectionProvider:129 - returning connection to pool, pool size: 1
16:48:18,137 INFO SettingsFactory:148 - JDBC batch size: 15
16:48:18,137 INFO SettingsFactory:151 - JDBC batch updates for versioned data: disabled
16:48:18,147 INFO SettingsFactory:156 - Scrollable result sets: enabled
16:48:18,147 DEBUG SettingsFactory:160 - Wrap result sets: disabled
16:48:18,147 INFO SettingsFactory:164 - JDBC3 getGeneratedKeys(): disabled
16:48:18,157 INFO TransactionFactoryFactory:31 - Using default transaction strategy (direct JDBC transactions)
16:48:18,207 INFO TransactionManagerLookupFactory:33 - No TransactionManagerLookup configured (in JTA environment, use of read-write or transactional second-level cache is not recommended)
16:48:18,207 INFO SettingsFactory:176 - Automatic flush during beforeCompletion(): disabled
16:48:18,207 INFO SettingsFactory:179 - Automatic session close at end of transaction: disabled
16:48:18,217 INFO SettingsFactory:260 - Cache provider: org.hibernate.cache.EhCacheProvider
16:48:18,227 INFO SettingsFactory:187 - Second-level cache: enabled
16:48:18,227 INFO SettingsFactory:192 - Optimize cache for minimal puts: disabled
16:48:18,227 INFO SettingsFactory:199 - Structured second-level cache entries: enabled
16:48:18,247 INFO SettingsFactory:203 - Query cache: disabled
16:48:18,247 INFO SettingsFactory:214 - Statistics: disabled
16:48:18,247 INFO SettingsFactory:218 - Deleted entity synthetic identifier rollback: disabled
16:48:18,257 INFO SettingsFactory:232 - Default entity-mode: pojo
16:48:18,638 INFO SessionFactoryImpl:140 - building session factory
16:48:18,638 DEBUG SessionFactoryImpl:149 - Session factory constructed with filter configurations : {}
16:48:18,648 DEBUG SessionFactoryImpl:152 - instantiating session factory with properties: {hibernate.connection.password=, java.runtime.name=Java(TM) 2 Runtime Environment, Standard Edition, sun.boot.library.path=C:\j2sdk1.4.2_04\jre\bin, java.vm.version=1.4.2_04-b05, hibernate.connection.username=sa, java.vm.vendor=Sun Microsystems Inc., java.vendor.url=http://java.sun.com/, path.separator=;, java.vm.name=Java HotSpot(TM) Client VM, file.encoding.pkg=sun.io, user.country=TW, sun.os.patch.level=Service Pack 4, java.vm.specification.name=Java Virtual Machine Specification, user.dir=c:\workspace\Associations, java.runtime.version=1.4.2_04-b05, java.awt.graphicsenv=sun.awt.Win32GraphicsEnvironment, java.endorsed.dirs=C:\j2sdk1.4.2_04\jre\lib\endorsed, os.arch=x86, java.io.tmpdir=C:\DOCUME~1\kent\LOCALS~1\Temp\, line.separator=
, java.vm.specification.vendor=Sun Microsystems Inc., user.variant=, os.name=Windows 2000, sun.java2d.fontpath=, java.library.path=C:\j2sdk1.4.2_04\bin;.;C:\WINNT\system32;C:\WINNT;C:\Program Files\Borland\Delphi7\Bin;C:\Program Files\Borland\Delphi7\Projects\Bpl\;C:\WINNT\system32;C:\WINNT;C:\WINNT\System32\Wbem;C:\j2sdk1.4.2_04\bin;c:\cygwin\bin, java.specification.name=Java Platform API Specification, java.class.version=48.0, java.util.prefs.PreferencesFactory=java.util.prefs.WindowsPreferencesFactory, os.version=5.0, user.home=C:\Documents and Settings\kent, user.timezone=Asia/Taipei, java.awt.printerjob=sun.awt.windows.WPrinterJob, file.encoding=MS950_HKSCS, java.specification.version=1.4, hibernate.connection.driver_class=org.hsqldb.jdbcDriver, user.name=kent, java.class.path=/c:/eclipse/plugins/org.eclipse.jdt.junit_3.0.1/junitsupport.jar;/c:/eclipse/plugins/org.eclipse.jdt.junit.runtime_3.0.0/junitruntime.jar;c:\workspace\Associations;C:\hibernate-3.0\hibernate3.jar;C:\hibernate-3.0\lib\xml-apis.jar;C:\hibernate-3.0\lib\ant-antlr-1.6.2.jar;C:\hibernate-3.0\lib\ant-junit-1.6.2.jar;C:\hibernate-3.0\lib\ant-launcher-1.6.2.jar;C:\hibernate-3.0\lib\antlr-2.7.5H3.jar;C:\hibernate-3.0\lib\ant-swing-1.6.2.jar;C:\hibernate-3.0\lib\asm.jar;C:\hibernate-3.0\lib\asm-attrs.jar;C:\hibernate-3.0\lib\c3p0-0.8.5.jar;C:\hibernate-3.0\lib\cglib-2.1.jar;C:\hibernate-3.0\lib\cleanimports.jar;C:\hibernate-3.0\lib\commons-collections-2.1.1.jar;C:\hibernate-3.0\lib\commons-logging-1.0.4.jar;C:\hibernate-3.0\lib\concurrent-1.3.2.jar;C:\hibernate-3.0\lib\connector.jar;C:\hibernate-3.0\lib\dom4j-1.5.2.jar;C:\hibernate-3.0\lib\ehcache-1.1.jar;C:\hibernate-3.0\lib\jaas.jar;C:\hibernate-3.0\lib\jacc-1_0-fr.jar;C:\hibernate-3.0\lib\jaxen-1.1-beta-4.jar;C:\hibernate-3.0\lib\jboss-cache.jar;C:\hibernate-3.0\lib\jboss-common.jar;C:\hibernate-3.0\lib\jboss-jmx.jar;C:\hibernate-3.0\lib\jboss-system.jar;C:\hibernate-3.0\lib\jdbc2_0-stdext.jar;C:\hibernate-3.0\lib\jgroups-2.2.7.jar;C:\hibernate-3.0\lib\jta.jar;C:\hibernate-3.0\lib\junit-3.8.1.jar;C:\hibernate-3.0\lib\log4j-1.2.9.jar;C:\hibernate-3.0\lib\oscache-2.1.jar;C:\hibernate-3.0\lib\proxool-0.8.3.jar;C:\hibernate-3.0\lib\swarmcache-1.0rc2.jar;C:\hibernate-3.0\lib\versioncheck.jar;C:\hibernate-3.0\lib\xerces-2.6.2.jar;C:\hibernate-3.0\lib\ant-1.6.2.jar;C:\hsqldb-1.7.3.3\lib\hsqldb.jar;C:\jars\junit.jar, hibernate.show_sql=false, java.vm.specification.version=1.0, java.home=C:\j2sdk1.4.2_04\jre, sun.arch.data.model=32, hibernate.connection.url=jdbc:hsqldb:file:data/school, hibernate.dialect=org.hibernate.dialect.HSQLDialect, user.language=zh, java.specification.vendor=Sun Microsystems Inc., awt.toolkit=sun.awt.windows.WToolkit, hibernate.cglib.use_reflection_optimizer=true, java.vm.info=mixed mode, java.version=1.4.2_04, java.ext.dirs=C:\j2sdk1.4.2_04\jre\lib\ext, sun.boot.class.path=C:\j2sdk1.4.2_04\jre\lib\rt.jar;C:\j2sdk1.4.2_04\jre\lib\i18n.jar;C:\j2sdk1.4.2_04\jre\lib\sunrsasign.jar;C:\j2sdk1.4.2_04\jre\lib\jsse.jar;C:\j2sdk1.4.2_04\jre\lib\jce.jar;C:\j2sdk1.4.2_04\jre\lib\charsets.jar;C:\j2sdk1.4.2_04\jre\classes, java.vendor=Sun Microsystems Inc., file.separator=\, hibernate.hbm2ddl.auto=update, java.vendor.url.bug=http://java.sun.com/cgi-bin/bugreport.cgi, sun.io.unicode.encoding=UnicodeLittle, sun.cpu.endian=little, sun.cpu.isalist=pentium i486 i386}
16:48:18,658 DEBUG CacheManager:191 - Creating new CacheManager with default config
16:48:18,678 DEBUG CacheManager:164 - Configuring ehcache from classpath.
16:48:18,688 WARN Configurator:126 - No configuration found. Configuring ehcache from ehcache-failsafe.xml found in the classpath: jar:file:/C:/hibernate-3.0/lib/ehcache-1.1.jar!/ehcache-failsafe.xml
16:48:18,728 DEBUG Configuration$DiskStore:185 - Disk Store Path: C:\DOCUME~1\kent\LOCALS~1\Temp\
16:48:19,669 DEBUG BasicEntityPersister:2234 - Static SQL for entity: mo.org.cpttm.school.Course
16:48:19,669 DEBUG BasicEntityPersister:2236 - Version select: select Id from Courses where Id =?
16:48:19,679 DEBUG BasicEntityPersister:2237 - Snapshot select: select course_.Id, course_.code as code0_, course_.title as title0_, course_.size as size0_, course_.public as public0_ from Courses course_ where course_.Id=?
16:48:19,679 DEBUG BasicEntityPersister:2239 - Insert 0: insert into Courses (code, title, size, public, Id) values (?, ?, ?, ?, ?)
16:48:19,739 DEBUG BasicEntityPersister:2240 - Update 0: update Courses set code=?, title=?, size=?, public=? where Id=?
16:48:19,739 DEBUG BasicEntityPersister:2241 - Delete 0: delete from Courses where Id=?
16:48:19,920 DEBUG BasicEntityPersister:2234 - Static SQL for entity: mo.org.cpttm.school.Bar
16:48:19,920 DEBUG BasicEntityPersister:2236 - Version select: select Id from Bar where Id =?
16:48:19,920 DEBUG BasicEntityPersister:2237 - Snapshot select: select bar_.Id, bar_.name as name5_ from Bar bar_ where bar_.Id=?
16:48:19,920 DEBUG BasicEntityPersister:2239 - Insert 0: insert into Bar (name, Id) values (?, ?)
16:48:19,930 DEBUG BasicEntityPersister:2240 - Update 0: update Bar set name=? where Id=?
16:48:19,930 DEBUG BasicEntityPersister:2241 - Delete 0: delete from Bar where Id=?
16:48:19,980 DEBUG BasicEntityPersister:2234 - Static SQL for entity: mo.org.cpttm.school.Foo
16:48:19,980 DEBUG BasicEntityPersister:2236 - Version select: select Id from Foo where Id =?
16:48:19,980 DEBUG BasicEntityPersister:2237 - Snapshot select: select foo_.Id, foo_.barId as barId6_ from Foo foo_ where foo_.Id=?
16:48:19,990 DEBUG BasicEntityPersister:2239 - Insert 0: insert into Foo (barId, Id) values (?, ?)
16:48:19,990 DEBUG BasicEntityPersister:2240 - Update 0: update Foo set barId=? where Id=?
16:48:19,990 DEBUG BasicEntityPersister:2241 - Delete 0: delete from Foo where Id=?
16:48:20,300 DEBUG BasicEntityPersister:2234 - Static SQL for entity: mo.org.cpttm.school.Student
16:48:20,300 DEBUG BasicEntityPersister:2236 - Version select: select Id from Students where Id =?
16:48:20,300 DEBUG BasicEntityPersister:2237 - Snapshot select: select student_.Id, student_.studentNo as studentNo4_, student_.name as name4_ from Students student_ where student_.Id=?
16:48:20,310 DEBUG BasicEntityPersister:2239 - Insert 0: insert into Students (studentNo, name, Id) values (?, ?, ?)
16:48:20,310 DEBUG BasicEntityPersister:2240 - Update 0: update Students set studentNo=?, name=? where Id=?
16:48:20,310 DEBUG BasicEntityPersister:2241 - Delete 0: delete from Students where Id=?
16:48:20,340 DEBUG AbstractCollectionPersister:479 - Static SQL for collection: mo.org.cpttm.school.Course.fees
16:48:20,340 DEBUG AbstractCollectionPersister:480 - Row insert: insert into fees (courseId, idx, elt) values (?, ?, ?)
16:48:20,340 DEBUG AbstractCollectionPersister:481 - Row update: update fees set elt=? where courseId=? and idx=?
16:48:20,340 DEBUG AbstractCollectionPersister:482 - Row delete: delete from fees where courseId=? and idx=?
16:48:20,350 DEBUG AbstractCollectionPersister:483 - One-shot delete: delete from fees where courseId=?
16:48:20,350 DEBUG AbstractCollectionPersister:479 - Static SQL for collection: mo.org.cpttm.school.Course.enrolledStudents
16:48:20,360 DEBUG AbstractCollectionPersister:480 - Row insert: insert into enrollments (courseId, studentId) values (?, ?)
16:48:20,360 DEBUG AbstractCollectionPersister:481 - Row update: update enrollments set studentId=? where courseId=? and studentId=?
16:48:20,360 DEBUG AbstractCollectionPersister:482 - Row delete: delete from enrollments where courseId=? and studentId=?
16:48:20,360 DEBUG AbstractCollectionPersister:483 - One-shot delete: delete from enrollments where courseId=?
16:48:20,400 DEBUG AbstractCollectionPersister:479 - Static SQL for collection: mo.org.cpttm.school.Student.enrolledCourses
16:48:20,410 DEBUG AbstractCollectionPersister:480 - Row insert: insert into enrollments (studentId, courseId) values (?, ?)
16:48:20,410 DEBUG AbstractCollectionPersister:481 - Row update: update enrollments set courseId=? where studentId=? and courseId=?
16:48:20,410 DEBUG AbstractCollectionPersister:482 - Row delete: delete from enrollments where studentId=? and courseId=?
16:48:20,410 DEBUG AbstractCollectionPersister:483 - One-shot delete: delete from enrollments where studentId=?
16:48:20,410 DEBUG AbstractCollectionPersister:479 - Static SQL for collection: mo.org.cpttm.school.Course.schedule
16:48:20,420 DEBUG AbstractCollectionPersister:480 - Row insert: insert into schedule (courseId, elt) values (?, ?)
16:48:20,420 DEBUG AbstractCollectionPersister:481 - Row update: update schedule set elt=? where courseId=? and elt=?
16:48:20,420 DEBUG AbstractCollectionPersister:482 - Row delete: delete from schedule where courseId=? and elt=?
16:48:20,420 DEBUG AbstractCollectionPersister:483 - One-shot delete: delete from schedule where courseId=?
16:48:20,490 DEBUG EntityLoader:120 - Static select for entity mo.org.cpttm.school.Course: select course0_.Id as Id0_, course0_.code as code0_0_, course0_.title as title0_0_, course0_.size as size0_0_, course0_.public as public0_0_ from Courses course0_ where course0_.Id=?
16:48:20,490 DEBUG EntityLoader:120 - Static select for entity mo.org.cpttm.school.Course: select course0_.Id as Id0_, course0_.code as code0_0_, course0_.title as title0_0_, course0_.size as size0_0_, course0_.public as public0_0_ from Courses course0_ where course0_.Id=?
16:48:20,530 DEBUG EntityLoader:120 - Static select for entity mo.org.cpttm.school.Course: select course0_.Id as Id0_, course0_.code as code0_0_, course0_.title as title0_0_, course0_.size as size0_0_, course0_.public as public0_0_ from Courses course0_ where course0_.Id=?
16:48:20,530 DEBUG EntityLoader:120 - Static select for entity mo.org.cpttm.school.Course: select course0_.Id as Id0_, course0_.code as code0_0_, course0_.title as title0_0_, course0_.size as size0_0_, course0_.public as public0_0_ from Courses course0_ where course0_.Id=?
16:48:20,540 DEBUG EntityLoader:120 - Static select for entity mo.org.cpttm.school.Bar: select bar0_.Id as Id0_, bar0_.name as name5_0_ from Bar bar0_ where bar0_.Id=?
16:48:20,540 DEBUG EntityLoader:120 - Static select for entity mo.org.cpttm.school.Bar: select bar0_.Id as Id0_, bar0_.name as name5_0_ from Bar bar0_ where bar0_.Id=?
16:48:20,540 DEBUG EntityLoader:120 - Static select for entity mo.org.cpttm.school.Bar: select bar0_.Id as Id0_, bar0_.name as name5_0_ from Bar bar0_ where bar0_.Id=?
16:48:20,540 DEBUG EntityLoader:120 - Static select for entity mo.org.cpttm.school.Bar: select bar0_.Id as Id0_, bar0_.name as name5_0_ from Bar bar0_ where bar0_.Id=?
16:48:20,551 DEBUG EntityLoader:120 - Static select for entity mo.org.cpttm.school.Foo: select foo0_.Id as Id0_, foo0_.barId as barId6_0_ from Foo foo0_ where foo0_.Id=?
16:48:20,551 DEBUG EntityLoader:120 - Static select for entity mo.org.cpttm.school.Foo: select foo0_.Id as Id0_, foo0_.barId as barId6_0_ from Foo foo0_ where foo0_.Id=?
16:48:20,551 DEBUG EntityLoader:120 - Static select for entity mo.org.cpttm.school.Foo: select foo0_.Id as Id0_, foo0_.barId as barId6_0_ from Foo foo0_ where foo0_.Id=?
16:48:20,561 DEBUG EntityLoader:120 - Static select for entity mo.org.cpttm.school.Foo: select foo0_.Id as Id0_, foo0_.barId as barId6_0_ from Foo foo0_ where foo0_.Id=?
16:48:20,561 DEBUG EntityLoader:120 - Static select for entity mo.org.cpttm.school.Student: select student0_.Id as Id0_, student0_.studentNo as studentNo4_0_, student0_.name as name4_0_ from Students student0_ where student0_.Id=?
16:48:20,561 DEBUG EntityLoader:120 - Static select for entity mo.org.cpttm.school.Student: select student0_.Id as Id0_, student0_.studentNo as studentNo4_0_, student0_.name as name4_0_ from Students student0_ where student0_.Id=?
16:48:20,571 DEBUG EntityLoader:120 - Static select for entity mo.org.cpttm.school.Student: select student0_.Id as Id0_, student0_.studentNo as studentNo4_0_, student0_.name as name4_0_ from Students student0_ where student0_.Id=?
16:48:20,571 DEBUG EntityLoader:120 - Static select for entity mo.org.cpttm.school.Student: select student0_.Id as Id0_, student0_.studentNo as studentNo4_0_, student0_.name as name4_0_ from Students student0_ where student0_.Id=?
16:48:20,581 DEBUG CollectionLoader:72 - Static select for collection mo.org.cpttm.school.Course.fees: select fees0_.courseId as courseId__, fees0_.elt as elt__, fees0_.idx as idx__ from fees fees0_ where fees0_.courseId=?
16:48:20,601 DEBUG CollectionLoader:72 - Static select for collection mo.org.cpttm.school.Course.enrolledStudents: select enrolledst0_.courseId as courseId__, enrolledst0_.studentId as studentId__, student1_.Id as Id0_, student1_.studentNo as studentNo4_0_, student1_.name as name4_0_ from enrollments enrolledst0_ inner join Students student1_ on enrolledst0_.studentId=student1_.Id where enrolledst0_.courseId=?
16:48:20,601 DEBUG CollectionLoader:72 - Static select for collection mo.org.cpttm.school.Student.enrolledCourses: select enrolledco0_.studentId as studentId__, enrolledco0_.courseId as courseId__, course1_.Id as Id0_, course1_.code as code0_0_, course1_.title as title0_0_, course1_.size as size0_0_, course1_.public as public0_0_ from enrollments enrolledco0_ inner join Courses course1_ on enrolledco0_.courseId=course1_.Id where enrolledco0_.studentId=?
16:48:20,601 DEBUG CollectionLoader:72 - Static select for collection mo.org.cpttm.school.Course.schedule: select schedule0_.courseId as courseId__, schedule0_.elt as elt__ from schedule schedule0_ where schedule0_.courseId=?
16:48:20,611 DEBUG SessionFactoryObjectFactory:39 - initializing class SessionFactoryObjectFactory
16:48:20,651 DEBUG SessionFactoryObjectFactory:76 - registered: 297eaf3e0387fdf9010387fe02790000 (unnamed)
16:48:20,651 INFO SessionFactoryObjectFactory:82 - Not binding factory to JNDI, no JNDI name configured
16:48:20,651 DEBUG SessionFactoryImpl:249 - instantiated session factory
16:48:20,711 INFO Dialect:91 - Using dialect: org.hibernate.dialect.HSQLDialect
16:48:20,721 INFO DriverManagerConnectionProvider:41 - Using Hibernate built-in connection pool (not for production use!)
16:48:20,721 INFO DriverManagerConnectionProvider:42 - Hibernate connection pool size: 20
16:48:20,721 INFO DriverManagerConnectionProvider:45 - autocommit mode: false
16:48:20,721 INFO DriverManagerConnectionProvider:80 - using driver: org.hsqldb.jdbcDriver at URL: jdbc:hsqldb:file:data/school
16:48:20,721 INFO DriverManagerConnectionProvider:83 - connection properties: {user=sa, password=}
16:48:20,731 INFO SchemaUpdate:105 - Running hbm2ddl schema update
16:48:20,731 INFO SchemaUpdate:117 - fetching database metadata
16:48:20,731 DEBUG DriverManagerConnectionProvider:93 - total checked-out connections: 0
16:48:20,731 DEBUG DriverManagerConnectionProvider:109 - opening new JDBC connection
16:48:20,771 DEBUG DriverManagerConnectionProvider:115 - created connection to: jdbc:hsqldb:file:data/school, Isolation Level: 1
16:48:20,851 INFO SchemaUpdate:133 - updating schema
16:48:20,871 INFO Configuration:851 - processing extends queue
16:48:20,871 INFO Configuration:855 - processing collection mappings
16:48:20,881 INFO Configuration:864 - processing association property references
16:48:20,881 INFO Configuration:893 - processing foreign key constraints
16:48:20,881 DEBUG Configuration:940 - resolving reference to class: mo.org.cpttm.school.Bar
16:48:20,891 DEBUG Configuration:940 - resolving reference to class: mo.org.cpttm.school.Student
16:48:20,891 DEBUG Configuration:940 - resolving reference to class: mo.org.cpttm.school.Course
16:48:20,891 DEBUG Configuration:940 - resolving reference to class: mo.org.cpttm.school.Course
16:48:20,891 DEBUG Configuration:940 - resolving reference to class: mo.org.cpttm.school.Course
16:48:21,081 INFO TableMetadata:38 - table found: BAR
16:48:21,091 INFO TableMetadata:39 - columns: [name, id]
16:48:21,091 INFO TableMetadata:40 - foreign keys: []
16:48:21,091 INFO TableMetadata:41 - indexes: [sys_pk_bar]
16:48:21,121 INFO TableMetadata:38 - table found: COURSES
16:48:21,131 INFO TableMetadata:39 - columns: [code, public, title, size, id]
16:48:21,131 INFO TableMetadata:40 - foreign keys: []
16:48:21,131 INFO TableMetadata:41 - indexes: [sys_pk_courses]
16:48:21,151 INFO TableMetadata:38 - table found: FOO
16:48:21,151 INFO TableMetadata:39 - columns: [barid, id]
16:48:21,151 INFO TableMetadata:40 - foreign keys: [fk114a6c7a201cb]
16:48:21,161 INFO TableMetadata:41 - indexes: [sys_idx_1, sys_pk_foo]
16:48:21,171 INFO TableMetadata:38 - table found: STUDENTS
16:48:21,171 INFO TableMetadata:39 - columns: [studentno, name, id]
16:48:21,171 INFO TableMetadata:40 - foreign keys: []
16:48:21,181 INFO TableMetadata:41 - indexes: [sys_pk_students]
16:48:21,222 INFO TableMetadata:38 - table found: ENROLLMENTS
16:48:21,222 INFO TableMetadata:39 - columns: [courseid, studentid]
16:48:21,232 INFO TableMetadata:40 - foreign keys: [fkd680fdefd28a0107, fkd680fdef8a36f1b]
16:48:21,232 INFO TableMetadata:41 - indexes: [sys_idx_5, sys_pk_enrollments, sys_idx_3]
16:48:21,242 INFO TableMetadata:38 - table found: FEES
16:48:21,252 INFO TableMetadata:39 - columns: [idx, courseid, elt]
16:48:21,252 INFO TableMetadata:40 - foreign keys: [fk2fe5add28a0107]
16:48:21,252 INFO TableMetadata:41 - indexes: [sys_idx_7, sys_pk_fees]
16:48:21,272 INFO TableMetadata:38 - table found: SCHEDULE
16:48:21,272 INFO TableMetadata:39 - columns: [courseid, elt]
16:48:21,282 INFO TableMetadata:40 - foreign keys: [fkd6669297d28a0107]
16:48:21,282 INFO TableMetadata:41 - indexes: [sys_idx_9]
16:48:21,342 INFO TableMetadata:38 - table found: HIBERNATE_UNIQUE_KEY
16:48:21,342 INFO TableMetadata:39 - columns: [next_hi]
16:48:21,342 INFO TableMetadata:40 - foreign keys: []
16:48:21,352 INFO TableMetadata:41 - indexes: []
16:48:21,352 INFO SchemaUpdate:153 - schema update complete
16:48:21,352 INFO DriverManagerConnectionProvider:147 - cleaning up connection pool: jdbc:hsqldb:file:data/school
16:48:21,362 INFO SessionFactoryImpl:366 - Checking 0 named queries
16:48:21,462 DEBUG SessionImpl:229 - opened session at timestamp: 4565721503178752
16:48:21,472 DEBUG JDBCTransaction:46 - begin
16:48:21,472 DEBUG AbstractBatcher:408 - opening JDBC connection
16:48:21,482 DEBUG DriverManagerConnectionProvider:93 - total checked-out connections: 0
16:48:21,482 DEBUG DriverManagerConnectionProvider:99 - using pooled JDBC connection, pool size: 0
16:48:21,482 DEBUG JDBCTransaction:50 - current autocommit status: false
16:48:21,512 DEBUG SessionImpl:774 - find: from Bar
16:48:21,522 DEBUG QueryParameters:220 - named parameters: {}
16:48:21,913 INFO DriverManagerConnectionProvider:147 - cleaning up connection pool: jdbc:hsqldb:file:data/school
16:48:22,023 DEBUG QueryTranslatorImpl:207 - parse() - HQL: from mo.org.cpttm.school.Bar
16:48:22,083 DEBUG AST:223 - --- HQL AST ---
\-[QUERY] 'query'
\-[SELECT_FROM] 'SELECT_FROM'
\-[FROM] 'from'
\-[DOT] '.'
+-[DOT] '.'
| +-[DOT] '.'
| | +-[DOT] '.'
| | | +-[IDENT] 'mo'
| | | \-[IDENT] 'org'
| | \-[IDENT] 'cpttm'
| \-[IDENT] 'school'
\-[IDENT] 'Bar'

16:48:22,083 DEBUG ErrorCounter:72 - throwQueryException() : no errors
16:48:22,203 DEBUG HqlSqlBaseWalker:119 - query() << begin, level = 1
16:48:22,273 DEBUG FromElement:79 - FromClause{level=1} : mo.org.cpttm.school.Bar (no alias) -> bar0_
16:48:22,293 DEBUG HqlSqlBaseWalker:124 - query() : finishing up , level = 1
16:48:22,293 DEBUG HqlSqlWalker:328 - processQuery() : ( SELECT ( FromClause{level=1} Bar bar0_ ) )
16:48:22,323 DEBUG HqlSqlWalker:448 - Derived SELECT clause created.
16:48:22,353 DEBUG JoinProcessor:112 - Using FROM fragment [Bar bar0_]
16:48:22,353 DEBUG HqlSqlBaseWalker:127 - query() >> end, level = 1
16:48:22,363 DEBUG AST:193 - --- SQL AST ---
\-[SELECT] QueryNode: 'SELECT' querySpaces (Bar)
+-[SELECT_CLAUSE] SelectClause: '{derived select clause}'
| +-[SELECT_EXPR] SelectExpressionImpl: 'bar0_.Id as Id' {FromElement{explicit,not a collection join,classAlias=null,role=null,tableName=Bar,tableAlias=bar0_,colums={,className=mo.org.cpttm.school.Bar}}}
| \-[SQL_TOKEN] SqlFragment: 'bar0_.name as name5_'
\-[FROM] FromClause: 'from' FromClause{level=1, fromElementCounter=1, fromElements=1, fromElementByClassAlias=[], fromElementByTableAlias=[bar0_], fromElementsByPath=[], collectionJoinFromElementsByPath=[], impliedElements=[]}
\-[FROM_FRAGMENT] FromElement: 'Bar bar0_' FromElement{explicit,not a collection join,classAlias=null,role=null,tableName=Bar,tableAlias=bar0_,colums={,className=mo.org.cpttm.school.Bar}}

16:48:22,363 DEBUG ErrorCounter:72 - throwQueryException() : no errors
16:48:22,433 DEBUG QueryTranslatorImpl:177 - HQL: from mo.org.cpttm.school.Bar
16:48:22,443 DEBUG QueryTranslatorImpl:178 - SQL: select bar0_.Id as Id, bar0_.name as name5_ from Bar bar0_
16:48:22,443 DEBUG ErrorCounter:72 - throwQueryException() : no errors
16:48:22,463 DEBUG AbstractBatcher:276 - about to open PreparedStatement (open PreparedStatements: 0, globally: 0)
16:48:22,463 DEBUG SQL:310 - select bar0_.Id as Id, bar0_.name as name5_ from Bar bar0_
16:48:22,463 DEBUG AbstractBatcher:364 - preparing statement
16:48:22,483 DEBUG AbstractBatcher:292 - about to open ResultSet (open ResultSets: 0, globally: 0)
16:48:22,483 DEBUG Loader:380 - processing result set
16:48:22,493 DEBUG Loader:385 - result set row: 0
16:48:22,493 DEBUG LongType:86 - returning '327680' as column: Id
16:48:22,503 DEBUG Loader:760 - result row: EntityKey[mo.org.cpttm.school.Bar#327680]
16:48:22,503 DEBUG Loader:905 - Initializing object from ResultSet: [mo.org.cpttm.school.Bar#327680]
16:48:22,554 DEBUG BasicEntityPersister:1665 - Hydrating entity: [mo.org.cpttm.school.Bar#327680]
16:48:22,554 DEBUG StringType:86 - returning 'bar1' as column: name5_
16:48:22,564 DEBUG Loader:385 - result set row: 1
16:48:22,564 DEBUG LongType:86 - returning '327681' as column: Id
16:48:22,574 DEBUG Loader:760 - result row: EntityKey[mo.org.cpttm.school.Bar#327681]
16:48:22,574 DEBUG Loader:905 - Initializing object from ResultSet: [mo.org.cpttm.school.Bar#327681]
16:48:22,574 DEBUG BasicEntityPersister:1665 - Hydrating entity: [mo.org.cpttm.school.Bar#327681]
16:48:22,584 DEBUG StringType:86 - returning 'bar2' as column: name5_
16:48:22,584 DEBUG Loader:404 - done processing result set (2 rows)
16:48:22,584 DEBUG AbstractBatcher:299 - about to close ResultSet (open ResultSets: 1, globally: 1)
16:48:22,594 DEBUG AbstractBatcher:284 - about to close PreparedStatement (open PreparedStatements: 1, globally: 1)
16:48:22,594 DEBUG AbstractBatcher:392 - closing statement
16:48:22,604 DEBUG Loader:490 - total objects hydrated: 2
16:48:22,604 DEBUG TwoPhaseLoad:96 - resolving associations for [mo.org.cpttm.school.Bar#327680]
16:48:22,614 DEBUG TwoPhaseLoad:167 - done materializing entity [mo.org.cpttm.school.Bar#327680]
16:48:22,614 DEBUG TwoPhaseLoad:96 - resolving associations for [mo.org.cpttm.school.Bar#327681]
16:48:22,624 DEBUG TwoPhaseLoad:167 - done materializing entity [mo.org.cpttm.school.Bar#327681]
16:48:22,624 DEBUG PersistenceContext:738 - initializing non-lazy collections
16:48:22,664 DEBUG DefaultDeleteEventListener:91 - deleting a persistent instance
16:48:22,674 DEBUG DefaultDeleteEventListener:126 - deleting [mo.org.cpttm.school.Bar#327680]
16:48:22,674 DEBUG SessionImpl:1006 - setting cache mode to: GET
16:48:22,674 DEBUG SessionImpl:1006 - setting cache mode to: NORMAL
16:48:22,694 DEBUG SessionImpl:1006 - setting cache mode to: GET
16:48:22,694 DEBUG SessionImpl:1006 - setting cache mode to: NORMAL
16:48:22,694 DEBUG DefaultDeleteEventListener:91 - deleting a persistent instance
16:48:22,704 DEBUG DefaultDeleteEventListener:126 - deleting [mo.org.cpttm.school.Bar#327681]
16:48:22,704 DEBUG SessionImpl:1006 - setting cache mode to: GET
16:48:22,714 DEBUG SessionImpl:1006 - setting cache mode to: NORMAL
16:48:22,714 DEBUG SessionImpl:1006 - setting cache mode to: GET
16:48:22,714 DEBUG SessionImpl:1006 - setting cache mode to: NORMAL
16:48:22,714 DEBUG SessionImpl:774 - find: from Foo
16:48:22,724 DEBUG QueryParameters:220 - named parameters: {}
16:48:22,724 DEBUG QueryTranslatorImpl:207 - parse() - HQL: from mo.org.cpttm.school.Foo
16:48:22,744 DEBUG AST:223 - --- HQL AST ---
\-[QUERY] 'query'
\-[SELECT_FROM] 'SELECT_FROM'
\-[FROM] 'from'
\-[DOT] '.'
+-[DOT] '.'
| +-[DOT] '.'
| | +-[DOT] '.'
| | | +-[IDENT] 'mo'
| | | \-[IDENT] 'org'
| | \-[IDENT] 'cpttm'
| \-[IDENT] 'school'
\-[IDENT] 'Foo'

16:48:22,744 DEBUG ErrorCounter:72 - throwQueryException() : no errors
16:48:22,744 DEBUG HqlSqlBaseWalker:119 - query() << begin, level = 1
16:48:22,754 DEBUG FromElement:79 - FromClause{level=1} : mo.org.cpttm.school.Foo (no alias) -> foo0_
16:48:22,754 DEBUG HqlSqlBaseWalker:124 - query() : finishing up , level = 1
16:48:22,794 DEBUG HqlSqlWalker:328 - processQuery() : ( SELECT ( FromClause{level=1} Foo foo0_ ) )
16:48:22,794 DEBUG HqlSqlWalker:448 - Derived SELECT clause created.
16:48:22,804 DEBUG JoinProcessor:112 - Using FROM fragment [Foo foo0_]
16:48:22,804 DEBUG HqlSqlBaseWalker:127 - query() >> end, level = 1
16:48:22,804 DEBUG AST:193 - --- SQL AST ---
\-[SELECT] QueryNode: 'SELECT' querySpaces (Foo)
+-[SELECT_CLAUSE] SelectClause: '{derived select clause}'
| +-[SELECT_EXPR] SelectExpressionImpl: 'foo0_.Id as Id' {FromElement{explicit,not a collection join,classAlias=null,role=null,tableName=Foo,tableAlias=foo0_,colums={,className=mo.org.cpttm.school.Foo}}}
| \-[SQL_TOKEN] SqlFragment: 'foo0_.barId as barId6_'
\-[FROM] FromClause: 'from' FromClause{level=1, fromElementCounter=1, fromElements=1, fromElementByClassAlias=[], fromElementByTableAlias=[foo0_], fromElementsByPath=[], collectionJoinFromElementsByPath=[], impliedElements=[]}
\-[FROM_FRAGMENT] FromElement: 'Foo foo0_' FromElement{explicit,not a collection join,classAlias=null,role=null,tableName=Foo,tableAlias=foo0_,colums={,className=mo.org.cpttm.school.Foo}}

16:48:22,804 DEBUG ErrorCounter:72 - throwQueryException() : no errors
16:48:22,824 DEBUG QueryTranslatorImpl:177 - HQL: from mo.org.cpttm.school.Foo
16:48:22,824 DEBUG QueryTranslatorImpl:178 - SQL: select foo0_.Id as Id, foo0_.barId as barId6_ from Foo foo0_
16:48:22,834 DEBUG ErrorCounter:72 - throwQueryException() : no errors
16:48:22,834 DEBUG AbstractFlushingEventListener:52 - flushing session
16:48:22,834 DEBUG AbstractFlushingEventListener:102 - processing flush-time cascades
16:48:22,844 DEBUG AbstractFlushingEventListener:150 - dirty checking collections
16:48:22,844 DEBUG AbstractFlushingEventListener:167 - Flushing entities and processing referenced collections
16:48:22,854 DEBUG AbstractFlushingEventListener:203 - Processing unreferenced collections
16:48:22,854 DEBUG AbstractFlushingEventListener:217 - Scheduling collection removes/(re)creates/updates
16:48:22,854 DEBUG AbstractFlushingEventListener:79 - Flushed: 0 insertions, 0 updates, 2 deletions to 2 objects
16:48:22,854 DEBUG AbstractFlushingEventListener:85 - Flushed: 0 (re)creations, 0 updates, 0 removals to 0 collections
16:48:22,864 DEBUG Printer:83 - listing entities:
16:48:22,864 DEBUG Printer:90 - mo.org.cpttm.school.Bar{name=bar1, id=327680}
16:48:22,874 DEBUG Printer:90 - mo.org.cpttm.school.Bar{name=bar2, id=327681}
16:48:22,874 DEBUG DefaultAutoFlushEventListener:60 - Dont need to execute flush
16:48:22,874 DEBUG AbstractBatcher:276 - about to open PreparedStatement (open PreparedStatements: 0, globally: 0)
16:48:22,874 DEBUG SQL:310 - select foo0_.Id as Id, foo0_.barId as barId6_ from Foo foo0_
16:48:22,884 DEBUG AbstractBatcher:364 - preparing statement
16:48:22,884 DEBUG AbstractBatcher:292 - about to open ResultSet (open ResultSets: 0, globally: 0)
16:48:22,884 DEBUG Loader:380 - processing result set
16:48:22,884 DEBUG Loader:385 - result set row: 0
16:48:22,934 DEBUG LongType:86 - returning '360448' as column: Id
16:48:22,934 DEBUG Loader:760 - result row: EntityKey[mo.org.cpttm.school.Foo#360448]
16:48:22,944 DEBUG Loader:905 - Initializing object from ResultSet: [mo.org.cpttm.school.Foo#360448]
16:48:22,944 DEBUG BasicEntityPersister:1665 - Hydrating entity: [mo.org.cpttm.school.Foo#360448]
16:48:22,944 DEBUG LongType:86 - returning '327680' as column: barId6_
16:48:22,944 DEBUG Loader:404 - done processing result set (1 rows)
16:48:22,954 DEBUG AbstractBatcher:299 - about to close ResultSet (open ResultSets: 1, globally: 1)
16:48:22,954 DEBUG AbstractBatcher:284 - about to close PreparedStatement (open PreparedStatements: 1, globally: 1)
16:48:22,954 DEBUG AbstractBatcher:392 - closing statement
16:48:22,954 DEBUG Loader:490 - total objects hydrated: 1
16:48:22,964 DEBUG TwoPhaseLoad:96 - resolving associations for [mo.org.cpttm.school.Foo#360448]
16:48:22,974 DEBUG DefaultLoadEventListener:193 - loading entity: [mo.org.cpttm.school.Bar#327680]
16:48:22,974 DEBUG DefaultLoadEventListener:209 - entity found in session cache
16:48:22,974 DEBUG DefaultLoadEventListener:326 - attempting to resolve: [mo.org.cpttm.school.Bar#327680]
16:48:22,984 DEBUG DefaultLoadEventListener:335 - resolved object in session cache: [mo.org.cpttm.school.Bar#327680]
16:48:22,984 DEBUG TwoPhaseLoad:167 - done materializing entity [mo.org.cpttm.school.Foo#360448]
16:48:22,994 DEBUG PersistenceContext:738 - initializing non-lazy collections
16:48:22,994 DEBUG DefaultDeleteEventListener:91 - deleting a persistent instance
16:48:22,994 DEBUG DefaultDeleteEventListener:126 - deleting [mo.org.cpttm.school.Foo#360448]
16:48:22,994 DEBUG SessionImpl:1006 - setting cache mode to: GET
16:48:23,004 DEBUG SessionImpl:1006 - setting cache mode to: NORMAL
16:48:23,004 DEBUG SessionImpl:1006 - setting cache mode to: GET
16:48:23,004 DEBUG SessionImpl:1006 - setting cache mode to: NORMAL
16:48:23,014 DEBUG DefaultSaveOrUpdateEventListener:159 - saving transient instance
16:48:23,014 DEBUG AbstractBatcher:408 - opening JDBC connection
16:48:23,014 DEBUG DriverManagerConnectionProvider:93 - total checked-out connections: 1
16:48:23,014 DEBUG DriverManagerConnectionProvider:109 - opening new JDBC connection
16:48:23,074 DEBUG DriverManagerConnectionProvider:115 - created connection to: jdbc:hsqldb:file:data/school, Isolation Level: 1
16:48:23,084 DEBUG AbstractBatcher:423 - closing JDBC connection (open PreparedStatements: 0, globally: 0) (open ResultSets: 0, globally: 0)
16:48:23,084 DEBUG DriverManagerConnectionProvider:129 - returning connection to pool, pool size: 1
16:48:23,094 DEBUG TableHiLoGenerator:64 - new hi value: 12
16:48:23,094 DEBUG AbstractSaveEventListener:89 - generated identifier: 393216, using strategy: org.hibernate.id.TableHiLoGenerator
16:48:23,094 DEBUG AbstractSaveEventListener:132 - saving [mo.org.cpttm.school.Bar#393216]
16:48:23,104 DEBUG DefaultSaveOrUpdateEventListener:159 - saving transient instance
16:48:23,104 DEBUG AbstractSaveEventListener:89 - generated identifier: 393217, using strategy: org.hibernate.id.TableHiLoGenerator
16:48:23,114 DEBUG AbstractSaveEventListener:132 - saving [mo.org.cpttm.school.Bar#393217]
16:48:23,114 DEBUG DefaultSaveOrUpdateEventListener:159 - saving transient instance
16:48:23,114 DEBUG AbstractBatcher:408 - opening JDBC connection
16:48:23,114 DEBUG DriverManagerConnectionProvider:93 - total checked-out connections: 1
16:48:23,124 DEBUG DriverManagerConnectionProvider:99 - using pooled JDBC connection, pool size: 0
16:48:23,134 DEBUG AbstractBatcher:423 - closing JDBC connection (open PreparedStatements: 0, globally: 0) (open ResultSets: 0, globally: 0)
16:48:23,134 DEBUG DriverManagerConnectionProvider:129 - returning connection to pool, pool size: 1
16:48:23,134 DEBUG TableHiLoGenerator:64 - new hi value: 13
16:48:23,134 DEBUG AbstractSaveEventListener:89 - generated identifier: 425984, using strategy: org.hibernate.id.TableHiLoGenerator
16:48:23,144 DEBUG AbstractSaveEventListener:132 - saving [mo.org.cpttm.school.Foo#425984]
16:48:23,144 DEBUG JDBCTransaction:83 - commit
16:48:23,144 DEBUG SessionImpl:292 - automatically flushing session
16:48:23,144 DEBUG AbstractFlushingEventListener:52 - flushing session
16:48:23,154 DEBUG AbstractFlushingEventListener:102 - processing flush-time cascades
16:48:23,154 DEBUG AbstractFlushingEventListener:150 - dirty checking collections
16:48:23,154 DEBUG AbstractFlushingEventListener:167 - Flushing entities and processing referenced collections
16:48:23,205 DEBUG BasicEntityPersister:2618 - mo.org.cpttm.school.Foo.bar is dirty
16:48:23,205 DEBUG DefaultFlushEntityEventListener:115 - Updating deleted entity: [mo.org.cpttm.school.Foo#360448]
16:48:23,215 DEBUG AbstractFlushingEventListener:203 - Processing unreferenced collections
16:48:23,215 DEBUG AbstractFlushingEventListener:217 - Scheduling collection removes/(re)creates/updates
16:48:23,215 DEBUG AbstractFlushingEventListener:79 - Flushed: 3 insertions, 1 updates, 3 deletions to 6 objects
16:48:23,225 DEBUG AbstractFlushingEventListener:85 - Flushed: 0 (re)creations, 0 updates, 0 removals to 0 collections
16:48:23,225 DEBUG Printer:83 - listing entities:
16:48:23,225 DEBUG Printer:90 - mo.org.cpttm.school.Bar{name=bar1, id=393216}
16:48:23,225 DEBUG Printer:90 - mo.org.cpttm.school.Bar{name=bar2, id=393217}
16:48:23,235 DEBUG Printer:90 - mo.org.cpttm.school.Bar{name=bar1, id=327680}
16:48:23,235 DEBUG Printer:90 - mo.org.cpttm.school.Foo{bar=mo.org.cpttm.school.Bar#327680, id=360448}
16:48:23,235 DEBUG Printer:90 - mo.org.cpttm.school.Bar{name=bar2, id=327681}
16:48:23,245 DEBUG Printer:90 - mo.org.cpttm.school.Foo{bar=mo.org.cpttm.school.Bar#393216, id=425984}
16:48:23,245 DEBUG AbstractFlushingEventListener:267 - executing flush
16:48:23,255 DEBUG BasicEntityPersister:1838 - Inserting entity: [mo.org.cpttm.school.Bar#393216]
16:48:23,255 DEBUG AbstractBatcher:276 - about to open PreparedStatement (open PreparedStatements: 0, globally: 0)
16:48:23,255 DEBUG SQL:310 - insert into Bar (name, Id) values (?, ?)
16:48:23,255 DEBUG AbstractBatcher:364 - preparing statement
16:48:23,265 DEBUG BasicEntityPersister:1627 - Dehydrating entity: [mo.org.cpttm.school.Bar#393216]
16:48:23,265 DEBUG StringType:59 - binding 'bar1' to parameter: 1
16:48:23,265 DEBUG LongType:59 - binding '393216' to parameter: 2
16:48:23,275 DEBUG AbstractBatcher:27 - Adding to batch
16:48:23,285 DEBUG BasicEntityPersister:1838 - Inserting entity: [mo.org.cpttm.school.Bar#393217]
16:48:23,285 DEBUG AbstractBatcher:152 - reusing prepared statement
16:48:23,285 DEBUG SQL:310 - insert into Bar (name, Id) values (?, ?)
16:48:23,285 DEBUG BasicEntityPersister:1627 - Dehydrating entity: [mo.org.cpttm.school.Bar#393217]
16:48:23,335 DEBUG StringType:59 - binding 'bar2' to parameter: 1
16:48:23,335 DEBUG LongType:59 - binding '393217' to parameter: 2
16:48:23,335 DEBUG AbstractBatcher:27 - Adding to batch
16:48:23,345 DEBUG BasicEntityPersister:1838 - Inserting entity: [mo.org.cpttm.school.Foo#425984]
16:48:23,345 DEBUG AbstractBatcher:54 - Executing batch size: 2
16:48:23,355 DEBUG AbstractBatcher:284 - about to close PreparedStatement (open PreparedStatements: 1, globally: 1)
16:48:23,355 DEBUG AbstractBatcher:392 - closing statement
16:48:23,355 DEBUG AbstractBatcher:276 - about to open PreparedStatement (open PreparedStatements: 0, globally: 0)
16:48:23,365 DEBUG SQL:310 - insert into Foo (barId, Id) values (?, ?)
16:48:23,365 DEBUG AbstractBatcher:364 - preparing statement
16:48:23,365 DEBUG BasicEntityPersister:1627 - Dehydrating entity: [mo.org.cpttm.school.Foo#425984]
16:48:23,375 DEBUG LongTyp

pmularien · **Posted:** Thu Apr 28, 2005 9:19 am

Maybe this is not the right observation, but isn't a property lazy-loaded if lazy=true? So, I think it is behaving as it should, unless I'm missing something.

freemant · **Posted:** Sat Apr 30, 2005 5:50 am

I am setting lazy to false so that the property should be initialized right away but it isn't. I suspect this is a bug.

Code:

<hibernate-mapping package="mo.org.cpttm.school"> 
   <class name="Foo" table="Foo" lazy="false"> 
      <id name="id" column="Id" type="long"> 
         <generator class="hilo"/> 
      </id> 
      <many-to-one 
         name="bar" 
         column="barId" 
         lazy="false"/> 
   </class>       
</hibernate-mapping> 

anthony · **Posted:** Sat Apr 30, 2005 2:56 pm

fetch=join, forget lazy

freemant · **Posted:** Sat Apr 30, 2005 9:10 pm

I'll try. Would you please let me know why lazy is not working? Or my concept of lazy is incorrect?

Thanks!

anthony · **Posted:** Sun May 01, 2005 3:58 am

if you check changelog:

Changes in version 3.0 beta 3 (30.1.2005)
------------------------------------------
....
* added lazy="true" to many-to-one and one-to-one mappings (requires bytecode instrumentation)

this means that if you want to use the lazy attribute on many-to-one (and properties), you need bytecode instrumentation.

You can have the lazy behaviour just by playing with fetch attribute (without bytecode instrumentation) and that's all... much easier isn't it? fetch attribute is also available for collection.

My advise is to _forget_ lazy and outer-join attributes and just remember that, by default fetch=select --> which allow lazy behaviour, if you don't want lazy, switch to fetch=join.

Of course, there should be rare cases where you'll have to use lazy/outer-join, but in general fetch is enough.

freemant · **Posted:** Mon May 02, 2005 4:39 am

Setting fetch="join" does load the object in the property fine, however, I am still very much confused by this lazy flag. As I am not using build-time byte code instrumentation, so the lazy flag should have no effect. So it should be equivalent to lazy=false, right? But it is indeed being lazy loaded. Why?

Thanks!

anthony · **Posted:** Mon May 02, 2005 5:16 am

nop, your lazy attribute is just ignored, so default values are considered.
In hibernate 3 default value for fetch attribute is "select".

freemant · **Posted:** Mon May 02, 2005 5:32 am

But according to the doc on <many-to-one> the default value
for the lazy attribute is false. This will prevent select fetching
from working (according to the doc again).

anthony · **Posted:** Mon May 02, 2005 5:56 am

many-to-one side

Quote:

fetch (optional - defaults to select): Chooses between outer-join fetching or sequential select fetching.

so by default, sequential select fetching
you have to understand that not only the _lazy_ attribute allows you to define a lazy behaviour.

In the class side, you have proxy + lazy attribute.
In the many-to-one side, you have fetch + outer-join (can also have an impact on lazy behaviour) + lazy, in the case of many-to-one, lazy attribute is the less used because it needs bytecode instrumentation.

I've told you that the easiest way to define it, is to use fetch attribute and stop. Now you're free to do what you want.

I agree there are many attributes to know but, that is seems difficult,but again, just focus on fetch attribute.

freemant · **Posted:** Mon May 02, 2005 6:04 am

Yes, I understand that setting fetch is the easier way, but I am trying
to get a clear picture on what's going on because what I read in the
doc seems to be contradicting to what is happening:

In section 19.1:

Quote:

Select fetching - a second SELECT is used to retrieve the associated entity or
collection. Unless you explicitly disable lazy fetching by specifying
lazy="false", this second select will only be executed when you actually
access the association.

I've followed this info and set lazy to false, but it still executes the
second select only when I access the association.