Useful logging mechanism: Mapped Diagnostic Context (MDC) in Logback

Quite often, enterprise-level web applications need to log sufficient information for troubleshooting problems but logging can be resource intensive and log analysis can be time consuming, especially if the application in question is deployed in production serving high volume of requests. Mapped Diagnostic Context (MDC)  in Logback is a useful logging mechanism that gives us the ability to select what to log. In this post, I describe a simple use case to demonstrate its usefulness.

If you are using Maven, you need the following dependencies in your pom.xml for this demo:

<dependency>

 <groupId>org.slf4j</groupId>

 <artifactId>slf4j-api</artifactId>

 <version>1.7.5</version>

</dependency>

<dependency>

 <groupId>ch.qos.logback</groupId>

 <artifactId>logback-core</artifactId>

 <version>1.0.13</version>

</dependency>

<dependency>

 <groupId>ch.qos.logback</groupId>

 <artifactId>logback-classic</artifactId>

 <version>1.0.13</version>

</dependency>

In the following example, we would like "Starting app" and "Finishing app" statements to be logged. We would also like to log "Hello Parthy" but not "Hello Fred", both of which are DEBUG-level log statements. 

Using MDC:

    public static void main( String[] args )

  {

        Logger logger = LoggerFactory.getLogger("personal.tests.logback");

        

        logger.info("Starting app.");

        String username = "Parthy";

        MDC.put("username",  username);

        logger.debug("Hello {}", username);

        MDC.remove("username");

        username = "Fred";

        MDC.put("username",  username);

        logger.debug("Hello {}", username);

        MDC.remove("username");

        

        logger.info("Finishing app.");

  }

logback.xml (using MDCFilter that is shipped with logback):

<configuration>

 <turboFilter class="ch.qos.logback.classic.turbo.MDCFilter">

  <MDCKey>username</MDCKey>

  <Value>parthy</Value>

  <OnMatch>ACCEPT</OnMatch>

 </turboFilter>

 <appender name="console" class="ch.qos.logback.core.ConsoleAppender">

  <encoder>

   <pattern>%date [%thread] %-5level %logger - %msg%n</pattern>

  </encoder>

 </appender>

 <root level="INFO">

  <appender-ref ref="console" />

 </root>

</configuration>

Setting the OnMatch value in the turboFilter to DENY will prevent "Hello Parthy" getting logged. In this case, "Hello Fred" will also not be logged because the root logger level is INFO and "Hello Fred" is logged at DEBUG level.

To use MDC effectively, developers should put the customer support hat and ask how can I trace an individual request amidst tens or hundreds of thousands of request with minimal noise in the logs. Find out how requests are identified (request id, session id, user name etc) and use those as MDC keys. You might say that such filtering is CPU intensive. Actually, logback's turboFilter is intended for high performance.

Interested? Read more here: http://logback.qos.ch/manual/filters.html