connection prematurely close BEFORE response 해결기

개요

reactor netty를 활용하는 Spring Cloud Gateway 서버에서 간헐적으로 connection prematurely close BEFORE response 오류가 발생하고 있었습니다.

 

해당 서버는 200 tps 정도로 요청을 처리하는데 하루에 간헐적으로 1~2건 정도 오류가 발생하였습니다.

 

어떤 에러인지?

에러 메시지를 해석해 보면 connection이 response를 받기 전에 close 되었다는 예외 메시지입니다.

왜 요청 중인 connection이 close 되었는지를 파악한다면 문제를 해결할 수 있을 것 같습니다.

 

 

환경

reactor-netty 1.1.13

jvm 17

spring-cloud-starter-gateway 4.0.9

envoy proxy 활용하는 pod to pod 통신과정에서 발생

 

Reactor Netty Debugging Guide

해당 오류는 reactor-netty 커뮤니티에서 자주 issue에 올라오기 때문에 공식문서에 FQA 가이드가 정리되어 있습니다.

 

https://projectreactor.io/docs/netty/release/reference/faq.html#faq.connection-closed

Frequently Asked Questions :: Reactor Netty Reference Guide

 

기본적으로 reactor-netty의 Clients는 connection pool을 활용하며, 유효한 connection을 얻어온 후 다양한 이유로 종료될 수 있습니다.

 

따라서 여러 가지를 확인하면 문제를 해결할 수 있다고 가이드합니다.

 

1. TCP dump를 통하여 FIN/RST signal이 상대 서버로부터 오는지 확인하기

 

2. network connection 확인하기

 

3. 방화벽이나 VPN 활용하는지 확인하기

 

4. 프록시나 로드밸런서를 활용하는지, client와 target server의 idle timeout 설정은 얼마인지

 

5. target server의 메모리 제한, max file limit size, bad request, max keep alive requests 는 얼마인지

 

HTTP 1.1 Keep Alive idle Timeout

keep alive idle timeout은 HTTP 연결을 재사용하기 위해 열어둔 TCP connection을 얼마나 오래 유휴 상태로 유지할지를 결정하는 시간입니다.

 

요청마다 TCP connection을 만들지 않기 때문에 오버헤드를 줄일 수 있습니다.

 

 

gateway server의 idle timeout

- max-idle-time: 3595000

- max-life-time: 60s

- eviction-interval: 30s

 

idle timeout은 3595초로 정의되어 있지만 max-life-time 설정에 의하여 60초마다 connection이 정리됩니다.

 

envoy proxy의 idle timeout

- 3600s

 

target server의 idle timeout

- 3605s

 

connection을 유지하는 시간이 gateway server < envoy proxy < target server 로 잘 구성되어 있습니다.

만약에 gateway server > envoy proxy 였다면 gateway server가 connection을 획득했을 때 envoy proxy는 idle timeout 이 발생하여 gateway server로 FIN / RST 패킷을 보내면서 connection prematurely close BEFORE response 예외가 발생할 수 있습니다.

 

TCP dump

idle timeout 설정상으로는 이슈가 발생하지 않아야 합니다.

따라서 정확한 원인을 파악하기 위해서 TCP dump도 수행하였습니다.

 

gateway -> target server 구간 TCP dump

1. gateway -> target server HTTP 요청

2. target server -> gateway -> tcp ack

3. gateway server 에 connection prematurely close BEFORE response 로그 발생

4. gateway server -> target server로 FIN/ACK 요청

5. target server -> gateway server로 FIN/ACK 요청

 

target server에서 FIN을 보내는 것이 아니라 gateway server에서 먼저 FIN/ACK을 보내서 연결을 종료하고 있는 것을 확인할 수 있었습니다.

 

gateway -> target server 구간 통신에는 envoy proxy가 존재하기 때문에 해당 구간에도 TCP dump를 수행해 보았지만 결과는 동일하게 gateway에서 먼저 FIN/ACK를 보내고 있었습니다.

 

client -> gateway 구간 TCP dump

클라이언트가 응답 수신 전에 연결을 끊거나 요청을 취소하는 경우를 의심해 볼 수 있지만 TCP dump 상 Client에서 받은 FIN은 확인되지 않았습니다.

 

그리고 연결을 끊었다면 gateway에서 응답을 받을 필요가 없을 텐데, 500 HTTP status code를 응답받고 있었습니다.

 

Envoy Access Log

envoy proxy도 로그를 남기고 있어 확인해 보았을 때 gateway -> target server로 DC 로그가 남아있었습니다.

DC는 Downstream Connection Termination으로 클라이언트가 서버의 응답을 받기 전에 끊었다는 것입니다.

 

여기까지 확인했을 때 gateway 내부에서 뭔가 취소가 발생하고 있는 것 같습니다.

 

Log DEBUG level

logging.level.reactor.netty.resources.PooledConnectionProvider=DEBUG
logging.level.reactor.netty.resources.DefaultPooledConnectionProvider=DEBUG
logging.level.reactor.netty.http.client.HttpClientOperations=DEBUG
logging.level.reactor.netty.channel.ChannelOperationsHandler=DEBUG

 

connection pool을 가져오고 반납하는 과정에서 race condition이 의심되어 DEBUG 로그를 활성화하였습니다.

 

