멀티스레드 환경에서 로그 추적이 안 될 때 - Thread ID의 중요성
시스템 구성
승인/취소 중계 서버에서 결제 처리 후 가맹점에 결과를 노티(Notification)로 전달하는 구조다.
- 노티 전송은 멀티스레드로 동작
- 가맹점이 노티 수신 URL을 등록하면 해당 주소로 거래 데이터가 전송됨
- 1곳이든 여러 곳이든 URL 단위로 등록 가능 (다중 노티 지원)
1
2
3
예시) 가맹점 A의 노티 수신 URL 등록
- https://api.merchant-a.com/payment/notify
- https://backup.merchant-a.com/payment/notify
문제 발생
인지 시점
- 서비스 오픈 후 운영 중 가맹점으로부터 컨펌 접수
증상
가맹점에서 컨펌이 들어왔다.
“노티 수신까지 2~3초 걸리는데, 승인 요청 시점부터 노티 응답까지 정확한 소요 시간을 확인해줄 수 있나요?”
우리 쪽에서는 1초도 안 걸려서 보냈다고 판단했지만, 그걸 증명할 로그가 문제였다. 로그를 열었는데, 이런 상태였다.
1
2
3
4
5
6
7
8
9
10
2025-05-XX 14:23:01.001 INFO - 핸들러 진입: merchant_001
2025-05-XX 14:23:01.003 INFO - 핸들러 진입: merchant_002
2025-05-XX 14:23:01.050 INFO - 승인 요청
2025-05-XX 14:23:01.055 INFO - 승인 요청
2025-05-XX 14:23:01.123 INFO - 승인 완료
2025-05-XX 14:23:01.130 INFO - 승인 완료
2025-05-XX 14:23:01.125 INFO - 노티 전송: https://api.merchant-a.com/payment/notify
2025-05-XX 14:23:01.128 INFO - 노티 전송: https://backup.merchant-a.com/payment/notify
2025-05-XX 14:23:01.340 INFO - 노티 응답 수신: 200 OK
2025-05-XX 14:23:01.520 INFO - 노티 응답 수신: 200 OK
어떤 응답이 어떤 요청에 대한 것인지 구분할 수 없었다. 여러 가맹점의 로그가 뒤섞이고, 같은 가맹점이라도 다중 노티가 동시에 나가면 추적이 불가능했다.
결국 가맹점에 “정확한 시간을 특정할 수 없다”고 답변할 수밖에 없었다.
원인 분석
Logback 설정을 확인했다.
1
2
<!-- 변경 전 -->
<pattern>%d{yyyy-MM-dd HH:mm:ss.SSS} %-5level - %msg%n</pattern>
Thread ID가 로그 패턴에 빠져 있었다.
멀티스레드 환경에서 이 패턴으로는 어떤 스레드가 어떤 요청을 처리했는지 알 수 없다. 서비스 오픈 당시 내가 로그 패턴 설계를 제대로 하지 못한 거다.
해결
Logback 패턴에 %thread를 추가했다.
1
2
<!-- 변경 후 -->
<pattern>%d{yyyy-MM-dd HH:mm:ss.SSS} [%thread] %-5level - %msg%n</pattern>
변경 후 로그:
1
2
3
4
5
6
7
8
9
10
11
2025-05-XX 14:23:01.001 [noti-pool-1] INFO - 핸들러 진입: merchant_001
2025-05-XX 14:23:01.050 [noti-pool-1] INFO - 승인 요청
2025-05-XX 14:23:01.123 [noti-pool-1] INFO - 승인 완료 (0.073s)
2025-05-XX 14:23:01.125 [noti-pool-1] INFO - 노티 전송: https://api.merchant-a.com/payment/notify
2025-05-XX 14:23:01.340 [noti-pool-1] INFO - 노티 응답 수신: 200 OK (0.215s)
2025-05-XX 14:23:01.003 [noti-pool-2] INFO - 핸들러 진입: merchant_001
2025-05-XX 14:23:01.055 [noti-pool-2] INFO - 승인 요청
2025-05-XX 14:23:01.130 [noti-pool-2] INFO - 승인 완료 (0.075s)
2025-05-XX 14:23:01.132 [noti-pool-2] INFO - 노티 전송: https://backup.merchant-a.com/payment/notify
2025-05-XX 14:23:01.520 [noti-pool-2] INFO - 노티 응답 수신: 200 OK (0.388s)
스레드 ID 기준으로 필터링하면 한 건의 전체 흐름이 보인다.
- 핸들러 진입 시간 → 가맹점 요청이 우리 서버에 도착한 시점
- 승인 요청/완료 → 승인 처리 소요 시간
- 노티 전송/응답 → 어떤 URL로 보냈고, 응답까지 얼마나 걸렸는지
같은 가맹점의 다중 노티도 스레드 단위로 분리해서 추적할 수 있게 됐다.
마무리
멀티스레드 환경에서 Thread ID 없는 로그는 있으나 마나다. 로그가 있어도 추적이 안 되면 없는 거랑 같다. 서비스 오픈 전에 로그 패턴을 점검했어야 했는데, 운영 중에 터져서야 알게 됐다.
가맹점한테 “확인이 안 됩니다”라고 답변한 것도 뼈아팠다. 그 순간 우리 시스템에 대한 신뢰가 깎인 거니까. ELK나 Grafana Loki 같은 로그 파이프라인이 있었으면 스레드 단위 추적이 훨씬 수월했을 텐데, 그건 아직 갖춰지지 않은 상태다.
로그는 장애가 터졌을 때 보는 게 아니라, 장애에 대비해서 미리 설계해놓는 거라는 걸 이번에 제대로 느꼈다.