간헐적인 502 는 어디서 오는가? (feat: NLB draining 과 istio 의 terminationDrainDuration)

들어가며

외부에서 우리 API 를 호출하는 쪽에서 문의가 하나 들어왔다. "API 를 호출했는데 502 를 받았습니다. 그런데 처리 상태는 바뀌어 있습니다."

로그를 확인해보니 상황이 묘했다. 클라이언트는 분명히 502 를 받았다고 한다. 그런데 우리 쪽 서버 앞단의 istio-proxy 액세스 로그에는 이렇게 남아 있었는데.

{
  "method": "PUT",
  "path": "/v1/foo/bar",
  "response_code": 0,
  "response_code_details": "downstream_remote_disconnect",
  "response_flags": "DC",
  "duration": 5899
}

response_flags: DC. Envoy 입장에서는 "다운스트림(클라이언트 방향)이 연결을 끊었다"는 기록이다. 클라이언트는 서버가 502 를 줬다고 하고 서버는 클라이언트가 끊었다고 하는, 양쪽 다 자기는 잘못이 없다고 말하는 상황이었다.

더 큰 문제는 따로 있었는데. 첫 요청에서 백엔드는 작업을 정상적으로 완료했다. 응답만 전달되지 못했을 뿐이다.

502 를 받은 호출자가 재시도하자 이번에는 "이미 처리된 요청"이라는 응답이 내려갔고 호출자 입장에서는 상태 불일치로 보였다. 인프라 계층의 커넥션 문제가 비멱등 API 를 만나 실제 문제가 된 케이스다.

이 간헐적인 502 의 범인을 시간을 꽤나 들여서 확인하였는데, 결론부터 이야기하면 원인은 한 줄이지만 그 과정에서 NLB 의 draining 이 실제로 어떻게 동작하는지, Envoy 는 커넥션을 어떻게 정리하는지, 그리고 "Terminate connections on deregistration" 같은 옵션이 정확히 어느 구간을 끊는지를 실측으로 확인하게 되어서 해당 과정을 공유해보고자 한다.

단서: 레이어마다 다른 증언

트래픽 경로는 다음과 같다.

Client → WAF → CloudFront → NLB → istio-ingressgateway → istio-proxy(sidecar) → app

NLB 는 IP target group 모드로 istio-ingressgateway 파드들을 직접 타겟으로 바라보는 구성이다. 각 레이어의 로그를 모아보면 이렇게 읽힌다.

모두가 "내 뒤쪽" 혹은 "내 앞쪽"을 가리키고 있어서, 이 상황에서 로그만 계속 들여다보는것은 답이 안 나올 것 같았고 관점을 바꿔서 언제 터지는지를 보기로 했다.

타이밍의 발견

CloudFront 액세스 로그를 Athena 로 쿼리해서 502 가 발생한 시각을 뽑고 그 옆에 istio-ingressgateway 파드 개수 메트릭을 나란히 놓았다.

sum(kube_pod_info{namespace="istio-system", pod=~"istio-ingressgateway-.+"})

5초 이상 걸린 요청 + AbortedOrigin 조합의 발생 시각이 파드 개수가 줄어드는 시점과 정확히 일치했다. 우연의 일치인가? 싶었지만 5~6건을 대조해보니 전부 맞았다. 다시 말해 istio-ingressgateway 가 scale-in 으로 종료될 때마다, 그 파드를 통과하던 요청 일부가 502 로 죽고 있었다.

파드 종료가 원인이라면 이야기는 graceful shutdown 으로 좁혀지는데, istio 의 종료 설정을 덤프해보니 이상한 값이 하나 보였다.

terminationDrainDuration: 5s. Envoy 가 SIGTERM 을 받은 뒤 in-flight 요청을 5초까지만 처리하고 남은 커넥션을 강제로 끊는다는 뜻이다. 기본값이다.

왜 종료 중인 파드로 요청이 계속 들어오는가

그런데 5초가 짧긴 해도, 종료 중인 파드라면 애초에 새 요청이 안 들어와야 하는것 아닌가? 라는 의문이 생긴다.

