EntityManagerFactory startup failure in deferred mode is only available on first use

[DredderGun]

Hello everyone!
Recently I observed a strange behavior while starting a simple project with Spring-boot + Hibernate that confuse me a lot.
I wrote a simple JPA entity and tried to start the project, but no entity wrote to a database. After long time searching why I accidentally had seen that the app after around 1-2 minute of correct working shut down with exit code 0 and the answer of my question appeared in a console: nested exception is org.hibernate.MappingException: Could not instantiate id generator [entity-name=null]
But why the app keeps silent before that moment and doesn`t show me any information about entity creation process? I think this is not trivial and confusing.

My application.properties for reproduction

spring.session.store-type=jdbc
spring.datasource.driver-class-name=org.postgresql.Driver
spring.jpa.database-platform=org.hibernate.dialect.PostgreSQL10Dialect
spring.datasource.url= jdbc:postgresql://localhost:5432/***
spring.datasource.username=***
spring.datasource.password=***
spring.jpa.properties.hibernate.default_schema=demo
spring.jpa.generate-ddl=true
spring.jpa.hibernate.ddl-auto=create

And a simple JPA entity with error:

@Entity
public class Item {
    @Id
    public Long id;

    @ElementCollection
    @CollectionTable(name = "IMAGE")
    @Column(name = "FILENAME")
    @CollectionId(
            columns = @Column(name = "IMAGE_ID"),
            type = @Type(type = "long"),
            generator = "SEQUENCE" <<<<< NOT CORRECT
    )
    protected List<String> images = new ArrayList<>();
}

Now if you try to start a project then you will not see any error message for almost a one or two minutes and you doesn`t get what the problem. When you fix the error the entity writes to DB without problems

Srping-boot version: v2.3.5.RELEASE

[snicoll]

But why the app keeps silent before that moment and doesn`t show me any information about entity creation process?

I don't know but given what you've shared and the exception it is also unclear why you think this is a problem in Spring Boot. If you want support, please take the time to share a small sample that reproduces the problem. You can do so by attaching a zip to this issue or share a link to a GitHub repository.

[DredderGun]

@snicoll
But it`s almost all that you need to reproduce. I am attaching a zip with all project to this message:
simple-demo-app.zip

[snicoll]

