Connection reset by peer 에러 발생 및 관련 처리_2 (Retries exhausted: 5/5 에러, Connection prematurely closed BEFORE response 에러)

 

2024.06.18 - [개발] - Connection reset by peer 에러 발생 및 관련 처리_1

Connection reset by peer 에러 발생 및 관련 처리_1

 

1번 글에서 이어지는 글입니다.

 

API통신하는 모듈에 대해서 반영한 다음 Connection reset by peer 에러가 없어지고 나서 안심하고 지내고 있었다..그러나 다른 에러가 발생하기 시작했다.

Retries exhausted: 5/5 라는 에러가 지속적으로 발생하는 것이였다.

해당 로직의 경우 WebClient를 사용하여 비동기 요청을 할 때 별도의 스레드를 생성하여 요청을 보내고 구독(subscribe)하면서 응답에 대해 블록하지않고 기다리고 실패하는 경우 retry를 시도하는 로직이 있었기 때문에 발생하는 에러였다.

정상적으로 재시도(retry) 처리가 되어야만 하는 상황임에도 불구하고 요청이 제대로 수행되지 않는 문제가 발생하여..

1차적은 조치로는 서버 재기동을 수행하였고, 그 이후 원인 분석 및 동일케이스 확인을 위한 삽질이 시작되었다.

 

이슈가 발생했던 이유 분석 및 정리.

외부시스템에 문제가 생겨서 정상적으로 처리가 되지못하는 프로세스가 되어버렸음.

이때 외부시스템에 문제가 생겼기 때문에 재요청을 계속 시도 했을텐데. 서비스가 정상 상태로 돌아왔음에도 기존 요청이 정상적으로 처리되지못하고 Retries exhausted: 5/5 에러만 발생하는 상황으로 되어버림.

 

상황 추측

WebClient를 사용한 비동기 요청에서 문제가 발생했는데 해당 이슈는 로그도 안남는 듯 한다.

그리고 저번에 maxIdleTime을 설정하면서 WebClient의 경우 커넥션풀을 지정해뒀는데… 이 케이스에서 풀이 다 찼을수도 있다는 생각이 들었다.

다음과 같이 확인해봐야 한다.

• 외부 시스템에 문제가 발생하는 경우 어떤식으로 동작하며 로그가 남는지 확인 필요하다고 느낌.(비동기일때)
• 커넥션 풀 문제인지 확인 필요.
  • 정상적으로 서비스가 돌아 왔음에도 API요청이 안되는듯 보여짐.(테스트필요.)

기타

• 로그상에서 확인 가능한 고유번호 추가도 필요해보인다. 로그 확인 시 스레드별로 어떻게 동작하고 로그를 남기는기 보기가 어려움.
• Thread Local 저장소를 사용하는 MDC 로그에 UUID와 같이 고유한 값을 넣어주고 로그 구분을 쉽게 하는 것도 적용해야 할 것 같음.
• 기존 시스템을 모니터링 하는 것도 빨리 붙여야 할 것 같다고 생각했다.

 

처리한 사항

재시도 요청로그가 남지않는 부분에 대해 다음과 같이 명시하여 retry시 시스템 로그라도 남기도록 변경처리 하였다.

RetryBackoffSpec retrySpec = Retry.fixedDelay(5, Duration.ofMillis(1000))
                           .doBeforeRetry(retrySignal -> {
                              log.warn("Retrying due to exception: {}. Retry attempt: {}",retrySignal.failure().getMessage(), retrySignal.totalRetries());
                           });

또한 기존에 돌아가던 서비스에 모니터링을 위해 핀포인트를 붙이려고 하는 마음을 더 강하게 만들어주는 시기였다.

그리고 다시 동일 상황이 발생했다.

현재 시스템의 경우 다음과 같은 형태로 비즈니스 로직이 수행 된다.

핀포인트로 확인 해 본 결과. PMS → PMS_API 호출 도중에 커넥션이 끊겼다고 보였다.
(Connection prematurely closed BEFORE response)

