Hi All,

I have a class that contains a Map keyed on an entity reference using <map-key-many-to-many>. Attempts to retrieve instances of this class with EntityMode.DOM4J result in a ClassCastException in PersistentIndexedElementHolder.readFrom, due to an attempt to cast a ManyToOneType to NullableType.

I have isolated this problem into a small test project, which contains just three classes, Source, Target, and Mapping (which contains the Map keyed on Source objects).

Attempts to retrieve a Mapping instance while in DOM4J mode throw a ClassCastException if embed-xml=true, but not if it is false. However, when embed-xml=false, no XML is generated for the Map within the Mapping object (this seems different to the behavior for other collections such as Bag).

I'd like to be able to include in the XML the ids for the map key and value entities. Any ideas?

Thanks!

Hibernate version:
3.0.5

Mapping documents:


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


Full stack trace of any exception that occurs:
java.lang.ClassCastException: org.hibernate.type.ManyToOneType
at org.hibernate.collection.PersistentIndexedElementHolder.readFrom(PersistentIndexedElementHolder.java:140)
at org.hibernate.loader.Loader.readCollectionElement(Loader.java:674)
at org.hibernate.loader.Loader.readCollectionElements(Loader.java:370)
at org.hibernate.loader.Loader.getRowFromResultSet(Loader.java:314)
at org.hibernate.loader.Loader.doQuery(Loader.java:412)
at org.hibernate.loader.Loader.doQueryAndInitializeNonLazyCollections(Loader.java:218)
at org.hibernate.loader.Loader.loadCollection(Loader.java:1434)
at org.hibernate.loader.collection.CollectionLoader.initialize(CollectionLoader.java:99)
at org.hibernate.persister.collection.AbstractCollectionPersister.initialize(AbstractCollectionPersister.java:489)
at org.hibernate.event.def.DefaultInitializeCollectionEventListener.onInitializeCollection(DefaultInitializeCollectionEventListener.java:60)
at org.hibernate.impl.SessionImpl.initializeCollection(SessionImpl.java:1430)
at org.hibernate.type.CollectionType.getCollection(CollectionType.java:484)
at org.hibernate.type.CollectionType.resolveKey(CollectionType.java:332)
at org.hibernate.type.CollectionType.resolve(CollectionType.java:326)
at org.hibernate.engine.TwoPhaseLoad.initializeEntity(TwoPhaseLoad.java:105)
at org.hibernate.loader.Loader.initializeEntitiesAndCollections(Loader.java:530)
at org.hibernate.loader.Loader.doQuery(Loader.java:436)
at org.hibernate.loader.Loader.doQueryAndInitializeNonLazyCollections(Loader.java:218)
at org.hibernate.loader.Loader.doList(Loader.java:1593)
at org.hibernate.loader.Loader.list(Loader.java:1577)
at org.hibernate.loader.hql.QueryLoader.list(QueryLoader.java:395)
at org.hibernate.hql.ast.QueryTranslatorImpl.list(QueryTranslatorImpl.java:270)
at org.hibernate.impl.SessionImpl.list(SessionImpl.java:844)
at org.hibernate.impl.QueryImpl.list(QueryImpl.java:74)
at XMLPersister$1.doInHibernate(XMLPersister.java:55)
at org.springframework.orm.hibernate3.HibernateTemplate.execute(HibernateTemplate.java:312)
at org.springframework.orm.hibernate3.HibernateTemplate.execute(HibernateTemplate.java:288)
at XMLPersister.getMappings(XMLPersister.java:49)
at XMLPersister.exportXML(XMLPersister.java:70)
at TestXMLPersister.testExportXML(TestXMLPersister.java:61)
at sun.reflect.NativeMethodAccessorImpl.invoke0(Native Method)
at sun.reflect.NativeMethodAccessorImpl.invoke(NativeMethodAccessorImpl.java)
at sun.reflect.DelegatingMethodAccessorImpl.invoke(DelegatingMethodAccessorImpl.java:25)
at TestSuiteDAO.main(TestSuiteDAO.java:20)


Name and version of the database you are using:
MySQL 4.1