일반적인 애플리케이션 파드에 붙는 istio-proxy(sidecar)는 실제로 그렇다. 파드가 Terminating 상태가 되면 EndpointSlice 에서 엔트리가 제거되는것이 아니라 해당 엔드포인트가 ready=false 로 마킹되고, EndpointSlice 를 watch 하던 istiod 가 이 엔드포인트를 EDS 응답에서 제외한 채 프록시들에 push 한다. 그래서 트래픽이 더 이상 그 파드로 가지 않는다.

preStop sleep 동안 이 전파가 끝나기 때문에, SIGTERM 이후 5초 drain 으로도 문제가 없다. (그리고 native sidecar 를 사용하는 경우 application container 가 모두 종료된 이후에서야 sidecar 에 SIGTERM 신호가 전달되니 in-flight 요청 처리에 대한 부분도 신경 쓸 필요가 없다. 참고 : sidecar-containers k8s 문서)

그런데 istio-ingressgateway 는 사정이 다르다. 이 파드는 NLB target group 이 IP 모드로 직접 바라보고 있다. 파드가 Terminating 상태가 되면 NLB 타겟은 deregistration(draining) 상태로 전이되는데, 실측해보니 이 상태에서도 요청이 계속 들어온다.

처음에는 버그인가 싶었지만 여러 번 테스트한 결론은 이렇다.

CloudFront 와 NLB, NLB 와 ingressgateway 사이의 커넥션은 keep-alive 로 재사용된다. 기존 커넥션 위로는 draining 이 시작된 뒤에도 HTTP 요청이 계속 흘러들어온다. 심지어 "신규 연결 차단" 도 칼같지 않았다.

게이트웨이의 downstream 활성 연결을 지켜보면 draining 시작 후 1~2분까지는 새 커넥션이 간간이 생기는 것도 관찰됐다. 나중에 보니 이건 AWS 문서에도 있는 이야기였다.

draining 중에는 신규 연결을 받지 않는 것이 맞지만 "configuration propagation delay 로 인해 타겟이 여전히 연결을 받을 수 있다"고 명시되어있다. 그래서 타임라인이 이렇게 완성된다.

1. istio-ingressgateway 파드가 scale-in 으로 Terminating 진입, preStop sleep 시작 (기존 설정 180초)
2. NLB 타겟은 draining 상태가 되지만, 기존 커넥션으로 요청은 계속 유입
3. preStop 이 끝나고 Envoy 에 SIGTERM
4. Envoy 는 5초(terminationDrainDuration) 동안만 in-flight 를 처리
5. 5초 안에 응답 못 한 요청의 커넥션이 강제 종료 → istio-proxy 에는 DC, CloudFront 에는 AbortedOrigin, 클라이언트에는 502

응답이 5초 이상 걸리는 요청일수록 당첨 확률이 높아진다. 문의가 들어온 API 는 한 번에 다루는 데이터가 많아 처리 시간이 길었고 그래서 유독 자주 걸렸다.

재현하기

가설이 섰으니 실제로 재현을 해볼 차례다. 프로덕션 트래픽에 영향을 주지 않도록 격리된 임시 ingressgateway 를 하나 더 만들고 뒤에 httpbin 을 붙였다. httpbin 의 /delay/10 엔드포인트는 10초 뒤에 응답을 주기 때문에 "느린 요청"을 만들기에 딱 좋다.

부하: 0.1초 간격으로 /delay/10 호출 (aiohttp, 비동기 스크립트)
조작: istio-ingressgateway-temp 파드를 삭제
관찰: 간헐적으로 downstream_remote_disconnect 발생

재현이 되었는데, 파드를 죽일 때마다 in-flight 였던 요청 일부가 DC 로 끊기는것을 확인 할 수 있었다.

1차 조치: 5초를 30초로

istio-ingressgateway 에 한해 terminationDrainDuration 을 5초에서 30초로 올렸다. 적용 후 같은 부하 테스트에서 DC 가 더 이상 발생하지 않았다.