오류가 발생하는 타임라인은 아래와 같았습니다.

1. connection 최초 생성

2. 하나의 connection을 24번 활용하고 connection pool에 반납

3. connection pool에서 connection을 꺼내와서 25번째 요청 시작 (request_sent)

4. Channel close 발생

5. response_incomplete

6. The connection observed an error 

 

이로써 유효한 connection을 가져오긴 했지만, 요청하고 응답을 받기 전 어디선가 취소가 되었음을 파악할 수 있습니다.

 

또한 25번째 요청마다 문제가 발생하진 않고, 16번째 요청에 발생하기도 하며, 82번째 요청에 발생하기도 하였습니다.

 

reactor.netty.http.client.HttpClientConnect

// In some cases the channel close event may be delayed and thus the connection to be
// returned to the pool and later the eviction functionality to remove it from the pool.
// In some rare cases the connection might be acquired immediately, before the channel close
// event and the eviction functionality is able to remove it from the pool; this may lead to I/O
// errors.
// Mark the connection as non-persistent here so that it is never returned to the pool and leave
// the channel close event to invalidate it.

 

HttpClientConnect 클래스의 주석을 살펴보면 몇몇 케이스에서 channel close event는 지연될 수 있다고 합니다.

따라서 connection pool에서 connection을 가져왔지만 pool에서 제거되고 I/O 에러로 이어질 수 있다고 합니다.

 

이를 통하여 특정 상황에서 target server에서 Connection: close가 응답으로 내려와서 connection pool에서 evict 되어야 하지만 이 부분이 지연되어 다음 요청 시에 I/O 에러가 관측된 것을 아닐까? 라는 가설을 세웠습니다.

 

다만 이전 요청의 Response 응답 시 헤더를 관찰했을 때 Connection 헤더는 관찰되지 않았습니다.

 

이전 요청에는 특이사항은 없었나?

헤더 값 이외의 과거 오류가 발생했던 건들의 이전 요청에 특이사항을 확인해 보았습니다.

이때 client로 부터 CANCEL signal 로그가 확인되었습니다.

N번째 요청에서 예외가 발생했을 때 N-1 번째 요청에서 Client의 취소 요청이 유입되고 있었습니다.

이로써 이전 요청의 취소가 현재 요청에 영향을 준다고 가설을 세울 수 있습니다.

 

 

어떻게 이전 요청의 취소가 현재 요청에 영향을 줄 수 있을까?

요청 A (N-1 번째)

  브라우저 -> Gateway -> Target server

  Target server 응답 완료 Gateway가 connection pool에 반납

  Gateway -> 브라우저 응답 전송 중 (아직 완료 안 됨)

 

요청 B (N번째)

  Pool에 반납된 connection을 재사용하여 Target Server로 요청 전송 중

 

이 시점에 브라우저가 요청 A를 취소 ( 탭 닫기, 새로고침 등)

 -> Gateway는 요청 A의 처리를 취소하려 함

 -> 요청 A의 취소 신호가 요청 B가 사용 중인 connection을 닫아버림

 -> PrematureCloseException 발생

 

 

로컬에서 재현해보기

준비과정

1. 임의의 route를 등록해두고, 로컬에서 8081 포트로 3초 지연되는 python 서버를 둔다.

2. 만들어둔 route로 요청을 보내면 3초 뒤에 응답이 온다.

3. reactor.netty.channel.ChannelOperations dispose 메서드에 디버깅을 찍는다.

  - 디버깅 시에는 요청받은 Thread만 막아두도록 설정하여 다음 요청이 처리될 수 있도록 한다.

 

재현과정

1. http 요청을 보내고 3초 전에 취소를 한다 (Ctrl + C)

2. 디버깅 포인트로 이동 된다.

3. http 요청을 보내고 3초가 지나기 전에 디버깅을 재개

 

 

해결방안

reactor-netty main 브랜치를 받아서 로컬에서 재현을 위한 테스트 메서드를 구현하다 보니 1.1.24 버전을 활용하면 이 부분은 해결됩니다.

 

구성한 테스트 메서드는 1.1.24 이후 버전부터는 성공하여, 1.1.23 버전에서는 실패합니다.

 

1.1.24 버전에 PR #3459가 반영되었습니다.

 

memory leak을 막기 위한 수정이였지만 DisposedConnection / DisposedChannel 개념이 도입되면서 이전 요청의 Connection 취소가 더 이상 영향을 주지 않게 되었습니다.

 

https://github.com/reactor/reactor-netty/pull/3459

When terminating detach the connection from request/response objects by violetagg · Pull Request #3459 · reactor/reactor-netty

 

Reactor Netty PR 올리기

재발방지를 위한 회귀 테스트를 구현하였고, 다른이의 삽질을 방지하기 위해 FAQ에 문서화를 보강하여 PR을 올렸습니다.

 

다만 1.1.x는 더 이상 지원하지 않는 버전이여서 문서에는 넣지 않았으면 좋겠다는 피드백을 받고 회귀 테스트만 반영하게 되었습니다.

 

https://github.com/reactor/reactor-netty/pull/4137

Add regression test for stale dispose closing reused connection by Junuu · Pull Request #4137 · reactor/reactor-netty