쿠버네티스 Istio protocol error: unsupported transfer encoding(Feign Client chunked)

자바/스프링 기반 애플리케이션 파드로 구성된 쿠버네티스[EKS] 클러스터를 운영 중 외부 API 호출이 불가능한 케이스가 생겼고 이를 분석한 내용을 정리하려고 한다. 

 

현재 envoy-proxy를 istio가 매핑한 istio-proxy 컨테이너가 파드마다 사이드카 형태로 배포되고 있어 모든 네트워크 통신을 proxy하고 있다. 

 

istio에 대해 생소하다면 먼저 baeldung에 자료를 참고하면 좋을 것 같다. 모듈 개발을 포함한 다양한 개발 직군에서 이해할 수 있게 잘 설명한 듯 하다.

https://www.baeldung.com/ops/istio-service-mesh

 

istio 버전은 다음과 같다.

[ec2-user@ip-10-250-32-36 ~]$ istioctl version
client version: 1.23.0
control plane version: 1.23.0
data plane version: 1.23.0 (31 proxies)

 

기존에 외부 호출은 문제되지 않았다. 

다음 처럼 아웃바운드에 대해서는 ALLOW_ANY로 모두 열려있는 상황이였다. 

  meshConfig:
    enableTracing: true
    defaultConfig:
      holdApplicationUntilProxyStarts: true
    accessLogFile: /dev/stdout
    outboundTrafficPolicy:
      mode: ALLOW_ANY

 

 

문제가 되는 부분은 신규 API 개발이였고 단순 방화벽 문제라 생각했다. 

처음에는 방화벽이 닫혀있었고 이를 오픈하여 정상 작동할 것이라 예측했다.

 

하지만 다음과 같은 오류를 반환했다.

upstream connect error or disconnect/reset before headers. reset reason: protocol error

 

 

파드 안에 접속하여 네트워크 통신을 확인해보기 위해 필요한 패키지를 설치하고 확인해보았다. 

apt-get update && apt-get install dnsutils -y && apt-get install curl -y

 

nslookup 명령어로 호출 시 대상 IP를 잘 찾았고 curl 로 요청을 보내도 정상 응답하였다. istio-proxy 컨테이너로 접속해서 호출하여도 정상 응답하였다. 

 

그렇다면 요청이 어디서 끊겼고 이유는 무엇일까 고민하게 되었다.

애플리케이션에 해당 API에 대한 로깅은 남아있었다. 요청이 애플리케이션까지 도달하는 데는 문제가 없어보였다. 그렇다면 응답이 나가는 과정에서 문제가 생길 것으로 예상했다. 위 오류만 보아도 upstream 즉 backend service와 연결이 끊긴 것으로 보였다. 

 

istio-proxy의 로그를 확인해보았다. 

"POST /api/... HTTP/1.1" 502 UPE upstream_reset_before_response_started{protocol_error} - "-" 104 87 75 - "43.203.254.209,10.250.34.161" "curl/8.5.0" ...

 

해당 로그만 보아서는 무슨 문제인지 파악되지 않았고 HTTP/1.1 통신을 하고 있고 프로토콜에 무슨 문제가 생겼나, TCP 연결이 끊길만한 이유가 뭐가 있을까 고민하게 되었다. 

 

일단 클라이언트에게 응답을 주기 위해 애플리케이션이 istio-proxy로 패킷을 전달할 때 오류가 나는 것으로 보였다. 

istio-egressgateway에는 에러 로그를 보이지 않았고 istio-ingressgateway에는 istio-proxy에서 발생한 동일한 오류를 보였다.

 

istio-proxy를 통한 패킷 흐름

 

위 그림은 트래픽이 어디서 끊겼는지 확인하기 위해 단순화해서 그려보았고 8, 9번 부분에서 연결이 끊긴 것으로 생각이 됐다. 애플리케이션에서 요청 이후 로그가 잘 출력되었기에 아마 9번에서 문제가 발생하지 않았을까 싶었다. 

 

istio-proxy에서 발생한 로그를 좀 더 상세히 분석하기 위해 로그 레벨을 trace로 변경하였다.

kubectl exec -it [pod] -c istio-proxy -- curl -X POST http://localhost:15000/logging?level=trace

 

해당 설정을 통해 해당 파드의 istio-proxy 모든 로그가 trace 레벨로 변경되었다. 다시 요청을 날려보고 로그를 확인해보았다.

istio-proxy log

Error dispatching received data: http/1.1 protocol error: unsupported transfer encoding

 

로그를 확인해보니 transfer encoding을 지원하지 않는다고 한다. 바로 위 Transfer-Encoding이 chunked임을 확인할 수 있었다.

위 파란색으로 표시한 부분을 보면 헤더에 key=Transfer-Encoding value=chunked 가 두 개가 들어왔다. 

정확히는 onHeaderCompleteImple 시점 이후에 헤더가 다시 셋팅되면서 오류가 떨어졌다. 이유는 잘 모르겠지만 backend service로 부터 패킷을 전달받아 헤더를 셋팅하는데 key=Transfer-Encoding value=chunked 이 값이 두 번 적용되었다.

 

