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>

Pandect

@Buurman: Its a logging mechanism. You can see more here slf4j.org/api/org/slf4j/MDC.html – Pandect

What logging framework are you using underneath slf4j? log4j, logback, java.util.logging, commons logging? – Whitewing

@superEb: for now log4j – Pandect

@RamDuttShukla Could you add your log4j configuration and some sample logging from you app to the question please? It may help. Thanks. – Economic

@Jonathan: Added the log4j.xml configuration. – Pandect

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.

Whitewing

Just adding to answer by superEb, logback manual has it on how to use MDC logback.qos.ch/manual/mdc.html – Tubuliflorous

I have tried the same way you are suggesting in your answer by referring the veera-sundar's blog, But the issue is somehow different – Pandect

I am accepting this answer because the explanation is quite helpful. Though it is not having the correct answer but it helps me to get the answer. – Pandect

@RamDuttShukla - I notice you unaccepted my answer. Please see the additions I made to the EDIT section. It may help you with your logging problems. – Whitewing

Yes, the reason of not logging was the <root> tag. You are right. Now I will again accept the answer thanks. – Pandect

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.

Criseyde