Message Title

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.

<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: