[Spring] MDC를 사용해 요청 별로 구분되는 로그 남기기

배경

최근 김영한님 강의에서 필터에 관한 내용을 보게 되었다.

강의에서는 UUID를 통해서 필터를 통과하는 요청에 대한 로그를 구분하고 있었는데, 이 방법은 같은 요청이더라도

필터를 통과하고 난 이후부터 응답하기 이전까지의 로그에 대해서는 같은 UUID를 로그로 남겨줄 수 없어 실제 서비스에서는 활용하기 힘들어 보였다.

 

그래서 여러 요청에 대한 로그가 무작위로 뒤섞이는 어지러운 상황에서도 특정 요청에 대한 로그를 구분할 수 있도록

도와주는 MDC라는 도구를 프로젝트에 사용했고, 이를 정리하고자 한다.

 

MDC란?

MDC(Maped Diagnostic Context)는 ThreadLocal을 통해 구현된 일종의 저장 공간을 제공하는 클래스로서,

Map<String, String> 구조의 객체를 지니고 있어 (Key, Value) 형태로 원하는 데이터를 하나의 요청(스레드) 내에서 넣고 꺼내는 것이 가능하다.

실제로 위처럼 구현된 static 메서드들(get과 put, clear 등)을 사용해서 UUID를 저장한 뒤 로그에 사용해 보도록 하겠다.

 

요청 별로 구분되는 로그 남기기

필자의 프로젝트에서는 응답과 요청을 로그로 남기기 위한 필터(LogginFilter)를 하나 만들었고,

스프링 구조 상 가장 앞쪽에 위치한 필터에서 MDC에 UUID를 넣고 로깅을 할 때마다 꺼내는 식으로 구현했다.

 

public class LoggingFilter implements Filter {

	@Override
    public void doFilter(ServletRequest request, ServletResponse response, FilterChain chain) throws IOException, ServletException {
		
    	UUID uuid = UUID.randomUUID();
        MDC.put("request_id", uuid.toString());
        
        chain.doFilter(request, response);
        
        MDC.clear();
    }
}

실제 필터를 간소화하면 위와 같다.

 

UUID를 생성한 뒤 MDC에 집어넣었다.

이제 로깅을 할 때마다 put 메서드를 활용해 꺼내서 사용해도 되고,

나는 logback을 사용하고 있기에 logback 설정 파일에서 아래와 같이 로그 패턴에 request_id를 꺼내서 사용하도록 했다.

// Logback
<property name="CONSOLE_LOG_PATTERN"
          value="[%X{request_id:-internal}] [%d{yyyy-MM-dd HH:mm:ss}:%-3relative] %clr(%-5level) %magenta(${PID:-}) --- [%thread] %cyan(%-40.40logger{36}) : %msg%n"/>

%X{key}의 형태로 value를 꺼낼 수 있다. Log4j나 Log4j2를 사용하는 경우는 이 링크를 참조하면 된다.

위처럼 :-internal을 덧붙이면 내장 톰캣 서버가 실행될 때는 요청이 필터를 통과하는 상황이 아니므로 UUID가 찍히지 않고 비어있게 되는데, 이를 방지하고자 해당하는 value가 없을 시 internal이라는 default value가 로그에 남도록 했다.

이때 사용할 문구는 각자 자유롭게 바꿔도 좋다.

 

실행해서 API를 호출해 보면 로그가 잘 찍히는 것을 확인할 수 있다.

 

Nginx가 처리한 요청과 동일한 식별자로 로그 남기기

현재 프로젝트에서는 WAS 앞에 리버스 프록시로서 Nginx를 사용하고 있다. Nginx 또한 처리한 요청에 대해 자체적으로 로그를 남기는데 이때 사용한 식별자와 WAS 내부의 로그에서 사용하는 식별자를 일치시키면 모니터링이 더 수월해질 것이라고 생각했다. 방법은 다음과 같다.

 

public class LoggingFilter implements Filter {

	@Override
    public void doFilter(ServletRequest request, ServletResponse response, FilterChain chain) throws IOException, ServletException {
		
    	String requestId = ((HttpServletRequest) request).getHeader("X-requestID");
        MDC.put("request_id", Objects.toString(requestId, UUID.randomUUID().toString()));
        
        chain.doFilter(request, response);
        
        MDC.clear();
    }
}

아까 사용한 LoggingFilter을 위와 같이 수정한다.

