[클러버] Spring Logging 전략 수립하기

https://minjun98.tistory.com/133

[클러버] 운영을 위한 초기 인프라 구축 과정

 

앞선 블로그 글에서 언급했듯이, 실제 운영 상의 문제 발생 시 빠르게 원인을 파악하고 대응하기 위해 적절한 로깅 전략을 수립하여 사용자들의 요청 및 응답 정보를 통일된 형식으로 상세히 기록하는 것의 필요성을 느꼈다. 

 

목차는 다음과 같다. 

1. 로깅 포맷 구성 

2. 로깅 위치

3. 비동기 작업 로깅

4. 로깅 구현 방법(요청, 응답 캐싱)

 

1. 로깅 포맷 구성

@Builder
public record HttpLogMessage(
        String httpMethod,
        String requestUri,
        HttpStatus httpStatus,
        long elapsedTime,
        Map<String, String> headers,
        Map<String, String> requestParam,
        String requestBody,
        String responseBody
) { }

• 로그 포맷은 다음과 같이 하나의 클래스에서 구성하였다.
• 요청 
  • http method
  • request uri: 요청 api (ex. /api/v1/clubs)
  • headers: 요청 내용에 포함된 http header 값
  • request param: 요청시 uri에 포함되어 있는 query string 내용
  • request body: 요청 본문(body)에 해당하는 내용
• 응답
  • http status code: http 응답에 대한 응답코드
  • response body: 응답 본문(body)
• 요청 시간
  • elapsed time: 요청 ~ 응답 처리하는데 걸린 시간

 

2. 로깅 위치

로깅 처리는 가장 첫 번째 Filter에서 수행했다. 해당 Filter의 위치는 사용자 요청 직후, 응답 직전인데, 다음과 같은 장점이 존재한다고 생각했다.

 

• 사용자 요청 직후
  • 모든 로그에서 요청 쓰레드의 고유 ID를 포함할 수 있다.
    
    • 필터 맨 앞단에 위치
      • Security Filter Chain의 order는 기본적으로 -100이기 때문에, 보통 필터 체인의 가장 앞단에 위치한다. 만약 Logging Filter가 이보다 뒤에 배치된다면, 요청 쓰레드의 ID를 로깅하는 것이 불가능해진다.
      • 이를 해결하기 위해 @Order(Ordered.HIGHEST_PRECEDENCE)를 사용하여 Logging Filter가 가장 앞에서 동작하도록 설정했다.  

        

    • Logback 연동
      • Logback에서 요청 쓰레드별 고유 ID를 접근할 수 있게하기 위해 MDC에 추가하였다.
      • MDC는 Thread Local 방식으로 동작하며, Logback appender에서 접근이 가능하다. 이를 통해, Logback의 통일된 포맷으로 포함시켜 로깅할 수 있다.

        @Slf4j
        @Component
        @Order(Ordered.HIGHEST_PRECEDENCE)
        public class ReqResLoggingFilter extends OncePerRequestFilter {
          	
            @Override
            protected void doFilterInternal(HttpServletRequest request, HttpServletResponse response, FilterChain filterChain){
                //1. 요청 쓰레드 고유 ID 생성
                String requestId = UUID.randomUUID().toString().substring(0, 8);
                
                //2. MDC에 저장
                MDC.put(REQUEST_ID, requestId);
        
                //3.Filter 및 비즈니스 로직 수행 (Logback을 통해 로깅 수행)
                filterChain.doFilter(cachingRequestWrapper, cachingResponseWrapper);
        		
                //4. 요청, 응답 로깅 
                log.info(HttpLogMessage.createHttpLogMessage(cachingRequestWrapper, cachingResponseWrapper, endTime - startTime).toString());
                
                //5. 요청 쓰레드 고유 ID 삭제
                MDC.remove(REQUEST_ID);
           		}
           }

        

        logback-spring.xml

• 사용자 응답 직전
  
  • 모든 위치에서의 예외 내용을 포함하여 로깅할 수 있다.
    • 만약, LoggingFilter보다 앞에 다른 필터가 존재하고 해당 필터에서 예외가 발생한다면, 해당 예외는 LoggingFilter까지 도달하지 못하기 때문에 관련 내용을 로깅하기 어려워진다.
    • 현재 프로젝트에서는 주로 JWT 관련 Custom Exception을 로깅한다.
      • JWTExceptionFilter(예외 처리) → JWTTokenFilter(인증 및 인가) 순서로 필터가 구성되어 있다.
        • JWTTokenFilter에서 CustomException이 발생하면 이를 JWTExceptionFilter에서 catch하여,
          에러 내용을 응답(HttpServletResponse)에 포함시켜 반환한다.
        • 가장 앞단에 위치한 LoggingFilter에서 이 예외 응답까지 포함해 로깅한다.

 

3. 비동기 작업 로깅

MDC는 ThreadLocal 방식을 사용하기 때문에 요청 쓰레드마다 고유한 Context를 유지할 수 있다.
하지만 비동기 처리를 위해 TaskExecutor를 사용하면 새로운 쓰레드에서 작업이 실행되기 때문에, 기존 쓰레드의 Context가 전달되지 않는 문제가 발생한다.