발생시기의 경우 2024-06-08 8시30분경.
해당시간에 외부서비스와 연동된 주소 중 유일하게 실패한 호출 모습

 

이 때 실패 하고 난 다음부터 Retry가 지속적으로 발생하는 것으로 추정되는데.. 초기 커넥션풀 설정의 경우 잘못 설정된 값이 적용되어 커넥션풀이 정상적으로 해지되지못했다고 생각했었다.
실패 후 Retry를 시도하면서 커넥션풀의 유휴시간이 5000초(대략적으로 1시간이상)로 잘못 설정되어 있는 부분이 있었다.이때 커넥션풀을 모두 잡아먹어서 문제가 발생한 것으로 추정된다.

기존 설정의 경우

ConnectionProvider provider = ConnectionProvider.fixed("fixed_connection_pool", MAX_CONN_TOTAL, CONNECT_TIMEOUT, Duration.ofSeconds(CONNECT_TIMEOUT));

변경한 설정의 경우

ConnectionProvider provider = ConnectionProvider.fixed("fixed_connection_pool", MAX_CONN_TOTAL, CONNECT_TIMEOUT, Duration.ofMillis(CONNECT_TIMEOUT));

변경점

Duration.ofSeconds(CONNECT_TIMEOUT) -> Duration.ofMillis(CONNECT_TIMEOUT)

명확하게 해결책이 나오지 않는 상황에서 나올 수 있는 케이스들에 대해서 정리를 해 보기로 하였다.

동일상황 만들어서 테스트 해보자.

서비스 요청이 안들어갔을때.
Retries exhausted: 5/5 에러 발생 관련 테스트 및 확인 (리트라이 발생시 에러 추적 및 시스템 확인 절차 수행)

대략적인 조건 정리.

• 외부API 기본 전제 조건.(불안정한 API서버)
  • 응답의 경우 동기,비동기 모두 특정시간 이상이 걸린다.(10s)
  • 서버는 간헐적으로 다운 될 수 있다.

커넥션 풀이 모두 찬 경우에는 문제가 발생하긴 하는 것 같다고 생각했다.

 

동일한 상황 발생하도록 세팅하였다.