적용하고 나서는 프로덕션 ingressgateway 전체를 의도적으로 rollout restart 하면서 지켜봤다. 롤링으로 파드 42대가 전부 교체되는 동안 502 는 발생하지 않았다.

여기까지가 1차전인데, "5초 이상 걸리는 요청의 502"는 잡았지만 로그를 다시 보니 이상한것이 남아 있었다. 0.x 초 만에 AbortedOrigin 으로 끊긴 요청들이다. 이건 drain 시간과는 무관해 보였다.

2차전: 영원히 안 죽는 커넥션

drain 시간을 늘리는 것 말고 더 깔끔한 방법이 없을까? 싶어서 EXIT_ON_ZERO_ACTIVE_CONNECTIONS 를 실험했다. 이 옵션을 켜면 Envoy 가 SIGTERM 이후 신규 연결을 거부하면서 기존 active connection 이 전부 소진될 때까지 기다렸다가 종료한다.

재현에 썼던 격리된 임시 게이트웨이에서는 훌륭하게 동작해서, 20~30초면 active connection 이 모두 정리되고 Envoy 가 깨끗하게 내려가는것을 확인했다.

그런데 실제 프로덕션 트래픽에서는 달랐다. 이번에는 프로덕션 게이트웨이와 동일한 레이블을 갖는 임시 게이트웨이를 하나 더 띄웠다. 같은 Service 오브젝트의 셀렉터에 걸리기 때문에 NLB 타겟으로 함께 등록되고, 실제 프로덕션 트래픽의 일부를 받는다.

여기에 terminationGracePeriodSeconds 를 600초까지 늘려서 지켜봐도, active connection 메트릭이 천천히 줄다가 1~4개가 10분 넘게 살아남았고 결국 SIGKILL 로 강제 종료됐다. 파드 안에 들어가 ss 로 열린 소켓을 직접 세어보니, 남아 있는 커넥션의 상대방 주소는 전부 NLB 였다.

누가 이 커넥션을 물고 있는 걸까.

connection id 로 범인 잡기

프로덕션 트래픽 일부를 받고 있는 그 임시 게이트웨이에 Envoy admin API 로 커넥션 레벨 로그를 켰다. 이렇게 하면 프로덕션 게이트웨이 전체에 trace 레벨 로그를 켜지 않고도 실제 트래픽을 관찰 할 수 있다.

curl -X POST localhost:15000/logging?conn_handler=debug
curl -X POST localhost:15000/logging?http=trace
curl -X POST localhost:15000/logging?http2=trace

이렇게 하면 모든 HTTP 요청 로그에 그 요청이 탄 connection id 가 태그로 남는다. connection id 는 시간이 지남에 따라 증가하는(incremental) 값이다. 즉 draining 시작 후 5~10분이 지나서야 끊기는 커넥션이 있다면, 그 커넥션의 낮은 id 를 로그에서 역추적해 과거에 어떤 요청들이 이 커넥션을 썼는지 알아낼 수 있다.

추적 결과, 끝까지 살아남는 커넥션은 전부 한 곳을 가리켰다. 모바일 클라이언트가 주기적으로 이벤트를 전송하는 엔드포인트로 가는 요청이었다.

이 요청들은 CDN 을 거치지 않고 NLB 에 직결되는 경로였고 Connection: keep-alive 헤더 덕분에 하나의 TCP 연결을 계속 재사용하고 있었다. 유저가 앱을 쓰는 동안 이벤트가 계속 발생하니 커넥션은 영원히 idle 이 되지 않고 Envoy 는 "active connection" 으로 계속 카운트한다.

커넥션의 수명이 우리 손이 아니라 유저 클라이언트의 행동에 달려있다면 "0 이 될 때까지 대기"는 종료 시점을 보장 할 수 없는것이고, EXIT_ON_ZERO_ACTIVE_CONNECTIONS 를 채택 할 수 없는 이유가 여기서 확정되었다.

