요청, 응답 로그에 correlationId 를 추가하자!

문제 정의

Caution

요청/응답 로그에 correlationId 가 찍히지 않는 문제가 발생
현재 우리는 로그들을 하나의 요청으로 그룹화 하기 위해 로그들에 correlationId 를 함께 출력 중이다.
그런데 HTTP 요청 / 응답 정보를 출력하는 로그들에서 correlationId 이 출력되지 않고 있었다.

• 에러 로그에는 correlationId 가 잘 나오지만 [Request]/[Response] 로그에는 값이 비어있는 모습이다.

원인 파악

correlationId 생성 확인

현재 correlationId 는 MDCFilter 클래스에서 생성해 주고 있다. 우선, 이 값이 잘 생성되고 있는지 correlationId 의 생존주기를 확인하고 있다.

@Slf4j  
@Component  
public class MDCFilter implements Filter {  
    private final String CORRELATION_ID = "correlationId";  
  
    @Override  
    public void doFilter(ServletRequest request, ServletResponse response, FilterChain chain)  
            throws IOException, ServletException {  
        String correlationId = generateCorrelationId();  

        log.info("USE {} : {}", CORRELATION_ID, correlationId); // correlationId 생성 확인 
        MDC.put(CORRELATION_ID, correlationId);  
		chain.doFilter(request, response);  
        log.info("END {} : {}", CORRELATION_ID, correlationId); // correlationId 삭제 확인   
        MDC.clear();  
    }  

    //...
}

• 출력 확인

[INFO][08-21 14:04:43][        ][c.g.logger.MDCFilter] USE correlationId : 45c20ce6 
[INFO][08-21 14:04:43][45c20ce6][c.g.e.GlobalExceptionHandler] [CodeZapException] codezap.global.exception.CodeZapException가 발생했습니다. 
codezap.global.exception.CodeZapException: 쿠키가 없어서 회원 정보를 찾을 수 없습니다. 다시 로그인해주세요.
        at 
        //...
        at java.base/java.lang.Thread.run(Thread.java:842)
[INFO][08-21 14:04:43][45c20ce6][c.g.logger.MDCFilter] END correlationId : 45c20ce6 
[INFO][08-21 14:04:43][        ][c.g.l.RequestResponseLogger] [Request] GET /templates, 헤더 값: content-type : application/json
        //... 
 요청 바디:  
[INFO][08-21 14:04:43][        ][c.g.l.RequestResponseLogger] [Response] Status: 401, Duration: 62ms, 헤더 값: Vary : Origin
        //...

Caution

correlationId 생성 주기 확인
정상적으로 correlationId 가 잘 생성되는 것을 확인하였다.
그런데, 요청 / 응답 내용을 출력하는 순간이 correlationId 삭제 이후이다.

correlationId 를 생성하는 MDCFilter 보다 요청 / 응답 로그를 출력하는 RequestResponseLogger 가 더 먼저 실행되는 것이 문제였다.

여기서 잠깐!

Tip

분명 로컬에서는 정상적으로 correlationId 가 보였는데, 뭐가 다른거죠?!

서버에서 사용하는 파일은 gradle bootJar 로 jar 파일을 생성 후 java -jar XXX 로 서버를 실행하고 있다.
이와 똑같이 gradle bootJar 를 사용해 jar 파일을 생성 후 터미널에서 java -jar XXX 를 실행하면 로컬에서도 똑같은 문제가 발생함을 확인할 수 있다.

결국 bootJar 와 단순 인텔리제이 실행은 무언가 다르다는 건데...
뭐가 다른지는 아직 몰라용~~ :ㅇ

조금 더 확실하게!

더 확실히 하기 위해 RequestResponseLogger 에도 로그를 찍어 보자.

