Log4J2 appender not logging to ThreadContext folder

Question

I have the following Log4J2 configuration XML:

<Routing name="myAppender">
    <Routes pattern="$${ctx:workId}">
        <Route>
            <File fileName="${my-path}/sites/${ctx:workId}/${date:yyyy-MM-dd}/${ctx:employeeId}/emp.log" name="myAppender-${ctx:workId}">
                <MarkerFilter marker="TELEMETRIC" onMatch="ACCEPT" onMismatch="DENY"/>
                <PatternLayout>
                    <Pattern>[%date{ISO8601}][%-5level][%logger{1.}][%marker][$${ctx:employeeId}] %X%m%n</Pattern>
                </PatternLayout>
            </File>
        </Route>
    </Routes>
</Routing>

<Async name="Async">     
    <AppenderRef ref="myAppender" level="info"/>
</Async>

However whenever the log4j2 appender writes to a file, it doesn't use the proper ${ctx:employeeId} string when it writes to the specified file path.

The first time the log4j2 appender writes to a file, it writes to the correct file path specified by ${ctx:employeeId}. But whenever information about an employee with another Id is put into the thread context, the appender is still logging to the old file path.

For example the first time the appender logs it writes to the correct path:

D:/example/logs/sites/1/2015-08-22/2/emp.log

But when the the logger is logging for the next employee Id (With a new ThreadContext) it is still logging into

D:/example/logs/sites/1/2015-08-22/2/emp.log

instead of for example:

D:/example/logs/sites/1/2015-08-22/3/emp.log

(Note the employee Id is different.)

In the log output pattern, I log the current employeeId [$${ctx:employeeId}], as well as what is in the current thread context %X. The output shows that the correct employeeId is being used and is in the ThreadContext, but the appender is not logging to that ${ctx:employeeId} file path.

Does anyone know if I am missing anything? Or if I am doing something wrong? Or is this possibly a bug with Log4j2? Thanks for any help!

D.B. D.B. · Accepted Answer · 2017-04-14T01:45:47

Well, I realize this answer comes long after the question has been asked but in case this might still help you or someone else I'll share what I've found.

First of all I'm not able to reproduce the problem, but I do have code that achieves what you want so I'm going to share my code in the hope that by looking at it you can determine where you went wrong. If not then please provide a Minimal, Complete, and Verifiable Example so that anyone trying to help you can reproduce the issue.

Here is my working code:

package pkg;

import org.apache.logging.log4j.LogManager;
import org.apache.logging.log4j.Logger;
import org.apache.logging.log4j.Marker;
import org.apache.logging.log4j.MarkerManager;
import org.apache.logging.log4j.ThreadContext;

public class Log4j2DiffFilePerCtxVarMain {
    private static final Marker TELEMETRIC = MarkerManager.getMarker("TELEMETRIC");

    public static void main(String[] args){
        Logger log = LogManager.getLogger();

        ThreadContext.put("workId", "mainWorkId");
        ThreadContext.put("employeeId", "mainEmployeeId");

        log.info(TELEMETRIC, "Hey here's some info log from main!");

        Thread t1 = new Thread(new Runnable(){
            public void run(){
                Logger log = LogManager.getLogger();
                ThreadContext.put("workId", "thread1WorkId");
                ThreadContext.put("employeeId", "thread1EmployeeId");

                log.info(TELEMETRIC, "Hey here's some info log from thread1!");
            }
        });
        t1.start();
    }
}

Here is the log4j2.xml:

<?xml version="1.0" encoding="UTF-8"?>
<Configuration status="WARN">
    <Appenders>
        <Routing name="myAppender">
            <Routes pattern="$${ctx:workId}">
                <Route>
                    <File
                        fileName="logs/${ctx:workId}/${date:yyyy-MM-dd}/${ctx:employeeId}/emp.log"
                        name="myAppender-${ctx:workId}">
                        <MarkerFilter marker="TELEMETRIC" onMatch="ACCEPT"
                            onMismatch="DENY" />
                        <PatternLayout>
                            <Pattern>[%date{ISO8601}][%-5level][%logger{1.}][%marker][$${ctx:employeeId}] %X %m%n</Pattern>
                        </PatternLayout>
                    </File>
                </Route>
            </Routes>
        </Routing>

        <Async name="Async">
            <AppenderRef ref="myAppender" level="info" />
        </Async>
    </Appenders>
    <Loggers>
        <Root level="trace">
            <appender-ref ref="Async" />
        </Root>
    </Loggers>
</Configuration>

When I run this code with this log4j2.xml I see the following results:

The first log contains this:

[2017-04-13T20:42:49,814][INFO ][p.Log4j2DiffFilePerCtxVarMain][TELEMETRIC][mainEmployeeId] {employeeId=mainEmployeeId, workId=mainWorkId} Hey here's some info log from main!

The second log contains this:

[2017-04-13T20:42:49,822][INFO ][p.Log4j2DiffFilePerCtxVarMain$1][TELEMETRIC][thread1EmployeeId] {employeeId=thread1EmployeeId, workId=thread1WorkId} Hey here's some info log from thread1!

Hope this helps!

Log4J2 appender not logging to ThreadContext folder

1 Answers