fix: Disable sharing of formatted timestamps between threads (#3802)

This change disables the sharing of formatted timestamps between threads in `InstantPatternThreadLocalCachedFormatter`.

Previously, a mutable `StringBuilder` was shared across threads via a cached object. This could lead to situations where one thread ("owner") was modifying the builder while another thread was reading from it, resulting in inaccurate or truncated timestamps.

This fix ensures that only thread-local instances are used, preventing concurrency issues and improving timestamp correctness under load.

This change is similar in nature to #1485 and fixes #3792.

Author: ppkarwasz

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>