Log4J2 with Routing Appenders and ThreadContext

I have some issues with log4j2 and the routing appenders.

My application generates different threads and within each thread I do something like this

ThreadContext.put("threadName", processName);

and processName will be generated within the thread based on different information. But that is not important, the only important information is, that processName will be different in each thread.

Now I have this log4j2.xml file

<?xml version="1.0" encoding="UTF-8"?>
<Configuration status="INFO">
    <Appenders>
        <Console name="console" target="SYSTEM_OUT">
            <PatternLayout pattern="%d{ABSOLUTE} %-5p [%-40.-40c{1}] %m%n"/>
        </Console>
        <Routing name="RoutingAppender">
            <Routes pattern="${ctx:threadName}">
                <Route>
                    <RollingFile name="Rolling-${ctx:threadName}"
                                 fileName="../log/${ctx:threadName}.log"
                                 filePattern="../log/${ctx:threadName}-%d{yyyy-MM-dd}.log"
                                 createOnDemand="true">
                        <PatternLayout pattern="%d{ABSOLUTE} %-5p [%-40.-40c{1}] %m%n"/>
                        <Policies>
                            <TimeBasedTriggeringPolicy interval="1" modulate="true"/>
                        </Policies>
                    </RollingFile>
                </Route>
            </Routes>
        </Routing>
    </Appenders>
    <Loggers>
        <Logger name="de.company" level="INFO" additivity="false">
            <AppenderRef ref="RoutingAppender"/>
            <AppenderRef ref="console"/>
        </Logger>
        <Logger name="com.company" level="INFO" additivity="false">
            <AppenderRef ref="RoutingAppender"/>
            <AppenderRef ref="console"/>
        </Logger>
        <Root level="INFO">
            <AppenderRef ref="RoutingAppender"/>
            <AppenderRef ref="console"/>
        </Root>
    </Loggers>
</Configuration>

And log4j creates logfiles for each thread without any issues.

Unfortunately log4j will create a logfile called ${ctx:threadName}.log. In this logfile the log messages from JSCH will appear. I guess that JSCH will create its own thread and since JSCH won't put a ThredName into the ThreadContext, log4j can not replace the variable and uses the variable from the configuration as the logfile name.

My goal would be to write all logfiles without a threadName in the ThreadContext into a single logfile.

I found this link in the documentation from log4j

https://logging.apache.org/log4j/log4j-2.2/faq.html#separate_log_files

but the issue is, that in that example they know what the value of threadName is. In my case I don't know the value.

ChatGPT told me, that I have to change the pattern within the <Routes> element and use a double $ like this

<Routes pattern="$${ctx:threadName}">

and than I can add a second <Route> element like this

<Routing name="RoutingAppender">
            <Routes pattern="$${ctx:threadName}">
                <Route key="$${ctx:threadName}">
                    <RollingFile name="Rolling-${ctx:threadName}"
                                 fileName="../log/${ctx:threadName}.log"
                                 filePattern="../log/${ctx:threadName}.log-%d{yyyy-MM-dd}"
                                 createOnDemand="true">
                        <PatternLayout pattern="%d{ABSOLUTE} %-5p [%-40.-40c{1}] %m%n"/>
                        <Policies>
                            <TimeBasedTriggeringPolicy interval="1" modulate="true"/>
                        </Policies>
                    </RollingFile>
                </Route>			
				<Route key="null">
					<RollingFile name="Rolling-service" 
								fileName="../log/default-service.log" 
								filePattern="../log/default-service.log-%d{yyyy-MM-dd}" 
								createOnDemand="true">
						<PatternLayout pattern="%d{ABSOLUTE} %-5p [%-40.-40c{1}] %m%n"/>
						<Policies>
							<TimeBasedTriggeringPolicy interval="1" modulate="true"/>
						</Policies>
					</RollingFile>
				</Route>			

            </Routes>
        </Routing>

But this is not working - I guess log4j interprets null as a String. The second approach was to remove the key attribute from the fallback route like this

            <Routes pattern="$${ctx:threadName}">
                <Route key="$${ctx:threadName}">
                    <RollingFile name="Rolling-${ctx:threadName}"
                                 fileName="../log/${ctx:threadName}.log"
                                 filePattern="../log/${ctx:threadName}.log-%d{yyyy-MM-dd}"
                                 createOnDemand="true">
                        <PatternLayout pattern="%d{ABSOLUTE} %-5p [%-40.-40c{1}] %m%n"/>
                        <Policies>
                            <TimeBasedTriggeringPolicy interval="1" modulate="true"/>
                        </Policies>
                    </RollingFile>
                </Route>
                <Route>
                    <RollingFile name="Rolling-service"
                                fileName="../log/default-service.log"
                                filePattern="../log/default-service.log-%d{yyyy-MM-dd}"
                                createOnDemand="true">
                        <PatternLayout pattern="%d{ABSOLUTE} %-5p [%-40.-40c{1}] %m%n"/>
                        <Policies>
                            <TimeBasedTriggeringPolicy interval="1" modulate="true"/>
                        </Policies>
                    </RollingFile>
                </Route>

            </Routes>

But in this case all log messages will be stored in the default-service.log.

Does anyone has a good idea what to do in this case?

Many greetings and thank you for your help!

The routing appender is tricky, because everything except the contents of <Route> is interpolated at compile-time, while the contents of <Route> will be evaluated if that route is chosen. Therefore if you have:

<Routing name="RoutingAppender">
  <Routes pattern="$${ctx:threadName}">
    <Route key="$${ctx:threadName}">
      <!-- Content 1 -->
    </Route>
    <Route>
      <!-- Content 2 -->
    </Route>
  </Routes>
</Routing>

it will be interpolated at configuration time to obtain:

<Routing name="RoutingAppender">
  <Routes pattern="${ctx:threadName}">
    <Route key="${ctx:threadName}">
      <!-- Content 1 unchanged -->
    </Route>
    <Route>
      <!-- Content 2 unchanged -->
    </Route>
  </Routes>
</Routing>

At runtime the pattern ${ctx:threadName} will be interpolated and matched against non-interpolated keys. Therefore:

• if ThreadContext.get("threadName") is null, the expression ${ctx:threadName} will evaluate to itself ${ctx:threadName} and match the key of the first (not second) route,
• if ThreadContext.get("threadName") is not null, it will not match any key and the second (default) route will be chosen.

Solutions

You can:

• either replace the contents of the second route with the fist one (in your last attempts) and viceversa,
• or add a default value for ${ctx:threadName} and use just a single default route:

<Properties>
  <Property name="threadName" value="default-service"/>
</Properties>
<Appenders>
  <Routing name="RoutingAppender">
    <Routes pattern="$${ctx:threadName}">
      <Route>
        <RollingFile name="Rolling-${ctx:threadName}"
                     fileName="../log/${ctx:threadName}.log"
                     filePattern="../log/${ctx:threadName}.log-%d{yyyy-MM-dd}"
                     createOnDemand="true">
        ...
        </RollingFile>
      </Route>
    </Routes>
  </Routing>
</Appenders>