Logging in Java with Logback and MDC

Logback brings a very large number of improvements over log4j like faster execution, native support for SLF4J,XML or Groovy based configuration files, automatic reloading of config files to name a few. logback builds upon on our previous work on log4j, simply put, logback is just a better log4j. The MDC(Mapped Diagnostic Context) is a map which stores the context data of the particular thread where the context is running. For example, in servlet, each user will be processed in its own thread and you can make each thread store the "username" and the log4j.xml or logback.xml will have a pattern like %X{key} to retrievce the values that are present in the MDC. The key will be ‘userName’ in our example. Another example would be that you might want to log the RESTful service request parameters as demonstrated below.

Step 1: Require the relevant jar library files.Define the following dependencies in the pom.xml files.

    <properties> 
     <logback.version>1.0.0</logback.version>
  <slf4j.version>1.6.4</slf4j.version>
 </properties>

        <!-- Logging -->

  <dependency>
   <groupId>ch.qos.logback</groupId>
   <artifactId>logback-classic</artifactId>
   <version>${logback.version}</version>
  </dependency>
  <dependency>
   <groupId>org.slf4j</groupId>
   <artifactId>slf4j-api</artifactId>
   <version>${slf4j.version}</version>
  </dependency>
  <dependency>
   <groupId>org.slf4j</groupId>
   <artifactId>log4j-over-slf4j</artifactId>
   <version>${slf4j.version}</version>
  </dependency>
  <dependency>
   <groupId>org.slf4j</groupId>
   <artifactId>jcl-over-slf4j</artifactId>
   <version>${slf4j.version}</version>
  </dependency>
  

Step 2: Define the logback.xml file, under src/main/resources folder in the maven structure.

<?xml version="1.0" encoding="UTF-8" ?>
<configuration debug="true" scan="false">

<!--
   1. Logback tries to find a file called logback.groovy in the classpath.
   2. If no such file is found, logback tries to find a file called logback-test.xml
      in the classpath.
   3. If no such file is found, it checks for the file logback.xml in the classpath.
   4. In case neither file is found, logback configures itself automatically using 
      the BasicConfigurator which will cause logging output to be directed on the console.
      
      See http://logback.qos.ch/manual/configuration.html
 -->
   <appender name="FILE" class="ch.qos.logback.core.rolling.RollingFileAppender">
   
   <file>logs/app.log</file>
   
   <rollingPolicy class="ch.qos.logback.core.rolling.FixedWindowRollingPolicy">
    <fileNamePattern>logs/app.%i.log.gz</fileNamePattern>
    <minIndex>1</minIndex>
    <maxIndex>12</maxIndex>
   </rollingPolicy>
   
   <triggeringPolicy class="ch.qos.logback.core.rolling.SizeBasedTriggeringPolicy">
    <maxFileSize>10MB</maxFileSize>
   </triggeringPolicy>
   
   <encoder>
      <!-- Note that MDC is added via myAppMDCMap -->
   <pattern>%d{ISO8601} %-5level [%thread] %logger{36} - [%X{myAppMDCMap}] - %msg%n</pattern>
  </encoder>
  </appender>
  
    <logger level="@LOG_LEVEL@" name="com.jpmorgan" />
    <logger level="INFO" name="org.springframework.web.servlet.mvc.method.annotation" /> 
    <logger level="WARN" name="org.springframework.jdbc.core" /> 
    
    
  <appender name="STDOUT" class="ch.qos.logback.core.ConsoleAppender">
    encoders are assigned the type ch.qos.logback.classic.encoder.PatternLayoutEncoder 
            by default
        <encoder>
            <pattern>%-4relative [%thread] %-5level %logger{35} - %msg %n
            </pattern>
        </encoder>
    </appender>  -->
      
  <!-- For root loggers, log to FILE appender -->
  <root level="@LOG_LEVEL@">
  <appender-ref ref="FILE" />
  <!-- <appender-ref ref="STDOUT" /> 
 </root>

</configuration>

Step 3: Define the MDC related classes to get context based logging. In this example, we want to log by portfolioCode.



Firstly a holder class that converts the values in a map to string when logging.

package com.myapp.logging;

import java.util.Map;
import java.util.Set;

/**
 * MDC Map holder - to provide custom toString
 */
public class MDCMap
{
    
    private Map<String, String> myAppMDCMap;
    
    public MDCMap(Map<String, String> gmrdMDCMap)
    {
        super();
        this.myAppMDCMap = gmrdMDCMap;
    }
    
    @Override
    public String toString()
    {
        StringBuilder toString = new StringBuilder();
        Set<String> keys = myAppMDCMap.keySet();
        for (String key : keys)
        {
            toString.append(key + "=" + myAppMDCMap.get(key) + ",");
        }
        return toString.substring(0, toString.length() - 1);
    }
}

Secondly, define the MDCLoggingHelper class. You could usethe MDC.put directly if your requirements are simple enough.

package com.myapp.logging;

import java.util.Map;

import org.slf4j.MDC;

public class MDCLoggingHelper
{
    
    /**
     * Add Cash ForeCast Params to MDC map
     */
    public void addParam(String portfolioCode)
    {
        MDC.put("PortfolioCode", portfolioCode);
        buildMap();
    }
    
    
    
    private void buildMap()
    {
        MDC.remove("myAppMDCMap"); // the names used in logback.xml %X{myAppMDCMap}
        @SuppressWarnings("unchecked")
        Map<String, String> currentMDCMap = MDC.getCopyOfContextMap();
        MDC.put("myAppMDCMap", new MDCMap(currentMDCMap).toString());
    }
}

Step 4: Finally, use it in your RESTFul service controller method as shown below.

@Controller
public class CashForecastController
{

    private final MDCLoggingHelper MDCLoggingHelper = new MDCLoggingHelper();
 private static final Logger logger = LoggerFactory.getLogger(CashForecastController.class);

 @RequestMapping(value = "/cashForecastFeed", method = RequestMethod.GET)
    public  @ResponseBody CashforecastFeedresponse generateCashForecastFeed(
            @RequestParam(value = "portfoliocd", required = true) String portfolioCode,
            @RequestParam(value = "valuationDate", required = true) @DateTimeFormat(pattern = "dd MMM yyyy") Date valuationDate) throws Exception
    {
        
        MDCLoggingHelper.addParam(portfolioCode);
        
        logger.info("Start processing  ");
  
  //....
 }
}

That's all to it. In the logs, now you can see the portfolioCode being added. This can improve your debugging as to which portfolio code is causing the problem.