NodeLocal DNSCache 켰더니 5초 지연이 다시 돌아온 이야기
지지난 주 새벽 3시
알림이 하나 왔다. payment-worker P99 레이턴시가 3초를 넘겼다는 거였다. 뭐, 우리 서비스에서 결제 처리가 3초씩 걸리는 건 상상만 해도 아찔한데, 근데 정작 워커 자체는 아무 것도 안 하고 있었다. CPU 5%, 메모리 정상, 큐도 밀리지 않았다.
일단 잠들었다. 낮에 확인하기로 했다. 아침에 눈 뜨자마자 로그를 보는데, 이상한 게 getaddrinfo 호출이 5초씩 잡히고 있었다. 익숙한 냄새였다. conntrack race condition. 5초 지연은 DNS 이슈의 시그니처 같은 거니까.
근데 왜? 우리는 몇 달 전에 이미 NodeLocal DNSCache를 넣었단 말이지.
얼마 전에 도입한 NodeLocal DNSCache
배경 설명이 필요한데, 우리 팀은 EKS 노드 60대 정도의 프로덕션 클러스터를 굴린다. 파드 수는 대략 1400개. 몇 달 전에 CoreDNS 부하 알림이 뜨기 시작하면서 NodeLocal DNSCache를 도입했다. 노드에 DaemonSet으로 DNS 캐시가 뜨고, 파드는 링크로컬 169.254.20.10 을 바라보게 하는 그 흔한 패턴 말이다.
도입 직후 효과는 확실했다. CoreDNS 쿼리량이 70% 정도 줄었고, conntrack race도 안 잡혔다. 그 이후로는 잘 잊고 지냈다. 인프라 팀 표어가 "잘 도는 건 건들지 말자"였는데, 그걸 성실히 지키고 있었던 셈이다.
문제를 다시 만난 순간
로그를 계속 파다 보니 특정 노드에서만 지연이 튀는 게 보였다. 그런데 그 노드에도 node-local-dns 파드는 정상적으로 떠 있었다. kubectl exec 로 들어가서 확인해도 curl -v 169.254.20.10:8080/health 는 잘 뜨는 상태.
그럼 뭐가 문제야?
파드 안에 들어가서 dig +noall +stats @169.254.20.10 example.internal 로 여러 번 때려봤다. 어? 이게 가끔 5초씩 잡힌다. 캐시된 걸 물어봤는데도. 이상하네.
tcpdump 를 파드 네트워크 네임스페이스 안에서 떠서 봤더니 좀 특이한 게 보였다. UDP 쿼리 하나가 나가는데 응답이 안 오면 재전송이 5초 뒤에 일어나고 그 재전송은 잘 되는 그림이었다. 그러니까 첫 UDP 패킷이 어딘가에서 삼켜지고 있었다.
삽질 1: node-local-dns 로그 파기
kubectl logs -n kube-system node-local-dns-xxxxx 를 봤는데 딱히 에러 로그가 안 나왔다. 그냥 조용했다. 이럴 때가 제일 어렵다. 뭘 알려주는 로그가 아무 것도 없으니까.
stats 플러그인 켜서 프로메테우스 스크레이핑 걸어놨었는데, 그것도 봐도 캐시 히트율 98%, 에러 카운터도 별 특이사항이 없었다. 이 시점에서 좀 멘탈이 나갔다.
삽질 2: conntrack 다시 의심
혹시 NodeLocal DNSCache가 뭔가 우회된 건 아닐까? 파드에서 실제로 169.254.20.10 이 아니라 kube-dns ClusterIP 로 나가고 있는 건 아닐까? 이 가설을 검증하려고 파드의 /etc/resolv.conf 를 확인했다.
nameserver 172.20.0.10
options ndots:5
어? 왜 kube-dns ClusterIP 가 여기 박혀 있지?
여기서 조금 깨달음이 왔다. 몇 달 전 도입할 때 우리는 dnsPolicy 를 명시적으로 바꾸지 않고, node-local-dns 파드가 iptables NOTRACK 룰을 심어서 169.254.20.10 을 hijack 하도록 되어 있었다. 즉 파드는 여전히 ClusterIP 를 향해 쏘지만, 노드 자체가 그걸 잡아채서 로컬 캐시로 돌리는 구조.
그런데 왜 5초 지연이? 그 hijack 이 안 되면 원래대로 CoreDNS 로 가서 처리되어야 하는 거잖아. 완전히 실패하는 게 아니라 5초 지연되는 이유가 뭐야.
진범: iptables 재적용 타이밍
이거 알아내는 데 반나절 걸렸다. 우리 노드에서 최근에 kube-proxy 를 nftables 모드로 마이그레이션 했었다. 지난 달에. 그런데 그거 하면서 iptables 를 완전히 안 쓰는 상태가 아니라, kube-proxy 는 nftables 를 쓰지만 CNI(Cilium) 랑 node-local-dns 는 여전히 iptables NOTRACK 룰을 심는 상태였다.
문제는 특정 상황에서 이 iptables NOTRACK 룰이 사라지는 시점이 있었다. nftables 관련 유틸이 방화벽 룰을 flush 하는 순간 iptables 룰도 같이 쓸려나가는 케이스가 있고, 이때 node-local-dns 가 룰을 다시 심기 전까지 짧게 창이 열린다. 그 창에 걸린 쿼리는 169.254.20.10 로 향했는데 아무도 응답하지 않으니 5초 재전송 타이머까지 대기.
node-local-dns 는 주기적으로(기본 60초) NOTRACK 룰을 재확인해서 없으면 다시 심는데, 이 60초 동안 몇몇 쿼리가 그 틈에 빠지고 있었다.
간단히 재현해봤다.
# 노드에 SSH
$ sudo iptables -t raw -L PREROUTING -v -n | grep 169.254
12 1024 NOTRACK udp -- * * 0.0.0.0/0 169.254.20.10 udp dpt:53
$ sudo iptables -t raw -F PREROUTING
# 이 상태에서 파드에서 dig
$ dig @169.254.20.10 example.com
# 5초 지연 발생, 이후 재전송에서 응답 옴
이거였다. NOTRACK 룰이 잠깐이라도 없어지면 그 시점에 나간 UDP 패킷은 conntrack 을 태우게 되고, 다시 들어오는 응답이 SNAT 도 안 되어 있으니까 파드가 안 받는다. 그러다 5초 뒤 재전송에서 성공.
해결
두 가지를 손댔다.
첫째, node-local-dns 를 v1.24 로 올렸다. 이 버전부터 룰 재확인 주기가 짧아지고, 방화벽 감지 로직도 개선됐다. 60초에서 실질적으로 5초 이내로 회복.
둘째, 노드 부팅 시 iptables 룰 flush 를 안 하도록 systemd 유닛 하나를 잡았다. 원인은 우리 노드 이미지에 firewalld 가 켜져 있었다는 사실이었다. AMI 만들면서 실수로 disabled 처리를 안 했다. firewalld 는 주기적으로 룰을 재적용하면서 다른 룰들을 flush 시켰다. 이걸 mask 처리했다.
systemctl mask firewalld
이 두 개 적용하고 나서 5초 지연 알림은 안 왔다.
배운 것
- NodeLocal DNSCache 는 hijack 방식이라 iptables 룰에 의존한다. 다른 곳에서 iptables 룰을 건드리는 순간 조용히 깨진다.
- node-local-dns 의 로그는 이런 케이스에 침묵한다. 룰이 없어도 데몬 자체는 계속 잘 도니까 에러가 안 뜬다.
stats를 봐도 캐시 히트만 잡히지 룰 상태는 안 잡힌다. - AMI 만들 때 firewalld 같은 것 확인. 요즘 Amazon Linux 2023 기본 이미지에는 켜져 있는 게 있고 아닌 게 있고 조금씩 다르다.
- kube-proxy 를 nftables 로 옮겼다고 다른 컴포넌트도 자동으로 넘어가는 건 아니다. iptables 와 nftables 가 공존하는 상태를 파악해두자.
우리 팀 노드가 이번 사건 이후 부팅 시 실행하는 헬스체크에 iptables -t raw -L PREROUTING | grep 169.254 를 하나 추가했다. 이게 없으면 알림 뜨게. 아직은 잘 잡히고 있다.
혹시 비슷한 케이스 겪은 분 있으면 어떻게 감지하셨는지 궁금하다. 우리는 결국 사후에 알아냈는데, 사전 감지 방법이 있으면 좋겠는데 마땅한 게 없었다.