Spring Sending an event as part of the EMF lock triggers a deadlock

Follow-up of #25799. With that fix in place, we still get a deadlock unfortunately.

main@1" prio=5 tid=0x1 nid=NA waiting
  java.lang.Thread.State: WAITING
     blocks task-1@6178
      at jdk.internal.misc.Unsafe.park(Unsafe.java:-1)
      at java.util.concurrent.locks.LockSupport.park(LockSupport.java:194)
      at java.util.concurrent.FutureTask.awaitDone(FutureTask.java:447)
      at java.util.concurrent.FutureTask.get(FutureTask.java:190)
      at org.springframework.orm.jpa.AbstractEntityManagerFactoryBean.getNativeEntityManagerFactory(AbstractEntityManagerFactoryBean.java:560)
      at org.springframework.orm.jpa.AbstractEntityManagerFactoryBean.invokeProxyMethod(AbstractEntityManagerFactoryBean.java:516)
      at org.springframework.orm.jpa.AbstractEntityManagerFactoryBean$ManagedEntityManagerFactoryInvocationHandler.invoke(AbstractEntityManagerFactoryBean.java:731)
      at com.sun.proxy.$Proxy77.getStatistics(Unknown Source:-1)
      at io.micrometer.core.instrument.binder.jpa.HibernateMetrics.<init>(HibernateMetrics.java:110)
      at org.springframework.boot.actuate.autoconfigure.metrics.orm.jpa.HibernateMetricsAutoConfiguration.bindEntityManagerFactoryToRegistry(HibernateMetricsAutoConfiguration.java:68)
      at org.springframework.boot.actuate.autoconfigure.metrics.orm.jpa.HibernateMetricsAutoConfiguration.lambda$bindEntityManagerFactoriesToRegistry$0(HibernateMetricsAutoConfiguration.java:60)
      at org.springframework.boot.actuate.autoconfigure.metrics.orm.jpa.HibernateMetricsAutoConfiguration$$Lambda$936.1374688565.accept(Unknown Source:-1)
      at java.util.LinkedHashMap.forEach(LinkedHashMap.java:684)
      at org.springframework.boot.actuate.autoconfigure.metrics.orm.jpa.HibernateMetricsAutoConfiguration.bindEntityManagerFactoriesToRegistry(HibernateMetricsAutoConfiguration.java:60)
      at jdk.internal.reflect.NativeMethodAccessorImpl.invoke0(NativeMethodAccessorImpl.java:-1)
      at jdk.internal.reflect.NativeMethodAccessorImpl.invoke(NativeMethodAccessorImpl.java:62)
      at jdk.internal.reflect.DelegatingMethodAccessorImpl.invoke(DelegatingMethodAccessorImpl.java:43)
      at java.lang.reflect.Method.invoke(Method.java:566)
      at org.springframework.beans.factory.annotation.AutowiredAnnotationBeanPostProcessor$AutowiredMethodElement.inject(AutowiredAnnotationBeanPostProcessor.java:755)
      at org.springframework.beans.factory.annotation.InjectionMetadata.inject(InjectionMetadata.java:130)
      at org.springframework.beans.factory.annotation.AutowiredAnnotationBeanPostProcessor.postProcessProperties(AutowiredAnnotationBeanPostProcessor.java:399)
      at org.springframework.beans.factory.support.AbstractAutowireCapableBeanFactory.populateBean(AbstractAutowireCapableBeanFactory.java:1415)
      at org.springframework.beans.factory.support.AbstractAutowireCapableBeanFactory.doCreateBean(AbstractAutowireCapableBeanFactory.java:608)
      at org.springframework.beans.factory.support.AbstractAutowireCapableBeanFactory.createBean(AbstractAutowireCapableBeanFactory.java:531)
      at org.springframework.beans.factory.support.AbstractBeanFactory.lambda$doGetBean$0(AbstractBeanFactory.java:335)
      at org.springframework.beans.factory.support.AbstractBeanFactory$$Lambda$302.1818449913.getObject(Unknown Source:-1)
      at org.springframework.beans.factory.support.DefaultSingletonBeanRegistry.getSingleton(DefaultSingletonBeanRegistry.java:234)
      - locked <0x258f> (a java.util.concurrent.ConcurrentHashMap)
      at org.springframework.beans.factory.support.AbstractBeanFactory.doGetBean(AbstractBeanFactory.java:333)
      at org.springframework.beans.factory.support.AbstractBeanFactory.getBean(AbstractBeanFactory.java:208)
      at org.springframework.beans.factory.support.DefaultListableBeanFactory.preInstantiateSingletons(DefaultListableBeanFactory.java:944)
      at org.springframework.context.support.AbstractApplicationContext.finishBeanFactoryInitialization(AbstractApplicationContext.java:925)
      at org.springframework.context.support.AbstractApplicationContext.refresh(AbstractApplicationContext.java:588)
      - locked <0x2590> (a java.lang.Object)
      at org.springframework.boot.web.servlet.context.ServletWebServerApplicationContext.refresh(ServletWebServerApplicationContext.java:144)

