apache / apache/logging-log4j2
AsyncLogger ignores Thread.setName() changes despite the UNCACHED strategy since 2.25.0
- Dominant language
- Java
- Stars
- 3.6k
- Forks
- 1.7k
- Avg merge
- 21h 30m
- Merged PRs (30d)
- 27
Description
## Description
Hello!
After upgrading Log4j Core from `2.24.3` to `2.25.0`, I noticed a change in how a fully asynchronous logger captures thread names.
My application executes multiple tasks on reused worker threads. Each task temporarily changes the name of the worker thread using `Thread.setName()` so that the currently executing task can be identified in the logs.
With Log4j `2.24.3`, the `%t` pattern reflects the name assigned by each task. With Log4j `2.25.0`, it keeps showing the name assigned by the first task executed on that worker thread.
This happens even when `log4j2.asyncLoggerThreadNameStrategy` is explicitly set to `UNCACHED`.
## Environment
- Operating system: Linux
- JDK: OpenJDK 26
- LMAX Disruptor: `4.0.0`
- Log4j versions compared:
- `2.24.3`
- `2.25.0`
## Reproduction
The example uses a fixed thread pool with exactly one worker. This guarantees that both tasks run on the same reused `Thread` instance while assigning it a different name for each task.
### `AsyncThreadNameExample.java`
```java
import java.util.concurrent.ExecutorService;
import java.util.concurrent.Executors;
import java.util.concurrent.TimeUnit;
import org.apache.logging.log4j.LogManager;
import org.apache.logging.log4j.Logger;
public final class AsyncThreadNameExample {
static {
System.setProperty(
"log4j2.contextSelector",
"org.apache.logging.log4j.core.async.AsyncLoggerContextSelector"
);
System.setProperty(
"log4j2.asyncLoggerThreadNameStrategy",
"UNCACHED"
);
System.setProperty(
"log4j2.enableThreadlocals",
"true"
);
}
public static void main(String[] args) throws InterruptedException {
ExecutorService executorService = Executors.newFixedThreadPool(1);
executorService.submit(new NamedTask("first-job"));
executorService.submit(new NamedTask("second-job"));
executorService.shutdown();
if (!executorService.awaitTermination(10, TimeUnit.SECONDS)) {
throw new IllegalStateException("Executor did not terminate in time");
}
LogManager.shutdown();
}
private static final class NamedTask implements Runnable {
private static final Logger LOGGER = LogManager.getLogger(NamedTask.class);
private final String taskName;
private NamedTask(String taskName) {
this.taskName = taskName;
}
@Override
public void run() {
Thread thread = Thread.currentThread();
String originalThreadName = thread.getName();
try {
thread.setName(taskName);
LOGGER.info("Executing {}", taskName);
} finally {
thread.setName(originalThreadName);
}
}
}
}
```
The system properties are set before the logger in `NamedTask` is initialized.
### `log4j2.xml`
```xml
```
The following JAR files are placed in the current directory:
```text
disruptor-4.0.0.jar
log4j-api-2.24.3.jar
log4j-core-2.24.3.jar
log4j-api-2.25.0.jar
log4j-core-2.25.0.jar
```
### Run with Log4j 2.24.3
```bash
java \
-cp ".:log4j-api-2.24.3.jar:log4j-core-2.24.3.jar:disruptor-4.0.0.jar" \
AsyncThreadNameExample.java
```
Output:
```text
[first-job] Executing first-job
[second-job] Executing second-job
```
### Run with Log4j 2.25.0
```bash
java \
-cp ".:log4j-api-2.25.0.jar:log4j-core-2.25.0.jar:disruptor-4.0.0.jar" \
AsyncThreadNameExample.java
```
Output:
```text
[first-job] Executing first-job
[first-job] Executing second-job
```
## Expected behavior
When `log4j2.asyncLoggerThreadNameStrategy` is set to `UNCACHED`, each log event should capture the current value returned by `Thread.getName()`:
```text
[first-job] Executing first-job
[second-job] Executing second-job
```
## Actual behavior
With Log4j `2.25.0`, the thread-local `RingBufferLogEventTranslator` retains the thread name captured during the first task:
```text
[first-job] Executing first-job
[first-job] Executing second-job
```
## Possible cause
The behavior appears to have changed in commit
[`dc6c53ab7bb195f3878d3ee92cd0ff20634326f1`](https://github.com/apache/logging-log4j2/commit/dc6c53ab7bb195f3878d3ee92cd0ff20634326f1),
merged through [PR #3171](https://github.com/apache/logging-log4j2/pull/3171).
That commit removed the following call from both `AsyncLogger.logWithThreadLocalTranslator(...)` overloads:
```java
initTranslatorThreadValues(translator);
```
It also removed the method that refreshed the thread values when the `UNCACHED` strategy was selected:
```java
private void initTranslatorThreadValues(
final RingBufferLogEventTranslator translator
) {
if (THREAD_NAME_CACHING_STRATEGY == ThreadNameCachingStrategy.UNCACHED) {
translator.updateThreadValues();
}
}
```
The PR discussion explains that a `RingBufferLogEventTranslator` is always used by the same thread that created it.
While the `Thread` instance remains the same in this example, its name changes between tasks through `Thread.setName()`. Therefore, retaining the values captured when the translator was created produces a stale thread name.
The current documentation for
[`log4j2.asyncLoggerThreadNameStrategy`](https://logging.apache.org/log4j/2.x/manual/systemproperties.html#log4j2.asyncLoggerThreadNameStrategy)
states that `UNCACHED` disables caching of the result of `Thread.getName()`.
## Questions
Is the behavior introduced in Log4j `2.25.0` intentional?
If changes made through `Thread.setName()` are no longer expected to be reflected by fully asynchronous loggers, should the `UNCACHED` strategy and its documentation be updated accordingly?
Otherwise, could this be considered a regression in the thread-local translator path?
Contributor guide
No contributing guide indexed for this repository
Research direction
Start with AsyncLogger.logWithThreadLocalTranslator(...) and RingBufferLogEventTranslator.updateThreadValues(), then compare the change from commit dc6c53ab7bb195f3878d3ee92cd0ff20634326f1. Run the provided AsyncThreadNameExample.java reproduction with Log4j 2.25.0. Done means determining whether UNCACHED must reflect both task-specific Thread.setName() values and updating the behavior or documentation accordingly.
Written by the indexing model from the issue text.
Assessment
- Tech stack
- java
- Domain
- observability-sre
- Issue type
- Bug
- Difficulty
- 3/5
- Estimated time
- 1-2 days
- Activity status
- Active
- Clarity
- Mostly clear
- Newbie friendliness
- 55/100