멀티스레드(여러 스레드를 거치는 단일 요청) 환경에서 로그 남기기

1. 들어가며

최근 회사에서 선박 단말(클라이언트)이 보낸 요청을 육상에 있는 해양 서비스(외부 API)의 HTTP 인터페이스로 중계하는

게이트웨이 서비스 개발 중 발생한 이슈와 이를 해결하며 알게된 점을 정리해보려고 합니다.

어느 날 "요청한 데이터와 다른 데이터가 온다"는 제보를 받았는데, 로그를 아무리 들여다봐도 어느 요청의 로그인지 알 수가 없었습니다.

동시에 여러 요청이 처리되는 줄이 뒤섞이고, 어느 응답이 어느 요청의 것인지 짝지을 방법이 없었습니다.

이 글은 그 문제를 어떻게 풀었는지에 대한 기록입니다.

 

2. 게이트웨이 서비스 소개

이 게이트웨이는 성격이 다른 두 프로토콜을 잇는 중계자 역할을 합니다.

• 클라이언트 사이드: 선박 단말과는 websocket 기반의 binary format으로 이루어진 메시징 프로토콜로 연결을 유지합니다.
• 외부 API 사이드: 육상의 해양 서비스와는 HTTP 요청/응답을 주고받습니다.

클라이언트가 정해진 메시지 포맷을 이용해 특정 데이터를 달라는 메시지를 전송하면,

게이트웨이가 그것을 HTTP 요청으로 바꿔 외부 API에 중계하고, 응답을 다시 메시지로 변경하여 돌려줍니다.

문제는 양쪽의 속도가 다르다는 것이었습니다.

메시지는 한 연결로 쏟아져 들어오는데 외부 API 호출은 느립니다.
실측해 보니 평균 150ms에서 1.3초, 느릴 때는 30초 타임아웃까지 갑니다.

메시지를 받은 자리에서 곧바로 HTTP를 호출하면 그 사이 들어오는 다른 메시지를 받지 못합니다.

그래서 게이트웨이의 메시지 수신 및 HTTP 송수신을 이벤트로 취급하고 받는 일과 처리하는 일을 분리했습니다.

• [수신]: 메시지를 받아 이벤트로 만들어 큐에 넣고 즉시 반환
• [처리]: 워커 여러 개가 큐에서 꺼내 외부 API 호출
• [전송]: 워커 여러 개가 꺼내 클라이언트로 전송

받는 쪽은 큐에 넣고 바로 다음 메시지를 받으러 가고, 느린 HTTP 호출은 워커 10개가 나눠 맡습니다.

전송도 마찬가지로 분리해, 처리 워커가 전송이 끝나기를 기다리지 않게 했습니다.      
그리고 이 구조가 이 글의 문제를 만들어 냅니다. 큐를 하나 둘 때마다 스레드 경계가 하나씩 생기기 때문입니다.

3. MDC란?

SLF4J의 MDC(Mapped Diagnostic Context)는 로그에 문맥 정보를 붙이는 표준적인 방법입니다.

즉, MDC는 로그 한 줄 한 줄에 "이건 어느 요청의 로그인가" 같은 문맥 정보를 붙이는 장치입니다.

이름 그대로 Map 형태의 진단 문맥이고, 로그 메시지마다 파라미터로 넘기는 대신 스레드에 매달아 두고 로거가 알아서 이를 꺼내 쓰게 합니다.

메시지에 직접 넣는 방식과 비교하면 차이가 분명하게 드러납니다.

  // 1.매번 넘기는 방식 — 모든 로그와 모든 메서드 시그니처가 오염됩니다                                                                                                                
  log.info("[{}] Relaying {}", correlationId, interfaceType);                                                                                                                        
  log.info("[{}] Relay succeeded ({})", correlationId, statusCode);                                                                                                                  
                                                                                                                                                                                     
  // 2.MDC — 한 번 넣어두면 그 스레드의 모든 로그에 따라붙습니다                                                                                                                       
  MDC.put("correlationId", correlationId);                                                                                                                                           
  log.info("Relaying {}", interfaceType);                                                                                                                                            
  log.info("Relay succeeded ({})", statusCode)

 

두번째 MDC를 사용하는 방식은 식별자를 문자열에 넣는 대신 스레드에 얹어두고,

