Skip to content
New issue

Have a question about this project? Sign up for a free GitHub account to open an issue and contact its maintainers and the community.

Sign up for GitHub

By clicking “Sign up for GitHub”, you agree to our terms of service and privacy statement. We’ll occasionally send you account related emails.

Already on GitHub? Sign in to your account

Jump to bottom

apparent deadlock in InternalLoggerRegistry.getLogger() #3252

Closed
jpcmonster opened this issue Nov 28, 2024 · 5 comments
Closed

apparent deadlock in InternalLoggerRegistry.getLogger() #3252

jpcmonster opened this issue Nov 28, 2024 · 5 comments
Labels
bug Incorrect, unexpected, or unintended behavior of existing code waiting-for-maintainer

Comments

@jpcmonster
Copy link

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 .
@jpcmonster jpcmonster mentioned this issue Nov 28, 2024
Closed
ppkarwasz added a commit that referenced this issue Dec 2, 2024
@ppkarwasz
Hardens PropertiesUtil against recursive property sources
cb59a70 
As showed in #3252, Spring's `JndiPropertySource` not only can throw exceptions, but can also perform logging calls.
Such a call causes a recursive call to `PropertiesUtil.getProperty("log4j2.flowMessageFactory"`) and a `StackOverflowException` in the best scenario. The worst scenario includes a deadlock.

This PR:

- Moves the creation of the default `MessageFactory` and `FlowMessageFactory` to the static initializer of `LoggerContext`. This should be close enough to the pre-2.23.0 location in `AbstractLogger`. The `LoggerContext` class is usually initialized, before Spring Boot adds its property sources to `PropertiesUtil`.
- Adds a check to `PropertiesUtil` to ignore recursive calls.

Closes #3252.
@ppkarwasz ppkarwasz mentioned this issue Dec 2, 2024
Merged
@ppkarwasz
Copy link
Contributor

@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 ppkarwasz added bug Incorrect, unexpected, or unintended behavior of existing code and removed waiting-for-maintainer labels Dec 2, 2024
@ppkarwasz
Copy link
Contributor

@jpcmonster,

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

@ppkarwasz ppkarwasz mentioned this issue Dec 9, 2024
Merged
@jpcmonster
Copy link
Author

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

@jpcmonster
Copy link
Author

@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
Copy link
Contributor

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

@ppkarwasz ppkarwasz mentioned this issue Dec 14, 2024
Closed
Sign up for free to join this conversation on GitHub. Already have an account? Sign in to comment
Assignees
No one assigned
Labels
bug Incorrect, unexpected, or unintended behavior of existing code waiting-for-maintainer
Projects
None yet
Milestone
No milestone
Development

No branches or pull requests
2 participants
@ppkarwasz @jpcmonster