diff --git a/log4j-core-test/src/main/java/org/apache/logging/log4j/core/test/appender/ListAppender.java b/log4j-core-test/src/main/java/org/apache/logging/log4j/core/test/appender/ListAppender.java index f941db12674..7d3aa438693 100644 --- a/log4j-core-test/src/main/java/org/apache/logging/log4j/core/test/appender/ListAppender.java +++ b/log4j-core-test/src/main/java/org/apache/logging/log4j/core/test/appender/ListAppender.java @@ -40,24 +40,24 @@ /** * This appender is primarily used for testing. Use in a real environment is discouraged as the - * List could eventually grow to cause an OutOfMemoryError. + * lists could eventually grow to cause an {@link OutOfMemoryError}. * - * This appender is not thread-safe. + *

This appender is thread-safe: all public methods are {@code synchronized} on {@code this}. + * Callers waiting for a minimum number of messages can use + * {@link #getMessages(int, long, TimeUnit)} which releases the monitor while waiting.

* - * This appender will use {@link Layout#toByteArray(LogEvent)}. + *

This appender will use {@link Layout#toByteArray(LogEvent)}.

* * @see org.apache.logging.log4j.core.test.junit.LoggerContextRule#getListAppender(String) ILC.getListAppender */ @Plugin(name = "List", category = Core.CATEGORY_NAME, elementType = Appender.ELEMENT_TYPE, printObject = true) public class ListAppender extends AbstractAppender { - // Use Collections.synchronizedList rather than CopyOnWriteArrayList because we expect - // more frequent writes than reads. - final List events = Collections.synchronizedList(new ArrayList()); + final List events = new ArrayList<>(); - private final List messages = Collections.synchronizedList(new ArrayList()); + private final List messages = new ArrayList<>(); - final List data = Collections.synchronizedList(new ArrayList()); + final List data = new ArrayList<>(); private final boolean newLine; @@ -66,30 +66,20 @@ public class ListAppender extends AbstractAppender { private static final String WINDOWS_LINE_SEP = "\r\n"; /** - * CountDownLatch for asynchronous logging tests. Example usage: - *
-     * @Rule
-     * public LoggerContextRule context = new LoggerContextRule("log4j-list.xml");
-     * private ListAppender listAppender;
+     * A {@link CountDownLatch} that is decremented once for every call to {@link #append(LogEvent)}.
      *
-     * @Before
-     * public void before() throws Exception {
-     *     listAppender = context.getListAppender("List");
-     * }
+     * 

Callers may assign a new latch before submitting a known number of log events, + * then await that latch to block until all events have been processed. Example:

+ *
{@code
+     * listAppender.countDownLatch = new CountDownLatch(1);
      *
-     * @Test
-     * public void testSomething() throws Exception {
-     *     listAppender.countDownLatch = new CountDownLatch(1);
+     * logger.info("log one event asynchronously");
      *
-     *     Logger logger = LogManager.getLogger();
-     *     logger.info("log one event asynchronously");
+     * // wait for the appender to finish processing this event (wait max 1 second)
+     * listAppender.countDownLatch.await(1, TimeUnit.SECONDS);
      *
-     *     // wait for the appender to finish processing this event (wait max 1 second)
-     *     listAppender.countDownLatch.await(1, TimeUnit.SECONDS);
-     *
-     *     // now assert something or do follow-up tests...
-     * }
-     * 
+ * // now assert something or do follow-up tests... + * }
*/ public volatile CountDownLatch countDownLatch = null; @@ -117,7 +107,7 @@ public ListAppender( } @Override - public void append(final LogEvent event) { + public synchronized void append(final LogEvent event) { final Layout layout = getLayout(); if (layout == null) { events.add(event.toImmutable()); @@ -131,12 +121,13 @@ public void append(final LogEvent event) { } else { write(layout.toByteArray(event)); } - if (countDownLatch != null) { - countDownLatch.countDown(); + final CountDownLatch latch = countDownLatch; + if (latch != null) { + latch.countDown(); } } - void write(final byte[] bytes) { + synchronized void write(final byte[] bytes) { if (raw) { data.add(bytes); return; @@ -174,7 +165,7 @@ void write(final byte[] bytes) { } @Override - public boolean stop(final long timeout, final TimeUnit timeUnit) { + public synchronized boolean stop(final long timeout, final TimeUnit timeUnit) { setStopping(); super.stop(timeout, timeUnit, false); final Layout layout = getLayout(); @@ -188,7 +179,7 @@ public boolean stop(final long timeout, final TimeUnit timeUnit) { return true; } - public ListAppender clear() { + public synchronized ListAppender clear() { events.clear(); messages.clear(); data.clear(); @@ -196,13 +187,13 @@ public ListAppender clear() { } /** Returns an immutable snapshot of captured log events */ - public List getEvents() { - return Collections.unmodifiableList(new ArrayList<>(events)); + public synchronized List getEvents() { + return Collections.unmodifiableList(new ArrayList<>(events)); } /** Returns an immutable snapshot of captured messages */ - public List getMessages() { - return Collections.unmodifiableList(new ArrayList<>(messages)); + public synchronized List getMessages() { + return Collections.unmodifiableList(new ArrayList<>(messages)); } /** @@ -211,13 +202,17 @@ public List getMessages() { */ public List getMessages(final int minSize, final long timeout, final TimeUnit timeUnit) throws InterruptedException { - Awaitility.waitAtMost(timeout, timeUnit).until(() -> messages.size() >= minSize); + Awaitility.waitAtMost(timeout, timeUnit).until(() -> { + synchronized (this) { + return messages.size() >= minSize; + } + }); return getMessages(); } /** Returns an immutable snapshot of captured data */ - public List getData() { - return Collections.unmodifiableList(new ArrayList<>(data)); + public synchronized List getData() { + return Collections.unmodifiableList(new ArrayList<>(data)); } public static ListAppender createAppender( diff --git a/log4j-core-test/src/test/java/org/apache/logging/log4j/core/test/appender/ListAppenderTest.java b/log4j-core-test/src/test/java/org/apache/logging/log4j/core/test/appender/ListAppenderTest.java new file mode 100644 index 00000000000..ac6fd5bc7aa --- /dev/null +++ b/log4j-core-test/src/test/java/org/apache/logging/log4j/core/test/appender/ListAppenderTest.java @@ -0,0 +1,224 @@ +/* + * 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.appender; + +import static org.assertj.core.api.Assertions.assertThat; + +import java.util.ArrayList; +import java.util.List; +import java.util.concurrent.CountDownLatch; +import java.util.concurrent.ExecutorService; +import java.util.concurrent.Executors; +import java.util.concurrent.TimeUnit; +import org.apache.logging.log4j.Level; +import org.apache.logging.log4j.core.LogEvent; +import org.apache.logging.log4j.core.impl.Log4jLogEvent; +import org.apache.logging.log4j.core.layout.PatternLayout; +import org.apache.logging.log4j.message.SimpleMessage; +import org.junit.jupiter.api.RepeatedTest; +import org.junit.jupiter.api.Test; + +/** + * Tests for {@link ListAppender}. + */ +class ListAppenderTest { + + private static LogEvent createEvent(final int workerId, final int index) { + return Log4jLogEvent.newBuilder() + .setLoggerName("worker-" + workerId) + .setLevel(Level.INFO) + .setMessage(new SimpleMessage("event-" + workerId + "-" + index)) + .build(); + } + + private static List expectedMessages(final int workerCount, final int eventsPerWorker) { + final List expected = new ArrayList<>(workerCount * eventsPerWorker); + for (int workerId = 0; workerId < workerCount; workerId++) { + for (int i = 0; i < eventsPerWorker; i++) { + expected.add("event-" + workerId + "-" + i); + } + } + return expected; + } + + private static List expectedEventKeys(final int workerCount, final int eventsPerWorker) { + final List expected = new ArrayList<>(workerCount * eventsPerWorker); + for (int workerId = 0; workerId < workerCount; workerId++) { + for (int i = 0; i < eventsPerWorker; i++) { + expected.add("worker-" + workerId + ":event-" + workerId + "-" + i); + } + } + return expected; + } + + @Test + void appendWithoutLayoutStoresEvents() { + final ListAppender appender = new ListAppender("test"); + appender.start(); + + appender.append(createEvent(0, 0)); + appender.append(createEvent(0, 1)); + + assertThat(appender.getEvents()).hasSize(2); + assertThat(appender.getMessages()).isEmpty(); + } + + @Test + void appendWithLayoutStoresMessages() { + final PatternLayout layout = PatternLayout.newBuilder().setPattern("%m").build(); + final ListAppender appender = new ListAppender("test", null, layout, false, false); + appender.start(); + + appender.append(createEvent(0, 0)); + appender.append(createEvent(0, 1)); + + assertThat(appender.getMessages()).hasSize(2); + assertThat(appender.getEvents()).isEmpty(); + } + + @Test + void clearResetsAllCollections() { + final ListAppender appender = new ListAppender("test"); + appender.start(); + + appender.append(createEvent(0, 0)); + assertThat(appender.getEvents()).hasSize(1); + + appender.clear(); + + assertThat(appender.getEvents()).isEmpty(); + assertThat(appender.getMessages()).isEmpty(); + assertThat(appender.getData()).isEmpty(); + } + + @Test + void getMessagesWithTimeoutReturnsOnceMinSizeReached() throws InterruptedException { + final PatternLayout layout = PatternLayout.newBuilder().setPattern("%m").build(); + final ListAppender appender = new ListAppender("test", null, layout, false, false); + appender.start(); + + // Append in a background thread, after a short delay + final Thread producer = new Thread(() -> { + try { + Thread.sleep(50); + } catch (final InterruptedException e) { + Thread.currentThread().interrupt(); + } + appender.append(createEvent(0, 0)); + }); + producer.start(); + + final List messages = appender.getMessages(1, 5, TimeUnit.SECONDS); + producer.join(); + + assertThat(messages).hasSize(1); + } + + /** + * Hammers {@link ListAppender#append(LogEvent)} concurrently using 10 workers each appending 1,000 deterministic + * events, then verifies that {@link ListAppender#getEvents()} is consistent (no events were lost or duplicated). + */ + @RepeatedTest(10) + void appendIsThreadSafeWithoutLayout() throws InterruptedException { + final int workerCount = 10; + final int eventsPerWorker = 1_000; + final List expectedEventKeys = expectedEventKeys(workerCount, eventsPerWorker); + + final ListAppender appender = new ListAppender("thread-safe-test"); + appender.start(); + + final ExecutorService executor = Executors.newFixedThreadPool(workerCount); + final CountDownLatch startGate = new CountDownLatch(1); + + for (int w = 0; w < workerCount; w++) { + final int workerId = w; + executor.submit(() -> { + try { + startGate.await(); + for (int i = 0; i < eventsPerWorker; i++) { + appender.append(createEvent(workerId, i)); + } + } catch (final InterruptedException e) { + Thread.currentThread().interrupt(); + } + }); + } + + startGate.countDown(); + executor.shutdown(); + assertThat(executor.awaitTermination(30, TimeUnit.SECONDS)) + .as("all workers completed within timeout") + .isTrue(); + + assertThat(appender.getEvents()) + .as("all events were captured without loss or duplication") + .hasSize(workerCount * eventsPerWorker); + + assertThat(appender.getEvents()) + .extracting(event -> + event.getLoggerName() + ":" + event.getMessage().getFormattedMessage()) + .as("all expected worker/message combinations are present exactly once") + .containsExactlyInAnyOrderElementsOf(expectedEventKeys); + } + + /** + * Hammers {@link ListAppender#append(LogEvent)} concurrently using 10 workers each appending 1,000 deterministic + * events with a layout, then verifies that {@link ListAppender#getMessages()} is consistent + * (no messages were lost or duplicated). + */ + @RepeatedTest(10) + void appendIsThreadSafeWithLayout() throws InterruptedException { + final int workerCount = 10; + final int eventsPerWorker = 1_000; + final List expectedMessages = expectedMessages(workerCount, eventsPerWorker); + + final PatternLayout layout = PatternLayout.newBuilder().setPattern("%m").build(); + final ListAppender appender = new ListAppender("thread-safe-layout-test", null, layout, false, false); + appender.start(); + + final ExecutorService executor = Executors.newFixedThreadPool(workerCount); + final CountDownLatch startGate = new CountDownLatch(1); + + for (int w = 0; w < workerCount; w++) { + final int workerId = w; + executor.submit(() -> { + try { + startGate.await(); + for (int i = 0; i < eventsPerWorker; i++) { + appender.append(createEvent(workerId, i)); + } + } catch (final InterruptedException e) { + Thread.currentThread().interrupt(); + } + }); + } + + startGate.countDown(); + executor.shutdown(); + assertThat(executor.awaitTermination(30, TimeUnit.SECONDS)) + .as("all workers completed within timeout") + .isTrue(); + + assertThat(appender.getMessages()) + .as("all messages were captured without loss or duplication") + .hasSize(workerCount * eventsPerWorker); + + assertThat(appender.getMessages()) + .as("all expected messages are present exactly once") + .containsExactlyInAnyOrderElementsOf(expectedMessages); + } +} diff --git a/src/changelog/.2.x.x/3926_revamp_list_appender.xml b/src/changelog/.2.x.x/3926_revamp_list_appender.xml new file mode 100644 index 00000000000..e66a5fdfadf --- /dev/null +++ b/src/changelog/.2.x.x/3926_revamp_list_appender.xml @@ -0,0 +1,13 @@ + + + + + + Revamp `ListAppender` for thread-safety and clarity. + +