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

**URL:** <https://discourse.hibernate.org/t/npe-when-enabling-debug-on-orm-results-loading-in-hibernate-6/7307>\
**Category:** Hibernate ORM\
**Created:** [February 27, 2023, 3:49pm UTC](https://discourse.hibernate.org/t/npe-when-enabling-debug-on-orm-results-loading-in-hibernate-6/7307 "2023-02-27T15:49:13Z")\
**Posts on this page:** 3\
**Page:** 1

<div class="post-metadata">

**Author:** ![sahawut](https://yyz1.discourse-cdn.com/flex035/user_avatar/discourse.hibernate.org/sahawut/32/2194_2.png) [@sahawut](https://discourse.hibernate.org/u/sahawut)\
**Post date:** [February 27, 2023, 3:49pm UTC](https://discourse.hibernate.org/t/npe-when-enabling-debug-on-orm-results-loading-in-hibernate-6/7307/1 "2023-02-27T15:49:13Z")

</div>

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.

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

```

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

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

```auto
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.

---

<div class="post-metadata">

**Author:** ![beikov](https://yyz1.discourse-cdn.com/flex035/user_avatar/discourse.hibernate.org/beikov/32/258_2.png) [@beikov](https://discourse.hibernate.org/u/beikov)\
**Post date:** [February 27, 2023, 7:33pm UTC](https://discourse.hibernate.org/t/npe-when-enabling-debug-on-orm-results-loading-in-hibernate-6/7307/2 "2023-02-27T19:33:25Z")

</div>

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.

---

<div class="post-metadata">

**Author:** ![sahawut](https://yyz1.discourse-cdn.com/flex035/user_avatar/discourse.hibernate.org/sahawut/32/2194_2.png) [@sahawut](https://discourse.hibernate.org/u/sahawut)\
**Post date:** [February 27, 2023, 8:21pm UTC](https://discourse.hibernate.org/t/npe-when-enabling-debug-on-orm-results-loading-in-hibernate-6/7307/3 "2023-02-27T20:21:53Z")

</div>

I copied the content of this post to [[HHH-16234] - Hibernate JIRA](https://hibernate.atlassian.net/browse/HHH-16234).