NullPointerException - Set in Collection not initialized

menlo · **Joined:** Tue Nov 16, 2004 10:10 am **Posts:** 2

Our object PublicationUnit contains a set of Issues objects which are mapped to a table. During the first session the Set of Issues gets initialized and gets an object added to it. On the second session the same PublicationUnit object is found and another Issues needs to be added to the Set. The Sets we create are fine, but somehow the Set within Hibernate's Collection object does not get initialized, thus producing a NullPointerExpection when Hibernate tries to determine the size of its Set. Any thoughts or ideas would be helpful in fixing this problem.

[b]Hibernate version:[/b] hibernate2-2.16.jar

[b]Mapping documents:
[/b]<hibernate-mapping>

<set name="issues" table="Issue_PublicationUnit" lazy="true" inverse="true" cascade="none" sort="unsorted" access="field">
<key column="PublicationUnit_ID"/>
<many-to-many class="org.jstor.model.repository.Issue" column="Issue_ID" outer-join="auto"/>
</set>
</class>
</hibernate-mapping>


<list name="numerationPublicationUnit" table="Issue_PublicationUnit" lazy="true" inverse="false" cascade="none" access="field">
<key column="Issue_ID"/>
<index column="Numeration_Index"/>
<many-to-many class="org.jstor.model.repository.PublicationUnit" column="PublicationUnit_ID" outer-join="auto"/>
</list>

[b]Code between sessionFactory.openSession() and session.close():
[/b]Cannot supply

[b]Full stack trace of any exception that occurs:
[/b]
java.lang.NullPointerException
at net.sf.hibernate.collection.Set.size(Set.java:107)
at org.apache.commons.collections.collection.AbstractCollectionDecorator.size(AbstractCollectionDecorator.java:137)
at org.apache.commons.events.observable.standard.StandardModificationHandler.preEvent(StandardModificationHandler.java:396)
at org.apache.commons.events.observable.ModificationHandler.preAdd(ModificationHandler.java:292)
at org.apache.commons.events.observable.ObservableCollection.add(ObservableCollection.java:212)
at org.jstor.produi.importdata.TOCXMLHelper.findOrAddPublicationUnit(TOCXMLHelper.java:791)

[b]Name and version of the database you are using:[/b]Oracle 9i

[b]The generated SQL (show_sql=true):[/b]

