You are viewing a plain text version of this content. The canonical link for it is here.
Posted to notifications@logging.apache.org by "jpcmonster (via GitHub)" <gi...@apache.org> on 2024/11/28 18:44:09 UTC
[I] apparent deadlock in InternalLoggerRegistry.getLogger() (logging-log4j2)
jpcmonster opened a new issue, #3252:
URL: https://github.com/apache/logging-log4j2/issues/3252
## 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](https://github.com/apache/logging-log4j2/blob/2.x/log4j-core/src/main/java/org/apache/logging/log4j/core/util/internal/InternalLoggerRegistry.java) in `InternalLoggerRegistry` and `LoggerContext` [use of](https://github.com/apache/logging-log4j2/blob/2.x/log4j-core/src/main/java/org/apache/logging/log4j/core/LoggerContext.java#L531) `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 .
--
This is an automated message from the Apache Git Service.
To respond to the message, please log on to GitHub and use the
URL above to go to the specific comment.
To unsubscribe, e-mail: notifications-unsubscribe@logging.apache.org.apache.org
For queries about this service, please contact Infrastructure at:
users@infra.apache.org
Re: [I] apparent deadlock in InternalLoggerRegistry.getLogger() (logging-log4j2)
Posted by "ppkarwasz (via GitHub)" <gi...@apache.org>.
ppkarwasz commented on issue #3252:
URL: https://github.com/apache/logging-log4j2/issues/3252#issuecomment-2511920370
@jpcmonster,
This is a real deadlock caused by a recursive call between the Log4j [`PropertiesUtil.getStringProperty()`](https://logging.apache.org/log4j/2.x/javadoc/log4j-api/org/apache/logging/log4j/util/PropertiesUtil.html) and the Spring [`JndiPropertySource.getProperty()`](https://docs.spring.io/spring-framework/docs/current/javadoc-api/org/springframework/jndi/JndiPropertySource.html). 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](https://docs.spring.io/spring-framework/docs/current/javadoc-api/org/springframework/jndi/JndiLocatorDelegate.html#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.
--
This is an automated message from the Apache Git Service.
To respond to the message, please log on to GitHub and use the
URL above to go to the specific comment.
To unsubscribe, e-mail: notifications-unsubscribe@logging.apache.org
For queries about this service, please contact Infrastructure at:
users@infra.apache.org
Re: [I] apparent deadlock in InternalLoggerRegistry.getLogger() (logging-log4j2)
Posted by "ppkarwasz (via GitHub)" <gi...@apache.org>.
ppkarwasz commented on issue #3252:
URL: https://github.com/apache/logging-log4j2/issues/3252#issuecomment-2539016998
Thanks,
I started a [Log4j `2.24.3` release vote](https://lists.apache.org/list?dev@logging.apache.org) on Tuesday. Unless someone finds issues, I'll release the artifacts tomorrow (72 hours from the start of the vote).
--
This is an automated message from the Apache Git Service.
To respond to the message, please log on to GitHub and use the
URL above to go to the specific comment.
To unsubscribe, e-mail: notifications-unsubscribe@logging.apache.org
For queries about this service, please contact Infrastructure at:
users@infra.apache.org
Re: [I] apparent deadlock in InternalLoggerRegistry.getLogger() (logging-log4j2)
Posted by "ppkarwasz (via GitHub)" <gi...@apache.org>.
ppkarwasz commented on issue #3252:
URL: https://github.com/apache/logging-log4j2/issues/3252#issuecomment-2527370096
@jpcmonster,
Can you check if our `2.24.3-SNAPSHOT` snapshot fixes your problem? See [downloads](https://logging.apache.org/download.html) for the URL of our snapshot Maven repository.
--
This is an automated message from the Apache Git Service.
To respond to the message, please log on to GitHub and use the
URL above to go to the specific comment.
To unsubscribe, e-mail: notifications-unsubscribe@logging.apache.org
For queries about this service, please contact Infrastructure at:
users@infra.apache.org
Re: [I] apparent deadlock in InternalLoggerRegistry.getLogger() (logging-log4j2)
Posted by "jpcmonster (via GitHub)" <gi...@apache.org>.
jpcmonster commented on issue #3252:
URL: https://github.com/apache/logging-log4j2/issues/3252#issuecomment-2538954926
@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!
--
This is an automated message from the Apache Git Service.
To respond to the message, please log on to GitHub and use the
URL above to go to the specific comment.
To unsubscribe, e-mail: notifications-unsubscribe@logging.apache.org
For queries about this service, please contact Infrastructure at:
users@infra.apache.org
Re: [I] apparent deadlock in InternalLoggerRegistry.getLogger() (logging-log4j2)
Posted by "ppkarwasz (via GitHub)" <gi...@apache.org>.
ppkarwasz closed issue #3252: apparent deadlock in InternalLoggerRegistry.getLogger()
URL: https://github.com/apache/logging-log4j2/issues/3252
--
This is an automated message from the Apache Git Service.
To respond to the message, please log on to GitHub and use the
URL above to go to the specific comment.
To unsubscribe, e-mail: notifications-unsubscribe@logging.apache.org
For queries about this service, please contact Infrastructure at:
users@infra.apache.org
Re: [I] apparent deadlock in InternalLoggerRegistry.getLogger() (logging-log4j2)
Posted by "jpcmonster (via GitHub)" <gi...@apache.org>.
jpcmonster commented on issue #3252:
URL: https://github.com/apache/logging-log4j2/issues/3252#issuecomment-2528061876
@ppkarwasz yes, I think I can try that fairly easily for you this morning; will circle back as soon as I know.
--
This is an automated message from the Apache Git Service.
To respond to the message, please log on to GitHub and use the
URL above to go to the specific comment.
To unsubscribe, e-mail: notifications-unsubscribe@logging.apache.org
For queries about this service, please contact Infrastructure at:
users@infra.apache.org