NPE when enabling DEBUG on orm.results.loading in Hibernate 6

Hibernate ORM
1

Enabling DEBUG or lower level on org.hibernate.orm.results.loading caused the toString() method of my entity class to throw NullPointerException (NPE) in Hibernate 6.1.7.

Here is the snippet that caused the NPE from my logback-test.xml file.

<logger name="org.hibernate.orm.results.loading" >
	<level value="DEBUG" /> 
</logger>

Here is the toString() method of my PcccFrame entity class, which throws NPE:

public String toString() {
	return this.getPccc().getNaturalKey() + ":" + this.getDrugName();
}

Note that my pccc field in the PcccFrame entity is a required (nullable = false) @ManyToOne reference property and its naturalKey is a required String property
(you may just ignore drugName field; it’s not relevant).

In other words, my PcccFrame object can never have a dangling pccc reference in the database. I am relying on Hibernate to eager-load pccc for me.

I got a NullPointerException when I try to access a collection of PcccFrame objects from a pccc instance. The (partial) stack trace is as follows:

java.lang.NullPointerException: Cannot invoke "com.example.Pccc.getNaturalKey()" because the return value of "com.example.PcccFrame.getPccc()" is null

	at com.example.PcccFrame.toString(PcccFrame.java:187)
	at java.base/java.util.Formatter$FormatSpecifier.printString(Formatter.java:3056)
	at java.base/java.util.Formatter$FormatSpecifier.print(Formatter.java:2933)
	at java.base/java.util.Formatter.format(Formatter.java:2689)
	at java.base/java.util.Formatter.format(Formatter.java:2625)
	at java.base/java.lang.String.format(String.java:4143)
	at org.jboss.logging.Slf4jLocationAwareLogger.doLogf(Slf4jLocationAwareLogger.java:81)
	at org.jboss.logging.Logger.debugf(Logger.java:739)
	at org.hibernate.sql.results.graph.entity.AbstractEntityInitializer.instantiateEntity(AbstractEntityInitializer.java:708)
	at org.hibernate.sql.results.graph.entity.AbstractEntityInitializer.resolveEntityInstance(AbstractEntityInitializer.java:699)
	at org.hibernate.sql.results.graph.entity.AbstractEntityInitializer.resolveInstance(AbstractEntityInitializer.java:666)
	at org.hibernate.sql.results.graph.entity.AbstractEntityInitializer.resolveEntityInstance(AbstractEntityInitializer.java:554)
	at org.hibernate.sql.results.graph.entity.AbstractEntityInitializer.resolveInstance(AbstractEntityInitializer.java:446)
	at org.hibernate.sql.results.internal.StandardRowReader.coordinateInitializers(StandardRowReader.java:140)
	at org.hibernate.sql.results.internal.StandardRowReader.readRow(StandardRowReader.java:97)
	at org.hibernate.sql.results.spi.ListResultsConsumer.consume(ListResultsConsumer.java:178)
	at org.hibernate.sql.results.spi.ListResultsConsumer.consume(ListResultsConsumer.java:33)
	at org.hibernate.sql.exec.internal.JdbcSelectExecutorStandardImpl.doExecuteQuery(JdbcSelectExecutorStandardImpl.java:443)
	at org.hibernate.sql.exec.internal.JdbcSelectExecutorStandardImpl.executeQuery(JdbcSelectExecutorStandardImpl.java:166)
	at org.hibernate.sql.exec.internal.JdbcSelectExecutorStandardImpl.list(JdbcSelectExecutorStandardImpl.java:91)
	at org.hibernate.sql.exec.spi.JdbcSelectExecutor.list(JdbcSelectExecutor.java:31)
	at org.hibernate.loader.ast.internal.SingleIdLoadPlan.load(SingleIdLoadPlan.java:140)
	at org.hibernate.loader.ast.internal.SingleIdLoadPlan.load(SingleIdLoadPlan.java:98)
	at org.hibernate.loader.ast.internal.CollectionLoaderBatchKey.load(CollectionLoaderBatchKey.java:122)
	at org.hibernate.persister.collection.AbstractCollectionPersister.initialize(AbstractCollectionPersister.java:789)
	at org.hibernate.event.internal.DefaultInitializeCollectionEventListener.onInitializeCollection(DefaultInitializeCollectionEventListener.java:75)
	at org.hibernate.event.service.internal.EventListenerGroupImpl.fireEventOnEachListener(EventListenerGroupImpl.java:107)
	at org.hibernate.internal.SessionImpl.initializeCollection(SessionImpl.java:1710)
	at org.hibernate.collection.spi.AbstractPersistentCollection.lambda$initialize$3(AbstractPersistentCollection.java:617)
	at org.hibernate.collection.spi.AbstractPersistentCollection.withTemporarySessionIfNeeded(AbstractPersistentCollection.java:265)
	at org.hibernate.collection.spi.AbstractPersistentCollection.initialize(AbstractPersistentCollection.java:615)
	at org.hibernate.collection.spi.AbstractPersistentCollection.read(AbstractPersistentCollection.java:136)
	at org.hibernate.collection.spi.PersistentSet.iterator(PersistentSet.java:164)
	at java.base/java.util.AbstractCollection.addAll(AbstractCollection.java:335)
	at com.example.ClassificationService.getPropertyCollection(ClassificationService.java:380)
	...

Our code has been like this since Hibernate 5 and it hasn’t changed.
We recently upgraded to Hibernate 6 and began to see this kind of NPE when debugging.
Peeking at the source code of AbstractEntityInitializer.java (line 708 as of hibernate-core version 6.1.7.Final),
it seems the debug print shouldn’t be too aggressively assuming that the Hibernate-managed reference is already loaded.

Here is the instantiateEntity method of AbstractEntityInitializer that I peeked at:

private Object instantiateEntity(Object entityIdentifier, SharedSessionContractImplementor session) {
	final Object instance = session.instantiate( concreteDescriptor.getEntityName(), entityKey.getIdentifier() );
	if ( EntityLoadingLogging.DEBUG_ENABLED ) {
		EntityLoadingLogging.ENTITY_LOADING_LOGGER.debugf(
				"(%s) Created new entity instance [%s] : %s",
				getSimpleConcreteImplName(),
				toLoggableString( getNavigablePath(), entityIdentifier),
				instance  // Is this too aggressively assuming that all properties in `instance` have been already fully loaded?
		);
	}
	return instance;
}

Please advise if this is a Hibernate bug. At this point, we work around it by setting the log level to INFO or above.

2

You can create a JIRA ticket for this. I guess it’s not very sensible to call the actual toString() method at this point, and we should rather log the identity hash code instead.

3

I copied the content of this post to [HHH-16234] - Hibernate JIRA.

1 Like