With the following state for task1, the thread that was created to initialise the JPA infrastructure, and the DB:

"task-1@6178" prio=5 tid=0x25 nid=NA waiting for monitor entry
  java.lang.Thread.State: BLOCKED
     waiting for main@1 to release lock on <0x258f> (a java.util.concurrent.ConcurrentHashMap)
      at org.springframework.beans.factory.support.DefaultSingletonBeanRegistry.getSingleton(DefaultSingletonBeanRegistry.java:217)
      at org.springframework.beans.factory.support.AbstractBeanFactory.doGetBean(AbstractBeanFactory.java:333)
      at org.springframework.beans.factory.support.AbstractBeanFactory.getBean(AbstractBeanFactory.java:213)
      at org.springframework.context.event.AbstractApplicationEventMulticaster.retrieveApplicationListeners(AbstractApplicationEventMulticaster.java:247)
      at org.springframework.context.event.AbstractApplicationEventMulticaster.getApplicationListeners(AbstractApplicationEventMulticaster.java:204)
      at org.springframework.context.event.SimpleApplicationEventMulticaster.multicastEvent(SimpleApplicationEventMulticaster.java:155)
      at org.springframework.context.support.AbstractApplicationContext.publishEvent(AbstractApplicationContext.java:426)
      at org.springframework.context.support.AbstractApplicationContext.publishEvent(AbstractApplicationContext.java:383)
      at org.springframework.boot.autoconfigure.orm.jpa.DataSourceInitializedPublisher.publishEventIfRequired(DataSourceInitializedPublisher.java:99)
      at org.springframework.boot.autoconfigure.orm.jpa.DataSourceInitializedPublisher.access$100(DataSourceInitializedPublisher.java:50)
      at org.springframework.boot.autoconfigure.orm.jpa.DataSourceInitializedPublisher$DataSourceSchemaCreatedPublisher.postProcessEntityManagerFactory(DataSourceInitializedPublisher.java:197)
      at org.springframework.orm.jpa.AbstractEntityManagerFactoryBean.buildNativeEntityManagerFactory(AbstractEntityManagerFactoryBean.java:430)
      at org.springframework.orm.jpa.AbstractEntityManagerFactoryBean$$Lambda$779.356347252.call(Unknown Source:-1)
      at java.util.concurrent.FutureTask.run$$$capture(FutureTask.java:264)
      at java.util.concurrent.FutureTask.run(FutureTask.java:-1)
      at java.util.concurrent.ThreadPoolExecutor.runWorker(ThreadPoolExecutor.java:1128)
      at java.util.concurrent.ThreadPoolExecutor$Worker.run(ThreadPoolExecutor.java:628)
      at java.lang.Thread.run(Thread.java:834)

There is a sample that reproduces the problem in https://github.com/spring-projects/spring-boot/issues/23735

Comment From: jhoeller

I suppose the affected listener bean (in the second stacktrace) has not been initialized yet, otherwise we wouldn't go into the full singleton lock there. If that's the case, it's expected and unavoidable in the current EMF bootstrap arrangement; the only solution is to enforce pre-initialization of all affected listener beans before the EMF bean (e.g. through @DependsOn declarations).

Comment From: snicoll

Thanks for the hint Juergen. Adding a dependency to the event listener seems to do the trick thus far. I am now looking a bit deeper to see if such link won't trigger another regression.

Comment From: snicoll

It did so I guess what we miss is a hook point where we could be notified that something is ready (but not injected as a dependency yet) and can be further tuned without having to declare depends on programmatically (a bit convoluted when we don't really know what's going to happen at runtime).

Comment From: snicoll

This issue has run its course. On the Spring Boot side of things, we've started to refactor the code to avoid the event in the first place.