This is an automated email from the ASF dual-hosted git repository. pkarwasz pushed a commit to branch 2.25.x in repository https://gitbox.apache.org/repos/asf/logging-log4j2.git
commit 6e2cdeb81a145762fe76bb1a9f432d4a37aa53b5 Author: Piotr P. Karwasz <[email protected]> AuthorDate: Fri Jul 4 14:29:06 2025 +0200 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. --- ...stantPatternThreadLocalCachedFormatterTest.java | 54 ++++++++++++++++++++++ .../InstantPatternThreadLocalCachedFormatter.java | 31 ++++--------- .../.2.x.x/3792_formatted-datetime-sharing.xml | 13 ++++++ 3 files changed, 76 insertions(+), 22 deletions(-) diff --git a/log4j-core-test/src/test/java/org/apache/logging/log4j/core/util/internal/instant/InstantPatternThreadLocalCachedFormatterTest.java b/log4j-core-test/src/test/java/org/apache/logging/log4j/core/util/internal/instant/InstantPatternThreadLocalCachedFormatterTest.java index 1f94b0b9ae..f4435c0086 100644 --- a/log4j-core-test/src/test/java/org/apache/logging/log4j/core/util/internal/instant/InstantPatternThreadLocalCachedFormatterTest.java +++ b/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,6 +32,8 @@ import java.time.temporal.ChronoUnit; 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; @@ -37,6 +41,7 @@ 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 @@ class InstantPatternThreadLocalCachedFormatterTest { 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(); + } + } } diff --git a/log4j-core/src/main/java/org/apache/logging/log4j/core/util/internal/instant/InstantPatternThreadLocalCachedFormatter.java b/log4j-core/src/main/java/org/apache/logging/log4j/core/util/internal/instant/InstantPatternThreadLocalCachedFormatter.java index 96bf4504aa..c5179382ff 100644 --- a/log4j-core/src/main/java/org/apache/logging/log4j/core/util/internal/instant/InstantPatternThreadLocalCachedFormatter.java +++ b/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 @@ final class InstantPatternThreadLocalCachedFormatter implements InstantPatternFo 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 diff --git a/src/changelog/.2.x.x/3792_formatted-datetime-sharing.xml b/src/changelog/.2.x.x/3792_formatted-datetime-sharing.xml new file mode 100644 index 0000000000..ad52ea9538 --- /dev/null +++ b/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>
