[트러블 빵야] Istio 를 디버깅 해보자! - Connection Refused 편

 

 

이스티오는 디버깅이 어려운 툴 중 하나라고 생각합니다. 그 이유는 간단하죠. 이스티오 자체가 어렵기 때문입니다.

 

서비스 메시 툴 답게 많은 네트워크 지식을 요구하기 때문에 디버깅이 어려울 수 밖에 없습니다. 네트워크 관련된 부분이 많기 때문에 어디서부터 디버깅을 해야 하는지 감도 사실 잘 안 옵니다.

 

이게 이스티오 문제인가? 클라우드 문제인가? 쿠버네티스 문제인가? 판단하기까지도 오래 걸리죠.

 

그러다 보니 애플리케이션을 배포하던 중 약간이라도 이스티오와 관련한 문제가 발생했다고 생각하는 경우 그냥 애플리케이션에서 이스티오를 빼버립니다.

 

정확히는 이스티오 사이드카(프록시)를 레이블을 통해 인젝션에서 제외시켜 버리는 것이죠.

 

이스티오 사이드카를 주입하지 않는 방법

 

이스티오 사이드카를 주입하지 않았기 때문에 대부분의 문제는 해결되지만, 이는 근본적인 해결 방법이 아닙니다.

 

그래도 이스티오 사이드카를 제외하는 건 이게 이스티오의 문제인지 판단하기엔 좋은 지표가 될 수 있죠.

뺄 땐 빼더라도 이유 정도는 괜찮잖아?

뺄 땐 빼더라도 이유 정도는 괜찮잖아?

 

하지만 이스티오 기능이 필요한 애플리케이션이라면 이스티오 기능을 사용할 수 없겠죠.

무작정 이스티오를 디버깅하는 것보단 정말 이스티오가 필요한 애플리케이션인지 파악하는 것도 중요하다고 생각합니다. 만약 이스티오가 굳이 필요 없다면, 그냥 이스티오 사이드카를 빼는 것이 정신 건강상 좋을 수도 있습니다.

 

앞으로는 단순히 이스티오 사이드카를 빼는 것이 아니라 적절한 디버깅을 통해 이스티오와 관련한 문제를 해결하는 데 도움이 될 수 있도록 "Istio 를 디버깅 해보자" 시리즈를 시작해보고자 합니다.

 

(시리즈라고는 했지만 운영하는 환경에서 문제가 발생하지 않으면 시리즈는 바로 여기서 끝날지도??!!)

 

그 중에서도 이번에는 "Connection Refused" 와 관련한 디버깅 방법을 소개하고자 합니다.

 

렛츠두더코드~

 

상황

---

상황은 Action Runner Controller(이하 ARC) 를 배포하다가 발생했습니다.

 

ARC 는 쿠버네티스에서 파드 단위로 Self Hosted Runner 를 구동할 수 있도록 도와주는 툴입니다.

 

https://github.com/actions/actions-runner-controller

 

Controller, Listener, Runner 크게 3가지 컴포넌트로 구분할 수 있는데 Listener 에서 문제가 발생했죠.

에러 로그

 

로그 내용을 대략 요약해 보자면

1. /access_tokens(1번) 엔드포인트를 통해 Github App Auth 의 Access Token 을 얻고자 함
2. DNS 쿼리는 성공적으로 수행했으나 Connection Refused 가 발생함

 

하나 이상한 점은 /access_tokens(1번)에 대한 엔드포인트만 Connection Refused 가 발생했고, 바로 다음에 실행한 /registration-token (2번)과 /runner-registration(3번) 엔드포인트는 관련한 에러 로그가 안 찍혔다는 점입니다.

 

이 또한 글 후반부에선 왜 이런 일이 일어났는지 알 수 있습니다!

 

원인

---

그럼 이제 이런 문제가 발생했는지 순차적으로 알아보죠!

 

Manifests

우선 배포된 쿠버네티스 API 나, 이스티오 API 쪽은 전부 정상이었습니다.

테스트다 보니 Istio SideCar API 도 ALLOW_ANY 로 해줌으로써 아웃바운드를 딱히 제한하지 않았습니다.

 

Code

다시 한번 로그 내용을 보면 Retryble client error 에 있는 내용은 Client 라이브러리가 반환해 주는 에러를 그대로 보여주는 것 같습니다.

 