출력 시점에 로그백이 모든 로그 이벤트에 붙여줍니다.

그래서 Hibernate나 HTTP와 같이 개발자가 작성하지 않은 코드가 찍는 로그까지 모두 같은 correlationId로 묶입니다.

이 차이가 큰 이유는, 문제가 드러나는 곳이 대개 내 코드가 아니기 때문입니다.

커넥션 타임아웃, SQL 지연, 커넥션 풀 고갈, TLS 핸드셰이크 실패 등은 모두 라이브러리가 찍는 로그입니다.

동시에 수십건이 처리되는 상황에서 그 줄들이 어느 요청이 것인지 구별하기 어려우면 그 원인을 찾기가 쉽지 않습니다.

MDC를 사용하면 correlationId를 통해 특정 요청이 처리되는 동안 찍힌 로그를 처음부터 끝까지 볼 수 있습니다.

 

4. MDC 적용해 보기

MDC를 이용하려면 두 가지만 하면 됩니다. 값을 넣고, 로그 패턴에서 꺼내는 것입니다.

// 넣기  
MDC.put("correlationId", "0ea748fa-...");
// 읽기
MDC.get("correlationId");
// 키 하나 지우기
MDC.remove("correlationId");
// 전부 지우기
MDC.clear();

 

application.yml 파일 설정을 통해 패턴에서는 %X{키}로 꺼냅니다.

logging:                                                                                                                                                                           
    pattern:                                                                                                                                                                         
      console: "%d{HH:mm:ss.SSS} %-5level [%.-8X{correlationId:-········}] %logger{32} - %msg%n"

 

그리고 아래와 같이 요청이 서비스에 들어오는 지점에서 식별자를 만들어 넣었습니다.

String correlationId = UUID.randomUUID().toString();
MDC.put("correlationId", correlationId);
log.info("Recieved {} from {}", interfaceType, senderMrn);

 

그런데 로그가 절반만 찍혔습니다.

14:42:39.501 INFO  [0ea748fa] c.a.s.mms.handler.SmmpHandler      - Received POST_GET from ...                                                                                      
14:42:39.507 INFO  [········] c.a.s.r.c.impl.SecomRelayCommand   - Relaying POST_GET → ...                                                                                         
14:42:39.512 INFO  [········] c.a.s.r.c.impl.SecomRelayCommand   - Relay POST_GET succeeded (200)                                                                                  
14:42:39.518 INFO  [········] c.a.s.r.e.t.MMSTransmissionEventProcessor - sent smmp message to ...

첫줄만 correlationId가 붙고 나머지는 기본값(········)입니다. 정작 "어느 응답이 어느 요청의 것인가"를

알아야 하는 구간이 전부 비어 있었습니다.

원인을 찾기 위해 요청이 처리되는 흐름을 정리하면 다음과 같습니다.

클라이언트 요청 처리 흐름(클라이언트 -> 서버 -> 클라이언트)

하나의 요청이 스레드를 3개 거치고 있었습니다.

큐에 넣는 스레드와 꺼내는 스레드가 다르니, 수신 시점에 넣어둔 MDC가 처리 시점, 전송 시점에 남아있지 않았던 것입니다.

 

5. 원인: MDC는 ThreadLocal이다.

ThreadLocal은 다음과 같은 성질을 가집니다.

• 스레드마다 독립된 값을 갖는다.
• 서로 다른 스레드는 접근이 불가능하다.
• 스레드 내부의 값은 살아 있는 한 계속 남아 있다.

이중 첫번째 성질에 의해 큐를 건너면 MDC가 비어 있었던 것입니다.

Thread1(수신 스레드)이 MDC.put()으로 넣은 값은 해당 스레드의 Map에만 들어가 있고,

큐에서 꺼낸 Thread2(처리 워커)는 자신의 비어있는 Map을 보고 있었습니다.

즉, MDC는 스레드 하나의 생명주기 안에서만 유효합니다.

그 경계를 넘어야 한다면, 값을 나르는 일은 어플리케이션이 직접 해야 합니다.

 

6. 해결: 식별자를 "컨텍스트"가 아닌 "데이터"로 다루기

원인을 알고 나니 방향은 분명해졌습니다.

