Логирование в Spring Boot с глобальным traceId (применяем Mapped Diagnostic Context (MDC))

В предыдущей статье я поверхностно описал о том, как и для чего можно использовать глобальные trace ID, внедрённые с помощью механизма, предоставленного библиотекой Spring Cloud Sleuth.

Сегодня хочу рассмотреть, как можно использовать trace ID с помощью Mapped Diagnostic Context (MDC), поддерживаемого Logback и Log4J. Для разнообразия, добавим в логирование также IP клиента, направившего REST-запрос.

1. Подключаем в pom.xml зависимости:

<dependencies>
 <dependency>
  <groupId>org.springframework.boot</groupId>
  <artifactId>spring-boot-starter-web</artifactId>
 </dependency>

 <dependency>
  <groupId>org.springframework.boot</groupId>
  <artifactId>spring-boot-configuration-processor</artifactId>
  <optional>true</optional>
 </dependency>

 <dependency>
  <groupId>org.projectlombok</groupId>
  <artifactId>lombok</artifactId>
 </dependency>
</dependencies>

2. Добавляем файл конфигурации logback-spring.xml:

<configuration>
    <include resource="org/springframework/boot/logging/logback/defaults.xml"/>

    <property name="LOG_FILE" value="log/demo.mdc"/>​
    <property name="CONSOLE_LOG_PATTERN"
              value="%clr(%d{yyyy-MM-dd HH:mm:ss.SSS}){faint} %clr(%-5level [%X{Slf4jMDCFilter.ID}] [%X{Slf4jMDCFilter.ClientIP}]) %clr(${PID:- }){magenta} %clr(---){faint} %clr([%15.15t]){faint} %clr(%-40.40logger{39}){cyan} %clr(:){faint} %m%n${LOG_EXCEPTION_CONVERSION_WORD:-%wEx}"/>
    <property name="FILE_LOG_PATTERN"
              value="%d{yyyy-MM-dd HH:mm:ss.SSS} %-5level [%X{Slf4jMDCFilter.ID} %X[Slf4jMDCFilter.ClientIP]] ${PID:- } --- [%15.15t] %-40.40logger{39} : %m%n${LOG_EXCEPTION_CONVERSION_WORD:-%wEx}" />

    <appender name="FILE" class="ch.qos.logback.core.rolling.RollingFileAppender">
        <File>${LOG_FILE}.log</File>
        <rollingPolicy class="ch.qos.logback.core.rolling.TimeBasedRollingPolicy">
            <FileNamePattern>${LOG_FILE}.%d{yyyy-MM-dd}.log</FileNamePattern>
            <MaxHistory>7</MaxHistory>
        </rollingPolicy>
        <encoder>
            <pattern>${FILE_LOG_PATTERN}</pattern>
        </encoder>
        <filter class="ch.qos.logback.classic.filter.ThresholdFilter">
            <level>INFO</level>
        </filter>
    </appender>

    <appender name="CONSOLE" class="ch.qos.logback.core.ConsoleAppender">
        <encoder>
            <pattern>${CONSOLE_LOG_PATTERN}</pattern>
        </encoder>
    </appender>

    <root level="INFO">
        <appender-ref ref="FILE"/>
        <appender-ref ref="CONSOLE"/>
    </root>

</configuration>

3. Делаем класс конфигурации, который создаст FilterRegistrationBean для сервлета, и задаём имена HTTP заголовков и ключей MDC:

