Missing PersistenceException cause message in refresh failure warn log [SPR-16559]

[spring-projects-issues]

cda opened SPR-16559 and commented

Logging a BeanCreationException containing a PersistenceException doesn't log the PersistenceException's cause (a MappingException in my case).

Log prints:

Exception encountered during context initialization - cancelling refresh attempt: org.springframework.beans.factory.BeanCreationException: Error creating bean with name 'entityManagerFactory' defined in class path resource [org/springframework/boot/autoconfigure/orm/jpa/HibernateJpaConfiguration.class]: Invocation of init method failed; nested exception is javax.persistence.PersistenceException: [PersistenceUnit: default] Unable to build Hibernate SessionFactory
but the important message is missing (extracted from manual debug):

org.hibernate.MappingException: Could not determine type for: pse.shop.component.ShopComponent, at table: shop_template_component, for columns: [org.hibernate.mapping.Column(component)]

From my investigation, the issue is in NestedExceptionUtls.java, line 52:

sb.append("nested exception is ").append(cause);
where cause is an instance of PersistenceException, but PersistenceException.toString() doesn't contain the cause string.

This issue adds development overhead requiring manual debug to extract the exception message.

---

Affects: 4.3.14, 5.0.4

Referenced from: commits eb9c43d, c15f23b

Backported to: 4.3.15

[spring-projects-issues]

Juergen Hoeller commented

You should see the full stacktrace for such an exception elsewhere, at the outermost level of initialization - possibly in your Servlet container log -, including all nested causes and their individual messages. That said, we should nevertheless do something about the PersistenceException case here... even if arguably Hibernate itself should include the nested message in the PersistenceException message.

[spring-projects-issues]

Juergen Hoeller commented

Also, I assume you're using an older Hibernate version? With Hibernate 5.2+, HibernateException itself extends PersistenceException, so there shouldn't be any extra nesting with swallowed nested messages anymore.

[spring-projects-issues]

cda commented

I'm using Hibernate 5.2.14.
My debug trace is as follows:
EntityManagerFactoryBuilderImpl.java: line 895, method "EntityManagerFactory build()":

catch (Exception e) {
     throw persistenceException( "Unable to build Hibernate SessionFactory", e );
}

, where persistenceException method creates a new PersistenceException object instance:

private PersistenceException persistenceException(String message, Exception cause) {
     return new PersistenceException(
               getExceptionHeader() + message,
               cause
     );
}

[spring-projects-issues]

cda commented

Stacktrace when the MappingException is being thrown:

at org.hibernate.mapping.SimpleValue.getType(SimpleValue.java:455)
at org.hibernate.mapping.SimpleValue.isValid(SimpleValue.java:422)
at org.hibernate.mapping.Property.isValid(Property.java:226)
at org.hibernate.mapping.PersistentClass.validate(PersistentClass.java:597)
at org.hibernate.mapping.RootClass.validate(RootClass.java:265)
at org.hibernate.boot.internal.MetadataImpl.validate(MetadataImpl.java:329)
at org.hibernate.boot.internal.SessionFactoryBuilderImpl.build(SessionFactoryBuilderImpl.java:459)
at org.hibernate.jpa.boot.internal.EntityManagerFactoryBuilderImpl.build(EntityManagerFactoryBuilderImpl.java:892)
at org.springframework.orm.jpa.vendor.SpringHibernateJpaPersistenceProvider.createContainerEntityManagerFactory(SpringHibernateJpaPersistenceProvider.java:57)
at org.springframework.orm.jpa.LocalContainerEntityManagerFactoryBean.createNativeEntityManagerFactory(LocalContainerEntityManagerFactoryBean.java:365)
at org.springframework.orm.jpa.AbstractEntityManagerFactoryBean.buildNativeEntityManagerFactory(AbstractEntityManagerFactoryBean.java:388)
at org.springframework.orm.jpa.AbstractEntityManagerFactoryBean.afterPropertiesSet(AbstractEntityManagerFactoryBean.java:377)
at org.springframework.orm.jpa.LocalContainerEntityManagerFactoryBean.afterPropertiesSet(LocalContainerEntityManagerFactoryBean.java:341)
at org.springframework.beans.factory.support.AbstractAutowireCapableBeanFactory.invokeInitMethods(AbstractAutowireCapableBeanFactory.java:1769)
at org.springframework.beans.factory.support.AbstractAutowireCapableBeanFactory.initializeBean(AbstractAutowireCapableBeanFactory.java:1706)
at org.springframework.beans.factory.support.AbstractAutowireCapableBeanFactory.doCreateBean(AbstractAutowireCapableBeanFactory.java:583)
at org.springframework.beans.factory.support.AbstractAutowireCapableBeanFactory.createBean(AbstractAutowireCapableBeanFactory.java:502)
at org.springframework.beans.factory.support.AbstractBeanFactory.lambda$doGetBean$0(AbstractBeanFactory.java:312)
at org.springframework.beans.factory.support.AbstractBeanFactory$$Lambda$104.698530155.getObject(Unknown Source:-1)
at org.springframework.beans.factory.support.DefaultSingletonBeanRegistry.getSingleton(DefaultSingletonBeanRegistry.java:228)
- locked <0x1b4c> (a java.util.concurrent.ConcurrentHashMap)
at org.springframework.beans.factory.support.AbstractBeanFactory.doGetBean(AbstractBeanFactory.java:310)
at org.springframework.beans.factory.support.AbstractBeanFactory.getBean(AbstractBeanFactory.java:200)
at org.springframework.context.support.AbstractApplicationContext.getBean(AbstractApplicationContext.java:1085)
at org.springframework.context.support.AbstractApplicationContext.finishBeanFactoryInitialization(AbstractApplicationContext.java:858)
at org.springframework.context.support.AbstractApplicationContext.refresh(AbstractApplicationContext.java:549)
- locked <0x1b4d> (a java.lang.Object)
at org.springframework.boot.web.servlet.context.ServletWebServerApplicationContext.refresh(ServletWebServerApplicationContext.java:140)
at org.springframework.boot.SpringApplication.refresh(SpringApplication.java:752)
at org.springframework.boot.SpringApplication.refreshContext(SpringApplication.java:388)
at org.springframework.boot.SpringApplication.run(SpringApplication.java:327)
at org.springframework.boot.SpringApplication.run(SpringApplication.java:1246)
at org.springframework.boot.SpringApplication.run(SpringApplication.java:1234)
at pse.Application.main(Application.java:61)
at sun.reflect.NativeMethodAccessorImpl.invoke0(NativeMethodAccessorImpl.java:-1)
at sun.reflect.NativeMethodAccessorImpl.invoke(NativeMethodAccessorImpl.java:62)
at sun.reflect.DelegatingMethodAccessorImpl.invoke(DelegatingMethodAccessorImpl.java:43)
at java.lang.reflect.Method.invoke(Method.java:498)
at org.springframework.boot.devtools.restart.RestartLauncher.run(RestartLauncher.java:49)

[spring-projects-issues]

Juergen Hoeller commented

Indeed, it looks like Hibernate 5.2 is still wrapping its exception in a PersistenceException when building an EntityManagerFactory... just not anymore when calling operations on an EntityManager. That's probably unintended but indeed a common source of frustration then.

[spring-projects-issues]

Juergen Hoeller commented

This will be available in the upcoming 5.0.5.BUILD-SNAPSHOT. Please give it a try if you have the chance!