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

When initialising the 'access_numbers' table (detailed below) hibernate will only retrieve the 'profiles' for the first access number.

but all access numbers with the same customerId should have the same profiles.

Hibernate version:3


Mapping documents:
<hibernate-mapping>

<class name="com.AccessNumberImpl" table="access_numbers">
<id name="id" type="int" unsaved-value="-1">
<column name="id" sql-type="integer" not-null="true"/>
<generator class="native"/>
</id>

<property name="number" unique="true" not-null="true"/>
<property name="name"/>
<property name="customerId"/>
<property name="customerName" formula="(select c.name from customers c where c.id = customerId)"/>

<bag name="profiles"
inverse="false"
order-by="name"
lazy="false"
cascade="all">

<key column="id" unique="false"/>
<one-to-many class="com.ProfileImpl"/>

</bag>

</class>

</hibernate-mapping>

<hibernate-mapping>

<class name="com.rococosoft.c3.bus.ProfileImpl" table="profiles">
<id name="id" type="int" unsaved-value="-1">
<column name="id" sql-type="integer" not-null="true"/>
<generator class="native"/>
</id>

<property name="customerId"/>
<property name="customerName" formula="(select c.name from customers c where c.id = customerId)"/>
<property name="name" not-null="true"/>
<property name="description"/>

</class>

</hibernate-mapping>


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

Debug level Hibernate log excerpt:
2006-10-20 17:22:26,790 DEBUG [SessionFactoryUtils] Opening Hibernate Session
2006-10-20 17:22:26,790 DEBUG [SessionImpl] opened session at timestamp: 4756936076451840
2006-10-20 17:22:26,791 DEBUG [SessionImpl] find: from com. .c3.number.bus.AccessNumberImpl t order by t.customerName, t.name
2006-10-20 17:22:26,791 DEBUG [QueryParameters] named parameters: {}
2006-10-20 17:22:26,794 DEBUG [QueryTranslatorImpl] parse() - HQL: from com. .c3.number.bus.AccessNumberImpl t order by t.customerName, t.name
2006-10-20 17:22:26,795 DEBUG [AST] --- HQL AST ---
\-[QUERY] 'query'
+-[SELECT_FROM] 'SELECT_FROM'
| \-[FROM] 'from'
| \-[RANGE] 'RANGE'
| +-[DOT] '.'
| | +-[DOT] '.'
| | | +-[DOT] '.'
| | | | +-[DOT] '.'
| | | | | +-[DOT] '.'
| | | | | | +-[IDENT] 'com'
| | | | | | \-[IDENT] ' '
| | | | | \-[IDENT] 'c3'
| | | | \-[IDENT] 'number'
| | | \-[IDENT] 'bus'
| | \-[IDENT] 'AccessNumberImpl'
| \-[ALIAS] 't'
\-[ORDER] 'order'
+-[DOT] '.'
| +-[IDENT] 't'
| \-[IDENT] 'customerName'
\-[DOT] '.'
+-[IDENT] 't'
2006-10-20 17:22:26,795 DEBUG [ErrorCounter] throwQueryException() : no errors
2006-10-20 17:22:26,795 DEBUG [HqlSqlBaseWalker] query() << begin, level = 1
2006-10-20 17:22:26,796 DEBUG [FromElement] FromClause{level=1} : com. .c3.number.bus.AccessNumberImpl (t) -> accessnumb0_
2006-10-20 17:22:26,798 DEBUG [FromReferenceNode] Resolved : t -> accessnumb0_.id
2006-10-20 17:22:26,798 DEBUG [DotNode] getDataType() : customerName -> org.hibernate.type.StringType@65ca
2006-10-20 17:22:26,798 DEBUG [FromReferenceNode] Resolved : t.customerName -> (select c.name from customers c where c.id = accessnumb0_.customerId)
2006-10-20 17:22:26,798 DEBUG [FromReferenceNode] Resolved : t -> accessnumb0_.id
2006-10-20 17:22:26,798 DEBUG [DotNode] getDataType() : name -> org.hibernate.type.StringType@65ca
2006-10-20 17:22:26,798 DEBUG [FromReferenceNode] Resolved : t.name -> accessnumb0_.name
2006-10-20 17:22:26,798 DEBUG [HqlSqlBaseWalker] query() : finishing up , level = 1
2006-10-20 17:22:26,798 DEBUG [HqlSqlWalker] processQuery() : ( SELECT ( FromClause{level=1} access_numbers accessnumb0_ ) ( order ( (select c.name from customers c where c.id = accessnumb0_.customerId) accessnumb0_.id customerName ) ( accessnumb0_.name accessnumb0_.id name ) ) )
2006-10-20 17:22:26,799 DEBUG [HqlSqlWalker] Derived SELECT clause created.
2006-10-20 17:22:26,799 DEBUG [JoinProcessor] Using FROM fragment [access_numbers accessnumb0_]
2006-10-20 17:22:26,799 DEBUG [HqlSqlBaseWalker] query() >> end, level = 1
2006-10-20 17:22:26,803 DEBUG [ConnectionManager] running Session.finalize()
2006-10-20 17:22:26,803 DEBUG [ConnectionManager] running Session.finalize()
2006-10-20 17:22:26,803 DEBUG [AST] --- SQL AST ---
\-[SELECT] QueryNode: 'SELECT' querySpaces (access_numbers)
+-[SELECT_CLAUSE] SelectClause: '{derived select clause}'
| +-[SELECT_EXPR] SelectExpressionImpl: 'accessnumb0_.id as id' {FromElement{explicit,not a collection join,not a fetch join,fetch non-lazy properties,classAlias=t,role=null,tableName=access_numbers,tableAlias=accessnumb0_,colums={,className=com. .c3.number.bus.AccessNumberImpl}}}
| \-[SQL_TOKEN] SqlFragment: 'accessnumb0_.number as number1_, accessnumb0_.name as name1_, accessnumb0_.description as descript4_1_, accessnumb0_.customerId as customerId1_, accessnumb0_.active_profile_id as active6_1_, accessnumb0_.actionType as actionType1_, accessnumb0_.actionName as actionName1_, (select c.name from customers c where c.id = accessnumb0_.customerId) as formula0_'
+-[FROM] FromClause: 'from' FromClause{level=1, fromElementCounter=1, fromElements=1, fromElementByClassAlias=[t], fromElementByTableAlias=[accessnumb0_], fromElementsByPath=[], collectionJoinFromElementsByPath=[], impliedElements=[]}
| \-[FROM_FRAGMENT] FromElement: 'access_numbers accessnumb0_' FromElement{explicit,not a collection join,not a fetch join,fetch non-lazy properties,classAlias=t,role=null,tableName=access_numbers,tableAlias=accessnumb0_,colums={,className=com. .c3.number.bus.AccessNumberImpl}}
\-[ORDER] OrderByClause: 'order'
+-[DOT] DotNode: '(select c.name from customers c where c.id = accessnumb0_.customerId)' {propertyName=customerName,dereferenceType=4,propertyPath=customerName,path=t.customerName,tableAlias=accessnumb0_,className=com. .c3.number.bus.AccessNumberImpl,classAlias=t}
| +-[ALIAS_REF] IdentNode: 'accessnumb0_.id' {alias=t, className=com. .c3.number.bus.AccessNumberImpl, tableAlias=accessnumb0_}
| \-[IDENT] IdentNode: 'customerName' {originalText=customerName}
\-[DOT] DotNode: 'accessnumb0_.name' {propertyName=name,dereferenceType=4,propertyPath=name,path=t.name,tableAlias=accessnumb0_,className=com. .c3.number.bus.AccessNumberImpl,classAlias=t}
+-[ALIAS_REF] IdentNode: 'accessnumb0_.id' {alias=t, className=com. .c3.number.bus.AccessNumberImpl, tableAlias=accessnumb0_}
\-[IDENT] IdentNode: 'name' {originalText=name}

