엔보이(envoy) 딥-다이브 (2) : 엔보이 로깅의 2가지 종류

 

[이전 편]
- 1편: 엔보이(envoy) 딥-다이브 (1) : 엔보이가 패킷을 받아 처리하기까지

 

앞서 1편에서 엔보이 사이드카가 두 애플리케이션 사이에서 프록시 역할을 수행하면서 패킷을 처리하는 과정에 관해 디테일하게 설명드렸습니다. 혹시 아직 1편을 못 보신 분은 1편을 먼저 읽고 오시면 도움이 됩니다.

 

이번 편은 조금 쉬운 버전으로, 엔보이 로깅의 2가지 종류에 대해 알아보고 확인해 봅시다.

엔보이는 크게 2가지 종류의 로그를 표준출력으로 출력할 수 있습니다. 표준출력이라는 뜻은 kubectl log나 로키로 확인할 수 있다는 뜻입니다. 

1. 컴포넌트 로그

엔보이가 동작하기 위한 여러 컴포넌트들의 로그입니다. 이 엔보이 컴포넌트의 로그는, 엔보이를 거친 패킷들의 로그를 출력하는 것이 아님에 유의합시다. 예를 들어 xDS 통신에 관한 로그들이 해당됩니다. 에러 로그 레벨을 지정할 수 있고 여러 컴포넌트별로 레벨을 지정해 줄 수도 있습니다. 로그 형식은 다음과 같습니다.

2024-02-01T16:03:06.358150Z    info    xdsproxy    
connected to upstream XDS server: istiod.istio-system.svc:15012

참고문서: https://www.envoyproxy.io/docs/envoy/latest/operations/cli#cmdoption-l 

 

istioOperator에서 메시 단위로 공통적으로 적용시킬 수 있고, Pod Annotations 형식으로 개별 워크로드에 적용시킬 수도 있습니다. 

 

뿐만 아니라 런타임 상태에서도 컴포넌트의 로그 레벨을 확인하거나 변경해 줄 수 있는데요. 다음과 같은 커맨드를 통해 엔보이 대시보드를 띄워봅시다.

istioctl dashboard envoy YOUR_POD_NAME -n YOUR_POD_NAMESPACE

위 커맨드를 입력하면 다음과 같이 대시보드를 포트 포워딩으로 띄울 수 있는데요. 그중config_dump 구성을 클릭하면 해당 엔보이 사이드카의 프록시 설정들을 까볼 수 있습니다. ( istioctl proxy-config 커맨드와 동일합니다.)

 

또 logging부분을 클릭해 현재 컴포넌트 로깅 레벨을 체크할 수 있고, 변경도 가능합니다.

 

하지만 실제 디버깅 시 유용한 정보는 아닙니다. 예를 들어 A -> B 애플리케이션 간 통신에서 502 Bad Gateway 에러가 발생했다면 우리가 궁금한 정보는 어떤 URL prefix에서, 어떤 라우팅규칙으로 인해 들어온 트래픽이, 어떤 이유로 502를 내려줬냐 하는 거죠.

 

이 컴포넌트 로그는 해당 엔보이 컨테이너가 라우팅 규칙을 못 받아왔거나 권한 인증 문제, DNS 실패 등 엔보이 애플리케이션 그 자체에서 에러가 발생했을 때 디버깅하는 용도입니다. 즉, DevOps와 SRE 엔지니어에게 유용한 로그이지 서버 엔지니어가 디버깅에 사용하기엔 무리가 있는 로그입니다.

 

  2. 액세스 로그

액세스 로그는 실제 엔보이로 들어오는 요청들을 출력합니다. 앞서 1편 엔보이 프록시가 패킷을 처리하는 절차에서 헤더와 바디, 트레일러로 구성된 요청은 업스트림으로 프록시되고 응답은 다운스트림으로 프록시되고 응답이 완료되면 엑세스 로그에 쓰기 등의 처리가 수행된다고 했죠, 바로 그 엑세스 로그입니다. 즉, 실제 디버깅 시 도움이 되는 로그들입니다. 예시 로그를 함께 볼까요?

[2024-02-02T02:53:05.383Z] "GET /repos/branches/1754307 HTTP/1.1" 
200 - via_upstream - "-" 0 38 61 61 "-" "Python/3.10 aiohttp/3.8.3" 
"65a48c13-a221-4b4f-9986-3be26bfe4e44" "newdeal.default.svc.cluster.local" 
"10.1.21.59:80" inbound|80|| 127.0.0.6:46249 10.1.21.59:80 10.1.42.143:45340 
outbound_.80_._.newdeal.default.svc.cluster.local default-route

Log Operator	로그 예시
[%START_TIME%]	[2024-02-02T02:53:05.383Z]
\"%REQ(:METHOD)% %REQ(X-ENVOY-ORIGINAL-PATH?:PATH)% %PROTOCOL%\"	"GET /repos/branches/1754307 HTTP/1.1"
%RESPONSE_CODE%	200
%RESPONSE_FLAGS%	-
%RESPONSE_CODE_DETAILS%	via_upstream
%CONNECTION_TERMINATION_DETAILS%	-
\"%UPSTREAM_TRANSPORT_FAILURE_REASON%\"	"-"
%BYTES_RECEIVED%	0
%BYTES_SENT%	38
%DURATION%	61
%RESP(X-ENVOY-UPSTREAM-SERVICE-TIME)%	61
\"%REQ(X-FORWARDED-FOR)%\"	"-"
\"%REQ(USER-AGENT)%\"	"Python/3.10 aiohttp/3.8.3"
\"%REQ(X-REQUEST-ID)%\"	"65a48c13-a221-4b4f-9986-3be26bfe4e44"
\"%REQ(:AUTHORITY)%\"	"newdeal.default.svc.cluster.local"
\"%UPSTREAM_HOST%\"	"10.1.21.59:80"
%UPSTREAM_CLUSTER%	inbound|80||
%UPSTREAM_LOCAL_ADDRESS%	127.0.0.6:46249
%DOWNSTREAM_LOCAL_ADDRESS%	10.1.21.59:80
%DOWNSTREAM_REMOTE_ADDRESS%	10.1.42.143:45340
%REQUESTED_SERVER_NAME%	outbound_.80_._.newdeal.default.svc.cluster.local
%ROUTE_NAME%	default-route

