MDC LogFilter 사용하기

MDC를 이용한 로그찍는 방법에 대해서 알아보겠습니다.

웹에서 요청이 들어왔을 때 contoller > service > repository 과정으로 로직이 흘러가고 이 과정에서 어떠한 문제가 발생하였을 때 딱 이부분만 로그를 보고 싶다라고하면 여러분들은 어떻게 로그를 찾아서 분석을 하시겠습니까?

보통 log파일을 열어서 특정 시점에 키워드로 관련 로그를 찾아가는 방법이 보편적인거 같습니다. 이번 과정에서는 MDC를 활용하여 한 스레드의 흐름 대해서 특정 로그키를 남기는 과정을 알아보려고 합니다.

MDC란?

MDC (Mapped Diagnostic Context)

실행 쓰레드들에 공통값을 주입하여 의미있는 정보를 추가해 로깅 할수있도록 제공한다.

Logging 을 남길때, 멀티쓰레드 환경에서 실행되는 task는 로그가 섞여 제대로 확인하기 힘들다.

실행되는 쓰레드마다 TheadLocal 변수에 Id값을 할당하여 실행흐름을 트래킹할 수 있다.

하지만 매번 쓰레드마다 위값을 주입해서 호출하는 것은 번거롭운데, MDC는 위 구현의 번거로움을 해소하고 Id 뿐만아니라 풍부한 값으로 로깅할수있도록 제공한다.slf4j,logback,log4j2 등 로거에서 MDC를 제공한다.

mdc.put()mdc.remove()등을 활용하여 세팅된 값을 활용할 수 있다.

[최대 이점]

한 스레드가 처리한 과정에 동일한 로그키를 남기게되면 해당 키워드로만 검색을하면 특정시간대에 두리번 할 필요도 없고 단번에 로그검색이 가능하실겁니다.

[코드 설명]

@Slf4j
public class LoggingFilter implements Filter {
    public static final String HEADER_ORIGIN = "Origin";
    public static final String HEADER_X_FORWARDED_FOR = "X-Forwarded-For";
    public static final String HEADER_LOG_KEY = "logKey";

    @Override
    public void doFilter(final ServletRequest req, final ServletResponse res, final FilterChain chain) throws IOException, ServletException {
        HttpServletRequest request = (HttpServletRequest) req;
        HttpServletResponse response = (HttpServletResponse) res;

        // 들어오는 헤더에 logKey가 존재하는 경우 해당 값 사용
        String logKey = request.getHeader(HEADER_LOG_KEY);
        if (!StringUtils.hasLength(logKey)) {
            logKey = UUID.randomUUID().toString(); // 없으면 신규 logKey생성
        }
        MDC.put(HEADER_LOG_KEY, logKey); // 로그 키 MDC put

        // 발신지 IP 추츨
        String ip = request.getHeader(HEADER_X_FORWARDED_FOR);
        if (!StringUtils.hasLength(ip)) {
            ip = "";
        }
        MDC.put(HEADER_X_FORWARDED_FOR, ip); // 발신 IP MDC put

        // 응답헤더에 정보 셋팅
        final String origin = request.getHeader(HEADER_ORIGIN);
        if (log.isDebugEnabled()) {
            log.debug("origin => {}", origin);
        }
        response.setHeader("Access-Control-Allow-Origin", origin);
        response.setHeader("Access-Control-Allow-Methods", "POST, GET, PUT, OPTIONS, DELETE, PATCH");
        response.setHeader("Access-Control-Max-Age", "3600");
        response.setHeader("Access-Control-Allow-Headers", "Origin, X-Requested-With, Content-Type, Accept");
        response.setHeader("Access-Control-Expose-Headers", "Location,Origin");
        response.setHeader("Access-Control-Allow-Credentials", "true");
        response.setHeader(HEADER_LOG_KEY, MDC.get(HEADER_LOG_KEY));

        // doFilter
        chain.doFilter(req, res);

        // 프로세스 종료 전 MCD 초기화
        MDC.remove(HEADER_LOG_KEY);
        MDC.remove(HEADER_X_FORWARDED_FOR);
    }
}

• 특정 로그키는 UUID형태로 생성하였습니다. (운이 좋지 않다면 겹치겠지만 극악의 확률이긴 합니다.)
• MDC에서 사용할 키는 “logKey”로 지정
• 각각의 controller에서 작성하는것보다 Filter단계에서 controller진입 전 공통으로 MDC 설정 환경이 반영되도록 하였습니다.
• 쓰레드가 MDC사용이 완료되면 무조건 반환을 해줘야한다. MDC.remove()
• 한 쓰레드당 쓰레드로컬에 MDC정보가 사용된다.
  • 코드에서볼 땐 항상 같은키로 put이되고 있는데 동시다발적으로 여러쓰레드가 활성되어있는 상태에서는 겹치는거 아니야? 라고생각 할 수 있다. 하지만 아니다 MDC.put(”logkey”, “유니크값”); 각 쓰레드가 고유의 ID로 로그를 남길 수 있는건 TheadLocal에 사용되기 때문에 서로다른 쓰레드간에 동일한 key값으로 MDC.put()을 하여도 전혀 영향이 없는 상태라고 보면된다.
• 아래 그림으로본다면 쓰레드 A, B, C 각각 쓰레드로컬을 가지고있고 그 쓰레드로컬에 MDC.put()이 발생된다.

 

[로그 확인해보기]

제가 시큐리티관련 프로젝트 진행 한곳에서 실제 활용했을 때 어떤 결과값으로찍히는지 확인해보겠습니다.

http://localhost/v1/members 라는 API호출 했을 때 controller, service각각 로그가 찍히도록 작성하였습니다.

• MemberController

@Slf4j
@RequiredArgsConstructor
@RestController
@RequestMapping("/v1/members")
public class MemberController {

    private final MemberService memberService;

    @GetMapping("/me")
    public MemberDto getMyMemberInfo() {
        log.info("MemberController : 내 정보 조회");
        return memberService.getMyInfo();
    }
}

• MemberService

@Transactional(readOnly = true)
@RequiredArgsConstructor
@Service
@Slf4j
public class MemberService extends AbstractService<Long, Member, MemberDto, MemberSearch, MemberRepository> {

    private final MemberRepository memberRepository;
    private final ApiClient apiClient;

    // 현재 SecurityContext 에 있는 유저 정보 가져오기
    public MemberDto getMyInfo() {
        log.info("MemberService : 내 정보 조회");
        return Optional.ofNullable(super.detail(MemberDto.builder()
                        .id(SecurityUtil.getCurrentMemberId())
                        .build()))
                .orElseThrow(() -> new RuntimeException("로그인 유저 정보가 없습니다."));
    }
}

[결과]

2022-05-02 20:19:41.667  INFO 95848 --- [http-nio-8080-exec-2][][a623a668-e16f-4379-a6b6-dc0778b6bc70] c.v.vegana.controller.MemberController   : MemberController : 내 정보 조회
2022-05-02 20:19:41.675  INFO 95848 --- [http-nio-8080-exec-2][][a623a668-e16f-4379-a6b6-dc0778b6bc70] com.vegana.vegana.service.MemberService  : MemberService : 내 정보 조회

• 동일 스레드 작업에 대해서 같은 logKey 값이 찍혀있는 걸 확인 할 수 있습니다.
  • 스레드
    • http-nio-8080-exec-2
  • 로그 키
    • a623a668-e16f-4379-a6b6-dc0778b6bc70

• •