간단하게 확인 가능하도록 커넥션풀 설정의 경우 작은수(2~5로 세팅을 바꾼다음 진행하였다.

간략정리

그냥 로컬환경에서 pms와 외부 API 2개를 띄워두고 테스트에 들어간다.

API에 요청 파라미터에 따라 다음과 같이 응답한다.

• 응답시간 지연(time=10) 10초뒤 응답
• 에러 발생 (error)
• 정상응답 처리.(그외)

1. 어드민에서 외부 API 호출(서버다운된 상태)
2. 어드민에서 외부 API 호출(서버는 살아있지만 응답이 느린상태)
   • 응답시간 지연 사용 및 랜덤 응답 사용
3. 어드민에서 외부 API 호출(서버는 살아있지만 디버깅으로 응답을 다 안주는상태)
   • 디버깅으로 응답 막아두고 계속 호출을 쌓아본다.
4. 어드민에서 외부 API 호출(서버는 살아있지만 간헐적으로 실패가 발생하는 상태)
   • 간헐적으로 실패를 떨궈본다.

위와같은 상태에서 Retries exhausted: 5/5 문제가 발생하는지 확인해본다.
API요청 도중에서 API 서버에 문제가 생겼다고 가정하여 서비스가 중단되면(shutdown) 문제가 된 케이스와 동일하게 retry만 일어나고 요청은 전달되지않는 상황이 발생했다...!!!

이 상태에서 외부서비스는 응답을 늦게 하는 형태이고, 응답도중 서비스에서 연결된 요청들에 대해서 접속을 다 끊어버렸다. 그 경우 다음과같이 Connection prematurely closed BEFORE response 에러가 발생한다. 그리고 Retry를 시도하게된다.

그 이후 서버가 살아나더라도 요청이 전송되지 않는 상태가 되어버린다.

문제 발생 상황 정리 및 확인.

0.9.0 버전의 경우

• [o] 외부 API 요청 중 강제로 연결 끊김.
  • 최근에 발생한 문제와 동일 한 문제가 발생한다. (0.9.0 버전의 경우 문제 발생함)
• [x] 외부 API 요청 중 error 발생
  • 정상적으로 재시도 수행 후 커넥션풀 반납.
• [x] 외부 API 요청 중 응답지연으로 인한 커넥션 풀 고갈.
  • 정상적으로 재시도 수행 후 커넥션풀 반납.

0.9.22 버전의 경우

• [x] 외부 API 요청 중 강제로 연결 끊김.
  • 정상적으로 재시도 수행 후 커넥션풀 반납.
• [x] 외부 API 요청 중 error 발생
  • 정상적으로 재시도 수행 후 커넥션풀 반납.
• [x] 외부 API 요청 중 응답지연으로 인한 커넥션 풀 고갈.
  • 정상적으로 재시도 수행 후 커넥션풀 반납.

 

초기버전으로 적용 한 상태와 어느정도 안정화된 버전을 사용한 상태에서 버전 차이에 따라 동일한 상황이지만 다르게 동작하게 되는걸 확인하였다.

그리고 해당 버전을 업그레이드 하는 방향으로 기존 서비스에 적용시키기로 했다.

관련해서 버전상의 문제가 발생하는 경우가 있어서 다음과 같이 지정했다.
netty-handler 4.1.29.Final -> netty-handler 4.1.50.Final

다음과 같이 기준이되는 버전 명시.

<dependencyManagement>
		<dependencies>
			<dependency>
				<groupId>io.netty</groupId>
				<artifactId>netty-bom</artifactId>
				<version>4.1.50.Final</version> <!-- 호환되는 최신 버전으로 설정 -->
				<type>pom</type>
				<scope>import</scope>
			</dependency>
		</dependencies>
	</dependencyManagement>

그외 나머지들의 경우 버전 없이 명시 reactor-netty 0.9.0 → reactor-netty 0.9.22 로 변경

<dependency>
	<groupId>io.projectreactor.netty</groupId>
	<artifactId>reactor-netty</artifactId>
	<version>0.9.22.RELEASE</version>
</dependency>
<dependency>
	<groupId>io.netty</groupId>
	<artifactId>netty-handler</artifactId>
</dependency>
<dependency>
	<groupId>io.netty</groupId>
	<artifactId>netty-handler-proxy</artifactId>
</dependency>
<dependency>
	<groupId>io.netty</groupId>
	<artifactId>netty-codec-socks</artifactId>
</dependency>

ConnectionProvider builder 방식으로 변경.

		ConnectionProvider provider = ConnectionProvider.builder("fixed_connection_pool")
				.maxConnections(MAX_CONN_TOTAL) // 최대 연결 수 설정
				.pendingAcquireTimeout(Duration.ofMillis(CONNECT_TIMEOUT)) // 대기 중인 연결 타임아웃
				.pendingAcquireMaxCount(-1)
				.maxIdleTime(Duration.ofMillis(CONNECT_TIMEOUT)) // 유휴 연결 타임아웃
				.evictInBackground(Duration.ofMillis(CONNECT_TIMEOUT)) //백그라운드에서 만료된 connection을 제거하는 주기
				.lifo()
				.build();

 

설정관련하여 참고한 주소( LIFO 설정 적용 및 다른 옵션값 적용)

참고주소

https://velog.io/@stella6767/비효울적인-Blocking-코드-WebClient-사용으로-개선

비효울적인 Blocking 코드 => WebClient 사용으로 개선

 

 

여러가지 케이스에 대비해서 테스트가 미흡했던것 같았고, 해당 이슈들에 대해서 처음 접하게 됬을 때 어떤점이 문제인지를 찾아가는 과정에서 막연함이 좀 있었다. 눈에 보이는 부분들이 아니라서 더 그렇다. 다른사람이 조금이라도 삽질을 덜 하도록 최대한 정리하여 보았다...!!