Skip to content

Commit 93cb845

Browse files
jhl221123Suvrat1629
authored and
ramanathan1504
committed
Expunge stale entries in InternalLoggerRegistry (apache#3681)
Co-authored-by: suvrat1629 <[email protected]>
1 parent a725019 commit 93cb845

File tree

3 files changed

+276
-38
lines changed

3 files changed

+276
-38
lines changed

‎log4j-core-test/src/test/java/org/apache/logging/log4j/core/util/internal/InternalLoggerRegistryTest.java‎

Lines changed: 153 additions & 0 deletions
Original file line numberDiff line numberDiff line change
@@ -0,0 +1,153 @@
1+
/*
2+
* Licensed to the Apache Software Foundation (ASF) under one or more
3+
* contributor license agreements. See the NOTICE file distributed with
4+
* this work for additional information regarding copyright ownership.
5+
* The ASF licenses this file to you under the Apache License, Version 2.0
6+
* (the "License"); you may not use this file except in compliance with
7+
* the License. You may obtain a copy of the License at
8+
*
9+
* http://www.apache.org/licenses/LICENSE-2.0
10+
*
11+
* Unless required by applicable law or agreed to in writing, software
12+
* distributed under the License is distributed on an "AS IS" BASIS,
13+
* WITHOUT WARRANTIES OR CONDITIONS OF ANY KIND, either express or implied.
14+
* See the License for the specific language governing permissions and
15+
* limitations under the License.
16+
*/
17+
package org.apache.logging.log4j.core.util.internal;
18+
19+
import static java.util.concurrent.TimeUnit.MILLISECONDS;
20+
import static java.util.concurrent.TimeUnit.SECONDS;
21+
import static org.awaitility.Awaitility.await;
22+
import static org.junit.jupiter.api.Assertions.assertEquals;
23+
import static org.junit.jupiter.api.Assertions.assertFalse;
24+
import static org.junit.jupiter.api.Assertions.assertNotNull;
25+
import static org.junit.jupiter.api.Assertions.assertNull;
26+
import static org.junit.jupiter.api.Assertions.assertSame;
27+
import static org.junit.jupiter.api.Assertions.assertTrue;
28+
29+
import java.lang.ref.WeakReference;
30+
import java.lang.reflect.Field;
31+
import java.util.Map;
32+
import org.apache.logging.log4j.core.Logger;
33+
import org.apache.logging.log4j.core.LoggerContext;
34+
import org.apache.logging.log4j.message.MessageFactory;
35+
import org.apache.logging.log4j.message.SimpleMessageFactory;
36+
import org.junit.jupiter.api.AfterEach;
37+
import org.junit.jupiter.api.BeforeEach;
38+
import org.junit.jupiter.api.Test;
39+
import org.junit.jupiter.api.TestInfo;
40+
41+
class InternalLoggerRegistryTest {
42+
private LoggerContext loggerContext;
43+
private InternalLoggerRegistry registry;
44+
private MessageFactory messageFactory;
45+
46+
@BeforeEach
47+
void setUp(TestInfo testInfo) throws NoSuchFieldException, IllegalAccessException {
48+
loggerContext = new LoggerContext(testInfo.getDisplayName());
49+
final Field registryField = loggerContext.getClass().getDeclaredField("loggerRegistry");
50+
registryField.setAccessible(true);
51+
registry = (InternalLoggerRegistry) registryField.get(loggerContext);
52+
messageFactory = SimpleMessageFactory.INSTANCE;
53+
}
54+
55+
@AfterEach
56+
void tearDown() {
57+
if (loggerContext != null) {
58+
loggerContext.stop();
59+
}
60+
}
61+
62+
@Test
63+
void testGetLoggerReturnsNullForNonExistentLogger() {
64+
assertNull(registry.getLogger("nonExistent", messageFactory));
65+
}
66+
67+
@Test
68+
void testComputeIfAbsentCreatesLogger() {
69+
final Logger logger = registry.computeIfAbsent(
70+
"testLogger", messageFactory, (name, factory) -> new Logger(loggerContext, name, factory) {});
71+
assertNotNull(logger);
72+
assertEquals("testLogger", logger.getName());
73+
}
74+
75+
@Test
76+
void testGetLoggerRetrievesExistingLogger() {
77+
final Logger logger = registry.computeIfAbsent(
78+
"testLogger", messageFactory, (name, factory) -> new Logger(loggerContext, name, factory) {});
79+
assertSame(logger, registry.getLogger("testLogger", messageFactory));
80+
}
81+
82+
@Test
83+
void testHasLoggerReturnsCorrectStatus() {
84+
assertFalse(registry.hasLogger("testLogger", messageFactory));
85+
registry.computeIfAbsent(
86+
"testLogger", messageFactory, (name, factory) -> new Logger(loggerContext, name, factory) {});
87+
assertTrue(registry.hasLogger("testLogger", messageFactory));
88+
}
89+
90+
@Test
91+
void testExpungeStaleWeakReferenceEntries() {
92+
final String loggerNamePrefix = "testLogger_";
93+
final int numberOfLoggers = 1000;
94+
95+
for (int i = 0; i < numberOfLoggers; i++) {
96+
final Logger logger = registry.computeIfAbsent(
97+
loggerNamePrefix + i,
98+
messageFactory,
99+
(name, factory) -> new Logger(loggerContext, name, factory) {});
100+
logger.info("Using logger {}", logger.getName());
101+
}
102+
103+
await().atMost(10, SECONDS).pollInterval(100, MILLISECONDS).untilAsserted(() -> {
104+
System.gc();
105+
registry.computeIfAbsent(
106+
"triggerExpunge", messageFactory, (name, factory) -> new Logger(loggerContext, name, factory) {});
107+
108+
final Map<MessageFactory, Map<String, WeakReference<Logger>>> loggerRefByNameByMessageFactory =
109+
reflectAndGetLoggerMapFromRegistry();
110+
final Map<String, WeakReference<Logger>> loggerRefByName =
111+
loggerRefByNameByMessageFactory.get(messageFactory);
112+
113+
int unexpectedCount = 0;
114+
for (int i = 0; i < numberOfLoggers; i++) {
115+
if (loggerRefByName.containsKey(loggerNamePrefix + i)) {
116+
unexpectedCount++;
117+
}
118+
}
119+
assertEquals(
120+
0, unexpectedCount, "Found " + unexpectedCount + " unexpected stale entries for MessageFactory");
121+
});
122+
}
123+
124+
@Test
125+
void testExpungeStaleMessageFactoryEntry() {
126+
final SimpleMessageFactory mockMessageFactory = new SimpleMessageFactory();
127+
Logger logger = registry.computeIfAbsent(
128+
"testLogger", mockMessageFactory, (name, factory) -> new Logger(loggerContext, name, factory) {});
129+
logger.info("Using logger {}", logger.getName());
130+
logger = null;
131+
132+
await().atMost(10, SECONDS).pollInterval(100, MILLISECONDS).untilAsserted(() -> {
133+
System.gc();
134+
registry.getLogger("triggerExpunge", mockMessageFactory);
135+
136+
final Map<MessageFactory, Map<String, WeakReference<Logger>>> loggerRefByNameByMessageFactory =
137+
reflectAndGetLoggerMapFromRegistry();
138+
assertNull(
139+
loggerRefByNameByMessageFactory.get(mockMessageFactory),
140+
"Stale MessageFactory entry was not removed from the outer map");
141+
});
142+
}
143+
144+
private Map<MessageFactory, Map<String, WeakReference<Logger>>> reflectAndGetLoggerMapFromRegistry()
145+
throws NoSuchFieldException, IllegalAccessException {
146+
final Field loggerMapField = registry.getClass().getDeclaredField("loggerRefByNameByMessageFactory");
147+
loggerMapField.setAccessible(true);
148+
@SuppressWarnings("unchecked")
149+
final Map<MessageFactory, Map<String, WeakReference<Logger>>> loggerMap =
150+
(Map<MessageFactory, Map<String, WeakReference<Logger>>>) loggerMapField.get(registry);
151+
return loggerMap;
152+
}
153+
}

‎log4j-core/src/main/java/org/apache/logging/log4j/core/util/internal/InternalLoggerRegistry.java‎

Lines changed: 110 additions & 38 deletions
Original file line numberDiff line numberDiff line change
@@ -18,28 +18,37 @@
1818

1919
import static java.util.Objects.requireNonNull;
2020

21+
import java.lang.ref.Reference;
22+
import java.lang.ref.ReferenceQueue;
2123
import java.lang.ref.WeakReference;
24+
import java.util.Collection;
2225
import java.util.HashMap;
26+
import java.util.Iterator;
2327
import java.util.Map;
24-
import java.util.Optional;
2528
import java.util.WeakHashMap;
2629
import java.util.concurrent.locks.Lock;
2730
import java.util.concurrent.locks.ReadWriteLock;
2831
import java.util.concurrent.locks.ReentrantReadWriteLock;
2932
import java.util.function.BiFunction;
33+
import java.util.stream.Collectors;
3034
import java.util.stream.Stream;
3135
import org.apache.logging.log4j.core.Logger;
36+
import org.apache.logging.log4j.core.LoggerContext;
3237
import org.apache.logging.log4j.message.MessageFactory;
3338
import org.apache.logging.log4j.status.StatusLogger;
3439
import org.jspecify.annotations.NullMarked;
3540
import org.jspecify.annotations.Nullable;
3641

3742
/**
38-
* Convenience class used by {@link org.apache.logging.log4j.core.LoggerContext}
43+
* A registry of {@link Logger}s namespaced by name and message factory.
44+
* This class is internally used by {@link LoggerContext}.
3945
* <p>
40-
* We don't use {@link org.apache.logging.log4j.spi.LoggerRegistry} from the Log4j API to keep Log4j Core independent
41-
* from the version of the Log4j API at runtime.
46+
* We don't use {@linkplain org.apache.logging.log4j.spi.LoggerRegistry the
47+
* registry from Log4j API} to keep Log4j Core independent from the version of
48+
* Log4j API at runtime.
49+
* This also allows Log4j Core to evolve independently from Log4j API.
4250
* </p>
51+
*
4352
* @since 2.25.0
4453
*/
4554
@NullMarked
@@ -49,13 +58,46 @@ public final class InternalLoggerRegistry {
4958
new WeakHashMap<>();
5059

5160
private final ReadWriteLock lock = new ReentrantReadWriteLock();
52-
5361
private final Lock readLock = lock.readLock();
54-
5562
private final Lock writeLock = lock.writeLock();
5663

64+
// ReferenceQueue to track stale WeakReferences
65+
private final ReferenceQueue<Logger> staleLoggerRefs = new ReferenceQueue<>();
66+
5767
public InternalLoggerRegistry() {}
5868

69+
/**
70+
* Expunges stale entries for logger references and message factories.
71+
*/
72+
private void expungeStaleEntries() {
73+
final Reference<? extends Logger> loggerRef = staleLoggerRefs.poll();
74+
75+
if (loggerRef != null) {
76+
writeLock.lock();
77+
try {
78+
while (staleLoggerRefs.poll() != null) {
79+
// Clear refQueue
80+
}
81+
82+
final Iterator<Map.Entry<MessageFactory, Map<String, WeakReference<Logger>>>>
83+
loggerRefByNameByMessageFactoryEntryIt =
84+
loggerRefByNameByMessageFactory.entrySet().iterator();
85+
while (loggerRefByNameByMessageFactoryEntryIt.hasNext()) {
86+
final Map.Entry<MessageFactory, Map<String, WeakReference<Logger>>>
87+
loggerRefByNameByMessageFactoryEntry = loggerRefByNameByMessageFactoryEntryIt.next();
88+
final Map<String, WeakReference<Logger>> loggerRefByName =
89+
loggerRefByNameByMessageFactoryEntry.getValue();
90+
loggerRefByName.values().removeIf(weakRef -> weakRef.get() == null);
91+
if (loggerRefByName.isEmpty()) {
92+
loggerRefByNameByMessageFactoryEntryIt.remove();
93+
}
94+
}
95+
} finally {
96+
writeLock.unlock();
97+
}
98+
}
99+
}
100+
59101
/**
60102
* Returns the logger associated with the given name and message factory.
61103
*
@@ -66,27 +108,39 @@ public InternalLoggerRegistry() {}
66108
public @Nullable Logger getLogger(final String name, final MessageFactory messageFactory) {
67109
requireNonNull(name, "name");
68110
requireNonNull(messageFactory, "messageFactory");
111+
expungeStaleEntries();
112+
69113
readLock.lock();
70114
try {
71-
return Optional.of(loggerRefByNameByMessageFactory)
72-
.map(loggerRefByNameByMessageFactory -> loggerRefByNameByMessageFactory.get(messageFactory))
73-
.map(loggerRefByName -> loggerRefByName.get(name))
74-
.map(WeakReference::get)
75-
.orElse(null);
115+
final Map<String, WeakReference<Logger>> loggerRefByName =
116+
loggerRefByNameByMessageFactory.get(messageFactory);
117+
if (loggerRefByName != null) {
118+
final WeakReference<Logger> loggerRef = loggerRefByName.get(name);
119+
if (loggerRef != null) {
120+
return loggerRef.get();
121+
}
122+
}
123+
return null;
76124
} finally {
77125
readLock.unlock();
78126
}
79127
}
80128

81-
public Stream<Logger> getLoggers() {
129+
public Collection<Logger> getLoggers() {
130+
expungeStaleEntries();
131+
82132
readLock.lock();
83133
try {
134+
// Return a new collection to allow concurrent iteration over the loggers
135+
//
136+
// https://github.com/apache/logging-log4j2/issues/3234
84137
return loggerRefByNameByMessageFactory.values().stream()
85138
.flatMap(loggerRefByName -> loggerRefByName.values().stream())
86139
.flatMap(loggerRef -> {
87140
@Nullable Logger logger = loggerRef.get();
88141
return logger != null ? Stream.of(logger) : Stream.empty();
89-
});
142+
})
143+
.collect(Collectors.toList());
90144
} finally {
91145
readLock.unlock();
92146
}
@@ -115,6 +169,8 @@ public boolean hasLogger(final String name, final MessageFactory messageFactory)
115169
public boolean hasLogger(final String name, final Class<? extends MessageFactory> messageFactoryClass) {
116170
requireNonNull(name, "name");
117171
requireNonNull(messageFactoryClass, "messageFactoryClass");
172+
expungeStaleEntries();
173+
118174
readLock.lock();
119175
try {
120176
return loggerRefByNameByMessageFactory.entrySet().stream()
@@ -134,44 +190,60 @@ public Logger computeIfAbsent(
134190
requireNonNull(name, "name");
135191
requireNonNull(messageFactory, "messageFactory");
136192
requireNonNull(loggerSupplier, "loggerSupplier");
193+
// Skipping `expungeStaleEntries()`, it will be invoked by the `getLogger()` invocation below
137194

138195
// Read lock fast path: See if logger already exists
139196
@Nullable Logger logger = getLogger(name, messageFactory);
140197
if (logger != null) {
141198
return logger;
142199
}
143200

201+
// Intentionally moving the logger creation outside the write lock, because:
202+
//
203+
// - Logger instantiation is expensive (causes contention on the write-lock)
204+
//
205+
// - User code might have circular code paths, though through different threads.
206+
// Consider `T1[ILR:computeIfAbsent] -> ... -> T1[Logger::new] -> ... -> T2[ILR::computeIfAbsent]`.
207+
// Hence, having logger instantiation while holding a write lock might cause deadlocks:
208+
// https://github.com/apache/logging-log4j2/issues/3252
209+
// https://github.com/apache/logging-log4j2/issues/3399
210+
//
211+
// - Creating loggers without a lock, allows multiple threads to create loggers in parallel, which also improves
212+
// performance.
213+
//
214+
// Since all loggers with the same parameters are equivalent, we can safely return the logger from the
215+
// thread that finishes first.
216+
Logger newLogger = loggerSupplier.apply(name, messageFactory);
217+
218+
// Report name and message factory mismatch if there are any
219+
final String loggerName = newLogger.getName();
220+
final MessageFactory loggerMessageFactory = newLogger.getMessageFactory();
221+
if (!loggerName.equals(name) || !loggerMessageFactory.equals(messageFactory)) {
222+
StatusLogger.getLogger()
223+
.error(
224+
"Newly registered logger with name `{}` and message factory `{}`, is requested to be associated with a different name `{}` or message factory `{}`.\n"
225+
+ "Effectively the message factory of the logger will be used and the other one will be ignored.\n"
226+
+ "This generally hints a problem at the logger context implementation.\n"
227+
+ "Please report this using the Log4j project issue tracker.",
228+
loggerName,
229+
loggerMessageFactory,
230+
name,
231+
messageFactory);
232+
}
233+
144234
// Write lock slow path: Insert the logger
145235
writeLock.lock();
146236
try {
147-
148-
// See if the logger is created by another thread in the meantime
149-
final Map<String, WeakReference<Logger>> loggerRefByName =
150-
loggerRefByNameByMessageFactory.computeIfAbsent(messageFactory, ignored -> new HashMap<>());
151-
WeakReference<Logger> loggerRef = loggerRefByName.get(name);
152-
if (loggerRef != null && (logger = loggerRef.get()) != null) {
153-
return logger;
237+
Map<String, WeakReference<Logger>> loggerRefByName = loggerRefByNameByMessageFactory.get(messageFactory);
238+
// noinspection Java8MapApi (avoid the allocation of lambda passed to `Map::computeIfAbsent`)
239+
if (loggerRefByName == null) {
240+
loggerRefByNameByMessageFactory.put(messageFactory, loggerRefByName = new HashMap<>());
154241
}
155242

156-
// Create the logger
157-
logger = loggerSupplier.apply(name, messageFactory);
158-
159-
// Report message factory mismatches, if there is any
160-
final MessageFactory loggerMessageFactory = logger.getMessageFactory();
161-
if (!loggerMessageFactory.equals(messageFactory)) {
162-
StatusLogger.getLogger()
163-
.error(
164-
"Newly registered logger with name `{}` and message factory `{}`, is requested to be associated with a different message factory: `{}`.\n"
165-
+ "Effectively the message factory of the logger will be used and the other one will be ignored.\n"
166-
+ "This generally hints a problem at the logger context implementation.\n"
167-
+ "Please report this using the Log4j project issue tracker.",
168-
name,
169-
loggerMessageFactory,
170-
messageFactory);
243+
final WeakReference<Logger> loggerRef = loggerRefByName.get(name);
244+
if (loggerRef == null || (logger = loggerRef.get()) == null) {
245+
loggerRefByName.put(name, new WeakReference<>(logger = newLogger, staleLoggerRefs));
171246
}
172-
173-
// Insert the logger
174-
loggerRefByName.put(name, new WeakReference<>(logger));
175247
return logger;
176248
} finally {
177249
writeLock.unlock();

0 commit comments

Comments
 (0)