AndrewBystrov opened a new issue, #4275:
URL: https://github.com/apache/logging-log4j2/issues/4275
## 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
<?xml version="1.0" encoding="UTF-8"?>
<Configuration status="WARN">
<Appenders>
<Console name="Console">
<PatternLayout pattern="[%t] %m%n"/>
</Console>
</Appenders>
<Loggers>
<Root level="INFO">
<AppenderRef ref="Console"/>
</Root>
</Loggers>
</Configuration>
```
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?
--
This is an automated message from the Apache Git Service.
To respond to the message, please log on to GitHub and use the
URL above to go to the specific comment.
To unsubscribe, e-mail: [email protected]
For queries about this service, please contact Infrastructure at:
[email protected]
