ConcurrectModificationException while adjusting log-level in runtime

[tnleeuw]

Description

During startup of our service, which is multi-threaded, we occasionally get a ConcurrentModificationException when set try to adjust the log-level.

Configuration

Version: 2.24.2

Operating system: Windows 11, Linux

JDK: JDK17, JDK21. Tested with multiple distributions.

Logs

At this line of code:

		Configurator.setLevel(msgLog.getName(), msgLogLevel);

We sometimes get this exception:

2024-12-06 10:36:53,174 ERROR [main] {} lifecycle.ApplicationMessageEvent - Application [Ibis4Test] an exception occurred while loading configuration [MainConfig]java.util.ConcurrentModificationException: null
 at java.base/java.util.HashMap$ValueSpliterator.forEachRemaining(Unknown Source) ~[?:?]
 at java.base/java.util.stream.ReferencePipeline$Head.forEach(Unknown Source) ~[?:?]
 at java.base/java.util.stream.ReferencePipeline$7$1.accept(Unknown Source) ~[?:?]
 at java.base/java.util.WeakHashMap$ValueSpliterator.forEachRemaining(Unknown Source) ~[?:?]
 at java.base/java.util.stream.AbstractPipeline.copyInto(Unknown Source) ~[?:?]
 at java.base/java.util.stream.AbstractPipeline.wrapAndCopyInto(Unknown Source) ~[?:?]
 at java.base/java.util.stream.ForEachOps$ForEachOp.evaluateSequential(Unknown Source) ~[?:?]
 at java.base/java.util.stream.ForEachOps$ForEachOp$OfRef.evaluateSequential(Unknown Source) ~[?:?]
 at java.base/java.util.stream.AbstractPipeline.evaluate(Unknown Source) ~[?:?]
 at java.base/java.util.stream.ReferencePipeline.forEach(Unknown Source) ~[?:?]
 at org.apache.logging.log4j.core.LoggerContext.updateLoggers(LoggerContext.java:776) ~[log4j-core-2.24.2.jar:2.24.2]
 at org.apache.logging.log4j.core.LoggerContext.updateLoggers(LoggerContext.java:766) ~[log4j-core-2.24.2.jar:2.24.2]
 at org.apache.logging.log4j.core.config.Configurator.setLevel(Configurator.java:379) ~[log4j-core-2.24.2.jar:2.24.2]
 at org.apache.logging.log4j.core.config.Configurator.setLevel(Configurator.java:414) ~[log4j-core-2.24.2.jar:2.24.2]
 at org.frankframework.core.Adapter.configure(Adapter.java:186) ~[frankframework-core-9.0.0-20241206.042346.jar:9.0.0-20241206.042346] at org.frankframework.configuration.AdapterManager.configure(AdapterManager.java:152) ~[frankframework-core-9.0.0-20241206.042346.jar:9.0.0-20241206.042346]
 at org.frankframework.lifecycle.ConfiguringLifecycleProcessor$LifecycleGroup.configure(ConfiguringLifecycleProcessor.java:84) ~[frankframework-core-9.0.0-20241206.042346.jar:9.0.0-20241206.042346] at 

(Rest of stacktrace omitted since it's not relevant).

Reproduction

Unfortunately since this goes wrong due to race-conditions in a multi-threaded environment, it will be hard to make a unit-test.

I have created this patch against the current 2.x branch in the repository. The patch to InternalLoggerRegistry should fix this issue. The change to LoggerRegistry is not required but changes the code to use best practice of not adding to a collection from Stream.forEach().

Subject: [PATCH] Fix multithreading issue
---
Index: log4j-api/src/main/java/org/apache/logging/log4j/spi/LoggerRegistry.java
IDEA additional info:
Subsystem: com.intellij.openapi.diff.impl.patch.CharsetEP
<+>UTF-8
===================================================================
diff --git a/log4j-api/src/main/java/org/apache/logging/log4j/spi/LoggerRegistry.java b/log4j-api/src/main/java/org/apache/logging/log4j/spi/LoggerRegistry.java
--- a/log4j-api/src/main/java/org/apache/logging/log4j/spi/LoggerRegistry.java	(revision df9190834372b9d5958ae80435424ad98140d358)
+++ b/log4j-api/src/main/java/org/apache/logging/log4j/spi/LoggerRegistry.java	(date 1733491829642)
@@ -28,6 +28,8 @@
 import java.util.concurrent.locks.Lock;
 import java.util.concurrent.locks.ReadWriteLock;
 import java.util.concurrent.locks.ReentrantReadWriteLock;
+import java.util.stream.Collectors;
+
 import org.apache.logging.log4j.Logger;
 import org.apache.logging.log4j.message.MessageFactory;
 import org.apache.logging.log4j.message.ParameterizedMessageFactory;
@@ -171,19 +173,19 @@
     }
 
     public Collection<T> getLoggers() {
-        return getLoggers(new ArrayList<>());
-    }
-
-    public Collection<T> getLoggers(final Collection<T> destination) {
-        requireNonNull(destination, "destination");
         readLock.lock();
         try {
-            loggerByMessageFactoryByName.values().stream()
+            return loggerByMessageFactoryByName.values().stream()
                     .flatMap(loggerByMessageFactory -> loggerByMessageFactory.values().stream())
-                    .forEach(destination::add);
+                    .collect(Collectors.toList());
         } finally {
             readLock.unlock();
         }
+    }
+
+    public Collection<T> getLoggers(final Collection<T> destination) {
+        requireNonNull(destination, "destination");
+        destination.addAll(getLoggers());
         return destination;
     }
 