즉, 코드 단에 어떠한 로직이 문제가 있어서 발생했다라기 보다는 Client 라이브러리를 통해 POST /access_token 을 호출했는데 Connection Refused 가 발생했고, 이를 그대로 리턴해준 것이죠.

 

그래도 확신한 것이 좋으니, 로그에 있는 에러 내용을 트레이싱 해보겠습니다.

 

저는 보통 코드를 살펴볼 때 로그를 코드에서 검색해 봅니다. 그래서 바로 ARC 코드를 Pull 해서 관련한 로그 내용이 있는지 검색해 보죠.

 

에러 트레이싱에 나와있는 go 파일들을 하나씩 따라가도 상관없는데 우리는 시간이 없으니 바로 로그를 검색해 봅니다.

go 파일들을 하나씩 따라간다는 방식 - 보여주는 .go 파일들은 한 스텝씩 찾아가서 확인

 

다행히 검색해 보니 어디서 호출한 로그인지 바로 나왔습니다.

client.go

 

1052 줄을 보면 엔드포인트를 호출하는 함수가 보입니다.

 

구현된 함수 코드를 보면 어찌어찌해서 Request 를 Send() 해줍니다.

http/client.go

 

또 Send() 를 살펴보게 되면, RoundTrip() 이라는 함수가 있는데

http/client.go

 

타고 타고 들어가면 해당 함수를 통해 실패한 요청에 대해 재시도를 하는 것을 확인할 수 있습니다.

client.go

 

이 말은 /access_tokens 에 실패할 경우 retry 횟수만큼 계속 시도를 한다는 것이죠.

 

그런데 로그를 보면 /access_tokens 에 대한 요청 실패는 하나이고, 다음 로그들이 찍힌 걸 볼 수 있습니다.

 

이걸로 어찌 됐든 한 번의 재시도 결과 /access_tokens 은 성공했다는 것을 알 수 있습니다.

 

성공했다는 또 다른 근거는 아래 코드에서 확인할 수 있습니다.

client.go

 

getting access token for GitHub App auth 라는 로그는 c.fetchAccessToken 함수 안에서 발생하는 것이고, getting runner registration token 은 이미지에서 보시다시피 바로 밑에 쪽에서 발생한 걸 알 수 있습니다.

 

이는 곧 c.fetchAccessToken 이 재시도는 했지만 성공적으로 수행되었다는 걸 알 수 있습니다.

 

코드 살펴본 결과 우리는 아래와 같이 정리할 수 있습니다.

1. /access_tokens 엔드포인트에 대한 실패 로그가 찍혔지만, 이는 한 번의 재시도 이후에 성공적으로 호출 되었다는 걸 알 수 있음
2. 재시도로 인해 성공했기 때문에 다음 엔드포인트인 /registration-token 도 성공적으로 호출됨
3. 결국 ARC 애플리케이션은 정상적으로 실행됨
4. 그런데, 왜 바로 성공 못하고 한번의 재시도 이후에 성공했을까? 라는 의문점이 생김

 

TCPDUMP

코드 레벨에서 확인할 수 있는 정보는 더 이상 없으니 이제는 어떠한 패킷들이 ARC 애플리케이션을 지나가는지 확인해 보겠습니다.

 

그런데 ARC 애플리케이션으로는 tcpdump 를 사용하기 한계가 있으니, 동일한 노드와 동일한 네임스페이스에 이스티오 사이드카를 주입한 Nginx 를 배포해서 패킷을 캡처해 보기로 했습니다.

apiVersion: v1
kind: Pod
metadata:
  name: sniff-01
  namespace: sniff-01
  labels:
    app: sniff-01
spec:
  containers:
    - name: sniff-01
      image: nginx:latest
      securityContext:
        privileged: true
      ports:
        - containerPort: 80
      command:
      - bash
      - -c
      - apt update && apt install -y tcpdump procps && rm -f /tmp/static-tcpdump && ln /bin/tcpdump /tmp/static-tcpdump && nginx -g "daemon off;"

 

근데 문제가 전혀 안보입니다.

http://naver.com 호출 결과

 

더 신기한 것은 Nginx 안에서 /access_tokens 를 호출해 봤는데 실패 없이 한 번에 성공했습니다.

