로깅 그리고 MDC
해당 내용은 WifiObserver라는 와이파이 공유기의 접속 목록을 크롤링 하여 해당 정보를 활용하는 프로젝트를 수행하며 공부한 내용입니다.
이전까지 로그에 대해서 크게 신경 쓰지 않았던 것 같다.
그래서 API 요청, SQL 문과 같이 가장 기본적인 요소들에 대해서만 로깅을 하였다.
"멀티 모듈 구조이고, 멀티 스레드를 활용하여 외부 페이지를 크롤링한다."
여기에 추후 배치도 추가된다.
위와 같은 기능 구현 사항이 있는 현재 프로젝트에서 로그를 제대로 남기지 않는다면 문제가 터졌을 때 대처하지 못할 것 같다는 생각이 들었다.
그래서 이번 프로젝트의 경우 아래 두 가지 기준으로 로그를 구현하였다.
- 모듈 단위로 로그를 남깁니다. ( 요청 -> 모듈 -> 응답 )
- 제어하지 못하는 곳에는 로그를 남깁니다.
모듈 단위로 로그를 남깁니다.
우선 첫 번째 기준인 "모듈 단위로 로그를 남깁니다."을 어떻게 구현하였는지 알아보자.
모듈을 기준으로 생각해 보면 모듈이 외부와 소통하는 것은 서비스 부분이라 생각하였다.
그렇기에 서비스가 모인 패키지를 포인트 컷으로 잡았다.
@Pointcut(value = "execution(* com.wifi.observer.client.wifi.client.*.*(..))")
public void wifiClientPointCut() {}해당 포인트 컷을 통해 정상적인 경우 로그를 기록하는 어드바이스
@Around("wifiClientPointCut()")
public Object clientLog(ProceedingJoinPoint pjp) throws Throwable {
...
}그리고 예외를 처리하는 어드바이스를 구성하였다.
@AfterThrowing(pointcut = "wifiClientPointCut()", throwing = "ex")
public void clientExceptionLog(Throwable ex) {
clientExceptionHandlerMapper.handleClientConnectionException(ex);
}예외처리
우선 예외를 어떻게 처리하였는지부터 살펴보자.
컨트롤러에서 예외를 처리할 때 아래 두 어노테이션을 자주 보았을 것이다.
- @RestControllerAdvice
- @ExceptionHandler
위의 두 어노테이션의 사용 방법은 다음과 같다.
@ExceptionHandler에 선언한 예외를 @RestControllerAdvice를 선언한 클래스의 메서드에서 처리한다.
나름 간단히 예외를 처리할 수 있기에 이번 프로젝트에서도 위 두 어노테이션을 사용하고 싶었지만, 위의 두 어노테이션은 org.springframework.web.bind.annotation에 속하는 어노테이션이다.
즉, web 관련 의존성이 없다면 해당 어노테이션을 사용할 수 없다는 뜻이다.
커스텀 예외처리
그래서 만들었다.
커스텀으로 만들기 위해서는 총 4개의 클래스가 필요했다.
- @모듈Advice
- 모듈ExceptionAdvice
- @모듈ExceptionHandler
- 모듈ExceptionHandlerMapper
각 클래스를 설명하자면 우선 @모듈Advice는 모듈ExceptionHandlerMapper에서 모듈ExceptionAdvice를 구분하기 위한 마커 어노테이션이다.
모듈ExceptionAdvice는 @모듈ExceptionHandler에 선언된 예외를 처리하는 메서드가 있는 메서드다.
@모듈ExceptionHandler는 예외를 선언하기 위한 인터페이스 컨테이너다.
모듈ExceptionHandlerMapper는 @모듈Advice가 선언된 클래스를 구분하고 메서드를 실행하는 클래스다.
구현에 대해서 설명 하기 위해 적는 글은 아니기에 구현 링크를 남긴다.
그래서 이렇게 구현한 모듈ExceptionHandlerMapper를 위에서처럼 예외를 처리하는 어드바이스에서 실행하도록 하면 @ExceptionHandler와 @RestControllerAdvice를 사용하여 예외 처리하는 것과 동일하게 예외를 처리할 수 있다.
정상 로그
이제 정상적인 경우 로그를 기록하는 어드바이스를 살펴보자.
이때 고려해야 할 부분은 다음과 같다.
- 외부 모듈에서 해당 모듈을 호출하는 것인가?
- 로깅 출력형식은 어떻게 할 것인가?
MDC
본격적으로 "외부 모듈에서 해당 모듈을 호출하는 것인가?"에 관해 설명하기 전에 이번 로깅 구현의 특징 중 하나는 MDC를 사용하였다는 것이다.
MDC는 ThreadLocal에 의해 현재 쓰레드 범위 내에서만 사용할 수 있는 로그에 담을 정보를 저장할 수 있는 일종의 로그 정보 저장소라 할 수 있다.
하지만 이는 비동기 쓰레드와 호출한 쓰레드의 MDC 영역이 달라 서로 연관된 로그를 남기는 것이 불가능하다는 문제가 있는데 이에 대한 해결 방법은 링크로 남긴다.
구현
이제 MDC가 로깅 정보를 담는 저장소라는 것을 알았다.
그리고 해당 저장소에 모듈마다의 추적 아이디(모듈TraceId) 그리고 실행 시점에서의 추적 아이디(traceId)를 저장하여 로그를 추적할 것이다.
즉, 추적 아이디(traceId)가 존재하지 않는다면 그 시점이 시작 시점이라는 것이다.
이를 통해서 우리는 외부 모듈에서 해당 모듈을 호출하는 것인지를 판단 할 수 있다.
이러한 판단이 중요한 이유는 호출한 곳에서 MDC를 정리할 책임이 있기 때문이다.
만약 외부 모듈에서 호출하였다면 MDC를 정리할 책임이 외부 모듈에 있다.
해당 모듈에서 호출하였다면 로그를 출력한 후 MDC를 정리하여야 한다.
이를 제대로 정리하지 않는다면 OutOfMemory에 빠질 수 있다.
출력형식
그럼, 이제 "로깅 출력형식은 어떻게 할 것인가?"에 대해 생각해 보자.
우선 가장 기본적인 방법은 아래와 같이 구현하는 것이다.
log.info("result1 : {}, result2 : {}" , result.get1(), result.get2());하지만 이러한 방법은 추후 로그를 재가공하기도 어려울 뿐 아니라 로그 기록 유지 보수도 어렵게 만든다.
그렇기에 이번에 선택한 방법은 객체를 json 형식으로 출력하는 것이다.
ObjectMapper을 통해 객체를 json 형식으로 바꾸기 때문에 아래와 같이 통일된 형식의 log 포맷을 유지할 수 있을 것이다.
log.info("{}", json);추가로 수정이 생기더라도 객체만 수정하면 되기에 유지 보수 측면에서도 장점이 생긴다.
그리고 외부 모듈에서 호출한 경우 모듈에서의 로깅 결과를 MDC에 저장하여야 하는데 Json 형식의 값을 저장하면 외부 모듈에서도 이를 활용하기 쉽다는 장점도 있다.
이러한 고려 점을 고민하며 작성한 이번 프로젝트에서의 로깅 코드는 아래와 같다.
@Around("wifiClientPointCut()")
public Object clientLog(ProceedingJoinPoint pjp) throws Throwable {
long currentTimeMillis = System.currentTimeMillis();
String timeStamp = getTimeStamp(currentTimeMillis);
String traceId = UUID.randomUUID().toString();
/** ClientTraceId 설정 */
MDC.put(CLIENTTRACEID.getKey(), traceId);
/** 외부 모듈에서의 호출인지 확인 */
boolean isCalled = setIsCalled();
/** 외부 모듈의 호출이 아니라면 traceId에 clientTraceId와 동일한 값 설정 */
if (!isCalled) {
MDC.put(COMMON_TRACE_ID_KEY, traceId);
}
String className = getClassName(pjp);
String methodName = getMethodName(pjp);
String tag = isAsync(methodName);
/** 시작 로그 */
startLog(traceId, methodName, pjp);
/** 메서드 실행 */
Object proceed = pjp.proceed();
Map<String, String> mdc = MDC.getCopyOfContextMap();
ClientLogDto clientLogDto =
ClientLogDto.builder()
.timestamp(timeStamp)
.duration((System.currentTimeMillis() - currentTimeMillis) + "ms")
.actor(className + "." + methodName)
.mdc(mdc)
.tag(tag)
.message("success client request")
.build();
/** 종료 로그 */
/** json 형식으로 변환 */
String logValue = objectMapper.writeValueAsString(clientLogDto);
if (!isCalled) {
log.info("{}", logValue);
MDC.clear();
} else {
MDC.put("clientLog", logValue);
}
return proceed;
}제어하지 못하는 곳에는 로그를 남깁니다.
이제 마지막으로 "제어하지 못하는 곳에는 로그를 남깁니다."는 어떻게 구현하였는지 알아보자.
이는 이전과 다르게 하나의 패키지에 모여있지 않을 수 있다.
그렇기에 어노테이션을 활용하여 제어하지 못하는 곳을 표시하였다.
그리고 어노테이션을 기준으로 하는 포인트 컷을 만들었다.
@Pointcut("@annotation(ClientTrace)")
public void clientTracePointCut() {}이후 로깅 정보를 저장하는 어드바이스와 출력하는 어드바이스를 만들어 로그를 구현하려 하였다.
@Before("clientTracePointCut()")
public void setMDCLog(JoinPoint joinPoint) {
...
}
@After(value = "clientTracePointCut()")
public void getMDCLog(JoinPoint joinPoint) {
...
}파라미터 타입이 모두 다르다
하지만 이때 문제는 어노테이션을 붙인 메서드의 파라미터 종류가 모두 다르다는 것이다.
그렇기에 이를 처리하기 위한 처음 구현은 아래와 같았다.
if(source instanceof ADto) {
... ADto 타입 정보 저장 메서드에서 ...
} else if (source instanceof BDto) {
... BDto 타입 정보 저장 메서드에서 ...
} 이와 같이 처리하면 파라미터 종류가 늘어남에 따라 복잡한 코드가 되고 관리하기 어려워질 것이 분명하였다.
그렇기에 Dto들을 하나로 묶을 방법이 필요하였고 로그 정보를 기록하는 인터페이스(LogAble)를 선언하고 모두 구현하게 하여 타입을 통일 시키는 방법을 선택하였다.
if(source instanceof LogAble) {
... LogAble 타입 저장 메서드에서 ...
}위의 코드에서 볼 수 있듯 이제는 어떤 Dto 타입이든 상관없이 LogAble을 구현하였는지만 확인하고 LogAble의 메서드를 활용하여 로그 정보를 기록할 수 있도록 수정하였다.
