fix: Disable sharing of formatted timestamps between threads

log4j-core-test/src/test/java/org/apache/logging/log4j/core/util/internal/instant/InstantPatternThreadLocalCachedFormatterTest.java

@@ -16,12 +16,14 @@
  */
 package org.apache.logging.log4j.core.util.internal.instant;
 
+import static java.util.concurrent.Executors.newSingleThreadExecutor;
 import static org.assertj.core.api.Assertions.assertThat;
 import static org.assertj.core.api.Assertions.assertThatThrownBy;
 import static org.mockito.ArgumentMatchers.any;
 import static org.mockito.ArgumentMatchers.eq;
 import static org.mockito.Mockito.doAnswer;
 import static org.mockito.Mockito.mock;
+import static org.mockito.Mockito.times;
 import static org.mockito.Mockito.verify;
 import static org.mockito.Mockito.verifyNoMoreInteractions;
 import static org.mockito.Mockito.when;
@@ -30,13 +32,16 @@
 import java.util.Locale;
 import java.util.Random;
 import java.util.TimeZone;
+import java.util.concurrent.ExecutionException;
+import java.util.concurrent.ExecutorService;
 import java.util.function.Function;
 import org.apache.logging.log4j.core.time.Instant;
 import org.apache.logging.log4j.core.time.MutableInstant;
 import org.junit.jupiter.api.Test;
 import org.junit.jupiter.params.ParameterizedTest;
 import org.junit.jupiter.params.provider.MethodSource;
 import org.junit.jupiter.params.provider.ValueSource;
+import org.junitpioneer.jupiter.Issue;
 
 class InstantPatternThreadLocalCachedFormatterTest {
 
@@ -289,4 +294,53 @@ private static MutableInstant createInstant(final long epochMillis, final int ep
         instant.initFromEpochMilli(epochMillis, epochMillisNanos);
         return instant;
     }
+
+    @Test
+    @Issue("https://github.com/apache/logging-log4j2/issues/3792")
+    void should_be_thread_safe() throws Exception {
+        // Instead of randomly testing the thread safety, we test that the current implementation does not
+        // cache results across threads.
+        //
+        // Modify this test if the implementation changes in the future.
+        final InstantPatternFormatter patternFormatter = mock(InstantPatternFormatter.class);
+        when(patternFormatter.getPrecision()).thenReturn(ChronoUnit.MILLIS);
+
+        final Instant instant = INSTANT0;
+        final String output = "thread-output";
+        doAnswer(invocation -> {
+                    StringBuilder buffer = invocation.getArgument(0);
+                    buffer.append(output)
+                            .append('-')
+                            .append(Thread.currentThread().getName());
+                    return null;
+                })
+                .when(patternFormatter)
+                .formatTo(any(StringBuilder.class), eq(instant));
+
+        final InstantFormatter cachedFormatter =
+                InstantPatternThreadLocalCachedFormatter.ofMilliPrecision(patternFormatter);
+
+        final int threadCount = 2;
+        for (int i = 0; i < threadCount; i++) {
+            formatOnNewThread(cachedFormatter, instant, output);
+        }
+        verify(patternFormatter, times(threadCount)).formatTo(any(StringBuilder.class), eq(instant));
+    }
+
+    private static void formatOnNewThread(
+            final InstantFormatter formatter, final Instant instant, final String expectedOutput)
+            throws ExecutionException, InterruptedException {
+        ExecutorService executor = newSingleThreadExecutor();
+        try {
+            executor.submit(() -> {
+                        String formatted = formatter.format(instant);
+                        assertThat(formatted)
+                                .isEqualTo(expectedOutput + "-"
+                                        + Thread.currentThread().getName());
+                    })
+                    .get();
+        } finally {
+            executor.shutdown();
+        }
+    }
 }

log4j-core/src/main/java/org/apache/logging/log4j/core/util/internal/instant/InstantPatternThreadLocalCachedFormatter.java

@@ -38,8 +38,6 @@ final class InstantPatternThreadLocalCachedFormatter implements InstantPatternFo
     private final ThreadLocal<Object[]> epochInstantAndBufferRef =
             ThreadLocal.withInitial(InstantPatternThreadLocalCachedFormatter::createEpochInstantAndBuffer);
 
-    private Object[] lastEpochInstantAndBuffer = createEpochInstantAndBuffer();
-
     private static Object[] createEpochInstantAndBuffer() {
         return new Object[] {-1L, new StringBuilder()};
     }
@@ -89,32 +87,21 @@ public ChronoUnit getPrecision() {
     public void formatTo(final StringBuilder buffer, final Instant instant) {
         requireNonNull(buffer, "buffer");
         requireNonNull(instant, "instant");
-        final Object[] prevEpochInstantAndBuffer = lastEpochInstantAndBuffer;
-        final long prevEpochInstant = (long) prevEpochInstantAndBuffer[0];
-        final StringBuilder prevBuffer = (StringBuilder) prevEpochInstantAndBuffer[1];
+        final Object[] epochInstantAndBuffer = epochInstantAndBufferRef.get();
+        final long prevEpochInstant = (long) epochInstantAndBuffer[0];
+        final StringBuilder localBuffer = (StringBuilder) epochInstantAndBuffer[1];
         final long nextEpochInstant = epochInstantExtractor.apply(instant);
-        if (prevEpochInstant == nextEpochInstant) {
-            buffer.append(prevBuffer);
-        } else {
-
-            // We could have used `StringBuilders.trimToMaxSize()` on `prevBuffer`.
+        if (prevEpochInstant != nextEpochInstant) {
+            // We could have used `StringBuilders.trimToMaxSize()` on `localBuffer`.
             // That is, we wouldn't want exploded `StringBuilder`s in hundreds of `ThreadLocal`s.
             // Though we are formatting instants and always expect to produce strings of more or less the same length.
             // Hence, no need for truncation.
 
-            // Populate a new cache entry
-            final Object[] nextEpochInstantAndBuffer = epochInstantAndBufferRef.get();
-            nextEpochInstantAndBuffer[0] = nextEpochInstant;
-            final StringBuilder nextBuffer = (StringBuilder) nextEpochInstantAndBuffer[1];
-            nextBuffer.setLength(0);
-            formatter.formatTo(nextBuffer, instant);
-
-            // Update the effective cache entry
-            lastEpochInstantAndBuffer = nextEpochInstantAndBuffer;
-
-            // Help out the request
-            buffer.append(nextBuffer);
+            epochInstantAndBuffer[0] = nextEpochInstant;
+            localBuffer.setLength(0);
+            formatter.formatTo(localBuffer, instant);
         }
+        buffer.append(localBuffer);
     }
 
     @Override

src/changelog/.2.x.x/3792_formatted-datetime-sharing.xml

@@ -0,0 +1,13 @@
+<?xml version="1.0" encoding="UTF-8"?>
+<!-- SPDX-License-Identifier: Apache-2.0 -->
+<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="fixed">
+  <issue id="3792" link="https://github.com/apache/logging-log4j2/issues/3792"/>
+  <description format="asciidoc">
+    Fix timestamp formatting concurrency issue, when `log4j2.enabledThreadlocals` is `true`.
+  </description>
+</entry>