curl -L \
  -X POST \
  -H "Accept: application/vnd.github+json" \
  -H "Authorization: Bearer <TOKEN>" \
  -H "X-GitHub-Api-Version: 2022-11-28" \
  https://api.github.com/app/installations/xxxxxx/access_tokens

 

참고로 위 엔드포인트에 사용되는 <TOKEN> 값은 아래 코드를 실행해서 얻을 수 있습니다.

//- npm 설치하기
//- npm install jsonwebtoken
const jwt = require('jsonwebtoken');
const fs = require('fs');

const privateKey = fs.readFileSync('./private-key.pem'); //- GitHub App 에서 발급받을 수 있음
const payload = {
    iat: Math.floor(Date.now() / 1000),          // 현재 시간 (초)
    exp: Math.floor(Date.now() / 1000) + 600,    // 10분 후 만료
    iss: '1131645',                          // GitHub App의 App ID
};

const token = jwt.sign(payload, privateKey, { algorithm: 'RS256' });
console.log(token);

 

흠.. 왜 Nginx 에선 한번에 성공하지..??

 

그러던 중 패킷에서 단서를 얻을 수 있었습니다.

패킷에 단서가

 

빨간색 네모를 친 패킷을 보면 DPort 가 15001입니다. 15001 포트는 이스티오 프록시의 인바운드 포트입니다.

 

이게 무슨 말이냐 이스티오 프록시는 iptables 를 재정의해서 애플리케이션에서 나오는 트래픽을 이스티오 프록시가 처리할 수 있도록 리다이렉션 해주는 이때 리다이렉션 해주어서 받는 트래픽은 이스티오 프록시의 15001 포트로 향하게 해 줍니다.

 

https://istio.io/latest/docs/ops/deployment/application-requirements/#ports-used-by-istio

 

Envoy outbound 라는 뜻은 애플리케이션 기준 외부로 나가는 트래픽을 받는 포트다 라고 이해해 주시면 됩니다.

 

아 왜 재시도 한번 이후에 엔드포인트가 성공했는지 알았습니다!

 

해결

---

Istio CNI 기준으로 애플리케이션을 배포할 때 Istio Validation 이라는 Init Container 가 iptables 유효성을 확인하고 이후에 메인 컨테이너들인 Nginx 와 Istio Proxy 가 실행됩니다.

 

Init Container 는 실행되는 순서가 보장되지만 메인 컨테이너들은 병렬로 처리되기 때문에 순서를 보장할 수 없습니다.

 

그에 따라 Istio Proxy 와 Nginx 는 동시에 뜨고 Nginx 입장에서는 Istio Proxy 가 성공적으로 실행되었는지 고려하지 않죠.

 

그런데 문제는 위에서 말씀드린 것처럼 Nginx 가 api.github.com 같은 외부 서비스로 나가기 위해선 반드시 Istio Proxy 를 지나가야 한다고 했습니다.

 

Istio Proxy 는 정상적으로 실행되는데 아무리 늦어도 1000ms 가 걸리는데, 만약 1000ms 이전에 Nginx 가 외부 서비스를 호출하게 되면 아직 준비 중인 Istio Proxy 로 요청이 가게 됩니다. 그에 따라 Istio Proxy 는 준비 중인 상태에서 호출을 받게 되어 Connection Refused 를 해버리는 것이죠.

 

이게 진짜인지 확인해 보기 위해 다음과 같이 파드를 배포해 줍니다.

apiVersion: v1
kind: Pod
metadata:
  name: sniff-01
  namespace: sniff-01
  labels:
    app: sniff-01
spec:
  containers:
    - name: sniff-01
      image: nginx:latest
      securityContext:
        privileged: true
      ports:
        - containerPort: 80
      command:
        - bash
        - -c
        - |
          tcpdump -n -i eth0 -w /tmp/tcpdump.pcap &
          
          curl -L https://google.com;
          
          nginx -g "daemon off;";

 

 

이러면 Istio Proxy 가 준비되는 시간인 1000ms 이전에 Nginx 가 https://google.com 로 요청을 보내게 되는데 로그를 보면 Connection Refused 가 발생하는 걸 확인할 수 있습니다.

 

