비동기 작업에서 사라진 MDC 전달하기

구조화 로그를 도입한 뒤 동기 요청과 비동기 작업의 로그를 비교하다가 빈 필드를 발견했습니다. 요청을 처리할 때는 남아 있던 사용자 정보와 요청 ID가 비동기 작업에서는 보이지 않았습니다. 같은 로그 포맷을 사용하고 있었지만, 작업을 실행하는 스레드가 달랐습니다.

스레드마다 다른 MDC

MDC는 로그에 요청 ID 같은 정보를 함께 남길 때 사용하는 키·값 저장소입니다. Logback에서는 스레드별로 관리되므로 요청 스레드에서 넣은 값이 다른 스레드에 자동으로 전달되지 않습니다. 로그 패턴이나 JSON 로깅 설정에서 해당 값을 출력하도록 구성해야 로그에도 나타납니다.

@Async나 별도 executor로 작업을 넘기면 실행 스레드가 바뀝니다. 요청을 제출한 쪽에는 MDC가 있어도 실제 작업을 실행하는 쪽에는 없을 수 있습니다.

TaskDecorator 적용

각 비동기 메서드에서 MDC를 복사할 수도 있지만, 그러면 같은 처리가 여러 곳에 들어갑니다. 한곳이라도 빠뜨리면 다시 로그가 끊깁니다. 그래서 executor의 작업 실행 전후를 감싸는 TaskDecorator를 적용했습니다.

작업이 제출될 때 요청 스레드의 MDC를 복사하고, 실행 직전에 작업 스레드에 설정하는 방식입니다. 이 decorator를 설정한 executor를 사용하는 작업에 같은 처리를 적용할 수 있습니다.

작업 종료 후 정리

값을 전달하는 것만으로는 충분하지 않았습니다. 스레드 풀은 스레드를 재사용하므로, 작업이 끝난 뒤 MDC를 남겨두면 다음 작업의 로그에 이전 요청 정보가 섞일 수 있습니다. 예외가 발생하더라도 정리하도록 finally에서 처리해야 합니다.

아래는 설명용 예시입니다. 작업 실행 전의 MDC도 저장해 뒀다가 복원하도록 구성했습니다. 실행 정책에 따라 호출한 스레드에서 작업이 실행되는 경우에도 기존 값을 지우지 않기 위해서입니다.

public class MdcTaskDecorator implements TaskDecorator {
    @Override
    public Runnable decorate(Runnable task) {
        Map<String, String> submitted = MDC.getCopyOfContextMap();
        return () -> {
            Map<String, String> previous = MDC.getCopyOfContextMap();
            try {
                restore(submitted);
                task.run();
            } finally {
                restore(previous);
            }
        };
    }
 
    private static void restore(Map<String, String> context) {
        if (context == null) {
            MDC.clear();
        } else {
            MDC.setContextMap(context);
        }
    }
}

작업을 요청한 쪽의 MDC가 비어 있으면 작업 스레드의 MDC도 비워 줍니다. 값이 있을 때만 덮어쓰면 작업 스레드에 남아 있던 정보로 로그를 기록할 수 있기 때문입니다.

다른 비동기 경로의 확인

이 패턴은 이후 Audit Event의 비동기 발행에서도 사용했습니다. 요청 정보가 이벤트 발행 로그까지 이어져 같은 요청에서 발생한 작업을 찾는 데 도움이 됐습니다.

TaskDecorator를 적용한 executor에서는 요청 스레드의 MDC를 작업 스레드로 전달하고, 작업이 끝나면 정리하도록 했습니다. 같은 방식을 Audit Event 발행에도 사용해 요청에서 이어진 로그를 찾을 수 있게 했습니다.

별도로 만든 executor에는 설정을 따로 적용해야 합니다. 새 비동기 작업을 추가할 때도 실행할 executor와 MDC 정리 여부를 확인하는 일은 남았습니다.

다음 글에서는 Audit Event 발행 구조의 변경 과정을 다룹니다.

참고 자료

• Logback MDC 설명 
• Spring TaskDecorator API