We have found that Hibernate crashes when its logging level is set to debug and we create an object with a bunch of empty collections. Changing the logging level to info avoids the crash.

Here are the details:

We are trying to create a data model we designed yesterday. The central object is a Campaign object which has four collections: a set of SourceLists, a set of CampaignLists, a set of JobDescriptions, and a set of WorkRequests.

Using good test-driven development, we have a test case:


public void testCreateClient () throws HibernateException {
SessionFactory factory = PersistenceManager.sessionFactory();

Session session = factory.openSession();

// null set
Set n = new HashSet();
//
Client client = new Client("test", n);
session.save(client);
//

Campaign campaign = new Campaign("test1", client, n, n, n, n);

client.getCampaigns().add(campaign);

// session.save(campaign);

session.flush();
session.close();
}


We were running with this log4j.properties:


### direct log messages to stdout ###
log4j.appender.stdout=org.apache.log4j.ConsoleAppender
log4j.appender.stdout.Target=System.out
log4j.appender.stdout.layout=org.apache.log4j.PatternLayout
log4j.appender.stdout.layout.ConversionPattern=%d{ABSOLUTE} %5p %c{1}:%L - %m%n

log4j.rootLogger=debug,stdout


When we run this test case, we get:


net.sf.hibernate.PropertyAccessException: IllegalArgumentException occurred calling getter of com.nimblefish.core.dao.SourceList.id at
net.sf.hibernate.property.BasicPropertyAccessor$BasicGetter.get(BasicPropertyAccessor.java:110) net.sf.hibernate.persister.AbstractEntityPersister.getIdentifier(AbstractEntityPersister.java:310) net.sf.hibernate.proxy.HibernateProxyHelper.getIdentifier(HibernateProxyHelper.java:50) net.sf.hibernate.type.EntityType.toString(EntityType.java:84)
net.sf.hibernate.type.PersistentCollectionType.toString(PersistentCollectionType.java:81)
net.sf.hibernate.impl.Printer.toString(Printer.java:49)
net.sf.hibernate.impl.Printer.toString(Printer.java:82)
net.sf.hibernate.impl.SessionImpl.flushEverything(SessionImpl.java:2228)
net.sf.hibernate.impl.SessionImpl.flush(SessionImpl.java:2186)
com.nimblefish.core.test.persist.PersistenceManagerTest.testCreateClient(PersistenceManagerTest.java:83)


This is very weird because we haven't *constructed* any SourceList objects *at all*! Hibernate is apparently trying to print the contents of an empty collection, and CGLIB is trying to wrap a null object and print it?!

If we change log4j.properties like so:


log4j.rootLogger=info,stdout


then the exception DOES NOT HAPPEN.

Here's the section of the fatal debug output:


10:29:43,195 DEBUG SessionImpl:2768 - Collection found: [com.nimblefish.core.dao.Campaign.sourceLists#1], was: [<unreferenced>]
10:29:43,195 DEBUG SessionImpl:2768 - Collection found: [com.nimblefish.core.dao.Campaign.campaignLists#1], was: [<unreferenced>]
10:29:43,195 DEBUG SessionImpl:2768 - Collection found: [com.nimblefish.core.dao.Campaign.workRequests#1], was: [<unreferenced>]
10:29:43,195 DEBUG SessionImpl:2768 - Collection found: [com.nimblefish.core.dao.Campaign.jobDescriptions#1], was: [<unreferenced>]
10:29:43,210 DEBUG SessionImpl:2664 - Processing unreferenced collections
10:29:43,210 DEBUG SessionImpl:2678 - Scheduling collection removes/(re)creates/updates
10:29:43,210 DEBUG SessionImpl:2217 - Flushed: 0 insertions, 0 updates, 0 deletions to 2 objects
10:29:43,210 DEBUG SessionImpl:2222 - Flushed: 5 (re)creations, 0 updates, 0 removals to 5 collections
10:29:43,210 DEBUG Printer:75 - listing entities:
10:29:43,226 ERROR BasicPropertyAccessor:106 - IllegalArgumentException in class: com.nimblefish.core.dao.SourceList, getter method of property: id


Here are the mappings:


<?xml version="1.0"?>
<!DOCTYPE hibernate-mapping
PUBLIC "-//Hibernate/Hibernate Mapping DTD//EN"
"http://hibernate.sourceforge.net/hibernate-mapping-2.0.dtd">

<hibernate-mapping>

<class name="com.nimblefish.core.dao.Client">

<id name="id" type="long" unsaved-value="null" >
<generator class="native"/>
</id>

<property name="name" type="string"/>

<set name="campaigns" inverse="true" cascade="all">
<key column="client_id"/>
<one-to-many class="com.nimblefish.core.dao.Campaign"/>
</set>
</class>

<class name="com.nimblefish.core.dao.Campaign">

<id name="id" type="long" unsaved-value="null" >
<generator class="native"/>
</id>

<property name="name" type="string"/>

<many-to-one name="client" column="client_id" not-null="true"
class="com.nimblefish.core.dao.Client"/>

<set name="sourceLists" inverse="true" cascade="all">
<key column="campaign_id"/>
<one-to-many class="com.nimblefish.core.dao.SourceList"/>
</set>

<set name="campaignLists" inverse="true" cascade="all">
<key column="campaign_id"/>
<one-to-many class="com.nimblefish.core.dao.CampaignList"/>
</set>

<set name="workRequests" inverse="true" cascade="all">
<key column="campaign_id"/>
<one-to-many class="com.nimblefish.core.dao.WorkRequest"/>
</set>

<set name="jobDescriptions" inverse="true" cascade="all">
<key column="campaign_id"/>
<one-to-many class="com.nimblefish.core.dao.JobDescription"/>
</set>

</class>

</hibernate-mapping>


We generated the code for Client.java and Campaign.java using codegen (which didn't complain at all).

This should be fixed :-)

Cheers!
Rob

Hum, try not to use the same new HashSet for all collection init. I don't know if that's the problem, but it sucks for sure.

Well shut my mouth, that WAS a problem. Changing that fixed it.

Wow. Thanks Emmanuel!

Cheers!
Rob

eheh, actually I started to trust you and looked at the Hibernate code before being doubtful :)