/tmp/tcpdump.pcap 을 아래 명령어를 통해 로컬로 가져온 뒤,

$ kubectl cp sniff-01:/tmp/tcpdump.pcap ./tcpdump.pcap -n sniff-01

 

와이어샤크로 켜고 패킷을 확인합니다.

 

Connection Refused 와 관련 있는 RST 플래그가 있는 걸 확인할 수 있습니다.

 

이걸로 확실해졌습니다!

 

이게 더 확실히 알려면 Nginx 컨테이너가 아닌 Istio Proxy 컨테이너에서 패킷을 캡처하는 것이 더 확실한데, 편의상 Nginx 컨테이너로 진행했습니다.

 

요약해 보면

1. Nginx 컨테이너와 Istio Proxy 컨테이너는 동시에 실행됨
2. Istio Proxy 가 정상적으로 준비되는 데 1000ms 정도 걸림
3. 1000ms 이전에 Nginx 컨테이너가 외부 서비스를 호출하면 Istio Proxy 가 준비 되지 않은 상태이기 때문에 Connection Refused 가 됨

 

그럼 이제 최종적으로 1번 엔드포인트 호출에 대해 재시도 없이 한 번에 성공하게끔 하려면 어떻게 해야 할까요?

에러 로그

 

핵심은 Istio Proxy 의 실행을 보장해 준 뒤에 Nginx 를 실행시켜 주는 것입니다.

 

이는 이스티오에서 제공해 주는 어노테이션을 사용하면 됩니다.

apiVersion: v1
kind: Pod
metadata:
  name: sniff-01
  namespace: sniff-01
  labels:
    app: sniff-01
  annotations:
    proxy.istio.io/config: |
      holdApplicationUntilProxyStarts: true

https://istio.io/latest/docs/reference/config/istio.mesh.v1alpha1/#ProxyConfig-hold_application_until_proxy_starts

 

그럼 이제 ARC 에도 해당 어노테이션을 넣어주어 순서를 보장해 주면 재시도 없이 한 번에 실행되는 걸 확인할 수 있습니다.

 

아니면 ARC 처럼 코드 레벨에서 재시도를 통해 복원력을 높여 이를 애플리케이션 레벨에서 해결하는 방법도 있습니다.

 

하지만 ARC 는 이스티오가 굳이 필요하지 않은 녀석이기 때문에 이스티오를 주입하지 않는 것도 방법입니다.

Runner 의 외부 통신을 제한하기 위해 Service Entry 와 SideCar 를 엄격하게 가져가면 필요하지도?!

보안이 중요한 환경이라면 Runner 에서 굳이 불필요한 google.com 같은 곳에 통신이 되도록 할 필욘 없으니까요

 

정리

---

ARC 가 실행되는 데 있어서 직접적인 영향이 있었던 것은 아니었지만, 그래도 왜 Connection Refused 가 발생했는지 알아낼 수 있었습니다.

 

이스티오 프록시와 연관이 있었던 걸 확신할 수 없었기 때문에 코드까지 살펴봤는데, 코드와 직접적인 상관이 없더라도 트러블 슈팅을 하는 데 있어 코드를 확인하는 것은 도움이 많이 된다고 생각합니다. 애플리케이션의 메커니즘을 한층 깊게 더 이해할 수 있죠.

 

트러블 슈팅을 진행하면서 자연스럽게 해결 방법을 알아냈다기 보다는 이스티오 프록시에 대한 개념이 어느 정도 있어서 해결했던 문제였던 것 같습니다.

 

하지만 조금 더 시간이 있어서 이스티오 프록시 자체에서 패킷을 캡처했더라면 자연스레 해결 방법을 알 수도 있었을 겁니다.

 

ARC 말고도 가끔 다른 애플리케이션을 배포할 때 Connection Refused 가 발생하는 것을 종종 발견할 수 있는데 부디 이 글이 그런 문제를 해결하는데 도움이 되었으면 좋겠습니다.

 

이로써 이스티오 프록시를 무작정 빼버리기 전에 한번 더 고민해볼 수 있는 용기가 +1 되었습니다!

 

만약 또 다른 이스티오 트러블 슈팅이 있었다면 2편으로 돌아오겠습니다!

 

그럼 오늘은 여기까지!