혹시라도 HTTP 헤더에서 X-requestID를 찾지 못한 경우 UUID를 새로 만들어서 집어넣도록 작성했다.

 

proxy_set_header X-RequestID $request_id;

Nginx 서버 요청을 설정하는 파일에서 위 문구를 추가한다.

위 캡처 사진에서 오타가 있다. X-Request-ID가 아니라 X-RequestID이다.

 

이제 Nginx 로그 패턴을 변경하면 된다.

Nginx로 처리하는 모든 요청에 대해 적용하고자 한다면 /etc/nginx/nginx.conf의 http 블록 안에, 서버 별로 다르게 적용할 것이라면 서버 설정 파일의 최상단에 다음과 같이 작성하도록 한다.

log_format  access_log_format  '$request_id $remote_addr - $remote_user [$time_local] "$request" '
                  '$status $body_bytes_sent "$http_referer" "$request_time" '
                  '"$http_user_agent" "$http_x_forwarded_for"';

log_format 옆에 있는 access_log_format은 로그 포맷의 이름을 설정한 것이다.

참고로 error_log 행의 가장 우측에 있는 error 문구는 Nginx 에러 로그가 몇 단계로 나누어져 있어서 error 레벨보다 하위의 레벨이라면 로깅을 하지 않겠다고 설정한 것이다.

 

// default 로그 패턴
218.159.198.87 - - [24/Mar/2024:16:05:09 +0900] "GET /api/place?latitude=37.505098&longitude=127.032941&page=0 HTTP/1.1" 200 51 "https://api.modu-menu.com/swagger-ui/index.html" "Mozilla/5.0 (Windows NT 10.0; Win64; x64) AppleWebKit/537.36 (KHTML, like Gecko) Chrome/123.0.0.0 Safari/537.36"


// 로그 패턴에 $request_id 추가 후
5b5103ad34fe5f9fb70106cf91d320ee 218.159.198.87 - - [24/Mar/2024:16:10:42 +0900] "GET /api/place?latitude=37.505098&longitude=127.032941&page=0 HTTP/1.1" 200 51 "https://api.modu-menu.com/swagger-ui/index.html" "0.028" "Mozilla/5.0 (Windows NT 10.0; Win64; x64) AppleWebKit/537.36 (KHTML, like Gecko) Chrome/123.0.0.0 Safari/537.36" "-"

/var/log/nginx/access.log에 들어가면 위와 같이 Nginx 로그가 잘 변경된 것을 확인할 수 있다.

 

주의할 점

위 코드에서 doFilter() 호출 이후에 MDC.clear()를 호출하도록 코드를 작성한 것에는 다음과 같은 이유가 있다.

MDC implementations typically use ThreadLocals to store the contextual information. That’s an easy and reasonable way to achieve thread-safety.
However, we should be careful using MDC with thread pools.
Let’s see how the combination of ThreadLocal-based MDCs and thread pools can be dangerous:
We get a thread from the thread pool.Then we store some contextual information in MDC using MDC.put() or ThreadContext.put().We use this information in some logs, and somehow we forgot to clear the MDC context.The borrowed thread comes back to the thread pool.After a while, the application gets the same thread from the pool.Since we didn’t clean up the MDC last time, this thread still owns some data from the previous execution.
This may cause some unexpected inconsistencies between executions.
One way to prevent this is to always remember to clean up the MDC context at the end of each execution. This approach usually needs rigorous human supervision and is therefore error-prone.

인용 출처: https://www.baeldung.com/mdc-in-log4j-2-logback

 

Spring MVC는 스레드 풀에 스레드들을 만들어둔 뒤 요청이 올 때마다 만들어둔 스레드를 꺼내서 작업을 할당하고 반납한다. 그런데 MDC는 스레드 별로 할당되는 ThreadLocal을 사용하여 구현된다.

 

즉, clear()를 하지 않고 스레드를 반납하게 되면 다음 요청에서 똑같은 스레드를 꺼내서 사용할 경우 반납하기 전에 할당된 값이 남아있을 수 있다는 얘기다.

 

이 값이 크게 의미가 없을 수도 있지만 민감한 정보가 담긴 채로 반납될 경우 관계 없는 사용자에게 노출될 여지가 있다.

따라서 MDC를 사용한 후에는 마지막에 반드시 clear()를 호출하는 습관을 들이도록 하자. 

 

참조

https://www.baeldung.com/mdc-in-log4j-2-logback

https://www.vompressor.com/nginx-log/