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

[snicoll]

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 spring-projects/spring-boot#23735

[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).

[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.

[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).

[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.