로깅에 대하여2 - Logback MDC

이전 포스팅 중 이런 포스팅이 있었다.

로깅에 대하여

로그에 대한 내용을 담은 글이었는데, 여기에 추가적으로 하나 더 아주 유용한 기능을 기록해보려 한다.

서버를 운영하던 중 사용자의 요청이 어디서부터 시작해서 어디서 끝나는지 로그가 무수히 찍히는 상황에서는 인지하기가 쉽지가 않다.

어떤 작업을 했고 어떤 과정을 거쳤는지, 에러가 났다면 어디서 시작해서 어떤 에러가 발생했는지 로그 자체는 남지만 과정의 흐름을 이해하기가 쉽지 않았다. 그래서 요청부터 응답까지의 사용자 흐름을 한눈에 파악할 수 있는 좋은 기능인 Logback MDC를 사용하는 방법을 기록하려고 한다. 

 

우선, 요즘 대부분의 Slf4j 구현체는 Logback을 사용한다. 물론 log4j를 사용할수도 있다.

나는 Logback을 사용할거고 여기서 제공하는 MDC 기능을 사용하겠다. 쉽게 말해 사용자의 요청부터 응답까지의 로그를 하나의 흐름으로 확인하는 방법이다.

 

logback-spring.xml 파일 작성

우선, logback 설정 파일을 좀 수정해줘야 한다. 

logback-spring.xml vs logback.xml

스프링 부트에서 로그 설정 파일을 정의할 때, logback.xml 또는 logback-spring.xml 파일을 사용할 수 있다. 차이점은:

• logback-spring.xml은 스프링 부트만의 확장 기능을 사용할 수 있다. 예를 들어, profile 기반 설정 등을 지원한다.
• logback.xml은 순수 Logback 설정 파일로, 스프링 부트의 확장 기능은 사용할 수 없다.

따라서, 스프링 부트를 사용 중이라면, logback-spring.xml 파일을 사용하는게 더 유연한 설정을 할 수 있다.

 

이 파일은 어디에 이미 있는게 아니다. 그래서 필요하다면 개발자가 직접 생성해서 만들어야 한다. 그 위치는 `src/main/resources`이다. 여기에 이 파일을 만들어두면 스프링 부트가 자동으로 인식하여 시작될 때 이 로그 설정을 적용한다. 

 

src/main/resources/logback-spring.xml

<configuration>
    <appender name="CONSOLE" class="ch.qos.logback.core.ConsoleAppender">
        <encoder>
            <pattern>[%d{yyyy-MM-dd HH:mm:ss}] [%thread] [%X{identifier}] %-5level %logger{36} - %msg%n</pattern>
        </encoder>
    </appender>

    <root level="info">
        <appender-ref ref="CONSOLE" />
    </root>

    <!-- 특정 패키지 로그 레벨 설정 -->
    <logger name="hello" level="debug" additivity="false">
        <appender-ref ref="CONSOLE" />
    </logger>
</configuration>

• 우선, pattern 부분을 수정해야 한다. 내가 커스텀해서 사용자의 요청부터 응답까지의 한 과정을 동일한 식별자로 남길 수 있는 부분을 추가해야 한다. 나는 [%X{identifier}] 라고 값을 넣었다.
  • %X{key}는 Logback에서 로그 출력 시 MDC에 저장된 특정 키의 값을 참조하는데 사용된다.
  • 그래서 MDC.put("key", value)로 저장한 값을 참조하게 된다.
• 각 패키지 별로 로그 레벨을 설정할 수 있다. `root`는 기본으로 info로 설정하고 그 내부적으로 필요한 패키지만 레벨을 수정하는게 좋을것이다. `root`부터 debug로 설정하면 별별 로그가 다 찍힐테니까.
• 내가 만드는 프로젝트의 패키지의 루트는 `hello`이다. 그래서 <logger>를 추가적으로 만들어서 `hello` 패키지의 로그 레벨을 debug로 설정했다.
• `additivity="false"`는 해당 Logger 에서 처리한 로그가 상위 Logger 에 전파되지 않도록 설정하는 기능이다. 이게 왜 필요하냐면, `hello`는 결국 `root` 하위 패키지이다. 그래서 저렇게 `root`와 `hello`에 대한 <logger>를 만들고 이 속성을 추가하지 않으면 두 개의 logger가 같은 로그를 찍는다. 그게 싫으니 `hello` 레벨에서 찍은 로그는 `root`에서는 찍지 않아도 된다는 의미이다.

 

