티스토리 뷰
이번에는 멀티 쓰레드 환경에서 요청 쓰레드 별로 식별가능한 로그를 남기는 방법에 대해 알아보도록 하겠습니다. 실무에서 유용하게 사용될 수 있으니 참고하시면 좋을 것 같습니다.
1. 로그가 뒤섞이는 문제 상황 소개 및 해결 방법(MDC)
[ 로그가 뒤섞이는 문제 상황 소개 ]
서비스를 운영하다 보면 로그를 통해 문의 대응 및 모니터링 등을 진행하게 된다. 그런데 문제는 멀티 쓰레드 환경에서 여러 동시에 요청이 처리되기 때문에 동일한 요청에 대한 로그가 연속적으로 쌓이는 것이 아니라, 순서없이 쌓인다는 것이다.
예를 들어 사용자 추가를 위한 요청이 동시 다발적으로 와서 다음과 같이 로그가 남았다고 하자. 아래의 로그를 보면 1개의 요청에 대한 로그가 쭉 남지 않고, 뒤섞임을 확인할 수 있다.
위의 로그를 요청 별로 묶어보면 다음과 같다. 우리는 요청 별로 로그를 확인해야 하는데, 로그가 뒤섞여서 정상적으로 파악이 어려운 것이다. 이를 위해 요청(Request) 별로 고유 값을 부여하고, 로그에 함께 출력되도록 하면 문제를 해결할 수 있다.
[ MDC(Mapped Diagnostic Context) 란? ]
MDC(Mapped Diagnostic Context)는 현재 실행중인 쓰레드에 메타 정보를 넣고 관리하는 공간이다. MDC는 내부적으로 Map을 관리하고 있어 (Key, Value) 형태로 값을 저장할 수 있다. 메티 정보를 쓰레드 별로 관리하기 위해 내부적으로는 쓰레드 로컬을 사용하고 있다.
스프링 애플리케이션에서는 요청(Request)이 오면 MDC에 uuid를 넣고 로그에 이를 포함시키면 된다. 그리고 uuid로 로그를 찾으면 1개의 요청에 대한 로그들을 살펴볼 수 있는데, 이를 실제로 적용해보도록 하자.
2. 멀티쓰레드 환경에서 MDC를 사용해 요청 별로 식별가능한 로그 남기기
[ MDC 필터 구현 및 로그 남기기 ]
스프링에서 MDC에 uuid를 만들어 넣을만한 곳은 필터, 인터셉터 등이 있는데 가장 앞단인 필터에 적용하는 것이 좋다. 그리고 필터들 중에서도 가장 먼저 등록되도록 해주면 좋다. 이러한 필터를 구현하면 다음과 같다.
@Component
@Order(Ordered.HIGHEST_PRECEDENCE)
class MDCLoggingFilter implements Filter {
@Override
public void doFilter(final ServletRequest servletRequest, final ServletResponse servletResponse, final FilterChain filterChain) throws IOException, ServletException {
final UUID uuid = UUID.randomUUID();
MDC.put("request_id", uuid.toString());
filterChain.doFilter(servletRequest, servletResponse);
MDC.clear();
}
}
여기서 주의할 점은 doFilter가 끝나서 나오면 clear를 해준다는 것이다. Spring MVC는 쓰레드 풀에 쓰레드들을 만들어 두고, 요청이 오면 쓰레드를 사용해 요청을 처리하고 반납한다. 그런데 MDC는 쓰레드 별로 저장되는 쓰레드 로컬을 사용하므로, 요청이 완료될 때 Clear를 해주지 않으면 다른 요청이 이 쓰레드를 재사용할 때 이전 데이터가 남아있을 수 있다. 실수로 주민번호와 같은 데이터를 MDC에 저장하고 삭제하지 않으면 다른 사용자가 모르는 사람의 주민번호를 얻는 상황이 생길 수 있다. 그러므로 반드시 Clear 해주어야 한다.
추가로 해당 필터는 다른 곳에서 사용될 필요가 없으므로 default 접근 제어자로 선언해주었다.
그러면 이를 실제 로그에서 출력할 수 있어야 한다. 로그를 관리하는 파일에서는 %X{key}로 적어주면 된다. 그런데 스프링 애플리케이션이 실행될 때에는 필터를 거치지 않으므로 “request_id”가 없어 다음과 같이 빈값으로 로그가 찍힌다.
그러므로 기본값을 지정해주면 좋을텐데, 사용하는 로거마다 기본값을 지정해주는 방법이 다르다. 대표적으로 자주 사용되는 Logback과 Log4J2만 해당 방법을 정리하면 다음과 같다.
// Logback
패턴: [%X{<Key>:-<Default>}]
적용 예시: [%X{request_id:-startup}] %d{HH:mm:ss.SSS} [%t] %-5level %logger{36} - %msg%n
// Log4J2
패턴: [%equals{%X{<Key>}}{}{<Default>}]
적용 예시: [%equals{%X{request_id}}{}{startup}] %d{HH:mm:ss.SSS} [%t] %-5level %logger{36} - %msg%n
그리고 이를 적용한 결과의 로그를 살펴보면 다음과 같다.애플리케이션이 시작할 때는 startup이라는 기본값으로 로그가 찍히고, 이후의 요청들에는 고유한 값이 부여됨을 확인할 수 있다.
단일 서버 내의 로그에 대해서는 위와 같이 MDC를 적용하면 해결할 수 있다. 하지만 오늘과 같이 외부 API 통신이 많은 분산 환경인 경우에는 로그 추적이 어려운데, 이를 위해 spring-cloud-sleuth 와 같은 기술이 있으니 참고하도록 하자.
3. Nginx와 톰캣 애플리케이션에서 동일한 식별자 사용하기
[ Nginx에 request_id 설정하기 ]
일반적으로 서버를 구축할 때는 Tomcat만 사용하는 것이 아니라 Nginx와 같은 웹서버를 앞단에 두고 사용하는 경우가 많다.
그렇기 때문에 Nginx로그와 Tomcat(애플리케이션) 로그를 함께 봐야하는 경우가 많은데, 이때 Nginx와 Tomcat이 동일한 request_id를 공유하면 로그 파악에 매우 용이해진다. Nginx 1.11.0부터는 요청에 대한 uid(unique id)를 제공해줘서 요청 구분이 가능하다. 다음과 같이 로그 포맷에 $request_id를 남기면 32자리의 hexdecimal(16bytes) 값으로 로그가 남게 된다.
log_format main '$request_id $remote_addr - $remote_user [$time_local] "$request" '
'$status $body_bytes_sent "$http_referer" "$request_time" '
'"$http_user_agent" "$http_x_forwarded_for"'
'"$ssl_protocol/$ssl_cipher" "$content_length"'
'"$request_length"' ;
d0c2fcfc6449f291883c979881bcf356 10.25.36.98 - - [28/Dec/2022:11:39:00 +0900] "POST /test HTTP/2.0" 200 100 "-" "0.293" "Mozilla/5.0 (Windows NT 10.0; Win64; x64) AppleWebKit/537.36 (KHTML, like Gecko) Chrome/108.0.0.0 Safari/537.36 Edg/108.0.1462.54" "-" "TLSv1.3/TLS_AES_256_GCM_SHA384" "44" "276"
위의 로그에서 d0c2fcfc6449f291883c979881bcf356가 request_id에 해당하는 값인데, 이를 애플리케이션에서 받아서 동일하게 남겨준다면 로그 파악이 쉬워진다. 그러므로 tomcat으로 요청을 프록시할 때 request_id 헤더 값을 추가하도록 하면 톰캣에서도 해당 값을 받아서 사용할 수 있다. 이를 위해서는 다음과 같은 proxy_set_header 설정이 Nginx에 추가되어야 한다.
proxy_set_header X-RequestID $request_id;
그리고 애플리케이션에서는 해당 헤더값을 꺼내서 MDC에 넣어주면 된다.
@Component
@Order(Ordered.HIGHEST_PRECEDENCE)
class MDCLoggingFilter implements Filter {
@Override
public void doFilter(final ServletRequest servletRequest, final ServletResponse servletResponse, final FilterChain filterChain) throws IOException, ServletException {
String requestId = ((HttpServletRequest)servletRequest).getHeader("X-RequestID");
MDC.put("request_id", StringUtils.defaultString(requestId, UUID.randomUUID().toString().replaceAll("-", "")));
filterChain.doFilter(servletRequest, servletResponse);
MDC.clear();
}
}
회사에서 업무를 진행하면서 로그가 뒤섞여 문의 대응 등을 하는데 어려움을 겪었습니다. 해결 방법은 떠올라도 "MDC"라는 키워드를 찾는게 어려워서 대응이 늦었었는데, 다른 분들은 쉽게 이런 상황을 해결하셨으면 좋겠습니다!
감사합니다:)
