I was able to reproduce the bug even with simplier C:
Code:
public class C implements Serializable {
private Long id;
private String value;
//...
public String getValue() {
return value;
}
public void setValue(String value) {
this.value = value;
}
}
I.e, no list required there to show the bug. 2 level of lists is enough.
Also in the log it says that 2 Collections were found, but then it loads 4! Well, of course 2 of them are just duplicate entries.
Shall we create a JIRA entry for this?
Name and version of the database: HSQL shipped with JBoss 4.0.4RC1
The generated SQL (show_sql=true):
select a0_.id as id1218_2_, blist1_.A_id as A1_4_,
b2_.id as BList2_4_, b2_.id as id1219_0_,
clist3_.B_id as B1_5_, c4_.id as CList2_5_, c4_.id as id1220_1_, c4_.value as value1220_1_ from A a0_
left outer join A_B blist1_ on a0_.id=blist1_.A_id
left outer join B b2_ on blist1_.BList_id=b2_.id
left outer join B_C clist3_ on b2_.id=clist3_.B_id
left outer join C c4_ on clist3_.CList_id=c4_.id where a0_.id=?;
Debug level Hibernate log excerpt:
16:40:21,123 INFO [STDOUT] Hibernate: select a0_.id as id1234_2_, blist1_.A_id
as A1_4_, b2_.id as BList2_4_, b2_.id as id1235_0_, clist3_.B_id as B1_5_, c4_.i
d as CList2_5_, c4_.id as id1236_1_, c4_.value as value1236_1_ from A a0_ left o
uter join A_B blist1_ on a0_.id=blist1_.A_id left outer join B b2_ on blist1_.BL
ist_id=b2_.id left outer join B_C clist3_ on b2_.id=clist3_.B_id left outer join
C c4_ on clist3_.CList_id=c4_.id where a0_.id=?
16:40:21,123 DEBUG [AbstractBatcher] about to open ResultSet (open ResultSets: 0, globally: 0)
16:40:21,123 DEBUG [Loader] result row: EntityKey[my.test.dmo.B#1], EntityKey[my.test.dmo.C#1], EntityKey[my.test.dmo.A#1]
16:40:21,123 DEBUG [Loader] found row of collection: [my.test.dmo.A.BList#1]
16:40:21,123 DEBUG [Loader] found row of collection: [my.test.dmo.B.CList#1]
16:40:21,123 DEBUG [Loader] result row: EntityKey[my.test.dmo.B#1], EntityKey[my.test.dmo.C#2], EntityKey[my.test.dmo.A#1]
16:40:21,123 DEBUG [Loader] found row of collection: [my.test.dmo.A.BList#1]
16:40:21,123 DEBUG [Loader] found row of collection: [my.test.dmo.B.CList#1]
16:40:21,123 DEBUG [Loader] result row: EntityKey[my.test.dmo.B#2], EntityKey[my.test.dmo.C#3], EntityKey[my.test.dmo.A#1]
16:40:21,123 DEBUG [Loader] found row of collection: [my.test.dmo.A.BList#1]
16:40:21,123 DEBUG [Loader] found row of collection: [my.test.dmo.B.CList#2]
16:40:21,123 DEBUG [Loader] result row: EntityKey[my.test.dmo.B#2], EntityKey[my.test.dmo.C#4], EntityKey[my.test.dmo.A#1]
16:40:21,123 DEBUG [Loader] found row of collection: [my.test.dmo.A.BList#1]
16:40:21,123 DEBUG [Loader] found row of collection: [my.test.dmo.B.CList#2]
16:40:21,123 DEBUG [AbstractBatcher] about to close ResultSet (open ResultSets:1, globally: 1)
16:40:21,123 DEBUG [AbstractBatcher] about to close PreparedStatement (open PreparedStatements: 1, globally: 1)
16:40:21,123 DEBUG [ConnectionManager] aggressively releasing JDBC connection
16:40:21,123 DEBUG [ConnectionManager] releasing JDBC connection [ (open PreparedStatements: 0, globally: 0) (open ResultSets: 0, globally: 0)]
16:40:21,123 DEBUG [TwoPhaseLoad] resolving associations for [my.test.dmo.B#1]
16:40:21,123 DEBUG [TwoPhaseLoad] done materializing entity [my.test.dmo.B#1]
16:40:21,123 DEBUG [TwoPhaseLoad] resolving associations for [my.test.dmo.C#1]
16:40:21,123 DEBUG [TwoPhaseLoad] done materializing entity [my.test.dmo.C#1]
16:40:21,123 DEBUG [TwoPhaseLoad] resolving associations for [my.test.dmo.A#1]
16:40:21,123 DEBUG [TwoPhaseLoad] done materializing entity [my.test.dmo.A#1]
16:40:21,123 DEBUG [TwoPhaseLoad] resolving associations for [my.test.dmo.C#2]
16:40:21,138 DEBUG [TwoPhaseLoad] done materializing entity [my.test.dmo.C#2]
16:40:21,138 DEBUG [TwoPhaseLoad] resolving associations for [my.test.dmo.B#2]
16:40:21,138 DEBUG [TwoPhaseLoad] done materializing entity [my.test.dmo.B#2]
16:40:21,138 DEBUG [TwoPhaseLoad] resolving associations for [my.test.dmo.C#3]
16:40:21,138 DEBUG [TwoPhaseLoad] done materializing entity [my.test.dmo.C#3]
16:40:21,138 DEBUG [TwoPhaseLoad] resolving associations for [my.test.dmo.C#4]
16:40:21,138 DEBUG [TwoPhaseLoad] done materializing entity [my.test.dmo.C#4]
16:40:21,138 DEBUG [CollectionLoadContext] 1 collections were found in result set for role: my.test.dmo.A.BList
16:40:21,138 DEBUG [CollectionLoadContext] collection fully initialized: [my.test.dmo.A.BList#1]
16:40:21,138 DEBUG [CollectionLoadContext] 1 collections initialized for role: my.test.dmo.A.BList
16:40:21,138 DEBUG [CollectionLoadContext] 2 collections were found in result set for role: my.test.dmo.B.CList
16:40:21,138 DEBUG [CollectionLoadContext] collection fully initialized: [my.test.dmo.B.CList#1]
16:40:21,138 DEBUG [CollectionLoadContext] collection fully initialized: [my.test.dmo.B.CList#2]
16:40:21,138 DEBUG [CollectionLoadContext] 2 collections initialized for role: my.test.dmo.B.CList
16:40:21,138 DEBUG [StatefulPersistenceContext] initializing non-lazy collections
16:40:21,138 DEBUG [Loader] done entity load
16:40:21,138 INFO [STDOUT] loadedA.getB:4