Debug level Hibernate log excerpt:
11:47:42,339 INFO Environment:464 - Hibernate 3.0.5
11:47:42,349 INFO Environment:477 - hibernate.properties not found
11:47:42,359 INFO Environment:510 - using CGLIB reflection optimizer
11:47:42,359 INFO Environment:540 - using JDK 1.4 java.sql.Timestamp handling
11:47:42,459 DEBUG DTDEntityResolver:42 - trying to locate http://hibernate.sourceforge.net/hibern ... ng-3.0.dtd in classpath under org/hibernate/
11:47:42,459 DEBUG DTDEntityResolver:53 - found http://hibernate.sourceforge.net/hibern ... ng-3.0.dtd in classpath
11:47:42,589 INFO HbmBinder:260 - Mapping class: Source -> SOURCE
11:47:42,589 DEBUG HbmBinder:1099 - Mapped property: id -> SOURCE_ID
11:47:42,629 DEBUG HbmBinder:1099 - Mapped property: name -> NAME
11:47:42,629 DEBUG HbmBinder:1099 - Mapped property: type -> SOURCE_TYPE
11:47:42,629 INFO HbmBinder:260 - Mapping class: Target -> TARGET
11:47:42,629 DEBUG HbmBinder:1099 - Mapped property: id -> TARGET_ID
11:47:42,629 DEBUG HbmBinder:1099 - Mapped property: name -> NAME
11:47:42,639 INFO HbmBinder:260 - Mapping class: Mapping -> MAPPING_TYPE
11:47:42,639 DEBUG HbmBinder:1099 - Mapped property: id -> MAPPING_TYPE_ID
11:47:42,639 DEBUG HbmBinder:1099 - Mapped property: mappingType -> MAPPING_TYPE
11:47:42,649 INFO HbmBinder:1218 - Mapping collection: Mapping.source2target -> MAPPINGS
11:47:42,649 DEBUG HbmBinder:1099 - Mapped property: source2target
11:47:42,649 DEBUG Configuration:998 - Preparing to build session factory with filters : {}
11:47:42,649 INFO Configuration:875 - processing extends queue
11:47:42,649 INFO Configuration:879 - processing collection mappings
11:47:42,649 DEBUG HbmBinder:2466 - Second pass for collection: Mapping.source2target
11:47:42,719 DEBUG HbmBinder:2482 - Mapped collection key: MAPPING_TYPE_ID, index: SOURCE_ID, element: TARGET_ID
11:47:42,719 INFO Configuration:888 - processing association property references
11:47:42,719 INFO Configuration:917 - processing foreign key constraints
11:47:42,719 DEBUG Configuration:964 - resolving reference to class: Target
11:47:42,719 DEBUG Configuration:964 - resolving reference to class: Source
11:47:42,719 DEBUG Configuration:964 - resolving reference to class: Mapping
11:47:42,729 INFO ConnectionProviderFactory:53 - Initializing connection provider: org.springframework.orm.hibernate3.LocalDataSourceConnectionProvider
11:47:42,959 INFO SettingsFactory:77 - RDBMS: MySQL, version: 4.1.10-nt
11:47:42,959 INFO SettingsFactory:78 - JDBC driver: MySQL-AB JDBC Driver, version: mysql-connector-java-3.1.7 ( $Date: 2005/01/25 19:11:41 $, $Revision: 1.27.4.54 $ )
11:47:42,989 INFO Dialect:92 - Using dialect: org.hibernate.dialect.MySQLDialect
11:47:42,989 INFO TransactionFactoryFactory:31 - Using default transaction strategy (direct JDBC transactions)
11:47:42,999 INFO TransactionManagerLookupFactory:33 - No TransactionManagerLookup configured (in JTA environment, use of read-write or transactional second-level cache is not recommended)
11:47:42,999 INFO SettingsFactory:125 - Automatic flush during beforeCompletion(): disabled
11:47:42,999 INFO SettingsFactory:129 - Automatic session close at end of transaction: disabled
11:47:42,999 INFO SettingsFactory:136 - JDBC batch size: 15
11:47:42,999 INFO SettingsFactory:139 - JDBC batch updates for versioned data: disabled
11:47:42,999 INFO SettingsFactory:144 - Scrollable result sets: enabled
11:47:42,999 DEBUG SettingsFactory:148 - Wrap result sets: disabled
11:47:43,009 INFO SettingsFactory:152 - JDBC3 getGeneratedKeys(): enabled
11:47:43,009 INFO SettingsFactory:160 - Connection release mode: null
11:47:43,009 INFO SettingsFactory:184 - Maximum outer join fetch depth: 2
11:47:43,009 INFO SettingsFactory:187 - Default batch fetch size: 1
11:47:43,009 INFO SettingsFactory:191 - Generate SQL with comments: disabled
11:47:43,009 INFO SettingsFactory:195 - Order SQL updates by primary key: disabled
11:47:43,009 INFO SettingsFactory:334 - Query translator: org.hibernate.hql.ast.ASTQueryTranslatorFactory
11:47:43,019 INFO ASTQueryTranslatorFactory:20 - Using ASTQueryTranslatorFactory
11:47:43,019 INFO SettingsFactory:203 - Query language substitutions: {}
11:47:43,019 INFO SettingsFactory:209 - Second-level cache: enabled
11:47:43,019 INFO SettingsFactory:213 - Query cache: disabled
11:47:43,019 INFO SettingsFactory:321 - Cache provider: org.hibernate.cache.EhCacheProvider
11:47:43,019 INFO SettingsFactory:228 - Optimize cache for minimal puts: disabled
11:47:43,019 INFO SettingsFactory:237 - Structured second-level cache entries: disabled
11:47:43,029 DEBUG SQLExceptionConverterFactory:52 - Using dialect defined converter
11:47:43,029 INFO SettingsFactory:261 - Statistics: disabled
11:47:43,029 INFO SettingsFactory:265 - Deleted entity synthetic identifier rollback: disabled
11:47:43,029 INFO SettingsFactory:279 - Default entity-mode: pojo
11:47:43,150 INFO SessionFactoryImpl:152 - building session factory
11:47:43,150 DEBUG SessionFactoryImpl:161 - Session factory constructed with filter configurations : {}
11:47:43,160 DEBUG SessionFactoryImpl:164 - instantiating session factory with properties: {java.runtime.name=Java(TM) 2 Runtime Environment, Standard Edition, sun.boot.library.path=F:\jdk1.4.2_05\jre\bin, java.vm.version=10.1.3.55 (040719.1509) dop5, java.vm.vendor=Oracle Corp., java.vendor.url=http://java.sun.com/, path.separator=;, java.vm.name=OJVM Client VM, file.encoding.pkg=sun.io, user.country=GB, sun.os.patch.level=Service Pack 1, java.vm.vendor.url=http://www.oracle.com/, java.vm.specification.name=Java Virtual Machine Specification, user.dir=F:\My Documents\Test Hibernate\Project1, java.runtime.version=1.4.2_05-b04, java.awt.graphicsenv=sun.awt.Win32GraphicsEnvironment, java.endorsed.dirs=F:\jdk1.4.2_05\jre\lib\endorsed, os.arch=x86, java.io.tmpdir=d:\DOCUME~1\702972~1\LOCALS~1\Temp\, line.separator=
, java.vm.specification.vendor=Sun Microsystems Inc., user.variant=, os.name=Windows XP, sun.java2d.fontpath=, java.library.path=C:\oracle\ora92\bin;C:\Program Files\Oracle\jre\1.3.1\bin;C:\Program Files\Oracle\jre\1.1.8\bin;C:\HYPERION\ESSBASE\BIN;C:\WINDOWS\system32;C:\WINDOWS;C:\WINDOWS\System32\Wbem;C:\WINDOWS\system32\nls;C:\WINDOWS\system32\nls\ENGLISH;C:\Program Files\Attachmate\E!E2K\;c:\jdk1.3.1\bin;Z:.;, java.specification.name=Java Platform API Specification, java.class.version=48.0, java.util.prefs.PreferencesFactory=java.util.prefs.WindowsPreferencesFactory, os.version=5.1, user.home=d:\documents and settings\702972421, user.timezone=Europe/London, java.awt.printerjob=sun.awt.windows.WPrinterJob, file.encoding=Cp1252, java.specification.version=1.4, user.name=702972421, java.class.path=F:\My Documents\Test Hibernate\Project1\classes;F:\Frameworks\hibernate-3.0\hibernate3.jar;F:\Frameworks\hibernate-3.0\lib\ehcache-1.1.jar;F:\Frameworks\hibernate-3.0\lib\jta.jar;F:\Frameworks\hibernate-3.0\lib\dom4j-1.6.jar;F:\Frameworks\hibernate-3.0\lib\cglib-2.1.jar;F:\Frameworks\hibernate-3.0\lib\asm-attrs.jar;F:\Frameworks\hibernate-3.0\lib\asm.jar;F:\Frameworks\hibernate-3.0\lib\antlr-2.7.5H3.jar;F:\Frameworks\junit3.8.1\junit.jar;F:\Frameworks\mysql-connector-java-3.1.7\mysql-connector-java-3.1.7-bin.jar;F:\Frameworks\spring-framework-1.2.1\dist\spring-core.jar;F:\Frameworks\spring-framework-1.2.1\dist\spring-beans.jar;F:\Frameworks\spring-framework-1.2.1\dist\spring-context.jar;F:\Frameworks\spring-framework-1.2.1\dist\spring-jdbc.jar;F:\Frameworks\spring-framework-1.2.1\dist\spring-dao.jar;F:\Frameworks\spring-framework-1.2.1\dist\spring-orm.jar;F:\Frameworks\spring-framework-1.2.1\dist\spring-hibernate.jar;F:\Frameworks\dbunit-2.1\dbunit-2.1.jar;F:\Frameworks\logging-log4j-1.2.11\dist\lib\log4j-1.2.11.jar;F:\JDev1013\jakarta-taglibs\commons-logging-1.0.3\commons-logging-api.jar;F:\JDev1013\jakarta-taglibs\commons-logging-1.0.3\commons-logging.jar;F:\Frameworks\commons-lang-2.0\commons-lang-2.0.jar;F:\JDev1013\jakarta-taglibs\commons-beanutils-1.6.1\commons-beanutils.jar;F:\JDev1013\jakarta-taglibs\commons-collections-2.1\commons-collections.jar;F:\JDev1013\jakarta-taglibs\commons-digester-1.5\commons-digester.jar, java.vm.specification.version=1.0, sun.java.command=TestSuiteDAO --create, sun.arch.data.model=32, java.home=F:\jdk1.4.2_05\jre, hibernate.dialect=org.hibernate.dialect.MySQLDialect, user.language=en, java.specification.vendor=Sun Microsystems Inc., awt.toolkit=sun.awt.windows.WToolkit, hibernate.cglib.use_reflection_optimizer=true, java.vm.info=Copyright (c) 1998-2004 Oracle Corp., nojit, java.version=1.4.2_05, java.ext.dirs=F:\jdk1.4.2_05\jre\lib\ext, sun.boot.class.path=F:\jdk1.4.2_05\jre\lib\rt.jar;F:\jdk1.4.2_05\jre\lib\i18n.jar;F:\jdk1.4.2_05\jre\lib\sunrsasign.jar;F:\jdk1.4.2_05\jre\lib\jsse.jar;F:\jdk1.4.2_05\jre\lib\jce.jar;F:\jdk1.4.2_05\jre\lib\charsets.jar;F:\jdk1.4.2_05\jre\classes, java.vendor=Sun Microsystems Inc., file.separator=\, hibernate.connection.provider_class=org.springframework.orm.hibernate3.LocalDataSourceConnectionProvider, java.vendor.url.bug=http://java.sun.com/cgi-bin/bugreport.cgi, java.compiler=NONE, sun.io.unicode.encoding=UnicodeLittle, sun.cpu.endian=little, sun.cpu.isalist=pentium i486 i386}
11:47:43,170 WARN Configurator:126 - No configuration found. Configuring ehcache from ehcache-failsafe.xml found in the classpath: jar:file:/F:/Frameworks/hibernate-3.0/lib/ehcache-1.1.jar!/ehcache-failsafe.xml
11:47:43,560 DEBUG BasicEntityPersister:2220 - Static SQL for entity: Mapping
11:47:43,560 DEBUG BasicEntityPersister:2222 - Version select: select MAPPING_TYPE_ID from MAPPING_TYPE where MAPPING_TYPE_ID =?
11:47:43,560 DEBUG BasicEntityPersister:2223 - Snapshot select: select mapping_.MAPPING_TYPE_ID, mapping_.MAPPING_TYPE as MAPPING2_2_ from MAPPING_TYPE mapping_ where mapping_.MAPPING_TYPE_ID=?
11:47:43,560 DEBUG BasicEntityPersister:2225 - Insert 0: insert into MAPPING_TYPE (MAPPING_TYPE, MAPPING_TYPE_ID) values (?, ?)
11:47:43,560 DEBUG BasicEntityPersister:2226 - Update 0: update MAPPING_TYPE set MAPPING_TYPE=? where MAPPING_TYPE_ID=?
11:47:43,560 DEBUG BasicEntityPersister:2227 - Delete 0: delete from MAPPING_TYPE where MAPPING_TYPE_ID=?
11:47:43,570 DEBUG BasicEntityPersister:2230 - Identity insert: insert into MAPPING_TYPE (MAPPING_TYPE) values (?)
11:47:43,590 DEBUG BasicEntityPersister:2220 - Static SQL for entity: Source
11:47:43,590 DEBUG BasicEntityPersister:2222 - Version select: select SOURCE_ID from SOURCE where SOURCE_ID =?
11:47:43,590 DEBUG BasicEntityPersister:2223 - Snapshot select: select source_.SOURCE_ID, source_.NAME as NAME0_, source_.SOURCE_TYPE as SOURCE3_0_ from SOURCE source_ where source_.SOURCE_ID=?
11:47:43,590 DEBUG BasicEntityPersister:2225 - Insert 0: insert into SOURCE (NAME, SOURCE_TYPE, SOURCE_ID) values (?, ?, ?)
11:47:43,590 DEBUG BasicEntityPersister:2226 - Update 0: update SOURCE set NAME=?, SOURCE_TYPE=? where SOURCE_ID=?
11:47:43,590 DEBUG BasicEntityPersister:2227 - Delete 0: delete from SOURCE where SOURCE_ID=?
11:47:43,590 DEBUG BasicEntityPersister:2230 - Identity insert: insert into SOURCE (NAME, SOURCE_TYPE) values (?, ?)
11:47:43,620 DEBUG BasicEntityPersister:2220 - Static SQL for entity: Target
11:47:43,620 DEBUG BasicEntityPersister:2222 - Version select: select TARGET_ID from TARGET where TARGET_ID =?
11:47:43,620 DEBUG BasicEntityPersister:2223 - Snapshot select: select target_.TARGET_ID, target_.NAME as NAME1_ from TARGET target_ where target_.TARGET_ID=?
11:47:43,620 DEBUG BasicEntityPersister:2225 - Insert 0: insert into TARGET (NAME, TARGET_ID) values (?, ?)
11:47:43,620 DEBUG BasicEntityPersister:2226 - Update 0: update TARGET set NAME=? where TARGET_ID=?
11:47:43,620 DEBUG BasicEntityPersister:2227 - Delete 0: delete from TARGET where TARGET_ID=?
11:47:43,620 DEBUG BasicEntityPersister:2230 - Identity insert: insert into TARGET (NAME) values (?)
11:47:43,630 DEBUG AbstractCollectionPersister:479 - Static SQL for collection: Mapping.source2target
11:47:43,630 DEBUG AbstractCollectionPersister:480 - Row insert: insert into MAPPINGS (MAPPING_TYPE_ID, SOURCE_ID, TARGET_ID) values (?, ?, ?)
11:47:43,630 DEBUG AbstractCollectionPersister:481 - Row update: update MAPPINGS set TARGET_ID=? where MAPPING_TYPE_ID=? and SOURCE_ID=?
11:47:43,640 DEBUG AbstractCollectionPersister:482 - Row delete: delete from MAPPINGS where MAPPING_TYPE_ID=? and SOURCE_ID=?
11:47:43,640 DEBUG AbstractCollectionPersister:483 - One-shot delete: delete from MAPPINGS where MAPPING_TYPE_ID=?
11:47:43,670 DEBUG EntityLoader:95 - Static select for entity Mapping: select mapping0_.MAPPING_TYPE_ID as MAPPING1_0_, mapping0_.MAPPING_TYPE as MAPPING2_2_0_ from MAPPING_TYPE mapping0_ where mapping0_.MAPPING_TYPE_ID=?
11:47:43,670 DEBUG EntityLoader:95 - Static select for entity Mapping: select mapping0_.MAPPING_TYPE_ID as MAPPING1_0_, mapping0_.MAPPING_TYPE as MAPPING2_2_0_ from MAPPING_TYPE mapping0_ where mapping0_.MAPPING_TYPE_ID=?
11:47:43,670 DEBUG EntityLoader:95 - Static select for entity Mapping: select mapping0_.MAPPING_TYPE_ID as MAPPING1_0_, mapping0_.MAPPING_TYPE as MAPPING2_2_0_ from MAPPING_TYPE mapping0_ where mapping0_.MAPPING_TYPE_ID=? for update
11:47:43,670 DEBUG EntityLoader:95 - Static select for entity Mapping: select mapping0_.MAPPING_TYPE_ID as MAPPING1_0_, mapping0_.MAPPING_TYPE as MAPPING2_2_0_ from MAPPING_TYPE mapping0_ where mapping0_.MAPPING_TYPE_ID=? for update
11:47:43,670 DEBUG EntityLoader:95 - Static select for entity Source: select source0_.SOURCE_ID as SOURCE1_0_, source0_.NAME as NAME0_0_, source0_.SOURCE_TYPE as SOURCE3_0_0_ from SOURCE source0_ where source0_.SOURCE_ID=?
11:47:43,670 DEBUG EntityLoader:95 - Static select for entity Source: select source0_.SOURCE_ID as SOURCE1_0_, source0_.NAME as NAME0_0_, source0_.SOURCE_TYPE as SOURCE3_0_0_ from SOURCE source0_ where source0_.SOURCE_ID=?
11:47:43,670 DEBUG EntityLoader:95 - Static select for entity Source: select source0_.SOURCE_ID as SOURCE1_0_, source0_.NAME as NAME0_0_, source0_.SOURCE_TYPE as SOURCE3_0_0_ from SOURCE source0_ where source0_.SOURCE_ID=? for update
11:47:43,680 DEBUG EntityLoader:95 - Static select for entity Source: select source0_.SOURCE_ID as SOURCE1_0_, source0_.NAME as NAME0_0_, source0_.SOURCE_TYPE as SOURCE3_0_0_ from SOURCE source0_ where source0_.SOURCE_ID=? for update
11:47:43,680 DEBUG EntityLoader:95 - Static select for entity Target: select target0_.TARGET_ID as TARGET1_0_, target0_.NAME as NAME1_0_ from TARGET target0_ where target0_.TARGET_ID=?
11:47:43,680 DEBUG EntityLoader:95 - Static select for entity Target: select target0_.TARGET_ID as TARGET1_0_, target0_.NAME as NAME1_0_ from TARGET target0_ where target0_.TARGET_ID=?
11:47:43,680 DEBUG EntityLoader:95 - Static select for entity Target: select target0_.TARGET_ID as TARGET1_0_, target0_.NAME as NAME1_0_ from TARGET target0_ where target0_.TARGET_ID=? for update
11:47:43,680 DEBUG EntityLoader:95 - Static select for entity Target: select target0_.TARGET_ID as TARGET1_0_, target0_.NAME as NAME1_0_ from TARGET target0_ where target0_.TARGET_ID=? for update
11:47:43,690 DEBUG CollectionLoader:94 - Static select for collection Mapping.source2target: select source2tar0_.MAPPING_TYPE_ID as MAPPING1_1_, source2tar0_.TARGET_ID as TARGET2_1_, source2tar0_.SOURCE_ID as SOURCE3_1_, target1_.TARGET_ID as TARGET1_0_, target1_.NAME as NAME1_0_ from MAPPINGS source2tar0_ inner join TARGET target1_ on source2tar0_.TARGET_ID=target1_.TARGET_ID where source2tar0_.MAPPING_TYPE_ID=?
11:47:43,700 DEBUG SessionFactoryObjectFactory:39 - initializing class SessionFactoryObjectFactory
11:47:43,700 DEBUG SessionFactoryObjectFactory:76 - registered: 8a6ece4504ccdbf00104ccdbf34a0000 (unnamed)
11:47:43,700 INFO SessionFactoryObjectFactory:82 - Not binding factory to JNDI, no JNDI name configured
11:47:43,700 DEBUG SessionFactoryImpl:262 - instantiated session factory
11:47:43,700 INFO SessionFactoryImpl:379 - Checking 0 named queries
11:47:43,761 INFO Dialect:92 - Using dialect: org.hibernate.dialect.MySQLDialect
11:47:43,761 INFO Configuration:875 - processing extends queue
11:47:43,761 INFO Configuration:879 - processing collection mappings
11:47:43,761 INFO Configuration:888 - processing association property references
11:47:43,761 INFO Configuration:917 - processing foreign key constraints
11:47:43,761 DEBUG Configuration:964 - resolving reference to class: Target
11:47:43,761 DEBUG Configuration:964 - resolving reference to class: Source
11:47:43,761 DEBUG Configuration:964 - resolving reference to class: Mapping
11:47:44,001 INFO Configuration:875 - processing extends queue
11:47:44,001 INFO Configuration:879 - processing collection mappings
11:47:44,001 INFO Configuration:888 - processing association property references
11:47:44,001 INFO Configuration:917 - processing foreign key constraints
11:47:44,001 DEBUG Configuration:964 - resolving reference to class: Target
11:47:44,001 DEBUG Configuration:964 - resolving reference to class: Source
11:47:44,001 DEBUG Configuration:964 - resolving reference to class: Mapping
11:47:44,572 DEBUG SessionImpl:250 - opened session at timestamp: 4588046190723072
11:47:44,592 DEBUG SessionImpl:250 - opened session at timestamp: 4588046190968832
11:47:44,592 DEBUG SessionImpl:212 - opened session [dom4j]
11:47:44,612 DEBUG SessionImpl:829 - find: from Mapping
11:47:44,612 DEBUG QueryParameters:224 - named parameters: {}
11:47:44,682 DEBUG QueryTranslatorImpl:207 - parse() - HQL: from Mapping
11:47:44,692 DEBUG AST:223 - --- HQL AST ---
\-[QUERY] 'query'
\-[SELECT_FROM] 'SELECT_FROM'
\-[FROM] 'from'
\-[RANGE] 'RANGE'
\-[IDENT] 'Mapping'

11:47:44,692 DEBUG ErrorCounter:72 - throwQueryException() : no errors
11:47:44,732 DEBUG HqlSqlBaseWalker:120 - query() << begin, level = 1
11:47:44,762 DEBUG FromElement:88 - FromClause{level=1} : Mapping (no alias) -> mapping0_
11:47:44,762 DEBUG HqlSqlBaseWalker:125 - query() : finishing up , level = 1
11:47:44,762 DEBUG HqlSqlWalker:331 - processQuery() : ( SELECT ( FromClause{level=1} MAPPING_TYPE mapping0_ ) )
11:47:44,772 DEBUG HqlSqlWalker:451 - Derived SELECT clause created.
11:47:44,782 DEBUG JoinProcessor:112 - Using FROM fragment [MAPPING_TYPE mapping0_]
11:47:44,782 DEBUG HqlSqlBaseWalker:128 - query() >> end, level = 1
11:47:44,792 DEBUG AST:193 - --- SQL AST ---
\-[SELECT] QueryNode: 'SELECT' querySpaces (MAPPING_TYPE)
+-[SELECT_CLAUSE] SelectClause: '{derived select clause}'
| +-[SELECT_EXPR] SelectExpressionImpl: 'mapping0_.MAPPING_TYPE_ID as MAPPING1_' {FromElement{explicit,not a collection join,not a fetch join,fetch non-lazy properties,classAlias=null,role=null,tableName=MAPPING_TYPE,tableAlias=mapping0_,colums={,className=Mapping}}}
| \-[SQL_TOKEN] SqlFragment: 'mapping0_.MAPPING_TYPE as MAPPING2_2_'
\-[FROM] FromClause: 'from' FromClause{level=1, fromElementCounter=1, fromElements=1, fromElementByClassAlias=[], fromElementByTableAlias=[mapping0_], fromElementsByPath=[], collectionJoinFromElementsByPath=[], impliedElements=[]}
\-[FROM_FRAGMENT] FromElement: 'MAPPING_TYPE mapping0_' FromElement{explicit,not a collection join,not a fetch join,fetch non-lazy properties,classAlias=null,role=null,tableName=MAPPING_TYPE,tableAlias=mapping0_,colums={,className=Mapping}}

11:47:44,792 DEBUG ErrorCounter:72 - throwQueryException() : no errors
11:47:44,802 DEBUG QueryTranslatorImpl:177 - HQL: from Mapping
11:47:44,802 DEBUG QueryTranslatorImpl:178 - SQL: select mapping0_.MAPPING_TYPE_ID as MAPPING1_, mapping0_.MAPPING_TYPE as MAPPING2_2_ from MAPPING_TYPE mapping0_
11:47:44,802 DEBUG ErrorCounter:72 - throwQueryException() : no errors
11:47:44,812 DEBUG AbstractBatcher:290 - about to open PreparedStatement (open PreparedStatements: 0, globally: 0)
11:47:44,812 DEBUG ConnectionManager:296 - opening JDBC connection
11:47:44,832 DEBUG SQL:324 - select mapping0_.MAPPING_TYPE_ID as MAPPING1_, mapping0_.MAPPING_TYPE as MAPPING2_2_ from MAPPING_TYPE mapping0_
11:47:44,832 DEBUG AbstractBatcher:378 - preparing statement
11:47:44,842 DEBUG AbstractBatcher:306 - about to open ResultSet (open ResultSets: 0, globally: 0)
11:47:44,842 DEBUG Loader:405 - processing result set
11:47:44,842 DEBUG Loader:410 - result set row: 0
11:47:44,842 DEBUG IntegerType:86 - returning '1' as column: MAPPING1_
11:47:44,852 DEBUG Loader:828 - result row: EntityKey[Mapping#1]
11:47:44,852 DEBUG Loader:978 - Initializing object from ResultSet: [Mapping#1]
11:47:44,862 DEBUG BasicEntityPersister:1651 - Hydrating entity: [Mapping#1]
11:47:44,862 DEBUG StringType:86 - returning 'Standard' as column: MAPPING2_2_
11:47:44,862 DEBUG Loader:429 - done processing result set (1 rows)
11:47:44,862 DEBUG AbstractBatcher:313 - about to close ResultSet (open ResultSets: 1, globally: 1)
11:47:44,862 DEBUG AbstractBatcher:298 - about to close PreparedStatement (open PreparedStatements: 1, globally: 1)
11:47:44,862 DEBUG AbstractBatcher:416 - closing statement
11:47:44,872 DEBUG Loader:528 - total objects hydrated: 1
11:47:44,872 DEBUG TwoPhaseLoad:96 - resolving associations for [Mapping#1]
11:47:44,882 DEBUG CollectionLoadContext:141 - creating collection wrapper:[Mapping.source2target#1]
11:47:44,892 DEBUG DefaultInitializeCollectionEventListener:42 - initializing collection [Mapping.source2target#1]
11:47:44,892 DEBUG DefaultInitializeCollectionEventListener:47 - checking second-level cache
11:47:44,892 DEBUG DefaultInitializeCollectionEventListener:59 - collection not cached
11:47:44,902 DEBUG Loader:1426 - loading collection: [Mapping.source2target#1]
11:47:44,902 DEBUG AbstractBatcher:290 - about to open PreparedStatement (open PreparedStatements: 0, globally: 0)
11:47:44,902 DEBUG SQL:324 - select source2tar0_.MAPPING_TYPE_ID as MAPPING1_1_, source2tar0_.TARGET_ID as TARGET2_1_, source2tar0_.SOURCE_ID as SOURCE3_1_, target1_.TARGET_ID as TARGET1_0_, target1_.NAME as NAME1_0_ from MAPPINGS source2tar0_ inner join TARGET target1_ on source2tar0_.TARGET_ID=target1_.TARGET_ID where source2tar0_.MAPPING_TYPE_ID=?
11:47:44,902 DEBUG AbstractBatcher:378 - preparing statement
11:47:44,902 DEBUG IntegerType:59 - binding '1' to parameter: 1
11:47:44,902 DEBUG AbstractBatcher:306 - about to open ResultSet (open ResultSets: 0, globally: 0)
11:47:44,912 DEBUG Loader:718 - result set contains (possibly empty) collection: [Mapping.source2target#1]
11:47:44,912 DEBUG CollectionLoadContext:85 - uninitialized collection: initializing
11:47:44,912 DEBUG Loader:405 - processing result set
11:47:44,912 DEBUG Loader:410 - result set row: 0
11:47:44,912 DEBUG IntegerType:86 - returning '1' as column: TARGET1_0_
11:47:44,912 DEBUG Loader:828 - result row: EntityKey[Target#1]
11:47:44,912 DEBUG Loader:978 - Initializing object from ResultSet: [Target#1]
11:47:44,912 DEBUG BasicEntityPersister:1651 - Hydrating entity: [Target#1]
11:47:44,912 DEBUG StringType:86 - returning 'LMN' as column: NAME1_0_
11:47:44,912 DEBUG IntegerType:86 - returning '1' as column: MAPPING1_1_
11:47:44,942 DEBUG Loader:654 - found row of collection: [Mapping.source2target#1]
11:47:44,942 DEBUG CollectionLoadContext:112 - reading row
11:47:44,942 DEBUG IntegerType:86 - returning '1' as column: TARGET2_1_
11:47:44,952 DEBUG IntegerType:86 - returning '1' as column: SOURCE3_1_
11:47:44,952 DEBUG DefaultLoadEventListener:143 - loading entity: [Source#1]
11:47:44,952 DEBUG DefaultLoadEventListener:216 - creating new proxy for entity
11:47:44,962 DEBUG AbstractBatcher:313 - about to close ResultSet (open ResultSets: 1, globally: 1)
11:47:44,962 DEBUG AbstractBatcher:298 - about to close PreparedStatement (open PreparedStatements: 1, globally: 1)
11:47:44,962 DEBUG AbstractBatcher:416 - closing statement
11:47:44,972 DEBUG JDBCContext:322 - after autocommit
11:47:44,972 DEBUG SessionImpl:403 - after transaction completion
11:47:44,972 DEBUG SessionImpl:269 - closing session