@Slf4j  
@Component  
public class RequestResponseLogger extends OncePerRequestFilter {  
    @Override  
    protected void doFilterInternal(HttpServletRequest request, HttpServletResponse response, FilterChain filterChain)  
            throws ServletException, IOException {  

		//...
		
        log.info("REQUEST / RESPONSE LOG START");  
        filterChain.doFilter(requestWrapper, responseWrapper);  
        log.info("REQUEST / RESPONSE LOG END");  

		//...
  
        log.info("[Request] {} {}, 헤더 값: {} \n 요청 바디: {}", request.getMethod(), request.getRequestURI(),  
                getHeaderAndValue(requestWrapper), getBodyAsUtf8String(requestWrapper.getContentAsByteArray()));  
        log.info("[Response] Status: {}, Duration: {}ms, 헤더 값: {} \n 응답 바디: {}", response.getStatus(), duration,  
                getHeaderAndValue(responseWrapper), getBodyAsUtf8String(responseWrapper.getContentAsByteArray()));  
  
        responseWrapper.copyBodyToResponse();  

		//...
    }  
}

요청을 보내면 다음과 같은 로그가 찍힌다.

[INFO][08-21 14:04:43][        ][c.g.l.RequestResponseLogger] REQUEST / RESPONSE LOG START 
[INFO][08-21 14:04:43][        ][c.g.logger.MDCFilter] USE correlationId : 45c20ce6 
[INFO][08-21 14:04:43][45c20ce6][c.g.e.GlobalExceptionHandler] [CodeZapException] codezap.global.exception.CodeZapException가 발생했습니다. 
codezap.global.exception.CodeZapException: 쿠키가 없어서 회원 정보를 찾을 수 없습니다. 다시 로그인해주세요.
        at 
        //...
        at java.base/java.lang.Thread.run(Thread.java:842)
[INFO][08-21 14:04:43][45c20ce6][c.g.logger.MDCFilter] END correlationId : 45c20ce6 
[INFO][08-21 14:04:43][        ][c.g.l.RequestResponseLogger] REQUEST / RESPONSE LOG END 
[INFO][08-21 14:04:43][        ][c.g.l.RequestResponseLogger] [Request] GET /templates, 헤더 값: content-type : application/json
        //...

문제 정의가 확실해 졌으니, 필터의 순서를 변경하자.

필터 순서 변경

필터 순서는 @Order 어노테이션을 사용해 손쉽게 지정해 줄 수 있다.
우리는 correlationId 를 먼저 생성 후 요청 / 응답 로그를 출력해야 하므로 MDCFilter 에는 @Order(1) 을, RequestResponseLogger 에는 @Order(2) 를 사용해 순서를 지정해 주었다.

[INFO][08-21 14:34:57][        ][c.g.logger.MDCFilter] USE correlationId : bf3a04e2 
[INFO][08-21 14:34:57][bf3a04e2][c.g.l.RequestResponseLogger] REQUEST / RESPONSE LOG START 
[INFO][08-21 14:34:57][bf3a04e2][c.g.e.GlobalExceptionHandler] [CodeZapException] codezap.global.exception.CodeZapException가 발생했습니다. 
codezap.global.exception.CodeZapException: 쿠키가 없어서 회원 정보를 찾을 수 없습니다. 다시 로그인해주세요.
        at codezap.auth.manager.CookieCredentialManager.checkCookieExist(CookieCredentialManager.java:32)
        //...
        at java.base/java.lang.Thread.run(Thread.java:842)
[INFO][08-21 14:34:57][bf3a04e2][c.g.l.RequestResponseLogger] REQUEST / RESPONSE LOG END 
[INFO][08-21 14:34:57][bf3a04e2][c.g.l.RequestResponseLogger] [Request] GET /templates, 헤더 값: content-type : application/json
        //...
 요청 바디:  
[INFO][08-21 14:34:57][bf3a04e2][c.g.l.RequestResponseLogger] [Response] Status: 401, Duration: 49ms, 헤더 값: Vary : Origin
        //...
[INFO][08-21 14:34:57][bf3a04e2][c.g.logger.MDCFilter] END correlationId : bf3a04e2 

설정이 잘 된다!