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.

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

Expunge stale loggers in InternalLoggerRegistry on method invocation #3474

Open
wants to merge 5 commits into
base: 2.x
Choose a base branch
from
Open
Show file tree
Hide file tree
Changes from 3 commits
Commits
File filter

Filter by extension

Filter by extension

Conversations
Failed to load comments.
Loading
Jump to
Jump to file
Failed to load files.
Loading
Diff view
Diff view
Copy link
Member

Choose a reason for hiding this comment

The reason will be displayed to describe this comment to others. Learn more.

Can you replace LoggerContext.getContext() calls as follows, please?

@Test
void someTest(TestInfo testInfo) {
    try (final LoggerContext loggerContext = new LoggerContext(testInfo.getDisplayName)) {
        // Use `loggerContext`
    }
}

That is, don't disrupt the global one, use ephemeral LCs instead.

Original file line number Diff line number Diff line change
@@ -0,0 +1,127 @@
/*
* 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.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;
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<Logger> 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");
Comment on lines +80 to +102
Copy link
Member

Choose a reason for hiding this comment

The reason will be displayed to describe this comment to others. Learn more.

Can we instead replace this as follows, please?

  1. Use an ephemeral LoggerContext (as I described in another comment)
  2. Create 1000 Loggers (should be many enough to create GC pressure)
  3. Log using all Loggers (so we imitate a real-world setup where Loggers are used at some point)
  4. Use Awaitility.waitAtMost(...).until(...) to verify that after a System.gc(), InternalLoggerRegistry::loggerRefByNameByMessageFactory is emptied

You can access to InternalLoggerRegistry::loggerRefByNameByMessageFactory using reflection. That is, first extract the LoggerContext::loggerRegistry field, and then the InternalLoggerRegistry::loggerRefByNameByMessageFactory field.

}

@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");
}
}
Original file line number Diff line number Diff line change
Expand Up @@ -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;
Expand All @@ -40,7 +42,9 @@
* A registry of {@link Logger}s namespaced by name and message factory.
* This class is internally used by {@link LoggerContext}.
* <p>
* 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.
* 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.
* </p>
*
Expand All @@ -53,23 +57,48 @@ 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<Logger> staleLoggerRefs = new ReferenceQueue<>();

public InternalLoggerRegistry() {}

/**
* Expunges stale logger references from the registry.
*/
private void expungeStaleEntries() {
Reference<? extends Logger> loggerRef;
while ((loggerRef = staleLoggerRefs.poll()) != null) {
removeLogger(loggerRef);
}
Comment on lines +72 to +75
Copy link
Member

Choose a reason for hiding this comment

The reason will be displayed to describe this comment to others. Learn more.

Would you mind changing this loop as follows, please?

boolean locked = false;
Reference<? extends Logger> loggerRef;
while ((loggerRef = staleLoggerRefs.poll()) != null) {
    Logger logger = loggerRef.get();
    if (logger != null) {
        if (!locked) {
            writeLock.lock();
        }
        unsafeRemoveLogger(logger);
    }
}
if (locked) {
    writeLock.unlock();
}

See my other comment regarding the unsafeRemoveLogger(Logger) method.

Copy link
Contributor

Choose a reason for hiding this comment

The reason will be displayed to describe this comment to others. Learn more.

Note that if loggerRef.get() returns null, we still need to remove the entry that holds the WeakReference.

What do you think about such an approach:

  1. We poll() the queue until its empty.
  2. If there was any reference in the queue we iterate once over all the entries of the map and we remove all the invalidated WeakReferences, not just those that were in the queue.

As of my previous comment, this seems a little bit inefficient if loggerRef.get() is not null, but is more efficient than iterating over all entries once-per-reference.

Copy link
Member

Choose a reason for hiding this comment

The reason will be displayed to describe this comment to others. Learn more.

@ppkarwasz, you're right. @Suvrat1629, please proceed with the suggestion of @ppkarwasz. Though I suggest having double-checking:

if (!refQueue.isEmpty) {
    lock();
    try {
        if (!refQueue.isEmpty) {
            // Clear `refQueue`
            // Clean up `loggerRefByNameByMessageFactory`
        }
    } finally {
       unlock();
    }
}

}

/**
* Removes a logger from the registry.
*/
private void removeLogger(Reference<? extends Logger> 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 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<String, WeakReference<Logger>> loggerRefByName =
Expand All @@ -87,6 +116,8 @@ public InternalLoggerRegistry() {}
}

public Collection<Logger> getLoggers() {
expungeStaleEntries(); // Clean up before retrieving

readLock.lock();
try {
// Return a new collection to allow concurrent iteration over the loggers
Expand All @@ -107,7 +138,7 @@ public Collection<Logger> 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.
*/
Expand All @@ -118,15 +149,18 @@ 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.
*/
public boolean hasLogger(final String name, final Class<? extends MessageFactory> messageFactoryClass) {
requireNonNull(name, "name");
requireNonNull(messageFactoryClass, "messageFactoryClass");
expungeStaleEntries(); // Clean up before checking

readLock.lock();
try {
return loggerRefByNameByMessageFactory.entrySet().stream()
Expand All @@ -142,12 +176,12 @@ public Logger computeIfAbsent(
final MessageFactory messageFactory,
final BiFunction<String, MessageFactory, Logger> 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;
Expand All @@ -158,15 +192,19 @@ 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);

Expand Down Expand Up @@ -194,9 +232,10 @@ public Logger computeIfAbsent(
if (loggerRefByName == null) {
loggerRefByNameByMessageFactory.put(messageFactory, loggerRefByName = new HashMap<>());
}

final WeakReference<Logger> 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 {
Expand Down