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

ConcurrentModificationException in LoggerContext due to race condition #3234

Open
AlexProgrammerDE opened this issue Nov 23, 2024 · 6 comments
Open

ConcurrentModificationException in LoggerContext due to race condition #3234

AlexProgrammerDE opened this issue Nov 23, 2024 · 6 comments
Labels
bug Incorrect, unexpected, or unintended behavior of existing code waiting-for-maintainer

Comments

@AlexProgrammerDE
Copy link

AlexProgrammerDE commented Nov 23, 2024 •
edited
Loading

Description

Presumably due to a1dfa85 my application throws an error when loggers get changed from multiple threads.
This is likely because InternalLoggerRegistry#getLoggers does not return a thread-safe stream.
Streams are by nature evaluated on the fly, thus still using the values of loggerRefByNameByMessageFactory after readLock was unlocked.
When multiple threads modify loggerRefByNameByMessageFactory, sometimes it errors with the attached error.
This happens inconsistently because it's a race condition, but I've been able to get this error a few times.

Configuration

Version: 2.24.2

Operating system: Windows

JDK: openjdk version "21.0.4" 2024-07-16 LTS

Logs

java.util.ConcurrentModificationException: null
	at java.base/java.util.HashMap$ValueSpliterator.forEachRemaining(HashMap.java:1792) ~[?:?]
	at java.base/java.util.stream.ReferencePipeline$Head.forEach(ReferencePipeline.java:762) ~[?:?]
	at java.base/java.util.stream.ReferencePipeline$7$1.accept(ReferencePipeline.java:276) ~[?:?]
	at java.base/java.util.WeakHashMap$ValueSpliterator.forEachRemaining(WeakHashMap.java:1223) ~[?:?]
	at java.base/java.util.stream.AbstractPipeline.copyInto(AbstractPipeline.java:509) ~[?:?]
	at java.base/java.util.stream.AbstractPipeline.wrapAndCopyInto(AbstractPipeline.java:499) ~[?:?]
	at java.base/java.util.stream.ForEachOps$ForEachOp.evaluateSequential(ForEachOps.java:151) ~[?:?]
	at java.base/java.util.stream.ForEachOps$ForEachOp$OfRef.evaluateSequential(ForEachOps.java:174) ~[?:?]
	at java.base/java.util.stream.AbstractPipeline.evaluate(AbstractPipeline.java:234) ~[?:?]
	at java.base/java.util.stream.ReferencePipeline.forEach(ReferencePipeline.java:596) ~[?:?]
	at org.apache.logging.log4j.core.LoggerContext.updateLoggers(LoggerContext.java:776) ~[?:?]
	at org.apache.logging.log4j.core.LoggerContext.updateLoggers(LoggerContext.java:766) ~[?:?]
	at org.apache.logging.log4j.core.config.Configurator.setLevel(Configurator.java:379) ~[?:?]
	at org.apache.logging.log4j.core.config.Configurator.setLevel(Configurator.java:414) ~[?:?]
	at com.soulfiremc.server.SoulFireServer.setupLogging(SoulFireServer.java:213) ~[?:?]
	at com.soulfiremc.server.SoulFireServer.setupLoggingAndVia(SoulFireServer.java:208) ~[?:?]
	at com.soulfiremc.server.InstanceManager.start(InstanceManager.java:194) ~[?:?]
	at com.soulfiremc.server.SoulFireScheduler.lambda$wrapFuture$6(SoulFireScheduler.java:140) ~[?:?]
	at java.base/java.util.concurrent.CompletableFuture$AsyncRun.run(CompletableFuture.java:1804) ~[?:?]
	at com.soulfiremc.server.SoulFireScheduler.runCommand(SoulFireScheduler.java:154) ~[?:?]
	at com.soulfiremc.server.SoulFireScheduler.lambda$schedule$2(SoulFireScheduler.java:79) ~[?:?]
	at java.base/java.util.concurrent.ForkJoinTask$RunnableExecuteAction.exec(ForkJoinTask.java:1423) ~[?:?]
	at java.base/java.util.concurrent.ForkJoinTask.doExec(ForkJoinTask.java:387) ~[?:?]
	at java.base/java.util.concurrent.ForkJoinPool$WorkQueue.topLevelExec(ForkJoinPool.java:1312) ~[?:?]
	at java.base/java.util.concurrent.ForkJoinPool.scan(ForkJoinPool.java:1843) ~[?:?]
	at java.base/java.util.concurrent.ForkJoinPool.runWorker(ForkJoinPool.java:1808) ~[?:?]
	at java.base/java.util.concurrent.ForkJoinWorkerThread.run(ForkJoinWorkerThread.java:188) ~[?:?]

