apparent deadlock in InternalLoggerRegistry.getLogger()

[jpcmonster]

Description

SpringBoot 3.x application experiences deadlock/hang at startup with ActiveMQ Artemis and log4j2.

Deadlock occurs if SpringBoot backend-preinit is enabled (the default); if disabled, it causes a stackoverflow instead. Both stacktraces are attached.

Best guess from our team is that it may relate to weak references in InternalLoggerRegistry and LoggerContext use of computeIfAbsent(). The speculation is that if a registered logger is released as a weak reference during initialization, then it may be repeatedly initialized - causing aconcurrency/deadlock issue.

Configuration

Version: 2.24.2

Operating system: Windows 10 (observed on Alma Linux as well)

JDK: Eclipse Temurin 17.0.8.1

Logs

with backend-preinit enabled:

Java stack information for the threads listed above:
===================================================
"main":
        at jdk.internal.misc.Unsafe.park(java.base@17.0.8.1/Native Method)
        - parking to wait for  <0x0000000613400050> (a java.util.concurrent.locks.ReentrantReadWriteLock$NonfairSync)
        at java.util.concurrent.locks.LockSupport.park(java.base@17.0.8.1/LockSupport.java:211)
        at java.util.concurrent.locks.AbstractQueuedSynchronizer.acquire(java.base@17.0.8.1/AbstractQueuedSynchronizer.java:715)
        at java.util.concurrent.locks.AbstractQueuedSynchronizer.acquireShared(java.base@17.0.8.1/AbstractQueuedSynchronizer.java:1027)
        at java.util.concurrent.locks.ReentrantReadWriteLock$ReadLock.lock(java.base@17.0.8.1/ReentrantReadWriteLock.java:738)
        at org.apache.logging.log4j.core.util.internal.InternalLoggerRegistry.getLogger(InternalLoggerRegistry.java:69)
        at org.apache.logging.log4j.core.util.internal.InternalLoggerRegistry.computeIfAbsent(InternalLoggerRegistry.java:139)
        at org.apache.logging.log4j.core.LoggerContext.getLogger(LoggerContext.java:530)
        at org.apache.logging.log4j.core.LoggerContext.getLogger(LoggerContext.java:503)
        at org.apache.logging.log4j.core.LoggerContext.getLogger(LoggerContext.java:65)
        at org.apache.commons.logging.LogAdapter$Log4jLog.<init>(LogAdapter.java:159)
        at org.apache.commons.logging.LogAdapter$Log4jAdapter.createLog(LogAdapter.java:113)
        at org.apache.commons.logging.LogAdapter$$Lambda$118/0x0000019da7117580.apply(Unknown Source)
        at org.apache.commons.logging.LogAdapter.createLog(LogAdapter.java:95)
        at org.apache.commons.logging.LogFactory.getLog(LogFactory.java:67)
        at org.apache.commons.logging.LogFactory.getLog(LogFactory.java:59)
        at org.apache.commons.beanutils.MethodUtils.getMatchingAccessibleMethod(MethodUtils.java:942)
        at org.apache.commons.beanutils.MappedPropertyDescriptor.getMethod(MappedPropertyDescriptor.java:404)
        at org.apache.commons.beanutils.MappedPropertyDescriptor.<init>(MappedPropertyDescriptor.java:104)
        at org.apache.commons.beanutils.PropertyUtilsBean.getPropertyDescriptor(PropertyUtilsBean.java:972)
        at org.apache.commons.beanutils.BeanUtilsBean.setProperty(BeanUtilsBean.java:935)
        at org.apache.activemq.artemis.utils.uri.BeanSupport.setData(BeanSupport.java:89)
        - locked <0x0000000613428b20> (a org.apache.commons.beanutils.BeanUtilsBean)
        at org.apache.activemq.artemis.uri.AbstractCFSchema.newConectionOptions(AbstractCFSchema.java:36)
        at org.apache.activemq.artemis.uri.TCPSchema.internalNewObject(TCPSchema.java:50)
        at org.apache.activemq.artemis.uri.TCPSchema.internalNewObject(TCPSchema.java:37)
        at org.apache.activemq.artemis.utils.uri.URISchema.newObject(URISchema.java:84)
        at org.apache.activemq.artemis.utils.uri.URIFactory.newObject(URIFactory.java:69)
        at org.apache.activemq.artemis.jndi.ActiveMQInitialContextFactory.createConnectionFactory(ActiveMQInitialContextFactory.java:185)
        at org.apache.activemq.artemis.jndi.ActiveMQInitialContextFactory.getInitialContext(ActiveMQInitialContextFactory.java:65)
        at javax.naming.spi.NamingManager.getInitialContext(java.naming@17.0.8.1/NamingManager.java:732)
        at javax.naming.InitialContext.getDefaultInitCtx(java.naming@17.0.8.1/InitialContext.java:305)
        at javax.naming.InitialContext.init(java.naming@17.0.8.1/InitialContext.java:236)
        at javax.naming.InitialContext.<init>(java.naming@17.0.8.1/InitialContext.java:208)
        at org.springframework.jndi.JndiTemplate.createInitialContext(JndiTemplate.java:141)
        at org.springframework.jndi.JndiTemplate.getContext(JndiTemplate.java:108)
        at org.springframework.jndi.JndiTemplate.execute(JndiTemplate.java:90)
        at org.springframework.jndi.JndiTemplate.lookup(JndiTemplate.java:157)
        at org.springframework.jndi.JndiTemplate.lookup(JndiTemplate.java:179)
        at org.springframework.jndi.JndiLocatorSupport.lookup(JndiLocatorSupport.java:96)
        at org.springframework.jndi.JndiLocatorDelegate.lookup(JndiLocatorDelegate.java:64)
        at org.springframework.jndi.JndiLocatorSupport.lookup(JndiLocatorSupport.java:78)
        at org.springframework.jndi.JndiLocatorDelegate.lookup(JndiLocatorDelegate.java:59)
        at org.springframework.jndi.JndiPropertySource.getProperty(JndiPropertySource.java:93)
        at org.springframework.boot.context.properties.source.SpringConfigurationPropertySource.getConfigurationProperty(SpringConfigurationPropertySource.java:84)