DOWNSTREAM(다운스트림)은 요청을 보낸 클라이언트, UPSTREAM(업스트림)은 요청을 받은 서버입니다.

 

조금 양이 많나요? 여기서 주목해야 할 구성요소가 있습니다. RESPONSE_CODE_DETAILS 에는 응답코드에 대한 사유가 적혀있는데요. RESPONSE_CODE_DETAILS 가 via_upstream으로 찍힌 것을 통해 업스트림(요청을 받는 서버)에서 502 응답코드를 내려줬다라고 해석할 수 있습니다. 엔보이 프록시 자체에서 내려준 응답코드가 아니라는 것이죠.

 

즉, RESPONSE_CODE_DETAILS를 통해 5** 응답을 엔보이 프록시가 내려준 것인지, 애플리케이션이 내려준 것인지 구분할 수 있게 됩니다.

 

뿐만 아니라 RESPONSE_CODE_DETAILS 에는 via_upstream 외에도 많은 응답이 존재합니다. 그 내용에 대해서는 다음 문서를 참고해 주세요. (참고문서)

 

만약 5** 에러의 원인이 엔보이 프록시가 아닌, 애플리케이션에서 내려준 것으로 구분되었을 때 디버깅은 어떻게 할 수 있을까요? 로그를 분석해 특정한 공통점을 찾는 것도 디버깅에 많은 도움이 될 수 있습니다.

• 특정한 prefix에서만 500 에러가 발생할 때 ( "GET /repos/branches/1754307 HTTP/1.1"  )
• 특정한 다운스트림 주소(요청을 보낸 클라이언트)에서만 500에러가 발생할 때 ( DOWNSTREAM_REMOTE_ADDRESS , 10.64.4.77:80 )
• 특정한 라우팅 규칙으로 인해서만 500에러가 발생할 때 ( default-route )

 

자, 그럼 이 액세스 로그를 출력하도록 어떻게 설정할 수 있을까요? 여기에는 3가지 방법이 있습니다. 그 중 2가지 방법을 소개해드리겠습니다. 나머지 1개의 방법은 EnvoyFilter를 사용하는 방법인데, 구성이 까다롭고 EnvoyFilter에 대해서는 새로운 챕터에서 다루는 것이 좋을 것 같아 여기서는 생략하고 나머지 2가지 방법을 소개해드리겠습니다.

 

1. IstioOperator 설정

istioOperator 커스텀 리소스의 meshConfig 필드를 통해 mesh 단위에서 로그를 출력하도록 할 수 있습니다.

spec:
  meshConfig:
    accessLogFile: /dev/stdout

 

하지만 이 방법은 특정한 워크로드에 대해서만 적용할 수 없는 메쉬 설정이고, 디테일한 필터링이 불가능합니다.

2. Telemetry API 적용

telemetry 커스텀 리소스를 사용하면 워크로드 단위로 엑세스 로그를 지정할 수 있고, 필터링 또한 가능합니다.

apiVersion: telemetry.istio.io/v1alpha1
kind: Telemetry
metadata:
  name: newdeal-example
  namespace: istio-system
 spec:
   accessLogging:
   - filter:
       expression: response.code >= 500
     providers:
     - name: envoy

위의 예제는 응답 코드가 500 이상인 응답에 한해 로깅을 허용하는 전체 메쉬 설정을 엔보이 사이드카에 배포합니다.

 

표현식으로 특정한 URL prefix에 대해서만 로그를 뱉거나 특정한 라우팅 규칙은 로그를 뱉지 못하게 하는 등, 다양한 커스텀 설정이 가능합니다.

 

뿐만 아니라 istio-system 네임스페이스에 배포하면 전체 메쉬로 설정을 적용시킬 수 있고, A 네임스페이스에 배포하면 A 네임스페이스로 설정을 한정시킬 수도 있습니다. (단일 워크로드에 적용시키도록 라벨 셀렉터로도 가능합니다!)

 

 

하지만 아직 Alpha 단계라고 경고문을 띄워주고 있어 istio 업그레이드 시 릴리즈 노트를 주의 깊게 살펴봐야 합니다. 내가 과연 Expert 수준인가,,?

 

---

 

여기까지 엔보이 로깅의 2가지 종류에 대해 살펴봤습니다. 컴포넌트 로그와 액세스 로그를 잘 구분하고 도입해 적절한 로그들로 디버깅 시에 많은 도움을 받을 수 있습니다.

 

다음 3편에서는 엔보이 프록시의 여러 기능 중 하나인, 일시적인 오류를 처리하는 3가지 방법 (서킷 브레이커, 자동 요청 재시도, 이상값 탐지)에 대해 살펴보겠습니다.