This shows the stream being collected due to the forEach call in LoggerContext#updateLoggers, but there being no read lock, therefore causing this race condition.

Reproduction

I unfortunately cannot provide an example because I do not have much experience with reproducing race conditions.
@AlexProgrammerDE
Copy link
Author

I'd suggest fixing this by making InternalLoggerRegistry#getLoggers return a precomputed Collection instead of returning a Stream. You could change the return type to Collection<Logger> and gather the stream inside the lock by calling Stream#toList.

ppkarwasz added a commit that referenced this issue Nov 24, 2024
@ppkarwasz
Fix ConcurrentModificationException in updateLoggers()
e3742de 
The `InternalLoggerRegistry` implementation introduced in version `2.24.2` did not return a copy of the registry, when `InternalLoggerRegistry.getLoggers()` was called. This could lead to a `ConcurrentModificationException` if a thread creates a new logger, while another thread calls `LoggerContext.updateLoggers()`.

Closes #3234
@ppkarwasz ppkarwasz mentioned this issue Nov 24, 2024
Open
@ppkarwasz
Copy link
Contributor

@AlexProgrammerDE,

Nice catch! 💯
#3235 should fix it.

@ppkarwasz ppkarwasz added bug Incorrect, unexpected, or unintended behavior of existing code and removed waiting-for-maintainer labels Nov 24, 2024
@jpcmonster
Copy link

I'm not certain this is related, but we're seeing what looks like a deadlock around InternalLoggerRegistry since 2.24.1 (in SpringBoot with Artemis) - if it is unrelated, I can try to file a new issue if required?

        at jdk.internal.misc.Unsafe.park([email protected]/Native Method)
        - parking to wait for  <0x0000000613400050> (a java.util.concurrent.locks.ReentrantReadWriteLock$NonfairSync)
        at java.util.concurrent.locks.LockSupport.park([email protected]/LockSupport.java:211)
        at java.util.concurrent.locks.AbstractQueuedSynchronizer.acquire([email protected]/AbstractQueuedSynchronizer.java:715)
        at java.util.concurrent.locks.AbstractQueuedSynchronizer.acquireShared([email protected]/AbstractQueuedSynchronizer.java:1027)
        at java.util.concurrent.locks.ReentrantReadWriteLock$ReadLock.lock([email protected]/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([email protected]/NamingManager.java:732)
        at javax.naming.InitialContext.getDefaultInitCtx([email protected]/InitialContext.java:305)
        at javax.naming.InitialContext.init([email protected]/InitialContext.java:236)
        at javax.naming.InitialContext.<init>([email protected]/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)
        ```

@ppkarwasz
Copy link
Contributor

@jpcmonster,

if it is unrelated, I can try to file a new issue if required?

I think it is unrelated, but looking at the stack trace it is almost definitely a dead lock. Do you know what is the other lock (0x0000000613400050) contended by threads? Could you file a new issue?

InternalLoggerRegistry appeared in version 2.24.2. Are you sure the version 2.24.1 has a similar bug?

@jpcmonster
Copy link

@ppkarwasz unfortunately we didn't deep dive 2.24.1 at the time, but the surface symptom ( SpringBoot failed to start, no logs were generated ) was the same. I will file a separate issue as we do have more info now - will see if we can identify the other lock.

@jpcmonster
Copy link

@ppkarwasz I have opened #3252 for the apparent deadlock - thanks!

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
3 participants
@ppkarwasz @AlexProgrammerDE @jpcmonster