지난주 화요일 새벽 2시 17분에 페이저가 울렸다. 결제 API의 P99 레이턴시가 1.2초를 찍고 있었다. 보통 80ms대로 노는 애가 갑자기 15배가 됐는데, 이게 가끔 한 번씩 튀고 끝나는 게 아니라 5분 동안 꾸준히 그 모양이었다. 멘탈이 살짝 나갔다. 결제는 트래픽 자체는 크지 않은데 도미노가 한번 시작되면 SLO 까먹는 속도가 가차 없는 구간이라.
결론부터 적자면, 그날 밤 범인은 애플리케이션도, DB도, 네트워크 장비도 아니었다. CoreDNS와 conntrack이었다. 며칠 뒤 NodeLocal DNSCache를 깐 후로는 같은 증상이 안 났는데, 이 일을 글로 정리해두고 싶었다. 비슷한 패턴은 의외로 흔한 것 같아서.
처음에 의심한 것들
알람 받자마자 떠오른 후보는 셋이었다. 결제 DB의 락, 외부 PG사 응답 지연, 그리고 한 시간 전쯤 내려간 결제 API의 새 버전. 솔직히 마지막 게 제일 의심스러웠다. 새벽에 알람 울리면 직전 배포가 의심되는 건 거의 본능이다.
그런데 셋 다 아니었다. 배포된 새 버전은 트레이스를 까보면 자기 일은 정상적으로 하고 있었다. 결제 DB도 한가했다. PG사 응답도 50ms 안쪽이었다. 그런데 결제 API의 outbound 호출 — 그러니까 인증 서비스, 쿠폰 서비스, 적립금 서비스로 가는 internal HTTP 호출 — 의 connect 단계에서 800ms씩 잡아먹고 있었다.
connect가 800ms? 클러스터 내부 통신인데? 이 시점에 머리에 의문부호 몇 개가 떴다.
DNS를 의심하기까지
처음엔 그냥 conntrack 테이블이 찼나 했다. node에 들어가서 conntrack -L | wc -l 때려봤더니 30만 줄 정도 나왔다. 한도가 200만이라 한참 여유가 있었다. 일단 후보에서 빼고 다음.
그 다음에 한 게 트레이스 좀 더 자세히 보기였다. OpenTelemetry로 들어오는 span을 보니까 connect 시간이 길어지는 호출들이 정확히 800ms 또는 1600ms 같은 식으로 깔끔한 배수로 떨어지고 있었다. 이거 보고 머리 한 번 식혔다. 800ms, 1600ms는 너무 익숙한 숫자다. 리졸버 재시도 타임아웃의 냄새가 났다.
CoreDNS Pod에 들어가서 로그를 봤더니 "i/o timeout" 같은 메시지가 일정 비율로 찍히고 있었다. 그리고 CoreDNS의 coredns_dns_request_duration_seconds 메트릭의 P99이 그 시점에 700ms 가까이 튄 흔적이 있었다. 평소엔 5ms 아래로 잘 돌던 애다.
이쯤 되니 내가 안다고 생각했던 것을 의심하기 시작했다. conntrack은 진짜 멀쩡한가?
진짜 원인: UDP DNS와 conntrack race
다시 conntrack을 봤는데, 이번에는 cat /proc/net/stat/nf_conntrack 로 통계를 봤다. insert_failed 카운터가 분당 수천 건씩 올라가고 있었다. 뭔가 보고 있었지만 알아채지 못한 거였다. conntrack 테이블 사이즈는 여유가 있었지만, insert에서 실패하는 케이스가 발생 중이었다.
여기서 잠깐 머리를 식혔다. conntrack이 여유가 있는데도 insert가 실패한다는 건, 흔히 알려진 시나리오가 하나 있다. UDP의 SNAT race condition. 같은 (src ip, src port, dst ip, dst port) 조합이 매우 짧은 시간 안에 두 개 생기면, 둘이 같은 conntrack 엔트리를 만들려다가 한쪽이 insert에 실패한다. UDP는 stateless라 커널이 무엇을 같은 흐름으로 볼지 결정하는 윈도우가 짧아서, 트래픽 패턴이 맞으면 운나쁘게 충돌한다. 결제 같은 fan-out 패턴은 내부적으로 동시에 여러 서비스를 호출하니, 짧은 순간에 같은 출발 포트를 쓸 가능성이 평소보다 높아진다.
그런데 우리는 평소에 이 문제를 거의 안 겪었다. 왜? 호출량이 평소보다 살짝 늘었던 것 같다. 그날 새벽 누가 어떤 캠페인 페이지를 노출시켰고 사람이 깨어 있었던 것 같다 — 이건 이튿날 마케팅 팀에 물어봐서 알았다. 정확히 동시에 일어나는 결제 요청 수가 평소의 1.6~1.7배 정도였다.
원인은 잡혔는데, 사실 충격은 좀 있었다. 알고는 있었던 클래식한 함정에 우리가 빠진 거다. NodeLocal DNSCache 도입은 작년 분기 OKR에 적혀 있다가 우선순위에 밀려서 흐지부지된 항목이었다. 그날 새벽에 뼈저렸다.
임시방편과 영구 조치
일단 그날 밤은 두 가지로 막았다. 결제 API의 dnsConfig에 single-request-reopen 옵션을 박았고 (glibc 리졸버가 A/AAAA를 같은 소켓에서 쏘다가 충돌하는 케이스를 줄여준다), ndots를 5에서 2로 내렸다. 이걸로 분당 DNS 쿼리 수가 60% 줄었다. 효과는 즉각이었다. 새벽 3시 10분쯤 P99이 다시 100ms 아래로 돌아왔다.
집에 가서 두 시간 자고 일어나서 영구 조치 작업을 시작했다. 이번에는 우선순위 안 밀린다.
NodeLocal DNSCache의 원리는 간단하다. 노드마다 DaemonSet으로 캐시 Pod를 띄우고, 각 노드의 169.254.20.10 같은 link-local IP에 listen시킨다. Pod의 /etc/resolv.conf가 이 IP를 가리키게 만들면, 클러스터 내부 DNS 쿼리는 노드 안에서 끝난다. 캐시에 있으면 microsecond 단위로 응답하고, 없으면 캐시 Pod가 TCP로 CoreDNS에 물어본다. 여기서 TCP가 핵심이다. UDP가 아니니까 conntrack의 SNAT race가 안 생긴다.
깔고 나서 coredns_dns_request_duration_seconds의 P99이 평소에도 한 자릿수 ms로 들어왔고, conntrack insert_failed도 거의 0으로 떨어졌다. 결제 API의 outbound P99 connect 시간은 평균 1.2ms대였다. 평소 5~6ms대였던 것에 비하면 체감이 컸다.
오해할까 봐 적어두는데, NodeLocal DNSCache가 만병통치는 아니다. 캐시 Pod가 죽으면 그 노드의 DNS가 잠깐 비는 순간이 있다. iptables 모드로 deploy하면 그 사이에 fallback이 안 되는 구조가 기본이라 신경 써서 봐야 한다. 우리는 캐시 Pod에 priorityClass를 system-node-critical로 박고, livenessProbe를 좀 보수적으로 설정했다. 그리고 DaemonSet 업데이트 전략을 OnDelete로 바꿔서 자동 롤링이 안 되게 했다 — DNS 캐시는 신중하게 갈아끼우고 싶다.
교훈 같은 것들
다 끝나고 나니까 곱씹게 된 게 몇 가지 있다.
하나, "알고는 있는" 함정이 가장 위험하다. UDP conntrack race는 우리 모두 어디서 한 번씩 들어본 얘기다. 그래서 더 미뤘다. 새 거라면 일정에 박아놓고 했을 텐데 익숙한 거라 다음 분기로 넘어갔다.
둘, conntrack 한도만 보지 말고 insert_failed를 봐야 한다. 우리 Grafana 대시보드에는 nf_conntrack_count만 있었지 insert_failed는 없었다. 사고 다음날 추가했다. 평소엔 0이지만 트래픽 패턴이 살짝 바뀌면 의외로 잘 튄다.
셋, 트레이스에서 connect 단계가 길어지면 일단 DNS를 의심하자. 800ms, 1600ms 같은 깔끔한 배수가 보이면 거의 확정이다. glibc 리졸버 기본 타임아웃이 5초고 한 번 재시도하기 때문에, 800ms은 첫 시도 timeout이라기엔 약간 짧지만 일부 musl 기반(alpine) 이미지에서 본 값과 일치한다. 우리 결제 API는 alpine을 쓰진 않지만, 옆에 있는 사이드카 envoy는 별개의 리졸버 동작을 한다. 결국 그날 본 800ms는 envoy의 outlier detection과 retry 정책이 합쳐져서 만든 값이었고, 이건 따로 또 정리해야 한다.
NodeLocal DNSCache 도입을 미뤄둔 클러스터가 있다면, 한번 진지하게 우선순위를 올려보길 권한다. 운영하면서 가장 빨리 뽑아낼 수 있는 안정성 ROI 중 하나라고 생각한다. 우리는 이번에 너무 늦게 깔았다.
다음에는 envoy의 DNS 리졸버 동작과 outlier detection이 conntrack과 어떻게 상호작용하는지를 좀 더 파보려고 한다. 사고 다음날 분석하면서 알게 된 건데, envoy가 strict_dns로 endpoint를 갱신할 때 짧은 간격으로 같은 source port를 재사용하는 패턴이 있어서, 이게 또 다른 race를 만들 수 있다. 다른 방법 쓰시는 분 있으면 댓글 남겨주세요.