위 사진은 이메일 비동기 전송 작업시 발생한 예외를 로깅했는데, 비동기 작업 쓰레드 ID에 빈값이 들어가 있는 것을 확인할 수 있다. 

 

TaskDecorator 활용

public class ClonedTaskDecorator implements TaskDecorator {
    @Override
    public Runnable decorate(Runnable runnable) {
        Map<String, String> callerThreadContext = MDC.getCopyOfContextMap();
        return () -> {
            MDC.setContextMap(callerThreadContext);
            runnable.run();
        };
    }
}

decorate 함수는 현재 쓰레드의 MDC(Context)를 복사하여 저장하는 작업을 수행한다.

이 함수는 기존에 실행할 쓰레드를 Runnable을 인자로 받아, MDC 복사 후 기존 쓰레드를 수행할 수 있는 새로운 Runnable을 반환한다.

ThreadPoolExecutor - execute 메서드

ThreadPoolExecutor을 통해서 비동기 작업이 수행될 때의 호출되는 execute 함수이다.

앞서 구현한 ClonedTaskDecorator를 통해 MDC 복사 및 저장 작업이 추가된(데코레이트)된 Runnable을 반환받아 이를 실행한다. 이를 통해 기존 쓰레드의 MDC값을 새로운 쓰레드의 MDC값에 복사, 저장한 후 Runnable을 실행할 수 있게 된다.

 

에러 로그에서도 기존 쓰레드의 고유 ID가 출력되는 것을 볼 수 있다.

 

4. 요청, 응답 캐싱 

Stream에서 요청 데이터 read 할때, 한 번 데이터를 읽으면 다시 해당 데이터를 읽지 못하는 문제가 있다. 이를 해결하기 위해

ContentCachingRequestWrapper, ContentCachingResponseWrapper로 HttpServletRequest, HttpServletResponse를 감싸 캐싱(OutputStream에 쓰기)한 데이터로 로깅을 수행한다.

@Slf4j
@Component
@Order(Ordered.HIGHEST_PRECEDENCE)
public class ReqResLoggingFilter extends OncePerRequestFilter {

public static final String REQUEST_ID = "request_id";

    @Override
    protected void doFilterInternal(HttpServletRequest request, HttpServletResponse response, FilterChain filterChain) throws ServletException, IOException {
        // 1. 원본 Request, Response 감싸기 
        ContentCachingRequestWrapper cachingRequestWrapper = new ContentCachingRequestWrapper(request);
        ContentCachingResponseWrapper cachingResponseWrapper = new ContentCachingResponseWrapper(response);

        //생략 
        
        // 2. 감싼 Request, Response 다음 필터 수행 (Controller에서 Request 읽기 수행 & 데이터 캐싱)
        filterChain.doFilter(cachingRequestWrapper, cachingResponseWrapper);
      
      	//생략

        try {
        	//3. 캐싱된 데이터 포함한 로그 포맷 구성 후 로깅 수행
        	log.info(HttpLogMessage.createHttpLogMessage(cachingRequestWrapper, cachingResponseWrapper, endTime - startTime).toString());
       	}
            //4. 원본 Response에 캐싱된 데이터 복사 후 전달 
            cachingResponseWrapper.copyBodyToResponse();
        } catch (Exception e) {
            log.error("[로깅 실패] : " + e);
            }
        //생략
    	}
    }

public static HttpLogMessage createHttpLogMessage(ContentCachingRequestWrapper requestWrapper, ContentCachingResponseWrapper responseWrapper, long elapsedTime) {
    return HttpLogMessage.builder()          	
            // 캐싱해둔 데이터 반환
            .requestBody(new String(requestWrapper.getContentAsByteArray()))
            .responseBody(new String(responseWrapper.getContentAsByteArray()))
            .build();
}

 

ContentCachingRequestWrapper

ContentCachingRequestWrapper - read()

Controller에서 ContentCachingRequestWrapper의 요청 데이터를 읽을 때, Outputstream인 cachedContent에 write(캐싱)한 후 읽은 데이터를 return한다.

ContentCachingRequestWrapper - getContentAsByteArray()

LoggingFilter에서는 위 함수를 통해 앞에서 캐싱한 데이터를 반환하여 로깅하기 때문에 읽었던 데이터를 다시 가져올 수 있다.

 

 ContentCachingResponseWrapper

ContentCachingResponseWrapper - copyBodyToResponse

Logging Filter에서 로깅 후 위 함수를 호출하여 클라이언트에 응답을 반환한다. 코드를 간단히 보면,

1. 감싸고 있던 원본 HttpServletResponse을 반환한다. 

2. 캐싱된 데이터를 원본 HttpServletResponse에 쓴다.

 

마무리  

앞선 전략들을 통해 다음과 같은 개선이 있었다고 생각한다.

 

1. 로깅 정보 누락 최소화

로깅 필터를 필터 체인의 가장 앞단에 배치하여 이후 모든 컴포넌트에서의 요청 쓰레드 ID와 예외처리를 로그에 포함시켰다.

 

2. 통일된 포맷으로 관리

로그 포맷을 하나의 클래스로 관리하게 구성하였다. 또한, MDC에 저장된 요청 Thread ID를 Logback Appender에 포함시켜 통일된 포맷으로 관리할 수 있게 구현하였다.