[hibernate-issues] [JIRA] (HHH-16234) NPE when enabling DEBUG on orm.results.loading in Hibernate 6.1.7

Sahawut Wesaratchakit ( https://hibernate.atlassian.net/secure/ViewProfile.jspa?accountId=557058%... ) *created* an issue Hibernate ORM ( https://hibernate.atlassian.net/browse/HHH?atlOrigin=eyJpIjoiY2M0NzlhNWM1... ) / Bug ( https://hibernate.atlassian.net/browse/HHH-16234?atlOrigin=eyJpIjoiY2M0Nz... ) HHH-16234 ( https://hibernate.atlassian.net/browse/HHH-16234?atlOrigin=eyJpIjoiY2M0Nz... ) NPE when enabling DEBUG on orm.results.loading in Hibernate 6.1.7 ( https://hibernate.atlassian.net/browse/HHH-16234?atlOrigin=eyJpIjoiY2M0Nz... ) Issue Type: Bug Affects Versions: 6.1.7 Assignee: Unassigned Components: hibernate-core Created: 27/Feb/2023 12:20 PM Environment: Hibernate-6.1.7, Java-17, Windows-10, PostGreSQL Priority: Minor Reporter: Sahawut Wesaratchakit ( https://hibernate.atlassian.net/secure/ViewProfile.jspa?accountId=557058%... ) 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; } @beikov identified it as a bug ( https://discourse.hibernate.org/t/npe-when-enabling-debug-on-orm-results-... ). At this point, we work around it by setting the log level to INFO or above. ( https://hibernate.atlassian.net/browse/HHH-16234#add-comment?atlOrigin=ey... ) Add Comment ( https://hibernate.atlassian.net/browse/HHH-16234#add-comment?atlOrigin=ey... ) Get Jira notifications on your phone! Download the Jira Cloud app for Android ( https://play.google.com/store/apps/details?id=com.atlassian.android.jira.... ) or iOS ( https://itunes.apple.com/app/apple-store/id1006972087?pt=696495&ct=Em... ) This message was sent by Atlassian Jira (v1001.0.0-SNAPSHOT#100217- sha1:58f696e )