MDC는 로그를 묶기위한 수단일 뿐, 값을 나르는 통로는 아니라는 것 입니다.

그래서 값은 큐를 건너는 이벤트 객체 안에 직접 넣었습니다.

이벤트 객체는 큐를 통해 값으로 전달되므로 스레드 경계와 무관합니다. 

MDC가 못 하는 일을 여기서 대신하는 셈입니다. 그리고 각 워커는 큐에서 꺼낸 직후에 MDC를 복원합니다.

이때, ThreadLocal의 세번째 성질에 의해 반드시 스레드내의 작업이 종료되는 지점에 MDC.clear()를 호출해야 합니다.

스레드가 살아 있는 한 값은 계속 남아있고, 스레드풀은 스레드를 재사용하기 때문에

해당 스레드가 전에 처리한 작업의 값을 정리해야 합니다.

	역할
이벤트 객체의 필드	스레드 경계의 값을 넘어 값을 나르는 통로
MDC	그 값을 로그 줄에 찍기 위한 표시 수단

 

7. 더 어려운 문제: 비동기 콜백

지금까지의 문제는 그래도 쉬운 편이었습니다.

이벤트 객체가 있으니 해당 이벤트 객체에 데이터를 담을 수 있었습니다.

문제는 외부 API가 결과를 별도 HTTP 요청으로 되돌려주는 시나리오였습니다.

요청에 대한 응답은 "접수했다"는 것뿐이고, 실제 결과는 게이트웨이로 새로운 HTTP 요청이 들어오는 형태로 도착합니다.

이는 모두 클라이언트의 단일 요청에 의해 발생한 흐름이며, 데이터가 하나의 문맥을 이루고 있습니다.

즉, 클라이언트의 요청 + 비동기 콜백을 하나로 묶는것이 데이터 흐름을 모니터링하기에 용이했습니다.

클라이언트 요청 + 비동기 콜백 처리 흐름

클라이언트의 요청과, 서버의 비동기 콜백은 다른 스레드, 다른 커넥션 그리고 반대 방향으로 들어옵니다.

게이트웨이에서 비동기 콜백은 클라이언트의 원래 요청과 연결고리가 없습니다.

따라서 이를 이벤트 객체에 태울 방법이 없었습니다.

방법은 요청을 보낼 때, 이를 미리 남겨두는 것이었습니다.

원래도 콜백의 수신자를 찾기 위한 대기 맵을 쓰고 있었는데, 거기에 correlationId를 함께 저장했습니다.

콜백이 도착하면 Map에서 꺼내 원래 요청의 식별자를 재사용합니다.

이 대기 맵의 등록은 처리 워커가, 조회는 톰캣 스레드가 담당합니다.

이때 서로 다른 스레드가 공유하므로 ConcurrentHashMap이어야 합니다.

또한 한가지 더 발견할 수 있었던 문제는 콜백이 클라이언트의 요청에 대한 응답보다 먼저 도착할 수 있다는 것입니다.

요청을 보낸 뒤에 맵에 등록하면, 그 사이에 콜백이 와서 수신자를 못 찾는 일이 생깁니다. 

그래서 요청을 보내기 전에 등록하도록 순서를 바꿨습니다.

 

8. 결과

로그가 이어지자, 그동안 보이지 않던 문제들이 드러났습니다.
가장 인상적이었던 건 메시지 전송 API가 세션이 없을 때 예외를 던지지 않고 그냥 반환하던 경우였습니다.

호출하는 쪽은 성공한 줄 알고 큐에서 메시지를 지웠습니다. 메시지가 사라지는데 아무도 모르고 있었습니다.

구간별로 기록을 남기기 시작하자 "보냈다고 기록됐는데 상대는 받지 못했다"가 눈에 보였고,

전송 전에 세션을 확인하도록 고칠 수 있었습니다.

이런 식으로 찾아낸 유실 경로가 세 곳이었습니다.

하려는 것	방법
한 요청의 로그를 묶어서 보기	MDC에 식별자를 넣고 패턴에 %X{}
큐를 건너 스레드가 바뀔 때	식별자를 이벤트 객체에 실어 나르고 워커가 복원
스레드 재사용으로 인한 오염	작업이 끝나는 지점에서 MDC.clear()
비동기 콜백 이어붙이기	대기맵에서 식별자를 함께 저장