@Data
@Configuration
@ConfigurationProperties(prefix = slf4jfilter")
public class Slf4jMDCFilterConfiguration {

    public static final String DEFAULT_RESPONSE_TOKEN_HEADER = "X-Token";
    public static final String DEFAULT_REQUEST_TOKEN_HEADER = "X-Token";
    public static final String DEFAULT_MDC_ID_TOKEN_KEY = "Slf4jMDCFilter.ID";
    public static final String DEFAULT_MDC_CLIENT_IP_KEY = "Slf4jMDCFilter.ClientIP";

    private String responseHeader = DEFAULT_RESPONSE_TOKEN_HEADER;
    private String mdcTokenKey = DEFAULT_MDC_ID_TOKEN_KEY;
    private String mdcClientIpKey = DEFAULT_MDC_CLIENT_IP_KEY;
    private String requestHeader = DEFAULT_REQUEST_TOKEN_HEADER;

    @Bean
    public FilterRegistrationBean servletRegistrationBean() {
        final FilterRegistrationBean registrationBean = new FilterRegistrationBean();
        final Slf4jMDCFilter slf4jMDCFilter = new Slf4jMDCFilter(responseHeader, mdcTokenKey, mdcClientIpKey, requestHeader);
        registrationBean.setFilter(slf4jMDCFilter);
        registrationBean.setOrder(2);
        return registrationBean;
    }
}

4. Делаем фильтр. В нем извлекаем из REST-запроса HTTP заголовки "X-Token" (наш trace ID) и "X-Forvarded-For" (IP). Если заголовок "X-Token" отсутствует, то будет создан новый trace ID (генерируем рандомный UUID):

@Data
@EqualsAndHashCode(callSuper = false)
@EnableConfigurationProperties(Slf4jMDCFilterConfiguration.class)
@Component
public class Slf4jMDCFilter extends OncePerRequestFilter {

    private final String responseHeader;
    private final String mdcTokenKey;
    private final String mdcClientIpKey;
    private final String requestHeader;

    public Slf4jMDCFilter() {
        responseHeader = Slf4jMDCFilterConfiguration.DEFAULT_RESPONSE_TOKEN_HEADER;
        mdcTokenKey = Slf4jMDCFilterConfiguration.DEFAULT_MDC_ID_TOKEN_KEY;
        mdcClientIpKey = Slf4jMDCFilterConfiguration.DEFAULT_MDC_CLIENT_IP_KEY;
        requestHeader = Slf4jMDCFilterConfiguration.DEFAULT_REQUEST_TOKEN_HEADER;
    }

    public Slf4jMDCFilter(final String responseHeader, final String mdcTokenKey, final String mdcClientIPKey, final String requestHeader) {
        this.responseHeader = responseHeader;
        this.mdcTokenKey = mdcTokenKey;
        this.mdcClientIpKey = mdcClientIPKey;
        this.requestHeader = requestHeader;
    }

    @Override
    protected void doFilterInternal(final HttpServletRequest request, final HttpServletResponse response, final FilterChain chain)
            throws java.io.IOException, ServletException {
        try {
            final String token = extractToken(request);
            final String clientIP = extractClientIP(request);
            MDC.put(mdcClientIpKey, clientIP);
            MDC.put(mdcTokenKey, token);
            if (!StringUtils.isEmpty(responseHeader)) {
                response.addHeader(responseHeader, token);
            }
            chain.doFilter(request, response);
        } finally {
            MDC.remove(mdcTokenKey);
            MDC.remove(mdcClientIpKey);
        }
    }

    private String extractToken(final HttpServletRequest request) {
        final String token;
        if (!StringUtils.isEmpty(requestHeader) && !StringUtils.isEmpty(request.getHeader(requestHeader))) {
            token = request.getHeader(requestHeader);
        } else {
            token = UUID.randomUUID().toString().toUpperCase().replace("-", "");
        }
        return token;
    }

    private String extractClientIP(final HttpServletRequest request) {
        final String clientIP;
        if (request.getHeader("X-Forwarded-For") != null) {
            clientIP = request.getHeader("X-Forwarded-For").split(",")[0];
        } else {
            clientIP = request.getRemoteAddr();
        }
        return clientIP;
    }

    @Override
    protected boolean isAsyncDispatch(final HttpServletRequest request) {
        return false;
    }

    @Override
    protected boolean shouldNotFilterErrorDispatch() {
        return false;
    }
}

5. Создаём "Hello!"-контроллер:

@Slf4j
@RestController
public class MyController {

    @GetMapping("/hello")
    public String getHello() {
        log.info("Called getHello");
        return "Hello!";
    }
}

6. Запускаем приложение и направляем ему два запроса:
1) Без заголовка "X-Token".

curl http://localhost:8080/hello

В ответ получаем "Hello!" и видим в логах запись с IP и сгенерированным токеном:

2019-01-19 16:13:52.965 INFO  [2B239745F1A4496CB5BF148FE9E1EDB9] [127.0.0.1] 31702 --- [nio-8080-exec-1] r.e.demo.mdc.controller.MyController     : Called getHello

2) С заголовком "X-Token".

curl -H "X-Token: 228dc00d216b" http://localhost:8080/hello

В ответ получаем "Hello!" и видим в логах запись с IP и переданным в заголовке токеном:

2019-01-19 16:16:33.889 INFO  [228dc00d216b] [127.0.0.1] 31702 --- [nio-8080-exec-3] r.e.demo.mdc.controller.MyController     : Called getHello

Код на GitHub