...

with backend-preinit disabled:

Exception in thread "SpringApplicationShutdownHook" java.lang.StackOverflowError
	at java.base/java.net.URI$Parser.parseAuthority(URI.java:3260)
	at java.base/java.net.URI$Parser.parseHierarchical(URI.java:3221)
	at java.base/java.net.URI$Parser.parse(URI.java:3177)
	at java.base/java.net.URI.<init>(URI.java:623)
	at org.apache.activemq.artemis.utils.uri.URIFactory.normalise(URIFactory.java:133)
	at org.apache.activemq.artemis.utils.uri.URIFactory.expandURI(URIFactory.java:49)
	at org.apache.activemq.artemis.jndi.ActiveMQInitialContextFactory.getFactoryType(ActiveMQInitialContextFactory.java:190)
	at org.apache.activemq.artemis.jndi.ActiveMQInitialContextFactory.getInitialContext(ActiveMQInitialContextFactory.java:61)
	at java.naming/javax.naming.spi.NamingManager.getInitialContext(NamingManager.java:732)
	at java.naming/javax.naming.InitialContext.getDefaultInitCtx(InitialContext.java:305)
	at java.naming/javax.naming.InitialContext.init(InitialContext.java:236)
	at java.naming/javax.naming.InitialContext.<init>(InitialContext.java:208)
	at org.springframework.jndi.JndiTemplate.createInitialContext(JndiTemplate.java:141)
	at org.springframework.jndi.JndiTemplate.getContext(JndiTemplate.java:108)
	at org.springframework.jndi.JndiTemplate.execute(JndiTemplate.java:90)
	at org.springframework.jndi.JndiTemplate.lookup(JndiTemplate.java:157)
	at org.springframework.jndi.JndiTemplate.lookup(JndiTemplate.java:179)
	at org.springframework.jndi.JndiLocatorSupport.lookup(JndiLocatorSupport.java:96)
	at org.springframework.jndi.JndiLocatorDelegate.lookup(JndiLocatorDelegate.java:64)
	at org.springframework.jndi.JndiLocatorSupport.lookup(JndiLocatorSupport.java:78)
	at org.springframework.jndi.JndiLocatorDelegate.lookup(JndiLocatorDelegate.java:59)
	at org.springframework.jndi.JndiPropertySource.getProperty(JndiPropertySource.java:93)
	at org.springframework.core.env.PropertySourcesPropertyResolver.getProperty(PropertySourcesPropertyResolver.java:85)

Reproduction

This happens consistently on startup of our SpringBoot 3.x application with Artemis 2.38 and Log4j 2.24.2 .

[ppkarwasz]

@jpcmonster,

This is a real deadlock caused by a recursive call between the Log4j PropertiesUtil.getStringProperty() and the Spring JndiPropertySource.getProperty(). The steps to reproduce are:

1. JndiPropertySource.getProperty() initializes Artemis.
2. Artemis locks BeanUtilsBean.
3. Log4j calls new Logger() after locking InternalLoggerRegistry.
4. Log4j looks for the log4j2.flowMessageFactory property in all available property sources.
5. We are back at step 1.

This cycle should explain both the deadlock and the stack overflow.

PR #3263 will eliminate the stack overflow and the dead lock.

In the meantime you can:

1. Either forcibly disabling JndiPropertySource by setting spring.jndi.ignore to true (see JndiLocatorDelegate#IGNORE_JNDI_PROPERTY_NAME).
2. Or, if you are not running in a Servlet environment, remove the java.naming.* system properties, since Spring does not use them to start Artemis.

[ppkarwasz]

@jpcmonster,

Can you check if our 2.24.3-SNAPSHOT snapshot fixes your problem? See downloads for the URL of our snapshot Maven repository.

[jpcmonster]

@ppkarwasz yes, I think I can try that fairly easily for you this morning; will circle back as soon as I know.

[jpcmonster]

@ppkarwasz sorry for the delay; getting our cicd to pick up snapshots end-to-end was more challenging than I expected, but I learned some things :). In any case, all our basic sanity checks / regression tests pass with this snapshot; I think it solves our problem - thank you!

[ppkarwasz]

Thanks,

I started a Log4j 2.24.3 release vote on Tuesday. Unless someone finds issues, I'll release the artifacts tomorrow (72 hours from the start of the vote).