This is an automated email from the ASF dual-hosted git repository.
pkarwasz pushed a commit to branch 2.x
in repository https://gitbox.apache.org/repos/asf/logging-log4j2.git
The following commit(s) were added to refs/heads/2.x by this push:
new 6cd74a88ba fix: Disable sharing of formatted timestamps between
threads (#3802)
6cd74a88ba is described below
commit 6cd74a88bace5e63fd605256a0dee38cb07ddc8e
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>
