Saturday, 15 April 2017

Adding MDC headers to every Spring MVC request

Mapped Diagnostic Context (MDC) logging allows you to set attributes associated with current thread, so that SLF4J (via your logger implementation library) can log those attributes with each logging statement without it having to be specified.

For example you could configure logback to log the sessionId on every statement, which is really handy when using a log indexer such as Splunk. This would allow you to easily see all the requests made by a user, for a given session. To use with logback, you'd set the pattern to %-4r [%thread] %-5level sessionId=%X{sessionId} - %msg%n

Setting these attributes for each entry point would be a pain so one way would be to implement a ServletRequestListener, which would allow setting the attributes at the start of the request and removing them again at the end of the request. (Note: It's important to remove the attributes afterwards, as threads are re-used by application servers and will give misleading logging statements)
If you're using Spring MVC then an alternative is to implement a HandlerInterceptor. How to configure it using annotations instead of XML is not immediately obvious, so here it is so I don't have to work it out again next time I need it.

This implementation just pulls values out of the request object without much manipulation. If you want to add the method parameters of an annotated handler method then you'll need to use Spring AOP instead.

HandlerInterceptor Implementation

import org.slf4j.MDC;
import org.springframework.web.servlet.handler.HandlerInterceptorAdapter;

import java.util.HashSet;
import java.util.Set;

import javax.servlet.http.HttpServletRequest;
import javax.servlet.http.HttpServletResponse;

/**
 * Adds logging.
 */
public class LoggingHandlerInterceptor extends HandlerInterceptorAdapter {
   /**
    * set of keys added to MDC so can be removed
    */
   private ThreadLocal<Set<String>> storedKeys = ThreadLocal.withInitial(() -> new HashSet<>());

   @Override
   public boolean preHandle(HttpServletRequest request, HttpServletResponse response, Object handler) throws Exception {
      addKey("sessionId", request.getHeader("X-Session-Id"));
      addKey("url", request.getRequestURI());
      if (request.getHeader("X-Request-Id") != null) {
         addKey("requestId", request.getHeader("X-Request-Id"));
      }
      return true;
   }

   private void addKey(String key, String value) {
      MDC.put(key, value);
      storedKeys.get().add(key);
   }

   @Override
   public void afterConcurrentHandlingStarted(HttpServletRequest request, HttpServletResponse response, Object handler) throws Exception {
      // request ended on current thread remove properties
      removeKeys();
   }

   @Override
   public void afterCompletion(HttpServletRequest request, HttpServletResponse response, Object handler, Exception ex)
           throws Exception {
      removeKeys();
   }

   private void removeKeys() {
      for (String key : storedKeys.get()) {
         MDC.remove(key);
      }
      storedKeys.remove();
   }
}

Spring Java Annotation Configuration

import org.springframework.context.annotation.Bean;
import org.springframework.context.annotation.Configuration;
import org.springframework.web.servlet.config.annotation.InterceptorRegistry;
import org.springframework.web.servlet.config.annotation.WebMvcConfigurerAdapter;

@Configuration
public class BeanConfiguration {

   @Bean
   public LoggingHandlerInterceptor loggingHandlerInterceptor() {
      return new LoggingHandlerInterceptor();
   }

   @Bean
   public WebMvcConfigurerAdapter webConfigurer() {
      return new WebMvcConfigurerAdapter() {
         @Override
         public void addInterceptors(InterceptorRegistry registry) {
            registry.addInterceptor(loggingHandlerInterceptor());
         }
      };
   }
}

And if your using logback and Spring Boot here is the configuration to output all MDC keys (using spring's default formatting):

logback-spring.xml

<?xml version="1.0" encoding="UTF-8"?>
<configuration>
  <include resource="org/springframework/boot/logging/logback/defaults.xml"/>
  <property name="CONSOLE_LOG_PATTERN" value="%clr(%d{yyyy-MM-dd HH:mm:ss.SSS}){faint} %clr(${LOG_LEVEL_PATTERN:-%5p}) %clr(${PID:- }){magenta} %clr(---){faint} %clr([%15.15t]){faint} %clr(%-40.40logger{39}){cyan} %clr(:){faint} %m %mdc%n${LOG_EXCEPTION_CONVERSION_WORD:-%wEx}"/>
  <property name="FILE_LOG_PATTERN" value="%d{yyyy-MM-dd HH:mm:ss.SSS} ${LOG_LEVEL_PATTERN:-%5p} ${PID:- } --- [%t] %-40.40logger{39} : %m %mdc%n${LOG_EXCEPTION_CONVERSION_WORD:-%wEx}"/>
  <include resource="org/springframework/boot/logging/logback/console-appender.xml"/>
  <include resource="org/springframework/boot/logging/logback/file-appender.xml"/>
  <root level="INFO">
    <appender-ref ref="CONSOLE"/>
    <appender-ref ref="FILE"/>
  </root>
</configuration>


No comments:

Post a Comment