Merge pull request #78 from tkowalcz/label-adapter-race-condition

Label adapter race condition

core/src/main/java/pl/tkowalcz/tjahzi/LogBufferTranscoder.java

@@ -4,8 +4,8 @@ import io.netty.buffer.ByteBuf;
 import io.netty.buffer.Unpooled;
 import org.agrona.DirectBuffer;
 import org.agrona.concurrent.AtomicBuffer;
-import pl.tkowalcz.tjahzi.http.TextBuilders;
 import pl.tkowalcz.tjahzi.utils.TextBuilder;
+import pl.tkowalcz.tjahzi.utils.TextBuilders;
 
 import java.nio.ByteBuffer;
 import java.util.Map;

core/src/main/java/pl/tkowalcz/tjahzi/utils/TextBuilders.java

@@ -1,6 +1,4 @@
-package pl.tkowalcz.tjahzi.http;
-
-import pl.tkowalcz.tjahzi.utils.TextBuilder;
+package pl.tkowalcz.tjahzi.utils;
 
 public class TextBuilders {
 

core/src/test/java/pl/tkowalcz/tjahzi/utils/TextBuildersTest.java

@@ -0,0 +1,55 @@
+package pl.tkowalcz.tjahzi.utils;
+
+import org.junit.jupiter.api.Test;
+
+import java.util.concurrent.atomic.AtomicReference;
+
+import static org.assertj.core.api.Assertions.assertThat;
+
+class TextBuildersTest {
+
+    @Test
+    void shouldClearBufferBeforeUse() {
+        // Given
+        TextBuilder textBuilder = TextBuilders.threadLocal();
+        textBuilder.append("abc");
+
+        // When
+        TextBuilder actual = TextBuilders.threadLocal();
+
+        // Then
+        assertThat(actual.toString()).isEmpty();
+    }
+
+    @Test
+    void shouldReturnSameBufferInsideSameThread() {
+        // When
+        TextBuilder textBuilder1 = TextBuilders.threadLocal();
+        TextBuilder textBuilder2 = TextBuilders.threadLocal();
+
+        // Then
+        assertThat(textBuilder1).isSameAs(textBuilder2);
+    }
+
+    @Test
+    void shouldReturnDifferentBufferInsideDifferentThreads() throws InterruptedException {
+        // Given
+        AtomicReference<TextBuilder> captor1 = new AtomicReference<>();
+        AtomicReference<TextBuilder> captor2 = new AtomicReference<>();
+
+        // When
+        Thread thread1 = new Thread(() -> captor1.set(TextBuilders.threadLocal()));
+        thread1.start();
+        thread1.join();
+
+        Thread thread2 = new Thread(() -> captor2.set(TextBuilders.threadLocal()));
+        thread2.start();
+        thread2.join();
+
+        // Then
+        assertThat(captor1.get()).isNotNull();
+        assertThat(captor2.get()).isNotNull();
+
+        assertThat(captor1.get()).isNotSameAs(captor2.get());
+    }
+}

log4j2-appender/src/main/java/pl/tkowalcz/tjahzi/log4j2/labels/Log4jAdapterLabelPrinter.java

@@ -4,6 +4,7 @@ import org.apache.logging.log4j.core.LogEvent;
 import org.apache.logging.log4j.core.pattern.LiteralPatternConverter;
 import org.apache.logging.log4j.core.pattern.LogEventPatternConverter;
 import org.apache.logging.log4j.core.pattern.PatternFormatter;
+import pl.tkowalcz.tjahzi.log4j2.utils.StringBuilders;
 
 import java.util.List;
 import java.util.function.Consumer;
@@ -11,7 +12,6 @@ import java.util.function.Consumer;
 @SuppressWarnings("ForLoopReplaceableByForEach")
 public class Log4jAdapterLabelPrinter implements LabelPrinter {
 
-    private final StringBuilder outputBuffer = new StringBuilder();
     private final List<PatternFormatter> formatters;
 
     public Log4jAdapterLabelPrinter(List<PatternFormatter> formatters) {
@@ -20,7 +20,7 @@ public class Log4jAdapterLabelPrinter implements LabelPrinter {
 
     @Override
     public void append(LogEvent event, Consumer<CharSequence> appendable) {
-        outputBuffer.setLength(0);
+        StringBuilder outputBuffer = StringBuilders.threadLocal();
 
         for (int i = 0; i < formatters.size(); i++) {
             formatters.get(i).format(event, outputBuffer);

log4j2-appender/src/main/java/pl/tkowalcz/tjahzi/log4j2/utils/StringBuilders.java

@@ -0,0 +1,13 @@
+package pl.tkowalcz.tjahzi.log4j2.utils;
+
+public class StringBuilders {
+
+    private static final ThreadLocal<StringBuilder> THREAD_LOCAL = ThreadLocal.withInitial(StringBuilder::new);
+
+    public static StringBuilder threadLocal() {
+        StringBuilder result = THREAD_LOCAL.get();
+        result.setLength(0);
+
+        return result;
+    }
+}

log4j2-appender/src/test/java/pl/tkowalcz/tjahzi/log4j2/LokiAppenderLargeBatchesTest.java

@@ -6,7 +6,6 @@ import org.hamcrest.BaseMatcher;
 import org.hamcrest.Description;
 import org.junit.jupiter.api.Test;
 import pl.tkowalcz.tjahzi.log4j2.infra.IntegrationTest;
-import pl.tkowalcz.tjahzi.log4j2.infra.LokiAssert;
 
 import java.util.List;
 import java.util.concurrent.TimeUnit;
@@ -33,7 +32,7 @@ class LokiAppenderLargeBatchesTest extends IntegrationTest {
                 "Tootsie roll carrot cake pastry jujubes jelly beans chupa chups. " +
                 "Souffle cake muffin liquorice tart souffle pie sesame snaps.";
 
-        long expectedTimestamp = System.currentTimeMillis();
+        long expectedTimestamp = TimeUnit.MILLISECONDS.toNanos(System.currentTimeMillis());
 
         // When
         for (int i = 0; i < 1000; i++) {

log4j2-appender/src/test/java/pl/tkowalcz/tjahzi/log4j2/MdcLogLabelConfigurationTest.java

@@ -0,0 +1,39 @@
+package pl.tkowalcz.tjahzi.log4j2;
+
+import org.apache.logging.log4j.LogManager;
+import org.apache.logging.log4j.Logger;
+import org.apache.logging.log4j.ThreadContext;
+import org.junit.jupiter.api.Test;
+import pl.tkowalcz.tjahzi.log4j2.infra.IntegrationTest;
+
+import java.util.UUID;
+
+import static org.hamcrest.CoreMatchers.equalTo;
+import static org.hamcrest.Matchers.greaterThanOrEqualTo;
+import static pl.tkowalcz.tjahzi.log4j2.infra.LokiAssert.assertThat;
+
+class MdcLogLabelConfigurationTest extends IntegrationTest {
+
+    @Test
+    void shouldSendMdcLogLabelAsConfigured() {
+        // Given
+        loadConfig("appender-test-with-md-log-label-set.xml");
+        Logger logger = LogManager.getLogger(MdcLogLabelConfigurationTest.class);
+
+        // When
+        String tid = UUID.randomUUID().toString();
+        ThreadContext.put("tid", tid);
+
+        logger.info("Test");
+
+        // Then
+        assertThat(loki)
+                .returns(response -> response
+                        .body("data.result.size()", greaterThanOrEqualTo(1))
+                        .body("data.result[0].stream.server", equalTo("127.0.0.1"))
+                        .body("data.result[0].stream.tid1", equalTo(tid))
+                        .body("data.result[0].stream.tid2", equalTo(tid))
+                        .body("data.result[0].stream.tid3", equalTo(tid))
+                );
+    }
+}

log4j2-appender/src/test/java/pl/tkowalcz/tjahzi/log4j2/infra/IntegrationTest.java

@@ -12,6 +12,7 @@ import org.testcontainers.junit.jupiter.Testcontainers;
 
 import java.net.URI;
 import java.net.URISyntaxException;
+import java.net.URL;
 
 @Testcontainers
 public class IntegrationTest {
@@ -37,9 +38,15 @@ public class IntegrationTest {
 
     public static LoggerContext loadConfig(String fileName) {
         try {
-            URI uri = IntegrationTest.class
+            URL resource = IntegrationTest.class
                     .getClassLoader()
-                    .getResource(fileName)
+                    .getResource(fileName);
+
+            if (resource == null) {
+                Assertions.fail("Resource " + fileName + " not found");
+            }
+
+            URI uri = resource
                     .toURI();
 
             return loadConfig(uri);

log4j2-appender/src/test/java/pl/tkowalcz/tjahzi/log4j2/utils/StringBuildersTest.java

@@ -0,0 +1,55 @@
+package pl.tkowalcz.tjahzi.log4j2.utils;
+
+import org.junit.jupiter.api.Test;
+
+import java.util.concurrent.atomic.AtomicReference;
+
+import static org.assertj.core.api.Assertions.assertThat;
+
+class StringBuildersTest {
+
+    @Test
+    void shouldClearBufferBeforeUse() {
+        // Given
+        StringBuilder stringBuilder = StringBuilders.threadLocal();
+        stringBuilder.append("abc");
+
+        // When
+        StringBuilder actual = StringBuilders.threadLocal();
+
+        // Then
+        assertThat(actual.toString()).isEmpty();
+    }
+
+    @Test
+    void shouldReturnSameBufferInsideSameThread() {
+        // When
+        StringBuilder stringBuilder1 = StringBuilders.threadLocal();
+        StringBuilder stringBuilder2 = StringBuilders.threadLocal();
+
+        // Then
+        assertThat(stringBuilder1).isSameAs(stringBuilder2);
+    }
+
+    @Test
+    void shouldReturnDifferentBufferInsideDifferentThreads() throws InterruptedException {
+        // Given
+        AtomicReference<StringBuilder> captor1 = new AtomicReference<>();
+        AtomicReference<StringBuilder> captor2 = new AtomicReference<>();
+
+        // When
+        Thread thread1 = new Thread(() -> captor1.set(StringBuilders.threadLocal()));
+        thread1.start();
+        thread1.join();
+
+        Thread thread2 = new Thread(() -> captor2.set(StringBuilders.threadLocal()));
+        thread2.start();
+        thread2.join();
+
+        // Then
+        assertThat(captor1.get()).isNotNull();
+        assertThat(captor2.get()).isNotNull();
+
+        assertThat(captor1.get()).isNotSameAs(captor2.get());
+    }
+}

log4j2-appender/src/test/resources/appender-test-with-md-log-label-set.xml

@@ -0,0 +1,30 @@
+<?xml version="1.0" encoding="UTF-8"?>
+<configuration packages="pl.tkowalcz.tjahzi.log4j2">
+    <Loggers>
+        <Root level="OFF">
+        </Root>
+
+        <Logger name="pl.tkowalcz" level="ALL">
+            <AppenderRef ref="Loki"/>
+        </Logger>
+    </Loggers>
+
+    <appenders>
+        <Loki name="Loki">
+            <host>${sys:loki.host}</host>
+            <port>${sys:loki.port}</port>
+
+            <ThresholdFilter level="ALL"/>
+            <PatternLayout>
+                <Pattern>%X{tid} [%t] %d{MM-dd HH:mm:ss.SSS} %5p %c{1} - %m%n%exception{full}</Pattern>
+            </PatternLayout>
+
+            <Header name="server" value="127.0.0.1"/>
+            <Label name="server" value="127.0.0.1"/>
+
+            <Label name="tid1" pattern="%X{tid}"/>
+            <Label name="tid2" value="${ctx:tid}"/>
+            <Label name="tid3" pattern="%mdc{tid}"/>
+        </Loki>
+    </appenders>
+</configuration>

logback-appender/src/test/java/pl/tkowalcz/tjahzi/logback/LokiAppenderLargeBatchesTest.java

@@ -32,7 +32,7 @@ class LokiAppenderLargeBatchesTest extends IntegrationTest {
                 "Tootsie roll carrot cake pastry jujubes jelly beans chupa chups. " +
                 "Souffle cake muffin liquorice tart souffle pie sesame snaps.";
 
-        long expectedTimestamp = System.currentTimeMillis();
+        long expectedTimestamp = TimeUnit.MILLISECONDS.toNanos(System.currentTimeMillis());
 
         // When
         for (int i = 0; i < 1000; i++) {