표준 예외 처리에서 로깅까지 (1)

이전에 코드스쿼드에 공개해서 반응이 뜨거웠던(?) 표준 예외 처리가 있습니다.
하지만 실무를 하다 보니 부족한 점이 보이고, 고도화하는 김에 로깅까지 해야겠다고 생각해서 글을 작성해봅니다.
이전의 repository 도 남기지만 굳이 참고하지 않고 본 코드만 따라오셔도 무방합니다.

[deprecated] 표준 예외 처리

표준 예외 처리에서 로깅까지

Step 1. 리팩터링

이전에 작성한 표준 예외 처리를 리팩터링 하는 것으로 시작하겠습니다.

1. ExceptionAdvice 분리

한개로 운영하던 ExceptionAdvice 에서 공통으로 사용하는 메소드를 BaseExceptionAdvice 로 분리했습니다.

 

2. 테스트 케이스

오류 발생시 logId 로 원인을 추적할 수 있습니다.

 

이 정도로 장애 원인을 추적할 수 있나?

실무에서는 장애를 추적하기 위해 장애 난 시점만이 아닌 연관된 흐름을 봐야 합니다.
하지만 Step 1 에서는 logId 가 에러 발생 시점에만 존재하기 때문에 동시에 요청이 들어온다면 추적이 어렵습니다.

다음 Step에서 MDC를 활용해서 개선해보겠습니다.

 

Step 2. MDC로 개선하기

MDC (Mapped Diagnostic Context)

멀티 쓰레드 로깅에 활용되는 기술인 NDC (Nested Diagnostic Context)에 java.util.map의 적용으로 사용성을 높인 기술로
각 쓰레드 별로 별도의 로깅 쓰레드를 정적 메서드로 관리할 수 있습니다.
현재 log4j와 logback에서만 MDC 기능을 제공하고 있습니다.

1. MDC 적용

매우 쉽습니다!
Filter에서 transactionId를 UUID로 생성하고 map을 사용하듯이 넣어주면 됩니다.

사용 역시 map과 같습니다.
하지만 여전히 필요한 곳에서 MDC를 호출해줘야 되기에 불편합니다.

@Component
public class MdcLogEnhancerFilter implements Filter {

    @Override
    public void doFilter(ServletRequest servletRequest, ServletResponse servletResponse, FilterChain filterChain)
        throws IOException, ServletException {
        MDC.put("transactionId", UUID.randomUUID().toString());
        filterChain.doFilter(servletRequest, servletResponse);
    }

    @Override
    public void destroy() {
        MDC.clear();
        Filter.super.destroy();
    }
}


@GetMapping("/api/test")
public void test() {
    System.out.println("system out");
    log.info("### log info");
    log.info("### MDC transactionId={}", MDC.get("transactionId"));
    throw new RuntimeException("test!! " + MDC.get("transactionId"));
}

어느 예제에서는 Interceptor에서 구현했지만, 저는 요청의 시작인 Filter부터 관리를 하고 싶어 Filter에 구현했습니다.

 

2. console logging pattern 설정

logging pattern 은 logback의 기본 pattern을 참고했습니다. Link

중요한 부분은 [%mdc{transactionId:--}] 입니다.

// application.yml

logging:
  pattern:
    console: '%clr(%d{${LOG_DATEFORMAT_PATTERN:yyyy-MM-dd HH:mm:ss.SSS}}){faint} %clr(${LOG_LEVEL_PATTERN:-%5p}) %clr(${PID:- }){magenta} %clr(---){faint} %clr([%15.15t]){faint} %clr(%-40.40logger{39}){cyan} %clr(:){faint} [%mdc{transactionId}] %m%n${LOG_EXCEPTION_CONVERSION_WORD:%wEx}'

 

3. 예외 처리 개선

Step 1 에서는 BaseExceptionAdvice에서 UUID를 만들었습니다.
하지만 이제는 MDC를 활용해서 개선할 수 있습니다.

public class ErrorResponse {

    private final String code;
    private final String message;
    private final LocalDateTime time = LocalDateTime.now();
    private final String transactionId = MDC.get("transactionId");
    private final List<FieldError> errors;

    public static ErrorResponse of(ErrorCode errorCode, BindingResult bindingResult) {
        return ErrorResponse.builder()
            .code(errorCode.name())
            .message(errorCode.getReason())
            .errors(FieldError.of(bindingResult))
            .build();
    }
    ...
}

다음은 BaseExceptionAdvice에서 UUID 생성 대신 exception trace를 출력하도록 변경합니다.
필요에 따라 excetption을 모두 출력하지 않고 getStackTrace()를 가져올 수도 있습니다.

 

public abstract class BaseExceptionAdvice {

    protected void preHandle(Exception ex) {
        log.error("### message={}, cause={}", ex.getMessage(), ex.getCause(), ex);
    }
}

이제 개선된 생성자와 preHandle에 맞게 exceptionAdvice를 변경해 줍니다.

 

public class BasicExceptionAdvice extends BaseExceptionAdvice {

    ...

    @ExceptionHandler(Exception.class)
    @ResponseStatus(HttpStatus.INTERNAL_SERVER_ERROR)
    protected ErrorResponse handleException(Exception ex) {
        preHandle(ex);
        return ErrorResponse.of(UNKNOWN);
    }
}

에러가 발생해도 깔끔하게 나옵니다!

 

하지만..

비동기 로직에서는 의도와는 다르게 MDC에 넣은 값이 출력되지 않습니다!
무슨 설정이 빠진 걸까요?

비동기에서의 MDC 적용은 다음으로 이어집니다.