From e907678e383cc7ded1bdf9029fb26277b10e7ddc Mon Sep 17 00:00:00 2001 From: suvrat1629 Date: Wed, 19 Feb 2025 20:10:15 +0530 Subject: [PATCH 1/5] ensured stale loggers are removed from InternalLoggerRegistry and also added InternalLoggerRegistryGCTest --- .../util/InternalLoggerRegistryGCTest.java | 122 ++++++++++++++++++ .../util/internal/InternalLoggerRegistry.java | 89 ++++++------- 2 files changed, 162 insertions(+), 49 deletions(-) create mode 100644 log4j-core-test/src/main/java/org/apache/logging/log4j/core/test/util/InternalLoggerRegistryGCTest.java diff --git a/log4j-core-test/src/main/java/org/apache/logging/log4j/core/test/util/InternalLoggerRegistryGCTest.java b/log4j-core-test/src/main/java/org/apache/logging/log4j/core/test/util/InternalLoggerRegistryGCTest.java new file mode 100644 index 00000000000..c913f923368 --- /dev/null +++ b/log4j-core-test/src/main/java/org/apache/logging/log4j/core/test/util/InternalLoggerRegistryGCTest.java @@ -0,0 +1,122 @@ +/* + * Licensed to the Apache Software Foundation (ASF) under one or more + * contributor license agreements. See the NOTICE file distributed with + * this work for additional information regarding copyright ownership. + * The ASF licenses this file to you under the Apache License, Version 2.0 + * (the "License"); you may not use this file except in compliance with + * the License. You may obtain a copy of the License at + * + * http://www.apache.org/licenses/LICENSE-2.0 + * + * Unless required by applicable law or agreed to in writing, software + * distributed under the License is distributed on an "AS IS" BASIS, + * WITHOUT WARRANTIES OR CONDITIONS OF ANY KIND, either express or implied. + * See the License for the specific language governing permissions and + * limitations under the License. + */ +package org.apache.logging.log4j.core.test.util; + +import static org.junit.jupiter.api.Assertions.*; + +import java.lang.ref.WeakReference; +import java.util.concurrent.CountDownLatch; +import java.util.concurrent.ExecutorService; +import java.util.concurrent.Executors; +import org.apache.logging.log4j.core.Logger; +import org.apache.logging.log4j.core.LoggerContext; +import org.apache.logging.log4j.core.util.internal.InternalLoggerRegistry; +import org.apache.logging.log4j.message.MessageFactory; +import org.apache.logging.log4j.message.SimpleMessageFactory; +import org.junit.jupiter.api.BeforeEach; +import org.junit.jupiter.api.Test; + +class InternalLoggerRegistryTest { + private InternalLoggerRegistry registry; + private MessageFactory messageFactory; + + @BeforeEach + void setUp() { + registry = new InternalLoggerRegistry(); + messageFactory = new SimpleMessageFactory(); + } + + @Test + void testGetLoggerReturnsNullForNonExistentLogger() { + assertNull(registry.getLogger("nonExistent", messageFactory)); + } + + @Test + void testComputeIfAbsentCreatesLogger() { + Logger logger = + registry.computeIfAbsent("testLogger", messageFactory, (name, factory) -> LoggerContext.getContext() + .getLogger(name, factory)); + assertNotNull(logger); + assertEquals("testLogger", logger.getName()); + } + + @Test + void testGetLoggerRetrievesExistingLogger() { + Logger logger = + registry.computeIfAbsent("testLogger", messageFactory, (name, factory) -> LoggerContext.getContext() + .getLogger(name, factory)); + assertSame(logger, registry.getLogger("testLogger", messageFactory)); + } + + @Test + void testHasLoggerReturnsCorrectStatus() { + assertFalse(registry.hasLogger("testLogger", messageFactory)); + registry.computeIfAbsent("testLogger", messageFactory, (name, factory) -> LoggerContext.getContext() + .getLogger(name, factory)); + assertTrue(registry.hasLogger("testLogger", messageFactory)); + } + + @Test + void testExpungeStaleEntriesRemovesGarbageCollectedLoggers() throws InterruptedException { + Logger logger = + registry.computeIfAbsent("testLogger", messageFactory, (name, factory) -> LoggerContext.getContext() + .getLogger(name, factory)); + + WeakReference weakRef = new WeakReference<>(logger); + logger = null; // Dereference to allow GC + + // Retry loop to give GC time to collect + for (int i = 0; i < 10; i++) { + System.gc(); + Thread.sleep(100); + if (weakRef.get() == null) { + break; + } + } + + // Access the registry to potentially trigger cleanup + registry.computeIfAbsent("tempLogger", messageFactory, (name, factory) -> LoggerContext.getContext() + .getLogger(name, factory)); + + assertNull(weakRef.get(), "Logger should have been garbage collected"); + assertNull( + registry.getLogger("testLogger", messageFactory), "Stale logger should be removed from the registry"); + } + + @Test + void testConcurrentAccess() throws InterruptedException { + int threadCount = 10; + ExecutorService executor = Executors.newFixedThreadPool(threadCount); + CountDownLatch latch = new CountDownLatch(threadCount); + + for (int i = 0; i < threadCount; i++) { + executor.submit(() -> { + registry.computeIfAbsent("testLogger", messageFactory, (name, factory) -> LoggerContext.getContext() + .getLogger(name, factory)); + latch.countDown(); + }); + } + + latch.await(); + executor.shutdown(); + + // Verify logger was created and is accessible after concurrent creation + assertNotNull( + registry.getLogger("testLogger", messageFactory), + "Logger should be accessible after concurrent creation"); + } +} 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 index eff1d46b77a..a1926a6d61f 100644 --- 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 @@ -18,6 +18,8 @@ import static java.util.Objects.requireNonNull; +import java.lang.ref.Reference; +import java.lang.ref.ReferenceQueue; import java.lang.ref.WeakReference; import java.util.Collection; import java.util.HashMap; @@ -39,10 +41,8 @@ /** * A registry of {@link Logger}s namespaced by name and message factory. * This class is internally used by {@link LoggerContext}. - *

- * We don't use {@linkplain org.apache.logging.log4j.spi.LoggerRegistry the registry from Log4j API} to keep Log4j Core independent from the version of Log4j API at runtime. - * This also allows Log4j Core to evolve independently from Log4j API. - *

+ * + * Handles automatic cleanup of stale logger references to prevent memory leaks. * * @since 2.25.0 */ @@ -53,23 +53,44 @@ public final class InternalLoggerRegistry { new WeakHashMap<>(); private final ReadWriteLock lock = new ReentrantReadWriteLock(); - private final Lock readLock = lock.readLock(); - private final Lock writeLock = lock.writeLock(); + // ReferenceQueue to track stale WeakReferences + private final ReferenceQueue staleLoggerRefs = new ReferenceQueue<>(); + public InternalLoggerRegistry() {} + /** + * Expunges stale logger references from the registry. + */ + private void expungeStaleEntries() { + Reference loggerRef; + while ((loggerRef = staleLoggerRefs.poll()) != null) { + removeLogger(loggerRef); + } + } + + /** + * Removes a logger from the registry. + */ + private void removeLogger(Reference loggerRef) { + writeLock.lock(); + try { + loggerRefByNameByMessageFactory.values().forEach(map -> map.values().removeIf(ref -> ref == loggerRef)); + } finally { + writeLock.unlock(); + } + } + /** * Returns the logger associated with the given name and message factory. - * - * @param name a logger name - * @param messageFactory a message factory - * @return the logger associated with the given name and message factory */ public @Nullable Logger getLogger(final String name, final MessageFactory messageFactory) { requireNonNull(name, "name"); requireNonNull(messageFactory, "messageFactory"); + expungeStaleEntries(); // Clean up before retrieving + readLock.lock(); try { final Map> loggerRefByName = @@ -87,11 +108,10 @@ public InternalLoggerRegistry() {} } public Collection getLoggers() { + expungeStaleEntries(); // Clean up before retrieving + readLock.lock(); try { - // Return a new collection to allow concurrent iteration over the loggers - // - // https://github.com/apache/logging-log4j2/issues/3234 return loggerRefByNameByMessageFactory.values().stream() .flatMap(loggerRefByName -> loggerRefByName.values().stream()) .flatMap(loggerRef -> { @@ -104,29 +124,17 @@ public Collection getLoggers() { } } - /** - * Checks if a logger associated with the given name and message factory exists. - * - * @param name a logger name - * @param messageFactory a message factory - * @return {@code true}, if the logger exists; {@code false} otherwise. - */ public boolean hasLogger(final String name, final MessageFactory messageFactory) { requireNonNull(name, "name"); requireNonNull(messageFactory, "messageFactory"); return getLogger(name, messageFactory) != null; } - /** - * Checks if a logger associated with the given name and message factory type exists. - * - * @param name a logger name - * @param messageFactoryClass a message factory class - * @return {@code true}, if the logger exists; {@code false} otherwise. - */ public boolean hasLogger(final String name, final Class messageFactoryClass) { requireNonNull(name, "name"); requireNonNull(messageFactoryClass, "messageFactoryClass"); + expungeStaleEntries(); // Clean up before checking + readLock.lock(); try { return loggerRefByNameByMessageFactory.entrySet().stream() @@ -142,37 +150,21 @@ public Logger computeIfAbsent( final MessageFactory messageFactory, final BiFunction loggerSupplier) { - // Check arguments requireNonNull(name, "name"); requireNonNull(messageFactory, "messageFactory"); requireNonNull(loggerSupplier, "loggerSupplier"); - // Read lock fast path: See if logger already exists + expungeStaleEntries(); // Clean up before adding a new logger + @Nullable Logger logger = getLogger(name, messageFactory); if (logger != null) { return logger; } - // Intentionally moving the logger creation outside the write lock, because: - // - // - Logger instantiation is expensive (causes contention on the write-lock) - // - // - User code might have circular code paths, though through different threads. - // Consider `T1[ILR:computeIfAbsent] -> ... -> T1[Logger::new] -> ... -> T2[ILR::computeIfAbsent]`. - // Hence, having logger instantiation while holding a write lock might cause deadlocks: - // https://github.com/apache/logging-log4j2/issues/3252 - // https://github.com/apache/logging-log4j2/issues/3399 - // - // - Creating loggers without a lock, allows multiple threads to create loggers in parallel, which also improves - // performance. - // - // Since all loggers with the same parameters are equivalent, we can safely return the logger from the - // thread that finishes first. Logger newLogger = loggerSupplier.apply(name, messageFactory); - - // Report name and message factory mismatch if there are any final String loggerName = newLogger.getName(); final MessageFactory loggerMessageFactory = newLogger.getMessageFactory(); + if (!loggerName.equals(name) || !loggerMessageFactory.equals(messageFactory)) { StatusLogger.getLogger() .error( @@ -186,17 +178,16 @@ public Logger computeIfAbsent( messageFactory); } - // Write lock slow path: Insert the logger writeLock.lock(); try { Map> loggerRefByName = loggerRefByNameByMessageFactory.get(messageFactory); - // noinspection Java8MapApi (avoid the allocation of lambda passed to `Map::computeIfAbsent`) if (loggerRefByName == null) { loggerRefByNameByMessageFactory.put(messageFactory, loggerRefByName = new HashMap<>()); } + final WeakReference loggerRef = loggerRefByName.get(name); if (loggerRef == null || (logger = loggerRef.get()) == null) { - loggerRefByName.put(name, new WeakReference<>(logger = newLogger)); + loggerRefByName.put(name, new WeakReference<>(logger = newLogger, staleLoggerRefs)); } return logger; } finally { From 38d86f104e63ba09c55d5d46c4177130a5da3652 Mon Sep 17 00:00:00 2001 From: suvrat1629 Date: Wed, 19 Feb 2025 20:21:21 +0530 Subject: [PATCH 2/5] removed wildcard imports --- .../log4j/core/test/util/InternalLoggerRegistryGCTest.java | 7 ++++++- 1 file changed, 6 insertions(+), 1 deletion(-) diff --git a/log4j-core-test/src/main/java/org/apache/logging/log4j/core/test/util/InternalLoggerRegistryGCTest.java b/log4j-core-test/src/main/java/org/apache/logging/log4j/core/test/util/InternalLoggerRegistryGCTest.java index c913f923368..59f7bdd0b68 100644 --- a/log4j-core-test/src/main/java/org/apache/logging/log4j/core/test/util/InternalLoggerRegistryGCTest.java +++ b/log4j-core-test/src/main/java/org/apache/logging/log4j/core/test/util/InternalLoggerRegistryGCTest.java @@ -16,7 +16,12 @@ */ package org.apache.logging.log4j.core.test.util; -import static org.junit.jupiter.api.Assertions.*; +import static org.junit.jupiter.api.Assertions.assertEquals; +import static org.junit.jupiter.api.Assertions.assertFalse; +import static org.junit.jupiter.api.Assertions.assertNotNull; +import static org.junit.jupiter.api.Assertions.assertNull; +import static org.junit.jupiter.api.Assertions.assertSame; +import static org.junit.jupiter.api.Assertions.assertTrue; import java.lang.ref.WeakReference; import java.util.concurrent.CountDownLatch; From adee3d52e5dd4d97368c759a83ec2e798a603bb5 Mon Sep 17 00:00:00 2001 From: suvrat1629 Date: Fri, 21 Feb 2025 19:39:31 +0530 Subject: [PATCH 3/5] added the comments again --- .../util/internal/InternalLoggerRegistry.java | 54 +++++++++++++++++-- 1 file changed, 51 insertions(+), 3 deletions(-) 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 index a1926a6d61f..af641684bc2 100644 --- 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 @@ -41,8 +41,12 @@ /** * A registry of {@link Logger}s namespaced by name and message factory. * This class is internally used by {@link LoggerContext}. - * - * Handles automatic cleanup of stale logger references to prevent memory leaks. + *

+ * We don't use {@linkplain org.apache.logging.log4j.spi.LoggerRegistry the + * registry from Log4j API} to keep Log4j Core independent from the version of + * Log4j API at runtime. + * This also allows Log4j Core to evolve independently from Log4j API. + *

* * @since 2.25.0 */ @@ -85,6 +89,10 @@ private void removeLogger(Reference loggerRef) { /** * Returns the logger associated with the given name and message factory. + * + * @param name a logger name + * @param messageFactory a message factory + * @return the logger associated with the given name and message factory */ public @Nullable Logger getLogger(final String name, final MessageFactory messageFactory) { requireNonNull(name, "name"); @@ -112,6 +120,9 @@ public Collection getLoggers() { readLock.lock(); try { + // Return a new collection to allow concurrent iteration over the loggers + // + // https://github.com/apache/logging-log4j2/issues/3234 return loggerRefByNameByMessageFactory.values().stream() .flatMap(loggerRefByName -> loggerRefByName.values().stream()) .flatMap(loggerRef -> { @@ -124,12 +135,27 @@ public Collection getLoggers() { } } + /** + * Checks if a logger associated with the given name and message factory exists. + * + * @param name a logger name + * @param messageFactory a message factory + * @return {@code true}, if the logger exists; {@code false} otherwise. + */ public boolean hasLogger(final String name, final MessageFactory messageFactory) { requireNonNull(name, "name"); requireNonNull(messageFactory, "messageFactory"); return getLogger(name, messageFactory) != null; } + /** + * Checks if a logger associated with the given name and message factory type + * exists. + * + * @param name a logger name + * @param messageFactoryClass a message factory class + * @return {@code true}, if the logger exists; {@code false} otherwise. + */ public boolean hasLogger(final String name, final Class messageFactoryClass) { requireNonNull(name, "name"); requireNonNull(messageFactoryClass, "messageFactoryClass"); @@ -161,10 +187,30 @@ public Logger computeIfAbsent( return logger; } + // Intentionally moving the logger creation outside the write lock, because: + // + // - Logger instantiation is expensive (causes contention on the write-lock) + // + // - User code might have circular code paths, though through different threads. + // Consider `T1[ILR:computeIfAbsent] -> ... -> T1[Logger::new] -> ... -> + // T2[ILR::computeIfAbsent]`. + // Hence, having logger instantiation while holding a write lock might cause + // deadlocks: + // https://github.com/apache/logging-log4j2/issues/3252 + // https://github.com/apache/logging-log4j2/issues/3399 + // + // - Creating loggers without a lock, allows multiple threads to create loggers + // in parallel, which also improves + // performance. + // + // Since all loggers with the same parameters are equivalent, we can safely + // return the logger from the + // thread that finishes first. Logger newLogger = loggerSupplier.apply(name, messageFactory); + + // Report name and message factory mismatch if there are any final String loggerName = newLogger.getName(); final MessageFactory loggerMessageFactory = newLogger.getMessageFactory(); - if (!loggerName.equals(name) || !loggerMessageFactory.equals(messageFactory)) { StatusLogger.getLogger() .error( @@ -178,9 +224,11 @@ public Logger computeIfAbsent( messageFactory); } + // Write lock slow path: Insert the logger writeLock.lock(); try { Map> loggerRefByName = loggerRefByNameByMessageFactory.get(messageFactory); + // noinspection Java8MapApi (avoid the allocation of lambda passed to `Map::computeIfAbsent`) if (loggerRefByName == null) { loggerRefByNameByMessageFactory.put(messageFactory, loggerRefByName = new HashMap<>()); } From 1a4c8641f720646b9d24ef5ef281761739791e8c Mon Sep 17 00:00:00 2001 From: suvrat1629 Date: Fri, 21 Feb 2025 21:28:38 +0530 Subject: [PATCH 4/5] changed the removeLogger to not iterate --- .../core/util/internal/InternalLoggerRegistry.java | 14 +++++++++++++- 1 file changed, 13 insertions(+), 1 deletion(-) 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 index af641684bc2..d379380e575 100644 --- 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 @@ -79,9 +79,21 @@ private void expungeStaleEntries() { * Removes a logger from the registry. */ private void removeLogger(Reference loggerRef) { + Logger logger = loggerRef.get(); + if (logger == null) return; // Logger already cleared + + MessageFactory messageFactory = logger.getMessageFactory(); + String name = logger.getName(); + writeLock.lock(); try { - loggerRefByNameByMessageFactory.values().forEach(map -> map.values().removeIf(ref -> ref == loggerRef)); + Map> loggerRefByName = loggerRefByNameByMessageFactory.get(messageFactory); + if (loggerRefByName != null) { + loggerRefByName.remove(name); + if (loggerRefByName.isEmpty()) { + loggerRefByNameByMessageFactory.remove(messageFactory); // Cleanup + } + } } finally { writeLock.unlock(); } From f1a62f9602da7820ad05eab1999f32bc81bd4c44 Mon Sep 17 00:00:00 2001 From: suvrat1629 Date: Sun, 23 Feb 2025 10:12:46 +0530 Subject: [PATCH 5/5] reverted more changes --- .../util/internal/InternalLoggerRegistry.java | 27 +++++++++---------- 1 file changed, 12 insertions(+), 15 deletions(-) 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 index d379380e575..a83faa830d1 100644 --- 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 @@ -102,7 +102,7 @@ private void removeLogger(Reference loggerRef) { /** * Returns the logger associated with the given name and message factory. * - * @param name a logger name + * @param name a logger name * @param messageFactory a message factory * @return the logger associated with the given name and message factory */ @@ -150,7 +150,7 @@ public Collection getLoggers() { /** * Checks if a logger associated with the given name and message factory exists. * - * @param name a logger name + * @param name a logger name * @param messageFactory a message factory * @return {@code true}, if the logger exists; {@code false} otherwise. */ @@ -161,10 +161,9 @@ public boolean hasLogger(final String name, final MessageFactory messageFactory) } /** - * Checks if a logger associated with the given name and message factory type - * exists. + * Checks if a logger associated with the given name and message factory type exists. * - * @param name a logger name + * @param name a logger name * @param messageFactoryClass a message factory class * @return {@code true}, if the logger exists; {@code false} otherwise. */ @@ -188,12 +187,14 @@ public Logger computeIfAbsent( final MessageFactory messageFactory, final BiFunction loggerSupplier) { + // Check arguments requireNonNull(name, "name"); requireNonNull(messageFactory, "messageFactory"); requireNonNull(loggerSupplier, "loggerSupplier"); expungeStaleEntries(); // Clean up before adding a new logger + // Read lock fast path: See if logger already exists @Nullable Logger logger = getLogger(name, messageFactory); if (logger != null) { return logger; @@ -204,19 +205,15 @@ public Logger computeIfAbsent( // - Logger instantiation is expensive (causes contention on the write-lock) // // - User code might have circular code paths, though through different threads. - // Consider `T1[ILR:computeIfAbsent] -> ... -> T1[Logger::new] -> ... -> - // T2[ILR::computeIfAbsent]`. - // Hence, having logger instantiation while holding a write lock might cause - // deadlocks: - // https://github.com/apache/logging-log4j2/issues/3252 - // https://github.com/apache/logging-log4j2/issues/3399 + // Consider `T1[ILR:computeIfAbsent] -> ... -> T1[Logger::new] -> ... -> T2[ILR::computeIfAbsent]`. + // Hence, having logger instantiation while holding a write lock might cause deadlocks: + // https://github.com/apache/logging-log4j2/issues/3252 + // https://github.com/apache/logging-log4j2/issues/3399 // - // - Creating loggers without a lock, allows multiple threads to create loggers - // in parallel, which also improves + // - Creating loggers without a lock, allows multiple threads to create loggers in parallel, which also improves // performance. // - // Since all loggers with the same parameters are equivalent, we can safely - // return the logger from the + // Since all loggers with the same parameters are equivalent, we can safely return the logger from the // thread that finishes first. Logger newLogger = loggerSupplier.apply(name, messageFactory);