HandlerInterceptor로 요청마다 식별자 설정

스프링에서 사용할 수 있는 인터셉터를 사용해서 요청이 들어올 때 서블릿에 도착하기 전 고유 식별자를 만들어 모든 흐름의 로그에 같은 식별자를 남기자. 

 

LoggingInterceptor

package hello.login.web.interceptor;

import org.slf4j.MDC;
import org.springframework.web.servlet.HandlerInterceptor;

import javax.servlet.http.HttpServletRequest;
import javax.servlet.http.HttpServletResponse;
import java.util.UUID;

public class LoggingInterceptor implements HandlerInterceptor {

    @Override
    public boolean preHandle(HttpServletRequest request, HttpServletResponse response, Object handler) throws Exception {
        String uuid = UUID.randomUUID().toString().substring(0, 8);
        String ipAddress = request.getHeader("X-Forwarded-For");
        if (ipAddress == null || ipAddress.isEmpty() || "unknown".equalsIgnoreCase(ipAddress)) {
            ipAddress = request.getRemoteAddr();
        }

        MDC.put("identifier", uuid + "-(CLIENT-IP)-" + ipAddress);
        return true;
    }

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

• UUID를 만들어 절대 중복될 수 없는 고유값을 생성한다.
• 요청 헤더에 있는 `X-Forwarded-For` 값을 통해 요청한 사용자의 IP를 받아온다. 이 경우 헤더에 이 값이 없을 수 있다. 그럴 경우에는 HttpServletRequest 객체가 가지고 있는 getRemoteAddr() 메서드를 통해 값을 추가한다.
• MDC.put("identifier", uuid + "-(CLIENT-IP)-" + ipAddress)
  • `identifier`라는 키로 고유값을 매핑한다.
• 모든 요청에 대한 응답이 끝나고 사용자에게 돌아가기 전에 호출되는 afterCompletion() 메서드에서 만들어진 MDC 값을 초기화한다.

여기서 이런 의문이 든다면 굉장히 좋은 의문이다. 

"요청이 동시에 두개가 들어왔을 때 요청A는 일찍 끝나서 MDC.clear()가 호출됐을 때 요청B는 계속 처리중이라 중간에 `identifer`의 값이 날라가는 것 아닌가?"

→ MDC(Mapped Diagnostic Context)는 스레드 로컬 기반으로 동작한다. 즉, MDC에 저장된 데이터는 각 요청마다 개별 스레드에 저장되므로, 한 요청에서 MDC.clear()가 호출되더라도 다른 요청의 MDC 데이터에는 영향을 미치지 않는다. 그래서 안심해도 된다.

 

이렇게 인터셉터를 만들었으면, 이제 인터셉터를 등록하면 된다.

WebMvcConfigurer에서 인터셉터 등록

package hello.login;

import hello.login.web.interceptor.LoggingInterceptor;
import org.springframework.context.annotation.Configuration;
import org.springframework.web.servlet.config.annotation.InterceptorRegistry;
import org.springframework.web.servlet.config.annotation.WebMvcConfigurer;


@Configuration
public class WebConfig implements WebMvcConfigurer {

