Enhance logging in JTLNullEventDelimiterTest

The goal is to catch the reason of the recurrent failure on MacOS.

Author: ppkarwasz

log4j-layout-template-json-test/src/test/java/org/apache/logging/log4j/layout/template/json/JsonTemplateLayoutNullEventDelimiterTest.java

@@ -24,53 +24,87 @@
 import java.net.Socket;
 import java.time.Duration;
 
+import org.apache.commons.codec.binary.Hex;
 import org.apache.logging.log4j.Level;
-import org.apache.logging.log4j.LogManager;
 import org.apache.logging.log4j.Logger;
-import org.assertj.core.api.Assertions;
+import org.apache.logging.log4j.core.LogEvent;
+import org.apache.logging.log4j.core.LoggerContext;
+import org.apache.logging.log4j.core.appender.SocketAppender;
+import org.apache.logging.log4j.core.filter.AbstractFilter;
+import org.apache.logging.log4j.core.test.junit.LoggerContextSource;
+import org.apache.logging.log4j.core.test.junit.Named;
+import org.apache.logging.log4j.status.StatusLogger;
+import org.apache.logging.log4j.test.TestProperties;
+import org.apache.logging.log4j.test.junit.UsingStatusListener;
+import org.apache.logging.log4j.test.junit.UsingTestProperties;
 import org.awaitility.Awaitility;
+import org.awaitility.core.ConditionTimeoutException;
+import org.junit.jupiter.api.AfterAll;
+import org.junit.jupiter.api.BeforeAll;
 import org.junit.jupiter.api.Test;
 
+import static org.assertj.core.api.Assertions.assertThat;
+
+@UsingStatusListener
+@UsingTestProperties
 class JsonTemplateLayoutNullEventDelimiterTest {
 
-    @Test
-    void test() throws Exception {
+    private static Logger LOGGER = StatusLogger.getLogger();
+
+    private static TcpServer server;
 
+    private static TestProperties props;
+
+    @BeforeAll
+    static void setup() throws IOException {
         // Start the TCP server.
-        try (final TcpServer server = new TcpServer(0)) {
-
-            // Set the configuration.
-            System.setProperty(
-                    "serverPort",
-                    String.valueOf(server.getPort()));
-            System.setProperty(
-                    "log4j.configurationFile",
-                    "nullEventDelimitedJsonTemplateLayoutLogging.xml");
-
-            // Produce log events.
-            final Logger logger = LogManager.getLogger(JsonTemplateLayoutNullEventDelimiterTest.class);
-            logger.log(Level.INFO, "foo");
-            logger.log(Level.INFO, "bar");
-
-            // Set the expected bytes.
-            final byte[] expectedBytes = {
-                    '"', 'f', 'o', 'o', '"', '\0',
-                    '"', 'b', 'a', 'r', '"', '\0'
-            };
-
-            // Wait for the log events.
+        server = new TcpServer(0);
+        // Set the configuration.
+        props.setProperty("serverPort", server.getPort());
+    }
+
+    @AfterAll
+    static void cleanup() throws IOException {
+        // Stop the TCP server.
+        server.close();
+    }
+
+    @Test
+    @LoggerContextSource
+    void test(final @Named("Socket") SocketAppender appender, final LoggerContext ctx) throws Exception {
+        assertThat(appender).isNotNull();
+        appender.addFilter(new AbstractFilter() {
+            @Override
+            public Result filter(LogEvent event) {
+                LOGGER.info("Sending message {}", event.getMessage());
+                return super.filter(event);
+            }
+        });
+        // Produce log events.
+        final Logger logger = ctx.getLogger(JsonTemplateLayoutNullEventDelimiterTest.class);
+        logger.log(Level.INFO, "foo");
+        logger.log(Level.INFO, "bar");
+
+        // Set the expected bytes.
+        final byte[] expectedBytes = {
+                '"', 'f', 'o', 'o', '"', '\0',
+                '"', 'b', 'a', 'r', '"', '\0'
+        };
+
+        // Wait for the log events.
+        try {
             Awaitility
                     .await()
                     .atMost(Duration.ofSeconds(10))
                     .pollDelay(Duration.ofSeconds(1))
                     .until(() -> server.getTotalReadByteCount() >= expectedBytes.length);
-
-            // Verify the received log events.
-            final byte[] actualBytes = server.getReceivedBytes();
-            Assertions.assertThat(actualBytes).startsWith(expectedBytes);
-
+        } catch (final ConditionTimeoutException e) {
+            LOGGER.info("Timeout reached while waiting for {} bytes.", expectedBytes.length);
         }
 
+        // Verify the received log events.
+        final byte[] actualBytes = server.getReceivedBytes();
+        assertThat(actualBytes).containsExactly(expectedBytes);
     }
 
     private static final class TcpServer extends Thread implements AutoCloseable {
@@ -90,6 +124,7 @@ private TcpServer(final int port) throws IOException {
             serverSocket.setSoTimeout(5_000);
             setDaemon(true);
             start();
+            LOGGER.info("TcpServer started on port {}.", port);
         }
 
         @Override
@@ -98,21 +133,24 @@ public void run() {
                 try (final Socket socket = serverSocket.accept()) {
                     final InputStream inputStream = socket.getInputStream();
                     final byte[] buffer = new byte[1024];
-                    // noinspection InfiniteLoopStatement
                     while (true) {
                         final int readByteCount = inputStream.read(buffer);
-                        if (readByteCount > 0) {
+                        if (readByteCount != -1) {
+                            LOGGER.info("Received bytes {}.", () -> Hex.encodeHex(buffer, 0, readByteCount, false));
                             synchronized (this) {
                                 totalReadByteCount += readByteCount;
                                 outputStream.write(buffer, 0, readByteCount);
                             }
+                        } else {
+                            break;
                         }
                     }
                 }
             } catch (final EOFException ignored) {
                 // Socket is closed.
             } catch (final Exception error) {
                 if (!closed) {
+                    LOGGER.error("TcpServer received an error.", error);
                     throw new RuntimeException(error);
                 }
             }

log4j-layout-template-json-test/src/test/resources/nullEventDelimitedJsonTemplateLayoutLogging.xml renamed to log4j-layout-template-json-test/src/test/resources/org/apache/logging/log4j/layout/template/json/JsonTemplateLayoutNullEventDelimiterTest.xml

@@ -19,7 +19,7 @@
   <Appenders>
     <Socket name="Socket"
             host="localhost"
-            port="${sys:serverPort}"
+            port="${test:serverPort}"
             protocol="TCP"
             ignoreExceptions="false"
             reconnectionDelay="100"