not able to put the values in the MDC

Question

I am trying to log few values in the onBeginRequest() of RequestCycle() in wicket. But the values are not being logged in the debug file. I am putting the values in the MDC in RequestCycleListeners().

Following is the code:

getRequestCycleListeners().add(new AbstractRequestCycleListener()
{       
public void onBeginRequest(RequestCycle cycle) 
{                   
  if( cycle.getRequest().getContainerRequest() instanceof HttpServletRequest )
  {
    HttpServletRequest containerRequest = 
        (HttpServletRequest)cycle.getRequest().getContainerRequest();

    MDC.put("serverName", containerRequest.getServerName());
    MDC.put("sessionId",  containerRequest.getSession().getId());

    LOGGER.debug("logging from RequestCycleListeners() !!!");
    WebClientInfo webClientInfo = new WebClientInfo(RequestCycle.get());
    System.out.println(webClientInfo.getUserAgent());
    System.out.println("webClientInfo.getProperties().getBrowserVersionMajor() " +containerRequest.getRemoteAddr());
}

};

I am expecting 'serverName', 'sessionId' to be logged in the debug file.

I have added this listener in the class which is extending the WebApplication.

I am using log4j.xml the DEBUG appender is looks as below:

<appender name="DEBUG" class="org.apache.log4j.rolling.RollingFileAppender">
  <param name="Append" value="true"/>
  <layout class="org.apache.log4j.PatternLayout">
    <param name="ConversionPattern" value="[%d{ISO8601} %t %5p] %m -- %X{serverName} -- %X{sessionId} -- %X{portNumber}%n"/>
  </layout>
  <filter class="org.apache.log4j.varia.LevelRangeFilter">
    <param name="LevelMin" value="DEBUG"/>
    <param name="LevelMax" value="WARN"/>
  </filter>
</appender>

and we are defining scope in root tag :

<root>
   <priority value="INFO" />
   <appender-ref ref="CONSOLE" />
   <appender-ref ref="DEBUG" />
   <appender-ref ref="ERROR" />
</root>

Answer 1

Typically, MDC values are only output to logs if you include MDC keys in your logging pattern via configuration. Since slf4j is just a facade, you need to have framework-specific support and configuration underneath slf4j to make use of MDC. Read slf4j's notes on that here.

So, for example, if you're using log4j as the impl underneath slf4j, then you would need log4j config (ConversionPattern) like:

%d %-5p [%c] [%X{serverName} %X{sessionId}] %m%n

Where %X{serverName} %X{sessionId} is the relevant part that pulls values from the MDC.

Here's a pretty good example using log4j without sl4j. See notes on X Conversion Character in log4j javadoc here.

Note that pattern syntax for logback is identical. See specifics for logback here.

Also note that best practice for MDC (which uses a ThreadLocal under-the-hood) is to clear the context (remove the values you put in the map) when the context is no longer in scope. That typically means calling remove or clear in a finally block, like:

try {
    //...
    MDC.put("key1", value1);
    MDC.put("key2", value2);
    //...
} finally {
    //this
    MDC.remove("key1");
    MDC.remove("key2");
    //or this
    MDC.clear();
}

This is especially important if the thread that holds the MDC belongs to a pool for later reuse. You certainly don't want to unintentionally log invalid context values since that will just cause confusion.

EDIT

Your log4j configuration seems a little odd, for the following reasons:

1. You are naming your appenders after log levels, which may cause confusion
2. Your RollingFileAppender does not define a file
3. Your root logger will log to 3 different appenders, one of which is named DEBUG, but it is configured to only log INFO level and greater (based on the priority tag), so debug statements will not be logged

Unless you have some specific categories configured separately that are not shown, I would guess that none of your LOGGER.debug statements are being logged, regardless of your attempt to use MDC.

Answer 2

Note, that if you are using AsyncAppender, clearing MDC from your thread won't protect you, since the log event and MDC handling happens in the AsyncAppender's thread. See also this related bug

Unfortunately, in v1.2.17 the latest released version of the EOLed log4j-1.x, the AsyncAppender's Dispatcher-Thread does not clear the MDC upon stopping either.

Since, the AsyncAppender/Dispatcher is fairly simple, it's easy to patch it by putting

finally
{
    MDC.clear();
}

at the try-block in org.apache.log4j.AsyncAppender.Dispatcher.run() method.

Of course, one can also workaround this by not using AsyncAppender when executing in a ServletContainer.