이전에 이런 로그가 없었는데 코드 변경 사항을 보니 Feign Client를 도입하고 신규 API를 호출하는 과정이 추가되었다.

 

로그 레벨을 debug로 변경 후 요청에 대한 헤더를 확인해보니 keep-alive 설정과 transfer-encoding 설정을 볼 수 있었다. 

logging:
  level:
    com...clients: debug

feign client req/res header

 

chunked 방식에 대해서는 여기서 따로 설명하지 않겠다. 해당 블로그를 참고하도록 하자. https://goyunji.tistory.com/8

 

결국 Content-Length를 알 수 없는 경우 Transfer-Encoding: chunked를 사용하여 데이터를 부분적으로 전송할 수 있다는 것이니 Content-Length를 알면 되지 않을까 생각했고 그러면 chunked 방식을 사용하지 않을 것이라 생각했다. 

 

Feign Client를 사용하여 외부를 호출하고 바로 반환하는 예제코드이다.

@PostMapping(value = "/selectFeign", consumes = MediaType.APPLICATION_JSON_VALUE, produces = MediaType.APPLICATION_JSON_VALUE)
public ResponseEntity<String> selectFeign(@RequestBody ReqDto reqDto) {
    try {
        return feignService.selectFeign(reqDto);
    } catch (Exception e) {
        throw new RuntimeException("selectFeign error", e);
    }
}

@PostMapping(value = "/external/apipath", consumes = MediaType.APPLICATION_JSON_VALUE)
ResponseEntity<String> selectFeign(
        @RequestBody ReqDto reqDto
);

 

위는 문제가 되는 예시 코드인데 당장 문제가 된 이유는 Feign Client로 받아온 응답을 Bypass로 다이렉트로 바로 반환해서 응답 헤더의 transfer-encoding: chunked가 동일하게 셋팅되어 넘어간 거 같다는 생각이 들어서 바디를 분리하여 테스트 해보았다. 이렇게 작성하면 Content-Lengh의 길이를 구할 수 있을 것이다.

ResponseEntity<String> stringResponseEntity = feignService.selectFegin(reqDto);

String body = stringResponseEntity.getBody();
return ResponseEntity.ok(body);

 

만약 body의 Content-Length를 알기 위해 다음 처럼 body를 다시 선언하고 응답 객체를 만들어 리턴하면 Content-Length를 알게 되고 onHeaderCompleteImple이 수행되며 정상 상태코드 200을 받게 된다. 

istio-proxy 로그를 확인해보면 Content-Length를 전달받았다.

 

외부 API로부터 응답을 받는 부분은 여전히 transfer-encoding: chunked 이다. 

Feign Client req/res log

 

단지 response의 body를 받아 응답 객체를 다시 만들어 istio-proxy가 Content-Length를 받고 chunked 방식을 사용하지 않도록 한 것이다. 

 

그림으로 표현하면 다음과 같을 것으로 예상된다.

return String

 

그런데 문제는 모든 응답을 String 선언을 하여 반환하는 것이다. 최소한 dto로 말아서 응답할 수는 있어야 하는거 아닌가싶었다.

 

istio discuss에서 필자와 비슷하게 해결한 케이스가 있어서 반가웠다.

https://discuss.istio.io/t/unsupported-transfer-encoding-error-in-istio-proxy/6021/10

필자와 마찬가지로 응답 값의 getBody를 수행한 후 다시 말아서 리턴하는 경우로 비슷하다고 느꼈지만 위 코멘트에서는

객체를 말아 넘겨도 문제가 안된다 하였다. 그래서 동일하게 테스트를 진행했다.

ReceiptResDto receiptResDto = feignService.selectFegin(reqDto);
return ResponseEntity.ok().body(receiptResDto);

 

이렇게 객체를 넘겨도 정상 처리가 되었지만 응답의 Conten-Length가 아닌 Transfer-Encoding: chunked로 넘어왔다. 

객체는 직렬화(Serialization)과정을 거쳐야만 스프링이 크기를 알 수 있기 때문에 chunked로 넘기는 것으로 보였다.

정상 응답 처리 / 객체 리턴

 

String과 다르게 객체를 리턴했을 경우, 정확히는 데이터를 꺼내 반환한 경우 정상적으로 한번의 chunked 헤더 셋팅을 하고 처리하였다.

데이터 가공 후 정상 처리

 

그럼 결국 외부에서 받아온 데이터를 선언 혹은 가공없이, DTO 객체를 바로 bypass하는 경우만 오류가 발생한다는 것인데 istio 버그인지, 아니면 feignClient 객체 내부 클라이언트 설정인지 의심이 생겼다.

 

다른 클라이언트 객체의 경우는 어떨까?

WebClient로 결과 값을 리턴을 바로 넘기는 경우, 가공하는 경우, String을 넘기는 경우, 객체를 넘기는 경우를 테스트해보았다. block()하여 동기로도 호출해보고 Mono 객체를 리턴하여 스트림으로 받는 것도 확인해보았다.

 

