ConcurrentModificationException in LoggerContext due to race condition

[AlexProgrammerDE]

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]

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]

@AlexProgrammerDE,

Nice catch! 💯
#3235 should fix it.

[jpcmonster]

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]

@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]

@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]

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

[tnleeuw]

I see that we ran into the same issue -- I raised it as #3283 before realizing this issue already existed.
I've included a patch with possible fix in "my" issue.

[kelunik]

Thank you @ppkarwasz, was just about to report this! 🙈