Index: log4j-core/src/main/java/org/apache/logging/log4j/core/util/internal/InternalLoggerRegistry.java
IDEA additional info:
Subsystem: com.intellij.openapi.diff.impl.patch.CharsetEP
<+>UTF-8
===================================================================
diff --git a/log4j-core/src/main/java/org/apache/logging/log4j/core/util/internal/InternalLoggerRegistry.java b/log4j-core/src/main/java/org/apache/logging/log4j/core/util/internal/InternalLoggerRegistry.java
--- a/log4j-core/src/main/java/org/apache/logging/log4j/core/util/internal/InternalLoggerRegistry.java	(revision df9190834372b9d5958ae80435424ad98140d358)
+++ b/log4j-core/src/main/java/org/apache/logging/log4j/core/util/internal/InternalLoggerRegistry.java	(date 1733491829631)
@@ -20,6 +20,7 @@
 
 import java.lang.ref.WeakReference;
 import java.util.HashMap;
+import java.util.List;
 import java.util.Map;
 import java.util.Optional;
 import java.util.WeakHashMap;
@@ -27,6 +28,7 @@
 import java.util.concurrent.locks.ReadWriteLock;
 import java.util.concurrent.locks.ReentrantReadWriteLock;
 import java.util.function.BiFunction;
+import java.util.stream.Collectors;
 import java.util.stream.Stream;
 import org.apache.logging.log4j.core.Logger;
 import org.apache.logging.log4j.message.MessageFactory;
@@ -81,12 +83,15 @@
     public Stream<Logger> getLoggers() {
         readLock.lock();
         try {
-            return loggerRefByNameByMessageFactory.values().stream()
+            // While under lock, gather all loggers and collect into a list so that we can safely stream through that list when lock is released
+            List<Logger> result = loggerRefByNameByMessageFactory.values().stream()
                     .flatMap(loggerRefByName -> loggerRefByName.values().stream())
                     .flatMap(loggerRef -> {
                         @Nullable Logger logger = loggerRef.get();
                         return logger != null ? Stream.of(logger) : Stream.empty();
-                    });
+                    })
+                    .collect(Collectors.toList());
+            return result.stream();
         } finally {
             readLock.unlock();
         }

[vy]

@tnleeuw, I guess this is a duplicate of #3234, fixed by #3235. Would you mind checking, please?

[tnleeuw]

@tnleeuw, I guess this is a duplicate of #3234, fixed by #3235. Would you mind checking, please?

Yes, it is a duplicate -- I just discovered that issue 🤦

I'll check your fix.

[tnleeuw]

@tnleeuw, I guess this is a duplicate of #3234, fixed by #3235. Would you mind checking, please?

I don't have a reliable production (it just randomly fails in our CI) but I looked at the code changes and based on my understanding of the problem I have confidence it fixes the issue, the change is similar to my own change that is included in the issue.

I did include one other change which is not related to the bug at hand but is a "Best Practice" when it comes to using Stream.forEach(), you may wish to look at it and include it in a separate change.

[ppkarwasz]

@tnleeuw,

I did include one other change which is not related to the bug at hand but is a "Best Practice" when it comes to using Stream.forEach(), you may wish to look at it and include it in a separate change.

I removed the improper use of forEach() in #3235. If you don't see other problems, I will merge it and cut a release next week.

[tnleeuw]

I saw your note, the change looks good to me!

[ppkarwasz]

Closing as duplicate of #3234.