Revamped ListAppender for thread-safety

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.
+ * <p>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.</p>
  *
- * This appender will use {@link Layout#toByteArray(LogEvent)}.
+ * <p>This appender will use {@link Layout#toByteArray(LogEvent)}.</p>
  *
  * @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<LogEvent> events = Collections.<LogEvent>synchronizedList(new ArrayList<LogEvent>());
+    final List<LogEvent> events = new ArrayList<>();
 
-    private final List<String> messages = Collections.<String>synchronizedList(new ArrayList<String>());
+    private final List<String> messages = new ArrayList<>();
 
-    final List<byte[]> data = Collections.<byte[]>synchronizedList(new ArrayList<byte[]>());
+    final List<byte[]> 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:
-     * <pre>
-     * @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");
-     * }
+     * <p>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:</p>
+     * <pre>{@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...
-     * }
-     * </pre>
+     * // now assert something or do follow-up tests...
+     * }</pre>
      */
     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<? extends Serializable> layout = getLayout();
         if (layout == null) {
             events.add(event.toImmutable());
@@ -131,12 +121,14 @@ public void append(final LogEvent event) {
         } else {
             write(layout.toByteArray(event));
         }
-        if (countDownLatch != null) {
-            countDownLatch.countDown();
+        notifyAll();
+        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 +166,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<? extends Serializable> layout = getLayout();
@@ -188,21 +180,21 @@ public boolean stop(final long timeout, final TimeUnit timeUnit) {
         return true;
     }
 
-    public ListAppender clear() {
+    public synchronized ListAppender clear() {
         events.clear();
         messages.clear();
         data.clear();
         return this;
     }
 
     /** Returns an immutable snapshot of captured log events */
-    public List<LogEvent> getEvents() {
-        return Collections.<LogEvent>unmodifiableList(new ArrayList<>(events));
+    public synchronized List<LogEvent> getEvents() {
+        return Collections.unmodifiableList(new ArrayList<>(events));
     }
 
     /** Returns an immutable snapshot of captured messages */
-    public List<String> getMessages() {
-        return Collections.<String>unmodifiableList(new ArrayList<>(messages));
+    public synchronized List<String> getMessages() {
+        return Collections.unmodifiableList(new ArrayList<>(messages));
     }
 
     /**
@@ -211,13 +203,17 @@ public List<String> getMessages() {
      */
     public List<String> 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<byte[]> getData() {
-        return Collections.<byte[]>unmodifiableList(new ArrayList<>(data));
+    public synchronized List<byte[]> getData() {
+        return Collections.unmodifiableList(new ArrayList<>(data));
     }
 
     public static ListAppender createAppender(

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<String> expectedMessages(final int workerCount, final int eventsPerWorker) {
+        final List<String> 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<String> expectedEventKeys(final int workerCount, final int eventsPerWorker) {
+        final List<String> 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<String> 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<String> 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<String> 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);
+    }
+}

src/changelog/.2.x.x/3926_revamp_list_appender.xml

@@ -0,0 +1,16 @@
+<?xml version="1.0" encoding="UTF-8"?>
+<entry xmlns="https://logging.apache.org/xml/ns"
+       xmlns:xsi="http://www.w3.org/2001/XMLSchema-instance"
+       xsi:schemaLocation="
+           https://logging.apache.org/xml/ns
+           https://logging.apache.org/xml/ns/log4j-changelog-0.xsd"
+       type="changed">
+    <issue id="3926" link="https://github.com/apache/logging-log4j2/pull/3926"/>
+    <description format="asciidoc">
+      Revamped `ListAppender` for thread-safety and clarity:
+      removed `Collections.synchronizedList` wrappers and replaced with `synchronized` on all public methods,
+      replaced `Awaitility` polling in `getMessages(int, long, TimeUnit)` with `Object#wait` / `notifyAll`,
+      improved class and `countDownLatch` Javadoc,
+      and added unit and concurrency tests.
+    </description>
+</entry>