그리고 격리된 임시 게이트웨이에서는 이 옵션이 깔끔하게 동작했던 이유도 같이 설명이 되는데, 그쪽을 지나던 커넥션은 전부 CloudFront 경유였고 CloudFront 는 origin(NLB) 쪽 keep-alive 커넥션을 60초 이상 유휴 상태면 알아서 끊어준다.

앞단에 커넥션 수명을 관리해주는 프록시가 있는 경로는 active connection 이 자연히 0 으로 수렴하지만, NLB 에 직결된 keep-alive 클라이언트가 하나라도 있는 경로는 영원히 수렴하지 않는것이다. 결국 옵션 자체의 문제라기보다는 트래픽이 어떤 경로로 들어오느냐의 문제였다.

NLB 의 draining 을 오해하고 있었다

이 과정에서 NLB 옵션 하나도 실측으로 정리하게 되었는데. NLB target group 에는 "Terminate connections on deregistration" 옵션이 있다. 이름만 보면 draining 이 끝날 때 관련 커넥션을 정리해줄 것 같은데.

실제로 켜고 테스트해보면:

• 이 옵션이 끊는 것은 실측상 (A) Client↔NLB 구간뿐이다 (client 가 다음 요청을 보낼 때 NLB 로부터 RST 를 받는다)
• (B) NLB↔target 구간은 건드리지 않는다. 80/443 리스너 모두 적용해도 마지막 active connection 은 줄지 않았다
• 그리고 이 옵션 자체가 deregistration delay(기본 300초)가 다 지난 뒤에야 동작한다

정리하면, (B) 구간의 커넥션은 client 가 끊거나 TCP keepalive/idle timeout 이 발생하지 않는 한 아무도 끊어주지 않는다. Envoy 는 스스로 active connection 을 먼저 끊지 않고 NLB 도 안 끊는다. "설마 아무도 안 끊겠어"의 답은 "정말 아무도 안 끊는다"였다.

그러면 저 keep-alive 커넥션 위의 요청들은 파드 종료 때 어떻게 되는 걸까. 해당 서비스의 스테이징 환경을 격리된 임시 게이트웨이에 붙여 마지막 실험을 해보았는데. 결과는 다행히 안전했다. Envoy 는 draining 중에 요청을 받으면 "이 커넥션은 곧 닫힌다"는 신호를 응답에 실어 보낸다. HTTP/1.1 이면 connection: close 헤더, HTTP/2 면 GOAWAY 프레임.

이걸 받은 브라우저는 다음 요청에서 자연스럽게 새 커넥션을 맺었다. Envoy 가 완전히 내려간 뒤에야 다음 요청을 보내는 경우도 마찬가지였다. 기존 커넥션이 없으면 DNS lookup 부터 TCP, TLS 핸드셰이크까지 새로 하고 아무 일 없다는 듯 전송된다. 네트워크 탭에서 어떤 에러도 발생하지 않았다.

최종 설계

2주의 실측 끝에 "모든 커넥션을 완벽하게 graceful 하게 종료한다"는 목표 자체를 버리기로 했다. EXIT_ON_ZERO_ACTIVE_CONNECTIONS 는 채택하지 않고, 대신 각 구간의 시간을 실측에 맞춰 다시 배치하는 형태로 정리했다.

preStop 과 deregistration delay 를 120초로 맞췄다. draining 이 시작되고도 1~2분은 신규 연결이 생길 수 있기 때문에, 해당 유입이 끝난 뒤에 Envoy 의 draining 이 시작되도록 preStop 이 deregistration delay 구간을 온전히 덮게 했다. 기본값 300초짜리 delay 는 실측을 근거로 120초까지 줄였다.

drain 90초의 근거는 CloudFront 의 keep-alive timeout 이다. 주력 트래픽은 CloudFront 를 경유하는데, CloudFront 는 origin 커넥션을 60초 유휴면 끊기 때문에 drain 이 60초를 넘으면 CF 경유 커넥션이 자연스럽게 소진되는것을 기대 할 수 있다. 실제로 60초로 두고 게이트웨이를 수동으로 내려보니 drain 이 끝나갈 무렵에도 NLB 직결 경로의 POST 가 드문드문 들어와서 여유를 더해 90초로 정했다.

