AsyncLogger ignores Thread.setName() changes despite the UNCACHED strategy since 2.25.0

[AndrewBystrov]

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

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 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:

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

java \
  -cp ".:log4j-api-2.24.3.jar:log4j-core-2.24.3.jar:disruptor-4.0.0.jar" \
  AsyncThreadNameExample.java

Output:

[first-job] Executing first-job
[second-job] Executing second-job

Run with Log4j 2.25.0

java \
  -cp ".:log4j-api-2.25.0.jar:log4j-core-2.25.0.jar:disruptor-4.0.0.jar" \
  AsyncThreadNameExample.java

Output:

[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():

[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:

[first-job] Executing first-job
[first-job] Executing second-job

Possible cause

The behavior appears to have changed in commit
dc6c53ab7bb195f3878d3ee92cd0ff20634326f1,
merged through PR #3171.

That commit removed the following call from both AsyncLogger.logWithThreadLocalTranslator(...) overloads:

initTranslatorThreadValues(translator);

It also removed the method that refreshed the thread values when the UNCACHED strategy was selected:

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
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?

[ramanathan1504]

Confirmed, and as per me is not intentional. it slipped out i think, a PR about something else.

@ppkarwasz can you look this? if you confirm i will try to close this with fixes or @AndrewBystrov if You interested to contribute. I am ready to review and approve.

[AndrewBystrov]

Confirmed, and as per me is not intentional. it slipped out i think, a PR about something else.

@ppkarwasz can you look this? if you confirm i will try to close this with fixes or @AndrewBystrov if You interested to contribute. I am ready to review and approve.

Thanks for confirming! I’d be happy to work on this.

I’ll prepare a fix for the UNCACHED strategy and add a regression test covering Thread.setName() changes on a reused worker thread. I’ll open a pull request and link it here once it is ready.

[ramanathan1504]

@AndrewBystrov

Thanks please go through the Building.adoc before giving pr

Checklist

1.red and green test case.
2.change log with one line meaning full description
3.spotless check.
4.use ./mvnw command not mvn