    @Override
    public void addInterceptors(InterceptorRegistry registry) {
        registry.addInterceptor(new LoggingInterceptor());
    }
}

 

하나의 요청에는 언제나 동일한 식별자가 기록됨을 확인

[2024-09-04 12:29:06] [http-nio-8080-exec-1] [8fd24009-(CLIENT-IP)-0:0:0:0:0:0:0:1] DEBUG c.g.controller.HealthzController - [healthz] Health Check
[2024-09-04 12:29:06] [http-nio-8080-exec-1] [8fd24009-(CLIENT-IP)-0:0:0:0:0:0:0:1] DEBUG c.gemmachat.service.HealthzService - [healthz] Wow condition is good 🎉

• 사용자가 요청을 했고 그 요청이 처리하는 과정이 계속해서 같은 식별자인 `8fd24009-(CLIENT-IP)-0:0:0:0:0:0:0:1`로 기록되고 있음을 확인할 수 있다. 나는 내가 내 서버에 요청했기 때문에 0:0:0:0:0:0:0:1(localhost)로 찍히고 있다.

 

이렇게 설정해두면, 요청부터 응답까지의 모든 과정을 동일한 식별자로 기록해서 한눈에 한 요청이 어떤 작업부터 어떤 흐름으로 무엇을 했는지 보기가 편하고 에러가 발생하더라도 어디서 출발해서 어떤 부분에서 에러를 마주했고 그 에러가 무엇인지 로그를 통해 트래킹하는게 쉬워진다. 

 

 

보너스. 서블릿 필터로 적용

"어? 저는 스프링 인터셉터 싫은데요? 서블릿 필터로는 안되나요?" → 됩니다! (굳이? 라는 생각이 들지만)

 

LogFilter

package hello.login.web.filter;

import lombok.extern.slf4j.Slf4j;
import org.slf4j.MDC;

import javax.servlet.*;
import javax.servlet.http.HttpServletRequest;
import javax.servlet.http.HttpServletResponse;
import java.io.IOException;
import java.util.UUID;

@Slf4j
public class LogFilter implements Filter {

    @Override
    public void init(FilterConfig filterConfig) throws ServletException {
        log.info("LogFilter init");
    }

    @Override
    public void doFilter(ServletRequest servletRequest,
                         ServletResponse servletResponse,
                         FilterChain filterChain) throws IOException, ServletException {
        log.info("LogFilter doFilter");

        HttpServletRequest request = (HttpServletRequest) servletRequest;
        HttpServletResponse response = (HttpServletResponse) servletResponse;

        String uuid = UUID.randomUUID().toString();

        String ipAddress = request.getHeader("X-Forwarded-For");
        if (ipAddress == null || ipAddress.isEmpty() || "unknown".equalsIgnoreCase(ipAddress)) {
            ipAddress = request.getRemoteAddr();
        }

        MDC.put("identifier", uuid + "-(CLIENT-IP)-" + ipAddress);

        try {
            filterChain.doFilter(request, response);
        } catch (Exception e) {
            throw new ServletException(e);
        } finally {
            MDC.clear();
        }
    }

    @Override
    public void destroy() {
        log.info("LogFilter destroy");
    }
}

• Filter를 구현한다. 동일하게 구현하면 된다. 다만, Filter는 doFilter 메서드 안에서 MDC.clear()도 응답을 사용자에게 내보내기 전에 처리해줘야 한다.

WebConfig

package hello.login;

import hello.login.web.filter.LogFilter;
import org.springframework.boot.web.servlet.FilterRegistrationBean;
import org.springframework.context.annotation.Bean;
import org.springframework.context.annotation.Configuration;

import javax.servlet.Filter;

@Configuration
public class WebConfig implements WebMvcConfigurer {

    @Bean
    public FilterRegistrationBean<LogFilter> logFilter() {
        FilterRegistrationBean<LogFilter> filterFilterRegistrationBean = new FilterRegistrationBean<>();
        filterFilterRegistrationBean.setFilter(new LogFilter());
        filterFilterRegistrationBean.setOrder(1);
        filterFilterRegistrationBean.addUrlPatterns("/*");

        return filterFilterRegistrationBean;
    }
}

• 서블릿 필터를 등록한다.

실행결과

[2024-09-04 15:59:48] [http-nio-8080-exec-3] [bed864ac-f818-4ef3-a2fc-8fd249a06da2-(CLIENT-IP)-0:0:0:0:0:0:0:1] INFO  hello.login.web.item.ItemController - HI