2006-10-20 17:22:26,803 DEBUG [ErrorCounter] throwQueryException() : no errors
2006-10-20 17:22:26,803 DEBUG [QueryTranslatorImpl] HQL: from com. .c3.number.bus.AccessNumberImpl t order by t.customerName, t.name
2006-10-20 17:22:26,803 DEBUG [QueryTranslatorImpl] SQL: select accessnumb0_.id as id, accessnumb0_.number as number1_, accessnumb0_.name as name1_, accessnumb0_.description as descript4_1_, accessnumb0_.customerId as customerId1_, accessnumb0_.active_profile_id as active6_1_, accessnumb0_.actionType as actionType1_, accessnumb0_.actionName as actionName1_, (select c.name from customers c where c.id = accessnumb0_.customerId) as formula0_ from access_numbers accessnumb0_ order by (select c.name from customers c where c.id = accessnumb0_.customerId), accessnumb0_.name
2006-10-20 17:22:26,803 DEBUG [ErrorCounter] throwQueryException() : no errors
2006-10-20 17:22:26,803 DEBUG [StandardQueryCache] checking cached query results in region: org.hibernate.cache.StandardQueryCache
2006-10-20 17:22:26,803 DEBUG [EhCache] key: sql: select accessnumb0_.id as id, accessnumb0_.number as number1_, accessnumb0_.name as name1_, accessnumb0_.description as descript4_1_, accessnumb0_.customerId as customerId1_, accessnumb0_.active_profile_id as active6_1_, accessnumb0_.actionType as actionType1_, accessnumb0_.actionName as actionName1_, (select c.name from customers c where c.id = accessnumb0_.customerId) as formula0_ from access_numbers accessnumb0_ order by (select c.name from customers c where c.id = accessnumb0_.customerId), accessnumb0_.name; parameters: ; named parameters: {}; first row: 0; max rows: 20
2006-10-20 17:22:26,803 DEBUG [MemoryStore] org.hibernate.cache.StandardQueryCacheCache: MemoryStore miss for sql: select accessnumb0_.id as id, accessnumb0_.number as number1_, accessnumb0_.name as name1_, accessnumb0_.description as descript4_1_, accessnumb0_.customerId as customerId1_, accessnumb0_.active_profile_id as active6_1_, accessnumb0_.actionType as actionType1_, accessnumb0_.actionName as actionName1_, (select c.name from customers c where c.id = accessnumb0_.customerId) as formula0_ from access_numbers accessnumb0_ order by (select c.name from customers c where c.id = accessnumb0_.customerId), accessnumb0_.name; parameters: ; named parameters: {}; first row: 0; max rows: 20
2006-10-20 17:22:26,803 DEBUG [Cache] org.hibernate.cache.StandardQueryCache cache - Miss
2006-10-20 17:22:26,803 DEBUG [EhCache] Element for sql: select accessnumb0_.id as id, accessnumb0_.number as number1_, accessnumb0_.name as name1_, accessnumb0_.description as descript4_1_, accessnumb0_.customerId as customerId1_, accessnumb0_.active_profile_id as active6_1_, accessnumb0_.actionType as actionType1_, accessnumb0_.actionName as actionName1_, (select c.name from customers c where c.id = accessnumb0_.customerId) as formula0_ from access_numbers accessnumb0_ order by (select c.name from customers c where c.id = accessnumb0_.customerId), accessnumb0_.name; parameters: ; named parameters: {}; first row: 0; max rows: 20 is null
2006-10-20 17:22:26,803 DEBUG [StandardQueryCache] query results were not found in cache
2006-10-20 17:22:26,804 DEBUG [AbstractBatcher] about to open PreparedStatement (open PreparedStatements: 0, globally: 0)
2006-10-20 17:22:26,804 DEBUG [ConnectionManager] opening JDBC connection
2006-10-20 17:22:26,804 DEBUG [SQL] select accessnumb0_.id as id, accessnumb0_.number as number1_, accessnumb0_.name as name1_, accessnumb0_.description as descript4_1_, accessnumb0_.customerId as customerId1_, accessnumb0_.active_profile_id as active6_1_, accessnumb0_.actionType as actionType1_, accessnumb0_.actionName as actionName1_, (select c.name from customers c where c.id = accessnumb0_.customerId) as formula0_ from access_numbers accessnumb0_ order by (select c.name from customers c where c.id = accessnumb0_.customerId), accessnumb0_.name limit ?
2006-10-20 17:22:26,804 DEBUG [AbstractBatcher] preparing statement
2006-10-20 17:22:26,827 DEBUG [AbstractBatcher] about to open ResultSet (open ResultSets: 0, globally: 0)
2006-10-20 17:22:26,827 DEBUG [Loader] processing result set
2006-10-20 17:22:26,827 DEBUG [Loader] result set row: 0
2006-10-20 17:22:26,827 DEBUG [IntegerType] returning '1' as column: id
2006-10-20 17:22:26,827 DEBUG [Loader] result row: EntityKey[com. .c3.number.bus.AccessNumberImpl#1]
2006-10-20 17:22:26,827 DEBUG [Loader] Initializing object from ResultSet: [com. .c3.number.bus.AccessNumberImpl#1]
2006-10-20 17:22:26,827 DEBUG [BasicEntityPersister] Hydrating entity: [com. .c3.number.bus.AccessNumberImpl#1]
2006-10-20 17:22:26,827 DEBUG [StringType] returning '18002423461622' as column: number1_
2006-10-20 17:22:26,828 DEBUG [StringType] returning 'eircom_access1' as column: name1_
2006-10-20 17:22:26,828 DEBUG [StringType] returning '' as column: descript4_1_
2006-10-20 17:22:26,828 DEBUG [IntegerType] returning '1' as column: customerId1_
2006-10-20 17:22:26,827 DEBUG [Loader] result row: EntityKey[com. .c3.number.bus.AccessNumberImpl#1]
2006-10-20 17:22:26,827 DEBUG [Loader] Initializing object from ResultSet: [com. .c3.number.bus.AccessNumberImpl#1]
2006-10-20 17:22:26,827 DEBUG [BasicEntityPersister] Hydrating entity: [com. .c3.number.bus.AccessNumberImpl#1]
2006-10-20 17:22:26,827 DEBUG [StringType] returning '18002423461622' as column: number1_
2006-10-20 17:22:26,828 DEBUG [StringType] returning 'eircom_access1' as column: name1_
2006-10-20 17:22:26,828 DEBUG [StringType] returning '' as column: descript4_1_
2006-10-20 17:22:26,828 DEBUG [IntegerType] returning '1' as column: customerId1_
2006-10-20 17:22:26,828 DEBUG [StringType] returning 'eircom' as column: formula0_
2006-10-20 17:22:26,828 DEBUG [IntegerType] returning '1' as column: active6_1_
2006-10-20 17:22:26,828 DEBUG [StringType] returning 'call_center' as column: actionType1_
2006-10-20 17:22:26,828 DEBUG [StringType] returning 'work' as column: actionName1_
2006-10-20 17:22:26,828 DEBUG [Loader] result set row: 1
2006-10-20 17:22:26,828 DEBUG [IntegerType] returning '2' as column: id
2006-10-20 17:22:26,828 DEBUG [Loader] result row: EntityKey[com. .c3.number.bus.AccessNumberImpl#2]
2006-10-20 17:22:26,828 DEBUG [Loader] Initializing object from ResultSet: [com. .c3.number.bus.AccessNumberImpl#2]
2006-10-20 17:22:26,828 DEBUG [BasicEntityPersister] Hydrating entity: [com. .c3.number.bus.AccessNumberImpl#2]
2006-10-20 17:22:26,828 DEBUG [StringType] returning '18002423461621' as column: number1_
2006-10-20 17:22:26,828 DEBUG [StringType] returning 'eircom_access2' as column: name1_
2006-10-20 17:22:26,828 DEBUG [StringType] returning '' as column: descript4_1_
2006-10-20 17:22:26,828 DEBUG [IntegerType] returning '1' as column: customerId1_
2006-10-20 17:22:26,828 DEBUG [StringType] returning 'eircom' as column: formula0_
2006-10-20 17:22:26,828 DEBUG [IntegerType] returning null as column: active6_1_
2006-10-20 17:22:26,829 DEBUG [StringType] returning 'call_center' as column: actionType1_
2006-10-20 17:22:26,829 DEBUG [StringType] returning 'work' as column: actionName1_
2006-10-20 17:22:26,829 DEBUG [Loader] done processing result set (2 rows)
2006-10-20 17:22:26,829 DEBUG [AbstractBatcher] about to close ResultSet (open ResultSets: 1, globally: 1)
2006-10-20 17:22:26,829 DEBUG [AbstractBatcher] about to close PreparedStatement (open PreparedStatements: 1, globally: 1)
2006-10-20 17:22:26,829 DEBUG [AbstractBatcher] closing statement
2006-10-20 17:22:26,829 DEBUG [Loader] total objects hydrated: 2
2006-10-20 17:22:26,829 DEBUG [TwoPhaseLoad] resolving associations for [com. .c3.number.bus.AccessNumberImpl#1]
2006-10-20 17:22:26,829 DEBUG [DefaultLoadEventListener] loading entity: [com. .c3.bus.ProfileImpl#1]
2006-10-20 17:22:26,829 DEBUG [DefaultLoadEventListener] attempting to resolve: [com. .c3.bus.ProfileImpl#1]
2006-10-20 17:22:26,829 DEBUG [DefaultLoadEventListener] object not resolved in any cache: [com. .c3.bus.ProfileImpl#1]
2006-10-20 17:22:26,829 DEBUG [BasicEntityPersister] Materializing entity: [com. .c3.bus.ProfileImpl#1]
2006-10-20 17:22:26,829 DEBUG [Loader] loading entity: [com. .c3.bus.ProfileImpl#1]
2006-10-20 17:22:26,829 DEBUG [AbstractBatcher] about to open PreparedStatement (open PreparedStatements: 0, globally: 0)
2006-10-20 17:22:26,829 DEBUG [SQL] select profileimp0_.id as id0_, profileimp0_.customerId as customerId7_0_, profileimp0_.name as name7_0_, profileimp0_.description as descript4_7_0_, profileimp0_.ruleSet as ruleSet7_0_, profileimp0_.active as active7_0_, profileimp0_.busyActionType as busyActi7_7_0_, profileimp0_.busyActionName as busyActi8_7_0_, profileimp0_.noAnswerActionType as noAnswer9_7_0_, profileimp0_.noAnswerActionName as noAnswe10_7_0_, (select c.name from customers c where c.id = profileimp0_.customerId) as formula6_0_ from profiles profileimp0_ where profileimp0_.id=?
2006-10-20 17:22:26,829 DEBUG [AbstractBatcher] preparing statement
2006-10-20 17:22:26,830 DEBUG [IntegerType] binding '1' to parameter: 1
2006-10-20 17:22:26,830 DEBUG [AbstractBatcher] about to open ResultSet (open ResultSets: 0, globally: 0)
2006-10-20 17:22:26,830 DEBUG [Loader] processing result set
2006-10-20 17:22:26,830 DEBUG [Loader] result set row: 0
2006-10-20 17:22:26,830 DEBUG [Loader] result set row: 0
2006-10-20 17:22:26,830 DEBUG [Loader] result row: EntityKey[com. .c3.bus.ProfileImpl#1]
2006-10-20 17:22:26,831 DEBUG [Loader] Initializing object from ResultSet: [com. .c3.bus.ProfileImpl#1]
2006-10-20 17:22:26,831 DEBUG [BasicEntityPersister] Hydrating entity: [com. .c3.bus.ProfileImpl#1]
2006-10-20 17:22:26,831 DEBUG [IntegerType] returning '1' as column: customerId7_0_
2006-10-20 17:22:26,831 DEBUG [StringType] returning 'eircom' as column: formula6_0_
2006-10-20 17:22:26,831 DEBUG [StringType] returning 'eircom_routing_1' as column: name7_0_
2006-10-20 17:22:26,831 DEBUG [StringType] returning '' as column: descript4_7_0_
2006-10-20 17:22:26,831 DEBUG [TextType] returning '<router>^M
^M
<processor name="root">^M
<all_rule call_center="work"/>^M
</processor>^M
^M
</router>^M
^M
' as column: ruleSet7_0_
2006-10-20 17:22:26,831 DEBUG [BooleanType] returning 'false' as column: active7_0_
2006-10-20 17:22:26,831 DEBUG [StringType] returning null as column: busyActi7_7_0_
2006-10-20 17:22:26,831 DEBUG [StringType] returning null as column: busyActi8_7_0_
2006-10-20 17:22:26,831 DEBUG [StringType] returning null as column: noAnswer9_7_0_
2006-10-20 17:22:26,831 DEBUG [StringType] returning null as column: noAnswe10_7_0_
2006-10-20 17:22:26,831 DEBUG [Loader] done processing result set (1 rows)
2006-10-20 17:22:26,831 DEBUG [AbstractBatcher] about to close ResultSet (open ResultSets: 1, globally: 1)
2006-10-20 17:22:26,831 DEBUG [AbstractBatcher] about to close PreparedStatement (open PreparedStatements: 1, globally: 1)
2006-10-20 17:22:26,831 DEBUG [AbstractBatcher] closing statement
2006-10-20 17:22:26,832 DEBUG [Loader] total objects hydrated: 1
2006-10-20 17:22:26,832 DEBUG [TwoPhaseLoad] resolving associations for [com. .c3.bus.ProfileImpl#1]
2006-10-20 17:22:26,832 DEBUG [TwoPhaseLoad] done materializing entity [com. .c3.bus.ProfileImpl#1]
2006-10-20 17:22:26,832 DEBUG [Loader] done entity load
2006-10-20 17:22:26,832 DEBUG [CollectionLoadContext] creating collection wrapper:[com. .c3.number.bus.AccessNumberImpl.terminatingNumbers#1]
2006-10-20 17:22:26,832 DEBUG [CollectionLoadContext] creating collection wrapper:[com. .c3.number.bus.AccessNumberImpl.profiles#1]
2006-10-20 17:22:26,832 DEBUG [TwoPhaseLoad] done materializing entity [com. .c3.number.bus.AccessNumberImpl#1]
2006-10-20 17:22:26,832 DEBUG [TwoPhaseLoad] resolving associations for [com. .c3.number.bus.AccessNumberImpl#2]
2006-10-20 17:22:26,832 DEBUG [CollectionLoadContext] creating collection wrapper:[com. .c3.number.bus.AccessNumberImpl.terminatingNumbers#2]
2006-10-20 17:22:26,832 DEBUG [CollectionLoadContext] creating collection wrapper:[com. .c3.number.bus.AccessNumberImpl.profiles#2]
2006-10-20 17:22:26,832 DEBUG [TwoPhaseLoad] done materializing entity [com. .c3.number.bus.AccessNumberImpl#2]
2006-10-20 17:22:26,832 DEBUG [PersistenceContext] initializing non-lazy collections
2006-10-20 17:22:26,832 DEBUG [DefaultInitializeCollectionEventListener] initializing collection [com. .c3.number.bus.AccessNumberImpl.profiles#2]
2006-10-20 17:22:26,832 DEBUG [DefaultInitializeCollectionEventListener] checking second-level cache
2006-10-20 17:22:26,832 DEBUG [DefaultInitializeCollectionEventListener] collection not cached
2006-10-20 17:22:26,832 DEBUG [Loader] loading collection: [com. .c3.number.bus.AccessNumberImpl.profiles#2]
2006-10-20 17:22:26,832 DEBUG [Loader] loading collection: [com. .c3.number.bus.AccessNumberImpl.profiles#2]
2006-10-20 17:22:26,832 DEBUG [AbstractBatcher] about to open PreparedStatement (open PreparedStatements: 0, globally: 0)
2006-10-20 17:22:26,832 DEBUG [SQL] select profiles0_.id as id1_, profiles0_.id as id0_, profiles0_.customerId as customerId7_0_, profiles0_.name as name7_0_, profiles0_.description as descript4_7_0_, profiles0_.ruleSet as ruleSet7_0_, profiles0_.active as active7_0_, profiles0_.busyActionType as busyActi7_7_0_, profiles0_.busyActionName as busyActi8_7_0_, profiles0_.noAnswerActionType as noAnswer9_7_0_, profiles0_.noAnswerActionName as noAnswe10_7_0_, (select c.name from customers c where c.id = profiles0_.customerId) as formula6_0_ from profiles profiles0_ where profiles0_.id=? order by profiles0_.name
2006-10-20 17:22:26,832 DEBUG [AbstractBatcher] preparing statement
2006-10-20 17:22:26,833 DEBUG [IntegerType] binding '2' to parameter: 1
2006-10-20 17:22:26,834 DEBUG [AbstractBatcher] about to open ResultSet (open ResultSets: 0, globally: 0)
2006-10-20 17:22:26,834 DEBUG [Loader] result set contains (possibly empty) collection: [com. .c3.number.bus.AccessNumberImpl.profiles#2]
2006-10-20 17:22:26,834 DEBUG [CollectionLoadContext] uninitialized collection: initializing
2006-10-20 17:22:26,834 DEBUG [Loader] processing result set
2006-10-20 17:22:26,834 DEBUG [Loader] done processing result set (0 rows)
2006-10-20 17:22:26,834 DEBUG [AbstractBatcher] about to close ResultSet (open ResultSets: 1, globally: 1)
2006-10-20 17:22:26,834 DEBUG [AbstractBatcher] about to close PreparedStatement (open PreparedStatements: 1, globally: 1)
2006-10-20 17:22:26,834 DEBUG [AbstractBatcher] closing statement
2006-10-20 17:22:26,834 DEBUG [Loader] total objects hydrated: 0
2006-10-20 17:22:26,834 DEBUG [CollectionLoadContext] 1 collections were found in result set for role: com. .c3.number.bus.AccessNumberImpl.profiles
2006-10-20 17:22:26,834 DEBUG [CollectionLoadContext] collection fully initialized: [com. .c3.number.bus.AccessNumberImpl.profiles#2]
2006-10-20 17:22:26,834 DEBUG [CollectionLoadContext] 1 collections initialized for role: com. .c3.number.bus.AccessNumberImpl.profiles
2006-10-20 17:22:26,834 DEBUG [Loader] done loading collection
2006-10-20 17:22:26,834 DEBUG [DefaultInitializeCollectionEventListener] collection initialized
2006-10-20 17:22:26,834 DEBUG [DefaultInitializeCollectionEventListener] initializing collection [com. .c3.number.bus.AccessNumberImpl.terminatingNumbers#2]
2006-10-20 17:22:26,834 DEBUG [DefaultInitializeCollectionEventListener] checking second-level cache
2006-10-20 17:22:26,834 DEBUG [DefaultInitializeCollectionEventListener] collection not cached
2006-10-20 17:22:26,834 DEBUG [Loader] loading collection: [com. .c3.number.bus.AccessNumberImpl.terminatingNumbers#2]
2006-10-20 17:22:26,834 DEBUG [AbstractBatcher] about to open PreparedStatement (open PreparedStatements: 0, globally: 0)
2006-10-20 17:22:26,834 DEBUG [SQL] select terminatin0_.id as id0_, terminatin0_.number as number0_ from terminating_numbers terminatin0_ where terminatin0_.id=?
2006-10-20 17:22:26,834 DEBUG [AbstractBatcher] preparing statement
2006-10-20 17:22:26,835 DEBUG [IntegerType] binding '2' to parameter: 1
2006-10-20 17:22:26,835 DEBUG [AbstractBatcher] about to open ResultSet (open ResultSets: 0, globally: 0)
2006-10-20 17:22:26,835 DEBUG [Loader] result set contains (possibly empty) collection: [com. .c3.number.bus.AccessNumberImpl.terminatingNumbers#2]
2006-10-20 17:22:26,835 DEBUG [CollectionLoadContext] uninitialized collection: initializing
2006-10-20 17:22:26,835 DEBUG [Loader] processing result set
2006-10-20 17:22:26,835 DEBUG [Loader] done processing result set (0 rows)
2006-10-20 17:22:26,835 DEBUG [AbstractBatcher] about to close ResultSet (open ResultSets: 1, globally: 1)
2006-10-20 17:22:26,835 DEBUG [AbstractBatcher] about to close PreparedStatement (open PreparedStatements: 1, globally: 1)
2006-10-20 17:22:26,835 DEBUG [AbstractBatcher] closing statement
2006-10-20 17:22:26,835 DEBUG [AbstractBatcher] closing statement
2006-10-20 17:22:26,835 DEBUG [CollectionLoadContext] 1 collections were found in result set for role: com. .c3.number.bus.AccessNumberImpl.terminatingNumbers
2006-10-20 17:22:26,835 DEBUG [CollectionLoadContext] collection fully initialized: [com. .c3.number.bus.AccessNumberImpl.terminatingNumbers#2]
2006-10-20 17:22:26,835 DEBUG [CollectionLoadContext] 1 collections initialized for role: com. .c3.number.bus.AccessNumberImpl.terminatingNumbers
2006-10-20 17:22:26,835 DEBUG [Loader] done loading collection
2006-10-20 17:22:26,835 DEBUG [DefaultInitializeCollectionEventListener] collection initialized
2006-10-20 17:22:26,835 DEBUG [DefaultInitializeCollectionEventListener] initializing collection [com. .c3.number.bus.AccessNumberImpl.profiles#1]
2006-10-20 17:22:26,835 DEBUG [DefaultInitializeCollectionEventListener] checking second-level cache
2006-10-20 17:22:26,836 DEBUG [DefaultInitializeCollectionEventListener] collection not cached
2006-10-20 17:22:26,836 DEBUG [Loader] loading collection: [com. .c3.number.bus.AccessNumberImpl.profiles#1]
2006-10-20 17:22:26,836 DEBUG [AbstractBatcher] about to open PreparedStatement (open PreparedStatements: 0, globally: 0)
2006-10-20 17:22:26,836 DEBUG [SQL] select profiles0_.id as id1_, profiles0_.id as id0_, profiles0_.customerId as customerId7_0_, profiles0_.name as name7_0_, profiles0_.description as descript4_7_0_, profiles0_.ruleSet as ruleSet7_0_, profiles0_.active as active7_0_, profiles0_.busyActionType as busyActi7_7_0_, profiles0_.busyActionName as busyActi8_7_0_, profiles0_.noAnswerActionType as noAnswer9_7_0_, profiles0_.noAnswerActionName as noAnswe10_7_0_, (select c.name from customers c where c.id = profiles0_.customerId) as formula6_0_ from profiles profiles0_ where profiles0_.id=? order by profiles0_.name
2006-10-20 17:22:26,836 DEBUG [AbstractBatcher] preparing statement
2006-10-20 17:22:26,836 DEBUG [IntegerType] binding '1' to parameter: 1
2006-10-20 17:22:26,837 DEBUG [AbstractBatcher] about to open ResultSet (open ResultSets: 0, globally: 0)
2006-10-20 17:22:26,837 DEBUG [Loader] result set contains (possibly empty) collection: [com. .c3.number.bus.AccessNumberImpl.profiles#1]
2006-10-20 17:22:26,837 DEBUG [CollectionLoadContext] uninitialized collection: initializing
2006-10-20 17:22:26,837 DEBUG [Loader] processing result set
2006-10-20 17:22:26,837 DEBUG [Loader] result set row: 0
2006-10-20 17:22:26,837 DEBUG [IntegerType] returning '1' as column: id0_
2006-10-20 17:22:26,837 DEBUG [Loader] result row: EntityKey[com. .c3.bus.ProfileImpl#1]
2006-10-20 17:22:26,837 DEBUG [IntegerType] returning '1' as column: id1_
2006-10-20 17:22:26,837 DEBUG [Loader] found row of collection: [com. .c3.number.bus.AccessNumberImpl.profiles#1]
2006-10-20 17:22:26,837 DEBUG [CollectionLoadContext] reading row
2006-10-20 17:22:26,837 DEBUG [IntegerType] returning '1' as column: id1_
2006-10-20 17:22:26,837 DEBUG [DefaultLoadEventListener] loading entity: [com. .c3.bus.ProfileImpl#1]
2006-10-20 17:22:26,837 DEBUG [DefaultLoadEventListener] attempting to resolve: [com. .c3.bus.ProfileImpl#1]
2006-10-20 17:22:26,837 DEBUG [DefaultLoadEventListener] resolved object in session cache: [com. .c3.bus.ProfileImpl#1]
2006-10-20 17:22:26,837 DEBUG [Loader] done processing result set (1 rows)
2006-10-20 17:22:26,838 DEBUG [AbstractBatcher] about to close ResultSet (open ResultSets: 1, globally: 1)
2006-10-20 17:22:26,838 DEBUG [AbstractBatcher] about to close PreparedStatement (open PreparedStatements: 1, globally: 1)
2006-10-20 17:22:26,838 DEBUG [AbstractBatcher] closing statement
2006-10-20 17:22:26,838 DEBUG [Loader] total objects hydrated: 0
2006-10-20 17:22:26,838 DEBUG [CollectionLoadContext] 1 collections were found in result set for role: com. .c3.number.bus.AccessNumberImpl.profiles
2006-10-20 17:22:26,838 DEBUG [CollectionLoadContext] collection fully initialized: [com. .c3.number.bus.AccessNumberImpl.profiles#1]
2006-10-20 17:22:26,838 DEBUG [CollectionLoadContext] 1 collections initialized for role: com. .c3.number.bus.AccessNumberImpl.profiles
2006-10-20 17:22:26,838 DEBUG [CollectionLoadContext] 1 collections initialized for role: com. .c3.number.bus.AccessNumberImpl.profiles
2006-10-20 17:22:26,838 DEBUG [Loader] done loading collection
2006-10-20 17:22:26,838 DEBUG [DefaultInitializeCollectionEventListener] collection initialized
2006-10-20 17:22:26,838 DEBUG [DefaultInitializeCollectionEventListener] initializing collection [com. .c3.number.bus.AccessNumberImpl.terminatingNumbers#1]
2006-10-20 17:22:26,838 DEBUG [DefaultInitializeCollectionEventListener] checking second-level cache
2006-10-20 17:22:26,838 DEBUG [DefaultInitializeCollectionEventListener] collection not cached
2006-10-20 17:22:26,838 DEBUG [Loader] loading collection: [com. .c3.number.bus.AccessNumberImpl.terminatingNumbers#1]
2006-10-20 17:22:26,838 DEBUG [AbstractBatcher] about to open PreparedStatement (open PreparedStatements: 0, globally: 0)
2006-10-20 17:22:26,838 DEBUG [SQL] select terminatin0_.id as id0_, terminatin0_.number as number0_ from terminating_numbers terminatin0_ where terminatin0_.id=?
2006-10-20 17:22:26,838 DEBUG [AbstractBatcher] preparing statement
2006-10-20 17:22:26,839 DEBUG [IntegerType] binding '1' to parameter: 1
2006-10-20 17:22:26,839 DEBUG [AbstractBatcher] about to open ResultSet (open ResultSets: 0, globally: 0)
2006-10-20 17:22:26,839 DEBUG [Loader] result set contains (possibly empty) collection: [com. .c3.number.bus.AccessNumberImpl.terminatingNumbers#1]
2006-10-20 17:22:26,839 DEBUG [CollectionLoadContext] uninitialized collection: initializing
2006-10-20 17:22:26,839 DEBUG [Loader] processing result set
2006-10-20 17:22:26,839 DEBUG [Loader] done processing result set (0 rows)
2006-10-20 17:22:26,839 DEBUG [AbstractBatcher] about to close ResultSet (open ResultSets: 1, globally: 1)
2006-10-20 17:22:26,839 DEBUG [AbstractBatcher] about to close PreparedStatement (open PreparedStatements: 1, globally: 1)
2006-10-20 17:22:26,839 DEBUG [AbstractBatcher] closing statement
2006-10-20 17:22:26,839 DEBUG [CollectionLoadContext] 1 collections were found in result set for role: com. .c3.number.bus.AccessNumberImpl.terminatingNumbers
2006-10-20 17:22:26,839 DEBUG [CollectionLoadContext] collection fully initialized: [com. .c3.number.bus.AccessNumberImpl.terminatingNumbers#1]
2006-10-20 17:22:26,839 DEBUG [CollectionLoadContext] 1 collections initialized for role: com. .c3.number.bus.AccessNumberImpl.terminatingNumbers
2006-10-20 17:22:26,839 DEBUG [Loader] done loading collection
2006-10-20 17:22:26,839 DEBUG [DefaultInitializeCollectionEventListener] collection initialized
2006-10-20 17:22:26,839 DEBUG [StandardQueryCache] caching query results in region: org.hibernate.cache.StandardQueryCache