그러면 90초가 지나도 남아있는 커넥션은? NLB 직결 keep-alive 커넥션은 90초 뒤 강제 종료되는데, 이건 받아들이기로 했다. draining 90초 동안 요청을 한 번이라도 보낸 클라이언트는 connection: close 나 GOAWAY 를 받고 이미 새 커넥션으로 옮겨탄 뒤라서, 실제로 끊기는 것은 90초 내내 요청이 없던 유휴 커넥션뿐이다. 이 이벤트 전송 클라이언트에는 전송 실패 시 localStorage 에 쌓아뒀다 재전송하는 로직도 있다.

1차전에서 남겨뒀던 0.x 초 만의 AbortedOrigin 은 결국 따로 잡지 않았다. 몇 건을 백엔드 액세스 로그와 대조해보니 이 요청들은 백엔드에 아예 도달하지 않았고, 수 초 안에 재시도가 성공하는 것을 확인 할 수 있었다.

CloudFront 가 NLB 와의 keep-alive 커넥션을 재사용하는 순간 하필 그 커넥션이 반대편에서 닫혀버린 케이스인데, CloudFront 는 비멱등 요청을 재시도하지 않기 때문에 이 레이스는 POST 에서만 502 로 표면화된다.

발생량도 전체 요청의 0.0002% 수준인데다 백엔드가 처리한 적 없는 요청이라 상태 불일치를 만들지 않으므로, 이건 클라이언트 재시도에 맡기기로 했다. 정말 위험했던 것은 반대로 백엔드는 요청을 처리했는데 클라이언트만 502 를 받는 케이스였고, 그게 이번에 처리한 502 다.

terminationDrainDuration 값을 늘리는 변경점 적용 후 문의의 원인이었던 간헐 502 는 재발하지 않았고, 그렇게 이 문제를 해결 할 수 있었다.

정리

• L4 와 L7 의 "draining" 은 다른 말이다. NLB 의 deregistration 은 신규 연결 차단일 뿐 기존 연결과 무관하고 Envoy 의 drain 은 기존 커넥션 정리다. 두 계층의 시간이 어긋나는 지점에서 502 가 발생한다.
• NLB 를 IP target 으로 직접 바라보는 파드는 sidecar 와 종료 시나리오가 완전히 다르다. EndpointSlice 에서 빠지면 트래픽이 멈추는 sidecar 에서의 처리 방식으로 ingressgateway 를 다루면 안 된다.
• "Terminate connections on deregistration" 은 Client↔NLB 구간만 끊는다. 옵션 이름만 보고 동작을 유추하면 안된다.
• "active connection 이 언제 0 이 되는가"는 옵션이 아니라 트래픽 구성이 결정한다. CloudFront 처럼 유휴 커넥션을 관리해주는 프록시 뒤에서는 EXIT_ON_ZERO_ACTIVE_CONNECTIONS 가 성립하지만 로드밸런서에 직결된 keep-alive 클라이언트가 하나라도 있으면 성립하지 않는다.
• connection id 는 훌륭한 추적 도구다. Envoy admin API 로 커넥션 레벨 로깅을 켜면, "어떤 요청이 이 커넥션을 만들었나"를 역추적할 수 있다.
• 레이어들이 서로를 가리킬 때는 로그 대조가 아니라 재현이 답이다. 임시 gateway 워크로드 + 지연 응답 + 파드 kill 조합이면 이런 부류의 문제는 대부분 재현할 수 있다. (아닌 경우에는 당연히 tcpdump 등으로 더 심층 조사를 해야한다)
• 그리고 이 모든 것과 별개로, 비멱등 API 는 언젠가 이런 인프라 이슈를 만나 상태 불일치로 표면화된다. 인프라를 고치는 것과 별개로 멱등성 설계는 필요하다.