String을 body로 리턴하는 경우 Content-Length를 리턴하였지만 객체를 리턴하는 경우는 여전히  key=Transfer-Encoding value=chunked가 리턴되었다. 이는 모두 정상으로 처리되었기에 FeignClient에 의심이 가기 시작했다. 

 

현재 필자는 jdk17, hc5 client를 enable하여 feignClient에서 ApacheHttp5Client를 사용하고 있다. 

feign:
  httpclient:
    hc5:
      enabled: true

 

실제 컨넥션을 맺고 Response를 받아오는 부분은 HttpRequestExecutor에서 확인할 수 있었다.

package org.apache.hc.core5.http.impl.io.HttpRequestExecutor

HttpRequestExecutor

정확히 한 번 ResponseEntity 데이터를 받고 헤더가 세팅되었다. 헤더가 chunked인 경우 connection속성이 keep-alive인데, response 매핑해 CloseableHttpResponse 객체를 생성 후 정상 close() 메소드를 정상 호출해 컨넥션을 종료한다.

CloseableHttpResponse

 

다만 close() 전에 컨넥션이 유지된 채 다양한 ExecChain들이 실행된다.

ExecChainElement

ExecChainElement -> ProtocolExec, RedirectExec, RetryExec ...

 

혹시 이 과정에서 tcp 연결을 유지하기 위해 헬스 체크 같은 요청을 던져보나? 싶기도 했지만 찾지 못했다.

이외 문제될 만한 코드는 도저히  찾지 못했다...

 

 istio에 설정 문제가 있지는 않을까?

 

https://datatracker.ietf.org/doc/html/rfc7230

RFC 7230: Hypertext Transfer Protocol (HTTP/1.1): Message Syntax and Routing

위 RFC 7230은 HTTP/1.1 프로토콜의 메시지 구문 및 라우팅을 정의하는 공식 문서인데, 일부 내용을 발췌한 것이다.

 

발신자는 메시지 본문에 chunked를 두 번 이상 적용해서는 안 된다고 한다. 이미 chunked된 메시지를 chunking하는 것은 허용되지 않는다고 적혀있다. 그렇다면 istio는 이 표준을 잘 지킨 것으로 생각된다.

 

istio-proxy에서는 backend-service와 통신하면 주고 받는 헤더, 패킷을 가지고 수행하는데 두 번 수신된 것인지, istio-proxy가 한 번 더 헤더를 셋팅한 것인지 의문이다.

실패한 경우

위에서 이미 눈썰미가 좋은 사람은 봤을 수도 있지만 Transfer-Encoding이 대, 소문자의 차이가 있었다. 다이렉트로 리턴 값을 넘기면 헤더 조차도 응답에 그대로 반환을 하고, istio가 Content-Length를 알 수 없어 다시 chunked로 설정하다가 오류가 난 것일까에 대한 생각도 들었다. 왜냐하면 외부 API는 응답을 소문자로 보내고 있었다.

 

하지만 이 가설대로라면 webClient도 동일해야 하는데 그렇지 않았다. 추가로 Http는 not case sensitive(대소문자 구별X)라고 한다.

 

따라서 확실하지 않지만 결론은 응답을 다이렉트로 보내면 헤더가 중첩되어 전송되는 것으로 이해하고 넘어가려고 한다. tomcat 말고 Undertow를 사용하면 중복된 헤더가 표시되지 않아 해결책으로 말하는 코멘트도 봤지만 시도해보지는 못했다. 이 방향이 맞다면 tomcat이 istio-proxy에게 Transfer-Encoding: chunked를 보내는 케이스가 있다고 해석이 된다.

 

또 다른 방향으로는 이를 공통으로 처리할 수 있게 istio-proxy가 중복된 transfer-encoding: chunked를 처리할 수는 없을까 생각이 들었다.

 

https://github.com/istio/istio/issues/48822

Tomcat/Istio "Transfer-Encoding: chunked" results in Upstream Error · Issue #48822 · istio/istio

EnvoyFilter에서  response_headers_to_remove: -Transfer-Encoding 헤더를 지우는 케이스도 보게 되었다.

 

이 방법은 아직 istio에 익숙하지 않아 러닝커브로 다가왔지만 istio 단에서 처리하는 것이 공통으로 처리하는 면에서 더 좋다고 생각하기도 하여 헤더를 지우는 방향으로 도전해봤는데 필자도 마찬가지로 적용되지 않았다.

(가만 생각해보면 istio는 죄가 없을지도...?)

 

The only fixes I know are to fix the application or treat the traffic as raw TCP (https://istio.io/latest/docs/ops/configuration/traffic-management/protocol-selection/)

코멘트를 보니 애플리케이션을 수정하거나 raw TCP로 처리하는 방향으로 추천하는 것도 볼 수 있었다.

 

필자 또한 중복된 Transfer-encoding을 방지하기 위해 애플리케이션을 수정하여 해결했다.

(내 지식 선에서) 정확한 원인이라고 딱 표현하기 애매한 이슈를 만나 것 같아 찝찝하지만 시간을 투자하다보면 항상 대안이 나오는 것도 신기한 것 같다.

 

 

 

혹시 같은 이슈를 겪고 원인을 아신다면 공유해주시면 감사드리겠습니다.