But it`s almost all that you need to reproduce

Sorry but guessing what the missing pieces are can lead to wasted efforts. I can reproduce the problem and it's yet another instance of a deadlock due to deferred bootstrap.

You can workaround the problem for now by adding the following to your project's configuration:

spring.data.jpa.repositories.bootstrap-mode=default

[snicoll]

So this isn't a deadlock as I suspected initially. If you're not using deferred mode for JPA, the JPA instructor is initialised in the main thread and leads to the following:

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; nested exception is org.hibernate.MappingException: Could not instantiate id generator [entity-name=null]
	at org.springframework.beans.factory.support.AbstractAutowireCapableBeanFactory.initializeBean(AbstractAutowireCapableBeanFactory.java:1794) ~[spring-beans-5.2.11.RELEASE.jar:5.2.11.RELEASE]
	at org.springframework.beans.factory.support.AbstractAutowireCapableBeanFactory.doCreateBean(AbstractAutowireCapableBeanFactory.java:594) ~[spring-beans-5.2.11.RELEASE.jar:5.2.11.RELEASE]
	at org.springframework.beans.factory.support.AbstractAutowireCapableBeanFactory.createBean(AbstractAutowireCapableBeanFactory.java:516) ~[spring-beans-5.2.11.RELEASE.jar:5.2.11.RELEASE]
	at org.springframework.beans.factory.support.AbstractBeanFactory.lambda$doGetBean$0(AbstractBeanFactory.java:324) ~[spring-beans-5.2.11.RELEASE.jar:5.2.11.RELEASE]
	at org.springframework.beans.factory.support.DefaultSingletonBeanRegistry.getSingleton(DefaultSingletonBeanRegistry.java:234) ~[spring-beans-5.2.11.RELEASE.jar:5.2.11.RELEASE]
	at org.springframework.beans.factory.support.AbstractBeanFactory.doGetBean(AbstractBeanFactory.java:322) ~[spring-beans-5.2.11.RELEASE.jar:5.2.11.RELEASE]
	at org.springframework.beans.factory.support.AbstractBeanFactory.getBean(AbstractBeanFactory.java:202) ~[spring-beans-5.2.11.RELEASE.jar:5.2.11.RELEASE]
	at org.springframework.context.support.AbstractApplicationContext.getBean(AbstractApplicationContext.java:1109) ~[spring-context-5.2.11.RELEASE.jar:5.2.11.RELEASE]
	at org.springframework.context.support.AbstractApplicationContext.finishBeanFactoryInitialization(AbstractApplicationContext.java:869) ~[spring-context-5.2.11.RELEASE.jar:5.2.11.RELEASE]
	at org.springframework.context.support.AbstractApplicationContext.refresh(AbstractApplicationContext.java:551) ~[spring-context-5.2.11.RELEASE.jar:5.2.11.RELEASE]
	at org.springframework.boot.web.servlet.context.ServletWebServerApplicationContext.refresh(ServletWebServerApplicationContext.java:143) ~[spring-boot-2.3.6.RELEASE.jar:2.3.6.RELEASE]
	at org.springframework.boot.SpringApplication.refresh(SpringApplication.java:758) ~[spring-boot-2.3.6.RELEASE.jar:2.3.6.RELEASE]
	at org.springframework.boot.SpringApplication.refresh(SpringApplication.java:750) ~[spring-boot-2.3.6.RELEASE.jar:2.3.6.RELEASE]
	at org.springframework.boot.SpringApplication.refreshContext(SpringApplication.java:405) ~[spring-boot-2.3.6.RELEASE.jar:2.3.6.RELEASE]
	at org.springframework.boot.SpringApplication.run(SpringApplication.java:315) ~[spring-boot-2.3.6.RELEASE.jar:2.3.6.RELEASE]
	at org.springframework.boot.SpringApplication.run(SpringApplication.java:1237) ~[spring-boot-2.3.6.RELEASE.jar:2.3.6.RELEASE]
	at org.springframework.boot.SpringApplication.run(SpringApplication.java:1226) ~[spring-boot-2.3.6.RELEASE.jar:2.3.6.RELEASE]
	at com.example.demo.DemoApplication.main(DemoApplication.java:14) ~[classes/:na]
Caused by: javax.persistence.PersistenceException: [PersistenceUnit: default] Unable to build Hibernate SessionFactory; nested exception is org.hibernate.MappingException: Could not instantiate id generator [entity-name=null]
	at org.springframework.orm.jpa.AbstractEntityManagerFactoryBean.buildNativeEntityManagerFactory(AbstractEntityManagerFactoryBean.java:403) ~[spring-orm-5.2.11.RELEASE.jar:5.2.11.RELEASE]
	at org.springframework.orm.jpa.AbstractEntityManagerFactoryBean.afterPropertiesSet(AbstractEntityManagerFactoryBean.java:378) ~[spring-orm-5.2.11.RELEASE.jar:5.2.11.RELEASE]
	at org.springframework.orm.jpa.LocalContainerEntityManagerFactoryBean.afterPropertiesSet(LocalContainerEntityManagerFactoryBean.java:341) ~[spring-orm-5.2.11.RELEASE.jar:5.2.11.RELEASE]
	at org.springframework.beans.factory.support.AbstractAutowireCapableBeanFactory.invokeInitMethods(AbstractAutowireCapableBeanFactory.java:1853) ~[spring-beans-5.2.11.RELEASE.jar:5.2.11.RELEASE]
	at org.springframework.beans.factory.support.AbstractAutowireCapableBeanFactory.initializeBean(AbstractAutowireCapableBeanFactory.java:1790) ~[spring-beans-5.2.11.RELEASE.jar:5.2.11.RELEASE]
	... 17 common frames omitted
Caused by: org.hibernate.MappingException: Could not instantiate id generator [entity-name=null]
	at org.hibernate.id.factory.internal.DefaultIdentifierGeneratorFactory.createIdentifierGenerator(DefaultIdentifierGeneratorFactory.java:124) ~[hibernate-core-5.4.23.Final.jar:5.4.23.Final]
	at org.hibernate.mapping.SimpleValue.createIdentifierGenerator(SimpleValue.java:355) ~[hibernate-core-5.4.23.Final.jar:5.4.23.Final]
	at org.hibernate.persister.collection.AbstractCollectionPersister.<init>(AbstractCollectionPersister.java:455) ~[hibernate-core-5.4.23.Final.jar:5.4.23.Final]
	at org.hibernate.persister.collection.BasicCollectionPersister.<init>(BasicCollectionPersister.java:59) ~[hibernate-core-5.4.23.Final.jar:5.4.23.Final]
	at java.base/jdk.internal.reflect.NativeConstructorAccessorImpl.newInstance0(Native Method) ~[na:na]
	at java.base/jdk.internal.reflect.NativeConstructorAccessorImpl.newInstance(NativeConstructorAccessorImpl.java:62) ~[na:na]
	at java.base/jdk.internal.reflect.DelegatingConstructorAccessorImpl.newInstance(DelegatingConstructorAccessorImpl.java:45) ~[na:na]
	at java.base/java.lang.reflect.Constructor.newInstance(Constructor.java:490) ~[na:na]
	at org.hibernate.persister.internal.PersisterFactoryImpl.createCollectionPersister(PersisterFactoryImpl.java:152) ~[hibernate-core-5.4.23.Final.jar:5.4.23.Final]
	at org.hibernate.persister.internal.PersisterFactoryImpl.createCollectionPersister(PersisterFactoryImpl.java:140) ~[hibernate-core-5.4.23.Final.jar:5.4.23.Final]
	at org.hibernate.metamodel.internal.MetamodelImpl.initialize(MetamodelImpl.java:225) ~[hibernate-core-5.4.23.Final.jar:5.4.23.Final]
	at org.hibernate.internal.SessionFactoryImpl.<init>(SessionFactoryImpl.java:301) ~[hibernate-core-5.4.23.Final.jar:5.4.23.Final]
	at org.hibernate.boot.internal.SessionFactoryBuilderImpl.build(SessionFactoryBuilderImpl.java:469) ~[hibernate-core-5.4.23.Final.jar:5.4.23.Final]
	at org.hibernate.jpa.boot.internal.EntityManagerFactoryBuilderImpl.build(EntityManagerFactoryBuilderImpl.java:1259) ~[hibernate-core-5.4.23.Final.jar:5.4.23.Final]
	at org.springframework.orm.jpa.vendor.SpringHibernateJpaPersistenceProvider.createContainerEntityManagerFactory(SpringHibernateJpaPersistenceProvider.java:58) ~[spring-orm-5.2.11.RELEASE.jar:5.2.11.RELEASE]
	at org.springframework.orm.jpa.LocalContainerEntityManagerFactoryBean.createNativeEntityManagerFactory(LocalContainerEntityManagerFactoryBean.java:365) ~[spring-orm-5.2.11.RELEASE.jar:5.2.11.RELEASE]
	at org.springframework.orm.jpa.AbstractEntityManagerFactoryBean.buildNativeEntityManagerFactory(AbstractEntityManagerFactoryBean.java:391) ~[spring-orm-5.2.11.RELEASE.jar:5.2.11.RELEASE]
	... 21 common frames omitted
Caused by: org.hibernate.MappingException: no entity name
	at org.hibernate.id.Assigned.configure(Assigned.java:45) ~[hibernate-core-5.4.23.Final.jar:5.4.23.Final]
	at org.hibernate.id.factory.internal.DefaultIdentifierGeneratorFactory.createIdentifierGenerator(DefaultIdentifierGeneratorFactory.java:118) ~[hibernate-core-5.4.23.Final.jar:5.4.23.Final]
	... 37 common frames omitted

It seems that when using deferred mode, the bean creating fails in the background and is not reported to the main thread. @jhoeller, does that ring a bell.

It is possible to make this application fail by injecting the EntityManager anywhere, for instance:

@Bean
public ApplicationRunner useEntityManager(EntityManager entityManager) {
	return args -> entityManager.contains("test");
}

[snicoll]

@DredderGun this sample app doesn't interact with the EntityManagerFactory and that doesn't sound very realistic. On first use you'd get the exception as I've indicated in my previous comment.

That said, there is a case to log this sooner. I am now going to transfer this issue to the Spring Framework issue tracker as there's nothing we can do in Spring Boot about this. Thanks for the report.