[b]Debug level Hibernate log excerpt:[/b]2004-11-16 09:30:41,625 DEBUG [AWT-EventQueue-0] impl.BatcherImpl (BatcherImpl.java:269) - closing statement
2004-11-16 09:30:41,625 DEBUG [AWT-EventQueue-0] impl.SessionImpl (SessionImpl.java:778) - generated identifier: 646
2004-11-16 09:30:41,625 DEBUG [AWT-EventQueue-0] impl.SessionImpl (SessionImpl.java:825) - saving [org.jstor.model.repository.Article#646]
2004-11-16 09:30:41,625 DEBUG [AWT-EventQueue-0] engine.Cascades (Cascades.java:497) - processing cascades for: org.jstor.model.repository.Article
2004-11-16 09:30:41,625 DEBUG [AWT-EventQueue-0] engine.Cascades$4 (Cascades.java:113) - cascading to saveOrUpdate()
2004-11-16 09:30:41,625 DEBUG [AWT-EventQueue-0] impl.SessionImpl (SessionImpl.java:1387) - saveOrUpdate() unsaved instance
2004-11-16 09:30:41,625 DEBUG [AWT-EventQueue-0] impl.BatcherImpl (BatcherImpl.java:200) - about to open: 0 open PreparedStatements, 0 open ResultSets
2004-11-16 09:30:41,640 DEBUG [AWT-EventQueue-0] impl.BatcherImpl (BatcherImpl.java:226) - select hibernate_sequence.nextval from dual
2004-11-16 09:30:41,640 DEBUG [AWT-EventQueue-0] impl.BatcherImpl (BatcherImpl.java:249) - preparing statement
2004-11-16 09:30:41,640 DEBUG [AWT-EventQueue-0] id.SequenceGenerator (SequenceGenerator.java:81) - Sequence identifier generated: 647
2004-11-16 09:30:41,640 DEBUG [AWT-EventQueue-0] impl.BatcherImpl (BatcherImpl.java:207) - done closing: 0 open PreparedStatements, 0 open ResultSets
2004-11-16 09:30:41,640 DEBUG [AWT-EventQueue-0] impl.BatcherImpl (BatcherImpl.java:269) - closing statement
2004-11-16 09:30:41,640 DEBUG [AWT-EventQueue-0] impl.SessionImpl (SessionImpl.java:778) - generated identifier: 647
2004-11-16 09:30:41,640 DEBUG [AWT-EventQueue-0] impl.SessionImpl (SessionImpl.java:825) - saving [org.jstor.model.repository.Variants#647]
2004-11-16 09:30:41,640 DEBUG [AWT-EventQueue-0] engine.Cascades (Cascades.java:497) - processing cascades for: org.jstor.model.repository.Variants
2004-11-16 09:30:41,640 DEBUG [AWT-EventQueue-0] engine.Cascades (Cascades.java:506) - done processing cascades for: org.jstor.model.repository.Variants
2004-11-16 09:30:41,640 DEBUG [AWT-EventQueue-0] engine.Cascades (Cascades.java:497) - processing cascades for: org.jstor.model.repository.Variants
2004-11-16 09:30:41,640 DEBUG [AWT-EventQueue-0] engine.Cascades (Cascades.java:506) - done processing cascades for: org.jstor.model.repository.Variants
2004-11-16 09:30:41,640 DEBUG [AWT-EventQueue-0] engine.Cascades$4 (Cascades.java:113) - cascading to saveOrUpdate()
2004-11-16 09:30:41,640 DEBUG [AWT-EventQueue-0] impl.SessionImpl (SessionImpl.java:1387) - saveOrUpdate() unsaved instance
2004-11-16 09:30:41,640 DEBUG [AWT-EventQueue-0] impl.BatcherImpl (BatcherImpl.java:200) - about to open: 0 open PreparedStatements, 0 open ResultSets
2004-11-16 09:30:41,656 DEBUG [AWT-EventQueue-0] impl.BatcherImpl (BatcherImpl.java:226) - select hibernate_sequence.nextval from dual
2004-11-16 09:30:41,656 DEBUG [AWT-EventQueue-0] impl.BatcherImpl (BatcherImpl.java:249) - preparing statement
2004-11-16 09:30:41,656 DEBUG [AWT-EventQueue-0] id.SequenceGenerator (SequenceGenerator.java:81) - Sequence identifier generated: 648
2004-11-16 09:30:41,656 DEBUG [AWT-EventQueue-0] impl.BatcherImpl (BatcherImpl.java:207) - done closing: 0 open PreparedStatements, 0 open ResultSets
2004-11-16 09:30:41,656 DEBUG [AWT-EventQueue-0] impl.BatcherImpl (BatcherImpl.java:269) - closing statement
2004-11-16 09:30:41,656 DEBUG [AWT-EventQueue-0] impl.SessionImpl (SessionImpl.java:778) - generated identifier: 648
2004-11-16 09:30:41,656 DEBUG [AWT-EventQueue-0] impl.SessionImpl (SessionImpl.java:825) - saving [org.jstor.model.repository.Variants#648]
2004-11-16 09:30:41,656 DEBUG [AWT-EventQueue-0] engine.Cascades (Cascades.java:497) - processing cascades for: org.jstor.model.repository.Variants
2004-11-16 09:30:41,656 DEBUG [AWT-EventQueue-0] engine.Cascades (Cascades.java:506) - done processing cascades for: org.jstor.model.repository.Variants
2004-11-16 09:30:41,656 DEBUG [AWT-EventQueue-0] engine.Cascades (Cascades.java:497) - processing cascades for: org.jstor.model.repository.Variants
2004-11-16 09:30:41,656 DEBUG [AWT-EventQueue-0] engine.Cascades (Cascades.java:506) - done processing cascades for: org.jstor.model.repository.Variants
2004-11-16 09:30:41,656 DEBUG [AWT-EventQueue-0] engine.Cascades$4 (Cascades.java:113) - cascading to saveOrUpdate()
2004-11-16 09:30:41,656 DEBUG [AWT-EventQueue-0] impl.SessionImpl (SessionImpl.java:1387) - saveOrUpdate() unsaved instance
2004-11-16 09:30:41,656 DEBUG [AWT-EventQueue-0] impl.BatcherImpl (BatcherImpl.java:200) - about to open: 0 open PreparedStatements, 0 open ResultSets
2004-11-16 09:30:41,671 DEBUG [AWT-EventQueue-0] impl.BatcherImpl (BatcherImpl.java:226) - select hibernate_sequence.nextval from dual
2004-11-16 09:30:41,671 DEBUG [AWT-EventQueue-0] impl.BatcherImpl (BatcherImpl.java:249) - preparing statement
2004-11-16 09:30:41,671 DEBUG [AWT-EventQueue-0] id.SequenceGenerator (SequenceGenerator.java:81) - Sequence identifier generated: 649
2004-11-16 09:30:41,671 DEBUG [AWT-EventQueue-0] impl.BatcherImpl (BatcherImpl.java:207) - done closing: 0 open PreparedStatements, 0 open ResultSets
2004-11-16 09:30:41,671 DEBUG [AWT-EventQueue-0] impl.BatcherImpl (BatcherImpl.java:269) - closing statement
2004-11-16 09:30:41,671 DEBUG [AWT-EventQueue-0] impl.SessionImpl (SessionImpl.java:778) - generated identifier: 649
2004-11-16 09:30:41,671 DEBUG [AWT-EventQueue-0] impl.SessionImpl (SessionImpl.java:825) - saving [org.jstor.model.repository.Variants#649]
2004-11-16 09:30:41,671 DEBUG [AWT-EventQueue-0] engine.Cascades (Cascades.java:497) - processing cascades for: org.jstor.model.repository.Variants
2004-11-16 09:30:41,671 DEBUG [AWT-EventQueue-0] engine.Cascades (Cascades.java:506) - done processing cascades for: org.jstor.model.repository.Variants
2004-11-16 09:30:41,671 DEBUG [AWT-EventQueue-0] engine.Cascades (Cascades.java:497) - processing cascades for: org.jstor.model.repository.Variants
2004-11-16 09:30:41,671 DEBUG [AWT-EventQueue-0] engine.Cascades (Cascades.java:506) - done processing cascades for: org.jstor.model.repository.Variants
2004-11-16 09:30:41,671 DEBUG [AWT-EventQueue-0] engine.Cascades (Cascades.java:506) - done processing cascades for: org.jstor.model.repository.Article
2004-11-16 09:30:41,671 DEBUG [AWT-EventQueue-0] impl.WrapVisitor (WrapVisitor.java:81) - Wrapped collection in role: org.jstor.model.repository.Article.notes
2004-11-16 09:30:41,671 DEBUG [AWT-EventQueue-0] impl.WrapVisitor (WrapVisitor.java:81) - Wrapped collection in role: org.jstor.model.repository.Article.appearsOnPage
2004-11-16 09:30:41,671 DEBUG [AWT-EventQueue-0] engine.Cascades (Cascades.java:497) - processing cascades for: org.jstor.model.repository.Article
2004-11-16 09:30:41,687 DEBUG [AWT-EventQueue-0] engine.Cascades (Cascades.java:506) - done processing cascades for: org.jstor.model.repository.Article
2004-11-16 09:30:41,703 WARN [AWT-EventQueue-0] repository.IllustrationImageFile (IllustrationImageFile.java:243) - setting olds to: 0 0 0 0
2004-11-16 09:30:41,843 DEBUG [AWT-EventQueue-0] impl.SessionImpl (SessionImpl.java:3260) - initializing collection [org.jstor.model.repository.PublicationUnit.publicationUnit#389]
2004-11-16 09:30:41,843 DEBUG [AWT-EventQueue-0] impl.SessionImpl (SessionImpl.java:3261) - checking second-level cache
2004-11-16 09:30:41,843 DEBUG [AWT-EventQueue-0] impl.SessionImpl (SessionImpl.java:3267) - collection not cached
2004-11-16 09:30:41,843 DEBUG [AWT-EventQueue-0] impl.BatcherImpl (BatcherImpl.java:200) - about to open: 0 open PreparedStatements, 0 open ResultSets
2004-11-16 09:30:41,843 DEBUG [AWT-EventQueue-0] impl.BatcherImpl (BatcherImpl.java:226) - select publicatio0_.parent as parent__, publicatio0_.PublicationUnit_ID as Publicat1___, publicatio0_.parent_Index as parent_10___, publicatio0_.PublicationUnit_ID as Publicat1_0_, publicatio0_.UnitNumber as UnitNumber0_, publicatio0_.PublicationUnitArchetype as Publicat3_0_, publicatio0_.Status as Status0_, publicatio0_.legacySystemIdentifier as legacySy5_0_, publicatio0_.parent as parent0_, publicatio0_.FormatExpression as FormatEx7_0_, publicatio0_.RangeFormatExpression as RangeFor8_0_, publicatio0_.StrongPersistentIdentifier as StrongPe9_0_ from PublicationUnit publicatio0_ where publicatio0_.parent=?
2004-11-16 09:30:41,843 DEBUG [AWT-EventQueue-0] impl.BatcherImpl (BatcherImpl.java:249) - preparing statement
2004-11-16 09:30:41,843 DEBUG [AWT-EventQueue-0] type.NullableType (NullableType.java:46) - binding '389' to parameter: 1
2004-11-16 09:30:41,843 DEBUG [AWT-EventQueue-0] loader.Loader (Loader.java:402) - result set contains (possibly empty) collection: [org.jstor.model.repository.PublicationUnit.publicationUnit#389]
2004-11-16 09:30:41,843 DEBUG [AWT-EventQueue-0] impl.SessionImpl (SessionImpl.java:3018) - uninitialized collection: initializing
2004-11-16 09:30:41,843 DEBUG [AWT-EventQueue-0] loader.Loader (Loader.java:277) - processing result set
2004-11-16 09:30:41,843 DEBUG [AWT-EventQueue-0] type.NullableType (NullableType.java:68) - returning '441' as column: Publicat1_0_
2004-11-16 09:30:41,859 DEBUG [AWT-EventQueue-0] loader.Loader (Loader.java:480) - result row: 441
2004-11-16 09:30:41,859 DEBUG [AWT-EventQueue-0] type.NullableType (NullableType.java:68) - returning '389' as column: parent__
2004-11-16 09:30:41,859 DEBUG [AWT-EventQueue-0] loader.Loader (Loader.java:367) - found row of collection: [org.jstor.model.repository.PublicationUnit.publicationUnit#389]
2004-11-16 09:30:41,859 DEBUG [AWT-EventQueue-0] impl.SessionImpl (SessionImpl.java:3041) - reading row
2004-11-16 09:30:41,859 DEBUG [AWT-EventQueue-0] type.NullableType (NullableType.java:68) - returning '441' as column: Publicat1___
2004-11-16 09:30:41,859 DEBUG [AWT-EventQueue-0] impl.SessionImpl (SessionImpl.java:1986) - loading [org.jstor.model.repository.PublicationUnit#441]
2004-11-16 09:30:41,859 DEBUG [AWT-EventQueue-0] impl.SessionImpl (SessionImpl.java:2083) - attempting to resolve [org.jstor.model.repository.PublicationUnit#441]
2004-11-16 09:30:41,859 DEBUG [AWT-EventQueue-0] impl.SessionImpl (SessionImpl.java:2099) - resolved object in session cache [org.jstor.model.repository.PublicationUnit#441]
2004-11-16 09:30:41,859 DEBUG [AWT-EventQueue-0] type.NullableType (NullableType.java:68) - returning '0' as column: parent_10___
2004-11-16 09:30:41,859 DEBUG [AWT-EventQueue-0] loader.Loader (Loader.java:294) - done processing result set (1 rows)
2004-11-16 09:30:41,859 DEBUG [AWT-EventQueue-0] impl.BatcherImpl (BatcherImpl.java:207) - done closing: 0 open PreparedStatements, 0 open ResultSets
2004-11-16 09:30:41,859 DEBUG [AWT-EventQueue-0] impl.BatcherImpl (BatcherImpl.java:269) - closing statement
2004-11-16 09:30:41,859 DEBUG [AWT-EventQueue-0] loader.Loader (Loader.java:314) - total objects hydrated: 0
2004-11-16 09:30:41,875 DEBUG [AWT-EventQueue-0] impl.SessionImpl (SessionImpl.java:3077) - 1 collections were found in result set
2004-11-16 09:30:41,875 DEBUG [AWT-EventQueue-0] impl.SessionImpl (SessionImpl.java:3095) - collection fully initialized: [org.jstor.model.repository.PublicationUnit.publicationUnit#389]
2004-11-16 09:30:41,875 DEBUG [AWT-EventQueue-0] impl.SessionImpl (SessionImpl.java:3098) - 1 collections initialized
2004-11-16 09:30:41,875 DEBUG [AWT-EventQueue-0] impl.SessionImpl (SessionImpl.java:3116) - initializing non-lazy collections
2004-11-16 09:30:41,875 DEBUG [AWT-EventQueue-0] impl.SessionImpl (SessionImpl.java:3269) - collection initialized
2004-11-16 09:30:41,875 DEBUG [AWT-EventQueue-0] impl.SessionImpl (SessionImpl.java:3260) - initializing collection [org.jstor.model.repository.PublicationUnit.issues#441]
2004-11-16 09:30:41,875 DEBUG [AWT-EventQueue-0] impl.SessionImpl (SessionImpl.java:3261) - checking second-level cache
2004-11-16 09:30:41,875 DEBUG [AWT-EventQueue-0] impl.SessionImpl (SessionImpl.java:3267) - collection not cached
2004-11-16 09:30:41,875 DEBUG [AWT-EventQueue-0] impl.BatcherImpl (BatcherImpl.java:200) - about to open: 0 open PreparedStatements, 0 open ResultSets
2004-11-16 09:30:41,875 DEBUG [AWT-EventQueue-0] impl.BatcherImpl (BatcherImpl.java:226) - select issues0_.PublicationUnit_ID as Publicat2___, issues0_.Issue_ID as Issue_ID__, issue1_.Issue_ID as Issue_ID0_, issue1_.Title_Variant_ID as Title_Va2_0_, issue1_.IssueCopyRight_Variant_ID as IssueCop3_0_, issue1_.DOI as DOI0_, issue1_.Status as Status0_, issue1_.legacySystemIdentifier as legacySy6_0_, issue1_.Extent as Extent0_, issue1_.ArticleGroup_ID as ArticleG8_0_, issue1_.PublicationStatement_ID as Publicat9_0_, issue1_.parent as parent0_, issue1_.CIL as CIL0_, issue1_.DigitizationBatch_ID as Digitiz12_0_, issue1_.jstordate as jstordate0_, issue1_.PubDate_Variant_ID as PubDate14_0_, issue1_.IssueOrdering as IssueOr15_0_, issue1_.lastModified as lastMod16_0_, issue1_.StrongPersistentIdentifier as StrongP17_0_, variants2_.VariantLarge_ID as VariantL1_1_, variants2_.ContinuedVariant_ID as Continue2_1_, variants2_.transliterated as translit3_1_, variants2_.unicode as unicode1_, variants3_.VariantLarge_ID as VariantL1_2_, variants3_.ContinuedVariant_ID as Continue2_2_, variants3_.transliterated as translit3_2_, variants3_.unicode as unicode2_, articlegro4_.ArticleGroup_ID as ArticleG1_3_, articlegro4_.ArticleGroupTitle_Variant_ID as ArticleG2_3_, articlegro4_.Status as Status3_, articlegro4_.legacySystemIdentifier as legacySy4_3_, articlegro4_.parent as parent3_, articlegro4_.StrongPersistentIdentifier as StrongPe6_3_, articlegro5_.ArticleGroup_ID as ArticleG1_4_, articlegro5_.ArticleGroupTitle_Variant_ID as ArticleG2_4_, articlegro5_.Status as Status4_, articlegro5_.legacySystemIdentifier as legacySy4_4_, articlegro5_.parent as parent4_, articlegro5_.StrongPersistentIdentifier as StrongPe6_4_, article6_.Article_ID as Article_ID5_, article6_.Title_Variant_ID as Title_Va2_5_, article6_.Status as Status5_, article6_.legacySystemIdentifier as legacySy4_5_, article6_.Abstract_Variant_ID as Abstract5_5_, article6_.DOI as DOI5_, article6_.Extent as Extent5_, article6_.ArticleCopyRight_Variant_ID as ArticleC8_5_, article6_.parentIssue as parentIs9_5_, article6_.Type as Type5_, article6_.ArticleGroup_ID as Article11_5_, article6_.lastModified as lastMod12_5_, article6_.StrongPersistentIdentifier as StrongP13_5_, article7_.Article_ID as Article_ID6_, article7_.Title_Variant_ID as Title_Va2_6_, article7_.Status as Status6_, article7_.legacySystemIdentifier as legacySy4_6_, article7_.Abstract_Variant_ID as Abstract5_6_, article7_.DOI as DOI6_, article7_.Extent as Extent6_, article7_.ArticleCopyRight_Variant_ID as ArticleC8_6_, article7_.parentIssue as parentIs9_6_, article7_.Type as Type6_, article7_.ArticleGroup_ID as Article11_6_, article7_.lastModified as lastMod12_6_, article7_.StrongPersistentIdentifier as StrongP13_6_, publicatio8_.PublicationStatement_ID as Publicat1_7_, publicatio8_.Licensor as Licensor7_, publicatio8_.Publisher_Variant_ID as Publishe3_7_, publicatio8_.Status as Status7_, publicatio8_.legacySystemIdentifier as legacySy5_7_, publicatio8_.Copyright_Variant_ID as Copyrigh6_7_, publicatio8_.parentISSN as parentISSN7_, publicatio8_.StrongPersistentIdentifier as StrongPe8_7_, issn9_.ISSN_ID as ISSN_ID8_, issn9_.Title_Variant_ID as Title_Va2_8_, issn9_.Status as Status8_, issn9_.legacySystemIdentifier as legacySy4_8_, issn9_.ISSNNumber as ISSNNumber8_, issn9_.parent as parent8_, issn9_.InArchive as InArchive8_, issn9_.HoldingLibraries as HoldingL8_8_, issn9_.PageEstimate as PageEsti9_8_, issn9_.eISSNNumber as eISSNNu10_8_, issn9_.StrongPersistentIdentifier as StrongP11_8_, titlehisto10_.TitleHistory_ID as TitleHis1_9_, titlehisto10_.Status as Status9_, titlehisto10_.legacySystemIdentifier as legacySy3_9_, titlehisto10_.BookReview as BookReview9_, titlehisto10_.bwIllustration as bwIllust5_9_, titlehisto10_.colorIllustration as colorIll6_9_, titlehisto10_.Frequency as Frequency9_, titlehisto10_.TitleHistory_Variant_ID as TitleHis8_9_, titlehisto10_.StrongPersistentIdentifier as StrongPe9_9_, digitizati11_.DigitizationBatch_ID as Digitiza1_10_, digitizati11_.BatchIdentifier as BatchIde2_10_, digitizati11_.legacySystemIdentifier as legacySy3_10_, digitizati11_.Status as Status10_, digitizati11_.StrongPersistentIdentifier as StrongPe5_10_ from Issue_PublicationUnit issues0_ inner join Issue issue1_ on issues0_.Issue_ID=issue1_.Issue_ID left outer join Variants variants2_ on issue1_.Title_Variant_ID=variants2_.VariantLarge_ID left outer join Variants variants3_ on variants2_.ContinuedVariant_ID=variants3_.VariantLarge_ID left outer join ArticleGroup articlegro4_ on issue1_.ArticleGroup_ID=articlegro4_.ArticleGroup_ID left outer join ArticleGroup articlegro5_ on articlegro4_.parent=articlegro5_.ArticleGroup_ID left outer join Article article6_ on articlegro5_.ArticleGroup_ID=article6_.ArticleGroup_ID left outer join Article article7_ on articlegro4_.ArticleGroup_ID=article7_.ArticleGroup_ID left outer join PublicationStatement publicatio8_ on issue1_.PublicationStatement_ID=publicatio8_.PublicationStatement_ID left outer join ISSN issn9_ on publicatio8_.parentISSN=issn9_.ISSN_ID left outer join TitleHistory titlehisto10_ on issn9_.parent=titlehisto10_.TitleHistory_ID left outer join DigitizationBatch digitizati11_ on issue1_.DigitizationBatch_ID=digitizati11_.DigitizationBatch_ID where issues0_.PublicationUnit_ID=?
2004-11-16 09:30:41,875 DEBUG [AWT-EventQueue-0] impl.BatcherImpl (BatcherImpl.java:249) - preparing statement
2004-11-16 09:30:41,875 DEBUG [AWT-EventQueue-0] type.NullableType (NullableType.java:46) - binding '441' to parameter: 1
2004-11-16 09:30:41,890 DEBUG [AWT-EventQueue-0] loader.Loader (Loader.java:402) - result set contains (possibly empty) collection: [org.jstor.model.repository.PublicationUnit.issues#441]
2004-11-16 09:30:41,890 DEBUG [AWT-EventQueue-0] impl.SessionImpl (SessionImpl.java:3025) - owning entity already loaded: ignoring
2004-11-16 09:30:41,890 DEBUG [AWT-EventQueue-0] loader.Loader (Loader.java:277) - processing result set
2004-11-16 09:30:41,890 DEBUG [AWT-EventQueue-0] type.NullableType (NullableType.java:68) - returning '442' as column: Issue_ID0_
2004-11-16 09:30:41,890 DEBUG [AWT-EventQueue-0] type.NullableType (NullableType.java:68) - returning '443' as column: VariantL1_1_
2004-11-16 09:30:41,890 DEBUG [AWT-EventQueue-0] type.NullableType (NullableType.java:64) - returning null as column: VariantL1_2_
2004-11-16 09:30:41,890 DEBUG [AWT-EventQueue-0] type.NullableType (NullableType.java:68) - returning '427' as column: ArticleG1_3_
2004-11-16 09:30:41,890 DEBUG [AWT-EventQueue-0] type.NullableType (NullableType.java:64) - returning null as column: ArticleG1_4_
2004-11-16 09:30:41,890 DEBUG [AWT-EventQueue-0] type.NullableType (NullableType.java:64) - returning null as column: Article_ID5_
2004-11-16 09:30:41,890 DEBUG [AWT-EventQueue-0] type.NullableType (NullableType.java:64) - returning null as column: Article_ID6_
2004-11-16 09:30:41,906 DEBUG [AWT-EventQueue-0] type.NullableType (NullableType.java:68) - returning '468' as column: Publicat1_7_
2004-11-16 09:30:41,906 DEBUG [AWT-EventQueue-0] type.NullableType (NullableType.java:68) - returning '370' as column: ISSN_ID8_
2004-11-16 09:30:41,906 DEBUG [AWT-EventQueue-0] type.NullableType (NullableType.java:68) - returning '373' as column: TitleHis1_9_
2004-11-16 09:30:41,906 DEBUG [AWT-EventQueue-0] type.NullableType (NullableType.java:68) - returning '369' as column: Digitiza1_10_
2004-11-16 09:30:41,906 DEBUG [AWT-EventQueue-0] loader.Loader (Loader.java:480) - result row: 442, 443, null, 427, null, null, null, 468, 370, 373, 369
2004-11-16 09:30:41,906 DEBUG [AWT-EventQueue-0] type.NullableType (NullableType.java:68) - returning '441' as column: Publicat2___
2004-11-16 09:30:41,906 DEBUG [AWT-EventQueue-0] loader.Loader (Loader.java:367) - found row of collection: [org.jstor.model.repository.PublicationUnit.issues#441]
2004-11-16 09:30:41,906 DEBUG [AWT-EventQueue-0] impl.SessionImpl (SessionImpl.java:3025) - owning entity already loaded: ignoring
2004-11-16 09:30:41,906 DEBUG [AWT-EventQueue-0] loader.Loader (Loader.java:294) - done processing result set (1 rows)
2004-11-16 09:30:41,906 DEBUG [AWT-EventQueue-0] impl.BatcherImpl (BatcherImpl.java:207) - done closing: 0 open PreparedStatements, 0 open ResultSets
2004-11-16 09:30:41,906 DEBUG [AWT-EventQueue-0] impl.BatcherImpl (BatcherImpl.java:269) - closing statement
2004-11-16 09:30:41,906 DEBUG [AWT-EventQueue-0] loader.Loader (Loader.java:314) - total objects hydrated: 0
2004-11-16 09:30:41,906 DEBUG [AWT-EventQueue-0] impl.SessionImpl (SessionImpl.java:3077) - 0 collections were found in result set
2004-11-16 09:30:41,921 DEBUG [AWT-EventQueue-0] impl.SessionImpl (SessionImpl.java:3098) - 0 collections initialized
2004-11-16 09:30:41,921 DEBUG [AWT-EventQueue-0] impl.SessionImpl (SessionImpl.java:3116) - initializing non-lazy collections
2004-11-16 09:30:41,921 DEBUG [AWT-EventQueue-0] impl.SessionImpl (SessionImpl.java:3269) - collection initialized

[/code]

tazzzzz · **Joined:** Tue Mar 30, 2004 12:23 pm **Posts:** 14

I'm working on this project and have some more information to add here.

We've been stepping through the Hibernate code a bit this morning and find that the last set of debugging messages are useful:

2004-11-18 09:04:05,589 DEBUG [main] impl.SessionImpl (SessionImpl.java:3260) - initializing collection [org.jstor.model.repository.Article.notes#3020]
2004-11-18 09:04:05,589 DEBUG [main] impl.SessionImpl (SessionImpl.java:3261) - checking second-level cache
2004-11-18 09:04:05,589 DEBUG [main] impl.SessionImpl (SessionImpl.java:3267) - collection not cached
2004-11-18 09:06:56,469 DEBUG [main] impl.BatcherImpl (BatcherImpl.java:200) - about to open: 0 open PreparedStatements, 0 open ResultSets
2004-11-18 09:06:56,484 DEBUG [main] impl.BatcherImpl (BatcherImpl.java:226) - select notes0_.Article_ID as Article_ID__, notes0_.Notes as Notes__, notes0_.Notes_Index as Notes_In3___ from Article_Notes notes0_ where notes0_.Article_ID=?
2004-11-18 09:06:56,484 DEBUG [main] impl.BatcherImpl (BatcherImpl.java:249) - preparing statement
2004-11-18 09:06:56,500 DEBUG [main] type.NullableType (NullableType.java:46) - binding '3020' to parameter: 1
2004-11-18 09:10:22,865 DEBUG [main] loader.Loader (Loader.java:402) - result set contains (possibly empty) collection: [org.jstor.model.repository.Article.notes#3020]
2004-11-18 09:10:22,880 DEBUG [main] impl.SessionImpl (SessionImpl.java:3025) - owning entity already loaded: ignoring
2004-11-18 09:10:39,709 DEBUG [main] loader.Loader (Loader.java:277) - processing result set
2004-11-18 09:11:15,538 DEBUG [main] loader.Loader (Loader.java:294) - done processing result set (0 rows)
2004-11-18 09:11:16,413 DEBUG [main] impl.BatcherImpl (BatcherImpl.java:207) - done closing: 0 open PreparedStatements, 0 open ResultSets
2004-11-18 09:11:16,429 DEBUG [main] impl.BatcherImpl (BatcherImpl.java:269) - closing statement
2004-11-18 09:17:38,657 DEBUG [main] impl.SessionImpl (SessionImpl.java:3077) - 0 collections were found in result set
2004-11-18 09:17:46,048 DEBUG [main] impl.SessionImpl (SessionImpl.java:3098) - 0 collections initialized

This is with a slightly different set of data, but we're running into the same issue. This is a lazy List that it *thinks* it's initializing. However, the last logging statement says that 0 collections were initialized.

The query that ran looked valid and, in this case, returned a resultset with no rows. (In the other case in the original posting, the resultset had one row). But, the empty List of results is never actually put into place in the Hibernate List object.

The loadingCollections map in SessionImpl is empty, causing a null to be passed in for "resultSetCollections" in SessionImpl.endLoadingCollections. So, nothing happens to the collection that was supposed to have been initialized.

Tracing this back further, the "owning entity already loaded line" comes from getLoadingCollection in SessionImpl. This is where Hibernate decides, essentially, not to initialize that List. Given that this code is called from a method that is supposed to initialize non-lazy collections, what it's doing makes sense.

The trouble is that the whole reason things got into the initialize path was that we had a lazy collection that was being accessed (the equals method was being called), and therefore needed initialization.

Perhaps there is some other bit of code that is supposed to be called when initializing a lazy collection? I haven't yet come across the difference between what's happening here and how things work in "normal" circumstances, when everything goes just fine. I'll try tracing through that path next.

Kevin

tazzzzz · **Joined:** Tue Mar 30, 2004 12:23 pm **Posts:** 14

I may be able to write a test case for this. The trouble seems to be this series of steps:

1) create a class with a lazy collection
2) Load up an entity of that class
3) do whatever you want, but don't touch that lazy collection
4) flush the session
5) try to access that lazy collection

The flush results in collectionsByKey getting cleared. Because you never touched that lazy collection, it doesn't get re-added. It also doesn't seem to get reinitialized.

AFAIK, it's legal to flush and then keep using those objects for later flushing, so this seems like a bug.

Kevin

tazzzzz · **Joined:** Tue Mar 30, 2004 12:23 pm **Posts:** 14

Here's a possible fix. I don't know if the only drawback is memory consumption, or if there's a way to get at something more optimal.

in SessionImpl.postFlush - get rid of collectionsByKey.clear() and the line that re-adds entries to collectionsByKey.

If there's a way to easily find out if a collection is lazy, you could just change the condition for re-adding entries to ce.reached || "collection is lazy"

Kevin

max · **Posted:** Fri Nov 19, 2004 3:47 am

ok - this might be a bug ... but you don't show the code and mapping that can be used to decide on this.

So, please provide a failing runnable test case - with mapping and code!

Thank you ;)

tazzzzz · **Joined:** Tue Mar 30, 2004 12:23 pm **Posts:** 14

I'm trying to make a minimal test to reproduce this, but it appears that the minimal test case is a bit more complicated than I thought.

In my tests so far, the CollectionEntry ce.reached flag is getting set to true for the collection in question, so the problem doesn't come up. I need to spend a bit more time figuring out what condition could cause ce.reached to not get set.

max · **Posted:** Fri Nov 19, 2004 12:47 pm

ok - we will wait with anticipation ;)

tazzzzz · **Joined:** Tue Mar 30, 2004 12:23 pm **Posts:** 14

We figured out what was happening here... apparently, some code in our Interceptor's findDirty method was causing a lazy collection to be initialized. This works fine the first time around, but doesn't work after another flush.

I don't know if this is supposed to work this way. My original suggestion of not clearing the collectionsByKey map does fix this problem, but is probably suboptimal.

Here's a test class you can drop in to the existing org.hibernate.test package. We're running against 2.1.6.

package org.hibernate.test;

import java.io.Serializable;
import java.util.ArrayList;
import java.util.Iterator;
import java.util.List;
import net.sf.hibernate.CallbackException;
import net.sf.hibernate.Interceptor;
import net.sf.hibernate.Session;
import net.sf.hibernate.type.Type;

public class LazyLoadingAfterFlushTest extends TestCase
{
public LazyLoadingAfterFlushTest(String x)
{
super(x);
}

public void testLazyLoadingShouldStillWorkAfterFlush() throws Exception
{
Session s = getSessions().openSession(new DirtyInterceptor());
Category cat1 = new Category();
Category cat2 = new Category();
List subList = new ArrayList();
subList.add(cat2);
cat1.setSubcategories(subList);
Serializable cat1Key = s.save(cat1);
s.save(cat2);
s.flush();
s.close();
s = getSessions().openSession(new DirtyInterceptor());
cat1 = (Category) s.load(Category.class, cat1Key);
s.flush();
s.flush();
cat1.getSubcategories().size();
s.close();
}

protected String[] getMappings() {
return new String[] {
"Category.hbm.xml"
};
}

public static class DirtyInterceptor implements Interceptor{

public boolean onLoad(Object entity, Serializable id, Object[] state, String[] propertyNames, Type[] types) throws CallbackException
{
return false;
}

public boolean onFlushDirty(Object entity, Serializable id, Object[] currentState, Object[] previousState, String[] propertyNames, Type[] types) throws CallbackException
{
return false;
}

public boolean onSave(Object entity, Serializable id, Object[] state, String[] propertyNames, Type[] types) throws CallbackException
{
return false;
}

public void onDelete(Object entity, Serializable id, Object[] state, String[] propertyNames, Type[] types) throws CallbackException
{

}

public void preFlush(Iterator entities) throws CallbackException
{

}

public void postFlush(Iterator entities) throws CallbackException
{

}

public Boolean isUnsaved(Object entity)
{
return null;
}

public int[] findDirty(Object entity, Serializable id, Object[] currentState, Object[] previousState, String[] propertyNames, Type[] types)
{
Category catEntity = (Category) entity;
catEntity.getSubcategories().size();
return null;
}

public Object instantiate(Class clazz, Serializable id) throws CallbackException
{
return null;
}

}
}

max · **Posted:** Fri Nov 19, 2004 3:41 pm

aah - accessing the session is not allowed in the interceptors methods!

As par the javadocs:

Quote:

* The <tt>Session</tt> may not be invoked from a callback (nor may a callback cause a collection or proxy to
* be lazily initialized).

So this is NOT a bug in Hibernates code, but a "misuse" of the API - please write that at your blog ;)

A fun chase though ;)

tazzzzz · **Joined:** Tue Mar 30, 2004 12:23 pm **Posts:** 14

Indeed... I've read the javadocs for interceptor, but I had been paying more attention to the individual method docs... particularly since that interceptor was started several months back.

And, yes, I will indeed post that to my blog :)

Kevin